17 January 2014, 16:26

Hi All,
Running Mahara 1.7.1 on Redhat Linux and encountering an issue with timestamps - the server time is set correctly to Australia/Adelaide (in both the settings and php.ini) and the PostGreSQL database is also set to that timezone. However Journal posts and forum topics are timestamped with a time in the future - so for example a journal entry I created at 1:45PM this afternoon was timestamped as Tomorrow at 12:15AM!

Since Adelaide is GMT +1030 and it appears to be adding on another 8 and a half hours, I'd suspect something funny is happening in Mahara to add more time on. I've tested this in our production environment in 1.7.1 and test which is 1.8.0. Any thoughts on what might be causing this?

Thanks,

Scott

21 January 2014, 12:02

Hi Scott,

I'd recommend double-checking that the timezone is the same on your web server and DB server. There is a known bug where you get exactly the kind of offset problems you're describing, if the timezone of the DB and the web server is not the same: https://bugs.launchpad.net/mahara/+bug/1187212

There's a patch for that in our Gerrit code review system, which would allow you to manually tell the DB server what time zone it should use. https://reviews.mahara.org/#/c/2257/

Cheers,

Aaron

22 January 2014, 14:09

Hi Aaron,

Cheers for that - I gave the $cfg->dbtimezone fix a go, but it didn't make any difference. I was triple checking the database timezone when I noticed the following:

Note that the blogpost I made at 10:47AM Adelaide time has a ctime (which should be in UTC) of 10:47AM as well.

Could this be a database issue or a code issue? I checked the code for blogs (although this happens with forum posts as well) and when inserting records there appears to be no manipulation of the ctime. So what's happening is the timezone is being added on twice - written to the database with it, then displayed with it added again.

Any thoughts?

Cheers,

Scott

22 January 2014, 16:45

Hi Scott,

That's the expected thing to see. To be sure, I tested this same thing on my local dev site. Inserted a new forum post into my Mahara at 4:23pm NZ time, then I looked in interaction_forum_post, and I see the time listed there as "2013-1-22 16:23:05". Then when I look at that forum post in the web browser, I see "Today, 4:23pm".

In Postgres, a "timestamp without time zone" is more or less kind of like a string that just reads "2013-1-22 14:23:05", with no time zone on it. When we later retrieve these values to use them in Mahara, we tell Postgres to convert them into a Unix epoch, using "EXTRACT(EPOCH FROM {$fieldname})". At that time, Postgres converts it from a "timestamp without time zone" to a "timestamp with time zone" by assuming that the time in the string is in the local time zone (which you can override with $cfg->dbtimezone), and then it converts that time with timezone into a Unix epoch. This behavior is kind of hinted at in the Postgres manual when it says that timestamps without time zones are converted into the system timezone when displayed: http://www.postgresql.org/docs/9.1/static/datatype-datetime.html

So for instance if you do "SELECT ctime FROM artefact WHERE id=3422", and then you change your timezone with "SET TIME ZONE UTC;" and repeat the select statement, you won't see any difference, it'll still show "2011-03-04 10:59:08".

But, if you do "SELECT EXTRACT(EPOCH FROM ctime) FROM artefact WHERE id=3422;", before and after changing your time zone, you will notice that the output is different.

Basically, the lifecycle of a Mahara timestamp is as follows:

1. We get the time from PHP using the time() function, which gives us the server's time as a Unix epoch.

2. We convert that to a string showing the time in the local (PHP) timezone, using the PHP function strftime().

3. We insert this into Postgres as a "timestamp without time zone"

4. Later, we retrieve it from Postgres using "EXTRACT(EPOCH FROM {$field})"

4a. This causes Postgres to convert the time to a "timestamp with time zone" by assuming it's a time in Postgres's timezone.

4b. Postgres then takes that timestamp with time zone and converts it to a Unix epoch.

5. Lastly, to display the time to the users, we take the epoch value we got from Postgres, and we again run it through strftime() to turn it into a human-readable time, using the local PHP timezone.

So, doing a little math on paper, I can see that if the time zone in PHP and the time zone in Postgres are different, it all goes smoothly until step 4a. At that point, Postgres will convert the timestamp to its own time zone instead of PHP's time zone. This will result in adding (Postgres UTC offset - PHP UTC offset) to every date displayed to the user.

Based on that formula, since you're seeing +10:30 added to your dates, it sounds like your Postgres timezone is correct at +10:30, while your PHP timezone is 0:00, UTC.

So, if you haven't already, try checking what you see in "default.timezone" from your phpinfo(), and try adding this to your config.php: date_default_timezone_set("Australia/Adelaide");

Sorry for writing such a long reply!

Cheers,

Aaron

23 January 2014, 13:09

Hi Aaron,

No worries with the long reply - very informative!

I see what you mean with how Mahara handles the time, so my suspicion is PHP isn't clever enough to figure out that Australia/South and Australia/Adelaide are the same thing. Looking in the server settings it doesn't recognise Australia/South (only Adelaide) so I'm going to try having everything - including PHP and the pg database - set to Australia/Adelaide.

Cheers,

Scott

23 January 2014, 14:31

Since this one has come up a few times, I've also added it to the Mahara troubleshooting page: https://wiki.mahara.org/index.php/System_Administrator%27s_Guide/Installing_Mahara/Troubleshooting#Q:_Time_zone_problems_.2F_Mahara_is_showing_incorrect_times_for_forum_posts

20 February 2014, 12:28

Hi Aaron,

Hate to drag this back up but after waiting for a while to get our Database Administrators to change the timezone on our PGSQL instance, we finally got to the point where the following was correct:

• Database TZ: Australia/Adelaide
• PHP default_timezone: Australia/Adelaide
• Apache Server timezone: Australia/Adelaide

And unfortunately our timestamps were still ten and a half hours ahead of where they should be.

So now what I've done is set the PHP default_timezone to Europe/London (e.g. GMT +0) and now the timestamps are coming up correctly.

Does this mean that the database and PHP don't read Australia/Adelaide the same way? In your wiki post this seems to indicate that the following is happening: 

This suggests that the database's time is correct at UTC-08:00, but PHP's time is incorrectly set to UTC+00:00, (-8 - 0) = -8. If instead the database's time had been wrong and PHP's time was correct, the offset would be (0 -(-8)) = 8, so all times would be 8 hours ahead.

And in my case it's going (+10:30, +10:30) = +21, whereas if I set PHP to GMT +0 it's still doing the offset but it's working out to (+10:30, +0) = +10:30.

Sorry if I'm being dense about this but PGSQL and PHP/Mahara aren't agreeing on what timezone Australia/Adelaide is! :) What sort of entry would I see in the logs if PGSQL and PHP don't agree on the timezone? Would it come up at all?

Cheers,

Scott

21 February 2014, 13:12

Well, "Australia/Adelaide" is on the list in the PHP manual, so that should be correct for PHP. But, you can use the timezone_identifiers_list() method to be sure, which should list all valid timezones. I believe PHP will not complain if you enter an incorrect timezone. There's also a mention that prior to PHP 5.4.0, date.timezone will be ignored if the TZ environment variable is set.

For postgres, the manual says that all valid timezones are listed in the "pg_timezone_names" view, and I do see "Australia/Adelaide" listed there as well on my server, although you should probably check that on your server.

If you enter an invalid timezone into Postgres, it'll silently accept it while treating it as UTC. This actually sounds like it may be what's going on in your case. If Postgres is not recognizing "Australia/Adelaide", and giving you times in UTC, then if you set PHP to UTC as well, you'll get 0-0 = 0, correct times.

Were you seeing times that were off by 21 hours? The only example you mentioned was in your first comment, where it was off by +10:30. If you're getting a 21 hour offset, then there may be something else going on as well, or maybe my math was wrong.

Cheers,

Aaron

25 February 2014, 12:48

Hi Aaron,

The time was off by 21 hours, but that's 21 hours off of GMT (which is why I kept talking about 10:30, since it'd be 10:30 added on twice).

I'll have a word with our DBAs to take a look at the postgres view table and I'll check that php method as well, thanks!