Discussion:
Filtering logs of a single execution of a (transient) service
Add Reply
Filipe Brandenburger
2018-03-23 19:52:06 UTC
Reply
Permalink
Raw Message
Hi!

So I'm testing a program repeatedly and using `systemd-run` to start a
service with it, passing it a specific unit name.

When the test finishes and I bring down the service, I want to be able to
collect the journald logs for that execution of the test alone.

Right now what I'm doing is naming the service differently every time,
including a random number, so I can collect the logs for that service alone
at the end. Such as:

# myservice_name=myservice-${RANDOM}.service
# systemd-run --unit="${myservice_name}" --remain-after-exit mybin
--myarg1 --myarg2 ...

And then collecting the logs using:

# journalctl -u "${myservice_name}"

One disadvantage of this approach is that the units pile up as I keep
running tests...

# systemctl status myservice-*.service

And that it's hard to find which one is the latest one, from an unrelated
session (this works only while active):

# systemctl list-units --state running myservice-*.service

I would like to run these tests all under a single unit name,
myservice.service. I'm fine with not having more than one of them at the
same time (in fact, that's a feature.)

But I wonder how I can get the logs for a single execution...

The best I could come up with was using a cursor to get the logs for the
last execution:

# journalctl -u myservice MESSAGE_ID=39f53479d3a045ac8e11786248231fbf
--show-cursor
-- Logs begin at Thu 2018-03-22 22:57:32 UTC, end at Fri 2018-03-23
19:17:01 UTC. --
Mar 23 16:40:00 mymachine systemd[1]: Started mybin --myarg1 --myarg2
Mar 23 16:45:00 mymachine systemd[1]: Started mybin --myarg1 --myarg2b
Mar 23 16:50:00 mymachine systemd[1]: Started mybin --myarg1 --myarg2
--myarg3
-- cursor:
s=abcde12345...;i=123f45;b=12345abcd...;m=f123f123;t=123456...;x=...

And then use the cursor to query journald and get the logs from the last
execution:

# journalctl -u myservice --after-cursor 's=abcde12345...;i=123f45;...'

That works to query the last execution of the service, but not a random
one...

I guess what I'm looking for is a way to get systemd to inject a journal
field to every message logged by my unit. Something like an environment
variable perhaps? Or some other field I can pass to systemd-run using -p.
Or something that systemd itself generates, that's unique for each
execution of the service and that I can query somehow (perhaps `systemd
show` while the service is up.) Is there any such thing?

Any other suggestions of how I should accomplish something like this?

Thanks!
Filipe
Lennart Poettering
2018-03-23 20:17:52 UTC
Reply
Permalink
Raw Message
Post by Filipe Brandenburger
Hi!
So I'm testing a program repeatedly and using `systemd-run` to start a
service with it, passing it a specific unit name.
When the test finishes and I bring down the service, I want to be able to
collect the journald logs for that execution of the test alone.
Right now what I'm doing is naming the service differently every time,
including a random number, so I can collect the logs for that service alone
What you are looking for is the "invocation ID". It's a 128bit random
UUID unique for each invocation cycle of a service (i.e it's generated
fresh whenever a unit enters the STARTING phase). It's included in the
service's env block (as well as the keyring and attached to its
cgroup). The journal will also attach it to every log message of the
service.

systemd-run currently doesn't show you the invocation ID however, but
I figure this is something we should really fix.
Post by Filipe Brandenburger
I guess what I'm looking for is a way to get systemd to inject a journal
field to every message logged by my unit. Something like an environment
variable perhaps? Or some other field I can pass to systemd-run using -p.
Or something that systemd itself generates, that's unique for each
execution of the service and that I can query somehow (perhaps `systemd
show` while the service is up.) Is there any such thing?
You can also use "-p LogExtraFields=QUUX=miep" to attach arbitrary
additional journal fields to all log messages of the service you run
that way.

Lennart
--
Lennart Poettering, Red Hat
Filipe Brandenburger
2018-03-23 20:31:00 UTC
Reply
Permalink
Raw Message
Thanks for your reply!

On Fri, Mar 23, 2018 at 1:17 PM, Lennart Poettering
Post by Lennart Poettering
What you are looking for is the "invocation ID". It's a 128bit random
UUID unique for each invocation cycle of a service (i.e it's generated
fresh whenever a unit enters the STARTING phase). It's included in the
service's env block (as well as the keyring and attached to its
cgroup). The journal will also attach it to every log message of the
service.
Very nice. Unfortunately only added on v232 and I still need to
support Ubuntu 16.04 which ships v229...
Post by Lennart Poettering
systemd-run currently doesn't show you the invocation ID however, but
I figure this is something we should really fix.
I can look into pushing a PR for that...
Post by Lennart Poettering
You can also use "-p LogExtraFields=QUUX=miep" to attach arbitrary
additional journal fields to all log messages of the service you run
that way.
Very nice too... But again introduced in v236.

So looks like back on this old version there's not much I can do... Oh well.

Thanks!
Filipe
Lennart Poettering
2018-04-06 10:27:31 UTC
Reply
Permalink
Raw Message
Post by Filipe Brandenburger
Post by Lennart Poettering
systemd-run currently doesn't show you the invocation ID however, but
I figure this is something we should really fix.
I can look into pushing a PR for that...
That'd be excellent. It should be possible to simply query the field
off the unit bus object right after the startup job we enqueued
finished. This of course means this can only work if --non-block is
not used (because in that case we just enqueue the job to start the
unit, but don't wait for it to actually start, and thus don't wait for
the invocation ID to be determined).

It's also a tiny bit racy: in theory somebody could run a unit by the
same name right after we started ours, and then we possibly might
query the invocation of that second run. Fixing this racy is very hard
however (it would probably entail extending the JobDone bus message to
include the invocation ID, but dbus isn't really friendly to such
extensions). An alternative approach to fixing this race might be
instead strictly enforce that transient units are never started more
than once, and then making use of the "AddRef" concept which allows
clients to pin a unit into memory while the client runs. Both together
mean that the unit could not be started a second time, and that it
can't be GC'ed and replaced by a different but identically named unit
either.

Lennart
--
Lennart Poettering, Red Hat
Loading...