recording time adjustment

[dolfs]

I had to do some work on my Raspberry and shut down moonfire and then took the power off. Although not planned, is later powered up, and interrupted power without a clean shutdown. Either way, once I started up to resume service, the web UI kept showing a latest recording just after 9PM (see attachment) and did not seem to catch up with the actual time which was around 10:40PM. Eventually I clicked on the 9:09PM file and it shows that it contained a recent recording (based on camera time stamp). So, it seems that in the face of an interruption of recording(s) the time index gets messed up.

Update: After a few hours the index had not corrected. I perform a systemctl stop and then a start and after a few minutes, that seems to have cured the issue.

[scottlamb]

Interesting. Could you gather logs from the offending timespan? also, several fields from the offending recording table rows: composite_id, run_offset, flags, start_time_90k, duration_90k, local_time_delta_90k.

[dolfs]

Here is the log with some comments interspersed. moonfire.daemon.log.txt

[scottlamb]

Thanks. That log has a smoking gun here:

Aug 14 21:05:51 moonfire moonfire-nvr[710]: Aug 14 21:05:51.538 INFO reserved 590d892d-b2e8-4e6c-9e1b-c4418d0abd69
Aug 14 22:37:39 moonfire systemd[1]: Time has been changed
Aug 14 22:38:48 moonfire moonfire-nvr[710]: Aug 14 22:38:48.965 INFO Committing extra transaction because there's no cached uuid

systemd says that CLOCK_REALTIME got adjusted. Those moonfire-nvr log entries on either side would have been no more than a minute apart, so it must have stepped forward by roughly an hour and a half, consistent with the difference between Moonfire's timestamps and the ones the camera encoded into the image.

Moonfire NVR currently only looks at CLOCK_REALTIME at the beginning of a recording, as described in time.md, so it's behaving as designed. Restarting forced a new recording to start; briefly losing the connection to the camera would have done the same thing.

I'm open to changing the design, but it's not clear to me off-hand what we could do better. If the system clock changes, should we assume the more recent time is better? should we just adjust the recordings currently in progress or also previous ones in the same boot or something? what would the consequences on a web interface / scrub bar be of changing times of recordings after the fact?

I mentioned in person that Moonfire also grabs CLOCK_REALTIME once per segment and sticks that in the database, but I must have misremembered. streamer.rs calls clocks.realtime() only at the beginning of a recording. We could change that for debugging purposes if nothing else.

[dolfs]

Clearly overlooked that. Good find. Totally baffled as to why it took 1.5 hrs after boot to get the time corrected (presumably through ntp as I did not do it manually).

As far as doing things better, I agree that the clock changing behind your back does not mean it changed to something better, although I would think that in the majority of cases it would. Whether or not it is worth it to add code to detect and handle such situations I am not sure. As far as "changes after the fact": that could likely be treated as if the UI was working with cached, and now stale data. Correcting "backwards" for the current boot might not be good enough anyway as nothing guarantees that there were not multiple restarts before the time was corrected. On the other hand, detecting it, and correcting backwards within the boot would, most often improve the situation, if not completely in some contrived cases.

It might make more sense to allow some UI action to have moonfire (re)check the time. That would be less intrusive than having to ssh and systemctl restart (which would also achieve it). Probably a low priority item and it would face the same logic as to how far back to correct.

[scottlamb]

I think I'll implement this idea from https://github.com/scottlamb/moonfire-nvr/issues/156#issuecomment-908568225:

I suppose I could force a new run to start if there's been a time jump (details below), splitting the RTSP session into two runs. The older run would still have the wrong time, but the newer one would be correct. Would this be less surprising?

(Detecting a time jump: one option would be to check periodically / on new recording and see if difference in (wall - monotonic) since previous measurements has exceeded some threshold. Another would be to use timerfd + TFD_TIMER_CANCEL_ON_SET on Linux as systemd does and not support this on other platforms. (I keep macOS working because it's convenient for developers, but Linux is a much better deployment target anyway.))