strange rlm_expiration behavior

Flamur Rogova flamur at ipko.net
Wed Oct 1 11:31:56 CEST 2008


Hi,
I am having strange behavior of rlm_expiration where it always returns 
"userlock", no matter what I put as expiration value.

my radius install is latest from git repository, with default 
configuration (unchanged in any way),

rlm_expiration rejects this user, date "10 Jan 2009", although it should 
be accepted...

could somebody confirm working rlm_expiration on latest sources ?


home raddb # cat users
a       Cleartext-Password := a, Expiration := "10 Jan 2009"
         Reply-Message = "ok"


home raddb # ../../sbin/radiusd -XX
Wed Oct  1 11:22:37 2008 : Info: FreeRADIUS Version 2.1.1, for host 
i686-pc-linux-gnu, built on Oct  1 2008 at 21:32:48
Wed Oct  1 11:22:37 2008 : Info: Copyright (C) 1999-2008 The FreeRADIUS 
server project and contributors.
Wed Oct  1 11:22:37 2008 : Info: There is NO warranty; not even for 
MERCHANTABILITY or FITNESS FOR A
Wed Oct  1 11:22:37 2008 : Info: PARTICULAR PURPOSE.
Wed Oct  1 11:22:37 2008 : Info: You may redistribute copies of 
FreeRADIUS under the terms of the
Wed Oct  1 11:22:37 2008 : Info: GNU General Public License v2.
Wed Oct  1 11:22:37 2008 : Info: Starting - reading configuration files ...
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/radiusd.conf
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/proxy.conf
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/clients.conf
Wed Oct  1 11:22:37 2008 : Debug: including files in directory 
/home/radius2.11/etc/raddb/modules/
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/radutmp
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/pap
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/logintime
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/detail
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/realm
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/acct_unique
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/expr
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/mac2vlan
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/files
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/echo
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/mschap
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/preprocess
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/krb5
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/pam
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/attr_rewrite
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/smbpasswd
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/policy
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/ldap
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/wimax
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/attr_filter
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/detail.log
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/mac2ip
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/always
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/sradutmp
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/checkval
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/inner-eap
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/detail.example.com
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/exec
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/passwd
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/digest
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/chap
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/linelog
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/etc_group
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/ippool
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/sql_log
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/counter
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/unix
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/modules/expiration
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/eap.conf
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/sql.conf
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/sql/mysql/dialup.conf
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/sql/mysql/counter.conf
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/policy.conf
Wed Oct  1 11:22:37 2008 : Debug: including files in directory 
/home/radius2.11/etc/raddb/sites-enabled/
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/sites-enabled/default
Wed Oct  1 11:22:37 2008 : Debug: including configuration file 
/home/radius2.11/etc/raddb/sites-enabled/inner-tunnel
Wed Oct  1 11:22:37 2008 : Debug: including dictionary file 
/home/radius2.11/etc/raddb/dictionary
Wed Oct  1 11:22:37 2008 : Debug: main {
Wed Oct  1 11:22:37 2008 : Debug:       prefix = "/home/radius2.11"
Wed Oct  1 11:22:37 2008 : Debug:       localstatedir = 
"/home/radius2.11/var"
Wed Oct  1 11:22:37 2008 : Debug:       logdir = 
"/home/radius2.11/var/log/radius"
Wed Oct  1 11:22:37 2008 : Debug:       libdir = "/home/radius2.11/lib"
Wed Oct  1 11:22:37 2008 : Debug:       radacctdir = 
"/home/radius2.11/var/log/radius/radacct"
Wed Oct  1 11:22:37 2008 : Debug:       hostname_lookups = no
Wed Oct  1 11:22:37 2008 : Debug:       max_request_time = 30
Wed Oct  1 11:22:37 2008 : Debug:       cleanup_delay = 5
Wed Oct  1 11:22:37 2008 : Debug:       max_requests = 1024
Wed Oct  1 11:22:37 2008 : Debug:       allow_core_dumps = no
Wed Oct  1 11:22:37 2008 : Debug:       pidfile = 
"/home/radius2.11/var/run/radiusd/radiusd.pid"
Wed Oct  1 11:22:37 2008 : Debug:       checkrad = 
"/home/radius2.11/sbin/checkrad"
Wed Oct  1 11:22:37 2008 : Debug:       debug_level = 0
Wed Oct  1 11:22:37 2008 : Debug:       proxy_requests = yes
Wed Oct  1 11:22:37 2008 : Debug:  log {
Wed Oct  1 11:22:37 2008 : Debug:       stripped_names = no
Wed Oct  1 11:22:37 2008 : Debug:       auth = no
Wed Oct  1 11:22:37 2008 : Debug:       auth_badpass = no
Wed Oct  1 11:22:37 2008 : Debug:       auth_goodpass = no
Wed Oct  1 11:22:37 2008 : Debug:  }
Wed Oct  1 11:22:37 2008 : Debug:  security {
Wed Oct  1 11:22:37 2008 : Debug:       max_attributes = 200
Wed Oct  1 11:22:37 2008 : Debug:       reject_delay = 1
Wed Oct  1 11:22:37 2008 : Debug:       status_server = yes
Wed Oct  1 11:22:37 2008 : Debug:  }
Wed Oct  1 11:22:37 2008 : Debug: }
Wed Oct  1 11:22:37 2008 : Debug:  client localhost {
Wed Oct  1 11:22:37 2008 : Debug:       ipaddr = 127.0.0.1
Wed Oct  1 11:22:37 2008 : Debug:       require_message_authenticator = no
Wed Oct  1 11:22:37 2008 : Debug:       secret = "testing123"
Wed Oct  1 11:22:37 2008 : Debug:       nastype = "other"
Wed Oct  1 11:22:37 2008 : Debug:  }
Wed Oct  1 11:22:37 2008 : Debug:  client 10.241.21.202 {
Wed Oct  1 11:22:37 2008 : Debug:       require_message_authenticator = no
Wed Oct  1 11:22:37 2008 : Debug:       secret = "testing123"
Wed Oct  1 11:22:37 2008 : Debug:       shortname = "winxp"
Wed Oct  1 11:22:37 2008 : Debug:       nastype = "other"
Wed Oct  1 11:22:37 2008 : Debug:  }
Wed Oct  1 11:22:37 2008 : Debug: radiusd: #### Loading Realms and Home 
Servers ####
Wed Oct  1 11:22:37 2008 : Debug:  proxy server {
Wed Oct  1 11:22:37 2008 : Debug:       retry_delay = 5
Wed Oct  1 11:22:37 2008 : Debug:       retry_count = 3
Wed Oct  1 11:22:37 2008 : Debug:       default_fallback = no
Wed Oct  1 11:22:37 2008 : Debug:       dead_time = 120
Wed Oct  1 11:22:37 2008 : Debug:       wake_all_if_all_dead = no
Wed Oct  1 11:22:37 2008 : Debug:  }
Wed Oct  1 11:22:37 2008 : Debug:  home_server localhost {
Wed Oct  1 11:22:37 2008 : Debug:       ipaddr = 127.0.0.1
Wed Oct  1 11:22:37 2008 : Debug:       port = 1812
Wed Oct  1 11:22:37 2008 : Debug:       type = "auth"
Wed Oct  1 11:22:37 2008 : Debug:       secret = "testing123"
Wed Oct  1 11:22:37 2008 : Debug:       response_window = 20
Wed Oct  1 11:22:37 2008 : Debug:       max_outstanding = 65536
Wed Oct  1 11:22:37 2008 : Debug:       zombie_period = 40
Wed Oct  1 11:22:37 2008 : Debug:       status_check = "status-server"
Wed Oct  1 11:22:37 2008 : Debug:       ping_interval = 30
Wed Oct  1 11:22:37 2008 : Debug:       check_interval = 30
Wed Oct  1 11:22:37 2008 : Debug:       num_answers_to_alive = 3
Wed Oct  1 11:22:37 2008 : Debug:       num_pings_to_alive = 3
Wed Oct  1 11:22:37 2008 : Debug:       revive_interval = 120
Wed Oct  1 11:22:37 2008 : Debug:       status_check_timeout = 4
Wed Oct  1 11:22:37 2008 : Debug:  }
Wed Oct  1 11:22:37 2008 : Debug:  home_server_pool my_auth_failover {
Wed Oct  1 11:22:37 2008 : Debug:       type = fail-over
Wed Oct  1 11:22:37 2008 : Debug:       home_server = localhost
Wed Oct  1 11:22:37 2008 : Debug:  }
Wed Oct  1 11:22:37 2008 : Debug:  realm example.com {
Wed Oct  1 11:22:37 2008 : Debug:       auth_pool = my_auth_failover
Wed Oct  1 11:22:37 2008 : Debug:  }
Wed Oct  1 11:22:37 2008 : Debug:  realm LOCAL {
Wed Oct  1 11:22:37 2008 : Debug:  }
Wed Oct  1 11:22:37 2008 : Debug: radiusd: #### Instantiating modules ####
Wed Oct  1 11:22:37 2008 : Debug:  instantiate {
Wed Oct  1 11:22:37 2008 : Debug:     (Loaded rlm_exec, checking if it's 
valid)
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to module rlm_exec
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating exec
Wed Oct  1 11:22:37 2008 : Debug:   exec {
Wed Oct  1 11:22:37 2008 : Debug:       wait = no
Wed Oct  1 11:22:37 2008 : Debug:       input_pairs = "request"
Wed Oct  1 11:22:37 2008 : Debug:       shell_escape = yes
Wed Oct  1 11:22:37 2008 : Debug:   }
Wed Oct  1 11:22:37 2008 : Debug:     (Loaded rlm_expr, checking if it's 
valid)
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to module rlm_expr
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating expr
Wed Oct  1 11:22:37 2008 : Debug:     (Loaded rlm_expiration, checking 
if it's valid)
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to module rlm_expiration
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating expiration
Wed Oct  1 11:22:37 2008 : Debug:   expiration {
Wed Oct  1 11:22:37 2008 : Debug:       reply-message = "Password Has 
Expired  "
Wed Oct  1 11:22:37 2008 : Debug:   }
Wed Oct  1 11:22:37 2008 : Debug:     (Loaded rlm_logintime, checking if 
it's valid)
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to module rlm_logintime
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating logintime
Wed Oct  1 11:22:37 2008 : Debug:   logintime {
Wed Oct  1 11:22:37 2008 : Debug:       reply-message = "You are calling 
outside your allowed timespan  "
Wed Oct  1 11:22:37 2008 : Debug:       minimum-timeout = 60
Wed Oct  1 11:22:37 2008 : Debug:   }
Wed Oct  1 11:22:37 2008 : Debug:  }
Wed Oct  1 11:22:37 2008 : Debug: radiusd: #### Loading Virtual Servers ####
Wed Oct  1 11:22:37 2008 : Debug: server inner-tunnel {
Wed Oct  1 11:22:37 2008 : Debug:  modules {
Wed Oct  1 11:22:37 2008 : Debug:  Module: Checking authenticate {...} 
for more modules to load
Wed Oct  1 11:22:37 2008 : Debug:     (Loaded rlm_pap, checking if it's 
valid)
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to module rlm_pap
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating pap
Wed Oct  1 11:22:37 2008 : Debug:   pap {
Wed Oct  1 11:22:37 2008 : Debug:       encryption_scheme = "auto"
Wed Oct  1 11:22:37 2008 : Debug:       auto_header = no
Wed Oct  1 11:22:37 2008 : Debug:   }
Wed Oct  1 11:22:37 2008 : Debug:     (Loaded rlm_chap, checking if it's 
valid)
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to module rlm_chap
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating chap
Wed Oct  1 11:22:37 2008 : Debug:     (Loaded rlm_mschap, checking if 
it's valid)
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to module rlm_mschap
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating mschap
Wed Oct  1 11:22:37 2008 : Debug:   mschap {
Wed Oct  1 11:22:37 2008 : Debug:       use_mppe = yes
Wed Oct  1 11:22:37 2008 : Debug:       require_encryption = no
Wed Oct  1 11:22:37 2008 : Debug:       require_strong = no
Wed Oct  1 11:22:37 2008 : Debug:       with_ntdomain_hack = no
Wed Oct  1 11:22:37 2008 : Debug:   }
Wed Oct  1 11:22:37 2008 : Debug:     (Loaded rlm_unix, checking if it's 
valid)
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to module rlm_unix
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating unix
Wed Oct  1 11:22:37 2008 : Debug:   unix {
Wed Oct  1 11:22:37 2008 : Debug:       radwtmp = 
"/home/radius2.11/var/log/radius/radwtmp"
Wed Oct  1 11:22:37 2008 : Debug:   }
Wed Oct  1 11:22:37 2008 : Debug:     (Loaded rlm_eap, checking if it's 
valid)
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to module rlm_eap
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating eap
Wed Oct  1 11:22:37 2008 : Debug:   eap {
Wed Oct  1 11:22:37 2008 : Debug:       default_eap_type = "md5"
Wed Oct  1 11:22:37 2008 : Debug:       timer_expire = 60
Wed Oct  1 11:22:37 2008 : Debug:       ignore_unknown_eap_types = no
Wed Oct  1 11:22:37 2008 : Debug:       cisco_accounting_username_bug = no
Wed Oct  1 11:22:37 2008 : Debug:       max_sessions = 2048
Wed Oct  1 11:22:37 2008 : Debug:   }
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to sub-module rlm_eap_md5
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating eap-md5
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to sub-module rlm_eap_leap
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating eap-leap
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to sub-module rlm_eap_gtc
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating eap-gtc
Wed Oct  1 11:22:37 2008 : Debug:    gtc {
Wed Oct  1 11:22:37 2008 : Debug:       challenge = "Password: "
Wed Oct  1 11:22:37 2008 : Debug:       auth_type = "PAP"
Wed Oct  1 11:22:37 2008 : Debug:    }
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to sub-module rlm_eap_tls
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating eap-tls
Wed Oct  1 11:22:37 2008 : Debug:    tls {
Wed Oct  1 11:22:37 2008 : Debug:       rsa_key_exchange = no
Wed Oct  1 11:22:37 2008 : Debug:       dh_key_exchange = yes
Wed Oct  1 11:22:37 2008 : Debug:       rsa_key_length = 512
Wed Oct  1 11:22:37 2008 : Debug:       dh_key_length = 512
Wed Oct  1 11:22:37 2008 : Debug:       verify_depth = 0
Wed Oct  1 11:22:37 2008 : Debug:       pem_file_type = yes
Wed Oct  1 11:22:37 2008 : Debug:       private_key_file = 
"/home/radius2.11/etc/raddb/certs/server.pem"
Wed Oct  1 11:22:37 2008 : Debug:       certificate_file = 
"/home/radius2.11/etc/raddb/certs/server.pem"
Wed Oct  1 11:22:37 2008 : Debug:       CA_file = 
"/home/radius2.11/etc/raddb/certs/ca.pem"
Wed Oct  1 11:22:37 2008 : Debug:       private_key_password = "whatever"
Wed Oct  1 11:22:37 2008 : Debug:       dh_file = 
"/home/radius2.11/etc/raddb/certs/dh"
Wed Oct  1 11:22:37 2008 : Debug:       random_file = 
"/home/radius2.11/etc/raddb/certs/random"
Wed Oct  1 11:22:37 2008 : Debug:       fragment_size = 1024
Wed Oct  1 11:22:37 2008 : Debug:       include_length = yes
Wed Oct  1 11:22:37 2008 : Debug:       check_crl = no
Wed Oct  1 11:22:37 2008 : Debug:       cipher_list = "DEFAULT"
Wed Oct  1 11:22:37 2008 : Debug:       make_cert_command = 
"/home/radius2.11/etc/raddb/certs/bootstrap"
Wed Oct  1 11:22:37 2008 : Debug:     cache {
Wed Oct  1 11:22:37 2008 : Debug:       enable = no
Wed Oct  1 11:22:37 2008 : Debug:       lifetime = 24
Wed Oct  1 11:22:37 2008 : Debug:       max_entries = 255
Wed Oct  1 11:22:37 2008 : Debug:     }
Wed Oct  1 11:22:37 2008 : Debug:    }
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to sub-module rlm_eap_ttls
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating eap-ttls
Wed Oct  1 11:22:37 2008 : Debug:    ttls {
Wed Oct  1 11:22:37 2008 : Debug:       default_eap_type = "md5"
Wed Oct  1 11:22:37 2008 : Debug:       copy_request_to_tunnel = no
Wed Oct  1 11:22:37 2008 : Debug:       use_tunneled_reply = no
Wed Oct  1 11:22:37 2008 : Debug:       virtual_server = "inner-tunnel"
Wed Oct  1 11:22:37 2008 : Debug:    }
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to sub-module rlm_eap_peap
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating eap-peap
Wed Oct  1 11:22:37 2008 : Debug:    peap {
Wed Oct  1 11:22:37 2008 : Debug:       default_eap_type = "mschapv2"
Wed Oct  1 11:22:37 2008 : Debug:       copy_request_to_tunnel = no
Wed Oct  1 11:22:37 2008 : Debug:       use_tunneled_reply = no
Wed Oct  1 11:22:37 2008 : Debug:       proxy_tunneled_request_as_eap = yes
Wed Oct  1 11:22:37 2008 : Debug:       virtual_server = "inner-tunnel"
Wed Oct  1 11:22:37 2008 : Debug:    }
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to sub-module 
rlm_eap_mschapv2
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating eap-mschapv2
Wed Oct  1 11:22:37 2008 : Debug:    mschapv2 {
Wed Oct  1 11:22:37 2008 : Debug:       with_ntdomain_hack = no
Wed Oct  1 11:22:37 2008 : Debug:    }
Wed Oct  1 11:22:37 2008 : Debug:  Module: Checking authorize {...} for 
more modules to load
Wed Oct  1 11:22:37 2008 : Debug:     (Loaded rlm_realm, checking if 
it's valid)
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to module rlm_realm
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating suffix
Wed Oct  1 11:22:37 2008 : Debug:   realm suffix {
Wed Oct  1 11:22:37 2008 : Debug:       format = "suffix"
Wed Oct  1 11:22:37 2008 : Debug:       delimiter = "@"
Wed Oct  1 11:22:37 2008 : Debug:       ignore_default = no
Wed Oct  1 11:22:37 2008 : Debug:       ignore_null = no
Wed Oct  1 11:22:37 2008 : Debug:   }
Wed Oct  1 11:22:37 2008 : Debug:     (Loaded rlm_files, checking if 
it's valid)
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to module rlm_files
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating files
Wed Oct  1 11:22:37 2008 : Debug:   files {
Wed Oct  1 11:22:37 2008 : Debug:       usersfile = 
"/home/radius2.11/etc/raddb/users"
Wed Oct  1 11:22:37 2008 : Debug:       acctusersfile = 
"/home/radius2.11/etc/raddb/acct_users"
Wed Oct  1 11:22:37 2008 : Debug:       preproxy_usersfile = 
"/home/radius2.11/etc/raddb/preproxy_users"
Wed Oct  1 11:22:37 2008 : Debug:       compat = "no"
Wed Oct  1 11:22:37 2008 : Debug:   }
Wed Oct  1 11:22:37 2008 : Debug:  Module: Checking session {...} for 
more modules to load
Wed Oct  1 11:22:37 2008 : Debug:     (Loaded rlm_radutmp, checking if 
it's valid)
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to module rlm_radutmp
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating radutmp
Wed Oct  1 11:22:37 2008 : Debug:   radutmp {
Wed Oct  1 11:22:37 2008 : Debug:       filename = 
"/home/radius2.11/var/log/radius/radutmp"
Wed Oct  1 11:22:37 2008 : Debug:       username = "%{User-Name}"
Wed Oct  1 11:22:37 2008 : Debug:       case_sensitive = yes
Wed Oct  1 11:22:37 2008 : Debug:       check_with_nas = yes
Wed Oct  1 11:22:37 2008 : Debug:       perm = 384
Wed Oct  1 11:22:37 2008 : Debug:       callerid = yes
Wed Oct  1 11:22:37 2008 : Debug:   }
Wed Oct  1 11:22:37 2008 : Debug:  Module: Checking post-proxy {...} for 
more modules to load
Wed Oct  1 11:22:37 2008 : Debug:  Module: Checking post-auth {...} for 
more modules to load
Wed Oct  1 11:22:37 2008 : Debug:     (Loaded rlm_attr_filter, checking 
if it's valid)
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to module rlm_attr_filter
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating 
attr_filter.access_reject
Wed Oct  1 11:22:37 2008 : Debug:   attr_filter attr_filter.access_reject {
Wed Oct  1 11:22:37 2008 : Debug:       attrsfile = 
"/home/radius2.11/etc/raddb/attrs.access_reject"
Wed Oct  1 11:22:37 2008 : Debug:       key = "%{User-Name}"
Wed Oct  1 11:22:37 2008 : Debug:   }
Wed Oct  1 11:22:37 2008 : Debug:  }
Wed Oct  1 11:22:37 2008 : Debug: }
Wed Oct  1 11:22:37 2008 : Debug:  modules {
Wed Oct  1 11:22:37 2008 : Debug:  Module: Checking authenticate {...} 
for more modules to load
Wed Oct  1 11:22:37 2008 : Debug:  Module: Checking authorize {...} for 
more modules to load
Wed Oct  1 11:22:37 2008 : Debug:     (Loaded rlm_preprocess, checking 
if it's valid)
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to module rlm_preprocess
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating preprocess
Wed Oct  1 11:22:37 2008 : Debug:   preprocess {
Wed Oct  1 11:22:37 2008 : Debug:       huntgroups = 
"/home/radius2.11/etc/raddb/huntgroups"
Wed Oct  1 11:22:37 2008 : Debug:       hints = 
"/home/radius2.11/etc/raddb/hints"
Wed Oct  1 11:22:37 2008 : Debug:       with_ascend_hack = no
Wed Oct  1 11:22:37 2008 : Debug:       ascend_channels_per_line = 23
Wed Oct  1 11:22:37 2008 : Debug:       with_ntdomain_hack = no
Wed Oct  1 11:22:37 2008 : Debug:       with_specialix_jetstream_hack = no
Wed Oct  1 11:22:37 2008 : Debug:       with_cisco_vsa_hack = no
Wed Oct  1 11:22:37 2008 : Debug:       with_alvarion_vsa_hack = no
Wed Oct  1 11:22:37 2008 : Debug:   }
Wed Oct  1 11:22:37 2008 : Debug:  Module: Checking preacct {...} for 
more modules to load
Wed Oct  1 11:22:37 2008 : Debug:     (Loaded rlm_acct_unique, checking 
if it's valid)
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to module rlm_acct_unique
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating acct_unique
Wed Oct  1 11:22:37 2008 : Debug:   acct_unique {
Wed Oct  1 11:22:37 2008 : Debug:       key = "User-Name, 
Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"
Wed Oct  1 11:22:37 2008 : Debug:   }
Wed Oct  1 11:22:37 2008 : Debug:  Module: Checking accounting {...} for 
more modules to load
Wed Oct  1 11:22:37 2008 : Debug:     (Loaded rlm_detail, checking if 
it's valid)
Wed Oct  1 11:22:37 2008 : Debug:  Module: Linked to module rlm_detail
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating detail
Wed Oct  1 11:22:37 2008 : Debug:   detail {
Wed Oct  1 11:22:37 2008 : Debug:       detailfile = 
"/home/radius2.11/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
Wed Oct  1 11:22:37 2008 : Debug:       header = "%t"
Wed Oct  1 11:22:37 2008 : Debug:       detailperm = 384
Wed Oct  1 11:22:37 2008 : Debug:       dirperm = 493
Wed Oct  1 11:22:37 2008 : Debug:       locking = no
Wed Oct  1 11:22:37 2008 : Debug:       log_packet_header = no
Wed Oct  1 11:22:37 2008 : Debug:   }
Wed Oct  1 11:22:37 2008 : Debug:  Module: Instantiating 
attr_filter.accounting_response
Wed Oct  1 11:22:37 2008 : Debug:   attr_filter 
attr_filter.accounting_response {
Wed Oct  1 11:22:37 2008 : Debug:       attrsfile = 
"/home/radius2.11/etc/raddb/attrs.accounting_response"
Wed Oct  1 11:22:37 2008 : Debug:       key = "%{User-Name}"
Wed Oct  1 11:22:37 2008 : Debug:   }
Wed Oct  1 11:22:37 2008 : Debug:  Module: Checking session {...} for 
more modules to load
Wed Oct  1 11:22:37 2008 : Debug:  Module: Checking post-proxy {...} for 
more modules to load
Wed Oct  1 11:22:37 2008 : Debug:  Module: Checking post-auth {...} for 
more modules to load
Wed Oct  1 11:22:37 2008 : Debug:  }
Wed Oct  1 11:22:37 2008 : Debug: radiusd: #### Opening IP addresses and 
Ports ####
Wed Oct  1 11:22:37 2008 : Debug: listen {
Wed Oct  1 11:22:37 2008 : Debug:       type = "auth"
Wed Oct  1 11:22:37 2008 : Debug:       ipaddr = *
Wed Oct  1 11:22:37 2008 : Debug:       port = 0
Wed Oct  1 11:22:37 2008 : Debug: }
Wed Oct  1 11:22:37 2008 : Debug: listen {
Wed Oct  1 11:22:37 2008 : Debug:       type = "acct"
Wed Oct  1 11:22:37 2008 : Debug:       ipaddr = *
Wed Oct  1 11:22:37 2008 : Debug:       port = 0
Wed Oct  1 11:22:37 2008 : Debug: }
Wed Oct  1 11:22:37 2008 : Debug: Listening on authentication address * 
port 1812
Wed Oct  1 11:22:37 2008 : Debug: Listening on accounting address * port 
1813
Wed Oct  1 11:22:37 2008 : Debug: Listening on proxy address * port 1814
Wed Oct  1 11:22:37 2008 : Debug: Ready to process requests.
rad_recv: Access-Request packet from host 10.241.21.202 port 4870, 
id=80, length=41
         User-Name = "a"
         User-Password = "a"
Wed Oct  1 11:22:43 2008 : Info: +- entering group authorize {...}
Wed Oct  1 11:22:43 2008 : Info: ++[preprocess] returns ok
Wed Oct  1 11:22:43 2008 : Info: ++[chap] returns noop
Wed Oct  1 11:22:43 2008 : Info: ++[mschap] returns noop
Wed Oct  1 11:22:43 2008 : Info: [suffix] No '@' in User-Name = "a", 
looking up realm NULL
Wed Oct  1 11:22:43 2008 : Info: [suffix] No such realm "NULL"
Wed Oct  1 11:22:43 2008 : Info: ++[suffix] returns noop
Wed Oct  1 11:22:43 2008 : Info: [eap] No EAP-Message, not doing EAP
Wed Oct  1 11:22:43 2008 : Info: ++[eap] returns noop
Wed Oct  1 11:22:43 2008 : Info: ++[unix] returns notfound
Wed Oct  1 11:22:43 2008 : Info: [files] users: Matched entry a at line 1
Wed Oct  1 11:22:43 2008 : Info: ++[files] returns ok
Wed Oct  1 11:22:43 2008 : Info: [expiration] Checking Expiration time: 
'10 Jan 2009'
Wed Oct  1 11:22:43 2008 : Info: [expiration] Account has expired
Wed Oct  1 11:22:43 2008 : Info: [expiration]   expand: Password Has 
Expired   -> Password Has Expired
Wed Oct  1 11:22:43 2008 : Info: ++[expiration] returns userlock
Wed Oct  1 11:22:43 2008 : Info: Using Post-Auth-Type Reject
Wed Oct  1 11:22:43 2008 : Info: +- entering group REJECT {...}
Wed Oct  1 11:22:43 2008 : Info: [attr_filter.access_reject]    expand: 
%{User-Name} -> a
Wed Oct  1 11:22:43 2008 : Debug:  attr_filter: Matched entry DEFAULT at 
line 11
Wed Oct  1 11:22:43 2008 : Info: ++[attr_filter.access_reject] returns 
updated
Wed Oct  1 11:22:43 2008 : Info: Delaying reject of request 0 for 1 seconds
Wed Oct  1 11:22:43 2008 : Debug: Going to the next request
Wed Oct  1 11:22:43 2008 : Debug: Waking up in 0.9 seconds.
Wed Oct  1 11:22:44 2008 : Info: Sending delayed reject for request 0
Sending Access-Reject of id 80 to 10.241.21.202 port 4870
         Reply-Message += "Password Has Expired\r\n"
Wed Oct  1 11:22:44 2008 : Debug: Waking up in 4.9 seconds.


Thanks,
Flamur



More information about the Freeradius-Users mailing list