Bug 15767 - Deadlock between two smbd processes
Summary: Deadlock between two smbd processes
Status: ASSIGNED
Alias: None
Product: Samba 4.1 and newer
Classification: Unclassified
Component: File services (show other bugs)
Version: 4.19.8
Hardware: PPC Linux
: P5 major (vote)
Target Milestone: ---
Assignee: Ralph Böhme
QA Contact: Samba QA Contact
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2024-12-13 13:29 UTC by Xavi Hernandez
Modified: 2025-01-08 14:28 UTC (History)
5 users (show)

See Also:

Attachments
Python script to trigger the deadlock (5.42 KB, text/plain)
2024-12-18 19:09 UTC, Xavi Hernandez 		no flags Details
Draft patch for a fix... (5.03 KB, text/plain)
2024-12-23 12:19 UTC, Stefan Metzmacher 		no flags Details
View All Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Xavi Hernandez 2024-12-13 13:29:43 UTC 
I've observed a deadlock in two smbd processes. One was processing an SMB_OP_CREATE request and the other an SMB_OP_LOCK.

This is the stack trace of first process (PID 3225171):

#0  0x00007fffa0cecbb0 in __pthread_mutex_lock_full () from /lib64/glibc-hwcaps/power9/libpthread-2.28.so
#1  0x00007fffa0a73cf8 in chain_mutex_lock (m=<optimized out>, m@entry=0x7fff9b3a71b0, waitflag=<optimized out>, waitflag@entry=true) at ../../lib/tdb/common/mutex.c:182
#2  0x00007fffa0a7432c in tdb_mutex_lock (tdb=0x1543c6900, rw=<optimized out>, off=<optimized out>, len=<optimized out>, waitflag=<optimized out>, pret=0x7fffd7df2e28) at ../../lib/tdb/common/mutex.c:234
#3  0x00007fffa0a6812c in fcntl_lock (waitflag=<optimized out>, len=1, off=376608, rw=0, tdb=0x1543c6900) at ../../lib/tdb/common/lock.c:200
#4  tdb_brlock (tdb=0x1543c6900, rw_type=<optimized out>, offset=<optimized out>, len=1, flags=<optimized out>) at ../../lib/tdb/common/lock.c:200
#5  0x00007fffa0a68af8 in tdb_nest_lock (flags=<optimized out>, ltype=0, offset=<optimized out>, tdb=0x1543c6900) at ../../lib/tdb/common/lock.c:390
#6  tdb_nest_lock (tdb=0x1543c6900, offset=<optimized out>, ltype=<optimized out>, flags=<optimized out>) at ../../lib/tdb/common/lock.c:336
#7  0x00007fffa0a69088 in tdb_lock_list (tdb=0x1543c6900, list=<optimized out>, ltype=<optimized out>, waitflag=<optimized out>) at ../../lib/tdb/common/lock.c:482
#8  0x00007fffa0a69198 in tdb_lock (tdb=0x1543c6900, list=<optimized out>, ltype=<optimized out>) at ../../lib/tdb/common/lock.c:500
#9  0x00007fffa0a64b50 in tdb_find_lock_hash (tdb=<optimized out>, tdb@entry=0x1543c6900, key=..., hash=<optimized out>, locktype=<optimized out>, locktype@entry=0, rec=<optimized out>, rec@entry=0x7fffd7df3080) at ../../lib/tdb/common/tdb.c:165
#10 0x00007fffa0a64ed0 in tdb_parse_record (tdb=0x1543c6900, key=..., parser=0x7fffa0e74470 <db_ctdb_ltdb_parser>, private_data=0x7fffd7df30e8) at ../../lib/tdb/common/tdb.c:329
#11 0x00007fffa0e74cbc in db_ctdb_ltdb_parse (db=<optimized out>, private_data=0x7fffd7df3140, parser=0x7fffa0e76470 <db_ctdb_parse_record_parser_nonpersistent>, key=...) at ../../source3/lib/dbwrap/dbwrap_ctdb.c:170
#12 db_ctdb_try_parse_local_record (ctx=ctx@entry=0x154328fc0, key=..., state=state@entry=0x7fffd7df3140) at ../../source3/lib/dbwrap/dbwrap_ctdb.c:1385
#13 0x00007fffa0e76024 in db_ctdb_parse_record (db=<optimized out>, key=..., parser=0x7fffa14ec820 <brl_get_locks_readonly_parser>, private_data=0x7fffd7df3218) at ../../source3/lib/dbwrap/dbwrap_ctdb.c:1425
#14 0x00007fffa0884760 in dbwrap_parse_record (db=<optimized out>, key=..., parser=<optimized out>, private_data=<optimized out>) at ../../lib/dbwrap/dbwrap.c:454
#15 0x00007fffa14ef5bc in brl_get_locks_readonly (fsp=0x1543d01e0) at ../../source3/locking/brlock.c:1884
#16 0x00007fffa1546968 in file_has_brlocks (fsp=0x1543d01e0) at ../../source3/smbd/open.c:2232
#17 delay_for_oplock (pgranted=<synthetic pointer>, poplock_type=<synthetic pointer>, first_open_attempt=<optimized out>, create_disposition=1, have_sharing_violation=false, lck=0x7fffd7df3ce8, lease=0x0, oplock_request=0, fsp=0x1543d01e0) at ../../source3/smbd/open.c:2749
#18 handle_share_mode_lease (pgranted=<synthetic pointer>, poplock_type=<synthetic pointer>, first_open_attempt=<optimized out>, lease=0x0, oplock_request=0, share_access=7, access_mask=131201, create_disposition=1, lck=0x7fffd7df3ce8, fsp=0x1543d01e0) at ../../source3/smbd/open.c:2865
#19 check_and_store_share_mode (first_open_attempt=<optimized out>, lease=0x0, oplock_request=0, share_access=7, access_mask=131201, create_disposition=1, lck=0x7fffd7df3ce8, req=0x154414800, fsp=0x1543d01e0) at ../../source3/smbd/open.c:3333
#20 open_ntcreate_lock_add_entry (lck=0x7fffd7df3ce8, keep_locked=0x7fffd7df3ad0, private_data=0x7fffd7df3cc8) at ../../source3/smbd/open.c:3688
#21 0x00007fffa14f6248 in share_mode_entry_prepare_lock_fn (glck=0x7fffd7df35b8, cb_private=0x7fffd7df3a88) at ../../source3/locking/share_mode_lock.c:2978
#22 0x00007fffa1317680 in g_lock_lock_cb_run_and_store (cb_state=cb_state@entry=0x7fffd7df35b8) at ../../source3/lib/g_lock.c:597
#23 0x00007fffa1319df8 in g_lock_lock_simple_fn (rec=0x7fffd7df3798, value=..., private_data=0x7fffd7df39a0) at ../../source3/lib/g_lock.c:1212
#24 0x00007fffa13160e0 in dbwrap_watched_do_locked_fn (backend_rec=<optimized out>, backend_value=..., private_data=0x7fffd7df3768) at ../../source3/lib/dbwrap/dbwrap_watch.c:458
#25 0x00007fffa0884e48 in dbwrap_do_locked (db=<optimized out>, key=..., fn=0x7fffa1316080 <dbwrap_watched_do_locked_fn>, private_data=0x7fffd7df3768) at ../../lib/dbwrap/dbwrap.c:602
#26 0x00007fffa1315274 in dbwrap_watched_do_locked (db=0x1543a7160, key=..., fn=0x7fffa1319ca0 <g_lock_lock_simple_fn>, private_data=0x7fffd7df39a0) at ../../source3/lib/dbwrap/dbwrap_watch.c:480
#27 0x00007fffa0884d60 in dbwrap_do_locked (db=<optimized out>, key=..., fn=<optimized out>, private_data=<optimized out>) at ../../lib/dbwrap/dbwrap.c:582
#28 0x00007fffa131b458 in g_lock_lock (ctx=0x1543cc630, key=..., type=<optimized out>, timeout=..., cb_fn=0x7fffa14f6190 <share_mode_entry_prepare_lock_fn>, cb_private=0x7fffd7df3a88) at ../../source3/lib/g_lock.c:1267
#29 0x00007fffa14fd060 in _share_mode_entry_prepare_lock (prepare_state=0x7fffd7df3cc8, id=..., servicepath=<optimized out>, smb_fname=<optimized out>, old_write_time=<optimized out>, fn=<optimized out>, private_data=0x7fffd7df3cc8, location=0x7fffa165b880 "../../source3/smbd/open.c:4292") at ../../source3/locking/share_mode_lock.c:3033
#30 0x00007fffa15491e0 in open_file_ntcreate (conn=conn@entry=0x154382050, req=req@entry=0x154414800, access_mask=<optimized out>, access_mask@entry=131201, share_access=share_access@entry=7, create_disposition=create_disposition@entry=1, create_options=create_options@entry=0, new_dos_attributes=<optimized out>, new_dos_attributes@entry=128, oplock_request=oplock_request@entry=0, lease=<optimized out>, lease@entry=0x0, private_flags=<optimized out>, private_flags@entry=0, parent_dir_fname=<optimized out>, smb_fname_atname=<optimized out>, pinfo=<optimized out>, pinfo@entry=0x7fffd7df3f1c, fsp=<optimized out>, fsp@entry=0x1543d01e0) at ../../source3/smbd/open.c:4286
#31 0x00007fffa154b94c in create_file_unixpath (conn=conn@entry=0x154382050, req=req@entry=0x154414800, dirfsp=dirfsp@entry=0x15439a7f0, smb_fname=smb_fname@entry=0x154416300, access_mask=access_mask@entry=131201, share_access=share_access@entry=7, create_disposition=create_disposition@entry=1, create_options=create_options@entry=0, file_attributes=file_attributes@entry=128, oplock_request=<optimized out>, oplock_request@entry=0, lease=<optimized out>, lease@entry=0x0, allocation_size=allocation_size@entry=0, private_flags=private_flags@entry=0, sd=sd@entry=0x0, ea_list=ea_list@entry=0x0, result=result@entry=0x7fffd7df4168, pinfo=pinfo@entry=0x7fffd7df4160) at ../../source3/smbd/open.c:6290
#32 0x00007fffa154dfac in create_file_default (conn=0x154382050, req=0x154414800, dirfsp=0x15439a7f0, smb_fname=0x154416300, access_mask=<optimized out>, share_access=<optimized out>, create_disposition=<optimized out>, create_options=<optimized out>, file_attributes=128, oplock_request=0, lease=0x0, allocation_size=0, private_flags=0, sd=0x0, ea_list=0x0, result=0x1544144e8, pinfo=0x1544144fc, in_context_blobs=0x7fffd7df4798, out_context_blobs=0x154414710) at ../../source3/smbd/open.c:6609
#33 0x00007fffa150972c in vfswrap_create_file (handle=<optimized out>, req=<optimized out>, dirfsp=<optimized out>, smb_fname=<optimized out>, access_mask=<optimized out>, share_access=<optimized out>, create_disposition=<optimized out>, create_options=<optimized out>, file_attributes=128, oplock_request=0, lease=0x0, allocation_size=0, private_flags=0, sd=0x0, ea_list=0x0, result=0x1544144e8, pinfo=0x1544144fc, in_context_blobs=0x7fffd7df4798, out_context_blobs=0x154414710) at ../../source3/modules/vfs_default.c:776
#34 0x00007fffa1559cbc in smb_vfs_call_create_file (handle=<optimized out>, req=<optimized out>, dirfsp=<optimized out>, smb_fname=<optimized out>, access_mask=<optimized out>, share_access=<optimized out>, create_disposition=<optimized out>, create_options=<optimized out>, file_attributes=128, oplock_request=0, lease=0x0, allocation_size=0, private_flags=0, sd=0x0, ea_list=0x0, result=0x1544144e8, pinfo=0x1544144fc, in_context_blobs=0x7fffd7df4798, out_context_blobs=0x154414710) at ../../source3/smbd/vfs.c:1560
#35 0x00007fff9c0a9ec4 in smb_time_audit_create_file (handle=0x154426820, req=0x154414800, dirfsp=0x15439a7f0, fname=0x154416300, access_mask=<optimized out>, share_access=<optimized out>, create_disposition=<optimized out>, create_options=<optimized out>, file_attributes=128, oplock_request=0, lease=0x0, allocation_size=0, private_flags=0, sd=0x0, ea_list=0x0, result_fsp=0x1544144e8, pinfo=0x1544144fc, in_context_blobs=0x7fffd7df4798, out_context_blobs=0x154414710) at ../../source3/modules/vfs_time_audit.c:634
#36 0x00007fffa1559cbc in smb_vfs_call_create_file (handle=<optimized out>, req=<optimized out>, dirfsp=<optimized out>, smb_fname=<optimized out>, access_mask=<optimized out>, share_access=<optimized out>, create_disposition=<optimized out>, create_options=<optimized out>, file_attributes=128, oplock_request=0, lease=0x0, allocation_size=0, private_flags=0, sd=0x0, ea_list=0x0, result=0x1544144e8, pinfo=0x1544144fc, in_context_blobs=0x7fffd7df4798, out_context_blobs=0x154414710) at ../../source3/smbd/vfs.c:1560
#37 0x00007fffa1597aa8 in smbd_smb2_create_send (in_context_blobs=..., in_name=0x154413ca0, in_create_options=<optimized out>, in_create_disposition=<optimized out>, in_share_access=<optimized out>, in_file_attributes=<optimized out>, in_desired_access=<optimized out>, in_impersonation_level=<optimized out>, in_oplock_level=<optimized out>, smb2req=0x154413770, ev=0x154328120, mem_ctx=0x154413770) at ../../source3/smbd/smb2_create.c:1115
#38 smbd_smb2_request_process_create (smb2req=0x154413770) at ../../source3/smbd/smb2_create.c:291
#39 0x00007fffa158a628 in smbd_smb2_request_dispatch (req=0x154413770) at ../../source3/smbd/smb2_server.c:3485
#40 0x00007fffa158c540 in smbd_smb2_io_handler (fde_flags=<optimized out>, xconn=0x154313f30) at ../../source3/smbd/smb2_server.c:5112
#41 smbd_smb2_connection_handler (ev=<optimized out>, fde=<optimized out>, flags=<optimized out>, private_data=<optimized out>) at ../../source3/smbd/smb2_server.c:5150
#42 0x00007fffa1198b2c in tevent_common_invoke_fd_handler (fde=0x15435add0, flags=<optimized out>, removed=0x0) at ../../lib/tevent/tevent_fd.c:158
#43 0x00007fffa11a2b9c in epoll_event_loop (tvalp=0x7fffd7df4b28, epoll_ev=0x1543b4e80) at ../../lib/tevent/tevent_epoll.c:730
#44 epoll_event_loop_once (ev=<optimized out>, location=<optimized out>) at ../../lib/tevent/tevent_epoll.c:946
#45 0x00007fffa11a0090 in std_event_loop_once (ev=0x154328120, location=0x7fffa1668db8 "../../source3/smbd/smb2_process.c:2158") at ../../lib/tevent/tevent_standard.c:110
#46 0x00007fffa119744c in _tevent_loop_once (ev=0x154328120, location=0x7fffa1668db8 "../../source3/smbd/smb2_process.c:2158") at ../../lib/tevent/tevent.c:823
#47 0x00007fffa1197884 in tevent_common_loop_wait (ev=<optimized out>, location=<optimized out>) at ../../lib/tevent/tevent.c:950
#48 0x00007fffa119ffc0 in std_event_loop_wait (ev=0x154328120, location=0x7fffa1668db8 "../../source3/smbd/smb2_process.c:2158") at ../../lib/tevent/tevent_standard.c:141
#49 0x00007fffa1197978 in _tevent_loop_wait (ev=<optimized out>, location=<optimized out>) at ../../lib/tevent/tevent.c:971
#50 0x00007fffa15737fc in smbd_process (ev_ctx=0x154328120, msg_ctx=<optimized out>, sock_fd=<optimized out>, interactive=<optimized out>) at ../../source3/smbd/smb2_process.c:2158
#51 0x000000011db5c554 in smbd_accept_connection (ev=0x154328120, fde=<optimized out>, flags=<optimized out>, private_data=<optimized out>) at ../../source3/smbd/server.c:1150
#52 0x00007fffa1198b2c in tevent_common_invoke_fd_handler (fde=0x1543ac2d0, flags=<optimized out>, removed=0x0) at ../../lib/tevent/tevent_fd.c:158
#53 0x00007fffa11a2b9c in epoll_event_loop (tvalp=0x7fffd7df4f98, epoll_ev=0x154328350) at ../../lib/tevent/tevent_epoll.c:730
#54 epoll_event_loop_once (ev=<optimized out>, location=<optimized out>) at ../../lib/tevent/tevent_epoll.c:946
#55 0x00007fffa11a0090 in std_event_loop_once (ev=0x154328120, location=0x11db60b50 "../../source3/smbd/server.c:1499") at ../../lib/tevent/tevent_standard.c:110
#56 0x00007fffa119744c in _tevent_loop_once (ev=0x154328120, location=0x11db60b50 "../../source3/smbd/server.c:1499") at ../../lib/tevent/tevent.c:823
#57 0x00007fffa1197884 in tevent_common_loop_wait (ev=<optimized out>, location=<optimized out>) at ../../lib/tevent/tevent.c:950
#58 0x00007fffa119ffc0 in std_event_loop_wait (ev=0x154328120, location=0x11db60b50 "../../source3/smbd/server.c:1499") at ../../lib/tevent/tevent_standard.c:141
#59 0x00007fffa1197978 in _tevent_loop_wait (ev=<optimized out>, location=<optimized out>) at ../../lib/tevent/tevent.c:971
#60 0x000000011db58c54 in smbd_parent_loop (parent=<optimized out>, ev_ctx=0x154328120) at ../../source3/smbd/server.c:1499
#61 main (argc=<optimized out>, argv=<optimized out>) at ../../source3/smbd/server.c:2258

This is the stack trace of the second process (PID 3518686):

#0  0x00007fffa0cecbb0 in __pthread_mutex_lock_full () from /lib64/glibc-hwcaps/power9/libpthread-2.28.so
#1  0x00007fffa0a73cf8 in chain_mutex_lock (m=<optimized out>, m@entry=0x7fff9ae071b0, waitflag=<optimized out>, waitflag@entry=true) at ../../lib/tdb/common/mutex.c:182
#2  0x00007fffa0a7432c in tdb_mutex_lock (tdb=0x1543ba120, rw=<optimized out>, off=<optimized out>, len=<optimized out>, waitflag=<optimized out>, pret=0x7fffd7df3858) at ../../lib/tdb/common/mutex.c:234
#3  0x00007fffa0a6812c in fcntl_lock (waitflag=<optimized out>, len=1, off=376608, rw=0, tdb=0x1543ba120) at ../../lib/tdb/common/lock.c:200
#4  tdb_brlock (tdb=0x1543ba120, rw_type=<optimized out>, offset=<optimized out>, len=1, flags=<optimized out>) at ../../lib/tdb/common/lock.c:200
#5  0x00007fffa0a68af8 in tdb_nest_lock (flags=<optimized out>, ltype=0, offset=<optimized out>, tdb=0x1543ba120) at ../../lib/tdb/common/lock.c:390
#6  tdb_nest_lock (tdb=0x1543ba120, offset=<optimized out>, ltype=<optimized out>, flags=<optimized out>) at ../../lib/tdb/common/lock.c:336
#7  0x00007fffa0a69088 in tdb_lock_list (tdb=0x1543ba120, list=<optimized out>, ltype=<optimized out>, waitflag=<optimized out>) at ../../lib/tdb/common/lock.c:482
#8  0x00007fffa0a69198 in tdb_lock (tdb=0x1543ba120, list=<optimized out>, ltype=<optimized out>) at ../../lib/tdb/common/lock.c:500
#9  0x00007fffa0a64b50 in tdb_find_lock_hash (tdb=<optimized out>, tdb@entry=0x1543ba120, key=..., hash=<optimized out>, locktype=<optimized out>, locktype@entry=0, rec=<optimized out>, rec@entry=0x7fffd7df3ab0) at ../../lib/tdb/common/tdb.c:165
#10 0x00007fffa0a64ed0 in tdb_parse_record (tdb=0x1543ba120, key=..., parser=0x7fffa0e74470 <db_ctdb_ltdb_parser>, private_data=0x7fffd7df3b18) at ../../lib/tdb/common/tdb.c:329
#11 0x00007fffa0e74cbc in db_ctdb_ltdb_parse (db=<optimized out>, private_data=0x7fffd7df3b70, parser=0x7fffa0e76470 <db_ctdb_parse_record_parser_nonpersistent>, key=...) at ../../source3/lib/dbwrap/dbwrap_ctdb.c:170
#12 db_ctdb_try_parse_local_record (ctx=ctx@entry=0x1543d4580, key=..., state=state@entry=0x7fffd7df3b70) at ../../source3/lib/dbwrap/dbwrap_ctdb.c:1385
#13 0x00007fffa0e76024 in db_ctdb_parse_record (db=<optimized out>, key=..., parser=0x7fffa1313910 <dbwrap_watched_parse_record_parser>, private_data=0x7fffd7df3c08) at ../../source3/lib/dbwrap/dbwrap_ctdb.c:1425
#14 0x00007fffa0884760 in dbwrap_parse_record (db=<optimized out>, key=..., parser=<optimized out>, private_data=<optimized out>) at ../../lib/dbwrap/dbwrap.c:454
#15 0x00007fffa1313ab4 in dbwrap_watched_parse_record (db=0x1543a7160, key=..., parser=0x7fffa13187d0 <g_lock_dump_fn>, private_data=0x7fffd7df3ce8) at ../../source3/lib/dbwrap/dbwrap_watch.c:783
#16 0x00007fffa0884760 in dbwrap_parse_record (db=<optimized out>, key=..., parser=<optimized out>, private_data=<optimized out>) at ../../lib/dbwrap/dbwrap.c:454
#17 0x00007fffa131c004 in g_lock_dump (ctx=<error reading variable: value has been optimized out>, key=..., fn=0x7fffa14f3d70 <fsp_update_share_mode_flags_fn>, private_data=0x7fffd7df3dd8) at ../../source3/lib/g_lock.c:1653
#18 0x00007fffa14f434c in share_mode_g_lock_dump (key=..., fn=0x7fffa14f3d70 <fsp_update_share_mode_flags_fn>, private_data=0x7fffd7df3dd8) at ../../source3/locking/share_mode_lock.c:96
#19 0x00007fffa14f8d44 in fsp_update_share_mode_flags (fsp=0x15433c550) at ../../source3/locking/share_mode_lock.c:1181
#20 file_has_read_lease (fsp=0x15433c550) at ../../source3/locking/share_mode_lock.c:1207
#21 0x00007fffa15ccc98 in contend_level2_oplocks_begin_default (type=<optimized out>, fsp=0x15433c550) at ../../source3/smbd/smb2_oplock.c:1282
#22 smbd_contend_level2_oplocks_begin (fsp=0x15433c550, type=<optimized out>) at ../../source3/smbd/smb2_oplock.c:1338
#23 0x00007fffa0dd0b54 in contend_level2_oplocks_begin (fsp=<optimized out>, type=<optimized out>) at ../../source3/lib/smbd_shim.c:72
#24 0x00007fffa14ecfd0 in brl_lock_windows_default (br_lck=0x154421330, plock=0x7fffd7df4250) at ../../source3/locking/brlock.c:457
#25 0x00007fffa150b70c in vfswrap_brl_lock_windows (handle=<optimized out>, br_lck=<optimized out>, plock=<optimized out>) at ../../source3/modules/vfs_default.c:3424
#26 0x00007fffa1561910 in smb_vfs_call_brl_lock_windows (handle=<optimized out>, br_lck=<optimized out>, plock=<optimized out>) at ../../source3/smbd/vfs.c:2686
#27 0x00007fff9c0a7350 in smb_time_audit_brl_lock_windows (handle=<optimized out>, br_lck=0x154421330, plock=0x7fffd7df4250) at ../../source3/modules/vfs_time_audit.c:1740
#28 0x00007fffa1561910 in smb_vfs_call_brl_lock_windows (handle=<optimized out>, br_lck=<optimized out>, plock=<optimized out>) at ../../source3/smbd/vfs.c:2686
#29 0x00007fffa14ed410 in brl_lock (br_lck=0x154421330, smblctx=3102281601, pid=..., start=0, size=18446744073709551615, lock_type=<optimized out>, lock_flav=WINDOWS_LOCK, blocker_pid=0x7fffd7df4540, psmblctx=0x7fffd7df4558) at ../../source3/locking/brlock.c:1004
#30 0x00007fffa14e7b18 in do_lock_fn (lck=<optimized out>, private_data=0x7fffd7df4508) at ../../source3/locking/locking.c:271
#31 0x00007fffa14fcd94 in _share_mode_do_locked_vfs_allowed (id=..., fn=0x7fffa14e7a60 <do_lock_fn>, private_data=0x7fffd7df4508, location=<optimized out>) at ../../source3/locking/share_mode_lock.c:2927
#32 0x00007fffa14e918c in do_lock (fsp=0x15433c550, req_mem_ctx=<optimized out>, req_guid=<optimized out>, smblctx=<optimized out>, count=18446744073709551615, offset=0, lock_type=<optimized out>, lock_flav=<optimized out>, pblocker_pid=0x7fffd7df46f0, 
    psmblctx=0x7fffd7df46d8) at ../../source3/locking/locking.c:335
#33 0x00007fffa155381c in smbd_do_locks_try (fsp=0x15433c550, num_locks=<optimized out>, locks=0x1543bc310, blocker_idx=0x7fffd7df46d6, blocking_pid=0x7fffd7df46f0, blocking_smblctx=0x7fffd7df46d8) at ../../source3/smbd/blocking.c:46
#34 0x00007fffa159dc90 in smbd_smb2_lock_try (req=req@entry=0x1543bc080) at ../../source3/smbd/smb2_lock.c:590
#35 0x00007fffa159ee8c in smbd_smb2_lock_send (in_locks=<optimized out>, in_lock_count=1, in_lock_sequence=<optimized out>, fsp=0x15433c550, smb2req=0x1543532e0, ev=0x154328120, mem_ctx=0x1543532e0) at ../../source3/smbd/smb2_lock.c:488
#36 smbd_smb2_request_process_lock (req=0x1543532e0) at ../../source3/smbd/smb2_lock.c:150
#37 0x00007fffa158a368 in smbd_smb2_request_dispatch (req=0x1543532e0) at ../../source3/smbd/smb2_server.c:3515
#38 0x00007fffa158c540 in smbd_smb2_io_handler (fde_flags=<optimized out>, xconn=0x154313f30) at ../../source3/smbd/smb2_server.c:5112
#39 smbd_smb2_connection_handler (ev=<optimized out>, fde=<optimized out>, flags=<optimized out>, private_data=<optimized out>) at ../../source3/smbd/smb2_server.c:5150
#40 0x00007fffa1198b2c in tevent_common_invoke_fd_handler (fde=0x1543670f0, flags=<optimized out>, removed=0x0) at ../../lib/tevent/tevent_fd.c:158
#41 0x00007fffa11a2b9c in epoll_event_loop (tvalp=0x7fffd7df4b28, epoll_ev=0x1543b4e80) at ../../lib/tevent/tevent_epoll.c:730
#42 epoll_event_loop_once (ev=<optimized out>, location=<optimized out>) at ../../lib/tevent/tevent_epoll.c:946
#43 0x00007fffa11a0090 in std_event_loop_once (ev=0x154328120, location=0x7fffa1668db8 "../../source3/smbd/smb2_process.c:2158") at ../../lib/tevent/tevent_standard.c:110
#44 0x00007fffa119744c in _tevent_loop_once (ev=0x154328120, location=0x7fffa1668db8 "../../source3/smbd/smb2_process.c:2158") at ../../lib/tevent/tevent.c:823
#45 0x00007fffa1197884 in tevent_common_loop_wait (ev=<optimized out>, location=<optimized out>) at ../../lib/tevent/tevent.c:950
#46 0x00007fffa119ffc0 in std_event_loop_wait (ev=0x154328120, location=0x7fffa1668db8 "../../source3/smbd/smb2_process.c:2158") at ../../lib/tevent/tevent_standard.c:141
#47 0x00007fffa1197978 in _tevent_loop_wait (ev=<optimized out>, location=<optimized out>) at ../../lib/tevent/tevent.c:971
#48 0x00007fffa15737fc in smbd_process (ev_ctx=0x154328120, msg_ctx=<optimized out>, sock_fd=<optimized out>, interactive=<optimized out>) at ../../source3/smbd/smb2_process.c:2158
#49 0x000000011db5c554 in smbd_accept_connection (ev=0x154328120, fde=<optimized out>, flags=<optimized out>, private_data=<optimized out>) at ../../source3/smbd/server.c:1150
#50 0x00007fffa1198b2c in tevent_common_invoke_fd_handler (fde=0x1543ac2d0, flags=<optimized out>, removed=0x0) at ../../lib/tevent/tevent_fd.c:158
#51 0x00007fffa11a2b9c in epoll_event_loop (tvalp=0x7fffd7df4f98, epoll_ev=0x154328350) at ../../lib/tevent/tevent_epoll.c:730
#52 epoll_event_loop_once (ev=<optimized out>, location=<optimized out>) at ../../lib/tevent/tevent_epoll.c:946
#53 0x00007fffa11a0090 in std_event_loop_once (ev=0x154328120, location=0x11db60b50 "../../source3/smbd/server.c:1499") at ../../lib/tevent/tevent_standard.c:110
#54 0x00007fffa119744c in _tevent_loop_once (ev=0x154328120, location=0x11db60b50 "../../source3/smbd/server.c:1499") at ../../lib/tevent/tevent.c:823
#55 0x00007fffa1197884 in tevent_common_loop_wait (ev=<optimized out>, location=<optimized out>) at ../../lib/tevent/tevent.c:950
#56 0x00007fffa119ffc0 in std_event_loop_wait (ev=0x154328120, location=0x11db60b50 "../../source3/smbd/server.c:1499") at ../../lib/tevent/tevent_standard.c:141
#57 0x00007fffa1197978 in _tevent_loop_wait (ev=<optimized out>, location=<optimized out>) at ../../lib/tevent/tevent.c:971
#58 0x000000011db58c54 in smbd_parent_loop (parent=<optimized out>, ev_ctx=0x154328120) at ../../source3/smbd/server.c:1499
#59 main (argc=<optimized out>, argv=<optimized out>) at ../../source3/smbd/server.c:2258

Both processes are waiting in a mutex. If we check what they are waiting for, we get:

First process (PID 3225171):

(gdb) f 3
#3  0x00007fffa0a6812c in fcntl_lock (waitflag=<optimized out>, len=1, off=376608, rw=0, tdb=0x1543c6900) at ../../lib/tdb/common/lock.c:200
200                     ret = fcntl_lock(tdb, rw_type, offset, len,
(gdb) p off
$1 = 376608
(gdb) p *tdb
$2 = {
  name = 0x154343850 "/var/lib/ctdb/volatile/brlock.tdb.10", 
  map_ptr = 0x7fff792c0000, 
  fd = 24, 
  map_size = 37224448, 
  read_only = 0, 
  traverse_read = 0, 
  traverse_write = 0, 
  allrecord_lock = {
    off = 0, 
    count = 0, 
    ltype = 0
  }, 
  num_lockrecs = 0, 
  lockrecs = 0x154439a10, 
  lockrecs_array_length = 2, 
  hdr_ofs = 4063232, 
  mutexes = 0x7fff9b010000, 
  ecode = TDB_ERR_NOEXIST, 
  hash_size = 100001, 
  feature_flags = 1, 
  flags = 7361, 
  travlocks = {
    next = 0x0, 
    off = 0, 
    list = 0, 
    lock_rw = 0
  }, 
  next = 0x154313d70, 
  device = 57, 
  inode = 159845439, 
  log = {
    log_fn = 0x7fffa0131010 <tdb_wrap_log>, 
    log_private = 0x0
  }, 
  hash_fn = 0x7fffa0a71e00 <tdb_jenkins_hash>, 
  open_flags = 524290, 
  methods = 0x7fffa0a8f9b8 <io_methods>, 
  transaction = 0x0, 
  page_size = 65536, 
  max_dead_records = 0, 
  interrupt_sig_ptr = 0x0
}

The second process (PID 3518686):

(gdb) f 3
#3  0x00007fffa0a6812c in fcntl_lock (waitflag=<optimized out>, len=1, off=376608, rw=0, tdb=0x1543ba120) at ../../lib/tdb/common/lock.c:200
200                     ret = fcntl_lock(tdb, rw_type, offset, len,
(gdb) p off
$1 = 376608
(gdb) p *tdb
$2 = {
  name = 0x154352010 "/var/lib/ctdb/volatile/locking.tdb.10", 
  map_ptr = 0x7fff7b770000, 
  fd = 25, 
  map_size = 205127680, 
  read_only = 0, 
  traverse_read = 0, 
  traverse_write = 0, 
  allrecord_lock = {
    off = 0, 
    count = 0, 
    ltype = 0
  }, 
  num_lockrecs = 0, 
  lockrecs = 0x154300e40, 
  lockrecs_array_length = 2, 
  hdr_ofs = 4063232, 
  mutexes = 0x7fff9aa70000, 
  ecode = TDB_ERR_NOEXIST, 
  hash_size = 100001, 
  feature_flags = 1, 
  flags = 7361, 
  travlocks = {
    next = 0x0, 
    off = 0, 
    list = 0, 
    lock_rw = 0
  }, 
  next = 0x1543c6900, 
  device = 57, 
  inode = 159845438, 
  log = {
    log_fn = 0x7fffa0131010 <tdb_wrap_log>, 
    log_private = 0x0
  }, 
  hash_fn = 0x7fffa0a71e00 <tdb_jenkins_hash>, 
  open_flags = 524290, 
  methods = 0x7fffa0a8f9b8 <io_methods>, 
  transaction = 0x0, 
  page_size = 65536, 
  max_dead_records = 0, 
  interrupt_sig_ptr = 0x0
}

Both are waiting for offset 376608, which maps to chain 94110, but for different tdb's.

Now looking the owner of chain 94110 in locking.tdb and brlock.tdb, I see the following:

locking.tdb, chain 94110 -> owner = 3225171
brlock.tdb, chain 94110 -> owner = 3518686

So process 3225171 owns locking.tdb:94110, and waits for brlock.tdb:94110.
And process 3518686 owns brlock.tdb:94110, and waits for locking.tdb:94110.

This is a deadlock.

When this happens, problems begin to accumulate, specially when ctdb vacuuming is triggered because it gets blocked trying to acquire the global lock of the tdb files, which timeouts after 120 seconds but causes all other locking operations from smbd to be blocked during that time.

The server is running RHEL 8.10, kernel 4.18.0-553.22.1 on ppc64le.

This server belongs to a Samba cluster with CTDB. The same issue has happened in other servers as well, on different days. Restarting samba resolves the problem.

When I was going to create the BZ, I've seen this old bug #13267, which looks similar and could be related.
Comment 1 Xavi Hernandez 2024-12-16 10:14:40 UTC 
I'm not sure if it could be useful, but I've seen that the only relation between the two operations seems to be the hash bucket they access. The key of the hash table is different, and the requests come from different clients (different IPs) connected to different shares.
Comment 2 Xavi Hernandez 2024-12-18 19:05:58 UTC 
I've been able to reproduce the deadlock on upstream master branch using a very minimal configuration.

This is the smb.conf:

    [global]
            security = user

    [share]
            path = /share
            guest ok = no
            browseable = yes
            read only = no
            comment = share

To increase the chances that the two processes use the same mutex, I've changed SMBD_VOLATILE_TDB_HASH_SIZE to 1 and recompiled.

Once done, I've started a process that opens and closes a file in an infinite loop. Another process locks and unlocks a byte range of another file in an infinite loop.

If the file accessed by by both processes is the same, everything works fine, but if they access different files, the deadlock happens.

I've had to create a python script to reproduce the deadlock since it's hard to force a real Windows client to continuously open and close a file (at least I have been unable to do so) because it seems to keep the file internally open even though the application closes it, so the server doesn't see the requests. To force Windows send the opens I need to create another process on another client accessing the same file, but this prevents the deadlock somehow.

I'll attach the script I used to reproduce it.
Comment 3 Xavi Hernandez 2024-12-18 19:09:54 UTC 
Created attachment 18515 [details]
Python script to trigger the deadlock

This script requires smbprotocol python package. I've needed to implement the Lock request because it was not implemented, but fortunately it was easy.

To trigger the deadlock, just run two instances of the script, using the following commands:

    # deadlock.py <smbd server ip> <user> <password> share testfile1 open &
    # deadlock.py <smbd server ip> <user> <password> share testfile2 lock &

This should immediately trigger the deadlock.
Comment 4 Xavi Hernandez 2024-12-19 10:41:33 UTC 
After looking at the code, the problem seems to happen in do_lock_fn(), in source3/locking/locking.c while processing an SMB LOCK request.

This function calls brl_get_locks_for_locking(), and then brl_lock().

The first function calls brl_get_locks(), which has this comment:

       /*******************************************************************            
        Fetch a set of byte range lock data from the database.                         
----->  Leave the record locked.                                                       
        TALLOC_FREE(brl) will release the lock in the destructor.                      
       ********************************************************************/           

This function ends up calling dbwrap_fecth_locked(), which checks lock order and succeeds since there's no other lock acquired.

After completing brl_get_locks_for_locking() an entry from brlock.tdb is still acquired.

The second function, brl_lock(), ends up calling dbwrap_parse_record(), which doesn't check lock order but tries to acquire a lock from locking.tdb.

This means that this process acquires locks in reverse order, since locking.tdb should be the first one, and brlock.tdb the second one.

This causes the deadlock.

Probably we should add lock order check in dbwrap_parse_record(), but this won't solve the problem. It will just detect it and will force a crash instead of causing a deadlock.

It also doesn't seem possible to reverse the order of the brl_get_locks_for_locking() and brl_lock() functions, nor release the lock before calling brl_lock(), so I'm not sure what's the right solution here.
Comment 5 Volker Lendecke 2024-12-19 14:57:55 UTC 
Wow, brilliant analysis.

In the second stacktrace of the original comment here, there's the contend_level2_oplocks_begin_default function. Is that always there in your stacktraces?

If so, then a possible way around this deadlock would be the following:

Before you enter the brlock engine, i.e. before you somehow lock the brlock record, call file_has_read_lease() and save that result. Then, in brl_lock_windows_default(), only call the contend_level2 functions if file_has_read_lease() returned true.

I haven't fully followed the code to see if this is easy, but and it might open a race condition where we don't break a level2 oplock when we should, but this is one way out.

The "real" solution in my opinion would be to merge the brlock data into locking.tdb. Back when I was working on this, I had done some work towards this, but I never finished it.
Comment 6 Xavi Hernandez 2024-12-19 16:59:56 UTC 
(In reply to Volker Lendecke from comment #5)
> Wow, brilliant analysis.
> 
> In the second stacktrace of the original comment here, there's the
> contend_level2_oplocks_begin_default function. Is that always there in your
> stacktraces?

Yes. Apparently it's always there.


> If so, then a possible way around this deadlock would be the following:
> 
> Before you enter the brlock engine, i.e. before you somehow lock the brlock
> record, call file_has_read_lease() and save that result. Then, in
> brl_lock_windows_default(), only call the contend_level2 functions if
> file_has_read_lease() returned true.

If I understand it correctly, currently file_has_read_lease() is called by contend_level2_oplocks_begin_default(), and it requires to take a lock on locking.tdb. So the idea is to move that request before the call to brl_get_locks_for_locking().

The question is that file_has_read_lease() takes a lock on locking.tdb and reads the necessary information, but once it returns, the lock is already released, right ? so that value could already be stale, which means that there still exists a race window. Or I'm wrong ?

I don't know the code well enough to fully understand it, though. So it's very likely I'm missing important things.


> I haven't fully followed the code to see if this is easy, but and it might
> open a race condition where we don't break a level2 oplock when we should,
> but this is one way out.

What sequence of operations I would need to test to try this case ?


> The "real" solution in my opinion would be to merge the brlock data into
> locking.tdb. Back when I was working on this, I had done some work towards
> this, but I never finished it.

This doesn't seem a quick nor easy change.
Comment 7 Xavi Hernandez 2024-12-20 09:34:17 UTC 
I've done a small experiment by making share_mode_g_lock_dump() public and using it to wrap the calls to brl_get_locks_for_locking() and brl_lock(). This way, the locking.tdb is always acquired before the brlocks.tdb and prevents the deadlock.

It seems to work fine because brl_locks() is reusing the already acquired lock and there's no inversion in the order of lock acquisition. However I don't know if this could have unwanted side effects or a performance impact.

What do you think ?
Comment 8 Ralph Böhme 2024-12-20 10:48:53 UTC 
Completely untested:

--- a/source3/locking/locking.c
+++ b/source3/locking/locking.c
@@ -337,7 +337,7 @@ NTSTATUS do_lock(files_struct *fsp,
                  fsp_fnum_dbg(fsp),
                  fsp_str_dbg(fsp));
 
-       status = share_mode_do_locked_vfs_allowed(fsp->file_id,
+       status = share_mode_do_locked_vfs_denied(fsp->file_id,
                                                  do_lock_fn,
                                                  &state);
        if (!NT_STATUS_IS_OK(status)) {

Iirc share_mode_do_locked_vfs_allowed() only acquires the "g_lock" while calling the callback function, whereas share_mode_do_locked_vfs_denied() acquires the low level database chainlock. This should fix the locking problem, but I'm not sure the semantics change wrt to disallowing VFS calls is acceptable. Currently we only check smb_vfs_assert_allowed() in a few places and SMB_VFS_BRL_LOCK_WINDOWS() is not one of them.
Comment 9 Xavi Hernandez 2024-12-20 11:03:26 UTC 
(In reply to Ralph Böhme from comment #8)
> Completely untested:
> 
> --- a/source3/locking/locking.c
> +++ b/source3/locking/locking.c
> @@ -337,7 +337,7 @@ NTSTATUS do_lock(files_struct *fsp,
>                   fsp_fnum_dbg(fsp),
>                   fsp_str_dbg(fsp));
>  
> -       status = share_mode_do_locked_vfs_allowed(fsp->file_id,
> +       status = share_mode_do_locked_vfs_denied(fsp->file_id,
>                                                   do_lock_fn,
>                                                   &state);
>         if (!NT_STATUS_IS_OK(status)) {
> 
> Iirc share_mode_do_locked_vfs_allowed() only acquires the "g_lock" while
> calling the callback function, whereas share_mode_do_locked_vfs_denied()
> acquires the low level database chainlock. This should fix the locking
> problem, but I'm not sure the semantics change wrt to disallowing VFS calls
> is acceptable. Currently we only check smb_vfs_assert_allowed() in a few
> places and SMB_VFS_BRL_LOCK_WINDOWS() is not one of them.

I tried this, but it causes a panic when I start sending SMB LOCK requests:

[2024/12/20 10:57:25.260000,  0] ../../source3/smbd/vfs.c:2733(smb_vfs_call_brl_lock_windows)
  smb_vfs_call_brl_lock_windows: Called with VFS denied by ../../source3/locking/locking.c:342
[2024/12/20 10:57:25.260115,  0] ../../lib/util/fault.c:178(smb_panic_log)
  ===============================================================
[2024/12/20 10:57:25.260145,  0] ../../lib/util/fault.c:185(smb_panic_log)
  INTERNAL ERROR: Called with VFS denied! in smbd (smbd[10.88.0.1]) (client [10.88.0.1]) pid 7976 (4.22.0pre1-GIT-7b73c574d93)
[2024/12/20 10:57:25.260174,  0] ../../lib/util/fault.c:190(smb_panic_log)
  If you are running a recent Samba version, and if you think this problem is not yet fixed in the latest versions, please consider reporting this bug, see https://wiki.samba.org/index.php
/Bug_Reporting
[2024/12/20 10:57:25.260201,  0] ../../lib/util/fault.c:191(smb_panic_log)
  ===============================================================
[2024/12/20 10:57:25.260228,  0] ../../lib/util/fault.c:193(smb_panic_log)
  PANIC (pid 7976): Called with VFS denied! in 4.22.0pre1-GIT-7b73c574d93
[2024/12/20 10:57:25.261350,  0] ../../lib/util/fault.c:304(log_stack_trace)
  BACKTRACE: 39 stack frames:
   #0 /usr/lib64/samba/libgenrand-private-samba.so(log_stack_trace+0x1f) [0x7fe9e0893b43]
   #1 /usr/lib64/samba/libgenrand-private-samba.so(smb_panic_log+0x1e8) [0x7fe9e0893ad7]
   #2 /usr/lib64/samba/libgenrand-private-samba.so(smb_panic+0x18) [0x7fe9e0893af2]
   #3 /usr/lib64/samba/libsmbd-base-private-samba.so(smb_vfs_call_brl_lock_windows+0xaf) [0x7fe9e3504c69]
   #4 /usr/lib64/samba/libsmbd-base-private-samba.so(brl_lock+0xbf) [0x7fe9e348bf06]
   #5 /usr/lib64/samba/libsmbd-base-private-samba.so(+0x454e6) [0x7fe9e34874e6]
   #6 /usr/lib64/samba/libsmbd-base-private-samba.so(+0x58af5) [0x7fe9e349aaf5]
   #7 /usr/lib64/samba/libsmbd-base-private-samba.so(_share_mode_do_locked_vfs_denied+0x191) [0x7fe9e349ad78]
   #8 /usr/lib64/samba/libsmbd-base-private-samba.so(do_lock+0x21a) [0x7fe9e3487738]

smb_vfs_call_brl_lock_windows() calls VFS_FIND(), which checks the smb_vfs_deny_global variable.
Comment 10 Ralph Böhme 2024-12-20 11:07:25 UTC 
Ah, ok, crap. I had forgotten that we actually enforce this for the whole VFS via VFS_FIND().
Comment 11 Xavi Hernandez 2024-12-23 11:17:02 UTC 
A colleague has seen that using version 4.17 doesn't seem to cause any issue. I've run a git bisect, and I've found that the first commit that triggers the bug is this:

commit 680c7907325b433856ac1dd916ab63e671fbe4ab
Author: Stefan Metzmacher <metze@samba.org>
Date:   Mon Aug 29 16:48:04 2022 +0200

    s3:smbd: make use of share_mode_entry_prepare_{lock_add,unlock}() in open_{file_ntcreate,directory}()
    
    This gives a nice speed up...
    
    The following test with 256 commections all looping with open/close
    on the same inode (share root) is improved drastically:
    
      smbtorture //127.0.0.1/m -Uroot%test smb2.bench.path-contention-shared \
             --option='torture:bench_path=' \
             --option="torture:timelimit=60" \
             --option="torture:nprocs=256" \
             --option="torture:qdepth=1"
    
    From something like this:
    
        open[num/s=11536,avslat=0.011450,minlat=0.000039,maxlat=0.052707]
        close[num/s=11534,avslat=0.010878,minlat=0.000022,maxlat=0.052342]
    
    (only this commit with the close part reverted) to:
    
        open[num/s=12722,avslat=0.009548,minlat=0.000051,maxlat=0.054338]
        close[num/s=12720,avslat=0.010701,minlat=0.000033,maxlat=0.054372]
    
    (with both patches) to:
    
        open[num/s=37680,avslat=0.003471,minlat=0.000040,maxlat=0.061411]
        close[num/s=37678,avslat=0.003440,minlat=0.000022,maxlat=0.051536]
    
    So we are finally perform similar like we did in Samba 4.12,
    which resulted in:
    
        open[num/s=36846,avslat=0.003574,minlat=0.000043,maxlat=0.020378]
        close[num/s=36844,avslat=0.003552,minlat=0.000026,maxlat=0.020321]
    
    BUG: https://bugzilla.samba.org/show_bug.cgi?id=15125
    
    Signed-off-by: Stefan Metzmacher <metze@samba.org>
    Reviewed-by: Jeremy Allison <jra@samba.org>


However this belongs to a much bigger PR with 105 commits: https://gitlab.com/samba-team/samba/-/merge_requests/2670
Comment 12 Stefan Metzmacher 2024-12-23 12:19:06 UTC 
Created attachment 18521 [details]
Draft patch for a fix...
Comment 13 Xavi Hernandez 2024-12-23 13:57:05 UTC 
I've tried the patch, and I get a panic:

[2024/12/23 13:53:52.263778,  0] ../../source3/locking/share_mode_lock.c:3395(_share_mode_entry_prepare_lock)
  PANIC: assert failed at ../../source3/locking/share_mode_lock.c(3395): share_mode_lock_key_refcount == 0
[2024/12/23 13:53:52.263863,  0] ../../lib/util/fault.c:178(smb_panic_log)
  ===============================================================
[2024/12/23 13:53:52.263894,  0] ../../lib/util/fault.c:185(smb_panic_log)
  INTERNAL ERROR: assert failed: share_mode_lock_key_refcount == 0 in smbd (smbd[10.88.0.1]) (client [10.88.0.1]) pid 667920 (4.22.0pre1-GIT-7b73c574d93)
[2024/12/23 13:53:52.263926,  0] ../../lib/util/fault.c:190(smb_panic_log)
  If you are running a recent Samba version, and if you think this problem is not yet fixed in the latest versions, please consider reporting this bug, see https://wiki.samba.org/index.php/Bug_Reporting
[2024/12/23 13:53:52.263956,  0] ../../lib/util/fault.c:191(smb_panic_log)
  ===============================================================
[2024/12/23 13:53:52.263988,  0] ../../lib/util/fault.c:193(smb_panic_log)
  PANIC (pid 667920): assert failed: share_mode_lock_key_refcount == 0 in 4.22.0pre1-GIT-7b73c574d93
[2024/12/23 13:53:52.264232,  0] ../../lib/util/fault.c:304(log_stack_trace)
  BACKTRACE: 35 stack frames:
   #0 /usr/lib64/samba/libgenrand-private-samba.so(log_stack_trace+0x1f) [0x7f1a7748bb43]
   #1 /usr/lib64/samba/libgenrand-private-samba.so(smb_panic_log+0x1e8) [0x7f1a7748bad7]
   #2 /usr/lib64/samba/libgenrand-private-samba.so(smb_panic+0x18) [0x7f1a7748baf2]
   #3 /usr/lib64/samba/libsmbd-base-private-samba.so(_share_mode_entry_prepare_lock+0x131) [0x7f1a7a0cfac7]
   #4 /usr/lib64/samba/libsmbd-base-private-samba.so(do_lock+0x244) [0x7f1a7a0bbc8e]
   #5 /usr/lib64/samba/libsmbd-base-private-samba.so(smbd_do_locks_try+0x9a) [0x7f1a7a12c457]
   #6 /usr/lib64/samba/libsmbd-base-private-samba.so(+0x111088) [0x7f1a7a187088]
   #7 /usr/lib64/samba/libsmbd-base-private-samba.so(+0x110dab) [0x7f1a7a186dab]
   #8 /usr/lib64/samba/libsmbd-base-private-samba.so(smbd_smb2_request_process_lock+0x81c) [0x7f1a7a1860af]
   #9 /usr/lib64/samba/libsmbd-base-private-samba.so(smbd_smb2_request_dispatch+0x231d) [0x7f1a7a169034]
   #10 /usr/lib64/samba/libsmbd-base-private-samba.so(+0xf890d) [0x7f1a7a16e90d]
   #11 /usr/lib64/samba/libsmbd-base-private-samba.so(+0xf8cd5) [0x7f1a7a16ecd5]
   #12 /usr/lib64/samba/libsmbd-base-private-samba.so(+0xf8d8a) [0x7f1a7a16ed8a]
   #13 /usr/lib64/samba/libtevent-private-samba.so(tevent_common_invoke_fd_handler+0x11d) [0x7f1a78c9dc0e]
   #14 /usr/lib64/samba/libtevent-private-samba.so(+0x13d34) [0x7f1a78ca9d34]
   #15 /usr/lib64/samba/libtevent-private-samba.so(+0x1440c) [0x7f1a78caa40c]
   #16 /usr/lib64/samba/libtevent-private-samba.so(+0xfbe6) [0x7f1a78ca5be6]
   #17 /usr/lib64/samba/libtevent-private-samba.so(_tevent_loop_once+0x10f) [0x7f1a78c9c63a]
   #18 /usr/lib64/samba/libtevent-private-samba.so(tevent_common_loop_wait+0x25) [0x7f1a78c9c970]
   #19 /usr/lib64/samba/libtevent-private-samba.so(+0xfc88) [0x7f1a78ca5c88]
   #20 /usr/lib64/samba/libtevent-private-samba.so(_tevent_loop_wait+0x2b) [0x7f1a78c9ca13]
   #21 /usr/lib64/samba/libsmbd-base-private-samba.so(smbd_process+0xdd1) [0x7f1a7a14d5e7]
   #22 smbd: client [10.88.0.1](+0x9069) [0x55c3ff809069]
   #23 /usr/lib64/samba/libtevent-private-samba.so(tevent_common_invoke_fd_handler+0x11d) [0x7f1a78c9dc0e]
   #24 /usr/lib64/samba/libtevent-private-samba.so(+0x13d34) [0x7f1a78ca9d34]
   #25 /usr/lib64/samba/libtevent-private-samba.so(+0x1440c) [0x7f1a78caa40c]
   #26 /usr/lib64/samba/libtevent-private-samba.so(+0xfbe6) [0x7f1a78ca5be6]
   #27 /usr/lib64/samba/libtevent-private-samba.so(_tevent_loop_once+0x10f) [0x7f1a78c9c63a]
   #28 /usr/lib64/samba/libtevent-private-samba.so(tevent_common_loop_wait+0x25) [0x7f1a78c9c970]
   #29 /usr/lib64/samba/libtevent-private-samba.so(+0xfc88) [0x7f1a78ca5c88]
   #30 /usr/lib64/samba/libtevent-private-samba.so(_tevent_loop_wait+0x2b) [0x7f1a78c9ca13]
   #31 smbd: client [10.88.0.1](+0x9d05) [0x55c3ff809d05]
   #32 smbd: client [10.88.0.1](main+0x171f) [0x55c3ff80c96c]
   #33 /lib64/libc.so.6(__libc_start_main+0xe5) [0x7f1a768787e5]
   #34 smbd: client [10.88.0.1](_start+0x2e) [0x55c3ff805cae]
[2024/12/23 13:53:52.264814,  0] ../../source3/lib/dumpcore.c:319(dump_core)
  coredump is handled by helper binary specified at /proc/sys/kernel/core_pattern
Comment 14 Ralph Böhme 2025-01-07 16:54:17 UTC 
Fyi: we're working on a fix.