Bug 44118 - New/deleted Samba printer shares not visible because invoke-rc.d samba fails with systemd
New/deleted Samba printer shares not visible because invoke-rc.d samba fails ...
Status: CLOSED FIXED
Product: UCS
Classification: Unclassified
Component: Samba
UCS 4.2
Other Linux
: P1 major (vote)
: UCS 4.2
Assigned To: Arvid Requate
Felix Botner
:
Depends on:
Blocks: 42057 44153
  Show dependency treegraph
 
Reported: 2017-03-28 19:59 CEST by Arvid Requate
Modified: 2017-04-04 18:28 CEST (History)
3 users (show)

See Also:
What kind of report is it?: Development Internal
What type of bug is this?: ---
Who will be affected by this bug?: ---
How will those affected feel about the bug?: ---
User Pain:
Enterprise Customer affected?:
School Customer affected?:
ISV affected?:
Waiting Support:
Flags outvoted (downgraded) after PO Review:
Ticket number:
Bug group (optional):
Max CVSS v3 score:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Arvid Requate univentionstaff 2017-03-28 19:59:32 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
============================================================================
Comment 1 Arvid Requate univentionstaff 2017-03-28 20:00:47 CEST
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.
Comment 2 Arvid Requate univentionstaff 2017-03-28 20:25:31 CEST
I've backported the systemd specific packaging changes from the Debian stretch package: 04_systemd.patch. The package is rebuilding, let's see.
Comment 3 Arvid Requate univentionstaff 2017-03-29 00:00:45 CEST
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.
===============================================================================
Comment 4 Arvid Requate univentionstaff 2017-03-29 00:05:41 CEST
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 ...
Comment 5 Daniel Tröder univentionstaff 2017-03-29 14:15:55 CEST
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.
Comment 6 Daniel Tröder univentionstaff 2017-03-29 14:17:38 CEST
BTW: I can run "systemctl start winbind.service" after the failed upgrade, and it'll start (and I can fix the upgrade).
Comment 7 Arvid Requate univentionstaff 2017-03-29 19:21:15 CEST
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
Comment 8 Arvid Requate univentionstaff 2017-03-29 19:48:08 CEST
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.
============================================================================
Comment 9 Arvid Requate univentionstaff 2017-03-29 20:17:29 CEST
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.
Comment 10 Arvid Requate univentionstaff 2017-03-29 20:26:14 CEST
/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.
Comment 11 Arvid Requate univentionstaff 2017-03-30 12:36:58 CEST
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.
Comment 12 Felix Botner univentionstaff 2017-04-04 12:46:43 CEST
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
Comment 13 Stefan Gohmann univentionstaff 2017-04-04 18:28:21 CEST
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".