Trying and ACK udp SIP packets ignored on call transfer (pjsip)

hofmanndavid · October 23, 2018, 1:43am

Bear with me please . I need to understand what I don’t understand yet. I am including my extensions.conf pjsip.conf a tcpdump and asterisk cli debug on the call transfer.

I see that asterisk is ignoring the trying and ack SIP packets from vbox endpoint and thus issuing re-invites. I say it is ignoring because I see those packets but somehow I am not configuring the endpoint correctly so that asterisk can recognize them.

I have cisco(62.15.164.62) -> asterisk(62.12.240.121) -> vbox(62.15.164.65)

So what happens is that a phone initiated call is setup and asterisk does some AGI handling

IP 62.15.164.62.61396 > 62.12.240.121.sip: UDP, length 1159
E..........v>..>>..y........INVITE sip:7010@62.12.240.121:5060 SIP/2.0
Via: SIP/2.0/UDP  62.15.164.62:5060;branch=z9hG4bK4CB8B17BE
From: <sip:0971110799@62.15.164.62>;tag=BD15CD5C-FC6
To: <sip:7010@62.12.240.121>
Date: Tue, 23 Oct 2018 02:00:59 GMT
Call-ID: 524DB3FB-D59E11E8-AAA1E790-46F000BF@62.15.164.62
Supported: 100rel,timer,replaces
Min-SE:  1800
Cisco-Guid: 1380744107-3583906280-2679701539-3944536960
User-Agent: Cisco-SIPGateway/IOS-12.x
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
CSeq: 101 INVITE
Max-Forwards: 70
Remote-Party-ID: <sip:0971110799@62.15.164.62>;party=calling;screen=yes;privacy=off
Timestamp: 1540260059
Contact: <sip:0971110799@62.15.164.62:5060>
Call-Info: <sip:62.15.164.62:5060>;method="NOTIFY;Event=telephone-event;Duration=2000"
Expires: 180
Allow-Events: telephone-event
Content-Type: application/sdp
Content-Length: 247

v=0
o=CiscoSystemsSIP-GW-UserAgent 1066 6200 IN IP4 62.15.164.62
s=SIP Call
c=IN IP4 62.15.164.62
t=0 0
m=audio 16658 RTP/AVP 0 101
c=IN IP4 62.15.164.62
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

IP 62.12.240.121.sip > 62.15.164.62.61396: UDP, length 326
E..bD.@.@...>..y>..>.....N.3SIP/2.0 100 Trying
Via: SIP/2.0/UDP 62.15.164.62:5060;rport=61396;received=62.15.164.62;branch=z9hG4bK4CB8B17BE
Call-ID: 524DB3FB-D59E11E8-AAA1E790-46F000BF@62.15.164.62
From: <sip:0971110799@62.15.164.62>;tag=BD15CD5C-FC6
To: <sip:7010@62.12.240.121>
CSeq: 101 INVITE
Server: Asterisk PBX 15.5.0
Content-Length:  0


IP 62.12.240.121.sip > 62.15.164.62.61396: UDP, length 818
E..ND.@.@...>..y>..>.....:..SIP/2.0 200 OK
Via: SIP/2.0/UDP 62.15.164.62:5060;rport=61396;received=62.15.164.62;branch=z9hG4bK4CB8B17BE
Call-ID: 524DB3FB-D59E11E8-AAA1E790-46F000BF@62.15.164.62
From: <sip:0971110799@62.15.164.62>;tag=BD15CD5C-FC6
To: <sip:7010@62.12.240.121>;tag=3780211b-39df-482f-8b48-b0ca039a65b2
CSeq: 101 INVITE
Server: Asterisk PBX 15.5.0
Contact: <sip:62.12.240.121:5060>
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Content-Type: application/sdp
Content-Length:   227

v=0
o=- 1066 6202 IN IP4 62.12.240.121
s=Asterisk
c=IN IP4 62.12.240.121
t=0 0
m=audio 26188 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

IP 62.15.164.62.61396 > 62.12.240.121.sip: UDP, length 371
E...........>..>>..y.....{.3ACK sip:62.12.240.121:5060 SIP/2.0
Via: SIP/2.0/UDP  62.15.164.62:5060;branch=z9hG4bK4CB8CF50
From: <sip:0971110799@62.15.164.62>;tag=BD15CD5C-FC6
To: <sip:7010@62.12.240.121>;tag=3780211b-39df-482f-8b48-b0ca039a65b2
Date: Tue, 23 Oct 2018 02:00:59 GMT
Call-ID: 524DB3FB-D59E11E8-AAA1E790-46F000BF@62.15.164.62
Max-Forwards: 70
CSeq: 101 ACK
Content-Length: 0

On the CLI

 == Setting global variable 'SIPDOMAIN' to '62.12.240.121'
    -- Executing [7010@civr:1] Answer("PJSIP/gw1-00000022", "") in new stack
       > 0x7f707c019640 -- Strict RTP learning after remote address set to: 62.15.164.62:16658


       > 0x7f707c019640 -- Strict RTP switching to RTP target address 62.15.164.62:16658 as source
    -- Executing [7010@civr:2] Log("PJSIP/gw1-00000022", "CALLER Id all: "" <0971110799>") in new stack
[Oct 22 21:20:39] ERROR[62669][C-00000012]: app_verbose.c:138 log_exec: Unknown log level: 'CALLER Id all:  <0971110799>'
    -- Executing [7010@civr:3] Log("PJSIP/gw1-00000022", "Caller Id num: 0971110799") in new stack
[Oct 22 21:20:39] ERROR[62669][C-00000012]: app_verbose.c:138 log_exec: Unknown log level: 'Caller Id num: 0971110799'
    -- Executing [7010@civr:4] GotoIf("PJSIP/gw1-00000022", "1?proceed") in new stack
    -- Goto (civr,7010,8)
    -- Executing [7010@civr:8] AGI("PJSIP/gw1-00000022", "/var/www/agi-bin/agi.php") in new stack
    -- Launched AGI Script /var/www/agi-bin/agi.php
<PJSIP/gw1-00000022>AGI Tx >> agi_request: /var/www/agi-bin/agi.php
<PJSIP/gw1-00000022>AGI Tx >> agi_channel: PJSIP/gw1-00000022
<PJSIP/gw1-00000022>AGI Tx >> agi_language: en
<PJSIP/gw1-00000022>AGI Tx >> agi_type: PJSIP
<PJSIP/gw1-00000022>AGI Tx >> agi_uniqueid: 1540257639.63
<PJSIP/gw1-00000022>AGI Tx >> agi_version: 15.5.0
<PJSIP/gw1-00000022>AGI Tx >> agi_callerid: 0971110799
<PJSIP/gw1-00000022>AGI Tx >> agi_calleridname: unknown
<PJSIP/gw1-00000022>AGI Tx >> agi_callingpres: 0
<PJSIP/gw1-00000022>AGI Tx >> agi_callingani2: 0
<PJSIP/gw1-00000022>AGI Tx >> agi_callington: 0
<PJSIP/gw1-00000022>AGI Tx >> agi_callingtns: 0
<PJSIP/gw1-00000022>AGI Tx >> agi_dnid: 7010
<PJSIP/gw1-00000022>AGI Tx >> agi_rdnis: unknown
<PJSIP/gw1-00000022>AGI Tx >> agi_context: civr
<PJSIP/gw1-00000022>AGI Tx >> agi_extension: 7010
<PJSIP/gw1-00000022>AGI Tx >> agi_priority: 8
<PJSIP/gw1-00000022>AGI Tx >> agi_enhanced: 0.0
<PJSIP/gw1-00000022>AGI Tx >> agi_accountcode:
<PJSIP/gw1-00000022>AGI Tx >> agi_threadid: 140122966906624
<PJSIP/gw1-00000022>AGI Tx >>
<PJSIP/gw1-00000022>AGI Rx << STREAM FILE /tmp/fest-yVABhE ""
    -- <PJSIP/gw1-00000022> Playing '/tmp/fest-yVABhE.slin' (escape_digits=) (sample_offset 0) (language 'en')
       > 0x7f707c019640 -- Strict RTP learning complete - Locking on source address 62.15.164.62:16658
<PJSIP/gw1-00000022>AGI Tx >> 200 result=0 endpos=47554
<PJSIP/gw1-00000022>AGI Rx << STREAM FILE /tmp/fest-9pPsxq "1234"
    -- <PJSIP/gw1-00000022> Playing '/tmp/fest-9pPsxq.slin' (escape_digits=1234) (sample_offset 0) (language 'en')
<PJSIP/gw1-00000022>AGI Tx >> 200 result=50 endpos=21920
<PJSIP/gw1-00000022>AGI Rx << STREAM FILE /tmp/fest-zztyOj "12"
    -- <PJSIP/gw1-00000022> Playing '/tmp/fest-zztyOj.slin' (escape_digits=12) (sample_offset 0) (language 'en')
<PJSIP/gw1-00000022>AGI Tx >> 200 result=49 endpos=12320
<PJSIP/gw1-00000022>AGI Rx << STREAM FILE /tmp/fest-FyUq0g "#*0123456789"
    -- <PJSIP/gw1-00000022> Playing '/tmp/fest-FyUq0g.slin' (escape_digits=#*0123456789) (sample_offset 0) (language 'en')
<PJSIP/gw1-00000022>AGI Tx >> 200 result=56 endpos=13440
<PJSIP/gw1-00000022>AGI Rx << WAIT FOR DIGIT 2000
<PJSIP/gw1-00000022>AGI Tx >> 200 result=53
<PJSIP/gw1-00000022>AGI Rx << WAIT FOR DIGIT 2000
<PJSIP/gw1-00000022>AGI Tx >> 200 result=55
<PJSIP/gw1-00000022>AGI Rx << WAIT FOR DIGIT 2000
<PJSIP/gw1-00000022>AGI Tx >> 200 result=55
<PJSIP/gw1-00000022>AGI Rx << WAIT FOR DIGIT 2000
<PJSIP/gw1-00000022>AGI Tx >> 200 result=55
<PJSIP/gw1-00000022>AGI Rx << WAIT FOR DIGIT 2000
<PJSIP/gw1-00000022>AGI Tx >> 200 result=53
<PJSIP/gw1-00000022>AGI Rx << WAIT FOR DIGIT 2000
<PJSIP/gw1-00000022>AGI Tx >> 200 result=0
<PJSIP/gw1-00000022>AGI Rx << SET CONTEXT call_center_altitude
<PJSIP/gw1-00000022>AGI Tx >> 200 result=0
<PJSIP/gw1-00000022>AGI Rx << SET CALLERID 00008577751000971110799
<PJSIP/gw1-00000022>AGI Tx >> 200 result=1
<PJSIP/gw1-00000022>AGI Rx << SET EXTENSION 1
<PJSIP/gw1-00000022>AGI Tx >> 200 result=0
<PJSIP/gw1-00000022>AGI Rx << SET PRIORITY 1
<PJSIP/gw1-00000022>AGI Tx >> 200 result=0
<PJSIP/gw1-00000022>AGI Rx << STREAM FILE /tmp/fest-e3ELZu ""
    -- <PJSIP/gw1-00000022> Playing '/tmp/fest-e3ELZu.slin' (escape_digits=) (sample_offset 0) (language 'en')
<PJSIP/gw1-00000022>AGI Tx >> 200 result=0 endpos=34697
    -- <PJSIP/gw1-00000022>AGI Script /var/www/agi-bin/agi.php completed, returning 0
    -- Executing [1@call_center_altitude:1] Dial("PJSIP/gw1-00000022", "PJSIP/vbox") in new stack
    -- Called PJSIP/vbox

Then on the CLI this invite is repeated until the call is dropped after some 30 secs

<--- Transmitting SIP request (1068 bytes) to UDP:62.15.164.65:5060 --->
INVITE sip:7011@62.15.164.65:5060 SIP/2.0
Via: SIP/2.0/UDP 62.12.240.121:5060;rport;branch=z9hG4bKPj702bedc6-b346-44b2-8cc1-bbdffcb75a89
From: <sip:00008577751000971110799@62.12.240.121>;tag=b2e6cd02-127c-42ca-a51a-f98cb26329aa
To: <sip:7011@62.15.164.65>
Contact: <sip:asterisk@62.12.240.121:5060>
Call-ID: 6de2b47c-8264-452a-9656-d7d4ed6b731f
CSeq: 11604 INVITE
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Session-Expires: 1800
Min-SE: 90
Remote-Party-ID: <sip:00008577751000971110799@62.12.240.121>;privacy=off;screen=no
Max-Forwards: 70
User-Agent: Asterisk PBX 15.5.0
Content-Type: application/sdp
Content-Length:   312

v=0
o=- 272899537 272899537 IN IP4 62.12.240.121
s=Asterisk
c=IN IP4 62.12.240.121
t=0 0
m=audio 21388 RTP/AVP 0 8 3 110 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:110 speex/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:60
a=sendrecv

After some re-invites and some 30 secs the call is dropped

  == Everyone is busy/congested at this time (1:0/0/1)
    -- Executing [1@call_center_altitude:2] Hangup("PJSIP/gw1-00000022", "") in new stack
  == Spawn extension (call_center_altitude, 1, 2) exited non-zero on 'PJSIP/gw1-00000022'

However, soing tcpdump does show that the endpoint vbox wants to accept the call

IP 62.15.164.65.sip > 62.12.240.121.58140: UDP, length 564
E..P....?...>..A>..y.....<qqSIP/2.0 100 Trying
Via: SIP/2.0/UDP 62.12.240.121:5060;branch=z9hG4bKPj702bedc6-b346-44b2-8cc1-bbdffcb75a89;received=62.12.240.121;rport=58140
From: <sip:00008577751000971110799@62.12.240.121>;tag=b2e6cd02-127c-42ca-a51a-f98cb26329aa
To: <sip:7011@62.15.164.65>
Call-ID: 6de2b47c-8264-452a-9656-d7d4ed6b731f
CSeq: 11604 INVITE
Server: Altitude vBox
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:7011@62.15.164.65:5060>
Content-Length: 0


IP 62.15.164.65.sip > 62.12.240.121.58140: UDP, length 859
E..w....?...>..A>..y.....c.`SIP/2.0 200 OK
Via: SIP/2.0/UDP 62.12.240.121:5060;branch=z9hG4bKPj702bedc6-b346-44b2-8cc1-bbdffcb75a89;received=62.12.240.121;rport=58140
From: <sip:00008577751000971110799@62.12.240.121>;tag=b2e6cd02-127c-42ca-a51a-f98cb26329aa
To: <sip:7011@62.15.164.65>;tag=as1dce0520
Call-ID: 6de2b47c-8264-452a-9656-d7d4ed6b731f
CSeq: 11604 INVITE
Server: Altitude vBox
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:7011@62.15.164.65:5060>
Content-Type: application/sdp
Content-Length: 251

v=0
o=root 140358089 140358089 IN IP4 62.15.164.65
s=Altitude vBox
c=IN IP4 62.15.164.65
t=0 0
m=audio 25364 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

However those packets are not picked up in the asterisk CLI.

My pjsip.conf

[t-udp-m]
type=transport
protocol=udp
bind=62.12.240.121:5060

[gw1]
type=endpoint
transport=t-udp-m
context=civr
disallow=all
allow=ulaw,speex,gsm
aors=gw1

[gw1]
type=identify
endpoint=gw1
match=62.15.164.62

[gw1]
type=aor
max_contacts=2
remove_existing=yes

[vbox]
type=endpoint
transport=t-udp-m
context=civr
disallow=all
allow=ulaw,alaw,gsm,speex
aors=vbox
send_rpid=yes 

[vbox]
type=identify
endpoint=vbox
match=62.15.164.65

[vbox]
type=aor
; qualify_frequency=0
contact=sip:7011@62.15.164.65:5060
max_contacts=1
remove_existing=yes

extensions.conf

[civr]
exten => 7010,1,Answer()
 same => n,Agi(/var/www/agi-bin/agi.php)
 same => n,Hangup()

[call_center_altitude]
exten => 1,1,Dial(PJSIP/vbox)
 same => n,Hangup()

Oh my. I pay you if you can help me solve this.

jcolp · October 23, 2018, 9:29am

Are you sure that a firewall or something isn’t blocking the traffic? The output of “pjsip set logger on” occurs straight from the socket we read data from, before anything really happens. If it doesn’t show up there then the application never got it.

david551 · October 23, 2018, 9:42am

The remote log shows the responses being sent to the wrong port number. I suspect something is NATting the port numbers but failing to reverse the process for the response.

Also, wheat you refer to as Re-INVITEs are not ReINVITEs, they are retransmissions of the initial INVITE. Re-INVITEs will have a To tag and a different CSEQ, and cannot be sent before the OK is accepted.

hofmanndavid · October 23, 2018, 11:01am

The TCPDUMP shown is on the asterisk(62.12.240.121) server that is supposed to receive the TRYING ad OK. Both the cli shows the invite but it does not get the trying and ack that are shown in the tcpdump

tcpdump -nqt -s 0 -A -i eth0 port 5060

where eth0 is the interface that has the IP 62.12.240.121
This is why I suspect there could not be a firewall issue. Is the reasoning correct?

hofmanndavid · October 23, 2018, 11:03am

tcpdump log is NOT remote, is on the same asterisk which CLI does not show the trying/ack. And because I listen to the port 5060 why would you conclude it is received at the wrong port number?
I think think the source port is making the confusion there because the destination port logged by tcpdump is 5060

Sorry about the re-invite confusion. It’s a retransmission of the same initial invite then.

jcolp · October 23, 2018, 11:16am

Because the tcpdump shows the wrong port:

IP 62.15.164.65.sip > 62.12.240.121.58140: UDP, length 564

That is a packet from IP address 62.15.164.65 port 5060, to IP address 62.12.240.121 port 58140

You can also see in the SIP traffic itself:

Via: SIP/2.0/UDP 62.12.240.121:5060;branch=z9hG4bKPj702bedc6-b346-44b2-8cc1-bbdffcb75a89;received=62.12.240.121;rport=58140

That the source IP address and port of the INVITE was 62.12.240.121 port 58140, so responses were sent there.

hofmanndavid · October 23, 2018, 11:22am

Thanks @jcolp I’ll look there. I was apparently reading the tcpdump wrong.
Could this be a Firewall or NAT issue?
I’ll post any update on further testings.

jcolp · October 23, 2018, 11:22am

Yes, it could be NAT changing the source address.

hofmanndavid · October 23, 2018, 2:05pm

Thanks!

as you mentioned the problem was a related to NAT and routing.

It’s working as expected.

Topic		Replies	Views
PJSIP : Expected ACK not send Asterisk SIP	12	1910	March 25, 2020
No inbound calls; sip INVITE not handled by asterisk Asterisk SIP	4	181	April 17, 2024
PJSIP in Asterisk 20 and Grandstream phone issue Asterisk SIP	2	112	August 14, 2024
Asterisk doesn't recognize INVITE Asterisk SIP	6	1848	May 14, 2019
PJSIP Configuration - Trunk + Endpoints Asterisk Support	3	1445	July 8, 2015

Trying and ACK udp SIP packets ignored on call transfer (pjsip)

Related topics