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.pid file. This prevents problems with boot scripts that
* expect the pidfile to appear quickly. Also, we avoid problems 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

Search Discussions

  • Magnus Hagander at Aug 4, 2007 at 3:46 pm

    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
  • Tom Lane at Aug 4, 2007 at 4:13 pm

    Magnus Hagander 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
  • Decibel! at Aug 4, 2007 at 4:31 pm

    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)
  • Tom Lane at Aug 4, 2007 at 4:47 pm

    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
  • Decibel! at Aug 4, 2007 at 4:50 pm

    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)
  • Tom Lane at Aug 4, 2007 at 6:26 pm

    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' milliseconds into 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_MAX 255
    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
    *

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
grouppgsql-hackers @
categoriespostgresql
postedAug 4, '07 at 3:10p
activeAug 4, '07 at 6:26p
posts7
users3
websitepostgresql.org...
irc#postgresql

People

Translate

site design / logo © 2022 Grokbase