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

Enable echo cancellation during calls #1559

Open
Gert-dev opened this issue Mar 9, 2024 · 7 comments
Open

Enable echo cancellation during calls #1559

Gert-dev opened this issue Mar 9, 2024 · 7 comments

Comments

@Gert-dev
Copy link

Gert-dev commented Mar 9, 2024

Currently if calls are made, no echo cancellation is applied to the pipeline, making callers hear themselves if you use speakers rather than headphones.

By comparison, browsers such as Firefox automatically apply echo cancellation during WebRTC calls (Jitsi, Google Meet, Microsoft Teams, ...) to solve this problem. Perhaps Dino could utilize a similar approach.

@mar-v-in
Copy link
Member

Dino has support for echo cancelation and noise reduction. However it's only used if the system has the webrtc-audio-processing library installed at build time. Which OS and Dino build are you using?

@Gert-dev
Copy link
Author

Gert-dev commented Mar 11, 2024

We (both sides) are both on the Flatpak version of Dino.

In case it's relevant: I'm additionally applying noise reduction from my end, but the other end is not. I'm also using PipeWire on the host system.

Not sure why this wouldn't be working, is there anything I can do to debug this, perhaps? It is working for me in Firefox (also Flatpak-ed) with the above-mentioned platforms, though, so might be some configuration somewhere.

@mar-v-in
Copy link
Member

The Flatpak version should support it (although I actually never tried, but the library is used in the build). I also would't expect your local noise reduction to be the culprit (but you can try how it is without it). You can try if there is anything suspicious being logged when starting with env G_MESSAGES_DEBUG=rtp flatpak run im.dino.Dino

@Gert-dev
Copy link
Author

Ran the command and it gives the following output - don't spot too much out of the ordinary at first glance:

╰─ env G_MESSAGES_DEBUG=rtp flatpak run im.dino.Dino
(dino:2): rtp-DEBUG: 19:11:33.933: plugin.vala:422: Using TONOR TC-777 Audio Device Mono for outgoing audio as it's default
(dino:2): rtp-DEBUG: 19:11:33.933: plugin.vala:422: Using USB-C to 3.5mm Headphone Jack Adapter Digitaal stereo (IEC958) for incoming audio as it's default

(dino:2): rtp-WARNING **: 19:11:33.933: plugin.vala:415: No preferred device for outgoing video. Media will not be processed.
(dino:2): rtp-DEBUG: 19:11:33.940: plugin.vala:174: New clock.

(dino:2): libnice-CRITICAL **: 19:11:35.038: nice_agent_set_relay_info: assertion 'username' failed

(dino:2): libnice-CRITICAL **: 19:11:35.038: nice_agent_set_relay_info: assertion 'username' failed
(dino:2): rtp-DEBUG: 19:11:35.127: module.vala:92: using opusenc to encode opus
(dino:2): rtp-DEBUG: 19:11:35.200: module.vala:106: using opusdec to decode opus
(dino:2): rtp-DEBUG: 19:11:35.216: device.vala:437: Creating device pulsedevice3
(dino:2): rtp-DEBUG: 19:11:35.217: plugin.vala:39: Continue pipe after modifications
(dino:2): rtp-DEBUG: 19:11:35.219: codec_util.vala:403: Pipeline to encode audio opus without payloader: audioconvert name=pulsedevice3_opus_encoder_convert ! audioresample name=pulsedevice3_opus_encoder_resample ! queue ! opusenc audio-type=voice inband-fec=true name=pulsedevice3_opus_encoder_encode
(dino:2): rtp-DEBUG: 19:11:35.220: codec_util.vala:414: Pipeline to payload audio opus: rtpopuspay pt=111 name=pulsedevice3_opus_1649835581_rtp_pay
(dino:2): rtp-DEBUG: 19:11:35.220: device.vala:149: Payload for audio with opus using ssrc 1649835581, seqnum_offset 4294967295, timestamp_offset 0
(dino:2): rtp-DEBUG: 19:11:35.224: device.vala:437: Creating device pulsedevice6
(dino:2): rtp-DEBUG: 19:11:35.230: plugin.vala:39: Continue pipe after modifications
(dino:2): rtp-DEBUG: 19:11:35.230: voice_processor.vala:90: VoiceProcessor.setup(audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)48000, channels=(int)1)
(dino:2): rtp-DEBUG: 19:11:35.239: plugin.vala:113: pad added: send_rtcp_src_0
(dino:2): rtp-DEBUG: 19:11:35.239: plugin.vala:113: pad added: recv_rtcp_sink_0
(dino:2): rtp-DEBUG: 19:11:35.239: plugin.vala:113: pad added: send_rtp_src_0
(dino:2): rtp-DEBUG: 19:11:35.239: plugin.vala:126: pad send_rtp_src_0 for stream 0
(dino:2): rtp-DEBUG: 19:11:35.239: stream.vala:710: Link send_rtp_src_0 to audio send_rtp for audio
(dino:2): rtp-DEBUG: 19:11:35.239: plugin.vala:113: pad added: send_rtp_sink_0
(dino:2): rtp-DEBUG: 19:11:35.239: codec_util.vala:355: Pipeline to decode audio opus: queue ! rtpopusdepay name=decode_0_rtp_depay ! opusdec use-inband-fec=true name=decode_0_opus_decode ! audioconvert name=decode_0_convert ! audioresample name=decode_0_resample
(dino:2): rtp-DEBUG: 19:11:35.240: plugin.vala:113: pad added: recv_rtp_sink_0
(dino:2): rtp-DEBUG: 19:11:35.240: plugin.vala:39: Continue pipe after modifications
(dino:2): rtp-DEBUG: 19:11:35.241: plugin.vala:164: pulsedevice3 stream changed status to GST_STREAM_STATUS_TYPE_CREATE
(dino:2): rtp-DEBUG: 19:11:35.241: plugin.vala:164: pulsedevice3 stream changed status to GST_STREAM_STATUS_TYPE_ENTER
(dino:2): rtp-DEBUG: 19:11:35.241: plugin.vala:164: pulsedevice3 stream changed status to GST_STREAM_STATUS_TYPE_ENTER
(dino:2): rtp-DEBUG: 19:11:35.241: plugin.vala:189: Latency message from pulsedevice3: live=true, min_latency=10000000, max_latency=200000000
(dino:2): rtp-DEBUG: 19:11:35.241: plugin.vala:189: Latency message from pulsedevice6: live=false, min_latency=0, max_latency=18446744073709551615
(dino:2): rtp-DEBUG: 19:11:35.241: plugin.vala:164: mixer_pulsedevice6 stream changed status to GST_STREAM_STATUS_TYPE_CREATE
(dino:2): rtp-DEBUG: 19:11:35.241: plugin.vala:164: mixer_pulsedevice6 stream changed status to GST_STREAM_STATUS_TYPE_ENTER
(dino:2): rtp-DEBUG: 19:11:35.241: plugin.vala:164: queue3 stream changed status to GST_STREAM_STATUS_TYPE_CREATE
(dino:2): rtp-DEBUG: 19:11:35.241: plugin.vala:164: queue3 stream changed status to GST_STREAM_STATUS_TYPE_ENTER
(dino:2): rtp-DEBUG: 19:11:35.241: plugin.vala:189: Latency message from rtcp_sink_0: live=true, min_latency=0, max_latency=18446744073709551615
(dino:2): rtp-DEBUG: 19:11:35.241: plugin.vala:189: Latency message from rtp_sink_0: live=true, min_latency=30000000, max_latency=1200000000
(dino:2): rtp-DEBUG: 19:11:35.241: plugin.vala:164: rtcp_src_0 stream changed status to GST_STREAM_STATUS_TYPE_CREATE
(dino:2): rtp-DEBUG: 19:11:35.241: plugin.vala:164: rtp_src_0 stream changed status to GST_STREAM_STATUS_TYPE_CREATE
(dino:2): rtp-DEBUG: 19:11:35.241: plugin.vala:164: rtcp_src_0 stream changed status to GST_STREAM_STATUS_TYPE_ENTER
(dino:2): rtp-DEBUG: 19:11:35.241: plugin.vala:189: Latency message from decode_0_opus_decode: live=false, min_latency=120000000, max_latency=18446744073709551615
(dino:2): rtp-DEBUG: 19:11:35.241: plugin.vala:164: queue4 stream changed status to GST_STREAM_STATUS_TYPE_CREATE
(dino:2): rtp-DEBUG: 19:11:35.241: plugin.vala:164: rtp_src_0 stream changed status to GST_STREAM_STATUS_TYPE_ENTER
(dino:2): rtp-DEBUG: 19:11:35.241: plugin.vala:164: queue4 stream changed status to GST_STREAM_STATUS_TYPE_ENTER
(dino:2): rtp-DEBUG: 19:11:35.243: plugin.vala:189: Latency message from pulsedevice3_opus_encoder_encode: live=true, min_latency=30000000, max_latency=1220000000
(dino:2): rtp-DEBUG: 19:11:35.264: stream.vala:296: Setting up encryption with key params inline:jOGZT22cNcKarkSLjuNYHZ4BDH7knXg5u8h1Ep2J
(dino:2): rtp-DEBUG: 19:11:35.264: plugin.vala:189: Latency message from rtp_sink_0: live=true, min_latency=50000000, max_latency=1220000000
(dino:2): rtp-DEBUG: 19:11:35.870: stream.vala:687: RTCP is ready, resending rtcp: true
(dino:2): rtp-DEBUG: 19:11:35.870: stream.vala:563: Setting up decryption with key params inline:TSsORISXNsfpyvqEFveyFt5XZQmmVQPd9Zk5rnwc

(dino:2): rtp-WARNING **: 19:11:35.871: plugin.vala:415: No preferred device for outgoing video. Media will not be processed.
(dino:2): rtp-DEBUG: 19:11:35.894: plugin.vala:164: rtpjitterbuffer0 stream changed status to GST_STREAM_STATUS_TYPE_CREATE
(dino:2): rtp-DEBUG: 19:11:35.894: plugin.vala:164: rtpjitterbuffer0 stream changed status to GST_STREAM_STATUS_TYPE_ENTER
(dino:2): rtp-DEBUG: 19:11:35.894: plugin.vala:189: Latency message from rtpjitterbuffer0: live=true, min_latency=100000000, max_latency=18446744073709551615
(dino:2): rtp-DEBUG: 19:11:35.970: plugin.vala:113: pad added: recv_rtp_src_0_748876654_111
(dino:2): rtp-DEBUG: 19:11:35.970: stream.vala:691: New ssrc 748876654 with pad recv_rtp_src_0_748876654_111
(dino:2): rtp-DEBUG: 19:11:35.970: stream.vala:700: Link recv_rtp_src_0_748876654_111 to audio decode for audio
(dino:2): rtp-DEBUG: 19:11:35.970: plugin.vala:39: Continue pipe after modifications
(dino:2): rtp-DEBUG: 19:11:35.978: plugin.vala:189: Latency message from pulsedevice6: live=false, min_latency=230000000, max_latency=18446744073709551615
(dino:2): rtp-DEBUG: 19:11:35.978: plugin.vala:189: Latency message from pulsedevice6: live=false, min_latency=230000000, max_latency=18446744073709551615
(dino:2): rtp-DEBUG: 19:11:36.979: voice_processor_native.cpp: Stream delay metrics: median=0 std=168 poor_delays=44%
(dino:2): rtp-DEBUG: 19:11:37.129: plugin.vala:170: Message from rtpsession0 in pipeline: application/x-rtp-source-sdes, cname=(string)"user3252580676\@host-d249095c", tool=(string)GStreamer;
(dino:2): rtp-DEBUG: 19:11:37.301: stream.vala:687: RTCP is ready, resending rtcp: true
(dino:2): rtp-DEBUG: 19:11:37.510: plugin.vala:194: Pipe bus message: GST_MESSAGE_STREAM_START
(dino:2): rtp-DEBUG: 19:11:37.510: plugin.vala:189: Latency message from rtcp_sink_0: live=true, min_latency=0, max_latency=18446744073709551615
(dino:2): rtp-DEBUG: 19:11:37.975: device.vala:437: Creating device pulsedevice0
(dino:2): rtp-DEBUG: 19:11:37.975: plugin.vala:39: Continue pipe after modifications

(dino:2): rtp-WARNING **: 19:11:37.977: voice_processor_native.cpp: ProcessReverseStream -7

(dino:2): rtp-WARNING **: 19:11:37.977: voice_processor_native.cpp: ProcessReverseStream -7
(dino:2): rtp-DEBUG: 19:11:37.977: codec_util.vala:403: Pipeline to encode audio opus without payloader: audioconvert name=pulsedevice0_opus_encoder_convert ! audioresample name=pulsedevice0_opus_encoder_resample ! queue ! opusenc audio-type=voice inband-fec=true name=pulsedevice0_opus_encoder_encode
(dino:2): rtp-DEBUG: 19:11:37.978: codec_util.vala:414: Pipeline to payload audio opus: rtpopuspay pt=111 name=pulsedevice0_opus_1649835581_rtp_pay
(dino:2): rtp-DEBUG: 19:11:37.978: device.vala:149: Payload for audio with opus using ssrc 1649835581, seqnum_offset 20599, timestamp_offset 2781517263
(dino:2): rtp-DEBUG: 19:11:37.982: plugin.vala:39: Continue pipe after modifications
(dino:2): rtp-DEBUG: 19:11:37.982: voice_processor.vala:90: VoiceProcessor.setup(audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)48000, channels=(int)1)
(dino:2): rtp-DEBUG: 19:11:37.993: plugin.vala:39: Continue pipe after modifications
(dino:2): rtp-DEBUG: 19:11:37.993: plugin.vala:39: Continue pipe after modifications
(dino:2): rtp-DEBUG: 19:11:37.994: device.vala:548: Destroyed device pulsedevice3
(dino:2): rtp-DEBUG: 19:11:37.994: plugin.vala:164: pulsedevice0 stream changed status to GST_STREAM_STATUS_TYPE_CREATE
(dino:2): rtp-DEBUG: 19:11:37.994: plugin.vala:164: pulsedevice0 stream changed status to GST_STREAM_STATUS_TYPE_ENTER
(dino:2): rtp-DEBUG: 19:11:37.994: plugin.vala:164: pulsedevice0 stream changed status to GST_STREAM_STATUS_TYPE_ENTER
(dino:2): rtp-DEBUG: 19:11:37.994: plugin.vala:189: Latency message from pulsedevice0: live=true, min_latency=10000000, max_latency=200000000
(dino:2): rtp-DEBUG: 19:11:37.994: plugin.vala:164: queue5 stream changed status to GST_STREAM_STATUS_TYPE_CREATE
(dino:2): rtp-DEBUG: 19:11:37.994: plugin.vala:164: queue5 stream changed status to GST_STREAM_STATUS_TYPE_ENTER
(dino:2): rtp-DEBUG: 19:11:37.994: plugin.vala:189: Latency message from pulsedevice0_opus_encoder_encode: live=true, min_latency=30000000, max_latency=1220000000
(dino:2): rtp-DEBUG: 19:11:37.994: plugin.vala:164: queue3 stream changed status to GST_STREAM_STATUS_TYPE_LEAVE
(dino:2): rtp-DEBUG: 19:11:37.994: plugin.vala:164: pulsedevice3 stream changed status to GST_STREAM_STATUS_TYPE_LEAVE
(dino:2): rtp-DEBUG: 19:11:37.994: plugin.vala:164: pulsedevice3 stream changed status to GST_STREAM_STATUS_TYPE_LEAVE

(dino:2): rtp-CRITICAL **: 19:11:38.049: file /run/build/dino/plugins/rtp/src/stream.vala: line 416: uncaught error: SRTP encrypt failed: srtp_err_status_replay_fail (crypto-error-quark, 3)
(dino:2): rtp-DEBUG: 19:11:38.978: voice_processor_native.cpp: Stream delay metrics: median=-44 std=0 poor_delays=100%
(dino:2): rtp-DEBUG: 19:11:38.978: voice_processor_native.cpp: set stream_delay=106
(dino:2): rtp-DEBUG: 19:11:43.983: voice_processor_native.cpp: Stream delay metrics: median=220 std=108 poor_delays=100%
(dino:2): rtp-DEBUG: 19:11:43.983: voice_processor_native.cpp: set stream_delay=154
(dino:2): rtp-DEBUG: 19:11:55.245: voice_processor.vala:153: Gain: 255 -> 242
(dino:2): rtp-DEBUG: 19:11:56.264: voice_processor.vala:153: Gain: 242 -> 210
(dino:2): rtp-DEBUG: 19:11:58.997: voice_processor_native.cpp: Stream delay metrics: median=88 std=32 poor_delays=24%
(dino:2): rtp-DEBUG: 19:12:04.002: voice_processor_native.cpp: Stream delay metrics: median=208 std=32 poor_delays=69%
(dino:2): rtp-DEBUG: 19:12:04.963: voice_processor.vala:153: Gain: 210 -> 231
(dino:2): rtp-DEBUG: 19:12:05.981: voice_processor.vala:153: Gain: 231 -> 255

@mar-v-in
Copy link
Member

From the logs it looks as if you change the input device shortly after the call started (from pulsedevice3 to pulsedevice0)? It might be that this breaks the echo cancellation, as this is not very well tested.

Automatic gain correction seems to be kicking in and then reversing its decision to lower input gain. Also the poor_delays is way to high for correct echo cancellation to work. So something is definitely not working as it should.

Can you try if it works when you don't change the input device after start?

@Gert-dev
Copy link
Author

Gert-dev commented Mar 16, 2024

Thanks for the follow-up!

From the logs it looks as if you change the input device shortly after the call started (from pulsedevice3 to pulsedevice0)?

Yes, that's correct. I have two actual microphone devices, and the RNNoise source that I configured as mentioned in the OP. After Dino starts I switch to the RNNoise source to avoid keyboard noises from being picked up (though maybe Dino doesn't even need it if it has noise reduction).

Off-topic: Dino always selects the microphone as default the next time it starts, likely because this is also the default in GNOME (but the RNNoise source can't be the default in GNOME because its own source is the microphone setting, so it knows which source to filter and it would otherwise be filtering itself).

Can you try if it works when you don't change the input device after start?

👍 Will try as soon as I do another call (can take a few days), but will report back ASAP.

@Gert-dev
Copy link
Author

Gert-dev commented Mar 22, 2024

I tried without changing the input right after, and unfortunately it's still the same.

Are there perhaps other logs I could extract or view to help debug?

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