Intercom feature failing

rcoetzee · May 4, 2017, 7:55am

Hi All
Trying to test this feature between 2 Internal phones ,when i dial the feature code *80XXXX where XXXX is the extension number ,the extension rings but call drops as soon as it is answered ,i see following error in CLI :
ast_prod: Prodding channel ‘SIP/2005-00000007’ failed
Any idea of what could be going wrong here ? I have enabled Intercom on both phones and allowed Intercom calls between them

david551 · May 4, 2017, 8:32am

Asterisk has now concept of internal phones and no concept of intercom calls.

You need to find out what the phones really mean, in technical terms, by intercom, and you also need to provide sip debugging logs of a failed call. Please mark logs as pre-formatted text, when pasting them into your forum post.

Your ast_prod: message is a warning, not an error, and it looks to me as though it is secondary effect from the channel already having been closed.

The normal reason for terminating a SIP call immediately on answer is that the peer offered a set of codecs none of which were allowed.

rcoetzee · May 4, 2017, 8:49am

Yeah unfortunately i don`t see much info in the SIP dialogs ,see below :
[2017-05-04 10:38:15] NOTICE[24197]: chan_sip.c:17159 check_auth: Correct auth, but based on stale nonce received from 'sip:2005@X.X.X.X:5060;transport=UDP;tag=53f51579’
Scheduling destruction of SIP dialog ‘03d7b8b263b3ed71563cb2394898cdcb@X.X.X.X:5060’ in 26752 ms (Method: INVITE)
[2017-05-04 10:38:16] ERROR[30137][C-00000023]: res_pjsip_header_funcs.c:520 func_write_header: This function requires a PJSIP channel.
[2017-05-04 10:38:16] ERROR[30137][C-00000023]: res_pjsip_header_funcs.c:520 func_write_header: This function requires a PJSIP channel.
Audio is at 14054
Adding codec ulaw to SDP
Adding codec alaw to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (no NAT) to 41.151.47.235:56011:
INVITE sip:2004@41.151.47.235:56011;rinstance=d645fb9f04d9788f;intercom=true SIP/2.0
Via: SIP/2.0/UDP X.X.X.X:5060;branch=z9hG4bK594b0ed6
Max-Forwards: 70
From: “Test User 1” sip:2005@X.X.X.X;tag=as47128ff7
To: sip:2004@41.151.47.235:56011;rinstance=d645fb9f04d9788f;intercom=true
Contact: sip:2005@X.X.X.X:5060
Call-ID: 6466112a46f92da458c88c6810236eae@X.X.X.X:5060
CSeq: 102 INVITE
User-Agent: AsteriskNow-13.0.190.17(13.12.1)
Date: Thu, 04 May 2017 08:38:16 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Alert-Info: Ring Answer
Call-Info: ;answer-after=0
P-Asserted-Identity: “Test User 1” sip:2005@X.X.X.X
Content-Type: application/sdp
Content-Length: 278

v=0
o=root 1707756712 1707756712 IN IP4 X.X.X.X
s=Asterisk PBX 13.12.1
c=IN IP4 X.X.X.X
t=0 0
m=audio 14054 RTP/AVP 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

Retransmitting #1 (no NAT) to 41.151.47.235:56011:
INVITE sip:2004@41.151.47.235:56011;rinstance=d645fb9f04d9788f;intercom=true SIP/2.0
Via: SIP/2.0/UDP X.X.X.X:5060;branch=z9hG4bK594b0ed6
Max-Forwards: 70
From: “Test User 1” sip:2005@X.X.X.X;tag=as47128ff7
To: sip:2004@41.151.47.235:56011;rinstance=d645fb9f04d9788f;intercom=true
Contact: sip:2005@X.X.X.X:5060
Call-ID: 6466112a46f92da458c88c6810236eae@X.X.X.X:5060
CSeq: 102 INVITE
User-Agent: AsteriskNow-13.0.190.17(13.12.1)
Date: Thu, 04 May 2017 08:38:16 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Alert-Info: Ring Answer
Call-Info: ;answer-after=0
P-Asserted-Identity: “Test User 1” sip:2005@X.X.X.X
Content-Type: application/sdp
Content-Length: 278

v=0
o=root 1707756712 1707756712 IN IP4 X.X.X.X
s=Asterisk PBX 13.12.1
c=IN IP4 X.X.X.X
t=0 0
m=audio 14054 RTP/AVP 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

<— SIP read from UDP:41.151.47.235:56011 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP X.X.X.X:5060;branch=z9hG4bK594b0ed6
From: “Test User 1” sip:2005@X.X.X.X;tag=as47128ff7
To: sip:2004@41.151.47.235:56011;rinstance=d645fb9f04d9788f;intercom=true
Call-ID: 6466112a46f92da458c88c6810236eae@X.X.X.X:5060
CSeq: 102 INVITE
Content-Length: 0

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

<— SIP read from UDP:41.151.47.235:56011 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP X.X.X.X:5060;branch=z9hG4bK594b0ed6
From: “Test User 1” sip:2005@X.X.X.X;tag=as47128ff7
To: sip:2004@41.151.47.235:56011;rinstance=d645fb9f04d9788f;intercom=true
Call-ID: 6466112a46f92da458c88c6810236eae@X.X.X.X:5060
CSeq: 102 INVITE
Content-Length: 0

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

<— SIP read from UDP:41.151.47.235:56011 —>
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP X.X.X.X:5060;branch=z9hG4bK594b0ed6
From: “Test User 1” sip:2005@X.X.X.X;tag=as47128ff7
To: “Test User” sip:2004@41.151.47.235:56011;rinstance=d645fb9f04d9788f;intercom=true;tag=503d0368
Call-ID: 6466112a46f92da458c88c6810236eae@X.X.X.X:5060
CSeq: 102 INVITE
Contact: sip:2004@41.151.47.235:56011;rinstance=d645fb9f04d9788f
User-agent: X-Lite release 4.9.7.1 stamp 83372
allow-events: talk
allow-events: hold
Content-Length: 0

<------------->
— (11 headers 0 lines) —
sip_route_dump: route/path hop: sip:2004@41.151.47.235:56011;rinstance=d645fb9f04d9788f
Scheduling destruction of SIP dialog ‘6466112a46f92da458c88c6810236eae@X.X.X.X:5060’ in 26752 ms (Method: INVITE)
Reliably Transmitting (no NAT) to 41.151.47.235:56011:
CANCEL sip:2004@41.151.47.235:56011;rinstance=d645fb9f04d9788f;intercom=true SIP/2.0
Via: SIP/2.0/UDP X.X.X.X:5060;branch=z9hG4bK594b0ed6
Max-Forwards: 70
From: “Test User 1” sip:2005@X.X.X.X;tag=as47128ff7
To: sip:2004@41.151.47.235:56011;rinstance=d645fb9f04d9788f;intercom=true
Call-ID: 6466112a46f92da458c88c6810236eae@X.X.X.X:5060
CSeq: 102 CANCEL
User-Agent: AsteriskNow-13.0.190.17(13.12.1)
Content-Length: 0

Scheduling destruction of SIP dialog ‘6466112a46f92da458c88c6810236eae@X.X.X.X:5060’ in 26752 ms (Method: INVITE)
[2017-05-04 10:38:21] WARNING[30137][C-00000023]: channel.c:4928 ast_prod: Prodding channel ‘SIP/2005-0000000a’ failed

<— SIP read from UDP:41.151.47.235:56011 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP X.X.X.X:5060;branch=z9hG4bK594b0ed6
From: “Test User 1” sip:2005@X.X.X.X;tag=as47128ff7
To: sip:2004@41.151.47.235:56011;rinstance=d645fb9f04d9788f;intercom=true;tag=503d0368
Call-ID: 6466112a46f92da458c88c6810236eae@X.X.X.X:5060
CSeq: 102 CANCEL
Contact: sip:2004@41.151.47.235:56011;rinstance=d645fb9f04d9788f
User-agent: X-Lite release 4.9.7.1 stamp 83372
Content-Length: 0

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

<— SIP read from UDP:41.151.47.235:56011 —>
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP X.X.X.X:5060;branch=z9hG4bK594b0ed6
From: “Test User 1” sip:2005@X.X.X.X;tag=as47128ff7
To: sip:2004@41.151.47.235:56011;rinstance=d645fb9f04d9788f;intercom=true;tag=503d0368
Call-ID: 6466112a46f92da458c88c6810236eae@X.X.X.X:5060
CSeq: 102 INVITE
User-agent: X-Lite release 4.9.7.1 stamp 83372
Content-Length: 0

<------------->
— (8 headers 0 lines) —
Transmitting (no NAT) to 41.151.47.235:56011:
ACK sip:2004@41.151.47.235:56011;rinstance=d645fb9f04d9788f SIP/2.0
Via: SIP/2.0/UDP X.X.X.X:5060;branch=z9hG4bK594b0ed6
Max-Forwards: 70
From: “Test User 1” sip:2005@X.X.X.X;tag=as47128ff7
To: sip:2004@41.151.47.235:56011;rinstance=d645fb9f04d9788f;intercom=true;tag=503d0368
Contact: sip:2005@X.X.X.X:5060
Call-ID: 6466112a46f92da458c88c6810236eae@X.X.X.X:5060
CSeq: 102 ACK
User-Agent: AsteriskNow-13.0.190.17(13.12.1)
Content-Length: 0

david551 · May 4, 2017, 8:52am

I said mark them as pre-formatted text; you have not done so!

david551 · May 4, 2017, 8:58am

Also, please use the log file, not a screen scrape, so we can see the timing, in particular the time from Ringing to Cancel.

Incidentally this call has not been answered. Asterisk abandoned it before it was answered. That will either be because it wasn’t answered within the dial timeout, or because the caller abandoned.

rcoetzee · May 4, 2017, 9:08am

Sorry i did mark it as pre-formatted ,guess it was because i copied it from CLI to Notepad. The phone rings once and then the call drops ,when i dial between these 2 extensions without feature code then it works 100%. Let me get the logs

rcoetzee · May 4, 2017, 11:43am

Sip_debug_intercom.txt (262.9 KB)
Called from 2005 to 2004

david551 · May 4, 2017, 11:57am

2017-05-04 12:14:41] VERBOSE[6622][C-00000060] pbx.c: Executing [*802004@ext-intercom:34] Dial("SIP/2005-0000001a", "SIP/2004,5,IA(beep)b(autoanswer^s^1(Ring Answer,<uri>;answer-after=0))") in new stack

[2017-05-04 12:14:46] VERBOSE[6622][C-00000060] app_dial.c: Nobody picked up in 5000 ms

You didn’t answer the call within the time you allowed in your Dial parameters (5 seconds). Maybe the phone didn’t understand the Call-Info header, or maybe you hadn’t disabled the security to prevent the phone being used as a bug.

rcoetzee · May 4, 2017, 12:39pm

Thanks for the quick response ,i was under the impression that the phone will auto answer when it is a intercom call ,also checked a autoanswer script running in the debugs

david551 · May 4, 2017, 1:37pm

Intercom mode is something to do with the phone; it is not anything that Asterisk knows about.

According to https://community.zoiper.com/748/what-is-the-correct-sip-header-for-auto-answer and https://community.zoiper.com/1718/intercom-paging only the paid for version of Zoiper supports auto-answer, and you have to explicitly enable it. The version 2 on yours seems to suggest you have the free version.

rcoetzee · May 4, 2017, 2:10pm

Thanks for the reply David ,really appreciate the help ,i do indeed have the free version that i was just using to test with ,i will test it with some physical handsets tommorow

david551 · May 4, 2017, 2:23pm

Please note that different products may use different methods for requesting auto-answer, but all should require it to be explicitly enabled on the device.

johnkiniston · May 4, 2017, 4:52pm

rcoetzee:

2017-05-04 10:38:16] ERROR[30137][C-00000023]: res_pjsip_header_funcs.c:520 func_write_header: This function requires a PJSIP channel.
[2017-05-04 10:38:16] ERROR[30137][C-00000023]: res_pjsip_header_funcs.c:520 func_write_header: This function requires a PJSIP channel.

Your phone may not be answering because you are using the wrong addheader function, You are using CHAN_SIP and trying to use the addheader function for CHAN_PJSIP

david551 · May 4, 2017, 7:06pm

The Call-Info header was in the actual INVITE.

rcoetzee · May 5, 2017, 4:23am

Hi ,i actually changed the phone driver to SIP from PJSIP ,although when i had it on PJSIP that error was showing “This function requires SIP channel”. That is why i changed the driver of the phone in the first place as i thought that maybe the feature was not supported on SIP channel

jcolp · May 5, 2017, 9:31am

Both channel drivers support putting arbitrary SIP headers on the outgoing INVITE, they just have different ways to do it.

johnkiniston · May 5, 2017, 3:33pm

These are the headers I use.

PJSIP
 same =>    n,Set(PJSIP_HEADER(add,Call-Info)=answer-after=0); Yealink
 same =>    n,Set(PJSIP_HEADER(add,Alert-Info)=info=AutoAnswer); Polycom Immediate Answer

CHAN_SIP
 same =>   n,SIPAddHeader(Alert-Info: AutoAnswer) Polycom
 same =>   n,SipAddHeader(Call-Info: <uri>\;answer-after=0); Yealink

david551 · May 5, 2017, 8:22pm

I assume uri is the result of redaction, not the literal letters u r i.

johnkiniston · May 5, 2017, 9:06pm

I’m actually using the string URI, It’s weird but works.

jcolp · May 5, 2017, 9:08pm

Phones are unlikely to really… care so I’m not surprised.