Mixed audio resulting in "Failed to unprotect SRTP packet" error

[gardenia]

Hi,

I am using JVB with jicofo and mixed audio (FYI: via this crude patch to jicofo, http://pastebin.ca/3584941).

I am using audio only (no video).

the good: it seems to be mostly working.

the bad: a percentage of calls (maybe 20%) are failing and the webrtc android client is throwing (lots of) errors as follows:

E/libjingle( 6718): Failed to unprotect audio RTP packet: size=39, seqnum=14646, SSRC=1150943895
W/libjingle( 6718): Failed to unprotect SRTP packet, err=10
E/libjingle( 6718): Failed to unprotect audio RTP packet: size=39, seqnum=14647, SSRC=1150943895
W/libjingle( 6718): Failed to unprotect SRTP packet, err=10
E/libjingle( 6718): Failed to unprotect audio RTP packet: size=39, seqnum=14648, SSRC=1150943895
W/libjingle( 6718): Failed to unprotect SRTP packet, err=10
E/libjingle( 6718): Failed to unprotect audio RTP packet: size=39, seqnum=14649, SSRC=1150943895

I replicated the problematic behavior while tcpdumping on the server.

in my clientside logs I see this error:
W/libjingle(23074): Failed to unprotect SRTP packet, err=10
E/libjingle(23074): Failed to unprotect audio RTP packet: size=109, seqnum=32616, SSRC=2297436400

I then looked through the tcpdump in wireshark for the corresponding info and found this snippet:

it looks to me as if the error in the client logs corresponds exactly to this jump from seq 60076 in that SSRC to 32616. i.e. it seems to me that libsrtp on the clientside is unhappy with the backwards jump in sequence numbers.

here is the associated jvb.log (with redacted ips / hosts).
http://filebin.ca/2fG7hhJg3Hyh/jvb.log

I am also happy to share any other logs or captures with you that might help.

Note: that it is a totally vanilla setup apart from the addition of rtp-level-relay-type="mixer" to some of the XML attributes when creating channels.

is there any extra logging or information that I could enable to pinpoint the issue further?

I am happy to try any patches or suggestions people have.

I would also be grateful for any pointers to places in the code I could dig into as I have no experience with the jvb codebase so rough pointers of where to get started would be help.

[gardenia]

I enabled FINER log level and also added some extra logging in SRTPCryptoContext::transformPacket

the following snippet shows the sequence number on SSRC 344202399 jumping from 50315 to
and I can see the sequence number in this example jumping from 47939 back to 50315

I have captured a few examples of this and in all cases it seems to follow the pattern of:

• good sequence number on a given ssrc
• lots of logging in the ballpark of "Created SendStream"
• bad sequence number on same ssrc

can anyone point me at where or why in the code the sequence number might have been reset here? I think I'm zoning in on the problem here but I'm just not experienced enough with the code to join the dots.

Thanks

jvb_verbose.txt

[brianh5]

this is pretty interesting. we've seen srtp_unprotect errors in last-n but the cause is a bit more obvious there since there are legitimate gaps in stream forwarding, i wouldn't expect the audio mixing to have that problem. @gardenia was the jump in sequence numbers tied to any event that you were aware of? such as: client muting/unmuting/new client joining/client leaving, anything like that?

[gardenia]

@brianh5 no we couldn't correlate it to any user event such as mute/unmute. that was one of the first things we tried as an area of investigation since we had found some webrtc tickets in relation to that.

in all cases I'm aware of it seemed to be preceded with this piece of logging:
org.jitsi.impl.neomedia.device.MediaDeviceSession.trace() Set format of track 0 to opus/rtp, 48000.0 Hz, Stereo

anecdotally it seemed that the above (see jvb.txt in my last comment for larger log snippet) always seemed to precede the problem state. I was not able to establish what it was that was firing the above event (whether it was triggered by some in band media channel event sent from the client or whataver) but that state change seemed to be correlatable to the problem. whether this is actually relevant or not I'm not sure.

I'm pretty sure we did not see the problem until we started using mixed audio streams. but I can't be totally sure about that.

[matteocampana-zz]

Hi @brianh5 and @bgrozev, any updates on this issue?
We experienced the same issue sometimes with mixed audio.

[brianh5]

We've actually been seeing this more. Planning on adding some checks in audio egress to try and catch any odd sequence number jumps to see if that finds anything interesting.

[brianh5]

So we dug into this today and found out why it had been happening to us a lot recently. The change I described on the email list a couple days back about allowing the direction of a channel to be changed before the connection is set up caused this to happen to about 50% of clients for us.

Basically the send source can be recreated, and whenever it's recreated it generates a random sequence number to start sending from. If it gets recreated and generates a random sequence number that's very different from the last one sent, it could throw off the ROC calculations and cause the srtp unprotect error. Now for us, this is happening frequently because the initial direction change (when we set it to SENDRECV) is causing the send stream to get created, and then again later it's getting recreated when setFormat is called (based on receiving the first audio packet). This particular scenario doesn't explain why you'd be seeing this issue (since you don't have our change), but it's possible something else could be triggering a similar situation. Once we have a fix in to get what we need without triggering this scenario, we're gonna add some checks in the jitsi code to try catch if/when this same situation happens again (caused by something else, that would hopefully be the root cause as when you see it).

[matteocampana-zz]

I digged into the code of JVB, libjitsi and fmj and it is still not clear for me where the sequence numbers are recreated in the case of a conference with only audio and mixer enabled.
It does not seems to me that setFormat or setDirection change the sequence numbers, or probably I'm missing something.

There is this method in AudioMediaStreamImpl class (libjitsi) that recreates send streams upon every PropertyChangeEvent fired with a FIXME, I'm not sure if it could be related:

  /**
     * Receives and reacts to property change events: if the selected device
     * (for capture, playback or notifications) has changed, then create or
     * recreate the streams in order to use it. We want to listen to these
     * events, especially for those generated after the audio system has
     * changed.
     *
     * @param ev The event which may contain a audio system change event.
     */
    public void propertyChange(PropertyChangeEvent ev)
    {
        /*
         * FIXME It is very wrong to do the following upon every
         * PropertyChangeEvent fired by MediaServiceImpl. Moreover, it does not
         * seem right that we'd want to start this MediaStream upon a
         * PropertyChangeEvent (regardless of its specifics).
         */
        if (sendStreamsAreCreated)
            recreateSendStreams();
        else
            start();
    }

[brianh5]

@matteocampana yes setFormat/setDirection do not change the sequence numbers directly, however they can drive the (re)creation of send streams (like in the code you pasted), which will reset the sequence number. (you can see this in SendSsrcInfo.java::getSequenceNumber in fmj).

[matteocampana-zz]

OK I see thanks, btw for us it is very difficult to reproduce the issue.

[gardenia]

@bgrozev I happened to notice:

jitsi/libjitsi@17c31a0#diff-c725edb92e08af7f679165c1a161de40

is this in anyway related to this issue? the reason I ask is I am upgrading my local version of JVB and am unclear if I need to retain my crude patch for this issue or if it may have been resolved already?

[bgrozev]

@bgrozev I happened to notice:

jitsi/libjitsi@17c31a0#diff-c725edb92e08af7f679165c1a161de40

is this in anyway related to this issue?

Sorry for the late response. I don't think this is related, as it is on the receive side of the bridge.