[Home]

Summary:ASTERISK-13547: cdr_radius duplicate accounting packets.
Reporter:rmartinez (rmartinez)Labels:
Date Opened:2009-02-09 14:29:40.000-0600Date Closed:2009-02-24 12:05:48.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:CDR/cdr_radius
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:Hello.
I've been experimenting some weird behavior with my asterisk box.  First let me clarify that i'm not absolutely sure if this is a problem related with the cdr_module or maybe the radiusclient. module  Hope you understand and would help me to track dow this issue.
I'm using the SVN-sruffell-asterisk-1.4-transcoder-r168696 version, because Digium was helping me with a TC400B issue.  Anyway the problem was happening even with the BRANCH version 1.4.
I'm also using raduisclient-ng-0.5.6 and I have a radius server with RADIATOR.
I'm sending calls to the asterisk box with sipp, as long as i stay below the 100 simulateous calls i can see the radius accounting packets arriving to my server without any problem, in the asterisk console i don't see any trouble.  But when i reach the 100 simultaneous calls i start to see three duplicate radius accounting packets in my radius server.  And the console of asterisk shows :

[Feb  2 11:30:11] ERROR[409]: cdr_radius.c:227 radius_log: Failed to record Radius CDR record!
[Feb  2 11:30:12] ERROR[410]: cdr_radius.c:227 radius_log: Failed to record Radius CDR record!
[Feb  2 11:30:13] ERROR[411]: cdr_radius.c:227 radius_log: Failed to record Radius CDR record!
[Feb  2 11:30:14] ERROR[412]: cdr_radius.c:227 radius_log: Failed to record Radius CDR record!


The /var/log/messages file shows :

Feb  2 10:54:28 b2buang01 asterisk[13250]: rc_check_reply: received invalid reply digest from RADIUS server
Feb  2 10:54:29 b2buang01 asterisk[13250]: rc_check_reply: received invalid reply digest from RADIUS server
Feb  2 10:54:30 b2buang01 asterisk[13250]: rc_check_reply: received invalid reply digest from RADIUS server
Feb  2 10:54:31 b2buang01 asterisk[13250]: rc_check_reply: received invalid reply digest from RADIUS server
Feb  2 10:54:32 b2buang01 asterisk[13250]: rc_check_reply: received invalid reply digest from RADIUS server
Feb  2 10:54:33 b2buang01 asterisk[13250]: rc_check_reply: received invalid reply digest from RADIUS server
Feb  2 10:54:34 b2buang01 asterisk[13250]: rc_check_reply: received invalid reply digest from RADIUS server
Feb  2 10:54:35 b2buang01 asterisk[13250]: rc_ip_hostname: couldn't look up host by addr: MY.IP.ADDR.D7
Feb  2 10:54:35 b2buang01 asterisk[13250]: rc_send_server: no reply from RADIUS server unknown:1646
Feb  2 10:54:36 b2buang01 asterisk[13250]: rc_ip_hostname: couldn't look up host by addr: MY.IP.ADDR.D7
Feb  2 10:54:36 b2buang01 asterisk[13250]: rc_send_server: no reply from RADIUS server unknown:1646
Feb  2 10:54:37 b2buang01 asterisk[13250]: rc_ip_hostname: couldn't look up host by addr: MY.IP.ADDR.D7
Feb  2 10:54:37 b2buang01 asterisk[13250]: rc_send_server: no reply from RADIUS server unknown:1646
Feb  2 10:54:38 b2buang01 asterisk[13250]: rc_ip_hostname: couldn't look up host by addr: MY.IP.ADDR.D7
Feb  2 10:54:38 b2buang01 asterisk[13250]: rc_send_server: no reply from RADIUS server unknown:1646
Feb  2 10:54:39 b2buang01 asterisk[13250]: rc_ip_hostname: couldn't look up host by addr: MY.IP.ADDR.D7
Feb  2 10:54:39 b2buang01 asterisk[13250]: rc_send_server: no reply from RADIUS server unknown:1646
Feb  2 10:54:40 b2buang01 asterisk[13250]: rc_ip_hostname: couldn't look up host by addr: MY.IP.ADDR.D7

Finally in my radius server i see the next lines :


Fri Jan 30 23:34:08 1998: DEBUG: Packet dump:
*** Received from 10.10.149.211 port 56844 ....
Code:       Accounting-Request
Identifier: 129
Authentic:  <237>U<254>W<129><156><159>D<153>A$<209><233>`G<9>
Attributes:
       Acct-Status-Type = Stop
       Asterisk-Acc-Code = "TO_PROVIDER"
       Asterisk-Src = "5502222272"
       Asterisk-Dst = "0130005411234618"
       Asterisk-Dst-Ctx = "INC_CALLS"
       Asterisk-Clid = ""sipp" <5502222272>"
       Asterisk-Chan = "SIP/5060-0972ae58"
       Asterisk-Dst-Chan = "SIP/TO_ITSP1-0972f830"
       Asterisk-Last-App = "Dial"
       Asterisk-Last-Data = "SIP/005411234618@TO_ITSP1"
       Asterisk-Start-Time = "2009-01-30 14:51:23 +0000"
       Asterisk-Answer-Time = "2009-01-30 14:51:28 +0000"
       Asterisk-End-Time = "2009-01-30 14:52:50 +0000"
       Asterisk-Duration = 87
       Asterisk-Bill-Sec = 82
       Asterisk-Disposition = "ANSWERED"
       Asterisk-AMA-Flags = "DOCUMENTATION"
       Asterisk-Unique-ID = "1233327083.102"
       Asterisk-User-Field = "B2BUA-PROVIDER-PRUEBAS"
       User-Name = "SIP/5060-0972ae58"
       Acct-Session-Id = "1233327083.102"
       NAS-Port = 0
       Acct-Delay-Time = 0
       NAS-IP-Address = 10.10.149.211

Fri Jan 30 23:34:08 1998: DEBUG: Handling request with Handler 'Request-Type = Accounting-Request'
Fri Jan 30 23:34:08 1998: DEBUG:  Deleting session for SIP/5060-0972ae58, 10.10.149.211, 0
Fri Jan 30 23:34:08 1998: DEBUG: Handling with AuthINTERNAL:
Fri Jan 30 23:34:08 1998: DEBUG: AuthBy INTERNAL result: ACCEPT, Fixed by DefaultResult
Fri Jan 30 23:34:08 1998: DEBUG: Accounting accepted Fri Jan 30 23:34:08 1998: DEBUG: Packet dump:
*** Sending to 10.10.149.211 port 56844 ....
Code:       Accounting-Response
Identifier: 129
Authentic:  <237>U<254>W<129><156><159>D<153>A$<209><233>`G<9>
Attributes:

Fri Jan 30 23:34:08 1998: DEBUG: Packet dump:
*** Received from 10.10.149.211 port 56844 ....
Code:       Accounting-Request
Identifier: 129
Authentic:  <237>U<254>W<129><156><159>D<153>A$<209><233>`G<9>
Attributes:
       Acct-Status-Type = Stop
       Asterisk-Acc-Code = "TO_PROVIDER"
       Asterisk-Src = "5502222272"
       Asterisk-Dst = "0130005411234618"
       Asterisk-Dst-Ctx = "INC_CALLS"
       Asterisk-Clid = ""sipp" <5502222272>"
       Asterisk-Chan = "SIP/5060-0972ae58"
       Asterisk-Dst-Chan = "SIP/TO_ITSP1-0972f830"
       Asterisk-Last-App = "Dial"
       Asterisk-Last-Data = "SIP/005411234618@TO_ITSP1"
       Asterisk-Start-Time = "2009-01-30 14:51:23 +0000"
       Asterisk-Answer-Time = "2009-01-30 14:51:28 +0000"
       Asterisk-End-Time = "2009-01-30 14:52:50 +0000"
       Asterisk-Duration = 87
       Asterisk-Bill-Sec = 82
       Asterisk-Disposition = "ANSWERED"
       Asterisk-AMA-Flags = "DOCUMENTATION"
       Asterisk-Unique-ID = "1233327083.102"
       Asterisk-User-Field = "B2BUA-PROVIDER-PRUEBAS"
       User-Name = "SIP/5060-0972ae58"
       Acct-Session-Id = "1233327083.102"
       NAS-Port = 0
       Acct-Delay-Time = 0
       NAS-IP-Address = 10.10.149.211

Fri Jan 30 23:34:08 1998: INFO: Duplicate request id 129 received from 10.10.149.211(56844): ignored

Fri Jan 30 23:34:08 1998: DEBUG: Packet dump:
*** Received from 10.10.149.211 port 56844 ....
Code:       Accounting-Request
Identifier: 129
Authentic:  <237>U<254>W<129><156><159>D<153>A$<209><233>`G<9>
Attributes:
       Acct-Status-Type = Stop
       Asterisk-Acc-Code = "TO_PROVIDER"
       Asterisk-Src = "5502222272"
       Asterisk-Dst = "0130005411234618"
       Asterisk-Dst-Ctx = "INC_CALLS"
       Asterisk-Clid = ""sipp" <5502222272>"
       Asterisk-Chan = "SIP/5060-0972ae58"
       Asterisk-Dst-Chan = "SIP/TO_ITSP1-0972f830"
       Asterisk-Last-App = "Dial"
       Asterisk-Last-Data = "SIP/005411234618@TO_ITSP1"
       Asterisk-Start-Time = "2009-01-30 14:51:23 +0000"
       Asterisk-Answer-Time = "2009-01-30 14:51:28 +0000"
       Asterisk-End-Time = "2009-01-30 14:52:50 +0000"
       Asterisk-Duration = 87
       Asterisk-Bill-Sec = 82
       Asterisk-Disposition = "ANSWERED"
       Asterisk-AMA-Flags = "DOCUMENTATION"
       Asterisk-Unique-ID = "1233327083.102"
       Asterisk-User-Field = "B2BUA-PROVIDER-PRUEBAS"
       User-Name = "SIP/5060-0972ae58"
       Acct-Session-Id = "1233327083.102"
       NAS-Port = 0
       Acct-Delay-Time = 0
       NAS-IP-Address = 10.10.149.211

Fri Jan 30 23:34:08 1998: INFO: Duplicate request id 129 received from 10.10.149.211(56844): ignored

As you can see the the first packet is OK, but for some reason i'm getting two more packets after the first arrive.

Can someone explain to me what i'm doing wrong?
Thanks
Ricardo.-


****** ADDITIONAL INFORMATION ******

This is the cdr.conf file :

[csv]
usegmtime=yes    ; log date/time in GMT.  Default is "no"
loguniqueid=yes  ; log uniqueid.  Default is "no"
loguserfield=yes ; log user field.  Default is "no"

[radius]
usegmtime=yes    ; log date/time in GMT
loguniqueid=yes  ; log uniqueid
loguserfield=yes ; log user field
; Set this to the location of the radiusclient-ng configuration file
; The default is /etc/radiusclient-ng/radiusclient.conf
radiuscfg => /usr/local/etc/radiusclient-ng/radiusclient.conf


This is the sip.conf



[general]

context=default ; Default context for incoming calls
allowoverlap=no ; Disable overlap dialing support. (Default is yes)
bindport=5060 ; UDP Port to bind to (SIP standard port is 5060)
; bindport is the local UDP port that Asterisk will
; listen on
bindaddr=0.0.0.0 ; IP address to bind to (0.0.0.0 binds to all)
srvlookup=yes ; Enable DNS SRV lookups on outbound calls
; Note: Asterisk only uses the first host
; in SRV records
; Disabling DNS SRV lookups disables the
; ability to place SIP calls based on domain
; names to some other SIP users on the Internet

[authentication]


[FROM_LCR_TEST]
type=friend
host=10.10.149.212
context=INC_CALLS
dtmfmode=rfc2833
canreinvite=no
rtptimeout=90
rtpholdtimeout=300
disallow=all
allow=g729
allow=g723
allow=ulaw
allow=alaw


;------ OUTGOING SIP CALLS TO ITSP1 -------------

[TO_ITSP1]
type=friend
host=10.10.149.197 ; IP address of external ITSP1
rtptimeout=90 ; Clear call if no RTP received
rtpholdtimeout=300 ; Clear call if no RTP while on hold (rtpholdtimeout > rtptimeout)
dtmfmode=rfc2833
canreinvite=no
disallow=all
allow=ulaw
allow=alaw

and this is the extension.conf


[general]
;
; If static is set to no, or omitted, then the pbx_config will rewrite
; this file when extensions are modified.  Remember that all comments
; made in the file will be lost when that happens.
;
; XXX Not yet implemented XXX
;
static=yes
;
; if static=yes and writeprotect=no, you can save dialplan by
; CLI command 'save dialplan' too
;
writeprotect=no

; The "Globals" category contains global variables that can be referenced
; in the dialplan with the GLOBAL dialplan function:
; ${GLOBAL(VARIABLE)}
; ${${GLOBAL(VARIABLE)}} or ${text${GLOBAL(VARIABLE)}} or any hybrid
; Unix/Linux environmental variables can be reached with the ENV dialplan
; function: ${ENV(VARIABLE)}
;
[globals]

[default]



[INC_CALLS]

exten => _0130.,1,Set(CDR(userfield)=B2BUA-ENTEL-PRUEBAS)
exten => _0130.,2,Set(CDR(accountcode)=TO_ENTEL)
exten => _0130.,3,Dial(SIP/${EXTEN:4}@TO_ITSP1)
exten => _0130.,4,Hangup()
Comments:By: rmartinez (rmartinez) 2009-02-13 12:07:52.000-0600

I have done a few more test.
I changed the radiusclient-ng version from 0.5.6 to 0.5.2.... i still have the problem.
I have removed the TC400B cards...i still have the problem.
By: rmartinez (rmartinez) 2009-02-24 07:13:26.000-0600

Hello.
I have checked more carefully my messages files (/var/log/messages)  and i have found this line.

Feb 20 11:16:57 b2buang01 asterisk[13268]: rc_get_seqnbr: fscanf failure: /var/run/radius.seq

Could this be the cause of the problem?


By: Tilghman Lesher (tilghman) 2009-02-24 12:05:26.000-0600

It may well be the cause of the problem, but the error is originating from the client library, not from Asterisk itself.  You'll need to open an issue with the project managing that client library, not with Asterisk.