Bug 3933 - "broken pipe" problem
"broken pipe" problem
Status: ASSIGNED
Product: Samba 3.0
Classification: Unclassified
Component: File Services
3.0.23b
All Windows 2000
: P3 normal
: none
Assigned To: Samba Bugzilla Account
Samba QA Contact
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2006-07-14 08:20 UTC by Sven Strickroth
Modified: 2007-09-11 09:18 UTC (History)
2 users (show)

See Also:


Attachments
SQL-logging patch (8.12 KB, patch)
2006-07-14 10:39 UTC, Sven Strickroth
no flags Details
debug-log (7.46 KB, text/plain)
2006-07-14 10:55 UTC, Sven Strickroth
no flags Details
debug-patch (709 bytes, patch)
2006-07-15 14:50 UTC, Sven Strickroth
no flags Details
debug-log (3.09 KB, text/plain)
2006-07-15 14:57 UTC, Sven Strickroth
no flags Details
SMB configuration as referred to in comment #12 (1.01 KB, text/plain)
2006-08-23 13:16 UTC, Stephen van Egmond
no flags Details
second debug-patch (w/o mysql-stuff) (612 bytes, patch)
2006-09-04 19:12 UTC, Sven Strickroth
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Sven Strickroth 2006-07-14 08:20:00 UTC
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).
Comment 1 Jeremy Allison 2006-07-14 10:24:39 UTC
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.
Comment 2 Sven Strickroth 2006-07-14 10:39:34 UTC
Created attachment 2035 [details]
SQL-logging patch
Comment 3 Sven Strickroth 2006-07-14 10:55:15 UTC
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.
Comment 4 Gerald (Jerry) Carter 2006-07-14 11:01:03 UTC
I like the patch but I would really prefer to se this integrated 
with SACL support.
Comment 5 Sven Strickroth 2006-07-14 11:18:58 UTC
(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) :)
Comment 6 Jeremy Allison 2006-07-14 11:30:33 UTC
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.
Comment 7 Sven Strickroth 2006-07-15 14:50:56 UTC
Created attachment 2039 [details]
debug-patch

debug output follows
Comment 8 Sven Strickroth 2006-07-15 14:57:29 UTC
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.
Comment 9 Jeremy Allison 2006-07-15 15:00:54 UTC
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
Comment 10 Sven Strickroth 2006-07-15 15:11:14 UTC
(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...
Comment 11 Sven Strickroth 2006-07-22 05:30:26 UTC
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...
Comment 12 Stephen van Egmond 2006-08-23 13:14:15 UTC
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.
Comment 13 Stephen van Egmond 2006-08-23 13:16:04 UTC
Created attachment 2102 [details]
SMB configuration as referred to in comment #12
Comment 14 Sven Strickroth 2006-09-04 19:12:59 UTC
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
Comment 15 Sven Strickroth 2006-09-04 19:19:14 UTC
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.