Hello,
 
I am trying to authenticate using Freeradius different types of clients that include associates
(or employees), guest users, devices like printers and VOIP phones as well as mobile devices.
I have created a relocatable module (in C - my_module_auth) that parses the 802.1x string and looks up
in a database to determine what type user has sent this request. Note this module is not
thread-safe and I have built it with the "thread unsafe" flag. I am using a few global
variables which are protected by a mutex.

How is it supposed to work:

 If the user is an employee then the authentication is proxied
to the remote radius server that looks up an Active Directory.  The client sends an EAP-PEAP
request to the local Radius server which is then proxied to the remote radius server. If the
user is authenticated by the remote Radius server it sends and Access-Accept to the local
radius server. After the local radius server receives the Access-Accept it then looks up a local
database for the VLAN and appends the correct VLAN to the Access-Accept and sends it to the NAS.
The local radius server meanwhile is supposed to store the username/MAC and the time of authentication
in a local database. This information is used to authenticate an employee locally if somehow the
remote Radius server is offline or unreachable. For all other users, the authentication is done
by the local radius server.

Note that I have no control of the remote Radius server (attached to the Active Directory) but
I do have control of the setup local Radius server. I also do not have control over associate PCs
and the EAP protocol (here PEAP) that it uses for authentication.

The current setup:

All works fine for the good cases, i.e. when the remote Radius server is available. For the case
of the remote Radius server down, I have set it up to reject the incoming request once the
Freeradius detects that the remote Radius (or proxy) server is down. So if the remote
Radius server is down or not online the local Radius server would then try to send the request
to the remote server a few times and declares it dead if no response if received within a
certain period of time. It then sends a reject back to the client.

In order to authenticate the client in my relocatable module, instead of sending the reject
back to the client I force a challenge by returning RLM_MODULE_UPDATED. If, instead of challenge,
I had looked up the local cache and sent an accept back to the client the switch or NAS would not
open the port since it assumes that the other side is spoofed. Note this is the supposed behavior for
EAP-PEAP (I assume). Hence I have to force a challenge to be sent to the client to send another
Access-Request for which then I send an Access-Accept.

The problems with the above approach are that sometimes the switch would open up the port and
sometimes it doesn’t. Also, sometimes we see the local Radius server in the gateway gets into an
unknown state, e.g. we force a challenge when the Radius server thinks it should be a reject. In
other words, this method is unreliable.

In order not to make the Radius server go into an unknown state and the NAS to believe that the
Radius side is not spoofed, the remote radius failure scenario is implemented (currently) as follows.
In this case I am not forcing a challenge to be sent to the client - instead I have configured the
switch to send a MAC authentication request to the local Radius server instead of an EAP-PEAP request.
A MAC request does not need to go through the full challenge-response cycle and hence an
Access-Accept response can be sent immediately.

With a Cisco switch this sometimes works but the entire process of authentication may take somewhere
between 60 - 90 seconds. As a result the client PC may have timed out with the DHCP request. The
client can get an IP address when the DHCP lease is renewed manually or waits for the next
round of DHCP requests which could take as much as 5 minutes to get a DHCP request.

Unlike the Cisco NAS where 802.1x authentication is tried first and if that fails then
MAC authentication is attempted, the HP switches sends the 802.1x and MAC authentication requests
intermixed with no particular order. Also, we see that in HP switches the entire traffic may
stop because a reject is sent to the switch.

The questions I want to ask are as follows:

1. Is this the right method to perform this operation or there could be a simpler way to do this,
i.e. authenticate the request using backup cache or database when remote Radius server is down?

2. Is there a way to know (by ping or other methods) if the remote radius server is down so
that I can perform the local authentication right away when the 802.1x request is received
instead of proxying the request a few times and then determining that the remote proxy Radius server
is not alive or not available?

3. If somehow  I determine that the remote Radius server is unavailable and I get a 802.1x request
(EAP-PEAP) can I verify the authenticity of the request using the local cache and send an
Access-Accept somehow tricking the NAS to open the port?

4. Is it possible to reduce the time for e.g. "Waking up in 119.8 seconds"?

Note, I have tried different settings in the proxy.conf but did not get satisfactiry results.
 
Any help will be greatly appreciated.

Thanks,

Jyoti.

Here's the log:

FreeRADIUS Version 2.1.9, for host i686-pc-linux-gnu, built on Aug 26 2010 at 00:17:16
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 ./radiusd.conf
including configuration file ./proxy.conf
including configuration file ./proxy_realm.conf
including configuration file ./clients.conf
including files in directory ./modules/
including configuration file ./modules/always
including configuration file ./modules/expr
including configuration file ./modules/example
including configuration file ./modules/echo
including configuration file ./modules/mac2vlan
including configuration file ./modules/sradutmp
including configuration file ./modules/wimax
including configuration file ./modules/cui
including configuration file ./modules/counter
including configuration file ./modules/ldap
including configuration file ./modules/smsotp
including configuration file ./modules/attr_filter
including configuration file ./modules/checkval
including configuration file ./modules/ntlm_auth
including configuration file ./modules/krb5
including configuration file ./modules/mac2ip
including configuration file ./modules/smbpasswd
including configuration file ./modules/otp
including configuration file ./modules/realm
including configuration file ./modules/passwd
including configuration file ./modules/attr_rewrite
including configuration file ./modules/etc_group
including configuration file ./modules/files
including configuration file ./modules/sql_log
including configuration file ./modules/chap
including configuration file ./modules/mschap
including configuration file ./modules/my_module_auth
including configuration file ./modules/radutmp
including configuration file ./modules/linelog
including configuration file ./modules/pam
including configuration file ./modules/detail
including configuration file ./modules/logintime
including configuration file ./modules/pap
including configuration file ./modules/digest
including configuration file ./modules/unix
including configuration file ./modules/ippool
including configuration file ./modules/perl
including configuration file ./modules/detail.example.com
including configuration file ./modules/sqlcounter_expire_on_login
including configuration file ./modules/acct_unique
including configuration file ./modules/expiration
including configuration file ./modules/preprocess
including configuration file ./modules/exec
including configuration file ./modules/inner-eap
including configuration file ./modules/policy
including configuration file ./modules/detail.log
including configuration file ./eap.conf
including configuration file ./sql.conf
including configuration file ./policy.conf
including files in directory ./sites-enabled/
including configuration file ./sites-enabled/control-socket
including configuration file ./sites-enabled/inner-tunnel
including configuration file ./sites-available/default
main {
 allow_core_dumps = no
}
including dictionary file ./dictionary
main {
 prefix = "/root/freeradius-2.1.9"
 localstatedir = "/root/freeradius-2.1.9/var"
 logdir = "/var/log/radius"
 libdir = "/root/freeradius-2.1.9/lib"
 radacctdir = "/var/log/radius/radacct"
 hostname_lookups = no
 max_request_time = 30
 cleanup_delay = 5
 max_requests = 1024
 pidfile = "/root/freeradius-2.1.9/var/run/radiusd/radiusd.pid"
 checkrad = "/root/freeradius-2.1.9/sbin/checkrad"
 debug_level = 0
 proxy_requests = yes
 log {
 stripped_names = yes
 auth = no
 auth_badpass = no
 auth_goodpass = no
 }
 security {
 max_attributes = 200
 reject_delay = 0
 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
 }
 realm LOCAL {
 authhost = LOCAL
 accthost = LOCAL
 }
 realm NULL {
 }
 realm DEFAULT {
 authhost = LOCAL
 accthost = LOCAL
 }
 realm remote_proxy_ad {
 authhost = xxx.xxx.158.50:1812
 accthost = xxx.xxx.158.50:1813
 secret = xxxxxxx
 }
 realm server2 {
 authhost = xxx.xxx.222.172:1812
 accthost = xxx.xxx.222.172:1813
 secret = Secret
 }
 home_server localhost {
 ipaddr = 127.0.0.1
 port = 1812
 type = "auth"
 secret = "testing123"
 response_window = 10
 no_response_fail = yes
 max_outstanding = 65536
 require_message_authenticator = no
 zombie_period = 10
 status_check = "status-server"
 ping_interval = 30
 check_interval = 15
 num_answers_to_alive = 3
 num_pings_to_alive = 3
 revive_interval = 300
 status_check_timeout = 4
 irt = 2
 mrt = 16
 mrc = 5
 mrd = 30
 }
 home_server_pool my_auth_failover {
 type = fail-over
 home_server = localhost
 }
radiusd: #### Loading Clients ####
 client localhost {
 ipaddr = 127.0.0.1
 require_message_authenticator = no
 secret = "xxxxxxx"
 shortname = "localhost"
 nastype = "other"
 }
 client xx.xx.35.130 {
 require_message_authenticator = no
 secret = "xxxxxxx"
 shortname = "dot1x"
 }
 client xx.xx.35.129 {
 require_message_authenticator = no
 secret = "xxxxxxx"
 shortname = "dot1x"
 }
 client xx.xx.35.140 {
 require_message_authenticator = no
 secret = "xxxxxxx"
 shortname = "wap"
 }
radiusd: #### Instantiating modules ####
 instantiate {
 Module: Linked to module rlm_exec
 Module: Instantiating exec
  exec {
 wait = no
 input_pairs = "request"
 shell_escape = yes
  }
 Module: Linked to module rlm_expr
 Module: Instantiating expr
 Module: Linked to module rlm_sql
 Module: Instantiating sql
  sql {
 driver = "rlm_sql_mysql"
 server = "localhost"
 port = ""
 login = "root"
 password = "xxxxxxxxx"
 radius_db = "xxxxxxxxx"
 read_groups = yes
 sqltrace = no
 sqltracefile = "/var/log/radius/sqltrace.sql"
 readclients = no
 deletestalesessions = yes
 num_sql_socks = 5
 lifetime = 0
 max_queries = 0
 sql_user_name = "%{User-Name}"
 default_user_profile = ""
 nas_query = "SELECT id,nasname,shortname,type,secret FROM nas"
 connect_failure_retry_delay = 60
 simul_count_query = ""
 simul_verify_query = ""
 postauth_query = ""
 safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
  }
rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked
rlm_sql (sql): Attempting to connect to root@localhost:/xxxxxxxxx
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
 Module: Linked to module rlm_my_module_auth
 Module: Instantiating my_module_auth
-------  MyModule instantiate module: rlm_my_module_auth
  my_module_auth {
 ad_query = 0
 postproxy = 0
 nasporttype = 0
 nasport = 0
 nasipaddr = 0
  }
^^^^^^^ Initialized database successfully.
 }
radiusd: #### Loading Virtual Servers ####
server inner-tunnel {
 modules {
 Module: Checking authenticate {...} for more modules to load
 Module: Linked to module rlm_pap
 Module: Instantiating pap
  pap {
 encryption_scheme = "auto"
 auto_header = no
  }
 Module: Linked to module rlm_chap
 Module: Instantiating chap
 Module: Linked to module rlm_mschap
 Module: Instantiating mschap
  mschap {
 use_mppe = yes
 require_encryption = no
 require_strong = no
 with_ntdomain_hack = no
  }
 Module: Linked to module rlm_unix
 Module: Instantiating unix
  unix {
 radwtmp = "/var/log/radius/radwtmp"
  }
 Module: Linked to module rlm_eap
 Module: Instantiating eap
  eap {
 default_eap_type = "peap"
 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
 pem_file_type = yes
 private_key_file = "/root/freeradius-2.1.9/etc/raddb/certs/server.key"
 certificate_file = "/root/freeradius-2.1.9/etc/raddb/certs/server.pem"
 CA_file = "/root/freeradius-2.1.9/etc/raddb/certs/ca.pem"
 private_key_password = "xxxxxx"
 dh_file = "/root/freeradius-2.1.9/etc/raddb/certs/dh"
 random_file = "/root/freeradius-2.1.9/etc/raddb/certs/.random"
 fragment_size = 1024
 include_length = yes
 check_crl = no
    cache {
 enable = no
 lifetime = 24
 max_entries = 255
    }
   }
 Module: Linked to sub-module rlm_eap_ttls
 Module: Instantiating eap-ttls
   ttls {
 default_eap_type = "md5"
 copy_request_to_tunnel = no
 use_tunneled_reply = no
 virtual_server = "inner-tunnel"
 include_length = yes
   }
 Module: 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"
   }
 Module: Linked to sub-module rlm_eap_mschapv2
 Module: Instantiating eap-mschapv2
   mschapv2 {
 with_ntdomain_hack = no
   }
 Module: Checking authorize {...} for more modules to load
 Module: Linked to module rlm_realm
 Module: Instantiating suffix
  realm suffix {
 format = "suffix"
 delimiter = "@"
 ignore_default = no
 ignore_null = no
  }
 Module: Linked to module rlm_files
 Module: Instantiating files
  files {
 usersfile = "./users"
 acctusersfile = "./acct_users"
 preproxy_usersfile = "./preproxy_users"
 compat = "no"
  }
 Module: Linked to module rlm_expiration
 Module: Instantiating expiration
  expiration {
 reply-message = "Password Has Expired  "
  }
 Module: Linked to module rlm_logintime
 Module: Instantiating logintime
  logintime {
 reply-message = "You are calling outside your allowed timespan  "
 minimum-timeout = 60
  }
 Module: Checking session {...} for more modules to load
 Module: Linked to module rlm_radutmp
 Module: Instantiating radutmp
  radutmp {
 filename = "/var/log/radius/radutmp"
 username = "%{User-Name}"
 case_sensitive = yes
 check_with_nas = yes
 perm = 384
 callerid = yes
  }
 Module: Checking post-proxy {...} for more modules to load
 Module: Checking post-auth {...} for more modules to load
 Module: Linked to module rlm_attr_filter
 Module: Instantiating attr_filter.access_reject
  attr_filter attr_filter.access_reject {
 attrsfile = "./attrs.access_reject"
 key = "%{User-Name}"
  }
 } # modules
} # server
server {
 modules {
 Module: Checking authenticate {...} for more modules to load
 Module: Checking authorize {...} for more modules to load
 Module: Linked to module rlm_preprocess
 Module: Instantiating preprocess
  preprocess {
 huntgroups = "./huntgroups"
 hints = "./hints"
 with_ascend_hack = no
 ascend_channels_per_line = 23
 with_ntdomain_hack = no
 with_specialix_jetstream_hack = no
 with_cisco_vsa_hack = no
 with_alvarion_vsa_hack = no
  }
 Module: Linked to module rlm_detail
 Module: Instantiating auth_log
  detail auth_log {
 detailfile = "/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d"
 header = "%t"
 detailperm = 384
 dirperm = 493
 locking = no
 log_packet_header = no
  }
 Module: Checking preacct {...} for more modules to load
 Module: Linked to module rlm_acct_unique
 Module: Instantiating acct_unique
  acct_unique {
 key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"
  }
 Module: Checking accounting {...} for more modules to load
 Module: Linked to module rlm_sql_log
 Module: Instantiating sql_log
  sql_log {
 path = "/var/log/radius/radacct/sql-relay"
 Post-Auth = "INSERT INTO radpostauth                     (username, pass, reply, authdate) VALUES                      ('%{User-Name}', '%{User-Password:-Chap-Password}',           '%{reply:Packet-Type}', '%S');"
 sql_user_name = "%{%{User-Name}:-DEFAULT}"
 utf8 = no
 safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
  }
 Module: Checking session {...} for more modules to load
 Module: Checking pre-proxy {...} 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 = "/root/freeradius-2.1.9/var/run/radiusd/radiusd.sock"
 }
}
Listening on authentication address * port 1812
Listening on accounting address * port 1813
Listening on command file /root/freeradius-2.1.9/var/run/radiusd/radiusd.sock
Listening on proxy address * port 1814
Ready to process requests.
rad_recv: Access-Request packet from host xx.xx.35.130 port 1812, id=76, length=379
 Framed-MTU = 1480
 NAS-IP-Address = xx.xx.35.130
 NAS-Identifier = "HP-SwitchSW02-02"
 User-Name = "host/LAB_LTOP2.XXXXXX.com"
 Service-Type = Framed-User
 Framed-Protocol = PPP
 NAS-Port = 3
 NAS-Port-Type = Ethernet
 NAS-Port-Id = "3"
 Called-Station-Id = "xx-xx-34-d1-16-40"
 Calling-Station-Id = "xx-xx-38-08-f9-7f"
 Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
 Tunnel-Type:0 = VLAN
 Tunnel-Medium-Type:0 = IEEE-802
 Tunnel-Private-Group-Id:0 = "1016"
 EAP-Message = 0x0201002301686f73742f53494d535f4c41425f4c544f50322e53505343534e2e636f6d
 Message-Authenticator = 0xa4ca1529d5920f12adb1f9787d05b0b9
 MS-RAS-Vendor = 11
 HP-Capability-Advert = 0x011a0000000b28
 HP-Capability-Advert = 0x011a0000000b2e
 HP-Capability-Advert = 0x011a0000000b30
 HP-Capability-Advert = 0x011a0000000b3d
 HP-Capability-Advert = 0x0138
 HP-Capability-Advert = 0x013a
 HP-Capability-Advert = 0x0140
 HP-Capability-Advert = 0x0141
 HP-Capability-Advert = 0x0151
+- 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/xx.xx.35.130/auth-detail-20110604
[auth_log] /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/xx.xx.35.130/auth-detail-20110604
[auth_log]  expand: %t -> Sat Jun  4 18:50:57 2011
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
[sql]  expand: %{User-Name} -> host/LAB_LTOP2.XXXXXX.com
[sql] sql_set_user escaped user --> 'host/LAB_LTOP2.XXXXXX.com'
rlm_sql (sql): Reserving sql socket id: 4
[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 = 'host/LAB_LTOP2.XXXXXX.com' ORDER BY id
[sql]  expand: SELECT GroupName FROM radusergroup WHERE UserName='%{SQL-User-Name}' -> SELECT GroupName FROM radusergroup WHERE UserName='host/LAB_LTOP2.XXXXXX.com'
rlm_sql (sql): Released sql socket id: 4
[sql] User host/LAB_LTOP2.XXXXXX.com not found
++[sql] returns notfound
[eap] EAP packet type response id 1 length 35
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
[files] users: Matched entry DEFAULT at line 172
++[files] returns ok
++[expiration] returns noop
++[logintime] returns noop
-------  MyModule authorization module: rlm_my_module_authorize.
-------  MyModule authorization module: proxy_server_alive = 0
-------  MyModule authorization module: proxy_sent_count = 0
-------  MyModule authorization module: proxy_server_timeout = 0
-------   Did not find state attribute. Proceed with normal handling.
-------   Mac address specified in this packet xx:xx:38:08:F9:7F
-------   NAS Port Type specified in this packet 15
-------   NAS Port specified in this packet 3
-------   NAS Port IP address specified in this packet 172434306
-------   NAS Port ID specified in this packet 3
-------  eap_header->code 2, eap_header->id 1, eap packet length 35, offset_to_data 5
-------   EAP Identity received host/LAB_LTOP2.XXXXXX.com
-------   Username/device name in incoming Radius packet host/LAB_LTOP2.XXXXXX.com.
[my_module_auth] ProxyRealmAuthorize: Preparing to proxy authentication request to realm "remote_proxy_ad"
[my_module_auth]  ---------- Username received host/LAB_LTOP2.XXXXXX.com
[my_module_auth]  ---------- Realmname is remote_proxy_ad
[my_module_auth]  ---------- Found realm "remote_proxy_ad"
[my_module_auth] Adding Realm = "remote_proxy_ad"
[my_module_auth]  ---------- Proxying request from user host/LAB_LTOP2.XXXXXX.com to realm remote_proxy_ad
[my_module_auth] Preparing to proxy authentication request to realm "remote_proxy_ad"
++[my_module_auth] returns updated
+- entering group pre-proxy {...}
++[files] returns noop
-------  MyModule pre-proxy  module: my_module_auth_preproxy
++[my_module_auth] returns ok
Sending Access-Request of id 21 to xxx.xxx.158.50 port 1812
 Framed-MTU = 1480
 NAS-IP-Address = xx.xx.35.130
 NAS-Identifier = "HP-SwitchSW02-02"
 User-Name = "host/LAB_LTOP2.XXXXXX.com"
 Service-Type = Framed-User
 Framed-Protocol = PPP
 NAS-Port = 3
 NAS-Port-Type = Ethernet
 NAS-Port-Id = "3"
 Called-Station-Id = "xx-xx-34-d1-16-40"
 Calling-Station-Id = "xx-xx-38-08-f9-7f"
 Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
 Tunnel-Type:0 = VLAN
 Tunnel-Medium-Type:0 = IEEE-802
 Tunnel-Private-Group-Id:0 = "1016"
 EAP-Message = 0x0201002301686f73742f53494d535f4c41425f4c544f50322e53505343534e2e636f6d
 Message-Authenticator = 0x00000000000000000000000000000000
 MS-RAS-Vendor = 11
 HP-Capability-Advert = 0x011a0000000b28
 HP-Capability-Advert = 0x011a0000000b2e
 HP-Capability-Advert = 0x011a0000000b30
 HP-Capability-Advert = 0x011a0000000b3d
 HP-Capability-Advert = 0x0138
 HP-Capability-Advert = 0x013a
 HP-Capability-Advert = 0x0140
 HP-Capability-Advert = 0x0141
 HP-Capability-Advert = 0x0151
 Proxy-State = 0x3736
Proxying request 0 to home server xxx.xxx.158.50 port 1812
Sending Access-Request of id 21 to xxx.xxx.158.50 port 1812
 Framed-MTU = 1480
 NAS-IP-Address = xx.xx.35.130
 NAS-Identifier = "HP-SwitchSW02-02"
 User-Name = "host/LAB_LTOP2.XXXXXX.com"
 Service-Type = Framed-User
 Framed-Protocol = PPP
 NAS-Port = 3
 NAS-Port-Type = Ethernet
 NAS-Port-Id = "3"
 Called-Station-Id = "xx-xx-34-d1-16-40"
 Calling-Station-Id = "xx-xx-38-08-f9-7f"
 Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
 Tunnel-Type:0 = VLAN
 Tunnel-Medium-Type:0 = IEEE-802
 Tunnel-Private-Group-Id:0 = "1016"
 EAP-Message = 0x0201002301686f73742f53494d535f4c41425f4c544f50322e53505343534e2e636f6d
 Message-Authenticator = 0x00000000000000000000000000000000
 MS-RAS-Vendor = 11
 HP-Capability-Advert = 0x011a0000000b28
 HP-Capability-Advert = 0x011a0000000b2e
 HP-Capability-Advert = 0x011a0000000b30
 HP-Capability-Advert = 0x011a0000000b3d
 HP-Capability-Advert = 0x0138
 HP-Capability-Advert = 0x013a
 HP-Capability-Advert = 0x0140
 HP-Capability-Advert = 0x0141
 HP-Capability-Advert = 0x0151
 Proxy-State = 0x3736
Going to the next request
Waking up in 0.9 seconds.
rad_recv: Access-Request packet from host xx.xx.35.130 port 1812, id=77, length=343
 Framed-MTU = 3038
 NAS-IP-Address = xx.xx.35.130
 NAS-Identifier = "HP-SwitchSW02-02"
 User-Name = "xxxx3808f97f"
 Service-Type = Call-Check
 Framed-Protocol = PPP
 NAS-Port = 3
 NAS-Port-Type = Ethernet
 NAS-Port-Id = "3"
 Called-Station-Id = "xx-xx-34-d1-16-7d"
 Calling-Station-Id = "xx-xx-38-08-f9-7f"
 Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
 Tunnel-Type:0 = VLAN
 Tunnel-Medium-Type:0 = IEEE-802
 Tunnel-Private-Group-Id:0 = "1016"
 EAP-Message = 0x0200001101303031623338303866393766
 Message-Authenticator = 0x2084d40026c95d354054c4cbbf4797b5
 MS-RAS-Vendor = 11
 HP-Capability-Advert = 0x011a0000000b28
 HP-Capability-Advert = 0x011a0000000b2e
 HP-Capability-Advert = 0x011a0000000b30
 HP-Capability-Advert = 0x011a0000000b3d
 HP-Capability-Advert = 0x0138
 HP-Capability-Advert = 0x013a
 HP-Capability-Advert = 0x0140
 HP-Capability-Advert = 0x0141
 HP-Capability-Advert = 0x0151
+- 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/xx.xx.35.130/auth-detail-20110604
[auth_log] /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/xx.xx.35.130/auth-detail-20110604
[auth_log]  expand: %t -> Sat Jun  4 18:50:57 2011
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
[sql]  expand: %{User-Name} -> xxxx3808f97f
[sql] sql_set_user escaped user --> 'xxxx3808f97f'
rlm_sql (sql): Reserving sql socket id: 3
[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 = 'xxxx3808f97f' ORDER BY id
[sql]  expand: SELECT GroupName FROM radusergroup WHERE UserName='%{SQL-User-Name}' -> SELECT GroupName FROM radusergroup WHERE UserName='xxxx3808f97f'
rlm_sql (sql): Released sql socket id: 3
[sql] User xxxx3808f97f not found
++[sql] returns notfound
[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] users: Matched entry DEFAULT at line 172
++[files] returns ok
++[expiration] returns noop
++[logintime] returns noop
-------  MyModule authorization module: rlm_my_module_authorize.
-------  MyModule authorization module: proxy_server_alive = 0
-------  MyModule authorization module: proxy_sent_count = 1
-------  MyModule authorization module: proxy_server_timeout = 0
-------   Did not find state attribute. Proceed with normal handling.
-------   Mac address specified in this packet xx:xx:38:08:F9:7F
-------   NAS Port Type specified in this packet 15
-------   NAS Port specified in this packet 3
-------   NAS Port IP address specified in this packet 172434306
-------   NAS Port ID specified in this packet 3
-------  eap_header->code 2, eap_header->id 0, eap packet length 17, offset_to_data 5
-------   EAP Identity received xxxx3808f97f
-------   Username/device name in incoming Radius packet xxxx3808f97f.
++[my_module_auth] returns fail
Using Post-Auth-Type Reject
+- entering group REJECT {...}
-------  MyModule post-authentication  module: my_module_auth_postauth
++[my_module_auth] returns fail
Sending Access-Reject of id 77 to xx.xx.35.130 port 1812
 Framed-Protocol = PPP
 Framed-Compression = Van-Jacobson-TCP-IP
Finished request 1.
Going to the next request
Waking up in 0.9 seconds.
Waking up in 4.0 seconds.
rad_recv: Access-Request packet from host xx.xx.35.130 port 1812, id=76, length=379
Sending duplicate proxied request to home server xxx.xxx.158.50 port 1812 - ID: 21
Sending Access-Request of id 21 to xxx.xxx.158.50 port 1812
 Framed-MTU = 1480
 NAS-IP-Address = xx.xx.35.130
 NAS-Identifier = "HP-SwitchSW02-02"
 User-Name = "host/LAB_LTOP2.XXXXXX.com"
 Service-Type = Framed-User
 Framed-Protocol = PPP
 NAS-Port = 3
 NAS-Port-Type = Ethernet
 NAS-Port-Id = "3"
 Called-Station-Id = "xx-xx-34-d1-16-40"
 Calling-Station-Id = "xx-xx-38-08-f9-7f"
 Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
 Tunnel-Type:0 = VLAN
 Tunnel-Medium-Type:0 = IEEE-802
 Tunnel-Private-Group-Id:0 = "1016"
 EAP-Message = 0x0201002301686f73742f53494d535f4c41425f4c544f50322e53505343534e2e636f6d
 Message-Authenticator = 0x00000000000000000000000000000000
 MS-RAS-Vendor = 11
 HP-Capability-Advert = 0x011a0000000b28
 HP-Capability-Advert = 0x011a0000000b2e
 HP-Capability-Advert = 0x011a0000000b30
 HP-Capability-Advert = 0x011a0000000b3d
 HP-Capability-Advert = 0x0138
 HP-Capability-Advert = 0x013a
 HP-Capability-Advert = 0x0140
 HP-Capability-Advert = 0x0141
 HP-Capability-Advert = 0x0151
 Proxy-State = 0x3736
Cleaning up request 1 ID 77 with timestamp +9
Waking up in 8.9 seconds.
rad_recv: Access-Request packet from host xx.xx.35.130 port 1812, id=76, length=379
Sending duplicate proxied request to home server xxx.xxx.158.50 port 1812 - ID: 21
Sending Access-Request of id 21 to xxx.xxx.158.50 port 1812
 Framed-MTU = 1480
 NAS-IP-Address = xx.xx.35.130
 NAS-Identifier = "HP-SwitchSW02-02"
 User-Name = "host/LAB_LTOP2.XXXXXX.com"
 Service-Type = Framed-User
 Framed-Protocol = PPP
 NAS-Port = 3
 NAS-Port-Type = Ethernet
 NAS-Port-Id = "3"
 Called-Station-Id = "xx-xx-34-d1-16-40"
 Calling-Station-Id = "xx-xx-38-08-f9-7f"
 Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
 Tunnel-Type:0 = VLAN
 Tunnel-Medium-Type:0 = IEEE-802
 Tunnel-Private-Group-Id:0 = "1016"
 EAP-Message = 0x0201002301686f73742f53494d535f4c41425f4c544f50322e53505343534e2e636f6d
 Message-Authenticator = 0x00000000000000000000000000000000
 MS-RAS-Vendor = 11
 HP-Capability-Advert = 0x011a0000000b28
 HP-Capability-Advert = 0x011a0000000b2e
 HP-Capability-Advert = 0x011a0000000b30
 HP-Capability-Advert = 0x011a0000000b3d
 HP-Capability-Advert = 0x0138
 HP-Capability-Advert = 0x013a
 HP-Capability-Advert = 0x0140
 HP-Capability-Advert = 0x0141
 HP-Capability-Advert = 0x0151
 Proxy-State = 0x3736
Waking up in 4.0 seconds.
Marking home server xxx.xxx.158.50 port 1812 as zombie (it looks like it is dead).
Waking up in 1.4 seconds.
rad_recv: Access-Request packet from host xx.xx.35.130 port 1812, id=76, length=379
Discarding duplicate request from client dot1x port 1812 - ID: 76 due to unfinished request 0
Waking up in 0.5 seconds.
Waking up in 2.2 seconds.
Waking up in 3.3 seconds.
Waking up in 5.0 seconds.
rad_recv: Access-Request packet from host xx.xx.35.130 port 1812, id=78, length=379
 Framed-MTU = 1480
 NAS-IP-Address = xx.xx.35.130
 NAS-Identifier = "HP-SwitchSW02-02"
 User-Name = "host/LAB_LTOP2.XXXXXX.com"
 Service-Type = Framed-User
 Framed-Protocol = PPP
 NAS-Port = 3
 NAS-Port-Type = Ethernet
 NAS-Port-Id = "3"
 Called-Station-Id = "xx-xx-34-d1-16-40"
 Calling-Station-Id = "xx-xx-38-08-f9-7f"
 Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
 Tunnel-Type:0 = VLAN
 Tunnel-Medium-Type:0 = IEEE-802
 Tunnel-Private-Group-Id:0 = "1050"
 EAP-Message = 0x0205002301686f73742f53494d535f4c41425f4c544f50322e53505343534e2e636f6d
 Message-Authenticator = 0x93732e302ef448c5537bf1f603f41ce6
 MS-RAS-Vendor = 11
 HP-Capability-Advert = 0x011a0000000b28
 HP-Capability-Advert = 0x011a0000000b2e
 HP-Capability-Advert = 0x011a0000000b30
 HP-Capability-Advert = 0x011a0000000b3d
 HP-Capability-Advert = 0x0138
 HP-Capability-Advert = 0x013a
 HP-Capability-Advert = 0x0140
 HP-Capability-Advert = 0x0141
 HP-Capability-Advert = 0x0151
+- 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/xx.xx.35.130/auth-detail-20110604
[auth_log] /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/xx.xx.35.130/auth-detail-20110604
[auth_log]  expand: %t -> Sat Jun  4 18:51:20 2011
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
[sql]  expand: %{User-Name} -> host/LAB_LTOP2.XXXXXX.com
[sql] sql_set_user escaped user --> 'host/LAB_LTOP2.XXXXXX.com'
rlm_sql (sql): Reserving sql socket id: 2
[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 = 'host/LAB_LTOP2.XXXXXX.com' ORDER BY id
[sql]  expand: SELECT GroupName FROM radusergroup WHERE UserName='%{SQL-User-Name}' -> SELECT GroupName FROM radusergroup WHERE UserName='host/LAB_LTOP2.XXXXXX.com'
rlm_sql (sql): Released sql socket id: 2
[sql] User host/LAB_LTOP2.XXXXXX.com not found
++[sql] returns notfound
[eap] EAP packet type response id 5 length 35
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
[files] users: Matched entry DEFAULT at line 172
++[files] returns ok
++[expiration] returns noop
++[logintime] returns noop
-------  MyModule authorization module: rlm_my_module_authorize.
-------  MyModule authorization module: proxy_server_alive = 0
-------  MyModule authorization module: proxy_sent_count = 1
-------  MyModule authorization module: proxy_server_timeout = 0
-------   Did not find state attribute. Proceed with normal handling.
-------   Mac address specified in this packet xx:xx:38:08:F9:7F
-------   NAS Port Type specified in this packet 15
-------   NAS Port specified in this packet 3
-------   NAS Port IP address specified in this packet 172434306
-------   NAS Port ID specified in this packet 3
-------  eap_header->code 2, eap_header->id 5, eap packet length 35, offset_to_data 5
-------   EAP Identity received host/LAB_LTOP2.XXXXXX.com
-------   Username/device name in incoming Radius packet host/LAB_LTOP2.XXXXXX.com.
[my_module_auth] ProxyRealmAuthorize: Preparing to proxy authentication request to realm "remote_proxy_ad"
[my_module_auth]  ---------- Username received host/LAB_LTOP2.XXXXXX.com
[my_module_auth]  ---------- Realmname is remote_proxy_ad
[my_module_auth]  ---------- Found realm "remote_proxy_ad"
[my_module_auth] Adding Realm = "remote_proxy_ad"
[my_module_auth]  ---------- Proxying request from user host/LAB_LTOP2.XXXXXX.com to realm remote_proxy_ad
[my_module_auth] Preparing to proxy authentication request to realm "remote_proxy_ad"
++[my_module_auth] returns updated
+- entering group pre-proxy {...}
++[files] returns noop
-------  MyModule pre-proxy  module: my_module_auth_preproxy
++[my_module_auth] returns ok
Sending Access-Request of id 146 to xxx.xxx.158.50 port 1812
 Framed-MTU = 1480
 NAS-IP-Address = xx.xx.35.130
 NAS-Identifier = "HP-SwitchSW02-02"
 User-Name = "host/LAB_LTOP2.XXXXXX.com"
 Service-Type = Framed-User
 Framed-Protocol = PPP
 NAS-Port = 3
 NAS-Port-Type = Ethernet
 NAS-Port-Id = "3"
 Called-Station-Id = "xx-xx-34-d1-16-40"
 Calling-Station-Id = "xx-xx-38-08-f9-7f"
 Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
 Tunnel-Type:0 = VLAN
 Tunnel-Medium-Type:0 = IEEE-802
 Tunnel-Private-Group-Id:0 = "1050"
 EAP-Message = 0x0205002301686f73742f53494d535f4c41425f4c544f50322e53505343534e2e636f6d
 Message-Authenticator = 0x00000000000000000000000000000000
 MS-RAS-Vendor = 11
 HP-Capability-Advert = 0x011a0000000b28
 HP-Capability-Advert = 0x011a0000000b2e
 HP-Capability-Advert = 0x011a0000000b30
 HP-Capability-Advert = 0x011a0000000b3d
 HP-Capability-Advert = 0x0138
 HP-Capability-Advert = 0x013a
 HP-Capability-Advert = 0x0140
 HP-Capability-Advert = 0x0141
 HP-Capability-Advert = 0x0151
 Proxy-State = 0x3738
Proxying request 2 to home server xxx.xxx.158.50 port 1812
Sending Access-Request of id 146 to xxx.xxx.158.50 port 1812
 Framed-MTU = 1480
 NAS-IP-Address = xx.xx.35.130
 NAS-Identifier = "HP-SwitchSW02-02"
 User-Name = "host/LAB_LTOP2.XXXXXX.com"
 Service-Type = Framed-User
 Framed-Protocol = PPP
 NAS-Port = 3
 NAS-Port-Type = Ethernet
 NAS-Port-Id = "3"
 Called-Station-Id = "xx-xx-34-d1-16-40"
 Calling-Station-Id = "xx-xx-38-08-f9-7f"
 Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
 Tunnel-Type:0 = VLAN
 Tunnel-Medium-Type:0 = IEEE-802
 Tunnel-Private-Group-Id:0 = "1050"
 EAP-Message = 0x0205002301686f73742f53494d535f4c41425f4c544f50322e53505343534e2e636f6d
 Message-Authenticator = 0x00000000000000000000000000000000
 MS-RAS-Vendor = 11
 HP-Capability-Advert = 0x011a0000000b28
 HP-Capability-Advert = 0x011a0000000b2e
 HP-Capability-Advert = 0x011a0000000b30
 HP-Capability-Advert = 0x011a0000000b3d
 HP-Capability-Advert = 0x0138
 HP-Capability-Advert = 0x013a
 HP-Capability-Advert = 0x0140
 HP-Capability-Advert = 0x0141
 HP-Capability-Advert = 0x0151
 Proxy-State = 0x3738
Going to the next request
Waking up in 0.9 seconds.
Waking up in 2.1 seconds.
Waking up in 7.5 seconds.
rad_recv: Access-Request packet from host xx.xx.35.130 port 1812, id=78, length=379
Sending duplicate proxied request to home server xxx.xxx.158.50 port 1812 - ID: 146
Sending Access-Request of id 146 to xxx.xxx.158.50 port 1812
 Framed-MTU = 1480
 NAS-IP-Address = xx.xx.35.130
 NAS-Identifier = "HP-SwitchSW02-02"
 User-Name = "host/LAB_LTOP2.XXXXXX.com"
 Service-Type = Framed-User
 Framed-Protocol = PPP
 NAS-Port = 3
 NAS-Port-Type = Ethernet
 NAS-Port-Id = "3"
 Called-Station-Id = "xx-xx-34-d1-16-40"
 Calling-Station-Id = "xx-xx-38-08-f9-7f"
 Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
 Tunnel-Type:0 = VLAN
 Tunnel-Medium-Type:0 = IEEE-802
 Tunnel-Private-Group-Id:0 = "1050"
 EAP-Message = 0x0205002301686f73742f53494d535f4c41425f4c544f50322e53505343534e2e636f6d
 Message-Authenticator = 0x00000000000000000000000000000000
 MS-RAS-Vendor = 11
 HP-Capability-Advert = 0x011a0000000b28
 HP-Capability-Advert = 0x011a0000000b2e
 HP-Capability-Advert = 0x011a0000000b30
 HP-Capability-Advert = 0x011a0000000b3d
 HP-Capability-Advert = 0x0138
 HP-Capability-Advert = 0x013a
 HP-Capability-Advert = 0x0140
 HP-Capability-Advert = 0x0141
 HP-Capability-Advert = 0x0151
 Proxy-State = 0x3738
Waking up in 5.7 seconds.
rad_recv: Access-Request packet from host xx.xx.35.130 port 1812, id=78, length=379
Marking home server xxx.xxx.158.50 port 1812 as dead.
Failed to find live home server for request 2
  Found Post-Proxy-Type
+- entering group Fail {...}
-------  MyModule post-proxy  module: my_module_auth_postproxy host/LAB_LTOP2.XXXXXX.com
++[my_module_auth] returns ok
ERROR: Failed to find live home server for realm remote_proxy_ad
  Found Post-Proxy-Type
+- entering group Fail {...}
-------  MyModule post-proxy  module: my_module_auth_postproxy host/LAB_LTOP2.XXXXXX.com
++[my_module_auth] returns ok
There was no response configured: rejecting request 2
Using Post-Auth-Type Reject
+- entering group REJECT {...}
-------  MyModule post-authentication  module: my_module_auth_postauth
++[my_module_auth] returns fail
Sending Access-Reject of id 78 to xx.xx.35.130 port 1812
Finished request 2.
Going to the next request
Waking up in 0.7 seconds.
Cleaning up request 0 ID 76 with timestamp +9
Waking up in 4.2 seconds.
Cleaning up request 2 ID 78 with timestamp +32
Waking up in 119.0 seconds.
Marking home server xxx.xxx.158.50 port 1812 alive again... we have no idea if it really is alive or not.
Ready to process requests.
rad_recv: Access-Request packet from host xx.xx.35.130 port 1812, id=79, length=379
 Framed-MTU = 1480
 NAS-IP-Address = xx.xx.35.130
 NAS-Identifier = "HP-SwitchSW02-02"
 User-Name = "host/LAB_LTOP2.XXXXXX.com"
 Service-Type = Framed-User
 Framed-Protocol = PPP
 NAS-Port = 3
 NAS-Port-Type = Ethernet
 NAS-Port-Id = "3"
 Called-Station-Id = "xx-xx-34-d1-16-40"
 Calling-Station-Id = "xx-xx-38-08-f9-7f"
 Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
 Tunnel-Type:0 = VLAN
 Tunnel-Medium-Type:0 = IEEE-802
 Tunnel-Private-Group-Id:0 = "1050"
 EAP-Message = 0x0214002301686f73742f53494d535f4c41425f4c544f50322e53505343534e2e636f6d
 Message-Authenticator = 0x54c6272b8e58a7ec3514e410142ab23c
 MS-RAS-Vendor = 11
 HP-Capability-Advert = 0x011a0000000b28
 HP-Capability-Advert = 0x011a0000000b2e
 HP-Capability-Advert = 0x011a0000000b30
 HP-Capability-Advert = 0x011a0000000b3d
 HP-Capability-Advert = 0x0138
 HP-Capability-Advert = 0x013a
 HP-Capability-Advert = 0x0140
 HP-Capability-Advert = 0x0141
 HP-Capability-Advert = 0x0151
+- 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/xx.xx.35.130/auth-detail-20110604
[auth_log] /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/xx.xx.35.130/auth-detail-20110604
[auth_log]  expand: %t -> Sat Jun  4 19:11:30 2011
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
[sql]  expand: %{User-Name} -> host/LAB_LTOP2.XXXXXX.com
[sql] sql_set_user escaped user --> 'host/LAB_LTOP2.XXXXXX.com'
rlm_sql (sql): Reserving sql socket id: 1
[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 = 'host/LAB_LTOP2.XXXXXX.com' ORDER BY id
[sql]  expand: SELECT GroupName FROM radusergroup WHERE UserName='%{SQL-User-Name}' -> SELECT GroupName FROM radusergroup WHERE UserName='host/LAB_LTOP2.XXXXXX.com'
rlm_sql (sql): Released sql socket id: 1
[sql] User host/LAB_LTOP2.XXXXXX.com not found
++[sql] returns notfound
[eap] EAP packet type response id 20 length 35
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
[files] users: Matched entry DEFAULT at line 172
++[files] returns ok
++[expiration] returns noop
++[logintime] returns noop
-------  MyModule authorization module: rlm_my_module_authorize.
-------  MyModule authorization module: proxy_server_alive = 1
-------  MyModule authorization module: proxy_sent_count = 0
-------  MyModule authorization module: proxy_server_timeout = 0
-------   Did not find state attribute. Proceed with normal handling.
-------   Mac address specified in this packet xx:xx:38:08:F9:7F
-------   NAS Port Type specified in this packet 15
-------   NAS Port specified in this packet 3
-------   NAS Port IP address specified in this packet 172434306
-------   NAS Port ID specified in this packet 3
-------  eap_header->code 2, eap_header->id 20, eap packet length 35, offset_to_data 5
-------   EAP Identity received host/LAB_LTOP2.XXXXXX.com
-------   Username/device name in incoming Radius packet host/LAB_LTOP2.XXXXXX.com.
[my_module_auth] ProxyRealmAuthorize: Preparing to proxy authentication request to realm "remote_proxy_ad"
[my_module_auth]  ---------- Username received host/LAB_LTOP2.XXXXXX.com
[my_module_auth]  ---------- Realmname is remote_proxy_ad
[my_module_auth]  ---------- Found realm "remote_proxy_ad"
[my_module_auth] Adding Realm = "remote_proxy_ad"
[my_module_auth]  ---------- Proxying request from user host/LAB_LTOP2.XXXXXX.com to realm remote_proxy_ad
[my_module_auth] Preparing to proxy authentication request to realm "remote_proxy_ad"
++[my_module_auth] returns updated
+- entering group pre-proxy {...}
++[files] returns noop
-------  MyModule pre-proxy  module: my_module_auth_preproxy
++[my_module_auth] returns ok
Sending Access-Request of id 58 to xxx.xxx.158.50 port 1812
 Framed-MTU = 1480
 NAS-IP-Address = xx.xx.35.130
 NAS-Identifier = "HP-SwitchSW02-02"
 User-Name = "host/LAB_LTOP2.XXXXXX.com"
 Service-Type = Framed-User
 Framed-Protocol = PPP
 NAS-Port = 3
 NAS-Port-Type = Ethernet
 NAS-Port-Id = "3"
 Called-Station-Id = "xx-xx-34-d1-16-40"
 Calling-Station-Id = "xx-xx-38-08-f9-7f"
 Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
 Tunnel-Type:0 = VLAN
 Tunnel-Medium-Type:0 = IEEE-802
 Tunnel-Private-Group-Id:0 = "1050"
 EAP-Message = 0x0214002301686f73742f53494d535f4c41425f4c544f50322e53505343534e2e636f6d
 Message-Authenticator = 0x00000000000000000000000000000000
 MS-RAS-Vendor = 11
 HP-Capability-Advert = 0x011a0000000b28
 HP-Capability-Advert = 0x011a0000000b2e
 HP-Capability-Advert = 0x011a0000000b30
 HP-Capability-Advert = 0x011a0000000b3d
 HP-Capability-Advert = 0x0138
 HP-Capability-Advert = 0x013a
 HP-Capability-Advert = 0x0140
 HP-Capability-Advert = 0x0141
 HP-Capability-Advert = 0x0151
 Proxy-State = 0x3739
Proxying request 3 to home server xxx.xxx.158.50 port 1812
Sending Access-Request of id 58 to xxx.xxx.158.50 port 1812
 Framed-MTU = 1480
 NAS-IP-Address = xx.xx.35.130
 NAS-Identifier = "HP-SwitchSW02-02"
 User-Name = "host/LAB_LTOP2.XXXXXX.com"
 Service-Type = Framed-User
 Framed-Protocol = PPP
 NAS-Port = 3
 NAS-Port-Type = Ethernet
 NAS-Port-Id = "3"
 Called-Station-Id = "xx-xx-34-d1-16-40"
 Calling-Station-Id = "xx-xx-38-08-f9-7f"
 Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
 Tunnel-Type:0 = VLAN
 Tunnel-Medium-Type:0 = IEEE-802
 Tunnel-Private-Group-Id:0 = "1050"
 EAP-Message = 0x0214002301686f73742f53494d535f4c41425f4c544f50322e53505343534e2e636f6d
 Message-Authenticator = 0x00000000000000000000000000000000
 MS-RAS-Vendor = 11
 HP-Capability-Advert = 0x011a0000000b28
 HP-Capability-Advert = 0x011a0000000b2e
 HP-Capability-Advert = 0x011a0000000b30
 HP-Capability-Advert = 0x011a0000000b3d
 HP-Capability-Advert = 0x0138
 HP-Capability-Advert = 0x013a
 HP-Capability-Advert = 0x0140
 HP-Capability-Advert = 0x0141
 HP-Capability-Advert = 0x0151
 Proxy-State = 0x3739
Going to the next request
Waking up in 0.9 seconds.
Waking up in 12.9 seconds.
rad_recv: Access-Request packet from host xx.xx.35.130 port 1812, id=79, length=379
Sending duplicate proxied request to home server xxx.xxx.158.50 port 1812 - ID: 58
Sending Access-Request of id 58 to xxx.xxx.158.50 port 1812
 Framed-MTU = 1480
 NAS-IP-Address = xx.xx.35.130
 NAS-Identifier = "HP-SwitchSW02-02"
 User-Name = "host/LAB_LTOP2.XXXXXX.com"
 Service-Type = Framed-User
 Framed-Protocol = PPP
 NAS-Port = 3
 NAS-Port-Type = Ethernet
 NAS-Port-Id = "3"
 Called-Station-Id = "xx-xx-34-d1-16-40"
 Calling-Station-Id = "xx-xx-38-08-f9-7f"
 Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
 Tunnel-Type:0 = VLAN
 Tunnel-Medium-Type:0 = IEEE-802
 Tunnel-Private-Group-Id:0 = "1050"
 EAP-Message = 0x0214002301686f73742f53494d535f4c41425f4c544f50322e53505343534e2e636f6d
 Message-Authenticator = 0x00000000000000000000000000000000
 MS-RAS-Vendor = 11
 HP-Capability-Advert = 0x011a0000000b28
 HP-Capability-Advert = 0x011a0000000b2e
 HP-Capability-Advert = 0x011a0000000b30
 HP-Capability-Advert = 0x011a0000000b3d
 HP-Capability-Advert = 0x0138
 HP-Capability-Advert = 0x013a
 HP-Capability-Advert = 0x0140
 HP-Capability-Advert = 0x0141
 HP-Capability-Advert = 0x0151
 Proxy-State = 0x3739
Waking up in 9.0 seconds.
rad_recv: Access-Request packet from host xx.xx.35.130 port 1812, id=79, length=379
Sending duplicate proxied request to home server xxx.xxx.158.50 port 1812 - ID: 58
Sending Access-Request of id 58 to xxx.xxx.158.50 port 1812
 Framed-MTU = 1480
 NAS-IP-Address = xx.xx.35.130
 NAS-Identifier = "HP-SwitchSW02-02"
 User-Name = "host/LAB_LTOP2.XXXXXX.com"
 Service-Type = Framed-User
 Framed-Protocol = PPP
 NAS-Port = 3
 NAS-Port-Type = Ethernet
 NAS-Port-Id = "3"
 Called-Station-Id = "xx-xx-34-d1-16-40"
 Calling-Station-Id = "xx-xx-38-08-f9-7f"
 Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
 Tunnel-Type:0 = VLAN
 Tunnel-Medium-Type:0 = IEEE-802
 Tunnel-Private-Group-Id:0 = "1050"
 EAP-Message = 0x0214002301686f73742f53494d535f4c41425f4c544f50322e53505343534e2e636f6d
 Message-Authenticator = 0x00000000000000000000000000000000
 MS-RAS-Vendor = 11
 HP-Capability-Advert = 0x011a0000000b28
 HP-Capability-Advert = 0x011a0000000b2e
 HP-Capability-Advert = 0x011a0000000b30
 HP-Capability-Advert = 0x011a0000000b3d
 HP-Capability-Advert = 0x0138
 HP-Capability-Advert = 0x013a
 HP-Capability-Advert = 0x0140
 HP-Capability-Advert = 0x0141
 HP-Capability-Advert = 0x0151
 Proxy-State = 0x3739
Waking up in 4.0 seconds.
Marking home server xxx.xxx.158.50 port 1812 as zombie (it looks like it is dead).
Waking up in 1.4 seconds.
rad_recv: Access-Request packet from host xx.xx.35.130 port 1812, id=79, length=379
Discarding duplicate request from client dot1x port 1812 - ID: 79 due to unfinished request 3
Waking up in 0.5 seconds.
Waking up in 2.2 seconds.
Waking up in 3.3 seconds.
Waking up in 5.0 seconds.
rad_recv: Access-Request packet from host xx.xx.35.130 port 1812, id=80, length=379
 Framed-MTU = 1480
 NAS-IP-Address = xx.xx.35.130
 NAS-Identifier = "HP-SwitchSW02-02"
 User-Name = "host/LAB_LTOP2.XXXXXX.com"
 Service-Type = Framed-User
 Framed-Protocol = PPP
 NAS-Port = 3
 NAS-Port-Type = Ethernet
 NAS-Port-Id = "3"
 Called-Station-Id = "xx-xx-34-d1-16-40"
 Calling-Station-Id = "xx-xx-38-08-f9-7f"
 Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
 Tunnel-Type:0 = VLAN
 Tunnel-Medium-Type:0 = IEEE-802
 Tunnel-Private-Group-Id:0 = "1050"
 EAP-Message = 0x0218002301686f73742f53494d535f4c41425f4c544f50322e53505343534e2e636f6d
 Message-Authenticator = 0xa21cb7ee63d23dc167a84a61b2f1d6c7
 MS-RAS-Vendor = 11
 HP-Capability-Advert = 0x011a0000000b28
 HP-Capability-Advert = 0x011a0000000b2e
 HP-Capability-Advert = 0x011a0000000b30
 HP-Capability-Advert = 0x011a0000000b3d
 HP-Capability-Advert = 0x0138
 HP-Capability-Advert = 0x013a
 HP-Capability-Advert = 0x0140
 HP-Capability-Advert = 0x0141
 HP-Capability-Advert = 0x0151
+- 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/xx.xx.35.130/auth-detail-20110604
[auth_log] /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/xx.xx.35.130/auth-detail-20110604
[auth_log]  expand: %t -> Sat Jun  4 19:11:53 2011
++[auth_log] returns ok
++[chap] returns noop
++[mschap] returns noop
[sql]  expand: %{User-Name} -> host/LAB_LTOP2.XXXXXX.com
[sql] sql_set_user escaped user --> 'host/LAB_LTOP2.XXXXXX.com'
rlm_sql (sql): Reserving sql socket id: 0
[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 = 'host/LAB_LTOP2.XXXXXX.com' ORDER BY id
[sql]  expand: SELECT GroupName FROM radusergroup WHERE UserName='%{SQL-User-Name}' -> SELECT GroupName FROM radusergroup WHERE UserName='host/LAB_LTOP2.XXXXXX.com'
rlm_sql (sql): Released sql socket id: 0
[sql] User host/LAB_LTOP2.XXXXXX.com not found
++[sql] returns notfound
[eap] EAP packet type response id 24 length 35
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
[files] users: Matched entry DEFAULT at line 172
++[files] returns ok
++[expiration] returns noop
++[logintime] returns noop
-------  MyModule authorization module: rlm_my_module_authorize.
-------  MyModule authorization module: proxy_server_alive = 0
-------  MyModule authorization module: proxy_sent_count = 1
-------  MyModule authorization module: proxy_server_timeout = 0
-------   Did not find state attribute. Proceed with normal handling.
-------   Mac address specified in this packet xx:xx:38:08:F9:7F
-------   NAS Port Type specified in this packet 15
-------   NAS Port specified in this packet 3
-------   NAS Port IP address specified in this packet 172434306
-------   NAS Port ID specified in this packet 3
-------  eap_header->code 2, eap_header->id 24, eap packet length 35, offset_to_data 5
-------   EAP Identity received host/LAB_LTOP2.XXXXXX.com
-------   Username/device name in incoming Radius packet host/LAB_LTOP2.XXXXXX.com.
[my_module_auth] ProxyRealmAuthorize: Preparing to proxy authentication request to realm "remote_proxy_ad"
[my_module_auth]  ---------- Username received host/LAB_LTOP2.XXXXXX.com
[my_module_auth]  ---------- Realmname is remote_proxy_ad
[my_module_auth]  ---------- Found realm "remote_proxy_ad"
[my_module_auth] Adding Realm = "remote_proxy_ad"
[my_module_auth]  ---------- Proxying request from user host/LAB_LTOP2.XXXXXX.com to realm remote_proxy_ad
[my_module_auth] Preparing to proxy authentication request to realm "remote_proxy_ad"
++[my_module_auth] returns updated
+- entering group pre-proxy {...}
++[files] returns noop
-------  MyModule pre-proxy  module: my_module_auth_preproxy
++[my_module_auth] returns ok
Sending Access-Request of id 168 to xxx.xxx.158.50 port 1812
 Framed-MTU = 1480
 NAS-IP-Address = xx.xx.35.130
 NAS-Identifier = "HP-SwitchSW02-02"
 User-Name = "host/LAB_LTOP2.XXXXXX.com"
 Service-Type = Framed-User
 Framed-Protocol = PPP
 NAS-Port = 3
 NAS-Port-Type = Ethernet
 NAS-Port-Id = "3"
 Called-Station-Id = "xx-xx-34-d1-16-40"
 Calling-Station-Id = "xx-xx-38-08-f9-7f"
 Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
 Tunnel-Type:0 = VLAN
 Tunnel-Medium-Type:0 = IEEE-802
 Tunnel-Private-Group-Id:0 = "1050"
 EAP-Message = 0x0218002301686f73742f53494d535f4c41425f4c544f50322e53505343534e2e636f6d
 Message-Authenticator = 0x00000000000000000000000000000000
 MS-RAS-Vendor = 11
 HP-Capability-Advert = 0x011a0000000b28
 HP-Capability-Advert = 0x011a0000000b2e
 HP-Capability-Advert = 0x011a0000000b30
 HP-Capability-Advert = 0x011a0000000b3d
 HP-Capability-Advert = 0x0138
 HP-Capability-Advert = 0x013a
 HP-Capability-Advert = 0x0140
 HP-Capability-Advert = 0x0141
 HP-Capability-Advert = 0x0151
 Proxy-State = 0x3830
Proxying request 4 to home server xxx.xxx.158.50 port 1812
Sending Access-Request of id 168 to xxx.xxx.158.50 port 1812
 Framed-MTU = 1480
 NAS-IP-Address = xx.xx.35.130
 NAS-Identifier = "HP-SwitchSW02-02"
 User-Name = "host/LAB_LTOP2.XXXXXX.com"
 Service-Type = Framed-User
 Framed-Protocol = PPP
 NAS-Port = 3
 NAS-Port-Type = Ethernet
 NAS-Port-Id = "3"
 Called-Station-Id = "xx-xx-34-d1-16-40"
 Calling-Station-Id = "xx-xx-38-08-f9-7f"
 Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
 Tunnel-Type:0 = VLAN
 Tunnel-Medium-Type:0 = IEEE-802
 Tunnel-Private-Group-Id:0 = "1050"
 EAP-Message = 0x0218002301686f73742f53494d535f4c41425f4c544f50322e53505343534e2e636f6d
 Message-Authenticator = 0x00000000000000000000000000000000
 MS-RAS-Vendor = 11
 HP-Capability-Advert = 0x011a0000000b28
 HP-Capability-Advert = 0x011a0000000b2e
 HP-Capability-Advert = 0x011a0000000b30
 HP-Capability-Advert = 0x011a0000000b3d
 HP-Capability-Advert = 0x0138
 HP-Capability-Advert = 0x013a
 HP-Capability-Advert = 0x0140
 HP-Capability-Advert = 0x0141
 HP-Capability-Advert = 0x0151
 Proxy-State = 0x3830
Going to the next request
Waking up in 0.9 seconds.
Waking up in 2.1 seconds.
Waking up in 7.5 seconds.
rad_recv: Access-Request packet from host xx.xx.35.130 port 1812, id=80, length=379
Sending duplicate proxied request to home server xxx.xxx.158.50 port 1812 - ID: 168
Sending Access-Request of id 168 to xxx.xxx.158.50 port 1812
 Framed-MTU = 1480
 NAS-IP-Address = xx.xx.35.130
 NAS-Identifier = "HP-SwitchSW02-02"
 User-Name = "host/LAB_LTOP2.XXXXXX.com"
 Service-Type = Framed-User
 Framed-Protocol = PPP
 NAS-Port = 3
 NAS-Port-Type = Ethernet
 NAS-Port-Id = "3"
 Called-Station-Id = "xx-xx-34-d1-16-40"
 Calling-Station-Id = "xx-xx-38-08-f9-7f"
 Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
 Tunnel-Type:0 = VLAN
 Tunnel-Medium-Type:0 = IEEE-802
 Tunnel-Private-Group-Id:0 = "1050"
 EAP-Message = 0x0218002301686f73742f53494d535f4c41425f4c544f50322e53505343534e2e636f6d
 Message-Authenticator = 0x00000000000000000000000000000000
 MS-RAS-Vendor = 11
 HP-Capability-Advert = 0x011a0000000b28
 HP-Capability-Advert = 0x011a0000000b2e
 HP-Capability-Advert = 0x011a0000000b30
 HP-Capability-Advert = 0x011a0000000b3d
 HP-Capability-Advert = 0x0138
 HP-Capability-Advert = 0x013a
 HP-Capability-Advert = 0x0140
 HP-Capability-Advert = 0x0141
 HP-Capability-Advert = 0x0151
 Proxy-State = 0x3830
Waking up in 5.7 seconds.
rad_recv: Access-Request packet from host xx.xx.35.130 port 1812, id=80, length=379
Marking home server xxx.xxx.158.50 port 1812 as dead.
Failed to find live home server for request 4
  Found Post-Proxy-Type
+- entering group Fail {...}
-------  MyModule post-proxy  module: my_module_auth_postproxy host/LAB_LTOP2.XXXXXX.com
++[my_module_auth] returns ok
ERROR: Failed to find live home server for realm remote_proxy_ad
  Found Post-Proxy-Type
+- entering group Fail {...}
-------  MyModule post-proxy  module: my_module_auth_postproxy host/LAB_LTOP2.XXXXXX.com
++[my_module_auth] returns ok
There was no response configured: rejecting request 4
Using Post-Auth-Type Reject
+- entering group REJECT {...}
-------  MyModule post-authentication  module: my_module_auth_postauth
++[my_module_auth] returns fail
Sending Access-Reject of id 80 to xx.xx.35.130 port 1812
Finished request 4.
Going to the next request
Waking up in 0.7 seconds.
Cleaning up request 3 ID 79 with timestamp +1242
Waking up in 4.2 seconds.
Cleaning up request 4 ID 80 with timestamp +1265
Waking up in 118.9 seconds.
Marking home server xxx.xxx.158.50 port 1812 alive again... we have no idea if it really is alive or not.
Ready to process requests.