Freeradius Isn't Listening
Hi everyone, Firstly, I'm new to this list, but I've searched for an answer to my problems for quite a while, and haven't been able to find a solution. Please excuse me if this has already been asked. *USAGE* I'm using Freeradius to log call statistics from my Cisco AS5400 call gateway to a MySQL database. We use this for accounting ( to keep track of how many minutes callers use ). *VERSION* I'm using FreeRADIUS Version 2.1.0, for host x86_64-pc-linux-gnu, built on Sep 17 2009 at 17:46:37 on ubuntu-server. *PROBLEM* The problem I'm having is that when I run Freeradius (in production or debug mode), my Cisco AS5400 is unable to connect to the freeradius server. When I do a netstat -a on my freeradius server, I see no connections listening on ports 1812 and 1813 (which freeradius should be listening on). I believe that once this problem has been resolved, my setup will work correctly: 1. Call comes into my Cisco AS5400. 2. Cisco AS5400 sends accounting requests to my freeradius server. 3. Freeradius server performs a MySQL query to my MySQL database. 4. Caller hangs up. 5. Cisco AS5400 sends an accounting request to my freeradius server. 6. Freeradius server performs a MySQL update to my MySQL database, thus ending the transaction. *FREERADIUS DEBUG* Here is the output of: freeradius -X root@RAD01:~# freeradius -X FreeRADIUS Version 2.1.0, for host x86_64-pc-linux-gnu, built on Sep 17 2009 at 17:46:37 Copyright (C) 1999-2008 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 v2. Starting - reading configuration files ... including configuration file /etc/freeradius/radiusd.conf including configuration file /etc/freeradius/clients.conf including files in directory /etc/freeradius/modules/ including configuration file /etc/freeradius/modules/krb5 including configuration file /etc/freeradius/modules/pap including configuration file /etc/freeradius/modules/unix including configuration file /etc/freeradius/modules/linelog including configuration file /etc/freeradius/modules/detail.example.com including configuration file /etc/freeradius/modules/wimax including configuration file /etc/freeradius/modules/realm including configuration file /etc/freeradius/modules/sql_log including configuration file /etc/freeradius/modules/exec including configuration file /etc/freeradius/modules/mac2ip including configuration file /etc/freeradius/modules/detail.log including configuration file /etc/freeradius/modules/passwd including configuration file /etc/freeradius/modules/attr_rewrite including configuration file /etc/freeradius/modules/acct_unique including configuration file /etc/freeradius/modules/always including configuration file /etc/freeradius/modules/digest including configuration file /etc/freeradius/modules/radutmp including configuration file /etc/freeradius/modules/attr_filter including configuration file /etc/freeradius/modules/smbpasswd including configuration file /etc/freeradius/modules/checkval including configuration file /etc/freeradius/modules/files including configuration file /etc/freeradius/modules/counter including configuration file /etc/freeradius/modules/expiration including configuration file /etc/freeradius/modules/chap including configuration file /etc/freeradius/modules/inner-eap including configuration file /etc/freeradius/modules/pam including configuration file /etc/freeradius/modules/policy including configuration file /etc/freeradius/modules/sradutmp including configuration file /etc/freeradius/modules/detail including configuration file /etc/freeradius/modules/expr including configuration file /etc/freeradius/modules/ippool including configuration file /etc/freeradius/modules/logintime including configuration file /etc/freeradius/modules/mschap including configuration file /etc/freeradius/modules/ldap including configuration file /etc/freeradius/modules/mac2vlan including configuration file /etc/freeradius/modules/preprocess including configuration file /etc/freeradius/modules/etc_group including configuration file /etc/freeradius/modules/echo including configuration file /etc/freeradius/sql.conf including configuration file /etc/freeradius/sql/mysql/dialup.conf including files in directory /etc/freeradius/sites-enabled/ including configuration file /etc/freeradius/sites-enabled/inner-tunnel including configuration file /etc/freeradius/sites-enabled/default including dictionary file /etc/freeradius/dictionary main { prefix = "/usr" localstatedir = "/var" logdir = "/var/log/freeradius" libdir = "/usr/lib/freeradius" radacctdir = "/var/log/freeradius/radacct" hostname_lookups = no max_request_time = 30 cleanup_delay = 5 max_requests = 9600 allow_core_dumps = no pidfile = "/var/run/freeradius/freeradius.pid" checkrad = "/usr/sbin/checkrad" debug_level = 0 proxy_requests = no log { stripped_names = no auth = yes auth_badpass = yes auth_goodpass = yes } security { max_attributes = 200 reject_delay = 1 status_server = yes } } client xx.xx.xx.xx { ipaddr = xx.xx.xx.xx require_message_authenticator = no secret = "password" shortname = "AA" nastype = "cisco" } radiusd: #### Loading Realms and Home Servers #### radiusd: #### Instantiating modules #### instantiate { } radiusd: #### Loading Virtual Servers #### server inner-tunnel { modules { Module: Checking session {...} for more modules to load Module: Linked to module rlm_sql Module: Instantiating sql sql { driver = "rlm_sql_mysql" server = "xx.xx.xx.xx" port = "" login = "radius" password = "password" radius_db = "accounting" read_groups = yes sqltrace = yes sqltracefile = "/var/log/freeradius/sqltrace.sql" readclients = no deletestalesessions = yes num_sql_socks = 25 sql_user_name = "%{User-Name}" default_user_profile = "" nas_query = "SELECT id,nasname,shortname,type,secret FROM nas" authorize_check_query = "" authorize_group_check_query = "" authorize_group_reply_query = "" accounting_onoff_query = "" accounting_update_query = "" accounting_update_query_alt = "" accounting_start_query = "INSERT INTO dids (sessionid, did, caller, start) VALUES ('%{NAS-Identifier}%{Acct-Session-Id}', '%{Called-Station-Id}', '%{Calling-Station-Id}', NOW())" accounting_start_query_alt = "" accounting_stop_query = "UPDATE dids SET stop=NOW(), duration=%{Acct-Session-Time}, termination_cause='%{Acct-Terminate-Cause}' WHERE sessionid='%{NAS-Identifier}%{Acct-Session-Id}' LIMIT 1" accounting_stop_query_alt = "" connect_failure_retry_delay = 60 simul_count_query = "" simul_verify_query = "" postauth_query = "" safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" } rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked rlm_sql (sql): Attempting to connect to radius@xx.xx.xx.xx:/accounting rlm_sql (sql): starting 0 rlm_sql (sql): Attempting to connect rlm_sql_mysql #0 rlm_sql_mysql: Starting connect to MySQL server for #0 rlm_sql (sql): Connected new DB handle, #0 rlm_sql (sql): starting 1 rlm_sql (sql): Attempting to connect rlm_sql_mysql #1 rlm_sql_mysql: Starting connect to MySQL server for #1 rlm_sql (sql): Connected new DB handle, #1 rlm_sql (sql): starting 2 rlm_sql (sql): Attempting to connect rlm_sql_mysql #2 rlm_sql_mysql: Starting connect to MySQL server for #2 rlm_sql (sql): Connected new DB handle, #2 rlm_sql (sql): starting 3 rlm_sql (sql): Attempting to connect rlm_sql_mysql #3 rlm_sql_mysql: Starting connect to MySQL server for #3 rlm_sql (sql): Connected new DB handle, #3 rlm_sql (sql): starting 4 rlm_sql (sql): Attempting to connect rlm_sql_mysql #4 rlm_sql_mysql: Starting connect to MySQL server for #4 rlm_sql (sql): Connected new DB handle, #4 rlm_sql (sql): starting 5 rlm_sql (sql): Attempting to connect rlm_sql_mysql #5 rlm_sql_mysql: Starting connect to MySQL server for #5 rlm_sql (sql): Connected new DB handle, #5 rlm_sql (sql): starting 6 rlm_sql (sql): Attempting to connect rlm_sql_mysql #6 rlm_sql_mysql: Starting connect to MySQL server for #6 rlm_sql (sql): Connected new DB handle, #6 rlm_sql (sql): starting 7 rlm_sql (sql): Attempting to connect rlm_sql_mysql #7 rlm_sql_mysql: Starting connect to MySQL server for #7 rlm_sql (sql): Connected new DB handle, #7 rlm_sql (sql): starting 8 rlm_sql (sql): Attempting to connect rlm_sql_mysql #8 rlm_sql_mysql: Starting connect to MySQL server for #8 rlm_sql (sql): Connected new DB handle, #8 rlm_sql (sql): starting 9 rlm_sql (sql): Attempting to connect rlm_sql_mysql #9 rlm_sql_mysql: Starting connect to MySQL server for #9 rlm_sql (sql): Connected new DB handle, #9 rlm_sql (sql): starting 10 rlm_sql (sql): Attempting to connect rlm_sql_mysql #10 rlm_sql_mysql: Starting connect to MySQL server for #10 rlm_sql (sql): Connected new DB handle, #10 rlm_sql (sql): starting 11 rlm_sql (sql): Attempting to connect rlm_sql_mysql #11 rlm_sql_mysql: Starting connect to MySQL server for #11 rlm_sql (sql): Connected new DB handle, #11 rlm_sql (sql): starting 12 rlm_sql (sql): Attempting to connect rlm_sql_mysql #12 rlm_sql_mysql: Starting connect to MySQL server for #12 rlm_sql (sql): Connected new DB handle, #12 rlm_sql (sql): starting 13 rlm_sql (sql): Attempting to connect rlm_sql_mysql #13 rlm_sql_mysql: Starting connect to MySQL server for #13 rlm_sql (sql): Connected new DB handle, #13 rlm_sql (sql): starting 14 rlm_sql (sql): Attempting to connect rlm_sql_mysql #14 rlm_sql_mysql: Starting connect to MySQL server for #14 rlm_sql (sql): Connected new DB handle, #14 rlm_sql (sql): starting 15 rlm_sql (sql): Attempting to connect rlm_sql_mysql #15 rlm_sql_mysql: Starting connect to MySQL server for #15 rlm_sql (sql): Connected new DB handle, #15 rlm_sql (sql): starting 16 rlm_sql (sql): Attempting to connect rlm_sql_mysql #16 rlm_sql_mysql: Starting connect to MySQL server for #16 rlm_sql (sql): Connected new DB handle, #16 rlm_sql (sql): starting 17 rlm_sql (sql): Attempting to connect rlm_sql_mysql #17 rlm_sql_mysql: Starting connect to MySQL server for #17 rlm_sql (sql): Connected new DB handle, #17 rlm_sql (sql): starting 18 rlm_sql (sql): Attempting to connect rlm_sql_mysql #18 rlm_sql_mysql: Starting connect to MySQL server for #18 rlm_sql (sql): Connected new DB handle, #18 rlm_sql (sql): starting 19 rlm_sql (sql): Attempting to connect rlm_sql_mysql #19 rlm_sql_mysql: Starting connect to MySQL server for #19 rlm_sql (sql): Connected new DB handle, #19 rlm_sql (sql): starting 20 rlm_sql (sql): Attempting to connect rlm_sql_mysql #20 rlm_sql_mysql: Starting connect to MySQL server for #20 rlm_sql (sql): Connected new DB handle, #20 rlm_sql (sql): starting 21 rlm_sql (sql): Attempting to connect rlm_sql_mysql #21 rlm_sql_mysql: Starting connect to MySQL server for #21 rlm_sql (sql): Connected new DB handle, #21 rlm_sql (sql): starting 22 rlm_sql (sql): Attempting to connect rlm_sql_mysql #22 rlm_sql_mysql: Starting connect to MySQL server for #22 rlm_sql (sql): Connected new DB handle, #22 rlm_sql (sql): starting 23 rlm_sql (sql): Attempting to connect rlm_sql_mysql #23 rlm_sql_mysql: Starting connect to MySQL server for #23 rlm_sql (sql): Connected new DB handle, #23 rlm_sql (sql): starting 24 rlm_sql (sql): Attempting to connect rlm_sql_mysql #24 rlm_sql_mysql: Starting connect to MySQL server for #24 rlm_sql (sql): Connected new DB handle, #24 } } modules { Module: Checking accounting {...} for more modules to load Module: Linked to module rlm_detail Module: Instantiating detail detail { detailfile = "/var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d" header = "%t" detailperm = 384 dirperm = 493 locking = no log_packet_header = no } Module: Checking session {...} for more modules to load } radiusd: #### Opening IP addresses and Ports #### listen { type = "auth" ipaddr = * port = 0 } listen { type = "acct" ipaddr = * port = 0 } Listening on authentication address * port 1812 Listening on accounting address * port 1813 Ready to process requests. *DEBUG LISTENING PORTS* As you can see in the previous section, my freeradius debug seems to execute perfectly. Note how it says it is listening on 1812 and 1813. When I do a netstat -a command, I get: root@RAD01:~# netstat -a Active Internet connections (servers and established) Proto Recv-Q Send-Q Local Address Foreign Address State tcp 0 0 *:ssh *:* LISTEN tcp 0 0 RAD01:37518 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37534 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37528 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37513 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37523 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37533 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37517 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37531 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37512 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37529 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:ssh cpe-xx.xx.xx.xx.:42502 ESTABLISHED tcp 0 0 RAD01:37519 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37530 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:ssh xx.xx.xx.xx.s:45758 ESTABLISHED tcp 0 0 RAD01:37516 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37515 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37514 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37511 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37510 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37522 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37526 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37521 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37525 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37524 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37520 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37527 xx.xx.xx.xx.s:mysql ESTABLISHED tcp 0 0 RAD01:37532 xx.xx.xx.xx.s:mysql ESTABLISHED tcp6 0 0 [::]:ssh [::]:* LISTEN udp 0 0 *:radius *:* udp 0 0 *:radius-acct *:* Active UNIX domain sockets (servers and established) Proto RefCnt Flags Type State I-Node Path unix 4 [ ] DGRAM 3587 /dev/log unix 2 [ ACC ] STREAM LISTENING 2363 @/com/ubuntu/upstart unix 2 [ ] DGRAM 2429 @/org/kernel/udev/udevd unix 2 [ ] DGRAM 3868 unix 2 [ ] DGRAM 3813 unix 3 [ ] DGRAM 2432 unix 3 [ ] DGRAM 2431 unix 3 [ ] STREAM CONNECTED 2415 @/com/ubuntu/upstart unix 3 [ ] STREAM CONNECTED 2414 Note how it appears that ports 1812 and 1813 do not have anything listening... *DEBUG NETWORK* Now, after seeing this, I thought maybe I have a firewall active or something. But upon further investigation, I found that iptables has no rules: root@RAD01:~# iptables -L Chain INPUT (policy ACCEPT) target prot opt source destination Chain FORWARD (policy ACCEPT) target prot opt source destination Chain OUTPUT (policy ACCEPT) target prot opt source destination And that my server is on a public IP (our radius server is hosted in the rackspace cloud, no firewall or anything as far as I know). *CONFIG FILES* Here are my freeradius configuration files. I've put them on a pastebin because I didn't want to make this email immensely long. Please have a look at them if you have any questions. http://pastie.org/893100 *CISCO SETUP* As I mentioned earlier, my freeradius *client* in this setup is my Cisco AS5400. When I have radius debugging turned on, on my cisco, here is some debugging output from a call. As you can see, it says that the server is not online. When I make calls, I see no activity in my freeradius debug window. So it seems that the packets aren't getting to freeradius from my cisco. *Jan 2 08:47:02.895: AAA/BIND(00000190): Bind i/f Serial7/0:15:23 *Jan 2 08:47:02.899: AAA/BIND(00000191): Bind i/f *Jan 2 08:47:02.903: RADIUS/ENCODE(00000191):Orig. component type = VOICE *Jan 2 08:47:02.903: RADIUS(00000191): Config NAS IP: 0.0.0.0 *Jan 2 08:47:02.903: RADIUS(00000191): sending *Jan 2 08:47:02.903: RADIUS/ENCODE: Best Local IP-Address 10.0.2.1 for Radius-Server xx.xx.xx.xx *Jan 2 08:47:02.907: RADIUS(00000191): Send Accounting-Request to xx.xx.xx.xx:1813 id 1646/154, len 128 *Jan 2 08:47:02.907: RADIUS: authenticator 5A 66 34 6D 47 00 B7 9E - BD 76 22 42 14 B6 A1 59 *Jan 2 08:47:02.907: RADIUS: Acct-Session-Id [44] 18 "0200000000000253" *Jan 2 08:47:02.907: RADIUS: Calling-Station-Id [31] 12 "8182179228" *Jan 2 08:47:02.907: RADIUS: Called-Station-Id [30] 12 "2172386245" *Jan 2 08:47:02.907: RADIUS: User-Name [1] 12 "8182179228" *Jan 2 08:47:02.907: RADIUS: Acct-Status-Type [40] 6 Start [1] *Jan 2 08:47:02.907: RADIUS: NAS-Port-Type [61] 6 Async [0] *Jan 2 08:47:02.907: RADIUS: NAS-Port [5] 6 0 *Jan 2 08:47:02.907: RADIUS: NAS-Port-Id [87] 18 "ISDN 7/7:15:D:24" *Jan 2 08:47:02.907: RADIUS: Service-Type [6] 6 Login [1] *Jan 2 08:47:02.907: RADIUS: NAS-IP-Address [4] 6 10.0.2.1 *Jan 2 08:47:02.907: RADIUS: Acct-Delay-Time [41] 6 0 *Jan 2 08:47:07.655: RADIUS: acct-timeout for 4012ECE4 now 5, acct-jitter 4294967295, acct-delay-time (at 4012ED5E) now 4 *Jan 2 08:47:07.655: RADIUS: no sg in radius-timers: ctx 0x66F7FB78 sg 0x0000 *Jan 2 08:47:07.655: RADIUS: Retransmit to (xx.xx.xx.xx:1812,1813) for id 1646/155 *Jan 2 08:47:12.687: RADIUS: acct-timeout for 4012ECE4 now 9, acct-jitter 0, acct-delay-time (at 4012ED5E) now 9 *Jan 2 08:47:12.687: RADIUS: no sg in radius-timers: ctx 0x66F7FB78 sg 0x0000 *Jan 2 08:47:12.687: RADIUS: Retransmit to (xx.xx.xx.xx:1812,1813) for id 1646/156 *Jan 2 08:47:14.947: RADIUS/ENCODE(00000191):Orig. component type = VOICE *Jan 2 08:47:14.947: RADIUS(00000191): Config NAS IP: 0.0.0.0 *Jan 2 08:47:14.947: RADIUS(00000191): sending *Jan 2 08:47:14.951: RADIUS/ENCODE: Best Local IP-Address xx.xx.xx.xx for Radius-Server xx.xx.xx.xx *Jan 2 08:47:14.951: RADIUS(00000191): Send Accounting-Request to xx.xx.xx.xx:1813 id 1646/157, len 158 *Jan 2 08:47:14.951: RADIUS: authenticator 6F 5D 1E 4E CC 63 E0 A1 - 64 3B 75 46 FF 42 65 55 *Jan 2 08:47:14.951: RADIUS: Acct-Session-Id [44] 18 "0200000000000253" *Jan 2 08:47:14.951: RADIUS: Calling-Station-Id [31] 12 "8182179228" *Jan 2 08:47:14.951: RADIUS: Called-Station-Id [30] 12 "2172386245" *Jan 2 08:47:14.951: RADIUS: Acct-Input-Octets [42] 6 94880 *Jan 2 08:47:14.951: RADIUS: Acct-Output-Octets [43] 6 95520 *Jan 2 08:47:14.951: RADIUS: Acct-Input-Packets [47] 6 593 *Jan 2 08:47:14.951: RADIUS: Acct-Output-Packets [48] 6 597 *Jan 2 08:47:14.951: RADIUS: Acct-Session-Time [46] 6 12 *Jan 2 08:47:14.951: RADIUS: User-Name [1] 12 "8182179228" *Jan 2 08:47:14.951: RADIUS: Acct-Status-Type [40] 6 Stop [2] *Jan 2 08:47:14.951: RADIUS: NAS-Port-Type [61] 6 Async [0] *Jan 2 08:47:14.951: RADIUS: NAS-Port [5] 6 0 *Jan 2 08:47:14.951: RADIUS: NAS-Port-Id [87] 18 "ISDN 7/7:15:D:24" *Jan 2 08:47:14.951: RADIUS: Service-Type [6] 6 Login [1] *Jan 2 08:47:14.951: RADIUS: NAS-IP-Address [4] 6 10.0.2.1 *Jan 2 08:47:14.951: RADIUS: Acct-Delay-Time [41] 6 0 *Jan 2 08:47:17.559: RADIUS: acct-timeout for 4012ECE4 now 14, acct-jitter 0, acct-delay-time (at 4012ED5E) now 14 *Jan 2 08:47:17.559: RADIUS: no sg in radius-timers: ctx 0x66F7FB78 sg 0x0000 *Jan 2 08:47:17.559: RADIUS: Retransmit to (xx.xx.xx.xx:1812,1813) for id 1646/158 *Jan 2 08:47:19.871: RADIUS: acct-timeout for 4013486C now 5, acct-jitter 4294967295, acct-delay-time (at 40134904) now 4 *Jan 2 08:47:19.871: RADIUS: no sg in radius-timers: ctx 0x67045494 sg 0x0000 *Jan 2 08:47:19.871: %RADIUS-4-RADIUS_DEAD: RADIUS server xx.xx.xx.xx:1812,1813 is not responding. *Jan 2 08:47:19.871: %RADIUS-4-RADIUS_ALIVE: RADIUS server xx.xx.xx.xx:1812,1813 has returned. *Jan 2 08:47:19.871: RADIUS: Retransmit to (xx.xx.xx.xx:1812,1813) for id 1646/159 *Jan 2 08:47:22.527: RADIUS: acct-timeout for 4012ECE4 now 19, acct-jitter 0, acct-delay-time (at 4012ED5E) now 19 *Jan 2 08:47:22.527: RADIUS: no sg in radius-timers: ctx 0x66F7FB78 sg 0x0000 *Jan 2 08:47:22.527: RADIUS: No response from (xx.xx.xx.xx:1812,1813) for id 1646/158 *Jan 2 08:47:22.527: RADIUS/DECODE: No response from radius-server; parse response; FAIL *Jan 2 08:47:22.527: RADIUS/DECODE: Case error(no response/ bad packet/ op decode);parse response; FAIL *Jan 2 08:47:24.903: RADIUS: acct-timeout for 4013486C now 9, acct-jitter 0, acct-delay-time (at 40134904) now 9 *Jan 2 08:47:24.903: RADIUS: no sg in radius-timers: ctx 0x67045494 sg 0x0000 *Jan 2 08:47:24.903: RADIUS: Retransmit to (173.203.117.112:1812,1813) for id 1646/161 *Jan 2 08:47:29.415: RADIUS: acct-timeout for 4013486C now 14, acct-jitter 0, acct-delay-time (at 40134904) now 14 *Jan 2 08:47:29.415: RADIUS: no sg in radius-timers: ctx 0x67045494 sg 0x0000 *Jan 2 08:47:29.415: RADIUS: Retransmit to (xx.xx.xx.xx:1812,1813) for id 1646/162 *Jan 2 08:47:34.415: RADIUS: acct-timeout for 4013486C now 19, acct-jitter 0, acct-delay-time (at 40134904) now 19 *Jan 2 08:47:34.415: RADIUS: no sg in radius-timers: ctx 0x67045494 sg 0x0000 *Jan 2 08:47:34.415: RADIUS: No response from (xx.xx.xx.xx:1812,1813) for id 1646/162 *Jan 2 08:47:34.415: RADIUS/DECODE: No response from radius-server; parse response; FAIL *Jan 2 08:47:34.415: RADIUS/DECODE: Case error(no response/ bad packet/ op decode);parse response; FAIL *HELP!* OK, so sorry for this terribly long email, but I hope that this has provided enough information for you guys to help me debug what the heck is going wrong here. I've spent tons of hours trying to resolve this to no avail. I'm out of ideas. Thanks so much for all of your help, this has been a really irritating and frustrating experience. I'm hoping that if anyone else has the same problem, this thread may help them later on. Thanks! -Randall
On Mon, Mar 29, 2010 at 2:12 PM, Randall Degges <rdegges@gmail.com> wrote:
FreeRADIUS Version 2.1.0, for host x86_64-pc-linux-gnu, built on Sep 17 2009
why? better use latest stable version.
Listening on authentication address * port 1812 Listening on accounting address * port 1813
root@RAD01:~# netstat -a
udp 0 0 *:radius *:* udp 0 0 *:radius-acct *:*
Note how it appears that ports 1812 and 1813 do not have anything listening...
Note how it says "radius" and "radius-acct"? run "grep radius /etc/services" and "netstat -anp"
As I mentioned earlier, my freeradius *client* in this setup is my Cisco AS5400. When I have radius debugging turned on, on my cisco, here is some debugging output from a call.
what is the output of freeradius debug at that point? -- Fajar
Hi,
*PROBLEM*
The problem I'm having is that when I run Freeradius (in production or debug mode), my Cisco AS5400 is unable to connect to the freeradius server. When I do a netstat -a on my freeradius server, I see no connections listening on ports 1812 and 1813 (which freeradius should be listening on).
It listens just fine: your netstat shows udp 0 0 *:radius *:* udp 0 0 *:radius-acct *:* You wouldn't believe it, but the IANA assigned port for "radius" is 1812 and "radius-acct" is 1813. It is BTW also what your FreeRADIUS debug says: Listening on authentication address * port 1812 Listening on accounting address * port 1813 Ready to process requests. So absolutely no problem here. If your server doesn't get any packets, then either the AS5400 isn't sending any, or there is indeed a firewall or other middlebox preventing the traffic from reaching your server.
I believe that once this problem has been resolved, my setup will work correctly:
1. Call comes into my Cisco AS5400. 2. Cisco AS5400 sends accounting requests to my freeradius server. 3. Freeradius server performs a MySQL query to my MySQL database. 4. Caller hangs up. 5. Cisco AS5400 sends an accounting request to my freeradius server. 6. Freeradius server performs a MySQL update to my MySQL database, thus ending the transaction.
That's what many people do, including myself. It works fine, if the accounting packets actually reach the server :-)
And that my server is on a public IP (our radius server is hosted in the rackspace cloud, no firewall or anything as far as I know).
Maybe the "as far as I know" constitutes a problem here? Find out with "tcpdump udp port 1813" if there is any accounting traffic reaching your box. Greetings, Stefan Winter
*CISCO SETUP*
As I mentioned earlier, my freeradius *client* in this setup is my Cisco AS5400. When I have radius debugging turned on, on my cisco, here is some debugging output from a call. As you can see, it says that the server is not online. When I make calls, I see no activity in my freeradius debug window. So it seems that the packets aren't getting to freeradius from my cisco.
*Jan 2 08:47:02.895: AAA/BIND(00000190): Bind i/f Serial7/0:15:23 *Jan 2 08:47:02.899: AAA/BIND(00000191): Bind i/f *Jan 2 08:47:02.903: RADIUS/ENCODE(00000191):Orig. component type = VOICE *Jan 2 08:47:02.903: RADIUS(00000191): Config NAS IP: 0.0.0.0 *Jan 2 08:47:02.903: RADIUS(00000191): sending *Jan 2 08:47:02.903: RADIUS/ENCODE: Best Local IP-Address 10.0.2.1 for Radius-Server xx.xx.xx.xx
*Jan 2 08:47:02.907: RADIUS(00000191): Send Accounting-Request to xx.xx.xx.xx:1813 id 1646/154, len 128
*Jan 2 08:47:02.907: RADIUS: authenticator 5A 66 34 6D 47 00 B7 9E - BD 76 22 42 14 B6 A1 59
*Jan 2 08:47:02.907: RADIUS: Acct-Session-Id [44] 18 "0200000000000253" *Jan 2 08:47:02.907: RADIUS: Calling-Station-Id [31] 12 "8182179228" *Jan 2 08:47:02.907: RADIUS: Called-Station-Id [30] 12 "2172386245" *Jan 2 08:47:02.907: RADIUS: User-Name [1] 12 "8182179228" *Jan 2 08:47:02.907: RADIUS: Acct-Status-Type [40] 6 Start [1] *Jan 2 08:47:02.907: RADIUS: NAS-Port-Type [61] 6 Async [0] *Jan 2 08:47:02.907: RADIUS: NAS-Port [5] 6 0
*Jan 2 08:47:02.907: RADIUS: NAS-Port-Id [87] 18 "ISDN 7/7:15:D:24" *Jan 2 08:47:02.907: RADIUS: Service-Type [6] 6 Login [1] *Jan 2 08:47:02.907: RADIUS: NAS-IP-Address [4] 6 10.0.2.1
*Jan 2 08:47:02.907: RADIUS: Acct-Delay-Time [41] 6 0
*Jan 2 08:47:07.655: RADIUS: acct-timeout for 4012ECE4 now 5, acct-jitter 4294967295, acct-delay-time (at 4012ED5E) now 4
*Jan 2 08:47:07.655: RADIUS: no sg in radius-timers: ctx 0x66F7FB78 sg 0x0000 *Jan 2 08:47:07.655: RADIUS: Retransmit to (xx.xx.xx.xx:1812,1813) for id 1646/155 *Jan 2 08:47:12.687: RADIUS: acct-timeout for 4012ECE4 now 9, acct-jitter 0, acct-delay-time (at 4012ED5E) now 9
*Jan 2 08:47:12.687: RADIUS: no sg in radius-timers: ctx 0x66F7FB78 sg 0x0000 *Jan 2 08:47:12.687: RADIUS: Retransmit to (xx.xx.xx.xx:1812,1813) for id 1646/156 *Jan 2 08:47:14.947: RADIUS/ENCODE(00000191):Orig. component type = VOICE *Jan 2 08:47:14.947: RADIUS(00000191): Config NAS IP: 0.0.0.0
*Jan 2 08:47:14.947: RADIUS(00000191): sending
*Jan 2 08:47:14.951: RADIUS/ENCODE: Best Local IP-Address xx.xx.xx.xx for Radius-Server xx.xx.xx.xx
*Jan 2 08:47:14.951: RADIUS(00000191): Send Accounting-Request to xx.xx.xx.xx:1813 id 1646/157, len 158
*Jan 2 08:47:14.951: RADIUS: authenticator 6F 5D 1E 4E CC 63 E0 A1 - 64 3B 75 46 FF 42 65 55
*Jan 2 08:47:14.951: RADIUS: Acct-Session-Id [44] 18 "0200000000000253" *Jan 2 08:47:14.951: RADIUS: Calling-Station-Id [31] 12 "8182179228" *Jan 2 08:47:14.951: RADIUS: Called-Station-Id [30] 12 "2172386245" *Jan 2 08:47:14.951: RADIUS: Acct-Input-Octets [42] 6 94880
*Jan 2 08:47:14.951: RADIUS: Acct-Output-Octets [43] 6 95520
*Jan 2 08:47:14.951: RADIUS: Acct-Input-Packets [47] 6 593
*Jan 2 08:47:14.951: RADIUS: Acct-Output-Packets [48] 6 597
*Jan 2 08:47:14.951: RADIUS: Acct-Session-Time [46] 6 12
*Jan 2 08:47:14.951: RADIUS: User-Name [1] 12 "8182179228" *Jan 2 08:47:14.951: RADIUS: Acct-Status-Type [40] 6 Stop [2] *Jan 2 08:47:14.951: RADIUS: NAS-Port-Type [61] 6 Async [0] *Jan 2 08:47:14.951: RADIUS: NAS-Port [5] 6 0 *Jan 2 08:47:14.951: RADIUS: NAS-Port-Id [87] 18 "ISDN 7/7:15:D:24" *Jan 2 08:47:14.951: RADIUS: Service-Type [6] 6 Login [1] *Jan 2 08:47:14.951: RADIUS: NAS-IP-Address [4] 6 10.0.2.1 *Jan 2 08:47:14.951: RADIUS: Acct-Delay-Time [41] 6 0 *Jan 2 08:47:17.559: RADIUS: acct-timeout for 4012ECE4 now 14, acct-jitter 0, acct-delay-time (at 4012ED5E) now 14 *Jan 2 08:47:17.559: RADIUS: no sg in radius-timers: ctx 0x66F7FB78 sg 0x0000 *Jan 2 08:47:17.559: RADIUS: Retransmit to (xx.xx.xx.xx:1812,1813) for id 1646/158 *Jan 2 08:47:19.871: RADIUS: acct-timeout for 4013486C now 5, acct-jitter 4294967295, acct-delay-time (at 40134904) now 4 *Jan 2 08:47:19.871: RADIUS: no sg in radius-timers: ctx 0x67045494 sg 0x0000 *Jan 2 08:47:19.871: %RADIUS-4-RADIUS_DEAD: RADIUS server xx.xx.xx.xx:1812,1813 is not responding. *Jan 2 08:47:19.871: %RADIUS-4-RADIUS_ALIVE: RADIUS server xx.xx.xx.xx:1812,1813 has returned. *Jan 2 08:47:19.871: RADIUS: Retransmit to (xx.xx.xx.xx:1812,1813) for id 1646/159 *Jan 2 08:47:22.527: RADIUS: acct-timeout for 4012ECE4 now 19, acct-jitter 0, acct-delay-time (at 4012ED5E) now 19 *Jan 2 08:47:22.527: RADIUS: no sg in radius-timers: ctx 0x66F7FB78 sg 0x0000 *Jan 2 08:47:22.527: RADIUS: No response from (xx.xx.xx.xx:1812,1813) for id 1646/158 *Jan 2 08:47:22.527: RADIUS/DECODE: No response from radius-server; parse response; FAIL *Jan 2 08:47:22.527: RADIUS/DECODE: Case error(no response/ bad packet/ op decode);parse response; FAIL *Jan 2 08:47:24.903: RADIUS: acct-timeout for 4013486C now 9, acct-jitter 0, acct-delay-time (at 40134904) now 9 *Jan 2 08:47:24.903: RADIUS: no sg in radius-timers: ctx 0x67045494 sg 0x0000 *Jan 2 08:47:24.903: RADIUS: Retransmit to (173.203.117.112:1812 <http://173.203.117.112:1812>,1813) for id 1646/161 *Jan 2 08:47:29.415: RADIUS: acct-timeout for 4013486C now 14, acct-jitter 0, acct-delay-time (at 40134904) now 14 *Jan 2 08:47:29.415: RADIUS: no sg in radius-timers: ctx 0x67045494 sg 0x0000 *Jan 2 08:47:29.415: RADIUS: Retransmit to (xx.xx.xx.xx:1812,1813) for id 1646/162 *Jan 2 08:47:34.415: RADIUS: acct-timeout for 4013486C now 19, acct-jitter 0, acct-delay-time (at 40134904) now 19 *Jan 2 08:47:34.415: RADIUS: no sg in radius-timers: ctx 0x67045494 sg 0x0000 *Jan 2 08:47:34.415: RADIUS: No response from (xx.xx.xx.xx:1812,1813) for id 1646/162 *Jan 2 08:47:34.415: RADIUS/DECODE: No response from radius-server; parse response; FAIL *Jan 2 08:47:34.415: RADIUS/DECODE: Case error(no response/ bad packet/ op decode);parse response; FAIL
*HELP!*
OK, so sorry for this terribly long email, but I hope that this has provided enough information for you guys to help me debug what the heck is going wrong here. I've spent tons of hours trying to resolve this to no avail. I'm out of ideas.
Thanks so much for all of your help, this has been a really irritating and frustrating experience. I'm hoping that if anyone else has the same problem, this thread may help them later on.
Thanks!
-Randall
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Stefan WINTER Ingenieur de Recherche Fondation RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche 6, rue Richard Coudenhove-Kalergi L-1359 Luxembourg Tel: +352 424409 1 Fax: +352 422473
Hi Stefan, Ah, I thought that it would have to show in the bottom portion of my netstat with the port numbers. Also, when I run tcpdump (tcpdump port 1812) (tcpdump port 1813) I see no packets at all. I've submitted a ticket with rackspace, although I'm like 99% sure there is no firewall there. We have another freeradius server (really old running version 1.7) on another rackspace server instance in the cloud as well, and it seems to work just fine (and it has used the same as5400 as well). So I think there may be another reason still, but once I hear back from rackspace I will make an update. Thanks so much for your help so far! I can't wait to get to the bottom of this one :( -Randall On Mon, Mar 29, 2010 at 8:41 AM, Stefan Winter <stefan.winter@restena.lu>wrote:
Hi,
*PROBLEM*
The problem I'm having is that when I run Freeradius (in production or debug mode), my Cisco AS5400 is unable to connect to the freeradius server. When I do a netstat -a on my freeradius server, I see no connections listening on ports 1812 and 1813 (which freeradius should be listening on).
It listens just fine: your netstat shows
udp 0 0 *:radius *:* udp 0 0 *:radius-acct *:*
You wouldn't believe it, but the IANA assigned port for "radius" is 1812 and "radius-acct" is 1813. It is BTW also what your FreeRADIUS debug says:
Listening on authentication address * port 1812 Listening on accounting address * port 1813 Ready to process requests.
So absolutely no problem here. If your server doesn't get any packets, then either the AS5400 isn't sending any, or there is indeed a firewall or other middlebox preventing the traffic from reaching your server.
I believe that once this problem has been resolved, my setup will work correctly:
1. Call comes into my Cisco AS5400. 2. Cisco AS5400 sends accounting requests to my freeradius server. 3. Freeradius server performs a MySQL query to my MySQL database. 4. Caller hangs up. 5. Cisco AS5400 sends an accounting request to my freeradius server. 6. Freeradius server performs a MySQL update to my MySQL database, thus ending the transaction.
That's what many people do, including myself. It works fine, if the accounting packets actually reach the server :-)
And that my server is on a public IP (our radius server is hosted in the rackspace cloud, no firewall or anything as far as I know).
Maybe the "as far as I know" constitutes a problem here? Find out with "tcpdump udp port 1813" if there is any accounting traffic reaching your box.
Greetings,
Stefan Winter
*CISCO SETUP*
As I mentioned earlier, my freeradius *client* in this setup is my Cisco AS5400. When I have radius debugging turned on, on my cisco, here is some debugging output from a call. As you can see, it says that the server is not online. When I make calls, I see no activity in my freeradius debug window. So it seems that the packets aren't getting to freeradius from my cisco.
*Jan 2 08:47:02.895: AAA/BIND(00000190): Bind i/f Serial7/0:15:23 *Jan 2 08:47:02.899: AAA/BIND(00000191): Bind i/f *Jan 2 08:47:02.903: RADIUS/ENCODE(00000191):Orig. component type = VOICE *Jan 2 08:47:02.903: RADIUS(00000191): Config NAS IP: 0.0.0.0 *Jan 2 08:47:02.903: RADIUS(00000191): sending *Jan 2 08:47:02.903: RADIUS/ENCODE: Best Local IP-Address 10.0.2.1 for Radius-Server xx.xx.xx.xx
*Jan 2 08:47:02.907: RADIUS(00000191): Send Accounting-Request to xx.xx.xx.xx:1813 id 1646/154, len 128
*Jan 2 08:47:02.907: RADIUS: authenticator 5A 66 34 6D 47 00 B7 9E - BD 76 22 42 14 B6 A1 59
*Jan 2 08:47:02.907: RADIUS: Acct-Session-Id [44] 18 "0200000000000253" *Jan 2 08:47:02.907: RADIUS: Calling-Station-Id [31] 12 "8182179228" *Jan 2 08:47:02.907: RADIUS: Called-Station-Id [30] 12 "2172386245" *Jan 2 08:47:02.907: RADIUS: User-Name [1] 12 "8182179228" *Jan 2 08:47:02.907: RADIUS: Acct-Status-Type [40] 6 Start [1] *Jan 2 08:47:02.907: RADIUS: NAS-Port-Type [61] 6 Async [0] *Jan 2 08:47:02.907: RADIUS: NAS-Port [5] 6 0
*Jan 2 08:47:02.907: RADIUS: NAS-Port-Id [87] 18 "ISDN 7/7:15:D:24" *Jan 2 08:47:02.907: RADIUS: Service-Type [6] 6 Login [1] *Jan 2 08:47:02.907: RADIUS: NAS-IP-Address [4] 6 10.0.2.1
*Jan 2 08:47:02.907: RADIUS: Acct-Delay-Time [41] 6 0
*Jan 2 08:47:07.655: RADIUS: acct-timeout for 4012ECE4 now 5, acct-jitter 4294967295, acct-delay-time (at 4012ED5E) now 4
*Jan 2 08:47:07.655: RADIUS: no sg in radius-timers: ctx 0x66F7FB78 sg 0x0000 *Jan 2 08:47:07.655: RADIUS: Retransmit to (xx.xx.xx.xx:1812,1813) for id 1646/155 *Jan 2 08:47:12.687: RADIUS: acct-timeout for 4012ECE4 now 9, acct-jitter 0, acct-delay-time (at 4012ED5E) now 9
*Jan 2 08:47:12.687: RADIUS: no sg in radius-timers: ctx 0x66F7FB78 sg 0x0000 *Jan 2 08:47:12.687: RADIUS: Retransmit to (xx.xx.xx.xx:1812,1813) for id 1646/156 *Jan 2 08:47:14.947: RADIUS/ENCODE(00000191):Orig. component type = VOICE *Jan 2 08:47:14.947: RADIUS(00000191): Config NAS IP: 0.0.0.0
*Jan 2 08:47:14.947: RADIUS(00000191): sending
*Jan 2 08:47:14.951: RADIUS/ENCODE: Best Local IP-Address xx.xx.xx.xx for Radius-Server xx.xx.xx.xx
*Jan 2 08:47:14.951: RADIUS(00000191): Send Accounting-Request to xx.xx.xx.xx:1813 id 1646/157, len 158
*Jan 2 08:47:14.951: RADIUS: authenticator 6F 5D 1E 4E CC 63 E0 A1 - 64 3B 75 46 FF 42 65 55
*Jan 2 08:47:14.951: RADIUS: Acct-Session-Id [44] 18 "0200000000000253" *Jan 2 08:47:14.951: RADIUS: Calling-Station-Id [31] 12 "8182179228" *Jan 2 08:47:14.951: RADIUS: Called-Station-Id [30] 12 "2172386245" *Jan 2 08:47:14.951: RADIUS: Acct-Input-Octets [42] 6 94880
*Jan 2 08:47:14.951: RADIUS: Acct-Output-Octets [43] 6 95520
*Jan 2 08:47:14.951: RADIUS: Acct-Input-Packets [47] 6 593
*Jan 2 08:47:14.951: RADIUS: Acct-Output-Packets [48] 6 597
*Jan 2 08:47:14.951: RADIUS: Acct-Session-Time [46] 6 12
*Jan 2 08:47:14.951: RADIUS: User-Name [1] 12 "8182179228" *Jan 2 08:47:14.951: RADIUS: Acct-Status-Type [40] 6 Stop [2] *Jan 2 08:47:14.951: RADIUS: NAS-Port-Type [61] 6 Async [0] *Jan 2 08:47:14.951: RADIUS: NAS-Port [5] 6 0 *Jan 2 08:47:14.951: RADIUS: NAS-Port-Id [87] 18 "ISDN 7/7:15:D:24" *Jan 2 08:47:14.951: RADIUS: Service-Type [6] 6 Login [1] *Jan 2 08:47:14.951: RADIUS: NAS-IP-Address [4] 6 10.0.2.1 *Jan 2 08:47:14.951: RADIUS: Acct-Delay-Time [41] 6 0 *Jan 2 08:47:17.559: RADIUS: acct-timeout for 4012ECE4 now 14, acct-jitter 0, acct-delay-time (at 4012ED5E) now 14 *Jan 2 08:47:17.559: RADIUS: no sg in radius-timers: ctx 0x66F7FB78 sg 0x0000 *Jan 2 08:47:17.559: RADIUS: Retransmit to (xx.xx.xx.xx:1812,1813) for id 1646/158 *Jan 2 08:47:19.871: RADIUS: acct-timeout for 4013486C now 5, acct-jitter 4294967295, acct-delay-time (at 40134904) now 4 *Jan 2 08:47:19.871: RADIUS: no sg in radius-timers: ctx 0x67045494 sg 0x0000 *Jan 2 08:47:19.871: %RADIUS-4-RADIUS_DEAD: RADIUS server xx.xx.xx.xx:1812,1813 is not responding. *Jan 2 08:47:19.871: %RADIUS-4-RADIUS_ALIVE: RADIUS server xx.xx.xx.xx:1812,1813 has returned. *Jan 2 08:47:19.871: RADIUS: Retransmit to (xx.xx.xx.xx:1812,1813) for id 1646/159 *Jan 2 08:47:22.527: RADIUS: acct-timeout for 4012ECE4 now 19, acct-jitter 0, acct-delay-time (at 4012ED5E) now 19 *Jan 2 08:47:22.527: RADIUS: no sg in radius-timers: ctx 0x66F7FB78 sg 0x0000 *Jan 2 08:47:22.527: RADIUS: No response from (xx.xx.xx.xx:1812,1813) for id 1646/158 *Jan 2 08:47:22.527: RADIUS/DECODE: No response from radius-server; parse response; FAIL *Jan 2 08:47:22.527: RADIUS/DECODE: Case error(no response/ bad packet/ op decode);parse response; FAIL *Jan 2 08:47:24.903: RADIUS: acct-timeout for 4013486C now 9, acct-jitter 0, acct-delay-time (at 40134904) now 9 *Jan 2 08:47:24.903: RADIUS: no sg in radius-timers: ctx 0x67045494 sg 0x0000 *Jan 2 08:47:24.903: RADIUS: Retransmit to (173.203.117.112:1812 <http://173.203.117.112:1812>,1813) for id 1646/161 *Jan 2 08:47:29.415: RADIUS: acct-timeout for 4013486C now 14, acct-jitter 0, acct-delay-time (at 40134904) now 14 *Jan 2 08:47:29.415: RADIUS: no sg in radius-timers: ctx 0x67045494 sg 0x0000 *Jan 2 08:47:29.415: RADIUS: Retransmit to (xx.xx.xx.xx:1812,1813) for id 1646/162 *Jan 2 08:47:34.415: RADIUS: acct-timeout for 4013486C now 19, acct-jitter 0, acct-delay-time (at 40134904) now 19 *Jan 2 08:47:34.415: RADIUS: no sg in radius-timers: ctx 0x67045494 sg 0x0000 *Jan 2 08:47:34.415: RADIUS: No response from (xx.xx.xx.xx:1812,1813) for id 1646/162 *Jan 2 08:47:34.415: RADIUS/DECODE: No response from radius-server; parse response; FAIL *Jan 2 08:47:34.415: RADIUS/DECODE: Case error(no response/ bad packet/ op decode);parse response; FAIL
*HELP!*
OK, so sorry for this terribly long email, but I hope that this has provided enough information for you guys to help me debug what the heck is going wrong here. I've spent tons of hours trying to resolve this to no avail. I'm out of ideas.
Thanks so much for all of your help, this has been a really irritating and frustrating experience. I'm hoping that if anyone else has the same problem, this thread may help them later on.
Thanks!
-Randall
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Stefan WINTER Ingenieur de Recherche Fondation RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche 6, rue Richard Coudenhove-Kalergi L-1359 Luxembourg
Tel: +352 424409 1 Fax: +352 422473
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Stefan & Everyone, I just confirmed that my server does have no firewall. The way I tested this is: *ON THE SERVER* tcpdump udp port 1812 *ON THE CLIENT* nc -u xx.xx.xx.xx 1812 <mash the keyboard repeatedly to send fake packets> When I do this I send some raw packets to my radius server on port 1812 for testing, and my tcpdump output shows each packet being received just fine. So I don't think this is a firewall issue. Can anyone check out my configs and see if something in there may be causing this issue? Thanks so much! -Randall On Mon, Mar 29, 2010 at 9:28 AM, Randall Degges <rdegges@gmail.com> wrote:
Hi Stefan,
Ah, I thought that it would have to show in the bottom portion of my netstat with the port numbers.
Also, when I run tcpdump (tcpdump port 1812) (tcpdump port 1813) I see no packets at all. I've submitted a ticket with rackspace, although I'm like 99% sure there is no firewall there. We have another freeradius server (really old running version 1.7) on another rackspace server instance in the cloud as well, and it seems to work just fine (and it has used the same as5400 as well).
So I think there may be another reason still, but once I hear back from rackspace I will make an update.
Thanks so much for your help so far! I can't wait to get to the bottom of this one :(
-Randall
On Mon, Mar 29, 2010 at 8:41 AM, Stefan Winter <stefan.winter@restena.lu>wrote:
Hi,
*PROBLEM*
The problem I'm having is that when I run Freeradius (in production or debug mode), my Cisco AS5400 is unable to connect to the freeradius server. When I do a netstat -a on my freeradius server, I see no connections listening on ports 1812 and 1813 (which freeradius should be listening on).
It listens just fine: your netstat shows
udp 0 0 *:radius *:* udp 0 0 *:radius-acct *:*
You wouldn't believe it, but the IANA assigned port for "radius" is 1812 and "radius-acct" is 1813. It is BTW also what your FreeRADIUS debug says:
Listening on authentication address * port 1812 Listening on accounting address * port 1813 Ready to process requests.
So absolutely no problem here. If your server doesn't get any packets, then either the AS5400 isn't sending any, or there is indeed a firewall or other middlebox preventing the traffic from reaching your server.
I believe that once this problem has been resolved, my setup will work correctly:
1. Call comes into my Cisco AS5400. 2. Cisco AS5400 sends accounting requests to my freeradius server. 3. Freeradius server performs a MySQL query to my MySQL database. 4. Caller hangs up. 5. Cisco AS5400 sends an accounting request to my freeradius server. 6. Freeradius server performs a MySQL update to my MySQL database, thus ending the transaction.
That's what many people do, including myself. It works fine, if the accounting packets actually reach the server :-)
And that my server is on a public IP (our radius server is hosted in the rackspace cloud, no firewall or anything as far as I know).
Maybe the "as far as I know" constitutes a problem here? Find out with "tcpdump udp port 1813" if there is any accounting traffic reaching your box.
Greetings,
Stefan Winter
*CISCO SETUP*
As I mentioned earlier, my freeradius *client* in this setup is my Cisco AS5400. When I have radius debugging turned on, on my cisco, here is some debugging output from a call. As you can see, it says that the server is not online. When I make calls, I see no activity in my freeradius debug window. So it seems that the packets aren't getting to freeradius from my cisco.
*Jan 2 08:47:02.895: AAA/BIND(00000190): Bind i/f Serial7/0:15:23 *Jan 2 08:47:02.899: AAA/BIND(00000191): Bind i/f *Jan 2 08:47:02.903: RADIUS/ENCODE(00000191):Orig. component type = VOICE *Jan 2 08:47:02.903: RADIUS(00000191): Config NAS IP: 0.0.0.0 *Jan 2 08:47:02.903: RADIUS(00000191): sending *Jan 2 08:47:02.903: RADIUS/ENCODE: Best Local IP-Address 10.0.2.1 for Radius-Server xx.xx.xx.xx
*Jan 2 08:47:02.907: RADIUS(00000191): Send Accounting-Request to xx.xx.xx.xx:1813 id 1646/154, len 128
*Jan 2 08:47:02.907: RADIUS: authenticator 5A 66 34 6D 47 00 B7 9E - BD 76 22 42 14 B6 A1 59
*Jan 2 08:47:02.907: RADIUS: Acct-Session-Id [44] 18 "0200000000000253" *Jan 2 08:47:02.907: RADIUS: Calling-Station-Id [31] 12 "8182179228" *Jan 2 08:47:02.907: RADIUS: Called-Station-Id [30] 12 "2172386245" *Jan 2 08:47:02.907: RADIUS: User-Name [1] 12 "8182179228" *Jan 2 08:47:02.907: RADIUS: Acct-Status-Type [40] 6 Start [1] *Jan 2 08:47:02.907: RADIUS: NAS-Port-Type [61] 6 Async [0] *Jan 2 08:47:02.907: RADIUS: NAS-Port [5] 6 0
*Jan 2 08:47:02.907: RADIUS: NAS-Port-Id [87] 18 "ISDN 7/7:15:D:24" *Jan 2 08:47:02.907: RADIUS: Service-Type [6] 6 Login [1] *Jan 2 08:47:02.907: RADIUS: NAS-IP-Address [4] 6 10.0.2.1
*Jan 2 08:47:02.907: RADIUS: Acct-Delay-Time [41] 6 0
*Jan 2 08:47:07.655: RADIUS: acct-timeout for 4012ECE4 now 5, acct-jitter 4294967295, acct-delay-time (at 4012ED5E) now 4
*Jan 2 08:47:07.655: RADIUS: no sg in radius-timers: ctx 0x66F7FB78 sg 0x0000 *Jan 2 08:47:07.655: RADIUS: Retransmit to (xx.xx.xx.xx:1812,1813) for id 1646/155 *Jan 2 08:47:12.687: RADIUS: acct-timeout for 4012ECE4 now 9, acct-jitter 0, acct-delay-time (at 4012ED5E) now 9
*Jan 2 08:47:12.687: RADIUS: no sg in radius-timers: ctx 0x66F7FB78 sg 0x0000 *Jan 2 08:47:12.687: RADIUS: Retransmit to (xx.xx.xx.xx:1812,1813) for id 1646/156 *Jan 2 08:47:14.947: RADIUS/ENCODE(00000191):Orig. component type = VOICE *Jan 2 08:47:14.947: RADIUS(00000191): Config NAS IP: 0.0.0.0
*Jan 2 08:47:14.947: RADIUS(00000191): sending
*Jan 2 08:47:14.951: RADIUS/ENCODE: Best Local IP-Address xx.xx.xx.xx for Radius-Server xx.xx.xx.xx
*Jan 2 08:47:14.951: RADIUS(00000191): Send Accounting-Request to xx.xx.xx.xx:1813 id 1646/157, len 158
*Jan 2 08:47:14.951: RADIUS: authenticator 6F 5D 1E 4E CC 63 E0 A1 - 64 3B 75 46 FF 42 65 55
*Jan 2 08:47:14.951: RADIUS: Acct-Session-Id [44] 18 "0200000000000253" *Jan 2 08:47:14.951: RADIUS: Calling-Station-Id [31] 12 "8182179228" *Jan 2 08:47:14.951: RADIUS: Called-Station-Id [30] 12 "2172386245" *Jan 2 08:47:14.951: RADIUS: Acct-Input-Octets [42] 6 94880
*Jan 2 08:47:14.951: RADIUS: Acct-Output-Octets [43] 6 95520
*Jan 2 08:47:14.951: RADIUS: Acct-Input-Packets [47] 6 593
*Jan 2 08:47:14.951: RADIUS: Acct-Output-Packets [48] 6 597
*Jan 2 08:47:14.951: RADIUS: Acct-Session-Time [46] 6 12
*Jan 2 08:47:14.951: RADIUS: User-Name [1] 12 "8182179228" *Jan 2 08:47:14.951: RADIUS: Acct-Status-Type [40] 6 Stop [2] *Jan 2 08:47:14.951: RADIUS: NAS-Port-Type [61] 6 Async [0] *Jan 2 08:47:14.951: RADIUS: NAS-Port [5] 6 0 *Jan 2 08:47:14.951: RADIUS: NAS-Port-Id [87] 18 "ISDN 7/7:15:D:24" *Jan 2 08:47:14.951: RADIUS: Service-Type [6] 6 Login [1] *Jan 2 08:47:14.951: RADIUS: NAS-IP-Address [4] 6 10.0.2.1 *Jan 2 08:47:14.951: RADIUS: Acct-Delay-Time [41] 6 0 *Jan 2 08:47:17.559: RADIUS: acct-timeout for 4012ECE4 now 14, acct-jitter 0, acct-delay-time (at 4012ED5E) now 14 *Jan 2 08:47:17.559: RADIUS: no sg in radius-timers: ctx 0x66F7FB78 sg 0x0000 *Jan 2 08:47:17.559: RADIUS: Retransmit to (xx.xx.xx.xx:1812,1813) for id 1646/158 *Jan 2 08:47:19.871: RADIUS: acct-timeout for 4013486C now 5, acct-jitter 4294967295, acct-delay-time (at 40134904) now 4 *Jan 2 08:47:19.871: RADIUS: no sg in radius-timers: ctx 0x67045494 sg 0x0000 *Jan 2 08:47:19.871: %RADIUS-4-RADIUS_DEAD: RADIUS server xx.xx.xx.xx:1812,1813 is not responding. *Jan 2 08:47:19.871: %RADIUS-4-RADIUS_ALIVE: RADIUS server xx.xx.xx.xx:1812,1813 has returned. *Jan 2 08:47:19.871: RADIUS: Retransmit to (xx.xx.xx.xx:1812,1813) for id 1646/159 *Jan 2 08:47:22.527: RADIUS: acct-timeout for 4012ECE4 now 19, acct-jitter 0, acct-delay-time (at 4012ED5E) now 19 *Jan 2 08:47:22.527: RADIUS: no sg in radius-timers: ctx 0x66F7FB78 sg 0x0000 *Jan 2 08:47:22.527: RADIUS: No response from (xx.xx.xx.xx:1812,1813) for id 1646/158 *Jan 2 08:47:22.527: RADIUS/DECODE: No response from radius-server; parse response; FAIL *Jan 2 08:47:22.527: RADIUS/DECODE: Case error(no response/ bad packet/ op decode);parse response; FAIL *Jan 2 08:47:24.903: RADIUS: acct-timeout for 4013486C now 9, acct-jitter 0, acct-delay-time (at 40134904) now 9 *Jan 2 08:47:24.903: RADIUS: no sg in radius-timers: ctx 0x67045494 sg 0x0000 *Jan 2 08:47:24.903: RADIUS: Retransmit to (173.203.117.112:1812 <http://173.203.117.112:1812>,1813) for id 1646/161 *Jan 2 08:47:29.415: RADIUS: acct-timeout for 4013486C now 14, acct-jitter 0, acct-delay-time (at 40134904) now 14 *Jan 2 08:47:29.415: RADIUS: no sg in radius-timers: ctx 0x67045494 sg 0x0000 *Jan 2 08:47:29.415: RADIUS: Retransmit to (xx.xx.xx.xx:1812,1813) for id 1646/162 *Jan 2 08:47:34.415: RADIUS: acct-timeout for 4013486C now 19, acct-jitter 0, acct-delay-time (at 40134904) now 19 *Jan 2 08:47:34.415: RADIUS: no sg in radius-timers: ctx 0x67045494 sg 0x0000 *Jan 2 08:47:34.415: RADIUS: No response from (xx.xx.xx.xx:1812,1813) for id 1646/162 *Jan 2 08:47:34.415: RADIUS/DECODE: No response from radius-server; parse response; FAIL *Jan 2 08:47:34.415: RADIUS/DECODE: Case error(no response/ bad packet/ op decode);parse response; FAIL
*HELP!*
OK, so sorry for this terribly long email, but I hope that this has provided enough information for you guys to help me debug what the heck is going wrong here. I've spent tons of hours trying to resolve this to no avail. I'm out of ideas.
Thanks so much for all of your help, this has been a really irritating and frustrating experience. I'm hoping that if anyone else has the same problem, this thread may help them later on.
Thanks!
-Randall
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Stefan WINTER Ingenieur de Recherche Fondation RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche 6, rue Richard Coudenhove-Kalergi L-1359 Luxembourg
Tel: +352 424409 1 Fax: +352 422473
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Randall Degges wrote:
I just confirmed that my server does have no firewall. The way I tested this is: ... When I do this I send some raw packets to my radius server on port 1812 for testing, and my tcpdump output shows each packet being received just fine. So I don't think this is a firewall issue.
BTW, tcpdump can sometimes bypass the FW by listening on the "raw" interface.
Can anyone check out my configs and see if something in there may be causing this issue?
If the server says it's listening on a port, it's listening on a port. If it says it's not receiving packets, it's not receiving packets. Something in between the network && FreeRADIUS is stopping the packets. Find out what, and fix it. But it isn't a FreeRADIUS issue. Alan DeKok.
I just confirmed that my server does have no firewall. The way I tested this is: ON THE SERVER tcpdump udp port 1812 ON THE CLIENT nc -u xx.xx.xx.xx 1812 <mash the keyboard repeatedly to send fake packets> When I do this I send some raw packets to my radius server on port 1812 for testing, and my tcpdump output shows each packet being received just fine. So I don't think this is a firewall issue. Run radtest on the server to verify that the server actually works - radtest bob badpassword localhost 1 <shared secret>. Then run radtest from another client that is on the same network that the AS5400 is on. My guess is that there is a firewall in front of your Linux server running FreeRADIUS. Rackspace typically puts a Cisco ASA firewall in front of a customer's Linux server. When you ran the nc test, was the system that you ran nc from on the same network with the Linux server running FreeRADIUS? They both might have been behind the same firewall. Check with Rackspace to see if there is a Cisco Firewall in front of your Linux server. Tim
Just wanted to thank everyone for their help. I've gotten the issue resolved. Apparently Freeradius was working 100%, what wasn't working, however, was my Cisco routing. We had our network worked on several weeks back, and all seemed to be working ok, but it never dawned on me to check if my Cisco AS5400 could ping out to the freeradius server or not (it couldn't). So after talking with our Cisco guy and straightening the issue out, all works well. Thanks so much for your help! -Randall On Mon, Mar 29, 2010 at 7:54 PM, Tim Sylvester < tim.sylvester@networkradius.com> wrote:
I just confirmed that my server does have no firewall. The way I tested this is:
*ON THE SERVER*
tcpdump udp port 1812
*ON THE CLIENT*
nc -u xx.xx.xx.xx 1812
<mash the keyboard repeatedly to send fake packets>
When I do this I send some raw packets to my radius server on port 1812 for testing, and my tcpdump output shows each packet being received just fine. So I don't think this is a firewall issue.
Run radtest on the server to verify that the server actually works – radtest bob badpassword localhost 1 <shared secret>. Then run radtest from another client that is on the same network that the AS5400 is on.
My guess is that there is a firewall in front of your Linux server running FreeRADIUS. Rackspace typically puts a Cisco ASA firewall in front of a customer’s Linux server. When you ran the nc test, was the system that you ran nc from on the same network with the Linux server running FreeRADIUS? They both might have been behind the same firewall. Check with Rackspace to see if there is a Cisco Firewall in front of your Linux server.
Tim
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
participants (5)
-
Alan DeKok -
Fajar A. Nugraha -
Randall Degges -
Stefan Winter -
Tim Sylvester