def start_command(): nonlocal currently_encoding log_queue.put( f"CLEAR_WINDOW:{video.uuid}:{video.video_settings.conversion_commands[video.status.current_command].uuid}" ) reusables.remove_file_handlers(logger) new_file_handler = reusables.get_file_handler( log_path / sanitize_filename( f"flix_conversion_{video.video_settings.video_title or video.video_settings.output_path.stem}_{file_date()}.log" ), level=logging.DEBUG, log_format="%(asctime)s - %(message)s", encoding="utf-8", ) logger.addHandler(new_file_handler) prevent_sleep_mode() currently_encoding = True runner.start_exec( video.video_settings.conversion_commands[ video.status.current_command].command, work_dir=str(video.work_path), ) set_status(video, queue_list=queue_list, queue_lock=queue_lock, running=True) status_queue.put(("queue", ))
def test_get_file_logger(self): logger = reusables.get_logger(__name__, stream=None, file_path=my_stream_path) logger.info("Test log") logger.error("Example 2nd error log") reusables.remove_file_handlers(logger) with open(my_stream_path) as f: lines = f.readlines() assert "INFO" in lines[0] assert "ERROR" in lines[1] assert "Example 2nd error log" in lines[1]
def test_change_log_level(self): logger = reusables.get_logger(__name__, level=logging.WARNING, stream=None, file_path=my_stream_path) logger.debug("Hello There, sexy") reusables.change_logger_levels(__name__, 10) logger.debug("This isn't a good idea") reusables.remove_file_handlers(logger) with open(my_stream_path) as f: line = f.readline() assert "good idea" in line, line
def test_remove_file_handlers(self): logger = reusables.get_logger("sample_file_logger", file_path=my_stream_path) logger.addHandler(logging.FileHandler("test_file")) logger.addHandler(logging.NullHandler()) reusables.remove_file_handlers("sample_file_logger") assert len(logger.handlers) == 2 assert isinstance(logger.handlers[0], logging.StreamHandler) try: os.unlink("test_file") except Exception: pass reusables.remove_all_handlers(logger)
def start_command(): nonlocal currently_encoding log_queue.put(f"CLEAR_WINDOW:{video_uuid}:{command_uuid}") reusables.remove_file_handlers(logger) new_file_handler = reusables.get_file_handler( log_path / sanitize_filename(f"flix_conversion_{log_name}_{file_date()}.log"), level=logging.DEBUG, log_format="%(asctime)s - %(message)s", encoding="utf-8", ) logger.addHandler(new_file_handler) currently_encoding = True runner.start_exec( command, work_dir=work_dir, )
def start_command(): nonlocal currently_encoding log_queue.put( f"CLEAR_WINDOW:{commands_to_run[0][0]}:{commands_to_run[0][1]}") reusables.remove_file_handlers(logger) new_file_handler = reusables.get_file_handler( log_path / f"flix_conversion_{commands_to_run[0][4]}_{file_date()}.log", level=logging.DEBUG, log_format="%(asctime)s - %(message)s", encoding="utf-8", ) logger.addHandler(new_file_handler) prevent_sleep_mode() currently_encoding = True status_queue.put( ("running", commands_to_run[0][0], commands_to_run[0][1])) runner.start_exec( commands_to_run[0][2], work_dir=commands_to_run[0][3], )
def test_log_exception_message(self): """ Validate the message passed to the custom log exception is written correctly in the logs. """ get_logger("my_logger", file_path="out.log") message = "I would like to take this moment to say something " \ "interesting has happened. " @log_exception("my_logger", message=message) def unique_function_5(): raise Exception("Interesting") try: unique_function_5() except Exception: pass remove_file_handlers("my_logger") with open(os.path.join("out.log"), "r") as f: assert message in f.readlines()[0] os.remove(os.path.join("out.log"))
def queue_worker(gui_proc, worker_queue, status_queue, log_queue): runner = BackgroundRunner(log_queue=log_queue) # Command looks like (video_uuid, command_uuid, command, work_dir) after_done_command = "" commands_to_run = [] gui_died = False currently_encoding = False paused = False log_path = Path(user_data_dir("FastFlix", appauthor=False, roaming=True)) / "logs" after_done_path = Path( user_data_dir("FastFlix", appauthor=False, roaming=True)) / "after_done_logs" def start_command(): nonlocal currently_encoding log_queue.put( f"CLEAR_WINDOW:{commands_to_run[0][0]}:{commands_to_run[0][1]}") reusables.remove_file_handlers(logger) new_file_handler = reusables.get_file_handler( log_path / f"flix_conversion_{commands_to_run[0][4]}_{file_date()}.log", level=logging.DEBUG, log_format="%(asctime)s - %(message)s", encoding="utf-8", ) logger.addHandler(new_file_handler) prevent_sleep_mode() currently_encoding = True status_queue.put( ("running", commands_to_run[0][0], commands_to_run[0][1])) runner.start_exec( commands_to_run[0][2], work_dir=commands_to_run[0][3], ) while True: if currently_encoding and not runner.is_alive(): reusables.remove_file_handlers(logger) if runner.error_detected: logger.info(t("Error detected while converting")) # Stop working! currently_encoding = False status_queue.put( ("error", commands_to_run[0][0], commands_to_run[0][1])) commands_to_run = [] allow_sleep_mode() if gui_died: return continue # Successfully encoded, do next one if it exists # First check if the current video has more commands logger.info(t("Command has completed")) status_queue.put( ("converted", commands_to_run[0][0], commands_to_run[0][1])) commands_to_run.pop(0) if commands_to_run: if not paused: logger.info(t("starting next command")) start_command() else: currently_encoding = False allow_sleep_mode() logger.debug(t("Queue has been paused")) continue else: logger.info(t("all conversions complete")) # Finished the queue # fastflix.current_encoding = None currently_encoding = False status_queue.put(("complete", )) allow_sleep_mode() if after_done_command: logger.info( f"{t('Running after done command:')} {after_done_command}" ) try: runner.start_exec(after_done_command, str(after_done_path)) except Exception: logger.exception( "Error occurred while running after done command") continue if gui_died: return if not gui_died and not gui_proc.is_alive(): gui_proc.join() gui_died = True if runner.is_alive() or currently_encoding: logger.info( t("The GUI might have died, but I'm going to keep converting!" )) else: logger.debug(t("Conversion worker shutting down")) return try: request = worker_queue.get(block=True, timeout=0.05) except Empty: continue except KeyboardInterrupt: status_queue.put(("exit", )) allow_sleep_mode() return else: if request[0] == "add_items": # Request looks like (queue command, log_dir, (commands)) log_path = Path(request[1]) for command in request[2]: if command not in commands_to_run: logger.debug( t(f"Adding command to the queue for {command[4]} - {command[2]}" )) commands_to_run.append(command) # else: # logger.debug(t(f"Command already in queue: {command[1]}")) if not runner.is_alive() and not paused: logger.debug( t("No encoding is currently in process, starting encode" )) start_command() if request[0] == "cancel": logger.debug(t("Cancel has been requested, killing encoding")) runner.kill() currently_encoding = False allow_sleep_mode() status_queue.put(("cancelled", commands_to_run[0][0], commands_to_run[0][1])) commands_to_run = [] if request[0] == "pause queue": logger.debug( t("Command worker received request to pause encoding after the current item completes" )) paused = True if request[0] == "resume queue": paused = False logger.debug( t("Command worker received request to resume encoding")) if commands_to_run and not runner.is_alive(): start_command() if request[0] == "set after done": after_done_command = request[1] if after_done_command: logger.debug( f'{t("Setting after done command to:")} {after_done_command}' ) else: logger.debug(t("Removing after done command")) if request[0] == "pause encode": logger.debug( t("Command worker received request to pause current encode" )) try: runner.pause() except Exception: logger.exception("Could not pause command") else: status_queue.put(("paused encode", commands_to_run[0][0], commands_to_run[0][1])) if request[0] == "resume encode": logger.debug( t("Command worker received request to resume paused encode" )) try: runner.resume() except Exception: logger.exception("Could not resume command") else: status_queue.put(("resumed encode", commands_to_run[0][0], commands_to_run[0][1]))
def queue_worker(gui_proc, worker_queue, status_queue, log_queue): runner = BackgroundRunner(log_queue=log_queue) gui_died = False currently_encoding = False video_uuid = None command_uuid = None command = None work_dir = None log_name = "" def start_command(): nonlocal currently_encoding log_queue.put(f"CLEAR_WINDOW:{video_uuid}:{command_uuid}") reusables.remove_file_handlers(logger) new_file_handler = reusables.get_file_handler( log_path / sanitize_filename(f"flix_conversion_{log_name}_{file_date()}.log"), level=logging.DEBUG, log_format="%(asctime)s - %(message)s", encoding="utf-8", ) logger.addHandler(new_file_handler) currently_encoding = True runner.start_exec( command, work_dir=work_dir, ) while True: if currently_encoding and not runner.is_alive(): reusables.remove_file_handlers(logger) log_queue.put("STOP_TIMER") currently_encoding = False if runner.error_detected: logger.info(t("Error detected while converting")) status_queue.put(("error", video_uuid, command_uuid)) if gui_died: return continue status_queue.put(("complete", video_uuid, command_uuid)) if gui_died: return if not gui_died and not gui_proc.is_alive(): gui_proc.join() gui_died = True if runner.is_alive() or currently_encoding: logger.info( t("The GUI might have died, but I'm going to keep converting!" )) else: logger.debug(t("Conversion worker shutting down")) return try: request = worker_queue.get(block=True, timeout=0.05) except Empty: continue except KeyboardInterrupt: status_queue.put(("exit", )) return else: if request[0] == "execute": _, video_uuid, command_uuid, command, work_dir, log_name = request start_command() if request[0] == "cancel": logger.debug(t("Cancel has been requested, killing encoding")) runner.kill() currently_encoding = False status_queue.put(("cancelled", video_uuid, command_uuid)) log_queue.put("STOP_TIMER") if request[0] == "pause encode": logger.debug( t("Command worker received request to pause current encode" )) try: runner.pause() except Exception: logger.exception("Could not pause command") if request[0] == "resume encode": logger.debug( t("Command worker received request to resume paused encode" )) try: runner.resume() except Exception: logger.exception("Could not resume command")
def queue_worker(gui_proc, worker_queue, status_queue, log_queue, queue_list, queue_lock: Lock): runner = BackgroundRunner(log_queue=log_queue) # Command looks like (video_uuid, command_uuid, command, work_dir) after_done_command = "" gui_died = False currently_encoding = False paused = False video: Optional[Video] = None def start_command(): nonlocal currently_encoding log_queue.put( f"CLEAR_WINDOW:{video.uuid}:{video.video_settings.conversion_commands[video.status.current_command].uuid}" ) reusables.remove_file_handlers(logger) new_file_handler = reusables.get_file_handler( log_path / sanitize_filename( f"flix_conversion_{video.video_settings.video_title or video.video_settings.output_path.stem}_{file_date()}.log" ), level=logging.DEBUG, log_format="%(asctime)s - %(message)s", encoding="utf-8", ) logger.addHandler(new_file_handler) prevent_sleep_mode() currently_encoding = True runner.start_exec( video.video_settings.conversion_commands[ video.status.current_command].command, work_dir=str(video.work_path), ) set_status(video, queue_list=queue_list, queue_lock=queue_lock, running=True) status_queue.put(("queue", )) # status_queue.put(("running", commands_to_run[0][0], commands_to_run[0][1], runner.started_at.isoformat())) while True: if currently_encoding and not runner.is_alive(): reusables.remove_file_handlers(logger) if runner.error_detected: logger.info(t("Error detected while converting")) # Stop working! currently_encoding = False set_status(video, queue_list=queue_list, queue_lock=queue_lock, errored=True) status_queue.put(("error", )) allow_sleep_mode() if gui_died: return continue # Successfully encoded, do next one if it exists # First check if the current video has more commands video.status.current_command += 1 log_queue.put("STOP_TIMER") if len(video.video_settings.conversion_commands ) > video.status.current_command: logger.debug("About to run next command for this video") set_status(video, queue_list=queue_list, queue_lock=queue_lock, next_command=True) status_queue.put(("queue", )) start_command() continue else: logger.debug(f"{video.uuid} has been completed") set_status(video, queue_list=queue_list, queue_lock=queue_lock, next_command=True, complete=True) status_queue.put(("queue", )) video = None if paused: currently_encoding = False allow_sleep_mode() logger.debug(t("Queue has been paused")) continue if video := get_next_video(queue_list=queue_list, queue_lock=queue_lock): start_command() continue else: currently_encoding = False allow_sleep_mode() logger.info(t("all conversions complete")) status_queue.put(("complete", )) if after_done_command: logger.info( f"{t('Running after done command:')} {after_done_command}" ) try: runner.start_exec(after_done_command, str(after_done_path)) except Exception: logger.exception( "Error occurred while running after done command") continue if gui_died: return if not gui_died and not gui_proc.is_alive(): gui_proc.join() gui_died = True if runner.is_alive() or currently_encoding: logger.info( t("The GUI might have died, but I'm going to keep converting!" )) else: logger.debug(t("Conversion worker shutting down")) return try: request = worker_queue.get(block=True, timeout=0.05) except Empty: continue except KeyboardInterrupt: status_queue.put(("exit", )) allow_sleep_mode() return else: if request[0] == "add_items": # Request looks like (queue command, log_dir, (commands)) log_path = Path(request[1]) if not currently_encoding and not paused: video = get_next_video(queue_list=queue_list, queue_lock=queue_lock) if video: start_command() if request[0] == "cancel": logger.debug(t("Cancel has been requested, killing encoding")) runner.kill() if video: set_status(video, queue_list=queue_list, queue_lock=queue_lock, reset_commands=True, cancelled=True) currently_encoding = False allow_sleep_mode() status_queue.put(("cancelled", video.uuid if video else "")) log_queue.put("STOP_TIMER") video = None if request[0] == "pause queue": logger.debug( t("Command worker received request to pause encoding after the current item completes" )) paused = True if request[0] == "resume queue": paused = False logger.debug( t("Command worker received request to resume encoding")) if not currently_encoding: if not video: video = get_next_video(queue_list=queue_list, queue_lock=queue_lock) if video: start_command() if request[0] == "set after done": after_done_command = request[1] if after_done_command: logger.debug( f'{t("Setting after done command to:")} {after_done_command}' ) else: logger.debug(t("Removing after done command")) if request[0] == "pause encode": logger.debug( t("Command worker received request to pause current encode" )) try: runner.pause() except Exception: logger.exception("Could not pause command") else: status_queue.put(("paused encode", )) if request[0] == "resume encode": logger.debug( t("Command worker received request to resume paused encode" )) try: runner.resume() except Exception: logger.exception("Could not resume command") else: status_queue.put(("resumed encode", ))
def main(): logging.basicConfig(level=logging.DEBUG) data_path = Path(user_data_dir("FastFlix", appauthor=False, roaming=True)) data_path.mkdir(parents=True, exist_ok=True) log_dir = data_path / "logs" log_dir.mkdir(parents=True, exist_ok=True) queue = Queue() status_queue = Queue() log_queue = Queue() def log(msg, level=logging.INFO): log_queue.put(msg) logger.log(level, msg) runner = BackgroundRunner(log_queue=log_queue) gui_proc = Process(target=start_app, args=(queue, status_queue, log_queue, data_path, log_dir)) gui_proc.start() logger = logging.getLogger("fastflix-core") coloredlogs.install(level="DEBUG", logger=logger) logger.info(f"Starting FastFlix {__version__}") for leftover in Path(data_path).glob(f"encoder_output_*.log"): try: leftover.unlink() except OSError: pass sent_response = True gui_close_message = False queued_requests = [] while True: if not gui_close_message and not gui_proc.is_alive(): gui_proc.join() gui_close_message = True if runner.is_alive() or queued_requests: log( "The GUI might have died, but I'm going to keep converting!", logging.WARNING) else: break try: request = queue.get(block=True, timeout=0.01) except Empty: if not runner.is_alive( ) and not sent_response and not queued_requests: ret = runner.process.poll() if ret > 0: log(f"Error during conversion", logging.WARNING) else: log("conversion complete") reusables.remove_file_handlers(logger) status_queue.put("complete") sent_response = True if not gui_proc.is_alive(): return except KeyboardInterrupt: status_queue.put("exit") return else: if request[0] == "command": if runner.is_alive(): queued_requests.append(request) else: log_queue.put("CLEAR_WINDOW") reusables.remove_file_handlers(logger) new_file_handler = reusables.get_file_handler( log_dir / f"flix_conversion_{file_date()}.log", level=logging.DEBUG, log_format="%(asctime)s - %(message)s", encoding="utf-8", ) logger.addHandler(new_file_handler) runner.start_exec(*request[1:]) sent_response = False if request[0] == "cancel": queued_requests = [] runner.kill() status_queue.put("cancelled") sent_response = True if not runner.is_alive(): if queued_requests: runner.start_exec(*queued_requests.pop()[1:]) sent_response = False