Help! Migrated iCal from 10.6.8 to 10.8.4, iCal clients getting HTTP 405 errors

Question

Level 1

0 points

Help! Migrated iCal from 10.6.8 to 10.8.4, iCal clients getting HTTP 405 errors

I had a 10.6.8 server. I added a new hard drive and ran a clean install of 10.8.4 + server. I successfully migrated OD and DNS (manually) from the old server. Now trying now to migrate iCal - since I migrated OD the GUIDs should match so it should be possible. I have two copies of the 10.6.8 partition and it's still bootable (although I'd rather not take the server down).

I first found these two discussions (3449764, 4159753). Trying to put the calendars/__uids__ folders in the "right place" never seemed to have worked, I found no evidence migration was triggered but the calendar service error logs or full of so much garbage it was hard to tell.

Following this helpful post yielded more promising results. I can see my old "Location and Resources" in server.app. Clients still couldn't connect, though - iCal refresh kept spinning, and calDAV requests got HTTP 503 and then 405 errors.

7/8/13 6:00:50 PM iCal[1404] -[DAVRequest:0x116682780 _readStreamEvent:] READ
<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<title>405 Method Not Allowed</title>
<p>The requested method PROPFIND is not allowed for the URL /default.html.en.</p>
<address>Apache/2.2.22 (Unix) DAV/2 PHP/5.3.15 with Suhosin-Patch mod_ssl/2.2.22 OpenSSL/0.9.8x Server at xxxxxxxx Port 443</address>

I restarted the server and enabled Wiki, hoping it'd kick iCal's WebDAV into place. Now clients are getting "iCal found the CalDAV server …but couldn't log in" for any account, old or new. The log shows:

7/8/13 7:46:09 PM          iCal[1719] 
HTTP/1.1 405 Method Not Allowed
Allow: GET,HEAD,POST,OPTIONS
<p>The requested method PROPFIND is not allowed for the URL /principals/.</p>

Can anyone point me in the right direction from here? Looks like caldavd slipped out of alignment with the Apache server...

PS Did Apple migrate iCal from flat files to PostgresSQL in Lion?? Everyone either has no idea what this means, or seems to take it for granted.

Thanks!

OS X Server

Posted on Jul 8, 2013 8:00 PM

Reply

Answer 1

cabal95

Level 1

0 points

Jul 8, 2013 9:16 PM in response to DLpres2

Is the second "PROPFIND not allowed" error you are getting from the calendar server log or the apache server log? If memory serves, it isn't apache that handles the requests but a different process.

And yes, I believe it was in Lion that Apple moved from flat files to PostgreSQL. Basically, the just moved the flat files into a SQL database, if you connect directly to PostgreSQL and browse around you will see the .ics entries for the individual ical events.

What if you try entering a port along with the server name? My iCal server doesn't run anything on port 80 or 443, maybe without the explicit port iCal is finding a server on port 80/443 on your server and trying to use it (apache) instead.

e.g. calendars.mydomain.org:8008 or maybe calendars.mydomain.org:8443

Reply

Answer 2

DLpres2 Author

Level 1

0 points

Jul 9, 2013 12:47 PM in response to cabal95

The "PROPFIND not allowed" is from the client iCal log.

I realized DNS had no SRV records defined, and added them in the proper format.

_caldav._tcp.xxxxxx.com service = 0 0 8008 xxxx.xxxxxxx.com.

_caldavs._tcp.xxxxxx.com service = 0 0 8443 xxxx.xxxxxxx.com.

I restarted DNS, flushed DNS cache on the client and confirmed the SRV records with nslookup.

Still, iCal declares "no CalDAV servers were found for xxx.xxxxx.com" and the log shows HTTP 405 errors at port 443.

Reply

Answer 3

cabal95

Level 1

0 points

Jul 9, 2013 1:39 PM in response to DLpres2

On the server under the Logs section, is there anything that looks possibly related in the Calendar Access/Error log and the Websites Access/Error log?

It still sounds like somehow the client is hitting Apache instead of the caldavd server. I just checked and I don't have any SRV records so mine has always "just worked" for whatever reason, even though I apparently do run apache on the server (I forgot the Wiki service automatically turns on Apache).

The Access and/or Error logs for both services should tell us if iCal is ever hitten the Calendar service at all, or just stopping at the Apache/Websites service.

Check one other thing. Try going to the following URLs with your user's GUID (the only way I know how to get this is with ldapsearch on the command line, it is the apple-generateduid variable. You might be able to get it Workgroup Manager too, not sure). I used Safari for this test, it asked me for my login which I authenticated with and I saw a bunch of "Principal Details" stuff come up.

https://server.domain.org/principals/__uids__/GUID-HERE/

https://server.domain.org:8443/principals/__uids__/GUID-HERE/

Oddly enough when I try to do it over a non-secured port (80 or 8008), it gives a 404 not found error; so it's possible that is something I configured on my side to not allow unsecured connections - not sure.

Reply

Answer 4

DLpres2 Author

Level 1

0 points

Jul 9, 2013 4:40 PM in response to cabal95

I tried accessing a specific GUID via a web browser. I tried different GUIDs and even just the main address over https:8443 and http:8008, and in all cases got absolutely nothing (connection timed out).

It seems that indeed iCal Server has nothing to do with Apache and that the HTTP serving is done by Twisted. caldavd confirm twistd is running on the server.

The only errors in caldavd from today are

2013-07-09 15:21:58-0700 [-] [calendarserver.tap.util#error] Unable to determine memory usage of PID: 14xx ((pid=14xx))

Open Directory has iCal and iCal ACL users and groups (UID 93, GID 93, 507) but these are all in the local directory, not LDAP. The server's computer entry in LDAP has no keywords at all, and I don't even know if keywords are keys and if it means I'm missing the iCal-related keys or not.

Reply

Answer 5

DLpres2 Author

Level 1

0 points

Jul 9, 2013 5:18 PM in response to DLpres2

It gets even more "interesting"... it appears as if when I turn off the Calendar service (from server.app), caldavd starts and vice versa.

For example I turn off and the error log shows "16:45:35 Server Shut Down?. 7 seconds later the log is re-opened and twistd is starting up, followed by all the instances of caldav.

A couple of minutes later I get:

013-07-09 16:56:50-0700 [-] [caldav-0]  [-] Unhandled Error
2013-07-09 16:56:50-0700 [-] [caldav-0]           Traceback (most recent call last):
2013-07-09 16:56:50-0700 [-] [caldav-0]             File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/python/log.py", line 69, in callWithContext
2013-07-09 16:56:50-0700 [-] [caldav-0]               return context.call({ILogContext: newCtx}, func, *args, **kw)
2013-07-09 16:56:50-0700 [-] [caldav-0]             File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/python/context.py", line 118, in callWithContext
2013-07-09 16:56:50-0700 [-] [caldav-0]               return self.currentContext().callWithContext(ctx, func, *args, **kw)
2013-07-09 16:56:50-0700 [-] [caldav-0]             File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/python/context.py", line 81, in callWithContext
2013-07-09 16:56:50-0700 [-] [caldav-0]               return func(*args,**kw)
2013-07-09 16:56:50-0700 [-] [caldav-0]             File "/Applications/Server.app/Contents/ServerRoot/usr/share/caldavd/lib/python/twext/internet/kqreactor.py", line 206, in _doWriteOrRead
2013-07-09 16:56:50-0700 [-] [caldav-0]               why = selectable.doRead()
2013-07-09 16:56:50-0700 [-] [caldav-0]           --- <exception caught here> ---
2013-07-09 16:56:50-0700 [-] [caldav-0]             File "/Applications/Server.app/Contents/ServerRoot/usr/share/caldavd/lib/python/twext/internet/sendfdport.py", line 295, in doRead
2013-07-09 16:56:50-0700 [-] [caldav-0]               description, protocol)
2013-07-09 16:56:50-0700 [-] [caldav-0]             File "/Applications/Server.app/Contents/ServerRoot/usr/share/caldavd/lib/python/twext/web2/metafd.py", line 103, in createTransport
2013-07-09 16:56:50-0700 [-] [caldav-0]               transport.startTLS(self.contextFactory)
2013-07-09 16:56:50-0700 [-] [caldav-0]             File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/internet/_newtls.py", line 178, in startTLS
2013-07-09 16:56:50-0700 [-] [caldav-0]               startTLS(self, ctx, normal, FileDescriptor)
2013-07-09 16:56:50-0700 [-] [caldav-0]             File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/internet/_newtls.py", line 138, in startTLS
2013-07-09 16:56:50-0700 [-] [caldav-0]               tlsFactory = TLSMemoryBIOFactory(contextFactory, client, None)
2013-07-09 16:56:50-0700 [-] [caldav-0]             File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/protocols/tls.py", line 594, in __init__
2013-07-09 16:56:50-0700 [-] [caldav-0]               contextFactory.getContext()
2013-07-09 16:56:50-0700 [-] [caldav-0]           exceptions.AttributeError: 'NoneType' object has no attribute 'getContext'
2013-07-09 16:56:50-0700 [-] [caldav-0]

This repeates for all the instances of caldav.

10 minutes later I turned on the service. It sent SIGTERMs to all the instances, and I saw

2013-07-09 17:10:29-0700 [twisted.internet.protocol.Factory] (TCP Port 7654 Closed)

2013-07-09 17:10:29-0700 [-] Main loop terminated.

2013-07-09 17:10:29-0700 [-] Server Shut Down.

6 seconds later twistd and caldav started again with these errors:

2013-07-09 17:10:29-0700 [-] [caldav-1]  [HTTPChannel,1,192.168.1.80] Unhandled Error
2013-07-09 17:10:29-0700 [-] [caldav-1]           Traceback (most recent call last):
2013-07-09 17:10:29-0700 [-] [caldav-1]             File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/internet/defer.py", line 290, in addCallbacks
2013-07-09 17:10:29-0700 [-] [caldav-1]               self._runCallbacks()
2013-07-09 17:10:29-0700 [-] [caldav-1]             File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/internet/defer.py", line 551, in _runCallbacks
2013-07-09 17:10:29-0700 [-] [caldav-1]               current.result = callback(current.result, *args, **kw)
2013-07-09 17:10:29-0700 [-] [caldav-1]             File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/internet/base.py", line 426, in _continueFiring
2013-07-09 17:10:29-0700 [-] [caldav-1]               callable(*args, **kwargs)
2013-07-09 17:10:29-0700 [-] [caldav-1]             File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/internet/base.py", line 621, in disconnectAll
2013-07-09 17:10:29-0700 [-] [caldav-1]               failure.Failure(main.CONNECTION_LOST))
2013-07-09 17:10:29-0700 [-] [caldav-1]           --- <exception caught here> ---
2013-07-09 17:10:29-0700 [-] [caldav-1]             File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/python/log.py", line 84, in callWithLogger
2013-07-09 17:10:29-0700 [-] [caldav-1]               return callWithContext({"system": lp}, func, *args, **kw)
2013-07-09 17:10:29-0700 [-] [caldav-1]             File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/python/log.py", line 69, in callWithContext
2013-07-09 17:10:29-0700 [-] [caldav-1]               return context.call({ILogContext: newCtx}, func, *args, **kw)
2013-07-09 17:10:29-0700 [-] [caldav-1]             File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/python/context.py", line 118, in callWithContext
2013-07-09 17:10:29-0700 [-] [caldav-1]               return self.currentContext().callWithContext(ctx, func, *args, **kw)
2013-07-09 17:10:29-0700 [-] [caldav-1]             File "/System/Library/Frameworks/Python.framework/Versions/2.7/Extras/lib/python/twisted/python/context.py", line 81, in callWithContext
2013-07-09 17:10:29-0700 [-] [caldav-1]               return func(*args,**kw)
2013-07-09 17:10:29-0700 [-] [caldav-1]             File "/Applications/Server.app/Contents/ServerRoot/usr/share/caldavd/lib/python/twext/backport/internet/tcp.py", line 281, in connectionLost
2013-07-09 17:10:29-0700 [-] [caldav-1]               protocol.connectionLost(reason)
2013-07-09 17:10:29-0700 [-] [caldav-1]             File "/Applications/Server.app/Contents/ServerRoot/usr/share/caldavd/lib/python/twext/web2/channel/http.py", line 976, in connectionLost
2013-07-09 17:10:29-0700 [-] [caldav-1]               self.factory.removeConnectedChannel(self)
2013-07-09 17:10:29-0700 [-] [caldav-1]             File "/Applications/Server.app/Contents/ServerRoot/usr/share/caldavd/lib/python/twext/web2/metafd.py", line 142, in removeConnectedChannel
2013-07-09 17:10:29-0700 [-] [caldav-1]               HTTPFactory.removeConnectedChannel(self, channel)
2013-07-09 17:10:29-0700 [-] [caldav-1]             File "/Applications/Server.app/Contents/ServerRoot/usr/share/caldavd/lib/python/twext/web2/channel/http.py", line 1053, in removeConnectedChannel
2013-07-09 17:10:29-0700 [-] [caldav-1]               self.connectedChannels.remove(channel)
2013-07-09 17:10:29-0700 [-] [caldav-1]           exceptions.KeyError: <twext.web2.channel.http.HTTPChannel object at 0x103e6b550>
2013-07-09 17:10:29-0700 [-] [caldav-1] 
2013-07-09 17:10:29-0700 [-] [caldav-1]  [-] Main loop terminated.

Needless to say, I have absolutely no idea what's going on at this point :-)

Reply

Answer 6

Linc Davis

Level 10

209,541 points

Jul 9, 2013 6:02 PM in response to DLpres2

How about killing caldavd and then posting continuous extracts from the error log and the system log as it tries to restart? No more than about 50 lines from each, please.

Reply

Answer 7

DLpres2 Author

Level 1

0 points

Jul 9, 2013 9:32 PM in response to Linc Davis

Every time I run ps aux | grep caldavd I get a different PID (and caldavd doesn't show up with ps x or in Activity Monitor). So How do I kill it? Sorry about my limited UNIX knowledge.

Given the amount of time I've spend on this so far (without getting anywhere), I'm also considering blowing up iCal (and migrating calendars one by one from an iCal app). Is there any relatively easy way of doing that without reinstalling the OS?

Reply

Answer 8

cabal95

Level 1

0 points

Jul 9, 2013 9:42 PM in response to DLpres2

It might already be dead. the PID you see with ps aux | grep caldavd might be grep itself. Try 'ps -awx | grep caldavd' it should be a little less verbose. If all you get back is a line that looks like this:

3228 ttys000 0:00.00 grep caldavd

Then it isn't running (that process is just the grep process matching itself). It almost sounds like there might be more issues unrelated to the import. Granted the instructions I posted were only used one time (I haven't had a need to try to re-import ical again).

Do you have a spare machine you can "burn" and do a clean mountain lion install on, then install the server app and do the ical migration/import on that machine? The basic path I took was:

1) Install ML clean.

2) Install Server app.

3) Join to existing OD server (just as a member/client, not as a replica or anything)

<3a) image off computer.>

4) Run import process.

If iCal still has problems, go back to the image made in 3a and try just turning on calendars and seeing if it works "stock".

Reply

Answer 9

Linc Davis

Level 10

209,541 points

Jul 9, 2013 9:51 PM in response to DLpres2

Just turn the service off and back on, and capture the subsequent messages in those two logs.

Reply

Answer 10

DLpres2 Author

Level 1

0 points

Jul 10, 2013 11:39 AM in response to Linc Davis

Thanks for everyone who's already helping - let me know where to ship you a pack of beer or your favorite roast...

caldavd log:

http://wikisend.com/download/469084/ical-caldavd.txt

system log:

http://wikisend.com/download/933108/ical-system.txt

I do have clones and other systems, I'll try to do an upgrade-in-place of the 10.6.8 server image into 10.8.4 server.

Reply

Answer 11

Linc Davis

Level 10

209,541 points

Jul 10, 2013 12:50 PM in response to DLpres2

Going by this line in the system log:

servermgrd[44281]: -[DNSManagerResourceRec addToBindZoneDB:version:]: Unable to create rdata for resource rec _caldav._tcp.precisionpost.com TXT

it seems that there's a problem in your DNS settings. You need to look at the BIND logs for clues to that.

It also seems that your CalDAV server is getting requests from your public IP address. Is that what you expect? Since you're using the server as your Internet gateway, you need to configure the firewall very carefully. I wouldn't do that at all.

Reply

Answer 12

DLpres2 Author

Level 1

0 points

Jul 10, 2013 4:46 PM in response to cabal95

Not much to add at this point. I did the upgrade-in-place, the ML portion completed but the server.app upgrade portion was a complete fail (the server.app setup wizard ran for 15 minutes and the summary screen was failure). Once I joined the main server's domain the test server's LDAP had 5 accounts left. I was able to log in to the test server's Calendar Server just fine, create calendar for those accounts and sync them.

Regarding the original server: After migrating OD & DNS and before Calendar Server, I ran a test and it worked fine; I was able to create calendars for OD users. Once I tried to bring over the old data and ran the migration process, the service was corrupted.

Of course, the fact that a fresh install of Calendar Server works (without migrating older calendars/settings) is not very surprising.

Reply

Answer 13

cabal95

Level 1

0 points

Jul 10, 2013 5:16 PM in response to DLpres2

As Linc says, I would double check all the DNS records and settings just to be sure all is correct.

Beyond that, the only thing I can guess at this point is that possibly by running your calendar test (turning on the calendar service and causing it to do it's initial configuration) cause the migration script to create conflicting data in the config and foul things up.

What I was saying above is if you have a spare machine I would do the following on it to test to see if it was the migration itself that was wrong, or something else in the process (for example like the fact you turned calendar service on first, or you did the OD migration first, etc.). If you have a spare machine, try this:

1) Install Mountain Lion and run all software updates.

2) Install the Server.app (don't even run it, just install it).

3) Perform the command line migration steps from the blog.

4) Then fire up the Server.app to see if everything looks correct, and then try testing a client.

The migration script probably expects all the config information to be in a very specific (i.e. blank/empty) state. Turning the Calendar service on for a test before migrating might have broken that migration script, even though it may have run without error.

Reply

Answer 14

DLpres2 Author

Level 1

0 points

Aug 8, 2013 4:42 PM in response to DLpres2

I owe an update - unfortunately none of the extensive troubleshooting steps helped. We also hired an expert consultant (who wrote multiple OS X administration books) and it became obvious that the easiest and fastest way to fix this was to nuke and reinstall everything again from scratch.

That worked for a while with the migration assistant, but I ended up wiping the server and reinstalling yet again, from scratch.

My moral of the story is for better or worse, my initial hunch was right: don't trust any "migration assistants" or other upgrade paths; when doing a major OS upgrade, if at all possible, do a clean install and migrate what's needed minimally and manually.

Reply