ipv6 squid deny_info redirect loop

[Krzysztof Kulaj]

Hello,

I think, there is a problem with deny_info web page when squid is running ipv6 only box. The problem appears on Ubuntu 12.04 LTS server x86_64 (squid from package - 3.1.19) as well as Ubuntu 13.10 (squid from package - 3.3.8). I tested this with firefox and opera - in both cases I got a lot of answers, and firefox end connection with user-message: "Firefox has detected that the server is redirecting the request for this address in a way that will never complete.". In Firebug from Firefox I see a lot of GET webpage with code 302 Moved Temporarily. In firefox squid is set simply as a proxy on port 3128. There is no any problems with dns or routing on squid box (as well as client machine)- all ipv6 addresses (ipv6.google.com, facebook etc) could be simply pinged or connected.

This bug cane be easily reproducable:

squid.conf:
******************************
acl manager proto cache_object
acl localhost src ::1
acl to_localhost dst ::1
acl SSL_ports port 443
acl Safe_ports port 80
acl Safe_ports port 21
acl Safe_ports port 443
acl Safe_ports port 70
acl Safe_ports port 210
acl Safe_ports port 1025-65535
acl Safe_ports port 280
acl Safe_ports port 488
acl Safe_ports port 591
acl Safe_ports port 777
acl CONNECT method CONNECT
acl TestNet src 2001:6f8:X::/48 ## global ipv6 network
acl ProxyServer dst 2001:6f8:X::3:1/96 ## global ipv6 address needed
http_access allow manager localhost
http_access deny manager
http_access deny !Safe_ports
http_access deny CONNECT !SSL_ports
http_access allow localhost
http_access allow ProxyServer
http_access deny TestNet
http_access deny all
http_port 3128
debug_options ALL,3
coredump_dir /var/spool/squid3
refresh_pattern ^ftp: 1440 20% 10080
refresh_pattern ^gopher: 1440 0% 1440
refresh_pattern -i (/cgi-bin/|\?) 0 0% 0
refresh_pattern (Release|Packages(.gz)*)$ 0 20% 2880
refresh_pattern . 0 20% 4320
error_directory /etc/squid3/errors
deny_info http://ipv6.google.com TestNet
****************************************************
I've been also trying to show deny_info webpage from internal network, from the box where squid is running, and others. I also tried to add ipv6.google.com as always_direct, but it bring no results.

/var/log/squid3/access.log
********************
1376732668.599 4 2001:6f8:X:0:68a9:e0da:c29a:1eea TCP_DENIED/302 355 GET http://ipv6.google.com/ - NONE/- text/html
1376732668.615 4 2001:6f8:X:0:68a9:e0da:c29a:1eea TCP_DENIED/302 355 GET http://ipv6.google.com/ - NONE/- text/html
1376732668.631 4 2001:6f8:X:0:68a9:e0da:c29a:1eea TCP_DENIED/302 355 GET http://ipv6.google.com/ - NONE/- text/html
****************
this messages appears 19 times - than connection is closed by firefox.

/var/log/squid3/cache - debug_options ALL,3
********************************************************
2013/08/17 12:02:10.557| fd_open() FD 9 HTTP Request
2013/08/17 12:02:10.557| comm.cc(1207) commSetTimeout: FD 9 timeout 900
2013/08/17 12:02:10.557| ACLList::matches: checking all
2013/08/17 12:02:10.557| ACL::checklistMatches: checking 'all'
2013/08/17 12:02:10.557| aclIpMatchIp: '[2001:6f8:X:0:68a9:e0da:c29a:1eea]:43171' found
2013/08/17 12:02:10.557| ACL::ChecklistMatches: result for 'all' is 1
2013/08/17 12:02:10.557| aclmatchAclList: 0x7fff6fe39e10 returning true (AND list satisfied)
2013/08/17 12:02:10.557| ACLChecklist::markFinished: 0x7fff6fe39e10 checklist processing finished
2013/08/17 12:02:10.559| comm_read_try: FD 9, size 4095, retval 471, errno 0
2013/08/17 12:02:10.559| commio_finish_callback: called for FD 9 (0, 0)
2013/08/17 12:02:10.559| parseHttpRequest: req_hdr = {Host: facebook.com^M
User-Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:23.0) Gecko/20100101 Firefox/23.0^M
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8^M
Accept-Language: en-US,en;q=0.5^M
Accept-Encoding: gzip, deflate^M
Cookie: datr=AX7BUWYNyh5PRT2GW662BWJl; fr=0DzAEbBwZNImObX3T.AWX47S4XqF-sSSayEl_aCetGvOw.BRwt6o.9l.FIC.AWWfKZ19; lu=TglKZMJcu6Qa8n-2rSmBpPYA; locale=pl_PL; csm=2^M
Connection: keep-alive^M
^M
}
2013/08/17 12:02:10.559| parseHttpRequest: end = {
2013/08/17 12:02:10.559| parseHttpRequest: prefix_sz = 471, req_line_sz = 35
2013/08/17 12:02:10.559| clientStreamInsertHead: Inserted node 0x7f0fd14711e8 with data 0x7f0fd1473970 after head
2013/08/17 12:02:10.559| comm.cc(1196) commSetTimeout: FD 9 timeout 86400
2013/08/17 12:02:10.559| comm.cc(1207) commSetTimeout: FD 9 timeout 86400
2013/08/17 12:02:10.559| urlParse: Split URL 'http://facebook.com/' into proto='http', host='facebook.com', port='80', path='/'
2013/08/17 12:02:10.559| clientSetKeepaliveFlag: http_ver = 1.1
2013/08/17 12:02:10.559| clientSetKeepaliveFlag: method = GET
2013/08/17 12:02:10.560| client_side_request.cc(142) ClientRequestContext: 0x7f0fd1471ae8 ClientRequestContext constructed
2013/08/17 12:02:10.560| client_side_request.cc(1322) doCallouts: Doing calloutContext->clientAccessCheck()
2013/08/17 12:02:10.560| ACLChecklist::preCheck: 0x7f0fd1475898 checking 'http_access allow manager localhost'
2013/08/17 12:02:10.560| ACLList::matches: checking manager
2013/08/17 12:02:10.560| ACL::checklistMatches: checking 'manager'
2013/08/17 12:02:10.560| ACL::ChecklistMatches: result for 'manager' is 0
2013/08/17 12:02:10.560| aclmatchAclList: 0x7f0fd1475898 returning false (AND list entry failed to match)
2013/08/17 12:02:10.560| aclmatchAclList: async=0 nodeMatched=0 async_in_progress=0 lastACLResult() = 0 finished() = 0
2013/08/17 12:02:10.560| ACLChecklist::preCheck: 0x7f0fd1475898 checking 'http_access deny manager'
2013/08/17 12:02:10.560| ACLList::matches: checking manager
2013/08/17 12:02:10.560| ACL::checklistMatches: checking 'manager'
2013/08/17 12:02:10.560| ACL::ChecklistMatches: result for 'manager' is 0
2013/08/17 12:02:10.560| aclmatchAclList: 0x7f0fd1475898 returning false (AND list entry failed to match)
2013/08/17 12:02:10.560| aclmatchAclList: async=0 nodeMatched=0 async_in_progress=0 lastACLResult() = 0 finished() = 0
2013/08/17 12:02:10.560| ACLChecklist::preCheck: 0x7f0fd1475898 checking 'http_access deny !Safe_ports'
2013/08/17 12:02:10.560| ACLList::matches: checking !Safe_ports
2013/08/17 12:02:10.560| ACL::checklistMatches: checking 'Safe_ports'
2013/08/17 12:02:10.560| ACL::ChecklistMatches: result for 'Safe_ports' is 1
2013/08/17 12:02:10.560| aclmatchAclList: 0x7f0fd1475898 returning false (AND list entry failed to match)
2013/08/17 12:02:10.560| aclmatchAclList: async=0 nodeMatched=0 async_in_progress=0 lastACLResult() = 0 finished() = 0
2013/08/17 12:02:10.560| ACLChecklist::preCheck: 0x7f0fd1475898 checking 'http_access deny CONNECT !SSL_ports'
2013/08/17 12:02:10.560| ACLList::matches: checking CONNECT
2013/08/17 12:02:10.560| ACL::checklistMatches: checking 'CONNECT'
2013/08/17 12:02:10.560| ACL::ChecklistMatches: result for 'CONNECT' is 0
2013/08/17 12:02:10.560| aclmatchAclList: 0x7f0fd1475898 returning false (AND list entry failed to match)
2013/08/17 12:02:10.560| aclmatchAclList: 0x7f0fd1475898 returning false (AND list entry failed to match)
2013/08/17 12:02:10.560| aclmatchAclList: async=0 nodeMatched=0 async_in_progress=0 lastACLResult() = 0 finished() = 0
2013/08/17 12:02:10.560| ACLChecklist::preCheck: 0x7f0fd1475898 checking 'http_access allow localhost'
2013/08/17 12:02:10.560| ACLList::matches: checking localhost
2013/08/17 12:02:10.560| ACL::checklistMatches: checking 'localhost'
2013/08/17 12:02:10.560| aclIpMatchIp: '[2001:6f8:1c2c:0:68a9:e0da:c29a:1eea]:43171' NOT found
2013/08/17 12:02:10.560| ACL::ChecklistMatches: result for 'localhost' is 0
2013/08/17 12:02:10.560| aclmatchAclList: 0x7f0fd1475898 returning false (AND list entry failed to match)
2013/08/17 12:02:10.560| aclmatchAclList: async=0 nodeMatched=0 async_in_progress=0 lastACLResult() = 0 finished() = 0
2013/08/17 12:02:10.560| ACLChecklist::preCheck: 0x7f0fd1475898 checking 'http_access allow ProxyServer'
2013/08/17 12:02:10.560| ACLList::matches: checking ProxyServer
2013/08/17 12:02:10.560| ACL::checklistMatches: checking 'ProxyServer'
2013/08/17 12:02:10.560| ipcache_gethostbyname: 'facebook.com', flags=1
2013/08/17 12:02:10.560| idnsALookup: buf is 30 bytes for facebook.com, id = 0xb39c
2013/08/17 12:02:10.560| comm_udp_sendto: Attempt to send UDP packet to [2001:4860:4860::8844]:53 using FD 5 using Port 52660
2013/08/17 12:02:10.560| aclMatchAcl: Can't yet compare 'ProxyServer' ACL for 'facebook.com'
2013/08/17 12:02:10.560| ACL::ChecklistMatches: result for 'ProxyServer' is 0
2013/08/17 12:02:10.560| aclmatchAclList: 0x7f0fd1475898 returning false (AND list entry failed to match)
2013/08/17 12:02:10.560| ACLChecklist::asyncInProgress: 0x7f0fd1475898 async set to 1
2013/08/17 12:02:10.560| aclmatchAclList: async=1 nodeMatched=0 async_in_progress=1 lastACLResult() = 0 finished() = 0
2013/08/17 12:02:10.599| idnsRead: starting with FD 5
2013/08/17 12:02:10.599| idnsRead: FD 5: received 58 bytes from [2001:4860:4860::8844]:53
2013/08/17 12:02:10.599| idnsGrokReply: ID 0xb39c, 1 answers
2013/08/17 12:02:10.599| idnsGrokReply: facebook.com AAAA query done. Configured to retrieve A now also.
2013/08/17 12:02:10.599| comm_udp_sendto: Attempt to send UDP packet to [2001:4860:4860::8844]:53 using FD 5 using Port 52660
2013/08/17 12:02:10.639| idnsRead: starting with FD 5
2013/08/17 12:02:10.639| idnsRead: FD 5: received 46 bytes from [2001:4860:4860::8844]:53
2013/08/17 12:02:10.639| idnsGrokReply: ID 0x32d, 1 answers
2013/08/17 12:02:10.639| ipcacheParse: facebook.com #0 [2a03:2880:2110:df07:face:b00c:0:1]
2013/08/17 12:02:10.639| ipcacheParse: facebook.com #1 173.252.110.27
2013/08/17 12:02:10.639| ipcacheParse: facebook.com #0 [2a03:2880:2110:df07:face:b00c:0:1]
2013/08/17 12:02:10.639| ipcacheParse: facebook.com #1 173.252.110.27
2013/08/17 12:02:10.639| ipcacheRelease: Releasing entry for 'facebook.com'
2013/08/17 12:02:10.639| ACLChecklist::asyncInProgress: 0x7f0fd1475898 async set to 0
2013/08/17 12:02:10.639| ACLChecklist::preCheck: 0x7f0fd1475898 checking 'http_access allow ProxyServer'
2013/08/17 12:02:10.639| ACLList::matches: checking ProxyServer
2013/08/17 12:02:10.639| ACL::checklistMatches: checking 'ProxyServer'
2013/08/17 12:02:10.639| ipcache_gethostbyname: 'facebook.com', flags=1
2013/08/17 12:02:10.639| aclIpMatchIp: '[2a03:2880:2110:df07:face:b00c:0:1]' NOT found
2013/08/17 12:02:10.639| aclIpMatchIp: '173.252.110.27' NOT found
2013/08/17 12:02:10.639| ACL::ChecklistMatches: result for 'ProxyServer' is 0
2013/08/17 12:02:10.639| aclmatchAclList: 0x7f0fd1475898 returning false (AND list entry failed to match)
2013/08/17 12:02:10.639| aclmatchAclList: async=0 nodeMatched=0 async_in_progress=0 lastACLResult() = 0 finished() = 0
2013/08/17 12:02:10.639| ACLChecklist::preCheck: 0x7f0fd1475898 checking 'http_access deny TestNet'
2013/08/17 12:02:10.639| ACLList::matches: checking TestNet
2013/08/17 12:02:10.639| ACL::checklistMatches: checking 'TestNet'
2013/08/17 12:02:10.640| aclIpMatchIp: '[2001:6f8:1c2c:0:68a9:e0da:c29a:1eea]:43171' found
2013/08/17 12:02:10.640| ACL::ChecklistMatches: result for 'TestNet' is 1
2013/08/17 12:02:10.640| aclmatchAclList: 0x7f0fd1475898 returning true (AND list satisfied)
2013/08/17 12:02:10.640| ACLChecklist::markFinished: 0x7f0fd1475898 checklist processing finished
2013/08/17 12:02:10.640| ACLChecklist::check: 0x7f0fd1475898 match found, calling back with 0
2013/08/17 12:02:10.640| ACLChecklist::checkCallback: 0x7f0fd1475898 answer=0
2013/08/17 12:02:10.640| The request GET http://facebook.com/ is DENIED, because it matched 'TestNet'
2013/08/17 12:02:10.640| storeCreateEntry: 'http://facebook.com/'
2013/08/17 12:02:10.640| store.cc(360) StoreEntry: new StoreEntry 0x7f0fd147a820
2013/08/17 12:02:10.640| MemObject.cc(76) MemObject: new MemObject 0x7f0fd147a8a0
2013/08/17 12:02:10.640| storeKeyPrivate: GET http://facebook.com/
2013/08/17 12:02:10.640| StoreEntry::hashInsert: Inserting Entry 0x7f0fd147a820 key '18620A22ADA2558D3273E75EFC62970F'
2013/08/17 12:02:10.640| StoreEntry::setReleaseFlag: '18620A22ADA2558D3273E75EFC62970F'
2013/08/17 12:02:10.640| StoreEntry::lock: key '18620A22ADA2558D3273E75EFC62970F' count=2
2013/08/17 12:02:10.640| StoreEntry::replaceHttpReply: http://facebook.com/
2013/08/17 12:02:10.640| InvokeHandlers: 18620A22ADA2558D3273E75EFC62970F
2013/08/17 12:02:10.640| StoreEntry::InvokeHandlers: checking client #0
2013/08/17 12:02:10.640| storeComplete: '18620A22ADA2558D3273E75EFC62970F'
2013/08/17 12:02:10.640| storeEntryValidLength: Checking '18620A22ADA2558D3273E75EFC62970F'
2013/08/17 12:02:10.640| InvokeHandlers: 18620A22ADA2558D3273E75EFC62970F
2013/08/17 12:02:10.640| StoreEntry::InvokeHandlers: checking client #0
2013/08/17 12:02:10.640| StoreEntry::unlock: key '18620A22ADA2558D3273E75EFC62970F' count=1
2013/08/17 12:02:10.640| clientStreamRead: Calling 1 with cbdata 0x7f0fd1474b50 from node 0x7f0fd14711e8
2013/08/17 12:02:10.640| store_client::copy: 18620A22ADA2558D3273E75EFC62970F, from 0, for length 4096, cb 1, cbdata 0x7f0fd1473a98
2013/08/17 12:02:10.640| storeClientCopy2: 18620A22ADA2558D3273E75EFC62970F
2013/08/17 12:02:10.640| store_client::doCopy: Copying normal from memory
2013/08/17 12:02:10.640| ZPH: Preserving TOS on miss, TOS=0
2013/08/17 12:02:10.640| The reply for GET http://facebook.com/ is ALLOWED, because it matched 'TestNet'
2013/08/17 12:02:10.640| StoreEntry::lock: key '18620A22ADA2558D3273E75EFC62970F' count=2
2013/08/17 12:02:10.640| clientReplyContext::sendMoreData: Appending 0 bytes after 224 bytes of headers
2013/08/17 12:02:10.640| clientStreamCallback: Calling 1 with cbdata 0x7f0fd1473970 from node 0x7f0fd146fc58
2013/08/17 12:02:10.640| commio_finish_callback: called for FD 9 (0, 11)
2013/08/17 12:02:10.640| client_side_reply.cc(1037) storeOKTransferDone: storeOKTransferDone out.offset=0 objectLen()=224 headers_sz=224
2013/08/17 12:02:10.641| ClientSocketContext::keepaliveNextRequest: FD 9
2013/08/17 12:02:10.641| clientStreamDetach: Detaching node 0x7f0fd14711e8
2013/08/17 12:02:10.641| Freeing clientStreamNode 0x7f0fd14711e8
2013/08/17 12:02:10.641| httpRequestFree: http://facebook.com/
2013/08/17 12:02:10.641| StoreEntry::unlock: key '18620A22ADA2558D3273E75EFC62970F' count=1
2013/08/17 12:02:10.641| clientStreamAbort: Aborting stream with tail 0x7f0fd146fc58
2013/08/17 12:02:10.641| clientStreamDetach: Detaching node 0x7f0fd146fc58
2013/08/17 12:02:10.641| client_side_request.cc(130) ~ClientRequestContext: 0x7f0fd1471ae8 ClientRequestContext destructed
2013/08/17 12:02:10.641| clientStreamDetach: Calling 1 with cbdata 0x7f0fd1474b50
2013/08/17 12:02:10.641| Freeing clientStreamNode 0x7f0fd146fc58
2013/08/17 12:02:10.641| storeUnregister: called for '18620A22ADA2558D3273E75EFC62970F'
2013/08/17 12:02:10.641| storePendingNClients: returning 0
2013/08/17 12:02:10.641| StoreEntry::unlock: key '18620A22ADA2558D3273E75EFC62970F' count=0
2013/08/17 12:02:10.641| storePendingNClients: returning 0
2013/08/17 12:02:10.641| storeRelease: Releasing: '18620A22ADA2558D3273E75EFC62970F'
2013/08/17 12:02:10.641| store.cc(403) destroyStoreEntry: destroyStoreEntry: destroying 0x7f0fd147a828
2013/08/17 12:02:10.641| store.cc(393) destroyMemObject: destroyMemObject 0x7f0fd147a8a0
2013/08/17 12:02:10.641| MemObject.cc(97) ~MemObject: del MemObject 0x7f0fd147a8a0
2013/08/17 12:02:10.641| ClientSocketContext:: FD 9: calling conn->readNextRequest()
2013/08/17 12:02:10.641| comm.cc(1207) commSetTimeout: FD 9 timeout 120
*********************************************************
this cache logs appears several time, I pasted only first request.

I will be happy If I'm able to anwser any your question or provide more information about this bug.

[Krzysztof-kulaj-s (krzysztof-kulaj-s)]

Hello,

I think, there is a problem with deny_info web page when squid is running ipv6 only box. The problem appears on Ubuntu 12.04 LTS server x86_64 (squid from package - 3.1.19) as well as Ubuntu 13.10 (squid from package - 3.3.8). I tested this with firefox and opera - in both cases I got a lot of answers, and firefox end connection with user-message: "Firefox has detected that the server is redirecting the request for this address in a way that will never complete.". In Firebug from Firefox I see a lot of GET webpage with code 302 Moved Temporarily. In firefox squid is set simply as a proxy on port 3128. There is no any problems with dns or routing on squid box (as well as client machine)- all ipv6 addresses (ipv6.google.com, facebook etc) could be simply pinged or connected.

This bug cane be easily reproducable:

squid.conf:
******************************
acl manager proto cache_object
acl localhost src ::1
acl to_localhost dst ::1
acl SSL_ports port 443
acl Safe_ports port 80
acl Safe_ports port 21
acl Safe_ports port 443
acl Safe_ports port 70
acl Safe_ports port 210
acl Safe_ports port 1025-65535
acl Safe_ports port 280
acl Safe_ports port 488
acl Safe_ports port 591
acl Safe_ports port 777
acl CONNECT method CONNECT
acl TestNet src 2001:6f8:X::/48 ## global ipv6 network
acl ProxyServer dst 2001:6f8:X::3:1/96 ## global ipv6 address needed
http_access allow manager localhost
http_access deny manager
http_access deny !Safe_ports
http_access deny CONNECT !SSL_ports
http_access allow localhost
http_access allow ProxyServer
http_access deny TestNet
http_access deny all
http_port 3128
debug_options ALL,3
coredump_dir /var/spool/squid3
refresh_pattern ^ftp: 1440 20% 10080
refresh_pattern ^gopher: 1440 0% 1440
refresh_pattern -i (/cgi-bin/|\?) 0 0% 0
refresh_pattern (Release|Packages(.gz)*)$ 0 20% 2880
refresh_pattern . 0 20% 4320
error_directory /etc/squid3/errors
deny_info http://ipv6.google.com TestNet
****************************************************
I've been also trying to show deny_info webpage from internal network, from the box where squid is running, and others. I also tried to add ipv6.google.com as always_direct, but it bring no results.

/var/log/squid3/access.log
********************
1376732668.599 4 2001:6f8:X:0:68a9:e0da:c29a:1eea TCP_DENIED/302 355 GET http://ipv6.google.com/ - NONE/- text/html
1376732668.615 4 2001:6f8:X:0:68a9:e0da:c29a:1eea TCP_DENIED/302 355 GET http://ipv6.google.com/ - NONE/- text/html
1376732668.631 4 2001:6f8:X:0:68a9:e0da:c29a:1eea TCP_DENIED/302 355 GET http://ipv6.google.com/ - NONE/- text/html
****************
this messages appears 19 times - than connection is closed by firefox.

/var/log/squid3/cache - debug_options ALL,3
********************************************************
2013/08/17 12:02:10.557| fd_open() FD 9 HTTP Request
2013/08/17 12:02:10.557| comm.cc(1207) commSetTimeout: FD 9 timeout 900
2013/08/17 12:02:10.557| ACLList::matches: checking all
2013/08/17 12:02:10.557| ACL::checklistMatches: checking 'all'
2013/08/17 12:02:10.557| aclIpMatchIp: '[2001:6f8:X:0:68a9:e0da:c29a:1eea]:43171' found
2013/08/17 12:02:10.557| ACL::ChecklistMatches: result for 'all' is 1
2013/08/17 12:02:1...

[Amos Jeffries (yadi)]

This is a user error in teh configuration. The browser being able to detect that shows deny_info is in fact working correctly.

The logged test is a request for a URL which is hosted on 2a03:2880:2110:df07:face:b00c:0:1.
 Note that this is outside of the permitted webserver dst range 2001:6f8:X::3:1/96 which is strangely labeled "ProxyServer".

Meaning that Squid ACLs will skip down to the deny TestNet line. Since the request is coming from a client in the range 2001:6f8:X::/48 it will be rejected by "deny TestNet" with a 302 redirect to http://ipv6.google.com as configured by deny_info.

When the client browser follows that redirection by making the request for http://ipv6.google.com/...

Squid preforms teh same sequence. This time finding the IP address for ipv6.google.com is another dst IP outside the 2001:6f8:X::3:1/96 IP address range. Resulting in an identical redirection.

The browser detects that http://ipv6.google.com/is being redirected to http://ipv6.google.com and halts.

[Amos Jeffries (yadi)]

this us a user configuration error.