source: logging.c @ 3d1a2db

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