33

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.
Improve this question
4
  • "don't see such log messages" - strange? I have a lot in grep systemd /var/log/syslog Commented Jun 2, 2017 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. Commented Jun 2, 2017 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. Commented Jun 10, 2017 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). Commented Jun 12, 2017 at 16:47

3 Answers 3

Reset to default
25

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.

Improve this answer
4
  • 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. Commented Nov 9, 2017 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. Commented Nov 10, 2017 at 4: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. Commented Nov 10, 2017 at 7:55
  • This helped me. Difference between ActiveExitTimestamp and ActiveEnterTimestamp gives me the time it took to restart the service. Commented Feb 6, 2020 at 7: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.
Improve this answer
2
  • 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. Commented Jun 6, 2017 at 7: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. Commented Mar 11, 2022 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
Improve this answer
2
  • 2
    service is an old Upstart command that works with systemd for compatbility. The native systemd command is systemctl status apache2. Commented Jun 2, 2017 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. Commented Jun 2, 2017 at 17:28

You must log in to answer this question.

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.