rad_recv: Access-Request packet from host 10.117.80.168 port 62503, id=162, length=93 Thu Sep 17 15:00:42 2009 : Debug: server dynamic_client_server { Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Calling decode_attribute with {User-Name} Thu Sep 17 15:00:42 2009 : Info: decode_attribute: {User-Name} Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Back from decode_attribute with Thu Sep 17 15:00:42 2009 : Debug: rlm_sql (sqlaugs): Ignoring unconnected handle 4.. Thu Sep 17 15:00:42 2009 : Debug: rlm_sql (sqlaugs): Ignoring unconnected handle 3.. Thu Sep 17 15:00:42 2009 : Debug: rlm_sql (sqlaugs): Ignoring unconnected handle 2.. Thu Sep 17 15:00:42 2009 : Debug: rlm_sql (sqlaugs): Ignoring unconnected handle 1.. Thu Sep 17 15:00:42 2009 : Debug: rlm_sql (sqlaugs): Ignoring unconnected handle 0.. Thu Sep 17 15:00:42 2009 : Info: rlm_sql (sqlaugs): There are no DB handles to use! skipped 5, tried to connect 0 Thu Sep 17 15:00:42 2009 : Error: rlm_sql: Error getting sql socket - returning FAIL Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Calling decode_attribute with {User-Name} Thu Sep 17 15:00:42 2009 : Info: decode_attribute: {User-Name} Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Back from decode_attribute with Thu Sep 17 15:00:42 2009 : Debug: rlm_sql (sqlroch): Reserving sql socket id: 4 Thu Sep 17 15:00:42 2009 : Info: rlm_sql: Xlating authorize_check_query... Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Calling decode_attribute with {SQL-User-Name}',NULL,NULL,NULL Thu Sep 17 15:00:42 2009 : Info: decode_attribute: {SQL-User-Name}',NULL,NULL,NULL Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Back from decode_attribute with Thu Sep 17 15:00:42 2009 : Debug: query: SELECT 1,'',NULL,NULL,NULL Thu Sep 17 15:00:42 2009 : Info: rlm_sql: Calling rlm_sql_process_groups... Thu Sep 17 15:00:42 2009 : Info: rlm_sql: Found 0 groups Thu Sep 17 15:00:42 2009 : Debug: rlm_sql (sqlroch): Released sql socket id: 4 Thu Sep 17 15:00:42 2009 : Info: rlm_sql: Finished rlm_sql_authorize Thu Sep 17 15:00:42 2009 : Info: radius_evaluate_condition: ("%{sqlroch: SELECT nasname FROM nas WHERE nasname = '%{Packet-Src-IP-Address}'}") Thu Sep 17 15:00:42 2009 : Info: >>> RECURSING WITH ... "%{sqlroch: SELECT nasname FROM nas WHERE nasname = '%{Packet-Src-IP-Address}'}") Thu Sep 17 15:00:42 2009 : Info: radius_evaluate_condition: "%{sqlroch: SELECT nasname FROM nas WHERE nasname = '%{Packet-Src-IP-Address}'}") Thu Sep 17 15:00:42 2009 : Info: >>> LOOKING AT "%{sqlroch: SELECT nasname FROM nas WHERE nasname = '%{Packet-Src-IP-Address}'}") Thu Sep 17 15:00:42 2009 : Info: expand_string: Calling radius_xlat with %{sqlroch: SELECT nasname FROM nas WHERE nasname = '%{Packet-Src-IP-Address}'} Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Calling decode_attribute with {sqlroch: SELECT nasname FROM nas WHERE nasname = '%{Packet-Src-IP-Address}'} Thu Sep 17 15:00:42 2009 : Info: decode_attribute: {sqlroch: SELECT nasname FROM nas WHERE nasname = '%{Packet-Src-IP-Address}'} Thu Sep 17 15:00:42 2009 : Info: rlm_sql_xlat: Called with ' SELECT nasname FROM nas WHERE nasname = '%{Packet-Src-IP-Address}'' Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Calling decode_attribute with {User-Name} Thu Sep 17 15:00:42 2009 : Info: decode_attribute: {User-Name} Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Back from decode_attribute with Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Calling decode_attribute with {Packet-Src-IP-Address}' Thu Sep 17 15:00:42 2009 : Info: decode_attribute: {Packet-Src-IP-Address}' Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Back from decode_attribute with Thu Sep 17 15:00:42 2009 : Info: rlm_sql_xlat: radius_xlat returned ' SELECT nasname FROM nas WHERE nasname = '10.117.80.168'' Thu Sep 17 15:00:42 2009 : Debug: rlm_sql (sqlroch): Reserving sql socket id: 3 Thu Sep 17 15:00:42 2009 : Debug: query: SELECT nasname FROM nas WHERE nasname = '10.117.80.168' Thu Sep 17 15:00:42 2009 : Debug: rlm_sql (sqlroch): Released sql socket id: 3 Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Back from decode_attribute with Thu Sep 17 15:00:42 2009 : Info: >>> Comparison returned 1 Thu Sep 17 15:00:42 2009 : Info: >>> GOT result 1 Thu Sep 17 15:00:42 2009 : Info: >>> AT EOL -> 1 Thu Sep 17 15:00:42 2009 : Info: >>> AFTER RECURSION ... ) Thu Sep 17 15:00:42 2009 : Info: >>> AT EOL -> 1 Thu Sep 17 15:00:42 2009 : Info: expand_string: Calling radius_xlat with %{Packet-Src-IP-Address} Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Calling decode_attribute with {Packet-Src-IP-Address} Thu Sep 17 15:00:42 2009 : Info: decode_attribute: {Packet-Src-IP-Address} Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Back from decode_attribute with Thu Sep 17 15:00:42 2009 : Info: expand_string: Calling radius_xlat with %{sqlroch: SELECT shortname FROM nas WHERE nasname = '%{Packet-Src-IP-Address}'} Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Calling decode_attribute with {sqlroch: SELECT shortname FROM nas WHERE nasname = '%{Packet-Src-IP-Address}'} Thu Sep 17 15:00:42 2009 : Info: decode_attribute: {sqlroch: SELECT shortname FROM nas WHERE nasname = '%{Packet-Src-IP-Address}'} Thu Sep 17 15:00:42 2009 : Info: rlm_sql_xlat: Called with ' SELECT shortname FROM nas WHERE nasname = '%{Packet-Src-IP-Address}'' Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Calling decode_attribute with {User-Name} Thu Sep 17 15:00:42 2009 : Info: decode_attribute: {User-Name} Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Back from decode_attribute with Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Calling decode_attribute with {Packet-Src-IP-Address}' Thu Sep 17 15:00:42 2009 : Info: decode_attribute: {Packet-Src-IP-Address}' Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Back from decode_attribute with Thu Sep 17 15:00:42 2009 : Info: rlm_sql_xlat: radius_xlat returned ' SELECT shortname FROM nas WHERE nasname = '10.117.80.168'' Thu Sep 17 15:00:42 2009 : Debug: rlm_sql (sqlroch): Reserving sql socket id: 2 Thu Sep 17 15:00:42 2009 : Debug: query: SELECT shortname FROM nas WHERE nasname = '10.117.80.168' Thu Sep 17 15:00:42 2009 : Debug: rlm_sql (sqlroch): Released sql socket id: 2 Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Back from decode_attribute with Thu Sep 17 15:00:42 2009 : Info: expand_string: Calling radius_xlat with %{sqlroch: SELECT secret FROM nas WHERE nasname = '%{Packet-Src-IP-Address}'} Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Calling decode_attribute with {sqlroch: SELECT secret FROM nas WHERE nasname = '%{Packet-Src-IP-Address}'} Thu Sep 17 15:00:42 2009 : Info: decode_attribute: {sqlroch: SELECT secret FROM nas WHERE nasname = '%{Packet-Src-IP-Address}'} Thu Sep 17 15:00:42 2009 : Info: rlm_sql_xlat: Called with ' SELECT secret FROM nas WHERE nasname = '%{Packet-Src-IP-Address}'' Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Calling decode_attribute with {User-Name} Thu Sep 17 15:00:42 2009 : Info: decode_attribute: {User-Name} Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Back from decode_attribute with Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Calling decode_attribute with {Packet-Src-IP-Address}' Thu Sep 17 15:00:42 2009 : Info: decode_attribute: {Packet-Src-IP-Address}' Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Back from decode_attribute with Thu Sep 17 15:00:42 2009 : Info: rlm_sql_xlat: radius_xlat returned ' SELECT secret FROM nas WHERE nasname = '10.117.80.168'' Thu Sep 17 15:00:42 2009 : Debug: rlm_sql (sqlroch): Reserving sql socket id: 1 Thu Sep 17 15:00:42 2009 : Debug: query: SELECT secret FROM nas WHERE nasname = '10.117.80.168' Thu Sep 17 15:00:42 2009 : Debug: rlm_sql (sqlroch): Released sql socket id: 1 Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Back from decode_attribute with Thu Sep 17 15:00:42 2009 : Info: expand_string: Calling radius_xlat with %{sqlroch: SELECT type FROM nas WHERE nasname = '%{Packet-Src-IP-Address}'} Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Calling decode_attribute with {sqlroch: SELECT type FROM nas WHERE nasname = '%{Packet-Src-IP-Address}'} Thu Sep 17 15:00:42 2009 : Info: decode_attribute: {sqlroch: SELECT type FROM nas WHERE nasname = '%{Packet-Src-IP-Address}'} Thu Sep 17 15:00:42 2009 : Info: rlm_sql_xlat: Called with ' SELECT type FROM nas WHERE nasname = '%{Packet-Src-IP-Address}'' Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Calling decode_attribute with {User-Name} Thu Sep 17 15:00:42 2009 : Info: decode_attribute: {User-Name} Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Back from decode_attribute with Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Calling decode_attribute with {Packet-Src-IP-Address}' Thu Sep 17 15:00:42 2009 : Info: decode_attribute: {Packet-Src-IP-Address}' Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Back from decode_attribute with Thu Sep 17 15:00:42 2009 : Info: rlm_sql_xlat: radius_xlat returned ' SELECT type FROM nas WHERE nasname = '10.117.80.168'' Thu Sep 17 15:00:42 2009 : Debug: rlm_sql (sqlroch): Reserving sql socket id: 0 Thu Sep 17 15:00:42 2009 : Debug: query: SELECT type FROM nas WHERE nasname = '10.117.80.168' Thu Sep 17 15:00:42 2009 : Debug: rlm_sql (sqlroch): Released sql socket id: 0 Thu Sep 17 15:00:42 2009 : Info: radius_xlat: Back from decode_attribute with Thu Sep 17 15:00:42 2009 : Info: ::: FROM 4 TO 0 MAX 4 Thu Sep 17 15:00:42 2009 : Info: ::: Examining FreeRADIUS-Client-IP-Address Thu Sep 17 15:00:42 2009 : Info: ::: APPENDING FreeRADIUS-Client-IP-Address FROM 0 TO 0 Thu Sep 17 15:00:42 2009 : Info: ::: Examining FreeRADIUS-Client-Shortname Thu Sep 17 15:00:42 2009 : Info: ::: APPENDING FreeRADIUS-Client-Shortname FROM 1 TO 1 Thu Sep 17 15:00:42 2009 : Info: ::: Examining FreeRADIUS-Client-Secret Thu Sep 17 15:00:42 2009 : Info: ::: APPENDING FreeRADIUS-Client-Secret FROM 2 TO 2 Thu Sep 17 15:00:42 2009 : Info: ::: Examining FreeRADIUS-Client-NAS-Type Thu Sep 17 15:00:42 2009 : Info: ::: APPENDING FreeRADIUS-Client-NAS-Type FROM 3 TO 3 Thu Sep 17 15:00:42 2009 : Info: ::: TO in 0 out 4 Thu Sep 17 15:00:42 2009 : Info: ::: to[0] = FreeRADIUS-Client-IP-Address Thu Sep 17 15:00:42 2009 : Info: ::: to[1] = FreeRADIUS-Client-Shortname Thu Sep 17 15:00:42 2009 : Info: ::: to[2] = FreeRADIUS-Client-Secret Thu Sep 17 15:00:42 2009 : Info: ::: to[3] = FreeRADIUS-Client-NAS-Type Thu Sep 17 15:00:42 2009 : Debug: } # server dynamic_client_server Thu Sep 17 15:00:42 2009 : Debug: - Added client 10.117.80.168 with shared secret xxxxxxxx