search

FreeRADIUS / freeradius-server

FreeRADIUS - A multi-protocol policy server.
http://freeradius.org
GNU General Public License v2.0
2.11k stars 1.08k forks source link

3.0.0: 'Null value in first column' in unixodbc xlat #457

Closed michael-mri closed 11 years ago

michael-mri commented 11 years ago

When using UnixODBC to connect to MSSQL db (tried it with posgresql odbc driver and does the same), it works on the first request, then fails:

 Debug: rlm_sql (sql): Reserved connection (4)
 Debug: rlm_sql (sql): Executing query: 'SELECT username from mytest WHERE csid = 'FFFFFFFFFFF0''
 Debug: (0) sql_xlat finished
 Debug: rlm_sql (sql): Released connection (4)
 Info: rlm_sql (sql): Closing connection (0): Too many free connections (5 > 3)
 Debug: rlm_sql_unixodbc: Socket destructor called, closing socket
Tue Oct 22 05:39:55 2013 : Debug: (0)     expand: "%{sql:SELECT username from mytest WHERE csid = '%{Calling-Station-Id}'}" -> 'test'

But one second request, it fails (returns empty string) saying 'Null value in first column':

 Debug: rlm_sql (sql): Executing query: 'SELECT username from mytest WHERE csid = 'FFFFFFFFFFF0''
 Debug: (1) Null value in first column
 Debug: rlm_sql (sql): Released connection (4)
 Info: rlm_sql (sql): Closing connection (1): Too many free connections (4 > 3)
 Debug: rlm_sql_unixodbc: Socket destructor called, closing socket
 Info: rlm_sql (sql): Closing connection (3): Hit idle_timeout, was idle for 123 seconds
  rlm_sql (sql): You probably need to lower "min"
 Debug: rlm_sql_unixodbc: Socket destructor called, closing socket
 Info: rlm_sql (sql): Closing connection (2): Hit idle_timeout, was idle for 123 seconds
 Debug: rlm_sql_unixodbc: Socket destructor called, closing socket
 Debug: (1)     expand: "%{sql:SELECT username from mytest WHERE csid = '%{Calling-Station-Id}'}" -> ''

Sometimes it works with further requests, sometimes not... It seems to work when a new connection to DB is made:

 Debug: rlm_sql (sql): Released connection (5)
 Info: rlm_sql (sql): Opening additional connection (6)
 Debug: (8)     expand: "%{sql:SELECT username from mytest WHERE csid = '%{Calling-Station-Id}'}" -> 'test'
 Debug: (8)         Tmp-String-0 := "test"

Full debug:

# /usr/local/sbin/radiusd -l stdout -fxxxx -d /usr/local/etc/raddb
Info: radiusd: FreeRADIUS Version 3.0.1 (git #4c389d4), for host x86_64-unknown-linux-gnu, built on Oct 21 2013 at 11:55:37
Debug: Server was built with: 
Debug:   accounting
Debug:   authentication
Debug:   ascend binary attributes
Debug:   coa
Debug:   control-socket
Debug:   detail
Debug:   dhcp
Debug:   dynamic clients
Debug:   proxy
Debug:   regex-pcre
Debug:   session-management
Debug:   stats
Debug:   tcp
Debug:   threads
Debug:   tls
Debug:   unlang
Debug:   vmps
Debug: Server core libs:
Debug:   talloc : 2.0.*
Debug:   ssl    : OpenSSL 0.9.8e-fips-rhel5 01 Jul 2008
Info: Copyright (C) 1999-2013 The FreeRADIUS server project and contributors.
Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
Info: PARTICULAR PURPOSE.
Info: You may redistribute copies of FreeRADIUS under the terms of the
Info: GNU General Public License.
Info: For more information about these matters, see the file named COPYRIGHT.
Info: Starting - reading configuration files ...
Debug: including dictionary file /usr/local/etc/raddb/dictionary
Debug: including configuration file /usr/local/etc/raddb/radiusd.conf
Debug: including configuration file /usr/local/etc/raddb/proxy.conf
Debug: including configuration file /usr/local/etc/raddb/clients.conf
Debug: including files in directory /usr/local/etc/raddb/mods-enabled/
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/sradutmp
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/unix
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/utf8
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/ntlm_auth
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/attr_filter
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/always
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/linelog
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/realm
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/soh
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/dynamic_clients
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/detail.log
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/sql
Debug: including configuration file /usr/local/etc/raddb/mods-config/sql/main/mssql/queries.conf
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/echo
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/passwd
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/expr
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/chap
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/replicate
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/digest
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/detail
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/preprocess
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/cache_eap
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/logintime
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/dhcp
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/eap
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/files
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/pap
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/radutmp
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/exec
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/mschap
Debug: including configuration file /usr/local/etc/raddb/mods-enabled/expiration
Debug: including files in directory /usr/local/etc/raddb/policy.d/
Debug: including configuration file /usr/local/etc/raddb/policy.d/canonicalization
Debug: including configuration file /usr/local/etc/raddb/policy.d/control
Debug: including configuration file /usr/local/etc/raddb/policy.d/operator-name
Debug: including configuration file /usr/local/etc/raddb/policy.d/filter
Debug: including configuration file /usr/local/etc/raddb/policy.d/accounting
Debug: including configuration file /usr/local/etc/raddb/policy.d/dhcp
Debug: including configuration file /usr/local/etc/raddb/policy.d/eap
Debug: including configuration file /usr/local/etc/raddb/policy.d/cui
Debug: including files in directory /usr/local/etc/raddb/sites-enabled/
Debug: including configuration file /usr/local/etc/raddb/sites-enabled/default
Debug: including configuration file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Debug: main {
Debug:  security {
Debug:      allow_core_dumps = no
Debug:  }
Debug: }
Debug: main {
Debug:  name = "radiusd"
Debug:  prefix = "/usr/local"
Debug:  localstatedir = "/usr/local/var"
Debug:  sbindir = "/usr/local/sbin"
Debug:  logdir = "/usr/local/var/log/radius"
Debug:  run_dir = "/usr/local/var/run/radiusd"
Debug:  libdir = "/usr/local/lib"
Debug:  radacctdir = "/usr/local/var/log/radius/radacct"
Debug:  hostname_lookups = no
Debug:  max_request_time = 30
Debug:  cleanup_delay = 5
Debug:  max_requests = 1024
Debug:  pidfile = "/usr/local/var/run/radiusd/radiusd.pid"
Debug:  checkrad = "/usr/local/sbin/checkrad"
Debug:  debug_level = 0
Debug:  proxy_requests = yes
Debug:  log {
Debug:      stripped_names = no
Debug:      auth = no
Debug:      auth_badpass = no
Debug:      auth_goodpass = no
Debug:      colourise = yes
Debug:  }
Debug:  security {
Debug:      max_attributes = 200
Debug:      reject_delay = 1
Debug:      status_server = yes
Debug:  }
Debug: }
Debug: radiusd: #### Loading Realms and Home Servers ####
Debug:  proxy server {
Debug:      retry_delay = 5
Debug:      retry_count = 3
Debug:      default_fallback = no
Debug:      dead_time = 120
Debug:      wake_all_if_all_dead = no
Debug:  }
Debug:  home_server localhost {
Debug:      ipaddr = 127.0.0.1
Debug:      port = 1812
Debug:      type = "auth"
Debug:      secret = "testing123"
Debug:      response_window = 20
Debug:      max_outstanding = 65536
Debug:      zombie_period = 40
Debug:      status_check = "status-server"
Debug:      ping_interval = 30
Debug:      check_interval = 30
Debug:      num_answers_to_alive = 3
Debug:      revive_interval = 120
Debug:      status_check_timeout = 4
Debug:   coa {
Debug:      irt = 2
Debug:      mrt = 16
Debug:      mrc = 5
Debug:      mrd = 30
Debug:   }
Debug:   limit {
Debug:      max_connections = 16
Debug:      max_requests = 0
Debug:      lifetime = 0
Debug:      idle_timeout = 0
Debug:   }
Debug:  }
Debug:  home_server_pool my_auth_failover {
Debug:  type = fail-over
Debug:  home_server = localhost
Debug:  }
Debug:  realm example.com {
Debug:  auth_pool = my_auth_failover
Debug:  }
Debug:  realm LOCAL {
Debug:  }
Debug: radiusd: #### Loading Clients ####
Debug:  client localhost {
Debug:      ipaddr = 127.0.0.1
Debug:      require_message_authenticator = no
Debug:      secret = "testing123"
Debug:      nas_type = "other"
Debug:      proto = "*"
Debug:   limit {
Debug:      max_connections = 16
Debug:      lifetime = 0
Debug:      idle_timeout = 30
Debug:   }
Debug:  }
Debug:  client 127.0.156.5 {
Debug:      require_message_authenticator = no
Debug:      secret = "Secret"
Debug:      shortname = "local-test"
Debug:   limit {
Debug:      max_connections = 16
Debug:      lifetime = 0
Debug:      idle_timeout = 30
Debug:   }
Debug:  }
Debug: radiusd: #### Instantiating modules ####
Debug:  instantiate {
Debug:  }
Debug:  modules {
Debug:     (Loaded rlm_radutmp, checking if it's valid)
Debug:   # Loaded module rlm_radutmp
Debug:   # Instantiating module "sradutmp" from file /usr/local/etc/raddb/mods-enabled/sradutmp
Debug:   radutmp sradutmp {
Debug:      filename = "/usr/local/var/log/radius/sradutmp"
Debug:      username = "%{User-Name}"
Debug:      case_sensitive = yes
Debug:      check_with_nas = yes
Debug:      permissions = 420
Debug:      caller_id = no
Debug:   }
Debug:     (Loaded rlm_unix, checking if it's valid)
Debug:   # Loaded module rlm_unix
Debug:   # Instantiating module "unix" from file /usr/local/etc/raddb/mods-enabled/unix
Debug:   unix {
Debug:      radwtmp = "/usr/local/var/log/radius/radwtmp"
Debug:   }
Debug:     (Loaded rlm_utf8, checking if it's valid)
Debug:   # Loaded module rlm_utf8
Debug:   # Instantiating module "utf8" from file /usr/local/etc/raddb/mods-enabled/utf8
Debug:     (Loaded rlm_exec, checking if it's valid)
Debug:   # Loaded module rlm_exec
Debug:   # Instantiating module "ntlm_auth" from file /usr/local/etc/raddb/mods-enabled/ntlm_auth
Debug:   exec ntlm_auth {
Debug:      wait = yes
Debug:      program = "/path/to/ntlm_auth --request-nt-key --domain=MYDOMAIN --username=%{mschap:User-Name} --password=%{User-Password}"
Debug:      shell_escape = yes
Debug:   }
Debug:     (Loaded rlm_attr_filter, checking if it's valid)
Debug:   # Loaded module rlm_attr_filter
Debug:   # Instantiating module "attr_filter.post-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter
Debug:   attr_filter attr_filter.post-proxy {
Debug:      filename = "/usr/local/etc/raddb/mods-config/attr_filter/post-proxy"
Debug:      key = "%{Realm}"
Debug:      relaxed = no
Debug:   }
Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/post-proxy
Debug:   # Instantiating module "attr_filter.pre-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter
Debug:   attr_filter attr_filter.pre-proxy {
Debug:      filename = "/usr/local/etc/raddb/mods-config/attr_filter/pre-proxy"
Debug:      key = "%{Realm}"
Debug:      relaxed = no
Debug:   }
Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/pre-proxy
Debug:   # Instantiating module "attr_filter.access_reject" from file /usr/local/etc/raddb/mods-enabled/attr_filter
Debug:   attr_filter attr_filter.access_reject {
Debug:      filename = "/usr/local/etc/raddb/mods-config/attr_filter/access_reject"
Debug:      key = "%{User-Name}"
Debug:      relaxed = no
Debug:   }
Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/access_reject
Debug:   # Instantiating module "attr_filter.access_challenge" from file /usr/local/etc/raddb/mods-enabled/attr_filter
Debug:   attr_filter attr_filter.access_challenge {
Debug:      filename = "/usr/local/etc/raddb/mods-config/attr_filter/access_challenge"
Debug:      key = "%{User-Name}"
Debug:      relaxed = no
Debug:   }
Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/access_challenge
Debug:   # Instantiating module "attr_filter.accounting_response" from file /usr/local/etc/raddb/mods-enabled/attr_filter
Debug:   attr_filter attr_filter.accounting_response {
Debug:      filename = "/usr/local/etc/raddb/mods-config/attr_filter/accounting_response"
Debug:      key = "%{User-Name}"
Debug:      relaxed = no
Debug:   }
Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/accounting_response
Debug:     (Loaded rlm_always, checking if it's valid)
Debug:   # Loaded module rlm_always
Debug:   # Instantiating module "fail" from file /usr/local/etc/raddb/mods-enabled/always
Debug:   always fail {
Debug:      rcode = "fail"
Debug:      simulcount = 0
Debug:      mpp = no
Debug:   }
Debug:   # Instantiating module "reject" from file /usr/local/etc/raddb/mods-enabled/always
Debug:   always reject {
Debug:      rcode = "reject"
Debug:      simulcount = 0
Debug:      mpp = no
Debug:   }
Debug:   # Instantiating module "noop" from file /usr/local/etc/raddb/mods-enabled/always
Debug:   always noop {
Debug:      rcode = "noop"
Debug:      simulcount = 0
Debug:      mpp = no
Debug:   }
Debug:   # Instantiating module "handled" from file /usr/local/etc/raddb/mods-enabled/always
Debug:   always handled {
Debug:      rcode = "handled"
Debug:      simulcount = 0
Debug:      mpp = no
Debug:   }
Debug:   # Instantiating module "updated" from file /usr/local/etc/raddb/mods-enabled/always
Debug:   always updated {
Debug:      rcode = "updated"
Debug:      simulcount = 0
Debug:      mpp = no
Debug:   }
Debug:   # Instantiating module "notfound" from file /usr/local/etc/raddb/mods-enabled/always
Debug:   always notfound {
Debug:      rcode = "notfound"
Debug:      simulcount = 0
Debug:      mpp = no
Debug:   }
Debug:   # Instantiating module "ok" from file /usr/local/etc/raddb/mods-enabled/always
Debug:   always ok {
Debug:      rcode = "ok"
Debug:      simulcount = 0
Debug:      mpp = no
Debug:   }
Debug:     (Loaded rlm_linelog, checking if it's valid)
Debug:   # Loaded module rlm_linelog
Debug:   # Instantiating module "linelog" from file /usr/local/etc/raddb/mods-enabled/linelog
Debug:   linelog {
Debug:      filename = "/usr/local/var/log/radius/linelog"
Debug:      permissions = 384
Debug:      format = "This is a log message for %{User-Name}"
Debug:      reference = "%{%{Packet-Type}:-format}"
Debug:   }
Debug:     (Loaded rlm_realm, checking if it's valid)
Debug:   # Loaded module rlm_realm
Debug:   # Instantiating module "IPASS" from file /usr/local/etc/raddb/mods-enabled/realm
Debug:   realm IPASS {
Debug:      format = "prefix"
Debug:      delimiter = "/"
Debug:      ignore_default = no
Debug:      ignore_null = no
Debug:   }
Debug:   # Instantiating module "suffix" from file /usr/local/etc/raddb/mods-enabled/realm
Debug:   realm suffix {
Debug:      format = "suffix"
Debug:      delimiter = "@"
Debug:      ignore_default = no
Debug:      ignore_null = no
Debug:   }
Debug:   # Instantiating module "realmpercent" from file /usr/local/etc/raddb/mods-enabled/realm
Debug:   realm realmpercent {
Debug:      format = "suffix"
Debug:      delimiter = "%"
Debug:      ignore_default = no
Debug:      ignore_null = no
Debug:   }
Debug:   # Instantiating module "ntdomain" from file /usr/local/etc/raddb/mods-enabled/realm
Debug:   realm ntdomain {
Debug:      format = "prefix"
Debug:      delimiter = "\"
Debug:      ignore_default = no
Debug:      ignore_null = no
Debug:   }
Debug:     (Loaded rlm_soh, checking if it's valid)
Debug:   # Loaded module rlm_soh
Debug:   # Instantiating module "soh" from file /usr/local/etc/raddb/mods-enabled/soh
Debug:   soh {
Debug:      dhcp = yes
Debug:   }
Debug:     (Loaded rlm_dynamic_clients, checking if it's valid)
Debug:   # Loaded module rlm_dynamic_clients
Debug:   # Instantiating module "dynamic_clients" from file /usr/local/etc/raddb/mods-enabled/dynamic_clients
Debug:     (Loaded rlm_detail, checking if it's valid)
Debug:   # Loaded module rlm_detail
Debug:   # Instantiating module "auth_log" from file /usr/local/etc/raddb/mods-enabled/detail.log
Debug:   detail auth_log {
Debug:      filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d"
Debug:      header = "%t"
Debug:      permissions = 384
Debug:      dir_permissions = 493
Debug:      locking = no
Debug:      log_packet_header = no
Debug:   }
Debug:   # Instantiating module "reply_log" from file /usr/local/etc/raddb/mods-enabled/detail.log
Debug:   detail reply_log {
Debug:      filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/reply-detail-%Y%m%d"
Debug:      header = "%t"
Debug:      permissions = 384
Debug:      dir_permissions = 493
Debug:      locking = no
Debug:      log_packet_header = no
Debug:   }
Debug:   # Instantiating module "pre_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log
Debug:   detail pre_proxy_log {
Debug:      filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d"
Debug:      header = "%t"
Debug:      permissions = 384
Debug:      dir_permissions = 493
Debug:      locking = no
Debug:      log_packet_header = no
Debug:   }
Debug:   # Instantiating module "post_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log
Debug:   detail post_proxy_log {
Debug:      filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d"
Debug:      header = "%t"
Debug:      permissions = 384
Debug:      dir_permissions = 493
Debug:      locking = no
Debug:      log_packet_header = no
Debug:   }
Debug:     (Loaded rlm_sql, checking if it's valid)
Debug:   # Loaded module rlm_sql
Debug:   # Instantiating module "sql" from file /usr/local/etc/raddb/mods-enabled/sql
Debug:   sql {
Debug:      driver = "rlm_sql_unixodbc"
Debug:      server = "prodDB"
Debug:      port = ""
Debug:      login = "test"
Debug:      password = "test"
Debug:      radius_db = "radius"
Debug:      read_groups = yes
Debug:      read_clients = no
Debug:      delete_stale_sessions = yes
Debug:      sql_user_name = "%{User-Name}"
Debug:      default_user_profile = ""
Debug:      client_query = "SELECT id,nasname,shortname,type,secret FROM nas"
Debug:      authorize_check_query = "SELECT id,UserName,Attribute,Value,op               FROM radcheck               WHERE Username = '%{SQL-User-Name}'                 ORDER BY id"
Debug:      authorize_reply_query = "SELECT id,UserName,Attribute,Value,op               FROM radreply               WHERE Username = '%{SQL-User-Name}'                 ORDER BY id"
Debug:      authorize_group_check_query = "SELECT radgroupcheck.id,radgroupcheck.GroupName,                         radgroupcheck.Attribute,radgroupcheck.Value,                radgroupcheck.op                       FROM radgroupcheck,radusergroup                     WHERE radusergroup.Username = '%{SQL-User-Name}'                        AND radusergroup.GroupName = radgroupcheck.GroupName                        ORDER BY radgroupcheck.id"
Debug:      authorize_group_reply_query = "SELECT radgroupreply.id,radgroupreply.GroupName,                         radgroupreply.Attribute,radgroupreply.Value,                radgroupreply.op                       FROM radgroupreply,radusergroup                     WHERE radusergroup.Username = '%{SQL-User-Name}'                        AND radusergroup.GroupName = radgroupreply.GroupName                        ORDER BY radgroupreply.id"
Debug:      group_membership_query = "SELECT groupname           FROM radusergroup           WHERE username = '%{SQL-User-Name}'           ORDER BY priority"
Debug:      simul_count_query = ""
Debug:      simul_verify_query = ""
Debug:      safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Debug:   }
Debug:    accounting {
Debug:      reference = "%{tolower:type.%{Acct-Status-Type}.query}"
Debug:    }
Debug:    post-auth {
Debug:      reference = ".query"
Debug:    }
Info: rlm_sql (sql): Driver rlm_sql_unixodbc (module rlm_sql_unixodbc) loaded and linked
Info: rlm_sql (sql): Attempting to connect to database "radius"
Debug: rlm_sql (sql): Initialising connection pool
Debug:    pool {
Debug:      start = 5
Debug:      min = 4
Debug:      max = 10
Debug:      spare = 3
Debug:      uses = 0
Debug:      lifetime = 0
Debug:      cleanup_delay = 5
Debug:      idle_timeout = 60
Debug:      spread = no
Debug:    }
Info: rlm_sql (sql): Opening additional connection (0)
Info: rlm_sql (sql): Opening additional connection (1)
Info: rlm_sql (sql): Opening additional connection (2)
Info: rlm_sql (sql): Opening additional connection (3)
Info: rlm_sql (sql): Opening additional connection (4)
Debug:   # Instantiating module "echo" from file /usr/local/etc/raddb/mods-enabled/echo
Debug:   exec echo {
Debug:      wait = yes
Debug:      program = "/bin/echo %{User-Name}"
Debug:      input_pairs = "request"
Debug:      output_pairs = "reply"
Debug:      shell_escape = yes
Debug:   }
Debug:     (Loaded rlm_passwd, checking if it's valid)
Debug:   # Loaded module rlm_passwd
Debug:   # Instantiating module "etc_passwd" from file /usr/local/etc/raddb/mods-enabled/passwd
Debug:   passwd etc_passwd {
Debug:      filename = "/etc/passwd"
Debug:      format = "*User-Name:Crypt-Password:"
Debug:      delimiter = ":"
Debug:      ignore_nislike = no
Debug:      ignore_empty = yes
Debug:      allow_multiple_keys = no
Debug:      hash_size = 100
Debug:   }
Debug: rlm_passwd: nfields: 3 keyfield 0(User-Name) listable: no
Debug:     (Loaded rlm_expr, checking if it's valid)
Debug:   # Loaded module rlm_expr
Debug:   # Instantiating module "expr" from file /usr/local/etc/raddb/mods-enabled/expr
Debug:   expr {
Debug:      safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Debug:   }
Debug:     (Loaded rlm_chap, checking if it's valid)
Debug:   # Loaded module rlm_chap
Debug:   # Instantiating module "chap" from file /usr/local/etc/raddb/mods-enabled/chap
Debug:     (Loaded rlm_replicate, checking if it's valid)
Debug:   # Loaded module rlm_replicate
Debug:   # Instantiating module "replicate" from file /usr/local/etc/raddb/mods-enabled/replicate
Debug:     (Loaded rlm_digest, checking if it's valid)
Debug:   # Loaded module rlm_digest
Debug:   # Instantiating module "digest" from file /usr/local/etc/raddb/mods-enabled/digest
Debug:   # Instantiating module "detail" from file /usr/local/etc/raddb/mods-enabled/detail
Debug:   detail {
Debug:      filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d"
Debug:      header = "%t"
Debug:      permissions = 384
Debug:      dir_permissions = 493
Debug:      locking = no
Debug:      log_packet_header = no
Debug:   }
Debug:     (Loaded rlm_preprocess, checking if it's valid)
Debug:   # Loaded module rlm_preprocess
Debug:   # Instantiating module "preprocess" from file /usr/local/etc/raddb/mods-enabled/preprocess
Debug:   preprocess {
Debug:      huntgroups = "/usr/local/etc/raddb/mods-config/preprocess/huntgroups"
Debug:      hints = "/usr/local/etc/raddb/mods-config/preprocess/hints"
Debug:      with_ascend_hack = no
Debug:      ascend_channels_per_line = 23
Debug:      with_ntdomain_hack = no
Debug:      with_specialix_jetstream_hack = no
Debug:      with_cisco_vsa_hack = no
Debug:      with_alvarion_vsa_hack = no
Debug:   }
Debug: reading pairlist file /usr/local/etc/raddb/mods-config/preprocess/huntgroups
Debug: reading pairlist file /usr/local/etc/raddb/mods-config/preprocess/hints
Debug:     (Loaded rlm_cache, checking if it's valid)
Debug:   # Loaded module rlm_cache
Debug:   # Instantiating module "cache_eap" from file /usr/local/etc/raddb/mods-enabled/cache_eap
Debug:   cache cache_eap {
Debug:      key = "%{%{control:State}:-%{%{reply:State}:-%{State}}}"
Debug:      ttl = 15
Debug:      max_entries = 16384
Debug:      epoch = 0
Debug:      add_stats = no
Debug:   }
Debug:     (Loaded rlm_logintime, checking if it's valid)
Debug:   # Loaded module rlm_logintime
Debug:   # Instantiating module "logintime" from file /usr/local/etc/raddb/mods-enabled/logintime
Debug:   logintime {
Debug:      minimum_timeout = 60
Debug:   }
Debug:     (Loaded rlm_dhcp, checking if it's valid)
Debug:   # Loaded module rlm_dhcp
Debug:   # Instantiating module "dhcp" from file /usr/local/etc/raddb/mods-enabled/dhcp
Debug:     (Loaded rlm_eap, checking if it's valid)
Debug:   # Loaded module rlm_eap
Debug:   # Instantiating module "eap" from file /usr/local/etc/raddb/mods-enabled/eap
Debug:   eap {
Debug:      default_eap_type = "md5"
Debug:      timer_expire = 60
Debug:      ignore_unknown_eap_types = no
Debug:      mod_accounting_username_bug = no
Debug:      max_sessions = 4096
Debug:   }
Debug:    # Linked to sub-module rlm_eap_md5
Debug:    # Linked to sub-module rlm_eap_leap
Debug:    # Linked to sub-module rlm_eap_gtc
Debug:    gtc {
Debug:      challenge = "Password: "
Debug:      auth_type = "PAP"
Debug:    }
Debug:    # Linked to sub-module rlm_eap_tls
Debug:    tls {
Debug:      tls = "tls-common"
Debug:    }
Debug:    tls-config tls-common {
Debug:      rsa_key_exchange = no
Debug:      dh_key_exchange = yes
Debug:      rsa_key_length = 512
Debug:      dh_key_length = 512
Debug:      verify_depth = 0
Debug:      ca_path = "/usr/local/etc/raddb/certs"
Debug:      pem_file_type = yes
Debug:      private_key_file = "/usr/local/etc/raddb/certs/server.pem"
Debug:      certificate_file = "/usr/local/etc/raddb/certs/server.pem"
Debug:      ca_file = "/usr/local/etc/raddb/certs/ca.pem"
Debug:      private_key_password = "whatever"
Debug:      dh_file = "/usr/local/etc/raddb/certs/dh"
Debug:      fragment_size = 1024
Debug:      include_length = yes
Debug:      check_crl = no
Debug:      cipher_list = "DEFAULT"
Debug:     cache {
Debug:      enable = yes
Debug:      lifetime = 24
Debug:      max_entries = 255
Debug:     }
Debug:     verify {
Debug:     }
Debug:     ocsp {
Debug:      enable = no
Debug:      override_cert_url = yes
Debug:      url = "http://127.0.0.1/ocsp/"
Debug:      use_nonce = yes
Debug:      timeout = 0
Debug:      softfail = yes
Debug:     }
Debug:    }
Debug:    # Linked to sub-module rlm_eap_ttls
Debug:    ttls {
Debug:      tls = "tls-common"
Debug:      default_eap_type = "md5"
Debug:      copy_request_to_tunnel = no
Debug:      use_tunneled_reply = no
Debug:      virtual_server = "inner-tunnel"
Debug:      include_length = yes
Debug:      require_client_cert = no
Debug:    }
Debug: Using cached TLS configuration from previous invocation
Debug:    # Linked to sub-module rlm_eap_peap
Debug:    peap {
Debug:      tls = "tls-common"
Debug:      default_method = "mschapv2"
Debug:      copy_request_to_tunnel = no
Debug:      use_tunneled_reply = no
Debug:      proxy_tunneled_request_as_eap = yes
Debug:      virtual_server = "inner-tunnel"
Debug:      soh = no
Debug:      require_client_cert = no
Debug:    }
Debug: Using cached TLS configuration from previous invocation
Debug:    # Linked to sub-module rlm_eap_mschapv2
Debug:    mschapv2 {
Debug:      with_ntdomain_hack = no
Debug:      send_error = no
Debug:    }
Debug:     (Loaded rlm_files, checking if it's valid)
Debug:   # Loaded module rlm_files
Debug:   # Instantiating module "files" from file /usr/local/etc/raddb/mods-enabled/files
Debug:   files {
Debug:      filename = "/usr/local/etc/raddb/mods-config/files/authorize"
Debug:      usersfile = "/usr/local/etc/raddb/mods-config/files/authorize"
Debug:      acctusersfile = "/usr/local/etc/raddb/mods-config/files/accounting"
Debug:      preproxy_usersfile = "/usr/local/etc/raddb/mods-config/files/pre-proxy"
Debug:      compat = "no"
Debug:   }
Debug: reading pairlist file /usr/local/etc/raddb/mods-config/files/authorize
Debug: reading pairlist file /usr/local/etc/raddb/mods-config/files/authorize
Debug: reading pairlist file /usr/local/etc/raddb/mods-config/files/accounting
Debug: reading pairlist file /usr/local/etc/raddb/mods-config/files/pre-proxy
Debug:     (Loaded rlm_pap, checking if it's valid)
Debug:   # Loaded module rlm_pap
Debug:   # Instantiating module "pap" from file /usr/local/etc/raddb/mods-enabled/pap
Debug:   pap {
Debug:      auto_header = no
Debug:      normalise = yes
Debug:   }
Debug:   # Instantiating module "radutmp" from file /usr/local/etc/raddb/mods-enabled/radutmp
Debug:   radutmp {
Debug:      filename = "/usr/local/var/log/radius/radutmp"
Debug:      username = "%{User-Name}"
Debug:      case_sensitive = yes
Debug:      check_with_nas = yes
Debug:      permissions = 384
Debug:      caller_id = yes
Debug:   }
Debug:   # Instantiating module "exec" from file /usr/local/etc/raddb/mods-enabled/exec
Debug:   exec {
Debug:      wait = no
Debug:      input_pairs = "request"
Debug:      shell_escape = yes
Debug:   }
Debug:     (Loaded rlm_mschap, checking if it's valid)
Debug:   # Loaded module rlm_mschap
Debug:   # Instantiating module "mschap" from file /usr/local/etc/raddb/mods-enabled/mschap
Debug:   mschap {
Debug:      use_mppe = yes
Debug:      require_encryption = no
Debug:      require_strong = no
Debug:      with_ntdomain_hack = yes
Debug:    passchange {
Debug:    }
Debug:      allow_retry = yes
Debug:   }
Debug:     (Loaded rlm_expiration, checking if it's valid)
Debug:   # Loaded module rlm_expiration
Debug:   # Instantiating module "expiration" from file /usr/local/etc/raddb/mods-enabled/expiration
Debug:  } # modules
Debug: radiusd: #### Loading Virtual Servers ####
Debug: server { # from file /usr/local/etc/raddb/radiusd.conf
Debug: } # server
Debug: server default { # from file /usr/local/etc/raddb/sites-enabled/default
Debug:  # Creating Auth-Type = digest
Debug:  # Loading authenticate {...}
Debug:  # Loading authorize {...}
WARNING: WARNING: Ignoring "ldap" (see raddb/mods-available/README.rst)
Debug:  # Loading preacct {...}
Debug:  # Loading virtual module acct_unique
Debug:  # Loading accounting {...}
Debug:  # Loading post-proxy {...}
Debug:  # Loading post-auth {...}
Debug:  # Loading virtual module remove_reply_message_if_eap
Debug:  # Loading virtual module remove_reply_message_if_eap
Debug: } # server
Debug: server inner-tunnel { # from file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Debug:  # Loading authenticate {...}
Debug:  # Loading authorize {...}
WARNING: WARNING: Ignoring "ldap" (see raddb/mods-available/README.rst)
Debug:  # Loading session {...}
Debug:  # Loading post-proxy {...}
Debug:  # Loading post-auth {...}
Debug: } # server
Debug:  thread pool {
Debug:      start_servers = 5
Debug:      max_servers = 32
Debug:      min_spare_servers = 3
Debug:      max_spare_servers = 10
Debug:      max_requests_per_server = 0
Debug:      cleanup_delay = 5
Debug:      max_queue_size = 65536
Debug:      auto_limit_acct = no
Debug:  }
Debug: Thread spawned new child 1. Total threads in pool: 1
Debug: Thread spawned new child 2. Total threads in pool: 2
Debug: Thread spawned new child 3. Total threads in pool: 3
Debug: Thread spawned new child 4. Total threads in pool: 4
Debug: Thread spawned new child 5. Total threads in pool: 5
Debug: Thread pool initialized
Debug: radiusd: #### Opening IP addresses and Ports ####
Debug: Library not found at path "/usr/local/lib/proto_auth.so"
Debug: listen {
Debug:      type = "auth"
Debug:      ipaddr = *
Debug:      port = 0
Debug:    limit {
Debug:      max_connections = 16
Debug:      lifetime = 0
Debug:      idle_timeout = 30
Debug:    }
Debug: Thread 1 waiting to be assigned a request
Debug: Thread 2 waiting to be assigned a request
Debug: Thread 3 waiting to be assigned a request
Debug: Thread 4 waiting to be assigned a request
Debug: Thread 5 waiting to be assigned a request
Debug: Re-wait 4
Debug: Re-wait 3
Debug: Re-wait 2
Debug: }
Debug: Library not found at path "/usr/local/lib/proto_acct.so"
Debug: listen {
Debug:      type = "acct"
Debug:      ipaddr = *
Debug:      port = 0
Debug:    limit {
Debug:      max_connections = 16
Debug:      lifetime = 0
Debug:      idle_timeout = 30
Debug:    }
Debug: Re-wait 1
Debug: Re-wait 5
Debug: Re-wait 4
Debug: Re-wait 3
Debug: }
Debug: Library not found at path "/usr/local/lib/proto_auth.so"
Debug: listen {
Debug:      type = "auth"
Debug:      ipaddr = 127.0.0.1
Debug:      port = 18120
Debug: Re-wait 2
Debug: Re-wait 5
Debug: Re-wait 4
Debug: Re-wait 3
Debug: }
Debug: Listening on auth address * port 1812 as server default
Debug: Listening on acct address * port 1813 as server default
Debug: Listening on auth address 127.0.0.1 port 18120 as server inner-tunnel
Debug: Opening new proxy address * port 1814
Debug: Listening on proxy address * port 1814
Info: Ready to process requests.
Debug: Re-wait 1

rad_recv: Access-Request packet from host 127.0.156.5 port 50598, id=149, length=93
  Code:     1
  Id:       149
  Length:   93
  Vector:   e1655af1c13c537cac1f2726bf3c8540
  Data:     2c  1e  54 45 53 54 2d 32 30 31 33 31 30 32 32 2d 30 35 
            33 39 35 35 2d 32 31 35 37 33 2d 31 
        02  12  91 ec 52 9c 10 02 7d ab 93 24 24 ce cf e0 da f4 
        1f  0e  46 46 46 46 46 46 46 46 46 46 46 30 
        01  0b  4a 75 73 74 41 74 65 73 74 
Debug: Threads: total/active/spare threads = 5/0/5
Debug: Waking up in 0.3 seconds.
Debug: Thread 2 got semaphore
Debug: Thread 2 handling request 0, (1 handled so far)
    Acct-Session-Id = 'TEST-20131022-053955-21573-1'
    User-Password = 'guessme'
    Calling-Station-Id = 'FFFFFFFFFFF0'
    User-Name = 'JustAtest'
Debug: (0) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Debug: (0)   authorize {
Debug: (0)   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0
Debug: (0)   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0
Debug: (0)   [preprocess] = ok
Debug: (0)   update reply {
Debug: %{sql:SELECT username from mytest WHERE csid = '%{Calling-Station-Id}'}
Debug: Parsed xlat tree:
Debug: xlat: sql
Debug: {
Debug:  literal: 'SELECT username from mytest WHERE csid = ''
Debug:  attribute: Calling-Station-Id
Debug:  {
Debug:      ref  2
Debug:      list 1
Debug:      tag -128
Debug:  }
Debug:  literal: '''
Debug: }
Debug: %{User-Name}
Debug: Parsed xlat tree:
Debug: attribute: User-Name
Debug: {
Debug:  ref  2
Debug:  list 1
Debug:  tag -128
Debug: }
Debug: (0)  expand: "%{User-Name}" -> 'JustAtest'
Debug: (0) SQL-User-Name set to "JustAtest"
Debug: rlm_sql (sql): Reserved connection (4)
Debug: rlm_sql (sql): Executing query: 'SELECT username from mytest WHERE csid = 'FFFFFFFFFFF0''
Debug: (0) sql_xlat finished
Debug: rlm_sql (sql): Released connection (4)
Info: rlm_sql (sql): Closing connection (0): Too many free connections (5 > 3)
Debug: rlm_sql_unixodbc: Socket destructor called, closing socket
Debug: (0)  expand: "%{sql:SELECT username from mytest WHERE csid = '%{Calling-Station-Id}'}" -> 'test'
Debug: (0)      Tmp-String-0 := "test"
Debug: (0) ::: FROM 1 TO 0 MAX 1
Debug: (0) ::: Examining Tmp-String-0
Debug: (0) ::: APPENDING Tmp-String-0 FROM 0 TO 0
Debug: (0) ::: TO in 0 out 1
Debug: (0) ::: to[0] = Tmp-String-0
Debug: (0)   } # update reply = noop
Debug: (0)   modsingle[authorize]: calling chap (rlm_chap) for request 0
Debug: (0)   modsingle[authorize]: returned from chap (rlm_chap) for request 0
Debug: (0)   [chap] = noop
Debug: (0)   modsingle[authorize]: calling mschap (rlm_mschap) for request 0
Debug: (0)   modsingle[authorize]: returned from mschap (rlm_mschap) for request 0
Debug: (0)   [mschap] = noop
Debug: (0)   modsingle[authorize]: calling digest (rlm_digest) for request 0
Debug: (0)   modsingle[authorize]: returned from digest (rlm_digest) for request 0
Debug: (0)   [digest] = noop
Debug: (0)   modsingle[authorize]: calling suffix (rlm_realm) for request 0
Debug: (0) suffix : No '@' in User-Name = "JustAtest", looking up realm NULL
Debug: (0) suffix : No such realm "NULL"
Debug: (0)   modsingle[authorize]: returned from suffix (rlm_realm) for request 0
Debug: (0)   [suffix] = noop
Debug: (0)   modsingle[authorize]: calling eap (rlm_eap) for request 0
Debug: (0) eap : No EAP-Message, not doing EAP
Debug: (0)   modsingle[authorize]: returned from eap (rlm_eap) for request 0
Debug: (0)   [eap] = noop
Debug: (0)   modsingle[authorize]: calling files (rlm_files) for request 0
Debug: (0)   modsingle[authorize]: returned from files (rlm_files) for request 0
Debug: (0)   [files] = noop
Debug: (0)   modsingle[authorize]: calling expiration (rlm_expiration) for request 0
Debug: (0)   modsingle[authorize]: returned from expiration (rlm_expiration) for request 0
Debug: (0)   [expiration] = noop
Debug: (0)   modsingle[authorize]: calling logintime (rlm_logintime) for request 0
Debug: (0)   modsingle[authorize]: returned from logintime (rlm_logintime) for request 0
Debug: (0)   [logintime] = noop
Debug: (0)   modsingle[authorize]: calling pap (rlm_pap) for request 0
WARNING: (0) WARNING: pap : No "known good" password found for the user.  Not setting Auth-Type.
WARNING: (0) WARNING: pap : Authentication will fail unless a "known good" password is available.
Debug: (0)   modsingle[authorize]: returned from pap (rlm_pap) for request 0
Debug: (0)   [pap] = noop
Debug: (0)  } #  authorize = ok
ERROR: (0) ERROR: No Auth-Type found: rejecting the user via Post-Auth-Type = Reject
Debug: (0) Failed to authenticate the user.
Debug: (0) Using Post-Auth-Type Reject
Debug: (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Debug: (0)  Post-Auth-Type REJECT {
Debug: (0)   modsingle[post-auth]: calling sql (rlm_sql) for request 0
Debug: .query
Debug: Parsed xlat tree:
Debug: literal: '.query'
Debug: (0) sql :    expand: ".query" -> '.query'
WARNING: WARNING: No such configuration item .query
Debug: (0)   modsingle[post-auth]: returned from sql (rlm_sql) for request 0
Debug: (0)   [-sql] = fail
Debug: (0)  } # Post-Auth-Type REJECT = fail
Debug: (0) Finished request 0.
Debug: Thread 2 waiting to be assigned a request
Debug: Waking up in 0.6 seconds.
Debug: (0) Sending delayed reject
Sending Access-Reject of id 149 from 127.0.156.5 port 1812 to 127.0.156.5 port 50598
  Code:     3
  Id:       149
  Length:   20
  Vector:   0d33d079ebc23d258b91dc7bb1075a1c
Debug: Waking up in 4.9 seconds.
Debug: (0) Cleaning up request packet ID 149 with timestamp +21
Info: Ready to process requests.

rad_recv: Access-Request packet from host 127.0.156.5 port 44008, id=87, length=93
  Code:     1
  Id:       87
  Length:   93
  Vector:   c2ebe7e6c756c7ee05f00b25c552feff
  Data:     2c  1e  54 45 53 54 2d 32 30 31 33 31 30 32 32 2d 30 35 
            34 31 33 36 2d 32 31 35 37 36 2d 31 
        02  12  1f f7 1b dd 4c 48 99 22 6d 35 2e 94 55 9b 27 27 
        1f  0e  46 46 46 46 46 46 46 46 46 46 46 30 
        01  0b  4a 75 73 74 41 74 65 73 74 
Debug: Waking up in 0.3 seconds.
Debug: Thread 5 got semaphore
Debug: Thread 5 handling request 1, (1 handled so far)
    Acct-Session-Id = 'TEST-20131022-054136-21576-1'
    User-Password = 'guessme'
    Calling-Station-Id = 'FFFFFFFFFFF0'
    User-Name = 'JustAtest'
Debug: (1) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Debug: (1)   authorize {
Debug: (1)   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 1
Debug: (1)   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 1
Debug: (1)   [preprocess] = ok
Debug: (1)   update reply {
Debug: %{sql:SELECT username from mytest WHERE csid = '%{Calling-Station-Id}'}
Debug: Parsed xlat tree:
Debug: xlat: sql
Debug: {
Debug:  literal: 'SELECT username from mytest WHERE csid = ''
Debug:  attribute: Calling-Station-Id
Debug:  {
Debug:      ref  2
Debug:      list 1
Debug:      tag -128
Debug:  }
Debug:  literal: '''
Debug: }
Debug: %{User-Name}
Debug: Parsed xlat tree:
Debug: attribute: User-Name
Debug: {
Debug:  ref  2
Debug:  list 1
Debug:  tag -128
Debug: }
Debug: (1)  expand: "%{User-Name}" -> 'JustAtest'
Debug: (1) SQL-User-Name set to "JustAtest"
Debug: rlm_sql (sql): Reserved connection (4)
Debug: rlm_sql (sql): Executing query: 'SELECT username from mytest WHERE csid = 'FFFFFFFFFFF0''
Debug: (1) Null value in first column
Debug: rlm_sql (sql): Released connection (4)
Info: rlm_sql (sql): Closing connection (1): Too many free connections (4 > 3)
Debug: rlm_sql_unixodbc: Socket destructor called, closing socket
Info: rlm_sql (sql): Closing connection (3): Hit idle_timeout, was idle for 123 seconds
rlm_sql (sql): You probably need to lower "min"
Debug: rlm_sql_unixodbc: Socket destructor called, closing socket
Info: rlm_sql (sql): Closing connection (2): Hit idle_timeout, was idle for 123 seconds
Debug: rlm_sql_unixodbc: Socket destructor called, closing socket
Debug: (1)  expand: "%{sql:SELECT username from mytest WHERE csid = '%{Calling-Station-Id}'}" -> ''
Debug: (1)      Tmp-String-0 := ""
Debug: (1) ::: FROM 1 TO 0 MAX 1
Debug: (1) ::: Examining Tmp-String-0
Debug: (1) ::: APPENDING Tmp-String-0 FROM 0 TO 0
Debug: (1) ::: TO in 0 out 1
Debug: (1) ::: to[0] = Tmp-String-0
Debug: (1)   } # update reply = noop
Debug: (1)   modsingle[authorize]: calling chap (rlm_chap) for request 1
Debug: (1)   modsingle[authorize]: returned from chap (rlm_chap) for request 1
Debug: (1)   [chap] = noop
Debug: (1)   modsingle[authorize]: calling mschap (rlm_mschap) for request 1
Debug: (1)   modsingle[authorize]: returned from mschap (rlm_mschap) for request 1
Debug: (1)   [mschap] = noop
Debug: (1)   modsingle[authorize]: calling digest (rlm_digest) for request 1
Debug: (1)   modsingle[authorize]: returned from digest (rlm_digest) for request 1
Debug: (1)   [digest] = noop
Debug: (1)   modsingle[authorize]: calling suffix (rlm_realm) for request 1
Debug: (1) suffix : No '@' in User-Name = "JustAtest", looking up realm NULL
Debug: (1) suffix : No such realm "NULL"
Debug: (1)   modsingle[authorize]: returned from suffix (rlm_realm) for request 1
Debug: (1)   [suffix] = noop
Debug: (1)   modsingle[authorize]: calling eap (rlm_eap) for request 1
Debug: (1) eap : No EAP-Message, not doing EAP
Debug: (1)   modsingle[authorize]: returned from eap (rlm_eap) for request 1
Debug: (1)   [eap] = noop
Debug: (1)   modsingle[authorize]: calling files (rlm_files) for request 1
Debug: (1)   modsingle[authorize]: returned from files (rlm_files) for request 1
Debug: (1)   [files] = noop
Debug: (1)   modsingle[authorize]: calling expiration (rlm_expiration) for request 1
Debug: (1)   modsingle[authorize]: returned from expiration (rlm_expiration) for request 1
Debug: (1)   [expiration] = noop
Debug: (1)   modsingle[authorize]: calling logintime (rlm_logintime) for request 1
Debug: (1)   modsingle[authorize]: returned from logintime (rlm_logintime) for request 1
Debug: (1)   [logintime] = noop
Debug: (1)   modsingle[authorize]: calling pap (rlm_pap) for request 1
WARNING: (1) WARNING: pap : No "known good" password found for the user.  Not setting Auth-Type.
WARNING: (1) WARNING: pap : Authentication will fail unless a "known good" password is available.
Debug: (1)   modsingle[authorize]: returned from pap (rlm_pap) for request 1
Debug: (1)   [pap] = noop
Debug: (1)  } #  authorize = ok
ERROR: (1) ERROR: No Auth-Type found: rejecting the user via Post-Auth-Type = Reject
Debug: (1) Failed to authenticate the user.
Debug: (1) Using Post-Auth-Type Reject
Debug: (1) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Debug: (1)  Post-Auth-Type REJECT {
Debug: (1)   modsingle[post-auth]: calling sql (rlm_sql) for request 1
Debug: .query
Debug: Parsed xlat tree:
Debug: literal: '.query'
Debug: (1) sql :    expand: ".query" -> '.query'
WARNING: WARNING: No such configuration item .query
Debug: (1)   modsingle[post-auth]: returned from sql (rlm_sql) for request 1
Debug: (1)   [-sql] = fail
Debug: (1)  } # Post-Auth-Type REJECT = fail
Debug: (1) Finished request 1.
Debug: Thread 5 waiting to be assigned a request
Debug: Waking up in 0.6 seconds.
Debug: (1) Sending delayed reject
Sending Access-Reject of id 87 from 127.0.156.5 port 1812 to 127.0.156.5 port 44008
  Code:     3
  Id:       87
  Length:   20
  Vector:   63aa509a0371b36f6e04948afc951cc3
Debug: Waking up in 4.9 seconds.

Debug: (1) Cleaning up request packet ID 87 with timestamp +122
Info: Ready to process requests.

rad_recv: Access-Request packet from host 127.0.156.5 port 45815, id=102, length=93
  Code:     1
  Id:       102
  Length:   93
  Vector:   db55f4ba2b97edc37fe3e5f91dfc37bb
  Data:     2c  1e  54 45 53 54 2d 32 30 31 33 31 30 32 32 2d 30 35 
            34 35 31 37 2d 32 31 35 38 32 2d 31 
        02  12  2a 8e ed e1 c3 9a 3f a8 73 de 64 36 80 fd 9d 78 
        1f  0e  46 46 46 46 46 46 46 46 46 46 46 30 
        01  0b  4a 75 73 74 41 74 65 73 74 
Debug: Waking up in 0.3 seconds.
Debug: Thread 4 got semaphore
Debug: Thread 4 handling request 2, (1 handled so far)
    Acct-Session-Id = 'TEST-20131022-054517-21582-1'
    User-Password = 'guessme'
    Calling-Station-Id = 'FFFFFFFFFFF0'
    User-Name = 'JustAtest'
Debug: (2) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Debug: (2)   authorize {
Debug: (2)   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 2
Debug: (2)   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 2
Debug: (2)   [preprocess] = ok
Debug: (2)   update reply {
Debug: %{sql:SELECT username from mytest WHERE csid = '%{Calling-Station-Id}'}
Debug: Parsed xlat tree:
Debug: xlat: sql
Debug: {
Debug:  literal: 'SELECT username from mytest WHERE csid = ''
Debug:  attribute: Calling-Station-Id
Debug:  {
Debug:      ref  2
Debug:      list 1
Debug:      tag -128
Debug:  }
Debug:  literal: '''
Debug: }
Debug: %{User-Name}
Debug: Parsed xlat tree:
Debug: attribute: User-Name
Debug: {
Debug:  ref  2
Debug:  list 1
Debug:  tag -128
Debug: }
Debug: (2)  expand: "%{User-Name}" -> 'JustAtest'
Debug: (2) SQL-User-Name set to "JustAtest"
Debug: rlm_sql (sql): Reserved connection (4)
Debug: rlm_sql (sql): Executing query: 'SELECT username from mytest WHERE csid = 'FFFFFFFFFFF0''
Debug: (2) Null value in first column
Debug: rlm_sql (sql): Released connection (4)
Info: rlm_sql (sql): Opening additional connection (5)
Debug: (2)  expand: "%{sql:SELECT username from mytest WHERE csid = '%{Calling-Station-Id}'}" -> ''
Debug: (2)      Tmp-String-0 := ""
Debug: (2) ::: FROM 1 TO 0 MAX 1
Debug: (2) ::: Examining Tmp-String-0
Debug: (2) ::: APPENDING Tmp-String-0 FROM 0 TO 0
Debug: (2) ::: TO in 0 out 1
Debug: (2) ::: to[0] = Tmp-String-0
Debug: (2)   } # update reply = noop
Debug: (2)   modsingle[authorize]: calling chap (rlm_chap) for request 2
Debug: (2)   modsingle[authorize]: returned from chap (rlm_chap) for request 2
Debug: (2)   [chap] = noop
Debug: (2)   modsingle[authorize]: calling mschap (rlm_mschap) for request 2
Debug: (2)   modsingle[authorize]: returned from mschap (rlm_mschap) for request 2
Debug: (2)   [mschap] = noop
Debug: (2)   modsingle[authorize]: calling digest (rlm_digest) for request 2
Debug: (2)   modsingle[authorize]: returned from digest (rlm_digest) for request 2
Debug: (2)   [digest] = noop
Debug: (2)   modsingle[authorize]: calling suffix (rlm_realm) for request 2
Debug: (2) suffix : No '@' in User-Name = "JustAtest", looking up realm NULL
Debug: (2) suffix : No such realm "NULL"
Debug: (2)   modsingle[authorize]: returned from suffix (rlm_realm) for request 2
Debug: (2)   [suffix] = noop
Debug: (2)   modsingle[authorize]: calling eap (rlm_eap) for request 2
Debug: (2) eap : No EAP-Message, not doing EAP
Debug: (2)   modsingle[authorize]: returned from eap (rlm_eap) for request 2
Debug: (2)   [eap] = noop
Debug: (2)   modsingle[authorize]: calling files (rlm_files) for request 2
Debug: (2)   modsingle[authorize]: returned from files (rlm_files) for request 2
Debug: (2)   [files] = noop
Debug: (2)   modsingle[authorize]: calling expiration (rlm_expiration) for request 2
Debug: (2)   modsingle[authorize]: returned from expiration (rlm_expiration) for request 2
Debug: (2)   [expiration] = noop
Debug: (2)   modsingle[authorize]: calling logintime (rlm_logintime) for request 2
Debug: (2)   modsingle[authorize]: returned from logintime (rlm_logintime) for request 2
Debug: (2)   [logintime] = noop
Debug: (2)   modsingle[authorize]: calling pap (rlm_pap) for request 2
WARNING: (2) WARNING: pap : No "known good" password found for the user.  Not setting Auth-Type.
WARNING: (2) WARNING: pap : Authentication will fail unless a "known good" password is available.
Debug: (2)   modsingle[authorize]: returned from pap (rlm_pap) for request 2
Debug: (2)   [pap] = noop
Debug: (2)  } #  authorize = ok
ERROR: (2) ERROR: No Auth-Type found: rejecting the user via Post-Auth-Type = Reject
Debug: (2) Failed to authenticate the user.
Debug: (2) Using Post-Auth-Type Reject
Debug: (2) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Debug: (2)  Post-Auth-Type REJECT {
Debug: (2)   modsingle[post-auth]: calling sql (rlm_sql) for request 2
Debug: .query
Debug: Parsed xlat tree:
Debug: literal: '.query'
Debug: (2) sql :    expand: ".query" -> '.query'
WARNING: WARNING: No such configuration item .query
Debug: (2)   modsingle[post-auth]: returned from sql (rlm_sql) for request 2
Debug: (2)   [-sql] = fail
Debug: (2)  } # Post-Auth-Type REJECT = fail
Debug: (2) Finished request 2.
Debug: Thread 4 waiting to be assigned a request
Debug: Waking up in 0.6 seconds.
Debug: (2) Sending delayed reject
Sending Access-Reject of id 102 from 127.0.156.5 port 1812 to 127.0.156.5 port 45815
  Code:     3
  Id:       102
  Length:   20
  Vector:   36634aeb2ed905c0fbbd1ad8330e6539
Debug: Waking up in 4.9 seconds.
Debug: (2) Cleaning up request packet ID 102 with timestamp +343
Info: Ready to process requests.
arr2036 commented 11 years ago

Probably the same fix as for #455