[asterisk-users] Call pickup on channel sip with SNOM phones issue

Mon Aug 27 16:01:54 CDT 2018

On Montag, 27. August 2018 17:42:37 Hans-Peter Jansen wrote:
> 
> What am I missing here, any suggestions?
> 

Okay, scratch it, "notifycid = yes" must reside in the general section! <Duh>

Now, it behaves as expected until:

[Aug 27 22:20:37] NOTICE[6200][C-00000003]: app_directed_pickup.c:365 pickup_exec: No target channel found for 62 at phones

Details:

extensions.conf:

[phones]
exten => 60,hint,SIP/60
exten => 61,hint,SIP/61
exten => 62,hint,SIP/62

exten => _60,1,Dial(SIP/60)
exten => _61,1,Dial(SIP/61)
exten => _62,1,Dial(SIP/62)

A call from external to 62 is notified to 60 three times:

First a little silly (local and remote are identical):

  == Extension Changed 62[phones] new state Ringing for Notify User 60 
Reliably Transmitting (NAT) to 172.16.23.60:2112:
NOTIFY sip:60 at 172.16.23.60:2112 SIP/2.0
Via: SIP/2.0/UDP 172.16.4.100:5060;branch=z9hG4bK2ec2ef2e;rport
Max-Forwards: 70
From: <sip:62 at 172.16.4.100;user=phone>;tag=as40973611
To: <sip:60 at 172.16.4.100>;tag=ebsb74m178
Contact: <sip:62 at 172.16.4.100:5060>
Call-ID: 3c95372c15b1-uz42rw4w6sy9
CSeq: 104 NOTIFY
User-Agent: Asterisk PBX 15.5.0
Subscription-State: active
Event: dialog
Content-Type: application/dialog-info+xml
Content-Length: 524

<?xml version="1.0"?>
<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="2" state="full" entity="sip:62 at 172.16.4.100">
<dialog id="62" call-id="pickup-3c95372c15b1-uz42rw4w6sy9" local-tag="ebsb74m178" remote-tag="as40973611" direction="recipient">
<remote>
<identity display="62">sip:62 at 172.16.4.100</identity>
<target uri="sip:62 at 172.16.4.100"/>
</remote>
<local>
<identity display="62">sip:62 at 172.16.4.100</identity>
<target uri="sip:62 at 172.16.4.100"/>
</local>
<state>early</state>
</dialog>
</dialog-info>

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

Then with an entity of sip:62 at 172.16.23.8, which is my old asterisk, but with 
correct local/remote values:

--- (7 headers 0 lines) ---
Reliably Transmitting (NAT) to 172.16.23.60:2112:
NOTIFY sip:60 at 172.16.23.60:2112 SIP/2.0
Via: SIP/2.0/UDP 172.16.4.100:5060;branch=z9hG4bK60e3a3a9;rport
Max-Forwards: 70
From: <sip:62 at 172.16.23.8;user=phone>;tag=as2c6b3fce
To: <sip:60 at 172.16.4.100>;tag=mafy78cezc
Contact: <sip:62 at 172.16.4.100:5060>
Call-ID: 3c95372c1b80-xmqzyr2cq6z2
CSeq: 105 NOTIFY
User-Agent: Asterisk PBX 15.5.0
Subscription-State: active
Event: dialog
Content-Type: application/dialog-info+xml
Content-Length: 541

<?xml version="1.0"?>
<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="3" state="full" entity="sip:62 at 172.16.23.8">
<dialog id="62" call-id="pickup-3c95372c1b80-xmqzyr2cq6z2" local-tag="mafy78cezc" remote-tag="as2c6b3fce" direction="recipient">
<remote>
<identity display="">sip:01721234567 at 172.16.4.100</identity>
<target uri="sip:01721234567 at 172.16.4.100"/>
</remote>
<local>
<identity display="LISA">sip:62 at 172.16.4.100</identity>
<target uri="sip:62 at 172.16.4.100"/>
</local>
<state>early</state>
</dialog>
</dialog-info>

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

And finally correctly:

--- (7 headers 0 lines) ---
Reliably Transmitting (NAT) to 172.16.23.60:2112:
NOTIFY sip:60 at 172.16.23.60:2112 SIP/2.0
Via: SIP/2.0/UDP 172.16.4.100:5060;branch=z9hG4bK6d9e9f60;rport
Max-Forwards: 70
From: <sip:62 at 172.16.4.100;user=phone>;tag=as40973611
To: <sip:60 at 172.16.4.100>;tag=ebsb74m178
Contact: <sip:62 at 172.16.4.100:5060>
Call-ID: 3c95372c15b1-uz42rw4w6sy9
CSeq: 105 NOTIFY
User-Agent: Asterisk PBX 15.5.0
Subscription-State: active
Event: dialog
Content-Type: application/dialog-info+xml
Content-Length: 542

<?xml version="1.0"?>
<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="3" state="full" entity="sip:62 at 172.16.4.100">
<dialog id="62" call-id="pickup-3c95372c15b1-uz42rw4w6sy9" local-tag="ebsb74m178" remote-tag="as40973611" direction="recipient">
<remote>
<identity display="">sip:01721234567 at 172.16.4.100</identity>
<target uri="sip:01721234567 at 172.16.4.100"/>
</remote>
<local>
<identity display="LISA">sip:62 at 172.16.4.100</identity>
<target uri="sip:62 at 172.16.4.100"/>
</local>
<state>early</state>
</dialog>
</dialog-info>

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

NOTIFY Ack:

--- (11 headers 0 lines) ---
sip_route_dump: route/path hop: <sip:62 at 172.16.23.62:37741>
    -- SIP/62-00000003 is ringing

<--- SIP read from UDP:172.16.23.60:2112 --->
SIP/2.0 200 Ok
Via: SIP/2.0/UDP 172.16.4.100:5060;branch=z9hG4bK6d9e9f60;rport=5060
From: <sip:62 at 172.16.4.100;user=phone>;tag=as40973611
To: <sip:60 at 172.16.4.100>;tag=ebsb74m178
Call-ID: 3c95372c15b1-uz42rw4w6sy9
CSeq: 105 NOTIFY
Content-Length: 0

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

60 want to take over the call:

<--- SIP read from UDP:172.16.23.60:2112 --->
INVITE sip:01721234567 at 172.16.4.100 SIP/2.0
Via: SIP/2.0/UDP 172.16.23.60:2112;branch=z9hG4bK-pb8ywn90vhet;rport
From: "HFO" <sip:60 at 172.16.4.100>;tag=omy5lrfdik
To: <sip:01721234567 at 172.16.4.100>
Call-ID: 3c953745720b-p5q7kgcj604q
CSeq: 1 INVITE
Max-Forwards: 70
Contact: <sip:60 at 172.16.23.60:2112>;reg-id=1
Replaces: pickup-3c95372c15b1-uz42rw4w6sy9;to-tag=as40973611;from-tag=ebsb74m178
P-Key-Flags: resolution="31x13", keys="4"
User-Agent: snom360/7.3.30
Accept: application/sdp
Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO
Allow-Events: talk, hold, refer, call-info
Supported: timer, 100rel, replaces, from-change
Session-Expires: 3600;refresher=uas
Min-SE: 90
Content-Type: application/sdp
Content-Length: 452

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

Unauthorized:

--- (19 headers 18 lines) ---
Sending to 172.16.23.60:2112 (NAT)
[Aug 27 22:20:37] NOTICE[6200][C-00000003]: chan_sip.c:26269 handle_request_invite: Trying to pick up 62 at phones
Sending to 172.16.23.60:2112 (NAT)
Using INVITE request as basis request - 3c953745720b-p5q7kgcj604q
Found peer '60' for '60' from 172.16.23.60:2112

<--- Reliably Transmitting (NAT) to 172.16.23.60:2112 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 172.16.23.60:2112;branch=z9hG4bK-pb8ywn90vhet;received=172.16.23.60;rport=2112
From: "HFO" <sip:60 at 172.16.4.100>;tag=omy5lrfdik
To: <sip:01721234567 at 172.16.4.100>;tag=as36a783db
Call-ID: 3c953745720b-p5q7kgcj604q
CSeq: 1 INVITE
Server: Asterisk PBX 15.5.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="5835824d"
Content-Length: 0

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

Ahh, okay

<--- SIP read from UDP:172.16.23.60:2112 --->
ACK sip:01721234567 at 172.16.4.100 SIP/2.0
Via: SIP/2.0/UDP 172.16.23.60:2112;branch=z9hG4bK-pb8ywn90vhet;rport
From: "HFO" <sip:60 at 172.16.4.100>;tag=omy5lrfdik
To: <sip:01721234567 at 172.16.4.100>;tag=as36a783db
Call-ID: 3c953745720b-p5q7kgcj604q
CSeq: 1 ACK
Max-Forwards: 70
Contact: <sip:60 at 172.16.23.60:2112>;reg-id=1
Content-Length: 0

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

You want auth, you get auth:

<--- SIP read from UDP:172.16.23.60:2112 --->
INVITE sip:01721234567 at 172.16.4.100 SIP/2.0
Via: SIP/2.0/UDP 172.16.23.60:2112;branch=z9hG4bK-zbjhw9im94ce;rport
From: "HFO" <sip:60 at 172.16.4.100>;tag=omy5lrfdik
To: <sip:01721234567 at 172.16.4.100>
Call-ID: 3c953745720b-p5q7kgcj604q
CSeq: 2 INVITE
Max-Forwards: 70
Contact: <sip:60 at 172.16.23.60:2112>;reg-id=1
Replaces: pickup-3c95372c15b1-uz42rw4w6sy9;to-tag=as40973611;from-tag=ebsb74m178
P-Key-Flags: resolution="31x13", keys="4"
User-Agent: snom360/7.3.30
Accept: application/sdp
Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO
Allow-Events: talk, hold, refer, call-info
Supported: timer, 100rel, replaces, from-change
Session-Expires: 3600;refresher=uas
Min-SE: 90
Authorization: Digest username="60",realm="asterisk",nonce="5835824d",uri="sip:01721234567 at 172.16.4.100",response="d7b5ae311ffa0c9f41154f952600220e",algorithm=MD5
Content-Type: application/sdp
Content-Length: 452

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

Figure out RTP parameter:

--- (20 headers 18 lines) ---
[Aug 27 22:20:37] NOTICE[6200][C-00000003]: chan_sip.c:26269 handle_request_invite: Trying to pick up 62 at phones
Sending to 172.16.23.60:2112 (NAT)
Using INVITE request as basis request - 3c953745720b-p5q7kgcj604q
Found peer '60' for '60' from 172.16.23.60:2112
  == Using SIP RTP CoS mark 5
Found RTP audio format 9
Found RTP audio format 0
Found RTP audio format 8
Found RTP audio format 3
Found RTP audio format 18
Found RTP audio format 4
Found RTP audio format 99
Found RTP audio format 101
[Aug 27 22:20:37] NOTICE[6200][C-00000003]: chan_sip.c:10742 process_sdp: Processed audio crypto attribute without SAVP specified; accepting anyway
Found audio description format g722 for ID 9
Found audio description format pcmu for ID 0
Found audio description format pcma for ID 8
Found audio description format gsm for ID 3
Found audio description format g729 for ID 18
Found audio description format g723 for ID 4
Found audio description format g726-32 for ID 99
Found audio description format telephone-event for ID 101
Capabilities: us - (alaw|ulaw|gsm), peer - audio=(ulaw|gsm|g723|alaw|g722|g729|g726)/video=(nothing)/text=(nothing), combined - (alaw|ulaw|gsm)
Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x1 (telephone-event|), combined - 0x0 (nothing)
       > 0x7f0fc405ecf0 -- Strict RTP learning after remote address set to: 172.16.23.60:54560
Peer audio RTP is at port 172.16.23.60:54560
Looking for 01721234567 in phones (domain 172.16.4.100)
sip_route_dump: route/path hop: <sip:60 at 172.16.23.60:2112>

Why asterisk is looking up the external caller in phones?

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

Let's talk together:

<--- Transmitting (NAT) to 172.16.23.60:2112 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.16.23.60:2112;branch=z9hG4bK-zbjhw9im94ce;received=172.16.23.60;rport=2112
From: "HFO" <sip:60 at 172.16.4.100>;tag=omy5lrfdik
To: <sip:01721234567 at 172.16.4.100>
Call-ID: 3c953745720b-p5q7kgcj604q
CSeq: 2 INVITE
Server: Asterisk PBX 15.5.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:01721234567 at 172.16.4.100:5060>
Content-Length: 0

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

Here it goes south: No target channel found for 62 at phones

[Aug 27 22:20:37] NOTICE[6200][C-00000003]: app_directed_pickup.c:365 pickup_exec: No target channel found for 62 at phones.
Scheduling destruction of SIP dialog '3c953745720b-p5q7kgcj604q' in 32000 ms (Method: INVITE)
Reliably Transmitting (NAT) to 172.16.23.60:2112:
NOTIFY sip:60 at 172.16.23.60:2112 SIP/2.0
Via: SIP/2.0/UDP 172.16.4.100:5060;branch=z9hG4bK126d8508;rport
Max-Forwards: 70
From: <sip:60 at 172.16.4.100;user=phone>;tag=as06a1662e
To: <sip:60 at 172.16.4.100>;tag=9ce2167e53
Contact: <sip:60 at 172.16.4.100:5060>
Call-ID: 3c95372c0a95-8efi7mvgrsud
CSeq: 104 NOTIFY
User-Agent: Asterisk PBX 15.5.0
Subscription-State: active
Event: dialog
Content-Type: application/dialog-info+xml
Content-Length: 200

<?xml version="1.0"?>
<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="2" state="full" entity="sip:60 at 172.16.4.100">
<dialog id="60">
<state>confirmed</state>
</dialog>
</dialog-info>

---

Game over:

<--- Reliably Transmitting (NAT) to 172.16.23.60:2112 --->
SIP/2.0 603 Declined
Via: SIP/2.0/UDP 172.16.23.60:2112;branch=z9hG4bK-zbjhw9im94ce;received=172.16.23.60;rport=2112
From: "HFO" <sip:60 at 172.16.4.100>;tag=omy5lrfdik
To: <sip:01721234567 at 172.16.4.100>;tag=as19bd5d41
Call-ID: 3c953745720b-p5q7kgcj604q
CSeq: 2 INVITE
Server: Asterisk PBX 15.5.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Content-Length: 0

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

It should work as such, but doesn't.

Any ideas are much appreciated.

Pete