Re: [squid-users] Squid, radius, invalid user auth problem

On Mon, Apr 10, 2006 at 10:49:07PM +0200, Henrik Nordstrom wrote:
> fre 2006-04-07 klockan 22:08 -0400 skrev Michael W. Lucas:
> > On Fri, Apr 07, 2006 at 11:49:48PM +0200, Henrik Nordstrom wrote:
> > > fre 2006-04-07 klockan 14:49 -0400 skrev Michael W. Lucas:
> > >
> > > > 2006/04/07 14:10:34| helperSubmit: blahuser_t 888888
> > > > 2006/04/07 14:10:34| aclMatchUser: user is blahuser_t, case_insensitive is 0
> > > > 2006/04/07 14:10:34| helperSubmit: http://slashdot.org/ 10.184.184.193/- blahuser_t GET
> > >
> > > The interesting part is what is going on between the first two lines
> > > above.. Squid queried the auth helper, but what response did it get?
> >
> > Unfortunately, that's all that's in the log. I'm on squid_radius_auth
> > 1.07, and couldn't find any logging options for it.
>
>
> Are you absolutely sure there is no other lines between those two? I
> thought this was only a grep of blahuser_t in cache.log, not a complete
> cache.log..

Yes, of course! I'm a doofus, my apologies.

2006/04/07 14:10:34| helperSubmit: blahuser_t 888888
2006/04/07 14:10:34| comm_poll: 2+0 FDs ready
2006/04/07 14:10:34| comm_poll: FD 69 ready for writing
2006/04/07 14:10:34| commHandleWrite: FD 69: off 0, sz 18.
2006/04/07 14:10:34| commHandleWrite: write() returns 18
2006/04/07 14:10:34| comm_poll: FD 295 ready for writing
2006/04/07 14:10:34| commHandleWrite: FD 295: off 0, sz 1380.
2006/04/07 14:10:34| commHandleWrite: write() returns 1380
2006/04/07 14:10:34| cbdataValid: 0xa551f30
2006/04/07 14:10:34| clientWriteComplete: FD 295, sz 1380, err 0, off 15180, len -1
2006/04/07 14:10:34| storeClientCopy: D0FC7FF3CE96707A9741E185ADA23C0C, seen 15180, want 15180, size 4096, cb 0x6c234d, cbdata 0xa551f30
2006/04/07 14:10:34| cbdataLock: 0xa5c0d08
2006/04/07 14:10:34| storeClientCopy2: D0FC7FF3CE96707A9741E185ADA23C0C
2006/04/07 14:10:34| storeClientCopy3: Copying from memory
2006/04/07 14:10:34| memCopy: offset 15180: size 4096
2006/04/07 14:10:34| cbdataValid: 0xa551f30
2006/04/07 14:10:34| clientSendMoreData: http://tarheelblue.cstv.com/sports/m-footbl/spec-rel/032206aac.html, 4096 bytes
2006/04/07 14:10:34| clientSendMoreData: FD 295 'http://tarheelblue.cstv.com/sports/m-footbl/spec-rel/032206aac.html', out.offset=15180
2006/04/07 14:10:34| comm_write: FD 295: sz 4096: hndl 0x6c2c10: data 0xa551f30.
2006/04/07 14:10:34| cbdataLock: 0xa551f30
2006/04/07 14:10:34| commSetSelect: FD 295 type 2
2006/04/07 14:10:34| cbdataUnlock: 0xa5c0d08
2006/04/07 14:10:34| cbdataUnlock: 0xa551f30
2006/04/07 14:10:34| comm_poll: 2+0 FDs ready
2006/04/07 14:10:34| comm_poll: FD 69 ready for reading
2006/04/07 14:10:34| cbdataValid: 0x9de9010
2006/04/07 14:10:34| helperHandleRead: 3 bytes from basicauthenticator #1.
2006/04/07 14:10:34| helperHandleRead: end of reply found
2006/04/07 14:10:34| cbdataValid: 0xa03e8c8
2006/04/07 14:10:34| authenticateBasicHandleReply: {OK}
2006/04/07 14:10:34| cbdataValid: 0xa34b178
2006/04/07 14:10:34| authenticateValidateUser: Validating Auth_user request '0xa5879a0'.
2006/04/07 14:10:34| authenticateValidateUser: Validated Auth_user request '0xa5879a0'.
2006/04/07 14:10:34| cbdataValid: 0x9d6c538
2006/04/07 14:10:34| aclCheck: checking 'http_access allow our_networks radius_auth '
2006/04/07 14:10:34| aclMatchAclList: checking our_networks
2006/04/07 14:10:34| aclMatchAcl: checking 'acl our_networks src 10.0.0.0/8 192.168.0.0/16 127.0.0.0/8'
2006/04/07 14:10:34| aclMatchIp: '10.184.184.193' found
2006/04/07 14:10:34| aclMatchAclList: checking radius_auth
2006/04/07 14:10:34| aclMatchAcl: checking 'acl radius_auth proxy_auth REQUIRED # Use the radius proxy auth'
2006/04/07 14:10:34| authenticateAuthenticate: header Basic YmxhaHVzZXJfdDo4ODg4ODg=.
2006/04/07 14:10:34| authenticateValidateUser: Validating Auth_user request '0xa5879a0'.
2006/04/07 14:10:34| authenticateValidateUser: Validated Auth_user request '0xa5879a0'.
2006/04/07 14:10:34| authenticateAuthUserRequestLock auth_user request '0xa5879a0'.
2006/04/07 14:10:34| authenticateAuthUserRequestLock auth_user request '0xa5879a0' now at '2'.
2006/04/07 14:10:34| authenticateAuthUserRequestUnlock auth_user request '0xa5879a0'.
2006/04/07 14:10:34| authenticateAuthUserRequestUnlock auth_user_request '0xa5879a0' now at '1'.
2006/04/07 14:10:34| authenticateAuthUserRequestLock auth_user request '0xa5879a0'.
2006/04/07 14:10:34| authenticateAuthUserRequestLock auth_user request '0xa5879a0' now at '2'.
2006/04/07 14:10:34| authenticateValidateUser: Validating Auth_user request '0xa5879a0'.
2006/04/07 14:10:34| authenticateValidateUser: Validated Auth_user request '0xa5879a0'.
2006/04/07 14:10:34| authenticateAuthUserRequestUnlock auth_user request '0xa5879a0'.
2006/04/07 14:10:34| authenticateAuthUserRequestUnlock auth_user_request '0xa5879a0' now at '1'.
2006/04/07 14:10:34| aclMatchUser: user is blahuser_t, case_insensitive is 0
2006/04/07 14:10:34| Top is (nil), Top->data is Unavailable
2006/04/07 14:10:34| aclMatchUser: user REQUIRED and auth-info present.
2006/04/07 14:10:34| aclMatchAclList: returning 1
2006/04/07 14:10:34| aclCheck: match found, returning 1
2006/04/07 14:10:34| cbdataUnlock: 0x9d6c538
2006/04/07 14:10:34| aclCheckCallback: answer=1
2006/04/07 14:10:34| cbdataValid: 0xa03b820
2006/04/07 14:10:34| The request GET http://slashdot.org/ is ALLOWED, because it matched 'radius_auth'
2006/04/07 14:10:34| redirectStart: 'http://slashdot.org/'
2006/04/07 14:10:34| cbdataLock: 0xa03b820
2006/04/07 14:10:34| cbdataLock: 0xa031d48
2006/04/07 14:10:34| cbdataValid: 0xa031d48
2006/04/07 14:10:34| comm_write: FD 9: sz 53: hndl (nil): data (nil).
2006/04/07 14:10:34| commSetSelect: FD 9 type 2
2006/04/07 14:10:34| commSetSelect: FD 9 type 1
2006/04/07 14:10:34| helperDispatch: Request sent to redirector #1, 53 bytes
2006/04/07 14:10:34| helperSubmit: http://slashdot.org/ 10.184.184.193/- blahuser_t GET

-- 
Michael W. Lucas	mwlucas@FreeBSD.org, mwlucas@BlackHelicopters.org
		http://www.BlackHelicopters.org/~mwlucas/
"The cloak of anonymity protects me from the nuisance of caring." -Non Sequitur