search

savonet / liquidsoap

Liquidsoap is a statically typed scripting general-purpose language with dedicated operators and backend for all thing media, streaming, file generation, automation, HTTP backend and more.
http://liquidsoap.info
GNU General Public License v2.0
1.41k stars 130 forks source link

Source X failed while streaming: File "stream/frame.ml", line 567, characters 2-8: Assertion failed! #684

Closed 5chdn closed 5 years ago

5chdn commented 5 years ago

Describe the bug After an upgrade to liquidsoap 1.3.4 (and switching to opam to manage the installation), the our radio server crashes around once a day.

2018/12/31 02:09:31 [http_6594:3] Buffer overrun: Dropping 0.02s. Consider increasing the max buffer size!
2018/12/31 02:10:25 [http_6594:3] New metadata chunk: ? -- My Moral Majority - Einfach Sterben.
2018/12/31 02:15:10 [http_6594:3] New metadata chunk: ? -- The Sound - Prove Me Wrong (Live).
2018/12/31 02:15:10 [http_6594:3] Buffer overrun: Dropping 0.02s. Consider increasing the max buffer size!
2018/12/31 02:15:10 [http_6594:3] Buffer overrun: Dropping 0.03s. Consider increasing the max buffer size!
2018/12/31 02:15:10 [http_6594:3] Buffer overrun: Dropping 0.03s. Consider increasing the max buffer size!
2018/12/31 02:15:10 [http_6594:3] Buffer overrun: Dropping 0.03s. Consider increasing the max buffer size!
2018/12/31 02:15:10 [http_6594:3] Buffer overrun: Dropping 0.03s. Consider increasing the max buffer size!
2018/12/31 02:15:10 [http_6594:3] Buffer overrun: Dropping 0.03s. Consider increasing the max buffer size!
2018/12/31 02:15:10 [http_6594:3] Buffer overrun: Dropping 0.03s. Consider increasing the max buffer size!
2018/12/31 02:15:10 [http_6594:3] Buffer overrun: Dropping 0.03s. Consider increasing the max buffer size!
2018/12/31 02:15:10 [http_6594:3] Buffer overrun: Dropping 0.03s. Consider increasing the max buffer size!
2018/12/31 02:15:10 [http_6594:3] Buffer overrun: Dropping 0.03s. Consider increasing the max buffer size!
2018/12/31 02:15:10 [http_6594:3] Buffer overrun: Dropping 0.03s. Consider increasing the max buffer size!
2018/12/31 02:15:10 [http_6594:3] Buffer overrun: Dropping 0.03s. Consider increasing the max buffer size!
2018/12/31 02:15:10 [http_6594:3] Buffer overrun: Dropping 0.03s. Consider increasing the max buffer size!
2018/12/31 02:15:10 [http_6594:3] Buffer overrun: Dropping 0.03s. Consider increasing the max buffer size!
2018/12/31 02:15:10 [http_6594:3] Buffer overrun: Dropping 0.03s. Consider increasing the max buffer size!
2018/12/31 02:15:10 [http_6594:3] Buffer overrun: Dropping 0.03s. Consider increasing the max buffer size!
2018/12/31 02:15:20 [clock.wallclock_main:2] Source Punkrockers failed while streaming: File "stream/frame.ml", line 567, characters 2-8: Assertion failed!
2018/12/31 02:15:20 [clock.wallclock_main:3] Raised at file "stream/frame.ml", line 567, characters 2-35
2018/12/31 02:15:20 [clock.wallclock_main:3] Called from file "stream/frame.ml", line 584, characters 4-26
2018/12/31 02:15:20 [clock.wallclock_main:3] Called from file "source.ml", line 528, characters 8-32
2018/12/31 02:15:20 [clock.wallclock_main:3] Called from file "outputs/output.ml", line 174, characters 8-18
2018/12/31 02:15:20 [clock.wallclock_main:3] Called from file "clock.ml", line 160, characters 17-25
2018/12/31 02:15:20 [Punkrockers:3] Closing connection...
2018/12/31 02:15:20 [clock.wallclock_main:2] Source Punkrockers(dot)1 failed while streaming: File "stream/frame.ml", line 567, characters 2-8: Assertion failed!
2018/12/31 02:15:20 [clock.wallclock_main:3] Raised at file "stream/frame.ml", line 567, characters 2-35
2018/12/31 02:15:20 [clock.wallclock_main:3] Called from file "stream/frame.ml", line 584, characters 4-26
2018/12/31 02:15:20 [clock.wallclock_main:3] Called from file "source.ml", line 528, characters 8-32
2018/12/31 02:15:20 [clock.wallclock_main:3] Called from file "outputs/output.ml", line 174, characters 8-18
2018/12/31 02:15:20 [clock.wallclock_main:3] Called from file "clock.ml", line 160, characters 17-25
2018/12/31 02:15:20 [Punkrockers(dot)1:3] Closing connection...
2018/12/31 02:15:20 [clock.wallclock_main:2] Source Punkrockers(dot)2 failed while streaming: File "stream/frame.ml", line 567, characters 2-8: Assertion failed!
2018/12/31 02:15:20 [clock.wallclock_main:3] Raised at file "stream/frame.ml", line 567, characters 2-35
2018/12/31 02:15:20 [clock.wallclock_main:3] Called from file "stream/frame.ml", line 584, characters 4-26
2018/12/31 02:15:20 [clock.wallclock_main:3] Called from file "source.ml", line 528, characters 8-32
2018/12/31 02:15:20 [clock.wallclock_main:3] Called from file "outputs/output.ml", line 174, characters 8-18
2018/12/31 02:15:20 [clock.wallclock_main:3] Called from file "clock.ml", line 160, characters 17-25
2018/12/31 02:15:20 [Punkrockers(dot)2:3] Closing connection...
2018/12/31 02:15:20 [http_6594:3] Incorrect stream type!
2018/12/31 02:15:20 [fallback_6596:3] Switch to audio_to_stereo_6592 with forgetful transition.
2018/12/31 02:15:20 [main:3] Shutdown started!
2018/12/31 02:15:20 [main:3] Waiting for threads to terminate...
2018/12/31 02:15:20 [threads:3] Shuting down thread gstreamer_main_loop
2018/12/31 02:15:20 [threads:3] Thread "gstreamer_main_loop" terminated (4 remaining).
2018/12/31 02:15:20 [threads:3] Shuting down thread http polling
2018/12/31 02:15:20 [Punkrockers(dot)3:3] Closing connection...
2018/12/31 02:15:20 [prrlist(dot)m3u:3] Finished with "/path/to/Desmond_Dekker/Desmond_Dekker-Rude_Boy_Train.mp3".
2018/12/31 02:15:20 [clock.wallclock_main:3] Streaming loop stopped.
2018/12/31 02:15:20 [threads:3] Thread "wallclock_main" terminated (3 remaining).
2018/12/31 02:15:20 [http_6594:2] Feeding stopped: the decoded stream was not of the right type. The typical situation is when you expect a stereo stream whereas the stream is mono (in this case the situation can easily be solved by using the audio_to_stereo operator to convert the stream to a stereo one).
2018/12/31 02:15:20 [threads:3] Thread "http polling" terminated (2 remaining).
2018/12/31 02:15:21 [threads:3] Thread "http polling" terminated (1 remaining).
2018/12/31 02:15:21 [threads:3] Shuting down thread http polling
2018/12/31 02:15:21 [threads:3] Thread "http polling" terminated (0 remaining).
2018/12/31 02:15:21 [main:3] Threads terminated.
2018/12/31 02:15:21 [threads:3] Shutting down scheduler...
2018/12/31 02:15:21 [threads:3] Scheduler shut down.
2018/12/31 02:15:21 [threads:3] Shutting down queues...
2018/12/31 02:15:21 [threads:3] Thread "generic queue #2" terminated.
2018/12/31 02:15:21 [threads:3] Thread "generic queue #1" terminated.
2018/12/31 02:15:21 [threads:3] Thread "non-blocking queue #2" terminated.
2018/12/31 02:15:21 [threads:3] Thread "non-blocking queue #1" terminated.
2018/12/31 02:15:21 [threads:3] Queues shut down
2018/12/31 02:15:21 [server:3] Closing socket.
2018/12/31 02:15:21 [main:3] Cleaning downloaded files...
2018/12/31 02:15:21 [main:3] Freeing memory...
2018/12/31 02:15:21 >>> LOG END

To Reproduce (Give me some time to fill this in, but if you have some ideas, let me know.)

Expected behavior It should run smooth without having to restart it daily (as it used to be the years before).

Version details

Install method Did you install via opam? Yes.

#!/bin/bash
echo "eval opam config env"
eval `opam config env`
echo "opam update"
opam update
echo "opam upgrade"
opam upgrade
echo "opam depext"
OPAMVAR_os_family=arch opam depext taglib mad lame vorbis cry samplerate opus lastfm gstreamer flac liquidsoap
echo "opam install"
opam install taglib mad lame vorbis cry samplerate opus lastfm gstreamer flac liquidsoap
echo "liquidsoap --version"
liquidsoap --version
toots commented 5 years ago

Hi. Thanks for this report. This looks like a fundamental issue that we should address quickly. Which version of liquidsoap did you upgrade from? Also, any chance you could share some of your script?

5chdn commented 5 years ago

I upgraded from 1.3.3 as far as I remember. I'm logging the crashes now and force the script to restart. That's a bit ugly, but the only solution to keep this alive currently. 23 crashes in 6 days:

2019-01-03 06:53:38
2019-01-03 06:53:40
2019-01-03 06:53:41
2019-01-05 06:36:04
2019-01-05 06:36:05
2019-01-05 06:36:06
2019-01-05 06:36:08
2019-01-05 13:02:01
2019-01-05 13:02:03
2019-01-05 13:02:04
2019-01-05 13:02:05
2019-01-05 13:02:06
2019-01-07 05:09:32
2019-01-07 05:09:33
2019-01-07 05:09:35
2019-01-07 05:09:36
2019-01-07 08:36:41
2019-01-07 08:36:42
2019-01-07 08:36:43
2019-01-08 10:44:24
2019-01-08 10:44:25
2019-01-08 10:44:26
2019-01-08 10:44:27

This is my script:

set("log.file.path","/path/to/log/<script>.log")
set("log.level",3)
set("gstreamer.debug_level",3)
set("log.stdout",true)
set("server.telnet",true)

ogg = output.icecast(
  %vorbis.cbr(
    samplerate=44100,
    channels=2,
    bitrate=128
  ),
  host="127.0.0.1",
  port=8000,
  public=true,
  password="secret",
  name="Radio",
  description="Radio - 24/7",
  genre="Various",
  url="http://example.com",
  mount="ogg"
)

mp3 = output.icecast(
  %mp3.cbr(
    bitrate=128,
    samplerate=44100,
    stereo=true,
    id3v2=false
  ),
  host="127.0.0.1",
  port=8000,
  public=true,
  password="secret",
  name="Radio",
  description="Radio - 24/7",
  genre="Various",
  url="http://example.com",
  mount="mp3"
)

musiclist = audio_to_stereo(
  smart_crossfade(
    normalize(
      mksafe(
        playlist(
          reload=21600,
          reload_mode="seconds",
          mode="random",
          "/path/to/playlist.m3u"
        )
      )
    )
  )
)

rotation = input.http(
  "http://localhost:8000/rotation",
  buffer=9.9
)

rotateshow = fallback(
  track_sensitive=false,
  [
    rotation,
    musiclist
  ]
)

podcast = input.http(
  "http://localhost:8000/podcast",
  buffer=9.9
)

podcastshow = fallback(
  track_sensitive=false,
  [
    podcast,
    rotateshow
  ]
)

relay = input.http(
  "http://localhost:8000/stream",
  buffer=9.9
)

relayshow = fallback(
  track_sensitive=false,
  [
    relay,
    podcastshow
  ]
)

funk = input.http(
  "http://localhost:8000/funk",
  buffer=9.9,
)

fullshow = fallback(
  track_sensitive=false,
  [
    funk,
    relayshow
  ]
)

def trigger(m) =
  system("sh /path/to/some-script.sh > /dev/null 2>&1 &")
end

fullshow = on_metadata(trigger, fullshow)

ogg(fullshow)
mp3(fullshow)
toots commented 5 years ago

Ok, I think I may have a fix. Any chance you could test with a git branch? Try this:

git clone --recursive https://github.com/savonet/liquidsoap.git
cd liquidsoap
git checkout fix-684
opam pin add .
toots commented 5 years ago

Hi,

I just fixed a bug on crossfade that will most likely warrant another bugfix release. If you can confirm that this fixes your issue, I'd be happy to ship that fix as well.

5chdn commented 5 years ago

Done.

[liquidsoap.1.3.4] synchronised from git+file:///home/stream/liquidsoap-fix684#fix-684
liquidsoap is now pinned to git+file:///home/stream/liquidsoap-fix684#fix-684 (version dev)
The following actions will be performed:
  ↗ upgrade liquidsoap 1.3.4 to dev*
Do you want to continue? [Y/n] Y

<><> Processing actions <><><><><><><><><><><><><><><><><><><><><><><><><><><><>
⊘ removed   liquidsoap.1.3.4
∗ installed liquidsoap.dev
Done.

And restarted.

2019/01/12 17:03:20 >>> LOG START
2019/01/12 17:03:20 [main:3] Liquidsoap 1.3.5+scm (file:///home/stream/liquidsoap-fix684@960bc77c117c5174f53b1ef1e7a7a41f5256319d:20190112:170220)
2019/01/12 17:03:20 [main:3] Using: bytes=[distributed with OCaml 4.02 or above] pcre=7.3.5 dtools=0.4.1 duppy=0.8.0 cry=0.6.2 mm=0.4.0 xmlplaylist=0.1.4 lastfm=0.3.2 ogg=0.5.2 vorbis=0.7.1 opus=0.1.2 mad=0.4.5 flac=0.1.3 flac.ogg=0.1.3 dynlink=[distributed with Ocaml] lame=0.3.3 gstreamer=0.3.0 samplerate=0.1.4 taglib=0.3.3 camomile=1.0.1
2019/01/12 17:03:20 [main:2] 
2019/01/12 17:03:20 [main:2] DISCLAIMER: This version of Liquidsoap has been
2019/01/12 17:03:20 [main:2] compiled from a snapshot of the development code.
2019/01/12 17:03:20 [main:2] As such, it should not be used in production
2019/01/12 17:03:20 [main:2] unless you know what you are doing!
2019/01/12 17:03:20 [main:2] 
2019/01/12 17:03:20 [main:2] We are, however, very interested in any feedback
2019/01/12 17:03:20 [main:2] about our development code and committed to fix
2019/01/12 17:03:20 [main:2] issues as soon as possible.
2019/01/12 17:03:20 [main:2] 
2019/01/12 17:03:20 [main:2] If you are interested in collaborating to
2019/01/12 17:03:20 [main:2] the development of Liquidsoap, feel free to
2019/01/12 17:03:20 [main:2] drop us a mail at <savonet-devl@lists.sf.net>
2019/01/12 17:03:20 [main:2] or to join the #savonet IRC channel on Freenode.
2019/01/12 17:03:20 [main:2] 
2019/01/12 17:03:20 [main:2] Please send any bug report or feature request
2019/01/12 17:03:20 [main:2] at <https://github.com/savonet/liquidsoap/issues>.
2019/01/12 17:03:20 [main:2] 
2019/01/12 17:03:20 [main:2] We hope you enjoy this snapshot build of Liquidsoap!
2019/01/12 17:03:20 [main:2]

I leave it running and monitor for crashes. Please ping me if I "forget" about reporting back.

I also found another bug that's pretty annoying right now, let me open another ticket for it once I am able to reproduce it.

5chdn commented 5 years ago

@toots no crash since the update 3 days ago, I think you nailed it :+1:

toots commented 5 years ago

Super awesome thanks for taking the time to test.

5chdn commented 5 years ago

Thanks for being so responsive!