sctp icon indicating copy to clipboard operation
sctp copied to clipboard

Ensure all INIT have a verification tag of 0 as per the spec

Open jmelancondev opened this issue 1 year ago • 6 comments

Description

We've been seeing issues with one of our tests that sometime hangs while opening a DataChannel between two peers. Looking at the detailed logs we've been seeing this pattern:

[Producer] sending INIT [Consumer] failed validating packet init chunk expects a verification tag of 0 on the packet when out-of-the-blue [Consumer] sending INIT [Producer] failed validating packet init chunk expects a verification tag of 0 on the packet when out-of-the-blue ...2 seconds pause... [Producer] sending INIT [Consumer] failed validating packet init chunk expects a verification tag of 0 on the packet when out-of-the-blue [Consumer] sending INIT [Producer] failed validating packet init chunk expects a verification tag of 0 on the packet when out-of-the-blue

and the data channel never opens

We've found out that there is a PR from a year ago in webrtc-rs that seems to fit exactly the issue we are hitting: webrtc-rs/webrtc#405

Where the fix was to ensure the init packet always uses the 0 tag, instead of using the Association state which might be different? We're just bringing that same fix here.

jmelancondev avatar Jul 09 '24 12:07 jmelancondev

Codecov Report

All modified and coverable lines are covered by tests :white_check_mark:

Project coverage is 81.66%. Comparing base (2600de3) to head (f7e04df). Report is 1 commits behind head on master.

Additional details and impacted files
@@           Coverage Diff           @@
##           master     #341   +/-   ##
=======================================
  Coverage   81.66%   81.66%           
=======================================
  Files          51       51           
  Lines        4384     4384           
=======================================
  Hits         3580     3580           
  Misses        661      661           
  Partials      143      143           
Flag Coverage Δ
go 81.66% <100.00%> (ø)
wasm 66.60% <100.00%> (ø)

Flags with carried forward coverage won't be shown. Click here to find out more.

:umbrella: View full report in Codecov by Sentry.
:loudspeaker: Have feedback on the report? Share it here.

codecov[bot] avatar Jul 10 '24 03:07 codecov[bot]

@jmelancongen Is this Pion on both sides when you see this happen? I would like to create a reproduce (I can help with that!)

Thank you so much for sending this PR over!

Sean-Der avatar Jul 10 '24 03:07 Sean-Der

I agree a reproducer or test would be nice. In the scenario where we are seeing this it is Pion on both sides so it should be doable. The specific test we are doing is a validation of our TURN provider, and I'm guessing the fact that there is a real network is important, I'm suspecting a specific packet being lost at the wrong moment during the initialization. I was lucky to find the webrtc-rs PR early so I haven't looked too deeply in the entire interaction, but we'll assemble the complete logs from the test and post them here and take a deeper look into it!

jmelancondev avatar Jul 10 '24 11:07 jmelancondev

Here is the SCTP handshake part of our test: sctp-handshake-hang.txt

From what I was told, the test runs every minute in multiple locations, and it reproduces the issue once every 2-3 weeks globally. I've boiled down the logs to these bits:

[00:10:46.9180-Dbg] [producer] [0xc0002401e0] sending INIT
[00:10:46.9631-Dbg] [consumer] [0xc0002723c0] sending INIT
[00:10:46.9632-Dbg] [consumer] [0xc0002723c0] chunkInit received in state 'CookieWait'
[00:10:46.9632-Dbg] [consumer] sending INIT ACK
[00:10:47.0227-Dbg] [producer] [0xc0002401e0] chunkInit received in state 'CookieWait'
[00:10:47.0227-Dbg] [producer] sending INIT ACK
[00:10:47.9187-Dbg] [producer] [0xc0002401e0] sending INIT
[00:10:47.9491-Wrn] [consumer] [0xc0002723c0] failed validating packet init chunk expects a verification tag of 0 on the packet when out-of-the-blue
[00:10:47.9632-Dbg] [consumer] [0xc0002723c0] sending INIT
[00:10:47.9954-Wrn] [producer] [0xc0002401e0] failed validating packet init chunk expects a verification tag of 0 on the packet when out-of-the-blue

I believe the specific problem stems from:

  • High enough latency that both sides send their INIT before receiving the other side
  • Both sides receive the INIT of the other
  • Both INIT ACK are lost

I'm not too sure how to isolate those conditions in a smaller self-contained reproducer though. Since it feels like it needs the relay to be triggered. I'm also not very familiar with the testing framework for pion sadly, but it might be easier to reproduce this way?

jmelancondev avatar Jul 11 '24 12:07 jmelancondev

Fantastic! I can write a test for that today, that will be pretty easy to reproduce.

Sean-Der avatar Jul 11 '24 13:07 Sean-Der

Sorry for the ping but did you have time to check on that? I'd would love to have the fix so we can remove a workaround on our side

jmelancondev avatar Aug 13 '24 18:08 jmelancondev

@jmelancongen Hello I was able to make a test for your PR https://github.com/pion/sctp/pull/359 once it's confirmed & reviewed, I'll merge yours :)

JoTurk avatar Jan 21 '25 21:01 JoTurk

Awesome that's great news. Thanks a lot for looking at it!

jmelancondev avatar Jan 22 '25 13:01 jmelancondev

I am so sorry @jmelancongen I lost track on this one.

Thank you @JoeTurki you are amazing! So appreciative of you getting into this stuff :)

I will merge this one, and then the test!

Sean-Der avatar Jan 24 '25 16:01 Sean-Der