EAP fails when proxying to a realm

28 Jun 2012


      I am trying to use MSCHAPv2 to authenticate users.  This works ok, except when I try to proxy to a realm.  Pasted below is the debug of a user trying to authenticate.  The realm is a prefix of the username.  What I see buried in the debug is:


# radiusd -X
FreeRADIUS Version 2.1.11, for host i686-pc-linux-gnu, built on Jun 28 2012 at 11:37:39
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/detail
including configuration file /etc/raddb/modules/opendirectory
including configuration file /etc/raddb/modules/unix
including configuration file /etc/raddb/modules/sradutmp
including configuration file /etc/raddb/modules/chap
including configuration file /etc/raddb/modules/dynamic_clients
including configuration file /etc/raddb/modules/ippool
including configuration file /etc/raddb/modules/realm
including configuration file /etc/raddb/modules/otp
including configuration file /etc/raddb/modules/mac2vlan
including configuration file /etc/raddb/modules/preprocess
including configuration file /etc/raddb/modules/expiration
including configuration file /etc/raddb/modules/smsotp
including configuration file /etc/raddb/modules/redis
including configuration file /etc/raddb/modules/policy
including configuration file /etc/raddb/modules/inner-eap
including configuration file /etc/raddb/modules/pam
including configuration file /etc/raddb/modules/mac2ip
including configuration file /etc/raddb/modules/detail.log
including configuration file /etc/raddb/modules/checkval
including configuration file /etc/raddb/modules/logintime
including configuration file /etc/raddb/modules/attr_filter
including configuration file /etc/raddb/modules/ntlm_auth
including configuration file /etc/raddb/modules/mschap
including configuration file /etc/raddb/modules/counter
including configuration file /etc/raddb/modules/cui
including configuration file /etc/raddb/modules/linelog
including configuration file /etc/raddb/modules/wimax
including configuration file /etc/raddb/modules/echo
including configuration file /etc/raddb/modules/rediswho
including configuration file /etc/raddb/modules/soh
including configuration file /etc/raddb/modules/attr_rewrite
including configuration file /etc/raddb/modules/passwd
including configuration file /etc/raddb/modules/krb5
including configuration file /etc/raddb/modules/ldap
including configuration file /etc/raddb/modules/sql_log
including configuration file /etc/raddb/modules/etc_group
including configuration file /etc/raddb/modules/radutmp
including configuration file /etc/raddb/modules/always
including configuration file /etc/raddb/modules/replicate
including configuration file /etc/raddb/modules/acct_unique
including configuration file /etc/raddb/modules/smbpasswd
including configuration file /etc/raddb/modules/pap
including configuration file /etc/raddb/modules/detail.example.com
including configuration file /etc/raddb/modules/perl
including configuration file /etc/raddb/modules/sqlcounter_expire_on_login
including configuration file /etc/raddb/modules/expr
including configuration file /etc/raddb/modules/digest
including configuration file /etc/raddb/modules/files
including configuration file /etc/raddb/modules/exec
including configuration file /etc/raddb/eap.conf
including configuration file /etc/raddb/sql.conf
including configuration file /etc/raddb/sql/mysql/dialup.conf
including configuration file /etc/raddb/policy.conf
including files in directory /etc/raddb/sites-enabled/
including configuration file /etc/raddb/sites-enabled/inner-tunnel
including configuration file /etc/raddb/sites-enabled/default
including configuration file /etc/raddb/sites-enabled/control-socket
main {
        allow_core_dumps = no
}
including dictionary file /etc/raddb/dictionary
main {
        name = "radiusd"
        prefix = "/usr"
        localstatedir = "/var"
        sbindir = "/usr/sbin"
        logdir = "/var/log/radius"
        run_dir = "/var/run/radiusd"
        libdir = "/usr/lib/freeradius"
        radacctdir = "/var/log/radius/radacct"
        hostname_lookups = no
        max_request_time = 30
        cleanup_delay = 5
        max_requests = 1024
        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+acct"
        secret = "t0werstream"
        response_window = 20
        max_outstanding = 65536
        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
 }
 
 realm myrealm {
        auth_pool = mypool
 }
 realm LOCAL {
 }
 home_server_pool my_auth_failover {
        type = fail-over
        home_server = localhost
 }
radiusd: #### Loading Clients ####
radiusd: #### Instantiating modules ####
 instantiate {
 Module: Linked to module rlm_exec
 Module: Instantiating module "exec" from file /etc/raddb/modules/exec
  exec {
        wait = no
        input_pairs = "request"
        shell_escape = yes
  }
 Module: Linked to module rlm_expr
 Module: Instantiating module "expr" from file /etc/raddb/modules/expr
 Module: Linked to module rlm_expiration
 Module: Instantiating module "expiration" from file /etc/raddb/modules/expiration
  expiration {
        reply-message = "Password Has Expired  "
  }
 Module: Linked to module rlm_logintime
 Module: Instantiating module "logintime" from file /etc/raddb/modules/logintime
  logintime {
        reply-message = "You are calling outside your allowed timespan  "
        minimum-timeout = 60
  }
 }
radiusd: #### Loading Virtual Servers ####
server { # from file /etc/raddb/radiusd.conf
 modules {
 Module: Checking authenticate {...} for more modules to load
 Module: Linked to module rlm_pap
 Module: Instantiating module "pap" from file /etc/raddb/modules/pap
  pap {
        encryption_scheme = "auto"
        auto_header = no
  }
 Module: Linked to module rlm_chap
 Module: Instantiating module "chap" from file /etc/raddb/modules/chap
 Module: Linked to module rlm_mschap
 Module: Instantiating module "mschap" from file /etc/raddb/modules/mschap
  mschap {
        use_mppe = yes
        require_encryption = no
        require_strong = no
        with_ntdomain_hack = no
        allow_retry = yes
  }
 Module: Linked to module rlm_digest
 Module: Instantiating module "digest" from file /etc/raddb/modules/digest
 Module: Linked to module rlm_unix
 Module: Instantiating module "unix" from file /etc/raddb/modules/unix
  unix {
        radwtmp = "/var/log/radius/radwtmp"
  }
 Module: Linked to module rlm_eap
 Module: Instantiating module "eap" from file /etc/raddb/eap.conf
  eap {
        default_eap_type = "md5"
        timer_expire = 60
        ignore_unknown_eap_types = no
        cisco_accounting_username_bug = no
        max_sessions = 4096
  }
 Module: Linked to sub-module rlm_eap_md5
 Module: Instantiating eap-md5
 Module: Linked to sub-module rlm_eap_leap
 Module: Instantiating eap-leap
 Module: Linked to sub-module rlm_eap_gtc
 Module: Instantiating eap-gtc
   gtc {
        challenge = "Password: "
        auth_type = "PAP"
   }
 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
        CA_path = "/etc/raddb/certs"
        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
    }
    verify {
    }
    ocsp {
        enable = no
        override_cert_url = yes
        url = "http://127.0.0.1/ocsp/"
    }
   }
 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: Linked to sub-module rlm_eap_peap
 Module: Instantiating eap-peap
   peap {
        default_eap_type = "mschapv2"
        copy_request_to_tunnel = no
        use_tunneled_reply = no
        proxy_tunneled_request_as_eap = yes
        virtual_server = "inner-tunnel"
        soh = no
   }
 Module: Linked to sub-module rlm_eap_mschapv2
 Module: Instantiating eap-mschapv2
   mschapv2 {
        with_ntdomain_hack = no
        send_error = no
   }
 Module: Checking authorize {...} for more modules to load
 Module: Linked to module rlm_preprocess
 Module: Instantiating module "preprocess" from file /etc/raddb/modules/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 module "auth_log" from file /etc/raddb/modules/detail.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 module "IPASS" from file /etc/raddb/modules/realm
  realm IPASS {
        format = "prefix"
        delimiter = "/"
        ignore_default = no
        ignore_null = no
  }
 Module: Linked to module rlm_files
 Module: Instantiating module "files" from file /etc/raddb/modules/files
  files {
        usersfile = "/etc/raddb/users"
        acctusersfile = "/etc/raddb/acct_users"
        preproxy_usersfile = "/etc/raddb/preproxy_users"
        compat = "no"
  }
 Module: Linked to module rlm_sql
 Module: Instantiating module "sql" from file /etc/raddb/sql.conf
  sql {
        driver = "rlm_sql_mysql"
        server = "localhost"
        port = ""
        login = "radius"
        password = "password"
        radius_db = "radiusdb"
        read_groups = yes
        sqltrace = no
        sqltracefile = "/var/log/radius/sqltrace.sql"
        readclients = yes
        deletestalesessions = yes
        num_sql_socks = 50
        lifetime = 0
        max_queries = 0
        sql_user_name = "%{User-Name}"
        default_user_profile = ""
        nas_query = "SELECT id, nasname, shortname, type, secret, server FROM nas"
        authorize_check_query = "SELECT id, username, attribute, value, op           FROM radcheck           WHERE username = '%{SQL-User-Name}'           ORDER BY id"
        authorize_reply_query = "SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '%{SQL-User-Name}'           ORDER BY id"
        authorize_group_check_query = "SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = '%{Sql-Group}'           ORDER BY id"
        authorize_group_reply_query = "SELECT id, groupname, attribute,           value, op           FROM radgroupreply           WHERE groupname = '%{Sql-Group}'           ORDER BY id"
        accounting_onoff_query = "          UPDATE radacct           SET              acctstoptime       =  '%S',              acctsessiontime    =  unix_timestamp('%S') -                                    unix_timestamp(acctstarttime),              acctterminatecause =  '%{Acct-Terminate-Cause}',              acctstopdelay      =  %{%{Acct-Delay-Time}:-0}           WHERE acctstoptime IS NULL           AND nasipaddress      =  '%{NAS-IP-Address}'           AND acctstarttime     <= '%S'"
        accounting_update_query = "           UPDATE radacct           SET              framedipaddress = '%{Framed-IP-Address}',              acctsessiontime     = '%{Acct-Session-Time}',              acctinputoctets     = '%{%{Acct-Input-Gigawords}:-0}'  << 32 |                                    '%{%{Acct-Input-Octets}:-0}',              acctoutputoctets    = '%{%{Acct-Output-Gigawords}:-0}' << 32 |                                    '%{%{Acct-Output-Octets}:-0}'           WHERE acctsessionid = '%{Acct-Session-Id}'           AND username        = '%{SQL-User-Name}'           AND nasipaddress    = '%{NAS-IP-Address}'"
        accounting_update_query_alt = "           INSERT INTO radacct             (acctsessionid,    acctuniqueid,      username,              realm,            nasipaddress,      nasportid,              nasporttype,      acctstarttime,     acctsessiontime,              acctauthentic,    connectinfo_start, acctinputoctets,              acctoutputoctets, calledstationid,   callingstationid,              servicetype,      framedprotocol,    framedipaddress,              acctstartdelay,   xascendsessionsvrkey)           VALUES             ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}',              '%{SQL-User-Name}',              '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}',              '%{NAS-Port-Type}',              DATE_SUB('%S',                       INTERVAL (%{%{Acct-Session-Time}:-0} +                                 %{%{Acct-Delay-Time}:-0}) SECOND),                       '%{Acct-Session-Time}',              '%{Acct-Authentic}', '',              '%{%{Acct-Input-Gigawords}:-0}' << 32 |              '%{%{Acct-Input-Octets}:-0}',              '%{%{Acct-Output-Gigawords}:-0}' << 32 |              '%{%{Acct-Output-Octets}:-0}',              '%{Called-Station-Id}', '%{Calling-Station-Id}',              '%{Service-Type}', '%{Framed-Protocol}',              '%{Framed-IP-Address}',              '0', '%{X-Ascend-Session-Svr-Key}')"
        accounting_start_query = "           INSERT INTO radacct             (acctsessionid,    acctuniqueid,     username,              realm,            nasipaddress,     nasportid,              nasporttype,      acctstarttime,    acctstoptime,              acctsessiontime,  acctauthentic,    connectinfo_start,              connectinfo_stop, acctinputoctets,  acctoutputoctets,              calledstationid,  callingstationid, acctterminatecause,              servicetype,      framedprotocol,   framedipaddress,              acctstartdelay,   acctstopdelay,    xascendsessionsvrkey)           VALUES             ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}',              '%{SQL-User-Name}',              '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}',              '%{NAS-Port-Type}', '%S', NULL,              '0', '%{Acct-Authentic}', '%{Connect-Info}',              '', '0', '0',              '%{Called-Station-Id}', '%{Calling-Station-Id}', '',              '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}',              '%{%{Acct-Delay-Time}:-0}', '0', '%{X-Ascend-Session-Svr-Key}')"
        accounting_start_query_alt = "           UPDATE radacct SET              acctstarttime     = '%S',              acctstartdelay    = '%{%{Acct-Delay-Time}:-0}',              connectinfo_start = '%{Connect-Info}'           WHERE acctsessionid  = '%{Acct-Session-Id}'           AND username         = '%{SQL-User-Name}'           AND nasipaddress     = '%{NAS-IP-Address}'"
        accounting_stop_query = "           UPDATE radacct SET              acctstoptime       = '%S',              acctsessiontime    = '%{Acct-Session-Time}',              acctinputoctets    = '%{%{Acct-Input-Gigawords}:-0}' << 32 |                                   '%{%{Acct-Input-Octets}:-0}',              acctoutputoctets   = '%{%{Acct-Output-Gigawords}:-0}' << 32 |                                   '%{%{Acct-Output-Octets}:-0}',              acctterminatecause = '%{Acct-Terminate-Cause}',              acctstopdelay      = '%{%{Acct-Delay-Time}:-0}',              connectinfo_stop   = '%{Connect-Info}'           WHERE acctsessionid   = '%{Acct-Session-Id}'           AND username          = '%{SQL-User-Name}'           AND nasipaddress      = '%{NAS-IP-Address}'"
        accounting_stop_query_alt = "           INSERT INTO radacct             (acctsessionid, acctuniqueid, username,              realm, nasipaddress, nasportid,              nasporttype, acctstarttime, acctstoptime,              acctsessiontime, acctauthentic, connectinfo_start,              connectinfo_stop, acctinputoctets, acctoutputoctets,              calledstationid, callingstationid, acctterminatecause,              servicetype, framedprotocol, framedipaddress,              acctstartdelay, acctstopdelay)           VALUES             ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}',              '%{SQL-User-Name}',              '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}',              '%{NAS-Port-Type}',              DATE_SUB('%S',                  INTERVAL (%{%{Acct-Session-Time}:-0} +                  %{%{Acct-Delay-Time}:-0}) SECOND),              '%S', '%{Acct-Session-Time}', '%{Acct-Authentic}', '',              '%{Connect-Info}',              '%{%{Acct-Input-Gigawords}:-0}' << 32 |              '%{%{Acct-Input-Octets}:-0}',              '%{%{Acct-Output-Gigawords}:-0}' << 32 |              '%{%{Acct-Output-Octets}:-0}',              '%{Called-Station-Id}', '%{Calling-Station-Id}',              '%{Acct-Terminate-Cause}',              '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}',              '0', '%{%{Acct-Delay-Time}:-0}')"
        group_membership_query = "SELECT groupname           FROM radusergroup           WHERE username = '%{SQL-User-Name}'           ORDER BY priority"
        connect_failure_retry_delay = 60
        simul_count_query = ""
        simul_verify_query = "SELECT radacctid, acctsessionid, username,                                nasipaddress, nasportid, framedipaddress,                                callingstationid, framedprotocol                                FROM radacct                                WHERE username = '%{SQL-User-Name}'                                AND acctstoptime IS NULL"
        postauth_query = "INSERT INTO radpostauth                           (username, pass, reply, authdate)                           VALUES (                           '%{User-Name}',                           '%{%{User-Password}:-%{Chap-Password}}',                           '%{reply:Packet-Type}', '%S')"
        safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
  }
rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked
rlm_sql (sql): Attempting to connect to radius@localhost:/radiusdb
rlm_sql (sql): starting 0
rlm_sql (sql): Attempting to connect rlm_sql_mysql #0
rlm_sql_mysql: Starting connect to MySQL server for #0
rlm_sql (sql): Connected new DB handle, #0
rlm_sql (sql): starting 1
rlm_sql (sql): Attempting to connect rlm_sql_mysql #1
rlm_sql_mysql: Starting connect to MySQL server for #1
rlm_sql (sql): Connected new DB handle, #1
rlm_sql (sql): starting 2
rlm_sql (sql): Attempting to connect rlm_sql_mysql #2
rlm_sql_mysql: Starting connect to MySQL server for #2
rlm_sql (sql): Connected new DB handle, #2
rlm_sql (sql): starting 3
rlm_sql (sql): Attempting to connect rlm_sql_mysql #3
rlm_sql_mysql: Starting connect to MySQL server for #3
rlm_sql (sql): Connected new DB handle, #3
rlm_sql (sql): starting 4
rlm_sql (sql): Attempting to connect rlm_sql_mysql #4
rlm_sql_mysql: Starting connect to MySQL server for #4
rlm_sql (sql): Connected new DB handle, #4
rlm_sql (sql): starting 5
rlm_sql (sql): Attempting to connect rlm_sql_mysql #5
rlm_sql_mysql: Starting connect to MySQL server for #5
rlm_sql (sql): Connected new DB handle, #5
rlm_sql (sql): starting 6
rlm_sql (sql): Attempting to connect rlm_sql_mysql #6
rlm_sql_mysql: Starting connect to MySQL server for #6
rlm_sql (sql): Connected new DB handle, #6
rlm_sql (sql): starting 7
rlm_sql (sql): Attempting to connect rlm_sql_mysql #7
rlm_sql_mysql: Starting connect to MySQL server for #7
rlm_sql (sql): Connected new DB handle, #7
rlm_sql (sql): starting 8
rlm_sql (sql): Attempting to connect rlm_sql_mysql #8
rlm_sql_mysql: Starting connect to MySQL server for #8
rlm_sql (sql): Connected new DB handle, #8
rlm_sql (sql): starting 9
rlm_sql (sql): Attempting to connect rlm_sql_mysql #9
rlm_sql_mysql: Starting connect to MySQL server for #9
rlm_sql (sql): Connected new DB handle, #9
rlm_sql (sql): starting 10
rlm_sql (sql): Attempting to connect rlm_sql_mysql #10
rlm_sql_mysql: Starting connect to MySQL server for #10
rlm_sql (sql): Connected new DB handle, #10
rlm_sql (sql): starting 11
rlm_sql (sql): Attempting to connect rlm_sql_mysql #11
rlm_sql_mysql: Starting connect to MySQL server for #11
rlm_sql (sql): Connected new DB handle, #11
rlm_sql (sql): starting 12
rlm_sql (sql): Attempting to connect rlm_sql_mysql #12
rlm_sql_mysql: Starting connect to MySQL server for #12
rlm_sql (sql): Connected new DB handle, #12
rlm_sql (sql): starting 13
rlm_sql (sql): Attempting to connect rlm_sql_mysql #13
rlm_sql_mysql: Starting connect to MySQL server for #13
rlm_sql (sql): Connected new DB handle, #13
rlm_sql (sql): starting 14
rlm_sql (sql): Attempting to connect rlm_sql_mysql #14
rlm_sql_mysql: Starting connect to MySQL server for #14
rlm_sql (sql): Connected new DB handle, #14
rlm_sql (sql): starting 15
rlm_sql (sql): Attempting to connect rlm_sql_mysql #15
rlm_sql_mysql: Starting connect to MySQL server for #15
rlm_sql (sql): Connected new DB handle, #15
rlm_sql (sql): starting 16
rlm_sql (sql): Attempting to connect rlm_sql_mysql #16
rlm_sql_mysql: Starting connect to MySQL server for #16
rlm_sql (sql): Connected new DB handle, #16
rlm_sql (sql): starting 17
rlm_sql (sql): Attempting to connect rlm_sql_mysql #17
rlm_sql_mysql: Starting connect to MySQL server for #17
rlm_sql (sql): Connected new DB handle, #17
rlm_sql (sql): starting 18
rlm_sql (sql): Attempting to connect rlm_sql_mysql #18
rlm_sql_mysql: Starting connect to MySQL server for #18
rlm_sql (sql): Connected new DB handle, #18
rlm_sql (sql): starting 19
rlm_sql (sql): Attempting to connect rlm_sql_mysql #19
rlm_sql_mysql: Starting connect to MySQL server for #19
rlm_sql (sql): Connected new DB handle, #19
rlm_sql (sql): starting 20
rlm_sql (sql): Attempting to connect rlm_sql_mysql #20
rlm_sql_mysql: Starting connect to MySQL server for #20
rlm_sql (sql): Connected new DB handle, #20
rlm_sql (sql): starting 21
rlm_sql (sql): Attempting to connect rlm_sql_mysql #21
rlm_sql_mysql: Starting connect to MySQL server for #21
rlm_sql (sql): Connected new DB handle, #21
rlm_sql (sql): starting 22
rlm_sql (sql): Attempting to connect rlm_sql_mysql #22
rlm_sql_mysql: Starting connect to MySQL server for #22
rlm_sql (sql): Connected new DB handle, #22
rlm_sql (sql): starting 23
rlm_sql (sql): Attempting to connect rlm_sql_mysql #23
rlm_sql_mysql: Starting connect to MySQL server for #23
rlm_sql (sql): Connected new DB handle, #23
rlm_sql (sql): starting 24
rlm_sql (sql): Attempting to connect rlm_sql_mysql #24
rlm_sql_mysql: Starting connect to MySQL server for #24
rlm_sql (sql): Connected new DB handle, #24
rlm_sql (sql): starting 25
rlm_sql (sql): Attempting to connect rlm_sql_mysql #25
rlm_sql_mysql: Starting connect to MySQL server for #25
rlm_sql (sql): Connected new DB handle, #25
rlm_sql (sql): starting 26
rlm_sql (sql): Attempting to connect rlm_sql_mysql #26
rlm_sql_mysql: Starting connect to MySQL server for #26
rlm_sql (sql): Connected new DB handle, #26
rlm_sql (sql): starting 27
rlm_sql (sql): Attempting to connect rlm_sql_mysql #27
rlm_sql_mysql: Starting connect to MySQL server for #27
rlm_sql (sql): Connected new DB handle, #27
rlm_sql (sql): starting 28
rlm_sql (sql): Attempting to connect rlm_sql_mysql #28
rlm_sql_mysql: Starting connect to MySQL server for #28
rlm_sql (sql): Connected new DB handle, #28
rlm_sql (sql): starting 29
rlm_sql (sql): Attempting to connect rlm_sql_mysql #29
rlm_sql_mysql: Starting connect to MySQL server for #29
rlm_sql (sql): Connected new DB handle, #29
rlm_sql (sql): starting 30
rlm_sql (sql): Attempting to connect rlm_sql_mysql #30
rlm_sql_mysql: Starting connect to MySQL server for #30
rlm_sql (sql): Connected new DB handle, #30
rlm_sql (sql): starting 31
rlm_sql (sql): Attempting to connect rlm_sql_mysql #31
rlm_sql_mysql: Starting connect to MySQL server for #31
rlm_sql (sql): Connected new DB handle, #31
rlm_sql (sql): starting 32
rlm_sql (sql): Attempting to connect rlm_sql_mysql #32
rlm_sql_mysql: Starting connect to MySQL server for #32
rlm_sql (sql): Connected new DB handle, #32
rlm_sql (sql): starting 33
rlm_sql (sql): Attempting to connect rlm_sql_mysql #33
rlm_sql_mysql: Starting connect to MySQL server for #33
rlm_sql (sql): Connected new DB handle, #33
rlm_sql (sql): starting 34
rlm_sql (sql): Attempting to connect rlm_sql_mysql #34
rlm_sql_mysql: Starting connect to MySQL server for #34
rlm_sql (sql): Connected new DB handle, #34
rlm_sql (sql): starting 35
rlm_sql (sql): Attempting to connect rlm_sql_mysql #35
rlm_sql_mysql: Starting connect to MySQL server for #35
rlm_sql (sql): Connected new DB handle, #35
rlm_sql (sql): starting 36
rlm_sql (sql): Attempting to connect rlm_sql_mysql #36
rlm_sql_mysql: Starting connect to MySQL server for #36
rlm_sql (sql): Connected new DB handle, #36
rlm_sql (sql): starting 37
rlm_sql (sql): Attempting to connect rlm_sql_mysql #37
rlm_sql_mysql: Starting connect to MySQL server for #37
rlm_sql (sql): Connected new DB handle, #37
rlm_sql (sql): starting 38
rlm_sql (sql): Attempting to connect rlm_sql_mysql #38
rlm_sql_mysql: Starting connect to MySQL server for #38
rlm_sql (sql): Connected new DB handle, #38
rlm_sql (sql): starting 39
rlm_sql (sql): Attempting to connect rlm_sql_mysql #39
rlm_sql_mysql: Starting connect to MySQL server for #39
rlm_sql (sql): Connected new DB handle, #39
rlm_sql (sql): starting 40
rlm_sql (sql): Attempting to connect rlm_sql_mysql #40
rlm_sql_mysql: Starting connect to MySQL server for #40
rlm_sql (sql): Connected new DB handle, #40
rlm_sql (sql): starting 41
rlm_sql (sql): Attempting to connect rlm_sql_mysql #41
rlm_sql_mysql: Starting connect to MySQL server for #41
rlm_sql (sql): Connected new DB handle, #41
rlm_sql (sql): starting 42
rlm_sql (sql): Attempting to connect rlm_sql_mysql #42
rlm_sql_mysql: Starting connect to MySQL server for #42
rlm_sql (sql): Connected new DB handle, #42
rlm_sql (sql): starting 43
rlm_sql (sql): Attempting to connect rlm_sql_mysql #43
rlm_sql_mysql: Starting connect to MySQL server for #43
rlm_sql (sql): Connected new DB handle, #43
rlm_sql (sql): starting 44
rlm_sql (sql): Attempting to connect rlm_sql_mysql #44
rlm_sql_mysql: Starting connect to MySQL server for #44
rlm_sql (sql): Connected new DB handle, #44
rlm_sql (sql): starting 45
rlm_sql (sql): Attempting to connect rlm_sql_mysql #45
rlm_sql_mysql: Starting connect to MySQL server for #45
rlm_sql (sql): Connected new DB handle, #45
rlm_sql (sql): starting 46
rlm_sql (sql): Attempting to connect rlm_sql_mysql #46
rlm_sql_mysql: Starting connect to MySQL server for #46
rlm_sql (sql): Connected new DB handle, #46
rlm_sql (sql): starting 47
rlm_sql (sql): Attempting to connect rlm_sql_mysql #47
rlm_sql_mysql: Starting connect to MySQL server for #47
rlm_sql (sql): Connected new DB handle, #47
rlm_sql (sql): starting 48
rlm_sql (sql): Attempting to connect rlm_sql_mysql #48
rlm_sql_mysql: Starting connect to MySQL server for #48
rlm_sql (sql): Connected new DB handle, #48
rlm_sql (sql): starting 49
rlm_sql (sql): Attempting to connect rlm_sql_mysql #49
rlm_sql_mysql: Starting connect to MySQL server for #49
rlm_sql (sql): Connected new DB handle, #49
rlm_sql (sql): Processing generate_sql_clients
rlm_sql (sql) in generate_sql_clients: query is SELECT id, nasname, shortname, type, secret, server FROM nas
rlm_sql (sql): Reserving sql socket id: 49
rlm_sql (sql): Read entry nasname=127.0.0.1,shortname=localhost,secret=secret
rlm_sql (sql): Adding client 127.0.0.1 (localhost, server=<none>) to clients list
rlm_sql (sql): Released sql socket id: 49
 Module: Checking preacct {...} for more modules to load
 Module: Linked to module rlm_acct_unique
 Module: Instantiating module "acct_unique" from file /etc/raddb/modules/acct_unique
  acct_unique {
        key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"
  }
 Module: Instantiating module "suffix" from file /etc/raddb/modules/realm
  realm suffix {
        format = "suffix"
        delimiter = "@"
        ignore_default = no
        ignore_null = no
  }
 Module: Checking accounting {...} for more modules to load
 Module: Instantiating module "detail" from file /etc/raddb/modules/detail
  detail {
        detailfile = "/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-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 module "radutmp" from file /etc/raddb/modules/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 module "attr_filter.accounting_response" from file /etc/raddb/modules/attr_filter
  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 module "reply_log" from file /etc/raddb/modules/detail.log
  detail reply_log {
        detailfile = "/var/log/radius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d"
        header = "%t"
        detailperm = 384
        dirperm = 493
        locking = no
        log_packet_header = no
  }
 Module: Instantiating module "attr_filter.access_reject" from file /etc/raddb/modules/attr_filter
  attr_filter attr_filter.access_reject {
        attrsfile = "/etc/raddb/attrs.access_reject"
        key = "%{User-Name}"
  }
 } # modules
} # server
server inner-tunnel { # from file /etc/raddb/sites-enabled/inner-tunnel
 modules {
 Module: Checking authenticate {...} for more modules to load
 Module: Checking authorize {...} for more modules to load
 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
 } # 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"
 }
}
listen {
        type = "auth"
        ipaddr = 127.0.0.1
        port = 18120
}
 ... adding new socket proxy address * port 41620
 ... adding new socket proxy address * port 46995
 ... adding new socket proxy address * port 43755
 ... adding new socket proxy address * port 35210
 ... adding new socket proxy address * port 53936
 ... adding new socket proxy address * port 60364
Listening on authentication address * port 1812
Listening on accounting address * port 1813
Listening on command file /var/run/radiusd/radiusd.sock
Listening on authentication address 127.0.0.1 port 18120 as server inner-tunnel
Listening on proxy address * port 1814
Ready to process requests.


rad_recv: Access-Request packet from host 69.38.220.74 port 33457, id=25, length=227
        User-Name = "myrealm/chris"
        Calling-Station-Id = "78-D6-F0-9B-62-97"
        NAS-IP-Address = 69.38.220.74
        NAS-Port = 1
        Called-Station-Id = "74-91-1A-63-49-58:My Wi-Fi"
        Service-Type = Framed-User
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        NAS-Identifier = "74-91-1A-63-49-58"
        Connect-Info = "CONNECT 802.11g/n"
        WISPr-Location-Name = "Lab"
        EAP-Message = 0x0200001101737072696e742f6368726973
        Vendor-25053-Attr-3 = 0x537072696e742057692d4669
        Message-Authenticator = 0x41f70f465513dc906b544110465b80ad
# Executing section authorize from file /etc/raddb/sites-enabled/default
+- 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/69.38.220.74/auth-detail-20120628
[auth_log] /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/69.38.220.74/auth-detail-20120628
[auth_log]      expand: %t -> Thu Jun 28 12:19:22 2012
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[IPASS] Looking up realm "myrealm" for User-Name = "myrealm/chris"
[IPASS] Found realm "myrealm"
[IPASS] Adding Stripped-User-Name = "chris"
[IPASS] Adding Realm = "myrealm"
[IPASS] Proxying request from user chris to realm myrealm
[IPASS] Preparing to proxy authentication request to realm "myrealm"
++[IPASS] returns updated
[eap] Request is supposed to be proxied to Realm myrealm.  Not doing EAP.
++[eap] returns noop
++[files] returns noop
[sql]   expand: %{User-Name} -> myrealm/chris
[sql] sql_set_user escaped user --> 'myrealm/chris'
rlm_sql (sql): Reserving sql socket id: 48
[sql]   expand: SELECT id, username, attribute, value, op           FROM radcheck           WHERE username = '%{SQL-User-Name}'           ORDER BY id -> SELECT id, username, attribute, value, op           FROM radcheck           WHERE username = 'myrealm/chris'           ORDER BY id
[sql]   expand: SELECT groupname           FROM radusergroup           WHERE username = '%{SQL-User-Name}'           ORDER BY priority -> SELECT groupname           FROM radusergroup           WHERE username = 'myrealm/chris'           ORDER BY priority
rlm_sql (sql): Released sql socket id: 48
[sql] User myrealm/chris not found
++[sql] returns notfound
++[expiration] returns noop
++[logintime] returns noop
++[pap] returns noop
  WARNING: Empty pre-proxy section.  Using default return values.
Sending Access-Request of id 22 to 127.0.0.1 port 1812
        User-Name = "chris"
        Calling-Station-Id = "78-D6-F0-9B-62-97"
        NAS-IP-Address = 1.1.1.1
        NAS-Port = 1
        Called-Station-Id = "74-91-1A-63-49-58:My Wi-Fi"
        Service-Type = Framed-User
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        NAS-Identifier = "74-91-1A-63-49-58"
        Connect-Info = "CONNECT 802.11g/n"
        WISPr-Location-Name = "Lab"
        EAP-Message = 0x0200001101737072696e742f6368726973
        Vendor-25053-Attr-3 = 0x537072696e742057692d4669
        Message-Authenticator = 0x00000000000000000000000000000000
        Proxy-State = 0x3235
Proxying request 0 to home server 127.0.0.1 port 1812
Sending Access-Request of id 22 to 127.0.0.1 port 1812
        User-Name = "chris"
        Calling-Station-Id = "78-D6-F0-9B-62-97"
        NAS-IP-Address = 1.1.1.1
        NAS-Port = 1
        Called-Station-Id = "74-91-1A-63-49-58:My Wi-Fi"
        Service-Type = Framed-User
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        NAS-Identifier = "74-91-1A-63-49-58"
        Connect-Info = "CONNECT 802.11g/n"
        WISPr-Location-Name = "Lab"
        EAP-Message = 0x0200001101737072696e742f6368726973
        Vendor-25053-Attr-3 = 0x537072696e742057692d4669
        Message-Authenticator = 0x00000000000000000000000000000000
        Proxy-State = 0x3235
Going to the next request
Waking up in 0.9 seconds.
rad_recv: Access-Request packet from host 127.0.0.1 port 1814, id=22, length=224
        User-Name = "chris"
        Calling-Station-Id = "78-D6-F0-9B-62-97"
        NAS-IP-Address = 1.1.1.1
        NAS-Port = 1
        Called-Station-Id = "74-91-1A-63-49-58:My Wi-Fi"
        Service-Type = Framed-User
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        NAS-Identifier = "74-91-1A-63-49-58"
        Connect-Info = "CONNECT 802.11g/n"
        WISPr-Location-Name = "Lab"
        EAP-Message = 0x0200001101737072696e742f6368726973
        Vendor-25053-Attr-3 = 0x537072696e742057692d4669
        Message-Authenticator = 0x89165f7b9f6f2901f98df17bc6ad51b1
        Proxy-State = 0x3235
# Executing section authorize from file /etc/raddb/sites-enabled/default
+- 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/127.0.0.1/auth-detail-20120628
[auth_log] /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/127.0.0.1/auth-detail-20120628
[auth_log]      expand: %t -> Thu Jun 28 12:19:22 2012
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[IPASS] No '/' in User-Name = "chris", looking up realm NULL
[IPASS] No such realm "NULL"
++[IPASS] returns noop
[eap] EAP packet type response id 0 length 17
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[files] returns noop
[sql]   expand: %{User-Name} -> chris
[sql] sql_set_user escaped user --> 'chris'
rlm_sql (sql): Reserving sql socket id: 47
[sql]   expand: SELECT id, username, attribute, value, op           FROM radcheck           WHERE username = '%{SQL-User-Name}'           ORDER BY id -> SELECT id, username, attribute, value, op           FROM radcheck           WHERE username = 'chris'           ORDER BY id
[sql]   expand: SELECT groupname           FROM radusergroup           WHERE username = '%{SQL-User-Name}'           ORDER BY priority -> SELECT groupname           FROM radusergroup           WHERE username = 'chris'           ORDER BY priority
rlm_sql (sql): Released sql socket id: 47
[sql] User chris not found
++[sql] returns notfound
++[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 = EAP
# Executing group from file /etc/raddb/sites-enabled/default
+- entering group authenticate {...}
[eap] Identity does not match User-Name, setting from EAP Identity.
[eap] Failed in handler
++[eap] returns invalid
Failed to authenticate the user.
Using Post-Auth-Type Reject
# Executing group from file /etc/raddb/sites-enabled/default
+- entering group REJECT {...}
[sql]   expand: %{User-Name} -> chris
[sql] sql_set_user escaped user --> 'chris'
[sql]   expand: %{User-Password} ->
[sql]   ... expanding second conditional
[sql]   expand: %{Chap-Password} ->
[sql]   expand: INSERT INTO radpostauth                           (username, pass, reply, authdate)                           VALUES (                           '%{User-Name}',                           '%{%{User-Password}:-%{Chap-Password}}',                           '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth                           (username, pass, reply, authdate)                           VALUES (                           'chris',                           '',                           'Access-Reject', '2012-06-28 12:19:22')
rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth                           (username, pass, reply, authdate)                           VALUES (                           'chris',                           '',                           'Access-Reject', '2012-06-28 12:19:22')
rlm_sql (sql): Reserving sql socket id: 46
rlm_sql (sql): Released sql socket id: 46
++[sql] returns ok
[attr_filter.access_reject]     expand: %{User-Name} -> chris
 attr_filter: Matched entry DEFAULT at line 11
++[attr_filter.access_reject] returns updated
Delaying reject of request 1 for 1 seconds
Going to the next request
Waking up in 0.9 seconds.
Sending delayed reject for request 1
Sending Access-Reject of id 22 to 127.0.0.1 port 1814
        Proxy-State = 0x3235
Waking up in 4.9 seconds.
rad_recv: Access-Reject packet from host 127.0.0.1 port 1812, id=22, length=24
        Proxy-State = 0x3235
# Executing section post-proxy from file /etc/raddb/sites-enabled/default
+- entering group post-proxy {...}
[eap] No pre-existing handler found
++[eap] returns noop
Using Post-Auth-Type Reject
# Executing group from file /etc/raddb/sites-enabled/default
+- entering group REJECT {...}
[sql]   expand: %{User-Name} -> myrealm/chris
[sql] sql_set_user escaped user --> 'myrealm/chris'
[sql]   expand: %{User-Password} ->
[sql]   ... expanding second conditional
[sql]   expand: %{Chap-Password} ->
[sql]   expand: INSERT INTO radpostauth                           (username, pass, reply, authdate)                           VALUES (                           '%{User-Name}',                           '%{%{User-Password}:-%{Chap-Password}}',                           '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth                           (username, pass, reply, authdate)                           VALUES (                           'myrealm/chris',                           '',                           'Access-Reject', '2012-06-28 12:19:22')
rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth                           (username, pass, reply, authdate)                           VALUES (                           'myrealm/chris',                           '',                           'Access-Reject', '2012-06-28 12:19:22')
rlm_sql (sql): Reserving sql socket id: 45
rlm_sql (sql): Released sql socket id: 45
++[sql] returns ok
[attr_filter.access_reject]     expand: %{User-Name} -> myrealm/chris
 attr_filter: Matched entry DEFAULT at line 11
++[attr_filter.access_reject] returns updated
Sending Access-Reject of id 25 to 69.38.220.74 port 33457
Finished request 0.
Going to the next request
Waking up in 4.9 seconds.
Cleaning up request 1 ID 22 with timestamp +7
Cleaning up request 0 ID 25 with timestamp +7
Ready to process requests.

Thanks,
Chris

EAP fails when proxying to a realm

Christopher Manigan