EAP problem
marco perugini
m.perugini at 4it.it
Wed Aug 1 03:14:48 CEST 2012
hi list!
i think we found same issue as david: something fails in eap-ttls. my
supplicant is a huawei wimax cpe [that obviously works great on my other
radius server but not the new one...]. we noticed some commit about ttls
so we built master branch from git in the afternoon but still we have
this problem; are we wrong about new eap-ttls configuration section? you
can find my "radiusd -Xxx" as attachment.
thanks folks,
marco
Il 28/07/12 23.25, Alan DeKok ha scritto:
> David Peterson wrote:
>> I am using an Alvarion WiMax CPE. The CPE works on my other radius server
>> just not the new one.
>
> I should have known.
>
> Can you at least run "radiusd -Xx" with the recent git "master" ?
> That will let us know exactly what is going on inside of the TTLS tunnel.
>
> That will allow us to fix the problem, too.
>
> Alan DeKok.
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
>
-------------- next part --------------
Tue Jul 31 19:28:40 2012 : Info: FreeRADIUS Version 3.0.0, for host x86_64-unknown-linux-gnu, built on Jul 31 2012 at 19:24:05
Tue Jul 31 19:28:40 2012 : Info: Copyright (C) 1999-2012 The FreeRADIUS server project and contributors.
Tue Jul 31 19:28:40 2012 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
Tue Jul 31 19:28:40 2012 : Info: PARTICULAR PURPOSE.
Tue Jul 31 19:28:40 2012 : Info: You may redistribute copies of FreeRADIUS under the terms of the
Tue Jul 31 19:28:40 2012 : Info: GNU General Public License v2.
Tue Jul 31 19:28:40 2012 : Info:
Tue Jul 31 19:28:40 2012 : Info: Starting - reading configuration files ...
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/radiusd.conf
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/proxy.conf
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/clients.conf
Tue Jul 31 19:28:40 2012 : Debug: including files in directory /etc/raddb/mods-enabled/
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/echo
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/inner-eap
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/utf8
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/dynamic_clients
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/checkval
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/attr_rewrite
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/ntlm_auth
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/radutmp
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/chap
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/attr_filter
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/counter
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/exec
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/linelog
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/expiration
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/eap
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/pap
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/detail.log
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/sradutmp
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/sql
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/sql/postgresql/dialup.conf
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/always
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/replicate
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/digest
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/wimax
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/expr
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/preprocess
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/mschap
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/acct_unique
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/realm
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/files
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/detail
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/passwd
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/logintime
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/perl
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/soh
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/cui
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/mods-enabled/unix
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/sql/postgresql/counter.conf
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/sqlippool.conf
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/sql/postgresql/ippool.conf
Tue Jul 31 19:28:40 2012 : Debug: including files in directory /etc/raddb/policy.d/
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/policy.d/dhcp
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/policy.d/control
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/policy.d/accounting
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/policy.d/canonicalization
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/policy.d/filter
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/policy.d/cui
Tue Jul 31 19:28:40 2012 : Debug: including files in directory /etc/raddb/sites-enabled/
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/sites-enabled/default
Tue Jul 31 19:28:40 2012 : Debug: including configuration file /etc/raddb/sites-enabled/inner-tunnel
Tue Jul 31 19:28:40 2012 : Debug: main {
Tue Jul 31 19:28:40 2012 : Debug: security {
Tue Jul 31 19:28:40 2012 : Debug: allow_core_dumps = no
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Error: /etc/raddb/radiusd.conf[0]: "allow_core_dumps" is deprecated. Please replace it with the up-to-date configuration
Tue Jul 31 19:28:40 2012 : Debug: allow_core_dumps = no
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: including dictionary file /etc/raddb/dictionary
Tue Jul 31 19:28:40 2012 : Debug: main {
Tue Jul 31 19:28:40 2012 : Debug: name = "radiusd"
Tue Jul 31 19:28:40 2012 : Debug: prefix = "/usr"
Tue Jul 31 19:28:40 2012 : Debug: localstatedir = "/var"
Tue Jul 31 19:28:40 2012 : Debug: sbindir = "/usr/sbin"
Tue Jul 31 19:28:40 2012 : Debug: logdir = "/var/log/radius"
Tue Jul 31 19:28:40 2012 : Debug: run_dir = "/var/run/radiusd"
Tue Jul 31 19:28:40 2012 : Debug: libdir = "/usr/lib"
Tue Jul 31 19:28:40 2012 : Debug: radacctdir = "/var/log/radius/radacct"
Tue Jul 31 19:28:40 2012 : Debug: hostname_lookups = no
Tue Jul 31 19:28:40 2012 : Debug: max_request_time = 30
Tue Jul 31 19:28:40 2012 : Debug: cleanup_delay = 5
Tue Jul 31 19:28:40 2012 : Debug: max_requests = 102400
Tue Jul 31 19:28:40 2012 : Debug: pidfile = "/var/run/radiusd/radiusd.pid"
Tue Jul 31 19:28:40 2012 : Debug: checkrad = "/usr/sbin/checkrad"
Tue Jul 31 19:28:40 2012 : Debug: debug_level = 0
Tue Jul 31 19:28:40 2012 : Debug: proxy_requests = yes
Tue Jul 31 19:28:40 2012 : Debug: log {
Tue Jul 31 19:28:40 2012 : Debug: stripped_names = no
Tue Jul 31 19:28:40 2012 : Debug: auth = yes
Tue Jul 31 19:28:40 2012 : Debug: auth_badpass = yes
Tue Jul 31 19:28:40 2012 : Debug: auth_goodpass = no
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: security {
Tue Jul 31 19:28:40 2012 : Debug: max_attributes = 200
Tue Jul 31 19:28:40 2012 : Debug: reject_delay = 1
Tue Jul 31 19:28:40 2012 : Debug: status_server = yes
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: radiusd: #### Loading Realms and Home Servers ####
Tue Jul 31 19:28:40 2012 : Debug: proxy server {
Tue Jul 31 19:28:40 2012 : Debug: retry_delay = 5
Tue Jul 31 19:28:40 2012 : Debug: retry_count = 3
Tue Jul 31 19:28:40 2012 : Debug: default_fallback = no
Tue Jul 31 19:28:40 2012 : Debug: dead_time = 120
Tue Jul 31 19:28:40 2012 : Debug: wake_all_if_all_dead = no
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: home_server localhost {
Tue Jul 31 19:28:40 2012 : Debug: ipaddr = 127.0.0.1
Tue Jul 31 19:28:40 2012 : Debug: port = 1812
Tue Jul 31 19:28:40 2012 : Debug: type = "auth"
Tue Jul 31 19:28:40 2012 : Debug: secret = "testing123"
Tue Jul 31 19:28:40 2012 : Debug: response_window = 20
Tue Jul 31 19:28:40 2012 : Debug: max_outstanding = 65536
Tue Jul 31 19:28:40 2012 : Debug: zombie_period = 40
Tue Jul 31 19:28:40 2012 : Debug: status_check = "status-server"
Tue Jul 31 19:28:40 2012 : Debug: ping_interval = 30
Tue Jul 31 19:28:40 2012 : Debug: check_interval = 30
Tue Jul 31 19:28:40 2012 : Debug: num_answers_to_alive = 3
Tue Jul 31 19:28:40 2012 : Debug: num_pings_to_alive = 3
Tue Jul 31 19:28:40 2012 : Debug: revive_interval = 120
Tue Jul 31 19:28:40 2012 : Debug: status_check_timeout = 4
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: home_server_pool my_auth_failover {
Tue Jul 31 19:28:40 2012 : Debug: type = fail-over
Tue Jul 31 19:28:40 2012 : Debug: home_server = localhost
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: realm example.com {
Tue Jul 31 19:28:40 2012 : Debug: auth_pool = my_auth_failover
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: realm LOCAL {
Tue Jul 31 19:28:40 2012 : Debug: nostrip
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: realm test.com {
Tue Jul 31 19:28:40 2012 : Debug: authhost = LOCAL
Tue Jul 31 19:28:40 2012 : Debug: accthost = LOCAL
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: realm NULL {
Tue Jul 31 19:28:40 2012 : Debug: authhost = LOCAL
Tue Jul 31 19:28:40 2012 : Debug: accthost = LOCAL
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: realm LOCAL {
Tue Jul 31 19:28:40 2012 : Debug: authhost = LOCAL
Tue Jul 31 19:28:40 2012 : Debug: accthost = LOCAL
Tue Jul 31 19:28:40 2012 : Debug: } # realm LOCAL
Tue Jul 31 19:28:40 2012 : Debug: radiusd: #### Loading Clients ####
Tue Jul 31 19:28:40 2012 : Debug: radiusd: #### Instantiating modules ####
Tue Jul 31 19:28:40 2012 : Debug: instantiate {
Tue Jul 31 19:28:40 2012 : Debug: (Loaded rlm_exec, checking if it's valid)
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to module rlm_exec
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating module "exec" from file /etc/raddb/mods-enabled/exec
Tue Jul 31 19:28:40 2012 : Debug: exec {
Tue Jul 31 19:28:40 2012 : Debug: wait = no
Tue Jul 31 19:28:40 2012 : Debug: input_pairs = "request"
Tue Jul 31 19:28:40 2012 : Debug: shell_escape = yes
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: (Loaded rlm_expr, checking if it's valid)
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to module rlm_expr
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating module "expr" from file /etc/raddb/mods-enabled/expr
Tue Jul 31 19:28:40 2012 : Debug: (Loaded rlm_expiration, checking if it's valid)
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to module rlm_expiration
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating module "expiration" from file /etc/raddb/mods-enabled/expiration
Tue Jul 31 19:28:40 2012 : Debug: expiration {
Tue Jul 31 19:28:40 2012 : Debug: reply-message = "Password Has Expired "
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: (Loaded rlm_logintime, checking if it's valid)
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to module rlm_logintime
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating module "logintime" from file /etc/raddb/mods-enabled/logintime
Tue Jul 31 19:28:40 2012 : Debug: logintime {
Tue Jul 31 19:28:40 2012 : Debug: reply-message = "You are calling outside your allowed timespan "
Tue Jul 31 19:28:40 2012 : Debug: minimum-timeout = 60
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: radiusd: #### Loading Virtual Servers ####
Tue Jul 31 19:28:40 2012 : Debug: server { # from file /etc/raddb/radiusd.conf
Tue Jul 31 19:28:40 2012 : Debug: modules {
Tue Jul 31 19:28:40 2012 : Debug: Module: Checking authenticate {...} for more modules to load
Tue Jul 31 19:28:40 2012 : Debug: (Loaded rlm_pap, checking if it's valid)
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to module rlm_pap
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating module "pap" from file /etc/raddb/mods-enabled/pap
Tue Jul 31 19:28:40 2012 : Debug: pap {
Tue Jul 31 19:28:40 2012 : Debug: encryption_scheme = "auto"
Tue Jul 31 19:28:40 2012 : Debug: auto_header = no
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: (Loaded rlm_chap, checking if it's valid)
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to module rlm_chap
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating module "chap" from file /etc/raddb/mods-enabled/chap
Tue Jul 31 19:28:40 2012 : Debug: (Loaded rlm_unix, checking if it's valid)
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to module rlm_unix
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating module "unix" from file /etc/raddb/mods-enabled/unix
Tue Jul 31 19:28:40 2012 : Debug: unix {
Tue Jul 31 19:28:40 2012 : Debug: radwtmp = "/var/log/radius/radwtmp"
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: (Loaded rlm_eap, checking if it's valid)
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to module rlm_eap
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating module "eap" from file /etc/raddb/mods-enabled/eap
Tue Jul 31 19:28:40 2012 : Debug: eap {
Tue Jul 31 19:28:40 2012 : Debug: default_eap_type = "ttls"
Tue Jul 31 19:28:40 2012 : Debug: timer_expire = 60
Tue Jul 31 19:28:40 2012 : Debug: ignore_unknown_eap_types = no
Tue Jul 31 19:28:40 2012 : Debug: cisco_accounting_username_bug = no
Tue Jul 31 19:28:40 2012 : Debug: max_sessions = 4096
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to sub-module rlm_eap_md5
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating eap-md5
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to sub-module rlm_eap_leap
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating eap-leap
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to sub-module rlm_eap_gtc
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating eap-gtc
Tue Jul 31 19:28:40 2012 : Debug: gtc {
Tue Jul 31 19:28:40 2012 : Debug: challenge = "Password: "
Tue Jul 31 19:28:40 2012 : Debug: auth_type = "PAP"
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to sub-module rlm_eap_tls
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating eap-tls
Tue Jul 31 19:28:40 2012 : Debug: tls {
Tue Jul 31 19:28:40 2012 : Debug: tls = "tls-common"
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: tls-config tls-common {
Tue Jul 31 19:28:40 2012 : Debug: rsa_key_exchange = no
Tue Jul 31 19:28:40 2012 : Debug: dh_key_exchange = yes
Tue Jul 31 19:28:40 2012 : Debug: rsa_key_length = 512
Tue Jul 31 19:28:40 2012 : Debug: dh_key_length = 512
Tue Jul 31 19:28:40 2012 : Debug: verify_depth = 0
Tue Jul 31 19:28:40 2012 : Debug: pem_file_type = yes
Tue Jul 31 19:28:40 2012 : Debug: private_key_password = "whatever"
Tue Jul 31 19:28:40 2012 : Debug: dh_file = "/etc/raddb/certs/dh"
Tue Jul 31 19:28:40 2012 : Debug: random_file = "/etc/raddb/certs/random"
Tue Jul 31 19:28:40 2012 : Debug: fragment_size = 1024
Tue Jul 31 19:28:40 2012 : Debug: include_length = yes
Tue Jul 31 19:28:40 2012 : Debug: check_crl = no
Tue Jul 31 19:28:40 2012 : Debug: cipher_list = "DEFAULT"
Tue Jul 31 19:28:40 2012 : Debug: make_cert_command = "/etc/raddb/certs/bootstrap"
Tue Jul 31 19:28:40 2012 : Debug: cache {
Tue Jul 31 19:28:40 2012 : Debug: enable = yes
Tue Jul 31 19:28:40 2012 : Debug: lifetime = 24
Tue Jul 31 19:28:40 2012 : Debug: max_entries = 255
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: verify {
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: ocsp {
Tue Jul 31 19:28:40 2012 : Debug: enable = no
Tue Jul 31 19:28:40 2012 : Debug: override_cert_url = yes
Tue Jul 31 19:28:40 2012 : Debug: url = "http://127.0.0.1/ocsp/"
Tue Jul 31 19:28:40 2012 : Debug: use_nonce = yes
Tue Jul 31 19:28:40 2012 : Debug: timeout = 0
Tue Jul 31 19:28:40 2012 : Debug: softfail = yes
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to sub-module rlm_eap_ttls
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating eap-ttls
Tue Jul 31 19:28:40 2012 : Debug: ttls {
Tue Jul 31 19:28:40 2012 : Debug: tls = "tls-common"
Tue Jul 31 19:28:40 2012 : Debug: default_eap_type = "mschapv2"
Tue Jul 31 19:28:40 2012 : Debug: copy_request_to_tunnel = yes
Tue Jul 31 19:28:40 2012 : Debug: use_tunneled_reply = yes
Tue Jul 31 19:28:40 2012 : Debug: virtual_server = "inner-tunnel"
Tue Jul 31 19:28:40 2012 : Debug: include_length = yes
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: debug: Using cached TLS configuration from previous invocation
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to sub-module rlm_eap_peap
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating eap-peap
Tue Jul 31 19:28:40 2012 : Debug: peap {
Tue Jul 31 19:28:40 2012 : Debug: tls = "tls-common"
Tue Jul 31 19:28:40 2012 : Debug: default_eap_type = "mschapv2"
Tue Jul 31 19:28:40 2012 : Debug: copy_request_to_tunnel = yes
Tue Jul 31 19:28:40 2012 : Debug: use_tunneled_reply = yes
Tue Jul 31 19:28:40 2012 : Debug: proxy_tunneled_request_as_eap = yes
Tue Jul 31 19:28:40 2012 : Debug: virtual_server = "inner-tunnel"
Tue Jul 31 19:28:40 2012 : Debug: soh = no
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: debug: Using cached TLS configuration from previous invocation
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to sub-module rlm_eap_mschapv2
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating eap-mschapv2
Tue Jul 31 19:28:40 2012 : Debug: mschapv2 {
Tue Jul 31 19:28:40 2012 : Debug: with_ntdomain_hack = no
Tue Jul 31 19:28:40 2012 : Debug: send_error = yes
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: Module: Checking authorize {...} for more modules to load
Tue Jul 31 19:28:40 2012 : Debug: (Loaded rlm_preprocess, checking if it's valid)
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to module rlm_preprocess
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating module "preprocess" from file /etc/raddb/mods-enabled/preprocess
Tue Jul 31 19:28:40 2012 : Debug: preprocess {
Tue Jul 31 19:28:40 2012 : Debug: huntgroups = "/etc/raddb/huntgroups"
Tue Jul 31 19:28:40 2012 : Debug: hints = "/etc/raddb/hints"
Tue Jul 31 19:28:40 2012 : Debug: with_ascend_hack = no
Tue Jul 31 19:28:40 2012 : Debug: ascend_channels_per_line = 23
Tue Jul 31 19:28:40 2012 : Debug: with_ntdomain_hack = no
Tue Jul 31 19:28:40 2012 : Debug: with_specialix_jetstream_hack = no
Tue Jul 31 19:28:40 2012 : Debug: with_cisco_vsa_hack = no
Tue Jul 31 19:28:40 2012 : Debug: with_alvarion_vsa_hack = no
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: (Loaded rlm_mschap, checking if it's valid)
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to module rlm_mschap
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating module "mschap" from file /etc/raddb/mods-enabled/mschap
Tue Jul 31 19:28:40 2012 : Debug: mschap {
Tue Jul 31 19:28:40 2012 : Debug: use_mppe = yes
Tue Jul 31 19:28:40 2012 : Debug: require_encryption = no
Tue Jul 31 19:28:40 2012 : Debug: require_strong = no
Tue Jul 31 19:28:40 2012 : Debug: with_ntdomain_hack = no
Tue Jul 31 19:28:40 2012 : Debug: passchange {
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: allow_retry = yes
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: (Loaded rlm_realm, checking if it's valid)
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to module rlm_realm
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating module "suffix" from file /etc/raddb/mods-enabled/realm
Tue Jul 31 19:28:40 2012 : Debug: realm suffix {
Tue Jul 31 19:28:40 2012 : Debug: format = "suffix"
Tue Jul 31 19:28:40 2012 : Debug: delimiter = "@"
Tue Jul 31 19:28:40 2012 : Debug: ignore_default = no
Tue Jul 31 19:28:40 2012 : Debug: ignore_null = no
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: (Loaded rlm_files, checking if it's valid)
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to module rlm_files
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating module "files" from file /etc/raddb/mods-enabled/files
Tue Jul 31 19:28:40 2012 : Debug: files {
Tue Jul 31 19:28:40 2012 : Debug: usersfile = "/etc/raddb/users"
Tue Jul 31 19:28:40 2012 : Debug: acctusersfile = "/etc/raddb/acct_users"
Tue Jul 31 19:28:40 2012 : Debug: preproxy_usersfile = "/etc/raddb/preproxy_users"
Tue Jul 31 19:28:40 2012 : Debug: compat = "no"
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: Module: Checking preacct {...} for more modules to load
Tue Jul 31 19:28:40 2012 : Debug: Module: Loading virtual module acct_unique
Tue Jul 31 19:28:40 2012 : Debug: Module: Checking accounting {...} for more modules to load
Tue Jul 31 19:28:40 2012 : Debug: (Loaded rlm_detail, checking if it's valid)
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to module rlm_detail
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating module "detail" from file /etc/raddb/mods-enabled/detail
Tue Jul 31 19:28:40 2012 : Debug: detail {
Tue Jul 31 19:28:40 2012 : Debug: detailfile = "/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d"
Tue Jul 31 19:28:40 2012 : Debug: header = "%t"
Tue Jul 31 19:28:40 2012 : Debug: detailperm = 384
Tue Jul 31 19:28:40 2012 : Debug: dirperm = 493
Tue Jul 31 19:28:40 2012 : Debug: locking = no
Tue Jul 31 19:28:40 2012 : Debug: log_packet_header = no
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: (Loaded rlm_radutmp, checking if it's valid)
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to module rlm_radutmp
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating module "radutmp" from file /etc/raddb/mods-enabled/radutmp
Tue Jul 31 19:28:40 2012 : Debug: radutmp {
Tue Jul 31 19:28:40 2012 : Debug: filename = "/var/log/radius/radutmp"
Tue Jul 31 19:28:40 2012 : Debug: username = "%{User-Name}"
Tue Jul 31 19:28:40 2012 : Debug: case_sensitive = yes
Tue Jul 31 19:28:40 2012 : Debug: check_with_nas = yes
Tue Jul 31 19:28:40 2012 : Debug: perm = 384
Tue Jul 31 19:28:40 2012 : Debug: callerid = yes
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: (Loaded rlm_sql, checking if it's valid)
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to module rlm_sql
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating module "sql" from file /etc/raddb/mods-enabled/sql
Tue Jul 31 19:28:40 2012 : Debug: sql {
Tue Jul 31 19:28:40 2012 : Debug: driver = "rlm_sql_postgresql"
Tue Jul 31 19:28:40 2012 : Debug: server = "172.20.22.30"
Tue Jul 31 19:28:40 2012 : Debug: port = "5432"
Tue Jul 31 19:28:40 2012 : Debug: login = "xxx"
Tue Jul 31 19:28:40 2012 : Debug: password = "xxx"
Tue Jul 31 19:28:40 2012 : Debug: radius_db = "xxx"
Tue Jul 31 19:28:40 2012 : Debug: read_groups = no
Tue Jul 31 19:28:40 2012 : Debug: readclients = yes
Tue Jul 31 19:28:40 2012 : Debug: deletestalesessions = yes
Tue Jul 31 19:28:40 2012 : Debug: sql_user_name = "%{%{Stripped-User-Name}:-%{%{User-Name}:-none}}"
Tue Jul 31 19:28:40 2012 : Debug: default_user_profile = ""
Tue Jul 31 19:28:40 2012 : Debug: nas_query = "SELECT s.id, host(s.ipaddr), s.shortname, s.nasclass, s.secret FROM radius_sources AS s INNER JOIN radius_layers AS lsrc ON s.layer=lsrc.id INNER JOIN radius_connections AS c ON c.src=lsrc.id INNER JOIN radius_layers AS ldst ON c.dst=ldst.id WHERE ldst.lname='Retelit-HAAA-Test-VM' ORDER BY s.id"
Tue Jul 31 19:28:40 2012 : Debug: authorize_check_query = "SELECT id, UserName, Attribute, Value, Op FROM rad_check_radius('%{outer.request:User-Name}') ORDER BY id"
Tue Jul 31 19:28:40 2012 : Debug: authorize_reply_query = "SELECT id,username,attribute,value,op FROM rad_reply_radius('%{outer.request:User-Name}', '%{NAS-Ip-Address}'::inet) ORDER BY id"
Tue Jul 31 19:28:40 2012 : Debug: authorize_group_check_query = ""
Tue Jul 31 19:28:40 2012 : Debug: authorize_group_reply_query = ""
Tue Jul 31 19:28:40 2012 : Debug: simul_count_query = ""
Tue Jul 31 19:28:40 2012 : Debug: simul_verify_query = ""
Tue Jul 31 19:28:40 2012 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: accounting {
Tue Jul 31 19:28:40 2012 : Debug: reference = "%{tolower:type.%{Acct-Status-Type}.query}"
Tue Jul 31 19:28:40 2012 : Debug: sqltrace = no
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: post-auth {
Tue Jul 31 19:28:40 2012 : Debug: reference = ".query"
Tue Jul 31 19:28:40 2012 : Debug: sqltrace = no
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Info: rlm_sql (sql): Driver rlm_sql_postgresql (module rlm_sql_postgresql) loaded and linked
Tue Jul 31 19:28:40 2012 : Info: rlm_sql (sql): Attempting to connect to radius at 172.20.22.30:5432/haaa
Tue Jul 31 19:28:40 2012 : Debug: rlm_sql (sql): Initialising connection pool
Tue Jul 31 19:28:40 2012 : Debug: rlm_sql (sql): Processing generate_sql_clients
Tue Jul 31 19:28:40 2012 : Debug: rlm_sql (sql) in generate_sql_clients: query is SELECT s.id, host(s.ipaddr), s.shortname, s.nasclass, s.secret FROM radius_sources AS s INNER JOIN radius_layers AS lsrc ON s.layer=lsrc.id INNER JOIN radius_connections AS c ON c.src=lsrc.id INNER JOIN radius_layers AS ldst ON c.dst=ldst.id WHERE ldst.lname='Retelit-HAAA-Test-VM' ORDER BY s.id
Tue Jul 31 19:28:40 2012 : Debug: rlm_sql (sql): Opening additional connection (0)
Tue Jul 31 19:28:40 2012 : Debug: No trigger subsection: ignoring trigger modules.sql.open
Tue Jul 31 19:28:40 2012 : Debug: rlm_sql (sql): Reserved connection (0)
Tue Jul 31 19:28:40 2012 : Error: rlm_sql (sql): Executing query
Tue Jul 31 19:28:40 2012 : Debug: rlm_sql_postgresql: Status: PGRES_TUPLES_OK
Tue Jul 31 19:28:40 2012 : Debug: rlm_sql_postgresql: query affected rows = 1 , fields = 5
Tue Jul 31 19:28:40 2012 : Debug: rlm_sql (sql): Read entry nasname=172.20.22.20,shortname=Proxy-Test-VM,secret=xxx
Tue Jul 31 19:28:40 2012 : Debug: rlm_sql (sql): Adding client 172.20.22.20 (Retelit-Proxy-Test-VM, server=<none>) to clients list
Tue Jul 31 19:28:40 2012 : Debug: rlm_sql (sql): Released connection (0)
Tue Jul 31 19:28:40 2012 : Debug: rlm_sql (sql): Closing idle connection (0): Too many free connections (1 > 0)
Tue Jul 31 19:28:40 2012 : Debug: rlm_sql (sql): Closing connection (0)
Tue Jul 31 19:28:40 2012 : Debug: No trigger subsection: ignoring trigger modules.sql.close
Tue Jul 31 19:28:40 2012 : Debug: (Loaded rlm_attr_filter, checking if it's valid)
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to module rlm_attr_filter
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating module "attr_filter.accounting_response" from file /etc/raddb/mods-enabled/attr_filter
Tue Jul 31 19:28:40 2012 : Debug: attr_filter attr_filter.accounting_response {
Tue Jul 31 19:28:40 2012 : Debug: attrsfile = "/etc/raddb/attrs.accounting_response"
Tue Jul 31 19:28:40 2012 : Debug: key = "%{User-Name}"
Tue Jul 31 19:28:40 2012 : Debug: relaxed = no
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: Module: Checking session {...} for more modules to load
Tue Jul 31 19:28:40 2012 : Debug: Module: Checking post-proxy {...} for more modules to load
Tue Jul 31 19:28:40 2012 : Debug: Module: Checking post-auth {...} for more modules to load
Tue Jul 31 19:28:40 2012 : Debug: (Loaded rlm_perl, checking if it's valid)
Tue Jul 31 19:28:40 2012 : Debug: Module: Linked to module rlm_perl
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating module "perl" from file /etc/raddb/mods-enabled/perl
Tue Jul 31 19:28:40 2012 : Debug: perl {
Tue Jul 31 19:28:40 2012 : Debug: module = "/etc/raddb/retelit.pl"
Tue Jul 31 19:28:40 2012 : Debug: func_authorize = "authorize"
Tue Jul 31 19:28:40 2012 : Debug: func_authenticate = "authenticate"
Tue Jul 31 19:28:40 2012 : Debug: func_accounting = "accounting"
Tue Jul 31 19:28:40 2012 : Debug: func_preacct = "preacct"
Tue Jul 31 19:28:40 2012 : Debug: func_checksimul = "checksimul"
Tue Jul 31 19:28:40 2012 : Debug: func_detach = "detach"
Tue Jul 31 19:28:40 2012 : Debug: func_xlat = "xlat"
Tue Jul 31 19:28:40 2012 : Debug: func_pre_proxy = "pre_proxy"
Tue Jul 31 19:28:40 2012 : Debug: func_post_proxy = "post_proxy"
Tue Jul 31 19:28:40 2012 : Debug: func_post_auth = "post_auth"
Tue Jul 31 19:28:40 2012 : Debug: func_recv_coa = "recv_coa"
Tue Jul 31 19:28:40 2012 : Debug: func_send_coa = "send_coa"
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: Module: Instantiating module "attr_filter.access_reject" from file /etc/raddb/mods-enabled/attr_filter
Tue Jul 31 19:28:40 2012 : Debug: attr_filter attr_filter.access_reject {
Tue Jul 31 19:28:40 2012 : Debug: attrsfile = "/etc/raddb/attrs.access_reject"
Tue Jul 31 19:28:40 2012 : Debug: key = "%{User-Name}"
Tue Jul 31 19:28:40 2012 : Debug: relaxed = no
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: } # modules
Tue Jul 31 19:28:40 2012 : Debug: } # server
Tue Jul 31 19:28:40 2012 : Debug: server inner-tunnel { # from file /etc/raddb/sites-enabled/inner-tunnel
Tue Jul 31 19:28:40 2012 : Debug: modules {
Tue Jul 31 19:28:40 2012 : Debug: Module: Checking authenticate {...} for more modules to load
Tue Jul 31 19:28:40 2012 : Debug: Module: Checking authorize {...} for more modules to load
Tue Jul 31 19:28:40 2012 : Debug: Module: Checking session {...} for more modules to load
Tue Jul 31 19:28:40 2012 : Debug: Module: Checking post-proxy {...} for more modules to load
Tue Jul 31 19:28:40 2012 : Debug: Module: Checking post-auth {...} for more modules to load
Tue Jul 31 19:28:40 2012 : Debug: } # modules
Tue Jul 31 19:28:40 2012 : Debug: } # server
Tue Jul 31 19:28:40 2012 : Debug: radiusd: #### Opening IP addresses and Ports ####
Tue Jul 31 19:28:40 2012 : Debug: listen {
Tue Jul 31 19:28:40 2012 : Debug: type = "auth"
Tue Jul 31 19:28:40 2012 : Debug: ipaddr = 172.20.22.10
Tue Jul 31 19:28:40 2012 : Debug: port = 0
Tue Jul 31 19:28:40 2012 : Debug: max_pps = 0
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: listen {
Tue Jul 31 19:28:40 2012 : Debug: type = "acct"
Tue Jul 31 19:28:40 2012 : Debug: ipaddr = 172.20.22.10
Tue Jul 31 19:28:40 2012 : Debug: port = 0
Tue Jul 31 19:28:40 2012 : Debug: max_pps = 0
Tue Jul 31 19:28:40 2012 : Debug: }
Tue Jul 31 19:28:40 2012 : Debug: Listening on authentication address 172.20.22.10 port 1812
Tue Jul 31 19:28:40 2012 : Debug: Listening on accounting address 172.20.22.10 port 1813
Tue Jul 31 19:28:40 2012 : Debug: Opening new proxy address 172.20.22.10 port 1814
Tue Jul 31 19:28:40 2012 : Debug: Listening on proxy address 172.20.22.10 port 1814
Tue Jul 31 19:28:40 2012 : Debug: No trigger subsection: ignoring trigger server.start
Tue Jul 31 19:28:40 2012 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 172.20.22.20 port 1814, id=85, length=246
NAS-Port-Type = Wireless-802.16
Service-Type = Framed-User
WiMAX-Available-In-Client = 99
WiMAX-BS-Id = 0x303030303230303630313031
WiMAX-Release = "1.1"
Message-Authenticator = 0x65a188b28be9125f4e7565fc1368279b
WiMAX-Accounting-Capabilities = Flow-Based
WiMAX-Hotlining-Capabilities = Hotline-Profile-Id
NAS-IP-Address = 192.168.98.201
Calling-Station-Id = "202bc168dc9d"
User-Name = "test_dhcp at test.com"
Event-Timestamp = "Jul 31 2012 19:29:23 CEST"
NAS-Identifier = "ITR_ASN-GW"
EAP-Message = 0x0223001701746573745f6468637040746573742e636f6d
WiMAX-GMT-Timezone-offset = 269352960
WiMAX-Idle-Mode-Notification-Cap = Supported
Proxy-State = 0x313938
Tue Jul 31 19:29:07 2012 : Info: (0) # Executing section authorize from file /etc/raddb/sites-enabled/default
Tue Jul 31 19:29:07 2012 : Info: (0) group authorize {
Tue Jul 31 19:29:07 2012 : Info: (0) - entering group authorize {...}
Tue Jul 31 19:29:07 2012 : Info: (0) [preprocess] = ok
Tue Jul 31 19:29:07 2012 : Info: (0) [chap] = noop
Tue Jul 31 19:29:07 2012 : Info: (0) [mschap] = noop
Tue Jul 31 19:29:07 2012 : Info: (0) suffix : Looking up realm "test.com" for User-Name = "test_dhcp at test.com"
Tue Jul 31 19:29:07 2012 : Info: (0) suffix : Found realm "test.com"
Tue Jul 31 19:29:07 2012 : Info: (0) suffix : Adding Stripped-User-Name = "test_dhcp"
Tue Jul 31 19:29:07 2012 : Info: (0) suffix : Adding Realm = "test.com"
Tue Jul 31 19:29:07 2012 : Info: (0) suffix : Authentication realm is LOCAL.
Tue Jul 31 19:29:07 2012 : Info: (0) [suffix] = ok
Tue Jul 31 19:29:07 2012 : Info: (0) eap : EAP packet type response id 35 length 23
Tue Jul 31 19:29:07 2012 : Info: (0) eap : EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize
Tue Jul 31 19:29:07 2012 : Info: (0) [eap] = ok
Tue Jul 31 19:29:07 2012 : Info: (0) Found Auth-Type = EAP
Tue Jul 31 19:29:07 2012 : Info: (0) # Executing group from file /etc/raddb/sites-enabled/default
Tue Jul 31 19:29:07 2012 : Info: (0) group authenticate {
Tue Jul 31 19:29:07 2012 : Info: (0) - entering group authenticate {...}
Tue Jul 31 19:29:07 2012 : Info: (0) eap : EAP Identity
Tue Jul 31 19:29:07 2012 : Info: (0) eap : processing type ttls
Tue Jul 31 19:29:07 2012 : Info: (0) ttls : Flushing SSL sessions (of #0)
Tue Jul 31 19:29:07 2012 : Info: (0) ttls : Initiate
Tue Jul 31 19:29:07 2012 : Info: (0) ttls : Start returned 1
Tue Jul 31 19:29:07 2012 : Info: (0) [eap] = handled
Sending Access-Challenge of id 85 to 172.20.22.20 port 1814
EAP-Message = 0x012400061520
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x89caa73889eeb23aa0dad48e28ea81e4
Proxy-State = 0x313938
Tue Jul 31 19:29:07 2012 : Info: (0) Finished request 0.
Tue Jul 31 19:29:07 2012 : Debug: Waking up in 0.3 seconds.
rad_recv: Access-Request packet from host 172.20.22.20 port 1814, id=88, length=327
NAS-Port-Type = Wireless-802.16
Service-Type = Framed-User
WiMAX-Available-In-Client = 99
WiMAX-BS-Id = 0x303030303230303630313031
WiMAX-Release = "1.1"
State = 0x89caa73889eeb23aa0dad48e28ea81e4
Message-Authenticator = 0xd8a258c8177394dbde42f4077196d4b8
WiMAX-Accounting-Capabilities = Flow-Based
WiMAX-Hotlining-Capabilities = Hotline-Profile-Id
NAS-IP-Address = 192.168.98.201
Calling-Station-Id = "202bc168dc9d"
User-Name = "test_dhcp at test.com"
Event-Timestamp = "Jul 31 2012 19:29:23 CEST"
NAS-Identifier = "ITR_ASN-GW"
EAP-Message = 0x0224005615800000004c160301004701000043030100001146d14d073568ee0ab3f1203131ed4c35b109c39068e20b0db558df75fb00001c002f0035000a000500040039003800160013003300320009001500120100
WiMAX-GMT-Timezone-offset = 269352960
WiMAX-Idle-Mode-Notification-Cap = Supported
Proxy-State = 0x323230
Tue Jul 31 19:29:08 2012 : Info: (1) # Executing section authorize from file /etc/raddb/sites-enabled/default
Tue Jul 31 19:29:08 2012 : Info: (1) group authorize {
Tue Jul 31 19:29:08 2012 : Info: (1) - entering group authorize {...}
Tue Jul 31 19:29:08 2012 : Info: (1) [preprocess] = ok
Tue Jul 31 19:29:08 2012 : Info: (1) [chap] = noop
Tue Jul 31 19:29:08 2012 : Info: (1) [mschap] = noop
Tue Jul 31 19:29:08 2012 : Info: (1) suffix : Looking up realm "test.com" for User-Name = "test_dhcp at test.com"
Tue Jul 31 19:29:08 2012 : Info: (1) suffix : Found realm "test.com"
Tue Jul 31 19:29:08 2012 : Info: (1) suffix : Adding Stripped-User-Name = "test_dhcp"
Tue Jul 31 19:29:08 2012 : Info: (1) suffix : Adding Realm = "test.com"
Tue Jul 31 19:29:08 2012 : Info: (1) suffix : Authentication realm is LOCAL.
Tue Jul 31 19:29:08 2012 : Info: (1) [suffix] = ok
Tue Jul 31 19:29:08 2012 : Info: (1) eap : EAP packet type response id 36 length 86
Tue Jul 31 19:29:08 2012 : Info: (1) eap : Continuing tunnel setup.
Tue Jul 31 19:29:08 2012 : Info: (1) [eap] = ok
Tue Jul 31 19:29:08 2012 : Info: (1) Found Auth-Type = EAP
Tue Jul 31 19:29:08 2012 : Info: (1) # Executing group from file /etc/raddb/sites-enabled/default
Tue Jul 31 19:29:08 2012 : Info: (1) group authenticate {
Tue Jul 31 19:29:08 2012 : Info: (1) - entering group authenticate {...}
Tue Jul 31 19:29:08 2012 : Info: (1) eap : Request found, released from the list
Tue Jul 31 19:29:08 2012 : Info: (1) eap : EAP/ttls
Tue Jul 31 19:29:08 2012 : Info: (1) eap : processing type ttls
Tue Jul 31 19:29:08 2012 : Info: (1) ttls : Authenticate
Tue Jul 31 19:29:08 2012 : Info: (1) ttls : processing EAP-TLS
Tue Jul 31 19:29:08 2012 : Debug: TLS Length 76
Tue Jul 31 19:29:08 2012 : Info: (1) ttls : Length Included
Tue Jul 31 19:29:08 2012 : Info: (1) ttls : eaptls_verify returned 11
Tue Jul 31 19:29:08 2012 : Info: (1) ttls : (other): before/accept initialization
Tue Jul 31 19:29:08 2012 : Info: (1) ttls : TLS_accept: before/accept initialization
Tue Jul 31 19:29:08 2012 : Info: (1) ttls : <<< TLS 1.0 Handshake [length 0047], ClientHello
Tue Jul 31 19:29:08 2012 : Info: (1) ttls : TLS_accept: SSLv3 read client hello A
Tue Jul 31 19:29:08 2012 : Info: (1) ttls : >>> TLS 1.0 Handshake [length 004a], ServerHello
Tue Jul 31 19:29:08 2012 : Info: (1) ttls : TLS_accept: SSLv3 write server hello A
Tue Jul 31 19:29:08 2012 : Info: (1) ttls : >>> TLS 1.0 Handshake [length 0a53], Certificate
Tue Jul 31 19:29:08 2012 : Info: (1) ttls : TLS_accept: SSLv3 write certificate A
Tue Jul 31 19:29:08 2012 : Info: (1) ttls : >>> TLS 1.0 Handshake [length 0004], ServerHelloDone
Tue Jul 31 19:29:08 2012 : Info: (1) ttls : TLS_accept: SSLv3 write server done A
Tue Jul 31 19:29:08 2012 : Info: (1) ttls : TLS_accept: SSLv3 flush data
Tue Jul 31 19:29:08 2012 : Info: (1) ttls : TLS_accept: Need to read more data: SSLv3 read client certificate A
Tue Jul 31 19:29:08 2012 : Debug: In SSL Handshake Phase
Tue Jul 31 19:29:08 2012 : Debug: In SSL Accept mode
Tue Jul 31 19:29:08 2012 : Info: (1) ttls : eaptls_process returned 13
Tue Jul 31 19:29:08 2012 : Info: (1) [eap] = handled
Sending Access-Challenge of id 88 to 172.20.22.20 port 1814
EAP-Message = 0x012503ec15c000000ab0160301004a020000460301501815e4c34d58048950fc411e8e84c38b1bdd40ba45f3a958e1225723656c4620b03ae42d8baea1394f9ce6c70496e1ae971067b777c4a61c0600c1f3a0771f79002f001603010a530b000a4f000a4c00054e3082054a30820432a003020102020101300d06092a864886f70d01010505003081ac310b3009060355040613024954310b3009060355040813024d49310f300d060355040713064d696c616e6f31173015060355040a130e526574656c697420532e702e412e311b3019060355040b1312526574656c6974204e6574776f726b696e67312830260603550403131f526574656c6974
EAP-Message = 0x2043657274696669636174696f6e20417574686f72697479311f301d06092a864886f70d010901161061646d696e40726574656c69742e6974301e170d3039303331363134323730395a170d3139303331343134323730395a3081a2310b3009060355040613024954310b3009060355040813024d49310f300d060355040713064d696c616e6f31173015060355040a130e526574656c697420532e702e412e311b3019060355040b1312526574656c6974204e6574776f726b696e67311e301c0603550403131563736e6c33312e63736e2e726574656c69742e6974311f301d06092a864886f70d010901161061646d696e40726574656c69742e69
EAP-Message = 0x7430820122300d06092a864886f70d01010105000382010f003082010a0282010100f1b783397e740af5228e340a80df90c8f161b1baf5984f5e0f5f54fc8795b0e065b07057e2ab483d2f71f2114854eaeed9aaa9c203a6636302d66162bd38724bffe3404cfa5fa21ae57ca359ad755ea1f56a3db387176d09208b7a4149ad6f668c8f579e376973b8372a9191aeca79c9dddbb2e15d3ac34d2acb317351ac3154799bc1c5675ee53ea75a1f2455edc369ce5bc75a41b9a84f386ffdb563d664157ea05961b78bbb8a62684260a394fd5db87d20baa9ee65965aba67b86ce9faf082cdc5ee838c0f1af7fbb6f7e14167c8496d6bd81f321664be8171
EAP-Message = 0xb9d5750d861fce6cbe5b7e89fc82ec0dd05f607e589de31868f24c4eaa5cfdb01e3e0fc6690203010001a382017d3082017930090603551d1304023000301106096086480186f8420101040403020640303406096086480186f842010d04271625456173792d5253412047656e65726174656420536572766572204365727469666963617465301d0603551d0e04160414e1d906bbe96bedf6f02ed11801a6933b1b25348c3081e10603551d230481d93081d68014f6840cec87e99637cb020d7495c9435bb0da72e9a181b2a481af3081ac310b3009060355040613024954310b3009060355040813024d49310f300d0603550407
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x89caa73888efb23aa0dad48e28ea81e4
Proxy-State = 0x323230
Tue Jul 31 19:29:08 2012 : Info: (1) Finished request 1.
Tue Jul 31 19:29:08 2012 : Debug: Waking up in 0.1 seconds.
rad_recv: Access-Request packet from host 172.20.22.20 port 1814, id=250, length=247
NAS-Port-Type = Wireless-802.16
Service-Type = Framed-User
WiMAX-Available-In-Client = 99
WiMAX-BS-Id = 0x303030303230303630313031
WiMAX-Release = "1.1"
State = 0x89caa73888efb23aa0dad48e28ea81e4
Message-Authenticator = 0xec6a9acb8061de62b5b597691b7bea09
WiMAX-Accounting-Capabilities = Flow-Based
WiMAX-Hotlining-Capabilities = Hotline-Profile-Id
NAS-IP-Address = 192.168.98.201
Calling-Station-Id = "202bc168dc9d"
User-Name = "test_dhcp at test.com"
Event-Timestamp = "Jul 31 2012 19:29:23 CEST"
NAS-Identifier = "ITR_ASN-GW"
EAP-Message = 0x022500061500
WiMAX-GMT-Timezone-offset = 269352960
WiMAX-Idle-Mode-Notification-Cap = Supported
Proxy-State = 0x323531
Tue Jul 31 19:29:08 2012 : Info: (2) # Executing section authorize from file /etc/raddb/sites-enabled/default
Tue Jul 31 19:29:08 2012 : Info: (2) group authorize {
Tue Jul 31 19:29:08 2012 : Info: (2) - entering group authorize {...}
Tue Jul 31 19:29:08 2012 : Info: (2) [preprocess] = ok
Tue Jul 31 19:29:08 2012 : Info: (2) [chap] = noop
Tue Jul 31 19:29:08 2012 : Info: (2) [mschap] = noop
Tue Jul 31 19:29:08 2012 : Info: (2) suffix : Looking up realm "test.com" for User-Name = "test_dhcp at test.com"
Tue Jul 31 19:29:08 2012 : Info: (2) suffix : Found realm "test.com"
Tue Jul 31 19:29:08 2012 : Info: (2) suffix : Adding Stripped-User-Name = "test_dhcp"
Tue Jul 31 19:29:08 2012 : Info: (2) suffix : Adding Realm = "test.com"
Tue Jul 31 19:29:08 2012 : Info: (2) suffix : Authentication realm is LOCAL.
Tue Jul 31 19:29:08 2012 : Info: (2) [suffix] = ok
Tue Jul 31 19:29:08 2012 : Info: (2) eap : EAP packet type response id 37 length 6
Tue Jul 31 19:29:08 2012 : Info: (2) eap : Continuing tunnel setup.
Tue Jul 31 19:29:08 2012 : Info: (2) [eap] = ok
Tue Jul 31 19:29:08 2012 : Info: (2) Found Auth-Type = EAP
Tue Jul 31 19:29:08 2012 : Info: (2) # Executing group from file /etc/raddb/sites-enabled/default
Tue Jul 31 19:29:08 2012 : Info: (2) group authenticate {
Tue Jul 31 19:29:08 2012 : Info: (2) - entering group authenticate {...}
Tue Jul 31 19:29:08 2012 : Info: (2) eap : Request found, released from the list
Tue Jul 31 19:29:08 2012 : Info: (2) eap : EAP/ttls
Tue Jul 31 19:29:08 2012 : Info: (2) eap : processing type ttls
Tue Jul 31 19:29:08 2012 : Info: (2) ttls : Authenticate
Tue Jul 31 19:29:08 2012 : Info: (2) ttls : processing EAP-TLS
Tue Jul 31 19:29:08 2012 : Info: (2) ttls : Received TLS ACK
Tue Jul 31 19:29:08 2012 : Info: (2) ttls : Received TLS ACK
Tue Jul 31 19:29:08 2012 : Info: (2) ttls : ACK handshake fragment handler
Tue Jul 31 19:29:08 2012 : Info: (2) ttls : eaptls_verify returned 1
Tue Jul 31 19:29:08 2012 : Info: (2) ttls : eaptls_process returned 13
Tue Jul 31 19:29:08 2012 : Info: (2) [eap] = handled
Sending Access-Challenge of id 250 to 172.20.22.20 port 1814
EAP-Message = 0x012603ec15c000000ab013064d696c616e6f31173015060355040a130e526574656c697420532e702e412e311b3019060355040b1312526574656c6974204e6574776f726b696e67312830260603550403131f526574656c69742043657274696669636174696f6e20417574686f72697479311f301d06092a864886f70d010901161061646d696e40726574656c69742e69748209009d1393ce43f4866330130603551d25040c300a06082b06010505070301300b0603551d0f0404030205a0300d06092a864886f70d010105050003820101000a3284106b517878ed608c9845f13db7cc78598772d16cfe8bf1d23272819dd64f79e61cc7c110e146
EAP-Message = 0xdfd5f63cc5b69e737a76d144d935d0bb0652bd3be9f4b6e419d128c1a8ad60e78cf9d238a48b520efc7c8e871c1059d1e88665401b8bae1ae7168543f3018ef425350a30dee047189e294e2205ca57a0ec1591ef92da9e312efd44feeabf4d8c1ffa92e8d7a507571b118ad060b3fb36117a0887e51821ed6f940e0e78dbaac7573e88bc9c18dd5eb0a16f41e35891b6d1d13fe136b7b5898560b321242137ed28fa79df88a89ba3ebf3277ffe8ce98ac8e26132da110bf1f67e47bd1f04b8d66a436fc998692ec40fa39b6e6c690450c5bfbe6617fa9e0004f8308204f4308203dca0030201020209009d1393ce43f48663300d06092a864886f70d01
EAP-Message = 0x010505003081ac310b3009060355040613024954310b3009060355040813024d49310f300d060355040713064d696c616e6f31173015060355040a130e526574656c697420532e702e412e311b3019060355040b1312526574656c6974204e6574776f726b696e67312830260603550403131f526574656c69742043657274696669636174696f6e20417574686f72697479311f301d06092a864886f70d010901161061646d696e40726574656c69742e6974301e170d3039303331363134323633325a170d3139303331343134323633325a3081ac310b3009060355040613024954310b3009060355040813024d49310f300d060355040713064d69
EAP-Message = 0x6c616e6f31173015060355040a130e526574656c697420532e702e412e311b3019060355040b1312526574656c6974204e6574776f726b696e67312830260603550403131f526574656c69742043657274696669636174696f6e20417574686f72697479311f301d06092a864886f70d010901161061646d696e40726574656c69742e697430820122300d06092a864886f70d01010105000382010f003082010a0282010100d49d4e9df67bf0340167476e7e73cace9b447a5811de6690b1a6210f4d6936b7a7611f23d00d22e46cf0713e3e899f41f0339ef521274d0324f258144a5575e3bc41c03167cf984824b060c23f850e
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x89caa7388becb23aa0dad48e28ea81e4
Proxy-State = 0x323531
Tue Jul 31 19:29:08 2012 : Info: (2) Finished request 2.
Tue Jul 31 19:29:08 2012 : Debug: Waking up in 0.1 seconds.
rad_recv: Access-Request packet from host 172.20.22.20 port 1814, id=186, length=246
NAS-Port-Type = Wireless-802.16
Service-Type = Framed-User
WiMAX-Available-In-Client = 99
WiMAX-BS-Id = 0x303030303230303630313031
WiMAX-Release = "1.1"
State = 0x89caa7388becb23aa0dad48e28ea81e4
Message-Authenticator = 0x5542518a84d9b5178e4fce76c9128ca6
WiMAX-Accounting-Capabilities = Flow-Based
WiMAX-Hotlining-Capabilities = Hotline-Profile-Id
NAS-IP-Address = 192.168.98.201
Calling-Station-Id = "202bc168dc9d"
User-Name = "test_dhcp at test.com"
Event-Timestamp = "Jul 31 2012 19:29:24 CEST"
NAS-Identifier = "ITR_ASN-GW"
EAP-Message = 0x022600061500
WiMAX-GMT-Timezone-offset = 269352960
WiMAX-Idle-Mode-Notification-Cap = Supported
Proxy-State = 0x3233
Tue Jul 31 19:29:08 2012 : Info: (3) # Executing section authorize from file /etc/raddb/sites-enabled/default
Tue Jul 31 19:29:08 2012 : Info: (3) group authorize {
Tue Jul 31 19:29:08 2012 : Info: (3) - entering group authorize {...}
Tue Jul 31 19:29:08 2012 : Info: (3) [preprocess] = ok
Tue Jul 31 19:29:08 2012 : Info: (3) [chap] = noop
Tue Jul 31 19:29:08 2012 : Info: (3) [mschap] = noop
Tue Jul 31 19:29:08 2012 : Info: (3) suffix : Looking up realm "test.com" for User-Name = "test_dhcp at test.com"
Tue Jul 31 19:29:08 2012 : Info: (3) suffix : Found realm "test.com"
Tue Jul 31 19:29:08 2012 : Info: (3) suffix : Adding Stripped-User-Name = "test_dhcp"
Tue Jul 31 19:29:08 2012 : Info: (3) suffix : Adding Realm = "test.com"
Tue Jul 31 19:29:08 2012 : Info: (3) suffix : Authentication realm is LOCAL.
Tue Jul 31 19:29:08 2012 : Info: (3) [suffix] = ok
Tue Jul 31 19:29:08 2012 : Info: (3) eap : EAP packet type response id 38 length 6
Tue Jul 31 19:29:08 2012 : Info: (3) eap : Continuing tunnel setup.
Tue Jul 31 19:29:08 2012 : Info: (3) [eap] = ok
Tue Jul 31 19:29:08 2012 : Info: (3) Found Auth-Type = EAP
Tue Jul 31 19:29:08 2012 : Info: (3) # Executing group from file /etc/raddb/sites-enabled/default
Tue Jul 31 19:29:08 2012 : Info: (3) group authenticate {
Tue Jul 31 19:29:08 2012 : Info: (3) - entering group authenticate {...}
Tue Jul 31 19:29:08 2012 : Info: (3) eap : Request found, released from the list
Tue Jul 31 19:29:08 2012 : Info: (3) eap : EAP/ttls
Tue Jul 31 19:29:08 2012 : Info: (3) eap : processing type ttls
Tue Jul 31 19:29:08 2012 : Info: (3) ttls : Authenticate
Tue Jul 31 19:29:08 2012 : Info: (3) ttls : processing EAP-TLS
Tue Jul 31 19:29:08 2012 : Info: (3) ttls : Received TLS ACK
Tue Jul 31 19:29:08 2012 : Info: (3) ttls : Received TLS ACK
Tue Jul 31 19:29:08 2012 : Info: (3) ttls : ACK handshake fragment handler
Tue Jul 31 19:29:08 2012 : Info: (3) ttls : eaptls_verify returned 1
Tue Jul 31 19:29:08 2012 : Info: (3) ttls : eaptls_process returned 13
Tue Jul 31 19:29:08 2012 : Info: (3) [eap] = handled
Sending Access-Challenge of id 186 to 172.20.22.20 port 1814
EAP-Message = 0x012702f6158000000ab06b3f7de87b74c45d6cd9b921aa2a49051a202170d89c4edf05d2f39a328548066fe9ce4aebe08494144cb7377f178f7b9862de098ea9cd7097d8677e72b7284c8298d7bde42d497acfb42ded6e6d533116289a93f3a0567a02ea696229e1191c1404f9f44060c0135013921517e42d4da4c212a0782be22ac96b37cc4fd8061d7eee00ddd5e5d9f793252d517f88257c53255b6dd0a7609d7b5011bd19fa5c7f7e88a676e2a11000af96391d54b670bd1d0203010001a382011530820111301d0603551d0e04160414f6840cec87e99637cb020d7495c9435bb0da72e93081e10603551d230481d93081d68014f6840cec87e9
EAP-Message = 0x9637cb020d7495c9435bb0da72e9a181b2a481af3081ac310b3009060355040613024954310b3009060355040813024d49310f300d060355040713064d696c616e6f31173015060355040a130e526574656c697420532e702e412e311b3019060355040b1312526574656c6974204e6574776f726b696e67312830260603550403131f526574656c69742043657274696669636174696f6e20417574686f72697479311f301d06092a864886f70d010901161061646d696e40726574656c69742e69748209009d1393ce43f48663300c0603551d13040530030101ff300d06092a864886f70d01010505000382010100c322a6c3f6e96dc1a6da4f6c54
EAP-Message = 0xec43da8d1d559ed4ce5d26a6cf9e3a7bc1b570d41ad3acc31d40b9c86222fb80b66d98155ac6540a378165e8c4f6631b952193c4c7439db504164307a04c2e8d2367f86ced03b034d71fc642e6ebaf26b0ded11e791a004a1585cdac763940d0230ba99208911ee97b452ab123756b3685389b3842b1dfd093636021dfa5da2098886d700bdc6718844fc84cff028aac3ce028fb36ce217d89e0d566ea1059b8f19a1dc800226de4e1bf17c7ef5379c9683fea7d6ba55b10a1b973dd4e0354fa5439ccdf8a0a04b39a61db4a5ed81e76ecd3b1c972ff07474330916a6d30d7f2934b9095eebb01a1fb4af79b369a92ea9b523c16030100040e000000
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x89caa7388aedb23aa0dad48e28ea81e4
Proxy-State = 0x3233
Tue Jul 31 19:29:08 2012 : Info: (3) Finished request 3.
Tue Jul 31 19:29:08 2012 : Debug: Waking up in 0.1 seconds.
Tue Jul 31 19:29:08 2012 : Debug: Waking up in 0.1 seconds.
Tue Jul 31 19:29:08 2012 : Debug: Waking up in 4.1 seconds.
rad_recv: Access-Request packet from host 172.20.22.20 port 1814, id=51, length=579
NAS-Port-Type = Wireless-802.16
Service-Type = Framed-User
WiMAX-Available-In-Client = 99
WiMAX-BS-Id = 0x303030303230303630313031
WiMAX-Release = "1.1"
State = 0x89caa7388aedb23aa0dad48e28ea81e4
Message-Authenticator = 0xd194ebbb6f9104d9050de9c2c9376532
WiMAX-Accounting-Capabilities = Flow-Based
WiMAX-Hotlining-Capabilities = Hotline-Profile-Id
NAS-IP-Address = 192.168.98.201
Calling-Station-Id = "202bc168dc9d"
User-Name = "test_dhcp at test.com"
Event-Timestamp = "Jul 31 2012 19:29:24 CEST"
NAS-Identifier = "ITR_ASN-GW"
EAP-Message = 0x0227015015800000014616030101061000010201000827cab6ec54a22506af4daeaf0249b3b711ce693668f2a7e1c9b29e7f0402b1f75bc4b6685eed4fc67afec0454d6ed5312bd6acf9acfc85dba4894f1a627580608385a98b8be656a7713437b223db8726c4ef3dd092ffb205f09594ca423945ffd614ee263bcd61231882726f445cc7f44e8125a966ced3e28cd52e5dc4a083798c2c61fdf6a8564e3c5bb8e4c1cd02e410094e80c44eefcf50ba56583b944b24ec72a87bd1f40a51f0a6496f152f4e92c27df95cddab4dc093477702e36c73e01341f7ba4ec439195abb7e62316241a26f5f8f516e0c3a9eebda28d6f23874127ad91dfabd0e90
EAP-Message = 0xf6a364e3e3892afd61233af199eac19bc72adc2d79b1efaf1403010001011603010030eb9c02a59b0dc4946061c789b261e8c32c9e222742b9065a690e05e1b6aaec2cc542d394032b769f494979c22ab5dbc7
WiMAX-GMT-Timezone-offset = 269352960
WiMAX-Idle-Mode-Notification-Cap = Supported
Proxy-State = 0x313036
Tue Jul 31 19:29:08 2012 : Info: (4) # Executing section authorize from file /etc/raddb/sites-enabled/default
Tue Jul 31 19:29:08 2012 : Info: (4) group authorize {
Tue Jul 31 19:29:08 2012 : Info: (4) - entering group authorize {...}
Tue Jul 31 19:29:08 2012 : Info: (4) [preprocess] = ok
Tue Jul 31 19:29:08 2012 : Info: (4) [chap] = noop
Tue Jul 31 19:29:08 2012 : Info: (4) [mschap] = noop
Tue Jul 31 19:29:08 2012 : Info: (4) suffix : Looking up realm "test.com" for User-Name = "test_dhcp at test.com"
Tue Jul 31 19:29:08 2012 : Info: (4) suffix : Found realm "test.com"
Tue Jul 31 19:29:08 2012 : Info: (4) suffix : Adding Stripped-User-Name = "test_dhcp"
Tue Jul 31 19:29:08 2012 : Info: (4) suffix : Adding Realm = "test.com"
Tue Jul 31 19:29:08 2012 : Info: (4) suffix : Authentication realm is LOCAL.
Tue Jul 31 19:29:08 2012 : Info: (4) [suffix] = ok
Tue Jul 31 19:29:08 2012 : Info: (4) eap : EAP packet type response id 39 length 253
Tue Jul 31 19:29:08 2012 : Info: (4) eap : Continuing tunnel setup.
Tue Jul 31 19:29:08 2012 : Info: (4) [eap] = ok
Tue Jul 31 19:29:08 2012 : Info: (4) Found Auth-Type = EAP
Tue Jul 31 19:29:08 2012 : Info: (4) # Executing group from file /etc/raddb/sites-enabled/default
Tue Jul 31 19:29:08 2012 : Info: (4) group authenticate {
Tue Jul 31 19:29:08 2012 : Info: (4) - entering group authenticate {...}
Tue Jul 31 19:29:08 2012 : Info: (4) eap : Request found, released from the list
Tue Jul 31 19:29:08 2012 : Info: (4) eap : EAP/ttls
Tue Jul 31 19:29:08 2012 : Info: (4) eap : processing type ttls
Tue Jul 31 19:29:08 2012 : Info: (4) ttls : Authenticate
Tue Jul 31 19:29:08 2012 : Info: (4) ttls : processing EAP-TLS
Tue Jul 31 19:29:08 2012 : Debug: TLS Length 326
Tue Jul 31 19:29:08 2012 : Info: (4) ttls : Length Included
Tue Jul 31 19:29:08 2012 : Info: (4) ttls : eaptls_verify returned 11
Tue Jul 31 19:29:08 2012 : Info: (4) ttls : <<< TLS 1.0 Handshake [length 0106], ClientKeyExchange
Tue Jul 31 19:29:08 2012 : Info: (4) ttls : TLS_accept: SSLv3 read client key exchange A
Tue Jul 31 19:29:08 2012 : Info: (4) ttls : <<< TLS 1.0 ChangeCipherSpec [length 0001]
Tue Jul 31 19:29:08 2012 : Info: (4) ttls : <<< TLS 1.0 Handshake [length 0010], Finished
Tue Jul 31 19:29:08 2012 : Info: (4) ttls : TLS_accept: SSLv3 read finished A
Tue Jul 31 19:29:08 2012 : Info: (4) ttls : >>> TLS 1.0 ChangeCipherSpec [length 0001]
Tue Jul 31 19:29:08 2012 : Info: (4) ttls : TLS_accept: SSLv3 write change cipher spec A
Tue Jul 31 19:29:08 2012 : Info: (4) ttls : >>> TLS 1.0 Handshake [length 0010], Finished
Tue Jul 31 19:29:08 2012 : Info: (4) ttls : TLS_accept: SSLv3 write finished A
Tue Jul 31 19:29:08 2012 : Info: (4) ttls : TLS_accept: SSLv3 flush data
Tue Jul 31 19:29:08 2012 : Debug: SSL: adding session b03ae42d8baea1394f9ce6c70496e1ae971067b777c4a61c0600c1f3a0771f79 to cache
Tue Jul 31 19:29:08 2012 : Info: (4) ttls : (other): SSL negotiation finished successfully
Tue Jul 31 19:29:08 2012 : Debug: SSL Connection Established
Tue Jul 31 19:29:08 2012 : Info: (4) ttls : eaptls_process returned 13
Tue Jul 31 19:29:08 2012 : Info: (4) [eap] = handled
Sending Access-Challenge of id 51 to 172.20.22.20 port 1814
EAP-Message = 0x0128004515800000003b14030100010116030100307578e00b4a606985dbc0ad4150c82f3d91a35bc7e856bdd8e4c3b78294e9e1840c6cfce7422342d30ee5e0a472e840a2
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x89caa7388de2b23aa0dad48e28ea81e4
Proxy-State = 0x313036
Tue Jul 31 19:29:08 2012 : Info: (4) Finished request 4.
Tue Jul 31 19:29:08 2012 : Debug: Waking up in 0.3 seconds.
rad_recv: Access-Request packet from host 172.20.22.20 port 1814, id=189, length=437
NAS-Port-Type = Wireless-802.16
Service-Type = Framed-User
WiMAX-Available-In-Client = 99
WiMAX-BS-Id = 0x303030303230303630313031
WiMAX-Release = "1.1"
State = 0x89caa7388de2b23aa0dad48e28ea81e4
Message-Authenticator = 0xaaffa657af4d14917a0ff54e48ebc08c
WiMAX-Accounting-Capabilities = Flow-Based
WiMAX-Hotlining-Capabilities = Hotline-Profile-Id
NAS-IP-Address = 192.168.98.201
Calling-Station-Id = "202bc168dc9d"
User-Name = "test_dhcp at test.com"
Event-Timestamp = "Jul 31 2012 19:29:24 CEST"
NAS-Identifier = "ITR_ASN-GW"
EAP-Message = 0x022800c41580000000ba1703010020a14d105ef00c3e93bd6c8c356199ff6ff0fd52f609d5bc35c6076ab7550fe6791703010090c3416b06c98d9a690baf85c852f8da16915df3845d0dd02bdaaace7b4b58c4764ada496293c2b968320226e5b0edde27976ea1f09eced7f4ae953526550e51c72875dc7f59918180a963e93c28a3ece33799535da047368cdbb845dde122211b32a95f5b750221eef00eac28556bb6381ca15be479bdaa152ca24a62d51ece0eba13c4971508947dbfb08746755c0043
WiMAX-GMT-Timezone-offset = 269352960
WiMAX-Idle-Mode-Notification-Cap = Supported
Proxy-State = 0x313439
Tue Jul 31 19:29:09 2012 : Info: (5) # Executing section authorize from file /etc/raddb/sites-enabled/default
Tue Jul 31 19:29:09 2012 : Info: (5) group authorize {
Tue Jul 31 19:29:09 2012 : Info: (5) - entering group authorize {...}
Tue Jul 31 19:29:09 2012 : Info: (5) [preprocess] = ok
Tue Jul 31 19:29:09 2012 : Info: (5) [chap] = noop
Tue Jul 31 19:29:09 2012 : Info: (5) [mschap] = noop
Tue Jul 31 19:29:09 2012 : Info: (5) suffix : Looking up realm "test.com" for User-Name = "test_dhcp at test.com"
Tue Jul 31 19:29:09 2012 : Info: (5) suffix : Found realm "test.com"
Tue Jul 31 19:29:09 2012 : Info: (5) suffix : Adding Stripped-User-Name = "test_dhcp"
Tue Jul 31 19:29:09 2012 : Info: (5) suffix : Adding Realm = "test.com"
Tue Jul 31 19:29:09 2012 : Info: (5) suffix : Authentication realm is LOCAL.
Tue Jul 31 19:29:09 2012 : Info: (5) [suffix] = ok
Tue Jul 31 19:29:09 2012 : Info: (5) eap : EAP packet type response id 40 length 196
Tue Jul 31 19:29:09 2012 : Info: (5) eap : Continuing tunnel setup.
Tue Jul 31 19:29:09 2012 : Info: (5) [eap] = ok
Tue Jul 31 19:29:09 2012 : Info: (5) Found Auth-Type = EAP
Tue Jul 31 19:29:09 2012 : Info: (5) # Executing group from file /etc/raddb/sites-enabled/default
Tue Jul 31 19:29:09 2012 : Info: (5) group authenticate {
Tue Jul 31 19:29:09 2012 : Info: (5) - entering group authenticate {...}
Tue Jul 31 19:29:09 2012 : Info: (5) eap : Request found, released from the list
Tue Jul 31 19:29:09 2012 : Info: (5) eap : EAP/ttls
Tue Jul 31 19:29:09 2012 : Info: (5) eap : processing type ttls
Tue Jul 31 19:29:09 2012 : Info: (5) ttls : Authenticate
Tue Jul 31 19:29:09 2012 : Info: (5) ttls : processing EAP-TLS
Tue Jul 31 19:29:09 2012 : Debug: TLS Length 186
Tue Jul 31 19:29:09 2012 : Info: (5) ttls : Length Included
Tue Jul 31 19:29:09 2012 : Info: (5) ttls : eaptls_verify returned 11
Tue Jul 31 19:29:09 2012 : Info: (5) ttls : eaptls_process returned 7
Tue Jul 31 19:29:09 2012 : Info: (5) ttls : Session established. Proceeding to decode tunneled attributes.
Tue Jul 31 19:29:09 2012 : Info: (5) ttls : Tunneled attribute 1 is too short (1 < 12) to contain anything useful.
Tue Jul 31 19:29:09 2012 : Debug: SSL: Removing session b03ae42d8baea1394f9ce6c70496e1ae971067b777c4a61c0600c1f3a0771f79 from the cache
Tue Jul 31 19:29:09 2012 : Info: (5) eap : Handler failed in EAP/ttls
Tue Jul 31 19:29:09 2012 : Info: (5) eap : Failed in EAP select
Tue Jul 31 19:29:09 2012 : Info: (5) [eap] = invalid
Tue Jul 31 19:29:09 2012 : Info: (5) Failed to authenticate the user.
Tue Jul 31 19:29:09 2012 : Auth: (5) Login incorrect: [test_dhcp at test.com/<via Auth-Type = EAP>] (from client Retelit-Proxy-Test-VM port 0 cli 202bc168dc9d)
Tue Jul 31 19:29:09 2012 : Info: (5) Using Post-Auth-Type Reject
Tue Jul 31 19:29:09 2012 : Info: (5) # Executing group from file /etc/raddb/sites-enabled/default
Tue Jul 31 19:29:09 2012 : Info: (5) group REJECT {
Tue Jul 31 19:29:09 2012 : Info: (5) - entering group REJECT {...}
Tue Jul 31 19:29:09 2012 : Info: (5) attr_filter.access_reject : expand: %{User-Name} -> test_dhcp at test.com
Tue Jul 31 19:29:09 2012 : Info: (5) attr_filter.access_reject : Matched entry DEFAULT at line 11
Tue Jul 31 19:29:09 2012 : Info: (5) [attr_filter.access_reject] = updated
Tue Jul 31 19:29:09 2012 : Info: (5) Finished request 5.
Tue Jul 31 19:29:09 2012 : Debug: Waking up in 0.2 seconds.
Tue Jul 31 19:29:09 2012 : Debug: Waking up in 0.6 seconds.
Tue Jul 31 19:29:10 2012 : Info: (5) Sending delayed reject
Sending Access-Reject of id 189 to 172.20.22.20 port 1814
EAP-Message = 0x04280004
Message-Authenticator = 0x00000000000000000000000000000000
Proxy-State = 0x313439
Tue Jul 31 19:29:10 2012 : Debug: Waking up in 2.8 seconds.
Tue Jul 31 19:29:12 2012 : Info: (0) Cleaning up request packet ID 85 with timestamp +27
Tue Jul 31 19:29:12 2012 : Debug: Waking up in 0.1 seconds.
Tue Jul 31 19:29:13 2012 : Info: (1) Cleaning up request packet ID 88 with timestamp +28
Tue Jul 31 19:29:13 2012 : Debug: Waking up in 0.1 seconds.
Tue Jul 31 19:29:13 2012 : Info: (2) Cleaning up request packet ID 250 with timestamp +28
Tue Jul 31 19:29:13 2012 : Debug: Waking up in 0.1 seconds.
Tue Jul 31 19:29:13 2012 : Info: (3) Cleaning up request packet ID 186 with timestamp +28
Tue Jul 31 19:29:13 2012 : Debug: Waking up in 0.4 seconds.
Tue Jul 31 19:29:13 2012 : Info: (4) Cleaning up request packet ID 51 with timestamp +28
Tue Jul 31 19:29:13 2012 : Debug: Waking up in 1.2 seconds.
Tue Jul 31 19:29:15 2012 : Info: (5) Cleaning up request packet ID 189 with timestamp +29
Tue Jul 31 19:29:15 2012 : Info: Ready to process requests.
More information about the Freeradius-Users
mailing list