[systemd-devel] Logged timestamps for service do not report correct times

[Sam Gilson]

Hey everyone, I've got a quick question about how the timestamps that are gathered by systemctl are emitted by systemd. My organization has a service that runs fairly early in boot (timestamp X ), it has DHCP to an internal network (no Internet)and stays in a polling loop for about 30 minutes. At some point later it finishes polling and obtain a new DHCP lease and at this time it has access to the Internet (X+30min). Once the service finished we queried the following monotonic timestamps: InactiveExitTimestampMonotonic, ActiveEnterTimestampMonotonic, ExecMainStartTimestampMonotonic. The InactiveExit timestamp indicates the unit was started around Timestamp X, which is as expected. However, ActiveEnter and ExecMainStart seems to put it at X + 30min, despite the unit already started ways back at X + x (we know because this service emits its own log when it starts up). We are trying to figure out how each of these timestamps are logged, as when we disable the internal DHCP loop, all these timestamps have very similar values. This indicates to me that our DHCP loop apparently runs between when InactiveExit and ActiveEnter are logged, which accounts for that extra 30 minutes added to the ActiveEnterTimestamp. The problem that we have is that we need the ActiveEnterTimestampMonotonic to be reported accurately when the internal DHCP loop runs.

Any help would be appreciated!

Best Regards,
Sam Gilson

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/systemd-devel/attachments/20190626/0f3626dd/attachment.html>