[
https://issues.apache.org/jira/browse/TS-1620?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13553566#comment-13553566
]
cauthy commented on TS-1620:
----------------------------
I find this again.Mine command line is wget --limit_rate=100000 <URL>.
And the access log is(I have remove some informations in the URL and host)
XXXXXXXXXXX - - [14/Jan/2013:17:39:08 +0800] 0 "GET XXXXXXXXXXXXX HTTP/1.0" 200
313239 "-" "Wget/1.11.4 Red Hat modified" TCP_HIT
And this is what I get from debug log.
[alts] ---- alternate #1 (Q = 1.003) has these request/response hdrs:
GET XXXXXXXXXXXXXXXXXX HTTP/1.0
User-Agent: Wget/1.11.4 Red Hat modified
Accept: */*
Host: XXXXXXXXXXXXXXX
HTTP/1.1 200 OK
Date: Mon, 14 Jan 2013 09:34:40 GMT
Server: Apache
Last-Modified: Thu, 10 Jan 2013 01:34:53 GMT
Accept-Ranges: bytes
Content-Length: 312864
Cache-Control: max-age=31104000
Expires: Thu, 09 Jan 2014 09:34:40 GMT
Content-Type: application/x-shockwave-flash
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_seq)
[SelectFromAlternates] Chosen alternate # 0
[alts] and the winner is alternate number 1
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_cache) [211]
[&HttpCacheSM::state_cache_open_read, CACHE_EVENT_OPEN_READ]
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http) [211]
[HttpSM::main_handler, CACHE_EVENT_OPEN_READ]
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http) [211]
[&HttpSM::state_cache_open_read, CACHE_EVENT_OPEN_READ]
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http) [211] cache_open_read -
CACHE_EVENT_OPEN_READ
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_trans)
[HttpTransact::HandleCacheOpenRead]
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_trans) CacheOpenRead --
hit
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_trans) Next action
HTTP_API_READ_CACHE_HDR; HandleCacheOpenReadHitFreshness
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http) [211] State Transition:
CACHE_LOOKUP -> API_READ_CACHE_HDR
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_seq)
[HttpTransact::HandleCacheOpenReadHitFreshness] Hit in cache
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_trans)
[HandleCacheOpenReadHitFreshness] request_sent_time : 1358156080
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_trans)
[HandleCacheOpenReadHitFreshness] response_received_time : 1358156080
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_match)
calculate_document_freshness_limit --- max_age set, freshness_limit = 31104000
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_match)
calculate_document_freshness_limit --- final freshness_limit = 31104000
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] age_value: 0
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] date_value: 1358156080
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] response_time: 1358156080
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] now: 1358156348
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] now (fixed): 1358156348
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] apparent_age: 0
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] corrected_received_age: 0
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] response_delay: 0
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] corrected_initial_age: 0
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] resident_time: 268
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] current_age: 268
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_match)
[what_is_document_freshness] fresh_limit: 31104000 current_age: 268
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_match)
[..._document_freshness] initial age limit: 31104000
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_match)
document_freshness --- current_age = 268
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_match)
document_freshness --- age_limit = 31104000
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_match)
document_freshness --- fresh_limit = 31104000
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_seq) document_freshness
--- current_age = 268
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_seq) document_freshness
--- age_limit = 31104000
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_seq) document_freshness
--- fresh_limit = 31104000
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_match)
[..._document_freshness] document is fresh; returning FRESHNESS_FRESH
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_seq)
[HttpTransact::HandleCacheOpenReadHitFreshness] Fresh copy
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_seq)
[HttpTransact::HandleCacheOpenReadHit] Authentication not needed
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_trans) Next action
HTTP_API_CACHE_LOOKUP_COMPLETE; HttpTransact::HandleCacheOpenReadHit
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http) [211] State Transition:
API_READ_CACHE_HDR -> API_CACHE_LOOKUP_COMPLETE
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_seq)
[HttpTransact::HandleCacheOpenReadHit] Authentication not needed
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_trans) CacheOpenRead ---
needs_auth = 0
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_trans) CacheOpenRead ---
needs_revalidate = 0
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_trans) CacheOpenRead ---
response_returnable = 1
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_trans) CacheOpenRead ---
needs_cache_auth = 0
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_trans) CacheOpenRead ---
send_revalidate = 0
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_trans) CacheOpenRead ---
HIT-FRESH
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_seq)
[HttpTransact::HandleCacheOpenReadHit] Serve from cache
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_trans)
[build_response_from_cache] Match! Serving full document.
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] age_value: 0
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] date_value: 1358156080
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] response_time: 1358156080
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] now: 1358156348
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] now (fixed): 1358156348
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] apparent_age: 0
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] corrected_received_age: 0
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] response_delay: 0
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] corrected_initial_age: 0
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] resident_time: 268
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_age)
[calculate_document_age] current_age: 268
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_trans)
[handle_content_length_header] RESPONSE cont len in hdr is 312864
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_trans) [WUTS code
generation] Hit/Miss: 48, Log: 49, Hier: 49, Status: 999
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_trans) Adding Server:
ATS/3.2.0
+++++++++ Base Header for Building Response +++++++++
-- State Machine Id: 211
HTTP/1.1 200 OK
Date: Mon, 14 Jan 2013 09:34:40 GMT
Server: Apache
Last-Modified: Thu, 10 Jan 2013 01:34:53 GMT
Accept-Ranges: bytes
Content-Length: 312864
Cache-Control: max-age=31104000
Expires: Thu, 09 Jan 2014 09:34:40 GMT
Content-Type: application/x-shockwave-flash
+++++++++ Proxy's Response 2 +++++++++
-- State Machine Id: 211
HTTP/1.0 200 OK
Date: Mon, 14 Jan 2013 09:34:40 GMT
Server: ATS/3.2.0
Last-Modified: Thu, 10 Jan 2013 01:34:53 GMT
Accept-Ranges: bytes
Content-Length: 312864
Cache-Control: max-age=31104000
Expires: Thu, 09 Jan 2014 09:34:40 GMT
Content-Type: application/x-shockwave-flash
Age: 268
Connection: keep-alive
Via: http/1.1 XXXXXXXXXXXXXXX (ApacheTrafficServer/3.2.0)
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http) [211] State Transition:
API_CACHE_LOOKUP_COMPLETE -> SERVE_FROM_CACHE
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http) [211]
perform_cache_write_action CACHE_DO_SERVE
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_redirect)
[HttpSM::do_redirect]
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_tunnel) [211] adding
producer 'cache read'
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_tunnel) [211] adding
consumer 'user agent'
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_tunnel) tunnel_run
started, p_arg is NULL
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_cs) tcp_init_cwnd_set 0
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_cs) desired TCP
congestion window is 0
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_tunnel) [211]
producer_handler [cache read VC_EVENT_READ_COMPLETE]
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 102
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http) [211]
[&HttpSM::tunnel_handler_cache_read, VC_EVENT_READ_COMPLETE]
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_tunnel) [211]
consumer_handler [user agent VC_EVENT_WRITE_COMPLETE]
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http) [211]
[&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE]
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_cs) [211] session
released by sm [211]
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_cs) [211] initiating io
for next header
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http) [211]
[HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http) [211]
[&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http_seq)
[HttpStateMachineGet::update_stats] Logging transaction
[Jan 14 17:39:08.802] Server {0x408d9940} DEBUG: (http) [211] dellocating sm
[Jan 14 17:39:11.753] Server {0x408d9940} DEBUG: (http_cs) [211]
[&HttpClientSession::state_keep_alive, VC_EVENT_EOS]
[Jan 14 17:39:11.753] Server {0x408d9940} DEBUG: (http_cs) [211] session closed
[Jan 14 17:39:11.753] Server {0x408d9940} DEBUG: (http_cs) [211] session destroy
> Traffic Server 3.2.0 stable can't record ttms correctly
> --------------------------------------------------------
>
> Key: TS-1620
> URL: https://issues.apache.org/jira/browse/TS-1620
> Project: Traffic Server
> Issue Type: Bug
> Components: Logging
> Reporter: evilbandon
>
> Traffic Server 3.2.0 stable can't record ttms correctly
> when I use Traffic Server 3.2.0 stable ,I find it can't record ttms correcly
> ,most records of ttms is 0
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
