using the builtin logging module

src/component.py

@@ -8,6 +8,7 @@ import os
 import sys
 import math
 import time
+import logging
 
 from toolkit.frame import BlankFrame
 from toolkit import (
@@ -15,6 +16,9 @@ from toolkit import (
 )
 
 
+log = logging.getLogger('AVP.ComponentHandler')
+
+
 class ComponentMetaclass(type(QtCore.QObject)):
     '''
         Checks the validity of each Component class and mutates some attrs.
@@ -135,17 +139,17 @@ class ComponentMetaclass(type(QtCore.QObject)):
         # Turn version string into a number
         try:
             if 'version' not in attrs:
-                print(
+                log.error(
                     'No version attribute in %s. Defaulting to 1' %
                     attrs['name'])
                 attrs['version'] = 1
             else:
                 attrs['version'] = int(attrs['version'].split('.')[0])
         except ValueError:
-            print('%s component has an invalid version string:\n%s' % (
+            log.critical('%s component has an invalid version string:\n%s' % (
                     attrs['name'], str(attrs['version'])))
         except KeyError:
-            print('%s component has no version string.' % attrs['name'])
+            log.critical('%s component has no version string.' % attrs['name'])
         else:
             return super().__new__(cls, name, parents, attrs)
         quit(1)
@@ -546,6 +550,8 @@ class Component(QtCore.QObject, metaclass=ComponentMetaclass):
                     and oldRelativeVal != newRelativeVal:
                 # Float changed without pixel value changing, which
                 # means the pixel value needs to be updated
+                log.debug('Updating %s #%s\'s relative widget: %s' % (
+                    self.name, self.compPos, attr))
                 self._trackedWidgets[attr].blockSignals(True)
                 self.updateRelativeWidgetMaximum(attr)
                 pixelVal = self.pixelValForAttr(attr, oldRelativeVal)
@@ -576,7 +582,7 @@ class ComponentError(RuntimeError):
             msg = str(sys.exc_info()[1])
         else:
             msg = 'Unknown error.'
-        print("##### ComponentError by %s's %s: %s" % (
+        log.error("ComponentError by %s's %s: %s" % (
             caller.name, name, msg))
 
         # Don't create multiple windows for quickly repeated messages

src/components/spectrum.py

@@ -4,6 +4,7 @@ import os
 import math
 import subprocess
 import time
+import logging
 
 from component import Component
 from toolkit.frame import BlankFrame, scale
@@ -13,6 +14,9 @@ from toolkit.ffmpeg import (
 )
 
 
+log = logging.getLogger('AVP.Components.Spectrum')
+
+
 class Component(Component):
     name = 'Spectrum'
     version = '1.0.0'
@@ -68,6 +72,7 @@ class Component(Component):
         if not changedSize \
                 and not self.changedOptions \
                 and self.previewFrame is not None:
+            log.debug('Comp #%s is reusing old preview frame' % self.compPos)
             return self.previewFrame
 
         frame = self.getPreviewFrame()
@@ -131,13 +136,14 @@ class Component(Component):
             '-frames:v', '1',
         ])
         logFilename = os.path.join(
-            self.core.dataDir, 'preview_%s.log' % str(self.compPos))
+            self.core.logDir, 'preview_%s.log' % str(self.compPos))
-        with open(logFilename, 'w') as log:
+        log.debug('Creating ffmpeg process (log at %s)' % logFilename)
-            log.write(" ".join(command) + '\n\n')
+        with open(logFilename, 'w') as logf:
-        with open(logFilename, 'a') as log:
+            logf.write(" ".join(command) + '\n\n')
+        with open(logFilename, 'a') as logf:
             pipe = openPipe(
                 command, stdin=subprocess.DEVNULL, stdout=subprocess.PIPE,
-                stderr=log, bufsize=10**8
+                stderr=logf, bufsize=10**8
             )
         byteFrame = pipe.stdout.read(self.chunkSize)
         closePipe(pipe)

src/components/video.py

@@ -3,6 +3,7 @@ from PyQt5 import QtGui, QtCore, QtWidgets
 import os
 import math
 import subprocess
+import logging
 
 from component import Component
 from toolkit.frame import BlankFrame, scale
@@ -10,6 +11,9 @@ from toolkit.ffmpeg import openPipe, closePipe, testAudioStream, FfmpegVideo
 from toolkit import checkOutput
 
 
+log = logging.getLogger('AVP.Components.Video')
+
+
 class Component(Component):
     name = 'Video'
     version = '1.0.0'
@@ -134,10 +138,17 @@ class Component(Component):
             '-ss', '90',
             '-frames:v', '1',
         ])
-        pipe = openPipe(
+
-            command, stdin=subprocess.DEVNULL, stdout=subprocess.PIPE,
+        logFilename = os.path.join(
-            stderr=subprocess.DEVNULL, bufsize=10**8
+            self.core.logDir, 'preview_%s.log' % str(self.compPos))
-        )
+        log.debug('Creating ffmpeg process (log at %s)' % logFilename)
+        with open(logFilename, 'w') as logf:
+            logf.write(" ".join(command) + '\n\n')
+        with open(logFilename, 'a') as logf:
+            pipe = openPipe(
+                command, stdin=subprocess.DEVNULL, stdout=subprocess.PIPE,
+                stderr=logf, bufsize=10**8
+            )
         byteFrame = pipe.stdout.read(self.chunkSize)
         closePipe(pipe)
 

src/components/waveform.py

@@ -4,6 +4,7 @@ from PyQt5.QtGui import QColor
 import os
 import math
 import subprocess
+import logging
 
 from component import Component
 from toolkit.frame import BlankFrame, scale
@@ -13,6 +14,9 @@ from toolkit.ffmpeg import (
 )
 
 
+log = logging.getLogger('AVP.Components.Waveform')
+
+
 class Component(Component):
     name = 'Waveform'
     version = '1.0.0'
@@ -106,10 +110,16 @@ class Component(Component):
             '-codec:v', 'rawvideo', '-',
             '-frames:v', '1',
         ])
-        pipe = openPipe(
+        logFilename = os.path.join(
-            command, stdin=subprocess.DEVNULL, stdout=subprocess.PIPE,
+            self.core.logDir, 'preview_%s.log' % str(self.compPos))
-            stderr=subprocess.DEVNULL, bufsize=10**8
+        log.debug('Creating ffmpeg process (log at %s)' % logFilename)
-        )
+        with open(logFilename, 'w') as logf:
+            logf.write(" ".join(command) + '\n\n')
+        with open(logFilename, 'a') as logf:
+            pipe = openPipe(
+                command, stdin=subprocess.DEVNULL, stdout=subprocess.PIPE,
+                stderr=logf, bufsize=10**8
+            )
         byteFrame = pipe.stdout.read(self.chunkSize)
         closePipe(pipe)
 

src/core.py

@@ -7,11 +7,17 @@ import sys
 import os
 import json
 from importlib import import_module
+import logging
 
 import toolkit
 import video_thread
 
 
+log = logging.getLogger('AVP.Core')
+STDOUT_LOGLVL = logging.WARNING
+FILE_LOGLVL = logging.DEBUG
+
+
 class Core:
     '''
         MainWindow and Command module both use an instance of this class
@@ -35,6 +41,7 @@ class Core:
                     continue
                 elif ext == '.py':
                     yield name
+        log.debug('Importing component modules')
         self.modules = [
             import_module('components.%s' % name)
             for name in findComponents()
@@ -67,7 +74,7 @@ class Core:
             compPos = len(self.selectedComponents)
         if len(self.selectedComponents) > 50:
             return None
-
+        log.debug('Inserting Component from module #%s' % moduleIndex)
         component = self.modules[moduleIndex].Component(
             moduleIndex, compPos, self
         )
@@ -104,7 +111,7 @@ class Core:
         self.componentListChanged()
 
     def updateComponent(self, i):
-        # print('updating %s' % self.selectedComponents[i])
+        log.debug('Updating %s #%s' % (self.selectedComponents[i], str(i)))
         self.selectedComponents[i].update()
 
     def moduleIndexFor(self, compName):
@@ -125,12 +132,17 @@ class Core:
         if not saveValueStore:
             return False
         try:
-            self.selectedComponents[compIndex].loadPreset(
+            comp = self.selectedComponents[compIndex]
+            comp.loadPreset(
                 saveValueStore,
                 presetName
             )
         except KeyError as e:
-            print('preset missing value: %s' % e)
+            log.warning(
+                '%s #%s\'s preset is missing value: %s' % (
+                    comp.name, str(compIndex), str(e)
+                )
+            )
 
         self.savedPresets[presetName] = dict(saveValueStore)
         return True
@@ -206,7 +218,7 @@ class Core:
                                 preset['preset']
                             )
                     except KeyError as e:
-                        print('%s missing value: %s' % (
+                        log.warning('%s missing value: %s' % (
                             self.selectedComponents[i], e)
                         )
 
@@ -224,7 +236,7 @@ class Core:
             typ, value, tb = data
             if typ.__name__ == 'KeyError':
                 # probably just an old version, still loadable
-                print('file missing value: %s' % value)
+                log.warning('Project file missing value: %s' % value)
                 return
             if hasattr(loader, 'createNewProject'):
                 loader.createNewProject(prompt=False)
@@ -244,6 +256,7 @@ class Core:
             Returns dictionary with section names as the keys, each one
             contains a list of tuples: (compName, version, compPresetDict)
         '''
+        log.debug('Parsing av file: %s' % filepath)
         validSections = (
                     'Components',
                     'Settings',
@@ -362,6 +375,7 @@ class Core:
 
     def createProjectFile(self, filepath, window=None):
         '''Create a project file (.avp) using the current program state'''
+        log.info('Creating %s' % filepath)
         settingsKeys = [
             'componentDir',
             'inputDir',
@@ -374,9 +388,8 @@ class Core:
                 filepath += '.avp'
             if os.path.exists(filepath):
                 os.remove(filepath)
-            with open(filepath, 'w') as f:
-                print('creating %s' % filepath)
 
+            with open(filepath, 'w') as f:
                 f.write('[Components]\n')
                 for comp in self.selectedComponents:
                     saveValueStore = comp.savePreset()
@@ -443,6 +456,7 @@ class Core:
             'settings': QtCore.QSettings(
                             os.path.join(dataDir, 'settings.ini'),
                             QtCore.QSettings.IniFormat),
+            'logDir': os.path.join(dataDir, 'log'),
             'presetDir': os.path.join(dataDir, 'presets'),
             'componentsPath': os.path.join(wd, 'components'),
             'encoderOptions': encoderOptions,
@@ -489,6 +503,13 @@ class Core:
             setattr(cls, classvar, val)
 
         cls.loadDefaultSettings()
+        if not os.path.exists(cls.dataDir):
+            os.makedirs(cls.dataDir)
+        for neededDirectory in (
+          cls.presetDir, cls.logDir, cls.settings.value("projectDir")):
+            if not os.path.exists(neededDirectory):
+                os.mkdir(neededDirectory)
+        cls.makeLogger()
 
     @classmethod
     def loadDefaultSettings(cls):
@@ -522,6 +543,42 @@ class Core:
             if val in ('true', 'false'):
                 cls.settings.setValue(key, True if val == 'true' else False)
 
+    @staticmethod
+    def makeLogger():
+        logFilename = os.path.join(Core.logDir, 'avp_debug.log')
+        libLogFilename = os.path.join(Core.logDir, 'global_debug.log')
+        # delete old logs
+        for log in (logFilename, libLogFilename):
+            if os.path.exists(log):
+                os.remove(log)
+
+        # create file handlers to capture every log message somewhere
+        logFile = logging.FileHandler(logFilename)
+        logFile.setLevel(FILE_LOGLVL)
+        libLogFile = logging.FileHandler(libLogFilename)
+        libLogFile.setLevel(FILE_LOGLVL)
+
+        # send some critical log messages to stdout as well
+        logStream = logging.StreamHandler()
+        logStream.setLevel(STDOUT_LOGLVL)
+
+        # create formatters and put everything together
+        fileFormatter = logging.Formatter(
+            '[%(asctime)s] <%(name)s> %(levelname)s: %(message)s'
+        )
+        streamFormatter = logging.Formatter(
+            '<%(name)s> %(message)s'
+        )
+        logFile.setFormatter(fileFormatter)
+        libLogFile.setFormatter(fileFormatter)
+        logStream.setFormatter(streamFormatter)
+        log = logging.getLogger('AVP')
+        log.setLevel(FILE_LOGLVL)
+        log.addHandler(logFile)
+        log.addHandler(logStream)
+        libLog = logging.getLogger()
+        libLog.setLevel(FILE_LOGLVL)
+        libLog.addHandler(libLogFile)
 
 # always store settings in class variables even if a Core object is not created
 Core.storeSettings()

src/main.py

@@ -1,10 +1,14 @@
 from PyQt5 import uic, QtWidgets
 import sys
 import os
+import logging
 
 from __init__ import wd
 
 
+log = logging.getLogger('AVP.Entrypoint')
+
+
 def main():
     app = QtWidgets.QApplication(sys.argv)
     app.setApplicationName("audio-visualizer")
@@ -28,6 +32,7 @@ def main():
         from command import Command
 
         main = Command()
+        log.debug("Finished creating command object")
 
     elif mode == 'GUI':
         from mainwindow import MainWindow
@@ -48,6 +53,7 @@ def main():
         # window.verticalLayout_2.setContentsMargins(0, topMargin, 0, 0)
 
         main = MainWindow(window, proj)
+        log.debug("Finished creating main window")
         window.raise_()
 
         signal.signal(signal.SIGINT, main.cleanUp)

src/mainwindow.py

@@ -13,6 +13,7 @@ import os
 import signal
 import filecmp
 import time
+import logging
 
 from core import Core
 import preview_thread
@@ -20,11 +21,15 @@ from presetmanager import PresetManager
 from toolkit import disableWhenEncoding, disableWhenOpeningProject, checkOutput
 
 
+log = logging.getLogger('AVP.MainWindow')
+
+
 class PreviewWindow(QtWidgets.QLabel):
     '''
         Paints the preview QLabel and maintains the aspect ratio when the
         window is resized.
     '''
+    log = logging.getLogger('AVP.MainWindow.Preview')
 
     def __init__(self, parent, img):
         super(PreviewWindow, self).__init__()
@@ -58,11 +63,15 @@ class PreviewWindow(QtWidgets.QLabel):
         if i >= 0:
             component = self.parent.core.selectedComponents[i]
             if not hasattr(component, 'previewClickEvent'):
+                self.log.info('Ignored click event')
                 return
             pos = (event.x(), event.y())
             size = (self.width(), self.height())
+            butt = event.button()
+            self.log.info('Click event for #%s: %s button %s' % (
+                i, pos, butt))
             component.previewClickEvent(
-                pos, size, event.button()
+                pos, size, butt
             )
             self.parent.core.updateComponent(i)
 
@@ -91,9 +100,10 @@ class MainWindow(QtWidgets.QMainWindow):
 
     def __init__(self, window, project):
         QtWidgets.QMainWindow.__init__(self)
-        # print('main thread id: {}'.format(QtCore.QThread.currentThreadId()))
         self.window = window
         self.core = Core()
+        log.debug(
+            'Main thread id: {}'.format(QtCore.QThread.currentThreadId()))
 
         # widgets of component settings
         self.pages = []
@@ -103,27 +113,23 @@ class MainWindow(QtWidgets.QMainWindow):
         self.autosaveCooldown = 0.2
         self.encoding = False
 
-        # Create data directory, load/create settings
+        # Find settings created by Core object
         self.dataDir = Core.dataDir
         self.presetDir = Core.presetDir
         self.autosavePath = os.path.join(self.dataDir, 'autosave.avp')
         self.settings = Core.settings
+
         self.presetManager = PresetManager(
             uic.loadUi(
                 os.path.join(Core.wd, 'presetmanager.ui')), self)
 
-        if not os.path.exists(self.dataDir):
-            os.makedirs(self.dataDir)
-        for neededDirectory in (
-          self.presetDir, self.settings.value("projectDir")):
-            if not os.path.exists(neededDirectory):
-                os.mkdir(neededDirectory)
-
         # Create the preview window and its thread, queues, and timers
+        log.debug('Creating preview window')
         self.previewWindow = PreviewWindow(self, os.path.join(
             Core.wd, "background.png"))
         window.verticalLayout_previewWrapper.addWidget(self.previewWindow)
 
+        log.debug('Starting preview thread')
         self.previewQueue = Queue()
         self.previewThread = QtCore.QThread(self)
         self.previewWorker = preview_thread.Worker(self, self.previewQueue)
@@ -132,6 +138,7 @@ class MainWindow(QtWidgets.QMainWindow):
         self.previewWorker.imageCreated.connect(self.showPreviewImage)
         self.previewThread.start()
 
+        log.debug('Starting preview timer')
         self.timer = QtCore.QTimer(self)
         self.timer.timeout.connect(self.processTask.emit)
         self.timer.start(500)
@@ -141,6 +148,8 @@ class MainWindow(QtWidgets.QMainWindow):
         componentList = self.window.listWidget_componentList
 
         if sys.platform == 'darwin':
+            log.debug(
+                'Darwin detected: showing progress label below progress bar')
             window.progressBar_createVideo.setTextVisible(False)
         else:
             window.progressLabel.setHidden(True)
@@ -276,6 +285,7 @@ class MainWindow(QtWidgets.QMainWindow):
         )
 
         self.updateWindowTitle()
+        log.debug('Showing main window')
         window.show()
 
         if project and project != self.autosavePath:
@@ -398,6 +408,7 @@ class MainWindow(QtWidgets.QMainWindow):
 
     @QtCore.pyqtSlot()
     def cleanUp(self, *args):
+        log.info('Ending the preview thread')
         self.timer.stop()
         self.previewThread.quit()
         self.previewThread.wait()
@@ -414,11 +425,12 @@ class MainWindow(QtWidgets.QMainWindow):
                 appName += '*'
         except AttributeError:
             pass
+        log.debug('Setting window title to %s' % appName)
         self.window.setWindowTitle(appName)
 
     @QtCore.pyqtSlot(int, dict)
     def updateComponentTitle(self, pos, presetStore=False):
-        if type(presetStore) == dict:
+        if type(presetStore) is dict:
             name = presetStore['preset']
             if name is None or name not in self.core.savedPresets:
                 modified = False
@@ -428,11 +440,20 @@ class MainWindow(QtWidgets.QMainWindow):
             modified = bool(presetStore)
         if pos < 0:
             pos = len(self.core.selectedComponents)-1
-        title = str(self.core.selectedComponents[pos])
+        name = str(self.core.selectedComponents[pos])
+        title = str(name)
         if self.core.selectedComponents[pos].currentPreset:
             title += ' - %s' % self.core.selectedComponents[pos].currentPreset
             if modified:
                 title += '*'
+        if type(presetStore) is bool:
+            log.debug('Forcing %s #%s\'s modified status to %s: %s' % (
+                name, pos, modified, title
+            ))
+        else:
+            log.debug('Setting %s #%s\'s title: %s' % (
+                name, pos, title
+            ))
         self.window.listWidget_componentList.item(pos).setText(title)
 
     def updateCodecs(self):
@@ -493,6 +514,8 @@ class MainWindow(QtWidgets.QMainWindow):
                 elif force or timeDiff >= self.autosaveCooldown * 5:
                     self.autosaveCooldown = 0.2
             self.autosaveTimes.insert(0, self.lastAutosave)
+        else:
+            log.debug('Autosave rejected by cooldown')
 
     def autosaveExists(self, identical=True):
         '''Determines if creating the autosave should be blocked.'''
@@ -500,9 +523,14 @@ class MainWindow(QtWidgets.QMainWindow):
             if self.currentProject and os.path.exists(self.autosavePath) \
                 and filecmp.cmp(
                     self.autosavePath, self.currentProject) == identical:
+                log.debug(
+                    'Autosave found %s to be identical' % \
+                        'not' if not identical else ''
+                )
                 return True
         except FileNotFoundError:
-            print('project file couldn\'t be located:', self.currentProject)
+            log.error(
+                'Project file couldn\'t be located:', self.currentProject)
             return identical
         return False
 
@@ -543,7 +571,7 @@ class MainWindow(QtWidgets.QMainWindow):
             self.window.lineEdit_outputFile.setText(fileName)
 
     def stopVideo(self):
-        print('stop')
+        log.info('Export cancelled')
         self.videoWorker.cancel()
         self.canceled = True
 
@@ -773,6 +801,7 @@ class MainWindow(QtWidgets.QMainWindow):
             mousePos = -1
         else:
             mousePos = mousePos.index(True)
+        log.debug('Click component list row %s' % mousePos)
         return mousePos
 
     @disableWhenEncoding

src/preview_thread.py

@@ -8,11 +8,15 @@ from PIL import Image
 from PIL.ImageQt import ImageQt
 from queue import Queue, Empty
 import os
+import logging
 
 from toolkit.frame import Checkerboard
 from toolkit import disableWhenOpeningProject
 
 
+log = logging.getLogger("AVP.PreviewThread")
+
+
 class Worker(QtCore.QObject):
 
     imageCreated = pyqtSignal(QtGui.QImage)
@@ -55,7 +59,7 @@ class Worker(QtCore.QObject):
                 self.background = Checkerboard(width, height)
 
             frame = self.background.copy()
-
+            log.debug('Creating new preview frame')
             components = nextPreviewInformation["components"]
             for component in reversed(components):
                 try:
@@ -73,10 +77,11 @@ class Worker(QtCore.QObject):
                             newFrame.width, newFrame.height,
                             width, height
                         )
+                    log.critical(errMsg)
                     self.error.emit(errMsg)
                     break
                 except RuntimeError as e:
-                    print(e)
+                    log.error(str(e))
             else:
                 self.frame = ImageQt(frame)
                 self.imageCreated.emit(QtGui.QImage(self.frame))

src/toolkit/ffmpeg.py

@@ -8,12 +8,16 @@ import subprocess
 import threading
 import signal
 from queue import PriorityQueue
+import logging
 
 import core
 from toolkit.common import checkOutput, pipeWrapper
 from component import ComponentError
 
 
+log = logging.getLogger('AVP.Toolkit.Ffmpeg')
+
+
 class FfmpegVideo:
     '''Opens a pipe to ffmpeg and stores a buffer of raw video frames.'''
 
@@ -88,13 +92,14 @@ class FfmpegVideo:
 
     def fillBuffer(self):
         logFilename = os.path.join(
-            core.Core.dataDir, 'extra_%s.log' % str(self.component.compPos))
+            core.Core.logDir, 'render_%s.log' % str(self.component.compPos))
-        with open(logFilename, 'w') as log:
+        log.debug('Creating ffmpeg process (log at %s)' % logFilename)
-            log.write(" ".join(self.command) + '\n\n')
+        with open(logFilename, 'w') as logf:
-        with open(logFilename, 'a') as log:
+            logf.write(" ".join(self.command) + '\n\n')
+        with open(logFilename, 'a') as logf:
             self.pipe = openPipe(
                 self.command, stdin=subprocess.DEVNULL, stdout=subprocess.PIPE,
-                stderr=log, bufsize=10**8
+                stderr=logf, bufsize=10**8
             )
         while True:
             if self.parent.canceled:
@@ -375,7 +380,7 @@ def getAudioDuration(filename):
     try:
         info = fileInfo.decode("utf-8").split('\n')
     except UnicodeDecodeError as e:
-        print('Unicode error:', str(e))
+        log.error('Unicode error:', str(e))
         return False
 
     for line in info:
@@ -398,7 +403,7 @@ def readAudioFile(filename, videoWorker):
     '''
     duration = getAudioDuration(filename)
     if not duration:
-        print('Audio file doesn\'t exist or unreadable.')
+        log.error('Audio file doesn\'t exist or unreadable.')
         return
 
     command = [

src/toolkit/frame.py

@@ -7,10 +7,14 @@ from PIL.ImageQt import ImageQt
 import sys
 import os
 import math
+import logging
 
 import core
 
 
+log = logging.getLogger('AVP.Toolkit.Frame')
+
+
 class FramePainter(QtGui.QPainter):
     '''
         A QPainter for a blank frame, which can be converted into a
@@ -79,6 +83,7 @@ def FloodFrame(width, height, RgbaTuple):
 @defaultSize
 def BlankFrame(width, height):
     '''The base frame used by each component to start drawing.'''
+    log.debug('Creating new %s*%s blank frame' % (width, height))
     return FloodFrame(width, height, (0, 0, 0, 0))
 
 
@@ -88,6 +93,7 @@ def Checkerboard(width, height):
         A checkerboard to represent transparency to the user.
         TODO: Would be cool to generate this image with numpy instead.
     '''
+    log.debug('Creating new %s*%s checkerboard' % (width, height))
     image = FloodFrame(1920, 1080, (0, 0, 0, 0))
     image.paste(Image.open(
         os.path.join(core.Core.wd, "background.png")),

src/video_thread.py

@@ -17,6 +17,7 @@ from queue import Queue, PriorityQueue
 from threading import Thread, Event
 import time
 import signal
+import logging
 
 from component import ComponentError
 from toolkit.frame import Checkerboard
@@ -26,6 +27,9 @@ from toolkit.ffmpeg import (
 )
 
 
+log = logging.getLogger("AVP.VideoThread")
+
+
 class Worker(QtCore.QObject):
 
     imageCreated = pyqtSignal(['QImage'])
@@ -92,7 +96,7 @@ class Worker(QtCore.QObject):
             by a renderNode later. All indices are multiples of self.sampleSize
             sampleSize * frameNo = audioI, AKA audio data starting at frameNo
         '''
-        print('Dispatching Frames for Compositing...')
+        log.debug('Dispatching Frames for Compositing...')
 
         for audioI in range(0, len(self.completeAudioArray), self.sampleSize):
             self.compositeQueue.put(audioI)
@@ -156,10 +160,12 @@ class Worker(QtCore.QObject):
         self.progressBarUpdate.emit(0)
         self.progressBarSetText.emit("Starting components...")
         canceledByComponent = False
-        print('Loaded Components:', ", ".join([
+        initText =  ", ".join([
             "%s) %s" % (num, str(component))
             for num, component in enumerate(reversed(self.components))
-        ]))
+        ])
+        print('Loaded Components:', initText)
+        log.info('Calling preFrameRender for %s' % initText)
         self.staticComponents = {}
         for compNo, comp in enumerate(reversed(self.components)):
             try:
@@ -191,6 +197,7 @@ class Worker(QtCore.QObject):
                         compError[0]
                     )
                 )
+                log.critical(errMsg)
                 comp._error.emit(errMsg, compError[1])
                 break
             if 'static' in compProps:
@@ -199,7 +206,7 @@ class Worker(QtCore.QObject):
 
         if self.canceled:
             if canceledByComponent:
-                print('Export cancelled by component #%s (%s): %s' % (
+                log.critical('Export cancelled by component #%s (%s): %s' % (
                     compNo,
                     comp.name,
                     'No message.' if comp.error() is None else (
@@ -224,8 +231,11 @@ class Worker(QtCore.QObject):
         ffmpegCommand = createFfmpegCommand(
             self.inputFile, self.outputFile, self.components, duration
         )
-        print('###### FFMPEG COMMAND ######\n%s' % " ".join(ffmpegCommand))
+        cmd = " ".join(ffmpegCommand)
+        print('###### FFMPEG COMMAND ######\n%s' % cmd)
         print('############################')
+        log.info('Opening pipe to ffmpeg')
+        log.info(cmd)
         self.out_pipe = openPipe(
             ffmpegCommand, stdin=sp.PIPE, stdout=sys.stdout, stderr=sys.stdout
         )
@@ -298,9 +308,9 @@ class Worker(QtCore.QObject):
         try:
             self.out_pipe.stdin.close()
         except BrokenPipeError:
-            print('Broken pipe to ffmpeg!')
+            log.error('Broken pipe to ffmpeg!')
         if self.out_pipe.stderr is not None:
-            print(self.out_pipe.stderr.read())
+            log.error(self.out_pipe.stderr.read())
             self.out_pipe.stderr.close()
             self.error = True
         self.out_pipe.wait()