Boost - Stale updates causes problems with updates?

[imriz]

Hi,

Yesterday, one of my users complained that one of his graphs was not updated for a significant amount of time (my update interval is 2 hours).
Investigating the issue, I've found that BOOST tried to perform an illegal update, which included the missing data:


01/02/2012 06:53:30 PM - BOOST: Poller[0] NOTE: Updating Local Data Id:'313832', Template:traffic_in:traffic_out, Output: 1325512806:3400599553:540592752 1325513104:3467195532:737565602 1325513422:3555211532:1117568116 1325513719:3635529014:1724907259
01/02/2012 06:56:50 PM - BOOST: Poller[0] WARNING: Stale Poller Data Found! Item Time:'1325512806', RRD Time:'1325513719' Ignoring Value!
01/02/2012 06:56:50 PM - BOOST: Poller[0] WARNING: Stale Poller Data Found! Item Time:'1325512806', RRD Time:'1325513719' Ignoring Value!
01/02/2012 06:56:50 PM - BOOST: Poller[0] WARNING: Stale Poller Data Found! Item Time:'1325512806', RRD Time:'1325513719' Ignoring Value!
01/02/2012 06:56:50 PM - BOOST: Poller[0] WARNING: Stale Poller Data Found! Item Time:'1325512806', RRD Time:'1325513719' Ignoring Value!
01/02/2012 06:56:50 PM - BOOST: Poller[0] WARNING: Stale Poller Data Found! Item Time:'1325512806', RRD Time:'1325513719' Ignoring Value!
01/02/2012 06:56:50 PM - BOOST: Poller[0] WARNING: Stale Poller Data Found! Item Time:'1325512806', RRD Time:'1325513719' Ignoring Value!
01/02/2012 06:56:50 PM - BOOST: Poller[0] WARNING: Stale Poller Data Found! Item Time:'1325512806', RRD Time:'1325513719' Ignoring Value!
01/02/2012 06:56:50 PM - BOOST: Poller[0] WARNING: Stale Poller Data Found! Item Time:'1325512806', RRD Time:'1325513719' Ignoring Value!
01/02/2012 06:56:50 PM - BOOST: Poller[0] WARNING: Stale Poller Data Found! Item Time:'1325512806', RRD Time:'1325513719' Ignoring Value!
01/02/2012 06:56:50 PM - BOOST: Poller[0] NOTE: Updating Local Data Id:'313832', Template:traffic_in:traffic_out, Output: 1325512806 1325513104 1325513422 1325513719 1325514029:2322161214 1325514341:3866007803:3089433285 1325514646:3930664492:3604904443 1325514919:4025955727:4283128537 1325515208:4175034609:1088164467 1325515514:4269390309:2060138232 1325515824:109707849:2238405190 1325516111:240085799:2468780087 1325516426:321992274:2629249694 1325516708:398867801:2816917051 1325517022:468458146:2975578611 1325517325:524753313:3190305686 1325517612:619153238:3360842404 1325517923:703990907:3603649413 1325518222:822494649:3822125627 1325518512:902968270:4077737397 1325518830:992666530:4264055126 1325519122:1070007469:135631877 1325519415:1165817288:278216004 1325519718:1238739335:552231723 1325520013:1308949418:777719836 1325520312:1392975807:994675413 1325520637:1466332733:1175771036 1325520939:1523779633:1368524705 1325521231:1579348117:1504886710 1325521536:1649727596:1644974018 1325521821:1706580597:1775454873 1325522134:1767012634:1922004542 1325522426:1817428705:2035924734 1325522730:1871469212:2159918280 1325523005:1892708712:2203429173


It looks like BOOST first append $time into $outbuf and only then performs the stale check. So if the data is stale, the outbuf still contains the orphaned timestamp.

I'm using BOOST 4.3, but at first glance, it seems like it is the same in the latest version.

Please advise if I mis-read the code, or is it a real bug.

Thanks,

[imriz]

Should I report a bug?

[gandalf]

Yep
R.

[imriz]

I've upgraded my boost plugin to the latest version (5.1) and I am still seeing a problem.

it seems like when the on-demand update is running while the poller is running, boost tries an incomplete update:

02/21/2012 07:00:16 PM - BOOST: Poller[0] NOTE: Updating Local Data ID:'318854', Total of '1' Updates to Process
02/21/2012 07:00:17 PM - BOOST: Poller[0] NOTE: Updating Local Data Id:'318854', Template:traffic_in:traffic_out, Output: 1329843213:2218203852
02/21/2012 07:05:19 PM - BOOST: Poller[0] NOTE: Updating Local Data ID:'318854', Total of '3' Updates to Process
02/21/2012 07:05:19 PM - BOOST: Poller[0] NOTE: Updating Local Data Id:'318854', Template:traffic_in:traffic_out, Output: 1329843213:3171414395 1329843730:3492132140:1460729342

I am guessing that because the on-demand update calls boost_process_poller_output, while the poller is running (and feeding incomplete results to boost_poller_on_demand), it gets incomplete results.

I should note, that due to performance considerations, we've changed the poller_output_boost table to the InnoDB engine, and that this change could also be related (row level locking etc).

Does it makes any sense to you?