[RADIATOR] RadSec and Local DBM Users

Thu Feb 17 04:28:34 CST 2011

Hi,

I'm currently setting up an environment where I use RadSec to authenticate to another Radiator and if that fails(with ignore or reject) it should continue to a local user database.
This should be pretty simple I think and it does work.. almost.

What is really weird about this, I think, is that I get a access request - it goes to the handler that calls the radsec identifier - so far correct, but radsec seem to respond "IGNORE" before it is even close to done - I've done a tcpdump and this response get in the log even before the request has left the server ??
And of course it continues to the local database where it gets a reject, because the user doesn't exist there.. and after that it gets a access-accept from radsec ??
And because it has already responded to the access-request it has nowhere to send the access-accept :)

If I shuffle these two authentication methods around it works perfectly.. but that is now how I want it to be ;)

<snip from conf>

<AuthBy DBFILE>
        Identifier      AuthenticateLocal
        Filename %D/users
</AuthBy>

<AuthBy RADSEC>
        Identifier AuthenticateRADSEC
        Secret <somesecret>
        Protocol tcp
        ReconnectTimeout 5
        NoreplyTimeout 2
        UseTLS
        TLS_CAFile %D/../ssl-certs/cacert.pem
        TLS_CertificateFile %D/../ssl-certs/<acert>.crt
        TLS_CertificateType PEM
        TLS_PrivateKeyFile %D/../ssl-certs/<acert>.key
        TLS_PrivateKeyPassword <somepass>
        TLS_ExpectedPeerName CN=<remote_cert_peer>
        Host 192.0.2.131
</AuthBy>

<Handler>
        AuthByPolicy ContinueUntilAccept
        AuthBy          AuthenticateRADSEC
        AuthBy          AuthenticateLocal
</Handler>

</snip from conf>

But during the RadSec negotiation something weird happens..

<snip from trace 4 log>
Thu Feb 17 10:45:56 2011: DEBUG: New TacacsplusConnection created for 192.0.2.124:60130
Thu Feb 17 10:45:56 2011: DEBUG: TacacsplusConnection request 192, 1, 1, 4, 2671080192, 14
Thu Feb 17 10:45:56 2011: DEBUG: TacacsplusConnection Authentication START 1, 1, 1 for someuser, , 
Thu Feb 17 10:45:56 2011: DEBUG: TacacsplusConnection Authentication REPLY 5, 1, Password: ,  
Thu Feb 17 10:45:56 2011: DEBUG: TacacsplusConnection request 192, 1, 3, 0, 2671080192, 14
Thu Feb 17 10:45:56 2011: DEBUG: TacacsplusConnection Authentication CONTINUE 0, <SNIP>, 
Thu Feb 17 10:45:56 2011: DEBUG: TACACSPLUS derived Radius request packet dump:
Code:       Access-Request
Identifier: UNDEF
Authentic:  @vg<173><181><209><149><211>O<140><28><133>,<160><173>~
Attributes:
        NAS-IP-Address = 192.0.2.124
        Service-Type = Login-User
        NAS-Identifier = "TACACS"
        User-Name = "someuser"
        User-Password = "<SNIP>"
        cisco-avpair = "action=1"
        cisco-avpair = "authen_type=1"
        cisco-avpair = "priv-lvl=1"
        cisco-avpair = "service=1"
        OSC-Version-Identifier = "192"

Thu Feb 17 10:45:56 2011: DEBUG: Handling request with Handler 'NAS-Identifier=TACACS', Identifier ''
Thu Feb 17 10:45:56 2011: DEBUG:  Deleting session for someuser, 192.0.2.124, 
Thu Feb 17 10:45:56 2011: DEBUG: Handling with Radius::AuthRADSEC
Thu Feb 17 10:45:56 2011: DEBUG: Packet dump:
*** Sending request to RadSec 192.0.2.131:2083 ....
Code:       Access-Request
Identifier: 1
Authentic:  @vg<173><181><209><149><211>O<140><28><133>,<160><173>~
Attributes:
        NAS-IP-Address = 192.0.2.124
        Service-Type = Login-User
        NAS-Identifier = "TACACS"
        User-Name = "someuser"
        User-Password = "<SNIP>"
        cisco-avpair = "action=1"
        cisco-avpair = "authen_type=1"
        cisco-avpair = "priv-lvl=1"
        cisco-avpair = "service=1"
        OSC-Version-Identifier = "192"
        Proxy-State = OSC-Extended-Id=1

Thu Feb 17 10:45:56 2011: DEBUG: AuthBy RADSEC result: IGNORE, 
Thu Feb 17 10:45:56 2011: DEBUG: Handling with Radius::AuthDBFILE: AuthenticateLocal
Thu Feb 17 10:45:56 2011: DEBUG: Radius::AuthDBFILE looks for match with someuser [someuser]
Thu Feb 17 10:45:56 2011: DEBUG: Radius::AuthDBFILE REJECT: No such user: someuser [someuser]
Thu Feb 17 10:45:56 2011: DEBUG: AuthBy DBFILE result: REJECT, No such user
Thu Feb 17 10:45:56 2011: INFO: Access rejected for someuser: No such user
Thu Feb 17 10:45:56 2011: DEBUG: Packet dump:
*** Reply to TACACSPLUS request:
Code:       Access-Reject
Identifier: UNDEF
Authentic:  @vg<173><181><209><149><211>O<140><28><133>,<160><173>~
Attributes:
        Reply-Message = "No such user"

Thu Feb 17 10:45:56 2011: DEBUG: TacacsplusConnection result Access-Reject
Thu Feb 17 10:45:56 2011: DEBUG: TacacsplusConnection Authentication REPLY 2, 0, No such user,  
Thu Feb 17 10:45:56 2011: DEBUG: TacacsplusConnection disconnected from 192.0.2.124:60130
Thu Feb 17 10:45:56 2011: DEBUG: Received reply in AuthRADSEC for req 1 from 192.0.2.131:2083
Thu Feb 17 10:45:56 2011: DEBUG: Packet dump:
*** Received from 192.0.2.131 port 2083 ....
Code:       Access-Accept
Identifier: 1
Authentic:  )-<164><24> <198><143><220><229><11>^<187><213><210>1<155>
Attributes:
        Service-Type = Administrative-User
        Mikrotik-Group = "full"
        Tacacs-AuthGroup = "manager"
        cisco-avpair = "priv-lvl=15"
        Management-Policy-Id = "15"
        Extreme-EPICenter-Role = "Administrator"
        Proxy-State = OSC-Extended-Id=1

Thu Feb 17 10:45:56 2011: DEBUG: Access accepted for someuser
Thu Feb 17 10:45:56 2011: DEBUG: Packet dump:
*** Reply to TACACSPLUS request:
Code:       Access-Accept
Identifier: UNDEF
Authentic:  @vg<173><181><209><149><211>O<140><28><133>,<160><173>~
Attributes:
        Reply-Message = "No such user"
        Service-Type = Administrative-User
        Mikrotik-Group = "full"
        Tacacs-AuthGroup = "manager"
        cisco-avpair = "priv-lvl=15"
        Management-Policy-Id = "15"
        Extreme-EPICenter-Role = "Administrator"

Thu Feb 17 10:45:56 2011: DEBUG: TacacsplusConnection result Access-Accept
Thu Feb 17 10:45:56 2011: DEBUG: TacacsplusConnection Authentication REPLY 1, 0, ,  
Thu Feb 17 10:45:56 2011: ERR: TacacsplusConnection write error, disconnecting: Bad file descriptor
Thu Feb 17 10:45:56 2011: DEBUG: TacacsplusConnection disconnected from 192.0.2.124:60130
Thu Feb 17 10:45:56 2011: DEBUG: TacacsplusConnection disconnected from 192.0.2.124:60130
</snip from trace 4 log>

Is this a "bug" or is it working "as-intended" ?

The server has the following setup
Radiator Version: 4.7 - latest patches as of today(20110217)
FreeBSD: 7.2-RELEASE-p7
Perl Modules: Digest::HMAC 1.02, Digest::MD5 2.38, Digest::SHA1 2.12, Net::SSLeay 1.36

Thanks,
Patrik