How to avoid re-INVITE - buggy endpoint

rodpp · September 5, 2021, 7:08am

Hello,

Configuration:
Two endpoints (Android Groundwire APP and Hikivision Doorbell) connected to an Asterisk 18.2.2.

Problem:
The Groundwire endpoint send a BYE to the Hikivision Doorbell, but the Asterisk receive it and do not forward. So the Doorbell doesn’t end the call until a timeout (90s max call duration in this case).

Possible Cause
The Hikivision Doorbell can’t handle reinvites very well. After receiving a reinvite from Asterisk, it returns “100 Trying” but never send a “200 OK” or reject it. Since an INVITE is pending, the BYE is deferred by Asterisk until the end of the REINVITE processing, and that never happens.

Question
Is it possible to change something on Asterisk configurations to avoid that REINVITES? I know it is not an Asterisk problem, as the Hikivision Doorbell seems to have a poor SIP implementation. But I can only try to solve this issue changing the Asterisk configurations, because the doorbell settings are limited.

Thank you very much!

Attachments
Diagram:

            10.0.3.119:5060                10.0.2.10:5060               10.0.3.117:8418  
          qqqqqqqqqqwqqqqqqqqq          qqqqqqqqqqwqqqqqqqqq          qqqqqqqqqqwqqqqqqqqq
  03:26:38.211642   x        INVITE (SDP)         x                             x         
        +0.002482   x qqqqqqqqqqqqqqqqqqqqqqqqqq> x                             x         
  03:26:38.214124   x      401 Unauthorized       x                             x         
        +0.028449   x <qqqqqqqqqqqqqqqqqqqqqqqqqq x                             x         
  03:26:38.242573   x             ACK             x                             x         
        +0.034199   x qqqqqqqqqqqqqqqqqqqqqqqqqq> x                             x         
  03:26:38.276772   x        INVITE (SDP)         x                             x         
        +0.003028   x qqqqqqqqqqqqqqqqqqqqqqqqqq> x                             x         
  03:26:38.279800   x         100 Trying          x                             x         
        +0.004115   x <qqqqqqqqqqqqqqqqqqqqqqqqqq x                             x         
  03:26:38.283915   x                             x        INVITE (SDP)         x         
        +0.500327   x                             x qqqqqqqqqqqqqqqqqqqqqqqqqq> x         
  03:26:38.784242   x                             x        INVITE (SDP)         x         
        +0.109728   x                             x qqqqqqqqqqqqqqqqqqqqqqqq>>> x         
  03:26:38.893970   x                             x         100 Trying          x         
        +0.000028   x                             x <qqqqqqqqqqqqqqqqqqqqqqqqqq x         
  03:26:38.893998   x                             x         100 Trying          x         
        +0.032060   x                             x <<<qqqqqqqqqqqqqqqqqqqqqqqq x         
  03:26:38.926058   x                             x         180 Ringing         x         
        +0.000503   x                             x <qqqqqqqqqqqqqqqqqqqqqqqqqq x         
  03:26:38.926561   x         180 Ringing         x                             x         
        +2.225643   x <qqqqqqqqqqqqqqqqqqqqqqqqqq x                             x         
  03:26:41.152204   x                             x        200 OK (SDP)         x         
        +0.000564   x                             x <qqqqqqqqqqqqqqqqqqqqqqqqqq x         
  03:26:41.152768   x                             x             ACK             x         
        +0.000528   x                             x qqqqqqqqqqqqqqqqqqqqqqqqqq> x         
  03:26:41.153296   x        200 OK (SDP)         x                             x         
        +0.020351   x <qqqqqqqqqqqqqqqqqqqqqqqqqq x                             x         
  03:26:41.173647   x             ACK             x                             x         
        +0.000638   x qqqqqqqqqqqqqqqqqqqqqqqqqq> x                             x         
  03:26:41.174285   x        INVITE (SDP)         x                             x         
        +0.029640   x <qqqqqqqqqqqqqqqqqqqqqqqqqq x                             x         
  03:26:41.203925   x         100 Trying          x                             x         
        +0.080661   x qqqqqqqqqqqqqqqqqqqqqqqqqq> x                             x         
  03:26:41.284586   x           MESSAGE           x                             x         
        +0.000228   x qqqqqqqqqqqqqqqqqqqqqqqqqq> x                             x         
  03:26:41.284814   x        202 Accepted         x                             x         
        +0.000282   x <qqqqqqqqqqqqqqqqqqqqqqqqqq x                             x         
  03:26:41.285096   x                             x           MESSAGE           x         
        +0.032778   x                             x qqqqqqqqqqqqqqqqqqqqqqqqqq> x         
  03:26:41.317874   x                             x     501 Not Implemented     x         
        +5.376330   x                             x <qqqqqqqqqqqqqqqqqqqqqqqqqq x         
  03:26:46.694204   x                             x             BYE             x         
        +0.000309   x                             x <qqqqqqqqqqqqqqqqqqqqqqqqqq x         
  03:26:46.694513   x                             x           200 OK            x         
       +85.077551   x                             x qqqqqqqqqqqqqqqqqqqqqqqqqq> x         
  03:28:11.772064   x             BYE             x                             x         
        +0.000332   x qqqqqqqqqqqqqqqqqqqqqqqqqq> x                             x         
  03:28:11.772396   x           200 OK            x                             x         
                    x <qqqqqqqqqqqqqqqqqqqqqqqqqq x                             x         
                    x                             x                             x         
                    x                             x                             x

RAW:

2021/09/05 03:26:38.211642 10.0.3.119:5060 -> 10.0.2.10:5060
INVITE sip:110@10.0.2.10:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.3.119:5060;rport;branch=z9hG4bK1716633144
From: 8112 <sip:8112@10.0.2.10>;tag=263020290
To: <sip:110@10.0.2.10:5060>
Call-ID: 868111105
CSeq: 20 INVITE
Contact: <sip:8112@10.0.3.119:5060>
Content-Type: application/sdp
Max-Forwards: 70
User-Agent: eXosip/3.6.0
Subject: This is a call for conversation
Content-Length:   353

v=0
o=E02520129 0 0 IN IP4 10.0.3.119
s=Talk session
c=IN IP4 10.0.3.119
t=0 0
m=audio 9654 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=framerate:50
a=sendrecv
m=video 9856 RTP/AVP 96
a=rtpmap:96 H264/90000
a=fmtp:96 packetization-mode=1;profile-level-id=4D0029
a=sendonly

2021/09/05 03:26:38.214124 10.0.2.10:5060 -> 10.0.3.119:5060
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 10.0.3.119:5060;rport=5060;received=10.0.3.119;branch=z9hG4bK1716633144
Call-ID: 868111105
From: "8112" <sip:8112@10.0.2.10>;tag=263020290
To: <sip:110@10.0.2.10>;tag=z9hG4bK1716633144
CSeq: 20 INVITE
WWW-Authenticate: Digest realm="asterisk",nonce="1630823198/6ac2981f29aabe00faf5034a97d40c74",opaque="016ccb892f78a121",algorithm=md5,qop="auth"
Server: Asterisk PBX 18.2.2
Content-Length:  0


2021/09/05 03:26:38.242573 10.0.3.119:5060 -> 10.0.2.10:5060
ACK sip:110@10.0.2.10:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.3.119:5060;rport;branch=z9hG4bK1716633144
Route: <sip:110@10.0.2.10:5060>
From: "8112" <sip:8112@10.0.2.10>;tag=263020290
To: <sip:110@10.0.2.10>;tag=z9hG4bK1716633144
Call-ID: 868111105
CSeq: 20 ACK
Content-Length: 0


2021/09/05 03:26:38.276772 10.0.3.119:5060 -> 10.0.2.10:5060
INVITE sip:110@10.0.2.10:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.3.119:5060;rport;branch=z9hG4bK581637817
From: 8112 <sip:8112@10.0.2.10>;tag=263020290
To: <sip:110@10.0.2.10:5060>
Call-ID: 868111105
CSeq: 21 INVITE
Contact: <sip:8112@10.0.3.119:5060>
Authorization: Digest username="8112", realm="asterisk", nonce="1630823198/6ac2981f29aabe00faf5034a97d40c74", uri="sip:110@10.0.2.10:5060", response="acfc1c9be52bff4d312e1ee064e8a45f", algorithm=MD5, cnonce="0a4f113b", opaque="016ccb892f
a121", qop=auth, nc=00000001
Content-Type: application/sdp
Max-Forwards: 70
User-Agent: eXosip/3.6.0
Subject: This is a call for conversation
Content-Length:   353

v=0
o=E02520129 0 0 IN IP4 10.0.3.119
s=Talk session
c=IN IP4 10.0.3.119
t=0 0
m=audio 9654 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=framerate:50
a=sendrecv
m=video 9856 RTP/AVP 96
a=rtpmap:96 H264/90000
a=fmtp:96 packetization-mode=1;profile-level-id=4D0029
a=sendonly

2021/09/05 03:26:38.279800 10.0.2.10:5060 -> 10.0.3.119:5060
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.0.3.119:5060;rport=5060;received=10.0.3.119;branch=z9hG4bK581637817
Call-ID: 868111105
From: "8112" <sip:8112@10.0.2.10>;tag=263020290
To: <sip:110@10.0.2.10>
CSeq: 21 INVITE
Server: Asterisk PBX 18.2.2
Content-Length:  0


2021/09/05 03:26:38.283915 10.0.2.10:5060 -> 10.0.3.117:8418
INVITE sip:RODCELL@10.0.3.117:8418;rinstance=EBFB42E9 SIP/2.0
Via: SIP/2.0/UDP 10.0.2.10:5060;rport;branch=z9hG4bKPjc9890f37-f09c-4a6b-902e-b98cf08e0828
From: "8112" <sip:8112@10.0.2.10>;tag=ae10c29c-d61c-47b0-bdf2-f49b1da4ce30
To: <sip:RODCELL@10.0.3.117;rinstance=EBFB42E9>
Contact: <sip:asterisk@10.0.2.10:5060>
Call-ID: 71e18ba5-5998-4e41-af23-faff6fc08a56
CSeq: 7679 INVITE
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Supported: 100rel, replaces, norefersub, histinfo
Max-Forwards: 70
User-Agent: Asterisk PBX 18.2.2
Content-Type: application/sdp
Content-Length:   420

v=0
o=- 1583410091 1583410091 IN IP4 10.0.2.10
s=Asterisk
c=IN IP4 10.0.2.10
t=0 0
m=audio 24824 RTP/AVP 0 8 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv
m=video 17758 RTP/AVP 99
a=rtpmap:99 H264/90000
a=fmtp:99 packetization-mode=1;profile-level-id=4D0029
a=recvonly

2021/09/05 03:26:38.784242 10.0.2.10:5060 -> 10.0.3.117:8418
INVITE sip:RODCELL@10.0.3.117:8418;rinstance=EBFB42E9 SIP/2.0
Via: SIP/2.0/UDP 10.0.2.10:5060;rport;branch=z9hG4bKPjc9890f37-f09c-4a6b-902e-b98cf08e0828
From: "8112" <sip:8112@10.0.2.10>;tag=ae10c29c-d61c-47b0-bdf2-f49b1da4ce30
To: <sip:RODCELL@10.0.3.117;rinstance=EBFB42E9>
Contact: <sip:asterisk@10.0.2.10:5060>
Call-ID: 71e18ba5-5998-4e41-af23-faff6fc08a56
CSeq: 7679 INVITE
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Supported: 100rel, replaces, norefersub, histinfo
Max-Forwards: 70
User-Agent: Asterisk PBX 18.2.2
Content-Type: application/sdp
Content-Length:   420

v=0
o=- 1583410091 1583410091 IN IP4 10.0.2.10
s=Asterisk
c=IN IP4 10.0.2.10
t=0 0
m=audio 24824 RTP/AVP 0 8 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv
m=video 17758 RTP/AVP 99
a=rtpmap:99 H264/90000
a=fmtp:99 packetization-mode=1;profile-level-id=4D0029
a=recvonly

2021/09/05 03:26:38.893970 10.0.3.117:8418 -> 10.0.2.10:5060
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.0.2.10:5060;rport=5060;branch=z9hG4bKPjc9890f37-f09c-4a6b-902e-b98cf08e0828;received=10.0.2.10
From: "8112" <sip:8112@10.0.2.10>;tag=ae10c29c-d61c-47b0-bdf2-f49b1da4ce30
Call-ID: 71e18ba5-5998-4e41-af23-faff6fc08a56
CSeq: 7679 INVITE
To: <sip:RODCELL@10.0.3.117;rinstance=EBFB42E9>
User-Agent: Groundwire/5.4.9 (build 1619523; Android 10; arm64-v8a)
Content-Length: 0


2021/09/05 03:26:38.893998 10.0.3.117:8418 -> 10.0.2.10:5060
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.0.2.10:5060;rport=5060;branch=z9hG4bKPjc9890f37-f09c-4a6b-902e-b98cf08e0828;received=10.0.2.10
From: "8112" <sip:8112@10.0.2.10>;tag=ae10c29c-d61c-47b0-bdf2-f49b1da4ce30
Call-ID: 71e18ba5-5998-4e41-af23-faff6fc08a56
CSeq: 7679 INVITE
To: <sip:RODCELL@10.0.3.117;rinstance=EBFB42E9>
User-Agent: Groundwire/5.4.9 (build 1619523; Android 10; arm64-v8a)
Content-Length: 0


2021/09/05 03:26:38.926058 10.0.3.117:8418 -> 10.0.2.10:5060
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 10.0.2.10:5060;rport=5060;branch=z9hG4bKPjc9890f37-f09c-4a6b-902e-b98cf08e0828;received=10.0.2.10
Contact: <sip:RODCELL@10.0.3.117:8418>
From: "8112" <sip:8112@10.0.2.10>;tag=ae10c29c-d61c-47b0-bdf2-f49b1da4ce30
Call-ID: 71e18ba5-5998-4e41-af23-faff6fc08a56
CSeq: 7679 INVITE
To: <sip:RODCELL@10.0.3.117;rinstance=EBFB42E9>;tag=FE280DD3A47689D858DD34D8DBC33D07
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Supported: replaces, path
User-Agent: Groundwire/5.4.9 (build 1619523; Android 10; arm64-v8a)
Content-Length: 0


2021/09/05 03:26:38.926561 10.0.2.10:5060 -> 10.0.3.119:5060
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 10.0.3.119:5060;rport=5060;received=10.0.3.119;branch=z9hG4bK581637817
Call-ID: 868111105
From: "8112" <sip:8112@10.0.2.10>;tag=263020290
To: <sip:110@10.0.2.10>;tag=72ded879-7456-4df6-9a6f-cf4801cbdb12
CSeq: 21 INVITE
Server: Asterisk PBX 18.2.2
Contact: <sip:10.0.2.10:5060>
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Content-Length:  0


2021/09/05 03:26:41.152204 10.0.3.117:8418 -> 10.0.2.10:5060
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.0.2.10:5060;rport=5060;branch=z9hG4bKPjc9890f37-f09c-4a6b-902e-b98cf08e0828;received=10.0.2.10
Contact: <sip:RODCELL@10.0.3.117:8418>
From: "8112" <sip:8112@10.0.2.10>;tag=ae10c29c-d61c-47b0-bdf2-f49b1da4ce30
Call-ID: 71e18ba5-5998-4e41-af23-faff6fc08a56
CSeq: 7679 INVITE
To: <sip:RODCELL@10.0.3.117;rinstance=EBFB42E9>;tag=FE280DD3A47689D858DD34D8DBC33D07
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Supported: replaces, path
Content-Type: application/sdp
User-Agent: Groundwire/5.4.9 (build 1619523; Android 10; arm64-v8a)
Content-Length: 337

v=0
o=- 2276426085 61765 IN IP4 172.26.170.170
s=kghtnqz
c=IN IP4 10.0.3.117
t=0 0
m=audio 36892 RTP/AVP 0 101
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv
m=video 10896 RTP/AVP 99
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=sendonly

2021/09/05 03:26:41.152768 10.0.2.10:5060 -> 10.0.3.117:8418
ACK sip:RODCELL@10.0.3.117:8418 SIP/2.0
Via: SIP/2.0/UDP 10.0.2.10:5060;rport;branch=z9hG4bKPjb477a5de-34b9-479f-8730-cb2a9248077d
From: "8112" <sip:8112@10.0.2.10>;tag=ae10c29c-d61c-47b0-bdf2-f49b1da4ce30
To: <sip:RODCELL@10.0.3.117;rinstance=EBFB42E9>;tag=FE280DD3A47689D858DD34D8DBC33D07
Call-ID: 71e18ba5-5998-4e41-af23-faff6fc08a56
CSeq: 7679 ACK
Max-Forwards: 70
User-Agent: Asterisk PBX 18.2.2
Content-Length:  0


2021/09/05 03:26:41.153296 10.0.2.10:5060 -> 10.0.3.119:5060
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.0.3.119:5060;rport=5060;received=10.0.3.119;branch=z9hG4bK581637817
Call-ID: 868111105
From: "8112" <sip:8112@10.0.2.10>;tag=263020290
To: <sip:110@10.0.2.10>;tag=72ded879-7456-4df6-9a6f-cf4801cbdb12
CSeq: 21 INVITE
Server: Asterisk PBX 18.2.2
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Contact: <sip:10.0.2.10:5060>
Supported: 100rel, replaces, norefersub
Content-Type: application/sdp
Content-Length:   330

v=0
o=- 0 2 IN IP4 10.0.2.10
s=Asterisk
c=IN IP4 10.0.2.10
t=0 0
m=audio 20670 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
m=video 6446 RTP/AVP 96
a=rtpmap:96 H264/90000
a=fmtp:96 packetization-mode=1;profile-level-id=4D0029
a=recvonly

2021/09/05 03:26:41.173647 10.0.3.119:5060 -> 10.0.2.10:5060
ACK sip:10.0.2.10:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.3.119:5060;rport;branch=z9hG4bK2055759711
From: "8112" <sip:8112@10.0.2.10>;tag=263020290
To: <sip:110@10.0.2.10>;tag=72ded879-7456-4df6-9a6f-cf4801cbdb12
Call-ID: 868111105
CSeq: 21 ACK
Contact: <sip:8112@10.0.3.119:5060>
Max-Forwards: 70
User-Agent: eXosip/3.6.0
Content-Length: 0


2021/09/05 03:26:41.174285 10.0.2.10:5060 -> 10.0.3.119:5060
INVITE sip:8112@10.0.3.119:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.2.10:5060;rport;branch=z9hG4bKPja5c42e89-bbd4-44b7-a1a4-884b28027d08
From: <sip:110@10.0.2.10>;tag=72ded879-7456-4df6-9a6f-cf4801cbdb12
To: "8112" <sip:8112@10.0.2.10>;tag=263020290
Contact: <sip:10.0.2.10:5060>
Call-ID: 868111105
CSeq: 27601 INVITE
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Supported: 100rel, replaces, norefersub, histinfo
Max-Forwards: 70
User-Agent: Asterisk PBX 18.2.2
Content-Type: application/sdp
Content-Length:   330

v=0
o=- 0 3 IN IP4 10.0.2.10
s=Asterisk
c=IN IP4 10.0.2.10
t=0 0
m=audio 20670 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
m=video 6446 RTP/AVP 96
a=rtpmap:96 H264/90000
a=fmtp:96 packetization-mode=1;profile-level-id=4D0029
a=sendonly

2021/09/05 03:26:41.203925 10.0.3.119:5060 -> 10.0.2.10:5060
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.0.2.10:5060;rport=5060;branch=z9hG4bKPja5c42e89-bbd4-44b7-a1a4-884b28027d08
From: <sip:110@10.0.2.10>;tag=72ded879-7456-4df6-9a6f-cf4801cbdb12
To: "8112" <sip:8112@10.0.2.10>;tag=263020290
Call-ID: 868111105
CSeq: 27601 INVITE
User-Agent: eXosip/3.6.0
Content-Length: 0


2021/09/05 03:26:41.284586 10.0.3.119:5060 -> 10.0.2.10:5060
MESSAGE sip:10.0.2.10:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.3.119:5060;rport;branch=z9hG4bK2104096068
From: "8112" <sip:8112@10.0.2.10>;tag=263020290
To: <sip:110@10.0.2.10>;tag=72ded879-7456-4df6-9a6f-cf4801cbdb12
Call-ID: 868111105
CSeq: 22 MESSAGE
Contact: <sip:8112@10.0.3.119:5060>
Proxy-Authorization: Digest username="8112", realm="asterisk", nonce="1630823198/6ac2981f29aabe00faf5034a97d40c74", uri="sip:10.0.2.10:5060", response="f405131f9170c821a93c25e21a697f49", algorithm=MD5, cnonce="0a4f113b", opaque="016ccb89
78a121", qop=auth, nc=00000002
Content-Type: text/plain
Max-Forwards: 70
User-Agent: eXosip/3.6.0
Content-Length:    48

<locknumXML>
<lockNum>1</lockNum>
</locknumXML>

2021/09/05 03:26:41.284814 10.0.2.10:5060 -> 10.0.3.119:5060
SIP/2.0 202 Accepted
Via: SIP/2.0/UDP 10.0.3.119:5060;rport=5060;received=10.0.3.119;branch=z9hG4bK2104096068
Call-ID: 868111105
From: "8112" <sip:8112@10.0.2.10>;tag=263020290
To: <sip:110@10.0.2.10>;tag=72ded879-7456-4df6-9a6f-cf4801cbdb12
CSeq: 22 MESSAGE
Server: Asterisk PBX 18.2.2
Content-Length:  0


2021/09/05 03:26:41.285096 10.0.2.10:5060 -> 10.0.3.117:8418
MESSAGE sip:RODCELL@10.0.3.117:8418 SIP/2.0
Via: SIP/2.0/UDP 10.0.2.10:5060;rport;branch=z9hG4bKPje611d6e2-ae2a-4585-accb-10bc80b47dc1
From: "8112" <sip:8112@10.0.2.10>;tag=ae10c29c-d61c-47b0-bdf2-f49b1da4ce30
To: <sip:RODCELL@10.0.3.117;rinstance=EBFB42E9>;tag=FE280DD3A47689D858DD34D8DBC33D07
Call-ID: 71e18ba5-5998-4e41-af23-faff6fc08a56
CSeq: 7680 MESSAGE
Max-Forwards: 70
User-Agent: Asterisk PBX 18.2.2
Content-Type: text/plain
Content-Length:    48

<locknumXML>
<lockNum>1</lockNum>
</locknumXML>

2021/09/05 03:26:41.317874 10.0.3.117:8418 -> 10.0.2.10:5060
SIP/2.0 501 Not Implemented
Via: SIP/2.0/UDP 10.0.2.10:5060;rport=5060;branch=z9hG4bKPje611d6e2-ae2a-4585-accb-10bc80b47dc1;received=10.0.2.10
Contact: <sip:RODCELL@10.0.3.117:8418>
From: "8112" <sip:8112@10.0.2.10>;tag=ae10c29c-d61c-47b0-bdf2-f49b1da4ce30
Call-ID: 71e18ba5-5998-4e41-af23-faff6fc08a56
CSeq: 7680 MESSAGE
To: <sip:RODCELL@10.0.3.117;rinstance=EBFB42E9>;tag=FE280DD3A47689D858DD34D8DBC33D07
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Supported: replaces, path
User-Agent: Groundwire/5.4.9 (build 1619523; Android 10; arm64-v8a)
Content-Length: 0


2021/09/05 03:26:46.694204 10.0.3.117:8418 -> 10.0.2.10:5060
BYE sip:asterisk@10.0.2.10:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.3.117:8418;branch=z9hG4bKbDeLIVvA662PpGG1;rport
Contact: <sip:RODCELL@10.0.3.117:8418>
Max-Forwards: 70
From: <sip:RODCELL@10.0.3.117;rinstance=EBFB42E9>;tag=FE280DD3A47689D858DD34D8DBC33D07
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Supported: replaces, path
Warning: 399 10.0.3.117 "User click in call fragment"
To: "8112" <sip:8112@10.0.2.10>;tag=ae10c29c-d61c-47b0-bdf2-f49b1da4ce30
Call-ID: 71e18ba5-5998-4e41-af23-faff6fc08a56
CSeq: 1 BYE
User-Agent: Groundwire/5.4.9 (build 1619523; Android 10; arm64-v8a)
Content-Length: 0


2021/09/05 03:26:46.694513 10.0.2.10:5060 -> 10.0.3.117:8418
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.0.3.117:8418;rport=8418;received=10.0.3.117;branch=z9hG4bKbDeLIVvA662PpGG1
Call-ID: 71e18ba5-5998-4e41-af23-faff6fc08a56
From: <sip:RODCELL@10.0.3.117;rinstance=EBFB42E9>;tag=FE280DD3A47689D858DD34D8DBC33D07
To: "8112" <sip:8112@10.0.2.10>;tag=ae10c29c-d61c-47b0-bdf2-f49b1da4ce30
CSeq: 1 BYE
Server: Asterisk PBX 18.2.2
Content-Length:  0


2021/09/05 03:28:11.772064 10.0.3.119:5060 -> 10.0.2.10:5060
BYE sip:10.0.2.10:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.3.119:5060;rport;branch=z9hG4bK1631350725
From: "8112" <sip:8112@10.0.2.10>;tag=263020290
To: <sip:110@10.0.2.10>;tag=72ded879-7456-4df6-9a6f-cf4801cbdb12
Call-ID: 868111105
CSeq: 23 BYE
Contact: <sip:8112@10.0.3.119:5060>
Proxy-Authorization: Digest username="8112", realm="asterisk", nonce="1630823198/6ac2981f29aabe00faf5034a97d40c74", uri="sip:10.0.2.10:5060", response="29eb3aebc3a57ae9d0bd0049cad08fc5", algorithm=MD5, cnonce="0a4f113b", opaque="016ccb89
78a121", qop=auth, nc=00000003
Max-Forwards: 70
User-Agent: eXosip/3.6.0
Content-Length: 0


2021/09/05 03:28:11.772396 10.0.2.10:5060 -> 10.0.3.119:5060
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.0.3.119:5060;rport=5060;received=10.0.3.119;branch=z9hG4bK1631350725
Call-ID: 868111105
From: "8112" <sip:8112@10.0.2.10>;tag=263020290
To: <sip:110@10.0.2.10>;tag=72ded879-7456-4df6-9a6f-cf4801cbdb12
CSeq: 23 BYE
Server: Asterisk PBX 18.2.2
Content-Length:  0

david551 · September 5, 2021, 10:42am

Asterisk doesn’t forward BYE. BYE causes an internal hangup event, but what the dialplan does subsequently determines when the call is terminated on the other party. You haven’t provide the dialplan and logging of what it is doing.

You haven’t said which channel driver you are using, so we don’t know the available configuration options.

I cannot work out why the re-INVITE is being sent, so I don’t know which option would control its sending.

rodpp · September 5, 2021, 1:50pm

Please, see below the dialplan:

[general]
[globals]
Rodrigo_Cellphone=PJSIP/RODCELL

[sets]
exten => 110,1,Dial(${Rodrigo_Cellphone},30)
same => n,Hangup()

And the logging:

 -- Executing [110@sets:1] Dial("PJSIP/8112-0000006a", "PJSIP/RODCELL,30") in new stack
    -- Called PJSIP/RODCELL
    -- PJSIP/RODCELL-0000006b is ringing
       > 0x7f2fcc166fe0 -- Strict RTP learning after remote address set to: 10.0.3.117:36892
       > 0x7f2fcc19f3e0 -- Strict RTP learning after remote address set to: 10.0.3.117:10896
    -- PJSIP/RODCELL-0000006b answered PJSIP/8112-0000006a
       > 0x7f2fcc0750d0 -- Strict RTP learning after remote address set to: 10.0.3.119:9654
       > 0x7f2fcc05c670 -- Strict RTP learning after remote address set to: 10.0.3.119:9856
    -- Channel PJSIP/RODCELL-0000006b joined 'simple_bridge' basic-bridge <dbd644a1-b364-4ae8-be52-19eac789e425>
    -- Channel PJSIP/8112-0000006a joined 'simple_bridge' basic-bridge <dbd644a1-b364-4ae8-be52-19eac789e425>
       > 0x7f2fcc0750d0 -- Strict RTP switching to RTP target address 10.0.3.119:9654 as source
       > 0x7f2fcc05c670 -- Strict RTP switching to RTP target address 10.0.3.119:9856 as source
       > 0x7f2fcc166fe0 -- Strict RTP switching to RTP target address 10.0.3.117:36892 as source
       > 0x7f2fcc19f3e0 -- Strict RTP switching to RTP target address 10.0.3.117:10896 as source
       > 0x7f2fcc166fe0 -- Strict RTP learning complete - Locking on source address 10.0.3.117:36892
       > 0x7f2fcc0750d0 -- Strict RTP learning complete - Locking on source address 10.0.3.119:9654
       > 0x7f2fcc05c670 -- Strict RTP learning complete - Locking on source address 10.0.3.119:9856
       > 0x7f2fcc19f3e0 -- Strict RTP learning complete - Locking on source address 10.0.3.117:10896
    -- Channel PJSIP/RODCELL-0000006b left 'simple_bridge' basic-bridge <dbd644a1-b364-4ae8-be52-19eac789e425>
    -- Channel PJSIP/8112-0000006a left 'simple_bridge' basic-bridge <dbd644a1-b364-4ae8-be52-19eac789e425>
  == Spawn extension (sets, 110, 1) exited non-zero on 'PJSIP/8112-0000006a'

I’m using PJSIP. Here is the endpoints entries in the database table ps_endpoints:

insert into ps_endpoints (id,transport,aors,auth,context,disallow,allow,direct_media,language) values ("8112","transport-udp","8112","8112","sets","all","alaw,ulaw,g729,h264","no","pt-br");
insert into ps_endpoints (id,transport,aors,auth,context,disallow,allow,direct_media,language) values ("RODCELL","transport-udp","RODCELL","RODCELL","sets","all","alaw,ulaw,g729,h264","no","pt-br");

Thank you!

david551 · September 5, 2021, 2:40pm

I can’t see any material difference between the OK to 119 and the subsequent re-INVITE, so I don’t understand the purpose of the re-INVITE. However, you could try disabling the common uses:

send_connected_line=no
direct_media=no
timers=no

However, ultimately it might come down to not supporting every possible broken peer.

For future reference, please take logging from the log files, not the screen as it contains time stamps.

rodpp · September 5, 2021, 3:15pm

I disabled as you suggested, now both endpoints config are:

insert into ps_endpoints (id,transport,aors,auth,context,disallow,allow,direct_media,language,send_connected_line,timers) values ("8112","transport-udp","8112","8112","sets","all","alaw,ulaw,g729,h264","no","pt-br","no","no");
insert into ps_endpoints (id,transport,aors,auth,context,disallow,allow,direct_media,language,send_connected_line,timers) values ("RODCELL","transport-udp","RODCELL","RODCELL","sets","all","alaw,ulaw,g729,h264","no","pt-br","no","no");

Exactly the same behavior as before, after “200 OK” Asterisk send a re-INVITE and the Hikvision doorbell fails to answer it.

If there are more suggestions, I appreciate.

Thank you very much david551!

rodpp · September 5, 2021, 4:31pm

Analyzing the Asterisk debug log of the re-INVITE, it seems the follow lines are related:

[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Delay sending reinvite because of outstanding transaction
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Sending delayed INVITE request

As a new user, I can’t attach files in this post. And the full log exceeds the post allowed characteres.

So, please see below an extract from the full log, comprising:

Asterisk 200 OK to Hikvision Doorbell, related with the first INVITE;
Hikvision Doorbell ACK to Asterisk;
==> Asterisk re-INVITE to Hikvision Doorbell.

SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.0.3.119:5060;rport=5060;received=10.0.3.119;branch=z9hG4bK1493001732
Call-ID: 156317553
From: "8112" <sip:8112@10.0.2.10>;tag=108434922
To: <sip:110@10.0.2.10>;tag=d8387212-ed2e-45e2-a93b-83f6e853ba60
CSeq: 21 INVITE
Server: Asterisk PBX 18.2.2
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Contact: <sip:10.0.2.10:5060>
Supported: 100rel, replaces, norefersub
Content-Type: application/sdp
Content-Length:   331

v=0
o=- 0 2 IN IP4 10.0.2.10
s=Asterisk
c=IN IP4 10.0.2.10
t=0 0
m=audio 14930 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
m=video 29056 RTP/AVP 96
a=rtpmap:96 H264/90000
a=fmtp:96 packetization-mode=1;profile-level-id=4D0029
a=recvonly

[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004 Event: TSX_STATE  Inv State: CONNECTING
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The state change pertains to the endpoint '8112(PJSIP/8112-00000004)'
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f279c0b4728)
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: There is no transaction involved in this state change
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The current inv state is CONNECTING
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: PJSIP/8112-00000004: Source of transaction state change is TX_MSG
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004 TSX State: Completed  Inv State: CONNECTING
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The state change pertains to the endpoint '8112(PJSIP/8112-00000004)'
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f279c0b4728)
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f279c0b4728
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The current transaction state is Completed
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The transaction state change event is TX_MSG
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The current inv state is CONNECTING
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  Nothing delayed
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004 TSX State: Completed  Inv State: CONNECTING
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  Topology: Pending: (null topology)  Active:  <0:audio-0:audio:sendrecv (ulaw)> <1:video-1:video:recvonly (h264)>
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  
[Sep  5 12:07:28] DEBUG[295777] chan_pjsip.c:  
[Sep  5 12:07:28] DEBUG[296486][C-00000003] chan_pjsip.c:  
[Sep  5 12:07:28] DEBUG[296486][C-00000003] chan_pjsip.c:  PJSIP/8112-00000004: Indicated Stop generators
[Sep  5 12:07:28] DEBUG[296486][C-00000003] chan_pjsip.c:  PJSIP/8112-00000004
[Sep  5 12:07:28] DEBUG[296486][C-00000003] stasis.c: Creating topic. name: bridge:all/bridge:4b254d46-227c-469f-bc28-ee75fc428a24, detail: 
[Sep  5 12:07:28] DEBUG[296486][C-00000003] stasis.c: Topic 'bridge:all/bridge:4b254d46-227c-469f-bc28-ee75fc428a24': 0x7f2824008070 created
[Sep  5 12:07:28] DEBUG[296486][C-00000003] bridge_native_rtp.c: Bridge '4b254d46-227c-469f-bc28-ee75fc428a24' can not use native RTP bridge as two channels are required
[Sep  5 12:07:28] DEBUG[296486][C-00000003] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Sep  5 12:07:28] DEBUG[296486][C-00000003] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Sep  5 12:07:28] DEBUG[296486][C-00000003] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping.
[Sep  5 12:07:28] DEBUG[296486][C-00000003] bridge.c: Chose bridge technology simple_bridge
[Sep  5 12:07:28] DEBUG[296486][C-00000003] bridge.c: Bridge 4b254d46-227c-469f-bc28-ee75fc428a24: calling simple_bridge technology constructor
[Sep  5 12:07:28] DEBUG[296486][C-00000003] bridge.c: Bridge 4b254d46-227c-469f-bc28-ee75fc428a24: calling simple_bridge technology start
[Sep  5 12:07:28] DEBUG[296486][C-00000003] stasis_bridges.c: Update: 0x7f28240105d8  Old: <none>  New: 4b254d46-227c-469f-bc28-ee75fc428a24
[Sep  5 12:07:28] DEBUG[296486][C-00000003] stasis_bridges.c: Update: 0x7f28240105d8  Old: <none>  New: 4b254d46-227c-469f-bc28-ee75fc428a24
[Sep  5 12:07:28] DEBUG[296496][C-00000003] bridge_channel.c: Bridge 4b254d46-227c-469f-bc28-ee75fc428a24: 0x7f2824013580(PJSIP/RODCELL-00000005) is joining
[Sep  5 12:07:28] DEBUG[296496][C-00000003] bridge_channel.c: Bridge 4b254d46-227c-469f-bc28-ee75fc428a24: pushing 0x7f2824013580(PJSIP/RODCELL-00000005)
[Sep  5 12:07:28] VERBOSE[296496][C-00000003] bridge_channel.c: Channel PJSIP/RODCELL-00000005 joined 'simple_bridge' basic-bridge <4b254d46-227c-469f-bc28-ee75fc428a24>
[Sep  5 12:07:28] DEBUG[296496][C-00000003] stasis_bridges.c: Update: 0x7f27a4004d08  Old: 4b254d46-227c-469f-bc28-ee75fc428a24  New: 4b254d46-227c-469f-bc28-ee75fc428a24
[Sep  5 12:07:28] DEBUG[296496][C-00000003] stasis_bridges.c: Update: 0x7f27a4004d08  Old: 4b254d46-227c-469f-bc28-ee75fc428a24  New: 4b254d46-227c-469f-bc28-ee75fc428a24
[Sep  5 12:07:28] DEBUG[296496][C-00000003] bridge_native_rtp.c: Bridge '4b254d46-227c-469f-bc28-ee75fc428a24' can not use native RTP bridge as two channels are required
[Sep  5 12:07:28] DEBUG[296496][C-00000003] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Sep  5 12:07:28] DEBUG[296496][C-00000003] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Sep  5 12:07:28] DEBUG[296496][C-00000003] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Sep  5 12:07:28] DEBUG[296496][C-00000003] bridge.c: Chose bridge technology simple_bridge
[Sep  5 12:07:28] DEBUG[296496][C-00000003] bridge.c: Bridge 4b254d46-227c-469f-bc28-ee75fc428a24 is already using the new technology.
[Sep  5 12:07:28] DEBUG[296496][C-00000003] bridge.c: Bridge 4b254d46-227c-469f-bc28-ee75fc428a24: 0x7f2824013580(PJSIP/RODCELL-00000005) is joining simple_bridge technology
[Sep  5 12:07:28] DEBUG[296496][C-00000003] stasis_bridges.c: Update: 0x7f27a40076e8  Old: 4b254d46-227c-469f-bc28-ee75fc428a24  New: 4b254d46-227c-469f-bc28-ee75fc428a24
[Sep  5 12:07:28] DEBUG[296496][C-00000003] stasis_bridges.c: Update: 0x7f27a40076e8  Old: 4b254d46-227c-469f-bc28-ee75fc428a24  New: 4b254d46-227c-469f-bc28-ee75fc428a24
[Sep  5 12:07:28] DEBUG[296496][C-00000003] chan_pjsip.c:  PJSIP/RODCELL-00000005: Indicated Media SSRC change
[Sep  5 12:07:28] DEBUG[296496][C-00000003] chan_pjsip.c:  PJSIP/RODCELL-00000005
[Sep  5 12:07:28] DEBUG[296486][C-00000003] bridge_channel.c: Bridge 4b254d46-227c-469f-bc28-ee75fc428a24: 0x7f282400c5a0(PJSIP/8112-00000004) is joining
[Sep  5 12:07:28] DEBUG[296486][C-00000003] bridge_channel.c: Bridge 4b254d46-227c-469f-bc28-ee75fc428a24: pushing 0x7f282400c5a0(PJSIP/8112-00000004)
[Sep  5 12:07:28] VERBOSE[296486][C-00000003] bridge_channel.c: Channel PJSIP/8112-00000004 joined 'simple_bridge' basic-bridge <4b254d46-227c-469f-bc28-ee75fc428a24>
[Sep  5 12:07:28] DEBUG[296486][C-00000003] stasis_bridges.c: Update: 0x7f282400cd98  Old: 4b254d46-227c-469f-bc28-ee75fc428a24  New: 4b254d46-227c-469f-bc28-ee75fc428a24
[Sep  5 12:07:28] DEBUG[296486][C-00000003] stasis_bridges.c: Update: 0x7f282400cd98  Old: 4b254d46-227c-469f-bc28-ee75fc428a24  New: 4b254d46-227c-469f-bc28-ee75fc428a24
[Sep  5 12:07:28] DEBUG[296486][C-00000003] bridge_native_rtp.c: Bridge '4b254d46-227c-469f-bc28-ee75fc428a24'.  Checking compatability for channels 'PJSIP/RODCELL-00000005' and 'PJSIP/8112-00000004'
[Sep  5 12:07:28] DEBUG[296486][C-00000003] bridge_native_rtp.c: Bridge '4b254d46-227c-469f-bc28-ee75fc428a24' can not use native RTP bridge as it was forbidden while getting details
[Sep  5 12:07:28] DEBUG[296486][C-00000003] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Sep  5 12:07:28] DEBUG[296486][C-00000003] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Sep  5 12:07:28] DEBUG[296486][C-00000003] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Sep  5 12:07:28] DEBUG[296486][C-00000003] bridge.c: Chose bridge technology simple_bridge
[Sep  5 12:07:28] DEBUG[296486][C-00000003] bridge.c: Bridge 4b254d46-227c-469f-bc28-ee75fc428a24 is already using the new technology.
[Sep  5 12:07:28] DEBUG[296486][C-00000003] bridge.c: Bridge 4b254d46-227c-469f-bc28-ee75fc428a24: 0x7f282400c5a0(PJSIP/8112-00000004) is joining simple_bridge technology
[Sep  5 12:07:28] DEBUG[296486][C-00000003] channel.c: Channel PJSIP/8112-00000004 setting read format path: ulaw -> ulaw
[Sep  5 12:07:28] DEBUG[296486][C-00000003] channel.c: Channel PJSIP/RODCELL-00000005 setting write format path: ulaw -> ulaw
[Sep  5 12:07:28] DEBUG[296486][C-00000003] channel.c: Channel PJSIP/RODCELL-00000005 setting read format path: ulaw -> ulaw
[Sep  5 12:07:28] DEBUG[296486][C-00000003] channel.c: Channel PJSIP/8112-00000004 setting write format path: ulaw -> ulaw
[Sep  5 12:07:28] DEBUG[296486][C-00000003] chan_pjsip.c:  PJSIP/8112-00000004: Indicated Stream topology request change
[Sep  5 12:07:28] DEBUG[296486][C-00000003] chan_pjsip.c:  PJSIP/8112-00000004: New topology:  <0:audio-0:audio:sendrecv (ulaw)> <1:video-1:video:sendonly (h264)>
[Sep  5 12:07:28] DEBUG[296486][C-00000003] chan_pjsip.c:  
[Sep  5 12:07:28] DEBUG[296486][C-00000003] chan_pjsip.c:  RC: 0
[Sep  5 12:07:28] DEBUG[296486][C-00000003] chan_pjsip.c:  PJSIP/8112-00000004
[Sep  5 12:07:28] DEBUG[296486][C-00000003] stasis_bridges.c: Update: 0x7f2824019078  Old: 4b254d46-227c-469f-bc28-ee75fc428a24  New: 4b254d46-227c-469f-bc28-ee75fc428a24
[Sep  5 12:07:28] DEBUG[296486][C-00000003] stasis_bridges.c: Update: 0x7f2824019078  Old: 4b254d46-227c-469f-bc28-ee75fc428a24  New: 4b254d46-227c-469f-bc28-ee75fc428a24
[Sep  5 12:07:28] DEBUG[295760] res_odbc.c: Releasing ODBC handle 0x117cf40 into pool
[Sep  5 12:07:28] DEBUG[296486][C-00000003] chan_pjsip.c:  PJSIP/8112-00000004: Indicated Media SSRC change
[Sep  5 12:07:28] DEBUG[296486][C-00000003] chan_pjsip.c:  PJSIP/8112-00000004
[Sep  5 12:07:28] DEBUG[296486][C-00000003] chan_pjsip.c:  PJSIP/8112-00000004: Indicated Private Cause Code
[Sep  5 12:07:28] DEBUG[296486][C-00000003] chan_pjsip.c:  PJSIP/8112-00000004
[Sep  5 12:07:28] DEBUG[295760] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0)
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Sep  5 12:07:28] DEBUG[295768] cdr.c: Finalized CDR for PJSIP/RODCELL-00000005 - start 1630854445.855912 answer 1630854448.944170 end 1630854448.945033 dur 3.089 bill 0.000 dispo ANSWERED
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Sep  5 12:07:28] DEBUG[295777] chan_pjsip.c:  PJSIP/8112-00000004:  <0:audio-0:audio:sendrecv (ulaw)> <1:video-1:video:sendonly (h264)>
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: New SDP? yes  Queued? no DP:  <0:audio-0:audio:sendrecv (ulaw)> <1:video-1:video:sendonly (h264)>  DA: none
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [1] in [0, 4294967295] gives [1](0)
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Delay sending reinvite because of outstanding transaction
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [1] in [0, 4294967295] gives [1](0)
[Sep  5 12:07:28] DEBUG[295777] chan_pjsip.c:  PJSIP/8112-00000004
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [90] in [0, 4294967295] gives [90](0)
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Sep  5 12:07:28] DEBUG[295760] devicestate.c: Changing state for PJSIP/RODCELL - state 2 (In use)
[Sep  5 12:07:28] DEBUG[295760] devicestate.c: No provider found, checking channel drivers for PJSIP - 8112
[Sep  5 12:07:28] DEBUG[295760] res_odbc.c: Reusing ODBC handle 0x117cf40 from class 'asterisk'
[Sep  5 12:07:28] DEBUG[295760] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ?
[Sep  5 12:07:28] DEBUG[295760] res_config_odbc.c: Parameter 1 ('id') = '8112'
[Sep  5 12:07:28] DEBUG[295760] res_odbc.c: Releasing ODBC handle 0x117cf40 into pool
[Sep  5 12:07:28] DEBUG[295760] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0)
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [1] in [0, 4294967295] gives [1](0)
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [1] in [0, 4294967295] gives [1](0)
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [90] in [0, 4294967295] gives [90](0)
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Sep  5 12:07:28] DEBUG[295760] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Sep  5 12:07:28] DEBUG[295760] devicestate.c: Changing state for PJSIP/8112 - state 2 (In use)
[Sep  5 12:07:28] VERBOSE[295776] res_pjsip_logger.c: <--- Received SIP request (347 bytes) from UDP:10.0.3.119:5060 --->
ACK sip:10.0.2.10:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.3.119:5060;rport;branch=z9hG4bK748306305
From: "8112" <sip:8112@10.0.2.10>;tag=108434922
To: <sip:110@10.0.2.10>;tag=d8387212-ed2e-45e2-a93b-83f6e853ba60
Call-ID: 156317553
CSeq: 21 ACK
Contact: <sip:8112@10.0.3.119:5060>
Max-Forwards: 70
User-Agent: eXosip/3.6.0
Content-Length: 0


[Sep  5 12:07:28] DEBUG[295776] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f279c0a9c18 for Request msg ACK/cseq=21 (rdata0x7f2810000eb8)
[Sep  5 12:07:28] DEBUG[295776] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000003d associated with dialog dlg0x7f279c0a9c18
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004 TSX State: Terminated  Inv State: CONNECTING
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The state change pertains to the endpoint '8112(PJSIP/8112-00000004)'
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f279c0b4728
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The current transaction state is Terminated
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The transaction state change event is USER
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The current inv state is CONNECTING
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: PJSIP/8112-00000004: INVITE delay check. tsx-state:Terminated
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004 TSX State: Terminated  Inv State: CONNECTING
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  Topology: Pending: (null topology)  Active:  <0:audio-0:audio:sendrecv (ulaw)> <1:video-1:video:recvonly (h264)>
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004 Event: RX_MSG  Inv State: CONFIRMED
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The state change pertains to the endpoint '8112(PJSIP/8112-00000004)'
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: There is no transaction involved in this state change
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The current inv state is CONFIRMED
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: PJSIP/8112-00000004: Received request
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Method is ACK
[Sep  5 12:07:28] DEBUG[295777] chan_pjsip.c:  PJSIP/8112-00000004
[Sep  5 12:07:28] DEBUG[295777] chan_pjsip.c:  PJSIP/8112-00000004
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004 Request: ACK 
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004 Handled request ACK  ? yes
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Sending delayed INVITE request
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: sending delayed INVITE request
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: New SDP? yes  Queued? yes DP:  <0:audio-0:audio:sendrecv (ulaw)> <1:video-1:video:sendonly (h264)>  DA:  <0:audio-0:audio:sendrecv (ulaw)> <1:video-1:video:recvonly (h264)>
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Pending media state exists
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Active media state exists and is not equal to pending
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: DP:  <0:audio-0:audio:sendrecv (ulaw)> <1:video-1:video:sendonly (h264)>
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: DA:  <0:audio-0:audio:sendrecv (ulaw)> <1:video-1:video:recvonly (h264)>
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: CP: (null topology)
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: CA:  <0:audio-0:audio:sendrecv (ulaw)> <1:video-1:video:recvonly (h264)>
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: DP:  <0:audio-0:audio:sendrecv (ulaw)> <1:video-1:video:sendonly (h264)>  DA:  <0:audio-0:audio:sendrecv (ulaw)> <1:video-1:video:recvonly (h264)>  CA:  <0:audio-0:audio:sendrecv (ulaw)> <1:video-1:video:recvonly (h264)>
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: slot: 0 DP: 0:audio-0:audio:sendrecv (ulaw)  DA: 0:audio-0:audio:sendrecv (ulaw)  CA: 0:audio-0:audio:sendrecv (ulaw)
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Same stream in all 3 states
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: All in the same state so nothing to do
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: slot: 1 DP: 1:video-1:video:sendonly (h264)  DA: 1:video-1:video:recvonly (h264)  CA: 1:video-1:video:recvonly (h264)
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Same stream in all 3 states
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Changed NP stream state from recvonly to sendonly
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Resetting default media states
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Running post-validation
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Topology:  <0:audio-0:audio:sendrecv (ulaw)> <1:video-1:video:sendonly (h264)>
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Checking stream 0:audio-0:audio:sendrecv (ulaw)
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Done with stream 0:audio-0:audio:sendrecv (ulaw)
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Checking stream 1:video-1:video:sendonly (h264)
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Done with stream 1:video-1:video:sendonly (h264)
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Valid
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: NP:  <0:audio-0:audio:sendrecv (ulaw)> <1:video-1:video:sendonly (h264)>
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: NP:  <0:audio-0:audio:sendrecv (ulaw)> <1:video-1:video:sendonly (h264)>
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Pruning and checking formats of streams
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Checking stream audio-0
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Found existing stream audio-0
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Checking stream video-1
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Found existing stream video-1
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Processing streams
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Processing stream 0:audio-0:audio:sendrecv (ulaw)
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004 Adding position 0
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  Using existing media_session
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004 Stream: 0:audio-0:audio:sendrecv (ulaw)
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_sdp_rtp.c:  PJSIP/8112-00000004 Type: audio 0:audio-0:audio:sendrecv (ulaw)
[Sep  5 12:07:28] DEBUG[295777] res_rtp_asterisk.c: (0x7f279c09e880) RTCP ignoring duplicate property
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_sdp_rtp.c:  RC: 1
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  Had handler
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Stream 0:audio-0:audio:sendrecv (ulaw) added
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Done with 0:audio-0:audio:sendrecv (ulaw)
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Processing stream 1:video-1:video:sendonly (h264)
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004 Adding position 1
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  Using existing media_session
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004 Stream: 1:video-1:video:sendonly (h264)
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_sdp_rtp.c:  PJSIP/8112-00000004 Type: video 1:video-1:video:sendonly (h264)
[Sep  5 12:07:28] DEBUG[295777] res_rtp_asterisk.c: (0x7f279c0599d0) RTCP ignoring duplicate property
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_sdp_rtp.c:  RC: 1
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  Had handler
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Stream 1:video-1:video:sendonly (h264) added
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Done with 1:video-1:video:sendonly (h264)
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Adding bundle groups (if available)
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Copying connection details
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Processing media 0
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Media 0 reset
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Processing media 1
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Media 1 has good existing connection info
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Method is INVITE
[Sep  5 12:07:28] DEBUG[295777] res_odbc.c: Reusing ODBC handle 0x117cf40 from class 'asterisk'
[Sep  5 12:07:28] DEBUG[295777] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_aors WHERE id = ?
[Sep  5 12:07:28] DEBUG[295777] res_config_odbc.c: Parameter 1 ('id') = '8112'
[Sep  5 12:07:28] DEBUG[295777] res_odbc.c: Releasing ODBC handle 0x117cf40 into pool
[Sep  5 12:07:28] DEBUG[295777] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[Sep  5 12:07:28] DEBUG[295777] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0)
[Sep  5 12:07:28] DEBUG[295777] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0)
[Sep  5 12:07:28] DEBUG[295777] config.c: extract uint from [60] in [0, 4294967295] gives [60](0)
[Sep  5 12:07:28] DEBUG[295777] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Sep  5 12:07:28] DEBUG[295777] config.c: extract uint from [2] in [0, 4294967295] gives [2](0)
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004
[Sep  5 12:07:28] DEBUG[295777] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.0.3.119'
[Sep  5 12:07:28] DEBUG[295777] res_pjsip/pjsip_resolver.c: Transport type for target '10.0.3.119' is 'UDP transport'
[Sep  5 12:07:28] DEBUG[295777] res_pjsip/pjsip_resolver.c: Target '10.0.3.119' is an IP address, skipping resolution
[Sep  5 12:07:28] DEBUG[295777] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 10.0.2.10:5060 (this may be re-written again later)
[Sep  5 12:07:28] DEBUG[295777] netsock2.c: Splitting '10.0.3.119' into...
[Sep  5 12:07:28] DEBUG[295777] netsock2.c: ...host '10.0.3.119' and port ''.
[Sep  5 12:07:28] VERBOSE[295777] res_pjsip_logger.c: <--- Transmitting SIP request (918 bytes) to UDP:10.0.3.119:5060 --->
INVITE sip:8112@10.0.3.119:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.2.10:5060;rport;branch=z9hG4bKPjab396e27-79b1-4f67-a2d9-bf58631c9ab6
From: <sip:110@10.0.2.10>;tag=d8387212-ed2e-45e2-a93b-83f6e853ba60
To: "8112" <sip:8112@10.0.2.10>;tag=108434922
Contact: <sip:10.0.2.10:5060>
Call-ID: 156317553
CSeq: 2192 INVITE
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Supported: 100rel, replaces, norefersub, histinfo
Max-Forwards: 70
User-Agent: Asterisk PBX 18.2.2
Content-Type: application/sdp
Content-Length:   331

v=0
o=- 0 3 IN IP4 10.0.2.10
s=Asterisk
c=IN IP4 10.0.2.10
t=0 0
m=audio 14930 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
m=video 29056 RTP/AVP 96
a=rtpmap:96 H264/90000
a=fmtp:96 packetization-mode=1;profile-level-id=4D0029
a=sendonly

[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004 TSX State: Calling  Inv State: CONFIRMED
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The state change pertains to the endpoint '8112(PJSIP/8112-00000004)'
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f279c06ab18)
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f279c06ab18
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The current transaction state is Calling
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The transaction state change event is TX_MSG
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c: The current inv state is CONFIRMED
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  Nothing delayed
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004 TSX State: Calling  Inv State: CONFIRMED
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  Topology: Pending:  <0:audio-0:audio:sendrecv (ulaw)> <1:video-1:video:sendonly (h264)>  Active:  <0:audio-0:audio:sendrecv (ulaw)> <1:video-1:video:recvonly (h264)>
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004: Sending session refresh SDP via re-INVITE
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004
[Sep  5 12:07:28] DEBUG[295777] res_pjsip_session.c:  PJSIP/8112-00000004

rodpp · September 5, 2021, 4:39pm

Here is a pastebin of the full log:

Thank you!

rodpp · September 8, 2021, 5:34am

Does anyone have a suggestion about what provoke the re-INVITE?

rodpp · September 9, 2021, 8:31pm

[Album] imgur.com

This figure shows how the video stream is offered on each step.

1- It starts with the Doorbell offering the video stream as a=sendonly (because it only has a camera and no display);
2- Next, the Asterisk server send a INVITE to the Android client using a=receiveonly;
3- The Android client send an OK to the Asterisk server with a=sendonly;
4- The Asterisk server send an OK to the Doorbell with a=receiveonly;
5- The Asterisk server send another INVITE with a=sendonly.

The audio stream is always sendreceive, so no problems with audio.

QUESTION
Is the Step 2 correct, or should Asterisk server offer to the Android cliente the video stream as a=sendonly?

david551 · September 10, 2021, 12:00am

Oops, I didn’t think the send v receive through clearly enough. I agree, if it is going to pass the restriction through, 2 needs to be sendonly. If 3 were sendonly, 5 should be inactive.

The Re-INVITE makes some sort of sense if it passing back the callee’s status. I’m pretty sure chan_sip doesn’t pass this information through.

rodpp · September 10, 2021, 6:35am

Could this sendonly/receiveonly erroneous change by Asterisk be a configuration problem in my Asterisk server?

I reviewed everything and couldn’t find anything related in Asterisk configuration.

Any hint will be much appreciated.

Thank you very much!

david551 · September 10, 2021, 9:51am

I don’t think it is a configuration change, but my familiarity with the code predates chan_pjsip and the rewrite of the SDP handling, so it will probably take me too long to work out what is happening.

jcolp · September 10, 2021, 9:51am

It’s unlikely to be configuration, but you’re using an old version of 18. You’d need to update to the latest before filing any issue.

rodpp · September 10, 2021, 1:53pm

Thank you all!

I’ll update the server and post here the result.

jcolp · September 10, 2021, 1:58pm

Issue reports go on the issue tracker[1]. The community forum is not an issue tracker.

[1] System Dashboard - Digium/Asterisk JIRA

rodpp · September 10, 2021, 2:16pm

I’ll update the Asterisk server and see how it behaves.

I’m very new in Asterisk, so don’t feel comfortable to report this yet. It’s much more likely an error in my side than an Asterisk issue…

rodpp · September 10, 2021, 6:00pm

I just updated to Asterisk 18.6.0 and tested again.

Unfortunately the new version has the same misbehavior.

As it’s unlikely to be configuration, maybe I should be filling an issue.

rodpp · September 10, 2021, 10:04pm

I tested with the following Asterisk versions:
16.8-cert11
16.20.0
18.2.2
18.6.0

All tested versions have the same behavior.

It’s a strong hint that the problem is something with my system, not Asterisk…

system · October 10, 2021, 10:04pm

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.

Topic		Replies	Views
Asterisk 1.8.9 - Re-invites issue Asterisk Support	8	1508	February 9, 2012
PJSIP Second INVITE after 200 Asterisk SIP	7	1094	September 11, 2018
Possible Major Bug: Reinvites with Multiple Switches Asterisk Support	1	367	June 16, 2007
Asterisk creating a second sip invite while only one is expected Asterisk Support	5	2733	May 12, 2021
Help with Hikvision Doorbell Registered to Asterisk Asterisk Endpoints	25	276	May 11, 2025

How to avoid re-INVITE - buggy endpoint

Related topics