Hi all,
I have a weird problem, as you can see in the log below the client can successfully authenticate once and after that fails. The network structure is:
1) pfSense with freeRadius as firewall, authentication and accounting server
2) A HP ProCurve 2626 with MAC based port access
3) A wireless access point
Starting - reading configuration files ...
reread_config: reading radiusd.conf
Config: including file: /usr/local/etc/raddb/proxy.conf
Config: including file: /usr/local/etc/raddb/clients.conf
Config: including file: /usr/local/etc/raddb/snmp.conf
Config: including file: /usr/local/etc/raddb/eap.conf
Config: including file: /usr/local/etc/raddb/sql.conf
main: prefix = "/usr/local"
main: localstatedir = "/var"
main: logdir = "/var/log"
main: libdir = "/usr/local/lib"
main: radacctdir = "/var/log/radacct"
main: hostname_lookups = no
main: max_request_time = 30
main: cleanup_delay = 5
main: max_requests = 2048
main: delete_blocked_requests = 0
main: port = 0
main: allow_core_dumps = no
main: log_stripped_names = no
main: log_file = "/var/log/radius.log"
main: log_auth = yes
main: log_auth_badpass = yes
main: log_auth_goodpass = yes
main: pidfile = "/var/run/radiusd/radiusd.pid"
main: bind_address = 10.0.2.1 IP address [10.0.2.1]
main: user = "(null)"
main: group = "(null)"
main: usercollide = no
main: lower_user = "no"
main: lower_pass = "no"
main: nospace_user = "no"
main: nospace_pass = "no"
main: checkrad = "/usr/local/sbin/checkrad"
main: proxy_requests = yes
proxy: retry_delay = 5
proxy: retry_count = 3
proxy: synchronous = no
proxy: default_fallback = yes
proxy: dead_time = 120
proxy: post_proxy_authorize = no
proxy: wake_all_if_all_dead = no
security: max_attributes = 200
security: reject_delay = 1
security: status_server = no
main: debug_level = 0
read_config_files: reading dictionary
read_config_files: reading naslist
Using deprecated naslist file. Support for this will go away soon.
read_config_files: reading clients
read_config_files: reading realms
radiusd: entering modules setup
Module: Library search path is /usr/local/lib
Module: Loaded exec
exec: wait = yes
exec: program = "(null)"
exec: input_pairs = "request"
exec: output_pairs = "(null)"
exec: packet_type = "(null)"
rlm_exec: Wait=yes but no output defined. Did you mean output=none?
Module: Instantiated exec (exec)
Module: Loaded expr
Module: Instantiated expr (expr)
Module: Loaded Counter
counter: filename = "/usr/local/etc/raddb/db.daily"
counter: key = "User-Name"
counter: reset = "daily"
counter: count-attribute = "Acct-Session-Time"
counter: counter-name = "Daily-Session-Time"
counter: check-name = "Max-Daily-Session"
counter: allowed-servicetype = "Framed-User"
counter: cache-size = 5000
rlm_counter: Counter attribute Daily-Session-Time is number 1830
rlm_counter: Current Time: 1317844840 [2011-10-05 22:00:40], Next reset 1317852000 [2011-10-06 00:00:00]
Module: Instantiated counter (daily)
counter: filename = "/usr/local/etc/raddb/db.weekly"
counter: key = "User-Name"
counter: reset = "weekly"
counter: count-attribute = "Acct-Session-Time"
counter: counter-name = "Weekly-Session-Time"
counter: check-name = "Max-Weekly-Session"
counter: allowed-servicetype = "(null)"
counter: cache-size = 5000
rlm_counter: Counter attribute Weekly-Session-Time is number 1832
rlm_counter: Current Time: 1317844840 [2011-10-05 22:00:40], Next reset 1318111200 [2011-10-09 00:00:00]
Module: Instantiated counter (weekly)
counter: filename = "/usr/local/etc/raddb/db.monthly"
counter: key = "User-Name"
counter: reset = "monthly"
counter: count-attribute = "Acct-Session-Time"
counter: counter-name = "Monthly-Session-Time"
counter: check-name = "Max-Monthly-Session"
counter: allowed-servicetype = "(null)"
counter: cache-size = 5000
rlm_counter: Counter attribute Monthly-Session-Time is number 1834
rlm_counter: Current Time: 1317844840 [2011-10-05 22:00:40], Next reset 1320098400 [2011-10-31 23:00:00]
Module: Instantiated counter (monthly)
counter: filename = "/usr/local/etc/raddb/db.forever"
counter: key = "User-Name"
counter: reset = "never"
counter: count-attribute = "Acct-Session-Time"
counter: counter-name = "Forever-Session-Time"
counter: check-name = "Max-Forever-Session"
counter: allowed-servicetype = "(null)"
counter: cache-size = 5000
rlm_counter: Counter attribute Forever-Session-Time is number 1836
rlm_counter: Current Time: 1317844840 [2011-10-05 22:00:40], Next reset 0 [2011-10-05 22:00:00]
Module: Instantiated counter (forever)
Module: Loaded PAP
pap: encryption_scheme = "crypt"
pap: auto_header = no
Module: Instantiated pap (pap)
Module: Loaded CHAP
Module: Instantiated chap (chap)
Module: Loaded MS-CHAP
mschap: use_mppe = yes
mschap: require_encryption = no
mschap: require_strong = no
mschap: with_ntdomain_hack = no
mschap: passwd = "(null)"
mschap: ntlm_auth = "(null)"
Module: Instantiated mschap (mschap)
Module: Loaded System
unix: cache = no
unix: passwd = "(null)"
unix: shadow = "(null)"
unix: group = "(null)"
unix: radwtmp = "/var/log/radwtmp"
unix: usegroup = no
unix: cache_reload = 600
Module: Instantiated unix (unix)
Module: Loaded eap
eap: default_eap_type = "md5"
eap: timer_expire = 60
eap: ignore_unknown_eap_types = no
eap: cisco_accounting_username_bug = no
rlm_eap: Loaded and initialized type md5
rlm_eap: Loaded and initialized type leap
gtc: challenge = "Password: "
gtc: auth_type = "PAP"
rlm_eap: Loaded and initialized type gtc
mschapv2: with_ntdomain_hack = no
rlm_eap: Loaded and initialized type mschapv2
Module: Instantiated eap (eap)
Module: Loaded preprocess
preprocess: huntgroups = "/usr/local/etc/raddb/huntgroups"
preprocess: hints = "/usr/local/etc/raddb/hints"
preprocess: with_ascend_hack = no
preprocess: ascend_channels_per_line = 23
preprocess: with_ntdomain_hack = no
preprocess: with_specialix_jetstream_hack = no
preprocess: with_cisco_vsa_hack = no
preprocess: with_alvarion_vsa_hack = no
Module: Instantiated preprocess (preprocess)
Module: Loaded realm
realm: format = "suffix"
realm: delimiter = "@"
realm: ignore_default = no
realm: ignore_null = no
Module: Instantiated realm (suffix)
Module: Loaded files
files: usersfile = "/usr/local/etc/raddb/users"
files: acctusersfile = "/usr/local/etc/raddb/acct_users"
files: preproxy_usersfile = "/usr/local/etc/raddb/preproxy_users"
files: compat = "no"
Module: Instantiated files (files)
Module: Loaded Acct-Unique-Session-Id
acct_unique: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"
Module: Instantiated acct_unique (acct_unique)
Module: Loaded detail
detail: detailfile = "/var/log/radacct/%{Client-IP-Address}/detail-%Y%m%d"
detail: detailperm = 384
detail: dirperm = 493
detail: locking = no
Module: Instantiated detail (detail)
Module: Loaded radutmp
radutmp: filename = "/var/log/radutmp"
radutmp: username = "%{User-Name}"
radutmp: case_sensitive = yes
radutmp: check_with_nas = yes
radutmp: perm = 384
radutmp: callerid = yes
Module: Instantiated radutmp (radutmp)
Listening on authentication 10.0.2.1:1812
Listening on accounting 10.0.2.1:1813
Ready to process requests.
rad_recv: Access-Request packet from host 10.0.2.2:1024, id=55, length=197
Framed-MTU = 1480
NAS-IP-Address = 10.0.2.2
NAS-Identifier = "Melkweg-0"
User-Name = "00026f898b62"
Service-Type = Framed-User
Framed-Protocol = PPP
NAS-Port = 1
NAS-Port-Type = Ethernet
NAS-Port-Id = "1"
Called-Station-Id = "00-1d-b3-2f-3f-3f"
Calling-Station-Id = "00-02-6f-89-8b-62"
Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
CHAP-Password = 0x36a38cdd1a470aebb4c6e8887360fb3fc9
Message-Authenticator = 0xdefb1131a6c68c375b062393ad67c22d
Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 0
modcall[authorize]: module "preprocess" returns ok for request 0
rlm_chap: Setting 'Auth-Type := CHAP'
modcall[authorize]: module "chap" returns ok for request 0
modcall[authorize]: module "mschap" returns noop for request 0
rlm_realm: No '@' in User-Name = "00026f898b62", looking up realm NULL
rlm_realm: No such realm "NULL"
modcall[authorize]: module "suffix" returns noop for request 0
rlm_eap: No EAP-Message, not doing EAP
modcall[authorize]: module "eap" returns noop for request 0
users: Matched entry 00026f898b62 at line 1
modcall[authorize]: module "files" returns ok for request 0
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
modcall[authorize]: module "daily" returns noop for request 0
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
modcall[authorize]: module "weekly" returns noop for request 0
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
modcall[authorize]: module "monthly" returns noop for request 0
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
modcall[authorize]: module "forever" returns noop for request 0
modcall: leaving group authorize (returns ok) for request 0
rad_check_password: Found Auth-Type CHAP
auth: type "CHAP"
Processing the authenticate section of radiusd.conf
modcall: entering group CHAP for request 0
rlm_chap: login attempt by "00026f898b62" with CHAP password
rlm_chap: Using clear text password "00026f898b62" for user 00026f898b62 authentication.
rlm_chap: chap user 00026f898b62 authenticated succesfully
modcall[authenticate]: module "chap" returns ok for request 0
modcall: leaving group CHAP (returns ok) for request 0
Processing the session section of radiusd.conf
modcall: entering group session for request 0
radius_xlat: '/var/log/radutmp'
modcall[session]: module "radutmp" returns ok for request 0
modcall: leaving group session (returns ok) for request 0
Login OK: [00026f898b62/<CHAP-Password>] (from client Switch1 port 1 cli 00-02-6f-89-8b-62)
Sending Access-Accept of id 55 to 10.0.2.2 port 1024
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "2"
Finished request 0
Going to the next request
--- Walking the entire request list ---
Waking up in 6 seconds...
--- Walking the entire request list ---
Cleaning up request 0 ID 55 with timestamp 4e8cb778
Nothing to do. Sleeping until we see a request.
rad_recv: Access-Request packet from host 10.0.2.2:1024, id=56, length=197
Framed-MTU = 1480
NAS-IP-Address = 10.0.2.2
NAS-Identifier = "Melkweg-0"
User-Name = "00026f898b64"
Service-Type = Framed-User
Framed-Protocol = PPP
NAS-Port = 1
NAS-Port-Type = Ethernet
NAS-Port-Id = "1"
Called-Station-Id = "00-1d-b3-2f-3f-3f"
Calling-Station-Id = "00-02-6f-89-8b-64"
Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
CHAP-Password = 0x37fe6aa7c21b09f9fff29122501809899b
Message-Authenticator = 0x4aad343a1934af2951356edec927fd4e
Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 1
modcall[authorize]: module "preprocess" returns ok for request 1
rlm_chap: Setting 'Auth-Type := CHAP'
modcall[authorize]: module "chap" returns ok for request 1
modcall[authorize]: module "mschap" returns noop for request 1
rlm_realm: No '@' in User-Name = "00026f898b64", looking up realm NULL
rlm_realm: No such realm "NULL"
modcall[authorize]: module "suffix" returns noop for request 1
rlm_eap: No EAP-Message, not doing EAP
modcall[authorize]: module "eap" returns noop for request 1
modcall[authorize]: module "files" returns notfound for request 1
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
modcall[authorize]: module "daily" returns noop for request 1
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
modcall[authorize]: module "weekly" returns noop for request 1
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
modcall[authorize]: module "monthly" returns noop for request 1
rlm_counter: Entering module authorize code
rlm_counter: Could not find Check item value pair
modcall[authorize]: module "forever" returns noop for request 1
modcall: leaving group authorize (returns ok) for request 1
rad_check_password: Found Auth-Type CHAP
auth: type "CHAP"
Processing the authenticate section of radiusd.conf
modcall: entering group CHAP for request 1
rlm_chap: login attempt by "00026f898b64" with CHAP password
rlm_chap: Could not find clear text password for user 00026f898b64
modcall[authenticate]: module "chap" returns invalid for request 1
modcall: leaving group CHAP (returns invalid) for request 1
auth: Failed to validate the user.
Login incorrect (rlm_chap: Clear text password not available): [00026f898b64/<CHAP-Password>] (from client Switch1 port 1 cli 00-02-6f-89-8b-64)
Delaying request 1 for 1 seconds
Finished request 1
Going to the next request
--- Walking the entire request list ---
Waking up in 1 seconds...
--- Walking the entire request list ---
Waking up in 1 seconds...
--- Walking the entire request list ---
Sending Access-Reject of id 56 to 10.0.2.2 port 1024
Waking up in 4 seconds...
--- Walking the entire request list ---
Cleaning up request 1 ID 56 with timestamp 4e8cb7b6
Nothing to do. Sleeping until we see a request.
Attached are the radiusd.conf and users file, please help me out…
Yours sincerely,
Mark van Beek
