ntlm_auth woes

28 May 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"

ntlm_auth woes

Tim ODriscoll