You are not logged in.
Pages: 1
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.
Offline
It's all in your journal.
Offline
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)
Offline
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.
Offline
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 ...
Offline
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=###################
| alias CUTF='LANG=en_XX.UTF-8@POSIX ' |
Offline
@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.
Offline
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)
| alias CUTF='LANG=en_XX.UTF-8@POSIX ' |
Offline
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)
Knowing others is wisdom, knowing yourself is enlightenment. ~Lao Tse
Offline
Tarqi, thank you, you restored my sanity.
Offline
Pages: 1