434582 - Way too many CalDAV requests from a few Lightning clients

Status: VERIFIED DUPLICATE of bug 435854

(Calendar :: Provider: CalDAV, defect)

Description

[Jeffrey Harris]

User-Agent:       Mozilla/5.0 (Macintosh; U; Intel Mac OS X; en-US; rv:1.8.1.14) Gecko/20080404 Firefox/2.0.0.14
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.14) Gecko/20080421 Lightning/0.8 Thunderbird/2.0.0.14

OSAF runs a free CalDAV server, called Hub, at hub.chandlerproject.org.  We have a fair number of Lightning users, most of whom make 1000-2000 CalDAV requests per day.

In April and May, there have been two different users with Lightning UserAgents that were hitting our server with 10 requests/second.

You can see a graph of the maximum number of hits from a single IP we get per day at:

http://tsm.osafoundation.org/series/hub:browser:max:count

The user in May apparently noticed there was crazy network traffic and killed Lightning pretty quickly, so the bumps in May are smaller, but looking at the logs shows 10 requests/second, like the April incident.

Here's what our logs look like:

{IP} - {user} [14/May/2008:21:10:44 -0700] "PROPFIND /dav/users/{user} HTTP/1.1" 207 406 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.14) Gecko/20080421 Lightning/0.8 Thunderbird/2.0.0.14"
{IP} - {user} [14/May/2008:21:10:44 -0700] "OPTIONS /dav/users/ HTTP/1.1" 200 - "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.14) Gecko/20080421 Lightning/0.8 Thunderbird/2.0.0.14"
{IP} - {user} [14/May/2008:21:10:44 -0700] "OPTIONS /dav/users/ HTTP/1.1" 200 - "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.14) Gecko/20080421 Lightning/0.8 Thunderbird/2.0.0.14"
{IP} - {user} [14/May/2008:21:10:44 -0700] "OPTIONS /dav/users/ HTTP/1.1" 200 - "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.14) Gecko/20080421 Lightning/0.8 Thunderbird/2.0.0.14"
{IP} - {user} [14/May/2008:21:10:44 -0700] "OPTIONS /dav/users/ HTTP/1.1" 200 - "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.14) Gecko/20080421 Lightning/0.8 Thunderbird/2.0.0.14"
{IP} - {user} [14/May/2008:21:10:44 -0700] "PROPFIND /dav/users/{user} HTTP/1.1" 207 406 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.14) Gecko/20080421 Lightning/0.8 Thunderbird/2.0.0.14"
{IP} - {user} [14/May/2008:21:10:44 -0700] "OPTIONS /dav/users/ HTTP/1.1" 200 - "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.14) Gecko/20080421 Lightning/0.8 Thunderbird/2.0.0.14"
{IP} - {user} [14/May/2008:21:10:44 -0700] "PROPFIND /dav/users/{user} HTTP/1.1" 207 406 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.14) Gecko/20080421 Lightning/0.8 Thunderbird/2.0.0.14"
{IP} - {user} [14/May/2008:21:10:44 -0700] "PROPFIND /dav/users/{user} HTTP/1.1" 207 406 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.14) Gecko/20080421 Lightning

Reproducible: Couldn't Reproduce

Steps to Reproduce:
I have no idea what these users are doing, but it's happened twice now with Lightning clients.  We've blocked the IP of the first user who didn't respond to email about the problem.  The second user gave up on Lightning apparently.

We'd love to help figure out what's going on, we can easily take a few clients hitting us this hard, but dozens would really be a problem.

Comment 1

[Bruno Browning]

There have been isolated reports of problems that sound rather like they might be this one, including against some non-Chandler CalDAV servers. I've never been able to reproduce them, including against my own Chandler instance using a URL whacked in a similar fashion to the one in your logs. Current Sunbird/Lightning nightlies have some new code which traps more errors in this part of the CalDAV provider's first server access, as well as facilities to do much more verbose logging - in part to help track down what's going on here. 

What Chandler version would have been on Hub when this happened? My 0.14.1 generates a "501 Method PROPFIND is not defined..." in response to a PROPFIND on an invalid URL like this, not a 207. It would be useful to know what the server response would have been here.

Comment 2

[Jeffrey Harris]

I'm sorry, I wasn't clear in my bug report; {user} above is an actual username, I just removed it for privacy (I had that sentence in my original report, I must've accidentally removed it).

So I think these are reasonable paths to be making PROPFIND and OPTIONS requests to, there are just too many requests.

At the time, hub was running 0.14.1.

I think we may be able to get in touch with this specific user, if you'd like to follow up with him.

Comment 3

[Bruno Browning]

Yes, I gathered that {user} was an anonymization - I think it was the {IP} that gave it away. :)  I'm sorry that I was not more explicit about the whackery I see in those paths. But ...
1) Lightning needs for the user to enter a calendar URL, not the URL of his/her home collection. So that PROPFIND against the home collection is wrong (should be against the calendar collection), and so is the OPTIONS, which should be against the home collection, not its parent
2) The page at http://chandlerproject.org/Projects/WebUIProtocolUrls#CalDAVCollection seems to imply that the above paths should have /chandler prepended to them. That's certainly the way it seems to work on my own Chandler 0.14.1 installation, where my home calendar is at /chandler/dav/bruno/Bruno_Browning and PROPFINDing or OPTIONing paths not beginning in /chandler gives no webdav joy. You can take this with a grain of salt, though, since Chandler paths have confused me since they were Cosmo 0.2 paths. :)

I suspect that the issue here is the same as the one reported in bug 435854 and already fixed by the checkin in bug 400835. Leaving this bug open for now, though, in case there's something about the Chandler side of this that I'm not understanding.

Comment 4

[Jeffrey Harris]

Re: 2) in comment#3, URLs on Hub are rewritten to remove the /chandler, so that part of the path is sensible.

The issue probably is 1), though, and I suspect you're right that this is a dupe of bug 435854, glad it should be fixed.  I think you can go ahead and close the bug as a dupe.

Comment 5

[Bruno Browning]

Resolving as dupe of bug 435854 based on comment #4