You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@trafficserver.apache.org by "cauthy (JIRA)" <ji...@apache.org> on 2013/01/15 08:18:12 UTC
[jira] [Commented] (TS-1620) Traffic Server 3.2.0 stable can't
record ttms correctly
[ 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