2.1.8 proxy zombie/dead/alive loops
In testing the new 2.1.8 for accounting packets I have discovered the following strange situation, There are 2 radius servers (radius-a and radius-b). Each server will relay packets it receives to the other server. (Currently only accounting packets are being received) The packets are collected in detail-relay file. The packets are then relayed via the sites/enabled/copy-acct-to-home-server config. What I observe is a single packet being read from the detail-relay.work file on radius-b and being sent radius-a. I do not see any response from radius-a being returned to radius-b. After what seems to be about 30 seconds the packet is resent from radius-b to radius-a. Again and again... On radius-b the following messages are logged (status_check = status-server).... Mon Jan 4 10:10:15 2010 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Mon Jan 4 10:10:15 2010 : Info: rlm_sql (sql): Attempting to connect to radiusd@localhost:/radius Mon Jan 4 10:10:15 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Mon Jan 4 10:10:15 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #1 Mon Jan 4 10:10:15 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #2 Mon Jan 4 10:10:15 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #3 Mon Jan 4 10:10:15 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Mon Jan 4 10:10:15 2010 : Info: Loaded virtual server inner-tunnel Mon Jan 4 10:10:15 2010 : Info: Loaded virtual server copy-acct-to-home-server Mon Jan 4 10:10:15 2010 : Info: Loaded virtual server <default> Mon Jan 4 10:10:15 2010 : Info: Ready to process requests. Mon Jan 4 10:10:42 2010 : Proxy: Marking home server 192.168.1.225 port 1813 as zombie (it looks like it is dead). Mon Jan 4 10:10:42 2010 : Proxy: Received response to status check 5938 (1 in current sequence) Mon Jan 4 10:11:11 2010 : Proxy: Received response to status check 6013 (2 in current sequence) Mon Jan 4 10:11:40 2010 : Proxy: Received response to status check 6048 (3 in current sequence) Mon Jan 4 10:11:40 2010 : Proxy: Marking home server 192.168.1.225 port 1813 alive Mon Jan 4 10:11:43 2010 : Proxy: Marking home server 192.168.1.225 port 1813 as zombie (it looks like it is dead). Mon Jan 4 10:11:43 2010 : Proxy: Received response to status check 6051 (4 in current sequence) Mon Jan 4 10:11:43 2010 : Proxy: Marking home server 192.168.1.225 port 1813 alive Mon Jan 4 10:12:13 2010 : Proxy: Marking home server 192.168.1.225 port 1813 as zombie (it looks like it is dead). Mon Jan 4 10:12:13 2010 : Proxy: Received response to status check 6086 (5 in current sequence) Mon Jan 4 10:12:13 2010 : Proxy: Marking home server 192.168.1.225 port 1813 alive Mon Jan 4 10:12:44 2010 : Proxy: Marking home server 192.168.1.225 port 1813 as zombie (it looks like it is dead). Mon Jan 4 10:12:44 2010 : Proxy: Received response to status check 6118 (6 in current sequence) Mon Jan 4 10:12:44 2010 : Proxy: Marking home server 192.168.1.225 port 1813 alive Mon Jan 4 10:13:14 2010 : Proxy: Marking home server 192.168.1.225 port 1813 as zombie (it looks like it is dead). Mon Jan 4 10:13:14 2010 : Proxy: Received response to status check 6153 (7 in current sequence) Mon Jan 4 10:13:14 2010 : Proxy: Marking home server 192.168.1.225 port 1813 alive On radius-a for the same time frame... Mon Jan 4 10:11:55 2010 : Proxy: Marking home server 192.168.1.226 port 1813 as zombie (it looks like it is dead). Mon Jan 4 10:11:55 2010 : Proxy: Received response to status check 669399 (6 in current sequence) Mon Jan 4 10:11:55 2010 : Proxy: Marking home server 192.168.1.226 port 1813 alive I then tried using the alternate "status_check = request " method, but I think I have it configured incorrectly since it is also not receiving a reply... Mon Jan 4 11:52:16 2010 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Mon Jan 4 11:52:16 2010 : Info: rlm_sql (sql): Attempting to connect to radiusd@localhost:/radius Mon Jan 4 11:52:16 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Mon Jan 4 11:52:16 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #1 Mon Jan 4 11:52:16 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #2 Mon Jan 4 11:52:16 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #3 Mon Jan 4 11:52:16 2010 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Mon Jan 4 11:52:16 2010 : Info: Loaded virtual server inner-tunnel Mon Jan 4 11:52:16 2010 : Info: Loaded virtual server copy-acct-to-home-server Mon Jan 4 11:52:16 2010 : Info: Loaded virtual server <default> Mon Jan 4 11:52:16 2010 : Info: Ready to process requests. Mon Jan 4 11:52:43 2010 : Proxy: Marking home server 192.168.1.225 port 1813 as zombie (it looks like it is dead). Mon Jan 4 11:52:44 2010 : Info: [sql] stop packet with zero session length. [user 'test_user_please_reject_me', nas '192.168.1.226'] Mon Jan 4 11:52:47 2010 : Error: No response to status check 5969 for home server 192.168.1.225 port 1813 Mon Jan 4 11:53:13 2010 : Info: [sql] stop packet with zero session length. [user 'test_user_please_reject_me', nas '192.168.1.226'] Mon Jan 4 11:53:16 2010 : Error: No response to status check 6007 for home server 192.168.1.225 port 1813 Mon Jan 4 11:53:43 2010 : Proxy: Marking home server 192.168.1.225 port 1813 as dead. Mon Jan 4 11:53:46 2010 : Info: [sql] stop packet with zero session length. [user 'test_user_please_reject_me', nas '192.168.1.226'] on radius-a, for status_check=request I added to acct_user, test_user_please_reject_me Auth-Type := Reject Reply-Message = "Status check only", Fall-Through = No I suspect I SHOULD be using status_check=status-server. Which then leads to why my server keeps getting marked as zombie/dead/alive.... It seems like the accounting stop packet being sent is not generating a reply...? Below is the only packet being sent... again and again.... Mon Jan 4 11:53:45 2010 Acct-Status-Type = Stop User-Name = "not_real_id@somerealm" Event-Timestamp = "Dec 31 2009 15:41:36 DST" Acct-Delay-Time = 331887 NAS-Identifier = "ERX-2" Acct-Session-Id = "0378168264" NAS-IP-Address = 192.168.1.101 Service-Type = Framed-User Framed-Protocol = PPP Framed-Compression = None ERX-Pppoe-Description = "pppoe 00:1d:68:ec:ee:64" Framed-IP-Address = 66.247.201.49 Framed-IP-Netmask = 255.255.255.255 ERX-Ingress-Policy-Name = "SOMEREALM_UP" ERX-Egress-Policy-Name = "SOMEREALM_DOWN" Calling-Station-Id = "ERX-08000000283" Acct-Input-Gigawords = 0 Acct-Input-Octets = 96 Acct-Output-Gigawords = 0 Acct-Output-Octets = 60 ERX-Input-Gigapkts = 0 Acct-Input-Packets = 0 ERX-Output-Gigapkts = 0 Acct-Output-Packets = 0 NAS-Port-Type = Ethernet NAS-Port = 2147483931 NAS-Port-Id = "GigabitEthernet 8/0.283:283" Acct-Authentic = RADIUS Acct-Session-Time = 0 Acct-Terminate-Cause = User-Request Proxy-State = 0x3534313734 Acct-Unique-Session-Id = "038113f04620fe75" Timestamp = 1262620425 Request-Authenticator = Verified I'm not certain what additional info would be helpful at this point. Thanks, -craig -------------------------------------------------------------------------------- Craig Campbell craig.campbell@ccraft.ca CampbellCraft Consulting Inc 2 Kenny Court Whitby, Ontario Canada L1R 2L8 905 922-2789 __________ Information from ESET Smart Security, version of virus signature database 4743 (20100104) __________ The message was checked by ESET Smart Security. http://www.eset.com
Craig Campbell wrote:
There are 2 radius servers (radius-a and radius-b). Each server will relay packets it receives to the other server. (Currently only accounting packets are being received) The packets are collected in detail-relay file. The packets are then relayed via the sites/enabled/copy-acct-to-home-server config.
OK...
What I observe is a single packet being read from the detail-relay.work file on radius-b and being sent radius-a. I do not see any response from radius-a being returned to radius-b. After what seems to be about 30 seconds the packet is resent from radius-b to radius-a. Again and again...
If the home server doesn't respond, the packet will be retried forever.
On radius-b the following messages are logged (status_check = status-server).... .. Mon Jan 4 10:10:42 2010 : Proxy: Marking home server 192.168.1.225 port 1813 as zombie (it looks like it is dead). Mon Jan 4 10:10:42 2010 : Proxy: Received response to status check 5938 (1 in current sequence) Mon Jan 4 10:11:11 2010 : Proxy: Received response to status check 6013 (2 in current sequence) Mon Jan 4 10:11:40 2010 : Proxy: Received response to status check 6048 (3 in current sequence) Mon Jan 4 10:11:40 2010 : Proxy: Marking home server 192.168.1.225 port 1813 alive Mon Jan 4 10:11:43 2010 : Proxy: Marking home server 192.168.1.225 port 1813 as zombie (it looks like it is dead).
Uh... the "response_window" is 3 seconds? Why?
Mon Jan 4 10:11:43 2010 : Proxy: Received response to status check 6051 (4 in current sequence) Mon Jan 4 10:11:43 2010 : Proxy: Marking home server 192.168.1.225 port 1813 alive
Hmm... that last bit shouldn't happen. The timing is such that it *can* send more than 3 Status-Server packets. But it should use those to make only *one* transition from "dead" to "alive".
Mon Jan 4 10:12:13 2010 : Proxy: Marking home server 192.168.1.225 port 1813 as zombie (it looks like it is dead). Mon Jan 4 10:12:13 2010 : Proxy: Received response to status check 6086 (5 in current sequence)
OK... the home server isn't getting the sequence numbers re-set. That's an issue, but probably a minor one.
Mon Jan 4 11:53:46 2010 : Info: [sql] stop packet with zero session length. [user 'test_user_please_reject_me', nas '192.168.1.226']
Why are you trying to log a test packet to SQL? Just make sure that the 'accounting' section returns 'ok' for the test packet.
I suspect I SHOULD be using status_check=status-server. Which then leads to why my server keeps getting marked as zombie/dead/alive....
Because the home server is down, and isn't responding.
It seems like the accounting stop packet being sent is not generating a reply...?
Yes. Go fix that. In 2.1.8, see raddb/sites-available/default. Go to the "accounting" section, and read the comments after the "sql" module. Alan DeKok.
participants (2)
-
Alan DeKok -
Craig Campbell