source: logging.c @ 66dc2c6

Last change on this file since 66dc2c6 was 66dc2c6, checked in by Jason Gross <jgross@mit.edu>, 8 years ago
Defer failed log messages Previously, when we failed to open a logging file, we errored, and dropped the log message. This commit makes it so that, if the reason we failed was a permissions error, we instead add the log entry to a queue of messages to be logged eventually, and inform the user that logging has been suspended. The user must run :flush-logs to resume logging. If :flush-log has an fopen that fails with EPERM or EACCES, we re-defer messages and inform the user. On shutdown, BarnOwl will attempt to log all messages currently in the queue one last time.
  • Property mode set to 100644
File size: 16.1 KB
Line 
1#include "owl.h"
2#include <stdio.h>
3
4typedef struct _owl_log_entry { /* noproto */
5  char *filename;
6  char *message;
7} owl_log_entry;
8
9
10static GMainContext *log_context;
11static GMainLoop *log_loop;
12static GThread *logging_thread;
13bool defer_logs;
14static GQueue *deferred_entry_queue;
15
16/* This is now the one function that should be called to log a
17 * message.  It will do all the work necessary by calling the other
18 * functions in this file as necessary.
19 */
20void owl_log_message(const owl_message *m) {
21  owl_function_debugmsg("owl_log_message: entering");
22
23  if (m == NULL) {
24    owl_function_debugmsg("owl_log_message: passed null message");
25    return;
26  }
27
28  /* should we be logging this message? */
29  if (!owl_log_shouldlog_message(m)) {
30    owl_function_debugmsg("owl_log_message: not logging message");
31    return;
32  }
33
34  /* handle incmoing messages */
35  if (owl_message_is_direction_in(m)) {
36    owl_log_incoming(m);
37    owl_function_debugmsg("owl_log_message: leaving");
38    return;
39  }
40
41  /* handle outgoing messages */
42  owl_log_outgoing(m);
43
44  owl_function_debugmsg("owl_log_message: leaving");
45}
46
47/* Return 1 if we should log the given message, otherwise return 0 */
48int owl_log_shouldlog_message(const owl_message *m) {
49  const owl_filter *f;
50
51  /* If there's a logfilter and this message matches it, log */
52  f=owl_global_get_filter(&g, owl_global_get_logfilter(&g));
53  if (f && owl_filter_message_match(f, m)) return(1);
54
55  /* otherwise we do things based on the logging variables */
56
57  /* skip login/logout messages if appropriate */
58  if (!owl_global_is_loglogins(&g) && owl_message_is_loginout(m)) return(0);
59     
60  /* check direction */
61  if ((owl_global_get_loggingdirection(&g)==OWL_LOGGING_DIRECTION_IN) && owl_message_is_direction_out(m)) {
62    return(0);
63  }
64  if ((owl_global_get_loggingdirection(&g)==OWL_LOGGING_DIRECTION_OUT) && owl_message_is_direction_in(m)) {
65    return(0);
66  }
67
68  if (owl_message_is_type_zephyr(m)) {
69    if (owl_message_is_personal(m) && !owl_global_is_logging(&g)) return(0);
70    if (!owl_message_is_personal(m) && !owl_global_is_classlogging(&g)) return(0);
71  } else {
72    if (owl_message_is_private(m) || owl_message_is_loginout(m)) {
73      if (!owl_global_is_logging(&g)) return(0);
74    } else {
75      if (!owl_global_is_classlogging(&g)) return(0);
76    }
77  }
78  return(1);
79}
80
81CALLER_OWN char *owl_log_zephyr(const owl_message *m)
82{
83    char *tmp = NULL;
84    GString *buffer = NULL;
85    buffer = g_string_new("");
86    tmp = short_zuser(owl_message_get_sender(m));
87    g_string_append_printf(buffer, "Class: %s Instance: %s", 
88                           owl_message_get_class(m), 
89                           owl_message_get_instance(m));
90    if (strcmp(owl_message_get_opcode(m), "")) {
91      g_string_append_printf(buffer, " Opcode: %s", 
92                             owl_message_get_opcode(m));
93    }
94    g_string_append_printf(buffer, "\n");
95    g_string_append_printf(buffer, "Time: %s Host: %s\n", 
96                           owl_message_get_timestr(m), 
97                           owl_message_get_hostname(m));
98    g_string_append_printf(buffer, "From: %s <%s>\n\n", 
99                           owl_message_get_zsig(m), tmp);
100    g_string_append_printf(buffer, "%s\n\n", owl_message_get_body(m));
101    g_free(tmp);
102    return g_string_free(buffer, FALSE);
103}
104
105CALLER_OWN char *owl_log_aim(const owl_message *m)
106{
107    GString *buffer = NULL;
108    buffer = g_string_new("");
109    g_string_append_printf(buffer, "From: <%s> To: <%s>\n", 
110                           owl_message_get_sender(m), owl_message_get_recipient(m));
111    g_string_append_printf(buffer, "Time: %s\n\n", 
112                           owl_message_get_timestr(m));
113    if (owl_message_is_login(m)) {
114        g_string_append_printf(buffer, "LOGIN\n\n");
115    } else if (owl_message_is_logout(m)) {
116        g_string_append_printf(buffer, "LOGOUT\n\n");
117    } else {
118        g_string_append_printf(buffer, "%s\n\n", owl_message_get_body(m));
119    }
120    return g_string_free(buffer, FALSE);
121}
122
123CALLER_OWN char *owl_log_jabber(const owl_message *m)
124{
125    GString *buffer = NULL;
126    buffer = g_string_new("");
127    g_string_append_printf(buffer, "From: <%s> To: <%s>\n",
128                           owl_message_get_sender(m), 
129                           owl_message_get_recipient(m));
130    g_string_append_printf(buffer, "Time: %s\n\n", 
131                           owl_message_get_timestr(m));
132    g_string_append_printf(buffer, "%s\n\n", owl_message_get_body(m));
133    return g_string_free(buffer, FALSE);
134}
135
136CALLER_OWN char *owl_log_generic(const owl_message *m)
137{
138    GString *buffer;
139    buffer = g_string_new("");
140    g_string_append_printf(buffer, "From: <%s> To: <%s>\n", 
141                           owl_message_get_sender(m), 
142                           owl_message_get_recipient(m));
143    g_string_append_printf(buffer, "Time: %s\n\n", 
144                           owl_message_get_timestr(m));
145    g_string_append_printf(buffer, "%s\n\n", 
146                           owl_message_get_body(m));
147    return g_string_free(buffer, FALSE);
148}
149
150static void owl_log_error_main_thread(gpointer data)
151{
152  owl_function_error("%s", (const char*)data);
153}
154
155static void G_GNUC_PRINTF(1, 2) owl_log_error(const char *fmt, ...)
156{
157  va_list ap;
158  char *data;
159
160  va_start(ap, fmt);
161  data = g_strdup_vprintf(fmt, ap);
162  va_end(ap);
163
164  owl_select_post_task(owl_log_error_main_thread,
165                       data, g_free, g_main_context_default());
166}
167
168static CALLER_OWN owl_log_entry *owl_log_new_entry(const char *buffer, const char *filename)
169{
170  owl_log_entry *log_msg = g_slice_new(owl_log_entry);
171  log_msg->message = g_strdup(buffer);
172  log_msg->filename = g_strdup(filename);
173  return log_msg;
174}
175
176static void owl_log_deferred_enqueue_message(const char *buffer, const char *filename)
177{
178  g_queue_push_tail(deferred_entry_queue, owl_log_new_entry(buffer, filename));
179}
180
181/* write out the entry if possible
182 * return 0 on success, errno on failure to open
183 */
184static int owl_log_try_write_entry(owl_log_entry *msg)
185{
186  FILE *file = NULL;
187  file = fopen(msg->filename, "a");
188  if (!file) {
189    return errno;
190  }
191  fprintf(file, "%s", msg->message);
192  fclose(file);
193  return 0;
194}
195
196static void owl_log_entry_free(void *data)
197{
198  owl_log_entry *msg = (owl_log_entry*)data;
199  if (msg) {
200    g_free(msg->message);
201    g_free(msg->filename);
202    g_slice_free(owl_log_entry, msg);
203  }
204}
205
206#if GLIB_CHECK_VERSION(2, 32, 0)
207#else
208static void owl_log_entry_free_gfunc(gpointer data, gpointer user_data)
209{
210  owl_log_entry_free(data);
211}
212#endif
213
214/* If we are deferring log messages, enqueue this entry for writing.
215 * Otherwise, try to write this log message, and, if it fails with
216 * EPERM or EACCES, go into deferred logging mode and queue an admin
217 * message.  If it fails with anything else, display an error message,
218 * but do not go into deferred logging mode. */
219static void owl_log_eventually_write_entry(gpointer data)
220{
221  int ret;
222  owl_log_entry *msg = (owl_log_entry*)data;
223  if (defer_logs) {
224    owl_log_deferred_enqueue_message(msg->message, msg->filename);
225  } else {
226    ret = owl_log_try_write_entry(msg);
227    if (ret == EPERM || ret == EACCES) {
228      defer_logs = true;
229      owl_log_error("Unable to open file for logging (%s): \n"
230                    "%s.  \n"
231                    "Consider renewing your tickets.  Logging has been \n"
232                    "suspended, and your messages will be saved.  To \n"
233                    "resume logging, use the command :flush-logs.\n\n",
234                    msg->filename,
235                    g_strerror(ret));
236      owl_log_deferred_enqueue_message(msg->message, msg->filename);
237    } else if (ret != 0) {
238      owl_log_error("Unable to open file for logging: %s (file %s)",
239                    g_strerror(ret),
240                    msg->filename);
241    }
242  }
243}
244
245/* tries to write the deferred log entries */
246static void owl_log_write_deferred_entries(gpointer data)
247{
248  owl_log_entry *entry;
249
250  defer_logs = false;
251  while (!g_queue_is_empty(deferred_entry_queue) && !defer_logs) {
252    entry = (owl_log_entry*)g_queue_pop_head(deferred_entry_queue);
253    owl_log_eventually_write_entry(entry);
254    owl_log_entry_free(entry);
255  }
256}
257
258void owl_log_flush_logs(void)
259{
260  owl_select_post_task(owl_log_write_deferred_entries, NULL, NULL, log_context);
261}
262
263void owl_log_enqueue_message(const char *buffer, const char *filename)
264{
265  owl_log_entry *log_msg = owl_log_new_entry(buffer, filename);
266  owl_select_post_task(owl_log_eventually_write_entry, log_msg,
267                       owl_log_entry_free, log_context);
268}
269
270void owl_log_append(const owl_message *m, const char *filename) {
271  char *buffer = NULL;
272  if (owl_message_is_type_zephyr(m)) {
273    buffer = owl_log_zephyr(m);
274  } else if (owl_message_is_type_jabber(m)) {
275    buffer = owl_log_jabber(m);
276  } else if (owl_message_is_type_aim(m)) {
277    buffer = owl_log_aim(m);
278  } else {
279    buffer = owl_log_generic(m);
280  }
281  owl_log_enqueue_message(buffer, filename);
282  g_free(buffer);
283}
284
285void owl_log_outgoing(const owl_message *m)
286{
287  char *filename, *logpath;
288  char *to, *temp;
289  GList *cc;
290
291  /* expand ~ in path names */
292  logpath = owl_util_makepath(owl_global_get_logpath(&g));
293
294  /* Figure out what path to log to */
295  if (owl_message_is_type_zephyr(m)) {
296    /* If this has CC's, do all but the "recipient" which we'll do below */
297    cc = owl_message_get_cc_without_recipient(m);
298    while (cc != NULL) {
299      temp = short_zuser(cc->data);
300      filename = g_build_filename(logpath, temp, NULL);
301      owl_log_append(m, filename);
302
303      g_free(filename);
304      g_free(temp);
305      g_free(cc->data);
306      cc = g_list_delete_link(cc, cc);
307    }
308
309    to = short_zuser(owl_message_get_recipient(m));
310  } else if (owl_message_is_type_jabber(m)) {
311    to = g_strdup_printf("jabber:%s", owl_message_get_recipient(m));
312    g_strdelimit(to, "/", '_');
313  } else if (owl_message_is_type_aim(m)) {
314    char *temp2;
315    temp = owl_aim_normalize_screenname(owl_message_get_recipient(m));
316    temp2 = g_utf8_strdown(temp,-1);
317    to = g_strdup_printf("aim:%s", temp2);
318    g_free(temp2);
319    g_free(temp);
320  } else {
321    to = g_strdup("loopback");
322  }
323
324  filename = g_build_filename(logpath, to, NULL);
325  owl_log_append(m, filename);
326  g_free(to);
327  g_free(filename);
328
329  filename = g_build_filename(logpath, "all", NULL);
330  owl_log_append(m, filename);
331  g_free(logpath);
332  g_free(filename);
333}
334
335
336void owl_log_outgoing_zephyr_error(const owl_zwrite *zw, const char *text)
337{
338  char *filename, *logpath;
339  char *tobuff, *recip;
340  owl_message *m;
341  GString *msgbuf;
342  /* create a present message so we can pass it to
343   * owl_log_shouldlog_message(void)
344   */
345  m = g_slice_new(owl_message);
346  /* recip_index = 0 because there can only be one recipient anyway */
347  owl_message_create_from_zwrite(m, zw, text, 0);
348  if (!owl_log_shouldlog_message(m)) {
349    owl_message_delete(m);
350    return;
351  }
352  owl_message_delete(m);
353
354  /* chop off a local realm */
355  recip = owl_zwrite_get_recip_n_with_realm(zw, 0);
356  tobuff = short_zuser(recip);
357  g_free(recip);
358
359  /* expand ~ in path names */
360  logpath = owl_util_makepath(owl_global_get_logpath(&g));
361  filename = g_build_filename(logpath, tobuff, NULL);
362  msgbuf = g_string_new("");
363  g_string_printf(msgbuf, "ERROR (owl): %s\n%s\n", tobuff, text);
364  if (text[strlen(text)-1] != '\n') {
365    g_string_append_printf(msgbuf, "\n");
366  }
367  owl_log_enqueue_message(msgbuf->str, filename);
368  g_string_free(msgbuf, TRUE);
369
370  filename = g_build_filename(logpath, "all", NULL);
371  g_free(logpath);
372  msgbuf = g_string_new("");
373  g_string_printf(msgbuf, "ERROR (owl): %s\n%s\n", tobuff, text);
374  if (text[strlen(text)-1] != '\n') {
375    g_string_append_printf(msgbuf, "\n");
376  }
377  owl_log_enqueue_message(msgbuf->str, filename);
378  g_string_free(msgbuf, TRUE);
379
380  g_free(tobuff);
381}
382
383void owl_log_incoming(const owl_message *m)
384{
385  char *filename, *allfilename, *logpath;
386  const char *from=NULL;
387  char *frombuff=NULL;
388  int len, ch, i, personal;
389
390  /* figure out if it's a "personal" message or not */
391  if (owl_message_is_type_zephyr(m)) {
392    if (owl_message_is_personal(m)) {
393      personal = 1;
394    } else {
395      personal = 0;
396    }
397  } else if (owl_message_is_type_jabber(m)) {
398    /* This needs to be fixed to handle groupchat */
399    const char* msgtype = owl_message_get_attribute_value(m,"jtype");
400    if (msgtype && !strcmp(msgtype,"groupchat")) {
401      personal = 0;
402    } else {
403      personal = 1;
404    }
405  } else {
406    if (owl_message_is_private(m) || owl_message_is_loginout(m)) {
407      personal = 1;
408    } else {
409      personal = 0;
410    }
411  }
412
413
414  if (owl_message_is_type_zephyr(m)) {
415    if (personal) {
416      from=frombuff=short_zuser(owl_message_get_sender(m));
417    } else {
418      from=frombuff=g_strdup(owl_message_get_class(m));
419    }
420  } else if (owl_message_is_type_aim(m)) {
421    /* we do not yet handle chat rooms */
422    char *normalto, *temp;
423    temp = owl_aim_normalize_screenname(owl_message_get_sender(m));
424    normalto = g_utf8_strdown(temp, -1);
425    from=frombuff=g_strdup_printf("aim:%s", normalto);
426    g_free(normalto);
427    g_free(temp);
428  } else if (owl_message_is_type_loopback(m)) {
429    from=frombuff=g_strdup("loopback");
430  } else if (owl_message_is_type_jabber(m)) {
431    if (personal) {
432      from=frombuff=g_strdup_printf("jabber:%s", 
433                                    owl_message_get_sender(m));
434    } else {
435      from=frombuff=g_strdup_printf("jabber:%s", 
436                                    owl_message_get_recipient(m));
437    }
438  } else {
439    from=frombuff=g_strdup("unknown");
440  }
441 
442  /* check for malicious sender formats */
443  len=strlen(frombuff);
444  if (len<1 || len>35) from="weird";
445  if (strchr(frombuff, '/')) from="weird";
446
447  ch=frombuff[0];
448  if (!g_ascii_isalnum(ch)) from="weird";
449
450  for (i=0; i<len; i++) {
451    if (frombuff[i]<'!' || frombuff[i]>='~') from="weird";
452  }
453
454  if (!strcmp(frombuff, ".") || !strcasecmp(frombuff, "..")) from="weird";
455
456  if (!personal) {
457    if (strcmp(from, "weird")) {
458      char* temp = g_utf8_strdown(frombuff, -1);
459      if (temp) {
460        g_free(frombuff);
461        from = frombuff = temp;
462      }
463    }
464  }
465
466  /* create the filename (expanding ~ in path names) */
467  if (personal) {
468    logpath = owl_util_makepath(owl_global_get_logpath(&g));
469    filename = g_build_filename(logpath, from, NULL);
470    allfilename = g_build_filename(logpath, "all", NULL);
471    owl_log_append(m, allfilename);
472    g_free(allfilename);
473  } else {
474    logpath = owl_util_makepath(owl_global_get_classlogpath(&g));
475    filename = g_build_filename(logpath, from, NULL);
476  }
477
478  owl_log_append(m, filename);
479  g_free(filename);
480
481  if (personal && owl_message_is_type_zephyr(m)) {
482    /* We want to log to all of the CC'd people who were not us, or
483     * the sender, as well.
484     */
485    char *temp;
486    GList *cc;
487    cc = owl_message_get_cc_without_recipient(m);
488    while (cc != NULL) {
489      temp = short_zuser(cc->data);
490      if (strcasecmp(temp, frombuff) != 0) {
491        filename = g_build_filename(logpath, temp, NULL);
492        owl_log_append(m, filename);
493        g_free(filename);
494      }
495
496      g_free(temp);
497      g_free(cc->data);
498      cc = g_list_delete_link(cc, cc);
499    }
500  }
501
502  g_free(frombuff);
503  g_free(logpath);
504}
505
506static gpointer owl_log_thread_func(gpointer data)
507{
508  log_context = g_main_context_new();
509  log_loop = g_main_loop_new(log_context, FALSE);
510  g_main_loop_run(log_loop);
511  return NULL;
512}
513
514void owl_log_init(void)
515{
516  log_context = g_main_context_new();
517#if GLIB_CHECK_VERSION(2, 31, 0)
518  logging_thread = g_thread_new("logging",
519                                owl_log_thread_func,
520                                NULL);
521#else
522  GError *error = NULL;
523  logging_thread = g_thread_create(owl_log_thread_func,
524                                   NULL,
525                                   TRUE,
526                                   &error);
527  if (error) {
528    endwin();
529    fprintf(stderr, "Error spawning logging thread: %s\n", error->message);
530    fflush(stderr);
531    exit(1);
532  }
533#endif
534
535  deferred_entry_queue = g_queue_new();
536}
537
538static void owl_log_quit_func(gpointer data)
539{
540  /* flush the deferred logs queue, trying to write the
541   * entries to the disk one last time */
542  owl_log_write_deferred_entries(NULL);
543#if GLIB_CHECK_VERSION(2, 32, 0)
544  g_queue_free_full(deferred_entry_queue, owl_log_entry_free);
545#else
546  g_queue_foreach(deferred_entry_queue, owl_log_entry_free_gfunc, NULL);
547  g_queue_free(deferred_entry_queue);
548#endif
549
550  g_main_loop_quit(log_loop);
551}
552
553void owl_log_shutdown(void)
554{
555  owl_select_post_task(owl_log_quit_func, NULL,
556                       NULL, log_context);
557  g_thread_join(logging_thread);
558}
Note: See TracBrowser for help on using the repository browser.