logrotate script needs to notify all samba processes when logs are rotated

[Simon Déziel]

After the log rotation, logrotate needs to notify all samba processes to release their open file descriptors on the log files.

The current logrotate configuration file does not do so and only notify the process that has it's PID stored /var/run/samba/.
This is wrong as other child will keep logging to the "deleted" files and may use all the disk space. Those "deleted" files are not showing in ls output but they are still consuming space in the file system.

I think the right solution to this bug would be to have logrotate to call "smbcontrol all reload-config". This solution was proposed by Andrew Bartlett, a Samba developer, in this email http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=160076#25. The smbcontrol utility will notify all related daemons (smbd, nmbd and winbindd) and their child processes to re-open a new log file.

I have confirmed that this problem affects Samba from Lucid to Natty at least.

[Simon Déziel (sdeziel)]

Steps to observe the problem :

# Only one log file exists
ls -1 /var/log/samba
cores
log.smbd

# Force the rotation
logrotate -f /etc/logrotate.d/samba

# The log is rotated but the old log file is missing (was rm'ed and does not show in ls)
ls -1 /var/log/samba
cores
log.smbd.1.gz

# with lsof we see the renamed file still opened and deleted
lsof | grep log.smbd
smbd 6593 root 2w REG 251,1 524288000 783512 /var/log/samba/log.smbd.1 (deleted)
smbd 6593 root 27w REG 251,1 524288000 783512 /var/log/samba/log.smbd.1 (deleted)
smbd 6595 root 2w REG 251,1 343 783436 /var/log/samba/log.smbd.1 (deleted)
smbd 6595 root 8w REG 251,1 343 783436 /var/log/samba/log.smbd.1 (deleted)

# Instruct smbd to reopen the log file (as Natty's logrotate does)
kill -HUP `cat /var/run/samba/smbd.pid`

# Now the log.smbd finally appears
ls -1 /var/log/samba
cores
log.smbd
log.smbd.1.gz

# lsof still shows problems due to other children processes not knowing to release the log file
lsof | grep log.smbd
smbd 6593 root 2w REG 251,1 202 783521 /var/log/samba/log.smbd
smbd 6593 root 8w REG 251,1 202 783521 /var/log/samba/log.smbd
smbd 6595 root 2w REG 251,1 343 783436 /var/log/samba/log.smbd.1 (deleted)
smbd 6595 root 8w REG 251,1 343 783436 /var/log/samba/log.smbd.1 (deleted)

Using "smbcontrol all reload-config" in the logrotate configuration file fixes the issue.

[Andreas Hasenack (ahasenack)]

I just saw this bug while merging Debian's latest samba into ubuntu, because it had this changelog snippet:

  * Fix logrotate for /var/log/samba/log.samba to send SIGHUP to all processes
    of the service (systemd only)

The logrotate script now uses smbcontrol <smbd|nmbd> reload-config (not "all", which isn't listed as a valid destination in the current smbcontrol help output [v4.6.5]), but I still see the problem happening. This is after a forced logrotate:

root@artful-samba-merge:/var/log/samba# fuser log*
/var/log/samba/log.: 8841
/var/log/samba/log.nmbd: 7177
/var/log/samba/log.nmbd.1: 8841
/var/log/samba/log.smbd: 7132 7140
/var/log/samba/log.smbd.1: 7133 7134 8841
/var/log/samba/log.wb-ARTFUL-SAMBA-MERGE: 6997 8841
/var/log/samba/log.wb-BUILTIN: 7138 8841
/var/log/samba/log.winbindd: 6996 8841
/var/log/samba/log.winbindd-idmap: 7137 8841

root@artful-samba-merge:/var/log/samba# smbcontrol smbd reload-config

root@artful-samba-merge:/var/log/samba# fuser log*
/var/log/samba/log.: 8841
/var/log/samba/log.nmbd: 7177
/var/log/samba/log.nmbd.1: 8841
/var/log/samba/log.smbd: 7132 7140
/var/log/samba/log.smbd.1: 7133 7134 8841
/var/log/samba/log.wb-ARTFUL-SAMBA-MERGE: 6997 8841
/var/log/samba/log.wb-BUILTIN: 7138 8841
/var/log/samba/log.winbindd: 6996 8841
/var/log/samba/log.winbindd-idmap: 7137 8841

The rotated log files are still kept open by smbd processes. I'll add the server-next tag to this bug to take a look at this in more detail soon.

[Andreas Hasenack (ahasenack)]

Oh, how silly of me. The 8841 process that shows in that fuser list is a tail -f I had open in another terminal.

That being said, there were still other processes, samba ones, which held an open fd to the log file, so this bug is still valid. I should just be more careful with my tail -f next time :)

[Andreas Hasenack (ahasenack)]

Still confirmed, even in cosmic with samba 4.8. The smbcontrol reload-config action still leaves processes hanging on to the rotated file.

[Andreas Hasenack (ahasenack)]

bionic onwards is using smbcontrol, and I still see some processes using the (deleted) rotated files. At least new log messages are going to the right place (log.smbd), so I'm not sure what's going on. Checked with eoan's samba 4.10.0.

[Andreas Hasenack (ahasenack)]

Bug still in our queue.

[schamane (schamane)]

Is there a corresponding bug report for Debian? I see the exact same issue on Debian Bullseye running Samba 4.13 but cannot find any report for it.

[Christian Ehrhardt  (paelzer)]

Hi,
I come by trying to clean or revive bugs that are dormant for too long.

In this case I think @Simon/@Andreas - could you just sit together for 5 min checking if this is still valid?

The most recent update is interesting but "only" for debian-stable. Not for anything really new.

@Schamane you seem to be on bullseye and there is a backport 2:4.16.1+dfsg-8~bpo11+1 available.
Since you have a repro environment, could you have a look if 4.16 is also still affected?

[schamane (schamane)]

Thanks for suggesting to upgrade to 2:4.16 via backports. The logrotate file included in this samba package does `/usr/bin/smbcontrol smbd reload-config`. I could do only limited testing so far. Anyhow, on the 1 machine where I upgraded to 2:4.16, after logrotation I still see what Andreas described in comment #5.

```
# /usr/bin/smbcontrol smbd reload-config
# kill -HUP `cat /var/run/samba/smbd.pid` # = kill -HUP 2763
# ps axu | grep '[s]mbd'
root 2763 0.0 1.7 75824 18172 ? Ss Jun13 0:00 /usr/sbin/smbd --foreground --no-process-group
root 2765 0.0 0.7 74964 8076 ? S Jun13 0:00 /usr/sbin/smbd --foreground --no-process-group
root 2766 0.0 0.4 74964 4788 ? S Jun13 0:00 /usr/sbin/smbd --foreground --no-process-group
# lsof +D /var/log 2>/dev/null|grep -E '\.[012](\.gz)?'
smbd-noti 2765 root 2w REG 8,7 9600 424 /var/log/samba/log.smbd.1
smbd-noti 2765 root 3w REG 8,7 9600 424 /var/log/samba/log.smbd.1
cleanupd 2766 root 2w REG 8,7 9600 424 /var/log/samba/log.smbd.1
cleanupd 2766 root 3w REG 8,7 9600 424 /var/log/samba/log.smbd.1

```

[Lucas Kanashiro (lucaskanashiro)]

Considering the tests performed by @schamane is correct this seems to be a valid bug even in kinetic, since there we have version 2:4.16.1+dfsg-8ubuntu1 (checking the changelog I do not see any delta regarding log rotation).

@Andreas could you please take a look at that?