summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorMark Salyzyn2015-11-06 14:26:52 -0600
committerMark Salyzyn2015-11-19 15:14:16 -0600
commit2d2e0a5c5eb0b0ea2fe1349da50e22228965faf9 (patch)
treeef9d05a98bc0eb3fe698089c0701e1db503ced29
parent9f903687011c195154b0c69c02e6aaa35c867242 (diff)
downloadplatform-system-core-2d2e0a5c5eb0b0ea2fe1349da50e22228965faf9.tar.gz
platform-system-core-2d2e0a5c5eb0b0ea2fe1349da50e22228965faf9.tar.xz
platform-system-core-2d2e0a5c5eb0b0ea2fe1349da50e22228965faf9.zip
liblog: resolve deadlocks
Although ever present, an increased regression introduced with commit b6bee33182cedea49199eb2252b3f3b442899c6d (liblog: logd: support logd.timestamp = monotonic). A signal handler can interrupt in locked context, if log is written in the signal handler, we are in deadlock. To reduce the contention and chances for this problem separate out timestamp lock from is loggable lock to reduce contention situations. Provide a best-guess response if lock would fail in timestamp path. Use a common lock() inline within each module, with a comment speaking to the issues surrounding calling a function that has a mutex within a signal handler. ToDo: Hold off signals temporarily in mainline, restart when unblock. Can not use pthread_sigmask(SIG_BLOCK,,) as it breaks AtCmd. Signed-off-by: Mark Salyzyn <salyzyn@google.com> Bug: 25563384 Change-Id: I47e2c87c988c3e359eb9eef129c6a3a08e9eedef
-rw-r--r--include/log/log.h6
-rw-r--r--liblog/fake_log_device.c7
-rw-r--r--liblog/log_is_loggable.c67
-rw-r--r--liblog/logd_write.c47
4 files changed, 86 insertions, 41 deletions
diff --git a/include/log/log.h b/include/log/log.h
index 1cdf7bc49..086d7427b 100644
--- a/include/log/log.h
+++ b/include/log/log.h
@@ -614,9 +614,11 @@ typedef enum log_id {
614 614
615/* 615/*
616 * Use the per-tag properties "log.tag.<tagname>" to generate a runtime 616 * Use the per-tag properties "log.tag.<tagname>" to generate a runtime
617 * result of non-zero to expose a log. 617 * result of non-zero to expose a log. prio is ANDROID_LOG_VERBOSE to
618 * ANDROID_LOG_FATAL. default_prio if no property. Undefined behavior if
619 * any other value.
618 */ 620 */
619int __android_log_is_loggable(int prio, const char *tag, int def); 621int __android_log_is_loggable(int prio, const char *tag, int default_prio);
620 622
621int __android_log_error_write(int tag, const char *subTag, int32_t uid, const char *data, 623int __android_log_error_write(int tag, const char *subTag, int32_t uid, const char *data,
622 uint32_t dataLen); 624 uint32_t dataLen);
diff --git a/liblog/fake_log_device.c b/liblog/fake_log_device.c
index 8a8ece250..cb80ee63c 100644
--- a/liblog/fake_log_device.c
+++ b/liblog/fake_log_device.c
@@ -99,6 +99,10 @@ static pthread_mutex_t fakeLogDeviceLock = PTHREAD_MUTEX_INITIALIZER;
99 99
100static void lock() 100static void lock()
101{ 101{
102 /*
103 * If we trigger a signal handler in the middle of locked activity and the
104 * signal handler logs a message, we could get into a deadlock state.
105 */
102 pthread_mutex_lock(&fakeLogDeviceLock); 106 pthread_mutex_lock(&fakeLogDeviceLock);
103} 107}
104 108
@@ -106,9 +110,12 @@ static void unlock()
106{ 110{
107 pthread_mutex_unlock(&fakeLogDeviceLock); 111 pthread_mutex_unlock(&fakeLogDeviceLock);
108} 112}
113
109#else // !defined(_WIN32) 114#else // !defined(_WIN32)
115
110#define lock() ((void)0) 116#define lock() ((void)0)
111#define unlock() ((void)0) 117#define unlock() ((void)0)
118
112#endif // !defined(_WIN32) 119#endif // !defined(_WIN32)
113 120
114 121
diff --git a/liblog/log_is_loggable.c b/liblog/log_is_loggable.c
index 814d96d09..e128edbd8 100644
--- a/liblog/log_is_loggable.c
+++ b/liblog/log_is_loggable.c
@@ -23,6 +23,22 @@
23 23
24#include <android/log.h> 24#include <android/log.h>
25 25
26static pthread_mutex_t lock_loggable = PTHREAD_MUTEX_INITIALIZER;
27
28static void lock()
29{
30 /*
31 * If we trigger a signal handler in the middle of locked activity and the
32 * signal handler logs a message, we could get into a deadlock state.
33 */
34 pthread_mutex_lock(&lock_loggable);
35}
36
37static void unlock()
38{
39 pthread_mutex_unlock(&lock_loggable);
40}
41
26struct cache { 42struct cache {
27 const prop_info *pinfo; 43 const prop_info *pinfo;
28 uint32_t serial; 44 uint32_t serial;
@@ -49,9 +65,7 @@ static void refresh_cache(struct cache *cache, const char *key)
49 cache->c = buf[0]; 65 cache->c = buf[0];
50} 66}
51 67
52static pthread_mutex_t lock = PTHREAD_MUTEX_INITIALIZER; 68static int __android_log_level(const char *tag, int default_prio)
53
54static int __android_log_level(const char *tag, int def)
55{ 69{
56 /* sizeof() is used on this array below */ 70 /* sizeof() is used on this array below */
57 static const char log_namespace[] = "persist.log.tag."; 71 static const char log_namespace[] = "persist.log.tag.";
@@ -86,7 +100,7 @@ static int __android_log_level(const char *tag, int def)
86 100
87 strcpy(key, log_namespace); 101 strcpy(key, log_namespace);
88 102
89 pthread_mutex_lock(&lock); 103 lock();
90 104
91 current_global_serial = __system_property_area_serial(); 105 current_global_serial = __system_property_area_serial();
92 106
@@ -156,7 +170,7 @@ static int __android_log_level(const char *tag, int def)
156 170
157 global_serial = current_global_serial; 171 global_serial = current_global_serial;
158 172
159 pthread_mutex_unlock(&lock); 173 unlock();
160 174
161 switch (toupper(c)) { 175 switch (toupper(c)) {
162 case 'V': return ANDROID_LOG_VERBOSE; 176 case 'V': return ANDROID_LOG_VERBOSE;
@@ -168,36 +182,47 @@ static int __android_log_level(const char *tag, int def)
168 case 'A': return ANDROID_LOG_FATAL; 182 case 'A': return ANDROID_LOG_FATAL;
169 case 'S': return -1; /* ANDROID_LOG_SUPPRESS */ 183 case 'S': return -1; /* ANDROID_LOG_SUPPRESS */
170 } 184 }
171 return def; 185 return default_prio;
172} 186}
173 187
174int __android_log_is_loggable(int prio, const char *tag, int def) 188int __android_log_is_loggable(int prio, const char *tag, int default_prio)
175{ 189{
176 int logLevel = __android_log_level(tag, def); 190 int logLevel = __android_log_level(tag, default_prio);
177 return logLevel >= 0 && prio >= logLevel; 191 return logLevel >= 0 && prio >= logLevel;
178} 192}
179 193
194/*
195 * Timestamp state generally remains constant, since a change is
196 * rare, we can accept a trylock failure gracefully. Use a separate
197 * lock from is_loggable to keep contention down b/25563384.
198 */
199static pthread_mutex_t lock_timestamp = PTHREAD_MUTEX_INITIALIZER;
200
180char android_log_timestamp() 201char android_log_timestamp()
181{ 202{
182 static struct cache r_time_cache = { NULL, -1, 0 }; 203 static struct cache r_time_cache = { NULL, -1, 0 };
183 static struct cache p_time_cache = { NULL, -1, 0 }; 204 static struct cache p_time_cache = { NULL, -1, 0 };
184 static uint32_t serial;
185 uint32_t current_serial;
186 char retval; 205 char retval;
187 206
188 pthread_mutex_lock(&lock); 207 if (pthread_mutex_trylock(&lock_timestamp)) {
208 /* We are willing to accept some race in this context */
209 if (!(retval = p_time_cache.c)) {
210 retval = r_time_cache.c;
211 }
212 } else {
213 static uint32_t serial;
214 uint32_t current_serial = __system_property_area_serial();
215 if (current_serial != serial) {
216 refresh_cache(&r_time_cache, "ro.logd.timestamp");
217 refresh_cache(&p_time_cache, "persist.logd.timestamp");
218 serial = current_serial;
219 }
220 if (!(retval = p_time_cache.c)) {
221 retval = r_time_cache.c;
222 }
189 223
190 current_serial = __system_property_area_serial(); 224 pthread_mutex_unlock(&lock_timestamp);
191 if (current_serial != serial) {
192 refresh_cache(&r_time_cache, "ro.logd.timestamp");
193 refresh_cache(&p_time_cache, "persist.logd.timestamp");
194 serial = current_serial;
195 } 225 }
196 if (!(retval = p_time_cache.c)) {
197 retval = r_time_cache.c;
198 }
199
200 pthread_mutex_unlock(&lock);
201 226
202 return tolower(retval ?: 'r'); 227 return tolower(retval ?: 'r');
203} 228}
diff --git a/liblog/logd_write.c b/liblog/logd_write.c
index a4310aee1..83c6dc296 100644
--- a/liblog/logd_write.c
+++ b/liblog/logd_write.c
@@ -54,14 +54,35 @@
54 54
55static int __write_to_log_init(log_id_t, struct iovec *vec, size_t nr); 55static int __write_to_log_init(log_id_t, struct iovec *vec, size_t nr);
56static int (*write_to_log)(log_id_t, struct iovec *vec, size_t nr) = __write_to_log_init; 56static int (*write_to_log)(log_id_t, struct iovec *vec, size_t nr) = __write_to_log_init;
57#if !defined(_WIN32)
58static pthread_mutex_t log_init_lock = PTHREAD_MUTEX_INITIALIZER;
59#endif
60 57
61#ifndef __unused 58#ifndef __unused
62#define __unused __attribute__((__unused__)) 59#define __unused __attribute__((__unused__))
63#endif 60#endif
64 61
62#if !defined(_WIN32)
63static pthread_mutex_t log_init_lock = PTHREAD_MUTEX_INITIALIZER;
64
65static void lock()
66{
67 /*
68 * If we trigger a signal handler in the middle of locked activity and the
69 * signal handler logs a message, we could get into a deadlock state.
70 */
71 pthread_mutex_lock(&log_init_lock);
72}
73
74static void unlock()
75{
76 pthread_mutex_unlock(&log_init_lock);
77}
78
79#else /* !defined(_WIN32) */
80
81#define lock() ((void)0)
82#define unlock() ((void)0)
83
84#endif /* !defined(_WIN32) */
85
65#if FAKE_LOG_DEVICE 86#if FAKE_LOG_DEVICE
66static int log_fds[(int)LOG_ID_MAX] = { -1, -1, -1, -1, -1 }; 87static int log_fds[(int)LOG_ID_MAX] = { -1, -1, -1, -1, -1 };
67#else 88#else
@@ -277,15 +298,11 @@ static int __write_to_log_daemon(log_id_t log_id, struct iovec *vec, size_t nr)
277 if (ret < 0) { 298 if (ret < 0) {
278 ret = -errno; 299 ret = -errno;
279 if (ret == -ENOTCONN) { 300 if (ret == -ENOTCONN) {
280#if !defined(_WIN32) 301 lock();
281 pthread_mutex_lock(&log_init_lock);
282#endif
283 close(logd_fd); 302 close(logd_fd);
284 logd_fd = -1; 303 logd_fd = -1;
285 ret = __write_to_log_initialize(); 304 ret = __write_to_log_initialize();
286#if !defined(_WIN32) 305 unlock();
287 pthread_mutex_unlock(&log_init_lock);
288#endif
289 306
290 if (ret < 0) { 307 if (ret < 0) {
291 return ret; 308 return ret;
@@ -329,18 +346,14 @@ const char *android_log_id_to_name(log_id_t log_id)
329 346
330static int __write_to_log_init(log_id_t log_id, struct iovec *vec, size_t nr) 347static int __write_to_log_init(log_id_t log_id, struct iovec *vec, size_t nr)
331{ 348{
332#if !defined(_WIN32) 349 lock();
333 pthread_mutex_lock(&log_init_lock);
334#endif
335 350
336 if (write_to_log == __write_to_log_init) { 351 if (write_to_log == __write_to_log_init) {
337 int ret; 352 int ret;
338 353
339 ret = __write_to_log_initialize(); 354 ret = __write_to_log_initialize();
340 if (ret < 0) { 355 if (ret < 0) {
341#if !defined(_WIN32) 356 unlock();
342 pthread_mutex_unlock(&log_init_lock);
343#endif
344#if (FAKE_LOG_DEVICE == 0) 357#if (FAKE_LOG_DEVICE == 0)
345 if (pstore_fd >= 0) { 358 if (pstore_fd >= 0) {
346 __write_to_log_daemon(log_id, vec, nr); 359 __write_to_log_daemon(log_id, vec, nr);
@@ -352,9 +365,7 @@ static int __write_to_log_init(log_id_t log_id, struct iovec *vec, size_t nr)
352 write_to_log = __write_to_log_daemon; 365 write_to_log = __write_to_log_daemon;
353 } 366 }
354 367
355#if !defined(_WIN32) 368 unlock();
356 pthread_mutex_unlock(&log_init_lock);
357#endif
358 369
359 return write_to_log(log_id, vec, nr); 370 return write_to_log(log_id, vec, nr);
360} 371}