search

libretime / libretime

LibreTime: Radio Broadcast & Automation Platform
http://libretime.org
GNU Affero General Public License v3.0
812 stars 225 forks source link

Stream goes offline during the night of some days #1488

Closed jooola closed 2 years ago

jooola commented 2 years ago

Describe the bug

The stream is going offline some random day during the night and we have huge downtimes (last one was 5h). This happened multiple times, but the monitoring tools didn't catch the downtime then, now it did.

The stream goes offline after the first track of the second show scheduled for that day, I am unsure if this is relevant.

Playout is not able to remove the cached file from the scheduler cache because it is busy, probably still used by liquidsoap.

The file doesn't not show any visible particularities.

To Reproduce

I don't know if this is reproducible, it happen randomly on my side.

Expected behavior

Stream should not go offline

LibreTime version:

77a9d9827

Installation method:

Additional context

Liquidsoap logs:

2022/01/06 02:26:15 [server:3] New client: 127.0.0.1.
2022/01/06 02:26:15 [lang:3] dynamic_source.get_id
2022/01/06 02:26:15 [server:3] Client 127.0.0.1 disconnected.
2022/01/06 02:28:50 [server:3] New client: 127.0.0.1.
2022/01/06 02:28:50 [decoder:3] Method "FLAC" accepted "/var/tmp/airtime/pypo/cache/scheduler/3829.flac".
2022/01/06 02:28:50 [lang:3] vars.show_name
2022/01/06 02:28:50 [server:3] Client 127.0.0.1 disconnected.
2022/01/06 02:28:50 [cue_cut_7721:3] Cueing out...
2022/01/06 02:28:50 [s4:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/7299.mp3".
2022/01/06 02:28:50 [s4:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/3829.flac" (RID 3).
2022/01/06 02:28:50 [cue_cut_7721:3] Cueing in...
2022/01/06 02:28:50 [amplify_7725:3] Overriding amplification: 0.455512.
2022/01/06 02:28:50 [lang:3] timeout --signal=KILL 45 pyponotify --media-id=55730 &
2022/01/06 02:28:50 [lang:3] Using stream_format 0
2022/01/06 02:28:50 [lang:3] Using stream_format 0
2022/01/06 02:28:50 [lang:3] Using stream_format 0
2022/01/06 02:29:59 [cue_cut_7721:3] Cueing out...
2022/01/06 02:29:59 [s4:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/3829.flac".
2022/01/06 02:29:59 [amplify_7725:3] End of the current overriding.
2022/01/06 02:29:59 [dummy(dot)3:3] Source failed (no more tracks) stopping output...
2022/01/06 02:29:59 [dummy(dot)4:3] Source failed (no more tracks) stopping output...
2022/01/06 02:29:59 [schedule_noise_switch:3] Switch to map_metadata_7800 with forgetful transition.
2022/01/06 02:29:59 [lang:3] transition called...
2022/01/06 02:30:00 [server:3] New client: 127.0.0.1.
2022/01/06 02:30:00 [decoder:3] Method "FLAC" accepted "/var/tmp/airtime/pypo/cache/scheduler/1794.flac".
2022/01/06 02:30:00 [lang:3] vars.show_name
2022/01/06 02:30:00 [server:3] Client 127.0.0.1 disconnected.
2022/01/06 02:30:00 [s4:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/1794.flac" (RID 4).
2022/01/06 02:30:00 [schedule_noise_switch:3] Switch to map_metadata_7793 with transition.
2022/01/06 02:30:00 [lang:3] transition called...
2022/01/06 02:30:00 [switch_7791:3] Switch to insert_metadata_7777.
2022/01/06 02:30:00 [cue_cut_7721:3] Cueing in...
2022/01/06 02:30:00 [amplify_7725:3] Overriding amplification: 0.565588.
2022/01/06 02:30:00 [lang:3] timeout --signal=KILL 45 pyponotify --media-id=55734 &
2022/01/06 02:30:00 [lang:3] Using stream_format 0
2022/01/06 02:30:00 [lang:3] Using stream_format 0
2022/01/06 02:30:00 [lang:3] Using stream_format 0
2022/01/06 02:33:09 [server:3] New client: 127.0.0.1.
2022/01/06 02:33:09 [lang:3] dynamic_source.get_id
2022/01/06 02:33:09 [server:3] Client 127.0.0.1 disconnected.
2022/01/06 02:36:08 [server:3] New client: 127.0.0.1.
2022/01/06 02:36:08 [lang:3] vars.show_name
2022/01/06 02:36:08 [server:3] Client 127.0.0.1 disconnected.
2022/01/06 02:40:04 [server:3] New client: 127.0.0.1.
2022/01/06 02:40:04 [lang:3] dynamic_source.get_id
2022/01/06 02:40:04 [server:3] Client 127.0.0.1 disconnected.
2022/01/06 02:43:48 [server:3] New client: 127.0.0.1.
2022/01/06 02:43:48 [lang:3] vars.show_name
2022/01/06 02:43:48 [server:3] Client 127.0.0.1 disconnected.
2022/01/06 02:44:40 [server:3] New client: 127.0.0.1.
2022/01/06 02:44:40 [lang:3] vars.show_name
2022/01/06 02:44:40 [server:3] Client 127.0.0.1 disconnected.
2022/01/06 02:44:48 [server:3] New client: 127.0.0.1.
2022/01/06 02:44:48 [lang:3] vars.show_name
2022/01/06 02:44:48 [server:3] Client 127.0.0.1 disconnected.
[...] Same logs until I restarted the playout service

playout :

[...] Too much logs, we should fix this logging problem
2022-01-06 02:33:09,554 [pypoliquidsoap] [INFO ]  XXX: scheduled_now_files: [{'start': datetime.datetime(2022, 1, 6, 1, 30), 'end': datetime.datetime(2022, 1, 6, 1, 36, 8), 'row_id': 55734, 'show_name': 'Musique', 'independent_event': False, 'type': 'file', 'id': 1794, 'fade_in': 500.0, 'fade_out': 500.0, 'cue_in': 0.419025, 'cue_out': 368.813333, 'metadata': {'item_url': 'https://radio.org/api/v2/files/1794/', 'name': '', 'mime': 'audio/flac', 'ftype': 'audioclip', 'filepath': 'imported/6/Michel Camilo & Tomatito/Spain/08 Aire De Tango.flac', 'import_status': 0, 'currently_accessing': 0, 'mtime': '2021-09-26T02:41:10Z', 'utime': '2021-09-26T02:41:07Z', 'lptime': '2022-01-06T01:30:00Z', 'md5': '1f6df79d38c1c6018cbe9a4be208daca', 'track_title': 'Aire De Tango', 'artist_name': 'Michel Camilo & Tomatito', 'bit_rate': 646035, 'sample_rate': 44100, 'format': None, 'length': '00:06:08.813333', 'album_title': 'Spain', 'genre': 'Electronic; Ambient; Classical; Rock', 'comments': None, 'year': '2000', 'track_number': 8, 'channels': 2, 'url': None, 'bpm': 103, 'rating': None, 'encoded_by': None, 'disc_number': None, 'mood': 'Acoustic', 'label': None, 'composer': None, 'encoder': None, 'checksum': None, 'lyrics': None, 'orchestra': None, 'conductor': None, 'lyricist': None, 'original_lyricist': None, 'radio_station_name': None, 'info_url': None, 'artist_url': None, 'audio_source_url': None, 'radio_station_url': None, 'buy_this_url': None, 'isrc_number': None, 'catalog_number': None, 'original_artist': None, 'copyright': None, 'report_datetime': None, 'report_location': None, 'report_organization': None, 'subject': None, 'contributor': None, 'language': 'sp', 'file_exists': True, 'replay_gain': '-4.95', 'cuein': '00:00:00.419025', 'cueout': '00:06:08.813333', 'silan_check': False, 'hidden': False, 'is_scheduled': True, 'is_playlist': False, 'filesize': 29873219, 'description': None, 'artwork': 'imported/6/artwork/08 Aire De Tango', 'track_type': 'MUS', 'directory': 'https://radio.org/api/v2/music-dirs/1/', 'edited_by': None, 'owner': 'https://radio.org/api/v2/users/6/'}, 'uri': 'https://radio.org/api/v2/files/1794/', 'replay_gain': '-4.95', 'filesize': 29873219, 'file_ext': '.flac', 'dst': '/var/tmp/airtime/pypo/cache/scheduler/1794.flac', 'file_ready': True}]
2022-01-06 02:40:04,939 [pypofetch] [INFO ]  File '/var/tmp/airtime/pypo/cache/scheduler/1794.flac' not removed. Still busy!
[...] Still bussy is being logged in loop until the service restarts
jooola commented 2 years ago

Probably related to https://github.com/savonet/liquidsoap/issues/1543

I upgraded to 1.4.4 to see if using ffmpeg fixes my problem. Testing is in progress

jooola commented 2 years ago

Even if the fix above isn't necessary the right one, we should consider adding the possibility to restrict the decoders used by liquidsoap. This should go into the stream settings in order to land in the liquidsoap generated config.

jooola commented 2 years ago

Upgrading to liquidsoap 1.4.4 fixed it, so I suspect some malformed files generated a bug on the liquidsoap side. Running with ffmpeg makes it run flawlessly.

I'll reopen if I see this error again.