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