Music on hold plays only for the first time

Asterisk Asterisk Support
1

Hi,

I am a new user of asterisk. I have an opensource softphone which I am using for testing purposes. On this phone I can hear the music on hold for the first time only. As I place the subsequent calls on hold, I don’t hear any music. Does it have to do anything with asterisk configuration or could it be an issue with the phone itself? Please help me as I am unable to proceed with my dev work.

Regards,
rk

2

More evidence needed. Please provide at least a verbose console log and sip history output for the device initiating the hold.

3

Hi David,

Sorry for not providing enough info. Here are some logs that may be helpful to you:

  1. SIP history :

[code]INDELASTDEVS1CLI> sip show history 432aabce021
INDELASTDEVS1CLI>

  • SIP Call

  1. TxReqRel INVITE / 102 INVITE

  2. Rx SIP/2.0 / 102 INVITE /180 RINGING

  3. CancelDestroy

  4. Rx SIP/2.0 / 102 INVITE /200 OK

  5. CancelDestroy

  6. Unhold SIP/2.0

  7. TxReq ACK / 102 ACK

  8. Rx INVITE / 102 INVITE /sip:3000@10.12.1.11

  9. CancelDestroy

  10. Hold INVITE

  11. TxRespRel SIP/2.0 / 102 INVITE

  12. Rx ACK / 102 ACK /sip:3000@10.12.1.11

  13. Rx INVITE / 103 INVITE /sip:3000@10.12.1.11

  14. CancelDestroy

  15. Unhold INVITE

  16. TxRespRel SIP/2.0 / 103 INVITE

  17. Rx ACK / 103 ACK /sip:3000@10.12.1.11

  18. Rx INVITE / 103 INVITE /sip:3000@10.12.1.11

  19. TxRespRel SIP/2.0 / 103 INVITE

  20. Rx ACK / 103 ACK /sip:3000@10.12.1.11

  21. ReTx 200 SIP/2.0 200 OK

  22. Rx ACK / 103 ACK /sip:3000@10.12.1.11

  23. ReTx 400 SIP/2.0 200 OK

  24. Rx ACK / 103 ACK /sip:3000@10.12.1.11

  25. ReTx 800 SIP/2.0 200 OK

  26. Rx ACK / 103 ACK /sip:3000@10.12.1.11

  27. ReTx 1600 SIP/2.0 200 OK

  28. Rx ACK / 103 ACK /sip:3000@10.12.1.11

  29. ReTx 3200 SIP/2.0 200 OK

  30. Rx ACK / 103 ACK /sip:3000@10.12.1.11

  31. ReTx 4000 SIP/2.0 200 OK

  32. Rx ACK / 103 ACK /sip:3000@10.12.1.11

  33. Rx INVITE / 104 INVITE /sip:3000@10.12.1.11

  34. CancelDestroy

  35. Unhold INVITE

  36. TxRespRel SIP/2.0 / 104 INVITE

  37. Rx ACK / 104 ACK /sip:3000@10.12.1.11

  38. MaxRetries (Non-critical)
    INDELASTDEVS1*CLI>[/code]

  39. Verbose console logs :

Dec 13 20:00:03 VERBOSE[11090] logger.c: -- Executing Dial("SIP/3000-b791e150", "SIP/3001") in new stack Dec 13 20:00:03 VERBOSE[11090] logger.c: -- Called 3001 Dec 13 20:00:03 VERBOSE[11090] logger.c: -- SIP/3001-097ec8f0 is ringing Dec 13 20:00:03 VERBOSE[11090] logger.c: -- SIP/3001-097ec8f0 is ringing Dec 13 20:00:05 VERBOSE[11090] logger.c: -- SIP/3001-097ec8f0 answered SIP/3000-b791e150 Dec 13 20:00:05 VERBOSE[11090] logger.c: -- Attempting native bridge of SIP/3000-b791e150 and SIP/3001-097ec8f0 Dec 13 20:00:10 VERBOSE[11090] logger.c: == Spawn extension (usd, 3001, 1) exited non-zero on 'SIP/3000-b791e150' Dec 13 20:00:11 VERBOSE[2333] logger.c: -- Unregistered SIP '3001' Dec 13 20:00:24 VERBOSE[2333] logger.c: -- Registered SIP '3001' at 10.8.31.17 port 5061 expires 3600 Dec 13 20:00:24 VERBOSE[2333] logger.c: -- Saved useragent "JavaForce/4.3.0" for peer 3001 Dec 13 20:00:52 VERBOSE[11228] logger.c: -- Executing Dial("SIP/3000-b791e150", "SIP/3001") in new stack Dec 13 20:00:52 VERBOSE[11228] logger.c: -- Called 3001 Dec 13 20:00:52 VERBOSE[11228] logger.c: -- SIP/3001-097ec8f0 is ringing Dec 13 20:00:54 VERBOSE[11228] logger.c: -- SIP/3001-097ec8f0 answered SIP/3000-b791e150 Dec 13 20:00:54 VERBOSE[11228] logger.c: -- Attempting native bridge of SIP/3000-b791e150 and SIP/3001-097ec8f0 Dec 13 20:00:58 VERBOSE[2333] logger.c: -- Started music on hold, class 'default', on SIP/3000-b791e150 Dec 13 20:01:25 VERBOSE[2333] logger.c: -- Stopped music on hold on SIP/3000-b791e150 Dec 13 20:02:29 VERBOSE[2300] logger.c: == Refreshing DNS lookups. Dec 13 20:03:17 VERBOSE[11228] logger.c: == Spawn extension (usd, 3001, 1) exited non-zero on 'SIP/3000-b791e150' Dec 13 20:07:29 VERBOSE[2300] logger.c: == Refreshing DNS lookups.

  1. Debug console logs:

[code]<-- SIP read from 10.8.32.8:5061:
INVITE sip:3001@10.12.1.11 SIP/2.0
Via: SIP/2.0/UDP 10.8.32.8:5061;branch=z123456-y12345-8489d9626d7fe5f1-1–d12345-;rport
Max-Forwards: 70
Contact: sip:3000@10.8.32.8:5061
To: "3001"sip:3001@10.12.1.11;tag=as47bcdb9b
From: "Unknown Name"sip:3000@10.8.32.8:5061;tag=ff7ce9fabac4d6c1
Call-ID: 15e2fb7b6d6e2e69580402350ec2d02e@10.12.1.11
Cseq: 102 INVITE
Allow: INVITE, ACK, CANCEL, BYE, REFER, NOTIFY, OPTIONS
User-Agent: JavaForce/4.4.0
Content-Type: application/sdp
Content-Length: 294

v=0
o=- 2289 2290 IN IP4 10.8.32.8
s=JavaForce/4.4.0
c=IN IP4 0.0.0.0
t=0 0
m=audio 32768 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=silenceSupp:off - - - -
a=ptime:20
a=sendonly
m=video -1 RTP/AVP 34
a=rtpmap:34 H263/90000
a=sendrecv

— (12 headers 15 lines) —
Using INVITE request as basis request - 15e2fb7b6d6e2e69580402350ec2d02e@10.12.1.11
Sending to 10.8.32.8 : 5061 (NAT)
Found RTP audio format 0
Found RTP audio format 101
Dec 13 18:23:59 WARNING[2333]: chan_sip.c:3680 process_sdp: Unknown SDP media type in offer: video -1 RTP/AVP 34
Peer audio RTP is at port 0.0.0.0:32768

Found description format PCMU
Found description format telephone-event
Found description format H263
Capabilities: us - 0xe (gsm|ulaw|alaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw)
Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
– Started music on hold, class ‘default’, on SIP/3001-b791e150
We’re at 10.12.1.11 port 17208
Adding codec 0x4 (ulaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (NAT) to 10.8.32.8:5061:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.8.32.8:5061;branch=z123456-y12345-8489d9626d7fe5f1-1–d12345-;received=10.8.32.8;rport=5061
From: "Unknown Name"sip:3000@10.8.32.8:5061;tag=ff7ce9fabac4d6c1
To: "3001"sip:3001@10.12.1.11;tag=as47bcdb9b
Call-ID: 15e2fb7b6d6e2e69580402350ec2d02e@10.12.1.11
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: sip:3001@10.12.1.11
Content-Type: application/sdp
Content-Length: 210

v=0
o=root 2288 2289 IN IP4 10.12.1.11
s=session
c=IN IP4 10.12.1.11
t=0 0
m=audio 17208 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -

<-- SIP read from 10.8.32.8:5061:
INVITE sip:3001@10.12.1.11 SIP/2.0
Via: SIP/2.0/UDP 10.8.32.8:5061;branch=z123456-y12345-8489d9626d7fe5f1-1–d12345-;rport
Max-Forwards: 70
Contact: sip:3000@10.8.32.8:5061
To: "3001"sip:3001@10.12.1.11;tag=as47bcdb9b
From: "Unknown Name"sip:3000@10.8.32.8:5061;tag=ff7ce9fabac4d6c1
Call-ID: 15e2fb7b6d6e2e69580402350ec2d02e@10.12.1.11
Cseq: 104 INVITE
Allow: INVITE, ACK, CANCEL, BYE, REFER, NOTIFY, OPTIONS
User-Agent: JavaForce/4.4.0
Content-Type: application/sdp
Content-Length: 235

v=0
o=- 2289 2294 IN IP4 10.8.32.8
s=JavaForce/4.4.0
c=IN IP4 0.0.0.0
t=0 0
m=audio 32768 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=silenceSupp:off - - - -
a=ptime:20
a=sendonly

— (12 headers 12 lines) —
Ignoring this INVITE request
We’re at 10.12.1.11 port 17208
Adding codec 0x4 (ulaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (NAT) to 10.8.32.8:5061:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.8.32.8:5061;branch=z123456-y12345-8489d9626d7fe5f1-1–d12345-;received=10.8.32.8;rport=5061
From: "Unknown Name"sip:3000@10.8.32.8:5061;tag=ff7ce9fabac4d6c1
To: "3001"sip:3001@10.12.1.11;tag=as47bcdb9b
Call-ID: 15e2fb7b6d6e2e69580402350ec2d02e@10.12.1.11
CSeq: 104 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: sip:3001@10.12.1.11
Content-Type: application/sdp
Content-Length: 210

v=0
o=root 2288 2293 IN IP4 10.12.1.11
s=session
c=IN IP4 10.12.1.11
t=0 0
m=audio 17208 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -

INDELASTDEVS1*CLI>
<-- SIP read from 10.8.32.8:5061:
ACK sip:3001@10.12.1.11 SIP/2.0
Via: SIP/2.0/UDP 10.8.32.8:5061;branch=z123456-y12345-8489d9626d7fe5f1-1–d12345-;rport
Max-Forwards: 70
Contact: sip:3000@10.8.32.8:5061
To: "3001"sip:3001@10.12.1.11;tag=as47bcdb9b
From: "Unknown Name"sip:3000@10.8.32.8:5061;tag=ff7ce9fabac4d6c1
Call-ID: 15e2fb7b6d6e2e69580402350ec2d02e@10.12.1.11
Cseq: 104 ACK
Allow: INVITE, ACK, CANCEL, BYE, REFER, NOTIFY, OPTIONS
User-Agent: JavaForce/4.4.0
Content-Length: 0

— (11 headers 0 lines) —
Retransmitting #1 (NAT) to 10.8.32.8:5061:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.8.32.8:5061;branch=z123456-y12345-8489d9626d7fe5f1-1–d12345-;received=10.8.32.8;rport=5061
From: "Unknown Name"sip:3000@10.8.32.8:5061;tag=ff7ce9fabac4d6c1
To: "3001"sip:3001@10.12.1.11;tag=as47bcdb9b
Call-ID: 15e2fb7b6d6e2e69580402350ec2d02e@10.12.1.11
CSeq: 104 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: sip:3001@10.12.1.11
Content-Type: application/sdp
Content-Length: 210

v=0
o=root 2288 2293 IN IP4 10.12.1.11
s=session
c=IN IP4 10.12.1.11
t=0 0
m=audio 17208 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -

[/code]

Appreciate your being helpful.

Thanks,
rk

4

It looks like it is not coping well with a broken UAC. The other side has completed a re-invite, sequence 103. It then resends a sequence 103 re-invite, even though it has already sent the sequence 103 ACK. Asterisk seems to get confused by this protocol violation.

Alternatively, in addition to the obvious protocol violation, there is something wrong with the ACK such that Asterisk fails to recognize it.

You may need to turn the debug level up.

5

Hi David,

You were absolutely right. The 103-reinvite was the main problem. I looked at the message and found that on subsequent hold messages the call sequence counter was not increasing the way it should have been. On fixing that, I can now hear music on hold for all hold requests.

Thanks a lot for your help.

Regards,
rk