Replicated Acctounting blocks replys
Dalton Porter
daltonporter at yahoo.com
Sat May 3 01:02:06 CEST 2014
Alan, I did run in debugging mode. I didn't notice any error. I'm attaching here in case I have missed something.
Attaching debug.
NAS=10.106.1.45
radius svr 2 = 10.101.248.112
What I see is after the Access Req/Resp, the NAS keeps sending Accounting Reqs.
Looking at tcpdump, I can see the Acct Response packet makes it from svr2 to srv1, but there is an ICMP port not reachable, which
I interpret to mean svr1 is not listening on that port (expected because replicate is fire and forget)
But then why doesn't svr1 respond to the NAS with an Accounting Response?
It fails to do so, so in a few sec, the NAS sends another accounting req.
This cycle repeats a few times - sometimes NAS just won't give up.
rad_recv: Access-Request packet from host 10.106.1.45 port 35711, id=121, length=191
User-Name = "QAQAQA_00"
User-Password = "testing"
NAS-Port = 77824
Service-Type = Framed-User
Framed-Protocol = PPP
Called-Station-Id = "XX.25.104.52"
Calling-Station-Id = "XX.226.96.135"
NAS-Port-Type = Virtual
Tunnel-Client-Endpoint:0 = "XX.226.96.135"
NAS-IP-Address = 10.106.1.45
Cisco-AVPair = "ip:source-ip=96.226.96.135"
Vendor-3076-Attr-146 = 0x4d6f62696c65587072657373696f6e
Vendor-3076-Attr-150 = 0x00000001
# Executing section authorize from file /etc/raddb/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
[suffix] No '@' in User-Name = "QAQAQA_00", looking up realm NULL
[suffix] Found realm "NULL"
[suffix] Adding Stripped-User-Name = "QAQAQA_00"
[suffix] Adding Realm = "NULL"
[suffix] Authentication realm is LOCAL.
++[suffix] returns ok
++[unix] returns notfound
[files] users: Matched entry DEFAULT at line 172
++[files] returns ok
[sql] expand: %{User-Name} -> QAQAQA_00
[sql] sql_set_user escaped user --> 'QAQAQA_00'
rlm_sql (sql): Reserving sql socket id: 19
[sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'QAQAQA_00' ORDER BY id
[sql] User found in radcheck table
[sql] expand: <snip>
[sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'QAQAQA_00' ORDER BY priority
rlm_sql (sql): Released sql socket id: 19
++[sql] returns ok
++[expiration] returns noop
++[logintime] returns noop
++[pap] returns updated
Found Auth-Type = PAP
# Executing group from file /etc/raddb/sites-enabled/default
+- entering group PAP {...}
[pap] login attempt with password "testing"
[pap] Using clear text password "testing"
[pap] User authenticated successfully
++[pap] returns ok
# Executing section post-auth from file /etc/raddb/sites-enabled/default
+- entering group post-auth {...}
++[exec] returns noop
Sending Access-Accept of id 121 to 10.106.1.45 port 35711
Framed-Protocol = PPP
Framed-Compression = Van-Jacobson-TCP-IP
Framed-IP-Address := 172.24.0.1
Finished request 0.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Accounting-Request packet from host 10.106.1.45 port 57645, id=122, length=185
User-Name = "QAQAQA_00"
NAS-Port = 77824
Service-Type = Framed-User
Framed-Protocol = PPP
Framed-IP-Address = 172.24.0.1
Called-Station-Id = "XX.25.104.52"
Calling-Station-Id = "XX.226.96.135"
Acct-Status-Type = Start
Acct-Delay-Time = 0
Acct-Session-Id = "7B600012"
Acct-Authentic = RADIUS
NAS-Port-Type = Virtual
Tunnel-Client-Endpoint:0 = "XX.226.96.135"
Vendor-3076-Attr-146 = 0x4d6f62696c65587072657373696f6e
Vendor-3076-Attr-150 = 0x00000001
Vendor-3076-Attr-151 = 0x00000005
NAS-IP-Address = 10.106.1.45
# Executing section preacct from file /etc/raddb/sites-enabled/default
+- entering group preacct {...}
++[preprocess] returns ok
++[control] returns ok
[acct_unique] Hashing 'NAS-Port = 77824,Client-IP-Address = 10.106.1.45,NAS-IP-Address = 10.106.1.45,Acct-Session-Id = "7B600012",User-Name = "QAQAQA_00"'
[acct_unique] Acct-Unique-Session-ID = "252b24a78b654e27".
++[acct_unique] returns ok
[suffix] No '@' in User-Name = "QAQAQA_00", looking up realm NULL
[suffix] Found realm "NULL"
[suffix] Adding Stripped-User-Name = "QAQAQA_00"
[suffix] Adding Realm = "NULL"
[suffix] Proxying request from user QAQAQA_00 to realm NULL
[suffix] Preparing to proxy accounting request to realm "NULL"
++[suffix] returns updated
++[files] returns noop
# Executing section accounting from file /etc/raddb/sites-enabled/default
+- entering group accounting {...}
[sql] expand: %{User-Name} -> QAQAQA_00
[sql] sql_set_user escaped user --> 'QAQAQA_00'
[sql] expand: %{Acct-Delay-Time} -> 0
[sql] expand: INSERT INTO radacct... <snip>
rlm_sql (sql): Reserving sql socket id: 18
rlm_sql (sql): Released sql socket id: 18
++[sql] returns ok
[replicate] Replicating packet to Realm NULL
Sending Accounting-Request of id 114 to 10.101.248.112 port 1813
User-Name = "QAQAQA_00"
NAS-Port = 77824
Service-Type = Framed-User
Framed-Protocol = PPP
Framed-IP-Address = 172.24.0.1
Called-Station-Id = "XX.25.104.52"
Calling-Station-Id = "XX.226.96.135"
Acct-Status-Type = Start
Acct-Delay-Time = 0
Acct-Session-Id = "7B600012"
Acct-Authentic = RADIUS
NAS-Port-Type = Virtual
Tunnel-Client-Endpoint:0 = "XX.226.96.135"
Vendor-3076-Attr-146 = 0x4d6f62696c65587072657373696f6e
Vendor-3076-Attr-150 = 0x00000001
Vendor-3076-Attr-151 = 0x00000005
NAS-IP-Address = 10.106.1.45
++[replicate] returns ok
Finished request 1.
Cleaning up request 1 ID 122 with timestamp +18
Going to the next request
Waking up in 3.7 seconds.
Cleaning up request 0 ID 121 with timestamp +17
Ready to process requests.
rad_recv: Accounting-Request packet from host 10.106.1.45 port 57645, id=123, length=185
User-Name = "QAQAQA_00"
NAS-Port = 77824
Service-Type = Framed-User
Framed-Protocol = PPP
Framed-IP-Address = 172.24.0.1
Called-Station-Id = "XX.25.104.52"
Calling-Station-Id = "XX.226.96.135"
Acct-Status-Type = Start
Acct-Delay-Time = 5
Acct-Session-Id = "7B600012"
Acct-Authentic = RADIUS
NAS-Port-Type = Virtual
Tunnel-Client-Endpoint:0 = "XX.226.96.135"
Vendor-3076-Attr-146 = 0x4d6f62696c65587072657373696f6e
Vendor-3076-Attr-150 = 0x00000001
Vendor-3076-Attr-151 = 0x00000005
NAS-IP-Address = 10.106.1.45
# Executing section preacct from file /etc/raddb/sites-enabled/default
+- entering group preacct {...}
++[preprocess] returns ok
++[control] returns ok
[acct_unique] Hashing 'NAS-Port = 77824,Client-IP-Address = 10.106.1.45,NAS-IP-Address = 10.106.1.45,Acct-Session-Id = "7B600012",User-Name = "QAQAQA_00"'
[acct_unique] Acct-Unique-Session-ID = "252b24a78b654e27".
++[acct_unique] returns ok
[suffix] No '@' in User-Name = "QAQAQA_00", looking up realm NULL
[suffix] Found realm "NULL"
[suffix] Adding Stripped-User-Name = "QAQAQA_00"
[suffix] Adding Realm = "NULL"
[suffix] Proxying request from user QAQAQA_00 to realm NULL
[suffix] Preparing to proxy accounting request to realm "NULL"
++[suffix] returns updated
++[files] returns noop
# Executing section accounting from file /etc/raddb/sites-enabled/default
+- entering group accounting {...}
[sql] expand: %{User-Name} -> QAQAQA_00
[sql] sql_set_user escaped user --> 'QAQAQA_00'
[sql] expand: %{Acct-Delay-Time} -> 5
[sql] expand: INSERT INTO radacct ...<snip>
rlm_sql (sql): Reserving sql socket id: 17
rlm_sql (sql): Released sql socket id: 17
++[sql] returns ok
[replicate] Replicating packet to Realm NULL
Sending Accounting-Request of id 118 to 10.101.248.112 port 1813
User-Name = "QAQAQA_00"
NAS-Port = 77824
Service-Type = Framed-User
Framed-Protocol = PPP
Framed-IP-Address = 172.24.0.1
Called-Station-Id = "XX.25.104.52"
Calling-Station-Id = "XX.226.96.135"
Acct-Status-Type = Start
Acct-Delay-Time = 5
Acct-Session-Id = "7B600012"
Acct-Authentic = RADIUS
NAS-Port-Type = Virtual
Tunnel-Client-Endpoint:0 = "XX.226.96.135"
Vendor-3076-Attr-146 = 0x4d6f62696c65587072657373696f6e
Vendor-3076-Attr-150 = 0x00000001
Vendor-3076-Attr-151 = 0x00000005
NAS-IP-Address = 10.106.1.45
++[replicate] returns ok
Finished request 2.
Cleaning up request 2 ID 123 with timestamp +23
Going to the next request
Ready to process requests.
rad_recv: Accounting-Request packet from host 10.106.1.45 port 57645, id=124, length=185
User-Name = "QAQAQA_00"
NAS-Port = 77824
Service-Type = Framed-User
Framed-Protocol = PPP
Framed-IP-Address = 172.24.0.1
Called-Station-Id = "XX.25.104.52"
Calling-Station-Id = "XX.226.96.135"
Acct-Status-Type = Start
Acct-Delay-Time = 10
Acct-Session-Id = "7B600012"
Acct-Authentic = RADIUS
NAS-Port-Type = Virtual
Tunnel-Client-Endpoint:0 = "XX.226.96.135"
Vendor-3076-Attr-146 = 0x4d6f62696c65587072657373696f6e
Vendor-3076-Attr-150 = 0x00000001
Vendor-3076-Attr-151 = 0x00000005
NAS-IP-Address = 10.106.1.45
# Executing section preacct from file /etc/raddb/sites-enabled/default
+- entering group preacct {...}
++[preprocess] returns ok
++[control] returns ok
[acct_unique] Hashing 'NAS-Port = 77824,Client-IP-Address = 10.106.1.45,NAS-IP-Address = 10.106.1.45,Acct-Session-Id = "7B600012",User-Name = "QAQAQA_00"'
[acct_unique] Acct-Unique-Session-ID = "252b24a78b654e27".
++[acct_unique] returns ok
[suffix] No '@' in User-Name = "QAQAQA_00", looking up realm NULL
[suffix] Found realm "NULL"
[suffix] Adding Stripped-User-Name = "QAQAQA_00"
[suffix] Adding Realm = "NULL"
[suffix] Proxying request from user QAQAQA_00 to realm NULL
[suffix] Preparing to proxy accounting request to realm "NULL"
++[suffix] returns updated
++[files] returns noop
# Executing section accounting from file /etc/raddb/sites-enabled/default
+- entering group accounting {...}
[sql] expand: %{User-Name} -> QAQAQA_00
[sql] sql_set_user escaped user --> 'QAQAQA_00'
[sql] expand: %{Acct-Delay-Time} -> 10
[sql] expand: INSERT INTO radacct ...<snip>
rlm_sql (sql): Reserving sql socket id: 16
rlm_sql (sql): Released sql socket id: 16
++[sql] returns ok
[replicate] Replicating packet to Realm NULL
Sending Accounting-Request of id 122 to 10.101.248.112 port 1813
User-Name = "QAQAQA_00"
NAS-Port = 77824
Service-Type = Framed-User
Framed-Protocol = PPP
Framed-IP-Address = 172.24.0.1
Called-Station-Id = "XX.25.104.52"
Calling-Station-Id = "XX.226.96.135"
Acct-Status-Type = Start
Acct-Delay-Time = 10
Acct-Session-Id = "7B600012"
Acct-Authentic = RADIUS
NAS-Port-Type = Virtual
Tunnel-Client-Endpoint:0 = "XX.226.96.135"
Vendor-3076-Attr-146 = 0x4d6f62696c65587072657373696f6e
Vendor-3076-Attr-150 = 0x00000001
Vendor-3076-Attr-151 = 0x00000005
NAS-IP-Address = 10.106.1.45
++[replicate] returns ok
Finished request 3.
Cleaning up request 3 ID 124 with timestamp +28
Going to the next request
Ready to process requests.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20140502/e8c11ed4/attachment-0001.html>
More information about the Freeradius-Users
mailing list