[systemd-devel] systemd unit transition timestamps

Thu Jun 10 10:49:44 UTC 2021

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 at 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 at fedora ~]# systemctl status dummy.service
? dummy.service - What a dummy
     Loaded: loaded (/etc/systemd/system/dummy.service; static)
     Active: inactive (dead)
[root at fedora ~]# systemctl show dummy.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=inactive
InactiveExitTimestampMonotonic=0
ActiveEnterTimestampMonotonic=0
ActiveExitTimestampMonotonic=0
InactiveEnterTimestampMonotonic=0
[root at fedora ~]# systemctl start dummy.service
[root at fedora ~]# systemctl show dummy.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=active
InactiveExitTimestampMonotonic=175860707
ActiveEnterTimestampMonotonic=175893099
ActiveExitTimestampMonotonic=0
InactiveEnterTimestampMonotonic=0
[root at fedora ~]# systemctl restart dummy.service
[root at fedora ~]# systemctl show dummy.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=active
InactiveExitTimestampMonotonic=185437815
ActiveEnterTimestampMonotonic=185449791
ActiveExitTimestampMonotonic=185427831
InactiveEnterTimestampMonotonic=185427831
[root at fedora ~]# systemctl stop dummy.service
[root at 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 at 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 at 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 at fedora ~]# systemctl show sshd.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=inactive
InactiveExitTimestampMonotonic=0
ActiveEnterTimestampMonotonic=0
ActiveExitTimestampMonotonic=0
InactiveEnterTimestampMonotonic=0
[root at fedora ~]# systemctl start sshd.service
[root at fedora ~]# systemctl show sshd.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=active
InactiveExitTimestampMonotonic=5174487021
ActiveEnterTimestampMonotonic=5174517047
ActiveExitTimestampMonotonic=0
InactiveEnterTimestampMonotonic=0
[root at fedora ~]# systemctl restart sshd.service
[root at fedora ~]# systemctl show sshd.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=active
InactiveExitTimestampMonotonic=5181218843
ActiveEnterTimestampMonotonic=5181264552
ActiveExitTimestampMonotonic=5181198681
InactiveEnterTimestampMonotonic=5181201346
[root at fedora ~]# systemctl stop sshd.service
[root at 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 at 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 at fedora ~]# systemctl show docker.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=inactive
InactiveExitTimestampMonotonic=0
ActiveEnterTimestampMonotonic=0
ActiveExitTimestampMonotonic=0
InactiveEnterTimestampMonotonic=0
[root at fedora ~]# systemctl start docker.service
[root at fedora ~]# systemctl show docker.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=active
InactiveExitTimestampMonotonic=236961155
ActiveEnterTimestampMonotonic=239566035
ActiveExitTimestampMonotonic=0
InactiveEnterTimestampMonotonic=0
[root at fedora ~]# systemctl restart docker.service
[root at fedora ~]# systemctl show docker.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=active
InactiveExitTimestampMonotonic=248678504
ActiveEnterTimestampMonotonic=250223975
ActiveExitTimestampMonotonic=247649250
InactiveEnterTimestampMonotonic=248675514
[root at fedora ~]# systemctl stop docker.service
Warning: Stopping docker.service, but it can still be activated by:
  docker.socket
[root at fedora ~]# systemctl show docker.service |grep -e "[Aa]ctive\(Enter\|Exit\)TimestampMonotonic\|ActiveState="
ActiveState=inactive
InactiveExitTimestampMonotonic=248678504
ActiveEnterTimestampMonotonic=250223975
ActiveExitTimestampMonotonic=269146800
InactiveEnterTimestampMonotonic=270187047
[root at 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 at fujitsu.com
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.