strongswan/src/libcharon/plugins/vici/vici_logger.c

184 lines
4.1 KiB
C
Raw Normal View History

/*
* Copyright (C) 2014 Martin Willi
* Copyright (C) 2014 revosec AG
*
* This program is free software; you can redistribute it and/or modify it
* under the terms of the GNU General Public License as published by the
* Free Software Foundation; either version 2 of the License, or (at your
* option) any later version. See <http://www.fsf.org/copyleft/gpl.txt>.
*
* This program is distributed in the hope that it will be useful, but
* WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY
* or FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
* for more details.
*/
#include "vici_logger.h"
#include "vici_builder.h"
#include <daemon.h>
#include <threading/mutex.h>
vici: Asynchronize debug logging 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.
2015-07-02 07:10:21 +00:00
#include <processing/jobs/callback_job.h>
typedef struct private_vici_logger_t private_vici_logger_t;
/**
* Private data of an vici_logger_t object.
*/
struct private_vici_logger_t {
/**
* Public vici_logger_t interface.
*/
vici_logger_t public;
/**
* Dispatcher
*/
vici_dispatcher_t *dispatcher;
/**
* Recursiveness avoidance counter
*/
int recursive;
vici: Asynchronize debug logging 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.
2015-07-02 07:10:21 +00:00
/**
* List of messages to raise async events
*/
linked_list_t *queue;
/**
* Mutex to synchronize logging
*/
mutex_t *mutex;
};
vici: Asynchronize debug logging 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.
2015-07-02 07:10:21 +00:00
/**
* Async callback to raise events for queued messages
*/
static job_requeue_t raise_events(private_vici_logger_t *this)
{
vici_message_t *message;
u_int count;
this->mutex->lock(this->mutex);
count = this->queue->get_count(this->queue);
this->queue->remove_first(this->queue, (void**)&message);
this->mutex->unlock(this->mutex);
if (count > 0)
{
this->dispatcher->raise_event(this->dispatcher, "log", 0, message);
}
if (count > 1)
{
return JOB_REQUEUE_DIRECT;
}
return JOB_REQUEUE_NONE;
}
/**
* Queue a message for async processing
*/
Spelling fixes * accumulating * acquire * alignment * appropriate * argument * assign * attribute * authenticate * authentication * authenticator * authority * auxiliary * brackets * callback * camellia * can't * cancelability * certificate * choinyambuu * chunk * collector * collision * communicating * compares * compatibility * compressed * confidentiality * configuration * connection * consistency * constraint * construction * constructor * database * decapsulated * declaration * decrypt * derivative * destination * destroyed * details * devised * dynamic * ecapsulation * encoded * encoding * encrypted * enforcing * enumerator * establishment * excluded * exclusively * exited * expecting * expire * extension * filter * firewall * foundation * fulfillment * gateways * hashing * hashtable * heartbeats * identifier * identifiers * identities * identity * implementers * indicating * initialize * initiate * initiation * initiator * inner * instantiate * legitimate * libraries * libstrongswan * logger * malloc * manager * manually * measurement * mechanism * message * network * nonexistent * object * occurrence * optional * outgoing * packages * packets * padding * particular * passphrase * payload * periodically * policies * possible * previously * priority * proposal * protocol * provide * provider * pseudo * pseudonym * public * qualifier * quantum * quintuplets * reached * reading * recommendation to * recommendation * recursive * reestablish * referencing * registered * rekeying * reliable * replacing * representing * represents * request * request * resolver * result * resulting * resynchronization * retriable * revocation * right * rollback * rule * rules * runtime * scenario * scheduled * security * segment * service * setting * signature * specific * specified * speed * started * steffen * strongswan * subjectaltname * supported * threadsafe * traffic * tremendously * treshold * unique * uniqueness * unknown * until * upper * using * validator * verification * version * version * warrior Closes strongswan/strongswan#164.
2020-02-05 04:30:52 +00:00
static void queue_message(private_vici_logger_t *this, vici_message_t *message)
vici: Asynchronize debug logging 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.
2015-07-02 07:10:21 +00:00
{
this->queue->insert_last(this->queue, message);
if (this->queue->get_count(this->queue) == 1)
{
lib->processor->queue_job(lib->processor, (job_t*)
callback_job_create((callback_job_cb_t)raise_events,
this, NULL, NULL));
}
}
METHOD(logger_t, log_, void,
private_vici_logger_t *this, debug_t group, level_t level, int thread,
ike_sa_t* ike_sa, const char *msg)
{
if (!this->dispatcher->has_event_listeners(this->dispatcher, "log"))
{
return;
}
this->mutex->lock(this->mutex);
/* avoid recursive invocations by the vici subsystem */
if (this->recursive++ == 0)
{
vici_message_t *message;
vici_builder_t *builder;
builder = vici_builder_create();
builder->add_kv(builder, "group", "%N", debug_names, group);
builder->add_kv(builder, "level", "%d", level);
builder->add_kv(builder, "thread", "%d", thread);
if (ike_sa)
{
builder->add_kv(builder, "ikesa-name", "%s",
ike_sa->get_name(ike_sa));
builder->add_kv(builder, "ikesa-uniqueid", "%u",
ike_sa->get_unique_id(ike_sa));
}
builder->add_kv(builder, "msg", "%s", msg);
message = builder->finalize(builder);
if (message)
{
Spelling fixes * accumulating * acquire * alignment * appropriate * argument * assign * attribute * authenticate * authentication * authenticator * authority * auxiliary * brackets * callback * camellia * can't * cancelability * certificate * choinyambuu * chunk * collector * collision * communicating * compares * compatibility * compressed * confidentiality * configuration * connection * consistency * constraint * construction * constructor * database * decapsulated * declaration * decrypt * derivative * destination * destroyed * details * devised * dynamic * ecapsulation * encoded * encoding * encrypted * enforcing * enumerator * establishment * excluded * exclusively * exited * expecting * expire * extension * filter * firewall * foundation * fulfillment * gateways * hashing * hashtable * heartbeats * identifier * identifiers * identities * identity * implementers * indicating * initialize * initiate * initiation * initiator * inner * instantiate * legitimate * libraries * libstrongswan * logger * malloc * manager * manually * measurement * mechanism * message * network * nonexistent * object * occurrence * optional * outgoing * packages * packets * padding * particular * passphrase * payload * periodically * policies * possible * previously * priority * proposal * protocol * provide * provider * pseudo * pseudonym * public * qualifier * quantum * quintuplets * reached * reading * recommendation to * recommendation * recursive * reestablish * referencing * registered * rekeying * reliable * replacing * representing * represents * request * request * resolver * result * resulting * resynchronization * retriable * revocation * right * rollback * rule * rules * runtime * scenario * scheduled * security * segment * service * setting * signature * specific * specified * speed * started * steffen * strongswan * subjectaltname * supported * threadsafe * traffic * tremendously * treshold * unique * uniqueness * unknown * until * upper * using * validator * verification * version * version * warrior Closes strongswan/strongswan#164.
2020-02-05 04:30:52 +00:00
queue_message(this, message);
}
}
this->recursive--;
this->mutex->unlock(this->mutex);
}
METHOD(logger_t, get_level, level_t,
private_vici_logger_t *this, debug_t group)
{
/* anything higher might produce a loop as sending messages or listening
* for clients might cause log messages itself */
return LEVEL_CTRL;
}
/**
* (Un-)register dispatcher functions/events
*/
static void manage_commands(private_vici_logger_t *this, bool reg)
{
this->dispatcher->manage_event(this->dispatcher, "log", reg);
}
METHOD(vici_logger_t, destroy, void,
private_vici_logger_t *this)
{
manage_commands(this, FALSE);
vici: Asynchronize debug logging 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.
2015-07-02 07:10:21 +00:00
this->queue->destroy_offset(this->queue, offsetof(vici_message_t, destroy));
this->mutex->destroy(this->mutex);
free(this);
}
/**
* See header
*/
vici_logger_t *vici_logger_create(vici_dispatcher_t *dispatcher)
{
private_vici_logger_t *this;
INIT(this,
.public = {
.logger = {
.log = _log_,
.get_level = _get_level,
},
.destroy = _destroy,
},
.dispatcher = dispatcher,
vici: Asynchronize debug logging 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.
2015-07-02 07:10:21 +00:00
.queue = linked_list_create(),
.mutex = mutex_create(MUTEX_TYPE_RECURSIVE),
);
manage_commands(this, TRUE);
return &this->public;
}