2018-11-28 12:31:16 +00:00
|
|
|
# coding=utf-8
|
|
|
|
|
2018-10-25 10:06:33 +00:00
|
|
|
import os
|
2022-03-10 03:40:18 +00:00
|
|
|
import sys
|
2018-10-25 10:06:33 +00:00
|
|
|
import logging
|
|
|
|
import re
|
2019-03-05 17:55:20 +00:00
|
|
|
import platform
|
2019-09-28 04:22:17 +00:00
|
|
|
import warnings
|
2018-10-25 10:06:33 +00:00
|
|
|
|
|
|
|
from logging.handlers import TimedRotatingFileHandler
|
2024-03-03 17:00:50 +00:00
|
|
|
from utilities.central import get_log_file_path
|
2022-01-24 04:07:52 +00:00
|
|
|
from pytz_deprecation_shim import PytzUsageWarning
|
|
|
|
|
2022-05-01 12:00:20 +00:00
|
|
|
from .get_args import args
|
|
|
|
from .config import settings
|
2019-03-05 17:55:20 +00:00
|
|
|
|
2018-10-25 10:06:33 +00:00
|
|
|
|
2018-11-10 18:53:27 +00:00
|
|
|
logger = logging.getLogger()
|
|
|
|
|
2018-10-25 10:06:33 +00:00
|
|
|
|
2021-06-21 04:02:54 +00:00
|
|
|
class FileHandlerFormatter(logging.Formatter):
|
|
|
|
"""Formatter that removes apikey from logs."""
|
|
|
|
APIKEY_RE = re.compile(r'apikey(?:=|%3D)([a-zA-Z0-9]+)')
|
|
|
|
IPv4_RE = re.compile(r'\b(?:(?:25[0-5]|2[0-4][0-9]|1[0-9][0-9]|[1-9]?[0-9])\.){3}(?:25[0-5]|2[0-4][0-9]|1[0-9]'
|
|
|
|
r'[0-9]|[1-9]?[0-9])\b')
|
|
|
|
|
2018-10-25 10:06:33 +00:00
|
|
|
def formatException(self, exc_info):
|
|
|
|
"""
|
|
|
|
Format an exception so that it prints on a single line.
|
|
|
|
"""
|
2021-06-21 04:02:54 +00:00
|
|
|
result = super(FileHandlerFormatter, self).formatException(exc_info)
|
2018-10-25 10:06:33 +00:00
|
|
|
return repr(result) # or format into one line however you want to
|
2021-06-21 04:02:54 +00:00
|
|
|
|
|
|
|
def formatApikey(self, s):
|
|
|
|
return re.sub(self.APIKEY_RE, 'apikey=(removed)', s)
|
|
|
|
|
|
|
|
def formatIPv4(self, s):
|
|
|
|
return re.sub(self.IPv4_RE, '***.***.***.***', s)
|
|
|
|
|
2018-10-25 10:06:33 +00:00
|
|
|
def format(self, record):
|
2021-06-21 04:02:54 +00:00
|
|
|
s = super(FileHandlerFormatter, self).format(record)
|
2018-10-25 10:06:33 +00:00
|
|
|
if record.exc_text:
|
|
|
|
s = s.replace('\n', '') + '|'
|
2021-06-21 04:02:54 +00:00
|
|
|
|
|
|
|
s = self.formatApikey(s)
|
|
|
|
s = self.formatIPv4(s)
|
|
|
|
|
2018-10-25 10:06:33 +00:00
|
|
|
return s
|
|
|
|
|
|
|
|
|
|
|
|
class NoExceptionFormatter(logging.Formatter):
|
|
|
|
def format(self, record):
|
|
|
|
record.exc_text = '' # ensure formatException gets called
|
|
|
|
return super(NoExceptionFormatter, self).format(record)
|
2022-01-03 03:59:30 +00:00
|
|
|
|
2018-10-25 10:06:33 +00:00
|
|
|
def formatException(self, record):
|
|
|
|
return ''
|
|
|
|
|
2024-02-28 04:51:10 +00:00
|
|
|
|
2023-12-27 03:48:02 +00:00
|
|
|
class UnwantedWaitressMessageFilter(logging.Filter):
|
|
|
|
def filter(self, record):
|
2024-03-03 17:15:23 +00:00
|
|
|
if settings.general.debug:
|
2023-12-27 03:48:02 +00:00
|
|
|
# no filtering in debug mode
|
|
|
|
return True
|
2024-03-03 17:00:50 +00:00
|
|
|
|
|
|
|
unwantedMessages = [
|
|
|
|
"Exception while serving /api/socket.io/",
|
|
|
|
['Session is disconnected', 'Session not found' ],
|
|
|
|
|
|
|
|
"Exception while serving /api/socket.io/",
|
|
|
|
["'Session is disconnected'", "'Session not found'" ],
|
|
|
|
|
|
|
|
"Exception while serving /api/socket.io/",
|
|
|
|
['"Session is disconnected"', '"Session not found"' ],
|
|
|
|
|
|
|
|
"Exception when servicing %r",
|
|
|
|
[],
|
2023-12-27 03:48:02 +00:00
|
|
|
]
|
2024-02-28 04:51:10 +00:00
|
|
|
|
|
|
|
wanted = True
|
2023-12-27 03:48:02 +00:00
|
|
|
listLength = len(unwantedMessages)
|
|
|
|
for i in range(0, listLength, 2):
|
|
|
|
if record.msg == unwantedMessages[i]:
|
|
|
|
exceptionTuple = record.exc_info
|
2024-02-28 04:51:10 +00:00
|
|
|
if exceptionTuple is not None:
|
2024-03-03 17:00:50 +00:00
|
|
|
if len(unwantedMessages[i+1]) == 0 or str(exceptionTuple[1]) in unwantedMessages[i+1]:
|
2023-12-27 03:48:02 +00:00
|
|
|
wanted = False
|
|
|
|
break
|
2024-02-28 04:51:10 +00:00
|
|
|
|
2023-12-27 03:48:02 +00:00
|
|
|
return wanted
|
|
|
|
|
2018-10-25 10:06:33 +00:00
|
|
|
|
2018-11-15 13:39:55 +00:00
|
|
|
def configure_logging(debug=False):
|
2020-01-29 11:53:29 +00:00
|
|
|
warnings.simplefilter('ignore', category=ResourceWarning)
|
2022-01-24 04:07:52 +00:00
|
|
|
warnings.simplefilter('ignore', category=PytzUsageWarning)
|
2023-07-26 23:34:49 +00:00
|
|
|
# warnings.simplefilter('ignore', category=SAWarning)
|
2019-09-28 04:22:17 +00:00
|
|
|
|
2024-02-26 11:25:10 +00:00
|
|
|
if debug:
|
|
|
|
log_level = logging.DEBUG
|
2018-11-15 13:39:55 +00:00
|
|
|
else:
|
2024-02-26 11:25:10 +00:00
|
|
|
log_level = logging.INFO
|
2022-01-03 03:59:30 +00:00
|
|
|
|
2018-11-10 18:53:27 +00:00
|
|
|
logger.handlers = []
|
2022-01-03 03:59:30 +00:00
|
|
|
|
2018-11-10 18:53:27 +00:00
|
|
|
logger.setLevel(log_level)
|
2022-01-03 03:59:30 +00:00
|
|
|
|
2018-11-10 18:53:27 +00:00
|
|
|
# Console logging
|
|
|
|
ch = logging.StreamHandler()
|
2018-11-28 12:08:38 +00:00
|
|
|
cf = (debug and logging.Formatter or NoExceptionFormatter)(
|
|
|
|
'%(asctime)-15s - %(name)-32s (%(thread)x) : %(levelname)s (%(module)s:%(lineno)d) - %(message)s')
|
2018-11-10 18:53:27 +00:00
|
|
|
ch.setFormatter(cf)
|
2022-01-03 03:59:30 +00:00
|
|
|
|
2024-02-26 11:25:10 +00:00
|
|
|
ch.setLevel(logging.DEBUG)
|
2018-11-10 18:53:27 +00:00
|
|
|
logger.addHandler(ch)
|
2022-01-03 03:59:30 +00:00
|
|
|
|
2018-11-15 13:39:55 +00:00
|
|
|
# File Logging
|
2018-10-25 10:06:33 +00:00
|
|
|
global fh
|
2022-03-10 03:40:18 +00:00
|
|
|
if sys.version_info >= (3, 9):
|
2024-03-03 17:00:50 +00:00
|
|
|
fh = PatchedTimedRotatingFileHandler(get_log_file_path(), when="midnight",
|
2022-03-10 03:40:18 +00:00
|
|
|
interval=1, backupCount=7, delay=True, encoding='utf-8')
|
|
|
|
else:
|
2024-03-03 17:00:50 +00:00
|
|
|
fh = TimedRotatingFileHandler(get_log_file_path(), when="midnight", interval=1,
|
2022-03-10 03:40:18 +00:00
|
|
|
backupCount=7, delay=True, encoding='utf-8')
|
2021-06-21 04:02:54 +00:00
|
|
|
f = FileHandlerFormatter('%(asctime)s|%(levelname)-8s|%(name)-32s|%(message)s|',
|
2024-01-03 04:04:14 +00:00
|
|
|
'%Y-%m-%d %H:%M:%S')
|
2018-10-25 10:06:33 +00:00
|
|
|
fh.setFormatter(f)
|
2024-02-26 11:25:10 +00:00
|
|
|
fh.setLevel(logging.DEBUG)
|
2019-04-04 13:21:30 +00:00
|
|
|
logger.addHandler(fh)
|
2022-01-03 03:59:30 +00:00
|
|
|
|
2018-11-15 13:39:55 +00:00
|
|
|
if debug:
|
2023-07-26 23:34:49 +00:00
|
|
|
logging.getLogger("alembic.runtime.migration").setLevel(logging.DEBUG)
|
2018-10-25 11:56:02 +00:00
|
|
|
logging.getLogger("apscheduler").setLevel(logging.DEBUG)
|
2018-10-25 10:06:33 +00:00
|
|
|
logging.getLogger("subliminal").setLevel(logging.DEBUG)
|
2018-11-28 11:45:39 +00:00
|
|
|
logging.getLogger("subliminal_patch").setLevel(logging.DEBUG)
|
|
|
|
logging.getLogger("subzero").setLevel(logging.DEBUG)
|
2018-10-25 11:56:02 +00:00
|
|
|
logging.getLogger("git").setLevel(logging.DEBUG)
|
|
|
|
logging.getLogger("apprise").setLevel(logging.DEBUG)
|
2020-01-22 04:54:32 +00:00
|
|
|
logging.getLogger("engineio.server").setLevel(logging.DEBUG)
|
|
|
|
logging.getLogger("socketio.server").setLevel(logging.DEBUG)
|
2020-06-10 16:04:54 +00:00
|
|
|
logging.getLogger("ffsubsync.subtitle_parser").setLevel(logging.DEBUG)
|
|
|
|
logging.getLogger("ffsubsync.speech_transformers").setLevel(logging.DEBUG)
|
|
|
|
logging.getLogger("ffsubsync.ffsubsync").setLevel(logging.DEBUG)
|
|
|
|
logging.getLogger("srt").setLevel(logging.DEBUG)
|
2019-03-05 17:55:20 +00:00
|
|
|
logging.debug('Bazarr version: %s', os.environ["BAZARR_VERSION"])
|
|
|
|
logging.debug('Bazarr branch: %s', settings.general.branch)
|
|
|
|
logging.debug('Operating system: %s', platform.platform())
|
|
|
|
logging.debug('Python version: %s', platform.python_version())
|
2018-10-25 10:06:33 +00:00
|
|
|
else:
|
2023-07-26 23:34:49 +00:00
|
|
|
logging.getLogger("alembic.runtime.migration").setLevel(logging.CRITICAL)
|
2018-10-25 11:56:02 +00:00
|
|
|
logging.getLogger("apscheduler").setLevel(logging.WARNING)
|
2020-10-02 13:48:53 +00:00
|
|
|
logging.getLogger("apprise").setLevel(logging.WARNING)
|
2018-10-25 10:06:33 +00:00
|
|
|
logging.getLogger("subliminal").setLevel(logging.CRITICAL)
|
2019-01-15 12:21:53 +00:00
|
|
|
logging.getLogger("subliminal_patch").setLevel(logging.CRITICAL)
|
|
|
|
logging.getLogger("subzero").setLevel(logging.ERROR)
|
2020-01-22 04:54:32 +00:00
|
|
|
logging.getLogger("engineio.server").setLevel(logging.ERROR)
|
|
|
|
logging.getLogger("socketio.server").setLevel(logging.ERROR)
|
2020-06-10 16:04:54 +00:00
|
|
|
logging.getLogger("ffsubsync.subtitle_parser").setLevel(logging.ERROR)
|
|
|
|
logging.getLogger("ffsubsync.speech_transformers").setLevel(logging.ERROR)
|
|
|
|
logging.getLogger("ffsubsync.ffsubsync").setLevel(logging.ERROR)
|
|
|
|
logging.getLogger("srt").setLevel(logging.ERROR)
|
2021-05-08 14:39:00 +00:00
|
|
|
logging.getLogger("SignalRCoreClient").setLevel(logging.CRITICAL)
|
|
|
|
logging.getLogger("websocket").setLevel(logging.CRITICAL)
|
2023-03-17 13:01:15 +00:00
|
|
|
logging.getLogger("ga4mp.ga4mp").setLevel(logging.ERROR)
|
2020-01-22 04:54:32 +00:00
|
|
|
|
2021-10-30 12:25:20 +00:00
|
|
|
logging.getLogger("waitress").setLevel(logging.ERROR)
|
2024-02-28 04:51:10 +00:00
|
|
|
logging.getLogger("waitress").addFilter(UnwantedWaitressMessageFilter())
|
2020-03-18 19:33:54 +00:00
|
|
|
logging.getLogger("knowit").setLevel(logging.CRITICAL)
|
2018-10-25 11:56:02 +00:00
|
|
|
logging.getLogger("enzyme").setLevel(logging.CRITICAL)
|
2018-10-25 10:06:33 +00:00
|
|
|
logging.getLogger("guessit").setLevel(logging.WARNING)
|
|
|
|
logging.getLogger("rebulk").setLevel(logging.WARNING)
|
|
|
|
logging.getLogger("stevedore.extension").setLevel(logging.CRITICAL)
|
2018-11-28 12:08:38 +00:00
|
|
|
|
2018-11-10 18:53:27 +00:00
|
|
|
|
2018-10-25 10:06:33 +00:00
|
|
|
def empty_log():
|
2018-12-15 00:36:28 +00:00
|
|
|
fh.doRollover()
|
2020-02-18 02:45:12 +00:00
|
|
|
logging.info('BAZARR Log file emptied')
|
2022-03-10 03:40:18 +00:00
|
|
|
|
|
|
|
|
|
|
|
class PatchedTimedRotatingFileHandler(TimedRotatingFileHandler):
|
|
|
|
# This super classed version of logging.TimedRotatingFileHandler is required to fix a bug in earlier version of
|
|
|
|
# Python 3.9, 3.10 and 3.11 where log rotation isn't working as expected and do not delete backup log files.
|
|
|
|
|
|
|
|
def __init__(self, filename, when='h', interval=1, backupCount=0, encoding=None, delay=False, utc=False,
|
|
|
|
atTime=None, errors=None):
|
|
|
|
super(PatchedTimedRotatingFileHandler, self).__init__(filename, when, interval, backupCount, encoding, delay, utc,
|
2022-05-01 12:00:20 +00:00
|
|
|
atTime, errors)
|
2022-03-10 03:40:18 +00:00
|
|
|
|
|
|
|
def getFilesToDelete(self):
|
|
|
|
"""
|
|
|
|
Determine the files to delete when rolling over.
|
|
|
|
More specific than the earlier method, which just used glob.glob().
|
|
|
|
"""
|
|
|
|
dirName, baseName = os.path.split(self.baseFilename)
|
|
|
|
fileNames = os.listdir(dirName)
|
|
|
|
result = []
|
|
|
|
# See bpo-44753: Don't use the extension when computing the prefix.
|
|
|
|
n, e = os.path.splitext(baseName)
|
2023-10-18 03:24:26 +00:00
|
|
|
prefix = f'{n}.'
|
2022-03-10 03:40:18 +00:00
|
|
|
plen = len(prefix)
|
|
|
|
for fileName in fileNames:
|
|
|
|
if self.namer is None:
|
|
|
|
# Our files will always start with baseName
|
|
|
|
if not fileName.startswith(baseName):
|
|
|
|
continue
|
|
|
|
else:
|
|
|
|
# Our files could be just about anything after custom naming, but
|
|
|
|
# likely candidates are of the form
|
|
|
|
# foo.log.DATETIME_SUFFIX or foo.DATETIME_SUFFIX.log
|
|
|
|
if (not fileName.startswith(baseName) and fileName.endswith(e) and
|
|
|
|
len(fileName) > (plen + 1) and not fileName[plen+1].isdigit()):
|
|
|
|
continue
|
|
|
|
|
|
|
|
if fileName[:plen] == prefix:
|
|
|
|
suffix = fileName[plen:]
|
|
|
|
# See bpo-45628: The date/time suffix could be anywhere in the
|
|
|
|
# filename
|
|
|
|
parts = suffix.split('.')
|
|
|
|
for part in parts:
|
|
|
|
if self.extMatch.match(part):
|
|
|
|
result.append(os.path.join(dirName, fileName))
|
|
|
|
break
|
|
|
|
if len(result) < self.backupCount:
|
|
|
|
result = []
|
|
|
|
else:
|
|
|
|
result.sort()
|
|
|
|
result = result[:len(result) - self.backupCount]
|
|
|
|
return result
|