Bug 12979 - The Samba response a STATUS_PENDING but a full response missed when get_share_mode_lock_internal Could not get share mode locker .
Summary: The Samba response a STATUS_PENDING but a full response missed when get_shar...
Status: RESOLVED FIXED
Alias: None
Product: Samba 4.1 and newer
Classification: Unclassified
Component: File services (show other bugs)
Version: 4.2.12
Hardware: x64 Linux
: P5 normal (vote)
Target Milestone: ---
Assignee: Ralph Böhme
QA Contact: Samba QA Contact
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2017-08-21 09:17 UTC by Lihaitao
Modified: 2018-09-27 09:34 UTC (History)
2 users (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Lihaitao 2017-08-21 09:17:40 UTC
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
---------------
Comment 1 Stefan Metzmacher 2017-08-21 09:30:08 UTC
Ralph, isn't that the EAGAIN problem we looked at a few weeks ago?
Comment 2 Lihaitao 2017-08-21 10:01:26 UTC
(In reply to Stefan Metzmacher from comment #1)
Thank you for your help.
Did the EAGAIN problem has a bug number.
Comment 3 Ralph Böhme 2017-08-21 11:36:15 UTC
Hm, iirc that was EINTR in bug #12853.
Comment 4 Lihaitao 2017-08-22 02:21:03 UTC
(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".
Comment 5 Lihaitao 2017-08-22 03:56:20 UTC
Created attachment 13487 [details]
The debug logs for  Samba response a STATUS_PENDING but a full response missed
Comment 7 Volker Lendecke 2017-08-31 06:29:16 UTC
For the reference: The reporter has asked to delete the attachment. That's why I put this to private.
Comment 9 Lihaitao 2017-08-31 06:54:03 UTC
(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.
Comment 10 Björn Jacke 2017-09-01 11:57:10 UTC
The content of attachment 13487 [details] has been deleted for the following reason:

requested by user
Comment 11 Ralph Böhme 2018-07-07 13:03:00 UTC
Is this still reproducible with current master?
Comment 12 Lihaitao 2018-09-20 03:54:07 UTC
(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
Comment 13 Lihaitao 2018-09-27 09:25:56 UTC
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
Comment 14 Lihaitao 2018-09-27 09:34:28 UTC
(In reply to Lihaitao from comment #13)
I have uploaded a debug log for users who might encounter the same issue in the future.