[Samba] Fwd: Client fails to mount with Samba running as daemon. Fine in foreground.

Oliver Northam oliver at sidigital.co
Mon Feb 26 18:28:23 UTC 2018 

Hi all,

Experiencing a really weird issue on my Samba instance (4.7.5). It is not
allowing users to browse any shares when running as a systemctl daemon, but
it is working fine when running as a foreground service.

Contents of systemctl service unit:

# cat /usr/lib/systemd/system/smb.service
[Unit]
Description=Samba SMB Daemon
After=syslog.target network.target nmb.service winbind.service

[Service]
Environment=KRB5CCNAME=FILE:/run/samba/krb5cc_samba
Type=notify
NotifyAccess=all
PIDFile=/run/smbd.pid
LimitNOFILE=16384
EnvironmentFile=-/etc/sysconfig/samba
ExecStart=/usr/sbin/smbd -F --no-process-group $SMBDOPTIONS
ExecReload=/usr/bin/kill -HUP $MAINPID
LimitCORE=infinity

[Install]
WantedBy=multi-user.target
Logs when running via systemctl:

[2018/02/26 16:57:37.676020,  3, pid=2994] ../lib/util/access.c:365(
allow_access)
  Allowed connection from 192.168.247.72 (192.168.247.72)
[2018/02/26 16:57:37.676283,  3, pid=2994] ../source3/param/loadparm.c:
3862(lp_load_ex)
  lp_load_ex: refreshing parameters
[2018/02/26 16:57:37.676497,  3, pid=2994] ../source3/param/loadparm.c:
549(init_globals)
  Initialising global parameters
[2018/02/26 16:57:37.676661,  3, pid=2994] ../source3/param/loadparm.c:
2776(lp_do_section)
  Processing section "[global]"
[2018/02/26 16:57:37.676960,  2, pid=2994] ../source3/param/loadparm.c:
2793(lp_do_section)
  Processing section "[test]"
[2018/02/26 16:57:37.677137,  3, pid=2994] ../source3/param/loadparm.c:
1611(lp_add_ipc)
  adding IPC service
[2018/02/26 16:57:37.677433,  2, pid=2994] ../source3/lib/interface.c:
345(add_interface)
  added interface ens192 ip=192.168.247.71 bcast=192.168.247.255
netmask=255.255.255.0
[2018/02/26 16:57:37.677553,  3, pid=2994] ../source3/smbd/oplock.c:1340(
init_oplocks)
  init_oplocks: initializing messages.
[2018/02/26 16:57:37.677770,  3, pid=2994] ../source3/smbd/process.c:
1959(process_smb)
  Transaction 0 of length 216 (0 toread)
[2018/02/26 16:57:37.677874,  3, pid=2994] ../source3/smbd/process.c:
1539(switch_message)
  switch message SMBnegprot (pid 2994) conn 0x0
[2018/02/26 16:57:37.678639,  3, pid=2994] ../source3/smbd/negprot.c:612(
reply_negprot)
  Requested protocol [PC NETWORK PROGRAM 1.0]
[2018/02/26 16:57:37.678766,  3, pid=2994] ../source3/smbd/negprot.c:612(
reply_negprot)
  Requested protocol [MICROSOFT NETWORKS 1.03]
[2018/02/26 16:57:37.678864,  3, pid=2994] ../source3/smbd/negprot.c:612(
reply_negprot)
  Requested protocol [MICROSOFT NETWORKS 3.0]
[2018/02/26 16:57:37.678968,  3, pid=2994] ../source3/smbd/negprot.c:612(
reply_negprot)
  Requested protocol [LANMAN1.0]
[2018/02/26 16:57:37.679071,  3, pid=2994] ../source3/smbd/negprot.c:612(
reply_negprot)
  Requested protocol [LM1.2X002]
[2018/02/26 16:57:37.679183,  3, pid=2994] ../source3/smbd/negprot.c:612(
reply_negprot)
  Requested protocol [DOS LANMAN2.1]
[2018/02/26 16:57:37.679280,  3, pid=2994] ../source3/smbd/negprot.c:612(
reply_negprot)
  Requested protocol [LANMAN2.1]
[2018/02/26 16:57:37.679379,  3, pid=2994] ../source3/smbd/negprot.c:612(
reply_negprot)
  Requested protocol [Samba]
[2018/02/26 16:57:37.679472,  3, pid=2994] ../source3/smbd/negprot.c:612(
reply_negprot)
  Requested protocol [NT LANMAN 1.0]
[2018/02/26 16:57:37.679583,  3, pid=2994] ../source3/smbd/negprot.c:612(
reply_negprot)
  Requested protocol [NT LM 0.12]
[2018/02/26 16:57:37.679693,  3, pid=2994] ../source3/smbd/negprot.c:612(
reply_negprot)
  Requested protocol [SMB 2.002]
[2018/02/26 16:57:37.679809,  3, pid=2994] ../source3/smbd/negprot.c:612(
reply_negprot)
  Requested protocol [SMB 2.???]
[2018/02/26 16:57:37.679986,  3, pid=2994] ../source3/smbd/smb2_negprot.
c:290(smbd_smb2_request_process_negprot)
  Selected protocol SMB2_FF
[2018/02/26 16:57:37.680477,  3, pid=2994] ../auth/gensec/gensec_start.c:
977(gensec_register)
  GENSEC backend 'gssapi_spnego' registered
[2018/02/26 16:57:37.680579,  3, pid=2994] ../auth/gensec/gensec_start.c:
977(gensec_register)
  GENSEC backend 'gssapi_krb5' registered
[2018/02/26 16:57:37.680684,  3, pid=2994] ../auth/gensec/gensec_start.c:
977(gensec_register)
  GENSEC backend 'gssapi_krb5_sasl' registered
[2018/02/26 16:57:37.680797,  3, pid=2994] ../auth/gensec/gensec_start.c:
977(gensec_register)
  GENSEC backend 'spnego' registered
[2018/02/26 16:57:37.680882,  3, pid=2994] ../auth/gensec/gensec_start.c:
977(gensec_register)
  GENSEC backend 'schannel' registered
[2018/02/26 16:57:37.680984,  3, pid=2994] ../auth/gensec/gensec_start.c:
977(gensec_register)
  GENSEC backend 'naclrpc_as_system' registered
[2018/02/26 16:57:37.681089,  3, pid=2994] ../auth/gensec/gensec_start.c:
977(gensec_register)
  GENSEC backend 'sasl-EXTERNAL' registered
[2018/02/26 16:57:37.681191,  3, pid=2994] ../auth/gensec/gensec_start.c:
977(gensec_register)
  GENSEC backend 'ntlmssp' registered
[2018/02/26 16:57:37.681291,  3, pid=2994] ../auth/gensec/gensec_start.c:
977(gensec_register)
  GENSEC backend 'ntlmssp_resume_ccache' registered
[2018/02/26 16:57:37.681384,  3, pid=2994] ../auth/gensec/gensec_start.c:
977(gensec_register)
  GENSEC backend 'http_basic' registered
[2018/02/26 16:57:37.681489,  3, pid=2994] ../auth/gensec/gensec_start.c:
977(gensec_register)
  GENSEC backend 'http_ntlm' registered
[2018/02/26 16:57:37.682280,  3, pid=2994] ../source3/smbd/negprot.c:753(
reply_negprot)
  Selected protocol SMB 2.???
[2018/02/26 16:57:37.682741,  3, pid=2994] ../source3/smbd/smb2_negprot.
c:290(smbd_smb2_request_process_negprot)
  Selected protocol SMB3_11
[2018/02/26 16:57:37.686193,  3, pid=2994] ../auth/ntlmssp/ntlmssp_util.
c:69(debug_ntlmssp_flags)
  Got NTLMSSP neg_flags=0x62088215
[2018/02/26 16:57:37.686799,  3, pid=2994] ../auth/ntlmssp/ntlmssp_
server.c:454(ntlmssp_server_preauth)
  Got user=[test] domain=[SAMBA] workstation=[THINKPAD-X270] len1=24
len2=330
[2018/02/26 16:57:37.686917,  3, pid=2994] ../source3/param/loadparm.c:
3862(lp_load_ex)
  lp_load_ex: refreshing parameters
[2018/02/26 16:57:37.687046,  3, pid=2994] ../source3/param/loadparm.c:
549(init_globals)
  Initialising global parameters
[2018/02/26 16:57:37.687198,  3, pid=2994] ../source3/param/loadparm.c:
2776(lp_do_section)
  Processing section "[global]"
[2018/02/26 16:57:37.687465,  2, pid=2994] ../source3/param/loadparm.c:
2793(lp_do_section)
  Processing section "[test]"
[2018/02/26 16:57:37.687611,  3, pid=2994] ../source3/param/loadparm.c:
1611(lp_add_ipc)
  adding IPC service
[2018/02/26 16:57:37.687742,  3, pid=2994] ../source3/auth/auth.c:189(
auth_check_ntlm_password)
  check_ntlm_password:  Checking password for unmapped user
[SAMBA]\[test]@[THINKPAD-X270] with the new password interface
[2018/02/26 16:57:37.687838,  3, pid=2994] ../source3/auth/auth.c:192(
auth_check_ntlm_password)
  check_ntlm_password:  mapped user is: [SAMBA]\[test]@[THINKPAD-X270]
[2018/02/26 16:57:37.687998,  2, pid=2994] ../source3/lib/smbldap.c:841(
smbldap_open_connection)
  smbldap_open_connection: connection opened
[2018/02/26 16:57:37.696554,  3, pid=2994] ../source3/lib/smbldap.c:1063(
smbldap_connect_system)
  ldap_connect_system: successful connection to the LDAP server
[2018/02/26 16:57:37.699013,  2, pid=2994] ipa_sam.c:3216(init_sam_from_
ldap)
  init_sam_from_ldap: Entry found for user: test
[2018/02/26 16:57:37.700693,  3, pid=2994] ../source3/auth/auth.c:256(
auth_check_ntlm_password)
  auth_check_ntlm_password: sam authentication for user [test] succeeded
[2018/02/26 16:57:37.700736,  3, pid=2994] ../auth/auth_log.c:760(log_
authentication_event_human_readable)
  Auth: [SMB2,(null)] user [SAMBA]\[test] at [Mon, 26 Feb 2018
16:57:37.700721 GMT] with [NTLMv2] status [NT_STATUS_OK] workstation
[THINKPAD-X270] remote host [ipv4:192.168.247.72:39014] became
[domain.internal]\[test] [S-1-5-21-2460180081-1733199439-1879006710-1003].
local host [ipv4:192.168.247.71:445]
[2018/02/26 16:57:37.700769,  3, pid=2994] ../auth/auth_log.c:591(log_no_
json)
  log_no_json: JSON auth logs not available unless compiled with jansson
[2018/02/26 16:57:37.700780,  2, pid=2994] ../source3/auth/auth.c:314(
auth_check_ntlm_password)
  check_ntlm_password:  authentication for user [test] -> [test] -> [test]
succeeded
[2018/02/26 16:57:37.700798,  3, pid=2994] ../auth/ntlmssp/ntlmssp_sign.
c:509(ntlmssp_sign_reset)
  NTLMSSP Sign/Seal - Initialising with flags:
[2018/02/26 16:57:37.700807,  3, pid=2994] ../auth/ntlmssp/ntlmssp_util.
c:69(debug_ntlmssp_flags)
  Got NTLMSSP neg_flags=0x62088215
[2018/02/26 16:57:37.700829,  3, pid=2994] ../auth/ntlmssp/ntlmssp_sign.
c:509(ntlmssp_sign_reset)
  NTLMSSP Sign/Seal - Initialising with flags:
[2018/02/26 16:57:37.700837,  3, pid=2994] ../auth/ntlmssp/ntlmssp_util.
c:69(debug_ntlmssp_flags)
  Got NTLMSSP neg_flags=0x62088215
[2018/02/26 16:57:37.702460,  3, pid=2994] ../source3/smbd/password.c:
130(register_homes_share)
  Using static (or previously created) service for user 'test'; path =
'/media/nas/test_dir'
[2018/02/26 16:57:37.703937,  3, pid=2994] ../lib/util/access.c:365(
allow_access)
  Allowed connection from 192.168.247.72 (192.168.247.72)
[2018/02/26 16:57:37.703995,  3, pid=2994] ../source3/smbd/service.c:595(
make_connection_snum)
  Connect path is '/tmp' for service [IPC$]
[2018/02/26 16:57:37.704019,  3, pid=2994] ../source3/smbd/vfs.c:113(vfs_
init_default)
  Initialising default vfs hooks
[2018/02/26 16:57:37.704039,  3, pid=2994] ../source3/smbd/vfs.c:139(vfs_
init_custom)
  Initialising custom vfs hooks from [/[Default VFS]/]
[2018/02/26 16:57:37.704093,  3, pid=2994] ../source3/smbd/service.c:841(
make_connection_snum)
  thinkpad-x270 (ipv4:192.168.247.72:39014) connect to service IPC$
initially as user test (uid=1368400003, gid=1368400003) (pid 2994)
[2018/02/26 16:57:37.704548,  3, pid=2994] ../source3/smbd/msdfs.c:1008(
get_referred_path)
  get_referred_path: |test| in dfs path \samba.domain.internal\test is not
a dfs root.
[2018/02/26 16:57:37.704565,  3, pid=2994] ../source3/smbd/smb2_server.c:
3139(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[1]
status[NT_STATUS_NOT_FOUND] || at ../source3/smbd/smb2_ioctl.c:309
[2018/02/26 16:57:37.704836,  3, pid=2994] ../source3/smbd/service.c:
1120(close_cnum)
  thinkpad-x270 (ipv4:192.168.247.72:39014) closed connection to service
IPC$
[2018/02/26 16:57:37.705095,  3, pid=2994] ../lib/util/access.c:365(
allow_access)
  Allowed connection from 192.168.247.72 (192.168.247.72)
[2018/02/26 16:57:37.705117,  3, pid=2994] ../libcli/security/dom_sid.c:
210(dom_sid_parse_endp)
  string_to_sid: SID @ipausers is not in a valid format
[2018/02/26 16:57:37.705526,  3, pid=2994] ../source3/smbd/service.c:595(
make_connection_snum)
  Connect path is '/media/nas/test_dir' for service [test]
[2018/02/26 16:57:37.705633,  3, pid=2994] ../libcli/security/dom_sid.c:
210(dom_sid_parse_endp)
  string_to_sid: SID @ipausers is not in a valid format
[2018/02/26 16:57:37.705869,  3, pid=2994] ../source3/smbd/vfs.c:113(vfs_
init_default)
  Initialising default vfs hooks
[2018/02/26 16:57:37.705962,  3, pid=2994] ../source3/smbd/vfs.c:139(vfs_
init_custom)
  Initialising custom vfs hooks from [/[Default VFS]/]
[2018/02/26 16:57:37.706100,  3, pid=2994] ../libcli/security/dom_sid.c:
210(dom_sid_parse_endp)
  string_to_sid: SID @ipausers is not in a valid format
[2018/02/26 16:57:37.706386,  0, pid=2994] ../source3/smbd/service.c:774(
make_connection_snum)
  canonicalize_connect_path failed for service test, path
/media/nas/test_dir
[2018/02/26 16:57:37.706955,  3, pid=2994] ../source3/smbd/smb2_server.c:
3139(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[1]
status[NT_STATUS_BAD_NETWORK_NAME] || at ../source3/smbd/smb2_tcon.c:135
[2018/02/26 16:57:37.707412,  3, pid=2994] ../source3/smbd/smb2_server.c:
3139(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[1]
status[NT_STATUS_NETWORK_NAME_DELETED] || at ../source3/smbd/smb2_server.c:
2491
[2018/02/26 16:57:37.707871,  3, pid=2994] ../source3/smbd/server_exit.c:
244(exit_server_common)
  Server exit (NT_STATUS_END_OF_FILE)
[2018/02/26 16:57:37.712408,  3, pid=2948] ../source3/lib/util_procid.c:
54(pid_to_procid)
  pid_to_procid: messaging_dgm_get_unique failed: No such file or directory


Command to run in foreground:
smbd -F

I'm a bit lost on this one because they're both using the same
configuration files. /etc/sysconfig/samba is also full of empty variables.

A few things to note:

- Samba is connected to a LDAP directory server
- Samba is running on Fedora 27
- Systemctl and foreground command are using same directory permissions and
same system user

Can anyone give me any clues on where to go from here? I don't fancy
running the foreground command in screen as a workaround!

Thanks,
Oliver

More information about the samba mailing list