0.8.6b: ERROR: illegal attempt to update using time X

gninja

Just upgraded to 0.8.6b, and I'm getting a large number of what looks like duplicate attempts to update rrd files.

Getting:
ERROR: illegal attempt to update using time 1097873100 when last update time is 1097873101 (minimum one second step)

If I set logging to debug and check the log, I see a lot of:

10/15/2004 01:30:05 PM - POLLER: Poller[0] CACTI2RRD: /usr/local/bin/rrdtool update /usr/local/www/data-dist/cacti/rra/ui02_load_1min_300.rrd --template load_1min 1097872201:0.77
10/15/2004 01:30:59 PM - POLLER: Poller[0] CACTI2RRD: /usr/local/bin/rrdtool update /usr/local/www/data-dist/cacti/rra/ui02_load_1min_300.rrd --template load_1min 1097872200:0.42

Clearing the poller cache didn't help.

raX · Posted: Mon Oct 18, 2004 11:00 am Post subject:

Run the following SQL query on your Cacti database. If you get any results back, it means that you have duplicate RRD filename references in your database.

gninja · Posted: Mon Oct 18, 2004 12:34 pm Post subject:

mysql> select
-> local_data_id,
-> count(data_source_path)
-> from data_template_data
-> where local_data_id > 0
-> group by local_data_id
-> having count(data_source_path) > 1;
Empty set (0.06 sec)

raX · Posted: Mon Oct 18, 2004 2:14 pm Post subject:

So your error isn't a result of duplicate filenames... Is it possible that more than one copy of cactid/cmd.php/poller.php is being started from cron? Remember that only poller.php should be executed every 5 minutes. Make sure to check both the /etc/crontab file and the /etc/cron.d/ directory.

-Ian

gninja · Posted: Mon Oct 18, 2004 2:42 pm Post subject:

Nope, only one cronjob.

$ crontab -l
*/5 * * * * /usr/local/bin/php-cli /usr/local/www/data/cacti/poller.php > /usr/local/www/data/cacti/cmd.out 2>&1

I've got output from before the 0.8.6b upgrade, and after and this didn't exist before.
Before 0.8.6b, I was running the 10/03 nightly with an rrd.php patch from TheWitness.

raX · Posted: Mon Oct 18, 2004 3:24 pm Post subject:

It is possible that you have a bunch of junk in your 'poller_output' table. Try doing a 'truncate table poller_output;' before running poller.php to see if that makes a difference.

-Ian

gninja · Posted: Mon Oct 18, 2004 3:59 pm Post subject:

Hrm. Ok, that seemed to fix it for most of one run. Then the latter portion of that run it started doing it again.

Subsequent runs are getting the error all over the place.

raX · Posted: Mon Oct 18, 2004 9:08 pm Post subject:

Try running poller.php all the way through so it finishes normally. Once it is finished open up a mysql prompt and do a 'select * from poller_output;'. Do you get any results from this query?

-Ian

gninja · Posted: Tue Oct 19, 2004 12:29 pm Post subject:

Yea, had a couple hundred rows in there.

Checked ps, and there were seven poller.php processes running, after I'd gotten the "finished" message.

Killed them all, ran it again.

And I've still got a lingering cmd.php and script_server.php, and an increasing number of rows in poller_output.

Standard out, and output to the cacti logfile stop 63 seconds after the cron job runs.

The lingering processes finished up about 2 minutes later, and left 749 rows in poller_output.

raX · Posted: Tue Oct 19, 2004 3:29 pm Post subject:

The last thing poller.php does before it exits is to run this SQL statement:

gninja · Posted: Tue Oct 19, 2004 3:40 pm Post subject:

Runtime generally hits about 60-70 seconds...

10/19/2004 01:46:08 PM - SYSTEM STATS: Time: 68.2162 s, Method: cmd.php, Processes: 6, Threads: N/A, Hosts: 63, Hosts/Process: 11

And due to some previous issues, my php memory limit is:

$ cat /usr/local/etc/php.ini | grep mem
memory_limit=2048M

raX · Posted: Tue Oct 19, 2004 3:56 pm Post subject:

Do you have a system cron log that you can use to confirm poller.php is not running more than once every 5 minutes? I think on most systems it is at /var/log/cron.

-Ian

gninja · Posted: Tue Oct 19, 2004 3:59 pm Post subject:

Once per 5 minutes:

Oct 19 13:50:00 monitor01 /usr/sbin/cron[27019]: (root) CMD (/usr/local/bin/php-cli /usr/local/www/data/cacti/poller.php > /usr/local/www/data/cacti/cmd.out 2>&1)
Oct 19 13:55:00 monitor01 /usr/sbin/cron[36121]: (root) CMD (/usr/local/bin/php-cli /usr/local/www/data/cacti/poller.php > /usr/local/www/data/cacti/cmd.out 2>&1)
Oct 19 14:00:00 monitor01 /usr/sbin/cron[44717]: (root) CMD (/usr/local/bin/php-cli /usr/local/www/data/cacti/poller.php > /usr/local/www/data/cacti/cmd.out 2>&1)
Oct 19 14:05:00 monitor01 /usr/sbin/cron[53907]: (root) CMD (/usr/local/bin/php-cli /usr/local/www/data/cacti/poller.php > /usr/local/www/data/cacti/cmd.out 2>&1)

raX · Posted: Tue Oct 19, 2004 4:07 pm Post subject:

What about if you look in the Cacti log? Do you see a "SYSTEM STATS" line about every 5 minutes there as well?

-Ian

gninja · Posted: Tue Oct 19, 2004 4:09 pm Post subject:

Yup.

10/19/2004 02:01:03 PM - SYSTEM STATS: Time: 62.4795 s, Method: cmd.php, Processes: 6, Threads: N/A, Hosts: 63, Hosts/Process: 11
10/19/2004 02:06:05 PM - SYSTEM STATS: Time: 64.8905 s, Method: cmd.php, Processes: 6, Threads: N/A, Hosts: 63, Hosts/Process: 11
10/19/2004 02:11:02 PM - SYSTEM STATS: Time: 61.8895 s, Method: cmd.php, Processes: 6, Threads: N/A, Hosts: 63, Hosts/Process: 11
10/19/2004 02:16:20 PM - SYSTEM STATS: Time: 79.4676 s, Method: cmd.php, Processes: 6, Threads: N/A, Hosts: 63, Hosts/Process: 11