Decoder "MAD" betrayed us

I’m trying to get my airtime back on track…

We were running an old build for a LOOOONG time (I think it was 2.5.2 from memory, although that could be the version of airtime prior not libretime). I recently upgraded to v3.0.8 (LibreTime Version 34d46e4) and all seemed to have gone OK except I noticed that scheduled tracks were not being played. Libretime thought they were being played but there was silence on the output. We didn’t notice for a while because we usually restream webstreams through libretime and these were unaffected. However, every time a scheduled mp3 track plays out we get a variation of;

2020/03/23 00:00:00 [decoder:2] Decoder “MAD” betrayed us on “/var/tmp/airtime/pypo/cache/scheduler/44.mp3”!

and silence on the stream. I spotted the advice that “Liquidsoap 1.1.1 support. 3.0.0-alpha.8 is most likely the last version to support liquidsoap 1.1.1 out of the box.”

So after much trial and error I managed to get a version of liquidsoap 1.3.4 to compile but this version can’t connect to the ShoutCAST stream (I moved the original binary and swopped it for the new binary and restarted service airtime-liquidsoap).

All help gratefully received!

Hmm what distribution of Linux are you using. LibreTime is very complex with all of it’s interwoven dependencies and configurations so it can be tricky to swap stuff piecemeal. I haven’t seen the MAD betrayal but there were issues with the older versions of Debian liquidsoap binary and MP3 playback reported by people. Ubuntu liquidsoap 1.1.1 appears to work. The newer liquidsoap Debian package is included as of Debian Buster.

I’m using ubuntu 16.04 (xenial) so not especially esoteric. I’m running liquidsoap 1.1.1 at present & the latest git pull (34d46e4). The only other post I could find regarding MAD betrayal was related to the config so I’m going to try to compare the default with my airtime.conf

Edit: So just to confirm, the latest git pull of libretime still works with liquidsoap 1.1.1?

I might have fixed it… When I compared the pre and post configs, the only notable change was the base port from 80 to 443. I put it back to 80 and managed to stream a track for a minute’s test. I’ll do some more testing and post back.

Hello ! We had a similar problem after installing Libretime with an exported/imported database from our previous Airtime install. Check the last posts from this thread (it’s about missing cc_files.filesize column in previous Airtime install) : [SOLVED]Files imported from previous Airtime 2.5 don't play/play blank

Ahhh, makes sense. In the interim I’d manually been into each file as they were file type ‘Nul’ and set them all to ‘Mus’ in the libretime pages… seems that may also have updated the filesize because when I ran your script I get;

DBD::Pg::st execute failed: ERROR: null value in column “filesize” violates not-null constraint

the filesize column is populated with sensible data.

EDIT: cough Having said sensible, the track length appears incorrect for some files;

General
Complete name : filename.mp3
Format : MPEG Audio
File size : 281 MiB
Duration : 2 h 2 min
Overall bit rate mode : Constant
Overall bit rate : 320 kb/s
Genre : Other

Audio
Format : MPEG Audio
Format version : Version 1
Format profile : Layer 3
Format settings : Joint stereo
Duration : 2 h 2 min
Bit rate mode : Constant
Bit rate : 320 kb/s
Channel(s) : 2 channels
Sampling rate : 44.1 kHz
Frame rate : 38.281 FPS (1152 SPF)
Compression mode : Lossy
Stream size : 281 MiB (100%)

Shows as;
01:01:24.518 in libretime.

However, streaming local mp3’s seems to be back on :slight_smile:

Spoke too soon, I queued up two mixes, the first played and the second did not :frowning:

Here’s the relevent section from ls_script_legacy.log, I’ve removed client dis/connections for brevity. @Leekid it does seem related to the metadata on the tracks; “End of track before cue-out point.”

2020/03/23 18:00:00 [lang:3] timeout --signal=KILL 45 pyponotify --source-name=live_dj --source-status=false &
2020/03/23 18:00:00 [lang:3] streams.live_dj_stop
2020/03/23 18:00:00 [lang:3] vars.show_name
2020/03/23 18:00:00 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/61.mp3".
2020/03/23 18:00:00 [s4:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/61.mp3" (RID 0).
2020/03/23 18:00:00 [schedule_noise_switch:3] Switch to map_metadata_5849 with transition.
2020/03/23 18:00:00 [lang:3] transition called...
2020/03/23 18:00:00 [switch_5847:3] Switch to insert_metadata_5833.
2020/03/23 18:00:00 [cue_cut_5774:3] Cueing in...
2020/03/23 18:00:00 [amplify_5778:3] Overriding amplification: 0.869961.
2020/03/23 18:00:00 [lang:3] timeout --signal=KILL 45 pyponotify --media-id=7282 &
2020/03/23 18:00:00 [lang:3] Using stream_format 0
2020/03/23 18:00:00 [lang:3] Using stream_format 0
2020/03/23 18:00:00 [lang:3] Using stream_format 0
2020/03/23 18:00:03 [cross_5841:3] No next track ready yet.
2020/03/23 18:00:03 [lang:3] URL now http://dirtybass.fm:7760/dirtybass.aac (change: false)
2020/03/23 18:00:03 [lang:3] New track inside HTTP stream
2020/03/23 18:00:03 [lang:3]   status: stopped
2020/03/23 18:00:03 [lang:3]   need to cross: false
2020/03/23 18:00:03 [lang:3]   remaining inf sec before, 0. sec after
2020/03/23 18:00:06 [dummy(dot)2:3] Source failed (no more tracks) stopping output...
2020/03/23 19:01:22 [cue_cut_5774:3] Cueing out...
2020/03/23 19:01:22 [s4:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/61.mp3".
2020/03/23 19:01:22 [amplify_5778:3] End of the current overriding.
2020/03/23 19:01:22 [cross_5781:3] No next track ready yet.
2020/03/23 19:01:22 [dummy(dot)3:3] Source failed (no more tracks) stopping output...
2020/03/23 19:01:22 [dummy(dot)4:3] Source failed (no more tracks) stopping output...
2020/03/23 19:01:22 [schedule_noise_switch:3] Switch to map_metadata_5856 with forgetful transition.
2020/03/23 19:01:22 [lang:3] transition called...
2020/03/23 19:01:22 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/56.mp3".
2020/03/23 19:01:22 [decoder:2] Decoder "MAD" betrayed us on "/var/tmp/airtime/pypo/cache/scheduler/56.mp3"!
2020/03/23 19:01:22 [s4:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/56.mp3" (RID 1).
2020/03/23 19:01:22 [schedule_noise_switch:3] Switch to map_metadata_5849 with transition.
2020/03/23 19:01:22 [lang:3] transition called...
2020/03/23 19:01:22 [switch_5847:3] Switch to insert_metadata_5833.
2020/03/23 19:01:22 [s4:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/56.mp3".
2020/03/23 19:01:22 [cue_cut_5774:3] Cueing in...
2020/03/23 19:01:22 [cue_cut_5774:2] Could not seek to cue point!
2020/03/23 19:01:22 [cue_cut_5774:3] End of track before cue-out point.
2020/03/23 19:01:22 [amplify_5778:3] Overriding amplification: 0.874984.
2020/03/23 19:01:22 [amplify_5778:3] End of the current overriding.
2020/03/23 19:01:22 [lang:3] timeout --signal=KILL 45 pyponotify --media-id=7281 &
2020/03/23 19:01:22 [dummy(dot)4:3] Source failed (no more tracks) stopping output...
2020/03/23 19:01:22 [schedule_noise_switch:3] Switch to map_metadata_5856 with forgetful transition.
2020/03/23 19:01:22 [lang:3] transition called...

Hello, it’s very easy to know if your current problem is database related : the freshly uploaded files (via Libretime’s upload procedure) must work…if not, it may be something else…our problem only concerned the tracks imported from the previous Airtime install via database export/import. Live streaming, webstreams etc. were ok.

hi there, OK… fair point. I’ll reimport the tracks and do some testing…

I ran the Admin > Settings > Dangerous > Delete all the tracks, and deleted manually the files from the filesystem too so everything would be fresh. I reimported all the tracks into the database… to be honest there weren’t that many so it wasn’t such a task. Once I went back into the calendar something odd had appeared, there were two ‘shows’ that apparently started broadcasting in March 2018 and ended today… For whatever reason these shows may not have had an end date set in the database (import failure or other database wierdness) and as such may have been interfering with subsequent scheduled content. Presumably these were ignored under 2.x but caused MADness under 3.x

In any event, when I tested it the scheduled tracks from the library appeared to be played out normally again :smiley: plus I fixed the track length with the help of this post so we’re all happy campers. :partying_face:

EDIT: for future reference, don’t change the base port from 443… you won’t be able to connect to your streaming service when you restart libretime services.