source: logging.c @ 7f463cf

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