[Samba] Problem After Upgrade - NT_STATUS_FILE_IS_A_DIRECTORY

Leandro Tracchia itmanager at alexanderconsultants.net
Fri Jul 9 11:15:48 MDT 2010 

> Debug level 10 logs are needed at this point to see what
> the smbd is seeing when looking at the CIFS mounted files.

Here is level 10 log of log.smbd that is generated when I experience the problem first described. 

[2010/07/09 12:48:25, 10] smbd/open.c:3365(create_file_default)
  create_file: access_mask = 0x20089 file_attributes = 0x80, share_access = 0x7, create_disposition = 0x1 create_options = 0x40 oplock_request = 0x3 root_dir_fid = 0x0, ea_list = 0x(nil), sd = 0x(nil), create_file_flags = 0x1, fname = RSA/Tables
[2010/07/09 12:48:25,  5] smbd/filename.c:148(unix_convert)
  unix_convert called on file "RSA/Tables"
[2010/07/09 12:48:25, 10] smbd/statcache.c:274(stat_cache_lookup)
  stat_cache_lookup: lookup succeeded for name [RSA/Tables] -> [RSA/Tables]
[2010/07/09 12:48:25,  3] smbd/vfs.c:865(check_reduced_name)
  reduce_name [RSA/Tables] [/media/server/RSA]
[2010/07/09 12:48:25, 10] smbd/vfs.c:937(check_reduced_name)
  reduce_name realpath [RSA/Tables] -> [/media/server/RSA/Tables]
[2010/07/09 12:48:25,  3] smbd/vfs.c:974(check_reduced_name)
  reduce_name: RSA/Tables reduced to /media/server/RSA/Tables
[2010/07/09 12:48:25, 10] smbd/open.c:2896(create_file_unixpath)
  create_file_unixpath: access_mask = 0x20089 file_attributes = 0x80, share_access = 0x7, create_disposition = 0x1 create_options = 0x40 oplock_request = 0x3 ea_list = 0x(nil), sd = 0x(nil), fname = RSA/Tables
[2010/07/09 12:48:25,  5] smbd/files.c:103(file_new)
  allocated file structure 16108, fnum = 20204 (2 used)
[2010/07/09 12:48:25,  2] smbd/dosmode.c:97(unix_mode)
  unix_mode(RSA/Tables) inheriting from RSA/Tables
[2010/07/09 12:48:25,  2] smbd/dosmode.c:106(unix_mode)
  unix_mode(RSA/Tables) inherit mode 40770
[2010/07/09 12:48:25,  3] smbd/dosmode.c:149(unix_mode)
  unix_mode(RSA/Tables) returning 0760
[2010/07/09 12:48:25, 10] smbd/open.c:1475(open_file_ntcreate)
  open_file_ntcreate: fname=RSA/Tables, dos_attrs=0x80 access_mask=0x20089 share_access=0x7 create_disposition = 0x1 create_options=0x40 unix mode=0760 oplock_request=3
[2010/07/09 12:48:25,  3] smbd/vfs.c:865(check_reduced_name)
  reduce_name [RSA/Tables] [/media/server/RSA]
[2010/07/09 12:48:25, 10] smbd/vfs.c:937(check_reduced_name)
  reduce_name realpath [RSA/Tables] -> [/media/server/RSA/Tables]
[2010/07/09 12:48:25,  3] smbd/vfs.c:974(check_reduced_name)
  reduce_name: RSA/Tables reduced to /media/server/RSA/Tables
[2010/07/09 12:48:25,  8] smbd/dosmode.c:494(dos_mode)
  dos_mode: RSA/Tables
[2010/07/09 12:48:25,  8] smbd/dosmode.c:189(dos_mode_from_sbuf)
  dos_mode_from_sbuf returning d
[2010/07/09 12:48:25,  8] smbd/dosmode.c:547(dos_mode)
  dos_mode returning d
[2010/07/09 12:48:25, 10] smbd/open.c:1653(open_file_ntcreate)
  open_file_ntcreate: fname=RSA/Tables, after mapping access_mask=0x20089
[2010/07/09 12:48:25, 10] lib/dbwrap_tdb.c:100(db_tdb_fetch_locked)
  Locking key 15000000000000003909
[2010/07/09 12:48:25, 10] lib/dbwrap_tdb.c:129(db_tdb_fetch_locked)
  Allocated locked data 0x0x7f8390299d50
[2010/07/09 12:48:25, 10] smbd/open.c:980(delay_for_oplocks)
  delay_for_oplocks: oplock type 0x3 on file 
[2010/07/09 12:48:25, 10] smbd/open.c:980(delay_for_oplocks)
  delay_for_oplocks: oplock type 0x3 on file 
[2010/07/09 12:48:25,  4] smbd/open.c:1913(open_file_ntcreate)
  calling open_file with flags=0x0 flags2=0x0 mode=0760, access_mask = 0x20089, open_access_mask = 0x20089
[2010/07/09 12:48:25, 10] smbd/open.c:160(fd_open)
  fd_open: name RSA/Tables, flags = 00 mode = 0760, fd = 31. 
[2010/07/09 12:48:25, 10] locking/posix.c:495(get_windows_lock_ref_count)
  get_windows_lock_count for file  = 0
[2010/07/09 12:48:25, 10] locking/posix.c:521(delete_windows_lock_ref_count)
  delete_windows_lock_ref_count for file 
[2010/07/09 12:48:25, 10] lib/dbwrap_tdb.c:42(db_tdb_record_destr)
  Unlocking key 15000000000000003909
[2010/07/09 12:48:25,  5] smbd/files.c:474(file_free)
  freed files structure 20204 (1 used)
[2010/07/09 12:48:25, 10] smbd/open.c:3218(create_file_unixpath)
  create_file_unixpath: NT_STATUS_FILE_IS_A_DIRECTORY
[2010/07/09 12:48:25, 10] smbd/open.c:3497(create_file_default)
  create_file: NT_STATUS_FILE_IS_A_DIRECTORY
[2010/07/09 12:48:25,  3] smbd/error.c:60(error_packet_set)
  error packet at smbd/nttrans.c(563) cmd=162 (SMBntcreateX) NT_STATUS_FILE_IS_A_DIRECTORY
[2010/07/09 12:48:25,  5] lib/util.c:632(show_msg)
[2010/07/09 12:48:25,  5] lib/util.c:642(show_msg)
  size=35
  smb_com=0xa2
  smb_rcls=186
  smb_reh=0
  smb_err=49152
  smb_flg=136
  smb_flg2=51201
  smb_tid=4
  smb_pid=5696
  smb_uid=100
  smb_mid=62275
  smt_wct=0
  smb_bcc=0
[2010/07/09 12:48:25, 10] lib/util_sock.c:789(read_smb_length_return_keepalive)
  got smb length of 176
[2010/07/09 12:48:25,  6] smbd/process.c:1456(process_smb)
  got message type 0x0 of len 0xb0
[2010/07/09 12:48:25,  3] smbd/process.c:1459(process_smb)
  Transaction 1680202 of length 180 (0 toread)
[2010/07/09 12:48:25,  5] lib/util.c:632(show_msg)
[2010/07/09 12:48:25,  5] lib/util.c:642(show_msg)
  size=176
  smb_com=0xa2
  smb_rcls=0
  smb_reh=0
  smb_err=0
  smb_flg=24
  smb_flg2=51207
  smb_tid=4
  smb_pid=5696
  smb_uid=100
  smb_mid=62339
  smt_wct=24
  smb_vwv[ 0]=  255 (0xFF)
  smb_vwv[ 1]=57054 (0xDEDE)
  smb_vwv[ 2]=23040 (0x5A00)
  smb_vwv[ 3]= 5632 (0x1600)
  smb_vwv[ 4]=    0 (0x0)
  smb_vwv[ 5]=    0 (0x0)
  smb_vwv[ 6]=    0 (0x0)
  smb_vwv[ 7]=35072 (0x8900)
  smb_vwv[ 8]=  512 (0x200)
  smb_vwv[ 9]=    0 (0x0)
  smb_vwv[10]=    0 (0x0)
  smb_vwv[11]=    0 (0x0)
  smb_vwv[12]=    0 (0x0)
  smb_vwv[13]=    0 (0x0)
  smb_vwv[14]=    0 (0x0)
  smb_vwv[15]= 1792 (0x700)
  smb_vwv[16]=    0 (0x0)
  smb_vwv[17]=  256 (0x100)
  smb_vwv[18]=    0 (0x0)
  smb_vwv[19]=    0 (0x0)
  smb_vwv[20]=    0 (0x0)
  smb_vwv[21]=  512 (0x200)
  smb_vwv[22]=    0 (0x0)
  smb_vwv[23]=  768 (0x300)
  smb_bcc=93
[2010/07/09 12:48:25, 10] ../lib/util/util.c:304(_dump_data)
  [0000] 00 5C 00 52 00 65 00 64   00 53 00 74 00 6F 00 6E   .\.R.e.d .S.t.o.n
  [0010] 00 65 00 20 00 41 00 72   00 73 00 65 00 6E 00 61   .e. .A.r .s.e.n.a
  [0020] 00 6C 00 5C 00 4C 00 65   00 65 00 20 00 4D 00 61   .l.\.L.e .e. .M.a
  [0030] 00 6E 00 73 00 69 00 6F   00 6E 00 20 00 50 00 68   .n.s.i.o .n. .P.h
  [0040] 00 61 00 73 00 65 00 20   00 49 00 49 00 5C 00 54   .a.s.e.  .I.I.\.T
  [0050] 00 61 00 62 00 6C 00 65   00 73 00 00 00           .a.b.l.e .s...
[2010/07/09 12:48:25,  3] smbd/process.c:1273(switch_message)
  switch message SMBntcreateX (pid 15334) conn 0x7f83902e6fe0
[2010/07/09 12:48:25,  4] smbd/uid.c:256(change_to_user)
  change_to_user: Skipping user change - already user
[2010/07/09 12:48:25, 10] smbd/nttrans.c:484(reply_ntcreate_and_X)
  reply_ntcreate_and_X: flags = 0x16, access_mask = 0x20089 file_attributes = 0x0, share_access = 0x7, create_disposition = 0x1 create_options = 0x0 root_dir_fid = 0x0, fname = RSA/Tables
[2010/07/09 12:48:25, 10] smbd/open.c:3365(create_file_default)
  create_file: access_mask = 0x20089 file_attributes = 0x0, share_access = 0x7, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x3 root_dir_fid = 0x0, ea_list = 0x(nil), sd = 0x(nil), create_file_flags = 0x1, fname = RSA/Tables
[2010/07/09 12:48:25,  5] smbd/filename.c:148(unix_convert)
  unix_convert called on file "RSA/Tables"
[2010/07/09 12:48:25, 10] smbd/statcache.c:274(stat_cache_lookup)
  stat_cache_lookup: lookup succeeded for name [RSA/Tables] -> [RSA/Tables]
[2010/07/09 12:48:25,  3] smbd/vfs.c:865(check_reduced_name)
  reduce_name [RSA/Tables] [/media/server/RSA]
[2010/07/09 12:48:25, 10] smbd/vfs.c:937(check_reduced_name)
  reduce_name realpath [RSA/Tables] -> [/media/server/RSA/Tables]
[2010/07/09 12:48:25,  3] smbd/vfs.c:974(check_reduced_name)
  reduce_name: RSA/Tables reduced to /media/server/RSA/Tables
[2010/07/09 12:48:25, 10] smbd/open.c:2896(create_file_unixpath)
  create_file_unixpath: access_mask = 0x20089 file_attributes = 0x0, share_access = 0x7, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x3 ea_list = 0x(nil), sd = 0x(nil), fname = RSA/Tables
[2010/07/09 12:48:25,  5] smbd/files.c:103(file_new)
  allocated file structure 16109, fnum = 20205 (2 used)
[2010/07/09 12:48:25,  2] smbd/dosmode.c:97(unix_mode)
  unix_mode(RSA/Tables) inheriting from RSA/Tables
[2010/07/09 12:48:25,  2] smbd/dosmode.c:106(unix_mode)
  unix_mode(RSA/Tables) inherit mode 40770
[2010/07/09 12:48:25,  3] smbd/dosmode.c:149(unix_mode)
  unix_mode(RSA/Tables) returning 0760
[2010/07/09 12:48:25, 10] smbd/open.c:1475(open_file_ntcreate)
  open_file_ntcreate: fname=RSA/Tables, dos_attrs=0x0 access_mask=0x20089 share_access=0x7 create_disposition = 0x1 create_options=0x0 unix mode=0760 oplock_request=3
[2010/07/09 12:48:25,  3] smbd/vfs.c:865(check_reduced_name)
  reduce_name [RSA/Tables] [/media/server/RSA]
[2010/07/09 12:48:25, 10] smbd/vfs.c:937(check_reduced_name)
  reduce_name realpath [RSA/Tables] -> [/media/server/RSA/Tables]
[2010/07/09 12:48:25,  3] smbd/vfs.c:974(check_reduced_name)
  reduce_name: RSA/Tables reduced to /media/server/RSA/Tables
[2010/07/09 12:48:25,  8] smbd/dosmode.c:494(dos_mode)
  dos_mode: RSA/Tables
[2010/07/09 12:48:25,  8] smbd/dosmode.c:189(dos_mode_from_sbuf)
  dos_mode_from_sbuf returning d
[2010/07/09 12:48:25,  8] smbd/dosmode.c:547(dos_mode)
  dos_mode returning d
[2010/07/09 12:48:25, 10] smbd/open.c:1653(open_file_ntcreate)
  open_file_ntcreate: fname=RSA/Tables, after mapping access_mask=0x20089
[2010/07/09 12:48:25, 10] lib/dbwrap_tdb.c:100(db_tdb_fetch_locked)
  Locking key 15000000000000003909
[2010/07/09 12:48:25, 10] lib/dbwrap_tdb.c:129(db_tdb_fetch_locked)
  Allocated locked data 0x0x7f8390299d50
[2010/07/09 12:48:25, 10] smbd/open.c:980(delay_for_oplocks)
  delay_for_oplocks: oplock type 0x3 on file 
[2010/07/09 12:48:25, 10] smbd/open.c:980(delay_for_oplocks)
  delay_for_oplocks: oplock type 0x3 on file 
[2010/07/09 12:48:25,  4] smbd/open.c:1913(open_file_ntcreate)
  calling open_file with flags=0x0 flags2=0x0 mode=0760, access_mask = 0x20089, open_access_mask = 0x20089
[2010/07/09 12:48:25, 10] smbd/open.c:160(fd_open)
  fd_open: name RSA/Tables, flags = 00 mode = 0760, fd = 31. 
[2010/07/09 12:48:25, 10] locking/posix.c:495(get_windows_lock_ref_count)
  get_windows_lock_count for file  = 0
[2010/07/09 12:48:25, 10] locking/posix.c:521(delete_windows_lock_ref_count)
  delete_windows_lock_ref_count for file 
[2010/07/09 12:48:25, 10] lib/dbwrap_tdb.c:42(db_tdb_record_destr)
  Unlocking key 15000000000000003909
[2010/07/09 12:48:25,  5] smbd/files.c:474(file_free)
  freed files structure 20205 (1 used)
[2010/07/09 12:48:25,  5] smbd/open.c:2391(open_directory)
  open_directory: opening directory RSA/Tables, access_mask = 0x20089, share_access = 0x7 create_options = 0x0, create_disposition = 0x1, file_attributes = 0x0
[2010/07/09 12:48:25, 10] smbd/posix_acls.c:3372(posix_get_nt_acl)
  posix_get_nt_acl: called for file RSA/Tables
[2010/07/09 12:48:25, 10] smbd/posix_acls.c:2522(canonicalise_acl)
  canonicalise_acl: Access ace entries before arrange :
[2010/07/09 12:48:25, 10] smbd/posix_acls.c:2535(canonicalise_acl)
  canon_ace index 0. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms ---
[2010/07/09 12:48:25, 10] smbd/posix_acls.c:2535(canonicalise_acl)
  canon_ace index 1. Type = allow SID = S-1-5-21-2665625993-2077132221-1624687091-3037 gid 1018 (editors) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms rwx
[2010/07/09 12:48:25, 10] smbd/posix_acls.c:2535(canonicalise_acl)
  canon_ace index 2. Type = allow SID = S-1-5-21-2665625993-2077132221-1624687091-1000 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx
[2010/07/09 12:48:25, 10] smbd/posix_acls.c:838(print_canon_ace_list)
  print_canon_ace_list: canonicalise_acl: ace entries after arrange  canon_ace index 0. Type = allow SID = S-1-5-21-2665625993-2077132221-1624687091-1000 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx
  canon_ace index 1. Type = allow SID = S-1-5-21-2665625993-2077132221-1624687091-3037 gid 1018 (editors) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms rwx
  canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms ---
[2010/07/09 12:48:25, 10] smbd/posix_acls.c:1116(map_canon_ace_perms)
  map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff
[2010/07/09 12:48:25, 10] smbd/posix_acls.c:1116(map_canon_ace_perms)
  map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff
[2010/07/09 12:48:25, 10] smbd/posix_acls.c:1116(map_canon_ace_perms)
  map_canon_ace_perms: Mapped (UNIX) 0 to (NT) 0
[2010/07/09 12:48:25, 10] smbd/open.c:113(check_open_rights)
  check_open_rights: file RSA/Tables requesting 0x20089 returning 0x20009 (NT_STATUS_OK)
[2010/07/09 12:48:25,  5] smbd/files.c:103(file_new)
  allocated file structure 16110, fnum = 20206 (2 used)
[2010/07/09 12:48:25, 10] lib/dbwrap_tdb.c:100(db_tdb_fetch_locked)
  Locking key 15000000000000003909
[2010/07/09 12:48:25, 10] lib/dbwrap_tdb.c:129(db_tdb_fetch_locked)
  Allocated locked data 0x0x7f839029add0
[2010/07/09 12:48:25, 10] locking/locking.c:716(unparse_share_modes)
  unparse_share_modes: del: 0, owrt: Fri May  1 10:32:46 2009 EDT cwrt: Wed Dec 31 19:00:00 1969 EST, tok: 0, num: 1
[2010/07/09 12:48:25, 10] locking/locking.c:518(print_share_mode_table)
  print_share_mode_table: share_mode_entry[0]:  pid = 15334, share_access = 0x7, private_options = 0x0, access_mask = 0x20089, mid = 0x0, type= 0x0, gen_id = 28771, uid = 1020, flags = 0, file_id 15:1000000000939:0
[2010/07/09 12:48:25, 10] lib/dbwrap_tdb.c:42(db_tdb_record_destr)
  Unlocking key 15000000000000003909
[2010/07/09 12:48:25, 10] smbd/open.c:3201(create_file_unixpath)
  create_file_unixpath: info=1
[2010/07/09 12:48:25, 10] smbd/open.c:3485(create_file_default)
  create_file: info=1
[2010/07/09 12:48:25,  8] smbd/dosmode.c:494(dos_mode)
  dos_mode: RSA/Tables
[2010/07/09 12:48:25,  8] smbd/dosmode.c:189(dos_mode_from_sbuf)
  dos_mode_from_sbuf returning d
[2010/07/09 12:48:25,  8] smbd/dosmode.c:547(dos_mode)
  dos_mode returning d
[2010/07/09 12:48:25,  5] smbd/nttrans.c:672(reply_ntcreate_and_X)
  reply_ntcreate_and_X: fnum = 20206, open name = RSA/Tables
[2010/07/09 12:48:25, 10] lib/util_sock.c:789(read_smb_length_return_keepalive)
  got smb length of 72
[2010/07/09 12:48:25,  6] smbd/process.c:1456(process_smb)
  got message type 0x0 of len 0x48
[2010/07/09 12:48:25,  3] smbd/process.c:1459(process_smb)
  Transaction 1680203 of length 76 (0 toread)
[2010/07/09 12:48:25,  5] lib/util.c:632(show_msg)
[2010/07/09 12:48:25,  5] lib/util.c:642(show_msg)
  size=72
  smb_com=0x32
  smb_rcls=0
  smb_reh=0
  smb_err=0
  smb_flg=24
  smb_flg2=51207
  smb_tid=4
  smb_pid=5696
  smb_uid=100
  smb_mid=62403
  smt_wct=15
  smb_vwv[ 0]=    4 (0x4)
  smb_vwv[ 1]=    0 (0x0)
  smb_vwv[ 2]=    2 (0x2)
  smb_vwv[ 3]=    8 (0x8)
  smb_vwv[ 4]=    0 (0x0)
  smb_vwv[ 5]=    0 (0x0)
  smb_vwv[ 6]=    0 (0x0)
  smb_vwv[ 7]=    0 (0x0)
  smb_vwv[ 8]=    0 (0x0)
  smb_vwv[ 9]=    4 (0x4)
  smb_vwv[10]=   68 (0x44)
  smb_vwv[11]=    0 (0x0)
  smb_vwv[12]=    0 (0x0)
  smb_vwv[13]=    1 (0x1)
  smb_vwv[14]=    7 (0x7)
  smb_bcc=7

More information about the samba mailing list