Improvements in the log system, especially on the server side. Now logging on
[yaz-moved-to-github.git] / src / log.c
1 /*
2  * Copyright (c) 1995-2004, Index Data
3  * See the file LICENSE for details.
4  *
5  * $Id: log.c,v 1.14 2004-11-16 17:08:11 heikki Exp $
6  */
7
8 /**
9  * \file log.c
10  * \brief Implements logging utility
11  */
12
13 #if HAVE_CONFIG_H
14 #include <config.h>
15 #endif
16
17 #ifdef WIN32
18 #include <windows.h>
19 #endif
20
21 #if YAZ_POSIX_THREADS
22 #include <pthread.h>
23 #endif
24
25 #if YAZ_GNU_THREADS
26 #include <pth.h>
27 #endif
28
29 #include <stdio.h>
30 #include <stdlib.h>
31 #include <ctype.h>
32 #include <string.h>
33 #include <stdarg.h>
34 #include <errno.h>
35 #include <time.h>
36 #include <yaz/nmem.h>
37 #include <yaz/log.h>
38
39 static NMEM_MUTEX log_mutex = 0;
40 static int mutex_init_flag = 0; /* not yet initialized */
41
42 #define HAS_STRERROR 1
43
44 #if HAS_STRERROR
45
46 #else
47 char *strerror(int n)
48 {
49     extern char *sys_errlist[];
50     return sys_errlist[n];
51 }
52
53 #endif
54
55
56
57 static int l_level = LOG_DEFAULT_LEVEL;
58 static FILE *l_file = NULL;
59 static char l_prefix[512] = "";
60 static char l_prefix2[512] = "";
61 static char l_fname[512] = "";
62
63 static char l_old_default_format[] = "%H:%M:%S-%d/%m";
64 static char l_new_default_format[] = "%Y%m%d-%H%M%S";
65 #define TIMEFORMAT_LEN 50
66 static char l_custom_format[TIMEFORMAT_LEN] = "";
67 static char *l_actual_format = l_old_default_format;
68
69 /** l_max_size tells when to rotate the log. Default to 1 GB */
70 static const int l_def_max_size = 1024*1024*1024;
71 static int l_max_size = 1024*1024*1024;
72
73 #define MAX_MASK_NAMES 35   /* 32 bits plus a few combo names */
74 static struct {
75     int mask;
76     char *name;
77 }  mask_names[MAX_MASK_NAMES] =
78 {
79     { LOG_FATAL,  "fatal"},
80     { LOG_DEBUG,  "debug"},
81     { LOG_WARN,   "warn" },
82     { LOG_LOG,    "log"  },
83     { LOG_ERRNO,  ""},
84     { LOG_MALLOC, "malloc"},
85     { LOG_APP,    "app"  },
86     { LOG_NOTIME, "" },
87     { LOG_APP2,   "app2" },
88     { LOG_APP3,   "app3" },
89     { LOG_ALL,    "all"  },
90     { LOG_FLUSH,  "flush" },
91     { LOG_LOGLVL, "loglevel" }, 
92     { 0,          "none" },
93     { 0, NULL }
94     /* the rest will be filled in if the user defines dynamic modules*/
95 };  
96 static unsigned int next_log_bit = LOG_LAST_BIT<<1; /* first dynamic bit */
97
98 static void init_mutex()
99 {
100     if (mutex_init_flag)
101         return;
102     nmem_mutex_create (&log_mutex);
103     mutex_init_flag = 1;
104 }
105
106
107 FILE *yaz_log_file(void)
108 {
109     if (!l_file)
110         l_file = stderr;
111     return l_file;
112 }
113
114 void yaz_log_init_file (const char *fname)
115 {
116     if (!mutex_init_flag)
117         init_mutex();
118     if (fname)
119     {
120         strncpy(l_fname, fname, sizeof(l_fname)-1);
121         l_fname[sizeof(l_fname)-1] = '\0';
122     }
123     else
124         l_fname[0] = '\0';
125     yaz_log_reopen();
126 }
127
128 void yaz_log_reopen(void)
129 {
130     FILE *new_file;
131     if (!mutex_init_flag)
132         init_mutex();
133     if (!l_file)
134         l_file = stderr;
135     if (!*l_fname)
136         new_file = stderr;
137     else if (!(new_file = fopen(l_fname, "a")))
138         return;
139     if (l_file != stderr)
140     {
141         fclose (l_file);
142     }
143     if (l_level & LOG_FLUSH)
144         setvbuf(new_file, 0, _IONBF, 0);
145     l_file = new_file;
146 }
147
148 static void rotate_log()
149 {
150     char newname[512];
151     if (l_file==stderr)
152         return; /* can't rotate that */
153     if (!*l_fname)
154         return; /* hmm, no name, can't rotate */
155     strncpy(newname, l_fname, 509);
156     newname[509] = '\0'; /* make sure it is terminated */
157     strcat(newname,".1");
158 #ifdef WIN32
159     /* windows can't rename a file if it is open */
160     fclose(l_file);
161     l_file = stderr;
162 #endif
163     rename(l_fname, newname);
164     yaz_log_reopen();
165 }
166
167
168 void yaz_log_init_level (int level)
169 {
170     if ( (l_level & LOG_FLUSH) != (level & LOG_FLUSH) )
171     {
172         l_level = level;
173         yaz_log_reopen(); /* make sure we set buffering right */
174     } else
175         l_level = level;
176     if (l_level  & LOG_LOGLVL)
177     {  /* dump the log level bits */
178         char *bittype="Static ";
179         int i;
180         yaz_log(LOG_LOGLVL,"Setting log level to %d = 0x%08x",l_level,l_level);
181         for (i = 0; mask_names[i].name; i++)
182             if (mask_names[i].mask && *mask_names[i].name)
183                 if (strcmp(mask_names[i].name,"all")!=0)
184                 {
185                     yaz_log(LOG_LOGLVL,"%s log bit %08x '%s' is %s",
186                         bittype, mask_names[i].mask, mask_names[i].name,
187                         (level & mask_names[i].mask)?  "ON": "off");
188                 if (mask_names[i].mask>LOG_LAST_BIT)
189                     bittype="Dynamic";
190                 }
191     }
192 }
193
194 void yaz_log_init_prefix (const char *prefix)
195 {
196     if (prefix && *prefix)
197         sprintf(l_prefix, "%.511s ", prefix);
198     else
199         *l_prefix = 0;
200 }
201
202 void yaz_log_init_prefix2 (const char *prefix)
203 {
204     if (prefix && *prefix)
205         sprintf(l_prefix2, "%.511s ", prefix);
206     else
207         *l_prefix2 = 0;
208 }
209
210 void yaz_log_init(int level, const char *prefix, const char *fname)
211 {
212     if (!mutex_init_flag)
213         init_mutex();
214     yaz_log_init_level (level);
215     yaz_log_init_prefix (prefix);
216     if (fname && *fname)
217         yaz_log_init_file (fname);
218 }
219
220 void yaz_log_init_max_size(int mx)
221 {
222     if (mx <0)
223         l_max_size = l_def_max_size;
224     else
225         l_max_size = mx;
226 }
227
228 static void (*start_hook_func)(int, const char *, void *) = NULL;
229 static void *start_hook_info;
230 static void (*end_hook_func)(int, const char *, void *) = NULL;
231 static void *end_hook_info;
232
233 void log_event_start (void (*func)(int, const char *, void *), void *info)
234 {
235     start_hook_func = func;
236     start_hook_info = info;
237 }
238
239 void log_event_end (void (*func)(int, const char *, void *), void *info)
240 {
241     end_hook_func = func;
242     end_hook_info = info;
243 }
244
245 void yaz_log(int level, const char *fmt, ...)
246 {
247     va_list ap;
248     char buf[4096], flags[1024];
249     int i;
250     time_t ti;
251     struct tm *tim;
252     char tbuf[TIMEFORMAT_LEN] = "";
253     int o_level = level;
254     int flen; 
255
256     if (!(level & l_level))
257         return;
258     if (!mutex_init_flag)
259         init_mutex();
260     if (!l_file)
261         l_file = stderr;
262     
263     if ((l_file != stderr) && (l_max_size>0))
264     {
265         nmem_mutex_enter (log_mutex);
266         flen = ftell(l_file);
267         if (flen>l_max_size) 
268             rotate_log();
269         nmem_mutex_leave (log_mutex);
270     }
271
272     *flags = '\0';
273     for (i = 0; level && mask_names[i].name; i++)
274         if ( mask_names[i].mask & level)
275         {
276             if (*mask_names[i].name && mask_names[i].mask && 
277                  mask_names[i].mask != LOG_ALL)
278             {
279                 sprintf(flags + strlen(flags), "[%s]", mask_names[i].name);
280                 level &= ~mask_names[i].mask;
281             }
282         }
283     va_start(ap, fmt);
284 #ifdef WIN32
285     _vsnprintf(buf, sizeof(buf)-1, fmt, ap);
286 #else
287 /* !WIN32 */
288 #if HAVE_VSNPRINTF
289     vsnprintf(buf, sizeof(buf), fmt, ap);
290 #else
291     vsprintf(buf, fmt, ap);
292 #endif
293 #endif
294 /* WIN32 */
295     if (o_level & LOG_ERRNO)
296     {
297         strcat(buf, " [");
298         yaz_strerror(buf+strlen(buf), 2048);
299         strcat(buf, "]");
300     }
301     va_end (ap);
302     if (start_hook_func)
303         (*start_hook_func)(o_level, buf, start_hook_info);
304     ti = time(0);
305     tim = localtime(&ti);
306     if (l_level & LOG_NOTIME)
307         tbuf[0] = '\0';
308     else
309         strftime(tbuf, TIMEFORMAT_LEN-1, l_actual_format, tim);
310     tbuf[TIMEFORMAT_LEN-1] = '\0';
311     fprintf(l_file, "%s %s%s %s%s\n", tbuf, l_prefix, flags,
312             l_prefix2, buf);
313     if (l_level & (LOG_FLUSH|LOG_DEBUG) )
314         fflush(l_file);
315     if (end_hook_func)
316         (*end_hook_func)(o_level, buf, end_hook_info);
317 }
318
319 void yaz_log_time_format(const char *fmt)
320 {
321     if ( !fmt || !*fmt) 
322     { /* no format, default to new */
323         l_actual_format = l_new_default_format;
324         return; 
325     }
326     if (0==strcmp(fmt,"old"))
327     { /* force the old format */
328         l_actual_format = l_old_default_format;
329         return; 
330     }
331     /* else use custom format */
332     strncpy(l_custom_format, fmt, TIMEFORMAT_LEN-1);
333     l_custom_format[TIMEFORMAT_LEN-1] = '\0';
334     l_actual_format = l_custom_format;
335 }
336
337 /** cleans a loglevel name from leading paths and suffixes */
338 static char *clean_name(const char *name, int len, char *namebuf, int buflen)
339 {
340     char *p = namebuf;
341     char *start = namebuf;
342     if (buflen <len)
343         len = buflen; 
344     strncpy(namebuf, name, len);
345     namebuf[len] = '\0';
346     while ((p = strchr(start,'/')))
347         start = p+1;
348     if ((p = strrchr(start,'.')))
349         *p = '\0';
350     return start;
351
352 }
353
354 static int define_module_bit(const char *name)
355 {
356     int i;
357     for (i = 0; mask_names[i].name; i++)
358         ;
359     if ( (i>=MAX_MASK_NAMES) || (next_log_bit >= 1<<31 ))
360     {
361         yaz_log(LOG_WARN,"No more log bits left, not logging '%s'", name);
362         return 0;
363     }
364     mask_names[i].mask = next_log_bit;
365     next_log_bit = next_log_bit<<1;
366     mask_names[i].name = xstrdup(name);
367     mask_names[i+1].name = NULL;
368     mask_names[i+1].mask = 0;
369     return mask_names[i].mask;
370 }
371
372 int yaz_log_module_level(const char *name)
373 {
374     int i;
375     char clean[255];
376     char *n = clean_name(name, strlen(name), clean, sizeof(clean));
377     for (i = 0; mask_names[i].name; i++)
378         if (0==strcmp(n,mask_names[i].name))
379         {
380             yaz_log(LOG_LOGLVL,"returning log bit 0x%x for '%s' %s",
381                     mask_names[i].mask, n, 
382                     strcmp(n,name)?name:"" );
383             return mask_names[i].mask;
384         }
385     yaz_log(LOG_LOGLVL,"returning NO log bit for '%s' %s", n, 
386                     strcmp(n,name)?name:"" );
387     return 0;
388 }
389
390 int yaz_log_mask_str (const char *str)
391 {
392     return yaz_log_mask_str_x (str, LOG_DEFAULT_LEVEL);
393 }
394
395 int yaz_log_mask_str_x (const char *str, int level)
396 {
397     const char *p;
398     int i;
399     int found;
400     char clean[255] = "";
401     char *n = clean;
402
403     while (*str)
404     {
405         found = 0;
406         for (p = str; *p && *p != ','; p++)
407             ;
408         if (*str == '-' || isdigit(*str))
409         {
410             level = atoi (str);
411             found = 1;
412         }
413         else 
414         {
415             n = clean_name(str, p-str, clean, sizeof(clean));
416             for (i = 0; mask_names[i].name; i++)
417                 if (0==strcmp (mask_names[i].name,n))
418                 {
419                     if (mask_names[i].mask)
420                         level |= mask_names[i].mask;
421                     else
422                         level = 0; /* 'none' clears them all */
423                     found = 1;
424                 }
425         }
426         if (!found)
427             level |= define_module_bit(n);
428         if (*p == ',')
429             p++;
430         str = p;
431     }
432     return level;
433 }