Q: Calendar Server not starting after OS X 10.10.5 update
My Calendar Server does not work anymore since I have installed the latest OS X 10.10.5 update. I also use the Server.app Version 4.1.3
(I don't want to migration to 5.0.4 until this is solved, because I do not want to make it worse)
It looks like the underlaying postgres does not work anymore, but I'm not an expert therefor I can be wrong.
What I have done is to move the Server.app to the Trash so that all Servers gets stop and moved it out again. When I start the Server.app then a setup is perform and at the end I get the following error:
'Preparing services - CalendarServer' Error Domain:CalendarServerPromotion Item:/Applications/Server.app/Contents/ServerRoot/usr/libexec/CalendarServerPro motion Code:1
Here also the things the logs from /Library/Server/Calendar and Contacts/Logs:
xpg_ctl.log:
2015-10-08 09:19:05 XPG.11720: Removing /Library/Server/Calendar and Contacts/Data/Database.xpg/backup/00000001000000000000002A.partial because /Library/Server/Calendar and Contacts/Data/Database.xpg/backup/00000001000000000000002A exists.
2015-10-08 09:19:05 XPG.11720: Process parent is PID 1
2015-10-08 09:19:05 XPG.11720: Excluding data directory.
2015-10-08 09:19:06 XPG.11720: Turning on archive logging.
2015-10-08 09:19:06 XPG.11720: Cleaning up any existing postmaster.pid file
2015-10-08 09:19:06 XPG.11720: Starting postgres.
2015-10-08 09:19:06 XPG.11720: Waiting for data directory: /Library/Server/Calendar and Contacts/Data/Database.xpg/cluster.pg
2015-10-08 09:19:06 XPG.11720: Data directory exists.
2015-10-08 09:19:06 XPG.11720: Spawning postgres now.
2015-10-08 09:19:06 XPG.11720: Waiting for socket to appear in socket directory: /var/run/caldavd/PostgresSocket
2015-10-08 09:19:06.290 CEST [11983] LOG: redirecting log output to logging collector process
2015-10-08 09:19:06.290 CEST [11983] HINT: Future log output will appear in directory "/Library/Server/Calendar and Contacts/Logs".
2015-10-08 09:19:07 XPG.11720: Socket available; starting should now be complete.
2015-10-08 09:19:07 XPG.11720: log receiver: pg_receivexlog: starting log streaming at 0/34000000 (timeline 1)
2015-10-08 09:19:07 XPG.11720: Starting backup heartbeat.
2015-10-08 09:19:08 XPG.11720: Decremented reference count. Count is now: 0
2015-10-08 09:19:08 XPG.11720: Reference count reached zero. Shutting down.
2015-10-08 09:19:08 XPG.11720: Killing idle connections...
2015-10-08 09:19:08 XPG.11720: Spawning... ('/Applications/Server.app/Contents/ServerRoot/usr/bin/psql', '-q', '-h', '/var/run/caldavd/PostgresSocket', '-d', 'postgres', '-c', "SELECT pid, (SELECT pg_terminate_backend(pid)) as killed from pg_stat_activity WHERE state LIKE 'idle';")
pid | killed
-----+--------
(0 rows)
2015-10-08 09:19:17 XPG.11720: Postgres exited.
2015-10-08 09:19:17 XPG.11720: pg_receivexlog still running; terminating.
2015-10-08 09:19:17 XPG.11720: log receiver: pg_receivexlog: not renaming "000000010000000000000035.partial", segment is not complete
pg_receivexlog: received interrupt signal, exiting
postgres_4.log:
AttributeError: 'module' object has no attribute 'openssl_md_meth_names'
2015-10-08 09:19:10.240 CEST [12032] LOG: archive command failed with exit code 1
2015-10-08 09:19:10.240 CEST [12032] DETAIL: The failed archive command was: python /Applications/Server.app/Contents/ServerRoot/usr/bin/xpostgres archive pg_xlog/000000010000000000000033 ../backup/000000010000000000000033
Traceback (most recent call last):
File "/Applications/Server.app/Contents/ServerRoot/usr/bin/xpostgres", line 38, in <module>
from tempfile import mkdtemp
File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/tempfil e.py", line 35, in <module>
from random import Random as _Random
File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/random. py", line 49, in <module>
import hashlib as _hashlib
File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/hashlib .py", line 138, in <module>
_hashlib.openssl_md_meth_names)
AttributeError: 'module' object has no attribute 'openssl_md_meth_names'
2015-10-08 09:19:11.356 CEST [12032] LOG: archive command failed with exit code 1
2015-10-08 09:19:11.356 CEST [12032] DETAIL: The failed archive command was: python /Applications/Server.app/Contents/ServerRoot/usr/bin/xpostgres archive pg_xlog/000000010000000000000033 ../backup/000000010000000000000033
Traceback (most recent call last):
File "/Applications/Server.app/Contents/ServerRoot/usr/bin/xpostgres", line 38, in <module>
from tempfile import mkdtemp
File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/tempfil e.py", line 35, in <module>
from random import Random as _Random
File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/random. py", line 49, in <module>
import hashlib as _hashlib
File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/hashlib .py", line 138, in <module>
_hashlib.openssl_md_meth_names)
AttributeError: 'module' object has no attribute 'openssl_md_meth_names'
2015-10-08 09:19:12.429 CEST [12032] LOG: archive command failed with exit code 1
2015-10-08 09:19:12.429 CEST [12032] DETAIL: The failed archive command was: python /Applications/Server.app/Contents/ServerRoot/usr/bin/xpostgres archive pg_xlog/000000010000000000000033 ../backup/000000010000000000000033
2015-10-08 09:19:12.429 CEST [12032] WARNING: archiving transaction log file "000000010000000000000033" failed too many times, will try again later
migration.log:
2015-10-08 09:19:04+0100 Nav ACL: <?xml version='1.0' encoding='UTF-8'?>
<acl xmlns='DAV:'>^M
<ace>^M
<principal>^M
<authenticated/>^M
</principal>^M
<grant>^M
<privilege>^M
<read/>^M
</privilege>^M
<privilege>^M
<read-current-user-privilege-set/>^M
</privilege>^M
</grant>^M
<protected/>^M
</ace>^M
</acl>
2015-10-08 09:19:04+0100 Creating /var/run/caldavd/PostgresSocket
2015-10-08 09:19:04+0100 Cluster already exists at /Library/Server/Calendar and Contacts/Data/Database.xpg/cluster.pg
2015-10-08 09:19:04+0100 Requesting postgres start via /Applications/Server.app/Contents/ServerRoot/usr/bin/xpg_ctl ["-c listen_addresses=''", '-k /var/run/caldavd/PostgresSocket', '-c shared_buffers=105', '-c max_connections=70', '-c standard_conforming_strings=on', '-c unix_socket_permissions=0770', '-c log_lock_waits=TRUE', '-c deadlock_timeout=10', "-c log_line_prefix='%m [%p] '", "-c log_directory='/Library/Server/Calendar and Contacts/Logs'", '-c log_truncate_on_rotation=on', '-c log_filename=postgresql_%w.log', '-c log_rotation_age=1440', '-c logging_collector=on']
2015-10-08 09:19:05+0100 received postgres stdout '2015-10-08 09:19:05 XPG.11632: Executing pg_ctl [\'/Applications/Server.app/Contents/ServerRoot/usr/bin/pg_ctl\', \'-p\', \'/Applications/Server.app/Contents/ServerRoot/usr/bin/xpostgres\', \'start\', \'-l\', \'/Library/Server/Calendar and Contacts/Logs/xpg_ctl.log\', \'-t 86400\', \'-w\', \'-o\', "-c listen_addresses=\'\' -k /var/run/caldavd/PostgresSocket -c shared_buffers=105 -c max_connections=70 -c standard_conforming_strings=on -c unix_socket_permissions=0770 -c log_lock_waits=TRUE -c deadlock_timeout=10 -c log_line_prefix=\'%m [%p] \' -c log_directory=\'/Library/Server/Calendar and Contacts/Logs\' -c log_truncate_on_rotation=on -c log_filename=postgresql_%w.log -c log_rotation_age=1440 -c logging_collector=on"]\n2015-10-08 09:19:05 XPG.11632: Spawning... [\'/Applications/Server.app/Contents/ServerRoot/usr/bin/pg_ctl\', \'-p\', \'/Applications/Server.app/Contents/ServerRoot/usr/bin/xpostgres\', \'start\', \'-l\', \'/Library/Server/Calendar and Contacts/Logs/xpg_ctl.log\', \'-t 86400\', \'-w\', \'-o\', "-c listen_addresses=\'\' -k /var/run/caldavd/PostgresSocket -c shared_buffers=105 -c max_connections=70 -c standard_conforming_strings=on -c unix_socket_permissions=0770 -c log_lock_waits=TRUE -c deadlock_timeout=10 -c log_line_prefix=\'%m [%p] \' -c log_directory=\'/Library/Server/Calendar and Contacts/Logs\' -c log_truncate_on_rotation=on -c log_filename=postgresql_%w.log -c log_rotation_age=1440 -c logging_collector=on"]\n'
2015-10-08 09:19:05+0100 received postgres stdout 'waiting for server to start....'
2015-10-08 09:19:06+0100 received postgres stdout '.'
2015-10-08 09:19:07+0100 received postgres stdout ' done\nserver started\n'
2015-10-08 09:19:07+0100 postgres process ended with status 0
2015-10-08 09:19:07+0100 /Applications/Server.app/Contents/ServerRoot/usr/bin/xpg_ctl exited
2015-10-08 09:19:08+0100 Beginning database schema check.
2015-10-08 09:19:08+0100 Required database key VERSION: 52.
2015-10-08 09:19:08+0100 Actual database key VERSION: 52.
2015-10-08 09:19:08+0100 Schema version check complete: no upgrade needed.
2015-10-08 09:19:08+0100 Database schema check complete.
2015-10-08 09:19:08+0100 Beginning database addressbook data check.
2015-10-08 09:19:08+0100 Required database key ADDRESSBOOK-DATAVERSION: 2.
2015-10-08 09:19:08+0100 Actual database key ADDRESSBOOK-DATAVERSION: 2.
2015-10-08 09:19:08+0100 Addressbook data version check complete: no upgrade needed.
2015-10-08 09:19:08+0100 Database addressbook data check complete.
2015-10-08 09:19:08+0100 Beginning database calendar data check.
2015-10-08 09:19:08+0100 Required database key CALENDAR-DATAVERSION: 6.
2015-10-08 09:19:08+0100 Actual database key CALENDAR-DATAVERSION: 6.
2015-10-08 09:19:08+0100 Calendar data version check complete: no upgrade needed.
2015-10-08 09:19:08+0100 Database calendar data check complete.
2015-10-08 09:19:08+0100 Beginning database notification data check.
2015-10-08 09:19:08+0100 Required database key NOTIFICATION-DATAVERSION: 1.
2015-10-08 09:19:08+0100 Actual database key NOTIFICATION-DATAVERSION: 1.
2015-10-08 09:19:08+0100 Notification data version check complete: no upgrade needed.
2015-10-08 09:19:08+0100 Database notification data check complete.
2015-10-08 09:19:08+0100 Beginning database other upgrades check.
2015-10-08 09:19:08+0100 Database other upgrades check complete.
Upgrade complete, shutting down.
2015-10-08 09:19:17+0100 postgres process ended with status 0
calendarcommonextra: Oct 08 09:19:17 Executing: /Applications/Server.app/Contents/ServerRoot/usr/sbin/serverctl enable service=org.calendarserver.agent
calendarcommonextra: Oct 08 09:19:17 Output: {
}
calendarcommonextra: Oct 08 09:19:17 Executing: /Applications/Server.app/Contents/ServerRoot/usr/sbin/serverctl enable service=org.calendarserver.relocate
calendarcommonextra: Oct 08 09:19:17 Output: {
}
calendarcommonextra: Oct 08 09:19:17 Executing: /Applications/Server.app/Contents/ServerRoot/usr/sbin/serverctl enable service=org.calendarserver.archive
calendarcommonextra: Oct 08 09:19:17 Output: {
}
calendarcommonextra: Oct 08 09:19:17 Executing: /bin/launchctl start org.calendarserver.agent
calendarcommonextra: Oct 08 09:19:17 Executing: /Applications/Server.app/Contents/ServerRoot/usr/libexec/calendarserver_log_con f
calendarcommonextra: Oct 08 09:19:17 Service was not previously enabled
servermgr_calender.log:
[cal] 08/10/15 09:32:15 CEST : Calling agent...
[cal] 08/10/15 09:32:31 CEST : Agent failure: The request timed out.
[cal] 08/10/15 09:32:31 CEST : Agent returned...
{
error = "The request timed out.";
}
[cal] 08/10/15 09:32:31 CEST : Command getLocationList duration 16.00 seconds
[cal] 08/10/15 09:32:31 CEST : getLocationList releasing request lock
[cal] 08/10/15 09:32:31 CEST : Command getResourceList received
[cal] 08/10/15 09:32:31 CEST : getResourceList attempting to acquire request lock...
[cal] 08/10/15 09:32:31 CEST : getResourceList acquired request lock
[cal] 08/10/15 09:32:31 CEST : calendarServerOperationWithRequest
[cal] 08/10/15 09:32:31 CEST : Calling agent...
[cal] 08/10/15 09:32:47 CEST : Agent failure: The request timed out.
[cal] 08/10/15 09:32:47 CEST : Agent returned...
{
error = "The request timed out.";
}
[cal] 08/10/15 09:32:47 CEST : Command getResourceList duration 15.92 seconds
[cal] 08/10/15 09:32:47 CEST : getResourceList releasing request lock
[cal] 08/10/15 09:33:50 CEST : Command getLocationList received
[cal] 08/10/15 09:33:50 CEST : getLocationList attempting to acquire request lock...
[cal] 08/10/15 09:33:50 CEST : getLocationList acquired request lock
[cal] 08/10/15 09:33:50 CEST : calendarServerOperationWithRequest
[cal] 08/10/15 09:33:50 CEST : Calling agent...
Can anybody hint me what to do?
Posted on Oct 8, 2015 12:36 AM
I found a solution for this problem that is not the solution I hoped for, but at least it solved my calendar problem.
I have updated my server to El Capitan and Server 5.0.4 this solved the problem and the calendar works now fine again.
Posted on Oct 12, 2015 6:20 AM