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