Re: [squid-users] How to debug external_acl_type

Hello,

Am 26.08.09 18:24, "John Doe" <jdmls_at_yahoo.com> schrieb:

> From: Maik Kündig <Maik.Kuendig_at_reist-tele.com>
>> auth_param basic program /usr/local/bin/my-auth.pl
>> external_acl_type myAclType children=1 ttl=1 %SRC %LOGIN
>> /usr/local/bin/foobar
>> acl MyAcl external myAclType
>> http_access allow MyAcl
>
> Maybe could you try with 'ttl=10'?
> If it is still not working, could you try to set 'concurrency=0'?

Don't work, I have attached the debug output. May this is a Problem?

2009/08/26 18:44:13| The reply for GET http://www.openbsd.org/ is ALLOWED,
because it matched 'MyAcl'

2009/08/26 18:44:13| The request GET http://www.openbsd.org/ is DENIED,
because it matched 'MyAcl'

-----8<-----
2009/08/26 18:43:56| Starting Squid Cache version 2.7.STABLE3 for
i386-debian-linux-gnu...
2009/08/26 18:43:56| Process ID 11308
2009/08/26 18:43:56| With 1024 file descriptors available
2009/08/26 18:43:56| Using epoll for the IO loop
2009/08/26 18:43:56| DNS Socket created at 0.0.0.0, port 37780, FD 6
2009/08/26 18:43:56| Adding domain localdomain from /etc/resolv.conf
2009/08/26 18:43:56| Adding domain localdomain from /etc/resolv.conf
2009/08/26 18:43:56| Adding nameserver 192.168.32.2 from /etc/resolv.conf
2009/08/26 18:43:56| helperOpenServers: Starting 5 'my-auth.pl' processes
2009/08/26 18:43:56| helperOpenServers: Starting 1 'foobar' processes
2009/08/26 18:43:56| User-Agent logging is disabled.
2009/08/26 18:43:56| Referer logging is disabled.
2009/08/26 18:43:56| logfileOpen: opening log /var/log/squid/access.log
2009/08/26 18:43:56| Unlinkd pipe opened on FD 17
2009/08/26 18:43:56| Swap maxSize 102400 KB, estimated 7876 objects
2009/08/26 18:43:56| Target number of buckets: 393
2009/08/26 18:43:56| Using 8192 Store buckets
2009/08/26 18:43:56| Max Mem size: 8192 KB
2009/08/26 18:43:56| Max Swap size: 102400 KB
2009/08/26 18:43:56| Local cache digest enabled; rebuild/rewrite every
3600/3600 sec
2009/08/26 18:43:56| logfileOpen: opening log /var/log/squid/store.log
2009/08/26 18:43:56| Rebuilding storage in /var/spool/squid (CLEAN)
2009/08/26 18:43:56| Using Least Load store dir selection
2009/08/26 18:43:56| Set Current Directory to /var/spool/squid
2009/08/26 18:43:56| Loaded Icons.
2009/08/26 18:43:57| Accepting proxy HTTP connections at 0.0.0.0, port 3128,
FD 19.
2009/08/26 18:43:57| Accepting ICP messages at 0.0.0.0, port 3130, FD 20.
2009/08/26 18:43:57| HTCP Disabled.
2009/08/26 18:43:57| WCCP Disabled.
2009/08/26 18:43:57| Ready to serve requests.
2009/08/26 18:43:57| Done reading /var/spool/squid swaplog (0 entries)
2009/08/26 18:43:57| Finished rebuilding storage from disk.
2009/08/26 18:43:57| 0 Entries scanned
2009/08/26 18:43:57| 0 Invalid entries.
2009/08/26 18:43:57| 0 With invalid flags.
2009/08/26 18:43:57| 0 Objects loaded.
2009/08/26 18:43:57| 0 Objects expired.
2009/08/26 18:43:57| 0 Objects cancelled.
2009/08/26 18:43:57| 0 Duplicate URLs purged.
2009/08/26 18:43:57| 0 Swapfile clashes avoided.
2009/08/26 18:43:57| Took 0.3 seconds ( 0.0 objects/sec).
2009/08/26 18:43:57| Beginning Validation Procedure
2009/08/26 18:43:57| Completed Validation Procedure
2009/08/26 18:43:57| Validated 0 Entries
2009/08/26 18:43:57| store_swap_size = 0k
2009/08/26 18:43:57| storeLateRelease: released 0 objects
2009/08/26 18:44:00| comm_select: timeout 472
2009/08/26 18:44:01| comm_select: time out
2009/08/26 18:44:01| comm_select: timeout 1
2009/08/26 18:44:01| comm_select: time out
2009/08/26 18:44:01| eventRun: RUN ID 19
2009/08/26 18:44:01| eventRun: Running 'MaintainSwapSpace', id 18

...

2009/08/26 18:44:08| created entry 0x892d7d0: 'Server: squid/2.7.STABLE3'
2009/08/26 18:44:08| 0x892c788 adding entry: 47 at 0
2009/08/26 18:44:08| created entry 0x892d838: 'Date: Wed, 26 Aug 2009
16:44:08 GMT'
2009/08/26 18:44:08| 0x892c788 adding entry: 23 at 1
2009/08/26 18:44:08| created entry 0x892d858: 'Content-Type: text/html'
2009/08/26 18:44:08| 0x892c788 adding entry: 18 at 2
2009/08/26 18:44:08| created entry 0x892e1b0: 'Content-Length: 1330'
2009/08/26 18:44:08| 0x892c788 adding entry: 14 at 3
2009/08/26 18:44:08| created entry 0x892e1f8: 'Expires: Wed, 26 Aug 2009
16:44:08 GMT'
2009/08/26 18:44:08| 0x892c788 adding entry: 25 at 4
2009/08/26 18:44:08| created entry 0x892e240: 'X-Squid-Error:
ERR_CACHE_ACCESS_DENIED 0'
2009/08/26 18:44:08| 0x892c788 adding entry: 61 at 5
2009/08/26 18:44:08| authenticateFixHeader: headertype:38 authuser:(nil)
2009/08/26 18:44:08| authenticateFixErrorHeader: Sending type:38 header:
'Basic realm="Squid proxy-caching web server"'
2009/08/26 18:44:08| created entry 0x892e288: 'Proxy-Authenticate: Basic
realm="Squid proxy-caching web server"'
2009/08/26 18:44:08| 0x892c788 adding entry: 38 at 6
2009/08/26 18:44:08| cleaning hdr: 0x892b618 owner: 3
2009/08/26 18:44:08| packing sline 0x892b608 using 0xbf84db50:
2009/08/26 18:44:08| HTTP/1.0 407 Proxy Authentication Required

...

2009/08/26 18:44:13| comm_select: timeout 1000
2009/08/26 18:44:13| comm_call_handlers(): got fd=19 read_event=1
write_event=0 F->read_handler=0x80666d0 F->write_handler=(nil)
2009/08/26 18:44:13| comm_call_handlers(): Calling read handler on fd=19
2009/08/26 18:44:13| commSetSelect: FD 19 type 1
2009/08/26 18:44:13| commSetEvents(fd=19)
2009/08/26 18:44:13| fd_open FD 18 HTTP Request
2009/08/26 18:44:13| httpAccept: FD 18: accepted port 3128 client
192.168.32.1:53074
2009/08/26 18:44:13| cbdataLock: 0x872d248
2009/08/26 18:44:13| comm_add_close_handler: FD 18, handler=0x806dd30,
data=0x892aaa8
2009/08/26 18:44:13| cbdataLock: 0x892aaa8
2009/08/26 18:44:13| commSetTimeout: FD 18 timeout 300
2009/08/26 18:44:13| aclCheckFast: list: 0x872b7f0
2009/08/26 18:44:13| aclMatchAclList: checking all
2009/08/26 18:44:13| aclMatchAcl: checking 'acl all src all'
2009/08/26 18:44:13| aclMatchIp: '192.168.32.1' found
2009/08/26 18:44:13| aclMatchAclList: returning 1
2009/08/26 18:44:13| commSetSelect: FD 18 type 1
2009/08/26 18:44:13| commSetEvents(fd=18)
2009/08/26 18:44:13| comm_accept: FD 19: (11) Resource temporarily
unavailable
2009/08/26 18:44:13| comm_select: timeout 485
2009/08/26 18:44:13| comm_call_handlers(): got fd=18 read_event=1
write_event=0 F->read_handler=0x806acf0 F->write_handler=(nil)
2009/08/26 18:44:13| comm_call_handlers(): Calling read handler on fd=18
2009/08/26 18:44:13| clientReadRequest: FD 18: reading request...
2009/08/26 18:44:13| cbdataLock: 0x892aaa8
2009/08/26 18:44:13| cbdataValid: 0x892aaa8
2009/08/26 18:44:13| Parser: retval 1: from 0->37: method 0->2; url 4->26;
version 28->36 (1/1)
2009/08/26 18:44:13| parseHttpRequest: Method is 'GET'
2009/08/26 18:44:13| parseHttpRequest: URI is 'http://www.openbsd.org/'
2009/08/26 18:44:13| parseHttpRequest: req_hdr = {Host: www.openbsd.org

User-Agent: Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10_5_8; de-de)
AppleWebKit/531.9 (KHTML, like Gecko) Version/4.0.3 Safari/531.9

Accept:
application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image
/png,*/*;q=0.5

Accept-Language: de-de

Accept-Encoding: gzip, deflate

Connection: keep-alive

Proxy-Connection: keep-alive

}
2009/08/26 18:44:13| parseHttpRequest: prefix_sz = 408, req_line_sz = 38
2009/08/26 18:44:13| parseHttpRequest: Request Header is

Host: www.openbsd.org

User-Agent: Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10_5_8; de-de)
AppleWebKit/531.9 (KHTML, like Gecko) Version/4.0.3 Safari/531.9

Accept:
application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image
/png,*/*;q=0.5

Accept-Language: de-de

Accept-Encoding: gzip, deflate

Connection: keep-alive

Proxy-Connection: keep-alive

2009/08/26 18:44:13| parseHttpRequest: Complete request received
2009/08/26 18:44:13| commSetTimeout: FD 18 timeout 86400
2009/08/26 18:44:13| init-ing hdr: 0x8907f6c owner: 2
2009/08/26 18:44:13| parsing hdr: (0x8907f6c)
Host: www.openbsd.org

User-Agent: Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10_5_8; de-de)
AppleWebKit/531.9 (KHTML, like Gecko) Version/4.0.3 Safari/531.9

Accept:
application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image
/png,*/*;q=0.5

Accept-Language: de-de

Accept-Encoding: gzip, deflate

Connection: keep-alive

Proxy-Connection: keep-alive

2009/08/26 18:44:13| creating entry 0x892f8b8: near 'Host: www.openbsd.org'
2009/08/26 18:44:13| created entry 0x892f8b8: 'Host: www.openbsd.org'
2009/08/26 18:44:13| 0x8907f6c adding entry: 27 at 0
2009/08/26 18:44:13| creating entry 0x892f810: near 'User-Agent: Mozilla/5.0
(Macintosh; U; Intel Mac OS X 10_5_8; de-de) AppleWebKit/531.9 (KHTML, like
Gecko) Version/4.0.3 Safari/531.9'
2009/08/26 18:44:13| created entry 0x892f810: 'User-Agent: Mozilla/5.0
(Macintosh; U; Intel Mac OS X 10_5_8; de-de) AppleWebKit/531.9 (KHTML, like
Gecko) Version/4.0.3 Safari/531.9'
2009/08/26 18:44:13| 0x8907f6c adding entry: 50 at 1
2009/08/26 18:44:13| creating entry 0x892f6e0: near 'Accept:
application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image
/png,*/*;q=0.5'
2009/08/26 18:44:13| created entry 0x892f6e0: 'Accept:
application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image
/png,*/*;q=0.5'
2009/08/26 18:44:13| 0x8907f6c adding entry: 0 at 2
2009/08/26 18:44:13| creating entry 0x892f698: near 'Accept-Language: de-de'
2009/08/26 18:44:13| created entry 0x892f698: 'Accept-Language: de-de'
2009/08/26 18:44:13| 0x8907f6c adding entry: 3 at 3
2009/08/26 18:44:13| creating entry 0x892f5c8: near 'Accept-Encoding: gzip,
deflate'
2009/08/26 18:44:13| created entry 0x892f5c8: 'Accept-Encoding: gzip,
deflate'
2009/08/26 18:44:13| 0x8907f6c adding entry: 2 at 4
2009/08/26 18:44:13| creating entry 0x892f580: near 'Connection: keep-alive'
2009/08/26 18:44:13| created entry 0x892f580: 'Connection: keep-alive'
2009/08/26 18:44:13| 0x8907f6c adding entry: 9 at 5
2009/08/26 18:44:13| creating entry 0x892f538: near 'Proxy-Connection:
keep-alive'
2009/08/26 18:44:13| created entry 0x892f538: 'Proxy-Connection: keep-alive'
2009/08/26 18:44:13| 0x8907f6c adding entry: 41 at 6
2009/08/26 18:44:13| removing 408 bytes; conn->in.offset = 0
2009/08/26 18:44:13| 0x8907f6c lookup for 20
2009/08/26 18:44:13| clientSetKeepaliveFlag: http_ver = 1.1
2009/08/26 18:44:13| clientSetKeepaliveFlag: method = GET
2009/08/26 18:44:13| 0x8907f6c lookup for 41
2009/08/26 18:44:13| 0x8907f6c: joining for id 41
2009/08/26 18:44:13| 0x8907f6c: joined for id 41: keep-alive
2009/08/26 18:44:13| 0x8907f6c lookup for 52
2009/08/26 18:44:13| 0x8907f6c lookup for 41
2009/08/26 18:44:13| 0x8907f6c: joining for id 41
2009/08/26 18:44:13| 0x8907f6c: joined for id 41: keep-alive
2009/08/26 18:44:13| 0x8907f6c lookup for 59
2009/08/26 18:44:13| cbdataLock: 0x872b978
2009/08/26 18:44:13| cbdataLock: 0x892aaa8
2009/08/26 18:44:13| cbdataLock: 0x892ace8
2009/08/26 18:44:13| cbdataValid: 0x872b978
2009/08/26 18:44:13| aclCheck: checking 'http_access allow MyAcl'
2009/08/26 18:44:13| aclMatchAclList: checking MyAcl
2009/08/26 18:44:13| aclMatchAcl: checking 'acl MyAcl external myAclType'
2009/08/26 18:44:13| aclMatchExternal: acl="myAclType"
2009/08/26 18:44:13| authenticateValidateUser: Validating Auth_user request
'(nil)'.
2009/08/26 18:44:13| authenticateValidateUser: Auth_user_request was NULL!
2009/08/26 18:44:13| authenticateAuthenticate: broken auth or no proxy_auth
header. Requesting auth header.
2009/08/26 18:44:13| aclAuthenticated: returning 0 sending authentication
challenge.
2009/08/26 18:44:13| aclMatchExternal: myAclType user not authenticated (-1)
2009/08/26 18:44:13| aclMatchAclList: no match, returning 0
2009/08/26 18:44:13| aclCheck: requiring Proxy Auth header.
2009/08/26 18:44:13| aclCheck: match found, returning 2
2009/08/26 18:44:13| cbdataUnlock: 0x872b978
2009/08/26 18:44:13| aclCheckCallback: answer=2
2009/08/26 18:44:13| cbdataValid: 0x892ace8
2009/08/26 18:44:13| The request GET http://www.openbsd.org/ is DENIED,
because it matched 'MyAcl'
2009/08/26 18:44:13| Access Denied: http://www.openbsd.org/
2009/08/26 18:44:13| AclMatchedName = MyAcl
2009/08/26 18:44:13| Proxy Auth Message = <null>
2009/08/26 18:44:13| storeCreateEntry: 'http://www.openbsd.org/'
2009/08/26 18:44:13| creating rep: 0x892c748
2009/08/26 18:44:13| init-ing hdr: 0x892c788 owner: 3
2009/08/26 18:44:13| 0x892c788 lookup for 41
2009/08/26 18:44:13| 0x892c788 lookup for 9
2009/08/26 18:44:13| 0x892c788 lookup for 41
2009/08/26 18:44:13| 0x892c788 lookup for 9
2009/08/26 18:44:13| 0x892c788 lookup for 25
2009/08/26 18:44:13| new_MemObject: returning 0x892b538
2009/08/26 18:44:13| new_StoreEntry: returning 0x892b500
2009/08/26 18:44:13| storeKeyPrivate: GET http://www.openbsd.org/
2009/08/26 18:44:13| storeHashInsert: Inserting Entry 0x892b500 key
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| storeReleaseRequest: 'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| storeLockObject: (store_client.c:122): key
'A83EE53AFB79EF45119733090C8AE2DF' count=2
2009/08/26 18:44:13| storeClientCopy: A83EE53AFB79EF45119733090C8AE2DF, seen
0, want 0, size 4096, cb 0x8071590, cbdata 0x892ace8
2009/08/26 18:44:13| cbdataLock: 0x892ace8
2009/08/26 18:44:13| cbdataLock: 0x892b698
2009/08/26 18:44:13| storeClientCopy2: A83EE53AFB79EF45119733090C8AE2DF
2009/08/26 18:44:13| storeClientCopy3: Waiting for more
2009/08/26 18:44:13| cbdataUnlock: 0x892b698
2009/08/26 18:44:13| storeLockObject: (errorpage.c:316): key
'A83EE53AFB79EF45119733090C8AE2DF' count=3
2009/08/26 18:44:13| creating rep: 0x892b5d8
2009/08/26 18:44:13| init-ing hdr: 0x892b618 owner: 3
2009/08/26 18:44:13| 0x892b618 lookup for 41
2009/08/26 18:44:13| 0x892b618 lookup for 9
2009/08/26 18:44:13| 0x892b618 lookup for 41
2009/08/26 18:44:13| 0x892b618 lookup for 9
2009/08/26 18:44:13| 0x892b618 lookup for 25
2009/08/26 18:44:13| errorConvert: %U --> 'http://www.openbsd.org/'
2009/08/26 18:44:13| errorConvert: %U --> 'http://www.openbsd.org/'
2009/08/26 18:44:13| errorConvert: %U --> 'http://www.openbsd.org/'
2009/08/26 18:44:13| errorConvert: %w --> 'webmaster'
2009/08/26 18:44:13| errorConvert: %h --> 'squid-ads.localdomain'
2009/08/26 18:44:13| errorConvert: %T --> 'Wed, 26 Aug 2009 16:44:13 GMT'
2009/08/26 18:44:13| errorConvert: %h --> 'squid-ads.localdomain'
2009/08/26 18:44:13| errorConvert: %s --> 'squid/2.7.STABLE3'
2009/08/26 18:44:13| errorConvert: %S --> '
<BR clear="all">
<HR noshade size="1px">
<ADDRESS>
Generated Wed, 26 Aug 2009 16:44:13 GMT by squid-ads.localdomain
(squid/2.7.STABLE3)
</ADDRESS>
</BODY></HTML>
'
2009/08/26 18:44:13| created entry 0x892f4f0: 'Server: squid/2.7.STABLE3'
2009/08/26 18:44:13| 0x892b618 adding entry: 47 at 0
2009/08/26 18:44:13| created entry 0x892f4a8: 'Date: Wed, 26 Aug 2009
16:44:13 GMT'
2009/08/26 18:44:13| 0x892b618 adding entry: 23 at 1
2009/08/26 18:44:13| created entry 0x892f460: 'Content-Type: text/html'
2009/08/26 18:44:13| 0x892b618 adding entry: 18 at 2
2009/08/26 18:44:13| created entry 0x892f3d0: 'Content-Length: 1321'
2009/08/26 18:44:13| 0x892b618 adding entry: 14 at 3
2009/08/26 18:44:13| created entry 0x892b368: 'Expires: Wed, 26 Aug 2009
16:44:13 GMT'
2009/08/26 18:44:13| 0x892b618 adding entry: 25 at 4
2009/08/26 18:44:13| created entry 0x892b320: 'X-Squid-Error:
ERR_CACHE_ACCESS_DENIED 0'
2009/08/26 18:44:13| 0x892b618 adding entry: 61 at 5
2009/08/26 18:44:13| authenticateFixHeader: headertype:38 authuser:(nil)
2009/08/26 18:44:13| authenticateFixErrorHeader: Sending type:38 header:
'Basic realm="Squid proxy-caching web server"'
2009/08/26 18:44:13| created entry 0x892b278: 'Proxy-Authenticate: Basic
realm="Squid proxy-caching web server"'
2009/08/26 18:44:13| 0x892b618 adding entry: 38 at 6
2009/08/26 18:44:13| cleaning hdr: 0x892c788 owner: 3
2009/08/26 18:44:13| packing sline 0x892c778 using 0xbf84db50:
2009/08/26 18:44:13| HTTP/1.0 407 Proxy Authentication Required

2009/08/26 18:44:13| storeAppend: appending 44 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 44
2009/08/26 18:44:13| packing hdr: (0x892c788)
2009/08/26 18:44:13| storeAppend: appending 6 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 6
2009/08/26 18:44:13| storeAppend: appending 2 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 2
2009/08/26 18:44:13| storeAppend: appending 17 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 17
2009/08/26 18:44:13| storeAppend: appending 2 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 2
2009/08/26 18:44:13| storeAppend: appending 4 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 4
2009/08/26 18:44:13| storeAppend: appending 2 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 2
2009/08/26 18:44:13| storeAppend: appending 29 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 29
2009/08/26 18:44:13| storeAppend: appending 2 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 2
2009/08/26 18:44:13| storeAppend: appending 12 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 12
2009/08/26 18:44:13| storeAppend: appending 2 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 2
2009/08/26 18:44:13| storeAppend: appending 9 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 9
2009/08/26 18:44:13| storeAppend: appending 2 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 2
2009/08/26 18:44:13| storeAppend: appending 14 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 14
2009/08/26 18:44:13| storeAppend: appending 2 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 2
2009/08/26 18:44:13| storeAppend: appending 4 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 4
2009/08/26 18:44:13| storeAppend: appending 2 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 2
2009/08/26 18:44:13| storeAppend: appending 7 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 7
2009/08/26 18:44:13| storeAppend: appending 2 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 2
2009/08/26 18:44:13| storeAppend: appending 29 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 29
2009/08/26 18:44:13| storeAppend: appending 2 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 2
2009/08/26 18:44:13| storeAppend: appending 13 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 13
2009/08/26 18:44:13| storeAppend: appending 2 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 2
2009/08/26 18:44:13| storeAppend: appending 25 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 25
2009/08/26 18:44:13| storeAppend: appending 2 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 2
2009/08/26 18:44:13| storeAppend: appending 18 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 18
2009/08/26 18:44:13| storeAppend: appending 2 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 2
2009/08/26 18:44:13| storeAppend: appending 44 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 44
2009/08/26 18:44:13| storeAppend: appending 2 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 2
2009/08/26 18:44:13| storeAppend: appending 2 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 2
2009/08/26 18:44:13| storeAppend: appending 1321 bytes for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| stmemAppend: len 1321
2009/08/26 18:44:13| storeExpireNow: 'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| InvokeHandlers: A83EE53AFB79EF45119733090C8AE2DF
2009/08/26 18:44:13| InvokeHandlers: checking client #0
2009/08/26 18:44:13| cbdataLock: 0x892b698
2009/08/26 18:44:13| storeClientCopy2: A83EE53AFB79EF45119733090C8AE2DF
2009/08/26 18:44:13| storeClientCopy3: Copying from memory
2009/08/26 18:44:13| stmemCopy: offset 0: size 4096
2009/08/26 18:44:13| storeSwapOutMaintainMemObject: lowest_offset = 0
2009/08/26 18:44:13| cbdataValid: 0x892ace8
2009/08/26 18:44:13| clientSendHeaders: FD 18 'http://www.openbsd.org/'
2009/08/26 18:44:13| creating rep: 0x892b5d8
2009/08/26 18:44:13| init-ing hdr: 0x892b618 owner: 3
2009/08/26 18:44:13| 0x892b618 lookup for 41
2009/08/26 18:44:13| 0x892b618 lookup for 9
2009/08/26 18:44:13| 0x892b618 lookup for 41
2009/08/26 18:44:13| 0x892b618 lookup for 9
2009/08/26 18:44:13| 0x892b618 lookup for 25
2009/08/26 18:44:13| appending hdr: 0x892b618 += 0x892c788
2009/08/26 18:44:13| created entry 0x892b230: 'Server: squid/2.7.STABLE3'
2009/08/26 18:44:13| 0x892b618 adding entry: 47 at 0
2009/08/26 18:44:13| created entry 0x892b1e8: 'Date: Wed, 26 Aug 2009
16:44:13 GMT'
2009/08/26 18:44:13| 0x892b618 adding entry: 23 at 1
2009/08/26 18:44:13| created entry 0x892b140: 'Content-Type: text/html'
2009/08/26 18:44:13| 0x892b618 adding entry: 18 at 2
2009/08/26 18:44:13| created entry 0x892b120: 'Content-Length: 1321'
2009/08/26 18:44:13| 0x892b618 adding entry: 14 at 3
2009/08/26 18:44:13| created entry 0x892b090: 'Expires: Wed, 26 Aug 2009
16:44:13 GMT'
2009/08/26 18:44:13| 0x892b618 adding entry: 25 at 4
2009/08/26 18:44:13| created entry 0x892e288: 'X-Squid-Error:
ERR_CACHE_ACCESS_DENIED 0'
2009/08/26 18:44:13| 0x892b618 adding entry: 61 at 5
2009/08/26 18:44:13| created entry 0x892e240: 'Proxy-Authenticate: Basic
realm="Squid proxy-caching web server"'
2009/08/26 18:44:13| 0x892b618 adding entry: 38 at 6
2009/08/26 18:44:13| 0x892b618 lookup for 41
2009/08/26 18:44:13| 0x892b618 lookup for 9
2009/08/26 18:44:13| 0x892b618 lookup for 41
2009/08/26 18:44:13| 0x892b618 lookup for 9
2009/08/26 18:44:13| 0x892b618 lookup for 25
2009/08/26 18:44:13| 0x892b618 del-by-id 41
2009/08/26 18:44:13| 0x892b618 del-by-id 68
2009/08/26 18:44:13| 0x892b618 del-by-id 21
2009/08/26 18:44:13| 0x892b618 del-by-id 20
2009/08/26 18:44:13| 0x892b618 del-by-id 49
2009/08/26 18:44:13| 0x892b618 lookup for 9
2009/08/26 18:44:13| created entry 0x892e1f8: 'X-Cache: MISS from
squid-ads.localdomain'
2009/08/26 18:44:13| 0x892b618 adding entry: 57 at 7
2009/08/26 18:44:13| created entry 0x892e1b0: 'X-Cache-Lookup: NONE from
squid-ads.localdomain:3128'
2009/08/26 18:44:13| 0x892b618 adding entry: 58 at 8
2009/08/26 18:44:13| clientBuildReplyHeader: Error, don't keep-alive
2009/08/26 18:44:13| 0x892b618: joining for id 52
2009/08/26 18:44:13| 0x892b618 del-by-id 52
2009/08/26 18:44:13| created entry 0x892d858: 'Via: 1.0
squid-ads.localdomain:3128 (squid/2.7.STABLE3)'
2009/08/26 18:44:13| 0x892b618 adding entry: 52 at 9
2009/08/26 18:44:13| created entry 0x892d838: 'Connection: close'
2009/08/26 18:44:13| 0x892b618 adding entry: 9 at 10
2009/08/26 18:44:13| clientSendHeaders: 305 bytes of headers
2009/08/26 18:44:13| The reply for GET http://www.openbsd.org/ is ALLOWED,
because it matched 'MyAcl'
2009/08/26 18:44:13| packing sline 0x892b608 using 0xbf84d980:
2009/08/26 18:44:13| HTTP/1.0 407 Proxy Authentication Required

2009/08/26 18:44:13| packing hdr: (0x892b618)
2009/08/26 18:44:13| comm_write: FD 18: sz 477: hndl 0x806d4b0: data
0x892ace8.
2009/08/26 18:44:13| cbdataLock: 0x892ace8
2009/08/26 18:44:13| commSetSelect: FD 18 type 2
2009/08/26 18:44:13| commSetEvents(fd=18)
2009/08/26 18:44:13| cbdataUnlock: 0x892ace8
2009/08/26 18:44:13| cbdataUnlock: 0x892b698
2009/08/26 18:44:13| storeSwapOut: http://www.openbsd.org/
2009/08/26 18:44:13| storeSwapOut: store_status = STORE_PENDING
2009/08/26 18:44:13| storeSwapOut: mem->inmem_lo = 0
2009/08/26 18:44:13| storeSwapOut: mem->inmem_hi = 1626
2009/08/26 18:44:13| storeSwapOut: swapout.queue_offset = 0
2009/08/26 18:44:13| storeSwapOutMaintainMemObject: lowest_offset = 0
2009/08/26 18:44:13| storeComplete: 'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| storeEntryValidLength: Checking
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| storeEntryValidLength: object_len = 1626
2009/08/26 18:44:13| storeEntryValidLength: hdr_sz = 305
2009/08/26 18:44:13| storeEntryValidLength: content_length = 1321
2009/08/26 18:44:13| storeSwapOut: http://www.openbsd.org/
2009/08/26 18:44:13| storeSwapOut: store_status = STORE_OK
2009/08/26 18:44:13| storeSwapOut: mem->inmem_lo = 0
2009/08/26 18:44:13| storeSwapOut: mem->inmem_hi = 1626
2009/08/26 18:44:13| storeSwapOut: swapout.queue_offset = 0
2009/08/26 18:44:13| storeSwapOutMaintainMemObject: lowest_offset = 0
2009/08/26 18:44:13| InvokeHandlers: A83EE53AFB79EF45119733090C8AE2DF
2009/08/26 18:44:13| InvokeHandlers: checking client #0
2009/08/26 18:44:13| storeUnlockObject: (errorpage.c:331): key
'A83EE53AFB79EF45119733090C8AE2DF' count=2
2009/08/26 18:44:13| cbdataFree: 0x892c6f8
2009/08/26 18:44:13| cbdataFree: Freeing 0x892c6f8
2009/08/26 18:44:13| cbdataUnlock: 0x892ace8
2009/08/26 18:44:13| cbdataUnlock: 0x892aaa8
2009/08/26 18:44:13| cbdataFree: 0x892b3e8
2009/08/26 18:44:13| cbdataFree: Freeing 0x892b3e8
2009/08/26 18:44:13| cbdataValid: 0x892aaa8
2009/08/26 18:44:13| cbdataValid: 0x892aaa8
2009/08/26 18:44:13| cbdataValid: 0x892aaa8
2009/08/26 18:44:13| cbdataUnlock: 0x892aaa8
2009/08/26 18:44:13| commSetSelect: FD 18 type 1
2009/08/26 18:44:13| commSetEvents(fd=18)
2009/08/26 18:44:13| comm_select: timeout 483
2009/08/26 18:44:13| comm_call_handlers(): got fd=18 read_event=0
write_event=4 F->read_handler=0x806acf0 F->write_handler=0x8072fb0
2009/08/26 18:44:13| commHandleWrite: FD 18: off 0, hd 0, sz 477.
2009/08/26 18:44:13| commHandleWrite: write() returns 477
2009/08/26 18:44:13| cbdataValid: 0x892ace8
2009/08/26 18:44:13| clientWriteComplete: FD 18, sz 477, err 0, off 305, len
1626
2009/08/26 18:44:13| storeClientCopy: A83EE53AFB79EF45119733090C8AE2DF, seen
305, want 305, size 4096, cb 0x806d8c0, cbdata 0x892ace8
2009/08/26 18:44:13| cbdataLock: 0x892ace8
2009/08/26 18:44:13| cbdataLock: 0x892b698
2009/08/26 18:44:13| storeClientCopy2: A83EE53AFB79EF45119733090C8AE2DF
2009/08/26 18:44:13| storeClientCopy3: Copying from memory
2009/08/26 18:44:13| stmemCopy: offset 305: size 4096
2009/08/26 18:44:13| storeSwapOutMaintainMemObject: lowest_offset = 305
2009/08/26 18:44:13| cbdataValid: 0x892ace8
2009/08/26 18:44:13| clientSendMoreData: http://www.openbsd.org/, 1321 bytes
2009/08/26 18:44:13| clientSendMoreData: FD 18 'http://www.openbsd.org/',
out.offset=305
2009/08/26 18:44:13| comm_write: FD 18: sz 1321: hndl 0x806dcd0: data
0x892ace8.
2009/08/26 18:44:13| cbdataLock: 0x892ace8
2009/08/26 18:44:13| commSetSelect: FD 18 type 2
2009/08/26 18:44:13| commSetEvents(fd=18)
2009/08/26 18:44:13| cbdataUnlock: 0x892ace8
2009/08/26 18:44:13| cbdataUnlock: 0x892b698
2009/08/26 18:44:13| cbdataUnlock: 0x892ace8
2009/08/26 18:44:13| commSetEvents(fd=18)
2009/08/26 18:44:13| comm_select: timeout 483
2009/08/26 18:44:13| comm_call_handlers(): got fd=18 read_event=0
write_event=4 F->read_handler=0x806acf0 F->write_handler=0x8072fb0
2009/08/26 18:44:13| commHandleWrite: FD 18: off 0, hd 0, sz 1321.
2009/08/26 18:44:13| commHandleWrite: write() returns 1321
2009/08/26 18:44:13| cbdataValid: 0x892ace8
2009/08/26 18:44:13| clientWriteComplete: FD 18, sz 1321, err 0, off 1626,
len 1626
2009/08/26 18:44:13| clientWriteComplete: FD 18 transfer is DONE
2009/08/26 18:44:13| comm_close: FD 18
2009/08/26 18:44:13| commCallCloseHandlers: FD 18
2009/08/26 18:44:13| commCallCloseHandlers: ch->handler=0x806dd30
2009/08/26 18:44:13| cbdataValid: 0x892aaa8
2009/08/26 18:44:13| connStateFree: FD 18
2009/08/26 18:44:13| httpRequestFree: http://www.openbsd.org/
2009/08/26 18:44:13| httpRequestFree: al.url='http://www.openbsd.org/'
2009/08/26 18:44:13| cbdataLock: 0x872b978
2009/08/26 18:44:13| cbdataLock: 0x892aaa8
2009/08/26 18:44:13| cbdataUnlock: 0x892aaa8
2009/08/26 18:44:13| cbdataUnlock: 0x872b978
2009/08/26 18:44:13| cbdataFree: 0x892b3e8
2009/08/26 18:44:13| cbdataFree: Freeing 0x892b3e8
2009/08/26 18:44:13| storeClientUnregister: called for
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| storeSwapOut: http://www.openbsd.org/
2009/08/26 18:44:13| storeSwapOut: store_status = STORE_OK
2009/08/26 18:44:13| storeSwapOut: mem->inmem_lo = 0
2009/08/26 18:44:13| storeSwapOut: mem->inmem_hi = 1626
2009/08/26 18:44:13| storeSwapOut: swapout.queue_offset = 0
2009/08/26 18:44:13| storeSwapOutMaintainMemObject: lowest_offset = 1627
2009/08/26 18:44:13| storeSwapOutMaintainMemObject: lowest_offset = 1627
2009/08/26 18:44:13| storePendingNClients: returning 0
2009/08/26 18:44:13| storeUnlockObject: (store_client.c:576): key
'A83EE53AFB79EF45119733090C8AE2DF' count=1
2009/08/26 18:44:13| cbdataFree: 0x892b698
2009/08/26 18:44:13| cbdataFree: Freeing 0x892b698
2009/08/26 18:44:13| storeUnlockObject: (client_side.c:1262): key
'A83EE53AFB79EF45119733090C8AE2DF' count=0
2009/08/26 18:44:13| storePendingNClients: returning 0
2009/08/26 18:44:13| storeRelease: Releasing:
'A83EE53AFB79EF45119733090C8AE2DF'
2009/08/26 18:44:13| destroy_StoreEntry: destroying 0x892b500
2009/08/26 18:44:13| ctx: enter level 0: 'http://www.openbsd.org/'
2009/08/26 18:44:13| destroy_MemObject: destroying 0x892b538
2009/08/26 18:44:13| destroying rep: 0x892c748
2009/08/26 18:44:13| cleaning hdr: 0x892c788 owner: 3
2009/08/26 18:44:13| destroying entry 0x892f4f0: 'Server: squid/2.7.STABLE3'
2009/08/26 18:44:13| destroying entry 0x892f4a8: 'Date: Wed, 26 Aug 2009
16:44:13 GMT'
2009/08/26 18:44:13| destroying entry 0x892f460: 'Content-Type: text/html'
2009/08/26 18:44:13| destroying entry 0x892f3d0: 'Content-Length: 1321'
2009/08/26 18:44:13| destroying entry 0x892b368: 'Expires: Wed, 26 Aug 2009
16:44:13 GMT'
2009/08/26 18:44:13| destroying entry 0x892b320: 'X-Squid-Error:
ERR_CACHE_ACCESS_DENIED 0'
2009/08/26 18:44:13| destroying entry 0x892b278: 'Proxy-Authenticate: Basic
realm="Squid proxy-caching web server"'
2009/08/26 18:44:13| ctx: exit level 0
2009/08/26 18:44:13| cleaning hdr: 0x8907f6c owner: 2
2009/08/26 18:44:13| destroying entry 0x892f8b8: 'Host: www.openbsd.org'
2009/08/26 18:44:13| destroying entry 0x892f810: 'User-Agent: Mozilla/5.0
(Macintosh; U; Intel Mac OS X 10_5_8; de-de) AppleWebKit/531.9 (KHTML, like
Gecko) Version/4.0.3 Safari/531.9'
2009/08/26 18:44:13| destroying entry 0x892f6e0: 'Accept:
application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image
/png,*/*;q=0.5'
2009/08/26 18:44:13| destroying entry 0x892f698: 'Accept-Language: de-de'
2009/08/26 18:44:13| destroying entry 0x892f5c8: 'Accept-Encoding: gzip,
deflate'
2009/08/26 18:44:13| destroying entry 0x892f580: 'Connection: keep-alive'
2009/08/26 18:44:13| destroying entry 0x892f538: 'Proxy-Connection:
keep-alive'
2009/08/26 18:44:13| destroying rep: 0x892b5d8
2009/08/26 18:44:13| cleaning hdr: 0x892b618 owner: 3
2009/08/26 18:44:13| destroying entry 0x892b230: 'Server: squid/2.7.STABLE3'
2009/08/26 18:44:13| destroying entry 0x892b1e8: 'Date: Wed, 26 Aug 2009
16:44:13 GMT'
2009/08/26 18:44:13| destroying entry 0x892b140: 'Content-Type: text/html'
2009/08/26 18:44:13| destroying entry 0x892b120: 'Content-Length: 1321'
2009/08/26 18:44:13| destroying entry 0x892b090: 'Expires: Wed, 26 Aug 2009
16:44:13 GMT'
2009/08/26 18:44:13| destroying entry 0x892e288: 'X-Squid-Error:
ERR_CACHE_ACCESS_DENIED 0'
2009/08/26 18:44:13| destroying entry 0x892e240: 'Proxy-Authenticate: Basic
realm="Squid proxy-caching web server"'
2009/08/26 18:44:13| destroying entry 0x892e1f8: 'X-Cache: MISS from
squid-ads.localdomain'
2009/08/26 18:44:13| destroying entry 0x892e1b0: 'X-Cache-Lookup: NONE from
squid-ads.localdomain:3128'
2009/08/26 18:44:13| destroying entry 0x892d858: 'Via: 1.0
squid-ads.localdomain:3128 (squid/2.7.STABLE3)'
2009/08/26 18:44:13| destroying entry 0x892d838: 'Connection: close'
2009/08/26 18:44:13| cbdataFree: 0x892ace8
2009/08/26 18:44:13| cbdataFree: 0x892ace8 has 1 locks, not freeing
2009/08/26 18:44:13| cbdataFree: 0x892aaa8
2009/08/26 18:44:13| cbdataFree: 0x892aaa8 has 1 locks, not freeing
2009/08/26 18:44:13| cbdataUnlock: 0x892aaa8
2009/08/26 18:44:13| cbdataUnlock: Freeing 0x892aaa8
2009/08/26 18:44:13| fd_close FD 18 Reading next request
2009/08/26 18:44:13| commSetEvents(fd=18)
2009/08/26 18:44:13| cbdataUnlock: 0x892ace8
2009/08/26 18:44:13| cbdataUnlock: Freeing 0x892ace8
2009/08/26 18:44:13| comm_select: timeout 482
2009/08/26 18:44:14| comm_select: time out
2009/08/26 18:44:14| comm_select: timeout 41
2009/08/26 18:44:14| comm_select: time out
2009/08/26 18:44:14| eventRun: RUN ID 35
2009/08/26 18:44:14| eventRun: Running 'MaintainSwapSpace', id 34
2009/08/26 18:44:14| storeMaintainSwapSpace: f=0.000000, max_scan=100,
max_remove=10
2009/08/26 18:44:14| cbdataFree: 0x892aa30
2009/08/26 18:44:14| cbdataFree: Freeing 0x892aa30
2009/08/26 18:44:14| storeUfsDirMaintain: /var/spool/squid removed 0/10
f=0.000 max_scan=100
2009/08/26 18:44:14| eventAdd: Adding 'MaintainSwapSpace', in 1.000000
seconds
2009/08/26 18:44:14| comm_select: timeout 1000
2009/08/26 18:44:15| comm_select: time out
2009/08/26 18:44:15| comm_select: timeout 45
2009/08/26 18:44:15| comm_select: time out
2009/08/26 18:44:15| eventRun: RUN ID 36
2009/08/26 18:44:15| eventRun: Running 'MaintainSwapSpace', id 35
2009/08/26 18:44:15| storeMaintainSwapSpace: f=0.000000, max_scan=100,
max_remove=10
2009/08/26 18:44:15| cbdataFree: 0x892aa30
2009/08/26 18:44:15| cbdataFree: Freeing 0x892aa30
2009/08/26 18:44:15| storeUfsDirMaintain: /var/spool/squid removed 0/10
f=0.000 max_scan=100
2009/08/26 18:44:15| eventAdd: Adding 'MaintainSwapSpace', in 1.000000
seconds
2009/08/26 18:44:15| comm_select: timeout 1000
2009/08/26 18:44:16| comm_select: time out
2009/08/26 18:44:16| comm_select: timeout 48
2009/08/26 18:44:16| comm_select: time out
2009/08/26 18:44:16| eventRun: RUN ID 37
2009/08/26 18:44:16| eventRun: Running 'MaintainSwapSpace', id 36
2009/08/26 18:44:16| storeMaintainSwapSpace: f=0.000000, max_scan=100,
max_remove=10
2009/08/26 18:44:16| cbdataFree: 0x892aa30
2009/08/26 18:44:16| cbdataFree: Freeing 0x892aa30
2009/08/26 18:44:16| storeUfsDirMaintain: /var/spool/squid removed 0/10
f=0.000 max_scan=100
2009/08/26 18:44:16| eventAdd: Adding 'MaintainSwapSpace', in 1.000000
seconds
2009/08/26 18:44:16| comm_select: timeout 952
2009/08/26 18:44:16| comm_call_handlers(): got fd=19 read_event=1
write_event=0 F->read_handler=0x80666d0 F->write_handler=(nil)
2009/08/26 18:44:16| comm_call_handlers(): Calling read handler on fd=19
2009/08/26 18:44:16| commSetSelect: FD 19 type 1
2009/08/26 18:44:16| commSetEvents(fd=19)
2009/08/26 18:44:16| fd_open FD 18 HTTP Request
2009/08/26 18:44:16| httpAccept: FD 18: accepted port 3128 client
192.168.32.1:53075
2009/08/26 18:44:16| cbdataLock: 0x872d248
2009/08/26 18:44:16| comm_add_close_handler: FD 18, handler=0x806dd30,
data=0x892aaa8
2009/08/26 18:44:16| cbdataLock: 0x892aaa8
2009/08/26 18:44:16| commSetTimeout: FD 18 timeout 300
2009/08/26 18:44:16| aclCheckFast: list: 0x872b7f0
2009/08/26 18:44:16| aclMatchAclList: checking all
2009/08/26 18:44:16| aclMatchAcl: checking 'acl all src all'
2009/08/26 18:44:16| aclMatchIp: '192.168.32.1' found
2009/08/26 18:44:16| aclMatchAclList: returning 1
2009/08/26 18:44:16| commSetSelect: FD 18 type 1
2009/08/26 18:44:16| commSetEvents(fd=18)
2009/08/26 18:44:16| comm_accept: FD 19: (11) Resource temporarily
unavailable
2009/08/26 18:44:17| comm_select: timeout 184
2009/08/26 18:44:17| comm_call_handlers(): got fd=18 read_event=1
write_event=0 F->read_handler=0x806acf0 F->write_handler=(nil)
2009/08/26 18:44:17| comm_call_handlers(): Calling read handler on fd=18
2009/08/26 18:44:17| clientReadRequest: FD 18: reading request...
2009/08/26 18:44:17| cbdataLock: 0x892aaa8
2009/08/26 18:44:17| cbdataValid: 0x892aaa8
2009/08/26 18:44:17| Parser: retval 1: from 0->37: method 0->2; url 4->26;
version 28->36 (1/1)
2009/08/26 18:44:17| parseHttpRequest: Method is 'GET'
2009/08/26 18:44:17| parseHttpRequest: URI is 'http://www.openbsd.org/'
2009/08/26 18:44:17| parseHttpRequest: req_hdr = {Host: www.openbsd.org

User-Agent: Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10_5_8; de-de)
AppleWebKit/531.9 (KHTML, like Gecko) Version/4.0.3 Safari/531.9

Accept:
application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image
/png,*/*;q=0.5

Accept-Language: de-de

Accept-Encoding: gzip, deflate

Proxy-Authorization: Basic Zm9vOmJhcg==

Connection: keep-alive

Proxy-Connection: keep-alive

}
2009/08/26 18:44:17| parseHttpRequest: prefix_sz = 449, req_line_sz = 38
2009/08/26 18:44:17| parseHttpRequest: Request Header is

Host: www.openbsd.org

User-Agent: Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10_5_8; de-de)
AppleWebKit/531.9 (KHTML, like Gecko) Version/4.0.3 Safari/531.9

Accept:
application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image
/png,*/*;q=0.5

Accept-Language: de-de

Accept-Encoding: gzip, deflate

Proxy-Authorization: Basic Zm9vOmJhcg==

Connection: keep-alive

Proxy-Connection: keep-alive

2009/08/26 18:44:17| parseHttpRequest: Complete request received
2009/08/26 18:44:17| commSetTimeout: FD 18 timeout 86400
2009/08/26 18:44:17| init-ing hdr: 0x8907f6c owner: 2
2009/08/26 18:44:17| parsing hdr: (0x8907f6c)
Host: www.openbsd.org

User-Agent: Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10_5_8; de-de)
AppleWebKit/531.9 (KHTML, like Gecko) Version/4.0.3 Safari/531.9

Accept:
application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image
/png,*/*;q=0.5

Accept-Language: de-de

Accept-Encoding: gzip, deflate

Proxy-Authorization: Basic Zm9vOmJhcg==

Connection: keep-alive

Proxy-Connection: keep-alive

2009/08/26 18:44:17| creating entry 0x892d838: near 'Host: www.openbsd.org'
2009/08/26 18:44:17| created entry 0x892d838: 'Host: www.openbsd.org'
2009/08/26 18:44:17| 0x8907f6c adding entry: 27 at 0
2009/08/26 18:44:17| creating entry 0x892d858: near 'User-Agent: Mozilla/5.0
(Macintosh; U; Intel Mac OS X 10_5_8; de-de) AppleWebKit/531.9 (KHTML, like
Gecko) Version/4.0.3 Safari/531.9'
2009/08/26 18:44:17| created entry 0x892d858: 'User-Agent: Mozilla/5.0
(Macintosh; U; Intel Mac OS X 10_5_8; de-de) AppleWebKit/531.9 (KHTML, like
Gecko) Version/4.0.3 Safari/531.9'
2009/08/26 18:44:17| 0x8907f6c adding entry: 50 at 1
2009/08/26 18:44:17| creating entry 0x892e1b0: near 'Accept:
application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image
/png,*/*;q=0.5'
2009/08/26 18:44:17| created entry 0x892e1b0: 'Accept:
application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image
/png,*/*;q=0.5'
2009/08/26 18:44:17| 0x8907f6c adding entry: 0 at 2
2009/08/26 18:44:17| creating entry 0x892e1f8: near 'Accept-Language: de-de'
2009/08/26 18:44:17| created entry 0x892e1f8: 'Accept-Language: de-de'
2009/08/26 18:44:17| 0x8907f6c adding entry: 3 at 3
2009/08/26 18:44:17| creating entry 0x892e240: near 'Accept-Encoding: gzip,
deflate'
2009/08/26 18:44:17| created entry 0x892e240: 'Accept-Encoding: gzip,
deflate'
2009/08/26 18:44:17| 0x8907f6c adding entry: 2 at 4
2009/08/26 18:44:17| creating entry 0x892e288: near 'Proxy-Authorization:
Basic Zm9vOmJhcg=='
2009/08/26 18:44:17| created entry 0x892e288: 'Proxy-Authorization: Basic
Zm9vOmJhcg=='
2009/08/26 18:44:17| 0x8907f6c adding entry: 40 at 5
2009/08/26 18:44:17| creating entry 0x892b090: near 'Connection: keep-alive'
2009/08/26 18:44:17| created entry 0x892b090: 'Connection: keep-alive'
2009/08/26 18:44:17| 0x8907f6c adding entry: 9 at 6
2009/08/26 18:44:17| creating entry 0x892b120: near 'Proxy-Connection:
keep-alive'
2009/08/26 18:44:17| created entry 0x892b120: 'Proxy-Connection: keep-alive'
2009/08/26 18:44:17| 0x8907f6c adding entry: 41 at 7
2009/08/26 18:44:17| removing 449 bytes; conn->in.offset = 0
2009/08/26 18:44:17| 0x8907f6c lookup for 20
2009/08/26 18:44:17| clientSetKeepaliveFlag: http_ver = 1.1
2009/08/26 18:44:17| clientSetKeepaliveFlag: method = GET
2009/08/26 18:44:17| 0x8907f6c lookup for 41
2009/08/26 18:44:17| 0x8907f6c: joining for id 41
2009/08/26 18:44:17| 0x8907f6c: joined for id 41: keep-alive
2009/08/26 18:44:17| 0x8907f6c lookup for 52
2009/08/26 18:44:17| 0x8907f6c lookup for 41
2009/08/26 18:44:17| 0x8907f6c: joining for id 41
2009/08/26 18:44:17| 0x8907f6c: joined for id 41: keep-alive
2009/08/26 18:44:17| 0x8907f6c lookup for 59
2009/08/26 18:44:17| cbdataLock: 0x872b978
2009/08/26 18:44:17| cbdataLock: 0x892aaa8
2009/08/26 18:44:17| cbdataLock: 0x892ace8
2009/08/26 18:44:17| cbdataValid: 0x872b978
2009/08/26 18:44:17| aclCheck: checking 'http_access allow MyAcl'
2009/08/26 18:44:17| aclMatchAclList: checking MyAcl
2009/08/26 18:44:17| aclMatchAcl: checking 'acl MyAcl external myAclType'
2009/08/26 18:44:17| aclMatchExternal: acl="myAclType"
2009/08/26 18:44:17| authenticateAuthenticate: header Basic Zm9vOmJhcg==.
2009/08/26 18:44:17| authenticateAuthenticate: This is a new checklist test
on FD:18
2009/08/26 18:44:17| authenticateAuthenticate: no connection authentication
type
2009/08/26 18:44:17| authenticateAuthUserRequestLock auth_user request
'0x892fdb0'.
2009/08/26 18:44:17| authenticateAuthUserRequestLock auth_user request
'0x892fdb0' now at '1'.
2009/08/26 18:44:17| authenticateDecodeAuth: header = 'Basic Zm9vOmJhcg=='
2009/08/26 18:44:17| authenticateBasicDecodeAuth: cleartext = 'foo:bar'
2009/08/26 18:44:17| authBasicAuthUserFindUsername: Looking for user 'foo'
2009/08/26 18:44:17| authBasicDecodeAuth: Creating new user 'foo'
2009/08/26 18:44:17| authenticateAuthUserLock auth_user '0x892fde0'.
2009/08/26 18:44:17| authenticateAuthUserLock auth_user '0x892fde0' now at
'1'.
2009/08/26 18:44:17| authenticateAuthUserLock auth_user '0x892fde0'.
2009/08/26 18:44:17| authenticateAuthUserLock auth_user '0x892fde0' now at
'2'.
2009/08/26 18:44:17| authenticateValidateUser: Validating Auth_user request
'0x892fdb0'.
2009/08/26 18:44:17| authenticateValidateUser: Validated Auth_user request
'0x892fdb0'.
2009/08/26 18:44:17| authenticateValidateUser: Validating Auth_user request
'0x892fdb0'.
2009/08/26 18:44:17| authenticateValidateUser: Validated Auth_user request
'0x892fdb0'.
2009/08/26 18:44:17| User not authenticated or credentials need rechecking.
2009/08/26 18:44:17| authenticateValidateUser: Validating Auth_user request
'0x892fdb0'.
2009/08/26 18:44:17| authenticateValidateUser: Validated Auth_user request
'0x892fdb0'.
2009/08/26 18:44:17| User not authenticated or credentials need rechecking.
2009/08/26 18:44:17| aclAuthenticated: returning 0 sending credentials to
helper.
2009/08/26 18:44:17| aclMatchExternal: myAclType user not authenticated (-1)
2009/08/26 18:44:17| aclMatchAclList: no match, returning 0
2009/08/26 18:44:17| aclCheck: checking password via authenticator
2009/08/26 18:44:17| authenticateValidateUser: Validating Auth_user request
'0x892fdb0'.
2009/08/26 18:44:17| authenticateValidateUser: Validated Auth_user request
'0x892fdb0'.
2009/08/26 18:44:17| authenticateStart: auth_user_request '0x892fdb0'
2009/08/26 18:44:17| authenticateStart: 'foo:bar'
2009/08/26 18:44:17| cbdataLock: 0x892b3e8
2009/08/26 18:44:17| authenticateAuthUserRequestLock auth_user request
'0x892fdb0'.
2009/08/26 18:44:17| authenticateAuthUserRequestLock auth_user request
'0x892fdb0' now at '2'.
2009/08/26 18:44:17| cbdataLock: 0x892feb0
2009/08/26 18:44:17| cbdataValid: 0x892feb0
2009/08/26 18:44:17| comm_write: FD 7: sz 8: hndl 0x808e530: data 0x87362c8.
2009/08/26 18:44:17| cbdataLock: 0x87362c8
2009/08/26 18:44:17| commSetSelect: FD 7 type 2
2009/08/26 18:44:17| commSetEvents(fd=7)
2009/08/26 18:44:17| helperDispatch: Request sent to basicauthenticator
#1[0], 8 bytes
2009/08/26 18:44:17| helperSubmit: foo bar
----->8-----

Best regards

Maik Kündig
Received on Thu Aug 27 2009 - 08:10:51 MDT