Experiencing a proplem with pap authentication using Freeradius 2.2.2

15 Nov 2013

      Good Morning,

We currently run 3 instances of freeradius 2.1.8 on Red Hat Enterprise 4
32-bit and it works flawlessly for us.  Thank you for that!  I have built a
Red Hat Enterprise 6 64-bit server and installed freeradius 2.2.2 on it.
When I change the RADIUS Server IP address on a device that currently works
with the RHEL4/freeradius 2.1.8 to the IP address of the new server, I am
unable to authenticate.

Here is the output from starting up freeradius 2.2.2 in -Xxx debug mode and
an attempt to authenticate.  If anyone can help me to resolve this I would
be greatly appreciative.  I can answer any questions and post configuration
file contents if required.

Thanks Very Much!

Derek

[root@chesva150a raddb]# /usr/local-wips/sbin/radiusd -Xxx
Fri Nov 15 09:24:05 2013 : Info: radiusd: FreeRADIUS Version 2.2.2, for
host x86_64-unknown-linux-gnu, built on Nov 11 2013 at 14:21:41
Fri Nov 15 09:24:05 2013 : Debug: Server was built with:
Fri Nov 15 09:24:05 2013 : Debug:   accounting
Fri Nov 15 09:24:05 2013 : Debug:   authentication
Fri Nov 15 09:24:05 2013 : Debug:  WITH_VMPS
Fri Nov 15 09:24:05 2013 : Debug: Server core libs:
Fri Nov 15 09:24:05 2013 : Debug:   ssl: OpenSSL 1.0.0-fips 29 Mar 2010
Fri Nov 15 09:24:05 2013 : Info: Copyright (C) 1999-2013 The FreeRADIUS
server project and contributors.
Fri Nov 15 09:24:05 2013 : Info: There is NO warranty; not even for
MERCHANTABILITY or FITNESS FOR A
Fri Nov 15 09:24:05 2013 : Info: PARTICULAR PURPOSE.
Fri Nov 15 09:24:05 2013 : Info: You may redistribute copies of FreeRADIUS
under the terms of the
Fri Nov 15 09:24:05 2013 : Info: GNU General Public License.
Fri Nov 15 09:24:05 2013 : Info: For more information about these matters,
see the file named COPYRIGHT.
Fri Nov 15 09:24:05 2013 : Info: Starting - reading configuration files ...
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/radiusd.conf
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/clients.conf
Fri Nov 15 09:24:05 2013 : Debug: including files in
directory /usr/local-wips/etc/raddb/modules/
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/linelog
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/radrelay
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/unix
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/rediswho
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/sql_log
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/preprocess
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/sradutmp
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/pam
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/realm
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/expiration
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/soh
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/policy
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/redis
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/perl
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/smbpasswd
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/etc_group
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/opendirectory
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/detail.log
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/checkval
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/files
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/smsotp
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/cache
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/dynamic_clients
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/logintime
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/otp
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/krb5
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/cui
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/echo
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/acct_unique
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/detail
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/wimax
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/mschap
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/radutmp
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/chap
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/sqlcounter_expire_on_login
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/digest
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/pap
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/replicate
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/expr
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/attr_filter
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/ntlm_auth
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/attr_rewrite
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/inner-eap
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/mac2vlan
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/dhcp_sqlippool
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/sql/mysql/ippool-dhcp.conf
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/always
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/ippool
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/counter
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/ldap
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/mac2ip
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/exec
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/passwd
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/modules/detail.example.com
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/eap.conf
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/policy.conf
Fri Nov 15 09:24:05 2013 : Debug: including files in
directory /usr/local-wips/etc/raddb/sites-enabled/
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/sites-enabled/default
Fri Nov 15 09:24:05 2013 : Debug: including configuration
file /usr/local-wips/etc/raddb/sites-enabled/inner-tunnel
Fri Nov 15 09:24:05 2013 : Debug: main {
Fri Nov 15 09:24:05 2013 : Debug:       allow_core_dumps = no
Fri Nov 15 09:24:05 2013 : Debug: }
Fri Nov 15 09:24:05 2013 : Debug: including dictionary
file /usr/local-wips/etc/raddb/dictionary
Fri Nov 15 09:24:05 2013 : Debug: main {
Fri Nov 15 09:24:05 2013 : Debug:       name = "radiusd"
Fri Nov 15 09:24:05 2013 : Debug:       prefix = "/usr/local-wips"
Fri Nov 15 09:24:05 2013 : Debug:       localstatedir = "/var"
Fri Nov 15 09:24:05 2013 : Debug:       sbindir = "/usr/local-wips/sbin"
Fri Nov 15 09:24:05 2013 : Debug:       logdir = "/var/log"
Fri Nov 15 09:24:05 2013 : Debug:       run_dir = "/var/run/radiusd"
Fri Nov 15 09:24:05 2013 : Debug:       libdir = "/usr/local-wips/lib"
Fri Nov 15 09:24:05 2013 : Debug:       radacctdir =
"/var/log/radacct-wips"
Fri Nov 15 09:24:05 2013 : Debug:       hostname_lookups = no
Fri Nov 15 09:24:05 2013 : Debug:       max_request_time = 30
Fri Nov 15 09:24:05 2013 : Debug:       cleanup_delay = 5
Fri Nov 15 09:24:05 2013 : Debug:       max_requests = 1024
Fri Nov 15 09:24:05 2013 : Debug:       pidfile =
"/var/run/radiusd/radiusd-wips.pid"
Fri Nov 15 09:24:05 2013 : Debug:       checkrad =
"/usr/local-wips/sbin/checkrad"
Fri Nov 15 09:24:05 2013 : Debug:       debug_level = 0
Fri Nov 15 09:24:05 2013 : Debug:       proxy_requests = no
Fri Nov 15 09:24:05 2013 : Debug:  log {
Fri Nov 15 09:24:05 2013 : Debug:       stripped_names = no
Fri Nov 15 09:24:05 2013 : Debug:       auth = no
Fri Nov 15 09:24:05 2013 : Debug:       auth_badpass = no
Fri Nov 15 09:24:05 2013 : Debug:       auth_goodpass = no
Fri Nov 15 09:24:05 2013 : Debug:  }
Fri Nov 15 09:24:05 2013 : Debug:  security {
Fri Nov 15 09:24:05 2013 : Debug:       max_attributes = 200
Fri Nov 15 09:24:05 2013 : Debug:       reject_delay = 1
Fri Nov 15 09:24:05 2013 : Debug:       status_server = yes
Fri Nov 15 09:24:05 2013 : Debug:  }
Fri Nov 15 09:24:05 2013 : Debug: }
Fri Nov 15 09:24:05 2013 : Debug: radiusd: #### Loading Realms and Home
Servers ####
Fri Nov 15 09:24:05 2013 : Debug: radiusd: #### Loading Clients ####
Fri Nov 15 09:24:05 2013 : Debug:  client 127.0.0.1 {
Fri Nov 15 09:24:05 2013 : Debug:       require_message_authenticator = no
Fri Nov 15 09:24:05 2013 : Debug:       secret = "S0meP@ssw0rd"
Fri Nov 15 09:24:05 2013 : Debug:       shortname = "localhost"
Fri Nov 15 09:24:05 2013 : Debug:       nastype = "other"
Fri Nov 15 09:24:05 2013 : Debug:  }
Fri Nov 15 09:24:05 2013 : Debug:  client 172.25.0.0/16 {
Fri Nov 15 09:24:05 2013 : Debug:       require_message_authenticator = no
Fri Nov 15 09:24:05 2013 : Debug:       secret = "S0meP@ssw0rd"
Fri Nov 15 09:24:05 2013 : Debug:       shortname = "dsl"
Fri Nov 15 09:24:05 2013 : Debug:  }
Fri Nov 15 09:24:05 2013 : Debug: radiusd: #### Instantiating modules ####
Fri Nov 15 09:24:05 2013 : Debug:  instantiate {
Fri Nov 15 09:24:05 2013 : Debug:     (Loaded rlm_exec, checking if it's
valid)
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to module rlm_exec
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating module "exec" from
file /usr/local-wips/etc/raddb/modules/exec
Fri Nov 15 09:24:05 2013 : Debug:   exec {
Fri Nov 15 09:24:05 2013 : Debug:       wait = no
Fri Nov 15 09:24:05 2013 : Debug:       input_pairs = "request"
Fri Nov 15 09:24:05 2013 : Debug:       shell_escape = yes
Fri Nov 15 09:24:05 2013 : Debug:       timeout = 10
Fri Nov 15 09:24:05 2013 : Debug:   }
Fri Nov 15 09:24:05 2013 : Debug:     (Loaded rlm_expr, checking if it's
valid)
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to module rlm_expr
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating module "expr" from
file /usr/local-wips/etc/raddb/modules/expr
Fri Nov 15 09:24:05 2013 : Debug:     (Loaded rlm_expiration, checking if
it's valid)
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to module rlm_expiration
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating module
"expiration" from file /usr/local-wips/etc/raddb/modules/expiration
Fri Nov 15 09:24:05 2013 : Debug:   expiration {
Fri Nov 15 09:24:05 2013 : Debug:       reply-message = "Password Has
Expired  "
Fri Nov 15 09:24:05 2013 : Debug:   }
Fri Nov 15 09:24:05 2013 : Debug:     (Loaded rlm_logintime, checking if
it's valid)
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to module rlm_logintime
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating module "logintime"
from file /usr/local-wips/etc/raddb/modules/logintime
Fri Nov 15 09:24:05 2013 : Debug:   logintime {
Fri Nov 15 09:24:05 2013 : Debug:       reply-message = "You are calling
outside your allowed timespan  "
Fri Nov 15 09:24:05 2013 : Debug:       minimum-timeout = 60
Fri Nov 15 09:24:05 2013 : Debug:   }
Fri Nov 15 09:24:05 2013 : Debug:  }
Fri Nov 15 09:24:05 2013 : Debug: radiusd: #### Loading Virtual Servers
####
Fri Nov 15 09:24:05 2013 : Debug: server { # from
file /usr/local-wips/etc/raddb/radiusd.conf
Fri Nov 15 09:24:05 2013 : Debug:  modules {
Fri Nov 15 09:24:05 2013 : Debug:   Module: Creating Auth-Type = digest
Fri Nov 15 09:24:05 2013 : Debug:   Module: Creating Post-Auth-Type =
REJECT
Fri Nov 15 09:24:05 2013 : Debug:  Module: Checking authenticate {...} for
more modules to load
Fri Nov 15 09:24:05 2013 : Debug:     (Loaded rlm_pap, checking if it's
valid)
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to module rlm_pap
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating module "pap" from
file /usr/local-wips/etc/raddb/modules/pap
Fri Nov 15 09:24:05 2013 : Debug:   pap {
Fri Nov 15 09:24:05 2013 : Debug:       encryption_scheme = "auto"
Fri Nov 15 09:24:05 2013 : Debug:       auto_header = no
Fri Nov 15 09:24:05 2013 : Debug:   }
Fri Nov 15 09:24:05 2013 : Debug:     (Loaded rlm_chap, checking if it's
valid)
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to module rlm_chap
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating module "chap" from
file /usr/local-wips/etc/raddb/modules/chap
Fri Nov 15 09:24:05 2013 : Debug:     (Loaded rlm_mschap, checking if it's
valid)
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to module rlm_mschap
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating module "mschap"
from file /usr/local-wips/etc/raddb/modules/mschap
Fri Nov 15 09:24:05 2013 : Debug:   mschap {
Fri Nov 15 09:24:05 2013 : Debug:       use_mppe = yes
Fri Nov 15 09:24:05 2013 : Debug:       require_encryption = no
Fri Nov 15 09:24:05 2013 : Debug:       require_strong = no
Fri Nov 15 09:24:05 2013 : Debug:       with_ntdomain_hack = no
Fri Nov 15 09:24:05 2013 : Debug:       allow_retry = yes
Fri Nov 15 09:24:05 2013 : Debug:   }
Fri Nov 15 09:24:05 2013 : Debug:     (Loaded rlm_digest, checking if it's
valid)
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to module rlm_digest
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating module "digest"
from file /usr/local-wips/etc/raddb/modules/digest
Fri Nov 15 09:24:05 2013 : Debug:     (Loaded rlm_unix, checking if it's
valid)
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to module rlm_unix
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating module "unix" from
file /usr/local-wips/etc/raddb/modules/unix
Fri Nov 15 09:24:05 2013 : Debug:   unix {
Fri Nov 15 09:24:05 2013 : Debug:       radwtmp = "/var/log/radwtmp"
Fri Nov 15 09:24:05 2013 : Debug:   }
Fri Nov 15 09:24:05 2013 : Debug:     (Loaded rlm_eap, checking if it's
valid)
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to module rlm_eap
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating module "eap" from
file /usr/local-wips/etc/raddb/eap.conf
Fri Nov 15 09:24:05 2013 : Debug:   eap {
Fri Nov 15 09:24:05 2013 : Debug:       default_eap_type = "md5"
Fri Nov 15 09:24:05 2013 : Debug:       timer_expire = 60
Fri Nov 15 09:24:05 2013 : Debug:       ignore_unknown_eap_types = no
Fri Nov 15 09:24:05 2013 : Debug:       cisco_accounting_username_bug = no
Fri Nov 15 09:24:05 2013 : Debug:       max_sessions = 4096
Fri Nov 15 09:24:05 2013 : Debug:   }
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to sub-module rlm_eap_md5
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating eap-md5
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to sub-module
rlm_eap_leap
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating eap-leap
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to sub-module rlm_eap_gtc
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating eap-gtc
Fri Nov 15 09:24:05 2013 : Debug:    gtc {
Fri Nov 15 09:24:05 2013 : Debug:       challenge = "Password: "
Fri Nov 15 09:24:05 2013 : Debug:       auth_type = "PAP"
Fri Nov 15 09:24:05 2013 : Debug:    }
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to sub-module rlm_eap_tls
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating eap-tls
Fri Nov 15 09:24:05 2013 : Debug:    tls {
Fri Nov 15 09:24:05 2013 : Debug:       rsa_key_exchange = no
Fri Nov 15 09:24:05 2013 : Debug:       dh_key_exchange = yes
Fri Nov 15 09:24:05 2013 : Debug:       rsa_key_length = 512
Fri Nov 15 09:24:05 2013 : Debug:       dh_key_length = 512
Fri Nov 15 09:24:05 2013 : Debug:       verify_depth = 0
Fri Nov 15 09:24:05 2013 : Debug:       CA_path =
"/usr/local-wips/etc/raddb/certs"
Fri Nov 15 09:24:05 2013 : Debug:       pem_file_type = yes
Fri Nov 15 09:24:05 2013 : Debug:       private_key_file =
"/usr/local-wips/etc/raddb/certs/server.pem"
Fri Nov 15 09:24:05 2013 : Debug:       certificate_file =
"/usr/local-wips/etc/raddb/certs/server.pem"
Fri Nov 15 09:24:05 2013 : Debug:       CA_file =
"/usr/local-wips/etc/raddb/certs/ca.pem"
Fri Nov 15 09:24:05 2013 : Debug:       private_key_password = "whatever"
Fri Nov 15 09:24:05 2013 : Debug:       dh_file =
"/usr/local-wips/etc/raddb/certs/dh"
Fri Nov 15 09:24:05 2013 : Debug:       fragment_size = 1024
Fri Nov 15 09:24:05 2013 : Debug:       include_length = yes
Fri Nov 15 09:24:05 2013 : Debug:       check_crl = no
Fri Nov 15 09:24:05 2013 : Debug:       cipher_list = "DEFAULT"
Fri Nov 15 09:24:05 2013 : Debug:       make_cert_command =
"/usr/local-wips/etc/raddb/certs/bootstrap"
Fri Nov 15 09:24:05 2013 : Debug:     cache {
Fri Nov 15 09:24:05 2013 : Debug:       enable = no
Fri Nov 15 09:24:05 2013 : Debug:       lifetime = 24
Fri Nov 15 09:24:05 2013 : Debug:       max_entries = 255
Fri Nov 15 09:24:05 2013 : Debug:     }
Fri Nov 15 09:24:05 2013 : Debug:     verify {
Fri Nov 15 09:24:05 2013 : Debug:     }
Fri Nov 15 09:24:05 2013 : Debug:     ocsp {
Fri Nov 15 09:24:05 2013 : Debug:       enable = no
Fri Nov 15 09:24:05 2013 : Debug:       override_cert_url = yes
Fri Nov 15 09:24:05 2013 : Debug:       url = "http://127.0.0.1/ocsp/"
Fri Nov 15 09:24:05 2013 : Debug:       use_nonce = yes
Fri Nov 15 09:24:05 2013 : Debug:       timeout = 0
Fri Nov 15 09:24:05 2013 : Debug:       softfail = no
Fri Nov 15 09:24:05 2013 : Debug:     }
Fri Nov 15 09:24:05 2013 : Debug:    }
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to sub-module
rlm_eap_ttls
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating eap-ttls
Fri Nov 15 09:24:05 2013 : Debug:    ttls {
Fri Nov 15 09:24:05 2013 : Debug:       default_eap_type = "md5"
Fri Nov 15 09:24:05 2013 : Debug:       copy_request_to_tunnel = no
Fri Nov 15 09:24:05 2013 : Debug:       use_tunneled_reply = no
Fri Nov 15 09:24:05 2013 : Debug:       virtual_server = "inner-tunnel"
Fri Nov 15 09:24:05 2013 : Debug:       include_length = yes
Fri Nov 15 09:24:05 2013 : Debug:    }
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to sub-module
rlm_eap_peap
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating eap-peap
Fri Nov 15 09:24:05 2013 : Debug:    peap {
Fri Nov 15 09:24:05 2013 : Debug:       default_eap_type = "mschapv2"
Fri Nov 15 09:24:05 2013 : Debug:       copy_request_to_tunnel = no
Fri Nov 15 09:24:05 2013 : Debug:       use_tunneled_reply = no
Fri Nov 15 09:24:05 2013 : Debug:       proxy_tunneled_request_as_eap = yes
Fri Nov 15 09:24:05 2013 : Debug:       virtual_server = "inner-tunnel"
Fri Nov 15 09:24:05 2013 : Debug:       soh = no
Fri Nov 15 09:24:05 2013 : Debug:    }
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to sub-module
rlm_eap_mschapv2
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating eap-mschapv2
Fri Nov 15 09:24:05 2013 : Debug:    mschapv2 {
Fri Nov 15 09:24:05 2013 : Debug:       with_ntdomain_hack = no
Fri Nov 15 09:24:05 2013 : Debug:       send_error = no
Fri Nov 15 09:24:05 2013 : Debug:    }
Fri Nov 15 09:24:05 2013 : Debug:  Module: Checking authorize {...} for
more modules to load
Fri Nov 15 09:24:05 2013 : Debug:     (Loaded rlm_preprocess, checking if
it's valid)
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to module rlm_preprocess
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating module
"preprocess" from file /usr/local-wips/etc/raddb/modules/preprocess
Fri Nov 15 09:24:05 2013 : Debug:   preprocess {
Fri Nov 15 09:24:05 2013 : Debug:       huntgroups =
"/usr/local-wips/etc/raddb/huntgroups"
Fri Nov 15 09:24:05 2013 : Debug:       hints =
"/usr/local-wips/etc/raddb/hints"
Fri Nov 15 09:24:05 2013 : Debug:       with_ascend_hack = no
Fri Nov 15 09:24:05 2013 : Debug:       ascend_channels_per_line = 23
Fri Nov 15 09:24:05 2013 : Debug:       with_ntdomain_hack = no
Fri Nov 15 09:24:05 2013 : Debug:       with_specialix_jetstream_hack = no
Fri Nov 15 09:24:05 2013 : Debug:       with_cisco_vsa_hack = no
Fri Nov 15 09:24:05 2013 : Debug:       with_alvarion_vsa_hack = no
Fri Nov 15 09:24:05 2013 : Debug:   }
Fri Nov 15 09:24:05 2013 : Debug: reading pairlist
file /usr/local-wips/etc/raddb/huntgroups
Fri Nov 15 09:24:05 2013 : Debug: reading pairlist
file /usr/local-wips/etc/raddb/hints
Fri Nov 15 09:24:05 2013 : Debug:     (Loaded rlm_realm, checking if it's
valid)
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to module rlm_realm
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating module "suffix"
from file /usr/local-wips/etc/raddb/modules/realm
Fri Nov 15 09:24:05 2013 : Debug:   realm suffix {
Fri Nov 15 09:24:05 2013 : Debug:       format = "suffix"
Fri Nov 15 09:24:05 2013 : Debug:       delimiter = "@"
Fri Nov 15 09:24:05 2013 : Debug:       ignore_default = no
Fri Nov 15 09:24:05 2013 : Debug:       ignore_null = no
Fri Nov 15 09:24:05 2013 : Debug:   }
Fri Nov 15 09:24:05 2013 : Debug:     (Loaded rlm_files, checking if it's
valid)
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to module rlm_files
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating module "files"
from file /usr/local-wips/etc/raddb/modules/files
Fri Nov 15 09:24:05 2013 : Debug:   files {
Fri Nov 15 09:24:05 2013 : Debug:       usersfile =
"/usr/local-wips/etc/raddb/users"
Fri Nov 15 09:24:05 2013 : Debug:       acctusersfile =
"/usr/local-wips/etc/raddb/acct_users"
Fri Nov 15 09:24:05 2013 : Debug:       preproxy_usersfile =
"/usr/local-wips/etc/raddb/preproxy_users"
Fri Nov 15 09:24:05 2013 : Debug:       compat = "no"
Fri Nov 15 09:24:05 2013 : Debug:   }
Fri Nov 15 09:24:05 2013 : Debug: reading pairlist
file /usr/local-wips/etc/raddb/users
Fri Nov 15 09:24:05 2013 : Debug: reading pairlist
file /usr/local-wips/etc/raddb/acct_users
Fri Nov 15 09:24:05 2013 : Debug: reading pairlist
file /usr/local-wips/etc/raddb/preproxy_users
Fri Nov 15 09:24:05 2013 : Debug:  Module: Checking preacct {...} for more
modules to load
Fri Nov 15 09:24:05 2013 : Debug:     (Loaded rlm_acct_unique, checking if
it's valid)
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to module rlm_acct_unique
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating module
"acct_unique" from file /usr/local-wips/etc/raddb/modules/acct_unique
Fri Nov 15 09:24:05 2013 : Debug:   acct_unique {
Fri Nov 15 09:24:05 2013 : Debug:       key = "User-Name, Acct-Session-Id,
NAS-IP-Address, NAS-Identifier, NAS-Port"
Fri Nov 15 09:24:05 2013 : Debug:   }
Fri Nov 15 09:24:05 2013 : Debug:  Module: Checking accounting {...} for
more modules to load
Fri Nov 15 09:24:05 2013 : Debug:     (Loaded rlm_detail, checking if it's
valid)
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to module rlm_detail
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating module "detail"
from file /usr/local-wips/etc/raddb/modules/detail
Fri Nov 15 09:24:05 2013 : Debug:   detail {
Fri Nov 15 09:24:05 2013 : Debug:       detailfile =
"/var/log/radacct-wips/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d"
Fri Nov 15 09:24:05 2013 : Debug:       header = "%t"
Fri Nov 15 09:24:05 2013 : Debug:       detailperm = 384
Fri Nov 15 09:24:05 2013 : Debug:       dirperm = 493
Fri Nov 15 09:24:05 2013 : Debug:       locking = no
Fri Nov 15 09:24:05 2013 : Debug:       log_packet_header = no
Fri Nov 15 09:24:05 2013 : Debug:   }
Fri Nov 15 09:24:05 2013 : Debug:     (Loaded rlm_attr_filter, checking if
it's valid)
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to module rlm_attr_filter
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating module
"attr_filter.accounting_response" from
file /usr/local-wips/etc/raddb/modules/attr_filter
Fri Nov 15 09:24:05 2013 : Debug:   attr_filter
attr_filter.accounting_response {
Fri Nov 15 09:24:05 2013 : Debug:       attrsfile =
"/usr/local-wips/etc/raddb/attrs.accounting_response"
Fri Nov 15 09:24:05 2013 : Debug:       key = "%{User-Name}"
Fri Nov 15 09:24:05 2013 : Debug:       relaxed = no
Fri Nov 15 09:24:05 2013 : Debug:   }
Fri Nov 15 09:24:05 2013 : Debug: reading pairlist
file /usr/local-wips/etc/raddb/attrs.accounting_response
Fri Nov 15 09:24:05 2013 : Debug:  Module: Checking session {...} for more
modules to load
Fri Nov 15 09:24:05 2013 : Debug:     (Loaded rlm_radutmp, checking if it's
valid)
Fri Nov 15 09:24:05 2013 : Debug:  Module: Linked to module rlm_radutmp
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating module "radutmp"
from file /usr/local-wips/etc/raddb/modules/radutmp
Fri Nov 15 09:24:05 2013 : Debug:   radutmp {
Fri Nov 15 09:24:05 2013 : Debug:       filename = "/var/log/radutmp-wips"
Fri Nov 15 09:24:05 2013 : Debug:       username = "%{User-Name}"
Fri Nov 15 09:24:05 2013 : Debug:       case_sensitive = yes
Fri Nov 15 09:24:05 2013 : Debug:       check_with_nas = yes
Fri Nov 15 09:24:05 2013 : Debug:       perm = 384
Fri Nov 15 09:24:05 2013 : Debug:       callerid = yes
Fri Nov 15 09:24:05 2013 : Debug:   }
Fri Nov 15 09:24:05 2013 : Debug:  Module: Checking post-proxy {...} for
more modules to load
Fri Nov 15 09:24:05 2013 : Debug:  Module: Checking post-auth {...} for
more modules to load
Fri Nov 15 09:24:05 2013 : Debug:  Module: Instantiating module
"attr_filter.access_reject" from
file /usr/local-wips/etc/raddb/modules/attr_filter
Fri Nov 15 09:24:05 2013 : Debug:   attr_filter attr_filter.access_reject {
Fri Nov 15 09:24:05 2013 : Debug:       attrsfile =
"/usr/local-wips/etc/raddb/attrs.access_reject"
Fri Nov 15 09:24:05 2013 : Debug:       key = "%{User-Name}"
Fri Nov 15 09:24:05 2013 : Debug:       relaxed = no
Fri Nov 15 09:24:05 2013 : Debug:   }
Fri Nov 15 09:24:05 2013 : Debug: reading pairlist
file /usr/local-wips/etc/raddb/attrs.access_reject
Fri Nov 15 09:24:05 2013 : Debug:  } # modules
Fri Nov 15 09:24:05 2013 : Debug: } # server
Fri Nov 15 09:24:05 2013 : Debug: server inner-tunnel { # from
file /usr/local-wips/etc/raddb/sites-enabled/inner-tunnel
Fri Nov 15 09:24:05 2013 : Debug:  modules {
Fri Nov 15 09:24:05 2013 : Debug:  Module: Checking authenticate {...} for
more modules to load
Fri Nov 15 09:24:05 2013 : Debug:  Module: Checking authorize {...} for
more modules to load
Fri Nov 15 09:24:05 2013 : Debug:  Module: Checking session {...} for more
modules to load
Fri Nov 15 09:24:05 2013 : Debug:  Module: Checking post-proxy {...} for
more modules to load
Fri Nov 15 09:24:05 2013 : Debug:  Module: Checking post-auth {...} for
more modules to load
Fri Nov 15 09:24:05 2013 : Debug:  } # modules
Fri Nov 15 09:24:05 2013 : Debug: } # server
Fri Nov 15 09:24:05 2013 : Debug: radiusd: #### Opening IP addresses and
Ports ####
Fri Nov 15 09:24:05 2013 : Debug: listen {
Fri Nov 15 09:24:05 2013 : Debug:       type = "auth"
Fri Nov 15 09:24:05 2013 : Debug:       ipaddr = 10.10.4.110
Fri Nov 15 09:24:05 2013 : Debug:       port = 1303
Fri Nov 15 09:24:05 2013 : Debug: }
Fri Nov 15 09:24:05 2013 : Debug: listen {
Fri Nov 15 09:24:05 2013 : Debug:       type = "acct"
Fri Nov 15 09:24:05 2013 : Debug:       ipaddr = 10.10.4.110
Fri Nov 15 09:24:05 2013 : Debug:       port = 1304
Fri Nov 15 09:24:05 2013 : Debug: }
Fri Nov 15 09:24:05 2013 : Debug: Listening on authentication address
10.10.4.110 port 1303
Fri Nov 15 09:24:05 2013 : Debug: Listening on accounting address
10.10.4.110 port 1304
Fri Nov 15 09:24:05 2013 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 172.25.8.25 port 1337, id=246,
length=76
        User-Name = "dwnek"
        User-Password = "MyP@ssw0rd"
        NAS-IP-Address = 192.168.0.25
        NAS-Identifier = "httpd"
        NAS-Port = 303
        NAS-Port-Type = Virtual
        Service-Type = Authenticate-Only
Fri Nov 15 09:25:30 2013 : Info: # Executing section authorize from
file /usr/local-wips/etc/raddb/sites-enabled/default
Fri Nov 15 09:25:30 2013 : Info: +group authorize {
Fri Nov 15 09:25:30 2013 : Info: ++[preprocess] = ok
Fri Nov 15 09:25:30 2013 : Info: ++[chap] = noop
Fri Nov 15 09:25:30 2013 : Info: ++[mschap] = noop
Fri Nov 15 09:25:30 2013 : Info: ++[digest] = noop
Fri Nov 15 09:25:30 2013 : Info: [suffix] No '@' in User-Name = "dwnek",
looking up realm NULL
Fri Nov 15 09:25:30 2013 : Info: [suffix] No such realm "NULL"
Fri Nov 15 09:25:30 2013 : Info: ++[suffix] = noop
Fri Nov 15 09:25:30 2013 : Info: [eap] No EAP-Message, not doing EAP
Fri Nov 15 09:25:30 2013 : Info: ++[eap] = noop
Fri Nov 15 09:25:30 2013 : Info: [files] users: Matched entry dwnek at line
22
Fri Nov 15 09:25:30 2013 : Info: [files]        expand: Hello, %{User-Name}
-> Hello, dwnek
Fri Nov 15 09:25:30 2013 : Info: ++[files] = ok
Fri Nov 15 09:25:30 2013 : Info: ++[expiration] = noop
Fri Nov 15 09:25:30 2013 : Info: ++[logintime] = noop
Fri Nov 15 09:25:30 2013 : Info: [pap] WARNING! No "known good" password
found for the user.  Authentication may fail because of this.
Fri Nov 15 09:25:30 2013 : Info: ++[pap] = noop
Fri Nov 15 09:25:30 2013 : Info: +} # group authorize = ok
Fri Nov 15 09:25:30 2013 : Info: ERROR: No authenticate method (Auth-Type)
found for the request: Rejecting the user
Fri Nov 15 09:25:30 2013 : Info: Failed to authenticate the user.
Fri Nov 15 09:25:30 2013 : Info: Using Post-Auth-Type REJECT
Fri Nov 15 09:25:30 2013 : Info: # Executing group from
file /usr/local-wips/etc/raddb/sites-enabled/default
Fri Nov 15 09:25:30 2013 : Info: +group REJECT {
Fri Nov 15 09:25:30 2013 : Info: [attr_filter.access_reject]    expand:
%{User-Name} -> dwnek
Fri Nov 15 09:25:30 2013 : Debug: attr_filter: Matched entry DEFAULT at
line 11
Fri Nov 15 09:25:30 2013 : Info: ++[attr_filter.access_reject] = updated
Fri Nov 15 09:25:30 2013 : Info: +} # group REJECT = updated
Fri Nov 15 09:25:30 2013 : Info: Delaying reject of request 0 for 1 seconds
Fri Nov 15 09:25:30 2013 : Debug: Going to the next request
Fri Nov 15 09:25:30 2013 : Debug: Waking up in 0.9 seconds.
Fri Nov 15 09:25:31 2013 : Info: Sending delayed reject for request 0
Sending Access-Reject of id 246 to 172.25.8.25 port 1337
        Reply-Message = "Hello, dwnek"
Fri Nov 15 09:25:31 2013 : Debug: Waking up in 4.9 seconds.
Fri Nov 15 09:25:36 2013 : Info: Cleaning up request 0 ID 246 with
timestamp +85
Fri Nov 15 09:25:36 2013 : Info: Ready to process requests.

Experiencing a proplem with pap authentication using Freeradius 2.2.2

dwnek＠dollartree.com