ListArc » English » Computer and Internet » ICal-server » Users+suddenly+unable+to+write+(Error+400+CalDAVWriteEntityQueueableOperati...


Users+suddenly+unabl...


01-02-2012 02:14 PM
1


iCal Server running under MacOS X Server 10.7.2 in an Intel mini.
Eight open directory users. Authentication set to "Any method"
Been working flawlessly for months.

iCal users have suddenly lost the ability to write new events to any CalDAV
calendar. Five seconds after entering a new event, users receive the
following modal popup:

> The request for ³New event² in ³Work² in account ³Tim² failed.
> The server responded with ³400²
> to operation CalDAVWriteEntityQueueableOperation.


Directory Server Password log shows the user authenticates successfully:

> Feb 1 2012 08:44:19 AUTH2: {0x4c5f1f4a1d18e4380000000400000004, timjbuck}
> WEBDAV-DIGEST authentication succeeded.


CalDAV log shows the event writes successfully(?):

> 173.166.105.217 - timjbuck [01/Feb/2012:08:44:19 -0400] "PUT
> /calendars/__uids__/165E6803-3F93-4881-A457-78F077816A28/C7E62099-614B-4B8B-84
> 9B-04952B4C0EFC/c519594d-d6f1-6f11-4127-645e58f0845f.ics HTTP/1.1" 400 286 "-"
> "CalendarStore/5.0.1 (1139.14); iCal/5.0.1 (1547.4); Mac OS X/10.7.2 (11C74)"
> i=8444 t=67.5 or=1



CalDAV error log shows nothing at the time of the write fail, but does show
multiple instances of some kind of problem with the twisted framework. The
timestamp on the error messages doesn't correspond to the failed calendar
writes:

> 2012-02-01 08:27:53-0500 [-] [caldav-8009] [AMP,client]
> [twistedcaldav.extensions#error] Client authentication scheme basic is not
> provided by server ['digest']
> 2012-02-01 08:27:53-0500 [-] [caldav-8009] [AMP,client]
> [twistedcaldav.extensions#error] Client authentication scheme basic is not
> provided by server ['digest']
> 2012-02-01 08:27:53-0500 [-] [caldav-8009] [AMP,client]
> [twistedcaldav.extensions#error] Client authentication scheme basic is not
> provided by server ['digest']

I'll admit to not knowing much about the twisted framework, and don't know
what to make of these errors.


Server had had directory problems leading up to this event. Open Directory
was blown away after a routine Safari update went bad. Restored from
backup, and services came back just fine. GUIDS on the calendars do not
appear to have changed as a result of that event.

At the same time we had difficulty getting the server to recognize it's
self-signed SSL certificate after the restore, but were able to blow away an
old key that was incorrectly cached.

So I am inclined to believe that we have some kind of directory problem
here, but the logs don't seem to bear that out.

Documentation doesn't list the error message we're receiving. Found lots of
Google references to CalDAVWriteEntityQueueableOperation, but none with the
Error 400. Not sure where else to turn.

Appreciate whatever insight any of you may have.

---
Tim J. Buck







_______________________________________________
Do not post admin requests to the list. They will be ignored.
iCal-server mailing list (iCal-)
Help/Unsubscribe/Update your Subscription:
https://lists.apple.com/mailman/options/ical-server/shu.mcknight%40zeusmail.org

This email sent to




01-02-2012 05:46 PM
2


Hi,

Replies inline.

On Feb 1, 2012, at 6:14 AM, Tim J. Buck wrote:

> iCal Server running under MacOS X Server 10.7.2 in an Intel mini.
> Eight open directory users. Authentication set to "Any method"
> Been working flawlessly for months.
>
> iCal users have suddenly lost the ability to write new events to any CalDAV
> calendar. Five seconds after entering a new event, users receive the
> following modal popup:
>
>> The request for ³New event² in ³Work² in account ³Tim² failed.
>> The server responded with ³400²
>> to operation CalDAVWriteEntityQueueableOperation.

This is the generic 'something went wrong' UI you get from iCal. The only somewhat useful information here is the http status code of 400.

> Directory Server Password log shows the user authenticates successfully:
>
>> Feb 1 2012 08:44:19 AUTH2: {0x4c5f1f4a1d18e4380000000400000004, timjbuck}
>> WEBDAV-DIGEST authentication succeeded.
>
>
> CalDAV log shows the event writes successfully(?):
>
>> 173.166.105.217 - timjbuck [01/Feb/2012:08:44:19 -0400] "PUT
>> /calendars/__uids__/165E6803-3F93-4881-A457-78F077816A28/C7E62099-614B-4B8B-84
>> 9B-04952B4C0EFC/c519594d-d6f1-6f11-4127-645e58f0845f.ics HTTP/1.1" 400 286 "-"
>> "CalendarStore/5.0.1 (1139.14); iCal/5.0.1 (1547.4); Mac OS X/10.7.2 (11C74)"
>> i=8444 t=67.5 or=1

That's not a successful put; note the status code of 400, which means 'bad request'.

> CalDAV error log shows nothing at the time of the write fail, but does show
> multiple instances of some kind of problem with the twisted framework. The
> timestamp on the error messages doesn't correspond to the failed calendar
> writes:
>
>> 2012-02-01 08:27:53-0500 [-] [caldav-8009] [AMP,client]
>> [twistedcaldav.extensions#error] Client authentication scheme basic is not
>> provided by server ['digest']
>> 2012-02-01 08:27:53-0500 [-] [caldav-8009] [AMP,client]
>> [twistedcaldav.extensions#error] Client authentication scheme basic is not
>> provided by server ['digest']
>> 2012-02-01 08:27:53-0500 [-] [caldav-8009] [AMP,client]
>> [twistedcaldav.extensions#error] Client authentication scheme basic is not
>> provided by server ['digest']
>
> I'll admit to not knowing much about the twisted framework, and don't know
> what to make of these errors.

> Server had had directory problems leading up to this event. Open Directory
> was blown away after a routine Safari update went bad. Restored from
> backup, and services came back just fine. GUIDS on the calendars do not
> appear to have changed as a result of that event.
>
> At the same time we had difficulty getting the server to recognize it's
> self-signed SSL certificate after the restore, but were able to blow away an
> old key that was incorrectly cached.

Seems very likely that your problems are due to either the OD restore or possibly the SSL changes. What happens if you set / reset the password for one of the users? This is probably a silly question, but has ical server been stopped / restarted since the OD restore was performed? If not, do so.

Double-check your iCal Server config against the enabled auth mechanisms of your server:

# check caldavd.plist by running the Terminal command:

/usr/libexec/PlistBuddy -c "print :Authentication" /etc/caldavd/caldavd.plist

You'll see something like the following. Basically we want to know the enabled or disabled state of Digest and Basic.

Dict {
Digest = Dict {
Algorithm = md5
Enabled = true
Qop =
}
Kerberos = Dict {
ServicePrincipal =
Enabled = false
}
Wiki = Dict {
UseSSL = false
Enabled = true
Hostname = redacted
URL = also redacted
}
Basic = Dict {
Enabled = true
}
}

# check the enabled auth mechs by supplying the LIST command to password server using telnet. You should see something like the following. We want to verify that webdav-digest is enabled.

server:~ admin$ telnet 127.0.0.1 3659
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
+OK ApplePasswordServer 10.7.0.0 password server at redacted ready.
LIST
+OK (SASL "SMB-NTLMv2" "SMB-NT" "MS-CHAPv2" "PPS" "OTP" "NTLM" "GSSAPI" "DIGEST-MD5" "CRAM-MD5" "WEBDAV-DIGEST" "DHX" "APOP" )


Additionally, please collect some OD debug logs while reproducing the login failure:

1) sudo odutil set log debug
2) repro login failure
3) sudo odutil set log default

This logging goes to /var/log/opendirectoryd.log. See if you can identify where the authentication attempt occurs in this log, and whether it's actually succeeding or failing.

HTH,
-dre

>
> So I am inclined to believe that we have some kind of directory problem
> here, but the logs don't seem to bear that out.
>
> Documentation doesn't list the error message we're receiving. Found lots of
> Google references to CalDAVWriteEntityQueueableOperation, but none with the
> Error 400. Not sure where else to turn.
>
> Appreciate whatever insight any of you may have.
>
> ---
> Tim J. Buck
>
>
>
>
>
>
>
> _______________________________________________
> Do not post admin requests to the list. They will be ignored.
> iCal-server mailing list (iCal-)
> Help/Unsubscribe/Update your Subscription:
> https://lists.apple.com/mailman/options/ical-server/dre%40apple.com
>
> This email sent to


_______________________________________________
Do not post admin requests to the list. They will be ignored.
iCal-server mailing list (iCal-)
Help/Unsubscribe/Update your Subscription:
https://lists.apple.com/mailman/options/ical-server/shu.mcknight%40zeusmail.org

This email sent to




03-02-2012 06:34 PM
3


On 2/1/12 12:46 PM, Andre LaBranche <> wrote:

> On Feb 1, 2012, at 6:14 AM, Tim J. Buck wrote:

>> CalDAV log shows the event writes successfully(?):
>>
>>> 173.166.105.217 - timjbuck [01/Feb/2012:08:44:19 -0400] "PUT
>>> /calendars/__uids__/165E6803-3F93-4881-A457-78F077816A28/C7E62099-614B-4B8B-
>>> 84
>>> 9B-04952B4C0EFC/c519594d-d6f1-6f11-4127-645e58f0845f.ics HTTP/1.1" 400 286
>>> "-"
>>> "CalendarStore/5.0.1 (1139.14); iCal/5.0.1 (1547.4); Mac OS X/10.7.2
>>> (11C74)"
>>> i=8444 t=67.5 or=1
>
> That's not a successful put; note the status code of 400, which means 'bad
> request'.

Wow, thanks. I never would have grasped that.





> Seems very likely that your problems are due to either the OD restore or
> possibly the SSL changes. What happens if you set / reset the password for one
> of the users?

I am able to set and reset passwords, and iCal seems to respond to the
change, but I am still only able to read (but not write). I continue to get
the 400 error even with a new password.



> This is probably a silly question, but has ical server been
> stopped / restarted since the OD restore was performed? If not, do so.

I know you had to ask : )

Yes, been restarted multiple times.



> Double-check your iCal Server config against the enabled auth mechanisms of
> your server:
>
> # check caldavd.plist by running the Terminal command:
> /usr/libexec/PlistBuddy -c "print :Authentication" /etc/caldavd/caldavd.plist
>

Dict {
Digest = Dict {
Algorithm = md5
Enabled = true
Qop =
}
Kerberos = Dict {
ServicePrincipal =
Enabled = true
}
Wiki = Dict {
UseSSL = false
Enabled = true
Hostname = 127.0.0.1
URL = http://127.0.0.1:8089/RPC2
}
Basic = Dict {
Enabled = false
}
}



> # check the enabled auth mechs by supplying the LIST command to password
> server using telnet. You should see something like the following. We want to
> verify that webdav-digest is enabled.

webdav-digest is enabled:

+OK (SASL "SMB-NTLMv2" "SMB-NT" "SMB-LAN-MANAGER" "MS-CHAPv2" "PPS" "OTP"
"NTLM" "GSSAPI" "DIGEST-MD5" "CRAM-MD5" "WEBDAV-DIGEST" "DHX" "APOP" )



> Additionally, please collect some OD debug logs while reproducing the login
> failure:
>
> 1) sudo odutil set log debug
> 2) repro login failure
> 3) sudo odutil set log default
>
> This logging goes to /var/log/opendirectoryd.log. See if you can identify
> where the authentication attempt occurs in this log, and whether it's actually
> succeeding or failing.

Looks like I gave incorrect info in the previous message.
This is a Snow Leopard server (10.6.8), not lion.
(Sorry - had just been working on a Lion server and got confused)

I don't see odutil, and I don't see /var/log/opendirectoryd.log

What should I be looking for in Snow Leopard? How do I change log level to
debug and where should I look for the appropriate open directory logs in
Snow Leopard Server?



---
Tim J. Buck


_______________________________________________
Do not post admin requests to the list. They will be ignored.
iCal-server mailing list (iCal-)
Help/Unsubscribe/Update your Subscription:
https://lists.apple.com/mailman/options/ical-server/shu.mcknight%40zeusmail.org

This email sent to
)



03-02-2012 06:51 PM
4


The 400 response means the client is sending "bad data", so something about the actual icalendar data is making the server unhappy. The actual error message is likely contained in the HTTP response body, but iCal isn't showing you the contents of that response. There are a couple ways to see that response -- you can enable HTTP logging within iCal by running this in Terminal on the client machine...

defaults write com.apple.ical LogHTTPActivity YES

...and then restarting iCal. iCal will now log all HTTP activity to /var/log/system.log

On Feb 3, 2012, at 10:34 AM, Tim J. Buck wrote:

> On 2/1/12 12:46 PM, Andre LaBranche <> wrote:
>
>> On Feb 1, 2012, at 6:14 AM, Tim J. Buck wrote:
>
>>> CalDAV log shows the event writes successfully(?):
>>>
>>>> 173.166.105.217 - timjbuck [01/Feb/2012:08:44:19 -0400] "PUT
>>>> /calendars/__uids__/165E6803-3F93-4881-A457-78F077816A28/C7E62099-614B-4B8B-
>>>> 84
>>>> 9B-04952B4C0EFC/c519594d-d6f1-6f11-4127-645e58f0845f.ics HTTP/1.1" 400 286
>>>> "-"
>>>> "CalendarStore/5.0.1 (1139.14); iCal/5.0.1 (1547.4); Mac OS X/10.7.2
>>>> (11C74)"
>>>> i=8444 t=67.5 or=1
>>
>> That's not a successful put; note the status code of 400, which means 'bad
>> request'.
>
> Wow, thanks. I never would have grasped that.
>
>
>
>
>
>> Seems very likely that your problems are due to either the OD restore or
>> possibly the SSL changes. What happens if you set / reset the password for one
>> of the users?
>
> I am able to set and reset passwords, and iCal seems to respond to the
> change, but I am still only able to read (but not write). I continue to get
> the 400 error even with a new password.
>
>
>
>> This is probably a silly question, but has ical server been
>> stopped / restarted since the OD restore was performed? If not, do so.
>
> I know you had to ask : )
>
> Yes, been restarted multiple times.
>
>
>
>> Double-check your iCal Server config against the enabled auth mechanisms of
>> your server:
>>
>> # check caldavd.plist by running the Terminal command:
>> /usr/libexec/PlistBuddy -c "print :Authentication" /etc/caldavd/caldavd.plist
>>
>
> Dict {
> Digest = Dict {
> Algorithm = md5
> Enabled = true
> Qop =
> }
> Kerberos = Dict {
> ServicePrincipal =
> Enabled = true
> }
> Wiki = Dict {
> UseSSL = false
> Enabled = true
> Hostname = 127.0.0.1
> URL = http://127.0.0.1:8089/RPC2
> }
> Basic = Dict {
> Enabled = false
> }
> }
>
>
>
>> # check the enabled auth mechs by supplying the LIST command to password
>> server using telnet. You should see something like the following. We want to
>> verify that webdav-digest is enabled.
>
> webdav-digest is enabled:
>
> +OK (SASL "SMB-NTLMv2" "SMB-NT" "SMB-LAN-MANAGER" "MS-CHAPv2" "PPS" "OTP"
> "NTLM" "GSSAPI" "DIGEST-MD5" "CRAM-MD5" "WEBDAV-DIGEST" "DHX" "APOP" )
>
>
>
>> Additionally, please collect some OD debug logs while reproducing the login
>> failure:
>>
>> 1) sudo odutil set log debug
>> 2) repro login failure
>> 3) sudo odutil set log default
>>
>> This logging goes to /var/log/opendirectoryd.log. See if you can identify
>> where the authentication attempt occurs in this log, and whether it's actually
>> succeeding or failing.
>
> Looks like I gave incorrect info in the previous message.
> This is a Snow Leopard server (10.6.8), not lion.
> (Sorry - had just been working on a Lion server and got confused)
>
> I don't see odutil, and I don't see /var/log/opendirectoryd.log
>
> What should I be looking for in Snow Leopard? How do I change log level to
> debug and where should I look for the appropriate open directory logs in
> Snow Leopard Server?
>
>
>
> ---
> Tim J. Buck
>
>
> _______________________________________________
> Do not post admin requests to the list. They will be ignored.
> iCal-server mailing list (iCal-)
> Help/Unsubscribe/Update your Subscription:
> https://lists.apple.com/mailman/options/ical-server/sagen%40apple.com
>
> This email sent to


_______________________________________________
Do not post admin requests to the list. They will be ignored.
iCal-server mailing list (iCal-)
Help/Unsubscribe/Update your Subscription:
https://lists.apple.com/mailman/options/ical-server/shu.mcknight%40zeusmail.org

This email sent to
)



03-02-2012 07:06 PM
5



On Feb 3, 2012, at 10:34 AM, Tim J. Buck wrote:
>
>> Additionally, please collect some OD debug logs while reproducing the login
>> failure:
>>
>> 1) sudo odutil set log debug
>> 2) repro login failure
>> 3) sudo odutil set log default
>>
>> This logging goes to /var/log/opendirectoryd.log. See if you can identify
>> where the authentication attempt occurs in this log, and whether it's actually
>> succeeding or failing.
>
> Looks like I gave incorrect info in the previous message.
> This is a Snow Leopard server (10.6.8), not lion.
> (Sorry - had just been working on a Lion server and got confused)
>
> I don't see odutil, and I don't see /var/log/opendirectoryd.log
>
> What should I be looking for in Snow Leopard? How do I change log level to
> debug and where should I look for the appropriate open directory logs in
> Snow Leopard Server?

Hi,

Since the auth is actually working, you probably don't need to proceed into directory service debugging. The cause of the http 400 is probably the thing to investigate, as Morgen points out. But FYI:

From the DirectoryService man page:

DIAGNOSTICS
There are two helpful signals you can send to the DirectoryService daemon to help diagnose problems
you may be having. (Example: % sudo killall -USR1 DirectoryService). USR2 logging automatically
turns off after 5 minutes.

o USR1

Turns Debug Logging (on/off)

See /Library/Logs/DirectoryService/DirectoryService.debug.log

o USR2

Turns API Logging (on/off)

See /var/log/system.log


We only want debug logging, not api logging, so run:

sudo killall -USR1 DirectoryService

to toggle the logging. It's quite verbose, so only enable it during problem repro attempts / debugging, unless advised otherwise. Since it sounds like it's your first adventure into this logging, I'll give you some hints: searching is typically more efficient than browsing

-dre