Topic: Time Problems and No Webmail

[devtay]

Hello,

I opened a bug on this and it was closed as not a bug (http://bugs.contribs.org/show_bug.cgi?id=8269) . I was advised to seek help here so here goes.

Problem:

I was verifying the date and time change on this past Sunday and noted the time was showing up wrong in the date and time panel of server manager. I SSH'd in and did date from the console and sure enough, it was wrong. I used date from the console to set the date and time and didn't think more about it until arriving to work on Monday. On Monday the date and time was again wrong and the date and time on the emails sent/received by my server were also wrong. I then went back and checked the date and time panel in server manager and it was wrong. To fix the date and time and allow myself some time to look into the problem, I disabled the NTP server and set the time to local time with the correct time zone.

Did some looking on bugzilla, forums and my logs and found out some good info. I was able to verify my time zone was correctly setup:

Code: [Select]

[root@]# ls -l /etc/localtime
lrwxrwxrwx 1 root root 37 Mar  5 07:42 /etc/localtime -> ../usr/share/zoneinfo/America/Chicago
and that my ntpd service was not working correctly since a power failure earlier in the week. The DNS resolution issue noted was due to ISP maintenance and is not significant in my mind.

Code: [Select]

2014-03-06 02:07:52.778296500 Error : Name or service not known
2014-03-06 02:07:52.778373500  6 Mar 02:07:52 ntpdate[3762]: can't find host 0.smeserver.pool.ntp.org
2014-03-06 02:07:52.778377500
2014-03-06 02:07:52.778385500  6 Mar 02:07:52 ntpdate[3762]: no servers can be used, exiting
2014-03-06 02:07:53.307829500  6 Mar 02:07:53 ntpd[3751]: logging to file /dev/stdout
2014-03-06 02:07:53.696316500  6 Mar 02:07:53 ntpd[3751]: precision = 1.000 usec
2014-03-06 02:07:53.703222500  6 Mar 02:07:53 ntpd[3751]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
2014-03-06 02:07:53.703224500  6 Mar 02:07:53 ntpd[3751]: Listening on interface wildcard, 0.0.0.0#123 Disabled
2014-03-06 02:07:53.703225500  6 Mar 02:07:53 ntpd[3751]: Listening on interface lo, 127.0.0.1#123 Enabled
2014-03-06 02:07:53.703226500  6 Mar 02:07:53 ntpd[3751]: Listening on interface eth0, 192.168.2.247#123 Enabled
2014-03-06 02:07:53.703227500  6 Mar 02:07:53 ntpd[3751]: Listening on interface eth1, 12.171.178.34#123 Enabled
2014-03-06 02:07:53.703234500  6 Mar 02:07:53 ntpd[3751]: kernel time sync status 0040
2014-03-06 02:08:08.517799500  6 Mar 02:08:08 ntpd[3751]: frequency initialized 151.799 PPM from /etc/ntp/drift
2014-03-06 02:11:24.698050500  6 Mar 02:11:24 ntpd[3751]: synchronized to LOCAL(0), stratum 10
2014-03-06 02:11:24.698052500  6 Mar 02:11:24 ntpd[3751]: kernel time sync enabled 0001
2014-03-06 02:13:33.697740500  6 Mar 02:13:33 ntpd[3751]: synchronized to 108.61.73.243, stratum 2
2014-03-06 08:07:48.766224500 Error : Name or service not known
2014-03-06 08:07:48.799275500  6 Mar 08:07:48 ntpdate[3750]: can't find host 0.smeserver.pool.ntp.org
2014-03-06 08:07:48.799278500
2014-03-06 08:07:48.799278500  6 Mar 08:07:48 ntpdate[3750]: no servers can be used, exiting
2014-03-06 08:07:49.265210500  6 Mar 08:07:49 ntpd[3739]: logging to file /dev/stdout
2014-03-06 08:07:49.782634500  6 Mar 08:07:49 ntpd[3739]: precision = 1.000 usec
2014-03-06 08:07:49.789845500  6 Mar 08:07:49 ntpd[3739]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
2014-03-06 08:07:49.789872500  6 Mar 08:07:49 ntpd[3739]: Listening on interface wildcard, 0.0.0.0#123 Disabled
2014-03-06 08:07:49.789888500  6 Mar 08:07:49 ntpd[3739]: Listening on interface lo, 127.0.0.1#123 Enabled
2014-03-06 08:07:49.789904500  6 Mar 08:07:49 ntpd[3739]: Listening on interface eth0, 192.168.2.247#123 Enabled
2014-03-06 08:07:49.789921500  6 Mar 08:07:49 ntpd[3739]: Listening on interface eth1, 12.171.178.34#123 Enabled
2014-03-06 08:07:49.789948500  6 Mar 08:07:49 ntpd[3739]: kernel time sync status 0040
2014-03-06 08:08:05.117662500  6 Mar 08:08:05 ntpd[3739]: frequency initialized 71.201 PPM from /etc/ntp/drift
2014-03-06 08:11:21.784687500  6 Mar 08:11:21 ntpd[3739]: synchronized to LOCAL(0), stratum 10
2014-03-06 08:11:21.784708500  6 Mar 08:11:21 ntpd[3739]: kernel time sync enabled 0001
I then thought it was a hardware clock issue. I scheduled some down time for this morning and checked the motherboard clock. It was set to UTC so I set it to local time and rebooted the server. I think that may have been a mistake because now I can't use webmail and I get the following messages over and over in my messages log:

Code: [Select]

Mar 11 13:49:55 ftmain httpd: PHP Warning:  strftime() [<a href='function.strftime'>function.strftime</a>]: It is not safe to rely on the system's timezone settings. You are *required* to use the date.timezone setting or the date_default_timezone_set() function. In case you used any of those methods and you are still getting this warning, you most likely misspelled the timezone identifier. We selected 'UTC' for 'UTC/0.0/no DST' instead in /home/httpd/html/horde/imp/config/prefs.php on line 1427

Code: [Select]

Mar 11 14:10:01 ftmain php: PHP Warning:  strftime(): It is not safe to rely on the system's timezone settings. You are *required* to use the date.timezone setting or the date_default_timezone_set() function. In case you used any of those methods and you are still getting this warning, you most likely misspelled the timezone identifier. We selected 'UTC' for 'UTC/0.0/no DST' instead in /home/httpd/html/horde/config/prefs.php on line 285


Code: [Select]

Mar 11 14:01:31 ftmain httpd: PHP Fatal error:  Uncaught exception 'Exception' with message 'DateTime::__construct() [<a href='datetime.--construct'>datetime.--construct</a>]: It is not safe to rely on the system's timezone settings. You are *required* to use the date.timezone setting or the date_default_timezone_set() function. In case you used any of those methods and you are still getting this warning, you most likely misspelled the timezone identifier. We selected 'UTC' for 'UTC/0.0/no DST' instead' in /home/httpd/html/horde/lib/Horde/Date.php:539 Stack trace: #0 /home/httpd/html/horde/lib/Horde/Date.php(539): DateTime->__construct() #1 /home/httpd/html/horde/lib/Horde/Date.php(590): Horde_Date->format('Y-m-d H:i:s') #2 /home/httpd/html/horde/lib/Horde/Alarm/sql.php(143): Horde_Date->sqlDateTime() #3 /home/httpd/html/horde/lib/Horde/Alarm.php(275): Horde_Alarm_sql->_list(false, Object(Horde_Date)) #4 /home/httpd/html/horde/lib/Horde/Alarm.php(321): Horde_Alarm->listAlarms(false, NULL, true, true) #5 /home/
The date and time panel is also showing UTC time, not the correct time for my location. I have restarted the server, stopped then restarted the ntpd, and I'm thinking disabling the NTP server again and setting local time. All of my PHP applications are using the system time and now they are all reporting UTC as well.

Since last night, this is my current ntpd log:

Code: [Select]

2014-03-10 22:25:59.851093500 10 Mar 17:25:59 ntpd[3739]: ntpd exiting on signal 15
2014-03-10 22:25:59.861223500 10 Mar 22:25:59 ntpdate[23011]: no servers can be used, exiting
2014-03-10 22:25:59.864260500 10 Mar 22:25:59 ntpd[23008]: logging to file /dev/stdout
2014-03-10 22:25:59.866779500 10 Mar 22:25:59 ntpd[23008]: precision = 1.000 usec
2014-03-10 22:25:59.873615500 10 Mar 22:25:59 ntpd[23008]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
2014-03-10 22:25:59.873638500 10 Mar 22:25:59 ntpd[23008]: Listening on interface wildcard, 0.0.0.0#123 Disabled
2014-03-10 22:25:59.873654500 10 Mar 22:25:59 ntpd[23008]: Listening on interface lo, 127.0.0.1#123 Enabled
2014-03-10 22:25:59.873678500 10 Mar 22:25:59 ntpd[23008]: Listening on interface eth0, 192.168.2.247#123 Enabled
2014-03-10 22:25:59.873701500 10 Mar 22:25:59 ntpd[23008]: Listening on interface eth1, 12.171.178.34#123 Enabled
2014-03-10 22:25:59.873724500 10 Mar 22:25:59 ntpd[23008]: kernel time sync status 0040
2014-03-10 22:25:59.874113500 10 Mar 22:25:59 ntpd[23008]: frequency initialized 71.201 PPM from /etc/ntp/drift
2014-03-10 17:37:05.526690500 10 Mar 17:37:05 ntpd[23008]: synchronized to LOCAL(0), stratum 10
2014-03-10 17:37:05.526708500 10 Mar 17:37:05 ntpd[23008]: kernel time sync enabled 0001
2014-03-10 17:40:40.598673500 10 Mar 17:40:40 ntpd[23008]: ntpd exiting on signal 15
2014-03-10 17:40:41.611008500 10 Mar 17:40:41 ntpdate[24214]: no servers can be used, exiting
2014-03-10 17:40:41.614105500 10 Mar 17:40:41 ntpd[24211]: logging to file /dev/stdout
2014-03-10 17:40:41.616734500 10 Mar 17:40:41 ntpd[24211]: precision = 1.000 usec
2014-03-10 17:40:41.623310500 10 Mar 17:40:41 ntpd[24211]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
2014-03-10 17:40:41.623333500 10 Mar 17:40:41 ntpd[24211]: Listening on interface wildcard, 0.0.0.0#123 Disabled
2014-03-10 17:40:41.623349500 10 Mar 17:40:41 ntpd[24211]: Listening on interface lo, 127.0.0.1#123 Enabled
2014-03-10 17:40:41.623363500 10 Mar 17:40:41 ntpd[24211]: Listening on interface eth0, 192.168.2.247#123 Enabled
2014-03-10 17:40:41.623378500 10 Mar 17:40:41 ntpd[24211]: Listening on interface eth1, 12.171.178.34#123 Enabled
2014-03-10 17:40:41.623400500 10 Mar 17:40:41 ntpd[24211]: kernel time sync status 0040
2014-03-10 17:40:41.623817500 10 Mar 17:40:41 ntpd[24211]: frequency initialized 71.201 PPM from /etc/ntp/drift
2014-03-10 17:41:13.561970500 10 Mar 17:41:13 ntpd[24211]: ntpd exiting on signal 15
2014-03-10 22:41:36.185011500 10 Mar 22:41:36 ntpdate[24330]: step time server 192.168.2.244 offset 18022.505365 sec
2014-03-10 22:41:36.188234500 10 Mar 22:41:36 ntpd[24327]: logging to file /dev/stdout
2014-03-10 22:41:36.190866500 10 Mar 22:41:36 ntpd[24327]: precision = 1.000 usec
2014-03-10 22:41:36.197893500 10 Mar 22:41:36 ntpd[24327]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
2014-03-10 22:41:36.197915500 10 Mar 22:41:36 ntpd[24327]: Listening on interface wildcard, 0.0.0.0#123 Disabled
2014-03-10 22:41:36.197932500 10 Mar 22:41:36 ntpd[24327]: Listening on interface lo, 127.0.0.1#123 Enabled
2014-03-10 22:41:36.197947500 10 Mar 22:41:36 ntpd[24327]: Listening on interface eth0, 192.168.2.247#123 Enabled
2014-03-10 22:41:36.197961500 10 Mar 22:41:36 ntpd[24327]: Listening on interface eth1, 12.171.178.34#123 Enabled
2014-03-10 22:41:36.197983500 10 Mar 22:41:36 ntpd[24327]: kernel time sync status 0040
2014-03-10 22:41:36.198487500 10 Mar 22:41:36 ntpd[24327]: frequency initialized 71.201 PPM from /etc/ntp/drift
2014-03-10 22:44:55.192557500 10 Mar 22:44:55 ntpd[24327]: synchronized to LOCAL(0), stratum 10
2014-03-10 22:44:55.192574500 10 Mar 22:44:55 ntpd[24327]: kernel time sync disabled 0001
2014-03-11 12:06:28.678934500 11 Mar 12:06:28 ntpdate[3872]: no server suitable for synchronization found
2014-03-11 12:06:29.187478500 11 Mar 12:06:29 ntpd[3861]: logging to file /dev/stdout
2014-03-11 12:06:29.706089500 11 Mar 12:06:29 ntpd[3861]: precision = 1.000 usec
2014-03-11 12:06:29.713038500 11 Mar 12:06:29 ntpd[3861]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
2014-03-11 12:06:29.713063500 11 Mar 12:06:29 ntpd[3861]: Listening on interface wildcard, 0.0.0.0#123 Disabled
2014-03-11 12:06:29.713078500 11 Mar 12:06:29 ntpd[3861]: Listening on interface lo, 127.0.0.1#123 Enabled
2014-03-11 12:06:29.713125500 11 Mar 12:06:29 ntpd[3861]: Listening on interface eth0, 192.168.2.247#123 Enabled
2014-03-11 12:06:29.713139500 11 Mar 12:06:29 ntpd[3861]: Listening on interface eth1, 12.171.178.34#123 Enabled
2014-03-11 12:06:29.713172500 11 Mar 12:06:29 ntpd[3861]: kernel time sync status 0040
2014-03-11 12:06:29.810172500 11 Mar 12:06:29 ntpd[3861]: frequency initialized 71.201 PPM from /etc/ntp/drift
2014-03-11 07:36:00.692199500 11 Mar 07:36:00 ntpdate[3758]: no server suitable for synchronization found
2014-03-11 07:36:01.337926500 11 Mar 07:36:01 ntpd[3743]: logging to file /dev/stdout
2014-03-11 07:36:01.767784500 11 Mar 07:36:01 ntpd[3743]: precision = 1.000 usec
2014-03-11 07:36:01.774927500 11 Mar 07:36:01 ntpd[3743]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
2014-03-11 07:36:01.774931500 11 Mar 07:36:01 ntpd[3743]: Listening on interface wildcard, 0.0.0.0#123 Disabled
2014-03-11 07:36:01.774932500 11 Mar 07:36:01 ntpd[3743]: Listening on interface lo, 127.0.0.1#123 Enabled
2014-03-11 07:36:01.774933500 11 Mar 07:36:01 ntpd[3743]: Listening on interface eth0, 192.168.2.247#123 Enabled
2014-03-11 07:36:01.774933500 11 Mar 07:36:01 ntpd[3743]: Listening on interface eth1, 12.171.178.34#123 Enabled
2014-03-11 07:36:01.774955500 11 Mar 07:36:01 ntpd[3743]: kernel time sync status 0040
2014-03-11 07:36:02.108124500 11 Mar 07:36:02 ntpd[3743]: frequency initialized 71.201 PPM from /etc/ntp/drift
2014-03-11 07:39:14.768811500 11 Mar 07:39:14 ntpd[3743]: synchronized to LOCAL(0), stratum 10
2014-03-11 07:39:14.768842500 11 Mar 07:39:14 ntpd[3743]: kernel time sync enabled 0001
2014-03-11 07:39:29.328503500 11 Mar 07:39:29 ntpd[3743]: ntpd exiting on signal 15
2014-03-11 12:39:35.081980500 11 Mar 12:39:35 ntpdate[4991]: step time server 199.102.46.72 offset 18000.220165 sec
2014-03-11 12:39:35.085263500 11 Mar 12:39:35 ntpd[4988]: logging to file /dev/stdout
2014-03-11 12:39:35.087967500 11 Mar 12:39:35 ntpd[4988]: precision = 1.000 usec
2014-03-11 12:39:35.095276500 11 Mar 12:39:35 ntpd[4988]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
2014-03-11 12:39:35.095300500 11 Mar 12:39:35 ntpd[4988]: Listening on interface wildcard, 0.0.0.0#123 Disabled
2014-03-11 12:39:35.095315500 11 Mar 12:39:35 ntpd[4988]: Listening on interface lo, 127.0.0.1#123 Enabled
2014-03-11 12:39:35.095329500 11 Mar 12:39:35 ntpd[4988]: Listening on interface eth0, 192.168.2.247#123 Enabled
2014-03-11 12:39:35.095342500 11 Mar 12:39:35 ntpd[4988]: Listening on interface eth1, 12.171.178.34#123 Enabled
2014-03-11 12:39:35.095365500 11 Mar 12:39:35 ntpd[4988]: kernel time sync status 0040
2014-03-11 12:39:35.647102500 11 Mar 12:39:35 ntpd[4988]: frequency initialized 71.201 PPM from /etc/ntp/drift
2014-03-11 12:42:49.130243500 11 Mar 12:42:49 ntpd[4988]: synchronized to 69.55.54.17, stratum 2
2014-03-11 12:42:49.130263500 11 Mar 12:42:49 ntpd[4988]: kernel time sync disabled 0001
2014-03-11 12:54:46.089463500 11 Mar 12:54:46 ntpd[4988]: synchronized to 108.61.73.243, stratum 2
2014-03-11 13:07:28.131697500 11 Mar 13:07:28 ntpd[4988]: synchronized to 69.55.54.17, stratum 2
2014-03-11 13:10:59.089657500 11 Mar 13:10:59 ntpd[4988]: synchronized to 108.61.73.243, stratum 2
2014-03-11 13:55:06.089730500 11 Mar 13:55:06 ntpd[4988]: synchronized to 69.55.54.17, stratum 2
2014-03-11 14:00:00.473164500 11 Mar 14:00:00 ntpd[4988]: ntpd exiting on signal 15
2014-03-11 14:00:09.875179500 11 Mar 14:00:09 ntpdate[19666]: step time server 199.241.31.224 offset -0.006551 sec
2014-03-11 14:00:09.878597500 11 Mar 14:00:09 ntpd[19662]: logging to file /dev/stdout
2014-03-11 14:00:09.881386500 11 Mar 14:00:09 ntpd[19662]: precision = 1.000 usec
2014-03-11 14:00:09.888790500 11 Mar 14:00:09 ntpd[19662]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
2014-03-11 14:00:09.888813500 11 Mar 14:00:09 ntpd[19662]: Listening on interface wildcard, 0.0.0.0#123 Disabled
2014-03-11 14:00:09.888830500 11 Mar 14:00:09 ntpd[19662]: Listening on interface lo, 127.0.0.1#123 Enabled
2014-03-11 14:00:09.888845500 11 Mar 14:00:09 ntpd[19662]: Listening on interface eth0, 192.168.2.247#123 Enabled
2014-03-11 14:00:09.888859500 11 Mar 14:00:09 ntpd[19662]: Listening on interface eth1, 12.171.178.34#123 Enabled
2014-03-11 14:00:09.888882500 11 Mar 14:00:09 ntpd[19662]: kernel time sync status 0040
2014-03-11 14:00:10.214815500 11 Mar 14:00:10 ntpd[19662]: frequency initialized 51.912 PPM from /etc/ntp/drift
2014-03-11 14:03:25.923753500 11 Mar 14:03:25 ntpd[19662]: synchronized to 66.175.209.17, stratum 2
2014-03-11 14:03:25.923771500 11 Mar 14:03:25 ntpd[19662]: kernel time sync enabled 0001
All of this started when I noted the time was wrong in the server manager date and time panel. Everything worked just fine prior to me changing the date with the date command from the console. I have checked my command syntax and verified it was correct. Any help would be appreciated.

[devtay]

Update:

When I disable the ntp server in date and time, all emails have an incorrect time, webmail doesn't work, and my php applications start working. If I use smeserver.pool.ntp.org, the emails have correct time, webmail doesn't work and my php applications report UTC.

The date and time shows UTC versus the correct time zone when I change it back to using smeserver.pool.ntp.org. I'm going to change the system battery just in case. I am getting no errors on the front panel of the server saying bat battery, etc.

[devtay]

Changed battery. Same problem. Looking more and more like a software error versus a hardware one.

[devtay]

This is in messages.

Code: [Select]

Mar 11 15:58:55 ftmain smbd[4046]: [2014/03/11 15:58:55.113603,  0] smbd/server.c:1082(main)
Mar 11 15:58:55 ftmain smbd[4046]:   standard input is not a socket, assuming -D option
Mar 11 15:58:57 ftmain ntpd[3741]: ntpd 4.2.2p1@1.1570-o Mon Dec  9 14:38:21 UTC 2013 (1)
Not sure why ntpd would change the date like that. Server manager date time panel shows:

Tue 11 Mar 2014 04:09:37 PM UTC

[CharlieBrady]

This is in messages.

Code: [Select]

Mar 11 15:58:57 ftmain ntpd[3741]: ntpd 4.2.2p1@1.1570-o Mon Dec  9 14:38:21 UTC 2013 (1)
Not sure why ntpd would change the date like that. Server manager date time panel shows:

Tue 11 Mar 2014 04:09:37 PM UTC

"Mon Dec  9 14:38:21 UTC 2013" is the date/time when the ntpd program was built. That's got nothing to do with the system time.

[devtay]

In the interest of closing this up, an update to SME Server fixed the problem. Here is the link to the bug explaining what happened:

http://bugs.contribs.org/show_bug.cgi?id=8269