Changing process PID causing journal logs to show old PID then logs are missing _SYSTEMD_ tags after a restart of systemd-journald #13708
Description
systemd version the issue has been seen with
systemd 243 (243.51-1-arch)
Used distribution
Arch Linux
Expected behaviour you didn't see
Logging for a process using tableflip for graceful upgrades stays visible in journalctl -u with the correct PID and _SYSTEMD_ tags stay present after a graceful upgrade of the process followed by a restart of systemd-journald.
Unexpected behaviour you saw
Logging for a process using tableflip for graceful upgrades has the old PID following a graceful upgrade, logs are not visible in journalctl -u and _SYSTEMD_ tags are missing after a restart of systemd-journald.
Our understanding of the problem is that the default systemd logging setup for StandardOutput and StandardError uses SOCK_STREAM sockets to /run/systemd/journal/stdout
[pid 6307] socket(AF_UNIX, SOCK_STREAM, 0) = 3
[pid 6307] connect(3, {sa_family=AF_UNIX, sun_path="/run/systemd/journal/stdout"}, 30) = 0
[pid 6307] shutdown(3, SHUT_RD) = 0
[pid 6307] getsockopt(3, SOL_SOCKET, SO_SNDBUF, [212992], [4]) = 0
[pid 6307] setsockopt(3, SOL_SOCKET, SO_SNDBUF, [8388608], 4) = 0
[pid 6307] fstat(3, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
[pid 6307] lseek(3, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek)
[pid 6307] write(3, "missing-logs\n\n30\n1\n0\n0\n0\n", 25) = 25
[pid 6307] dup3(3, 1, 0) = 1
[pid 6307] close(3) = 0
[pid 6307] fstat(1, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
[pid 6307] dup2(1, 2) = 2
On the other end systemd-journald gets the peer PID by calling getsockopt to get SO_PEERCRED
accept4(3, NULL, NULL, SOCK_CLOEXEC|SOCK_NONBLOCK) = 101
getsockopt(101, SOL_SOCKET, SO_PEERCRED, {pid=6307, uid=1000, gid=1000}, [12]) = 0
shutdown(101, SHUT_WR) = 0
epoll_ctl(89, EPOLL_CTL_ADD, 101, {EPOLLIN, {u32=2065424624, u64=94194993193200}}) = 0
epoll_wait(89, [{EPOLLIN, {u32=2065424624, u64=94194993193200}}], 100, -1) = 1
read(101, "missing-logs\n\n30\n1\n0\n0\n0\n", 2055) = 25
Because tableflip passes all file descriptors (including STDOUT and STDERR) to the new process during the graceful upgrade, the problem is twofold:
- the socket stays open and
systemd-journaldstill maps incoming logs to the old PID, showing incorrectly in the output - after getting restarted,
systemd-journald, is unable to reconstruct metadata for the process since callinggetsockopton that socket to get the peer PID fromSO_PEERCREDon start will still return the old PID for which all/procreferences are gone.
read(8, "PID:6842 2019/10/02 17:11:56 Hel"..., 2055) = 36
openat(AT_FDCWD, "/proc/6307/comm", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
readlinkat(AT_FDCWD, "/proc/6307/exe", 0x564b7d588b60, 4096) = -1 ENOENT (No such file or directory)
prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
openat(AT_FDCWD, "/proc/6307/cmdline", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/proc/6307/status", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/proc/6307/sessionid", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/proc/6307/loginuid", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/proc/6307/cgroup", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/run/log/journal/e08bf831a8034fbca67c2e3e4043443b/system.journal", O_RDWR|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
The workaround we have found so far is to log to /run/systemd/journal/socket with libraries using SOCK_DGRAM so SCM_CREDENTIALS are passed and the PID stays up-to-date.
But ideally, we'd keep logging to STDOUT which is more portable.
Steps to reproduce the problem
Build this Go program using tableflip:
$ echo 'package main
import (
"flag"
"fmt"
"log"
"os"
"os/signal"
"syscall"
"github.com/cloudflare/tableflip"
)
func main() {
var (
pidFile = flag.String("pid-file", "", "`Path` to pid file")
)
flag.Parse()
log.SetPrefix(fmt.Sprintf("PID:%d ", os.Getpid()))
upg, err := tableflip.New(tableflip.Options{
PIDFile: *pidFile,
})
if err != nil {
panic(err)
}
defer upg.Stop()
// Do an upgrade on SIGHUP
go func() {
sig := make(chan os.Signal, 1)
signal.Notify(sig, syscall.SIGHUP)
for range sig {
err := upg.Upgrade()
if err != nil {
log.Println("Upgrade failed:", err)
}
}
}()
log.Printf("Hello.")
if err := upg.Ready(); err != nil {
panic(err)
}
<-upg.Exit()
}' > /tmp/missing-logs.go
$ cd /tmp
$ go build missing-logs.go
And create a systemd unit
$ echo '[Unit]
Description=missing-logs
[Service]
Type=simple
ExecStart=/tmp/missing-logs -pid-file /tmp/missing-logs.pid
ExecReload=/bin/kill -HUP $MAINPID
PIDFile=/tmp/missing-logs.pid' > ~/.config/systemd/user/missing-logs.service
$ systemctl --user daemon-reload
Run the unit
$ systemctl --user start missing-logs
See it is logging fine with the correct PID (5408)
$ systemctl --user status missing-logs
● missing-logs.service - missing-logs
Loaded: loaded (/home/tlefebvre/.config/systemd/user/missing-logs.service; static; vendor preset: enabled)
Active: active (running) since Wed 2019-10-02 16:36:15 PDT; 1s ago
Main PID: 5408 (missing-logs)
CGroup: /user.slice/user-1000.slice/user@1000.service/missing-logs.service
└─5408 /tmp/missing-logs -pid-file /tmp/missing-logs.pid
Oct 02 16:36:15 arch-x1 systemd[770]: Started missing-logs.
Oct 02 16:36:15 arch-x1 missing-logs[5408]: PID:5408 2019/10/02 16:36:15 Hello.
Trigger a graceful reload
$ systemctl --user reload missing-logs
See it is still logging fine albeit the PID reported by systemd-journald being wrong (5408 instead of 5436, though correctly reported by Main PID)
$ systemctl --user status missing-logs
● missing-logs.service - missing-logs
Loaded: loaded (/home/tlefebvre/.config/systemd/user/missing-logs.service; static; vendor preset: enabled)
Active: active (running) since Wed 2019-10-02 16:36:15 PDT; 58s ago
Process: 5435 ExecReload=/bin/kill -HUP $MAINPID (code=exited, status=0/SUCCESS)
Main PID: 5436 (missing-logs)
CGroup: /user.slice/user-1000.slice/user@1000.service/missing-logs.service
└─5436 /tmp/missing-logs -pid-file /tmp/missing-logs.pid
Oct 02 16:36:15 arch-x1 systemd[770]: Started missing-logs.
Oct 02 16:36:15 arch-x1 missing-logs[5408]: PID:5408 2019/10/02 16:36:15 Hello.
Oct 02 16:37:13 arch-x1 systemd[770]: Reloading missing-logs.
Oct 02 16:37:13 arch-x1 systemd[770]: Reloaded missing-logs.
Oct 02 16:37:13 arch-x1 missing-logs[5408]: PID:5436 2019/10/02 16:37:13 Hello.
Now, restart systemd-journald and trigger another reload
$ sudo systemctl restart systemd-journald
$ systemctl --user reload missing-logs
Notice we are not getting logs anymore for the unit, despite the new PID (5492) being correctly tracked in Main PID
$ systemctl --user status missing-logs
● missing-logs.service - missing-logs
Loaded: loaded (/home/tlefebvre/.config/systemd/user/missing-logs.service; static; vendor preset: enabled)
Active: active (running) since Wed 2019-10-02 16:36:15 PDT; 2min 39s ago
Process: 5491 ExecReload=/bin/kill -HUP $MAINPID (code=exited, status=0/SUCCESS)
Main PID: 5492 (missing-logs)
CGroup: /user.slice/user-1000.slice/user@1000.service/missing-logs.service
└─5492 /tmp/missing-logs -pid-file /tmp/missing-logs.pid
Oct 02 16:36:15 arch-x1 systemd[770]: Started missing-logs.
Oct 02 16:36:15 arch-x1 missing-logs[5408]: PID:5408 2019/10/02 16:36:15 Hello.
Oct 02 16:37:13 arch-x1 systemd[770]: Reloading missing-logs.
Oct 02 16:37:13 arch-x1 systemd[770]: Reloaded missing-logs.
Oct 02 16:37:13 arch-x1 missing-logs[5408]: PID:5436 2019/10/02 16:37:13 Hello.
Oct 02 16:38:49 arch-x1 systemd[770]: Reloading missing-logs.
Oct 02 16:38:49 arch-x1 systemd[770]: Reloaded missing-logs.
Some logs are still available looking at the missing-logs tag, but are depleted of _SYSTEMD_ tags such as _SYSTEMD_UNIT which causes them to stop showing up in journal for the unit.
$ journalctl --user -t missing-logs -o verbose
Wed 2019-10-02 16:38:49.947469 PDT [s=72e1c146a73243cb85f8350936b452e9;i=f1d0b;b=f3eab880cbef4f459070c9501988e035;m=854b7586;t=593f5f88f094d;x=b7434a687f6d0ee8]
_TRANSPORT=stdout
PRIORITY=6
_UID=1000
_GID=1000
_MACHINE_ID=e08bf831a8034fbca67c2e3e4043443b
_HOSTNAME=arch-x1
_BOOT_ID=f3eab880cbef4f459070c9501988e035
_STREAM_ID=632c7cb249bb4e0bb5c8abef8676cb7b
SYSLOG_IDENTIFIER=missing-logs
_PID=5408
MESSAGE=PID:5492 2019/10/02 16:38:49 Hello.
Happy to give more information if needed, thanks for your help!