samba - Feb 2018 - 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

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

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,
> martin
Hi 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