Memory leak with input.harbor and FLAC #9

th3hamm0r · 2020-04-08T08:03:23Z

Describe the bug
We are facing liquidsoap instances with constantly increasing memory usage. It seems like it has started with the customer's switch from mp3 to an Ogg/FLAC stream.
It also seems like the issue is related to the metadata inside the stream, as during the night, where the metadata density is very low, the memory keeps its level or grows very slow.
I don't know, if that helps: disconnects of the input stream do not change/free the memory.

Some notes to our setup and why FLAC seems to have the problem for us:

Our production-liquidsoap directly receives the FLAC stream and it suffers from the memory issue.
In our test-environment, we have one "relay"-instance of liquidsoap, which receives the FLAC stream and just forwards it as Ogg/Vorbis to the different dev environments with the liquidsoap-instances running our actual business logic. In this setup only the relay, which receives the FLAC, has the memory issue.

To Reproduce
Unfortunately, I think I cannot give you access to our customer's FLAC stream. It should have metadata. Our "relay" from above is actually dead simple:

live_source = audio_to_stereo(input.harbor(
    "live_input",
    buffer=5.,
    max=20.,
    port=2000,
    password="1337"
))

# relay the live stream to the local liquidsoap instance with our business logic
output.icecast(
    ...
)

# provide on-demand-stream for our dev environments
output.harbor(
    ...
)

Expected behavior
no leak :)

Version details

OS: Ubuntu 16.04
Versions: 1.1.1, 1.3.7, 1.4.1

Install method
Ubuntu package (1.1.1) and opam (1.3.7, 1.4.1)

The text was updated successfully, but these errors were encountered:

smimram · 2020-04-08T10:43:24Z

if you are looking for a quick fix, you could try disabling the native flac decoder and use ffmpeg instead?

toots · 2020-04-08T18:33:05Z

It would be great to be able to confirm that the problem comes from the flac decoder indeed. I'll try to reproduce and fix in time to push this to 1.4.2.

th3hamm0r · 2020-04-08T18:41:46Z

Thanks for your quick response! I haven't used ffmpeg with liquidsoap before, but I will try to set it up tomorrow.

th3hamm0r · 2020-04-09T13:04:45Z

I've tried to replace the native decoder with ffmpeg, but failed.
Actually the metadata doesn't get forwarded as with the native decoder, and the forwarded audio contains click noises. So I'm obviously doing it wrong. Is it actually possible for Ogg/flac (we receive it through an icecast-stream as "application/ogg") to be replaced by ffmpeg that easy? The click noises made me skeptical.

add_decoder(
    name="FLAC_EXT",
    description="Decode FLAC using ffmpeg",
    mimes=["application/ogg"],
    test=fun(file) -> -1,
    "/usr/bin/ffmpeg -c:a flac -i - -f wav -"
)
set("decoder.stream_decoders", ["FLAC_EXT"])

toots · 2020-04-10T14:27:51Z

I think we meant the internal ffmpeg decoder. For liquidsoap 1.4.1, you need to:

Install ocaml-ffmepg version 0.4.1
Recompile liquidsoap with it
Set it to accept application/ogg and disable the ogg decoder:

set("decoder.mime_types.ffmpeg",["application/ogg"]) # Or more if needed..
set("decoder.mime_types.ogg",[])

toots · 2020-04-12T16:29:09Z

I think that I can reproduce with:

set("log.level",4)
set("decoder.file_extensions.ffmpeg",[])
s = single("/tmp/bla.ogg")
clock.assign_new(sync="none",[s])
output.dummy(s)

toots · 2020-04-12T22:58:45Z

Looks pretty stable with vorbis so most likely an issue specific to FLAC, indeed.

toots · 2020-04-12T23:32:07Z

Pretty stable in pure flac decoding (after fixing a bug in the decoder!), so likely somewhere in ogg/flac decoding, specifically.

toots · 2020-04-13T00:03:46Z

Ok, looks like the issue is fixes in the current master for ocaml-flac. Going to prepare a bugfix backport for the 0.1.5 branch/release series. It'll be out later today.

toots · 2020-04-14T20:17:43Z

Fixed ocaml-flac is now in opam. You may want to update it to confirm that it does fix the issue on your end..

th3hamm0r · 2020-04-14T20:29:18Z

@toots thanks a lot!
I've already deployed it by pinning the 0.1.6 branch earlier today. Unfortunately it looks like it has still an increasing memory usage, but I will check it again tomorrow.

toots · 2020-04-14T21:13:00Z

Ho damn. I hope it stabilizes..

th3hamm0r · 2020-04-15T08:55:23Z

It still increases steadily :(
During the night (low metadata densitiy) it again slowed down a bit, in the morning it started increasing faster.
The main instance of our test-deployment now runs for 14 days and stays constantly at about 45MB. The relay which I've updated yesterday now runs for about 24 hours and consumes 118MB.
But I will keep it running for now.

Just to be sure that I've installed the update correctly yesterday:
I've pinned the new flac library with opam pin add flac https://github.com/savonet/ocaml-flac.git#0.1.6, which then recompiled liquidsoap 1.4.1. The log started with the following, which looks right to me:

2020/04/14 10:49:00 [main:3] Liquidsoap 1.4.1
2020/04/14 10:49:00 [main:3] Using: bytes=[distributed with OCaml 4.02 or above] pcre=7.4.3 sedlex=2.1 menhirLib=20200211 dtools=0.4.1 duppy=0.8.0 cry=0.6.4 mm=0.5.0 ogg=0.5.2 vorbis=0.7.1 mad=0.4.5 flac=0.1.6 flac.ogg=0.1.6 dynlink=[distributed with Ocaml] lame=0.3.3 samplerate=0.1.4 taglib=0.3.6 camomile=1.0.2

th3hamm0r · 2020-04-15T13:04:24Z

Based on your sample in https://github.com/savonet/liquidsoap/issues/1146#issuecomment-612641697 I've tried to simulate the stream we get from our customer, but I failed (my setup: one instance that produces an ogg-flac stream with single(...) and output.icecast, and one that receives it).
For some reason the receiving instance always disconnects on every track change, so obviously there is something missing on my producer-side.

While debugging my setup for the simulation, I increased the loglevel on the relay instance. I've appended parts of the log below.
What looks a bit suspicious to me is that this ogg-stream is somehow sequentialized, in contrast to my failed attempt to simulate it. So maybe that's also the reason why you weren't able to reproduce this specific issue?

Fyi: "relay_output" is the output.harbor for our dev environments and "local_icecast" is the output.icecast for the local LS-instance with our business logic (see https://github.com/savonet/liquidsoap/issues/1146#issue-596387116).

...
2020/04/15 13:46:14 [harbor:4] New client on port ******: ******
2020/04/15 13:46:14 [harbor:4] Header: User-Agent, value: omnia9/3.19.57.
2020/04/15 13:46:14 [harbor:4] HTTP GET request on /admin/metadata.
2020/04/15 13:46:14 [harbor:4] HTTP Arg: mount, value: /******.
2020/04/15 13:46:14 [harbor:4] HTTP Arg: song, value: ******.
2020/04/15 13:46:14 [harbor:4] HTTP Arg: mode, value: updinfo.
2020/04/15 13:46:14 [harbor:4] Request to update metadata for mount /****** on port ******
2020/04/15 13:46:14 [harbor:4] Client logged in.
2020/04/15 13:46:14 [harbor:4] Returned 405 for '/admin/metadata?mode=updinfo&mount=%2F******&song=******': Source format does not support ICY metadata update
2020/04/15 13:46:14 [decoder.ogg:5] Reached last page of logical stream 8b383
2020/04/15 13:46:14 [decoder.ogg:5] All data from stream 8b383 has been decoded
2020/04/15 13:46:14 [decoder.ogg:5] Found a ogg logical stream, serial: 8b384
2020/04/15 13:46:14 [decoder.ogg:5] Trying ogg/flac format
2020/04/15 13:46:14 [decoder.ogg:5] ogg/flac format detected for stream 8b384
2020/04/15 13:46:16 [input(dot)harbor_7243:4] End of track.
2020/04/15 13:46:16 [on_metadata_7246:5] Got metadata at position 1276: calling handler...
2020/04/15 13:46:16 [relay:3] on_metadata - [("title", "******"), ("vendor", "reference libFLAC 1.3.1 20141125")]
2020/04/15 13:46:16 [ogg.muxer:4] local_icecast: Setting end of track 294257ef.
2020/04/15 13:46:16 [ogg.muxer:4] local_icecast: Every ogg logical tracks have ended: setting end of stream.
2020/04/15 13:46:16 [ogg.muxer:4] local_icecast: Starting new sequentialized ogg stream.
2020/04/15 13:46:16 [ogg.muxer:4] local_icecast: Starting all streams
2020/04/15 13:46:16 [ogg.muxer:4] relay_output: Setting end of track 3322c18e.
2020/04/15 13:46:16 [ogg.muxer:4] relay_output: Every ogg logical tracks have ended: setting end of stream.
2020/04/15 13:46:17 [ogg.muxer:4] relay_output: Starting new sequentialized ogg stream.
2020/04/15 13:46:17 [ogg.muxer:4] relay_output: Starting all streams
2020/04/15 13:46:35 [harbor:4] New client on port ******: ******
2020/04/15 13:46:35 [harbor:4] Header: User-Agent, value: omnia9/3.19.57.
2020/04/15 13:46:35 [harbor:4] HTTP GET request on /admin/metadata.
2020/04/15 13:46:35 [harbor:4] HTTP Arg: mount, value: /******.
2020/04/15 13:46:35 [harbor:4] HTTP Arg: song, value: ******.
2020/04/15 13:46:35 [harbor:4] HTTP Arg: mode, value: updinfo.
2020/04/15 13:46:35 [harbor:4] Request to update metadata for mount /****** on port ******
2020/04/15 13:46:35 [harbor:4] Client logged in.
2020/04/15 13:46:35 [harbor:4] Returned 405 for '/admin/metadata?mode=updinfo&mount=%2F******&song=******': Source format does not support ICY metadata update
2020/04/15 13:46:35 [decoder.ogg:5] Reached last page of logical stream 8b384
2020/04/15 13:46:35 [decoder.ogg:5] All data from stream 8b384 has been decoded
2020/04/15 13:46:35 [decoder.ogg:5] Found a ogg logical stream, serial: 8b385
2020/04/15 13:46:35 [decoder.ogg:5] Trying ogg/flac format
2020/04/15 13:46:35 [decoder.ogg:5] ogg/flac format detected for stream 8b385
2020/04/15 13:46:39 [input(dot)harbor_7243:4] End of track.
2020/04/15 13:46:39 [on_metadata_7246:5] Got metadata at position 120: calling handler...
2020/04/15 13:46:39 [relay:3] on_metadata - [("title", "******"), ("vendor", "reference libFLAC 1.3.1 20141125")]
2020/04/15 13:46:39 [ogg.muxer:4] relay_output: Setting end of track e7e5ef1.
2020/04/15 13:46:39 [ogg.muxer:4] relay_output: Every ogg logical tracks have ended: setting end of stream.
2020/04/15 13:46:39 [ogg.muxer:4] relay_output: Starting new sequentialized ogg stream.
2020/04/15 13:46:39 [ogg.muxer:4] relay_output: Starting all streams
2020/04/15 13:46:39 [ogg.muxer:4] local_icecast: Setting end of track 2d27fb6.
2020/04/15 13:46:39 [ogg.muxer:4] local_icecast: Every ogg logical tracks have ended: setting end of stream.
2020/04/15 13:46:39 [ogg.muxer:4] local_icecast: Starting new sequentialized ogg stream.
2020/04/15 13:46:39 [ogg.muxer:4] local_icecast: Starting all streams
2020/04/15 13:49:18 [harbor:4] New client on port ******: ******
2020/04/15 13:49:18 [harbor:4] Header: User-Agent, value: omnia9/3.19.57.
2020/04/15 13:49:18 [harbor:4] HTTP GET request on /admin/metadata.
2020/04/15 13:49:18 [harbor:4] HTTP Arg: mount, value: /******.
2020/04/15 13:49:18 [harbor:4] HTTP Arg: song, value: ******.
2020/04/15 13:49:18 [harbor:4] HTTP Arg: mode, value: updinfo.
2020/04/15 13:49:18 [harbor:4] Request to update metadata for mount /****** on port ******
2020/04/15 13:49:18 [harbor:4] Client logged in.
2020/04/15 13:49:18 [harbor:4] Returned 405 for '/admin/metadata?mode=updinfo&mount=%2F******&song=******': Source format does not support ICY metadata update
2020/04/15 13:49:18 [decoder.ogg:5] Reached last page of logical stream 8b385
2020/04/15 13:49:18 [decoder.ogg:5] All data from stream 8b385 has been decoded
2020/04/15 13:49:18 [decoder.ogg:5] Found a ogg logical stream, serial: 8b386
2020/04/15 13:49:18 [decoder.ogg:5] Trying ogg/flac format
2020/04/15 13:49:18 [decoder.ogg:5] ogg/flac format detected for stream 8b386
...

I hope this helps a bit in finding the issue.

toots · 2020-04-15T14:02:14Z

Well damn.. 😅

At least I'm pretty sure I did fix an unrelated memleak.. I just shouldn't have rushed the release..

Thanks for all these details, I'll have another pass on it. Also, it looks like I did break ogg/flac stream decoding... Are you sure you did test in production with the latest ocaml-flac? In any case, I'd recommend downgrading to flac.0.1.5 while I fix the fix..

I'll hit you up when I have a new binding to test.

th3hamm0r · 2020-04-15T14:51:23Z

@toots First I have to thank you for your effort! 👍

Also, it looks like I did break ogg/flac stream decoding... Are you sure you did test in production with the latest ocaml-flac? In any case, I'd recommend downgrading to flac.0.1.5 while I fix the fix..

For me it looks like I've deployed the latest version, I pinned the 0.1.6 branch yesterday, it recompiled liquidsoap and the log tells me flac=0.1.6 (see https://github.com/savonet/liquidsoap/issues/1146#issuecomment-613910344) 😅

Just to be sure: you are saying you've broken the ogg/flac stream decoding. Did you see that in my logs above? Because so far I can see, our application still works correctly with the upgrade to flac.0.1.6 (audio and metadata seem to be ok). Just that the memory consumption is still increasing.

Also, no worries! All my tests are only deployed on our test environment at the moment. So I'm looking forward to test upcoming changes there 😄

toots · 2020-04-15T14:58:05Z

@toots First I have to thank you for your effort! 👍

Also, it looks like I did break ogg/flac stream decoding... Are you sure you did test in production with the latest ocaml-flac? In any case, I'd recommend downgrading to flac.0.1.5 while I fix the fix..

For me it looks like I've deployed the latest version, I pinned the 0.1.6 branch yesterday, it recompiled liquidsoap and the log tells me flac=0.1.6 (see #1146 (comment)) 😅

Just to be sure: you are saying you've broken the ogg/flac stream decoding. Did you see that in my logs above? Because so far I can see, our application still works correctly with the upgrade to flac.0.1.6 (audio and metadata seem to be ok). Just that the memory consumption is still increasing.

Also, no worries! All my tests are only deployed on our test environment at the moment. So I'm looking forward to test upcoming changes there 😄

Great!

When I say broken, I mean that I can reproduce your issue with the stream disconnecting at each end-of-track. I self-inflicted myself with the infamous ogg decoder bug where decoders think end of track = end of stream.. (the ogg specs isn't great on this one).

I have a fix for that but I'm also seeing some much slower memleak that I'm testing. And I think this time we should run it by you before a new release 😅

toots · 2020-04-20T23:21:13Z

Good to know!

Would you be able to test with the latest master code for ocaml-flac? It seems better during my tests. I still see memory increasing but at a seemingly very slow pace.

I can reproduce the allocations increase and observe them with valgrind but I'm still not sure why the data isn't getting cleaned up, OCaml's GC should be taking care of it. I'm gonna keep testing.

th3hamm0r · 2020-04-21T08:28:51Z

I've pinned flac to the master, but then rebuilding liquidsoap failed for some reason:

#=== ERROR while compiling liquidsoap.1.4.1 ===================================#
# context     2.0.6 | linux/x86_64 | ocaml-base-compiler.4.08.0 | https://opam.ocaml.org#a78d3c20
# path        ~/.opam/4.08.0/.opam-switch/build/liquidsoap.1.4.1
# command     ~/.opam/opam-init/hooks/sandbox.sh build make
# exit-code   2
# env-file    ~/.opam/log/liquidsoap-27136-c61e7b.env
# output-file ~/.opam/log/liquidsoap-27136-c61e7b.out
### output ###
# [...]
# Error: This expression has type int -> string * int
#        but an expression was expected of type
#          Flac.Decoder.read = bytes -> int -> int -> int
#        Type int is not compatible with type bytes 
# ../Makefile.rules:124: recipe for target 'decoder/flac_decoder.cmx' failed
# make[2]: *** [decoder/flac_decoder.cmx] Error 2
# make[2]: Leaving directory '/home/test/.opam/4.08.0/.opam-switch/build/liquidsoap.1.4.1/src'
# ../Makefile.rules:67: recipe for target 'all-auto-ocaml-prog' failed
# make[1]: *** [all-auto-ocaml-prog] Error 2
# make[1]: Leaving directory '/home/test/.opam/4.08.0/.opam-switch/build/liquidsoap.1.4.1/src'
# Makefile.rules:27: recipe for target 'all-subdirs' failed
# make: *** [all-subdirs] Error 2

I first tried rebuilding after opam update && opam upgrade, which failed, then by pinning liquidsoap to the master, but that installation failed too due to an unmatched dependency duppy >= 0.8.1. I haven't installed a dev-version of liquidsoap yet, so that was my naive approach. Before I further try to install that dev-version correctly, maybe there is an easier solution for my build-problem?

toots · 2020-04-21T15:25:47Z

My bad I meant to say the 0.1.7 branch, to be tested with 1.4.x, possibly 1.4.2 if you want to get ahead of the coming release... Also, it wasn't properly pushed.. It should be all good now, sorry for wasting some of your time..

toots · 2020-04-24T04:49:08Z

Hey! I found the issue. The C callbacks need to register their thread with the OCaml GC as explained here: https://caml.inria.fr/pub/docs/manual-ocaml/intfc.html#s%3AC-multithreading.

It's a pretty annoying change so I'm gonna take a minute to think about it but it'll get done as soon as possible.

I'm transferring this issue to ocaml-flac..

th3hamm0r · 2020-05-05T08:32:48Z

Hm, still seeing an increasing memory usage. I've updated the pinned 0.1.7 branch of flac, which recompiled my liquidsoap 1.4.1. I also double-checked the pinned repo in the build-dir of the opam switch, which contains your latest fixes. Did I miss something?

toots · 2020-05-05T13:54:49Z

It's possible that the bug is still here and wasn't caught in those changes but they clearly fixed a leak on my end. I would recommend to fully unpin, make sure you've got the latest changes by pulling the v0.1.7 tag directly and re-pinning:

% opam unpin flac
% cd /path/to/ocaml-flac
% git fetch && git checkout v0.1.7
% opam install -y .

th3hamm0r · 2020-05-11T09:26:35Z

I've re-pinned it as you said a few days ago, the memory is still increasing. Nevertheless thank you for your effort to find the issue! Should we open a new issue or do you re-open this one?

smimram · 2020-05-11T10:19:11Z

Let's reopen so that we don't forget.

toots self-assigned this Apr 8, 2020

toots closed this as completed in 02e36ae Apr 13, 2020

toots referenced this issue Apr 13, 2020

Backport memory leak fix for savonet/liquidsoap#1146

10c4d21

toots reopened this Apr 15, 2020

toots transferred this issue from savonet/liquidsoap Apr 24, 2020

toots closed this as completed in 353547f May 2, 2020

smimram reopened this May 11, 2020

gabsoftware mentioned this issue Apr 21, 2023

RAM and CPU usage skyrocketting when sending FLAC to input.harbor (on v2.1.4 and 2.2.0) savonet/liquidsoap#3017

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Memory leak with input.harbor and FLAC #9

Memory leak with input.harbor and FLAC #9

th3hamm0r commented Apr 8, 2020

smimram commented Apr 8, 2020

toots commented Apr 8, 2020

th3hamm0r commented Apr 8, 2020

th3hamm0r commented Apr 9, 2020

toots commented Apr 10, 2020

toots commented Apr 12, 2020

toots commented Apr 12, 2020

toots commented Apr 12, 2020

toots commented Apr 13, 2020

toots commented Apr 14, 2020

th3hamm0r commented Apr 14, 2020

toots commented Apr 14, 2020

th3hamm0r commented Apr 15, 2020

th3hamm0r commented Apr 15, 2020

toots commented Apr 15, 2020

th3hamm0r commented Apr 15, 2020

toots commented Apr 15, 2020

toots commented Apr 20, 2020

th3hamm0r commented Apr 21, 2020

toots commented Apr 21, 2020

toots commented Apr 24, 2020

th3hamm0r commented May 5, 2020

toots commented May 5, 2020

th3hamm0r commented May 11, 2020

smimram commented May 11, 2020

Memory leak with input.harbor and FLAC #9

Memory leak with input.harbor and FLAC #9

Comments

th3hamm0r commented Apr 8, 2020

smimram commented Apr 8, 2020

toots commented Apr 8, 2020

th3hamm0r commented Apr 8, 2020

th3hamm0r commented Apr 9, 2020

toots commented Apr 10, 2020

toots commented Apr 12, 2020

toots commented Apr 12, 2020

toots commented Apr 12, 2020

toots commented Apr 13, 2020

toots commented Apr 14, 2020

th3hamm0r commented Apr 14, 2020

toots commented Apr 14, 2020

th3hamm0r commented Apr 15, 2020

th3hamm0r commented Apr 15, 2020

toots commented Apr 15, 2020

th3hamm0r commented Apr 15, 2020

toots commented Apr 15, 2020

toots commented Apr 20, 2020

th3hamm0r commented Apr 21, 2020

toots commented Apr 21, 2020

toots commented Apr 24, 2020

th3hamm0r commented May 5, 2020

toots commented May 5, 2020

th3hamm0r commented May 11, 2020

smimram commented May 11, 2020