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.4k stars 130 forks source link

switch "replay_metadata" seems not to be respected (setting it to false has wrong effect). Probably apply also to "fallback" and other switch based operators. #1476

Closed matteo-daddi closed 2 years ago

matteo-daddi commented 3 years ago

Describe the bug In a "switch" (and "fallback" and probably all "switch-based" operators) setting replay_metadata to false seems to led to WRONGLY replaying of some metadata! MAY BE related to #1096 and #1241 (I've also tried to follow the advice in that discussion with no success)

By man pages: " replay_metadata: Replay the last metadata of a child when switching to it in the middle of a track! " So it's not 100% clear but setting it to false should disable metadata replay.

...But it seems that even with "false" some metadata are replayed. The replayed metadata seems the last occurred during child selection phase (if new metadata has been generated by the child after its selection they are lost, only the ones generated during selection phase are replayed).

To Reproduce

set("log.file",true)
set("log.stdout",false)
set("log.file.path","./replay_metadata=false_HAS_NO_EFFECT.log")

##Please read the inline comments and start the test when your computer clock is at around 10s. Then let play till the switch select the first child for at least 2 times and wait untill it re-switches to the second child

##I've used synth waves to let others easily test the script
sine440_5s_wMD = map_metadata(fun(m) -> [("freq", "\nMD from sine 440"), ("time", string_of(gettimeofday()))], sine(duration=5.,440.))
sine880_5s_wMD = map_metadata(fun(m) -> [("freq", "\nMD from sine 880"), ("time", string_of(gettimeofday()))], sine(duration=5.,880.))
saw440_5s_wMD = map_metadata(fun(m) -> [("freq", "\nMD from SAW 440"), ("time", string_of(gettimeofday()))], saw(duration=5.,440.))
sine1320_5s_wMD = map_metadata(fun(m) -> [("freq", "MD from sine 1320"), ("time", string_of(gettimeofday()))], sine(duration=5.,1320.))

#If you start the script at around 10s the switch should start using sine1320_5s_wMD, then at around 30s it should start play around 10 secs from the "sequence(*)"
s = switch(replay_metadata=false,track_sensitive=false, [({30s-38s}, sequence([sine440_5s_wMD, sine880_5s_wMD, saw440_5s_wMD])), ({true}, sine1320_5s_wMD)])

#Here we print all the metadata we see to demonstrate that "replay_metadata=false" is not respected
s = on_metadata(fun(m) -> print("#{m['freq']} Hz started at #{m['time']} ; "), s)

##bufferize is set to false otherwise alsa will prebuffer frames introducing latency (am I right?)
##Note that bufferize value SHOULD not be important, it is set to false just to have time respected as much as possible.
##also fallible value should not be significant
output.alsa(bufferize=false,fallible=true,s)

OUTPUT:

MD from sine 1320 Hz started at 1610986811.92 ; MD from sine 1320 Hz started at 1610986816.9 ; MD from sine 1320 Hz started at 1610986821.9 ; MD from sine 1320 Hz started at 1610986826.91 ;

MD from sine 440 Hz started at 1610986830.07 ;

MD from sine 880 Hz started at 1610986835.08 ; MD from sine 1320 Hz started at 1610986839.91 ; MD from sine 1320 Hz started at 1610986844.9 ; MD from sine 1320 Hz started at 1610986849.9 ; MD from sine 1320 Hz started at 1610986854.91 ; MD from sine 1320 Hz started at 1610986859.91 ; MD from sine 1320 Hz started at 1610986864.9 ; MD from sine 1320 Hz started at 1610986869.91 ; MD from sine 1320 Hz started at 1610986874.9 ; MD from sine 1320 Hz started at 1610986879.9 ; MD from sine 1320 Hz started at 1610986884.91 ; MD from sine 1320 Hz started at 1610986889.91 ;

MD from sine 440 Hz started at 1610986830.07 ;

MD from SAW 440 Hz started at 1610986892.07 ;

MD from SAW 440 Hz started at 1610986897.07 ; MD from sine 1320 Hz started at 1610986889.91 ; MD from sine 1320 Hz started at 1610986902.9 ;

LOG:

2021/01/18 16:20:11 >>> LOG START 2021/01/18 16:20:11 [main:3] Liquidsoap 1.4.3 2021/01/18 16:20:11 [main:3] Using: bytes=[distributed with OCaml 4.02 or above] pcre=7.4.6 sedlex=2.2 menhirLib=20201216 dtools=0.4.2 duppy=0.8.0 cry=0.6.5 mm=0.5.0 ogg=0.5.2 vorbis=0.7.1 mad=0.4.5 dynlink=[distributed with Ocaml] lame=0.3.4 alsa=0.2.3 samplerate=0.1.5 taglib=0.3.6 camomile=1.0.2 2021/01/18 16:20:11 [dynamic.loader:3] Could not find dynamic module for fdkaac encoder. 2021/01/18 16:20:11 [frame:3] Using 44100Hz audio, 25Hz video, 44100Hz master. 2021/01/18 16:20:11 [frame:3] Frame size must be a multiple of 1764 ticks = 1764 audio samples = 1 video samples. 2021/01/18 16:20:11 [frame:3] Targetting 'frame.duration': 0.04s = 1764 audio samples = 1764 ticks. 2021/01/18 16:20:11 [frame:3] Frames last 0.04s = 1764 audio samples = 1 video samples = 1764 ticks. 2021/01/18 16:20:11 [sandbox:3] Sandboxing disabled 2021/01/18 16:20:11 [video.converter:3] Couldn't find preferred video converter: gavl. 2021/01/18 16:20:11 [audio.converter:3] Using samplerate converter: libsamplerate. 2021/01/18 16:20:11 [alsa_out(default):3] Using ALSA 1.1.8. 2021/01/18 16:20:11 [alsa_out(default):3] Samplefreq=44100Hz, Bufsize=1764B, Frame=4B, Periods=4 2021/01/18 16:20:11 [clock.wallclock_alsa:3] Streaming loop starts, synchronized by active sources. 2021/01/18 16:20:11 [switch_7414:3] Switch to map_metadata_7411. 2021/01/18 16:20:11 [map_metadata_7411:3] Inserting missing metadata. 2021/01/18 16:20:14 [alsa_out(default):2] Underrun! You may minimize them by increasing the buffer size. 2021/01/18 16:20:14 [alsa_out(default):2] Trying to recover.. 2021/01/18 16:20:16 [map_metadata_7411:3] Inserting missing metadata. 2021/01/18 16:20:21 [map_metadata_7411:3] Inserting missing metadata. 2021/01/18 16:20:26 [map_metadata_7411:3] Inserting missing metadata. 2021/01/18 16:20:30 [switch_7414:3] Switch to sequence_7413 with transition. 2021/01/18 16:20:30 [map_metadata_7396:3] Inserting missing metadata. 2021/01/18 16:20:35 [map_metadata_7401:3] Inserting missing metadata. 2021/01/18 16:20:38 [switch_7414:3] Switch to map_metadata_7411 with transition. 2021/01/18 16:20:39 [map_metadata_7411:3] Inserting missing metadata. 2021/01/18 16:20:44 [map_metadata_7411:3] Inserting missing metadata. 2021/01/18 16:20:49 [map_metadata_7411:3] Inserting missing metadata. 2021/01/18 16:20:54 [map_metadata_7411:3] Inserting missing metadata. 2021/01/18 16:20:59 [map_metadata_7411:3] Inserting missing metadata. 2021/01/18 16:21:04 [map_metadata_7411:3] Inserting missing metadata. 2021/01/18 16:21:09 [map_metadata_7411:3] Inserting missing metadata. 2021/01/18 16:21:14 [map_metadata_7411:3] Inserting missing metadata. 2021/01/18 16:21:19 [map_metadata_7411:3] Inserting missing metadata. 2021/01/18 16:21:24 [map_metadata_7411:3] Inserting missing metadata. 2021/01/18 16:21:29 [map_metadata_7411:3] Inserting missing metadata. 2021/01/18 16:21:30 [switch_7414:3] Switch to sequence_7413 with transition. 2021/01/18 16:21:32 [map_metadata_7406:3] Inserting missing metadata. 2021/01/18 16:21:37 [map_metadata_7406:3] Inserting missing metadata. 2021/01/18 16:21:38 [switch_7414:3] Switch to map_metadata_7411 with transition. 2021/01/18 16:21:42 [map_metadata_7411:3] Inserting missing metadata. 2021/01/18 16:21:42 [main:3] Shutdown started! 2021/01/18 16:21:42 [main:3] Waiting for main threads to terminate... 2021/01/18 16:21:43 [clock.wallclock_alsa:3] Streaming loop stopped. 2021/01/18 16:21:43 [main:3] Threads terminated. 2021/01/18 16:21:43 [threads:3] Shutting down scheduler... 2021/01/18 16:21:43 [threads:3] Scheduler shut down. 2021/01/18 16:21:43 [threads:3] Waiting for queue threads to terminate... 2021/01/18 16:21:43 [threads:3] Queues shut down 2021/01/18 16:21:43 [main:3] Cleaning downloaded files... 2021/01/18 16:21:43 [main:3] Freeing memory... 2021/01/18 16:21:43 >>> LOG END

Expected behavior The second occurrence of "MD from sine 440 Hz started at 1610986830.07 ; " should not appear! ...Probably "MD from sine 440 Hz started at 1610986830.07 ; " is wrongly replayed despite replay_metadata=false.

Version details

Install method opam

matteo-daddi commented 3 years ago

It may be worth checking also the first version of my BUG report (see the edit history) because it may highlight another strange and possibly wrong behavior of metadata replaying (possibly another different bug but they can be the same).

...In general it seems that in these 2 cases some metadata are replayed: A) with "replay_metadata=false" (as shown in the "final" report); B) with "replay_metadata=ANYVALUE" and A CHILD SWITCH HAPPENS ON TRACK BOUNDARY, NOT IN THE MIDDLE (as shown in the "first" version of the report). The replayed metadata seems the last occurred during child selection phase (if new metadata has been generated by the child after its selection they are not replayed, only the ones generated during selection phase are replayed).

I've edited my report because in its first version I wrongly assumed that the "at()" operator was not track_sensitive (it seems it is). So I've rewritten the whole report without using "at()".

matteo-daddi commented 3 years ago

UPDATE: It seems that adding "transition_length=0." to the switch changes which metadata is replied and led to obtaining the same identical output for both "replay_metadata=false" and "replay_metadata=true"...

In particula for both:

s = switch(transition_length=0., replay_metadata=false,track_sensitive=false, [({30s-38s}, sequence([sine440_5s_wMD, sine880_5s_wMD, saw440_5s_wMD])), ({true}, sine1320_5s_wMD)])

and

s = switch(transition_length=0., replay_metadata=true,track_sensitive=false, [({30s-38s}, sequence([sine440_5s_wMD, sine880_5s_wMD, saw440_5s_wMD])), ({true}, sine1320_5s_wMD)])

(Difference between the 2 is only replay_matadata's value; Difference w.r.t. original example is the addition of transition_length=0.)

The obtained output (using the timestamps from original example and simulating same run conditions) is:

MD from sine 1320 Hz started at 1610986811.92 ; MD from sine 1320 Hz started at 1610986816.9 ; MD from sine 1320 Hz started at 1610986821.9 ; MD from sine 1320 Hz started at 1610986826.91 ;

MD from sine 440 Hz started at 1610986830.07 ;

MD from sine 880 Hz started at 1610986835.08 ; MD from sine 1320 Hz started at 1610986839.91 ; MD from sine 1320 Hz started at 1610986844.9 ; MD from sine 1320 Hz started at 1610986849.9 ; MD from sine 1320 Hz started at 1610986854.91 ; MD from sine 1320 Hz started at 1610986859.91 ; MD from sine 1320 Hz started at 1610986864.9 ; MD from sine 1320 Hz started at 1610986869.91 ; MD from sine 1320 Hz started at 1610986874.9 ; MD from sine 1320 Hz started at 1610986879.9 ; MD from sine 1320 Hz started at 1610986884.91 ; MD from sine 1320 Hz started at 1610986889.91 ;

MD from sine 880 Hz started at 1610986835.08 ;

MD from SAW 440 Hz started at 1610986892.07 ;

MD from SAW 440 Hz started at 1610986897.07 ; MD from sine 1320 Hz started at 1610986889.91 ; MD from sine 1320 Hz started at 1610986902.9 ;

...As you can see, instead of "MD from sine 440 Hz started at 1610986830.07 ;" like in the original example, now the replayed metadata seems to be "MD from sine 880 Hz started at 1610986835.08 ;" which should be RIGHT for the case where "replay_metadata=true" but SHOULD NOT APPEAR in the case where "replay_metadata=false".

...Maybe I'm missing something or I have not understood the meaning of: "replay_metadata", "transition_length" and maybe "transitions" (left as default in all the examples)... So it could be a problem of mine or a simple ambiguity in the DOC. But the behavior I observe looks a bit weird to me!

Thanks ;-)

matteo-daddi commented 3 years ago

UPDATE: POSSIBLE WORKAROUND (or Solved?) I've found a possible SOLUTION that seems to led to the expected behavior (expected at least by me):

The solution consists in adding "transitions=[fun(a,b) -> empty(),fun(a,b) -> empty()], transition_length=0.," to the switch in the example script... and, in general, it seems to work also in other switch based operators (fallback, rotate, others?)

Edited part of the example script: s = switch(transitions=[fun(a,b) -> empty(),fun(a,b) -> empty()], transition_length=0.,replay_metadata=false,track_sensitive=false, [({30s-38s}, sequence([sine440_5s_wMD, sine880_5s_wMD, saw440_5s_wMD])), ({true}, sine1320_5s_wMD)])

The obtained OUTPUT is this:

MD from sine 1320 Hz started at 1611396072.37 ; MD from sine 1320 Hz started at 1611396077.34 ; MD from sine 1320 Hz started at 1611396082.34 ; MD from sine 1320 Hz started at 1611396087.34 ;

MD from sine 440 Hz started at 1611396090.06 ;

MD from sine 880 Hz started at 1611396095.06 ; MD from sine 1320 Hz started at 1611396100.34 ; MD from sine 1320 Hz started at 1611396105.35 ; MD from sine 1320 Hz started at 1611396110.34 ; MD from sine 1320 Hz started at 1611396115.34 ; MD from sine 1320 Hz started at 1611396120.35 ; MD from sine 1320 Hz started at 1611396125.34 ; MD from sine 1320 Hz started at 1611396130.35 ; MD from sine 1320 Hz started at 1611396135.34 ; MD from sine 1320 Hz started at 1611396140.34 ; MD from sine 1320 Hz started at 1611396145.35 ;

MD from SAW 440 Hz started at 1611396152.07 ;

MD from SAW 440 Hz started at 1611396157.07 ; MD from sine 1320 Hz started at 1611396158.36 ; MD from sine 1320 Hz started at 1611396163.36 ;

...Here you can clearly see that no metadata is wrongly replayed! :-) (and also the played sounds seem OK!)

The associated LOG is this:

2021/01/23 10:01:12 >>> LOG START 2021/01/23 10:01:11 [main:3] Liquidsoap 1.4.3 2021/01/23 10:01:11 [main:3] Using: bytes=[distributed with OCaml 4.02 or above] pcre=7.4.6 sedlex=2.2 menhirLib=20201216 dtools=0.4.2 duppy=0.8.0 cry=0.6.5 mm=0.5.0 ogg=0.5.2 vorbis=0.7.1 mad=0.4.5 dynlink=[distributed with Ocaml] lame=0.3.4 alsa=0.2.3 samplerate=0.1.5 taglib=0.3.6 camomile=1.0.2 2021/01/23 10:01:11 [dynamic.loader:3] Could not find dynamic module for fdkaac encoder. 2021/01/23 10:01:12 [frame:3] Using 44100Hz audio, 25Hz video, 44100Hz master. 2021/01/23 10:01:12 [frame:3] Frame size must be a multiple of 1764 ticks = 1764 audio samples = 1 video samples. 2021/01/23 10:01:12 [frame:3] Targetting 'frame.duration': 0.04s = 1764 audio samples = 1764 ticks. 2021/01/23 10:01:12 [frame:3] Frames last 0.04s = 1764 audio samples = 1 video samples = 1764 ticks. 2021/01/23 10:01:12 [sandbox:3] Sandboxing disabled 2021/01/23 10:01:12 [video.converter:3] Couldn't find preferred video converter: gavl. 2021/01/23 10:01:12 [audio.converter:3] Using samplerate converter: libsamplerate. 2021/01/23 10:01:12 [alsa_out(default):3] Using ALSA 1.1.8. 2021/01/23 10:01:12 [alsa_out(default):3] Samplefreq=44100Hz, Bufsize=1764B, Frame=4B, Periods=4 2021/01/23 10:01:12 [clock.wallclock_alsa:3] Streaming loop starts, synchronized by active sources. 2021/01/23 10:01:12 [switch_7414:3] Switch to map_metadata_7411. 2021/01/23 10:01:12 [map_metadata_7411:3] Inserting missing metadata. 2021/01/23 10:01:17 [map_metadata_7411:3] Inserting missing metadata. 2021/01/23 10:01:22 [map_metadata_7411:3] Inserting missing metadata. 2021/01/23 10:01:27 [map_metadata_7411:3] Inserting missing metadata. 2021/01/23 10:01:30 [switch_7414:3] Switch to sequence_7413 with transition. 2021/01/23 10:01:30 [map_metadata_7396:3] Inserting missing metadata. 2021/01/23 10:01:35 [map_metadata_7401:3] Inserting missing metadata. 2021/01/23 10:01:38 [switch_7414:3] Switch to map_metadata_7411 with transition. 2021/01/23 10:01:40 [map_metadata_7411:3] Inserting missing metadata. 2021/01/23 10:01:45 [map_metadata_7411:3] Inserting missing metadata. 2021/01/23 10:01:50 [map_metadata_7411:3] Inserting missing metadata. 2021/01/23 10:01:55 [map_metadata_7411:3] Inserting missing metadata. 2021/01/23 10:02:00 [map_metadata_7411:3] Inserting missing metadata. 2021/01/23 10:02:05 [map_metadata_7411:3] Inserting missing metadata. 2021/01/23 10:02:10 [map_metadata_7411:3] Inserting missing metadata. 2021/01/23 10:02:15 [map_metadata_7411:3] Inserting missing metadata. 2021/01/23 10:02:20 [map_metadata_7411:3] Inserting missing metadata. 2021/01/23 10:02:25 [map_metadata_7411:3] Inserting missing metadata. 2021/01/23 10:02:30 [switch_7414:3] Switch to sequence_7413 with transition. 2021/01/23 10:02:32 [map_metadata_7406:3] Inserting missing metadata. 2021/01/23 10:02:37 [map_metadata_7406:3] Inserting missing metadata. 2021/01/23 10:02:38 [switch_7414:3] Switch to map_metadata_7411 with transition. 2021/01/23 10:02:38 [map_metadata_7411:3] Inserting missing metadata. 2021/01/23 10:02:43 [map_metadata_7411:3] Inserting missing metadata. 2021/01/23 10:02:44 [main:3] Shutdown started! 2021/01/23 10:02:44 [main:3] Waiting for main threads to terminate... 2021/01/23 10:02:44 [clock.wallclock_alsa:3] Streaming loop stopped. 2021/01/23 10:02:44 [main:3] Threads terminated. 2021/01/23 10:02:44 [threads:3] Shutting down scheduler... 2021/01/23 10:02:44 [threads:3] Scheduler shut down. 2021/01/23 10:02:44 [threads:3] Waiting for queue threads to terminate... 2021/01/23 10:02:44 [threads:3] Queues shut down 2021/01/23 10:02:44 [main:3] Cleaning downloaded files... 2021/01/23 10:02:44 [main:3] Freeing memory... 2021/01/23 10:02:44 >>> LOG END

...I leave the issue opened because I don't know if what I've found is a workaround (that may be useful also to someone else) or maybe the issue doesn't exist at all and is caused by a simple misunderstanding of the documentation by me.

In the second case the ones with that knowledge may close this issue otherwise it may be worth to investigate!

Thank you! ;-)

martinkirch commented 3 years ago

Hello, Can confirm this workaround works with v1.4.4. Thanks !

stale[bot] commented 2 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

stale[bot] commented 2 years ago

This issue was closed for lack of activity. If you believe that it is still relevant, please confirm that it applies to the latest released version of liquidsoap and re-open the ticket. Thanks!