search

radioangrezi / angrezi-live-recorder

a audio recorder for live radio with meta data and remote-triggered cuts. Connects to Airtime for auto-scheduled recordings.
MIT License
3 stars 0 forks source link

(some) recordings fail or stop after 3 seconds #15

Open jelko opened 4 years ago

jelko commented 4 years ago

If two recordings are scheduled in rapid succession (without a break in between or with a very short break only), the second recording will (most likely) fail.

Guess: The scheduled start of the second recording is (correctly) triggered, when the Recorder (process) is (technically) still running. The process naturally needs time to start and save the file and terminate. Since the start of the sucessive recording is correctly triggered, it will not be repeated (or queued), even though it does fail, which is logged correctly.

Report from plenum:

Probleme mit dem Recorder: Sendungen werden nicht richtig aufgezeichnet Leo und Jelko ist die Fehlerquelle (nun) bekannt, kann aber voraussichtlich in 3 Wochen bearbeitet werden. Bitte aktuell Aufnahmen manuell starten und den Start überprüfen.

@the-leonat Habe ich Details des Problems vergessen oder nicht beachtet?

jelko commented 4 years ago

The problem is not specific to successive recordings! Recordings do fail (or stop after 3 seconds) even without a preceding show (or a successive one).

Log from a failed try (Auto-scheduled start for 17:00:00, fail / stop after 3 seconds, manual restart after 29 seconds via web interface):

Aug 25 16:42:00 angrezi-streaming python[4853]: [9.6K blob data]
Aug 25 16:42:02 angrezi-streaming python[4853]: [326B blob data]
Aug 25 16:42:02 angrezi-streaming python[4853]: WARNING:root:Can not start scheduled rec. Recorder already running.
Aug 25 16:42:02 angrezi-streaming python[4853]: INFO:airtime_schedule:End was re-scheduled at 2020-08-25 18:44:00+02:00 with job rec-end-airtime-846
Aug 25 16:42:02 angrezi-streaming python[4853]: INFO:airtime_schedule:Scheduling... 842 <airtime_schedule.AirtimeBroadcastRecording object at 0x7fc75d5401d0>
Aug 25 16:42:02 angrezi-streaming python[4853]: INFO:airtime_schedule:Start was re-scheduled at 2020-08-25 19:00:00+02:00 with job rec-start-airtime-842
Aug 25 16:42:02 angrezi-streaming python[4853]: INFO:airtime_schedule:End was re-scheduled at 2020-08-25 23:59:00+02:00 with job rec-end-airtime-842
Aug 25 16:44:00 angrezi-streaming python[4853]: [8.9K blob data]
Aug 25 16:44:00 angrezi-streaming python[4853]: INFO:recorder:Finishing file '2020/08/25/radio-angrezi-live-2020-08-25-16-39-54_incomplete.mp3'
Aug 25 16:44:00 angrezi-streaming python[4853]: shutting down
Aug 25 16:44:00 angrezi-streaming python[4853]: bye..
Aug 25 16:44:00 angrezi-streaming python[4853]: DEBUG:recorder:Streamripper terminated.
Aug 25 16:44:00 angrezi-streaming python[4853]: INFO:recorder:File: '2020/08/25/radio-angrezi-live-2020-08-25-16-39-54.mp3'
Aug 25 16:44:00 angrezi-streaming python[4853]: DEBUG:recorder:Current filename: 2020/08/25/radio-angrezi-live-2020-08-25-16-39-54_incomplete.mp3
Aug 25 16:44:00 angrezi-streaming python[4853]: DEBUG:recorder:New filename: 2020/08/25/radio-angrezi-live-2020-08-25-16-39-54.mp3
Aug 25 16:44:02 angrezi-streaming python[4853]: INFO:airtime_schedule:Un-Scheduling... 846 <airtime_schedule.AirtimeBroadcastRecording object at 0x7fc75d53ac90>
Aug 25 17:00:00 angrezi-streaming python[4853]: INFO:recorder:File: '2020/08/25/radio-angrezi-live-2020-08-25-17-00-00_incomplete.mp3'
Aug 25 17:00:00 angrezi-streaming python[4853]: DEBUG:recorder:Starting streamripper
Aug 25 17:00:00 angrezi-streaming python[4853]: Connecting...
Aug 25 17:00:00 angrezi-streaming python[4853]: stream: Radio Angrezi
Aug 25 17:00:00 angrezi-streaming python[4853]: server name: Icecast 2.4.3
Aug 25 17:00:00 angrezi-streaming python[4853]: declared bitrate: 320
Aug 25 17:00:00 angrezi-streaming python[4853]: meta interval: 16000
Aug 25 17:00:02 angrezi-streaming python[4853]: [409B blob data]
Aug 25 17:00:02 angrezi-streaming python[4853]: WARNING:root:Can not start scheduled rec. Recorder already running.
Aug 25 17:00:02 angrezi-streaming python[4853]: INFO:airtime_schedule:End was re-scheduled at 2020-08-25 23:59:00+02:00 with job rec-end-airtime-842
Aug 25 17:00:02 angrezi-streaming python[4853]: INFO:airtime_schedule:Un-Scheduling... 842 <airtime_schedule.AirtimeBroadcastRecording object at 0x7fc75d5401d0>
Aug 25 17:00:02 angrezi-streaming python[4853]: DEBUG:recorder:Recording stop called.
Aug 25 17:00:02 angrezi-streaming python[4853]: INFO:recorder:Finishing file '2020/08/25/radio-angrezi-live-2020-08-25-17-00-00_incomplete.mp3'
Aug 25 17:00:02 angrezi-streaming python[4853]: shutting down
Aug 25 17:00:02 angrezi-streaming python[4853]: bye..
Aug 25 17:00:02 angrezi-streaming python[4853]: DEBUG:recorder:Streamripper terminated.
Aug 25 17:00:02 angrezi-streaming python[4853]: INFO:recorder:File: '2020/08/25/radio-angrezi-live-2020-08-25-17-00-00_alpenkritik.mp3'
Aug 25 17:00:02 angrezi-streaming python[4853]: DEBUG:recorder:Current filename: 2020/08/25/radio-angrezi-live-2020-08-25-17-00-00_incomplete.mp3
Aug 25 17:00:02 angrezi-streaming python[4853]: DEBUG:recorder:New filename: 2020/08/25/radio-angrezi-live-2020-08-25-17-00-00_alpenkritik.mp3
Aug 25 17:00:29 angrezi-streaming python[4853]: DEBUG:recorder:Recording stop called.
Aug 25 17:00:29 angrezi-streaming python[4853]: INFO:recorder:File: '2020/08/25/radio-angrezi-live-2020-08-25-17-00-29_incomplete.mp3'
Aug 25 17:00:29 angrezi-streaming python[4853]: DEBUG:recorder:Starting streamripper
Aug 25 17:00:29 angrezi-streaming python[4853]: Connecting...
Aug 25 17:00:29 angrezi-streaming python[4853]: stream: Radio Angrezi
Aug 25 17:00:29 angrezi-streaming python[4853]: server name: Icecast 2.4.3
jelko commented 4 years ago

A first analysis of airtime_schedule.pyshows that the 3 seconds might correlate with SECONDS_WITHIN_START_IMMEDIATELY = 3. The faulty stop after the beginning might be triggered through the auto_start for show that are already running:

        if start:
            if self.start < now() + datetime.timedelta(seconds=SECONDS_WITHIN_START_IMMEDIATELY):
                # start immediately if start has passed or within 3 sec from now
                self.trigger_start(id=self.id, name=self.name)

Or / and triggered by "Un-Scheduling" stale or finished recordings in update() of AirtimeRecordingScheduler:

                if previous_broadcast and previous_broadcast not in others:
                    # stop stale / finished show and recordings
                    logger.info("Un-Scheduling... %i %s" % (previous_broadcast.get_unique_id(), previous_broadcast.__repr__()))
                    previous_broadcast.unschedule_and_stop_recording()