ntlm_auth woes
Tim ODriscoll
tim.odriscoll at lambrookschool.co.uk
Sun May 28 22:16:19 CEST 2017
Hello All,
I'm running freeradius 2.1.12 on Ubuntu, with sernet-samba-4.6.4.
My freeradius server is a domain member, and there's two other sernet-samba-4.6.4 AD DC's on the network.
I've recently updated sernet-samba from 4.2.14 to 4.6.4 and now my WiFi clients can't authenticate via mschap.
I've re-set the permissions on /var/lib/samba/winbindd_privileged and /var/run/samba/winbindd_privileged. wbinfo appears to work properly.
ntlm_auth works fine from the command line, using username and password, but fails when I use challenge and nt-response with a logon failure, both on the command line and through freeradius.
I'm stuck. I've been through all the documentation I can find, set freeradius up from scratch again and I'm still hitting this error.
Can anyone offer some pointers as to where I can dig into next to solve this?
Output from 'freeradius -Xxx' below, after calling radtest pointed to the inner-tunnel.
Many thanks,
Tim
Sun May 28 20:38:06 2017 : Info: FreeRADIUS Version 2.1.12, for host x86_64-pc-linux-gnu, built on Feb 24 2014 at 14:57:57
Sun May 28 20:38:06 2017 : Info: Copyright (C) 1999-2009 The FreeRADIUS server project and contributors.
Sun May 28 20:38:06 2017 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
Sun May 28 20:38:06 2017 : Info: PARTICULAR PURPOSE.
Sun May 28 20:38:06 2017 : Info: You may redistribute copies of FreeRADIUS under the terms of the
Sun May 28 20:38:06 2017 : Info: GNU General Public License v2.
Sun May 28 20:38:06 2017 : Info: Starting - reading configuration files ...
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/radiusd.conf
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/proxy.conf
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/clients.conf
Sun May 28 20:38:06 2017 : Debug: including files in directory /etc/freeradius/modules/
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/realm
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/passwd
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/acct_unique
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/chap
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/otp
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/exec
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/linelog
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/detail
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/perl
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/mac2vlan
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/detail.log
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/etc_group
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/rediswho
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/attr_filter
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/mschap
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/files
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/redis
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/opendirectory
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/cui
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/smbpasswd
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/counter
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/expr
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/ippool
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/digest
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/radutmp
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/ntlm_auth
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/attr_rewrite
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/mac2ip
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/wimax
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/krb5
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/ldap
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/detail.example.com
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/sql_log
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/expiration
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/sqlcounter_expire_on_login
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/inner-eap
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/sradutmp
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/always
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/smsotp
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/preprocess
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/pam
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/replicate
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/dynamic_clients
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/checkval
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/echo
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/policy
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/soh
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/logintime
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/pap
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/modules/unix
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/eap.conf
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/policy.conf
Sun May 28 20:38:06 2017 : Debug: including files in directory /etc/freeradius/sites-enabled/
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/sites-enabled/default
Sun May 28 20:38:06 2017 : Debug: including configuration file /etc/freeradius/sites-enabled/inner-tunnel
Sun May 28 20:38:06 2017 : Debug: main {
Sun May 28 20:38:06 2017 : Debug: user = "freerad"
Sun May 28 20:38:06 2017 : Debug: group = "freerad"
Sun May 28 20:38:06 2017 : Debug: allow_core_dumps = no
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: including dictionary file /etc/freeradius/dictionary
Sun May 28 20:38:06 2017 : Debug: main {
Sun May 28 20:38:06 2017 : Debug: name = "freeradius"
Sun May 28 20:38:06 2017 : Debug: prefix = "/usr"
Sun May 28 20:38:06 2017 : Debug: localstatedir = "/var"
Sun May 28 20:38:06 2017 : Debug: sbindir = "/usr/sbin"
Sun May 28 20:38:06 2017 : Debug: logdir = "/var/log/freeradius"
Sun May 28 20:38:06 2017 : Debug: run_dir = "/var/run/freeradius"
Sun May 28 20:38:06 2017 : Debug: libdir = "/usr/lib/freeradius"
Sun May 28 20:38:06 2017 : Debug: radacctdir = "/var/log/freeradius/radacct"
Sun May 28 20:38:06 2017 : Debug: hostname_lookups = no
Sun May 28 20:38:06 2017 : Debug: max_request_time = 30
Sun May 28 20:38:06 2017 : Debug: cleanup_delay = 5
Sun May 28 20:38:06 2017 : Debug: max_requests = 1024
Sun May 28 20:38:06 2017 : Debug: pidfile = "/var/run/freeradius/freeradius.pid"
Sun May 28 20:38:06 2017 : Debug: checkrad = "/usr/sbin/checkrad"
Sun May 28 20:38:06 2017 : Debug: debug_level = 0
Sun May 28 20:38:06 2017 : Debug: proxy_requests = yes
Sun May 28 20:38:06 2017 : Debug: log {
Sun May 28 20:38:06 2017 : Debug: stripped_names = no
Sun May 28 20:38:06 2017 : Debug: auth = yes
Sun May 28 20:38:06 2017 : Debug: auth_badpass = yes
Sun May 28 20:38:06 2017 : Debug: auth_goodpass = yes
Sun May 28 20:38:06 2017 : Debug: msg_badpass = "%{Packet-Src-IP-Address}"
Sun May 28 20:38:06 2017 : Debug: msg_goodpass = "%{Packet-Src-IP-Address}"
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: security {
Sun May 28 20:38:06 2017 : Debug: max_attributes = 200
Sun May 28 20:38:06 2017 : Debug: reject_delay = 1
Sun May 28 20:38:06 2017 : Debug: status_server = yes
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: radiusd: #### Loading Realms and Home Servers ####
Sun May 28 20:38:06 2017 : Debug: proxy server {
Sun May 28 20:38:06 2017 : Debug: retry_delay = 5
Sun May 28 20:38:06 2017 : Debug: retry_count = 3
Sun May 28 20:38:06 2017 : Debug: default_fallback = no
Sun May 28 20:38:06 2017 : Debug: dead_time = 120
Sun May 28 20:38:06 2017 : Debug: wake_all_if_all_dead = no
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: home_server localhost {
Sun May 28 20:38:06 2017 : Debug: ipaddr = 127.0.0.1
Sun May 28 20:38:06 2017 : Debug: port = 1812
Sun May 28 20:38:06 2017 : Debug: type = "auth"
Sun May 28 20:38:06 2017 : Debug: secret = "testing123"
Sun May 28 20:38:06 2017 : Debug: response_window = 20
Sun May 28 20:38:06 2017 : Debug: max_outstanding = 65536
Sun May 28 20:38:06 2017 : Debug: require_message_authenticator = yes
Sun May 28 20:38:06 2017 : Debug: zombie_period = 40
Sun May 28 20:38:06 2017 : Debug: status_check = "status-server"
Sun May 28 20:38:06 2017 : Debug: ping_interval = 30
Sun May 28 20:38:06 2017 : Debug: check_interval = 30
Sun May 28 20:38:06 2017 : Debug: num_answers_to_alive = 3
Sun May 28 20:38:06 2017 : Debug: num_pings_to_alive = 3
Sun May 28 20:38:06 2017 : Debug: revive_interval = 120
Sun May 28 20:38:06 2017 : Debug: status_check_timeout = 4
Sun May 28 20:38:06 2017 : Debug: coa {
Sun May 28 20:38:06 2017 : Debug: irt = 2
Sun May 28 20:38:06 2017 : Debug: mrt = 16
Sun May 28 20:38:06 2017 : Debug: mrc = 5
Sun May 28 20:38:06 2017 : Debug: mrd = 30
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: home_server_pool my_auth_failover {
Sun May 28 20:38:06 2017 : Debug: type = fail-over
Sun May 28 20:38:06 2017 : Debug: home_server = localhost
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: realm example.com {
Sun May 28 20:38:06 2017 : Debug: auth_pool = my_auth_failover
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: realm LOCAL {
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: radiusd: #### Loading Clients ####
Sun May 28 20:38:06 2017 : Debug: client localhost {
Sun May 28 20:38:06 2017 : Debug: ipaddr = 127.0.0.1
Sun May 28 20:38:06 2017 : Debug: require_message_authenticator = no
Sun May 28 20:38:06 2017 : Debug: secret = "testing123"
Sun May 28 20:38:06 2017 : Debug: nastype = "other"
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: client 192.168.4.0/24 {
Sun May 28 20:38:06 2017 : Debug: require_message_authenticator = no
Sun May 28 20:38:06 2017 : Debug: secret = ##redacted##
Sun May 28 20:38:06 2017 : Debug: shortname = "wifi"
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: radiusd: #### Instantiating modules ####
Sun May 28 20:38:06 2017 : Debug: instantiate {
Sun May 28 20:38:06 2017 : Debug: (Loaded rlm_exec, checking if it's valid)
Sun May 28 20:38:06 2017 : Debug: Module: Linked to module rlm_exec
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "exec" from file /etc/freeradius/modules/exec
Sun May 28 20:38:06 2017 : Debug: exec {
Sun May 28 20:38:06 2017 : Debug: wait = no
Sun May 28 20:38:06 2017 : Debug: input_pairs = "request"
Sun May 28 20:38:06 2017 : Debug: shell_escape = yes
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: (Loaded rlm_expr, checking if it's valid)
Sun May 28 20:38:06 2017 : Debug: Module: Linked to module rlm_expr
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "expr" from file /etc/freeradius/modules/expr
Sun May 28 20:38:06 2017 : Debug: (Loaded rlm_expiration, checking if it's valid)
Sun May 28 20:38:06 2017 : Debug: Module: Linked to module rlm_expiration
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "expiration" from file /etc/freeradius/modules/expiration
Sun May 28 20:38:06 2017 : Debug: expiration {
Sun May 28 20:38:06 2017 : Debug: reply-message = "Password Has Expired "
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: (Loaded rlm_logintime, checking if it's valid)
Sun May 28 20:38:06 2017 : Debug: Module: Linked to module rlm_logintime
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "logintime" from file /etc/freeradius/modules/logintime
Sun May 28 20:38:06 2017 : Debug: logintime {
Sun May 28 20:38:06 2017 : Debug: reply-message = "You are calling outside your allowed timespan "
Sun May 28 20:38:06 2017 : Debug: minimum-timeout = 60
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: radiusd: #### Loading Virtual Servers ####
Sun May 28 20:38:06 2017 : Debug: server { # from file /etc/freeradius/radiusd.conf
Sun May 28 20:38:06 2017 : Debug: modules {
Sun May 28 20:38:06 2017 : Debug: Module: Creating Auth-Type = digest
Sun May 28 20:38:06 2017 : Debug: Module: Creating Post-Auth-Type = REJECT
Sun May 28 20:38:06 2017 : Debug: Module: Checking authenticate {...} for more modules to load
Sun May 28 20:38:06 2017 : Debug: (Loaded rlm_pap, checking if it's valid)
Sun May 28 20:38:06 2017 : Debug: Module: Linked to module rlm_pap
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "pap" from file /etc/freeradius/modules/pap
Sun May 28 20:38:06 2017 : Debug: pap {
Sun May 28 20:38:06 2017 : Debug: encryption_scheme = "auto"
Sun May 28 20:38:06 2017 : Debug: auto_header = no
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: (Loaded rlm_chap, checking if it's valid)
Sun May 28 20:38:06 2017 : Debug: Module: Linked to module rlm_chap
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "chap" from file /etc/freeradius/modules/chap
Sun May 28 20:38:06 2017 : Debug: (Loaded rlm_mschap, checking if it's valid)
Sun May 28 20:38:06 2017 : Debug: Module: Linked to module rlm_mschap
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "mschap" from file /etc/freeradius/modules/mschap
Sun May 28 20:38:06 2017 : Debug: mschap {
Sun May 28 20:38:06 2017 : Debug: use_mppe = yes
Sun May 28 20:38:06 2017 : Debug: require_encryption = no
Sun May 28 20:38:06 2017 : Debug: require_strong = no
Sun May 28 20:38:06 2017 : Debug: with_ntdomain_hack = yes
Sun May 28 20:38:06 2017 : Debug: ntlm_auth = "/usr/bin/ntlm_auth --request-nt-key --require-membership-of=LAMBROOK+dialupaccess --username=%{%{Stripped-User-Name}:-%{%{User-Name}:-None}} --challenge=%{%{mschap:Challenge}:-00} --nt-response=%{%{mschap:NT-Response}:-00}"
Sun May 28 20:38:06 2017 : Debug: allow_retry = yes
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: (Loaded rlm_digest, checking if it's valid)
Sun May 28 20:38:06 2017 : Debug: Module: Linked to module rlm_digest
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "digest" from file /etc/freeradius/modules/digest
Sun May 28 20:38:06 2017 : Debug: (Loaded rlm_unix, checking if it's valid)
Sun May 28 20:38:06 2017 : Debug: Module: Linked to module rlm_unix
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "unix" from file /etc/freeradius/modules/unix
Sun May 28 20:38:06 2017 : Debug: unix {
Sun May 28 20:38:06 2017 : Debug: radwtmp = "/var/log/freeradius/radwtmp"
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: (Loaded rlm_eap, checking if it's valid)
Sun May 28 20:38:06 2017 : Debug: Module: Linked to module rlm_eap
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "eap" from file /etc/freeradius/eap.conf
Sun May 28 20:38:06 2017 : Debug: eap {
Sun May 28 20:38:06 2017 : Debug: default_eap_type = "peap"
Sun May 28 20:38:06 2017 : Debug: timer_expire = 60
Sun May 28 20:38:06 2017 : Debug: ignore_unknown_eap_types = no
Sun May 28 20:38:06 2017 : Debug: cisco_accounting_username_bug = no
Sun May 28 20:38:06 2017 : Debug: max_sessions = 4096
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: Module: Linked to sub-module rlm_eap_md5
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating eap-md5
Sun May 28 20:38:06 2017 : Debug: Module: Linked to sub-module rlm_eap_leap
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating eap-leap
Sun May 28 20:38:06 2017 : Debug: Module: Linked to sub-module rlm_eap_gtc
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating eap-gtc
Sun May 28 20:38:06 2017 : Debug: gtc {
Sun May 28 20:38:06 2017 : Debug: challenge = "Password: "
Sun May 28 20:38:06 2017 : Debug: auth_type = "PAP"
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: Module: Linked to sub-module rlm_eap_tls
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating eap-tls
Sun May 28 20:38:06 2017 : Debug: tls {
Sun May 28 20:38:06 2017 : Debug: rsa_key_exchange = no
Sun May 28 20:38:06 2017 : Debug: dh_key_exchange = yes
Sun May 28 20:38:06 2017 : Debug: rsa_key_length = 512
Sun May 28 20:38:06 2017 : Debug: dh_key_length = 512
Sun May 28 20:38:06 2017 : Debug: verify_depth = 0
Sun May 28 20:38:06 2017 : Debug: CA_path = "/etc/freeradius/certs"
Sun May 28 20:38:06 2017 : Debug: pem_file_type = yes
Sun May 28 20:38:06 2017 : Debug: private_key_file = "/etc/freeradius/certs/server.key"
Sun May 28 20:38:06 2017 : Debug: certificate_file = "/etc/freeradius/certs/server.pem"
Sun May 28 20:38:06 2017 : Debug: CA_file = "/etc/freeradius/certs/ca.pem"
Sun May 28 20:38:06 2017 : Debug: private_key_password = "whatever"
Sun May 28 20:38:06 2017 : Debug: dh_file = "/etc/freeradius/certs/dh"
Sun May 28 20:38:06 2017 : Debug: random_file = "/dev/urandom"
Sun May 28 20:38:06 2017 : Debug: fragment_size = 1024
Sun May 28 20:38:06 2017 : Debug: include_length = yes
Sun May 28 20:38:06 2017 : Debug: check_crl = no
Sun May 28 20:38:06 2017 : Debug: cipher_list = "DEFAULT"
Sun May 28 20:38:06 2017 : Debug: make_cert_command = "/etc/freeradius/certs/bootstrap"
Sun May 28 20:38:06 2017 : Debug: ecdh_curve = "prime256v1"
Sun May 28 20:38:06 2017 : Debug: cache {
Sun May 28 20:38:06 2017 : Debug: enable = no
Sun May 28 20:38:06 2017 : Debug: lifetime = 24
Sun May 28 20:38:06 2017 : Debug: max_entries = 255
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: verify {
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: ocsp {
Sun May 28 20:38:06 2017 : Debug: enable = no
Sun May 28 20:38:06 2017 : Debug: override_cert_url = yes
Sun May 28 20:38:06 2017 : Debug: url = "http://127.0.0.1/ocsp/"
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: Module: Linked to sub-module rlm_eap_ttls
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating eap-ttls
Sun May 28 20:38:06 2017 : Debug: ttls {
Sun May 28 20:38:06 2017 : Debug: default_eap_type = "md5"
Sun May 28 20:38:06 2017 : Debug: copy_request_to_tunnel = no
Sun May 28 20:38:06 2017 : Debug: use_tunneled_reply = yes
Sun May 28 20:38:06 2017 : Debug: virtual_server = "inner-tunnel"
Sun May 28 20:38:06 2017 : Debug: include_length = yes
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: Module: Linked to sub-module rlm_eap_peap
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating eap-peap
Sun May 28 20:38:06 2017 : Debug: peap {
Sun May 28 20:38:06 2017 : Debug: default_eap_type = "mschapv2"
Sun May 28 20:38:06 2017 : Debug: copy_request_to_tunnel = no
Sun May 28 20:38:06 2017 : Debug: use_tunneled_reply = yes
Sun May 28 20:38:06 2017 : Debug: proxy_tunneled_request_as_eap = yes
Sun May 28 20:38:06 2017 : Debug: virtual_server = "inner-tunnel"
Sun May 28 20:38:06 2017 : Debug: soh = no
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: Module: Linked to sub-module rlm_eap_mschapv2
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating eap-mschapv2
Sun May 28 20:38:06 2017 : Debug: mschapv2 {
Sun May 28 20:38:06 2017 : Debug: with_ntdomain_hack = no
Sun May 28 20:38:06 2017 : Debug: send_error = no
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: Module: Checking authorize {...} for more modules to load
Sun May 28 20:38:06 2017 : Debug: Module: Loading virtual module rewrite.calling_station_id
Sun May 28 20:38:06 2017 : Debug: (Loaded rlm_always, checking if it's valid)
Sun May 28 20:38:06 2017 : Debug: Module: Linked to module rlm_always
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "updated" from file /etc/freeradius/modules/always
Sun May 28 20:38:06 2017 : Debug: always updated {
Sun May 28 20:38:06 2017 : Debug: rcode = "updated"
Sun May 28 20:38:06 2017 : Debug: simulcount = 0
Sun May 28 20:38:06 2017 : Debug: mpp = no
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "noop" from file /etc/freeradius/modules/always
Sun May 28 20:38:06 2017 : Debug: always noop {
Sun May 28 20:38:06 2017 : Debug: rcode = "noop"
Sun May 28 20:38:06 2017 : Debug: simulcount = 0
Sun May 28 20:38:06 2017 : Debug: mpp = no
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: (Loaded rlm_preprocess, checking if it's valid)
Sun May 28 20:38:06 2017 : Debug: Module: Linked to module rlm_preprocess
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "preprocess" from file /etc/freeradius/modules/preprocess
Sun May 28 20:38:06 2017 : Debug: preprocess {
Sun May 28 20:38:06 2017 : Debug: huntgroups = "/etc/freeradius/huntgroups"
Sun May 28 20:38:06 2017 : Debug: hints = "/etc/freeradius/hints"
Sun May 28 20:38:06 2017 : Debug: with_ascend_hack = no
Sun May 28 20:38:06 2017 : Debug: ascend_channels_per_line = 23
Sun May 28 20:38:06 2017 : Debug: with_ntdomain_hack = no
Sun May 28 20:38:06 2017 : Debug: with_specialix_jetstream_hack = no
Sun May 28 20:38:06 2017 : Debug: with_cisco_vsa_hack = no
Sun May 28 20:38:06 2017 : Debug: with_alvarion_vsa_hack = no
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: (Loaded rlm_detail, checking if it's valid)
Sun May 28 20:38:06 2017 : Debug: Module: Linked to module rlm_detail
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "auth_log" from file /etc/freeradius/modules/detail.log
Sun May 28 20:38:06 2017 : Debug: detail auth_log {
Sun May 28 20:38:06 2017 : Debug: detailfile = "/var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d"
Sun May 28 20:38:06 2017 : Debug: header = "%t"
Sun May 28 20:38:06 2017 : Debug: detailperm = 384
Sun May 28 20:38:06 2017 : Debug: dirperm = 493
Sun May 28 20:38:06 2017 : Debug: locking = no
Sun May 28 20:38:06 2017 : Debug: log_packet_header = no
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: (Loaded rlm_realm, checking if it's valid)
Sun May 28 20:38:06 2017 : Debug: Module: Linked to module rlm_realm
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "suffix" from file /etc/freeradius/modules/realm
Sun May 28 20:38:06 2017 : Debug: realm suffix {
Sun May 28 20:38:06 2017 : Debug: format = "suffix"
Sun May 28 20:38:06 2017 : Debug: delimiter = "@"
Sun May 28 20:38:06 2017 : Debug: ignore_default = no
Sun May 28 20:38:06 2017 : Debug: ignore_null = no
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: (Loaded rlm_perl, checking if it's valid)
Sun May 28 20:38:06 2017 : Debug: Module: Linked to module rlm_perl
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "authorized_macs" from file /etc/freeradius/modules/perl
Sun May 28 20:38:06 2017 : Debug: perl authorized_macs {
Sun May 28 20:38:06 2017 : Debug: module = "/etc/freeradius/get_mac.pl"
Sun May 28 20:38:06 2017 : Debug: func_authorize = "authorize"
Sun May 28 20:38:06 2017 : Debug: func_authenticate = "authenticate"
Sun May 28 20:38:06 2017 : Debug: func_accounting = "accounting"
Sun May 28 20:38:06 2017 : Debug: func_preacct = "preacct"
Sun May 28 20:38:06 2017 : Debug: func_checksimul = "checksimul"
Sun May 28 20:38:06 2017 : Debug: func_detach = "detach"
Sun May 28 20:38:06 2017 : Debug: func_xlat = "xlat"
Sun May 28 20:38:06 2017 : Debug: func_pre_proxy = "pre_proxy"
Sun May 28 20:38:06 2017 : Debug: func_post_proxy = "post_proxy"
Sun May 28 20:38:06 2017 : Debug: func_post_auth = "post_auth"
Sun May 28 20:38:06 2017 : Debug: func_recv_coa = "recv_coa"
Sun May 28 20:38:06 2017 : Debug: func_send_coa = "send_coa"
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: Module: Checking preacct {...} for more modules to load
Sun May 28 20:38:06 2017 : Debug: (Loaded rlm_acct_unique, checking if it's valid)
Sun May 28 20:38:06 2017 : Debug: Module: Linked to module rlm_acct_unique
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "acct_unique" from file /etc/freeradius/modules/acct_unique
Sun May 28 20:38:06 2017 : Debug: acct_unique {
Sun May 28 20:38:06 2017 : Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: (Loaded rlm_files, checking if it's valid)
Sun May 28 20:38:06 2017 : Debug: Module: Linked to module rlm_files
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "files" from file /etc/freeradius/modules/files
Sun May 28 20:38:06 2017 : Debug: files {
Sun May 28 20:38:06 2017 : Debug: usersfile = "/etc/freeradius/users"
Sun May 28 20:38:06 2017 : Debug: acctusersfile = "/etc/freeradius/acct_users"
Sun May 28 20:38:06 2017 : Debug: preproxy_usersfile = "/etc/freeradius/preproxy_users"
Sun May 28 20:38:06 2017 : Debug: compat = "no"
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: Module: Checking accounting {...} for more modules to load
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "detail" from file /etc/freeradius/modules/detail
Sun May 28 20:38:06 2017 : Debug: detail {
Sun May 28 20:38:06 2017 : Debug: detailfile = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d"
Sun May 28 20:38:06 2017 : Debug: header = "%t"
Sun May 28 20:38:06 2017 : Debug: detailperm = 384
Sun May 28 20:38:06 2017 : Debug: dirperm = 493
Sun May 28 20:38:06 2017 : Debug: locking = no
Sun May 28 20:38:06 2017 : Debug: log_packet_header = no
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: (Loaded rlm_radutmp, checking if it's valid)
Sun May 28 20:38:06 2017 : Debug: Module: Linked to module rlm_radutmp
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "radutmp" from file /etc/freeradius/modules/radutmp
Sun May 28 20:38:06 2017 : Debug: radutmp {
Sun May 28 20:38:06 2017 : Debug: filename = "/var/log/freeradius/radutmp"
Sun May 28 20:38:06 2017 : Debug: username = "%{User-Name}"
Sun May 28 20:38:06 2017 : Debug: case_sensitive = yes
Sun May 28 20:38:06 2017 : Debug: check_with_nas = yes
Sun May 28 20:38:06 2017 : Debug: perm = 384
Sun May 28 20:38:06 2017 : Debug: callerid = yes
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: (Loaded rlm_attr_filter, checking if it's valid)
Sun May 28 20:38:06 2017 : Debug: Module: Linked to module rlm_attr_filter
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "attr_filter.accounting_response" from file /etc/freeradius/modules/attr_filter
Sun May 28 20:38:06 2017 : Debug: attr_filter attr_filter.accounting_response {
Sun May 28 20:38:06 2017 : Debug: attrsfile = "/etc/freeradius/attrs.accounting_response"
Sun May 28 20:38:06 2017 : Debug: key = "%{User-Name}"
Sun May 28 20:38:06 2017 : Debug: relaxed = no
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: Module: Checking session {...} for more modules to load
Sun May 28 20:38:06 2017 : Debug: Module: Checking post-proxy {...} for more modules to load
Sun May 28 20:38:06 2017 : Debug: Module: Checking post-auth {...} for more modules to load
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "reply_log" from file /etc/freeradius/modules/detail.log
Sun May 28 20:38:06 2017 : Debug: detail reply_log {
Sun May 28 20:38:06 2017 : Debug: detailfile = "/var/log/freeradius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d"
Sun May 28 20:38:06 2017 : Debug: header = "%t"
Sun May 28 20:38:06 2017 : Debug: detailperm = 384
Sun May 28 20:38:06 2017 : Debug: dirperm = 493
Sun May 28 20:38:06 2017 : Debug: locking = no
Sun May 28 20:38:06 2017 : Debug: log_packet_header = no
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "attr_filter.access_reject" from file /etc/freeradius/modules/attr_filter
Sun May 28 20:38:06 2017 : Debug: attr_filter attr_filter.access_reject {
Sun May 28 20:38:06 2017 : Debug: attrsfile = "/etc/freeradius/attrs.access_reject"
Sun May 28 20:38:06 2017 : Debug: key = "%{User-Name}"
Sun May 28 20:38:06 2017 : Debug: relaxed = no
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: } # modules
Sun May 28 20:38:06 2017 : Debug: } # server
Sun May 28 20:38:06 2017 : Debug: server inner-tunnel { # from file /etc/freeradius/sites-enabled/inner-tunnel
Sun May 28 20:38:06 2017 : Debug: modules {
Sun May 28 20:38:06 2017 : Debug: Module: Checking authenticate {...} for more modules to load
Sun May 28 20:38:06 2017 : Debug: Module: Checking authorize {...} for more modules to load
Sun May 28 20:38:06 2017 : Debug: Module: Checking session {...} for more modules to load
Sun May 28 20:38:06 2017 : Debug: Module: Checking post-proxy {...} for more modules to load
Sun May 28 20:38:06 2017 : Debug: Module: Checking post-auth {...} for more modules to load
Sun May 28 20:38:06 2017 : Debug: Module: Instantiating module "perl" from file /etc/freeradius/modules/perl
Sun May 28 20:38:06 2017 : Debug: perl {
Sun May 28 20:38:06 2017 : Debug: module = "/etc/freeradius/get_vlan.pl"
Sun May 28 20:38:06 2017 : Debug: func_authorize = "authorize"
Sun May 28 20:38:06 2017 : Debug: func_authenticate = "authenticate"
Sun May 28 20:38:06 2017 : Debug: func_accounting = "accounting"
Sun May 28 20:38:06 2017 : Debug: func_preacct = "preacct"
Sun May 28 20:38:06 2017 : Debug: func_checksimul = "checksimul"
Sun May 28 20:38:06 2017 : Debug: func_detach = "detach"
Sun May 28 20:38:06 2017 : Debug: func_xlat = "xlat"
Sun May 28 20:38:06 2017 : Debug: func_pre_proxy = "pre_proxy"
Sun May 28 20:38:06 2017 : Debug: func_post_proxy = "post_proxy"
Sun May 28 20:38:06 2017 : Debug: func_post_auth = "post_auth"
Sun May 28 20:38:06 2017 : Debug: func_recv_coa = "recv_coa"
Sun May 28 20:38:06 2017 : Debug: func_send_coa = "send_coa"
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: } # modules
Sun May 28 20:38:06 2017 : Debug: } # server
Sun May 28 20:38:06 2017 : Debug: radiusd: #### Opening IP addresses and Ports ####
Sun May 28 20:38:06 2017 : Debug: listen {
Sun May 28 20:38:06 2017 : Debug: type = "auth"
Sun May 28 20:38:06 2017 : Debug: ipaddr = *
Sun May 28 20:38:06 2017 : Debug: port = 0
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: listen {
Sun May 28 20:38:06 2017 : Debug: type = "acct"
Sun May 28 20:38:06 2017 : Debug: ipaddr = *
Sun May 28 20:38:06 2017 : Debug: port = 0
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Debug: listen {
Sun May 28 20:38:06 2017 : Debug: type = "auth"
Sun May 28 20:38:06 2017 : Debug: ipaddr = 127.0.0.1
Sun May 28 20:38:06 2017 : Debug: port = 18120
Sun May 28 20:38:06 2017 : Debug: }
Sun May 28 20:38:06 2017 : Info: ... adding new socket proxy address * port 46065
Sun May 28 20:38:06 2017 : Debug: Listening on authentication address * port 1812
Sun May 28 20:38:06 2017 : Debug: Listening on accounting address * port 1813
Sun May 28 20:38:06 2017 : Debug: Listening on authentication address 127.0.0.1 port 18120 as server inner-tunnel
Sun May 28 20:38:06 2017 : Debug: Listening on proxy address * port 1814
Sun May 28 20:38:06 2017 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 127.0.0.1 port 35354, id=203, length=139
User-Name = "tim.odriscoll"
NAS-IP-Address = 127.0.0.1
NAS-Port = 0
Message-Authenticator = ##redacted##
MS-CHAP-Challenge = ##redacted##
MS-CHAP-Response = ##redacted##
Sun May 28 20:38:13 2017 : Info: server inner-tunnel {
Sun May 28 20:38:13 2017 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/inner-tunnel
Sun May 28 20:38:13 2017 : Info: +- entering group authorize {...}
Sun May 28 20:38:13 2017 : Info: ++[chap] returns noop
Sun May 28 20:38:13 2017 : Info: [mschap] Found MS-CHAP attributes. Setting 'Auth-Type = mschap'
Sun May 28 20:38:13 2017 : Info: ++[mschap] returns ok
Sun May 28 20:38:13 2017 : Info: [suffix] No '@' in User-Name = "tim.odriscoll", looking up realm NULL
Sun May 28 20:38:13 2017 : Info: [suffix] No such realm "NULL"
Sun May 28 20:38:13 2017 : Info: ++[suffix] returns noop
Sun May 28 20:38:13 2017 : Info: ++[control] returns noop
Sun May 28 20:38:13 2017 : Info: [eap] No EAP-Message, not doing EAP
Sun May 28 20:38:13 2017 : Info: ++[eap] returns noop
Sun May 28 20:38:13 2017 : Info: ++[files] returns noop
Sun May 28 20:38:13 2017 : Info: ++[expiration] returns noop
Sun May 28 20:38:13 2017 : Info: ++[logintime] returns noop
Sun May 28 20:38:13 2017 : Info: ++[pap] returns noop
Sun May 28 20:38:13 2017 : Info: Found Auth-Type = MSCHAP
Sun May 28 20:38:13 2017 : Info: # Executing group from file /etc/freeradius/sites-enabled/inner-tunnel
Sun May 28 20:38:13 2017 : Info: +- entering group MS-CHAP {...}
Sun May 28 20:38:13 2017 : Info: [mschap] Told to do MS-CHAPv1 with NT-Password
Sun May 28 20:38:13 2017 : Info: [mschap] expand: %{Stripped-User-Name} ->
Sun May 28 20:38:13 2017 : Info: [mschap] ... expanding second conditional
Sun May 28 20:38:13 2017 : Info: [mschap] expand: %{User-Name} -> tim.odriscoll
Sun May 28 20:38:13 2017 : Info: [mschap] expand: %{%{User-Name}:-None} -> tim.odriscoll
Sun May 28 20:38:13 2017 : Info: [mschap] expand: --username=%{%{Stripped-User-Name}:-%{%{User-Name}:-None}} -> --username=tim.odriscoll
Sun May 28 20:38:13 2017 : Info: [mschap] mschap1: 71
Sun May 28 20:38:13 2017 : Info: [mschap] expand: %{mschap:Challenge} -> 7174bcc95af75dca
Sun May 28 20:38:13 2017 : Info: [mschap] expand: --challenge=%{%{mschap:Challenge}:-00} -> --challenge=##redacted##
Sun May 28 20:38:13 2017 : Info: [mschap] expand: %{mschap:NT-Response} -> ##redacted##
Sun May 28 20:38:13 2017 : Info: [mschap] expand: --nt-response=%{%{mschap:NT-Response}:-00} -> --nt-response=##redacted##
Sun May 28 20:38:14 2017 : Debug: Exec-Program output: Logon failure (0xc000006d)
Sun May 28 20:38:14 2017 : Debug: Exec-Program-Wait: plaintext: Logon failure (0xc000006d)
Sun May 28 20:38:14 2017 : Debug: Exec-Program: returned: 1
Sun May 28 20:38:14 2017 : Info: [mschap] External script failed.
Sun May 28 20:38:14 2017 : Info: [mschap] MS-CHAP-Response is incorrect.
Sun May 28 20:38:14 2017 : Info: ++[mschap] returns reject
Sun May 28 20:38:14 2017 : Info: Failed to authenticate the user.
Sun May 28 20:38:14 2017 : Info: expand: %{Packet-Src-IP-Address} -> 127.0.0.1
Sun May 28 20:38:14 2017 : Auth: Login incorrect (mschap: External script says Logon failure (0xc000006d)): [tim.odriscoll/<via Auth-Type = mschap>] (from client localhost port 0) 127.0.0.1
Sun May 28 20:38:14 2017 : Info: } # server inner-tunnel
Sun May 28 20:38:14 2017 : Info: Using Post-Auth-Type Reject
Sun May 28 20:38:14 2017 : Info: # Executing group from file /etc/freeradius/sites-enabled/inner-tunnel
Sun May 28 20:38:14 2017 : Info: +- entering group REJECT {...}
Sun May 28 20:38:14 2017 : Info: [attr_filter.access_reject] expand: %{User-Name} -> tim.odriscoll
Sun May 28 20:38:14 2017 : Debug: attr_filter: Matched entry DEFAULT at line 11
Sun May 28 20:38:14 2017 : Info: ++[attr_filter.access_reject] returns updated
Sun May 28 20:38:14 2017 : Info: Delaying reject of request 0 for 1 seconds
Sun May 28 20:38:14 2017 : Debug: Going to the next request
Sun May 28 20:38:14 2017 : Debug: Waking up in 0.8 seconds.
Sun May 28 20:38:14 2017 : Info: Sending delayed reject for request 0
Sending Access-Reject of id 203 to 127.0.0.1 port 35354
MS-CHAP-Error = "\000E=691 R=1"
More information about the Freeradius-Users
mailing list