Endless loop with deflate/ssl

[Lieven Govaerts]

Hi,

while trying to checkout svn's trunk from the apache repository svn/serf hangs in an endless loop. As I won't have time to finish my analysis this weekend, I tried to put all the necessary details in this mail. From reading the relevant source code it looks like a serf issue, not an svn issue.

* Platform:

Windows 7 running in a VirtualBox VM (on MacOSX)

Visual Studio Standard 2005, svn trunk@1134194, serf trunk@1474, Debug build of both.

* Build:

gen-make.py -t vcproj --vsnet-version=2005 --without-neon --with-httpd=../httpd-2.2.15 --with-serf=../serf --with-openssl=../openssl-0.9.8j --with-zlib=zlib --disable-shared

* What steps will reproduce the problem?

Debug\svn\svn\svn co https://svn.apache.org/repos/asf/subversion/trunk c:\temp\trunk

* What happens?

After checking a number of files, svn will hang after a while in a loop.

While the number of files changes from run to run, the endless loop reproduces all the time.

* Analysis:

When pausing the process inside the VS debugger, this is the relevant stack trace:

> svn.exe!serf_dechunk_read(serf_bucket_t * bucket=0x02a07920, unsigned int requested=8096, const char * * data=0x0012f374, unsigned int * len=0x0012f380)  Line 132 C

  svn.exe!serf_deflate_read(serf_bucket_t * bucket=0x02a07aa0, unsigned int requested=8000, const char * * data=0x0012f460, unsigned int * len=0x0012f454)  Line 251 + 0x24 bytes C

  svn.exe!serf_response_read(serf_bucket_t * bucket=0x02a06e20, unsigned int requested=8000, const char * * data=0x0012f460, unsigned int * len=0x0012f454)  Line 387 + 0x20 bytes C

  svn.exe!handle_fetch(serf_request_t * request=0x03edfcc8, serf_bucket_t * response=0x02a06e20, void * handler_baton=0x03ee25a8, apr_pool_t * pool=0x03d70840)  Line 878 + 0x1d bytes C

  svn.exe!handle_response(serf_request_t * request=0x03edfcc8, serf_bucket_t * response=0x02a06e20, svn_ra_serf__handler_t * ctx=0x03ee25f0, int * serf_status=0x0012f4d8, apr_pool_t * pool=0x03d70840)  Line 1485 + 0x1d bytes C

  svn.exe!handle_response_cb(serf_request_t * request=0x03edfcc8, serf_bucket_t * response=0x02a06e20, void * baton=0x03ee25f0, apr_pool_t * pool=0x03d70840)  Line 1517 + 0x30 bytes C

  svn.exe!handle_response(serf_request_t * request=0x03edfcc8, apr_pool_t * pool=0x03d70840)  Line 828 + 0x1e bytes C

  svn.exe!read_from_connection(serf_connection_t * conn=0x0243e2c0)  Line 948 + 0xd bytes C

  svn.exe!serf__process_connection(serf_connection_t * conn=0x0243e2c0, short events=5)  Line 1050 + 0x9 bytes C

  svn.exe!serf_event_trigger(serf_context_t * s=0x018fc6b0, void * serf_baton=0x0243e2c8, const apr_pollfd_t * desc=0x0243d6e8)  Line 207 + 0x11 bytes C

  svn.exe!serf_context_run(serf_context_t * ctx=0x018fc6b0, int duration=-694967296, apr_pool_t * pool=0x03653d50)  Line 269 + 0x11 bytes C

  svn.exe!finish_report(void * report_baton=0x018ed980, apr_pool_t * pool=0x018ec4c0)  Line 2355 + 0x1a bytes C

  svn.exe!svn_wc_crawl_revisions5(svn_wc_context_t * wc_ctx=0x018c5470, const char * local_abspath=0x018ec570, const svn_ra_reporter3_t * reporter=0x0088d1bc, void * report_baton=0x018ed980, int restore_files=1, svn_depth_t depth=svn_depth_unknown, int honor_depth_exclude=1, int depth_compatibility_trick=0, int use_commit_times=0, svn_error_t * (void *)* cancel_func=0x0055d0d9, void * cancel_baton=0x00000000, void (void *, const svn_wc_notify_t *, apr_pool_t *)* notify_func=0x00574000, void * notify_baton=0x018f75b8, apr_pool_t * scratch_pool=0x018ec4c0)  Line 844 + 0x29 bytes C

  svn.exe!update_internal(long * result_rev=0x00000000, const char * local_abspath=0x018ec570, const char * anchor_abspath=0x0190d910, const svn_opt_revision_t * revision=0x0012f99c, svn_depth_t depth=svn_depth_unknown, int depth_is_sticky=0, int ignore_externals=0, int allow_unver_obstructions=0, int adds_as_modification=1, int innerupdate=0, int * timestamp_sleep=0x0012fad8, int notify_summary=1, svn_client_ctx_t * ctx=0x018c5410, apr_pool_t * pool=0x018ec4c0)  Line 406 + 0x59 bytes C

  svn.exe!svn_client__update_internal(long * result_rev=0x00000000, const char * local_abspath=0x018ec570, const svn_opt_revision_t * revision=0x0012fb94, svn_depth_t depth=svn_depth_unknown, int depth_is_sticky=1, int ignore_externals=0, int allow_unver_obstructions=0, int adds_as_modification=1, int make_parents=0, int innerupdate=0, int * timestamp_sleep=0x0012fad8, svn_client_ctx_t * ctx=0x018c5410, apr_pool_t * pool=0x018ec4c0)  Line 549 + 0x3b bytes C

  svn.exe!svn_client__checkout_internal(long * result_rev=0x00000000, const char * url=0x018ec500, const char * local_abspath=0x018ec570, const svn_opt_revision_t * peg_revision=0x0012fb7c, const svn_opt_revision_t * revision=0x0012fb94, const svn_client__ra_session_from_path_results * ra_cache=0x00000000, svn_depth_t depth=svn_depth_unknown, int ignore_externals=0, int allow_unver_obstructions=0, int innercheckout=0, int * timestamp_sleep=0x00000000, svn_client_ctx_t * ctx=0x018c5410, apr_pool_t * pool=0x018ec4c0)  Line 222 + 0x31 bytes C

  svn.exe!svn_client_checkout3(long * result_rev=0x00000000, const char * URL=0x018ec500, const char * path=0x018f7e70, const svn_opt_revision_t * peg_revision=0x0012fb7c, const svn_opt_revision_t * revision=0x0012fb94, svn_depth_t depth=svn_depth_unknown, int ignore_externals=0, int allow_unver_obstructions=0, svn_client_ctx_t * ctx=0x018c5410, apr_pool_t * pool=0x018ec4c0)  Line 260 + 0x33 bytes C

  svn.exe!svn_cl__checkout(apr_getopt_t * os=0x018c0228, void * baton=0x0012fd78, apr_pool_t * pool=0x018c0080)  Line 168 + 0x3a bytes C

  svn.exe!main(int argc=4, const char * * argv=0x018b1500)  Line 2573 + 0x1c bytes C

  svn.exe!__tmainCRTStartup()  Line 597 + 0x19 bytes C

  svn.exe!mainCRTStartup()  Line 414 C

In deflate_buckets.c line 248, the intput stream ctx->stream (wrapping dechunk, ssl decryption and socket) return APR_EOF when read. Since there is no data to inflate, and no data left in ctx->inflate_stream, serf_bucket_read at line 338 also return APR_EOF. 

With both no data to read from the socket, and all data inflated and returned to svn, I'd expect the APR_EOF is returned to svn, but that doesn't seem to happen. Instead, in deflate_buckets.c line 341 and further, the APR_EOF is translated to APR_SUCCESS and that is returned to svn. Which in turn tries to read again.

Digging a bit deeper, in dechunk_buckets.c:125, current state = STATE_CHUNK, ctx->body_left = 67033. On every read from the socket, len=0 bytes and status APR_EOF are returned. 

Question 1: why does the response bucket expect 67k more data, while nothing will be received anymore of the socket.

Question 2: even in the case of the server cutting of the response, why is APR_EOF ignored in deflate_buckets.c resulting in the endless loop.

Lieven