I tried a dry-run merge, using a tr...@908933 client, and it hangs with
Serf, but completes in a few seconds with Neon. (When I say it hangs, an
identical test except using a trunk build from 2010-02-04 hung for 25
minutes before I interrupted it.)
The test case here uses a 1....@902803 WC, clean except for a local mod
to the 'STATUS' file. The "##" lines are comments I typed while I was
waiting, to remind me when I issued the command.
[[[
$ svn merge --dry-run ^/subversion/branches/1.6.x-r891672/@902803
--- Merging r891676 through r902803 into '.':
U subversion/tests/cmdline/externals_tests.py
## Started ~10:49 ...
^C/home/julianfoad/src/subversion-a/subversion/svn/util.c:900: (apr_err=4)
/home/julianfoad/src/subversion-a/subversion/libsvn_client/merge.c:9460:
(apr_err=4)
/home/julianfoad/src/subversion-a/subversion/libsvn_client/merge.c:8082:
(apr_err=4)
/home/julianfoad/src/subversion-a/subversion/libsvn_client/merge.c:7753:
(apr_err=4)
/home/julianfoad/src/subversion-a/subversion/libsvn_client/merge.c:4863:
(apr_err=4)
/home/julianfoad/src/subversion-a/subversion/libsvn_ra_serf/update.c:2248:
(apr_err=4)
svn: Error retrieving REPORT (4): Interrupted system call
$ svn merge --dry-run ^/subversion/branches/1.6.x-r891672/@902803
--config-option=servers:global:http-library=neon
--- Merging r891676 through r902803 into '.':
U subversion/tests/cmdline/externals_tests.py
U subversion/libsvn_client/commit_util.c
$ svn merge --dry-run ^/subversion/branches/1.6.x-r891672/@902803
--config-option=servers:global:http-library=neon
--- Merging r891676 through r902803 into '.':
U subversion/tests/cmdline/externals_tests.py
U subversion/libsvn_client/commit_util.c
$ svn merge --dry-run ^/subversion/branches/1.6.x-r891672/@902803
--config-option=servers:global:http-library=serf
--- Merging r891676 through r902803 into '.':
U subversion/tests/cmdline/externals_tests.py
## Started 11:16 ...
]]]
Here's the stack trace if I interrupt it in GDB after about 10 seconds:
[[[
--- Merging r891676 through r902803 into '.':
U subversion/tests/cmdline/externals_tests.py
^C
Program received signal SIGINT, Interrupt.
0x0040e422 in __kernel_vsyscall ()
(gdb) bt
#0 0x0040e422 in __kernel_vsyscall ()
#1 0x004dc156 in epoll_wait () from /lib/tls/i686/cmov/libc.so.6
#2 0x0061d3ad in apr_pollset_poll () from /usr/lib/libapr-1.so.0
#3 0x00d149e8 in serf_context_run () from /usr/lib/libserf-0.so.0
#4 0x00af2b9d in finish_report (report_baton=0x966f148, pool=0x966ef30)
at /home/julianfoad/src/subversion-b/subversion/libsvn_ra_serf/update.c:2237
#5 0x002eff90 in drive_merge_report_editor (
target_abspath=0x81b5c70 "/home/julianfoad/src/subversion-1.6.x",
url1=0x80ad3d0
"https://svn.apache.org/repos/asf/subversion/branches/1.6.x";, revision1=891675,
url2=0x80ad448
"https://svn.apache.org/repos/asf/subversion/branches/1.6.x-r891672";,
revision2=902803, children_with_mergeinfo=0x9123318,
depth=svn_depth_infinity,
notify_b=0xbfffede4, callbacks=0x31be60, merge_b=0xbfffed74, pool=0x966ef30)
at /home/julianfoad/src/subversion-b/subversion/libsvn_client/merge.c:4863
#6 0x002f5b76 in do_directory_merge (
url1=0x80ad3d0
"https://svn.apache.org/repos/asf/subversion/branches/1.6.x";, revision1=891675,
url2=0x80ad448
"https://svn.apache.org/repos/asf/subversion/branches/1.6.x-r891672";,
revision2=902803, target_abspath=0x81b5c70
"/home/julianfoad/src/subversion-1.6.x",
depth=svn_depth_infinity, squelch_mergeinfo_notifications=0,
notify_b=0xbfffede4,
merge_b=0xbfffed74, pool=0x9123270)
at /home/julianfoad/src/subversion-b/subversion/libsvn_client/merge.c:7746
#7 0x002f66cf in do_merge (merge_sources=0x80ac9f0,
target_abspath=0x81b5c70 "/home/julianfoad/src/subversion-1.6.x",
sources_ancestral=1,
sources_related=1, same_repos=1, ignore_ancestry=0, force=0, dry_run=1,
record_only=0,
reintegrate_merge=0, squelch_mergeinfo_notifications=0,
depth=svn_depth_infinity,
merge_options=0x0, use_sleep=0xbfffef30, ctx=0x808fb60, pool=0x808f200)
at /home/julianfoad/src/subversion-b/subversion/libsvn_client/merge.c:8079
#8 0x002fa646 in svn_client_merge_peg3 (
source=0x81b5968
"https://svn.apache.org/repos/asf/subversion/branches/1.6.x-r891672";,
ranges_to_merge=0x81b5b80, peg_revision=0xbfffefe0, target_wcpath=0x8073548
"",
depth=svn_depth_unknown, ignore_ancestry=0, force=0, record_only=0,
dry_run=1,
merge_options=0x0, ctx=0x808fb60, pool=0x808f200)
at /home/julianfoad/src/subversion-b/subversion/libsvn_client/merge.c:9451
#9 0x0805b0b2 in svn_cl__merge (os=0x808f3a8, baton=0xbffff248, pool=0x808f200)
at /home/julianfoad/src/subversion-b/subversion/svn/merge-cmd.c:322
#10 0x0805a53e in main (argc=5, argv=0xbffff394)
at /home/julianfoad/src/subversion-b/subversion/svn/main.c:2249
]]]
If in GDB I step through the big loop in RA-serf's finish_report(),
pausing in each iteration, then it works [1]. If, however, I break at
the beginning of the loop, set a breakpoint at the end of the loop, and
let that loop run through at full speed, then it hangs in
serf_context_run() in some iteration of the loop. [2]
If I insert debug prints [3], I get:
[[[
## ra-serf finish_report() loop:
## done=0, fetches=0, propfinds=0, t=-694967296
## done=0, num_conns=2, cur_conn=1
## done=0, fetches=0, propfinds=0, t=-694967296
## done=0, num_conns=2, cur_conn=1
## done=0, fetches=0, propfinds=0, t=-694967296
## done=0, num_conns=2, cur_conn=1
## done=0, fetches=0, propfinds=0, t=-694967296
## done=0, num_conns=2, cur_conn=1
## done=0, fetches=2, propfinds=0, t=-694967296
## done=1, num_conns=2, cur_conn=1
## done=1, fetches=2, propfinds=0, t=-694967296
## done=1, num_conns=2, cur_conn=1
[... hundreds of repeats ...]
## done=1, fetches=2, propfinds=0, t=-694967296
## done=1, num_conns=2, cur_conn=1
## done=1, fetches=2, propfinds=0, t=-694967296
--- Merging r891676 through r902803 into '.':
U subversion/tests/cmdline/externals_tests.py
## done=1, num_conns=2, cur_conn=1
## done=1, fetches=1, propfinds=0, t=-694967296
[... hangs here ...]
]]]
The timeout looks wrong, for a start. Could that be the problem?
My Serf is version 0.3.0.
- Julian
[1]
[[[
(gdb) run
Starting program:
/home/julianfoad/build/subversion-b/subversion/svn/.libs/lt-svn merge --dry-run
\^/subversion/branches/1.6.x-r891672/@902803
--config-option=servers:global:http-library=serf
[Thread debugging using libthread_db enabled]
[New Thread 0xb7eb2b70 (LWP 10080)]
[Thread 0xb7eb2b70 (LWP 10080) exited]
Breakpoint 2, finish_report (report_baton=0x966f148, pool=0x966ef30)
at /home/julianfoad/src/subversion-b/subversion/libsvn_ra_serf/update.c:2235
2235 while (!report->done || report->active_fetches ||
report->active_propfinds)
(gdb) c
Continuing.
Breakpoint 3, finish_report (report_baton=0x966f148, pool=0x966ef30)
at /home/julianfoad/src/subversion-b/subversion/libsvn_ra_serf/update.c:2238
2238 if (APR_STATUS_IS_TIMEUP(status))
(gdb) c
Continuing.
Breakpoint 3, finish_report (report_baton=0x966f148, pool=0x966ef30)
at /home/julianfoad/src/subversion-b/subversion/libsvn_ra_serf/update.c:2238
2238 if (APR_STATUS_IS_TIMEUP(status))
(gdb) c
Continuing.
Breakpoint 3, finish_report (report_baton=0x966f148, pool=0x966ef30)
at /home/julianfoad/src/subversion-b/subversion/libsvn_ra_serf/update.c:2238
2238 if (APR_STATUS_IS_TIMEUP(status))
(gdb) c
Continuing.
Breakpoint 3, finish_report (report_baton=0x966f148, pool=0x966ef30)
at /home/julianfoad/src/subversion-b/subversion/libsvn_ra_serf/update.c:2238
2238 if (APR_STATUS_IS_TIMEUP(status))
(gdb) c
Continuing.
Breakpoint 3, finish_report (report_baton=0x966f148, pool=0x966ef30)
at /home/julianfoad/src/subversion-b/subversion/libsvn_ra_serf/update.c:2238
2238 if (APR_STATUS_IS_TIMEUP(status))
(gdb) c
Continuing.
Breakpoint 3, finish_report (report_baton=0x966f148, pool=0x966ef30)
at /home/julianfoad/src/subversion-b/subversion/libsvn_ra_serf/update.c:2238
2238 if (APR_STATUS_IS_TIMEUP(status))
(gdb) c
Continuing.
--- Merging r891676 through r902803 into '.':
U subversion/tests/cmdline/externals_tests.py
U subversion/libsvn_client/commit_util.c
Breakpoint 3, finish_report (report_baton=0x966f148, pool=0x966ef30)
at /home/julianfoad/src/subversion-b/subversion/libsvn_ra_serf/update.c:2238
2238 if (APR_STATUS_IS_TIMEUP(status))
(gdb) c
Continuing.
Program exited normally.
]]]
[2]
[[[
Starting program:
/home/julianfoad/build/subversion-b/subversion/svn/.libs/lt-svn merge --dry-run
\^/subversion/branches/1.6.x-r891672/@902803
--config-option=servers:global:http-library=serf
[Thread debugging using libthread_db enabled]
[New Thread 0xb7eb2b70 (LWP 31900)]
[Thread 0xb7eb2b70 (LWP 31900) exited]
Breakpoint 2, finish_report (report_baton=0x966f148, pool=0x966ef30)
at /home/julianfoad/src/subversion-b/subversion/libsvn_ra_serf/update.c:2235
2235 while (!report->done || report->active_fetches ||
report->active_propfinds)
(gdb) b 2382
Breakpoint 4 at 0xf4dfb8: file
/home/julianfoad/src/subversion-b/subversion/libsvn_ra_serf/update.c, line 2382.
(gdb) c
Continuing.
--- Merging r891676 through r902803 into '.':
U subversion/tests/cmdline/externals_tests.py
^C
]]]
[3]
[[[
printf("## ra-serf finish_report() loop:\n");
while (!report->done || report->active_fetches || report->active_propfinds)
{
printf("## done=%d, fetches=%u, propfinds=%u, t=%ld\n", report->done,
report->active_fetches, report->active_propfinds, sess->timeout);
fflush(stdout);
status = serf_context_run(sess->context, sess->timeout, pool);
if (APR_STATUS_IS_TIMEUP(status))
{
return svn_error_create(SVN_ERR_RA_DAV_CONN_TIMEOUT,
NULL,
_("Connection timed out"));
}
if (status)
{
SVN_ERR(sess->pending_error);
return svn_error_wrap_apr(status, _("Error retrieving REPORT (%d)"),
status);
}
printf("## done=%d, num_conns=%d, cur_conn=%d\n", (int)report->done,
(int)sess->num_conns, (int)sess->cur_conn); fflush(stdout);
/* Open extra connections if we have enough requests to send. */
if (sess->num_conns < MAX_NR_OF_CONNS)
SVN_ERR(open_connection_if_needed(sess, report->active_fetches +
report->active_propfinds));
/* Switch our connection. */
[...]
]]]
