3.0.6 strange bug causing infinite loop on "Ready to process requests" message

6 Jan 2015

      Hello,

I am in the process of upgrading my freeradius 2.2 servers to the latest
3.x. I had things mostly working under 3.0.4, which happened to be the
latest net/freeradius3 port for FreeBSD until today. After upgrading to
3.0.6, I experience the following problem.

After sending the first test authentication request, generated by radtest
client, radiusd emits a second "Ready to process requests" line and
continues to repeat it over and over at will and without delay, until the
log filesystem is full. Stopping it requires a kill -9. This seems to
happen only when a request is received. The server does not send a response.

Again, this does not happen under 3.0.4... I tested by going back to 3.0.4
from 3.0.6 using the same configuration.

The only thing unusual about my config is that I am using rlm_perl with
threaded perl. However the server never seems to enter the rlm_perl module.

I'm hoping someone can help identify if this is actually a bug or something
dumb in my configuration, or a problem with my binary?

Here is relevant OS info and radiusd -X output

FreeBSD 10.1-RELEASE-p3 #3 r276161M: Tue Dec 23 20:32:25 EST 2014
  root@fbsd_101_amd64_builder:/usr/obj/usr/src/sys/CUSTOM

fbsd101-vm# radiusd -X
radiusd: FreeRADIUS Version 3.0.6, for host amd64-portbld-freebsd10.1,
built on Jan  6 2015 at 19:19:50
Copyright (C) 1999-2014 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 dictionary file /usr/local/share/freeradius/dictionary
including dictionary file /usr/local/share/freeradius/dictionary.dhcp
including dictionary file /usr/local/share/freeradius/dictionary.vqp
including dictionary file /usr/local/etc/raddb/dictionary
including configuration file /usr/local/etc/raddb/radiusd.conf
main {
 security {
  user = "freeradius"
  group = "freeradius"
  allow_core_dumps = no
 }
}
main {
name = "radiusd"
prefix = "/usr/local"
localstatedir = "/var"
sbindir = "/usr/local/sbin"
logdir = "/var/log/radius"
run_dir = "/var/run/radiusd"
libdir = "/usr/local/lib"
radacctdir = "/var/log/radius/radacct"
hostname_lookups = no
max_request_time = 30
cleanup_delay = 5
max_requests = 999999
pidfile = "/var/run/radiusd/radiusd.pid"
checkrad = "/usr/local/sbin/checkrad"
debug_level = 0
proxy_requests = no
 log {
  stripped_names = no
  auth = yes
  auth_badpass = no
  auth_goodpass = no
  colourise = yes
  msg_denied = "You are already logged in - access denied"
 }
 security {
  max_attributes = 200
  reject_delay = 1.000000
  status_server = yes
  allow_vulnerable_openssl = "no"
 }
}
radiusd: #### Loading Realms and Home Servers ####
radiusd: #### Loading Clients ####
 client 192.168.92.0/24 {
  ipaddr = 192.168.92.0/24
  require_message_authenticator = no
  secret = <<< secret >>>
  limit {
  max_connections = 16
  lifetime = 0
  idle_timeout = 30
  }
 }
Debugger not attached
radiusd: #### Instantiating modules ####
  # Loaded module rlm_perl
  # Instantiating module "perl" from file /usr/local/etc/raddb/radiusd.conf
  perl {
  filename = "/test/freeradius_hook"
  func_authorize = "authorize"
  func_authenticate = "authenticate"
  func_post_auth = "post_auth"
  func_accounting = "accounting"
  func_preacct = "preacct"
  func_checksimul = "checksimul"
  func_detach = "detach"
  func_xlat = "xlat"
  func_pre_proxy = "pre_proxy"
  func_post_proxy = "post_proxy"
  func_recv_coa = "recv_coa"
  func_send_coa = "send_coa"
  }
  # Loaded module rlm_detail
  # Instantiating module "detail" from file
/usr/local/etc/raddb/radiusd.conf
  detail {
  filename = "/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
  header = "%t"
  permissions = 420
  locking = no
  escape_filenames = no
  log_packet_header = no
  }
  # Loaded module rlm_expr
  # Instantiating module "expr" from file /usr/local/etc/raddb/radiusd.conf
  expr {
  safe_characters =
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_:
/äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ"
  }
  # Loaded module rlm_eap
  # Instantiating module "eap" from file /usr/local/etc/raddb/radiusd.conf
  eap {
  default_eap_type = "peap"
  timer_expire = 60
  ignore_unknown_eap_types = no
  mod_accounting_username_bug = no
  max_sessions = 2048
  }
   # Linked to sub-module rlm_eap_gtc
   gtc {
    challenge = "Password: "
    auth_type = "PAP"
   }
   # Linked to sub-module rlm_eap_tls
   tls {
    tls = "tls-common"
   }
   tls-config tls-common {
    rsa_key_exchange = no
    dh_key_exchange = yes
    rsa_key_length = 512
    dh_key_length = 512
    verify_depth = 0
    pem_file_type = yes
    private_key_file = "/etc/ssl/server.key"
    certificate_file = "/etc/ssl/server.crt"
    ca_file = "/etc/ssl/server.crt"
    dh_file = "/usr/local/etc/raddb/dhparam"
    random_file = "/test/random"
    fragment_size = 1024
    include_length = yes
    check_crl = no
    ecdh_curve = "prime256v1"
    cache {
    enable = no
    lifetime = 24
    max_entries = 255
    }
    verify {
    }
    ocsp {
    enable = no
    override_cert_url = no
    use_nonce = yes
    timeout = 0
    softfail = no
    }
   }
   # Linked to sub-module rlm_eap_ttls
   ttls {
    tls = "tls-common"
    default_eap_type = "gtc"
    copy_request_to_tunnel = yes
    use_tunneled_reply = yes
    include_length = yes
    require_client_cert = no
   }
Using cached TLS configuration from previous invocation
   # Linked to sub-module rlm_eap_peap
   peap {
    tls = "tls-common"
    default_method = "gtc"
    copy_request_to_tunnel = yes
    use_tunneled_reply = yes
    proxy_tunneled_request_as_eap = yes
    soh = no
    require_client_cert = no
   }
Using cached TLS configuration from previous invocation
  # Loaded module rlm_radutmp
  # Instantiating module "radutmp" from file
/usr/local/etc/raddb/radiusd.conf
  radutmp {
  filename = "/var/log/radius/radutmp"
  username = "%{User-Name}"
  case_sensitive = yes
  check_with_nas = yes
  permissions = 420
  caller_id = yes
  }
  # Instantiating module "sradutmp" from file
/usr/local/etc/raddb/radiusd.conf
  radutmp sradutmp {
  filename = "/var/log/radius/sradutmp"
  username = "%{User-Name}"
  case_sensitive = yes
  check_with_nas = yes
  permissions = 420
  caller_id = no
  }
  # Loaded module rlm_attr_filter
  # Instantiating module "attr_filter" from file
/usr/local/etc/raddb/radiusd.conf
  attr_filter {
  filename = "/usr/local/etc/raddb/attrs"
  key = "%{Realm}"
  relaxed = no
  }
reading pairlist file /usr/local/etc/raddb/attrs
  # Loaded module rlm_preprocess
  # Instantiating module "preprocess" from file
/usr/local/etc/raddb/radiusd.conf
  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
radiusd: #### Loading Virtual Servers ####
server { # from file /usr/local/etc/raddb/radiusd.conf
 # Creating Auth-Type = PERL
 # Loading authenticate {...}
 # Loading authorize {...}
 # Loading preacct {...}
 # Loading accounting {...}
} # server
radiusd: #### Opening IP addresses and Ports ####
listen {
  type = "auth"
  ipaddr = *
  port = 1812
}
listen {
  type = "acct"
  ipaddr = *
  port = 1813
}
Listening on auth address * port 1812
Listening on acct address * port 1813
Ready to process requests

Ready to process requests
Ready to process requests
Ready to process requests
Ready to process requests
Ready to process requests
Ready to process requests
Ready to process requests
Ready to process requests
Ready to process requests
^^ Above log message repeats indefinitely

Here is full radiusd.conf

client 192.168.92.0/24 {
    ipaddr = 192.168.92.0/24
    secret = d0ee524f6cb9966ce134d251a3e820c7
}

prefix = /usr/local
exec_prefix = ${prefix}
sysconfdir = ${prefix}/etc
localstatedir = /var
sbindir = ${exec_prefix}/sbin
logdir = /var/log/radius
raddbdir = ${sysconfdir}/raddb
radacctdir = ${logdir}/radacct
name = radiusd
confdir = ${raddbdir}
modconfdir = ${confdir}/mods-config
certdir = ${confdir}/certs
cadir   = ${confdir}/certs
run_dir = ${localstatedir}/run/${name}
db_dir = ${raddbdir}
pidfile = /var/run/radiusd/radiusd.pid
checkrad = ${sbindir}/checkrad

listen {
    ipaddr = *
    port = 1812
    type = auth
}

listen {
    ipaddr = *
    port = 1813
    type = acct
}

log {
    destination = files
    colourise = yes
    file = ${logdir}/radius.log
    syslog_facility = daemon

    stripped_names = no
    auth = yes
    auth_badpass = no
    auth_goodpass = no
}

security {
user = freeradius
group = freeradius
    allow_core_dumps = no
    max_attributes = 200
    reject_delay = 1
    status_server = yes
}

thread pool {
    start_servers = 8
    max_servers = 80
    min_spare_servers = 4
    max_spare_servers = 16
    max_requests_per_server = 0
}

max_request_time = 30
cleanup_delay = 5
max_requests = 999999
hostname_lookups = no
delete_blocked_requests = no

regular_expressions = yes
extended_expressions = yes

usercollide = no
lower_user = no
lower_pass = no
nospace_user = no
nospace_pass = no
snmp = no

proxy_requests = no

modules {
    perl {
        filename = /test/freeradius_hook
    }

    detail {
        filename = ${radacctdir}/%{Client-IP-Address}/detail-%Y%m%d
        permissions = 0644
    }

    expr {
        safe_characters =
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_:
/äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ"
    }

    eap {
        default_eap_type = peap
        timer_expire     = 60
        ignore_unknown_eap_types = no

        gtc {
            challenge = "Password: "
            auth_type = PAP
        }

        tls-config tls-common {
            private_key_password =
            private_key_file = /etc/ssl/server.key
            certificate_file = /etc/ssl/server.crt
            ca_file = /etc/ssl/server.crt
            dh_file = /usr/local/etc/raddb/dhparam
            random_file = /test/random
        }

    tls {
    tls = tls-common
    }

        ttls {
            tls = tls-common

            default_eap_type = gtc
            copy_request_to_tunnel = yes
            use_tunneled_reply = yes
        }

        peap {
    tls = tls-common

            default_eap_type = gtc
            default_method = gtc
            copy_request_to_tunnel = yes
            use_tunneled_reply = yes
        }

    }

    radutmp {
        filename = ${logdir}/radutmp
        username = %{User-Name}
        case_sensitive = yes
        check_with_nas = yes
        caller_id = "yes"
    }

    radutmp sradutmp {
        filename = ${logdir}/sradutmp
        permissions = 0644
        caller_id = "no"
    }

    attr_filter {
        filename = ${confdir}/attrs
    }

    preprocess {
        huntgroups = ${confdir}/huntgroups
        hints = ${confdir}/hints
        with_ascend_hack = no
        ascend_channels_per_line = 23
        with_ntdomain_hack = no
        with_specialix_jetstream_hack = no
        with_cisco_vsa_hack = no
    }
}

policy {
    class_value_prefix = 'ai:'

    acct_unique {
        if ("%{string:Class}" =~
/${policy.class_value_prefix}([0-9a-f]{32})/i) {
            update request {
                &Acct-Unique-Session-Id := "%{md5:%{1},%{Acct-Session-ID}}"
            }
        }

        else {
            update request {
                &Acct-Unique-Session-Id :=
"%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}"
            }
        }
    }

    insert_acct_class {
        update reply {
            &Class =
"${policy.class_value_prefix}%{md5:%t,%I,%{Packet-Src-Port},%{Packet-Src-IP-Address},%{NAS-IP-Address},%{Calling-Station-ID},%{User-Name}}"
        }
    }

    acct_counters64.preacct {
        update request {
            &Acct-Input-Octets64 = "%{expr:(&Acct-Input-Gigawords << 32) |
&Acct-Input-Octets}"
            &Acct-Output-Octets64 = "%{expr:(&Acct-Output-Gigawords << 32)
| &Acct-Output-Octets}"
        }
    }
}

server {
    authorize {
        preprocess
        eap
        perl
    }

    authenticate {
        Auth-Type PERL {
            perl
        }
        eap
    }

    preacct {
        preprocess
        acct_unique
    }

    accounting {
        perl
    }

    post-proxy {
        eap
        perl
    }
}

3.0.6 strange bug causing infinite loop on "Ready to process requests" message

Nick Rogers