I have attached the debug log, still clue less on this.
--
Regards,
Faisal.
------ Original Message ------
From: "Lerner, Steve" <[email protected]>
To: "[email protected]" <[email protected]>;
"Muhammad Faisal" <[email protected]>
Sent: 3/21/2016 5:20:05 PM
Subject: RE: Question on ATS Performance
Do you have a way to analyze the requests inbound that are correlated
with the 502s? Are they legit requests?
Steve Lerner | Principal Architect, Performance Engineering | m
212.495.9212 | [email protected] | Skype: steve.lerner
From: Muhammad Faisal [mailto:[email protected]]
Sent: Monday, March 21, 2016 8:04 AM
To:[email protected]; [email protected]
Subject: Re: Question on ATS Performance
ATS is connected to upstream router directly im using PBR to redirect
traffic for http caching.
--
Regards,
Faisal.
------ Original Message ------
From: "Lerner, Steve" <[email protected]>
To: "[email protected]" <[email protected]>;
"Muhammad Faisal" <[email protected]>
Sent: 3/21/2016 5:00:00 PM
Subject: RE: Question on ATS Performance
If I may be so bold… what kind of front end do you have in front of
the ATS service? I.e. any other firewall, load balancer, network
proxy, etc?
Steve Lerner | Principal Architect, Performance Engineering | m
212.495.9212 | [email protected] | Skype: steve.lerner
From: Muhammad Faisal [mailto:[email protected]]
Sent: Monday, March 21, 2016 7:57 AM
To:[email protected]; [email protected]
Subject: Re: Question on ATS Performance
Hi Leif,
The error 502 is causing impact on user experience. When traffic if
diverted toward ATS in a production environment many established
session re-establish via ATS box. In this case several websites starts
giving 502 errors. Disabling keep alive and restarting server didn’t
help this time so i offload the traffic for now. Kindly guide how to
fix this behavior ?
PS: Mostly sites found hosted on @K@mai
--
Regards,
Faisal.
------ Original Message ------
From: "Leif Hedstrom" <[email protected]>
To: [email protected]
Sent: 2/13/2016 9:41:55 AM
Subject: Re: Question on ATS Performance
On Feb 12, 2016, at 8:38 PM, Muhammad Faisal <[email protected]>
wrote:
Hi Leif,
Yes I’m using v6.1.1. I turned off keep-alive for sometime and
re-enabled it this resolved the 502 error. The jira already has
TS-3959 I have updated my comments though.Should I file it on Jira?
Ah. Yeh, TS-3959 is sufficient I think. Did re-enabling keep-alive
actually resolve it again?
@bcall: Any ideas on this?
— leif
+++++++++ Incoming Request +++++++++
-- State Machine Id: 1032
GET http://www.espncricinfo.com/ HTTP/1.1Host: www.espncricinfo.comConnection:
keep-aliveCache-Control: max-age=0Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8Upgrade-Insecure-Requests:
1User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML,
like Gecko) Chrome/49.0.2623.87 Safari/537.36Accept-Encoding:
gzipAccept-Language: en-US,en;q=0.8[Mar 21 17:34:33.291] Server
{0x2b7aa9a19700} DEBUG: <HttpTransact.cc:1903 (DecideCacheLookup)> (http_trans)
[DecideCacheLookup] Will do cache lookup.
[Mar 21 17:34:33.291] Server {0x2b7aa9a19700} DEBUG: <HttpTransact.cc:1904
(DecideCacheLookup)> (http_seq) [DecideCacheLookup] Will do cache lookup
[Mar 21 17:34:33.291] Server {0x2b7aa9a19700} DEBUG: <HttpTransact.cc:1947
(DecideCacheLookup)> (http_trans) Next action SM_ACTION_CACHE_LOOKUP; __null
[Mar 21 17:34:33.291] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [1032] State Transition:
SM_ACTION_API_POST_REMAP -> SM_ACTION_CACHE_LOOKUP
[Mar 21 17:34:33.291] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:4403
(do_cache_lookup_and_read)> (http_seq) [HttpSM::do_cache_lookup_and_read]
[1032] Issuing cache lookup for URL http://www.espncricinfo.com/
[Mar 21 17:34:33.291] Server {0x2b7aa9a19700} DEBUG: <HttpCacheSM.cc:102
(state_cache_open_read)> (http_cache) [1032]
[&HttpCacheSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED]
[Mar 21 17:34:33.291] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [1032] [HttpSM::main_handler,
CACHE_EVENT_OPEN_READ_FAILED]
[Mar 21 17:34:33.291] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:2473
(state_cache_open_read)> (http) [1032] [&HttpSM::state_cache_open_read,
CACHE_EVENT_OPEN_READ_FAILED]
[Mar 21 17:34:33.291] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:2508
(state_cache_open_read)> (http) [1032] cache_open_read -
CACHE_EVENT_OPEN_READ_FAILED
[Mar 21 17:34:33.291] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:2509
(state_cache_open_read)> (http) [state_cache_open_read] open read failed.
[Mar 21 17:34:33.291] Server {0x2b7aa9a19700} DEBUG: <HttpTransact.cc:2161
(HandleCacheOpenRead)> (http_trans) [HttpTransact::HandleCacheOpenRead]
[Mar 21 17:34:33.291] Server {0x2b7aa9a19700} DEBUG: <HttpTransact.cc:2191
(HandleCacheOpenRead)> (http_trans) CacheOpenRead -- miss
[Mar 21 17:34:33.291] Server {0x2b7aa9a19700} DEBUG: <HttpTransact.cc:2198
(HandleCacheOpenRead)> (http_trans) Next action SM_ACTION_DNS_LOOKUP;
OSDNSLookup
[Mar 21 17:34:33.291] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [1032] State Transition:
SM_ACTION_CACHE_LOOKUP -> SM_ACTION_DNS_LOOKUP
[Mar 21 17:34:33.291] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:3997
(do_hostdb_lookup)> (http_seq) [HttpSM::do_hostdb_lookup] Doing DNS Lookup
[Mar 21 17:34:33.311] Server {0x2b7aa9a19700} DEBUG: <DNS.cc:1096 (getby)>
(dns) received query www.espncricinfo.com type = 1, timeout = 0
[Mar 21 17:34:33.312] Server {0x2b7aaad35700} DEBUG: <DNS.cc:1062 (mainEvent)>
(dns) enqueing query www.espncricinfo.com
[Mar 21 17:34:33.312] Server {0x2b7aaad35700} DEBUG: <DNS.cc:1068 (mainEvent)>
(dns) adding first to collapsing queue
[Mar 21 17:34:33.312] Server {0x2b7aaad35700} DEBUG: <DNS.cc:982
(write_dns_event)> (dns) send query (qtype=1) for www.espncricinfo.com to fd 108
[Mar 21 17:34:33.312] Server {0x2b7aaad35700} DEBUG: <DNS.cc:1014
(write_dns_event)> (dns) sent qname = www.espncricinfo.com, id = 4397,
nameserver = 0
[Mar 21 17:34:33.312] Server {0x2b7aaad35700} DEBUG: <P_DNSProcessor.h:229
(sent_one)> (dns) sent_one: failover_number for resolver 0 is 1
[Mar 21 17:34:33.312] Server {0x2b7aaad35700} DEBUG: <DNS.cc:762 (recv_dns)>
(dns) received packet size = 443
[Mar 21 17:34:33.312] Server {0x2b7aaad35700} DEBUG: <DNS.cc:764 (recv_dns)>
(dns) round-robin: nameserver 0 DNS response code = 0
[Mar 21 17:34:33.312] Server {0x2b7aaad35700} DEBUG: <DNS.cc:1481
(dns_process)> (dns) received cname = wwwakamai.espncricinfo.com
[Mar 21 17:34:33.312] Server {0x2b7aaad35700} DEBUG: <DNS.cc:1481
(dns_process)> (dns) received cname = content.cricinfo.com.edgesuite.net
[Mar 21 17:34:33.312] Server {0x2b7aaad35700} DEBUG: <DNS.cc:1481
(dns_process)> (dns) received cname = blabla.g.akamai.net
[Mar 21 17:34:33.312] Server {0x2b7aaad35700} DEBUG: <DNS.cc:1555
(dns_process)> (dns) received A name = blabla.g.akamai.net
[Mar 21 17:34:33.312] Server {0x2b7aaad35700} DEBUG: <DNS.cc:1572
(dns_process)> (dns) received A = [AKMAI IP]
[Mar 21 17:34:33.312] Server {0x2b7aaad35700} DEBUG: <DNS.cc:1572
(dns_process)> (dns) received A = [AKAMAI IP]
[Mar 21 17:34:33.312] Server {0x2b7aaad35700} DEBUG: <DNS.cc:1185 (dns_result)>
(dns) SUCCESS result for www.espncricinfo.com = [AKAMAI IP] retry 0
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <DNS.cc:1273 (postEvent)>
(dns) called back continuation for www.espncricinfo.com
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [1032] [HttpSM::main_handler, EVENT_HOST_DB_LOOKUP]
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:2115
(state_hostdb_lookup)> (http) [1032] [&HttpSM::state_hostdb_lookup,
EVENT_HOST_DB_LOOKUP]
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpTransact.cc:8344
(ink_cluster_time)> (http_trans) [ink_cluster_time] local: 1458563673,
highest_delta: 0, cluster: 1458563673
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpTransact.cc:1634
(OSDNSLookup)> (http_trans) [HttpTransact::OSDNSLookup] This was attempt 1
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpTransact.cc:1697
(OSDNSLookup)> (http_seq) [HttpTransact::OSDNSLookup] DNS Lookup successful
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpTransact.cc:1731
(OSDNSLookup)> (http_trans) [OSDNSLookup] DNS lookup for O.S. successful IP:
[AKAMAI IP]
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpTransact.cc:1801
(OSDNSLookup)> (http_trans) Next action SM_ACTION_API_OS_DNS;
HandleCacheOpenReadMiss
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [1032] State Transition:
SM_ACTION_DNS_LOOKUP -> SM_ACTION_API_OS_DNS
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpTransact.cc:3059
(HandleCacheOpenReadMiss)> (http_trans) [HandleCacheOpenReadMiss] --- MISS
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpTransact.cc:3061
(HandleCacheOpenReadMiss)> (http_seq) [HttpTransact::HandleCacheOpenReadMiss]
Miss in cache
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpTransact.cc:5183
(add_client_ip_to_outgoing_request)> (http_trans) client_ip_set = 0
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpTransact.cc:5187
(add_client_ip_to_outgoing_request)> (http_trans) inserted request header
'Client-ip: 1.2.3.4'
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpTransact.cc:5209
(add_client_ip_to_outgoing_request)> (http_trans)
[add_client_ip_to_outgoing_request] Appended connecting client's (1.2.3.4) to
the X-Forwards header
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpTransact.cc:7789
(build_request)> (http_trans) [build_request] removing host name from url
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpTransact.cc:7816
(build_request)> (http_trans) [build_request] request like cacheable but keep
conditional headers
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpTransact.cc:8344
(ink_cluster_time)> (http_trans) [ink_cluster_time] local: 1458563673,
highest_delta: 0, cluster: 1458563673
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpTransact.cc:7836
(build_request)> (http_trans) [build_request] request_sent_time: 1458563673
+++++++++ Proxy's Request +++++++++
-- State Machine Id: 1032
GET / HTTP/1.1Host: www.espncricinfo.comCache-Control: max-age=0Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8Upgrade-Insecure-Requests:
1User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML,
like Gecko) Chrome/49.0.2623.87 Safari/537.36Accept-Encoding:
gzipAccept-Language: en-US,en;q=0.8Client-ip: 1.2.3.4X-Forwarded-For:
1.2.3.4Via: http/1.1 wc01[71CBEBE2] (ApacheTrafficServer/6.1.1)[Mar 21
17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [1032] State Transition:
SM_ACTION_API_OS_DNS -> SM_ACTION_CACHE_ISSUE_WRITE
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:4530
(do_cache_prepare_action)> (http_cache_write) [1032] writing to cache with URL
http://www.espncricinfo.com/
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpCacheSM.cc:161
(state_cache_open_write)> (http_cache) [1032]
[&HttpCacheSM::state_cache_open_write, CACHE_EVENT_OPEN_WRITE]
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [1032] [HttpSM::main_handler, CACHE_EVENT_OPEN_WRITE]
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:2363
(state_cache_open_write)> (http) [1032] [&HttpSM : state_cache_open_write,
CACHE_EVENT_OPEN_WRITE]
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpTransact.cc:3025
(handle_cache_write_lock)> (http_trans) Next action next; __null
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [1032] State Transition:
SM_ACTION_CACHE_ISSUE_WRITE -> SM_ACTION_ORIGIN_SERVER_OPEN
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:4555
(do_http_server_open)> (http_track) entered inside do_http_server_open ][IPv4]
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:4575
(do_http_server_open)> (http) [1032] open connection to www.espncricinfo.com:
AKAMAIIP:80
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:4587
(do_http_server_open)> (http_seq) [HttpSM::do_http_server_open] Sending request
to server
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpSessionManager.cc:289
(acquire_session)> (http_ss) [acquire session] thread pool search failed
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:4803
(do_http_server_open)> (http) calling netProcessor.connect_re
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [1032] [HttpSM::main_handler, NET_EVENT_OPEN]
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:1618
(state_http_server_open)> (http_track) entered inside state_http_server_open
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpSM.cc:1619
(state_http_server_open)> (http) [1032] [&HttpSM::state_http_server_open,
NET_EVENT_OPEN]
[Mar 21 17:34:33.313] Server {0x2b7aa9a19700} DEBUG: <HttpServerSession.cc:91
(new_connection)> (http_ss) [667] session born, netvc 0x2b7af800ae20
+++++++++ Proxy's Request after hooks +++++++++
-- State Machine Id: 1032
GET / HTTP/1.1Host: www.espncricinfo.comCache-Control: max-age=0Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8Upgrade-Insecure-Requests:
1User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML,
like Gecko) Chrome/49.0.2623.87 Safari/537.36Accept-Encoding:
gzipAccept-Language: en-US,en;q=0.8Client-ip: 1.2.3.4X-Forwarded-For:
1.2.3.4Via: http/1.1 wc01[71CBEBE2] (ApacheTrafficServer/6.1.1)[Mar 21
17:34:35.538] Server {0x2b7aa8908700} DEBUG: <HttpClientSession.cc:409
(state_keep_alive)> (http_cs) [5] [&HttpClientSession::state_keep_alive,
VC_EVENT_READ_READY]
[Mar 21 17:34:35.538] Server {0x2b7aa8908700} DEBUG: <HttpClientSession.cc:139
(new_transaction)> (http_cs) [5] Starting transaction 115 using sm [1033]
[Mar 21 17:34:35.538] Server {0x2b7aa8908700} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [1033] [HttpSM::main_handler, VC_EVENT_READ_READY]
[Mar 21 17:34:35.538] Server {0x2b7aa8908700} DEBUG: <HttpSM.cc:579
(state_read_client_request_header)> (http) [1033]
[&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY]
[Mar 21 17:34:35.538] Server {0x2b7aa8908700} DEBUG: <HttpSM.cc:724
(state_read_client_request_header)> (http) [1033] done parsing client request
header
[Mar 21 17:34:35.538] Server {0x2b7aa8908700} DEBUG: <HttpTransact.cc:1066
(ModifyRequest)> (http_trans) START HttpTransact::ModifyRequest
[Mar 21 17:34:35.538] Server {0x2b7aa8908700} DEBUG: <HttpTransact.cc:8344
(ink_cluster_time)> (http_trans) [ink_cluster_time] local: 1458563675,
highest_delta: 0, cluster: 1458563675
[Mar 21 17:34:35.538] Server {0x2b7aa8908700} DEBUG: <HttpTransact.cc:1157
(ModifyRequest)> (http_trans) END HttpTransact::ModifyRequest
[Mar 21 17:34:35.538] Server {0x2b7aa8908700} DEBUG: <HttpTransact.cc:1159
(ModifyRequest)> (http_trans) Checking if transaction wants to upgrade
[Mar 21 17:34:35.538] Server {0x2b7aa8908700} DEBUG: <HttpTransact.cc:1166
(ModifyRequest)> (http_trans) Next action SM_ACTION_API_READ_REQUEST_HDR;
HttpTransact::StartRemapRequest
[Mar 21 17:34:35.538] Server {0x2b7aa8908700} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [1033] State Transition:
SM_ACTION_UNDEFINED -> SM_ACTION_API_READ_REQUEST_HDR
[Mar 21 17:34:35.538] Server {0x2b7aa8908700} DEBUG: <HttpSM.cc:1376
(state_api_callout)> (http) [1033] calling plugin on hook
TS_HTTP_READ_REQUEST_HDR_HOOK at hook 0x1cf3fc0
[Mar 21 17:34:35.538] Server {0x2b7aa8908700} DEBUG: <HttpSM.cc:1271
(state_api_callback)> (http) [1033] [&HttpSM::state_api_callback,
HTTP_API_CONTINUE]
[Mar 21 17:34:35.538] Server {0x2b7aa8908700} DEBUG: <HttpSM.cc:1311
(state_api_callout)> (http) [1033] [&HttpSM::state_api_callout,
HTTP_API_CONTINUE]
[Mar 21 17:34:35.538] Server {0x2b7aa8908700} DEBUG: <HttpSM.cc:1376
(state_api_callout)> (http) [1033] calling plugin on hook
TS_HTTP_READ_REQUEST_HDR_HOOK at hook 0x1cf3fa0
[Mar 21 17:34:35.538] Server {0x2b7aa8908700} DEBUG: <HttpSM.cc:1271
(state_api_callback)> (http) [1033] [&HttpSM::state_api_callback,
HTTP_API_CONTINUE]
[Mar 21 17:34:35.538] Server {0x2b7aa8908700} DEBUG: <HttpSM.cc:1311
(state_api_callout)> (http) [1033] [&HttpSM::state_api_callout,
HTTP_API_CONTINUE]
[Mar 21 17:34:35.538] Server {0x2b7aa8908700} DEBUG: <HttpTransact.cc:682
(StartRemapRequest)> (http_trans) API request to skip remapping
[Mar 21 17:34:35.538] Server {0x2b7aa8908700} DEBUG: <HttpTransact.cc:690
(StartRemapRequest)> (http_trans) Next action SM_ACTION_POST_REMAP_SKIP;
HttpTransact::HandleRequest
[Mar 21 17:34:35.538] Server {0x2b7aa8908700} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [1033] State Transition:
SM_ACTION_API_READ_REQUEST_HDR -> SM_ACTION_POST_REMAP_SKIP
