source: logging.c @ 4f746f8

release-1.8release-1.9
Last change on this file since 4f746f8 was cc305b5, checked in by Adam Glasgall <glasgall@mit.edu>, 10 years ago
Move log-writing onto a background thread. Currently, Barnowl writes message logs on the same thread as the UI and other I/O. This means that if writing log files is very slow (e.g. if logpath or classlogpath point to somewhere in AFS and the fileserver that volume relies on is very slow to respond), barnowl freezes up until the write completes. This patch creates a background logging thread as part of initialization and runs a main loop on that thread. Logging is then accomplished by posting tasks that write to log files to that thread, a la how other threads can post tasks to the UI thread's main loop. Post a quit task to the logging thread's mainloop instead of quitting directly Calling g_main_quit() on the main thread to quit the logging thread could resultin log tasks still in its queue getting lost. Instead, after we've shut down everything that could log messages, post a quit task to the log thread so that it'll only get run after everything outstanding has been processed.
  • Property mode set to 100644
File size: 13.2 KB
Line 
1#include "owl.h"
2#include <stdlib.h>
3#include <string.h>
4#include <ctype.h>
5#include <sys/param.h>
6
7typedef struct _owl_log_entry { /* noproto */
8  char *filename;
9  char *message;
10} owl_log_entry;
11
12
13static GMainContext *log_context;
14static GMainLoop *log_loop;
15static GThread *logging_thread;
16
17/* This is now the one function that should be called to log a
18 * message.  It will do all the work necessary by calling the other
19 * functions in this file as necessary.
20 */
21void owl_log_message(const owl_message *m) {
22  owl_function_debugmsg("owl_log_message: entering");
23
24  if (m == NULL) {
25    owl_function_debugmsg("owl_log_message: passed null message");
26    return;
27  }
28
29  /* should we be logging this message? */
30  if (!owl_log_shouldlog_message(m)) {
31    owl_function_debugmsg("owl_log_message: not logging message");
32    return;
33  }
34
35  /* handle incmoing messages */
36  if (owl_message_is_direction_in(m)) {
37    owl_log_incoming(m);
38    owl_function_debugmsg("owl_log_message: leaving");
39    return;
40  }
41
42  /* handle outgoing messages */
43  owl_log_outgoing(m);
44
45  owl_function_debugmsg("owl_log_message: leaving");
46}
47
48/* Return 1 if we should log the given message, otherwise return 0 */
49int owl_log_shouldlog_message(const owl_message *m) {
50  const owl_filter *f;
51
52  /* If there's a logfilter and this message matches it, log */
53  f=owl_global_get_filter(&g, owl_global_get_logfilter(&g));
54  if (f && owl_filter_message_match(f, m)) return(1);
55
56  /* otherwise we do things based on the logging variables */
57
58  /* skip login/logout messages if appropriate */
59  if (!owl_global_is_loglogins(&g) && owl_message_is_loginout(m)) return(0);
60     
61  /* check direction */
62  if ((owl_global_get_loggingdirection(&g)==OWL_LOGGING_DIRECTION_IN) && owl_message_is_direction_out(m)) {
63    return(0);
64  }
65  if ((owl_global_get_loggingdirection(&g)==OWL_LOGGING_DIRECTION_OUT) && owl_message_is_direction_in(m)) {
66    return(0);
67  }
68
69  if (owl_message_is_type_zephyr(m)) {
70    if (owl_message_is_personal(m) && !owl_global_is_logging(&g)) return(0);
71    if (!owl_message_is_personal(m) && !owl_global_is_classlogging(&g)) return(0);
72  } else {
73    if (owl_message_is_private(m) || owl_message_is_loginout(m)) {
74      if (!owl_global_is_logging(&g)) return(0);
75    } else {
76      if (!owl_global_is_classlogging(&g)) return(0);
77    }
78  }
79  return(1);
80}
81
82char *owl_log_zephyr(const owl_message *m) {
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
105char *owl_log_aim(const owl_message *m) {
106    GString *buffer = NULL;
107    buffer = g_string_new("");
108    g_string_append_printf(buffer, "From: <%s> To: <%s>\n", 
109                           owl_message_get_sender(m), owl_message_get_recipient(m));
110    g_string_append_printf(buffer, "Time: %s\n\n", 
111                           owl_message_get_timestr(m));
112    if (owl_message_is_login(m)) {
113        g_string_append_printf(buffer, "LOGIN\n\n");
114    } else if (owl_message_is_logout(m)) {
115        g_string_append_printf(buffer, "LOGOUT\n\n");
116    } else {
117        g_string_append_printf(buffer, "%s\n\n", owl_message_get_body(m));
118    }
119    return g_string_free(buffer, FALSE);
120}
121
122char *owl_log_jabber(const owl_message *m) {
123    GString *buffer = NULL;
124    buffer = g_string_new("");
125    g_string_append_printf(buffer, "From: <%s> To: <%s>\n",
126                           owl_message_get_sender(m), 
127                           owl_message_get_recipient(m));
128    g_string_append_printf(buffer, "Time: %s\n\n", 
129                           owl_message_get_timestr(m));
130    g_string_append_printf(buffer, "%s\n\n", owl_message_get_body(m));
131    return g_string_free(buffer, FALSE);
132}
133
134char *owl_log_generic(const owl_message *m) {
135    GString *buffer;
136    buffer = g_string_new("");
137    g_string_append_printf(buffer, "From: <%s> To: <%s>\n", 
138                           owl_message_get_sender(m), 
139                           owl_message_get_recipient(m));
140    g_string_append_printf(buffer, "Time: %s\n\n", 
141                           owl_message_get_timestr(m));
142    g_string_append_printf(buffer, "%s\n\n", 
143                           owl_message_get_body(m));
144    return g_string_free(buffer, FALSE);
145}
146
147static void owl_log_error_main_thread(gpointer data)
148{
149  owl_function_error("%s", (const char*)data);
150}
151
152static void owl_log_error(const char *message)
153{
154  char *data = g_strdup(message);
155  owl_select_post_task(owl_log_error_main_thread,
156                       data, g_free, g_main_context_default());
157}
158
159static void owl_log_write_entry(gpointer data)
160{
161  owl_log_entry *msg = (owl_log_entry*)data;
162  FILE *file = NULL;
163  file = fopen(msg->filename, "a");
164  if (!file) {
165    owl_log_error("Unable to open file for logging");
166    return;
167  }
168  fprintf(file, "%s", msg->message);
169  fclose(file);
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_free(msg);
179  }
180}
181
182void owl_log_enqueue_message(const char *buffer, const char *filename)
183{
184  owl_log_entry *log_msg = NULL; 
185  log_msg = g_new(owl_log_entry,1);
186  log_msg->message = g_strdup(buffer);
187  log_msg->filename = g_strdup(filename);
188  owl_select_post_task(owl_log_write_entry, log_msg, 
189                       owl_log_entry_free, log_context);
190}
191
192void owl_log_append(const owl_message *m, const char *filename) {
193  char *buffer = NULL;
194  if (owl_message_is_type_zephyr(m)) {
195    buffer = owl_log_zephyr(m);
196  } else if (owl_message_is_type_jabber(m)) {
197    buffer = owl_log_jabber(m);
198  } else if (owl_message_is_type_aim(m)) {
199    buffer = owl_log_aim(m);
200  } else {
201    buffer = owl_log_generic(m);
202  }
203  owl_log_enqueue_message(buffer, filename);
204  g_free(buffer);
205}
206
207void owl_log_outgoing(const owl_message *m)
208{
209  char *filename, *logpath;
210  char *to, *temp;
211  GList *cc;
212
213  /* expand ~ in path names */
214  logpath = owl_util_makepath(owl_global_get_logpath(&g));
215
216  /* Figure out what path to log to */
217  if (owl_message_is_type_zephyr(m)) {
218    /* If this has CC's, do all but the "recipient" which we'll do below */
219    cc = owl_message_get_cc_without_recipient(m);
220    while (cc != NULL) {
221      temp = short_zuser(cc->data);
222      filename = g_strdup_printf("%s/%s", logpath, temp);
223      owl_log_append(m, filename);
224
225      g_free(filename);
226      g_free(temp);
227      g_free(cc->data);
228      cc = g_list_delete_link(cc, cc);
229    }
230
231    to = short_zuser(owl_message_get_recipient(m));
232  } else if (owl_message_is_type_jabber(m)) {
233    to = g_strdup_printf("jabber:%s", owl_message_get_recipient(m));
234    g_strdelimit(to, "/", '_');
235  } else if (owl_message_is_type_aim(m)) {
236    char *temp2;
237    temp = owl_aim_normalize_screenname(owl_message_get_recipient(m));
238    temp2 = g_utf8_strdown(temp,-1);
239    to = g_strdup_printf("aim:%s", temp2);
240    g_free(temp2);
241    g_free(temp);
242  } else {
243    to = g_strdup("loopback");
244  }
245
246  filename = g_strdup_printf("%s/%s", logpath, to);
247  owl_log_append(m, filename);
248  g_free(to);
249  g_free(filename);
250
251  filename = g_strdup_printf("%s/all", logpath);
252  owl_log_append(m, filename);
253  g_free(logpath);
254  g_free(filename);
255}
256
257
258void owl_log_outgoing_zephyr_error(const owl_zwrite *zw, const char *text)
259{
260  char *filename, *logpath;
261  char *tobuff, *recip;
262  owl_message *m;
263  GString *msgbuf;
264  /* create a present message so we can pass it to
265   * owl_log_shouldlog_message(void)
266   */
267  m = g_new(owl_message, 1);
268  /* recip_index = 0 because there can only be one recipient anyway */
269  owl_message_create_from_zwrite(m, zw, text, 0);
270  if (!owl_log_shouldlog_message(m)) {
271    owl_message_delete(m);
272    return;
273  }
274  owl_message_delete(m);
275
276  /* chop off a local realm */
277  recip = owl_zwrite_get_recip_n_with_realm(zw, 0);
278  tobuff = short_zuser(recip);
279  g_free(recip);
280
281  /* expand ~ in path names */
282  logpath = owl_util_makepath(owl_global_get_logpath(&g));
283  filename = g_strdup_printf("%s/%s", logpath, tobuff);
284  msgbuf = g_string_new("");
285  g_string_printf(msgbuf, "ERROR (owl): %s\n%s\n", tobuff, text);
286  if (text[strlen(text)-1] != '\n') {
287    g_string_append_printf(msgbuf, "\n");
288  }
289  owl_log_enqueue_message(msgbuf->str, filename);
290  g_string_free(msgbuf, TRUE);
291
292  filename = g_strdup_printf("%s/all", logpath);
293  g_free(logpath);
294  msgbuf = g_string_new("");
295  g_string_printf(msgbuf, "ERROR (owl): %s\n%s\n", tobuff, text);
296  if (text[strlen(text)-1] != '\n') {
297    g_string_append_printf(msgbuf, "\n");
298  }
299  owl_log_enqueue_message(msgbuf->str, filename);
300  g_string_free(msgbuf, TRUE);
301
302  g_free(tobuff);
303}
304
305void owl_log_incoming(const owl_message *m)
306{
307  char *filename, *allfilename, *logpath;
308  const char *from=NULL;
309  char *frombuff=NULL;
310  int len, ch, i, personal;
311
312  /* figure out if it's a "personal" message or not */
313  if (owl_message_is_type_zephyr(m)) {
314    if (owl_message_is_personal(m)) {
315      personal = 1;
316    } else {
317      personal = 0;
318    }
319  } else if (owl_message_is_type_jabber(m)) {
320    /* This needs to be fixed to handle groupchat */
321    const char* msgtype = owl_message_get_attribute_value(m,"jtype");
322    if (msgtype && !strcmp(msgtype,"groupchat")) {
323      personal = 0;
324    } else {
325      personal = 1;
326    }
327  } else {
328    if (owl_message_is_private(m) || owl_message_is_loginout(m)) {
329      personal = 1;
330    } else {
331      personal = 0;
332    }
333  }
334
335
336  if (owl_message_is_type_zephyr(m)) {
337    if (personal) {
338      from=frombuff=short_zuser(owl_message_get_sender(m));
339    } else {
340      from=frombuff=g_strdup(owl_message_get_class(m));
341    }
342  } else if (owl_message_is_type_aim(m)) {
343    /* we do not yet handle chat rooms */
344    char *normalto, *temp;
345    temp = owl_aim_normalize_screenname(owl_message_get_sender(m));
346    normalto = g_utf8_strdown(temp, -1);
347    from=frombuff=g_strdup_printf("aim:%s", normalto);
348    g_free(normalto);
349    g_free(temp);
350  } else if (owl_message_is_type_loopback(m)) {
351    from=frombuff=g_strdup("loopback");
352  } else if (owl_message_is_type_jabber(m)) {
353    if (personal) {
354      from=frombuff=g_strdup_printf("jabber:%s", 
355                                    owl_message_get_sender(m));
356    } else {
357      from=frombuff=g_strdup_printf("jabber:%s", 
358                                    owl_message_get_recipient(m));
359    }
360  } else {
361    from=frombuff=g_strdup("unknown");
362  }
363 
364  /* check for malicious sender formats */
365  len=strlen(frombuff);
366  if (len<1 || len>35) from="weird";
367  if (strchr(frombuff, '/')) from="weird";
368
369  ch=frombuff[0];
370  if (!g_ascii_isalnum(ch)) from="weird";
371
372  for (i=0; i<len; i++) {
373    if (frombuff[i]<'!' || frombuff[i]>='~') from="weird";
374  }
375
376  if (!strcmp(frombuff, ".") || !strcasecmp(frombuff, "..")) from="weird";
377
378  if (!personal) {
379    if (strcmp(from, "weird")) {
380      char* temp = g_utf8_strdown(frombuff, -1);
381      if (temp) {
382        g_free(frombuff);
383        from = frombuff = temp;
384      }
385    }
386  }
387
388  /* create the filename (expanding ~ in path names) */
389  if (personal) {
390    logpath = owl_util_makepath(owl_global_get_logpath(&g));
391    filename = g_strdup_printf("%s/%s", logpath, from);
392    allfilename = g_strdup_printf("%s/all", logpath);
393    owl_log_append(m, allfilename);
394    g_free(allfilename);
395  } else {
396    logpath = owl_util_makepath(owl_global_get_classlogpath(&g));
397    filename = g_strdup_printf("%s/%s", logpath, from);
398  }
399
400  owl_log_append(m, filename);
401  g_free(filename);
402
403  if (personal && owl_message_is_type_zephyr(m)) {
404    /* We want to log to all of the CC'd people who were not us, or
405     * the sender, as well.
406     */
407    char *temp;
408    GList *cc;
409    cc = owl_message_get_cc_without_recipient(m);
410    while (cc != NULL) {
411      temp = short_zuser(cc->data);
412      if (strcasecmp(temp, frombuff) != 0) {
413        filename = g_strdup_printf("%s/%s", logpath, temp);
414        owl_log_append(m, filename);
415        g_free(filename);
416      }
417
418      g_free(temp);
419      g_free(cc->data);
420      cc = g_list_delete_link(cc, cc);
421    }
422  }
423
424  g_free(frombuff);
425  g_free(logpath);
426}
427
428static gpointer owl_log_thread_func(gpointer data)
429{
430  log_context = g_main_context_new();
431  log_loop = g_main_loop_new(log_context, FALSE);
432  g_main_loop_run(log_loop);
433  return NULL;
434}
435
436void owl_log_init(void) 
437{
438  GError *error = NULL;
439  logging_thread = g_thread_create(owl_log_thread_func,
440                                   NULL,
441                                   TRUE,
442                                   &error);
443  if (error) {
444    endwin();
445    fprintf(stderr, "Error spawning logging thread: %s\n", error->message);
446    fflush(stderr);
447    exit(1);
448  }
449 
450}
451
452static void owl_log_quit_func(gpointer data)
453{
454  g_main_loop_quit(log_loop);
455}
456
457void owl_log_shutdown(void)
458{
459  owl_select_post_task(owl_log_quit_func, NULL,
460                       NULL, log_context);
461  g_thread_join(logging_thread);
462}
Note: See TracBrowser for help on using the repository browser.