[
https://issues.apache.org/jira/browse/TS-3487?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14485371#comment-14485371
]
Feifei Cai commented on TS-3487:
--------------------------------
{{transaction_no_activity_timeout_in}} specifies how long ATS keeps connections
to clients open if a transaction stalls. In my understanding, each time before
ATS starts to read from or write to client (e.g. read client request headers,
read client request body, write response to client...), we setup a
{{transaction_no_activity_timeout_in}} timer, assuming that the transaction is
on no-activity status. Once ATS read data from or write data to client, the
transaction switches to active status, we reset the
{{transaction_no_activity_timeout_in}} timer. The timer only runs between last
read/write and next read/write. Every read/write will reset the timer, since a
read/write means that the transaction switches status from no-activity status
to active status.
In the current implementation, we set up {{transaction_no_activity_timeout_in}}
timer at 2 points:
# {{HttpSM::state_read_client_request_header}}
# {{HttpTransact::SM_ACTION_API_SEND_RESPONSE_HDR}}
This works fine for GET method, because ATS read from or write to client only
at these 2 points. However, for POST method, the point
{{HttpSM::do_setup_post_tunnel}} is missed. We need to set up the timer with
the newest configuration, because {{transaction_no_activity_timeout_in}} may
have been overridden in some hook points between
{{HttpSM::state_read_client_request_header}} and
{{HttpSM::do_setup_post_tunnel}}.
Please take a look at the debug output as follows, it's the test result of my
local python test:
{noformat}
$ traffic_server -T '(http_cs|http_ss|inactivity|socket)'
traffic_server: using root directory '/tmp/tsqa/base_envs/tmp9hwEUd'
[Apr 8 14:57:01.119] Server {0x7fa8e276c800} NOTE: Traffic Server is running
unprivileged, not switching to user 'nobody'
[Apr 8 14:57:01.128] Server {0x7fa8e276c800} DEBUG: (inactivity_cop) default
inactivity timeout is set to: 86400
[Apr 8 14:57:04.683] Server {0x7fa8e276c800} DEBUG: (socket) net_activity
updating inactivity 0, NetVC=0x7fa8d8016600
[Apr 8 14:57:04.683] Server {0x7fa8e276c800} DEBUG: (http_cs) [0] session
born, netvc 0x7fa8d8016600
[Apr 8 14:57:04.683] Server {0x7fa8e276c800} DEBUG: (http_cs) [0] Starting
transaction 1 using sm [0]
[Apr 8 14:57:04.683] Server {0x7fa8e276c800} DEBUG: (socket)
UnixNetVConnection::remove_from_keep_alive_lru NetVC=0x7fa8d8016600
[Apr 8 14:57:04.683] Server {0x7fa8e276c800} DEBUG: (socket) Set inactive
timeout=120000000000, for NetVC=0x7fa8d8016600
[Apr 8 14:57:04.683] Server {0x7fa8e276c800} DEBUG: (socket) Set active
timeout=900000000000, NetVC=0x7fa8d8016600
[Apr 8 14:57:04.683] Server {0x7fa8e276c800} DEBUG: (socket) Set inactive
timeout=5000000000, for NetVC=0x7fa8d8016600
[Apr 8 14:57:05.131] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505025131303369 timeout at: 1428505029 timeout in: 5
[Apr 8 14:57:06.141] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505026141133710 timeout at: 1428505029 timeout in: 5
[Apr 8 14:57:06.702] Server {0x7fa8e276c800} DEBUG: (socket) net_activity
updating inactivity 5000000000, NetVC=0x7fa8d8016600
[Apr 8 14:57:07.138] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505027138484319 timeout at: 1428505031 timeout in: 5
[Apr 8 14:57:08.137] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505028137647712 timeout at: 1428505031 timeout in: 5
[Apr 8 14:57:09.140] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505029140409681 timeout at: 1428505031 timeout in: 5
[Apr 8 14:57:09.687] Server {0x7fa8e276c800} DEBUG: (socket) net_activity
updating inactivity 5000000000, NetVC=0x7fa8d8016600
[Apr 8 14:57:09.687] Server {0x7fa8e276c800} DEBUG: (socket) ::open:
setsockopt() TCP_NODELAY on socket
[Apr 8 14:57:09.687] Server {0x7fa8e276c800} DEBUG: (http_ss) [0] session
born, netvc 0x7fa8d8016340
[Apr 8 14:57:09.687] Server {0x7fa8e276c800} DEBUG: (socket) Set inactive
timeout=1800000000000, for NetVC=0x7fa8d8016340
[Apr 8 14:57:09.687] Server {0x7fa8e276c800} DEBUG: (socket) Set active
timeout=0, NetVC=0x7fa8d8016340
[Apr 8 14:57:09.687] Server {0x7fa8e276c800} DEBUG: (socket) read_disable
updating inactivity_at 0, NetVC=0x7fa8d8016600
[Apr 8 14:57:09.917] Server {0x7fa8e276c800} DEBUG: (socket) net_activity
updating inactivity 1800000000000, NetVC=0x7fa8d8016340
[Apr 8 14:57:10.139] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016340 now: 1428505030139478064 timeout at: 1428506829 timeout in:
1800
[Apr 8 14:57:10.139] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505030139478064 timeout at: 1428505034 timeout in: 5
[Apr 8 14:57:11.138] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016340 now: 1428505031138038881 timeout at: 1428506829 timeout in:
1800
[Apr 8 14:57:11.138] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505031138038881 timeout at: 1428505034 timeout in: 5
[Apr 8 14:57:11.689] Server {0x7fa8e276c800} DEBUG: (socket) net_activity
updating inactivity 5000000000, NetVC=0x7fa8d8016600
[Apr 8 14:57:11.689] Server {0x7fa8e276c800} DEBUG: (socket) net_activity
updating inactivity 1800000000000, NetVC=0x7fa8d8016340
[Apr 8 14:57:12.134] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016340 now: 1428505032134839215 timeout at: 1428506831 timeout in:
1800
[Apr 8 14:57:12.134] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505032134839215 timeout at: 1428505036 timeout in: 5
[Apr 8 14:57:13.135] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016340 now: 1428505033135687382 timeout at: 1428506831 timeout in:
1800
[Apr 8 14:57:13.135] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505033135687382 timeout at: 1428505036 timeout in: 5
[Apr 8 14:57:14.139] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016340 now: 1428505034139220082 timeout at: 1428506831 timeout in:
1800
[Apr 8 14:57:14.139] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505034139220082 timeout at: 1428505036 timeout in: 5
[Apr 8 14:57:15.144] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016340 now: 1428505035143999563 timeout at: 1428506831 timeout in:
1800
[Apr 8 14:57:15.144] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505035143999563 timeout at: 1428505036 timeout in: 5
[Apr 8 14:57:15.691] Server {0x7fa8e276c800} DEBUG: (socket) net_activity
updating inactivity 5000000000, NetVC=0x7fa8d8016600
[Apr 8 14:57:15.691] Server {0x7fa8e276c800} DEBUG: (socket) net_activity
updating inactivity 1800000000000, NetVC=0x7fa8d8016340
[Apr 8 14:57:15.923] Server {0x7fa8e276c800} DEBUG: (socket) net_activity
updating inactivity 1800000000000, NetVC=0x7fa8d8016340
[Apr 8 14:57:15.923] Server {0x7fa8e276c800} DEBUG: (socket) Set inactive
timeout=30000000000, for NetVC=0x7fa8d8016340
[Apr 8 14:57:15.923] Server {0x7fa8e276c800} DEBUG: (socket) Cancel inactive
timeout for NetVC=0x7fa8d8016600
[Apr 8 14:57:15.923] Server {0x7fa8e276c800} DEBUG: (socket) Set inactive
timeout=5000000000, for NetVC=0x7fa8d8016600
[Apr 8 14:57:15.923] Server {0x7fa8e276c800} DEBUG: (http_cs)
tcp_init_cwnd_set 0
[Apr 8 14:57:15.923] Server {0x7fa8e276c800} DEBUG: (http_cs) desired TCP
congestion window is 0
[Apr 8 14:57:15.923] Server {0x7fa8e276c800} DEBUG: (socket) Set inactive
timeout=120000000000, for NetVC=0x7fa8d8016340
[Apr 8 14:57:15.923] Server {0x7fa8e276c800} DEBUG: (http_ss) Releasing
session, private_session=0, sharing_match=1
[Apr 8 14:57:15.923] Server {0x7fa8e276c800} DEBUG: (socket) Set inactive
timeout=120000000000, for NetVC=0x7fa8d8016340
[Apr 8 14:57:15.923] Server {0x7fa8e276c800} DEBUG: (socket) Set active
timeout=0, NetVC=0x7fa8d8016340
[Apr 8 14:57:15.923] Server {0x7fa8e276c800} DEBUG: (http_ss) [0] [release
session] session placed into shared pool
[Apr 8 14:57:15.923] Server {0x7fa8e276c800} DEBUG: (socket) net_activity
updating inactivity 5000000000, NetVC=0x7fa8d8016600
[Apr 8 14:57:15.923] Server {0x7fa8e276c800} DEBUG: (http_cs) [0] session
released by sm [0]
[Apr 8 14:57:15.923] Server {0x7fa8e276c800} DEBUG: (http_cs) [0] initiating
io for next header
[Apr 8 14:57:15.923] Server {0x7fa8e276c800} DEBUG: (socket)
UnixNetVConnection::add_to_keep_alive_lru NetVC=0x7fa8d8016600
[Apr 8 14:57:15.923] Server {0x7fa8e276c800} DEBUG: (socket) Set inactive
timeout=115000000000, for NetVC=0x7fa8d8016600
[Apr 8 14:57:15.923] Server {0x7fa8e276c800} DEBUG: (socket) Cancel active
timeout for NetVC=0x7fa8d8016600
[Apr 8 14:57:15.923] Server {0x7fa8e276c800} DEBUG: (http_cs) [0]
[&HttpClientSession::state_keep_alive, VC_EVENT_EOS]
[Apr 8 14:57:15.923] Server {0x7fa8e276c800} DEBUG: (http_cs) [0] session
closed
[Apr 8 14:57:15.923] Server {0x7fa8e276c800} DEBUG: (http_cs) [0] session
destroy
[Apr 8 14:57:15.923] Server {0x7fa8e276c800} DEBUG: (socket)
UnixNetVConnection::remove_from_keep_alive_lru NetVC=0x7fa8d8016600
[Apr 8 14:57:15.925] Server {0x7fa8e276c800} DEBUG: (socket) net_activity
updating inactivity 0, NetVC=0x7fa8d8016600
[Apr 8 14:57:15.925] Server {0x7fa8e276c800} DEBUG: (http_cs) [1] session
born, netvc 0x7fa8d8016600
[Apr 8 14:57:15.925] Server {0x7fa8e276c800} DEBUG: (http_cs) [1] Starting
transaction 1 using sm [1]
[Apr 8 14:57:15.925] Server {0x7fa8e276c800} DEBUG: (socket)
UnixNetVConnection::remove_from_keep_alive_lru NetVC=0x7fa8d8016600
[Apr 8 14:57:15.925] Server {0x7fa8e276c800} DEBUG: (socket) Set inactive
timeout=120000000000, for NetVC=0x7fa8d8016600
[Apr 8 14:57:15.925] Server {0x7fa8e276c800} DEBUG: (socket) Set active
timeout=900000000000, NetVC=0x7fa8d8016600
[Apr 8 14:57:15.925] Server {0x7fa8e276c800} DEBUG: (socket) Set inactive
timeout=5000000000, for NetVC=0x7fa8d8016600
[Apr 8 14:57:16.143] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505036143032735 timeout at: 1428505040 timeout in: 5
[Apr 8 14:57:16.143] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016340 now: 1428505036143032735 timeout at: 1428505155 timeout in:
120
[Apr 8 14:57:17.143] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505037143375551 timeout at: 1428505040 timeout in: 5
[Apr 8 14:57:17.143] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016340 now: 1428505037143375551 timeout at: 1428505155 timeout in:
120
[Apr 8 14:57:17.926] Server {0x7fa8e276c800} DEBUG: (socket) net_activity
updating inactivity 5000000000, NetVC=0x7fa8d8016600
[Apr 8 14:57:18.139] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505038139116118 timeout at: 1428505042 timeout in: 5
[Apr 8 14:57:18.139] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016340 now: 1428505038139116118 timeout at: 1428505155 timeout in:
120
[Apr 8 14:57:19.140] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505039140791435 timeout at: 1428505042 timeout in: 5
[Apr 8 14:57:19.140] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016340 now: 1428505039140791435 timeout at: 1428505155 timeout in:
120
[Apr 8 14:57:20.144] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505040144920102 timeout at: 1428505042 timeout in: 5
[Apr 8 14:57:20.144] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016340 now: 1428505040144920102 timeout at: 1428505155 timeout in:
120
[Apr 8 14:57:20.929] Server {0x7fa8e276c800} DEBUG: (socket) net_activity
updating inactivity 5000000000, NetVC=0x7fa8d8016600
[Apr 8 14:57:20.930] Server {0x7fa8e276c800} DEBUG: (http_ss) [0] [acquire
session] return session from shared pool
[Apr 8 14:57:20.930] Server {0x7fa8e276c800} DEBUG: (socket) Set inactive
timeout=1800000000000, for NetVC=0x7fa8d8016340
[Apr 8 14:57:20.930] Server {0x7fa8e276c800} DEBUG: (socket) Set active
timeout=0, NetVC=0x7fa8d8016340
[Apr 8 14:57:20.930] Server {0x7fa8e276c800} DEBUG: (socket) read_disable
updating inactivity_at 0, NetVC=0x7fa8d8016600
[Apr 8 14:57:20.930] Server {0x7fa8e276c800} DEBUG: (socket) net_activity
updating inactivity 1800000000000, NetVC=0x7fa8d8016340
[Apr 8 14:57:21.141] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505041141307016 timeout at: 1428505045 timeout in: 5
[Apr 8 14:57:21.141] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016340 now: 1428505041141307016 timeout at: 1428506840 timeout in:
1800
[Apr 8 14:57:22.136] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505042136444039 timeout at: 1428505045 timeout in: 5
[Apr 8 14:57:22.136] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016340 now: 1428505042136444039 timeout at: 1428506840 timeout in:
1800
[Apr 8 14:57:23.132] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505043132072873 timeout at: 1428505045 timeout in: 5
[Apr 8 14:57:23.132] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016340 now: 1428505043132072873 timeout at: 1428506840 timeout in:
1800
[Apr 8 14:57:24.135] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505044135809052 timeout at: 1428505045 timeout in: 5
[Apr 8 14:57:24.135] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016340 now: 1428505044135809052 timeout at: 1428506840 timeout in:
1800
[Apr 8 14:57:25.131] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505045131560648 timeout at: 1428505045 timeout in: 5
[Apr 8 14:57:25.131] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016340 now: 1428505045131560648 timeout at: 1428506840 timeout in:
1800
[Apr 8 14:57:26.136] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505046136950493 timeout at: 1428505045 timeout in: 5
[Apr 8 14:57:26.136] Server {0x7fa8e276c800} DEBUG: (inactivity_cop_verbose)
vc: 0x7fa8d8016600 now: 1428505046136950493 timeout at: 1428505045924333252
timeout in: 5000000000
[Apr 8 14:57:26.136] Server {0x7fa8e276c800} DEBUG: (http_ss) [0] session
closing, netvc 0x7fa8d8016340
[Apr 8 14:57:26.137] Server {0x7fa8e276c800} DEBUG: (socket)
UnixNetVConnection::remove_from_keep_alive_lru NetVC=0x7fa8d8016340
[Apr 8 14:57:26.137] Server {0x7fa8e276c800} DEBUG: (http_cs) [1] session
closed
[Apr 8 14:57:26.137] Server {0x7fa8e276c800} DEBUG: (http_cs) [1] session
destroy
[Apr 8 14:57:26.137] Server {0x7fa8e276c800} DEBUG: (socket)
UnixNetVConnection::remove_from_keep_alive_lru NetVC=0x7fa8d8016600
{noformat}
> cannot override proxy.config.http.transaction_no_activity_timeout_in per
> remap rule for POST methold
> ----------------------------------------------------------------------------------------------------
>
> Key: TS-3487
> URL: https://issues.apache.org/jira/browse/TS-3487
> Project: Traffic Server
> Issue Type: Bug
> Components: HTTP
> Affects Versions: 5.2.1
> Reporter: Feifei Cai
> Assignee: Bryan Call
> Labels: review
> Fix For: 6.0.0
>
> Attachments: TS-3487.diff
>
>
> The configuration and test are as follows:
> remap.config:
> {noformat}
> map /test1 http://httpbin.org
> map /test2 http://httpbin.org @plugin=conf_remap.so
> @pparam=proxy.config.http.transaction_no_activity_timeout_in=15
> {noformat}
> records.config:
> {noformat}
> CONFIG proxy.config.http.transaction_no_activity_timeout_in INT 5
> CONFIG proxy.config.diags.debug.enabled INT 1
> CONFIG proxy.config.diags.debug.tags STRING
> http_cs|http_ss|inactivity.*|socket
> {noformat}
> {code:title=test.py}
> import time
> import logging
> import socket
> log = logging.getLogger(__name__)
> logging.basicConfig(level=logging.INFO)
> import SocketServer
> url1 = 'POST /test1/post HTTP/1.1\r\n'
> url2 = 'POST /test2/post HTTP/1.1\r\n'
> header1 = 'Host: 127.0.0.1\r\n'
> # last header need additional '\r\n'
> header2 = 'Content-Length: 10\r\n\r\n'
> body1 = '12345'
> body2 = '67890'
> def get_socket():
> s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
> s.connect(('127.0.0.1', 8080))
> return s
> def test_global_config():
> s = get_socket()
> log.info('start test global config...')
> try:
> # before remap
> s.send(url1)
> time.sleep(2) # < global config
> s.send(header1)
> time.sleep(3) # < global config
> s.send(header2)
> # after remap
> time.sleep(2) # < global config
> s.send(body1)
> time.sleep(4) # < global config
> s.send(body2)
> log.info('test global config: pass!')
> except IOError:
> log.info('test global config: fail!')
> response = s.recv(4096)
> print response
> def test_per_remap_config():
> s = get_socket()
> log.info('start test per remap config...')
> try:
> # before remap
> s.send(url2)
> time.sleep(2) # < global config
> s.send(header1)
> time.sleep(3) # < global config
> s.send(header2)
> # after remap
> time.sleep(11) # < per remap config
> s.send(body1)
> time.sleep(13) # < per remap config
> s.send(body2)
> log.info('test per remap config: pass!')
> except IOError:
> log.info('test per remap config: fail!')
> response = s.recv(4096)
> print response
> if __name__ == '__main__':
> test_global_config()
> test_per_remap_config()
> {code}
> {{test_global_config()}} would pass, but {{test_per_remap_config()}} fails.
> {{proxy.config.http.transaction_no_activity_timeout_in}} in per remap rule
> does not works.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
