So, I am trying to have bro send me report/alerts at specific timeslots.
Given current_time is the wall-clock time, I am relying on current_time() function to get time and then, my code is : if (hh:mm:ss == desired time), run a report. I noticed inconsistencies so here is more detailed debug log:
I notice, jumps in the current_time:
Report time is 1447869593.121702, report hour is 9:59:53
Report time is 1447869595.234395, report hour is 9:59:55
Report time is 1447869596.45385, report hour is 9:59:56
Report time is 1447869597.636261, report hour is 9:59:57
Report time is 1447869598.597632, report hour is 9:59:58
Report time is 1447869599.628088, report hour is 9:59:59
Report time is 1447869601.926001, report hour is 10:0:1 <----- no 10:0:0 ?
Report time is 1447869603.182218, report hour is 10:0:3 <--- jump
Report time is 1447869604.166191, report hour is 10:0:4
Report time is 1447869605.647308, report hour is 10:0:5
Report time is 1447869606.499426, report hour is 10:0:6
Report time is 1447869607.383869, report hour is 10:0:7
Report time is 1447869617.52706, report hour is 10:0:17 <----- big jump
Report time is 1447869618.188414, report hour is 10:0:18
Report time is 1447869619.04252, report hour is 10:0:19 <- stall ?
Report time is 1447869619.733979, report hour is 10:0:19 <--- stall ?
Report time is 1447869622.635545, report hour is 10:0:22
Report time is 1447869623.28335, report hour is 10:0:23
I believe network_time would be somewhat better probably and will try to see how that fares for my usecase. Any idea why I see such jumps on the wall-clock times ? I'd think this should be rather more reliable ?
So, I am trying to have bro send me report/alerts at specific time-slots.
Given current_time is the wall-clock time, I am relying on
current_time() function to get time and then, my code is : if
(hh:mm:ss == desired time), run a report. I noticed inconsistencies
so here is more detailed debug log:
I notice, jumps in the current_time:
Report time is 1447869593.121702, report hour is 9:59:53
Report time is 1447869595.234395, report hour is 9:59:55
Report time is 1447869596.45385, report hour is 9:59:56
Report time is 1447869597.636261, report hour is 9:59:57
Report time is 1447869598.597632, report hour is 9:59:58
Report time is 1447869599.628088, report hour is 9:59:59
Report time is 1447869601.926001, report hour is 10:0:1 <----- no 10:0:0 ?
Report time is 1447869603.182218, report hour is 10:0:3 <--- jump
Report time is 1447869604.166191, report hour is 10:0:4
Report time is 1447869605.647308, report hour is 10:0:5
Report time is 1447869606.499426, report hour is 10:0:6
Report time is 1447869607.383869, report hour is 10:0:7
Report time is 1447869617.52706, report hour is 10:0:17 <----- big jump
Report time is 1447869618.188414, report hour is 10:0:18
Report time is 1447869619.04252, report hour is 10:0:19 <- stall ?
Report time is 1447869619.733979, report hour is 10:0:19 <--- stall ?
Report time is 1447869622.635545, report hour is 10:0:22
Report time is 1447869623.28335, report hour is 10:0:23
I believe network_time would be somewhat better probably and will try
to see how that fares for my use case.
Any idea why I see such jumps on the wall-clock times ? I'd think this
should be rather more reliable ?
My recommendation for how to implement this would be to calculate a unix
timestamp (seconds since 1970) that corresponds to the next time you
want send a report and then poll for when time() is >= this value. After
sending the report, calculate the next timestamp.
I'm not sure what you have available but to generate the unix timestamp
I would use localtime() or gmtime() (using gmtime() avoids daylight
saving time issues) to break out the fields, set the H, M and S to the
desired values and then use mktime() (or timegm()) to convert back to a
unix timestamp.
My recommendation for how to implement this would be to calculate a unix
timestamp (seconds since 1970) that corresponds to the next time you
want send a report and then poll for when time() is >= this value. After
sending the report, calculate the next timestamp.
For the script you sent me, the 1-second skips aren't that surprising.
Bro's "schedule" sets a minimum time in the future for when the event
will occur. The actual time will be a tad later, depending on how long
it takes the event engine to process the buffer of packets that leads
to the clock advancing past the scheduled time. So for example if
at network time 1.95 you schedule an event for one second in the future,
that won't be looked at until a set of packets arrives for which one
of them has a network time of >= 2.95. Those packets will first be
processed before doing the scheduled event.
In addition, network-time will lag current-time by an amount proportional
to the packet capture buffer. If the buffer is a few hundred msec's worth,
then you will not infrequently get a mismatch regarding times of one-second
granularity.
OTOH, this:
Report time is 1447869607.383869, report hour is 10:0:7
Report time is 1447869617.52706, report hour is 10:0:17 <----- big jump
is definitely not good. I'm not seeing how your script could lead to
that behavior other than the event engine going away (= spending time
processing packets) for around 10 seconds.
Regarding this:
Report time is 1447869618.188414, report hour is 10:0:18
Report time is 1447869619.04252, report hour is 10:0:19 <- stall ?
Report time is 1447869619.733979, report hour is 10:0:19 <--- stall ?
I can at least construct a theory. Suppose the event was supposed to
happen at 10:0:18.8. A packet comes in with that network time, so the
event fires, but only 200 msec later, so current-time shows 10:0:19.
The script schedules based on network-time rather than current-time, so
it'll set the next event for 10:0:19.8. When that packet arrives, there's
less to process, so the script runs before the current-time advances to
10:0:20.
In any case, I agree that Craig's proposed fix is a good way to deal
with this. In addtion, I think this points up the utility of Bro
providing cron-style event scheduling in addition to relative-time
scheduling.