You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@subversion.apache.org by Franz Sirl <Fr...@lauterbach.com> on 2024/10/01 14:00:54 UTC
svn log gives E130003: Malformed XML via DAV
Hi,
recently this svn log command started to fail like that:
```
> svn log --xml --verbose --search @ --use-merge-history --incremental
--revision 172342:{2024-09-30}
http://svn/svn/project/branches/cd/2024_09 >/dev/null
svn: E175009: The XML response contains invalid XML
svn: E130003: Malformed XML: mismatched tag at line 139122
```
Removing the --verbose lets the command succeed, so it seems related to
the sending of the changed pathes. Also running the command with a
file:// URL directly on the server works fine.
Server and client are 1.14.3+issue4711-fix (BTW, when will there be an
official release with the fix for issue 4711?) running on x64-linux.
Actually the failure mode looks quite similar to issue 4711, but this
time the problem happens on the server side.
Looking at the transferred data with wireshark shows this at the end:
```
<S:log-item>
<S:modified-path node-kind="file" text-mods="true"
prop-mods="false">...</S:modified-path>
... (>40000 lines of modified-path/added-path redacted)
<S:modified-path node-kind="file" text-mods="true"
prop-mods="false">...</S:modified-path>
</S:log-report>
```
So the closing tag `</S:log-item>` is missing. This closing tag is only
sent by log_revision_receiver() in subversion/mod_dav_svn/reports/log.c
and is used as a callback in
subversion/libsvn_repos/log.c.
Looking at the code the only failure mode I could imagine so far is that
if the last revision processed for this transaction ends up with
`baton.found_rev_of_interest = FALSE`.
In this case send_log() doesn't call callbacks->revision_receiver() and
so the log-item tag never gets closed?
Hope this helps to track down the bug,
Franz
PS: While investigating that I found a small cosmetic bug in the
prototype (fortunately the code follows the definition) for do_logs() in
subversion/libsvn_repos/log.c:
```
Index: subversion/libsvn_repos/log.c
===================================================================
--- subversion/libsvn_repos/log.c (revision 1921065)
+++ subversion/libsvn_repos/log.c (working copy)
@@ -1719,8 +1719,8 @@
int limit,
svn_boolean_t strict_node_history,
svn_boolean_t include_merged_revisions,
+ svn_boolean_t subtractive_merge,
svn_boolean_t handling_merged_revisions,
- svn_boolean_t subtractive_merge,
svn_boolean_t ignore_missing_locations,
const apr_array_header_t *revprops,
svn_boolean_t descending_order,
```
Re: svn log gives E130003: Malformed XML via DAV
Posted by Daniel Sahlberg <ds...@apache.org>.
On 2024/10/01 14:00:54 Franz Sirl wrote:
(snip)
> PS: While investigating that I found a small cosmetic bug in the
> prototype (fortunately the code follows the definition) for do_logs() in
> subversion/libsvn_repos/log.c:
> ```
> Index: subversion/libsvn_repos/log.c
> ===================================================================
> --- subversion/libsvn_repos/log.c (revision 1921065)
> +++ subversion/libsvn_repos/log.c (working copy)
> @@ -1719,8 +1719,8 @@
> int limit,
> svn_boolean_t strict_node_history,
> svn_boolean_t include_merged_revisions,
> + svn_boolean_t subtractive_merge,
> svn_boolean_t handling_merged_revisions,
> - svn_boolean_t subtractive_merge,
> svn_boolean_t ignore_missing_locations,
> const apr_array_header_t *revprops,
> svn_boolean_t descending_order,
> ```
Thank you for the patch! I've comitted this in r1921423.
Kind regards,
Daniel
Re: [PATCH] Fix missing log-item close tag in on-the-wire XML
Posted by Franz Sirl <Fr...@lauterbach.com>.
Am 2024-10-15 um 12:23 schrieb Daniel Sahlberg:
> Den mån 14 okt. 2024 kl 13:07 skrev Franz Sirl <Franz.Sirl-
> kernel@lauterbach.com <ma...@lauterbach.com>>:
>
> Hi,
>
> the attached patch fixes both issue 4856 and the (different) bug
> we were seeing in one of our own repositories.
> The problem boils down to the fact that with `svn log --xml --verbose`
> a log-item is opened every time the PATH_CHANGE_RECEIVER callback is
> used. But if the revision is later declared "unimportant", the
> corresponding log-item closure is never sent via the REVISION_RECEIVER
> callback.
>
> The patch fixes that by always using an intermediate callback routine
> and recording the call of inner() in a new flag in
> interesting_merge_baton_t. This flag is then used to decide if the
> REVISION_RECEIVER callback has to be called to close the log-item.
>
> With yet another flag in interesting_merge_baton_t record_inner_call()
> could be merged into interesting_merge() if you prefer that.
>
>
> Thank you for the patch!
>
> In the discussion about issue 4177, Daniel Shahaf mentioned that there
> was an inconsistency about the number of times the receiver callback was
> called, so it seems likely you have found that issue.
>
> I'm going to test this further when time permits, hopefully this week.
Hello Daniel,
in the meantime I noticed that the previous patch streams out a lot of
duplicated revisions. I've come up with v2 of the patch, which probably
has a bit of unnecessary code because I'm not so sure about when and how
this code recurses.
The patch avoids the duplicates, but it also triggers a strange behavior
with --limit. If I add for example a `--limit 1` to the log command, the
XML generated by file: and http: start to differ a lot on the repository
I used for testing. I don't know what to make of that...
BTW, the SVN_ERR_ASSERT() in subversion/libsvn_ra_serf/log.c was just
helpful to get a better error report. It's not necessary for the
functionality of the patch.
Hope this helps,
Franz
Re: [PATCH] Fix missing log-item close tag in on-the-wire XML
Posted by Daniel Sahlberg <da...@gmail.com>.
Den mån 14 okt. 2024 kl 13:07 skrev Franz Sirl <
Franz.Sirl-kernel@lauterbach.com>:
> Hi,
>
> the attached patch fixes both issue 4856 and the (different) bug
> we were seeing in one of our own repositories.
> The problem boils down to the fact that with `svn log --xml --verbose`
> a log-item is opened every time the PATH_CHANGE_RECEIVER callback is
> used. But if the revision is later declared "unimportant", the
> corresponding log-item closure is never sent via the REVISION_RECEIVER
> callback.
>
> The patch fixes that by always using an intermediate callback routine
> and recording the call of inner() in a new flag in
> interesting_merge_baton_t. This flag is then used to decide if the
> REVISION_RECEIVER callback has to be called to close the log-item.
>
> With yet another flag in interesting_merge_baton_t record_inner_call()
> could be merged into interesting_merge() if you prefer that.
>
Thank you for the patch!
In the discussion about issue 4177, Daniel Shahaf mentioned that there was
an inconsistency about the number of times the receiver callback was
called, so it seems likely you have found that issue.
I'm going to test this further when time permits, hopefully this week.
Kind regards,
Daniel
[PATCH] Fix missing log-item close tag in on-the-wire XML
Posted by Franz Sirl <Fr...@lauterbach.com>.
Hi,
the attached patch fixes both issue 4856 and the (different) bug
we were seeing in one of our own repositories.
The problem boils down to the fact that with `svn log --xml --verbose`
a log-item is opened every time the PATH_CHANGE_RECEIVER callback is
used. But if the revision is later declared "unimportant", the
corresponding log-item closure is never sent via the REVISION_RECEIVER
callback.
The patch fixes that by always using an intermediate callback routine
and recording the call of inner() in a new flag in
interesting_merge_baton_t. This flag is then used to decide if the
REVISION_RECEIVER callback has to be called to close the log-item.
With yet another flag in interesting_merge_baton_t record_inner_call()
could be merged into interesting_merge() if you prefer that.
Franz.
Re: svn log gives E130003: Malformed XML via DAV
Posted by Franz Sirl <fr...@lauterbach.com>.
Hi Nathan,
after further checking it turns out the failure mode I see is exactly
the same like issue 4856, only you need to use --verbose and http to see
it (`r` is the repository like created by `repro-4856.sh`):
```
> svn log --xml --verbose --use-merge-history -r 9:10 http://svn/r/A4
>/dev/null
svn: E175009: The XML response contains invalid XML
svn: E130003: Malformed XML: mismatched tag at line 57
```
Looking into the intermediate XML on the wire shows the same missing
log-item end tag. Again with file: access the XML looks fine.
Franz
Re: svn log gives E130003: Malformed XML via DAV
Posted by Franz Sirl <fr...@lauterbach.com>.
Am 2024-10-02 um 17:10 schrieb Franz Sirl:
> So I came up with the attached tentative and so far untested patch.
> I'm currently building packages and will test them as soon as build is
> finished.
Unfortunately the patch is just papering over the real bug. The XML
error is gone, but the transferred XML is still truncated.
So it seems the bug is really about handling the sizes of the transfer
buffers, though the compressed (1,063,630 bytes, ~ 1MiB + 16 KiB) and
uncompressed (13,725,443 bytes) XML sizes don't look typical buffer sizes...
Anyway, fixing this likely requires far more insight into the subversion
code than I have. So unless I get some hints on where to look, I'm out
for now.
But if there is anything for me to help with, just let me know.
Franz
Re: svn log gives E130003: Malformed XML via DAV
Posted by Franz Sirl <Fr...@lauterbach.com>.
Am 2024-10-02 um 16:02 schrieb Nathan Hartman:
> On Tue, Oct 1, 2024 at 10:03 AM Franz Sirl
> <Fr...@lauterbach.com> wrote:
>> Looking at the transferred data with wireshark shows this at the end:
>> ```
>> <S:log-item>
>> <S:modified-path node-kind="file" text-mods="true"
>> prop-mods="false">...</S:modified-path>
>> ... (>40000 lines of modified-path/added-path redacted)
>> <S:modified-path node-kind="file" text-mods="true"
>> prop-mods="false">...</S:modified-path>
>> </S:log-report>
>> ```
>>
>> So the closing tag `</S:log-item>` is missing. This closing tag is only
>> sent by log_revision_receiver() in subversion/mod_dav_svn/reports/log.c
>> and is used as a callback in
>> subversion/libsvn_repos/log.c.
>> Looking at the code the only failure mode I could imagine so far is that
>> if the last revision processed for this transaction ends up with
>> `baton.found_rev_of_interest = FALSE`.
>> In this case send_log() doesn't call callbacks->revision_receiver() and
>> so the log-item tag never gets closed?
>
>
> Thank you for the analysis.
>
> Would you say that the Issue 4711 patch in the issue tracker [3]
> improves the situation, even if it's still missing something?
To make it clear, all the tests I've done on client+server have
the patch [3] applied. It's in use for quite some time here without
bad effects (and fixed the problem for us, the reporter of 4711 is a
colleague of mine). I believe the log-item bug is totally separate
bug on server-side. I just meant to express that maybe a similar
missing corner case handling (like 4711 on client) is the reason
for this bug on the server-side.
> If we suspect that baton.found_rev_of_interest being FALSE for the
> last processed revision causes the missing tag, we'll need to come up
> with a reproduction recipe that triggers that. Could you rerun the
> command but with a revision range where the last revision *is* of
> interest, and tell us if the XML is formed correctly?
The command worked well for a long time, only after one of my colleagues
committed a merge from the trunk to this release branch it stopped to work.
This merge contained mergeinfo about the merged trunk revisions and also
mergeinfo about the merges from the colleagues user branch to trunk.
Probably this changed internal processing order in a way that made a
baton.found_rev_of_interest=FALSE come as the last log-item.
With a http:// URL the command fails midway while outputting the XML
resulting in a truncated file (2.8M size). With a file:// URL the XML is
5.4M in size and passes (with --incremental removed) a validity check
with `jing -c subversion/svn/schema/log.rnc`.
After thinking about it some more it occurred to me that since file://
is OK, subversion/libsvn_repos/log.c should be fine and rather the
problem is in subversion/mod_dav_svn/reports/log.c.
So I came up with the attached tentative and so far untested patch.
I'm currently building packages and will test them as soon as build is
finished.
BTW, it would make comparing/diffing the XML easier if both file:// and
http:// outputs would use the same template to output the <path> tag.
Franz
Re: svn log gives E130003: Malformed XML via DAV
Posted by Nathan Hartman <ha...@gmail.com>.
On Wed, Oct 2, 2024 at 10:02 AM Nathan Hartman <ha...@gmail.com> wrote:
>
> On Tue, Oct 1, 2024 at 10:03 AM Franz Sirl
> <Fr...@lauterbach.com> wrote:
> >
> > Hi,
> >
> > recently this svn log command started to fail like that:
> >
> > ```
> > > svn log --xml --verbose --search @ --use-merge-history --incremental
> > --revision 172342:{2024-09-30}
> > http://svn/svn/project/branches/cd/2024_09 >/dev/null
> > svn: E175009: The XML response contains invalid XML
> > svn: E130003: Malformed XML: mismatched tag at line 139122
> > ```
> >
> > Removing the --verbose lets the command succeed, so it seems related to
> > the sending of the changed pathes. Also running the command with a
> > file:// URL directly on the server works fine.
> >
> > Server and client are 1.14.3+issue4711-fix (BTW, when will there be an
> > official release with the fix for issue 4711?) running on x64-linux.
> > Actually the failure mode looks quite similar to issue 4711, but this
> > time the problem happens on the server side.
>
>
> I thought I remembered fix(es) for unbalanced XML closing tags being
> implemented, committed, and backported to the 1.14.x branch!! But
> looking through the history, I only see two regression tests that were
> committed and both are @XFail() (meaning, expected FAILs).
>
> Those tests were committed to trunk in r1877310 and r1897133.
>
> Now, it seems there are two issues in the issue tracker related to
> this: Issue 4711 [1] (which you referenced) and Issue 4856 [2]. I'm
> adding a note to both...
>
>
> > Looking at the transferred data with wireshark shows this at the end:
> > ```
> > <S:log-item>
> > <S:modified-path node-kind="file" text-mods="true"
> > prop-mods="false">...</S:modified-path>
> > ... (>40000 lines of modified-path/added-path redacted)
> > <S:modified-path node-kind="file" text-mods="true"
> > prop-mods="false">...</S:modified-path>
> > </S:log-report>
> > ```
> >
> > So the closing tag `</S:log-item>` is missing. This closing tag is only
> > sent by log_revision_receiver() in subversion/mod_dav_svn/reports/log.c
> > and is used as a callback in
> > subversion/libsvn_repos/log.c.
> > Looking at the code the only failure mode I could imagine so far is that
> > if the last revision processed for this transaction ends up with
> > `baton.found_rev_of_interest = FALSE`.
> > In this case send_log() doesn't call callbacks->revision_receiver() and
> > so the log-item tag never gets closed?
>
>
> Thank you for the analysis.
>
> Would you say that the Issue 4711 patch in the issue tracker [3]
> improves the situation, even if it's still missing something?
>
> If we suspect that baton.found_rev_of_interest being FALSE for the
> last processed revision causes the missing tag, we'll need to come up
> with a reproduction recipe that triggers that. Could you rerun the
> command but with a revision range where the last revision *is* of
> interest, and tell us if the XML is formed correctly?
>
>
> > Hope this helps to track down the bug,
> > Franz
> >
> > PS: While investigating that I found a small cosmetic bug in the
> > prototype (fortunately the code follows the definition) for do_logs() in
> > subversion/libsvn_repos/log.c:
> > ```
> > Index: subversion/libsvn_repos/log.c
> > ===================================================================
> > --- subversion/libsvn_repos/log.c (revision 1921065)
> > +++ subversion/libsvn_repos/log.c (working copy)
> > @@ -1719,8 +1719,8 @@
> > int limit,
> > svn_boolean_t strict_node_history,
> > svn_boolean_t include_merged_revisions,
> > + svn_boolean_t subtractive_merge,
> > svn_boolean_t handling_merged_revisions,
> > - svn_boolean_t subtractive_merge,
> > svn_boolean_t ignore_missing_locations,
> > const apr_array_header_t *revprops,
> > svn_boolean_t descending_order,
> > ```
>
>
> Good catch! The 11th and 12th arguments are swapped in the forward
> declaration. I'll commit this fix in a bit, but before I do that, I
> want to go over the call sites and verify they do not have the
> arguments swapped due to copying-and-pasting of the (wrong) forward
> declaration. Hopefully as you say the code follows the definition (and
> not the forward declaration).
>
> Thanks again,
> Nathan
Forgot to include the links... doh!
[1] Issue 4711: https://issues.apache.org/jira/browse/SVN-4711?issueNumber=4711
[2] Issue 4856: https://issues.apache.org/jira/browse/SVN-4856?issueNumber=4856
[3] Patch in issue tracker for Issue 4711:
https://issues.apache.org/jira/secure/attachment/13045647/4711_patch_new.txt
Re: svn log gives E130003: Malformed XML via DAV
Posted by Nathan Hartman <ha...@gmail.com>.
On Tue, Oct 1, 2024 at 10:03 AM Franz Sirl
<Fr...@lauterbach.com> wrote:
>
> Hi,
>
> recently this svn log command started to fail like that:
>
> ```
> > svn log --xml --verbose --search @ --use-merge-history --incremental
> --revision 172342:{2024-09-30}
> http://svn/svn/project/branches/cd/2024_09 >/dev/null
> svn: E175009: The XML response contains invalid XML
> svn: E130003: Malformed XML: mismatched tag at line 139122
> ```
>
> Removing the --verbose lets the command succeed, so it seems related to
> the sending of the changed pathes. Also running the command with a
> file:// URL directly on the server works fine.
>
> Server and client are 1.14.3+issue4711-fix (BTW, when will there be an
> official release with the fix for issue 4711?) running on x64-linux.
> Actually the failure mode looks quite similar to issue 4711, but this
> time the problem happens on the server side.
I thought I remembered fix(es) for unbalanced XML closing tags being
implemented, committed, and backported to the 1.14.x branch!! But
looking through the history, I only see two regression tests that were
committed and both are @XFail() (meaning, expected FAILs).
Those tests were committed to trunk in r1877310 and r1897133.
Now, it seems there are two issues in the issue tracker related to
this: Issue 4711 [1] (which you referenced) and Issue 4856 [2]. I'm
adding a note to both...
> Looking at the transferred data with wireshark shows this at the end:
> ```
> <S:log-item>
> <S:modified-path node-kind="file" text-mods="true"
> prop-mods="false">...</S:modified-path>
> ... (>40000 lines of modified-path/added-path redacted)
> <S:modified-path node-kind="file" text-mods="true"
> prop-mods="false">...</S:modified-path>
> </S:log-report>
> ```
>
> So the closing tag `</S:log-item>` is missing. This closing tag is only
> sent by log_revision_receiver() in subversion/mod_dav_svn/reports/log.c
> and is used as a callback in
> subversion/libsvn_repos/log.c.
> Looking at the code the only failure mode I could imagine so far is that
> if the last revision processed for this transaction ends up with
> `baton.found_rev_of_interest = FALSE`.
> In this case send_log() doesn't call callbacks->revision_receiver() and
> so the log-item tag never gets closed?
Thank you for the analysis.
Would you say that the Issue 4711 patch in the issue tracker [3]
improves the situation, even if it's still missing something?
If we suspect that baton.found_rev_of_interest being FALSE for the
last processed revision causes the missing tag, we'll need to come up
with a reproduction recipe that triggers that. Could you rerun the
command but with a revision range where the last revision *is* of
interest, and tell us if the XML is formed correctly?
> Hope this helps to track down the bug,
> Franz
>
> PS: While investigating that I found a small cosmetic bug in the
> prototype (fortunately the code follows the definition) for do_logs() in
> subversion/libsvn_repos/log.c:
> ```
> Index: subversion/libsvn_repos/log.c
> ===================================================================
> --- subversion/libsvn_repos/log.c (revision 1921065)
> +++ subversion/libsvn_repos/log.c (working copy)
> @@ -1719,8 +1719,8 @@
> int limit,
> svn_boolean_t strict_node_history,
> svn_boolean_t include_merged_revisions,
> + svn_boolean_t subtractive_merge,
> svn_boolean_t handling_merged_revisions,
> - svn_boolean_t subtractive_merge,
> svn_boolean_t ignore_missing_locations,
> const apr_array_header_t *revprops,
> svn_boolean_t descending_order,
> ```
Good catch! The 11th and 12th arguments are swapped in the forward
declaration. I'll commit this fix in a bit, but before I do that, I
want to go over the call sites and verify they do not have the
arguments swapped due to copying-and-pasting of the (wrong) forward
declaration. Hopefully as you say the code follows the definition (and
not the forward declaration).
Thanks again,
Nathan