Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

baresip keeps re-sending 200 Answering after receiving ACK #3029

Closed
juha-h opened this issue May 17, 2024 Discussed in #3028 · 28 comments
Closed

baresip keeps re-sending 200 Answering after receiving ACK #3029

juha-h opened this issue May 17, 2024 Discussed in #3028 · 28 comments

Comments

@juha-h
Copy link
Collaborator

juha-h commented May 17, 2024

I converted this to an issue. I don't know if re-sending of 200 response and call not being established is due to bug in SDP handing or something else. I suspect there is bug in baresip somewhere, since the same test with pjsip pjsua works fine.

Discussed in #3028

Originally posted by juha-h May 16, 2024
Can someone figure out why in below baresip keeps on re-sending 200 Answering after it has received ACK? ACK URI is the same as Contact URI of 200 response and also Call-IDs, To and From tags match. Why is the call not established?

16:15:22.416#
TCP 192.168.80.215:5060 -> 192.168.80.215:43708
INVITE sip:test@test.tutpro.com;gr=urn:uuid:9b21c1a8-dc58-a3d6-83d5-7be67cbe70ce SIP/2.0
Via: SIP/2.0/TCP 192.168.80.215;branch=z9hG4bKaad.e70b6ae7000000000000000000000000.0
To: <sip:test@test.tutpro.com>
From: <sip:click2dial@test.tutpro.com>;tag=0314d28d9107d990420d02e8ee696485-6a4090c4
CSeq: 1 INVITE
Call-ID: 664606ea65838@test.tutpro.com
Max-Forwards: 70
Content-Length: 131
User-Agent: OpenSIPg SIP Proxy (5.9.0-0b01 (x86_64/linux))
Contact: <sip:click2dial@192.168.80.215:5060>
Content-Type: application/sdp

v=0
o=click-to-dial 0 0 IN IP4 0.0.0.0
s=session
c=IN IP4 0.0.0.0
b=CT:1000
t=0 0
m=audio 9 RTP/AVP 0
a=rtpmap:0 PCMU/8000

ua: sipsess connect via TCP 192.168.80.215:5060 --> 192.168.80.215:43708
test@test.tutpro.com: account match for test
ua: using connection-address 0.0.0.0 of SDP offer
call: alloc with params laddr=?, af=AF_INET, use_rtp=1
call: use_video=1

16:15:22.416#
TCP 192.168.80.215:43708 -> 192.168.80.215:5060
SIP/2.0 180 Ringing
Via: SIP/2.0/TCP 192.168.80.215;branch=z9hG4bKaad.e70b6ae7000000000000000000000000.0
To: <sip:test@test.tutpro.com>;tag=9e08861de321af9d
From: <sip:click2dial@test.tutpro.com>;tag=0314d28d9107d990420d02e8ee696485-6a4090c4
CSeq: 1 INVITE
Call-ID: 664606ea65838@test.tutpro.com
Server: baresip v3.11.0 (x86_64/Linux)
Contact: <sip:test@test.tutpro.com;gr=urn:uuid:9b21c1a8-dc58-a3d6-83d5-7be67cbe70ce>
Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,NOTIFY,SUBSCRIBE,INFO,MESSAGE,UPDATE,REFER
Content-Length: 0

sip:test@test.tutpro.com: Incoming call from:  sip:click2dial@test.tutpro.com - audio-video: sendrecv-inactive - (press 'a' to accept)
alsa: reset: srate=8000, ch=1, num_frames=320, pcmfmt=S16_LE
alsa: playback started (default)
presence: ua=0x557214c9fa70 got event 10 (CALL_INCOMING)
alsa: stopping playback thread (default)
call: answering call on line 1 from sip:click2dial@test.tutpro.com with 200
stream: update 'audio'
stream: disable audio RTP receiver
stream: disable audio RTP sender
stream: enable audio RTP receiver
stream: update 'video'
stream: disable video RTP receiver
stream: disable video RTP sender
stream: enable video RTP receiver
presence: ua=0x557214c9fa70 got event 28 (CALL_LOCAL_SDP)

16:15:27.605#
TCP 192.168.80.215:43708 -> 192.168.80.215:5060
SIP/2.0 200 Answering
Via: SIP/2.0/TCP 192.168.80.215;branch=z9hG4bKaad.e70b6ae7000000000000000000000000.0
To: <sip:test@test.tutpro.com>;tag=9e08861de321af9d
From: <sip:click2dial@test.tutpro.com>;tag=0314d28d9107d990420d02e8ee696485-6a4090c4
CSeq: 1 INVITE
Call-ID: 664606ea65838@test.tutpro.com
Server: baresip v3.11.0 (x86_64/Linux)
Contact: <sip:test@test.tutpro.com;gr=urn:uuid:9b21c1a8-dc58-a3d6-83d5-7be67cbe70ce>
Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,NOTIFY,SUBSCRIBE,INFO,MESSAGE,UPDATE,REFER
Supported: gruu,path,outbound,replaces,norefersub
Content-Type: application/sdp
Content-Length: 212

v=0
o=- 3966051803 1648392487 IN IP6 ?
s=-
c=IN IP6 ?
t=0 0
m=audio 22582 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=sendrecv
a=ssrc:4276972270 cname:sip:test@test.tutpro.com
a=minptime:20
a=ptime:20
a=label:1

16:15:27.606#
TCP 192.168.80.215:5060 -> 192.168.80.215:43708
ACK sip:test@test.tutpro.com;gr=urn:uuid:9b21c1a8-dc58-a3d6-83d5-7be67cbe70ce SIP/2.0
Via: SIP/2.0/TCP 192.168.80.215;branch=z9hG4bKaad.e70b6ae7000000000000000000000000.0
From: <sip:click2dial@test.tutpro.com>;tag=0314d28d9107d990420d02e8ee696485-6a4090c4
Call-ID: 664606ea65838@test.tutpro.com
To: <sip:test@test.tutpro.com>;tag=9e08861de321af9d
CSeq: 1 ACK
User-Agent: OpenSIPg SIP Proxy (5.9.0-0b01 (x86_64/linux))
Content-Length: 0

... other requests/responses

16:15:29.107#
TCP 192.168.80.215:43708 -> 192.168.80.215:5060
SIP/2.0 200 Answering
Via: SIP/2.0/TCP 192.168.80.215;branch=z9hG4bKaad.e70b6ae7000000000000000000000000.0
To: <sip:test@test.tutpro.com>;tag=9e08861de321af9d
From: <sip:click2dial@test.tutpro.com>;tag=0314d28d9107d990420d02e8ee696485-6a4090c4
CSeq: 1 INVITE
Call-ID: 664606ea65838@test.tutpro.com
Server: baresip v3.11.0 (x86_64/Linux)
Contact: <sip:test@test.tutpro.com;gr=urn:uuid:9b21c1a8-dc58-a3d6-83d5-7be67cbe70ce>
Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,NOTIFY,SUBSCRIBE,INFO,MESSAGE,UPDATE,REFER
Supported: gruu,path,outbound,replaces,norefersub
Content-Type: application/sdp
Content-Length: 212

v=0
o=- 3966051803 1648392487 IN IP6 ?
s=-
c=IN IP6 ?
t=0 0
m=audio 22582 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=sendrecv
a=ssrc:4276972270 cname:sip:test@test.tutpro.com
a=minptime:20
a=ptime:20
a=label:1

16:15:31.107#
TCP 192.168.80.215:43708 -> 192.168.80.215:5060
SIP/2.0 200 Answering
Via: SIP/2.0/TCP 192.168.80.215;branch=z9hG4bKaad.e70b6ae7000000000000000000000000.0
To: <sip:test@test.tutpro.com>;tag=9e08861de321af9d
From: <sip:click2dial@test.tutpro.com>;tag=0314d28d9107d990420d02e8ee696485-6a4090c4
CSeq: 1 INVITE
Call-ID: 664606ea65838@test.tutpro.com
Server: baresip v3.11.0 (x86_64/Linux)
Contact: <sip:test@test.tutpro.com;gr=urn:uuid:9b21c1a8-dc58-a3d6-83d5-7be67cbe70ce>
Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,NOTIFY,SUBSCRIBE,INFO,MESSAGE,UPDATE,REFER
Supported: gruu,path,outbound,replaces,norefersub
Content-Type: application/sdp
Content-Length: 212

v=0
o=- 3966051803 1648392487 IN IP6 ?
s=-
c=IN IP6 ?
t=0 0
m=audio 22582 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=sendrecv
a=ssrc:4276972270 cname:sip:test@test.tutpro.com
a=minptime:20
a=ptime:20
a=label:1

... and so on

```</div>
@alfredh
Copy link
Collaborator

alfredh commented May 17, 2024

why is the connection address 0.0.0.0 ?

the network address in SDP is not set...

@juha-h
Copy link
Collaborator Author

juha-h commented May 17, 2024

It is 0.0.0.0, because there is no media in the call. Edit 0.0.0.0 is a valid IP address and thus according to RFC 8866 can be used on c= line.

@alfredh
Copy link
Collaborator

alfredh commented May 17, 2024

please take a look at this code:

https://github.com/baresip/baresip/blob/main/src/ua.c#L850

Can you please try to add some debug printf here and figure out what is going on ?

The problem is that the incoming offer has IPv4, while the answer has IPv6.
This is incorrect.

@juha-h
Copy link
Collaborator Author

juha-h commented May 17, 2024

I added some debug:

	if (sa_isset(laddr, SA_ADDR)) {
		sa_cpy(&cprm.laddr, laddr);
	}
	else if (sa_isset(&ua->dst, SA_ADDR)) {
		laddr = net_laddr_for(net, &ua->dst);
		info("ua: ****** laddr = %j\n", laddr);
		if (!sa_isset(laddr, SA_ADDR)) {
			warning("ua: no laddr for %j\n", &ua->dst);
			sa_init(&ua->dst, AF_UNSPEC);
			return EINVAL;
		}

		sa_init(&ua->dst, AF_UNSPEC);
		info("ua: ****** ua->dst = %j\n", ua->dst);
		sa_cpy(&cprm.laddr, laddr);
	} else {
		info("ua: ****** &ua->dst sa_isset is NOT set\n");
	}

and got:

ua: ****** &ua->dst sa_isset is NOT set

Soif (sa_isset(&ua->dst, SA_ADDR)) fails on 0.0.0.0. Is that correct?

@juha-h
Copy link
Collaborator Author

juha-h commented May 17, 2024

It is not set because of this test in sa_isset:

	case AF_INET:
		if (flag & SA_ADDR)
			if (INADDR_ANY == sa->u.in.sin_addr.s_addr)
				return false;

which means that in call_alloc cprm.a ==AF_UNSPEC.

Could that explain c=IN IP6 ? in 200 response?

Anyway, 0.0.0.0 clearly is a IP4 address and even if sa_isset on 0.0.0.0 returns false, address family of 0.0.0.0 should be AF_INET, not AF_UNSPEC.

@alfredh
Copy link
Collaborator

alfredh commented May 17, 2024

Thanks!

call_alloc should validate input parameters. For example af=UNSPEC is incorrect.

@juha-h
Copy link
Collaborator Author

juha-h commented May 17, 2024

Yes, and in this (0.0.0.0) case, af should be AF_INET.

@alfredh
Copy link
Collaborator

alfredh commented May 17, 2024

hi @juha-h please take a look at this logic:

https://github.com/baresip/re/blob/main/src/sdp/msg.c#L409

the address family info in SDP is encoded in two places:

example:

IN IP4 ::1

IN IP6 127.0.0.1

The address part may also contain a hostname, mainly used in the old days.

The sdp_connection function should parse the SDP message
to get a hint about which AF to use, but it should not use the actual address.
This is done in sdp_decode.

@juha-h
Copy link
Collaborator Author

juha-h commented May 17, 2024

In the test call, bareip knows the address family used in the offer and allocates the call with correct af param:

ua: using connection-address 0.0.0.0 of SDP offer
ua: ****** &ua->dst 0.0.0.0 sa_isset is NOT set
call: alloc with params laddr=?, af=AF_INET, use_rtp=1

But why does it use IP6 ? in the response?

@alfredh
Copy link
Collaborator

alfredh commented May 17, 2024

Here is a small patch, please test it if you want:

diff --git a/src/call.c b/src/call.c
index 48f6ddf5..15127208 100644
--- a/src/call.c
+++ b/src/call.c
@@ -833,6 +833,11 @@ int call_alloc(struct call **callp, const struct config *cfg, struct list *lst,
        debug("call: alloc with params laddr=%j, af=%s, use_rtp=%d\n",
              &prm->laddr, net_af2name(prm->af), prm->use_rtp);
 
+       if (prm->af == AF_UNSPEC)
+               return EAFNOSUPPORT;
+       if (!sa_isset(&prm->laddr, SA_ADDR))
+               return EINVAL;
+
        call = mem_zalloc(sizeof(*call), call_destructor);
        if (!call)
                return ENOMEM;
diff --git a/src/ua.c b/src/ua.c
index 5daeff45..ea9e358b 100644
--- a/src/ua.c
+++ b/src/ua.c
@@ -671,10 +671,15 @@ static int sdp_connection(const struct mbuf *mb, int *af, struct sa *sa)
        if (err)
                goto out;
 
+       sa_init(sa, *af);
+
        err = sa_set(sa, &pl2, pl_u32(&pl1));
        if (sa_af(sa) == AF_INET6 && sa_is_linklocal(sa))
                err |= net_set_dst_scopeid(net, sa);
 
+       if (!sa_isset(sa, SA_ADDR))
+               return EPROTO;
+
 out:
        return err;
 }

I am afraid that the whole logic is broken. The logic in ua.c is trying to connect to the SDP address
to figure out which local interface to use. This is quite fragile logic.

What happens if the SIP traffic is over IPv4 but the SDP contains IPv6 ?

@juha-h
Copy link
Collaborator Author

juha-h commented May 17, 2024

Now SDP in 200 response looks OK:

v=0
o=- 2052100033 1683209668 IN IP4 192.168.187.215
s=-
c=IN IP4 192.168.187.215
t=0 0
m=audio 32252 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=sendrecv
a=ssrc:984973977 cname:sip:test@test.tutpro.com
a=minptime:20
a=ptime:20
a=label:1

But the original issue still remains, i.e., baresip keeps re-sending 200 Answering after receiving ACK.

@juha-h
Copy link
Collaborator Author

juha-h commented May 17, 2024

Here is once more INVITE, 200, and ACK:

18:16:31.514#
TCP 192.168.187.215:5060 -> 192.168.187.215:33356
INVITE sip:test-0x563bb0fd0e10@192.168.187.215:33356;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 192.168.187.215;branch=z9hG4bKc49b.7f7d3e12000000000000000000000000.0
To: <sip:test@test.tutpro.com>
From: <sip:click2dial@test.tutpro.com>;tag=2dd3d4389fe3d66c5cb97dc370ab7d7b-77871c40
CSeq: 1 INVITE
Call-ID: 664774cf7d937@test.tutpro.com
Max-Forwards: 70
Content-Length: 131
User-Agent: OpenSIPg SIP Proxy (5.9.0-0b01 (x86_64/linux))
Contact: <sip:click2dial@192.168.187.215:5060>
Content-Type: application/sdp

v=0
o=click-to-dial 0 0 IN IP4 0.0.0.0
s=session
c=IN IP4 0.0.0.0
b=CT:1000
t=0 0
m=audio 9 RTP/AVP 0
a=rtpmap:0 PCMU/8000

ua: sipsess connect via TCP 192.168.187.215:5060 --> 192.168.187.215:33356
test@test.tutpro.com: selected for test-0x563bb0fd0e10
call: alloc with params laddr=192.168.187.215, af=AF_INET, use_rtp=1
call: use_video=1

18:16:31.515#
TCP 192.168.187.215:33356 -> 192.168.187.215:5060
SIP/2.0 180 Ringing
Via: SIP/2.0/TCP 192.168.187.215;branch=z9hG4bKc49b.7f7d3e12000000000000000000000000.0
To: <sip:test@test.tutpro.com>;tag=086025c05737e41e
From: <sip:click2dial@test.tutpro.com>;tag=2dd3d4389fe3d66c5cb97dc370ab7d7b-77871c40
CSeq: 1 INVITE
Call-ID: 664774cf7d937@test.tutpro.com
Server: baresip v3.12.0 (x86_64/Linux)
Contact: <sip:test-0x563bb0fd0e10@192.168.187.215:33356;transport=tcp>
Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,NOTIFY,SUBSCRIBE,INFO,MESSAGE,UPDATE,REFER
Content-Length: 0

sip:test@test.tutpro.com: Incoming call from:  sip:click2dial@test.tutpro.com - audio-video: sendrecv-inactive - (press 'a' to accept)
alsa: reset: srate=8000, ch=1, num_frames=320, pcmfmt=S16_LE
alsa: playback started (default)
presence: ua=0x563bb0fd0e10 got event 10 (CALL_INCOMING)
alsa: stopping playback thread (default)
call: answering call on line 1 from sip:click2dial@test.tutpro.com with 200
stream: update 'audio'
stream: disable audio RTP receiver
stream: disable audio RTP sender
stream: enable audio RTP receiver
stream: update 'video'
stream: disable video RTP receiver
stream: disable video RTP sender
stream: enable video RTP receiver
presence: ua=0x563bb0fd0e10 got event 28 (CALL_LOCAL_SDP)

18:16:38.998#
TCP 192.168.187.215:33356 -> 192.168.187.215:5060
SIP/2.0 200 Answering
Via: SIP/2.0/TCP 192.168.187.215;branch=z9hG4bKc49b.7f7d3e12000000000000000000000000.0
To: <sip:test@test.tutpro.com>;tag=086025c05737e41e
From: <sip:click2dial@test.tutpro.com>;tag=2dd3d4389fe3d66c5cb97dc370ab7d7b-77871c40
CSeq: 1 INVITE
Call-ID: 664774cf7d937@test.tutpro.com
Server: baresip v3.12.0 (x86_64/Linux)
Contact: <sip:test-0x563bb0fd0e10@192.168.187.215:33356;transport=tcp>
Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,NOTIFY,SUBSCRIBE,INFO,MESSAGE,UPDATE,REFER
Supported: gruu,replaces,norefersub
Content-Type: application/sdp
Content-Length: 238

v=0
o=- 4011905543 53170349 IN IP4 192.168.187.215
s=-
c=IN IP4 192.168.187.215
t=0 0
m=audio 29218 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=sendrecv
a=ssrc:3283568507 cname:sip:test@test.tutpro.com
a=minptime:20
a=ptime:20
a=label:1

18:16:38.999#
TCP 192.168.187.215:5060 -> 192.168.187.215:33356
ACK sip:test-0x563bb0fd0e10@192.168.187.215:33356;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 192.168.187.215;branch=z9hG4bKc49b.7f7d3e12000000000000000000000000.0
From: <sip:click2dial@test.tutpro.com>;tag=2dd3d4389fe3d66c5cb97dc370ab7d7b-77871c40
Call-ID: 664774cf7d937@test.tutpro.com
To: <sip:test@test.tutpro.com>;tag=086025c05737e41e
CSeq: 1 ACK
User-Agent: OpenSIPg SIP Proxy (5.9.0-0b01 (x86_64/linux))
Content-Length: 0
...

I have been reading RFC3261 and the ACK looks OK:

  • R-URI matches Contact URI of 200
  • To and From tags match those of the dialog
  • Call-ID matches that of the dialog
  • CSeq number is that of INVITE

Why is the call not established and baresip keeps of sending the 200 response?

@juha-h
Copy link
Collaborator Author

juha-h commented May 17, 2024

Any hints where I could place debug about handling of the ACK in order to find out if there is something wrong with it?

@alfredh
Copy link
Collaborator

alfredh commented May 17, 2024

https://github.com/baresip/re/blob/main/src/sipsess/listen.c#L129

this is where we receive ACK. Please try to add debug print here.

btw, did you try Route or Record-Route ?

@juha-h
Copy link
Collaborator Author

juha-h commented May 19, 2024

OK, I added lots of debug to listen.c starting with this:

static void ack_handler(struct sipsess_sock *sock, const struct sip_msg *msg)
{
	struct sipsess *sess;
	int err = 0;

	DEBUG_WARNING("**** at ack_handler\n");
       ...

Then I made call between two baresips to verify that the debug works and got:

presence: ua=0x55deb7bf8e70 got event 28 (CALL_LOCAL_SDP)
11:21:07.033#
TCP 192.168.187.215:46670 -> 192.168.187.215:5060
SIP/2.0 200 Answering
Record-Route: <sip:192.168.187.215;transport=tcp;lr>
Via: SIP/2.0/TCP 192.168.187.215;branch=z9hG4bK286b.9682f02f5f72b035315c4e361ea9d9c9.0;i=fa
Via: SIP/2.0/TCP 192.168.187.162:51568;received=192.168.187.162;branch=z9hG4bKfbfc4f2fdeb27151;rport=51568
To: <sip:test@test.tutpro.com>;tag=2f4d2a4945c21783
From: "Bar" <sip:bar@test.tutpro.com>;tag=933f5e4c30aafcc3
Call-ID: 733822cb9e1ec505
CSeq: 35401 INVITE
Server: baresip v3.12.0 (x86_64/Linux)
Contact: <sip:test@test.tutpro.com;gr=urn:uuid:9b21c1a8-dc58-a3d6-83d5-7be67cbe70ce>
Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,NOTIFY,SUBSCRIBE,INFO,MESSAGE,UPDATE,REFER
Supported: gruu,path,outbound,replaces,norefersub
Content-Type: application/sdp
Content-Length: 537

v=0
o=- 2168111687 1348604187 IN IP4 192.168.187.215
s=-
c=IN IP4 192.168.187.215
t=0 0
m=audio 33848 RTP/AVP 96 97 9 98 0 8 10
a=rtpmap:96 opus/48000/2
a=fmtp:96 stereo=0;sprop-stereo=0;maxaveragebitrate=28000;cbr=0;useinbandfec=1
a=rtpmap:97 AMR/8000
a=rtpmap:9 G722/8000
a=rtpmap:98 G7221/16000
a=fmtp:98 bitrate=32000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:10 telephone-event/8000
a=fmtp:10 0-15
a=sendrecv
a=ssrc:1102508081 cname:sip:test@test.tutpro.com
a=minptime:20
a=ptime:20
a=label:1
a=mid:0

1:21:07.341#
TCP 192.168.187.215:5060 -> 192.168.187.215:46670
ACK sip:test-0x55deb7bf8e70@192.168.187.215:46670;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 192.168.187.215;branch=z9hG4bK286b.0d995ce914a8470a0ed827d4aca2da63.0;i=fa
Via: SIP/2.0/TCP 192.168.187.162:51568;received=192.168.187.162;branch=z9hG4bK6890f69188d1b07c;rport=51568
Max-Forwards: 69
To: <sip:test@test.tutpro.com>;tag=2f4d2a4945c21783
From: "Bar" <sip:bar@test.tutpro.com>;tag=933f5e4c30aafcc3
Call-ID: 733822cb9e1ec505
CSeq: 35401 ACK
User-Agent: baresip v60.3.0 (Android 14/aarch64)
Content-Length: 0


sipsess: **** at ack_handler
sipsess: **** sess->estabh

Then I made the click2dial test where the problem appears (SIP proxy sends INVITE to baresip which replies with 200 and then gets ACK from SIP proxy). When baresip got the ACK, it didn't call the handler at all!

presence: ua=0x559438466e70 got event 28 (CALL_LOCAL_SDP)
11:26:59.033#
TCP 192.168.187.215:38018 -> 192.168.187.215:5060
SIP/2.0 200 Answering
Via: SIP/2.0/TCP 192.168.187.215;branch=z9hG4bK9a7e.c4d36c63000000000000000000000000.0
To: <sip:test@test.tutpro.com>;tag=87ed59caced13ca4
From: <sip:click2dial@test.tutpro.com>;tag=2dd3d4389fe3d66c5cb97dc370ab7d7b-adeee3ed
CSeq: 1 INVITE
Call-ID: 6649b7cf5418e@test.tutpro.com
Server: baresip v3.12.0 (x86_64/Linux)
Contact: <sip:test@test.tutpro.com;gr=urn:uuid:9b21c1a8-dc58-a3d6-83d5-7be67cbe70ce>
Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,NOTIFY,SUBSCRIBE,INFO,MESSAGE,UPDATE,REFER
Supported: gruu,path,outbound,replaces,norefersub
Content-Type: application/sdp
Content-Length: 235

v=0
o=- 32323647 57534931 IN IP4 192.168.187.215
s=-
c=IN IP4 192.168.187.215
t=0 0
m=audio 45424 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=sendrecv
a=ssrc:768223670 cname:sip:test@test.tutpro.com
a=minptime:20
a=ptime:20
a=label:1

11:26:59.035#
TCP 192.168.187.215:5060 -> 192.168.187.215:38018
ACK sip:test@test.tutpro.com;gr=urn:uuid:9b21c1a8-dc58-a3d6-83d5-7be67cbe70ce SIP/2.0
Via: SIP/2.0/TCP 192.168.187.215;branch=z9hG4bK9a7e.c4d36c63000000000000000000000000.0
From: <sip:click2dial@test.tutpro.com>;tag=2dd3d4389fe3d66c5cb97dc370ab7d7b-adeee3ed
Call-ID: 6649b7cf5418e@test.tutpro.com
To: <sip:test@test.tutpro.com>;tag=87ed59caced13ca4
CSeq: 1 ACK
User-Agent: OpenSIPg SIP Proxy (5.9.0-0b01 (x86_64/linux))
Content-Length: 0


11:26:59.038#
TCP 192.168.187.215:5060 -> 192.168.187.215:38018
REFER sip:test-0x559438466e70@192.168.187.215:38018;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 192.168.187.215;branch=z9hG4bK6a7e.b17b7de4000000000000000000000000.0
To: <sip:test@test.tutpro.com>;tag=87ed59caced13ca4
From: <sip:click2dial@test.tutpro.com>;tag=2dd3d4389fe3d66c5cb97dc370ab7d7b-adeee3ed
CSeq: 2 REFER
Call-ID: 6649b7cf5418e@test.tutpro.com
Max-Forwards: 70
Content-Length: 0
User-Agent: OpenSIPg SIP Proxy (5.9.0-0b01 (x86_64/linux))
Contact: <sip:click2dial@192.168.187.215:5060>
Referred-By: <sip:click2dial@test.tutpro.com>
Refer-To: sip:bar@test.tutpro.com
Refer-Sub: false
Supported: norefersub

Where do I need to add debug to find out why the ACK handler was not called?

@juha-h
Copy link
Collaborator Author

juha-h commented May 19, 2024

Here is the same test with pjsua and it does handle the ACK and changes call state to CONFIRMED:

5778) to TCP 192.168.187.215:5060:
SIP/2.0 200 OK
Via: SIP/2.0/TCP 192.168.187.215;received=192.168.187.215;branch=z9hG4bKc3c6.41b30474000000000000000000000000.0
Call-ID: 6649bbbd08536@test.tutpro.com
From: <sip:click2dial@test.tutpro.com>;tag=2dd3d4389fe3d66c5cb97dc370ab7d7b-af20fb79
To: <sip:test@test.tutpro.com>;tag=b132529a-5b18-464f-9fd3-fbb6d413c6d3
CSeq: 1 INVITE
Contact: <sip:test@192.168.187.215:54891;transport=TCP;ob>
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Content-Type: application/sdp
Content-Length:   269

v=0
o=- 3925097021 3925097022 IN IP4 192.168.187.215
s=pjmedia
b=AS:117
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0
c=IN IP4 192.168.187.215
b=TIAS:96000
a=rtcp:4001 IN IP4 192.168.187.215
a=sendrecv
a=rtpmap:0 PCMU/8000
a=ssrc:847787833 cname:300cd3cd6225186f

--end msg--
11:43:47.646            pjsua_app.c  .......Call 0 state changed to CONNECTING
>>> 11:43:47.647           pjsua_core.c  .RX 442 bytes Request msg ACK/cseq=1 (rdata0x55bc6e8c2748) from TCP 192.168.187.215:5060:
ACK sip:test@192.168.187.215:54891;transport=TCP;ob SIP/2.0
Via: SIP/2.0/TCP 192.168.187.215;branch=z9hG4bKc3c6.41b30474000000000000000000000000.0
From: <sip:click2dial@test.tutpro.com>;tag=2dd3d4389fe3d66c5cb97dc370ab7d7b-af20fb79
Call-ID: 6649bbbd08536@test.tutpro.com
To: <sip:test@test.tutpro.com>;tag=b132529a-5b18-464f-9fd3-fbb6d413c6d3
CSeq: 1 ACK
User-Agent: OpenSIPg SIP Proxy (5.9.0-0b01 (x86_64/linux))
Content-Length: 0


--end msg--
11:43:47.647            pjsua_app.c  .....Call 0 state changed to CONFIRMED

@juha-h
Copy link
Collaborator Author

juha-h commented May 19, 2024

Regarding btw, did you try Route or Record-Route ?, I didn't try because in this test there is no SIP proxy proxying the requests. My SIP proxy in this test acts as SIP UAC.

@alfredh
Copy link
Collaborator

alfredh commented May 19, 2024

Can you try to test both UDP and TCP transport to see if there is any difference ?

Please add some debug info to this function in transp.c:

static void sip_recv(struct sip *sip, const struct sip_msg *msg,
		     size_t start)
{
	struct le *le = sip->lsnrl.head;

	if (sip->traceh) {
		sip->traceh(false, msg->tp, &msg->src, &msg->dst,
			    msg->mb->buf + start, msg->mb->end - start,
			    sip->arg);
	}

	if (msg->req) {
		if (!have_essential_fields(msg)){
			(void)sip_reply(sip, msg, 400, "Bad Request");
			return;
		}
	}

	/* check consistency between CSeq method and that of request line */
	if (msg->req && pl_casecmp(&(msg->cseq.met), &(msg->met))){
		(void)sip_reply(sip, msg, 400, "Bad Request");
		return;
	}

	while (le) {
		struct sip_lsnr *lsnr = le->data;

		le = le->next;

		if (msg->req != lsnr->req)
			continue;

		if (lsnr->msgh(msg, lsnr->arg))
			return;
	}

	if (msg->req) {
		(void)re_fprintf(stderr, "unhandled request from %J: %r %r\n",
				 &msg->src, &msg->met, &msg->ruri);

		if (!pl_strcmp(&msg->met, "CANCEL"))
			(void)sip_reply(sip, msg,
					481, "Transaction Does Not Exist");
		else
			(void)sip_reply(sip, msg,
					501, "Not Implemented");
	}
	else {
		(void)re_fprintf(stderr, "unhandled response from %J:"
				 " %u %r (%r)\n", &msg->src,
				 msg->scode, &msg->reason, &msg->cseq.met);
	}
}

Does the ACK message get into the SIP-stack at all, i.e. are you running with SIP trace (-s) ?

@juha-h
Copy link
Collaborator Author

juha-h commented May 19, 2024

I'll try to test with UDP and will add debug. The packets that I showed in #3029 (comment), come from -s. So baresip is receiving the ACK.

Isn't there any debug or warning message if baresip drops a request without processing it?

@juha-h
Copy link
Collaborator Author

juha-h commented May 19, 2024

Changing transport to UDP didn't make any difference. Will add debug next.

@juha-h
Copy link
Collaborator Author

juha-h commented May 19, 2024

Found why ACK is not processed: Max-Forwards header is missing. BUT, why is 400 Bad Request not generated?

	/* check consistency between CSeq method and that of request line */
	if (msg->req && pl_casecmp(&(msg->cseq.met), &(msg->met))){
		(void)sip_reply(sip, msg, 400, "Bad Request");
		return;
	}

It does not appear in baresip trace nor in wireshark capture.

@alfredh
Copy link
Collaborator

alfredh commented May 19, 2024

Max-Forwards is a mandatory header for all requests. Could you please try to add it
to ACK and see if it works ?

It is not possible to reply to a ACK message:

https://github.com/baresip/re/blob/main/src/sip/reply.c#L34

You could try to add some extra logging where the messages is checked -> have_essential_fields()

@juha-h
Copy link
Collaborator Author

juha-h commented May 19, 2024

Missing Max-Forwards from ACK seems to be Kamailio bug, since it automatically generates the ACK.

Since there cannot be response to ACK, a warning or debug message should be generated instead.

@alfredh
Copy link
Collaborator

alfredh commented May 19, 2024

Related commit: commit f6db77d

@juha-h
Copy link
Collaborator Author

juha-h commented May 19, 2024

So if have_essential_field test fails, there should be check is msg is ACK and if so, generate a debug/warning message:

	if (msg->req) {
		if (!have_essential_fields(msg)){
			(void)sip_reply(sip, msg, 400, "Bad Request");
			return;
		}
	}

@juha-h
Copy link
Collaborator Author

juha-h commented May 19, 2024

How about this?

diff --git a/src/sip/transp.c b/src/sip/transp.c
index e62e9f1..69b88b4 100644
--- a/src/sip/transp.c
+++ b/src/sip/transp.c
@@ -334,7 +334,10 @@ static void sip_recv(struct sip *sip, const struct sip_msg *msg,
 
    if (msg->req) {
        if (!have_essential_fields(msg)){
-           (void)sip_reply(sip, msg, 400, "Bad Request");
+           if (!pl_strcmp(&msg->met, "ACK"))
+               DEBUG_WARNING("Received bad ACK request\n");
+           else
+               (void)sip_reply(sip, msg, 400, "Bad Request");
            return;
        }
    }

Should I create a PR?

@juha-h
Copy link
Collaborator Author

juha-h commented May 19, 2024

I could now close this, since the issue is solved. A new one should be opened about bogus SDP with ? address or a PR created to fix it.

@juha-h
Copy link
Collaborator Author

juha-h commented May 19, 2024

Closed due to new PR baresip/re#1124 and new issue #3033.

@juha-h juha-h closed this as completed May 19, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants