i3
src/log.c
Go to the documentation of this file.
00001 /*
00002  * vim:ts=4:sw=4:expandtab
00003  *
00004  * i3 - an improved dynamic tiling window manager
00005  * © 2009-2011 Michael Stapelberg and contributors (see also: LICENSE)
00006  *
00007  * log.c: Setting of loglevels, logging functions.
00008  *
00009  */
00010 #include <stdarg.h>
00011 #include <stdio.h>
00012 #include <string.h>
00013 #include <stdbool.h>
00014 #include <stdlib.h>
00015 #include <sys/time.h>
00016 #include <unistd.h>
00017 #include <fcntl.h>
00018 #include <sys/mman.h>
00019 #include <sys/stat.h>
00020 #include <errno.h>
00021 
00022 #include "util.h"
00023 #include "log.h"
00024 #include "i3.h"
00025 #include "libi3.h"
00026 #include "shmlog.h"
00027 
00028 /* loglevels.h is autogenerated at make time */
00029 #include "loglevels.h"
00030 
00031 static uint64_t loglevel = 0;
00032 static bool verbose = false;
00033 static FILE *errorfile;
00034 char *errorfilename;
00035 
00036 /* SHM logging variables */
00037 
00038 /* The name for the SHM (/i3-log-%pid). Will end up on /dev/shm on most
00039  * systems. Global so that we can clean up at exit. */
00040 char *shmlogname = "";
00041 /* Size limit for the SHM log, by default 25 MiB. Can be overwritten using the
00042  * flag --shmlog-size. */
00043 int shmlog_size = 0;
00044 /* If enabled, logbuffer will point to a memory mapping of the i3 SHM log. */
00045 static char *logbuffer;
00046 /* A pointer (within logbuffer) where data will be written to next. */
00047 static char *logwalk;
00048 /* A pointer to the byte where we last wrapped. Necessary to not print the
00049  * left-overs at the end of the ringbuffer. */
00050 static char *loglastwrap;
00051 /* Size (in bytes) of the i3 SHM log. */
00052 static int logbuffer_size;
00053 /* File descriptor for shm_open. */
00054 static int logbuffer_shm;
00055 
00056 /*
00057  * Writes the offsets for the next write and for the last wrap to the
00058  * shmlog_header.
00059  * Necessary to print the i3 SHM log in the correct order.
00060  *
00061  */
00062 static void store_log_markers(void) {
00063     i3_shmlog_header *header = (i3_shmlog_header*)logbuffer;
00064 
00065     header->offset_next_write = (logwalk - logbuffer);
00066     header->offset_last_wrap = (loglastwrap - logbuffer);
00067     header->size = logbuffer_size;
00068 }
00069 
00070 /*
00071  * Initializes logging by creating an error logfile in /tmp (or
00072  * XDG_RUNTIME_DIR, see get_process_filename()).
00073  *
00074  * Will be called twice if --shmlog-size is specified.
00075  *
00076  */
00077 void init_logging(void) {
00078     if (!errorfilename) {
00079         if (!(errorfilename = get_process_filename("errorlog")))
00080             ELOG("Could not initialize errorlog\n");
00081         else {
00082             errorfile = fopen(errorfilename, "w");
00083             if (fcntl(fileno(errorfile), F_SETFD, FD_CLOEXEC)) {
00084                 ELOG("Could not set close-on-exec flag\n");
00085             }
00086         }
00087     }
00088 
00089     /* If this is a debug build (not a release version), we will enable SHM
00090      * logging by default, unless the user turned it off explicitly. */
00091     if (logbuffer == NULL && shmlog_size > 0) {
00092         /* Reserve 1% of the RAM for the logfile, but at max 25 MiB.
00093          * For 512 MiB of RAM this will lead to a 5 MiB log buffer.
00094          * At the moment (2011-12-10), no testcase leads to an i3 log
00095          * of more than ~ 600 KiB. */
00096         long long physical_mem_bytes = (long long)sysconf(_SC_PHYS_PAGES) *
00097                                                   sysconf(_SC_PAGESIZE);
00098         logbuffer_size = min(physical_mem_bytes * 0.01, shmlog_size);
00099         sasprintf(&shmlogname, "/i3-log-%d", getpid());
00100         logbuffer_shm = shm_open(shmlogname, O_RDWR | O_CREAT | O_TRUNC, S_IREAD | S_IWRITE);
00101         if (logbuffer_shm == -1) {
00102             ELOG("Could not shm_open SHM segment for the i3 log: %s\n", strerror(errno));
00103             return;
00104         }
00105 
00106         if (ftruncate(logbuffer_shm, logbuffer_size) == -1) {
00107             close(logbuffer_shm);
00108             shm_unlink("/i3-log-");
00109             ELOG("Could not ftruncate SHM segment for the i3 log: %s\n", strerror(errno));
00110             return;
00111         }
00112 
00113         logbuffer = mmap(NULL, logbuffer_size, PROT_READ | PROT_WRITE, MAP_SHARED, logbuffer_shm, 0);
00114         if (logbuffer == MAP_FAILED) {
00115             close(logbuffer_shm);
00116             shm_unlink("/i3-log-");
00117             ELOG("Could not mmap SHM segment for the i3 log: %s\n", strerror(errno));
00118             logbuffer = NULL;
00119             return;
00120         }
00121         logwalk = logbuffer + sizeof(i3_shmlog_header);
00122         loglastwrap = logbuffer + logbuffer_size;
00123         store_log_markers();
00124     }
00125 }
00126 
00127 /*
00128  * Set verbosity of i3. If verbose is set to true, informative messages will
00129  * be printed to stdout. If verbose is set to false, only errors will be
00130  * printed.
00131  *
00132  */
00133 void set_verbosity(bool _verbose) {
00134     verbose = _verbose;
00135 }
00136 
00137 /*
00138  * Enables the given loglevel.
00139  *
00140  */
00141 void add_loglevel(const char *level) {
00142     /* Handle the special loglevel "all" */
00143     if (strcasecmp(level, "all") == 0) {
00144         loglevel = UINT64_MAX;
00145         return;
00146     }
00147 
00148     for (int i = 0; i < sizeof(loglevels) / sizeof(char*); i++) {
00149         if (strcasecmp(loglevels[i], level) != 0)
00150             continue;
00151 
00152         /* The position in the array (plus one) is the amount of times
00153          * which we need to shift 1 to the left to get our bitmask for
00154          * the specific loglevel. */
00155         loglevel |= (1 << (i+1));
00156         break;
00157     }
00158 }
00159 
00160 /*
00161  * Logs the given message to stdout (if print is true) while prefixing the
00162  * current time to it. Additionally, the message will be saved in the i3 SHM
00163  * log if enabled.
00164  * This is to be called by *LOG() which includes filename/linenumber/function.
00165  *
00166  */
00167 static void vlog(const bool print, const char *fmt, va_list args) {
00168     /* Precisely one page to not consume too much memory but to hold enough
00169      * data to be useful. */
00170     static char message[4096];
00171     static struct tm result;
00172     static time_t t;
00173     static struct tm *tmp;
00174     static size_t len;
00175 
00176     /* Get current time */
00177     t = time(NULL);
00178     /* Convert time to local time (determined by the locale) */
00179     tmp = localtime_r(&t, &result);
00180     /* Generate time prefix */
00181     len = strftime(message, sizeof(message), "%x %X - ", tmp);
00182 
00183     /*
00184      * logbuffer  print
00185      * ----------------
00186      *  true      true   format message, save, print
00187      *  true      false  format message, save
00188      *  false     true   print message only
00189      *  false     false  INVALID, never called
00190      */
00191     if (!logbuffer) {
00192 #ifdef DEBUG_TIMING
00193         struct timeval tv;
00194         gettimeofday(&tv, NULL);
00195         printf("%s%d.%d - ", message, tv.tv_sec, tv.tv_usec);
00196 #else
00197         printf("%s", message);
00198 #endif
00199         vprintf(fmt, args);
00200     } else {
00201         len += vsnprintf(message + len, sizeof(message) - len, fmt, args);
00202         if (len < 0 ) {
00203             fprintf(stderr, "BUG: something is overflowing here. Dropping the log entry\n");
00204             return;
00205         }
00206 
00207         if (len >= sizeof(message)) {
00208             fprintf(stderr, "BUG: single log message > 4k\n");
00209         }
00210 
00211         /* If there is no space for the current message (plus trailing
00212          * nullbyte) in the ringbuffer, we need to wrap and write to the
00213          * beginning again. */
00214         if ((len+1) >= (logbuffer_size - (logwalk - logbuffer))) {
00215             loglastwrap = logwalk;
00216             logwalk = logbuffer + sizeof(i3_shmlog_header);
00217         }
00218 
00219         /* Copy the buffer, terminate it, move the write pointer to the byte after
00220          * our current message. */
00221         strncpy(logwalk, message, len);
00222         logwalk[len] = '\0';
00223         logwalk += len + 1;
00224 
00225         store_log_markers();
00226 
00227         if (print)
00228             fwrite(message, len, 1, stdout);
00229     }
00230 }
00231 
00232 /*
00233  * Logs the given message to stdout while prefixing the current time to it,
00234  * but only if verbose mode is activated.
00235  *
00236  */
00237 void verboselog(char *fmt, ...) {
00238     va_list args;
00239 
00240     if (!logbuffer && !verbose)
00241         return;
00242 
00243     va_start(args, fmt);
00244     vlog(verbose, fmt, args);
00245     va_end(args);
00246 }
00247 
00248 /*
00249  * Logs the given message to stdout while prefixing the current time to it.
00250  *
00251  */
00252 void errorlog(char *fmt, ...) {
00253     va_list args;
00254 
00255     va_start(args, fmt);
00256     vlog(true, fmt, args);
00257     va_end(args);
00258 
00259     /* also log to the error logfile, if opened */
00260     va_start(args, fmt);
00261     vfprintf(errorfile, fmt, args);
00262     fflush(errorfile);
00263     va_end(args);
00264 }
00265 
00266 /*
00267  * Logs the given message to stdout while prefixing the current time to it,
00268  * but only if the corresponding debug loglevel was activated.
00269  * This is to be called by DLOG() which includes filename/linenumber
00270  *
00271  */
00272 void debuglog(uint64_t lev, char *fmt, ...) {
00273     va_list args;
00274 
00275     if (!logbuffer && !(loglevel & lev))
00276         return;
00277 
00278     va_start(args, fmt);
00279     vlog((loglevel & lev), fmt, args);
00280     va_end(args);
00281 }