Exception thrown when using chained certificates
Hi, I finally managed to get Calendar Server (version 4.2) to run on my Mac (10.7.5). It runs without problems if I use a self-signed certificate. However, I wanted to go a step further, and introduce my root and intermediate certificates in the process. However, the server fails with the output listed at the end of this message. This is the relevant part of caldavd.plist: <!-- SSL/TLS --> <!-- Public key --> <key>SSLCertificate</key> <string>/usr/local/caldavd/etc/caldav-server.crt</string> <!-- SSL authority chain (for intermediate certs) --> <key>SSLAuthorityChain</key> <string>/usr/local/caldavd/etc/chain.crt</string> <!-- Private key --> <key>SSLPrivateKey</key> <string>/usr/local/caldavd/etc/caldav-server.key</string> I created these, using roughly these steps: openssl genrsa -des3 -passout pass:stdin -out root-ca.key 4096 openssl req -new -key root-ca.key -out root-ca.csr openssl x509 -req -days 4384 -in root-ca.csr -signkey root-ca.key \ -extfile GenerateCertificate.cfg -extensions v3_ca -out root-ca.crt openssl pkcs12 -export -in root-ca.crt -inkey root-ca.key -out root-ca.p12 openssl pkcs12 -in root-ca.p12 -out root-ca.pem -nodes intermediate: openssl genrsa -des3 -out intermediate-ca.key 2048 openssl req -new -key intermediate-ca.key -out intermediate-ca.csr openssl x509 -req -days 4384 -in intermediate-ca.csr \ -CA root-ca.crt -CAkey root-ca.key \ -set_serial 1 -extfile GenerateCertificate.cfg -extensions v3_ca -out intermediate-ca.crt openssl pkcs12 -export -in intermediate-ca.crt -inkey intermediate-ca.key \ -chain -CAfile root-ca.crt -out intermediate-ca.p12 openssl pkcs12 -in intermediate-ca.p12 -out intermediate-ca.pem -nodes leaf certificates: export name=caldav-server openssl genrsa -des3 -out $name.key 2048 openssl req -new -key $name.key -out $name.csr openssl x509 -req -days 1095 -in $name.csr -CA root/intermediate-ca.crt -CAkey root/intermediate-ca.key \ -set_serial 1 -out $name.crt openssl pkcs12 -export -in $name.crt -inkey $name.key -chain -CAfile root/intermediate-ca.pem -out $name.p12 openssl pkcs12 -in $name.p12 -out $name.pem -nodes And then produces chain.crt by doing: cat caldav-server.crt intermediate-ca.crt root-ca.crt > chain.crt I created a virtualenv for caldav server, where I'm running Twisted 12.3.0 (same problem appears with 12.0.0). Any pointer toward resolving this issue would be most helpful :) Thanks, Nikola This is the output I'm getting: 2013-03-31 20:02:24+0200 [-] [caldav-0] [-] Unhandled Error 2013-03-31 20:02:24+0200 [-] [caldav-0] Traceback (most recent call last): 2013-03-31 20:02:24+0200 [-] [caldav-0] File "/usr/local/caldavd/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-macosx-10.7-intel.egg/twisted/python/log.py", line 73, in callWithContext 2013-03-31 20:02:24+0200 [-] [caldav-0] return context.call({ILogContext: newCtx}, func, *args, **kw) 2013-03-31 20:02:24+0200 [-] [caldav-0] File "/usr/local/caldavd/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-macosx-10.7-intel.egg/twisted/python/context.py", line 118, in callWithContext 2013-03-31 20:02:24+0200 [-] [caldav-0] return self.currentContext().callWithContext(ctx, func, *args, **kw) 2013-03-31 20:02:24+0200 [-] [caldav-0] File "/usr/local/caldavd/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-macosx-10.7-intel.egg/twisted/python/context.py", line 81, in callWithContext 2013-03-31 20:02:24+0200 [-] [caldav-0] return func(*args,**kw) 2013-03-31 20:02:24+0200 [-] [caldav-0] File "/usr/local/caldavd/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-macosx-10.7-intel.egg/twisted/internet/selectreactor.py", line 151, in _doReadOrWrite 2013-03-31 20:02:24+0200 [-] [caldav-0] why = getattr(selectable, method)() 2013-03-31 20:02:24+0200 [-] [caldav-0] --- <exception caught here> --- 2013-03-31 20:02:24+0200 [-] [caldav-0] File "/usr/local/caldavd/lib/python2.7/site-packages/twext/internet/sendfdport.py", line 295, in doRead 2013-03-31 20:02:24+0200 [-] [caldav-0] description, protocol) 2013-03-31 20:02:24+0200 [-] [caldav-0] File "/usr/local/caldavd/lib/python2.7/site-packages/twext/web2/metafd.py", line 103, in createTransport 2013-03-31 20:02:24+0200 [-] [caldav-0] transport.startTLS(self.contextFactory) 2013-03-31 20:02:24+0200 [-] [caldav-0] File "/usr/local/caldavd/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-macosx-10.7-intel.egg/twisted/internet/_newtls.py", line 179, in startTLS 2013-03-31 20:02:24+0200 [-] [caldav-0] startTLS(self, ctx, normal, FileDescriptor) 2013-03-31 20:02:24+0200 [-] [caldav-0] File "/usr/local/caldavd/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-macosx-10.7-intel.egg/twisted/internet/_newtls.py", line 139, in startTLS 2013-03-31 20:02:24+0200 [-] [caldav-0] tlsFactory = TLSMemoryBIOFactory(contextFactory, client, None) 2013-03-31 20:02:24+0200 [-] [caldav-0] File "/usr/local/caldavd/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-macosx-10.7-intel.egg/twisted/protocols/tls.py", line 602, in __init__ 2013-03-31 20:02:24+0200 [-] [caldav-0] contextFactory.getContext() 2013-03-31 20:02:24+0200 [-] [caldav-0] exceptions.AttributeError: 'NoneType' object has no attribute 'getContext'
On Mar 31, 2013, at 3:40 PM, Nikola Knežević <laladelausanne@gmail.com> wrote:
This is the output I'm getting:
Would you mind attaching the full output of the server's start up - ideally with debug logging enabled - rather than just the traceback? Thanks. (I suspect the problem is something simple, like a typo in the file name, and it's just reporting the error badly, but I can't be sure.) -glyph
On Apr 1, 2013, at 9:59 , Glyph wrote:
On Mar 31, 2013, at 3:40 PM, Nikola Knežević <laladelausanne@gmail.com> wrote:
This is the output I'm getting:
Would you mind attaching the full output of the server's start up - ideally with debug logging enabled - rather than just the traceback?
Sure, thanks for the response! The output is below the message. I'm using the following command to start the server: sudo -u _calendar /usr/local/caldavd/bin/caldavd -X -f /usr/local/caldavd/etc/caldavd.plist -T /usr/local/caldavd/bin/twistd And I enabled debugging by setting: <!-- Log levels --> <key>DefaultLogLevel</key> <string>debug</string> <!-- debug, info, warn, error --> Exception is triggered by starting iCal that is set to connect to this server. Thanks, Nikola 2013-04-01 10:46:33+0200 [-] Log opened. 2013-04-01 10:46:33+0200 [-] twistd 12.3.0 (/usr/local/caldavd/bin/python2.7 2.7.3) starting up. 2013-04-01 10:46:33+0200 [-] reactor class: twisted.internet.selectreactor.SelectReactor. 2013-04-01 10:46:33+0200 [-] ControlSocket starting on '/usr/local/caldavd/run/caldavd.sock' 2013-04-01 10:46:33+0200 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseSchemaService#warn] Beginning database schema check. 2013-04-01 10:46:33+0200 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseSchemaService#warn] Required database key VERSION: 12. 2013-04-01 10:46:33+0200 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseSchemaService#warn] Actual database key VERSION: 12. 2013-04-01 10:46:33+0200 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseSchemaService#warn] Schema version check complete: no upgrade needed. 2013-04-01 10:46:33+0200 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseSchemaService#warn] Database schema check complete. 2013-04-01 10:46:33+0200 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseDataService#warn] Beginning database data check. 2013-04-01 10:46:33+0200 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseDataService#warn] Required database key CALENDAR-DATAVERSION: 3. 2013-04-01 10:46:33+0200 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseDataService#warn] Actual database key CALENDAR-DATAVERSION: 3. 2013-04-01 10:46:33+0200 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseDataService#warn] Data version check complete: no upgrade needed. 2013-04-01 10:46:33+0200 [-] [txdav.common.datastore.upgrade.sql.upgrade.UpgradeDatabaseDataService#warn] Database data check complete. 2013-04-01 10:46:33+0200 [-] [calendarserver.tap.util#info] Configuring augment service of type: <class 'twistedcaldav.directory.augment.AugmentXMLDB'> 2013-04-01 10:46:33+0200 [-] [calendarserver.tap.util#info] Configuring directory service of type: twistedcaldav.directory.xmlfile.XMLDirectoryService 2013-04-01 10:46:33+0200 [-] [calendarserver.tap.util#info] Configuring resource service of type: <class 'twistedcaldav.directory.xmlfile.XMLDirectoryService'> 2013-04-01 10:46:33+0200 [-] [calendarserver.tap.util#info] Setting up principal collection: <class 'twistedcaldav.directory.principal.DirectoryPrincipalProvisioningResource'> 2013-04-01 10:46:33+0200 [-] [twistedcaldav.directory.directory.GroupMembershipCache#debug] is group-cacher-populated 2013-04-01 10:46:33+0200 [-] [twistedcaldav.directory.directory.GroupMembershipCache#debug] Getting Cache Token for 'group-cacher-populated' 2013-04-01 10:46:33+0200 [-] [twistedcaldav.memcachepool.MemCachePool#debug] Initating new client connection to: <twext.internet.gaiendpoint.GAIEndpoint object at 0x10d894fd0> 2013-04-01 10:46:33+0200 [-] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 0, #busy: 0, #pending: 0, #queued: 0 2013-04-01 10:46:33+0200 [Uninitialized] [twistedcaldav.memcachepool.MemCachePool#debug] Busied client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x10dcd58c0> 2013-04-01 10:46:33+0200 [Uninitialized] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 0, #busy: 1, #pending: 0, #queued: 0 2013-04-01 10:46:33+0200 [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Freed client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x10dcd58c0> 2013-04-01 10:46:33+0200 [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 1, #busy: 0, #pending: 0, #queued: 0 2013-04-01 10:46:33+0200 [PooledMemCacheProtocol,client] [twistedcaldav.directory.directory.GroupMembershipCacheUpdater#info] Group membership cache is already populated 2013-04-01 10:46:33+0200 [-] LimitingInheritingProtocolFactory starting on 8443 2013-04-01 10:46:33+0200 [-] LimitingInheritingProtocolFactory starting on 8443 2013-04-01 10:46:33+0200 [-] Factory starting on 7654 2013-04-01 10:46:33+0200 [-] [calendarserver.tap.caldav.CalDAVServiceMaker#info] Adding notification service 2013-04-01 10:46:33+0200 [-] [calendarserver.tap.caldav.CalDAVServiceMaker#info] Adding group caching service 2013-04-01 10:46:34+0200 [twisted.internet.protocol.Factory] ConnectionFromPeerNode connection established (HOST:IPv4Address(TCP, '127.0.0.1', 7654) PEER:IPv4Address(TCP, '127.0.0.1', 62909)) 2013-04-01 10:46:34+0200 [Uninitialized] ConnectionFromPeerNode connection established (HOST:IPv4Address(TCP, '127.0.0.1', 62909) PEER:IPv4Address(TCP, '127.0.0.1', 7654)) 2013-04-01 10:46:34+0200 [Uninitialized] ConnectionFromPeerNode connection established (HOST:IPv4Address(TCP, '127.0.0.1', 62911) PEER:IPv4Address(TCP, '127.0.0.1', 7654)) 2013-04-01 10:46:34+0200 [twisted.internet.protocol.Factory] ConnectionFromPeerNode connection established (HOST:IPv4Address(TCP, '127.0.0.1', 7654) PEER:IPv4Address(TCP, '127.0.0.1', 62911)) 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] Log opened. 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] twistd 12.3.0 (/usr/local/caldavd/bin/python2.7 2.7.3) starting up. 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] reactor class: twisted.internet.selectreactor.SelectReactor. 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] /usr/local/caldavd/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-macosx-10.7-intel.egg/twisted/python/util.py:560: exceptions.UserWarning: tried to drop privileges and setuid 93 but uid is already 93; should we be root? Continuing. 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] set uid/gid 93/93 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] [twistedcaldav.directory.directory.GroupMembershipCacherService#warn] Starting group membership cacher service 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] [twistedcaldav.directory.directory.GroupMembershipCacherService#debug] Group membership update called 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] [twistedcaldav.directory.directory.GroupMembershipCache#debug] is group-cacher-populated 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] [twistedcaldav.directory.directory.GroupMembershipCache#debug] Getting Cache Token for 'group-cacher-populated' 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] [twistedcaldav.memcachepool.MemCachePool#debug] Initating new client connection to: <twext.internet.gaiendpoint.GAIEndpoint object at 0x10fbc4450> 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 0, #busy: 0, #pending: 0, #queued: 0 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [Uninitialized] [twistedcaldav.memcachepool.MemCachePool#debug] Busied client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x10fbc9368> 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [Uninitialized] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 0, #busy: 1, #pending: 0, #queued: 0 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Freed client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x10fbc9368> 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 1, #busy: 0, #pending: 0, #queued: 0 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.directory.directory.GroupMembershipCacheUpdater#info] Updating group membership cache 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.directory.directory.GroupMembershipCacheUpdater#info] Group membership snapshot file exists: /var/db/caldavd/Data/memberships_cache 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.directory.directory.GroupMembershipCacheUpdater#info] Attempting to acquire group membership cache lock 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.directory.directory.GroupMembershipCache#debug] add group-cacher-lock 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.directory.directory.GroupMembershipCache#debug] Adding Cache Token for 'group-cacher-lock' 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Busied client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x10fbc9368> 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 0, #busy: 1, #pending: 0, #queued: 0 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Freed client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x10fbc9368> 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 1, #busy: 0, #pending: 0, #queued: 0 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.directory.directory.GroupMembershipCacheUpdater#info] Acquired lock 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.directory.directory.GroupMembershipCacheUpdater#info] Retrieving list of all proxies 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] [twistedcaldav.database#debug] Starting ADBAPI thread: 4567547904 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] [twistedcaldav.directory.directory.GroupMembershipCacheUpdater#info] There are 4 proxies 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] [twistedcaldav.directory.directory.GroupMembershipCacheUpdater#info] Retrieving group hierarchy from directory 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] [twistedcaldav.directory.directory.GroupMembershipCacheUpdater#info] 1 groups retrieved from the directory 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] [twistedcaldav.directory.directory.GroupMembershipCacheUpdater#info] 0 groups are proxies 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] [twistedcaldav.directory.directory.GroupMembershipCacheUpdater#info] There are 0 users delegated-to via groups 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] [twistedcaldav.directory.directory.GroupMembershipCacheUpdater#info] Taking snapshot of group memberships to /var/db/caldavd/Data/memberships_cache 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] [twistedcaldav.directory.directory.GroupMembershipCacheUpdater#info] Storing 0 group memberships in memcached 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] [twistedcaldav.directory.directory.GroupMembershipCache#debug] set group-cacher-populated 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] [twistedcaldav.directory.directory.GroupMembershipCache#debug] Setting Cache Token for 'group-cacher-populated' 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] [twistedcaldav.memcachepool.MemCachePool#debug] Busied client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x10fbc9368> 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [-] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 0, #busy: 1, #pending: 0, #queued: 0 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Freed client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x10fbc9368> 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 1, #busy: 0, #pending: 0, #queued: 0 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.directory.directory.GroupMembershipCacheUpdater#info] Releasing lock 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.directory.directory.GroupMembershipCache#debug] delete group-cacher-lock 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.directory.directory.GroupMembershipCache#debug] Deleting Cache Token for 'group-cacher-lock' 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Busied client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x10fbc9368> 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 0, #busy: 1, #pending: 0, #queued: 0 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Freed client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x10fbc9368> 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 1, #busy: 0, #pending: 0, #queued: 0 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.directory.directory.GroupMembershipCacheUpdater#info] Group memberships cache updated 2013-04-01 10:46:39+0200 [-] [groupcacher] 2013-04-01 10:46:39+0200 [PooledMemCacheProtocol,client] [twistedcaldav.directory.directory.GroupMembershipCacherService#info] Scheduling next group membership update 2013-04-01 10:46:39+0200 [-] [notifications] 2013-04-01 10:46:39+0200 [-] Log opened. 2013-04-01 10:46:39+0200 [-] [notifications] 2013-04-01 10:46:39+0200 [-] twistd 12.3.0 (/usr/local/caldavd/bin/python2.7 2.7.3) starting up. 2013-04-01 10:46:39+0200 [-] [notifications] 2013-04-01 10:46:39+0200 [-] reactor class: twisted.internet.selectreactor.SelectReactor. 2013-04-01 10:46:39+0200 [-] [notifications] 2013-04-01 10:46:39+0200 [-] AMPPushNotifierFactory starting on 62311 2013-04-01 10:46:39+0200 [-] [notifications] 2013-04-01 10:46:39+0200 [-] InternalNotificationFactory starting on 62309 2013-04-01 10:46:39+0200 [-] [notifications] 2013-04-01 10:46:39+0200 [-] /usr/local/caldavd/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-macosx-10.7-intel.egg/twisted/python/util.py:560: exceptions.UserWarning: tried to drop privileges and setuid 93 but uid is already 93; should we be root? Continuing. 2013-04-01 10:46:39+0200 [-] [notifications] 2013-04-01 10:46:39+0200 [-] set uid/gid 93/93 2013-04-01 10:46:39+0200 [-] [caldav-1] Reading configuration from file: /usr/local/caldavd/etc/caldavd.plist 2013-04-01 10:46:39+0200 [-] [caldav-1] [-] Log opened. 2013-04-01 10:46:39+0200 [-] [caldav-1] [-] twistd 12.3.0 (/usr/local/caldavd/bin/python2.7 2.7.3) starting up. 2013-04-01 10:46:39+0200 [-] [caldav-1] [-] reactor class: twisted.internet.selectreactor.SelectReactor. 2013-04-01 10:46:39+0200 [-] [caldav-1] [-] /usr/local/caldavd/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-macosx-10.7-intel.egg/twisted/python/util.py:560: exceptions.UserWarning: tried to drop privileges and setuid 93 but uid is already 93; should we be root? Continuing. 2013-04-01 10:46:39+0200 [-] [caldav-1] [-] set uid/gid 93/93 2013-04-01 10:46:39+0200 [-] [caldav-0] Reading configuration from file: /usr/local/caldavd/etc/caldavd.plist 2013-04-01 10:46:39+0200 [-] [caldav-0] [-] Log opened. 2013-04-01 10:46:39+0200 [-] [caldav-0] [-] twistd 12.3.0 (/usr/local/caldavd/bin/python2.7 2.7.3) starting up. 2013-04-01 10:46:39+0200 [-] [caldav-0] [-] reactor class: twisted.internet.selectreactor.SelectReactor. 2013-04-01 10:46:39+0200 [-] [caldav-0] [-] /usr/local/caldavd/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-macosx-10.7-intel.egg/twisted/python/util.py:560: exceptions.UserWarning: tried to drop privileges and setuid 93 but uid is already 93; should we be root? Continuing. 2013-04-01 10:46:39+0200 [-] [caldav-0] [-] set uid/gid 93/93 2013-04-01 10:47:22+0200 [-] [caldav-0] [-] Unhandled Error 2013-04-01 10:47:22+0200 [-] [caldav-0] Traceback (most recent call last): 2013-04-01 10:47:22+0200 [-] [caldav-0] File "/usr/local/caldavd/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-macosx-10.7-intel.egg/twisted/python/log.py", line 73, in callWithContext 2013-04-01 10:47:22+0200 [-] [caldav-0] return context.call({ILogContext: newCtx}, func, *args, **kw) 2013-04-01 10:47:22+0200 [-] [caldav-0] File "/usr/local/caldavd/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-macosx-10.7-intel.egg/twisted/python/context.py", line 118, in callWithContext 2013-04-01 10:47:22+0200 [-] [caldav-0] return self.currentContext().callWithContext(ctx, func, *args, **kw) 2013-04-01 10:47:22+0200 [-] [caldav-0] File "/usr/local/caldavd/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-macosx-10.7-intel.egg/twisted/python/context.py", line 81, in callWithContext 2013-04-01 10:47:22+0200 [-] [caldav-0] return func(*args,**kw) 2013-04-01 10:47:22+0200 [-] [caldav-0] File "/usr/local/caldavd/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-macosx-10.7-intel.egg/twisted/internet/selectreactor.py", line 151, in _doReadOrWrite 2013-04-01 10:47:22+0200 [-] [caldav-0] why = getattr(selectable, method)() 2013-04-01 10:47:22+0200 [-] [caldav-0] --- <exception caught here> --- 2013-04-01 10:47:22+0200 [-] [caldav-0] File "/usr/local/caldavd/lib/python2.7/site-packages/twext/internet/sendfdport.py", line 295, in doRead 2013-04-01 10:47:22+0200 [-] [caldav-0] description, protocol) 2013-04-01 10:47:22+0200 [-] [caldav-0] File "/usr/local/caldavd/lib/python2.7/site-packages/twext/web2/metafd.py", line 103, in createTransport 2013-04-01 10:47:22+0200 [-] [caldav-0] transport.startTLS(self.contextFactory) 2013-04-01 10:47:22+0200 [-] [caldav-0] File "/usr/local/caldavd/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-macosx-10.7-intel.egg/twisted/internet/_newtls.py", line 179, in startTLS 2013-04-01 10:47:22+0200 [-] [caldav-0] startTLS(self, ctx, normal, FileDescriptor) 2013-04-01 10:47:22+0200 [-] [caldav-0] File "/usr/local/caldavd/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-macosx-10.7-intel.egg/twisted/internet/_newtls.py", line 139, in startTLS 2013-04-01 10:47:22+0200 [-] [caldav-0] tlsFactory = TLSMemoryBIOFactory(contextFactory, client, None) 2013-04-01 10:47:22+0200 [-] [caldav-0] File "/usr/local/caldavd/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-macosx-10.7-intel.egg/twisted/protocols/tls.py", line 602, in __init__ 2013-04-01 10:47:22+0200 [-] [caldav-0] contextFactory.getContext() 2013-04-01 10:47:22+0200 [-] [caldav-0] exceptions.AttributeError: 'NoneType' object has no attribute 'getContext'
Still not sure; I need to go do some testing of my own, but can you check on something? I think this line might be a clue: On Apr 1, 2013, at 1:50 AM, Nikola Knežević <laladelausanne@gmail.com> wrote:
2013-04-01 10:46:39+0200 [-] [caldav-0] [-] /usr/local/caldavd/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-macosx-10.7-intel.egg/twisted/python/util.py:560: exceptions.UserWarning: tried to drop privileges and setuid 93 but uid is already 93; should we be root? Continuing.
Is your SSL cert (including private key & any chain certs) readable by UID 93? -glyph
On Apr 2, 2013, at 18:17 , Glyph wrote:
Still not sure; I need to go do some testing of my own, but can you check on something? I think this line might be a clue:
On Apr 1, 2013, at 1:50 AM, Nikola Knežević <laladelausanne@gmail.com> wrote:
2013-04-01 10:46:39+0200 [-] [caldav-0] [-] /usr/local/caldavd/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-macosx-10.7-intel.egg/twisted/python/util.py:560: exceptions.UserWarning: tried to drop privileges and setuid 93 but uid is already 93; should we be root? Continuing.
Is your SSL cert (including private key & any chain certs) readable by UID 93?
Hi Glyph, sure, can gladly check anything on my computer :) Yes, it is readable: /usr/local/caldavd/etc % ll total 176 ..snip.. -rw-r--r-- 1 _calendar _calendar 1358 Mar 26 02:53 accounts.xml -rw-r--r-- 1 _calendar _calendar 864 Mar 28 23:14 augments.xml -rw-r--r-- 1 _calendar _calendar 1131 Mar 29 21:38 caldav-server.crt -rw-r--r-- 1 _calendar _calendar 1743 Mar 29 21:38 caldav-server.key -rw-r--r-- 1 _calendar _calendar 6952 Mar 30 11:31 caldav-server.pem ..snip… /usr/local/caldavd/etc % id 93 uid=93(_calendar) gid=93(_calendar) groups=93(_calendar),405(com.apple.sharepoint.group.4),12(everyone),29(certusers),30(_keytabusers),61(localaccounts),216(_postgres) Best, Nikola
On Apr 2, 2013, at 9:46 AM, Nikola Knežević <laladelausanne@gmail.com> wrote:
On Apr 2, 2013, at 18:17 , Glyph wrote:
Still not sure; I need to go do some testing of my own, but can you check on something? I think this line might be a clue:
On Apr 1, 2013, at 1:50 AM, Nikola Knežević <laladelausanne@gmail.com> wrote:
2013-04-01 10:46:39+0200 [-] [caldav-0] [-] /usr/local/caldavd/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-macosx-10.7-intel.egg/twisted/python/util.py:560: exceptions.UserWarning: tried to drop privileges and setuid 93 but uid is already 93; should we be root? Continuing.
Is your SSL cert (including private key & any chain certs) readable by UID 93?
Hi Glyph,
sure, can gladly check anything on my computer :)
Yes, it is readable:
/usr/local/caldavd/etc % ll total 176 ..snip.. -rw-r--r-- 1 _calendar _calendar 1358 Mar 26 02:53 accounts.xml -rw-r--r-- 1 _calendar _calendar 864 Mar 28 23:14 augments.xml -rw-r--r-- 1 _calendar _calendar 1131 Mar 29 21:38 caldav-server.crt -rw-r--r-- 1 _calendar _calendar 1743 Mar 29 21:38 caldav-server.key -rw-r--r-- 1 _calendar _calendar 6952 Mar 30 11:31 caldav-server.pem ..snip…
/usr/local/caldavd/etc % id 93 uid=93(_calendar) gid=93(_calendar) groups=93(_calendar),405(com.apple.sharepoint.group.4),12(everyone),29(certusers),30(_keytabusers),61(localaccounts),216(_postgres)
OK, Nikola, I can't seem to reproduce your issue myself. If you have any other information that you think is germane, please let me know. Can you load the certificate with OpenSSL? Can you point another web server at it - not caldavd - and speak to clients with it? -glyph
On Apr 3, 2013, at 1:15 , Glyph wrote:
OK, Nikola, I can't seem to reproduce your issue myself. If you have any other information that you think is germane, please let me know. Can you load the certificate with OpenSSL? Can you point another web server at it - not caldavd - and speak to clients with it?
Hi Glyph, I also tried the certificates with Apache - it works. However, when starting Apache, I was prompted for caldav-server.key's password. Maybe that is causing problems for twisted? If so, how could I create a passwordless key, if possible? OpenSSL correctly verifies the certificate: /tmp/keys % openssl verify -verbose -CAfile chain.crt -purpose sslserver caldav-server.crt caldav-server.crt: OK /tmp/keys % perl -n0777e 'map { print "---\n"; open(CMD, "| openssl x509 -noout -subject -issuer"); quote> print CMD; close(CMD) } /^-----BEGIN.*?^-----END.*?\n/gsm' chain.crt --- subject= /C=CH/ST=X/O=Nikola/CN=caldav-server issuer= /C=CH/ST=X/O=Nikola/CN=Intermediate CA --- subject= /C=CH/ST=X/O=Nikola/CN=Intermediate CA issuer= /C=CH/ST=X/O=Nikola/CN=Root CA --- subject= /C=CH/ST=X/O=Nikola/CN=Root CA issuer= /C=CH/ST=X/O=Nikola/CN=Root CA /tmp/keys % % openssl x509 -noout -text -in caldav-server.crt Certificate: Data: Version: 1 (0x0) Serial Number: 1 (0x1) Signature Algorithm: sha1WithRSAEncryption Issuer: C=CH, ST=X, O=Nikola, CN=Intermediate CA Validity Not Before: Mar 29 18:43:21 2013 GMT Not After : Mar 28 18:43:21 2016 GMT Subject: C=CH, ST=X, O=Nikola, CN=caldav-server Subject Public Key Info: Public Key Algorithm: rsaEncryption RSA Public Key: (2048 bit) Modulus (2048 bit): xx Exponent: yy Signature Algorithm: sha1WithRSAEncryption uu If it may help, these are python modules running on my system: % pip list Calendar-and-Contacts-Server (4.2.-r10865M-) distribute (0.6.35) kerberos (1.1.1) opendirectory (1.0) psutil (0.6.1) pyasn1 (0.1.6) pyasn1-modules (0.0.4) pycalendar (2.0) pycrypto (2.6) pycrypto-on-pypi (2.3) pydoctor (0.5b1) PyGreSQL (4.1.1) pyOpenSSL (0.13) python-dateutil (2.1) python-ldap (2.4.10) pytz (2013b) setproctitle (1.1.7) six (1.3.0) sqlparse (0.1.2) Twisted (12.3.0) wsgiref (0.1.2) xattr (0.6.4) zope.interface (4.0.5) Thanks, Nikola
Hi,
I also tried the certificates with Apache - it works. However, when starting Apache, I was prompted for caldav-server.key's password. Maybe that is causing problems for twisted? If so, how could I create a passwordless key, if possible?
Yes, I think you have to strip the password from the key. I had to do it for older versions, and if that has changed let me know. I did some attempt to add http://docs.python.org/2/library/getpass.html to read the passphrase for the key, but it had some problems, probably because I was not sure about what the different processes did at the time, and how they communicated. Some day I might try again. This is how to strip it : openssl rsa -in filename.key -out filename.key.nopass It is not optimal, and it makes me cringe everytime an application makes me do this.. Exim does it to. Luckilly I am not running some important calendarserver so I can live with it for now. /Fred
Calendar server uses a couple different mechanisms to acquire a certificate's passphrase: 1) It will run the program specified in caldavd.plist "SSLCertAdmin", which defaults to /Applications/Server.app/Contents/ServerRoot/usr/sbin/certadmin on OS X Server. It passes "--get-private-key-passphrase /path/to/private.key" to that program which returns the passphrase on stdout. 2) It will run the program specified in caldavd.plist "SSLPassPhraseDialog", which defaults to /etc/apache2/getsslpassphrase. It determines whether the key type is DSA or RSA, and then <serverhostname>:<port> <keytype> to that program which returns the passphrase on stdout. You could try configuring the SSLPassPhraseDialog key to an appropriate program on your system. The problem is I don't know if this will work if the program you specify needs to interact with a tty to prompt for the passphrase because the calendar server worker processes don't have a tty as far as I know. ~morgen On Apr 4, 2013, at 11:52 PM, Fredrik Unger <fred@tree.se> wrote:
Hi,
I also tried the certificates with Apache - it works. However, when starting Apache, I was prompted for caldav-server.key's password. Maybe that is causing problems for twisted? If so, how could I create a passwordless key, if possible?
Yes, I think you have to strip the password from the key.
I had to do it for older versions, and if that has changed let me know.
I did some attempt to add http://docs.python.org/2/library/getpass.html to read the passphrase for the key, but it had some problems, probably because I was not sure about what the different processes did at the time, and how they communicated. Some day I might try again.
This is how to strip it :
openssl rsa -in filename.key -out filename.key.nopass
It is not optimal, and it makes me cringe everytime an application makes me do this.. Exim does it to.
Luckilly I am not running some important calendarserver so I can live with it for now.
/Fred _______________________________________________ calendarserver-users mailing list calendarserver-users@lists.macosforge.org https://lists.macosforge.org/mailman/listinfo/calendarserver-users
On Apr 5, 2013, at 10:33 AM, Morgen Sagen <sagen@apple.com> wrote:
You could try configuring the SSLPassPhraseDialog key to an appropriate program on your system. The problem is I don't know if this will work if the program you specify needs to interact with a tty to prompt for the passphrase because the calendar server worker processes don't have a tty as far as I know.
If the supplied traceback is what happens when the user doesn't or can't specify a passphrase, or specifies the wrong passphrase, for the cert, that's still a pretty serious bug :). Would someone like to confirm that and file it at calendarserver.org? -glyph
On Apr 5, 2013, at 19:33 , Morgen Sagen wrote:
Calendar server uses a couple different mechanisms to acquire a certificate's passphrase:
1) It will run the program specified in caldavd.plist "SSLCertAdmin", which defaults to /Applications/Server.app/Contents/ServerRoot/usr/sbin/certadmin on OS X Server. It passes "--get-private-key-passphrase /path/to/private.key" to that program which returns the passphrase on stdout.
2) It will run the program specified in caldavd.plist "SSLPassPhraseDialog", which defaults to /etc/apache2/getsslpassphrase. It determines whether the key type is DSA or RSA, and then <serverhostname>:<port> <keytype> to that program which returns the passphrase on stdout.
You could try configuring the SSLPassPhraseDialog key to an appropriate program on your system. The problem is I don't know if this will work if the program you specify needs to interact with a tty to prompt for the passphrase because the calendar server worker processes don't have a tty as far as I know.
Glyph, Fred and Morgen, thanks for your help on this issue. I confirm that once I strip the password from the key, caldavd works as expected. I will check whether I can use security(1) tool in place of SSLPassPhraseDialog (with some modifications to caldavd's code), as I don't have certadmin on my Mac OS X. Thanks once again, Nikola
participants (4)
-
Fredrik Unger
-
Glyph
-
Morgen Sagen
-
Nikola Knežević