Use a custom log handler for libassuan.
[gnupg.git] / common / logging.c
1 /* logging.c - Useful logging functions
2  * Copyright (C) 1998, 1999, 2000, 2001, 2003, 2004, 2005, 2006, 
3  *               2009, 2010 Free Software Foundation, Inc.
4  *
5  * This file is part of JNLIB.
6  *
7  * JNLIB is free software; you can redistribute it and/or modify it
8  * under the terms of the GNU Lesser General Public License as
9  * published by the Free Software Foundation; either version 3 of
10  * the License, or (at your option) any later version.
11  *
12  * JNLIB is distributed in the hope that it will be useful, but
13  * WITHOUT ANY WARRANTY; without even the implied warranty of
14  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
15  * Lesser General Public License for more details.
16  *
17  * You should have received a copy of the GNU Lesser General Public
18  * License along with this program; if not, see <http://www.gnu.org/licenses/>.
19  */
20
21
22 #include <config.h>
23 #include <stdlib.h>
24 #include <stdio.h>
25 #include <string.h>
26 #include <stdarg.h>
27 #include <stddef.h>
28 #include <errno.h>
29 #include <time.h>
30 #include <sys/types.h>
31 #include <sys/stat.h>
32 #ifndef HAVE_W32_SYSTEM
33 #include <sys/socket.h>
34 #include <sys/un.h>
35 #endif /*!HAVE_W32_SYSTEM*/
36 #include <unistd.h>
37 #include <fcntl.h>
38 #include <assert.h>
39
40
41 #define JNLIB_NEED_LOG_LOGV 1
42 #define JNLIB_NEED_AFLOCAL 1
43 #include "libjnlib-config.h"
44 #include "logging.h"
45
46
47 static estream_t logstream;
48 static int log_socket = -1;
49 static char prefix_buffer[80];
50 static int with_time;
51 static int with_prefix;
52 static int with_pid;
53 static unsigned long (*get_tid_callback)(void);
54 static int running_detached;
55 static int force_prefixes;
56
57 static int missing_lf;
58 static int errorcount;
59
60
61 int
62 log_get_errorcount (int clear)
63 {
64     int n = errorcount;
65     if( clear )
66         errorcount = 0;
67     return n;
68 }
69
70 void
71 log_inc_errorcount (void)
72 {
73    errorcount++;
74 }
75
76
77 /* The following 3 functions are used by es_fopencookie to write logs
78    to a socket.  */
79 struct fun_cookie_s
80 {
81   int fd;
82   int quiet;
83   int want_socket;
84   int is_socket;
85   char name[1];
86 };
87
88
89 /* Write NBYTES of BUFFER to file descriptor FD. */
90 static int
91 writen (int fd, const void *buffer, size_t nbytes)
92 {
93   const char *buf = buffer;
94   size_t nleft = nbytes;
95   int nwritten;
96   
97   while (nleft > 0)
98     {
99       nwritten = write (fd, buf, nleft);
100       if (nwritten < 0 && errno == EINTR)
101         continue;
102       if (nwritten < 0)
103         return -1;
104       nleft -= nwritten;
105       buf = buf + nwritten;
106     }
107   
108   return 0;
109 }
110
111
112 static ssize_t 
113 fun_writer (void *cookie_arg, const void *buffer, size_t size)
114 {
115   struct fun_cookie_s *cookie = cookie_arg;
116
117   /* Note that we always try to reconnect to the socket but print
118      error messages only the first time an error occured.  If
119      RUNNING_DETACHED is set we don't fall back to stderr and even do
120      not print any error messages.  This is needed because detached
121      processes often close stderr and by writing to file descriptor 2
122      we might send the log message to a file not intended for logging
123      (e.g. a pipe or network connection). */
124   if (cookie->want_socket && cookie->fd == -1)
125     {
126       /* Not yet open or meanwhile closed due to an error. */
127       cookie->is_socket = 0;
128       cookie->fd = socket (PF_LOCAL, SOCK_STREAM, 0);
129       if (cookie->fd == -1)
130         {
131           if (!cookie->quiet && !running_detached
132               && isatty (fileno (stderr)))
133             fprintf (stderr, "failed to create socket for logging: %s\n",
134                      strerror(errno));
135         }
136       else
137         {
138           struct sockaddr_un addr;
139           size_t addrlen;
140           
141           memset (&addr, 0, sizeof addr);
142           addr.sun_family = PF_LOCAL;
143           strncpy (addr.sun_path, cookie->name, sizeof (addr.sun_path)-1);
144           addr.sun_path[sizeof (addr.sun_path)-1] = 0;
145           addrlen = SUN_LEN (&addr);
146       
147           if (connect (cookie->fd, (struct sockaddr *) &addr, addrlen) == -1)
148             {
149               if (!cookie->quiet && !running_detached
150                   && isatty (fileno (stderr)))
151                 fprintf (stderr, "can't connect to `%s': %s\n",
152                          cookie->name, strerror(errno));
153               close (cookie->fd);
154               cookie->fd = -1;
155             }
156         }
157       
158       if (cookie->fd == -1)
159         {
160           if (!running_detached)
161             {
162               /* Due to all the problems with apps not running
163                  detached but being called with stderr closed or
164                  used for a different purposes, it does not make
165                  sense to switch to stderr.  We therefore disable it. */
166               if (!cookie->quiet)
167                 {
168                   /* fputs ("switching logging to stderr\n", stderr);*/
169                   cookie->quiet = 1;
170                 }
171               cookie->fd = -1; /*fileno (stderr);*/
172             }
173         }
174       else /* Connection has been established. */
175         {
176           cookie->quiet = 0;
177           cookie->is_socket = 1;
178         }
179     }
180
181   log_socket = cookie->fd;
182   if (cookie->fd != -1 && !writen (cookie->fd, buffer, size))
183     return (ssize_t)size; /* Okay. */ 
184
185   if (!running_detached && cookie->fd != -1
186       && isatty (fileno (stderr)))
187     {
188       if (*cookie->name)
189         fprintf (stderr, "error writing to `%s': %s\n",
190                  cookie->name, strerror(errno));
191       else
192         fprintf (stderr, "error writing to file descriptor %d: %s\n",
193                  cookie->fd, strerror(errno));
194     }
195   if (cookie->is_socket && cookie->fd != -1)
196     {
197       close (cookie->fd);
198       cookie->fd = -1;
199       log_socket = -1;
200     }
201
202   return (ssize_t)size;
203 }
204
205
206 static int
207 fun_closer (void *cookie_arg)
208 {
209   struct fun_cookie_s *cookie = cookie_arg;
210
211   if (cookie->fd != -1 && cookie->fd != 2)
212     close (cookie->fd);
213   jnlib_free (cookie);
214   log_socket = -1;
215   return 0;
216 }
217
218
219 /* Common function to either set the logging to a file or a file
220    descriptor. */
221 static void
222 set_file_fd (const char *name, int fd) 
223 {
224   estream_t fp;
225   int want_socket;
226   struct fun_cookie_s *cookie;
227
228   /* Close an open log stream.  */
229   if (logstream)
230     {
231       es_fclose (logstream);
232       logstream = NULL;
233     }
234
235   /* Figure out what kind of logging we want.  */
236   if (name && !strcmp (name, "-"))
237     {
238       name = NULL;
239       fd = fileno (stderr);
240     }
241
242   if (name)
243     {
244       want_socket = (!strncmp (name, "socket://", 9) && name[9]);
245       if (want_socket)
246         name += 9;
247     }
248   else
249     {
250       want_socket = 0;
251     }
252
253   /* Setup a new stream.  */
254
255   /* The xmalloc below is justified because we can expect that this
256      function is called only during initialization and there is no
257      easy way out of this error condition.  */
258   cookie = jnlib_xmalloc (sizeof *cookie + (name? strlen (name):0));
259   strcpy (cookie->name, name? name:"");
260   cookie->quiet = 0;
261   cookie->is_socket = 0;
262   cookie->want_socket = want_socket;
263   if (!name)
264     cookie->fd = fd;
265   else if (want_socket)
266     cookie->fd = -1;
267   else
268     {
269       do
270         cookie->fd = open (name, O_WRONLY|O_APPEND|O_CREAT,
271                            (S_IRUSR|S_IRGRP|S_IROTH|S_IWUSR|S_IWGRP|S_IWOTH));
272       while (cookie->fd == -1 && errno == EINTR);
273     }
274   log_socket = cookie->fd;
275
276   {
277     es_cookie_io_functions_t io = { NULL };
278     io.func_write = fun_writer;
279     io.func_close = fun_closer;
280     
281     fp = es_fopencookie (cookie, "w", io);
282   }
283
284   /* On error default to a stderr based estream.  */
285   if (!fp)
286     {
287       fp = es_fpopen (stderr, "a");
288       if (fp)
289         {
290           if (name)
291             es_fprintf (fp, "failed to open log file `%s': %s\n",
292                         name, strerror (errno));
293           else
294             es_fprintf (fp, "failed to fdopen file descriptor %d: %s\n",
295                         fd, strerror (errno));
296         }
297       else
298         {
299           fprintf (stderr, "failed to use stderr as log stream: %s\n",
300                    strerror (errno));
301           /* No way to log something.  Create a dummy estream so that
302              there is something we can use.  */
303           fp = es_fpopen (NULL, "a");
304           if (!fp)
305             {
306               fprintf (stderr, "fatal: failed to open dummy stream: %s\n",
307                        strerror (errno));
308               abort();
309             }
310         }
311     }
312
313   es_setvbuf (fp, NULL, _IOLBF, 0);
314   
315   logstream = fp;
316
317   /* We always need to print the prefix and the pid for socket mode,
318      so that the server reading the socket can do something
319      meaningful. */
320   force_prefixes = want_socket;
321
322   missing_lf = 0;
323 }
324
325
326 /* Set the file to write log to.  The special names NULL and "-" may
327    be used to select stderr and names formatted like
328    "socket:///home/foo/mylogs" may be used to write the logging to the
329    socket "/home/foo/mylogs".  If the connection to the socket fails
330    or a write error is detected, the function writes to stderr and
331    tries the next time again to connect the socket.
332   */
333 void
334 log_set_file (const char *name) 
335 {
336   set_file_fd (name? name: "-", -1);
337 }
338
339 void
340 log_set_fd (int fd)
341 {
342   set_file_fd (NULL, fd);
343 }
344
345
346 void
347 log_set_get_tid_callback (unsigned long (*cb)(void))
348 {
349   get_tid_callback = cb;
350 }
351
352
353 void
354 log_set_prefix (const char *text, unsigned int flags)
355 {
356   if (text)
357     {
358       strncpy (prefix_buffer, text, sizeof (prefix_buffer)-1);
359       prefix_buffer[sizeof (prefix_buffer)-1] = 0;
360     }
361   
362   with_prefix = (flags & JNLIB_LOG_WITH_PREFIX);
363   with_time = (flags & JNLIB_LOG_WITH_TIME);
364   with_pid  = (flags & JNLIB_LOG_WITH_PID);
365   running_detached = (flags & JNLIB_LOG_RUN_DETACHED);
366 }
367
368
369 const char *
370 log_get_prefix (unsigned int *flags)
371 {
372   if (flags)
373     {
374       *flags = 0;
375       if (with_prefix)
376         *flags |= JNLIB_LOG_WITH_PREFIX;
377       if (with_time)
378         *flags |= JNLIB_LOG_WITH_TIME;
379       if (with_pid)
380         *flags |= JNLIB_LOG_WITH_PID;
381       if (running_detached)
382         *flags |= JNLIB_LOG_RUN_DETACHED;
383     }
384   return prefix_buffer;
385 }
386
387 /* This function returns true if the file descriptor FD is in use for
388    logging.  This is preferable over a test using log_get_fd in that
389    it allows the logging code to use more then one file descriptor.  */
390 int
391 log_test_fd (int fd)
392 {
393   if (logstream)
394     {
395       int tmp = es_fileno (logstream);
396       if ( tmp != -1 && tmp == fd)
397         return 1;
398     }
399   if (log_socket != -1 && log_socket == fd)
400     return 1;
401   return 0;
402 }
403
404 int
405 log_get_fd ()
406 {
407   return logstream? es_fileno(logstream) : -1;
408 }
409
410 estream_t
411 log_get_stream ()
412 {
413   assert (logstream);
414   return logstream;
415 }
416
417 static void
418 do_logv (int level, int ignore_arg_ptr, const char *fmt, va_list arg_ptr)
419 {
420   if (!logstream)
421     {
422       log_set_file (NULL); /* Make sure a log stream has been set.  */
423       assert (logstream);
424     }
425
426   es_flockfile (logstream);
427   if (missing_lf && level != JNLIB_LOG_CONT)
428     es_putc_unlocked ('\n', logstream );
429   missing_lf = 0;
430
431   if (level != JNLIB_LOG_CONT)
432     { /* Note this does not work for multiple line logging as we would
433        * need to print to a buffer first */
434       if (with_time && !force_prefixes)
435         {
436           struct tm *tp;
437           time_t atime = time (NULL);
438           
439           tp = localtime (&atime);
440           es_fprintf_unlocked (logstream, "%04d-%02d-%02d %02d:%02d:%02d ",
441                                1900+tp->tm_year, tp->tm_mon+1, tp->tm_mday,
442                                tp->tm_hour, tp->tm_min, tp->tm_sec );
443         }
444       if (with_prefix || force_prefixes)
445         es_fputs_unlocked (prefix_buffer, logstream);
446       if (with_pid || force_prefixes)
447         {
448           if (get_tid_callback)
449             es_fprintf_unlocked (logstream, "[%u.%lx]", 
450                         (unsigned int)getpid (), get_tid_callback ());
451           else
452             es_fprintf_unlocked (logstream, "[%u]", (unsigned int)getpid ());
453         }
454       if (!with_time || force_prefixes)
455         es_putc_unlocked (':', logstream);
456       /* A leading backspace suppresses the extra space so that we can
457          correctly output, programname, filename and linenumber. */
458       if (fmt && *fmt == '\b')
459         fmt++;
460       else
461         es_putc_unlocked (' ', logstream);
462     }
463
464   switch (level)
465     {
466     case JNLIB_LOG_BEGIN: break;
467     case JNLIB_LOG_CONT: break;
468     case JNLIB_LOG_INFO: break;
469     case JNLIB_LOG_WARN: break;
470     case JNLIB_LOG_ERROR: break;
471     case JNLIB_LOG_FATAL: es_fputs_unlocked ("Fatal: ",logstream ); break;
472     case JNLIB_LOG_BUG:   es_fputs_unlocked ("Ohhhh jeeee: ", logstream); break;
473     case JNLIB_LOG_DEBUG: es_fputs_unlocked ("DBG: ", logstream ); break;
474     default: 
475       es_fprintf_unlocked (logstream,"[Unknown log level %d]: ", level);
476       break;
477     }
478
479   if (fmt)
480     {
481       if (ignore_arg_ptr)
482         es_fputs_unlocked (fmt, logstream);
483       else
484         es_vfprintf_unlocked (logstream, fmt, arg_ptr);
485       if (*fmt && fmt[strlen(fmt)-1] != '\n')
486         missing_lf = 1;
487     }
488
489   if (level == JNLIB_LOG_FATAL)
490     {
491       if (missing_lf)
492         es_putc_unlocked ('\n', logstream);
493       es_funlockfile (logstream);
494       exit (2);
495     }
496   else if (level == JNLIB_LOG_BUG)
497     {
498       if (missing_lf)
499         es_putc_unlocked ('\n', logstream );
500       es_funlockfile (logstream);
501       abort ();
502     }
503   else
504     es_funlockfile (logstream);
505 }
506
507
508 static void
509 do_log (int level, const char *fmt, ...)
510 {
511   va_list arg_ptr ;
512   
513   va_start (arg_ptr, fmt) ;
514   do_logv (level, 0, fmt, arg_ptr);
515   va_end (arg_ptr);
516 }
517
518
519 void
520 log_logv (int level, const char *fmt, va_list arg_ptr)
521 {
522   do_logv (level, 0, fmt, arg_ptr);
523 }
524
525
526 void
527 log_string (int level, const char *string)
528 {
529   /* We need to provide a dummy arg_ptr.  volatile is needed to
530      suppress compiler warnings.  */
531   volatile va_list dummy_arg_ptr;
532
533   do_logv (level, 1, string, dummy_arg_ptr);
534 }
535
536
537 void
538 log_info (const char *fmt, ...)
539 {
540   va_list arg_ptr ;
541   
542   va_start (arg_ptr, fmt);
543   do_logv (JNLIB_LOG_INFO, 0, fmt, arg_ptr);
544   va_end (arg_ptr);
545 }
546
547
548 void
549 log_error (const char *fmt, ...)
550 {
551   va_list arg_ptr ;
552   
553   va_start (arg_ptr, fmt);
554   do_logv (JNLIB_LOG_ERROR, 0, fmt, arg_ptr);
555   va_end (arg_ptr);
556   /* Protect against counter overflow.  */
557   if (errorcount < 30000)
558     errorcount++;
559 }
560
561
562 void
563 log_fatal (const char *fmt, ...)
564 {
565   va_list arg_ptr ;
566   
567   va_start (arg_ptr, fmt);
568   do_logv (JNLIB_LOG_FATAL, 0, fmt, arg_ptr);
569   va_end (arg_ptr);
570   abort (); /* Never called; just to make the compiler happy.  */
571 }
572
573
574 void
575 log_bug (const char *fmt, ...)
576 {
577   va_list arg_ptr ;
578
579   va_start (arg_ptr, fmt);
580   do_logv (JNLIB_LOG_BUG, 0, fmt, arg_ptr);
581   va_end (arg_ptr);
582   abort (); /* Never called; just to make the compiler happy.  */
583 }
584
585
586 void
587 log_debug (const char *fmt, ...)
588 {
589   va_list arg_ptr ;
590   
591   va_start (arg_ptr, fmt);
592   do_logv (JNLIB_LOG_DEBUG, 0, fmt, arg_ptr);
593   va_end (arg_ptr);
594 }
595
596
597 void
598 log_printf (const char *fmt, ...)
599 {
600   va_list arg_ptr;
601   
602   va_start (arg_ptr, fmt);
603   do_logv (fmt ? JNLIB_LOG_CONT : JNLIB_LOG_BEGIN, 0, fmt, arg_ptr);
604   va_end (arg_ptr);
605 }
606
607
608 /* Print a hexdump of BUFFER.  With TEXT of NULL print just the raw
609    dump, with TEXT just an empty string, print a trailing linefeed,
610    otherwise print an entire debug line. */
611 void
612 log_printhex (const char *text, const void *buffer, size_t length)
613 {
614   if (text && *text)
615     log_debug ("%s ", text);
616   if (length)
617     {
618       const unsigned char *p = buffer;
619       log_printf ("%02X", *p);
620       for (length--, p++; length--; p++)
621         log_printf (" %02X", *p);
622     }
623   if (text)
624     log_printf ("\n");
625 }
626
627
628 #if __GNUC__ > 2 || (__GNUC__ == 2 && __GNUC_MINOR__ >= 5 )
629 void
630 bug_at( const char *file, int line, const char *func )
631 {
632   do_log (JNLIB_LOG_BUG, ("... this is a bug (%s:%d:%s)\n"), file, line, func);
633   abort (); /* Never called; just to make the compiler happy.  */
634 }
635 #else
636 void
637 bug_at( const char *file, int line )
638 {
639   do_log (JNLIB_LOG_BUG, _("you found a bug ... (%s:%d)\n"), file, line);
640   abort (); /* Never called; just to make the compiler happy.  */
641 }
642 #endif
643