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
Martin Schwenke
2018-Feb-02 09:27 UTC
[Samba] Upgrading a ctdb cluster: samba not listening on TCP port 445
On Thu, 1 Feb 2018 13:11:58 +0100, Nicolas Zuber via samba <samba at lists.samba.org> wrote:> 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).Now the guesses get more esoteric. :-) What do you see if you run "ss -tlnp src :445" as root? I see smbd listening on both IPv4 and IPv6: LISTEN 0 50 *:445 *:* users:(("smbd",pid=2315,fd=36)) LISTEN 0 50 :::445 :::* users:(("smbd",pid=2315,fd=34)) If you see smbd listening on port 445 then what happens if you run: # ctdb checktcpport 445 Failed to bind to TCP port 445 It should fail to bind, which is what CTDB's monitor event looks for when testing to see smbd is listing on the port. peace & happiness, martin
Nicolas Zuber
2018-Feb-05 12:43 UTC
[Samba] Upgrading a ctdb cluster: samba not listening on TCP port 445
Am Fr 02.02.2018 um 10:27 schrieb Martin Schwenke:> On Thu, 1 Feb 2018 13:11:58 +0100, Nicolas Zuber via samba > <samba at lists.samba.org> wrote: > >> 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). > > Now the guesses get more esoteric. :-) > > What do you see if you run "ss -tlnp src :445" as root? > > I see smbd listening on both IPv4 and IPv6: > > LISTEN 0 50 > *:445 *:* > users:(("smbd",pid=2315,fd=36)) LISTEN 0 > 50 :::445 :::* > users:(("smbd",pid=2315,fd=34)) > > If you see smbd listening on port 445 then what happens if you run: > > # ctdb checktcpport 445 > Failed to bind to TCP port 445 > > It should fail to bind, which is what CTDB's monitor event looks for > when testing to see smbd is listing on the port. > > peace & happiness, > martin >Hello Martin, Thank you very much for your help. When using the commands you suggested, it showed that samba was not listing on port 445 and ctdb checktcpport 445 did not fail. Somehow the upgrade process to 4.7.1 worked after several tries and I tried to figure out why. During the investigation I found out that the smbd process failed after one minute (before that I was probably not patient enough to see smbd fail), reporting that samba 4.7.1 was running and it refused to start 4.7.4 (at this time I tried to directly upgrade to 4.7.4): [2018/02/04 20:18:16.968393, 0] ../source3/smbd/server.c:1532(smbd_claim_version) Feb 4 20:18:16 fileb smbd[5835]: smbd_claim_version: smbd 4.7.1 already running, refusing to start version 4.7.4 The next thing was to stop ctdb on both file servers to do an offline upgrade. This worked fine without any problems. So it seems that a rolling upgrade from 4.7.1 to 4.7.4 did not work in my case in contrast to the information on the samba wiki:"For releases within a minor version (i.e. X.Y.Z to X.Y.Z'), rolling upgrades will work unless otherwise stated.". I could not find any information in the release notes that rolling upgrades do not work, but next time I will try to do an offline upgrade first. Thank you for your time and help. peace & happiness, Nicolas