Nicolas Zuber
2018-Feb-01 09:57 UTC
[Samba] Upgrading a ctdb cluster: samba not listening on TCP port 445
Hi all, I try to update two clustered samba file servers. Right now samba 4.7.0 with ctdb is running on both of them. To update samba I stopped ctdb on one of the servers, and compiled and installed samba 4.7.1 with: ./configure --with-cluster-support --with-shared-modules=idmap_tdb2,idmap_ad,vfs_glusterfs --with-systemd Trying to start ctdb on the updated server fails with " ctdb-eventd[19790]: 50.samba: samba not listening on TCP port 445" in the ctdb.log. Trying to update directly to 4.7.3 or 4.7.4 shows the same error message. Removing the "clustered = yes" from the smb.conf file and starting smbd by hand works fine and the smbd process listens on port 445. Downgrading again to 4.7.0 worked without any problems and ctdb and smbd are running again without any problems, but this is only a temporary solution. Any help in how to debug this problem will be appreciated. Best regards, Nicolas ctdb.conf # Do NOT run CTDB without a recovery lock file unless you know exactly # what you are doing. CTDB_RECOVERY_LOCK=/var/run/gluster/shared_storage/ctdb/lockfile # List of public addresses for providing NAS services. No default. CTDB_PUBLIC_ADDRESSES=/var/run/gluster/shared_storage/ctdb/public_addresses # List of nodes in the cluster. CTDB_NODES=/var/run/gluster/shared_storage/ctdb/nodes # What services should CTDB manage? Default is none. CTDB_MANAGES_SAMBA=yes CTDB_MANAGES_WINBIND=yes CTDB_MANAGES_NFS=no CTDB_SAMBA_SKIP_SHARE_CHECK=yes CTDB_SERVICE_NMB=nmb # Default is to use the log file below instead of syslog. CTDB_LOGGING=file:/var/log/ctdb.log CTDB_DEBUGLEVEL=NOTICE testparm output excluding the shared folders: netbios name = FILE realm = PI5.MYDOMAIN workgroup = PI5 log file = /var/log/samba/tmp/samba_%I.log clustering = Yes registry shares = Yes load printers = No security = ADS deadtime = 10 template homedir = /gluster/mnt/users/%U template shell = /bin/bash winbind refresh tickets = Yes winbind use default domain = Yes idmap config pi5:range = 20000-1999999 idmap config pi5:backend = rid idmap config *:range = 10000-19999 idmap config * : backend = tdb store dos attributes = Yes map acl inherit = Yes inherit acls = Yes vfs objects = acl_xattr
Martin Schwenke
2018-Feb-01 11:04 UTC
[Samba] Upgrading a ctdb cluster: samba not listening on TCP port 445
Hi Nicolas, On Thu, 1 Feb 2018 10:57:59 +0100, Nicolas Zuber via samba <samba at lists.samba.org> wrote:> I try to update two clustered samba file servers. Right now samba 4.7.0 > with ctdb is running on both of them. To update samba I stopped ctdb on > one of the servers, and compiled and installed samba 4.7.1 with: > > ./configure --with-cluster-support --with-shared-modules=idmap_tdb2,idmap_ad,vfs_glusterfs --with-systemd > > Trying to start ctdb on the updated server fails with " > ctdb-eventd[19790]: 50.samba: samba not listening on TCP port 445" in > the ctdb.log. Trying to update directly to 4.7.3 or 4.7.4 shows the same > error message. > > Removing the "clustered = yes" from the smb.conf file and starting smbd > by hand works fine and the smbd process listens on port 445. Downgrading > again to 4.7.0 worked without any problems and ctdb and smbd are running > again without any problems, but this is only a temporary solution. > > Any help in how to debug this problem will be appreciated.The error about samba not listening is coming from CTDB's "monitor" event. Before this, CTDB's "startup" event would have attempted to start smbd. Can you find any evidence in log.smbd (or similar) about smbd failing somewhere? If there are no messages from smbd then I wonder if systemd might be getting in the way and not even trying to start smbd? Does journalctl (with whatever the standard options are) tell you anything useful? Thanks... peace & happiness, martin
Nicolas Zuber
2018-Feb-01 12:11 UTC
[Samba] Upgrading a ctdb cluster: samba not listening on TCP port 445
Am Do 01.02.2018 um 12:04 schrieb Martin Schwenke:> Hi Nicolas, > > On Thu, 1 Feb 2018 10:57:59 +0100, Nicolas Zuber via samba > <samba at lists.samba.org> wrote: > >> I try to update two clustered samba file servers. Right now samba 4.7.0 >> with ctdb is running on both of them. To update samba I stopped ctdb on >> one of the servers, and compiled and installed samba 4.7.1 with: >> >> ./configure --with-cluster-support --with-shared-modules=idmap_tdb2,idmap_ad,vfs_glusterfs --with-systemd >> >> Trying to start ctdb on the updated server fails with " >> ctdb-eventd[19790]: 50.samba: samba not listening on TCP port 445" in >> the ctdb.log. Trying to update directly to 4.7.3 or 4.7.4 shows the same >> error message. >> >> Removing the "clustered = yes" from the smb.conf file and starting smbd >> by hand works fine and the smbd process listens on port 445. Downgrading >> again to 4.7.0 worked without any problems and ctdb and smbd are running >> again without any problems, but this is only a temporary solution. >> >> Any help in how to debug this problem will be appreciated. > The error about samba not listening is coming from CTDB's "monitor" > event. Before this, CTDB's "startup" event would have attempted to > start smbd. Can you find any evidence in log.smbd (or similar) about > smbd failing somewhere? > > If there are no messages from smbd then I wonder if systemd might be > getting in the way and not even trying to start smbd? Does journalctl > (with whatever the standard options are) tell you anything useful? > > Thanks... > > peace & happiness, > martinHi Martin, the samba log is spammed with: [2018/02/01 12:22:51.965183, 5] ../lib/dbwrap/dbwrap.c:160(dbwrap_check_lock_order) check lock order 3 for g_lock.tdb [2018/02/01 12:22:51.966145, 5] ../lib/dbwrap/dbwrap.c:128(dbwrap_lock_order_state_destructor) release lock order 3 for g_lock.tdb after starting the ctdb process and setting the log level to 5. If I set the log level to 2 it shows that winbind and nmbd starts successfully and no complains about a failed smbd process (see log below). Checking with journal -lu smb shows no errors when starting ctdb: "systemd[1]: Starting Samba SMB Daemon..." and "systemd[1]: Started Samba SMB Daemon". The systemd smb.service file looks like this: [Unit] Description=Samba SMB Daemon After=syslog.target network.target nmb.service winbind.service [Service] Environment="PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/usr/local/samba/bin/:/usr/local/samba/sbin/" Type=forking ExecStart=/usr/local/samba/sbin/smbd PIDFile=/usr/local/samba/var/run/smbd.pid [Install] WantedBy=multi-user.target As far as I can see, the smbd process seems to start successfully and I have no idea why it is not listening on the port. Thanks, Nicolas samba.log: [2018/02/01 12:42:52.524438, 2] ../source3/lib/interface.c:345(add_interface) added interface eno1 ip=172.1.1.4 bcast=172.1.255.255 netmask=255.255.0.0 [2018/02/01 12:42:52.524477, 2] ../source3/lib/interface.c:345(add_interface) added interface enp4s0f1 ip=172.16.1.4 bcast=172.16.255.255 netmask=255.255.0.0 [2018/02/01 12:42:52.524493, 2] ../source3/lib/interface.c:345(add_interface) added interface enp4s0f1 ip=172.16.1.55 bcast=172.16.255.255 netmask=255.255.0.0 [2018/02/01 12:42:52.524506, 2] ../source3/lib/interface.c:345(add_interface) added interface enp4s0f0 ip=172.17.1.4 bcast=172.17.255.255 netmask=255.255.0.0 [2018/02/01 12:42:52.524520, 2] ../source3/lib/interface.c:345(add_interface) added interface virbr0 ip=192.168.122.1 bcast=192.168.122.255 netmask=255.255.255.0 [2018/02/01 12:42:52.525029, 2] ../source3/lib/interface.c:345(add_interface) added interface eno1 ip=172.1.1.4 bcast=172.1.255.255 netmask=255.255.0.0 [2018/02/01 12:42:52.525047, 2] ../source3/lib/interface.c:345(add_interface) added interface enp4s0f1 ip=172.16.1.4 bcast=172.16.255.255 netmask=255.255.0.0 [2018/02/01 12:42:52.525061, 2] ../source3/lib/interface.c:345(add_interface) added interface enp4s0f1 ip=172.16.1.55 bcast=172.16.255.255 netmask=255.255.0.0 [2018/02/01 12:42:52.525074, 2] ../source3/lib/interface.c:345(add_interface) added interface enp4s0f0 ip=172.17.1.4 bcast=172.17.255.255 netmask=255.255.0.0 [2018/02/01 12:42:52.525088, 2] ../source3/lib/interface.c:345(add_interface) added interface virbr0 ip=192.168.122.1 bcast=192.168.122.255 netmask=255.255.255.0 [2018/02/01 12:42:52.527622, 0] ../source3/winbindd/winbindd_cache.c:3170(initialize_winbindd_cache) initialize_winbindd_cache: clearing cache and re-creating with version number 2 [2018/02/01 12:42:52.529264, 2] ../source3/winbindd/winbindd_util.c:283(add_trusted_domain_from_tdc) Added domain BUILTIN (null) S-1-5-32 [2018/02/01 12:42:52.529360, 2] ../source3/winbindd/winbindd_util.c:283(add_trusted_domain_from_tdc) Added domain FILE (null) SID [2018/02/01 12:42:52.529432, 2] ../source3/winbindd/winbindd_util.c:283(add_trusted_domain_from_tdc) Added domain PI5 MYDOMAIN SID [2018/02/01 12:42:52.530113, 0] ../lib/util/become_daemon.c:124(daemon_ready) STATUS=daemon 'winbindd' finished starting up and ready to serve connections [2018/02/01 12:42:52.701886, 2] ../source3/lib/interface.c:345(add_interface) added interface eno1 ip=172.1.1.4 bcast=172.1.255.255 netmask=255.255.0.0 [2018/02/01 12:42:52.701925, 2] ../source3/lib/interface.c:345(add_interface) added interface enp4s0f1 ip=172.16.1.4 bcast=172.16.255.255 netmask=255.255.0.0 [2018/02/01 12:42:52.701940, 2] ../source3/lib/interface.c:345(add_interface) added interface enp4s0f1 ip=172.16.1.55 bcast=172.16.255.255 netmask=255.255.0.0 [2018/02/01 12:42:52.701954, 2] ../source3/lib/interface.c:345(add_interface) added interface enp4s0f0 ip=172.17.1.4 bcast=172.17.255.255 netmask=255.255.0.0 [2018/02/01 12:42:52.701972, 2] ../source3/lib/interface.c:345(add_interface) added interface virbr0 ip=192.168.122.1 bcast=192.168.122.255 netmask=255.255.255.0 [2018/02/01 12:42:52.702123, 2] ../source3/nmbd/nmbd_subnetdb.c:180(make_subnet) making subnet name:172.17.1.4 Broadcast address:172.17.255.255 Subnet mask:255.255.0.0 [2018/02/01 12:42:52.702383, 2] ../source3/nmbd/nmbd_subnetdb.c:180(make_subnet) making subnet name:172.16.1.55 Broadcast address:172.16.255.255 Subnet mask:255.255.0.0 [2018/02/01 12:42:52.702515, 2] ../source3/nmbd/nmbd_subnetdb.c:180(make_subnet) making subnet name:172.16.1.4 Broadcast address:172.16.255.255 Subnet mask:255.255.0.0 [2018/02/01 12:42:52.702661, 2] ../source3/nmbd/nmbd_subnetdb.c:180(make_subnet) making subnet name:172.1.1.4 Broadcast address:172.1.255.255 Subnet mask:255.255.0.0 [2018/02/01 12:42:52.702690, 2] ../source3/nmbd/nmbd_subnetdb.c:180(make_subnet) making subnet name:UNICAST_SUBNET Broadcast address:0.0.0.0 Subnet mask:0.0.0.0 [2018/02/01 12:42:52.702717, 2] ../source3/nmbd/nmbd_subnetdb.c:180(make_subnet) making subnet name:REMOTE_BROADCAST_SUBNET Broadcast address:0.0.0.0 Subnet mask:0.0.0.0 [2018/02/01 12:42:52.702771, 2] ../source3/nmbd/nmbd_lmhosts.c:43(load_lmhosts_file) load_lmhosts_file: Can't open lmhosts file /usr/local/samba/etc/lmhosts. Error was No such file or directory [2018/02/01 12:42:52.703801, 0] ../lib/util/become_daemon.c:124(daemon_ready) STATUS=daemon 'nmbd' finished starting up and ready to serve connections [2018/02/01 12:42:52.707865, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) query_name_response: Multiple (2) responses received for a query on subnet 172.16.1.4 for name PI5<1d>. This response was from IP 172.16.1.57, reporting an IP address of 172.16.1.57. [2018/02/01 12:42:52.708061, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) query_name_response: Multiple (2) responses received for a query on subnet 172.16.1.55 for name PI5<1d>. This response was from IP 172.16.1.57, reporting an IP address of 172.16.1.57. [2018/02/01 12:42:52.710885, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) query_name_response: Multiple (2) responses received for a query on subnet 172.17.1.4 for name PI5<1d>. This response was from IP 172.17.1.5, reporting an IP address of 172.17.1.5. [2018/02/01 12:42:52.724314, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) query_name_response: Multiple (2) responses received for a query on subnet 172.1.1.4 for name PI5<1d>. This response was from IP 172.1.1.3, reporting an IP address of 172.1.1.3. [2018/02/01 12:42:52.760083, 2] ../source3/lib/interface.c:345(add_interface) added interface eno1 ip=172.1.1.4 bcast=172.1.255.255 netmask=255.255.0.0 [2018/02/01 12:42:52.760125, 2] ../source3/lib/interface.c:345(add_interface) added interface enp4s0f1 ip=172.16.1.4 bcast=172.16.255.255 netmask=255.255.0.0 [2018/02/01 12:42:52.760193, 2] ../source3/lib/interface.c:345(add_interface) added interface enp4s0f1 ip=172.16.1.55 bcast=172.16.255.255 netmask=255.255.0.0 [2018/02/01 12:42:52.760208, 2] ../source3/lib/interface.c:345(add_interface) added interface enp4s0f0 ip=172.17.1.4 bcast=172.17.255.255 netmask=255.255.0.0 [2018/02/01 12:42:52.760221, 2] ../source3/lib/interface.c:345(add_interface) added interface virbr0 ip=192.168.122.1 bcast=192.168.122.255 netmask=255.255.255.0 [2018/02/01 12:42:52.760474, 1] ../source3/profile/profile_dummy.c:30(set_profile_level) INFO: Profiling support unavailable in this build. [2018/02/01 12:42:53.510134, 0] ../source3/nmbd/nmbd_mynames.c:36(my_name_register_failed) my_name_register_failed: Failed to register my name FILE<20> on subnet 172.17.1.4. [2018/02/01 12:42:53.510179, 0] ../source3/nmbd/nmbd_namelistdb.c:320(standard_fail_register) standard_fail_register: Failed to register/refresh name FILE<20> on subnet 172.17.1.4 [2018/02/01 12:42:53.510201, 0] ../source3/nmbd/nmbd_mynames.c:36(my_name_register_failed) my_name_register_failed: Failed to register my name FILE<03> on subnet 172.17.1.4. [2018/02/01 12:42:53.510222, 0] ../source3/nmbd/nmbd_namelistdb.c:320(standard_fail_register) standard_fail_register: Failed to register/refresh name FILE<03> on subnet 172.17.1.4 [2018/02/01 12:42:53.510245, 0] ../source3/nmbd/nmbd_mynames.c:36(my_name_register_failed) my_name_register_failed: Failed to register my name FILE<00> on subnet 172.17.1.4. [2018/02/01 12:42:53.510266, 0] ../source3/nmbd/nmbd_namelistdb.c:320(standard_fail_register) standard_fail_register: Failed to register/refresh name FILE<00> on subnet 172.17.1.4 [2018/02/01 12:42:56.818658, 2] ../source3/nmbd/nmbd_elections.c:111(check_for_master_browser_fail) check_for_master_browser_fail: Forcing election on workgroup PI5 subnet 192.168.122.1 [2018/02/01 12:42:59.821489, 2] ../source3/nmbd/nmbd_elections.c:41(send_election_dgram) send_election_dgram: Sending election packet for workgroup PI5 on subnet 192.168.122.1 [2018/02/01 12:43:01.823528, 2] ../source3/nmbd/nmbd_elections.c:41(send_election_dgram) send_election_dgram: Sending election packet for workgroup PI5 on subnet 192.168.122.1 [2018/02/01 12:43:03.825540, 2] ../source3/nmbd/nmbd_elections.c:41(send_election_dgram) send_election_dgram: Sending election packet for workgroup PI5 on subnet 192.168.122.1 [2018/02/01 12:43:05.827617, 2] ../source3/nmbd/nmbd_elections.c:41(send_election_dgram) send_election_dgram: Sending election packet for workgroup PI5 on subnet 192.168.122.1 [2018/02/01 12:43:07.121240, 2] ../source3/nmbd/nmbd_elections.c:41(send_election_dgram) send_election_dgram: Sending election packet for workgroup PI5 on subnet 192.168.122.1 [2018/02/01 12:43:07.121288, 2] ../source3/nmbd/nmbd_elections.c:201(run_elections) run_elections: >>> Won election for workgroup PI5 on subnet 192.168.122.1 <<< [2018/02/01 12:43:07.121311, 2] ../source3/nmbd/nmbd_become_lmb.c:538(become_local_master_browser) become_local_master_browser: Starting to become a master browser for workgroup PI5 on subnet 192.168.122.1 [2018/02/01 12:43:16.647156, 0] ../source3/nmbd/nmbd_become_lmb.c:397(become_local_master_stage2) ***** Samba name server FILE is now a local master browser for workgroup PI5 on subnet 192.168.122.1 ***** -- Nicolas Zuber (MSc) Universität Stuttgart 5. Physikalisches Institut Pfaffenwaldring 57 D-70569 Stuttgart Tel.: +49 (0)711 685 64977