Jacob - Mon, 2015/12/14 - 23:07

Since I migrated to the new v14 fileserver my samba log files are growing like crazy.

/var/log/samba/samba.log has a lot of messages i don't understand. It seems to be reloading the conf file time and time again. It also gives debug like source code references...

[2015/12/14 16:44:05.761478,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[homes]"
[2015/12/14 16:44:05.761702,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[dctax]"
[2015/12/14 16:44:05.761876,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[dcpayroll]"
[2015/12/14 16:44:05.762264,  2] ../source3/lib/interface.c:341(add_interface)
  added interface eth0 ip=192.168.69.7 bcast=192.168.69.255 netmask=255.255.255.0
[2015/12/14 16:44:05.772417,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[homes]"
[2015/12/14 16:44:05.772529,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[dctax]"
[2015/12/14 16:44:05.772613,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[dcpayroll]"
[2015/12/14 16:44:05.778626,  2] ../source3/smbd/service.c:407(create_connection_session_info)
  guest user (from session setup) not permitted to access this share (dctax)
[2015/12/14 16:44:05.778777,  1] ../source3/smbd/service.c:550(make_connection_snum)
  create_connection_session_info failed: NT_STATUS_ACCESS_DENIED
[2015/12/14 16:44:05.780296,  2] ../source3/smbd/service.c:407(create_connection_session_info)
  guest user (from session setup) not permitted to access this share (dctax)
[2015/12/14 16:44:05.780343,  1] ../source3/smbd/service.c:550(make_connection_snum)
  create_connection_session_info failed: NT_STATUS_ACCESS_DENIED
[2015/12/14 16:44:14.673947,  2] ../source3/smbd/close.c:780(close_normal_file)
  dooy closed file DCtaxData/Clients DCTS/Wema/W-Holdings NV/Winstbelasting/Fiscal year 2013/DCTS2015-414 AWB 2013, W-Holdings N.V..pdf (numopen=6) NT_STATUS_OK
[2015/12/14 16:44:51.141449,  2] ../source3/smbd/server.c:419(remove_child_pid)
  Could not find child 32520 -- ignoring
[2015/12/14 16:45:06.144041,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[homes]"
[2015/12/14 16:45:06.144272,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[dctax]"
[2015/12/14 16:45:06.144446,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[dcpayroll]"
[2015/12/14 16:45:06.144837,  2] ../source3/lib/interface.c:341(add_interface)
  added interface eth0 ip=192.168.69.7 bcast=192.168.69.255 netmask=255.255.255.0
[2015/12/14 16:45:06.156000,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[homes]"
[2015/12/14 16:45:06.156170,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[dctax]"
[2015/12/14 16:45:06.156316,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[dcpayroll]"
[2015/12/14 16:45:06.201427,  2] ../source3/smbd/service.c:407(create_connection_session_info)
  guest user (from session setup) not permitted to access this share (dctax)
[2015/12/14 16:45:06.201576,  1] ../source3/smbd/service.c:550(make_connection_snum)
  create_connection_session_info failed: NT_STATUS_ACCESS_DENIED
[2015/12/14 16:45:06.203547,  2] ../source3/smbd/service.c:407(create_connection_session_info)
  guest user (from session setup) not permitted to access this share (dctax)
[2015/12/14 16:45:06.203689,  1] ../source3/smbd/service.c:550(make_connection_snum)
  create_connection_session_info failed: NT_STATUS_ACCESS_DENIED
[2015/12/14 16:45:13.613774,  2] ../source3/smbd/open.c:1002(open_file)
  luzina opened file DCtaxData/AVvB/Brf commentaar AvVB invoering VAS signed.pdf read=No write=No (numopen=5)
[2015/12/14 16:45:13.623158,  2] ../source3/smbd/close.c:780(close_normal_file)
  luzina closed file DCtaxData/AVvB/Brf commentaar AvVB invoering VAS signed.pdf (numopen=4) NT_STATUS_OK
[2015/12/14 16:45:13.696562,  2] ../source3/smbd/open.c:1002(open_file)
  luzina opened file DCtaxData/SIAD/Tabel premie AOV-AWW-AZV 2010-2015.pdf read=No write=No (numopen=5)
[2015/12/14 16:45:13.702143,  2] ../source3/smbd/close.c:780(close_normal_file)
  luzina closed file DCtaxData/SIAD/Tabel premie AOV-AWW-AZV 2010-2015.pdf (numopen=4) NT_STATUS_OK
[2015/12/14 16:45:51.178867,  2] ../source3/smbd/server.c:419(remove_child_pid)
  Could not find child 32522 -- ignoring
[2015/12/14 16:46:06.512498,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[homes]"
[2015/12/14 16:46:06.512724,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[dctax]"
[2015/12/14 16:46:06.512900,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[dcpayroll]"
[2015/12/14 16:46:06.513290,  2] ../source3/lib/interface.c:341(add_interface)
  added interface eth0 ip=192.168.69.7 bcast=192.168.69.255 netmask=255.255.255.0
[2015/12/14 16:46:06.524274,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[homes]"
[2015/12/14 16:46:06.524401,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[dctax]"
[2015/12/14 16:46:06.524499,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[dcpayroll]"
[2015/12/14 16:46:06.527047,  2] ../source3/smbd/service.c:407(create_connection_session_info)
  guest user (from session setup) not permitted to access this share (dctax)
[2015/12/14 16:46:06.527172,  1] ../source3/smbd/service.c:550(make_connection_snum)
  create_connection_session_info failed: NT_STATUS_ACCESS_DENIED
[2015/12/14 16:46:51.226838,  2] ../source3/smbd/server.c:419(remove_child_pid)
  Could not find child 32548 -- ignoring
[2015/12/14 16:47:06.884600,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[homes]"
[2015/12/14 16:47:06.884827,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[dctax]"
[2015/12/14 16:47:06.885029,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[dcpayroll]"
[2015/12/14 16:47:06.885408,  2] ../source3/lib/interface.c:341(add_interface)
  added interface eth0 ip=192.168.69.7 bcast=192.168.69.255 netmask=255.255.255.0
[2015/12/14 16:47:06.896006,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[homes]"
[2015/12/14 16:47:06.896132,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[dctax]"
[2015/12/14 16:47:06.896228,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[dcpayroll]"
[2015/12/14 16:47:06.898207,  2] ../source3/smbd/service.c:407(create_connection_session_info)
  guest user (from session setup) not permitted to access this share (dctax)
[2015/12/14 16:47:06.898292,  1] ../source3/smbd/service.c:550(make_connection_snum)
  create_connection_session_info failed: NT_STATUS_ACCESS_DENIED
[2015/12/14 16:47:51.274362,  2] ../source3/smbd/server.c:419(remove_child_pid)
  Could not find child 32550 -- ignoring
[2015/12/14 16:48:07.253954,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[homes]"
[2015/12/14 16:48:07.254195,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[dctax]"
[2015/12/14 16:48:07.254370,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[dcpayroll]"
[2015/12/14 16:48:07.254754,  2] ../source3/lib/interface.c:341(add_interface)
  added interface eth0 ip=192.168.69.7 bcast=192.168.69.255 netmask=255.255.255.0
[2015/12/14 16:48:07.265065,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[homes]"
[2015/12/14 16:48:07.265231,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[dctax]"
[2015/12/14 16:48:07.265378,  2] ../source3/param/loadparm.c:3582(do_section)
  Processing section "[dcpayroll]"

And /var/log/auth.log has a ton of messages regarding user nobody

Dec 14 16:33:31 bridge2 smbd[32424]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:34:17 bridge2 smbd[32427]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:35:17 bridge2 smbd[32430]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:36:17 bridge2 smbd[32455]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:37:17 bridge2 smbd[32457]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:37:54 bridge2 smbd[32424]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:38:17 bridge2 smbd[32460]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:38:42 bridge2 smbd[32461]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:38:42 bridge2 smbd[32462]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:39:01 bridge2 CRON[32464]: pam_unix(cron:session): session opened for user root by (uid=0)
Dec 14 16:39:01 bridge2 CRON[32464]: pam_unix(cron:session): session closed for user root
Dec 14 16:39:17 bridge2 smbd[32485]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:40:17 bridge2 smbd[32487]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:40:58 bridge2 smbd[32424]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:41:17 bridge2 smbd[32512]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:42:17 bridge2 smbd[32514]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:43:17 bridge2 smbd[32517]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:44:17 bridge2 smbd[32519]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:45:17 bridge2 smbd[32521]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:46:06 bridge2 smbd[32546]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:47:06 bridge2 smbd[32549]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:48:07 bridge2 smbd[32551]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:49:07 bridge2 smbd[32553]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:50:06 bridge2 smbd[32555]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:50:06 bridge2 smbd[32556]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:51:06 bridge2 smbd[32581]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:52:06 bridge2 smbd[32584]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:52:41 bridge2 smbd[32585]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:52:41 bridge2 smbd[32586]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:52:47 bridge2 smbd[32587]: pam_unix(samba:session): session closed for user nobody
Dec 14 16:53:07 bridge2 smbd[32589]: pam_unix(samba:session): session closed for user nobody​

Any advice how to solve underlying problems?

 

Forum: 
Support
Tags: 
samba
fileserver
Jeremy Davis's picture

Jeremy Davis - Tue, 2015/12/15 - 01:20
TBH I'm not sure about why it appears to be reloading the conf. It almost looks like it's crashing then restarting.

As for your auth log, is this server internet accessible? If so you should block the ports that Samba uses (Samba/SMB/CIFS should not be internet accessible). The Samba wiki has info about which ports it exposes (v14.0 fileserver uses an NT4 type config).

If it's not internet accessible then my guess is that there is something on your network which is trying to access your Samba server without credentials. Maybe its windows clients which use "Network Neighbourhood" to scan for available services/servers? I would be inclined to try to work out what it is and stop it from doing that (or give it credentials if you want it to keep doing that)...

However regarding log size, it seems that Samba does not do a log rotate on the samba.log (only nmdb.log and smdb.log) so it might help a bit if you add that to the logrotate config. Here is what is is by default: 

# cat /etc/logrotate.d/samba
/var/log/samba/log.smbd {
	weekly
	missingok
	rotate 7
	postrotate
		/etc/init.d/smbd reload > /dev/null
	endscript
	compress
	notifempty
}

/var/log/samba/log.nmbd {
	weekly
	missingok
	rotate 7
	postrotate
		[ ! -f /var/run/samba/nmbd.pid ] || kill -HUP `cat /var/run/samba/nmbd.pid`
	endscript
	compress
	notifempty
}

I've never adjusted it before but I'd assume that you could use what is there as a guide. I'm guessing that you'd need to stop samba to do the rotation (as the others do). I'd be really interested on what you find as we might want to adjust the default for v14.1.

Jacob - Sat, 2016/01/02 - 20:36

Been very busy the last weeks. The samba box is not accessible from the internet (only ssh is forwarded in router / fw). But I have Spiceworks running and scanning statusses. I will temporarily disable that, and see if the "session closed for user nobody" disappears.

I am not looking for a log rotation, but prefer to get rid of all the debug style messages that even refer to source code modules. 

I like creating small log files, by resolving errors that generate too much noise. I have increased log level for now, hopefully that will give me more leads on finding root causes.

Jeremy Davis's picture

Jeremy Davis - Tue, 2016/01/05 - 06:14
But I'm guessing that that may be it. I'll be interested to hear how it goes. I suspect that it is checking that Samba shares are available. Perhaps there is a way to create a "polling" account so it can legitimately test the Samba shares without making noise in the logs?

Off on a tangent I have serious issues with spiceworks' walled garden "community". Years ago when I was a Windows sys admin I found a ton of useful; info and friendly helpful people on there. But a couple of years ago I tried to help some TurnKey users who had posted on the spiceworks forums. For full disclosure I mentioned that I was involved with TurnKey. Despite the fact that I didn't post anything other than helpful info & advice, my comments got moderated (deleted) and my account got blocked. When I contacted them to inquire why, I was told that "vendors" are blocked from posting unless they are "approved". When I asked how I would go about becoming "approved" I was informed that basically it just requires a monthly subscription (IIRC it was a few thousand per month). Sorry about the rant...

Jacob - Sun, 2016/01/17 - 21:57

Created a fresh VM, installed TKL fileserver v14, migrated users, directory structure, samba-users, passwords and config from the live box. Ready to do some serious troubleshooting.

But I am still getting truckloads of log messages that I, after 3 days of intensive google-ing, cannot solve. I am thinking about throwing v14 out of the window and go back to v13. I have to confess, for the first time in 5 years, I looked at Windows Server pricing :(

Next week I will try to block another 2-3 days, and take it to the Samba community. Any suggestions what might be the best place to find some help??

Jeremy Davis's picture

Jeremy Davis - Mon, 2016/01/18 - 04:14
FWIW as Samba4 is installed from Debian, posting a Debian bug may be the best starting point.

I just spent over an hour trying to investigate this further...

Firstly as I think I've mentioned previously, I can't find anyone reporting the same issue. The only thread I found that seemed similar was the one that I mentioned before (caused by someone/something that didn't have authorisation trying to connect). I think that monitoring software that scans for SMB shares (such as Spiceworks) may be the cause? Although I still think that that logging should be able to be turned down, and/or the monitoring software should be able to be configured so that it has a legitimate log in. Out of interest did disabling SpiceWorks change things at all? If it did then perhaps it's worth asking on their forums about possible workarounds?

I also spent about half an hour digging through all the Debian Samba bug reports (for Jessie/stable; i.e. what v14.0 uses). TBH I didn't see any that lined up at all with your experience. The only ones that seemed possibly and/or marginally similar (although some I am sure are not related) are:

  • https://bugs.debian.org/cgi-bin/pkgreport.cgi?bug=702201
  • https://bugs.debian.org/cgi-bin/pkgreport.cgi?bug=799059
  • https://bugs.debian.org/cgi-bin/pkgreport.cgi?bug=735524
  • https://bugs.debian.org/cgi-bin/pkgreport.cgi?bug=804705
  • https://bugs.debian.org/cgi-bin/pkgreport.cgi?bug=803924

    We may have also discussed this previously, but I also checked out the logging level. By default it should be turned all the way down (which seems to be the case); but you can turn it up if need be. IMO it shouldn't be logging that much stuff when turned all the way down. IMO that is definitely a bug! But whether it's a bug caused by TurnKey's samba.conf, a Debian bug or an upstream bug I'm not at all sure. It does seem that it is being highlighted by something on your network though...

    Worst case scenario; going back to v13.0 is a legitimate option. When Wheezy (what v13.0 is built on) reaches what was previously coined "EOL" (end of life) later this year; it will automatically switch over to LTS (Long Term Support - the security repo will be handed from the Debian security team to the LTS team). As they have fewer resources you may find that security bugs aren't patched quite as quickly but they should still get patched. IIRC LTS support is 5 years... TurnKey support might get a bit flakey as the time goes on although as a long time TKL and Hub user with legitimate issues we'll keep users like yourself in mind and will try to provide as much as support as we can.

    Regardless of what the final outcome is, thank you so much for all your hard work on this and for your ongoing contribution to TurnKey.

    • Jacob - Mon, 2016/01/18 - 16:32

    Hi Jeremy, after a more or less decent night of sleep, I am attacking it again ;)

    I dont care about the size or rotation of the logs, I can fix that. But my approach is, that when I look at my log files, and I see errors / warnings, I dig in and try to resolve the underlying problem that is causing those lines to appear in my log files. For me that is the best way to keep logs under control, and knowing everything works smooth, helps me sleep better. And when new things show up, it doesn't get burried in all the messages that 'are probably nothing serious'.

    There seem to be a couple of different problems going on, and I am not sure if they are related to each other at all.

    I not only disabled Spiceworks, but removed it completely from my network, to be sure that is not interfering.

    Samba log level was 2, when I copied those snippets

    Samba security = user, but I suspect some win clients are not playing nice, and try to browse samba services without proper credentials. That might cause all the user Nobody lines, and both the 'create_connection_session_info failed: NT_STATUS_ACCESS_DENIED' lines  and 'guest user (from session setup) not permitted to access this share' lines. Just now I created a new user named 'smbbrowser', and hope this name will show up in my log instead of the Nobody, to confirm my hypothesis.

    There is also a different problem, samba seems to reload its config file again and again. I'm still clueless why.

    And another different problem: '../source3/smbd/server.c:419(remove_child_pid)
      Could not find child 32522 -- ignoring'  It seems to be spawning child processes, and then looses track of them. I found one reference this might be related to print services, but since I don't use those, they should be completely disabled and not causing noise in my logs.

     

    I think I may have a problem with log rotation somewhere else, not related to samba. I am running a simple proftp service, and I have to manually restart it every monday morning. In the weekend there are only 2 things different from weekdays: TKLBAM full backup and probably log rotation. (I will get back to this later)

     

    Jeremy Davis's picture

    Jeremy Davis - Tue, 2016/01/19 - 05:28
    There does seem to be a few different things going on.

    When you first posted and I was trying to help you troubleshoot, I did a clean v14.0 install and discovered that the log file had a lot of stuff in it (before I had even barely used it). When googling I discovered that Samba logging levels are from 1 (least) to 10 (most). I assumed that it must have been set to 8 or 9 by default; but it turns out that was at 1! IMO that is a bug right there... At the lowest logging level IMO it should only be logging errors (not a ton of 'info' type entries)!

    Ah! You mention others have noted that Print server (CUPS) could be (at least partially) the issue. Even though you haven't enabled it, IIRC is it actually configured by default in the TurnKey Fileserver. I know that you have tweaked your config file yourself, but perhaps this is still an issue? I vaguely recall a fairly simple command to disable CUPS support altogether and I recommend doing that (even if you think it shouldn't make any difference). Surely it won't hurt?

    Anyway; I wish that I had something more for you. But I really admire your patience and tenacity! :)

    Jacob - Tue, 2016/01/19 - 17:54

    Samba doesn't really conform to debug / log levels I have seen everywhere else ;)

    Excessive reloading of parameters from smb.conf: I found out Samba reads the complete contents of smb.conf every 60 seconds, to see if something has changed(?). Not sure if that is very efficient, but that's the way it is.

    User nobody and guest user in session setup: I changed the guest user to a different one (smbbrowser), and from Webmin restarted Samba. Nothing changed, still showing user Nobody in /var/log/auth. But after rebooting the entire box, user SmbBrowser showed up. I still don't like it that I have to enable guest access to Samba, just because some clients want to browse the offered services. I will have to look into this deeper. Perhaps split samba logs per machine, and try to isolate the unruly one(s). I have user based security, I don't want anonymous guests roaming my server, grrrr.

    BTW, I also found out the most recent windows 10 build, has a huge bug, that breaks network services discovery in Windows. So win10 clients are no longer able to discover samba servers, NAS boxes etc. You can still connect with full URL, it's not name resolution, but Netbios discovery that is broken. (this complicated my search).

    Now for the rogue forking and missing childs: it appears this is an old bug, being reintroduced again, and again, and again. I found those references, but not a solution for the current version, other than to change the debug level for the message and complile it yourself. (Not using TKL for that). What can I do?

    https://bugzilla.samba.org/show_bug.cgi?id=8269 

    http://samba.2283325.n4.nabble.com/Samba-4-1-9-Could-not-find-child-erro...

    You are correct, I already disbled printing in smb

    load printers = no
printing = bsd
printcap name = /dev/null
disable spoolss = yes

     

    Jeremy Davis's picture

    Jeremy Davis - Fri, 2016/01/22 - 10:24
    Sounds like the Jessie Samba4 implementation is a bit messy and buggy. :(

    Keep me posted how you go and if there's anything I can help out with let me know.

    Add new comment