Could you please explain what you mean by "This can be proven when using Safari to browse the
CardDAV store."?
Also, I am virtually certain this is a server issue, not a client issue. It's true that the iPhone is more
responsive, as you correctly observed, but if you look closely, you will see that the little network access
wheel spins for quite a long time after you make an edit. The difference, I believe, is just that the UI
was designed not to wait until the server gets its head out if its butt.
For anyone who might be able to make more sense out of this than I (who know nothing about WebDAV),
I am posting the access log and error logs of a single delete transaction. (the first short
excerpt is from the access log. The rest is the error log. I have put a break in the 22 second gap after
13:59:03, just to mark the delay. In fact, there was no gap in the log.
What I can see, is that
1. The client (or the server thinks the client) tries to log in unauthenticated twice, before accepting the
PROPFIND command on a third, authenticated, try. (The multiple wasted unauthenticated tries seems
like sloppiness somewhere, although it does not seem to be the primary issue.)
2. Then the server searches the cache, unsuccessfully.
3. Then, finally, it (I think!) searches the database directly.
4. Then 22 seconds pass. Why? Is there supposed to be a response to the PROPFIND command logged?
IS there one? Does the client eventually just throw up its hands and say, "I've waited long enough, I'm
just going to send a delete command"? Could this be a problem?
5. Anyway, the unauthenticated, unauthenticated, authenticated waltz is repeated, and the address
is finally deleted. Hooray.
Is this enlightening to anyone?
Access log:
10.0.128.99 - - [28/Jan/2011:13:59:02 -0400] "PROPFIND /addressbooks/_uids_/F2557B5F-872A-459A-AA82-A9111D4FF6D8/addressbook/ HTTP/1.1" 401 141 "-" "Address%20Book/875 CFNetwork/454.11.5 Darwin/10.5.0 (i386) (Macmini3%2C1)" [6.3 ms] [8844 1]
10.0.128.99 - - [28/Jan/2011:13:59:02 -0400] "PROPFIND /addressbooks/_uids_/F2557B5F-872A-459A-AA82-A9111D4FF6D8/addressbook/ HTTP/1.1" 401 141 "-" "Address%20Book/875 CFNetwork/454.11.5 Darwin/10.5.0 (i386) (Macmini3%2C1)" [6.0 ms] [8844 1]
10.0.128.99 - my.name [28/Jan/2011:13:59:03 -0400] "PROPFIND /addressbooks/_uids_/F2557B5F-872A-459A-AA82-A9111D4FF6D8/addressbook/ HTTP/1.1" 207 1192 "-" "Address%20Book/875 CFNetwork/454.11.5 Darwin/10.5.0 (i386) (Macmini3%2C1)" [282.5 ms] [8844 1]
10.0.128.99 - - [28/Jan/2011:13:59:25 -0400] "DELETE /addressbooks/_uids_/F2557B5F-872A-459A-AA82-A9111D4FF6D8/addressbook/1628B447-675B-4FA2-9446-27AA1FED9BCC-ABSPlugin.vcf HTTP/1.1" 401 141 "-" "Address%20Book/875 CFNetwork/454.11.5 Darwin/10.5.0 (i386) (Macmini3%2C1)" [6.5 ms] [8844 1]
10.0.128.99 - - [28/Jan/2011:13:59:25 -0400] "DELETE /addressbooks/_uids_/F2557B5F-872A-459A-AA82-A9111D4FF6D8/addressbook/1628B447-675B-4FA2-9446-27AA1FED9BCC-ABSPlugin.vcf HTTP/1.1" 401 141 "-" "Address%20Book/875 CFNetwork/454.11.5 Darwin/10.5.0 (i386) (Macmini3%2C1)" [6.7 ms] [8844 1]
10.0.128.99 - my.name [28/Jan/2011:13:59:26 -0400] "DELETE /addressbooks/_uids_/F2557B5F-872A-459A-AA82-A9111D4FF6D8/addressbook/1628B447-675B-4FA2-9446-27AA1FED9BCC-ABSPlugin.vcf HTTP/1.1" 204 0 "-" "Address%20Book/875 CFNetwork/454.11.5 Darwin/10.5.0 (i386) (Macmini3%2C1)" [305.7 ms] [8844 1]
Error log.
2011-01-28 13:59:02-0500 [-] [carddav-8801] [HTTPChannel,810,127.0.0.1] [twistedcaldav.pdmonster.PDClientAddressWrapper#debug] GetClientAddress(host='127.0.0.1', port=58825)
2011-01-28 13:59:02-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.pdmonster.PDClientAddressWrapper#debug] result = AmpBox({'_answer': '627', 'host': '10.0.128.99', 'port': '64182'})
2011-01-28 13:59:02-0500 [-] [carddav-8801] [AMP,client] [addressbookserver.provision.root#info] Unauthenticated users not enabled with the 'addressbook' SACL
2011-01-28 13:59:02-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.directory.digest.DigestCredentialsMemcache#debug] Getting Cache Token for '40529143635706101657652538015428002403284424733689190597'
2011-01-28 13:59:02-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.memcachepool.MemCachePool#debug] Busied client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x102451680>
2011-01-28 13:59:02-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 1, #busy: 1, #pending: 0, #queued: 0
2011-01-28 13:59:02-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Freed client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x102451680>
2011-01-28 13:59:02-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 2, #busy: 0, #pending: 0, #queued: 0
2011-01-28 13:59:02-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.directory.digest.DigestCredentialsMemcache#debug] Setting Cache Token for '40529143635706101657652538015428002403284424733689190597'
2011-01-28 13:59:02-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Busied client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x102451680>
2011-01-28 13:59:02-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 1, #busy: 1, #pending: 0, #queued: 0
2011-01-28 13:59:02-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Freed client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x102451680>
2011-01-28 13:59:02-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 2, #busy: 0, #pending: 0, #queued: 0
2011-01-28 13:59:02-0500 [-] [carddav-8801] [HTTPChannel,812,127.0.0.1] [twistedcaldav.pdmonster.PDClientAddressWrapper#debug] GetClientAddress(host='127.0.0.1', port=58827)
2011-01-28 13:59:02-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.pdmonster.PDClientAddressWrapper#debug] result = AmpBox({'_answer': '628', 'host': '10.0.128.99', 'port': '64185'})
2011-01-28 13:59:02-0500 [-] [carddav-8801] [AMP,client] [addressbookserver.provision.root#info] Unauthenticated users not enabled with the 'addressbook' SACL
2011-01-28 13:59:02-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.directory.digest.DigestCredentialsMemcache#debug] Getting Cache Token for '324145617233519746216005813245549566731145786113637426457'
2011-01-28 13:59:02-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.memcachepool.MemCachePool#debug] Busied client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x102451680>
2011-01-28 13:59:02-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 1, #busy: 1, #pending: 0, #queued: 0
2011-01-28 13:59:02-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Freed client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x102451680>
2011-01-28 13:59:02-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 2, #busy: 0, #pending: 0, #queued: 0
2011-01-28 13:59:02-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.directory.digest.DigestCredentialsMemcache#debug] Setting Cache Token for '324145617233519746216005813245549566731145786113637426457'
2011-01-28 13:59:02-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Busied client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x102451680>
2011-01-28 13:59:02-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 1, #busy: 1, #pending: 0, #queued: 0
2011-01-28 13:59:02-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Freed client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x102451680>
2011-01-28 13:59:02-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 2, #busy: 0, #pending: 0, #queued: 0
2011-01-28 13:59:02-0500 [-] [carddav-8801] [HTTPChannel,813,127.0.0.1] [twistedcaldav.pdmonster.PDClientAddressWrapper#debug] GetClientAddress(host='127.0.0.1', port=58828)
2011-01-28 13:59:02-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.pdmonster.PDClientAddressWrapper#debug] result = AmpBox({'_answer': '629', 'host': '10.0.128.99', 'port': '64186'})
2011-01-28 13:59:03-0500 [-] [carddav-8801] [-] [twistedcaldav.cache.MemcacheResponseCache#debug] hashing key for get: ('PROPFIND', '/principals/_uids_/14F36AEA-95D2-4972-BC26-22A949BFE5ED/', '/addressbooks/_uids_/F2557B5F-872A-459A-AA82-A9111D4FF6D8/addressbook/', '0', 4743151936869921573) to '00ac81f7c265221483dcd95f938b096a'
2011-01-28 13:59:03-0500 [-] [carddav-8801] [-] [twistedcaldav.cache.MemcacheResponseCache#debug] Checking cache for: '00ac81f7c265221483dcd95f938b096a'
2011-01-28 13:59:03-0500 [-] [carddav-8801] [-] [twistedcaldav.memcachepool.MemCachePool#debug] Busied client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x102451680>
2011-01-28 13:59:03-0500 [-] [carddav-8801] [-] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 1, #busy: 1, #pending: 0, #queued: 0
2011-01-28 13:59:03-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Freed client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x102451680>
2011-01-28 13:59:03-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 2, #busy: 0, #pending: 0, #queued: 0
2011-01-28 13:59:03-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.cache.MemcacheResponseCache#debug] Not in cache: '00ac81f7c265221483dcd95f938b096a'
2011-01-28 13:59:03-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.extensions#info] PROPFIND /addressbooks/_uids_/F2557B5F-872A-459A-AA82-A9111D4FF6D8/addressbook/ HTTP/1.1
2011-01-28 13:59:25-0500 [-] [carddav-8801] [HTTPChannel,814,127.0.0.1] [twistedcaldav.pdmonster.PDClientAddressWrapper#debug] GetClientAddress(host='127.0.0.1', port=58830)
2011-01-28 13:59:25-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.pdmonster.PDClientAddressWrapper#debug] result = AmpBox({'_answer': '62a', 'host': '10.0.128.99', 'port': '64191'})
2011-01-28 13:59:25-0500 [-] [carddav-8801] [AMP,client] [addressbookserver.provision.root#info] Unauthenticated users not enabled with the 'addressbook' SACL
2011-01-28 13:59:25-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.directory.digest.DigestCredentialsMemcache#debug] Getting Cache Token for '176338867087046732190082476761184731168841123273853073655'
2011-01-28 13:59:25-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.memcachepool.MemCachePool#debug] Busied client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x102451680>
2011-01-28 13:59:25-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 1, #busy: 1, #pending: 0, #queued: 0
2011-01-28 13:59:25-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Freed client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x102451680>
2011-01-28 13:59:25-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 2, #busy: 0, #pending: 0, #queued: 0
2011-01-28 13:59:25-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.directory.digest.DigestCredentialsMemcache#debug] Setting Cache Token for '176338867087046732190082476761184731168841123273853073655'
2011-01-28 13:59:25-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Busied client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x102451680>
2011-01-28 13:59:25-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 1, #busy: 1, #pending: 0, #queued: 0
2011-01-28 13:59:25-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Freed client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x102451680>
2011-01-28 13:59:25-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 2, #busy: 0, #pending: 0, #queued: 0
2011-01-28 13:59:25-0500 [-] [carddav-8801] [HTTPChannel,816,127.0.0.1] [twistedcaldav.pdmonster.PDClientAddressWrapper#debug] GetClientAddress(host='127.0.0.1', port=58832)
2011-01-28 13:59:25-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.pdmonster.PDClientAddressWrapper#debug] result = AmpBox({'_answer': '62b', 'host': '10.0.128.99', 'port': '64193'})
2011-01-28 13:59:25-0500 [-] [carddav-8801] [AMP,client] [addressbookserver.provision.root#info] Unauthenticated users not enabled with the 'addressbook' SACL
2011-01-28 13:59:25-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.directory.digest.DigestCredentialsMemcache#debug] Getting Cache Token for '488631217415836679412525151549904578551159231456520613440'
2011-01-28 13:59:25-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.memcachepool.MemCachePool#debug] Busied client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x102451680>
2011-01-28 13:59:25-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 1, #busy: 1, #pending: 0, #queued: 0
2011-01-28 13:59:25-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Freed client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x102451680>
2011-01-28 13:59:25-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 2, #busy: 0, #pending: 0, #queued: 0
2011-01-28 13:59:25-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.directory.digest.DigestCredentialsMemcache#debug] Setting Cache Token for '488631217415836679412525151549904578551159231456520613440'
2011-01-28 13:59:25-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Busied client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x102451680>
2011-01-28 13:59:25-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 1, #busy: 1, #pending: 0, #queued: 0
2011-01-28 13:59:25-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Freed client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x102451680>
2011-01-28 13:59:25-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 2, #busy: 0, #pending: 0, #queued: 0
2011-01-28 13:59:25-0500 [-] [carddav-8801] [HTTPChannel,817,127.0.0.1] [twistedcaldav.pdmonster.PDClientAddressWrapper#debug] GetClientAddress(host='127.0.0.1', port=58833)
2011-01-28 13:59:25-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.pdmonster.PDClientAddressWrapper#debug] result = AmpBox({'_answer': '62c', 'host': '10.0.128.99', 'port': '64194'})
2011-01-28 13:59:25-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.extensions.CachingPropertyStore#debug] Cache miss: <twistedcaldav.extensions.CachingPropertyStore object at 0x104953990>, '/Library/AddressBookServer/Documents/addressbooks/_uids_/F2/55/F2557B5F-872A-459A-AA82-A9111D4FF6D8/addressbook', ('DAV:', 'resourcetype')
2011-01-28 13:59:25-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.extensions#info] DELETE /addressbooks/_uids_/F2557B5F-872A-459A-AA82-A9111D4FF6D8/addressbook/1628B447-675B-4FA2-9446-27AA1FED9BCC-ABSPlugin.vcf HTTP/1.1
2011-01-28 13:59:25-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.extensions.CachingPropertyStore#debug] Cache miss: <twistedcaldav.extensions.CachingPropertyStore object at 0x104953390>, '/Library/AddressBookServer/Documents/addressbooks/_uids_/F2/55/F2557B5F-872A-459A-AA82-A9111D4FF6D8/addressbook/1628B447-675B-4FA2-9446-27AA1FED9BCC-ABSPlugin.vcf', ('http://twistedmatrix.com/xml_namespace/dav/', 'getcontentmd5')
2011-01-28 13:59:26-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.extensions.CachingPropertyStore#debug] Cache miss: <twistedcaldav.extensions.CachingPropertyStore object at 0x104953050>, '/Library/AddressBookServer/Documents/addressbooks/_uids_/F2/55/F2557B5F-872A-459A-AA82-A9111D4FF6D8/addressbook', ('DAV:', 'resourcetype')
2011-01-28 13:59:26-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.extensions.CachingPropertyStore#debug] Cache miss: <twistedcaldav.extensions.CachingPropertyStore object at 0x10632ff50>, '/Library/AddressBookServer/Documents/addressbooks/_uids_/F2/55/F2557B5F-872A-459A-AA82-A9111D4FF6D8', ('http://twistedmatrix.com/xml_namespace/dav/private/', 'quota-used')
2011-01-28 13:59:26-0500 [-] [carddav-8801] [AMP,client] [twisted.web2.dav.fileop#info] Deleting file /Library/AddressBookServer/Documents/addressbooks/_uids_/F2/55/F2557B5F-872A-459A-AA82-A9111D4FF6D8/addressbook/1628B447-675B-4FA2-9446-27AA1FED9BCC-ABSPlugin.vcf
2011-01-28 13:59:26-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.cache.MemcacheChangeNotifier#debug] Changing Cache Token for '/addressbooks/_uids_/F2557B5F-872A-459A-AA82-A9111D4FF6D8'
2011-01-28 13:59:26-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.memcachepool.MemCachePool#debug] Busied client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x102451680>
2011-01-28 13:59:26-0500 [-] [carddav-8801] [AMP,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 1, #busy: 1, #pending: 0, #queued: 0
2011-01-28 13:59:26-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Freed client: <twistedcaldav.memcachepool.PooledMemCacheProtocol instance at 0x102451680>
2011-01-28 13:59:26-0500 [-] [carddav-8801] [PooledMemCacheProtocol,client] [twistedcaldav.memcachepool.MemCachePool#debug] Clients #free: 2, #busy: 0, #pending: 0, #queued: 0