Examining some recent RADIUS accounting records, it would appear
that the RADIUS accounting packets occasionally do not report
Connect-Info status. In a quick check on a recently installed pop,
there were 168 Start or Stop records with "NAS-Port-Type=Async". Only
123 of those contained "Connect-Info" status. In fact, only 109
contained "Calling-Station-Id" status.
I had been collecting the debug output from "set debug isdn on" and
"set debug mdp-max on" and have correlated the results (somewhat
difficult with the relative pm timestamps) in the appended data.
Since I didn't see any pattern, I thought I'd offer the results to see
if any others could spot an obvious correlation.
Events #1,2,4,5,& 6 were missing the "Connect-Info" status. Event
#3 appears to indicate a retrain/renegotiation activity. Event #7 & 8
include "Connect-Info". Event #7 did not include "Calling-Station-Id".
It looks like a bug to me.
I did a spot check on a much more active pm3 with ComOS 3.7, (2)
PRI, DMS-100 and (5) original Livingston modem cards. It also dropped
both of the forementioned status items from the RADIUS accounting
data.
###################### Event 1 ######################
[001:00:40:46:60] M0: mdp_allocate service 90
[001:00:40:46:60] S1: Modem M0 bound
[001:00:40:46:60] S1: Sending Request Connect - 64Kbps / Voice (B2 ID:ee)
[001:00:40:46:65] S1: Received Connect - B2
[001:00:40:46:65] S1: Modem M0 connecting
[001:00:40:46:65] M0: mdp_bind: (S1) dsl_id 0 ch_n 2 slot 2
[001:00:40:46:65] M0: mdp2_activate: S1 ANSWER
[001:00:41:00:45] M0: mdp2_psm: RX 28800 TX 28800 ret 0 ren 0 dloss 0 rob 0
Sat Aug 16 14:26:37 1997
Acct-Session-Id = "160000B8"
User-Name = "user1"
Client-Id = 206.104.196.66
Client-Port-Id = 1
NAS-Port-Type = Async
Acct-Status-Type = Start
Acct-Authentic = RADIUS
Called-Station-Id = "3651123"
Calling-Station-Id = "3523942878"
User-Service-Type = Framed-User
Framed-Protocol = PPP
Framed-Address = 208.6.218.40
Acct-Delay-Time = 0
###################### Event 2 ######################
[001:00:41:15:60] M3: mdp_allocate service 90
[001:00:41:15:60] S3: Modem M3 bound
[001:00:41:15:60] S3: Sending Request Connect - 64Kbps / Voice (B4 ID:ef)
[001:00:41:15:60] S3: Received Connect - B4
[001:00:41:15:60] S3: Modem M3 connecting
[001:00:41:15:60] M3: mdp_bind: (S3) dsl_id 0 ch_n 4 slot 5
[001:00:41:15:60] M3: mdp2_activate: S3 ANSWER
[001:00:41:29:40] M3: mdp2_psm: RX 28800 TX 28800 ret 0 ren 0 dloss 0 rob 0
Sat Aug 16 14:27:09 1997
Acct-Session-Id = "160000B9"
User-Name = "user2"
Client-Id = 206.104.196.66
Client-Port-Id = 3
NAS-Port-Type = Async
Acct-Status-Type = Start
Acct-Authentic = RADIUS
Called-Station-Id = "3651123"
Calling-Station-Id = "3523948595"
User-Service-Type = Framed-User
Framed-Protocol = PPP
Framed-Address = 208.6.218.1
Acct-Delay-Time = 0
###################### Event 3 ######################
[001:00:52:10:00] M1: mdp2_psm: RX 31200 TX 31200 ret 0 ren 0 dloss 0 rob 0
[001:00:52:11:60] M1: mdp2_psm: RX 31200 TX 31200 ret 1 ren 0 dloss 0 rob 0
[001:00:52:48:25] M1: mdp2_psm: RX 31200 TX 28800 ret 1 ren 0 dloss 0 rob 0
[001:00:52:52:10] M1: mdp2_psm: RX 31200 TX 28800 ret 1 ren 1 dloss 0 rob 0
**** Retrain/renegotiate? ****
###################### Event 4 ######################
[001:00:53:28:20] M3: mdp_deactivate: from S3
[001:00:53:28:20] M3: mdp_deactivate: port(S3) released
[001:00:53:28:20] M3: mdp2_psm: INIT dp 4f08 in_mbx 4f14 out_mbx 4f56
[001:00:53:28:20] S3: Sending Disconnect Request
[001:00:53:28:35] S3: Received Clear Conf (B4 ID:ef)
[001:00:53:34:30] M3: mdp2_psm: DLOAD
[001:00:53:35:60] M3: mdp2_dload: EOF index ffc0 size 20000 MDP_STATE_OMC
[001:00:53:37:65] M3: mdp2_psm: READY
Sat Aug 16 14:39:00 1997
Acct-Session-Id = "160000B9"
User-Name = "user2"
Client-Id = 206.104.196.66
Client-Port-Id = 3
NAS-Port-Type = Async
Acct-Status-Type = Stop
Acct-Session-Time = 712
Acct-Authentic = RADIUS
Acct-Input-Octets = 31420
Acct-Output-Octets = 185016
Called-Station-Id = "3651123"
Calling-Station-Id = "3523948595"
Acct-Terminate-Cause = User-Request
User-Service-Type = Framed-User
Framed-Protocol = PPP
Framed-Address = 208.6.218.1
Acct-Delay-Time = 0
###################### Event 5 ######################
[001:00:54:33:85] M1: mdp2_psm: RX 31200 TX 26400 ret 1 ren 1 dloss 0 rob 0
[001:00:54:33:85] M1: mdp2_psm: RX 31200 TX 26400 ret 1 ren 1 dloss 0 rob 0
[001:00:54:36:85] M1: mdp2_psm: RX 31200 TX 26400 ret 1 ren 2 dloss 0 rob 0
[001:00:57:13:25] M1: mdp_deactivate: from S0
[001:00:57:13:25] M1: mdp_deactivate: port(S0) released
[001:00:57:13:25] M1: mdp2_psm: INIT dp 4a64 in_mbx 4a70 out_mbx 4ab2
[001:00:57:13:25] S0: Sending Disconnect Request
[001:00:57:13:40] S0: Received Clear Conf (B1 ID:ed)
[001:00:57:19:35] M1: mdp2_psm: DLOAD
[001:00:57:20:65] M1: mdp2_dload: EOF index ffc0 size 20000 MDP_STATE_OMC
[001:00:57:22:65] M1: mdp2_psm: READY
Sat Aug 16 14:42:46 1997
Acct-Session-Id = "160000B7"
User-Name = "user3"
Client-Id = 206.104.196.66
Client-Port-Id = 0
NAS-Port-Type = Async
Acct-Status-Type = Stop
Acct-Session-Time = 1157
Acct-Authentic = RADIUS
Acct-Input-Octets = 97741
Acct-Output-Octets = 775727
Called-Station-Id = "3651123"
Calling-Station-Id = "3523948948"
Acct-Terminate-Cause = User-Request
User-Service-Type = Framed-User
Framed-Protocol = PPP
Framed-Address = 208.6.218.42
Acct-Delay-Time = 0
###################### Event 6 ######################
[001:01:03:24:05] M1: mdp_allocate service 90
[001:01:03:24:05] S0: Modem M1 bound
[001:01:03:24:05] S0: Sending Request Connect - 64Kbps / Voice (B1 ID:f0)
[001:01:03:24:05] S0: Received Connect - B1
[001:01:03:24:05] S0: Modem M1 connecting
[001:01:03:24:05] M1: mdp_bind: (S0) dsl_id 0 ch_n 1 slot 1
[001:01:03:24:05] M1: mdp2_activate: S0 ANSWER
[001:01:03:38:65] M1: mdp2_psm: RX 33600 TX 33600 ret 0 ren 0 dloss 0 rob 0
Sat Aug 16 14:49:16 1997
Acct-Session-Id = "160000BA"
User-Name = "user4"
Client-Id = 206.104.196.66
Client-Port-Id = 0
NAS-Port-Type = Async
Acct-Status-Type = Start
Acct-Authentic = RADIUS
Called-Station-Id = "3651123"
Calling-Station-Id = "3527427432"
User-Service-Type = Framed-User
Framed-Protocol = PPP
Framed-Address = 208.6.218.38
Acct-Delay-Time = 0
###################### Event 7 ######################
[001:01:03:60:00] M3: mdp_allocate service 90
[001:01:03:60:00] S3: Modem M3 bound
[001:01:03:60:00] S3: Sending Request Connect - 64Kbps / Voice (B4 ID:f1)
[001:01:03:60:05] S3: Received Connect - B4
[001:01:03:60:05] S3: Modem M3 connecting
[001:01:03:60:05] M3: mdp_bind: (S3) dsl_id 0 ch_n 4 slot 5
[001:01:03:60:05] M3: mdp2_activate: S3 ANSWER
[001:01:04:14:10] M3: mdp2_psm: RX 24000 TX 26400 ret 0 ren 0 dloss 0 rob 0
Sat Aug 16 14:49:52 1997
Acct-Session-Id = "160000BB"
User-Name = "user5"
Client-Id = 206.104.196.66
Client-Port-Id = 3
NAS-Port-Type = Async
Acct-Status-Type = Start
Acct-Authentic = RADIUS
Connect-Info = "26400 LAPM/V42BIS"
Called-Station-Id = "3651123"
User-Service-Type = Framed-User
Framed-Protocol = PPP
Framed-Address = 208.6.218.12
Acct-Delay-Time = 0
###################### Event 8 ######################
[001:01:11:42:10] M5: mdp_allocate service 90
[001:01:11:42:10] S4: Modem M5 bound
[001:01:11:42:10] S4: Sending Request Connect - 64Kbps / Voice (B5 ID:f2)
[001:01:11:42:15] S4: Received Connect - B5
[001:01:11:42:15] S4: Modem M5 connecting
[001:01:11:42:15] M5: mdp_bind: (S4) dsl_id 0 ch_n 5 slot 6
[001:01:11:42:15] M5: mdp2_activate: S4 ANSWER
[001:01:11:55:75] M5: mdp2_psm: RX 33600 TX 33600 ret 0 ren 0 dloss 0 rob 0
Sat Aug 16 14:57:33 1997
Acct-Session-Id = "160000BC"
User-Name = "user3"
Client-Id = 206.104.196.66
Client-Port-Id = 4
NAS-Port-Type = Async
Acct-Status-Type = Start
Acct-Authentic = RADIUS
Connect-Info = "33600 LAPM/V42BIS"
Called-Station-Id = "3651123"
Calling-Station-Id = "3523948948"
User-Service-Type = Framed-User
Framed-Protocol = PPP
Framed-Address = 208.6.218.4
Acct-Delay-Time = 0