source: logging.c @ e38f315

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