strange calendar errors, python process taking CPU

The caldavd_setup.log is unremarkable and appears that everything worked until the end.

Feb 14 19:53:50 [CalendarServerCommonSetup] Serveradmin successful

Feb 14 19:53:50 [CalendarServerCommonSetup] Calling fix-permissions

Feb 14 19:53:50 [CalendarServerCommonSetup] Calling calendarserver_upgrade --postprocess

Feb 14 19:54:01 [CalendarServerCommonSetup] Output from calendarserver_upgrade: 2016-02-14 19:53:53-0600 Converting augments.xml

2016-02-14 19:53:53-0600 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>

2016-02-14 19:53:53-0600 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>

Created directory: /var/run/caldavd_requests

2016-02-14 19:53:58-0600 Unable to connect to database for schema creation: [Errno 32] Broken pipe

2016-02-14 19:53:59-0600 Can't start or connect to postgres: md5 password authentication failed

Failed to start service.

Feb 14 19:54:01 [CalendarServerCommonSetup] Sending to serveradmin: calendar:command = exportPushCertificates

Feb 14 19:54:01 [CalendarServerCommonSetup] Output: calendar:Exported = "Yes"

Feb 14 19:54:01 [CalendarServerCommonSetup] Executing: /Applications/Server.app/Contents/ServerRoot/usr/sbin/serverctl enable service=org.calendarserver.agent

Feb 14 19:54:01 [CalendarServerCommonSetup] Output: {

}

Feb 14 19:54:01 [CalendarServerCommonSetup] Executing: /Applications/Server.app/Contents/ServerRoot/usr/sbin/serverctl enable service=org.calendarserver.relocate

Feb 14 19:54:02 [CalendarServerCommonSetup] Output: {

}

Feb 14 19:54:02 [CalendarServerCommonSetup] Executing: /Applications/Server.app/Contents/ServerRoot/usr/sbin/serverctl enable service=org.calendarserver.archive

Feb 14 19:54:02 [CalendarServerCommonSetup] Output: {

}

Feb 14 19:54:02 [CalendarServerCommonSetup] Executing: /bin/launchctl start org.calendarserver.agent

Feb 14 19:54:02 [CalendarServerCommonSetup] Executing: /Applications/Server.app/Contents/ServerRoot/Library/CalendarServer/Setup/Calen darServerLogRotationConf

Feb 14 19:54:02 [CalendarServerCommonSetup] Service was not previously enabled

Feb 14 19:54:02 [CalendarServerCommonSetup] Exiting with success

Drew,

Thanks for engaging on the fox chase with me!

I found some more hints in the server app log folder. There's a 60MB log file caldav_agent.log chock full of this message:

AttributeError: 'module' object has no attribute 'openssl_md_meth_names'

Traceback (most recent call last):

File "/usr/bin/twistd", line 13, in <module>

from twisted.scripts.twistd import run

File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/scripts/twistd.py", line 11, in <module>

from twisted.application import app

File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/application/app.py", line 13, in <module>

from twisted.persisted import sob

File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twi sted/persisted/sob.py", line 21, in <module>

from hashlib import md5

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'

meth_names? Is my server smoking meth? LOL

i tried the 3.2.1 recovery. It didn't work.

Indeed. everything else on this server is going along swimmingly. I even have one wordpress site using a web app I made to proxypass php to php7 php-fpm. It's about four times faster than the php55 mod_php used by the web server default. The idea of nuke and rebuild isn't any fun -- I also have real catchall addresses set up for multiple domains on email. That's a feat in itself!!! 😁 So, I'm not inclined at all to nuke my baby. I just wanted to start using calendar! LOL

That is a piece of the puzzle: I'm on Yosemite (not el capitan) and server 5.

There are issues with the mac python packages, and I've found some discussion about that floating around the webs. unfortunately, many of them end by installing el capitan. I wasn't wanting to do that either because of the SIP issues making it more difficult.

What I have been able to glean from those discussion, though, is that the python linking gets confused as to which hash library it should load and loads ones from other versions. Yosemite has 2.6 and 2.7. So, I'm not really sure how to verify this... Is it a case where server failed to finish a script, or a case where yosemite has a bad install?

Incidentally, Drew, you asked above about postgres status. I ran that and got this:

postgres:error = <62706c69 73743030 d4010203 04050618 19582476 65727369 6f6e5824 6f626a65 63747359 24617263 68697665 72542474 6f701200 0186a0a4 07081112 55246e75 6c6cd409 0a0b0c0d 0e0f1056 4e53436f 64655a4e 53557365 72496e66 6f584e53 446f6d61 696e5624 636c6173 73100180 00800280 035f1014 636f6d2e 6170706c 652e7365 72766572 6d677264 d2131415 165a2463 6c617373 6e616d65 5824636c 61737365 73574e53 4572726f 72a21517 584e534f 626a6563 745f100f 4e534b65 79656441 72636869 766572d1 1a1b5472 6f6f7480 0108111a 232d3237 3c424b52 5d666d6f 7173758c 919ca5ad b0b9cbce d3000000 00000001 01000000 00000000 1c000000 00000000 00000000 00000000 d5>
postgres:errorDescription = "The operation couldn’t be completed. (com.apple.servermgrd error 1.)"
postgres:errorCode = 1

Drew,

I've been digging around on this. I upgraded the OS to Mavericks. Problem persisted. I dug around in the calendar Logs and found this:

2016-02-17 03:30:18 CSTLOG:  redirecting log output to logging collector process
2016-02-17 03:30:18 CSTHINT:  Future log output will appear in directory "/Library/Server/Calendar and Contacts/Logs".
2016-02-17 03:30:19 XPG.25365:  Socket available; starting should now be complete.
2016-02-17 03:30:19 XPG.25365:  log receiver: pg_receivexlog: could not connect to server: FATAL:  role "caldav" does not exist


pg_receivexlog: disconnected; waiting 5 seconds to try again
2016-02-17 03:30:21 XPG.25365:  Decremented reference count. Count is now: 0
2016-02-17 03:30:21 XPG.25365:  Reference count reached zero.  Shutting down.
2016-02-17 03:30:21 XPG.25365:  Killing idle connections...
2016-02-17 03:30:21 XPG.25365:  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';")
psql: FATAL:  role "caldav" does not exist

I Have the runaway logging happening in /Calendar and Contacts/data/database.xpg/backup as well

I have that issue managed at the moment (excluded from time machine and carbon copy cloner). But that backup runaway explains the python.

I'm not sure how to fix the missing role "caldav". I've seen a million threads now where people use Postgres to repair null entries but honestly, I don't understand it well enough to do it.

ANy ideas?

Just to help anyone else looking for this later one.

There are several threads laying around where _teamserver and python go off the charts. Literally, one of the cores on my poor mini server (fortunately, I have a quad core) has been pegging out at 80-100% for several days over this mess -- sys cpu was around 4% and user CPU hovering are 15% the entire time.

The root problem comes from what I posted above -- somewhere in the configuration files that had been either half-migrated, not migrated, or corrupted along the path, some plist was trying to use the wrong hashlib.py definition and it was causing the calendar server to be unable to keep the postgres process connected to the caldav socket. This was generating a constant reconnection. That reconnection was dumping logs into the postgres journal. These services have a postgres archive journal activated. When working, it's a great thing because it's a rolling log of database history. Unfortunately, when reconnection cause several kb of logs to be generated every five seconds, you can get 100s of gb of logs piling up quickly.

To top it all off, it appeared to me that the corrupt/incomplete migration never actually migrated the database itself, thereby further compounding the mess -- so there were (null) IDs in the database. I'm not so dedicated to it that I could get that fixed.

I was not able to chase down the precise issue. I did fix it, however. I had no old data to migrate. So I went with a chance and set out to reset Just the Calendar services of the server app.

I've seen threads of people asking, and I can now confirm that this worked to reset only the Calendar service:

1. Toss the Server.app to the trash. Wait for the script to trigger the pop up confirmation. Click OK.
2. Empty the contents of /Library/Server/Calendar and Contacts.
3. Move Server.app back to Applications folder.
4. Start Server. Wait for the migration scripts to run.
5. Start services.

Calendar, wiki, contacts... all of them started nicely. web service works perfectly. More importantly, my load all dropped to normal again. sys CPU (before I turned web services back on was 0.5% and user was 2%. that's what I expect and have come to see as normal (as long as the wordpress sites aren't getting hammered).

Thanks for attempting to help me, Drew!