30

I have a service (written by myself) running on a Debian (Jessie) server, and the service's own logs happen to indicate that it restarted at a particular time. There is no indication of a segfault or other crash, so I am now trying to figure out if the application somehow silently failed and got respawned by systemd, or whether a user purposely restarted the service via systemctl.

The shell history doesn't show such activity, but that is not conclusive because of export HISTCONTROL=ignoreboth and because an SSH session might have just timed out, preventing a previous login's bash history from being written to disk. The server was not rebooted at the time.

But I would expect that systemd itself should keep a log indicating when a service was purposely restarted. To my surprise I was unable to find any documentation (e.g. for journalctl) on how to get such logs.

Some other posts (e.g. Where is / why is there no log for normal user systemd services?) seem to indicate that there should be log messages like this:

Jan 15 19:28:08 qbd-x230-suse.site systemd[1]: Starting chatty.service...
Jan 15 19:28:08 qbd-x230-suse.site systemd[1]: Started chatty.service.

But I don't see such log messages on my system.

Is there a way to find out when systemd services were started, stopped or restarted?

Edit: It seems the typical problem people might run into is that they run journalctl as a non-privileged user. This is not the case for me, I have been operating as root the whole time. In response to a comment, running grep systemd /var/log/syslog gives me only this:

Jun  6 09:28:35 server systemd[22057]: Starting Paths.
Jun  6 09:28:35 server systemd[22057]: Reached target Paths.
Jun  6 09:28:35 server systemd[22057]: Starting Timers.
Jun  6 09:28:35 server systemd[22057]: Reached target Timers.
Jun  6 09:28:35 server systemd[22057]: Starting Sockets.
Jun  6 09:28:35 server systemd[22057]: Reached target Sockets.
Jun  6 09:28:35 server systemd[22057]: Starting Basic System.
Jun  6 09:28:35 server systemd[22057]: Reached target Basic System.
Jun  6 09:28:35 server systemd[22057]: Starting Default.
Jun  6 09:28:35 server systemd[22057]: Reached target Default.
Jun  6 09:28:35 server systemd[22057]: Startup finished in 59ms.
Jun  6 09:37:08 server systemd[1]: Reexecuting.
sourcejedi
  • 50,249
mindriot
  • 531
  • "don't see such log messages" - strange? I have a lot in grep systemd /var/log/syslog – hschou Jun 02 '17 at 10:20
  • On my system I only see very generic messages such as Stopped target Default, Starting Shutdown etc. Nothing indicating anything about individual services. Maybe it's just a configuration problem? Note I am on Debian Jessie in this particular case. – mindriot Jun 02 '17 at 10:57
  • Check your /etc/systemd/journald.conf hasn't overridden MaxLevelStore or MaxLevelSyslog, and look in all the other places you can configure journald as listed in man journald.conf. – meuh Jun 10 '17 at 16:12
  • Thanks for the tip. Unfortunately, all config files located unter /etc/systemd are essentially empty (all options commented out, including the ones you mentioned). – mindriot Jun 12 '17 at 16:47

3 Answers3

24

If you need to script this, you should look into using the systemctl show command. It is more useful for scripts than trying to parse anything from status. For example, to find when the service last started you can use:

$ systemctl show systemd-journald --property=ActiveEnterTimestamp
ActiveEnterTimestamp=Wed 2017-11-08 05:55:17 UTC

If you would like to see all the properties available just omit the flag and it will dump them all out.

$ systemctl show <service_name>

The documentation for these properties can be found here.

jdf
  • 341
  • Interesting, I wasn't aware of the properties. Unfortunately, they are set just the same, regardless of whether the service failed and respawned, or the service was purposely restarted by a user. – mindriot Nov 09 '17 at 21:57
  • 1
    @mindriot regarding your first point though, have you checked StatusErrno and Result? I would wonder if those change if the service failed or was restarted. If you really need to go further try adding an ExecStopPost step where you touch a file and update a timestamp on shutdown. That will help you differentiate between silent restarts and purposeful ones. – jdf Nov 10 '17 at 04:34
  • Thanks, that is also a good point. I won't be able to check/reproduce the situation easily; my original post is almost half a year old already and we've since had a few changes to the system. I'll check if I can try it out somewhere though – if I get a chance. – mindriot Nov 10 '17 at 07:55
  • This helped me. Difference between ActiveExitTimestamp and ActiveEnterTimestamp gives me the time it took to restart the service. – nurettin Feb 06 '20 at 07:22
5

With the default configuration on Debian, an unprivileged user will have access to neither the systemd-journald, nor syslog logs. If logged in as a normal user, you will receive this response from journalctl:

$ journalctl 
No journal files were found.

which is a bit confusing.

If you are logged in as root, journalctl --unit=yourservice should give you the information you are looking for. After a systemctl restart bind9 on my server, I get this after journalctl --unit=bind9:

Jun 03 18:20:24 ns systemd[1]: Stopping BIND Domain Name Server...
Jun 03 18:20:24 ns named[27605]: received control channel command 'stop'
Jun 03 18:20:24 ns systemd[1]: Starting BIND Domain Name Server...
Jun 03 18:20:24 ns systemd[1]: Started BIND Domain Name Server.

If I kill bind9 explicitly with kill -9, journalctl --unit=bind9 gives:

Jun 03 18:46:25 ns systemd[1]: bind9.service: main process exited, code=killed, status=9/KILL
Jun 03 18:46:25 ns rndc[28028]: rndc: connect failed: 127.0.0.1#953: connection refused
Jun 03 18:46:25 ns systemd[1]: bind9.service: control process exited, code=exited status=1
Jun 03 18:46:25 ns systemd[1]: Unit bind9.service entered failed state.
Jun 03 18:46:25 ns systemd[1]: bind9.service holdoff time over, scheduling restart.
Jun 03 18:46:25 ns systemd[1]: Stopping BIND Domain Name Server...
Jun 03 18:46:25 ns systemd[1]: Starting BIND Domain Name Server...
Jun 03 18:46:25 ns systemd[1]: Started BIND Domain Name Server.

The first line indicates that the process died because it was killed.

systemd-journald also forwards all log messages to syslog, so you should also find these messages in /var/log/syslog.

Systemd and systemd-journald have a default compiled in configuration that can be changed in /etc/systemd/system.conf and /etc/systemd/journald.conf.

It may be useful to know that per default, systemd-journald stores the logs under /run, which is tmpfs, and therefore disappears after a reboot. This means that in order to get log messages older than the last boot, you'll have to look at syslog files. In this case journalctl won't give you logs older than the last boot. This can be changed in /etc/systemd/journald.conf by setting Storage=persistent.

The manual pages which documents this are:

man 8 systemd-journald
man 5 journald.conf
man 5 systemd-system.conf
man 5 systemd-user.conf

Also note that in order for a service to be restarted automatically by systemd, this must be configured in it's .service file. From man 5 systemd.service:

   Restart=
       Configures whether the service shall be
       restarted when the service process exits, is
       killed, or a timeout is reached. The service
       process may be the main service process, but it
       may also be one of the processes specified with
       ExecStartPre=, ExecStartPost=, ExecStop=,
       ExecStopPost=, or ExecReload=. When the death
       of the process is a result of systemd operation
       (e.g. service stop or restart), the service
       will not be restarted. Timeouts include missing
       the watchdog "keep-alive ping" deadline and a
       service start, reload, and stop operation
       timeouts.

       Takes one of no, on-success, on-failure,
       on-abnormal, on-watchdog, on-abort, or always.
       If set to no (the default), the service will
       not be restarted.
Tom Bjerck
  • 319
  • Thank you for the extensive and well-written post that probably solves the issue for most users. Unfortunately, in my case I do not see any log lines attributed to systemd when outputting the journal as you described, even though I have worked as root the whole time. /var/log/syslog does not show anything either. This is systemd 215 by the way. – mindriot Jun 06 '17 at 07:43
  • The messages "Stopping BIND Domain Name Server..." and "Starting BIND Domain Name Server..." are output from BIND, systemd just captures this output and sends to journalctl and syslog. What if BIND or some other binary showed no output for the unit? There is no way to see if the service started. Systemd will show output if its stopped but nothing for when it starts. The only way I found to show output is with journalctl -x to show context of actions. But the man page for journalctl states not to put this output in reports. – Dave Mar 11 '22 at 14:46
3

You can see the last time your service started or restarted. Use service chatty status or systemctl status chatty. Here are examples for apache2 or httpd service:

# service apache2 status
● apache2.service - LSB: Apache2 web server
   Loaded: loaded (/etc/init.d/apache2)
  Drop-In: /lib/systemd/system/apache2.service.d
       └─forking.conf
   Active: active (running) since ven. 2017-06-02 15:53:01 CEST; 21min ago
  Process: 14773 ExecStop=/etc/init.d/apache2 stop (code=exited, status=0/SUCCESS)
  Process: 22912 ExecReload=/etc/init.d/apache2 reload (code=exited, status=0/SUCCESS)
  Process: 14880 ExecStart=/etc/init.d/apache2 start (code=exited, status=0/SUCCESS)
   CGroup: /system.slice/apache2.service

the line Active: active (running) since Wen. 2017-06-02 15:53:01 CEST; 21min ago show since how the service is running but I don't know if you can display like a 'list' exactly what you are looking for.

# systemctl status httpd

● httpd.service - The Apache HTTP Server
   Loaded: loaded (/usr/lib/systemd/system/httpd.service; enabled; vendor preset: disabled)
   Active: active (running) since Fri 2019-10-11 00:35:58 EEST; 1 weeks 3 days ago
     Docs: man:httpd(8)
           man:apachectl(8)
  Process: 29728 ExecReload=/usr/sbin/httpd $OPTIONS -k graceful (code=exited, status=0/SUCCESS)
 Main PID: 10722 (httpd)
   Status: "Total requests: 0; Current requests/sec: 0; Current traffic:   0 B/sec"
   Memory: 8.7M
Gryu
  • 837
klaypez
  • 313
  • 1
  • 2
  • 9
  • 1
    service is an old Upstart command that works with systemd for compatbility. The native systemd command is systemctl status apache2. – Mark Stosberg Jun 02 '17 at 16:20
  • Thanks. Unfortunately it only shows when the service was (re-)started, but not why; and it also only shows the current situation, i.e., the last restart. – mindriot Jun 02 '17 at 17:28