igmt

Q: 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)

Posted on Jan 22, 2015 2:07 AM

Close

Q: Server Calendar migration failed

  • All replies
  • Helpful answers

  • by igmt,

    igmt igmt Jan 22, 2015 6:38 AM in response to igmt
    Level 1 (0 points)
    Jan 22, 2015 6:38 AM in response to igmt

    for testing purposes I renamed the data folder and started the calendar service again.

    The new data folder got created but the loop like below is still showing up every 10 seconds:

     

    [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.";
    }
    
  • by Linc Davis,

    Linc Davis Linc Davis Jan 22, 2015 6:05 PM in response to igmt
    Level 10 (207,926 points)
    Applications
    Jan 22, 2015 6:05 PM in response to igmt
  • by igmt,

    igmt igmt Jan 23, 2015 4:51 AM in response to Linc Davis
    Level 1 (0 points)
    Jan 23, 2015 4:51 AM in response to Linc Davis

    Hi Linc,

    thanks for pointing me to that thread. That at least made me able to recover the database.

    The next problem is that Calendar keeps in starting state with the following error in the logs:

     

    No reverse proxies for Calendar and Contacts

  • by Linc Davis,

    Linc Davis Linc Davis Jan 23, 2015 7:39 AM in response to igmt
    Level 10 (207,926 points)
    Applications
    Jan 23, 2015 7:39 AM in response to igmt

    I suggest you start a new discussion of this new issue with some more context from the log.