Bug 15657 - lock order reversal between smb2 create and lock operations
Summary: lock order reversal between smb2 create and lock operations
Status: NEW
Alias: None
Product: Samba 4.1 and newer
Classification: Unclassified
Component: File services (show other bugs)
Version: 4.18.10
Hardware: x64 Solaris
: P5 major (vote)
Target Milestone: ---
Assignee: Samba QA Contact
QA Contact: Samba QA Contact
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2024-06-05 04:03 UTC by Jonathan Matthew
Modified: 2024-06-05 07:07 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 Jonathan Matthew 2024-06-05 04:03:54 UTC
Recently we encountered a deadlock between two smbd processes, which appears to be caused by a lock order reversal between smb2 lock and create operations.  Stack traces from the processes that caused it are below.  This was on illumos (OmniOS r151048), where tdb uses mutexes.  Once we worked out that it was deadlocked on some mutexes, we inspected the mutex state to confirm that we had two smbd processes where each one was waiting on a mutex owned by the other.  Since one of the mutexes was a lock on the g_lock db, many other smbd processes ended up waiting, affecting a decent percentage of our users.

After looking at it for a while, we had to kill one of the processes to get everything unstuck, which does seem to have worked.  We're considering disabling tdb mutexes, as it seems like the deadlock detection you get with fcntl file locking would avoid this happening again.

The brlock db has lock order 2 and the g_lock db has lock order 3, so as I understand it, there shouldn't be any code paths that access the brlock db while holding a lock from g_lock.  This part of one of the stack traces shows where I think the problem is:

 fffff7ffe4146f09 dbwrap_parse_record () + 5c
 fffff7ffdffc8e48 brl_get_locks_readonly () + 121                       <--- takes brlock mutex
 fffff7ffdfec1e43 file_has_brlocks () + 18
 fffff7ffdfec3326 delay_for_oplock () + 49a
 fffff7ffdfec3879 handle_share_mode_lease () + 17e
 fffff7ffdfec5083 check_and_store_share_mode () + da
 fffff7ffdfec5a11 open_ntcreate_lock_add_entry () + 85
 fffff7ffdffd6cb8 share_mode_entry_prepare_lock_fn () + 225
 fffff7ffe40c2596 g_lock_lock_cb_run_and_store () + 1b7
 fffff7ffe40c47ff g_lock_lock_simple_fn () + 3f5
 fffff7ffe40bdc90 dbwrap_watched_do_locked_fn () + 92
 fffff7ffe414b2eb db_tdb_do_locked () + 313
 fffff7ffe4147425 dbwrap_do_locked () + 88
 fffff7ffe40bdda1 dbwrap_watched_do_locked () + fe
 fffff7ffe4147425 dbwrap_do_locked () + 88
 fffff7ffe40c4ab6 g_lock_lock () + 1bf                                  <--- takes g_lock mutex
 fffff7ffdffd7009 _share_mode_entry_prepare_lock () + 226
 fffff7ffdfec7123 open_file_ntcreate () + 1515

dbwrap doesn't do lock order checking in dbwrap_parse_record(), so it doesn't identify this as a problem.

As far as I can tell, this is the only time we've seen this, and we're not able to reproduce it.  It appears to have happened because two unrelated users did different operations on unrelated files at the same time.

This is what the first involved process was doing, which I understand to be the correct order to acquire these locks in:

9607:   /opt/local/sbin/smbd -D
 fffff7ffee9b9b0a lwp_mutex_timedlock (fffff7ffed7071a8, 0, fffff7ffee2f2ac0)
 fffff7ffee9a9fb6 mutex_lock_internal (fffff7ffed7071a8, 0, 1) + 1b6
 fffff7ffee9aa695 mutex_lock_impl (fffff7ffed7071a8, 0) + 125
 fffff7ffee9aa7f3 mutex_lock (fffff7ffed7071a8) + 13
 fffff7ffe4cb8627 chain_mutex_lock () + 23
 fffff7ffe4cb8764 tdb_mutex_lock () + a1
 fffff7ffe4cac56e fcntl_lock () + 52
 fffff7ffe4cac741 tdb_brlock () + 9e
 fffff7ffe4cacd43 tdb_nest_lock () + 1bc 
 fffff7ffe4cacf92 tdb_lock_list () + 79
 fffff7ffe4cad02f tdb_lock () + 2a 
 fffff7ffe4ca9381 tdb_find_lock_hash () + 50
 fffff7ffe4ca980d tdb_parse_record () + 70
 fffff7ffe414b54b db_tdb_parse () + 95
 fffff7ffe4146f09 dbwrap_parse_record () + 5c
 fffff7ffe40beedf dbwrap_watched_parse_record () + a6 
 fffff7ffe4146f09 dbwrap_parse_record () + 5c
 fffff7ffe40c60ef g_lock_dump () + 11e                                                  <--- takes g_lock mutex
 fffff7ffdffccfa8 share_mode_g_lock_dump () + 7c 
 fffff7ffdffd0680 fsp_update_share_mode_flags () + a4
 fffff7ffdffd0810 file_has_read_lease () + 18
 fffff7ffdff5f6a5 contend_level2_oplocks_begin_default () + b2
 fffff7ffdff5faf4 smbd_contend_level2_oplocks_begin () + 20
 fffff7ffe2b613a0 contend_level2_oplocks_begin () + 30
 fffff7ffdffc5c19 brl_lock_windows_default () + 1e8 
 fffff7ffdfe7e015 vfswrap_brl_lock_windows () + b7
 fffff7ffdfedfd2f smb_vfs_call_brl_lock_windows () + 103
 fffff7ffdffc699d brl_lock () + 159
 fffff7ffdffc185d do_lock_fn () + 12a                                                   <--- takes brlock mutex
 fffff7ffdffd69be _share_mode_do_locked_vfs_allowed () + 14b
 fffff7ffdffc1b25 do_lock () + 277
 fffff7ffdfed29c7 smbd_do_locks_try () + 9a
 fffff7ffdff2b2ec smbd_smb2_lock_try () + 11c
 fffff7ffdff2afca smbd_smb2_lock_send () + ab2
 fffff7ffdff2a2b5 smbd_smb2_request_process_lock () + 81c
 fffff7ffdff0f726 smbd_smb2_request_dispatch () + 1706 
 fffff7ffdff146e2 smbd_smb2_io_handler () + 864
 fffff7ffdff14819 smbd_smb2_connection_handler () + 4d
 fffff7ffe4cfbcbc tevent_common_invoke_fd_handler () + 121
 fffff7ffe4d01079 poll_event_loop_poll () + 68b
 fffff7ffe4d0132a poll_event_loop_once () + bf
 fffff7ffe4cfa7f7 _tevent_loop_once () + 116
 fffff7ffe4cfab45 tevent_common_loop_wait () + 25
 fffff7ffe4cfabed _tevent_loop_wait () + 2b
 fffff7ffdfef554f smbd_process () + d88
 000000000040b017 smbd_accept_connection () + 440
 fffff7ffe4cfbcbc tevent_common_invoke_fd_handler () + 121
 fffff7ffe4d01079 poll_event_loop_poll () + 68b
 fffff7ffe4d0132a poll_event_loop_once () + bf
 fffff7ffe4cfa7f7 _tevent_loop_once () + 116
 fffff7ffe4cfab45 tevent_common_loop_wait () + 25
 fffff7ffe4cfabed _tevent_loop_wait () + 2b
 000000000040bdd1 smbd_parent_loop () + b4
 000000000040e100 main () + 19b5
 0000000000407d47 _start_crt () + 87
 0000000000407ca8 _start () + 18

This is the full stack trace from the process taking the locks in the opposite order:

25201:  /opt/local/sbin/smbd -D
 fffff7ffee9b9b0a lwp_mutex_timedlock (fffff7ffed75c1a8, 0, fffff7ffee2f2ac0)
 fffff7ffee9a9fb6 mutex_lock_internal (fffff7ffed75c1a8, 0, 1) + 1b6
 fffff7ffee9aa695 mutex_lock_impl (fffff7ffed75c1a8, 0) + 125
 fffff7ffee9aa7f3 mutex_lock (fffff7ffed75c1a8) + 13
 fffff7ffe4cb8627 chain_mutex_lock () + 23
 fffff7ffe4cb8764 tdb_mutex_lock () + a1
 fffff7ffe4cac56e fcntl_lock () + 52
 fffff7ffe4cac741 tdb_brlock () + 9e
 fffff7ffe4cacd43 tdb_nest_lock () + 1bc
 fffff7ffe4cacf92 tdb_lock_list () + 79
 fffff7ffe4cad02f tdb_lock () + 2a
 fffff7ffe4ca9381 tdb_find_lock_hash () + 50
 fffff7ffe4ca980d tdb_parse_record () + 70
 fffff7ffe414b54b db_tdb_parse () + 95
 fffff7ffe4146f09 dbwrap_parse_record () + 5c
 fffff7ffdffc8e48 brl_get_locks_readonly () + 121                       <--- takes brlock mutex
 fffff7ffdfec1e43 file_has_brlocks () + 18
 fffff7ffdfec3326 delay_for_oplock () + 49a
 fffff7ffdfec3879 handle_share_mode_lease () + 17e
 fffff7ffdfec5083 check_and_store_share_mode () + da
 fffff7ffdfec5a11 open_ntcreate_lock_add_entry () + 85
 fffff7ffdffd6cb8 share_mode_entry_prepare_lock_fn () + 225
 fffff7ffe40c2596 g_lock_lock_cb_run_and_store () + 1b7
 fffff7ffe40c47ff g_lock_lock_simple_fn () + 3f5
 fffff7ffe40bdc90 dbwrap_watched_do_locked_fn () + 92
 fffff7ffe414b2eb db_tdb_do_locked () + 313
 fffff7ffe4147425 dbwrap_do_locked () + 88
 fffff7ffe40bdda1 dbwrap_watched_do_locked () + fe
 fffff7ffe4147425 dbwrap_do_locked () + 88
 fffff7ffe40c4ab6 g_lock_lock () + 1bf                                  <--- takes g_lock mutex
 fffff7ffdffd7009 _share_mode_entry_prepare_lock () + 226
 fffff7ffdfec7123 open_file_ntcreate () + 1515
 fffff7ffdfecc376 create_file_unixpath () + eae
 fffff7ffdfeccff6 create_file_default () + 4fc
 fffff7ffdfe774e7 vfswrap_create_file () + 74
 fffff7ffdfed9e82 smb_vfs_call_create_file () + 148
 fffff7ffdff210a3 smbd_smb2_create_send () + 14fa
 fffff7ffdff1e731 smbd_smb2_request_process_create () + 7a1
 fffff7ffdff0f6a4 smbd_smb2_request_dispatch () + 1684
 fffff7ffdff146e2 smbd_smb2_io_handler () + 864
 fffff7ffdff14819 smbd_smb2_connection_handler () + 4d
 fffff7ffe4cfbcbc tevent_common_invoke_fd_handler () + 121
 fffff7ffe4d01079 poll_event_loop_poll () + 68b
 fffff7ffe4d0132a poll_event_loop_once () + bf
 fffff7ffe4cfa7f7 _tevent_loop_once () + 116
 fffff7ffe4cfab45 tevent_common_loop_wait () + 25
 fffff7ffe4cfabed _tevent_loop_wait () + 2b
 fffff7ffdfef554f smbd_process () + d88
 000000000040b017 smbd_accept_connection () + 440
 fffff7ffe4cfbcbc tevent_common_invoke_fd_handler () + 121
 fffff7ffe4d01079 poll_event_loop_poll () + 68b
 fffff7ffe4d0132a poll_event_loop_once () + bf
 fffff7ffe4cfa7f7 _tevent_loop_once () + 116
 fffff7ffe4cfab45 tevent_common_loop_wait () + 25
 fffff7ffe4cfabed _tevent_loop_wait () + 2b
 000000000040bdd1 smbd_parent_loop () + b4
 000000000040e100 main () + 19b5
 0000000000407d47 _start_crt () + 87
 0000000000407ca8 _start () + 18


and in case it helps, here's one of the other processes that was stuck:

8220:   /opt/local/sbin/smbd -D
 fffff7ffee9b9b0a lwp_mutex_timedlock (fffff7ffed7071a8, 0, fffff7ffee2f2ac0)
 fffff7ffee9a9fb6 mutex_lock_internal (fffff7ffed7071a8, 0, 1) + 1b6
 fffff7ffee9aa695 mutex_lock_impl (fffff7ffed7071a8, 0) + 125
 fffff7ffee9aa7f3 mutex_lock (fffff7ffed7071a8) + 13
 fffff7ffe4cb8627 chain_mutex_lock () + 23
 fffff7ffe4cb8764 tdb_mutex_lock () + a1
 fffff7ffe4cac56e fcntl_lock () + 52
 fffff7ffe4cac741 tdb_brlock () + 9e
 fffff7ffe4cacd43 tdb_nest_lock () + 1bc
 fffff7ffe4cacf92 tdb_lock_list () + 79
 fffff7ffe4cad02f tdb_lock () + 2a
 fffff7ffe4cada43 tdb_chainlock () + 5b
 fffff7ffe414b07a db_tdb_do_locked () + a2
 fffff7ffe4147425 dbwrap_do_locked () + 88
 fffff7ffe40bdda1 dbwrap_watched_do_locked () + fe
 fffff7ffe4147425 dbwrap_do_locked () + 88
 fffff7ffe40c4ab6 g_lock_lock () + 1bf
 fffff7ffdffd7009 _share_mode_entry_prepare_lock () + 226
 fffff7ffdfec8f7a open_directory () + ef5
 fffff7ffdfecc427 create_file_unixpath () + f5f
 fffff7ffdfeccff6 create_file_default () + 4fc
 fffff7ffdfe774e7 vfswrap_create_file () + 74
 fffff7ffdfed9e82 smb_vfs_call_create_file () + 148
 fffff7ffdff210a3 smbd_smb2_create_send () + 14fa
 fffff7ffdff1e731 smbd_smb2_request_process_create () + 7a1
 fffff7ffdff0f6a4 smbd_smb2_request_dispatch () + 1684
 fffff7ffdff146e2 smbd_smb2_io_handler () + 864
 fffff7ffdff14819 smbd_smb2_connection_handler () + 4d
 fffff7ffe4cfbcbc tevent_common_invoke_fd_handler () + 121
 fffff7ffe4d01079 poll_event_loop_poll () + 68b
 fffff7ffe4d0132a poll_event_loop_once () + bf
 fffff7ffe4cfa7f7 _tevent_loop_once () + 116
 fffff7ffe4cfab45 tevent_common_loop_wait () + 25
 fffff7ffe4cfabed _tevent_loop_wait () + 2b
 fffff7ffdfef554f smbd_process () + d88
 000000000040b017 smbd_accept_connection () + 440
 fffff7ffe4cfbcbc tevent_common_invoke_fd_handler () + 121
 fffff7ffe4d01079 poll_event_loop_poll () + 68b
 fffff7ffe4d0132a poll_event_loop_once () + bf
 fffff7ffe4cfa7f7 _tevent_loop_once () + 116
 fffff7ffe4cfab45 tevent_common_loop_wait () + 25
 fffff7ffe4cfabed _tevent_loop_wait () + 2b
 000000000040bdd1 smbd_parent_loop () + b4
 000000000040e100 main () + 19b5
 0000000000407d47 _start_crt () + 87
 0000000000407ca8 _start () + 18