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
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
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
)
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
)
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
On 2/3/12 2:06 PM, Andre LaBranche <> wrote:
> Since the auth is actually working, you probably don't need to proceed into
> directory service debugging.
I did get into the Directory Service debug log. As you said, it is quite
verbose, but am I correct that the auth seems to be working? :
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1470,
API: MapName, Server Used : mbr_mig DAC : Name = com.apple.access_calendar :
isUser = 0
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
Cache hit - com.apple.access_calendar (0x0000000100295C50)
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
Cache entry is a negative entry (discarding result)
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1470,
API: MapName, Server Used : mbr_mig DAR : Name = com.apple.access_calendar :
Not found
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1470,
API: MapName, Server Used : mbr_mig DAC : Name = com.apple.access_calendar :
isUser = 0
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
Cache hit - com.apple.access_calendar (0x0000000100295C50)
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
Cache entry is a negative entry (discarding result)
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1470,
API: MapName, Server Used : mbr_mig DAR : Name = com.apple.access_calendar :
Not found
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1470,
API: MapName, Server Used : mbr_mig DAC : Name = com.apple.access_calendar :
isUser = 0
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
Cache hit - com.apple.access_calendar (0x0000000100295C50)
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
Cache entry is a negative entry (discarding result)
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1470,
API: MapName, Server Used : mbr_mig DAR : Name = com.apple.access_calendar :
Not found
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1472,
API: dsDoDirNodeAuth(), LDAPv3 Used : DAC : Node Ref = 33556781 : User Name
= timjbuck : Auth Method = dsAuthMethodStandard:dsAuthNodeDIGEST-MD5 : Auth
Only Flag = 1 : Continue Data = 0
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - CLDAPv3Plugin:
DoAuthenticationOnRecordType - Attempting use of authentication method
dsAuthMethodStandard:dsAuthNodeDIGEST-MD5
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - CLDAPv3Plugin: Attempting
to get dsAttrTypeStandard:AuthenticationAuthority
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - CLDAPv3Plugin:
LookupAttribute value found
;ApplePasswordServer;0x4c5f1f4a1d18e4380000000400000004,1024 35
1225406072978067361098757052121962069672316632844369972172679617900101624798
5576824058798475198080356794812540999170186758384332600474653861606992466000
7699837181248612215547009986071956366076636846194743899953910907222561638167
3728893176650606664725373219822346621141425994680181319980206281690411785957
54889 :2002:4160:c082::c62c:3ff:fe0b:44fd
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - CLDAPv3Plugin:
LookupAttribute value found
;Kerberosv5;0x4c5f1f4a1d18e4380000000400000004;
CH.NET;INTELMINI.BEFREECHURCH.NET;1024 35
1225406072978067361098757052121962069672316632844369972172679617900101624798
5576824058798475198080356794812540999170186758384332600474653861606992466000
7699837181248612215547009986071956366076636846194743899953910907222561638167
3728893176650606664725373219822346621141425994680181319980206281690411785957
54889 :2002:4160:c082::c62c:3ff:fe0b:44fd
2012-02-03 14:32:43 EST - T[0x0000000101A04000] -
CLDAPv3Plugin::DoPasswordServerAuth:
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - CLDAPv3Plugin: Attempting
use of authentication method dsAuthMethodStandard:dsAuthNodeDIGEST-MD5
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Internal Dispatch, API:
dsDoPlugInCustomCall(), PasswordServer Used : DAC : Node Ref = 33556783 :
Request Code = 1
2012-02-03 14:32:43 EST - T[0x0000000101A04000] -
CPSPlugIn::DoPlugInCustomCall
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Internal Dispatch, API:
dsDoPlugInCustomCall(), PasswordServer Used : DAR : Node Ref = 33556783 :
Request Code = 1 : Result code = 0
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Internal Dispatch, API:
dsDoDirNodeAuth(), PasswordServer Used : DAC : Node Ref = 33556783 : User
Name = 0x4c5f1f4a1d18e4380000000400000004,1024 35
1225406072978067361098757052121962069672316632844369972172679617900101624798
5576824058798475198080356794812540999170186758384332600474653861606992466000
7699837181248612215547009986071956366076636846194743899953910907222561638167
3728893176650606664725373219822346621141425994680181319980206281690411785957
54889 : Auth Method =
dsAuthMethodStandard:dsAuthNodeDIGEST-MD5 : Auth Only Flag = 1 : Continue
Data = 0
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - PasswordServer PlugIn:
Attempting use of authentication method
dsAuthMethodStandard:dsAuthNodeDIGEST-MD5
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - GetAuthMethodConstant
siResult=0, uiAuthMethod=1236, mech=
2012-02-03 14:32:43 EST - T[0x0000000101A04000] -
CPSPlugIn::EndServerSession opens: 19, closes 16
2012-02-03 14:32:43 EST - T[0x0000000101A04000] -
hexHash=DD4CA447A77ACD2496FA9489DEE08228
2012-02-03 14:32:43 EST - T[0x0000000101A04000] -
CPSPlugIn::HandleFirstContact: trying LDAP Hint
2012-02-03 14:32:43 EST - T[0x0000000101A04000] -
CPSPlugIn::HandleFirstContact: hint is 127.0.0.1, result = 0
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - BeginServerSession, ip =
127.0.0.1, inSock = -1
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - GetAuthMethodSASLName
siResult=0, mech=WEBDAV-DIGEST
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - CPSPlugIn::Attempting SASL
Authentication
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - DIGEST-MD5 client step 2
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - DIGEST-MD5 unrecognized
pair method/PUT: ignoring
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - AUTH2
757365726E616D653D2274696D6A6275636B222C207265616C6D3D222F536561726368222C20
6E6F6E63653D2233353733313537373738303434373633373238373030333733303035353431
3932313637393434323731323739303030323132363936333338222C207572693D222F63616C
656E646172732F5F5F756964735F5F2F31363545363830332D334639332D343838312D413435
372D3738463037373831364132382F33463738454344342D414437382D343643352D42354632
2D3931323832323234433335302F45314242463842352D313735372D344534462D413038342D
3438433233323039303938432E696373222C20726573706F6E73653D22646432356338656537
3735653964316436613337353730666464316231633565222C616C676F726974686D3D6D6435
2C7573657269643D307834633566316634613164313865343338303030303030303430303030
30303034
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - DIGEST-MD5 client step 3
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - PasswordServer PlugIn:
SASL authentication error 0
2012-02-03 14:32:43 EST - T[0x0000000101A04000] -
CPSPlugIn::DoAuthentication returning 0
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Internal Dispatch, API:
dsDoDirNodeAuth(), PasswordServer Used : DAR : Node Ref = 33556783 : Result
code = 0
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1472,
API: dsDoDirNodeAuth(), LDAPv3 Used : DAR : Node Ref = 33556781 : Result
code = 0
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1472,
API: MapName, Server Used : mbr_mig DAC : Name = timjbuck : isUser = 1
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
Cache hit - timjbuck (0x00000001002B3EF0)
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1472,
API: MapName, Server Used : mbr_mig DAR : Name = timjbuck : GUID =
165E6803-3F93-4881-A457-78F077816A28
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1472,
API: MapName, Server Used : mbr_mig DAC : Name =
com.apple.access_all_services : isUser = 0
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
Cache hit - com.apple.access_all_services (0x000000010063C280)
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
Cache entry is a negative entry (discarding result)
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1472,
API: MapName, Server Used : mbr_mig DAR : Name =
com.apple.access_all_services : Not found
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1472,
API: MapName, Server Used : mbr_mig DAC : Name = com.apple.access_calendar :
isUser = 0
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
Cache hit - com.apple.access_calendar (0x0000000100295C50)
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
Cache entry is a negative entry (discarding result)
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1472,
API: MapName, Server Used : mbr_mig DAR : Name = com.apple.access_calendar :
Not found
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1472,
API: MembershipCall, Server Used : mbr_mig DAC
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
Cache hit - timjbuck (0x00000001002B3EF0)
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Dispatch -
Lookup - user/computer GUID 165E6803-3F93-4881-A457-78F077816A28 - succeeded
timjbuck
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Resolve Groups -
'timjbuck' fresh 4471 > 1357
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Resolve Groups -
'timjbuck' (/LDAPv3/127.0.0.1) - waiting for an inflight membership
generation to complete
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Resolve Groups -
'timjbuck' (/LDAPv3/127.0.0.1) - finished waiting for an inflight membership
generation to complete
2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1472,
API: MembershipCall, Server Used : mbr_mig DAR
_______________________________________________
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
)
On 2/3/12 2:06 PM, Andre LaBranche <> wrote:
> 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.
So I appear to be authenticating correctly, but the CalDAV server is unable
to write new data to the calendar store. Users can read but not write to
their calendars.
What I'm not grasping is how the access privileges are applied to the
calendar data. Everything in /Library/CalendarServer appears to have POSIX
permissions _calendar:_calendar. I don't see any ACLs.
How does the web server know who is allowed to publish data to specific
calendars?
(Hate to ask such basic questions, but I can't seem to find the appropriate
manual.)
---
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
)
An authentication problem would get you an HTTP 401, so it doesn't appear to be directory related.
On Feb 3, 2012, at 12:27 PM, Tim J. Buck wrote:
> On 2/3/12 2:06 PM, Andre LaBranche <> wrote:
>
>> Since the auth is actually working, you probably don't need to proceed into
>> directory service debugging.
>
> I did get into the Directory Service debug log. As you said, it is quite
> verbose, but am I correct that the auth seems to be working? :
>
>
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1470,
> API: MapName, Server Used : mbr_mig DAC : Name = com.apple.access_calendar :
> isUser = 0
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
> Cache hit - com.apple.access_calendar (0x0000000100295C50)
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
> Cache entry is a negative entry (discarding result)
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1470,
> API: MapName, Server Used : mbr_mig DAR : Name = com.apple.access_calendar :
> Not found
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1470,
> API: MapName, Server Used : mbr_mig DAC : Name = com.apple.access_calendar :
> isUser = 0
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
> Cache hit - com.apple.access_calendar (0x0000000100295C50)
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
> Cache entry is a negative entry (discarding result)
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1470,
> API: MapName, Server Used : mbr_mig DAR : Name = com.apple.access_calendar :
> Not found
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1470,
> API: MapName, Server Used : mbr_mig DAC : Name = com.apple.access_calendar :
> isUser = 0
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
> Cache hit - com.apple.access_calendar (0x0000000100295C50)
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
> Cache entry is a negative entry (discarding result)
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1470,
> API: MapName, Server Used : mbr_mig DAR : Name = com.apple.access_calendar :
> Not found
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1472,
> API: dsDoDirNodeAuth(), LDAPv3 Used : DAC : Node Ref = 33556781 : User Name
> = timjbuck : Auth Method = dsAuthMethodStandard:dsAuthNodeDIGEST-MD5 : Auth
> Only Flag = 1 : Continue Data = 0
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - CLDAPv3Plugin:
> DoAuthenticationOnRecordType - Attempting use of authentication method
> dsAuthMethodStandard:dsAuthNodeDIGEST-MD5
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - CLDAPv3Plugin: Attempting
> to get dsAttrTypeStandard:AuthenticationAuthority
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - CLDAPv3Plugin:
> LookupAttribute value found
> ;ApplePasswordServer;0x4c5f1f4a1d18e4380000000400000004,1024 35
> 1225406072978067361098757052121962069672316632844369972172679617900101624798
> 5576824058798475198080356794812540999170186758384332600474653861606992466000
> 7699837181248612215547009986071956366076636846194743899953910907222561638167
> 3728893176650606664725373219822346621141425994680181319980206281690411785957
> 54889 :2002:4160:c082::c62c:3ff:fe0b:44fd
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - CLDAPv3Plugin:
> LookupAttribute value found
> ;Kerberosv5;0x4c5f1f4a1d18e4380000000400000004;
> CH.NET;INTELMINI.BEFREECHURCH.NET;1024 35
> 1225406072978067361098757052121962069672316632844369972172679617900101624798
> 5576824058798475198080356794812540999170186758384332600474653861606992466000
> 7699837181248612215547009986071956366076636846194743899953910907222561638167
> 3728893176650606664725373219822346621141425994680181319980206281690411785957
> 54889 :2002:4160:c082::c62c:3ff:fe0b:44fd
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] -
> CLDAPv3Plugin::DoPasswordServerAuth:
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - CLDAPv3Plugin: Attempting
> use of authentication method dsAuthMethodStandard:dsAuthNodeDIGEST-MD5
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Internal Dispatch, API:
> dsDoPlugInCustomCall(), PasswordServer Used : DAC : Node Ref = 33556783 :
> Request Code = 1
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] -
> CPSPlugIn::DoPlugInCustomCall
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Internal Dispatch, API:
> dsDoPlugInCustomCall(), PasswordServer Used : DAR : Node Ref = 33556783 :
> Request Code = 1 : Result code = 0
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Internal Dispatch, API:
> dsDoDirNodeAuth(), PasswordServer Used : DAC : Node Ref = 33556783 : User
> Name = 0x4c5f1f4a1d18e4380000000400000004,1024 35
> 1225406072978067361098757052121962069672316632844369972172679617900101624798
> 5576824058798475198080356794812540999170186758384332600474653861606992466000
> 7699837181248612215547009986071956366076636846194743899953910907222561638167
> 3728893176650606664725373219822346621141425994680181319980206281690411785957
> 54889 : Auth Method =
> dsAuthMethodStandard:dsAuthNodeDIGEST-MD5 : Auth Only Flag = 1 : Continue
> Data = 0
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - PasswordServer PlugIn:
> Attempting use of authentication method
> dsAuthMethodStandard:dsAuthNodeDIGEST-MD5
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - GetAuthMethodConstant
> siResult=0, uiAuthMethod=1236, mech=
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] -
> CPSPlugIn::EndServerSession opens: 19, closes 16
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] -
> hexHash=DD4CA447A77ACD2496FA9489DEE08228
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] -
> CPSPlugIn::HandleFirstContact: trying LDAP Hint
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] -
> CPSPlugIn::HandleFirstContact: hint is 127.0.0.1, result = 0
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - BeginServerSession, ip =
> 127.0.0.1, inSock = -1
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - GetAuthMethodSASLName
> siResult=0, mech=WEBDAV-DIGEST
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - CPSPlugIn::Attempting SASL
> Authentication
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - DIGEST-MD5 client step 2
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - DIGEST-MD5 unrecognized
> pair method/PUT: ignoring
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - AUTH2
> 757365726E616D653D2274696D6A6275636B222C207265616C6D3D222F536561726368222C20
> 6E6F6E63653D2233353733313537373738303434373633373238373030333733303035353431
> 3932313637393434323731323739303030323132363936333338222C207572693D222F63616C
> 656E646172732F5F5F756964735F5F2F31363545363830332D334639332D343838312D413435
> 372D3738463037373831364132382F33463738454344342D414437382D343643352D42354632
> 2D3931323832323234433335302F45314242463842352D313735372D344534462D413038342D
> 3438433233323039303938432E696373222C20726573706F6E73653D22646432356338656537
> 3735653964316436613337353730666464316231633565222C616C676F726974686D3D6D6435
> 2C7573657269643D307834633566316634613164313865343338303030303030303430303030
> 30303034
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - DIGEST-MD5 client step 3
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - PasswordServer PlugIn:
> SASL authentication error 0
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] -
> CPSPlugIn::DoAuthentication returning 0
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Internal Dispatch, API:
> dsDoDirNodeAuth(), PasswordServer Used : DAR : Node Ref = 33556783 : Result
> code = 0
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1472,
> API: dsDoDirNodeAuth(), LDAPv3 Used : DAR : Node Ref = 33556781 : Result
> code = 0
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1472,
> API: MapName, Server Used : mbr_mig DAC : Name = timjbuck : isUser = 1
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
> Cache hit - timjbuck (0x00000001002B3EF0)
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1472,
> API: MapName, Server Used : mbr_mig DAR : Name = timjbuck : GUID =
> 165E6803-3F93-4881-A457-78F077816A28
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1472,
> API: MapName, Server Used : mbr_mig DAC : Name =
> com.apple.access_all_services : isUser = 0
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
> Cache hit - com.apple.access_all_services (0x000000010063C280)
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
> Cache entry is a negative entry (discarding result)
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1472,
> API: MapName, Server Used : mbr_mig DAR : Name =
> com.apple.access_all_services : Not found
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1472,
> API: MapName, Server Used : mbr_mig DAC : Name = com.apple.access_calendar :
> isUser = 0
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
> Cache hit - com.apple.access_calendar (0x0000000100295C50)
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
> Cache entry is a negative entry (discarding result)
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1472,
> API: MapName, Server Used : mbr_mig DAR : Name = com.apple.access_calendar :
> Not found
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1472,
> API: MembershipCall, Server Used : mbr_mig DAC
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Membership -
> Cache hit - timjbuck (0x00000001002B3EF0)
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - mbr_mig - Dispatch -
> Lookup - user/computer GUID 165E6803-3F93-4881-A457-78F077816A28 - succeeded
> timjbuck
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Resolve Groups -
> 'timjbuck' fresh 4471 > 1357
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Resolve Groups -
> 'timjbuck' (/LDAPv3/127.0.0.1) - waiting for an inflight membership
> generation to complete
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Resolve Groups -
> 'timjbuck' (/LDAPv3/127.0.0.1) - finished waiting for an inflight membership
> generation to complete
> 2012-02-03 14:32:43 EST - T[0x0000000101A04000] - Client: Python, PID: 1472,
> API: MembershipCall, Server Used : mbr_mig DAR
>
>
>
>
>
>
> _______________________________________________
> 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
)
Anything interesting in iCal Server's error log? /var/log/caldavd/error.log
In general, ACLs are based on GUID and are all internal to iCal Server, and have nothing to do with filesystem permissions. You do want to make sure that SACLs are off, though.
-dre
On Feb 3, 2012, at 12:46 PM, Tim J. Buck wrote:
> On 2/3/12 2:06 PM, Andre LaBranche <> wrote:
>
>> 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.
>
> So I appear to be authenticating correctly, but the CalDAV server is unable
> to write new data to the calendar store. Users can read but not write to
> their calendars.
>
> What I'm not grasping is how the access privileges are applied to the
> calendar data. Everything in /Library/CalendarServer appears to have POSIX
> permissions _calendar:_calendar. I don't see any ACLs.
>
> How does the web server know who is allowed to publish data to specific
> calendars?
>
> (Hate to ask such basic questions, but I can't seem to find the appropriate
> manual.)
>
>
> ---
> 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
)
On Feb 4, 2012, at 10:32 AM, Tim J. Buck wrote:
> On 2/3/12 4:18 PM, Andr LaBranche <> wrote:
>
>> In general, ACLs are based on GUID andare all internal to iCal Srver, and
>> have nothing to do with filesystem permissions. You do want to ae sure that
>> SACLs are off, though.
>
> SACLs are off
>
>
>> Anythinginteresting in iCal Server's error log? /var/log/caldavd/error.log
>
> Lots. But don't know what I'm looking for, so don' know how to search.
>
> Here's what I did:
>
> 1) Set iCal logging to debug, nd restart
> 2) On my laptop, dragged one calendar event from Friday to Saturday,
> resulting in the 40 error at 04/Feb/2012:13:09:8.
> 3) Shut down iCal server
>
> Here's the access lg:
Ok, all that is just more proof that there is a bad request.
Have you tried deleting the CalDAV account from iCal and then re-creating it? If there are any SSL issues, doing that might help.
Otherwise, we'd need to see the actual body of the request that is returning the HTTP 400. You can get by quitting iCal and launching it via Terminal as follows:
/Applications/iCal.app/Contents/MacOS/iCal -LogHTTPActivity YES
warning: it's very verbose. Please don't send the entire log, just the stuff related to the HTTP 400.
HTH,
-dre
_______________________________________________
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
)
