]> granicus.if.org Git - postgresql/blob - src/backend/utils/error/elog.c
FATAL errors should cause exit with nonzero status if we are not running
[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.82 2001/03/10 04:21:51 tgl 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.  We also want
455                  * to exit with nonzero exit code if not running under the postmaster
456                  * (for example, if we are being run from the initdb script, we'd
457                  * better return an error status).
458                  */
459                 if (lev == FATAL || !Warn_restart_ready || proc_exit_inprogress)
460                 {
461                         /*
462                          * fflush here is just to improve the odds that we get to see
463                          * the error message, in case things are so hosed that proc_exit
464                          * crashes.  Any other code you might be tempted to add here
465                          * should probably be in an on_proc_exit callback instead.
466                          */
467                         fflush(stdout);
468                         fflush(stderr);
469                         proc_exit((int) (proc_exit_inprogress || !IsUnderPostmaster));
470                 }
471
472                 /*
473                  * Guard against infinite loop from elog() during error recovery.
474                  */
475                 if (InError)
476                         elog(REALLYFATAL, "elog: error during error recovery, giving up!");
477                 InError = true;
478
479                 /*
480                  * Otherwise we can return to the main loop in postgres.c.
481                  */
482                 siglongjmp(Warn_restart, 1);
483         }
484
485         if (lev > FATAL)
486         {
487                 /*
488                  * Serious crash time. Postmaster will observe nonzero process
489                  * exit status and kill the other backends too.
490                  *
491                  * XXX: what if we are *in* the postmaster?  proc_exit() won't kill
492                  * our children...
493                  */
494                 ImmediateInterruptOK = false;
495                 fflush(stdout);
496                 fflush(stderr);
497                 proc_exit(lev);
498         }
499
500         /* We reach here if lev <= NOTICE.      OK to return to caller. */
501 }
502
503 int
504 DebugFileOpen(void)
505 {
506         int                     fd,
507                                 istty;
508
509         Debugfile = -1;
510         ElogDebugIndentLevel = 0;
511
512         if (OutputFileName[0])
513         {
514                 /*
515                  * A debug-output file name was given.
516                  *
517                  * Make sure we can write the file, and find out if it's a tty.
518                  */
519                 if ((fd = open(OutputFileName, O_CREAT | O_APPEND | O_WRONLY,
520                                            0666)) < 0)
521                         elog(FATAL, "DebugFileOpen: open of %s: %m",
522                                  OutputFileName);
523                 istty = isatty(fd);
524                 close(fd);
525
526                 /*
527                  * Redirect our stderr to the debug output file.
528                  */
529                 if (!freopen(OutputFileName, "a", stderr))
530                         elog(FATAL, "DebugFileOpen: %s reopen as stderr: %m",
531                                  OutputFileName);
532                 Debugfile = fileno(stderr);
533                 /*
534                  * If the file is a tty and we're running under the postmaster,
535                  * try to send stdout there as well (if it isn't a tty then stderr
536                  * will block out stdout, so we may as well let stdout go wherever
537                  * it was going before).
538                  */
539                 if (istty && IsUnderPostmaster)
540                         if (!freopen(OutputFileName, "a", stdout))
541                                 elog(FATAL, "DebugFileOpen: %s reopen as stdout: %m",
542                                          OutputFileName);
543                 return Debugfile;
544         }
545
546         /*
547          * If no filename was specified, send debugging output to stderr. If
548          * stderr has been hosed, try to open a file.
549          */
550         fd = fileno(stderr);
551         if (fcntl(fd, F_GETFD, 0) < 0)
552         {
553                 snprintf(OutputFileName, MAXPGPATH, "%s%cpg.errors.%d",
554                                  DataDir, SEP_CHAR, (int) MyProcPid);
555                 fd = open(OutputFileName, O_CREAT | O_APPEND | O_WRONLY, 0666);
556         }
557         if (fd < 0)
558                 elog(FATAL, "DebugFileOpen: could not open debugging file");
559
560         Debugfile = fd;
561         return Debugfile;
562 }
563
564
565 /*
566  * Return a timestamp string like
567  *
568  *   "2000-06-04 13:12:03 "
569  */
570 static const char *
571 print_timestamp(void)
572 {
573         time_t curtime;
574         static char buf[TIMESTAMP_SIZE + 1];
575
576         curtime = time(NULL);
577
578         strftime(buf, sizeof(buf),
579                          "%Y-%m-%d %H:%M:%S ",
580                          localtime(&curtime));
581
582         return buf;
583 }
584
585
586
587 /*
588  * Return a string like
589  *
590  *     "[123456] "
591  *
592  * with the current pid.
593  */
594 static const char *
595 print_pid(void)
596 {
597         static char buf[PID_SIZE + 1];
598
599         snprintf(buf, PID_SIZE + 1, "[%d]      ", (int)MyProcPid);
600         return buf;
601 }
602
603
604
605 #ifdef ENABLE_SYSLOG
606
607 #ifndef PG_SYSLOG_LIMIT
608 # define PG_SYSLOG_LIMIT 128
609 #endif
610
611 /*
612  * Write a message line to syslog if the syslog option is set.
613  *
614  * Our problem here is that many syslog implementations don't handle
615  * long messages in an acceptable manner. While this function doesn't
616  * help that fact, it does work around by splitting up messages into
617  * smaller pieces.
618  */
619 static void
620 write_syslog(int level, const char *line)
621 {
622         static bool     openlog_done = false;
623         static unsigned long seq = 0;
624         static int      syslog_fac = LOG_LOCAL0;
625
626         int len = strlen(line);
627
628         if (Use_syslog == 0)
629                 return;
630
631         if (!openlog_done)
632         {
633                 if (strcasecmp(Syslog_facility,"LOCAL0") == 0) 
634                         syslog_fac = LOG_LOCAL0;
635                 if (strcasecmp(Syslog_facility,"LOCAL1") == 0)
636                         syslog_fac = LOG_LOCAL1;
637                 if (strcasecmp(Syslog_facility,"LOCAL2") == 0)
638                         syslog_fac = LOG_LOCAL2;
639                 if (strcasecmp(Syslog_facility,"LOCAL3") == 0)
640                         syslog_fac = LOG_LOCAL3;
641                 if (strcasecmp(Syslog_facility,"LOCAL4") == 0)
642                         syslog_fac = LOG_LOCAL4;
643                 if (strcasecmp(Syslog_facility,"LOCAL5") == 0)
644                         syslog_fac = LOG_LOCAL5;
645                 if (strcasecmp(Syslog_facility,"LOCAL6") == 0)
646                         syslog_fac = LOG_LOCAL6;
647                 if (strcasecmp(Syslog_facility,"LOCAL7") == 0)
648                         syslog_fac = LOG_LOCAL7;
649                 openlog(Syslog_ident, LOG_PID | LOG_NDELAY, syslog_fac);
650                 openlog_done = true;
651         }
652
653         /*
654          * We add a sequence number to each log message to suppress "same"
655          * messages.
656          */
657         seq++;
658
659         /* divide into multiple syslog() calls if message is too long */
660         /* or if the message contains embedded NewLine(s) '\n' */
661         if (len > PG_SYSLOG_LIMIT || strchr(line,'\n') != NULL )
662         {
663                 int             chunk_nr = 0;
664
665                 while (len > 0)
666                 {
667                         char    buf[PG_SYSLOG_LIMIT+1];
668                         int             buflen;
669                         int             l;
670                         int             i;
671
672                         /* if we start at a newline, move ahead one char */
673                         if (line[0] == '\n')
674                         {
675                                 line++;
676                                 len--;
677                                 continue;
678                         }
679
680                         strncpy(buf, line, PG_SYSLOG_LIMIT);
681                         buf[PG_SYSLOG_LIMIT] = '\0';
682                         if (strchr(buf,'\n') != NULL) 
683                                 *strchr(buf,'\n') = '\0';
684
685                         l = strlen(buf);
686 #ifdef MULTIBYTE
687                         /* trim to multibyte letter boundary */ 
688                         buflen = pg_mbcliplen(buf, l, l);
689                         if (buflen <= 0)
690                             return;
691                         buf[buflen] = '\0';
692                         l = strlen(buf);
693 #endif
694                         /* already word boundary? */
695                         if (isspace((unsigned char) line[l]) || line[l] == '\0')
696                                 buflen = l;
697                         else
698                         {
699                                 /* try to divide at word boundary */
700                                 i = l - 1;
701                                 while (i > 0 && !isspace((unsigned char) buf[i]))
702                                         i--;
703
704                                 if (i <= 0)     /* couldn't divide word boundary */
705                                         buflen = l;
706                                 else
707                                 {
708                                         buflen = i;
709                                         buf[i] = '\0';
710                                 }
711                         }
712
713                         chunk_nr++;
714
715                         syslog(level, "[%lu-%d] %s", seq, chunk_nr, buf);
716                         line += buflen;
717                         len -= buflen;
718                 }
719         }
720         else
721         {
722                 /* message short enough */
723                 syslog(level, "[%lu] %s", seq, line);
724         }
725 }
726
727 #endif /* ENABLE_SYSLOG */