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@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*
