SOLVED - Graph update delayed - missing last hour

[yont]

Greetings,

I'm trying to figure our why all of my graphs are missing the last hour of data. I'm using v0.8.7d, spine poller.

crontab:

Code: Select all

*/5     *       *       *       *       cacti    /usr/local/bin/php /usr/local/share/cacti/poller.php > /dev/null 2>&1

• Verified owner:group as cacti

I've noticed something that looks a little strange. As you can see there is exactly (+ 1 sec) a 1 hour difference between the polled device queries and the SQL updates. Or so it seems.. I verified that my system date is current. Does this mean that the actual updates to the rrd files are delayed until 4:55, 1 hour from now (3:55) or that the time recorded in the rrd file is now + hour?

Code: Select all

08/15/2009 03:55:01 PM - SPINE: Poller[0] Host[2] DS[8] SCRIPT: /usr/local/bin/php /usr/local/share/cacti/scripts/ss_fping.php 74.125.67.100, output: min:52.5300 avg:56.1027 max:58.1170 dev:1.9104 loss:0.0000
08/15/2009 03:55:01 PM - SPINE: Poller[0] Host[2] DEBUG: HOST COMPLETE: About to Exit Host Polling Thread Function
08/15/2009 03:55:01 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 0
08/15/2009 03:55:01 PM - SPINE: Poller[0] DEBUG: Thread Cleanup Complete
08/15/2009 03:55:01 PM - SPINE: Poller[0] DEBUG: PHP Script Server Pipes Closed
08/15/2009 03:55:01 PM - SPINE: Poller[0] DEBUG: Allocated Variable Memory Freed
08/15/2009 03:55:01 PM - SPINE: Poller[0] SPINE: Net-SNMP API Shutdown Completed
08/15/2009 03:55:01 PM - SPINE: Poller[0] DEBUG: MYSQL Free & Close Completed
08/15/2009 03:55:01 PM - SPINE: Poller[0] Time: 0.5797 s, Threads: 60, Hosts: 2
08/15/2009 04:55:02 PM - CMDPHP: Poller[0] DEVEL: SQL Assoc: "select poller_id,end_time from poller_time where poller_id=0"
08/15/2009 04:55:02 PM - CMDPHP: Poller[0] DEVEL: SQL Assoc: "select  poller_output.output,  poller_output.time,  poller_output.local_data_id,  poller_item.rrd_path,  poller_item.rrd_name,  poller_item.rrd_num  from (poller_output,poller_item)  where (poller_output.local_data_id=poller_item.local_data_id and poller_output.rrd_name=poller_item.rrd_name)  "
08/15/2009 04:55:02 PM - CMDPHP: Poller[0] DEVEL: SQL Assoc: "select     data_template_rrd.data_source_name,     data_input_fields.data_name     from (data_template_rrd,data_input_fields)     where data_template_rrd.data_input_field_id=data_input_fields.id     and data_template_rrd.local_data_id=8"
08/15/2009 04:55:02 PM - CMDPHP: Poller[0] DEVEL: SQL Exec: "delete from poller_output where local_data_id='8' and rrd_name='' and time='2009-08-15 15:55:00'"
08/15/2009 04:55:02 PM - POLLER: Poller[0] CACTI2RRD: /usr/local/bin/rrdtool update /usr/local/share/cacti/rra/sparkplug_parent_dev_8.rrd --template min:avg:max 1250373300:52.5300:56.1027:58.1170
08/15/2009 04:55:02 PM - SYSTEM STATS: Time:1.4168 Method:spine Processes:10 Threads:60 Hosts:4 HostsPerProcess:1 DataSources:7 RRDsProcessed:7
08/15/2009 04:55:02 PM - CMDPHP: Poller[0] DEVEL: SQL Exec: "REPLACE INTO settings (name,value) VALUES ('stats_poller','Time:1.4168 Method:spine Processes:10 Threads:60 Hosts:4 HostsPerProcess:1 DataSources:7 RRDsProcessed:7')"
08/15/2009 04:55:02 PM - CMDPHP: Poller[0] DEVEL: SQL Cell: "SELECT COUNT(*) FROM poller_command"
08/15/2009 04:55:02 PM - CMDPHP: Poller[0] DEVEL: SQL Exec: "REPLACE INTO settings (name,value) VALUES ('stats_recache','RecacheTime:0.0 HostsRecached:0')"

Have I missed something in my configuration? Thanks all!

yont

[cert-eh-fiable]

that looks as though the time updated on the box the script would be pulling from the system time

[yont]

As you can see (20:13mil) translates to 08:13PM. The poller log entries show the correct time +2 minutes (i.e. 8:15PM, 2 munutes elapsed waiting for the poller to run) But the SQL entries show 9:15PM, one hour later than the system datetime. Strange - Mystery to me...

Code: Select all

admin@noc:/usr/local/share/cacti/log# date
Sat Aug 15 20:13:49 MST 2009
admin@noc:/usr/local/share/cacti/log# tail -f cacti.log
...{ snip - too much to post with debug enabled }...

08/15/2009 08:15:01 PM - SPINE: Poller[0] DEBUG: Allocated Variable Memory Freed
08/15/2009 09:15:01 PM - POLLER: Poller[0] CACTI2RRD: /usr/local/bin/rrdtool update /usr/local/share/cacti/rra/localhost_mem_swap_4.rrd --template mem_swap 1250388900:U
08/15/2009 08:15:01 PM - SPINE: Poller[0] SPINE: Net-SNMP API Shutdown Completed
08/15/2009 08:15:01 PM - SPINE: Poller[0] DEBUG: MYSQL Free & Close Completed
08/15/2009 08:15:01 PM - SPINE: Poller[0] Time: 0.1012 s, Threads: 60, Hosts: 2
08/15/2009 08:15:01 PM - SPINE: Poller[0] Host[2] DS[8] SCRIPT: /usr/local/bin/php /usr/local/share/cacti/scripts/ss_fping.php 74.125.45.100, output: min:25.7370 avg:26.3690 max:27.0390 dev:0.4784 loss:0.0000
08/15/2009 08:15:01 PM - SPINE: Poller[0] DEBUG: SQL:'INSERT INTO poller_output (local_data_id, rrd_name, time, output) VALUES (8,'','2009-08-15 20:15:01','min:25.7370 avg:26.3690 max:27.0390 dev:0.4784 loss:0.0000')'
08/15/2009 08:15:01 PM - SPINE: Poller[0] Host[2] DEBUG: HOST COMPLETE: About to Exit Host Polling Thread Function
08/15/2009 08:15:01 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 0
08/15/2009 08:15:01 PM - SPINE: Poller[0] DEBUG: SQL:'replace into settings (name,value) values ('date',NOW())'
08/15/2009 08:15:01 PM - SPINE: Poller[0] DEBUG: SQL:'insert into poller_time (poller_id, start_time, end_time) values (0, NOW(), NOW())'
08/15/2009 08:15:01 PM - SPINE: Poller[0] DEBUG: Thread Cleanup Complete
08/15/2009 08:15:01 PM - SPINE: Poller[0] DEBUG: PHP Script Server Pipes Closed
08/15/2009 08:15:01 PM - SPINE: Poller[0] DEBUG: Allocated Variable Memory Freed
08/15/2009 08:15:01 PM - SPINE: Poller[0] SPINE: Net-SNMP API Shutdown Completed
08/15/2009 08:15:01 PM - SPINE: Poller[0] DEBUG: MYSQL Free & Close Completed
08/15/2009 08:15:01 PM - SPINE: Poller[0] Time: 0.3643 s, Threads: 60, Hosts: 2
08/15/2009 09:15:02 PM - POLLER: Poller[0] Parsed MULTI output field 'min:25.7370' [map min->min]
08/15/2009 09:15:02 PM - POLLER: Poller[0] Parsed MULTI output field 'avg:26.3690' [map avg->avg]
08/15/2009 09:15:02 PM - POLLER: Poller[0] Parsed MULTI output field 'max:27.0390' [map max->max]
08/15/2009 09:15:02 PM - POLLER: Poller[0] CACTI2RRD: /usr/local/bin/rrdtool update /usr/local/share/cacti/rra/sparkplug_parent_dev_8.rrd --template min:avg:max 1250388901:25.7370:26.3690:27.0390
08/15/2009 09:15:02 PM - SYSTEM STATS: Time:1.4168 Method:spine Processes:10 Threads:60 Hosts:4 HostsPerProcess:1 DataSources:7 RRDsProcessed:7

The demarcation seems to be between the "poller" and "spine"

Code: Select all

08/15/2009 08:15:01 PM - SPINE: Poller[0] Time: 0.3643 s, Threads: 60, Hosts: 2
08/15/2009 09:15:02 PM - POLLER: Poller[0] Parsed MULTI output field 'min:25.7370' [map min->min]

[cert-eh-fiable]

if you resync the poller do the logs match up?

Console -> Utilities > rebuild poller cache

[yont]

I had tried that, but for good measure did so again. Result: (in the order written to in the log - top to bottom:

Code: Select all

08/15/2009 10:30:00 PM - POLLER: Poller[0] CACTI2RRD: /usr/local/bin/rrdtool update /usr/local/share/cacti/rra/localhost_load_1min_5.rrd --template load_1min:load_5min:load_15min 1250393400:0.00:0.01:0.00
08/15/2009 09:30:00 PM - SPINE: Poller[0] Host[3] DS[11] SNMP: v1: ptp-mm2spark.brfn.az.commspeed.net, dsname: rssi_oid, oid: .1.3.6.1.4.1.5454.1.50.3.14.0, value: -29

A little further down in the log:

Code: Select all

08/15/2009 09:30:01 PM - SPINE: Poller[0] Time: 0.3947 s, Threads: 60, Hosts: 2
08/15/2009 10:30:01 PM - CMDPHP: Poller[0] DEVEL: SQL Assoc: "select poller_id,end_time from poller_time where poller_id=0"

[cert-eh-fiable]

Yes that's interesting.

I thought you could run one poller or the other but not both spine and cmd.php at the same time where they would both show in the log like that. I've never used spine so I don't know if that's a normal log or not.

What happens if you change to the other poller in your config? Same logs?

[yont]

Here's a look at my poller settings. The other "Poller Type" option is cmd.php which is "not" selected.

[yont]

The problem was with the default timezone setting in the php.ini file. While I set the proper timezone on the OS install, evidently, you must also set the date.timezone = your_timezone in the php.ini file. So setting it and restarting apache, all is working now.

cmd.php pulling the datetime from php env variables.

Code: Select all

$start = date("Y-n-d H:i:s"); // for runtime measurement

Apache ENV from Cacti/Tech Support

Code: Select all

date
date/time support 	enabled
"Olson" Timezone Database Version 	2009.1
Timezone Database 	internal
Default timezone 	America/Denver

Directive	Local Value	Master Value
date.default_latitude	31.7667	31.7667
date.default_longitude	35.2333	35.2333
date.sunrise_zenith	90.583333	90.583333
date.sunset_zenith	90.583333	90.583333
Default timezone 	America/Denver America/Denver

Edit /usr/loca/etc/php.ini adding timezone

Code: Select all

;;;;;;;;;;;;;;;;;;;
; Module Settings ;
;;;;;;;;;;;;;;;;;;;
 
[Date]
; Defines the default timezone used by the date functions
date.timezone = America/Phoenix

Apache ENV from Cacti/Tech Support - after php.ini edit

Code: Select all

date
date/time support 	enabled
"Olson" Timezone Database Version 	2009.1
Timezone Database 	internal
Default timezone 	America/Phoenix

Directive	Local Value	Master Value
date.default_latitude	31.7667	31.7667
date.default_longitude	35.2333	35.2333
date.sunrise_zenith	90.583333	90.583333
date.sunset_zenith	90.583333	90.583333
date.timezone	America/Phoenix	America/Phoenix

And results

Code: Select all

08/16/2009 09:45:01 AM - SPINE: Poller[0] DEBUG: MYSQL Free & Close Completed
08/16/2009 09:45:01 AM - SPINE: Poller[0] Time: 0.3645 s, Threads: 15, Hosts: 2
08/16/2009 09:45:02 AM - CMDPHP: Poller[0] DEVEL: SQL Assoc: "select poller_id,end_time from poller_time where poller_id=0"

Let me say thank you cert-eh-fiable. I really appreciate your help.

yont