[
https://issues.apache.org/jira/browse/TS-2497?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13984173#comment-13984173
]
Shaun McGinnity commented on TS-2497:
-------------------------------------
Hi Brian,
yes, it is a simple test simulating a server closing the connection before
reading the complete post. I am sending a post with Content-Length: 3100000.
The server reads 100000 bytes and then closes the connection.
I have added some debug. On a successful post
HttpSM::tunnel_handler_post_or_put deallocates the buffers created for the post
tunnel:
Apr 29 11:04:10 - INFO - HttpSM::attach_client_session 0x10d5b980 0x10d5d598
Apr 29 11:04:10 - INFO - free_MIOBuffer 0x5001350
Apr 29 11:04:10 - INFO - free_MIOBuffer 0x5001350 DONE
Apr 29 11:04:10 - INFO - HttpSM::do_setup_post_tunnel 0x10d5b980 add_producer :
buffer 0x5001368
Apr 29 11:04:10 - INFO - HttpTunnel::add_producer : 0x10d5d598 buffer_start =
0x5001368 read_buffer = 0x5001350
Apr 29 11:05:29 - INFO - HttpSM::tunnel_handler_post_or_put :
HTTP_SM_POST_SUCCESS deallocate_buffers 0x10d5d598
Apr 29 11:05:29 - INFO - 0x10d5d598 :: deallocate_buffers
Apr 29 11:05:29 - INFO - 0x10d5d598 :: deallocate_buffers : free
producers[0].read_buffer 0x5001350
Apr 29 11:05:29 - INFO - free_MIOBuffer 0x5001350
Apr 29 11:05:29 - INFO - free_MIOBuffer 0x5001350 DONE
Apr 29 11:05:29 - INFO - HttpTunnel::reset 0x10d5d598
Apr 29 11:05:29 - INFO - HttpSM::setup_server_transfer 0x10d5b980 add_producer
: buffer 0x5001368
Apr 29 11:05:29 - INFO - HttpTunnel::add_producer : 0x10d5d598 buffer_start =
0x5001368 read_buffer = 0x5001350
Apr 29 11:05:29 - INFO - free_MIOBuffer 0x5001620
Apr 29 11:05:29 - INFO - free_MIOBuffer 0x5001620 DONE
Apr 29 11:05:29 - INFO - HttpSM::kill_this : deallocate_buffers 0x10d5d598
Apr 29 11:05:29 - INFO - 0x10d5d598 :: deallocate_buffers
Apr 29 11:05:29 - INFO - 0x10d5d598 :: deallocate_buffers : free
producers[0].read_buffer 0x5001350
Apr 29 11:05:29 - INFO - free_MIOBuffer 0x5001350
Apr 29 11:05:29 - INFO - free_MIOBuffer 0x5001350 DONE
Apr 29 11:05:29 - INFO - free_MIOBuffer 0x5001710
Apr 29 11:05:29 - INFO - free_MIOBuffer 0x5001710 DONE
On a failed post the buffer used in the post tunnel is not freed:
Apr 29 11:03:54 - INFO - HttpSM::attach_client_session 0x10d5b980 0x10d5d598
Apr 29 11:03:54 - INFO - free_MIOBuffer 0x5001440
Apr 29 11:03:54 - INFO - free_MIOBuffer 0x5001440 DONE
Apr 29 11:03:54 - INFO - HttpSM::do_setup_post_tunnel 0x10d5b980 add_producer :
buffer 0x5001458
Apr 29 11:03:54 - INFO - HttpTunnel::add_producer : 0x10d5d598 buffer_start =
0x5001458 read_buffer = 0x5001440
Apr 29 11:03:57 - INFO - HttpSM::tunnel_handler_post_or_put :
HTTP_SM_POST_SERVER_FAIL 0x10d5d598
Apr 29 11:03:57 - INFO - HttpSM::handle_post_failure : 0x10d5d598
Apr 29 11:03:57 - INFO - ua_session->do_io_read
Apr 29 11:03:57 - INFO - HttpTunnel::reset 0x10d5d598
Apr 29 11:03:57 - INFO - free_MIOBuffer 0x5001620
Apr 29 11:03:57 - INFO - free_MIOBuffer 0x5001620 DONE
Apr 29 11:03:57 - INFO - HttpSM::setup_internal_transfer 0x10d5b980
add_producer : buffer 0x5001638
Apr 29 11:03:57 - INFO - HttpTunnel::add_producer : 0x10d5d598 buffer_start =
0x5001638 read_buffer = 0x5001620
Apr 29 11:03:57 - INFO - HttpSM::kill_this : deallocate_buffers 0x10d5d598
Apr 29 11:03:57 - INFO - 0x10d5d598 :: deallocate_buffers
Apr 29 11:03:57 - INFO - 0x10d5d598 :: deallocate_buffers : free
producers[0].read_buffer 0x5001620
Apr 29 11:03:57 - INFO - free_MIOBuffer 0x5001620
Apr 29 11:03:57 - INFO - free_MIOBuffer 0x5001620 DONE
Apr 29 11:03:57 - INFO - free_MIOBuffer 0x5001710
Apr 29 11:03:57 - INFO - free_MIOBuffer 0x5001710 DONE
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)
