Unknown opus error possibly related to phase_inversion parameter

[Vaalyn]

Describe the bug I'm seeing an issue with liquidsoap in AzuraCast where when trying to output an ogg opus stream to an IceCast server LS terminates because of an "Unkown opus error".

Link to related issue

When I look at the following log entries and the code of the lines mentioned I think the error has something to do with the new phase_inversion parameter for %opus:

...
2019/12/12 14:05:30 [clock.wallclock_main:2] Source brg_local_3 failed while streaming: Failure("Unknown opus error")!
2019/12/12 14:05:30 [clock.wallclock_main:3] Raised by primitive operation at file "opus.ml", line 181, characters 34-63
2019/12/12 14:05:30 [clock.wallclock_main:3] Called from file "ogg_formats/opus_encoder.ml", line 61, characters 9-108
...

Here is the full log output of liquidsoap after running the process:

2019/12/12 14:05:29 >>> LOG START
2019/12/12 14:05:29 [main:3] Liquidsoap 1.4.0
2019/12/12 14:05:29 [main:3] Using: bytes=[distributed with OCaml 4.02 or above] pcre=7.4.3 sedlex=2.1 menhirLib=20190924 dtools=0.4.1 duppy=0.8.0 cry=0.6.1 mm=0.5.0 ogg=0.5.2 vorbis=0.7.1 opus=0.1.3 mad=0.4.5 flac=0.1.5 flac.ogg=0.1.5 dynlink=[distributed with Ocaml] lame=0.3.3 fdkaac=0.3.1 samplerate=0.1.4 taglib=0.3.3 ssl=0.5.9 camomile=1.0.2 faad=0.4.0
2019/12/12 14:05:29 [frame:3] Using 44100Hz audio, 25Hz video, 44100Hz master.
2019/12/12 14:05:29 [frame:3] Frame size must be a multiple of 1764 ticks = 1764 audio samples = 1 video samples.
2019/12/12 14:05:29 [frame:3] Targetting 'frame.duration': 0.04s = 1764 audio samples = 1764 ticks.
2019/12/12 14:05:29 [frame:3] Frames last 0.04s = 1764 audio samples = 1 video samples = 1764 ticks.
2019/12/12 14:05:29 [decoder:3] Method "MAD" accepted "/usr/local/share/icecast/web/error.mp3".
2019/12/12 14:05:29 [sandbox:3] Running inside a docker container, disabling sandboxing..
2019/12/12 14:05:29 [video.converter:3] Couldn't find preferred video converter: gavl.
2019/12/12 14:05:29 [audio.converter:3] Using samplerate converter: libsamplerate.
2019/12/12 14:05:29 [harbor:3] Adding mountpoint '/' on port 8010
2019/12/12 14:05:29 [playlist_jingles:3] Loading playlist...
2019/12/12 14:05:29 [playlist_jingles:3] No mime type specified, trying autodetection.
2019/12/12 14:05:29 [playlist_jingles:3] Playlist treated as format application/x-mpegURL
2019/12/12 14:05:29 [playlist_jingles:3] Successfully loaded a playlist of 25 tracks.
2019/12/12 14:05:29 [playlist_blackys_jingles:3] Loading playlist...
2019/12/12 14:05:29 [playlist_blackys_jingles:3] No mime type specified, trying autodetection.
2019/12/12 14:05:29 [playlist_blackys_jingles:3] Playlist treated as format application/x-mpegURL
2019/12/12 14:05:29 [playlist_blackys_jingles:3] Successfully loaded a playlist of 3 tracks.
2019/12/12 14:05:29 [playlist_nightdj:3] Loading playlist...
2019/12/12 14:05:29 [playlist_nightdj:3] No mime type specified, trying autodetection.
2019/12/12 14:05:29 [decoder:3] Method "MAD" accepted "/var/azuracast/stations/brg/media/Jingles/katrina_hadley_-_brg_jingle_-28w_big_jim-29.mp3".
2019/12/12 14:05:29 [playlist_nightdj:3] Playlist treated as format application/x-mpegURL
2019/12/12 14:05:29 [playlist_nightdj:3] Successfully loaded a playlist of 608 tracks.
2019/12/12 14:05:29 [playlist_daydj:3] Loading playlist...
2019/12/12 14:05:29 [playlist_daydj:3] No mime type specified, trying autodetection.
2019/12/12 14:05:29 [lang:3] AzuraCast Raw Response: annotate:title="I Am No Hero [Remastered]",artist="MandoPony",duration="272.",song_id="3b34245825ef0769a38a1a05374418e2",media_id="20978",playlist_id="1":/var/azuracast/stations/brg/media/DayDj/mandopony_-_i_am_no_hero_-5Bremastered-5D.mp3
2019/12/12 14:05:29 [decoder:3] Method "MAD" accepted "/var/azuracast/stations/brg/media/Jingles/peter_new_-_brg_jingle.mp3".
2019/12/12 14:05:29 [decoder:3] Method "MAD" accepted "/var/azuracast/stations/brg/media/Jingles/brg_-_sendeplan.mp3".
2019/12/12 14:05:29 [decoder:3] Method "MAD" accepted "/var/azuracast/stations/brg/media/DayDj/mandopony_-_i_am_no_hero_-5Bremastered-5D.mp3".
2019/12/12 14:05:29 [playlist_daydj:3] Playlist treated as format application/x-mpegURL
2019/12/12 14:05:29 [playlist_daydj:3] Successfully loaded a playlist of 2686 tracks.
2019/12/12 14:05:29 [decoder:3] Method "MAD" accepted "/var/azuracast/stations/brg/media/NightDj/luna_jax_-_starry_starry_night_-28vincent_parody-29.mp3".
2019/12/12 14:05:29 [error_jingle:3] "/usr/local/share/icecast/web/error.mp3" is static, resolving once for all...
2019/12/12 14:05:29 [brg_next_song:3] Prepared "/var/azuracast/stations/brg/media/DayDj/mandopony_-_i_am_no_hero_-5Bremastered-5D.mp3" (RID 7).
2019/12/12 14:05:29 [brg_local_1:3] Connecting mount /stream for source@127.0.0.1...
2019/12/12 14:05:29 [decoder:3] Method "MAD" accepted "/var/azuracast/stations/brg/media/DayDj/spectra_-_peace_at_last..._-28neverlaststanding_remix-29.mp3".
2019/12/12 14:05:29 [brg_local_1:3] Connection setup was successful.
2019/12/12 14:05:29 [brg_local_2:3] Connecting mount /mobile for source@127.0.0.1...
2019/12/12 14:05:30 [brg_local_2:3] Connection setup was successful.
2019/12/12 14:05:30 [brg_local_3:3] Connecting mount /opus for source@127.0.0.1...
2019/12/12 14:05:30 [brg_local_3:3] Connection setup was successful.
2019/12/12 14:05:30 [clock.wallclock_main:3] Streaming loop starts, synchronized with wallclock.
2019/12/12 14:05:30 [brg_live_switch:3] Switch to brg_safe_fallback.
2019/12/12 14:05:30 [brg_safe_fallback:3] Switch to brg_radio_cue.
2019/12/12 14:05:30 [brg_requests_fallback:3] Switch to brg_autodj_fallback.
2019/12/12 14:05:30 [brg_autodj_fallback:3] Switch to audio_to_stereo_7689.
2019/12/12 14:05:30 [lang:3] AzuraCast Feedback Response: OK
2019/12/12 14:05:30 [clock.wallclock_main:2] Source brg_local_3 failed while streaming: Failure("Unknown opus error")!
2019/12/12 14:05:30 [clock.wallclock_main:3] Raised by primitive operation at file "opus.ml", line 181, characters 34-63
2019/12/12 14:05:30 [clock.wallclock_main:3] Called from file "ogg_formats/opus_encoder.ml", line 61, characters 9-108
2019/12/12 14:05:30 [clock.wallclock_main:3] Called from file "ogg_formats/opus_encoder.ml", line 66, characters 14-24
2019/12/12 14:05:30 [clock.wallclock_main:3] Called from file "ogg_formats/ogg_muxer.ml", line 217, characters 10-41
2019/12/12 14:05:30 [clock.wallclock_main:3] Called from file "encoder/ogg_encoder.ml", line 171, characters 27-50
2019/12/12 14:05:30 [clock.wallclock_main:3] Called from file "list.ml", line 110, characters 12-15
2019/12/12 14:05:30 [clock.wallclock_main:3] Called from file "encoder/ogg_encoder.ml", line 173, characters 8-26
2019/12/12 14:05:30 [clock.wallclock_main:3] Called from file "outputs/output.ml", line 254, characters 24-44
2019/12/12 14:05:30 [clock.wallclock_main:3] Called from file "outputs/output.ml", line 181, characters 8-24
2019/12/12 14:05:30 [clock.wallclock_main:3] Called from file "clock.ml", line 160, characters 17-25
2019/12/12 14:05:30 [brg_local_3:3] Closing connection...
2019/12/12 14:05:30 [main:3] Shutdown started!
2019/12/12 14:05:30 [main:3] Waiting for main threads to terminate...
2019/12/12 14:05:30 [brg_local_2:3] Closing connection...
2019/12/12 14:05:30 [brg_local_1:3] Closing connection...
2019/12/12 14:05:30 [clock.wallclock_main:3] Streaming loop stopped.
2019/12/12 14:05:30 [main:3] Threads terminated.
2019/12/12 14:05:30 [threads:3] Shutting down scheduler...
2019/12/12 14:05:30 [threads:3] Scheduler shut down.
2019/12/12 14:05:30 [threads:3] Waiting for queue threads to terminate...
2019/12/12 14:05:30 [threads:3] Queues shut down
2019/12/12 14:05:30 [server:3] Closing socket.
2019/12/12 14:05:30 [main:3] Cleaning downloaded files...
2019/12/12 14:05:30 [main:3] Freeing memory...

To Reproduce This is the part of the liquidsoap.liq where %opus is used:

output.icecast(%opus(samplerate=48000, bitrate=96, vbr="none", application="audio", channels=2, signal="music", complexity=10, max_bandwidth="full_band"), id="brony_radio_germany__test_stream_local_2", host = "127.0.0.1", port = 8030, password = "xxx", mount = "/opus", name = "Brony Radio Germany - Test Stream", description = "", genre = "Brony Musik", url = "https://www.bronyradiogermany.com", public = false, encoding = "UTF-8", radio)

I've also tried explicitly adding phase_inversion=true / phase_inversion=true to the %opus parameters but nothing changed, still terminating the process with the same error.

Expected behavior Liquidsoap should not encounter an "Unknown opus error" while encoding ogg opus.

Version details

• Host Debian 9
• Docker Container Ubuntu 18.04
• Liquidsoap 1.4.0

Install method opam

[smimram]

Strange, the following is working here:

s = sine()
output.file(%opus(samplerate=48000, bitrate=96, vbr="none", application="audio", channels=2, signal="music", complexity=10, max_bandwidth="full_band"), "/tmp/x.ogg", s)

[smimram]

My version of libopus0 is 1.3-1+b1, what is yours?

[Vaalyn]

My version of libopus0 is 1.3-1+b1, what is yours?

In Ubuntu 18.04 LTS this is the available version of libopus0 that we get through apt-get:

libopus0:
  Installed: 1.1.2-1ubuntu1
  Candidate: 1.1.2-1ubuntu1
  Version table:
 *** 1.1.2-1ubuntu1 500
        500 http://archive.ubuntu.com/ubuntu bionic/main amd64 Packages
        100 /var/lib/dpkg/status

[Vaalyn]

I've checked if the version of libopus0 is the cause of this issue and I can confirm that this is indeed the case. After adding the Ubuntu 19.04 package list and explicitly installing libopus0 version 1.3.1 on my dev machine the error does not happen anymore.

[ivellios1988]

Looks like the issue is also present in a version of Liquidsoap currently used in Centova Cast. I updated my installation of CC yesterday and since then I'm unable to start Liquidsoap. Logfile says:

2020/01/29 13:48:18 [ogg.muxer:3] output_autodj: Could not find any opus encoder.
2020/01/29 13:48:18 [clock.wallclock_main:2] Error when starting output output_autodj: Not_found!

And here's the complete log: https://pastebin.com/tfD9fXgB

[smimram]

The bug on centova cast is a different one: it says that you don't have an opus encoder installed (presumably you don't have the required libraries).

[ivellios1988]

Ok, I see. Is there any way to solve this? I'm running CC on Centos 7. OPUS libraries and opus-tools are installed.

[toots]

Ok, sorry for the flipflop. Ubuntu 18.04 (2 years old) has libopus 1.3 so it doesn't seem unreasonable to force it as the minimal version, which closes this ticket.. Thanks for reporting and investigating!

[toots]

Actually, I was wrong, 18.04 only has 1.1.2.. debian/stable, however, has 1.3. I still want to keep it this way as there's no reason to maintain code specific to versions that are already pretty outdated. I don't like to force that kind of thing on the user but I think the trade-off in the case here is in favor of forcing the most recent version.