Freeradius 2 doesn't start after upgrade to PFS 2.2
-
Can you run /path/to/radiusd/radiusd -X and see what it bombs out on?
-
[2.2.1-RELEASE][root@router.xxxxx.xxx]/: radiusd -X
radiusd: FreeRADIUS Version 2.2.6, for host amd64-portbld-freebsd10.1, built on Jan 28 2015 at 18:26:44
Copyright (C) 1999-2013 The FreeRADIUS server project and contributors.
There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
PARTICULAR PURPOSE.
You may redistribute copies of FreeRADIUS under the terms of the
GNU General Public License.
For more information about these matters, see the file named COPYRIGHT.
Starting - reading configuration files …
including configuration file /usr/local/etc/raddb/radiusd.conf
including configuration file /usr/local/etc/raddb/clients.conf
including files in directory /usr/local/etc/raddb/modules/
including configuration file /usr/local/etc/raddb/modules/wimax
including configuration file /usr/local/etc/raddb/modules/always
including configuration file /usr/local/etc/raddb/modules/attr_filter
including configuration file /usr/local/etc/raddb/modules/attr_rewrite
including configuration file /usr/local/etc/raddb/modules/cache
including configuration file /usr/local/etc/raddb/modules/chap
including configuration file /usr/local/etc/raddb/modules/checkval
including configuration file /usr/local/etc/raddb/modules/counter
including configuration file /usr/local/etc/raddb/modules/cui
including configuration file /usr/local/etc/raddb/modules/detail
including configuration file /usr/local/etc/raddb/modules/detail.example.com
including configuration file /usr/local/etc/raddb/modules/detail.log
including configuration file /usr/local/etc/raddb/modules/dhcp_sqlippool
including configuration file /usr/local/etc/raddb/sql/mysql/ippool-dhcp.conf
including configuration file /usr/local/etc/raddb/modules/digest
including configuration file /usr/local/etc/raddb/modules/dynamic_clients
including configuration file /usr/local/etc/raddb/modules/echo
including configuration file /usr/local/etc/raddb/modules/etc_group
including configuration file /usr/local/etc/raddb/modules/exec
including configuration file /usr/local/etc/raddb/modules/expiration
including configuration file /usr/local/etc/raddb/modules/expr
including configuration file /usr/local/etc/raddb/modules/files
including configuration file /usr/local/etc/raddb/modules/inner-eap
including configuration file /usr/local/etc/raddb/modules/ippool
including configuration file /usr/local/etc/raddb/modules/krb5
including configuration file /usr/local/etc/raddb/modules/ldap
including configuration file /usr/local/etc/raddb/modules/linelog
including configuration file /usr/local/etc/raddb/modules/otp
including configuration file /usr/local/etc/raddb/modules/logintime
including configuration file /usr/local/etc/raddb/modules/mac2ip
including configuration file /usr/local/etc/raddb/modules/mac2vlan
including configuration file /usr/local/etc/raddb/modules/mschap
including configuration file /usr/local/etc/raddb/modules/ntlm_auth
including configuration file /usr/local/etc/raddb/modules/opendirectory
including configuration file /usr/local/etc/raddb/modules/pam
including configuration file /usr/local/etc/raddb/modules/pap
including configuration file /usr/local/etc/raddb/modules/passwd
including configuration file /usr/local/etc/raddb/modules/perl
including configuration file /usr/local/etc/raddb/modules/policy
including configuration file /usr/local/etc/raddb/modules/preprocess
including configuration file /usr/local/etc/raddb/modules/radrelay
including configuration file /usr/local/etc/raddb/modules/radutmp
including configuration file /usr/local/etc/raddb/modules/realm
including configuration file /usr/local/etc/raddb/modules/redis
including configuration file /usr/local/etc/raddb/modules/rediswho
including configuration file /usr/local/etc/raddb/modules/replicate
including configuration file /usr/local/etc/raddb/modules/smbpasswd
including configuration file /usr/local/etc/raddb/modules/smsotp
including configuration file /usr/local/etc/raddb/modules/soh
including configuration file /usr/local/etc/raddb/modules/sql_log
including configuration file /usr/local/etc/raddb/modules/sqlcounter_expire_on_login
including configuration file /usr/local/etc/raddb/modules/sradutmp
including configuration file /usr/local/etc/raddb/modules/unix
including configuration file /usr/local/etc/raddb/modules/acct_unique
including configuration file /usr/local/etc/raddb/modules/motp
including configuration file /usr/local/etc/raddb/modules/datacounter_acct
including configuration file /usr/local/etc/raddb/eap.conf
including configuration file /usr/local/etc/raddb/policy.conf
including files in directory /usr/local/etc/raddb/sites-enabled/
including configuration file /usr/local/etc/raddb/sites-enabled/default
main {
allow_core_dumps = no
}
including dictionary file /usr/local/etc/raddb/dictionary
main {
name = "radiusd"
prefix = "/usr/pbi/freeradius-amd64"
localstatedir = "/var"
sbindir = "/usr/pbi/freeradius-amd64/sbin"
logdir = "/var/log"
run_dir = "/var/run"
radacctdir = "/var/log/radacct"
hostname_lookups = no
max_request_time = 30
cleanup_delay = 5
max_requests = 1024
pidfile = "/var/run/radiusd.pid"
checkrad = "/usr/pbi/freeradius-amd64/sbin/checkrad"
debug_level = 0
proxy_requests = yes
log {
stripped_names = no
auth = no
auth_badpass = no
auth_goodpass = no
msg_badpass = ""
msg_goodpass = ""
}
security {
max_attributes = 200
reject_delay = 1
status_server = no
allow_vulnerable_openssl = no
}
}
radiusd: #### Loading Realms and Home Servers ####
radiusd: #### Loading Clients ####
client AP1 {
ipaddr = 192.168.162.6
require_message_authenticator = no
secret = "3948fh83"
shortname = "AP1"
nastype = "other"
}
client AP2 {
ipaddr = 192.168.162.7
require_message_authenticator = no
secret = "3948fh83"
shortname = "AP2"
nastype = "other"
}
client def-router {
ipaddr = 192.168.162.1
require_message_authenticator = no
secret = "3470892"
shortname = "def-router"
nastype = "other"
}
radiusd: #### Instantiating modules ####
instantiate {
Module: Linked to module rlm_exec
Module: Instantiating module "exec" from file /usr/local/etc/raddb/modules/exec
exec {
wait = no
input_pairs = "request"
shell_escape = yes
timeout = 10
}
Module: Linked to module rlm_expr
Module: Instantiating module "expr" from file /usr/local/etc/raddb/modules/expr
Module: Linked to module rlm_counter
Module: Instantiating module "daily" from file /usr/local/etc/raddb/modules/counter
counter daily {
filename = "/var/log/radacct/timecounter/db.daily"
key = "User-Name"
reset = "daily"
count-attribute = "Acct-Session-Time"
counter-name = "Daily-Session-Time"
check-name = "Max-Daily-Session"
reply-name = "Session-Timeout"
cache-size = 5000
}
rlm_counter: Counter attribute Daily-Session-Time is number 11273
rlm_counter: Current Time: 1426685092 [2015-03-18 14:24:52], Next reset 1426719600 [2015-03-19 00:00:00]
Module: Instantiating module "weekly" from file /usr/local/etc/raddb/modules/counter
counter weekly {
filename = "/var/log/radacct/timecounter/db.weekly"
key = "User-Name"
reset = "weekly"
count-attribute = "Acct-Session-Time"
counter-name = "Weekly-Session-Time"
check-name = "Max-Weekly-Session"
reply-name = "Session-Timeout"
cache-size = 5000
}
rlm_counter: Counter attribute Weekly-Session-Time is number 11275
rlm_counter: Current Time: 1426685092 [2015-03-18 14:24:52], Next reset 1426978800 [2015-03-22 00:00:00]
Module: Instantiating module "monthly" from file /usr/local/etc/raddb/modules/counter
counter monthly {
filename = "/var/log/radacct/timecounter/db.monthly"
key = "User-Name"
reset = "monthly"
count-attribute = "Acct-Session-Time"
counter-name = "Monthly-Session-Time"
check-name = "Max-Monthly-Session"
reply-name = "Session-Timeout"
cache-size = 5000
}
rlm_counter: Counter attribute Monthly-Session-Time is number 11277
rlm_counter: Current Time: 1426685092 [2015-03-18 14:24:52], Next reset 1427842800 [2015-04-01 01:00:00]
Module: Instantiating module "forever" from file /usr/local/etc/raddb/modules/counter
counter forever {
filename = "/var/log/radacct/timecounter/db.forever"
key = "User-Name"
reset = "never"
count-attribute = "Acct-Session-Time"
counter-name = "Forever-Session-Time"
check-name = "Max-Forever-Session"
reply-name = "Session-Timeout"
cache-size = 5000
}
rlm_counter: Counter attribute Forever-Session-Time is number 11279
rlm_counter: Current Time: 1426685092 [2015-03-18 14:24:52], Next reset 0 [2015-03-18 14:00:00]
Module: Linked to module rlm_expiration
Module: Instantiating module "expiration" from file /usr/local/etc/raddb/modules/expiration
expiration {
reply-message = "Password Has Expired "
}
Module: Linked to module rlm_logintime
Module: Instantiating module "logintime" from file /usr/local/etc/raddb/modules/logintime
logintime {
reply-message = "You are calling outside your allowed timespan "
minimum-timeout = 60
}
}
radiusd: #### Loading Virtual Servers ####
server { # from file h▒▒▒
modules {
Module: Creating Auth-Type = MOTP
Module: Creating Auth-Type = digest
Module: Creating Autz-Type = Status-Server
Module: Creating Acct-Type = Status-Server
Module: Creating Post-Auth-Type = REJECT
Module: Checking authenticate {…} for more modules to load
Module: Linked to module rlm_pap
Module: Instantiating module "pap" from file /usr/local/etc/raddb/modules/pap
pap {
encryption_scheme = "auto"
auto_header = no
}
Module: Linked to module rlm_chap
Module: Instantiating module "chap" from file /usr/local/etc/raddb/modules/chap
Module: Linked to module rlm_mschap
Module: Instantiating module "mschap" from file /usr/local/etc/raddb/modules/mschap
mschap {
use_mppe = yes
require_encryption = no
require_strong = no
with_ntdomain_hack = yes
allow_retry = yes
}
Module: Instantiating module "motp" from file /usr/local/etc/raddb/modules/motp
exec motp {
wait = yes
program = " /usr/pbi/freeradius-amd64/local/etc/raddb/scripts/otpverify.sh %{request:User-Name} %{request:User-Password} %{reply:MOTP-Init-Secret} %{reply:MOTP-PIN} %{reply:MOTP-Offset}"
input_pairs = "request"
shell_escape = yes
}
Module: Linked to module rlm_digest
Module: Instantiating module "digest" from file /usr/local/etc/raddb/modules/digest
Module: Linked to module rlm_unix
Module: Instantiating module "unix" from file /usr/local/etc/raddb/modules/unix
unix {
radwtmp = "/var/log/radwtmp"
}
Module: Linked to module rlm_eap
Module: Instantiating module "eap" from file /usr/local/etc/raddb/eap.conf
eap {
default_eap_type = "peap"
timer_expire = 60
ignore_unknown_eap_types = no
cisco_accounting_username_bug = no
max_sessions = 4096
}
Module: Linked to sub-module rlm_eap_tls
Module: Instantiating eap-tls
tls {
rsa_key_exchange = no
dh_key_exchange = yes
rsa_key_length = 512
dh_key_length = 512
verify_depth = 0
CA_path = "/usr/local/etc/raddb/certs"
pem_file_type = yes
private_key_file = "/usr/local/etc/raddb/certs/server_key.pem"
certificate_file = "/usr/local/etc/raddb/certs/server_cert.pem"
CA_file = "/usr/local/etc/raddb/certs/ca_cert.pem"
private_key_password = "xxxxx"
dh_file = "/usr/local/etc/raddb/certs/dh"
random_file = "/usr/local/etc/raddb/certs/random"
fragment_size = 1024
include_length = yes
check_crl = yes
cipher_list = "DEFAULT"
ecdh_curve = "prime256v1"
cache {
enable = no
lifetime = 24
max_entries = 255
}
verify {
}
ocsp {
enable = no
override_cert_url = no
url = "http://127.0.0.1/ocsp/"
use_nonce = yes
timeout = 0
softfail = no
}
}
Module: Linked to sub-module rlm_eap_ttls
Module: Instantiating eap-ttls
ttls {
default_eap_type = "md5"
copy_request_to_tunnel = no
use_tunneled_reply = no
include_length = yes
}
Module: Linked to sub-module rlm_eap_peap
Module: Instantiating eap-peap
peap {
default_eap_type = "mschapv2"
copy_request_to_tunnel = no
use_tunneled_reply = no
proxy_tunneled_request_as_eap = yes
soh = no
}
Module: Linked to sub-module rlm_eap_mschapv2
Module: Instantiating eap-mschapv2
mschapv2 {
with_ntdomain_hack = no
send_error = no
}
Module: Checking authorize {...} for more modules to load
Module: Linked to module rlm_preprocess
Module: Instantiating module "preprocess" from file /usr/local/etc/raddb/modules/preprocess
preprocess {
huntgroups = "/usr/local/etc/raddb/huntgroups"
hints = "/usr/local/etc/raddb/hints"
with_ascend_hack = no
ascend_channels_per_line = 23
with_ntdomain_hack = no
with_specialix_jetstream_hack = no
with_cisco_vsa_hack = no
with_alvarion_vsa_hack = no
}
reading pairlist file /usr/local/etc/raddb/huntgroups
reading pairlist file /usr/local/etc/raddb/hints
Module: Linked to module rlm_realm
Module: Instantiating module "suffix" from file /usr/local/etc/raddb/modules/realm
realm suffix {
format = "suffix"
delimiter = "@"
ignore_default = no
ignore_null = yes
}
Module: Instantiating module "ntdomain" from file /usr/local/etc/raddb/modules/realm
realm ntdomain {
format = "prefix"
delimiter = ""
ignore_default = no
ignore_null = yes
}
Module: Linked to module rlm_files
Module: Instantiating module "files" from file /usr/local/etc/raddb/modules/files
files {
usersfile = "/usr/local/etc/raddb/users"
acctusersfile = "/usr/local/etc/raddb/acct_users"
preproxy_usersfile = "/usr/local/etc/raddb/preproxy_users"
compat = "no"
}
reading pairlist file /usr/local/etc/raddb/users
reading pairlist file /usr/local/etc/raddb/acct_users
reading pairlist file /usr/local/etc/raddb/preproxy_users
Module: Linked to module rlm_checkval
Module: Instantiating module "checkval" from file /usr/local/etc/raddb/modules/checkval
checkval {
item-name = "Calling-Station-Id"
check-name = "Calling-Station-Id"
data-type = "string"
notfound-reject = no
}
rlm_checkval: Registered name Calling-Station-Id for attribute 31
Module: Checking preacct {...} for more modules to load
Module: Linked to module rlm_acct_unique
Module: Instantiating module "acct_unique" from file /usr/local/etc/raddb/modules/acct_unique
acct_unique {
key = "User-Name, Acct-Session-Id, NAS-IP-Address, NAS-Identifier, NAS-Port"
}
Module: Checking accounting {...} for more modules to load
Module: Linked to module rlm_detail
Module: Instantiating module "detail" from file /usr/local/etc/raddb/modules/detail
detail {
detailfile = "/var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d"
header = "%t"
detailperm = 384
dirperm = 493
locking = no
log_packet_header = no
}
Module: Instantiating module "datacounterdaily" from file /usr/local/etc/raddb/modules/datacounter_acct
exec datacounterdaily {
wait = yes
program = "/bin/sh /usr/pbi/freeradius-amd64/local/etc/raddb/scripts/datacounter_acct.sh %{request:User-Name} daily %{request:Acct-Input-Octets} %{request:Acct-Output-Octets}"
input_pairs = "request"
shell_escape = yes
}
Module: Instantiating module "datacounterweekly" from file /usr/local/etc/raddb/modules/datacounter_acct
exec datacounterweekly {
wait = yes
program = "/bin/sh /usr/pbi/freeradius-amd64/local/etc/raddb/scripts/datacounter_acct.sh %{request:User-Name} weekly %{request:Acct-Input-Octets} %{request:Acct-Output-Octets}"
input_pairs = "request"
shell_escape = yes
}
Module: Instantiating module "datacountermonthly" from file /usr/local/etc/raddb/modules/datacounter_acct
exec datacountermonthly {
wait = yes
program = "/bin/sh /usr/pbi/freeradius-amd64/local/etc/raddb/scripts/datacounter_acct.sh %{request:User-Name} monthly %{request:Acct-Input-Octets} %{request:Acct-Output-Octets}"
input_pairs = "request"
shell_escape = yes
}
Module: Instantiating module "datacounterforever" from file /usr/local/etc/raddb/modules/datacounter_acct
exec datacounterforever {
wait = yes
program = "/bin/sh /usr/pbi/freeradius-amd64/local/etc/raddb/scripts/datacounter_acct.sh %{request:User-Name} forever %{request:Acct-Input-Octets} %{request:Acct-Output-Octets}"
input_pairs = "request"
shell_escape = yes
}
Module: Linked to module rlm_radutmp
Module: Instantiating module "radutmp" from file /usr/local/etc/raddb/modules/radutmp
radutmp {
filename = "/var/log/radutmp"
username = "%{User-Name}"
case_sensitive = yes
check_with_nas = yes
perm = 384
callerid = yes
}
Module: Linked to module rlm_attr_filter
Module: Instantiating module "attr_filter.accounting_response" from file /usr/local/etc/raddb/modules/attr_filter
attr_filter attr_filter.accounting_response {
attrsfile = "/usr/local/etc/raddb/attrs.accounting_response"
key = "%{User-Name}"
relaxed = no
}
reading pairlist file /usr/local/etc/raddb/attrs.accounting_response
Module: Checking session {...} for more modules to load
Module: Checking pre-proxy {...} for more modules to load
Module: Instantiating module "attr_filter.pre-proxy" from file /usr/local/etc/raddb/modules/attr_filter
attr_filter attr_filter.pre-proxy {
attrsfile = "/usr/local/etc/raddb/attrs.pre-proxy"
key = "%{Realm}"
relaxed = no
}
reading pairlist file /usr/local/etc/raddb/attrs.pre-proxy
Module: Checking post-proxy {...} for more modules to load
Module: Instantiating module "attr_filter.post-proxy" from file /usr/local/etc/raddb/modules/attr_filter
attr_filter attr_filter.post-proxy {
attrsfile = "/usr/local/etc/raddb/attrs"
key = "%{Realm}"
relaxed = no
}
reading pairlist file /usr/local/etc/raddb/attrs
Module: Checking post-auth {...} for more modules to load
Module: Instantiating module "attr_filter.access_reject" from file /usr/local/etc/raddb/modules/attr_filter
attr_filter attr_filter.access_reject {
attrsfile = "/usr/local/etc/raddb/attrs.access_reject"
key = "%{User-Name}"
relaxed = no
}
reading pairlist file /usr/local/etc/raddb/attrs.access_reject
} # modules
} # server
radiusd: #### Opening IP addresses and Ports ####
listen {
type = "auth"
ipaddr = 192.168.162.1
port = 1812
}
listen {
type = "acct"
ipaddr = 192.168.162.1
port = 1813
}
Listening on authentication address 192.168.162.1 port 1812
Listening on accounting address 192.168.162.1 port 1813
Listening on proxy address 192.168.162.1 port 1814
Ready to process requests.
rad_recv: Accounting-Request packet from host 192.168.162.7 port 36188, id=198, length=167
Acct-Session-Id = "00000014-00000052"
Acct-Status-Type = Start
Acct-Authentic = RADIUS
User-Name = "xxxxx"
NAS-IP-Address = 192.168.162.7
NAS-Identifier = "24a43cb09d24"
NAS-Port = 0
Called-Station-Id = "2A-A4-3C-B2-9D-24:www.xxxxx.xxx"
Calling-Station-Id = "F4-F1-E1-78-25-72"
NAS-Port-Type = Wireless-802.11
Connect-Info = "CONNECT 0Mbps 802.11b"Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default
+group preacct {
++[preprocess] = ok
++update request {
expand: %{Acct-Session-Time} ->
… expanding second conditional
expand: %{Acct-Delay-Time} ->
... expanding second conditional
expand: %l - %{%{Acct-Session-Time}:-0} - %{%{Acct-Delay-Time}:-0} -> 1426685114 - 0 - 0
expand: %{expr: %l - %{%{Acct-Session-Time}:-0} - %{%{Acct-Delay-Time}:-0}} -> 1426685114
++} # update request = noop
[acct_unique] Hashing 'NAS-Port = 0,NAS-Identifier = "24a43cb09d24",NAS-IP-Address = 192.168.162.7,Acct-Session-Id = "00000014-00000052",User-Name = "xxxxxx"'
[acct_unique] Acct-Unique-Session-ID = "4f292197fd2cce30".
++[acct_unique] = ok
[suffix] No '@' in User-Name = "xxxxx", skipping NULL due to config.
++[suffix] = noop
[ntdomain] No '' in User-Name = "xxxxx", skipping NULL due to config.
++[ntdomain] = noop
++[files] = noop
+} # group preacct = okExecuting section accounting from file /usr/local/etc/raddb/sites-enabled/default
+group accounting {
[detail] expand: %{Packet-Src-IP-Address} -> 192.168.162.7
[detail] expand: /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d -> /var/log/radacct/192.168.162.7/detail-20150318
[detail] /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /var/log/radacct/192.168.162.7/detail-20150318
[detail] expand: %t -> Wed Mar 18 14:25:14 2015
++[detail] = ok
rlm_counter: We only run on Accounting-Stop packets.
++[daily] = noop
rlm_counter: We only run on Accounting-Stop packets.
++[weekly] = noop
rlm_counter: We only run on Accounting-Stop packets.
++[monthly] = noop
rlm_counter: We only run on Accounting-Stop packets.
++[forever] = noop
++? if ((request:Acct-Status-Type == Stop) || (request:Acct-Status-Type == Interim-Update))
?? Evaluating (request:Acct-Status-Type == Stop) -> FALSE
?? Evaluating (request:Acct-Status-Type == Interim-Update) -> FALSE
++? if ((request:Acct-Status-Type == Stop) || (request:Acct-Status-Type == Interim-Update)) -> FALSE
++[unix] = ok
[radutmp] expand: /var/log/radutmp -> /var/log/radutmp
[radutmp] expand: %{User-Name} -> xxxxx
++[radutmp] = ok
++[exec] = noop
[attr_filter.accounting_response] expand: %{User-Name} -> xxxxx
attr_filter: Matched entry DEFAULT at line 12
++[attr_filter.accounting_response] = updated
+} # group accounting = updated
Sending Accounting-Response of id 198 to 192.168.162.7 port 36188
Finished request 0.
Cleaning up request 0 ID 198 with timestamp +22
Going to the next request
Ready to process requests.
rad_recv: Accounting-Request packet from host 192.168.162.7 port 36188, id=197, length=209
Acct-Session-Id = "00000014-00000050"
Acct-Status-Type = Stop
Acct-Authentic = RADIUS
User-Name = "xxxxx"
NAS-IP-Address = 192.168.162.7
NAS-Identifier = "24a43cb09d24"
NAS-Port = 0
Called-Station-Id = "2A-A4-3C-B2-9D-24:www.xxxxx.xxx"
Calling-Station-Id = "F4-F1-E1-78-25-72"
NAS-Port-Type = Wireless-802.11
Connect-Info = "CONNECT 0Mbps 802.11b"
Acct-Session-Time = 37470
Acct-Input-Packets = 74428
Acct-Output-Packets = 215628
Acct-Input-Octets = 6889347
Acct-Output-Octets = 309713911
Event-Timestamp = "Mar 18 2015 14:24:30 CET"
Acct-Terminate-Cause = User-RequestExecuting section preacct from file /usr/local/etc/raddb/sites-enabled/default
+group preacct {
++[preprocess] = ok
++update request {
expand: %{Acct-Session-Time} -> 37470
expand: %{Acct-Delay-Time} ->
… expanding second conditional
expand: %l - %{%{Acct-Session-Time}:-0} - %{%{Acct-Delay-Time}:-0} -> 1426685114 - 37470 - 0
expand: %{expr: %l - %{%{Acct-Session-Time}:-0} - %{%{Acct-Delay-Time}:-0}} -> 1426647644
++} # update request = noop
[acct_unique] Hashing 'NAS-Port = 0,NAS-Identifier = "24a43cb09d24",NAS-IP-Address = 192.168.162.7,Acct-Session-Id = "00000014-00000050",User-Name = "xxxxx"'
[acct_unique] Acct-Unique-Session-ID = "dd1874c05f137518".
++[acct_unique] = ok
[suffix] No '@' in User-Name = "xxxxx", skipping NULL due to config.
++[suffix] = noop
[ntdomain] No '' in User-Name = "xxxxx", skipping NULL due to config.
++[ntdomain] = noop
++[files] = noop
+} # group preacct = okExecuting section accounting from file /usr/local/etc/raddb/sites-enabled/default
+group accounting {
[detail] expand: %{Packet-Src-IP-Address} -> 192.168.162.7
[detail] expand: /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d -> /var/log/radacct/192.168.162.7/detail-20150318
[detail] /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /var/log/radacct/192.168.162.7/detail-20150318
[detail] expand: %t -> Wed Mar 18 14:25:14 2015
++[detail] = ok
rlm_counter: Packet Unique ID = 'dd1874c05f137518'
rlm_counter: Searching the database for key 'xxxxx'
rlm_counter: Could not find the requested key in the database.
rlm_counter: User=xxxxx, New Counter=860.
rlm_counter: Storing new value in database.
rlm_counter: New value stored successfully.
++[daily] = ok
rlm_counter: Packet Unique ID = 'dd1874c05f137518'
rlm_counter: Searching the database for key 'xxxxx'
rlm_counter: Could not find the requested key in the database.
rlm_counter: User=xxxxx, New Counter=860.
rlm_counter: Storing new value in database.
rlm_counter: New value stored successfully.
++[weekly] = ok
rlm_counter: Packet Unique ID = 'dd1874c05f137518'
rlm_counter: Searching the database for key 'xxxxx'
rlm_counter: Could not find the requested key in the database.
rlm_counter: User=xxxxx, New Counter=860.
rlm_counter: Storing new value in database.
rlm_counter: New value stored successfully.
++[monthly] = ok
rlm_counter: Packet Unique ID = 'dd1874c05f137518'
rlm_counter: Searching the database for key 'xxxxx'
rlm_counter: Could not find the requested key in the database.
rlm_counter: User=xxxxx, New Counter=860.
rlm_counter: Storing new value in database.
rlm_counter: New value stored successfully.
++[forever] = ok
++? if ((request:Acct-Status-Type == Stop) || (request:Acct-Status-Type == Interim-Update))
?? Evaluating (request:Acct-Status-Type == Stop) -> TRUE
?? Skipping (request:Acct-Status-Type == Interim-Update)
++? if ((request:Acct-Status-Type == Stop) || (request:Acct-Status-Type == Interim-Update)) -> TRUE
++if ((request:Acct-Status-Type == Stop) || (request:Acct-Status-Type == Interim-Update)) {
[datacounterdaily] expand: %{request:User-Name} -> xxxxx
[datacounterdaily] expand: %{request:Acct-Input-Octets} -> 6889347
[datacounterdaily] expand: %{request:Acct-Output-Octets} -> 309713911
Exec output:
[datacounterdaily] Exec: program returned: 0
+++[datacounterdaily] = ok
[datacounterweekly] expand: %{request:User-Name} -> xxxxx
[datacounterweekly] expand: %{request:Acct-Input-Octets} -> 6889347
[datacounterweekly] expand: %{request:Acct-Output-Octets} -> 309713911
Exec output:
[datacounterweekly] Exec: program returned: 0
+++[datacounterweekly] = ok
[datacountermonthly] expand: %{request:User-Name} -> xxxxx
[datacountermonthly] expand: %{request:Acct-Input-Octets} -> 6889347
[datacountermonthly] expand: %{request:Acct-Output-Octets} -> 309713911
Exec output:
[datacountermonthly] Exec: program returned: 0
+++[datacountermonthly] = ok
[datacounterforever] expand: %{request:User-Name} -> xxxxx
[datacounterforever] expand: %{request:Acct-Input-Octets} -> 6889347
[datacounterforever] expand: %{request:Acct-Output-Octets} -> 309713911
Exec output:
[datacounterforever] Exec: program returned: 0
+++[datacounterforever] = ok
++} # if ((request:Acct-Status-Type == Stop) || (request:Acct-Status-Type == Interim-Update)) = ok
++[unix] = ok
[radutmp] expand: /var/log/radutmp -> /var/log/radutmp
[radutmp] expand: %{User-Name} -> xxxxx
rlm_radutmp: Logout entry for NAS AP2 port 0 has wrong ID
++[radutmp] = ok
++[exec] = noop
[attr_filter.accounting_response] expand: %{User-Name} -> xxxxx
attr_filter: Matched entry DEFAULT at line 12
++[attr_filter.accounting_response] = updated
+} # group accounting = updated
Sending Accounting-Response of id 197 to 192.168.162.7 port 36188
Finished request 1.
Cleaning up request 1 ID 197 with timestamp +22
Going to the next request
Ready to process requests. -
Going to the next request
Ready to process requests.Looks like it starts to me.
-
Yes it did and it does. Wen I (re)start the PFS box Freeradius is not starting. I have to click the save button then it starts right away. I don't have to change any of the settings just click the save button in the settings UI is enough to start Freeradius but it doesn't start after a reboot of the system. Wen I stop freeradius in the PFS web GUI and start it on the ssh command line with radiusd -X it also runs normal.
See https://forum.pfsense.org/index.php?topic=87441.msg480196#msg480196
and https://forum.pfsense.org/index.php?topic=87441.msg487188#msg487188 -
After restart Pfsense 2.2.1 freeradius not starting. If button SAVE on Services:FreeRADIUS: Interfaces or Services:FreeRADIUS: Setting (WebGui) then Starting. How to solve the automatic start? Reinstall/Uninstall does not solve the problem, if there is a reboot.
-
i think it might be best to create a bugreport for this.
instead of clicking "save' , have you tried restarting the service manually ? (status–>services)If that works, then you might be able to get it running automatically by temporarily installing the "service watchdog" package and having it monitor the freeradius service.
-
Are these full installs or nanobsd installs that are having this issue?
I can reproduce that same error message by deliberately corrupting db.daily file, but once I do that saving FreeRADIUS config pages does not solve the problem. Are you guys deleting the file before saving settings?
-
Full symmetric multiprocessing kernel install.
In my case, it is several months between the db.daily corruptions.I delete the file and do not touch any settings.
-
@G.D.:
Full symmetric multiprocessing kernel install.
In my case, it is several months between the db.daily corruptions.I delete the file and do not touch any settings.
That's interesting, so it does not happen every time you restart FreeRADIUS, but sometimes. Do you use 'Amount of Time' feature under Users tab?
It might help if someone uploaded corrupt db.daily file here. -
That is another user that has it happening on every restart.
In my case it is very long time between corruptions. Though I have very few restarts.I can tell you that in my case the corrupted db.daily is smaller than a good one.
Corrupted: 16 KiB
Good: 64 KiBI do not use the "Amount of Time" feature.
-
All counter files on my system are 128 KiB. Can you upload your good file, I will compare the two. I have been running FreeRADIUS package since 2.0 RC days and never experienced this issue.
-
With me the problem is mysql56, freeradius2 can´t start after boot but works ok manually starting service after boot.
radiusd[84593]: rlm_sql_mysql: Couldn't connect socket to MySQL server radius@localhost:radius
I´m looking for for a way to delay freeradius2 service to start, I think in this way mysql will be ready for new connections before freeradius starts.
-
New version of FreeRADIUS package 1.6.11 fixes the issue of multiple radiusd instances being launched (see: https://redmine.pfsense.org/issues/4337). It is a long shot that that will resolve your problem, but please upgrade and report back. You do need to remove/install package rather than reinstall for the changes to appear on your system. If the update is installed correctly you should see below lines in /usr/local/etc/rc.d/radiusd.sh
... rc_start() { SERVICENAME="radiusd" LOCKFILE="/tmp/${SERVICENAME}_start.lock" PIDFILE="/var/run/${SERVICENAME}.pid" ...
-
FreeRadius 2.2.6_3 pkg v1.6.11 Pfsense 2.2.1. remove/install package. The problem is not solved. How to remove a second copy of the program (The FreeRADIUS daemon)? After removal pkg it remains in line "service"
Log:
rlm_counter: Failed to open file /var/log/radacct/timecounter/db.daily: No such file or directory
radiusd[88428]: /usr/local/etc/raddb/modules/counter[71]: Instantiation failed for module "daily"/usr/local/etc/rc.d/radiusd.sh –>
....
rc_start() {
SERVICENAME="radiusd"
LOCKFILE="/tmp/${SERVICENAME}_start.lock"
PIDFILE="/var/run/${SERVICENAME}.pid"
....
-
Removing the package does not remove "/var/log/radacct/timecounter/db.daily" so delete the file manually and try to start FreeRADIUS.
-
Here also installed the update and rebooted and after that powered off the box and restarted but in both restarts the problem is not solved.
-
Can't reproduce this issue, so unless you guys can post additional info that might help in identifying this problem, this is not going get solved.
As a work around you can probably modify startup script '/usr/local/etc/rc.d/radiusd.sh' to remove corrupt file before every start.
-
Dears,
The problem appeared only when I do restore a full backup & the box reboot & re-installing the installed packages…I have tried all work around here with no luck !
in the console it's sayingStarting package freeradius2...done. Starting /usr/local/etc/rc.d/radius.sh...done.
but the service is not started & in the log I can find this:
Apr 20 02:58:32 php-fpm[245]: /rc.start_packages: Restarting/Starting all packages. Apr 20 02:58:32 php-fpm[245]: /rc.start_packages: The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?' Apr 20 02:58:32 php-fpm[245]: /rc.start_packages: The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?' Apr 20 02:58:32 php-fpm[245]: /rc.start_packages: The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?' Apr 20 02:58:32 php-fpm[245]: /rc.start_packages: The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?' Apr 20 02:58:32 php-fpm[245]: /rc.start_packages: The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?' Apr 20 02:58:32 php-fpm[245]: /rc.start_packages: The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?' Apr 20 02:58:32 php-fpm[245]: /rc.start_packages: The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?'
Seems like the box try to stop the service instead of starting it !!!
-
I 've same problem and I can't resolve it :-\ :(
-
I have a fresh pfsense install… with only freeradius & got the error only when restoring the all backup file & the system reboot & reinstalling the packages again...
SOLVED after installing any other package (i.e. squid3 or dansguardian or any other),
if I remove those packages… the problem retains !!! it must have another package installed to start automatically :D :D
-
For my system with regular install (not NanoBSD) and memory file system for /tmp and /var I found a workaround that worked for me in https://forum.pfsense.org/index.php?topic=92636.0.
Still I believe that the problem described is a bug in pfsense/freeradius, which in my case was first introduced when upgrading from 2.2 to 2.2.1 (occasionally no service start at (re)boot). It became even worse (never start at (re)boot) when upgrading to 2.2.2. Note that the in the original clean install of 2.2 freeradius worked flawlessly.
-
Hi;
I experience the exact same issue with a fresh install of pfSense 2.2.2 and freeradius2 1.6.12. Well, not exactly fresh install: I did have to upgrade from pfSense 2.1 as 2.2 does not install correctly on soekris board 6501.The setup is basic with only a connection from RADIUS to a LDAP Active Directory, nothing else installed or configured behond your typically home firewall setup. Service will only start if I save a file on the GUI (no changes necessary) or start manually from command line as described in this post. I notice this now so I have nothing yet to provide in addition to what was already posted.
I'll use the mentioned work around at https://forum.pfsense.org/index.php?topic=92636.0 for now as I need to move on to other priorities but willing to help if some more knowledgeable people can provide pointers or things to try. As mentioned, starting in debug mode provides no additional clue as start-up manually works flawlessly. Errors in system logs are already provided I those are the ones I see.
-
We were struggling with the same problem, but on a fresh, pristine 2.2.4 on a standar PC
2.2.4-RELEASE (amd64)
built on Sat Jul 25 19:57:37 CDT 2015
FreeBSD 10.1-RELEASE-p15So far we have found this strange behavior on logs as shown on snapshot1
The server is stopping the radius servce instead of starting it up at the boot process.The logs shown was taken on a clean boot so we're sure there is some error on php-fm rc.start process for FreeRadius
By now the workaround was to install Watchdog package and mark FreeRadius for monitor and start up when found stopped or crashed. It's usefull for other purposes :P
-
After looking at the code, it seems that it is the way the package is handling a resync. During a resync it is restarting the service about 9 times as bg calls and confusing the service.
I fixed mine by modifying the /usr/local/etc/rc.d/radius.sh so that it did not do a restart unless the service was already running.
#!/bin/sh # This file was automatically generated # by the pfSense service handler. SERVICENAME="radiusd" PIDFILE="/var/run/${SERVICENAME}.pid" rc_start() { LOCKFILE="/tmp/${SERVICENAME}_start.lock" # prevent this part of script from running in parallel if ( set -o noclobber; echo "$$" > "$LOCKFILE") 2> /dev/null; then # make sure lock file is removed even if script is terminated trap 'rm -f "$LOCKFILE"; exit $?' INT TERM EXIT /usr/pbi/freeradius-amd64/local/etc/rc.d/radiusd onestart # try to wait until the service starts if [ ! -f "$PIDFILE" ]; then echo "$SERVICENAME.sh: PID file was not found" for i in 1 2 3 4 5; do if [ -f "$PIDFILE" ]; then echo "$SERVICENAME.sh: Service started PID: `cat $PIDFILE`" break else echo "$SERVICENAME.sh: Waiting 0.5 seconds" sleep 0.5 fi done else echo "$SERVICENAME.sh: Service running PID: `cat $PIDFILE`" fi rm -f "$LOCKFILE" trap - INT TERM EXIT else echo "$SERVICENAME.sh: Cannot continue at this moment, this script is already trying to start service PID: $(cat $LOCKFILE)" fi } rc_stop() { if [ ! -f "$PIDFILE" ]; then echo "$SERVICENAME.sh: PID file was not found" else /usr/pbi/freeradius-amd64/local/etc/rc.d/radiusd onestop fi } rc_restart() { if [ ! -f "$PIDFILE" ]; then echo "$SERVICENAME.sh: PID file was not found" else /usr/pbi/freeradius-amd64/local/etc/rc.d/radiusd onestop # try to wait until the service starts for i in 1 2 3 4 5; do if [ ! -f "$PIDFILE" ]; then echo "$SERVICENAME.sh: Service Stopped" rc_start break else echo "$SERVICENAME.sh: Waiting 0.5 seconds to stop" sleep 0.5 fi done fi } case $1 in start) rc_start ;; stop) rc_stop ;; restart) rc_restart ;; esac
And then to clean up the boot process, I then added an internal_name to the package in the /cf/conf/config.xml
<installedpackages><package><name>freeradius2</name> <internal_name>radiusd</internal_name> <website>http://www.freeradius.org/</website></package></installedpackages>
Now the service is running after every boot.
-
To prevent radiusd being startet multiple times the code in rc_start was added by https://redmine.pfsense.org/issues/4337. This was then merged in https://github.com/pfsense/pfsense-packages/pull/839/files
Like SmileyAU suggestet /usr/local/etc/rc.d/radiusd.sh ist started with the Argument start and stop multiple times. This is done by pfSctl -c 'service reload packages'.
This leads to a RaceCondition where rc_start is still running and rc_stop is called. For me this leads to a always stopped radiusd.I fixed this by checking the LOCKFILE and the PIDFILE in rc_stop.
#!/bin/sh # This file was automatically generated # by the pfSense service handler. SERVICENAME="radiusd" LOCKFILE="/tmp/${SERVICENAME}_start.lock" PIDFILE="/var/run/${SERVICENAME}.pid" rc_start() { # prevent this part of script from running in parallel if ( set -o noclobber; echo "$$" > "$LOCKFILE") 2> /dev/null; then # make sure lock file is removed even if script is terminated trap 'rm -f "$LOCKFILE"; exit $?' INT TERM EXIT /usr/pbi/freeradius-amd64/local/etc/rc.d/radiusd onestart # try to wait until the service starts if [ ! -f "$PIDFILE" ]; then echo "$SERVICENAME.sh: PID file was not found" for i in 1 2 3 4 5; do if [ -f "$PIDFILE" ]; then echo "$SERVICENAME.sh: Service started PID: `cat $PIDFILE`" break else echo "$SERVICENAME.sh: Waiting 0.5 seconds" sleep 0.5 fi done else echo "$SERVICENAME.sh: Service running PID: `cat $PIDFILE`" fi rm -f "$LOCKFILE" trap - INT TERM EXIT else echo "$SERVICENAME.sh: Cannot continue at this moment, this script is already trying to start service PID: $(cat $LOCKFILE)" fi } rc_stop() { # Don't stop if service start is in progress # pfSctl -c 'service reload packages' call start and stop multiple times if [ ! -f "$LOCKFILE" -a -f "$PIDFILE" ]; then /usr/pbi/freeradius-amd64/local/etc/rc.d/radiusd onestop fi } case $1 in start) rc_start ;; stop) rc_stop ;; restart) rc_stop rc_start ;; esac
-
All the technical details are way beyond my knowledge. Since the last upgrade the Freeradius problems are gone and Freeradius is (re)starting as it should after a reboot of pfSense. Great I don't have to start it manually anymore.
-
I'm on pfSense 2.2.6 and freeradius2 Package 1.6.19, which both are the newest Versions.
Since this is a Race Condition the Problem will hit only some users. It depends on the Hardware you are running pfSense on.I like to see this Problem solved in the freeradius2 Package, because now I have to manually patch this every time a new pfSense Version or freeradius2 Package is installed.
I can create a Pull Request against freeradius.inc on https://github.com/pfsense/pfsense-packages, if someone give me a hint howto get something out of the rc_ Functions.
-
I got it fixed when I went to "Packages" tab and reinstalled Freeradius2 by pressing on its [pkg] button.
I run PFS 2.2.6 and had the same problem and reinstalling the packadge solved the problem.
-
The correct solution may be to make pfsense not try to start and stop service at the same time.
Checking PIDs and lockfiles seems like a workaround.
Another workaround i found is to add "sleep 10" at the beginning of rc_start so all rc_stops are finished before rc_starts. (but this may fail if rc_stops take more than 10s)
@bbaumer:if someone give me a hint howto get something out of the rc_ Functions.
What do you mean?
-
To prevent radiusd being startet multiple times the code in rc_start was added by https://redmine.pfsense.org/issues/4337. This was then merged in https://github.com/pfsense/pfsense-packages/pull/839/files
Like SmileyAU suggestet /usr/local/etc/rc.d/radiusd.sh ist started with the Argument start and stop multiple times. This is done by pfSctl -c 'service reload packages'.
This leads to a RaceCondition where rc_start is still running and rc_stop is called. For me this leads to a always stopped radiusd.I fixed this by checking the LOCKFILE and the PIDFILE in rc_stop.
#!/bin/sh # This file was automatically generated # by the pfSense service handler. SERVICENAME="radiusd" LOCKFILE="/tmp/${SERVICENAME}_start.lock" PIDFILE="/var/run/${SERVICENAME}.pid" rc_start() { # prevent this part of script from running in parallel if ( set -o noclobber; echo "$$" > "$LOCKFILE") 2> /dev/null; then # make sure lock file is removed even if script is terminated trap 'rm -f "$LOCKFILE"; exit $?' INT TERM EXIT /usr/pbi/freeradius-amd64/local/etc/rc.d/radiusd onestart # try to wait until the service starts if [ ! -f "$PIDFILE" ]; then echo "$SERVICENAME.sh: PID file was not found" for i in 1 2 3 4 5; do if [ -f "$PIDFILE" ]; then echo "$SERVICENAME.sh: Service started PID: `cat $PIDFILE`" break else echo "$SERVICENAME.sh: Waiting 0.5 seconds" sleep 0.5 fi done else echo "$SERVICENAME.sh: Service running PID: `cat $PIDFILE`" fi rm -f "$LOCKFILE" trap - INT TERM EXIT else echo "$SERVICENAME.sh: Cannot continue at this moment, this script is already trying to start service PID: $(cat $LOCKFILE)" fi } rc_stop() { # Don't stop if service start is in progress # pfSctl -c 'service reload packages' call start and stop multiple times if [ ! -f "$LOCKFILE" -a -f "$PIDFILE" ]; then /usr/pbi/freeradius-amd64/local/etc/rc.d/radiusd onestop fi } case $1 in start) rc_start ;; stop) rc_stop ;; restart) rc_stop rc_start ;; esac
Thanks, this works, please someone commit this code in so others won't have this issue. Whenever the:
"check_reload_status: Starting packages"
initiates, it'll restart the radius and the race condition occurs, the checking for PID on rc_stop makes this problem go away.
-
I got it fixed when I went to "Packages" tab and reinstalled Freeradius2 by pressing on its [pkg] button.
I run PFS 2.2.6 and had the same problem and reinstalling the packadge solved the problem.
This works as well, unsure why…
Also the previous post on the fix, it works but then you can never stop it, since the PID file is there when it's running. Not sure how to 100% prevent this issue.
-
Same problem here on 2.3 release, service doesn't start in 90% of the cases on reboot….
As suggested by bbaumer just edit /usr/local/etc/rc.d/radiusd.sh by this way to solve the situation :) :
#!/bin/sh # This file was automatically generated # by the pfSense service handler. SERVICENAME="radiusd" LOCKFILE="/tmp/${SERVICENAME}_start.lock" PIDFILE="/var/run/${SERVICENAME}.pid" rc_start() { # prevent this part of script from running in parallel if ( set -o noclobber; echo "$$" > "$LOCKFILE") 2> /dev/null; then # make sure lock file is removed even if script is terminated trap 'rm -f "$LOCKFILE"; exit $?' INT TERM EXIT /usr/local/etc/rc.d/radiusd onestart # try to wait until the service starts if [ ! -f "$PIDFILE" ]; then echo "$SERVICENAME.sh: PID file was not found" for i in 1 2 3 4 5; do if [ -f "$PIDFILE" ]; then echo "$SERVICENAME.sh: Service started PID: `cat $PIDFILE`" break else echo "$SERVICENAME.sh: Waiting 0.5 seconds" sleep 0.5 fi done else echo "$SERVICENAME.sh: Service running PID: `cat $PIDFILE`" fi rm -f "$LOCKFILE" trap - INT TERM EXIT else echo "$SERVICENAME.sh: Cannot continue at this moment, this script is already trying to start service PID: $(cat $LOCKFILE)" fi } rc_stop() { # Don't stop if service start is in progress # pfSctl -c 'service reload packages' call start and stop multiple times if [ ! -f "$LOCKFILE" -a -f "$PIDFILE" ]; then /usr/local/etc/rc.d/radiusd onestop fi } case $1 in start) rc_start ;; stop) rc_stop ;; restart) rc_stop rc_start ;; esac
-
All madness hopefully fixed here:
https://github.com/pfsense/FreeBSD-ports/pull/267 (merged in 1.7.5)
https://github.com/pfsense/FreeBSD-ports/pull/268 (pending) -
@bbaumer I submitted a bug report regarding this issue. Unfortunately, it got rejected because he was unable to recreate the issue in his testing environment. Check this for more details:
[https://redmine.pfsense.org/issues/11013](link url)
Almost 5 years later, this issue still exists under certain conditions and they refuse to add the one conditional statement that would fix it for those it affects even though it wouldn't cause any problems for the rest of their users.
-
UPDATE 11/02/2020:
This issue has finally been resolved in FreeRADIUS package version 0.15.7_20
Thank you Renato!