Thread: Problem with log_timezone not being set during early startup
I came across a problem with the log_timezone patch. Given these
conditions:
* log_min_messages is at least debug3
* log_line_prefix includes %t or %m
* log_timezone is not explicitly set in postgresql.conf
the postmaster will dump core during startup, because it tries to format
an elog message using log_timezone while the variable is still NULL.
I can think of several ways of fixing this, but they all have drawbacks:
1. Tweak elog.c so that the timestamp-formatting escapes are disregarded
if log_timezone is still NULL. This is simple and robust, but some will
complain that early-startup messages are formatted differently from
those appearing later. I don't put a lot of weight on that, because
it is *necessarily* the case that messages appearing before GUCs are
all initialized will look different from those later. But it's a bit
annoying, and might be more than a bit annoying for CSV-format logging.
2. Tweak pg_localtime() so that it takes a null tz argument as meaning
GMT. I find this one pretty ugly --- it seems to remove a useful error
check even after startup. Also, it's not clear whether having messages
that are labeled in the wrong timezone is better or worse than not
labeling them at all. I'm also a bit worried whether invoking tzload()
too early in startup would work reliably.
3. Somehow rearrange the order of startup processing to guarantee that
log_timezone becomes set before log_line_prefix can be set. I thought
of a number of variants of this before realizing that any of them would
break the concern mentioned in postmaster.c:
* If timezone is not set, determine what the OS uses. (In theory this * should be done during GUC
initialization,but because it can take as * much as several seconds, we delay it until after we've created the *
postmaster.pidfile. This prevents problems with boot scripts that * expect the pidfile to appear quickly. Also, we
avoidproblems with * trying to locate the timezone files too early in initialization.)
This is what led us to run pg_timezone_initialize() as late as we do,
and I don't see any very good way around it. We could hack things so
that log_line_prefix doesn't become active until even later, but that
doesn't really improve matters in terms of having early-startup messages
be consistent with later ones.
I don't feel that we have to have a perfect solution to this, because
the messages in question will normally only be debugging ones. But we
definitely can't have it dumping core.
I'm leaning to solution #1 as being the simplest and least likely to
have unforeseen difficulties. I'm not sure if doing the same thing
in the CSV-log patch will be OK though. Comments?
regards, tom lane
Tom Lane wrote: > I came across a problem with the log_timezone patch. Given these > conditions: > * log_min_messages is at least debug3 > * log_line_prefix includes %t or %m > * log_timezone is not explicitly set in postgresql.conf > the postmaster will dump core during startup, because it tries to format > an elog message using log_timezone while the variable is still NULL. > > I can think of several ways of fixing this, but they all have drawbacks: > > 1. Tweak elog.c so that the timestamp-formatting escapes are disregarded > if log_timezone is still NULL. This is simple and robust, but some will > complain that early-startup messages are formatted differently from > those appearing later. I don't put a lot of weight on that, because > it is *necessarily* the case that messages appearing before GUCs are > all initialized will look different from those later. But it's a bit > annoying, and might be more than a bit annoying for CSV-format logging. Any way to tweak this place and have it log in GMT instead, when log_timezone is NULL? That way it would only change the early startup messages (thus avoiding the concern in #2), but it'd still show the timezone (different from the system, but it'd be something deterministic). I think that's better than just dropping the TZ information. If not, I still agree with you that #1 is the best way to go from these. > 2. Tweak pg_localtime() so that it takes a null tz argument as meaning > GMT. I find this one pretty ugly --- it seems to remove a useful error > check even after startup. Also, it's not clear whether having messages > that are labeled in the wrong timezone is better or worse than not > labeling them at all. I'm also a bit worried whether invoking tzload() > too early in startup would work reliably. Depends on what you mean with "wrong timezone". If they're labelled with a timezone that's not the same as the time is in, then it's very very bad because it gives you the wrong time. If you mean labeling them as GMT when the user expected EST (or whatever), think that's better than no TZ at all - as long as we specify the TZ, the time is exact, even if the user may need to do some calculations to figure out it in the local one. I do agree that removing that error check is bad. //Magnus
Magnus Hagander <magnus@hagander.net> writes:
> Any way to tweak this place and have it log in GMT instead, when
> log_timezone is NULL?
I think this is just a variant of my #2. The main risk factor IMHO
is that the first call is going to invoke tzload() for the GMT zone
(pgtz does not seem to special-case GMT in any meaningful way),
and it's not entirely clear how much infrastructure has to be up
before that would work. It's probably all right, seeing that we
won't get here until GUC has set log_line_prefix to something
nondefault, but I haven't tried it.
There's a value judgment involved here: is it better to print timestamps
in GMT (which the user won't be expecting) than to not print them at all?
I can see arguments on both sides of that.
regards, tom lane
On Sat, Aug 04, 2007 at 12:12:46PM -0400, Tom Lane wrote: > There's a value judgment involved here: is it better to print timestamps > in GMT (which the user won't be expecting) than to not print them at all? > I can see arguments on both sides of that. As long as it's clear that the times are in GMT I think that's better. Something else to consider... normally you'd have to have a pretty serious condition to run into this in normal usage, right? (I doubt there's many folks that use any debug level, let alone 3) I think that gives us more flexibility. -- Decibel!, aka Jim Nasby decibel@decibel.org EnterpriseDB http://enterprisedb.com 512.569.9461 (cell)
Decibel! <decibel@decibel.org> writes:
> Something else to consider... normally you'd have to have a pretty
> serious condition to run into this in normal usage, right? (I doubt
> there's many folks that use any debug level, let alone 3) I think that
> gives us more flexibility.
Yeah. This whole issue will really only affect developers, except for
cases where startup fails completely.
I complained earlier that tzload() might be unsafe if invoked too early,
but actually there's a worse issue, which is circularity: it's far from
clear that that code path cannot invoke elog itself. (Even if it doesn't
today, someone might innocently stick a debugging elog into someplace
like get_share_path.) This could be worked around, with some hack on
the order of forcing GMT zone to be loaded before we begin GUC
initialization, but I'm really wondering how much work we want to put
into a marginal nicety.
regards, tom lane
On Sat, Aug 04, 2007 at 12:46:32PM -0400, Tom Lane wrote: > Decibel! <decibel@decibel.org> writes: > > Something else to consider... normally you'd have to have a pretty > > serious condition to run into this in normal usage, right? (I doubt > > there's many folks that use any debug level, let alone 3) I think that > > gives us more flexibility. > > Yeah. This whole issue will really only affect developers, except for > cases where startup fails completely. And when startup fails completely, you're far less likely to care about timezone. Perhaps if we don't have log_timezone set yet we could output something such as 'LOCALTIME' so that it was obvious. Or maybe output whatever $TZ is set to? -- Decibel!, aka Jim Nasby decibel@decibel.org EnterpriseDB http://enterprisedb.com 512.569.9461 (cell)
Decibel! <decibel@decibel.org> writes:
> Perhaps if we don't have log_timezone set yet we could output something
> such as 'LOCALTIME' so that it was obvious. Or maybe output whatever $TZ
> is set to?
I think you're confused. This is not a matter of knowing what to print
for the timezone part, it's how do we print the timestamp at all.
I've got a patch that seems to work, but I'm a bit dissatisfied with
making guc.c explicitly aware of this issue. Haven't thought of a
better place to put the call though...
regards, tom lane
Index: src/backend/utils/error/elog.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/error/elog.c,v
retrieving revision 1.192
diff -c -r1.192 elog.c
*** src/backend/utils/error/elog.c 4 Aug 2007 01:26:54 -0000 1.192
--- src/backend/utils/error/elog.c 4 Aug 2007 17:21:26 -0000
***************
*** 1497,1512 **** { struct timeval tv; pg_time_t
stamp_time; char strfbuf[128], msbuf[8];
gettimeofday(&tv,NULL); stamp_time = (pg_time_t) tv.tv_sec;
pg_strftime(strfbuf,sizeof(strfbuf), /* leave room for milliseconds... */
"%Y-%m-%d %H:%M:%S %Z",
! pg_localtime(&stamp_time, log_timezone)); /* 'paste'
millisecondsinto place... */ sprintf(msbuf, ".%03d", (int) (tv.tv_usec / 1000));
--- 1497,1521 ---- { struct timeval tv; pg_time_t
stamp_time;
+ pg_tz *tz; char strfbuf[128],
msbuf[8]; gettimeofday(&tv, NULL); stamp_time = (pg_time_t) tv.tv_sec;
+ /*
+ * Normally we print log timestamps in log_timezone, but
+ * during startup we could get here before that's set.
+ * If so, fall back to gmt_timezone (which must be set
+ * up already).
+ */
+ tz = log_timezone ? log_timezone : gmt_timezone;
+ pg_strftime(strfbuf, sizeof(strfbuf), /* leave room for
milliseconds...*/ "%Y-%m-%d %H:%M:%S %Z",
! pg_localtime(&stamp_time, tz)); /* 'paste' milliseconds into
place...*/ sprintf(msbuf, ".%03d", (int) (tv.tv_usec / 1000));
***************
*** 1518,1539 **** case 't': { pg_time_t stamp_time = (pg_time_t)
time(NULL); char strfbuf[128]; pg_strftime(strfbuf, sizeof(strfbuf),
"%Y-%m-%d %H:%M:%S %Z",
! pg_localtime(&stamp_time, log_timezone));
appendStringInfoString(buf,strfbuf); } break; case 's': {
pg_time_t stamp_time = (pg_time_t) MyStartTime; char strfbuf[128];
pg_strftime(strfbuf, sizeof(strfbuf), "%Y-%m-%d %H:%M:%S %Z",
! pg_localtime(&stamp_time, log_timezone));
appendStringInfoString(buf,strfbuf); } break;
--- 1527,1554 ---- case 't': { pg_time_t stamp_time = (pg_time_t)
time(NULL);
+ pg_tz *tz; char strfbuf[128];
+ tz = log_timezone ? log_timezone : gmt_timezone;
+ pg_strftime(strfbuf, sizeof(strfbuf), "%Y-%m-%d %H:%M:%S %Z",
! pg_localtime(&stamp_time, tz)); appendStringInfoString(buf,
strfbuf); } break; case 's': { pg_time_t
stamp_time = (pg_time_t) MyStartTime;
+ pg_tz *tz; char strfbuf[128];
+ tz = log_timezone ? log_timezone : gmt_timezone;
+ pg_strftime(strfbuf, sizeof(strfbuf), "%Y-%m-%d %H:%M:%S %Z",
! pg_localtime(&stamp_time, tz)); appendStringInfoString(buf,
strfbuf); } break;
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/misc/guc.c,v
retrieving revision 1.409
diff -c -r1.409 guc.c
*** src/backend/utils/misc/guc.c 4 Aug 2007 01:26:54 -0000 1.409
--- src/backend/utils/misc/guc.c 4 Aug 2007 17:21:27 -0000
***************
*** 2927,2932 ****
--- 2927,2938 ---- long stack_rlimit; /*
+ * Before log_line_prefix could possibly receive a nondefault setting,
+ * make sure that timezone processing is minimally alive (see elog.c).
+ */
+ pg_timezone_pre_initialize();
+
+ /* * Build sorted array of all GUC variables. */ build_guc_variables();
Index: src/include/pgtime.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/pgtime.h,v
retrieving revision 1.16
diff -c -r1.16 pgtime.h
*** src/include/pgtime.h 4 Aug 2007 01:26:54 -0000 1.16
--- src/include/pgtime.h 4 Aug 2007 17:21:27 -0000
***************
*** 52,57 ****
--- 52,58 ---- extern size_t pg_strftime(char *s, size_t max, const char *format, const struct pg_tm * tm);
+ extern void pg_timezone_pre_initialize(void); extern void pg_timezone_initialize(void); extern pg_tz *pg_tzset(const
char*tzname); extern bool tz_acceptable(pg_tz *tz);
***************
*** 64,69 ****
--- 65,71 ---- extern pg_tz *session_timezone; extern pg_tz *log_timezone;
+ extern pg_tz *gmt_timezone; /* Maximum length of a timezone name (not including trailing null) */ #define
TZ_STRLEN_MAX255
Index: src/timezone/pgtz.c
===================================================================
RCS file: /cvsroot/pgsql/src/timezone/pgtz.c,v
retrieving revision 1.52
diff -c -r1.52 pgtz.c
*** src/timezone/pgtz.c 4 Aug 2007 01:26:54 -0000 1.52
--- src/timezone/pgtz.c 4 Aug 2007 17:21:27 -0000
***************
*** 33,38 ****
--- 33,41 ---- /* Current log timezone (controlled by log_timezone GUC) */ pg_tz *log_timezone = NULL;
+ /* UTC (a/k/a GMT) as a pg_tz struct */
+ pg_tz *gmt_timezone = NULL;
+ static char tzdir[MAXPGPATH]; static bool done_tzdir = false;
***************
*** 1251,1256 ****
--- 1254,1280 ---- return NULL; /* keep compiler quiet */ }
+
+ /*
+ * Pre-initialize timezone library
+ *
+ * This is called before GUC variable initialization begins. Its purpose
+ * is to ensure that elog.c has a pgtz variable available to format timestamps
+ * with, in case log_line_prefix is set to a value requiring that. We cannot
+ * set log_timezone yet.
+ */
+ void
+ pg_timezone_pre_initialize(void)
+ {
+ /*
+ * Note: we don't insist on tz_acceptable() for the GMT zone, because
+ * we won't actually do any interesting arithmetic with it.
+ */
+ gmt_timezone = pg_tzset("GMT");
+ if (!gmt_timezone) /* probably shouldn't happen */
+ elog(FATAL, "could not initialize GMT timezone");
+ }
+ /* * Initialize timezone library *