search

FreeRADIUS / freeradius-server

FreeRADIUS - A multi-protocol policy server.
http://freeradius.org
GNU General Public License v2.0
2.12k stars 1.08k forks source link

[defect]: rlm_python: Fatal Python error: drop_gil: drop_gil: GIL is not locked #5111

Open sirmax123 opened 1 year ago

sirmax123 commented 1 year ago

What type of defect/bug is this?

Crash or memory corruption (segv, abort, etc...)

How can the issue be reproduced?

I'd like to have 2 instances of Python code (using rlm_python) in order to split my code into 2 scripts

e.g smx like this ipaddr.py:

...
  for AVPair in p['request']:
    if (AVPair[0] == "User-Name"):
      if (is_ip_addr(AVPair[1]):
      ...
        config = ( ('Cleartext-Password', 'hello'), ('Auth-Type', 'PYTHON-IPADDR') )
        return radiusd.RLM_MODULE_OK, reply, config
     else:
       return radiusd.RLM_MODULE_NOOP

service.py: and the second script returns something like

        config = ( ('Cleartext-Password', 'hello'), ('Auth-Type', 'PYTHON-NOT-IPADDR') )
        return radiusd.RLM_MODULE_OK, reply, config

The idia is to handle in different scripts for different kinds of usernames, I need it for Cisco ISG, where I have users with User-Name = IP ADDRESS and Service where User-Name is name of service

So I'm trying to do it in the following way:

    authorize {
        python3_ipaddress_username # <--- name of module instance  where module=ipaddr.py defined
        python3_service_username # <--- name of module instance  where module=service.py defined
  }
    authenticate {
        Auth-Type PYTHON-IPADDR {
            python3_ipaddress_username
        }

        Auth-Type PYTHON-NOT-IPADDR {
            python3_service_username
        }
}

There is no real code in scripts, just 2 copies of example.py from distribution.

And I got:

Fatal Python error: drop_gil: drop_gil: GIL is not locked

One script works OK, so as workaround I can put all code into one file, it possible.

Log output from the FreeRADIUS daemon

root@radius:/usr/local/freeradius/sbin# ./radiusd -XXXX
Tue Jul 18 14:30:26 2023 : Debug: Server was built with:
Tue Jul 18 14:30:26 2023 : Debug:   accounting                : yes
Tue Jul 18 14:30:26 2023 : Debug:   authentication            : yes
Tue Jul 18 14:30:26 2023 : Debug:   ascend-binary-attributes  : yes
Tue Jul 18 14:30:26 2023 : Debug:   coa                       : yes
Tue Jul 18 14:30:26 2023 : Debug:   recv-coa-from-home-server : no
Tue Jul 18 14:30:26 2023 : Debug:   control-socket            : yes
Tue Jul 18 14:30:26 2023 : Debug:   detail                    : yes
Tue Jul 18 14:30:26 2023 : Debug:   dhcp                      : yes
Tue Jul 18 14:30:26 2023 : Debug:   dynamic-clients           : yes
Tue Jul 18 14:30:26 2023 : Debug:   osfc2                     : no
Tue Jul 18 14:30:26 2023 : Debug:   proxy                     : yes
Tue Jul 18 14:30:26 2023 : Debug:   regex-pcre                : no
Tue Jul 18 14:30:26 2023 : Debug:   regex-posix               : yes
Tue Jul 18 14:30:26 2023 : Debug:   regex-posix-extended      : yes
Tue Jul 18 14:30:26 2023 : Debug:   session-management        : yes
Tue Jul 18 14:30:26 2023 : Debug:   stats                     : yes
Tue Jul 18 14:30:26 2023 : Debug:   systemd                   : no
Tue Jul 18 14:30:26 2023 : Debug:   tcp                       : yes
Tue Jul 18 14:30:26 2023 : Debug:   threads                   : yes
Tue Jul 18 14:30:26 2023 : Debug:   tls                       : yes
Tue Jul 18 14:30:26 2023 : Debug:   unlang                    : yes
Tue Jul 18 14:30:26 2023 : Debug:   vmps                      : yes
Tue Jul 18 14:30:26 2023 : Debug:   developer                 : yes
Tue Jul 18 14:30:26 2023 : Debug: Server core libs:
Tue Jul 18 14:30:26 2023 : Debug:   freeradius-server         : 3.2.4
Tue Jul 18 14:30:26 2023 : Debug:   talloc                    : 2.3.*
Tue Jul 18 14:30:26 2023 : Debug:   ssl                       : 3.0.0b dev
Tue Jul 18 14:30:26 2023 : Debug: Endianness:
Tue Jul 18 14:30:26 2023 : Debug:   little
Tue Jul 18 14:30:26 2023 : Debug: Compilation flags:
Tue Jul 18 14:30:26 2023 : Debug:   cppflags :
Tue Jul 18 14:30:26 2023 : Debug:   cflags   : -I. -Isrc -include src/freeradius-devel/autoconf.h -include src/freeradius-devel/build.h -include src/freeradius-devel/features.h -include src/freeradius-devel/radpaths.h -fno-strict-aliasing -Wno-date-time -g3 -Wall -std=c99 -D_GNU_SOURCE -D_REENTRANT -D_POSIX_PTHREAD_SEMANTICS -DOPENSSL_NO_KRB5 -Wshadow -Wpointer-arith -Wcast-qual -Wcast-align -Wwrite-strings -Wstrict-prototypes -Wmissing-prototypes -Wmissing-declarations -Wnested-externs -W -Wredundant-decls -Wundef -Wformat-y2k -Wno-format-extra-args -Wno-format-zero-length -Wno-cast-align -Wformat-nonliteral -Wformat-security -Wformat=2 -DWITH_VERIFY_PTR=1 -DIS_MODULE=1
Tue Jul 18 14:30:26 2023 : Debug:   ldflags  :
Tue Jul 18 14:30:26 2023 : Debug:   libs     : -lcrypto -lssl -ltalloc -latomic -lnsl -lresolv -ldl -lpthread
Tue Jul 18 14:30:26 2023 : Debug:
Tue Jul 18 14:30:26 2023 : Info: FreeRADIUS Version 3.2.4
Tue Jul 18 14:30:26 2023 : Info: Copyright (C) 1999-2022 The FreeRADIUS server project and contributors
Tue Jul 18 14:30:26 2023 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
Tue Jul 18 14:30:26 2023 : Info: PARTICULAR PURPOSE
Tue Jul 18 14:30:26 2023 : Info: You may redistribute copies of FreeRADIUS under the terms of the
Tue Jul 18 14:30:26 2023 : Info: GNU General Public License
Tue Jul 18 14:30:26 2023 : Info: For more information about these matters, see the file named COPYRIGHT
Tue Jul 18 14:30:26 2023 : Info: Starting - reading configuration files ...
Tue Jul 18 14:30:26 2023 : Debug: including dictionary file /usr/local/freeradius/share/freeradius/dictionary
Tue Jul 18 14:30:26 2023 : Debug: including dictionary file /usr/local/freeradius/share/freeradius/dictionary.dhcp
Tue Jul 18 14:30:26 2023 : Debug: including dictionary file /usr/local/freeradius/share/freeradius/dictionary.vqp
Tue Jul 18 14:30:26 2023 : Debug: including dictionary file /usr/local/freeradius/etc/raddb/dictionary
Tue Jul 18 14:30:26 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/radiusd.conf
Tue Jul 18 14:30:26 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/clients.conf
Tue Jul 18 14:30:26 2023 : Debug: including files in directory /usr/local/freeradius/etc/raddb/mods-enabled/
Tue Jul 18 14:30:26 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/mods-enabled/preprocess
Tue Jul 18 14:30:26 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/mods-enabled/digest
Tue Jul 18 14:30:26 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/mods-enabled/chap
Tue Jul 18 14:30:26 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/mods-enabled/python3_ipaddress_username
Tue Jul 18 14:30:26 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/mods-enabled/echo
Tue Jul 18 14:30:26 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/mods-enabled/python3_service_username
Tue Jul 18 14:30:26 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/mods-enabled/pap
Tue Jul 18 14:30:26 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/mods-enabled/files
Tue Jul 18 14:30:26 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/mods-enabled/realm
Tue Jul 18 14:30:26 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/mods-enabled/expr
Tue Jul 18 14:30:26 2023 : Debug: including files in directory /usr/local/freeradius/etc/raddb/policy.d/
Tue Jul 18 14:30:26 2023 : Debug: including files in directory /usr/local/freeradius/etc/raddb/sites-enabled/
Tue Jul 18 14:30:26 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/sites-enabled/default
Tue Jul 18 14:30:26 2023 : Debug: main {
Tue Jul 18 14:30:26 2023 : Debug:  security {
Tue Jul 18 14:30:26 2023 : Debug:   user = "freerad"
Tue Jul 18 14:30:26 2023 : Debug:   group = "freerad"
Tue Jul 18 14:30:26 2023 : Debug:   allow_core_dumps = yes
Tue Jul 18 14:30:26 2023 : Debug:  }
Tue Jul 18 14:30:26 2023 : Debug:   name = "freeradius"
Tue Jul 18 14:30:26 2023 : Debug:   prefix = "/usr/local/freeradius"
Tue Jul 18 14:30:26 2023 : Debug:   localstatedir = "/usr/local/freeradius/var"
Tue Jul 18 14:30:26 2023 : Debug:   logdir = "/usr/local/freeradius/var/log/radius"
Tue Jul 18 14:30:26 2023 : Debug:   run_dir = "/usr/local/freeradius/var/run/freeradius"
Tue Jul 18 14:30:26 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[7]: The item 'raddbdir' is defined, but is unused by the configuration
Tue Jul 18 14:30:26 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[8]: The item 'radacctdir' is defined, but is unused by the configuration
Tue Jul 18 14:30:26 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[20]: The item 'libdir' is defined, but is unused by the configuration
Tue Jul 18 14:30:26 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[21]: The item 'pidfile' is defined, but is unused by the configuration
Tue Jul 18 14:30:26 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[23]: The item 'correct_escapes' is defined, but is unused by the configuration
Tue Jul 18 14:30:26 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[25]: The item 'max_request_time' is defined, but is unused by the configuration
Tue Jul 18 14:30:26 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[26]: The item 'cleanup_delay' is defined, but is unused by the configuration
Tue Jul 18 14:30:26 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[27]: The item 'max_requests' is defined, but is unused by the configuration
Tue Jul 18 14:30:26 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[28]: The item 'hostname_lookups' is defined, but is unused by the configuration
Tue Jul 18 14:30:26 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[43]: The item 'checkrad' is defined, but is unused by the configuration
Tue Jul 18 14:30:26 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[56]: The item 'proxy_requests' is defined, but is unused by the configuration
Tue Jul 18 14:30:26 2023 : Debug: }
Tue Jul 18 14:30:26 2023 : Info: Core dumps are enabled
Tue Jul 18 14:30:26 2023 : Debug: main {
Tue Jul 18 14:30:26 2023 : Debug:   name = "freeradius"
Tue Jul 18 14:30:26 2023 : Debug:   prefix = "/usr/local/freeradius"
Tue Jul 18 14:30:26 2023 : Debug:   localstatedir = "/usr/local/freeradius/var"
Tue Jul 18 14:30:26 2023 : Debug:   sbindir = "/usr/local/freeradius/sbin"
Tue Jul 18 14:30:26 2023 : Debug:   logdir = "/usr/local/freeradius/var/log/radius"
Tue Jul 18 14:30:26 2023 : Debug:   run_dir = "/usr/local/freeradius/var/run/freeradius"
Tue Jul 18 14:30:26 2023 : Debug:   libdir = "/usr/local/freeradius/lib"
Tue Jul 18 14:30:26 2023 : Debug:   radacctdir = "/usr/local/freeradius/var/log/radius/radacct"
Tue Jul 18 14:30:26 2023 : Debug:   hostname_lookups = no
Tue Jul 18 14:30:26 2023 : Debug:   max_request_time = 30
Tue Jul 18 14:30:26 2023 : Debug:   cleanup_delay = 5
Tue Jul 18 14:30:26 2023 : Debug:   max_requests = 16384
Tue Jul 18 14:30:26 2023 : Debug:   postauth_client_lost = no
Tue Jul 18 14:30:26 2023 : Debug:   pidfile = "/usr/local/freeradius/var/run/freeradius/freeradius.pid"
Tue Jul 18 14:30:26 2023 : Debug:   checkrad = "/usr/local/freeradius/sbin/checkrad"
Tue Jul 18 14:30:26 2023 : Debug:   debug_level = 0
Tue Jul 18 14:30:26 2023 : Debug:   proxy_requests = no
Tue Jul 18 14:30:26 2023 : Debug:  log {
Tue Jul 18 14:30:26 2023 : Debug:   stripped_names = no
Tue Jul 18 14:30:26 2023 : Debug:   auth = yes
Tue Jul 18 14:30:26 2023 : Debug:   auth_badpass = yes
Tue Jul 18 14:30:26 2023 : Debug:   auth_goodpass = yes
Tue Jul 18 14:30:26 2023 : Debug:   colourise = yes
Tue Jul 18 14:30:26 2023 : Debug:   msg_denied = "You are already logged in - access denied"
Tue Jul 18 14:30:26 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[31]: The item 'destination' is defined, but is unused by the configuration
Tue Jul 18 14:30:26 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[33]: The item 'file' is defined, but is unused by the configuration
Tue Jul 18 14:30:26 2023 : Debug:  }
Tue Jul 18 14:30:26 2023 : Debug:  resources {
Tue Jul 18 14:30:26 2023 : Debug:  }
Tue Jul 18 14:30:26 2023 : Debug:  security {
Tue Jul 18 14:30:26 2023 : Debug:   max_attributes = 0
Tue Jul 18 14:30:26 2023 : Debug:   reject_delay = 0.000000
Tue Jul 18 14:30:26 2023 : Debug:   status_server = no
Tue Jul 18 14:30:26 2023 : Debug:   allow_vulnerable_openssl = "no"
Tue Jul 18 14:30:26 2023 : Debug:  }
Tue Jul 18 14:30:26 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[7]: The item 'raddbdir' is defined, but is unused by the configuration
Tue Jul 18 14:30:26 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[23]: The item 'correct_escapes' is defined, but is unused by the configuration
Tue Jul 18 14:30:26 2023 : Debug: }
Tue Jul 18 14:30:26 2023 : Debug: radiusd: #### Loading Realms and Home Servers ####
Tue Jul 18 14:30:26 2023 : Debug: radiusd: #### Loading Clients ####
Tue Jul 18 14:30:26 2023 : Debug:  client localhost {
Tue Jul 18 14:30:26 2023 : Debug:   ipaddr = 127.0.0.1
Tue Jul 18 14:30:26 2023 : Debug:   require_message_authenticator = no
Tue Jul 18 14:30:26 2023 : Debug:   secret = "testing123"
Tue Jul 18 14:30:26 2023 : Debug:   nas_type = "other"
Tue Jul 18 14:30:26 2023 : Debug:   proto = "*"
Tue Jul 18 14:30:26 2023 : Debug:   limit {
Tue Jul 18 14:30:26 2023 : Debug:       max_connections = 16
Tue Jul 18 14:30:26 2023 : Debug:       lifetime = 0
Tue Jul 18 14:30:26 2023 : Debug:       idle_timeout = 30
Tue Jul 18 14:30:26 2023 : Debug:   }
Tue Jul 18 14:30:26 2023 : Debug:  }
Tue Jul 18 14:30:26 2023 : Debug: Adding client 127.0.0.1/32 (127.0.0.1) to prefix tree 32
Tue Jul 18 14:30:26 2023 : Debug:  client localhost_ipv6 {
Tue Jul 18 14:30:26 2023 : Debug:   ipv6addr = ::1
Tue Jul 18 14:30:26 2023 : Debug:   require_message_authenticator = no
Tue Jul 18 14:30:26 2023 : Debug:   secret = "testing123"
Tue Jul 18 14:30:26 2023 : Debug:   limit {
Tue Jul 18 14:30:26 2023 : Debug:       max_connections = 16
Tue Jul 18 14:30:26 2023 : Debug:       lifetime = 0
Tue Jul 18 14:30:26 2023 : Debug:       idle_timeout = 30
Tue Jul 18 14:30:26 2023 : Debug:   }
Tue Jul 18 14:30:26 2023 : Debug:  }
Tue Jul 18 14:30:26 2023 : Debug: Adding client ::1/128 (::1) to prefix tree 128
Tue Jul 18 14:30:26 2023 : Info: Debugger not attached
Tue Jul 18 14:30:26 2023 : Debug:  # Creating Auth-Type = PYTHON_IPADRESS
Tue Jul 18 14:30:26 2023 : Debug:  # Creating Auth-Type = PYTHON_SERVICE
Tue Jul 18 14:30:26 2023 : Debug: radiusd: #### Instantiating modules ####
Tue Jul 18 14:30:26 2023 : Debug:  modules {
Tue Jul 18 14:30:26 2023 : Debug: Loading rlm_preprocess with path: /usr/local/freeradius/lib/rlm_preprocess.so
Tue Jul 18 14:30:26 2023 : Debug: Loaded rlm_preprocess, checking if it's valid
Tue Jul 18 14:30:26 2023 : Debug:   # Loaded module rlm_preprocess
Tue Jul 18 14:30:26 2023 : Debug:   # Loading module "preprocess" from file /usr/local/freeradius/etc/raddb/mods-enabled/preprocess
Tue Jul 18 14:30:26 2023 : Debug:   preprocess {
Tue Jul 18 14:30:26 2023 : Debug:       huntgroups = "/usr/local/freeradius/etc/raddb/mods-config/preprocess/huntgroups"
Tue Jul 18 14:30:26 2023 : Debug:       hints = "/usr/local/freeradius/etc/raddb/mods-config/preprocess/hints"
Tue Jul 18 14:30:26 2023 : Debug:       with_ascend_hack = no
Tue Jul 18 14:30:26 2023 : Debug:       ascend_channels_per_line = 23
Tue Jul 18 14:30:26 2023 : Debug:       with_ntdomain_hack = no
Tue Jul 18 14:30:26 2023 : Debug:       with_specialix_jetstream_hack = no
Tue Jul 18 14:30:26 2023 : Debug:       with_cisco_vsa_hack = no
Tue Jul 18 14:30:26 2023 : Debug:       with_alvarion_vsa_hack = no
Tue Jul 18 14:30:26 2023 : Debug:   }
Tue Jul 18 14:30:26 2023 : Debug: Loading rlm_digest with path: /usr/local/freeradius/lib/rlm_digest.so
Tue Jul 18 14:30:26 2023 : Debug: Loaded rlm_digest, checking if it's valid
Tue Jul 18 14:30:26 2023 : Debug:   # Loaded module rlm_digest
Tue Jul 18 14:30:26 2023 : Debug:   # Loading module "digest" from file /usr/local/freeradius/etc/raddb/mods-enabled/digest
Tue Jul 18 14:30:26 2023 : Debug: Loading rlm_chap with path: /usr/local/freeradius/lib/rlm_chap.so
Tue Jul 18 14:30:26 2023 : Debug: Loaded rlm_chap, checking if it's valid
Tue Jul 18 14:30:26 2023 : Debug:   # Loaded module rlm_chap
Tue Jul 18 14:30:26 2023 : Debug:   # Loading module "chap" from file /usr/local/freeradius/etc/raddb/mods-enabled/chap
Tue Jul 18 14:30:26 2023 : Debug: Loading rlm_python3 with path: /usr/local/freeradius/lib/rlm_python3.so
Tue Jul 18 14:30:26 2023 : Debug: Loaded rlm_python3, checking if it's valid
Tue Jul 18 14:30:26 2023 : Debug:   # Loaded module rlm_python3
Tue Jul 18 14:30:26 2023 : Debug:   # Loading module "python3_ipaddress_username" from file /usr/local/freeradius/etc/raddb/mods-enabled/python3_ipaddress_username
Tue Jul 18 14:30:26 2023 : Debug:   python3 python3_ipaddress_username {
Tue Jul 18 14:30:26 2023 : Debug:       mod_instantiate = "ipaddress_username"
Tue Jul 18 14:30:26 2023 : Debug:       func_instantiate = "instantiate"
Tue Jul 18 14:30:26 2023 : Debug:       mod_authorize = "ipaddress_username"
Tue Jul 18 14:30:26 2023 : Debug:       func_authorize = "authorize"
Tue Jul 18 14:30:26 2023 : Debug:       mod_authenticate = "ipaddress_username"
Tue Jul 18 14:30:26 2023 : Debug:       func_authenticate = "authenticate"
Tue Jul 18 14:30:26 2023 : Debug:       mod_preacct = "ipaddress_username"
Tue Jul 18 14:30:26 2023 : Debug:       func_preacct = "preacct"
Tue Jul 18 14:30:26 2023 : Debug:       mod_accounting = "ipaddress_username"
Tue Jul 18 14:30:26 2023 : Debug:       func_accounting = "accounting"
Tue Jul 18 14:30:26 2023 : Debug:       mod_checksimul = "ipaddress_username"
Tue Jul 18 14:30:26 2023 : Debug:       func_checksimul = "checksimul"
Tue Jul 18 14:30:26 2023 : Debug:       mod_pre_proxy = "ipaddress_username"
Tue Jul 18 14:30:26 2023 : Debug:       func_pre_proxy = "pre_proxy"
Tue Jul 18 14:30:26 2023 : Debug:       mod_post_proxy = "ipaddress_username"
Tue Jul 18 14:30:26 2023 : Debug:       func_post_proxy = "post_proxy"
Tue Jul 18 14:30:26 2023 : Debug:       mod_post_auth = "ipaddress_username"
Tue Jul 18 14:30:26 2023 : Debug:       func_post_auth = "post_auth"
Tue Jul 18 14:30:26 2023 : Debug:       mod_recv_coa = "ipaddress_username"
Tue Jul 18 14:30:26 2023 : Debug:       func_recv_coa = "recv_coa"
Tue Jul 18 14:30:26 2023 : Debug:       mod_send_coa = "ipaddress_username"
Tue Jul 18 14:30:26 2023 : Debug:       func_send_coa = "send_coa"
Tue Jul 18 14:30:26 2023 : Debug:       mod_detach = "ipaddress_username"
Tue Jul 18 14:30:26 2023 : Debug:       func_detach = "detach"
Tue Jul 18 14:30:26 2023 : Debug:       python_path = ":/usr/local/freeradius/etc/raddb/mods-config/python3"
Tue Jul 18 14:30:26 2023 : Debug:       cext_compat = yes
Tue Jul 18 14:30:26 2023 : Debug:       pass_all_vps = no
Tue Jul 18 14:30:26 2023 : Debug:       pass_all_vps_dict = yes
Tue Jul 18 14:30:26 2023 : Debug:   }
Tue Jul 18 14:30:26 2023 : Debug: Loading rlm_exec with path: /usr/local/freeradius/lib/rlm_exec.so
Tue Jul 18 14:30:26 2023 : Debug: Loaded rlm_exec, checking if it's valid
Tue Jul 18 14:30:26 2023 : Debug:   # Loaded module rlm_exec
Tue Jul 18 14:30:26 2023 : Debug:   # Loading module "echo" from file /usr/local/freeradius/etc/raddb/mods-enabled/echo
Tue Jul 18 14:30:26 2023 : Debug:   exec echo {
Tue Jul 18 14:30:26 2023 : Debug:       wait = yes
Tue Jul 18 14:30:26 2023 : Debug:       program = "/bin/echo %{User-Name}"
Tue Jul 18 14:30:26 2023 : Debug:       input_pairs = "request"
Tue Jul 18 14:30:26 2023 : Debug:       output_pairs = "reply"
Tue Jul 18 14:30:26 2023 : Debug:       shell_escape = yes
Tue Jul 18 14:30:26 2023 : Debug:   }
Tue Jul 18 14:30:26 2023 : Debug:   # Loading module "python3_service_username" from file /usr/local/freeradius/etc/raddb/mods-enabled/python3_service_username
Tue Jul 18 14:30:26 2023 : Debug:   python3 python3_service_username {
Tue Jul 18 14:30:26 2023 : Debug:       mod_instantiate = "example"
Tue Jul 18 14:30:26 2023 : Debug:       func_instantiate = "instantiate"
Tue Jul 18 14:30:26 2023 : Debug:       mod_authorize = "example"
Tue Jul 18 14:30:26 2023 : Debug:       func_authorize = "authorize"
Tue Jul 18 14:30:26 2023 : Debug:       mod_authenticate = "example"
Tue Jul 18 14:30:26 2023 : Debug:       func_authenticate = "authenticate"
Tue Jul 18 14:30:26 2023 : Debug:       mod_preacct = "example"
Tue Jul 18 14:30:26 2023 : Debug:       func_preacct = "preacct"
Tue Jul 18 14:30:26 2023 : Debug:       mod_accounting = "example"
Tue Jul 18 14:30:26 2023 : Debug:       func_accounting = "accounting"
Tue Jul 18 14:30:26 2023 : Debug:       mod_checksimul = "example"
Tue Jul 18 14:30:26 2023 : Debug:       func_checksimul = "checksimul"
Tue Jul 18 14:30:26 2023 : Debug:       mod_pre_proxy = "example"
Tue Jul 18 14:30:26 2023 : Debug:       func_pre_proxy = "pre_proxy"
Tue Jul 18 14:30:26 2023 : Debug:       mod_post_proxy = "example"
Tue Jul 18 14:30:26 2023 : Debug:       func_post_proxy = "post_proxy"
Tue Jul 18 14:30:26 2023 : Debug:       mod_post_auth = "example"
Tue Jul 18 14:30:26 2023 : Debug:       func_post_auth = "post_auth"
Tue Jul 18 14:30:26 2023 : Debug:       mod_recv_coa = "example"
Tue Jul 18 14:30:26 2023 : Debug:       func_recv_coa = "recv_coa"
Tue Jul 18 14:30:26 2023 : Debug:       mod_send_coa = "example"
Tue Jul 18 14:30:26 2023 : Debug:       func_send_coa = "send_coa"
Tue Jul 18 14:30:26 2023 : Debug:       mod_detach = "example"
Tue Jul 18 14:30:26 2023 : Debug:       func_detach = "detach"
Tue Jul 18 14:30:26 2023 : Debug:       python_path = ":/usr/local/freeradius/etc/raddb/mods-config/python3"
Tue Jul 18 14:30:26 2023 : Debug:       cext_compat = yes
Tue Jul 18 14:30:26 2023 : Debug:       pass_all_vps = no
Tue Jul 18 14:30:26 2023 : Debug:       pass_all_vps_dict = yes
Tue Jul 18 14:30:26 2023 : Debug:   }
Tue Jul 18 14:30:26 2023 : Debug: Loading rlm_pap with path: /usr/local/freeradius/lib/rlm_pap.so
Tue Jul 18 14:30:26 2023 : Debug: Loaded rlm_pap, checking if it's valid
Tue Jul 18 14:30:26 2023 : Debug:   # Loaded module rlm_pap
Tue Jul 18 14:30:26 2023 : Debug:   # Loading module "pap" from file /usr/local/freeradius/etc/raddb/mods-enabled/pap
Tue Jul 18 14:30:26 2023 : Debug:   pap {
Tue Jul 18 14:30:26 2023 : Debug:       normalise = yes
Tue Jul 18 14:30:26 2023 : Debug:   }
Tue Jul 18 14:30:26 2023 : Debug:   # Loading module "module_pap_1" from file /usr/local/freeradius/etc/raddb/mods-enabled/pap
Tue Jul 18 14:30:26 2023 : Debug:   pap module_pap_1 {
Tue Jul 18 14:30:26 2023 : Debug:       normalise = yes
Tue Jul 18 14:30:26 2023 : Debug:   }
Tue Jul 18 14:30:26 2023 : Debug:   # Loading module "module_pap_2" from file /usr/local/freeradius/etc/raddb/mods-enabled/pap
Tue Jul 18 14:30:26 2023 : Debug:   pap module_pap_2 {
Tue Jul 18 14:30:26 2023 : Debug:       normalise = yes
Tue Jul 18 14:30:26 2023 : Debug:   }
Tue Jul 18 14:30:26 2023 : Debug: Loading rlm_files with path: /usr/local/freeradius/lib/rlm_files.so
Tue Jul 18 14:30:26 2023 : Debug: Loaded rlm_files, checking if it's valid
Tue Jul 18 14:30:26 2023 : Debug:   # Loaded module rlm_files
Tue Jul 18 14:30:26 2023 : Debug:   # Loading module "module_files_1" from file /usr/local/freeradius/etc/raddb/mods-enabled/files
Tue Jul 18 14:30:26 2023 : Debug:   files module_files_1 {
Tue Jul 18 14:30:26 2023 : Debug:       filename = "/usr/local/freeradius/etc/raddb/mods-config/module_files_1/authorize"
Tue Jul 18 14:30:26 2023 : Debug:       usersfile = "/usr/local/freeradius/etc/raddb/mods-config/module_files_1/authorize"
Tue Jul 18 14:30:26 2023 : Debug:   }
Tue Jul 18 14:30:26 2023 : Debug:   # Loading module "module_files_2" from file /usr/local/freeradius/etc/raddb/mods-enabled/files
Tue Jul 18 14:30:26 2023 : Debug:   files module_files_2 {
Tue Jul 18 14:30:26 2023 : Debug:       filename = "/usr/local/freeradius/etc/raddb/mods-config/module_files_2/authorize"
Tue Jul 18 14:30:26 2023 : Debug:       usersfile = "/usr/local/freeradius/etc/raddb/mods-config/module_files_2/authorize"
Tue Jul 18 14:30:26 2023 : Debug:   }
Tue Jul 18 14:30:26 2023 : Debug: Loading rlm_realm with path: /usr/local/freeradius/lib/rlm_realm.so
Tue Jul 18 14:30:26 2023 : Debug: Loaded rlm_realm, checking if it's valid
Tue Jul 18 14:30:26 2023 : Debug:   # Loaded module rlm_realm
Tue Jul 18 14:30:26 2023 : Debug:   # Loading module "IPASS" from file /usr/local/freeradius/etc/raddb/mods-enabled/realm
Tue Jul 18 14:30:26 2023 : Debug:   realm IPASS {
Tue Jul 18 14:30:26 2023 : Debug:       format = "prefix"
Tue Jul 18 14:30:26 2023 : Debug:       delimiter = "/"
Tue Jul 18 14:30:26 2023 : Debug:       ignore_default = no
Tue Jul 18 14:30:26 2023 : Debug:       ignore_null = no
Tue Jul 18 14:30:26 2023 : Debug:   }
Tue Jul 18 14:30:26 2023 : Debug:   # Loading module "suffix" from file /usr/local/freeradius/etc/raddb/mods-enabled/realm
Tue Jul 18 14:30:26 2023 : Debug:   realm suffix {
Tue Jul 18 14:30:26 2023 : Debug:       format = "suffix"
Tue Jul 18 14:30:26 2023 : Debug:       delimiter = "@"
Tue Jul 18 14:30:26 2023 : Debug:       ignore_default = no
Tue Jul 18 14:30:26 2023 : Debug:       ignore_null = no
Tue Jul 18 14:30:26 2023 : Debug:   }
Tue Jul 18 14:30:26 2023 : Debug:   # Loading module "bangpath" from file /usr/local/freeradius/etc/raddb/mods-enabled/realm
Tue Jul 18 14:30:26 2023 : Debug:   realm bangpath {
Tue Jul 18 14:30:26 2023 : Debug:       format = "prefix"
Tue Jul 18 14:30:26 2023 : Debug:       delimiter = "!"
Tue Jul 18 14:30:26 2023 : Debug:       ignore_default = no
Tue Jul 18 14:30:26 2023 : Debug:       ignore_null = no
Tue Jul 18 14:30:26 2023 : Debug:   }
Tue Jul 18 14:30:26 2023 : Debug:   # Loading module "realmpercent" from file /usr/local/freeradius/etc/raddb/mods-enabled/realm
Tue Jul 18 14:30:26 2023 : Debug:   realm realmpercent {
Tue Jul 18 14:30:26 2023 : Debug:       format = "suffix"
Tue Jul 18 14:30:26 2023 : Debug:       delimiter = "%"
Tue Jul 18 14:30:26 2023 : Debug:       ignore_default = no
Tue Jul 18 14:30:26 2023 : Debug:       ignore_null = no
Tue Jul 18 14:30:26 2023 : Debug:   }
Tue Jul 18 14:30:26 2023 : Debug:   # Loading module "ntdomain" from file /usr/local/freeradius/etc/raddb/mods-enabled/realm
Tue Jul 18 14:30:26 2023 : Debug:   realm ntdomain {
Tue Jul 18 14:30:26 2023 : Debug:       format = "prefix"
Tue Jul 18 14:30:26 2023 : Debug:       delimiter = "\\"
Tue Jul 18 14:30:26 2023 : Debug:       ignore_default = no
Tue Jul 18 14:30:26 2023 : Debug:       ignore_null = no
Tue Jul 18 14:30:26 2023 : Debug:   }
Tue Jul 18 14:30:26 2023 : Debug: Loading rlm_expr with path: /usr/local/freeradius/lib/rlm_expr.so
Tue Jul 18 14:30:26 2023 : Debug: Loaded rlm_expr, checking if it's valid
Tue Jul 18 14:30:26 2023 : Debug:   # Loaded module rlm_expr
Tue Jul 18 14:30:26 2023 : Debug:   # Loading module "expr" from file /usr/local/freeradius/etc/raddb/mods-enabled/expr
Tue Jul 18 14:30:26 2023 : Debug:   expr {
Tue Jul 18 14:30:26 2023 : Debug:       safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ"
Tue Jul 18 14:30:26 2023 : Debug:   }
Tue Jul 18 14:30:26 2023 : Debug:   instantiate {
Tue Jul 18 14:30:26 2023 : Debug:   }
Tue Jul 18 14:30:26 2023 : Debug:   # Instantiating module "preprocess" from file /usr/local/freeradius/etc/raddb/mods-enabled/preprocess
Tue Jul 18 14:30:26 2023 : Debug: reading pairlist file /usr/local/freeradius/etc/raddb/mods-config/preprocess/huntgroups
Tue Jul 18 14:30:26 2023 : Debug: reading pairlist file /usr/local/freeradius/etc/raddb/mods-config/preprocess/hints
Tue Jul 18 14:30:26 2023 : Debug:   # Instantiating module "python3_ipaddress_username" from file /usr/local/freeradius/etc/raddb/mods-enabled/python3_ipaddress_username
Tue Jul 18 14:30:26 2023 : Info: Python version: 3.10.6 (main, May 29 2023, 11:10:38) [GCC 11.3.0]
*** instantiate ***
{'request': None, 'reply': None, 'config': None, 'session-state': None, 'proxy-request': None, 'proxy-reply': None}
<pymysql.connections.Connection object at 0x7f6af93cfc10>
[{'id': 12117, 'uid': 5872, 'ip': 3232269124, 'hostname': 'len10', 'network': 0, 'mac': '90:94:e4:ed:ad:f5', 'disable': 0, 'forced': 0, 'blocktime': 0, 'expire': datetime.date(2030, 1, 1), 'seen': 0, 'comments': '', 'vid': 3299, 'nas': 123638406563423, 'option_82': 0, 'ports': '15', 'boot_file': '', 'changed': datetime.datetime(2023, 2, 4, 12, 21, 1)}, {'id': 11594, 'uid': 5543, 'ip': 3232268844, 'hostname': 'sp7ak51', 'network': 0, 'mac': 'e8:48:b8:99:87:eb', 'disable': 0, 'forced': 0, 'blocktime': 0, 'expire': datetime.date(2030, 1, 1), 'seen': 0, 'comments': '', 'vid': 3051, 'nas': 123638407509972, 'option_82': 0, 'ports': '3', 'boot_file': '', 'changed': datetime.datetime(2022, 3, 1, 11, 40, 43)}, {'id': 10623, 'uid': 5107, 'ip': 3232271011, 'hostname': 'en2k30', 'network': 0, 'mac': '50:d4:f7:af:db:23', 'disable': 0, 'forced': 0, 'blocktime': 0, 'expire': '0000-00-00', 'seen': 0, 'comments': '', 'vid': 2002, 'nas': 123638407276559, 'option_82': 0, 'ports': '10', 'boot_file': '', 'changed': datetime.datetime(2020, 2, 4, 16, 32, 35)}, {'id': 9368, 'uid': 4569, 'ip': 3232269914, 'hostname': 'sasha7', 'network': 0, 'mac': 'e8:94:f6:8f:28:03', 'disable': 0, 'forced': 0, 'blocktime': 0, 'expire': '0000-00-00', 'seen': 0, 'comments': '', 'vid': 3096, 'nas': 80796821719, 'option_82': 0, 'ports': '12', 'boot_file': '', 'changed': datetime.datetime(2017, 1, 26, 11, 22, 49)}, {'id': 4716, 'uid': 78, 'ip': 3232269515, 'hostname': 'milana', 'network': 0, 'mac': '00:1a:92:97:72:2f', 'disable': 0, 'forced': 0, 'blocktime': 0, 'expire': '0000-00-00', 'seen': 0, 'comments': '', 'vid': 3063, 'nas': 80796805856, 'option_82': 0, 'ports': '1', 'boot_file': '', 'changed': datetime.datetime(2012, 4, 28, 16, 21, 20)}, {'id': 9793, 'uid': 1407, 'ip': 3232271064, 'hostname': 'doshenko', 'network': 0, 'mac': '3c:84:6a:00:d6:89', 'disable': 0, 'forced': 0, 'blocktime': 0, 'expire': '0000-00-00', 'seen': 0, 'comments': '', 'vid': 3002, 'nas': 123638406465897, 'option_82': 0, 'ports': '11', 'boot_file': '', 'changed': datetime.datetime(2018, 3, 21, 14, 28, 21)}, {'id': 11222, 'uid': 3454, 'ip': 3232268895, 'hostname': 'len_1', 'network': 0, 'mac': 'a0:f3:c1:ee:7f:e9', 'disable': 0, 'forced': 0, 'blocktime': 0, 'expire': '0000-00-00', 'seen': 0, 'comments': '', 'vid': 3253, 'nas': 190154839202432, 'option_82': 0, 'ports': '14', 'boot_file': '', 'changed': datetime.datetime(2021, 2, 23, 13, 14, 35)}, {'id': 4712, 'uid': 88, 'ip': 3232268412, 'hostname': 'aspera', 'network': 0, 'mac': '34:60:f9:6b:b5:ee', 'disable': 0, 'forced': 0, 'blocktime': 0, 'expire': '0000-00-00', 'seen': 0, 'comments': '', 'vid': 3063, 'nas': 80796805856, 'option_82': 0, 'ports': '1', 'boot_file': '', 'changed': datetime.datetime(2012, 4, 28, 15, 47, 19)}, {'id': 11209, 'uid': 2211, 'ip': 3232270497, 'hostname': 'zlata', 'network': 0, 'mac': '64:70:02:be:c7:4f', 'disable': 0, 'forced': 0, 'blocktime': 0, 'expire': '0000-00-00', 'seen': 0, 'comments': '', 'vid': 3074, 'nas': 123638407500547, 'option_82': 0, 'ports': '1', 'boot_file': '', 'changed': datetime.datetime(2021, 2, 17, 17, 31, 52)}, {'id': 7103, 'uid': 1238, 'ip': 3232270609, 'hostname': 'loki', 'network': 0, 'mac': 'f4:f2:6d:4c:2a:93', 'disable': 0, 'forced': 0, 'blocktime': 0, 'expire': '0000-00-00', 'seen': 0, 'comments': '', 'vid': 3077, 'nas': 123638408947744, 'option_82': 0, 'ports': '18', 'boot_file': '', 'changed': datetime.datetime(2014, 1, 18, 15, 3)}]
****************
Tue Jul 18 14:30:26 2023 : Debug:   # Instantiating module "python3_service_username" from file /usr/local/freeradius/etc/raddb/mods-enabled/python3_service_username
Fatal Python error: drop_gil: drop_gil: GIL is not locked
Python runtime state: initialized

Current thread 0x00007f6af9fc6740 (most recent call first):
  <no Python frame>

Extension modules: radiusd, _cffi_backend (total: 2)
Aborted (core dumped)

Relevant log output from client utilities

rlm_python

Backtrace from LLDB or GDB

root@radius:/usr/local/freeradius/sbin# gdb --args ./radiusd -XXXX
GNU gdb (Ubuntu 12.1-0ubuntu1~22.04) 12.1
Copyright (C) 2022 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from ./radiusd...
(gdb) run
Starting program: /usr/local/freeradius/sbin/radiusd -XXXX
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Tue Jul 18 14:34:33 2023 : Debug: Server was built with:
Tue Jul 18 14:34:33 2023 : Debug:   accounting                : yes
Tue Jul 18 14:34:33 2023 : Debug:   authentication            : yes
Tue Jul 18 14:34:33 2023 : Debug:   ascend-binary-attributes  : yes
Tue Jul 18 14:34:33 2023 : Debug:   coa                       : yes
Tue Jul 18 14:34:33 2023 : Debug:   recv-coa-from-home-server : no
Tue Jul 18 14:34:33 2023 : Debug:   control-socket            : yes
Tue Jul 18 14:34:33 2023 : Debug:   detail                    : yes
Tue Jul 18 14:34:33 2023 : Debug:   dhcp                      : yes
Tue Jul 18 14:34:33 2023 : Debug:   dynamic-clients           : yes
Tue Jul 18 14:34:33 2023 : Debug:   osfc2                     : no
Tue Jul 18 14:34:33 2023 : Debug:   proxy                     : yes
Tue Jul 18 14:34:33 2023 : Debug:   regex-pcre                : no
Tue Jul 18 14:34:33 2023 : Debug:   regex-posix               : yes
Tue Jul 18 14:34:33 2023 : Debug:   regex-posix-extended      : yes
Tue Jul 18 14:34:33 2023 : Debug:   session-management        : yes
Tue Jul 18 14:34:33 2023 : Debug:   stats                     : yes
Tue Jul 18 14:34:33 2023 : Debug:   systemd                   : no
Tue Jul 18 14:34:33 2023 : Debug:   tcp                       : yes
Tue Jul 18 14:34:33 2023 : Debug:   threads                   : yes
Tue Jul 18 14:34:33 2023 : Debug:   tls                       : yes
Tue Jul 18 14:34:33 2023 : Debug:   unlang                    : yes
Tue Jul 18 14:34:33 2023 : Debug:   vmps                      : yes
Tue Jul 18 14:34:33 2023 : Debug:   developer                 : yes
Tue Jul 18 14:34:33 2023 : Debug: Server core libs:
Tue Jul 18 14:34:33 2023 : Debug:   freeradius-server         : 3.2.4
Tue Jul 18 14:34:33 2023 : Debug:   talloc                    : 2.3.*
Tue Jul 18 14:34:33 2023 : Debug:   ssl                       : 3.0.0b dev
Tue Jul 18 14:34:33 2023 : Debug: Endianness:
Tue Jul 18 14:34:33 2023 : Debug:   little
Tue Jul 18 14:34:33 2023 : Debug: Compilation flags:
Tue Jul 18 14:34:33 2023 : Debug:   cppflags :
Tue Jul 18 14:34:33 2023 : Debug:   cflags   : -I. -Isrc -include src/freeradius-devel/autoconf.h -include src/freeradius-devel/build.h -include src/freeradius-devel/features.h -include src/freeradius-devel/radpaths.h -fno-strict-aliasing -Wno-date-time -g3 -Wall -std=c99 -D_GNU_SOURCE -D_REENTRANT -D_POSIX_PTHREAD_SEMANTICS -DOPENSSL_NO_KRB5 -Wshadow -Wpointer-arith -Wcast-qual -Wcast-align -Wwrite-strings -Wstrict-prototypes -Wmissing-prototypes -Wmissing-declarations -Wnested-externs -W -Wredundant-decls -Wundef -Wformat-y2k -Wno-format-extra-args -Wno-format-zero-length -Wno-cast-align -Wformat-nonliteral -Wformat-security -Wformat=2 -DWITH_VERIFY_PTR=1 -DIS_MODULE=1
Tue Jul 18 14:34:33 2023 : Debug:   ldflags  :
Tue Jul 18 14:34:33 2023 : Debug:   libs     : -lcrypto -lssl -ltalloc -latomic -lnsl -lresolv -ldl -lpthread
Tue Jul 18 14:34:33 2023 : Debug:
Tue Jul 18 14:34:33 2023 : Info: FreeRADIUS Version 3.2.4
Tue Jul 18 14:34:33 2023 : Info: Copyright (C) 1999-2022 The FreeRADIUS server project and contributors
Tue Jul 18 14:34:33 2023 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
Tue Jul 18 14:34:33 2023 : Info: PARTICULAR PURPOSE
Tue Jul 18 14:34:33 2023 : Info: You may redistribute copies of FreeRADIUS under the terms of the
Tue Jul 18 14:34:33 2023 : Info: GNU General Public License
Tue Jul 18 14:34:33 2023 : Info: For more information about these matters, see the file named COPYRIGHT
[Detaching after fork from child process 223655]
Tue Jul 18 14:34:33 2023 : Info: Starting - reading configuration files ...
Tue Jul 18 14:34:33 2023 : Debug: including dictionary file /usr/local/freeradius/share/freeradius/dictionary
Tue Jul 18 14:34:33 2023 : Debug: including dictionary file /usr/local/freeradius/share/freeradius/dictionary.dhcp
Tue Jul 18 14:34:33 2023 : Debug: including dictionary file /usr/local/freeradius/share/freeradius/dictionary.vqp
Tue Jul 18 14:34:33 2023 : Debug: including dictionary file /usr/local/freeradius/etc/raddb/dictionary
Tue Jul 18 14:34:33 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/radiusd.conf
Tue Jul 18 14:34:33 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/clients.conf
Tue Jul 18 14:34:33 2023 : Debug: including files in directory /usr/local/freeradius/etc/raddb/mods-enabled/
Tue Jul 18 14:34:33 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/mods-enabled/preprocess
Tue Jul 18 14:34:33 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/mods-enabled/digest
Tue Jul 18 14:34:33 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/mods-enabled/chap
Tue Jul 18 14:34:33 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/mods-enabled/python3_ipaddress_username
Tue Jul 18 14:34:33 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/mods-enabled/echo
Tue Jul 18 14:34:33 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/mods-enabled/python3_service_username
Tue Jul 18 14:34:33 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/mods-enabled/pap
Tue Jul 18 14:34:33 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/mods-enabled/files
Tue Jul 18 14:34:33 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/mods-enabled/realm
Tue Jul 18 14:34:33 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/mods-enabled/expr
Tue Jul 18 14:34:33 2023 : Debug: including files in directory /usr/local/freeradius/etc/raddb/policy.d/
Tue Jul 18 14:34:33 2023 : Debug: including files in directory /usr/local/freeradius/etc/raddb/sites-enabled/
Tue Jul 18 14:34:33 2023 : Debug: including configuration file /usr/local/freeradius/etc/raddb/sites-enabled/default
Tue Jul 18 14:34:33 2023 : Debug: main {
Tue Jul 18 14:34:33 2023 : Debug:  security {
Tue Jul 18 14:34:33 2023 : Debug:   user = "freerad"
Tue Jul 18 14:34:33 2023 : Debug:   group = "freerad"
Tue Jul 18 14:34:33 2023 : Debug:   allow_core_dumps = yes
Tue Jul 18 14:34:33 2023 : Debug:  }
Tue Jul 18 14:34:33 2023 : Debug:   name = "freeradius"
Tue Jul 18 14:34:33 2023 : Debug:   prefix = "/usr/local/freeradius"
Tue Jul 18 14:34:33 2023 : Debug:   localstatedir = "/usr/local/freeradius/var"
Tue Jul 18 14:34:33 2023 : Debug:   logdir = "/usr/local/freeradius/var/log/radius"
Tue Jul 18 14:34:33 2023 : Debug:   run_dir = "/usr/local/freeradius/var/run/freeradius"
Tue Jul 18 14:34:33 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[7]: The item 'raddbdir' is defined, but is unused by the configuration
Tue Jul 18 14:34:33 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[8]: The item 'radacctdir' is defined, but is unused by the configuration
Tue Jul 18 14:34:33 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[20]: The item 'libdir' is defined, but is unused by the configuration
Tue Jul 18 14:34:33 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[21]: The item 'pidfile' is defined, but is unused by the configuration
Tue Jul 18 14:34:33 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[23]: The item 'correct_escapes' is defined, but is unused by the configuration
Tue Jul 18 14:34:33 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[25]: The item 'max_request_time' is defined, but is unused by the configuration
Tue Jul 18 14:34:33 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[26]: The item 'cleanup_delay' is defined, but is unused by the configuration
Tue Jul 18 14:34:33 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[27]: The item 'max_requests' is defined, but is unused by the configuration
Tue Jul 18 14:34:33 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[28]: The item 'hostname_lookups' is defined, but is unused by the configuration
Tue Jul 18 14:34:33 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[43]: The item 'checkrad' is defined, but is unused by the configuration
Tue Jul 18 14:34:33 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[56]: The item 'proxy_requests' is defined, but is unused by the configuration
Tue Jul 18 14:34:33 2023 : Debug: }
Tue Jul 18 14:34:33 2023 : Info: Core dumps are enabled
Tue Jul 18 14:34:33 2023 : Debug: main {
Tue Jul 18 14:34:33 2023 : Debug:   name = "freeradius"
Tue Jul 18 14:34:33 2023 : Debug:   prefix = "/usr/local/freeradius"
Tue Jul 18 14:34:33 2023 : Debug:   localstatedir = "/usr/local/freeradius/var"
Tue Jul 18 14:34:33 2023 : Debug:   sbindir = "/usr/local/freeradius/sbin"
Tue Jul 18 14:34:33 2023 : Debug:   logdir = "/usr/local/freeradius/var/log/radius"
Tue Jul 18 14:34:33 2023 : Debug:   run_dir = "/usr/local/freeradius/var/run/freeradius"
Tue Jul 18 14:34:33 2023 : Debug:   libdir = "/usr/local/freeradius/lib"
Tue Jul 18 14:34:33 2023 : Debug:   radacctdir = "/usr/local/freeradius/var/log/radius/radacct"
Tue Jul 18 14:34:33 2023 : Debug:   hostname_lookups = no
Tue Jul 18 14:34:33 2023 : Debug:   max_request_time = 30
Tue Jul 18 14:34:33 2023 : Debug:   cleanup_delay = 5
Tue Jul 18 14:34:33 2023 : Debug:   max_requests = 16384
Tue Jul 18 14:34:33 2023 : Debug:   postauth_client_lost = no
Tue Jul 18 14:34:33 2023 : Debug:   pidfile = "/usr/local/freeradius/var/run/freeradius/freeradius.pid"
Tue Jul 18 14:34:33 2023 : Debug:   checkrad = "/usr/local/freeradius/sbin/checkrad"
Tue Jul 18 14:34:33 2023 : Debug:   debug_level = 0
Tue Jul 18 14:34:33 2023 : Debug:   proxy_requests = no
Tue Jul 18 14:34:33 2023 : Debug:  log {
Tue Jul 18 14:34:33 2023 : Debug:   stripped_names = no
Tue Jul 18 14:34:33 2023 : Debug:   auth = yes
Tue Jul 18 14:34:33 2023 : Debug:   auth_badpass = yes
Tue Jul 18 14:34:33 2023 : Debug:   auth_goodpass = yes
Tue Jul 18 14:34:33 2023 : Debug:   colourise = yes
Tue Jul 18 14:34:33 2023 : Debug:   msg_denied = "You are already logged in - access denied"
Tue Jul 18 14:34:33 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[31]: The item 'destination' is defined, but is unused by the configuration
Tue Jul 18 14:34:33 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[33]: The item 'file' is defined, but is unused by the configuration
Tue Jul 18 14:34:33 2023 : Debug:  }
Tue Jul 18 14:34:33 2023 : Debug:  resources {
Tue Jul 18 14:34:33 2023 : Debug:  }
Tue Jul 18 14:34:33 2023 : Debug:  security {
Tue Jul 18 14:34:33 2023 : Debug:   max_attributes = 0
Tue Jul 18 14:34:33 2023 : Debug:   reject_delay = 0.000000
Tue Jul 18 14:34:33 2023 : Debug:   status_server = no
Tue Jul 18 14:34:33 2023 : Debug:   allow_vulnerable_openssl = "no"
Tue Jul 18 14:34:33 2023 : Debug:  }
Tue Jul 18 14:34:33 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[7]: The item 'raddbdir' is defined, but is unused by the configuration
Tue Jul 18 14:34:33 2023 : Warning: /usr/local/freeradius/etc/raddb/radiusd.conf[23]: The item 'correct_escapes' is defined, but is unused by the configuration
Tue Jul 18 14:34:33 2023 : Debug: }
Tue Jul 18 14:34:33 2023 : Debug: radiusd: #### Loading Realms and Home Servers ####
Tue Jul 18 14:34:33 2023 : Debug: radiusd: #### Loading Clients ####
Tue Jul 18 14:34:33 2023 : Debug:  client localhost {
Tue Jul 18 14:34:33 2023 : Debug:   ipaddr = 127.0.0.1
Tue Jul 18 14:34:33 2023 : Debug:   require_message_authenticator = no
Tue Jul 18 14:34:33 2023 : Debug:   secret = "testing123"
Tue Jul 18 14:34:33 2023 : Debug:   nas_type = "other"
Tue Jul 18 14:34:33 2023 : Debug:   proto = "*"
Tue Jul 18 14:34:33 2023 : Debug:   limit {
Tue Jul 18 14:34:33 2023 : Debug:       max_connections = 16
Tue Jul 18 14:34:33 2023 : Debug:       lifetime = 0
Tue Jul 18 14:34:33 2023 : Debug:       idle_timeout = 30
Tue Jul 18 14:34:33 2023 : Debug:   }
Tue Jul 18 14:34:33 2023 : Debug:  }
Tue Jul 18 14:34:33 2023 : Debug: Adding client 127.0.0.1/32 (127.0.0.1) to prefix tree 32
Tue Jul 18 14:34:33 2023 : Debug:  client localhost_ipv6 {
Tue Jul 18 14:34:33 2023 : Debug:   ipv6addr = ::1
Tue Jul 18 14:34:33 2023 : Debug:   require_message_authenticator = no
Tue Jul 18 14:34:33 2023 : Debug:   secret = "testing123"
Tue Jul 18 14:34:33 2023 : Debug:   limit {
Tue Jul 18 14:34:33 2023 : Debug:       max_connections = 16
Tue Jul 18 14:34:33 2023 : Debug:       lifetime = 0
Tue Jul 18 14:34:33 2023 : Debug:       idle_timeout = 30
Tue Jul 18 14:34:33 2023 : Debug:   }
Tue Jul 18 14:34:33 2023 : Debug:  }
Tue Jul 18 14:34:33 2023 : Debug: Adding client ::1/128 (::1) to prefix tree 128
Tue Jul 18 14:34:33 2023 : Info: Found debugger attached
Tue Jul 18 14:34:33 2023 : Debug:  # Creating Auth-Type = PYTHON_IPADRESS
Tue Jul 18 14:34:33 2023 : Debug:  # Creating Auth-Type = PYTHON_SERVICE
Tue Jul 18 14:34:33 2023 : Debug: radiusd: #### Instantiating modules ####
Tue Jul 18 14:34:33 2023 : Debug:  modules {
Tue Jul 18 14:34:33 2023 : Debug: Loading rlm_preprocess with path: /usr/local/freeradius/lib/rlm_preprocess.so
Tue Jul 18 14:34:33 2023 : Debug: Loaded rlm_preprocess, checking if it's valid
Tue Jul 18 14:34:33 2023 : Debug:   # Loaded module rlm_preprocess
Tue Jul 18 14:34:33 2023 : Debug:   # Loading module "preprocess" from file /usr/local/freeradius/etc/raddb/mods-enabled/preprocess
Tue Jul 18 14:34:33 2023 : Debug:   preprocess {
Tue Jul 18 14:34:33 2023 : Debug:       huntgroups = "/usr/local/freeradius/etc/raddb/mods-config/preprocess/huntgroups"
Tue Jul 18 14:34:33 2023 : Debug:       hints = "/usr/local/freeradius/etc/raddb/mods-config/preprocess/hints"
Tue Jul 18 14:34:33 2023 : Debug:       with_ascend_hack = no
Tue Jul 18 14:34:33 2023 : Debug:       ascend_channels_per_line = 23
Tue Jul 18 14:34:33 2023 : Debug:       with_ntdomain_hack = no
Tue Jul 18 14:34:33 2023 : Debug:       with_specialix_jetstream_hack = no
Tue Jul 18 14:34:33 2023 : Debug:       with_cisco_vsa_hack = no
Tue Jul 18 14:34:33 2023 : Debug:       with_alvarion_vsa_hack = no
Tue Jul 18 14:34:33 2023 : Debug:   }
Tue Jul 18 14:34:33 2023 : Debug: Loading rlm_digest with path: /usr/local/freeradius/lib/rlm_digest.so
Tue Jul 18 14:34:33 2023 : Debug: Loaded rlm_digest, checking if it's valid
Tue Jul 18 14:34:33 2023 : Debug:   # Loaded module rlm_digest
Tue Jul 18 14:34:33 2023 : Debug:   # Loading module "digest" from file /usr/local/freeradius/etc/raddb/mods-enabled/digest
Tue Jul 18 14:34:33 2023 : Debug: Loading rlm_chap with path: /usr/local/freeradius/lib/rlm_chap.so
Tue Jul 18 14:34:33 2023 : Debug: Loaded rlm_chap, checking if it's valid
Tue Jul 18 14:34:33 2023 : Debug:   # Loaded module rlm_chap
Tue Jul 18 14:34:33 2023 : Debug:   # Loading module "chap" from file /usr/local/freeradius/etc/raddb/mods-enabled/chap
Tue Jul 18 14:34:33 2023 : Debug: Loading rlm_python3 with path: /usr/local/freeradius/lib/rlm_python3.so
Tue Jul 18 14:34:33 2023 : Debug: Loaded rlm_python3, checking if it's valid
Tue Jul 18 14:34:33 2023 : Debug:   # Loaded module rlm_python3
Tue Jul 18 14:34:33 2023 : Debug:   # Loading module "python3_ipaddress_username" from file /usr/local/freeradius/etc/raddb/mods-enabled/python3_ipaddress_username
Tue Jul 18 14:34:33 2023 : Debug:   python3 python3_ipaddress_username {
Tue Jul 18 14:34:33 2023 : Debug:       mod_instantiate = "ipaddress_username"
Tue Jul 18 14:34:33 2023 : Debug:       func_instantiate = "instantiate"
Tue Jul 18 14:34:33 2023 : Debug:       mod_authorize = "ipaddress_username"
Tue Jul 18 14:34:33 2023 : Debug:       func_authorize = "authorize"
Tue Jul 18 14:34:33 2023 : Debug:       mod_authenticate = "ipaddress_username"
Tue Jul 18 14:34:33 2023 : Debug:       func_authenticate = "authenticate"
Tue Jul 18 14:34:33 2023 : Debug:       mod_preacct = "ipaddress_username"
Tue Jul 18 14:34:33 2023 : Debug:       func_preacct = "preacct"
Tue Jul 18 14:34:33 2023 : Debug:       mod_accounting = "ipaddress_username"
Tue Jul 18 14:34:33 2023 : Debug:       func_accounting = "accounting"
Tue Jul 18 14:34:33 2023 : Debug:       mod_checksimul = "ipaddress_username"
Tue Jul 18 14:34:33 2023 : Debug:       func_checksimul = "checksimul"
Tue Jul 18 14:34:33 2023 : Debug:       mod_pre_proxy = "ipaddress_username"
Tue Jul 18 14:34:33 2023 : Debug:       func_pre_proxy = "pre_proxy"
Tue Jul 18 14:34:33 2023 : Debug:       mod_post_proxy = "ipaddress_username"
Tue Jul 18 14:34:33 2023 : Debug:       func_post_proxy = "post_proxy"
Tue Jul 18 14:34:33 2023 : Debug:       mod_post_auth = "ipaddress_username"
Tue Jul 18 14:34:33 2023 : Debug:       func_post_auth = "post_auth"
Tue Jul 18 14:34:33 2023 : Debug:       mod_recv_coa = "ipaddress_username"
Tue Jul 18 14:34:33 2023 : Debug:       func_recv_coa = "recv_coa"
Tue Jul 18 14:34:33 2023 : Debug:       mod_send_coa = "ipaddress_username"
Tue Jul 18 14:34:33 2023 : Debug:       func_send_coa = "send_coa"
Tue Jul 18 14:34:33 2023 : Debug:       mod_detach = "ipaddress_username"
Tue Jul 18 14:34:33 2023 : Debug:       func_detach = "detach"
Tue Jul 18 14:34:33 2023 : Debug:       python_path = ":/usr/local/freeradius/etc/raddb/mods-config/python3"
Tue Jul 18 14:34:33 2023 : Debug:       cext_compat = yes
Tue Jul 18 14:34:33 2023 : Debug:       pass_all_vps = no
Tue Jul 18 14:34:33 2023 : Debug:       pass_all_vps_dict = yes
Tue Jul 18 14:34:33 2023 : Debug:   }
Tue Jul 18 14:34:33 2023 : Debug: Loading rlm_exec with path: /usr/local/freeradius/lib/rlm_exec.so
Tue Jul 18 14:34:33 2023 : Debug: Loaded rlm_exec, checking if it's valid
Tue Jul 18 14:34:33 2023 : Debug:   # Loaded module rlm_exec
Tue Jul 18 14:34:33 2023 : Debug:   # Loading module "echo" from file /usr/local/freeradius/etc/raddb/mods-enabled/echo
Tue Jul 18 14:34:33 2023 : Debug:   exec echo {
Tue Jul 18 14:34:33 2023 : Debug:       wait = yes
Tue Jul 18 14:34:33 2023 : Debug:       program = "/bin/echo %{User-Name}"
Tue Jul 18 14:34:33 2023 : Debug:       input_pairs = "request"
Tue Jul 18 14:34:33 2023 : Debug:       output_pairs = "reply"
Tue Jul 18 14:34:33 2023 : Debug:       shell_escape = yes
Tue Jul 18 14:34:33 2023 : Debug:   }
Tue Jul 18 14:34:33 2023 : Debug:   # Loading module "python3_service_username" from file /usr/local/freeradius/etc/raddb/mods-enabled/python3_service_username
Tue Jul 18 14:34:33 2023 : Debug:   python3 python3_service_username {
Tue Jul 18 14:34:33 2023 : Debug:       mod_instantiate = "example"
Tue Jul 18 14:34:33 2023 : Debug:       func_instantiate = "instantiate"
Tue Jul 18 14:34:33 2023 : Debug:       mod_authorize = "example"
Tue Jul 18 14:34:33 2023 : Debug:       func_authorize = "authorize"
Tue Jul 18 14:34:33 2023 : Debug:       mod_authenticate = "example"
Tue Jul 18 14:34:33 2023 : Debug:       func_authenticate = "authenticate"
Tue Jul 18 14:34:33 2023 : Debug:       mod_preacct = "example"
Tue Jul 18 14:34:33 2023 : Debug:       func_preacct = "preacct"
Tue Jul 18 14:34:33 2023 : Debug:       mod_accounting = "example"
Tue Jul 18 14:34:33 2023 : Debug:       func_accounting = "accounting"
Tue Jul 18 14:34:33 2023 : Debug:       mod_checksimul = "example"
Tue Jul 18 14:34:33 2023 : Debug:       func_checksimul = "checksimul"
Tue Jul 18 14:34:33 2023 : Debug:       mod_pre_proxy = "example"
Tue Jul 18 14:34:33 2023 : Debug:       func_pre_proxy = "pre_proxy"
Tue Jul 18 14:34:33 2023 : Debug:       mod_post_proxy = "example"
Tue Jul 18 14:34:33 2023 : Debug:       func_post_proxy = "post_proxy"
Tue Jul 18 14:34:33 2023 : Debug:       mod_post_auth = "example"
Tue Jul 18 14:34:33 2023 : Debug:       func_post_auth = "post_auth"
Tue Jul 18 14:34:33 2023 : Debug:       mod_recv_coa = "example"
Tue Jul 18 14:34:33 2023 : Debug:       func_recv_coa = "recv_coa"
Tue Jul 18 14:34:33 2023 : Debug:       mod_send_coa = "example"
Tue Jul 18 14:34:33 2023 : Debug:       func_send_coa = "send_coa"
Tue Jul 18 14:34:33 2023 : Debug:       mod_detach = "example"
Tue Jul 18 14:34:33 2023 : Debug:       func_detach = "detach"
Tue Jul 18 14:34:33 2023 : Debug:       python_path = ":/usr/local/freeradius/etc/raddb/mods-config/python3"
Tue Jul 18 14:34:33 2023 : Debug:       cext_compat = yes
Tue Jul 18 14:34:33 2023 : Debug:       pass_all_vps = no
Tue Jul 18 14:34:33 2023 : Debug:       pass_all_vps_dict = yes
Tue Jul 18 14:34:33 2023 : Debug:   }
Tue Jul 18 14:34:33 2023 : Debug: Loading rlm_pap with path: /usr/local/freeradius/lib/rlm_pap.so
Tue Jul 18 14:34:33 2023 : Debug: Loaded rlm_pap, checking if it's valid
Tue Jul 18 14:34:33 2023 : Debug:   # Loaded module rlm_pap
Tue Jul 18 14:34:33 2023 : Debug:   # Loading module "pap" from file /usr/local/freeradius/etc/raddb/mods-enabled/pap
Tue Jul 18 14:34:33 2023 : Debug:   pap {
Tue Jul 18 14:34:33 2023 : Debug:       normalise = yes
Tue Jul 18 14:34:33 2023 : Debug:   }
Tue Jul 18 14:34:33 2023 : Debug:   # Loading module "module_pap_1" from file /usr/local/freeradius/etc/raddb/mods-enabled/pap
Tue Jul 18 14:34:33 2023 : Debug:   pap module_pap_1 {
Tue Jul 18 14:34:33 2023 : Debug:       normalise = yes
Tue Jul 18 14:34:33 2023 : Debug:   }
Tue Jul 18 14:34:33 2023 : Debug:   # Loading module "module_pap_2" from file /usr/local/freeradius/etc/raddb/mods-enabled/pap
Tue Jul 18 14:34:33 2023 : Debug:   pap module_pap_2 {
Tue Jul 18 14:34:33 2023 : Debug:       normalise = yes
Tue Jul 18 14:34:33 2023 : Debug:   }
Tue Jul 18 14:34:33 2023 : Debug: Loading rlm_files with path: /usr/local/freeradius/lib/rlm_files.so
Tue Jul 18 14:34:33 2023 : Debug: Loaded rlm_files, checking if it's valid
Tue Jul 18 14:34:33 2023 : Debug:   # Loaded module rlm_files
Tue Jul 18 14:34:33 2023 : Debug:   # Loading module "module_files_1" from file /usr/local/freeradius/etc/raddb/mods-enabled/files
Tue Jul 18 14:34:33 2023 : Debug:   files module_files_1 {
Tue Jul 18 14:34:33 2023 : Debug:       filename = "/usr/local/freeradius/etc/raddb/mods-config/module_files_1/authorize"
Tue Jul 18 14:34:33 2023 : Debug:       usersfile = "/usr/local/freeradius/etc/raddb/mods-config/module_files_1/authorize"
Tue Jul 18 14:34:33 2023 : Debug:   }
Tue Jul 18 14:34:33 2023 : Debug:   # Loading module "module_files_2" from file /usr/local/freeradius/etc/raddb/mods-enabled/files
Tue Jul 18 14:34:33 2023 : Debug:   files module_files_2 {
Tue Jul 18 14:34:33 2023 : Debug:       filename = "/usr/local/freeradius/etc/raddb/mods-config/module_files_2/authorize"
Tue Jul 18 14:34:33 2023 : Debug:       usersfile = "/usr/local/freeradius/etc/raddb/mods-config/module_files_2/authorize"
Tue Jul 18 14:34:33 2023 : Debug:   }
Tue Jul 18 14:34:33 2023 : Debug: Loading rlm_realm with path: /usr/local/freeradius/lib/rlm_realm.so
Tue Jul 18 14:34:33 2023 : Debug: Loaded rlm_realm, checking if it's valid
Tue Jul 18 14:34:33 2023 : Debug:   # Loaded module rlm_realm
Tue Jul 18 14:34:33 2023 : Debug:   # Loading module "IPASS" from file /usr/local/freeradius/etc/raddb/mods-enabled/realm
Tue Jul 18 14:34:33 2023 : Debug:   realm IPASS {
Tue Jul 18 14:34:33 2023 : Debug:       format = "prefix"
Tue Jul 18 14:34:33 2023 : Debug:       delimiter = "/"
Tue Jul 18 14:34:33 2023 : Debug:       ignore_default = no
Tue Jul 18 14:34:33 2023 : Debug:       ignore_null = no
Tue Jul 18 14:34:33 2023 : Debug:   }
Tue Jul 18 14:34:33 2023 : Debug:   # Loading module "suffix" from file /usr/local/freeradius/etc/raddb/mods-enabled/realm
Tue Jul 18 14:34:33 2023 : Debug:   realm suffix {
Tue Jul 18 14:34:33 2023 : Debug:       format = "suffix"
Tue Jul 18 14:34:33 2023 : Debug:       delimiter = "@"
Tue Jul 18 14:34:33 2023 : Debug:       ignore_default = no
Tue Jul 18 14:34:33 2023 : Debug:       ignore_null = no
Tue Jul 18 14:34:33 2023 : Debug:   }
Tue Jul 18 14:34:33 2023 : Debug:   # Loading module "bangpath" from file /usr/local/freeradius/etc/raddb/mods-enabled/realm
Tue Jul 18 14:34:33 2023 : Debug:   realm bangpath {
Tue Jul 18 14:34:33 2023 : Debug:       format = "prefix"
Tue Jul 18 14:34:33 2023 : Debug:       delimiter = "!"
Tue Jul 18 14:34:33 2023 : Debug:       ignore_default = no
Tue Jul 18 14:34:33 2023 : Debug:       ignore_null = no
Tue Jul 18 14:34:33 2023 : Debug:   }
Tue Jul 18 14:34:33 2023 : Debug:   # Loading module "realmpercent" from file /usr/local/freeradius/etc/raddb/mods-enabled/realm
Tue Jul 18 14:34:33 2023 : Debug:   realm realmpercent {
Tue Jul 18 14:34:33 2023 : Debug:       format = "suffix"
Tue Jul 18 14:34:33 2023 : Debug:       delimiter = "%"
Tue Jul 18 14:34:33 2023 : Debug:       ignore_default = no
Tue Jul 18 14:34:33 2023 : Debug:       ignore_null = no
Tue Jul 18 14:34:33 2023 : Debug:   }
Tue Jul 18 14:34:33 2023 : Debug:   # Loading module "ntdomain" from file /usr/local/freeradius/etc/raddb/mods-enabled/realm
Tue Jul 18 14:34:33 2023 : Debug:   realm ntdomain {
Tue Jul 18 14:34:33 2023 : Debug:       format = "prefix"
Tue Jul 18 14:34:33 2023 : Debug:       delimiter = "\\"
Tue Jul 18 14:34:33 2023 : Debug:       ignore_default = no
Tue Jul 18 14:34:33 2023 : Debug:       ignore_null = no
Tue Jul 18 14:34:33 2023 : Debug:   }
Tue Jul 18 14:34:33 2023 : Debug: Loading rlm_expr with path: /usr/local/freeradius/lib/rlm_expr.so
Tue Jul 18 14:34:33 2023 : Debug: Loaded rlm_expr, checking if it's valid
Tue Jul 18 14:34:33 2023 : Debug:   # Loaded module rlm_expr
Tue Jul 18 14:34:33 2023 : Debug:   # Loading module "expr" from file /usr/local/freeradius/etc/raddb/mods-enabled/expr
Tue Jul 18 14:34:33 2023 : Debug:   expr {
Tue Jul 18 14:34:33 2023 : Debug:       safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ"
Tue Jul 18 14:34:33 2023 : Debug:   }
Tue Jul 18 14:34:33 2023 : Debug:   instantiate {
Tue Jul 18 14:34:33 2023 : Debug:   }
Tue Jul 18 14:34:33 2023 : Debug:   # Instantiating module "preprocess" from file /usr/local/freeradius/etc/raddb/mods-enabled/preprocess
Tue Jul 18 14:34:33 2023 : Debug: reading pairlist file /usr/local/freeradius/etc/raddb/mods-config/preprocess/huntgroups
Tue Jul 18 14:34:33 2023 : Debug: reading pairlist file /usr/local/freeradius/etc/raddb/mods-config/preprocess/hints
Tue Jul 18 14:34:33 2023 : Debug:   # Instantiating module "python3_ipaddress_username" from file /usr/local/freeradius/etc/raddb/mods-enabled/python3_ipaddress_username
Tue Jul 18 14:34:33 2023 : Info: Python version: 3.10.6 (main, May 29 2023, 11:10:38) [GCC 11.3.0]
*** instantiate ***
{'request': None, 'reply': None, 'config': None, 'session-state': None, 'proxy-request': None, 'proxy-reply': None}
<pymysql.connections.Connection object at 0x7ffff6bcbc10>
[{'id': 12117, 'uid': 5872, 'ip': 3232269124, 'hostname': 'len10', 'network': 0, 'mac': '90:94:e4:ed:ad:f5', 'disable': 0, 'forced': 0, 'blocktime': 0, 'expire': datetime.date(2030, 1, 1), 'seen': 0, 'comments': '', 'vid': 3299, 'nas': 123638406563423, 'option_82': 0, 'ports': '15', 'boot_file': '', 'changed': datetime.datetime(2023, 2, 4, 12, 21, 1)}, {'id': 11594, 'uid': 5543, 'ip': 3232268844, 'hostname': 'sp7ak51', 'network': 0, 'mac': 'e8:48:b8:99:87:eb', 'disable': 0, 'forced': 0, 'blocktime': 0, 'expire': datetime.date(2030, 1, 1), 'seen': 0, 'comments': '', 'vid': 3051, 'nas': 123638407509972, 'option_82': 0, 'ports': '3', 'boot_file': '', 'changed': datetime.datetime(2022, 3, 1, 11, 40, 43)}, {'id': 10623, 'uid': 5107, 'ip': 3232271011, 'hostname': 'en2k30', 'network': 0, 'mac': '50:d4:f7:af:db:23', 'disable': 0, 'forced': 0, 'blocktime': 0, 'expire': '0000-00-00', 'seen': 0, 'comments': '', 'vid': 2002, 'nas': 123638407276559, 'option_82': 0, 'ports': '10', 'boot_file': '', 'changed': datetime.datetime(2020, 2, 4, 16, 32, 35)}, {'id': 9368, 'uid': 4569, 'ip': 3232269914, 'hostname': 'sasha7', 'network': 0, 'mac': 'e8:94:f6:8f:28:03', 'disable': 0, 'forced': 0, 'blocktime': 0, 'expire': '0000-00-00', 'seen': 0, 'comments': '', 'vid': 3096, 'nas': 80796821719, 'option_82': 0, 'ports': '12', 'boot_file': '', 'changed': datetime.datetime(2017, 1, 26, 11, 22, 49)}, {'id': 4716, 'uid': 78, 'ip': 3232269515, 'hostname': 'milana', 'network': 0, 'mac': '00:1a:92:97:72:2f', 'disable': 0, 'forced': 0, 'blocktime': 0, 'expire': '0000-00-00', 'seen': 0, 'comments': '', 'vid': 3063, 'nas': 80796805856, 'option_82': 0, 'ports': '1', 'boot_file': '', 'changed': datetime.datetime(2012, 4, 28, 16, 21, 20)}, {'id': 9793, 'uid': 1407, 'ip': 3232271064, 'hostname': 'doshenko', 'network': 0, 'mac': '3c:84:6a:00:d6:89', 'disable': 0, 'forced': 0, 'blocktime': 0, 'expire': '0000-00-00', 'seen': 0, 'comments': '', 'vid': 3002, 'nas': 123638406465897, 'option_82': 0, 'ports': '11', 'boot_file': '', 'changed': datetime.datetime(2018, 3, 21, 14, 28, 21)}, {'id': 11222, 'uid': 3454, 'ip': 3232268895, 'hostname': 'len_1', 'network': 0, 'mac': 'a0:f3:c1:ee:7f:e9', 'disable': 0, 'forced': 0, 'blocktime': 0, 'expire': '0000-00-00', 'seen': 0, 'comments': '', 'vid': 3253, 'nas': 190154839202432, 'option_82': 0, 'ports': '14', 'boot_file': '', 'changed': datetime.datetime(2021, 2, 23, 13, 14, 35)}, {'id': 4712, 'uid': 88, 'ip': 3232268412, 'hostname': 'aspera', 'network': 0, 'mac': '34:60:f9:6b:b5:ee', 'disable': 0, 'forced': 0, 'blocktime': 0, 'expire': '0000-00-00', 'seen': 0, 'comments': '', 'vid': 3063, 'nas': 80796805856, 'option_82': 0, 'ports': '1', 'boot_file': '', 'changed': datetime.datetime(2012, 4, 28, 15, 47, 19)}, {'id': 11209, 'uid': 2211, 'ip': 3232270497, 'hostname': 'zlata', 'network': 0, 'mac': '64:70:02:be:c7:4f', 'disable': 0, 'forced': 0, 'blocktime': 0, 'expire': '0000-00-00', 'seen': 0, 'comments': '', 'vid': 3074, 'nas': 123638407500547, 'option_82': 0, 'ports': '1', 'boot_file': '', 'changed': datetime.datetime(2021, 2, 17, 17, 31, 52)}, {'id': 7103, 'uid': 1238, 'ip': 3232270609, 'hostname': 'loki', 'network': 0, 'mac': 'f4:f2:6d:4c:2a:93', 'disable': 0, 'forced': 0, 'blocktime': 0, 'expire': '0000-00-00', 'seen': 0, 'comments': '', 'vid': 3077, 'nas': 123638408947744, 'option_82': 0, 'ports': '18', 'boot_file': '', 'changed': datetime.datetime(2014, 1, 18, 15, 3)}]
****************
Tue Jul 18 14:34:33 2023 : Debug:   # Instantiating module "python3_service_username" from file /usr/local/freeradius/etc/raddb/mods-enabled/python3_service_username
Fatal Python error: drop_gil: drop_gil: GIL is not locked
Python runtime state: initialized

Current thread 0x00007ffff77c2740 (most recent call first):
  <no Python frame>

Extension modules: radiusd, _cffi_backend (total: 2)

Program received signal SIGABRT, Aborted.
__pthread_kill_implementation (no_tid=0, signo=6, threadid=140737345496896) at ./nptl/pthread_kill.c:44
44  ./nptl/pthread_kill.c: No such file or directory.
sirmax123 commented 1 year ago

tested on

./radiusd -v
radiusd: FreeRADIUS Version 3.2.4 (git #892334968), for host x86_64-pc-linux-gnu, built on Jul 18 2023 at 12:20:50
FreeRADIUS Version 3.2.4
Copyright (C) 1999-2022 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
freeradius -v
radiusd: FreeRADIUS Version 3.0.26, for host x86_64-pc-linux-gnu, built on Jan  4 2023 at 03:23:09
FreeRADIUS Version 3.0.26
Copyright (C) 1999-2021 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

with same result

arr2036 commented 1 year ago

Please submit a PR with a testcase which reproduces this and we'll try to develop a fix. I'd also be interested to see if you still get the crash with master (v4) as that code is substantially different.

sirmax123 commented 1 year ago

do not know how to create PR, could you please provide me with an example?

Steps to reproduce:

Build:

  1. git clone https://github.com/FreeRADIUS/freeradius-server.git
  2. git checkout remotes/origin/v3.2.x
  3. ./configure; make; make install

Configure:

  1. Prepere radiusd.conf (no includes! all you need is in file!) /usr/local/freeradius/etc/raddb/radiusd.conf (path depends on your OS i guess, it is from Ubuntu 22.04)

prefix = /usr/local/freeradius exec_prefix = ${prefix} sysconfdir = ${prefix}/etc localstatedir = ${prefix}/var sbindir = ${exec_prefix}/sbin logdir = ${localstatedir}/log/radius raddbdir = ${sysconfdir}/raddb radacctdir = ${logdir}/radacct name = freeradius modconfdir = ${confdir}/mods-config

certdir = ${confdir}/certs

cadir = ${confdir}/certs

run_dir = ${localstatedir}/run/${name} libdir = ${exec_prefix}/lib pidfile = ${run_dir}/${name}.pid correct_escapes = true max_request_time = 30 cleanup_delay = 5 max_requests = 16384 hostname_lookups = no

log { destination = files colourise = yes file = ${logdir}/radius.log stripped_names = no auth = yes auth_badpass = yes auth_goodpass = yes msg_denied = "You are already logged in - access denied" } checkrad = ${sbindir}/checkrad security { user = freerad group = freerad allow_core_dumps = yes } proxy_requests = no

client 100.100.100.254 { secret = radius shortname = ASR1001 nastype = other }

client localhost { ipaddr = 127.0.0.1 proto = * secret = secret require_message_authenticator = no } thread pool { start_servers = 5 max_servers = 32 min_spare_servers = 3 max_spare_servers = 10 max_requests_per_server = 0 auto_limit_acct = no }

modules { python3 python3_ipaddress_username { python_path =":${modconfdir}/${.:name}" module = ipaddress_username pass_all_vps_dict = yes mod_instantiate = ${.module} func_instantiate = instantiate mod_detach = ${.module} func_detach = detach mod_authorize = ${.module} func_authorize = authorize mod_authenticate = ${.module} func_authenticate = authenticate mod_preacct = ${.module} func_preacct = preacct mod_accounting = ${.module} func_accounting = accounting mod_checksimul = ${.module} func_checksimul = checksimul mod_pre_proxy = ${.module} func_pre_proxy = pre_proxy mod_post_proxy = ${.module} func_post_proxy = post_proxy mod_post_auth = ${.module} func_post_auth = post_auth mod_recv_coa = ${.module} func_recv_coa = recv_coa mod_send_coa = ${.module} func_send_coa = send_coa }

python3 python3_service_username {
    python_path =":${modconfdir}/${.:name}"
    module = service_username
    pass_all_vps_dict = yes
    mod_instantiate = ${.module}
    func_instantiate = instantiate
    mod_detach = ${.module}
    func_detach = detach
    mod_authorize = ${.module}
    func_authorize = authorize
    mod_authenticate = ${.module}
    func_authenticate = authenticate
    mod_preacct = ${.module}
    func_preacct = preacct
    mod_accounting = ${.module}
    func_accounting = accounting
    mod_checksimul = ${.module}
    func_checksimul = checksimul
    mod_pre_proxy = ${.module}
    func_pre_proxy = pre_proxy
    mod_post_proxy = ${.module}
    func_post_proxy = post_proxy
    mod_post_auth = ${.module}
    func_post_auth = post_auth
    mod_recv_coa = ${.module}
    func_recv_coa = recv_coa
    mod_send_coa = ${.module}
    func_send_coa = send_coa
}

}

instantiate { }

policy { }

server default { listen { type = auth ipv4addr = * port = 1812 limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } }

listen {
    ipv4addr = *
    port = 1813
    type = acct
}
instantiate {
}
authorize {
    python3_ipaddress_username
    python3_service_username
}

authenticate {
    Auth-Type PYTHON_IPADRESS {
        python3_ipaddress_username
    }
    Auth-Type PYTHON_SERVICE {
        python3_service_username
    }
}

}


2. Fix `example.py` (from distribution): add 2 methods, just simple placeholders doing nothing:

def authenticate(p): print(" authenticate ") radiusd.radlog(radiusd.L_INFO, ' radlog call in authenticate ') print() print(p) print() print(radiusd.config) return radiusd.RLM_MODULE_OK

def checksimul(p): print(" checksimul ") radiusd.radlog(radiusd.L_INFO, ' radlog call in checksimul ') print() print(p) print() print(radiusd.config) return radiusd.RLM_MODULE_OK


3. Copy  `example.py` to `/usr/local/freeradius/etc/raddb/mods-config/python3/ipaddress_username.py` and to `/usr/local/freeradius/etc/raddb/mods-config/python3/service_username.py`
(path also depends on your system!)

4. Executer radiusd with command: `cd /usr/local/freeradius/sbin  && ./radiusd -XXXX`

5. Got an error:

instantiate {'request': None, 'reply': None, 'config': None, 'session-state': None, 'proxy-request': None, 'proxy-reply': None} Tue Jul 18 15:41:36 2023 : Debug: # Instantiating module "python3_service_username" from file /usr/local/freeradius/etc/raddb/radiusd.conf Fatal Python error: drop_gil: drop_gil: GIL is not locked Python runtime state: initialized

Current thread 0x00007f4164b2a740 (most recent call first):



Also I tried to build v4 but configuration is different and I still working on making simple working configuration (will update if I will be able to run rlm_python on v4)
jpereira commented 1 year ago

@sirmax123 Could you please perform your tests against the branch v32/fix-5111 in https://github.com/jpereira/freeradius-server/ ?

sirmax123 commented 1 year ago

@sirmax123 Could you please perform your tests against the branch v32/fix-5111 in https://github.com/jpereira/freeradius-server/ ?

Just built and tested, looks good to me:

git clone https://github.com/jpereira/freeradius-server.git
git switch v32/fix-5111
./configure  --prefix=/usr/local/freeradius
make
make install
 /usr/local/freeradius/sbin/radiusd -v
radiusd: FreeRADIUS Version 3.2.4 (git #d5b1f3644), for host x86_64-pc-linux-gnu, built on Jul 25 2023 at 15:00:40
FreeRADIUS Version 3.2.4
Copyright (C) 1999-2022 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
Tue Jul 25 15:24:22 2023 : Debug: (0) python3_ipaddress_username: Initialised new thread state 0x561d2b669a30
Tue Jul 25 15:24:22 2023 : Debug: (0) python3_ipaddress_username: Using thread state 0x561d2b669a30
*** authorize ***
Tue Jul 25 15:24:22 2023 : Info: *** radlog call in authorize ***

{'request': (('User-Name', 'SERVICE_IN_4120_OUT_4120'), ('User-Password', 'hello'), ('NAS-IP-Address', '10.90.1.213'), ('NAS-Port', '0'), ('Message-Authenticator', '0x44e06cbda100b814fca8f03a653870ff')), 'reply': None, 'config': None, 'session-state': None, 'proxy-request': None, 'proxy-reply': None}

{}
Tue Jul 25 15:24:22 2023 : Debug: (0)     modsingle[authorize]: returned from python3_ipaddress_username (rlm_python3)
Tue Jul 25 15:24:22 2023 : Debug: (0)     [python3_ipaddress_username] = ok
Tue Jul 25 15:24:22 2023 : Debug: (0)     modsingle[authorize]: calling python3_service_username (rlm_python3)
Tue Jul 25 15:24:22 2023 : Debug: (0) python3_service_username: Initialised new thread state 0x561d2b669c60
Tue Jul 25 15:24:22 2023 : Debug: (0) python3_service_username: Using thread state 0x561d2b669c60
*** authorize ***
Tue Jul 25 15:24:22 2023 : Info: *** radlog call in authorize ***

{'request': (('User-Name', 'SERVICE_IN_4120_OUT_4120'), ('User-Password', 'hello'), ('NAS-IP-Address', '10.90.1.213'), ('NAS-Port', '0'), ('Message-Authenticator', '0x44e06cbda100b814fca8f03a653870ff')), 'reply': None, 'config': None, 'session-state': None, 'proxy-request': None, 'proxy-reply': None}

{}
Tue Jul 25 15:24:22 2023 : Debug: (0)     modsingle[authorize]: returned from python3_service_username (rlm_python3)
Tue Jul 25 15:24:22 2023 : Debug: (0)     [python3_service_username] = ok
Tue Jul 25 15:24:22 2023 : Debug: (0)   } # authorize = ok
Tue Jul 25 15:24:22 2023 : ERROR: (0) No Auth-Type found: rejecting the user via Post-Auth-Type = Reject
Tue Jul 25 15:24:22 2023 : Debug: (0) Failed to authenticate the user
Tue Jul 25 15:24:22 2023 : Debug: (0) Using Post-Auth-Type Reject
Tue Jul 25 15:24:22 2023 : Debug: (0) Post-Auth-Type sub-section not found.  Ignoring.

(tested with radtest SERVICE_IN_4120_OUT_4120 hello localhost 0 secret command)

So, I think this issue can be marked as fixed when your patch is merged.

Thank you!

jpereira commented 1 year ago

Thank you @sirmax123 for the feedback.

@sirmax123 Could you please perform your tests against the branch v32/fix-5111 in https://github.com/jpereira/freeradius-server/ ?

Just built and tested, looks good to me:

alexs20 commented 1 month ago

Any chance that this fix will come to the upcoming release? We are also waiting for it.

---EDIT---

We are running a simple python script in docker based on freeradius/freeradius-server:3.2.6, and everything seems works fine except the radius shutdown process. When we stop it it complains about:

`Fatal Python error: drop_gil: drop_gil: GIL is not locked Python runtime state: initialized

Current thread 0x00007f13307c5080 (most recent call first): File "/lib/python3.10/socket.py", line 496 in _real_close File "/lib/python3.10/ssl.py", line 1362 in _real_close File "/lib/python3.10/socket.py", line 502 in close File "/lib/python3.10/http/client.py", line 961 in close File "/usr/local/lib/python3.10/dist-packages/urllib3/connection.py", line 318 in close File "/usr/local/lib/python3.10/dist-packages/botocore/awsrequest.py", line 80 in close File "/usr/local/lib/python3.10/dist-packages/urllib3/connectionpool.py", line 1180 in _close_pool_connections File "/lib/python3.10/weakref.py", line 591 in call File "/lib/python3.10/weakref.py", line 667 in _exitfunc

Extension modules: radiusd (total: 1) `

I presume it is related to the issue mentioned above.