Server Calendar migration failed
Hi,
last week when installing the latest server update for Mavericks the Calendar and Contacts stopped working. I tried everything to get it working again for the past few days like reinstalling server and even updated to Yosemite and installed Server 4 with the hope it would migrate correctly but without any luck.
The calendar state keeps in Starting and will never change to Started.
Below you can find the migration.log:
calendarcommonextra: Jan 21 21:49:45 Clean install: False
calendarcommonextra: Jan 21 21:49:45 Legacy indicator file does not exist
calendarcommonextra: Jan 21 21:49:46 Default certificate is: /etc/certificates/MYSERVER.FC3592DE1A30B14C74BE9CAFCBACFCC57615842C.cert.pem
calendarcommonextra: Jan 21 21:49:46 Default cert path: /etc/certificates/MYSERVER.FC3592DE1A30B14C74BE9CAFCBACFCC57615842C.cert.pem
calendarcommonextra: Jan 21 21:49:46 Reading plist /Library/Server/Calendar and Contacts/Config/caldavd-system.plist
calendarcommonextra: Jan 21 21:49:46 EnableCalDAV=True
calendarcommonextra: Jan 21 21:49:46 EnableCardDAV=True
calendarcommonextra: Jan 21 21:49:46 Looking up DatabaseRoot
calendarcommonextra: Jan 21 21:49:51 Output from calendarserver_config: DatabaseRoot=/Library/Server/Calendar and Contacts/Data/Database.xpg
calendarcommonextra: Jan 21 21:49:51 Looking up Postgres.ClusterName
calendarcommonextra: Jan 21 21:49:52 Output from calendarserver_config: Postgres.ClusterName=cluster.pg
calendarcommonextra: Jan 21 21:49:52 Sending to serveradmin: calendar:command = exportPushCertificates
calendarcommonextra: Jan 21 21:49:55 Output from push certificate export: calendar:Exported = "Yes"
calendarcommonextra: Jan 21 21:49:55 Calling calendarserver_upgrade --postprocess
calendarcommonextra: Jan 21 21:50:01 Output from calendarserver_upgrade: 2015-01-21 21:49:59+0100 Root ACL: <?xml version='1.0' encoding='UTF-8'?>
<acl xmlns='DAV:'>
<ace>
<principal>
<authenticated/>
</principal>
<grant>
<privilege>
<read/>
</privilege>
<privilege>
<read-current-user-privilege-set/>
</privilege>
</grant>
<protected/>
</ace>
</acl>
2015-01-21 21:49:59+0100 Nav ACL: <?xml version='1.0' encoding='UTF-8'?>
<acl xmlns='DAV:'>
<ace>
<principal>
<authenticated/>
</principal>
<grant>
<privilege>
<read/>
</privilege>
<privilege>
<read-current-user-privilege-set/>
</privilege>
</grant>
<protected/>
</ace>
</acl>
2015-01-21 21:49:59+0100 CalDAV APNS certificate passphrase retreived from keychain
2015-01-21 21:49:59+0100 CardDAV APNS certificate passphrase retreived from keychain
2015-01-21 21:49:59+0100 iMIP Sending password successfully retreived from keychain
2015-01-21 21:49:59+0100 iMIP Receiving password successfully retreived from keychain
2015-01-21 21:49:59+0100 Root ACL: <?xml version='1.0' encoding='UTF-8'?>
<acl xmlns='DAV:'>
<ace>
<principal>
<authenticated/>
</principal>
<grant>
<privilege>
<read/>
</privilege>
<privilege>
<read-current-user-privilege-set/>
</privilege>
</grant>
<protected/>
</ace>
</acl>
2015-01-21 21:49:59+0100 Nav ACL: <?xml version='1.0' encoding='UTF-8'?>
<acl xmlns='DAV:'>
<ace>
<principal>
<authenticated/>
</principal>
<grant>
<privilege>
<read/>
</privilege>
<privilege>
<read-current-user-privilege-set/>
</privilege>
</grant>
<protected/>
</ace>
</acl>
2015-01-21 21:49:59+0100 iMIP Sending password successfully retreived from keychain
2015-01-21 21:49:59+0100 iMIP Receiving password successfully retreived from keychain
2015-01-21 21:49:59+0100 Root ACL: <?xml version='1.0' encoding='UTF-8'?>
<acl xmlns='DAV:'>
<ace>
<principal>
<authenticated/>
</principal>
<grant>
<privilege>
<read/>
</privilege>
<privilege>
<read-current-user-privilege-set/>
</privilege>
</grant>
<protected/>
</ace>
</acl>
2015-01-21 21:49:59+0100 Nav ACL: <?xml version='1.0' encoding='UTF-8'?>
<acl xmlns='DAV:'>
<ace>
<principal>
<authenticated/>
</principal>
<grant>
<privilege>
<read/>
</privilege>
<privilege>
<read-current-user-privilege-set/>
</privilege>
</grant>
<protected/>
</ace>
</acl>
2015-01-21 21:49:59+0100 iMIP Sending password successfully retreived from keychain
2015-01-21 21:49:59+0100 iMIP Receiving password successfully retreived from keychain
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.application.app
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.internet.protocol
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.mail.smtp
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.internet.base
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.web.client
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.persisted.sob
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.names.client
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.protocols.basic
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.application.internet
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.web.html
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.protocols.amp
2015-01-21 21:49:59+0100 Replacing Twisted log.msg object twistedLogMessage in twext.python.log
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.python.threadpool
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.web._newclient
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.cred.checkers
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.persisted.styles
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.internet.tcp
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twext.internet.adaptendpoint
2015-01-21 21:49:59+0100 Replacing Twisted log.err object err in txweb2.dav.xattrprops
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.internet.udp
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.mail.pop3client
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.internet.task
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.internet.endpoints
2015-01-21 21:49:59+0100 Replacing Twisted log.err object err in twisted.internet._baseprocess
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.names.dns
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twext.internet.spawnsvc
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twext.enterprise.adbapi2
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.web.http
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.internet.selectreactor
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.internet.posixbase
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.protocols.policies
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.plugin
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.internet.defer
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.internet._posixstdio
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.web.template
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.protocols.tls
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.protocols.memcache
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.enterprise.adbapi
2015-01-21 21:49:59+0100 Replacing Twisted log module object log in twisted.internet.process
2015-01-21 21:49:59+0100 Calendar and Contacts Server 6.0-unknown starting Utility process...
2015-01-21 21:49:59+0100 Creating /var/run/caldavd/PostgresSocket
2015-01-21 21:49:59+0100 Cluster already exists at /Library/Server/Calendar and Contacts/Data/Database.xpg/cluster.pg
2015-01-21 21:49:59+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=165', '-c max_connections=110', '-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-01-21 21:50:00+0100 received postgres stdout "2015-01-21 21:50:00 XPG.2178: Spawning... ('/usr/bin/tar', '-xz', '-f', '/Library/Server/Calendar and Contacts/Data/Database.xpg/backup/base_backup/base_complete.tar.gz', '-C', '/Library/Server/Calendar and Contacts/Data/Database.xpg/cluster.pg')\n"
2015-01-21 21:50:00+0100 received postgres stdout '2015-01-21 21:50:00 XPG.2178: Preparing to upgrade outdated database cluster.\n'
2015-01-21 21:50:00+0100 received postgres stderr Traceback (most recent call last):
File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/internet/defer.py", line 423, in errback
2015-01-21 21:50:00+0100 received postgres stderr self._startRunCallbacks(fail)
File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/internet/defer.py", line 490, in _startRunCallbacks
self._runCallbacks()
File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/internet/defer.py", line 577, in _runCallbacks
2015-01-21 21:50:00+0100 received postgres stderr current.result = callback(current.result, *args, **kw)
File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/internet/defer.py", line 1155, in gotResult
_inlineCallbacks(r, g, deferred)
--- <exception caught here> ---
File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/internet/defer.py", line 1097, in _inlineCallbacks
result = result.throwExceptionIntoGenerator(g)
File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/python/failure.py", line 389, in throwExceptionIntoGenerator
2015-01-21 21:50:00+0100 received postgres stderr return g.throw(self.type, self.value, self.tb)
File "/Applications/Server.app/Contents/ServerRoot/usr/bin/xpg_ctl", line 2038, in main
2015-01-21 21:50:00+0100 received postgres stderr result = yield xpg.do_everything(argv, environ)
File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/internet/defer.py", line 1097, in _inlineCallbacks
result = result.throwExceptionIntoGenerator(g)
2015-01-21 21:50:00+0100 received postgres stderr File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/python/failure.py", line 389, in throwExceptionIntoGenerator
return g.throw(self.type, self.value, self.tb)
File "/Applications/Server.app/Contents/ServerRoot/usr/bin/xpg_ctl", line 1994, in do_everything
result = yield self.command_object.execute()
File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/internet/defer.py", line 1097, in _inlineCallbacks
result = result.throwExceptionIntoGenerator(g)
File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/python/failure.py", line 389, in throwExceptionIntoGenerator
return g.throw(self.type, self.value, self.tb)
File "/Applications/Server.app/Contents/ServerRoot/usr/bin/xpg_ctl", line 1726, in execute
yield xpg.do_restore()
File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/internet/defer.py", line 1099, in _inlineCallbacks
result = g.send(result)
File "/Applications/Server.app/Contents/ServerRoot/usr/bin/xpg_ctl", line 1028, in do_restore
did_upgrade = self.upgrade_cluster_if_needed()
File "/Applications/Server.app/Contents/ServerRoot/usr/bin/xpg_ctl", line 1452, in upgrade_cluster_if_needed
2015-01-21 21:50:00+0100 received postgres stderr os.rename(self.data_directory, orig_data_dir)
exceptions.OSError: [Errno 66] Directory not empty
2015-01-21 21:50:00+0100 postgres process ended with status 256
2015-01-21 21:50:00+0100 Could not start postgres; see postgres.log
2015-01-21 21:50:01+0100 Can't start or connect to postgres
Failed to start service.
2015-01-21 21:50:01+0100 Main loop terminated.
calendarcommonextra: Jan 21 21:50:01 Executing: /Applications/Server.app/Contents/ServerRoot/usr/sbin/serverctl enable service=org.calendarserver.agent
calendarcommonextra: Jan 21 21:50:01 Output: {
}
calendarcommonextra: Jan 21 21:50:01 Executing: /Applications/Server.app/Contents/ServerRoot/usr/sbin/serverctl enable service=org.calendarserver.relocate
calendarcommonextra: Jan 21 21:50:01 Output: {
}
calendarcommonextra: Jan 21 21:50:01 Executing: /bin/launchctl start org.calendarserver.agent
calendarcommonextra: Jan 21 21:50:01 Executing: /Applications/Server.app/Contents/ServerRoot/usr/libexec/calendarserver_log_con f
calendarcommonextra: Jan 21 21:50:01 Allowing supervisor to enable service
calendarcommonextra: Jan 21 21:50:01 Configuring reverse proxies
Also in the servermgr_calendar.log I see this message repeating:
[cal] 1/21/15, 9:52:46 PM GMT+1 : Command getState duration 20.40 seconds
[cal] 1/21/15, 9:52:46 PM GMT+1 : getState releasing request lock
[cal] 1/21/15, 9:52:46 PM GMT+1 : Command getState received
[cal] 1/21/15, 9:52:46 PM GMT+1 : getState attempting to acquire request lock...
[cal] 1/21/15, 9:52:46 PM GMT+1 : getState acquired request lock
[cal] 1/21/15, 9:52:46 PM GMT+1 : getState begin
[cal] 1/21/15, 9:52:46 PM GMT+1 : Read Settings
[cal] 1/21/15, 9:52:46 PM GMT+1 : calendarServerOperationWithRequest
[cal] 1/21/15, 9:52:46 PM GMT+1 : Calling agent...
[cal] 1/21/15, 9:53:02 PM GMT+1 : Agent failure: The request timed out.
[cal] 1/21/15, 9:53:02 PM GMT+1 : Agent returned...
{
error = "The request timed out.";
}
Thanks for the help.
Best regards
Rob
Mac mini, OS X Yosemite (10.10.1)
