Freeradius configuration to support EAP-TLS, EAP-TTLS and EAP-PEAP

11 Dec 2008

      Hi Everybody. 

We are having some issues in setting up freeradius to support EAP-TLS, EAP-TTLS and EAP-PEAP.
Our goal is to have our authentication server providing those three Auth-Type simultaneously.
To support EAP-TLS, we generate our CA and certificates via TinyCA.

Here are our configurations files :

######radiusd.conf##########
prefix = /usr/local
exec_prefix = ${prefix}
sysconfdir = ${prefix}/etc
localstatedir = ${prefix}/var
sbindir = ${exec_prefix}/sbin
logdir = ${localstatedir}/log/radius
raddbdir = ${sysconfdir}/raddb
radacctdir = ${logdir}/radacct
confdir = ${raddbdir}
run_dir = ${localstatedir}/run/radiusd
db_dir = $(raddbdir)
libdir = ${exec_prefix}/lib
pidfile = ${run_dir}/radiusd.pid
max_request_time = 30
cleanup_delay = 5
max_requests = 1024
listen {
        type = auth
        ipaddr = *
        port = 0
}
listen {
        ipaddr = *
        port = 0
        type = acct
}
hostname_lookups = no
allow_core_dumps = no
regular_expressions     = yes
extended_expressions    = yes
log {
        destination = files
        file = ${logdir}/radius.log
        syslog_facility = daemon
        stripped_names = no
        auth = no
        auth_badpass = no
        auth_goodpass = no
}
checkrad = ${sbindir}/checkrad
security {
 max_attributes = 200
        reject_delay = 1
        status_server = yes
}
proxy_requests  = yes
$INCLUDE proxy.conf
$INCLUDE clients.conf
snmp    = no
$INCLUDE snmp.conf
thread pool {
        start_servers = 5
        max_servers = 32
        min_spare_servers = 3
        max_spare_servers = 10
        max_requests_per_server = 0
}
modules {
        $INCLUDE ${confdir}/modules/
        $INCLUDE eap.conf
        $INCLUDE sql.conf
        $INCLUDE sql/mysql/counter.conf
}
instantiate {
        exec
        expr
        expiration
        logintime
}
$INCLUDE policy.conf
$INCLUDE sites-enabled/

#######sites-enabled/behanzin.uac.bj###############
authorize {
        preprocess
        chap
        mschap
        digest
        suffix
        eap {
                ok = return
        }
        unix
        expiration
        logintime
        pap
        passwd
}
authenticate {
        Auth-Type PAP {
                pap
        }
        Auth-Type CHAP {
                chap
        }
        Auth-Type MS-CHAP {
                mschap
        }
        digest
        unix
        eap
}
preacct {
        preprocess
        acct_unique
        suffix
        files
}
accounting {
        detail
        unix
        radutmp
        attr_filter.accounting_response
}
session {
        radutmp
}
post-auth {
        exec
        Post-Auth-Type REJECT {
                attr_filter.access_reject
        }
}
pre-proxy {
}
post-proxy {
        eap
}

We also add radius' log after an authentication attempt from  windows XP OS

using windows built in supplicant by supplying a username and password stored in 

our /etc/passwd file. But the authentication failed with this error message :

rlm_eap: identity does not match User-Name, setting from EAP identity

########Radius logs ################
...............Thu Dec 11 14:59:10 2008 : Debug: main {
Thu Dec 11 14:59:10 2008 : Debug:       prefix = "/usr/local"
Thu Dec 11 14:59:10 2008 : Debug:       localstatedir = "/usr/local/var"
Thu Dec 11 14:59:10 2008 : Debug:       logdir = "/usr/local/var/log/radius"
Thu Dec 11 14:59:10 2008 : Debug:       libdir = "/usr/local/lib"
Thu Dec 11 14:59:10 2008 : Debug:       radacctdir = "/usr/local/var/log/radius/radacct"
Thu Dec 11 14:59:10 2008 : Debug:       hostname_lookups = no
Thu Dec 11 14:59:10 2008 : Debug:       max_request_time = 30
Thu Dec 11 14:59:10 2008 : Debug:       cleanup_delay = 5
Thu Dec 11 14:59:10 2008 : Debug:       max_requests = 1024
Thu Dec 11 14:59:10 2008 : Debug:       allow_core_dumps = no
Thu Dec 11 14:59:10 2008 : Debug:       pidfile = "/usr/local/var/run/radiusd/radiusd.pid"
Thu Dec 11 14:59:10 2008 : Debug:       checkrad = "/usr/local/sbin/checkrad"
Thu Dec 11 14:59:10 2008 : Debug:       debug_level = 0
Thu Dec 11 14:59:10 2008 : Debug:       proxy_requests = yes
Thu Dec 11 14:59:10 2008 : Debug:  log {
Thu Dec 11 14:59:10 2008 : Debug:       stripped_names = no
Thu Dec 11 14:59:10 2008 : Debug:       auth = no
Thu Dec 11 14:59:10 2008 : Debug:       auth_badpass = no
Thu Dec 11 14:59:10 2008 : Debug:       auth_goodpass = no
Thu Dec 11 14:59:10 2008 : Debug:  }
Thu Dec 11 14:59:10 2008 : Debug: }
Thu Dec 11 14:59:10 2008 : Debug:  client localhost {
Thu Dec 11 14:59:10 2008 : Debug:       ipaddr = 127.0.0.1
Thu Dec 11 14:59:10 2008 : Debug:       require_message_authenticator = no
Thu Dec 11 14:59:10 2008 : Debug:       secret = "testing123"
Thu Dec 11 14:59:10 2008 : Debug:       nastype = "other"
Thu Dec 11 14:59:10 2008 : Debug:  }
Thu Dec 11 14:59:10 2008 : Debug:  client 172.21.0.9 {
Thu Dec 11 14:59:10 2008 : Debug:       require_message_authenticator = no
Thu Dec 11 14:59:10 2008 : Debug:       secret = "testing123"
Thu Dec 11 14:59:10 2008 : Debug:       shortname = "Behanzin"
Thu Dec 11 14:59:10 2008 : Debug:       nastype = "other"
Thu Dec 11 14:59:10 2008 : Debug:  }
Thu Dec 11 14:59:10 2008 : Debug:  client 172.21.1.251 {
Thu Dec 11 14:59:10 2008 : Debug:       require_message_authenticator = no
Thu Dec 11 14:59:10 2008 : Debug:       secret = "testing123"
Thu Dec 11 14:59:10 2008 : Debug:       shortname = "TestingAP"
Thu Dec 11 14:59:10 2008 : Debug:       nastype = "other"
Thu Dec 11 14:59:10 2008 : Debug:  }
Thu Dec 11 14:59:10 2008 : Debug: radiusd: #### Loading Realms and Home Servers ####
Thu Dec 11 14:59:10 2008 : Debug:  proxy server {
Thu Dec 11 14:59:10 2008 : Debug:       retry_delay = 5
Thu Dec 11 14:59:10 2008 : Debug:       retry_count = 3
Thu Dec 11 14:59:10 2008 : Debug:       default_fallback = no
Thu Dec 11 14:59:10 2008 : Debug:       dead_time = 120
Thu Dec 11 14:59:10 2008 : Debug:       wake_all_if_all_dead = no
Thu Dec 11 14:59:10 2008 : Debug:  }
Thu Dec 11 14:59:10 2008 : Debug:  home_server localhost {
Thu Dec 11 14:59:10 2008 : Debug:       ipaddr = 127.0.0.1
Thu Dec 11 14:59:10 2008 : Debug:       port = 1812
Thu Dec 11 14:59:10 2008 : Debug:       type = "auth"
Thu Dec 11 14:59:10 2008 : Debug:       secret = "testing123"
Thu Dec 11 14:59:10 2008 : Debug:       response_window = 20
Thu Dec 11 14:59:10 2008 : Debug:       max_outstanding = 65536
Thu Dec 11 14:59:10 2008 : Debug:       zombie_period = 40
Thu Dec 11 14:59:10 2008 : Debug:       status_check = "status-server"
Thu Dec 11 14:59:10 2008 : Debug:       ping_check = "none"
Thu Dec 11 14:59:10 2008 : Debug:       ping_interval = 30
Thu Dec 11 14:59:10 2008 : Debug:       check_interval = 30
Thu Dec 11 14:59:10 2008 : Debug:       num_answers_to_alive = 3
Thu Dec 11 14:59:10 2008 : Debug:       num_pings_to_alive = 3
Thu Dec 11 14:59:10 2008 : Debug:       revive_interval = 120
Thu Dec 11 14:59:10 2008 : Debug:       status_check_timeout = 4
Thu Dec 11 14:59:10 2008 : Debug:  }
Thu Dec 11 14:59:10 2008 : Debug:  home_server_pool my_auth_failover {
Thu Dec 11 14:59:10 2008 : Debug:       type = fail-over
Thu Dec 11 14:59:10 2008 : Debug:       home_server = localhost
Thu Dec 11 14:59:10 2008 : Debug:  }
Thu Dec 11 14:59:10 2008 : Debug:  realm uac.bj {
Thu Dec 11 14:59:10 2008 : Debug:       auth_pool = my_auth_failover
Thu Dec 11 14:59:10 2008 : Debug:  }
Thu Dec 11 14:59:10 2008 : Debug:  realm LOCAL {
Thu Dec 11 14:59:10 2008 : Debug:  }
Thu Dec 11 14:59:10 2008 : Debug: radiusd: #### Instantiating modules ####
Thu Dec 11 14:59:10 2008 : Debug:  instantiate {
Thu Dec 11 14:59:10 2008 : Debug:     (Loaded rlm_exec, checking if it's valid)
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to module rlm_exec
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating exec
Thu Dec 11 14:59:10 2008 : Debug:   exec {
Thu Dec 11 14:59:10 2008 : Debug:       wait = no
Thu Dec 11 14:59:10 2008 : Debug:       input_pairs = "request"
Thu Dec 11 14:59:10 2008 : Debug:       shell_escape = yes
Thu Dec 11 14:59:10 2008 : Debug:   }
Thu Dec 11 14:59:10 2008 : Debug:     (Loaded rlm_expr, checking if it's valid)
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to module rlm_expr
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating expr
Thu Dec 11 14:59:10 2008 : Debug:     (Loaded rlm_expiration, checking if it's valid)
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to module rlm_expiration
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating expiration
Thu Dec 11 14:59:10 2008 : Debug:   expiration {
Thu Dec 11 14:59:10 2008 : Debug:       reply-message = "Password Has Expired  "
Thu Dec 11 14:59:10 2008 : Debug:   }
Thu Dec 11 14:59:10 2008 : Debug:     (Loaded rlm_logintime, checking if it's valid)
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to module rlm_logintime
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating logintime
Thu Dec 11 14:59:10 2008 : Debug:   logintime {
Thu Dec 11 14:59:10 2008 : Debug:       reply-message = "You are calling outside your allowed timespan  "
Thu Dec 11 14:59:10 2008 : Debug:       minimum-timeout = 60
Thu Dec 11 14:59:10 2008 : Debug:   }
Thu Dec 11 14:59:10 2008 : Debug:  }
Thu Dec 11 14:59:10 2008 : Debug: radiusd: #### Loading Virtual Servers ####
Thu Dec 11 14:59:10 2008 : Debug: server {
Thu Dec 11 14:59:10 2008 : Debug:  modules {
Thu Dec 11 14:59:10 2008 : Debug:  Module: Checking authenticate {...} for more modules to load
Thu Dec 11 14:59:10 2008 : Debug:     (Loaded rlm_pap, checking if it's valid)
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to module rlm_pap
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating pap
Thu Dec 11 14:59:10 2008 : Debug:   pap {
Thu Dec 11 14:59:10 2008 : Debug:       encryption_scheme = "auto"
Thu Dec 11 14:59:10 2008 : Debug:       auto_header = no
Thu Dec 11 14:59:10 2008 : Debug:   }
Thu Dec 11 14:59:10 2008 : Debug:     (Loaded rlm_chap, checking if it's valid)
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to module rlm_chap
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating chap
Thu Dec 11 14:59:10 2008 : Debug:     (Loaded rlm_mschap, checking if it's valid)
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to module rlm_mschap
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating mschap
Thu Dec 11 14:59:10 2008 : Debug:   mschap {
Thu Dec 11 14:59:10 2008 : Debug:       use_mppe = yes
Thu Dec 11 14:59:10 2008 : Debug:       require_encryption = no
Thu Dec 11 14:59:10 2008 : Debug:       require_strong = no
Thu Dec 11 14:59:10 2008 : Debug:       with_ntdomain_hack = no
Thu Dec 11 14:59:10 2008 : Debug:   }
Thu Dec 11 14:59:10 2008 : Debug:     (Loaded rlm_digest, checking if it's valid)
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to module rlm_digest
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating digest
Thu Dec 11 14:59:10 2008 : Debug:     (Loaded rlm_unix, checking if it's valid)
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to module rlm_unix
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating unix
Thu Dec 11 14:59:10 2008 : Debug:   unix {
Thu Dec 11 14:59:10 2008 : Debug:       radwtmp = "/usr/local/var/log/radius/radwtmp"
Thu Dec 11 14:59:10 2008 : Debug:   }
Thu Dec 11 14:59:10 2008 : Debug:     (Loaded rlm_eap, checking if it's valid)
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to module rlm_eap
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating eap
Thu Dec 11 14:59:10 2008 : Debug:   eap {
Thu Dec 11 14:59:10 2008 : Debug:       default_eap_type = "md5"
Thu Dec 11 14:59:10 2008 : Debug:       timer_expire = 60
Thu Dec 11 14:59:10 2008 : Debug:       ignore_unknown_eap_types = yes
Thu Dec 11 14:59:10 2008 : Debug:       cisco_accounting_username_bug = no
Thu Dec 11 14:59:10 2008 : Debug:   }
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to sub-module rlm_eap_md5
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating eap-md5
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to sub-module rlm_eap_leap
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating eap-leap
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to sub-module rlm_eap_gtc
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating eap-gtc
Thu Dec 11 14:59:10 2008 : Debug:    gtc {
Thu Dec 11 14:59:10 2008 : Debug:       challenge = "Password: "
Thu Dec 11 14:59:10 2008 : Debug:       auth_type = "PAP"
Thu Dec 11 14:59:10 2008 : Debug:    }
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to sub-module rlm_eap_tls
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating eap-tls
Thu Dec 11 14:59:10 2008 : Debug:    tls {
Thu Dec 11 14:59:10 2008 : Debug:       rsa_key_exchange = no
Thu Dec 11 14:59:10 2008 : Debug:       dh_key_exchange = yes
Thu Dec 11 14:59:10 2008 : Debug:       rsa_key_length = 512
Thu Dec 11 14:59:10 2008 : Debug:       dh_key_length = 512
Thu Dec 11 14:59:10 2008 : Debug:       verify_depth = 0
Thu Dec 11 14:59:10 2008 : Debug:       pem_file_type = yes
Thu Dec 11 14:59:10 2008 : Debug:       private_key_file = "/usr/local/etc/raddb/certs/behanzin@uac.bj-cert.pem"
Thu Dec 11 14:59:10 2008 : Debug:       certificate_file = "/usr/local/etc/raddb/certs/behanzin@uac.bj-cert.pem"
Thu Dec 11 14:59:10 2008 : Debug:       CA_file = "/usr/local/etc/raddb/certs/UAC_CA-cacert.pem"
Thu Dec 11 14:59:10 2008 : Debug:       private_key_password = "UacCertificate07"
Thu Dec 11 14:59:10 2008 : Debug:       dh_file = "/usr/local/etc/raddb/certs/dh"
Thu Dec 11 14:59:10 2008 : Debug:       random_file = "/usr/local/etc/raddb/certs/random"
Thu Dec 11 14:59:10 2008 : Debug:       fragment_size = 1024
Thu Dec 11 14:59:10 2008 : Debug:       include_length = yes
Thu Dec 11 14:59:10 2008 : Debug:       check_crl = no
Thu Dec 11 14:59:10 2008 : Debug:       cipher_list = "DEFAULT"
Thu Dec 11 14:59:10 2008 : Debug:    }
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to sub-module rlm_eap_ttls
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating eap-ttls
Thu Dec 11 14:59:10 2008 : Debug:    ttls {
Thu Dec 11 14:59:10 2008 : Debug:       default_eap_type = "md5"
Thu Dec 11 14:59:10 2008 : Debug:       copy_request_to_tunnel = no
Thu Dec 11 14:59:10 2008 : Debug:       use_tunneled_reply = no
Thu Dec 11 14:59:10 2008 : Debug:       virtual_server = "inner-tunnel"
Thu Dec 11 14:59:10 2008 : Debug:    }
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to sub-module rlm_eap_peap
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating eap-peap
Thu Dec 11 14:59:10 2008 : Debug:    peap {
Thu Dec 11 14:59:10 2008 : Debug:       default_eap_type = "mschapv2"
Thu Dec 11 14:59:10 2008 : Debug:       copy_request_to_tunnel = no
Thu Dec 11 14:59:10 2008 : Debug:       use_tunneled_reply = no
Thu Dec 11 14:59:10 2008 : Debug:       proxy_tunneled_request_as_eap = yes
Thu Dec 11 14:59:10 2008 : Debug:       virtual_server = "inner-tunnel"
Thu Dec 11 14:59:10 2008 : Debug:    }
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to sub-module rlm_eap_mschapv2
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating eap-mschapv2
Thu DThu Dec 11 14:59:10 2008 : Debug:       with_ntdomain_hack = no
Thu Dec 11 14:59:10 2008 : Debug:    }
Thu Dec 11 14:59:10 2008 : Debug:  Module: Checking authorize {...} for more modules to load
Thu Dec 11 14:59:10 2008 : Debug:     (Loaded rlm_preprocess, checking if it's valid)
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to module rlm_preprocess
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating preprocess
Thu Dec 11 14:59:10 2008 : Debug:   preprocess {
Thu Dec 11 14:59:10 2008 : Debug:       huntgroups = "/usr/local/etc/raddb/huntgroups"
Thu Dec 11 14:59:10 2008 : Debug:       hints = "/usr/local/etc/raddb/hints"
Thu Dec 11 14:59:10 2008 : Debug:       with_ascend_hack = no
Thu Dec 11 14:59:10 2008 : Debug:       ascend_channels_per_line = 23
Thu Dec 11 14:59:10 2008 : Debug:       with_ntdomain_hack = no
Thu Dec 11 14:59:10 2008 : Debug:       with_specialix_jetstream_hack = no
Thu Dec 11 14:59:10 2008 : Debug:       with_cisco_vsa_hack = no
Thu Dec 11 14:59:10 2008 : Debug:       with_alvarion_vsa_hack = no
Thu Dec 11 14:59:10 2008 : Debug:   }
Thu Dec 11 14:59:10 2008 : Debug:     (Loaded rlm_realm, checking if it's valid)
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to module rlm_realm
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating suffix
Thu Dec 11 14:59:10 2008 : Debug:   realm suffix {
Thu Dec 11 14:59:10 2008 : Debug:       format = "suffix"
Thu Dec 11 14:59:10 2008 : Debug:       delimiter = "@"
Thu Dec 11 14:59:10 2008 : Debug:       ignore_default = no
Thu Dec 11 14:59:10 2008 : Debug:       ignore_null = no
Thu Dec 11 14:59:10 2008 : Debug:   }
Thu Dec 11 14:59:10 2008 : Debug:     (Loaded rlm_passwd, checking if it's valid)
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to module rlm_passwd
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating passwd
Thu Dec 11 14:59:10 2008 : Debug:   passwd passwd {
Thu Dec 11 14:59:10 2008 : Debug:       filename = "/etc/shadow"
Thu Dec 11 14:59:10 2008 : Debug:       format = "*=User-Name:MD5-Password"
Thu Dec 11 14:59:10 2008 : Debug:       delimiter = ":"
Thu Dec 11 14:59:10 2008 : Debug:       ignorenislike = yes
Thu Dec 11 14:59:10 2008 : Debug:       ignoreempty = yes
Thu Dec 11 14:59:10 2008 : Debug:       allowmultiplekeys = yes
Thu Dec 11 14:59:10 2008 : Debug:       hashsize = 50
Thu Dec 11 14:59:10 2008 : Debug:   }
Thu Dec 11 14:59:10 2008 : Debug: rlm_passwd: nfields: 2 keyfield 0(User-Name) listable: no
Thu Dec 11 14:59:10 2008 : Debug:  Module: Checking preacct {...} for more modules to load
Thu Dec 11 14:59:10 2008 : Debug:     (Loaded rlm_acct_unique, checking if it's valid)
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to module rlm_acct_unique
Thu Dec 11 14:59:10 2008 : Debug:    mschapv2 {
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating acct_unique
Thu Dec 11 14:59:10 2008 : Debug:   acct_unique {
Thu Dec 11 14:59:10 2008 : Debug:       key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"
Thu Dec 11 14:59:10 2008 : Debug:   }
Thu Dec 11 14:59:10 2008 : Debug:     (Loaded rlm_files, checking if it's valid)
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to module rlm_files
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating files
Thu Dec 11 14:59:10 2008 : Debug:   files {
Thu Dec 11 14:59:10 2008 : Debug:       usersfile = "/usr/local/etc/raddb/users"
Thu Dec 11 14:59:10 2008 : Debug:       acctusersfile = "/usr/local/etc/raddb/acct_users"
Thu Dec 11 14:59:10 2008 : Debug:       preproxy_usersfile = "/usr/local/etc/raddb/preproxy_users"
Thu Dec 11 14:59:10 2008 : Debug:       compat = "no"
Thu Dec 11 14:59:10 2008 : Debug:   }
Thu Dec 11 14:59:10 2008 : Debug:  Module: Checking accounting {...} for more modules to load
Thu Dec 11 14:59:10 2008 : Debug:     (Loaded rlm_detail, checking if it's valid)
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to module rlm_detail
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating detail
Thu Dec 11 14:59:10 2008 : Debug:   detail {
Thu Dec 11 14:59:10 2008 : Debug:       detailfile = "/usr/local/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
Thu Dec 11 14:59:10 2008 : Debug:       header = "%t"
Thu Dec 11 14:59:10 2008 : Debug:       detailperm = 384
Thu Dec 11 14:59:10 2008 : Debug:       dirperm = 493
Thu Dec 11 14:59:10 2008 : Debug:       locking = no
Thu Dec 11 14:59:10 2008 : Debug:       log_packet_header = no
Thu Dec 11 14:59:10 2008 : Debug:   }
Thu Dec 11 14:59:10 2008 : Debug:     (Loaded rlm_radutmp, checking if it's valid)
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to module rlm_radutmp
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating radutmp
Thu Dec 11 14:59:10 2008 : Debug:   radutmp {
Thu Dec 11 14:59:10 2008 : Debug:       filename = "/usr/local/var/log/radius/radutmp"
Thu Dec 11 14:59:10 2008 : Debug:       username = "%{User-Name}"
Thu Dec 11 14:59:10 2008 : Debug:       case_sensitive = yes
Thu Dec 11 14:59:10 2008 : Debug:       check_with_nas = yes
Thu Dec 11 14:59:10 2008 : Debug:       perm = 384
Thu Dec 11 14:59:10 2008 : Debug:       callerid = yes
Thu Dec 11 14:59:10 2008 : Debug:   }
Thu Dec 11 14:59:10 2008 : Debug:     (Loaded rlm_attr_filter, checking if it's valid)
Thu Dec 11 14:59:10 2008 : Debug:  Module: Linked to module rlm_attr_filter
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating attr_filter.accounting_response
Thu Dec 11 14:59:10 2008 : Debug:   attr_filter attr_filter.accounting_response {
Thu Dec 11 14:59:10 2008 : Debug:       attrsfile = "/usr/local/etc/raddb/attrs.accounting_response"
Thu Dec 11 14:59:10 2008 : Debug:       key = "%{User-Name}"
Thu Dec 11 14:59:10 2008 : Debug:   }
Thu Dec 11 14:59:10 2008 : Debug:  Module: Checking session {...} for more modules to load
Thu Dec 11 14:59:10 2008 : Debug:  Module: Checking post-proxy {...} for more modules to load
Thu Dec 11 14:59:10 2008 : Debug:  Module: Checking post-auth {...} for more modules to load
Thu Dec 11 14:59:10 2008 : Debug:  Module: Instantiating attr_filter.access_reject
Thu Dec 11 14:59:10 2008 : Debug:   attr_filter attr_filter.access_reject {
Thu Dec 11 14:59:10 2008 : Debug:       attrsfile = "/usr/local/etc/raddb/attrs.access_reject"
Thu Dec 11 14:59:10 2008 : Debug:       key = "%{User-Name}"
Thu Dec 11 14:59:10 2008 : Debug:   }
Thu Dec 11 14:59:10 2008 : Debug:  }
Thu Dec 11 14:59:10 2008 : Debug: }
Thu Dec 11 14:59:10 2008 : Debug: radiusd: #### Opening IP addresses and Ports ####
Thu Dec 11 14:59:10 2008 : Debug: listen {
Thu Dec 11 14:59:10 2008 : Debug:       type = "auth"
Thu Dec 11 14:59:10 2008 : Debug:       ipaddr = *
Thu Dec 11 14:59:10 2008 : Debug:       port = 0
Thu Dec 11 14:59:10 2008 : Debug: }
Thu Dec 11 14:59:10 2008 : Debug: listen {
Thu Dec 11 14:59:10 2008 : Debug:       type = "acct"
Thu Dec 11 14:59:10 2008 : Debug:       ipaddr = *
Thu Dec 11 14:59:10 2008 : Debug:       port = 0
Thu Dec 11 14:59:10 2008 : Debug: }
Thu Dec 11 14:59:10 2008 : Debug: Listening on authentication address * port 1812
Thu Dec 11 14:59:10 2008 : Debug: Listening on accounting address * port 1813
Thu Dec 11 14:59:10 2008 : Debug: Listening on proxy address * port 1814
Thu Dec 11 14:59:10 2008 : Debug: Ready to process requests.
rad_recv: Access-Request packet from host 172.21.1.251 port 1035, id=233, length=145
        User-Name = "toto@uac.bj"
        NAS-IP-Address = 172.21.1.251
        Connect-Info = "CONNECT 802.11"
        Called-Station-Id = "0060b33573b4"
        Calling-Station-Id = "000e35dfc4c9"
        NAS-Identifier = "ap"
        NAS-Port-Type = Wireless-802.11
        NAS-Port = 40
        NAS-Port-Id = "40"
        Framed-MTU = 1400
        EAP-Message = 0x0269001001746f746f407561632e626a
        Message-Authenticator = 0x4047d95682a4670d24da3c2fa434814e
Thu Dec 11 15:00:37 2008 : Debug: +- entering group authorize
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0
Thu Dec 11 15:00:37 2008 : Debug: ++[preprocess] returns ok
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling chap (rlm_chap) for request 0
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from chap (rlm_chap) for request 0
Thu Dec 11 15:00:37 2008 : Debug: ++[chap] returns noop
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling mschap (rlm_mschap) for request 0
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from mschap (rlm_mschap) for request 0
Thu Dec 11 15:00:37 2008 : Debug: ++[mschap] returns noop
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling digest (rlm_digest) for request 0
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from digest (rlm_digest) for request 0
Thu Dec 11 15:00:37 2008 : Debug: ++[digest] returns noop
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling suffix (rlm_realm) for request 0
Thu Dec 11 15:00:37 2008 : Debug:     rlm_realm: Looking up realm "uac.bj" for User-Name = "toto@uac.bj"
Thu Dec 11 15:00:37 2008 : Debug:     rlm_realm: Found realm "uac.bj"
Thu Dec 11 15:00:37 2008 : Debug:     rlm_realm: Adding Stripped-User-Name = "toto"
Thu Dec 11 15:00:37 2008 : Debug:     rlm_realm: Adding Realm = "uac.bj"
Thu Dec 11 15:00:37 2008 : Debug:     rlm_realm: Proxying request from user toto to realm uac.bj
Thu Dec 11 15:00:37 2008 : Debug:     rlm_realm: Preparing to proxy authentication request to realm "uac.bj"
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from suffix (rlm_realm) for request 0
Thu Dec 11 15:00:37 2008 : Debug: ++[suffix] returns updated
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling eap (rlm_eap) for request 0
Thu Dec 11 15:00:37 2008 : Debug:   rlm_eap: Request is supposed to be proxied to Realm uac.bj.  Not doing EAP.
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from eap (rlm_eap) for request 0
Thu Dec 11 15:00:37 2008 : Debug: ++[eap] returns noop
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling unix (rlm_unix) for request 0
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from unix (rlm_unix) for request 0
Thu Dec 11 15:00:37 2008 : Debug: ++[unix] returns updated
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling expiration (rlm_expiration) for request 0
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from expiration (rlm_expiration) for request 0
Thu Dec 11 15:00:37 2008 : Debug: ++[expiration] returns noop
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling logintime (rlm_logintime) for request 0
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from logintime (rlm_logintime) for request 0
Thu Dec 11 15:00:37 2008 : Debug: ++[logintime] returns noop
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling pap (rlm_pap) for request 0
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from pap (rlm_pap) for request 0
Thu Dec 11 15:00:37 2008 : Debug: ++[pap] returns noop
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling passwd (rlm_passwd) for request 0
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from passwd (rlm_passwd) for request 0
Thu Dec 11 15:00:37 2008 : Debug: ++[passwd] returns notfound
Thu Dec 11 15:00:37 2008 : Debug:  proxy: allocating destination 127.0.0.1 port 1812 - Id 200
Sending Access-Request of id 200 to 127.0.0.1 port 1812
        User-Name = "toto"
        NAS-IP-Address = 172.21.1.251
        Connect-Info = "CONNECT 802.11"
        Called-Station-Id = "0060b33573b4"
        Calling-Station-Id = "000e35dfc4c9"
        NAS-Identifier = "ap"
        NAS-Port-Type = Wireless-802.11
        NAS-Port = 40
        NAS-Port-Id = "40"
        Framed-MTU = 1400
        EAP-Message = 0x0269001001746f746f407561632e626a
        Message-Authenticator = 0x00000000000000000000000000000000
        Proxy-State = 0x323333
Thu Dec 11 15:00:37 2008 : Debug: Proxying request 0 to home server 127.0.0.1 port 1812
Sending Access-Request of id 200 to 127.0.0.1 port 1812
        User-Name = "toto"
        NAS-IP-Address = 172.21.1.251
        Connect-Info = "CONNECT 802.11"
        Called-Station-Id = "0060b33573b4"
        Calling-Station-Id = "000e35dfc4c9"
        NAS-Identifier = "ap"
        NAS-Port-Type = Wireless-802.11
        NAS-Port = 40
        NAS-Port-Id = "40"
        Framed-MTU = 1400
        EAP-Message = 0x0269001001746f746f407561632e626a
        Message-Authenticator = 0x00000000000000000000000000000000
        Proxy-State = 0x323333
Thu Dec 11 15:00:37 2008 : Debug: Going to the next request
Thu Dec 11 15:00:37 2008 : Debug: Waking up in 0.9 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 1814, id=200, length=143
        User-Name = "toto"
        NAS-IP-Address = 172.21.1.251
        Connect-Info = "CONNECT 802.11"
        Called-Station-Id = "0060b33573b4"
        Calling-Station-Id = "000e35dfc4c9"
        NAS-Identifier = "ap"
        NAS-Port-Type = Wireless-802.11
        NAS-Port = 40
        NAS-Port-Id = "40"
 Framed-MTU = 1400
        EAP-Message = 0x0269001001746f746f407561632e626a
        Message-Authenticator = 0x37c8e239d08fc96baa9a8711c785a234
        Proxy-State = 0x323333
Thu Dec 11 15:00:37 2008 : Debug: +- entering group authorize
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 1
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 1
Thu Dec 11 15:00:37 2008 : Debug: ++[preprocess] returns ok
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling chap (rlm_chap) for request 1
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from chap (rlm_chap) for request 1
Thu Dec 11 15:00:37 2008 : Debug: ++[chap] returns noop
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling mschap (rlm_mschap) for request 1
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from mschap (rlm_mschap) for request 1
Thu Dec 11 15:00:37 2008 : Debug: ++[mschap] returns noop
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling digest (rlm_digest) for request 1
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from digest (rlm_digest) for request 1
Thu Dec 11 15:00:37 2008 : Debug: ++[digest] returns noop
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling suffix (rlm_realm) for request 1
Thu Dec 11 15:00:37 2008 : Debug:     rlm_realm: No '@' in User-Name = "toto", looking up realm NULL
Thu Dec 11 15:00:37 2008 : Debug:     rlm_realm: No such realm "NULL"
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from suffix (rlm_realm) for request 1
Thu Dec 11 15:00:37 2008 : Debug: ++[suffix] returns noop
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling eap (rlm_eap) for request 1
Thu Dec 11 15:00:37 2008 : Debug:   rlm_eap: EAP packet type response id 105 length 16
Thu Dec 11 15:00:37 2008 : Debug:   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from eap (rlm_eap) for request 1
Thu Dec 11 15:00:37 2008 : Debug: ++[eap] returns updated
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling unix (rlm_unix) for request 1
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from unix (rlm_unix) for request 1
Thu Dec 11 15:00:37 2008 : Debug: ++[unix] returns updated
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling expiration (rlm_expiration) for request 1
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from expiration (rlm_expiration) for request 1
Thu Dec 11 15:00:37 2008 : Debug: ++[expiration] returns noop
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling logintime (rlm_logintime) for request 1
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from logintime (rlm_logintime) for request 1
Thu Dec 11 15:00:37 2008 : Debug: ++[logintime] returns noop
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling pap (rlm_pap) for request 1
Thu Dec 11 15:00:37 2008 : Debug: rlm_pap: Found existing Auth-Type, not changing it.
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from pap (rlm_pap) for request 1
Thu Dec 11 15:00:37 2008 : Debug: ++[pap] returns noop
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: calling passwd (rlm_passwd) for request 1
Thu Dec 11 15:00:37 2008 : Debug: rlm_passwd: Added MD5-Password: 'HsrtQesmWHodM:14211::::::' to config_items
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authorize]: returned from passwd (rlm_passwd) for request 1
Thu Dec 11 15:00:37 2008 : Debug: ++[passwd] returns ok
Thu Dec 11 15:00:37 2008 : Debug:   rad_check_password:  Found Auth-Type EAP
Thu Dec 11 15:00:37 2008 : Debug: auth: type "EAP"
Thu Dec 11 15:00:37 2008 : Debug: +- entering group authenticate
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authenticate]: calling eap (rlm_eap) for request 1
Thu Dec 11 15:00:37 2008 : Error: rlm_eap: Identity does not match User-Name, setting from EAP Identity.
Thu Dec 11 15:00:37 2008 : Debug:   rlm_eap: Failed in handler
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[authenticate]: returned from eap (rlm_eap) for request 1
Thu Dec 11 15:00:37 2008 : Debug: ++[eap] returns invalid
Thu Dec 11 15:00:37 2008 : Debug: auth: Failed to validate the user.
Thu Dec 11 15:00:37 2008 : Debug:   Found Post-Auth-Type Reject
Thu Dec 11 15:00:37 2008 : Debug: +- entering group REJECT
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) for request 1
Thu Dec 11 15:00:37 2008 : Debug:       expand: %{User-Name} -> toto
Thu Dec 11 15:00:37 2008 : Debug:  attr_filter: Matched entry DEFAULT at line 11
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) for reque
st 1
Thu Dec 11 15:00:37 2008 : Debug: ++[attr_filter.access_reject] returns updated
Sending Access-Reject of id 200 to 127.0.0.1 port 1814
        Proxy-State = 0x323333
Thu Dec 11 15:00:37 2008 : Debug: Finished request 1.
Thu Dec 11 15:00:37 2008 : Debug: Going to the next request
Thu Dec 11 15:00:37 2008 : Debug: Waking up in 0.9 seconds.
rad_recv: Access-Reject packet from host 127.0.0.1 port 1812, id=200, length=25
        Proxy-State = 0x323333
Thu Dec 11 15:00:37 2008 : Debug: +- entering group post-proxy
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[post-proxy]: calling eap (rlm_eap) for request 0
Thu Dec 11 15:00:37 2008 : Debug:   rlm_eap: No pre-existing handler found
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[post-proxy]: returned from eap (rlm_eap) for request 0
Thu Dec 11 15:00:37 2008 : Debug: ++[eap] returns noop
Thu Dec 11 15:00:37 2008 : Debug:   Found Post-Auth-Type Reject
Thu Dec 11 15:00:37 2008 : Debug: +- entering group REJECT
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) for request 0
Thu Dec 11 15:00:37 2008 : Debug:       expand: %{User-Name} -> toto@uac.bj
Thu Dec 11 15:00:37 2008 : Debug:  attr_filter: Matched entry DEFAULT at line 11
Thu Dec 11 15:00:37 2008 : Debug:   modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) for request 0
Thu Dec 11 15:00:37 2008 : Debug: ++[attr_filter.access_reject] returns updated
Sending Access-Reject of id 233 to 172.21.1.251 port 1035
Thu Dec 11 15:00:37 2008 : Debug: Finished request 0.
Thu Dec 11 15:00:37 2008 : Debug: Going to the next request
Thu Dec 11 15:00:37 2008 : Debug: Waking up in 4.9 seconds.
Thu Dec 11 15:00:42 2008 : Debug: Cleaning up request 1 ID 200 with timestamp +87
Thu Dec 11 15:00:42 2008 : Debug: Cleaning up request 0 ID 233 with timestamp +87
Thu Dec 11 15:00:42 2008 : Debug: Ready to process requests.

Is there something wrong in our configurations?
Is tit normal that there is no User-Password attribute in Access-Request packet?
Thanks very much to help us solve these problems.

Attou eric

Alan DeKok

tnt＠kalik.net

Jason Wittlin-Cohen

tags

participants (4)