Good afternoon.
We have to use the equipment ASR-1004 (boot system bootflash:asr1000rp1-adventerprisek9.03.16.00.S.155-3.S-ext.bin).
Use ip unnumbered, QinQ. Integration ISG billing system UTM5 from Netup.
It has been observed that NAS-server closing session of authorized subscribers with positive balance.
It can be seen from dhcp.log file in block №3.
==================== 1 BLOCK ====================
Sep 18 19:53:31 Info : 725f3700 packet log: DISCOVER from a8:f9:4b:23:dd:8e relay-agent-info 0106000407e6001602080006001e58a90a66 dhc
p-class-identifier 'Eltex-NV102-fs_nv102_160602_0.1.10'
Sep 18 19:53:32 ?Debug : 725f3700 LeaseManager: static_offer: IP 46.43.x.x for MAC a8:f9:4b:23:dd:8e; switch #602; port #22; VLAN #2
022
Sep 18 19:53:32 ?Debug : 725f3700 DHCP_Server: sending OFFER of 46.43.x.x to a8:f9:4b:23:dd:8e
chaddr: a8:f9:4b:23:dd:8e
Sep 18 19:53:32 Info : 725f3700 packet log: OFFER to a8:f9:4b:23:dd:8e offered IP 46.43.x.x
chaddr: a8:f9:4b:23:dd:8e
Sep 18 19:53:58 ?Debug : 725f3700 DBConnection_mysql: <0x262ce80> SQL SELECT query: SELECT id,ip,expired,updated,client_id,binding_id,f
lags FROM dhcp_leases WHERE mac='a8:f9:4b:23:dd:8e' ORDER BY id
Sep 18 19:53:58 Info : 725f3700 packet log: REQUEST from a8:f9:4b:23:dd:8e requested IP 46.43.x.x state SELECTING relay-agent-info
0106000407e6001602080006001e58a90a66 dhcp-class-identifier 'Eltex-NV102-fs_nv102_160602_0.1.10'
Sep 18 19:53:58 ?Debug : 725f3700 LeaseManager: static_offer: IP 46.43.x.x for MAC a8:f9:4b:23:dd:8e; switch #602; port #22; VLAN #2
022
Sep 18 19:53:58 ?Debug : 725f3700 DHCP_Server: sending ACK of 46.43.x.x to a8:f9:4b:23:dd:8e
chaddr: a8:f9:4b:23:dd:8e
Sep 18 19:53:58 Info : 725f3700 packet log: ACK to a8:f9:4b:23:dd:8e client IP 46.43.x.x
=========================================================
DISCOVER --->OFFER--->REQUEST--->ACK = IP 46.43.x.x (it's okay for now)
====2 BLOCK.Accounting-Start (Also, everything is fine) ========
Sep 18 19:53:58 Info : 268d1700 AcctQueue: Accounting-Start for SID 0/0/0/2022.1624_0A00040100005BAE user '46.43.x.x' slink ID 985
13 from NAS 10.0.x.x
(Framed-IP-Address=IP:46.43.x.x)
(User-Name=STRING:46.43.x.x)
================= 3 BLOCK (STOP is not clear?) =============
Sep 18 19:54:00 Info : 268d1700 AcctQueue: Accouting-Stop for SID 0/0/0/2022.1624_0A00040100005BAE user '46.43.x.x' slink ID 98513
========================================================
Inexplicably NAS-server performed after 2 seconds after Accouting-Stop (19:54:00) after Accounting-Start (19:53:58).
And this procedure is repeated in a circle on 1 unto 3 block.
Тhe same situation:
Sep 27 14:28:27 Info : 96a1a700 AcctQueue: Accounting-Start for SID 0/0/0/2002.1624_0A00040100065687 user '46.43.x.x' slink ID 216943 from NAS 10.0.x.x
Sep 27 14:29:32 Info : 96a1a700 AcctQueue: Accouting-Stop for SID 0/0/0/2002.1624_0A00040100065687 user '46.43.x.x' slink ID 216943 from NAS 10.0.x.x
(Cisco:Cisco-Account-Info=STRING:S46.43.x.x)
(Cisco:Cisco-Account-Info=STRING:S46.43.x.x)
Sep 27 14:29:36 Info : 96a1a700 AcctQueue: Accounting-Start for SID 0/0/0/2002.1624_0A000401000656A5 user '46.43.x.x' slink ID 216943 from NAS 10.0.x.x
Sep 27 14:29:50 Info : 96a1a700 AcctQueue: Accouting-Stop for SID 0/0/0/2002.1624_0A000401000656A5 user '46.43.x.x' slink ID 216943 from NAS 10.0.x.x
(Cisco:Cisco-Account-Info=STRING:S46.43.x.x)
(Cisco:Cisco-Account-Info=STRING:S46.43.x.x)
Sep 27 14:29:55 Info : 96a1a700 AcctQueue: Accounting-Start for SID 0/0/0/2002.1624_0A000401000656AA user '46.43.x.x' slink ID 216943 from NAS 10.0.x.x
Sep 27 14:30:16 Info : 96a1a700 AcctQueue: Accouting-Stop for SID 0/0/0/2002.1624_0A000401000656AA user '46.43.x.x' slink ID 216943 from NAS 10.0.x.x
(Cisco:Cisco-Account-Info=STRING:S46.43.x.x)
(Cisco:Cisco-Account-Info=STRING:S46.43.x.x)
Sep 27 14:30:18 Info : 96a1a700 AcctQueue: Accounting-Start for SID 0/0/0/2002.1624_0A000401000656B8 user '46.43.x.x' slink ID 216943 from NAS 10.0.x.x
Sep 27 14:30:34 Info : 96a1a700 AcctQueue: Accouting-Stop for SID 0/0/0/2002.1624_0A000401000656B8 user '46.43.x.x' slink ID 216943 from NAS 10.0.x.x
After an appeal in support Netup, the boys reported the following:
....From the point of view of UTM5 all these requests are valid and do not indicate the presence of a problem.
However, Accouting-Stop for session 0/0/0/2022.1624_0A00040100005BAE, for session 0/0/0/2022.1624_0A0004010000DB52,
there is a standard attribute 49 (Acct-Terminate-Cause), of value 7.
Judging by RFC 2866, this value should be interpreted as follows::
7 Admin Reboot Administrator is ending service on the NAS, for example prior to rebooting
the NAS
For example, for the session 0/0/0/2022.1624_0A0004010000DB52 This listing is as follows:
--- RADIUS Pkt ---
Code: [4] ID: [126]
Auth: Size 16; Data [0x10cff05097707693fb892e8edd5fb787]
Attr: [44] Vendor: [0] Size 32; Data [0x302f302f302f323032322e313632345f30413030303430313030303044423532]
(Acct-Session-Id=STRING:0/0/0/2022.1624_0A0004010000DB52)
Attr: [8] Vendor: [0] Size 4; Data [0x2e2bc328]
(Framed-IP-Address=IP:46.43.x.x)
Attr: [7] Vendor: [0] Size 4; Data [0x00000001]
(Framed-Protocol=INT:1)
Attr: [47] Vendor: [0] Size 4; Data [0x00000000]
(Acct-Input-Packets=INT:0)
Attr: [48] Vendor: [0] Size 4; Data [0x00000000]
(Acct-Output-Packets=INT:0)
Attr: [42] Vendor: [0] Size 4; Data [0x00000000]
(Acct-Input-Octets=INT:0)
Attr: [43] Vendor: [0] Size 4; Data [0x00000000]
(Acct-Output-Octets=INT:0)
Attr: [253] Vendor: [9] Size 4; Data [0x49303b30]
(Cisco:Cisco-Control-Info=STRING:I0;0)
Attr: [253] Vendor: [9] Size 4; Data [0x4f303b30]
(Cisco:Cisco-Control-Info=STRING:O0;0)
Attr: [1] Vendor: [0] Size 12; Data [0x34362e34332e3139352e3430]
(User-Name=STRING:46.43.x.x)
Attr: [45] Vendor: [0] Size 4; Data [0x00000002]
(Acct-Authentic=INT:2)
Attr: [1] Vendor: [9] Size 24; Data [0x636f6e6e6563742d70726f67726573733d43616c6c205570]
(Cisco:Cisco-AVPair=STRING:connect-progress=Call Up)
Attr: [46] Vendor: [0] Size 4; Data [0x00000005]
(Acct-Session-Time=INT:5)
Attr: [49] Vendor: [0] Size 4; Data [0x00000007]
(Acct-Terminate-Cause=INT:7)
Attr: [1] Vendor: [9] Size 29; Data [0x646973632d63617573652d6578743d54532053657373696f6e20456e64]
(Cisco:Cisco-AVPair=STRING:disc-cause-ext=TS Session End)
Attr: [40] Vendor: [0] Size 4; Data [0x00000002]
(Acct-Status-Type=INT:2)
Attr: [31] Vendor: [0] Size 16; Data [0x30303036303031653538613930613636]
(Calling-Station-Id=STRING:0006001e58a90a66)
Attr: [61] Vendor: [0] Size 4; Data [0x00000022]
(NAS-Port-Type=INT:34)
Attr: [2] Vendor: [9] Size 64; Data [0x3030303430376536303031363a303030363030316535386139306136363a456c7465782d4e563130322d66735f6e763130325f3136303630325f302e312e3130]
(Cisco:Cisco-NAS-Port=STRING:000407e60016:0006001e58a90a66:Eltex-NV102-fs_nv102_160602_0.1.10)
Attr: [5] Vendor: [0] Size 4; Data [0x007e6658]
(NAS-Port=INT:8283736)
Attr: [87] Vendor: [0] Size 64; Data [0x3030303430376536303031363a303030363030316535386139306136363a456c7465782d4e563130322d66735f6e763130325f3136303630325f302e312e3130]
(NAS-Port-Id=STRING:000407e60016:0006001e58a90a66:Eltex-NV102-fs_nv102_160602_0.1.10)
Attr: [1] Vendor: [9] Size 54; Data [0x76656e646f722d636c6173732d69642d7461673d456c7465782d4e563130322d66735f6e763130325f3136303630325f302e312e3130]
(Cisco:Cisco-AVPair=STRING:vendor-class-id-tag=Eltex-NV102-fs_nv102_160602_0.1.10)
Attr: [1] Vendor: [9] Size 27; Data [0x636972637569742d69642d7461673d303030343037653630303136]
(Cisco:Cisco-AVPair=STRING:circuit-id-tag=000407e60016)
Attr: [1] Vendor: [9] Size 30; Data [0x72656d6f74652d69642d7461673d30303036303031653538613930613636]
(Cisco:Cisco-AVPair=STRING:remote-id-tag=0006001e58a90a66)
Attr: [6] Vendor: [0] Size 4; Data [0x00000002]
(Service-Type=INT:2)
Attr: [4] Vendor: [0] Size 4; Data [0x0a000402]
(NAS-IP-Address=IP:10.0.x.x)
Attr: [55] Vendor: [0] Size 4; Data [0x57de95c3]
(Event-Timestamp=DATE:1474205123)
Attr: [32] Vendor: [0] Size 16; Data [0x627261732e616368696e736b2e6e6574]
(NAS-Identifier=STRING:xxxxxxxx)
Attr: [41] Vendor: [0] Size 4; Data [0x00000000]
(Acct-Delay-Time=INT:0)
Technical support Netup refers to "Admin Reboot Administrator"
and recommended to apply to the ТАС.
======================================================
From the billing system dhcp.log from block №1 It is seen that everything is fine,
subscribers dismantle ip address, and by the
asr-1004 if you look, you will see:
bras#show subscriber session
Uniq ID Interface State Service Up-time TC Ct. Identifier
4391 DHCPv4 authen Lterm 00:00:00 cc2d.8cd6.4b0e
6067 DHCPv4 authen Lterm 00:00:00 1caf.f762.b891
4203 DHCPv4 authen Lterm 00:00:00 30b5.c2a7.2c97
7983 DHCPv4 authen Lterm 00:00:00 a8f9.4b22.a5ea
5325 DHCPv4 authen Lterm 00:00:00 0026.5ad2.6f51
924 DHCPv4 authen Lterm 00:00:00 84c9.b24a.45dc
3664 DHCPv4 authen Lterm 00:00:00 c8d3.a38c.b2cc
IP addresses for the subscribers do not have.
Does anyone similar situation arose?
If you need additional technical information, can provide the further communication.
Thank you to respect Ragulin Oleg.
