RPirr

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

Close

Q: Calendar Server not starting after OS X 10.10.5 update

  • All replies
  • Helpful answers

  • by RPirr,

    RPirr RPirr Oct 8, 2015 7:36 AM in response to RPirr
    Level 1 (0 points)
    Oct 8, 2015 7:36 AM in response to RPirr

    deleted

  • by Linc Davis,

    Linc Davis Linc Davis Oct 8, 2015 11:55 AM in response to RPirr
    Level 10 (207,963 points)
    Applications
    Oct 8, 2015 11:55 AM in response to RPirr
  • by RPirr,

    RPirr RPirr Oct 9, 2015 2:03 AM in response to Linc Davis
    Level 1 (0 points)
    Oct 9, 2015 2:03 AM in response to Linc Davis

    I found this thread myself, but I have not a fail migration. Therefor I can not perform a manuell migration as described in the post.

     

    So I'm still stuck.

     

    I tried to restore an old version of the cluster.pg from my backup, but this does not help also. I have still the same problem :-(

     

    One thing that I also find very strange is, that I have disabled the calendar services, but according to the servermgr_calendar.log there is still some process that wants to start the calendar service and fails.

  • by Linc Davis,

    Linc Davis Linc Davis Oct 9, 2015 8:32 AM in response to RPirr
    Level 10 (207,963 points)
    Applications
    Oct 9, 2015 8:32 AM in response to RPirr

    I don't know how to do surgery on a Postgres database. I would restore the boot volume from a backup that predates the problem, then copy it to another volume, boot from that, and update directly to the current versions of OS X and the Server app. Test. That's how server updates should always be done. If you don't like the results, all you have to do is reboot.

     

    If necessary, when you have a working configuration back, you can export all network calendars on the clients as ICS, then reinitialize the CalDAV database and import.

  • by RPirr,Solvedanswer

    RPirr RPirr Oct 12, 2015 6:20 AM in response to Linc Davis
    Level 1 (0 points)
    Oct 12, 2015 6:20 AM in response to Linc Davis

    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.

  • by Pantoffel,

    Pantoffel Pantoffel Nov 3, 2015 1:04 PM in response to RPirr
    Level 1 (0 points)
    Nov 3, 2015 1:04 PM in response to RPirr

    I'm happy to report that this also solved my problem, thanks for posting. I was hesitant to update before solving the issue, but your success encouraged me.