RE: [squid-users] https: fails with CONNECT error:invalid-request

From: Brand, Thomas R. <TRBrand@dont-contact.us>
Date: Thu, 21 Sep 2006 12:03:27 -0400

-----Original Message-----
From: Henrik Nordstrom [mailto:henrik@henriknordstrom.net]
>Looks like your Squid didn't like the request at all.
>What does cache.log say?

The cache log is as follows, see end of page for access.log and
store.log for the same timeframe.

With what (little) I know right now, I suspect that either:
        1) the coporate proxy server is refusing the https connection
           from my squid server, or
      2) I have to modify something in my configuration file, or
      3) To use pass-thru https requests, I need to build squid
         using '--enable-ssl'
      4) both 2 & 3

Thanks for helping out.
Tom

cvs9058[logs] cat cache.log
2006/09/21 11:51:39| Starting Squid Cache version 2.6.STABLE2 for
i686-unknown-sysv5UnixWare7.1.3...
2006/09/21 11:51:39| Process ID 22047
2006/09/21 11:51:39| With 2048 file descriptors available
2006/09/21 11:51:39| DNS Socket created at 0.0.0.0, port 33787, FD 4
2006/09/21 11:51:39| Adding nameserver 10.16.11.11 from /etc/resolv.conf
2006/09/21 11:51:39| Adding nameserver 10.4.3.112 from /etc/resolv.conf
2006/09/21 11:51:39| Adding domain rxstores.cvs.com from
/etc/resolv.conf
2006/09/21 11:51:39| Adding domain cvs.com from /etc/resolv.conf
2006/09/21 11:51:39| Referer logging is disabled.
2006/09/21 11:51:39| Unlinkd pipe opened on FD 9
2006/09/21 11:51:39| Swap maxSize 102400 KB, estimated 7876 objects
2006/09/21 11:51:39| Target number of buckets: 393
2006/09/21 11:51:39| Using 8192 Store buckets
2006/09/21 11:51:39| Max Mem size: 8192 KB
2006/09/21 11:51:39| Max Swap size: 102400 KB
2006/09/21 11:51:39| storeDigestCalcCap: have: 0, want 7876 entries;
limits: [1, 7876]
2006/09/21 11:51:39| cacheDigestInit: capacity: 7876 entries, bpe: 5;
size: 4923 bytes
2006/09/21 11:51:39| Local cache digest enabled; rebuild/rewrite every
3600/3600 sec
2006/09/21 11:51:39| Rebuilding storage in /usr/local/squid/var/cache
(CLEAN)
2006/09/21 11:51:39| Using Least Load store dir selection
2006/09/21 11:51:39| Set Current Directory to
/usr/local/squid/var/coredumps
2006/09/21 11:51:39| Loaded Icons.
2006/09/21 11:51:39| Accepting transparently proxied HTTP connections at
0.0.0.0, port 80, FD 11.
2006/09/21 11:51:39| WCCP Disabled.
2006/09/21 11:51:39| WCCPv2 Disabled.
2006/09/21 11:51:39| Configuring Parent 10.64.2.72/80/0
2006/09/21 11:51:39| --> IP address #0: 10.64.2.72
2006/09/21 11:51:39| Ready to serve requests.
2006/09/21 11:51:39| Done reading /usr/local/squid/var/cache swaplog
(249 entries)
2006/09/21 11:51:39| xrename: renaming
/usr/local/squid/var/cache/swap.state.new to
/usr/local/squid/var/cache/swap.state
2006/09/21 11:51:39| Finished rebuilding storage from disk.
2006/09/21 11:51:39| 249 Entries scanned
2006/09/21 11:51:39| 0 Invalid entries.
2006/09/21 11:51:39| 0 With invalid flags.
2006/09/21 11:51:39| 249 Objects loaded.
2006/09/21 11:51:39| 0 Objects expired.
2006/09/21 11:51:39| 0 Objects cancelled.
2006/09/21 11:51:39| 0 Duplicate URLs purged.
2006/09/21 11:51:39| 0 Swapfile clashes avoided.
2006/09/21 11:51:39| Took 0.4 seconds ( 605.7 objects/sec).
2006/09/21 11:51:39| Beginning Validation Procedure
2006/09/21 11:51:40| Completed Validation Procedure
2006/09/21 11:51:40| Validated 249 Entries
2006/09/21 11:51:40| store_swap_size = 3146k
2006/09/21 11:51:40| storeDigestRebuildStart: rebuild #1
2006/09/21 11:51:40| storeDigestCalcCap: have: 274, want 274 entries;
limits: [243, 7876]
2006/09/21 11:51:40| storeDigestResize: 7876 -> 274; change: 7602 (97%)
2006/09/21 11:51:40| storeDigestResize: big change, resizing.
2006/09/21 11:51:40| cacheDigestInit: capacity: 274 entries, bpe: 5;
size: 172 bytes
2006/09/21 11:51:40| storeDigestRewrite: start rewrite #1
2006/09/21 11:51:40| storeDigestRewriteStart: waiting for rebuild to
finish.
2006/09/21 11:51:40| storeDigestRebuildFinish: done.
2006/09/21 11:51:40| storeDigestRewriteFinish: digest expires at
1158857500 (+3600)
2006/09/21 11:51:40| storeLateRelease: released 0 objects
2006/09/21 11:51:45| NOTICE: no explicit transparent proxy support.
Assuming getsockname works
2006/09/21 11:51:45| The request GET
http://sb.google.com/safebrowsing/update?version=goog-sandbox-text:1:5&w
rkey=MTrwnZd9nPSBFSlC3vjL0M_4 is AL
LOWED, because it matched 'all'
2006/09/21 11:51:45| aclMatchRegex: match '\?' found in
'/safebrowsing/update?version=goog-sandbox-text:1:5&wrkey=MTrwnZd9nPSBFS
lC3vjL0M_4'
2006/09/21 11:51:45| The reply for GET
http://sb.google.com/safebrowsing/update?version=goog-sandbox-text:1:5&w
rkey=MTrwnZd9nPSBFSlC3vjL0M_4 is
ALLOWED, because it matched 'all'
2006/09/21 11:51:45| fwdServerClosed: FD 12
http://sb.google.com/safebrowsing/update?version=goog-sandbox-text:1:5&w
rkey=MTrwnZd9nPSBFSlC3vjL0M_
4
2006/09/21 11:52:14| The request GET http://www.woot.com/Blog/Rss.aspx
is ALLOWED, because it matched 'all'
2006/09/21 11:52:14| The reply for GET http://www.woot.com/Blog/Rss.aspx
is ALLOWED, because it matched 'all'
2006/09/21 11:52:14| fwdServerClosed: FD 12
http://www.woot.com/Blog/Rss.aspx
2006/09/21 11:52:29| The request GET
http://blogs.ittoolbox.com/RSSNewBlogs.asp is ALLOWED, because it
matched 'all'
2006/09/21 11:52:29| The reply for GET
http://blogs.ittoolbox.com/RSSNewBlogs.asp is ALLOWED, because it
matched 'all'
2006/09/21 11:52:29| fwdServerClosed: FD 12
http://blogs.ittoolbox.com/RSSNewBlogs.asp
2006/09/21 11:52:31| clientReadRequest: FD 10 Invalid Request
2006/09/21 11:52:31| The reply for CONNECT error:invalid-request is
ALLOWED, because it matched 'all'
2006/09/21 11:52:36| Preparing for shutdown after 4 requests
2006/09/21 11:52:36| Waiting 30 seconds for active connections to finish

cvs9058[logs] cat access.log
1158853905.613 19 10.31.129.28 TCP_MISS/502 2622 GET
http://sb.google.com/safebrowsing/update? - DEFAULT_PARENT/10.64.2.72
text/html
1158853934.264 19 10.31.129.28 TCP_MISS/502 2622 GET
http://www.woot.com/Blog/Rss.aspx - DEFAULT_PARENT/10.64.2.72 text/html
1158853949.260 19 10.31.129.28 TCP_MISS/502 2622 GET
http://blogs.ittoolbox.com/RSSNewBlogs.asp - DEFAULT_PARENT/10.64.2.72
text/html
1158853951.535 0 10.31.129.28 TCP_DENIED/400 1381 CONNECT
error:invalid-request - NONE/- text/html

cvs9058[logs] cat store.log
1158853905.613 RELEASE -1 FFFFFFFF 6C929B18F5ACD096CF20542F98215314 502
-1 -1 -1 text/html 2358/2358 GET
http://sb.google.com/safebrowsing/update?
1158853934.264 RELEASE -1 FFFFFFFF 5326E7ABDF2D3885D9FB47D2BD3F7FD2 502
-1 -1 -1 text/html 2358/2358 GET
http://www.woot.com/Blog/Rss.aspx
1158853949.260 RELEASE -1 FFFFFFFF 517A296D24FF5EA30F5FC8C6185D9634 502
-1 -1 -1 text/html 2358/2358 GET
http://blogs.ittoolbox.com/RSSNewBlogs.asp
1158853951.535 RELEASE -1 FFFFFFFF 8A86CF060E86EDCF94E6B2078B2CE473 400
1158853951 0 1158853951 text/html 1381/1381 CONNECT
error:invalid-request
cvs9058[logs
Received on Thu Sep 21 2006 - 10:03:39 MDT

This archive was generated by hypermail pre-2.1.9 : Sun Oct 01 2006 - 12:00:04 MDT