pfSense with freeRadius and CHAP

Thu Oct 6 11:26:59 CEST 2011

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  
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20111006/6ae4f36e/attachment.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: radiusd.conf
Type: application/octet-stream
Size: 6369 bytes
Desc: not available
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20111006/6ae4f36e/attachment.obj>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: users
Type: application/octet-stream
Size: 195 bytes
Desc: not available
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20111006/6ae4f36e/attachment-0001.obj>