Upgrade 1.2.18 to 1.2.21 - Error: Maximum runtime of 298 seconds exceeded

[warben61]

Hi all,
I recently upgraded from 1.2.18 to 1.2.21 and I'm having trouble with the poller not completing. It intermittently maxes out at 298 seconds and of course when that happens, not all RRDs are updated and I'm ending up with breaks in the graphs.

I also need to mention that I updated spine and Ubuntu at the same time. Spine to version 1.2.21, Ubuntu from 18.04 to 20.04. That of course updated php from 7.2 to 7.4 so I had to adjust the php.ini settings as well. I'm throwing in the towel on google searching and asking for help. What can I look for to debug this?

Besides the poller issue, everything else appears to be working. All the custom templates/data sources/graphs I've created over the years are fine. It's just that now they have occasional breaks.
Somewhere in the update process, a second cron job was added so I had 2 pollers running at the same time. I deleted that cron job so I'm fairly certain there's only one running now

Here's a small piece of the cacti log filtered to system stats. The number of RRDs Processed varies under normal circumstances because of residential connections going up and down on an ISP network.

2022/06/17 08:50:22 - SYSTEM STATS: Time:20.4175 Method:spine Processes:5 Threads:50 Hosts:6037 HostsPerProcess:1208 DataSources:46579 RRDsProcessed:34203
2022/06/17 08:55:21 - SYSTEM STATS: Time:19.1695 Method:spine Processes:5 Threads:50 Hosts:6037 HostsPerProcess:1208 DataSources:46579 RRDsProcessed:34197
2022/06/17 09:00:21 - SYSTEM STATS: Time:20.0889 Method:spine Processes:5 Threads:50 Hosts:6037 HostsPerProcess:1208 DataSources:46579 RRDsProcessed:34185
2022/06/17 09:10:01 - SYSTEM STATS: Time:299.4940 Method:spine Processes:5 Threads:50 Hosts:6037 HostsPerProcess:1208 DataSources:46579 RRDsProcessed:29258
2022/06/17 09:15:00 - SYSTEM STATS: Time:299.1006 Method:spine Processes:5 Threads:50 Hosts:6037 HostsPerProcess:1208 DataSources:46579 RRDsProcessed:29357
2022/06/17 09:15:21 - SYSTEM STATS: Time:19.2340 Method:spine Processes:5 Threads:50 Hosts:6037 HostsPerProcess:1208 DataSources:46579 RRDsProcessed:34192
2022/06/17 09:20:27 - SYSTEM STATS: Time:25.0940 Method:spine Processes:5 Threads:50 Hosts:6037 HostsPerProcess:1208 DataSources:46579 RRDsProcessed:34194
2022/06/17 09:25:22 - SYSTEM STATS: Time:20.1992 Method:spine Processes:5 Threads:50 Hosts:6037 HostsPerProcess:1208 DataSources:46579 RRDsProcessed:34230

Thanks for any help you can provide.

[TheWitness]

pull the 1.2.x spine and try again. Likely it's segfaulting. You can find errors in your Cacti stderr file.

[warben61]

You're on to something there. It's definitely segfaulting. I just pulled the latest 1.2.21 from the website and installed... same results. Do I need to do anything other than the steps below?

./bootstrap
./configure
make
make install
chown root:root /usr/local/spine/bin/spine
chmod +s /usr/local/spine/bin/spine

This is what posted to cacti_stderr.log after the latest poller cycle:

double free or corruption (fasttop)
FATAL: Spine Encountered a Segmentation Fault
Generating backtrace...0 line(s)...
FATAL: Spine Interrupted by Abort Signal
Unable to flush stdout: Broken pipe

[TheWitness]

Cool, now do this...

Code: Select all

gdb ./spine
run

Then, once it crashes:

Code: Select all

bt
bt full

Post the output.

[warben61]

Sorry for the delay, my day ended and then I had evening plans. I attached a few files here for you. It ran perfectly fine for an hour before I caught something. The only change I made to the output was to sanitize our snmp communities with snmp-xxx.

GDB Debug - No errors: Debug of a polling cycle that completed successfully

GDB Debug - Abort Signal 11-05am and 11-10am: The following lines posted to the cacti_stderr.log file:
double free or corruption (fasttop)
FATAL: Spine Interrupted by Abort Signal

GDB Debug - Segfault 11-15am: The following lines posted to the cacti_stderr.log file:
double free or corruption (fasttop)
FATAL: Spine Encountered a Segmentation Fault
Generating backtrace...0 line(s)...
FATAL: Spine Interrupted by Abort Signal
Unable to flush stdout: Broken pipe

[TheWitness]

I've made a few changes to the 1.2.x branch. Definitely found the double free error. Keep testing.

[warben61]

Awesome, thanks. Will do. I pulled the latest from github and have it running. I'll let you know tomorrow how it runs overnight.

[warben61]

Quick update - So far so good with spine but I'm getting some new errors in cacti.log. I attached a snippet of the cacti log and another spine trace.

2022/06/18 23:20:20 - SPINE: Poller[1] PID[1036393] PT[140459389220608] ERROR: SQL Failed! Error:'1582', Message:'Incorrect parameter count in the call to native function 'FROM_UNIXTIME'', SQL Fragment:'INSERT INTO poller_output (local_data_id, rrd_name, time, output) VALUES (42253, 'traffic_in', FROM_UNIXTIME(), '2303863764'),(42253, 'traffic_out', FROM_UNIXTIME(), '2399666103') ON DUPLICATE KEY UPDATE output=VALUES(output)'

[TheWitness]

Well, that's not good. Looking into it this morning after breakfast.

[warben61]

Hmm I'm still getting occasional double free of corruption as well as the segfaults. And another new thing: something related to netsnmp.

lock in _callback_lock sleeps more than 100 milliseconds in snmp_call_callbacks
netsnmp_assert lock_holded < 100 failed callback.c:146 _callback_lock()

I don't know if the snmp problem results in breaks in the graphs or not. Side note... thoughts on adding timestamps to cacti_stderr.log? I'll see if I can catch a debug of it.

This is my log for the last 8 hours when it rotated at midnight.

double free or corruption (fasttop)
FATAL: Spine Interrupted by Abort Signal
Unable to flush stdout: Broken pipe
double free or corruption (fasttop)
FATAL: Spine Interrupted by Abort Signal
lock in _callback_lock sleeps more than 100 milliseconds in snmp_call_callbacks
netsnmp_assert lock_holded < 100 failed callback.c:146 _callback_lock()
double free or corruption (fasttop)
FATAL: Spine Encountered a Segmentation Fault
Generating backtrace...0 line(s)...
FATAL: Spine Interrupted by Abort Signal
lock in _callback_lock sleeps more than 100 milliseconds in snmp_call_callbacks
netsnmp_assert lock_holded < 100 failed callback.c:146 _callback_lock()
lock in _callback_lock sleeps more than 100 milliseconds in snmp_call_callbacks
netsnmp_assert lock_holded < 100 failed callback.c:146 _callback_lock()
double free or corruption (fasttop)
FATAL: Spine Interrupted by Abort Signal
lock in _callback_lock sleeps more than 100 milliseconds in snmp_call_callbacks
netsnmp_assert lock_holded < 100 failed callback.c:146 _callback_lock()
double free or corruption (fasttop)
FATAL: Spine Encountered a Segmentation Fault
Generating backtrace...0 line(s)...
FATAL: Spine Interrupted by Abort Signal
FATAL: Spine Encountered a Segmentation Fault
Generating backtrace...0 line(s)...
Unable to flush stdout: Broken pipe
double free or corruption (fasttop)
FATAL: Spine Interrupted by Abort Signal
double free or corruption (fasttop)
FATAL: Spine Interrupted by Abort Signal
Unable to flush stdout: Broken pipe
double free or corruption (fasttop)
FATAL: Spine Interrupted by Abort Signal

[TheWitness]

Okay, the time issue should be MySQL error solved. Let's see if it fixes the aborts too. Keep testing.

[TheWitness]

This guy here, appears to be a thread safety issue with the net-snmp library on the session open. According to their documentation it was apparently thread safe, but I guess now. I'll re-introduce the mutex lock.

Code: Select all

netsnmp_assert lock_holded < 100 failed callback.c:146 _callback_lock()

[TheWitness]

Okay, that snmp session issue change is backed out. Keep testing.

[warben61]

10-4, testing now. Thanks. The SQL errors are gone on now. Time will tell on segfaults.

[TheWitness]

Okay, keep me updated.