Re: Problem with log_timezone not being set during early startup

Decibel! <decibel(at)decibel(dot)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
*