When a smb-connection ends like this (which happens quite often; suppose a windows-bug): "Jul 14 10:46:45 fileserver smbd[13283]: [2006/07/14 10:46:45, 0] lib/util_sock.c:read_data(534) Jul 14 10:46:45 fileserver smbd[13283]: read_data: read failure for 4 bytes to client 192.168.18.1. Error = Keine Route zum Zielrechner Jul 14 10:46:45 fileserver smbd[13283]: [2006/07/14 10:46:45, 0] lib/util_sock.c:write_data(562) Jul 14 10:46:45 fileserver smbd[13283]: write_data: write failure in writing to client 192.168.18.1. Error Datenübergabe unterbrochen (broken pipe) Jul 14 10:46:45 fileserver smbd[13283]: [2006/07/14 10:46:45, 0] lib/util_sock.c:send_smb(769) Jul 14 10:46:45 fileserver smbd[13283]: Error writing 75 bytes to client. -1. (Datenübergabe unterbrochen (broken pipe))" Locked files weren't unlocked and "smbd/session.c:session_yield" isn't executed (important for utmp-logging).
Dead records left in the lock database aren't an issue - the next opener of that dev/ino pair detects they are dead and removes them. Not calling session_yield on exit is a strange report. Look in smbd/server.c in exit_server_common() which should be called on all server exit paths. In there is a call to : invalidate_all_vuids() which calls : invalidate_vuid() for each active vuid. invalidate_vuid calls : session_yield() for each vuid. If you're sure this is happening can you test by adding debug statements ? Jeremy.
Created attachment 2035 [details] SQL-logging patch
Created attachment 2036 [details] debug-log I've set mysqllogginglog to Yes, so I've some more debugging. As u can see when "broken pipe occours" no "UPDATE..." is logged, so I assume that the function isn't called.
I like the patch but I would really prefer to se this integrated with SACL support.
(In reply to comment #4) > I like the patch but I would really prefer to see this integrated > with SACL support. Yep (any hints for doing that?), but that doesn't solve the problem atm (even when s.o. uses utmp) :)
There are many other early returns in session_yield, what I suggest is just adding a debug level zero before every "return" statement to try why this is being terminated early. I'm pretty sure session_yield is being called on exit. Jeremy.
Created attachment 2039 [details] debug-patch debug output follows
Created attachment 2040 [details] debug-log as you can see, where the "broken pipe" is (pid 18327), there is no "1", "2", "3" or "4" and the session is in MySQL still "open" (outtime = 0). So I suppose session-yield isn't called.
If session_yeild isn't called what are these messages in your log ? Jul 15 11:24:26 fileserver smbd[7608]: [2006/07/15 11:24:26, 0] smbd/session.c:session_yield(222) I don't understand your sql stuff and don't know what you're trying to do with it - please remove it and test by just adding standard DEBUG messages into the code as I asked. That way I'll know the base code is good. Jeremy
(In reply to comment #9) > If session_yeild isn't called what are these messages in your log ? > Jul 15 11:24:26 fileserver smbd[7608]: [2006/07/15 11:24:26, 0] > smbd/session.c:session_yield(222) It is called, but not when "broken pipe" occours. See pid 18327. There is no debug log from "smbd/session.c:session_yield". > I don't understand your sql stuff and don't know what you're trying to do with > it - please remove it and test by just adding standard DEBUG messages into the > code as I asked. That way I'll know the base code is good. I need it cuz it's my production server (don't beat me). When session_yield is called there must be at least the debug "1". I try to debug some more and write my results here...
When I set the debug-level to 100 the problem doesn't occour at all: no error like this "Jul 14 10:46:45 fileserver smbd[13283]: Error writing 75 bytes to client. -1. (Datenübergabe unterbrochen (broken pipe))" and smbd/session.c:session_yield always logs the logout. :( I go on testing with debug-level 0...
I am experiencing a similar problem, on a completely stock Samba installation on Ubuntu. Package version = 3.0.22-1ubuntu3.1. Clients are Mac OSX, over a gigabit network. Approximately once a day, while transferring files (read or write to samba, doesn't seem to matter) samba will log the following: [2006/08/16 19:40:41, 0] lib/util_sock.c:read_data(529) read_data: read failure for 4 bytes to client 10.10.171.112. Error = No route to host [2006/08/16 19:40:41, 1] smbd/service.c:close_cnum(890) alicia-murlende (10.10.171.112) closed connection to service 2-regen-archive [2006/08/16 19:40:43, 0] lib/util_sock.c:read_data(529) read_data: read failure for 4 bytes to client 10.10.171.112. Error = No route to host [2006/08/16 19:40:43, 1] smbd/service.c:close_cnum(890) And the client will report the connection closed unexpectedly. I will attach the smb.conf next... Happy to help debug this, I have a fair bit of latitude in how the system is configured and operates. It's in production, but not heavily used.
Created attachment 2102 [details] SMB configuration as referred to in comment #12
Created attachment 2121 [details] second debug-patch (w/o mysql-stuff) I applied that patch to smbd and then I run it. smbstatus shows me some unlocked files on pid 28749 (but that PID isn't running any more), so this is a hint that session_yield isn't called and the user isn't logged out correctly. All those session_yields (debug 1 and 2) before the broken pipe are caused by a lot of mapped network-drives... I cannot say what this occours, but it occours sometimes (5-12 times a day). [root@fileserver /var/log]# grep 28749 messages Sep 4 09:09:05 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:05, 0] smbd/session.c:session_yield(170) Sep 4 09:09:05 fileserver smbd_vscan-clamav[28749]: 1 Sep 4 09:09:05 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:05, 0] smbd/session.c:session_yield(174) Sep 4 09:09:05 fileserver smbd_vscan-clamav[28749]: 2 Sep 4 09:09:06 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:06, 0] smbd/session.c:session_yield(170) Sep 4 09:09:06 fileserver smbd_vscan-clamav[28749]: 1 Sep 4 09:09:06 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:06, 0] smbd/session.c:session_yield(174) Sep 4 09:09:06 fileserver smbd_vscan-clamav[28749]: 2 Sep 4 09:09:06 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:06, 0] smbd/session.c:session_yield(170) Sep 4 09:09:06 fileserver smbd_vscan-clamav[28749]: 1 Sep 4 09:09:06 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:06, 0] smbd/session.c:session_yield(174) Sep 4 09:09:06 fileserver smbd_vscan-clamav[28749]: 2 Sep 4 09:09:08 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:08, 0] smbd/session.c:session_yield(170) Sep 4 09:09:08 fileserver smbd_vscan-clamav[28749]: 1 Sep 4 09:09:08 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:08, 0] smbd/session.c:session_yield(174) Sep 4 09:09:08 fileserver smbd_vscan-clamav[28749]: 2 Sep 4 09:09:08 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:08, 0] smbd/session.c:session_yield(170) Sep 4 09:09:08 fileserver smbd_vscan-clamav[28749]: 1 Sep 4 09:09:08 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:08, 0] smbd/session.c:session_yield(174) Sep 4 09:09:08 fileserver smbd_vscan-clamav[28749]: 2 Sep 4 09:09:09 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:09, 0] smbd/session.c:session_yield(170) Sep 4 09:09:09 fileserver smbd_vscan-clamav[28749]: 1 Sep 4 09:09:09 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:09, 0] smbd/session.c:session_yield(174) Sep 4 09:09:09 fileserver smbd_vscan-clamav[28749]: 2 Sep 4 09:09:16 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:16, 0] smbd/session.c:session_yield(170) Sep 4 09:09:16 fileserver smbd_vscan-clamav[28749]: 1 Sep 4 09:09:16 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:16, 0] smbd/session.c:session_yield(174) Sep 4 09:09:16 fileserver smbd_vscan-clamav[28749]: 2 Sep 4 09:09:16 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:16, 0] smbd/session.c:session_yield(170) Sep 4 09:09:16 fileserver smbd_vscan-clamav[28749]: 1 Sep 4 09:09:16 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:16, 0] smbd/session.c:session_yield(174) Sep 4 09:09:16 fileserver smbd_vscan-clamav[28749]: 2 Sep 4 09:09:17 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:17, 0] smbd/session.c:session_yield(170) Sep 4 09:09:17 fileserver smbd_vscan-clamav[28749]: 1 Sep 4 09:09:17 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:17, 0] smbd/session.c:session_yield(174) Sep 4 09:09:17 fileserver smbd_vscan-clamav[28749]: 2 Sep 4 09:09:22 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:22, 0] smbd/session.c:session_yield(170) Sep 4 09:09:22 fileserver smbd_vscan-clamav[28749]: 1 Sep 4 09:09:22 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:22, 0] smbd/session.c:session_yield(174) Sep 4 09:09:22 fileserver smbd_vscan-clamav[28749]: 2 Sep 4 09:09:30 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:30, 0] smbd/session.c:session_yield(170) Sep 4 09:09:30 fileserver smbd_vscan-clamav[28749]: 1 Sep 4 09:09:30 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:30, 0] smbd/session.c:session_yield(174) Sep 4 09:09:30 fileserver smbd_vscan-clamav[28749]: 2 Sep 4 09:09:30 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:30, 0] smbd/session.c:session_yield(170) Sep 4 09:09:30 fileserver smbd_vscan-clamav[28749]: 1 Sep 4 09:09:30 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:09:30, 0] smbd/session.c:session_yield(174) Sep 4 09:09:30 fileserver smbd_vscan-clamav[28749]: 2 Sep 4 09:36:38 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:36:38, 0] lib/util_sock.c:read_data(534) Sep 4 09:36:38 fileserver smbd_vscan-clamav[28749]: read_data: read failure for 4 bytes to client 192.168.10.12. Error = Keine Route zum Zielrechner Sep 4 09:36:38 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:36:38, 0] lib/util_sock.c:write_data(562) Sep 4 09:36:38 fileserver smbd_vscan-clamav[28749]: write_data: write failure in writing to client 192.168.10.12. Error Datenübergabe unterbrochen (broken pipe) Sep 4 09:36:38 fileserver smbd_vscan-clamav[28749]: [2006/09/04 09:36:38, 0] lib/util_sock.c:send_smb(769) Sep 4 09:36:38 fileserver smbd_vscan-clamav[28749]: Error writing 75 bytes to client. -1. (Datenübergabe unterbrochen (broken pipe)) There is no DEBUG4 after the broken pipe, so I assume again that session_yield isn't called correctly. A normal logout looks like this: Sep 5 00:17:30 fileserver smbd_vscan-clamav[31807]: [2006/09/05 00:17:30, 0] smbd/session.c:session_yield(170) Sep 5 00:17:30 fileserver smbd_vscan-clamav[31807]: 1 Sep 5 00:17:30 fileserver smbd_vscan-clamav[31807]: [2006/09/05 00:17:30, 0] smbd/session.c:session_yield(174) Sep 5 00:17:30 fileserver smbd_vscan-clamav[31807]: 2 Sep 5 00:17:30 fileserver smbd_vscan-clamav[31807]: [2006/09/05 00:17:30, 0] smbd/session.c:session_yield(185) Sep 5 00:17:30 fileserver smbd_vscan-clamav[31807]: 3 Sep 5 00:17:30 fileserver smbd_vscan-clamav[31807]: [2006/09/05 00:17:30, 0] smbd/session.c:session_yield(202) Sep 5 00:17:30 fileserver smbd_vscan-clamav[31807]: 4
I forgot to add that we use W2K-clients with domain-logons to samba-server (now samba 3.0.23c). The user-profile is on the samba-server (roaming profile, which is deleted on the workstation after logging off, we just roam the ntuser.dat/ini-files the rest is on the server using "USER SHELL FOLDERS"). I suppose that this problem happens when s.o. uses "restart" or "logoff" on the client (maybe several times) and w2k closes the connection and establishes again one for a few secs (I suppose for the profile-stuff). When you need my smb.conf just tell me and i post it here.