Calendar broken after Lion to Mavericks server update

Look in /var/log/caldavd/migration.log for any indications of an upgrade error.

Based on those error messages, it would appear the schema in the Calendar Server Postgres database did not get updated. That happens at initial upgrade to Mavericks Server (which would log to /var/log/caldavd/migration.log), and should also happen every time you start up the Calendar Server (which would log to /var/log/caldavd/error.log). Check both of those log files.

For example, a successful upgrade from Mountain Lion Server to Mavericks Server would have these messages in /var/log/caldavd/migration.log -- I'm pulling out some relevant snippets:

calendarcommonextra: Oct 22 14:15:06 Looking up DatabaseRoot

calendarcommonextra: Oct 22 14:15:08 Output from calendarserver_config: DatabaseRoot=/Library/Server/Calendar and Contacts/Data/Database.xpg

calendarcommonextra: Oct 22 14:15:09 DatabaseRoot does not yet exist: /Library/Server/Calendar and Contacts/Data/Database.xpg

calendarcommonextra: Oct 22 14:15:09 Forked calendar server cluster does exist: /Library/Server/postgres_service_clusters/calendar

calendarcommonextra: Oct 22 14:15:09 Created DatabaseRoot

calendarcommonextra: Oct 22 14:15:09 Relocating data to /Library/Server/Calendar and Contacts/Data/Database.xpg/cluster.pg

2013-10-22 14:15:17-0800 received postgres stdout 'waiting for server to start....'

2013-10-22 14:15:18-0800 received postgres stdout '.'

2013-10-22 14:15:20-0800 received postgres stdout ' done\nserver started\n'

2013-10-22 14:15:20-0800 postgres process ended with status 0

2013-10-22 14:15:20-0800 /Applications/Server.app/Contents/ServerRoot/usr/bin/xpg_ctl exited

2013-10-22 14:15:34-0800 Beginning database schema check.

2013-10-22 14:15:34-0800 Required database key VERSION: 24.

2013-10-22 14:15:34-0800 Actual database key VERSION: 12.

2013-10-22 14:15:34-0800 Starting schema upgrade from version 12 to 24.

2013-10-22 14:15:34-0800 Applying schema upgrade: upgrade_from_12_to_13.sql

2013-10-22 14:15:35-0800 Applying schema upgrade: upgrade_from_13_to_14.sql

2013-10-22 14:15:35-0800 Applying schema upgrade: upgrade_from_14_to_15.sql

2013-10-22 14:15:36-0800 Applying schema upgrade: upgrade_from_15_to_16.sql

2013-10-22 14:15:36-0800 Applying schema upgrade: upgrade_from_16_to_17.sql

2013-10-22 14:15:37-0800 Applying schema upgrade: upgrade_from_17_to_18.sql

2013-10-22 14:15:37-0800 Applying schema upgrade: upgrade_from_18_to_19.sql

2013-10-22 14:15:37-0800 Applying schema upgrade: upgrade_from_19_to_20.sql

2013-10-22 14:15:42-0800 Applying schema upgrade: upgrade_from_20_to_21.sql

2013-10-22 14:15:42-0800 Applying schema upgrade: upgrade_from_21_to_22.sql

2013-10-22 14:15:42-0800 Applying schema upgrade: upgrade_from_22_to_23.sql

2013-10-22 14:15:42-0800 Applying schema upgrade: upgrade_from_23_to_24.sql

2013-10-22 14:15:42-0800 Schema upgraded from version 12 to 24.

2013-10-22 14:15:42-0800 Database schema check complete.

2013-10-22 14:15:42-0800 Beginning database addressbook data check.

2013-10-22 14:15:42-0800 Required database key ADDRESSBOOK-DATAVERSION: 2.

2013-10-22 14:15:42-0800 Actual database key ADDRESSBOOK-DATAVERSION: 1.

2013-10-22 14:15:42-0800 Starting addressbook data upgrade from version 1 to 2.

2013-10-22 14:15:42-0800 Applying data upgrade: txdav.common.datastore.upgrade.sql.upgrades.addressbook_upgrade_from_1_to_2.doU pgrade

2013-10-22 14:15:46-0800 Addressbook data upgraded from version 1 to 2.

2013-10-22 14:15:46-0800 Database addressbook data check complete.

2013-10-22 14:15:46-0800 Beginning database calendar data check.

2013-10-22 14:15:46-0800 Required database key CALENDAR-DATAVERSION: 5.

2013-10-22 14:15:46-0800 Actual database key CALENDAR-DATAVERSION: 3.

2013-10-22 14:15:46-0800 Starting calendar data upgrade from version 3 to 5.

2013-10-22 14:15:46-0800 Applying data upgrade: txdav.common.datastore.upgrade.sql.upgrades.calendar_upgrade_from_3_to_4.doUpgr ade

2013-10-22 14:15:50-0800 Applying data upgrade: txdav.common.datastore.upgrade.sql.upgrades.calendar_upgrade_from_4_to_5.doUpgr ade

2013-10-22 14:15:51-0800 Calendar data upgraded from version 3 to 5.

2013-10-22 14:15:51-0800 Database calendar data check complete.

Then, every time you start Calendar Server, /var/log/caldavd/error.log will show some messages noting what schema version is required and what is actually detected within the Postgres cluster, e.g.:

2013-10-23 19:02:21-0700 [-] [txdav.base.datastore.subpostgres#warn] received postgres stdout 'waiting for server to start....'

2013-10-23 19:02:25-0700 [-] [txdav.base.datastore.subpostgres#warn] received postgres stdout '.'

2013-10-23 19:02:26-0700 [-] [txdav.base.datastore.subpostgres#warn] received postgres stdout ' done\nserver started\n'

2013-10-23 19:02:26-0700 [-] [txdav.base.datastore.subpostgres#warn] postgres process ended with status 0

2013-10-23 19:02:26-0700 [-] [txdav.base.datastore.subpostgres#warn] /Applications/Server.app/Contents/ServerRoot/usr/bin/xpg_ctl exited

2013-10-23 19:02:27-0700 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseSchemaStep#warn] Beginning database schema check.

2013-10-23 19:02:27-0700 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseSchemaStep#warn] Required database key VERSION: 24.

2013-10-23 19:02:27-0700 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseSchemaStep#warn] Actual database key VERSION: 24.

2013-10-23 19:02:27-0700 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseSchemaStep#warn] Schema version check complete: no upgrade needed.

2013-10-23 19:02:27-0700 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseSchemaStep#warn] Database schema check complete.

2013-10-23 19:02:27-0700 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseAddressBookDataStep# warn] Beginning database addressbook data check.

2013-10-23 19:02:27-0700 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseAddressBookDataStep# warn] Required database key ADDRESSBOOK-DATAVERSION: 2.

2013-10-23 19:02:27-0700 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseAddressBookDataStep# warn] Actual database key ADDRESSBOOK-DATAVERSION: 2.

2013-10-23 19:02:27-0700 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseAddressBookDataStep# warn] Addressbook data version check complete: no upgrade needed.

2013-10-23 19:02:27-0700 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseAddressBookDataStep# warn] Database addressbook data check complete.

2013-10-23 19:02:27-0700 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseCalendarDataStep#war n] Beginning database calendar data check.

2013-10-23 19:02:27-0700 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseCalendarDataStep#war n] Required database key CALENDAR-DATAVERSION: 5.

2013-10-23 19:02:27-0700 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseCalendarDataStep#war n] Actual database key CALENDAR-DATAVERSION: 5.

2013-10-23 19:02:27-0700 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseCalendarDataStep#war n] Calendar data version check complete: no upgrade needed.

2013-10-23 19:02:27-0700 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseCalendarDataStep#war n] Database calendar data check complete.

2013-10-23 19:02:27-0700 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseOtherStep#warn] Beginning database other upgrades check.

2013-10-23 19:02:27-0700 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseOtherStep#warn] No dropbox migration needed

2013-10-23 19:02:27-0700 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseOtherStep#warn] Database other upgrades check complete.

gnaegi, in /var/log/caldavd/error.log, what do you see after "received postgres stdout 'waiting for server to start....'"

Any advise how to solve this issue? The migration failed during the migration and now every time at startup...

Thank you!

Best regards,

Ives

2013-10-26 00:02:31+0200 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseSchemaStep#warn] Beginning database schema check.

2013-10-26 00:02:31+0200 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseSchemaStep#warn] Required database key VERSION: 24.

2013-10-26 00:02:31+0200 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseSchemaStep#warn] Actual database key VERSION: 13.

2013-10-26 00:02:31+0200 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseSchemaStep#warn] Starting schema upgrade from version 13 to 24.

2013-10-26 00:02:31+0200 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseSchemaStep#warn] Applying schema upgrade: upgrade_from_13_to_14.sql

2013-10-26 00:02:32+0200 [-] [calendarserver.tap.util#error] Step failure

Traceback (most recent call last):

File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/internet/defer.py", line 397, in errback

self._startRunCallbacks(fail)

File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/internet/defer.py", line 464, in _startRunCallbacks

self._runCallbacks()

File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/internet/defer.py", line 551, in _runCallbacks

current.result = callback(current.result, *args, **kw)

Can you look through the log files in /var/log/caldavd/postgresql/ to look for errors?

Well, also, is there more to that Traceback you pasted above?

Thank you! Yes, this seems to be the full trace up to the next event:

2013-10-26 00:02:31+0200 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseSchemaStep#warn] Beginning database schema check.

2013-10-26 00:02:31+0200 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseSchemaStep#warn] Required database key VERSION: 24.

2013-10-26 00:02:31+0200 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseSchemaStep#warn] Actual database key VERSION: 13.

2013-10-26 00:02:31+0200 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseSchemaStep#warn] Starting schema upgrade from version 13 to 24.

2013-10-26 00:02:31+0200 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseSchemaStep#warn] Applying schema upgrade: upgrade_from_13_to_14.sql

2013-10-26 00:02:32+0200 [-] [calendarserver.tap.util#error] Step failure

Traceback (most recent call last):

File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/internet/defer.py", line 397, in errback

self._startRunCallbacks(fail)

File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/internet/defer.py", line 464, in _startRunCallbacks

self._runCallbacks()

File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/internet/defer.py", line 551, in _runCallbacks

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 1101, 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 1043, in _inlineCallbacks

result = result.throwExceptionIntoGenerator(g)

File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/python/failure.py", line 382, in throwExceptionIntoGenerator

return g.throw(self.type, self.value, self.tb)

File "/Applications/Server.app/Contents/ServerRoot/usr/share/caldavd/lib/python/txda v/common/datastore/upgrade/sql/upgrade.py", line 143, in databaseUpgrade

yield self.upgradeVersion(actual_version, required_version, dialect)

File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/internet/defer.py", line 1043, in _inlineCallbacks

result = result.throwExceptionIntoGenerator(g)

File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/python/failure.py", line 382, in throwExceptionIntoGenerator

return g.throw(self.type, self.value, self.tb)

File "/Applications/Server.app/Contents/ServerRoot/usr/share/caldavd/lib/python/txda v/common/datastore/upgrade/sql/upgrade.py", line 208, in upgradeVersion

yield self.applyUpgrade(fp)

File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/internet/defer.py", line 1043, in _inlineCallbacks

result = result.throwExceptionIntoGenerator(g)

File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/python/failure.py", line 382, in throwExceptionIntoGenerator

return g.throw(self.type, self.value, self.tb)

File "/Applications/Server.app/Contents/ServerRoot/usr/share/caldavd/lib/python/txda v/common/datastore/upgrade/sql/upgrade.py", line 316, in applyUpgrade

yield sqlTxn.execSQLBlock(sql)

File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/internet/defer.py", line 1043, in _inlineCallbacks

result = result.throwExceptionIntoGenerator(g)

File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/python/failure.py", line 382, in throwExceptionIntoGenerator

return g.throw(self.type, self.value, self.tb)

File "/Applications/Server.app/Contents/ServerRoot/usr/share/caldavd/lib/python/txda v/common/datastore/sql.py", line 1025, in execSQLBlock

yield self.execSQL(stmt)

File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/internet/defer.py", line 1043, in _inlineCallbacks

result = result.throwExceptionIntoGenerator(g)

File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/python/failure.py", line 382, in throwExceptionIntoGenerator

return g.throw(self.type, self.value, self.tb)

File "/Applications/Server.app/Contents/ServerRoot/usr/share/caldavd/lib/python/txda v/common/datastore/sql.py", line 1009, in execSQL

results = (yield self._sqlTxn.execSQL(*a, **kw))

File "/Applications/Server.app/Contents/ServerRoot/usr/share/caldavd/lib/python/twex t/internet/threadutils.py", line 74, in _oneWorkUnit

result = instruction()

File "/Applications/Server.app/Contents/ServerRoot/usr/share/caldavd/lib/python/twex t/enterprise/adbapi2.py", line 306, in <lambda>

lambda: self._reallyExecSQL(*args, **kw)

File "/Applications/Server.app/Contents/ServerRoot/usr/share/caldavd/lib/python/twex t/enterprise/adbapi2.py", line 240, in _reallyExecSQL

self._cursor.execute(sql, args)

File "/Applications/Server.app/Contents/ServerRoot/usr/share/caldavd/lib/python/txda v/base/datastore/dbapiclient.py", line 77, in execute

self.realCursor.execute(sql, args)

File "/Applications/Server.app/Contents/ServerRoot/usr/share/caldavd/lib/python/pgdb .py", line 323, in execute

return self.executemany(operation, [params])

File "/Applications/Server.app/Contents/ServerRoot/usr/share/caldavd/lib/python/pgdb .py", line 349, in executemany

rows = self._src.execute(sql)

pg.ProgrammingError: ERROR: column "calendar_resource_name" contains null values

To diagnose this, connect to the Calendar Server postgres via:

sudo psql -h /var/run/caldavd/ccs_postgres_3d403b3009fe0c830944d87bd751fbe9 -d caldav -U caldav

(replace the ccs_postgres_NNN value above with whatever is on your server)

Next, run this query:

select calendar_resource_id from calendar_bind where calendar_resource_name is null;

If there are any results to this query, those are most likely the issue. Then we can sort out how to fix this.

I am having the same problem after upgrading. Everything looks like its working on the server but no ones calendars or contacts are connecting. When we try the client gives an unknown error after taking a while to connect. It also complains about not ifnding a secure server.

I tried the query above and didn't get any errors. Just posted

calendar_resource_id

-----------------

0 rows

keyboardboy1: Are you actually seeing the 'pg.ProgrammingError: ERROR: column "calendar_resource_name" contains null values' error in any of the /var/log/caldavd/* logs ? Otherwise you have a different issue. I would look in /var/log/caldavd/error.log to see what's up.

Here is a snippet. This is the only error I see, however on another log i noticed a statemtn that a postgres client config file was missing. I think it was from the migration log.

2013-10-28 15:00:08-0400 [-] [twistedcaldav.authkerb.NegotiateCredentialFactory#error] getServerPrincipalDetails: ('Principal not found in keytab', -1)

[txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseOtherStep#warn] Beginning database other upgrades check.

2013-10-28 15:00:08-0400 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseOtherStep#warn] No dropbox migration needed

2013-10-28 15:00:08-0400 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseOtherStep#warn] Database other upgrades check complete.

2013-10-28 15:00:08-0400 [-] [twistedcaldav.authkerb.NegotiateCredentialFactory#error] getServerPrincipalDetails: ('Principal not found in keytab', -1)

2013-10-28 15:00:12-0400 [-] [caldav-0] Removing stale pidfile /var/run/caldavd/caldav-instance-0.pid

2013-10-28 15:00:13-0400 [-] [caldav-1] Reading configuration from file: /Applications/Server.app/Contents/ServerRoot/private/etc/caldavd/caldavd-apple. plist

2013-10-28 15:00:13-0400 [-] [caldav-1] [-] Log opened.

2013-10-28 15:00:13-0400 [-] [caldav-0] Reading configuration from file: /Applications/Server.app/Contents/ServerRoot/private/etc/caldavd/caldavd-apple. plist

2013-10-28 15:00:13-0400 [-] [caldav-0] [-] Log opened.

You say your clients can't connect -- is there anything logged to /var/log/caldavd/access.log when they try to connect? Also, you can try connecting directly to the Calendar Server using your web browser by visiting https://yourservername:8443/ -- that should result in you getting a login dialog, and displaying a collection listing.

Oddly those logs have remained empty today, and trying to access via the browser hasn't worked. I tested the dns and on port 8008 and 8443 you can get to the server. Everything worked fine just before upgrading.

When you say "on port 8008 and 8443 you can get to the server", what do you mean by that? What client did you try with and what response did you get?

If you "curl -vv -k https://yourservername:8443/" are you getting back a response containing (among other things) an HTTP header of "Server: Twisted/12.2.0 TwistedWeb/9.0.0"