Description
What type of defect/bug is this?
Unexpected behaviour (obvious or verified by project member)
How can the issue be reproduced?
Hi experts,
I am using the FreeRadius v4.0 with tacacs module to do some testing, and server side using the tac_plus.
I start FreeRadius server and I can see rlm_tacacs module will create 2 connecting sockets in pool by default, the connections are established, I wait for more than 3 minutes and do login test, and I can see rlm_tacacs module used the pre-created socket to do authentication request to tac_plus server, but server return PST, and I can't login, after 2 times failures, I can login successful.
netstat -anlp|grep tac_plus
tcp 0 0 0.0.0.0:49 0.0.0.0:* LISTEN 782597/tac_plus
tcp 0 0 127.0.0.1:49 127.0.0.1:56469 ESTABLISHED 2070836/tac_plus
tcp 0 0 127.0.0.1:49 127.0.0.1:39381 ESTABLISHED 2070840/tac_plus
tcp6 0 0 :::49 :::* LISTEN 782597/tac_plus
unix 2 [ ] DGRAM 1099435751 782597/tac_plus
netstat -anlp|grep radiusd
tcp 0 0 127.0.0.1:43123 127.0.0.1:1814 ESTABLISHED 2070789/radiusd
tcp 0 0 127.0.0.1:45567 127.0.0.1:1814 ESTABLISHED 2070789/radiusd
tcp 0 0 127.0.0.1:56853 127.0.0.1:1814 ESTABLISHED 2070789/radiusd
tcp 0 0 127.0.0.1:39381 127.0.0.1:49 ESTABLISHED 2070789/radiusd
tcp 0 0 127.0.0.1:40537 127.0.0.1:1814 ESTABLISHED 2070789/radiusd
tcp 0 0 127.0.0.1:56635 127.0.0.1:1814 ESTABLISHED 2070789/radiusd
tcp 0 0 127.0.0.1:56309 127.0.0.1:1814 ESTABLISHED 2070789/radiusd
tcp 0 0 127.0.0.1:37877 127.0.0.1:1814 ESTABLISHED 2070789/radiusd
tcp 0 0 127.0.0.1:36851 127.0.0.1:1814 ESTABLISHED 2070789/radiusd
tcp 0 0 127.0.0.1:56469 127.0.0.1:49 ESTABLISHED 2070789/radiusd
after 3 minutes:
netstat -anlp|grep tac_plus
tcp 0 0 0.0.0.0:49 0.0.0.0:* LISTEN 782597/tac_plus
tcp6 0 0 :::49 :::* LISTEN 782597/tac_plus
unix 2 [ ] DGRAM 1099435751 782597/tac_plus
netstat -anlp|grep radiusd
tcp 0 0 127.0.0.1:43123 127.0.0.1:1814 ESTABLISHED 2070789/radiusd
tcp 0 0 127.0.0.1:45567 127.0.0.1:1814 ESTABLISHED 2070789/radiusd
tcp 0 0 127.0.0.1:56853 127.0.0.1:1814 ESTABLISHED 2070789/radiusd
tcp 1 0 127.0.0.1:39381 127.0.0.1:49 CLOSE_WAIT 2070789/radiusd
tcp 0 0 127.0.0.1:40537 127.0.0.1:1814 ESTABLISHED 2070789/radiusd
tcp 0 0 127.0.0.1:56635 127.0.0.1:1814 ESTABLISHED 2070789/radiusd
tcp 0 0 127.0.0.1:56309 127.0.0.1:1814 ESTABLISHED 2070789/radiusd
tcp 0 0 127.0.0.1:37877 127.0.0.1:1814 ESTABLISHED 2070789/radiusd
tcp 0 0 127.0.0.1:36851 127.0.0.1:1814 ESTABLISHED 2070789/radiusd
tcp 1 0 127.0.0.1:56469 127.0.0.1:49 CLOSE_WAIT 2070789/radiusd
udp 0 0 169.254.195.0:1812 0.0.0.0:* 2070789/radiusd
the reason is tac_plus server side has read socket timeout which was 3 minutes, if no coming request, it will drop it, but when I login my server, tacacs module still using the CLOSE_WAIT connection to send the request, so it will lead my 2 login failures
question is : could Tacacs module do some enhance to avoid such auth failure?
Log output from the FreeRADIUS daemon
2025-06-05T15:40:01.171654+08:00: Debug : Loaded module rlm_tacacs_tcp
2025-06-05T15:40:01.171771+08:00: Debug : tcp {
2025-06-05T15:40:01.171788+08:00: Debug : ipaddr = 127.0.0.1
2025-06-05T15:40:01.171797+08:00: Debug : port = 49
2025-06-05T15:40:01.171805+08:00: Debug : secret = testkey123
2025-06-05T15:40:01.171813+08:00: Debug : max_packet_size = 4096
2025-06-05T15:40:01.171820+08:00: Debug : max_send_coalesce = 1024
2025-06-05T15:40:01.171826+08:00: Debug : }
2025-06-05T15:40:01.171833+08:00: Debug : type = Authentication-Start
2025-06-05T15:40:01.171839+08:00: Debug : type = Authentication-Continue
2025-06-05T15:40:01.171844+08:00: Debug : type = Authentication-Error
2025-06-05T15:40:01.171849+08:00: Debug : type = Authentication-Fail
2025-06-05T15:40:01.171855+08:00: Debug : max_attributes = 255
2025-06-05T15:40:01.171872+08:00: Debug : response_window = 20
2025-06-05T15:40:01.171881+08:00: Debug : zombie_period = 40
2025-06-05T15:40:01.171968+08:00: Debug : pool {
2025-06-05T15:40:01.171985+08:00: Debug : start = 1
2025-06-05T15:40:01.172005+08:00: Debug : min = 1
2025-06-05T15:40:01.172017+08:00: Debug : max = 5
2025-06-05T15:40:01.172023+08:00: Debug : connecting = 2
2025-06-05T15:40:01.172030+08:00: Debug : uses = 0
2025-06-05T15:40:01.172072+08:00: Debug : lifetime = 0
2025-06-05T15:40:01.172097+08:00: Debug : idle_timeout = 0
2025-06-05T15:40:01.172129+08:00: Debug : open_delay = 0.2
2025-06-05T15:40:01.172147+08:00: Debug : close_delay = 10.0
2025-06-05T15:40:01.172155+08:00: Debug : manage_interval = 0.2
2025-06-05T15:40:01.172162+08:00: Debug : max_backlog = 1000
2025-06-05T15:40:01.172181+08:00: Debug : connection {
2025-06-05T15:40:01.172190+08:00: Debug : connect_timeout = 3.0
2025-06-05T15:40:01.172197+08:00: Debug : reconnect_delay = 1
2025-06-05T15:40:01.172203+08:00: Debug : }
2025-06-05T15:40:01.172211+08:00: Debug : request {
2025-06-05T15:40:01.172219+08:00: Debug : per_connection_max = 2000
2025-06-05T15:40:01.172238+08:00: Debug : per_connection_target = 1000
2025-06-05T15:40:01.172252+08:00: Debug : free_delay = 10.0
2025-06-05T15:40:01.172259+08:00: Debug : }
2025-06-05T15:40:01.172278+08:00: Debug : }
2025-06-05T15:40:01.172300+08:00: Debug : retry {
2025-06-05T15:40:01.172308+08:00: Debug : initial_rtx_time = 2
2025-06-05T15:40:01.172316+08:00: Debug : max_rtx_time = 16
2025-06-05T15:40:01.172323+08:00: Debug : max_rtx_count = 5
2025-06-05T15:40:01.172329+08:00: Debug : max_rtx_duration = 30
2025-06-05T15:40:01.172335+08:00: Debug : }
2025-06-05T15:40:01.172339+08:00: Debug : }
2025-06-05T15:40:01.172344+08:00: Debug : } # static
2025-06-05T15:40:01.172349+08:00: Debug : #### Bootstrapping rlm modules ####
2025-06-05T15:40:01.172354+08:00: Debug : Bootstrapping rlm_exec "exec"
2025-06-05T15:40:01.172499+08:00: Debug : xlat_func_register: dhcpv4.decode
2025-06-05T15:40:01.172519+08:00: Debug : xlat_func_register: dhcpv4.encode
2025-06-05T15:40:01.172535+08:00: Debug : xlat_func_register: dhcpv6.decode
2025-06-05T15:40:01.172542+08:00: Debug : xlat_func_register: dhcpv6.encode
2025-06-05T15:40:01.172553+08:00: Debug : xlat_func_register: radius.decode
2025-06-05T15:40:01.172560+08:00: Debug : xlat_func_register: radius.encode
2025-06-05T15:40:01.172646+08:00: Debug : Including dictionary file "/etc/opt/LU3Pfreeradius-server/dictionary"
2025-06-05T15:40:01.172659+08:00: Debug : #### Instantiating listeners ####
2025-06-05T15:40:01.172699+08:00: Debug : Compiling policies in server default { ... }
2025-06-05T15:40:01.172720+08:00: Debug : Compiling policies in - recv Access-Request {...}
2025-06-05T15:40:01.173504+08:00: Debug : Instantiating xlat "reg_eq" node 0x24a8970, new instance 0x226c3b0
2025-06-05T15:40:01.173872+08:00: Debug : Instantiating xlat "cmp_eq" node 0x2492a00, new instance 0x2492be0
2025-06-05T15:40:01.173981+08:00: Debug : Warning: Skipping send Access-Accept { ... } as it was not found.
2025-06-05T15:40:01.173998+08:00: Debug : Warning: Skipping send Access-Challenge { ... } as it was not found.
2025-06-05T15:40:01.174003+08:00: Debug : Warning: Skipping send Access-Reject { ... } as it was not found.
2025-06-05T15:40:01.174008+08:00: Debug : Warning: Skipping recv Accounting-Request { ... } as it was not found.
2025-06-05T15:40:01.174012+08:00: Debug : Warning: Skipping send Accounting-Response { ... } as it was not found.
2025-06-05T15:40:01.174017+08:00: Debug : Warning: Skipping recv Status-Server { ... } as it was not found.
2025-06-05T15:40:01.174029+08:00: Debug : Warning: Skipping recv CoA-Request { ... } as it was not found.
2025-06-05T15:40:01.174035+08:00: Debug : Warning: Skipping send CoA-ACK { ... } as it was not found.
2025-06-05T15:40:01.174040+08:00: Debug : Warning: Skipping send CoA-NAK { ... } as it was not found.
2025-06-05T15:40:01.174044+08:00: Debug : Warning: Skipping recv Disconnect-Request { ... } as it was not found.
2025-06-05T15:40:01.174049+08:00: Debug : Warning: Skipping send Disconnect-ACK { ... } as it was not found.
2025-06-05T15:40:01.174054+08:00: Debug : Warning: Skipping send Disconnect-NAK { ... } as it was not found.
2025-06-05T15:40:01.174058+08:00: Debug : Warning: Skipping send Protocol-Error { ... } as it was not found.
2025-06-05T15:40:01.174063+08:00: Debug : Warning: Skipping send Do-Not-Respond { ... } as it was not found.
2025-06-05T15:40:01.174069+08:00: Debug : Compiling policies in - authenticate Jradius {...}
2025-06-05T15:40:01.174078+08:00: Debug : Warning: Skipping new client { ... } as it was not found.
2025-06-05T15:40:01.174083+08:00: Debug : Warning: Skipping add client { ... } as it was not found.
2025-06-05T15:40:01.174088+08:00: Debug : Warning: Skipping deny client { ... } as it was not found.
2025-06-05T15:40:01.174094+08:00: Warn : radius { ... } section is unused
2025-06-05T15:40:01.174101+08:00: Debug : #### Instantiating process modules ####
2025-06-05T15:40:01.174106+08:00: Debug : Protecting data for module "default" 0x2d18000-0x2d18fff
2025-06-05T15:40:01.174128+08:00: Debug : Instantiating process_radius "default"
2025-06-05T15:40:01.174157+08:00: Debug : Protecting data for module "default" 0x2d1a000-0x2d1afff
2025-06-05T15:40:01.174176+08:00: Debug : #### Instantiating protocol modules ####
2025-06-05T15:40:01.174201+08:00: Debug : Instantiating proto_radius "default.radius.udp"
2025-06-05T15:40:01.174231+08:00: Debug : Instantiating proto_radius_udp "default.radius.udp.udp"
2025-06-05T15:40:01.174316+08:00: Debug : #### Instantiating rlm modules ####
2025-06-05T15:40:01.174343+08:00: Debug : Protecting data for module "exec" 0x2d4d000-0x2d4dfff
2025-06-05T15:40:01.174402+08:00: Debug : Instantiating rlm_exec "exec"
2025-06-05T15:40:01.174416+08:00: Debug : Protecting data for module "exec" 0x2d4f000-0x2d4ffff
2025-06-05T15:40:01.174478+08:00: Debug : Instantiating rlm_jradius "jradius"
2025-06-05T15:40:01.174494+08:00: Debug : rlm_jradius: instance: 0x2d53060
2025-06-05T15:40:01.174498+08:00: Debug : rlm_jradius: instance name: 0x2bf48f0
2025-06-05T15:40:01.174503+08:00: Debug : rlm_jradius: instance name: jradius
2025-06-05T15:40:01.174514+08:00: Info : rlm_jradius: configuring jradius server 127.0.0.1:1814
2025-06-05T15:40:01.174520+08:00: Info : rlm_jradius: starting JRadius connection 0
2025-06-05T15:40:01.174650+08:00: Info : rlm_jradius: starting JRadius connection 1
2025-06-05T15:40:01.174759+08:00: Info : rlm_jradius: starting JRadius connection 2
2025-06-05T15:40:01.174873+08:00: Info : rlm_jradius: starting JRadius connection 3
2025-06-05T15:40:01.174956+08:00: Info : rlm_jradius: starting JRadius connection 4
2025-06-05T15:40:01.175027+08:00: Info : rlm_jradius: starting JRadius connection 5
2025-06-05T15:40:01.175102+08:00: Info : rlm_jradius: starting JRadius connection 6
2025-06-05T15:40:01.175221+08:00: Info : rlm_jradius: starting JRadius connection 7
2025-06-05T15:40:01.175290+08:00: Debug : Protecting data for module "jradius" 0x2d53000-0x2d53fff
2025-06-05T15:40:01.175345+08:00: Debug : Instantiating rlm_tacacs "tacacs"
2025-06-05T15:40:01.175359+08:00: Warn : Ignoring "trunk.per_connection_max = 2000", forcing to "trunk.per_connection_max = 255"
2025-06-05T15:40:01.175365+08:00: Warn : Ignoring "trunk.per_connection_target = 1000", forcing to "trunk.per_connection_target = 127"
2025-06-05T15:40:01.175370+08:00: Warn : Ignoring "revive_interval = 0", forcing to "revive_interval = 10"
2025-06-05T15:40:01.175394+08:00: Debug : Protecting data for module "tacacs" 0x2d5b000-0x2d5bfff
2025-06-05T15:40:01.175431+08:00: Debug : Instantiating rlm_tacacs_tcp "tacacs.tcp"
2025-06-05T15:40:01.175456+08:00: Debug : Protecting data for module "tacacs.tcp" 0x2d5e000-0x2d5efff
2025-06-05T15:40:01.241140+08:00: Debug : Creating 1/1 networks
2025-06-05T15:40:01.241751+08:00: Debug : Waiting for semaphore from network 1/1
2025-06-05T15:40:01.253994+08:00: Info : Network 0 - Starting
2025-06-05T15:40:01.254341+08:00: Debug : Network 0 - Started
2025-06-05T15:40:01.257036+08:00: Debug : Creating 1/2 workers
2025-06-05T15:40:01.257573+08:00: Debug : Creating 2/2 workers
2025-06-05T15:40:01.257834+08:00: Debug : Waiting for semaphore from worker 1/2
2025-06-05T15:40:01.266783+08:00: Info : Worker 0 - Starting
2025-06-05T15:40:01.266984+08:00: Debug : tacacs - [0] Starting initial connection
2025-06-05T15:40:01.267008+08:00: Debug : tacacs - Calling connection_alloc(tconn=0x7f4b58030ff0, el=0x7f4b58006050, conf=0x2d5b290, log_prefix="tacacs", uctx=0x7f4b58028900)
2025-06-05T15:40:01.267047+08:00: Debug : tacacs - [1] - Signalled to start from HALTED state
2025-06-05T15:40:01.267061+08:00: Debug : tacacs - [1] - Connection changed state HALTED -> INIT
2025-06-05T15:40:01.267067+08:00: Debug : tacacs - [1] Trunk connection changed state HALTED -> INIT
2025-06-05T15:40:01.267307+08:00: Debug : tacacs - [1] - Connection changed state INIT -> CONNECTING
2025-06-05T15:40:01.267324+08:00: Info : tacacs - [1] Trunk connection changed state INIT -> CONNECTING
2025-06-05T15:40:01.267354+08:00: Debug : Instantiating xlat "reg_eq" node 0x24a8970, instance 0x226c430, new thread instance 0x7f4b5803b310
2025-06-05T15:40:01.267364+08:00: Debug : Instantiating xlat "cmp_eq" node 0x2492a00, instance (nil), new thread instance 0x7f4b5803b3b0
2025-06-05T15:40:01.267402+08:00: Debug : Worker 0 - Started
2025-06-05T15:40:01.267451+08:00: Debug : tacacs - [1] - Connection changed state CONNECTING -> CONNECTED
2025-06-05T15:40:01.267489+08:00: Debug : tacacs - [1] - Connection established
2025-06-05T15:40:01.267499+08:00: Debug : tacacs - [1] Trunk connection changed state CONNECTING -> ACTIVE
2025-06-05T15:40:01.267522+08:00: Debug : Waiting for semaphore from worker 2/2
2025-06-05T15:40:01.267572+08:00: Info : Worker 1 - Starting
2025-06-05T15:40:01.267860+08:00: Debug : tacacs - [0] Starting initial connection
2025-06-05T15:40:01.267884+08:00: Debug : tacacs - Calling connection_alloc(tconn=0x7f4b4c030ff0, el=0x7f4b4c006050, conf=0x2d5b290, log_prefix="tacacs", uctx=0x7f4b4c028900)
2025-06-05T15:40:01.267905+08:00: Debug : tacacs - [2] - Signalled to start from HALTED state
2025-06-05T15:40:01.267912+08:00: Debug : tacacs - [2] - Connection changed state HALTED -> INIT
2025-06-05T15:40:01.267917+08:00: Debug : tacacs - [2] Trunk connection changed state HALTED -> INIT
2025-06-05T15:40:01.271143+08:00: Debug : tacacs - [2] - Connection changed state INIT -> CONNECTING
2025-06-05T15:40:01.271163+08:00: Info : tacacs - [2] Trunk connection changed state INIT -> CONNECTING
2025-06-05T15:40:01.271192+08:00: Debug : Instantiating xlat "reg_eq" node 0x24a8970, instance 0x226c430, new thread instance 0x7f4b4c03b310
2025-06-05T15:40:01.271203+08:00: Debug : Instantiating xlat "cmp_eq" node 0x2492a00, instance (nil), new thread instance 0x7f4b4c03b3b0
2025-06-05T15:40:01.271232+08:00: Debug : Worker 1 - Started
2025-06-05T15:40:01.271257+08:00: Debug : tacacs - [2] - Connection changed state CONNECTING -> CONNECTED
2025-06-05T15:40:01.271317+08:00: Debug : tacacs - [2] - Connection established
2025-06-05T15:40:01.271326+08:00: Debug : tacacs - [2] Trunk connection changed state CONNECTING -> ACTIVE
2025-06-05T15:40:01.271507+08:00: Info : Scheduler created successfully with 1 networks and 2 workers
2025-06-05T15:40:01.271526+08:00: Debug : #### Opening listener interfaces ####
2025-06-05T15:40:01.272201+08:00: Debug : Opened listener for radius
2025-06-05T15:40:01.272288+08:00: Info : post-suid-down capabilities: =ep
2025-06-05T15:40:01.279998+08:00: Debug : Freeing default (0x229e940)
2025-06-05T15:40:01.280025+08:00: Debug : Unprotecting data for module "default" 0x2d1a000-0x2d1afff
2025-06-05T15:40:01.280051+08:00: Debug : Unprotecting data for module "default" 0x2d18000-0x2d18fff
2025-06-05T15:40:01.280101+08:00: Debug : process_radius unloaded
2025-06-05T15:40:01.280281+08:00: Debug : Freeing default.radius.udp (0x29be390)
2025-06-05T15:40:01.280301+08:00: Debug : Freeing default.radius.udp.udp (0x29b3ba0)
2025-06-05T15:40:01.280326+08:00: Debug : proto_radius_udp unloaded
2025-06-05T15:40:01.280428+08:00: Debug : proto_radius unloaded
2025-06-05T15:40:01.288222+08:00: Debug : Worker 0 - Channel open
2025-06-05T15:40:01.288243+08:00: Debug : Worker 0 - Received channel 0x7f4b54033ca0 into array entry 0
2025-06-05T15:40:01.291884+08:00: Debug : Listening on radius_udp server 169.254.195.0 port 1812 bound to virtual server default
2025-06-05T15:40:01.291909+08:00: Debug : Network 0 - Using new socket radius_udp server 169.254.195.0 port 1812 with FD 49
2025-06-05T15:40:01.293283+08:00: Debug : Worker 1 - Channel open
2025-06-05T15:40:01.293304+08:00: Debug : Worker 1 - Received channel 0x7f4b54074340 into array entry 0
2025-06-05T15:40:01.321588+08:00: Info : Ready to process requests
2025-06-05T15:40:01.467511+08:00: Debug : tacacs - Trunk changed state IDLE -> ACTIVE
2025-06-05T15:40:01.473299+08:00: Debug : tacacs - Trunk changed state IDLE -> ACTIVERelevant log output from client utilities
2025-06-05T15:45:37.277424+08:00: Debug : Network 0 - Reading data from FD 49
2025-06-05T15:45:37.277566+08:00: Debug : proto_radius_udp - Received Access-Request ID 69 length 95 radius_udp server 169.254.195.0 port 1812
2025-06-05T15:45:37.277628+08:00: Debug : Network 0 - Read 95 byte(s) from FD 49
2025-06-05T15:45:37.277723+08:00: Debug : Worker 0 - Channel data-to-responder
2025-06-05T15:45:37.277765+08:00: Debug : Worker 0 - Received request 1
(1) Thu Jun 5 15:45:37 2025 : Debug : Time tracking started in yielded state
2025-06-05T15:45:37.278011+08:00: Debug : Worker 0 - Resetting cleanup timer to +30
(1) Thu Jun 5 15:45:37 2025 : Debug : Request resuming
(1) Thu Jun 5 15:45:37 2025 : Debug : default {
(1) Thu Jun 5 15:45:37 2025 : Debug : Received Access-Request ID 69 from 169.254.131.0:56802 to 169.254.195.0:1812 via int0
(1) Thu Jun 5 15:45:37 2025 : Debug : User-Name = "testuser1"
(1) Thu Jun 5 15:45:37 2025 : Debug : NAS-Identifier = "LCP_CLI"
(1) Thu Jun 5 15:45:37 2025 : Debug : Service-Type = Authenticate-Only
(1) Thu Jun 5 15:45:37 2025 : Debug : Calling-Station-Id = "10.76.89.53"
(1) Thu Jun 5 15:45:37 2025 : Debug : NAS-IP-Address = 169.254.64.1
(1) Thu Jun 5 15:45:37 2025 : Debug : NAS-Port = 2099136
(1) Thu Jun 5 15:45:37 2025 : Debug : NAS-Port-Type = Virtual
(1) Thu Jun 5 15:45:37 2025 : Debug : User-Password = "testpass123"
(1) Thu Jun 5 15:45:37 2025 : Debug : Net {
(1) Thu Jun 5 15:45:37 2025 : Debug : Src {
(1) Thu Jun 5 15:45:37 2025 : Debug : IP = 169.254.131.0
(1) Thu Jun 5 15:45:37 2025 : Debug : Port = 56802
(1) Thu Jun 5 15:45:37 2025 : Debug : }
(1) Thu Jun 5 15:45:37 2025 : Debug : Dst {
(1) Thu Jun 5 15:45:37 2025 : Debug : IP = 169.254.195.0
(1) Thu Jun 5 15:45:37 2025 : Debug : Port = 1812
(1) Thu Jun 5 15:45:37 2025 : Debug : }
(1) Thu Jun 5 15:45:37 2025 : Debug : Timestamp = "2025-06-05T07:45:37Z"
(1) Thu Jun 5 15:45:37 2025 : Debug : }
(1) Thu Jun 5 15:45:37 2025 : Debug : Packet-Type = Access-Request
(1) Thu Jun 5 15:45:37 2025 : Debug : No request.State attribute, can't restore session-state
(1) Thu Jun 5 15:45:37 2025 : Debug : Running 'recv Access-Request' from file /etc/opt/LU3Pfreeradius-server/sites-cpm/cpm_radius_config
(1) Thu Jun 5 15:45:37 2025 : WARN : Module default returned 3-7
(1) Thu Jun 5 15:45:37 2025 : Debug : recv Access-Request {
(1) Thu Jun 5 15:45:37 2025 : Debug : if (User-Name =~ /^testuser1$/) {
(1) Thu Jun 5 15:45:37 2025 : Debug : | =~
(1) Thu Jun 5 15:45:37 2025 : Debug : | User-Name
(1) Thu Jun 5 15:45:37 2025 : Debug : | %{User-Name}
(1) Thu Jun 5 15:45:37 2025 : Debug : | --> testuser1
(1) Thu Jun 5 15:45:37 2025 : Debug : | %reg_eq({testuser1})
(1) Thu Jun 5 15:45:37 2025 : Debug : | --> true
(1) Thu Jun 5 15:45:37 2025 : Debug : subrequest @TaCaCs::Authentication-Start {
(1.0) Thu Jun 5 15:45:37 2025 : Debug : No child state found in parent 1
(1.0) Thu Jun 5 15:45:37 2025 : Debug : Time tracking started in yielded state
(1) Thu Jun 5 15:45:37 2025 : Debug : Request yielded
(1.0) Thu Jun 5 15:45:37 2025 : Debug : Request resuming
(1.0) Thu Jun 5 15:45:37 2025 : Debug : User-Name := "testuser1"
(1.0) Thu Jun 5 15:45:37 2025 : Debug : Client-Port := 2099136
(1.0) Thu Jun 5 15:45:37 2025 : Debug : Remote-Address := 169.254.64.1
(1.0) Thu Jun 5 15:45:37 2025 : Debug : Data := "testpass123"
(1.0) Thu Jun 5 15:45:37 2025 : Debug : Packet.Version-Major := 12
(1.0) Thu Jun 5 15:45:37 2025 : Debug : Packet.Version-Minor := 1
(1.0) Thu Jun 5 15:45:37 2025 : Debug : Packet.Packet-Type := Authentication
(1.0) Thu Jun 5 15:45:37 2025 : Debug : Packet.Sequence-Number := 1
(1.0) Thu Jun 5 15:45:37 2025 : Debug : Packet.Flags := None
(1.0) Thu Jun 5 15:45:37 2025 : Debug : Packet.Length := 0
(1.0) Thu Jun 5 15:45:37 2025 : Debug : Authentication-Type := PAP
(1.0) Thu Jun 5 15:45:37 2025 : Debug : Action := LOGIN
(1.0) Thu Jun 5 15:45:37 2025 : Debug : Authentication-Service := LOGIN
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Trunk request 2 changed state INIT -> PENDING
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - tacacs - [1] Trunk connection assigned request 2
2025-06-05T15:45:37.279102+08:00: Debug : tacacs - [1] Calling connection_notify(tconn=0x7f4b58030ff0, conn=0x7f4b58031150, el=0x7f4b58006050, events=TRUNK_CONN_EVENT_WRITE, uctx=0x7f4b58028900)
(1.0) Thu Jun 5 15:45:37 2025 : WARN : tacacs - Module tacacs returned 5-7
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Request yielded
2025-06-05T15:45:37.279197+08:00: Debug : tacacs - [1] Signalled writable
2025-06-05T15:45:37.279206+08:00: Debug : tacacs - [1] Calling request_mux(el=0x7f4b58006050, tconn=0x7f4b58030ff0, conn=0x7f4b58031150, uctx=0x7f4b58028900)
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Sending Authentication-Start ID 1 length 0 over connection proto tcp local 0.0.0.0 port 0 remote 127.0.0.1 port 49
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Encoded packet
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - 0000: c1 01 01 00 e3 f9 71 27 00 00 00 2f f9 da 37 1f
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - 0010: 39 e3 f2 19 7e b9 b0 69 27 f2 a0 3e 68 9b d8 08
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - 0020: ba 30 f1 de de ed d8 3c 0e 83 78 12 12 b8 27 7c
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - 0030: 37 50 04 3a de e5 77 f1 c7 06 42
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Packet-Type = Authentication-Start
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - User-Name = "testuser1"
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Client-Port = "2099136"
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Remote-Address = "169.254.64.1"
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Data = 0x7465737470617373313233
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Packet {
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Version-Major = Plus
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Version-Minor = 1
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Packet-Type = Authentication
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Sequence-Number = 1
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Flags = None
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Session-Id = 3824775463
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Length = 0
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - }
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Authentication-Type = PAP
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Action = LOGIN
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Authentication-Service = LOGIN
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Trunk request 2 changed state PENDING -> SENT
2025-06-05T15:45:37.279578+08:00: Debug : tacacs - [1] Calling connection_notify(tconn=0x7f4b58030ff0, conn=0x7f4b58031150, el=0x7f4b58006050, events=TRUNK_CONN_EVENT_READ, uctx=0x7f4b58028900)
2025-06-05T15:45:37.279654+08:00: Error : tacacs - Connection proto tcp local 0.0.0.0 port 0 remote 127.0.0.1 port 49 failed: EPIPE: Broken pipe
2025-06-05T15:45:37.279669+08:00: Debug : tacacs - [1] - Signalled to reconnect from CONNECTED state
2025-06-05T15:45:37.279680+08:00: Debug : tacacs - [1] - Connection changed state CONNECTED -> FAILED
2025-06-05T15:45:37.279687+08:00: Debug : tacacs - [1] - Connection changed state FAILED -> CLOSED
2025-06-05T15:45:37.279693+08:00: Info : tacacs - [1] Trunk connection changed state ACTIVE -> CLOSED
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Trunk request 2 changed state SENT -> CANCEL
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Calling request_cancel(conn=0x7f4b58031150, preq=0x7f4b5809ddc0, reason=TRUNK_CANCEL_REASON_MOVE, uctx=0x7f4b58028900)
2025-06-05T15:45:37.279729+08:00: Debug : tacacs - [1] Calling connection_notify(tconn=0x7f4b58030ff0, conn=0x7f4b58031150, el=0x7f4b58006050, events=TRUNK_CONN_EVENT_NONE, uctx=0x7f4b58028900)
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - tacacs - [1] Trunk connection released request 2
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Calling request_conn_release(conn=0x7f4b58031150, preq=0x7f4b5809ddc0, uctx=0x7f4b58028900)
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Trunk request 2 changed state CANCEL -> UNASSIGNED
(1.0) Thu Jun 5 15:45:37 2025 : WARN : tacacs - Refusing to enqueue requests - No active connections and last event was a connection failure
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Trunk request 2 changed state UNASSIGNED -> FAILED
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Calling request_fail(request=0x7f4b580969e0, preq=0x7f4b5809ddc0, rctx=0x7f4b5809d490, state=UNASSIGNED uctx=0x7f4b58028900)
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Interpreter - Request marked as runnable
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Request marked as runnable
(1.0) Thu Jun 5 15:45:37 2025 : Debug : tacacs - Calling request_free(request=0x7f4b580969e0, preq=0x7f4b5809ddc0, uctx=0x7f4b58028900)
2025-06-05T15:45:37.279863+08:00: Debug : tacacs - Failed shutting down connection proto tcp local 0.0.0.0 port 0 remote 127.0.0.1 port 49: ENOTCONN: Transport endpoint is not connected
2025-06-05T15:45:37.279904+08:00: Debug : tacacs - Connection closed - proto tcp local 0.0.0.0 port 0 remote 127.0.0.1 port 49