squid 5.2: ntlm_fake_auth refuse to valid credentials

David Touzeau <david@xxxxxxxxxxxxxx> · Thu, 11 Nov 2021 02:12:04 +0100



    Hi, 

      i would like to use ntlm_fake_auth but it seems Squid refuse to
      switch to authenticated user and return a 407 to the browser and
      squid never accept  credentials.

      
      What i missing ?

      
      Configuration seems simple:

    auth_param ntlm program /lib/squid3/ntlm_fake_auth -v
    auth_param ntlm children 20 startup=5 idle=1 concurrency=0
      queue-size=80 on-persistent-overload=ERR
    acl AUTHENTICATED proxy_auth REQUIRED
    http_access deny  !AUTHENTICATED

      
      Here the debug mode;

      
      2021/11/11
        01:36:16.862 kid1| 14,3| ipcache.cc(614) ipcache_gethostbyname:
        ipcache_gethostbyname: 'www.squid-cache.org', flags=1
      2021/11/11 01:36:16.862 kid1| 28,3| Ip.cc(538) match:
        aclIpMatchIp: '212.199.163.170' NOT found
      2021/11/11 01:36:16.862 kid1| 28,3| Ip.cc(538) match:
        aclIpMatchIp: '196.200.160.70' NOT found
      2021/11/11 01:36:16.862 kid1| 28,3| Acl.cc(151) matches:
        checked: NetworksBlackLists = 0
      2021/11/11 01:36:16.862 kid1| 28,3| Acl.cc(151) matches:
        checked: http_access#29 = 0
      2021/11/11 01:36:16.862 kid1| 28,5| Checklist.cc(397)
        bannedAction: Action 'DENIED/0' is not banned
      2021/11/11 01:36:16.862 kid1| 28,5| Acl.cc(124) matches:
        checking http_access#30
      2021/11/11 01:36:16.862 kid1| 28,5| Acl.cc(124) matches:
        checking NormalPorts
      2021/11/11 01:36:16.862 kid1| 24,7| SBuf.cc(212) append: from
        c-string to id SBuf1021843
      2021/11/11 01:36:16.862 kid1| 24,7| SBuf.cc(160) rawSpace:
        reserving 13 for SBuf1021843
      2021/11/11 01:36:16.862 kid1| 24,7| SBuf.cc(865) reAlloc:
        SBuf1021843 new store capacity: 40
      2021/11/11 01:36:16.862 kid1| 28,3| StringData.cc(33) match:
        aclMatchStringList: checking 'MyPortNameID1'
      2021/11/11 01:36:16.862 kid1| 28,3| StringData.cc(36) match:
        aclMatchStringList: 'MyPortNameID1' found
      2021/11/11 01:36:16.862 kid1| 28,3| Acl.cc(151) matches:
        checked: NormalPorts = 1
      2021/11/11 01:36:16.862 kid1| 28,5| Acl.cc(124) matches:
        checking !AUTHENTICATED
      2021/11/11 01:36:16.862 kid1| 28,5| Acl.cc(124) matches:
        checking AUTHENTICATED
      2021/11/11 01:36:16.862 kid1| 29,4| UserRequest.cc(354)
        authenticate: No connection authentication type
      2021/11/11 01:36:16.862 kid1| 29,5| User.cc(36) User:
        Initialised auth_user '0x5570e8c4d240'.
      2021/11/11 01:36:16.862 kid1| 29,5| UserRequest.cc(99)
        UserRequest: initialised request 0x5570e8cdacf0
      2021/11/11 01:36:16.862 kid1| 24,7| SBuf.cc(212) append: from
        c-string to id SBuf1021846
      2021/11/11 01:36:16.862 kid1| 24,7| SBuf.cc(160) rawSpace:
        reserving 61 for SBuf1021846
      2021/11/11 01:36:16.862 kid1| 24,7| SBuf.cc(865) reAlloc:
        SBuf1021846 new store capacity: 128
      2021/11/11 01:36:16.862 kid1| 29,5| UserRequest.cc(77) valid:
        Validated. Auth::UserRequest '0x5570e8cdacf0'.
      2021/11/11 01:36:16.862 kid1| 29,5| UserRequest.cc(77) valid:
        Validated. Auth::UserRequest '0x5570e8cdacf0'.
      2021/11/11 01:36:16.862 kid1| 33,2| client_side.cc(507)
        setAuth: Adding connection-auth to local=192.168.90.170:3128
        remote=192.168.90.10:50746 FD 12 flags=1 from new NTLM handshake
        request
      2021/11/11 01:36:16.862 kid1| 29,5| UserRequest.cc(77) valid:
        Validated. Auth::UserRequest '0x5570e8cdacf0'.
      2021/11/11 01:36:16.862 kid1| 28,3| AclProxyAuth.cc(131)
        checkForAsync: checking password via authenticator
      2021/11/11 01:36:16.862 kid1| 29,5| UserRequest.cc(77) valid:
        Validated. Auth::UserRequest '0x5570e8cdacf0'.
      2021/11/11 01:36:16.862 kid1| 84,5| helper.cc(1292)
        StatefulGetFirstAvailable: StatefulGetFirstAvailable: Running
        servers 5
      2021/11/11 01:36:16.862 kid1| 84,5| helper.cc(1309)
        StatefulGetFirstAvailable: StatefulGetFirstAvailable: returning
        srv-Hlpr66
      2021/11/11 01:36:16.862 kid1| 5,5| AsyncCall.cc(26)
        AsyncCall: The AsyncCall helperStatefulDispatchWriteDone
        constructed, this=0x5570e8c8f8e0 [call581993]
      2021/11/11 01:36:16.862 kid1| 5,5| Write.cc(35) Write:
        local=[::] remote=[::] FD 10 flags=1: sz 60: asynCall
        0x5570e8c8f8e0*1
      2021/11/11 01:36:16.862 kid1| 5,5| ModEpoll.cc(117)
        SetSelect: FD 10, type=2, handler=1, client_data=0x7f9e5d8a75a8,
        timeout=0
      2021/11/11 01:36:16.862 kid1| 84,5| helper.cc(1430)
        helperStatefulDispatch: helperStatefulDispatch: Request sent to
        ntlmauthenticator #Hlpr66, 60 bytes
      2021/11/11 01:36:16.862 kid1| 28,4| Acl.cc(72)
        AuthenticateAcl: returning 2 sending credentials to helper.
      2021/11/11 01:36:16.862 kid1| 28,3| Acl.cc(151) matches:
        checked: AUTHENTICATED = -1 async
      2021/11/11 01:36:16.862 kid1| 28,3| Acl.cc(151) matches:
        checked: !AUTHENTICATED = -1 async
      2021/11/11 01:36:16.862 kid1| 28,3| Acl.cc(151) matches:
        checked: http_access#30 = -1 async
      2021/11/11 01:36:16.862 kid1| 28,3| Acl.cc(151) matches:
        checked: http_access = -1 async
      2021/11/11 01:36:16.862 kid1| 33,4| Server.cc(90)
        readSomeData: local=192.168.90.170:3128
        remote=192.168.90.10:50746 FD 12 flags=1: reading request...
      2021/11/11 01:36:16.862 kid1| 33,5| AsyncCall.cc(26)
        AsyncCall: The AsyncCall Server::doClientRead constructed,
        this=0x5570e87cfd50 [call581994]
      2021/11/11 01:36:16.862 kid1| 5,5| Read.cc(57)
        comm_read_base: comm_read, queueing read for
        local=192.168.90.170:3128 remote=192.168.90.10:50746 FD 12
        flags=1; asynCall 0x5570e87cfd50*1
      2021/11/11 01:36:16.862 kid1| 5,5| ModEpoll.cc(117)
        SetSelect: FD 12, type=1, handler=1, client_data=0x7f9e5d8a7678,
        timeout=0
      2021/11/11 01:36:16.862 kid1| 33,5| AsyncJob.cc(154) callEnd:
        Http1::Server status out: [ job17296]
      2021/11/11 01:36:16.862 kid1| 33,5| AsyncCallQueue.cc(57)
        fireNext: leaving Server::doClientRead(local=192.168.90.170:3128
        remote=192.168.90.10:50746 FD 12 flags=1, data="">
      2021/11/11 01:36:16.862 kid1| 5,5| Write.cc(66) HandleWrite:
        local=[::] remote=[::] FD 10 flags=1: off 0, sz 60.
      2021/11/11 01:36:16.862 kid1| 5,5| Write.cc(108) HandleWrite:
        write() returns 60
      2021/11/11 01:36:16.862 kid1| 5,3| IoCallback.cc(116) finish:
        called for local=[::] remote=[::] FD 10 flags=1 (0, 0)
      2021/11/11 01:36:16.862 kid1| 5,5| AsyncCall.cc(93)
        ScheduleCall: IoCallback.cc(135) will call
        helperStatefulDispatchWriteDone(local=[::] remote=[::] FD 10
        flags=1, data="" size=60, buf=0x5570e8d2c1a0)
        [call581993]
      ntlm_fake_auth.cc(170): pid=4454 :2021/11/11 01:36:16.862
        kid1| 5,5| AsyncCallQueue.cc(55) fireNext: entering
        helperStatefulDispatchWriteDone(local=[::] remote=[::] FD 10
        flags=1, data="" size=60, buf=0x5570e8d2c1a0)
      Got 'YR' from Squid with data:
      2021/11/11 01:36:16.862 kid1| 5,5| AsyncCall.cc(38) make:
        make call helperStatefulDispatchWriteDone [call581993]
      [0000]  4E 54 4C 4D 53 53 50 00  01 00 00 00 07 82 08 A2 
        NTLMSSP. ........
      2021/11/11 01:36:16.862 kid1| 5,5| AsyncCallQueue.cc(57)
        fireNext: leaving helperStatefulDispatchWriteDone(local=[::]
        remote=[::] FD 10 flags=1, data="" size=60,
        buf=0x5570e8d2c1a0)
      [0010]  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 
        ........ ........
      2021/11/11 01:36:16.862 kid1| 5,5| ModEpoll.cc(117)
        SetSelect: FD 10, type=2, handler=0, client_data=0, timeout=0
      [0020]  0A 00 63 45 00 00 00 0F                           
        ..cE.... 
      ntlm_fake_auth.cc(197): pid=4454 :sending 'TT' to squid
          with data:
      [0000]  4E 54 4C 4D 53 53 50 00  02 00 00 00 09 00 09 00 
          NTLMSSP. ........
      2021/11/11 01:36:16.862 kid1| 5,3| Read.cc(145)
          HandleRead: FD 10, size 32767, retval 72, errno 0
      [0010]  AE AA AA AA 07 82 08 A2  E8 DB F0 45 D4 04 00 32 
          ........ ...E...2
      2021/11/11 01:36:16.862 kid1| 5,3| IoCallback.cc(116)
          finish: called for local=[::] remote=[::] FD 10 flags=1 (0, 0)
      [0020]  00 00 00 00 00 00 3A 00  57 4F 52 4B 47 52 4F 55 
          ........ WORKGROU
      [0030]  50                                           
              P
      2021/11/11 01:36:16.862 kid1| 5,4| AsyncCall.cc(93)
        ScheduleCall: IoCallback.cc(135) will call
        helperStatefulHandleRead(local=[::] remote=[::] FD 10 flags=1,
        data="" size=72, buf=0x5570e87635b0) [call581969]
      2021/11/11 01:36:16.862 kid1| 5,4| AsyncCallQueue.cc(55)
        fireNext: entering helperStatefulHandleRead(local=[::]
        remote=[::] FD 10 flags=1, data="" size=72,
        buf=0x5570e87635b0)
      2021/11/11 01:36:16.862 kid1| 5,4| AsyncCall.cc(38) make:
        make call helperStatefulHandleRead [call581969]
      2021/11/11 01:36:16.862 kid1| 84,5| helper.cc(1081)
        helperStatefulHandleRead: helperStatefulHandleRead: 72 bytes
        from ntlmauthenticator #Hlpr66
      2021/11/11 01:36:16.862 kid1| 84,3| helper.cc(1103)
        helperStatefulHandleRead: helperStatefulHandleRead: end of reply
        found
      2021/11/11 01:36:16.862 kid1| 84,3| Reply.cc(41) finalize:
        Parsing helper buffer
      2021/11/11 01:36:16.862 kid1| 84,3| Reply.cc(59) finalize:
        Buff length is larger than 2
      2021/11/11 01:36:16.862 kid1| 29,4| UserRequest.cc(306)
          HandleReply: Need to challenge the client with a server token:
'TlRMTVNTUAACAAAACQAJAK6qqqoHggii6NvwRdQEADIAAAAAAAA6AFdPUktHUk9VUA=='
      2021/11/11 01:36:16.862 kid1| 29,5| UserRequest.cc(77) valid:
        Validated. Auth::UserRequest '0x5570e8cdacf0'.
      2021/11/11 01:36:16.862 kid1| 28,5| InnerNode.cc(94)
        resumeMatchingAt: checking http_access at 29
      2021/11/11 01:36:16.862 kid1| 28,5| Checklist.cc(397)
        bannedAction: Action 'DENIED/0' is not banned
      2021/11/11 01:36:16.862 kid1| 28,5| InnerNode.cc(94)
        resumeMatchingAt: checking http_access#30 at 1
      2021/11/11 01:36:16.862 kid1| 28,5| InnerNode.cc(94)
        resumeMatchingAt: checking !AUTHENTICATED at 0
      2021/11/11 01:36:16.862 kid1| 28,5| Acl.cc(124) matches:
        checking AUTHENTICATED
      2021/11/11 01:36:16.862 kid1| 29,5| UserRequest.cc(77) valid:
        Validated. Auth::UserRequest '0x5570e8cdacf0'.
      2021/11/11 01:36:16.862 kid1| 29,5| UserRequest.cc(77) valid:
        Validated. Auth::UserRequest '0x5570e8cdacf0'.
      2021/11/11 01:36:16.862 kid1| 29,2| UserRequest.cc(197)
          authenticate: need to challenge client
          'TlRMTVNTUAACAAAACQAJAK6qqqoHggii6NvwRdQEADIAAAAAAAA6AFdPUktHUk9VUA=='!
      2021/11/11 01:36:16.862 kid1| 29,5| UserRequest.cc(77) valid:
        Validated. Auth::UserRequest '0x5570e8cdacf0'.
      2021/11/11 01:36:16.862 kid1| 28,4| Acl.cc(78)
        AuthenticateAcl: returning 3 sending authentication challenge.
      2021/11/11 01:36:16.862 kid1| 28,3| Checklist.cc(63)
        markFinished: 0x5570e876da88 answer AUTH_REQUIRED for
        AuthenticateAcl exception
      2021/11/11 01:36:16.862 kid1| 28,3| Acl.cc(151) matches:
          checked: AUTHENTICATED = -1
      2021/11/11 01:36:16.863 kid1| 28,3| InnerNode.cc(97)
        resumeMatchingAt: checked: !AUTHENTICATED = -1
      2021/11/11 01:36:16.863 kid1| 28,3| InnerNode.cc(97)
        resumeMatchingAt: checked: http_access#30 = -1
      2021/11/11 01:36:16.863 kid1| 28,3| InnerNode.cc(97)
        resumeMatchingAt: checked: http_access = -1
      2021/11/11 01:36:16.863 kid1| 28,3| Checklist.cc(163)
        checkCallback: ACLChecklist::checkCallback: 0x5570e876da88
        answer=AUTH_REQUIRED
      2021/11/11 01:36:16.863 kid1| 85,2|
        client_side_request.cc(759) clientAccessCheckDone: The request
        GET http://www.squid-cache.org/ is AUTH_REQUIRED; last ACL
        checked: AUTHENTICATED
      2021/11/11 01:36:16.863 kid1| 85,5|
        client_side_request.cc(775) clientAccessCheckDone: Access
          Denied: http://www.squid-cache.org/
      2021/11/11 01:36:16.863 kid1| 85,5|
        client_side_request.cc(776) clientAccessCheckDone:
        AclMatchedName = AUTHENTICATED
      2021/11/11 01:36:16.863 kid1| 33,5|
        client_side_request.cc(779) clientAccessCheckDone: Proxy Auth
        Message = Authentication in progress
      2021/11/11 01:36:16.863 kid1| 28,4| FilledChecklist.cc(67)
        ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7fff22f7a0b0
      2021/11/11 01:36:16.863 kid1| 28,4| Checklist.cc(197)
        ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed
        0x7fff22f7a0b0
      2021/11/11 01:36:16.863 kid1| 28,4| FilledChecklist.cc(67)
        ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7fff22f7a0b0
      2021/11/11 01:36:16.863 kid1| 28,4| Checklist.cc(197)
        ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed
        0x7fff22f7a0b0
      2021/11/11 01:36:16.863 kid1| 85,5|
        client_side_request.cc(1445) sslBumpAccessCheck: cannot SslBump
        this request
      2021/11/11 01:36:16.863 kid1| 73,3| HttpRequest.cc(662)
        storeId: sent back effectiveRequestUrl:
        http://www.squid-cache.org/
      2021/11/11 01:36:16.863 kid1| 24,7| SBuf.cc(160) rawSpace:
        reserving 1 for SBuf1021849
      2021/11/11 01:36:16.863 kid1| 24,7| SBuf.cc(167) rawSpace:
        SBuf1021849 not growing
      2021/11/11 01:36:16.863 kid1| 20,3| store.cc(785)
        storeCreatePureEntry: storeCreateEntry:
        'http://www.squid-cache.org/'
      2021/11/11 01:36:16.863 kid1| 20,5| store.cc(347) StoreEntry:
        StoreEntry constructed, this=0x5570e87b5620
      2021/11/11 01:36:16.863 kid1| 20,3| MemObject.cc(101)
        MemObject: MemObject constructed, this=0x5570e8ad2990
      2021/11/11 01:36:16.863 kid1| 55,7| HttpHeader.cc(152)
        HttpHeader: init-ing hdr: 0x5570e8c55128 owner: 3
      2021/11/11 01:36:16.863 kid1| 88,3| MemObject.cc(84) setUris:
        0x5570e8ad2990 storeId: http://www.squid-cache.org/
      2021/11/11 01:36:16.863 kid1| 24,7| SBuf.cc(85) assign:
        assigning SBuf1021850 from SBuf1021792
      2021/11/11 01:36:16.863 kid1| 20,3| store.cc(444) lock:
        storeCreateEntry locked key [null_store_key]
        e:=V/0x5570e87b5620*1
      2021/11/11 01:36:16.863 kid1| 20,3| store.cc(586)
        setPrivateKey: 01 e:=V/0x5570e87b5620*1
      2021/11/11 01:36:16.863 kid1| 20,3| store.cc(422) hashInsert:
        StoreEntry::hashInsert: Inserting Entry e:=XIV/0x5570e87b5620*1
        key '771C000000000000A607000001000000'
      2021/11/11 01:36:16.863 kid1| 20,3| store.cc(444) lock:
        clientReplyContext::setReplyToStoreEntry locked key
        771C000000000000A607000001000000 e:=XIV/0x5570e87b5620*2
      2021/11/11 01:36:16.863 kid1| 4,4| errorpage.cc(604)
        errorAppendEntry: Creating an error page for entry
        0x5570e87b5620 with errorstate 0x5570e8c527b8 page id 2
      2021/11/11 01:36:16.863 kid1| 55,7| HttpHeader.cc(152)
        HttpHeader: init-ing hdr: 0x5570e8ddec88 owner: 3
      2021/11/11 01:36:16.863 kid1| 4,2| errorpage.cc(1259)
        BuildContent: No existing error page language negotiated for
        ERR_CACHE_ACCESS_DENIED. Using default error file.
    
  
_______________________________________________
squid-users mailing list
squid-users@xxxxxxxxxxxxxxxxxxxxx
http://lists.squid-cache.org/listinfo/squid-users