SOLVED smbd Crashing (Signal 4) on File Delete

[ewhac]

I am currently running FreeNAS-9.3-STABLE-201505130355, and have observed a weird issue that will probably have @cyberjock issuing well-earned snark.

I have a single CIFS share that is sharing home directories for all the FreeNAS users. I set it up back in the FreeNAS 8.3 days, using UNIX permissions. The share is accessed via both Windows and Linux clients. This setup has worked without major issue for some time.

Last week, an attempt to delete a file caused smbd to repeatedly crash:

Code:

May 31 01:28:49 alexandria smbd[2289]:  STATUS=daemon 'smbd' finished starting up and ready to serve connectionsScheduled cleanup of brl and lock database after unclean shutdown
May 31 01:28:49 alexandria kernel: pid 80807 (smbd), uid 1001: exited on signal 4 (core dumped)
May 31 01:28:59 alexandria winbindd[2296]: [2015/05/31 01:28:59.964789,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:28:59 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:00 alexandria winbindd[2296]: [2015/05/31 01:29:00.055145,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:00 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:00 alexandria winbindd[2296]: [2015/05/31 01:29:00.056297,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:00 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:00 alexandria winbindd[2296]: [2015/05/31 01:29:00.059923,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:00 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:00 alexandria kernel: pid 81087 (smbd), uid 1001: exited on signal 4 (core dumped)
May 31 01:29:10 alexandria winbindd[2296]: [2015/05/31 01:29:10.484314,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:10 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:10 alexandria winbindd[2296]: [2015/05/31 01:29:10.507320,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:10 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:10 alexandria winbindd[2296]: [2015/05/31 01:29:10.508460,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:10 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:10 alexandria winbindd[2296]: [2015/05/31 01:29:10.512060,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:10 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:10 alexandria kernel: pid 81088 (smbd), uid 1001: exited on signal 4 (core dumped)
May 31 01:29:20 alexandria winbindd[2296]: [2015/05/31 01:29:20.928624,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:20 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:20 alexandria winbindd[2296]: [2015/05/31 01:29:20.952273,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:20 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:20 alexandria winbindd[2296]: [2015/05/31 01:29:20.953541,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:20 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:20 alexandria winbindd[2296]: [2015/05/31 01:29:20.957199,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:20 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:21 alexandria kernel: pid 81089 (smbd), uid 1001: exited on signal 4 (core dumped)
May 31 01:29:31 alexandria winbindd[2296]: [2015/05/31 01:29:31.373367,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:31 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:31 alexandria winbindd[2296]: [2015/05/31 01:29:31.396407,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:31 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:31 alexandria winbindd[2296]: [2015/05/31 01:29:31.397558,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:31 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:31 alexandria winbindd[2296]: [2015/05/31 01:29:31.401161,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:31 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:31 alexandria kernel: pid 81095 (smbd), uid 1001: exited on signal 4 (core dumped)
May 31 01:29:41 alexandria winbindd[2296]: [2015/05/31 01:29:41.820456,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:41 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:41 alexandria winbindd[2296]: [2015/05/31 01:29:41.844528,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:41 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:41 alexandria winbindd[2296]: [2015/05/31 01:29:41.845922,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:41 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:41 alexandria winbindd[2296]: [2015/05/31 01:29:41.849732,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:41 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:42 alexandria kernel: pid 81097 (smbd), uid 1001: exited on signal 4 (core dumped)
May 31 01:29:52 alexandria winbindd[2296]: [2015/05/31 01:29:52.263644,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:52 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:52 alexandria winbindd[2296]: [2015/05/31 01:29:52.286747,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:52 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:52 alexandria winbindd[2296]: [2015/05/31 01:29:52.287889,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:52 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:52 alexandria winbindd[2296]: [2015/05/31 01:29:52.291479,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:29:52 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:29:52 alexandria kernel: pid 81098 (smbd), uid 1001: exited on signal 4 (core dumped)
May 31 01:30:02 alexandria winbindd[2296]: [2015/05/31 01:30:02.707551,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:30:02 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:30:02 alexandria winbindd[2296]: [2015/05/31 01:30:02.730806,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:30:02 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:30:02 alexandria winbindd[2296]: [2015/05/31 01:30:02.731970,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:30:02 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:30:02 alexandria winbindd[2296]: [2015/05/31 01:30:02.735625,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:30:02 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:30:03 alexandria kernel: pid 81104 (smbd), uid 1001: exited on signal 4 (core dumped)
May 31 01:30:13 alexandria winbindd[2296]: [2015/05/31 01:30:13.151577,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:30:13 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:30:13 alexandria winbindd[2296]: [2015/05/31 01:30:13.174690,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:30:13 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:30:13 alexandria winbindd[2296]: [2015/05/31 01:30:13.175842,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:30:13 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:30:13 alexandria winbindd[2296]: [2015/05/31 01:30:13.179461,  0] ../source3/winbindd/winbindd_samr.c:769(sam_rids_to_names)
May 31 01:30:13 alexandria winbindd[2296]:  sam_rids_to_names: possible deadlock - trying to lookup SID S-1-5-21-2039921271-1382851169-3180764252
May 31 01:30:13 alexandria kernel: pid 81113 (smbd), uid 1001: exited on signal 4 (core dumped)

The file in question had been created using the Windows client; the deletion was attempted using the 'rm' command from a Linux client. The 'rm' command hung as the above messages accumulated in the logs, until I killed it with ^C. The file itself was perfectly readable from the Linux client.

I ssh'ed into the FreeNAS server and 'rm'ed the file from there without incident.

I haven't yet tried all possible creation/deletion client permutations yet, but the fact that smbd is flat-out crashing seems unusually bad. Any suggestions on how to drill down on the problem? Config file contents available upon request.

 

[SweetAndLow]

The deadlock issue has to do with a old freenas bug. Search around for the fix and it will go away forever. I don't think it ever caused a crash though. So there might be a new issue.

 

[ewhac]

The deadlock issue has to do with a old freenas bug. Search around for the fix and it will go away forever.

You would be referring to fixsid.py? Nope. I had the "possible deadlock" issue a while back (before updating to 9.3, I think). fixsid.py fixed it back then, but now it's back (which surprised me). Running fixsid.py again results in a message to the effect of, "Nope, everything looks fine to me..." Rebooting also doesn't make the problem go away.

 

[anodos]

Enter following commands:

Code:

service samba_server stop
rm -rf /var/db/samba4/*
rm -rf /var/etc/private*
net groupmap cleanup
service ix-pre-samba start
service samba_server start

I think those are the proper commands. YMMV, IANAL, etc.

 

[ewhac]

I'll give those a try this evening (all run as root, one presumes).

 

[DrKK]

Enter following commands:

Code:

service samba_server stop
rm -rf /var/db/samba4/*
rm -rf /var/etc/private*
net groupmap cleanup
service ix-pre-samba start
service samba_server start

I think those are the proper commands. YMMV, IANAL, etc.

What does "net groupmap cleanup" do? Just curious.

 

[anodos]

What does "net groupmap cleanup" do? Just curious.

It blows away the mappings between Windows group SIDs and UNIX groups (to view such mappings type "net groupmap list"). If you want a headache, read samba's manpage for the "net" command. Of course -in typical samba fashion- the command "net groupmap cleanup" isn't listed in the manpage.

I believe the above series of commands above will
1) stop samba
2-3) nuke the info stored in samba-related config databases
4) blow away the chaff
5) regenerate new mappings
6) start samba back up

I made a bug report seeking clarification. We'll see how that goes. :D

 

[DrKK]

It blows away the mappings between Windows group SIDs and UNIX groups (to view such mappings type "net groupmap list"). If you want a headache, read samba's manpage for the "net" command. Of course -in typical samba fashion- the command "net groupmap cleanup" isn't listed in the manpage.

I believe the above series of commands above will
1) stop samba
2-3) nuke the info stored in samba-related config databases
4) blow away the chaff
5) regenerate new mappings
6) start samba back up

I made a bug report seeking clarification. We'll see how that goes. :D

Thanks for the information.

 

[ewhac]

Finally got around to trying it again. I performed the cleanup outlined above, which stopped the SID/deadlock messages. I copied a ZIP file from the Windows client to the NAS, rebooted into Linux, and successfully unzipped the file from the Linux client. However, when I try to delete the file, 'smbd' crashes in a loop, this time without the SID messages:

Code:

Jun 26 00:00:00 alexandria syslog-ng[1690]: Configuration reload request received, reloading configuration;
Jun 26 00:59:44 alexandria smbd[12293]:  STATUS=daemon 'smbd' finished starting up and ready to serve connectionsScheduled cleanup of brl and lock database after unclean shutdown
Jun 26 00:59:44 alexandria kernel: pid 6874 (smbd), uid 1001: exited on signal 4 (core dumped)
Jun 26 00:59:54 alexandria kernel: pid 7544 (smbd), uid 1001: exited on signal 4 (core dumped)
Jun 26 01:00:05 alexandria kernel: pid 7553 (smbd), uid 1001: exited on signal 4 (core dumped)
Jun 26 01:00:15 alexandria kernel: pid 7615 (smbd), uid 1001: exited on signal 4 (core dumped)

The messages continue until I kill the 'rm' command with ^C.

Signal 4 means illegal instruction, doesn't it?

 

[ewhac]

Updated to FreeNAS-9.3-STABLE-201506232120; problem persists. Tried bumping max CIFS protocol from 2.x to 3.x; problem persists.

So I decided to crank up the logging level to Debug to see what popped out. I ended up with a collection of log messages in log.smbd which made it look like 'smbd' was stuck in an infinite (recursive?) loop until it finally crashed. The filename I was attempting to delete is named "sw_2013_ost_flac.zip"

Code:

[2015/06/27 17:37:03.673839, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../lib/util/util.c:556(dump_data)
  [0000] 00 00 00 0A 02 00 00 00  00 2F 00 73 00 77 00 5F  ........ ./.s.w._
  [0010] 00 32 00 30 00 31 00 33  00 5F 00 6F 00 73 00 74  .2.0.1.3 ._.o.s.t
  [0020] 00 5F 00 66 00 6C 00 61  00 63 00 2E 00 7A 00 69  ._.f.l.a .c...z.i
  [0030] 00 70 00 00 00 00 00  .p.....
[2015/06/27 17:37:03.673969,  3, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/process.c:1406(switch_message)
  switch message SMBtrans2 (pid 11208) conn 0x8100957e0
[2015/06/27 17:37:03.674002,  4, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/uid.c:384(change_to_user)
  Skipping user change - already user
[2015/06/27 17:37:03.674047,  5, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/filename.c:258(unix_convert)
  unix_convert called on file "sw_2013_ost_flac.zip"
[2015/06/27 17:37:03.674078,  5, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/filename.c:421(unix_convert)
  unix_convert begin: name = sw_2013_ost_flac.zip, dirpath = , start = sw_2013_ost_flac.zip
[2015/06/27 17:37:03.674133,  5, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/filename.c:444(unix_convert)
  conversion of base_name finished sw_2013_ost_flac.zip -> sw_2013_ost_flac.zip
[2015/06/27 17:37:03.674163,  8, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/lib/util.c:995(is_in_path)
  is_in_path: sw_2013_ost_flac.zip
[2015/06/27 17:37:03.674191,  8, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/lib/util.c:1019(is_in_path)
  is_in_path: match not found
[2015/06/27 17:37:03.674220,  3, pid=11208, effective(1001, 1001), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1137(check_reduced_name)
  check_reduced_name [sw_2013_ost_flac.zip] [/mnt/uranus/home/ewhac]
[2015/06/27 17:37:03.674285, 10, pid=11208, effective(1001, 1001), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1197(check_reduced_name)
  check_reduced_name realpath [sw_2013_ost_flac.zip] -> [/mnt/uranus/home/ewhac/sw_2013_ost_flac.zip]
[2015/06/27 17:37:03.674316,  3, pid=11208, effective(1001, 1001), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1267(check_reduced_name)
  check_reduced_name: sw_2013_ost_flac.zip reduced to /mnt/uranus/home/ewhac/sw_2013_ost_flac.zip
[2015/06/27 17:37:03.674348,  3, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/trans2.c:8267(call_trans2setfilepathinfo)
  call_trans2setfilepathinfo(6) sw_2013_ost_flac.zip (fnum [fsp is NULL]) info_level=522 totdata=2
[2015/06/27 17:37:03.674388,  3, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/trans2.c:7844(smbd_do_setfilepathinfo)
  smbd_do_setfilepathinfo: sw_2013_ost_flac.zip (fnum [fsp is NULL]) info_level=522 totdata=2
[2015/06/27 17:37:03.674418, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/trans2.c:7733(smb_posix_unlink)
  smb_posix_unlink: file sw_2013_ost_flac.zip
[2015/06/27 17:37:03.674451, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/open.c:4279(create_file_default)
  create_file: access_mask = 0x10000 file_attributes = 0x10001ff, share_access = 0x7, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x0 private_flags = 0x0 root_dir_fid = 0x0, ea_list = 0x0x0, sd = 0x0x0, fname = sw_2013_ost_flac.zip
[2015/06/27 17:37:03.674493, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/open.c:3787(create_file_unixpath)
  create_file_unixpath: access_mask = 0x10000 file_attributes = 0x10001ff, share_access = 0x7, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x0 private_flags = 0x0 ea_list = 0x0x0, sd = 0x0x0, fname = sw_2013_ost_flac.zip
[2015/06/27 17:37:03.674858, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/trans2.c:262(get_ea_names_from_file)
  get_ea_list_from_file: ea_namelist size = 52
[2015/06/27 17:37:03.674932, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/trans2.c:181(get_ea_value)
  get_ea_value: EA user.DosStream.Zone.Identifier:$DATA is of length 27
[2015/06/27 17:37:03.674961, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../lib/util/util.c:556(dump_data)
  [0000] 5B 5A 6F 6E 65 54 72 61  6E 73 66 65 72 5D 0D 0A  [ZoneTra nsfer]..
  [0010] 5A 6F 6E 65 49 64 3D 33  0D 0A 00  ZoneId=3 ...
[2015/06/27 17:37:03.675050, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/open.c:3463(open_streams_for_delete)
  open_streams_for_delete found 2 streams
[2015/06/27 17:37:03.675083, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/open.c:3494(open_streams_for_delete)
  Unable to stat stream: sw_2013_ost_flac.zip:Zone.Identifier:$DATA
[2015/06/27 17:37:03.675113, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/open.c:4279(create_file_default)
  create_file: access_mask = 0x10000 file_attributes = 0x80, share_access = 0x7, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x0 private_flags = 0x4 root_dir_fid = 0x0, ea_list = 0x0x0, sd = 0x0x0, fname = sw_2013_ost_flac.zip:Zone.Identifier:$DATA
[2015/06/27 17:37:03.675146, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/open.c:3787(create_file_unixpath)
  create_file_unixpath: access_mask = 0x10000 file_attributes = 0x80, share_access = 0x7, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x0 private_flags = 0x4 ea_list = 0x0x0, sd = 0x0x0, fname = sw_2013_ost_flac.zip:Zone.Identifier:$DATA
[2015/06/27 17:37:03.675199, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/trans2.c:262(get_ea_names_from_file)
  get_ea_list_from_file: ea_namelist size = 52
[2015/06/27 17:37:03.675253, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/trans2.c:181(get_ea_value)
  get_ea_value: EA user.DosStream.Zone.Identifier:$DATA is of length 27
[2015/06/27 17:37:03.675345, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../lib/util/util.c:556(dump_data)
  [0000] 5B 5A 6F 6E 65 54 72 61  6E 73 66 65 72 5D 0D 0A  [ZoneTra nsfer]..
  [0010] 5A 6F 6E 65 49 64 3D 33  0D 0A 00  ZoneId=3 ...
[2015/06/27 17:37:03.675420, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/open.c:3463(open_streams_for_delete)
  open_streams_for_delete found 2 streams
[2015/06/27 17:37:03.675450, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/open.c:3494(open_streams_for_delete)
  Unable to stat stream: sw_2013_ost_flac.zip:Zone.Identifier:$DATA
[2015/06/27 17:37:03.675486, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/open.c:4279(create_file_default)
  create_file: access_mask = 0x10000 file_attributes = 0x80, share_access = 0x7, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x0 private_flags = 0x4 root_dir_fid = 0x0, ea_list = 0x0x0, sd = 0x0x0, fname = sw_2013_ost_flac.zip:Zone.Identifier:$DATA
[2015/06/27 17:37:03.675519, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/open.c:3787(create_file_unixpath)
  create_file_unixpath: access_mask = 0x10000 file_attributes = 0x80, share_access = 0x7, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x0 private_flags = 0x4 ea_list = 0x0x0, sd = 0x0x0, fname = sw_2013_ost_flac.zip:Zone.Identifier:$DATA
[2015/06/27 17:37:03.675574, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/trans2.c:262(get_ea_names_from_file)
  get_ea_list_from_file: ea_namelist size = 52
[2015/06/27 17:37:03.675629, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/trans2.c:181(get_ea_value)
  get_ea_value: EA user.DosStream.Zone.Identifier:$DATA is of length 27
[2015/06/27 17:37:03.675657, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../lib/util/util.c:556(dump_data)
  [0000] 5B 5A 6F 6E 65 54 72 61  6E 73 66 65 72 5D 0D 0A  [ZoneTra nsfer]..
  [0010] 5A 6F 6E 65 49 64 3D 33  0D 0A 00  ZoneId=3 ...
[2015/06/27 17:37:03.675732, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/open.c:3463(open_streams_for_delete)
  open_streams_for_delete found 2 streams
[2015/06/27 17:37:03.675762, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/open.c:3494(open_streams_for_delete)
  Unable to stat stream: sw_2013_ost_flac.zip:Zone.Identifier:$DATA
[2015/06/27 17:37:03.675791, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/open.c:4279(create_file_default)
  create_file: access_mask = 0x10000 file_attributes = 0x80, share_access = 0x7, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x0 private_flags = 0x4 root_dir_fid = 0x0, ea_list = 0x0x0, sd = 0x0x0, fname = sw_2013_ost_flac.zip:Zone.Identifier:$DATA
[2015/06/27 17:37:03.675823, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/open.c:3787(create_file_unixpath)
  create_file_unixpath: access_mask = 0x10000 file_attributes = 0x80, share_access = 0x7, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x0 private_flags = 0x4 ea_list = 0x0x0, sd = 0x0x0, fname = sw_2013_ost_flac.zip:Zone.Identifier:$DATA
[2015/06/27 17:37:03.675876, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/trans2.c:262(get_ea_names_from_file)
  get_ea_list_from_file: ea_namelist size = 52
[ ... ]

That last set of 14 lines repeats until finally:

Code:

[2015/06/27 17:37:05.127387, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/open.c:4279(create_file_default)
  create_file: access_mask = 0x10000 file_attributes = 0x80, share_access = 0x7, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x0 private_flags = 0x4 root_dir_fid = 0x0, ea_list = 0x0x0, sd = 0x0x0, fname = sw_2013_ost_flac.zip:Zone.Identifier:$DATA
[2015/06/27 17:37:05.127419, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/open.c:3787(create_file_unixpath)
  create_file_unixpath: access_mask = 0x10000 file_attributes = 0x80, share_access = 0x7, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x0 private_flags = 0x4 ea_list = 0x0x0, sd = 0x0x0, fname = sw_2013_ost_flac.zip:Zone.Identifier:$DATA
[2015/06/27 17:37:05.127478, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/trans2.c:262(get_ea_names_from_file)
  get_ea_list_from_file: ea_namelist size = 52
[2015/06/27 17:37:05.127531, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/trans2.c:181(get_ea_value)
  get_ea_value: EA user.DosStream.Zone.Identifier:$DATA is of length 27
[2015/06/27 17:37:05.127560, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../lib/util/util.c:556(dump_data)
  [0000] 5B 5A 6F 6E 65 54 72 61  6E 73 66 65 72 5D 0D 0A  [ZoneTra nsfer]..
  [0010] 5A 6F 6E 65 49 64 3D 33  0D 0A 00  ZoneId=3 ...
[2015/06/27 17:37:05.127632, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/open.c:3463(open_streams_for_delete)
  open_streams_for_delete found 2 streams
[2015/06/27 17:37:05.127662, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/open.c:3494(open_streams_for_delete)
  Unable to stat stream: sw_2013_ost_flac.zip:Zone.Identifier:$DATA
[2015/06/27 17:37:05.127695, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/open.c:4279(create_file_default)
  create_file: access_mask = 0x10000 file_attributes = 0x80, share_access = 0x7, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x0 private_flags = 0x4 root_dir_fid = 0x0, ea_list = 0x0x0, sd = 0x0x0, fname = sw_2013_ost_flac.zip:Zone.Identifier:$DATA
[2015/06/27 17:37:05.127727, 10, pid=11208, effective(1001, 1001), real(0, 0)] ../source3/smbd/open.c:3787(create_file_unixpath)
  create_file_unixpath: access_mask = 0x10000 file_attributes = 0x80, share_access = 0x7, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x0 private_flags = 0x4 ea_list = 0x0x0, sd = 0x0x0, fname = sw_2013_ost_flac.zip:Zone.Identifier:$DATA
[2015/06/27 17:37:05.172762,  5, pid=11239, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:187(dbwrap_check_lock_order)
  check lock order 2 for /var/db/samba4/serverid.tdb
[2015/06/27 17:37:05.172882, 10, pid=11239, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order)
  lock order:  1:<none> 2:/var/db/samba4/serverid.tdb 3:<none>
[2015/06/27 17:37:05.172924, 10, pid=11239, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key)
  Locking key E72B000000000000FFFF
[2015/06/27 17:37:05.172902,  3, pid=11181, effective(0, 0), real(0, 0)] ../source3/smbd/server.c:429(remove_child_pid)
[2015/06/27 17:37:05.172980, 10, pid=11239, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal)
  ../source3/smbd/server.c:429 Unclean shutdown of pid 11208
  Allocated locked data 0x0x810020f60
[ ... ]

Note the difference in timestamps -- 'smbd' was basically spraying those messages continuously for about 1500ms before crashing. Without actually looking at a core dump (where do smbd core dumps get dropped?), my first wild guess is that this is a recursive loop that finally runs out of stack space.

Any other cheeseball diagnostics I could try?

 

[MoistVonLipwig]

Did you manage to solve this? I have this problem when accessing freenas from CIFS/Linux but not from CIFS/Mac. I'm using unix permissions too. NFS/Linux works without problems, but I'd rather use the same on all of my computers.

 

[ewhac]

Did you manage to solve this?

Not so far. However, I just last night pulled down an update to FreeNAS that supposedly has a newer version of Samba, and haven't yet crashed my desktop back into Windows to re-test it.

 

[MoistVonLipwig]

Not so far. However, I just last night pulled down an update to FreeNAS that supposedly has a newer version of Samba, and haven't yet crashed my desktop back into Windows to re-test it.

Ok. I think I just solved it, but it might not be the same issue. Basically I just went through all files, set the same owner and group on them and removed the execute flag on all files. You mentioned "fixsid.py" above but I didn't think it applied to me since I hadn't seen anything about it when googling "signal 4". But maybe it was anyway. Anyhow, CIFS/Linux has worked for a couple of hours now, before it didn't even work for minutes unless I just read from the share.

EDIT: Scratch that, it signal 4'd again :(

 

[thekow]

FreeNas Stable 9.3

I am also having this issue now.
No idea how to fix this. I have tried permissions etc.
I am assuming it is something to do with my HP microserver 8 running intel celeron?
Signal 4 being an illegal instruction.

Rsync works fine until i put the --delete switch in then it instantly signal 4 every 4 seconds until I cancel.
If i delete files from my windows box over the network (which is also samba) it's fine.

 

[dsfew32]

Getting same thing.

Symptoms are:
* When I try to move file from a linux machine (cifs) it takes minutes to move from one place up a single folder
* Copy works fine
* If I try and move the same file from windows it works fine
* No idea what's going on here. For some strange reason seems to happen when I copy a file to move around from my windows D drive, not C and not when I touch a file.
* I don't see any permission differences or problems with unix-style or acl (though share is set to windows-style)



ERRORS:
In the error log I get many repeats of:

Code:

pid 17843 (smbd), uid 1000: exited on signal 4

When I check the logs (log level minimum) I get:

Code:

[2016/02/15 04:56:49.263145,  1] ../source3/smbd/server.c:391(cleanup_timeout_fn)
  Cleaning up brl and lock database after unclean shutdown
[2016/02/15 04:56:50.839308,  1] ../source3/smbd/server.c:438(remove_child_pid)
  Scheduled cleanup of brl and lock database after unclean shutdown

Not sure why it's shuting down. Increasing to 'normal'

Code:

[2016/02/15 05:04:25.154357,  2] ../source3/param/loadparm.c:3585(do_section)
  Processing section "[MoviesAndShows]"
[2016/02/15 05:04:25.155087,  2] ../source3/param/loadparm.c:3585(do_section)
  Processing section "[annasfiles]"
[2016/02/15 05:04:25.156108,  2] ../source3/param/loadparm.c:3585(do_section)
  Processing section "[userfiles]"
[2016/02/15 05:04:25.157061,  2] ../source3/param/loadparm.c:3585(do_section)
  Processing section "[recordedTV]"
[2016/02/15 05:04:25.171890,  2] ../source3/auth/auth.c:278(auth_check_ntlm_password)
  check_ntlm_password:  authentication for user [user] -> [user] -> [user] succeeded
[2016/02/15 05:04:25.186486,  2] ../lib/util/modules.c:196(do_smb_load_module)
  Module 'streams_xattr' loaded
[2016/02/15 05:04:25.187085,  2] ../lib/util/modules.c:196(do_smb_load_module)
  Module 'aio_pthread' loaded
[2016/02/15 05:04:25.188579,  2] ../lib/util/modules.c:196(do_smb_load_module)
  Module 'zfsacl' loaded
[2016/02/15 05:04:25.218739,  2] ../lib/util/modules.c:196(do_smb_load_module)
  Module 'zfs_space' loaded
[2016/02/15 05:04:25.220191,  2] ../lib/util/modules.c:196(do_smb_load_module)
  Module 'shadow_copy2' loaded
[2016/02/15 05:04:25.221727,  2] ../source3/smbd/service.c:856(make_connection_snum)
  192.168.1.161 (ipv4:192.168.1.161:46518) connect to service userfiles initially as user user (uid=1000, gid=1000) (pid 28623)
[2016/02/15 05:04:26.030305,  1] ../source3/smbd/server.c:438(remove_child_pid)
  Scheduled cleanup of brl and lock database after unclean shutdown

Increasing to debug:

Code:

[2016/02/15 05:17:19.734892,  3, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/process.c:1406(switch_message)
  switch message SMBtrans2 (pid 31634) conn 0x810097660
[2016/02/15 05:17:19.734984,  4, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/uid.c:384(change_to_user)
  Skipping user change - already user
[2016/02/15 05:17:19.735076,  3, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/trans2.c:5342(call_trans2qfilepathinfo)
  call_trans2qfilepathinfo: TRANSACT2_QPATHINFO: level = 512
[2016/02/15 05:17:19.735175,  5, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/filename.c:258(unix_convert)
  unix_convert called on file "software/workspace/kagglecompetitions/bnp/uml-book.pdf"
[2016/02/15 05:17:19.735263,  5, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/filename.c:421(unix_convert)
  unix_convert begin: name = software/workspace/kagglecompetitions/bnp/uml-book.pdf, dirpath = , start = software/workspace/kagglecompetitions/bnp/uml-book.pdf
[2016/02/15 05:17:19.735346, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:242(shadow_copy2_strip_snapshot)
  ../source3/modules/vfs_shadow_copy2.c:242: enter path 'software/workspace/kagglecompetitions/bnp/uml-book.pdf'
[2016/02/15 05:17:19.735451, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:242(shadow_copy2_strip_snapshot)
  ../source3/modules/vfs_shadow_copy2.c:242: enter path 'software/workspace/kagglecompetitions/bnp'
[2016/02/15 05:17:19.735555,  5, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/filename.c:185(check_parent_exists)
  check_parent_exists: name = software/workspace/kagglecompetitions/bnp/uml-book.pdf, dirpath = software/workspace/kagglecompetitions/bnp, start = uml-book.pdf
[2016/02/15 05:17:19.735646, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:242(shadow_copy2_strip_snapshot)
  ../source3/modules/vfs_shadow_copy2.c:242: enter path 'software/workspace/kagglecompetitions/bnp'
[2016/02/15 05:17:19.735748,  8, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/lib/util.c:995(is_in_path)
  is_in_path: software/workspace/kagglecompetitions/bnp/uml-book.pdf
[2016/02/15 05:17:19.735835,  8, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/lib/util.c:1019(is_in_path)
  is_in_path: match not found
[2016/02/15 05:17:19.735922,  3, pid=31634, effective(1000, 1000), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1137(check_reduced_name)
  check_reduced_name [software/workspace/kagglecompetitions/bnp/uml-book.pdf] [/mnt/storage1/home/user/userfiles]
[2016/02/15 05:17:19.736009, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:242(shadow_copy2_strip_snapshot)
  ../source3/modules/vfs_shadow_copy2.c:242: enter path 'software/workspace/kagglecompetitions/bnp/uml-book.pdf'
[2016/02/15 05:17:19.736248, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:242(shadow_copy2_strip_snapshot)
  ../source3/modules/vfs_shadow_copy2.c:242: enter path 'software/workspace/kagglecompetitions/bnp'
[2016/02/15 05:17:19.736448, 10, pid=31634, effective(1000, 1000), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1197(check_reduced_name)
  check_reduced_name realpath [software/workspace/kagglecompetitions/bnp/uml-book.pdf] -> [/mnt/storage1/home/user/userfiles/software/workspace/kagglecompetitions/bnp/uml-book.pdf]
[2016/02/15 05:17:19.736534,  3, pid=31634, effective(1000, 1000), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1267(check_reduced_name)
  check_reduced_name: software/workspace/kagglecompetitions/bnp/uml-book.pdf reduced to /mnt/storage1/home/user/userfiles/software/workspace/kagglecompetitions/bnp/uml-book.pdf
[2016/02/15 05:17:19.736613, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:242(shadow_copy2_strip_snapshot)
  ../source3/modules/vfs_shadow_copy2.c:242: enter path 'software/workspace/kagglecompetitions/bnp/uml-book.pdf'
[2016/02/15 05:17:19.736711,  3, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/trans2.c:5448(call_trans2qfilepathinfo)
  call_trans2qfilepathinfo: SMB_VFS_LSTAT of software/workspace/kagglecompetitions/bnp/uml-book.pdf failed (No such file or directory)
[2016/02/15 05:17:19.736800,  3, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/error.c:82(error_packet_set)
  NT error packet at ../source3/smbd/trans2.c(5450) cmd=50 (SMBtrans2) NT_STATUS_OBJECT_NAME_NOT_FOUND
[2016/02/15 05:17:19.736881,  5, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/lib/util.c:168(show_msg)
[2016/02/15 05:17:19.736925,  5, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/lib/util.c:178(show_msg)
  size=35
  smb_com=0x32
  smb_rcls=52
  smb_reh=0
  smb_err=49152
  smb_flg=128
  smb_flg2=49155
  smb_tid=17573
  smb_pid=26530
  smb_uid=2907
  smb_mid=4712
  smt_wct=0
  smb_bcc=0
[2016/02/15 05:17:19.737379, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../lib/util/util.c:556(dump_data)
[2016/02/15 05:17:19.737717, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/lib/util_sock.c:337(read_smb_length_return_keepalive)
  got smb length of 278
[2016/02/15 05:17:19.737810,  6, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/process.c:1801(process_smb)
  got message type 0x0 of len 0x116
[2016/02/15 05:17:19.737895,  3, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/process.c:1803(process_smb)
  Transaction 116 of length 282 (0 toread)
[2016/02/15 05:17:19.737982,  5, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/lib/util.c:168(show_msg)
[2016/02/15 05:17:19.738027,  5, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/lib/util.c:178(show_msg)
  size=278
  smb_com=0x7
  smb_rcls=0
  smb_reh=0
  smb_err=0
  smb_flg=0
  smb_flg2=49153
  smb_tid=17573
  smb_pid=26530
  smb_uid=2907
  smb_mid=4713
  smt_wct=1
  smb_vwv[ 0]=  23 (0x17)
  smb_bcc=241
[2016/02/15 05:17:19.738563, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../lib/util/util.c:556(dump_data)
  [0000] 04 2F 00 73 00 6F 00 66  00 74 00 77 00 61 00 72  ./.s.o.f .t.w.a.r
  [0010] 00 65 00 2F 00 77 00 6F  00 72 00 6B 00 73 00 70  .e./.w.o .r.k.s.p
  [0020] 00 61 00 63 00 65 00 2F  00 6B 00 61 00 67 00 67  .a.c.e./ .k.a.g.g
  [0030] 00 6C 00 65 00 63 00 6F  00 6D 00 70 00 65 00 74  .l.e.c.o .m.p.e.t
  [0040] 00 69 00 74 00 69 00 6F  00 6E 00 73 00 2F 00 62  .i.t.i.o .n.s./.b
  [0050] 00 6E 00 70 00 2F 00 70  00 79 00 74 00 68 00 6F  .n.p./.p .y.t.h.o
  [0060] 00 6E 00 2F 00 75 00 6D  00 6C 00 2D 00 62 00 6F  .n./.u.m .l.-.b.o
  [0070] 00 6F 00 6B 00 2E 00 70  00 64 00 66 00 00 00 04  .o.k...p .d.f....
  [0080] 00 2F 00 73 00 6F 00 66  00 74 00 77 00 61 00 72  ./.s.o.f .t.w.a.r
  [0090] 00 65 00 2F 00 77 00 6F  00 72 00 6B 00 73 00 70  .e./.w.o .r.k.s.p
  [00A0] 00 61 00 63 00 65 00 2F  00 6B 00 61 00 67 00 67  .a.c.e./ .k.a.g.g
  [00B0] 00 6C 00 65 00 63 00 6F  00 6D 00 70 00 65 00 74  .l.e.c.o .m.p.e.t
  [00C0] 00 69 00 74 00 69 00 6F  00 6E 00 73 00 2F 00 62  .i.t.i.o .n.s./.b
  [00D0] 00 6E 00 70 00 2F 00 75  00 6D 00 6C 00 2D 00 62  .n.p./.u .m.l.-.b
  [00E0] 00 6F 00 6F 00 6B 00 2E  00 70 00 64 00 66 00 00  .o.o.k.. .p.d.f..
  [00F0] 00                                                .
[2016/02/15 05:17:19.739482,  3, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/process.c:1406(switch_message)
  switch message SMBmv (pid 31634) conn 0x810097660
[2016/02/15 05:17:19.739569,  4, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/uid.c:384(change_to_user)
  Skipping user change - already user
[2016/02/15 05:17:19.739669,  5, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/filename.c:258(unix_convert)
  unix_convert called on file "software/workspace/kagglecompetitions/bnp/python/uml-book.pdf"
[2016/02/15 05:17:19.739763,  5, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/filename.c:421(unix_convert)
  unix_convert begin: name = software/workspace/kagglecompetitions/bnp/python/uml-book.pdf, dirpath = , start = software/workspace/kagglecompetitions/bnp/python/uml-book.pdf
[2016/02/15 05:17:19.739845, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:242(shadow_copy2_strip_snapshot)
  ../source3/modules/vfs_shadow_copy2.c:242: enter path 'software/workspace/kagglecompetitions/bnp/python/uml-book.pdf'
[2016/02/15 05:17:19.739954,  5, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/filename.c:444(unix_convert)
  conversion of base_name finished software/workspace/kagglecompetitions/bnp/python/uml-book.pdf -> software/workspace/kagglecompetitions/bnp/python/uml-book.pdf
[2016/02/15 05:17:19.740043,  8, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/lib/util.c:995(is_in_path)
  is_in_path: software/workspace/kagglecompetitions/bnp/python/uml-book.pdf
[2016/02/15 05:17:19.740133,  8, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/lib/util.c:1019(is_in_path)
  is_in_path: match not found
[2016/02/15 05:17:19.740220,  3, pid=31634, effective(1000, 1000), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1137(check_reduced_name)
  check_reduced_name [software/workspace/kagglecompetitions/bnp/python/uml-book.pdf] [/mnt/storage1/home/user/userfiles]
[2016/02/15 05:17:19.740306, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:242(shadow_copy2_strip_snapshot)
  ../source3/modules/vfs_shadow_copy2.c:242: enter path 'software/workspace/kagglecompetitions/bnp/python/uml-book.pdf'
[2016/02/15 05:17:19.740569, 10, pid=31634, effective(1000, 1000), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1197(check_reduced_name)
  check_reduced_name realpath [software/workspace/kagglecompetitions/bnp/python/uml-book.pdf] -> [/mnt/storage1/home/user/userfiles/software/workspace/kagglecompetitions/bnp/python/uml-book.pdf]
[2016/02/15 05:17:19.740654,  3, pid=31634, effective(1000, 1000), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1267(check_reduced_name)
  check_reduced_name: software/workspace/kagglecompetitions/bnp/python/uml-book.pdf reduced to /mnt/storage1/home/user/userfiles/software/workspace/kagglecompetitions/bnp/python/uml-book.pdf
[2016/02/15 05:17:19.740744,  5, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/filename.c:258(unix_convert)
  unix_convert called on file "software/workspace/kagglecompetitions/bnp/uml-book.pdf"
[2016/02/15 05:17:19.740832,  5, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/filename.c:421(unix_convert)
  unix_convert begin: name = software/workspace/kagglecompetitions/bnp/uml-book.pdf, dirpath = , start = software/workspace/kagglecompetitions/bnp/uml-book.pdf
[2016/02/15 05:17:19.740921, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:242(shadow_copy2_strip_snapshot)
  ../source3/modules/vfs_shadow_copy2.c:242: enter path 'software/workspace/kagglecompetitions/bnp/uml-book.pdf'
[2016/02/15 05:17:19.741022, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:242(shadow_copy2_strip_snapshot)
  ../source3/modules/vfs_shadow_copy2.c:242: enter path 'software/workspace/kagglecompetitions/bnp'
[2016/02/15 05:17:19.741127,  5, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/filename.c:185(check_parent_exists)
  check_parent_exists: name = software/workspace/kagglecompetitions/bnp/uml-book.pdf, dirpath = software/workspace/kagglecompetitions/bnp, start = uml-book.pdf
[2016/02/15 05:17:19.741217, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:242(shadow_copy2_strip_snapshot)
  ../source3/modules/vfs_shadow_copy2.c:242: enter path 'software/workspace/kagglecompetitions/bnp'
[2016/02/15 05:17:19.741317,  8, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/lib/util.c:995(is_in_path)
  is_in_path: software/workspace/kagglecompetitions/bnp/uml-book.pdf
[2016/02/15 05:17:19.741404,  8, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/lib/util.c:1019(is_in_path)
  is_in_path: match not found
[2016/02/15 05:17:19.741491,  3, pid=31634, effective(1000, 1000), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1137(check_reduced_name)
  check_reduced_name [software/workspace/kagglecompetitions/bnp/uml-book.pdf] [/mnt/storage1/home/user/userfiles]
[2016/02/15 05:17:19.741578, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:242(shadow_copy2_strip_snapshot)
  ../source3/modules/vfs_shadow_copy2.c:242: enter path 'software/workspace/kagglecompetitions/bnp/uml-book.pdf'
[2016/02/15 05:17:19.741805, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:242(shadow_copy2_strip_snapshot)
  ../source3/modules/vfs_shadow_copy2.c:242: enter path 'software/workspace/kagglecompetitions/bnp'
[2016/02/15 05:17:19.742005, 10, pid=31634, effective(1000, 1000), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1197(check_reduced_name)
  check_reduced_name realpath [software/workspace/kagglecompetitions/bnp/uml-book.pdf] -> [/mnt/storage1/home/user/userfiles/software/workspace/kagglecompetitions/bnp/uml-book.pdf]
[2016/02/15 05:17:19.742095,  3, pid=31634, effective(1000, 1000), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1267(check_reduced_name)
  check_reduced_name: software/workspace/kagglecompetitions/bnp/uml-book.pdf reduced to /mnt/storage1/home/user/userfiles/software/workspace/kagglecompetitions/bnp/uml-book.pdf
[2016/02/15 05:17:19.742180,  3, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/reply.c:7007(reply_mv)
  reply_mv : software/workspace/kagglecompetitions/bnp/python/uml-book.pdf -> software/workspace/kagglecompetitions/bnp/uml-book.pdf
[2016/02/15 05:17:19.742265,  3, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/reply.c:6652(rename_internals)
  rename_internals: case_sensitive = 1, case_preserve = 1, short case preserve = 1, directory = software/workspace/kagglecompetitions/bnp/python/uml-book.pdf, newname = software/workspace/kagglecompetitions/bnp/uml-book.pdf, last_component_dest = uml-book.pdf
[2016/02/15 05:17:19.742349, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:242(shadow_copy2_strip_snapshot)
  ../source3/modules/vfs_shadow_copy2.c:242: enter path 'software/workspace/kagglecompetitions/bnp/python/uml-book.pdf'
[2016/02/15 05:17:19.742452, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/open.c:4279(create_file_default)
  create_file: access_mask = 0x10000 file_attributes = 0x10001ff, share_access = 0x3, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x0 private_flags = 0x0 root_dir_fid = 0x0, ea_list = 0x0x0, sd = 0x0x0, fname = software/workspace/kagglecompetitions/bnp/python/uml-book.pdf
[2016/02/15 05:17:19.742538, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/open.c:3787(create_file_unixpath)
  create_file_unixpath: access_mask = 0x10000 file_attributes = 0x10001ff, share_access = 0x3, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x0 private_flags = 0x0 ea_list = 0x0x0, sd = 0x0x0, fname = software/workspace/kagglecompetitions/bnp/python/uml-book.pdf
[2016/02/15 05:17:19.742627, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:242(shadow_copy2_strip_snapshot)
  ../source3/modules/vfs_shadow_copy2.c:242: enter path 'software/workspace/kagglecompetitions/bnp/python/uml-book.pdf'
[2016/02/15 05:17:19.742732, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:242(shadow_copy2_strip_snapshot)
  ../source3/modules/vfs_shadow_copy2.c:242: enter path 'software/workspace/kagglecompetitions/bnp/python/uml-book.pdf'
[2016/02/15 05:17:19.742898, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/trans2.c:262(get_ea_names_from_file)
  get_ea_list_from_file: ea_namelist size = 52
[2016/02/15 05:17:19.742987, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:242(shadow_copy2_strip_snapshot)
  ../source3/modules/vfs_shadow_copy2.c:242: enter path 'software/workspace/kagglecompetitions/bnp/python/uml-book.pdf'
[2016/02/15 05:17:19.743164, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/trans2.c:181(get_ea_value)
  get_ea_value: EA user.DosStream.Zone.Identifier:$DATA is of length 27
[2016/02/15 05:17:19.743250, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../lib/util/util.c:556(dump_data)
  [0000] 5B 5A 6F 6E 65 54 72 61  6E 73 66 65 72 5D 0D 0A  [ZoneTra nsfer]..
  [0010] 5A 6F 6E 65 49 64 3D 33  0D 0A 00                ZoneId=3 ...
[2016/02/15 05:17:19.743411, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:242(shadow_copy2_strip_snapshot)
  ../source3/modules/vfs_shadow_copy2.c:242: enter path 'software/workspace/kagglecompetitions/bnp/python/uml-book.pdf'
[2016/02/15 05:17:19.743516, 10, pid=31634, effective(1000, 1000), real(0, 0)] ../source3/smbd/open.c:3463(open_streams_for_delete)
  open_streams_for_delete found 2 streams

If anyone has any other info, please let me know.

 

[danno]

I've encountered this intermittently as well. It didn't happen until I switched from Windows to Linux (Mint) on my laptop, so I initially thought it was something with the CIFS config on my Linux FSTAB setup. I feel a little relieved to see others reporting it, but am wondering if there is some way to work around the issue, either on the FreeNAS side or on the Linux client side.

It seems to happen most when I try to delete a file or folder from Linux Mint on one of the SMB shares. The Linux file manager will hang, and the signal 4 messages will continue on the FreeNAS console for a long time (until some sort of timeout happens):

Code:

pid 11037 (smbd), uid 1001: exited on signal 4
pid 11684 (smbd), uid 1001: exited on signal 4
pid 11685 (smbd), uid 1001: exited on signal 4
pid 11701 (smbd), uid 1001: exited on signal 4
pid 11885 (smbd), uid 1001: exited on signal 4
pid 11905 (smbd), uid 1001: exited on signal 4
pid 11914 (smbd), uid 1001: exited on signal 4
pid 11924 (smbd), uid 1001: exited on signal 4
pid 11933 (smbd), uid 1001: exited on signal 4
pid 11957 (smbd), uid 1001: exited on signal 4
pid 11966 (smbd), uid 1001: exited on signal 4
pid 11976 (smbd), uid 1001: exited on signal 4
pid 11986 (smbd), uid 1001: exited on signal 4
pid 11995 (smbd), uid 1001: exited on signal 4
pid 12004 (smbd), uid 1001: exited on signal 4
pid 12029 (smbd), uid 1001: exited on signal 4
pid 12038 (smbd), uid 1001: exited on signal 4

A prior post mentioned that NFS seems to avoid the problem, but I'm using CIFS for my FreeNAS shares because there are still a few Windows devices in the mix (which work better with SMB than with NFS). If someone has had success with a workaround (I'm assuming a bug has been reported as was mentioned earlier in this thread), please post back.

 

[JR Gonzalez]

Same issue. I posted this in another thread because I didn't notice this one. What is going on here? Has anybody figured this one out?

 

[JR Gonzalez]

I filed a bug.

Seems like they want my debug logs tho. But... none of that stuff is redacted. Don't want to give it up. It's a pretty easy problem to reproduce though. In my config I'm using the FreeNAS box as a DC. I authenticate against it using Samba/winbind on the clients then use pam_mount to mount user home dirs (and other shares in /mnt). All shares give me this problem. I even tried creating fresh datasets and shares to see if that would fix it but no. Seems like a pretty serious bug. Can someone add to it if they get a chance?

https://bugs.freenas.org/issues/15808

 

[rogerh]

I filed a bug.

Seems like they want my debug logs tho. But... none of that stuff is redacted. Don't want to give it up. It's a pretty easy problem to reproduce though. In my config I'm using the FreeNAS box as a DC. I authenticate against it using Samba/winbind on the clients then use pam_mount to mount user home dirs (and other shares in /mnt). All shares give me this problem. I even tried creating fresh datasets and shares to see if that would fix it but no. Seems like a pretty serious bug. Can someone add to it if they get a chance?

https://bugs.freenas.org/issues/15808

Unless you have some particularly sensitive information, bear in mind that the people at iX system often have access to a large number of TrueNAS systems belonging to a wide range of firms and have considerable experience of maintaining other people's confidential data safely. You could send the file, possibly encrypted, to a named person.

 

[JR Gonzalez]

I'll try that. I should mention in order to eliminate mount.cifs as the culprit I copied the same files to a share on a synology. Then used mount.cifs on the same system I was testing for FreeNAS. The behavior was as expected. Files written from OSX and Windows were able to rm without issue. So the problem seems related to FreeNAS' samba. I'm pretty sure Synology uses some version of Samba as well.