libretime/playout/libretime_playout/player/file.py

184 lines
6.3 KiB
Python
Raw Permalink Normal View History

import hashlib
2023-02-26 01:27:00 +01:00
import logging
import os
import time
from queue import Empty, Queue
from threading import Thread
from typing import Optional
2023-03-01 17:13:02 +01:00
import requests
from libretime_api_client.v2 import ApiClient
from .events import FileEvent, FileEvents
2023-02-26 01:27:00 +01:00
logger = logging.getLogger(__name__)
class PypoFile(Thread):
2022-08-14 19:55:39 +02:00
name = "file"
daemon = True
2022-08-14 19:55:39 +02:00
file_events_queue: "Queue[FileEvents]"
file_events: FileEvents
def __init__(
self,
file_queue: "Queue[FileEvents]",
api_client: ApiClient,
):
Thread.__init__(self)
self.file_events_queue = file_queue
self.file_events = {}
self.api_client = api_client
def copy_file(self, file_event: FileEvent):
"""
Copy file_event from local library directory to local cache directory.
"""
if file_event.local_filepath.is_file():
logger.debug(
"found file %s in cache %s",
file_event.id,
file_event.local_filepath,
)
file_event.file_ready = True
return
logger.info(
"copying file %s to cache %s",
file_event.id,
file_event.local_filepath,
)
try:
try:
with file_event.local_filepath.open("wb") as file_fd:
response = self.api_client.download_file(file_event.id, stream=True)
for chunk in response.iter_content(chunk_size=8192):
file_fd.write(chunk)
except requests.exceptions.HTTPError as exception:
file_event.local_filepath.unlink(missing_ok=True)
raise RuntimeError(
f"could not download file {file_event.id}"
) from exception
# make file world readable and owner writable
file_event.local_filepath.chmod(0o644)
if file_event.filesize == 0:
file_event.filesize = self.report_file_size_and_md5_to_api(
str(file_event.local_filepath),
file_event.id,
)
file_event.file_ready = True
except Exception as exception: # pylint: disable=broad-exception-caught
logger.exception(
"could not copy file %s to %s: %s",
file_event.id,
file_event.local_filepath,
exception,
)
def report_file_size_and_md5_to_api(self, file_path: str, file_id: int) -> int:
try:
file_size = os.path.getsize(file_path)
2023-03-01 17:13:02 +01:00
with open(file_path, "rb") as file_fd:
fix(playout): improve the way hashlib is called in libretime_playout/player (#3135) ### Description Improves the way hashlib is called in libretime_playout/player so that is isn't broken on systems with python < 3.9 The way it is currently called in site-packages/libretime_playout/player/file.py, in the section where scheduled files are copied to the cache dir for playout, specifies the usedforsecurity=False flag as follows: `hasher = hashlib.md5(usedforsecurity=False)` hashlib.md5 did not support this flag until Python 3.9. Attempting to specify the flag directly as an argument to hashlib.md5(), in an older python environment (such as that in Ubuntu Focal 20.04), is unsafe, and can cause hashlib.md5() to balk/throw an exception, which results in file copy operations failing. This then precipitates into playout problems, as scheduled media is missing from the cache folder. This PR instead calls using hashlib.new(), and passes the argument to that, as follows: `hasher = hashlib.new('md5', usedforsecurity=False)` This method of calling with the flag argument is safer, because the constructor will take it or leave it gracefully, regardless of whether the system has a version of hashlib that supports the `usedforsecurity` flag. AFAICT, it improves (fixes) function on older systems without negatively impacting others. ### Testing Notes **What I did:** Before applying this patch, we were experiencing occasional but fairly regular periods of silence when the system was supposed to be playing a song or track. This behavior was consistent with errors such as the following being present in the playout log: ``` 2025-01-15 14:01:28,331 | INFO | libretime_playout.player.file:copy_file:47 - copying file 19834 to cache /var/lib/libretime/playout/scheduler/19834.mp3 2025-01-15 14:01:28,466 | ERROR | libretime_playout.player.file:copy_file:77 - could not copy file 19834 to /var/lib/libretime/playout/scheduler/19834.mp3: 'usedforsecurity' is an invalid keyword argument for openssl_md5() Traceback (most recent call last): File "/opt/libretime/lib/python3.8/site-packages/libretime_playout/player/file.py", line 70, in copy_file file_event.filesize = self.report_file_size_and_md5_to_api( File "/opt/libretime/lib/python3.8/site-packages/libretime_playout/player/file.py", line 89, in report_file_size_and_md5_to_api hasher = hashlib.md5(usedforsecurity=False) TypeError: 'usedforsecurity' is an invalid keyword argument for openssl_md5() ``` _For more information about the characterization and results of this problem, see issue #3134_ **Testing on running systems** After the patch was applied, these errors were no longer seen. I first tested this on a dev server, and then on a live server, with approximately 100 distinct tracks of playout occurring over about 24 hours. There were no file copy failures, and no related playout problems, which was a major and immediate improvement. **Testing installer, fresh installs** ***Ubuntu 20.04*** I deployed a patch to the installer and installed it on a blank system running Ubuntu 20.04 and tested it to make sure the fix was applied and worked. ***Debian 11*** I deployed patch to the installer and installed it on a blank system running Debian Bullseye (which runs python = 3.9) , and tested it there to make sure it did not break anything or introduce a regression. ### **Links** Closes: #3134
2025-01-18 00:11:02 +01:00
hasher = hashlib.new("md5", usedforsecurity=False)
while True:
2023-03-01 17:13:02 +01:00
data = file_fd.read(8192)
if not data:
break
hasher.update(data)
md5_hash = hasher.hexdigest()
except OSError as exception:
file_size = 0
logger.exception(
"Error getting file size and md5 hash for file id %s: %s",
file_id,
exception,
2021-05-27 16:23:02 +02:00
)
# Make PUT request to LibreTime to update the file size and hash
error_msg = f"Could not update media file {file_id} with file size and md5 hash"
2017-10-03 03:37:06 +02:00
try:
self.api_client.update_file(
file_id,
json={"filesize": file_size, "md5": md5_hash},
)
2023-03-01 17:13:02 +01:00
except (requests.exceptions.ConnectionError, requests.exceptions.Timeout):
logger.exception(error_msg)
except Exception as exception: # pylint: disable=broad-exception-caught
logger.exception("%s: %s", error_msg, exception)
return file_size
def get_highest_priority_file_event(
self,
file_events: FileEvents,
) -> Optional[FileEvent]:
"""
Get highest priority file event in the queue. Currently the highest
priority is decided by how close the start time is to "now".
"""
if file_events is None or len(file_events) == 0:
return None
sorted_keys = sorted(file_events.keys())
if len(sorted_keys) == 0:
return None
highest_priority = sorted_keys[0]
file_event = file_events[highest_priority]
logger.debug("Highest priority item: %s", highest_priority)
# Remove this media_item from the dictionary. On the next iteration
# (from the main function) we won't consider it for prioritization
# anymore. If on the next iteration we have received a new schedule,
# it is very possible we will have to deal with the same media_items
# again. In this situation, the worst possible case is that we try to
# copy the file again and realize we already have it (thus aborting the copy).
del file_events[highest_priority]
return file_event
def main(self):
while True:
try:
if self.file_events is None or len(self.file_events) == 0:
# We have no schedule, so we have nothing else to do. Let's
# do a blocked wait on the queue
self.file_events = self.file_events_queue.get(block=True)
else:
# We have a schedule we need to process, but we also want
# to check if a newer schedule is available. In this case
# do a non-blocking queue.get and in either case (we get something
# or we don't), get back to work on preparing getting files.
try:
self.file_events = self.file_events_queue.get_nowait()
except Empty:
pass
file_event = self.get_highest_priority_file_event(self.file_events)
if file_event is not None:
self.copy_file(file_event)
except Exception as exception: # pylint: disable=broad-exception-caught
logger.exception(exception)
raise exception
def run(self):
"""
Entry point of the thread
"""
2021-05-27 16:23:02 +02:00
try:
self.main()
except Exception as exception: # pylint: disable=broad-exception-caught
logger.exception(exception)
time.sleep(5)
feat(playout): enhance playout logging (#1495) Some initial work on modernizing the playout app. This replace any custom logger or logging based logger with the logging tools from libretime_shared.logging and loguru. Removed all the thread/function assigned logger (self.logger = ...), as this makes it part of the logic (passing logger though function args) as it should not. Of a dedicated logger is required for a specific task, it should use the create_task_logger function. - refactor: remove dead code - refactor: remove py2 specific fix - feat: remove unused test command - feat: setup shared cli and logging tools - feat: replace logging with loguru - feat: setup shared cli and logging tools for notify - fix: warn method deos not exist - feat: make cli setup the entrypoint - fix: install shared modules globally in production use extra_requires to load local packages in dev environement - feat: configure log path in systemd service - feat: default behavior is to log to console only - feat: create log dir during install - chore: add comment - fix: don't create useless dir in install - fix: move notify logs to /var/log/libretime dir - fix: update setup_logger attrs - style: linting - fix: replace verbosity flag with log-level flag - feat: use shared logging tool in liquidsoap - fix: pass logger down to api client - feat: allow custom log_filepath in liquidsoap config - chore: add pylintrc to playout - refactor: fix pylint errors - feat: set liquidsoap log filepath in systemd service - fix: missing setup entrypoint update BREAKING CHANGE: for playout and liquidsoap the default log file path changed to None and will only log to the console when developing / testing. Unless you are running the app as a systemd service (production) the default logs filepaths changed: from "/var/log/airtime/pypo/pypo.log" to "/var/log/libretime/playout.log" and from "/var/log/airtime/pypo-liquidsoap/ls_script.log" to "/var/log/libretime/liquidsoap.log" BREAKING CHANGE: for playout-notify the default log file path changed from "/var/log/airtime/pypo/notify.log" to "/var/log/libretime/playout-notify.log"
2022-01-13 16:11:37 +01:00
logger.info("PypoFile thread exiting")