Music Hold just start to play at begining of a Call randomly

fandrade · June 21, 2016, 1:15pm

Hello guys,

Im having an issue with music hold. When I make a Call to to some external number, randomly I have the music hold stating to play for 2 seconds and stops.

This is my log file:

<— Reliably Transmitting (NAT) to 172.26.154.198:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.26.154.198:5060;branch=z9hG4bKv6cntf0060vg2cds21i0sb0000g00.1;received=172.26.154.198;rport=5060
From: sip:0121139457000@172.26.154.198;tag=99fe416b
To: “5482” sip:5482@10.55.127.29;tag=as4a7ad4be
Call-ID: 0c6e5dba19ac9f5c326cb6001cea3691@10.55.127.29:5060
CSeq: 1 INVITE
Server: Converja PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: sip:5482@10.55.127.29:5060
Content-Type: application/sdp
Content-Length: 228

v=0
o=root 1263606582 1263606583 IN IP4 10.55.127.29
s=Converja PBX
c=IN IP4 10.55.127.29
t=0 0
m=audio 13558 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=recvonly

<------------>
– Started music on hold, class ‘default’, on SIP/5482-00000217

<— SIP read from UDP:172.26.154.198:5060 —>
ACK sip:5482@10.55.127.29:5060 SIP/2.0
Via: SIP/2.0/UDP 172.26.154.198:5060;branch=z9hG4bKf2b5eq008gbhq09pu6q1.1
Call-ID: 0c6e5dba19ac9f5c326cb6001cea3691@10.55.127.29:5060
From: sip:0121139457000@172.26.154.198;tag=99fe416b
To: “5482” sip:5482@10.55.127.29;tag=as4a7ad4be
CSeq: 1 ACK
Max-Forwards: 69
Content-Length: 0

<------------->
— (8 headers 0 lines) —

<— SIP read from UDP:10.0.10.207:5062 —>

<------------->

<— SIP read from UDP:10.0.10.108:5060 —>

<------------->

<— SIP read from UDP:10.0.10.106:5062 —>

<------------->

<— SIP read from UDP:172.26.154.198:5060 —>
INVITE sip:5482@10.55.127.29:5060 SIP/2.0
Via: SIP/2.0/UDP 172.26.154.198:5060;branch=z9hG4bKv6cntf0060vg2cds21i0sb0000010.1
Call-ID: 0c6e5dba19ac9f5c326cb6001cea3691@10.55.127.29:5060
From: sip:0121139457000@172.26.154.198;tag=99fe416b
To: “5482” sip:5482@10.55.127.29;tag=as4a7ad4be
CSeq: 2 INVITE
Contact: sip:0121139457000@172.26.154.198:5060;transport=udp
Max-Forwards: 69
Content-Length: 213
Content-Type: application/sdp

v=0
o=HuaweiSoftX3000 205686092 205686095 IN IP4 172.26.154.198
s=Sip Call
c=IN IP4 172.26.154.198
t=0 0
m=audio 52420 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
<------------->
— (10 headers 9 lines) —
Sending to 172.26.154.198:5060 (NAT)
Found RTP audio format 0
Found RTP audio format 101
Found audio description format PCMU for ID 0
Found audio description format telephone-event for ID 101
Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
Peer audio RTP is at port 172.26.154.198:52420

<— Transmitting (NAT) to 172.26.154.198:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.26.154.198:5060;branch=z9hG4bKv6cntf0060vg2cds21i0sb0000010.1;received=172.26.154.198;rport=5060
From: sip:0121139457000@172.26.154.198;tag=99fe416b
To: “5482” sip:5482@10.55.127.29;tag=as4a7ad4be
Call-ID: 0c6e5dba19ac9f5c326cb6001cea3691@10.55.127.29:5060
CSeq: 2 INVITE
Server: Converja PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: sip:5482@10.55.127.29:5060
Content-Length: 0

<------------>
Audio is at 13558
Adding codec 0x4 (ulaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP

<— Reliably Transmitting (NAT) to 172.26.154.198:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.26.154.198:5060;branch=z9hG4bKv6cntf0060vg2cds21i0sb0000010.1;received=172.26.154.198;rport=5060
From: sip:0121139457000@172.26.154.198;tag=99fe416b
To: “5482” sip:5482@10.55.127.29;tag=as4a7ad4be
Call-ID: 0c6e5dba19ac9f5c326cb6001cea3691@10.55.127.29:5060
CSeq: 2 INVITE
Server: Converja PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: sip:5482@10.55.127.29:5060
Content-Type: application/sdp
Content-Length: 228

v=0
o=root 1263606582 1263606584 IN IP4 10.55.127.29
s=Converja PBX
c=IN IP4 10.55.127.29
t=0 0
m=audio 13558 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

<------------>
– Stopped music on hold on SIP/5482-00000217

<— SIP read from UDP:172.26.154.198:5060 —>
ACK sip:5482@10.55.127.29:5060 SIP/2.0
Via: SIP/2.0/UDP 172.26.154.198:5060;branch=z9hG4bKeo1bd0206o2hs31mf511.1
Call-ID: 0c6e5dba19ac9f5c326cb6001cea3691@10.55.127.29:5060
From: sip:0121139457000@172.26.154.198;tag=99fe416b
To: “5482” sip:5482@10.55.127.29;tag=as4a7ad4be
CSeq: 2 ACK
Max-Forwards: 69
Content-Length: 0

<------------->
— (8 headers 0 lines) —

<— SIP read from UDP:10.0.10.109:5060 —>

<------------->

<— SIP read from UDP:10.0.10.167:5062 —>

<------------->

<— SIP read from UDP:10.0.10.165:5060 —>
REGISTER sip:10.0.10.25:5060 SIP/2.0
From: sip:5482@10.0.10.25;tag=6e8e08-a50a000a-13c4-55013-1-289a17a0-1
To: sip:5482@10.0.10.25
Call-ID: 7018d0-a50a000a-13c4-55013-1-9704de2-1
CSeq: 1317 REGISTER
Via: SIP/2.0/UDP 10.0.10.165:5060;rport;branch=z9hG4bK-54d59-14b626d6-6968ca33
Max-Forwards: 70
Supported: replaces,100rel,eventlist,timer
Allow: REGISTER, INVITE, ACK, BYE, REFER, NOTIFY, CANCEL, INFO, OPTIONS, PRACK, SUBSCRIBE, PUBLISH
User-Agent: AUDC-IPPhone/2.2.4.86 (405-Rev0; 00908f758091)
Expires: 3600
Authorization: Digest username=“5482”,realm=“converja”,nonce=“75796451”,uri=“sip:10.0.10.25:5060”,response=“3e6cda3d8fbd4d711076ed5589968155”,algorithm=MD5
Contact: sip:5482@10.0.10.165:5060
Content-Length: 0

<------------->
— (14 headers 0 lines) —
Sending to 10.0.10.165:5060 (NAT)

<— Transmitting (NAT) to 10.0.10.165:5060 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 10.0.10.165:5060;branch=z9hG4bK-54d59-14b626d6-6968ca33;received=10.0.10.165;rport=5060
From: sip:5482@10.0.10.25;tag=6e8e08-a50a000a-13c4-55013-1-289a17a0-1
To: sip:5482@10.0.10.25;tag=as55d3ee9c
Call-ID: 7018d0-a50a000a-13c4-55013-1-9704de2-1
CSeq: 1317 REGISTER
Server: Converja PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“converja”, nonce="0c7cf464"
Content-Length: 0

<------------>
Scheduling destruction of SIP dialog ‘7018d0-a50a000a-13c4-55013-1-9704de2-1’ in 32000 ms (Method: REGISTER)

<— SIP read from UDP:10.0.10.165:5060 —>
REGISTER sip:10.0.10.25:5060 SIP/2.0
From: sip:5482@10.0.10.25;tag=6e8e08-a50a000a-13c4-55013-1-289a17a0-1
To: sip:5482@10.0.10.25
Call-ID: 7018d0-a50a000a-13c4-55013-1-9704de2-1
CSeq: 1318 REGISTER
Via: SIP/2.0/UDP 10.0.10.165:5060;rport;branch=z9hG4bK-54d59-14b6270b-5ac8801
Max-Forwards: 70
Supported: replaces,100rel,eventlist,timer
Allow: REGISTER, INVITE, ACK, BYE, REFER, NOTIFY, CANCEL, INFO, OPTIONS, PRACK, SUBSCRIBE, PUBLISH
User-Agent: AUDC-IPPhone/2.2.4.86 (405-Rev0; 00908f758091)
Expires: 3600
Authorization: Digest username=“5482”,realm=“converja”,nonce=“0c7cf464”,uri=“sip:10.0.10.25:5060”,response=“83071f6f555d840baf3f813cf4eed502”,algorithm=MD5
Contact: sip:5482@10.0.10.165:5060
Content-Length: 0

<------------->
— (14 headers 0 lines) —
Sending to 10.0.10.165:5060 (NAT)
Reliably Transmitting (NAT) to 10.0.10.165:5060:
OPTIONS sip:5482@10.0.10.165:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.10.25:5060;branch=z9hG4bK3a438117;rport
Max-Forwards: 70
From: “asterisk” sip:asterisk@10.0.10.25;tag=as6a150f46
To: sip:5482@10.0.10.165:5060
Contact: sip:asterisk@10.0.10.25:5060
Call-ID: 46285c511f5321776292987807c6abde@10.0.10.25:5060
CSeq: 102 OPTIONS
User-Agent: Converja PBX
Date: Tue, 21 Jun 2016 13:00:45 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0

<— Transmitting (NAT) to 10.0.10.165:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.0.10.165:5060;branch=z9hG4bK-54d59-14b6270b-5ac8801;received=10.0.10.165;rport=5060
From: sip:5482@10.0.10.25;tag=6e8e08-a50a000a-13c4-55013-1-289a17a0-1
To: sip:5482@10.0.10.25;tag=as55d3ee9c
Call-ID: 7018d0-a50a000a-13c4-55013-1-9704de2-1
CSeq: 1318 REGISTER
Server: Converja PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Expires: 800
Contact: sip:5482@10.0.10.165:5060;expires=800
Date: Tue, 21 Jun 2016 13:00:45 GMT
Content-Length: 0

<------------>
Scheduling destruction of SIP dialog ‘7018d0-a50a000a-13c4-55013-1-9704de2-1’ in 32000 ms (Method: REGISTER)

<— SIP read from UDP:10.0.10.165:5060 —>
SIP/2.0 200 OK
From: "asterisk"sip:asterisk@10.0.10.25;tag=as6a150f46
To: sip:5482@10.0.10.165:5060;tag=6f05d8-a50a000a-13c4-55013-54d59-782954af-54d59
Call-ID: 46285c511f5321776292987807c6abde@10.0.10.25:5060
CSeq: 102 OPTIONS
Via: SIP/2.0/UDP 10.0.10.25:5060;rport=5060;branch=z9hG4bK3a438117
Supported: replaces,100rel,eventlist,timer
User-Agent: AUDC-IPPhone/2.2.4.86 (405-Rev0; 00908f758091)
Content-Length: 0

<------------->
— (9 headers 0 lines) —
Really destroying SIP dialog ‘46285c511f5321776292987807c6abde@10.0.10.25:5060’ Method: OPTIONS

<— SIP read from UDP:10.0.10.165:5060 —>
BYE sip:01139457000@10.0.10.25:5060 SIP/2.0
From: "Felipe Brunelli de Andrade"sip:5482@10.0.10.25;tag=6efd68-a50a000a-13c4-55013-54d4d-729d6002-54d4d
To: sip:01139457000@10.0.10.25;tag=as271d44f7
Call-ID: 6f8c98-a50a000a-13c4-55013-54d4d-3b4a7424-54d4d
CSeq: 2 BYE
Via: SIP/2.0/UDP 10.0.10.165:5060;rport;branch=z9hG4bK-54d5a-14b62941-c113e3d
Max-Forwards: 70
Supported: replaces,100rel,eventlist,timer
Allow: REGISTER, INVITE, ACK, BYE, REFER, NOTIFY, CANCEL, INFO, OPTIONS, PRACK, SUBSCRIBE, PUBLISH
User-Agent: AUDC-IPPhone/2.2.4.86 (405-Rev0; 00908f758091)
Content-Length: 0

<------------->
— (11 headers 0 lines) —
Sending to 10.0.10.165:5060 (NAT)
Scheduling destruction of SIP dialog ‘6f8c98-a50a000a-13c4-55013-54d4d-3b4a7424-54d4d’ in 6400 ms (Method: BYE)

<— Transmitting (NAT) to 10.0.10.165:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.0.10.165:5060;branch=z9hG4bK-54d5a-14b62941-c113e3d;received=10.0.10.165;rport=5060
From: "Felipe Brunelli de Andrade"sip:5482@10.0.10.25;tag=6efd68-a50a000a-13c4-55013-54d4d-729d6002-54d4d
To: sip:01139457000@10.0.10.25;tag=as271d44f7
Call-ID: 6f8c98-a50a000a-13c4-55013-54d4d-3b4a7424-54d4d
CSeq: 2 BYE
Server: Converja PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0

<------------>
– Executing [h@a2billing:1] Hangup(“SIP/5482-00000217”, “”) in new stack
== Spawn extension (a2billing, h, 1) exited non-zero on 'SIP/5482-00000217’
Scheduling destruction of SIP dialog ‘0c6e5dba19ac9f5c326cb6001cea3691@10.55.127.29:5060’ in 6400 ms (Method: ACK)
set_destination: Parsing sip:0121139457000@172.26.154.198:5060;user=phone;transport=udp for address/port to send to
set_destination: set destination to 172.26.154.198:5060
Reliably Transmitting (NAT) to 172.26.154.198:5060:
BYE sip:0121139457000@172.26.154.198:5060;user=phone;transport=udp SIP/2.0
Via: SIP/2.0/UDP 10.55.127.29:5060;branch=z9hG4bK1f5502e0;rport
Max-Forwards: 70
From: “5482” sip:5482@10.55.127.29;tag=as4a7ad4be
To: sip:0121139457000@172.26.154.198;tag=99fe416b
Call-ID: 0c6e5dba19ac9f5c326cb6001cea3691@10.55.127.29:5060
CSeq: 103 BYE
User-Agent: Converja PBX
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0

a2billing.php: file:Class.RateEngine.php - line:1296 - uniqueid:1466514032.564 - DIAL SIP/algar/0121139457000,60,HRrTL(331110000:61000:30000)
a2billing.php: file:Class.RateEngine.php - line:1430 - uniqueid:1466514032.564 - HANGUPCAUSE: 16
a2billing.php: file:Class.RateEngine.php - line:1431 - uniqueid:1466514032.564 - DIALSTATUS: ANSWER
a2billing.php: file:Class.RateEngine.php - line:981 - uniqueid:1466514032.564 - :[sessiontime:5 - id_cc_package_offer:-1 - package2apply:]
a2billing.php:
a2billing.php:
a2billing.php: file:Class.RateEngine.php - line:1129 - uniqueid:1466514032.564 - [CC_asterisk_stop : SQL: DONE : result=1]
– <SIP/5482-00000217>AGI Script a2billing.php completed, returning 4
== Spawn extension (a2billing, 01139457000, 6) exited non-zero on ‘SIP/5482-00000217’
== MixMonitor close filestream
== End MixMonitor Recording SIP/5482-00000217
set_destination: Parsing sip:5461@10.0.10.207:5062 for address/port to send to
set_destination: set destination to 10.0.10.207:5062
Reliably Transmitting (NAT) to 10.0.10.207:5062:
NOTIFY sip:5461@10.0.10.207:5062 SIP/2.0
Via: SIP/2.0/UDP 10.0.10.25:5060;branch=z9hG4bK4c0ad473;rport
Max-Forwards: 70
From: sip:5482@10.0.10.25;tag=as5b76f2a5
To: “Sala de Reunião Engenharia” sip:5461@10.0.10.25;tag=4293629051
Contact: sip:5482@10.0.10.25:5060
Call-ID: 2533604502@10.0.10.207
CSeq: 1550 NOTIFY
User-Agent: Converja PBX
Subscription-State: active
Event: dialog
Content-Type: application/dialog-info+xml
Content-Length: 206

<?xml version="1.0"?> terminated

== Extension Changed 5482[subscribe-context] new state Idle for Notify User 5461

Im using Asterisk 1.8.16.0

Do you have any idea how to solve this?

david551 · June 21, 2016, 8:40pm

The trace is incomplete, but looking at the OK at the start, it has a=recvonly, which means the INVITE that you didn’t include must have had a=sendonly, i.e. the peer started the call already on hold, so you should have heard music on hold.

I haven’t looked any further down the trace.

fandrade · June 21, 2016, 8:47pm

Tks David,

But I don’t know why I can hear the other side saying "Hello… " and we can continue the conversation…

any idea?

david551 · June 21, 2016, 8:58pm

Please obtain your log from the log file, not a screen scrape. That way, there will be time stamps in it. Also, please mark it as unformatted text in the forum, so that the bits in angle brackets are preserved. It should also avoid your losing the start of the dialogue.

Some unknown interval after the call was started on hold, the peer has sent a re-invite to take it off hold, and, before acknowledging that, Asterisk has turned off its music on hold. I assume that there is a negligible delay between receiving the re-invite and turning off the music.