Tdesktop: Calls via PulseAudio problems

Created on 18 May 2017  路  22Comments  路  Source: telegramdesktop/tdesktop

Steps to reproduce

  1. Use Telegram via PulseAudio.
  2. Accept call from someone or make a call.
  3. Try to start a conversation (if doesn't crash, see #3412).

Expected behaviour

Hear a crystal-clear voice without crashes, stops and other undefined behavior.

Actual behaviour

Noise and crackling audio (often, but not always - depends e.g. on drivers). Opening another audio application or pavucontrol stops a call with a message: "There seems to be a problem with audio playback on your computer. Please make sure that your computer's speakers and microphone are working and try again".

Configuration

Operating system:
Arch Linux, PulseAudio, Intel HD Audio
Version of Telegram Desktop:
1.1.2
Used theme:
Default

Logs:
Insert logs here (if necessary)


Attached recorded audio: voice-pulseaudio-test.ogg.zip

picture zaps166
👍5

Most helpful comment

Crashing here as well, no sign of dumps in tdata. Fedora 25, telegram 1.1.2. Sometimes it just hangs when starting the voice call or even answering. The last message on the popup is "connecting..." and then the whole app just disappears.

picture kmare on 19 May 2017
👍2

All 22 comments

Did you build it from sources or simply downloaded a prebuilt binary?

grishka picture grishka on 19 May 2017

Currently I have prebuilt binary. I think this is problem with pulseaudio implementation - v1.0.37 works much more stable.
About recorded audio: Sometimes I have similar problems when audio latency is too small in pulseaudio software.

zaps166 picture zaps166 on 19 May 2017

Same here crash when accepting a call on archlinux using the stable version (1.1.2).
Do the same on ubuntu of a friend

larfadin picture larfadin on 19 May 2017
👍2

@larfadin Do you have crash dumps in ~/.local/share/TelegramDesktop/tdata/dumps ? Or in ~/.TelegramDesktop/tdata/dumps ?

john-preston picture john-preston on 19 May 2017

There is no dumps in ~/.local/share/TelegramDesktop/tdata/dumps.
Telegram just suddenly shut down.

larfadin picture larfadin on 19 May 2017

Same issue here and no logs in dumps

cono picture cono on 19 May 2017

Currently I have infinity loop, debugger output (process pause):
gdb-pulse-tdesktop
Maybe it hangs instead of crash.

zaps166 picture zaps166 on 19 May 2017

Crashing here as well, no sign of dumps in tdata. Fedora 25, telegram 1.1.2. Sometimes it just hangs when starting the voice call or even answering. The last message on the popup is "connecting..." and then the whole app just disappears.

kmare picture kmare on 19 May 2017
👍2

@zaps166 this looks like a deadlock. What version do you see this in?

john-preston picture john-preston on 20 May 2017

Telegram 1.1.2 Linux x64, prebuilt binary. Deadlock happens only once, but crashes are very often.

zaps166 picture zaps166 on 20 May 2017

Telegram 1.1.4 alpha precompiled binary: running pavucontrol still aborts call with error. Once I had still corrupted audio

zaps166 picture zaps166 on 25 May 2017

Fragment from console output (I have two devices - sound card (default) and additional over HDMI):

D/tgvoip: out device #0: alsa_output.pci-0000_00_1b.0.analog-stereo (Wbudowany d藕wi臋k Analogowe stereo)
D/tgvoip: out device #1: alsa_output.pci-0000_01_00.1.hdmi-stereo-extra1 (GP104 High Definition Audio Controller Digital Stereo (HDMI 2))
D/tgvoip: in device #0: alsa_output.pci-0000_00_1b.0.analog-stereo.monitor (Monitor of Wbudowany d藕wi臋k Analogowe stereo)
D/tgvoip: in device #1: alsa_input.pci-0000_00_1b.0.analog-stereo (Wbudowany d藕wi臋k Analogowe stereo)
D/tgvoip: in device #2: alsa_output.pci-0000_01_00.1.hdmi-stereo-extra1.monitor (Monitor of GP104 High Definition Audio Controller Digital Stereo (HDMI 2))

I/tgvoip: jitter: resyncing, next timestamp = -120 (step=60, minDelay=2)
V/tgvoip: opus_encoder: setting bitrate to 17000
W/tgvoip: jitter: found no packet for timestamp -120 (last put = 0, lost = 0)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp -180 (last put = 0, lost = 0)
V/tgvoip: PLC
D/tgvoip: Current RTT via 91.108.8.4: 0,079, average: 0,079
D/tgvoip: Current RTT via 91.108.8.2: 0,083, average: 0,083
W/tgvoip: jitter: found no packet for timestamp -60 (last put = 0, lost = 0)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp -120 (last put = 0, lost = 0)
V/tgvoip: PLC
I/tgvoip: jitter: resyncing, next timestamp = -60 (step=60, minDelay=2)
W/tgvoip: jitter: found no packet for timestamp -60 (last put = 60, lost = 0)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp -120 (last put = 60, lost = 0)
V/tgvoip: PLC
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp -60 (last put = 120, lost = 0)
I/tgvoip: jitter: resyncing, next timestamp = 60 (step=60, minDelay=2)
D/tgvoip: Current RTT via 91.108.12.1: 0,288, average: 0,288
D/tgvoip: Current RTT via 91.108.12.5: 0,292, average: 0,292
I/tgvoip: jitter: resyncing, next timestamp = 180 (step=60, minDelay=2)
D/tgvoip: Current RTT via 91.108.16.2: 0,398, average: 0,398
D/tgvoip: Current RTT via 91.108.16.3: 0,401, average: 0,401
I/tgvoip: jitter: resyncing, next timestamp = 240 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 360 (step=60, minDelay=2)
W/tgvoip: jitter: found no packet for timestamp 360 (last put = 540, lost = 0)
I/tgvoip: jitter: resyncing, next timestamp = 480 (step=60, minDelay=2)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp 420 (last put = 600, lost = 0)
I/tgvoip: jitter: resyncing, next timestamp = 540 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 660 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 780 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 840 (step=60, minDelay=2)
V/tgvoip: opus_encoder: setting bitrate to 18000
I/tgvoip: jitter: resyncing, next timestamp = 960 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 1080 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 1140 (step=60, minDelay=2)
W/tgvoip: jitter: found no packet for timestamp 1140 (last put = 1260, lost = 0)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp 1140 (last put = 1320, lost = 0)
I/tgvoip: jitter: resyncing, next timestamp = 1260 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 1380 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 1440 (step=60, minDelay=2)
W/tgvoip: jitter: found no packet for timestamp 1440 (last put = 1620, lost = 0)
I/tgvoip: jitter: resyncing, next timestamp = 1560 (step=60, minDelay=2)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp 1500 (last put = 1680, lost = 0)
I/tgvoip: jitter: resyncing, next timestamp = 1680 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 1740 (step=60, minDelay=2)
W/tgvoip: jitter: found no packet for timestamp 1740 (last put = 1860, lost = 0)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp 1740 (last put = 1920, lost = 0)
V/tgvoip: opus_encoder: setting bitrate to 19000
I/tgvoip: jitter: resyncing, next timestamp = 1860 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 1980 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 2040 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 2160 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 2280 (step=60, minDelay=2)
D/tgvoip: new delay from stddev 1
I/tgvoip: jitter: resyncing, next timestamp = 2400 (step=60, minDelay=1)
I/tgvoip: jitter: resyncing, next timestamp = 2520 (step=60, minDelay=1)
I/tgvoip: jitter: resyncing, next timestamp = 2640 (step=60, minDelay=1)
I/tgvoip: jitter: resyncing, next timestamp = 2700 (step=60, minDelay=1)
I/tgvoip: jitter: resyncing, next timestamp = 2820 (step=60, minDelay=1)
I/tgvoip: jitter: resyncing, next timestamp = 2940 (step=60, minDelay=1)
V/tgvoip: opus_encoder: setting bitrate to 20000
I/tgvoip: jitter: resyncing, next timestamp = 3000 (step=60, minDelay=1)
W/tgvoip: jitter: found no packet for timestamp 3000 (last put = 3060, lost = 0)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp 3000 (last put = 3120, lost = 0)
I/tgvoip: jitter: resyncing, next timestamp = 3120 (step=60, minDelay=1)
I/tgvoip: jitter: resyncing, next timestamp = 3180 (step=60, minDelay=1)
I/tgvoip: jitter: resyncing, next timestamp = 3300 (step=60, minDelay=1)
I/tgvoip: jitter: resyncing, next timestamp = 3420 (step=60, minDelay=1)
I/tgvoip: jitter: resyncing, next timestamp = 3540 (step=60, minDelay=1)
I/tgvoip: jitter: resyncing, next timestamp = 3600 (step=60, minDelay=1)
I/tgvoip: jitter: resyncing, next timestamp = 3720 (step=60, minDelay=1)
W/tgvoip: jitter: found no packet for timestamp 3720 (last put = 3840, lost = 0)
I/tgvoip: jitter: resyncing, next timestamp = 3840 (step=60, minDelay=1)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp 3780 (last put = 3900, lost = 0)
I/tgvoip: jitter: resyncing, next timestamp = 3900 (step=60, minDelay=1)
I/tgvoip: jitter: resyncing, next timestamp = 4020 (step=60, minDelay=1)
I/tgvoip: jitter: resyncing, next timestamp = 4080 (step=60, minDelay=1)
I/tgvoip: jitter: resyncing, next timestamp = 4200 (step=60, minDelay=1)
W/tgvoip: jitter: found no packet for timestamp 4200 (last put = 4260, lost = 0)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp 4200 (last put = 4320, lost = 0)
I/tgvoip: jitter: resyncing, next timestamp = 4320 (step=60, minDelay=1)
I/tgvoip: jitter: resyncing, next timestamp = 4440 (step=60, minDelay=1)
I/tgvoip: jitter: resyncing, next timestamp = 4500 (step=60, minDelay=1)
E/tgvoip: Can't provide 25536 bytes of audio data at a time
I/tgvoip: jitter: resyncing, next timestamp = 4620 (step=60, minDelay=1)
E/tgvoip: Can't provide 25536 bytes of audio data at a time
E/tgvoip: Can't provide 25536 bytes of audio data at a time
E/tgvoip: Can't provide 25536 bytes of audio data at a time
V/tgvoip: new endpoint 0: 95.160.241.119:18724
W/tgvoip: Received reflector peer info, my=C9F91959:32265, peer=77F1A05F:18724
E/tgvoip: Can't provide 25536 bytes of audio data at a time
E/tgvoip: Audio I/O failed
V/tgvoip: Call state changed to 4
E/tgvoip: Can't provide 25536 bytes of audio data at a time
E/tgvoip: Can't provide 25536 bytes of audio data at a time
E/tgvoip: Can't provide 25536 bytes of audio data at a time
I/tgvoip: jitter: resyncing, next timestamp = 4740 (step=60, minDelay=1)
E/tgvoip: Can't provide 25536 bytes of audio data at a time
E/tgvoip: Can't provide 25536 bytes of audio data at a time
E/tgvoip: Can't provide 25536 bytes of audio data at a time
I/tgvoip: jitter: resyncing, next timestamp = 4800 (step=60, minDelay=1)
E/tgvoip: Can't provide 25536 bytes of audio data at a time
E/tgvoip: Can't provide 25536 bytes of audio data at a time
E/tgvoip: Can't provide 25536 bytes of audio data at a time
E/tgvoip: Can't provide 25536 bytes of audio data at a time
E/tgvoip: Can't provide 25536 bytes of audio data at a time
E/tgvoip: Can't provide 25536 bytes of audio data at a time
D/tgvoip: Entered VoIPController::~VoIPController
D/tgvoip: before shutdown socket
D/tgvoip: before join sendThread
E/tgvoip: tried to send null packet
I/tgvoip: === send thread exiting ===
D/tgvoip: before join recvThread
E/tgvoip: error receiving 88 / Operacja na obiekcie, kt贸ry nie jest gniazdem
E/tgvoip: Packet has zero length.
I/tgvoip: === recv thread exiting ===
D/tgvoip: before join tickThread
I/tgvoip: === tick thread exiting ===
D/tgvoip: before close socket
D/tgvoip: before free send buffers
D/tgvoip: before delete jitter buffer
D/tgvoip: before stop decoder
I/tgvoip: ==== decoder exiting ====
D/tgvoip: before delete audio input
D/tgvoip: before delete encoder
D/tgvoip: before delete audio output
D/tgvoip: before delete decoder
D/tgvoip: before delete echo canceller
D/tgvoip: Left VoIPController::~VoIPController

Log is taken when I had corrupted audio and then I've started pavucontrol which ends a call with an error.

pavucontrol ends a call with an error only when I have enabled HDMI in pulse audio as a second device (but audio goes through sound card). Other software hangs playing for a moment, pulse audio simple interface doesn't return any error at this moment (https://github.com/zaps166/QMPlay2/blob/master/src/modules/PulseAudio/Pulse.cpp#L133).

corrupted audio is for sure on playback stream and probably not on capture stream. Usually latency is too low (this is pulseaudio issue, it depends also on drivers...), but currently I can't reproduce it using lower latencies using pulseaudio simple interface. Long time ago I had this issue also on Skype and event QMPlay2 (with latencies lower than IIRC 80ms). Currently I have this issue only on Telegram (sometimes, which is still annoying).

Custom pulseaudio config changes:

resample-method = speex-float-5
default-sample-format = s32le
default-sample-rate = 48000
alternate-sample-rate = 48000
zaps166 picture zaps166 on 28 May 2017

@zaps166 yep, it says right there that it can't provide as much data at a time as the PA server is asking for and this has to deal with the latency, of course. This would also introduce a lot of jitter. Not that the library can't deal with excessive jitter, but it would degrade the audio quality noticeably. In your log, it asks for 25536 bytes, which is a whopping 266 ms of data (at 16 bit 48 khz). Am I understanding it correctly that you have latency set too high in PA config somewhere so it wants these huge buffers?

grishka picture grishka on 28 May 2017

Can't provide 25536 bytes of audio data at a time is probably something wrong when call ends or other error...

Currently I'm using VOIP and I have corrupted sound without this error (also on other applications in this moment when I play something, so Telegram sets my PA in bad state (too low latency for my PA?) :D). The console output doesn't much differ when sound is corrupted and not corrupted (sound can fix itself after e.g. a few minutes and then it plays correctly).

Am I understanding it correctly that you have latency set too high in PA config somewhere so it wants these huge buffers?

I didn't change in pulseaudio config anything else that what I pasted before :D

Btw. can I make a test call without calling to someone else?

Another log with corrupted sound (short testing call):

V/tgvoip: new endpoint 10001: 91.108.8.1:527
V/tgvoip: new endpoint 40006: 91.108.8.6:526
V/tgvoip: new endpoint 10004: 91.108.12.5:525
V/tgvoip: new endpoint 10002: 91.108.12.2:523
V/tgvoip: new endpoint 50002: 91.108.16.2:529
V/tgvoip: new endpoint 50003: 91.108.16.3:538
D/tgvoip: out device #0: alsa_output.pci-0000_00_1b.0.analog-stereo (Wbudowany d藕wi臋k Analogowe stereo)
D/tgvoip: out device #1: alsa_output.pci-0000_01_00.1.hdmi-stereo-extra1 (GP104 High Definition Audio Controller Digital Stereo (HDMI 2))
D/tgvoip: in device #0: alsa_output.pci-0000_00_1b.0.analog-stereo.monitor (Monitor of Wbudowany d藕wi臋k Analogowe stereo)
D/tgvoip: in device #1: alsa_input.pci-0000_00_1b.0.analog-stereo (Wbudowany d藕wi臋k Analogowe stereo)
D/tgvoip: in device #2: alsa_output.pci-0000_01_00.1.hdmi-stereo-extra1.monitor (Monitor of GP104 High Definition Audio Controller Digital Stereo (HDMI 2))
W/tgvoip: Set remote endpoints
I/tgvoip: update data saving mode, config 0, enabled 0, reqd by peer 0
W/tgvoip: Starting voip controller
V/tgvoip: trying bind to port 29914
D/tgvoip: Bound to local UDP port 29914
I/tgvoip: Receive thread starting
V/tgvoip: Call state changed to 2
I/tgvoip: Detected IPv4 connectivity, will not try IPv6
D/tgvoip: Received init
I/tgvoip: Peer version is 3
W/tgvoip: Received duplicated packet for seq 1
W/tgvoip: Received duplicated packet for seq 1
W/tgvoip: Received duplicated packet for seq 1
W/tgvoip: Received duplicated packet for seq 1
W/tgvoip: Received duplicated packet for seq 1
D/tgvoip: Received ping from 91.108.8.1:527
D/tgvoip: Received ping from 91.108.8.6:526
V/tgvoip: Call state changed to 2
D/tgvoip: Received init ack
I/tgvoip: peer version from init ack 3
I/tgvoip: before create audio io
V/tgvoip: starting encoder, packets per frame=3
I/tgvoip: decoder: packets per frame 3
W/tgvoip: jitter: found no packet for timestamp 5160 (last put = 0, lost = 0)
W/tgvoip: jitter: found no packet for timestamp 5220 (last put = 0, lost = 0)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp 5160 (last put = 0, lost = 0)
V/tgvoip: Call state changed to 3
V/tgvoip: PLC
I/tgvoip: Sending public endpoints request
D/tgvoip: Sending public endpoints request to 91.108.8.1:527
D/tgvoip: Received ping from 91.108.12.2:523
D/tgvoip: Received ping from 91.108.12.5:525
D/tgvoip: new delay from stddev 2
V/tgvoip: Sending ping to 91.108.8.1
V/tgvoip: Sending ping to 91.108.8.6
V/tgvoip: Sending ping to 91.108.12.5
V/tgvoip: Sending ping to 91.108.12.2
V/tgvoip: Sending ping to 91.108.16.2
V/tgvoip: Sending ping to 91.108.16.3
V/tgvoip: new endpoint 0: 95.160.241.119:25457
W/tgvoip: Received reflector peer info, my=C9F91959:29914, peer=77F1A05F:25457
V/tgvoip: opus_encoder: setting bitrate to 17000
D/tgvoip: Received ping from 91.108.16.2:529
D/tgvoip: Received ping from 91.108.16.3:538
D/tgvoip: Current RTT via 91.108.8.6: 0,076, average: 0,076
D/tgvoip: Current RTT via 91.108.8.1: 0,080, average: 0,080
V/tgvoip: Sending ping to 95.160.241.119
D/tgvoip: Current RTT via 95.160.241.119: 0,010, average: 0,010
I/tgvoip: jitter: resyncing, next timestamp = -120 (step=60, minDelay=2)
I/tgvoip: Switching to p2p (Inet)
W/tgvoip: jitter: found no packet for timestamp -120 (last put = 0, lost = 0)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp -180 (last put = 0, lost = 0)
V/tgvoip: PLC
I/tgvoip: jitter: resyncing, next timestamp = -60 (step=60, minDelay=2)
W/tgvoip: jitter: found no packet for timestamp -60 (last put = 60, lost = 0)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp -120 (last put = 60, lost = 0)
V/tgvoip: PLC
D/tgvoip: Current RTT via 91.108.12.5: 0,287, average: 0,287
D/tgvoip: Current RTT via 91.108.12.2: 0,291, average: 0,291
I/tgvoip: jitter: resyncing, next timestamp = 0 (step=60, minDelay=2)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp -60 (last put = 120, lost = 0)
D/tgvoip: Current RTT via 91.108.16.2: 0,399, average: 0,399
D/tgvoip: Current RTT via 91.108.16.3: 0,404, average: 0,404
I/tgvoip: jitter: resyncing, next timestamp = 120 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 240 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 300 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 420 (step=60, minDelay=2)
W/tgvoip: jitter: found no packet for timestamp 600 (last put = 540, lost = 0)
W/tgvoip: jitter: found no packet for timestamp 660 (last put = 540, lost = 1)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp 600 (last put = 540, lost = 2)
V/tgvoip: PLC
V/tgvoip: opus_encoder: setting bitrate to 18000
W/tgvoip: jitter: found no packet for timestamp 720 (last put = 540, lost = 3)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp 660 (last put = 540, lost = 4)
V/tgvoip: PLC
I/tgvoip: jitter: resyncing, next timestamp = 480 (step=60, minDelay=2)
W/tgvoip: jitter: found no packet for timestamp 480 (last put = 600, lost = 5)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp 420 (last put = 600, lost = 6)
V/tgvoip: PLC
I/tgvoip: jitter: resyncing, next timestamp = 540 (step=60, minDelay=2)
W/tgvoip: jitter: found no packet for timestamp 540 (last put = 660, lost = 7)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp 480 (last put = 660, lost = 8)
V/tgvoip: PLC
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp 540 (last put = 720, lost = 0)
I/tgvoip: jitter: resyncing, next timestamp = 660 (step=60, minDelay=2)
D/tgvoip: new delay from stddev 3
I/tgvoip: jitter: resyncing, next timestamp = 660 (step=60, minDelay=3)
W/tgvoip: jitter: found no packet for timestamp 660 (last put = 840, lost = 0)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp 660 (last put = 900, lost = 0)
I/tgvoip: jitter: resyncing, next timestamp = 780 (step=60, minDelay=3)
I/tgvoip: jitter: resyncing, next timestamp = 840 (step=60, minDelay=3)
I/tgvoip: jitter: resyncing, next timestamp = 960 (step=60, minDelay=3)
I/tgvoip: jitter: resyncing, next timestamp = 1080 (step=60, minDelay=3)
I/tgvoip: jitter: resyncing, next timestamp = 1200 (step=60, minDelay=3)
I/tgvoip: jitter: resyncing, next timestamp = 1260 (step=60, minDelay=3)
V/tgvoip: opus_encoder: setting bitrate to 19000
I/tgvoip: jitter: resyncing, next timestamp = 1380 (step=60, minDelay=3)
I/tgvoip: jitter: resyncing, next timestamp = 1440 (step=60, minDelay=3)
I/tgvoip: jitter: resyncing, next timestamp = 1560 (step=60, minDelay=3)
I/tgvoip: jitter: resyncing, next timestamp = 1680 (step=60, minDelay=3)
I/tgvoip: jitter: resyncing, next timestamp = 1800 (step=60, minDelay=3)
I/tgvoip: jitter: resyncing, next timestamp = 1860 (step=60, minDelay=3)
I/tgvoip: jitter: resyncing, next timestamp = 1980 (step=60, minDelay=3)
I/tgvoip: jitter: resyncing, next timestamp = 2040 (step=60, minDelay=3)
I/tgvoip: jitter: resyncing, next timestamp = 2160 (step=60, minDelay=3)
I/tgvoip: jitter: resyncing, next timestamp = 2280 (step=60, minDelay=3)
V/tgvoip: opus_encoder: setting bitrate to 20000
I/tgvoip: jitter: resyncing, next timestamp = 2400 (step=60, minDelay=3)
I/tgvoip: jitter: resyncing, next timestamp = 2460 (step=60, minDelay=3)
I/tgvoip: jitter: resyncing, next timestamp = 2580 (step=60, minDelay=3)
D/tgvoip: Entered VoIPController::~VoIPController
D/tgvoip: before shutdown socket
D/tgvoip: before join sendThread
E/tgvoip: error receiving 88 / Operacja na obiekcie, kt贸ry nie jest gniazdem
E/tgvoip: Packet has zero length.
I/tgvoip: === recv thread exiting ===
E/tgvoip: tried to send null packet
I/tgvoip: === send thread exiting ===
D/tgvoip: before join recvThread
D/tgvoip: before join tickThread
I/tgvoip: === tick thread exiting ===
D/tgvoip: before close socket
D/tgvoip: before free send buffers
D/tgvoip: before delete jitter buffer
D/tgvoip: before stop decoder
I/tgvoip: ==== decoder exiting ====
D/tgvoip: before delete audio input
D/tgvoip: before delete encoder
D/tgvoip: before delete audio output
D/tgvoip: before delete decoder
D/tgvoip: before delete echo canceller
D/tgvoip: Left VoIPController::~VoIPController

E/tgvoip: Audio I/O failed: another step to reproduce is:

  • start a call with disabled (in PA) HDMI output on nvidia card,
  • enable HDMI output in pavucontrol,
  • telegram stops a call with an error (only Telegram, other apps (QMPlay2, Audacity) still plays/captures audio).
zaps166 picture zaps166 on 28 May 2017

Btw. I found that pa_stream_connect_record uses playback attributes instead of recording (according to docs - fragsize should be set instead of tlength, prebuf, minreq).

Also (in playback) if tlength is in bytes (?) - 40ms is used. IIRC 80 ms (960*8 bytes for 48kHz Mono 16-bit) doesn't cause any problems in PA on different hardware configurations. Is it too large value for VOIP (I think that PA might not reach really low latencies whatever you set, but CPU usage is higher and it can cause sound corruption in some cases)?

zaps166 picture zaps166 on 28 May 2017

80 ms is reasonable for VoIP apps, I'll try that. Thanks for pointing out. I don't have any real hardware to test this on, but on my virtual machine it seems to work with whatever values I put in there.

grishka picture grishka on 28 May 2017

Took me a while to find this bug report. Am using 1.1.2 on Ubuntu 64 Bit 17.04. This is also happening to me in the sense that:

  1. If I make a call to someone and they answer, the whole Telegram app crashes with the "No Network Found trying to reconnect" window. It takes a second and reconnects again to the telegram app but I can repeat this every time by simply calling someone from the Desktop version. On the Phone it works perfectly.

  2. If I receive a call from anyone, it crashes with the same window mentioned on point 1.

luisalvarado picture luisalvarado on 28 May 2017

Opening another audio application or pavucontrol stops a call with a message: "There seems to be a problem with audio playback on your computer. Please make sure that your computer's speakers and microphone are working and try again".

Now (1.1.18) I've got abort instead:

D/tgvoip: === Updating voip config ===
V/tgvoip: audio_bitrate_step_decr -> 1000.000000
V/tgvoip: audio_bitrate_step_incr -> 1000.000000
V/tgvoip: audio_congestion_window -> 1024.000000
V/tgvoip: audio_frame_size -> 60.000000
V/tgvoip: audio_init_bitrate -> 16000.000000
V/tgvoip: audio_init_bitrate_edge -> 8000.000000
V/tgvoip: audio_init_bitrate_gprs -> 8000.000000
V/tgvoip: audio_init_bitrate_saving -> 8000.000000
V/tgvoip: audio_max_bitrate -> 20000.000000
V/tgvoip: audio_max_bitrate_edge -> 16000.000000
V/tgvoip: audio_max_bitrate_gprs -> 8000.000000
V/tgvoip: audio_max_bitrate_saving -> 8000.000000
V/tgvoip: jitter_losses_to_reset -> 20.000000
V/tgvoip: jitter_max_delay_20 -> 25.000000
V/tgvoip: jitter_max_delay_40 -> 15.000000
V/tgvoip: jitter_max_delay_60 -> 10.000000
V/tgvoip: jitter_max_slots_20 -> 50.000000
V/tgvoip: jitter_max_slots_40 -> 30.000000
V/tgvoip: jitter_max_slots_60 -> 20.000000
V/tgvoip: jitter_min_delay_20 -> 6.000000
V/tgvoip: jitter_min_delay_40 -> 4.000000
V/tgvoip: jitter_min_delay_60 -> 2.000000
V/tgvoip: jitter_resync_threshold -> 0.500000
V/tgvoip: use_system_aec -> true
V/tgvoip: use_system_ns -> true
V/tgvoip: new endpoint 40007: 91.108.8.7:523
V/tgvoip: new endpoint 40006: 91.108.8.6:529
V/tgvoip: new endpoint 10003: 91.108.12.3:522
V/tgvoip: new endpoint 10002: 91.108.12.2:534
V/tgvoip: new endpoint 50001: 91.108.16.1:527
V/tgvoip: new endpoint 50004: 91.108.16.4:535
W/tgvoip: Set remote endpoints
V/tgvoip: Adding endpoint: 91.108.8.7:523, UDP
V/tgvoip: Adding endpoint: 91.108.8.6:529, UDP
V/tgvoip: Adding endpoint: 91.108.12.3:522, UDP
V/tgvoip: Adding endpoint: 91.108.12.2:534, UDP
V/tgvoip: Adding endpoint: 91.108.16.1:527, UDP
V/tgvoip: Adding endpoint: 91.108.16.4:535, UDP
I/tgvoip: update data saving mode, config 0, enabled 0, reqd by peer 0
W/tgvoip: Starting voip controller
V/tgvoip: trying bind to port 20223
D/tgvoip: Bound to local UDP port 20223
I/tgvoip: Receive thread starting
V/tgvoip: Call state changed to 2
V/tgvoip: Sending UDP ping to 91.108.8.7:523
V/tgvoip: Sending UDP ping to 91.108.8.6:529
V/tgvoip: Sending UDP ping to 91.108.12.3:522
V/tgvoip: Sending UDP ping to 91.108.12.2:534
V/tgvoip: Sending UDP ping to 91.108.16.1:527
V/tgvoip: Sending UDP ping to 91.108.16.4:535
I/tgvoip: Detected IPv4 connectivity, will not try IPv6
D/tgvoip: Received init
I/tgvoip: Peer version is 3
W/tgvoip: Received duplicated packet for seq 1
W/tgvoip: Received duplicated packet for seq 1
W/tgvoip: Received duplicated packet for seq 1
W/tgvoip: Received duplicated packet for seq 1
W/tgvoip: Received duplicated packet for seq 1
V/tgvoip: Call state changed to 2
D/tgvoip: Received init ack
I/tgvoip: peer version from init ack 3
I/tgvoip: before create audio io
V/tgvoip: starting encoder, packets per frame=3
I/tgvoip: decoder: packets per frame 3
W/tgvoip: jitter: found no packet for timestamp -4276271305145676 (last put = 0, lost = 0)
W/tgvoip: jitter: found no packet for timestamp -4276271305145616 (last put = 0, lost = 0)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp -4276271305145676 (last put = 0, lost = 0)
I/tgvoip: Sending public endpoints request
D/tgvoip: Sending public endpoints request to 91.108.8.7:523
V/tgvoip: PLC
V/tgvoip: Call state changed to 3
I/tgvoip: jitter: resyncing, next timestamp = 0 (step=60, minDelay=3)
D/tgvoip: new delay from stddev 2
V/tgvoip: Sending ping to 91.108.8.7
V/tgvoip: Sending ping to 91.108.8.6
V/tgvoip: Sending ping to 91.108.12.3
V/tgvoip: Sending ping to 91.108.12.2
V/tgvoip: Sending ping to 91.108.16.1
V/tgvoip: Sending ping to 91.108.16.4
W/tgvoip: jitter: found no packet for timestamp 0 (last put = 180, lost = 0)
V/tgvoip: outstanding delay change: -40
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp -60 (last put = 180, lost = 0)
V/tgvoip: outstanding delay change: -20
V/tgvoip: PLC
V/tgvoip: new endpoint 0: 95.160.241.119:20034
W/tgvoip: Received reflector peer info, my=C9F91959:20223, peer=77F1A05F:20034
W/tgvoip: jitter: found no packet for timestamp 60 (last put = 180, lost = 0)
V/tgvoip: outstanding delay change: 0
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp 0 (last put = 180, lost = 0)
V/tgvoip: PLC
I/tgvoip: jitter: resyncing, next timestamp = 120 (step=60, minDelay=2)
V/tgvoip: opus_encoder: setting bitrate to 17000
D/tgvoip: Current RTT via 91.108.8.6: 0,077, average: 0,077
D/tgvoip: Current RTT via 91.108.8.7: 0,084, average: 0,084
V/tgvoip: Sending ping to 95.160.241.119
W/tgvoip: jitter: found no packet for timestamp 120 (last put = 240, lost = 0)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp 60 (last put = 240, lost = 0)
V/tgvoip: PLC
I/tgvoip: jitter: resyncing, next timestamp = 180 (step=60, minDelay=2)
V/tgvoip: Trying to recover late packet
W/tgvoip: jitter: found no packet for timestamp 120 (last put = 300, lost = 0)
D/tgvoip: Received ping from 95.160.241.119:20034
D/tgvoip: Received ping from 91.108.8.7:523
D/tgvoip: Received ping from 91.108.8.6:529
I/tgvoip: jitter: resyncing, next timestamp = 300 (step=60, minDelay=2)
D/tgvoip: Received ping from 91.108.12.3:522
D/tgvoip: Received ping from 91.108.12.2:534
D/tgvoip: Current RTT via 91.108.12.3: 0,297, average: 0,297
D/tgvoip: Current RTT via 91.108.12.2: 0,301, average: 0,301
I/tgvoip: jitter: resyncing, next timestamp = 420 (step=60, minDelay=2)
D/tgvoip: Received ping from 91.108.16.1:527
D/tgvoip: Received ping from 91.108.16.4:535
D/tgvoip: Current RTT via 91.108.16.1: 0,399, average: 0,399
D/tgvoip: Current RTT via 91.108.16.4: 0,403, average: 0,403
I/tgvoip: jitter: resyncing, next timestamp = 540 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 600 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 720 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 840 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 900 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 1020 (step=60, minDelay=2)
V/tgvoip: opus_encoder: setting bitrate to 18000
I/tgvoip: jitter: resyncing, next timestamp = 1140 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 1200 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 1320 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 1440 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 1500 (step=60, minDelay=2)
I/tgvoip: jitter: resyncing, next timestamp = 1620 (step=60, minDelay=2)
E/tgvoip: Can't provide 23616 bytes of audio data at a time
Assertion '!m->thread || !pa_thread_is_running(m->thread) || !in_worker(m)' failed at pulse/thread-mainloop.c:187, function pa_threaded_mainloop_unlock(). Aborting.
Przerwane
zaps166 picture zaps166 on 1 Aug 2017

Try after https://github.com/telegramdesktop/tdesktop/commit/a00941f7ce9e20251cf88424281286ea4aeaad6e

Aokromes picture Aokromes on 3 Jan 2018

I confirm the issue

(tested several linux machines, all have problems in varying degrees)

@john-preston fyi

proea picture proea on 10 Jul 2018

@zaps166 @proea Try on 1.3.14 :)

Aokromes picture Aokromes on 27 Aug 2018

@Aokromes looks more stable now

proea picture proea on 7 Nov 2018
Was this page helpful?
0 / 5 - 0 ratings

Related issues

whywhyy picture whywhyy  路  3Comments
JhonSane picture JhonSane  路  3Comments
Yanrishatum picture Yanrishatum  路  3Comments
slowaways picture slowaways  路  3Comments
matteotumiati picture matteotumiati  路  3Comments