Univention Bugzilla – Bug 44118
New/deleted Samba printer shares not visible because invoke-rc.d samba fails with systemd
Last modified: 2017-04-04 18:28:21 CEST
During product tests with printer shares, new created (or removed) printer shares did not become visible (or stayed visible). The listener log shows that systemd doesn't remolad the service properly: ============================================================================ 28.03.17 08:16:27.087 LISTENER ( PROCESS ) : updating 'uid=user2,ou=einheit1,dc=ar41pt1,dc=qa' command m 28.03.17 08:16:27.181 LISTENER ( WARN ) : replication: Can't contact LDAP server: retrying 28.03.17 08:31:02.960 LISTENER ( PROCESS ) : updating 'cn=printer1,cn=printers,dc=ar41pt1,dc=qa' command a 28.03.17 08:31:02.973 LISTENER ( WARN ) : replication: Can't contact LDAP server: retrying 28.03.17 08:31:03.095 LISTENER ( WARN ) : cups-printers: info: univention-lpadmin -u allow:all -o auth-info-required=none -p printer1 -m foomatic-rip/Generic-PostScript_Level_1_Printer-Postscript1.ppd -v socket://192.168.0.80 -E Job for samba.service failed. See 'systemctl status samba.service' and 'journalctl -xn' for details. invoke-rc.d: initscript samba, action "reload" failed. 28.03.17 08:32:00.369 LISTENER ( PROCESS ) : updating 'cn=printer2,cn=printers,dc=ar41pt1,dc=qa' command a 28.03.17 08:32:07.563 LISTENER ( PROCESS ) : updating 'cn=printer1,cn=printers,dc=ar41pt1,dc=qa' command m 28.03.17 08:32:07.649 LISTENER ( WARN ) : cups-printers: info: univention-lpadmin -u allow:all -o auth-info-required=none -p printer1 -v socket://192.168.0.80:9100 -E Job for samba.service failed. See 'systemctl status samba.service' and 'journalctl -xn' for details. invoke-rc.d: initscript samba, action "reload" failed. 28.03.17 08:33:34.639 LISTENER ( PROCESS ) : updating 'cn=printer3,cn=printers,dc=ar41pt1,dc=qa' command a 28.03.17 08:33:34.672 LISTENER ( WARN ) : cups-printers: info: univention-lpadmin -u allow:all -o auth-info-required=none -p printer3 -m foomatic-rip/Generic-PostScript_Level_1_Printer-Postscript1.ppd -v socket://192.168.0.80:9100 -E Job for samba.service failed. See 'systemctl status samba.service' and 'journalctl -xn' for details. invoke-rc.d: initscript samba, action "reload" failed. 28.03.17 08:34:01.300 LISTENER ( PROCESS ) : updating 'cn=printer4,cn=printers,dc=ar41pt1,dc=qa' command a Job for samba.service failed. See 'systemctl status samba.service' and 'journalctl -xn' for details. invoke-rc.d: initscript samba, action "reload" failed. 28.03.17 09:04:54.487 LISTENER ( PROCESS ) : updating 'cn=printer5,cn=printers,dc=ar41pt1,dc=qa' command a 28.03.17 09:04:54.513 LISTENER ( WARN ) : replication: Can't contact LDAP server: retrying 28.03.17 09:04:54.548 LISTENER ( WARN ) : cups-printers: info: univention-lpadmin -u allow:all -o auth-info-required=none -p printer5 -v socket://192.168.0.80:9100 -E Job for samba.service failed. See 'systemctl status samba.service' and 'journalctl -xn' for details. invoke-rc.d: initscript samba, action "reload" failed. 28.03.17 09:05:25.894 LISTENER ( PROCESS ) : updating 'cn=printer6,cn=printers,dc=ar41pt1,dc=qa' command a Job for samba.service failed. See 'systemctl status samba.service' and 'journalctl -xn' for details. invoke-rc.d: initscript samba, action "reload" failed. 28.03.17 09:20:53.625 LISTENER ( PROCESS ) : updating 'cn={31b2f340-016d-11d2-945f-00c04fb984f9},cn=policies,cn=system,dc=ar41pt1,dc=qa' command m 28.03.17 09:20:53.760 LISTENER ( WARN ) : replication: Can't contact LDAP server: retrying 28.03.17 09:21:46.281 LISTENER ( PROCESS ) : updating 'cn={31b2f340-016d-11d2-945f-00c04fb984f9},cn=policies,cn=system,dc=ar41pt1,dc=qa' command m 28.03.17 09:29:23.021 LISTENER ( PROCESS ) : updating 'cn=printer1,cn=printers,dc=ar41pt1,dc=qa' command d 28.03.17 09:29:23.049 LISTENER ( WARN ) : replication: Can't contact LDAP server: retrying 28.03.17 09:29:23.454 LISTENER ( WARN ) : cups-printers: info: univention-lpadmin -x printer1 Job for samba.service failed. See 'systemctl status samba.service' and 'journalctl -xn' for details. invoke-rc.d: initscript samba, action "reload" failed. 28.03.17 09:29:24.402 LISTENER ( PROCESS ) : updating 'cn=printer2,cn=printers,dc=ar41pt1,dc=qa' command d 28.03.17 09:29:24.430 LISTENER ( PROCESS ) : updating 'cn=printer3,cn=printers,dc=ar41pt1,dc=qa' command d 28.03.17 09:29:24.471 LISTENER ( WARN ) : cups-printers: info: univention-lpadmin -x printer3 Job for samba.service failed. See 'systemctl status samba.service' and 'journalctl -xn' for details. invoke-rc.d: initscript samba, action "reload" failed. 28.03.17 09:29:25.257 LISTENER ( PROCESS ) : updating 'cn=printer4,cn=printers,dc=ar41pt1,dc=qa' command d 28.03.17 09:29:25.273 LISTENER ( PROCESS ) : updating 'cn=printer5,cn=printers,dc=ar41pt1,dc=qa' command d 28.03.17 09:29:25.321 LISTENER ( WARN ) : cups-printers: info: univention-lpadmin -x printer5 Job for samba.service failed. See 'systemctl status samba.service' and 'journalctl -xn' for details. invoke-rc.d: initscript samba, action "reload" failed. 28.03.17 09:29:26.088 LISTENER ( PROCESS ) : updating 'cn=printer6,cn=printers,dc=ar41pt1,dc=qa' command d Job for samba.service failed. See 'systemctl status samba.service' and 'journalctl -xn' for details. invoke-rc.d: initscript samba, action "reload" failed. 28.03.17 09:30:25.607 LISTENER ( PROCESS ) : updating 'cn=printer7,cn=printers,dc=ar41pt1,dc=qa' command a ============================================================================
root@slave102:~# service samba status ● samba.service - LSB: ensure Samba daemons are started (nmbd and smbd) Loaded: loaded (/etc/init.d/samba) Active: inactive (dead) Mär 28 08:33:35 slave102 systemd[1]: Unit samba.service cannot be reloaded because it is inactive. Mär 28 08:34:16 slave102 systemd[1]: Unit samba.service cannot be reloaded because it is inactive. Mär 28 09:04:55 slave102 systemd[1]: Unit samba.service cannot be reloaded because it is inactive. Mär 28 09:05:41 slave102 systemd[1]: Unit samba.service cannot be reloaded because it is inactive. Mär 28 09:29:24 slave102 systemd[1]: Unit samba.service cannot be reloaded because it is inactive. Mär 28 09:29:25 slave102 systemd[1]: Unit samba.service cannot be reloaded because it is inactive. Mär 28 09:29:26 slave102 systemd[1]: Unit samba.service cannot be reloaded because it is inactive. Mär 28 09:29:41 slave102 systemd[1]: Unit samba.service cannot be reloaded because it is inactive. Mär 28 09:30:26 slave102 systemd[1]: Unit samba.service cannot be reloaded because it is inactive. Mär 28 09:31:07 slave102 systemd[1]: Unit samba.service cannot be reloaded because it is inactive. root@slave102:~# service samba reload Job for samba.service failed. See 'systemctl status samba.service' and 'journalctl -xn' for details.
I've backported the systemd specific packaging changes from the Debian stretch package: 04_systemd.patch. The package is rebuilding, let's see.
With the Debian systemd service definitions the process structure is different: With the sysv-init the main samba process started smbd and winbindd as children. With the Debian systemd services smbd and winbindd are started separately. Updating the packages in UCS 4.2 RC leaves winbind stopped, even though it should be started in winbind.postinst. journalctl says: =============================================================================== Mär 27 21:11:02 backup101 systemd[1]: Starting Samba Winbind Daemon... -- Subject: Unit winbind.service has begun with start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit winbind.service has begun starting up. Mär 27 21:11:02 backup101 systemd[1]: winbind.service: Supervising process 17839 which is not our child. We'll most likely not notice when it exits. Mär 27 21:11:02 backup101 systemd[1]: winbind.service: Supervising process 17716 which is not our child. We'll most likely not notice when it exits. Mär 27 21:12:32 backup101 systemd[1]: winbind.service start operation timed out. Terminating. Mär 27 21:12:32 backup101 systemd[1]: Failed to start Samba Winbind Daemon. -- Subject: Unit winbind.service has failed -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit winbind.service has failed. -- -- The result is failed. Mär 27 21:12:32 backup101 systemd[1]: Unit winbind.service entered failed state. Mär 27 21:12:36 backup101 systemd[1]: Reloading. ===============================================================================
log.winbind says: ============================================================================ [2017/03/27 21:10:51.622774, 0, pid=17716] ../lib/util/become_daemon.c:124(daemon_ready) STATUS=daemon 'winbindd' finished starting up and ready to serve connections [2017/03/27 21:11:02.403106, 0, pid=17839] ../lib/util/pidfile.c:104(pidfile_create) ERROR: winbindd is already running. File /var/run/samba/winbindd.pid exists and process id 17716 is running. ============================================================================ Hmm, according to journalctl it was systemd that started 17839 and 17716 ...
univention-upgrade now fails: ============================================================================ winbind (2:4.6.1-1A~4.2.0.201703282145) wird eingerichtet ... Job for winbind.service failed. See 'systemctl status winbind.service' and 'journalctl -xn' for details. invoke-rc.d: initscript winbind, action "start" failed. dpkg: Fehler beim Bearbeiten des Paketes winbind (--configure): Unterprozess installiertes post-installation-Skript gab den Fehlerwert 1 zurück root@s122:~# systemctl status winbind.service -l ● winbind.service - Samba Winbind Daemon Loaded: loaded (/lib/systemd/system/winbind.service; enabled) Active: failed (Result: timeout) since Mi 2017-03-29 14:07:58 CEST; 2min 41s ago Docs: man:winbindd(8) man:samba(7) man:smb.conf(5) Main PID: 5470 Status: "Starting process..." Mär 29 14:06:28 s122 systemd[1]: winbind.service: Supervising process 5586 which is not our child. We'll most likely not notice when it exits. Mär 29 14:06:28 s122 systemd[1]: winbind.service: Supervising process 5470 which is not our child. We'll most likely not notice when it exits. Mär 29 14:07:58 s122 systemd[1]: winbind.service start operation timed out. Terminating. Mär 29 14:07:58 s122 systemd[1]: Failed to start Samba Winbind Daemon. Mär 29 14:07:58 s122 systemd[1]: Unit winbind.service entered failed state. ============================================================================ root@s122:~# systemctl status samba-ad-dc.service ● samba-ad-dc.service - Samba AD Daemon Loaded: loaded (/lib/systemd/system/samba-ad-dc.service; enabled) Active: active (running) since Mi 2017-03-29 14:06:17 CEST; 6min ago Docs: man:samba(8) man:samba(7) man:smb.conf(5) Main PID: 5459 (samba) Status: "winbindd: ready to serve connections..." CGroup: /system.slice/samba-ad-dc.service ├─5459 /usr/sbin/samba ├─5461 /usr/sbin/samba ├─5463 /usr/sbin/samba ├─5464 /usr/sbin/samba ├─5465 /usr/sbin/samba ├─5466 /usr/sbin/samba ├─5468 /usr/sbin/samba ├─5469 /usr/sbin/samba └─5471 /usr/sbin/samba Mär 29 14:06:17 s122 systemd[1]: Started Samba AD Daemon. ============================================================================ root@s122:~# grep winbind /var/log/dpkg.log | less 2017-03-29 14:05:34 upgrade winbind:amd64 2:4.6.1-1A~4.2.0.201703231239 2:4.6.1-1A~4.2.0.201703282145 2017-03-29 14:05:34 status half-configured winbind:amd64 2:4.6.1-1A~4.2.0.201703231239 2017-03-29 14:05:34 status unpacked winbind:amd64 2:4.6.1-1A~4.2.0.201703231239 2017-03-29 14:05:34 status half-installed winbind:amd64 2:4.6.1-1A~4.2.0.201703231239 2017-03-29 14:05:34 status half-installed winbind:amd64 2:4.6.1-1A~4.2.0.201703231239 2017-03-29 14:05:35 status unpacked winbind:amd64 2:4.6.1-1A~4.2.0.201703282145 2017-03-29 14:05:35 status unpacked winbind:amd64 2:4.6.1-1A~4.2.0.201703282145 2017-03-29 14:06:28 configure winbind:amd64 2:4.6.1-1A~4.2.0.201703282145 <keine> 2017-03-29 14:06:28 status unpacked winbind:amd64 2:4.6.1-1A~4.2.0.201703282145 2017-03-29 14:06:28 status unpacked winbind:amd64 2:4.6.1-1A~4.2.0.201703282145 2017-03-29 14:06:28 status unpacked winbind:amd64 2:4.6.1-1A~4.2.0.201703282145 2017-03-29 14:06:28 status unpacked winbind:amd64 2:4.6.1-1A~4.2.0.201703282145 2017-03-29 14:06:28 status unpacked winbind:amd64 2:4.6.1-1A~4.2.0.201703282145 2017-03-29 14:06:28 status half-configured winbind:amd64 2:4.6.1-1A~4.2.0.201703282145 ============================================================================ root@s122:~# less /var/log/samba/log.winbindd [2017/03/29 13:48:22.781080, 0, pid=1091] ../lib/util/become_daemon.c:124(daemon_ready) STATUS=daemon 'winbindd' finished starting up and ready to serve connections [2017/03/29 14:06:18.057172, 0, pid=5470] ../source3/winbindd/winbindd_cache.c:3171(initialize_winbindd_cache) initialize_winbindd_cache: clearing cache and re-creating with version number 2 [2017/03/29 14:06:18.468918, 0, pid=5470] ../lib/util/become_daemon.c:124(daemon_ready) STATUS=daemon 'winbindd' finished starting up and ready to serve connections [2017/03/29 14:06:28.935173, 0, pid=5586] ../lib/util/pidfile.c:104(pidfile_create) ERROR: winbindd is already running. File /var/run/samba/winbindd.pid exists and process id 5470 is running.
BTW: I can run "systemctl start winbind.service" after the failed upgrade, and it'll start (and I can fix the upgrade).
Picking up the Debian stretch systemd changes and adjusting them to our product is too intrusive at this stage, given that 1. the samba package is used in univention-samba4 as well as in univention-samba configurations. 2. univention-samba4 configures samba to start smbd and winbindd on it's own (which is currently handled by the sysv style init scripts) I've reverted them, so ignore everything between Comment 3 and this one. I guess the issue may have been triggered because I have run /etc/init.d/samba restart manually during the tests because the printer shares were not appearing in printmanagement.msc. I hope that the following changes help to avoid this problem: r17440: Avoid accidental smbd starts due to testparm errors r17441: Skip systemd for samba/smbd reload r17442: Revert systemd specific adjustments r17443: systemd specific adjustments from upstream Samba Package: samba Version: 2:4.6.1-1A~4.2.0.201703291823 Branch: ucs_4.2-0
Optimism is a virtue, but the issue is not fixed: ============================================================================ 27.03.17 21:48:35.768 LISTENER ( PROCESS ) : updating 'cn=printer1,cn=printers,dc=ar41pt1,dc=qa' command a 27.03.17 21:48:35.795 LISTENER ( WARN ) : cups-printers: info: univention-lpadmin -u allow:all -o auth-info-required=none -p printer1 -v socket://192.168.0.80:9100 -E Job for samba.service failed. See 'systemctl status samba.service' and 'journalctl -xn' for details. invoke-rc.d: initscript samba, action "reload" failed. 27.03.17 21:49:02.363 LISTENER ( PROCESS ) : updating 'cn=printer2,cn=printers,dc=ar41pt1,dc=qa' command a 27.03.17 21:49:02.385 LISTENER ( WARN ) : cups-printers: info: univention-lpadmin -u allow:all -o auth-info-required=none -p printer2 -v socket://192.168.0.80:9100 -E Job for samba.service failed. See 'systemctl status samba.service' and 'journalctl -xn' for details. invoke-rc.d: initscript samba, action "reload" failed. 27.03.17 21:49:46.366 LISTENER ( PROCESS ) : updating 'cn=printer3,cn=printers,dc=ar41pt1,dc=qa' command a 27.03.17 21:49:46.390 LISTENER ( WARN ) : cups-printers: info: univention-lpadmin -u allow:all -o auth-info-required=none -p printer3 -v socket://192.168.0.80:9100 -E Job for samba.service failed. See 'systemctl status samba.service' and 'journalctl -xn' for details. invoke-rc.d: initscript samba, action "reload" failed. 27.03.17 21:50:24.385 LISTENER ( PROCESS ) : updating 'cn=drucker1,cn=printers,dc=ar41pt1,dc=qa' command a Job for samba.service failed. See 'systemctl status samba.service' and 'journalctl -xn' for details. invoke-rc.d: initscript samba, action "reload" failed. 27.03.17 21:51:22.018 LISTENER ( PROCESS ) : updating 'cn=drucker2,cn=printers,dc=ar41pt1,dc=qa' command a Job for samba.service failed. See 'systemctl status samba.service' and 'journalctl -xn' for details. invoke-rc.d: initscript samba, action "reload" failed. 27.03.17 21:51:48.586 LISTENER ( PROCESS ) : updating 'cn=drucker3,cn=printers,dc=ar41pt1,dc=qa' command a Job for samba.service failed. See 'systemctl status samba.service' and 'journalctl -xn' for details. invoke-rc.d: initscript samba, action "reload" failed. ============================================================================
Ok, found it, the cups-printers.py listener runs invoke-rc.d samba reload and that fails: ================================================ root@backup101:~# invoke-rc.d samba reload Job for samba.service failed. See 'systemctl status samba.service' and 'journalctl -xn' for details. invoke-rc.d: initscript samba, action "reload" failed. root@backup101:~# /etc/init.d/samba reload Reloading smbd. ================================================ I've adjusted all occurances of this: r78479 services/univention-printserver r78480 services/univention-samba r78481 services/univention-ldb-modules r78482 management/univention-ldap r78483 test/ucs-test Packages are rebuilding.
/etc/init.d/samba reload doesn't work with uinvention-samba. I'll change it to /etc/init.d/smbd reload once svn works again.
Ok, works on memberservers as well, I guess I just tested on a messed up system in the end yesterday, so ignore Comment 10. =========================================================================== 27.03.17 23:04:09.412 LISTENER ( PROCESS ) : updating 'cn=drucker4,cn=printers,dc=ar41pt1,dc=qa' command a 27.03.17 23:04:09.421 LISTENER ( WARN ) : cups-printers: info: univention-lpadmin -u allow:all -o auth-info-required=none -p drucker4 -v socket://192.168.0.80:9100 -E Reloading samba configuration (via systemctl): samba.service. =========================================================================== I've also needlessly adjusted a "service samba restart" in a dead postinst code branch in r78492 univention-samba4/debian/univention-samba4.postinst. Doesn't hurt, won't revert.
OK - univention-printserver OK - univention-samba OK - univention-ldb-modules OK - univention-ldap OK - ucs-test OK - no more invoke-rc.d samba ... in svn OK - no more service samba ... in svn
UCS 4.2 has been released: https://docs.software-univention.de/release-notes-4.2-0-en.html https://docs.software-univention.de/release-notes-4.2-0-de.html If this error occurs again, please use "Clone This Bug".