1 | #include "owl.h" |
---|
2 | #include <stdio.h> |
---|
3 | |
---|
4 | typedef struct _owl_log_entry { /* noproto */ |
---|
5 | char *filename; |
---|
6 | char *message; |
---|
7 | } owl_log_entry; |
---|
8 | |
---|
9 | typedef struct _owl_log_options { /* noproto */ |
---|
10 | bool drop_failed_logs; |
---|
11 | bool display_initial_log_count; |
---|
12 | } owl_log_options; |
---|
13 | |
---|
14 | static GMainContext *log_context; |
---|
15 | static GMainLoop *log_loop; |
---|
16 | static GThread *logging_thread; |
---|
17 | static bool defer_logs; /* to be accessed only on the disk-writing thread */ |
---|
18 | static GQueue *deferred_entry_queue; |
---|
19 | |
---|
20 | /* This is now the one function that should be called to log a |
---|
21 | * message. It will do all the work necessary by calling the other |
---|
22 | * functions in this file as necessary. |
---|
23 | */ |
---|
24 | void owl_log_message(const owl_message *m) { |
---|
25 | owl_function_debugmsg("owl_log_message: entering"); |
---|
26 | |
---|
27 | if (m == NULL) { |
---|
28 | owl_function_debugmsg("owl_log_message: passed null message"); |
---|
29 | return; |
---|
30 | } |
---|
31 | |
---|
32 | /* should we be logging this message? */ |
---|
33 | if (!owl_log_shouldlog_message(m)) { |
---|
34 | owl_function_debugmsg("owl_log_message: not logging message"); |
---|
35 | return; |
---|
36 | } |
---|
37 | |
---|
38 | owl_log_perl(m); |
---|
39 | |
---|
40 | owl_function_debugmsg("owl_log_message: leaving"); |
---|
41 | } |
---|
42 | |
---|
43 | /* Return 1 if we should log the given message, otherwise return 0 */ |
---|
44 | int owl_log_shouldlog_message(const owl_message *m) { |
---|
45 | const owl_filter *f; |
---|
46 | |
---|
47 | /* If there's a logfilter and this message matches it, log */ |
---|
48 | f=owl_global_get_filter(&g, owl_global_get_logfilter(&g)); |
---|
49 | if (f && owl_filter_message_match(f, m)) return(1); |
---|
50 | |
---|
51 | /* otherwise we do things based on the logging variables */ |
---|
52 | |
---|
53 | /* skip login/logout messages if appropriate */ |
---|
54 | if (!owl_global_is_loglogins(&g) && owl_message_is_loginout(m)) return(0); |
---|
55 | |
---|
56 | /* check direction */ |
---|
57 | if ((owl_global_get_loggingdirection(&g)==OWL_LOGGING_DIRECTION_IN) && owl_message_is_direction_out(m)) { |
---|
58 | return(0); |
---|
59 | } |
---|
60 | if ((owl_global_get_loggingdirection(&g)==OWL_LOGGING_DIRECTION_OUT) && owl_message_is_direction_in(m)) { |
---|
61 | return(0); |
---|
62 | } |
---|
63 | |
---|
64 | if (owl_message_is_type_zephyr(m)) { |
---|
65 | if (owl_message_is_personal(m) && !owl_global_is_logging(&g)) return(0); |
---|
66 | if (!owl_message_is_personal(m) && !owl_global_is_classlogging(&g)) return(0); |
---|
67 | } else { |
---|
68 | if (owl_message_is_private(m) || owl_message_is_loginout(m)) { |
---|
69 | if (!owl_global_is_logging(&g)) return(0); |
---|
70 | } else { |
---|
71 | if (!owl_global_is_classlogging(&g)) return(0); |
---|
72 | } |
---|
73 | } |
---|
74 | return(1); |
---|
75 | } |
---|
76 | |
---|
77 | static void owl_log_error_main_thread(gpointer data) |
---|
78 | { |
---|
79 | owl_function_error("%s", (const char*)data); |
---|
80 | } |
---|
81 | |
---|
82 | static void owl_log_adminmsg_main_thread(gpointer data) |
---|
83 | { |
---|
84 | owl_function_adminmsg("Logging", (const char*)data); |
---|
85 | } |
---|
86 | |
---|
87 | static void owl_log_makemsg_main_thread(gpointer data) |
---|
88 | { |
---|
89 | owl_function_makemsg((const char*)data); |
---|
90 | } |
---|
91 | |
---|
92 | static void G_GNUC_PRINTF(1, 2) owl_log_error(const char *fmt, ...) |
---|
93 | { |
---|
94 | va_list ap; |
---|
95 | char *data; |
---|
96 | |
---|
97 | va_start(ap, fmt); |
---|
98 | data = g_strdup_vprintf(fmt, ap); |
---|
99 | va_end(ap); |
---|
100 | |
---|
101 | owl_select_post_task(owl_log_error_main_thread, |
---|
102 | data, g_free, g_main_context_default()); |
---|
103 | } |
---|
104 | |
---|
105 | static void G_GNUC_PRINTF(1, 2) owl_log_adminmsg(const char *fmt, ...) |
---|
106 | { |
---|
107 | va_list ap; |
---|
108 | char *data; |
---|
109 | |
---|
110 | va_start(ap, fmt); |
---|
111 | data = g_strdup_vprintf(fmt, ap); |
---|
112 | va_end(ap); |
---|
113 | |
---|
114 | owl_select_post_task(owl_log_adminmsg_main_thread, |
---|
115 | data, g_free, g_main_context_default()); |
---|
116 | } |
---|
117 | |
---|
118 | static void G_GNUC_PRINTF(1, 2) owl_log_makemsg(const char *fmt, ...) |
---|
119 | { |
---|
120 | va_list ap; |
---|
121 | char *data; |
---|
122 | |
---|
123 | va_start(ap, fmt); |
---|
124 | data = g_strdup_vprintf(fmt, ap); |
---|
125 | va_end(ap); |
---|
126 | |
---|
127 | owl_select_post_task(owl_log_makemsg_main_thread, |
---|
128 | data, g_free, g_main_context_default()); |
---|
129 | } |
---|
130 | |
---|
131 | static CALLER_OWN owl_log_entry *owl_log_new_entry(const char *buffer, const char *filename) |
---|
132 | { |
---|
133 | owl_log_entry *log_msg = g_slice_new(owl_log_entry); |
---|
134 | log_msg->message = g_strdup(buffer); |
---|
135 | log_msg->filename = g_strdup(filename); |
---|
136 | return log_msg; |
---|
137 | } |
---|
138 | |
---|
139 | static void owl_log_deferred_enqueue_message(const char *buffer, const char *filename) |
---|
140 | { |
---|
141 | g_queue_push_tail(deferred_entry_queue, owl_log_new_entry(buffer, filename)); |
---|
142 | } |
---|
143 | |
---|
144 | static void owl_log_deferred_enqueue_first_message(const char *buffer, const char *filename) |
---|
145 | { |
---|
146 | g_queue_push_head(deferred_entry_queue, owl_log_new_entry(buffer, filename)); |
---|
147 | } |
---|
148 | |
---|
149 | /* write out the entry if possible |
---|
150 | * return 0 on success, errno on failure to open |
---|
151 | */ |
---|
152 | static int owl_log_try_write_entry(owl_log_entry *msg) |
---|
153 | { |
---|
154 | FILE *file = NULL; |
---|
155 | file = fopen(msg->filename, "a"); |
---|
156 | if (!file) { |
---|
157 | return errno; |
---|
158 | } |
---|
159 | fprintf(file, "%s", msg->message); |
---|
160 | fclose(file); |
---|
161 | return 0; |
---|
162 | } |
---|
163 | |
---|
164 | static void owl_log_entry_free(void *data) |
---|
165 | { |
---|
166 | owl_log_entry *msg = (owl_log_entry*)data; |
---|
167 | if (msg) { |
---|
168 | g_free(msg->message); |
---|
169 | g_free(msg->filename); |
---|
170 | g_slice_free(owl_log_entry, msg); |
---|
171 | } |
---|
172 | } |
---|
173 | |
---|
174 | #if GLIB_CHECK_VERSION(2, 32, 0) |
---|
175 | #else |
---|
176 | static void owl_log_entry_free_gfunc(gpointer data, gpointer user_data) |
---|
177 | { |
---|
178 | owl_log_entry_free(data); |
---|
179 | } |
---|
180 | #endif |
---|
181 | |
---|
182 | static void owl_log_file_error(owl_log_entry *msg, int errnum) |
---|
183 | { |
---|
184 | owl_log_error("Unable to open file for logging: %s (file %s)", |
---|
185 | g_strerror(errnum), |
---|
186 | msg->filename); |
---|
187 | } |
---|
188 | |
---|
189 | /* If we are deferring log messages, enqueue this entry for writing. |
---|
190 | * Otherwise, try to write this log message, and, if it fails with |
---|
191 | * EPERM, EACCES, or ETIMEDOUT, go into deferred logging mode and |
---|
192 | * queue an admin message. If it fails with anything else, display an |
---|
193 | * error message, drop the log message, and do not go into deferred |
---|
194 | * logging mode. |
---|
195 | * |
---|
196 | * N.B. This function is called only on the disk-writing thread. */ |
---|
197 | static void owl_log_eventually_write_entry(gpointer data) |
---|
198 | { |
---|
199 | int ret; |
---|
200 | owl_log_entry *msg = (owl_log_entry*)data; |
---|
201 | if (defer_logs) { |
---|
202 | owl_log_deferred_enqueue_message(msg->message, msg->filename); |
---|
203 | } else { |
---|
204 | ret = owl_log_try_write_entry(msg); |
---|
205 | if (ret == EPERM || ret == EACCES || ret == ETIMEDOUT) { |
---|
206 | defer_logs = true; |
---|
207 | owl_log_error("Unable to open file for logging (%s): \n" |
---|
208 | "%s. \n" |
---|
209 | "Consider renewing your tickets. Logging has been \n" |
---|
210 | "suspended, and your messages will be saved. To \n" |
---|
211 | "resume logging, use the command :flush-logs.\n\n", |
---|
212 | msg->filename, |
---|
213 | g_strerror(ret)); |
---|
214 | /* If we were not in deferred logging mode, either the queue should be |
---|
215 | * empty, or we are attempting to log a message that we just popped off |
---|
216 | * the head of the queue. Either way, we should enqueue this message as |
---|
217 | * the first message in the queue, rather than the last, so that we |
---|
218 | * preserve message ordering. */ |
---|
219 | owl_log_deferred_enqueue_first_message(msg->message, msg->filename); |
---|
220 | } else if (ret != 0) { |
---|
221 | owl_log_file_error(msg, ret); |
---|
222 | } |
---|
223 | } |
---|
224 | } |
---|
225 | |
---|
226 | /* tries to write the deferred log entries |
---|
227 | * |
---|
228 | * N.B. This function is called only on the disk-writing thread. */ |
---|
229 | static void owl_log_write_deferred_entries(gpointer data) |
---|
230 | { |
---|
231 | owl_log_entry *entry; |
---|
232 | owl_log_options *opts = (owl_log_options *)data; |
---|
233 | int ret; |
---|
234 | int logged_message_count = 0; |
---|
235 | bool all_succeeded = true; |
---|
236 | |
---|
237 | if (opts->display_initial_log_count) { |
---|
238 | if (g_queue_is_empty(deferred_entry_queue)) { |
---|
239 | owl_log_makemsg("There are no logs to flush."); |
---|
240 | } else { |
---|
241 | owl_log_makemsg("Attempting to flush %u logs...", |
---|
242 | g_queue_get_length(deferred_entry_queue)); |
---|
243 | } |
---|
244 | } |
---|
245 | |
---|
246 | defer_logs = false; |
---|
247 | while (!g_queue_is_empty(deferred_entry_queue) && !defer_logs) { |
---|
248 | logged_message_count++; |
---|
249 | entry = (owl_log_entry*)g_queue_pop_head(deferred_entry_queue); |
---|
250 | if (!opts->drop_failed_logs) { |
---|
251 | /* Attempt to write the log entry. If it fails, re-queue the entry at |
---|
252 | * the head of the queue. */ |
---|
253 | owl_log_eventually_write_entry(entry); |
---|
254 | } else { |
---|
255 | /* Attempt to write the log entry. If it fails, print an error message, |
---|
256 | * drop the log, and keep going through the queue. */ |
---|
257 | ret = owl_log_try_write_entry(entry); |
---|
258 | if (ret != 0) { |
---|
259 | all_succeeded = false; |
---|
260 | owl_log_file_error(entry, ret); |
---|
261 | } |
---|
262 | } |
---|
263 | owl_log_entry_free(entry); |
---|
264 | } |
---|
265 | if (logged_message_count > 0) { |
---|
266 | if (opts->display_initial_log_count) { |
---|
267 | /* first clear the "attempting to flush" message from the status bar */ |
---|
268 | owl_log_makemsg(""); |
---|
269 | } |
---|
270 | if (!defer_logs) { |
---|
271 | if (all_succeeded) { |
---|
272 | owl_log_adminmsg("Flushed %d logs and resumed logging.", |
---|
273 | logged_message_count); |
---|
274 | } else { |
---|
275 | owl_log_adminmsg("Flushed or dropped %d logs and resumed logging.", |
---|
276 | logged_message_count); |
---|
277 | } |
---|
278 | } else { |
---|
279 | owl_log_error("Attempted to flush %d logs; %u deferred logs remain.", |
---|
280 | logged_message_count, g_queue_get_length(deferred_entry_queue)); |
---|
281 | } |
---|
282 | } |
---|
283 | } |
---|
284 | |
---|
285 | void owl_log_flush_logs(bool drop_failed_logs, bool quiet) |
---|
286 | { |
---|
287 | owl_log_options *data = g_new(owl_log_options, 1); |
---|
288 | data->drop_failed_logs = drop_failed_logs; |
---|
289 | data->display_initial_log_count = !quiet; |
---|
290 | |
---|
291 | owl_select_post_task(owl_log_write_deferred_entries, |
---|
292 | data, |
---|
293 | g_free, |
---|
294 | log_context); |
---|
295 | } |
---|
296 | |
---|
297 | void owl_log_enqueue_message(const char *buffer, const char *filename) |
---|
298 | { |
---|
299 | owl_log_entry *log_msg = owl_log_new_entry(buffer, filename); |
---|
300 | owl_select_post_task(owl_log_eventually_write_entry, log_msg, |
---|
301 | owl_log_entry_free, log_context); |
---|
302 | } |
---|
303 | |
---|
304 | void owl_log_append(const owl_message *m, const char *filename) { |
---|
305 | char *buffer = owl_perlconfig_message_call_method(m, "log", 0, NULL); |
---|
306 | owl_log_enqueue_message(buffer, filename); |
---|
307 | g_free(buffer); |
---|
308 | } |
---|
309 | |
---|
310 | void owl_log_outgoing_zephyr_error(const owl_zwrite *zw, const char *text) |
---|
311 | { |
---|
312 | char *filename, *logpath; |
---|
313 | char *tobuff, *recip; |
---|
314 | owl_message *m; |
---|
315 | GString *msgbuf; |
---|
316 | /* create a present message so we can pass it to |
---|
317 | * owl_log_shouldlog_message(void) |
---|
318 | */ |
---|
319 | m = g_slice_new(owl_message); |
---|
320 | /* recip_index = 0 because there can only be one recipient anyway */ |
---|
321 | owl_message_create_from_zwrite(m, zw, text, 0); |
---|
322 | if (!owl_log_shouldlog_message(m)) { |
---|
323 | owl_message_delete(m); |
---|
324 | return; |
---|
325 | } |
---|
326 | owl_message_delete(m); |
---|
327 | |
---|
328 | /* chop off a local realm */ |
---|
329 | recip = owl_zwrite_get_recip_n_with_realm(zw, 0); |
---|
330 | tobuff = short_zuser(recip); |
---|
331 | g_free(recip); |
---|
332 | |
---|
333 | /* expand ~ in path names */ |
---|
334 | logpath = owl_util_makepath(owl_global_get_logpath(&g)); |
---|
335 | filename = g_build_filename(logpath, tobuff, NULL); |
---|
336 | msgbuf = g_string_new(""); |
---|
337 | g_string_printf(msgbuf, "ERROR (owl): %s\n%s\n", tobuff, text); |
---|
338 | if (text[strlen(text)-1] != '\n') { |
---|
339 | g_string_append_printf(msgbuf, "\n"); |
---|
340 | } |
---|
341 | owl_log_enqueue_message(msgbuf->str, filename); |
---|
342 | g_string_free(msgbuf, TRUE); |
---|
343 | |
---|
344 | filename = g_build_filename(logpath, "all", NULL); |
---|
345 | g_free(logpath); |
---|
346 | msgbuf = g_string_new(""); |
---|
347 | g_string_printf(msgbuf, "ERROR (owl): %s\n%s\n", tobuff, text); |
---|
348 | if (text[strlen(text)-1] != '\n') { |
---|
349 | g_string_append_printf(msgbuf, "\n"); |
---|
350 | } |
---|
351 | owl_log_enqueue_message(msgbuf->str, filename); |
---|
352 | g_string_free(msgbuf, TRUE); |
---|
353 | |
---|
354 | g_free(tobuff); |
---|
355 | } |
---|
356 | |
---|
357 | void owl_log_perl(const owl_message *m) |
---|
358 | { |
---|
359 | char *filenames_string = owl_perlconfig_call_with_message("BarnOwl::Logging::get_filenames_as_string", m); |
---|
360 | char **filenames = g_strsplit(filenames_string, "\n", 0); |
---|
361 | char **filename_ptr; |
---|
362 | g_free(filenames_string); |
---|
363 | |
---|
364 | for (filename_ptr = filenames; *filename_ptr != NULL; filename_ptr++) { |
---|
365 | owl_log_append(m, *filename_ptr); |
---|
366 | } |
---|
367 | |
---|
368 | g_strfreev(filenames); |
---|
369 | } |
---|
370 | |
---|
371 | static gpointer owl_log_thread_func(gpointer data) |
---|
372 | { |
---|
373 | log_context = g_main_context_new(); |
---|
374 | log_loop = g_main_loop_new(log_context, FALSE); |
---|
375 | g_main_loop_run(log_loop); |
---|
376 | return NULL; |
---|
377 | } |
---|
378 | |
---|
379 | void owl_log_init(void) |
---|
380 | { |
---|
381 | log_context = g_main_context_new(); |
---|
382 | #if GLIB_CHECK_VERSION(2, 31, 0) |
---|
383 | logging_thread = g_thread_new("logging", |
---|
384 | owl_log_thread_func, |
---|
385 | NULL); |
---|
386 | #else |
---|
387 | GError *error = NULL; |
---|
388 | logging_thread = g_thread_create(owl_log_thread_func, |
---|
389 | NULL, |
---|
390 | TRUE, |
---|
391 | &error); |
---|
392 | if (error) { |
---|
393 | endwin(); |
---|
394 | fprintf(stderr, "Error spawning logging thread: %s\n", error->message); |
---|
395 | fflush(stderr); |
---|
396 | exit(1); |
---|
397 | } |
---|
398 | #endif |
---|
399 | |
---|
400 | deferred_entry_queue = g_queue_new(); |
---|
401 | } |
---|
402 | |
---|
403 | static void owl_log_quit_func(gpointer data) |
---|
404 | { |
---|
405 | /* flush the deferred logs queue, trying to write the |
---|
406 | * entries to the disk one last time. Drop any failed |
---|
407 | * entries, and be quiet about it. */ |
---|
408 | owl_log_options opts; |
---|
409 | opts.drop_failed_logs = true; |
---|
410 | opts.display_initial_log_count = false; |
---|
411 | owl_log_write_deferred_entries(&opts); |
---|
412 | #if GLIB_CHECK_VERSION(2, 32, 0) |
---|
413 | g_queue_free_full(deferred_entry_queue, owl_log_entry_free); |
---|
414 | #else |
---|
415 | g_queue_foreach(deferred_entry_queue, owl_log_entry_free_gfunc, NULL); |
---|
416 | g_queue_free(deferred_entry_queue); |
---|
417 | #endif |
---|
418 | |
---|
419 | g_main_loop_quit(log_loop); |
---|
420 | } |
---|
421 | |
---|
422 | void owl_log_shutdown(void) |
---|
423 | { |
---|
424 | owl_select_post_task(owl_log_quit_func, NULL, |
---|
425 | NULL, log_context); |
---|
426 | g_thread_join(logging_thread); |
---|
427 | } |
---|