source: logging.c @ 09a3afc

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