make it easier to track down scopes spawned out of unit process from the "systemctl status" output of the unit (to make logs associated to original unit easier to find)

[rkjnsn]

systemd version the issue has been seen with

247

Used distribution

Debian

Linux kernel version used (uname -a)

5.7.17-1-amd64 #1 SMP Debian 5.7.17-1 (2021-01-08) x86_64 GNU/Linux

CPU architecture issue was seen on

x86_64

Expected behaviour you didn't see

Output from the main process was not visible in the output of systemctl status when using PAMName=, making it difficult to diagnose any issues with the service.

Steps to reproduce the problem

1. Create a simple service containing User= and PAMName=. In the PAM configuration for the provided name, include pam_systemd.
2. Set StandardOutput=journal
3. Start the service.

Even though pam_systemd creates a new session scope for the main process and its children, I would expect messages written to the stdout fd provided by systemd to still be associated with the unit (at the very least for the output of the main process, itself). While these messages do show up in the journal if I look at all messages, they can be a pain to find, especially if one is used to just using systemctl status. If the unit failed, it can be even trickier, as I have not discovered a way to determine what session scope ended up getting briefly used by the failed unit in order to filter the journal.

[poettering]

This is kinda expected: once you open your own PAM session your processes are part of a new scope, and the logs are associated with that...

It might make sense to somehow make this more discoverable, i.e. maybe track to which scopes process are migrated from a service, and then mention this in the "systemctl status" output of the service. i.e. indicate relationships between scopes and the units they have been spawned from.

I am not convinced we should mangle all the logs together in one. if you have a service like gdm then you have a bazillion of scopes spawned from it, and i doubt htat would be useful to see

[poettering]

Took the liberty to convert this into an RFE issue asking for such a link-up.

[rkjnsn]

once you open your own PAM session your processes are part of a new scope

From the perspective of a service author, I think this is the key difference between PAMName= and something like the GDM case you mentioned.

With GDM, the main service still runs in the unit's scope, and is responsible for opening its own scope for each session. In this case, I agree that it doesn't make sense to show the log messages from all spawned scopes along with those of the main service by default. (Though tracking the relationship might allow killing a service along with all its spawned sessions, which could be useful at times.) If GDM wants some messages from its children to show under the unit scope, it can do that my relaying those messages itself.

With the PAMName=, however, the service process isn't opening its own PAM session. Rather, systemd is opening one on its behalf. In this case, there is only one session scope, in which the main process itself (which systemd is still otherwise tracking and managing) is running. In this case, I would expect log messages (at the very least the stdout of the main process) to be associated with the unit, as otherwise there's no way for such a service to log anything to the unit scope at all, which makes it difficult to track down errors or view logs for multiple invocations of the unit.

[rkjnsn]

Probably for similar reasons, it appears LogExtraFields= appears only to apply to the main process when using PAMName=. The fact that it applies at all, though, enables a rather dirty workaround to find the logs: use LogExtraFields to attach a custom field to the messages generated by the main process. Filter the journal by that custom field to find the main process's log messages, and note the _SYSTEMD_INVOCATION_IDs of those messages. Finally, filter the journal by those invocation IDs to find the all of the log messages generated by the unit, including those logged by subprocesses. (If there's a better way to do this currently, please let me know.)