spine in cacti hung up polling non-existent device

[jenglish724]

I’m seeing this – I believe its hung up on the bolded line below. When I run spine from the command line, it does what its supposed to do.. (below)
But executing spine from inside cacti gets hung up. Only one device is defined. --first=4 --last=4

2018/05/04 13:35:01 - POLLER: Poller[1] NOTE: Poller Int: '60', Cron Int: '60', Time Since Last: '299.93', Max Runtime '58', Poller Runs: '1'
2018/05/04 13:35:01 - POLLER: Poller[1] WARNING: Cron is out of sync with the Poller Interval! The Poller Interval is '60' seconds, with a maximum of a '60' second Cron, but 299.9 seconds have passed since the last poll!
2018/05/04 13:35:01 - POLLER: Poller[1] WARNING: Poller Output Table not Empty. Issues: 34, DS[138, 138, 133, 133, 128, 128, 123, 123, 118, 113, 108, 142, 142, 137, 137, 132, 132, 127, 127, 122], Additional Issues Remain. Only showing first 20
2018/05/04 13:35:01 - POLLER: Poller[1] DEBUG: About to Spawn a Remote Process [CMD: /usr/local/spine/bin/spine, ARGS: --poller=1 --first=0 --last=0 --mibs]
2018/05/04 13:35:02 - POLLER: Poller[1] DEBUG: About to Spawn a Remote Process [CMD: /usr/local/spine/bin/spine, ARGS: --poller=1 --first=4 --last=4 --mibs]
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.
Waiting on 2 of 2 pollers.



# /usr/local/spine/bin/spine
SPINE: Using spine config file [/etc/spine.conf]
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The path_php_server variable is /usr/share/cacti-1.1.38/script_server.php
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The path_cactilog variable is /usr/share/cacti/log/cacti.log
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The log_destination variable is 1 (FILE)
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The path_php variable is /bin/php
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The availability_method variable is 2
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The ping_recovery_count variable is 3
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The ping_failure_count variable is 2
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The ping_method variable is 2
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The ping_retries variable is 1
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The ping_timeout variable is 400
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The snmp_retries variable is 3
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The log_perror variable is 1
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The log_pwarn variable is 0
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The boost_redirect variable is 0
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The boost_rrd_update_enable variable is 0
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The log_pstats variable is 0
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The threads variable is 50
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The polling interval is 60 seconds
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The number of concurrent processes is 1
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The script timeout is 150
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The selective_device_debug variable is
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The spine_log_level variable is 2
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The number of php script servers to run is 1
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: StartDevice='-1', EndDevice='-1', TotalPHPScripts='1'
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The PHP Script Server is Required
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The Maximum SNMP OID Get Size is 5
2018/05/04 13:36:57 - SPINE: Poller[1] Version 1.1.38 starting
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: MySQL is Thread Safe!
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: Spine is running asroot.
2018/05/04 13:36:57 - SPINE: Poller[1] SPINE: Initializing Net-SNMP API
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: Issues with SNMP Header Version information, assuming old version of Net-SNMP.
2018/05/04 13:36:57 - SPINE: Poller[1] SPINE: Initializing PHP Script Server(s)
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: SS[0] PHP Script Server Routine Starting
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: SS[0] PHP Script Server About to FORK Child Process
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: SS[0] PHP Script Server Child FORK Success
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: SS[0] Confirmed PHP Script Server running using readfd[7], writefd[6]
2018/05/04 13:36:57 - SPINE: Poller[1] NOTE: Spine will support multithread device polling.
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: Initial Value of Active Threads is 0
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: Valid Thread to be Created
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: In Poller, About to Start Polling of Device for Device ID 4
2018/05/04 13:36:57 - SPINE: Poller[1] SPINE: Active Threads is 1, Pending is 1
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] DEBUG: Entering SNMP Ping
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] SNMP Result: Device responded to SNMP
2018/05/04 13:36:57 - SPINE: Poller[1] Updating Full System Information Table
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] TH[1] RECACHE: Processing 5 items in the auto reindex cache for '172.24.17.133'
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] TH[1] Recache DataQuery[1] OID: .1.3.6.1.2.1.1.3.0, output: 188781916
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] TH[1] Recache DataQuery[3] OID: .1.3.6.1.2.1.1.3.0, output: 188781916
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] TH[1] Recache DataQuery[4] OID: .1.3.6.1.2.1.1.3.0, output: 188781916
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] TH[1] Recache DataQuery[5] OID: .1.3.6.1.2.1.1.3.0, output: 188781916
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] TH[1] Recache DataQuery[6] OID: .1.3.6.1.2.1.1.3.0, output: 188781916
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] TH[1] NOTE: There are '11' Polling Items for this Device
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] TH[1] DS[109] SS[0] SERVER: /usr/share/cacti-1.1.38/scripts/ss_net_snmp_disk_bytes.php ss_net_snmp_disk_bytes '172.24.17.133', output: bytesread:0 byteswritten:65212416
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] TH[1] DS[124] SS[0] SERVER: /usr/share/cacti-1.1.38/scripts/ss_host_disk.php ss_host_disk '172.24.17.133' '4' '2:161:500:1:5:EPICsnmp::::::' 'get' 'used' '3', output: 8353488896
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] TH[1] DS[124] SS[0] SERVER: /usr/share/cacti-1.1.38/scripts/ss_host_disk.php ss_host_disk '172.24.17.133' '4' '2:161:500:1:5:EPICsnmp::::::' 'get' 'total' '3', output: 20935475200
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] TH[1] DS[129] SS[0] SERVER: /usr/share/cacti-1.1.38/scripts/ss_host_disk.php ss_host_disk '172.24.17.133' '4' '2:161:500:1:5:EPICsnmp::::::' 'get' 'used' '31', output: 421355520
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] TH[1] DS[129] SS[0] SERVER: /usr/share/cacti-1.1.38/scripts/ss_host_disk.php ss_host_disk '172.24.17.133' '4' '2:161:500:1:5:EPICsnmp::::::' 'get' 'total' '31', output: 8320901120
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] TH[1] DS[134] SS[0] SERVER: /usr/share/cacti-1.1.38/scripts/ss_host_disk.php ss_host_disk '172.24.17.133' '4' '2:161:500:1:5:EPICsnmp::::::' 'get' 'used' '36', output: 2084704256
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] TH[1] DS[134] SS[0] SERVER: /usr/share/cacti-1.1.38/scripts/ss_host_disk.php ss_host_disk '172.24.17.133' '4' '2:161:500:1:5:EPICsnmp::::::' 'get' 'total' '36', output: 15719186432
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] TH[1] DS[139] SS[0] SERVER: /usr/share/cacti-1.1.38/scripts/ss_host_disk.php ss_host_disk '172.24.17.133' '4' '2:161:500:1:5:EPICsnmp::::::' 'get' 'used' '46', output: 0
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] TH[1] DS[139] SS[0] SERVER: /usr/share/cacti-1.1.38/scripts/ss_host_disk.php ss_host_disk '172.24.17.133' '4' '2:161:500:1:5:EPICsnmp::::::' 'get' 'total' '46', output: 8320253952
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] TH[1] DS[114] SNMP: v2: 172.24.17.133, dsname: ssCpuUser, oid: .1.3.6.1.4.1.2021.11.9.0, value: 2
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] TH[1] DS[119] SNMP: v2: 172.24.17.133, dsname: mem_buffers, oid: .1.3.6.1.4.1.2021.4.14.0, value: 885448
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] TH[1] Total Time: 0.25 Seconds
2018/05/04 13:36:57 - SPINE: Poller[1] Device[4] TH[1] DEBUG: HOST COMPLETE: About to Exit Device Polling Thread Function
2018/05/04 13:36:57 - SPINE: Poller[1] DEBUG: The Value of Active Threads is 0 for Device ID 4
2018/05/04 13:36:57 - SPINE: Poller[1] POLLR: Active Threads is 0, Pending is 0
2018/05/04 13:36:58 - SPINE: Poller[1] SPINE: The Final Value of Threads is 0
2018/05/04 13:36:58 - SPINE: Poller[1] DEBUG: Thread Cleanup Complete
2018/05/04 13:36:58 - SPINE: Poller[1] DEBUG: SS[0] Script Server Shutdown Started
2018/05/04 13:36:58 - SPINE: Poller[1] DEBUG: PHP Script Server Pipes Closed
2018/05/04 13:36:58 - SPINE: Poller[1] DEBUG: Allocated Variable Memory Freed
2018/05/04 13:36:58 - SPINE: Poller[1] DEBUG: MYSQL Free & Close Completed
2018/05/04 13:36:58 - SPINE: Poller[1] DEBUG: Net-SNMP Close Completed
2018/05/04 13:36:58 - SPINE: Poller[1] Time: 1.2886 s, Threads: 50, Devices: 1

[netniV]

It's probably more about the fact that it's trying to us a zero device id. The real question is why it is trying to spawn with no first or last device it.

[jenglish724]

Is this something in mariadb keeping it from start with first and last device ?
Any suggestions on what to change to try and correct this?
This is cacti 1.1.38 and spine 1.1.38.
There’s only one device at the moment.
Wipe out cacti db and reinitialize it?

[netniV]

I think there's an issue there. I've asked some questions and waiting on an answer before I can say what to do next.

[jenglish724]

to clarify, are you asking me a question? Because we're asking the same question it seems.

running cmd.php poller everything ends quickly, as expected. With spine.. something keeps it running .

# cat /var/log/cacti/cacti.log
05/08/2018 12:15:02 - SYSTEM STATS: Time:1.3075 Method:cmd.php Processes:1 Threads:N/A Hosts:1 HostsPerProcess:1 DataSources:1 RRDsProcessed:1
05/08/2018 12:15:03 - AUTOM8 ERROR: The Network ID: 1 is disabled. You must use the 'force' option to force it's execution.
05/08/2018 12:20:03 - SYSTEM STATS: Time:1.3571 Method:cmd.php Processes:1 Threads:N/A Hosts:1 HostsPerProcess:1 DataSources:5 RRDsProcessed:5
05/08/2018 12:25:03 - SYSTEM STATS: Time:1.2596 Method:cmd.php Processes:1 Threads:N/A Hosts:1 HostsPerProcess:1 DataSources:5 RRDsProcessed:5
05/08/2018 12:30:03 - SYSTEM STATS: Time:1.2906 Method:cmd.php Processes:1 Threads:N/A Hosts:1 HostsPerProcess:1 DataSources:5 RRDsProcessed:5
05/08/2018 12:35:02 - SYSTEM STATS: Time:1.2838 Method:cmd.php Processes:1 Threads:N/A Hosts:1 HostsPerProcess:1 DataSources:5 RRDsProcessed:5
05/08/2018 12:40:03 - SYSTEM STATS: Time:1.2717 Method:cmd.php Processes:1 Threads:N/A Hosts:1 HostsPerProcess:1 DataSources:5 RRDsProcessed:5
05/08/2018 12:50:00 - POLLER: Poller[1] Maximum runtime of 298 seconds exceeded. Exiting.
05/08/2018 12:50:00 - SYSTEM STATS: Time:298.8383 Method:spine Processes:1 Threads:1 Hosts:1 HostsPerProcess:1 DataSources:5 RRDsProcessed:0
05/08/2018 13:00:01 - POLLER: Poller[1] Maximum runtime of 298 seconds exceeded. Exiting.
05/08/2018 13:00:01 - SYSTEM STATS: Time:299.8381 Method:spine Processes:1 Threads:1 Hosts:1 HostsPerProcess:1 DataSources:5 RRDsProcessed:0
05/08/2018 13:05:00 - POLLER: Poller[1] Maximum runtime of 298 seconds exceeded. Exiting.
05/08/2018 13:05:00 - SYSTEM STATS: Time:298.8707 Method:spine Processes:1 Threads:1 Hosts:1 HostsPerProcess:1 DataSources:5 RRDsProcessed:5
05/08/2018 13:05:03 - SYSTEM STATS: Time:1.2801 Method:cmd.php Processes:1 Threads:N/A Hosts:1 HostsPerProcess:1 DataSources:5 RRDsProcessed:5


# ps -ef | grep poller
cacti 117179 117169 0 12:55 ? 00:00:00 /bin/sh -c /usr/bin/php /usr/share/cacti/poller.php > /dev/null 2>&1
cacti 117180 117179 0 12:55 ? 00:00:00 /usr/bin/php /usr/share/cacti/poller.php
root 117381 115969 0 12:56 pts/0 00:00:00 grep --color=auto poller


# /usr/local/spine/bin/spine/spine
SPINE: Using spine config file [/etc/spine.conf]
SPINE: Version 1.1.38 starting
SPINE: Time: 1.0614 s, Threads: 1, Devices: 1