On Thu, Jul 15, 2010 at 4:06 PM, C. Michael Pilato <cmpilato_at_collab.net> wrote:
> On 06/22/2010 08:57 AM, Julian Foad wrote:
>> Here are some Apache access log entries from one occurrence, with paths
>> anonymized and the client Id string (always "SVN/1.6.6 (r40053)
>> neon/0.28.3") omitted for brevity:
>> [[[
>> 127.0.0.1 - UserK [16/Dec/2009:20:25:17 -0800]
>> "MKACTIVITY /svn/RepoJ/!svn/act/ActivityA HTTP/1.1" 201 312 "-"
>> 127.0.0.1 - UserK [16/Dec/2009:23:20:45 -0800]
>> "PROPPATCH /svn/RepoJ/!svn/wrk/ActivityA/branches/BranchD/PathG HTTP/1.1" 207 582 "-"
>> 127.0.0.1 - UserM [17/Dec/2009:00:12:45 -0800]
>> "MERGE /svn/RepoJ/branches/BranchH/PathC HTTP/1.1" 200 953 "-"
>> 127.0.0.1 - UserM [17/Dec/2009:00:12:59 -0800]
>> "MERGE /svn/RepoJ/branches/BranchP/PathC HTTP/1.1" 200 965 "-"
>> 127.0.0.1 - UserK [17/Dec/2009:00:21:19 -0800]
>> "DELETE /svn/RepoJ/!svn/act/ActivityA HTTP/1.1" 204 - "-"
>> 127.0.0.1 - UserK [17/Dec/2009:00:32:45 -0800]
>> "MKACTIVITY /svn/RepoJ/!svn/act/ActivityB HTTP/1.1" 201 312 "-"
>> 127.0.0.1 - UserK [17/Dec/2009:00:39:58 -0800]
>> "MERGE /svn/RepoJ/branches/BranchD/PathJ HTTP/1.1" 500 279 "-"
>> 127.0.0.1 - UserK [17/Dec/2009:00:39:59 -0800]
>> "PROPPATCH /svn/RepoJ/!svn/wrk/ActivityB/branches/BranchD/PathE HTTP/1.1" 207 569 "-"
>> 127.0.0.1 - UserK [17/Dec/2009:00:39:59 -0800]
>> "MERGE /svn/RepoJ/branches/BranchD/PathJ HTTP/1.1" 500 279 "-"
>> ]]]
>
> This sequence looks weird to me. In Subversion, there's always exactly one
> MERGE -- the next-to-last step in a commit (which is begun by a MKACTIVITY
> in HTTPv1, a POST in HTTPv2). You've got two MKACTIVITYs, and four MERGEs.
> Unless there are more operations that occurred but are just missing from
> your report there, that's just weird.
>
>> and the corresponding error log:
>> [[[
>> [Thu Dec 17 00:39:58 2009] [error] [client 127.0.0.1]
>> Could not MERGE resource "/svn/RepoJ/!svn/act/ActivityA" into "/svn/RepoJ/branches/BranchD/PathJ". [500, #0]
>> [Thu Dec 17 00:39:58 2009] [error] [client 127.0.0.1]
>> There was a problem opening the transaction specified by this activity. [500, #2]
>> [Thu Dec 17 00:39:58 2009] [error] [client 127.0.0.1]
>> Can't open file '/svn/repos/RepoJ/db/transactions/props': No such file or directory [500, #2]
>> ]]]
>>
>> The error appears to match the second-last MERGE in the access log. I
>> don't have a copy of the body of the MERGE request in this case.
>>
>> The error refers to an activity Id that was the subject of the DELETE
>> that was logged 18 minutes earlier. A comment from one of our guys
>> looking at the logs: "We are seeing 22,600 changes for Activity A and no
>> merge at the end (just a DELETE). Then we see about 931 commands for
>> Activity B and a MERGE that fails for Activity A."
>>
>> Is this a case where the client side shouldn't be sending a MERGE at
>> this point? Even if that is the primary problem, I'm still interested
>> in Subversion's response to this MERGE request.
>
> Our codebase should definitely not allow a bogus (NULL) txn-id to be
> casually transformed in a path. You can commit assertions around those
> parts *right now*.
>
> If no MERGE occurs at the end of a stream of activity modifications, that's
> usually means that one of those modifications failed and the client has
> bailed on the commit (it then issues the DELETE of the activity as a cleanup
> step). Weird that something would then try to MERGE the activity that was
> already DELETEd.
>
> This is not behavior I've seen in Subversion's own codebase -- so maybe just
> a rare WANdisco software bug?
Possibly. If we're shoving in bogus commands, that would
understandably result in Subversion weirdness. Thanks for double
checking the arithmetic!
-Hyrum
Received on 2010-07-15 17:16:52 CEST