[asterisk-users] Audiocodes MP124-FXS replying BUSY when line is not.

Mon Mar 10 13:48:59 CDT 2008

Hello,

Has anybody seen that Audiocodes gateway is replying with "486 Busy
here" when it's actually not (last call ended ~15 seconds ago).

I see this quite often. From other logs i see that previous call ends
at  11:13:01, then app_queue tries to dial at 11:13:14 and fails
numerous times, before succeeding at 11:14:02

I have attached sample SIP debug log:

Any ideas what i could try to change in config to avoid this? It's
config seems huge, maybe anybody has some experience with those
gateways?

Regards,
Atis

-------------------- start of log --------------------

[Mar 10 11:13:14] VERBOSE[30165] logger.c:     -- Executing
[28254 at local_dial:70] Dial("Local/28254 at default_queue-e8c3,2",
"SIP/90166|15|gtM(queue_call_answer^28254)") in new stack
[Mar 10 11:13:14] DEBUG[30165] res_config_mysql.c: MySQL RealTime:
Everything is fine.
[Mar 10 11:13:14] DEBUG[30165] res_config_mysql.c: MySQL RealTime:
Insert SQL: INSERT INTO channels SET uniqueid = '1205172794.6453',
started = '1205172794', channel = 'SIP/90166-45079a0', state = 'Down',
callerid_num = '', callerid_name = '', accountcode = '', context =
'default-sip', exten = 's', priority = '1', application = '', data =
''
[Mar 10 11:13:14] DEBUG[30165] res_config_mysql.c: MySQL RealTime: row
inserted on table: channels, id: 0
[Mar 10 11:13:14] DEBUG[30165] chan_sip.c: Call to peer '90166' is 1 out of 8
[Mar 10 11:13:14] VERBOSE[30165] logger.c: Audio is at aa.bb.cc.dd port 47732
[Mar 10 11:13:14] VERBOSE[30165] logger.c: Adding codec 0x4 (ulaw) to SDP
[Mar 10 11:13:14] VERBOSE[30165] logger.c: Adding codec 0x2 (gsm) to SDP
[Mar 10 11:13:14] VERBOSE[30165] logger.c: Adding codec 0x8 (alaw) to SDP
[Mar 10 11:13:14] VERBOSE[30165] logger.c: Adding codec 0x10 (g726aal2) to SDP
[Mar 10 11:13:14] VERBOSE[30165] logger.c: Adding codec 0x20 (adpcm) to SDP
[Mar 10 11:13:14] VERBOSE[30165] logger.c: Adding codec 0x40 (slin) to SDP
[Mar 10 11:13:14] VERBOSE[30165] logger.c: Adding codec 0x80 (lpc10) to SDP
[Mar 10 11:13:14] VERBOSE[30165] logger.c: Adding codec 0x400 (ilbc) to SDP
[Mar 10 11:13:14] VERBOSE[30165] logger.c: Adding codec 0x800 (g726) to SDP
[Mar 10 11:13:14] VERBOSE[30165] logger.c: Adding non-codec 0x1
(telephone-event) to SDP
[Mar 10 11:13:14] VERBOSE[30165] logger.c: Reliably Transmitting (NAT)
to ee.ff.gg.hh:5060:
INVITE sip:90166 at ee.ff.gg.hh SIP/2.0
Via: SIP/2.0/UDP aa.bb.cc.dd:5060;branch=z9hG4bK3977e3c7;rport
From: "28901-----2067217913" <sip:2067217913 at aa.bb.cc.dd>;tag=as18481a04
To: <sip:90166 at ee.ff.gg.hh>
Contact: <sip:2067217913 at aa.bb.cc.dd>
Call-ID: 398ef46a157b71af443414704f2fabde at aa.bb.cc.dd
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Mon, 10 Mar 2008 18:13:14 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Type: application/sdp
Content-Length: 471

v=0
o=root 31887 31887 IN IP4 aa.bb.cc.dd
s=session
c=IN IP4 aa.bb.cc.dd
t=0 0
m=audio 47732 RTP/AVP 0 3 8 112 5 10 7 97 111 101
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:112 AAL2-G726-32/8000
a=rtpmap:5 DVI4/8000
a=rtpmap:10 L16/8000
a=rtpmap:7 LPC/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:111 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

---

[Mar 10 11:13:14] VERBOSE[30165] logger.c:     -- Called 90166
[Mar 10 11:13:14] DEBUG[30165] res_config_mysql.c: MySQL RealTime:
Everything is fine.
[Mar 10 11:13:14] DEBUG[30165] res_config_mysql.c: MySQL RealTime:
Update SQL: UPDATE channels SET callerid_num = '28254', callerid_name
= '', accountcode = '1205172743.6428', con
[Mar 10 11:13:14] DEBUG[30165] res_config_mysql.c: MySQL RealTime:
Updated 1 rows on table: channels
<--- SIP read from ee.ff.gg.hh:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP aa.bb.cc.dd:5060;branch=z9hG4bK3977e3c7;rport
From: "28901-----2067217913" <sip:2067217913 at aa.bb.cc.dd>;tag=as18481a04
To: <sip:90166 at ee.ff.gg.hh>;tag=1c1673732975
Call-ID: 398ef46a157b71af443414704f2fabde at aa.bb.cc.dd
CSeq: 102 INVITE
Supported: em,timer,replaces,path
Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE
Server: Audiocodes-Sip-Gateway-MP-124 FXS/v.4.80A.025.004
Content-Length: 0

<------------->
[Mar 10 11:13:14] VERBOSE[31897] logger.c: --- (10 headers 0 lines) ---
[Mar 10 11:13:14] VERBOSE[31897] logger.c:
<--- SIP read from ee.ff.gg.hh:5060 --->
SIP/2.0 486 Busy Here
Via: SIP/2.0/UDP aa.bb.cc.dd:5060;branch=z9hG4bK3977e3c7;rport
From: "28901-----2067217913" <sip:2067217913 at aa.bb.cc.dd>;tag=as18481a04
To: <sip:90166 at ee.ff.gg.hh>;tag=1c1673732975
Call-ID: 398ef46a157b71af443414704f2fabde at aa.bb.cc.dd
CSeq: 102 INVITE
Contact: <sip:90166 at ee.ff.gg.hh>
Supported: em,timer,replaces,path
Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE
Server: Audiocodes-Sip-Gateway-MP-124 FXS/v.4.80A.025.004
Reason: Q.850 ;cause=17
Content-Length: 0

<------------->
[Mar 10 11:13:14] VERBOSE[31897] logger.c: --- (12 headers 0 lines) ---
[Mar 10 11:13:14] VERBOSE[31897] logger.c:     -- Got SIP response 486
"Busy Here" back from ee.ff.gg.hh
[Mar 10 11:13:14] VERBOSE[31897] logger.c: Transmitting (NAT) to
ee.ff.gg.hh:5060:
ACK sip:90166 at ee.ff.gg.hh SIP/2.0
Via: SIP/2.0/UDP aa.bb.cc.dd:5060;branch=z9hG4bK3977e3c7;rport
From: "28901-----2067217913" <sip:2067217913 at aa.bb.cc.dd>;tag=as18481a04
To: <sip:90166 at ee.ff.gg.hh>;tag=1c1673732975
Contact: <sip:2067217913 at aa.bb.cc.dd>
Call-ID: 398ef46a157b71af443414704f2fabde at aa.bb.cc.dd
CSeq: 102 ACK
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0

---
[Mar 10 11:13:14] VERBOSE[30165] logger.c:     -- SIP/90166-c45079a0 is busy
[Mar 10 11:13:14] DEBUG[30165] res_config_mysql.c: MySQL RealTime:
Everything is fine.
[Mar 10 11:13:14] DEBUG[30165] res_config_mysql.c: MySQL RealTime:
Delete SQL: DELETE FROM channels WHERE uniqueid = '1205172794.6453'
[Mar 10 11:13:14] DEBUG[30165] res_config_mysql.c: MySQL RealTime:
Deleted 1 rows on table: channels
[Mar 10 11:13:14] DEBUG[30165] chan_sip.c: Call to peer '90166'
removed from call limit 8
[Mar 10 11:13:14] VERBOSE[30165] logger.c:   == Everyone is
busy/congested at this time (1:1/0/0)
----------------------------------------- end of log -------------------

-- 
Atis Lezdins,
VoIP Project Manager / Developer,
atis at iq-labs.net
Skype: atis.lezdins
Cell Phone: +371 28806004
Cell Phone: +1 800 7300689
Work phone: +1 800 7502835