systemd unit transition timestamps

["paul.nieleck@xxxxxxxxxxx" <paul.nieleck@xxxxxxxxxxx>]

Hi Folks!

I'm sorry for bothering you, but I have a question regarding the systemd
transition timestamps ActiveEnterTimestamp, ActiveExitTimestamp,
InactiveEnterTimestamp and InactiveExitTimestamp that I couldn't figure out
myself. As far as I understand from the man page org.freedesktop.systemd1,
these "fields are 0 in case such a transition has not yet been recorded on this
boot". Therefore, I wanted to use these values to see when certain services
and targets were started or stopped.

As it turns out, this applies only for some services and I don't understand why.
Here's an example:


Oneshot dummy.service
---------------------
1. service hasn't been started: all values 0
2. service starts: ActiveEnterTimestamp set
3. service restart: all Timestamps updated
3. service stops: all values 0

[root@fedora ~]# systemctl cat dummy.service
# /etc/systemd/system/dummy.service
[Unit]
Description=What a dummy
[Service]
Type=oneshot
ExecStart=/bin/bash -c "date"
RemainAfterExit=yes
[root@fedora ~]# systemctl status dummy.service
? dummy.service - What a dummy
     Loaded: loaded (/etc/systemd/system/dummy.service; static)
     Active: inactive (dead)
[root@fedora ~]# systemctl show dummy.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=inactive
InactiveExitTimestampMonotonic=0
ActiveEnterTimestampMonotonic=0
ActiveExitTimestampMonotonic=0
InactiveEnterTimestampMonotonic=0
[root@fedora ~]# systemctl start dummy.service
[root@fedora ~]# systemctl show dummy.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=active
InactiveExitTimestampMonotonic=175860707
ActiveEnterTimestampMonotonic=175893099
ActiveExitTimestampMonotonic=0
InactiveEnterTimestampMonotonic=0
[root@fedora ~]# systemctl restart dummy.service
[root@fedora ~]# systemctl show dummy.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=active
InactiveExitTimestampMonotonic=185437815
ActiveEnterTimestampMonotonic=185449791
ActiveExitTimestampMonotonic=185427831
InactiveEnterTimestampMonotonic=185427831
[root@fedora ~]# systemctl stop dummy.service
[root@fedora ~]# systemctl show dummy.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=inactive
InactiveExitTimestampMonotonic=0
ActiveEnterTimestampMonotonic=0
ActiveExitTimestampMonotonic=0
InactiveEnterTimestampMonotonic=0



sshd.service
------------
It's another type but has similar behavior

[root@fedora ~]# systemctl cat sshd.service
# /usr/lib/systemd/system/sshd.service
[Unit]
Description=OpenSSH server daemon
Documentation=man:sshd(8) man:sshd_config(5)
After=network.target sshd-keygen.target
Wants=sshd-keygen.target

[Service]
Type=notify
EnvironmentFile=-/etc/sysconfig/sshd
ExecStart=/usr/sbin/sshd -D $OPTIONS
ExecReload=/bin/kill -HUP $MAINPID
KillMode=process
Restart=on-failure
RestartSec=42s

[Install]
WantedBy=multi-user.target
[root@fedora ~]# systemctl status sshd.service
? sshd.service - OpenSSH server daemon
     Loaded: loaded (/usr/lib/systemd/system/sshd.service; disabled; vendor preset: disabled)
     Active: inactive (dead)
       Docs: man:sshd(8)
             man:sshd_config(5)
[root@fedora ~]# systemctl show sshd.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=inactive
InactiveExitTimestampMonotonic=0
ActiveEnterTimestampMonotonic=0
ActiveExitTimestampMonotonic=0
InactiveEnterTimestampMonotonic=0
[root@fedora ~]# systemctl start sshd.service
[root@fedora ~]# systemctl show sshd.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=active
InactiveExitTimestampMonotonic=5174487021
ActiveEnterTimestampMonotonic=5174517047
ActiveExitTimestampMonotonic=0
InactiveEnterTimestampMonotonic=0
[root@fedora ~]# systemctl restart sshd.service
[root@fedora ~]# systemctl show sshd.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=active
InactiveExitTimestampMonotonic=5181218843
ActiveEnterTimestampMonotonic=5181264552
ActiveExitTimestampMonotonic=5181198681
InactiveEnterTimestampMonotonic=5181201346
[root@fedora ~]# systemctl stop sshd.service
[root@fedora ~]# systemctl show sshd.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=inactive
InactiveExitTimestampMonotonic=0
ActiveEnterTimestampMonotonic=0
ActiveExitTimestampMonotonic=0
InactiveEnterTimestampMonotonic=0



docker.service
--------------
For the docker.service, however, the timestamp values remain also after the
stop.

[root@fedora ~]# systemctl status docker.service
? docker.service - Docker Application Container Engine
     Loaded: loaded (/usr/lib/systemd/system/docker.service; disabled; vendor preset: disabled)
     Active: inactive (dead)
TriggeredBy: ? docker.socket
       Docs: https://docs.docker.com
[root@fedora ~]# systemctl show docker.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=inactive
InactiveExitTimestampMonotonic=0
ActiveEnterTimestampMonotonic=0
ActiveExitTimestampMonotonic=0
InactiveEnterTimestampMonotonic=0
[root@fedora ~]# systemctl start docker.service
[root@fedora ~]# systemctl show docker.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=active
InactiveExitTimestampMonotonic=236961155
ActiveEnterTimestampMonotonic=239566035
ActiveExitTimestampMonotonic=0
InactiveEnterTimestampMonotonic=0
[root@fedora ~]# systemctl restart docker.service
[root@fedora ~]# systemctl show docker.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=active
InactiveExitTimestampMonotonic=248678504
ActiveEnterTimestampMonotonic=250223975
ActiveExitTimestampMonotonic=247649250
InactiveEnterTimestampMonotonic=248675514
[root@fedora ~]# systemctl stop docker.service
Warning: Stopping docker.service, but it can still be activated by:
  docker.socket
[root@fedora ~]# systemctl show docker.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=inactive
InactiveExitTimestampMonotonic=248678504
ActiveEnterTimestampMonotonic=250223975
ActiveExitTimestampMonotonic=269146800
InactiveEnterTimestampMonotonic=270187047
[root@fedora ~]#



When I did my tests, I saw that for my dummy.service respective events were
emitted on the dbus after systemctl stop that contained the correct timestamps.
So they seem to be cleared afterwards.

I'm not really familiar with the systemd code. Looking into it, I found that
the timestamps are set in unit_notify(). But this obviously works, considering
the events on the dbus.

I found one more difference when I monitored the dbus: For the dummy.service
there's an UnitRemoved() event, but not for the docker.service. If I read that
correct, it means that the unit object is removed from the d-bus and therefore
the timestamps are lost. Am I right?

So, anyways, I don't see the difference between the units that causes the
different behavior. Furthermore, from my point of view (as a user) it
contradicts the description of the Timestamp values in the man page somehow,
where it says "recorded on this boot".

Is this behaviour intended? Or is there another way to read the times a unit
was stopped, without setting up my own event listener or searching the
(potentially rotated/vacuumed) journal?

I tested on the latest Fedora 34 Workstation release with
  systemd 248 (v248-2.fc34)
and on openSUSE as well as on SLES12 (this is actually my target system) with
older versions.

Cheers,
Paul

---
With best regards
Paul Nieleck
Associate Software Developer
FJ CE EPS BS2000 DS OS4


FUJITSU
Mies-van-der-Rohe-Straße 8, 80807 München, Germany
Tel.: +49 (89) 62060 2933
E-mail: paul.nieleck@xxxxxxxxxxx
Web: ts.fujitsu.com
Company details: Fujitsu Technology Solutions GmbH / ts.fujitsu.com/imprint
This communication contains information that is confidential, proprietary in nature and/or privileged.  It is for the exclusive use of the intended recipient(s). If you are not the intended recipient(s) or the person responsible for delivering it to the intended recipient(s), please note that any form of dissemination, distribution or copying of this communication is strictly prohibited and may be unlawful. If you have received this communication in error, please immediately notify the sender and delete the original communication. Thank you for your cooperation.
Please be advised that neither Fujitsu, its affiliates, its employees or agents accept liability for any errors, omissions or damages caused by delays of receipt or by any virus infection in this message or its attachments, or which may otherwise arise as a result of this e-mail transmission.


_______________________________________________
systemd-devel mailing list
systemd-devel@xxxxxxxxxxxxxxxxxxxxx
https://lists.freedesktop.org/mailman/listinfo/systemd-devel