Robust Proxy Accounting problem after switch from 2.2.10 to 3.2.1
Martin Zaharinov
micron10 at gmail.com
Wed Nov 23 14:55:19 UTC 2022
Hi all
i try to switch from freeradius 2.2.10 to 3.2.1
After fix all configs and dictionary
go to this problem real radius server not respons :
10.10.10.1 is proxy radius
192.168.10.1 is real radius server.
with freeradius 2.2.10 with old config real radius respons on query.
but after switch to freeradius 3.2.1 radius stop respons on query.
May be i make wrong config or ?
See log :
Wed Nov 23 20:08:23 2022 : Debug: }
Wed Nov 23 20:08:23 2022 : Debug: Listening on acct address * port 1813
Wed Nov 23 20:08:23 2022 : Debug: Listening on detail file /var/log/freeradius/radacct/detail.example.com/detail-*:* as server home.example.com
Wed Nov 23 20:08:23 2022 : Info: Ready to process requests
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - User-Name = "test_bgbras"
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - NAS-Identifier = "demo-bng"
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - NAS-IP-Address = 10.10.10.1
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - NAS-Port = 0
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - NAS-Port-Id = "vlan100"
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - NAS-Port-Type = Virtual
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - Service-Type = Framed-User
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - Framed-Protocol = PPP
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - Calling-Station-Id = "f6:cb:f6:40:1f:a0"
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - Called-Station-Id = "1a:27:b5:27:bb:53"
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - Class = 0x6375693d746573745f6267627261732c73753d3934323033392c736b3d686c3677777564716138396d2c626b69643d32323534303038392c626b7269643d332c6d763d3532393135313830303939372c6d743d3630353333342c676d743d3630343830302c73703d312c73723d2c61633d312c75693d3934323033392c6363693d3138382c63633d47656e6572616c2c61733d312c636f3d2c64623d3130323430302c75623d3130323430302c63626b69643d3232353430303930
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - Acct-Status-Type = Start
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - Acct-Authentic = RADIUS
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - Acct-Session-Id = "16fecbef21f8c2cf"
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - Acct-Session-Time = 0
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - Acct-Input-Octets = 0
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - Acct-Output-Octets = 0
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - Acct-Input-Packets = 0
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - Acct-Output-Packets = 0
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - Acct-Input-Gigawords = 0
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - Acct-Output-Gigawords = 0
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - Framed-IP-Address = 10.0.0.3
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - Event-Timestamp = "Nov 23 2022 19:59:44 IST"
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Trying to read VP from line - Acct-Unique-Session-Id = "319ef2e5f83ff3c6e82f09959978097b"
Wed Nov 23 20:08:23 2022 : Debug: detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): Read packet from /var/log/freeradius/radacct/detail.example.com/detail.work
User-Name = "test_bgbras"
NAS-Identifier = "demo-bng"
NAS-IP-Address = 10.10.10.1
NAS-Port = 0
NAS-Port-Id = "vlan100"
NAS-Port-Type = Virtual
Service-Type = Framed-User
Framed-Protocol = PPP
Calling-Station-Id = "f6:cb:f6:40:1f:a0"
Called-Station-Id = "1a:27:b5:27:bb:53"
Class = 0x6375693d746573745f6267627261732c73753d3934323033392c736b3d686c3677777564716138396d2c626b69643d32323534303038392c626b7269643d332c6d763d3532393135313830303939372c6d743d3630353333342c676d743d3630343830302c73703d312c73723d2c61633d312c75693d3934323033392c6363693d3138382c63633d47656e6572616c2c61733d312c636f3d2c64623d3130323430302c75623d3130323430302c63626b69643d3232353430303930
Acct-Status-Type = Start
Acct-Authentic = RADIUS
Acct-Session-Id = "16fecbef21f8c2cf"
Acct-Session-Time = 0
Acct-Input-Octets = 0
Acct-Output-Octets = 0
Acct-Input-Packets = 0
Acct-Output-Packets = 0
Acct-Input-Gigawords = 0
Acct-Output-Gigawords = 0
Framed-IP-Address = 10.0.0.3
Event-Timestamp = "Nov 23 2022 19:59:44 IST"
Acct-Unique-Session-Id = "319ef2e5f83ff3c6e82f09959978097b"
Packet-Original-Timestamp = "Nov 23 2022 19:59:44 IST"
Acct-Delay-Time = 519
Packet-Transmit-Counter = 1
Wed Nov 23 20:08:23 2022 : Debug: (0) Empty preacct section in virtual server "home.example.com". Using default return values.
Wed Nov 23 20:08:23 2022 : Debug: (0) # Executing section accounting from file /etc/freeradius/sites-enabled/robust-proxy-accounting
Wed Nov 23 20:08:23 2022 : Debug: (0) accounting {
Wed Nov 23 20:08:23 2022 : Debug: (0) update control {
Wed Nov 23 20:08:23 2022 : Debug: (0) &Proxy-To-Realm := 'acct_realm.example.com'
Wed Nov 23 20:08:23 2022 : Debug: (0) } # update control = noop
Wed Nov 23 20:08:23 2022 : Debug: (0) } # accounting = noop
Wed Nov 23 20:08:23 2022 : Debug: Using home pool acct for realm acct_realm.example.com
Wed Nov 23 20:08:23 2022 : Debug: (0) Starting proxy to home server 192.168.10.1 port 1813
Wed Nov 23 20:08:23 2022 : Debug: (0) server home.example.com {
Wed Nov 23 20:08:23 2022 : Debug: (0) Empty pre-proxy section in virtual server "home.example.com". Using default return values.
Wed Nov 23 20:08:23 2022 : Debug: (0) }
Wed Nov 23 20:08:23 2022 : Debug: (0) proxy: Trying to allocate ID (0/2)
Wed Nov 23 20:08:23 2022 : Debug: (0) proxy: Trying to open a new listener to the home server
Wed Nov 23 20:08:23 2022 : Debug: Opened new proxy socket 'proxy address 10.10.10.1 port 48401'
Wed Nov 23 20:08:23 2022 : Debug: Listening on proxy address 10.10.10.1 port 48401
Wed Nov 23 20:08:23 2022 : Debug: (0) proxy: Trying to allocate ID (1/2)
Wed Nov 23 20:08:23 2022 : Debug: (0) proxy: request is now in proxy hash
Wed Nov 23 20:08:23 2022 : Debug: (0) proxy: allocating destination 192.168.10.1 port 1813 - Id 122
Wed Nov 23 20:08:23 2022 : Debug: (0) Proxying request to home server 192.168.10.1 port 1813 timeout 6.000000
Wed Nov 23 20:08:23 2022 : Debug: Waking up in 0.3 seconds.
Wed Nov 23 20:08:23 2022 : Debug: Ignoring spoofed proxy reply. Signature is invalid
Wed Nov 23 20:08:23 2022 : Debug: Waking up in 0.1 seconds.
Wed Nov 23 20:08:24 2022 : Debug: (0) Expecting proxy response no later than 5.666547 seconds from now
Wed Nov 23 20:08:24 2022 : Debug: Waking up in 5.6 seconds.
Wed Nov 23 20:08:29 2022 : Debug: (0) No proxy response, giving up on request and marking it done
Wed Nov 23 20:08:29 2022 : Proxy: Marking home server 192.168.10.1 port 1813 as zombie (it has not responded in 6.000000 seconds).
Wed Nov 23 20:08:29 2022 : Debug: (1) proxy: Trying to allocate ID (0/2)
Wed Nov 23 20:08:29 2022 : Debug: (1) proxy: request is now in proxy hash
Wed Nov 23 20:08:29 2022 : Debug: (1) proxy: allocating destination 192.168.10.1 port 1813 - Id 198
Wed Nov 23 20:08:29 2022 : Debug: PING: Waiting 4 seconds for response to ping
Wed Nov 23 20:08:29 2022 : Debug: (1) Sent Accounting-Request Id 198 from 10.10.10.1:48401 to 192.168.10.1:1813 length 98
Wed Nov 23 20:08:29 2022 : Debug: (1) User-Name := "test_user_status_check"
Wed Nov 23 20:08:29 2022 : Debug: (1) Acct-Status-Type := Stop
Wed Nov 23 20:08:29 2022 : Debug: (1) Acct-Session-Id := "00000000"
Wed Nov 23 20:08:29 2022 : Debug: (1) Event-Timestamp := "Nov 23 2022 20:08:29 IST"
Wed Nov 23 20:08:29 2022 : Debug: (1) NAS-Identifier := "Status Check 0. Are you alive?"
Wed Nov 23 20:08:29 2022 : Debug: PING: Next status packet in 30 seconds
Wed Nov 23 20:08:29 2022 : ERROR: (0) Failing proxied request for user "test_bgbras", due to lack of any response from home server 192.168.10.1 port 1813
Wed Nov 23 20:08:29 2022 : Debug: (0) Clearing existing &reply: attributes
Wed Nov 23 20:08:29 2022 : Debug: (0) Found Post-Proxy-Type Fail-Accounting
Wed Nov 23 20:08:29 2022 : Debug: (0) server home.example.com {
Wed Nov 23 20:08:29 2022 : Debug: (0) # Executing group from file /etc/freeradius/sites-enabled/robust-proxy-accounting
Wed Nov 23 20:08:29 2022 : Debug: (0) Post-Proxy-Type Fail-Accounting {
Wed Nov 23 20:08:29 2022 : Debug: (0) modsingle[post-proxy]: calling detail.example.com (rlm_detail)
Wed Nov 23 20:08:29 2022 : Debug: /var/log/freeradius/radacct/detail.example.com/detail-%Y%m%d:%H:%G
Wed Nov 23 20:08:29 2022 : Debug: Parsed xlat tree:
Wed Nov 23 20:08:29 2022 : Debug: literal --> /var/log/freeradius/radacct/detail.example.com/detail-
Wed Nov 23 20:08:29 2022 : Debug: percent --> Y
Wed Nov 23 20:08:29 2022 : Debug: percent --> m
Wed Nov 23 20:08:29 2022 : Debug: percent --> d
Wed Nov 23 20:08:29 2022 : Debug: literal --> :
Wed Nov 23 20:08:29 2022 : Debug: percent --> H
Wed Nov 23 20:08:29 2022 : Debug: literal --> :
Wed Nov 23 20:08:29 2022 : Debug: percent --> G
Wed Nov 23 20:08:29 2022 : Debug: (0) detail.example.com: EXPAND /var/log/freeradius/radacct/detail.example.com/detail-%Y%m%d:%H:%G
Wed Nov 23 20:08:29 2022 : Debug: (0) detail.example.com: --> /var/log/freeradius/radacct/detail.example.com/detail-20221123:20:08
Wed Nov 23 20:08:29 2022 : Debug: (0) detail.example.com: /var/log/freeradius/radacct/detail.example.com/detail-%Y%m%d:%H:%G expands to /var/log/freeradius/radacct/detail.example.com/detail-20221123:20:08
Wed Nov 23 20:08:29 2022 : WARNING: (0) detail.example.com: Suppressing infinite loop
Wed Nov 23 20:08:29 2022 : Debug: (0) modsingle[post-proxy]: returned from detail.example.com (rlm_detail)
Wed Nov 23 20:08:29 2022 : Debug: (0) [detail.example.com] = noop
Wed Nov 23 20:08:29 2022 : Debug: (0) } # Post-Proxy-Type Fail-Accounting = noop
Wed Nov 23 20:08:29 2022 : Debug: (0) }
Wed Nov 23 20:08:29 2022 : Debug: (0) detail (/var/log/freeradius/radacct/detail.example.com/detail-*:*): No response to request. Will retry in 30 seconds
Wed Nov 23 20:08:29 2022 : Debug: (0) Finished request
Wed Nov 23 20:08:29 2022 : Debug: (0) Cleaning up request packet ID 0 with timestamp +0 due to done
Wed Nov 23 20:08:29 2022 : Debug: Waking up in 3.9 seconds.
Wed Nov 23 20:08:29 2022 : Debug: Ignoring spoofed proxy reply. Signature is invalid
Wed Nov 23 20:08:29 2022 : Debug: Waking up in 3.8 seconds.
Wed Nov 23 20:08:33 2022 : Error: No response to status check 1 ID 198 for home server 192.168.10.1 port 1813
Wed Nov 23 20:08:33 2022 : Debug: Waking up in 25.3 seconds.
Best regards,
Martin
More information about the Freeradius-Users
mailing list