1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
|
From 856ea64129cdc7ee56969524d7abaaae08c22c6a Mon Sep 17 00:00:00 2001
From: Martin Willi <martin@revosec.ch>
Date: Thu, 2 Jul 2015 09:10:21 +0200
Subject: [PATCH] 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.
---
src/libcharon/plugins/vici/vici_logger.c | 48 +++++++++++++++++++++++++++++++-
1 file changed, 47 insertions(+), 1 deletion(-)
diff --git a/src/libcharon/plugins/vici/vici_logger.c b/src/libcharon/plugins/vici/vici_logger.c
index cffd65b..6d3584e 100644
--- a/src/libcharon/plugins/vici/vici_logger.c
+++ b/src/libcharon/plugins/vici/vici_logger.c
@@ -18,6 +18,7 @@
#include <daemon.h>
#include <threading/mutex.h>
+#include <processing/jobs/callback_job.h>
typedef struct private_vici_logger_t private_vici_logger_t;
@@ -42,11 +43,54 @@ struct private_vici_logger_t {
int recursive;
/**
+ * List of messages to raise async events
+ */
+ linked_list_t *queue;
+
+ /**
* Mutex to synchronize logging
*/
mutex_t *mutex;
};
+/**
+ * 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
+ */
+static void queue_messsage(private_vici_logger_t *this, vici_message_t *message)
+{
+ 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)
@@ -75,7 +119,7 @@ METHOD(logger_t, log_, void,
message = builder->finalize(builder);
if (message)
{
- this->dispatcher->raise_event(this->dispatcher, "log", 0, message);
+ queue_messsage(this, message);
}
}
this->recursive--;
@@ -101,6 +145,7 @@ METHOD(vici_logger_t, destroy, void,
private_vici_logger_t *this)
{
manage_commands(this, FALSE);
+ this->queue->destroy_offset(this->queue, offsetof(vici_message_t, destroy));
this->mutex->destroy(this->mutex);
free(this);
}
@@ -121,6 +166,7 @@ vici_logger_t *vici_logger_create(vici_dispatcher_t *dispatcher)
.destroy = _destroy,
},
.dispatcher = dispatcher,
+ .queue = linked_list_create(),
.mutex = mutex_create(MUTEX_TYPE_RECURSIVE),
);
--
2.4.6
|
