[Cosmo-dev] Hub 500 errors

[Jared Rhine]

Yesterday there were 91 "5xx" errors reported generated by Cosmo 0.7.1 
on the Hub:

http://tsm.osafoundation.org/series/hub:errors/browse

I actually find 94 errors in the log (can't explain the extra 3 right 
now).  46 of those were straight "500" errors.  The rest are 501.

15 errors are PROPFINDs (501s); 7 of those are PROPFINDs on the / 
resource.  2 are against a /mc URL (same collection and user); the rest 
against a ticketed /pim URL (anonymous auth).

33 errors are 501s against /cmp/signup.  My best interpretation is there 
was 1 user (based on IP) who tried 19 times to sign up with Opera 9.23. 
  Another user (different IP) tried 5 times to sign up with Opera 9.10. 
  A third user tried 9 times with Opera 9.23.  All users were on Windows.

39 errors are 500s against /mc/collection.  There are 2 authenticated 
users and one ticket.  The ticket is 0.7.1.dev-r15338, 1 auth is 0.7.0.1 
PPC, the last 0.7.0.1 intel mac.

Searching for ERROR in the Cosmo logs, I see 4 "[DeadlockRetryFilter] 
the server encountered an unexpected error", with following 2 lines:

org.hibernate.validator.InvalidStateException: validation failed for: 
org.osaf.cosmo.model.EventExceptionStamp
         at 
org.hibernate.validator.event.ValidateEventListener.validate(ValidateEventListener.java:148)

Maybe not a 500, but right before one, I see a WARN:

2007-09-19 09:36:55,039 WARN  [EventExceptionValidator] event validation 
error
net.fortuna.ical4j.model.ValidationException: Property [DESCRIPTION] 
must be specified once
         at 
net.fortuna.ical4j.util.PropertyValidator.assertOne(PropertyValidator.java:107)

with the event:

2007-09-19 09:36:55,040 WARN  [EventExceptionValidator] error validating 
event: BEGIN:VCALENDAR^M
PRODID:-//Open Source Applications Foundation//NONSGML Chandler Server//EN^M
VERSION:2.0^M
CALSCALE:GREGORIAN^M
BEGIN:VEVENT^M
DTSTAMP:20070918T052156Z^M
UID:FDA60544-6343-11DC-A551-000D933C46F0^M
RECURRENCE-ID;TZID=America/Los_Angeles;VALUE=DATE-TIME:20070917T150000^M
DTSTART;TZID=America/Los_Angeles;VALUE=DATE-TIME;X-OSAF-ANYTIME=MISSING:20070917T150000^M
BEGIN:VALARM^M
ACTION:DISPLAY^M
TRIGGER;X-OSAF-MISSING=TRUE:-PT15M^M
END:VALARM^M
END:VEVENT^M
END:VCALENDAR^M

There's no other indications of errors I can see.

I don't pretend this email is well-organized or sufficient for next 
steps or anything like that.  These types of analysis are time-consuming 
so I'm just stopping at an arbitrary point on this first analysis so 
people know roughly what's up and the info currently available.

The info from the Cosmo logs is probably all there is.  Additional data 
gathering probably requires painful network tracing to see the actual 
messages returned over the wire in the 500 response body.

My guess is that we consider some of the above actionable, even possibly 
short-list.  Recommendations/analysis abound, but I'll start with just 
getting this initial report out there for people to mull over.

-- Jared