You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@trafficserver.apache.org by "David Carlin (JIRA)" <ji...@apache.org> on 2013/11/24 22:02:35 UTC
[jira] [Commented] (TS-2391) Traffic Server tries to reverse
resolve 127.0.0.1
[ https://issues.apache.org/jira/browse/TS-2391?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13831051#comment-13831051 ]
David Carlin commented on TS-2391:
----------------------------------
This is what I see during a 'hang'
{noformat}
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) probe aa30de0f80a82135 1 [ignore_timeout = 0]
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) '' failed
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) fail timeout 0
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) enqueuing additional request
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) probe aa30de0f80a82135 1 [ignore_timeout = 0]
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) '' failed
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) fail timeout 0
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) enqueuing additional request
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) probe aa30de0f80a82135 1 [ignore_timeout = 0]
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) '' failed
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) fail timeout 0
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) enqueuing additional request
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) probe aa30de0f80a82135 1 [ignore_timeout = 0]
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) '' failed
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) fail timeout 0
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) enqueuing additional request
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) probe aa30de0f80a82135 1 [ignore_timeout = 0]
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) '' failed
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) fail timeout 0
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) enqueuing additional request
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) probe aa30de0f80a82135 1 [ignore_timeout = 0]
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) '' failed
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) fail timeout 0
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (hostdb) enqueuing additional request
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (dns) received packet size = 109
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (dns) primary DNS response code = 0
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (dns) received rcode = 3
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (dns) DNS error 3 for [1.0.0.127.in-addr.arpa]
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (dns) send query (qtype=12) for to fd 236
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (dns) sent qname = , id = 61114, nameserver = 0
[Nov 24 20:57:58.036] Server {0x2b759c8953a0} DEBUG: (dns) sent_one: failover_number for resolver 0 is 1
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (dns) received packet size = 92
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (dns) primary DNS response code = 0
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (dns) received rcode = 0
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (dns) DNS error 0 for []
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (dns) FAIL result for = <not found> retry 0
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (dns) called back continuation for
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) probe aa30de0f80a82135 1 [ignore_timeout = 1]
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) '' failed
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) fail timeout 0
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) failed for 127.0.0.1
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) inserting for: : (md5: aa30de0f80a82135) bucket: 1017 now: 1385326523 timeout: 0 ttl: 0
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
[Nov 24 20:57:58.037] Server {0x2b759c8953a0} DEBUG: (hostdb) dequeuing additional request
{noformat}
> Traffic Server tries to reverse resolve 127.0.0.1
> -------------------------------------------------
>
> Key: TS-2391
> URL: https://issues.apache.org/jira/browse/TS-2391
> Project: Traffic Server
> Issue Type: Bug
> Components: Core
> Reporter: David Carlin
>
> We have a number of remaps using 127.0.0.1 for serving healthchecks. Bryan Call noticed ATS seems to try and resolve 1.0.0.127.in-addr.arpa for every one of the requests (there are a lot, sometimes hundreds per second).
> Occasionally this process hangs; If I grep squid.blog for 127.0.0.1 I'll see the healthcheck log entries flowing and then all of a sudden it'll stop anywhere from 15-80 seconds. Then the backlog of healthchecks is cleared out at once. 5-20 minutes later this process will recur.
> From traffic.out with debug dns.*|hostdb.* - this occurs continuously. Lookup for 1.0.0.127.in-addr.arpa fails (NXDOMAIN) and it doesn't get added to HostDB.
> Unsure if related, but TS-852 seemed similar.
> {noformat}
> [Nov 24 20:40:46.619] Server {0x2b759c8953a0} DEBUG: (dns) received query type = 12, timeout = 0
> [Nov 24 20:40:46.619] Server {0x2b759c8953a0} DEBUG: (dns) enqueing query 1.0.0.127.in-addr.arpa
> [Nov 24 20:40:46.619] Server {0x2b759c8953a0} DEBUG: (dns) adding first to collapsing queue
> [Nov 24 20:40:46.619] Server {0x2b759c8953a0} DEBUG: (dns) send query (qtype=12) for 1.0.0.127.in-addr.arpa to fd 236
> [Nov 24 20:40:46.619] Server {0x2b759c8953a0} DEBUG: (dns) sent qname = 1.0.0.127.in-addr.arpa, id = 56887, nameserver = 0
> [Nov 24 20:40:46.619] Server {0x2b759c8953a0} DEBUG: (dns) sent_one: failover_number for resolver 0 is 1
> [Nov 24 20:40:46.619] Server {0x2b759c8953a0} DEBUG: (dns) received packet size = 109
> [Nov 24 20:40:46.619] Server {0x2b759c8953a0} DEBUG: (dns) primary DNS response code = 0
> [Nov 24 20:40:46.619] Server {0x2b759c8953a0} DEBUG: (dns) received rcode = 3
> [Nov 24 20:40:46.619] Server {0x2b759c8953a0} DEBUG: (dns) DNS error 3 for [1.0.0.127.in-addr.arpa]
> [Nov 24 20:40:46.619] Server {0x2b759c8953a0} DEBUG: (dns) send query (qtype=12) for to fd 236
> [Nov 24 20:40:46.619] Server {0x2b759c8953a0} DEBUG: (dns) sent qname = , id = 4497, nameserver = 0
> [Nov 24 20:40:46.620] Server {0x2b759c8953a0} DEBUG: (dns) sent_one: failover_number for resolver 0 is 1
> [Nov 24 20:40:46.620] Server {0x2b759c8953a0} DEBUG: (dns) received packet size = 92
> [Nov 24 20:40:46.620] Server {0x2b759c8953a0} DEBUG: (dns) primary DNS response code = 0
> [Nov 24 20:40:46.620] Server {0x2b759c8953a0} DEBUG: (dns) received rcode = 0
> [Nov 24 20:40:46.620] Server {0x2b759c8953a0} DEBUG: (dns) DNS error 0 for []
> [Nov 24 20:40:46.620] Server {0x2b759c8953a0} DEBUG: (dns) FAIL result for = <not found> retry 0
> [Nov 24 20:40:46.620] Server {0x2b759c8953a0} DEBUG: (dns) called back continuation for
> [Nov 24 20:40:46.620] Server {0x2b759c8953a0} DEBUG: (hostdb) probe aa30de0f80a82135 1 [ignore_timeout = 1]
> [Nov 24 20:40:46.620] Server {0x2b759c8953a0} DEBUG: (hostdb) '' failed
> [Nov 24 20:40:46.620] Server {0x2b759c8953a0} DEBUG: (hostdb) fail timeout 0
> [Nov 24 20:40:46.620] Server {0x2b759c8953a0} DEBUG: (hostdb) failed for 127.0.0.1
> [Nov 24 20:40:46.620] Server {0x2b759c8953a0} DEBUG: (hostdb) inserting for: : (md5: aa30de0f80a82135) bucket: 1017 now: 1385325494 timeout: 0 ttl: 0
> [Nov 24 20:40:46.707] Server {0x2b759d74e700} DEBUG: (hostdb) probe 127.0.0.1 9993e35a45b4be6a 1 [ignore_timeout = 0]
> [Nov 24 20:40:46.707] Server {0x2b759d74e700} DEBUG: (hostdb) immediate answer for 127.0.0.1
> [Nov 24 20:40:46.707] Server {0x2b759d74e700} DEBUG: (hostdb) probe aa30de0f80a82135 1 [ignore_timeout = 0]
> [Nov 24 20:40:46.707] Server {0x2b759d74e700} DEBUG: (hostdb) '' failed
> [Nov 24 20:40:46.707] Server {0x2b759d74e700} DEBUG: (hostdb) fail timeout 0
> [Nov 24 20:40:46.707] Server {0x2b759d74e700} DEBUG: (hostdb) delaying force 0 answer for 127.0.0.1
> [Nov 24 20:40:46.707] Server {0x2b759c8953a0} DEBUG: (hostdb) probe aa30de0f80a82135 1 [ignore_timeout = 0]
> [Nov 24 20:40:46.708] Server {0x2b759c8953a0} DEBUG: (hostdb) '' failed
> [Nov 24 20:40:46.708] Server {0x2b759c8953a0} DEBUG: (hostdb) fail timeout 0
> [Nov 24 20:40:46.708] Server {0x2b759c8953a0} DEBUG: (hostdb) DNS IP 127.0.0.1
> {noformat}
> YTS doesn't have this issue:
> {noformat}
> bash-3.2# traffic_server -k
> [Nov 24 20:18:11.941] {4146358528} STATUS: opened /home/y/logs/yts/diags.log
> [Nov 24 20:18:11.959] Server {4146358528} DEBUG: (dns) ink_dns_init: called with init_called = 0
> [Nov 24 20:18:11.992] Server {4146358528} DEBUG: (dns) initial dns_sequence_number = 10131
> [Nov 24 20:18:11.993] Server {4146358528} DEBUG: (dns) localhost=<hostname redacted>
> [Nov 24 20:18:11.993] Server {4146358528} DEBUG: (dns) Round-robin nameservers = 0
> [Nov 24 20:18:12.554] Server {4146358528} DEBUG: (dns) DNSHandler::startEvent: on thread0
> [Nov 24 20:18:12.554] Server {4146358528} DEBUG: (dns) open_con: opening connection <dns server ip redacted>:53
> [Nov 24 20:18:12.554] Server {4146358528} DEBUG: (dns) random port = 28292
> [Nov 24 20:18:12.554] Server {4146358528} DEBUG: (dns) opening connection <dns server ip redacted>:53 SUCCEEDED for 0
> [Nov 24 20:18:12.860] Server {3991255952} DEBUG: (hostdb) probe 127.0.0.1 E9B7563422C93608 0 [ignore_timeout = 0]
> [Nov 24 20:18:12.863] Server {3991255952} DEBUG: (hostdb) delaying force 0 answer for 127.0.0.1 [timeout 0]
> [Nov 24 20:18:12.866] Server {4146358528} DEBUG: (hostdb) probe 127.0.0.1 E9B7563422C93608 0 [ignore_timeout = 0]
> [Nov 24 20:18:12.866] Server {4146358528} DEBUG: (hostdb) DNS 127.0.0.1
> [Nov 24 20:18:12.867] Server {4146358528} DEBUG: (hostdb_insert) inserting in bucket 2926
> [Nov 24 20:18:12.867] Server {4146358528} DEBUG: (hostdb) inserting for: 127.0.0.1: (md5: E9B7563422C93608) now: 1385324292 timeout: 2097151 ttl: 2097151
> [Nov 24 20:18:12.867] Server {4146358528} DEBUG: (hostdb) done 127.0.0.1 TTL 2097151
> [Nov 24 20:18:12.870] Server {4146358528} DEBUG: (hostdb) probe 127.0.0.1 E9B7563422C93608 1 [ignore_timeout = 0]
> [Nov 24 20:18:12.870] Server {4146358528} DEBUG: (hostdb) immediate setby for 127.0.0.1
> [Nov 24 20:18:14.657] Server {3990203280} DEBUG: (hostdb) probe 127.0.0.1 E9B7563422C93608 1 [ignore_timeout = 0]
> [Nov 24 20:18:14.657] Server {3990203280} DEBUG: (hostdb) immediate answer for 127.0.0.1
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.1#6144)