Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Systemd notification does not accept events after READY is received #133

Open
mvorisek opened this issue Dec 7, 2021 · 11 comments
Open

Systemd notification does not accept events after READY is received #133

mvorisek opened this issue Dec 7, 2021 · 11 comments

Comments

@mvorisek
Copy link

mvorisek commented Dec 7, 2021

Some services like mysql-server emit systemd notifications like READY status. Does docker-systemctl-replacement accept any of these (at least accept and discard)?

Currently, I see the following errors in mysql-server log file:

2021-12-07T15:16:10.286252Z 0 [Warning] [MY-011808] [Server] Failed to write 'READY=1 STATUS=Server is operational MAIN_PID=7904 ' to systemd notification. Error: 'Connection refused'
@gdraheim
Copy link
Owner

gdraheim commented Dec 7, 2021

For a "Type=notify" service the notify-socket is actually created. It waits for the READY=1 on each ExecStart before continuing. After it got that signal it will close the socket however.

It should be visible in the debug.log.

May be mysql sends multiple of the READY=1 signals, so we need to assume that it is fine. The mysql examples did not have a problem so far.

https://github.com/gdraheim/docker-systemctl-images/blob/master/opensuse-lamp-stack.dockerfile

@mvorisek
Copy link
Author

mvorisek commented Dec 8, 2021 •
edited
Loading

Here are the logs:

$ cat /var/log/systemctl.debug.log
2021-12-08 06:53:35,298 INFO EXEC BEGIN /usr/bin/systemctl-replacement.py daemon-reload --system
2021-12-08 06:53:35,299 DEBUG ======= systemctl.py daemon-reload
2021-12-08 06:53:35,301 DEBUG found 186 sysd files
2021-12-08 06:53:35,301 DEBUG found 2 sysv files
2021-12-08 06:53:35,307 INFO    dbus-org.freedesktop.timesync1.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 06:53:35,307 DEBUG   dbus-org.freedesktop.timesync1.service:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 06:53:35,313 ERROR   getty-static.service: Service Executable path is not absolute.
2021-12-08 06:53:35,313 DEBUG   getty-static.service:  (W21) ignoring systemctl --no-block start [email protected] [email protected] [email protected] [email protected] [email protected]
2021-12-08 06:53:35,315 ERROR   initrd-cleanup.service: Service Executable path is not absolute.
2021-12-08 06:53:35,315 DEBUG   initrd-cleanup.service:  (W21) ignoring systemctl --no-block isolate initrd-switch-root.target
2021-12-08 06:53:35,316 WARNING initrd-parse-etc.service: Service Executable path is not absolute.
2021-12-08 06:53:35,316 DEBUG   initrd-parse-etc.service:  (W21) ignoring systemctl --no-block start initrd-fs.target
2021-12-08 06:53:35,316 ERROR   initrd-parse-etc.service: Service Executable path is not absolute.
2021-12-08 06:53:35,316 DEBUG   initrd-parse-etc.service:  (W21) ignoring systemctl --no-block start initrd-cleanup.service
2021-12-08 06:53:35,317 ERROR   initrd-switch-root.service: Service Executable path is not absolute.
2021-12-08 06:53:35,317 DEBUG   initrd-switch-root.service:  (W21) ignoring systemctl --no-block switch-root /sysroot
2021-12-08 06:53:35,318 WARNING initrd-udevadm-cleanup-db.service: Service Executable path is not absolute.
2021-12-08 06:53:35,318 DEBUG   initrd-udevadm-cleanup-db.service:  (W21) ignoring udevadm info --cleanup-db
2021-12-08 06:53:35,323 WARNING rc-local.service: Service type=forking does not provide a Service PIDFile.
2021-12-08 06:53:35,323 DEBUG   rc-local.service:  (W12) this will not allow sending signals to the MainPID (expect restart problems)
2021-12-08 06:53:35,333 ERROR   systemd-ask-password-console.service: Service Executable path is not absolute.
2021-12-08 06:53:35,333 DEBUG   systemd-ask-password-console.service:  (W21) ignoring systemd-tty-ask-password-agent --watch --console
2021-12-08 06:53:35,333 ERROR   systemd-ask-password-wall.service: Service Executable path is not absolute.
2021-12-08 06:53:35,334 DEBUG   systemd-ask-password-wall.service:  (W21) ignoring systemd-tty-ask-password-agent --wall
2021-12-08 06:53:35,335 ERROR   systemd-boot-system-token.service: Service Executable path is not absolute.
2021-12-08 06:53:35,335 DEBUG   systemd-boot-system-token.service:  (W21) ignoring bootctl random-seed --graceful
2021-12-08 06:53:35,336 ERROR   systemd-exit.service: found a .service file without a [Service] section
2021-12-08 06:53:35,336 DEBUG   systemd-exit.service:  (E00) which does render the unit definition pretty useless
2021-12-08 06:53:35,337 ERROR   systemd-halt.service: Service Executable path is not absolute.
2021-12-08 06:53:35,337 DEBUG   systemd-halt.service:  (W21) ignoring systemctl --force halt
2021-12-08 06:53:35,339 ERROR   systemd-journal-flush.service: Service Executable path is not absolute.
2021-12-08 06:53:35,339 DEBUG   systemd-journal-flush.service:  (W21) ignoring journalctl --flush
2021-12-08 06:53:35,340 ERROR   systemd-journal-flush.service: Service Executable path is not absolute.
2021-12-08 06:53:35,340 DEBUG   systemd-journal-flush.service:  (W22) ignoring journalctl --smart-relinquish-var
2021-12-08 06:53:35,341 INFO    systemd-journald.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 06:53:35,341 DEBUG   systemd-journald.service:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 06:53:35,342 INFO    [email protected]: Service type=notify does not provide a Service PIDFile.
2021-12-08 06:53:35,342 DEBUG   [email protected]:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 06:53:35,342 ERROR   systemd-kexec.service: Service Executable path is not absolute.
2021-12-08 06:53:35,342 DEBUG   systemd-kexec.service:  (W21) ignoring systemctl --force kexec
2021-12-08 06:53:35,344 ERROR   systemd-machine-id-commit.service: Service Executable path is not absolute.
2021-12-08 06:53:35,344 DEBUG   systemd-machine-id-commit.service:  (W21) ignoring systemd-machine-id-setup --commit
2021-12-08 06:53:35,345 INFO    systemd-networkd.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 06:53:35,345 DEBUG   systemd-networkd.service:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 06:53:35,346 ERROR   systemd-poweroff.service: found a .service file without a [Service] section
2021-12-08 06:53:35,346 DEBUG   systemd-poweroff.service:  (E00) which does render the unit definition pretty useless
2021-12-08 06:53:35,347 ERROR   systemd-reboot.service: found a .service file without a [Service] section
2021-12-08 06:53:35,347 DEBUG   systemd-reboot.service:  (E00) which does render the unit definition pretty useless
2021-12-08 06:53:35,348 INFO    systemd-resolved.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 06:53:35,348 DEBUG   systemd-resolved.service:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 06:53:35,349 INFO    systemd-rfkill.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 06:53:35,349 DEBUG   systemd-rfkill.service:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 06:53:35,350 ERROR   systemd-sysusers.service: Service Executable path is not absolute.
2021-12-08 06:53:35,350 DEBUG   systemd-sysusers.service:  (W21) ignoring systemd-sysusers
2021-12-08 06:53:35,351 INFO    systemd-timesyncd.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 06:53:35,351 DEBUG   systemd-timesyncd.service:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 06:53:35,352 ERROR   systemd-tmpfiles-clean.service: Service Executable path is not absolute.
2021-12-08 06:53:35,352 DEBUG   systemd-tmpfiles-clean.service:  (W21) ignoring systemd-tmpfiles --clean
2021-12-08 06:53:35,352 ERROR   systemd-tmpfiles-setup-dev.service: Service Executable path is not absolute.
2021-12-08 06:53:35,353 DEBUG   systemd-tmpfiles-setup-dev.service:  (W21) ignoring systemd-tmpfiles --prefix=/dev --create --boot
2021-12-08 06:53:35,353 ERROR   systemd-tmpfiles-setup.service: Service Executable path is not absolute.
2021-12-08 06:53:35,353 DEBUG   systemd-tmpfiles-setup.service:  (W21) ignoring systemd-tmpfiles --create --remove --boot --exclude-prefix=/dev
2021-12-08 06:53:35,356 INFO    [email protected]: Service type=notify does not provide a Service PIDFile.
2021-12-08 06:53:35,356 DEBUG   [email protected]:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 06:53:35,357 INFO  found 110 dependencies for units
2021-12-08 06:53:35,358 DEBUG written unit deps to /etc/systemd/systemctl.deps.cache
2021-12-08 06:53:35,358 INFO  found 5 alias units
2021-12-08 06:53:35,358 DEBUG written aliases to /etc/systemd/systemctl.alias.cache
2021-12-08 06:53:52,224 INFO EXEC BEGIN /usr/bin/systemctl-replacement.py preset mysql.service --system
2021-12-08 06:53:52,225 DEBUG ======= systemctl.py preset mysql.service
2021-12-08 06:53:52,227 DEBUG found 188 sysd files
2021-12-08 06:53:52,228 DEBUG found 2 sysv files
2021-12-08 06:53:52,228 DEBUG multi-user.target system is-running?
2021-12-08 06:53:52,729 INFO system is offline
2021-12-08 06:53:52,730 DEBUG found 1 preset files
2021-12-08 06:53:57,526 INFO EXEC BEGIN /usr/bin/systemctl-replacement.py show mysql --system
2021-12-08 06:53:57,526 DEBUG ======= systemctl.py show mysql
2021-12-08 06:53:57,528 DEBUG found 188 sysd files
2021-12-08 06:53:57,529 DEBUG found 2 sysv files
2021-12-08 06:53:57,529 DEBUG show --property=None
2021-12-08 06:53:57,529 INFO try read unit mysql.service
2021-12-08 06:53:57,924 INFO EXEC BEGIN /usr/bin/systemctl-replacement.py start mysql --system
2021-12-08 06:53:57,924 DEBUG ======= systemctl.py start mysql
2021-12-08 06:53:57,926 DEBUG found 188 sysd files
2021-12-08 06:53:57,927 DEBUG found 2 sysv files
2021-12-08 06:53:57,946 DEBUG socket dbus.socket -> service dbus.service
2021-12-08 06:53:57,964 DEBUG multi-user.target system is-running?
2021-12-08 06:53:58,465 INFO system is offline
2021-12-08 06:53:58,467 DEBUG /lib/systemd/.../mysql.service no --user mode >> accept
2021-12-08 06:53:58,467 INFO    mysql.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 06:53:58,467 DEBUG   mysql.service:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 06:53:58,467 DEBUG  start unit mysql.service => /lib/systemd/.../mysql.service
2021-12-08 06:53:58,468 INFO    mysql.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 06:53:58,469 INFO  pre-start '/usr/share/mysql-8.0/mysql-systemd-start' 'pre'
2021-12-08 06:53:58,513 DEBUG pre-start done (OK) <->
2021-12-08 06:53:58,514 DEBUG use NOTIFY_SOCKET=/run/systemd/...fy.mysql.service
2021-12-08 06:53:58,514 DEBUG ExecStart[0]: /usr/sbin/mysqld
2021-12-08 06:53:58,514 INFO notify start '/usr/sbin/mysqld'
2021-12-08 06:53:58,515 INFO notify started PID 7131
2021-12-08 06:53:58,517 DEBUG setgid 107 for group mysql
2021-12-08 06:53:58,518 DEBUG setgroups [107] < (mysql)
2021-12-08 06:53:58,518 DEBUG setgroups [107] > [] 
2021-12-08 06:53:58,518 DEBUG setuid 105 for user mysql
2021-12-08 06:53:59,017 DEBUG notify start done (OK) <->
2021-12-08 06:53:59,017 DEBUG okay, wating on socket for 0.0s
2021-12-08 06:53:59,018 INFO wait $NOTIFY_SOCKET, timeout 0.0 (lapse 3)
2021-12-08 06:54:00,018 INFO .... timeout while waiting for 'READY=1' status on $NOTIFY_SOCKET
2021-12-08 06:54:00,018 DEBUG notify = {}
2021-12-08 06:54:00,019 INFO notify start done 7131
2021-12-08 06:54:04,578 INFO EXEC BEGIN /usr/bin/systemctl-replacement.py show mysql --system
2021-12-08 06:54:04,579 DEBUG ======= systemctl.py show mysql
2021-12-08 06:54:04,582 DEBUG found 188 sysd files
2021-12-08 06:54:04,583 DEBUG found 2 sysv files
2021-12-08 06:54:04,583 DEBUG show --property=None
2021-12-08 06:54:04,583 INFO try read unit mysql.service
2021-12-08 06:54:05,018 INFO EXEC BEGIN /usr/bin/systemctl-replacement.py stop mysql --system
2021-12-08 06:54:05,018 DEBUG ======= systemctl.py stop mysql
2021-12-08 06:54:05,020 DEBUG found 188 sysd files
2021-12-08 06:54:05,021 DEBUG found 2 sysv files
2021-12-08 06:54:05,044 DEBUG socket dbus.socket -> service dbus.service
2021-12-08 06:54:05,066 DEBUG multi-user.target system is-running?
2021-12-08 06:54:05,568 INFO system is offline
2021-12-08 06:54:05,569 DEBUG /lib/systemd/.../mysql.service no --user mode >> accept
2021-12-08 06:54:05,569 INFO    mysql.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 06:54:05,569 DEBUG   mysql.service:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 06:54:05,569 INFO  stop unit mysql.service => /lib/systemd/.../mysql.service
2021-12-08 06:54:05,570 INFO    mysql.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 06:54:05,571 INFO no ExecStop => systemctl kill
2021-12-08 06:54:05,573 DEBUG .... mainpid 7131 to pid list [7131]
2021-12-08 06:54:05,573 INFO stop kill PID 7131
2021-12-08 06:54:05,573 INFO service PIDs not stopped after 0.0
2021-12-08 06:54:05,573 INFO hard kill PIDs [7131]
2021-12-08 06:54:06,074 INFO hard kill PID 7131
2021-12-08 06:54:06,575 INFO done hard kill PID 7131 OK
2021-12-08 06:54:06,576 INFO truncated /run/mysql.service.status
2021-12-08 06:54:08,503 INFO EXEC BEGIN /usr/bin/systemctl-replacement.py show mysql --system
2021-12-08 06:54:08,504 DEBUG ======= systemctl.py show mysql
2021-12-08 06:54:08,506 DEBUG found 188 sysd files
2021-12-08 06:54:08,507 DEBUG found 2 sysv files
2021-12-08 06:54:08,507 DEBUG show --property=None
2021-12-08 06:54:08,507 INFO try read unit mysql.service
2021-12-08 06:54:08,968 INFO EXEC BEGIN /usr/bin/systemctl-replacement.py start mysql --system
2021-12-08 06:54:08,968 DEBUG ======= systemctl.py start mysql
2021-12-08 06:54:08,971 DEBUG found 188 sysd files
2021-12-08 06:54:08,971 DEBUG found 2 sysv files
2021-12-08 06:54:08,996 DEBUG socket dbus.socket -> service dbus.service
2021-12-08 06:54:09,019 DEBUG multi-user.target system is-running?
2021-12-08 06:54:09,520 INFO system is offline
2021-12-08 06:54:09,522 DEBUG /lib/systemd/.../mysql.service no --user mode >> accept
2021-12-08 06:54:09,522 INFO    mysql.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 06:54:09,522 DEBUG   mysql.service:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 06:54:09,522 DEBUG  start unit mysql.service => /lib/systemd/.../mysql.service
2021-12-08 06:54:09,523 INFO    mysql.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 06:54:09,524 INFO  pre-start '/usr/share/mysql-8.0/mysql-systemd-start' 'pre'
2021-12-08 06:54:09,577 DEBUG pre-start done (OK) <->
2021-12-08 06:54:09,578 DEBUG use NOTIFY_SOCKET=/run/systemd/...fy.mysql.service
2021-12-08 06:54:09,578 DEBUG ExecStart[0]: /usr/sbin/mysqld
2021-12-08 06:54:09,579 INFO notify start '/usr/sbin/mysqld'
2021-12-08 06:54:09,580 INFO notify started PID 7903
2021-12-08 06:54:09,581 DEBUG setgid 107 for group mysql
2021-12-08 06:54:09,581 DEBUG setgroups [107] < (mysql)
2021-12-08 06:54:09,582 DEBUG setgroups [107] > [] 
2021-12-08 06:54:09,582 DEBUG setuid 105 for user mysql
2021-12-08 06:54:10,081 DEBUG notify start done (OK) <->
2021-12-08 06:54:10,081 DEBUG okay, wating on socket for 0.0s
2021-12-08 06:54:10,081 INFO wait $NOTIFY_SOCKET, timeout 0.0 (lapse 3)
2021-12-08 06:54:11,082 INFO .... timeout while waiting for 'READY=1' status on $NOTIFY_SOCKET
2021-12-08 06:54:11,082 DEBUG notify = {}
2021-12-08 06:54:11,083 INFO notify start done 7903
2021-12-08 06:54:21,291 INFO EXEC BEGIN /usr/bin/systemctl-replacement.py show mysql --system
2021-12-08 06:54:21,291 DEBUG ======= systemctl.py show mysql
2021-12-08 06:54:21,293 DEBUG found 188 sysd files
2021-12-08 06:54:21,294 DEBUG found 2 sysv files
2021-12-08 06:54:21,294 DEBUG show --property=None
2021-12-08 06:54:21,294 INFO try read unit mysql.service
2021-12-08 06:54:21,707 INFO EXEC BEGIN /usr/bin/systemctl-replacement.py restart mysql --system
2021-12-08 06:54:21,708 DEBUG ======= systemctl.py restart mysql
2021-12-08 06:54:21,711 DEBUG found 188 sysd files
2021-12-08 06:54:21,713 DEBUG found 2 sysv files
2021-12-08 06:54:21,742 DEBUG socket dbus.socket -> service dbus.service
2021-12-08 06:54:21,768 DEBUG multi-user.target system is-running?
2021-12-08 06:54:22,269 INFO system is offline
2021-12-08 06:54:22,270 DEBUG /lib/systemd/.../mysql.service no --user mode >> accept
2021-12-08 06:54:22,270 INFO    mysql.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 06:54:22,270 DEBUG   mysql.service:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 06:54:22,271 INFO  restart service mysql.service => /lib/systemd/.../mysql.service
2021-12-08 06:54:22,271 INFO (restart) => stop/start mysql.service
2021-12-08 06:54:22,272 INFO    mysql.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 06:54:22,272 INFO no ExecStop => systemctl kill
2021-12-08 06:54:22,274 DEBUG .... mainpid 7903 to pid list [7903]
2021-12-08 06:54:22,274 INFO stop kill PID 7903
2021-12-08 06:54:22,274 INFO service PIDs not stopped after 0.0
2021-12-08 06:54:22,274 INFO hard kill PIDs [7903]
2021-12-08 06:54:22,775 INFO hard kill PID 7903
2021-12-08 06:54:23,276 INFO done hard kill PID 7903 OK
2021-12-08 06:54:23,277 INFO    mysql.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 06:54:23,278 INFO  pre-start '/usr/share/mysql-8.0/mysql-systemd-start' 'pre'
2021-12-08 06:54:23,325 DEBUG pre-start done (OK) <->
2021-12-08 06:54:23,326 DEBUG use NOTIFY_SOCKET=/run/systemd/...fy.mysql.service
2021-12-08 06:54:23,326 DEBUG ExecStart[0]: /usr/sbin/mysqld
2021-12-08 06:54:23,326 INFO notify start '/usr/sbin/mysqld'
2021-12-08 06:54:23,327 INFO notify started PID 9124
2021-12-08 06:54:23,329 DEBUG setgid 107 for group mysql
2021-12-08 06:54:23,329 DEBUG setgroups [107] < (mysql)
2021-12-08 06:54:23,329 DEBUG setgroups [107] > [] 
2021-12-08 06:54:23,329 DEBUG setuid 105 for user mysql
2021-12-08 06:54:23,829 DEBUG notify start done (OK) <->
2021-12-08 06:54:23,829 DEBUG okay, wating on socket for 0.0s
2021-12-08 06:54:23,829 INFO wait $NOTIFY_SOCKET, timeout 0.0 (lapse 3)
2021-12-08 06:54:24,830 INFO .... timeout while waiting for 'READY=1' status on $NOTIFY_SOCKET
2021-12-08 06:54:24,830 DEBUG notify = {}
2021-12-08 06:54:24,831 INFO notify start done 9124


$ cat /var/log/mysql/error.log
2021-12-08T06:53:45.124057Z 0 [System] [MY-013169] [Server] /usr/sbin/mysqld (mysqld 8.0.27) initializing of server in progress as process 6524
2021-12-08T06:53:45.137801Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2021-12-08T06:53:45.817097Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2021-12-08T06:53:49.047326Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.27) starting as process 6597
2021-12-08T06:53:49.061992Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2021-12-08T06:53:49.740096Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2021-12-08T06:53:50.082454Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2021-12-08T06:53:50.082506Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2021-12-08T06:53:50.116777Z 7 [System] [MY-013172] [Server] Received SHUTDOWN from user boot. Shutting down mysqld (Version: 8.0.27).
2021-12-08T06:53:50.117650Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/run/mysqld/mysqlx.sock
2021-12-08T06:53:51.657012Z 0 [System] [MY-010910] [Server] /usr/sbin/mysqld: Shutdown complete (mysqld 8.0.27)  MySQL Community Server - GPL.
2021-12-08T06:53:58.805775Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.27) starting as process 7131
2021-12-08T06:53:58.820187Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2021-12-08T06:53:59.252269Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2021-12-08T06:53:59.532212Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2021-12-08T06:53:59.532272Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2021-12-08T06:53:59.562689Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/run/mysqld/mysqlx.sock
2021-12-08T06:53:59.562730Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.27'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MySQL Community Server - GPL.
2021-12-08T06:54:05.573771Z 0 [System] [MY-013172] [Server] Received SHUTDOWN from user <via user signal>. Shutting down mysqld (Version: 8.0.27).
2021-12-08T06:54:05.573960Z 0 [Warning] [MY-011808] [Server] Failed to write 'STOPPING=1 STATUS=Server shutdown in progress ' to systemd notification. Error: 'Connection refused'
2021-12-08T06:54:09.868590Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.27) starting as process 7903
2021-12-08T06:54:09.882204Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2021-12-08T06:54:11.403453Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2021-12-08T06:54:11.612292Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2021-12-08T06:54:11.612354Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2021-12-08T06:54:11.658422Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/run/mysqld/mysqlx.sock
2021-12-08T06:54:11.658578Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.27'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MySQL Community Server - GPL.
2021-12-08T06:54:11.658649Z 0 [Warning] [MY-011808] [Server] Failed to write 'READY=1 STATUS=Server is operational MAIN_PID=7903 ' to systemd notification. Error: 'Connection refused'
2021-12-08T06:54:22.274380Z 0 [System] [MY-013172] [Server] Received SHUTDOWN from user <via user signal>. Shutting down mysqld (Version: 8.0.27).
2021-12-08T06:54:22.274535Z 0 [Warning] [MY-011808] [Server] Failed to write 'STOPPING=1 STATUS=Server shutdown in progress ' to systemd notification. Error: 'Transport endpoint is not connected'
2021-12-08T06:54:23.614534Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.27) starting as process 9124
2021-12-08T06:54:23.630266Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2021-12-08T06:54:24.039743Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2021-12-08T06:54:24.245336Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2021-12-08T06:54:24.245387Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2021-12-08T06:54:24.289074Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/run/mysqld/mysqlx.sock
2021-12-08T06:54:24.289194Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.27'  socket: '0'  port: 3306  MySQL Community Server - GPL.

@mvorisek
Copy link
Author

mvorisek commented Dec 8, 2021

This issue is present on Debian 11 only. On Debian 10, there are no systemd notification issues.

Log diff: https://www.diffchecker.com/QFwZOApx

The mysql-server version is exactly the same.

Both deployed using Ansible on clean Docker images, the only difference is the OS and the related different distro packages.

@mvorisek
Copy link
Author

mvorisek commented Dec 8, 2021 •
edited
Loading

Debian 11 has default python v3.9. Debian 10 v2.x. This is the configuration used for all logs above.

I did an experiment with python v3.8 on Debian 10. When python v3.8 (instead of v2.x) is used on Debian 10, the same issue is present (eg. Failed to write 'READY=1 is logged from mysql server in Debian 10 too). All non-python related things are absolutely same and deployed on clean image.

The only change from docker-systemctl-replacement perspective is that when python v3.x is used, Ansible 2.11 is installed. When python v2.x is used, Ansible version is 2.9. Not sure if Ansible emit a different systemd commands, but otherwise the different behaviour has to come from docker-systemctl-replacement when a different major python version is used.

@gdraheim
Copy link
Owner

gdraheim commented Dec 8, 2021

2021-12-08 06:53:59,017 DEBUG okay, wating on socket for 0.0s
2021-12-08 06:53:59,018 INFO wait $NOTIFY_SOCKET, timeout 0.0 (lapse 3)
2021-12-08 06:54:00,018 INFO .... timeout while waiting for 'READY=1' status on $NOTIFY_SOCKET

Having a zero timeout does not sound like a good idea.

@mvorisek
Copy link
Author

mvorisek commented Dec 8, 2021

The service config is:

[Unit]
Description=MySQL Community Server
Documentation=man:mysqld(8)
Documentation=http://dev.mysql.com/doc/refman/en/using-systemd.html
After=network.target
[Install]
WantedBy=multi-user.target
[Service]
User=mysql
Group=mysql
Type=notify
PermissionsStartOnly=true
ExecStartPre=+/usr/share/mysql-8.0/mysql-systemd-start pre
ExecStart=/usr/sbin/mysqld
TimeoutSec=0
LimitNOFILE = 10000
Restart=on-failure
RestartPreventExitStatus=1

using the develop docker-systemctl-replacement (because of the executable + prefix for ExecStartPre)

@mvorisek
Copy link
Author

mvorisek commented Dec 8, 2021

based on the official systemd/systemd#10501 , 0 and 0s should imply infinity

@gdraheim
Copy link
Owner

gdraheim commented Dec 8, 2021

Well, that's not implemented.

It seems nobody did try such a global non-timeout before.

@mvorisek
Copy link
Author

mvorisek commented Dec 8, 2021 

$ cat /var/log/systemctl.debug.log
2021-12-08 07:55:51,593 INFO EXEC BEGIN /usr/bin/systemctl-replacement.py daemon-reload --system
2021-12-08 07:55:51,593 DEBUG ======= systemctl.py daemon-reload
2021-12-08 07:55:51,595 DEBUG found 186 sysd files
2021-12-08 07:55:51,596 DEBUG found 2 sysv files
2021-12-08 07:55:51,602 INFO    dbus-org.freedesktop.timesync1.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 07:55:51,602 DEBUG   dbus-org.freedesktop.timesync1.service:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 07:55:51,607 ERROR   getty-static.service: Service Executable path is not absolute.
2021-12-08 07:55:51,607 DEBUG   getty-static.service:  (W21) ignoring systemctl --no-block start [email protected] [email protected] [email protected] [email protected] [email protected]
2021-12-08 07:55:51,609 ERROR   initrd-cleanup.service: Service Executable path is not absolute.
2021-12-08 07:55:51,609 DEBUG   initrd-cleanup.service:  (W21) ignoring systemctl --no-block isolate initrd-switch-root.target
2021-12-08 07:55:51,610 WARNING initrd-parse-etc.service: Service Executable path is not absolute.
2021-12-08 07:55:51,610 DEBUG   initrd-parse-etc.service:  (W21) ignoring systemctl --no-block start initrd-fs.target
2021-12-08 07:55:51,610 ERROR   initrd-parse-etc.service: Service Executable path is not absolute.
2021-12-08 07:55:51,610 DEBUG   initrd-parse-etc.service:  (W21) ignoring systemctl --no-block start initrd-cleanup.service
2021-12-08 07:55:51,611 ERROR   initrd-switch-root.service: Service Executable path is not absolute.
2021-12-08 07:55:51,611 DEBUG   initrd-switch-root.service:  (W21) ignoring systemctl --no-block switch-root /sysroot
2021-12-08 07:55:51,612 WARNING initrd-udevadm-cleanup-db.service: Service Executable path is not absolute.
2021-12-08 07:55:51,612 DEBUG   initrd-udevadm-cleanup-db.service:  (W21) ignoring udevadm info --cleanup-db
2021-12-08 07:55:51,618 WARNING rc-local.service: Service type=forking does not provide a Service PIDFile.
2021-12-08 07:55:51,618 DEBUG   rc-local.service:  (W12) this will not allow sending signals to the MainPID (expect restart problems)
2021-12-08 07:55:51,627 ERROR   systemd-ask-password-console.service: Service Executable path is not absolute.
2021-12-08 07:55:51,628 DEBUG   systemd-ask-password-console.service:  (W21) ignoring systemd-tty-ask-password-agent --watch --console
2021-12-08 07:55:51,628 ERROR   systemd-ask-password-wall.service: Service Executable path is not absolute.
2021-12-08 07:55:51,628 DEBUG   systemd-ask-password-wall.service:  (W21) ignoring systemd-tty-ask-password-agent --wall
2021-12-08 07:55:51,630 ERROR   systemd-boot-system-token.service: Service Executable path is not absolute.
2021-12-08 07:55:51,630 DEBUG   systemd-boot-system-token.service:  (W21) ignoring bootctl random-seed --graceful
2021-12-08 07:55:51,630 ERROR   systemd-exit.service: found a .service file without a [Service] section
2021-12-08 07:55:51,631 DEBUG   systemd-exit.service:  (E00) which does render the unit definition pretty useless
2021-12-08 07:55:51,632 ERROR   systemd-halt.service: Service Executable path is not absolute.
2021-12-08 07:55:51,632 DEBUG   systemd-halt.service:  (W21) ignoring systemctl --force halt
2021-12-08 07:55:51,634 ERROR   systemd-journal-flush.service: Service Executable path is not absolute.
2021-12-08 07:55:51,634 DEBUG   systemd-journal-flush.service:  (W21) ignoring journalctl --flush
2021-12-08 07:55:51,634 ERROR   systemd-journal-flush.service: Service Executable path is not absolute.
2021-12-08 07:55:51,634 DEBUG   systemd-journal-flush.service:  (W22) ignoring journalctl --smart-relinquish-var
2021-12-08 07:55:51,636 INFO    systemd-journald.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 07:55:51,636 DEBUG   systemd-journald.service:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 07:55:51,636 INFO    [email protected]: Service type=notify does not provide a Service PIDFile.
2021-12-08 07:55:51,637 DEBUG   [email protected]:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 07:55:51,637 ERROR   systemd-kexec.service: Service Executable path is not absolute.
2021-12-08 07:55:51,637 DEBUG   systemd-kexec.service:  (W21) ignoring systemctl --force kexec
2021-12-08 07:55:51,639 ERROR   systemd-machine-id-commit.service: Service Executable path is not absolute.
2021-12-08 07:55:51,639 DEBUG   systemd-machine-id-commit.service:  (W21) ignoring systemd-machine-id-setup --commit
2021-12-08 07:55:51,640 INFO    systemd-networkd.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 07:55:51,640 DEBUG   systemd-networkd.service:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 07:55:51,641 ERROR   systemd-poweroff.service: found a .service file without a [Service] section
2021-12-08 07:55:51,641 DEBUG   systemd-poweroff.service:  (E00) which does render the unit definition pretty useless
2021-12-08 07:55:51,642 ERROR   systemd-reboot.service: found a .service file without a [Service] section
2021-12-08 07:55:51,642 DEBUG   systemd-reboot.service:  (E00) which does render the unit definition pretty useless
2021-12-08 07:55:51,643 INFO    systemd-resolved.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 07:55:51,643 DEBUG   systemd-resolved.service:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 07:55:51,644 INFO    systemd-rfkill.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 07:55:51,644 DEBUG   systemd-rfkill.service:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 07:55:51,645 ERROR   systemd-sysusers.service: Service Executable path is not absolute.
2021-12-08 07:55:51,645 DEBUG   systemd-sysusers.service:  (W21) ignoring systemd-sysusers
2021-12-08 07:55:51,646 INFO    systemd-timesyncd.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 07:55:51,647 DEBUG   systemd-timesyncd.service:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 07:55:51,647 ERROR   systemd-tmpfiles-clean.service: Service Executable path is not absolute.
2021-12-08 07:55:51,647 DEBUG   systemd-tmpfiles-clean.service:  (W21) ignoring systemd-tmpfiles --clean
2021-12-08 07:55:51,648 ERROR   systemd-tmpfiles-setup-dev.service: Service Executable path is not absolute.
2021-12-08 07:55:51,648 DEBUG   systemd-tmpfiles-setup-dev.service:  (W21) ignoring systemd-tmpfiles --prefix=/dev --create --boot
2021-12-08 07:55:51,648 ERROR   systemd-tmpfiles-setup.service: Service Executable path is not absolute.
2021-12-08 07:55:51,648 DEBUG   systemd-tmpfiles-setup.service:  (W21) ignoring systemd-tmpfiles --create --remove --boot --exclude-prefix=/dev
2021-12-08 07:55:51,653 INFO    [email protected]: Service type=notify does not provide a Service PIDFile.
2021-12-08 07:55:51,653 DEBUG   [email protected]:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 07:55:51,654 INFO  found 110 dependencies for units
2021-12-08 07:55:51,655 DEBUG written unit deps to /etc/systemd/systemctl.deps.cache
2021-12-08 07:55:51,655 INFO  found 5 alias units
2021-12-08 07:55:51,655 DEBUG written aliases to /etc/systemd/systemctl.alias.cache
2021-12-08 07:56:12,083 INFO EXEC BEGIN /usr/bin/systemctl-replacement.py preset mysql.service --system
2021-12-08 07:56:12,084 DEBUG ======= systemctl.py preset mysql.service
2021-12-08 07:56:12,085 DEBUG found 188 sysd files
2021-12-08 07:56:12,087 DEBUG found 2 sysv files
2021-12-08 07:56:12,087 DEBUG multi-user.target system is-running?
2021-12-08 07:56:12,588 INFO system is offline
2021-12-08 07:56:12,588 DEBUG found 1 preset files
2021-12-08 07:56:18,448 INFO EXEC BEGIN /usr/bin/systemctl-replacement.py show mysql --system
2021-12-08 07:56:18,449 DEBUG ======= systemctl.py show mysql
2021-12-08 07:56:18,451 DEBUG found 188 sysd files
2021-12-08 07:56:18,452 DEBUG found 2 sysv files
2021-12-08 07:56:18,452 DEBUG show --property=None
2021-12-08 07:56:18,452 INFO try read unit mysql.service
2021-12-08 07:56:18,859 INFO EXEC BEGIN /usr/bin/systemctl-replacement.py start mysql --system
2021-12-08 07:56:18,859 DEBUG ======= systemctl.py start mysql
2021-12-08 07:56:18,861 DEBUG found 188 sysd files
2021-12-08 07:56:18,862 DEBUG found 2 sysv files
2021-12-08 07:56:18,883 DEBUG socket dbus.socket -> service dbus.service
2021-12-08 07:56:18,902 DEBUG multi-user.target system is-running?
2021-12-08 07:56:19,403 INFO system is offline
2021-12-08 07:56:19,405 DEBUG /lib/systemd/.../mysql.service no --user mode >> accept
2021-12-08 07:56:19,405 INFO    mysql.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 07:56:19,405 DEBUG   mysql.service:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 07:56:19,405 DEBUG  start unit mysql.service => /lib/systemd/.../mysql.service
2021-12-08 07:56:19,406 INFO    mysql.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 07:56:19,408 INFO  pre-start '/usr/share/mysql-8.0/mysql-systemd-start' 'pre'
2021-12-08 07:56:19,509 DEBUG pre-start done (OK) <->
2021-12-08 07:56:19,511 DEBUG use NOTIFY_SOCKET=/run/systemd/...fy.mysql.service
2021-12-08 07:56:19,511 DEBUG ExecStart[0]: /usr/sbin/mysqld
2021-12-08 07:56:19,513 INFO notify start '/usr/sbin/mysqld'
2021-12-08 07:56:19,514 INFO notify started PID 7132
2021-12-08 07:56:19,517 DEBUG setgid 107 for group mysql
2021-12-08 07:56:19,517 DEBUG setgroups [107] < (mysql)
2021-12-08 07:56:19,517 DEBUG setgroups [107] > [] 
2021-12-08 07:56:19,517 DEBUG setuid 105 for user mysql
2021-12-08 07:56:20,015 DEBUG notify start done (OK) <->
2021-12-08 07:56:20,016 DEBUG okay, wating on socket for 100.0s
2021-12-08 07:56:20,016 INFO wait $NOTIFY_SOCKET, timeout 100.0 (lapse 3)
2021-12-08 07:56:21,017 DEBUG read_notify_socket(34):STATUS=Server startup in progress|
2021-12-08 07:56:21,017 DEBUG seen notify  ---      :STATUS=Server startup in progress
2021-12-08 07:56:22,019 DEBUG read_notify_socket(51):READY=1|STATUS=Server is operational|MAIN_PID=7132|
2021-12-08 07:56:22,019 DEBUG seen notify  ---      :READY=1
2021-12-08 07:56:22,019 DEBUG seen notify  ---      :STATUS=Server is operational
2021-12-08 07:56:26,022 INFO .... seen 'READY=1' but no MAINPID update status on $NOTIFY_SOCKET
2021-12-08 07:56:26,022 DEBUG notify = {'STATUS': 'Server is operational', 'READY': '1', 'MAIN_PID': '7132'}
2021-12-08 07:56:26,023 INFO notify start done 7132
2021-12-08 07:56:31,508 INFO EXEC BEGIN /usr/bin/systemctl-replacement.py show mysql --system
2021-12-08 07:56:31,508 DEBUG ======= systemctl.py show mysql
2021-12-08 07:56:31,510 DEBUG found 188 sysd files
2021-12-08 07:56:31,511 DEBUG found 2 sysv files
2021-12-08 07:56:31,511 DEBUG show --property=None
2021-12-08 07:56:31,511 INFO try read unit mysql.service
2021-12-08 07:56:32,036 INFO EXEC BEGIN /usr/bin/systemctl-replacement.py stop mysql --system
2021-12-08 07:56:32,037 DEBUG ======= systemctl.py stop mysql
2021-12-08 07:56:32,038 DEBUG found 188 sysd files
2021-12-08 07:56:32,039 DEBUG found 2 sysv files
2021-12-08 07:56:32,062 DEBUG socket dbus.socket -> service dbus.service
2021-12-08 07:56:32,083 DEBUG multi-user.target system is-running?
2021-12-08 07:56:32,584 INFO system is offline
2021-12-08 07:56:32,585 DEBUG /lib/systemd/.../mysql.service no --user mode >> accept
2021-12-08 07:56:32,586 INFO    mysql.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 07:56:32,586 DEBUG   mysql.service:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 07:56:32,586 INFO  stop unit mysql.service => /lib/systemd/.../mysql.service
2021-12-08 07:56:32,587 INFO    mysql.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 07:56:32,587 INFO no ExecStop => systemctl kill
2021-12-08 07:56:32,589 DEBUG .... mainpid 7132 to pid list [7132]
2021-12-08 07:56:32,589 INFO stop kill PID 7132
2021-12-08 07:56:33,590 INFO done kill PID 7132 OK
2021-12-08 07:56:33,591 INFO truncated /run/mysql.service.status
2021-12-08 07:56:35,633 INFO EXEC BEGIN /usr/bin/systemctl-replacement.py show mysql --system
2021-12-08 07:56:35,634 DEBUG ======= systemctl.py show mysql
2021-12-08 07:56:35,636 DEBUG found 188 sysd files
2021-12-08 07:56:35,637 DEBUG found 2 sysv files
2021-12-08 07:56:35,637 DEBUG show --property=None
2021-12-08 07:56:35,637 INFO try read unit mysql.service
2021-12-08 07:56:36,115 INFO EXEC BEGIN /usr/bin/systemctl-replacement.py start mysql --system
2021-12-08 07:56:36,115 DEBUG ======= systemctl.py start mysql
2021-12-08 07:56:36,117 DEBUG found 188 sysd files
2021-12-08 07:56:36,118 DEBUG found 2 sysv files
2021-12-08 07:56:36,137 DEBUG socket dbus.socket -> service dbus.service
2021-12-08 07:56:36,155 DEBUG multi-user.target system is-running?
2021-12-08 07:56:36,656 INFO system is offline
2021-12-08 07:56:36,657 DEBUG /lib/systemd/.../mysql.service no --user mode >> accept
2021-12-08 07:56:36,657 INFO    mysql.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 07:56:36,658 DEBUG   mysql.service:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 07:56:36,658 DEBUG  start unit mysql.service => /lib/systemd/.../mysql.service
2021-12-08 07:56:36,659 INFO    mysql.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 07:56:36,660 INFO  pre-start '/usr/share/mysql-8.0/mysql-systemd-start' 'pre'
2021-12-08 07:56:36,714 DEBUG pre-start done (OK) <->
2021-12-08 07:56:36,715 DEBUG use NOTIFY_SOCKET=/run/systemd/...fy.mysql.service
2021-12-08 07:56:36,715 DEBUG ExecStart[0]: /usr/sbin/mysqld
2021-12-08 07:56:36,716 INFO notify start '/usr/sbin/mysqld'
2021-12-08 07:56:36,717 INFO notify started PID 7904
2021-12-08 07:56:36,718 DEBUG setgid 107 for group mysql
2021-12-08 07:56:36,719 DEBUG setgroups [107] < (mysql)
2021-12-08 07:56:36,719 DEBUG setgroups [107] > [] 
2021-12-08 07:56:36,719 DEBUG setuid 105 for user mysql
2021-12-08 07:56:37,218 DEBUG notify start done (OK) <->
2021-12-08 07:56:37,218 DEBUG okay, wating on socket for 100.0s
2021-12-08 07:56:37,218 INFO wait $NOTIFY_SOCKET, timeout 100.0 (lapse 3)
2021-12-08 07:56:38,220 DEBUG read_notify_socket(34):STATUS=Server startup in progress|
2021-12-08 07:56:38,220 DEBUG seen notify  ---      :STATUS=Server startup in progress
2021-12-08 07:56:39,222 DEBUG read_notify_socket(51):READY=1|STATUS=Server is operational|MAIN_PID=7904|
2021-12-08 07:56:39,222 DEBUG seen notify  ---      :READY=1
2021-12-08 07:56:39,222 DEBUG seen notify  ---      :STATUS=Server is operational
2021-12-08 07:56:43,225 INFO .... seen 'READY=1' but no MAINPID update status on $NOTIFY_SOCKET
2021-12-08 07:56:43,226 DEBUG notify = {'STATUS': 'Server is operational', 'READY': '1', 'MAIN_PID': '7904'}
2021-12-08 07:56:43,226 INFO notify start done 7904
2021-12-08 07:56:53,317 INFO EXEC BEGIN /usr/bin/systemctl-replacement.py show mysql --system
2021-12-08 07:56:53,318 DEBUG ======= systemctl.py show mysql
2021-12-08 07:56:53,319 DEBUG found 188 sysd files
2021-12-08 07:56:53,320 DEBUG found 2 sysv files
2021-12-08 07:56:53,320 DEBUG show --property=None
2021-12-08 07:56:53,320 INFO try read unit mysql.service
2021-12-08 07:56:53,841 INFO EXEC BEGIN /usr/bin/systemctl-replacement.py restart mysql --system
2021-12-08 07:56:53,841 DEBUG ======= systemctl.py restart mysql
2021-12-08 07:56:53,844 DEBUG found 188 sysd files
2021-12-08 07:56:53,845 DEBUG found 2 sysv files
2021-12-08 07:56:53,867 DEBUG socket dbus.socket -> service dbus.service
2021-12-08 07:56:53,888 DEBUG multi-user.target system is-running?
2021-12-08 07:56:54,390 INFO system is offline
2021-12-08 07:56:54,391 DEBUG /lib/systemd/.../mysql.service no --user mode >> accept
2021-12-08 07:56:54,392 INFO    mysql.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 07:56:54,392 DEBUG   mysql.service:  (W11) this will make systemctl to wait for MAINPID (expect timeout problems)
2021-12-08 07:56:54,392 INFO  restart service mysql.service => /lib/systemd/.../mysql.service
2021-12-08 07:56:54,393 INFO (restart) => stop/start mysql.service
2021-12-08 07:56:54,393 INFO    mysql.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 07:56:54,394 INFO no ExecStop => systemctl kill
2021-12-08 07:56:54,395 DEBUG .... mainpid 7904 to pid list [7904]
2021-12-08 07:56:54,395 INFO stop kill PID 7904
2021-12-08 07:56:55,397 INFO done kill PID 7904 OK
2021-12-08 07:56:55,397 INFO    mysql.service: Service type=notify does not provide a Service PIDFile.
2021-12-08 07:56:55,399 INFO  pre-start '/usr/share/mysql-8.0/mysql-systemd-start' 'pre'
2021-12-08 07:56:55,441 DEBUG pre-start done (OK) <->
2021-12-08 07:56:55,442 DEBUG use NOTIFY_SOCKET=/run/systemd/...fy.mysql.service
2021-12-08 07:56:55,442 DEBUG ExecStart[0]: /usr/sbin/mysqld
2021-12-08 07:56:55,443 INFO notify start '/usr/sbin/mysqld'
2021-12-08 07:56:55,444 INFO notify started PID 9124
2021-12-08 07:56:55,445 DEBUG setgid 107 for group mysql
2021-12-08 07:56:55,445 DEBUG setgroups [107] < (mysql)
2021-12-08 07:56:55,446 DEBUG setgroups [107] > [] 
2021-12-08 07:56:55,446 DEBUG setuid 105 for user mysql
2021-12-08 07:56:55,945 DEBUG notify start done (OK) <->
2021-12-08 07:56:55,945 DEBUG okay, wating on socket for 100.0s
2021-12-08 07:56:55,946 INFO wait $NOTIFY_SOCKET, timeout 100.0 (lapse 3)
2021-12-08 07:56:56,947 DEBUG read_notify_socket(34):STATUS=Server startup in progress|
2021-12-08 07:56:56,947 DEBUG seen notify  ---      :STATUS=Server startup in progress
2021-12-08 07:56:57,949 DEBUG read_notify_socket(51):READY=1|STATUS=Server is operational|MAIN_PID=9124|
2021-12-08 07:56:57,949 DEBUG seen notify  ---      :READY=1
2021-12-08 07:56:57,949 DEBUG seen notify  ---      :STATUS=Server is operational
2021-12-08 07:57:01,953 INFO .... seen 'READY=1' but no MAINPID update status on $NOTIFY_SOCKET
2021-12-08 07:57:01,953 DEBUG notify = {'STATUS': 'Server is operational', 'READY': '1', 'MAIN_PID': '9124'}
2021-12-08 07:57:01,953 INFO notify start done 9124


$ cat /var/log/mysql/error.log
2021-12-08T07:56:03.342410Z 0 [System] [MY-013169] [Server] /usr/sbin/mysqld (mysqld 8.0.27) initializing of server in progress as process 6525
2021-12-08T07:56:03.356598Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2021-12-08T07:56:04.332493Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2021-12-08T07:56:08.634284Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.27) starting as process 6598
2021-12-08T07:56:08.648744Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2021-12-08T07:56:09.377045Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2021-12-08T07:56:09.896271Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2021-12-08T07:56:09.896322Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2021-12-08T07:56:09.957232Z 7 [System] [MY-013172] [Server] Received SHUTDOWN from user boot. Shutting down mysqld (Version: 8.0.27).
2021-12-08T07:56:09.958253Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/run/mysqld/mysqlx.sock
2021-12-08T07:56:11.522019Z 0 [System] [MY-010910] [Server] /usr/sbin/mysqld: Shutdown complete (mysqld 8.0.27)  MySQL Community Server - GPL.
2021-12-08T07:56:19.838275Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.27) starting as process 7132
2021-12-08T07:56:19.853473Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2021-12-08T07:56:20.505695Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2021-12-08T07:56:20.904779Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2021-12-08T07:56:20.904970Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2021-12-08T07:56:20.949209Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.27'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MySQL Community Server - GPL.
2021-12-08T07:56:20.949703Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/run/mysqld/mysqlx.sock
2021-12-08T07:56:32.589330Z 0 [System] [MY-013172] [Server] Received SHUTDOWN from user <via user signal>. Shutting down mysqld (Version: 8.0.27).
2021-12-08T07:56:32.589501Z 0 [Warning] [MY-011808] [Server] Failed to write 'STOPPING=1 STATUS=Server shutdown in progress ' to systemd notification. Error: 'Connection refused'
2021-12-08T07:56:33.325483Z 0 [System] [MY-010910] [Server] /usr/sbin/mysqld: Shutdown complete (mysqld 8.0.27)  MySQL Community Server - GPL.
2021-12-08T07:56:33.326759Z 0 [Warning] [MY-011808] [Server] Failed to write 'STATUS=Server shutdown complete' to systemd notification. Error: 'Transport endpoint is not connected'
2021-12-08T07:56:37.011499Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.27) starting as process 7904
2021-12-08T07:56:37.025530Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2021-12-08T07:56:37.492053Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2021-12-08T07:56:37.756452Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2021-12-08T07:56:37.756511Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2021-12-08T07:56:37.821893Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/run/mysqld/mysqlx.sock
2021-12-08T07:56:37.822478Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.27'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MySQL Community Server - GPL.
2021-12-08T07:56:54.395866Z 0 [System] [MY-013172] [Server] Received SHUTDOWN from user <via user signal>. Shutting down mysqld (Version: 8.0.27).
2021-12-08T07:56:54.396037Z 0 [Warning] [MY-011808] [Server] Failed to write 'STOPPING=1 STATUS=Server shutdown in progress ' to systemd notification. Error: 'Connection refused'
2021-12-08T07:56:55.204785Z 0 [System] [MY-010910] [Server] /usr/sbin/mysqld: Shutdown complete (mysqld 8.0.27)  MySQL Community Server - GPL.
2021-12-08T07:56:55.207791Z 0 [Warning] [MY-011808] [Server] Failed to write 'STATUS=Server shutdown complete' to systemd notification. Error: 'Transport endpoint is not connected'
2021-12-08T07:56:55.733392Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.27) starting as process 9124
2021-12-08T07:56:55.747530Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2021-12-08T07:56:56.179623Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2021-12-08T07:56:56.391915Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2021-12-08T07:56:56.391976Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2021-12-08T07:56:56.441873Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/run/mysqld/mysqlx.sock
2021-12-08T07:56:56.441942Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.27'  socket: '0'  port: 3306  MySQL Community Server - GPL.

When I set the timeout to 100s in the config, the READY notification is accepted.

is there any reason to not translate 0 into infinity?

The STOPPING notification is not accepted, previously you have written:

For a "Type=notify" service the notify-socket is actually created. It waits for the READY=1 on each ExecStart before continuing. After it got that signal it will close the socket however.

why is the socket closed at all? can it be kept alive so the services can dispatch the notifications regularly?

@mvorisek mvorisek changed the title Systemd notification should be accepted Systemd notification does not wait when 0 is specified and does not accept events after READY is received Dec 8, 2021
@mvorisek mvorisek changed the title Systemd notification does not wait when 0 is specified and does not accept events after READY is received Systemd notification does not accept events after READY is received Dec 8, 2021
@mvorisek
Copy link
Author

mvorisek commented Dec 8, 2021

for the 0 issue, I have created separate #135 issue

@gdraheim
Copy link
Owner

gdraheim commented Dec 8, 2021

why is the socket closed at all? can it be kept alive so the services can dispatch the notifications regularly?

The systemctl-replacement is very different from a systemd daemon - it will start the processes and detach from them. There is no counterpart that could listen on the socket. As further notifications on the socket are only for logging some messages, it is not really needed for the start/stop mechanism of services.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@gdraheim @mvorisek