source: logging.c @ f809cad

Last change on this file since f809cad was f809cad, checked in by Jason Gross <jgross@mit.edu>, 9 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: 15.9 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 owl_log_error(const char *message)
156{
157  char *data = g_strdup(message);
158  owl_select_post_task(owl_log_error_main_thread,
159                       data, g_free, g_main_context_default());
160}
161
162static CALLER_OWN owl_log_entry *owl_log_new_entry(const char *buffer, const char *filename)
163{
164  owl_log_entry *log_msg = g_new(owl_log_entry, 1);
165  log_msg->message = g_strdup(buffer);
166  log_msg->filename = g_strdup(filename);
167  return log_msg;
168}
169
170static void owl_log_deferred_enqueue_message(const char *buffer, const char *filename)
171{
172  g_queue_push_tail(deferred_entry_queue, owl_log_new_entry(buffer, filename));
173}
174
175/* write out the entry if possible
176 * return 0 on success, errno on failure to open
177 */
178static int owl_log_try_write_entry(owl_log_entry *msg)
179{
180  FILE *file = NULL;
181  file = fopen(msg->filename, "a");
182  if (!file) {
183    return errno;
184  }
185  fprintf(file, "%s", msg->message);
186  fclose(file);
187  return 0;
188}
189
190static void owl_log_entry_free(void *data)
191{
192  owl_log_entry *msg = (owl_log_entry*)data;
193  if (msg) {
194    g_free(msg->message);
195    g_free(msg->filename);
196    g_free(msg);
197  }
198}
199
200static void owl_log_entry_free_gfunc(gpointer data, gpointer user_data)
201{
202  owl_log_entry_free(data);
203}
204
205/* If we are deferring log messages, enqueue this entry for
206 * writing.  Otherwise, try to write this log message, and,
207 * if it fails with EPERM or EACCES, go into deferred logging
208 * mode and queue an admin message.  If it fails with anything
209 * else, display an error message, but do not go into deferred
210 * logging mode. */
211static void owl_log_eventually_write_entry(gpointer data)
212{
213  int ret;
214  gchar *errmsg;
215  owl_log_entry *msg = (owl_log_entry*)data;
216  if (defer_logs) {
217    owl_log_deferred_enqueue_message(msg->message, msg->filename);
218  } else {
219    ret = owl_log_try_write_entry(msg);
220    if (ret == EPERM || ret == EACCES) {
221      defer_logs = true;
222      owl_log_error("Unable to open file for logging; you do not have \n"
223                    "permission.  Consider renewing your tickets.  \n"
224                    "Logging has been suspended, and your messages \n"
225                    "will be saved.  To resume logging, use the \n"
226                    "command :flush-logs.\n\n");
227      owl_log_deferred_enqueue_message(msg->message, msg->filename);
228    } else if (ret != 0) {
229      errmsg = g_strdup_printf("Unable to open file for logging: %s", g_strerror(ret));
230      owl_log_error(errmsg);
231      g_free(errmsg);
232    }
233  }
234}
235
236/* tries to the deferred log entries */
237static void owl_log_write_deferred_entries(gpointer data)
238{
239  owl_log_entry *entry;
240
241  defer_logs = false;
242  while (!g_queue_is_empty(deferred_entry_queue) && !defer_logs) {
243    entry = (owl_log_entry*)g_queue_pop_head(deferred_entry_queue);
244    owl_log_eventually_write_entry(entry);
245    owl_log_entry_free(entry);
246  }
247}
248
249void owl_log_flush_logs(void)
250{
251  owl_select_post_task(owl_log_write_deferred_entries, NULL, NULL, log_context);
252}
253
254void owl_log_enqueue_message(const char *buffer, const char *filename)
255{
256  owl_log_entry *log_msg = owl_log_new_entry(buffer, filename);
257  owl_select_post_task(owl_log_eventually_write_entry, log_msg,
258                       owl_log_entry_free, log_context);
259}
260
261void owl_log_append(const owl_message *m, const char *filename) {
262  char *buffer = NULL;
263  if (owl_message_is_type_zephyr(m)) {
264    buffer = owl_log_zephyr(m);
265  } else if (owl_message_is_type_jabber(m)) {
266    buffer = owl_log_jabber(m);
267  } else if (owl_message_is_type_aim(m)) {
268    buffer = owl_log_aim(m);
269  } else {
270    buffer = owl_log_generic(m);
271  }
272  owl_log_enqueue_message(buffer, filename);
273  g_free(buffer);
274}
275
276void owl_log_outgoing(const owl_message *m)
277{
278  char *filename, *logpath;
279  char *to, *temp;
280  GList *cc;
281
282  /* expand ~ in path names */
283  logpath = owl_util_makepath(owl_global_get_logpath(&g));
284
285  /* Figure out what path to log to */
286  if (owl_message_is_type_zephyr(m)) {
287    /* If this has CC's, do all but the "recipient" which we'll do below */
288    cc = owl_message_get_cc_without_recipient(m);
289    while (cc != NULL) {
290      temp = short_zuser(cc->data);
291      filename = g_build_filename(logpath, temp, NULL);
292      owl_log_append(m, filename);
293
294      g_free(filename);
295      g_free(temp);
296      g_free(cc->data);
297      cc = g_list_delete_link(cc, cc);
298    }
299
300    to = short_zuser(owl_message_get_recipient(m));
301  } else if (owl_message_is_type_jabber(m)) {
302    to = g_strdup_printf("jabber:%s", owl_message_get_recipient(m));
303    g_strdelimit(to, "/", '_');
304  } else if (owl_message_is_type_aim(m)) {
305    char *temp2;
306    temp = owl_aim_normalize_screenname(owl_message_get_recipient(m));
307    temp2 = g_utf8_strdown(temp,-1);
308    to = g_strdup_printf("aim:%s", temp2);
309    g_free(temp2);
310    g_free(temp);
311  } else {
312    to = g_strdup("loopback");
313  }
314
315  filename = g_build_filename(logpath, to, NULL);
316  owl_log_append(m, filename);
317  g_free(to);
318  g_free(filename);
319
320  filename = g_build_filename(logpath, "all", NULL);
321  owl_log_append(m, filename);
322  g_free(logpath);
323  g_free(filename);
324}
325
326
327void owl_log_outgoing_zephyr_error(const owl_zwrite *zw, const char *text)
328{
329  char *filename, *logpath;
330  char *tobuff, *recip;
331  owl_message *m;
332  GString *msgbuf;
333  /* create a present message so we can pass it to
334   * owl_log_shouldlog_message(void)
335   */
336  m = g_new(owl_message, 1);
337  /* recip_index = 0 because there can only be one recipient anyway */
338  owl_message_create_from_zwrite(m, zw, text, 0);
339  if (!owl_log_shouldlog_message(m)) {
340    owl_message_delete(m);
341    return;
342  }
343  owl_message_delete(m);
344
345  /* chop off a local realm */
346  recip = owl_zwrite_get_recip_n_with_realm(zw, 0);
347  tobuff = short_zuser(recip);
348  g_free(recip);
349
350  /* expand ~ in path names */
351  logpath = owl_util_makepath(owl_global_get_logpath(&g));
352  filename = g_build_filename(logpath, tobuff, NULL);
353  msgbuf = g_string_new("");
354  g_string_printf(msgbuf, "ERROR (owl): %s\n%s\n", tobuff, text);
355  if (text[strlen(text)-1] != '\n') {
356    g_string_append_printf(msgbuf, "\n");
357  }
358  owl_log_enqueue_message(msgbuf->str, filename);
359  g_string_free(msgbuf, TRUE);
360
361  filename = g_build_filename(logpath, "all", NULL);
362  g_free(logpath);
363  msgbuf = g_string_new("");
364  g_string_printf(msgbuf, "ERROR (owl): %s\n%s\n", tobuff, text);
365  if (text[strlen(text)-1] != '\n') {
366    g_string_append_printf(msgbuf, "\n");
367  }
368  owl_log_enqueue_message(msgbuf->str, filename);
369  g_string_free(msgbuf, TRUE);
370
371  g_free(tobuff);
372}
373
374void owl_log_incoming(const owl_message *m)
375{
376  char *filename, *allfilename, *logpath;
377  const char *from=NULL;
378  char *frombuff=NULL;
379  int len, ch, i, personal;
380
381  /* figure out if it's a "personal" message or not */
382  if (owl_message_is_type_zephyr(m)) {
383    if (owl_message_is_personal(m)) {
384      personal = 1;
385    } else {
386      personal = 0;
387    }
388  } else if (owl_message_is_type_jabber(m)) {
389    /* This needs to be fixed to handle groupchat */
390    const char* msgtype = owl_message_get_attribute_value(m,"jtype");
391    if (msgtype && !strcmp(msgtype,"groupchat")) {
392      personal = 0;
393    } else {
394      personal = 1;
395    }
396  } else {
397    if (owl_message_is_private(m) || owl_message_is_loginout(m)) {
398      personal = 1;
399    } else {
400      personal = 0;
401    }
402  }
403
404
405  if (owl_message_is_type_zephyr(m)) {
406    if (personal) {
407      from=frombuff=short_zuser(owl_message_get_sender(m));
408    } else {
409      from=frombuff=g_strdup(owl_message_get_class(m));
410    }
411  } else if (owl_message_is_type_aim(m)) {
412    /* we do not yet handle chat rooms */
413    char *normalto, *temp;
414    temp = owl_aim_normalize_screenname(owl_message_get_sender(m));
415    normalto = g_utf8_strdown(temp, -1);
416    from=frombuff=g_strdup_printf("aim:%s", normalto);
417    g_free(normalto);
418    g_free(temp);
419  } else if (owl_message_is_type_loopback(m)) {
420    from=frombuff=g_strdup("loopback");
421  } else if (owl_message_is_type_jabber(m)) {
422    if (personal) {
423      from=frombuff=g_strdup_printf("jabber:%s",
424                                    owl_message_get_sender(m));
425    } else {
426      from=frombuff=g_strdup_printf("jabber:%s",
427                                    owl_message_get_recipient(m));
428    }
429  } else {
430    from=frombuff=g_strdup("unknown");
431  }
432
433  /* check for malicious sender formats */
434  len=strlen(frombuff);
435  if (len<1 || len>35) from="weird";
436  if (strchr(frombuff, '/')) from="weird";
437
438  ch=frombuff[0];
439  if (!g_ascii_isalnum(ch)) from="weird";
440
441  for (i=0; i<len; i++) {
442    if (frombuff[i]<'!' || frombuff[i]>='~') from="weird";
443  }
444
445  if (!strcmp(frombuff, ".") || !strcasecmp(frombuff, "..")) from="weird";
446
447  if (!personal) {
448    if (strcmp(from, "weird")) {
449      char* temp = g_utf8_strdown(frombuff, -1);
450      if (temp) {
451        g_free(frombuff);
452        from = frombuff = temp;
453      }
454    }
455  }
456
457  /* create the filename (expanding ~ in path names) */
458  if (personal) {
459    logpath = owl_util_makepath(owl_global_get_logpath(&g));
460    filename = g_build_filename(logpath, from, NULL);
461    allfilename = g_build_filename(logpath, "all", NULL);
462    owl_log_append(m, allfilename);
463    g_free(allfilename);
464  } else {
465    logpath = owl_util_makepath(owl_global_get_classlogpath(&g));
466    filename = g_build_filename(logpath, from, NULL);
467  }
468
469  owl_log_append(m, filename);
470  g_free(filename);
471
472  if (personal && owl_message_is_type_zephyr(m)) {
473    /* We want to log to all of the CC'd people who were not us, or
474     * the sender, as well.
475     */
476    char *temp;
477    GList *cc;
478    cc = owl_message_get_cc_without_recipient(m);
479    while (cc != NULL) {
480      temp = short_zuser(cc->data);
481      if (strcasecmp(temp, frombuff) != 0) {
482        filename = g_build_filename(logpath, temp, NULL);
483        owl_log_append(m, filename);
484        g_free(filename);
485      }
486
487      g_free(temp);
488      g_free(cc->data);
489      cc = g_list_delete_link(cc, cc);
490    }
491  }
492
493  g_free(frombuff);
494  g_free(logpath);
495}
496
497static gpointer owl_log_thread_func(gpointer data)
498{
499  log_context = g_main_context_new();
500  log_loop = g_main_loop_new(log_context, FALSE);
501  g_main_loop_run(log_loop);
502  return NULL;
503}
504
505void owl_log_init(void)
506{
507  log_context = g_main_context_new();
508#if GLIB_CHECK_VERSION(2, 31, 0)
509  logging_thread = g_thread_new("logging",
510                                owl_log_thread_func,
511                                NULL);
512#else
513  GError *error = NULL;
514  logging_thread = g_thread_create(owl_log_thread_func,
515                                   NULL,
516                                   TRUE,
517                                   &error);
518  if (error) {
519    endwin();
520    fprintf(stderr, "Error spawning logging thread: %s\n", error->message);
521    fflush(stderr);
522    exit(1);
523  }
524#endif
525
526  deferred_entry_queue = g_queue_new();
527}
528
529static void owl_log_quit_func(gpointer data)
530{
531  /* flush the deferred logs queue, trying to write the
532   * entries to the disk one last time */
533  owl_log_write_deferred_entries(NULL);
534#if GLIB_CHECK_VERSION(2, 32, 0)
535  g_queue_free_full(deferred_entry_queue, owl_log_entry_free_gfunc);
536#else
537  g_queue_foreach(deferred_entry_queue, owl_log_entry_free_gfunc, NULL);
538  g_queue_free(deferred_entry_queue);
539#endif
540
541  g_main_loop_quit(log_loop);
542}
543
544void owl_log_shutdown(void)
545{
546  owl_select_post_task(owl_log_quit_func, NULL,
547                       NULL, log_context);
548  g_thread_join(logging_thread);
549}
Note: See TracBrowser for help on using the repository browser.