Auth: rlm_krb5: [test1 at CSP-BACK] krb5_rd_req() failed: Permission denied in replay cache code

Jimmy g17jimmy at gmail.com
Tue Jun 14 22:44:42 CEST 2011


I have Kerberos 1.6 configured to use OpenLDAP 2.3.43 as a back end. I
am trying to configure Freeradius 2.1.7 to authenticate to Kerberos.

I am having problems getting Freeradiusto authenticate while started
in daemon mode. When the process is started in debug mode it seems to
funciton, but authentications while in daemon mode return the error:

>Auth: rlm_krb5: [test1 at CSP-BACK] krb5_rd_req() failed: Permission denied in replay cache code

Since authentication works in debug mode I'm not sure what I can give
to support the error besides the krb5kdc/slapd/radius log outputs and
the client side output. Functional output of debug mode is included as
well. I appreciate any help you can provide. If I should post any
config files please let me know what you would like to see. Thank you
very much.

*****************client side output*****************
radtest test1 at CSP-BACK qwer krb 1812 SharedSecret
Sending Access-Request of id 213 to  [SERVER IP ADDRESS ] port 1812
        User-Name = "test1 at CSP-BACK"
        User-Password = "qwer"
        NAS-IP-Address = 127.0.0.1
        NAS-Port = 1812
rad_recv: Access-Reject packet from host [SERVER IP ADDRESS ] port
1812, id=213, length=20
***********************************************
*****************radius log*****************
Tue Jun 14 16:17:23 2011 : Auth: rlm_krb5: [test1 at CSP-BACK]
krb5_rd_req() failed: Permission denied in replay cache code
***********************************************
*****************krb5kdc log*****************
Jun 14 16:17:22 krb.csp krb5kdc[10954](info): AS_REQ (12 etypes {18 17
16 23 1 3 2 11 10 15 12 13}) [SERVER IP ADDRESS ]: ISSUE: authtime
1308082642, etypes {rep=18 tkt=18 ses=18}, test1 at CSP-BACK for
krbtgt/CSP-BACK at CSP-BACK
Jun 14 16:17:23 krb.csp krb5kdc[10954](info): TGS_REQ (7 etypes {18 17
16 23 1 3 2})  [SERVER IP ADDRESS ]: ISSUE: authtime 1308082642,
etypes {rep=18 tkt=18 ses=18}, test1 at CSP-BACK for
radius/krb.csp at CSP-BACK
********************************************
*****************slapd log*****************
Jun 14 16:17:22 krb slapd[10742]: conn=9 op=54 SRCH
base="cn=KRB,dc=CSPKRB" scope=2 deref=0
filter="(&(|(objectClass=krbPrincipalAux)(objectClass=krbPrincipal))(krbPrincipalName=test1 at CSP-BACK))"
Jun 14 16:17:22 krb slapd[10742]: conn=9 op=54 SRCH
attr=krbprincipalname objectclass krbprincipalkey krbmaxrenewableage
krbmaxticketlife krbticketflags krbprincipalexpiration
krbticketpolicyreference krbUpEnabled krbpwdpolicyreference
krbpasswordexpiration krbLastFailedAuth krbLoginFailedCount
krbLastSuccessfulAuth nsaccountlock loginexpirationtime logindisabled
modifytimestamp krbLastPwdChange krbExtraData krbObjectReferences
Jun 14 16:17:22 krb slapd[10742]: conn=9 op=54 SEARCH RESULT tag=101
err=0 nentries=1 text=
Jun 14 16:17:22 krb slapd[10742]: conn=9 op=55 SRCH
base="cn=KRB,dc=CSPKRB" scope=2 deref=0
filter="(&(|(objectClass=krbPrincipalAux)(objectClass=krbPrincipal))(krbPrincipalName=krbtgt/CSP-BACK at CSP-BACK))"
Jun 14 16:17:22 krb slapd[10742]: conn=9 op=55 SRCH
attr=krbprincipalname objectclass krbprincipalkey krbmaxrenewableage
krbmaxticketlife krbticketflags krbprincipalexpiration
krbticketpolicyreference krbUpEnabled krbpwdpolicyreference
krbpasswordexpiration krbLastFailedAuth krbLoginFailedCount
krbLastSuccessfulAuth nsaccountlock loginexpirationtime logindisabled
modifytimestamp krbLastPwdChange krbExtraData krbObjectReferences
Jun 14 16:17:22 krb slapd[10742]: conn=9 op=55 SEARCH RESULT tag=101
err=0 nentries=1 text=
Jun 14 16:17:23 krb slapd[10742]: conn=9 op=56 SRCH
base="cn=KRB,dc=CSPKRB" scope=2 deref=0
filter="(&(|(objectClass=krbPrincipalAux)(objectClass=krbPrincipal))(krbPrincipalName=krbtgt/CSP-BACK at CSP-BACK))"
Jun 14 16:17:23 krb slapd[10742]: conn=9 op=56 SRCH
attr=krbprincipalname objectclass krbprincipalkey krbmaxrenewableage
krbmaxticketlife krbticketflags krbprincipalexpiration
krbticketpolicyreference krbUpEnabled krbpwdpolicyreference
krbpasswordexpiration krbLastFailedAuth krbLoginFailedCount
krbLastSuccessfulAuth nsaccountlock loginexpirationtime logindisabled
modifytimestamp krbLastPwdChange krbExtraData krbObjectReferences
Jun 14 16:17:23 krb slapd[10742]: conn=9 op=56 SEARCH RESULT tag=101
err=0 nentries=1 text=
Jun 14 16:17:23 krb slapd[10742]: conn=9 op=57 SRCH
base="cn=KRB,dc=CSPKRB" scope=2 deref=0
filter="(&(|(objectClass=krbPrincipalAux)(objectClass=krbPrincipal))(krbPrincipalName=radius/krb.csp at CSP-BACK))"
Jun 14 16:17:23 krb slapd[10742]: conn=9 op=57 SRCH
attr=krbprincipalname objectclass krbprincipalkey krbmaxrenewableage
krbmaxticketlife krbticketflags krbprincipalexpiration
krbticketpolicyreference krbUpEnabled krbpwdpolicyreference
krbpasswordexpiration krbLastFailedAuth krbLoginFailedCount
krbLastSuccessfulAuth nsaccountlock loginexpirationtime logindisabled
modifytimestamp krbLastPwdChange krbExtraData krbObjectReferences
Jun 14 16:17:23 krb slapd[10742]: conn=9 op=57 SEARCH RESULT tag=101
err=0 nentries=1 text=
********************************************

****************************************************************************************
****************************************************************************************
DEBUG MODE OUTPUT
When I run the server in debug mode here is the output from radiusd -X:
********************************************
FreeRADIUS Version 2.1.7, for host x86_64-redhat-linux-gnu, built on
Mar 31 2010 at 00:14:28
Copyright (C) 1999-2009 The FreeRADIUS server project and contributors.
There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
PARTICULAR PURPOSE.
You may redistribute copies of FreeRADIUS under the terms of the
GNU General Public License v2.
Starting - reading configuration files ...
including configuration file /etc/raddb/radiusd.conf
including configuration file /etc/raddb/proxy.conf
including configuration file /etc/raddb/clients.conf
including files in directory /etc/raddb/modules/
including configuration file /etc/raddb/modules/unix
including configuration file /etc/raddb/modules/pap
including configuration file /etc/raddb/modules/always
including configuration file /etc/raddb/modules/attr_rewrite
including configuration file /etc/raddb/modules/perl
including configuration file /etc/raddb/modules/detail
including configuration file /etc/raddb/modules/detail.example.com
including configuration file /etc/raddb/modules/expr
including configuration file /etc/raddb/modules/checkval
including configuration file /etc/raddb/modules/preprocess
including configuration file /etc/raddb/modules/sql_log
including configuration file /etc/raddb/modules/inner-eap
including configuration file /etc/raddb/modules/chap
including configuration file /etc/raddb/modules/detail.log
including configuration file /etc/raddb/modules/digest
including configuration file /etc/raddb/modules/sradutmp
including configuration file /etc/raddb/modules/files
including configuration file /etc/raddb/modules/linelog
including configuration file /etc/raddb/modules/smbpasswd
including configuration file /etc/raddb/modules/mschap
including configuration file /etc/raddb/modules/cui
including configuration file /etc/raddb/modules/pam
including configuration file /etc/raddb/modules/exec
including configuration file /etc/raddb/modules/policy
including configuration file /etc/raddb/modules/smsotp
including configuration file /etc/raddb/modules/acct_unique
including configuration file /etc/raddb/modules/expiration
including configuration file /etc/raddb/modules/otp
including configuration file /etc/raddb/modules/realm
including configuration file /etc/raddb/modules/sqlcounter_expire_on_login
including configuration file /etc/raddb/modules/etc_group
including configuration file /etc/raddb/modules/ippool
including configuration file /etc/raddb/modules/logintime
including configuration file /etc/raddb/modules/passwd
including configuration file /etc/raddb/modules/attr_filter
including configuration file /etc/raddb/modules/wimax
including configuration file /etc/raddb/modules/radutmp
including configuration file /etc/raddb/modules/mac2ip
including configuration file /etc/raddb/modules/counter
including configuration file /etc/raddb/modules/echo
including configuration file /etc/raddb/modules/mac2vlan
including configuration file /etc/raddb/modules/krb5
including configuration file /etc/raddb/eap.conf
including configuration file /etc/raddb/policy.conf
including files in directory /etc/raddb/sites-enabled/
including configuration file /etc/raddb/sites-enabled/control-socket
including configuration file /etc/raddb/sites-enabled/inner-tunnel
including configuration file /etc/raddb/sites-enabled/default
group = radiusd
user = radiusd
including dictionary file /etc/raddb/dictionary
main {
        prefix = "/usr"
        localstatedir = "/var"
        logdir = "/var/log/radius"
        libdir = "/usr/lib64/freeradius"
        radacctdir = "/var/log/radius/radacct"
        hostname_lookups = no
        max_request_time = 30
        cleanup_delay = 5
        max_requests = 1024
        allow_core_dumps = no
        pidfile = "/var/run/radiusd/radiusd.pid"
        checkrad = "/usr/sbin/checkrad"
        debug_level = 0
        proxy_requests = yes
 log {
        stripped_names = no
        auth = no
        auth_badpass = no
        auth_goodpass = no
 }
 security {
        max_attributes = 200
        reject_delay = 1
        status_server = yes
 }
}
radiusd: #### Loading Realms and Home Servers ####
 proxy server {
        retry_delay = 5
        retry_count = 3
        default_fallback = no
        dead_time = 120
        wake_all_if_all_dead = no
 }
 home_server localhost {
        ipaddr = 127.0.0.1
        port = 1812
        type = "auth"
        secret = "testing123"
        response_window = 20
        max_outstanding = 65536
        require_message_authenticator = no
        zombie_period = 40
        status_check = "status-server"
        ping_interval = 30
        check_interval = 30
        num_answers_to_alive = 3
        num_pings_to_alive = 3
        revive_interval = 120
        status_check_timeout = 4
        irt = 2
        mrt = 16
        mrc = 5
        mrd = 30
 }
 home_server_pool my_auth_failover {
        type = fail-over
        home_server = localhost
 }
 realm example.com {
        auth_pool = my_auth_failover
 }
 realm LOCAL {
 }
radiusd: #### Loading Clients ####
 client localhost {
        ipaddr = 127.0.0.1
        require_message_authenticator = no
        secret = "testing123"
        nastype = "other"
 }
 client [CLIENT SUBNET]/16 {
        require_message_authenticator = no
        secret = "SharedSecret"
        nastype = "other"
 }
radiusd: #### Instantiating modules ####
 instantiate {
 Module: Linked to module rlm_exec
 Module: Instantiating exec
  exec {
        wait = no
        input_pairs = "request"
        shell_escape = yes
  }
 Module: Linked to module rlm_expr
 Module: Instantiating expr
 Module: Linked to module rlm_expiration
 Module: Instantiating expiration
  expiration {
        reply-message = "Password Has Expired  "
  }
 Module: Linked to module rlm_logintime
 Module: Instantiating logintime
  logintime {
        reply-message = "You are calling outside your allowed timespan  "
        minimum-timeout = 60
  }
 }
radiusd: #### Loading Virtual Servers ####
server inner-tunnel {
 modules {
 Module: Checking authorize {...} for more modules to load
 } # modules
} # server
server {
 modules {
 Module: Checking authenticate {...} for more modules to load
 Module: Linked to module rlm_krb5
 Module: Instantiating krb5
  krb5 {
        keytab = "/etc/raddb/rad.keytab"
        service_principal = "radius/krb.csp"
  }
rlm_krb5: krb5_init ok
 Module: Linked to module rlm_eap
 Module: Instantiating eap
  eap {
        default_eap_type = "ttls"
        timer_expire = 60
        ignore_unknown_eap_types = no
        cisco_accounting_username_bug = no
        max_sessions = 2048
  }
 Module: Linked to sub-module rlm_eap_tls
 Module: Instantiating eap-tls
   tls {
        rsa_key_exchange = no
        dh_key_exchange = yes
        rsa_key_length = 512
        dh_key_length = 512
        verify_depth = 0
        pem_file_type = yes
        private_key_file = "/etc/raddb/certs/server.pem"
        certificate_file = "/etc/raddb/certs/server.pem"
        CA_file = "/etc/raddb/certs/ca.pem"
        private_key_password = "whatever"
        dh_file = "/etc/raddb/certs/dh"
        random_file = "/etc/raddb/certs/random"
        fragment_size = 1024
        include_length = yes
        check_crl = no
        cipher_list = "DEFAULT"
        make_cert_command = "/etc/raddb/certs/bootstrap"
    cache {
        enable = no
        lifetime = 24
        max_entries = 255
    }
   }
 Module: Linked to sub-module rlm_eap_ttls
 Module: Instantiating eap-ttls
   ttls {
        default_eap_type = "md5"
        copy_request_to_tunnel = no
        use_tunneled_reply = no
        virtual_server = "inner-tunnel"
        include_length = yes
   }
 Module: Checking authorize {...} for more modules to load
 Module: Linked to module rlm_preprocess
 Module: Instantiating preprocess
  preprocess {
        huntgroups = "/etc/raddb/huntgroups"
        hints = "/etc/raddb/hints"
        with_ascend_hack = no
        ascend_channels_per_line = 23
        with_ntdomain_hack = no
        with_specialix_jetstream_hack = no
        with_cisco_vsa_hack = no
        with_alvarion_vsa_hack = no
  }
 Module: Linked to module rlm_detail
 Module: Instantiating auth_log
  detail auth_log {
        detailfile =
"/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d"
        header = "%t"
        detailperm = 384
        dirperm = 493
        locking = no
        log_packet_header = no
  }
 Module: Linked to module rlm_realm
 Module: Instantiating suffix
  realm suffix {
        format = "suffix"
        delimiter = "@"
        ignore_default = no
        ignore_null = no
  }
 Module: Linked to module rlm_unix
 Module: Instantiating unix
  unix {
        radwtmp = "/var/log/radius/radwtmp"
  }
 Module: Linked to module rlm_files
 Module: Instantiating files
  files {
        usersfile = "/etc/raddb/users"
        acctusersfile = "/etc/raddb/acct_users"
        preproxy_usersfile = "/etc/raddb/preproxy_users"
        compat = "no"
  }
 Module: Linked to module rlm_pap
 Module: Instantiating pap
  pap {
        encryption_scheme = "auto"
        auto_header = no
  }
 Module: Checking preacct {...} for more modules to load
 Module: Linked to module rlm_acct_unique
 Module: Instantiating acct_unique
  acct_unique {
        key = "User-Name, Acct-Session-Id, NAS-IP-Address,
Client-IP-Address, NAS-Port"
  }
 Module: Checking accounting {...} for more modules to load
 Module: Instantiating detail
  detail {
        detailfile =
"/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
        header = "%t"
        detailperm = 384
        dirperm = 493
        locking = no
        log_packet_header = no
  }
 Module: Linked to module rlm_radutmp
 Module: Instantiating radutmp
  radutmp {
        filename = "/var/log/radius/radutmp"
        username = "%{User-Name}"
        case_sensitive = yes
        check_with_nas = yes
        perm = 384
        callerid = yes
  }
 Module: Linked to module rlm_attr_filter
 Module: Instantiating attr_filter.accounting_response
  attr_filter attr_filter.accounting_response {
        attrsfile = "/etc/raddb/attrs.accounting_response"
        key = "%{User-Name}"
  }
 Module: Checking session {...} for more modules to load
 Module: Checking post-proxy {...} for more modules to load
 Module: Checking post-auth {...} for more modules to load
 Module: Instantiating attr_filter.access_reject
  attr_filter attr_filter.access_reject {
        attrsfile = "/etc/raddb/attrs.access_reject"
        key = "%{User-Name}"
  }
 } # modules
} # server
radiusd: #### Opening IP addresses and Ports ####
listen {
        type = "auth"
        ipaddr = *
        port = 0
}
listen {
        type = "acct"
        ipaddr = *
        port = 0
}
listen {
        type = "control"
 listen {
        socket = "/var/run/radiusd/radiusd.sock"
 }
}
Listening on authentication address * port 1812
Listening on accounting address * port 1813
Listening on command file /var/run/radiusd/radiusd.sock
Listening on proxy address * port 1814
Ready to process requests.

***************************************************upon issing
radtest***************************************************
rad_recv: Access-Request packet from host  [CLIENT IP ADDRESS ] port
35916, id=141, length=66
        User-Name = "test1 at CSP-BACK"
        User-Password = "qwer"
        NAS-IP-Address = 127.0.0.1
        NAS-Port = 1812
+- entering group authorize {...}
++[preprocess] returns ok
[auth_log]      expand:
/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d ->
/var/log/radius/radacct/ [CLIENT IP ADDRESS ]/auth-detail-20110614
[auth_log] /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d
expands to /var/log/radius/radacct/ [CLIENT IP ADDRESS
]/auth-detail-20110614
[auth_log]      expand: %t -> Tue Jun 14 16:25:45 2011
++[auth_log] returns ok
[suffix] Looking up realm "CSP-BACK" for User-Name = "test1 at CSP-BACK"
[suffix] No such realm "CSP-BACK"
++[suffix] returns noop
[eap] No EAP-Message, not doing EAP
++[eap] returns noop
++[unix] returns notfound
[files] users: Matched entry DEFAULT at line 49
++[files] returns ok
++[expiration] returns noop
++[logintime] returns noop
[pap] WARNING! No "known good" password found for the user.
Authentication may fail because of this.
++[pap] returns noop
Found Auth-Type = Kerberos
+- entering group Kerberos {...}
++[krb5] returns ok
  WARNING: Empty section.  Using default return values.
Sending Access-Accept of id 141 to [CLIENT IP ADDRESS ] port 35916
Finished request 0.
Going to the next request
Waking up in 4.9 seconds.
Cleaning up request 0 ID 141 with timestamp +168
Ready to process requests.
***************************************************
*****************client side output*****************
 radtest test1 at CSP-BACK qwer krb 1812 SharedSecret
Sending Access-Request of id 141 to [CLIENT IP ADDRESS ] port 1812
        User-Name = "test1 at CSP-BACK"
        User-Password = "qwer"
        NAS-IP-Address = 127.0.0.1
        NAS-Port = 1812
rad_recv: Access-Accept packet from host [CLIENT IP ADDRESS ] port
1812, id=141, length=20
***************************************************
*****************krb5kdc.log*****************
Jun 14 16:25:45 krb.csp krb5kdc[10954](info): AS_REQ (12 etypes {18 17
16 23 1 3 2 11 10 15 12 13}) [SERVER IP ADDRESS ]: ISSUE: authtime
1308083145, etypes {rep=18 tkt=18 ses=18}, test1 at CSP-BACK for
krbtgt/CSP-BACK at CSP-BACK
Jun 14 16:25:46 krb.csp krb5kdc[10954](info): TGS_REQ (7 etypes {18 17
16 23 1 3 2}) [SERVER IP ADDRESS ]: ISSUE: authtime 1308083145, etypes
{rep=18 tkt=18 ses=18}, test1 at CSP-BACK for radius/krb.csp at CSP-BACK
***************************************************
*****************slapd.log*****************
Jun 14 16:25:45 krb slapd[10742]: conn=9 op=58 SRCH
base="cn=KRB,dc=CSPKRB" scope=2 deref=0
filter="(&(|(objectClass=krbPrincipalAux)(objectClass=krbPrincipal))(krbPrincipalName=test1 at CSP-BACK))"
Jun 14 16:25:45 krb slapd[10742]: conn=9 op=58 SRCH
attr=krbprincipalname objectclass krbprincipalkey krbmaxrenewableage
krbmaxticketlife krbticketflags krbprincipalexpiration
krbticketpolicyreference krbUpEnabled krbpwdpolicyreference
krbpasswordexpiration krbLastFailedAuth krbLoginFailedCount
krbLastSuccessfulAuth nsaccountlock loginexpirationtime logindisabled
modifytimestamp krbLastPwdChange krbExtraData krbObjectReferences
Jun 14 16:25:45 krb slapd[10742]: conn=9 op=58 SEARCH RESULT tag=101
err=0 nentries=1 text=
Jun 14 16:25:45 krb slapd[10742]: conn=9 op=59 SRCH
base="cn=KRB,dc=CSPKRB" scope=2 deref=0
filter="(&(|(objectClass=krbPrincipalAux)(objectClass=krbPrincipal))(krbPrincipalName=krbtgt/CSP-BACK at CSP-BACK))"
Jun 14 16:25:45 krb slapd[10742]: conn=9 op=59 SRCH
attr=krbprincipalname objectclass krbprincipalkey krbmaxrenewableage
krbmaxticketlife krbticketflags krbprincipalexpiration
krbticketpolicyreference krbUpEnabled krbpwdpolicyreference
krbpasswordexpiration krbLastFailedAuth krbLoginFailedCount
krbLastSuccessfulAuth nsaccountlock loginexpirationtime logindisabled
modifytimestamp krbLastPwdChange krbExtraData krbObjectReferences
Jun 14 16:25:45 krb slapd[10742]: conn=9 op=59 SEARCH RESULT tag=101
err=0 nentries=1 text=
Jun 14 16:25:46 krb slapd[10742]: conn=9 op=60 SRCH
base="cn=KRB,dc=CSPKRB" scope=2 deref=0
filter="(&(|(objectClass=krbPrincipalAux)(objectClass=krbPrincipal))(krbPrincipalName=krbtgt/CSP-BACK at CSP-BACK))"
Jun 14 16:25:46 krb slapd[10742]: conn=9 op=60 SRCH
attr=krbprincipalname objectclass krbprincipalkey krbmaxrenewableage
krbmaxticketlife krbticketflags krbprincipalexpiration
krbticketpolicyreference krbUpEnabled krbpwdpolicyreference
krbpasswordexpiration krbLastFailedAuth krbLoginFailedCount
krbLastSuccessfulAuth nsaccountlock loginexpirationtime logindisabled
modifytimestamp krbLastPwdChange krbExtraData krbObjectReferences
Jun 14 16:25:46 krb slapd[10742]: conn=9 op=60 SEARCH RESULT tag=101
err=0 nentries=1 text=
Jun 14 16:25:46 krb slapd[10742]: conn=9 op=61 SRCH
base="cn=KRB,dc=CSPKRB" scope=2 deref=0
filter="(&(|(objectClass=krbPrincipalAux)(objectClass=krbPrincipal))(krbPrincipalName=radius/krb.csp at CSP-BACK))"
Jun 14 16:25:46 krb slapd[10742]: conn=9 op=61 SRCH
attr=krbprincipalname objectclass krbprincipalkey krbmaxrenewableage
krbmaxticketlife krbticketflags krbprincipalexpiration
krbticketpolicyreference krbUpEnabled krbpwdpolicyreference
krbpasswordexpiration krbLastFailedAuth krbLoginFailedCount
krbLastSuccessfulAuth nsaccountlock loginexpirationtime logindisabled
modifytimestamp krbLastPwdChange krbExtraData krbObjectReferences
Jun 14 16:25:46 krb slapd[10742]: conn=9 op=61 SEARCH RESULT tag=101
err=0 nentries=1 text=

(no radius log output in debug mode)




More information about the Freeradius-Users mailing list