Spine dies with buffer overflow

[santti]

Hi people,

I have a fresh cacti install on RHEL5 (i386) using following versions:

cacti-0.8.7b-2.el5.rf
cacti-spine-0.8.7a-1 (locally compiled from www.cacti.net sources)
mysql-5.0.45-7.el5
php-5.1.6-20.el5
net-snmp-5.3.1-24.el5_2.1
rrdtool-1.2.23-1.el5.rf

First of all I made some testing with cmd.php poller, polling localhost snmp and couple hp-procurve switches, and everything seems to working fine. After some testing I changed poller to spine, and started to get errors to cacti.log:

07/15/2008 02:50:00 PM - POLLER: Poller[0] Maximum runtime of 298 seconds exceeded. Exiting.

I removed the hp switch from configuration and spine started to work. After that I added it again, and same problems started. Now I debugged the situation a bit further by running spine from the commandline:

# su - cacti -c "/usr/bin/spine -V 5 -f 4 -l 4"
SPINE: Using spine config file [/etc/spine.conf]
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'path_webroot''
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'path_cactilog''
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The path_php_server variable is /var/www/cacti/script_server.php
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The path_cactilog variable is /var/www/cacti/log/cacti.log
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'log_destination''
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The log_destination variable is 2 (BOTH)
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'path_php_binary''
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The path_php variable is /usr/bin/php
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'availability_method''
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The availability_method variable is 2
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'ping_recovery_count''
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The ping_recovery_count variable is 3
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'ping_failure_count''
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The ping_failure_count variable is 2
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'ping_method''
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The ping_method variable is 2
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'ping_retries''
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The ping_retries variable is 1
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'ping_timeout''
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The ping_timeout variable is 400
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'log_perror''
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The log_perror variable is 1
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'log_pwarn''
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The log_pwarn variable is 0
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'log_pstats''
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The log_pstats variable is 0
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'max_threads''
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The threads variable is 1
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'poller_interval''
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The polling interval is 300 seconds
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'concurrent_processes''
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The number of concurrent processes is 10
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'script_timeout''
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The script timeout is 25
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'php_servers''
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The number of php script servers to run is 2
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT action FROM poller_item WHERE action=2 AND host_id BETWEEN 4 AND 4 LIMIT 1'
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: StartHost='4', EndHost='4', TotalPHPScripts='0'
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The PHP Script Server is Not Required
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'max_get_size''
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The Maximum SNMP OID Get Size is 10
07/16/2008 10:06:09 AM - SPINE: Poller[0] Version 0.8.7b starting
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: MySQL is Thread Safe!
07/16/2008 10:06:09 AM - SPINE: Poller[0] SPINE: Initializing Net-SNMP API
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SNMP Header Version is 5.3.1
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SNMP Library Version is 5.3.1
07/16/2008 10:06:09 AM - SPINE: Poller[0] SPINE: Initializing PHP Script Server(s)
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT id FROM host WHERE disabled='' AND id BETWEEN 4 AND 4 ORDER BY id'
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: Initial Value of Active Threads is 0
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: Valid Thread to be Created
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 1
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: In Poller, About to Start Polling of Host
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT snmp_port, count(snmp_port) FROM poller_item WHERE host_id=0 AND rrd_next_step < 0 GROUP BY snmp_port'
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT action, hostname, snmp_community, snmp_version, snmp_username, snmp_password, rrd_name, rrd_path, arg1, arg2, arg3, local_data_id, rrd_num, snmp_port, snmp_timeout, snmp_auth_protocol, snmp_priv_passphrase, snmp_priv_protocol, snmp_context FROM poller_item WHERE host_id=0 and rrd_next_step <=0 ORDER by snmp_port'
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'UPDATE poller_item SET rrd_next_step=rrd_next_step-300 WHERE host_id=0'
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'UPDATE poller_item SET rrd_next_step=rrd_step-300 WHERE rrd_next_step < 0 and host_id=0'
07/16/2008 10:06:09 AM - SPINE: Poller[0] Host[0] DEBUG: HOST COMPLETE: About to Exit Host Polling Thread Function
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 0
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: Valid Thread to be Created
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 1
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: In Poller, About to Start Polling of Host
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT id, hostname, snmp_community, snmp_version, snmp_username, snmp_password, snmp_auth_protocol, snmp_priv_passphrase, snmp_priv_protocol, snmp_context, snmp_port, snmp_timeout, max_oids, availability_method, ping_method, ping_port, ping_timeout, ping_retries, status, status_event_count, status_fail_date, status_rec_date, status_last_error, min_time, max_time, cur_time, avg_time, total_polls, failed_polls, availability FROM host WHERE id=4'
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: UDP Ping return_code was -1, errno was 111, total_time was 2213.9549
07/16/2008 10:06:09 AM - SPINE: Poller[0] Host[4] PING: Result UDP: Host is Alive
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'UPDATE host SET status='3', status_event_count='0', status_fail_date='0000-00-00 00:00:00', status_rec_date='0000-00-00 00:00:00', status_last_error='', min_time='0.180960', max_time='12.220000', cur_time='2.213950', avg_time='1.105492', total_polls='217', failed_polls='0', availability='100.0000' WHERE id='4''
07/16/2008 10:06:09 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT data_query_id, action, op, assert_value, arg1 FROM poller_reindex WHERE host_id=4'
07/16/2008 10:06:09 AM - SPINE: Poller[0] Host[4] RECACHE: Processing 1 items in the auto reindex cache for 'hpswitch'
*** buffer overflow detected ***: /usr/bin/spine terminated
======= Backtrace: =========
/lib/libc.so.6(__chk_fail+0x41)[0x3a1e41]
/lib/libc.so.6[0x3a178c]
/lib/libc.so.6(__snprintf_chk+0x37)[0x3a1677]
/usr/bin/spine[0x8051853]
/usr/bin/spine[0x8051c3d]
/lib/libpthread.so.0[0x8d445b]
/lib/libc.so.6(clone+0x5e)[0x38dc4e]
======= Memory map: ========
00110000-00151000 r-xp 00000000 68:02 363453 /lib/libssl.so.0.9.8b
00151000-00155000 rwxp 00040000 68:02 363453 /lib/libssl.so.0.9.8b
00157000-0027a000 r-xp 00000000 68:05 822727 /usr/lib/mysql/libmysqlclient_r.so.15.0.0
0027a000-002bc000 rwxp 00123000 68:05 822727 /usr/lib/mysql/libmysqlclient_r.so.15.0.0
002bc000-002bd000 rwxp 002bc000 00:00 0
002bd000-003fa000 r-xp 00000000 68:02 363433 /lib/libc-2.5.so
003fa000-003fc000 r-xp 0013d000 68:02 363433 /lib/libc-2.5.so
003fc000-003fd000 rwxp 0013f000 68:02 363433 /lib/libc-2.5.so
003fd000-00400000 rwxp 003fd000 00:00 0
00400000-0042d000 r-xp 00000000 68:05 626171 /usr/lib/libgssapi_krb5.so.2.2
0042d000-0042e000 rwxp 0002d000 68:05 626171 /usr/lib/libgssapi_krb5.so.2.2
0042e000-00453000 r-xp 00000000 68:05 626169 /usr/lib/libk5crypto.so.3.1
00453000-00454000 rwxp 00025000 68:05 626169 /usr/lib/libk5crypto.so.3.1
00454000-0045c000 r-xp 00000000 68:05 626168 /usr/lib/libkrb5support.so.0.1
0045c000-0045d000 rwxp 00007000 68:05 626168 /usr/lib/libkrb5support.so.0.1
0045d000-00461000 r-xp 00000000 68:02 360487 /lib/libnss_dns-2.5.so
00461000-00462000 r-xp 00003000 68:02 360487 /lib/libnss_dns-2.5.so
00462000-00463000 rwxp 00004000 68:02 360487 /lib/libnss_dns-2.5.so
0049a000-004a5000 r-xp 00000000 68:02 363436 /lib/libgcc_s-4.1.2-20080102.so.1
004a5000-004a6000 rwxp 0000a000 68:02 363436 /lib/libgcc_s-4.1.2-20080102.so.1
0073d000-00757000 r-xp 00000000 68:02 363432 /lib/ld-2.5.so
00757000-00758000 r-xp 00019000 68:02 363432 /lib/ld-2.5.so
00758000-00759000 rwxp 0001a000 68:02 363432 /lib/ld-2.5.so
0082b000-0082c000 r-xp 0082b000 00:00 0 [vdso]
008a0000-008a2000 r-xp 00000000 68:02 363434 /lib/libdl-2.5.so
008a2000-008a3000 r-xp 00001000 68:02 363434 /lib/libdl-2.5.so
008a3000-008a4000 rwxp 00002000 68:02 363434 /lib/libdl-2.5.so
008a6000-008cb000 r-xp 00000000 68:02 363437 /lib/libm-2.5.so
008cb000-008cc000 r-xp 00024000 68:02 363437 /lib/libm-2.5.so
008cc000-008cd000 rwxp 00025000 68:02 363437 /lib/libm-2.5.so
008cf000-008e2000 r-xp 00000000 68:02 363439 /lib/libpthread-2.5.so
008e2000-008e3000 r-xp 00012000 68:02 363439 /lib/libpthread-2.5.so
008e3000-008e4000 rwxp 00013000 68:02 363439 /lib/libpthread-2.5.so
008e4000-008e6000 rwxp 008e4000 00:00 0
008e8000-008fa000 r-xp 00000000 68:05 626154 /usr/lib/libz.so.1.2.3
008fa000-008fb000 rwxp 00011000 68:05 626154 /usr/lib/libz.so.1.2.3
00908000-00943000 r-xp 00000000 68:02 363449 /lib/libsepol.so.1
00943000-00944000 rwxp 0003a000 68:02 363449 /lib/libsepol.so.1
00944000-0094e000 rwxp 00944000 00:00 0
00950000-00966000 r-xp 00000000 68:02 363450 /lib/libselinux.so.1
00966000-00968000 rwxp 00015000 68:02 363450 /lib/libselinux.so.1
00a58000-00a6b000 r-xp 00000000 68:02 363446 /lib/libnsl-2.5.so
00a6b000-00a6c000 r-xp 00012000 68:02 363446 /lib/libnsl-2.5.so
00a6c000-00a6d000 rwxp 00013000 68:02 363446 /lib/libnsl-2.5.so
00a6d000-00a6f000 rwxp 00a6d000 00:00 0
00a71000-00b08000 r-xp 00000000 68:05 626324 /usr/lib/libnetsnmp.so.10.0.1
00b08000-00b0a000 rwxp 00097000 68:05 626324 /usr/lib/libnetsnmp.so.10.0.1
00b0a000-00b29000 rwxp 00b0a000 00:00 0
00b79000-00b82000 r-xp 00000000 68:02 360489 /lib/libnss_files-2.5.so
00b82000-00b83000 r-xp 00008000 68:02 360489 /lib/libnss_files-2.5.so
00b83000-00b84000 rwxp 00009000 68:02 360489 /lib/libnss_files-2.5.so
00b88000-00ca5000 r-xp 00000000 68:02 363452 /lib/libcrypto.so.0.9.8b
00ca5000-00cb8000 rwxp 0011c000 68:02 363452 /lib/libcrypto.so.0.9.8b
00cb8000-00cbb000 rwxp 00cb8000 00:00 0
00d4b000-00d4d000 r-xp 00000000 68:02 363447 /lib/libkeyutils-1.2.so
00d4d000-00d4e000 rwxp 00001000 68:02 363447 /lib/libkeyutils-1.2.so
00d50000-00d52000 r-xp 00000000 68:02 363451 /lib/libcom_err.so.2.1
00d52000-00d53000 rwxp 00001000 68:02 363451 /lib/libcom_err.so.2.1
00d55000-00d64000 r-xp 00000000 68:02 363448 /lib/libresolv-2.5.so
00d64000-00d65000 r-xp 0000e000 68:02 363448 /lib/libresolv-2.5.so
00d65000-00d66000 rwxp 0000f000 68:02 363448 /lib/libresolv-2.5.so
00d66000-00d68000 rwxp 00d66000 00:00 0
00d6a000-00dfa000 r-xp 00000000 68:05 626170 /usr/lib/libkrb5.so.3.3
00dfa000-00dfd000 rwxp 0008f000 68:05 626170 /usr/lib/libkrb5.so.3.3
06ef6000-06eff000 r-xp 00000000 68:02 363456 /lib/libcrypt-2.5.so
06eff000-06f00000 r-xp 00008000 68:02 363456 /lib/libcrypt-2.5.so
06f00000-06f01000 rwxp 00009000 68:02 363456 /lib/libcrypt-2.5.so
06f01000-06f28000 rwxp 06f01000 00:00 0
08048000-0805a000 r-xp 00000000 68:05 1639708 /usr/bin/spine
0805a000-0805b000 rw-p 00011000 68:05 1639708 /usr/bin/spine
0805b000-0805d000 rw-p 0805b000 00:00 0
08342000-0842b000 rw-p 08342000 00:00 0
b7307000-b7308000 ---p b7307000 00:00 0
b7308000-b7d08000 rw-p b7308000 00:00 0
b7d08000-b7f08000 r--p 00000000 68:05 625474 /usr/lib/locale/locale-archive
b7f08000-b7f0e000 rw-p b7f08000 00:00 0
b7f1a000-b7f1c000 rw-p b7f1a000 00:00 0
bff21000-bff36000 rw-p bff21000 00:00 0 [stack]

The result will remain same if I clear the pollercache or not. Do you have any ideas what might be wrong, and how to fix the issue? In a production environment I really need faster poller than cmd.php to get reasonable performance.

[marian]

Hi, i have the same problem on CentOS 5.2 2.6.18-92.1.6.el5 #1 SMP 64bit.

cacti-0.8.7b-2.el5.rf
cacti-spine-0.8.7a-1.el5.rf

Can anyone solve it?

07/18/2008 10:54:25 AM - SPINE: Poller[0] DEBUG: SQL:'SELECT data_query_id, action, op, assert_value, arg1 FROM poller_reindex WHERE host_id=68'
07/18/2008 10:54:25 AM - SPINE: Poller[0] Host[68] RECACHE: Processing 1 items in the auto reindex cache for 'switch'
*** buffer overflow detected ***: spine terminated
======= Backtrace: =========
/lib64/libc.so.6(__chk_fail+0x2f)[0x384a0e55ff]
/lib64/libc.so.6[0x384a0e4e5b]
/lib64/libc.so.6(__snprintf_chk+0x7b)[0x384a0e4d2b]
spine[0x40984f]
spine[0x409b63]
/lib64/libpthread.so.0[0x384b806307]
/lib64/libc.so.6(clone+0x6d)[0x384a0d1ded]
======= Memory map: ========
00400000-00412000 r-xp 00000000 09:02 32682159 /usr/bin/spine
00611000-00612000 rw-p 00011000 09:02 32682159 /usr/bin/spine

[speedracer05]

On Centos 5.2, I have experienced the same issue. As a workaround, I downloaded and compiled the tarball:

http://www.cacti.net/spine_download.php

I had to install libtool before compiling:

yum install libtool

Then, follow the install instructions:

http://www.cacti.net/spine_install.php

Looks like an issue with the cacti-spine yum repository rpm.

[quruli]

I've faced similar problem (spine die with buffer overflow) with CentOS5.2(32bit) and I couldn't fix it for a week.

My environment was as follows

• CentOS release 5.2 (Final) i386
  cacti.noarch 0.8.7b-2.el5.rf
  cacti-spine.i386 0.8.7a-1.el5.rf
  mysql.i386 5.0.45-7.el5
  php.i386 5.1.6-20.el5_2.1
  net-snmp.i386 1:5.3.1-24.el5_2.1
  rrdtool.i386 1.2.23-1.el5.rf

Seeing speedracer05 comment, I tried to compile spine from sourcecode and modified Cacti's poller PATH to indicate new spine binaly file. Then I found that new spine works fine and it looks datum are being collected properly.

Thanks a lot! speedracer05