Impl Logging / Reporting base

bin/ffx.py

@@ -1,12 +1,11 @@
 #! /usr/bin/python3
 
-import os, sys, subprocess, json, click, time, re
+import os, click, time, logging
 
 from ffx.file_properties import FileProperties
 
 from ffx.ffx_app import FfxApp
 from ffx.ffx_controller import FfxController
-from ffx.show_controller import ShowController
 from ffx.tmdb_controller import TmdbController
 
 from ffx.database import databaseContext
@@ -32,11 +31,47 @@ VERSION='0.1.3'
 @click.group()
 @click.pass_context
 @click.option('--database-file', type=str, default='', help='Path to database file')
-def ffx(ctx, database_file):
+@click.option('-v', '--verbose', type=int, default=0, help='Set verbosity of output')
+@click.option("--dry-run", is_flag=True, default=False)
+def ffx(ctx, database_file, verbose, dry_run):
     """FFX"""
 
     ctx.obj = {}
     ctx.obj['database'] = databaseContext(databasePath=database_file)
+    ctx.obj['dry_run'] = dry_run
+    ctx.obj['verbosity'] = verbose
+
+    # Critical 50
+    # Error 40
+    # Warning 30
+    # Info 20
+    # Debug 10
+    fileLogVerbosity = max(40 - verbose * 10, 10)
+    consoleLogVerbosity = max(20 - verbose * 10, 10)
+
+    homeDir = os.path.expanduser("~")
+    ffxLogDir = os.path.join(homeDir, '.local', 'var', 'log')
+    if not os.path.exists(ffxLogDir):
+        os.makedirs(ffxLogDir)
+    ffxLogFilePath = os.path.join(ffxLogDir, 'ffx.log')
+
+    ctx.obj['logger'] = logging.getLogger('FFX')
+    ctx.obj['logger'].setLevel(logging.DEBUG)
+
+    ffxFileHandler = logging.FileHandler(ffxLogFilePath)
+    ffxFileHandler.setLevel(fileLogVerbosity)
+    ffxConsoleHandler = logging.StreamHandler()
+    ffxConsoleHandler.setLevel(consoleLogVerbosity)
+
+    fileFormatter = logging.Formatter(
+        '%(asctime)s - %(name)s - %(levelname)s - %(message)s')
+    ffxFileHandler.setFormatter(fileFormatter)
+    consoleFormatter = logging.Formatter(
+        '%(message)s')
+    ffxConsoleHandler.setFormatter(consoleFormatter)
+
+    ctx.obj['logger'].addHandler(ffxConsoleHandler)
+    ctx.obj['logger'].addHandler(ffxFileHandler)
 
 
 # Define a subcommand
@@ -52,8 +87,6 @@ def help():
     click.echo(f"Usage: ffx [input file] [output file] [vp9|av1] [q=[nn[,nn,...]]] [p=nn] [a=nnn[k]] [ac3=nnn[k]] [dts=nnn[k]] [crop]")
 
 
-
-
 @ffx.command()
 @click.pass_context
 @click.argument('filename', nargs=1)
@@ -107,15 +140,14 @@ def getUnmuxSequence(trackDescriptor: TrackDescriptor, sourcePath, targetPrefix,
 @click.option('-l', '--label', type=str, default='', help='Label to be used as filename prefix')
 @click.option("-o", "--output-directory", type=str, default='')
 @click.option("-s", "--subtitles-only", is_flag=True, default=False)
-@click.option("--dry-run", is_flag=True, default=False)
 def unmux(ctx,
             paths,
             label,
             output_directory,
-            subtitles_only,
+            subtitles_only):
-            dry_run):
 
     existingSourcePaths = [p for p in paths if os.path.isfile(p)]
+    if ctx.obj['verbosity'] > 0:
         click.echo(f"\nUnmuxing {len(existingSourcePaths)} files")
 
     for sourcePath in existingSourcePaths:
@@ -134,9 +166,11 @@ def unmux(ctx,
             targetIndicator = f"_S{season}E{episode}" if label and season != -1 and episode != -1 else ''
             
             if label and not targetIndicator:
+                if ctx.obj['verbosity'] > 0:
                     click.echo(f"Skipping file {fp.getFilename()}: Label set but no indicator recognized")
                 continue
             else:
+                if ctx.obj['verbosity'] > 0:
                     click.echo(f"\nUnmuxing file {fp.getFilename()}\n")
 
             for trackDescriptor in sourceMediaDescriptor.getAllTrackDescriptors():
@@ -149,14 +183,18 @@ def unmux(ctx,
                     unmuxSequence = getUnmuxSequence(trackDescriptor, sourcePath, targetPrefix, targetDirectory = output_directory)
                     
                     if unmuxSequence:
-                        if not dry_run:
+                        if not ctx.obj['dry_run']:
+                            if ctx.obj['verbosity'] > 0:
                                 click.echo(f"Executing unmuxing sequence: {' '.join(unmuxSequence)}")
                             out, err, rc = executeProcess(unmuxSequence)
                             if rc:
+                                if ctx.obj['verbosity'] > 0:
                                     click.echo(f"Unmuxing of stream {trackDescriptor.getIndex()} failed with error ({rc}) {err}")        
                     else:
+                        if ctx.obj['verbosity'] > 0:
                             click.echo(f"Skipping stream with unknown codec {trackDescriptor.getCodec()}")
         except Exception as ex:
+            if ctx.obj['verbosity'] > 0:
                 click.echo(f"Skipping File {sourcePath} ({ex})")
 
 
@@ -215,9 +253,6 @@ def shows(ctx):
 @click.option("-j", "--no-jellyfin", is_flag=True, default=False)
 @click.option("-np", "--no-pattern", is_flag=True, default=False)
 
-@click.option("--dry-run", is_flag=True, default=False)
-
-
 def convert(ctx,
             paths,
             label,
@@ -246,8 +281,7 @@ def convert(ctx,
             denoise,
             no_tmdb,
             no_jellyfin,
-            no_pattern,
+            no_pattern):
-            dry_run):
     """Batch conversion of audiovideo files in format suitable for web playback, e.g. jellyfin
 
     Files found under PATHS will be converted according to parameters.
@@ -259,8 +293,6 @@ def convert(ctx,
     
     context = ctx.obj
     
-    context['dry_run'] = dry_run
-    
     context['video_encoder'] = VideoEncoder.fromLabel(video_encoder)
 
     context['use_jellyfin'] = not no_jellyfin
@@ -277,6 +309,7 @@ def convert(ctx,
     qualityTokens = quality.split(',')
     q_list = [q for q in qualityTokens if q.isnumeric()]
 
+    if ctx.obj['verbosity'] > 0:
         click.echo(f"Qualities: {q_list}")
 
     context['bitrates'] = {}
@@ -284,6 +317,7 @@ def convert(ctx,
     context['bitrates']['ac3'] = str(ac3_bitrate) if str(ac3_bitrate).endswith('k') else f"{ac3_bitrate}k"
     context['bitrates']['dts'] = str(dts_bitrate) if str(dts_bitrate).endswith('k') else f"{dts_bitrate}k"
  
+    if ctx.obj['verbosity'] > 0:
         click.echo(f"Stereo bitrate: {context['bitrates']['stereo']}")
         click.echo(f"AC3 bitrate: {context['bitrates']['ac3']}")
         click.echo(f"DTS bitrate: {context['bitrates']['dts']}")
@@ -296,12 +330,14 @@ def convert(ctx,
         if cTokens and len(cTokens) == 2:
             context['crop_start'] = int(cTokens[0])
             context['crop_length'] = int(cTokens[1])
+            if ctx.obj['verbosity'] > 0:
                 click.echo(f"Crop start={context['crop_start']} length={context['crop_length']}")
 
 
     tc = TmdbController() if context['use_tmdb'] else None
 
     existingSourcePaths = [p for p in paths if os.path.isfile(p) and p.split('.')[-1] in FfxController.INPUT_FILE_EXTENSIONS]
+    if ctx.obj['verbosity'] > 0:
         click.echo(f"\nRunning {len(existingSourcePaths) * len(q_list)} jobs")
     jobIndex = 0
  
@@ -315,6 +351,7 @@ def convert(ctx,
         sourceFileBasename = '.'.join(sourcePathTokens[:-1])
         sourceFilenameExtension = sourcePathTokens[-1]
 
+        if ctx.obj['verbosity'] > 0:
             click.echo(f"\nProcessing file {sourcePath}")
 
 
@@ -324,6 +361,7 @@ def convert(ctx,
         #HINT: This is None if the filename did not match anything in database
         currentPattern = mediaFileProperties.getPattern() if context['use_pattern'] else None
 
+        if ctx.obj['verbosity'] > 0:
             click.echo(f"Pattern matching: {'No' if currentPattern is None else 'Yes'}")
 
         # fileBasename = ''
@@ -385,9 +423,9 @@ def convert(ctx,
 
             # Case pattern matching
 
-            targetMediaDescriptor = currentPattern.getMediaDescriptor()
+            targetMediaDescriptor = currentPattern.getMediaDescriptor(ctx.obj)
 
-            currentShowDescriptor = currentPattern.getShowDescriptor()
+            currentShowDescriptor = currentPattern.getShowDescriptor(ctx.obj)
             
 
             if context['use_tmdb']:
@@ -422,6 +460,7 @@ def convert(ctx,
             # click.echo(f"tmd subindices: {[t.getIndex() for t in targetMediaDescriptor.getAllTrackDescriptors()]} {[t.getSubIndex() for t in targetMediaDescriptor.getAllTrackDescriptors()]}  {[t.getDispositionFlag(TrackDisposition.DEFAULT) for t in targetMediaDescriptor.getAllTrackDescriptors()]}")
             # raise click.Abort
 
+            if ctx.obj['verbosity'] > 0:
                 click.echo(f"Input mapping tokens (2nd pass): {targetMediaDescriptor.getInputMappingTokens()}")
 
             fc = FfxController(context, targetMediaDescriptor, sourceMediaDescriptor)
@@ -435,13 +474,15 @@ def convert(ctx,
             # audioTokens = fc.generateAudioEncodingTokens()
             # click.echo(f"Audio Tokens: {audioTokens}")
 
+            if ctx.obj['verbosity'] > 0:
                 click.echo(f"Season={mediaFileProperties.getSeason()} Episode={mediaFileProperties.getEpisode()}")
 
-
+        if ctx.obj['verbosity'] > 0:
             click.echo(f"fileBasename={sourceFileBasename}")
 
         for q in q_list:
 
+            if ctx.obj['verbosity'] > 0:
                 click.echo(f"\nRunning job {jobIndex} file={sourcePath} q={q}")
             jobIndex += 1
 
@@ -464,6 +505,7 @@ def convert(ctx,
     #TODO: click.confirm('Warning! This file is not compliant to the defined source schema! Do you want to continue?', abort=True)
 
     endTime = time.perf_counter()
+    if ctx.obj['verbosity'] > 0:
         click.echo(f"\nDONE\nTime elapsed {endTime - startTime}")
 
 

bin/ffx/ffx_controller.py

@@ -404,7 +404,7 @@ class FfxController():
                                                             FfxController.DEFAULT_FILE_FORMAT,
                                                             FfxController.DEFAULT_FILE_EXTENSION)
 
-            click.echo(f"Command: {' '.join(commandSequence)}")
+            # click.echo(f"Command: {' '.join(commandSequence)}")
 
             if not self.__context['dry_run']:
                 executeProcess(commandSequence)
@@ -421,7 +421,7 @@ class FfxController():
 
             commandSequence1 += FfxController.NULL_TOKENS
 
-            click.echo(f"Command 1: {' '.join(commandSequence1)}")
+            # click.echo(f"Command 1: {' '.join(commandSequence1)}")
 
             if os.path.exists(FfxController.TEMP_FILE_NAME):
                 os.remove(FfxController.TEMP_FILE_NAME)
@@ -449,7 +449,7 @@ class FfxController():
                                                             FfxController.DEFAULT_FILE_FORMAT,
                                                             FfxController.DEFAULT_FILE_EXTENSION)
 
-            click.echo(f"Command 2: {' '.join(commandSequence2)}")
+            # click.echo(f"Command 2: {' '.join(commandSequence2)}")
 
             if not self.__context['dry_run']:            
                 out, err, rc = executeProcess(commandSequence2)

bin/ffx/file_properties.py

@@ -23,6 +23,8 @@ class FileProperties():
 
         self.context = context
 
+        self.__logger = context['logger']
+
         # Separate basedir, basename and extension for current source file
         self.__sourcePath = sourcePath
 
@@ -167,7 +169,7 @@ class FileProperties():
 
 
     def getMediaDescriptor(self):
-        return MediaDescriptor.fromFfprobe(self.getFormatData(), self.getStreamData())
+        return MediaDescriptor.fromFfprobe(self.context, self.getFormatData(), self.getStreamData())
 
 
     def getShowId(self) -> int:
@@ -233,6 +235,6 @@ class FileProperties():
 
         targetFilename = '_'.join(targetFilenameTokens)
 
-        click.echo(f"Target filename: {targetFilename}")
+        self.__logger.debug(f"assembleTargetFileBasename(): Target filename: {targetFilename}")
 
         return targetFilename

bin/ffx/helper.py

@@ -32,7 +32,6 @@ def dictDiff(a : dict, b : dict):
 def dictCache(element: dict, cache: list = []):
     for index in range(len(cache)):
         diff = dictDiff(cache[index], element)
-        click.echo(f"dictCache() element={element} index={index} cached={cache[index]} diff={diff}")
         if not diff:
             return index, cache
     cache.append(element)

bin/ffx/media_descriptor.py

@@ -1,6 +1,4 @@
-import os
+import os, re, click, logging
-import re
-import click
 
 from typing import List, Self
 
@@ -36,6 +34,17 @@ class MediaDescriptor:
 
     def __init__(self, **kwargs):
 
+        if MediaDescriptor.CONTEXT_KEY in kwargs.keys():
+            if type(kwargs[MediaDescriptor.CONTEXT_KEY]) is not dict:
+                raise TypeError(
+                    f"MediaDescriptor.__init__(): Argument {MediaDescriptor.CONTEXT_KEY} is required to be of type dict"
+                )
+            self.__context = kwargs[MediaDescriptor.CONTEXT_KEY]
+            self.__logger = self.__context['logger']
+        else:
+            self.__context = {}
+            self.__logger = logging.getLogger('FFX').addHandler(logging.NullHandler())
+
         if MediaDescriptor.TAGS_KEY in kwargs.keys():
             if type(kwargs[MediaDescriptor.TAGS_KEY]) is not dict:
                 raise TypeError(
@@ -149,10 +158,12 @@ class MediaDescriptor:
 
 
     @classmethod
-    def fromFfprobe(cls, formatData, streamData):
+    def fromFfprobe(cls, context, formatData, streamData):
 
         kwargs = {}
 
+        kwargs[MediaDescriptor.CONTEXT_KEY] = context
+
         if MediaDescriptor.FFPROBE_TAGS_KEY in formatData.keys():
             kwargs[MediaDescriptor.TAGS_KEY] = formatData[
                 MediaDescriptor.FFPROBE_TAGS_KEY
@@ -242,17 +253,14 @@ class MediaDescriptor:
     def compare(self, vsMediaDescriptor: Self):
 
         if not isinstance(vsMediaDescriptor, self.__class__):
-            raise click.ClickException(
+            errorMessage = f"MediaDescriptor.compare(): Argument is required to be of type {self.__class__}"
-                f"MediaDescriptor.compare(): Argument is required to be of type {self.__class__}"
+            self.__logger.error(errorMessage)
-            )
+            # raise click.ClickException(errorMessage)
+            click.Abort()
 
         vsTags = vsMediaDescriptor.getTags()
         tags = self.getTags()
 
-        # tags ist leer
-        # click.echo(f"tags={tags} vsTags={vsTags}")
-        # raise click.Abort
-
         # HINT: Some tags differ per file, for example creation_time, so these are removed before diff
         for emt in MediaDescriptor.EXCLUDED_MEDIA_TAGS:
             if emt in tags.keys():
@@ -342,7 +350,7 @@ class MediaDescriptor:
 
 
     def getInputMappingTokens(self, use_sub_index: bool = True, only_video: bool = False):
-        """?: Tracks must be reordered for source index order"""
+        """Tracks must be reordered for source index order"""
 
         # reorderedTrackDescriptors = self.getReorderedTrackDescriptors()
         inputMappingTokens = []
@@ -405,22 +413,25 @@ class MediaDescriptor:
 
                         subtitleFileDescriptors.append(subtitleFileDescriptor)
 
-        click.echo(f"Available subtitle files {subtitleFileDescriptors}\n")
+        self.__logger.debug(f"searchSubtitleFiles(): Available subtitle files {subtitleFileDescriptors}")
 
         return subtitleFileDescriptors
 
 
     def importSubtitles(self, searchDirectory, prefix, season: int = -1, episode: int = -1):
         
-        click.echo(f"Season: {season} Episode: {episode}")
+        # click.echo(f"Season: {season} Episode: {episode}")
+        self.__logger.debug(f"importSubtitles(): Season: {season} Episode: {episode}")
 
         availableFileSubtitleDescriptors = self.searchSubtitleFiles(searchDirectory, prefix)
         
-        click.echo(f"availableFileSubtitleDescriptors: {availableFileSubtitleDescriptors}")
+        # click.echo(f"availableFileSubtitleDescriptors: {availableFileSubtitleDescriptors}")
+        self.__logger.debug(f"importSubtitles(): availableFileSubtitleDescriptors: {availableFileSubtitleDescriptors}")
 
         subtitleTracks = self.getSubtitleTracks()
         
-        click.echo(f"subtitleTracks: {[s.getIndex() for s in subtitleTracks]}")
+        # click.echo(f"subtitleTracks: {[s.getIndex() for s in subtitleTracks]}")
+        self.__logger.debug(f"importSubtitles(): subtitleTracks: {[s.getIndex() for s in subtitleTracks]}")
 
         # if len(availableFileSubtitleDescriptors) != len(subtitleTracks):
         #     raise click.ClickException(f"MediaDescriptor.importSubtitles(): Number if subtitle files not matching number of subtitle tracks")
@@ -438,10 +449,13 @@ class MediaDescriptor:
             else []
         )
 
-        click.echo(f"matchingSubtitleFileDescriptors: {matchingSubtitleFileDescriptors}")
+        # click.echo(f"matchingSubtitleFileDescriptors: {matchingSubtitleFileDescriptors}")
+        self.__logger.debug(f"importSubtitles(): matchingSubtitleFileDescriptors: {matchingSubtitleFileDescriptors}")
+        click.echo(f"importSubtitles(): matchingSubtitleFileDescriptors: {matchingSubtitleFileDescriptors}")
 
         for msfd in matchingSubtitleFileDescriptors:
             matchingSubtitleTrackDescriptor = [s for s in subtitleTracks if s.getIndex() == msfd["index"]]
             if matchingSubtitleTrackDescriptor:
-                click.echo(f"Found matching subtitle file {msfd["path"]}\n")
+                # click.echo(f"Found matching subtitle file {msfd["path"]}\n")
+                self.__logger.debug(f"importSubtitles(): Found matching subtitle file {msfd["path"]}")
                 matchingSubtitleTrackDescriptor[0].setExternalSourceFilePath(msfd["path"])

bin/ffx/media_details_screen.py

@@ -157,7 +157,7 @@ class MediaDetailsScreen(Screen):
         self.__currentPattern = self.__mediaFileProperties.getPattern()
 
         # keine tags vorhanden
-        self.__targetMediaDescriptor = self.__currentPattern.getMediaDescriptor() if self.__currentPattern is not None else None
+        self.__targetMediaDescriptor = self.__currentPattern.getMediaDescriptor(self.context) if self.__currentPattern is not None else None
 
         # Enumerating differences between media descriptors
         # from file (=current) vs from stored in database (=target)
@@ -452,7 +452,7 @@ class MediaDetailsScreen(Screen):
                 selected_track_data = self.tracksTable.get_row(row_key)
 
                 kwargs = {}
-                
+                kwargs[TrackDescriptor.CONTEXT_KEY] = self.context
                 kwargs[TrackDescriptor.INDEX_KEY] = int(selected_track_data[0])
                 kwargs[TrackDescriptor.TRACK_TYPE_KEY] = TrackType.fromLabel(selected_track_data[1])
                 kwargs[TrackDescriptor.SUB_INDEX_KEY] = int(selected_track_data[2])

bin/ffx/model/pattern.py

@@ -41,9 +41,9 @@ class Pattern(Base):
     def getShowId(self):
         return int(self.show_id)
 
-    def getShowDescriptor(self) -> ShowDescriptor:
+    def getShowDescriptor(self, context) -> ShowDescriptor:
-        click.echo(f"self.show {self.show} id={self.show_id}")
+        # click.echo(f"self.show {self.show} id={self.show_id}")
-        return self.show.getDescriptor()
+        return self.show.getDescriptor(context)
 
     def getId(self):
         return int(self.id)
@@ -55,11 +55,13 @@ class Pattern(Base):
         return {str(t.key):str(t.value) for t in self.media_tags}
 
 
-    def getMediaDescriptor(self):
+    def getMediaDescriptor(self, context):
 
         kwargs = {}
-        kwargs[MediaDescriptor.TAGS_KEY] = self.getTags()
 
+        kwargs[MediaDescriptor.CONTEXT_KEY] = context
+
+        kwargs[MediaDescriptor.TAGS_KEY] = self.getTags()
         kwargs[MediaDescriptor.TRACK_DESCRIPTOR_LIST_KEY] = []
 
         # Set ordered subindices
@@ -68,7 +70,7 @@ class Pattern(Base):
             trackType = track.getType()
             if not trackType in subIndexCounter.keys():
                 subIndexCounter[trackType] = 0
-            kwargs[MediaDescriptor.TRACK_DESCRIPTOR_LIST_KEY].append(track.getDescriptor(subIndex = subIndexCounter[trackType]))
+            kwargs[MediaDescriptor.TRACK_DESCRIPTOR_LIST_KEY].append(track.getDescriptor(context, subIndex = subIndexCounter[trackType]))
             subIndexCounter[trackType] += 1
 
         return MediaDescriptor(**kwargs)

bin/ffx/model/show.py

@@ -44,10 +44,10 @@ class Show(Base):
     indicator_episode_digits = Column(Integer, default=ShowDescriptor.DEFAULT_INDICATOR_EPISODE_DIGITS)
 
 
-    def getDescriptor(self):
+    def getDescriptor(self, context):
         
         kwargs = {}
-        
+        kwargs[ShowDescriptor.CONTEXT_KEY] = context
         kwargs[ShowDescriptor.ID_KEY] = int(self.id)
         kwargs[ShowDescriptor.NAME_KEY] = str(self.name)
         kwargs[ShowDescriptor.YEAR_KEY] = int(self.year)

bin/ffx/model/track.py

@@ -189,10 +189,12 @@ class Track(Base):
             return bool(self.disposition_flags & 2**disposition.index())
 
 
-    def getDescriptor(self, subIndex : int = -1) -> TrackDescriptor:
+    def getDescriptor(self, context, subIndex : int = -1) -> TrackDescriptor:
 
         kwargs = {}
 
+        kwargs[TrackDescriptor.CONTEXT_KEY] = context
+
         kwargs[TrackDescriptor.ID_KEY] = self.getId()
         kwargs[TrackDescriptor.PATTERN_ID_KEY] = self.getPatternId()
 

bin/ffx/pattern_controller.py

@@ -137,14 +137,14 @@ class PatternController():
         finally:
             s.close()
 
-    def getMediaDescriptor(self, patternId):
+    def getMediaDescriptor(self, context, patternId):
 
         try:
             s = self.Session()
             q = s.query(Pattern).filter(Pattern.id == int(patternId))
 
             if q.count():
-                return q.first().getMediaDescriptor()
+                return q.first().getMediaDescriptor(context)
             else:
                 return None
 

bin/ffx/pattern_details_screen.py

@@ -126,7 +126,7 @@ class PatternDetailsScreen(Screen):
 
             for tr in tracks:
 
-                td : TrackDescriptor = tr.getDescriptor()
+                td : TrackDescriptor = tr.getDescriptor(self.context)
 
                 trackType = td.getType()
                 if not trackType in typeCounter.keys():
@@ -292,7 +292,7 @@ class PatternDetailsScreen(Screen):
                 trackIndex = int(selected_track_data[0])
                 trackSubIndex = int(selected_track_data[2])
 
-                return self.__tc.getTrack(self.__pattern.getId(), trackIndex).getDescriptor(subIndex=trackSubIndex)
+                return self.__tc.getTrack(self.__pattern.getId(), trackIndex).getDescriptor(self.context, subIndex=trackSubIndex)
 
             else:
                 return None

bin/ffx/show_controller.py

@@ -20,7 +20,7 @@ class ShowController():
 
             if q.count():
                 show: Show = q.first() 
-                return show.getDescriptor()
+                return show.getDescriptor(self.context)
 
         except Exception as ex:
             raise click.ClickException(f"ShowController.getShowDescriptor(): {repr(ex)}")

bin/ffx/show_descriptor.py

@@ -1,19 +1,10 @@
-import click
+import logging
-
-from typing import List, Self
-
-from ffx.track_type import TrackType
-from ffx.track_disposition import TrackDisposition
-
-from ffx.track_descriptor import TrackDescriptor
-
-from ffx.helper import dictDiff, DIFF_ADDED_KEY, DIFF_CHANGED_KEY, DIFF_REMOVED_KEY
 
 
 class ShowDescriptor():
     """This class represents the structural content of a media file including streams and metadata"""
 
-    # CONTEXT_KEY = 'context'
+    CONTEXT_KEY = 'context'
     
     ID_KEY = 'id'
     NAME_KEY = 'name'
@@ -32,6 +23,17 @@ class ShowDescriptor():
 
     def __init__(self, **kwargs):
 
+        if ShowDescriptor.CONTEXT_KEY in kwargs.keys():
+            if type(kwargs[ShowDescriptor.CONTEXT_KEY]) is not dict:
+                raise TypeError(
+                    f"ShowDescriptor.__init__(): Argument {ShowDescriptor.CONTEXT_KEY} is required to be of type dict"
+                )
+            self.__context = kwargs[ShowDescriptor.CONTEXT_KEY]
+            self.__logger = self.__context['logger']
+        else:
+            self.__context = {}
+            self.__logger = logging.getLogger('FFX').addHandler(logging.NullHandler())
+
         if ShowDescriptor.ID_KEY in kwargs.keys():
                 if type(kwargs[ShowDescriptor.ID_KEY]) is not int:
                         raise TypeError(f"ShowDescriptor.__init__(): Argument {ShowDescriptor.ID_KEY} is required to be of type int")

bin/ffx/test/helper.py

@@ -169,7 +169,7 @@ def createMediaTestFile(mediaDescriptor: MediaDescriptor,
         if trackType == TrackType.VIDEO:
 
             cacheIndex, generatorCache = dictCache({'type': TrackType.VIDEO}, generatorCache)
-            click.echo(f"createMediaTestFile() cache index={cacheIndex} size={len(generatorCache)}")
+            # click.echo(f"createMediaTestFile() cache index={cacheIndex} size={len(generatorCache)}")
 
             if cacheIndex == -1:
                 generatorTokens += ['-f',
@@ -192,9 +192,9 @@ def createMediaTestFile(mediaDescriptor: MediaDescriptor,
             audioLayout = 'stereo'
 
             cacheIndex, generatorCache = dictCache({'type': TrackType.AUDIO, 'layout': audioLayout}, generatorCache)
-            click.echo(f"createMediaTestFile() cache index={cacheIndex} size={len(generatorCache)}")
+            # click.echo(f"createMediaTestFile() cache index={cacheIndex} size={len(generatorCache)}")
 
-            click.echo(f"generartorCache index={cacheIndex} len={len(generatorCache)}")
+            # click.echo(f"generartorCache index={cacheIndex} len={len(generatorCache)}")
             if cacheIndex == -1:
                 generatorTokens += ['-f',
                                     'lavfi',
@@ -214,7 +214,7 @@ def createMediaTestFile(mediaDescriptor: MediaDescriptor,
         if trackType == TrackType.SUBTITLE:
 
             cacheIndex, generatorCache = dictCache({'type': TrackType.SUBTITLE}, generatorCache)
-            click.echo(f"createMediaTestFile() cache index={cacheIndex} size={len(generatorCache)}")
+            # click.echo(f"createMediaTestFile() cache index={cacheIndex} size={len(generatorCache)}")
 
             if cacheIndex == -1:
                 importTokens = ['-i', createVttFile(SHORT_SUBTITLE_SEQUENCE)]
@@ -254,10 +254,10 @@ def createMediaTestFile(mediaDescriptor: MediaDescriptor,
 
     commandTokens += [outputPath]
 
-    print(f"command sequence: {commandTokens}")
+    # click.echo(f"command sequence: {commandTokens}")
     out, err, rc = executeProcess(commandTokens)
-    if rc:
+    #if rc:
-        print(f"Creating testfile failed with {rc}: {err}")
+    #    click.echo(f"Creating testfile failed with {rc}: {err}")
 
     return outputPath
 

bin/ffx/test/scenario.py

@@ -14,6 +14,9 @@ class Scenario():
                                             os.path.dirname(__file__))),
                                             'ffx.py')
 
+        self._logger = context['logger']
+        self._reportLogger = context['report_logger']
+
     @staticmethod    
     def list():
         basePath = os.path.dirname(__file__)

bin/ffx/test/scenario_1.py

@@ -24,23 +24,27 @@ class Scenario1(Scenario):
 
     def run(self):
 
-        click.echo(f"Running scenario 1")
+        self._logger.info(f"Running {self.__class__.__name__}")
 
         kwargs = {}
+        kwargs[TrackDescriptor.CONTEXT_KEY] = self._context
         kwargs[TrackDescriptor.TRACK_TYPE_KEY] = TrackType.VIDEO
         kwargs[TrackDescriptor.DISPOSITION_SET_KEY] = set([TrackDisposition.DEFAULT])
         trackDescriptor1 = TrackDescriptor(**kwargs)
 
         kwargs = {}
+        kwargs[TrackDescriptor.CONTEXT_KEY] = self._context
         kwargs[TrackDescriptor.TRACK_TYPE_KEY] = TrackType.AUDIO
         kwargs[TrackDescriptor.DISPOSITION_SET_KEY] = set([TrackDisposition.DEFAULT])
         trackDescriptor2 = TrackDescriptor(**kwargs)
 
         kwargs = {}
+        kwargs[TrackDescriptor.CONTEXT_KEY] = self._context
         kwargs[TrackDescriptor.TRACK_TYPE_KEY] = TrackType.AUDIO
         trackDescriptor3 = TrackDescriptor(**kwargs)
 
         kwargs = {}
+        kwargs[MediaDescriptor.CONTEXT_KEY] = self._context
         kwargs[MediaDescriptor.TRACK_DESCRIPTOR_LIST_KEY] = [trackDescriptor1,
                                                                 trackDescriptor2,
                                                                 trackDescriptor3]
@@ -58,11 +62,14 @@ class Scenario1(Scenario):
                             'convert',
                             mediaFilePath]
 
-        click.echo(f"Scenarion 1 test sequence: {commandSequence}")
+        self._logger.debug(f"Scenario1.run(): test sequence: {commandSequence}")
 
         out, err, rc = executeProcess(commandSequence, directory = self._testDirectory)
-        click.echo(f"process output: {out}")
 
+        if out:
+            self._logger.debug(f"Scenario1.run(): process output: {out}")
+        if rc:
+            self._logger.error(f"Scenario1.run(): process resultet in error {rc}: {err}")
 
         # Phase 4: Evaluate results
 
@@ -87,6 +94,9 @@ class Scenario1(Scenario):
             assert resultMediaTracks[2].getType() == TrackType.AUDIO, f"Stream #2 is not of type audio"
             assert resultMediaTracks[2].getDispositionFlag(TrackDisposition.DEFAULT), f"Stream #1 has not set default disposition"
 
+            self._reportLogger.info('Scenario 1 test passed')
+
         except AssertionError as ae:
 
-            click.echo(f"Scenario 1 test failed ({ae})")
+            # click.echo(f"Scenario 1 test failed ({ae})")
+            self._reportLogger.error(f"Scenario 1 test failed ({ae})")

bin/ffx/track_descriptor.py

@@ -1,4 +1,4 @@
-import click
+import logging
 
 from .iso_language import IsoLanguage
 from .track_type import TrackType
@@ -10,6 +10,8 @@ from .helper import dictDiff, setDiff
 
 class TrackDescriptor:
 
+    CONTEXT_KEY = "context"
+
     ID_KEY = "id"
     INDEX_KEY = "index"
     SOURCE_INDEX_KEY = "source_index"
@@ -34,6 +36,17 @@ class TrackDescriptor:
 
     def __init__(self, **kwargs):
 
+        if TrackDescriptor.CONTEXT_KEY in kwargs.keys():
+            if type(kwargs[TrackDescriptor.CONTEXT_KEY]) is not dict:
+                raise TypeError(
+                    f"TrackDescriptor.__init__(): Argument {TrackDescriptor.CONTEXT_KEY} is required to be of type dict"
+                )
+            self.__context = kwargs[TrackDescriptor.CONTEXT_KEY]
+            self.__logger = self.__context['logger']
+        else:
+            self.__context = {}
+            self.__logger = logging.getLogger('FFX').addHandler(logging.NullHandler())
+
         if TrackDescriptor.ID_KEY in kwargs.keys():
             if type(kwargs[TrackDescriptor.ID_KEY]) is not int:
                 raise TypeError(

bin/ffx/track_details_screen.py

@@ -268,6 +268,8 @@ class TrackDetailsScreen(Screen):
 
         kwargs = {}
 
+        kwargs[TrackDescriptor.CONTEXT_KEY] = self.context
+
         kwargs[TrackDescriptor.PATTERN_ID_KEY] = int(self.__pattern.getId())
 
         kwargs[TrackDescriptor.INDEX_KEY] = self.__index

bin/ffx_tests.py

@@ -1,64 +1,73 @@
 #! /usr/bin/python3
 
-import os, sys, subprocess, json, click, time, re, tempfile, math
+import os, logging, click
-from datetime import datetime, timedelta
 
 from ffx.file_properties import FileProperties
-
-from ffx.ffx_app import FfxApp
 from ffx.ffx_controller import FfxController
-from ffx.show_controller import ShowController
-from ffx.tmdb_controller import TmdbController
 
 from ffx.database import databaseContext
 
-from ffx.track_descriptor import TrackDescriptor
-from ffx.track_type import TrackType
-from ffx.video_encoder import VideoEncoder
-from ffx.track_disposition import TrackDisposition
-
-from ffx.process import executeProcess
-
 from ffx.test.helper import createMediaTestFile
 
 from ffx.test.scenario import Scenario
 
-VERSION='0.1.0'
-
-# 0.1.1
-# Bugfixes, TMBD identify shows
-# 0.1.2
-# Bugfixes
-# 0.1.3
-# Subtitle file imports
-
 
 @click.group()
 @click.pass_context
-def ffx(ctx):
+@click.option('-v', '--verbose', type=int, default=0, help='Set verbosity of output')
+@click.option("--dry-run", is_flag=True, default=False)
+def ffx(ctx, verbose, dry_run):
     """FFX"""
 
     ctx.obj = {}
     ctx.obj['database'] = databaseContext(databasePath=None)
+    ctx.obj['dry_run'] = dry_run
 
+    ctx.obj['verbosity'] = verbose
 
-# Define a subcommand
+    # Critical 50
-@ffx.command()
+    # Error 40
-def version():
+    # Warning 30
-    click.echo(VERSION)
+    # Info 20
+    # Debug 10
+    fileLogVerbosity = max(40 - verbose * 10, 10)
+    consoleLogVerbosity = max(20 - verbose * 10, 10)
 
+    homeDir = os.path.expanduser("~")
+    ffxLogDir = os.path.join(homeDir, '.local', 'var', 'log')
+    if not os.path.exists(ffxLogDir):
+        os.makedirs(ffxLogDir)
+    ffxLogFilePath = os.path.join(ffxLogDir, 'ffx.tests.log')
 
-# Another subcommand
+    ctx.obj['logger'] = logging.getLogger('FFX Tests')
-@ffx.command()
+    ctx.obj['logger'].setLevel(logging.DEBUG)
-def help():
+
-    click.echo(f"ffx tests {VERSION}\n")
+    ctx.obj['report_logger'] = logging.getLogger('FFX Test Result')
-    click.echo(f"Usage: ffx_test ...")
+    ctx.obj['report_logger'].setLevel(logging.INFO)
+
+    ffxFileHandler = logging.FileHandler(ffxLogFilePath)
+    ffxFileHandler.setLevel(fileLogVerbosity)
+    ffxConsoleHandler = logging.StreamHandler()
+    ffxConsoleHandler.setLevel(consoleLogVerbosity)
 
+    os.unlink('ffx_test_report.log')
+    ffxTestReportFileHandler = logging.FileHandler('ffx_test_report.log')
 
-# @ffx.command()
+    fileFormatter = logging.Formatter(
-# def show():
+        '%(asctime)s - %(name)s - %(levelname)s - %(message)s')
-#     for i in Scenario().list():
+    ffxFileHandler.setFormatter(fileFormatter)
-#         click.echo(i)
+    consoleFormatter = logging.Formatter(
+        '%(message)s')
+    ffxConsoleHandler.setFormatter(consoleFormatter)
+    reportFormatter = logging.Formatter(
+        '%(message)s')
+    ffxTestReportFileHandler.setFormatter(reportFormatter)
+
+    ctx.obj['logger'].addHandler(ffxConsoleHandler)
+    ctx.obj['logger'].addHandler(ffxFileHandler)
+
+    ctx.obj['report_logger'].addHandler(ffxConsoleHandler)
+    ctx.obj['report_logger'].addHandler(ffxTestReportFileHandler)
     
 
 # Another subcommand
@@ -67,11 +76,13 @@ def help():
 def run(ctx):
     """Run ffx test sequences"""
 
-    for scenarioIdentifier in Scenario().list():
+    ctx.obj['logger'].info('Starting FFX test runs')
+
+    for scenarioIdentifier in Scenario.list():
 
         scenario = Scenario.getClassReference(scenarioIdentifier)(ctx.obj)
 
-        click.echo(f"Running scenario {scenarioIdentifier}")
+        ctx.obj['logger'].info(f"Running scenario {scenarioIdentifier}")
 
         scenario.run()
 

bin/logg.py

@@ -0,0 +1,52 @@
+#! /usr/bin/python3
+
+import logging
+
+logger = logging.getLogger('FFX')
+logger.setLevel(logging.DEBUG)
+
+testLogger = logging.getLogger('FFX Test')
+testLogger.setLevel(logging.DEBUG)
+
+
+# create file handler that logs debug and higher level messages
+ffxFileHandler = logging.FileHandler('ffx.log')
+ffxFileHandler.setLevel(logging.DEBUG)
+
+# create file handler that logs debug and higher level messages
+ffxTestReportFileHandler = logging.FileHandler('ffx_test_report.log')
+ffxTestReportFileHandler.setLevel(logging.DEBUG)
+
+# create console handler with a higher log level
+ffxConsoleHandler = logging.StreamHandler()
+#ffxConsoleHandler.setLevel(logging.ERROR)
+
+# create formatter and add it to the handlers
+formatter = logging.Formatter(
+    '%(asctime)s - %(name)s - %(levelname)s - %(message)s')
+ffxConsoleHandler.setFormatter(formatter)
+ffxFileHandler.setFormatter(formatter)
+
+
+# add the handlers to logger
+testLogger.addHandler(ffxConsoleHandler)
+
+
+logger.addHandler(ffxConsoleHandler)
+logger.addHandler(ffxFileHandler)
+
+
+
+logger.debug('debug message')
+logger.info('info message')
+logger.warning('warn message')
+logger.error('error message')
+logger.critical('critical message')
+
+
+testLogger.info('TEST: info message')
+
+
+
+click / consoleLogger
+