Error when starting smbd4

[Stux]

When watching the system boot console screen, I see something about a configuration problem in smb4.conf.

This chatter is not in the dmesg.

Does anyone know where this is logged so I can see what it actually said?

Thanks

 

[Stux]

Does anyone know where this is logged so I can see what it actually said?

A partital answer to this seems to be /var/log/messages

and I see this

Code:

Oct  4 13:23:24 titan ntpd[2147]: ntpd 4.2.8p8-a (1): Starting
Oct  4 13:23:25 titan generate_smb4_conf.py: [generate_smb4_conf:1498] Unable to open /var/db/samba4/private/secrets.tdb: [Errno 2] No such file or directory
Oct  4 13:23:25 titan generate_smb4_conf.py: [common.pipesubr:66] Popen()ing: /sbin/sysctl -n 'kern.maxfilesperproc'
Oct  4 13:23:25 titan generate_smb4_conf.py: [common.pipesubr:66] Popen()ing: mount
Oct  4 13:23:25 titan generate_smb4_conf.py: [common.pipesubr:66] Popen()ing: /usr/local/bin/net -d 0 getlocalsid
Oct  4 13:23:26 titan smbd: dnssd_clientstub ConnectToServer: connect()-> No of tries: 1
Oct  4 13:23:26 titan root: /etc/rc: WARNING: failed precmd routine for vmware_guestd
Oct  4 13:23:27 titan smbd: dnssd_clientstub ConnectToServer: connect()-> No of tries: 2
Oct  4 13:23:28 titan smbd: dnssd_clientstub ConnectToServer: connect()-> No of tries: 3
Oct  4 13:23:29 titan smbd: dnssd_clientstub ConnectToServer: connect() failed path:/var/run/mdnsd Socket:36 Err:-1 Errno:2 No such file or directory
Oct  4 13:23:36 titan mDNSResponder: mDNSResponder (Engineering Build) (Sep 26 2016 21:17:15) starting
Oct  4 13:23:36 titan mDNSResponder:   8: Listening for incoming Unix Domain Socket client requests
Oct  4 13:23:36 titan mDNSResponder: mDNS_AddDNSServer: Lock not held! mDNS_busy (0) mDNS_reentrancy (0)
Oct  4 13:23:36 titan mDNSResponder: mDNS_AddDNSServer: Lock not held! mDNS_busy (0) mDNS_reentrancy (0)
Oct  4 13:23:36 titan mDNSResponder: CheckNATMappings: Failed to allocate port 5350 UDP multicast socket for PCP & NAT-PMP announcements
Oct  4 13:23:36 titan netatalk[3348]: Netatalk AFP server starting
Oct  4 13:23:36 titan mDNSResponder: mDNS_Register_internal: ERROR!! Tried to register AuthRecord 0000000801406D60 titan.local. (Addr) that's already in the list
Oct  4 13:23:36 titan mDNSResponder: mDNS_Register_internal: ERROR!! Tried to register AuthRecord 0000000801407180 230.1.0.10.in-addr.arpa. (PTR) that's already in the list
Oct  4 13:23:36 titan netatalk[3348]: Registered with Zeroconf
Oct  4 13:23:36 titan cnid_metad[3369]: CNID Server listening on localhost:4700
Oct  4 13:23:36 titan afpd[3368]: Netatalk AFP/TCP listening on 10.0.1.230:548

Is this a problem?

This is not quite the console scroll I see at startup, as it mentions something about running with debug to work out wth etc... but again... can't see it, because it scrolls past...

 

[MrToddsFriends]

Does anyone know where this is logged so I can see what it actually said?

Nothing in /var/log/samba4/log.smbd or one of the other log files in /var/log/samba4/ either?

BTW: I'm seeing the following in log.smbd:

Code:

  STATUS=daemon 'smbd' finished starting up and ready to serve connectionsparams.c:OpenConfFile() - Unable to open configuration file "/usr/local/etc/smb4.conf":

Don't know the reason for this message. Wild guesses: Maybe smbd is started before the recreation of all config files from the FreeNAS config database is finished or all of the tmpfs mouting magic is done.

 

[dlavigne]

Is this on the latest -U2? If not, does updating resolve it?

 

[Stux]

Is this on the latest -U2? If not, does updating resolve it?

It does not :-\

This is with U2:

Code:

Oct  7 14:06:51 titan generate_smb4_conf.py: [generate_smb4_conf:1498] Unable to open /var/db/samba4/private/secrets.tdb: [Errno 2] No such file or directory
Oct  7 14:06:51 titan generate_smb4_conf.py: [common.pipesubr:66] Popen()ing: /sbin/sysctl -n 'kern.maxfilesperproc'
Oct  7 14:06:51 titan generate_smb4_conf.py: [common.pipesubr:66] Popen()ing: mount
Oct  7 14:06:51 titan generate_smb4_conf.py: [common.pipesubr:66] Popen()ing: /usr/local/bin/net -d 0 getlocalsid

there didn't seem to be anything interesting in /var/log/samba4/log.smbd either at about that time

Code:

[2016/10/07 14:06:52.332228,  1] ../source3/profile/profile_dummy.c:30(set_profile_level)
  INFO: Profiling support unavailable in this build.
[2016/10/07 14:06:51.450636,  1] ../source3/smbd/files.c:218(file_init_global)
  file_init_global: Information only: requested 939611 open files, 59392 are available.
[2016/10/07 14:06:51.468422,  0] ../lib/util/become_daemon.c:124(daemon_ready)
  STATUS=daemon 'smbd' finished starting up and ready to serve connections

I suspect the error is ignored and doesn't mean anything, as everything else seems to be working right, but surely, that shouldn't be the way its supposed to be?

/var/db/samba4/private/secrets.tdb seems to exist

Code:

/var/db/samba4/private# ls -alt
total 156
drwx------  2 root  wheel	  34 Oct  7 23:19 msg.sock/
drwxr-xr-x  4 root  wheel	  14 Oct  7 19:10 ../
-rw-------  1 root  wheel	 696 Oct  7 19:04 netlogon_creds_cli.tdb
-rw-------  1 root  wheel  421888 Sep 27 21:36 passdb.tdb
drwx------  3 root  wheel	   6 Sep 27 17:46 ./
-rw-------  1 root  wheel  430080 Sep 20 16:23 secrets.tdb

 

[Mirfster]

Yeah, I recall seeing it as well (running 9.10.1). Seems to me like it is as @MrToddsFriends stated and not adverse effects on the system are seen. Of course only us really geek folks who actually watch the system booting up would see it... ;)

 

[anodos]

It does not :-\

This is with U2:

Code:

Oct  7 14:06:51 titan generate_smb4_conf.py: [generate_smb4_conf:1498] Unable to open /var/db/samba4/private/secrets.tdb: [Errno 2] No such file or directory
Oct  7 14:06:51 titan generate_smb4_conf.py: [common.pipesubr:66] Popen()ing: /sbin/sysctl -n 'kern.maxfilesperproc'
Oct  7 14:06:51 titan generate_smb4_conf.py: [common.pipesubr:66] Popen()ing: mount
Oct  7 14:06:51 titan generate_smb4_conf.py: [common.pipesubr:66] Popen()ing: /usr/local/bin/net -d 0 getlocalsid

"generate_smb4_conf.py" is a freenas-specific script that, among other things, generates the smb4.conf file on boot using parameters stored in the freenas config db file thingy. During the boot process, it appears that FreeNAS will try to back up the secrets.tdb file before generating the smb4.conf file. My best guess about what is going on (because I don't particularly feel like poking around the github repo) is that the goal of this code is to preserve the domain / local SID for the FreeNAS server. If this SID changes then bad things will happen to the permissions on your samba shares, and you will experience lots of pain and frustration.

I suppose it's possible that "generate_smb4_conf.py" is being executed before FreeNAS is ready for it to be executed.