Log systemd service starts/stops

jernst · 2014-09-04 18:18:07

If I say

systemctl restart foo.service

does this get logged somewhere?

I noticed that if bar.service Requires foo.service, restarting foo.service will also restart bar.service, and I'm sure there are other ramifications that I simply haven't noticed :-) So how would I get a log that sort of looks like:

Stopped bar.service
Stopped foo.service
Started foo.service
Started bar.service

I can't find anything ... but somehow I think this simply must exist.

tomk · 2014-09-04 18:21:29

It's all in your journal.

jernst · 2014-09-04 18:30:15

I was hoping it is, but where? I can't find it. (perhaps too many trees in the forest. which tree am I looking for?)

Addition: To figure this out, I created a test service:

[Unit]
Description=Bar test service

[Service]
ExecStart=/bin/echo Starting bar.service
ExecStop=/bin/echo Stopping bar.service
Type=oneshot
RemainAfterExit=yes

In one shell, I follow the journal:

journalctl -f -o verbose

and in another shell, I do things such as:

systemctl start bar

but the only thing I'm getting from journalctl is the output of my "echo". Do I interpret this as "systemd does not log stuff about itself"? Or is there some kind of setting somewhere that tells systemd to log service events? I can't find one in the man pages either.

Addition 2: For now, I've put extra logging statements into ExecStartPre and ExecStopPost, which let me debug what I need to debug, but I'm still hoping there is some instrumentation so those aren't needed.

Last edited by jernst (2014-09-05 00:04:01)

tomk · 2014-09-05 07:08:22

I directed you to the journal section of the wiki's systemd page because it provides information about filtering the output. It also refers to the relevant man pages, and other resources. Here's a very simple (and real) example from my laptop:

$ journalctl -u rpcbind.service
.....
Aug 09 14:01:43 tk-r4k systemd[1]: Starting RPC bind service...
Aug 09 14:01:44 tk-r4k systemd[1]: Started RPC bind service.
Aug 10 10:52:08 tk-r4k systemd[1]: Stopped RPC bind service.
.....

Why are you making up dummy services anyway? IMO there are no circumstances when a dummy is better than the real thing, and you have a selection of actual services on your system to choose from.

jernst · 2014-09-05 23:13:03

I'm building my own service, the details of which I don't really want to bother anybody with right now, and I'm trying to understand what is going wrong. The dummy service was to strip away everything that could get in the way of me understanding what I'm doing.

In the example you provided, it seems that it is rpcbind.service that reports those events to the journal. I understand how to access such events.

I was asking about something else: how could I convince systemd (not, in your example, rpcbind.service) to report to the journal what it is doing, and why. For example, if I have two services foo.service and bar.service, and bar.service gets stopped because foo.service gets stopped (due to a dependency), the daemon behind neither foo.service or bar.service really knows that, so it's hard for them to report the reasons for those "cascading" stops. However, systemd knows -- it evaluates the .service files after all -- and I had been hoping that I could convince it to tell us about it in the journal, perhaps with an additional verbose setting. But apparently not ...

progandy · 2014-09-05 23:34:47

You'll have to run journalctl as root. It should be logged as UNIT=bar.service, SYSLOG_IDENTIFIER=systemd, one example from me:

sudo systemctl start chrony.service
sudo systemctl stop chrony.service
sudo journalctl -o verbose --since today UNIT=chrony.service SYSLOG_IDENTIFIER=systemd

Sa 2014-09-06 01:19:32.432387 CEST [s=###########################;i=#####;b=###########################;m=#######;t=##########;x=#############]
    PRIORITY=6
    _UID=0
    _GID=0
    _MACHINE_ID=###########################
    _HOSTNAME=pamobile
    SYSLOG_FACILITY=3
    SYSLOG_IDENTIFIER=systemd
    _TRANSPORT=journal
    _PID=1
    _COMM=systemd
    _EXE=/usr/lib/systemd/systemd
    _CMDLINE=/sbin/init
    _CAP_EFFECTIVE=3fffffffff
    _SYSTEMD_CGROUP=/
    CODE_FILE=src/core/job.c
    CODE_LINE=721
    CODE_FUNCTION=job_log_status_message
    MESSAGE_ID=#######################
    RESULT=done
    UNIT=chrony.service
    MESSAGE=Started Chrony Network Time Daemon.
    _BOOT_ID=############################
    _SOURCE_REALTIME_TIMESTAMP=###########

...

Sa 2014-09-06 01:19:40.538847 CEST [s=###############################;i=#####;b=###############################;m=########;t=############;x=#########################]
    PRIORITY=6
    _UID=0
    _GID=0
    _MACHINE_ID=###############################
    _HOSTNAME=pamobile
    SYSLOG_FACILITY=3
    SYSLOG_IDENTIFIER=systemd
    _TRANSPORT=journal
    _PID=1
    _COMM=systemd
    _EXE=/usr/lib/systemd/systemd
    _CMDLINE=/sbin/init
    _CAP_EFFECTIVE=3fffffffff
    _SYSTEMD_CGROUP=/
    CODE_FILE=src/core/job.c
    CODE_FUNCTION=job_log_status_message
    RESULT=done
    UNIT=chrony.service
    CODE_LINE=729
    MESSAGE_ID=###############################
    MESSAGE=Stopped Chrony Network Time Daemon.
    _BOOT_ID=###############################
    _SOURCE_REALTIME_TIMESTAMP=###################

jernst · 2014-09-06 20:03:06

@progandy: Now I'm completely baffled. I tried the exact same thing as you did, and I can confirm I see similar messages in the journal (minus the fact that I don't seem to have chrony configured correctly, so it doesn't actually start, but journal messages are there with the same UNIT and SYSLOG_IDENTIFIER; I run cronie instead).

Now I remove the "chrony" filter, like this:

sudo journalctl -o verbose -f SYSLOG_IDENTIFIER=systemd

and confirm that chrony events continue to show up when I say

systemctl start chrony

But then I try the same thing with other services, like

systemctl start cronie
systemctl start mysqld
systemctl start httpd

and I get nothing. (Yes, I stopped them first.)

Finally, I removed all filters

sudo journalctl -o verbose -f

and there still is nothing.

progandy · 2014-09-06 21:26:26

I really don't know what is broken on your side. It works for me with all services I try (httpd, mysqld/maridb, cups, bluetooth, cups.socket)

progandy@pamobile ~ % sudo systemctl status cronie
● cronie.service - Periodic Command Scheduler
   Loaded: loaded (/usr/lib/systemd/system/cronie.service; enabled)
   Active: active (running) since Sa 2014-09-06 23:15:58 CEST; 26s ago
 Main PID: 29100 (crond)
   CGroup: /system.slice/cronie.service
           └─29100 /usr/bin/crond -n
progandy@pamobile ~ % sudo systemctl start cronie  
progandy@pamobile ~ % sudo systemctl restart cronie
progandy@pamobile ~ % sudo systemctl stop cronie
progandy@pamobile ~ % sudo systemctl stop cronie
progandy@pamobile ~ % sudo systemctl start cronie

progandy@pamobile ~ % sudo journalctl -f SYSLOG_IDENTIFIER=systemd
Sep 06 23:16:36 pamobile systemd[1]: Started Periodic Command Scheduler.        # > start when already started
Sep 06 23:16:54 pamobile systemd[1]: Stopping Periodic Command Scheduler...     # > begin restart ...
Sep 06 23:16:54 pamobile systemd[1]: Starting Periodic Command Scheduler...     #   ...
Sep 06 23:16:54 pamobile systemd[1]: Started Periodic Command Scheduler.        #   ... end restart
Sep 06 23:17:00 pamobile systemd[1]: Stopping Periodic Command Scheduler...     # > begin stop ...
Sep 06 23:17:00 pamobile systemd[1]: Stopped Periodic Command Scheduler.        #   ... end stop
Sep 06 23:17:01 pamobile systemd[1]: Stopped Periodic Command Scheduler.        # > stop when already stopped
Sep 06 23:17:04 pamobile systemd[1]: Starting Periodic Command Scheduler...     # > begin start ...
Sep 06 23:17:04 pamobile systemd[1]: Started Periodic Command Scheduler.        #   ... end start

Last edited by progandy (2014-09-06 21:28:50)

Tarqi · 2014-09-06 22:09:40

I can confirm that behavior, for me it started some weeks/months ago, systemd is just quiet about its own activities. Interestingly this is working inside a systemd-nspwan machine (no shared journal), but not outside of the (same) host. Configuration differs just marginal: The nspawn limits the journal runtime/disk-usage, the host journal is volatile. However, I did not investigate this further.

Edit: After rereading my post, i stumbled across the word quiet and rebooted with this one removed from the kernel commandline. And... it works again. So systemd seems to honor this boot-option in a wrong(?) way?!

Edit: Filed a bug: https://bugs.archlinux.org/task/41942

Edit: Behavior is intentional and has been changed some time ago. Use systemd.log_level=info on the kernel commandline to restore the formerly used log-level.

Last edited by Tarqi (2014-09-12 23:41:44)

jernst · 2014-09-23 03:47:41

Tarqi, thank you, you restored my sanity.

Arch Linux

#1 2014-09-04 18:18:07

Log systemd service starts/stops

#2 2014-09-04 18:21:29

Re: Log systemd service starts/stops

#3 2014-09-04 18:30:15

Re: Log systemd service starts/stops

#4 2014-09-05 07:08:22

Re: Log systemd service starts/stops

#5 2014-09-05 23:13:03

Re: Log systemd service starts/stops

#6 2014-09-05 23:34:47

Re: Log systemd service starts/stops

#7 2014-09-06 20:03:06

Re: Log systemd service starts/stops

#8 2014-09-06 21:26:26

Re: Log systemd service starts/stops

#9 2014-09-06 22:09:40

Re: Log systemd service starts/stops

#10 2014-09-23 03:47:41

Re: Log systemd service starts/stops

Board footer