]> granicus.if.org Git - postgresql/blob - src/backend/utils/error/elog.c
Change Copyright from PostgreSQL, Inc to PostgreSQL Global Development Group.
[postgresql] / src / backend / utils / error / elog.c
1 /*-------------------------------------------------------------------------
2  *
3  * elog.c
4  *        error logger
5  *
6  * Portions Copyright (c) 1996-2001, PostgreSQL Global Development Group
7  * Portions Copyright (c) 1994, Regents of the University of California
8  *
9  *
10  * IDENTIFICATION
11  *        $Header: /cvsroot/pgsql/src/backend/utils/error/elog.c,v 1.80 2001/01/24 19:43:15 momjian Exp $
12  *
13  *-------------------------------------------------------------------------
14  */
15 #include "postgres.h"
16
17 #include <time.h>
18 #include <fcntl.h>
19 #ifndef O_RDONLY
20 #include <sys/file.h>
21 #endif   /* O_RDONLY */
22 #include <sys/types.h>
23 #include <errno.h>
24 #include <unistd.h>
25 #include <signal.h>
26 #include <sys/time.h>
27 #include <ctype.h>
28 #ifdef ENABLE_SYSLOG
29 #include <syslog.h>
30 #endif
31
32 #include "commands/copy.h"
33 #include "libpq/libpq.h"
34 #include "libpq/pqformat.h"
35 #include "miscadmin.h"
36 #include "storage/proc.h"
37 #include "tcop/tcopprot.h"
38 #include "utils/memutils.h"
39
40 #ifdef MULTIBYTE
41 #include "mb/pg_wchar.h"
42 #endif
43
44 extern int      errno;
45
46 extern CommandDest whereToSendOutput;
47
48 #ifdef ENABLE_SYSLOG
49 /*
50  * 0 = only stdout/stderr
51  * 1 = stdout+stderr and syslog
52  * 2 = syslog only
53  * ... in theory anyway
54  */
55 int Use_syslog = 0;
56 char *Syslog_facility;
57 char *Syslog_ident;
58
59 static void write_syslog(int level, const char *line);
60
61 #else
62 # define Use_syslog 0
63 #endif
64
65 bool Log_timestamp;
66 bool Log_pid;
67
68 #define TIMESTAMP_SIZE 20               /* format `YYYY-MM-DD HH:MM:SS ' */
69 #define PID_SIZE 9                              /* format `[123456] ' */
70
71 static const char * print_timestamp(void);
72 static const char * print_pid(void);
73
74 static int      Debugfile = -1;
75 static int      ElogDebugIndentLevel = 0;
76
77 /*--------------------
78  * elog
79  *              Primary error logging function.
80  *
81  * 'lev': error level; indicates recovery action to take, if any.
82  * 'fmt': a printf-style string.
83  * Additional arguments, if any, are formatted per %-escapes in 'fmt'.
84  *
85  * In addition to the usual %-escapes recognized by printf, "%m" in
86  * fmt is replaced by the error message for the current value of errno.
87  *
88  * Note: no newline is needed at the end of the fmt string, since
89  * elog will provide one for the output methods that need it.
90  *
91  * If 'lev' is ERROR or worse, control does not return to the caller.
92  * See elog.h for the error level definitions.
93  *--------------------
94  */
95 void
96 elog(int lev, const char *fmt, ...)
97 {
98         va_list         ap;
99         /*
100          * The expanded format and final output message are dynamically
101          * allocated if necessary, but not if they fit in the "reasonable
102          * size" buffers shown here.  In extremis, we'd rather depend on
103          * having a few hundred bytes of stack space than on malloc() still
104          * working (since memory-clobber errors often take out malloc first).
105          * Don't make these buffers unreasonably large though, on pain of
106          * having to chase a bug with no error message.
107          *
108          * Note that we use malloc() not palloc() because we want to retain
109          * control if we run out of memory.  palloc() would recursively call
110          * elog(ERROR), which would be all right except if we are working on a
111          * FATAL or REALLYFATAL error.  We'd lose track of the fatal condition
112          * and report a mere ERROR to outer loop, which would be a Bad Thing.
113          * So, we substitute an appropriate message in-place, without downgrading
114          * the level if it's above ERROR.
115          */
116         char            fmt_fixedbuf[128];
117         char            msg_fixedbuf[256];
118         char       *fmt_buf = fmt_fixedbuf;
119         char       *msg_buf = msg_fixedbuf;
120         /* this buffer is only used for strange values of lev: */
121         char            prefix_buf[32];
122         /* this buffer is only used if errno has a bogus value: */
123         char            errorstr_buf[32];
124         const char *errorstr;
125         const char *prefix;
126         const char *cp;
127         char       *bp;
128         int                     indent = 0;
129         int                     space_needed;
130         int                     len;
131         /* size of the prefix needed for timestamp and pid, if enabled */
132         size_t          timestamp_size;
133
134         if (lev <= DEBUG && Debugfile < 0)
135                 return;                                 /* ignore debug msgs if noplace to send */
136
137         /* Save error str before calling any function that might change errno */
138         errorstr = strerror(errno);
139         /*
140          * Some strerror()s return an empty string for out-of-range errno.
141          * This is ANSI C spec compliant, but not exactly useful.
142          */
143         if (errorstr == NULL || *errorstr == '\0')
144         {
145                 sprintf(errorstr_buf, "error %d", errno);
146                 errorstr = errorstr_buf;
147         }
148
149         if (lev == ERROR || lev == FATAL)
150         {
151                 /*
152                  * Convert initialization errors into fatal errors.
153                  * This is probably redundant, because Warn_restart_ready won't
154                  * be set anyway...
155                  */
156                 if (IsInitProcessingMode())
157                         lev = FATAL;
158                 /*
159                  * If we are inside a critical section, all errors become STOP errors.
160                  * See miscadmin.h.
161                  */
162                 if (CritSectionCount > 0)
163                         lev = STOP;
164         }
165
166         /* choose message prefix and indent level */
167         switch (lev)
168         {
169                 case NOIND:
170                         indent = ElogDebugIndentLevel - 1;
171                         if (indent < 0)
172                                 indent = 0;
173                         if (indent > 30)
174                                 indent = indent % 30;
175                         prefix = "DEBUG:  ";
176                         break;
177                 case DEBUG:
178                         indent = ElogDebugIndentLevel;
179                         if (indent < 0)
180                                 indent = 0;
181                         if (indent > 30)
182                                 indent = indent % 30;
183                         prefix = "DEBUG:  ";
184                         break;
185                 case NOTICE:
186                         prefix = "NOTICE:  ";
187                         break;
188                 case ERROR:
189                         prefix = "ERROR:  ";
190                         break;
191                 default:
192                         sprintf(prefix_buf, "FATAL %d:  ", lev);
193                         prefix = prefix_buf;
194                         break;
195         }
196
197         timestamp_size = 0;
198         if (Log_timestamp)
199                 timestamp_size += TIMESTAMP_SIZE;
200         if (Log_pid)
201                 timestamp_size += PID_SIZE;
202
203         /*
204          * Set up the expanded format, consisting of the prefix string plus
205          * input format, with any %m replaced by strerror() string (since
206          * vsnprintf won't know what to do with %m).  To keep space
207          * calculation simple, we only allow one %m.
208          */
209         space_needed = timestamp_size + strlen(prefix) + indent + (lineno ? 24 : 0)
210                 + strlen(fmt) + strlen(errorstr) + 1;
211         if (space_needed > (int) sizeof(fmt_fixedbuf))
212         {
213                 fmt_buf = (char *) malloc(space_needed);
214                 if (fmt_buf == NULL)
215                 {
216                         /* We're up against it, convert to out-of-memory error */
217                         fmt_buf = fmt_fixedbuf;
218                         if (lev < FATAL)
219                         {
220                                 lev = ERROR;
221                                 prefix = "ERROR:  ";
222                         }
223                         fmt = "elog: out of memory";            /* this must fit in
224                                                                                                  * fmt_fixedbuf! */
225                 }
226         }
227
228         fmt_buf[0] = '\0';
229
230         if (Log_timestamp)
231                 strcat(fmt_buf, print_timestamp());
232         if (Log_pid)
233                 strcat(fmt_buf, print_pid());
234
235         strcat(fmt_buf, prefix);
236
237         bp = fmt_buf + strlen(fmt_buf);
238         while (indent-- > 0)
239                 *bp++ = ' ';
240
241         /* If error was in CopyFrom() print the offending line number -- dz */
242         if (lineno)
243         {
244                 sprintf(bp, "copy: line %d, ", lineno);
245                 bp += strlen(bp);
246                 if (lev == ERROR || lev >= FATAL)
247                         lineno = 0;
248         }
249
250         for (cp = fmt; *cp; cp++)
251         {
252                 if (cp[0] == '%' && cp[1] != '\0')
253                 {
254                         if (cp[1] == 'm')
255                         {
256
257                                 /*
258                                  * XXX If there are any %'s in errorstr then vsnprintf
259                                  * will do the Wrong Thing; do we need to cope? Seems
260                                  * unlikely that % would appear in system errors.
261                                  */
262                                 strcpy(bp, errorstr);
263
264                                 /*
265                                  * copy the rest of fmt literally, since we can't afford
266                                  * to insert another %m.
267                                  */
268                                 strcat(bp, cp + 2);
269                                 bp += strlen(bp);
270                                 break;
271                         }
272                         else
273                         {
274                                 /* copy % and next char --- this avoids trouble with %%m */
275                                 *bp++ = *cp++;
276                                 *bp++ = *cp;
277                         }
278                 }
279                 else
280                         *bp++ = *cp;
281         }
282         *bp = '\0';
283
284         /*
285          * Now generate the actual output text using vsnprintf(). Be sure to
286          * leave space for \n added later as well as trailing null.
287          */
288         space_needed = sizeof(msg_fixedbuf);
289         for (;;)
290         {
291                 int                     nprinted;
292
293                 va_start(ap, fmt);
294                 nprinted = vsnprintf(msg_buf, space_needed - 2, fmt_buf, ap);
295                 va_end(ap);
296
297                 /*
298                  * Note: some versions of vsnprintf return the number of chars
299                  * actually stored, but at least one returns -1 on failure. Be
300                  * conservative about believing whether the print worked.
301                  */
302                 if (nprinted >= 0 && nprinted < space_needed - 3)
303                         break;
304                 /* It didn't work, try to get a bigger buffer */
305                 if (msg_buf != msg_fixedbuf)
306                         free(msg_buf);
307                 space_needed *= 2;
308                 msg_buf = (char *) malloc(space_needed);
309                 if (msg_buf == NULL)
310                 {
311                         /* We're up against it, convert to out-of-memory error */
312                         msg_buf = msg_fixedbuf;
313                         if (lev < FATAL)
314                         {
315                                 lev = ERROR;
316                                 prefix = "ERROR:  ";
317                         }
318                         msg_buf[0] = '\0';
319                         if (Log_timestamp)
320                                 strcat(msg_buf, print_timestamp());
321                         if (Log_pid)
322                                 strcat(msg_buf, print_pid());
323                         strcat(msg_buf, prefix);
324                         strcat(msg_buf, "elog: out of memory");
325                         break;
326                 }
327         }
328
329         /*
330          * Message prepared; send it where it should go
331          */
332
333 #ifdef ENABLE_SYSLOG
334         /* Write to syslog, if enabled */
335         if (Use_syslog >= 1)
336         {
337                 int syslog_level;
338
339                 switch (lev)
340                 {
341                         case NOIND:
342                                 syslog_level = LOG_DEBUG;
343                                 break;
344                         case DEBUG:
345                                 syslog_level = LOG_DEBUG;
346                                 break;
347                         case NOTICE:
348                                 syslog_level = LOG_NOTICE;
349                                 break;
350                         case ERROR:
351                                 syslog_level = LOG_WARNING;
352                                 break;
353                         case FATAL:
354                                 syslog_level = LOG_ERR;
355                                 break;
356                         case REALLYFATAL:
357                         default:
358                                 syslog_level = LOG_CRIT;
359                 }
360
361                 write_syslog(syslog_level, msg_buf + timestamp_size);
362         }
363 #endif /* ENABLE_SYSLOG */
364
365         /* syslog doesn't want a trailing newline, but other destinations do */
366         strcat(msg_buf, "\n");
367
368         len = strlen(msg_buf);
369
370         /* Write to debug file, if open and enabled */
371         /* NOTE: debug file is typically pointed at stderr */
372         if (Debugfile >= 0 && Use_syslog <= 1)
373                 write(Debugfile, msg_buf, len);
374
375         if (lev > DEBUG && whereToSendOutput == Remote)
376         {
377                 /* Send IPC message to the front-end program */
378                 MemoryContext oldcxt;
379                 char            msgtype;
380
381                 /*
382                  * Since backend libpq may call palloc(), switch to a context where
383                  * there's fairly likely to be some free space.  After all the
384                  * pushups above, we don't want to drop the ball by running out of
385                  * space now...
386                  */
387                 oldcxt = MemoryContextSwitchTo(ErrorContext);
388
389                 if (lev == NOTICE)
390                         msgtype = 'N';
391                 else
392                 {
393
394                         /*
395                          * Abort any COPY OUT in progress when an error is detected.
396                          * This hack is necessary because of poor design of copy
397                          * protocol.
398                          */
399                         pq_endcopyout(true);
400                         msgtype = 'E';
401                 }
402                 /* exclude the timestamp from msg sent to frontend */
403                 pq_puttextmessage(msgtype, msg_buf + timestamp_size);
404
405                 /*
406                  * This flush is normally not necessary, since postgres.c will
407                  * flush out waiting data when control returns to the main loop.
408                  * But it seems best to leave it here, so that the client has some
409                  * clue what happened if the backend dies before getting back to
410                  * the main loop ... error/notice messages should not be a
411                  * performance-critical path anyway, so an extra flush won't hurt
412                  * much ...
413                  */
414                 pq_flush();
415
416                 MemoryContextSwitchTo(oldcxt);
417         }
418
419         if (lev > DEBUG && whereToSendOutput != Remote)
420         {
421
422                 /*
423                  * We are running as an interactive backend, so just send the
424                  * message to stderr.  But don't send a duplicate if Debugfile
425                  * write, above, already sent to stderr.
426                  */
427                 if (Debugfile != fileno(stderr))
428                         fputs(msg_buf, stderr);
429         }
430
431         /* done with the message, release space */
432         if (fmt_buf != fmt_fixedbuf)
433                 free(fmt_buf);
434         if (msg_buf != msg_fixedbuf)
435                 free(msg_buf);
436
437         /*
438          * Perform error recovery action as specified by lev.
439          */
440         if (lev == ERROR || lev == FATAL)
441         {
442                 /* Prevent immediate interrupt while entering error recovery */
443                 ImmediateInterruptOK = false;
444
445                 /*
446                  * For a FATAL error, we let proc_exit clean up and exit.
447                  *
448                  * If we have not yet entered the main backend loop (ie, we are in
449                  * the postmaster or in backend startup), we also go directly to
450                  * proc_exit.  The same is true if anyone tries to report an error
451                  * after proc_exit has begun to run.  (It's proc_exit's
452                  * responsibility to see that this doesn't turn into infinite
453                  * recursion!)  But in the latter case, we exit with nonzero exit
454                  * code to indicate that something's pretty wrong.
455                  */
456                 if (lev == FATAL || !Warn_restart_ready || proc_exit_inprogress)
457                 {
458                         /*
459                          * fflush here is just to improve the odds that we get to see
460                          * the error message, in case things are so hosed that proc_exit
461                          * crashes.  Any other code you might be tempted to add here
462                          * should probably be in an on_proc_exit callback instead.
463                          */
464                         fflush(stdout);
465                         fflush(stderr);
466                         proc_exit((int) proc_exit_inprogress);
467                 }
468
469                 /*
470                  * Guard against infinite loop from elog() during error recovery.
471                  */
472                 if (InError)
473                         elog(REALLYFATAL, "elog: error during error recovery, giving up!");
474                 InError = true;
475
476                 /*
477                  * Otherwise we can return to the main loop in postgres.c.
478                  */
479                 siglongjmp(Warn_restart, 1);
480         }
481
482         if (lev > FATAL)
483         {
484                 /*
485                  * Serious crash time. Postmaster will observe nonzero process
486                  * exit status and kill the other backends too.
487                  *
488                  * XXX: what if we are *in* the postmaster?  proc_exit() won't kill
489                  * our children...
490                  */
491                 ImmediateInterruptOK = false;
492                 fflush(stdout);
493                 fflush(stderr);
494                 proc_exit(lev);
495         }
496
497         /* We reach here if lev <= NOTICE.      OK to return to caller. */
498 }
499
500 int
501 DebugFileOpen(void)
502 {
503         int                     fd,
504                                 istty;
505
506         Debugfile = -1;
507         ElogDebugIndentLevel = 0;
508
509         if (OutputFileName[0])
510         {
511                 /*
512                  * A debug-output file name was given.
513                  *
514                  * Make sure we can write the file, and find out if it's a tty.
515                  */
516                 if ((fd = open(OutputFileName, O_CREAT | O_APPEND | O_WRONLY,
517                                            0666)) < 0)
518                         elog(FATAL, "DebugFileOpen: open of %s: %m",
519                                  OutputFileName);
520                 istty = isatty(fd);
521                 close(fd);
522
523                 /*
524                  * Redirect our stderr to the debug output file.
525                  */
526                 if (!freopen(OutputFileName, "a", stderr))
527                         elog(FATAL, "DebugFileOpen: %s reopen as stderr: %m",
528                                  OutputFileName);
529                 Debugfile = fileno(stderr);
530                 /*
531                  * If the file is a tty and we're running under the postmaster,
532                  * try to send stdout there as well (if it isn't a tty then stderr
533                  * will block out stdout, so we may as well let stdout go wherever
534                  * it was going before).
535                  */
536                 if (istty && IsUnderPostmaster)
537                         if (!freopen(OutputFileName, "a", stdout))
538                                 elog(FATAL, "DebugFileOpen: %s reopen as stdout: %m",
539                                          OutputFileName);
540                 return Debugfile;
541         }
542
543         /*
544          * If no filename was specified, send debugging output to stderr. If
545          * stderr has been hosed, try to open a file.
546          */
547         fd = fileno(stderr);
548         if (fcntl(fd, F_GETFD, 0) < 0)
549         {
550                 snprintf(OutputFileName, MAXPGPATH, "%s%cpg.errors.%d",
551                                  DataDir, SEP_CHAR, (int) MyProcPid);
552                 fd = open(OutputFileName, O_CREAT | O_APPEND | O_WRONLY, 0666);
553         }
554         if (fd < 0)
555                 elog(FATAL, "DebugFileOpen: could not open debugging file");
556
557         Debugfile = fd;
558         return Debugfile;
559 }
560
561
562 /*
563  * Return a timestamp string like
564  *
565  *   "2000-06-04 13:12:03 "
566  */
567 static const char *
568 print_timestamp(void)
569 {
570         time_t curtime;
571         static char buf[TIMESTAMP_SIZE + 1];
572
573         curtime = time(NULL);
574
575         strftime(buf, sizeof(buf),
576                          "%Y-%m-%d %H:%M:%S ",
577                          localtime(&curtime));
578
579         return buf;
580 }
581
582
583
584 /*
585  * Return a string like
586  *
587  *     "[123456] "
588  *
589  * with the current pid.
590  */
591 static const char *
592 print_pid(void)
593 {
594         static char buf[PID_SIZE + 1];
595
596         snprintf(buf, PID_SIZE + 1, "[%d]      ", (int)MyProcPid);
597         return buf;
598 }
599
600
601
602 #ifdef ENABLE_SYSLOG
603
604 #ifndef PG_SYSLOG_LIMIT
605 # define PG_SYSLOG_LIMIT 128
606 #endif
607
608 /*
609  * Write a message line to syslog if the syslog option is set.
610  *
611  * Our problem here is that many syslog implementations don't handle
612  * long messages in an acceptable manner. While this function doesn't
613  * help that fact, it does work around by splitting up messages into
614  * smaller pieces.
615  */
616 static void
617 write_syslog(int level, const char *line)
618 {
619         static bool     openlog_done = false;
620         static unsigned long seq = 0;
621         static int      syslog_fac = LOG_LOCAL0;
622
623         int len = strlen(line);
624
625         if (Use_syslog == 0)
626                 return;
627
628         if (!openlog_done)
629         {
630                 if (strcasecmp(Syslog_facility,"LOCAL0") == 0) 
631                         syslog_fac = LOG_LOCAL0;
632                 if (strcasecmp(Syslog_facility,"LOCAL1") == 0)
633                         syslog_fac = LOG_LOCAL1;
634                 if (strcasecmp(Syslog_facility,"LOCAL2") == 0)
635                         syslog_fac = LOG_LOCAL2;
636                 if (strcasecmp(Syslog_facility,"LOCAL3") == 0)
637                         syslog_fac = LOG_LOCAL3;
638                 if (strcasecmp(Syslog_facility,"LOCAL4") == 0)
639                         syslog_fac = LOG_LOCAL4;
640                 if (strcasecmp(Syslog_facility,"LOCAL5") == 0)
641                         syslog_fac = LOG_LOCAL5;
642                 if (strcasecmp(Syslog_facility,"LOCAL6") == 0)
643                         syslog_fac = LOG_LOCAL6;
644                 if (strcasecmp(Syslog_facility,"LOCAL7") == 0)
645                         syslog_fac = LOG_LOCAL7;
646                 openlog(Syslog_ident, LOG_PID | LOG_NDELAY, syslog_fac);
647                 openlog_done = true;
648         }
649
650         /*
651          * We add a sequence number to each log message to suppress "same"
652          * messages.
653          */
654         seq++;
655
656         /* divide into multiple syslog() calls if message is too long */
657         /* or if the message contains embedded NewLine(s) '\n' */
658         if (len > PG_SYSLOG_LIMIT || strchr(line,'\n') != NULL )
659         {
660                 int             chunk_nr = 0;
661
662                 while (len > 0)
663                 {
664                         char    buf[PG_SYSLOG_LIMIT+1];
665                         int             buflen;
666                         int             l;
667                         int             i;
668
669                         /* if we start at a newline, move ahead one char */
670                         if (line[0] == '\n')
671                         {
672                                 line++;
673                                 len--;
674                                 continue;
675                         }
676
677                         strncpy(buf, line, PG_SYSLOG_LIMIT);
678                         buf[PG_SYSLOG_LIMIT] = '\0';
679                         if (strchr(buf,'\n') != NULL) 
680                                 *strchr(buf,'\n') = '\0';
681
682                         l = strlen(buf);
683 #ifdef MULTIBYTE
684                         /* trim to multibyte letter boundary */ 
685                         buflen = pg_mbcliplen(buf, l, l);
686                         buf[buflen] = '\0';
687                         l = strlen(buf);
688 #endif
689                         /* already word boundary? */
690                         if (isspace((unsigned char) line[l]) || line[l] == '\0')
691                                 buflen = l;
692                         else
693                         {
694                                 /* try to divide at word boundary */
695                                 i = l - 1;
696                                 while (i > 0 && !isspace((unsigned char) buf[i]))
697                                         i--;
698
699                                 if (i <= 0)     /* couldn't divide word boundary */
700                                         buflen = l;
701                                 else
702                                 {
703                                         buflen = i;
704                                         buf[i] = '\0';
705                                 }
706                         }
707
708                         chunk_nr++;
709
710                         syslog(level, "[%lu-%d] %s", seq, chunk_nr, buf);
711                         line += buflen;
712                         len -= buflen;
713                 }
714         }
715         else
716         {
717                 /* message short enough */
718                 syslog(level, "[%lu] %s", seq, line);
719         }
720 }
721
722 #endif /* ENABLE_SYSLOG */