samba - Oct 2008 - Closing sessions and smbstatus

Hi,

When are client sessions closed?  

Let me explain what I'm trying to do...  we're in a School district and
we try to stop kids logging more than once.  They way I did this before
was to dump the active sessions from our previous Server2003 fileserver
into a file once a minute and process it with a Perl script to check who
was connected from where, rebooting machines remotely as needed!  This
work well enough with the odd 'hung' session causing minor problems.

So now I'm trying to do the same thing with our new Samba (3.0.31)
fileserver using the output from smbstatus.  However, in many cases
sessions are still in there long after the user has logged out of the
machine.  I'm even seeing two sessions for different people on the same
machine with the same pid number!  How is this working?  Why are not all
sessions ending when the user logs off?  Am I going to be able to use
this for what I'm trying to do?!!


The fileserver itself is working great, we have over 2000 users happily
using it with less problems than we had on the Windows box.  I really
appreciate all the work the Samba team does!

Many thanks,

Steve Rippl
Woodland School District

> Hi,
>
> When are client sessions closed?  
>
> Let me explain what I'm trying to do...  we're in a School district
and
> we try to stop kids logging more than once.  They way I did this before
> was to dump the active sessions from our previous Server2003 fileserver
> into a file once a minute and process it with a Perl script to check who
> was connected from where, rebooting machines remotely as needed!  This
> work well enough with the odd 'hung' session causing minor
problems.
>   
I'm in exactly the same situation. The school, PDC for ~100 computers, 
hundreds of users.
We need to track the logon / logoff. I can't find any usable tools so I 
made my own system.
I found that most reliable is the smbstatus output. Windows do strange 
thinks with connections during domain logons so use of preexec script is 
complicated.
By the Perl script I run smbstatus every 5 seconds, scan the changes 
from previous run and write it to the MySQL DB. That's all woks
fine.
> So now I'm trying to do the same thing with our new Samba (3.0.31)
> fileserver using the output from smbstatus.  However, in many cases
> sessions are still in there long after the user has logged out of the
> machine.  I'm even seeing two sessions for different people on the same
> machine with the same pid number!  How is this working?  Why are not all
> sessions ending when the user logs off?  Am I going to be able to use
> this for what I'm trying to do?!!
>   
I have some problems with this too. See this thread:
  [Samba] smbstatus - switched off computers are sometimes showed
  http://lists.samba.org/archive/samba/2008-September/143701.html

Now I get some new experience with it. The main problem is that samba 
sometimes doesn't update the sessionid.tdb file when the process exits. 
This records is not showed in smbstatus output, because smbstatus checks 
if the PID exists. I patched the smbstatus so it showed me that there is 
the records with no related PID. Then, maybe after 1 day or so, this PID 
is used for other proccess and I can see the "ghost" logon in my 
tracking system (and in most cases logoff at next run - after 5 seconds).
On the list is now the thread "[Samba] processes not closing" where is
described some self-repair function related do sessionid.tdf file. The 
samba process when writing to this file should check all records and 
delete it if the PID doesn't exist. It will be nice but In my situation 
it doesn't work. Maybe it's because of Samba version (3.0.24, official 
Debian Etch package).

The most strange think I've seen is that I get some fake logon records 
for one user day-by-day at the same time. Let say USER1@COMP1 - tracked 
logon at tuesday 14:10:12, then at the same time at wednesday and 
thursday. In fact the COMP1 is switched off or other user is loged on at 
the time. The USER1 were loged on the COMP1 at monday.
> The fileserver itself is working great, we have over 2000 users happily
> using it with less problems than we had on the Windows box.  I really
> appreciate all the work the Samba team does!
>   
The same experience. Samba-based solution with one PDC is rock-stable 
for us in comparsion with several Windows 2003 AD servers running
before.
> Many thanks,
>
> Steve Rippl
> Woodland School District
>

> On Mon, Oct 20, 2008 at 12:52:57PM -0700, Steve Rippl wrote:
> 
> > But checking our server I find that the processes DO still exist!
So
> > I'm getting a user session in smbstatus with a specific PID and
when
I
> > ps -ef | grep PID there is the smbd process still running, yet the
user
> > has long since logged out (days ago)?!  It's not just that the
.tbd
file
> > hasn't been updated, it's that the /usr/local/bin/smbd process
is
still
> > running.  A restart of Samba clears them all up immediately, but why
are
> > they hanging around when the client is gone?  Is this just happening
to
> > me on our particular setup or is this normal behavior?
> 
> No, that's not normal behavior, but it does explain why
> the session id's are hanging around. Once the client
> terminates the TCP session the smbd should die (and
> clean up all resources such as session id's etc.).
> 
> When you find a process in this state attach using
> strace -p <pid> (on Linux) to see what it's up to.
> 
> Jeremy.
So after one day I have ~50 left-over sessions.  Running strace as above
I seem to usually get...

select(32, [5 23 31], [], NULL, {43, 450000}) = 0 (Timeout)
gettimeofday({1224652458, 61107}, NULL) = 0
geteuid()                               = 0
getegid()                               = 0
setgroups(0, [])                        = 0
setresgid(4294967295, 0, 4294967295)    = 0
getegid()                               = 0
setresuid(0, 0, 4294967295)             = 0
geteuid()                               = 0
write(23, "\205\0\0\0", 4)              = 4
gettimeofday({1224652458, 61549}, NULL) = 0
geteuid()                               = 0
fstat(25, {st_mode=S_IFREG|0644, st_size=894111, ...}) = 0
gettimeofday({1224652458, 61698}, NULL) = 0
select(32, [5 23 31], [], NULL, {60, 0} <unfinished ...>

although a couple of time I got more go by...

...[cut-off]...
getegid()                               = 0
setgroups(0, [])                        = 0
setresgid(4294967295, 0, 4294967295)    = 0
getegid()                               = 0
setresuid(0, 0, 4294967295)             = 0
geteuid()                               = 0
fcntl(8, F_SETLKW, {type=F_RDLCK, whence=SEEK_SET, start=244, len=1}) 0
fcntl(8, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=244, len=1}) 0
stat("/etc/pam.d", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
open("/etc/pam.d/samba", O_RDONLY)      = 25
fstat(25, {st_mode=S_IFREG|0644, st_size=69, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x7f2f8db98000
read(25, "@include common-auth\n@include co"..., 4096) = 69
stat("/etc/pam.d", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
open("/etc/pam.d/common-auth", O_RDONLY) = 29
fstat(29, {st_mode=S_IFREG|0644, st_size=484, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x7f2f8db97000
read(29, "#\n# /etc/pam.d/common-auth - aut"..., 4096) = 484
open("/lib/security/pam_unix.so", O_RDONLY) = 30
read(30,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260*\0\0"...,
832) = 832
fstat(30, {st_mode=S_IFREG|0644, st_size=50568, ...}) = 0
mmap(NULL, 2195080, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 30,
0) = 0x7f2f892fd000
mprotect(0x7f2f89309000, 2093056, PROT_NONE) = 0
mmap(0x7f2f89508000, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 30, 0xb000) = 0x7f2f89508000
mmap(0x7f2f89509000, 48776, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f2f89509000
close(30)                               = 0
open("/etc/ld.so.cache", O_RDONLY)      = 30
fstat(30, {st_mode=S_IFREG|0644, st_size=45774, ...}) = 0
mmap(NULL, 45774, PROT_READ, MAP_PRIVATE, 30, 0) = 0x7f2f8db8b000
close(30)                               = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or
directory)
open("/lib/libselinux.so.1", O_RDONLY)  = 30
read(30,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240Q\0\0"...,
832) = 832
fstat(30, {st_mode=S_IFREG|0644, st_size=109368, ...}) = 0
mmap(NULL, 2209176, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 30,
0) = 0x7f2f888d4000
mprotect(0x7f2f888ed000, 2097152, PROT_NONE) = 0
mmap(0x7f2f88aed000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 30, 0x19000) = 0x7f2f88aed000
mmap(0x7f2f88aef000, 1432, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f2f88aef000
close(30)                               = 0
open("/etc/selinux/config", O_RDONLY)   = -1 ENOENT (No such file or
directory)
statfs("/selinux", 0x7fff960e0250)      = -1 ENOENT (No such file or
directory)
open("/proc/mounts", O_RDONLY)          = 30
fstat(30, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x7f2f8db8a000
read(30, "rootfs / rootfs rw 0 0\nnone /sys"..., 1024) = 1024
read(30, "dered 0 0\n/dev/mapper/group-mate"..., 1024) = 649
read(30, "", 1024)                      = 0
close(30)                               = 0
munmap(0x7f2f8db8a000, 4096)            = 0
munmap(0x7f2f8db8b000, 45774)           = 0
open("/lib/security/pam_smbpass.so", O_RDONLY) = -1 ENOENT (No such
file
or directory)
read(29, "", 4096)                      = 0
close(29)                               = 0
munmap(0x7f2f8db97000, 4096)            = 0
stat("/etc/pam.d", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
open("/etc/pam.d/common-account", O_RDONLY) = 29
fstat(29, {st_mode=S_IFREG|0644, st_size=392, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x7f2f8db97000
read(29, "#\n# /etc/pam.d/common-account - "..., 4096) = 392
read(29, "", 4096)                      = 0
close(29)                               = 0
munmap(0x7f2f8db97000, 4096)            = 0
stat("/etc/pam.d", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
open("/etc/pam.d/common-session", O_RDONLY) = 29
fstat(29, {st_mode=S_IFREG|0644, st_size=372, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x7f2f8db97000
read(29, "#\n# /etc/pam.d/common-session - "..., 4096) = 372
read(29, "", 4096)                      = 0
close(29)                               = 0
munmap(0x7f2f8db97000, 4096)            = 0
read(25, "", 4096)                      = 0
close(25)                               = 0
munmap(0x7f2f8db98000, 4096)            = 0
open("/etc/pam.d/other", O_RDONLY)      = 25
fstat(25, {st_mode=S_IFREG|0644, st_size=520, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x7f2f8db98000
read(25, "#\n# /etc/pam.d/other - specify t"..., 4096) = 520
stat("/etc/pam.d", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
open("/etc/pam.d/common-auth", O_RDONLY) = 29
fstat(29, {st_mode=S_IFREG|0644, st_size=484, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x7f2f8db97000
read(29, "#\n# /etc/pam.d/common-auth - aut"..., 4096) = 484
read(29, "", 4096)                      = 0
close(29)                               = 0
munmap(0x7f2f8db97000, 4096)            = 0
stat("/etc/pam.d", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
open("/etc/pam.d/common-account", O_RDONLY) = 29
fstat(29, {st_mode=S_IFREG|0644, st_size=392, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x7f2f8db97000
read(29, "#\n# /etc/pam.d/common-account - "..., 4096) = 392
read(29, "", 4096)                      = 0
close(29)                               = 0
munmap(0x7f2f8db97000, 4096)            = 0
stat("/etc/pam.d", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
open("/etc/pam.d/common-password", O_RDONLY) = 29
fstat(29, {st_mode=S_IFREG|0644, st_size=1571, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x7f2f8db97000
read(29, "#\n# /etc/pam.d/common-password -"..., 4096) = 1571
read(29, "", 4096)                      = 0
close(29)                               = 0
munmap(0x7f2f8db97000, 4096)            = 0
stat("/etc/pam.d", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
open("/etc/pam.d/common-session", O_RDONLY) = 29
fstat(29, {st_mode=S_IFREG|0644, st_size=372, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x7f2f8db97000
read(29, "#\n# /etc/pam.d/common-session - "..., 4096) = 372
read(29, "", 4096)                      = 0
close(29)                               = 0
munmap(0x7f2f8db97000, 4096)            = 0
read(25, "", 4096)                      = 0
close(25)                               = 0
munmap(0x7f2f8db98000, 4096)            = 0
getuid()                                = 0
gettimeofday({1224651679, 698762}, NULL) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0
sendto(19, "<86>Oct 21 22:01:19 smbd: pam_un"..., 84,
MSG_NOSIGNAL,
NULL, 0) = 84
munmap(0x7f2f892fd000, 2195080)         = 0
munmap(0x7f2f888d4000, 2209176)         = 0
fcntl(8, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=244, len=1}) 0
fcntl(8, F_SETLK, {type=F_WRLCK, whence=SEEK_SET, start=119392, len=1})
= 0
fcntl(8, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=119392, len=1})
= 0
fcntl(8, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=164, len=1}) 0
fcntl(8, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=164, len=1}) 0
fcntl(8, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=244, len=1}) 0
write(23,
"\0\0\0\'\377SMBt\0\0\0\0\210\1\310\0\0\0\0\0\0\0\0\0\0"...,
43) = 43
gettimeofday({1224651679, 699806}, NULL) = 0
select(32, [5 23 31], [], NULL, {60, 0}) = 1 (in [23], left {60, 0})
read(23, "\0\0\0#", 4)                  = 4
read(23,
"\377SMBq\0\0\0\0\30\7\310\0\0\0\0\0\0\0\0\0\0\0\0\3\0\377"...,
35) = 35
geteuid()                               = 0
getegid()                               = 0
setgroups(0, [])                        = 0
setresgid(4294967295, 0, 4294967295)    = 0
getegid()                               = 0
setresuid(0, 0, 4294967295)             = 0
geteuid()                               = 0
chdir("/srv/materials")                 = 0
geteuid()                               = 0
getegid()                               = 0
setgroups(0, [])                        = 0
setresgid(4294967295, 0, 4294967295)    = 0
getegid()                               = 0
setresuid(0, 0, 4294967295)             = 0
geteuid()                               = 0
gettimeofday({1224651679, 700334}, NULL) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0
geteuid()                               = 0
write(26, "[2008/10/21 22:01:19, 1] smbd/se"..., 57) = 57
geteuid()                               = 0
write(26, "  10.42.70.34 (10.42.70.34) clos"..., 67) = 67
fcntl(9, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=300, len=1}) 0
fcntl(9, F_SETLK, {type=F_WRLCK, whence=SEEK_SET, start=992424, len=1})
= 0
fcntl(9, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=992424, len=1})
= 0
fcntl(9, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=164, len=1}) 0
fcntl(9, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=164, len=1}) 0
fcntl(9, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=300, len=1}) 0
chdir("/")                              = 0
geteuid()                               = 0
getegid()                               = 0
setgroups(0, [])                        = 0
setresgid(4294967295, 0, 4294967295)    = 0
getegid()                               = 0
setresuid(0, 0, 4294967295)             = 0
geteuid()                               = 0
write(23,
"\0\0\0#\377SMBq\0\0\0\0\210\1\310\0\0\0\0\0\0\0\0\0\0\0"...,
39) = 39
gettimeofday({1224651679, 701084}, NULL) = 0
select(32, [5 23 31], [], NULL, {60, 0} <unfinished ...>
Process 7683 detached


Any help would be much appreciated as I'm relying on accurate sessions
in order to be able to have accurate records of who's on where and when
(student accountability!)