diff --git a/TorrentToMedia.py b/TorrentToMedia.py index 89efedaf..a71a31f9 100755 --- a/TorrentToMedia.py +++ b/TorrentToMedia.py @@ -1,4 +1,5 @@ import datetime +import logging import os import sys @@ -11,6 +12,9 @@ from nzb2media.user_scripts import external_script from nzb2media.utils.encoding import char_replace, convert_to_ascii from nzb2media.utils.links import replace_links +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def process_torrent(input_directory, input_name, input_category, input_hash, input_id, client_agent): status = 1 # 1 = failed | 0 = success @@ -18,7 +22,7 @@ def process_torrent(input_directory, input_name, input_category, input_hash, inp found_file = 0 if client_agent != 'manual' and not nzb2media.DOWNLOAD_INFO: - logger.debug(f'Adding TORRENT download info for directory {input_directory} to database') + log.debug(f'Adding TORRENT download info for directory {input_directory} to database') my_db = main_db.DBConnection() @@ -42,7 +46,7 @@ def process_torrent(input_directory, input_name, input_category, input_hash, inp } my_db.upsert('downloads', new_value_dict, control_value_dict) - logger.debug(f'Received Directory: {input_directory} | Name: {input_name} | Category: {input_category}') + log.debug(f'Received Directory: {input_directory} | Name: {input_name} | Category: {input_category}') # Confirm the category by parsing directory structure input_directory, input_name, input_category, root = nzb2media.category_search( @@ -54,30 +58,30 @@ def process_torrent(input_directory, input_name, input_category, input_hash, inp usercat = input_category - logger.debug(f'Determined Directory: {input_directory} | Name: {input_name} | Category: {input_category}') + log.debug(f'Determined Directory: {input_directory} | Name: {input_name} | Category: {input_category}') # auto-detect section section = nzb2media.CFG.findsection(input_category).isenabled() - if section is None: #Check for user_scripts for 'ALL' and 'UNCAT' + if section is None: # Check for user_scripts for 'ALL' and 'UNCAT' if usercat in nzb2media.CATEGORIES: section = nzb2media.CFG.findsection('ALL').isenabled() usercat = 'ALL' else: section = nzb2media.CFG.findsection('UNCAT').isenabled() usercat = 'UNCAT' - if section is None: # We haven't found any categories to process. - logger.error(f'Category:[{input_category}] is not defined or is not enabled. Please rename it or ensure it is enabled for the appropriate section in your autoProcessMedia.cfg and try again.') + if section is None: # We haven't found any categories to process. + log.error(f'Category:[{input_category}] is not defined or is not enabled. Please rename it or ensure it is enabled for the appropriate section in your autoProcessMedia.cfg and try again.') return [-1, ''] if len(section) > 1: - logger.error(f'Category:[{usercat}] is not unique, {section.keys()} are using it. Please rename it or disable all other sections using the same category name in your autoProcessMedia.cfg and try again.') + log.error(f'Category:[{usercat}] is not unique, {section.keys()} are using it. Please rename it or disable all other sections using the same category name in your autoProcessMedia.cfg and try again.') return [-1, ''] if section: section_name = section.keys()[0] - logger.info(f'Auto-detected SECTION:{section_name}') + log.info(f'Auto-detected SECTION:{section_name}') else: - logger.error(f'Unable to locate a section with subsection:{input_category} enabled in your autoProcessMedia.cfg, exiting!') + log.error(f'Unable to locate a section with subsection:{input_category} enabled in your autoProcessMedia.cfg, exiting!') return [-1, ''] section = dict(section[section_name][usercat]) # Type cast to dict() to allow effective usage of .get() @@ -110,13 +114,13 @@ def process_torrent(input_directory, input_name, input_category, input_hash, inp if output_destination in input_directory: output_destination = input_directory - logger.info(f'Output directory set to: {output_destination}') + log.info(f'Output directory set to: {output_destination}') if nzb2media.SAFE_MODE and output_destination == nzb2media.TORRENT_DEFAULT_DIRECTORY: - logger.error(f'The output directory:[{input_directory}] is the Download Directory. Edit outputDirectory in autoProcessMedia.cfg. Exiting') + log.error(f'The output directory:[{input_directory}] is the Download Directory. Edit outputDirectory in autoProcessMedia.cfg. Exiting') return [-1, ''] - logger.debug(f'Scanning files in directory: {input_directory}') + log.debug(f'Scanning files in directory: {input_directory}') if section_name in ['HeadPhones', 'Lidarr']: nzb2media.NOFLATTEN.extend( @@ -131,9 +135,9 @@ def process_torrent(input_directory, input_name, input_category, input_hash, inp input_files = nzb2media.list_media_files(input_directory, other=True, otherext=extensions) if len(input_files) == 0 and os.path.isfile(input_directory): input_files = [input_directory] - logger.debug(f'Found 1 file to process: {input_directory}') + log.debug(f'Found 1 file to process: {input_directory}') else: - logger.debug(f'Found {len(input_files)} files in {input_directory}') + log.debug(f'Found {len(input_files)} files in {input_directory}') for inputFile in input_files: file_path = os.path.dirname(inputFile) file_name, file_ext = os.path.splitext(os.path.basename(inputFile)) @@ -145,16 +149,16 @@ def process_torrent(input_directory, input_name, input_category, input_hash, inp target_file = nzb2media.os.path.join( nzb2media.os.path.join(output_destination, os.path.basename(file_path)), full_file_name, ) - logger.debug(f'Setting outputDestination to {os.path.dirname(target_file)} to preserve folder structure') + log.debug(f'Setting outputDestination to {os.path.dirname(target_file)} to preserve folder structure') if root == 1: if not found_file: - logger.debug(f'Looking for {input_name} in: {inputFile}') + log.debug(f'Looking for {input_name} in: {inputFile}') if any([ nzb2media.sanitize_name(input_name) in nzb2media.sanitize_name(inputFile), nzb2media.sanitize_name(file_name) in nzb2media.sanitize_name(input_name), ]): found_file = True - logger.debug(f'Found file {full_file_name} that matches Torrent Name {input_name}') + log.debug(f'Found file {full_file_name} that matches Torrent Name {input_name}') else: continue @@ -163,10 +167,10 @@ def process_torrent(input_directory, input_name, input_category, input_hash, inp ctime_lapse = now - datetime.datetime.fromtimestamp(os.path.getctime(inputFile)) if not found_file: - logger.debug('Looking for files with modified/created dates less than 5 minutes old.') + log.debug('Looking for files with modified/created dates less than 5 minutes old.') if (mtime_lapse < datetime.timedelta(minutes=5)) or (ctime_lapse < datetime.timedelta(minutes=5)): found_file = True - logger.debug(f'Found file {full_file_name} with date modified/created less than 5 minutes ago.') + log.debug(f'Found file {full_file_name} with date modified/created less than 5 minutes ago.') else: continue # This file has not been recently moved or created, skip it @@ -175,12 +179,12 @@ def process_torrent(input_directory, input_name, input_category, input_hash, inp nzb2media.copy_link(inputFile, target_file, nzb2media.USE_LINK) nzb2media.remove_read_only(target_file) except Exception: - logger.error(f'Failed to link: {inputFile} to {target_file}') + log.error(f'Failed to link: {inputFile} to {target_file}') input_name, output_destination = convert_to_ascii(input_name, output_destination) if extract == 1: - logger.debug(f'Checking for archives to extract in directory: {input_directory}') + log.debug(f'Checking for archives to extract in directory: {input_directory}') nzb2media.extract_files(input_directory, output_destination, keep_archive) if input_category not in nzb2media.NOFLATTEN: @@ -193,20 +197,20 @@ def process_torrent(input_directory, input_name, input_category, input_hash, inp nzb2media.list_media_files(output_destination, media=True, audio=False, meta=False, archives=False), ) if num_videos > 0: - logger.info(f'Found {num_videos} media files in {output_destination}') + log.info(f'Found {num_videos} media files in {output_destination}') status = 0 elif extract != 1: - logger.info(f'Found no media files in {output_destination}. Sending to {section_name} to process') + log.info(f'Found no media files in {output_destination}. Sending to {section_name} to process') status = 0 else: - logger.warning(f'Found no media files in {output_destination}') + log.warning(f'Found no media files in {output_destination}') # Only these sections can handling failed downloads # so make sure everything else gets through without the check for failed if section_name not in ['CouchPotato', 'Radarr', 'SickBeard', 'SiCKRAGE', 'NzbDrone', 'Sonarr', 'Watcher3']: status = 0 - logger.info(f'Calling {section_name}:{usercat} to post-process:{input_name}') + log.info(f'Calling {section_name}:{usercat} to post-process:{input_name}') if nzb2media.TORRENT_CHMOD_DIRECTORY: nzb2media.rchmod(output_destination, nzb2media.TORRENT_CHMOD_DIRECTORY) @@ -245,12 +249,12 @@ def process_torrent(input_directory, input_name, input_category, input_hash, inp if result.status_code != 0: if not nzb2media.TORRENT_RESUME_ON_FAILURE: - logger.error( + log.error( 'A problem was reported in the autoProcess* script. ' 'Torrent won\'t resume seeding (settings)', ) elif client_agent != 'manual': - logger.error( + log.error( 'A problem was reported in the autoProcess* script. ' 'If torrent was paused we will resume seeding', ) @@ -263,10 +267,10 @@ def process_torrent(input_directory, input_name, input_category, input_hash, inp # remove torrent if nzb2media.USE_LINK == 'move-sym' and not nzb2media.DELETE_ORIGINAL == 1: - logger.debug(f'Checking for sym-links to re-direct in: {input_directory}') + log.debug(f'Checking for sym-links to re-direct in: {input_directory}') for dirpath, _, files in os.walk(input_directory): for file in files: - logger.debug(f'Checking symlink: {os.path.join(dirpath, file)}') + log.debug(f'Checking symlink: {os.path.join(dirpath, file)}') replace_links(os.path.join(dirpath, file)) nzb2media.remove_torrent(client_agent, input_hash, input_id, input_name) @@ -285,12 +289,12 @@ def main(args): # clientAgent for Torrents client_agent = nzb2media.TORRENT_CLIENT_AGENT - logger.info('#########################################################') - logger.info(f'## ..::[{os.path.basename(__file__)}]::.. ##') - logger.info('#########################################################') + log.info('#########################################################') + log.info(f'## ..::[{os.path.basename(__file__)}]::.. ##') + log.info('#########################################################') # debug command line options - logger.debug(f'Options passed into TorrentToMedia: {args}') + log.debug(f'Options passed into TorrentToMedia: {args}') # Post-Processing Result result = ProcessResult( @@ -301,33 +305,33 @@ def main(args): try: input_directory, input_name, input_category, input_hash, input_id = nzb2media.parse_args(client_agent, args) except Exception: - logger.error('There was a problem loading variables') + log.error('There was a problem loading variables') return -1 if input_directory and input_name and input_hash and input_id: result = process_torrent(input_directory, input_name, input_category, input_hash, input_id, client_agent) elif nzb2media.TORRENT_NO_MANUAL: - logger.warning('Invalid number of arguments received from client, and no_manual set') + log.warning('Invalid number of arguments received from client, and no_manual set') else: # Perform Manual Post-Processing - logger.warning('Invalid number of arguments received from client, Switching to manual run mode ...') + log.warning('Invalid number of arguments received from client, Switching to manual run mode ...') for section, subsections in nzb2media.SECTIONS.items(): for subsection in subsections: if not nzb2media.CFG[section][subsection].isenabled(): continue for dir_name in nzb2media.get_dirs(section, subsection, link='hard'): - logger.info(f'Starting manual run for {section}:{subsection} - Folder:{dir_name}') + log.info(f'Starting manual run for {section}:{subsection} - Folder:{dir_name}') - logger.info(f'Checking database for download info for {os.path.basename(dir_name)} ...') + log.info(f'Checking database for download info for {os.path.basename(dir_name)} ...') nzb2media.DOWNLOAD_INFO = nzb2media.get_download_info(os.path.basename(dir_name), 0) if nzb2media.DOWNLOAD_INFO: client_agent = nzb2media.DOWNLOAD_INFO[0]['client_agent'] or 'manual' input_hash = nzb2media.DOWNLOAD_INFO[0]['input_hash'] or '' input_id = nzb2media.DOWNLOAD_INFO[0]['input_id'] or '' - logger.info(f'Found download info for {os.path.basename(dir_name)}, setting variables now ...') + log.info(f'Found download info for {os.path.basename(dir_name)}, setting variables now ...') else: - logger.info(f'Unable to locate download info for {os.path.basename(dir_name)}, continuing to try and process this release ...') + log.info(f'Unable to locate download info for {os.path.basename(dir_name)}, continuing to try and process this release ...') client_agent = 'manual' input_hash = '' input_id = '' @@ -342,13 +346,13 @@ def main(args): client_agent, ) if results.status_code != 0: - logger.error(f'A problem was reported when trying to perform a manual run for {section}:{subsection}.') + log.error(f'A problem was reported when trying to perform a manual run for {section}:{subsection}.') result = results if result.status_code == 0: - logger.info(f'The {args[0]} script completed successfully.') + log.info(f'The {args[0]} script completed successfully.') else: - logger.error(f'A problem was reported in the {args[0]} script.') + log.error(f'A problem was reported in the {args[0]} script.') del nzb2media.MYAPP return result.status_code diff --git a/nzb2media/__init__.py b/nzb2media/__init__.py index 2c346956..feaaf24c 100644 --- a/nzb2media/__init__.py +++ b/nzb2media/__init__.py @@ -2,6 +2,7 @@ from __future__ import annotations import itertools import locale +import logging import os import pathlib import platform @@ -11,6 +12,9 @@ import sys import time import typing +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + try: import win32event except ImportError: @@ -417,9 +421,7 @@ def configure_migration(): # run migrate to convert old cfg to new style cfg plus fix any cfg missing values/options. if not config.migrate(): - logger.error( - f'Unable to migrate config file {CONFIG_FILE}, exiting ...', - ) + log.error(f'Unable to migrate config file {CONFIG_FILE}, exiting ...') if 'NZBOP_SCRIPTDIR' in os.environ: pass # We will try and read config from Environment. else: @@ -430,7 +432,7 @@ def configure_migration(): CFG = config.addnzbget() else: # load newly migrated config - logger.info(f'Loading config from [{CONFIG_FILE}]') + log.info(f'Loading config from [{CONFIG_FILE}]') CFG = config() @@ -448,7 +450,7 @@ def configure_logging_part_2(): if LOG_ENV: for item in os.environ: - logger.info(f'{item}: {os.environ[item]}', 'ENVIRONMENT') + log.info(f'{item}: {os.environ[item]}') def configure_general(): @@ -493,7 +495,7 @@ def configure_updates(): # Check for updates via GitHUB if version_checker.check_for_new_version() and AUTO_UPDATE: - logger.info('Auto-Updating nzbToMedia, Please wait ...') + log.info('Auto-Updating nzbToMedia, Please wait ...') if version_checker.update(): # restart nzbToMedia try: @@ -502,14 +504,10 @@ def configure_updates(): pass restart() else: - logger.error( - 'Update failed, not restarting. Check your log for more information.', - ) + log.error('Update failed, not restarting. Check your log for more information.') # Set Current Version - logger.info( - f'nzbToMedia Version:{NZBTOMEDIA_VERSION} Branch:{GIT_BRANCH} ({platform.system()} {platform.release()})', - ) + log.info(f'nzbToMedia Version:{NZBTOMEDIA_VERSION} Branch:{GIT_BRANCH} ({platform.system()} {platform.release()})') def configure_wake_on_lan(): @@ -1424,22 +1422,14 @@ def configure_utility_locations(): if not (os.path.isfile(FFMPEG)): # problem FFMPEG = None - logger.warning( - 'Failed to locate ffmpeg.exe. Transcoding disabled!', - ) - logger.warning( - 'Install ffmpeg with x264 support to enable this feature ...', - ) + log.warning('Failed to locate ffmpeg.exe. Transcoding disabled!') + log.warning('Install ffmpeg with x264 support to enable this feature ...') if not (os.path.isfile(FFPROBE)): FFPROBE = None if CHECK_MEDIA: - logger.warning( - 'Failed to locate ffprobe.exe. Video corruption detection disabled!', - ) - logger.warning( - 'Install ffmpeg with x264 support to enable this feature ...', - ) + log.warning('Failed to locate ffprobe.exe. Video corruption detection disabled!') + log.warning('Install ffmpeg with x264 support to enable this feature ...') else: if SYS_PATH: @@ -1475,9 +1465,7 @@ def configure_utility_locations(): pass if not SEVENZIP: SEVENZIP = None - logger.warning( - 'Failed to locate 7zip. Transcoding of disk images and extraction of .7z files will not be possible!', - ) + log.warning('Failed to locate 7zip. Transcoding of disk images and extraction of .7z files will not be possible!') try: PAR2CMD = ( subprocess.Popen(['which', 'par2'], stdout=subprocess.PIPE) @@ -1489,9 +1477,7 @@ def configure_utility_locations(): pass if not PAR2CMD: PAR2CMD = None - logger.warning( - 'Failed to locate par2. Repair and rename using par files will not be possible!', - ) + log.warning('Failed to locate par2. Repair and rename using par files will not be possible!') if os.path.isfile(os.path.join(FFMPEG_PATH, 'ffmpeg')) or os.access( os.path.join(FFMPEG_PATH, 'ffmpeg'), os.X_OK, @@ -1528,10 +1514,8 @@ def configure_utility_locations(): pass if not FFMPEG: FFMPEG = None - logger.warning('Failed to locate ffmpeg. Transcoding disabled!') - logger.warning( - 'Install ffmpeg with x264 support to enable this feature ...', - ) + log.warning('Failed to locate ffmpeg. Transcoding disabled!') + log.warning('Install ffmpeg with x264 support to enable this feature ...') if os.path.isfile(os.path.join(FFMPEG_PATH, 'ffprobe')) or os.access( os.path.join(FFMPEG_PATH, 'ffprobe'), @@ -1570,14 +1554,8 @@ def configure_utility_locations(): if not FFPROBE: FFPROBE = None if CHECK_MEDIA: - logger.warning( - 'Failed to locate ffprobe. Video corruption detection disabled!', - ) - logger.warning( - 'Install ffmpeg with x264 support to enable this feature ...', - ) - - + log.warning('Failed to locate ffprobe. Video corruption detection disabled!') + log.warning('Install ffmpeg with x264 support to enable this feature ...') def initialize(section=None): @@ -1590,9 +1568,6 @@ def initialize(section=None): configure_process() configure_locale() - # init logging - logger.ntm_log_instance.init_logging() - configure_migration() configure_logging_part_2() diff --git a/nzb2media/auto_process/books.py b/nzb2media/auto_process/books.py index 17d47b07..f7b573b6 100644 --- a/nzb2media/auto_process/books.py +++ b/nzb2media/auto_process/books.py @@ -1,5 +1,7 @@ from __future__ import annotations +import logging + import requests import nzb2media @@ -9,6 +11,9 @@ from nzb2media.utils.encoding import convert_to_ascii from nzb2media.utils.network import server_responding from nzb2media.utils.paths import remote_dir +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def process( *, @@ -44,7 +49,7 @@ def process( # Begin processing url = nzb2media.utils.common.create_url(scheme, host, port, web_root) if not server_responding(url): - logger.error('Server did not respond. Exiting', section) + log.error('Server did not respond. Exiting') return ProcessResult.failure( f'{section}: Failed to post-process - {section} did not respond.', ) @@ -57,41 +62,39 @@ def process( 'dir': remote_dir(dir_name) if remote_path else dir_name, } - logger.debug(f'Opening URL: {url} with params: {params}', section) + log.debug(f'Opening URL: {url} with params: {params}') try: - r = requests.get(url, params=params, verify=False, timeout=(30, 300)) + response = requests.get(url, params=params, verify=False, timeout=(30, 300)) except requests.ConnectionError: - logger.error('Unable to open URL') + log.error('Unable to open URL') return ProcessResult.failure( f'{section}: Failed to post-process - Unable to connect to ' f'{section}', ) - logger.postprocess(f'{r.text}', section) + log.debug(response.text) - if r.status_code not in [ + if response.status_code not in [ requests.codes.ok, requests.codes.created, requests.codes.accepted, ]: - logger.error(f'Server returned status {r.status_code}', section) + log.error(f'Server returned status {response.status_code}') return ProcessResult.failure( f'{section}: Failed to post-process - Server returned status ' - f'{r.status_code}', + f'{response.status_code}', ) - elif r.text == 'OK': - logger.postprocess( + elif response.text == 'OK': + log.debug( f'SUCCESS: ForceProcess for {dir_name} has been started in LazyLibrarian', - section, ) return ProcessResult.success( f'{section}: Successfully post-processed {input_name}', ) else: - logger.error( + log.error( f'FAILED: ForceProcess of {dir_name} has Failed in LazyLibrarian', - section, ) return ProcessResult.failure( f'{section}: Failed to post-process - Returned log from {section} ' diff --git a/nzb2media/auto_process/comics.py b/nzb2media/auto_process/comics.py index 109e2b3e..2a9298a2 100644 --- a/nzb2media/auto_process/comics.py +++ b/nzb2media/auto_process/comics.py @@ -1,5 +1,6 @@ from __future__ import annotations +import logging import os import requests @@ -11,6 +12,9 @@ from nzb2media.utils.encoding import convert_to_ascii from nzb2media.utils.network import server_responding from nzb2media.utils.paths import remote_dir +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def process( *, @@ -48,7 +52,7 @@ def process( # Begin processing url = nzb2media.utils.common.create_url(scheme, host, port, web_root) if not server_responding(url): - logger.error('Server did not respond. Exiting', section) + log.error('Server did not respond. Exiting') return ProcessResult.failure( f'{section}: Failed to post-process - {section} did not respond.', ) @@ -72,13 +76,13 @@ def process( success = False - logger.debug(f'Opening URL: {url}', section) + log.debug(f'Opening URL: {url}') try: r = requests.post( url, params=params, stream=True, verify=False, timeout=(30, 300), ) except requests.ConnectionError: - logger.error('Unable to open URL', section) + log.error('Unable to open URL') return ProcessResult.failure( f'{section}: Failed to post-process - Unable to connect to ' f'{section}', @@ -88,7 +92,7 @@ def process( requests.codes.created, requests.codes.accepted, ]: - logger.error(f'Server returned status {r.status_code}', section) + log.error(f'Server returned status {r.status_code}') return ProcessResult.failure( f'{section}: Failed to post-process - Server returned status ' f'{r.status_code}', @@ -96,21 +100,19 @@ def process( for line in r.text.split('\n'): if line: - logger.postprocess(line, section) + log.debug(line) if 'Post Processing SUCCESSFUL' in line: success = True if success: - logger.postprocess( - 'SUCCESS: This issue has been processed successfully', section, - ) + log.debug('SUCCESS: This issue has been processed successfully') return ProcessResult.success( f'{section}: Successfully post-processed {input_name}', ) else: - logger.warning( - 'The issue does not appear to have successfully processed. Please check your Logs', - section, + log.warning( + 'The issue does not appear to have successfully processed. ' + 'Please check your Logs', ) return ProcessResult.failure( f'{section}: Failed to post-process - Returned log from ' diff --git a/nzb2media/auto_process/common.py b/nzb2media/auto_process/common.py index 5ed7c8d4..ae57ad90 100644 --- a/nzb2media/auto_process/common.py +++ b/nzb2media/auto_process/common.py @@ -1,9 +1,13 @@ from __future__ import annotations +import logging import typing import requests +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + class ProcessResult(typing.NamedTuple): status_code: int @@ -39,23 +43,22 @@ def command_complete(url, params, headers, section): timeout=(30, 60), ) except requests.ConnectionError: - logger.error(f'Unable to open URL: {url}', section) + log.error(f'Unable to open URL: {url}') return None if r.status_code not in [ requests.codes.ok, requests.codes.created, requests.codes.accepted, ]: - logger.error(f'Server returned status {r.status_code}', section) + log.error(f'Server returned status {r.status_code}') return None else: try: return r.json()['status'] except (ValueError, KeyError): - # ValueError catches simplejson's JSONDecodeError and json's ValueError - logger.error( - f'{section} did not return expected json data.', section, - ) + # ValueError catches simplejson's JSONDecodeError and + # json's ValueError + log.error(f'{section} did not return expected json data.') return None @@ -70,14 +73,14 @@ def completed_download_handling(url2, headers, section='MAIN'): timeout=(30, 60), ) except requests.ConnectionError: - logger.error(f'Unable to open URL: {url2}', section) + log.error(f'Unable to open URL: {url2}') return False if r.status_code not in [ requests.codes.ok, requests.codes.created, requests.codes.accepted, ]: - logger.error(f'Server returned status {r.status_code}', section) + log.error(f'Server returned status {r.status_code}') return False else: try: diff --git a/nzb2media/auto_process/games.py b/nzb2media/auto_process/games.py index 0bb427b4..332a24cd 100644 --- a/nzb2media/auto_process/games.py +++ b/nzb2media/auto_process/games.py @@ -1,5 +1,6 @@ from __future__ import annotations +import logging import os import shutil @@ -11,6 +12,9 @@ from nzb2media.utils.common import flatten from nzb2media.utils.encoding import convert_to_ascii from nzb2media.utils.network import server_responding +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def process( *, @@ -46,7 +50,7 @@ def process( # Begin processing url = nzb2media.utils.common.create_url(scheme, host, port, web_root) if not server_responding(url): - logger.error('Server did not respond. Exiting', section) + log.error('Server did not respond. Exiting') return ProcessResult.failure( f'{section}: Failed to post-process - {section} did not respond.', ) @@ -66,36 +70,30 @@ def process( 'status': download_status, } - logger.debug(f'Opening URL: {url}', section) + log.debug(f'Opening URL: {url}') try: r = requests.get(url, params=params, verify=False, timeout=(30, 300)) except requests.ConnectionError: - logger.error('Unable to open URL') + log.error('Unable to open URL') return ProcessResult.failure( f'{section}: Failed to post-process - Unable to connect to ' f'{section}', ) result = r.json() - logger.postprocess(result, section) + log.debug(result) if library: - logger.postprocess(f'moving files to library: {library}', section) + log.debug(f'moving files to library: {library}') try: shutil.move(dir_name, os.path.join(library, input_name)) except Exception: - logger.error( - f'Unable to move {dir_name} to {os.path.join(library, input_name)}', - section, - ) + log.error(f'Unable to move {dir_name} to {os.path.join(library, input_name)}') return ProcessResult.failure( f'{section}: Failed to post-process - Unable to move files', ) else: - logger.error( - 'No library specified to move files to. Please edit your configuration.', - section, - ) + log.error('No library specified to move files to. Please edit your configuration.') return ProcessResult.failure( f'{section}: Failed to post-process - No library defined in ' f'{section}', @@ -106,24 +104,18 @@ def process( requests.codes.created, requests.codes.accepted, ]: - logger.error(f'Server returned status {r.status_code}', section) + log.error(f'Server returned status {r.status_code}') return ProcessResult.failure( f'{section}: Failed to post-process - Server returned status ' f'{r.status_code}', ) elif result['success']: - logger.postprocess( - f'SUCCESS: Status for {gamez_id} has been set to {download_status} in Gamez', - section, - ) + log.debug(f'SUCCESS: Status for {gamez_id} has been set to {download_status} in Gamez') return ProcessResult.success( f'{section}: Successfully post-processed {input_name}', ) else: - logger.error( - f'FAILED: Status for {gamez_id} has NOT been updated in Gamez', - section, - ) + log.error(f'FAILED: Status for {gamez_id} has NOT been updated in Gamez') return ProcessResult.failure( f'{section}: Failed to post-process - Returned log from {section} ' f'was not as expected.', diff --git a/nzb2media/auto_process/movies.py b/nzb2media/auto_process/movies.py index 83381203..12028a18 100644 --- a/nzb2media/auto_process/movies.py +++ b/nzb2media/auto_process/movies.py @@ -1,6 +1,7 @@ from __future__ import annotations import json +import logging import os import time @@ -24,6 +25,9 @@ from nzb2media.utils.nzb import report_nzb from nzb2media.utils.paths import remote_dir from nzb2media.utils.paths import remove_dir +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def process( *, @@ -86,9 +90,7 @@ def process( route = web_root base_url = nzb2media.utils.common.create_url(scheme, host, port, route) if not apikey: - logger.info( - 'No CouchPotato or Radarr apikey entered. Performing transcoder functions only', - ) + log.info('No CouchPotato or Radarr apikey entered. Performing transcoder functions only') release = None elif server_responding(base_url): if section == 'CouchPotato': @@ -96,7 +98,7 @@ def process( else: release = None else: - logger.error('Server did not respond. Exiting', section) + log.error('Server did not respond. Exiting') return ProcessResult.failure( f'{section}: Failed to post-process - {section} did not respond.', ) @@ -140,9 +142,7 @@ def process( ) and extract ): - logger.debug( - f'Checking for archives to extract in directory: {dir_name}', - ) + log.debug(f'Checking for archives to extract in directory: {dir_name}') nzb2media.extract_files(dir_name) input_name, dir_name = convert_to_ascii(input_name, dir_name) @@ -164,16 +164,10 @@ def process( rename_subs(dir_name) if num_files and valid_files == num_files: if status: - logger.info( - f'Status shown as failed from Downloader, but {good_files} valid video files found. Setting as success.', - section, - ) + log.info(f'Status shown as failed from Downloader, but {good_files} valid video files found. Setting as success.') status = 0 elif num_files and valid_files < num_files: - logger.info( - 'Status shown as success from Downloader, but corrupt video files found. Setting as failed.', - section, - ) + log.info('Status shown as success from Downloader, but corrupt video files found. Setting as failed.') status = 1 if ( 'NZBOP_VERSION' in os.environ @@ -181,33 +175,21 @@ def process( ): print('[NZB] MARK=BAD') if good_files == num_files: - logger.debug( - f'Video marked as failed due to missing required language: {nzb2media.REQUIRE_LAN}', - section, - ) + log.debug(f'Video marked as failed due to missing required language: {nzb2media.REQUIRE_LAN}') else: - logger.debug( - 'Video marked as failed due to missing playable audio or video', - section, - ) + log.debug('Video marked as failed due to missing playable audio or video') if ( good_files < num_files and failure_link ): # only report corrupt files failure_link += '&corrupt=true' elif client_agent == 'manual': - logger.warning( - f'No media files found in directory {dir_name} to manually process.', - section, - ) + log.warning(f'No media files found in directory {dir_name} to manually process.') return ProcessResult( message='', status_code=0, # Success (as far as this script is concerned) ) else: - logger.warning( - f'No media files found in directory {dir_name}. Processing this as a failed download', - section, - ) + log.warning(f'No media files found in directory {dir_name}. Processing this as a failed download') status = 1 if ( 'NZBOP_VERSION' in os.environ @@ -219,25 +201,15 @@ def process( if nzb2media.TRANSCODE == 1: result, new_dir_name = transcoder.transcode_directory(dir_name) if result == 0: - logger.debug( - f'Transcoding succeeded for files in {dir_name}', section, - ) + log.debug(f'Transcoding succeeded for files in {dir_name}') dir_name = new_dir_name - logger.debug( - f'Config setting \'chmodDirectory\' currently set to {oct(chmod_directory)}', - section, - ) + log.debug(f'Config setting \'chmodDirectory\' currently set to {oct(chmod_directory)}') if chmod_directory: - logger.info( - f'Attempting to set the octal permission of \'{oct(chmod_directory)}\' on directory \'{dir_name}\'', - section, - ) + log.info(f'Attempting to set the octal permission of \'{oct(chmod_directory)}\' on directory \'{dir_name}\'') nzb2media.rchmod(dir_name, chmod_directory) else: - logger.error( - f'Transcoding failed for files in {dir_name}', section, - ) + log.error(f'Transcoding failed for files in {dir_name}') return ProcessResult( message=f'{section}: Failed to post-process - Transcoding failed', status_code=1, @@ -252,13 +224,11 @@ def process( client_agent in [nzb2media.TORRENT_CLIENT_AGENT, 'manual'] and nzb2media.USE_LINK == 'move-sym' ): - logger.debug(f'Renaming: {video} to: {video2}') + log.debug(f'Renaming: {video} to: {video2}') os.rename(video, video2) if not apikey: # If only using Transcoder functions, exit here. - logger.info( - 'No CouchPotato or Radarr or Watcher3 apikey entered. Processing completed.', - ) + log.info('No CouchPotato or Radarr or Watcher3 apikey entered. Processing completed.') return ProcessResult( message=f'{section}: Successfully post-processed {input_name}', status_code=0, @@ -280,10 +250,8 @@ def process( command = 'renamer.scan' url = f'{base_url}{command}' - logger.debug(f'Opening URL: {url} with PARAMS: {params}', section) - logger.postprocess( - f'Starting {method} scan for {input_name}', section, - ) + log.debug(f'Opening URL: {url} with PARAMS: {params}') + log.debug(f'Starting {method} scan for {input_name}') if section == 'Radarr': payload = { @@ -294,12 +262,8 @@ def process( } if not download_id: payload.pop('downloadClientId') - logger.debug( - f'Opening URL: {base_url} with PARAMS: {payload}', section, - ) - logger.postprocess( - f'Starting DownloadedMoviesScan scan for {input_name}', section, - ) + log.debug(f'Opening URL: {base_url} with PARAMS: {payload}') + log.debug(f'Starting DownloadedMoviesScan scan for {input_name}') if section == 'Watcher3': if input_name and os.path.isfile( @@ -316,24 +280,20 @@ def process( } if not download_id: payload.pop('guid') - logger.debug( - f'Opening URL: {base_url} with PARAMS: {payload}', section, - ) - logger.postprocess( - f'Starting postprocessing scan for {input_name}', section, - ) + log.debug(f'Opening URL: {base_url} with PARAMS: {payload}') + log.debug(f'Starting postprocessing scan for {input_name}') try: if section == 'CouchPotato': - r = requests.get( + response = requests.get( url, params=params, verify=False, timeout=(30, 1800), ) elif section == 'Watcher3': - r = requests.post( + response = requests.post( base_url, data=payload, verify=False, timeout=(30, 1800), ) else: - r = requests.post( + response = requests.post( base_url, data=json.dumps(payload), headers=headers, @@ -342,30 +302,25 @@ def process( timeout=(30, 1800), ) except requests.ConnectionError: - logger.error('Unable to open URL', section) + log.error('Unable to open URL') return ProcessResult( - message='{0}: Failed to post-process - Unable to connect to {0}'.format( - section, - ), + message=f'{section}: Failed to post-process - Unable to connect to {section}', status_code=1, ) - result = r.json() - if r.status_code not in [ + result = response.json() + if response.status_code not in [ requests.codes.ok, requests.codes.created, requests.codes.accepted, ]: - logger.error(f'Server returned status {r.status_code}', section) + log.error(f'Server returned status {response.status_code}') return ProcessResult( - message=f'{section}: Failed to post-process - Server returned status {r.status_code}', + message=f'{section}: Failed to post-process - Server returned status {response.status_code}', status_code=1, ) elif section == 'CouchPotato' and result['success']: - logger.postprocess( - f'SUCCESS: Finished {method} scan for folder {dir_name}', - section, - ) + log.debug(f'SUCCESS: Finished {method} scan for folder {dir_name}') if method == 'manage': return ProcessResult( message=f'{section}: Successfully post-processed {input_name}', @@ -374,13 +329,13 @@ def process( elif section == 'Radarr': try: scan_id = int(result['id']) - logger.debug(f'Scan started with id: {scan_id}', section) - except Exception as e: - logger.warning(f'No scan id was returned due to: {e}', section) + log.debug(f'Scan started with id: {scan_id}') + except Exception as error: + log.warning(f'No scan id was returned due to: {error}') scan_id = None elif section == 'Watcher3' and result['status'] == 'finished': update_movie_status = result['tasks']['update_movie_status'] - logger.postprocess(f'Watcher3 updated status to {section}') + log.debug(f'Watcher3 updated status to {section}') if update_movie_status == 'Finished': return ProcessResult( message=f'{section}: Successfully post-processed {input_name}', @@ -392,38 +347,26 @@ def process( status_code=1, ) else: - logger.error( - f'FAILED: {method} scan was unable to finish for folder {dir_name}. exiting!', - section, - ) + log.error(f'FAILED: {method} scan was unable to finish for folder {dir_name}. exiting!') return ProcessResult( message=f'{section}: Failed to post-process - Server did not return success', status_code=1, ) else: nzb2media.FAILED = True - logger.postprocess( - f'FAILED DOWNLOAD DETECTED FOR {input_name}', section, - ) + log.debug(f'FAILED DOWNLOAD DETECTED FOR {input_name}') if failure_link: report_nzb(failure_link, client_agent) if section == 'Radarr': - logger.postprocess( - f'SUCCESS: Sending failed download to {section} for CDH processing', - section, - ) + log.debug(f'SUCCESS: Sending failed download to {section} for CDH processing') return ProcessResult( - message='{0}: Sending failed download back to {0}'.format( - section, - ), - status_code=1, # Return as failed to flag this in the downloader. + message=f'{section}: Sending failed download back to {section}', + status_code=1, + # Return as failed to flag this in the downloader. ) # Return failed flag, but log the event as successful. elif section == 'Watcher3': - logger.postprocess( - f'Sending failed download to {section} for CDH processing', - section, - ) + log.debug(f'Sending failed download to {section} for CDH processing') path = remote_dir(dir_name) if remote_path else dir_name if input_name and os.path.isfile( os.path.join(dir_name, input_name), @@ -435,17 +378,16 @@ def process( 'guid': download_id, 'mode': 'failed', } - r = requests.post( + response = requests.post( base_url, data=payload, verify=False, timeout=(30, 1800), ) - result = r.json() - logger.postprocess(f'Watcher3 response: {result}') + result = response.json() + log.debug(f'Watcher3 response: {result}') if result['status'] == 'finished': return ProcessResult( - message='{0}: Sending failed download back to {0}'.format( - section, - ), - status_code=1, # Return as failed to flag this in the downloader. + message=f'{section}: Sending failed download back to {section}', + status_code=1, + # Return as failed to flag this in the downloader. ) # Return failed flag, but log the event as successful. if ( @@ -453,117 +395,93 @@ def process( and os.path.isdir(dir_name) and not os.path.dirname(dir_name) == dir_name ): - logger.postprocess( - f'Deleting failed files and folder {dir_name}', section, - ) + log.debug(f'Deleting failed files and folder {dir_name}') remove_dir(dir_name) if not release_id and not media_id: - logger.error( - f'Could not find a downloaded movie in the database matching {input_name}, exiting!', - section, - ) + log.error(f'Could not find a downloaded movie in the database matching {input_name}, exiting!') return ProcessResult( - message='{0}: Failed to post-process - Failed download not found in {0}'.format( - section, - ), + message='{0}: Failed to post-process - Failed download not found in {0}'.format(section), status_code=1, ) if release_id: - logger.postprocess( - f'Setting failed release {input_name} to ignored ...', section, - ) + log.debug(f'Setting failed release {input_name} to ignored ...') url = f'{base_url}release.ignore' params = {'id': release_id} - logger.debug(f'Opening URL: {url} with PARAMS: {params}', section) + log.debug(f'Opening URL: {url} with PARAMS: {params}') try: - r = requests.get( - url, params=params, verify=False, timeout=(30, 120), + response = requests.get( + url, params=params, verify=False, + timeout=(30, 120), ) except requests.ConnectionError: - logger.error(f'Unable to open URL {url}', section) + log.error(f'Unable to open URL {url}') return ProcessResult( - message='{0}: Failed to post-process - Unable to connect to {0}'.format( - section, - ), + message='{0}: Failed to post-process - Unable to connect to {0}'.format(section), status_code=1, ) - result = r.json() - if r.status_code not in [ + result = response.json() + if response.status_code not in [ requests.codes.ok, requests.codes.created, requests.codes.accepted, ]: - logger.error( - f'Server returned status {r.status_code}', section, - ) + log.error(f'Server returned status {response.status_code}') return ProcessResult( status_code=1, - message=f'{section}: Failed to post-process - Server returned status {r.status_code}', + message=f'{section}: Failed to post-process - Server returned status {response.status_code}', ) elif result['success']: - logger.postprocess( - f'SUCCESS: {input_name} has been set to ignored ...', - section, - ) + log.debug(f'SUCCESS: {input_name} has been set to ignored ...') else: - logger.warning( - f'FAILED: Unable to set {input_name} to ignored!', section, - ) + log.warning(f'FAILED: Unable to set {input_name} to ignored!') return ProcessResult( message=f'{section}: Failed to post-process - Unable to set {input_name} to ignored', status_code=1, ) - logger.postprocess( - 'Trying to snatch the next highest ranked release.', section, - ) + log.debug('Trying to snatch the next highest ranked release.') url = f'{base_url}movie.searcher.try_next' - logger.debug(f'Opening URL: {url}', section) + log.debug(f'Opening URL: {url}') try: - r = requests.get( + response = requests.get( url, params={'media_id': media_id}, verify=False, timeout=(30, 600), ) except requests.ConnectionError: - logger.error(f'Unable to open URL {url}', section) + log.error(f'Unable to open URL {url}') return ProcessResult.failure( f'{section}: Failed to post-process - Unable to connect to ' f'{section}', ) - result = r.json() - if r.status_code not in [ + result = response.json() + if response.status_code not in [ requests.codes.ok, requests.codes.created, requests.codes.accepted, ]: - logger.error(f'Server returned status {r.status_code}', section) + log.error(f'Server returned status {response.status_code}') return ProcessResult.failure( f'{section}: Failed to post-process - Server returned status ' - f'{r.status_code}', + f'{response.status_code}', ) elif result['success']: - logger.postprocess( - 'SUCCESS: Snatched the next highest release ...', section, - ) + log.debug('SUCCESS: Snatched the next highest release ...') return ProcessResult.success( f'{section}: Successfully snatched next highest release', ) else: - logger.postprocess( - 'SUCCESS: Unable to find a new release to snatch now. CP will keep searching!', - section, - ) + log.debug('SUCCESS: Unable to find a new release to snatch now. CP will keep searching!') return ProcessResult.success( f'{section}: No new release found now. ' f'{section} will keep searching', @@ -584,9 +502,7 @@ def process( # we will now check to see if CPS has finished renaming before returning to TorrentToMedia and unpausing. timeout = time.time() + 60 * wait_for while time.time() < timeout: # only wait 2 (default) minutes, then return. - logger.postprocess( - 'Checking for status change, please stand by ...', section, - ) + log.debug('Checking for status change, please stand by ...') if section == 'CouchPotato': release = get_release(base_url, imdbid, download_id, release_id) scan_id = None @@ -600,19 +516,13 @@ def process( release_status_old is None ): # we didn't have a release before, but now we do. title = release[release_id]['title'] - logger.postprocess( - f'SUCCESS: Movie {title} has now been added to CouchPotato with release status of [{str(release_status_new).upper()}]', - section, - ) + log.debug(f'SUCCESS: Movie {title} has now been added to CouchPotato with release status of [{str(release_status_new).upper()}]') return ProcessResult.success( f'{section}: Successfully post-processed {input_name}', ) if release_status_new != release_status_old: - logger.postprocess( - f'SUCCESS: Release {release_id} has now been marked with a status of [{str(release_status_new).upper()}]', - section, - ) + log.debug(f'SUCCESS: Release {release_id} has now been marked with a status of [{str(release_status_new).upper()}]') return ProcessResult.success( f'{section}: Successfully post-processed {input_name}', ) @@ -622,33 +532,21 @@ def process( url = f'{base_url}/{scan_id}' command_status = command_complete(url, params, headers, section) if command_status: - logger.debug( - f'The Scan command return status: {command_status}', - section, - ) + log.debug(f'The Scan command return status: {command_status}') if command_status in ['completed']: - logger.debug( - 'The Scan command has completed successfully. Renaming was successful.', - section, - ) + log.debug('The Scan command has completed successfully. Renaming was successful.') return ProcessResult.success( f'{section}: Successfully post-processed {input_name}', ) elif command_status in ['failed']: - logger.debug( - 'The Scan command has failed. Renaming was not successful.', - section, - ) + log.debug('The Scan command has failed. Renaming was not successful.') # return ProcessResult( # message='{0}: Failed to post-process {1}'.format(section, input_name), # status_code=1, # ) if not os.path.isdir(dir_name): - logger.postprocess( - f'SUCCESS: Input Directory [{dir_name}] has been processed and removed', - section, - ) + log.debug(f'SUCCESS: Input Directory [{dir_name}] has been processed and removed') return ProcessResult.success( f'{section}: Successfully post-processed {input_name}', ) @@ -656,10 +554,7 @@ def process( elif not list_media_files( dir_name, media=True, audio=False, meta=False, archives=True, ): - logger.postprocess( - f'SUCCESS: Input Directory [{dir_name}] has no remaining media files. This has been fully processed.', - section, - ) + log.debug(f'SUCCESS: Input Directory [{dir_name}] has no remaining media files. This has been fully processed.') return ProcessResult.success( f'{section}: Successfully post-processed {input_name}', ) @@ -671,19 +566,12 @@ def process( if section == 'Radarr' and completed_download_handling( url2, headers, section=section, ): - logger.debug( - f'The Scan command did not return status completed, but complete Download Handling is enabled. Passing back to {section}.', - section, - ) + log.debug(f'The Scan command did not return status completed, but complete Download Handling is enabled. Passing back to {section}.') return ProcessResult.success( f'{section}: Complete DownLoad Handling is enabled. Passing back ' f'to {section}', ) - logger.warning( - f'{input_name} does not appear to have changed status after {wait_for} minutes, Please check your logs.', - section, - ) - + log.warning(f'{input_name} does not appear to have changed status after {wait_for} minutes, Please check your logs.') return ProcessResult.failure( f'{section}: Failed to post-process - No change in status', ) @@ -702,33 +590,33 @@ def get_release(base_url, imdb_id=None, download_id=None, release_id=None): params['id'] = release_id or imdb_id if not (release_id or imdb_id or download_id): - logger.debug('No information available to filter CP results') + log.debug('No information available to filter CP results') return results url = f'{base_url}{cmd}' - logger.debug(f'Opening URL: {url} with PARAMS: {params}') + log.debug(f'Opening URL: {url} with PARAMS: {params}') try: r = requests.get(url, params=params, verify=False, timeout=(30, 60)) except requests.ConnectionError: - logger.error(f'Unable to open URL {url}') + log.error(f'Unable to open URL {url}') return results try: result = r.json() except ValueError: # ValueError catches simplejson's JSONDecodeError and json's ValueError - logger.error('CouchPotato returned the following non-json data') + log.error('CouchPotato returned the following non-json data') for line in r.iter_lines(): - logger.error(line) + log.error(line) return results if not result['success']: if 'error' in result: - logger.error(result['error']) + log.error(result['error']) else: id_param = params['id'] - logger.error(f'no media found for id {id_param}') + log.error(f'no media found for id {id_param}') return results # Gather release info and return it back, no need to narrow results diff --git a/nzb2media/auto_process/music.py b/nzb2media/auto_process/music.py index 6f5e2ee4..2e31b535 100644 --- a/nzb2media/auto_process/music.py +++ b/nzb2media/auto_process/music.py @@ -1,6 +1,7 @@ from __future__ import annotations import json +import logging import os import time @@ -17,6 +18,9 @@ from nzb2media.utils.network import server_responding from nzb2media.utils.paths import remote_dir from nzb2media.utils.paths import remove_dir +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def process( *, @@ -59,7 +63,7 @@ def process( route = f'{web_root}/api/v1' if section == 'Lidarr' else f'{web_root}/api' url = nzb2media.utils.common.create_url(scheme, host, port, route) if not server_responding(url): - logger.error('Server did not respond. Exiting', section) + log.error('Server did not respond. Exiting') return ProcessResult.failure( f'{section}: Failed to post-process - {section} did not respond.', ) @@ -88,9 +92,7 @@ def process( ) and extract ): - logger.debug( - f'Checking for archives to extract in directory: {dir_name}', - ) + log.debug(f'Checking for archives to extract in directory: {dir_name}') nzb2media.extract_files(dir_name) input_name, dir_name = convert_to_ascii(input_name, dir_name) @@ -127,10 +129,7 @@ def process( return res # The status hasn't changed. uTorrent can resume seeding now. - logger.warning( - f'The music album does not appear to have changed status after {wait_for} minutes. Please check your Logs', - section, - ) + log.warning(f'The music album does not appear to have changed status after {wait_for} minutes. Please check your Logs') return ProcessResult.failure( f'{section}: Failed to post-process - No change in wanted status', ) @@ -140,13 +139,13 @@ def process( url = nzb2media.utils.common.create_url(scheme, host, port, route) headers = {'X-Api-Key': apikey} if remote_path: - logger.debug(f'remote_path: {remote_dir(dir_name)}', section) + log.debug(f'remote_path: {remote_dir(dir_name)}') data = {'name': 'Rename', 'path': remote_dir(dir_name)} else: - logger.debug(f'path: {dir_name}', section) + log.debug(f'path: {dir_name}') data = {'name': 'Rename', 'path': dir_name} try: - logger.debug(f'Opening URL: {url} with data: {data}', section) + log.debug(f'Opening URL: {url} with data: {data}') r = requests.post( url, data=json.dumps(data), @@ -156,7 +155,7 @@ def process( timeout=(30, 1800), ) except requests.ConnectionError: - logger.error(f'Unable to open URL: {url}', section) + log.error(f'Unable to open URL: {url}') return ProcessResult.failure( f'{section}: Failed to post-process - Unable to connect to ' f'{section}', @@ -165,9 +164,9 @@ def process( try: res = r.json() scan_id = int(res['id']) - logger.debug(f'Scan started with id: {scan_id}', section) - except Exception as e: - logger.warning(f'No scan id was returned due to: {e}', section) + log.debug(f'Scan started with id: {scan_id}') + except Exception as error: + log.warning(f'No scan id was returned due to: {error}') return ProcessResult.failure( f'{section}: Failed to post-process - Unable to start scan', ) @@ -182,38 +181,24 @@ def process( break n += 1 if command_status: - logger.debug( - f'The Scan command return status: {command_status}', section, - ) + log.debug(f'The Scan command return status: {command_status}') if not os.path.exists(dir_name): - logger.debug( - f'The directory {dir_name} has been removed. Renaming was successful.', - section, - ) + log.debug(f'The directory {dir_name} has been removed. Renaming was successful.') return ProcessResult.success( f'{section}: Successfully post-processed {input_name}', ) elif command_status and command_status in ['completed']: - logger.debug( - 'The Scan command has completed successfully. Renaming was successful.', - section, - ) + log.debug('The Scan command has completed successfully. Renaming was successful.') return ProcessResult.success( f'{section}: Successfully post-processed {input_name}', ) elif command_status and command_status in ['failed']: - logger.debug( - 'The Scan command has failed. Renaming was not successful.', - section, - ) + log.debug('The Scan command has failed. Renaming was not successful.') # return ProcessResult.failure( # f'{section}: Failed to post-process {input_name}' # ) else: - logger.debug( - f'The Scan command did not return status completed. Passing back to {section} to attempt complete download handling.', - section, - ) + log.debug(f'The Scan command did not return status completed. Passing back to {section} to attempt complete download handling.') return ProcessResult( message=f'{section}: Passing back to {section} to attempt ' f'Complete Download Handling', @@ -222,24 +207,19 @@ def process( else: if section == 'Lidarr': - logger.postprocess( - f'FAILED: The download failed. Sending failed download to {section} for CDH processing', - section, - ) + log.debug(f'FAILED: The download failed. Sending failed download to {section} for CDH processing') # Return as failed to flag this in the downloader. return ProcessResult.failure( f'{section}: Download Failed. Sending back to {section}', ) else: - logger.warning('FAILED DOWNLOAD DETECTED', section) + log.warning('FAILED DOWNLOAD DETECTED') if ( delete_failed and os.path.isdir(dir_name) and not os.path.dirname(dir_name) == dir_name ): - logger.postprocess( - f'Deleting failed files and folder {dir_name}', section, - ) + log.postprocess(f'Deleting failed files and folder {dir_name}') remove_dir(dir_name) # Return as failed to flag this in the downloader. return ProcessResult.failure( @@ -251,21 +231,19 @@ def process( def get_status(url, apikey, dir_name): - logger.debug( - f'Attempting to get current status for release:{os.path.basename(dir_name)}', - ) + log.debug(f'Attempting to get current status for release:{os.path.basename(dir_name)}') params = { 'apikey': apikey, 'cmd': 'getHistory', } - logger.debug(f'Opening URL: {url} with PARAMS: {params}') + log.debug(f'Opening URL: {url} with PARAMS: {params}') try: r = requests.get(url, params=params, verify=False, timeout=(30, 120)) except requests.RequestException: - logger.error('Unable to open URL') + log.error('Unable to open URL') return None try: @@ -284,43 +262,34 @@ def force_process( ): release_status = get_status(url, apikey, dir_name) if not release_status: - logger.error( - f'Could not find a status for {input_name}, is it in the wanted list ?', - section, - ) + log.error(f'Could not find a status for {input_name}, is it in the wanted list ?') - logger.debug(f'Opening URL: {url} with PARAMS: {params}', section) + log.debug(f'Opening URL: {url} with PARAMS: {params}') try: r = requests.get(url, params=params, verify=False, timeout=(30, 300)) except requests.ConnectionError: - logger.error(f'Unable to open URL {url}', section) + log.error(f'Unable to open URL {url}') return ProcessResult.failure( f'{section}: Failed to post-process - Unable to connect to ' f'{section}', ) - logger.debug(f'Result: {r.text}', section) + log.debug(f'Result: {r.text}') if r.status_code not in [ requests.codes.ok, requests.codes.created, requests.codes.accepted, ]: - logger.error(f'Server returned status {r.status_code}', section) + log.error(f'Server returned status {r.status_code}') return ProcessResult.failure( f'{section}: Failed to post-process - Server returned status {r.status_code}', ) elif r.text == 'OK': - logger.postprocess( - f'SUCCESS: Post-Processing started for {input_name} in folder {dir_name} ...', - section, - ) + log.debug(f'SUCCESS: Post-Processing started for {input_name} in folder {dir_name} ...') else: - logger.error( - f'FAILED: Post-Processing has NOT started for {input_name} in folder {dir_name}. exiting!', - section, - ) + log.error(f'FAILED: Post-Processing has NOT started for {input_name} in folder {dir_name}. exiting!') return ProcessResult.failure( f'{section}: Failed to post-process - Returned log from {section} ' f'was not as expected.', @@ -333,18 +302,12 @@ def force_process( if ( current_status is not None and current_status != release_status ): # Something has changed. CPS must have processed this movie. - logger.postprocess( - f'SUCCESS: This release is now marked as status [{current_status}]', - section, - ) + log.debug(f'SUCCESS: This release is now marked as status [{current_status}]') return ProcessResult.success( f'{section}: Successfully post-processed {input_name}', ) if not os.path.isdir(dir_name): - logger.postprocess( - f'SUCCESS: The input directory {dir_name} has been removed Processing must have finished.', - section, - ) + log.debug(f'SUCCESS: The input directory {dir_name} has been removed Processing must have finished.') return ProcessResult.success( f'{section}: Successfully post-processed {input_name}', ) diff --git a/nzb2media/auto_process/tv.py b/nzb2media/auto_process/tv.py index 30931c39..c2e3ea26 100644 --- a/nzb2media/auto_process/tv.py +++ b/nzb2media/auto_process/tv.py @@ -3,6 +3,7 @@ from __future__ import annotations import copy import errno import json +import logging import os import time @@ -27,6 +28,9 @@ from nzb2media.utils.nzb import report_nzb from nzb2media.utils.paths import remote_dir from nzb2media.utils.paths import remove_dir +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def process( *, @@ -90,12 +94,10 @@ def process( # Should be changed after refactor. fork, fork_params = init_sickbeard.auto_fork() elif not username and not apikey and not sso_username: - logger.info( - 'No SickBeard / SiCKRAGE username or Sonarr apikey entered. Performing transcoder functions only', - ) + log.info('No SickBeard / SiCKRAGE username or Sonarr apikey entered. Performing transcoder functions only') fork, fork_params = 'None', {} else: - logger.error('Server did not respond. Exiting', section) + log.error('Server did not respond. Exiting') return ProcessResult.failure( f'{section}: Failed to post-process - {section} did not respond.', ) @@ -123,9 +125,9 @@ def process( if dir_name: try: os.makedirs(dir_name) # Attempt to create the directory - except OSError as e: + except OSError as error: # Re-raise the error if it wasn't about the directory not existing - if e.errno != errno.EEXIST: + if error.errno != errno.EEXIST: raise if 'process_method' not in fork_params or ( @@ -150,9 +152,7 @@ def process( ) and extract ): - logger.debug( - f'Checking for archives to extract in directory: {dir_name}', - ) + log.debug(f'Checking for archives to extract in directory: {dir_name}') nzb2media.extract_files(dir_name) input_name, dir_name = convert_to_ascii(input_name, dir_name) @@ -179,10 +179,10 @@ def process( rename_subs(dir_name) if num_files > 0: if valid_files == num_files and not status == 0: - logger.info('Found Valid Videos. Setting status Success') + log.info('Found Valid Videos. Setting status Success') status = 0 if valid_files < num_files and status == 0: - logger.info('Found corrupt videos. Setting status Failed') + log.info('Found corrupt videos. Setting status Failed') status = 1 if ( 'NZBOP_VERSION' in os.environ @@ -190,42 +190,26 @@ def process( ): print('[NZB] MARK=BAD') if good_files == num_files: - logger.debug( - f'Video marked as failed due to missing required language: {nzb2media.REQUIRE_LAN}', - section, - ) + log.debug(f'Video marked as failed due to missing required language: {nzb2media.REQUIRE_LAN}') else: - logger.debug( - 'Video marked as failed due to missing playable audio or video', - section, - ) + log.debug('Video marked as failed due to missing playable audio or video') if ( good_files < num_files and failure_link ): # only report corrupt files failure_link += '&corrupt=true' elif client_agent == 'manual': - logger.warning( - f'No media files found in directory {dir_name} to manually process.', - section, - ) + log.warning(f'No media files found in directory {dir_name} to manually process.') # Success (as far as this script is concerned) return ProcessResult.success() elif nzb_extraction_by == 'Destination': - logger.info( - 'Check for media files ignored because nzbExtractionBy is set to Destination.', - ) + log.info('Check for media files ignored because nzbExtractionBy is set to Destination.') if status == 0: - logger.info('Setting Status Success.') + log.info('Setting Status Success.') else: - logger.info( - 'Downloader reported an error during download or verification. Processing this as a failed download.', - ) + log.info('Downloader reported an error during download or verification. Processing this as a failed download.') status = 1 else: - logger.warning( - f'No media files found in directory {dir_name}. Processing this as a failed download', - section, - ) + log.warning(f'No media files found in directory {dir_name}. Processing this as a failed download') status = 1 if ( 'NZBOP_VERSION' in os.environ @@ -238,26 +222,15 @@ def process( ): # only transcode successful downloads result, new_dir_name = transcoder.transcode_directory(dir_name) if result == 0: - logger.debug( - f'SUCCESS: Transcoding succeeded for files in {dir_name}', - section, - ) + log.debug(f'SUCCESS: Transcoding succeeded for files in {dir_name}') dir_name = new_dir_name - logger.debug( - f'Config setting \'chmodDirectory\' currently set to {oct(chmod_directory)}', - section, - ) + log.debug(f'Config setting \'chmodDirectory\' currently set to {oct(chmod_directory)}') if chmod_directory: - logger.info( - f'Attempting to set the octal permission of \'{oct(chmod_directory)}\' on directory \'{dir_name}\'', - section, - ) + log.info(f'Attempting to set the octal permission of \'{oct(chmod_directory)}\' on directory \'{dir_name}\'') nzb2media.rchmod(dir_name, chmod_directory) else: - logger.error( - f'FAILED: Transcoding failed for files in {dir_name}', section, - ) + log.error(f'FAILED: Transcoding failed for files in {dir_name}') return ProcessResult.failure( f'{section}: Failed to post-process - Transcoding failed', ) @@ -343,45 +316,31 @@ def process( if status == 0: if section == 'NzbDrone' and not apikey: - logger.info('No Sonarr apikey entered. Processing completed.') + log.info('No Sonarr apikey entered. Processing completed.') return ProcessResult.success( f'{section}: Successfully post-processed {input_name}', ) - logger.postprocess( - 'SUCCESS: The download succeeded, sending a post-process request', - section, - ) + log.debug('SUCCESS: The download succeeded, sending a post-process request') else: nzb2media.FAILED = True if failure_link: report_nzb(failure_link, client_agent) if 'failed' in fork_params: - logger.postprocess( - f'FAILED: The download failed. Sending \'failed\' process request to {fork} branch', - section, - ) + log.debug(f'FAILED: The download failed. Sending \'failed\' process request to {fork} branch') elif section == 'NzbDrone': - logger.postprocess( - f'FAILED: The download failed. Sending failed download to {fork} for CDH processing', - section, - ) + log.debug(f'FAILED: The download failed. Sending failed download to {fork} for CDH processing') # Return as failed to flag this in the downloader. return ProcessResult.failure( f'{section}: Download Failed. Sending back to {section}', ) else: - logger.postprocess( - f'FAILED: The download failed. {fork} branch does not handle failed downloads. Nothing to process', - section, - ) + log.debug(f'FAILED: The download failed. {fork} branch does not handle failed downloads. Nothing to process') if ( delete_failed and os.path.isdir(dir_name) and not os.path.dirname(dir_name) == dir_name ): - logger.postprocess( - f'Deleting failed files and folder {dir_name}', section, - ) + log.debug(f'Deleting failed files and folder {dir_name}') remove_dir(dir_name) # Return as failed to flag this in the downloader. return ProcessResult.failure( @@ -410,7 +369,7 @@ def process( headers = {'X-Api-Key': apikey} # params = {'sortKey': 'series.title', 'page': 1, 'pageSize': 1, 'sortDir': 'asc'} if remote_path: - logger.debug(f'remote_path: {remote_dir(dir_name)}', section) + log.debug(f'remote_path: {remote_dir(dir_name)}') data = { 'name': 'DownloadedEpisodesScan', 'path': remote_dir(dir_name), @@ -418,7 +377,7 @@ def process( 'importMode': import_mode, } else: - logger.debug(f'path: {dir_name}', section) + log.debug(f'path: {dir_name}') data = { 'name': 'DownloadedEpisodesScan', 'path': dir_name, @@ -435,15 +394,14 @@ def process( else: s = requests.Session() - logger.debug( - f'Opening URL: {url} with params: {fork_params}', section, + log.debug(f'Opening URL: {url} with params: {fork_params}', section, ) if not apikey and username and password: login = f'{web_root}/login' login_params = {'username': username, 'password': password} - r = s.get(login, verify=False, timeout=(30, 60)) - if r.status_code in [401, 403] and r.cookies.get('_xsrf'): - login_params['_xsrf'] = r.cookies.get('_xsrf') + response = s.get(login, verify=False, timeout=(30, 60)) + if response.status_code in [401, 403] and response.cookies.get('_xsrf'): + login_params['_xsrf'] = response.cookies.get('_xsrf') s.post( login, data=login_params, @@ -451,7 +409,7 @@ def process( verify=False, timeout=(30, 60), ) - r = s.get( + response = s.get( url, auth=(username, password), params=fork_params, @@ -495,7 +453,7 @@ def process( else: params = fork_params - r = s.get( + response = s.get( url, params=params, stream=True, @@ -503,8 +461,8 @@ def process( timeout=(30, 1800), ) elif section == 'NzbDrone': - logger.debug(f'Opening URL: {url} with data: {data}', section) - r = requests.post( + log.debug(f'Opening URL: {url} with data: {data}') + response = requests.post( url, data=json.dumps(data), headers=headers, @@ -513,21 +471,21 @@ def process( timeout=(30, 1800), ) except requests.ConnectionError: - logger.error(f'Unable to open URL: {url}', section) + log.error(f'Unable to open URL: {url}') return ProcessResult.failure( f'{section}: Failed to post-process - Unable to connect to ' f'{section}', ) - if r.status_code not in [ + if response.status_code not in [ requests.codes.ok, requests.codes.created, requests.codes.accepted, ]: - logger.error(f'Server returned status {r.status_code}', section) + log.error(f'Server returned status {response.status_code}') return ProcessResult.failure( f'{section}: Failed to post-process - Server returned status ' - f'{r.status_code}', + f'{response.status_code}', ) success = False @@ -535,13 +493,13 @@ def process( started = False if section == 'SickBeard': if apikey: - if r.json()['result'] == 'success': + if response.json()['result'] == 'success': success = True else: - for line in r.iter_lines(): + for line in response.iter_lines(): if line: line = line.decode('utf-8') - logger.postprocess(line, section) + log.debug(line) if 'Moving file from' in line: input_name = os.path.split(line)[1] if 'added to the queue' in line: @@ -558,16 +516,16 @@ def process( if api_version >= 2: success = True else: - if r.json()['result'] == 'success': + if response.json()['result'] == 'success': success = True elif section == 'NzbDrone': try: - res = r.json() + res = response.json() scan_id = int(res['id']) - logger.debug(f'Scan started with id: {scan_id}', section) + log.debug(f'Scan started with id: {scan_id}') started = True - except Exception as e: - logger.warning(f'No scan id was returned due to: {e}', section) + except Exception as error: + log.warning(f'No scan id was returned due to: {error}') scan_id = None started = False @@ -576,9 +534,7 @@ def process( and delete_failed and not os.path.dirname(dir_name) == dir_name ): - logger.postprocess( - f'Deleting failed files and folder {dir_name}', section, - ) + log.debug(f'Deleting failed files and folder {dir_name}') remove_dir(dir_name) if success: @@ -596,50 +552,33 @@ def process( break n += 1 if command_status: - logger.debug( - f'The Scan command return status: {command_status}', section, - ) + log.debug(f'The Scan command return status: {command_status}') if not os.path.exists(dir_name): - logger.debug( - f'The directory {dir_name} has been removed. Renaming was successful.', - section, - ) + log.debug(f'The directory {dir_name} has been removed. Renaming was successful.') return ProcessResult.success( f'{section}: Successfully post-processed {input_name}', ) elif command_status and command_status in ['completed']: - logger.debug( - 'The Scan command has completed successfully. Renaming was successful.', - section, - ) + log.debug('The Scan command has completed successfully. Renaming was successful.') return ProcessResult.success( f'{section}: Successfully post-processed {input_name}', ) elif command_status and command_status in ['failed']: - logger.debug( - 'The Scan command has failed. Renaming was not successful.', - section, - ) + log.debug('The Scan command has failed. Renaming was not successful.') # return ProcessResult.failure( # f'{section}: Failed to post-process {input_name}' # ) url2 = nzb2media.utils.common.create_url(scheme, host, port, route) if completed_download_handling(url2, headers, section=section): - logger.debug( - f'The Scan command did not return status completed, but complete Download Handling is enabled. Passing back to {section}.', - section, - ) + log.debug(f'The Scan command did not return status completed, but complete Download Handling is enabled. Passing back to {section}.') return ProcessResult( message=f'{section}: Complete DownLoad Handling is enabled. ' f'Passing back to {section}', status_code=status, ) else: - logger.warning( - 'The Scan command did not return a valid status. Renaming was not successful.', - section, - ) + log.warning('The Scan command did not return a valid status. Renaming was not successful.') return ProcessResult.failure( f'{section}: Failed to post-process {input_name}', ) diff --git a/nzb2media/configuration.py b/nzb2media/configuration.py index cc81431f..f435acf7 100644 --- a/nzb2media/configuration.py +++ b/nzb2media/configuration.py @@ -1,6 +1,7 @@ from __future__ import annotations import copy +import logging import os import shutil from itertools import chain @@ -9,10 +10,14 @@ import configobj import nzb2media +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + class Section(configobj.Section): def isenabled(self): - # checks if subsection enabled, returns true/false if subsection specified otherwise returns true/false in {} + # checks if subsection enabled, returns true/false if subsection + # specified otherwise returns true/false in {} if not self.sections: try: value = list(ConfigObj.find_key(self, 'enabled'))[0] @@ -118,7 +123,7 @@ class ConfigObj(configobj.ConfigObj, Section): shutil.copyfile(nzb2media.CONFIG_SPEC_FILE, nzb2media.CONFIG_FILE) CFG_OLD = config(nzb2media.CONFIG_FILE) except Exception as error: - logger.error(f'Error {error} when copying to .cfg') + log.error(f'Error {error} when copying to .cfg') try: # check for autoProcessMedia.cfg.spec and create if it does not exist @@ -126,7 +131,7 @@ class ConfigObj(configobj.ConfigObj, Section): shutil.copyfile(nzb2media.CONFIG_FILE, nzb2media.CONFIG_SPEC_FILE) CFG_NEW = config(nzb2media.CONFIG_SPEC_FILE) except Exception as error: - logger.error(f'Error {error} when copying to .spec') + log.error(f'Error {error} when copying to .spec') # check for autoProcessMedia.cfg and autoProcessMedia.cfg.spec and if they don't exist return and fail if CFG_NEW is None or CFG_OLD is None: @@ -313,11 +318,7 @@ class ConfigObj(configobj.ConfigObj, Section): os.environ['NZBPO_NDCATEGORY'] == os.environ['NZBPO_SBCATEGORY'] ): - logger.warning( - '{x} category is set for SickBeard and Sonarr. Please check your config in NZBGet'.format( - x=os.environ['NZBPO_NDCATEGORY'], - ), - ) + log.warning('{x} category is set for SickBeard and Sonarr. Please check your config in NZBGet'.format(x=os.environ['NZBPO_NDCATEGORY'])) if ( 'NZBPO_RACATEGORY' in os.environ and 'NZBPO_CPSCATEGORY' in os.environ @@ -326,11 +327,7 @@ class ConfigObj(configobj.ConfigObj, Section): os.environ['NZBPO_RACATEGORY'] == os.environ['NZBPO_CPSCATEGORY'] ): - logger.warning( - '{x} category is set for CouchPotato and Radarr. Please check your config in NZBGet'.format( - x=os.environ['NZBPO_RACATEGORY'], - ), - ) + log.warning('{x} category is set for CouchPotato and Radarr. Please check your config in NZBGet'.format(x=os.environ['NZBPO_RACATEGORY'])) if ( 'NZBPO_RACATEGORY' in os.environ and 'NZBPO_W3CATEGORY' in os.environ @@ -339,11 +336,7 @@ class ConfigObj(configobj.ConfigObj, Section): os.environ['NZBPO_RACATEGORY'] == os.environ['NZBPO_W3CATEGORY'] ): - logger.warning( - '{x} category is set for Watcher3 and Radarr. Please check your config in NZBGet'.format( - x=os.environ['NZBPO_RACATEGORY'], - ), - ) + log.warning('{x} category is set for Watcher3 and Radarr. Please check your config in NZBGet'.format(x=os.environ['NZBPO_RACATEGORY'])) if ( 'NZBPO_W3CATEGORY' in os.environ and 'NZBPO_CPSCATEGORY' in os.environ @@ -352,11 +345,7 @@ class ConfigObj(configobj.ConfigObj, Section): os.environ['NZBPO_W3CATEGORY'] == os.environ['NZBPO_CPSCATEGORY'] ): - logger.warning( - '{x} category is set for CouchPotato and Watcher3. Please check your config in NZBGet'.format( - x=os.environ['NZBPO_W3CATEGORY'], - ), - ) + log.warning('{x} category is set for CouchPotato and Watcher3. Please check your config in NZBGet'.format(x=os.environ['NZBPO_W3CATEGORY'])) if ( 'NZBPO_LICATEGORY' in os.environ and 'NZBPO_HPCATEGORY' in os.environ @@ -365,11 +354,7 @@ class ConfigObj(configobj.ConfigObj, Section): os.environ['NZBPO_LICATEGORY'] == os.environ['NZBPO_HPCATEGORY'] ): - logger.warning( - '{x} category is set for HeadPhones and Lidarr. Please check your config in NZBGet'.format( - x=os.environ['NZBPO_LICATEGORY'], - ), - ) + log.warning('{x} category is set for HeadPhones and Lidarr. Please check your config in NZBGet'.format(x=os.environ['NZBPO_LICATEGORY'])) section = 'Nzb' key = 'NZBOP_DESTDIR' if key in os.environ: @@ -1118,14 +1103,14 @@ class ConfigObj(configobj.ConfigObj, Section): cfg_new[section][os.environ[env_cat_key]]['enabled'] = 1 except Exception as error: - logger.debug(f'Error {error} when applying NZBGet config') + log.debug(f'Error {error} when applying NZBGet config') try: # write our new config to autoProcessMedia.cfg cfg_new.filename = nzb2media.CONFIG_FILE cfg_new.write() except Exception as error: - logger.debug(f'Error {error} when writing changes to .cfg') + log.debug(f'Error {error} when writing changes to .cfg') return cfg_new diff --git a/nzb2media/databases.py b/nzb2media/databases.py index ccc4cc62..1ae3874d 100644 --- a/nzb2media/databases.py +++ b/nzb2media/databases.py @@ -1,20 +1,25 @@ from __future__ import annotations +import logging +import sys + from nzb2media import main_db from nzb2media.utils.files import backup_versioned_file +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + MIN_DB_VERSION = 1 # oldest db version we support migrating from MAX_DB_VERSION = 2 def backup_database(version): - logger.info('Backing up database before upgrade') + log.info('Backing up database before upgrade') if not backup_versioned_file(main_db.db_filename(), version): - logger.log_error_and_exit( - 'Database backup failed, abort upgrading database', - ) + logging.critical('Database backup failed, abort upgrading database') + sys.exit(1) else: - logger.info('Proceeding with upgrade') + log.info('Proceeding with upgrade') # ====================== @@ -47,14 +52,12 @@ class InitialSchema(main_db.SchemaUpgrade): cur_db_version = self.check_db_version() if cur_db_version < MIN_DB_VERSION: - logger.log_error_and_exit( - f'Your database version ({cur_db_version}) is too old to migrate from what this version of nzbToMedia supports ({MIN_DB_VERSION}).\nPlease remove nzbtomedia.db file to begin fresh.', - ) + log.critical(f'Your database version ({cur_db_version}) is too old to migrate from what this version of nzbToMedia supports ({MIN_DB_VERSION}).\nPlease remove nzbtomedia.db file to begin fresh.') + sys.exit(1) if cur_db_version > MAX_DB_VERSION: - logger.log_error_and_exit( - f'Your database version ({cur_db_version}) has been incremented past what this version of nzbToMedia supports ({MAX_DB_VERSION}).\nIf you have used other forks of nzbToMedia, your database may be unusable due to their modifications.', - ) + log.critical(f'Your database version ({cur_db_version}) has been incremented past what this version of nzbToMedia supports ({MAX_DB_VERSION}).\nIf you have used other forks of nzbToMedia, your database may be unusable due to their modifications.') + sys.exit(1) if cur_db_version < MAX_DB_VERSION: # We need to upgrade. queries = [ 'CREATE TABLE downloads2 (input_directory TEXT, input_name TEXT, input_hash TEXT, input_id TEXT, client_agent TEXT, status INTEGER, last_update NUMERIC, CONSTRAINT pk_downloadID PRIMARY KEY (input_directory, input_name));', diff --git a/nzb2media/extractor/__init__.py b/nzb2media/extractor/__init__.py index 608fbee9..6b1c7cb8 100644 --- a/nzb2media/extractor/__init__.py +++ b/nzb2media/extractor/__init__.py @@ -1,5 +1,6 @@ from __future__ import annotations +import logging import os import platform import shutil @@ -11,13 +12,16 @@ from time import sleep import nzb2media +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def extract(file_path, output_destination): success = 0 # Using Windows if platform.system() == 'Windows': if not os.path.exists(nzb2media.SEVENZIP): - nzb2media.logger.error('EXTRACTOR: Could not find 7-zip, Exiting') + log.error('EXTRACTOR: Could not find 7-zip, Exiting') return False wscriptlocation = os.path.join( os.environ['WINDIR'], 'system32', 'wscript.exe', @@ -109,20 +113,14 @@ def extract(file_path, output_destination): ): # we do have '7za' extract_commands[k] = ['7za', 'x', '-y'] else: - nzb2media.logger.error( - f'EXTRACTOR: {cmd} not found, disabling support for {k}', - ) + log.error(f'EXTRACTOR: {cmd} not found, disabling support for {k}') del extract_commands[k] devnull.close() else: - nzb2media.logger.warning( - 'EXTRACTOR: Cannot determine which tool to use when called from Transmission', - ) + log.warning('EXTRACTOR: Cannot determine which tool to use when called from Transmission') if not extract_commands: - nzb2media.logger.warning( - 'EXTRACTOR: No archive extracting programs found, plugin will be disabled', - ) + log.warning('EXTRACTOR: No archive extracting programs found, plugin will be disabled') ext = os.path.splitext(file_path) cmd = [] @@ -150,7 +148,7 @@ def extract(file_path, output_destination): if ext[1] in extract_commands: cmd = extract_commands[ext[1]] else: - nzb2media.logger.debug(f'EXTRACTOR: Unknown file type: {ext[1]}') + log.debug(f'EXTRACTOR: Unknown file type: {ext[1]}') return False # Create outputDestination folder @@ -166,8 +164,8 @@ def extract(file_path, output_destination): else: passwords = [] - nzb2media.logger.info(f'Extracting {file_path} to {output_destination}') - nzb2media.logger.debug(f'Extracting {cmd} {file_path} {output_destination}') + log.info(f'Extracting {file_path} to {output_destination}') + log.debug(f'Extracting {cmd} {file_path} {output_destination}') orig_files = [] orig_dirs = [] @@ -192,19 +190,17 @@ def extract(file_path, output_destination): else: cmd = nzb2media.NICENESS + cmd cmd2 = cmd - if not 'gunzip' in cmd: # gunzip doesn't support password + if 'gunzip' not in cmd: # gunzip doesn't support password cmd2.append('-p-') # don't prompt for password. p = Popen( cmd2, stdout=devnull, stderr=devnull, startupinfo=info, ) # should extract files fine. res = p.wait() if res == 0: # Both Linux and Windows return 0 for successful. - nzb2media.logger.info( - f'EXTRACTOR: Extraction was successful for {file_path} to {output_destination}', - ) + log.info(f'EXTRACTOR: Extraction was successful for {file_path} to {output_destination}') success = 1 elif len(passwords) > 0 and not 'gunzip' in cmd: - nzb2media.logger.info('EXTRACTOR: Attempting to extract with passwords') + log.info('EXTRACTOR: Attempting to extract with passwords') for password in passwords: if ( password == '' @@ -219,17 +215,13 @@ def extract(file_path, output_destination): ) # should extract files fine. res = p.wait() if (res >= 0 and platform == 'Windows') or res == 0: - nzb2media.logger.info( - f'EXTRACTOR: Extraction was successful for {file_path} to {output_destination} using password: {password}', - ) + log.info(f'EXTRACTOR: Extraction was successful for {file_path} to {output_destination} using password: {password}') success = 1 break else: continue except Exception: - nzb2media.logger.error( - f'EXTRACTOR: Extraction failed for {file_path}. Could not call command {cmd}', - ) + log.error(f'EXTRACTOR: Extraction failed for {file_path}. Could not call command {cmd}') os.chdir(pwd) return False @@ -256,7 +248,5 @@ def extract(file_path, output_destination): pass return True else: - nzb2media.logger.error( - f'EXTRACTOR: Extraction failed for {file_path}. Result was {res}', - ) + log.error(f'EXTRACTOR: Extraction failed for {file_path}. Result was {res}') return False diff --git a/nzb2media/main_db.py b/nzb2media/main_db.py index 43836fe4..e1969ced 100644 --- a/nzb2media/main_db.py +++ b/nzb2media/main_db.py @@ -1,11 +1,15 @@ from __future__ import annotations +import logging import re import sqlite3 import time import nzb2media +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def db_filename(filename='nzbtomedia.db', suffix=None): """ @@ -52,15 +56,12 @@ class DBConnection: while attempt < 5: try: if args is None: - logger.log(f'{self.filename}: {query}', logger.DB) + log.debug(f'{self.filename}: {query}') cursor = self.connection.cursor() cursor.execute(query) sql_result = cursor.fetchone()[0] else: - logger.log( - f'{self.filename}: {query} with args {args}', - logger.DB, - ) + log.debug(f'{self.filename}: {query} with args {args}') cursor = self.connection.cursor() cursor.execute(query, args) sql_result = cursor.fetchone()[0] @@ -72,16 +73,14 @@ class DBConnection: 'unable to open database file' in error.args[0] or 'database is locked' in error.args[0] ): - logger.log(f'DB error: {error}', logger.WARNING) + log.warning(f'DB error: {error}') attempt += 1 time.sleep(1) else: - logger.log(f'DB error: {error}', logger.ERROR) + log.error(f'DB error: {error}') raise except sqlite3.DatabaseError as error: - logger.log( - f'Fatal error executing query: {error}', logger.ERROR, - ) + log.error(f'Fatal error executing query: {error}') raise return sql_result @@ -98,21 +97,16 @@ class DBConnection: for qu in querylist: if len(qu) == 1: if log_transaction: - logger.log(qu[0], logger.DEBUG) + log.debug(qu[0]) sql_result.append(self.connection.execute(qu[0])) elif len(qu) > 1: if log_transaction: - logger.log( - f'{qu[0]} with args {qu[1]}', logger.DEBUG, - ) + log.debug(f'{qu[0]} with args {qu[1]}') sql_result.append( self.connection.execute(qu[0], qu[1]), ) self.connection.commit() - logger.log( - f'Transaction with {len(querylist)} query\'s executed', - logger.DEBUG, - ) + log.debug(f'Transaction with {len(querylist)} query\'s executed') return sql_result except sqlite3.OperationalError as error: sql_result = [] @@ -122,18 +116,16 @@ class DBConnection: 'unable to open database file' in error.args[0] or 'database is locked' in error.args[0] ): - logger.log(f'DB error: {error}', logger.WARNING) + log.warning(f'DB error: {error}') attempt += 1 time.sleep(1) else: - logger.log(f'DB error: {error}', logger.ERROR) + log.error(f'DB error: {error}') raise except sqlite3.DatabaseError as error: if self.connection: self.connection.rollback() - logger.log( - f'Fatal error executing query: {error}', logger.ERROR, - ) + log.error(f'Fatal error executing query: {error}') raise return sql_result @@ -148,13 +140,10 @@ class DBConnection: while attempt < 5: try: if args is None: - logger.log(f'{self.filename}: {query}', logger.DB) + log.debug(f'{self.filename}: {query}') sql_result = self.connection.execute(query) else: - logger.log( - f'{self.filename}: {query} with args {args}', - logger.DB, - ) + log.debug(f'{self.filename}: {query} with args {args}') sql_result = self.connection.execute(query, args) self.connection.commit() # get out of the connection attempt loop since we were successful @@ -164,16 +153,14 @@ class DBConnection: 'unable to open database file' in error.args[0] or 'database is locked' in error.args[0] ): - logger.log(f'DB error: {error}', logger.WARNING) + log.warning(f'DB error: {error}') attempt += 1 time.sleep(1) else: - logger.log(f'DB error: {error}', logger.ERROR) + log.error(f'DB error: {error}') raise except sqlite3.DatabaseError as error: - logger.log( - f'Fatal error executing query: {error}', logger.ERROR, - ) + log.error(f'Fatal error executing query: {error}') raise return sql_result @@ -239,7 +226,7 @@ class DBSanityCheck: def upgrade_database(connection, schema): - logger.log('Checking database structure...', logger.MESSAGE) + log.info('Checking database structure...') _process_upgrade(connection, schema) @@ -251,15 +238,9 @@ def pretty_name(class_name): def _process_upgrade(connection, upgrade_class): instance = upgrade_class(connection) - logger.log( - f'Checking {pretty_name(upgrade_class.__name__)} database upgrade', - logger.DEBUG, - ) + log.debug(f'Checking {pretty_name(upgrade_class.__name__)} database upgrade') if not instance.test(): - logger.log( - f'Database upgrade required: {pretty_name(upgrade_class.__name__)}', - logger.MESSAGE, - ) + log.info(f'Database upgrade required: {pretty_name(upgrade_class.__name__)}') try: instance.execute() except sqlite3.DatabaseError as error: @@ -267,15 +248,9 @@ def _process_upgrade(connection, upgrade_class): f'Error in {upgrade_class.__name__}: {error}', ) raise - logger.log( - f'{upgrade_class.__name__} upgrade completed', - logger.DEBUG, - ) + log.debug(f'{upgrade_class.__name__} upgrade completed') else: - logger.log( - f'{upgrade_class.__name__} upgrade not required', - logger.DEBUG, - ) + log.debug(f'{upgrade_class.__name__} upgrade not required') for upgradeSubClass in upgrade_class.__subclasses__(): _process_upgrade(connection, upgradeSubClass) diff --git a/nzb2media/managers/pymedusa.py b/nzb2media/managers/pymedusa.py index c3a74ca0..b3746b15 100644 --- a/nzb2media/managers/pymedusa.py +++ b/nzb2media/managers/pymedusa.py @@ -1,5 +1,6 @@ from __future__ import annotations +import logging import time import requests @@ -8,6 +9,9 @@ import nzb2media.utils.common from nzb2media.auto_process.common import ProcessResult from nzb2media.managers.sickbeard import SickBeard +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + class PyMedusa(SickBeard): """PyMedusa class.""" @@ -38,10 +42,7 @@ class PyMedusaApiV1(SickBeard): def api_call(self) -> ProcessResult: self._process_fork_prarams() - logger.debug( - f'Opening URL: {self.url} with params: {self.sb_init.fork_params}', - self.sb_init.section, - ) + log.debug(f'Opening URL: {self.url} with params: {self.sb_init.fork_params}') try: response = self.session.get( self.url, @@ -52,10 +53,7 @@ class PyMedusaApiV1(SickBeard): timeout=(30, 1800), ) except requests.ConnectionError: - logger.error( - f'Unable to open URL: {self.url}', - self.sb_init.section, - ) + log.error(f'Unable to open URL: {self.url}') return ProcessResult.failure( f'{self.sb_init.section}: Failed to post-process - Unable to ' f'connect to {self.sb_init.section}', @@ -67,10 +65,7 @@ class PyMedusaApiV1(SickBeard): requests.codes.accepted, ] if response.status_code not in successful_status_codes: - logger.error( - f'Server returned status {response.status_code}', - self.sb_init.section, - ) + log.error(f'Server returned status {response.status_code}') result = ProcessResult.failure( f'{self.sb_init.section}: Failed to post-process - Server ' f'returned status {response.status_code}', @@ -98,7 +93,7 @@ class PyMedusaApiV2(SickBeard): # Check for an apikey # This is required with using fork = medusa-apiv2 if not sb_init.apikey: - logger.error( + log.error( 'For the section SickBeard `fork = medusa-apiv2` you also ' 'need to configure an `apikey`', ) @@ -119,10 +114,7 @@ class PyMedusaApiV2(SickBeard): try: response = self.session.get(url, verify=False, timeout=(30, 1800)) except requests.ConnectionError: - logger.error( - 'Unable to get postprocess identifier status', - self.sb_init.section, - ) + log.error('Unable to get postprocess identifier status') return False try: @@ -134,7 +126,7 @@ class PyMedusaApiV2(SickBeard): def api_call(self) -> ProcessResult: self._process_fork_prarams() - logger.debug(f'Opening URL: {self.url}', self.sb_init.section) + log.debug(f'Opening URL: {self.url}') payload = self.sb_init.fork_params payload['resource'] = self.sb_init.fork_params['nzbName'] del payload['nzbName'] @@ -155,10 +147,7 @@ class PyMedusaApiV2(SickBeard): timeout=(30, 1800), ) except requests.ConnectionError: - logger.error( - 'Unable to send postprocess request', - self.sb_init.section, - ) + log.error('Unable to send postprocess request') return ProcessResult.failure( f'{self.sb_init.section}: Unable to send postprocess request ' f'to PyMedusa', @@ -169,7 +158,7 @@ class PyMedusaApiV2(SickBeard): try: jdata = response.json() except ValueError: - logger.debug('No data returned from provider') + log.debug('No data returned from provider') return ProcessResult.failure('No data returned from provider') else: jdata = {} @@ -196,7 +185,7 @@ class PyMedusaApiV2(SickBeard): # Log Medusa's PP logs here. if response.get('output'): for line in response['output']: - logger.postprocess(line, self.sb_init.section) + log.postprocess(line) # For now this will most likely always be True. # In the future we could return an exit state for when the PP in diff --git a/nzb2media/managers/sickbeard.py b/nzb2media/managers/sickbeard.py index 7c302654..3aac8329 100644 --- a/nzb2media/managers/sickbeard.py +++ b/nzb2media/managers/sickbeard.py @@ -1,6 +1,7 @@ from __future__ import annotations import copy +import logging import requests from oauthlib.oauth2 import LegacyApplicationClient @@ -10,6 +11,9 @@ import nzb2media from nzb2media.auto_process.common import ProcessResult from nzb2media.utils.paths import remote_dir +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + class InitSickBeard: """SickBeard init class. @@ -60,7 +64,7 @@ class InitSickBeard: # config settings if nzb2media.FORK_SET: # keep using determined fork for multiple (manual) post-processing - logger.info( + log.info( f'{self.section}:{self.input_category} fork already set to ' f'{nzb2media.FORK_SET[0]}', ) @@ -87,7 +91,7 @@ class InitSickBeard: protocol = 'https://' if self.ssl else 'http://' if self.section == 'NzbDrone': - logger.info(f'Attempting to verify {self.input_category} fork') + log.info(f'Attempting to verify {self.input_category} fork') url = nzb2media.utils.common.create_url( scheme=protocol, host=self.host, @@ -96,20 +100,20 @@ class InitSickBeard: ) headers = {'X-Api-Key': self.apikey} try: - r = requests.get( + response = requests.get( url, headers=headers, stream=True, verify=False, ) except requests.ConnectionError: - logger.warning( + log.warning( f'Could not connect to {self.section}:' f'{self.input_category} to verify fork!', ) - if not r.ok: - logger.warning( + if not response.ok: + log.warning( f'Connection to {self.section}:{self.input_category} ' f'failed! Check your configuration', ) @@ -117,7 +121,7 @@ class InitSickBeard: self.fork = ['default', {}] elif self.section == 'SiCKRAGE': - logger.info(f'Attempting to verify {self.input_category} fork') + log.info(f'Attempting to verify {self.input_category} fork') if self.api_version >= 2: url = nzb2media.utils.common.create_url( @@ -155,27 +159,27 @@ class InitSickBeard: password=self.sso_password, ) token = oauth_token['access_token'] - r = requests.get( + response = requests.get( url, headers={f'Authorization': f'Bearer {token}'}, stream=True, verify=False, ) else: - r = requests.get( + response = requests.get( url, params=api_params, stream=True, verify=False, ) - if not r.ok: - logger.warning( + if not response.ok: + log.warning( f'Connection to {self.section}:{self.input_category} ' f'failed! Check your configuration', ) except requests.ConnectionError: - logger.warning( + log.warning( f'Could not connect to {self.section}:' f'{self.input_category} to verify API version!', ) @@ -197,9 +201,7 @@ class InitSickBeard: elif self.fork == 'auto': self.detect_fork() - logger.info( - f'{self.section}:{self.input_category} fork set to {self.fork[0]}', - ) + log.info(f'{self.section}:{self.input_category} fork set to {self.fork[0]}') nzb2media.FORK_SET = self.fork self.fork, self.fork_params = self.fork[0], self.fork[1] # This will create the fork object, and attach to self.fork_obj. @@ -211,15 +213,15 @@ class InitSickBeard: try: json_data = r.json() except ValueError: - logger.error('Failed to get JSON data from response') - logger.debug('Response received') + log.error('Failed to get JSON data from response') + log.debug('Response received') raise try: json_data = json_data['data'] except KeyError: - logger.error('Failed to get data from JSON') - logger.debug(f'Response received: {json_data}') + log.error('Failed to get data from JSON') + log.debug(f'Response received: {json_data}') raise else: if isinstance(json_data, str): @@ -231,13 +233,11 @@ class InitSickBeard: # Find excess parameters excess_parameters = set(params).difference(optional_parameters) excess_parameters.remove('cmd') # Don't remove cmd from api params - logger.debug( - f'Removing excess parameters: ' f'{sorted(excess_parameters)}', - ) + log.debug(f'Removing excess parameters: ' f'{sorted(excess_parameters)}') rem_params.extend(excess_parameters) return rem_params, True except: - logger.error('Failed to identify optionalParameters') + log.error('Failed to identify optionalParameters') return rem_params, False def detect_fork(self): @@ -245,7 +245,7 @@ class InitSickBeard: detected = False params = nzb2media.ALL_FORKS rem_params = [] - logger.info(f'Attempting to auto-detect {self.input_category} fork') + log.info(f'Attempting to auto-detect {self.input_category} fork') # Define the order to test. # Default must be first since default fork doesn't reject parameters. # Then in order of most unique parameters. @@ -269,7 +269,7 @@ class InitSickBeard: # attempting to auto-detect fork try: - s = requests.Session() + session = requests.Session() if not self.apikey and self.username and self.password: login = nzb2media.utils.common.create_url( @@ -282,54 +282,54 @@ class InitSickBeard: 'username': self.username, 'password': self.password, } - r = s.get(login, verify=False, timeout=(30, 60)) - if r.status_code in [401, 403] and r.cookies.get('_xsrf'): - login_params['_xsrf'] = r.cookies.get('_xsrf') - s.post(login, data=login_params, stream=True, verify=False) - r = s.get( + response = session.get(login, verify=False, timeout=(30, 60)) + if response.status_code in [401, 403] and response.cookies.get('_xsrf'): + login_params['_xsrf'] = response.cookies.get('_xsrf') + session.post(login, data=login_params, stream=True, verify=False) + response = session.get( url, auth=(self.username, self.password), params=api_params, verify=False, ) except requests.ConnectionError: - logger.info( + log.info( f'Could not connect to {self.section}:{self.input_category} ' f'to perform auto-fork detection!', ) - r = [] + response = [] - if r and r.ok: + if response and response.ok: if self.apikey: - rem_params, found = self._api_check(r, params, rem_params) + rem_params, found = self._api_check(response, params, rem_params) if found: params['cmd'] = 'sg.postprocess' else: # try different api set for non-SickGear forks. api_params = {'cmd': 'help', 'subject': 'postprocess'} try: if not self.apikey and self.username and self.password: - r = s.get( + response = session.get( url, auth=(self.username, self.password), params=api_params, verify=False, ) else: - r = s.get(url, params=api_params, verify=False) + response = session.get(url, params=api_params, verify=False) except requests.ConnectionError: - logger.info( + log.info( f'Could not connect to {self.section}:' f'{self.input_category} to perform auto-fork ' f'detection!', ) - rem_params, found = self._api_check(r, params, rem_params) + rem_params, found = self._api_check(response, params, rem_params) params['cmd'] = 'postprocess' else: # Find excess parameters rem_params.extend( param for param in params - if f'name="{param}"' not in r.text + if f'name="{param}"' not in response.text ) # Remove excess params @@ -343,18 +343,18 @@ class InitSickBeard: if detected: self.fork = fork - logger.info( + log.info( f'{self.section}:{self.input_category} fork auto-detection ' f'successful ...', ) elif rem_params: - logger.info( + log.info( f'{self.section}:{self.input_category} fork auto-detection ' f'found custom params {params}', ) self.fork = ['custom', params] else: - logger.info( + log.info( f'{self.section}:{self.input_category} fork auto-detection ' f'failed', ) @@ -371,12 +371,12 @@ class InitSickBeard: 'Medusa-api': PyMedusaApiV1, 'Medusa-apiv2': PyMedusaApiV2, } - logger.debug(f'Create object for fork {self.fork}') + log.debug(f'Create object for fork {self.fork}') if self.fork and mapped_forks.get(self.fork): # Create the fork object and pass self (SickBeardInit) to it for all the data, like Config. self.fork_obj = mapped_forks[self.fork](self) else: - logger.info( + log.info( f'{self.section}:{self.input_category} Could not create a ' f'fork object for {self.fork}. Probaly class not added yet.', ) @@ -537,10 +537,7 @@ class SickBeard: def api_call(self) -> ProcessResult: """Perform a base sickbeard api call.""" self._process_fork_prarams() - logger.debug( - f'Opening URL: {self.url} with params: {self.sb_init.fork_params}', - self.sb_init.section, - ) + log.debug(f'Opening URL: {self.url} with params: {self.sb_init.fork_params}') try: if ( not self.sb_init.apikey @@ -559,9 +556,9 @@ class SickBeard: 'username': self.sb_init.username, 'password': self.sb_init.password, } - r = self.session.get(login, verify=False, timeout=(30, 60)) - if r.status_code in [401, 403] and r.cookies.get('_xsrf'): - login_params['_xsrf'] = r.cookies.get('_xsrf') + response = self.session.get(login, verify=False, timeout=(30, 60)) + if response.status_code in [401, 403] and response.cookies.get('_xsrf'): + login_params['_xsrf'] = response.cookies.get('_xsrf') self.session.post( login, data=login_params, @@ -578,10 +575,7 @@ class SickBeard: timeout=(30, 1800), ) except requests.ConnectionError: - logger.error( - f'Unable to open URL: {self.url}', - self.sb_init.section, - ) + log.error(f'Unable to open URL: {self.url}') result = ProcessResult.failure( f'{self.sb_init.section}: Failed to post-process - Unable to ' f'connect to {self.sb_init.section}', @@ -593,10 +587,7 @@ class SickBeard: requests.codes.accepted, ] if response.status_code not in successful_statuses: - logger.error( - f'Server returned status {response.status_code}', - self.sb_init.section, - ) + log.error(f'Server returned status {response.status_code}') result = ProcessResult.failure( f'{self.sb_init.section}: Failed to post-process - Server ' f'returned status {response.status_code}', @@ -614,7 +605,7 @@ class SickBeard: for line in response.iter_lines(): if line: line = line.decode('utf-8') - logger.postprocess(line, self.sb_init.section) + log.postprocess(line) # if 'Moving file from' in line: # input_name = os.path.split(line)[1] # if 'added to the queue' in line: diff --git a/nzb2media/plugins/plex.py b/nzb2media/plugins/plex.py index d26a0f7f..8c220f9c 100644 --- a/nzb2media/plugins/plex.py +++ b/nzb2media/plugins/plex.py @@ -1,9 +1,14 @@ from __future__ import annotations +import logging + import requests import nzb2media +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def configure_plex(config): nzb2media.PLEX_SSL = int(config['Plex']['plex_ssl']) @@ -35,9 +40,7 @@ def plex_update(category): section = None if not nzb2media.PLEX_SECTION: return - logger.debug( - f'Attempting to update Plex Library for category {category}.', 'PLEX', - ) + log.debug(f'Attempting to update Plex Library for category {category}.') for item in nzb2media.PLEX_SECTION: if item[0] == category: section = item[1] @@ -45,6 +48,6 @@ def plex_update(category): if section: url = f'{url}{section}/refresh?X-Plex-Token={nzb2media.PLEX_TOKEN}' requests.get(url, timeout=(60, 120), verify=False) - logger.debug('Plex Library has been refreshed.', 'PLEX') + log.debug('Plex Library has been refreshed.') else: - logger.debug('Could not identify section for plex update', 'PLEX') + log.debug('Could not identify section for plex update') diff --git a/nzb2media/plugins/subtitles.py b/nzb2media/plugins/subtitles.py index bc378095..97c9278b 100644 --- a/nzb2media/plugins/subtitles.py +++ b/nzb2media/plugins/subtitles.py @@ -1,5 +1,6 @@ from __future__ import annotations +import logging import os import re @@ -8,6 +9,9 @@ from babelfish import Language import nzb2media +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def import_subs(filename): if not nzb2media.GETSUBS: @@ -28,9 +32,7 @@ def import_subs(filename): if not languages: return - logger.info( - f'Attempting to download subtitles for {filename}', 'SUBTITLES', - ) + log.info(f'Attempting to download subtitles for {filename}') try: video = subliminal.scan_video(filename) subtitles = subliminal.download_best_subtitles({video}, languages) @@ -41,11 +43,8 @@ def import_subs(filename): video.name, subtitle.language, ) os.chmod(subtitle_path, 0o644) - except Exception as e: - logger.error( - f'Failed to download subtitles for {filename} due to: {e}', - 'SUBTITLES', - ) + except Exception as error: + log.error(f'Failed to download subtitles for {filename} due to: {error}') def rename_subs(path): @@ -109,16 +108,12 @@ def rename_subs(path): break new_sub = f'{new_sub}{ext}' # add extension now if os.path.isfile(new_sub): # Don't copy over existing - final check. - logger.debug( - f'Unable to rename sub file {sub} as destination {new_sub} already exists', - ) + log.debug(f'Unable to rename sub file {sub} as destination {new_sub} already exists') continue - logger.debug( - f'Renaming sub file from {sub} to {new_sub}', - ) + log.debug(f'Renaming sub file from {sub} to {new_sub}') renamed.append(new_sub) try: os.rename(sub, new_sub) except Exception as error: - logger.error(f'Unable to rename sub file due to: {error}') + log.error(f'Unable to rename sub file due to: {error}') return diff --git a/nzb2media/processor/manual.py b/nzb2media/processor/manual.py index 94453469..3ea4303e 100644 --- a/nzb2media/processor/manual.py +++ b/nzb2media/processor/manual.py @@ -1,5 +1,6 @@ from __future__ import annotations +import logging import os import nzb2media @@ -8,12 +9,13 @@ from nzb2media.processor import nzb from nzb2media.utils.common import get_dirs from nzb2media.utils.download_info import get_download_info +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def process(): # Perform Manual Post-Processing - logger.warning( - 'Invalid number of arguments received from client, Switching to manual run mode ...', - ) + log.warning('Invalid number of arguments received from client, Switching to manual run mode ...') # Post-Processing Result result = ProcessResult( @@ -26,29 +28,21 @@ def process(): if not nzb2media.CFG[section][subsection].isenabled(): continue for dir_name in get_dirs(section, subsection, link='move'): - logger.info( - f'Starting manual run for {section}:{subsection} - Folder: {dir_name}', - ) - logger.info( - f'Checking database for download info for {os.path.basename(dir_name)} ...', - ) + log.info(f'Starting manual run for {section}:{subsection} - Folder: {dir_name}') + log.info(f'Checking database for download info for {os.path.basename(dir_name)} ...') nzb2media.DOWNLOAD_INFO = get_download_info( os.path.basename(dir_name), 0, ) if nzb2media.DOWNLOAD_INFO: - logger.info( - f'Found download info for {os.path.basename(dir_name)}, setting variables now ...', - ) + log.info(f'Found download info for {os.path.basename(dir_name)}, setting variables now ...') client_agent = ( - nzb2media.DOWNLOAD_INFO[0]['client_agent'] or 'manual' + nzb2media.DOWNLOAD_INFO[0]['client_agent'] or 'manual' ) download_id = nzb2media.DOWNLOAD_INFO[0]['input_id'] or '' else: - logger.info( - f'Unable to locate download info for {os.path.basename(dir_name)}, continuing to try and process this release ...', - ) + log.info(f'Unable to locate download info for {os.path.basename(dir_name)}, continuing to try and process this release ...') client_agent = 'manual' download_id = '' @@ -69,8 +63,6 @@ def process(): input_category=subsection, ) if results.status_code != 0: - logger.error( - f'A problem was reported when trying to perform a manual run for {section}:{subsection}.', - ) + log.error(f'A problem was reported when trying to perform a manual run for {section}:{subsection}.') result = results return result diff --git a/nzb2media/processor/nzb.py b/nzb2media/processor/nzb.py index 5d46ab72..e0ac31fe 100644 --- a/nzb2media/processor/nzb.py +++ b/nzb2media/processor/nzb.py @@ -1,6 +1,7 @@ from __future__ import annotations import datetime +import logging import nzb2media from nzb2media import main_db @@ -20,6 +21,9 @@ from nzb2media.utils.encoding import convert_to_ascii from nzb2media.utils.files import extract_files from nzb2media.utils.nzb import get_nzoid +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def process( input_directory, @@ -31,9 +35,7 @@ def process( failure_link=None, ): if nzb2media.SAFE_MODE and input_directory == nzb2media.NZB_DEFAULT_DIRECTORY: - logger.error( - f'The input directory:[{input_directory}] is the Default Download Directory. Please configure category directories to prevent processing of other media.', - ) + log.error(f'The input directory:[{input_directory}] is the Default Download Directory. Please configure category directories to prevent processing of other media.') return ProcessResult( message='', status_code=-1, @@ -41,23 +43,16 @@ def process( if not download_id and client_agent == 'sabnzbd': download_id = get_nzoid(input_name) - if client_agent != 'manual' and not nzb2media.DOWNLOAD_INFO: - logger.debug( - f'Adding NZB download info for directory {input_directory} to database', - ) - + log.debug(f'Adding NZB download info for directory {input_directory} to database') my_db = main_db.DBConnection() - input_directory1 = input_directory input_name1 = input_name - try: encoded, input_directory1 = char_replace(input_directory) encoded, input_name1 = char_replace(input_name) except Exception: pass - control_value_dict = {'input_directory': input_directory1} new_value_dict = { 'input_name': input_name1, @@ -68,7 +63,6 @@ def process( 'last_update': datetime.date.today().toordinal(), } my_db.upsert('downloads', new_value_dict, control_value_dict) - # auto-detect section if input_category is None: input_category = 'UNCAT' @@ -77,68 +71,45 @@ def process( if section is None: section = nzb2media.CFG.findsection('ALL').isenabled() if section is None: - logger.error( - f'Category:[{input_category}] is not defined or is not enabled. Please rename it or ensure it is enabled for the appropriate section in your autoProcessMedia.cfg and try again.', - ) + log.error(f'Category:[{input_category}] is not defined or is not enabled. Please rename it or ensure it is enabled for the appropriate section in your autoProcessMedia.cfg and try again.') return ProcessResult( message='', status_code=-1, ) else: usercat = 'ALL' - if len(section) > 1: - logger.error( - f'Category:[{input_category}] is not unique, {section.keys()} are using it. Please rename it or disable all other sections using the same category name in your autoProcessMedia.cfg and try again.', - ) + log.error(f'Category:[{input_category}] is not unique, {section.keys()} are using it. Please rename it or disable all other sections using the same category name in your autoProcessMedia.cfg and try again.') return ProcessResult( message='', status_code=-1, ) - if section: section_name = section.keys()[0] - logger.info(f'Auto-detected SECTION:{section_name}') + log.info(f'Auto-detected SECTION:{section_name}') else: - logger.error( - f'Unable to locate a section with subsection:{input_category} enabled in your autoProcessMedia.cfg, exiting!', - ) + log.error(f'Unable to locate a section with subsection:{input_category} enabled in your autoProcessMedia.cfg, exiting!') return ProcessResult( status_code=-1, message='', ) - cfg = dict(nzb2media.CFG[section_name][usercat]) - extract = int(cfg.get('extract', 0)) - try: if int(cfg.get('remote_path')) and not nzb2media.REMOTE_PATHS: - logger.error( - f'Remote Path is enabled for {section_name}:{input_category} but no Network mount points are defined. Please check your autoProcessMedia.cfg, exiting!', - ) + log.error(f'Remote Path is enabled for {section_name}:{input_category} but no Network mount points are defined. Please check your autoProcessMedia.cfg, exiting!') return ProcessResult( status_code=-1, message='', ) except Exception: remote_path = cfg.get('remote_path') - logger.error( - f'Remote Path {remote_path} is not valid for {section_name}:{input_category} Please set this to either 0 to disable or 1 to enable!', - ) - + log.error(f'Remote Path {remote_path} is not valid for {section_name}:{input_category} Please set this to either 0 to disable or 1 to enable!') input_name, input_directory = convert_to_ascii(input_name, input_directory) - if extract == 1 and not (status > 0 and nzb2media.NOEXTRACTFAILED): - logger.debug( - f'Checking for archives to extract in directory: {input_directory}', - ) + log.debug(f'Checking for archives to extract in directory: {input_directory}') extract_files(input_directory) - - logger.info( - f'Calling {section_name}:{input_category} to post-process:{input_name}', - ) - + log.info(f'Calling {section_name}:{input_category} to post-process:{input_name}') if section_name == 'UserScript': result = external_script( input_directory, input_name, input_category, section[usercat], @@ -169,9 +140,7 @@ def process( input_category=input_category, failure_link=failure_link, ) - plex_update(input_category) - if result.status_code == 0: if client_agent != 'manual': # update download status in our DB @@ -183,7 +152,7 @@ def process( 'Radarr', 'Lidarr', ]: - # cleanup our processing folders of any misc unwanted files and empty directories + # cleanup our processing folders of any misc unwanted files and + # empty directories clean_dir(input_directory, section_name, input_category) - return result diff --git a/nzb2media/processor/nzbget.py b/nzb2media/processor/nzbget.py index 7744e9ca..95295c20 100644 --- a/nzb2media/processor/nzbget.py +++ b/nzb2media/processor/nzbget.py @@ -1,11 +1,15 @@ from __future__ import annotations +import logging import os import sys import nzb2media from nzb2media.processor import nzb +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def parse_download_id(): """Parse nzbget download_id from environment.""" @@ -34,7 +38,7 @@ def _parse_total_status(): status_summary = os.environ['NZBPP_TOTALSTATUS'] if status_summary != 'SUCCESS': status = os.environ['NZBPP_STATUS'] - logger.info(f'Download failed with status {status}.') + log.info(f'Download failed with status {status}.') return 1 return 0 @@ -43,14 +47,14 @@ def _parse_par_status(): """Parse nzbget par status from environment.""" par_status = os.environ['NZBPP_PARSTATUS'] if par_status == '1' or par_status == '4': - logger.warning('Par-repair failed, setting status \'failed\'') + log.warning('Par-repair failed, setting status \'failed\'') return 1 return 0 def _parse_unpack_status(): if os.environ['NZBPP_UNPACKSTATUS'] == '1': - logger.warning('Unpack failed, setting status \'failed\'') + log.warning('Unpack failed, setting status \'failed\'') return 1 return 0 @@ -64,17 +68,11 @@ def _parse_health_status(): # Unpack was skipped due to nzb-file properties # or due to errors during par-check if int(os.environ['NZBPP_HEALTH']) < 1000: - logger.warning( - 'Download health is compromised and Par-check/repair disabled or no .par2 files found. Setting status \'failed\'', - ) + log.warning('Download health is compromised and Par-check/repair disabled or no .par2 files found. Setting status \'failed\'') status = 1 else: - logger.info( - 'Par-check/repair disabled or no .par2 files found, and Unpack not required. Health is ok so handle as though download successful', - ) - logger.info( - 'Please check your Par-check/repair settings for future downloads.', - ) + log.info('Par-check/repair disabled or no .par2 files found, and Unpack not required. Health is ok so handle as though download successful') + log.info('Please check your Par-check/repair settings for future downloads.') return status @@ -94,11 +92,9 @@ def check_version(): version = os.environ['NZBOP_VERSION'] # Check if the script is called from nzbget 11.0 or later if version[0:5] < '11.0': - logger.error( - f'NZBGet Version {version} is not supported. Please update NZBGet.', - ) + log.error(f'NZBGet Version {version} is not supported. Please update NZBGet.') sys.exit(nzb2media.NZBGET_POSTPROCESS_ERROR) - logger.info(f'Script triggered from NZBGet Version {version}.') + log.info(f'Script triggered from NZBGet Version {version}.') def process(): diff --git a/nzb2media/processor/sab.py b/nzb2media/processor/sab.py index e745b93a..6bee57a4 100644 --- a/nzb2media/processor/sab.py +++ b/nzb2media/processor/sab.py @@ -1,16 +1,19 @@ from __future__ import annotations +import logging import os from nzb2media.processor import nzb -# Constants +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + MINIMUM_ARGUMENTS = 8 def process_script(): version = os.environ['SAB_VERSION'] - logger.info(f'Script triggered from SABnzbd {version}.') + log.info(f'Script triggered from SABnzbd {version}.') return nzb.process( input_directory=os.environ['SAB_COMPLETE_DIR'], input_name=os.environ['SAB_FINAL_NAME'], @@ -39,7 +42,7 @@ def process(args): 8. Failure URL """ version = '0.7.17+' if len(args) > MINIMUM_ARGUMENTS else '' - logger.info(f'Script triggered from SABnzbd {version}') + log.info(f'Script triggered from SABnzbd {version}') return nzb.process( input_directory=args[1], input_name=args[2], diff --git a/nzb2media/scene_exceptions.py b/nzb2media/scene_exceptions.py index 9cc0370d..8bc7b49f 100644 --- a/nzb2media/scene_exceptions.py +++ b/nzb2media/scene_exceptions.py @@ -1,5 +1,6 @@ from __future__ import annotations +import logging import os import platform import re @@ -9,6 +10,10 @@ import subprocess import nzb2media from nzb2media.utils.files import list_media_files +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + + reverse_list = [ r'\.\d{2}e\d{2}s\.', r'\.[pi]0801\.', @@ -112,14 +117,11 @@ def rename_file(filename, newfile_path): + '.NTM' + os.path.splitext(newfile_path)[1] ) - logger.debug( - f'Replacing file name {filename} with download name {newfile_path}', - 'EXCEPTION', - ) + log.error(f'Replacing file name {filename} with download name {newfile_path}') try: os.rename(filename, newfile_path) except Exception as error: - logger.error(f'Unable to rename file due to: {error}', 'EXCEPTION') + log.error(f'Unable to rename file due to: {error}') def replace_filename(filename, dirname, name): @@ -129,20 +131,12 @@ def replace_filename(filename, dirname, name): is not None ): newname = os.path.basename(dirname).replace(' ', '.') - logger.debug( - f'Replacing file name {head} with directory name {newname}', - 'EXCEPTION', - ) + log.debug(f'Replacing file name {head} with directory name {newname}') elif media_pattern.search(name.replace(' ', '.').lower()) is not None: newname = name.replace(' ', '.') - logger.debug( - f'Replacing file name {head} with download name {newname}', - 'EXCEPTION', - ) + log.debug(f'Replacing file name {head} with download name {newname}') else: - logger.warning( - f'No name replacement determined for {head}', 'EXCEPTION', - ) + log.warning(f'No name replacement determined for {head}') newname = name newfile = newname + file_extension newfile_path = os.path.join(dirname, newfile) @@ -168,10 +162,7 @@ def reverse_filename(filename, dirname, name): else: newname = head[::-1].title() newname = newname.replace(' ', '.') - logger.debug( - f'Reversing filename {head} to {newname}', - 'EXCEPTION', - ) + log.debug(f'Reversing filename {head} to {newname}') newfile = newname + file_extension newfile_path = os.path.join(dirname, newfile) return newfile_path @@ -199,16 +190,11 @@ def rename_script(dirname): ) if os.path.isfile(dest): continue - logger.debug( - f'Renaming file {orig} to {dest}', - 'EXCEPTION', - ) + log.debug(f'Renaming file {orig} to {dest}') try: os.rename(orig, dest) except Exception as error: - logger.error( - f'Unable to rename file due to: {error}', 'EXCEPTION', - ) + log.error(f'Unable to rename file due to: {error}') def par2(dirname): @@ -230,12 +216,12 @@ def par2(dirname): bitbucket = open('NUL') else: bitbucket = open('/dev/null') - logger.info(f'Running par2 on file {parfile}.', 'PAR2') + log.info(f'Running par2 on file {parfile}.') command = [nzb2media.PAR2CMD, 'r', parfile, '*'] cmd = '' for item in command: cmd = f'{cmd} {item}' - logger.debug(f'calling command:{cmd}', 'PAR2') + log.debug(f'calling command:{cmd}') try: proc = subprocess.Popen( command, stdout=bitbucket, stderr=bitbucket, @@ -243,11 +229,9 @@ def par2(dirname): proc.communicate() result = proc.returncode except Exception: - logger.error( - f'par2 file processing for {parfile} has failed', 'PAR2', - ) + log.error(f'par2 file processing for {parfile} has failed') if result == 0: - logger.info('par2 file processing succeeded', 'PAR2') + log.info('par2 file processing succeeded') os.chdir(pwd) bitbucket.close() diff --git a/nzb2media/torrent/deluge.py b/nzb2media/torrent/deluge.py index 8eebd8e0..0325b0ef 100644 --- a/nzb2media/torrent/deluge.py +++ b/nzb2media/torrent/deluge.py @@ -1,9 +1,14 @@ from __future__ import annotations +import logging + from deluge_client import DelugeRPCClient import nzb2media +log = logging.getLogger() +log.addHandler(logging.NullHandler()) + def configure_client(): agent = 'deluge' @@ -12,11 +17,11 @@ def configure_client(): user = nzb2media.DELUGE_USER password = nzb2media.DELUGE_PASSWORD - logger.debug(f'Connecting to {agent}: http://{host}:{port}') + log.debug(f'Connecting to {agent}: http://{host}:{port}') client = DelugeRPCClient(host, port, user, password) try: client.connect() except Exception: - logger.error('Failed to connect to Deluge') + log.error('Failed to connect to Deluge') else: return client diff --git a/nzb2media/torrent/qbittorrent.py b/nzb2media/torrent/qbittorrent.py index 0aae6fb8..e60f4ac6 100644 --- a/nzb2media/torrent/qbittorrent.py +++ b/nzb2media/torrent/qbittorrent.py @@ -1,9 +1,14 @@ from __future__ import annotations +import logging + from qbittorrent import Client as qBittorrentClient import nzb2media +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def configure_client(): agent = 'qbittorrent' @@ -12,13 +17,11 @@ def configure_client(): user = nzb2media.QBITTORRENT_USER password = nzb2media.QBITTORRENT_PASSWORD - logger.debug( - f'Connecting to {agent}: http://{host}:{port}', - ) + log.debug(f'Connecting to {agent}: http://{host}:{port}') client = qBittorrentClient(f'http://{host}:{port}/') try: client.login(user, password) except Exception: - logger.error('Failed to connect to qBittorrent') + log.error('Failed to connect to qBittorrent') else: return client diff --git a/nzb2media/torrent/synology.py b/nzb2media/torrent/synology.py index 5449b805..85c75e22 100644 --- a/nzb2media/torrent/synology.py +++ b/nzb2media/torrent/synology.py @@ -1,9 +1,13 @@ from __future__ import annotations +import logging + from syno.downloadstation import DownloadStation import nzb2media +log = logging.getLogger(__name__) + def configure_client(): agent = 'synology' @@ -12,10 +16,10 @@ def configure_client(): user = nzb2media.SYNO_USER password = nzb2media.SYNO_PASSWORD - logger.debug(f'Connecting to {agent}: http://{host}:{port}') + log.debug(f'Connecting to {agent}: http://{host}:{port}') try: client = DownloadStation(host, port, user, password) except Exception: - logger.error('Failed to connect to synology') + log.error('Failed to connect to synology') else: return client diff --git a/nzb2media/torrent/transmission.py b/nzb2media/torrent/transmission.py index e377ef58..2a42b5a5 100644 --- a/nzb2media/torrent/transmission.py +++ b/nzb2media/torrent/transmission.py @@ -1,9 +1,14 @@ from __future__ import annotations +import logging + from transmissionrpc.client import Client as TransmissionClient import nzb2media +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def configure_client(): agent = 'transmission' @@ -12,10 +17,10 @@ def configure_client(): user = nzb2media.TRANSMISSION_USER password = nzb2media.TRANSMISSION_PASSWORD - logger.debug(f'Connecting to {agent}: http://{host}:{port}') + log.debug(f'Connecting to {agent}: http://{host}:{port}') try: client = TransmissionClient(host, port, user, password) except Exception: - logger.error('Failed to connect to Transmission') + log.error('Failed to connect to Transmission') else: return client diff --git a/nzb2media/torrent/utorrent.py b/nzb2media/torrent/utorrent.py index 246c0ee0..fc752157 100644 --- a/nzb2media/torrent/utorrent.py +++ b/nzb2media/torrent/utorrent.py @@ -1,9 +1,14 @@ from __future__ import annotations +import logging + from utorrent.client import UTorrentClient import nzb2media +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def configure_client(): agent = 'utorrent' @@ -11,10 +16,10 @@ def configure_client(): user = nzb2media.UTORRENT_USER password = nzb2media.UTORRENT_PASSWORD - logger.debug(f'Connecting to {agent}: {web_ui}') + log.debug(f'Connecting to {agent}: {web_ui}') try: client = UTorrentClient(web_ui, user, password) except Exception: - logger.error('Failed to connect to uTorrent') + log.error('Failed to connect to uTorrent') else: return client diff --git a/nzb2media/transcoder.py b/nzb2media/transcoder.py index a11aab74..98559dcd 100644 --- a/nzb2media/transcoder.py +++ b/nzb2media/transcoder.py @@ -2,6 +2,7 @@ from __future__ import annotations import errno import json +import logging import os import pathlib import platform @@ -16,6 +17,9 @@ from babelfish import Language import nzb2media from nzb2media.utils.paths import make_dir +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + __author__ = 'Justin' @@ -34,10 +38,7 @@ def is_video_good(video: pathlib.Path, status, require_lan=None): test_details, res = get_video_details(nzb2media.TEST_FILE) if res != 0 or test_details.get('error'): disable = True - logger.info( - 'DISABLED: ffprobe failed to analyse test file. Stopping corruption check.', - 'TRANSCODER', - ) + log.info('DISABLED: ffprobe failed to analyse test file. Stopping corruption check.') if test_details.get('streams'): vid_streams = [ item @@ -51,10 +52,7 @@ def is_video_good(video: pathlib.Path, status, require_lan=None): ] if not (len(vid_streams) > 0 and len(aud_streams) > 0): disable = True - logger.info( - 'DISABLED: ffprobe failed to analyse streams from test file. Stopping corruption check.', - 'TRANSCODER', - ) + log.info('DISABLED: ffprobe failed to analyse streams from test file. Stopping corruption check.') if disable: if status: # if the download was 'failed', assume bad. @@ -63,21 +61,15 @@ def is_video_good(video: pathlib.Path, status, require_lan=None): else: return True - logger.info( - f'Checking [{video.name}] for corruption, please stand by ...', - 'TRANSCODER', - ) + log.info(f'Checking [{video.name}] for corruption, please stand by ...') video_details, result = get_video_details(video) if result != 0: - logger.error(f'FAILED: [{video.name}] is corrupted!', 'TRANSCODER') + log.error(f'FAILED: [{video.name}] is corrupted!') return False if video_details.get('error'): error_details = video_details.get('error') - logger.info( - f'FAILED: [{video.name}] returned error [{error_details}].', - 'TRANSCODER', - ) + log.info(f'FAILED: [{video.name}] returned error [{error_details}].') return False if video_details.get('streams'): video_streams = [ @@ -101,15 +93,10 @@ def is_video_good(video: pathlib.Path, status, require_lan=None): else: valid_audio = audio_streams if len(video_streams) > 0 and len(valid_audio) > 0: - logger.info( - f'SUCCESS: [{video.name}] has no corruption.', 'TRANSCODER', - ) + log.info(f'SUCCESS: [{video.name}] has no corruption.') return True else: - logger.info( - f'FAILED: [{video.name}] has {len(video_streams)} video streams and {len(audio_streams)} audio streams. Assume corruption.', - 'TRANSCODER', - ) + log.info(f'FAILED: [{video.name}] has {len(video_streams)} video streams and {len(audio_streams)} audio streams. Assume corruption.') return False @@ -124,7 +111,7 @@ def zip_out(file, img, bitbucket): cmd, stdout=subprocess.PIPE, stderr=bitbucket, ) except Exception: - logger.error(f'Extracting [{file}] has failed', 'TRANSCODER') + log.error(f'Extracting [{file}] has failed') return procin @@ -186,7 +173,7 @@ def get_video_details(videofile, img=None, bitbucket=None): result = proc.returncode video_details = json.loads(out.decode()) except Exception: - logger.error(f'Checking [{file}] has failed', 'TRANSCODER') + log.error(f'Checking [{file}] has failed') return video_details, result @@ -781,9 +768,9 @@ def extract_subs(file, newfile_path, bitbucket): item for item in video_details['streams'] if item['codec_type'] == 'subtitle' - and item['tags']['language'] in nzb2media.SLANGUAGES - and item['codec_name'] != 'hdmv_pgs_subtitle' - and item['codec_name'] != 'pgssub' + and item['tags']['language'] in nzb2media.SLANGUAGES + and item['codec_name'] != 'hdmv_pgs_subtitle' + and item['codec_name'] != 'pgssub' ] except Exception: sub_streams = [ @@ -823,7 +810,7 @@ def extract_subs(file, newfile_path, bitbucket): if platform.system() != 'Windows': command = nzb2media.NICENESS + command - logger.info(f'Extracting {lan} subtitle from: {file}') + log.info(f'Extracting {lan} subtitle from: {file}') print_cmd(command) result = 1 # set result to failed in case call fails. try: @@ -833,16 +820,16 @@ def extract_subs(file, newfile_path, bitbucket): out, err = proc.communicate() result = proc.returncode except Exception: - logger.error('Extracting subtitle has failed') + log.error('Extracting subtitle has failed') if result == 0: try: shutil.copymode(file, output_file) except Exception: pass - logger.info(f'Extracting {lan} subtitle from {file} has succeeded') + log.info(f'Extracting {lan} subtitle from {file} has succeeded') else: - logger.error('Extracting subtitles has failed') + log.error('Extracting subtitles has failed') def process_list(it, new_dir, bitbucket): @@ -858,14 +845,14 @@ def process_list(it, new_dir, bitbucket): ext in ['.iso', '.bin', '.img'] and ext not in nzb2media.IGNOREEXTENSIONS ): - logger.debug(f'Attempting to rip disk image: {item}', 'TRANSCODER') + log.debug(f'Attempting to rip disk image: {item}') new_list.extend(rip_iso(item, new_dir, bitbucket)) rem_list.append(item) elif ( re.match('.+VTS_[0-9][0-9]_[0-9].[Vv][Oo][Bb]', item) and '.vob' not in nzb2media.IGNOREEXTENSIONS ): - logger.debug(f'Found VIDEO_TS image file: {item}', 'TRANSCODER') + log.debug(f'Found VIDEO_TS image file: {item}') if not vts_path: try: vts_path = re.match('(.+VIDEO_TS)', item).groups()[0] @@ -876,7 +863,7 @@ def process_list(it, new_dir, bitbucket): re.match('.+BDMV[/\\]SOURCE[/\\][0-9]+[0-9].[Mm][Tt][Ss]', item) and '.mts' not in nzb2media.IGNOREEXTENSIONS ): - logger.debug(f'Found MTS image file: {item}', 'TRANSCODER') + log.debug(f'Found MTS image file: {item}') if not mts_path: try: mts_path = re.match('(.+BDMV[/\\]SOURCE)', item).groups()[ @@ -912,17 +899,11 @@ def process_list(it, new_dir, bitbucket): it.extend(new_list) for item in rem_list: it.remove(item) - logger.debug( - f'Successfully extracted .vob file {new_list[0]} from disk image', - 'TRANSCODER', - ) + log.debug(f'Successfully extracted .vob file {new_list[0]} from disk image') elif new_list and not success: new_list = [] rem_list = [] - logger.error( - 'Failed extracting .vob files from disk image. Stopping transcoding.', - 'TRANSCODER', - ) + log.error('Failed extracting .vob files from disk image. Stopping transcoding.') return it, rem_list, new_list, success @@ -930,10 +911,7 @@ def mount_iso( item, new_dir, bitbucket, ): # Currently only supports Linux Mount when permissions allow. if platform.system() == 'Windows': - logger.error( - f'No mounting options available under Windows for image file {item}', - 'TRANSCODER', - ) + log.error(f'No mounting options available under Windows for image file {item}') return [] mount_point = os.path.join(os.path.dirname(os.path.abspath(item)), 'temp') make_dir(mount_point) @@ -951,9 +929,7 @@ def mount_iso( re.match('.+VTS_[0-9][0-9]_[0-9].[Vv][Oo][Bb]', full_path) and '.vob' not in nzb2media.IGNOREEXTENSIONS ): - logger.debug( - f'Found VIDEO_TS image file: {full_path}', 'TRANSCODER', - ) + log.debug(f'Found VIDEO_TS image file: {full_path}') try: vts_path = re.match('(.+VIDEO_TS)', full_path).groups()[0] except Exception: @@ -963,9 +939,7 @@ def mount_iso( re.match('.+BDMV[/\\]STREAM[/\\][0-9]+[0-9].[Mm]', full_path) and '.mts' not in nzb2media.IGNOREEXTENSIONS ): - logger.debug( - f'Found MTS image file: {full_path}', 'TRANSCODER', - ) + log.debug(f'Found MTS image file: {full_path}') try: mts_path = re.match( '(.+BDMV[/\\]STREAM)', full_path, @@ -973,10 +947,7 @@ def mount_iso( except Exception: mts_path = os.path.split(full_path)[0] return combine_mts(mts_path) - logger.error( - f'No VIDEO_TS or BDMV/SOURCE folder found in image file {mount_point}', - 'TRANSCODER', - ) + log.error(f'No VIDEO_TS or BDMV/SOURCE folder found in image file {mount_point}') return ['failure'] # If we got here, nothing matched our criteria @@ -985,27 +956,18 @@ def rip_iso(item, new_dir, bitbucket): failure_dir = 'failure' # Mount the ISO in your OS and call combineVTS. if not nzb2media.SEVENZIP: - logger.debug( - f'No 7zip installed. Attempting to mount image file {item}', - 'TRANSCODER', - ) + log.debug(f'No 7zip installed. Attempting to mount image file {item}') try: new_files = mount_iso( item, new_dir, bitbucket, ) # Currently only works for Linux. except Exception: - logger.error( - f'Failed to mount and extract from image file {item}', - 'TRANSCODER', - ) + log.error(f'Failed to mount and extract from image file {item}') new_files = [failure_dir] return new_files cmd = [nzb2media.SEVENZIP, 'l', item] try: - logger.debug( - f'Attempting to extract .vob or .mts from image file {item}', - 'TRANSCODER', - ) + log.debug(f'Attempting to extract .vob or .mts from image file {item}') print_cmd(cmd) proc = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=bitbucket) out, err = proc.communicate() @@ -1077,13 +1039,10 @@ def rip_iso(item, new_dir, bitbucket): name = os.path.splitext(os.path.split(item)[1])[0] new_files.append({item: {'name': name, 'files': combined}}) if not new_files: - logger.error( - f'No VIDEO_TS or BDMV/SOURCE folder found in image file. Attempting to mount and scan {item}', - 'TRANSCODER', - ) + log.error(f'No VIDEO_TS or BDMV/SOURCE folder found in image file. Attempting to mount and scan {item}') new_files = mount_iso(item, new_dir, bitbucket) except Exception: - logger.error(f'Failed to extract from image file {item}', 'TRANSCODER') + log.error(f'Failed to extract from image file {item}') new_files = [failure_dir] return new_files @@ -1183,13 +1142,13 @@ def print_cmd(command): cmd = '' for item in command: cmd = f'{cmd} {item}' - logger.debug(f'calling command:{cmd}') + log.debug(f'calling command:{cmd}') def transcode_directory(dir_name): if not nzb2media.FFMPEG: return 1, dir_name - logger.info('Checking for files to be transcoded') + log.info('Checking for files to be transcoded') final_result = 0 # initialize as successful if nzb2media.OUTPUTVIDEOPATH: new_dir = nzb2media.OUTPUTVIDEOPATH @@ -1229,15 +1188,15 @@ def transcode_directory(dir_name): try: # Try to remove the file that we're transcoding to just in case. (ffmpeg will return an error if it already exists for some reason) os.remove(newfile_path) - except OSError as e: + except OSError as error: if ( - e.errno != errno.ENOENT + error.errno != errno.ENOENT ): # Ignore the error if it's just telling us that the file doesn't exist - logger.debug(f'Error when removing transcoding target: {e}') - except Exception as e: - logger.debug(f'Error when removing transcoding target: {e}') + log.debug(f'Error when removing transcoding target: {error}') + except Exception as error: + log.debug(f'Error when removing transcoding target: {error}') - logger.info(f'Transcoding video: {newfile_path}') + log.info(f'Transcoding video: {newfile_path}') print_cmd(command) result = 1 # set result to failed in case call fails. try: @@ -1256,15 +1215,15 @@ def transcode_directory(dir_name): for vob in data['files']: procin = zip_out(vob, img, bitbucket) if procin: - logger.debug(f'Feeding in file: {vob} to Transcoder') + log.debug(f'Feeding in file: {vob} to Transcoder') shutil.copyfileobj(procin.stdout, proc.stdin) procin.stdout.close() out, err = proc.communicate() if err: - logger.error(f'Transcoder returned:{err} has failed') + log.error(f'Transcoder returned:{err} has failed') result = proc.returncode except Exception: - logger.error(f'Transcoding of video {newfile_path} has failed') + log.error(f'Transcoding of video {newfile_path} has failed') if nzb2media.SUBSDIR and result == 0 and isinstance(file, str): for sub in get_subs(file): @@ -1282,7 +1241,7 @@ def transcode_directory(dir_name): shutil.copymode(file, newfile_path) except Exception: pass - logger.info(f'Transcoding of video to {newfile_path} succeeded') + log.info(f'Transcoding of video to {newfile_path} succeeded') if os.path.isfile(newfile_path) and ( file in new_list or not nzb2media.DUPLICATE ): @@ -1291,9 +1250,7 @@ def transcode_directory(dir_name): except Exception: pass else: - logger.error( - f'Transcoding of video to {newfile_path} failed with result {result}', - ) + log.error(f'Transcoding of video to {newfile_path} failed with result {result}') # this will be 0 (successful) it all are successful, else will return a positive integer for failure. final_result = final_result + result if nzb2media.MOUNTED: # In case we mounted an .iso file, unmount here. diff --git a/nzb2media/user_scripts.py b/nzb2media/user_scripts.py index c8cd940d..ddb057a0 100644 --- a/nzb2media/user_scripts.py +++ b/nzb2media/user_scripts.py @@ -1,5 +1,6 @@ from __future__ import annotations +import logging import os from subprocess import Popen @@ -10,6 +11,9 @@ from nzb2media.plugins.subtitles import import_subs from nzb2media.utils.files import list_media_files from nzb2media.utils.paths import remove_dir +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def external_script(output_destination, torrent_name, torrent_label, settings): final_result = 0 # start at 0. @@ -23,9 +27,7 @@ def external_script(output_destination, torrent_name, torrent_label, settings): nzb2media.USER_SCRIPT_MEDIAEXTENSIONS.lower().split(',') ) except Exception: - logger.error( - 'user_script_mediaExtensions could not be set', 'USERSCRIPT', - ) + log.error('user_script_mediaExtensions could not be set') nzb2media.USER_SCRIPT_MEDIAEXTENSIONS = [] nzb2media.USER_SCRIPT = settings.get('user_script_path', '') @@ -42,7 +44,7 @@ def external_script(output_destination, torrent_name, torrent_label, settings): if isinstance(nzb2media.USER_SCRIPT_PARAM, str): nzb2media.USER_SCRIPT_PARAM = nzb2media.USER_SCRIPT_PARAM.split(',') except Exception: - logger.error('user_script_params could not be set', 'USERSCRIPT') + log.error('user_script_params could not be set') nzb2media.USER_SCRIPT_PARAM = [] nzb2media.USER_SCRIPT_SUCCESSCODES = settings.get('user_script_successCodes', 0) @@ -52,7 +54,7 @@ def external_script(output_destination, torrent_name, torrent_label, settings): nzb2media.USER_SCRIPT_SUCCESSCODES.split(',') ) except Exception: - logger.error('user_script_successCodes could not be set', 'USERSCRIPT') + log.error('user_script_successCodes could not be set') nzb2media.USER_SCRIPT_SUCCESSCODES = 0 nzb2media.USER_SCRIPT_CLEAN = int(settings.get('user_script_clean', 1)) @@ -69,10 +71,7 @@ def external_script(output_destination, torrent_name, torrent_label, settings): if transcoder.is_video_good(video, 0): import_subs(video) else: - logger.info( - f'Corrupt video file found {video}. Deleting.', - 'USERSCRIPT', - ) + log.info(f'Corrupt video file found {video}. Deleting.') os.unlink(video) for dirpath, _, filenames in os.walk(output_destination): @@ -80,10 +79,7 @@ def external_script(output_destination, torrent_name, torrent_label, settings): file_path = nzb2media.os.path.join(dirpath, file) file_name, file_extension = os.path.splitext(file) - logger.debug( - f'Checking file {file} to see if this should be processed.', - 'USERSCRIPT', - ) + log.debug(f'Checking file {file} to see if this should be processed.') if ( file_extension in nzb2media.USER_SCRIPT_MEDIAEXTENSIONS @@ -120,31 +116,21 @@ def external_script(output_destination, torrent_name, torrent_label, settings): cmd = '' for item in command: cmd = f'{cmd} {item}' - logger.info( - f'Running script {cmd} on file {file_path}.', 'USERSCRIPT', - ) + log.info(f'Running script {cmd} on file {file_path}.') try: p = Popen(command) res = p.wait() if ( str(res) in nzb2media.USER_SCRIPT_SUCCESSCODES ): # Linux returns 0 for successful. - logger.info(f'UserScript {command[0]} was successfull') + log.info(f'UserScript {command[0]} was successfull') result = 0 else: - logger.error( - f'UserScript {command[0]} has failed with return code: {res}', - 'USERSCRIPT', - ) - logger.info( - f'If the UserScript completed successfully you should add {res} to the user_script_successCodes', - 'USERSCRIPT', - ) + log.error(f'UserScript {command[0]} has failed with return code: {res}') + log.info(f'If the UserScript completed successfully you should add {res} to the user_script_successCodes') result = int(1) except Exception: - logger.error( - f'UserScript {command[0]} has failed', 'USERSCRIPT', - ) + log.error(f'UserScript {command[0]} has failed') result = int(1) final_result += result @@ -164,14 +150,10 @@ def external_script(output_destination, torrent_name, torrent_label, settings): and num_files_new == 0 and final_result == 0 ): - logger.info( - f'All files have been processed. Cleaning outputDirectory {output_destination}', - ) + log.info(f'All files have been processed. Cleaning outputDirectory {output_destination}') remove_dir(output_destination) elif nzb2media.USER_SCRIPT_CLEAN == int(1) and num_files_new != 0: - logger.info( - f'{num_files} files were processed, but {num_files_new} still remain. outputDirectory will not be cleaned.', - ) + log.info(f'{num_files} files were processed, but {num_files_new} still remain. outputDirectory will not be cleaned.') return ProcessResult( status_code=final_result, message='User Script Completed', diff --git a/nzb2media/utils/common.py b/nzb2media/utils/common.py index 4241c3bb..8257d8a6 100644 --- a/nzb2media/utils/common.py +++ b/nzb2media/utils/common.py @@ -1,5 +1,6 @@ from __future__ import annotations +import logging import os.path import urllib.parse @@ -9,6 +10,9 @@ from nzb2media.utils.files import move_file from nzb2media.utils.paths import clean_directory from nzb2media.utils.paths import flatten_dir +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def flatten(output_destination): return flatten_dir( @@ -32,7 +36,7 @@ def clean_dir(path, section, subsection): def process_dir(path, link): folders = [] - logger.info(f'Searching {path} for mediafiles to post-process ...') + log.info(f'Searching {path} for mediafiles to post-process ...') dir_contents = os.listdir(path) # search for single files and move them into their own folder for post-processing @@ -54,16 +58,12 @@ def process_dir(path, link): # Generate a list of media files mediafiles = (item for item in filepaths if os.path.isfile(item)) - if any(sync_files): - logger.info('') - else: + if not any(sync_files): for mediafile in mediafiles: try: move_file(mediafile, path, link) - except Exception as e: - logger.error( - f'Failed to move {os.path.split(mediafile)[1]} to its own directory: {e}', - ) + except Exception as error: + log.error(f'Failed to move {os.path.split(mediafile)[1]} to its own directory: {error}') # removeEmptyFolders(path, removeRoot=False) @@ -98,25 +98,19 @@ def get_dirs(section, subsection, link='hard'): try: to_return.extend(process_dir(directory, link)) - except Exception as e: - logger.error( - f'Failed to add directories from {watch_directory} for post-processing: {e}', - ) + except Exception as error: + log.error(f'Failed to add directories from {watch_directory} for post-processing: {error}') if nzb2media.USE_LINK == 'move': try: output_directory = os.path.join(nzb2media.OUTPUT_DIRECTORY, subsection) if os.path.exists(output_directory): to_return.extend(process_dir(output_directory, link)) - except Exception as e: - logger.error( - f'Failed to add directories from {nzb2media.OUTPUT_DIRECTORY} for post-processing: {e}', - ) + except Exception as error: + log.error(f'Failed to add directories from {nzb2media.OUTPUT_DIRECTORY} for post-processing: {error}') if not to_return: - logger.debug( - f'No directories identified in {section}:{subsection} for post-processing', - ) + log.debug(f'No directories identified in {section}:{subsection} for post-processing') return list(set(to_return)) diff --git a/nzb2media/utils/download_info.py b/nzb2media/utils/download_info.py index c3510e00..aa44a142 100644 --- a/nzb2media/utils/download_info.py +++ b/nzb2media/utils/download_info.py @@ -1,23 +1,25 @@ from __future__ import annotations import datetime +import logging from nzb2media import main_db +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + database = main_db.DBConnection() def update_download_info_status(input_name, status): - msg = 'Updating DB download status of {0} to {1}' + log.debug(f'Updating DB download status of {input_name} to {status}') action = 'UPDATE downloads SET status=?, last_update=? WHERE input_name=?' args = [status, datetime.date.today().toordinal(), input_name] - logger.db(msg.format(input_name, status)) database.action(action, args) def get_download_info(input_name, status): - msg = 'Getting download info for {0} from the DB' + log.debug(f'Getting download info for {input_name} from the DB') action = 'SELECT * FROM downloads WHERE input_name=? AND status=?' args = [input_name, status] - logger.db(msg.format(input_name)) return database.select(action, args) diff --git a/nzb2media/utils/encoding.py b/nzb2media/utils/encoding.py index 9bd48b83..4ee4b04e 100644 --- a/nzb2media/utils/encoding.py +++ b/nzb2media/utils/encoding.py @@ -1,9 +1,13 @@ from __future__ import annotations +import logging import os import nzb2media +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def char_replace(name_in): # Special character hex range: @@ -69,7 +73,7 @@ def convert_to_ascii(input_name, dir_name): encoded, base2 = char_replace(base) if encoded: dir_name = os.path.join(directory, base2) - logger.info(f'Renaming directory to: {base2}.', 'ENCODER') + log.info(f'Renaming directory to: {base2}.') os.rename(os.path.join(directory, base), dir_name) if 'NZBOP_SCRIPTDIR' in os.environ: print(f'[NZB] DIRECTORY={dir_name}') @@ -78,9 +82,7 @@ def convert_to_ascii(input_name, dir_name): for subdirname in dirnames: encoded, subdirname2 = char_replace(subdirname) if encoded: - logger.info( - f'Renaming directory to: {subdirname2}.', 'ENCODER', - ) + log.info(f'Renaming directory to: {subdirname2}.') os.rename( os.path.join(dirname, subdirname), os.path.join(dirname, subdirname2), @@ -90,7 +92,7 @@ def convert_to_ascii(input_name, dir_name): for filename in filenames: encoded, filename2 = char_replace(filename) if encoded: - logger.info(f'Renaming file to: {filename2}.', 'ENCODER') + log.info(f'Renaming file to: {filename2}.') os.rename( os.path.join(dirname, filename), os.path.join(dirname, filename2), diff --git a/nzb2media/utils/files.py b/nzb2media/utils/files.py index 2768b07d..5bf82255 100644 --- a/nzb2media/utils/files.py +++ b/nzb2media/utils/files.py @@ -1,5 +1,6 @@ from __future__ import annotations +import logging import os import re import shutil @@ -17,11 +18,12 @@ from nzb2media.utils.naming import sanitize_name from nzb2media.utils.paths import get_dir_size from nzb2media.utils.paths import make_dir +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def move_file(filename, path, link): - logger.debug( - f'Found file {os.path.split(filename)[1]} in root directory {path}.', - ) + log.debug(f'Found file {os.path.split(filename)[1]} in root directory {path}.') new_path = None file_ext = os.path.splitext(filename)[1] try: @@ -46,10 +48,8 @@ def move_file(filename, path, link): title = os.path.splitext(os.path.basename(filename))[0] new_path = os.path.join(path, sanitize_name(title)) - except Exception as e: - logger.error( - f'Exception parsing name for media file: {os.path.split(filename)[1]}: {e}', - ) + except Exception as error: + log.error(f'Exception parsing name for media file: {os.path.split(filename)[1]}: {error}') if not new_path: title = os.path.splitext(os.path.basename(filename))[0] @@ -94,9 +94,7 @@ def is_min_size(input_name, min_size): try: input_size = get_dir_size(os.path.dirname(input_name)) except Exception: - logger.error( - f'Failed to get file size for {input_name}', 'MINSIZE', - ) + log.error(f'Failed to get file size for {input_name}') return True # Ignore files under a certain size @@ -170,9 +168,7 @@ def list_media_files( if delete_ignored == 1: try: os.unlink(path) - logger.debug( - f'Ignored file {cur_file} has been removed ...', - ) + log.debug(f'Ignored file {cur_file} has been removed ...') except Exception: pass else: @@ -207,9 +203,7 @@ def list_media_files( if delete_ignored == 1: try: os.unlink(full_cur_file) - logger.debug( - f'Ignored file {cur_file} has been removed ...', - ) + log.debug(f'Ignored file {cur_file} has been removed ...') except Exception: pass continue @@ -239,7 +233,7 @@ def extract_files(src, dst=None, keep_archive=None): extracted_folder.append(dir_path) extracted_archive.append(archive_name) except Exception: - logger.error(f'Extraction failed for: {full_file_name}') + log.error(f'Extraction failed for: {full_file_name}') for folder in extracted_folder: for inputFile in list_media_files( @@ -250,52 +244,34 @@ def extract_files(src, dst=None, keep_archive=None): archive_name = re.sub(r'part[0-9]+', '', archive_name) if archive_name not in extracted_archive or keep_archive: continue # don't remove if we haven't extracted this archive, or if we want to preserve them. - logger.info( - f'Removing extracted archive {full_file_name} from folder {folder} ...', - ) + log.info(f'Removing extracted archive {full_file_name} from folder {folder} ...') try: if not os.access(inputFile, os.W_OK): os.chmod(inputFile, stat.S_IWUSR) os.remove(inputFile) time.sleep(1) - except Exception as e: - logger.error(f'Unable to remove file {inputFile} due to: {e}') + except Exception as error: + log.error(f'Unable to remove file {inputFile} due to: {error}') def backup_versioned_file(old_file, version): num_tries = 0 - new_file = f'{old_file}.v{version}' - while not os.path.isfile(new_file): if not os.path.isfile(old_file): - logger.log( - f'Not creating backup, {old_file} doesn\'t exist', logger.DEBUG, - ) + log.debug(f'Not creating backup, {old_file} doesn\'t exist') break - try: - logger.log( - f'Trying to back up {old_file} to {new_file}', - logger.DEBUG, - ) + log.debug(f'Trying to back up {old_file} to {new_file}') shutil.copy(old_file, new_file) - logger.log('Backup done', logger.DEBUG) + log.debug('Backup done') break except Exception as error: - logger.log( - f'Error while trying to back up {old_file} to {new_file} : {error}', - logger.WARNING, - ) + log.warning(f'Error while trying to back up {old_file} to {new_file} : {error}') num_tries += 1 time.sleep(1) - logger.log('Trying again.', logger.DEBUG) - + log.debug('Trying again.') if num_tries >= 10: - logger.log( - f'Unable to back up {old_file} to {new_file} please do it manually.', - logger.ERROR, - ) + log.error(f'Unable to back up {old_file} to {new_file} please do it manually.') return False - return True diff --git a/nzb2media/utils/identification.py b/nzb2media/utils/identification.py index c531b500..1ec4282d 100644 --- a/nzb2media/utils/identification.py +++ b/nzb2media/utils/identification.py @@ -1,5 +1,6 @@ from __future__ import annotations +import logging import os import re @@ -8,25 +9,27 @@ import requests from nzb2media.utils.naming import sanitize_name +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def find_imdbid(dir_name, input_name, omdb_api_key): imdbid = None - - logger.info(f'Attemping imdbID lookup for {input_name}') + log.info(f'Attemping imdbID lookup for {input_name}') # find imdbid in dirName - logger.info('Searching folder and file names for imdbID ...') + log.info('Searching folder and file names for imdbID ...') m = re.search(r'\b(tt\d{7,8})\b', dir_name + input_name) if m: imdbid = m.group(1) - logger.info(f'Found imdbID [{imdbid}]') + log.info(f'Found imdbID [{imdbid}]') return imdbid if os.path.isdir(dir_name): for file in os.listdir(dir_name): m = re.search(r'\b(tt\d{7,8})\b', file) if m: imdbid = m.group(1) - logger.info(f'Found imdbID [{imdbid}] via file name') + log.info(f'Found imdbID [{imdbid}] via file name') return imdbid if 'NZBPR__DNZB_MOREINFO' in os.environ: dnzb_more_info = os.environ.get('NZBPR__DNZB_MOREINFO', '') @@ -37,9 +40,9 @@ def find_imdbid(dir_name, input_name, omdb_api_key): m = regex.match(dnzb_more_info) if m: imdbid = m.group(1) - logger.info(f'Found imdbID [{imdbid}] from DNZB-MoreInfo') + log.info(f'Found imdbID [{imdbid}] from DNZB-MoreInfo') return imdbid - logger.info('Searching IMDB for imdbID ...') + log.info('Searching IMDB for imdbID ...') try: guess = guessit.guessit(input_name) except Exception: @@ -58,12 +61,10 @@ def find_imdbid(dir_name, input_name, omdb_api_key): url = 'http://www.omdbapi.com' if not omdb_api_key: - logger.info( - 'Unable to determine imdbID: No api key provided for omdbapi.com.', - ) + log.info('Unable to determine imdbID: No api key provided for omdbapi.com.') return - logger.debug(f'Opening URL: {url}') + log.debug(f'Opening URL: {url}') try: r = requests.get( @@ -73,24 +74,24 @@ def find_imdbid(dir_name, input_name, omdb_api_key): timeout=(60, 300), ) except requests.ConnectionError: - logger.error(f'Unable to open URL {url}') + log.error(f'Unable to open URL {url}') return try: results = r.json() except Exception: - logger.error('No json data returned from omdbapi.com') + log.error('No json data returned from omdbapi.com') try: imdbid = results['imdbID'] except Exception: - logger.error('No imdbID returned from omdbapi.com') + log.error('No imdbID returned from omdbapi.com') if imdbid: - logger.info(f'Found imdbID [{imdbid}]') + log.info(f'Found imdbID [{imdbid}]') return imdbid - logger.warning(f'Unable to find a imdbID for {input_name}') + log.warning(f'Unable to find a imdbID for {input_name}') return imdbid @@ -105,78 +106,59 @@ def category_search( pathlist = os.path.normpath(input_directory).split(os.sep) if input_category and input_category in pathlist: - logger.debug( - f'SEARCH: Found the Category: {input_category} in directory structure', - ) + log.debug(f'SEARCH: Found the Category: {input_category} in directory structure') elif input_category: - logger.debug( - f'SEARCH: Could not find the category: {input_category} in the directory structure', - ) + log.debug(f'SEARCH: Could not find the category: {input_category} in the directory structure') else: try: input_category = list(set(pathlist) & set(categories))[ -1 ] # assume last match is most relevant category. - logger.debug( - f'SEARCH: Found Category: {input_category} in directory structure', - ) + log.debug(f'SEARCH: Found Category: {input_category} in directory structure') except IndexError: input_category = '' - logger.debug( - 'SEARCH: Could not find a category in the directory structure', - ) + log.debug('SEARCH: Could not find a category in the directory structure') if not os.path.isdir(input_directory) and os.path.isfile( input_directory, ): # If the input directory is a file if not input_name: input_name = os.path.split(os.path.normpath(input_directory))[1] return input_directory, input_name, input_category, root - if input_category and os.path.isdir( os.path.join(input_directory, input_category), ): - logger.info( - f'SEARCH: Found category directory {input_category} in input directory directory {input_directory}', - ) + log.info(f'SEARCH: Found category directory {input_category} in input directory directory {input_directory}') input_directory = os.path.join(input_directory, input_category) - logger.info(f'SEARCH: Setting input_directory to {input_directory}') + log.info(f'SEARCH: Setting input_directory to {input_directory}') if input_name and os.path.isdir(os.path.join(input_directory, input_name)): - logger.info( - f'SEARCH: Found torrent directory {input_name} in input directory directory {input_directory}', - ) + log.info(f'SEARCH: Found torrent directory {input_name} in input directory directory {input_directory}') input_directory = os.path.join(input_directory, input_name) - logger.info(f'SEARCH: Setting input_directory to {input_directory}') + log.info(f'SEARCH: Setting input_directory to {input_directory}') tordir = True elif input_name and os.path.isdir( os.path.join(input_directory, sanitize_name(input_name)), ): - logger.info( - f'SEARCH: Found torrent directory {sanitize_name(input_name)} in input directory directory {input_directory}', - ) + log.info(f'SEARCH: Found torrent directory {sanitize_name(input_name)} in input directory directory {input_directory}') input_directory = os.path.join( input_directory, sanitize_name(input_name), ) - logger.info(f'SEARCH: Setting input_directory to {input_directory}') + log.info(f'SEARCH: Setting input_directory to {input_directory}') tordir = True elif input_name and os.path.isfile( os.path.join(input_directory, input_name), ): - logger.info( - f'SEARCH: Found torrent file {input_name} in input directory directory {input_directory}', - ) + log.info(f'SEARCH: Found torrent file {input_name} in input directory directory {input_directory}') input_directory = os.path.join(input_directory, input_name) - logger.info(f'SEARCH: Setting input_directory to {input_directory}') + log.info(f'SEARCH: Setting input_directory to {input_directory}') tordir = True elif input_name and os.path.isfile( os.path.join(input_directory, sanitize_name(input_name)), ): - logger.info( - f'SEARCH: Found torrent file {sanitize_name(input_name)} in input directory directory {input_directory}', - ) + log.info(f'SEARCH: Found torrent file {sanitize_name(input_name)} in input directory directory {input_directory}') input_directory = os.path.join( input_directory, sanitize_name(input_name), ) - logger.info(f'SEARCH: Setting input_directory to {input_directory}') + log.info(f'SEARCH: Setting input_directory to {input_directory}') tordir = True elif input_name and os.path.isdir(input_directory): for file in os.listdir(input_directory): @@ -184,13 +166,9 @@ def category_search( input_name, sanitize_name(input_name), ]: - logger.info( - f'SEARCH: Found torrent file {file} in input directory directory {input_directory}', - ) + log.info(f'SEARCH: Found torrent file {file} in input directory directory {input_directory}') input_directory = os.path.join(input_directory, file) - logger.info( - f'SEARCH: Setting input_directory to {input_directory}', - ) + log.info(f'SEARCH: Setting input_directory to {input_directory}') input_name = file tordir = True break @@ -209,9 +187,7 @@ def category_search( index = pathlist.index(input_category) if index + 1 < len(pathlist): tordir = True - logger.info( - f'SEARCH: Found a unique directory {pathlist[index + 1]} in the category directory', - ) + log.info(f'SEARCH: Found a unique directory {pathlist[index + 1]} in the category directory') if not input_name: input_name = pathlist[index + 1] except ValueError: @@ -219,9 +195,7 @@ def category_search( if input_name and not tordir: if input_name in pathlist or sanitize_name(input_name) in pathlist: - logger.info( - f'SEARCH: Found torrent directory {input_name} in the directory structure', - ) + log.info(f'SEARCH: Found torrent directory {input_name} in the directory structure') tordir = True else: root = 1 @@ -229,11 +203,7 @@ def category_search( root = 2 if root > 0: - logger.info( - 'SEARCH: Could not find a unique directory for this download. Assume a common directory.', - ) - logger.info( - 'SEARCH: We will try and determine which files to process, individually', - ) + log.info('SEARCH: Could not find a unique directory for this download. Assume a common directory.') + log.info('SEARCH: We will try and determine which files to process, individually') return input_directory, input_name, input_category, root diff --git a/nzb2media/utils/links.py b/nzb2media/utils/links.py index 75e288ed..5d05d8e7 100644 --- a/nzb2media/utils/links.py +++ b/nzb2media/utils/links.py @@ -1,5 +1,6 @@ from __future__ import annotations +import logging import os import shutil @@ -7,6 +8,9 @@ import linktastic from nzb2media.utils.paths import make_dir +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + try: from jaraco.windows.filesystem import islink, readlink except ImportError: @@ -18,73 +22,55 @@ except ImportError: def copy_link(src, target_link, use_link): - logger.info(f'MEDIAFILE: [{os.path.basename(target_link)}]', 'COPYLINK') - logger.info(f'SOURCE FOLDER: [{os.path.dirname(src)}]', 'COPYLINK') - logger.info(f'TARGET FOLDER: [{os.path.dirname(target_link)}]', 'COPYLINK') + log.info(f'MEDIAFILE: [{os.path.basename(target_link)}]') + log.info(f'SOURCE FOLDER: [{os.path.dirname(src)}]') + log.info(f'TARGET FOLDER: [{os.path.dirname(target_link)}]') if src != target_link and os.path.exists(target_link): - logger.info( - 'MEDIAFILE already exists in the TARGET folder, skipping ...', - 'COPYLINK', - ) + log.info('MEDIAFILE already exists in the TARGET folder, skipping ...') return True elif ( src == target_link and os.path.isfile(target_link) and os.path.isfile(src) ): - logger.info( - 'SOURCE AND TARGET files are the same, skipping ...', 'COPYLINK', - ) + log.info('SOURCE AND TARGET files are the same, skipping ...') return True elif src == os.path.dirname(target_link): - logger.info( - 'SOURCE AND TARGET folders are the same, skipping ...', 'COPYLINK', - ) + log.info('SOURCE AND TARGET folders are the same, skipping ...') return True make_dir(os.path.dirname(target_link)) try: if use_link == 'dir': - logger.info( - 'Directory linking SOURCE FOLDER -> TARGET FOLDER', 'COPYLINK', - ) + log.info('Directory linking SOURCE FOLDER -> TARGET FOLDER') linktastic.dirlink(src, target_link) return True if use_link == 'junction': - logger.info( - 'Directory junction linking SOURCE FOLDER -> TARGET FOLDER', - 'COPYLINK', - ) + log.info('Directory junction linking SOURCE FOLDER -> TARGET FOLDER') linktastic.dirlink(src, target_link) return True elif use_link == 'hard': - logger.info( - 'Hard linking SOURCE MEDIAFILE -> TARGET FOLDER', 'COPYLINK', - ) + log.info('Hard linking SOURCE MEDIAFILE -> TARGET FOLDER') linktastic.link(src, target_link) return True elif use_link == 'sym': - logger.info( - 'Sym linking SOURCE MEDIAFILE -> TARGET FOLDER', 'COPYLINK', - ) + log.info('Sym linking SOURCE MEDIAFILE -> TARGET FOLDER') linktastic.symlink(src, target_link) return True elif use_link == 'move-sym': - logger.info( - 'Sym linking SOURCE MEDIAFILE -> TARGET FOLDER', 'COPYLINK', - ) + log.info('Sym linking SOURCE MEDIAFILE -> TARGET FOLDER') shutil.move(src, target_link) linktastic.symlink(target_link, src) return True elif use_link == 'move': - logger.info('Moving SOURCE MEDIAFILE -> TARGET FOLDER', 'COPYLINK') + log.info('Moving SOURCE MEDIAFILE -> TARGET FOLDER') shutil.move(src, target_link) return True - except Exception as e: - logger.warning(f'Error: {e}, copying instead ... ', 'COPYLINK') + except Exception as error: + log.warning(f'Error: {error}, copying instead ... ') - logger.info('Copying SOURCE MEDIAFILE -> TARGET FOLDER', 'COPYLINK') + log.info('Copying SOURCE MEDIAFILE -> TARGET FOLDER') shutil.copy(src, target_link) return True @@ -101,17 +87,12 @@ def replace_links(link, max_depth=10): link_depth = attempt if not link_depth: - logger.debug(f'{link} is not a link') + log.debug(f'{link} is not a link') elif link_depth > max_depth or ( link_depth == max_depth and islink(target) ): - logger.warning( - f'Exceeded maximum depth {max_depth} while following link {link}', - ) + log.warning(f'Exceeded maximum depth {max_depth} while following link {link}') else: - logger.info( - f'Changing sym-link: {link} to point directly to file: {target}', - 'COPYLINK', - ) + log.info(f'Changing sym-link: {link} to point directly to file: {target}') os.unlink(link) linktastic.symlink(target, link) diff --git a/nzb2media/utils/network.py b/nzb2media/utils/network.py index 79890bcb..50252d46 100644 --- a/nzb2media/utils/network.py +++ b/nzb2media/utils/network.py @@ -1,5 +1,6 @@ from __future__ import annotations +import logging import socket import struct import time @@ -8,6 +9,9 @@ import requests import nzb2media +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def make_wake_on_lan_packet(mac_address): """Build the Wake-On-LAN 'Magic Packet'.""" @@ -28,7 +32,7 @@ def wake_on_lan(ethernet_address): connection.setsockopt(socket.SOL_SOCKET, socket.SO_BROADCAST, 1) connection.sendto(magic_packet, ('', 9)) - logger.info(f'WakeOnLan sent for mac: {ethernet_address}') + log.info(f'WakeOnLan sent for mac: {ethernet_address}') def test_connection(host, port): @@ -49,37 +53,37 @@ def wake_up(): mac = wol['mac'] max_attempts = 4 - logger.info('Trying to wake On lan.') + log.info('Trying to wake On lan.') for attempt in range(0, max_attempts): - logger.info(f'Attempt {attempt + 1} of {max_attempts}') + log.info(f'Attempt {attempt + 1} of {max_attempts}') if test_connection(host, port) == 'Up': - logger.info(f'System with mac: {mac} has been woken.') + log.info(f'System with mac: {mac} has been woken.') break wake_on_lan(mac) time.sleep(20) else: if test_connection(host, port) == 'Down': # final check. msg = 'System with mac: {0} has not woken after {1} attempts.' - logger.warning(msg.format(mac, max_attempts)) + log.warning(msg.format(mac, max_attempts)) - logger.info('Continuing with the rest of the script.') + log.info('Continuing with the rest of the script.') def server_responding(base_url): - logger.debug(f'Attempting to connect to server at {base_url}', 'SERVER') + log.debug(f'Attempting to connect to server at {base_url}') try: requests.get(base_url, timeout=(60, 120), verify=False) except (requests.ConnectionError, requests.exceptions.Timeout): - logger.error(f'Server failed to respond at {base_url}', 'SERVER') + log.error(f'Server failed to respond at {base_url}') return False else: - logger.debug(f'Server responded at {base_url}', 'SERVER') + log.debug(f'Server responded at {base_url}') return True def find_download(client_agent, download_id): - logger.debug(f'Searching for Download on {client_agent} ...') + log.debug(f'Searching for Download on {client_agent} ...') if client_agent == 'utorrent': torrents = nzb2media.TORRENT_CLASS.list()[1]['torrents'] for torrent in torrents: @@ -115,7 +119,7 @@ def find_download(client_agent, download_id): url, params=params, verify=False, timeout=(30, 120), ) except requests.ConnectionError: - logger.error('Unable to open URL') + log.error('Unable to open URL') return False # failure result = r.json() diff --git a/nzb2media/utils/nzb.py b/nzb2media/utils/nzb.py index 7c86f11f..582cb086 100644 --- a/nzb2media/utils/nzb.py +++ b/nzb2media/utils/nzb.py @@ -1,16 +1,20 @@ from __future__ import annotations +import logging import os import requests import nzb2media +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def get_nzoid(input_name): nzoid = None slots = [] - logger.debug('Searching for nzoid from SAbnzbd ...') + log.debug('Searching for nzoid from SAbnzbd ...') if 'http' in nzb2media.SABNZBD_HOST: base_url = f'{nzb2media.SABNZBD_HOST}:{nzb2media.SABNZBD_PORT}/api' else: @@ -24,7 +28,7 @@ def get_nzoid(input_name): try: r = requests.get(url, params=params, verify=False, timeout=(30, 120)) except requests.ConnectionError: - logger.error('Unable to open URL') + log.error('Unable to open URL') return nzoid # failure try: result = r.json() @@ -36,12 +40,12 @@ def get_nzoid(input_name): ], ) except Exception: - logger.warning('Data from SABnzbd queue could not be parsed') + log.warning('Data from SABnzbd queue could not be parsed') params['mode'] = 'history' try: r = requests.get(url, params=params, verify=False, timeout=(30, 120)) except requests.ConnectionError: - logger.error('Unable to open URL') + log.error('Unable to open URL') return nzoid # failure try: result = r.json() @@ -53,21 +57,21 @@ def get_nzoid(input_name): ], ) except Exception: - logger.warning('Data from SABnzbd history could not be parsed') + log.warning('Data from SABnzbd history could not be parsed') try: for nzo_id, name in slots: if name in [input_name, clean_name]: nzoid = nzo_id - logger.debug(f'Found nzoid: {nzoid}') + log.debug(f'Found nzoid: {nzoid}') break except Exception: - logger.warning('Data from SABnzbd could not be parsed') + log.warning('Data from SABnzbd could not be parsed') return nzoid def report_nzb(failure_link, client_agent): # Contact indexer site - logger.info('Sending failure notification to indexer site') + log.info('Sending failure notification to indexer site') if client_agent == 'nzbget': headers = {'User-Agent': 'NZBGet / nzbToMedia.py'} elif client_agent == 'sabnzbd': @@ -76,6 +80,6 @@ def report_nzb(failure_link, client_agent): return try: requests.post(failure_link, headers=headers, timeout=(30, 300)) - except Exception as e: - logger.error(f'Unable to open URL {failure_link} due to {e}') + except Exception as error: + log.error(f'Unable to open URL {failure_link} due to {error}') return diff --git a/nzb2media/utils/parsers.py b/nzb2media/utils/parsers.py index f31c1442..f9edc490 100644 --- a/nzb2media/utils/parsers.py +++ b/nzb2media/utils/parsers.py @@ -1,9 +1,13 @@ from __future__ import annotations +import logging import os import nzb2media +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def parse_other(args): return os.path.normpath(args[1]), '', '', '', '' @@ -99,7 +103,7 @@ def parse_synods(args): input_id = f'dbid_{torrent_id}' # res = nzb2media.TORRENT_CLASS.tasks_list(additional_param='detail') res = nzb2media.TORRENT_CLASS.tasks_info(input_id, additional_param='detail') - logger.debug(f'result from syno {res}') + log.debug(f'result from syno {res}') if res['success']: try: tasks = res['data']['tasks'] @@ -107,7 +111,7 @@ def parse_synods(args): input_id = task['id'] input_directory = task['additional']['detail']['destination'] except: - logger.error('unable to find download details in Synology DS') + log.error('unable to find download details in Synology DS') # Syno paths appear to be relative. Let's test to see if the returned path exists, and if not append to /volume1/ if not os.path.isdir(input_directory): for root in ['/volume1/', '/volume2/', '/volume3/', '/volume4/']: diff --git a/nzb2media/utils/paths.py b/nzb2media/utils/paths.py index fb283cde..6ecb1efc 100644 --- a/nzb2media/utils/paths.py +++ b/nzb2media/utils/paths.py @@ -1,5 +1,6 @@ from __future__ import annotations +import logging import os import re import shutil @@ -8,6 +9,9 @@ from functools import partial import nzb2media +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def onerror(func, path, exc_info): """ @@ -29,11 +33,11 @@ def onerror(func, path, exc_info): def remove_dir(dir_name): - logger.info(f'Deleting {dir_name}') + log.info(f'Deleting {dir_name}') try: shutil.rmtree(dir_name, onerror=onerror) except Exception: - logger.error(f'Unable to delete folder {dir_name}') + log.error(f'Unable to delete folder {dir_name}') def make_dir(path): @@ -77,7 +81,7 @@ def remove_empty_folders(path, remove_root=True): return # remove empty subfolders - logger.debug(f'Checking for empty folders in:{path}') + log.debug(f'Checking for empty folders in:{path}') files = os.listdir(path) if len(files): for f in files: @@ -88,7 +92,7 @@ def remove_empty_folders(path, remove_root=True): # if folder empty, delete it files = os.listdir(path) if len(files) == 0 and remove_root: - logger.debug(f'Removing empty folder:{path}') + log.debug(f'Removing empty folder:{path}') os.rmdir(path) @@ -98,66 +102,51 @@ def remove_read_only(filename): file_attribute = os.stat(filename)[0] if not file_attribute & stat.S_IWRITE: # File is read-only, so make it writeable - logger.debug( - f'Read only mode on file {filename}. Attempting to make it writeable', - ) + log.debug(f'Read only mode on file {filename}. Attempting to make it writeable') try: os.chmod(filename, stat.S_IWRITE) except Exception: - logger.warning( - f'Cannot change permissions of {filename}', logger.WARNING, - ) + log.warning(f'Cannot change permissions of {filename}') def flatten_dir(destination, files): - logger.info(f'FLATTEN: Flattening directory: {destination}') + log.info(f'FLATTEN: Flattening directory: {destination}') for outputFile in files: dir_path = os.path.dirname(outputFile) file_name = os.path.basename(outputFile) - if dir_path == destination: continue - target = os.path.join(destination, file_name) - try: shutil.move(outputFile, target) except Exception: - logger.error(f'Could not flatten {outputFile}', 'FLATTEN') - + log.error(f'Could not flatten {outputFile}') remove_empty_folders(destination) # Cleanup empty directories def clean_directory(path, files): if not os.path.exists(path): - logger.info( - f'Directory {path} has been processed and removed ...', 'CLEANDIR', - ) + log.info(f'Directory {path} has been processed and removed ...') return if nzb2media.FORCE_CLEAN and not nzb2media.FAILED: - logger.info(f'Doing Forceful Clean of {path}', 'CLEANDIR') + log.info(f'Doing Forceful Clean of {path}') remove_dir(path) return if files: - logger.info( - f'Directory {path} still contains {len(files)} unprocessed file(s), skipping ...', - 'CLEANDIRS', - ) + log.info(f'Directory {path} still contains {len(files)} unprocessed file(s), skipping ...') return - logger.info( - f'Directory {path} has been processed, removing ...', 'CLEANDIRS', - ) + log.info(f'Directory {path} has been processed, removing ...') try: shutil.rmtree(path, onerror=onerror) except Exception: - logger.error(f'Unable to delete directory {path}') + log.error(f'Unable to delete directory {path}') def rchmod(path, mod): - logger.log(f'Changing file mode of {path} to {oct(mod)}') + log.info(f'Changing file mode of {path} to {oct(mod)}') os.chmod(path, mod) if not os.path.isdir(path): return # Skip files diff --git a/nzb2media/utils/processes.py b/nzb2media/utils/processes.py index 61fb5d57..c840fc0f 100644 --- a/nzb2media/utils/processes.py +++ b/nzb2media/utils/processes.py @@ -1,5 +1,6 @@ from __future__ import annotations +import logging import os import socket import subprocess @@ -16,6 +17,9 @@ if os.name == 'nt': from win32api import CloseHandle, GetLastError from winerror import ERROR_ALREADY_EXISTS +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + class WindowsProcess: def __init__(self): @@ -109,8 +113,7 @@ def restart(): if popen_list: popen_list += SYS_ARGV - logger.log(f'Restarting nzbToMedia with {popen_list}') - logger.close() + log.info(f'Restarting nzbToMedia with {popen_list}') p = subprocess.Popen(popen_list, cwd=os.getcwd()) p.wait() status = p.returncode diff --git a/nzb2media/utils/torrent.py b/nzb2media/utils/torrent.py index 1725fecf..794b2c30 100644 --- a/nzb2media/utils/torrent.py +++ b/nzb2media/utils/torrent.py @@ -1,5 +1,6 @@ from __future__ import annotations +import logging import time import nzb2media @@ -9,6 +10,9 @@ from nzb2media.torrent import synology from nzb2media.torrent import transmission from nzb2media.torrent import utorrent +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + torrent_clients = { 'deluge': deluge, 'qbittorrent': qbittorrent, @@ -31,9 +35,7 @@ def create_torrent_class(client_agent): def pause_torrent(client_agent, input_hash, input_id, input_name): - logger.debug( - f'Stopping torrent {input_name} in {client_agent} while processing', - ) + log.debug(f'Stopping torrent {input_name} in {client_agent} while processing') try: if client_agent == 'utorrent' and nzb2media.TORRENT_CLASS != '': nzb2media.TORRENT_CLASS.stop(input_hash) @@ -47,15 +49,13 @@ def pause_torrent(client_agent, input_hash, input_id, input_name): nzb2media.TORRENT_CLASS.pause(input_hash) time.sleep(5) except Exception: - logger.warning( - f'Failed to stop torrent {input_name} in {client_agent}', - ) + log.warning(f'Failed to stop torrent {input_name} in {client_agent}') def resume_torrent(client_agent, input_hash, input_id, input_name): if not nzb2media.TORRENT_RESUME == 1: return - logger.debug(f'Starting torrent {input_name} in {client_agent}') + log.debug(f'Starting torrent {input_name} in {client_agent}') try: if client_agent == 'utorrent' and nzb2media.TORRENT_CLASS != '': nzb2media.TORRENT_CLASS.start(input_hash) @@ -69,14 +69,12 @@ def resume_torrent(client_agent, input_hash, input_id, input_name): nzb2media.TORRENT_CLASS.resume(input_hash) time.sleep(5) except Exception: - logger.warning( - f'Failed to start torrent {input_name} in {client_agent}', - ) + log.warning(f'Failed to start torrent {input_name} in {client_agent}') def remove_torrent(client_agent, input_hash, input_id, input_name): if nzb2media.DELETE_ORIGINAL == 1 or nzb2media.USE_LINK == 'move': - logger.debug(f'Deleting torrent {input_name} from {client_agent}') + log.debug(f'Deleting torrent {input_name} from {client_agent}') try: if client_agent == 'utorrent' and nzb2media.TORRENT_CLASS != '': nzb2media.TORRENT_CLASS.removedata(input_hash) @@ -91,8 +89,6 @@ def remove_torrent(client_agent, input_hash, input_id, input_name): nzb2media.TORRENT_CLASS.delete_permanently(input_hash) time.sleep(5) except Exception: - logger.warning( - f'Failed to delete torrent {input_name} in {client_agent}', - ) + log.warning(f'Failed to delete torrent {input_name} in {client_agent}') else: resume_torrent(client_agent, input_hash, input_id, input_name) diff --git a/nzb2media/version_check.py b/nzb2media/version_check.py index dd458fe7..a13e5e05 100644 --- a/nzb2media/version_check.py +++ b/nzb2media/version_check.py @@ -2,6 +2,7 @@ # Modified by: echel0n from __future__ import annotations +import logging import os import platform import re @@ -15,6 +16,9 @@ from urllib.request import urlretrieve import nzb2media from nzb2media import github_api as github +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + class CheckVersion: """Version checker that runs in a thread with the SB scheduler.""" @@ -60,15 +64,13 @@ class CheckVersion: force: if true the VERSION_NOTIFY setting will be ignored and a check will be forced """ if not nzb2media.VERSION_NOTIFY and not force: - logger.log( - 'Version checking is disabled, not checking for the newest version', - ) + log.info('Version checking is disabled, not checking for the newest version') return False - logger.log(f'Checking if {self.install_type} needs an update') + log.info(f'Checking if {self.install_type} needs an update') if not self.updater.need_update(): nzb2media.NEWEST_VERSION_STRING = None - logger.log('No update needed') + log.info('No update needed') return False self.updater.set_newest_text() @@ -104,9 +106,7 @@ class GitUpdateManager(UpdateManager): self._num_commits_ahead = 0 def _git_error(self): - logger.debug( - 'Unable to find your git executable - Set git_path in your autoProcessMedia.cfg OR delete your .git folder and run from source to enable updates.', - ) + log.debug('Unable to find your git executable - Set git_path in your autoProcessMedia.cfg OR delete your .git folder and run from source to enable updates.') def _find_working_git(self): test_cmd = 'version' @@ -116,19 +116,14 @@ class GitUpdateManager(UpdateManager): else: main_git = 'git' - logger.log( - 'Checking if we can use git commands: {git} {cmd}'.format( - git=main_git, cmd=test_cmd, - ), - logger.DEBUG, - ) + log.debug('Checking if we can use git commands: {git} {cmd}'.format(git=main_git, cmd=test_cmd)) output, err, exit_status = self._run_git(main_git, test_cmd) if exit_status == 0: - logger.log(f'Using: {main_git}', logger.DEBUG) + log.debug(f'Using: {main_git}') return main_git else: - logger.log(f'Not using: {main_git}', logger.DEBUG) + log.debug(f'Not using: {main_git}') # trying alternatives @@ -143,25 +138,20 @@ class GitUpdateManager(UpdateManager): alternative_git.append(main_git.lower()) if alternative_git: - logger.log('Trying known alternative git locations', logger.DEBUG) + log.debug('Trying known alternative git locations') for cur_git in alternative_git: - logger.log( - 'Checking if we can use git commands: {git} {cmd}'.format( - git=cur_git, cmd=test_cmd, - ), - logger.DEBUG, - ) + log.debug('Checking if we can use git commands: {git} {cmd}'.format(git=cur_git, cmd=test_cmd)) output, err, exit_status = self._run_git(cur_git, test_cmd) if exit_status == 0: - logger.log(f'Using: {cur_git}', logger.DEBUG) + log.debug(f'Using: {cur_git}') return cur_git else: - logger.log(f'Not using: {cur_git}', logger.DEBUG) + log.debug(f'Not using: {cur_git}') # Still haven't found a working git - logger.debug( + log.debug( 'Unable to find your git executable - ' 'Set git_path in your autoProcessMedia.cfg OR ' 'delete your .git folder and run from source to enable updates.', @@ -175,21 +165,14 @@ class GitUpdateManager(UpdateManager): err = None if not git_path: - logger.log( - 'No git specified, can\'t use git commands', logger.DEBUG, - ) + log.debug('No git specified, can\'t use git commands') exit_status = 1 return output, err, exit_status cmd = f'{git_path} {args}' try: - logger.log( - 'Executing {cmd} with your shell in {directory}'.format( - cmd=cmd, directory=nzb2media.APP_ROOT, - ), - logger.DEBUG, - ) + log.debug('Executing {cmd} with your shell in {directory}'.format(cmd=cmd, directory=nzb2media.APP_ROOT)) p = subprocess.Popen( cmd, stdin=subprocess.PIPE, @@ -206,29 +189,21 @@ class GitUpdateManager(UpdateManager): if output: output = output.strip() if nzb2media.LOG_GIT: - logger.log(f'git output: {output}', logger.DEBUG) + log.debug(f'git output: {output}') except OSError: - logger.log(f'Command {cmd} didn\'t work') + log.error(f'Command {cmd} didn\'t work') exit_status = 1 exit_status = 128 if ('fatal:' in output) or err else exit_status if exit_status == 0: - logger.log(f'{cmd} : returned successful', logger.DEBUG) + log.debug(f'{cmd} : returned successful') exit_status = 0 elif nzb2media.LOG_GIT and exit_status in (1, 128): - logger.log( - f'{cmd} returned : {output}', - logger.DEBUG, - ) + log.debug(f'{cmd} returned : {output}') else: if nzb2media.LOG_GIT: - logger.log( - '{cmd} returned : {output}, treat as error for now'.format( - cmd=cmd, output=output, - ), - logger.DEBUG, - ) + log.debug('{cmd} returned : {output}, treat as error for now'.format(cmd=cmd, output=output)) exit_status = 1 return output, err, exit_status @@ -248,10 +223,7 @@ class GitUpdateManager(UpdateManager): if exit_status == 0 and output: cur_commit_hash = output.strip() if not re.match('^[a-z0-9]+$', cur_commit_hash): - logger.log( - 'Output doesn\'t look like a hash, not using it', - logger.ERROR, - ) + log.error('Output doesn\'t look like a hash, not using it') return False self._cur_commit_hash = cur_commit_hash if self._cur_commit_hash: @@ -290,10 +262,7 @@ class GitUpdateManager(UpdateManager): ) if not exit_status == 0: - logger.log( - 'Unable to contact github, can\'t check for update', - logger.ERROR, - ) + log.error('Unable to contact github, can\'t check for update') return # get latest commit_hash from remote @@ -305,16 +274,12 @@ class GitUpdateManager(UpdateManager): cur_commit_hash = output.strip() if not re.match('^[a-z0-9]+$', cur_commit_hash): - logger.log( - 'Output doesn\'t look like a hash, not using it', - logger.DEBUG, - ) + log.debug('Output doesn\'t look like a hash, not using it') return - else: self._newest_commit_hash = cur_commit_hash else: - logger.log('git didn\'t return newest commit hash', logger.DEBUG) + log.debug('git didn\'t return newest commit hash') return # get number of commits behind and ahead (option --count not supported git < 1.7.2) @@ -329,47 +294,22 @@ class GitUpdateManager(UpdateManager): self._num_commits_ahead = int(output.count('>')) except Exception: - logger.log( - 'git didn\'t return numbers for behind and ahead, not using it', - logger.DEBUG, - ) + log.debug('git didn\'t return numbers for behind and ahead, not using it') return - logger.log( - 'cur_commit = {current} % (newest_commit)= {new}, ' - 'num_commits_behind = {x}, num_commits_ahead = {y}'.format( - current=self._cur_commit_hash, - new=self._newest_commit_hash, - x=self._num_commits_behind, - y=self._num_commits_ahead, - ), - logger.DEBUG, - ) + log.debug('cur_commit = {current} % (newest_commit)= {new}, num_commits_behind = {x}, num_commits_ahead = {y}'.format(current=self._cur_commit_hash, new=self._newest_commit_hash, x=self._num_commits_behind, y=self._num_commits_ahead)) def set_newest_text(self): if self._num_commits_ahead: - logger.log( - 'Local branch is ahead of {branch}. Automatic update not possible.'.format( - branch=self.branch, - ), - logger.ERROR, - ) + log.error('Local branch is ahead of {branch}. Automatic update not possible.'.format(branch=self.branch)) elif self._num_commits_behind: - logger.log( - 'There is a newer version available (you\'re {x} commit{s} behind)'.format( - x=self._num_commits_behind, - s='s' if self._num_commits_behind > 1 else '', - ), - logger.MESSAGE, - ) + log.info('There is a newer version available (you\'re {x} commit{s} behind)'.format(x=self._num_commits_behind, s='s' if self._num_commits_behind > 1 else '')) else: return def need_update(self): if not self._find_installed_version(): - logger.error( - 'Unable to determine installed version via git, please check your logs!', - ) + log.error('Unable to determine installed version via git, please check your logs!') return False if not self._cur_commit_hash: @@ -378,10 +318,7 @@ class GitUpdateManager(UpdateManager): try: self._check_github_for_update() except Exception as error: - logger.log( - f'Unable to contact github, can\'t check for update: {error!r}', - logger.ERROR, - ) + log.error(f'Unable to contact github, can\'t check for update: {error!r}') return False if self._num_commits_behind > 0: @@ -428,9 +365,7 @@ class SourceUpdateManager(UpdateManager): with open(version_file) as fp: self._cur_commit_hash = fp.read().strip(' \n\r') except OSError as error: - logger.log( - f'Unable to open \'version.txt\': {error}', logger.DEBUG, - ) + log.debug(f'Unable to open \'version.txt\': {error}') if not self._cur_commit_hash: self._cur_commit_hash = None @@ -444,10 +379,7 @@ class SourceUpdateManager(UpdateManager): try: self._check_github_for_update() except Exception as error: - logger.log( - f'Unable to contact github, can\'t check for update: {error!r}', - logger.ERROR, - ) + log.error(f'Unable to contact github, can\'t check for update: {error!r}') return False if not self._cur_commit_hash or self._num_commits_behind > 0: @@ -472,7 +404,8 @@ class SourceUpdateManager(UpdateManager): self.github_repo_user, self.github_repo, self.branch, ) - # try to get newest commit hash and commits behind directly by comparing branch and current commit + # try to get newest commit hash and commits behind directly by + # comparing branch and current commit if self._cur_commit_hash: branch_compared = gh.compare( base=self.branch, head=self._cur_commit_hash, @@ -501,14 +434,7 @@ class SourceUpdateManager(UpdateManager): # when _cur_commit_hash doesn't match anything _num_commits_behind == 100 self._num_commits_behind += 1 - logger.log( - 'cur_commit = {current} % (newest_commit)= {new}, num_commits_behind = {x}'.format( - current=self._cur_commit_hash, - new=self._newest_commit_hash, - x=self._num_commits_behind, - ), - logger.DEBUG, - ) + log.debug('cur_commit = {current} % (newest_commit)= {new}, num_commits_behind = {x}'.format(current=self._cur_commit_hash, new=self._newest_commit_hash, x=self._num_commits_behind)) def set_newest_text(self): @@ -516,29 +442,16 @@ class SourceUpdateManager(UpdateManager): nzb2media.NEWEST_VERSION_STRING = None if not self._cur_commit_hash: - logger.log( - 'Unknown current version number, don\'t know if we should update or not', - logger.ERROR, - ) + log.error('Unknown current version number, don\'t know if we should update or not') elif self._num_commits_behind > 0: - logger.log( - 'There is a newer version available (you\'re {x} commit{s} behind)'.format( - x=self._num_commits_behind, - s='s' if self._num_commits_behind > 1 else '', - ), - logger.MESSAGE, - ) + log.info('There is a newer version available (you\'re {x} commit{s} behind)'.format(x=self._num_commits_behind, s='s' if self._num_commits_behind > 1 else '')) else: return def update(self): """Download and install latest source tarball from github.""" tar_download_url = ( - 'https://github.com/{org}/{repo}/tarball/{branch}'.format( - org=self.github_repo_user, - repo=self.github_repo, - branch=self.branch, - ) + 'https://github.com/{org}/{repo}/tarball/{branch}'.format(org=self.github_repo_user, repo=self.github_repo, branch=self.branch) ) version_path = os.path.join(nzb2media.APP_ROOT, 'version.txt') @@ -547,49 +460,35 @@ class SourceUpdateManager(UpdateManager): sb_update_dir = os.path.join(nzb2media.APP_ROOT, 'sb-update') if os.path.isdir(sb_update_dir): - logger.log( - f'Clearing out update folder {sb_update_dir} before extracting', - ) + log.info(f'Clearing out update folder {sb_update_dir} before extracting') shutil.rmtree(sb_update_dir) - logger.log( - f'Creating update folder {sb_update_dir} before extracting', - ) + log.info(f'Creating update folder {sb_update_dir} before extracting') os.makedirs(sb_update_dir) # retrieve file - logger.log(f'Downloading update from {tar_download_url!r}') + log.info(f'Downloading update from {tar_download_url!r}') tar_download_path = os.path.join( sb_update_dir, 'nzbtomedia-update.tar', ) urlretrieve(tar_download_url, tar_download_path) if not os.path.isfile(tar_download_path): - logger.log( - 'Unable to retrieve new version from {url}, can\'t update'.format( - url=tar_download_url, - ), - logger.ERROR, - ) + log.error('Unable to retrieve new version from {url}, can\'t update'.format(url=tar_download_url)) return False if not tarfile.is_tarfile(tar_download_path): - logger.log( - 'Retrieved version from {url} is corrupt, can\'t update'.format( - url=tar_download_url, - ), - logger.ERROR, - ) + log.error('Retrieved version from {url} is corrupt, can\'t update'.format(url=tar_download_url)) return False # extract to sb-update dir - logger.log(f'Extracting file {tar_download_path}') + log.info(f'Extracting file {tar_download_path}') tar = tarfile.open(tar_download_path) tar.extractall(sb_update_dir) tar.close() # delete .tar.gz - logger.log(f'Deleting file {tar_download_path}') + log.info(f'Deleting file {tar_download_path}') os.remove(tar_download_path) # find update dir name @@ -599,23 +498,16 @@ class SourceUpdateManager(UpdateManager): if os.path.isdir(os.path.join(sb_update_dir, x)) ] if len(update_dir_contents) != 1: - logger.log( - f'Invalid update data, update failed: {update_dir_contents}', - logger.ERROR, - ) + log.error(f'Invalid update data, update failed: {update_dir_contents}') return False content_dir = os.path.join(sb_update_dir, update_dir_contents[0]) # walk temp folder and move files to main folder - logger.log( - 'Moving files from {source} to {destination}'.format( - source=content_dir, destination=nzb2media.APP_ROOT, - ), - ) + log.info('Moving files from {source} to {destination}'.format(source=content_dir, destination=nzb2media.APP_ROOT)) for dirname, _, filenames in os.walk( content_dir, ): # @UnusedVariable - dirname = dirname[len(content_dir) + 1 :] + dirname = dirname[len(content_dir) + 1:] for curfile in filenames: old_path = os.path.join(content_dir, dirname, curfile) new_path = os.path.join(nzb2media.APP_ROOT, dirname, curfile) @@ -629,15 +521,9 @@ class SourceUpdateManager(UpdateManager): os.remove(new_path) os.renames(old_path, new_path) except Exception as error: - logger.log( - 'Unable to update {path}: {msg}'.format( - path=new_path, msg=error, - ), - logger.DEBUG, - ) - os.remove( - old_path, - ) # Trash the updated file without moving in new path + log.debug('Unable to update {path}: {msg}'.format(path=new_path, msg=error)) + # Trash the updated file without moving in new path + os.remove(old_path) continue if os.path.isfile(new_path): @@ -649,20 +535,12 @@ class SourceUpdateManager(UpdateManager): with open(version_path, 'w') as ver_file: ver_file.write(self._newest_commit_hash) except OSError as error: - logger.log( - 'Unable to write version file, update not complete: {msg}'.format( - msg=error, - ), - logger.ERROR, - ) + log.error('Unable to write version file, update not complete: {msg}'.format(msg=error),) return False except Exception as error: - logger.log( - f'Error while trying to update: {error}', - logger.ERROR, - ) - logger.log(f'Traceback: {traceback.format_exc()}', logger.DEBUG) + log.error(f'Error while trying to update: {error}') + log.debug(f'Traceback: {traceback.format_exc()}') return False return True diff --git a/nzbToMedia.py b/nzbToMedia.py index 730983e9..84cb881f 100755 --- a/nzbToMedia.py +++ b/nzbToMedia.py @@ -1,3 +1,4 @@ +import logging import os import sys @@ -6,17 +7,20 @@ from nzb2media.processor import nzbget, sab, manual from nzb2media.processor.nzb import process from nzb2media.auto_process.common import ProcessResult +log = logging.getLogger(__name__) +log.addHandler(logging.NullHandler()) + def main(args, section=None): # Initialize the config nzb2media.initialize(section) - logger.info('#########################################################') - logger.info(f'## ..::[{os.path.basename(__file__)}]::.. ##') - logger.info('#########################################################') + log.info('#########################################################') + log.info(f'## ..::[{os.path.basename(__file__)}]::.. ##') + log.info('#########################################################') # debug command line options - logger.debug(f'Options passed into nzbToMedia: {args}') + log.debug(f'Options passed into nzbToMedia: {args}') # Post-Processing Result result = ProcessResult( @@ -35,22 +39,22 @@ def main(args, section=None): result = sab.process(args) # Generic program elif len(args) > 5 and args[5] == 'generic': - logger.info('Script triggered from generic program') + log.info('Script triggered from generic program') result = process(args[1], input_name=args[2], input_category=args[3], download_id=args[4]) elif nzb2media.NZB_NO_MANUAL: - logger.warning('Invalid number of arguments received from client, and no_manual set') + log.warning('Invalid number of arguments received from client, and no_manual set') else: manual.process() if result.status_code == 0: - logger.info(f'The {args[0]} script completed successfully.') + log.info(f'The {args[0]} script completed successfully.') if result.message: print(result.message + '!') if 'NZBOP_SCRIPTDIR' in os.environ: # return code for nzbget v11 del nzb2media.MYAPP return nzb2media.NZBGET_POSTPROCESS_SUCCESS else: - logger.error(f'A problem was reported in the {args[0]} script.') + log.error(f'A problem was reported in the {args[0]} script.') if result.message: print(result.message + '!') if 'NZBOP_SCRIPTDIR' in os.environ: # return code for nzbget v11