I have a scripts on windows to create files on a samba server. Some times the scripts failuer for waiting samba's response. A wireshark's captur shows samba's response is "Create Response, Error: STATUS_PENDING" and a full response doesn't come later. I have read the microsoft's article. It's said "An interim response indicates to the client that the request has been received and a full response will come later." https://msdn.microsoft.com/en-us/library/cc246721.aspx The samba's log shows that time there is an errors "fd_open" and "get_share_mode_lock_internal" ------------------------- ../source3/smbd/open.c:408(fd_open) fd_open: name "filename", flags = 04002 mode = 0666, fd = -1. Resource temporarily unavailable ...... ../source3/locking/share_mode_lock.c:341(get_share_mode_lock_internal) get_share_mode_lock_internal: Could not get share mode lock ...... ../source3/smbd/open.c:2759(open_file_ntcreate) No share mode lock found after EWOULDBLOCK, retrying sync ------------------------- I have read the source,the simple logic is like the next.The logic shows while share mode lock is null,a call back event is missing. I think it is the full response's event. ---------the simple source logic-------------- schedule_defer_open defer_open(lck,....... if (lck) { //lck is not NULL …… watch_req = dbwrap_record_watch_send( //create the watcher …… tevent_req_set_callback(watch_req, defer_open_done, //add the call back event's …… } ----------------------- A STATUS_PENDING is responsed but a full response missed when get_share_mode_lock_internal Could not get share mode lockget locker. I think it is a bug. script's main code --------------- set objFs = CreateObject("scripting.filesystemobject") Set objTxtSt = objFs.CreateTextFile(strCSV1, True) objTxtSt.Close ---------------
Ralph, isn't that the EAGAIN problem we looked at a few weeks ago?
(In reply to Stefan Metzmacher from comment #1) Thank you for your help. Did the EAGAIN problem has a bug number.
Hm, iirc that was EINTR in bug #12853.
(In reply to Ralph Böhme from comment #3) Thank you for your help. It isn't the same problem to bug #12853. I have two problems. 1 1: The full response is missing after a STATUS_PENDING response. 2: The reason of get_share_mode_lock_internal's "Could not get share mode lock".
Created attachment 13487 [details] The debug logs for Samba response a STATUS_PENDING but a full response missed
For the reference: The reporter has asked to delete the attachment. That's why I put this to private.
(In reply to Volker Lendecke from comment #7) Thank you for your help. Another debug log which the same as the attachment has been added as comment #6.
The content of attachment 13487 [details] has been deleted for the following reason: requested by user
Is this still reproducible with current master?
(In reply to Ralph Böhme from comment #11) sorry for the late reply. The following versions have been confirmed. It has been fixed. 4.7.1 4.8.5 4.9.0
The debug logs for Samba response a STATUS_PENDING but a full response missed 1 [2017/08/22 16:27:14.609334, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/smb2_server.c:3464(smbd_smb2_io_handler) 2 smbd_smb2_request idx[1] of 5 vectors 3 [2017/08/22 16:27:14.609378, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/smb2_server.c:646(smb2_validate_sequence_number) 4 smb2_validate_sequence_number: clearing id 158 (position 158) from bitmap 5 [2017/08/22 16:27:14.609395, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/smb2_server.c:1954(smbd_smb2_request_dispatch) 6 smbd_smb2_request_dispatch: opcode[SMB2_OP_CREATE] mid = 158 7 [2017/08/22 16:27:14.609414, 4, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/uid.c:384(change_to_user) 8 Skipping user change - already user 9 [2017/08/22 16:27:14.609440, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/smb2_create.c:501(smbd_smb2_create_send) 10 smbd_smb2_create: name[etc\local.csv] 11 [2017/08/22 16:27:14.609458, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/smb2_create.c:917(smbd_smb2_create_send) 12 smbd_smb2_create_send: open execution phase 13 [2017/08/22 16:27:14.609473, 5, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/filename.c:257(unix_convert) 14 unix_convert called on file "etc/local.csv" 15 [2017/08/22 16:27:14.609494, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/statcache.c:283(stat_cache_lookup) 16 stat_cache_lookup: lookup succeeded for name [ETC/LOCAL.CSV] -> [etc/local.csv] 17 [2017/08/22 16:27:14.609523, 5, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/filename.c:449(unix_convert) 18 unix_convert begin: name = etc/local.csv, dirpath = , start = etc/local.csv 19 [2017/08/22 16:27:14.609544, 5, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/filename.c:184(check_parent_exists) 20 check_parent_exists: name = etc/local.csv, dirpath = etc, start = local.csv 21 [2017/08/22 16:27:14.609568, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/mangle_hash2.c:418(is_mangled) 22 is_mangled local.csv ? 23 [2017/08/22 16:27:14.609584, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/mangle_hash2.c:357(is_mangled_component) 24 is_mangled_component local.csv (len 9) ? 25 [2017/08/22 16:27:14.609600, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/mangle_hash2.c:418(is_mangled) 26 is_mangled local.csv ? 27 [2017/08/22 16:27:14.609629, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/mangle_hash2.c:357(is_mangled_component) 28 is_mangled_component local.csv (len 9) ? 29 [2017/08/22 16:27:14.609670, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/mangle_hash2.c:418(is_mangled) 30 is_mangled local.csv ? 31 [2017/08/22 16:27:14.609686, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/mangle_hash2.c:357(is_mangled_component) 32 is_mangled_component local.csv (len 9) ? 33 [2017/08/22 16:27:14.609699, 5, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/filename.c:844(unix_convert) 34 New file local.csv 35 [2017/08/22 16:27:14.609714, 3, pid=2159, effective(1003, 1003), real(1003, 0), class=vfs] ../source3/smbd/vfs.c:1174(check_reduced_name) 36 check_reduced_name [etc/local.csv] [/test] 37 [2017/08/22 16:27:14.609741, 10, pid=2159, effective(1003, 1003), real(1003, 0), class=vfs] ../source3/smbd/vfs.c:1234(check_reduced_name) 38 check_reduced_name realpath [etc/local.csv] -> [/test/etc/local.csv] 39 [2017/08/22 16:27:14.609756, 3, pid=2159, effective(1003, 1003), real(1003, 0), class=vfs] ../source3/smbd/vfs.c:1322(check_reduced_name) 40 check_reduced_name: etc/local.csv reduced to /test/etc/local.csv 41 [2017/08/22 16:27:14.609771, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/open.c:4986(create_file_default) 42 create_file: access_mask = 0x16019f file_attributes = 0x20, share_access = 0x0, create_disposition = 0x2 create_options = 0x44 oplock_request = 0x2 private_flags = 0x 0 root_dir_fid = 0x0, ea_list = 0x(nil), sd = 0x(nil), fname = etc/local.csv 43 [2017/08/22 16:27:14.609789, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/open.c:4463(create_file_unixpath) 44 create_file_unixpath: access_mask = 0x16019f file_attributes = 0x20, share_access = 0x0, create_disposition = 0x2 create_options = 0x44 oplock_request = 0x2 private_f lags = 0x0 ea_list = 0x(nil), sd = 0x(nil), fname = etc/local.csv 45 [2017/08/22 16:27:14.609811, 5, pid=2159, effective(1003, 1003), real(1003, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) 46 check lock order 1 for /var/lib/samba/smbXsrv_open_global.tdb 47 [2017/08/22 16:27:14.609827, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) 48 lock order: 1:/var/lib/samba/smbXsrv_open_global.tdb 2:<none> 3:<none> 49 [2017/08/22 16:27:14.609845, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) 50 Locking key E02D9CD3 51 [2017/08/22 16:27:14.609866, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) 52 Allocated locked data 0x0x7f0840df8bb0 53 [2017/08/22 16:27:14.609882, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/smbXsrv_open.c:584(smbXsrv_open_global_verify_record) 54 smbXsrv_open_global_verify_record: empty value 55 [2017/08/22 16:27:14.609916, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/smbXsrv_open.c:702(smbXsrv_open_global_store) 56 smbXsrv_open_global_store: key 'E02D9CD3' stored 57 [2017/08/22 16:27:14.609935, 1, pid=2159, effective(1003, 1003), real(1003, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) 58 &global_blob: struct smbXsrv_open_globalB 59 version : SMBXSRV_VERSION_0 (0) 60 seqnum : 0x00000001 (1) 61 info : union smbXsrv_open_globalU(case 0) 62 info0 : * 63 info0: struct smbXsrv_open_global0 64 db_rec : * 65 server_id: struct server_id 66 pid : 0x000000000000086f (2159) 67 task_id : 0x00000000 (0) 68 vnn : 0xffffffff (4294967295) 69 unique_id : 0x2541aa8afef7c726 (2684614366849386278) 70 open_global_id : 0xe02d9cd3 (3761085651) 71 open_persistent_id : 0x00000000e02d9cd3 (3761085651) 72 open_volatile_id : 0x00000000371b8263 (924549731) 73 open_owner : S-1-5-21-565434867-2860691321-1600925857-1000 74 open_time : Tue Aug 22 04:27:15 PM 2017 CST 75 create_guid : 00000000-0000-0000-0000-000000000000 76 client_guid : 3c26f202-86a5-11e7-b6b8-525400ebf704 77 app_instance_id : 00000000-0000-0000-0000-000000000000 78 disconnect_time : NTTIME(0) 79 durable_timeout_msec : 0x00000000 (0) 80 durable : 0x00 (0) 81 backend_cookie : DATA_BLOB length=0 82 [2017/08/22 16:27:14.610076, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) 83 Unlocking key E02D9CD3 84 [2017/08/22 16:27:14.610136, 5, pid=2159, effective(1003, 1003), real(1003, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) 85 release lock order 1 for /var/lib/samba/smbXsrv_open_global.tdb 86 [2017/08/22 16:27:14.610152, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) 87 lock order: 1:<none> 2:<none> 3:<none> 88 [2017/08/22 16:27:14.610168, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/smbXsrv_open.c:876(smbXsrv_open_create) 89 smbXsrv_open_create: global_id (0xe02d9cd3) stored 90 [2017/08/22 16:27:14.610182, 1, pid=2159, effective(1003, 1003), real(1003, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) 91 &open_blob: struct smbXsrv_openB 92 version : SMBXSRV_VERSION_0 (0) 93 reserved : 0x00000000 (0) 94 info : union smbXsrv_openU(case 0) 95 info0 : * 96 info0: struct smbXsrv_open 97 table : * 98 db_rec : NULL 99 local_id : 0x371b8263 (924549731) 100 global : * 101 global: struct smbXsrv_open_global0 102 db_rec : NULL 103 server_id: struct server_id 104 pid : 0x000000000000086f (2159) 105 task_id : 0x00000000 (0) 106 vnn : 0xffffffff (4294967295) 107 unique_id : 0x2541aa8afef7c726 (2684614366849386278) 108 open_global_id : 0xe02d9cd3 (3761085651) 109 open_persistent_id : 0x00000000e02d9cd3 (3761085651) 110 open_volatile_id : 0x00000000371b8263 (924549731) 111 open_owner : S-1-5-21-565434867-2860691321-1600925857-1000 112 open_time : Tue Aug 22 04:27:15 PM 2017 CST 113 create_guid : 00000000-0000-0000-0000-000000000000 114 client_guid : 3c26f202-86a5-11e7-b6b8-525400ebf704 115 app_instance_id : 00000000-0000-0000-0000-000000000000 116 disconnect_time : NTTIME(0) 117 durable_timeout_msec : 0x00000000 (0) 118 durable : 0x00 (0) 119 backend_cookie : DATA_BLOB length=0 120 status : NT_STATUS_OK 121 idle_time : Tue Aug 22 04:27:15 PM 2017 CST 122 compat : NULL 123 [2017/08/22 16:27:14.610363, 5, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/files.c:129(file_new) 124 allocated file structure fnum 924549731 (3 used) 125 [2017/08/22 16:27:14.610382, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/files.c:744(file_name_hash) 126 file_name_hash: /test/etc/local.csv hash 0x463a0bd6 127 [2017/08/22 16:27:14.610401, 3, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/dosmode.c:196(unix_mode) 128 unix_mode(etc/local.csv) returning 0666 129 [2017/08/22 16:27:14.610416, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/open.c:2492(open_file_ntcreate) 130 open_file_ntcreate: fname=etc/local.csv, dos_attrs=0x20 access_mask=0x16019f share_access=0x0 create_disposition = 0x2 create_options=0x44 unix mode=0666 oplock_reque st=2 private_flags = 0x0 131 [2017/08/22 16:27:14.610434, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/open.c:2650(open_file_ntcreate) 132 open_file_ntcreate: fname=etc/local.csv, after mapping access_mask=0x16019f 133 [2017/08/22 16:27:14.610449, 4, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/open.c:2740(open_file_ntcreate) 134 calling open_file with flags=0x2 flags2=0x8C0 mode=0666, access_mask = 0x16019f, open_access_mask = 0x16019f 135 [2017/08/22 16:27:14.610466, 10, pid=2159, effective(1003, 1003), real(1003, 0), class=acls] ../source3/smbd/posix_acls.c:3521(posix_get_nt_acl) 136 posix_get_nt_acl: called for file etc 137 [2017/08/22 16:27:14.610504, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/passdb/lookup_sid.c:1237(uid_to_sid) 138 uid 0 -> sid S-1-5-21-565434867-2860691321-1600925857-1001 139 [2017/08/22 16:27:14.611403, 5, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/passdb/lookup_sid.c:1278(gid_to_sid) 140 gid_to_sid: winbind failed to find a sid for gid 1003 141 [2017/08/22 16:27:14.611438, 4, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/sec_ctx.c:216(push_sec_ctx) 142 push_sec_ctx(1003, 1003) : sec_ctx_stack_ndx = 1 143 [2017/08/22 16:27:14.611458, 4, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/uid.c:491(push_conn_ctx) 144 push_conn_ctx(1826659811) : conn_ctx_stack_ndx = 0 145 [2017/08/22 16:27:14.611472, 4, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/sec_ctx.c:316(set_sec_ctx) 146 setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1 147 [2017/08/22 16:27:14.611487, 5, pid=2159, effective(1003, 1003), real(1003, 0)] ../libcli/security/security_token.c:53(security_token_debug) 148 Security token: (NULL) 149 [2017/08/22 16:27:14.611500, 5, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) 150 UNIX token of user 0 151 Primary group is 0 and contains 0 supplementary groups 152 [2017/08/22 16:27:14.611542, 4, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/sec_ctx.c:421(pop_sec_ctx) 153 pop_sec_ctx (1003, 1003) - sec_ctx_stack_ndx = 0 154 [2017/08/22 16:27:14.611560, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/passdb/lookup_sid.c:1141(legacy_gid_to_sid) 155 LEGACY: gid 1003 -> sid S-1-22-2-1003 156 [2017/08/22 16:27:14.611578, 10, pid=2159, effective(1003, 1003), real(1003, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) 157 canonicalise_acl: Access ace entries before arrange : 158 [2017/08/22 16:27:14.611592, 10, pid=2159, effective(1003, 1003), real(1003, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) 159 canon_ace index 0. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms rwx 160 [2017/08/22 16:27:14.611632, 10, pid=2159, effective(1003, 1003), real(1003, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) 161 canon_ace index 1. Type = allow SID = S-1-22-2-1003 gid 1003 (jawk0102) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms rwx 162 [2017/08/22 16:27:14.611722, 10, pid=2159, effective(1003, 1003), real(1003, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) 163 canon_ace index 2. Type = allow SID = S-1-5-21-565434867-2860691321-1600925857-1001 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx 164 [2017/08/22 16:27:14.611784, 10, pid=2159, effective(1003, 1003), real(1003, 0), class=acls] ../source3/smbd/posix_acls.c:848(print_canon_ace_list) 165 print_canon_ace_list: canonicalise_acl: ace entries after arrange 166 canon_ace index 0. Type = allow SID = S-1-5-21-565434867-2860691321-1600925857-1001 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx 167 canon_ace index 1. Type = allow SID = S-1-22-2-1003 gid 1003 (jawk0102) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms rwx 168 canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms rwx 169 [2017/08/22 16:27:14.611917, 10, pid=2159, effective(1003, 1003), real(1003, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) 170 map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff 171 [2017/08/22 16:27:14.611936, 10, pid=2159, effective(1003, 1003), real(1003, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) 172 map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff 173 [2017/08/22 16:27:14.611950, 10, pid=2159, effective(1003, 1003), real(1003, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) 174 map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff 175 [2017/08/22 16:27:14.612062, 3, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/open.c:414(fd_open) 176 smbd_check_access_rights: nanosleep. 177 [2017/08/22 16:27:14.612113, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/open.c:422(fd_open) 178 fd_open: name etc/local.csv, flags = 04302 mode = 0666, fd = -1. Resource temporarily unavailable 179 [2017/08/22 16:27:14.612139, 3, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/open.c:895(open_file) 180 Error opening file etc/local.csv (NT_STATUS_NETWORK_BUSY) (local_flags=2242) (flags=2242) 181 [2017/08/22 16:27:14.612166, 5, pid=2159, effective(1003, 1003), real(1003, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) 182 check lock order 1 for /var/lib/samba/locking.tdb 183 [2017/08/22 16:27:14.612180, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) 184 lock order: 1:/var/lib/samba/locking.tdb 2:<none> 3:<none> 185 [2017/08/22 16:27:14.612199, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) 186 Locking key 00000000000000000000 187 [2017/08/22 16:27:14.612238, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) 188 Allocated locked data 0x0x7f0840e01e50 189 [2017/08/22 16:27:14.612258, 4, pid=2159, effective(1003, 1003), real(1003, 0), class=locking] ../source3/locking/share_mode_lock.c:336(get_share_mode_lock_internal) 190 get_share_mode_lock_internal witeh servicepath=NULL smb_fname=NULL ,old_write_time = NULL 191 [2017/08/22 16:27:14.612273, 5, pid=2159, effective(1003, 1003), real(1003, 0), class=locking] ../source3/locking/share_mode_lock.c:347(get_share_mode_lock_internal) 192 get_share_mode_lock_internal: Could not get share mode lock 193 [2017/08/22 16:27:14.612289, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) 194 Unlocking key 00000000000000000000 195 [2017/08/22 16:27:14.612306, 5, pid=2159, effective(1003, 1003), real(1003, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) 196 release lock order 1 for /var/lib/samba/locking.tdb 197 [2017/08/22 16:27:14.612320, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) 198 lock order: 1:<none> 2:<none> 3:<none> 199 [2017/08/22 16:27:14.612336, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/open.c:1924(defer_open) 200 defer_open_sharing_error: time [1503390434.609806] adding deferred open entry for mid 158 201 [2017/08/22 16:27:14.612352, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/smb2_create.c:1610(push_deferred_open_message_smb2) 202 push_deferred_open_message_smb2: timeout at 2017/08/22 16:27:14.609806 203 [2017/08/22 16:27:14.612373, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/open.c:2773(open_file_ntcreate) 204 No share mode lock found after EWOULDBLOCK, retrying sync 205 [2017/08/22 16:27:14.612395, 5, pid=2159, effective(1003, 1003), real(1003, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) 206 check lock order 1 for /var/lib/samba/smbXsrv_open_global.tdb 207 [2017/08/22 16:27:14.612411, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) 208 lock order: 1:/var/lib/samba/smbXsrv_open_global.tdb 2:<none> 3:<none> 209 [2017/08/22 16:27:14.612427, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) 210 Locking key E02D9CD3 211 [2017/08/22 16:27:14.612446, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) 212 Allocated locked data 0x0x7f0840e35a90 213 [2017/08/22 16:27:14.612468, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) 214 Unlocking key E02D9CD3 215 [2017/08/22 16:27:14.612483, 5, pid=2159, effective(1003, 1003), real(1003, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) 216 release lock order 1 for /var/lib/samba/smbXsrv_open_global.tdb 217 [2017/08/22 16:27:14.612497, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) 218 lock order: 1:<none> 2:<none> 3:<none> 219 [2017/08/22 16:27:14.612516, 5, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/files.c:555(file_free) 220 freed files structure 924549731 (2 used) 221 [2017/08/22 16:27:14.612530, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/open.c:4807(create_file_unixpath) 222 create_file_unixpath: NT_STATUS_SHARING_VIOLATION 223 [2017/08/22 16:27:14.612544, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/open.c:5083(create_file_default) 224 create_file: NT_STATUS_SHARING_VIOLATION 225 [2017/08/22 16:27:14.612559, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/smb2_create.c:1419(open_was_deferred_smb2) 226 open_was_deferred_smb2: mid = 158 227 smbd_smb2_request_pending_queue: req->current_idx = 1 228 req->in.vector[0].iov_len = 0 229 req->in.vector[1].iov_len = 0 230 req->in.vector[2].iov_len = 64 231 req->in.vector[3].iov_len = 56 232 req->in.vector[4].iov_len = 152 233 req->out.vector[0].iov_len = 4 234 req->out.vector[1].iov_len = 0 235 req->out.vector[2].iov_len = 64 236 req->out.vector[3].iov_len = 8 237 req->out.vector[4].iov_len = 0 238 [2017/08/22 16:27:14.613733, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/smb2_server.c:1482(smbd_smb2_request_pending_timer) 239 smbd_smb2_request_pending_queue: opcode[SMB2_OP_CREATE] mid 158 going async 240 [2017/08/22 16:27:14.613773, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/smb2_server.c:898(smb2_set_operation_credit) 241 smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 482/512, total granted/max/low/range 31/8192/159/31 242 [2017/08/22 16:27:14.613790, 10, pid=2159, effective(1003, 1003), real(1003, 0)] ../source3/smbd/smb2_server.c:1576(smbd_smb2_request_pending_timer) 243 state->vector[0/5].iov_len = 4 244 state->vector[1/5].iov_len = 0 245 state->vector[2/5].iov_len = 64 246 state->vector[3/5].iov_len = 8 247 state->vector[4/5].iov_len = 1
(In reply to Lihaitao from comment #13) I have uploaded a debug log for users who might encounter the same issue in the future.