Traffic Server
  1. Traffic Server
  2. TS-871

Subversion (1.7) with serf fails with ATS in forward and reverse proxy mode

    Details

    • Type: Bug Bug
    • Status: Patch Available
    • Priority: Major Major
    • Resolution: Unresolved
    • Affects Version/s: 3.0.0
    • Fix Version/s: 6.0.0
    • Component/s: HTTP
    • Labels:
      None

      Description

      When accessing a remote subversion repository via http or https with svn 1.7, it will currently timeout:

      igalic@tynix ~/src/asf % svn co http://svn.apache.org/repos/asf/trafficserver/plugins/stats_over_http/
      svn: E020014: Unable to connect to a repository at URL 'http://svn.apache.org/repos/asf/trafficserver/plugins/stats_over_http'
      svn: E020014: Unspecified error message: 504 Connection Timed Out
      1 igalic@tynix ~/src/asf %
      

      I have started traffic_server -Thttp and captured the output, which I'm attaching.
      There's also a capture from the network.

      1. TS-871-20121107.diff
        6 kB
        Ben Reser
      2. TS-871.diff
        8 kB
        Leif Hedstrom
      3. stats.diff
        1 kB
        Leif Hedstrom
      4. revats_Thttp.debug.notime.txt
        26 kB
        Igor Galić
      5. serf_revproxy.cap
        2 kB
        Igor Galić
      6. revats_Thttp.debug.txt
        45 kB
        Igor Galić
      7. ats_Thttp.debug.notime.txt
        26 kB
        Igor Galić
      8. serf_proxy.cap
        2 kB
        Igor Galić
      9. ats_Thttp.debug.txt
        45 kB
        Igor Galić

        Issue Links

          Activity

          Leif Hedstrom made changes -
          Fix Version/s 6.0.0 [ 12324897 ]
          Fix Version/s sometime [ 12316277 ]
          Hide
          Bryan Call added a comment - - edited

          Leif Hedstrom Can you test again and see if it works with subversion?

          Show
          Bryan Call added a comment - - edited Leif Hedstrom Can you test again and see if it works with subversion?
          Bryan Call made changes -
          Assignee Leif Hedstrom [ zwoop ]
          Leif Hedstrom made changes -
          Fix Version/s sometime [ 12316277 ]
          Fix Version/s 6.0.0 [ 12324897 ]
          Leif Hedstrom made changes -
          Assignee Bryan Call [ bcall ]
          Leif Hedstrom made changes -
          Fix Version/s 6.0.0 [ 12324897 ]
          Fix Version/s 5.0.0 [ 12324893 ]
          Leif Hedstrom made changes -
          Fix Version/s 5.0.0 [ 12324893 ]
          Fix Version/s 3.5.2 [ 12324127 ]
          Show
          Leif Hedstrom added a comment - Moving to 5.0.0 as per https://cwiki.apache.org/confluence/display/TS/New+Release+Processes
          Leif Hedstrom made changes -
          Fix Version/s 3.5.2 [ 12324127 ]
          Fix Version/s 3.5.1 [ 12324126 ]
          Leif Hedstrom made changes -
          Fix Version/s 3.5.1 [ 12324126 ]
          Fix Version/s 3.5.0 [ 12324125 ]
          Leif Hedstrom made changes -
          Fix Version/s 3.5.0 [ 12324125 ]
          Fix Version/s 3.3.3 [ 12322479 ]
          Hide
          Leif Hedstrom added a comment -

          Yeah, I think there's more work on this. I have a test setup, I can fiddle with it again after vacation.

          Show
          Leif Hedstrom added a comment - Yeah, I think there's more work on this. I have a test setup, I can fiddle with it again after vacation.
          Hide
          James Peach added a comment -

          TS-1627 was committed. Is this still an issue? Is anyone able to set up a test for this?

          Show
          James Peach added a comment - TS-1627 was committed. Is this still an issue? Is anyone able to set up a test for this?
          Leif Hedstrom made changes -
          Fix Version/s 3.3.3 [ 12322479 ]
          Fix Version/s 3.3.2 [ 12321745 ]
          Leif Hedstrom made changes -
          Fix Version/s 3.3.2 [ 12321745 ]
          Fix Version/s 3.3.1 [ 12321686 ]
          Hide
          Leif Hedstrom added a comment -

          Moving remaining bugs to 3.3.2.

          Show
          Leif Hedstrom added a comment - Moving remaining bugs to 3.3.2.
          Hide
          Leif Hedstrom added a comment -

          If fixing the payload issues doesn't resolve all the Subversion problems, please move this bug out to 3.3.2 or 3.3.3. Last I tested, fixing the payload issue was not quite enough.

          Show
          Leif Hedstrom added a comment - If fixing the payload issues doesn't resolve all the Subversion problems, please move this bug out to 3.3.2 or 3.3.3. Last I tested, fixing the payload issue was not quite enough.
          Leif Hedstrom made changes -
          Assignee Leif Hedstrom [ zwoop ] Bryan Call [ bcall ]
          Hide
          Leif Hedstrom added a comment -

          Also see TS-1627. To test this, edit .subversion/servers, and add e.g.

          [global]
          http-proxy-host = localhost
          http-proxy-port = 80

          Show
          Leif Hedstrom added a comment - Also see TS-1627 . To test this, edit .subversion/servers, and add e.g. [global] http-proxy-host = localhost http-proxy-port = 80
          Hide
          Uri Shachar added a comment -

          I've created a general CR for request payload handling + added a patch

          Show
          Uri Shachar added a comment - I've created a general CR for request payload handling + added a patch
          Uri Shachar made changes -
          Link This issue is related to TS-1627 [ TS-1627 ]
          James Peach made changes -
          Link This issue is related to TS-1604 [ TS-1604 ]
          Ben Reser made changes -
          Attachment TS-871-20121107.diff [ 12552449 ]
          Hide
          Ben Reser added a comment - - edited

          I took a look at the patch Leif had attached here. It did not apply cleanly so I worked through the issues. In the process I removed some unnecessary whitespace changes and a change of a variable to a static that don't really seem to be related to this issue. I'm attaching this updated patch as TS-871-20121107.diff.

          This patch is able to function with Subversion 1.7 using Neon. However it will not work with Subversion 1.8 which can only use serf (and probably won't work with Subversion clients using serf in general though I haven't tested that).

          In verifying that the patch works I modified Subversion's test suite to run through a forward TS. All tests pass (again with 1.7 using neon).

          Now that I've looked at the code I can make one big observation. TS (without any patch) assumes that only POST and PUT can have request bodies. It also rejects any method it does not know e.g. REPORT.

          It's not clear what the problem is with serf but for some reason the REPORT response body gets cut off when I do a checkout. It's cut off in both the response back to TS and to the Subversion client. So it'll take some more digging to understand what the problem is. It's made more complicated by the fact that 1.8 is using pipelining.

          Show
          Ben Reser added a comment - - edited I took a look at the patch Leif had attached here. It did not apply cleanly so I worked through the issues. In the process I removed some unnecessary whitespace changes and a change of a variable to a static that don't really seem to be related to this issue. I'm attaching this updated patch as TS-871 -20121107.diff. This patch is able to function with Subversion 1.7 using Neon. However it will not work with Subversion 1.8 which can only use serf (and probably won't work with Subversion clients using serf in general though I haven't tested that). In verifying that the patch works I modified Subversion's test suite to run through a forward TS. All tests pass (again with 1.7 using neon). Now that I've looked at the code I can make one big observation. TS (without any patch) assumes that only POST and PUT can have request bodies. It also rejects any method it does not know e.g. REPORT. It's not clear what the problem is with serf but for some reason the REPORT response body gets cut off when I do a checkout. It's cut off in both the response back to TS and to the Subversion client. So it'll take some more digging to understand what the problem is. It's made more complicated by the fact that 1.8 is using pipelining.
          Hide
          Igor Galić added a comment -

          I was unable to repro the issue Ben reported here, reason being: I went over https:// while he went over http://

          Here's what happens with an svn co:

          igalic@tynix ~/src/asf % svn co http://svn.apache.org/repos/asf/subversion/trunk subversion.snew
          svn: E175002: Unable to connect to a repository at URL 'http://svn.apache.org/repos/asf/subversion/trunk'
          svn: E175002: Server sent unexpected return value (504 Connection Timed Out) in response to OPTIONS request for 'http://svn.apache.org/repos/asf/subversion/trunk'
          1 igalic@tynix ~/src/asf %
          

          On the traffic_server side we have:

          [Nov  6 23:37:46.767] Server {0x7fc78400f840} DEBUG: (http_init) proxy.config.http.redirection_enabled = 0
          [Nov  6 23:37:46.767] Server {0x7fc78400f840} DEBUG: (http_init) proxy.config.http.number_of_redirections = 1
          [Nov  6 23:37:46.767] Server {0x7fc78400f840} DEBUG: (http_init) proxy.config.http.post_copy_size = 2048
          [Nov  6 23:37:46.769] Server {0x7fc78400f840} DEBUG: (http_aeua) [HttpConfig::init_aeua_filter] - Config: "/opt/ats-trunk/etc/trafficserver/ae_ua.config"
          [Nov  6 23:37:46.769] Server {0x7fc78400f840} DEBUG: (http_aeua) [HttpConfig::init_aeua_filter] - Opening config "/opt/ats-trunk/etc/trafficserver/ae_ua.config"
          [Nov  6 23:37:46.769] Server {0x7fc78400f840} DEBUG: (http_aeua) [HttpConfig::init_aeua_filter] - Added 0 REGEXP filters
          [Nov  6 23:37:46.769] Server {0x7fc78400f840} DEBUG: (http_aeua) [init_http_aeua_filter] - Total loaded 0 REGEXP for Accept-Enconding/User-Agent filtering
          [Nov  6 23:37:46.769] Server {0x7fc78400f840} WARNING: connection throttle too high, 30000 (throttle) + 192 (internal use) > 4096 (file descriptor limit), using throttle of 3904
          [Nov  6 23:37:46.770] Server {0x7fc78400f840} NOTE: cache clustering disabled
          [Nov  6 23:37:46.782] Server {0x7fc78400f840} NOTE: cache clustering disabled
          [Nov  6 23:37:46.796] Server {0x7fc78400f840} NOTE: logging initialized[11], logging_mode = 3
          [Nov  6 23:37:46.808] Server {0x7fc78400f840} NOTE: traffic server running
          [Nov  6 23:37:46.877] Server {0x7fc78400f840} NOTE: cache enabled
          [Nov  6 23:37:52.855] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpAccept:mainEvent 0x7fc774016600] accepted connection from 192.168.122.1:38202 transport type = 0
          [Nov  6 23:37:52.856] Server {0x7fc78400f840} DEBUG: (http_cs) [0] session born, netvc 0x7fc774016600
          [Nov  6 23:37:52.873] Server {0x7fc78400f840} DEBUG: (http_cs) [0] using accept inactivity timeout [120 seconds]
          [Nov  6 23:37:52.873] Server {0x7fc78400f840} DEBUG: (http_cs) [0] Starting transaction 1 using sm [0]
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_READ_READY]
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY]
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) [0] done parsing client request header
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http_trans) START HttpTransact::ModifyRequest
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http_trans) [ink_cluster_time] local: 1352241472, highest_delta: 0, cluster: 1352241472
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http_trans) END HttpTransact::ModifyRequest
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http_trans) Next action HTTP_API_READ_REQUEST_HDR; HttpTransact::StartRemapRequest
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: STATE_UNDEFINED -> API_READ_REQUEST_HDR
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http_trans) START HttpTransact::StartRemapRequest
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http_trans) Before Remapping:
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) HTTP_HEADER 0x7fc77a89f898: [T: 3, L:   48, OBJFLAGS: 0]  
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) [TYPE: REQ, V: 10001, URL: 0x7fc77a89fb18, METHOD: "OPTIONS", METHOD_LEN: 7, FIELDS: 0x7fc77a89f8c8]
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) URL 0x7fc77a89fb18: [T: 2, L:  128, OBJFLAGS: 0]  
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) [URLTYPE: 1, SWKSIDX: 94,
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) 	SCHEME: "http", SCHEME_LEN: 4,
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) 	USER: "", USER_LEN: 0,
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) 	PASSWORD: "", PASSWORD_LEN: 0,
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) 	HOST: "svn.apache.org", HOST_LEN: 14,
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) 	PORT: "", PORT_LEN: 0, PORT_NUM: 0
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) 	PATH: "repos/asf/subversion/trunk", PATH_LEN: 26,
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) 	PARAMS: "", PARAMS_LEN: 0,
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) 	QUERY: "", QUERY_LEN: 0,
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) 	FRAGMENT: "", FRAGMENT_LEN: 0]
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) MIME_HEADER 0x7fc77a89f8c8: [T: 4, L:  592, OBJFLAGS: 0]  
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) 
          	[PBITS: 0x0009000001044804, SLACC: 0xFFFFF5FFFFF49FF1FFFFFFFFFFF0F2FF, HEADBLK: 0x7fc77a89f908, TAILBLK: 0x7fc77a89f908]
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) 	[CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) FIELD_BLOCK 0x7fc77a89f908: [T: 5, L:  528, OBJFLAGS: 0]  
          [Nov  6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) [FREETOP: 11, NEXTBLK: (nil)]
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 0 (0x7fc77a89f918), LIVE    
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "SVN/1.7.7 neon/0.29.6", V_LEN: 21, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 35, F: 1]
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 1 (0x7fc77a89f938), LIVE    
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "Connection", N_LEN: 10, N_IDX: 12, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "TE", V_LEN: 2, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 16, F: 1]
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 2 (0x7fc77a89f958), LIVE    
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "TE", N_LEN: 2, N_IDX: 121, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "trailers", V_LEN: 8, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 14, F: 1]
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 3 (0x7fc77a89f978), LIVE    
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "Host", N_LEN: 4, N_IDX: 30, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "svn.apache.org", V_LEN: 14, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 22, F: 1]
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 4 (0x7fc77a89f998), LIVE    
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "Content-Type", N_LEN: 12, N_IDX: 20, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "text/xml", V_LEN: 8, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 24, F: 1]
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 5 (0x7fc77a89f9b8), LIVE    
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "Accept-Encoding", N_LEN: 15, N_IDX: 1, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "gzip", V_LEN: 4, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: 0x7fc77a89fa58, RAW: 1, RAWLEN: 23, F: 1]
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 6 (0x7fc77a89f9d8), LIVE    
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "DAV", N_LEN: 3, N_IDX: -1, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "http://subversion.tigris.org/xmlns/dav/svn/depth", V_LEN: 48, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: 0x7fc77a89f9f8, RAW: 1, RAWLEN: 55, F: 1]
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 7 (0x7fc77a89f9f8), LIVE    
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "DAV", N_LEN: 3, N_IDX: -1, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "http://subversion.tigris.org/xmlns/dav/svn/mergeinfo", V_LEN: 52, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: 0x7fc77a89fa18, RAW: 1, RAWLEN: 59, F: 0]
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 8 (0x7fc77a89fa18), LIVE    
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "DAV", N_LEN: 3, N_IDX: -1, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "http://subversion.tigris.org/xmlns/dav/svn/log-revprops", V_LEN: 55, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 62, F: 0]
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 9 (0x7fc77a89fa38), LIVE    
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "Content-Length", N_LEN: 14, N_IDX: 16, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "104", V_LEN: 3, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 21, F: 1]
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 	SLOT #10 (0x7fc77a89fa58), LIVE    
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "Accept-Encoding", N_LEN: 15, N_IDX: 1, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "gzip", V_LEN: 4, 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 23, F: 0]
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http_trans) END HttpTransact::StartRemapRequest
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http_trans) Next action HTTP_API_PRE_REMAP; HttpTransact::PerformRemap
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: API_READ_REQUEST_HDR -> HTTP_API_PRE_REMAP
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http_trans) Inside PerformRemap
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http_trans) Next action HTTP_REMAP_REQUEST; HttpTransact::EndRemapRequest
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: HTTP_API_PRE_REMAP -> HTTP_REMAP_REQUEST
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpSM::do_remap_request] Remapping request
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http_trans) START HttpTransact::EndRemapRequest
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http_trans) EndRemapRequest host is svn.apache.org
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http_trans) After Remapping:
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) HTTP_HEADER 0x7fc77a89f898: [T: 3, L:   48, OBJFLAGS: 0]  
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [TYPE: REQ, V: 10001, URL: 0x7fc77a89fb18, METHOD: "OPTIONS", METHOD_LEN: 7, FIELDS: 0x7fc77a89f8c8]
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) URL 0x7fc77a89fb18: [T: 2, L:  128, OBJFLAGS: 0]  
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [URLTYPE: 1, SWKSIDX: 94,
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 	SCHEME: "http", SCHEME_LEN: 4,
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 	USER: "", USER_LEN: 0,
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 	PASSWORD: "", PASSWORD_LEN: 0,
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 	HOST: "svn.apache.org", HOST_LEN: 14,
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 	PORT: "", PORT_LEN: 0, PORT_NUM: 0
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 	PATH: "repos/asf/subversion/trunk", PATH_LEN: 26,
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 	PARAMS: "", PARAMS_LEN: 0,
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 	QUERY: "", QUERY_LEN: 0,
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 	FRAGMENT: "", FRAGMENT_LEN: 0]
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) MIME_HEADER 0x7fc77a89f8c8: [T: 4, L:  592, OBJFLAGS: 0]  
          [Nov  6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) 
          	[PBITS: 0x0009000001044804, SLACC: 0xFFFFF5FFFFF49FF1FFFFFFFFFFF0F2FF, HEADBLK: 0x7fc77a89f908, TAILBLK: 0x7fc77a89f908]
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 	[CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) FIELD_BLOCK 0x7fc77a89f908: [T: 5, L:  528, OBJFLAGS: 0]  
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [FREETOP: 11, NEXTBLK: (nil)]
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 0 (0x7fc77a89f918), LIVE    
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "SVN/1.7.7 neon/0.29.6", V_LEN: 21, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 35, F: 1]
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 1 (0x7fc77a89f938), LIVE    
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "Connection", N_LEN: 10, N_IDX: 12, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "TE", V_LEN: 2, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 16, F: 1]
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 2 (0x7fc77a89f958), LIVE    
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "TE", N_LEN: 2, N_IDX: 121, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "trailers", V_LEN: 8, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 14, F: 1]
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 3 (0x7fc77a89f978), LIVE    
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "Host", N_LEN: 4, N_IDX: 30, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "svn.apache.org", V_LEN: 14, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 22, F: 1]
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 4 (0x7fc77a89f998), LIVE    
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "Content-Type", N_LEN: 12, N_IDX: 20, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "text/xml", V_LEN: 8, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 24, F: 1]
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 5 (0x7fc77a89f9b8), LIVE    
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "Accept-Encoding", N_LEN: 15, N_IDX: 1, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "gzip", V_LEN: 4, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: 0x7fc77a89fa58, RAW: 1, RAWLEN: 23, F: 1]
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 6 (0x7fc77a89f9d8), LIVE    
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "DAV", N_LEN: 3, N_IDX: -1, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "http://subversion.tigris.org/xmlns/dav/svn/depth", V_LEN: 48, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: 0x7fc77a89f9f8, RAW: 1, RAWLEN: 55, F: 1]
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 7 (0x7fc77a89f9f8), LIVE    
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "DAV", N_LEN: 3, N_IDX: -1, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "http://subversion.tigris.org/xmlns/dav/svn/mergeinfo", V_LEN: 52, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: 0x7fc77a89fa18, RAW: 1, RAWLEN: 59, F: 0]
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 8 (0x7fc77a89fa18), LIVE    
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "DAV", N_LEN: 3, N_IDX: -1, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "http://subversion.tigris.org/xmlns/dav/svn/log-revprops", V_LEN: 55, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 62, F: 0]
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 9 (0x7fc77a89fa38), LIVE    
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "Content-Length", N_LEN: 14, N_IDX: 16, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "104", V_LEN: 3, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 21, F: 1]
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 	SLOT #10 (0x7fc77a89fa58), LIVE    
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "Accept-Encoding", N_LEN: 15, N_IDX: 1, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "gzip", V_LEN: 4, 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 23, F: 0]
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http_trans) END HttpTransact::EndRemapRequest
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http_trans) Next action HTTP_API_POST_REMAP; HttpTransact::HandleRequest
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: HTTP_REMAP_REQUEST -> HTTP_API_POST_REMAP
          [Nov  6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http_trans) START HttpTransact::HandleRequest
          [Nov  6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http_trans) [is_request_valid]no request header errors
          [Nov  6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleRequest] request valid.
          [Nov  6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) HTTP_HEADER 0x7fc77a89f898: [T: 3, L:   48, OBJFLAGS: 0]  
          [Nov  6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) [TYPE: REQ, V: 10001, URL: 0x7fc77a89fb18, METHOD: "OPTIONS", METHOD_LEN: 7, FIELDS: 0x7fc77a89f8c8]
          [Nov  6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) URL 0x7fc77a89fb18: [T: 2, L:  128, OBJFLAGS: 0]  
          [Nov  6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) [URLTYPE: 1, SWKSIDX: 94,
          [Nov  6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) 	SCHEME: "http", SCHEME_LEN: 4,
          [Nov  6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) 	USER: "", USER_LEN: 0,
          [Nov  6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) 	PASSWORD: "", PASSWORD_LEN: 0,
          [Nov  6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) 	HOST: "svn.apache.org", HOST_LEN: 14,
          [Nov  6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) 	PORT: "", PORT_LEN: 0, PORT_NUM: 0
          [Nov  6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) 	PATH: "repos/asf/subversion/trunk", PATH_LEN: 26,
          [Nov  6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) 	PARAMS: "", PARAMS_LEN: 0,
          [Nov  6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) 	QUERY: "", QUERY_LEN: 0,
          [Nov  6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) 	FRAGMENT: "", FRAGMENT_LEN: 0]
          [Nov  6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) MIME_HEADER 0x7fc77a89f8c8: [T: 4, L:  592, OBJFLAGS: 0]  
          [Nov  6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) 
          	[PBITS: 0x0009000001044804, SLACC: 0xFFFFF5FFFFF49FF1FFFFFFFFFFF0F2FF, HEADBLK: 0x7fc77a89f908, TAILBLK: 0x7fc77a89f908]
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) 	[CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) FIELD_BLOCK 0x7fc77a89f908: [T: 5, L:  528, OBJFLAGS: 0]  
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [FREETOP: 11, NEXTBLK: (nil)]
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 0 (0x7fc77a89f918), LIVE    
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64, 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) V: "SVN/1.7.7 neon/0.29.6", V_LEN: 21, 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 35, F: 1]
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 1 (0x7fc77a89f938), LIVE    
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [N: "Connection", N_LEN: 10, N_IDX: 12, 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) V: "TE", V_LEN: 2, 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 16, F: 1]
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 2 (0x7fc77a89f958), LIVE    
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [N: "TE", N_LEN: 2, N_IDX: 121, 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) V: "trailers", V_LEN: 8, 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 14, F: 1]
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 3 (0x7fc77a89f978), LIVE    
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [N: "Host", N_LEN: 4, N_IDX: 30, 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) V: "svn.apache.org", V_LEN: 14, 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 22, F: 1]
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 4 (0x7fc77a89f998), LIVE    
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [N: "Content-Type", N_LEN: 12, N_IDX: 20, 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) V: "text/xml", V_LEN: 8, 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 24, F: 1]
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 5 (0x7fc77a89f9b8), LIVE    
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [N: "Accept-Encoding", N_LEN: 15, N_IDX: 1, 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) V: "gzip", V_LEN: 4, 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: 0x7fc77a89fa58, RAW: 1, RAWLEN: 23, F: 1]
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 6 (0x7fc77a89f9d8), LIVE    
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [N: "DAV", N_LEN: 3, N_IDX: -1, 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) V: "http://subversion.tigris.org/xmlns/dav/svn/depth", V_LEN: 48, 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: 0x7fc77a89f9f8, RAW: 1, RAWLEN: 55, F: 1]
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 7 (0x7fc77a89f9f8), LIVE    
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [N: "DAV", N_LEN: 3, N_IDX: -1, 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) V: "http://subversion.tigris.org/xmlns/dav/svn/mergeinfo", V_LEN: 52, 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: 0x7fc77a89fa18, RAW: 1, RAWLEN: 59, F: 0]
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 8 (0x7fc77a89fa18), LIVE    
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [N: "DAV", N_LEN: 3, N_IDX: -1, 
          [Nov  6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) V: "http://subversion.tigris.org/xmlns/dav/svn/log-revprops", V_LEN: 55, 
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 62, F: 0]
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) 	SLOT # 9 (0x7fc77a89fa38), LIVE    
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) [N: "Content-Length", N_LEN: 14, N_IDX: 16, 
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) V: "104", V_LEN: 3, 
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 21, F: 1]
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) 
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) 	SLOT #10 (0x7fc77a89fa58), LIVE    
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) [N: "Accept-Encoding", N_LEN: 15, N_IDX: 1, 
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) V: "gzip", V_LEN: 4, 
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 23, F: 0]
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) 
          +++++++++ Incoming Request +++++++++
          -- State Machine Id: 0
          OPTIONS http://svn.apache.org/repos/asf/subversion/trunk HTTP/1.1
          User-Agent: SVN/1.7.7 neon/0.29.6
          Connection: TE
          TE: trailers
          Host: svn.apache.org
          Content-Type: text/xml
          Accept-Encoding: gzip
          DAV: http://subversion.tigris.org/xmlns/dav/svn/depth
          DAV: http://subversion.tigris.org/xmlns/dav/svn/mergeinfo
          DAV: http://subversion.tigris.org/xmlns/dav/svn/log-revprops
          Content-Length: 104
          Accept-Encoding: gzip
          
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_trans) [DecideCacheLookup] Will NOT do cache lookup.
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_seq) [DecideCacheLookup] Will NOT do cache lookup
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_trans) Next action HTTP_API_CACHE_LOOKUP_COMPLETE; CallOSDNSLookup
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: HTTP_API_POST_REMAP -> API_CACHE_LOOKUP_COMPLETE
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_trans) Next action DNS_LOOKUP; OSDNSLookup
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: API_CACHE_LOOKUP_COMPLETE -> DNS_LOOKUP
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpStateMachineGet::do_hostdb_lookup] Doing DNS Lookup
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_trans) [HttpTransact::OSDNSLookup] This was attempt 1
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::OSDNSLookup] DNS Lookup successful
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_trans) [OSDNSLookup] DNS lookup for O.S. successful IP: 160.45.251.2
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_trans) Next action HttpTransact::HTTP_API_OS_DNS; LookupSkipOpenServer
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: DNS_LOOKUP -> API_OS_DNS
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_trans) request not cacheable, so bypass parent
          [Nov  6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_trans) client_ip_set = 0
          [Nov  6 23:37:52.885] Server {0x7fc78400f840} DEBUG: (http_trans) inserted request header 'Client-ip: 192.168.122.1'
          [Nov  6 23:37:52.885] Server {0x7fc78400f840} DEBUG: (http_trans) [add_client_ip_to_outgoing_request] Appended connecting client's (192.168.122.1) to the X-Forwards header
          [Nov  6 23:37:52.885] Server {0x7fc78400f840} DEBUG: (http_trans) [ink_cluster_time] local: 1352241472, highest_delta: 0, cluster: 1352241472
          [Nov  6 23:37:52.885] Server {0x7fc78400f840} DEBUG: (http_trans) [build_request] request_sent_time: 1352241472
          +++++++++ Proxy's Request +++++++++
          -- State Machine Id: 0
          OPTIONS /repos/asf/subversion/trunk HTTP/1.1
          User-Agent: SVN/1.7.7 neon/0.29.6
          Host: svn.apache.org
          Content-Type: text/xml
          Accept-Encoding: gzip
          DAV: http://subversion.tigris.org/xmlns/dav/svn/depth
          DAV: http://subversion.tigris.org/xmlns/dav/svn/mergeinfo
          DAV: http://subversion.tigris.org/xmlns/dav/svn/log-revprops
          Content-Length: 104
          Accept-Encoding: gzip
          Client-ip: 192.168.122.1
          X-Forwarded-For: 192.168.122.1
          Via: http/1.1 tynix[FE80000000000000B6749FFFFE9DDA61] (ApacheTrafficServer/3.2.3 [uSc s f p eN:tMc  i p s ])
          
          [Nov  6 23:37:52.885] Server {0x7fc78400f840} DEBUG: (http_trans) Next action next; HttpTransact::HandleResponse
          [Nov  6 23:37:52.885] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: API_OS_DNS -> ORIGIN_SERVER_OPEN
          [Nov  6 23:37:52.885] Server {0x7fc78400f840} DEBUG: (http_track) entered inside do_http_server_open
          [Nov  6 23:37:52.885] Server {0x7fc78400f840} DEBUG: (http) [0] open connection to svn.apache.org: 160.45.251.2:80
          [Nov  6 23:37:52.885] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpSM::do_http_server_open] Sending request to server
          [Nov  6 23:37:52.885] Server {0x7fc78400f840} DEBUG: (http) calling netProcessor.connect_re
          [Nov  6 23:37:52.886] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, NET_EVENT_OPEN]
          [Nov  6 23:37:52.886] Server {0x7fc78400f840} DEBUG: (http_track) entered inside state_http_server_open
          [Nov  6 23:37:52.886] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_http_server_open, NET_EVENT_OPEN]
          [Nov  6 23:37:52.886] Server {0x7fc78400f840} DEBUG: (http_ss) [0] session born, netvc 0x7fc774015dc0
          [Nov  6 23:37:52.917] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE]
          [Nov  6 23:37:52.917] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE]
          [Nov  6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT]
          [Nov  6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_read_server_response_header, VC_EVENT_INACTIVITY_TIMEOUT]
          [Nov  6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_ss) [0] session closed
          [Nov  6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::handle_server_setup_error, VC_EVENT_NONE]
          [Nov  6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_trans) [HttpTransact::HandleResponse]
          [Nov  6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response received
          [Nov  6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_trans) [ink_cluster_time] local: 1352241503, highest_delta: 0, cluster: 1352241503
          [Nov  6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_trans) [HandleResponse] response_received_time: 1352241503
          +++++++++ Incoming O.S. Response +++++++++
          -- State Machine Id: 0
          HTTP/0.9 0 
          
          [Nov  6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response not valid
          [Nov  6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] (hrfs)
          [Nov  6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_trans) [1] failed to connect [6] to 160.45.251.2
          [Nov  6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_trans) [retry_server_connection_not_open] attempts now: 2, max: 6
          [Nov  6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] Error. Retrying...
          [Nov  6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: ORIGIN_SERVER_OPEN -> ORIGIN_SERVER_OPEN
          [Nov  6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_track) entered inside do_http_server_open
          [Nov  6 23:38:23.723] Server {0x7fc78400f840} DEBUG: (http) [0] open connection to svn.apache.org: 160.45.251.2:80
          [Nov  6 23:38:23.723] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpSM::do_http_server_open] Sending request to server
          [Nov  6 23:38:23.723] Server {0x7fc78400f840} DEBUG: (http) calling netProcessor.connect_re
          [Nov  6 23:38:23.723] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, NET_EVENT_OPEN]
          [Nov  6 23:38:23.723] Server {0x7fc78400f840} DEBUG: (http_track) entered inside state_http_server_open
          [Nov  6 23:38:23.723] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_http_server_open, NET_EVENT_OPEN]
          [Nov  6 23:38:23.723] Server {0x7fc78400f840} DEBUG: (http_ss) [1] session born, netvc 0x7fc774015b00
          [Nov  6 23:38:23.773] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE]
          [Nov  6 23:38:23.773] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE]
          [Nov  6 23:38:54.658] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT]
          [Nov  6 23:38:54.658] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_read_server_response_header, VC_EVENT_INACTIVITY_TIMEOUT]
          [Nov  6 23:38:54.658] Server {0x7fc78400f840} DEBUG: (http_ss) [1] session closed
          [Nov  6 23:38:54.658] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::handle_server_setup_error, VC_EVENT_NONE]
          [Nov  6 23:38:54.658] Server {0x7fc78400f840} DEBUG: (http_trans) [HttpTransact::HandleResponse]
          [Nov  6 23:38:54.658] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response received
          [Nov  6 23:38:54.658] Server {0x7fc78400f840} DEBUG: (http_trans) [ink_cluster_time] local: 1352241534, highest_delta: 0, cluster: 1352241534
          [Nov  6 23:38:54.658] Server {0x7fc78400f840} DEBUG: (http_trans) [HandleResponse] response_received_time: 1352241534
          +++++++++ Incoming O.S. Response +++++++++
          -- State Machine Id: 0
          HTTP/0.9 0 
          
          [Nov  6 23:38:54.658] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response not valid
          [Nov  6 23:38:54.658] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] (hrfs)
          [Nov  6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http_trans) [2] failed to connect [6] to 160.45.251.2
          [Nov  6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http_trans) [retry_server_connection_not_open] attempts now: 3, max: 6
          [Nov  6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] Error. Retrying...
          [Nov  6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: ORIGIN_SERVER_OPEN -> ORIGIN_SERVER_OPEN
          [Nov  6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http_track) entered inside do_http_server_open
          [Nov  6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http) [0] open connection to svn.apache.org: 160.45.251.2:80
          [Nov  6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpSM::do_http_server_open] Sending request to server
          [Nov  6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http) calling netProcessor.connect_re
          [Nov  6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, NET_EVENT_OPEN]
          [Nov  6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http_track) entered inside state_http_server_open
          [Nov  6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_http_server_open, NET_EVENT_OPEN]
          [Nov  6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http_ss) [2] session born, netvc 0x7fc774015dc0
          [Nov  6 23:38:55.716] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE]
          [Nov  6 23:38:55.716] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE]
          [Nov  6 23:39:26.618] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT]
          [Nov  6 23:39:26.618] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_read_server_response_header, VC_EVENT_INACTIVITY_TIMEOUT]
          [Nov  6 23:39:26.618] Server {0x7fc78400f840} DEBUG: (http_ss) [2] session closed
          [Nov  6 23:39:26.618] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::handle_server_setup_error, VC_EVENT_NONE]
          [Nov  6 23:39:26.618] Server {0x7fc78400f840} DEBUG: (http_trans) [HttpTransact::HandleResponse]
          [Nov  6 23:39:26.618] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response received
          [Nov  6 23:39:26.618] Server {0x7fc78400f840} DEBUG: (http_trans) [ink_cluster_time] local: 1352241566, highest_delta: 0, cluster: 1352241566
          [Nov  6 23:39:26.618] Server {0x7fc78400f840} DEBUG: (http_trans) [HandleResponse] response_received_time: 1352241566
          +++++++++ Incoming O.S. Response +++++++++
          -- State Machine Id: 0
          HTTP/0.9 0 
          
          [Nov  6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response not valid
          [Nov  6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] (hrfs)
          [Nov  6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http_trans) [3] failed to connect [6] to 160.45.251.2
          [Nov  6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http_trans) [retry_server_connection_not_open] attempts now: 4, max: 6
          [Nov  6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] Error. Retrying...
          [Nov  6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: ORIGIN_SERVER_OPEN -> ORIGIN_SERVER_OPEN
          [Nov  6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http_track) entered inside do_http_server_open
          [Nov  6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http) [0] open connection to svn.apache.org: 160.45.251.2:80
          [Nov  6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpSM::do_http_server_open] Sending request to server
          [Nov  6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http) calling netProcessor.connect_re
          [Nov  6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, NET_EVENT_OPEN]
          [Nov  6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http_track) entered inside state_http_server_open
          [Nov  6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_http_server_open, NET_EVENT_OPEN]
          [Nov  6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http_ss) [3] session born, netvc 0x7fc774015b00
          [Nov  6 23:39:26.671] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE]
          [Nov  6 23:39:26.671] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE]
          [Nov  6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT]
          [Nov  6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_read_server_response_header, VC_EVENT_INACTIVITY_TIMEOUT]
          [Nov  6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_ss) [3] session closed
          [Nov  6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::handle_server_setup_error, VC_EVENT_NONE]
          [Nov  6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_trans) [HttpTransact::HandleResponse]
          [Nov  6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response received
          [Nov  6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_trans) [ink_cluster_time] local: 1352241597, highest_delta: 0, cluster: 1352241597
          [Nov  6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_trans) [HandleResponse] response_received_time: 1352241597
          +++++++++ Incoming O.S. Response +++++++++
          -- State Machine Id: 0
          HTTP/0.9 0 
          
          [Nov  6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response not valid
          [Nov  6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] (hrfs)
          [Nov  6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_trans) [4] failed to connect [6] to 160.45.251.2
          [Nov  6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_trans) [retry_server_connection_not_open] attempts now: 5, max: 6
          [Nov  6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] Error. Retrying...
          [Nov  6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: ORIGIN_SERVER_OPEN -> ORIGIN_SERVER_OPEN
          [Nov  6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_track) entered inside do_http_server_open
          [Nov  6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http) [0] open connection to svn.apache.org: 160.45.251.2:80
          [Nov  6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpSM::do_http_server_open] Sending request to server
          [Nov  6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http) calling netProcessor.connect_re
          [Nov  6 23:39:57.585] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, NET_EVENT_OPEN]
          [Nov  6 23:39:57.585] Server {0x7fc78400f840} DEBUG: (http_track) entered inside state_http_server_open
          [Nov  6 23:39:57.585] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_http_server_open, NET_EVENT_OPEN]
          [Nov  6 23:39:57.585] Server {0x7fc78400f840} DEBUG: (http_ss) [4] session born, netvc 0x7fc774015dc0
          [Nov  6 23:39:58.146] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE]
          [Nov  6 23:39:58.146] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE]
          [Nov  6 23:40:28.540] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT]
          [Nov  6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_read_server_response_header, VC_EVENT_INACTIVITY_TIMEOUT]
          [Nov  6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http_ss) [4] session closed
          [Nov  6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::handle_server_setup_error, VC_EVENT_NONE]
          [Nov  6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http_trans) [HttpTransact::HandleResponse]
          [Nov  6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response received
          [Nov  6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http_trans) [ink_cluster_time] local: 1352241628, highest_delta: 0, cluster: 1352241628
          [Nov  6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http_trans) [HandleResponse] response_received_time: 1352241628
          +++++++++ Incoming O.S. Response +++++++++
          -- State Machine Id: 0
          HTTP/0.9 0 
          
          [Nov  6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response not valid
          [Nov  6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] (hrfs)
          [Nov  6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http_trans) [5] failed to connect [6] to 160.45.251.2
          [Nov  6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http_trans) [retry_server_connection_not_open] attempts now: 6, max: 6
          [Nov  6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] Error. Retrying...
          [Nov  6 23:40:28.542] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: ORIGIN_SERVER_OPEN -> ORIGIN_SERVER_OPEN
          [Nov  6 23:40:28.542] Server {0x7fc78400f840} DEBUG: (http_track) entered inside do_http_server_open
          [Nov  6 23:40:28.542] Server {0x7fc78400f840} DEBUG: (http) [0] open connection to svn.apache.org: 160.45.251.2:80
          [Nov  6 23:40:28.542] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpSM::do_http_server_open] Sending request to server
          [Nov  6 23:40:28.542] Server {0x7fc78400f840} DEBUG: (http) calling netProcessor.connect_re
          [Nov  6 23:40:28.542] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, NET_EVENT_OPEN]
          [Nov  6 23:40:28.542] Server {0x7fc78400f840} DEBUG: (http_track) entered inside state_http_server_open
          [Nov  6 23:40:28.542] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_http_server_open, NET_EVENT_OPEN]
          [Nov  6 23:40:28.542] Server {0x7fc78400f840} DEBUG: (http_ss) [5] session born, netvc 0x7fc774015b00
          [Nov  6 23:40:28.885] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE]
          [Nov  6 23:40:28.886] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE]
          [Nov  6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT]
          [Nov  6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_read_server_response_header, VC_EVENT_INACTIVITY_TIMEOUT]
          [Nov  6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http_ss) [5] session closed
          [Nov  6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::handle_server_setup_error, VC_EVENT_NONE]
          [Nov  6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http_trans) [HttpTransact::HandleResponse]
          [Nov  6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response received
          [Nov  6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http_trans) [ink_cluster_time] local: 1352241659, highest_delta: 0, cluster: 1352241659
          [Nov  6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http_trans) [HandleResponse] response_received_time: 1352241659
          +++++++++ Incoming O.S. Response +++++++++
          -- State Machine Id: 0
          HTTP/0.9 0 
          
          [Nov  6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response not valid
          [Nov  6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] (hrfs)
          [Nov  6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] Error. No more retries.
          [Nov  6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_server_connection_not_open] (hscno)
          [Nov  6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::handle_server_connection_not_open] 
          [Nov  6 23:40:59.496] Server {0x7fc78400f840} DEBUG: (http_trans) [ink_cluster_time] local: 1352241659, highest_delta: 0, cluster: 1352241659
          [Nov  6 23:40:59.496] Server {0x7fc78400f840} DEBUG: (http) [0] hostdb update marking IP: 160.45.251.2:80 as down
          [Nov  6 23:40:59.496] Server {0x7fc78400f840} DEBUG: (http) server info = 160.45.251.2:80
          [Nov  6 23:40:59.496] Server {0x7fc78400f840} DEBUG: (http_trans) [WUTS code generation] Hit/Miss: 49, Log: 112, Hier: 106, Status: 800
          [Nov  6 23:40:59.496] Server {0x7fc78400f840} DEBUG: (http_trans) Adding Server: ATS/3.2.3
          +++++++++ Proxy's Response 2 +++++++++
          -- State Machine Id: 0
          HTTP/1.1 504 Connection Timed Out
          Date: Tue, 06 Nov 2012 22:40:59 GMT
          Connection: keep-alive
          Via: http/1.1 tynix (ApacheTrafficServer/3.2.3 [uSc sEf p eT:tMc  i p sF])
          Server: ATS/3.2.3
          
          [Nov  6 23:40:59.496] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: ORIGIN_SERVER_OPEN -> PROXY_SEND_ERROR_CACHE_NOOP
          [Nov  6 23:40:59.496] Server {0x7fc78400f840} DEBUG: (http_tunnel) [0] adding producer 'internal msg'
          [Nov  6 23:40:59.496] Server {0x7fc78400f840} DEBUG: (http_tunnel) [0] adding consumer 'user agent'
          [Nov  6 23:40:59.496] Server {0x7fc78400f840} DEBUG: (http_tunnel) tunnel_run started, p_arg is NULL
          [Nov  6 23:40:59.497] Server {0x7fc78400f840} DEBUG: (http_cs) tcp_init_cwnd_set 0
          [Nov  6 23:40:59.497] Server {0x7fc78400f840} DEBUG: (http_cs) desired TCP congestion window is 0
          [Nov  6 23:40:59.497] Server {0x7fc78400f840} DEBUG: (http_tunnel) [0] consumer_handler [user agent VC_EVENT_WRITE_COMPLETE]
          [Nov  6 23:40:59.497] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE]
          [Nov  6 23:40:59.497] Server {0x7fc78400f840} DEBUG: (http_cs) [0] session released by sm [0]
          [Nov  6 23:40:59.497] Server {0x7fc78400f840} DEBUG: (http_cs) [0] data already in buffer, starting new transaction
          [Nov  6 23:40:59.497] Server {0x7fc78400f840} DEBUG: (http_cs) [0] using accept inactivity timeout [120 seconds]
          [Nov  6 23:40:59.497] Server {0x7fc78400f840} DEBUG: (http_cs) [0] Starting transaction 2 using sm [1]
          [Nov  6 23:40:59.497] Server {0x7fc78400f840} DEBUG: (http) [1] [&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY]
          [Nov  6 23:40:59.497] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
          [Nov  6 23:40:59.498] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
          [Nov  6 23:40:59.498] Server {0x7fc78400f840} DEBUG: (http_redirect) [HttpTunnel::deallocate_postdata_copy_buffers]
          [Nov  6 23:40:59.498] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpStateMachineGet::update_stats] Logging transaction
          [Nov  6 23:40:59.498] Server {0x7fc78400f840} DEBUG: (http_trans) Adding new large stat block
          [Nov  6 23:40:59.498] Server {0x7fc78400f840} DEBUG: (http) [0] dellocating sm
          [Nov  6 23:40:59.498] Server {0x7fc78400f840} DEBUG: (http) [1] [HttpSM::main_handler, VC_EVENT_EOS]
          [Nov  6 23:40:59.498] Server {0x7fc78400f840} DEBUG: (http) [1] [&HttpSM::state_read_client_request_header, VC_EVENT_EOS]
          [Nov  6 23:40:59.498] Server {0x7fc78400f840} DEBUG: (http) [1] error parsing client request header
          [Nov  6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_trans) [BadRequest]parser marked request bad
          [Nov  6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_trans) [ink_cluster_time] local: 1352241659, highest_delta: 0, cluster: 1352241659
          [Nov  6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_trans) [WUTS code generation] Hit/Miss: 98, Log: 118, Hier: 49, Status: 806
          [Nov  6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_trans) Adding Server: ATS/3.2.3
          +++++++++ Proxy's Response 2 +++++++++
          -- State Machine Id: 1
          HTTP/1.1 400 Invalid HTTP Request
          Date: Tue, 06 Nov 2012 22:40:59 GMT
          Connection: close
          Via: http/1.1 tynix (ApacheTrafficServer/3.2.3 [uEc s f p eH:t c  i p s ])
          Server: ATS/3.2.3
          
          [Nov  6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_trans) Next action PROXY_SEND_ERROR_CACHE_NOOP; NULL
          [Nov  6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http) [1] State Transition: STATE_UNDEFINED -> PROXY_SEND_ERROR_CACHE_NOOP
          [Nov  6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_tunnel) [1] adding producer 'internal msg'
          [Nov  6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_tunnel) [1] adding consumer 'user agent'
          [Nov  6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_tunnel) tunnel_run started, p_arg is NULL
          [Nov  6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_cs) tcp_init_cwnd_set 1
          [Nov  6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_tunnel) [1] consumer_handler [user agent VC_EVENT_WRITE_COMPLETE]
          [Nov  6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http) [1] [&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE]
          [Nov  6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_cs) [0] session closed
          [Nov  6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_cs) [0] session destroy
          [Nov  6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http) [1] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
          [Nov  6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http) [1] [&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
          [Nov  6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_redirect) [HttpTunnel::deallocate_postdata_copy_buffers]
          [Nov  6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpStateMachineGet::update_stats] Logging transaction
          [Nov  6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http) [1] dellocating sm
          

          A number of things can be observed:

          The OPTIONS body is discarded, while the Content-Length is kept in tact. That seems rather odd behaviour to begin with.
          Next, the svn.apache.org server almost immediately answers with a 400, but we don't pass that on to the client.
          Instead we loop a number of times, then send the client a 504. This behaviour, again, seems rather weird.

          Show
          Igor Galić added a comment - I was unable to repro the issue Ben reported here, reason being: I went over https:// while he went over http:// Here's what happens with an svn co: igalic@tynix ~/src/asf % svn co http://svn.apache.org/repos/asf/subversion/trunk subversion.snew svn: E175002: Unable to connect to a repository at URL 'http://svn.apache.org/repos/asf/subversion/trunk' svn: E175002: Server sent unexpected return value (504 Connection Timed Out) in response to OPTIONS request for 'http://svn.apache.org/repos/asf/subversion/trunk' 1 igalic@tynix ~/src/asf % On the traffic_server side we have: [Nov 6 23:37:46.767] Server {0x7fc78400f840} DEBUG: (http_init) proxy.config.http.redirection_enabled = 0 [Nov 6 23:37:46.767] Server {0x7fc78400f840} DEBUG: (http_init) proxy.config.http.number_of_redirections = 1 [Nov 6 23:37:46.767] Server {0x7fc78400f840} DEBUG: (http_init) proxy.config.http.post_copy_size = 2048 [Nov 6 23:37:46.769] Server {0x7fc78400f840} DEBUG: (http_aeua) [HttpConfig::init_aeua_filter] - Config: "/opt/ats-trunk/etc/trafficserver/ae_ua.config" [Nov 6 23:37:46.769] Server {0x7fc78400f840} DEBUG: (http_aeua) [HttpConfig::init_aeua_filter] - Opening config "/opt/ats-trunk/etc/trafficserver/ae_ua.config" [Nov 6 23:37:46.769] Server {0x7fc78400f840} DEBUG: (http_aeua) [HttpConfig::init_aeua_filter] - Added 0 REGEXP filters [Nov 6 23:37:46.769] Server {0x7fc78400f840} DEBUG: (http_aeua) [init_http_aeua_filter] - Total loaded 0 REGEXP for Accept-Enconding/User-Agent filtering [Nov 6 23:37:46.769] Server {0x7fc78400f840} WARNING: connection throttle too high, 30000 (throttle) + 192 (internal use) > 4096 (file descriptor limit), using throttle of 3904 [Nov 6 23:37:46.770] Server {0x7fc78400f840} NOTE: cache clustering disabled [Nov 6 23:37:46.782] Server {0x7fc78400f840} NOTE: cache clustering disabled [Nov 6 23:37:46.796] Server {0x7fc78400f840} NOTE: logging initialized[11], logging_mode = 3 [Nov 6 23:37:46.808] Server {0x7fc78400f840} NOTE: traffic server running [Nov 6 23:37:46.877] Server {0x7fc78400f840} NOTE: cache enabled [Nov 6 23:37:52.855] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpAccept:mainEvent 0x7fc774016600] accepted connection from 192.168.122.1:38202 transport type = 0 [Nov 6 23:37:52.856] Server {0x7fc78400f840} DEBUG: (http_cs) [0] session born, netvc 0x7fc774016600 [Nov 6 23:37:52.873] Server {0x7fc78400f840} DEBUG: (http_cs) [0] using accept inactivity timeout [120 seconds] [Nov 6 23:37:52.873] Server {0x7fc78400f840} DEBUG: (http_cs) [0] Starting transaction 1 using sm [0] [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_READ_READY] [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY] [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) [0] done parsing client request header [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http_trans) START HttpTransact::ModifyRequest [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http_trans) [ink_cluster_time] local: 1352241472, highest_delta: 0, cluster: 1352241472 [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http_trans) END HttpTransact::ModifyRequest [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http_trans) Next action HTTP_API_READ_REQUEST_HDR; HttpTransact::StartRemapRequest [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: STATE_UNDEFINED -> API_READ_REQUEST_HDR [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http_trans) START HttpTransact::StartRemapRequest [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http_trans) Before Remapping: [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) HTTP_HEADER 0x7fc77a89f898: [T: 3, L: 48, OBJFLAGS: 0] [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) [TYPE: REQ, V: 10001, URL: 0x7fc77a89fb18, METHOD: "OPTIONS", METHOD_LEN: 7, FIELDS: 0x7fc77a89f8c8] [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) URL 0x7fc77a89fb18: [T: 2, L: 128, OBJFLAGS: 0] [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) [URLTYPE: 1, SWKSIDX: 94, [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) SCHEME: "http", SCHEME_LEN: 4, [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) USER: "", USER_LEN: 0, [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) PASSWORD: "", PASSWORD_LEN: 0, [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) HOST: "svn.apache.org", HOST_LEN: 14, [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) PORT: "", PORT_LEN: 0, PORT_NUM: 0 [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) PATH: "repos/asf/subversion/trunk", PATH_LEN: 26, [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) PARAMS: "", PARAMS_LEN: 0, [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) QUERY: "", QUERY_LEN: 0, [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) FRAGMENT: "", FRAGMENT_LEN: 0] [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) MIME_HEADER 0x7fc77a89f8c8: [T: 4, L: 592, OBJFLAGS: 0] [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) [PBITS: 0x0009000001044804, SLACC: 0xFFFFF5FFFFF49FF1FFFFFFFFFFF0F2FF, HEADBLK: 0x7fc77a89f908, TAILBLK: 0x7fc77a89f908] [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0] [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) FIELD_BLOCK 0x7fc77a89f908: [T: 5, L: 528, OBJFLAGS: 0] [Nov 6 23:37:52.876] Server {0x7fc78400f840} DEBUG: (http) [FREETOP: 11, NEXTBLK: (nil)] [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) SLOT # 0 (0x7fc77a89f918), LIVE [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "SVN/1.7.7 neon/0.29.6", V_LEN: 21, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 35, F: 1] [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) SLOT # 1 (0x7fc77a89f938), LIVE [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "Connection", N_LEN: 10, N_IDX: 12, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "TE", V_LEN: 2, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 16, F: 1] [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) SLOT # 2 (0x7fc77a89f958), LIVE [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "TE", N_LEN: 2, N_IDX: 121, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "trailers", V_LEN: 8, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 14, F: 1] [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) SLOT # 3 (0x7fc77a89f978), LIVE [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "Host", N_LEN: 4, N_IDX: 30, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "svn.apache.org", V_LEN: 14, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 22, F: 1] [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) SLOT # 4 (0x7fc77a89f998), LIVE [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "Content-Type", N_LEN: 12, N_IDX: 20, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "text/xml", V_LEN: 8, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 24, F: 1] [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) SLOT # 5 (0x7fc77a89f9b8), LIVE [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "Accept-Encoding", N_LEN: 15, N_IDX: 1, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "gzip", V_LEN: 4, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: 0x7fc77a89fa58, RAW: 1, RAWLEN: 23, F: 1] [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) SLOT # 6 (0x7fc77a89f9d8), LIVE [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "DAV", N_LEN: 3, N_IDX: -1, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "http://subversion.tigris.org/xmlns/dav/svn/depth", V_LEN: 48, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: 0x7fc77a89f9f8, RAW: 1, RAWLEN: 55, F: 1] [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) SLOT # 7 (0x7fc77a89f9f8), LIVE [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "DAV", N_LEN: 3, N_IDX: -1, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "http://subversion.tigris.org/xmlns/dav/svn/mergeinfo", V_LEN: 52, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: 0x7fc77a89fa18, RAW: 1, RAWLEN: 59, F: 0] [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) SLOT # 8 (0x7fc77a89fa18), LIVE [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "DAV", N_LEN: 3, N_IDX: -1, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "http://subversion.tigris.org/xmlns/dav/svn/log-revprops", V_LEN: 55, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 62, F: 0] [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) SLOT # 9 (0x7fc77a89fa38), LIVE [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "Content-Length", N_LEN: 14, N_IDX: 16, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "104", V_LEN: 3, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 21, F: 1] [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) SLOT #10 (0x7fc77a89fa58), LIVE [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [N: "Accept-Encoding", N_LEN: 15, N_IDX: 1, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) V: "gzip", V_LEN: 4, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 23, F: 0] [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http_trans) END HttpTransact::StartRemapRequest [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http_trans) Next action HTTP_API_PRE_REMAP; HttpTransact::PerformRemap [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: API_READ_REQUEST_HDR -> HTTP_API_PRE_REMAP [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http_trans) Inside PerformRemap [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http_trans) Next action HTTP_REMAP_REQUEST; HttpTransact::EndRemapRequest [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: HTTP_API_PRE_REMAP -> HTTP_REMAP_REQUEST [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpSM::do_remap_request] Remapping request [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http_trans) START HttpTransact::EndRemapRequest [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http_trans) EndRemapRequest host is svn.apache.org [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http_trans) After Remapping: [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) HTTP_HEADER 0x7fc77a89f898: [T: 3, L: 48, OBJFLAGS: 0] [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [TYPE: REQ, V: 10001, URL: 0x7fc77a89fb18, METHOD: "OPTIONS", METHOD_LEN: 7, FIELDS: 0x7fc77a89f8c8] [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) URL 0x7fc77a89fb18: [T: 2, L: 128, OBJFLAGS: 0] [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [URLTYPE: 1, SWKSIDX: 94, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) SCHEME: "http", SCHEME_LEN: 4, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) USER: "", USER_LEN: 0, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) PASSWORD: "", PASSWORD_LEN: 0, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) HOST: "svn.apache.org", HOST_LEN: 14, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) PORT: "", PORT_LEN: 0, PORT_NUM: 0 [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) PATH: "repos/asf/subversion/trunk", PATH_LEN: 26, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) PARAMS: "", PARAMS_LEN: 0, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) QUERY: "", QUERY_LEN: 0, [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) FRAGMENT: "", FRAGMENT_LEN: 0] [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) MIME_HEADER 0x7fc77a89f8c8: [T: 4, L: 592, OBJFLAGS: 0] [Nov 6 23:37:52.877] Server {0x7fc78400f840} DEBUG: (http) [PBITS: 0x0009000001044804, SLACC: 0xFFFFF5FFFFF49FF1FFFFFFFFFFF0F2FF, HEADBLK: 0x7fc77a89f908, TAILBLK: 0x7fc77a89f908] [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0] [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) FIELD_BLOCK 0x7fc77a89f908: [T: 5, L: 528, OBJFLAGS: 0] [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [FREETOP: 11, NEXTBLK: (nil)] [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) SLOT # 0 (0x7fc77a89f918), LIVE [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "SVN/1.7.7 neon/0.29.6", V_LEN: 21, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 35, F: 1] [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) SLOT # 1 (0x7fc77a89f938), LIVE [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "Connection", N_LEN: 10, N_IDX: 12, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "TE", V_LEN: 2, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 16, F: 1] [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) SLOT # 2 (0x7fc77a89f958), LIVE [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "TE", N_LEN: 2, N_IDX: 121, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "trailers", V_LEN: 8, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 14, F: 1] [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) SLOT # 3 (0x7fc77a89f978), LIVE [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "Host", N_LEN: 4, N_IDX: 30, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "svn.apache.org", V_LEN: 14, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 22, F: 1] [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) SLOT # 4 (0x7fc77a89f998), LIVE [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "Content-Type", N_LEN: 12, N_IDX: 20, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "text/xml", V_LEN: 8, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 24, F: 1] [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) SLOT # 5 (0x7fc77a89f9b8), LIVE [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "Accept-Encoding", N_LEN: 15, N_IDX: 1, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "gzip", V_LEN: 4, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: 0x7fc77a89fa58, RAW: 1, RAWLEN: 23, F: 1] [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) SLOT # 6 (0x7fc77a89f9d8), LIVE [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "DAV", N_LEN: 3, N_IDX: -1, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "http://subversion.tigris.org/xmlns/dav/svn/depth", V_LEN: 48, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: 0x7fc77a89f9f8, RAW: 1, RAWLEN: 55, F: 1] [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) SLOT # 7 (0x7fc77a89f9f8), LIVE [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "DAV", N_LEN: 3, N_IDX: -1, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "http://subversion.tigris.org/xmlns/dav/svn/mergeinfo", V_LEN: 52, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: 0x7fc77a89fa18, RAW: 1, RAWLEN: 59, F: 0] [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) SLOT # 8 (0x7fc77a89fa18), LIVE [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "DAV", N_LEN: 3, N_IDX: -1, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "http://subversion.tigris.org/xmlns/dav/svn/log-revprops", V_LEN: 55, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 62, F: 0] [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) SLOT # 9 (0x7fc77a89fa38), LIVE [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "Content-Length", N_LEN: 14, N_IDX: 16, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "104", V_LEN: 3, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 21, F: 1] [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) SLOT #10 (0x7fc77a89fa58), LIVE [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [N: "Accept-Encoding", N_LEN: 15, N_IDX: 1, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) V: "gzip", V_LEN: 4, [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 23, F: 0] [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http_trans) END HttpTransact::EndRemapRequest [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http_trans) Next action HTTP_API_POST_REMAP; HttpTransact::HandleRequest [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: HTTP_REMAP_REQUEST -> HTTP_API_POST_REMAP [Nov 6 23:37:52.878] Server {0x7fc78400f840} DEBUG: (http_trans) START HttpTransact::HandleRequest [Nov 6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http_trans) [is_request_valid]no request header errors [Nov 6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleRequest] request valid. [Nov 6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) HTTP_HEADER 0x7fc77a89f898: [T: 3, L: 48, OBJFLAGS: 0] [Nov 6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) [TYPE: REQ, V: 10001, URL: 0x7fc77a89fb18, METHOD: "OPTIONS", METHOD_LEN: 7, FIELDS: 0x7fc77a89f8c8] [Nov 6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) URL 0x7fc77a89fb18: [T: 2, L: 128, OBJFLAGS: 0] [Nov 6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) [URLTYPE: 1, SWKSIDX: 94, [Nov 6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) SCHEME: "http", SCHEME_LEN: 4, [Nov 6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) USER: "", USER_LEN: 0, [Nov 6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) PASSWORD: "", PASSWORD_LEN: 0, [Nov 6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) HOST: "svn.apache.org", HOST_LEN: 14, [Nov 6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) PORT: "", PORT_LEN: 0, PORT_NUM: 0 [Nov 6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) PATH: "repos/asf/subversion/trunk", PATH_LEN: 26, [Nov 6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) PARAMS: "", PARAMS_LEN: 0, [Nov 6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) QUERY: "", QUERY_LEN: 0, [Nov 6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) FRAGMENT: "", FRAGMENT_LEN: 0] [Nov 6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) MIME_HEADER 0x7fc77a89f8c8: [T: 4, L: 592, OBJFLAGS: 0] [Nov 6 23:37:52.879] Server {0x7fc78400f840} DEBUG: (http) [PBITS: 0x0009000001044804, SLACC: 0xFFFFF5FFFFF49FF1FFFFFFFFFFF0F2FF, HEADBLK: 0x7fc77a89f908, TAILBLK: 0x7fc77a89f908] [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0] [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) FIELD_BLOCK 0x7fc77a89f908: [T: 5, L: 528, OBJFLAGS: 0] [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [FREETOP: 11, NEXTBLK: (nil)] [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) SLOT # 0 (0x7fc77a89f918), LIVE [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64, [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) V: "SVN/1.7.7 neon/0.29.6", V_LEN: 21, [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 35, F: 1] [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) SLOT # 1 (0x7fc77a89f938), LIVE [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [N: "Connection", N_LEN: 10, N_IDX: 12, [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) V: "TE", V_LEN: 2, [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 16, F: 1] [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) SLOT # 2 (0x7fc77a89f958), LIVE [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [N: "TE", N_LEN: 2, N_IDX: 121, [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) V: "trailers", V_LEN: 8, [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 14, F: 1] [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) SLOT # 3 (0x7fc77a89f978), LIVE [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [N: "Host", N_LEN: 4, N_IDX: 30, [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) V: "svn.apache.org", V_LEN: 14, [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 22, F: 1] [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) SLOT # 4 (0x7fc77a89f998), LIVE [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [N: "Content-Type", N_LEN: 12, N_IDX: 20, [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) V: "text/xml", V_LEN: 8, [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 24, F: 1] [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) SLOT # 5 (0x7fc77a89f9b8), LIVE [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [N: "Accept-Encoding", N_LEN: 15, N_IDX: 1, [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) V: "gzip", V_LEN: 4, [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: 0x7fc77a89fa58, RAW: 1, RAWLEN: 23, F: 1] [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) SLOT # 6 (0x7fc77a89f9d8), LIVE [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [N: "DAV", N_LEN: 3, N_IDX: -1, [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) V: "http://subversion.tigris.org/xmlns/dav/svn/depth", V_LEN: 48, [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: 0x7fc77a89f9f8, RAW: 1, RAWLEN: 55, F: 1] [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) SLOT # 7 (0x7fc77a89f9f8), LIVE [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [N: "DAV", N_LEN: 3, N_IDX: -1, [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) V: "http://subversion.tigris.org/xmlns/dav/svn/mergeinfo", V_LEN: 52, [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: 0x7fc77a89fa18, RAW: 1, RAWLEN: 59, F: 0] [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) SLOT # 8 (0x7fc77a89fa18), LIVE [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) [N: "DAV", N_LEN: 3, N_IDX: -1, [Nov 6 23:37:52.880] Server {0x7fc78400f840} DEBUG: (http) V: "http://subversion.tigris.org/xmlns/dav/svn/log-revprops", V_LEN: 55, [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 62, F: 0] [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) SLOT # 9 (0x7fc77a89fa38), LIVE [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) [N: "Content-Length", N_LEN: 14, N_IDX: 16, [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) V: "104", V_LEN: 3, [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 21, F: 1] [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) SLOT #10 (0x7fc77a89fa58), LIVE [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) [N: "Accept-Encoding", N_LEN: 15, N_IDX: 1, [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) V: "gzip", V_LEN: 4, [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 23, F: 0] [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) +++++++++ Incoming Request +++++++++ -- State Machine Id: 0 OPTIONS http://svn.apache.org/repos/asf/subversion/trunk HTTP/1.1 User-Agent: SVN/1.7.7 neon/0.29.6 Connection: TE TE: trailers Host: svn.apache.org Content-Type: text/xml Accept-Encoding: gzip DAV: http://subversion.tigris.org/xmlns/dav/svn/depth DAV: http://subversion.tigris.org/xmlns/dav/svn/mergeinfo DAV: http://subversion.tigris.org/xmlns/dav/svn/log-revprops Content-Length: 104 Accept-Encoding: gzip [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_trans) [DecideCacheLookup] Will NOT do cache lookup. [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_seq) [DecideCacheLookup] Will NOT do cache lookup [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_trans) Next action HTTP_API_CACHE_LOOKUP_COMPLETE; CallOSDNSLookup [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: HTTP_API_POST_REMAP -> API_CACHE_LOOKUP_COMPLETE [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_trans) Next action DNS_LOOKUP; OSDNSLookup [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: API_CACHE_LOOKUP_COMPLETE -> DNS_LOOKUP [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpStateMachineGet::do_hostdb_lookup] Doing DNS Lookup [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_trans) [HttpTransact::OSDNSLookup] This was attempt 1 [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::OSDNSLookup] DNS Lookup successful [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_trans) [OSDNSLookup] DNS lookup for O.S. successful IP: 160.45.251.2 [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_trans) Next action HttpTransact::HTTP_API_OS_DNS; LookupSkipOpenServer [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: DNS_LOOKUP -> API_OS_DNS [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_trans) request not cacheable, so bypass parent [Nov 6 23:37:52.881] Server {0x7fc78400f840} DEBUG: (http_trans) client_ip_set = 0 [Nov 6 23:37:52.885] Server {0x7fc78400f840} DEBUG: (http_trans) inserted request header 'Client-ip: 192.168.122.1' [Nov 6 23:37:52.885] Server {0x7fc78400f840} DEBUG: (http_trans) [add_client_ip_to_outgoing_request] Appended connecting client's (192.168.122.1) to the X-Forwards header [Nov 6 23:37:52.885] Server {0x7fc78400f840} DEBUG: (http_trans) [ink_cluster_time] local: 1352241472, highest_delta: 0, cluster: 1352241472 [Nov 6 23:37:52.885] Server {0x7fc78400f840} DEBUG: (http_trans) [build_request] request_sent_time: 1352241472 +++++++++ Proxy's Request +++++++++ -- State Machine Id: 0 OPTIONS /repos/asf/subversion/trunk HTTP/1.1 User-Agent: SVN/1.7.7 neon/0.29.6 Host: svn.apache.org Content-Type: text/xml Accept-Encoding: gzip DAV: http://subversion.tigris.org/xmlns/dav/svn/depth DAV: http://subversion.tigris.org/xmlns/dav/svn/mergeinfo DAV: http://subversion.tigris.org/xmlns/dav/svn/log-revprops Content-Length: 104 Accept-Encoding: gzip Client-ip: 192.168.122.1 X-Forwarded-For: 192.168.122.1 Via: http/1.1 tynix[FE80000000000000B6749FFFFE9DDA61] (ApacheTrafficServer/3.2.3 [uSc s f p eN:tMc i p s ]) [Nov 6 23:37:52.885] Server {0x7fc78400f840} DEBUG: (http_trans) Next action next; HttpTransact::HandleResponse [Nov 6 23:37:52.885] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: API_OS_DNS -> ORIGIN_SERVER_OPEN [Nov 6 23:37:52.885] Server {0x7fc78400f840} DEBUG: (http_track) entered inside do_http_server_open [Nov 6 23:37:52.885] Server {0x7fc78400f840} DEBUG: (http) [0] open connection to svn.apache.org: 160.45.251.2:80 [Nov 6 23:37:52.885] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpSM::do_http_server_open] Sending request to server [Nov 6 23:37:52.885] Server {0x7fc78400f840} DEBUG: (http) calling netProcessor.connect_re [Nov 6 23:37:52.886] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, NET_EVENT_OPEN] [Nov 6 23:37:52.886] Server {0x7fc78400f840} DEBUG: (http_track) entered inside state_http_server_open [Nov 6 23:37:52.886] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_http_server_open, NET_EVENT_OPEN] [Nov 6 23:37:52.886] Server {0x7fc78400f840} DEBUG: (http_ss) [0] session born, netvc 0x7fc774015dc0 [Nov 6 23:37:52.917] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE] [Nov 6 23:37:52.917] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE] [Nov 6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT] [Nov 6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_read_server_response_header, VC_EVENT_INACTIVITY_TIMEOUT] [Nov 6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_ss) [0] session closed [Nov 6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::handle_server_setup_error, VC_EVENT_NONE] [Nov 6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_trans) [HttpTransact::HandleResponse] [Nov 6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response received [Nov 6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_trans) [ink_cluster_time] local: 1352241503, highest_delta: 0, cluster: 1352241503 [Nov 6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_trans) [HandleResponse] response_received_time: 1352241503 +++++++++ Incoming O.S. Response +++++++++ -- State Machine Id: 0 HTTP/0.9 0 [Nov 6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response not valid [Nov 6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] (hrfs) [Nov 6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_trans) [1] failed to connect [6] to 160.45.251.2 [Nov 6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_trans) [retry_server_connection_not_open] attempts now: 2, max: 6 [Nov 6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] Error. Retrying... [Nov 6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: ORIGIN_SERVER_OPEN -> ORIGIN_SERVER_OPEN [Nov 6 23:38:23.722] Server {0x7fc78400f840} DEBUG: (http_track) entered inside do_http_server_open [Nov 6 23:38:23.723] Server {0x7fc78400f840} DEBUG: (http) [0] open connection to svn.apache.org: 160.45.251.2:80 [Nov 6 23:38:23.723] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpSM::do_http_server_open] Sending request to server [Nov 6 23:38:23.723] Server {0x7fc78400f840} DEBUG: (http) calling netProcessor.connect_re [Nov 6 23:38:23.723] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, NET_EVENT_OPEN] [Nov 6 23:38:23.723] Server {0x7fc78400f840} DEBUG: (http_track) entered inside state_http_server_open [Nov 6 23:38:23.723] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_http_server_open, NET_EVENT_OPEN] [Nov 6 23:38:23.723] Server {0x7fc78400f840} DEBUG: (http_ss) [1] session born, netvc 0x7fc774015b00 [Nov 6 23:38:23.773] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE] [Nov 6 23:38:23.773] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE] [Nov 6 23:38:54.658] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT] [Nov 6 23:38:54.658] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_read_server_response_header, VC_EVENT_INACTIVITY_TIMEOUT] [Nov 6 23:38:54.658] Server {0x7fc78400f840} DEBUG: (http_ss) [1] session closed [Nov 6 23:38:54.658] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::handle_server_setup_error, VC_EVENT_NONE] [Nov 6 23:38:54.658] Server {0x7fc78400f840} DEBUG: (http_trans) [HttpTransact::HandleResponse] [Nov 6 23:38:54.658] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response received [Nov 6 23:38:54.658] Server {0x7fc78400f840} DEBUG: (http_trans) [ink_cluster_time] local: 1352241534, highest_delta: 0, cluster: 1352241534 [Nov 6 23:38:54.658] Server {0x7fc78400f840} DEBUG: (http_trans) [HandleResponse] response_received_time: 1352241534 +++++++++ Incoming O.S. Response +++++++++ -- State Machine Id: 0 HTTP/0.9 0 [Nov 6 23:38:54.658] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response not valid [Nov 6 23:38:54.658] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] (hrfs) [Nov 6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http_trans) [2] failed to connect [6] to 160.45.251.2 [Nov 6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http_trans) [retry_server_connection_not_open] attempts now: 3, max: 6 [Nov 6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] Error. Retrying... [Nov 6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: ORIGIN_SERVER_OPEN -> ORIGIN_SERVER_OPEN [Nov 6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http_track) entered inside do_http_server_open [Nov 6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http) [0] open connection to svn.apache.org: 160.45.251.2:80 [Nov 6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpSM::do_http_server_open] Sending request to server [Nov 6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http) calling netProcessor.connect_re [Nov 6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, NET_EVENT_OPEN] [Nov 6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http_track) entered inside state_http_server_open [Nov 6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_http_server_open, NET_EVENT_OPEN] [Nov 6 23:38:54.659] Server {0x7fc78400f840} DEBUG: (http_ss) [2] session born, netvc 0x7fc774015dc0 [Nov 6 23:38:55.716] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE] [Nov 6 23:38:55.716] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE] [Nov 6 23:39:26.618] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT] [Nov 6 23:39:26.618] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_read_server_response_header, VC_EVENT_INACTIVITY_TIMEOUT] [Nov 6 23:39:26.618] Server {0x7fc78400f840} DEBUG: (http_ss) [2] session closed [Nov 6 23:39:26.618] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::handle_server_setup_error, VC_EVENT_NONE] [Nov 6 23:39:26.618] Server {0x7fc78400f840} DEBUG: (http_trans) [HttpTransact::HandleResponse] [Nov 6 23:39:26.618] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response received [Nov 6 23:39:26.618] Server {0x7fc78400f840} DEBUG: (http_trans) [ink_cluster_time] local: 1352241566, highest_delta: 0, cluster: 1352241566 [Nov 6 23:39:26.618] Server {0x7fc78400f840} DEBUG: (http_trans) [HandleResponse] response_received_time: 1352241566 +++++++++ Incoming O.S. Response +++++++++ -- State Machine Id: 0 HTTP/0.9 0 [Nov 6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response not valid [Nov 6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] (hrfs) [Nov 6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http_trans) [3] failed to connect [6] to 160.45.251.2 [Nov 6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http_trans) [retry_server_connection_not_open] attempts now: 4, max: 6 [Nov 6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] Error. Retrying... [Nov 6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: ORIGIN_SERVER_OPEN -> ORIGIN_SERVER_OPEN [Nov 6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http_track) entered inside do_http_server_open [Nov 6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http) [0] open connection to svn.apache.org: 160.45.251.2:80 [Nov 6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpSM::do_http_server_open] Sending request to server [Nov 6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http) calling netProcessor.connect_re [Nov 6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, NET_EVENT_OPEN] [Nov 6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http_track) entered inside state_http_server_open [Nov 6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_http_server_open, NET_EVENT_OPEN] [Nov 6 23:39:26.619] Server {0x7fc78400f840} DEBUG: (http_ss) [3] session born, netvc 0x7fc774015b00 [Nov 6 23:39:26.671] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE] [Nov 6 23:39:26.671] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE] [Nov 6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT] [Nov 6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_read_server_response_header, VC_EVENT_INACTIVITY_TIMEOUT] [Nov 6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_ss) [3] session closed [Nov 6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::handle_server_setup_error, VC_EVENT_NONE] [Nov 6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_trans) [HttpTransact::HandleResponse] [Nov 6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response received [Nov 6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_trans) [ink_cluster_time] local: 1352241597, highest_delta: 0, cluster: 1352241597 [Nov 6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_trans) [HandleResponse] response_received_time: 1352241597 +++++++++ Incoming O.S. Response +++++++++ -- State Machine Id: 0 HTTP/0.9 0 [Nov 6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response not valid [Nov 6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] (hrfs) [Nov 6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_trans) [4] failed to connect [6] to 160.45.251.2 [Nov 6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_trans) [retry_server_connection_not_open] attempts now: 5, max: 6 [Nov 6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] Error. Retrying... [Nov 6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: ORIGIN_SERVER_OPEN -> ORIGIN_SERVER_OPEN [Nov 6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_track) entered inside do_http_server_open [Nov 6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http) [0] open connection to svn.apache.org: 160.45.251.2:80 [Nov 6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpSM::do_http_server_open] Sending request to server [Nov 6 23:39:57.584] Server {0x7fc78400f840} DEBUG: (http) calling netProcessor.connect_re [Nov 6 23:39:57.585] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, NET_EVENT_OPEN] [Nov 6 23:39:57.585] Server {0x7fc78400f840} DEBUG: (http_track) entered inside state_http_server_open [Nov 6 23:39:57.585] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_http_server_open, NET_EVENT_OPEN] [Nov 6 23:39:57.585] Server {0x7fc78400f840} DEBUG: (http_ss) [4] session born, netvc 0x7fc774015dc0 [Nov 6 23:39:58.146] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE] [Nov 6 23:39:58.146] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE] [Nov 6 23:40:28.540] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT] [Nov 6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_read_server_response_header, VC_EVENT_INACTIVITY_TIMEOUT] [Nov 6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http_ss) [4] session closed [Nov 6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::handle_server_setup_error, VC_EVENT_NONE] [Nov 6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http_trans) [HttpTransact::HandleResponse] [Nov 6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response received [Nov 6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http_trans) [ink_cluster_time] local: 1352241628, highest_delta: 0, cluster: 1352241628 [Nov 6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http_trans) [HandleResponse] response_received_time: 1352241628 +++++++++ Incoming O.S. Response +++++++++ -- State Machine Id: 0 HTTP/0.9 0 [Nov 6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response not valid [Nov 6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] (hrfs) [Nov 6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http_trans) [5] failed to connect [6] to 160.45.251.2 [Nov 6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http_trans) [retry_server_connection_not_open] attempts now: 6, max: 6 [Nov 6 23:40:28.541] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] Error. Retrying... [Nov 6 23:40:28.542] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: ORIGIN_SERVER_OPEN -> ORIGIN_SERVER_OPEN [Nov 6 23:40:28.542] Server {0x7fc78400f840} DEBUG: (http_track) entered inside do_http_server_open [Nov 6 23:40:28.542] Server {0x7fc78400f840} DEBUG: (http) [0] open connection to svn.apache.org: 160.45.251.2:80 [Nov 6 23:40:28.542] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpSM::do_http_server_open] Sending request to server [Nov 6 23:40:28.542] Server {0x7fc78400f840} DEBUG: (http) calling netProcessor.connect_re [Nov 6 23:40:28.542] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, NET_EVENT_OPEN] [Nov 6 23:40:28.542] Server {0x7fc78400f840} DEBUG: (http_track) entered inside state_http_server_open [Nov 6 23:40:28.542] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_http_server_open, NET_EVENT_OPEN] [Nov 6 23:40:28.542] Server {0x7fc78400f840} DEBUG: (http_ss) [5] session born, netvc 0x7fc774015b00 [Nov 6 23:40:28.885] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE] [Nov 6 23:40:28.886] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE] [Nov 6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT] [Nov 6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::state_read_server_response_header, VC_EVENT_INACTIVITY_TIMEOUT] [Nov 6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http_ss) [5] session closed [Nov 6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::handle_server_setup_error, VC_EVENT_NONE] [Nov 6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http_trans) [HttpTransact::HandleResponse] [Nov 6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response received [Nov 6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http_trans) [ink_cluster_time] local: 1352241659, highest_delta: 0, cluster: 1352241659 [Nov 6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http_trans) [HandleResponse] response_received_time: 1352241659 +++++++++ Incoming O.S. Response +++++++++ -- State Machine Id: 0 HTTP/0.9 0 [Nov 6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::HandleResponse] Response not valid [Nov 6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] (hrfs) [Nov 6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_response_from_server] Error. No more retries. [Nov 6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http_trans) [handle_server_connection_not_open] (hscno) [Nov 6 23:40:59.495] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpTransact::handle_server_connection_not_open] [Nov 6 23:40:59.496] Server {0x7fc78400f840} DEBUG: (http_trans) [ink_cluster_time] local: 1352241659, highest_delta: 0, cluster: 1352241659 [Nov 6 23:40:59.496] Server {0x7fc78400f840} DEBUG: (http) [0] hostdb update marking IP: 160.45.251.2:80 as down [Nov 6 23:40:59.496] Server {0x7fc78400f840} DEBUG: (http) server info = 160.45.251.2:80 [Nov 6 23:40:59.496] Server {0x7fc78400f840} DEBUG: (http_trans) [WUTS code generation] Hit/Miss: 49, Log: 112, Hier: 106, Status: 800 [Nov 6 23:40:59.496] Server {0x7fc78400f840} DEBUG: (http_trans) Adding Server: ATS/3.2.3 +++++++++ Proxy's Response 2 +++++++++ -- State Machine Id: 0 HTTP/1.1 504 Connection Timed Out Date: Tue, 06 Nov 2012 22:40:59 GMT Connection: keep-alive Via: http/1.1 tynix (ApacheTrafficServer/3.2.3 [uSc sEf p eT:tMc i p sF]) Server: ATS/3.2.3 [Nov 6 23:40:59.496] Server {0x7fc78400f840} DEBUG: (http) [0] State Transition: ORIGIN_SERVER_OPEN -> PROXY_SEND_ERROR_CACHE_NOOP [Nov 6 23:40:59.496] Server {0x7fc78400f840} DEBUG: (http_tunnel) [0] adding producer 'internal msg' [Nov 6 23:40:59.496] Server {0x7fc78400f840} DEBUG: (http_tunnel) [0] adding consumer 'user agent' [Nov 6 23:40:59.496] Server {0x7fc78400f840} DEBUG: (http_tunnel) tunnel_run started, p_arg is NULL [Nov 6 23:40:59.497] Server {0x7fc78400f840} DEBUG: (http_cs) tcp_init_cwnd_set 0 [Nov 6 23:40:59.497] Server {0x7fc78400f840} DEBUG: (http_cs) desired TCP congestion window is 0 [Nov 6 23:40:59.497] Server {0x7fc78400f840} DEBUG: (http_tunnel) [0] consumer_handler [user agent VC_EVENT_WRITE_COMPLETE] [Nov 6 23:40:59.497] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE] [Nov 6 23:40:59.497] Server {0x7fc78400f840} DEBUG: (http_cs) [0] session released by sm [0] [Nov 6 23:40:59.497] Server {0x7fc78400f840} DEBUG: (http_cs) [0] data already in buffer, starting new transaction [Nov 6 23:40:59.497] Server {0x7fc78400f840} DEBUG: (http_cs) [0] using accept inactivity timeout [120 seconds] [Nov 6 23:40:59.497] Server {0x7fc78400f840} DEBUG: (http_cs) [0] Starting transaction 2 using sm [1] [Nov 6 23:40:59.497] Server {0x7fc78400f840} DEBUG: (http) [1] [&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY] [Nov 6 23:40:59.497] Server {0x7fc78400f840} DEBUG: (http) [0] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE] [Nov 6 23:40:59.498] Server {0x7fc78400f840} DEBUG: (http) [0] [&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE] [Nov 6 23:40:59.498] Server {0x7fc78400f840} DEBUG: (http_redirect) [HttpTunnel::deallocate_postdata_copy_buffers] [Nov 6 23:40:59.498] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpStateMachineGet::update_stats] Logging transaction [Nov 6 23:40:59.498] Server {0x7fc78400f840} DEBUG: (http_trans) Adding new large stat block [Nov 6 23:40:59.498] Server {0x7fc78400f840} DEBUG: (http) [0] dellocating sm [Nov 6 23:40:59.498] Server {0x7fc78400f840} DEBUG: (http) [1] [HttpSM::main_handler, VC_EVENT_EOS] [Nov 6 23:40:59.498] Server {0x7fc78400f840} DEBUG: (http) [1] [&HttpSM::state_read_client_request_header, VC_EVENT_EOS] [Nov 6 23:40:59.498] Server {0x7fc78400f840} DEBUG: (http) [1] error parsing client request header [Nov 6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_trans) [BadRequest]parser marked request bad [Nov 6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_trans) [ink_cluster_time] local: 1352241659, highest_delta: 0, cluster: 1352241659 [Nov 6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_trans) [WUTS code generation] Hit/Miss: 98, Log: 118, Hier: 49, Status: 806 [Nov 6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_trans) Adding Server: ATS/3.2.3 +++++++++ Proxy's Response 2 +++++++++ -- State Machine Id: 1 HTTP/1.1 400 Invalid HTTP Request Date: Tue, 06 Nov 2012 22:40:59 GMT Connection: close Via: http/1.1 tynix (ApacheTrafficServer/3.2.3 [uEc s f p eH:t c i p s ]) Server: ATS/3.2.3 [Nov 6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_trans) Next action PROXY_SEND_ERROR_CACHE_NOOP; NULL [Nov 6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http) [1] State Transition: STATE_UNDEFINED -> PROXY_SEND_ERROR_CACHE_NOOP [Nov 6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_tunnel) [1] adding producer 'internal msg' [Nov 6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_tunnel) [1] adding consumer 'user agent' [Nov 6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_tunnel) tunnel_run started, p_arg is NULL [Nov 6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_cs) tcp_init_cwnd_set 1 [Nov 6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_tunnel) [1] consumer_handler [user agent VC_EVENT_WRITE_COMPLETE] [Nov 6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http) [1] [&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE] [Nov 6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_cs) [0] session closed [Nov 6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_cs) [0] session destroy [Nov 6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http) [1] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE] [Nov 6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http) [1] [&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE] [Nov 6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_redirect) [HttpTunnel::deallocate_postdata_copy_buffers] [Nov 6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http_seq) [HttpStateMachineGet::update_stats] Logging transaction [Nov 6 23:40:59.499] Server {0x7fc78400f840} DEBUG: (http) [1] dellocating sm A number of things can be observed: The OPTIONS body is discarded, while the Content-Length is kept in tact. That seems rather odd behaviour to begin with. Next, the svn.apache.org server almost immediately answers with a 400 , but we don't pass that on to the client. Instead we loop a number of times, then send the client a 504 . This behaviour, again, seems rather weird.
          Hide
          Ben Reser added a comment -

          Worth nothing here that OPTIONS request does not have a body in the HTTP/1.1 spec. However, it does specify that future extensions may have a body and specifies the conditions in which to expect a body. Subversion is using the OPTIONS request body.

          There is a sentence in the RFC that says that a server may discard the body. However, a proxy is not a "server" in the sense of the HTTP spec so you should be passing the body along.

          http://www.w3.org/Protocols/rfc2616/rfc2616-sec9.html

          Show
          Ben Reser added a comment - Worth nothing here that OPTIONS request does not have a body in the HTTP/1.1 spec. However, it does specify that future extensions may have a body and specifies the conditions in which to expect a body. Subversion is using the OPTIONS request body. There is a sentence in the RFC that says that a server may discard the body. However, a proxy is not a "server" in the sense of the HTTP spec so you should be passing the body along. http://www.w3.org/Protocols/rfc2616/rfc2616-sec9.html
          Hide
          Ben Reser added a comment -

          I was able to replicate this with svn 1.6 using neon, svn1.7 using neon and svn trunk using serf. I agree with the comment earlier that the problems seems to be that the body of the OPTIONS request is not sent.

          Show
          Ben Reser added a comment - I was able to replicate this with svn 1.6 using neon, svn1.7 using neon and svn trunk using serf. I agree with the comment earlier that the problems seems to be that the body of the OPTIONS request is not sent.
          Leif Hedstrom made changes -
          Fix Version/s 3.3.1 [ 12321686 ]
          Fix Version/s 3.3.0 [ 12316495 ]
          Leif Hedstrom made changes -
          Fix Version/s 3.3.0 [ 12316495 ]
          Fix Version/s 3.1.6 [ 12320168 ]
          Hide
          Leif Hedstrom added a comment -

          Moving out to v3.3.0, move back to 3.1.4 if this will be work on soon.

          Show
          Leif Hedstrom added a comment - Moving out to v3.3.0, move back to 3.1.4 if this will be work on soon .
          Leif Hedstrom made changes -
          Fix Version/s 3.1.6 [ 12320168 ]
          Fix Version/s 3.1.5 [ 12320056 ]
          Leif Hedstrom made changes -
          Fix Version/s 3.1.5 [ 12320056 ]
          Fix Version/s 3.1.4 [ 12318543 ]
          Leif Hedstrom made changes -
          Fix Version/s 3.1.4 [ 12318543 ]
          Fix Version/s 3.1.3 [ 12317969 ]
          Leif Hedstrom made changes -
          Fix Version/s 3.1.3 [ 12317969 ]
          Fix Version/s 3.1.1 [ 12316496 ]
          Hide
          Leif Hedstrom added a comment -

          I won't have time to work on this for a while, so moving out. If anyone else cares to pick it up where I left off, please reassign as appropriate.

          Show
          Leif Hedstrom added a comment - I won't have time to work on this for a while, so moving out. If anyone else cares to pick it up where I left off, please reassign as appropriate.
          Leif Hedstrom made changes -
          Attachment TS-871.diff [ 12498906 ]
          Hide
          Leif Hedstrom added a comment -

          This fixes a few of the problems here, but is fairly risky. And worse, it doesn't solve all the problems, but at least it is a step in the right direction.

          Show
          Leif Hedstrom added a comment - This fixes a few of the problems here, but is fairly risky. And worse, it doesn't solve all the problems, but at least it is a step in the right direction.
          Leif Hedstrom made changes -
          Attachment TS-871.diff [ 12498682 ]
          Hide
          Igor Galić added a comment - - edited

          YAY! for consistency! Looks exactly the same in forward proxy mode.

          Contrast svn 1.6.12 (testing ubuntu's stock):

          1318411080.368 189 127.0.0.1 TCP_MISS/200 887 OPTIONS http://svn.eu.apache.org/repos/asf/trafficserver/plugins/stats_over_http - DIRECT/svn.eu.apache.org text/xml -
          1318411080.562 192 127.0.0.1 TCP_MISS/207 609 PROPFIND http://svn.eu.apache.org/repos/asf/trafficserver/plugins/stats_over_http - DIRECT/svn.eu.apache.org text/xml -
          1318411080.754 191 127.0.0.1 TCP_MISS/207 484 PROPFIND http://svn.eu.apache.org/repos/asf/!svn/vcc/default - DIRECT/svn.eu.apache.org text/xml -
          1318411080.946 189 127.0.0.1 TCP_MISS/207 498 PROPFIND http://svn.eu.apache.org/repos/asf/!svn/bln/1182279 - DIRECT/svn.eu.apache.org text/xml -
          1318411081.140 191 127.0.0.1 TCP_MISS/207 609 PROPFIND http://svn.eu.apache.org/repos/asf/trafficserver/plugins/stats_over_http - DIRECT/svn.eu.apache.org text/xml -
          1318411081.332 189 127.0.0.1 TCP_MISS/207 484 PROPFIND http://svn.eu.apache.org/repos/asf/!svn/vcc/default - DIRECT/svn.eu.apache.org text/xml -
          1318411081.524 190 127.0.0.1 TCP_MISS/207 498 PROPFIND http://svn.eu.apache.org/repos/asf/!svn/bln/1182279 - DIRECT/svn.eu.apache.org text/xml -
          1318411081.718 190 127.0.0.1 TCP_MISS/207 609 PROPFIND http://svn.eu.apache.org/repos/asf/trafficserver/plugins/stats_over_http - DIRECT/svn.eu.apache.org text/xml -
          1318411081.909 189 127.0.0.1 TCP_MISS/207 504 PROPFIND http://svn.eu.apache.org/repos/asf/!svn/vcc/default - DIRECT/svn.eu.apache.org text/xml -
          1318411082.103 191 127.0.0.1 TCP_MISS/207 619 PROPFIND http://svn.eu.apache.org/repos/asf/!svn/bc/1182279/trafficserver/plugins/stats_over_http - DIRECT/svn.eu.apache.org text/xml -
          1318411082.299 190 127.0.0.1 TCP_MISS/200 887 OPTIONS http://svn.eu.apache.org/repos/asf/trafficserver/plugins/stats_over_http - DIRECT/svn.eu.apache.org text/xml -
          1318411082.492 192 127.0.0.1 TCP_MISS/207 609 PROPFIND http://svn.eu.apache.org/repos/asf/trafficserver/plugins/stats_over_http - DIRECT/svn.eu.apache.org text/xml -
          1318411082.686 190 127.0.0.1 TCP_MISS/207 609 PROPFIND http://svn.eu.apache.org/repos/asf/trafficserver/plugins/stats_over_http - DIRECT/svn.eu.apache.org text/xml -
          1318411082.878 189 127.0.0.1 TCP_MISS/207 484 PROPFIND http://svn.eu.apache.org/repos/asf/!svn/vcc/default - DIRECT/svn.eu.apache.org text/xml -
          1318411083.068 189 127.0.0.1 TCP_MISS/207 498 PROPFIND http://svn.eu.apache.org/repos/asf/!svn/bln/1182279 - DIRECT/svn.eu.apache.org text/xml -
          1318411083.262 191 127.0.0.1 TCP_MISS/207 609 PROPFIND http://svn.eu.apache.org/repos/asf/trafficserver/plugins/stats_over_http - DIRECT/svn.eu.apache.org text/xml -
          1318411083.453 190 127.0.0.1 TCP_MISS/207 484 PROPFIND http://svn.eu.apache.org/repos/asf/!svn/vcc/default - DIRECT/svn.eu.apache.org text/xml -
          1318411083.645 190 127.0.0.1 TCP_MISS/207 498 PROPFIND http://svn.eu.apache.org/repos/asf/!svn/bln/1182279 - DIRECT/svn.eu.apache.org text/xml -
          1318411084.118 473 127.0.0.1 TCP_MISS/200 11899 REPORT http://svn.eu.apache.org/repos/asf/!svn/vcc/default - DIRECT/svn.eu.apache.org text/xml -
          

          But of course, that uses a different library. - I just wanted to show that the proxy actually works.

          Show
          Igor Galić added a comment - - edited YAY! for consistency! Looks exactly the same in forward proxy mode. Contrast svn 1.6.12 (testing ubuntu's stock): 1318411080.368 189 127.0.0.1 TCP_MISS/200 887 OPTIONS http://svn.eu.apache.org/repos/asf/trafficserver/plugins/stats_over_http - DIRECT/svn.eu.apache.org text/xml - 1318411080.562 192 127.0.0.1 TCP_MISS/207 609 PROPFIND http://svn.eu.apache.org/repos/asf/trafficserver/plugins/stats_over_http - DIRECT/svn.eu.apache.org text/xml - 1318411080.754 191 127.0.0.1 TCP_MISS/207 484 PROPFIND http://svn.eu.apache.org/repos/asf/!svn/vcc/default - DIRECT/svn.eu.apache.org text/xml - 1318411080.946 189 127.0.0.1 TCP_MISS/207 498 PROPFIND http://svn.eu.apache.org/repos/asf/!svn/bln/1182279 - DIRECT/svn.eu.apache.org text/xml - 1318411081.140 191 127.0.0.1 TCP_MISS/207 609 PROPFIND http://svn.eu.apache.org/repos/asf/trafficserver/plugins/stats_over_http - DIRECT/svn.eu.apache.org text/xml - 1318411081.332 189 127.0.0.1 TCP_MISS/207 484 PROPFIND http://svn.eu.apache.org/repos/asf/!svn/vcc/default - DIRECT/svn.eu.apache.org text/xml - 1318411081.524 190 127.0.0.1 TCP_MISS/207 498 PROPFIND http://svn.eu.apache.org/repos/asf/!svn/bln/1182279 - DIRECT/svn.eu.apache.org text/xml - 1318411081.718 190 127.0.0.1 TCP_MISS/207 609 PROPFIND http://svn.eu.apache.org/repos/asf/trafficserver/plugins/stats_over_http - DIRECT/svn.eu.apache.org text/xml - 1318411081.909 189 127.0.0.1 TCP_MISS/207 504 PROPFIND http://svn.eu.apache.org/repos/asf/!svn/vcc/default - DIRECT/svn.eu.apache.org text/xml - 1318411082.103 191 127.0.0.1 TCP_MISS/207 619 PROPFIND http://svn.eu.apache.org/repos/asf/!svn/bc/1182279/trafficserver/plugins/stats_over_http - DIRECT/svn.eu.apache.org text/xml - 1318411082.299 190 127.0.0.1 TCP_MISS/200 887 OPTIONS http://svn.eu.apache.org/repos/asf/trafficserver/plugins/stats_over_http - DIRECT/svn.eu.apache.org text/xml - 1318411082.492 192 127.0.0.1 TCP_MISS/207 609 PROPFIND http://svn.eu.apache.org/repos/asf/trafficserver/plugins/stats_over_http - DIRECT/svn.eu.apache.org text/xml - 1318411082.686 190 127.0.0.1 TCP_MISS/207 609 PROPFIND http://svn.eu.apache.org/repos/asf/trafficserver/plugins/stats_over_http - DIRECT/svn.eu.apache.org text/xml - 1318411082.878 189 127.0.0.1 TCP_MISS/207 484 PROPFIND http://svn.eu.apache.org/repos/asf/!svn/vcc/default - DIRECT/svn.eu.apache.org text/xml - 1318411083.068 189 127.0.0.1 TCP_MISS/207 498 PROPFIND http://svn.eu.apache.org/repos/asf/!svn/bln/1182279 - DIRECT/svn.eu.apache.org text/xml - 1318411083.262 191 127.0.0.1 TCP_MISS/207 609 PROPFIND http://svn.eu.apache.org/repos/asf/trafficserver/plugins/stats_over_http - DIRECT/svn.eu.apache.org text/xml - 1318411083.453 190 127.0.0.1 TCP_MISS/207 484 PROPFIND http://svn.eu.apache.org/repos/asf/!svn/vcc/default - DIRECT/svn.eu.apache.org text/xml - 1318411083.645 190 127.0.0.1 TCP_MISS/207 498 PROPFIND http://svn.eu.apache.org/repos/asf/!svn/bln/1182279 - DIRECT/svn.eu.apache.org text/xml - 1318411084.118 473 127.0.0.1 TCP_MISS/200 11899 REPORT http://svn.eu.apache.org/repos/asf/!svn/vcc/default - DIRECT/svn.eu.apache.org text/xml - But of course, that uses a different library. - I just wanted to show that the proxy actually works.
          Hide
          Igor Galić added a comment -

          In reverse proxy mode: curl vs svn:

          igalic@tynix ~/src/asf % curl http://svn.apache.org/repos/asf/trafficserver/plugins/stats_over_http/
          <html><head><title>asf - Revision 1182271: /trafficserver/plugins/stats_over_http</title></head>
          <body>
           <h2>asf - Revision 1182271: /trafficserver/plugins/stats_over_http</h2>
           <ul>
            <li><a href="../">..</a></li>
            <li><a href="CHANGES">CHANGES</a></li>
            <li><a href="LICENSE">LICENSE</a></li>
            <li><a href="Makefile">Makefile</a></li>
            <li><a href="NOTICE">NOTICE</a></li>
            <li><a href="README">README</a></li>
            <li><a href="stats_over_http.c">stats_over_http.c</a></li>
           </ul>
           <hr noshade><em>Powered by <a href="http://subversion.tigris.org/">Subversion</a> version 1.6.17 (r1128011).</em>
          </body></html>%                                                                                                                                                                                                                                igalic@tynix ~/src/asf % svn co http://svn.apache.org/repos/asf/trafficserver/plugins/stats_over_http/
          subversion/svn/checkout-cmd.c:168: (apr_err=175002)
          subversion/libsvn_client/checkout.c:137: (apr_err=175002)
          subversion/libsvn_client/ra.c:492: (apr_err=175002)
          subversion/libsvn_client/ra.c:693: (apr_err=175002)
          subversion/libsvn_client/revisions.c:73: (apr_err=175002)
          subversion/libsvn_ra_serf/property.c:1022: (apr_err=175002)
          subversion/libsvn_ra_serf/util.c:2322: (apr_err=175002)
          subversion/libsvn_ra_serf/property.c:655: (apr_err=175002)
          subversion/libsvn_ra_serf/util.c:768: (apr_err=175002)
          subversion/libsvn_ra_serf/util.c:2094: (apr_err=175002)
          subversion/libsvn_ra_serf/util.c:2094: (apr_err=175002)
          svn: E175002: PROPFIND request on '/repos/asf/trafficserver/plugins/stats_over_http' failed: 504 Connection Timed Out
          1 igalic@tynix ~/src/asf % 
          

          squid.blob

          1318410084.440 190 127.0.0.1 TCP_MISS/200 905 OPTIONS http://svn.eu.apache.org/repos/asf/trafficserver/plugins/stats_over_http - DIRECT/svn.eu.apache.org text/xml -
          1318410268.720 184279 127.0.0.1 ERR_READ_TIMEOUT/504 438 PROPFIND http://svn.eu.apache.org/repos/asf/trafficserver/plugins/stats_over_http - TIMEOUT_DIRECT/svn.eu.apache.org text/html -
          1318410268.720 0 127.0.0.1 ERR_INVALID_REQ/400 217 - / - NONE/- text/html -
          
          Show
          Igor Galić added a comment - In reverse proxy mode: curl vs svn: igalic@tynix ~/src/asf % curl http://svn.apache.org/repos/asf/trafficserver/plugins/stats_over_http/ <html><head><title>asf - Revision 1182271: /trafficserver/plugins/stats_over_http</title></head> <body> <h2>asf - Revision 1182271: /trafficserver/plugins/stats_over_http</h2> <ul> <li><a href="../">..</a></li> <li><a href="CHANGES">CHANGES</a></li> <li><a href="LICENSE">LICENSE</a></li> <li><a href="Makefile">Makefile</a></li> <li><a href="NOTICE">NOTICE</a></li> <li><a href="README">README</a></li> <li><a href="stats_over_http.c">stats_over_http.c</a></li> </ul> <hr noshade><em>Powered by <a href="http://subversion.tigris.org/">Subversion</a> version 1.6.17 (r1128011).</em> </body></html>% igalic@tynix ~/src/asf % svn co http://svn.apache.org/repos/asf/trafficserver/plugins/stats_over_http/ subversion/svn/checkout-cmd.c:168: (apr_err=175002) subversion/libsvn_client/checkout.c:137: (apr_err=175002) subversion/libsvn_client/ra.c:492: (apr_err=175002) subversion/libsvn_client/ra.c:693: (apr_err=175002) subversion/libsvn_client/revisions.c:73: (apr_err=175002) subversion/libsvn_ra_serf/property.c:1022: (apr_err=175002) subversion/libsvn_ra_serf/util.c:2322: (apr_err=175002) subversion/libsvn_ra_serf/property.c:655: (apr_err=175002) subversion/libsvn_ra_serf/util.c:768: (apr_err=175002) subversion/libsvn_ra_serf/util.c:2094: (apr_err=175002) subversion/libsvn_ra_serf/util.c:2094: (apr_err=175002) svn: E175002: PROPFIND request on '/repos/asf/trafficserver/plugins/stats_over_http' failed: 504 Connection Timed Out 1 igalic@tynix ~/src/asf % squid.blob 1318410084.440 190 127.0.0.1 TCP_MISS/200 905 OPTIONS http://svn.eu.apache.org/repos/asf/trafficserver/plugins/stats_over_http - DIRECT/svn.eu.apache.org text/xml - 1318410268.720 184279 127.0.0.1 ERR_READ_TIMEOUT/504 438 PROPFIND http://svn.eu.apache.org/repos/asf/trafficserver/plugins/stats_over_http - TIMEOUT_DIRECT/svn.eu.apache.org text/html - 1318410268.720 0 127.0.0.1 ERR_INVALID_REQ/400 217 - / - NONE/- text/html -
          Leif Hedstrom made changes -
          Attachment TS-871.diff [ 12498682 ]
          Hide
          Leif Hedstrom added a comment -

          Proposed changes, slightly better comments etc.

          Show
          Leif Hedstrom added a comment - Proposed changes, slightly better comments etc.
          Leif Hedstrom made changes -
          Attachment TS-871.diff [ 12498673 ]
          Leif Hedstrom made changes -
          Attachment stats.diff [ 12498678 ]
          Hide
          Leif Hedstrom added a comment -

          I also think there's a bug in the stats code here. In the case of OPTIONS or TRACE methods, we erroneously also count these two methods as "extensions". This patches fixes this, I think.

          Show
          Leif Hedstrom added a comment - I also think there's a bug in the stats code here. In the case of OPTIONS or TRACE methods, we erroneously also count these two methods as "extensions". This patches fixes this, I think.
          Leif Hedstrom made changes -
          Assignee Leif Hedstrom [ zwoop ]
          Leif Hedstrom made changes -
          Attachment TS-871.diff [ 12498673 ]
          Hide
          Leif Hedstrom added a comment -

          Igor, can you try the attached diff (against trunk) ?

          Show
          Leif Hedstrom added a comment - Igor, can you try the attached diff (against trunk) ?
          Leif Hedstrom made changes -
          Status Open [ 1 ] Patch Available [ 10002 ]
          Leif Hedstrom made changes -
          Fix Version/s 3.1.1 [ 12316496 ]
          Affects Version/s 3.0.0 [ 12314754 ]
          Affects Version/s 3.1.1 [ 12316496 ]
          Hide
          Leif Hedstrom added a comment -

          Looking at the wire, it seems ATS forwards the request to the SVN "origin" without the body :-/. I'm not sure why yet.

          Show
          Leif Hedstrom added a comment - Looking at the wire, it seems ATS forwards the request to the SVN "origin" without the body :-/. I'm not sure why yet.
          Hide
          Leif Hedstrom added a comment -

          This seems to reproduce it:

          loki (19:05) 641/0 $ telnet localhost 80
          Trying 127.0.0.1...
          Connected to localhost.
          Escape character is '^]'.
          OPTIONS http://svn.apache.org/repos/asf/trafficserver/plugins/stats_over_http HTTP/1.1
          Host: svn.apache.org
          User-Agent: SVN/1.7.0-dev serf/1.0.0
          Content-Type: text/xml
          DAV: http://subversion.tigris.org/xmlns/dav/svn/depth
          DAV: http://subversion.tigris.org/xmlns/dav/svn/mergeinfo
          DAV: http://subversion.tigris.org/xmlns/dav/svn/log-revprops
          Transfer-Encoding: chunked
          
          83
          <?xml version="1.0" encoding="utf-8"?><D:options xmlns:D="DAV:"><D:activity-collection-set></D:activity-collection-set></D:options>
          0
          
          Show
          Leif Hedstrom added a comment - This seems to reproduce it: loki (19:05) 641/0 $ telnet localhost 80 Trying 127.0.0.1... Connected to localhost. Escape character is '^]'. OPTIONS http: //svn.apache.org/repos/asf/trafficserver/plugins/stats_over_http HTTP/1.1 Host: svn.apache.org User-Agent: SVN/1.7.0-dev serf/1.0.0 Content-Type: text/xml DAV: http: //subversion.tigris.org/xmlns/dav/svn/depth DAV: http: //subversion.tigris.org/xmlns/dav/svn/mergeinfo DAV: http: //subversion.tigris.org/xmlns/dav/svn/log-revprops Transfer-Encoding: chunked 83 <?xml version= "1.0" encoding= "utf-8" ?><D:options xmlns:D= "DAV:" ><D:activity-collection-set></D:activity-collection-set></D:options> 0
          Hide
          Igor Galić added a comment -

          It should be said that it doesn't make much sense to compare this with how svn's other http lib: neon, behaves. Neon encapsulates the whole request in one "transaction", while serf does gazillion of requests.

          Show
          Igor Galić added a comment - It should be said that it doesn't make much sense to compare this with how svn's other http lib: neon, behaves. Neon encapsulates the whole request in one "transaction", while serf does gazillion of requests.
          Igor Galić made changes -
          Attachment revats_Thttp.debug.notime.txt [ 12485517 ]
          Hide
          Igor Galić added a comment -

          no times for easier diff

          Show
          Igor Galić added a comment - no times for easier diff
          Igor Galić made changes -
          Attachment serf_revproxy.cap [ 12485515 ]
          Hide
          Igor Galić added a comment -

          pcap of the before traffic_server capture

          Show
          Igor Galić added a comment - pcap of the before traffic_server capture
          Igor Galić made changes -
          Attachment revats_Thttp.debug.txt [ 12485514 ]
          Hide
          Igor Galić added a comment -
          Show
          Igor Galić added a comment - ATS configured in reverse proxy mode: map http://svn.apache.org/ http://svn.eu.apache.org/ reverse_map http://svn.eu.apache.org/ http://svn.apache.org/ map https://svn.apache.org/ https://svn.eu.apache.org/ reverse_map https://svn.eu.apache.org/ https://svn.apache.org/ with 127.0.1.3 svn.apache.org in /etc/hosts
          Igor Galić made changes -
          Attachment ats_Thttp.debug.notime.txt [ 12485513 ]
          Hide
          Igor Galić added a comment -

          Same as before but with no time stamps for easier diff with the next file

          Show
          Igor Galić added a comment - Same as before but with no time stamps for easier diff with the next file
          Igor Galić made changes -
          Summary Subversion (1.7) with serf fails with ATS in forward mode Subversion (1.7) with serf fails with ATS in forward and reverse proxy mode
          Igor Galić made changes -
          Attachment serf_proxy.cap [ 12485509 ]
          Hide
          Igor Galić added a comment -

          tshark -w serf_proxy.cap -i lo port 8080

          Show
          Igor Galić added a comment - tshark -w serf_proxy.cap -i lo port 8080
          Igor Galić made changes -
          Field Original Value New Value
          Attachment ats_Thttp.debug.txt [ 12485508 ]
          Hide
          Igor Galić added a comment -

          traffic_server -Thttp

          Show
          Igor Galić added a comment - traffic_server -Thttp
          Igor Galić created issue -

            People

            • Assignee:
              Leif Hedstrom
              Reporter:
              Igor Galić
            • Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated:

                Development