Duplicate SIP Messages

For some reason I am getting duplicates in the SIP signalling. Whilst it does appear work, its very strange and I would like to resolve it. This is occuring when simply calling internal extensions as well as external resources via trunks in sip.conf. You can see in the trace it sends an INVITE and then immediately ‘Retransmitting #1’ of the same packet with no change and no reasoning

  == Using SIP RTP CoS mark 5
       > 0x7f84f0062780 -- Strict RTP learning after remote address set to: 10.100.255.98:4018
[Apr 21 16:46:03] NOTICE[19959]: chan_sip.c:30620 sip_poke_peer: Still have a QUALIFY dialog active, deleting
    -- Executing [123@access-level3:1] Dial("SIP/200700-00000012", "SIP/helpdesksipivr/422125") in new stack
  == Using SIP RTP CoS mark 5
Audio is at 11240
Adding codec alaw to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (no NAT) to 10.102.96.95:5060:
INVITE sip:422125@10.102.96.95:5060 SIP/2.0
Via: SIP/2.0/UDP 10.102.0.143:5060;branch=z9hG4bK20be8a9f
Max-Forwards: 70
From: "Daniel Smith Test" <sip:200700@100.100.0.143>;tag=as6688fa3c
To: <sip:422125@100.100.96.95:5060>
Contact: <sip:200700@100.100.0.143:5060>
Call-ID: 73b788ef64989e177ea68d0c3e9bc907@100.100.0.143:5060
CSeq: 102 INVITE
User-Agent: Test PABX AU
Date: Thu, 21 Apr 2022 06:46:03 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 245

v=0
o=root 588390985 588390985 IN IP4 100.100.0.143
s=Test PABX AU
c=IN IP4 10.100.255.98
t=0 0
m=audio 4018 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

---
    -- Called SIP/helpdesksipivr/422125
Retransmitting #1 (no NAT) to 100.100.96.95:5060:
INVITE sip:422125@100.100.96.95:5060 SIP/2.0
Via: SIP/2.0/UDP 100.100.0.143:5060;branch=z9hG4bK20be8a9f
Max-Forwards: 70
From: "Daniel Smith Test" <sip:200700@100.100.0.143>;tag=as6688fa3c
To: <sip:422125@100.100.96.95:5060>
Contact: <sip:200700@100.100.0.143:5060>
Call-ID: 73b788ef64989e177ea68d0c3e9bc907@100.100.0.143:5060
CSeq: 102 INVITE
User-Agent: Test PABX AU
Date: Thu, 21 Apr 2022 06:46:03 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 245

v=0
o=root 588390985 588390985 IN IP4 100.100.0.143
s=Test PABX AU
c=IN IP4 10.100.255.98
t=0 0
m=audio 4018 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

---

Dialplan
‘123’ => 1. Dial(SIP/helpdesksipivr/422125) [extensions-custom.conf:519]
or
exten => 123,1,Dial(SIP/pma4vmlupdsco01/422125)

sip.conf
[general]
disallow=all
allow=alaw

context=invalid
subscribecontext=phones-pres
callcounter=yes
useragent=Test PABX AU
sdpsession=Test PABX AU

allowguest=no
allowoverlap=no

udpbindaddr=0.0.0.0
tcpenable=no
transport=udp

qualify=yes
srvlookup=no

nat=no
directmedia=yes
directrtpsetup=yes

rtcachefriends=yes
rtupdate=yes
rtautoclear=yes

[helpdesksipivr]
type=peer
host=100.100.96.95
port=5060
context=from-cisco
disallow=all
allow=alaw
qualify=yes
insecure=port,invite
nat=no

It could be a simple timing problem. I have a couple of older WiFi devices that show retransmissions once in a while, whereas new deskphones with cables almost never show that behavior. It could also be that on of the devices is too busy to answer in time. Without further info, this is difficult to diagnose.

This is how SIP behaves when packets are lost or arrive too late. You haven’t provided timing information either in our message sequence chart or your logs (don’t screen scrape logs, as, by default, they lack a lot of timing information).

From which packets are repeated, I would say this is a case of lost, rather than delayed, packets, e.g. there would have been two ACKs to the 401, if the first 401 was just delayed.

Also note that chan_sip is no longer supported, and will be removed next year.

Oh right sorry here is sngrep with timings
timer1 = 500
timerb = 32000
second leg is ~150ms away

<------------->
[Apr 22 09:58:00] VERBOSE[19959] chan_sip.c: --- (13 headers 0 lines) ---
[Apr 22 09:58:00] VERBOSE[19959] chan_sip.c: Really destroying SIP dialog '22b21cf5136d19f84ee04ce4001e0cf5@10.102.0.143:5060' Method: OPTIONS
[2022-04-22 09:58:04.719] Asterisk 18.11.1 built by root @ asterisk-ubuntu-new on a x86_64 running Linux on 2022-04-06 06:50:03 UTC
[Apr 22 09:58:04] VERBOSE[10053] loader.c: Reloading module 'logger' (Logger)
[2022-04-22 09:58:04.719] VERBOSE[10053] logger.c: Asterisk Queue Logger restarted
[2022-04-22 09:58:05.314] VERBOSE[10053] asterisk.c: Remote UNIX connection disconnected
[2022-04-22 09:58:18.666] VERBOSE[19959][C-00000017] netsock2.c: Using SIP RTP CoS mark 5
[2022-04-22 09:58:18.667] VERBOSE[19959][C-00000017] res_rtp_asterisk.c: 0x7f84f00651a0 -- Strict RTP learning after remote address set to: 10.100.255.98:4006
[2022-04-22 09:58:18.667] NOTICE[19959] chan_sip.c: Still have a QUALIFY dialog active, deleting
[2022-04-22 09:58:18.668] VERBOSE[10057][C-00000017] pbx.c: Executing [123@access-level3:1] Dial("SIP/200700-0000001e", "SIP/helpdesk-ubuntu/422125") in new stack
[2022-04-22 09:58:18.669] VERBOSE[10057][C-00000017] netsock2.c: Using SIP RTP CoS mark 5
[2022-04-22 09:58:18.670] VERBOSE[10057][C-00000017] chan_sip.c: Audio is at 18228
[2022-04-22 09:58:18.670] VERBOSE[10057][C-00000017] chan_sip.c: Adding codec alaw to SDP
[2022-04-22 09:58:18.670] VERBOSE[10057][C-00000017] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[2022-04-22 09:58:18.671] VERBOSE[10057][C-00000017] chan_sip.c: Reliably Transmitting (no NAT) to 10.102.96.95:5060:
INVITE sip:422125@10.102.96.95:5060 SIP/2.0
Via: SIP/2.0/UDP 10.102.0.143:5060;branch=z9hG4bK0ec77795
Max-Forwards: 70
From: "Daniel Smith Test" <sip:200700@10.102.0.143>;tag=as215a4017
To: <sip:422125@10.102.96.95:5060>
Contact: <sip:200700@10.102.0.143:5060>
Call-ID: 3e3bcecf080f86ba35d659043b9ddeec@10.102.0.143:5060
CSeq: 102 INVITE
User-Agent: Test PABX AU
Date: Thu, 21 Apr 2022 23:58:18 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 245

v=0
o=root 381049237 381049237 IN IP4 10.102.0.143
s=Test PABX AU
c=IN IP4 10.100.255.98
t=0 0
m=audio 4006 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

---
[2022-04-22 09:58:18.673] VERBOSE[10057][C-00000017] app_dial.c: Called SIP/helpdesk-ubuntu/422125
[2022-04-22 09:58:18.822] VERBOSE[19959] chan_sip.c: Retransmitting #1 (no NAT) to 10.102.96.95:5060:
INVITE sip:422125@10.102.96.95:5060 SIP/2.0
Via: SIP/2.0/UDP 10.102.0.143:5060;branch=z9hG4bK0ec77795
Max-Forwards: 70
From: "Daniel Smith Test" <sip:200700@10.102.0.143>;tag=as215a4017
To: <sip:422125@10.102.96.95:5060>
Contact: <sip:200700@10.102.0.143:5060>
Call-ID: 3e3bcecf080f86ba35d659043b9ddeec@10.102.0.143:5060
CSeq: 102 INVITE
User-Agent: Test PABX AU
Date: Thu, 21 Apr 2022 23:58:18 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 245

v=0
o=root 381049237 381049237 IN IP4 10.102.0.143
s=Test PABX AU
c=IN IP4 10.100.255.98
t=0 0
m=audio 4006 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

---
[2022-04-22 09:58:18.825] VERBOSE[19959] chan_sip.c: 
<--- SIP read from UDP:10.102.96.95:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.102.0.143:5060;branch=z9hG4bK0ec77795
From: "Daniel Smith Test" <sip:200700@10.102.0.143>;tag=as215a4017
To: <sip:422125@10.102.96.95:5060>
Call-ID: 3e3bcecf080f86ba35d659043b9ddeec@10.102.0.143:5060
CSeq: 102 INVITE
User-Agent: FreeSWITCH-Test
Content-Length: 0

<------------->
[2022-04-22 09:58:18.826] VERBOSE[19959] chan_sip.c: --- (8 headers 0 lines) ---
[2022-04-22 09:58:18.828] VERBOSE[19959] chan_sip.c: 
<--- SIP read from UDP:10.102.96.95:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.102.0.143:5060;branch=z9hG4bK0ec77795
From: "Daniel Smith Test" <sip:200700@10.102.0.143>;tag=as215a4017
To: <sip:422125@10.102.96.95:5060>;tag=714v0Nvyt00Sa
Call-ID: 3e3bcecf080f86ba35d659043b9ddeec@10.102.0.143:5060
CSeq: 102 INVITE
Contact: <sip:422125@10.102.96.95:5060;transport=udp>
User-Agent: FreeSWITCH-Test
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 247
Remote-Party-ID: "422125" <sip:422125@10.102.96.95>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1650572442 1650572443 IN IP4 10.102.96.95
s=FreeSWITCH
c=IN IP4 10.102.96.95
t=0 0
m=audio 13056 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
<------------->
[2022-04-22 09:58:18.829] VERBOSE[19959] chan_sip.c: --- (16 headers 11 lines) ---
[2022-04-22 09:58:18.829] VERBOSE[19959][C-00000017] chan_sip.c: Got SDP version 1650572443 and unique parts [FreeSWITCH 1650572442 IN IP4 10.102.96.95]
[2022-04-22 09:58:18.830] VERBOSE[19959][C-00000017] chan_sip.c: Found RTP audio format 8
[2022-04-22 09:58:18.830] VERBOSE[19959][C-00000017] chan_sip.c: Found RTP audio format 101
[2022-04-22 09:58:18.830] VERBOSE[19959][C-00000017] chan_sip.c: Found audio description format PCMA for ID 8
[2022-04-22 09:58:18.830] VERBOSE[19959][C-00000017] chan_sip.c: Found audio description format telephone-event for ID 101
[2022-04-22 09:58:18.830] VERBOSE[19959][C-00000017] chan_sip.c: Capabilities: us - (alaw), peer - audio=(alaw)/video=(nothing)/text=(nothing), combined - (alaw)
[2022-04-22 09:58:18.830] VERBOSE[19959][C-00000017] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[2022-04-22 09:58:18.830] VERBOSE[19959][C-00000017] res_rtp_asterisk.c: 0x7f8584015be0 -- Strict RTP learning after remote address set to: 10.102.96.95:13056
[2022-04-22 09:58:18.831] VERBOSE[19959][C-00000017] chan_sip.c: Peer audio RTP is at port 10.102.96.95:13056
[2022-04-22 09:58:18.831] VERBOSE[19959][C-00000017] sip/route.c: sip_route_dump: route/path hop: <sip:422125@10.102.96.95:5060;transport=udp>
[2022-04-22 09:58:18.831] VERBOSE[19959][C-00000017] chan_sip.c: set_destination: Parsing <sip:422125@10.102.96.95:5060;transport=udp> for address/port to send to
[2022-04-22 09:58:18.831] VERBOSE[19959][C-00000017] chan_sip.c: set_destination: set destination to 10.102.96.95:5060
[2022-04-22 09:58:18.831] VERBOSE[19959][C-00000017] chan_sip.c: Transmitting (no NAT) to 10.102.96.95:5060:
ACK sip:422125@10.102.96.95:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 10.102.0.143:5060;branch=z9hG4bK2ebd81eb
Max-Forwards: 70
From: "Daniel Smith Test" <sip:200700@10.102.0.143>;tag=as215a4017
To: <sip:422125@10.102.96.95:5060>;tag=714v0Nvyt00Sa
Contact: <sip:200700@10.102.0.143:5060>
Call-ID: 3e3bcecf080f86ba35d659043b9ddeec@10.102.0.143:5060
CSeq: 102 ACK
User-Agent: Test PABX AU
Content-Length: 0


---
[2022-04-22 09:58:18.832] VERBOSE[10057][C-00000017] app_dial.c: SIP/helpdesk-ubuntu-0000001f answered SIP/200700-0000001e
[2022-04-22 09:58:18.833] VERBOSE[10058][C-00000017] bridge_channel.c: Channel SIP/helpdesk-ubuntu-0000001f joined 'simple_bridge' basic-bridge <fe189437-1765-4eb0-bd56-4d8f2ad72e90>
[2022-04-22 09:58:18.833] VERBOSE[10057][C-00000017] bridge_channel.c: Channel SIP/200700-0000001e joined 'simple_bridge' basic-bridge <fe189437-1765-4eb0-bd56-4d8f2ad72e90>
[2022-04-22 09:58:18.834] VERBOSE[10057][C-00000017] bridge.c: Bridge fe189437-1765-4eb0-bd56-4d8f2ad72e90: switching from simple_bridge technology to native_rtp
[2022-04-22 09:58:18.834] VERBOSE[10057][C-00000017] bridge_native_rtp.c: Remotely bridged 'SIP/200700-0000001e' and 'SIP/helpdesk-ubuntu-0000001f' - media will flow directly between them
[2022-04-22 09:58:18.972] VERBOSE[19959] chan_sip.c: 
<--- SIP read from UDP:10.102.96.95:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.102.0.143:5060;branch=z9hG4bK0ec77795
From: "Daniel Smith Test" <sip:200700@10.102.0.143>;tag=as215a4017
To: <sip:422125@10.102.96.95:5060>;tag=714v0Nvyt00Sa
Call-ID: 3e3bcecf080f86ba35d659043b9ddeec@10.102.0.143:5060
CSeq: 102 INVITE
Contact: <sip:422125@10.102.96.95:5060;transport=udp>
User-Agent: FreeSWITCH-Test
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 247
Remote-Party-ID: "422125" <sip:422125@10.102.96.95>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1650572442 1650572443 IN IP4 10.102.96.95
s=FreeSWITCH
c=IN IP4 10.102.96.95
t=0 0
m=audio 13056 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
<------------->
[2022-04-22 09:58:18.973] VERBOSE[19959] chan_sip.c: --- (16 headers 11 lines) ---
[2022-04-22 09:58:18.973] VERBOSE[19959][C-00000017] chan_sip.c: set_destination: Parsing <sip:422125@10.102.96.95:5060;transport=udp> for address/port to send to
[2022-04-22 09:58:18.973] VERBOSE[19959][C-00000017] chan_sip.c: set_destination: set destination to 10.102.96.95:5060
[2022-04-22 09:58:18.973] VERBOSE[19959][C-00000017] chan_sip.c: Transmitting (no NAT) to 10.102.96.95:5060:
ACK sip:422125@10.102.96.95:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 10.102.0.143:5060;branch=z9hG4bK26485ab4
Max-Forwards: 70
From: "Daniel Smith Test" <sip:200700@10.102.0.143>;tag=as215a4017
To: <sip:422125@10.102.96.95:5060>;tag=714v0Nvyt00Sa
Contact: <sip:200700@10.102.0.143:5060>
Call-ID: 3e3bcecf080f86ba35d659043b9ddeec@10.102.0.143:5060
CSeq: 102 ACK
User-Agent: Test PABX AU
Content-Length: 0


---
[2022-04-22 09:58:21.609] VERBOSE[10057][C-00000017] bridge_channel.c: Channel SIP/200700-0000001e left 'native_rtp' basic-bridge <fe189437-1765-4eb0-bd56-4d8f2ad72e90>
[2022-04-22 09:58:21.609] VERBOSE[10057][C-00000017] chan_sip.c: set_destination: Parsing <sip:422125@10.102.96.95:5060;transport=udp> for address/port to send to
[2022-04-22 09:58:21.609] VERBOSE[10057][C-00000017] chan_sip.c: set_destination: set destination to 10.102.96.95:5060
[2022-04-22 09:58:21.609] VERBOSE[10057][C-00000017] chan_sip.c: Audio is at 18228
[2022-04-22 09:58:21.609] VERBOSE[10057][C-00000017] chan_sip.c: Adding codec alaw to SDP
[2022-04-22 09:58:21.609] VERBOSE[10057][C-00000017] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[2022-04-22 09:58:21.609] VERBOSE[10057][C-00000017] chan_sip.c: Reliably Transmitting (no NAT) to 10.102.96.95:5060:
INVITE sip:422125@10.102.96.95:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 10.102.0.143:5060;branch=z9hG4bK29b83c62
Max-Forwards: 70
From: "Daniel Smith Test" <sip:200700@10.102.0.143>;tag=as215a4017
To: <sip:422125@10.102.96.95:5060>;tag=714v0Nvyt00Sa
Contact: <sip:200700@10.102.0.143:5060>
Call-ID: 3e3bcecf080f86ba35d659043b9ddeec@10.102.0.143:5060
CSeq: 103 INVITE
User-Agent: Test PABX AU
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
X-asterisk-Info: SIP re-invite (External RTP bridge)
Content-Type: application/sdp
Content-Length: 245

v=0
o=root 381049237 381049238 IN IP4 10.102.0.143
s=Test PABX AU
c=IN IP4 10.102.0.143
t=0 0
m=audio 18228 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

---
[2022-04-22 09:58:21.609] VERBOSE[10058][C-00000017] bridge_channel.c: Channel SIP/helpdesk-ubuntu-0000001f left 'native_rtp' basic-bridge <fe189437-1765-4eb0-bd56-4d8f2ad72e90>
[2022-04-22 09:58:21.610] VERBOSE[10057][C-00000017] pbx.c: Spawn extension (access-level3, 123, 1) exited non-zero on 'SIP/200700-0000001e'
[2022-04-22 09:58:21.610] VERBOSE[10058][C-00000017] chan_sip.c: Scheduling destruction of SIP dialog '3e3bcecf080f86ba35d659043b9ddeec@10.102.0.143:5060' in 9600 ms (Method: INVITE)
[2022-04-22 09:58:21.759] VERBOSE[19959] chan_sip.c: Retransmitting #1 (no NAT) to 10.102.96.95:5060:
INVITE sip:422125@10.102.96.95:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 10.102.0.143:5060;branch=z9hG4bK29b83c62
Max-Forwards: 70
From: "Daniel Smith Test" <sip:200700@10.102.0.143>;tag=as215a4017
To: <sip:422125@10.102.96.95:5060>;tag=714v0Nvyt00Sa
Contact: <sip:200700@10.102.0.143:5060>
Call-ID: 3e3bcecf080f86ba35d659043b9ddeec@10.102.0.143:5060
CSeq: 103 INVITE
User-Agent: Test PABX AU
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
X-asterisk-Info: SIP re-invite (External RTP bridge)
Content-Type: application/sdp
Content-Length: 245

v=0
o=root 381049237 381049238 IN IP4 10.102.0.143
s=Test PABX AU
c=IN IP4 10.102.0.143
t=0 0
m=audio 18228 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

---
[2022-04-22 09:58:21.776] VERBOSE[19959] chan_sip.c: 
<--- SIP read from UDP:10.102.96.95:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.102.0.143:5060;branch=z9hG4bK29b83c62
From: "Daniel Smith Test" <sip:200700@10.102.0.143>;tag=as215a4017
To: <sip:422125@10.102.96.95:5060>;tag=714v0Nvyt00Sa
Call-ID: 3e3bcecf080f86ba35d659043b9ddeec@10.102.0.143:5060
CSeq: 103 INVITE
User-Agent: FreeSWITCH-Test
Content-Length: 0

<------------->
[2022-04-22 09:58:21.777] VERBOSE[19959] chan_sip.c: --- (8 headers 0 lines) ---
[2022-04-22 09:58:21.778] VERBOSE[19959] chan_sip.c: 
<--- SIP read from UDP:10.102.96.95:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.102.0.143:5060;branch=z9hG4bK29b83c62
From: "Daniel Smith Test" <sip:200700@10.102.0.143>;tag=as215a4017
To: <sip:422125@10.102.96.95:5060>;tag=714v0Nvyt00Sa
Call-ID: 3e3bcecf080f86ba35d659043b9ddeec@10.102.0.143:5060
CSeq: 103 INVITE
Contact: <sip:422125@10.102.96.95:5060;transport=udp>
User-Agent: FreeSWITCH-Test
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 247

v=0
o=FreeSWITCH 1650572442 1650572443 IN IP4 10.102.96.95
s=FreeSWITCH
c=IN IP4 10.102.96.95
t=0 0
m=audio 13056 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
<------------->
[2022-04-22 09:58:21.780] VERBOSE[19959] chan_sip.c: --- (14 headers 11 lines) ---
[2022-04-22 09:58:21.780] VERBOSE[19959][C-00000017] chan_sip.c: Comparing SDP version 1650572443 -> 1650572443 and unique parts [FreeSWITCH 1650572442 IN IP4 10.102.96.95] -> [FreeSWITCH 1650572442 IN IP4 10.102.96.95]
[2022-04-22 09:58:21.780] VERBOSE[19959][C-00000017] chan_sip.c: set_destination: Parsing <sip:422125@10.102.96.95:5060;transport=udp> for address/port to send to
[2022-04-22 09:58:21.780] VERBOSE[19959][C-00000017] chan_sip.c: set_destination: set destination to 10.102.96.95:5060
[2022-04-22 09:58:21.780] VERBOSE[19959][C-00000017] chan_sip.c: Transmitting (no NAT) to 10.102.96.95:5060:
ACK sip:422125@10.102.96.95:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 10.102.0.143:5060;branch=z9hG4bK3558d59c
Max-Forwards: 70
From: "Daniel Smith Test" <sip:200700@10.102.0.143>;tag=as215a4017
To: <sip:422125@10.102.96.95:5060>;tag=714v0Nvyt00Sa
Contact: <sip:200700@10.102.0.143:5060>
Call-ID: 3e3bcecf080f86ba35d659043b9ddeec@10.102.0.143:5060
CSeq: 103 ACK
User-Agent: Test PABX AU
Content-Length: 0


---
[2022-04-22 09:58:21.781] VERBOSE[19959] chan_sip.c: set_destination: Parsing <sip:422125@10.102.96.95:5060;transport=udp> for address/port to send to
[2022-04-22 09:58:21.781] VERBOSE[19959] chan_sip.c: set_destination: set destination to 10.102.96.95:5060
[2022-04-22 09:58:21.781] VERBOSE[19959] chan_sip.c: Reliably Transmitting (no NAT) to 10.102.96.95:5060:
BYE sip:422125@10.102.96.95:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 10.102.0.143:5060;branch=z9hG4bK47cdf1ab
Max-Forwards: 70
From: "Daniel Smith Test" <sip:200700@10.102.0.143>;tag=as215a4017
To: <sip:422125@10.102.96.95:5060>;tag=714v0Nvyt00Sa
Call-ID: 3e3bcecf080f86ba35d659043b9ddeec@10.102.0.143:5060
CSeq: 104 BYE
User-Agent: Test PABX AU
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0


---
[2022-04-22 09:58:21.781] VERBOSE[19959] chan_sip.c: Scheduling destruction of SIP dialog '3e3bcecf080f86ba35d659043b9ddeec@10.102.0.143:5060' in 9600 ms (Method: INVITE)
[2022-04-22 09:58:21.909] VERBOSE[19959] chan_sip.c: 
<--- SIP read from UDP:10.102.96.95:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.102.0.143:5060;branch=z9hG4bK29b83c62
From: "Daniel Smith Test" <sip:200700@10.102.0.143>;tag=as215a4017
To: <sip:422125@10.102.96.95:5060>;tag=714v0Nvyt00Sa
Call-ID: 3e3bcecf080f86ba35d659043b9ddeec@10.102.0.143:5060
CSeq: 103 INVITE
Contact: <sip:422125@10.102.96.95:5060;transport=udp>
User-Agent: FreeSWITCH-Test
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 247

v=0
o=FreeSWITCH 1650572442 1650572443 IN IP4 10.102.96.95
s=FreeSWITCH
c=IN IP4 10.102.96.95
t=0 0
m=audio 13056 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
<------------->
[2022-04-22 09:58:21.909] VERBOSE[19959] chan_sip.c: --- (14 headers 11 lines) ---
[2022-04-22 09:58:21.909] VERBOSE[19959][C-00000017] chan_sip.c: set_destination: Parsing <sip:422125@10.102.96.95:5060;transport=udp> for address/port to send to
[2022-04-22 09:58:21.909] VERBOSE[19959][C-00000017] chan_sip.c: set_destination: set destination to 10.102.96.95:5060
[2022-04-22 09:58:21.909] VERBOSE[19959][C-00000017] chan_sip.c: Transmitting (no NAT) to 10.102.96.95:5060:
ACK sip:422125@10.102.96.95:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 10.102.0.143:5060;branch=z9hG4bK23ea07be
Max-Forwards: 70
From: "Daniel Smith Test" <sip:200700@10.102.0.143>;tag=as215a4017
To: <sip:422125@10.102.96.95:5060>;tag=714v0Nvyt00Sa
Contact: <sip:200700@10.102.0.143:5060>
Call-ID: 3e3bcecf080f86ba35d659043b9ddeec@10.102.0.143:5060
CSeq: 103 ACK
User-Agent: Test PABX AU
Content-Length: 0


---
[2022-04-22 09:58:21.930] VERBOSE[19959] chan_sip.c: Retransmitting #1 (no NAT) to 10.102.96.95:5060:
BYE sip:422125@10.102.96.95:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 10.102.0.143:5060;branch=z9hG4bK47cdf1ab
Max-Forwards: 70
From: "Daniel Smith Test" <sip:200700@10.102.0.143>;tag=as215a4017
To: <sip:422125@10.102.96.95:5060>;tag=714v0Nvyt00Sa
Call-ID: 3e3bcecf080f86ba35d659043b9ddeec@10.102.0.143:5060
CSeq: 104 BYE
User-Agent: Test PABX AU
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0


---
[2022-04-22 09:58:21.937] VERBOSE[19959] chan_sip.c: 
<--- SIP read from UDP:10.102.96.95:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.102.0.143:5060;branch=z9hG4bK47cdf1ab
From: "Daniel Smith Test" <sip:200700@10.102.0.143>;tag=as215a4017
To: <sip:422125@10.102.96.95:5060>;tag=714v0Nvyt00Sa
Call-ID: 3e3bcecf080f86ba35d659043b9ddeec@10.102.0.143:5060
CSeq: 104 BYE
User-Agent: FreeSWITCH-Test
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Content-Length: 0

<------------->
[2022-04-22 09:58:21.938] VERBOSE[19959] chan_sip.c: --- (10 headers 0 lines) ---
[2022-04-22 09:58:21.938] VERBOSE[19959] chan_sip.c: Really destroying SIP dialog '3e3bcecf080f86ba35d659043b9ddeec@10.102.0.143:5060' Method: INVITE
[2022-04-22 09:58:22.080] VERBOSE[19959] chan_sip.c: 
<--- SIP read from UDP:10.102.96.95:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.102.0.143:5060;branch=z9hG4bK47cdf1ab
From: "Daniel Smith Test" <sip:200700@10.102.0.143>;tag=as215a4017
To: <sip:422125@10.102.96.95:5060>;tag=714v0Nvyt00Sa
Call-ID: 3e3bcecf080f86ba35d659043b9ddeec@10.102.0.143:5060
CSeq: 104 BYE
User-Agent: FreeSWITCH-Test
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Content-Length: 0

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

Interesting. Do you get more meaningful messages when you increase the verbosity and enable debugging?

All consistent with outbound packets being dropped by the network.

But its retransmitting too fast?
timer T1 = 500 not 150

Looking at https://raw.githubusercontent.com/asterisk/asterisk/18.11/channels/chan_sip.c
it looks to me like the retransmit is suppose to happen after Timer T1 is reached

[2022-04-22 09:58:21.609] VERBOSE[10057][C-00000017] chan_sip.c: Reliably Transmitting (no NAT) to 10.102.96.95:5060:
INVITE sip:422125@10.102.96.95:5060;transport=udp SIP/2.0

[2022-04-22 09:58:21.759] VERBOSE[19959] chan_sip.c: Retransmitting #1 (no NAT) to 10.102.96.95:5060:
INVITE sip:422125@10.102.96.95:5060;transport=udp SIP/2.0

150ms

[2022-04-22 09:58:18.671] VERBOSE[10057][C-00000017] chan_sip.c: Reliably Transmitting (no NAT) to 10.102.96.95:5060:
INVITE sip:422125@10.102.96.95:5060 SIP/2.0

[2022-04-22 09:58:18.822] VERBOSE[19959] chan_sip.c: Retransmitting #1 (no NAT) to 10.102.96.95:5060:
INVITE sip:422125@10.102.96.95:5060 SIP/2.0

151ms

[2022-04-22 09:58:21.609] VERBOSE[10057][C-00000017] chan_sip.c: Reliably Transmitting (no NAT) to 10.102.96.95:5060:
INVITE sip:422125@10.102.96.95:5060;transport=udp SIP/2.0

[2022-04-22 09:58:21.759] VERBOSE[19959] chan_sip.c: Retransmitting #1 (no NAT) to 10.102.96.95:5060:
INVITE sip:422125@10.102.96.95:5060;transport=udp SIP/2.0

150ms

It could be that the static value in the .conf file is 500ms, but the actual value could be 150ms, or less. I vaguely remember that T1 takes a different value in case the account uses qualification. chan_sip should probably not be used any more, because hardly anybody remembers the details these days.

Asterisk calibrates T1 using the round trip times from qualify.

No bugs will get fixed in chan_sip, as no-one is maintaining it. It is officially deprecated, It will not be included in the Asterisk code distributed in Autumn 2023, and one already has to take special steps when building and configuring for it to be included…

For chan_pjsip, unlike chan_sip, the qualify time doesn’t influence the T1 timer currently. It always uses the configured value.

Thanks all. So in conclusion for future readers, chan_sip will take the ping time from the options message (when qualify = yes) and retransmit when no response has been recieved within that ping time. Ping time found here
asterisk -rx ‘sip show peer xxxx’ | grep Status

I think it should time out at about twice the ping time.