The vici logger uses the listener_t.log() callback to raise vici events.
When doing so, it holds the bus lock as reader while acquiring the vici socket
mutex (1). If at the same time the vici socket enables a writer, that thread
tries to lock the watcher mutex (2). The watcher thread uses debugging while
holding the lock, i.e. acquires the bus read lock (3).
(1) bus.rlock -> vici.lock!
(2) vici.lock -> watcher.lock!
(3) watcher.lock -> bus.rlock!
This all actually would resolve just fine, as we have a shared read lock on the
bus. However, under Windows we seem to have a strict writer preference when
acquiring the rwlock (4). This results in blocking read locks until any pending
write lock can be fulfilled, and makes the constellation deadlock. The relevant
threads are:
Thread (1)
6 0x71313d25 in wait_ at threading/windows/mutex.c:137
7 0x7054c8a2 in find_entry at vici_socket.c:201
8 0x7054d690 in send_ at vici_socket.c:624
9 0x7054f6c1 in send_op at vici_dispatcher.c:119
10 0x705502c1 in raise_event at vici_dispatcher.c:469
12 0x704c3878 in log_cb at bus/bus.c:332
13 0x712c7c3a in invoke_function at collections/linked_list.c:414
14 0x704c3a63 in vlog at bus/bus.c:400
15 0x704c3b36 in log_ at bus/bus.c:430
18 0x70508f1f in process_response at sa/ikev2/task_manager_v2.c:664
20 0x704f5430 in process_message at sa/ike_sa.c:1369
21 0x704e3823 in execute at processing/jobs/process_message_job.c:74
22 0x712e629f in process_job at processing/processor.c:235
Thread (2)
4 0x71313b61 in lock at threading/windows/mutex.c:66
5 0x712e81fd in add at processing/watcher.c:441
6 0x712e1ab9 in add_watcher at networking/streams/stream.c:213
7 0x712e1b4d in on_write at networking/streams/stream.c:237
8 0x7054d606 in _cb_enable_writer at vici_socket.c:609
9 0x712e5e34 in execute at processing/jobs/callback_job.c:77
10 0x712e629f in process_job at processing/processor.c:235
Thread (3)
3 0x71313f38 in read_lock at threading/windows/rwlock.c:74
4 0x704c3971 in vlog at bus/bus.c:373
5 0x704cc156 in dbg_bus at daemon.c:126
6 0x712e7bf9 in watch at processing/watcher.c:316
7 0x712e5e34 in execute at processing/jobs/callback_job.c:77
8 0x712e629f in process_job at processing/processor.c:235
Thread (4)
3 0x71313f70 in write_lock at threading/windows/rwlock.c:82
4 0x704c378b in remove_logger at bus/bus.c:290
5 0x704cb284 in listener_unregister at control/controller.c:166
6 0x713136cd in thread_cleanup_pop at threading/windows/thread.c:558
8 0x704cb94e in initiate at control/controller.c:435
9 0x70553996 in _cb_initiate at vici_control.c:187
12 0x7054d200 in _cb_process_queue at vici_socket.c:508
13 0x712e5e34 in execute at processing/jobs/callback_job.c:77
14 0x712e629f in process_job at processing/processor.c:235
To avoid such a situation, we dissolve the (1) lock sequence. It's actually
never good practice to acquire shared locks during bus hooks, as it is
problematic if we raise bus events while holding the lock. We do so by
raising vici events for log message asynchronously, but of curse must keep
log order as is using a synchronized queue.
Josh Soref