Bug 4887 - INTERNAL ERROR: Signal 11 in smbd reply_write_and_X -> write_file -> memset
INTERNAL ERROR: Signal 11 in smbd reply_write_and_X -> write_file -> memset
Status: ASSIGNED
Product: Samba 3.0
Classification: Unclassified
Component: File Services
3.0.25b
x86 Linux
: P3 normal
: none
Assigned To: Samba Bugzilla Account
Samba QA Contact
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2007-08-15 11:50 UTC by Orion Poplawski
Modified: 2007-08-15 14:49 UTC (History)
0 users

See Also:


Attachments
smb log with log level = 10 (46.69 KB, application/octet-stream)
2007-08-15 14:49 UTC, Orion Poplawski
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Orion Poplawski 2007-08-15 11:50:13 UTC
Getting these fairly frequently on a Fedora 7 box:

Aug 12 09:01:00 saga smbd[20225]: [2007/08/12 09:01:00, 0] lib/fault.c:fault_report(41)
Aug 12 09:01:00 saga smbd[20225]:   ======================================================
=========
Aug 12 09:01:00 saga smbd[20225]: [2007/08/12 09:01:00, 0] lib/fault.c:fault_report(42)
Aug 12 09:01:00 saga smbd[20225]:   INTERNAL ERROR: Signal 11 in pid 20225 (3.0.25b-2.fc7)

Aug 12 09:01:00 saga smbd[20225]:   Please read the Trouble-Shooting section of the Samba3
-HOWTO
Aug 12 09:01:00 saga smbd[20225]: [2007/08/12 09:01:00, 0] lib/fault.c:fault_report(44)
Aug 12 09:01:00 saga smbd[20225]:
Aug 12 09:01:00 saga smbd[20225]:   From: http://www.samba.org/samba/docs/Samba3-HOWTO.pdf

Aug 12 09:01:00 saga smbd[20225]: [2007/08/12 09:01:00, 0] lib/fault.c:fault_report(45)
Aug 12 09:01:00 saga smbd[20225]:   ======================================================
=========
Aug 12 09:01:00 saga smbd[20225]: [2007/08/12 09:01:00, 0] lib/util.c:smb_panic(1654)
Aug 12 09:01:00 saga smbd[20225]:   PANIC (pid 20225): internal error
Aug 12 09:01:00 saga smbd[20225]: [2007/08/12 09:01:00, 0] lib/util.c:log_stack_trace(1758
)
Aug 12 09:01:00 saga smbd[20225]:   BACKTRACE: 12 stack frames:
Aug 12 09:01:00 saga smbd[20225]:    #0 smbd(log_stack_trace+0x2d) [0x802439fd]
Aug 12 09:01:00 saga smbd[20225]:    #1 smbd(smb_panic+0x5d) [0x80243b2d]
Aug 12 09:01:00 saga smbd[20225]:    #2 smbd [0x8022e53a]
Aug 12 09:01:00 saga smbd[20225]:    #3 [0x12d420]
Aug 12 09:01:00 saga smbd[20225]:    #4 /lib/libc.so.6(memset+0x37) [0x3d86f7]
Aug 12 09:01:00 saga smbd[20225]:    #5 smbd(write_file+0x979) [0x80067169]
Aug 12 09:01:00 saga smbd[20225]:    #6 smbd(reply_write_and_X+0x571) [0x80086261]
Aug 12 09:01:00 saga smbd[20225]:    #7 smbd [0x800c54d0]
Aug 12 09:01:00 saga smbd[20225]:    #8 smbd(smbd_process+0x836) [0x800c6566]
Aug 12 09:01:00 saga smbd[20225]:    #9 smbd(main+0xbdd) [0x8032079d]
Aug 12 09:01:00 saga smbd[20225]:    #10 /lib/libc.so.6(__libc_start_main+0xe0) [0x37ef70]

Aug 12 09:01:00 saga smbd[20225]:    #11 smbd [0x8004a181]
Aug 12 09:01:00 saga smbd[20225]: [2007/08/12 09:01:00, 0] lib/fault.c:dump_core(181)
Aug 12 09:01:00 saga smbd[20225]:   dumping core in /var/log/samba/cores/smbd
Aug 12 09:01:00 saga smbd[20225]:

I believe this is during Ghost writing a backup to the share.

(gdb) bt
#0  0x0012d402 in __kernel_vsyscall ()
#1  0x00391fa0 in raise () from /lib/libc.so.6
#2  0x003938b1 in abort () from /lib/libc.so.6
#3  0x8022dff9 in dump_core () at lib/fault.c:192
#4  0x80243be5 in smb_panic (why=0x8037ca8c "internal error") at lib/util.c:1670
#5  0x8022e53a in sig_fault (sig=11) at lib/fault.c:47
#6  <signal handler called>
#7  0x003d86f7 in memset () from /lib/libc.so.6
#8  0x80067169 in write_file (fsp=0x80e43c70, data=0x80e53954 "", pos=113377280,
    n=4181983233) at /usr/include/bits/string3.h:96
#9  0x80086261 in reply_write_and_X (conn=0x80e941d0, inbuf=0x80e53910 "",
    outbuf=0x80e73d58 "", length=69, bufsize=131072) at smbd/reply.c:3135
#10 0x800c54d0 in switch_message (type=47, inbuf=0x80e53910 "", outbuf=0x80e73d58 "",
    size=69, bufsize=131072) at smbd/process.c:1003
#11 0x800c6566 in smbd_process () at smbd/process.c:1030
#12 0x8032079d in main (argc=-1109787819, argv=0xbfe3ff34) at smbd/server.c:1120

(gdb) print *fsp
$2 = {next = 0x0, prev = 0x0, fnum = 5408, conn = 0x80e941d0, fh = 0x80debc38,
  num_smb_operations = 3390, rap_print_jobid = 0, dev = 2145, inode = 351842,
  initial_allocation_size = 0, mode = 33268, file_pid = 1628, vuid = 101,
  wbmpx_ptr = 0x0, wcp = 0x80e95080, open_time = {tv_sec = 1187114387,
    tv_usec = 808635}, access_mask = 131487, share_access = 1,
  pending_modtime_owner = 0, pending_modtime = {tv_sec = 0, tv_nsec = 0},
  last_write_time = {tv_sec = 0, tv_nsec = 0}, oplock_type = 3, sent_oplock_break = 0,
  oplock_timeout = 0x0, last_lock_failure = {context = {smbpid = 0, tid = 0, pid = {
        pid = 0}}, start = 0, size = 0, fnum = 0, lock_type = READ_LOCK,
    lock_flav = WINDOWS_LOCK}, current_lock_count = 0, pending_break_messages = 0x0,
  num_pending_break_messages = 0, can_lock = 1, can_read = 1, can_write = 1,
  print_file = 0, modified = 1, is_directory = 0, is_stat = 0, aio_write_behind = 0,
  lockdb_clean = 0, initial_delete_on_close = 0, posix_open = 0,
  fsp_name = 0x80dee748 "nome/C_Drive118_i001.iv2i", vfs_extension = 0x0,
  fake_file_handle = 0x0, notify = 0x0}
Comment 1 Orion Poplawski 2007-08-15 11:59:11 UTC
Looks like the memsets in write_file are:

memset(wcp->data + wcp->data_size, '\0', pos - (wcp->offset + wcp->data_size) );

and

memset(wcp->data, '\0', wcp->data_size);

(gdb) print *wcp
$7 = {file_size = 112984064, offset = 112984064, alloc_size = 262144,
  data_size = 393216, data = 0x80eb5938 ""}
(gdb) print pos
$8 = 113377280
Comment 2 Jeremy Allison 2007-08-15 12:21:28 UTC
I'm assuming you have "write cache size = XXX" set in your smb.conf ?
I recently fixed a bug in this (reported by another user). Can you
check out the SAMBA_3_0_25 svn tree to test this ? I think this should
be fixed for 3.0.25c but I'd like to be sure. You could also remove the
write cache size parameter and check that also fixes it.
Jeremy.
Comment 3 Orion Poplawski 2007-08-15 13:26:39 UTC
(In reply to comment #2)
> I'm assuming you have "write cache size = XXX" set in your smb.conf ?

Indeed.  I've installed the latest SAMBA_3_0_25 svn branch and we'll give that a try.

BTW - is it possible for a client to override the write cache setting?  I'm trying to track down slow SMB performance from Mac OS X clients and it appears that their writes are written to disk in 4kb chunks despite the write cache size = 262144 setting for that share.
Comment 4 Jeremy Allison 2007-08-15 13:42:04 UTC
write cache is only used for oplocked files, and clients can defeat it be doing a scatter write pattern. I'd need to see debug level 10 logs to see why this is occurring.
Jeremy.
Comment 5 Orion Poplawski 2007-08-15 14:49:36 UTC
Created attachment 2867 [details]
smb log with log level = 10 

This is a log from a OS X client doing a write of a 512k file.  Looks like oplocks aren't being used at all, and hence no write cache.  I don't know if there are any other things that would obviously impair performance.  I only see about 3.4MB/s writing from a OS X client and around 8.8MB/s from a linux client.