Serf crash on spurious data between responses

While debugging a problem reported on users I accidentally sent an extra
byte to the client: I sent Content-Length of N and then sent N+1 bytes.
The first N bytes made a valid response, so serf was happy at that
stage. When processing the next request the extra byte causes serf to
attempt to handle the spurious data before any request handler is setup.
This is with serf 1.3.x_at_2440.

I have a script to reproduce the problem. The script creates a dumb
server that responds with two OPTIONS responses, but it writes some
spurious data between the valid responses. With pool debugging and
valgrind I see this:

$ valgrind -q subversion/svn/.libs/lt-svn ls http://127.0.0.1:7777/svn/t_sponis_testrepo
==8150== Invalid read of size 4
==8150== at 0x6509DA5: serf_bucket_mem_alloc (allocator.c:172)
==8150== by 0x650A048: serf_bucket_barrier_create (barrier_buckets.c:33)
==8150== by 0x5239857: accept_response (util.c:574)
==8150== by 0x6507DBA: read_from_connection (outgoing.c:1120)
==8150== by 0x650800C: serf__process_connection (outgoing.c:1247)
==8150== by 0x6505B0A: serf_event_trigger (context.c:226)
==8150== by 0x6505C8D: serf_context_run (context.c:300)
==8150== by 0x5239F78: svn_ra_serf__context_run (util.c:859)
==8150== by 0x523A1D5: svn_ra_serf__context_run_wait (util.c:930)
==8150== by 0x523A297: svn_ra_serf__context_run_one (util.c:954)
==8150== by 0x522992F: svn_ra_serf__probe_proxy (options.c:562)
==8150== by 0x522F61C: svn_ra_serf__open (serf.c:607)
==8150== Address 0x8e64868 is 40 bytes inside a block of size 72 free'd
==8150== at 0x402AF4C: free (vg_replace_malloc.c:468)
==8150== by 0x4BB51F9: pool_clear_debug (apr_pools.c:1576)
==8150== by 0x4BB534D: pool_destroy_debug (apr_pools.c:1638)
==8150== by 0x4BB5436: apr_pool_destroy_debug (apr_pools.c:1680)
==8150== by 0x6506E4B: destroy_request (outgoing.c:502)
==8150== by 0x6507EE0: read_from_connection (outgoing.c:1186)
==8150== by 0x650800C: serf__process_connection (outgoing.c:1247)
==8150== by 0x6505B0A: serf_event_trigger (context.c:226)
==8150== by 0x6505C8D: serf_context_run (context.c:300)
==8150== by 0x5239F78: svn_ra_serf__context_run (util.c:859)
==8150== by 0x523A1D5: svn_ra_serf__context_run_wait (util.c:930)
==8150== by 0x523A297: svn_ra_serf__context_run_one (util.c:954)

In gdb I see:

(gdb) r
Starting program: /home/pm/sw/subversion/obj-1.8/subversion/svn/.libs/lt-svn ls http://127.0.0.1:7777/svn/t_sponis_testrepo

Breakpoint 2, setup_request (request=0x460288) at outgoing.c:693
693 apr_pool_create(&request->respool, conn->pool);
(gdb) c
Continuing.

Breakpoint 3, read_from_connection (conn=0x45bf40) at outgoing.c:1120
1120 request->resp_bkt = (*request->acceptor)(request, conn->stream,
(gdb)
Continuing.

Breakpoint 1, destroy_request (request=0x460288) at outgoing.c:502
502 apr_pool_destroy(request->respool);
(gdb)
Continuing.

Breakpoint 3, read_from_connection (conn=0x45bf40) at outgoing.c:1120
1120 request->resp_bkt = (*request->acceptor)(request, conn->stream,
(gdb)

The final call to request->acceptor() occurs after destroy_request() but
before the next setup_request().

#!/usr/bin/python
import SocketServer
import re

class MyTCPHandler(SocketServer.StreamRequestHandler):

  responses = [
    ('HTTP/1.1 200 OK\r\n'
     'SVN-Repository-MergeInfo: yes\r\n'
     'SVN-Allow-Bulk-Updates: On\r\n'
     'SVN-Rev-Root-Stub: /svn/t_sponis_testrepo/!svn/rvr\r\n'
     'Content-Length: 201\r\n'
     'SVN-Txn-Root-Stub: /svn/t_sponis_testrepo/!svn/txr\r\n'
     'SVN-VTxn-Root-Stub: /svn/t_sponis_testrepo/!svn/vtxr\r\n'
     'SVN-Repository-UUID: 0926ec5e-c495-11e3-b81a-bb1aca739395\r\n'
     'Server: Apache\r\n'
     'DAV: 1,2, version-control,checkout,working-resource, merge,baseline,activity,version-controlled-collection, http://subversion.tigris.org/xmlns/dav/svn/depth, http://subversion.tigris.org/xmlns/dav/svn/log-revprops, http://subversion.tigris.org/xmlns/dav/svn/atomic-revprops, http://subversion.tigris.org/xmlns/dav/svn/partial-replay, http://subversion.tigris.org/xmlns/dav/svn/inherited-props, http://subversion.tigris.org/xmlns/dav/svn/inline-props, http://subversion.tigris.org/xmlns/dav/svn/reverse-file-revs, http://subversion.tigris.org/xmlns/dav/svn/mergeinfo, http://subversion.tigris.org/xmlns/dav/svn/ephemeral-txnprops, http://subversion.tigris.org/xmlns/dav/svn/replay-rev-resource\r\n'
     'SVN-VTxn-Stub: /svn/t_sponis_testrepo/!svn/vtxn\r\n'
     'SVN-Rev-Stub: /svn/t_sponis_testrepo/!svn/rev\r\n'
     'MS-Author-Via: DAV\r\n'
     'SVN-Me-Resource: /svn/t_sponis_testrepo/!svn/me\r\n'
     'Date: Tue, 06 Jan 2015 14:43:25 GMT\r\n'
     'SVN-Txn-Stub: /svn/t_sponis_testrepo/!svn/txn\r\n'
     'Allow: OPTIONS,GET,HEAD,POST,DELETE,TRACE,PROPFIND,PROPPATCH,COPY,MOVE,LOCK,UNLOCK,CHECKOUT\r\n'
     'SVN-Repository-Root: /svn/t_sponis_testrepo\r\n'
     'SVN-Supported-Posts: create-txn, create-txn-with-props\r\n'
     'Content-Type: text/xml; charset="utf-8\r\n'
     'SVN-Youngest-Rev: 16\r\n'
     '\r\n'
     '<?xml version="1.0" encoding="utf-8"?>\n'
     '<D:options-response xmlns:D="DAV:">\n'
     '<D:activity-collection-set><D:href>/svn/t_sponis_testrepo/!svn/act/</D:href></D:activity-collection-set></D:options-response>\n'
     'spurious data'
     ),
    ('HTTP/1.1 200 OK\r\n'
     'DAV: 1,2, version-control,checkout,working-resource, merge,baseline,activity,version-controlled-collection, http://subversion.tigris.org/xmlns/dav/svn/depth, http://subversion.tigris.org/xmlns/dav/svn/log-revprops, http://subversion.tigris.org/xmlns/dav/svn/atomic-revprops, http://subversion.tigris.org/xmlns/dav/svn/partial-replay, http://subversion.tigris.org/xmlns/dav/svn/inherited-props, http://subversion.tigris.org/xmlns/dav/svn/inline-props, http://subversion.tigris.org/xmlns/dav/svn/reverse-file-revs, http://subversion.tigris.org/xmlns/dav/svn/mergeinfo\r\n'
     'MS-Author-Via: DAV\r\n'
     'Date: Tue, 06 Jan 2015 14:43:25 GMT\r\n'
     'Content-Length: 97\r\n'
     'Allow: OPTIONS,GET,HEAD,POST,DELETE,TRACE,PROPFIND,PROPPATCH,COPY,MOVE,LOCK,UNLOCK,CHECKOUT\r\n'
     'Content-Type: text/xml; charset="utf-8\r\n'
     'Server: Apache\r\n'
     '\r\n'
     '<?xml version="1.0" encoding="utf-8"?>\n'
     '<D:options-response xmlns:D="DAV:">\n'
     '</D:options-response>\n'
     ),
    ]
  response = 0
    
  def handle(self):
    clen = None
    chunked = False
    while True:
      self.data = self.rfile.readline().strip()
      print "read: " + self.data
      if self.data == "Transfer-Encoding: chunked":
        chunked = True
      m = re.match('Content-Length: (.*)', self.data)
      if m:
        clen = int(m.group(1))
      if self.data == '':
        break
    if chunked: # Handling one chunk is enough for now
      self.data = self.rfile.readline().strip()
      print "read: " + self.data
      clen = int(self.data, 16)
    if clen:
      self.data = self.rfile.read(clen)
      print "read: " + self.data
    if chunked:
      self.data = self.rfile.readline().strip()
      self.data = self.rfile.readline().strip()
      print "read: " + self.data

    self.wfile.write(MyTCPHandler.responses[MyTCPHandler.response])
    MyTCPHandler.response += 1
    if MyTCPHandler.response == 7:
      MyTCPHandler.response = 0

if __name__ == "__main__":

  SocketServer.TCPServer.allow_reuse_address = True
  server = SocketServer.TCPServer(("localhost", 7777), MyTCPHandler)
  server.serve_forever()

-- 
Philip Martin | Subversion Committer
WANdisco // *Non-Stop Data*