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

=?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:

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