[
https://issues.apache.org/jira/browse/TS-2497?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13984753#comment-13984753
]
Shaun McGinnity commented on TS-2497:
-------------------------------------
hi Brian,
here is the debug with the buffer allocation locations recorded:
Apr 29 21:13:29 - INFO - HttpSM::attach_client_session 0x10613980 0x10615598
Apr 29 21:13:29 - INFO - free_MIOBuffer 0x49b5530
memory/IOBuffer/HttpSM.cc:5575 --> setup_server_send_request
Apr 29 21:13:29 - INFO - free_MIOBuffer 0x49b5530 DONE
Apr 29 21:13:29 - INFO - HttpSM::do_setup_post_tunnel 0x10613980 add_producer :
buffer 0x49b5548
Apr 29 21:13:29 - INFO - HttpTunnel::add_producer : 0x10615598 buffer_start =
0x49b5548 read_buffer = 0x49b5530
Apr 29 21:14:47 - INFO - HttpSM::tunnel_handler_post_or_put :
HTTP_SM_POST_SUCCESS deallocate_buffers 0x10615598
Apr 29 21:14:47 - INFO - 0x10615598 :: deallocate_buffers
Apr 29 21:14:47 - INFO - 0x10615598 :: deallocate_buffers : free
producers[0].read_buffer 0x49b5530
Apr 29 21:14:47 - INFO - free_MIOBuffer 0x49b5530
memory/IOBuffer/HttpSM.cc:5259 --> do_setup_post_tunnel
Apr 29 21:14:47 - INFO - free_MIOBuffer 0x49b5530 DONE
Apr 29 21:14:47 - INFO - HttpTunnel::reset 0x10615598
Apr 29 21:14:47 - INFO - HttpSM::setup_server_transfer 0x10613980 add_producer
: buffer 0x49b5548
Apr 29 21:14:47 - INFO - HttpTunnel::add_producer : 0x10615598 buffer_start =
0x49b5548 read_buffer = 0x49b5530
Apr 29 21:14:47 - INFO - free_MIOBuffer 0x49b5620
memory/IOBuffer/HttpServerSession.cc:87 --> HttpServerSession::new_connection
Apr 29 21:14:47 - INFO - free_MIOBuffer 0x49b5620 DONE
Apr 29 21:14:47 - INFO - HttpSM::kill_this : deallocate_buffers 0x10615598
Apr 29 21:14:47 - INFO - 0x10615598 :: deallocate_buffers
Apr 29 21:14:47 - INFO - 0x10615598 :: deallocate_buffers : free
producers[0].read_buffer 0x49b5530
Apr 29 21:14:47 - INFO - free_MIOBuffer 0x49b5530
memory/IOBuffer/HttpSM.cc:6189 --> setup_server_transfer
Apr 29 21:14:47 - INFO - free_MIOBuffer 0x49b5530 DONE
Apr 29 21:14:47 - INFO - free_MIOBuffer 0x49b5710
memory/IOBuffer/HttpClientSession.cc:237 --> HttpClientSession::new_connection
Apr 29 21:14:47 - INFO - free_MIOBuffer 0x49b5710 DONE
Post failure:
Apr 29 21:32:08 - INFO - HttpSM::attach_client_session 0x11869980 0x1186b598
Apr 29 21:32:08 - INFO - free_MIOBuffer 0x5c37530
memory/IOBuffer/HttpSM.cc:5575 --> setup_server_send_request
Apr 29 21:32:08 - INFO - free_MIOBuffer 0x5c37530 DONE
Apr 29 21:32:08 - INFO - HttpSM::do_setup_post_tunnel 0x11869980 add_producer :
buffer 0x5c37548
Apr 29 21:32:08 - INFO - HttpTunnel::add_producer : 0x1186b598 buffer_start =
0x5c37548 read_buffer = 0x5c37530
Apr 29 21:32:11 - INFO - HttpSM::tunnel_handler_post_or_put :
HTTP_SM_POST_SERVER_FAIL 0x1186b598
Apr 29 21:32:11 - INFO - HttpSM::handle_post_failure : 0x1186b598
Apr 29 21:32:11 - INFO - ua_session->do_io_read
Apr 29 21:32:11 - INFO - HttpTunnel::reset 0x1186b598
Apr 29 21:32:11 - INFO - free_MIOBuffer 0x5c37620
memory/IOBuffer/HttpServerSession.cc:87 --> HttpServerSession::new_connection
Apr 29 21:32:11 - INFO - free_MIOBuffer 0x5c37620 DONE
Apr 29 21:32:11 - INFO - HttpSM::setup_internal_transfer 0x11869980
add_producer : buffer 0x5c37638
Apr 29 21:32:11 - INFO - HttpTunnel::add_producer : 0x1186b598 buffer_start =
0x5c37638 read_buffer = 0x5c37620
Apr 29 21:32:11 - INFO - HttpSM::kill_this : deallocate_buffers 0x1186b598
Apr 29 21:32:11 - INFO - 0x1186b598 :: deallocate_buffers
Apr 29 21:32:11 - INFO - 0x1186b598 :: deallocate_buffers : free
producers[0].read_buffer 0x5c37620
Apr 29 21:32:11 - INFO - free_MIOBuffer 0x5c37620
memory/IOBuffer/HttpSM.cc:5889 --> HttpSM::setup_internal_transfer
Apr 29 21:32:11 - INFO - free_MIOBuffer 0x5c37620 DONE
Apr 29 21:32:11 - INFO - free_MIOBuffer 0x5c37710
memory/IOBuffer/HttpClientSession.cc:237 --> HttpClientSession::new_connection
Apr 29 21:32:11 - INFO - free_MIOBuffer 0x5c37710 DONE
There are 4 frees compared to 5 in the successful case. The buffer that is not
freed is created in HttpSM::do_setup_post_tunnel.
With the change removed i.e. call made to HttpTunnel deallocate_buffers in
handle_post_failure then we get 5 frees.
Apr 29 21:21:51 - INFO - HttpSM::attach_client_session 0x10613980 0x10615598
Apr 29 21:21:51 - INFO - free_MIOBuffer 0x49b5620
memory/IOBuffer/HttpSM.cc:5575 --> setup_server_send_request
Apr 29 21:21:51 - INFO - free_MIOBuffer 0x49b5620 DONE
Apr 29 21:21:51 - INFO - HttpSM::do_setup_post_tunnel 0x10613980 add_producer :
buffer 0x49b5638
Apr 29 21:21:51 - INFO - HttpTunnel::add_producer : 0x10615598 buffer_start =
0x49b5638 read_buffer = 0x49b5620
Apr 29 21:21:54 - INFO - HttpSM::tunnel_handler_post_or_put :
HTTP_SM_POST_SERVER_FAIL 0x10615598
Apr 29 21:21:54 - INFO - HttpSM::handle_post_failure : 0x10615598
Apr 29 21:21:54 - INFO - ua_session->do_io_read
Apr 29 21:21:54 - INFO - 0x10615598 :: deallocate_buffers
Apr 29 21:21:54 - INFO - 0x10615598 :: deallocate_buffers : free
producers[0].read_buffer 0x49b5620
Apr 29 21:21:54 - INFO - free_MIOBuffer 0x49b5620
memory/IOBuffer/HttpSM.cc:5259 --> do_setup_post_tunnel
Apr 29 21:21:54 - INFO - free_MIOBuffer 0x49b5620 DONE
Apr 29 21:21:54 - INFO - HttpTunnel::reset 0x10615598
Apr 29 21:21:54 - INFO - free_MIOBuffer 0x49b5530
memory/IOBuffer/HttpServerSession.cc:87 --> HttpServerSession::new_connection
Apr 29 21:21:54 - INFO - free_MIOBuffer 0x49b5530 DONE
Apr 29 21:21:54 - INFO - HttpSM::setup_internal_transfer 0x10613980
add_producer : buffer 0x49b5548
Apr 29 21:21:54 - INFO - HttpTunnel::add_producer : 0x10615598 buffer_start =
0x49b5548 read_buffer = 0x49b5530
Apr 29 21:21:54 - INFO - HttpSM::kill_this : deallocate_buffers 0x10615598
Apr 29 21:21:54 - INFO - 0x10615598 :: deallocate_buffers
Apr 29 21:21:54 - INFO - 0x10615598 :: deallocate_buffers : free
producers[0].read_buffer 0x49b5530
Apr 29 21:21:54 - INFO - free_MIOBuffer 0x49b5530
memory/IOBuffer/HttpSM.cc:5889 --> HttpSM::setup_internal_transfer
Apr 29 21:21:54 - INFO - free_MIOBuffer 0x49b5530 DONE
Apr 29 21:21:54 - INFO - free_MIOBuffer 0x49b5710
memory/IOBuffer/HttpClientSession.cc:237 -->
HttpClientSession::new_connection
Apr 29 21:21:54 - INFO - free_MIOBuffer 0x49b5710 DONE
I am using curl to send the post request and a simple java server to terminate
the connection early. It is not using the regression test framework.
Let me know if you need more debug.
Regards,
Shaun
> Failed post results in tunnel buffers being returned to freelist prematurely
> ----------------------------------------------------------------------------
>
> Key: TS-2497
> URL: https://issues.apache.org/jira/browse/TS-2497
> Project: Traffic Server
> Issue Type: Bug
> Components: Core
> Reporter: Brian Geffon
> Assignee: Brian Geffon
> Fix For: 4.2.0
>
>
> When a post fails to an origin server either the server died or the server
> returned a response without reading all of the post data, in either case, TS
> will destroy buffers too early. This normally does not result in a crash
> because the MIOBuffers are returned to the freelist and only with sufficient
> load will the race happen causing a crash. Additionally, even if a crash
> doesn't happen you might have data corruption across post requests from the
> buffers being used after being returned to the freelist.
> Thanks to Thomas Jackson for help reproducing and resolving this bug.
> An example stack trace, while we've seen other crashes in write_avail too.
> #0 0x00000000004eff14 in IOBufferBlock::read_avail (this=0x0) at
> ../iocore/eventsystem/I_IOBuffer.h:362
> #1 0x000000000050d151 in MIOBuffer::append_block_internal
> (this=0x2aab38001130, b=0x2aab0c037200) at
> ../iocore/eventsystem/P_IOBuffer.h:946
> #2 0x000000000050d39b in MIOBuffer::append_block (this=0x2aab38001130,
> asize_index=15) at ../iocore/eventsystem/P_IOBuffer.h:986
> #3 0x000000000050d49b in MIOBuffer::add_block (this=0x2aab38001130) at
> ../iocore/eventsystem/P_IOBuffer.h:994
> #4 0x000000000055cee2 in MIOBuffer::check_add_block (this=0x2aab38001130) at
> ../iocore/eventsystem/P_IOBuffer.h:1002
> #5 0x000000000055d115 in MIOBuffer::write_avail (this=0x2aab38001130) at
> ../iocore/eventsystem/P_IOBuffer.h:1048
> #6 0x00000000006c18f3 in read_from_net (nh=0x2aaafca0d208,
> vc=0x2aab1c009140, thread=0x2aaafca0a010) at UnixNetVConnection.cc:234
> #7 0x00000000006c37bf in UnixNetVConnection::net_read_io
> (this=0x2aab1c009140, nh=0x2aaafca0d208, lthread=0x2aaafca0a010) at
> UnixNetVConnection.cc:816
> #8 0x00000000006be392 in NetHandler::mainNetEvent (this=0x2aaafca0d208,
> event=5, e=0x271d8e0) at UnixNet.cc:380
> #9 0x00000000004f05c4 in Continuation::handleEvent (this=0x2aaafca0d208,
> event=5, data=0x271d8e0) at ../iocore/eventsystem/I_Continuation.h:146
> #10 0x00000000006e361e in EThread::process_event (this=0x2aaafca0a010,
> e=0x271d8e0, calling_code=5) at UnixEThread.cc:142
> #11 0x00000000006e3b13 in EThread::execute (this=0x2aaafca0a010) at
> UnixEThread.cc:264
> #12 0x00000000006e290b in spawn_thread_internal (a=0x2716400) at Thread.cc:88
> #13 0x0000003372c077e1 in start_thread () from /lib64/libpthread.so.0
> #14 0x00000033728e68ed in clone () from /lib64/libc.so.6
--
This message was sent by Atlassian JIRA
(v6.2#6252)
