CI flake: sdnotify-conmon test: getting MAINPID=1 instead of READY

[edsantiago]

Symptom: the sdnotify : conmon test in 260-sdnotify.bats is flaking a lot:

# #/vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv
# #|     FAIL: final output from sdnotify
# #| expected: 'READY=1'
# #|   actual: 'MAINPID=98229'
# #\^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

This is a reminder for Ed to take a look at

podman/test/system/260-sdnotify.bats

Line 104 in a226e6e

is "${lines[-1]}" "READY=1" "final output from sdnotify"

• gce_instance:fedora : sys podman fedora-33 root host
  • PR shell completion for the network flag #8699
    • 12-12 14:18
  • PR podman: drop checking valid rootless UID #8693
    • 12-11 10:56
• gce_instance:fedora : sys podman fedora-33 rootless host
  • PR Add volume prune --filter support #8689
    • 12-12 22:08
  • PR Refine public key usage when remote #8676
    • 12-10 18:33
• gce_instance:prior-fedora : sys podman fedora-32 root host
  • PR RHEL gating tests: more journald exceptions #8714
    • 12-14 09:53
• gce_instance:prior-fedora : sys podman fedora-32 root host
  • PR image sign using per user registries.d #7357
    • 12-07 11:02
• gce_instance:prior-ubuntu : sys podman ubuntu-19 root host
  • PR Bump github.com/opencontainers/selinux from 1.6.0 to 1.7.0 #8659
    • 12-09 07:07
  • PR Do not pull if image domain is localhost #8641
    • 12-07 18:09
• gce_instance:ubuntu : sys podman ubuntu-20 root host
  • PR Make podman stats slirp check more robust #8648
    • 12-08 11:06
• gce_instance:fedora : sys podman fedora-33 rootless host
  • PR Support --network=default as if it was private #8551
    • 12-03 06:09
• gce_instance:fedora : sys podman fedora-33 root host
  • PR Add support for volume ls --filter label=key=value #8345
    • 11-14 15:28
  • PR enable ipv6 networks #8143
    • 11-10 06:06

[greg-flexidao]

Didn't create issue yet for that, but it looks like it's belong here...

I just upgraded from 2.2.0 to 2.2.1, I get (timeout) error on all (6) different services running with systemd and sdnotify, that in turn makes all services to restart every 90s.

systemd config:

[Unit]
Description=Podman $SERVICE_NAME.service
Wants=network.target
After=network-online.target

[Service]
Environment=PODMAN_SYSTEMD_UNIT=%N
Environment=XDG_RUNTIME_DIR=/run/user/$USER_ID
User=$USER_SERVICE_NAME
Group=$USER_SERVICE_NAME
Restart=always
ExecStartPre=-/usr/bin/podman rm --ignore -f $SERVICE_NAME
ExecStart=/usr/bin/podman run --log-level=debug --sdnotify=conmon \\
      --name $SERVICE_NAME \\
      $SERVICE_IMAGE_ARGS \\
      $SERVICE_IMAGE:$SERVICE_IMAGE_TAG \\
      $SERVICE_RUN_ARGS
ExecStop=/usr/bin/podman stop -t 10 $SERVICE_NAME
ExecStopPost=-/usr/bin/podman rm --ignore -f $SERVICE_NAME

Type=notify
KillMode=none
NotifyAccess=all

[Install]
WantedBy=multi-user.target

Logs are also not showing anything in particular, the services work normally for ~90s, yet all are stuck in activating (start) stage, before being restarted with following error:

Dec 14 16:27:05 ethnode podman[18730]: level=info ts=2020-12-14T16:27:05.617Z caller=main.go:694 msg="Server is ready to receive web requests."
Dec 14 16:28:35 ethnode systemd[1]: prometheus.service: start operation timed out. Terminating.
Dec 14 16:28:35 ethnode systemd[1]: prometheus.service: Failed with result 'timeout'.
Dec 14 16:28:35 ethnode systemd[1]: Failed to start Podman prometheus.service.
Dec 14 16:28:35 ethnode systemd[1]: prometheus.service: Scheduled restart job, restart counter is at 1.
Dec 14 16:28:35 ethnode systemd[1]: Stopped Podman prometheus.service.

[edsantiago]

@bytniak could you please file this as a new issue? I'm 99.99% sure that what you're seeing is unrelated to the flake reported in this issue. sdnotify hanging is a classic failure mode with many, many different possible causes (eg wrong setting of $NOTIFY_SOCKET, wrong version of conmon). This issue is about a very particular race condition in CI testing. Thank you!

[edsantiago]

Got lucky with #8720: the flake triggered and shows that we are seeing:

# socat log:
# MAINPID=103530
# READY=1
# MAINPID=103530

[github-actions]

A friendly reminder that this issue had no activity for 30 days.

[edsantiago]

This has not recurred since #8720 merged - but that was a sweep-it-under-the-rug workaround. The real problem may or may not persist (I don't know, because there's no way to track it); and if it does, it may or may not be serious (I don't know, because I'm not systemd-savvy enough); and if it's serious, I don't know if it's a podman problem, or conmon, or systemd itself.

I suspect our only rational option here is to close but I'd like someone else to confirm. @giuseppe ? @mheon ?

[mheon]

I think we can close until and unless we see something similar in the wild - chasing sdnotify bugs is difficult and does not seem to have much payoff for us in general.