Thread: BUG #15547: default timezone on servers running while time changedfrom PDT to PST reverting to UTC.

The following bug has been logged on the website:

Bug reference:      15547
Logged by:          Matteo Bignotti
Email address:      gugoll@gmail.com
PostgreSQL version: 9.6.1
Operating system:   CentOS 7
Description:

I have a bunch of servers that never restarted in the past couple of months
and had postgres running since before Nov. 4th and I discovered that their
default timezone changed in the background.

● postgresql.service - PostgreSQL database server
[...]
   Active: active (running) since Tue 2018-10-23 15:52:42 PDT; 1 months 18
days ago

in postgresql.conf the value of timezone and log_timezone is set to
"localtime" and I have a symlink in /usr/share/zoneinfo/ that points at the
timezone I want (also I know that's how Debian handles it). This works fine,
always, except in this situation I cannot seem to reproduce in any way. A
simple restart of postgres fixes the situation, but that's not what I wanted
to do.

I run these queries on 2 different servers in the America/Los_Angeles
timezone: psql [credentials] -c "SELECT now();" -c "show timezone;" -c
"SELECT timezone('UTC', now()) as UTC"

[no bug]
              now
-------------------------------
 2018-12-11 16:02:11.783056-08
(1 row)
 TimeZone
-----------
 localtime
(1 row)
            utc
----------------------------
 2018-12-12 00:02:11.823465
(1 row)

[with bug]
              now
-------------------------------
 2018-12-12 00:03:30.970079+00
(1 row)
 TimeZone
-----------
 localtime
(1 row)
            utc
----------------------------
 2018-12-12 00:03:30.971193
(1 row)

I really blame this situation on DST simply because that's the only thing
that happened in this timeframe that could've caused a timezone "flop".

both servers point to America/Los_Angeles and this server "with bug" is the
last one I have that exhibits, all my attempts at reproducing this have been
in vain.

Thank you


=?utf-8?q?PG_Bug_reporting_form?= <noreply@postgresql.org> writes:
> I have a bunch of servers that never restarted in the past couple of months
> and had postgres running since before Nov. 4th and I discovered that their
> default timezone changed in the background.

Hmph.  Ordinarily I'd expect that the default zone data would be cached
in the postmaster and inherited via fork() by backends, so that as long
as you didn't do something like change the timezone setting in
postgresql.conf, the behavior would be stable until postmaster restart.
(People who live in zones with frequent DST law changes have complained
of that ... but I'm not very much in a hurry to change it.)

So it's not at all clear what happened here.  I think that Red Hat did
push out a tzdata update in early November, but even so, the behavior
of America/Los_Angeles shouldn't have changed.  *Maybe* this could
be explained by having restarted those postmasters during the tiny
interval where the package update was happening and there wasn't anything
valid for /etc/localtime to point at --- but that stretches credulity.

If you can figure out a way to reproduce this, we'd be interested to
hear what it is.

            regards, tom lane


Thanks for the quick response.

I thought the same thing about tzdata but I didn't update that on any servers in that timeframe, the servers are only updated manually and the only package that I added was "psmisc-22.20-15.el7.x86_64" on Nov 14th.

Additionally, the service postgresql has been reloaded several times (but never restarted), I even tried reloading now and keeps its "bug".
I did notice, skimming through the source, that when loading the timezone there's a check to make sure the timezone selected "makes sense" otherwise defaults to UTC, but what throws me off is that querying the database still returns my original 'timezone' and not 'utc'.

Some more info:

this is the PS situation on that server:

postgres  5236  0.0  0.2 342980  4852 ?        S    Oct23  20:02 /usr/bin/postgres -D /var/lib/pgsql/data
postgres  5288  0.0  0.0 195440  1004 ?        Ss   Oct23   0:00  \_ postgres: logger process
postgres  5298  0.0  0.8 343388 15256 ?        Ss   Oct23   0:53  \_ postgres: checkpointer process
postgres  5299  0.0  0.1 342980  2008 ?        Ss   Oct23   0:25  \_ postgres: writer process
postgres  5300  0.0  0.2 342980  5212 ?        Ss   Oct23   1:36  \_ postgres: wal writer process
postgres  5301  0.0  0.0 343504  1708 ?        Ss   Oct23   1:20  \_ postgres: autovacuum launcher process
postgres  5302  0.0  0.0 195828  1356 ?        Ss   Oct23   9:22  \_ postgres: stats collector process
postgres 17078  0.0  0.1 344052  2224 ?        Ss   Oct23   0:00  \_ postgres: postgres dbbase [local] idle
postgres 31257  0.0  0.0 343808  1304 ?        Ss   Dec05   0:00  \_ postgres: postgres dbbase 127.0.0.1(39728) idle
postgres 31258  0.0  0.0 343808  1300 ?        Ss   Dec05   0:00  \_ postgres: postgres dbbase 127.0.0.1(39732) idle
postgres 19698  0.3  0.7 347208 14360 ?        Ss   Dec07  18:51  \_ postgres: postgres dbbase [local] idle
postgres 10441  0.0  0.2 344052  5580 ?        Ss   17:13   0:00  \_ postgres: postgres dbbase [local] idle


and netstat

# netstat -antup | grep 5432
tcp        0      0 127.0.0.1:5432          0.0.0.0:*               LISTEN      5236/postgres
tcp        0      0 127.0.0.1:5432          127.0.0.1:39732         ESTABLISHED 31258/postgres: pos
tcp        0      0 127.0.0.1:5432          127.0.0.1:39728         ESTABLISHED 31257/postgres: pos
tcp        0      0 127.0.0.1:39732         127.0.0.1:5432          ESTABLISHED 31253/sm
tcp        0      0 127.0.0.1:39728         127.0.0.1:5432          ESTABLISHED 31251/c2s
tcp6       0      0 ::1:5432                :::*                    LISTEN      5236/postgres




So far I've tried faking time with both changing the time manually and using ntp, but no matter what, the processes catch up to the real time, so it's not a good test... and now I  have placed a server in a closed environment and made it believe it's Oct. 31st, turned off ntp, and I'll keep observing.
If you guys can think of any additional logging/test I could turn on/launch over there to make sure I track this possible behavior, that'd be cool

Thank you :)


On Tue, Dec 11, 2018 at 4:46 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
PG Bug reporting form <noreply@postgresql.org> writes:
> I have a bunch of servers that never restarted in the past couple of months
> and had postgres running since before Nov. 4th and I discovered that their
> default timezone changed in the background.

Hmph.  Ordinarily I'd expect that the default zone data would be cached
in the postmaster and inherited via fork() by backends, so that as long
as you didn't do something like change the timezone setting in
postgresql.conf, the behavior would be stable until postmaster restart.
(People who live in zones with frequent DST law changes have complained
of that ... but I'm not very much in a hurry to change it.)

So it's not at all clear what happened here.  I think that Red Hat did
push out a tzdata update in early November, but even so, the behavior
of America/Los_Angeles shouldn't have changed.  *Maybe* this could
be explained by having restarted those postmasters during the tiny
interval where the package update was happening and there wasn't anything
valid for /etc/localtime to point at --- but that stretches credulity.

If you can figure out a way to reproduce this, we'd be interested to
hear what it is.

                        regards, tom lane
Matteo <gugoll@gmail.com> writes:
> I thought the same thing about tzdata but I didn't update that on any
> servers in that timeframe, the servers are only updated manually and the
> only package that I added was "psmisc-22.20-15.el7.x86_64" on Nov 14th.

Hm.  Just to clarify: do you believe that the servers with the wrong
timezone behavior actually changed behavior sometime after being started?
It'd be way easier to believe that they'd been wrong since postmaster
start.  Also, do you have the postmaster logs going back to startup?
It'd be interesting to check for possible error/warning messages at
postmaster start, and/or whenever the behavior changed.

            regards, tom lane


Yeah what's wrong definitely happened post start, because I replicate machines from the same codebase/kickstart every time, so I'm sure they're fine on install/boot. And this same thing happened on virtual and physical machines. Unfortunately I had no logs, because this bug was discovered about a month after the time switch, recent logs were no help and also journal had rotated several times over, so no luck there :(

thank you very much

Teo

On Wed, Dec 12, 2018 at 6:38 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:
Matteo <gugoll@gmail.com> writes:
> I thought the same thing about tzdata but I didn't update that on any
> servers in that timeframe, the servers are only updated manually and the
> only package that I added was "psmisc-22.20-15.el7.x86_64" on Nov 14th.

Hm.  Just to clarify: do you believe that the servers with the wrong
timezone behavior actually changed behavior sometime after being started?
It'd be way easier to believe that they'd been wrong since postmaster
start.  Also, do you have the postmaster logs going back to startup?
It'd be interesting to check for possible error/warning messages at
postmaster start, and/or whenever the behavior changed.

                        regards, tom lane


--
Matteo