1 /* logging.c - Useful logging functions
2 * Copyright (C) 1998, 1999, 2000, 2001, 2003, 2004, 2005, 2006,
3 * 2009, 2010 Free Software Foundation, Inc.
5 * This file is part of GnuPG.
7 * GnuPG is free software; you can redistribute it and/or modify it
8 * under the terms of either
10 * - the GNU Lesser General Public License as published by the Free
11 * Software Foundation; either version 3 of the License, or (at
12 * your option) any later version.
16 * - the GNU General Public License as published by the Free
17 * Software Foundation; either version 2 of the License, or (at
18 * your option) any later version.
20 * or both in parallel, as here.
22 * GnuPG is distributed in the hope that it will be useful, but
23 * WITHOUT ANY WARRANTY; without even the implied warranty of
24 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
25 * General Public License for more details.
27 * You should have received a copies of the GNU General Public License
28 * and the GNU Lesser General Public License along with this program;
29 * if not, see <https://www.gnu.org/licenses/>.
41 #include <sys/types.h>
43 #ifdef HAVE_W32_SYSTEM
44 # ifdef HAVE_WINSOCK2_H
45 # include <winsock2.h>
48 #else /*!HAVE_W32_SYSTEM*/
49 # include <sys/socket.h>
51 # include <netinet/in.h>
52 # include <arpa/inet.h>
53 #endif /*!HAVE_W32_SYSTEM*/
57 /* #include <execinfo.h> */
59 #define GNUPG_COMMON_NEED_AFLOCAL 1
62 #include "common-defs.h"
65 #ifdef HAVE_W32_SYSTEM
66 # define S_IRGRP S_IRUSR
67 # define S_IROTH S_IRUSR
68 # define S_IWGRP S_IWUSR
69 # define S_IWOTH S_IWUSR
73 #ifdef HAVE_W32CE_SYSTEM
74 # define isatty(a) (0)
78 #if defined (AF_INET6) && defined(PF_INET) \
79 && defined (INET6_ADDRSTRLEN) && defined(HAVE_INET_PTON)
84 # define EAFNOSUPPORT EINVAL
86 #ifndef INADDR_NONE /* Slowaris is missing that. */
87 #define INADDR_NONE ((unsigned long)(-1))
88 #endif /*INADDR_NONE*/
90 #ifdef HAVE_W32_SYSTEM
91 #define sock_close(a) closesocket(a)
93 #define sock_close(a) close(a)
97 static estream_t logstream;
98 static int log_socket = -1;
99 static char prefix_buffer[80];
100 static int with_time;
101 static int with_prefix;
103 #ifdef HAVE_W32_SYSTEM
104 static int no_registry;
106 static int (*get_pid_suffix_cb)(unsigned long *r_value);
107 static const char * (*socket_dir_cb)(void);
108 static int running_detached;
109 static int force_prefixes;
111 static int missing_lf;
112 static int errorcount;
116 log_get_errorcount (int clear)
125 log_inc_errorcount (void)
131 /* The following 3 functions are used by es_fopencookie to write logs
139 #ifdef HAVE_W32CE_SYSTEM
146 /* Write NBYTES of BUFFER to file descriptor FD. */
148 writen (int fd, const void *buffer, size_t nbytes, int is_socket)
150 const char *buf = buffer;
151 size_t nleft = nbytes;
153 #ifndef HAVE_W32_SYSTEM
154 (void)is_socket; /* Not required. */
159 #ifdef HAVE_W32_SYSTEM
161 nwritten = send (fd, buf, nleft, 0);
164 nwritten = write (fd, buf, nleft);
166 if (nwritten < 0 && errno == EINTR)
171 buf = buf + nwritten;
178 /* Returns true if STR represents a valid port number in decimal
179 notation and no garbage is following. */
181 parse_portno (const char *str, unsigned short *r_port)
185 for (value=0; *str && (*str >= '0' && *str <= '9'); str++)
187 value = value * 10 + (*str - '0');
200 fun_writer (void *cookie_arg, const void *buffer, size_t size)
202 struct fun_cookie_s *cookie = cookie_arg;
204 /* FIXME: Use only estream with a callback for socket writing. This
205 avoids the ugly mix of fd and estream code. */
207 /* Note that we always try to reconnect to the socket but print
208 error messages only the first time an error occurred. If
209 RUNNING_DETACHED is set we don't fall back to stderr and even do
210 not print any error messages. This is needed because detached
211 processes often close stderr and by writing to file descriptor 2
212 we might send the log message to a file not intended for logging
213 (e.g. a pipe or network connection). */
214 if (cookie->want_socket && cookie->fd == -1)
217 struct sockaddr_in6 srvr_addr_in6;
219 struct sockaddr_in srvr_addr_in;
220 #ifndef HAVE_W32_SYSTEM
221 struct sockaddr_un srvr_addr_un;
223 const char *name_for_err = "";
225 struct sockaddr *srvr_addr = NULL;
226 unsigned short port = 0;
229 const char *name = cookie->name;
231 /* Not yet open or meanwhile closed due to an error. */
232 cookie->is_socket = 0;
234 /* Check whether this is a TCP socket or a local socket. */
235 if (!strncmp (name, "tcp://", 6) && name[6])
241 #ifndef HAVE_W32_SYSTEM
242 else if (!strncmp (name, "socket://", 9))
249 #ifndef HAVE_W32_SYSTEM
250 memset (&srvr_addr, 0, sizeof srvr_addr);
251 srvr_addr_un.sun_family = af;
252 if (!*name && (name = socket_dir_cb ()) && *name)
254 if (strlen (name) + 7 < sizeof (srvr_addr_un.sun_path)-1)
256 strncpy (srvr_addr_un.sun_path,
257 name, sizeof (srvr_addr_un.sun_path)-1);
258 strcat (srvr_addr_un.sun_path, "/S.log");
259 srvr_addr_un.sun_path[sizeof (srvr_addr_un.sun_path)-1] = 0;
260 srvr_addr = (struct sockaddr *)&srvr_addr_un;
261 addrlen = SUN_LEN (&srvr_addr_un);
262 name_for_err = srvr_addr_un.sun_path;
267 if (*name && strlen (name) < sizeof (srvr_addr_un.sun_path)-1)
269 strncpy (srvr_addr_un.sun_path,
270 name, sizeof (srvr_addr_un.sun_path)-1);
271 srvr_addr_un.sun_path[sizeof (srvr_addr_un.sun_path)-1] = 0;
272 srvr_addr = (struct sockaddr *)&srvr_addr_un;
273 addrlen = SUN_LEN (&srvr_addr_un);
276 #endif /*!HAVE_W32SYSTEM*/
281 #ifdef HAVE_INET_PTON
282 void *addrbuf = NULL;
283 #endif /*HAVE_INET_PTON*/
285 addrstr = xtrymalloc (strlen (name) + 1);
287 addrlen = 0; /* This indicates an error. */
288 else if (*name == '[')
290 /* Check for IPv6 literal address. */
291 strcpy (addrstr, name+1);
292 p = strchr (addrstr, ']');
293 if (!p || p[1] != ':' || !parse_portno (p+2, &port))
295 gpg_err_set_errno (EINVAL);
304 memset (&srvr_addr_in6, 0, sizeof srvr_addr_in6);
305 srvr_addr_in6.sin6_family = af;
306 srvr_addr_in6.sin6_port = htons (port);
307 #ifdef HAVE_INET_PTON
308 addrbuf = &srvr_addr_in6.sin6_addr;
309 #endif /*HAVE_INET_PTON*/
310 srvr_addr = (struct sockaddr *)&srvr_addr_in6;
311 addrlen = sizeof srvr_addr_in6;
313 gpg_err_set_errno (EAFNOSUPPORT);
320 /* Check for IPv4 literal address. */
321 strcpy (addrstr, name);
322 p = strchr (addrstr, ':');
323 if (!p || !parse_portno (p+1, &port))
325 gpg_err_set_errno (EINVAL);
331 memset (&srvr_addr_in, 0, sizeof srvr_addr_in);
332 srvr_addr_in.sin_family = af;
333 srvr_addr_in.sin_port = htons (port);
334 #ifdef HAVE_INET_PTON
335 addrbuf = &srvr_addr_in.sin_addr;
336 #endif /*HAVE_INET_PTON*/
337 srvr_addr = (struct sockaddr *)&srvr_addr_in;
338 addrlen = sizeof srvr_addr_in;
344 #ifdef HAVE_INET_PTON
345 if (inet_pton (af, addrstr, addrbuf) != 1)
347 #else /*!HAVE_INET_PTON*/
348 /* We need to use the old function. If we are here v6
349 support isn't enabled anyway and thus we can do fine
350 without. Note that Windows has a compatible inet_pton
351 function named inetPton, but only since Vista. */
352 srvr_addr_in.sin_addr.s_addr = inet_addr (addrstr);
353 if (srvr_addr_in.sin_addr.s_addr == INADDR_NONE)
355 #endif /*!HAVE_INET_PTON*/
361 cookie->fd = addrlen? socket (pf, SOCK_STREAM, 0) : -1;
362 if (cookie->fd == -1)
364 if (!cookie->quiet && !running_detached
365 && isatty (es_fileno (es_stderr)))
366 es_fprintf (es_stderr, "failed to create socket for logging: %s\n",
371 if (connect (cookie->fd, srvr_addr, addrlen) == -1)
373 if (!cookie->quiet && !running_detached
374 && isatty (es_fileno (es_stderr)))
375 es_fprintf (es_stderr, "can't connect to '%s%s': %s\n",
376 cookie->name, name_for_err, strerror(errno));
377 sock_close (cookie->fd);
382 if (cookie->fd == -1)
384 if (!running_detached)
386 /* Due to all the problems with apps not running
387 detached but being called with stderr closed or used
388 for a different purposes, it does not make sense to
389 switch to stderr. We therefore disable it. */
392 /* fputs ("switching logging to stderr\n", stderr);*/
395 cookie->fd = -1; /*fileno (stderr);*/
398 else /* Connection has been established. */
401 cookie->is_socket = 1;
405 log_socket = cookie->fd;
406 if (cookie->fd != -1)
408 #ifdef HAVE_W32CE_SYSTEM
409 if (cookie->use_writefile)
413 WriteFile ((HANDLE)cookie->fd, buffer, size, &nwritten, NULL);
414 return (gpgrt_ssize_t)size; /* Okay. */
417 if (!writen (cookie->fd, buffer, size, cookie->is_socket))
418 return (gpgrt_ssize_t)size; /* Okay. */
421 if (!running_detached && cookie->fd != -1
422 && isatty (es_fileno (es_stderr)))
425 es_fprintf (es_stderr, "error writing to '%s': %s\n",
426 cookie->name, strerror(errno));
428 es_fprintf (es_stderr, "error writing to file descriptor %d: %s\n",
429 cookie->fd, strerror(errno));
431 if (cookie->is_socket && cookie->fd != -1)
433 sock_close (cookie->fd);
438 return (gpgrt_ssize_t)size;
443 fun_closer (void *cookie_arg)
445 struct fun_cookie_s *cookie = cookie_arg;
447 if (cookie->fd != -1 && cookie->fd != 2)
448 sock_close (cookie->fd);
455 /* Common function to either set the logging to a file or a file
458 set_file_fd (const char *name, int fd)
462 #ifdef HAVE_W32CE_SYSTEM
463 int use_writefile = 0;
465 struct fun_cookie_s *cookie;
467 /* Close an open log stream. */
470 es_fclose (logstream);
474 /* Figure out what kind of logging we want. */
475 if (name && !strcmp (name, "-"))
478 fd = es_fileno (es_stderr);
482 if (name && !strncmp (name, "tcp://", 6) && name[6])
484 #ifndef HAVE_W32_SYSTEM
485 else if (name && !strncmp (name, "socket://", 9))
487 #endif /*HAVE_W32_SYSTEM*/
488 #ifdef HAVE_W32CE_SYSTEM
489 else if (name && !strcmp (name, "GPG2:"))
493 ActivateDevice (L"Drivers\\"GNUPG_NAME"_Log", 0);
494 /* Ignore a filename and write the debug output to the GPG2:
496 hd = CreateFile (L"GPG2:", GENERIC_WRITE,
497 FILE_SHARE_READ | FILE_SHARE_WRITE,
498 NULL, OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL, NULL);
499 fd = (hd == INVALID_HANDLE_VALUE)? -1 : (int)hd;
504 #endif /*HAVE_W32CE_SYSTEM*/
506 /* Setup a new stream. */
508 /* The xmalloc below is justified because we can expect that this
509 function is called only during initialization and there is no
510 easy way out of this error condition. */
511 cookie = xmalloc (sizeof *cookie + (name? strlen (name):0));
512 strcpy (cookie->name, name? name:"");
514 cookie->is_socket = 0;
515 cookie->want_socket = want_socket;
516 #ifdef HAVE_W32CE_SYSTEM
517 cookie->use_writefile = use_writefile;
521 else if (want_socket)
526 cookie->fd = open (name, O_WRONLY|O_APPEND|O_CREAT,
527 (S_IRUSR|S_IRGRP|S_IROTH|S_IWUSR|S_IWGRP|S_IWOTH));
528 while (cookie->fd == -1 && errno == EINTR);
530 log_socket = cookie->fd;
533 es_cookie_io_functions_t io = { NULL };
534 io.func_write = fun_writer;
535 io.func_close = fun_closer;
537 fp = es_fopencookie (cookie, "w", io);
540 /* On error default to a stderr based estream. */
544 es_setvbuf (fp, NULL, _IOLBF, 0);
548 /* We always need to print the prefix and the pid for socket mode,
549 so that the server reading the socket can do something
551 force_prefixes = want_socket;
557 /* Set the file to write log to. The special names NULL and "-" may
558 be used to select stderr and names formatted like
559 "socket:///home/foo/mylogs" may be used to write the logging to the
560 socket "/home/foo/mylogs". If the connection to the socket fails
561 or a write error is detected, the function writes to stderr and
562 tries the next time again to connect the socket.
565 log_set_file (const char *name)
567 set_file_fd (name? name: "-", -1);
573 set_file_fd (NULL, fd);
577 /* Set a function to retrieve the directory name of a socket if
578 * only "socket://" has been given to log_set_file. */
580 log_set_socket_dir_cb (const char *(*fnc)(void))
587 log_set_pid_suffix_cb (int (*cb)(unsigned long *r_value))
589 get_pid_suffix_cb = cb;
594 log_set_prefix (const char *text, unsigned int flags)
598 strncpy (prefix_buffer, text, sizeof (prefix_buffer)-1);
599 prefix_buffer[sizeof (prefix_buffer)-1] = 0;
602 with_prefix = (flags & GPGRT_LOG_WITH_PREFIX);
603 with_time = (flags & GPGRT_LOG_WITH_TIME);
604 with_pid = (flags & GPGRT_LOG_WITH_PID);
605 running_detached = (flags & GPGRT_LOG_RUN_DETACHED);
606 #ifdef HAVE_W32_SYSTEM
607 no_registry = (flags & GPGRT_LOG_NO_REGISTRY);
613 log_get_prefix (unsigned int *flags)
619 *flags |= GPGRT_LOG_WITH_PREFIX;
621 *flags |= GPGRT_LOG_WITH_TIME;
623 *flags |= GPGRT_LOG_WITH_PID;
624 if (running_detached)
625 *flags |= GPGRT_LOG_RUN_DETACHED;
626 #ifdef HAVE_W32_SYSTEM
628 *flags |= GPGRT_LOG_NO_REGISTRY;
631 return prefix_buffer;
634 /* This function returns true if the file descriptor FD is in use for
635 logging. This is preferable over a test using log_get_fd in that
636 it allows the logging code to use more then one file descriptor. */
642 int tmp = es_fileno (logstream);
643 if ( tmp != -1 && tmp == fd)
646 if (log_socket != -1 && log_socket == fd)
654 return logstream? es_fileno(logstream) : -1;
662 log_set_file (NULL); /* Make sure a log stream has been set. */
669 do_logv (int level, int ignore_arg_ptr, const char *fmt, va_list arg_ptr)
673 #ifdef HAVE_W32_SYSTEM
678 : read_w32_registry_string (NULL, GNUPG_REGISTRY_DIR,
680 log_set_file (tmp && *tmp? tmp : NULL);
683 log_set_file (NULL); /* Make sure a log stream has been set. */
688 es_flockfile (logstream);
689 if (missing_lf && level != GPGRT_LOG_CONT)
690 es_putc_unlocked ('\n', logstream );
693 if (level != GPGRT_LOG_CONT)
694 { /* Note this does not work for multiple line logging as we would
695 * need to print to a buffer first */
696 if (with_time && !force_prefixes)
699 time_t atime = time (NULL);
701 tp = localtime (&atime);
702 es_fprintf_unlocked (logstream, "%04d-%02d-%02d %02d:%02d:%02d ",
703 1900+tp->tm_year, tp->tm_mon+1, tp->tm_mday,
704 tp->tm_hour, tp->tm_min, tp->tm_sec );
706 if (with_prefix || force_prefixes)
707 es_fputs_unlocked (prefix_buffer, logstream);
708 if (with_pid || force_prefixes)
710 unsigned long pidsuf;
713 if (get_pid_suffix_cb && (pidfmt=get_pid_suffix_cb (&pidsuf)))
714 es_fprintf_unlocked (logstream, pidfmt == 1? "[%u.%lu]":"[%u.%lx]",
715 (unsigned int)getpid (), pidsuf);
717 es_fprintf_unlocked (logstream, "[%u]", (unsigned int)getpid ());
719 if ((!with_time && (with_prefix || with_pid)) || force_prefixes)
720 es_putc_unlocked (':', logstream);
721 /* A leading backspace suppresses the extra space so that we can
722 correctly output, programname, filename and linenumber. */
723 if (fmt && *fmt == '\b')
726 if (with_time || with_prefix || with_pid || force_prefixes)
727 es_putc_unlocked (' ', logstream);
732 case GPGRT_LOG_BEGIN: break;
733 case GPGRT_LOG_CONT: break;
734 case GPGRT_LOG_INFO: break;
735 case GPGRT_LOG_WARN: break;
736 case GPGRT_LOG_ERROR: break;
737 case GPGRT_LOG_FATAL: es_fputs_unlocked ("Fatal: ",logstream ); break;
738 case GPGRT_LOG_BUG: es_fputs_unlocked ("Ohhhh jeeee: ", logstream); break;
739 case GPGRT_LOG_DEBUG: es_fputs_unlocked ("DBG: ", logstream ); break;
741 es_fprintf_unlocked (logstream,"[Unknown log level %d]: ", level);
748 { /* This is used by log_string and comes with the extra
749 * feature that after a LF the next line is indent at the
750 * length of the prefix. Note that we do not yet include
751 * the length of the timestamp and pid in the indent
753 const char *p, *pend;
755 for (p = fmt; (pend = strchr (p, '\n')); p = pend+1)
756 es_fprintf_unlocked (logstream, "%*s%.*s",
758 && (with_prefix || force_prefixes))
759 ?strlen (prefix_buffer)+2:0), "",
760 (int)(pend - p)+1, p);
761 es_fputs_unlocked (p, logstream);
764 es_vfprintf_unlocked (logstream, fmt, arg_ptr);
765 if (*fmt && fmt[strlen(fmt)-1] != '\n')
769 if (level == GPGRT_LOG_FATAL)
772 es_putc_unlocked ('\n', logstream);
773 es_funlockfile (logstream);
776 else if (level == GPGRT_LOG_BUG)
779 es_putc_unlocked ('\n', logstream );
780 es_funlockfile (logstream);
781 /* Using backtrace requires a configure test and to pass
782 * -rdynamic to gcc. Thus we do not enable it now. */
784 /* void *btbuf[20]; */
785 /* int btidx, btlen; */
788 /* btlen = backtrace (btbuf, DIM (btbuf)); */
789 /* btstr = backtrace_symbols (btbuf, btlen); */
791 /* for (btidx=0; btidx < btlen; btidx++) */
792 /* log_debug ("[%d] %s\n", btidx, btstr[btidx]); */
797 es_funlockfile (logstream);
802 log_log (int level, const char *fmt, ...)
806 va_start (arg_ptr, fmt) ;
807 do_logv (level, 0, fmt, arg_ptr);
813 log_logv (int level, const char *fmt, va_list arg_ptr)
815 do_logv (level, 0, fmt, arg_ptr);
820 do_log_ignore_arg (int level, const char *str, ...)
823 va_start (arg_ptr, str);
824 do_logv (level, 1, str, arg_ptr);
829 /* Log STRING at LEVEL but indent from the second line on by the
830 * length of the prefix. */
832 log_string (int level, const char *string)
834 /* We need a dummy arg_ptr, but there is no portable way to create
835 * one. So we call the do_logv function through a variadic wrapper. */
836 do_log_ignore_arg (level, string);
841 log_info (const char *fmt, ...)
845 va_start (arg_ptr, fmt);
846 do_logv (GPGRT_LOG_INFO, 0, fmt, arg_ptr);
852 log_error (const char *fmt, ...)
856 va_start (arg_ptr, fmt);
857 do_logv (GPGRT_LOG_ERROR, 0, fmt, arg_ptr);
859 /* Protect against counter overflow. */
860 if (errorcount < 30000)
866 log_fatal (const char *fmt, ...)
870 va_start (arg_ptr, fmt);
871 do_logv (GPGRT_LOG_FATAL, 0, fmt, arg_ptr);
873 abort (); /* Never called; just to make the compiler happy. */
878 log_bug (const char *fmt, ...)
882 va_start (arg_ptr, fmt);
883 do_logv (GPGRT_LOG_BUG, 0, fmt, arg_ptr);
885 abort (); /* Never called; just to make the compiler happy. */
890 log_debug (const char *fmt, ...)
894 va_start (arg_ptr, fmt);
895 do_logv (GPGRT_LOG_DEBUG, 0, fmt, arg_ptr);
901 log_printf (const char *fmt, ...)
905 va_start (arg_ptr, fmt);
906 do_logv (fmt ? GPGRT_LOG_CONT : GPGRT_LOG_BEGIN, 0, fmt, arg_ptr);
911 /* Flush the log - this is useful to make sure that the trailing
912 linefeed has been printed. */
916 do_log_ignore_arg (GPGRT_LOG_CONT, NULL);
920 /* Print a hexdump of BUFFER. With TEXT of NULL print just the raw
921 dump, with TEXT just an empty string, print a trailing linefeed,
922 otherwise print an entire debug line. */
924 log_printhex (const char *text, const void *buffer, size_t length)
927 log_debug ("%s ", text);
930 const unsigned char *p = buffer;
931 log_printf ("%02X", *p);
932 for (length--, p++; length--; p++)
933 log_printf (" %02X", *p);
943 is found in sexputils.c
949 is found in sexputils.c
954 log_clock (const char *string)
957 static unsigned long long initial;
959 unsigned long long now;
961 if (clock_gettime (CLOCK_REALTIME, &tv))
963 log_debug ("error getting the realtime clock value\n");
966 now = tv.tv_sec * 1000000000ull;
972 log_debug ("[%6llu] %s", (now - initial)/1000, string);
974 /* You need to link with -ltr to enable the above code. */
975 log_debug ("[not enabled in the source] %s", string);
980 #ifdef GPGRT_HAVE_MACRO_FUNCTION
982 bug_at( const char *file, int line, const char *func )
984 log_log (GPGRT_LOG_BUG, "... this is a bug (%s:%d:%s)\n", file, line, func);
985 abort (); /* Never called; just to make the compiler happy. */
987 #else /*!GPGRT_HAVE_MACRO_FUNCTION*/
989 bug_at( const char *file, int line )
991 log_log (GPGRT_LOG_BUG, "you found a bug ... (%s:%d)\n", file, line);
992 abort (); /* Never called; just to make the compiler happy. */
994 #endif /*!GPGRT_HAVE_MACRO_FUNCTION*/
997 #ifdef GPGRT_HAVE_MACRO_FUNCTION
999 _log_assert (const char *expr, const char *file, int line, const char *func)
1001 log_log (GPGRT_LOG_BUG, "Assertion \"%s\" in %s failed (%s:%d)\n",
1002 expr, func, file, line);
1003 abort (); /* Never called; just to make the compiler happy. */
1005 #else /*!GPGRT_HAVE_MACRO_FUNCTION*/
1007 _log_assert (const char *expr, const char *file, int line)
1009 log_log (GPGRT_LOG_BUG, "Assertion \"%s\" failed (%s:%d)\n",
1011 abort (); /* Never called; just to make the compiler happy. */
1013 #endif /*!GPGRT_HAVE_MACRO_FUNCTION*/