freeradius update attributes in access-accept reply

23 Feb 2016

      Hello freeradius-users,

Iam running freeradius on ubuntu 14.04 LTS with mysql and daloradius.
Now i trie to authenticate a user via RADIUS on a Procurve Switch.

But the problem is that the configured service-type attribute are not send in the Access-Accept message.
Only in the Access-Challenge messages the attribute where send tot he procurve switch.
I need it in the Access-Accept reply message.

This is my logfile from the radiusserver:
Tue Feb 23 15:45:33 2016 : Info: FreeRADIUS Version 2.1.12, for host x86_64-pc-linux-gnu, built on Aug 26 2015 at 14:47:03
Tue Feb 23 15:45:33 2016 : Info: Copyright (C) 1999-2009 The FreeRADIUS server project and contributors.
Tue Feb 23 15:45:33 2016 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
Tue Feb 23 15:45:33 2016 : Info: PARTICULAR PURPOSE.
Tue Feb 23 15:45:33 2016 : Info: You may redistribute copies of FreeRADIUS under the terms of the
Tue Feb 23 15:45:33 2016 : Info: GNU General Public License v2.
Tue Feb 23 15:45:33 2016 : Info: Starting - reading configuration files ...
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/radiusd.conf
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/proxy.conf
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/clients.conf
Tue Feb 23 15:45:33 2016 : Debug: including files in directory /etc/freeradius/modules/
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/passwd
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/sqlcounter_expire_on_login
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/preprocess
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/mschap
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/radutmp
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/smsotp
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/sradutmp
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/unix
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/replicate
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/smbpasswd
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/detail
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/checkval
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/acct_unique
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/wimax
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/ntlm_auth
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/files
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/pap
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/realm
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/etc_group
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/soh
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/sql_log
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/opendirectory
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/perl
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/detail.log
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/mac2vlan
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/echo
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/linelog
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/redis
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/attr_filter
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/chap
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/mac2ip
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/expiration
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/digest
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/attr_rewrite
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/pam
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/counter
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/always
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/cui
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/logintime
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/expr
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/inner-eap
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/detail.example.com
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/ldap
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/otp
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/ippool
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/dynamic_clients
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/rediswho
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/exec
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/policy
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/modules/krb5
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/eap.conf
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/sql.conf
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/sql/mysql/dialup.conf
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/sql/mysql/counter.conf
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/policy.conf
Tue Feb 23 15:45:33 2016 : Debug: including files in directory /etc/freeradius/sites-enabled/
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/sites-enabled/default
Tue Feb 23 15:45:33 2016 : Debug: including configuration file /etc/freeradius/sites-enabled/inner-tunnel
Tue Feb 23 15:45:33 2016 : Debug: main {
Tue Feb 23 15:45:33 2016 : Debug:          user = "freerad"
Tue Feb 23 15:45:33 2016 : Debug:          group = "freerad"
Tue Feb 23 15:45:33 2016 : Debug:          allow_core_dumps = no
Tue Feb 23 15:45:33 2016 : Debug: }
Tue Feb 23 15:45:33 2016 : Debug: including dictionary file /etc/freeradius/dictionary
Tue Feb 23 15:45:33 2016 : Debug: main {
Tue Feb 23 15:45:33 2016 : Debug:          name = "freeradius"
Tue Feb 23 15:45:33 2016 : Debug:          prefix = "/usr"
Tue Feb 23 15:45:33 2016 : Debug:          localstatedir = "/var"
Tue Feb 23 15:45:33 2016 : Debug:          sbindir = "/usr/sbin"
Tue Feb 23 15:45:33 2016 : Debug:          logdir = "/var/log/freeradius"
Tue Feb 23 15:45:33 2016 : Debug:          run_dir = "/var/run/freeradius"
Tue Feb 23 15:45:33 2016 : Debug:          libdir = "/usr/lib/freeradius"
Tue Feb 23 15:45:33 2016 : Debug:          radacctdir = "/var/log/freeradius/radacct"
Tue Feb 23 15:45:33 2016 : Debug:          hostname_lookups = no
Tue Feb 23 15:45:33 2016 : Debug:          max_request_time = 30
Tue Feb 23 15:45:33 2016 : Debug:          cleanup_delay = 5
Tue Feb 23 15:45:33 2016 : Debug:          max_requests = 1024
Tue Feb 23 15:45:33 2016 : Debug:          pidfile = "/var/run/freeradius/freeradius.pid"
Tue Feb 23 15:45:33 2016 : Debug:          checkrad = "/usr/sbin/checkrad"
Tue Feb 23 15:45:33 2016 : Debug:          debug_level = 0
Tue Feb 23 15:45:33 2016 : Debug:          proxy_requests = yes
Tue Feb 23 15:45:33 2016 : Debug:  log {
Tue Feb 23 15:45:33 2016 : Debug:          stripped_names = no
Tue Feb 23 15:45:33 2016 : Debug:          auth = no
Tue Feb 23 15:45:33 2016 : Debug:          auth_badpass = no
Tue Feb 23 15:45:33 2016 : Debug:          auth_goodpass = no
Tue Feb 23 15:45:33 2016 : Debug:  }
Tue Feb 23 15:45:33 2016 : Debug:  security {
Tue Feb 23 15:45:33 2016 : Debug:          max_attributes = 200
Tue Feb 23 15:45:33 2016 : Debug:          reject_delay = 1
Tue Feb 23 15:45:33 2016 : Debug:          status_server = yes
Tue Feb 23 15:45:33 2016 : Debug:  }
Tue Feb 23 15:45:33 2016 : Debug: }
Tue Feb 23 15:45:33 2016 : Debug: radiusd: #### Loading Realms and Home Servers ####
Tue Feb 23 15:45:33 2016 : Debug:  proxy server {
Tue Feb 23 15:45:33 2016 : Debug:          retry_delay = 5
Tue Feb 23 15:45:33 2016 : Debug:          retry_count = 3
Tue Feb 23 15:45:33 2016 : Debug:          default_fallback = no
Tue Feb 23 15:45:33 2016 : Debug:          dead_time = 120
Tue Feb 23 15:45:33 2016 : Debug:          wake_all_if_all_dead = no
Tue Feb 23 15:45:33 2016 : Debug:  }
Tue Feb 23 15:45:33 2016 : Debug:  home_server localhost {
Tue Feb 23 15:45:33 2016 : Debug:          ipaddr = 127.0.0.1
Tue Feb 23 15:45:33 2016 : Debug:          port = 1812
Tue Feb 23 15:45:33 2016 : Debug:          type = "auth"
Tue Feb 23 15:45:33 2016 : Debug:          secret = "testing123"
Tue Feb 23 15:45:33 2016 : Debug:          response_window = 20
Tue Feb 23 15:45:33 2016 : Debug:          max_outstanding = 65536
Tue Feb 23 15:45:33 2016 : Debug:          require_message_authenticator = yes
Tue Feb 23 15:45:33 2016 : Debug:          zombie_period = 40
Tue Feb 23 15:45:33 2016 : Debug:          status_check = "status-server"
Tue Feb 23 15:45:33 2016 : Debug:          ping_interval = 30
Tue Feb 23 15:45:33 2016 : Debug:          check_interval = 30
Tue Feb 23 15:45:33 2016 : Debug:          num_answers_to_alive = 3
Tue Feb 23 15:45:33 2016 : Debug:          num_pings_to_alive = 3
Tue Feb 23 15:45:33 2016 : Debug:          revive_interval = 120
Tue Feb 23 15:45:33 2016 : Debug:          status_check_timeout = 4
Tue Feb 23 15:45:33 2016 : Debug:   coa {
Tue Feb 23 15:45:33 2016 : Debug:          irt = 2
Tue Feb 23 15:45:33 2016 : Debug:          mrt = 16
Tue Feb 23 15:45:33 2016 : Debug:          mrc = 5
Tue Feb 23 15:45:33 2016 : Debug:          mrd = 30
Tue Feb 23 15:45:33 2016 : Debug:   }
Tue Feb 23 15:45:33 2016 : Debug:  }
Tue Feb 23 15:45:33 2016 : Debug:  home_server_pool my_auth_failover {
Tue Feb 23 15:45:33 2016 : Debug:          type = fail-over
Tue Feb 23 15:45:33 2016 : Debug:          home_server = localhost
Tue Feb 23 15:45:33 2016 : Debug:  }
Tue Feb 23 15:45:33 2016 : Debug:  realm example.com {
Tue Feb 23 15:45:33 2016 : Debug:          auth_pool = my_auth_failover
Tue Feb 23 15:45:33 2016 : Debug:  }
Tue Feb 23 15:45:33 2016 : Debug:  realm LOCAL {
Tue Feb 23 15:45:33 2016 : Debug:  }
Tue Feb 23 15:45:33 2016 : Debug: radiusd: #### Loading Clients ####
Tue Feb 23 15:45:33 2016 : Debug:  client localhost {
Tue Feb 23 15:45:33 2016 : Debug:          ipaddr = 127.0.0.1
Tue Feb 23 15:45:33 2016 : Debug:          require_message_authenticator = no
Tue Feb 23 15:45:33 2016 : Debug:          secret = "testing123"
Tue Feb 23 15:45:33 2016 : Debug:          nastype = "other"
Tue Feb 23 15:45:33 2016 : Debug:  }
Tue Feb 23 15:45:33 2016 : Debug: radiusd: #### Instantiating modules ####
Tue Feb 23 15:45:33 2016 : Debug:  instantiate {
Tue Feb 23 15:45:33 2016 : Debug:     (Loaded rlm_exec, checking if it's valid)
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to module rlm_exec
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating module "exec" from file /etc/freeradius/modules/exec
Tue Feb 23 15:45:33 2016 : Debug:   exec {
Tue Feb 23 15:45:33 2016 : Debug:          wait = no
Tue Feb 23 15:45:33 2016 : Debug:          input_pairs = "request"
Tue Feb 23 15:45:33 2016 : Debug:          shell_escape = yes
Tue Feb 23 15:45:33 2016 : Debug:   }
Tue Feb 23 15:45:33 2016 : Debug:     (Loaded rlm_expr, checking if it's valid)
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to module rlm_expr
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating module "expr" from file /etc/freeradius/modules/expr
Tue Feb 23 15:45:33 2016 : Debug:     (Loaded rlm_expiration, checking if it's valid)
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to module rlm_expiration
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating module "expiration" from file /etc/freeradius/modules/expiration
Tue Feb 23 15:45:33 2016 : Debug:   expiration {
Tue Feb 23 15:45:33 2016 : Debug:          reply-message = "Password Has Expired  "
Tue Feb 23 15:45:33 2016 : Debug:   }
Tue Feb 23 15:45:33 2016 : Debug:     (Loaded rlm_logintime, checking if it's valid)
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to module rlm_logintime
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating module "logintime" from file /etc/freeradius/modules/logintime
Tue Feb 23 15:45:33 2016 : Debug:   logintime {
Tue Feb 23 15:45:33 2016 : Debug:          reply-message = "You are calling outside your allowed timespan  "
Tue Feb 23 15:45:33 2016 : Debug:          minimum-timeout = 60
Tue Feb 23 15:45:33 2016 : Debug:   }
Tue Feb 23 15:45:33 2016 : Debug:  }
Tue Feb 23 15:45:33 2016 : Debug: radiusd: #### Loading Virtual Servers ####
Tue Feb 23 15:45:33 2016 : Debug: server { # from file /etc/freeradius/radiusd.conf
Tue Feb 23 15:45:33 2016 : Debug:  modules {
Tue Feb 23 15:45:33 2016 : Debug:   Module: Creating Auth-Type = digest
Tue Feb 23 15:45:33 2016 : Debug:   Module: Creating Post-Auth-Type = REJECT
Tue Feb 23 15:45:33 2016 : Debug:  Module: Checking authenticate {...} for more modules to load
Tue Feb 23 15:45:33 2016 : Debug:     (Loaded rlm_pap, checking if it's valid)
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to module rlm_pap
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating module "pap" from file /etc/freeradius/modules/pap
Tue Feb 23 15:45:33 2016 : Debug:   pap {
Tue Feb 23 15:45:33 2016 : Debug:          encryption_scheme = "auto"
Tue Feb 23 15:45:33 2016 : Debug:          auto_header = no
Tue Feb 23 15:45:33 2016 : Debug:   }
Tue Feb 23 15:45:33 2016 : Debug:     (Loaded rlm_chap, checking if it's valid)
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to module rlm_chap
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating module "chap" from file /etc/freeradius/modules/chap
Tue Feb 23 15:45:33 2016 : Debug:     (Loaded rlm_mschap, checking if it's valid)
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to module rlm_mschap
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating module "mschap" from file /etc/freeradius/modules/mschap
Tue Feb 23 15:45:33 2016 : Debug:   mschap {
Tue Feb 23 15:45:33 2016 : Debug:          use_mppe = yes
Tue Feb 23 15:45:33 2016 : Debug:          require_encryption = yes
Tue Feb 23 15:45:33 2016 : Debug:          require_strong = yes
Tue Feb 23 15:45:33 2016 : Debug:          with_ntdomain_hack = yes
Tue Feb 23 15:45:33 2016 : Debug:          allow_retry = yes
Tue Feb 23 15:45:33 2016 : Debug:   }
Tue Feb 23 15:45:33 2016 : Debug:     (Loaded rlm_digest, checking if it's valid)
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to module rlm_digest
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating module "digest" from file /etc/freeradius/modules/digest
Tue Feb 23 15:45:33 2016 : Debug:     (Loaded rlm_unix, checking if it's valid)
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to module rlm_unix
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating module "unix" from file /etc/freeradius/modules/unix
Tue Feb 23 15:45:33 2016 : Debug:   unix {
Tue Feb 23 15:45:33 2016 : Debug:          radwtmp = "/var/log/freeradius/radwtmp"
Tue Feb 23 15:45:33 2016 : Debug:   }
Tue Feb 23 15:45:33 2016 : Debug:     (Loaded rlm_eap, checking if it's valid)
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to module rlm_eap
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating module "eap" from file /etc/freeradius/eap.conf
Tue Feb 23 15:45:33 2016 : Debug:   eap {
Tue Feb 23 15:45:33 2016 : Debug:          default_eap_type = "md5"
Tue Feb 23 15:45:33 2016 : Debug:          timer_expire = 60
Tue Feb 23 15:45:33 2016 : Debug:          ignore_unknown_eap_types = no
Tue Feb 23 15:45:33 2016 : Debug:          cisco_accounting_username_bug = no
Tue Feb 23 15:45:33 2016 : Debug:          max_sessions = 4096
Tue Feb 23 15:45:33 2016 : Debug:   }
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to sub-module rlm_eap_md5
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating eap-md5
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to sub-module rlm_eap_leap
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating eap-leap
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to sub-module rlm_eap_gtc
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating eap-gtc
Tue Feb 23 15:45:33 2016 : Debug:    gtc {
Tue Feb 23 15:45:33 2016 : Debug:          challenge = "Password: "
Tue Feb 23 15:45:33 2016 : Debug:          auth_type = "PAP"
Tue Feb 23 15:45:33 2016 : Debug:    }
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to sub-module rlm_eap_tls
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating eap-tls
Tue Feb 23 15:45:33 2016 : Debug:    tls {
Tue Feb 23 15:45:33 2016 : Debug:          rsa_key_exchange = no
Tue Feb 23 15:45:33 2016 : Debug:          dh_key_exchange = yes
Tue Feb 23 15:45:33 2016 : Debug:          rsa_key_length = 512
Tue Feb 23 15:45:33 2016 : Debug:          dh_key_length = 512
Tue Feb 23 15:45:33 2016 : Debug:          verify_depth = 0
Tue Feb 23 15:45:33 2016 : Debug:          CA_path = "/etc/freeradius/certs"
Tue Feb 23 15:45:33 2016 : Debug:          pem_file_type = yes
Tue Feb 23 15:45:33 2016 : Debug:          private_key_file = "/etc/freeradius/certs/server.key"
Tue Feb 23 15:45:33 2016 : Debug:          certificate_file = "/etc/freeradius/certs/server.pem"
Tue Feb 23 15:45:33 2016 : Debug:          CA_file = "/etc/freeradius/certs/ca.pem"
Tue Feb 23 15:45:33 2016 : Debug:          private_key_password = "whatever"
Tue Feb 23 15:45:33 2016 : Debug:          dh_file = "/etc/freeradius/certs/dh"
Tue Feb 23 15:45:33 2016 : Debug:          random_file = "/dev/urandom"
Tue Feb 23 15:45:33 2016 : Debug:          fragment_size = 1024
Tue Feb 23 15:45:33 2016 : Debug:          include_length = yes
Tue Feb 23 15:45:33 2016 : Debug:          check_crl = no
Tue Feb 23 15:45:33 2016 : Debug:          cipher_list = "DEFAULT"
Tue Feb 23 15:45:33 2016 : Debug:          make_cert_command = "/etc/freeradius/certs/bootstrap"
Tue Feb 23 15:45:33 2016 : Debug:          ecdh_curve = "prime256v1"
Tue Feb 23 15:45:33 2016 : Debug:     cache {
Tue Feb 23 15:45:33 2016 : Debug:          enable = no
Tue Feb 23 15:45:33 2016 : Debug:          lifetime = 24
Tue Feb 23 15:45:33 2016 : Debug:          max_entries = 255
Tue Feb 23 15:45:33 2016 : Debug:     }
Tue Feb 23 15:45:33 2016 : Debug:     verify {
Tue Feb 23 15:45:33 2016 : Debug:     }
Tue Feb 23 15:45:33 2016 : Debug:     ocsp {
Tue Feb 23 15:45:33 2016 : Debug:          enable = no
Tue Feb 23 15:45:33 2016 : Debug:          override_cert_url = yes
Tue Feb 23 15:45:33 2016 : Debug:          url = "http://127.0.0.1/ocsp/"
Tue Feb 23 15:45:33 2016 : Debug:     }
Tue Feb 23 15:45:33 2016 : Debug:    }
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to sub-module rlm_eap_ttls
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating eap-ttls
Tue Feb 23 15:45:33 2016 : Debug:    ttls {
Tue Feb 23 15:45:33 2016 : Debug:          default_eap_type = "md5"
Tue Feb 23 15:45:33 2016 : Debug:          copy_request_to_tunnel = no
Tue Feb 23 15:45:33 2016 : Debug:          use_tunneled_reply = yes
Tue Feb 23 15:45:33 2016 : Debug:          virtual_server = "inner-tunnel"
Tue Feb 23 15:45:33 2016 : Debug:          include_length = yes
Tue Feb 23 15:45:33 2016 : Debug:    }
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to sub-module rlm_eap_peap
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating eap-peap
Tue Feb 23 15:45:33 2016 : Debug:    peap {
Tue Feb 23 15:45:33 2016 : Debug:          default_eap_type = "mschapv2"
Tue Feb 23 15:45:33 2016 : Debug:          copy_request_to_tunnel = no
Tue Feb 23 15:45:33 2016 : Debug:          use_tunneled_reply = yes
Tue Feb 23 15:45:33 2016 : Debug:          proxy_tunneled_request_as_eap = yes
Tue Feb 23 15:45:33 2016 : Debug:          virtual_server = "inner-tunnel"
Tue Feb 23 15:45:33 2016 : Debug:          soh = no
Tue Feb 23 15:45:33 2016 : Debug:    }
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to sub-module rlm_eap_mschapv2
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating eap-mschapv2
Tue Feb 23 15:45:33 2016 : Debug:    mschapv2 {
Tue Feb 23 15:45:33 2016 : Debug:          with_ntdomain_hack = no
Tue Feb 23 15:45:33 2016 : Debug:          send_error = no
Tue Feb 23 15:45:33 2016 : Debug:    }
Tue Feb 23 15:45:33 2016 : Debug:  Module: Checking authorize {...} for more modules to load
Tue Feb 23 15:45:33 2016 : Debug:     (Loaded rlm_preprocess, checking if it's valid)
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to module rlm_preprocess
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating module "preprocess" from file /etc/freeradius/modules/preprocess
Tue Feb 23 15:45:33 2016 : Debug:   preprocess {
Tue Feb 23 15:45:33 2016 : Debug:          huntgroups = "/etc/freeradius/huntgroups"
Tue Feb 23 15:45:33 2016 : Debug:          hints = "/etc/freeradius/hints"
Tue Feb 23 15:45:33 2016 : Debug:          with_ascend_hack = no
Tue Feb 23 15:45:33 2016 : Debug:          ascend_channels_per_line = 23
Tue Feb 23 15:45:33 2016 : Debug:          with_ntdomain_hack = no
Tue Feb 23 15:45:33 2016 : Debug:          with_specialix_jetstream_hack = no
Tue Feb 23 15:45:33 2016 : Debug:          with_cisco_vsa_hack = no
Tue Feb 23 15:45:33 2016 : Debug:          with_alvarion_vsa_hack = no
Tue Feb 23 15:45:33 2016 : Debug:   }
Tue Feb 23 15:45:33 2016 : Debug:     (Loaded rlm_realm, checking if it's valid)
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to module rlm_realm
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating module "suffix" from file /etc/freeradius/modules/realm
Tue Feb 23 15:45:33 2016 : Debug:   realm suffix {
Tue Feb 23 15:45:33 2016 : Debug:          format = "suffix"
Tue Feb 23 15:45:33 2016 : Debug:          delimiter = "@"
Tue Feb 23 15:45:33 2016 : Debug:          ignore_default = no
Tue Feb 23 15:45:33 2016 : Debug:          ignore_null = no
Tue Feb 23 15:45:33 2016 : Debug:   }
Tue Feb 23 15:45:33 2016 : Debug:     (Loaded rlm_sql, checking if it's valid)
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to module rlm_sql
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating module "sql" from file /etc/freeradius/sql.conf
Tue Feb 23 15:45:33 2016 : Debug:   sql {
Tue Feb 23 15:45:33 2016 : Debug:          driver = "rlm_sql_mysql"
Tue Feb 23 15:45:33 2016 : Debug:          server = "localhost"
Tue Feb 23 15:45:33 2016 : Debug:          port = ""
Tue Feb 23 15:45:33 2016 : Debug:          login = "freeradius"
Tue Feb 23 15:45:33 2016 : Debug:          password = "radius123"
Tue Feb 23 15:45:33 2016 : Debug:          radius_db = "radius"
Tue Feb 23 15:45:33 2016 : Debug:          read_groups = yes
Tue Feb 23 15:45:33 2016 : Debug:          sqltrace = yes
Tue Feb 23 15:45:33 2016 : Debug:          sqltracefile = "/var/log/freeradius/sqltrace.sql"
Tue Feb 23 15:45:33 2016 : Debug:          readclients = yes
Tue Feb 23 15:45:33 2016 : Debug:          deletestalesessions = yes
Tue Feb 23 15:45:33 2016 : Debug:          num_sql_socks = 5
Tue Feb 23 15:45:33 2016 : Debug:          lifetime = 0
Tue Feb 23 15:45:33 2016 : Debug:          max_queries = 0
Tue Feb 23 15:45:33 2016 : Debug:          sql_user_name = "%{User-Name}"
Tue Feb 23 15:45:33 2016 : Debug:          default_user_profile = ""
Tue Feb 23 15:45:33 2016 : Debug:          nas_query = "SELECT id, nasname, shortname, type, secret, server FROM nas"
Tue Feb 23 15:45:33 2016 : Debug:          authorize_check_query = "SELECT id, username, attribute, value, op           FROM radcheck           WHERE username = '%{SQL-User-Name}'           ORDER BY id"
Tue Feb 23 15:45:33 2016 : Debug:          authorize_reply_query = "SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '%{SQL-User-Name}'           ORDER BY id"
Tue Feb 23 15:45:33 2016 : Debug:          authorize_group_check_query = "SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = '%{Sql-Group}'           ORDER BY id"
Tue Feb 23 15:45:33 2016 : Debug:          authorize_group_reply_query = "SELECT id, groupname, attribute,           value, op           FROM radgroupreply           WHERE groupname = '%{Sql-Group}'           ORDER BY id"
Tue Feb 23 15:45:33 2016 : Debug:          accounting_onoff_query = "          UPDATE radacct           SET              acctstoptime       =  '%S',              acctsessiontime    =  unix_timestamp('%S') -                                    unix_timestamp(acctstarttime),              acctterminatecause =  '%{Acct-Terminate-Cause}',              acctstopdelay      =  %{%{Acct-Delay-Time}:-0}           WHERE acctstoptime IS NULL           AND nasipaddress      =  '%{NAS-IP-Address}'           AND acctstarttime     <= '%S'"
Tue Feb 23 15:45:33 2016 : Debug:          accounting_update_query = "           UPDATE radacct           SET              framedipaddress = '%{Framed-IP-Address}',              acctsessiontime     = '%{Acct-Session-Time}',              acctinputoctets     = '%{%{Acct-Input-Gigawords}:-0}'  << 32 |                                    '%{%{Acct-Input-Octets}:-0}',              acctoutputoctets    = '%{%{Acct-Output-Gigawords}:-0}' << 32 |                                    '%{%{Acct-Output-Octets}:-0}'           WHERE acctsessionid = '%{Acct-Session-Id}'           AND username        = '%{SQL-User-Name}'           AND nasipaddress    = '%{NAS-IP-Address}'"
Tue Feb 23 15:45:33 2016 : Debug:          accounting_update_query_alt = "           INSERT INTO radacct             (acctsessionid,    acctuniqueid,      username,              realm,            nasipaddress,      nasportid,              nasporttype,      acctstarttime,     acctsessiontime,              acctauthentic,    connectinfo_start, acctinputoctets,              acctoutputoctets, calledstationid,   callingstationid,              servicetype,      framedprotocol,    framedipaddress,              acctstartdelay,   xascendsessionsvrkey)           VALUES             ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}',              '%{SQL-User-Name}',              '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}',              '%{NAS-Port-Type}',              DATE_SUB('%S',                       INTERVAL (%{%{Acct-Session-Time}:-0} +                                 %{%{Acct-Delay-Time}:-0}) SECOND),                       '%{Acct-Session-Time}',              '%{Acct-Authentic}', '',              '%{%{Acct-Input-Gigawords}:-0}' << 32 |              '%{%{Acct-Input-Octets}:-0}',              '%{%{Acct-Output-Gigawords}:-0}' << 32 |              '%{%{Acct-Output-Octets}:-0}',              '%{Called-Station-Id}', '%{Calling-Station-Id}',              '%{Service-Type}', '%{Framed-Protocol}',              '%{Framed-IP-Address}',              '0', '%{X-Ascend-Session-Svr-Key}')"
Tue Feb 23 15:45:33 2016 : Debug:          accounting_start_query = "           INSERT INTO radacct             (acctsessionid,    acctuniqueid,     username,              realm,            nasipaddress,     nasportid,              nasporttype,      acctstarttime,    acctstoptime,              acctsessiontime,  acctauthentic,    connectinfo_start,              connectinfo_stop, acctinputoctets,  acctoutputoctets,              calledstationid,  callingstationid, acctterminatecause,              servicetype,      framedprotocol,   framedipaddress,              acctstartdelay,   acctstopdelay,    xascendsessionsvrkey)           VALUES             ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}',              '%{SQL-User-Name}',              '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}',              '%{NAS-Port-Type}', '%S', NULL,              '0', '%{Acct-Authentic}', '%{Connect-Info}',              '', '0', '0',              '%{Called-Station-Id}', '%{Calling-Station-Id}', '',              '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}',              '%{%{Acct-Delay-Time}:-0}', '0', '%{X-Ascend-Session-Svr-Key}')"
Tue Feb 23 15:45:33 2016 : Debug:          accounting_start_query_alt = "           UPDATE radacct SET              acctstarttime     = '%S',              acctstartdelay    = '%{%{Acct-Delay-Time}:-0}',              connectinfo_start = '%{Connect-Info}'           WHERE acctsessionid  = '%{Acct-Session-Id}'           AND username         = '%{SQL-User-Name}'           AND nasipaddress     = '%{NAS-IP-Address}'"
Tue Feb 23 15:45:33 2016 : Debug:          accounting_stop_query = "           UPDATE radacct SET              acctstoptime       = '%S',              acctsessiontime    = '%{Acct-Session-Time}',              acctinputoctets    = '%{%{Acct-Input-Gigawords}:-0}' << 32 |                                   '%{%{Acct-Input-Octets}:-0}',              acctoutputoctets   = '%{%{Acct-Output-Gigawords}:-0}' << 32 |                                   '%{%{Acct-Output-Octets}:-0}',              acctterminatecause = '%{Acct-Terminate-Cause}',              acctstopdelay      = '%{%{Acct-Delay-Time}:-0}',              connectinfo_stop   = '%{Connect-Info}'           WHERE acctsessionid   = '%{Acct-Session-Id}'           AND username          = '%{SQL-User-Name}'           AND nasipaddress      = '%{NAS-IP-Address}'"
Tue Feb 23 15:45:33 2016 : Debug:          accounting_stop_query_alt = "           INSERT INTO radacct             (acctsessionid, acctuniqueid, username,              realm, nasipaddress, nasportid,              nasporttype, acctstarttime, acctstoptime,              acctsessiontime, acctauthentic, connectinfo_start,              connectinfo_stop, acctinputoctets, acctoutputoctets,              calledstationid, callingstationid, acctterminatecause,              servicetype, framedprotocol, framedipaddress,              acctstartdelay, acctstopdelay)           VALUES             ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}',              '%{SQL-User-Name}',              '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}',              '%{NAS-Port-Type}',              DATE_SUB('%S',                  INTERVAL (%{%{Acct-Session-Time}:-0} +                  %{%{Acct-Delay-Time}:-0}) SECOND),              '%S', '%{Acct-Session-Time}', '%{Acct-Authentic}', '',              '%{Connect-Info}',              '%{%{Acct-Input-Gigawords}:-0}' << 32 |              '%{%{Acct-Input-Octets}:-0}',              '%{%{Acct-Output-Gigawords}:-0}' << 32 |              '%{%{Acct-Output-Octets}:-0}',              '%{Called-Station-Id}', '%{Calling-Station-Id}',              '%{Acct-Terminate-Cause}',              '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}',              '0', '%{%{Acct-Delay-Time}:-0}')"
Tue Feb 23 15:45:33 2016 : Debug:          group_membership_query = "SELECT groupname           FROM radusergroup           WHERE username = '%{SQL-User-Name}'           ORDER BY priority"
Tue Feb 23 15:45:33 2016 : Debug:          connect_failure_retry_delay = 60
Tue Feb 23 15:45:33 2016 : Debug:          simul_count_query = ""
Tue Feb 23 15:45:33 2016 : Debug:          simul_verify_query = "SELECT radacctid, acctsessionid, username,                                nasipaddress, nasportid, framedipaddress,                                callingstationid, framedprotocol                                FROM radacct                                WHERE username = '%{SQL-User-Name}'                                AND acctstoptime IS NULL"
Tue Feb 23 15:45:33 2016 : Debug:          postauth_query = "INSERT INTO radpostauth                           (username, pass, reply, authdate)                           VALUES (                           '%{User-Name}',                           '%{%{User-Password}:-%{Chap-Password}}',                           '%{reply:Packet-Type}', '%S')"
Tue Feb 23 15:45:33 2016 : Debug:          safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Tue Feb 23 15:45:33 2016 : Debug:   }
Tue Feb 23 15:45:33 2016 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked
Tue Feb 23 15:45:33 2016 : Info: rlm_sql (sql): Attempting to connect to freeradius@localhost:/radius
Tue Feb 23 15:45:33 2016 : Debug: rlm_sql (sql): starting 0
Tue Feb 23 15:45:33 2016 : Info: rlm_sql (sql): Attempting to connect rlm_sql_mysql #0
Tue Feb 23 15:45:33 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0
Tue Feb 23 15:45:33 2016 : Info: rlm_sql (sql): Connected new DB handle, #0
Tue Feb 23 15:45:33 2016 : Debug: rlm_sql (sql): starting 1
Tue Feb 23 15:45:33 2016 : Info: rlm_sql (sql): Attempting to connect rlm_sql_mysql #1
Tue Feb 23 15:45:33 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #1
Tue Feb 23 15:45:33 2016 : Info: rlm_sql (sql): Connected new DB handle, #1
Tue Feb 23 15:45:33 2016 : Debug: rlm_sql (sql): starting 2
Tue Feb 23 15:45:33 2016 : Info: rlm_sql (sql): Attempting to connect rlm_sql_mysql #2
Tue Feb 23 15:45:33 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #2
Tue Feb 23 15:45:33 2016 : Info: rlm_sql (sql): Connected new DB handle, #2
Tue Feb 23 15:45:33 2016 : Debug: rlm_sql (sql): starting 3
Tue Feb 23 15:45:33 2016 : Info: rlm_sql (sql): Attempting to connect rlm_sql_mysql #3
Tue Feb 23 15:45:33 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #3
Tue Feb 23 15:45:33 2016 : Info: rlm_sql (sql): Connected new DB handle, #3
Tue Feb 23 15:45:33 2016 : Debug: rlm_sql (sql): starting 4
Tue Feb 23 15:45:33 2016 : Info: rlm_sql (sql): Attempting to connect rlm_sql_mysql #4
Tue Feb 23 15:45:33 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4
Tue Feb 23 15:45:33 2016 : Info: rlm_sql (sql): Connected new DB handle, #4
Tue Feb 23 15:45:33 2016 : Debug: rlm_sql (sql): Processing generate_sql_clients
Tue Feb 23 15:45:33 2016 : Debug: rlm_sql (sql) in generate_sql_clients: query is SELECT id, nasname, shortname, type, secret, server FROM nas
Tue Feb 23 15:45:33 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 4
Tue Feb 23 15:45:33 2016 : Debug: rlm_sql_mysql: query:  SELECT id, nasname, shortname, type, secret, server FROM nas
Tue Feb 23 15:45:33 2016 : Debug: rlm_sql (sql): Read entry nasname=192.168.6.211,shortname=test,secret=radius123
Tue Feb 23 15:45:33 2016 : Debug: rlm_sql (sql): Adding client 192.168.6.211 (test, server=<none>) to clients list
Tue Feb 23 15:45:33 2016 : Debug: rlm_sql (sql): Released sql socket id: 4
Tue Feb 23 15:45:33 2016 : Debug:  Module: Checking preacct {...} for more modules to load
Tue Feb 23 15:45:33 2016 : Debug:     (Loaded rlm_acct_unique, checking if it's valid)
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to module rlm_acct_unique
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating module "acct_unique" from file /etc/freeradius/modules/acct_unique
Tue Feb 23 15:45:33 2016 : Debug:   acct_unique {
Tue Feb 23 15:45:33 2016 : Debug:          key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"
Tue Feb 23 15:45:33 2016 : Debug:   }
Tue Feb 23 15:45:33 2016 : Debug:     (Loaded rlm_files, checking if it's valid)
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to module rlm_files
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating module "files" from file /etc/freeradius/modules/files
Tue Feb 23 15:45:33 2016 : Debug:   files {
Tue Feb 23 15:45:33 2016 : Debug:          usersfile = "/etc/freeradius/users"
Tue Feb 23 15:45:33 2016 : Debug:          acctusersfile = "/etc/freeradius/acct_users"
Tue Feb 23 15:45:33 2016 : Debug:          preproxy_usersfile = "/etc/freeradius/preproxy_users"
Tue Feb 23 15:45:33 2016 : Debug:          compat = "no"
Tue Feb 23 15:45:33 2016 : Debug:   }
Tue Feb 23 15:45:33 2016 : Debug:  Module: Checking accounting {...} for more modules to load
Tue Feb 23 15:45:33 2016 : Debug:     (Loaded rlm_detail, checking if it's valid)
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to module rlm_detail
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating module "detail" from file /etc/freeradius/modules/detail
Tue Feb 23 15:45:33 2016 : Debug:   detail {
Tue Feb 23 15:45:33 2016 : Debug:          detailfile = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d"
Tue Feb 23 15:45:33 2016 : Debug:          header = "%t"
Tue Feb 23 15:45:33 2016 : Debug:          detailperm = 384
Tue Feb 23 15:45:33 2016 : Debug:          dirperm = 493
Tue Feb 23 15:45:33 2016 : Debug:          locking = no
Tue Feb 23 15:45:33 2016 : Debug:          log_packet_header = no
Tue Feb 23 15:45:33 2016 : Debug:   }
Tue Feb 23 15:45:33 2016 : Debug:     (Loaded rlm_radutmp, checking if it's valid)
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to module rlm_radutmp
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating module "radutmp" from file /etc/freeradius/modules/radutmp
Tue Feb 23 15:45:33 2016 : Debug:   radutmp {
Tue Feb 23 15:45:33 2016 : Debug:          filename = "/var/log/freeradius/radutmp"
Tue Feb 23 15:45:33 2016 : Debug:          username = "%{User-Name}"
Tue Feb 23 15:45:33 2016 : Debug:          case_sensitive = yes
Tue Feb 23 15:45:33 2016 : Debug:          check_with_nas = yes
Tue Feb 23 15:45:33 2016 : Debug:          perm = 384
Tue Feb 23 15:45:33 2016 : Debug:          callerid = yes
Tue Feb 23 15:45:33 2016 : Debug:   }
Tue Feb 23 15:45:33 2016 : Debug:     (Loaded rlm_attr_filter, checking if it's valid)
Tue Feb 23 15:45:33 2016 : Debug:  Module: Linked to module rlm_attr_filter
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating module "attr_filter.accounting_response" from file /etc/freeradius/modules/attr_filter
Tue Feb 23 15:45:33 2016 : Debug:   attr_filter attr_filter.accounting_response {
Tue Feb 23 15:45:33 2016 : Debug:          attrsfile = "/etc/freeradius/attrs.accounting_response"
Tue Feb 23 15:45:33 2016 : Debug:          key = "%{User-Name}"
Tue Feb 23 15:45:33 2016 : Debug:          relaxed = no
Tue Feb 23 15:45:33 2016 : Debug:   }
Tue Feb 23 15:45:33 2016 : Debug:  Module: Checking session {...} for more modules to load
Tue Feb 23 15:45:33 2016 : Debug:  Module: Checking post-proxy {...} for more modules to load
Tue Feb 23 15:45:33 2016 : Debug:  Module: Checking post-auth {...} for more modules to load
Tue Feb 23 15:45:33 2016 : Debug:  Module: Instantiating module "attr_filter.access_reject" from file /etc/freeradius/modules/attr_filter
Tue Feb 23 15:45:33 2016 : Debug:   attr_filter attr_filter.access_reject {
Tue Feb 23 15:45:33 2016 : Debug:          attrsfile = "/etc/freeradius/attrs.access_reject"
Tue Feb 23 15:45:33 2016 : Debug:          key = "%{User-Name}"
Tue Feb 23 15:45:33 2016 : Debug:          relaxed = no
Tue Feb 23 15:45:33 2016 : Debug:   }
Tue Feb 23 15:45:33 2016 : Debug:  } # modules
Tue Feb 23 15:45:33 2016 : Debug: } # server
Tue Feb 23 15:45:33 2016 : Debug: server inner-tunnel { # from file /etc/freeradius/sites-enabled/inner-tunnel
Tue Feb 23 15:45:33 2016 : Debug:  modules {
Tue Feb 23 15:45:33 2016 : Debug:  Module: Checking authenticate {...} for more modules to load
Tue Feb 23 15:45:33 2016 : Debug:  Module: Checking authorize {...} for more modules to load
Tue Feb 23 15:45:33 2016 : Debug:  Module: Checking session {...} for more modules to load
Tue Feb 23 15:45:33 2016 : Debug:  Module: Checking post-proxy {...} for more modules to load
Tue Feb 23 15:45:33 2016 : Debug:  Module: Checking post-auth {...} for more modules to load
Tue Feb 23 15:45:33 2016 : Debug:  } # modules
Tue Feb 23 15:45:33 2016 : Debug: } # server
Tue Feb 23 15:45:33 2016 : Debug: radiusd: #### Opening IP addresses and Ports ####
Tue Feb 23 15:45:33 2016 : Debug: listen {
Tue Feb 23 15:45:33 2016 : Debug:          type = "auth"
Tue Feb 23 15:45:33 2016 : Debug:          ipaddr = *
Tue Feb 23 15:45:33 2016 : Debug:          port = 0
Tue Feb 23 15:45:33 2016 : Debug: }
Tue Feb 23 15:45:33 2016 : Debug: listen {
Tue Feb 23 15:45:33 2016 : Debug:          type = "acct"
Tue Feb 23 15:45:33 2016 : Debug:          ipaddr = *
Tue Feb 23 15:45:33 2016 : Debug:          port = 0
Tue Feb 23 15:45:33 2016 : Debug: }
Tue Feb 23 15:45:33 2016 : Debug: listen {
Tue Feb 23 15:45:33 2016 : Debug:          type = "auth"
Tue Feb 23 15:45:33 2016 : Debug:          ipaddr = 127.0.0.1
Tue Feb 23 15:45:33 2016 : Debug:          port = 18120
Tue Feb 23 15:45:33 2016 : Debug: }
Tue Feb 23 15:45:33 2016 : Info:  ... adding new socket proxy address * port 54611
Tue Feb 23 15:45:33 2016 : Debug: Listening on authentication address * port 1812
Tue Feb 23 15:45:33 2016 : Debug: Listening on accounting address * port 1813
Tue Feb 23 15:45:33 2016 : Debug: Listening on authentication address 127.0.0.1 port 18120 as server inner-tunnel
Tue Feb 23 15:45:33 2016 : Debug: Listening on proxy address * port 1814
Tue Feb 23 15:45:33 2016 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 192.168.6.211 port 1812, id=142, length=116
                User-Name = "1234"
                NAS-IP-Address = 211.6.168.192
                NAS-Identifier = "SWITCH01-TEST"
                NAS-Port-Type = Virtual
                Service-Type = NAS-Prompt-User
                EAP-Message = 0x020000090131323334
                Message-Authenticator = 0x17ebe7cb3727cfa3b2fde0893d30241a
                MS-RAS-Vendor = 184549376
                Calling-Station-Id = "192.168.14.114"
Tue Feb 23 15:45:41 2016 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default
Tue Feb 23 15:45:41 2016 : Info: +- entering group authorize {...}
Tue Feb 23 15:45:41 2016 : Info: ++[preprocess] returns ok
Tue Feb 23 15:45:41 2016 : Info: ++[chap] returns noop
Tue Feb 23 15:45:41 2016 : Info: ++[mschap] returns noop
Tue Feb 23 15:45:41 2016 : Info: ++[digest] returns noop
Tue Feb 23 15:45:41 2016 : Info: [suffix] No '@' in User-Name = "1234", looking up realm NULL
Tue Feb 23 15:45:41 2016 : Info: [suffix] No such realm "NULL"
Tue Feb 23 15:45:41 2016 : Info: ++[suffix] returns noop
Tue Feb 23 15:45:41 2016 : Info: [eap] EAP packet type response id 0 length 9
Tue Feb 23 15:45:41 2016 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation
Tue Feb 23 15:45:41 2016 : Info: ++[eap] returns updated
Tue Feb 23 15:45:41 2016 : Info: [sql]     expand: %{User-Name} -> 1234
Tue Feb 23 15:45:41 2016 : Info: [sql] sql_set_user escaped user --> '1234'
Tue Feb 23 15:45:41 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 3
Tue Feb 23 15:45:41 2016 : Info: [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 = '1234'           ORDER BY id
Tue Feb 23 15:45:41 2016 : Debug: rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM radcheck           WHERE username = '1234'           ORDER BY id
Tue Feb 23 15:45:41 2016 : Info: [sql] User found in radcheck table
Tue Feb 23 15:45:41 2016 : Info: [sql]     expand: SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '%{SQL-User-Name}'           ORDER BY id -> SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '1234'           ORDER BY id
Tue Feb 23 15:45:41 2016 : Debug: rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '1234'           ORDER BY id
Tue Feb 23 15:45:41 2016 : Info: [sql]     expand: SELECT groupname           FROM radusergroup           WHERE username = '%{SQL-User-Name}'           ORDER BY priority -> SELECT groupname           FROM radusergroup           WHERE username = '1234'           ORDER BY priority
Tue Feb 23 15:45:41 2016 : Debug: rlm_sql_mysql: query:  SELECT groupname           FROM radusergroup           WHERE username = '1234'           ORDER BY priority
Tue Feb 23 15:45:41 2016 : Info: [sql]     expand: SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = '%{Sql-Group}'           ORDER BY id -> SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = 'HP-Procurve-Admin'           ORDER BY id
Tue Feb 23 15:45:41 2016 : Debug: rlm_sql_mysql: query:  SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = 'HP-Procurve-Admin'           ORDER BY id
Tue Feb 23 15:45:41 2016 : Info: [sql] User found in group HP-Procurve-Admin
Tue Feb 23 15:45:41 2016 : Info: [sql]     expand: SELECT id, groupname, attribute,           value, op           FROM radgroupreply           WHERE groupname = '%{Sql-Group}'           ORDER BY id -> SELECT id, groupname, attribute,           value, op           FROM radgroupreply           WHERE groupname = 'HP-Procurve-Admin'           ORDER BY id
Tue Feb 23 15:45:41 2016 : Debug: rlm_sql_mysql: query:  SELECT id, groupname, attribute,           value, op           FROM radgroupreply           WHERE groupname = 'HP-Procurve-Admin'           ORDER BY id
Tue Feb 23 15:45:41 2016 : Debug: rlm_sql (sql): Released sql socket id: 3
Tue Feb 23 15:45:41 2016 : Info: ++[sql] returns ok
Tue Feb 23 15:45:41 2016 : Info: ++[expiration] returns noop
Tue Feb 23 15:45:41 2016 : Info: ++[logintime] returns noop
Tue Feb 23 15:45:41 2016 : Info: [pap] WARNING: Auth-Type already set.  Not setting to PAP
Tue Feb 23 15:45:41 2016 : Info: ++[pap] returns noop
Tue Feb 23 15:45:41 2016 : Info: Found Auth-Type = EAP
Tue Feb 23 15:45:41 2016 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Feb 23 15:45:41 2016 : Info: !!!    Replacing User-Password in config items with Cleartext-Password.     !!!
Tue Feb 23 15:45:41 2016 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Feb 23 15:45:41 2016 : Info: !!! Please update your configuration so that the "known good"               !!!
Tue Feb 23 15:45:41 2016 : Info: !!! clear text password is in Cleartext-Password, and not in User-Password. !!!
Tue Feb 23 15:45:41 2016 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Feb 23 15:45:41 2016 : Info: # Executing group from file /etc/freeradius/sites-enabled/default
Tue Feb 23 15:45:41 2016 : Info: +- entering group authenticate {...}
Tue Feb 23 15:45:41 2016 : Info: [eap] EAP Identity
Tue Feb 23 15:45:41 2016 : Info: [eap] processing type md5
Tue Feb 23 15:45:41 2016 : Debug: rlm_eap_md5: Issuing Challenge
Tue Feb 23 15:45:41 2016 : Info: ++[eap] returns handled
Sending Access-Challenge of id 142 to 192.168.6.211 port 1812
                Service-Type = Administrative-User
                EAP-Message = 0x01010016041092556e11d1495a77ac213fbf04b83b8d
                Message-Authenticator = 0x00000000000000000000000000000000
                State = 0x0d497f860d487b663cf1bfd5de864a48
Tue Feb 23 15:45:41 2016 : Info: Finished request 0.
Tue Feb 23 15:45:41 2016 : Debug: Going to the next request
Tue Feb 23 15:45:41 2016 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.6.211 port 1812, id=143, length=131
                User-Name = "1234"
                NAS-IP-Address = 211.6.168.192
                NAS-Identifier = "SWITCH01-TEST"
                NAS-Port-Type = Virtual
                Service-Type = NAS-Prompt-User
                State = 0x0d497f860d487b663cf1bfd5de864a48
                EAP-Message = 0x020100060319
                Message-Authenticator = 0xae7630668dd6118c160131b4cefec517
                MS-RAS-Vendor = 184549376
                Calling-Station-Id = "192.168.14.114"
Tue Feb 23 15:45:41 2016 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default
Tue Feb 23 15:45:41 2016 : Info: +- entering group authorize {...}
Tue Feb 23 15:45:41 2016 : Info: ++[preprocess] returns ok
Tue Feb 23 15:45:41 2016 : Info: ++[chap] returns noop
Tue Feb 23 15:45:41 2016 : Info: ++[mschap] returns noop
Tue Feb 23 15:45:41 2016 : Info: ++[digest] returns noop
Tue Feb 23 15:45:41 2016 : Info: [suffix] No '@' in User-Name = "1234", looking up realm NULL
Tue Feb 23 15:45:41 2016 : Info: [suffix] No such realm "NULL"
Tue Feb 23 15:45:41 2016 : Info: ++[suffix] returns noop
Tue Feb 23 15:45:41 2016 : Info: [eap] EAP packet type response id 1 length 6
Tue Feb 23 15:45:41 2016 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation
Tue Feb 23 15:45:41 2016 : Info: ++[eap] returns updated
Tue Feb 23 15:45:41 2016 : Info: [sql]     expand: %{User-Name} -> 1234
Tue Feb 23 15:45:41 2016 : Info: [sql] sql_set_user escaped user --> '1234'
Tue Feb 23 15:45:41 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 2
Tue Feb 23 15:45:41 2016 : Info: [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 = '1234'           ORDER BY id
Tue Feb 23 15:45:41 2016 : Debug: rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM radcheck           WHERE username = '1234'           ORDER BY id
Tue Feb 23 15:45:41 2016 : Info: [sql] User found in radcheck table
Tue Feb 23 15:45:41 2016 : Info: [sql]     expand: SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '%{SQL-User-Name}'           ORDER BY id -> SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '1234'           ORDER BY id
Tue Feb 23 15:45:41 2016 : Debug: rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '1234'           ORDER BY id
Tue Feb 23 15:45:41 2016 : Info: [sql]     expand: SELECT groupname           FROM radusergroup           WHERE username = '%{SQL-User-Name}'           ORDER BY priority -> SELECT groupname           FROM radusergroup           WHERE username = '1234'           ORDER BY priority
Tue Feb 23 15:45:41 2016 : Debug: rlm_sql_mysql: query:  SELECT groupname           FROM radusergroup           WHERE username = '1234'           ORDER BY priority
Tue Feb 23 15:45:41 2016 : Info: [sql]     expand: SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = '%{Sql-Group}'           ORDER BY id -> SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = 'HP-Procurve-Admin'           ORDER BY id
Tue Feb 23 15:45:41 2016 : Debug: rlm_sql_mysql: query:  SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = 'HP-Procurve-Admin'           ORDER BY id
Tue Feb 23 15:45:41 2016 : Info: [sql] User found in group HP-Procurve-Admin
Tue Feb 23 15:45:41 2016 : Info: [sql]     expand: SELECT id, groupname, attribute,           value, op           FROM radgroupreply           WHERE groupname = '%{Sql-Group}'           ORDER BY id -> SELECT id, groupname, attribute,           value, op           FROM radgroupreply           WHERE groupname = 'HP-Procurve-Admin'           ORDER BY id
Tue Feb 23 15:45:41 2016 : Debug: rlm_sql_mysql: query:  SELECT id, groupname, attribute,           value, op           FROM radgroupreply           WHERE groupname = 'HP-Procurve-Admin'           ORDER BY id
Tue Feb 23 15:45:41 2016 : Debug: rlm_sql (sql): Released sql socket id: 2
Tue Feb 23 15:45:41 2016 : Info: ++[sql] returns ok
Tue Feb 23 15:45:41 2016 : Info: ++[expiration] returns noop
Tue Feb 23 15:45:41 2016 : Info: ++[logintime] returns noop
Tue Feb 23 15:45:41 2016 : Info: [pap] WARNING: Auth-Type already set.  Not setting to PAP
Tue Feb 23 15:45:41 2016 : Info: ++[pap] returns noop
Tue Feb 23 15:45:41 2016 : Info: Found Auth-Type = EAP
Tue Feb 23 15:45:41 2016 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Feb 23 15:45:41 2016 : Info: !!!    Replacing User-Password in config items with Cleartext-Password.     !!!
Tue Feb 23 15:45:41 2016 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Feb 23 15:45:41 2016 : Info: !!! Please update your configuration so that the "known good"               !!!
Tue Feb 23 15:45:41 2016 : Info: !!! clear text password is in Cleartext-Password, and not in User-Password. !!!
Tue Feb 23 15:45:41 2016 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Feb 23 15:45:41 2016 : Info: # Executing group from file /etc/freeradius/sites-enabled/default
Tue Feb 23 15:45:41 2016 : Info: +- entering group authenticate {...}
Tue Feb 23 15:45:41 2016 : Info: [eap] Request found, released from the list
Tue Feb 23 15:45:41 2016 : Info: [eap] EAP NAK
Tue Feb 23 15:45:41 2016 : Info: [eap] EAP-NAK asked for EAP-Type/peap
Tue Feb 23 15:45:41 2016 : Info: [eap] processing type tls
Tue Feb 23 15:45:41 2016 : Info: [tls] Initiate
Tue Feb 23 15:45:41 2016 : Info: [tls] Start returned 1
Tue Feb 23 15:45:41 2016 : Info: ++[eap] returns handled
Sending Access-Challenge of id 143 to 192.168.6.211 port 1812
                Service-Type = Administrative-User
                EAP-Message = 0x010200061920
                Message-Authenticator = 0x00000000000000000000000000000000
                State = 0x0d497f860c4b66663cf1bfd5de864a48
Tue Feb 23 15:45:41 2016 : Info: Finished request 1.
Tue Feb 23 15:45:41 2016 : Debug: Going to the next request
Tue Feb 23 15:45:41 2016 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.6.211 port 1812, id=144, length=211
                User-Name = "1234"
                NAS-IP-Address = 211.6.168.192
                NAS-Identifier = "SWITCH01-TEST"
                NAS-Port-Type = Virtual
                Service-Type = NAS-Prompt-User
                State = 0x0d497f860c4b66663cf1bfd5de864a48
                EAP-Message = 0x020200561900160303004b010000470303ab6769c0d58d7f9d9e64e9ab8b98b5fd91331b6289cea731d117c81ab3d7f2f900000c003d0035003c002f000a000901000012000d000e000c060105010401030102010101
                Message-Authenticator = 0x3bd3a5d1bd573a86245aa80ae07478ff
                MS-RAS-Vendor = 184549376
                Calling-Station-Id = "192.168.14.114"
Tue Feb 23 15:45:41 2016 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default
Tue Feb 23 15:45:41 2016 : Info: +- entering group authorize {...}
Tue Feb 23 15:45:41 2016 : Info: ++[preprocess] returns ok
Tue Feb 23 15:45:41 2016 : Info: ++[chap] returns noop
Tue Feb 23 15:45:41 2016 : Info: ++[mschap] returns noop
Tue Feb 23 15:45:41 2016 : Info: ++[digest] returns noop
Tue Feb 23 15:45:41 2016 : Info: [suffix] No '@' in User-Name = "1234", looking up realm NULL
Tue Feb 23 15:45:41 2016 : Info: [suffix] No such realm "NULL"
Tue Feb 23 15:45:41 2016 : Info: ++[suffix] returns noop
Tue Feb 23 15:45:41 2016 : Info: [eap] EAP packet type response id 2 length 86
Tue Feb 23 15:45:41 2016 : Info: [eap] Continuing tunnel setup.
Tue Feb 23 15:45:41 2016 : Info: ++[eap] returns ok
Tue Feb 23 15:45:41 2016 : Info: Found Auth-Type = EAP
Tue Feb 23 15:45:41 2016 : Info: # Executing group from file /etc/freeradius/sites-enabled/default
Tue Feb 23 15:45:41 2016 : Info: +- entering group authenticate {...}
Tue Feb 23 15:45:41 2016 : Info: [eap] Request found, released from the list
Tue Feb 23 15:45:41 2016 : Info: [eap] EAP/peap
Tue Feb 23 15:45:41 2016 : Info: [eap] processing type peap
Tue Feb 23 15:45:41 2016 : Info: [peap] processing EAP-TLS
Tue Feb 23 15:45:41 2016 : Info: [peap] eaptls_verify returned 7
Tue Feb 23 15:45:41 2016 : Info: [peap] Done initial handshake
Tue Feb 23 15:45:41 2016 : Info: [peap]     (other): before/accept initialization
Tue Feb 23 15:45:41 2016 : Info: [peap]     TLS_accept: before/accept initialization
Tue Feb 23 15:45:41 2016 : Info: [peap] <<< TLS 1.0 Handshake [length 004b], ClientHello
Tue Feb 23 15:45:41 2016 : Info: [peap]     TLS_accept: SSLv3 read client hello A
Tue Feb 23 15:45:41 2016 : Info: [peap] >>> TLS 1.0 Handshake [length 002a], ServerHello
Tue Feb 23 15:45:41 2016 : Info: [peap]     TLS_accept: SSLv3 write server hello A
Tue Feb 23 15:45:41 2016 : Info: [peap] >>> TLS 1.0 Handshake [length 02e6], Certificate
Tue Feb 23 15:45:41 2016 : Info: [peap]     TLS_accept: SSLv3 write certificate A
Tue Feb 23 15:45:41 2016 : Info: [peap] >>> TLS 1.0 Handshake [length 0004], ServerHelloDone
Tue Feb 23 15:45:41 2016 : Info: [peap]     TLS_accept: SSLv3 write server done A
Tue Feb 23 15:45:41 2016 : Info: [peap]     TLS_accept: SSLv3 flush data
Tue Feb 23 15:45:41 2016 : Info: [peap]     TLS_accept: Need to read more data: SSLv3 read client certificate A
Tue Feb 23 15:45:41 2016 : Debug: In SSL Handshake Phase
Tue Feb 23 15:45:41 2016 : Debug: In SSL Accept mode
Tue Feb 23 15:45:41 2016 : Info: [peap] eaptls_process returned 13
Tue Feb 23 15:45:41 2016 : Info: [peap] EAPTLS_HANDLED
Tue Feb 23 15:45:41 2016 : Info: ++[eap] returns handled
Sending Access-Challenge of id 144 to 192.168.6.211 port 1812
                EAP-Message = 0x010303291900160301002a02000026030134c2c8fe81a89853a504ac4216bfcd1fc0eda05b01ad8c4b3e03edff9e43127d0000350016030102e60b0002e20002df0002dc308202d8308201c0a003020102020900a0b10d9f121dd008300d06092a864886f70d01010b05003024312230200603550403131972616469757330322d6b657363682e636c617373656e2e6465301e170d3136303232323039333634395a170d3236303231393039333634395a3024312230200603550403131972616469757330322d6b657363682e636c617373656e2e646530820122300d06092a864886f70d01010105000382010f003082010a0282010100971a63c43d
                EAP-Message = 0xf2b17bc57816c5c71129af0b0c5f5a204a9a95eaef60de83596dd0a29042c1a605502c5b95d73d9ca51609c2d41815e3c81a31dbd0ce43d20f9e206b1dd4dc2218b66d1a30d32a546d50ede101691f8df4d64ecd20896a1ca61163ef880b81d3243d647adb27bc943a379185208308203ee571f2d2d665e419e945e8d4bfe75b602b557222bbba56036f38cfc25f79e5cb03fc851cef447313c4474fa32dc4aa7bf3ed62eabcce51e15d5c575847982dc313f7e9621f0b4c7a6a33867bc0e396867f60977bf172e789850bf1b9a46a2594912b4f2b0eccfef51d2a87b2b3f534bf1485bf19c74dbbc1fea76340ab52c8cef84c19a7d1038d89f9c90203
                EAP-Message = 0x010001a30d300b30090603551d1304023000300d06092a864886f70d01010b05000382010100218b7b3a3c12279ed2e0f5ff559a9ca32bb24f41262e22544b73dfc8876e0aff872161dd12f4855679b928fa34327111dc74c4cc45371f9661a23eaebea0824669534c78a630229e06c56a772ade4024d1042e4f3f96d1fa6d8055cc594e4f24b0517a5a554816ebfa557b5f5524695dbcdb92fe59323c0dcae23169a10e17964fdfc0d583537be90c080356747c652d2d44d77725fd36fced8cd5801cbf98a9cb7e25c1f332f303287a3e98c1cc67aefb8f02dc1e03c8b2555935b7cc389f50ee01f0f19a3211e35406654c242f3f3804b8f94776ef56
                EAP-Message = 0x4f29c6c98be03ab4ca56f65f6c340b40867a94d719979692f3e5bfad7caec05cc561380b09056f7cdf16030100040e000000
                Message-Authenticator = 0x00000000000000000000000000000000
                State = 0x0d497f860f4a66663cf1bfd5de864a48
Tue Feb 23 15:45:41 2016 : Info: Finished request 2.
Tue Feb 23 15:45:41 2016 : Debug: Going to the next request
Tue Feb 23 15:45:41 2016 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.6.211 port 1812, id=145, length=459
                User-Name = "1234"
                NAS-IP-Address = 211.6.168.192
                NAS-Identifier = "SWITCH01-TEST"
                NAS-Port-Type = Virtual
                Service-Type = NAS-Prompt-User
                State = 0x0d497f860f4a66663cf1bfd5de864a48
                EAP-Message = 0x0203014c190016030101061000010201005dfdb2a2b54c590ef5d7cc360c6473c1486587d785b79ffead7bc460be2704428796e2b114874b8968c95ac964d71fcfe5d5ade81f82988dad45ca9b08c5205e269138b22ed0f6b339254f0fbf249b965f134aa59fbbeb310006de279dbea43115459743bb9d34520dae23c4db996e07cad77a149ad9da0e2b94a3effa431a113ddecddddba449674bb643465d7f6a32541a51d0560c24643f5d4953e8da3761c7d6555d45f789e8c2db692768f57ed65a395752e943fe7beb2a7c74b6b3ed661a2dfba98f899806a90a51a95ee14d11eb19014bc9a867d570b0e1dc29b2114864ffcc7e3a7e79ee4d6cfbd0
                EAP-Message = 0x669aa7029cc07705cacc9d17cbf59a69fac73ac41403010001011603010030c7788739c5cc92d32780d2a3adddd296b748bdf783510c22ce44c3cb34d24aa031e9ed04ff61d09c0668d082dd4646e3
                Message-Authenticator = 0x635e498c0eec7a5cccbe224717e8c348
                MS-RAS-Vendor = 184549376
                Calling-Station-Id = "192.168.14.114"
Tue Feb 23 15:45:42 2016 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default
Tue Feb 23 15:45:42 2016 : Info: +- entering group authorize {...}
Tue Feb 23 15:45:42 2016 : Info: ++[preprocess] returns ok
Tue Feb 23 15:45:42 2016 : Info: ++[chap] returns noop
Tue Feb 23 15:45:42 2016 : Info: ++[mschap] returns noop
Tue Feb 23 15:45:42 2016 : Info: ++[digest] returns noop
Tue Feb 23 15:45:42 2016 : Info: [suffix] No '@' in User-Name = "1234", looking up realm NULL
Tue Feb 23 15:45:42 2016 : Info: [suffix] No such realm "NULL"
Tue Feb 23 15:45:42 2016 : Info: ++[suffix] returns noop
Tue Feb 23 15:45:42 2016 : Info: [eap] EAP packet type response id 3 length 253
Tue Feb 23 15:45:42 2016 : Info: [eap] Continuing tunnel setup.
Tue Feb 23 15:45:42 2016 : Info: ++[eap] returns ok
Tue Feb 23 15:45:42 2016 : Info: Found Auth-Type = EAP
Tue Feb 23 15:45:42 2016 : Info: # Executing group from file /etc/freeradius/sites-enabled/default
Tue Feb 23 15:45:42 2016 : Info: +- entering group authenticate {...}
Tue Feb 23 15:45:42 2016 : Info: [eap] Request found, released from the list
Tue Feb 23 15:45:42 2016 : Info: [eap] EAP/peap
Tue Feb 23 15:45:42 2016 : Info: [eap] processing type peap
Tue Feb 23 15:45:42 2016 : Info: [peap] processing EAP-TLS
Tue Feb 23 15:45:42 2016 : Info: [peap] eaptls_verify returned 7
Tue Feb 23 15:45:42 2016 : Info: [peap] Done initial handshake
Tue Feb 23 15:45:42 2016 : Info: [peap] <<< TLS 1.0 Handshake [length 0106], ClientKeyExchange
Tue Feb 23 15:45:42 2016 : Info: [peap]     TLS_accept: SSLv3 read client key exchange A
Tue Feb 23 15:45:42 2016 : Info: [peap] <<< TLS 1.0 ChangeCipherSpec [length 0001]
Tue Feb 23 15:45:42 2016 : Info: [peap] <<< TLS 1.0 Handshake [length 0010], Finished
Tue Feb 23 15:45:42 2016 : Info: [peap]     TLS_accept: SSLv3 read finished A
Tue Feb 23 15:45:42 2016 : Info: [peap] >>> TLS 1.0 ChangeCipherSpec [length 0001]
Tue Feb 23 15:45:42 2016 : Info: [peap]     TLS_accept: SSLv3 write change cipher spec A
Tue Feb 23 15:45:42 2016 : Info: [peap] >>> TLS 1.0 Handshake [length 0010], Finished
Tue Feb 23 15:45:42 2016 : Info: [peap]     TLS_accept: SSLv3 write finished A
Tue Feb 23 15:45:42 2016 : Info: [peap]     TLS_accept: SSLv3 flush data
Tue Feb 23 15:45:42 2016 : Info: [peap]     (other): SSL negotiation finished successfully
Tue Feb 23 15:45:42 2016 : Debug: SSL Connection Established
Tue Feb 23 15:45:42 2016 : Info: [peap] eaptls_process returned 13
Tue Feb 23 15:45:42 2016 : Info: [peap] EAPTLS_HANDLED
Tue Feb 23 15:45:42 2016 : Info: ++[eap] returns handled
Sending Access-Challenge of id 145 to 192.168.6.211 port 1812
                EAP-Message = 0x0104004119001403010001011603010030ea9ac534b5665ede970c0f2b17eeaef50b4889af5b2f1c0cb08c51c504fe230d42017d37df12ae7e23b8e38815a58993
                Message-Authenticator = 0x00000000000000000000000000000000
                State = 0x0d497f860e4d66663cf1bfd5de864a48
Tue Feb 23 15:45:42 2016 : Info: Finished request 3.
Tue Feb 23 15:45:42 2016 : Debug: Going to the next request
Tue Feb 23 15:45:42 2016 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.6.211 port 1812, id=146, length=131
                User-Name = "1234"
                NAS-IP-Address = 211.6.168.192
                NAS-Identifier = "SWITCH01-TEST"
                NAS-Port-Type = Virtual
                Service-Type = NAS-Prompt-User
                State = 0x0d497f860e4d66663cf1bfd5de864a48
                EAP-Message = 0x020400061900
                Message-Authenticator = 0x70b79c3d9fa53cd08bb48bd815a0a2af
                MS-RAS-Vendor = 184549376
                Calling-Station-Id = "192.168.14.114"
Tue Feb 23 15:45:42 2016 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default
Tue Feb 23 15:45:42 2016 : Info: +- entering group authorize {...}
Tue Feb 23 15:45:42 2016 : Info: ++[preprocess] returns ok
Tue Feb 23 15:45:42 2016 : Info: ++[chap] returns noop
Tue Feb 23 15:45:42 2016 : Info: ++[mschap] returns noop
Tue Feb 23 15:45:42 2016 : Info: ++[digest] returns noop
Tue Feb 23 15:45:42 2016 : Info: [suffix] No '@' in User-Name = "1234", looking up realm NULL
Tue Feb 23 15:45:42 2016 : Info: [suffix] No such realm "NULL"
Tue Feb 23 15:45:42 2016 : Info: ++[suffix] returns noop
Tue Feb 23 15:45:42 2016 : Info: [eap] EAP packet type response id 4 length 6
Tue Feb 23 15:45:42 2016 : Info: [eap] Continuing tunnel setup.
Tue Feb 23 15:45:42 2016 : Info: ++[eap] returns ok
Tue Feb 23 15:45:42 2016 : Info: Found Auth-Type = EAP
Tue Feb 23 15:45:42 2016 : Info: # Executing group from file /etc/freeradius/sites-enabled/default
Tue Feb 23 15:45:42 2016 : Info: +- entering group authenticate {...}
Tue Feb 23 15:45:42 2016 : Info: [eap] Request found, released from the list
Tue Feb 23 15:45:42 2016 : Info: [eap] EAP/peap
Tue Feb 23 15:45:42 2016 : Info: [eap] processing type peap
Tue Feb 23 15:45:42 2016 : Info: [peap] processing EAP-TLS
Tue Feb 23 15:45:42 2016 : Info: [peap] Received TLS ACK
Tue Feb 23 15:45:42 2016 : Info: [peap] ACK handshake is finished
Tue Feb 23 15:45:42 2016 : Info: [peap] eaptls_verify returned 3
Tue Feb 23 15:45:42 2016 : Info: [peap] eaptls_process returned 3
Tue Feb 23 15:45:42 2016 : Info: [peap] EAPTLS_SUCCESS
Tue Feb 23 15:45:42 2016 : Info: [peap] Session established.  Decoding tunneled attributes.
Tue Feb 23 15:45:42 2016 : Info: [peap] Peap state TUNNEL ESTABLISHED
Tue Feb 23 15:45:42 2016 : Info: ++[eap] returns handled
Sending Access-Challenge of id 146 to 192.168.6.211 port 1812
                EAP-Message = 0x0105002b190017030100202b8a05992bfcee61c127eb4722aca63f80d3dfcc7bab78c60a3c41a659a10fb8
                Message-Authenticator = 0x00000000000000000000000000000000
                State = 0x0d497f86094c66663cf1bfd5de864a48
Tue Feb 23 15:45:42 2016 : Info: Finished request 4.
Tue Feb 23 15:45:42 2016 : Debug: Going to the next request
Tue Feb 23 15:45:42 2016 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.6.211 port 1812, id=147, length=168
                User-Name = "1234"
                NAS-IP-Address = 211.6.168.192
                NAS-Identifier = "SWITCH01-TEST"
                NAS-Port-Type = Virtual
                Service-Type = NAS-Prompt-User
                State = 0x0d497f86094c66663cf1bfd5de864a48
                EAP-Message = 0x0205002b1900170301002022f3c45761dfa101968af468f6a95339b01c176d48a72061254682aa6d1d7c5a
                Message-Authenticator = 0x1a5d2573de10c5ea6a9d1f2aee5625fd
                MS-RAS-Vendor = 184549376
                Calling-Station-Id = "192.168.14.114"
Tue Feb 23 15:45:42 2016 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default
Tue Feb 23 15:45:42 2016 : Info: +- entering group authorize {...}
Tue Feb 23 15:45:42 2016 : Info: ++[preprocess] returns ok
Tue Feb 23 15:45:42 2016 : Info: ++[chap] returns noop
Tue Feb 23 15:45:42 2016 : Info: ++[mschap] returns noop
Tue Feb 23 15:45:42 2016 : Info: ++[digest] returns noop
Tue Feb 23 15:45:42 2016 : Info: [suffix] No '@' in User-Name = "1234", looking up realm NULL
Tue Feb 23 15:45:42 2016 : Info: [suffix] No such realm "NULL"
Tue Feb 23 15:45:42 2016 : Info: ++[suffix] returns noop
Tue Feb 23 15:45:42 2016 : Info: [eap] EAP packet type response id 5 length 43
Tue Feb 23 15:45:42 2016 : Info: [eap] Continuing tunnel setup.
Tue Feb 23 15:45:42 2016 : Info: ++[eap] returns ok
Tue Feb 23 15:45:42 2016 : Info: Found Auth-Type = EAP
Tue Feb 23 15:45:42 2016 : Info: # Executing group from file /etc/freeradius/sites-enabled/default
Tue Feb 23 15:45:42 2016 : Info: +- entering group authenticate {...}
Tue Feb 23 15:45:42 2016 : Info: [eap] Request found, released from the list
Tue Feb 23 15:45:42 2016 : Info: [eap] EAP/peap
Tue Feb 23 15:45:42 2016 : Info: [eap] processing type peap
Tue Feb 23 15:45:42 2016 : Info: [peap] processing EAP-TLS
Tue Feb 23 15:45:42 2016 : Info: [peap] eaptls_verify returned 7
Tue Feb 23 15:45:42 2016 : Info: [peap] Done initial handshake
Tue Feb 23 15:45:42 2016 : Info: [peap] eaptls_process returned 7
Tue Feb 23 15:45:42 2016 : Info: [peap] EAPTLS_OK
Tue Feb 23 15:45:42 2016 : Info: [peap] Session established.  Decoding tunneled attributes.
Tue Feb 23 15:45:42 2016 : Info: [peap] Peap state WAITING FOR INNER IDENTITY
Tue Feb 23 15:45:42 2016 : Info: [peap] Identity - 1234
Tue Feb 23 15:45:42 2016 : Info: [peap] Got inner identity '1234'
Tue Feb 23 15:45:42 2016 : Info: [peap] Setting default EAP type for tunneled EAP session.
Tue Feb 23 15:45:42 2016 : Info: [peap] Got tunneled request
                EAP-Message = 0x020500090131323334
server  {
Tue Feb 23 15:45:42 2016 : Info: [peap] Setting User-Name to 1234
Sending tunneled request
                EAP-Message = 0x020500090131323334
                FreeRADIUS-Proxied-To = 127.0.0.1
                User-Name = "1234"
server inner-tunnel {
Tue Feb 23 15:45:42 2016 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/inner-tunnel
Tue Feb 23 15:45:42 2016 : Info: +- entering group authorize {...}
Tue Feb 23 15:45:42 2016 : Info: ++[chap] returns noop
Tue Feb 23 15:45:42 2016 : Info: ++[mschap] returns noop
Tue Feb 23 15:45:42 2016 : Info: [suffix] No '@' in User-Name = "1234", looking up realm NULL
Tue Feb 23 15:45:42 2016 : Info: [suffix] No such realm "NULL"
Tue Feb 23 15:45:42 2016 : Info: ++[suffix] returns noop
Tue Feb 23 15:45:42 2016 : Info: ++[control] returns noop
Tue Feb 23 15:45:42 2016 : Info: [eap] EAP packet type response id 5 length 9
Tue Feb 23 15:45:42 2016 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation
Tue Feb 23 15:45:42 2016 : Info: ++[eap] returns updated
Tue Feb 23 15:45:42 2016 : Info: ++[files] returns noop
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: %{User-Name} -> 1234
Tue Feb 23 15:45:42 2016 : Info: [sql] sql_set_user escaped user --> '1234'
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 1
Tue Feb 23 15:45:42 2016 : Info: [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 = '1234'           ORDER BY id
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM radcheck           WHERE username = '1234'           ORDER BY id
Tue Feb 23 15:45:42 2016 : Info: [sql] User found in radcheck table
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '%{SQL-User-Name}'           ORDER BY id -> SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '1234'           ORDER BY id
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '1234'           ORDER BY id
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: SELECT groupname           FROM radusergroup           WHERE username = '%{SQL-User-Name}'           ORDER BY priority -> SELECT groupname           FROM radusergroup           WHERE username = '1234'           ORDER BY priority
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql_mysql: query:  SELECT groupname           FROM radusergroup           WHERE username = '1234'           ORDER BY priority
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = '%{Sql-Group}'           ORDER BY id -> SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = 'HP-Procurve-Admin'           ORDER BY id
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql_mysql: query:  SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = 'HP-Procurve-Admin'           ORDER BY id
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql (sql): Released sql socket id: 1
Tue Feb 23 15:45:42 2016 : Info: ++[sql] returns ok
Tue Feb 23 15:45:42 2016 : Info: ++[expiration] returns noop
Tue Feb 23 15:45:42 2016 : Info: ++[logintime] returns noop
Tue Feb 23 15:45:42 2016 : Info: [pap] WARNING: Auth-Type already set.  Not setting to PAP
Tue Feb 23 15:45:42 2016 : Info: ++[pap] returns noop
Tue Feb 23 15:45:42 2016 : Info: Found Auth-Type = EAP
Tue Feb 23 15:45:42 2016 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Feb 23 15:45:42 2016 : Info: !!!    Replacing User-Password in config items with Cleartext-Password.     !!!
Tue Feb 23 15:45:42 2016 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Feb 23 15:45:42 2016 : Info: !!! Please update your configuration so that the "known good"               !!!
Tue Feb 23 15:45:42 2016 : Info: !!! clear text password is in Cleartext-Password, and not in User-Password. !!!
Tue Feb 23 15:45:42 2016 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Feb 23 15:45:42 2016 : Info: # Executing group from file /etc/freeradius/sites-enabled/inner-tunnel
Tue Feb 23 15:45:42 2016 : Info: +- entering group authenticate {...}
Tue Feb 23 15:45:42 2016 : Info: [eap] EAP Identity
Tue Feb 23 15:45:42 2016 : Info: [eap] processing type mschapv2
Tue Feb 23 15:45:42 2016 : Debug: rlm_eap_mschapv2: Issuing Challenge
Tue Feb 23 15:45:42 2016 : Info: ++[eap] returns handled
} # server inner-tunnel
Tue Feb 23 15:45:42 2016 : Info: [peap] Got tunneled reply code 11
                EAP-Message = 0x0106001e1a01060019108f9ae5e1e773168c098f021e5eb93d4831323334
                Message-Authenticator = 0x00000000000000000000000000000000
                State = 0x6162be1b6164a4ac160d1d957d730383
Tue Feb 23 15:45:42 2016 : Info: [peap] Got tunneled reply RADIUS code 11
                EAP-Message = 0x0106001e1a01060019108f9ae5e1e773168c098f021e5eb93d4831323334
                Message-Authenticator = 0x00000000000000000000000000000000
                State = 0x6162be1b6164a4ac160d1d957d730383
Tue Feb 23 15:45:42 2016 : Info: [peap] Got tunneled Access-Challenge
  PEAP tunnel data out 0000: 1a 01 06 00 19 10 8f 9a e5 e1 e7 73 16 8c 09 8f
  PEAP tunnel data out 0010: 02 1e 5e b9 3d 48 31 32 33 34
Tue Feb 23 15:45:42 2016 : Info: ++[eap] returns handled
Sending Access-Challenge of id 147 to 192.168.6.211 port 1812
                EAP-Message = 0x0106003b1900170301003067bf2338238b7bca8ef7ef4051623cf7eb1d140c350fc2cf1506a4f97d1e64494141be8566aaa6351f18cdcd51c2bad0
                Message-Authenticator = 0x00000000000000000000000000000000
                State = 0x0d497f86084f66663cf1bfd5de864a48
Tue Feb 23 15:45:42 2016 : Info: Finished request 5.
Tue Feb 23 15:45:42 2016 : Debug: Going to the next request
Tue Feb 23 15:45:42 2016 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.6.211 port 1812, id=148, length=216
                User-Name = "1234"
                NAS-IP-Address = 211.6.168.192
                NAS-Identifier = "SWITCH01-TEST"
                NAS-Port-Type = Virtual
                Service-Type = NAS-Prompt-User
                State = 0x0d497f86084f66663cf1bfd5de864a48
                EAP-Message = 0x0206005b19001703010050c54c0374d48331d44c233ddf239ed06afcdf5825bb291bb909009b9d0381bbb4c1caa824a57ed00f1764b4ce50d13cb6299d20f22d24ec58d9d53fad9462b355ae34b84835129fcfb2093a461d567048
                Message-Authenticator = 0xd7fb5217628dd8369628f52948d02c67
                MS-RAS-Vendor = 184549376
                Calling-Station-Id = "192.168.14.114"
Tue Feb 23 15:45:42 2016 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default
Tue Feb 23 15:45:42 2016 : Info: +- entering group authorize {...}
Tue Feb 23 15:45:42 2016 : Info: ++[preprocess] returns ok
Tue Feb 23 15:45:42 2016 : Info: ++[chap] returns noop
Tue Feb 23 15:45:42 2016 : Info: ++[mschap] returns noop
Tue Feb 23 15:45:42 2016 : Info: ++[digest] returns noop
Tue Feb 23 15:45:42 2016 : Info: [suffix] No '@' in User-Name = "1234", looking up realm NULL
Tue Feb 23 15:45:42 2016 : Info: [suffix] No such realm "NULL"
Tue Feb 23 15:45:42 2016 : Info: ++[suffix] returns noop
Tue Feb 23 15:45:42 2016 : Info: [eap] EAP packet type response id 6 length 91
Tue Feb 23 15:45:42 2016 : Info: [eap] Continuing tunnel setup.
Tue Feb 23 15:45:42 2016 : Info: ++[eap] returns ok
Tue Feb 23 15:45:42 2016 : Info: Found Auth-Type = EAP
Tue Feb 23 15:45:42 2016 : Info: # Executing group from file /etc/freeradius/sites-enabled/default
Tue Feb 23 15:45:42 2016 : Info: +- entering group authenticate {...}
Tue Feb 23 15:45:42 2016 : Info: [eap] Request found, released from the list
Tue Feb 23 15:45:42 2016 : Info: [eap] EAP/peap
Tue Feb 23 15:45:42 2016 : Info: [eap] processing type peap
Tue Feb 23 15:45:42 2016 : Info: [peap] processing EAP-TLS
Tue Feb 23 15:45:42 2016 : Info: [peap] eaptls_verify returned 7
Tue Feb 23 15:45:42 2016 : Info: [peap] Done initial handshake
Tue Feb 23 15:45:42 2016 : Info: [peap] eaptls_process returned 7
Tue Feb 23 15:45:42 2016 : Info: [peap] EAPTLS_OK
Tue Feb 23 15:45:42 2016 : Info: [peap] Session established.  Decoding tunneled attributes.
Tue Feb 23 15:45:42 2016 : Info: [peap] Peap state phase2
Tue Feb 23 15:45:42 2016 : Info: [peap] EAP type mschapv2
Tue Feb 23 15:45:42 2016 : Info: [peap] Got tunneled request
                EAP-Message = 0x0206003f1a0206003a31da54aae7ed025f63818a1f7b17cd934800000000000000006941aa38ea42622be320ddeca697b590fef937d30cd993760031323334
server  {
Tue Feb 23 15:45:42 2016 : Info: [peap] Setting User-Name to 1234
Sending tunneled request
                EAP-Message = 0x0206003f1a0206003a31da54aae7ed025f63818a1f7b17cd934800000000000000006941aa38ea42622be320ddeca697b590fef937d30cd993760031323334
                FreeRADIUS-Proxied-To = 127.0.0.1
                User-Name = "1234"
                State = 0x6162be1b6164a4ac160d1d957d730383
server inner-tunnel {
Tue Feb 23 15:45:42 2016 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/inner-tunnel
Tue Feb 23 15:45:42 2016 : Info: +- entering group authorize {...}
Tue Feb 23 15:45:42 2016 : Info: ++[chap] returns noop
Tue Feb 23 15:45:42 2016 : Info: ++[mschap] returns noop
Tue Feb 23 15:45:42 2016 : Info: [suffix] No '@' in User-Name = "1234", looking up realm NULL
Tue Feb 23 15:45:42 2016 : Info: [suffix] No such realm "NULL"
Tue Feb 23 15:45:42 2016 : Info: ++[suffix] returns noop
Tue Feb 23 15:45:42 2016 : Info: ++[control] returns noop
Tue Feb 23 15:45:42 2016 : Info: [eap] EAP packet type response id 6 length 63
Tue Feb 23 15:45:42 2016 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation
Tue Feb 23 15:45:42 2016 : Info: ++[eap] returns updated
Tue Feb 23 15:45:42 2016 : Info: ++[files] returns noop
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: %{User-Name} -> 1234
Tue Feb 23 15:45:42 2016 : Info: [sql] sql_set_user escaped user --> '1234'
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 0
Tue Feb 23 15:45:42 2016 : Info: [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 = '1234'           ORDER BY id
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM radcheck           WHERE username = '1234'           ORDER BY id
Tue Feb 23 15:45:42 2016 : Info: [sql] User found in radcheck table
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '%{SQL-User-Name}'           ORDER BY id -> SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '1234'           ORDER BY id
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '1234'           ORDER BY id
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: SELECT groupname           FROM radusergroup           WHERE username = '%{SQL-User-Name}'           ORDER BY priority -> SELECT groupname           FROM radusergroup           WHERE username = '1234'           ORDER BY priority
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql_mysql: query:  SELECT groupname           FROM radusergroup           WHERE username = '1234'           ORDER BY priority
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = '%{Sql-Group}'           ORDER BY id -> SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = 'HP-Procurve-Admin'           ORDER BY id
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql_mysql: query:  SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = 'HP-Procurve-Admin'           ORDER BY id
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql (sql): Released sql socket id: 0
Tue Feb 23 15:45:42 2016 : Info: ++[sql] returns ok
Tue Feb 23 15:45:42 2016 : Info: ++[expiration] returns noop
Tue Feb 23 15:45:42 2016 : Info: ++[logintime] returns noop
Tue Feb 23 15:45:42 2016 : Info: [pap] WARNING: Auth-Type already set.  Not setting to PAP
Tue Feb 23 15:45:42 2016 : Info: ++[pap] returns noop
Tue Feb 23 15:45:42 2016 : Info: Found Auth-Type = EAP
Tue Feb 23 15:45:42 2016 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Feb 23 15:45:42 2016 : Info: !!!    Replacing User-Password in config items with Cleartext-Password.     !!!
Tue Feb 23 15:45:42 2016 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Feb 23 15:45:42 2016 : Info: !!! Please update your configuration so that the "known good"               !!!
Tue Feb 23 15:45:42 2016 : Info: !!! clear text password is in Cleartext-Password, and not in User-Password. !!!
Tue Feb 23 15:45:42 2016 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Feb 23 15:45:42 2016 : Info: # Executing group from file /etc/freeradius/sites-enabled/inner-tunnel
Tue Feb 23 15:45:42 2016 : Info: +- entering group authenticate {...}
Tue Feb 23 15:45:42 2016 : Info: [eap] Request found, released from the list
Tue Feb 23 15:45:42 2016 : Info: [eap] EAP/mschapv2
Tue Feb 23 15:45:42 2016 : Info: [eap] processing type mschapv2
Tue Feb 23 15:45:42 2016 : Info: [mschapv2] # Executing group from file /etc/freeradius/sites-enabled/inner-tunnel
Tue Feb 23 15:45:42 2016 : Info: [mschapv2] +- entering group MS-CHAP {...}
Tue Feb 23 15:45:42 2016 : Info: [mschap] Creating challenge hash with username: 1234
Tue Feb 23 15:45:42 2016 : Info: [mschap] Told to do MS-CHAPv2 for 1234 with NT-Password
Tue Feb 23 15:45:42 2016 : Info: [mschap] adding MS-CHAPv2 MPPE keys
Tue Feb 23 15:45:42 2016 : Info: ++[mschap] returns ok
Tue Feb 23 15:45:42 2016 : Debug: MSCHAP Success
Tue Feb 23 15:45:42 2016 : Info: ++[eap] returns handled
} # server inner-tunnel
Tue Feb 23 15:45:42 2016 : Info: [peap] Got tunneled reply code 11
                EAP-Message = 0x010700331a0306002e533d31453141333445313845333144453634323243303744374444463833423436314635434132424136
                Message-Authenticator = 0x00000000000000000000000000000000
                State = 0x6162be1b6065a4ac160d1d957d730383
Tue Feb 23 15:45:42 2016 : Info: [peap] Got tunneled reply RADIUS code 11
                EAP-Message = 0x010700331a0306002e533d31453141333445313845333144453634323243303744374444463833423436314635434132424136
                Message-Authenticator = 0x00000000000000000000000000000000
                State = 0x6162be1b6065a4ac160d1d957d730383
Tue Feb 23 15:45:42 2016 : Info: [peap] Got tunneled Access-Challenge
  PEAP tunnel data out 0000: 1a 03 06 00 2e 53 3d 31 45 31 41 33 34 45 31 38
  PEAP tunnel data out 0010: 45 33 31 44 45 36 34 32 32 43 30 37 44 37 44 44
  PEAP tunnel data out 0020: 46 38 33 42 34 36 31 46 35 43 41 32 42 41 36
Tue Feb 23 15:45:42 2016 : Info: ++[eap] returns handled
Sending Access-Challenge of id 148 to 192.168.6.211 port 1812
                EAP-Message = 0x0107005b19001703010050c4d6781c42a769e49995eddde0f39054a452a415ba7033be63f401fa2c876c2fed4d926e97a11a7c5ca625adfd746efcb3e0736f62c967ba51ee0718385ee5daaa58ac9529d80821fdc70c1efa6154c0
                Message-Authenticator = 0x00000000000000000000000000000000
                State = 0x0d497f860b4e66663cf1bfd5de864a48
Tue Feb 23 15:45:42 2016 : Info: Finished request 6.
Tue Feb 23 15:45:42 2016 : Debug: Going to the next request
Tue Feb 23 15:45:42 2016 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.6.211 port 1812, id=149, length=168
                User-Name = "1234"
                NAS-IP-Address = 211.6.168.192
                NAS-Identifier = "SWITCH01-TEST"
                NAS-Port-Type = Virtual
                Service-Type = NAS-Prompt-User
                State = 0x0d497f860b4e66663cf1bfd5de864a48
                EAP-Message = 0x0207002b190017030100203bd61645e3583319a411219921d8df3471af6a1012bf51c9f59dbac842803fe4
                Message-Authenticator = 0x1428e10214392763b0e798d4ce4b9738
                MS-RAS-Vendor = 184549376
                Calling-Station-Id = "192.168.14.114"
Tue Feb 23 15:45:42 2016 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default
Tue Feb 23 15:45:42 2016 : Info: +- entering group authorize {...}
Tue Feb 23 15:45:42 2016 : Info: ++[preprocess] returns ok
Tue Feb 23 15:45:42 2016 : Info: ++[chap] returns noop
Tue Feb 23 15:45:42 2016 : Info: ++[mschap] returns noop
Tue Feb 23 15:45:42 2016 : Info: ++[digest] returns noop
Tue Feb 23 15:45:42 2016 : Info: [suffix] No '@' in User-Name = "1234", looking up realm NULL
Tue Feb 23 15:45:42 2016 : Info: [suffix] No such realm "NULL"
Tue Feb 23 15:45:42 2016 : Info: ++[suffix] returns noop
Tue Feb 23 15:45:42 2016 : Info: [eap] EAP packet type response id 7 length 43
Tue Feb 23 15:45:42 2016 : Info: [eap] Continuing tunnel setup.
Tue Feb 23 15:45:42 2016 : Info: ++[eap] returns ok
Tue Feb 23 15:45:42 2016 : Info: Found Auth-Type = EAP
Tue Feb 23 15:45:42 2016 : Info: # Executing group from file /etc/freeradius/sites-enabled/default
Tue Feb 23 15:45:42 2016 : Info: +- entering group authenticate {...}
Tue Feb 23 15:45:42 2016 : Info: [eap] Request found, released from the list
Tue Feb 23 15:45:42 2016 : Info: [eap] EAP/peap
Tue Feb 23 15:45:42 2016 : Info: [eap] processing type peap
Tue Feb 23 15:45:42 2016 : Info: [peap] processing EAP-TLS
Tue Feb 23 15:45:42 2016 : Info: [peap] eaptls_verify returned 7
Tue Feb 23 15:45:42 2016 : Info: [peap] Done initial handshake
Tue Feb 23 15:45:42 2016 : Info: [peap] eaptls_process returned 7
Tue Feb 23 15:45:42 2016 : Info: [peap] EAPTLS_OK
Tue Feb 23 15:45:42 2016 : Info: [peap] Session established.  Decoding tunneled attributes.
Tue Feb 23 15:45:42 2016 : Info: [peap] Peap state phase2
Tue Feb 23 15:45:42 2016 : Info: [peap] EAP type mschapv2
Tue Feb 23 15:45:42 2016 : Info: [peap] Got tunneled request
                EAP-Message = 0x020700061a03
server  {
Tue Feb 23 15:45:42 2016 : Info: [peap] Setting User-Name to 1234
Sending tunneled request
                EAP-Message = 0x020700061a03
                FreeRADIUS-Proxied-To = 127.0.0.1
                User-Name = "1234"
                State = 0x6162be1b6065a4ac160d1d957d730383
server inner-tunnel {
Tue Feb 23 15:45:42 2016 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/inner-tunnel
Tue Feb 23 15:45:42 2016 : Info: +- entering group authorize {...}
Tue Feb 23 15:45:42 2016 : Info: ++[chap] returns noop
Tue Feb 23 15:45:42 2016 : Info: ++[mschap] returns noop
Tue Feb 23 15:45:42 2016 : Info: [suffix] No '@' in User-Name = "1234", looking up realm NULL
Tue Feb 23 15:45:42 2016 : Info: [suffix] No such realm "NULL"
Tue Feb 23 15:45:42 2016 : Info: ++[suffix] returns noop
Tue Feb 23 15:45:42 2016 : Info: ++[control] returns noop
Tue Feb 23 15:45:42 2016 : Info: [eap] EAP packet type response id 7 length 6
Tue Feb 23 15:45:42 2016 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation
Tue Feb 23 15:45:42 2016 : Info: ++[eap] returns updated
Tue Feb 23 15:45:42 2016 : Info: ++[files] returns noop
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: %{User-Name} -> 1234
Tue Feb 23 15:45:42 2016 : Info: [sql] sql_set_user escaped user --> '1234'
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 4
Tue Feb 23 15:45:42 2016 : Info: [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 = '1234'           ORDER BY id
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM radcheck           WHERE username = '1234'           ORDER BY id
Tue Feb 23 15:45:42 2016 : Info: [sql] User found in radcheck table
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '%{SQL-User-Name}'           ORDER BY id -> SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '1234'           ORDER BY id
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql_mysql: query:  SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '1234'           ORDER BY id
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: SELECT groupname           FROM radusergroup           WHERE username = '%{SQL-User-Name}'           ORDER BY priority -> SELECT groupname           FROM radusergroup           WHERE username = '1234'           ORDER BY priority
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql_mysql: query:  SELECT groupname           FROM radusergroup           WHERE username = '1234'           ORDER BY priority
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = '%{Sql-Group}'           ORDER BY id -> SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = 'HP-Procurve-Admin'           ORDER BY id
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql_mysql: query:  SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = 'HP-Procurve-Admin'           ORDER BY id
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql (sql): Released sql socket id: 4
Tue Feb 23 15:45:42 2016 : Info: ++[sql] returns ok
Tue Feb 23 15:45:42 2016 : Info: ++[expiration] returns noop
Tue Feb 23 15:45:42 2016 : Info: ++[logintime] returns noop
Tue Feb 23 15:45:42 2016 : Info: [pap] WARNING: Auth-Type already set.  Not setting to PAP
Tue Feb 23 15:45:42 2016 : Info: ++[pap] returns noop
Tue Feb 23 15:45:42 2016 : Info: Found Auth-Type = EAP
Tue Feb 23 15:45:42 2016 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Feb 23 15:45:42 2016 : Info: !!!    Replacing User-Password in config items with Cleartext-Password.     !!!
Tue Feb 23 15:45:42 2016 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Feb 23 15:45:42 2016 : Info: !!! Please update your configuration so that the "known good"               !!!
Tue Feb 23 15:45:42 2016 : Info: !!! clear text password is in Cleartext-Password, and not in User-Password. !!!
Tue Feb 23 15:45:42 2016 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Feb 23 15:45:42 2016 : Info: # Executing group from file /etc/freeradius/sites-enabled/inner-tunnel
Tue Feb 23 15:45:42 2016 : Info: +- entering group authenticate {...}
Tue Feb 23 15:45:42 2016 : Info: [eap] Request found, released from the list
Tue Feb 23 15:45:42 2016 : Info: [eap] EAP/mschapv2
Tue Feb 23 15:45:42 2016 : Info: [eap] processing type mschapv2
Tue Feb 23 15:45:42 2016 : Info: [eap] Freeing handler
Tue Feb 23 15:45:42 2016 : Info: ++[eap] returns ok
Tue Feb 23 15:45:42 2016 : Info: # Executing section post-auth from file /etc/freeradius/sites-enabled/inner-tunnel
Tue Feb 23 15:45:42 2016 : Info: +- entering group post-auth {...}
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: %{User-Name} -> 1234
Tue Feb 23 15:45:42 2016 : Info: [sql] sql_set_user escaped user --> '1234'
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: %{User-Password} ->
Tue Feb 23 15:45:42 2016 : Info: [sql]     ... expanding second conditional
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: %{Chap-Password} ->
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: INSERT INTO radpostauth                           (username, pass, reply, authdate)                           VALUES (                           '%{User-Name}',                           '%{%{User-Password}:-%{Chap-Password}}',                           '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth                           (username, pass, reply, authdate)                           VALUES (                           '1234',                           '',                           'Access-Accept', '2016-02-23 15:45:42')
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: /var/log/freeradius/sqltrace.sql -> /var/log/freeradius/sqltrace.sql
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth                           (username, pass, reply, authdate)                           VALUES (                           '1234',                           '',                           'Access-Accept', '2016-02-23 15:45:42')
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 3
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql_mysql: query:  INSERT INTO radpostauth                           (username, pass, reply, authdate)                           VALUES (                           '1234',                           '',                           'Access-Accept', '2016-02-23 15:45:42')
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql (sql): Released sql socket id: 3
Tue Feb 23 15:45:42 2016 : Info: ++[sql] returns ok
Tue Feb 23 15:45:42 2016 : Info:               expand: %{request:User-Name} -> 1234
Tue Feb 23 15:45:42 2016 : Info: ++[outer.reply] returns ok
} # server inner-tunnel
Tue Feb 23 15:45:42 2016 : Info: [peap] Got tunneled reply code 2
                MS-MPPE-Encryption-Policy = 0x00000002
                MS-MPPE-Encryption-Types = 0x00000004
                MS-MPPE-Send-Key = 0x912567151985026409e260663b70aa06
                MS-MPPE-Recv-Key = 0x02a930052a14bd9b484e190eaabd4b49
                EAP-Message = 0x03070004
                Message-Authenticator = 0x00000000000000000000000000000000
                User-Name = "1234"
Tue Feb 23 15:45:42 2016 : Info: [peap] Got tunneled reply RADIUS code 2
                MS-MPPE-Encryption-Policy = 0x00000002
                MS-MPPE-Encryption-Types = 0x00000004
                MS-MPPE-Send-Key = 0x912567151985026409e260663b70aa06
                MS-MPPE-Recv-Key = 0x02a930052a14bd9b484e190eaabd4b49
                EAP-Message = 0x03070004
                Message-Authenticator = 0x00000000000000000000000000000000
                User-Name = "1234"
Tue Feb 23 15:45:42 2016 : Info: [peap] Tunneled authentication was successful.
Tue Feb 23 15:45:42 2016 : Info: [peap] SUCCESS
Tue Feb 23 15:45:42 2016 : Info: [peap] Saving tunneled attributes for later
Tue Feb 23 15:45:42 2016 : Info: ++[eap] returns handled
Sending Access-Challenge of id 149 to 192.168.6.211 port 1812
                User-Name = "1234"
                Service-Type = Administrative-User
                EAP-Message = 0x0108002b190017030100202db20bbce3b72afa194b4f3d3bc314eaa7406a57c511ba71b42d2ffce72d01fc
                Message-Authenticator = 0x00000000000000000000000000000000
                State = 0x0d497f860a4166663cf1bfd5de864a48
Tue Feb 23 15:45:42 2016 : Info: Finished request 7.
Tue Feb 23 15:45:42 2016 : Debug: Going to the next request
Tue Feb 23 15:45:42 2016 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.6.211 port 1812, id=150, length=168
                User-Name = "1234"
                NAS-IP-Address = 211.6.168.192
                NAS-Identifier = "SWITCH01-TEST"
                NAS-Port-Type = Virtual
                Service-Type = NAS-Prompt-User
                State = 0x0d497f860a4166663cf1bfd5de864a48
                EAP-Message = 0x0208002b19001703010020358541ebeef1d422e9a8abf682c3ff01eccba593fee137a12c3d3fe651a8c471
                Message-Authenticator = 0xd046b2197cd82e8855887dbd74e9edd3
                MS-RAS-Vendor = 184549376
                Calling-Station-Id = "192.168.14.114"
Tue Feb 23 15:45:42 2016 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default
Tue Feb 23 15:45:42 2016 : Info: +- entering group authorize {...}
Tue Feb 23 15:45:42 2016 : Info: ++[preprocess] returns ok
Tue Feb 23 15:45:42 2016 : Info: ++[chap] returns noop
Tue Feb 23 15:45:42 2016 : Info: ++[mschap] returns noop
Tue Feb 23 15:45:42 2016 : Info: ++[digest] returns noop
Tue Feb 23 15:45:42 2016 : Info: [suffix] No '@' in User-Name = "1234", looking up realm NULL
Tue Feb 23 15:45:42 2016 : Info: [suffix] No such realm "NULL"
Tue Feb 23 15:45:42 2016 : Info: ++[suffix] returns noop
Tue Feb 23 15:45:42 2016 : Info: [eap] EAP packet type response id 8 length 43
Tue Feb 23 15:45:42 2016 : Info: [eap] Continuing tunnel setup.
Tue Feb 23 15:45:42 2016 : Info: ++[eap] returns ok
Tue Feb 23 15:45:42 2016 : Info: Found Auth-Type = EAP
Tue Feb 23 15:45:42 2016 : Info: # Executing group from file /etc/freeradius/sites-enabled/default
Tue Feb 23 15:45:42 2016 : Info: +- entering group authenticate {...}
Tue Feb 23 15:45:42 2016 : Info: [eap] Request found, released from the list
Tue Feb 23 15:45:42 2016 : Info: [eap] EAP/peap
Tue Feb 23 15:45:42 2016 : Info: [eap] processing type peap
Tue Feb 23 15:45:42 2016 : Info: [peap] processing EAP-TLS
Tue Feb 23 15:45:42 2016 : Info: [peap] eaptls_verify returned 7
Tue Feb 23 15:45:42 2016 : Info: [peap] Done initial handshake
Tue Feb 23 15:45:42 2016 : Info: [peap] eaptls_process returned 7
Tue Feb 23 15:45:42 2016 : Info: [peap] EAPTLS_OK
Tue Feb 23 15:45:42 2016 : Info: [peap] Session established.  Decoding tunneled attributes.
Tue Feb 23 15:45:42 2016 : Info: [peap] Peap state send tlv success
Tue Feb 23 15:45:42 2016 : Info: [peap] Received EAP-TLV response.
Tue Feb 23 15:45:42 2016 : Info: [peap] Success
Tue Feb 23 15:45:42 2016 : Info: [peap] Using saved attributes from the original Access-Accept
                User-Name = "1234"
Tue Feb 23 15:45:42 2016 : Info: [eap] Freeing handler
Tue Feb 23 15:45:42 2016 : Info: ++[eap] returns ok
Tue Feb 23 15:45:42 2016 : Info: # Executing section post-auth from file /etc/freeradius/sites-enabled/default
Tue Feb 23 15:45:42 2016 : Info: +- entering group post-auth {...}
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: %{User-Name} -> 1234
Tue Feb 23 15:45:42 2016 : Info: [sql] sql_set_user escaped user --> '1234'
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: %{User-Password} ->
Tue Feb 23 15:45:42 2016 : Info: [sql]     ... expanding second conditional
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: %{Chap-Password} ->
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: INSERT INTO radpostauth                           (username, pass, reply, authdate)                           VALUES (                           '%{User-Name}',                           '%{%{User-Password}:-%{Chap-Password}}',                           '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth                           (username, pass, reply, authdate)                           VALUES (                           '1234',                           '',                           'Access-Accept', '2016-02-23 15:45:42')
Tue Feb 23 15:45:42 2016 : Info: [sql]     expand: /var/log/freeradius/sqltrace.sql -> /var/log/freeradius/sqltrace.sql
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth                           (username, pass, reply, authdate)                           VALUES (                           '1234',                           '',                           'Access-Accept', '2016-02-23 15:45:42')
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 2
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql_mysql: query:  INSERT INTO radpostauth                           (username, pass, reply, authdate)                           VALUES (                           '1234',                           '',                           'Access-Accept', '2016-02-23 15:45:42')
Tue Feb 23 15:45:42 2016 : Debug: rlm_sql (sql): Released sql socket id: 2
Tue Feb 23 15:45:42 2016 : Info: ++[sql] returns ok
Tue Feb 23 15:45:42 2016 : Info: ++[exec] returns noop
Sending Access-Accept of id 150 to 192.168.6.211 port 1812
                User-Name = "1234"
                MS-MPPE-Recv-Key = 0xb59a7655a33a5a5b6979a195b6277d8e7ac7a128b3eb78f2a941de634490be80
                MS-MPPE-Send-Key = 0x47a29459f2ffd034955b9c980be7b66750706df94a0f24f279ca9999b3753da6
                EAP-Message = 0x03080004
                Message-Authenticator = 0x00000000000000000000000000000000
Tue Feb 23 15:45:42 2016 : Info: Finished request 8.
Tue Feb 23 15:45:42 2016 : Debug: Going to the next request
Tue Feb 23 15:45:42 2016 : Debug: Waking up in 4.9 seconds.
Tue Feb 23 15:45:46 2016 : Info: Cleaning up request 0 ID 142 with timestamp +8
Tue Feb 23 15:45:46 2016 : Info: Cleaning up request 1 ID 143 with timestamp +8
Tue Feb 23 15:45:46 2016 : Info: Cleaning up request 2 ID 144 with timestamp +8
Tue Feb 23 15:45:47 2016 : Info: Cleaning up request 3 ID 145 with timestamp +9
Tue Feb 23 15:45:47 2016 : Info: Cleaning up request 4 ID 146 with timestamp +9
Tue Feb 23 15:45:47 2016 : Info: Cleaning up request 5 ID 147 with timestamp +9
Tue Feb 23 15:45:47 2016 : Info: Cleaning up request 6 ID 148 with timestamp +9
Tue Feb 23 15:45:47 2016 : Info: Cleaning up request 7 ID 149 with timestamp +9
Tue Feb 23 15:45:47 2016 : Info: Cleaning up request 8 ID 150 with timestamp +9
Tue Feb 23 15:45:47 2016 : Info: Ready to process requests.

Best regards
Jonas

freeradius update attributes in access-accept reply

Kiefer, Jonas