Replace sys.std{out,err} statements with logger/print calls (#331)

* Change global default log level to 'INFO'

We're going to increase our usage of logger statements instead of print instructions (where deemed opportune).

* Replace sys.std{out,err} statements with logger/print calls

Fixes #303.

whipper/__init__.py

@@ -4,7 +4,7 @@
 
 __version__ = '0.7.2'
 
-level = logging.WARNING
+level = logging.INFO
 if 'WHIPPER_DEBUG' in os.environ:
     level = os.environ['WHIPPER_DEBUG'].upper()
 if 'WHIPPER_LOGFILE' in os.environ:

whipper/command/accurip.py

@@ -18,8 +18,6 @@
 # You should have received a copy of the GNU General Public License
 # along with whipper.  If not, see <http://www.gnu.org/licenses/>.
 
-import sys
-
 from whipper.command.basecommand import BaseCommand
 from whipper.common.accurip import get_db_entry, ACCURATERIP_URL
 
@@ -42,18 +40,17 @@ def do(self):
 
         count = responses[0].num_tracks
 
-        sys.stdout.write("Found %d responses for %d tracks\n\n" % (
-            len(responses), count))
+        logger.info("Found %d responses for %d tracks",
+                    (len(responses), count))
 
         for (i, r) in enumerate(responses):
             if r.num_tracks != count:
-                sys.stdout.write(
-                    "Warning: response %d has %d tracks instead of %d\n" % (
-                        i, r.num_tracks, count))
+                logger.warning("response %d has %d tracks instead of %d", (
+                               i, r.num_tracks, count))
 
         # checksum and confidence by track
         for track in range(count):
-            sys.stdout.write("Track %d:\n" % (track + 1))
+            print("Track %d:" % (track + 1))
             checksums = {}
 
             for (i, r) in enumerate(responses):
@@ -82,9 +79,9 @@ def do(self):
             sortedChecksums.reverse()
 
             for highest, checksum in sortedChecksums:
-                sys.stdout.write("  %d result(s) for checksum %s: %s\n" % (
-                    len(checksums[checksum]), checksum,
-                    str(checksums[checksum])))
+                print("  %d result(s) for checksum %s: %s" % (
+                      len(checksums[checksum]),
+                      checksum, str(checksums[checksum])))
 
 
 class AccuRip(BaseCommand):

whipper/command/cd.py

@@ -22,7 +22,6 @@
 import cdio
 import os
 import glob
-import sys
 import logging
 from whipper.command.basecommand import BaseCommand
 from whipper.common import (
@@ -84,29 +83,28 @@ def add_arguments(parser):
     def do(self):
         self.config = config.Config()
         self.program = program.Program(self.config,
-                                       record=self.options.record,
-                                       stdout=sys.stdout)
+                                       record=self.options.record)
         self.runner = task.SyncRunner()
 
         # if the device is mounted (data session), unmount it
         self.device = self.options.device
-        sys.stdout.write('Checking device %s\n' % self.device)
+        logger.info('checking device %s', self.device)
 
         utils.load_device(self.device)
         utils.unmount_device(self.device)
 
         # first, read the normal TOC, which is fast
-        print("Reading TOC...")
+        logger.info("reading TOC...")
         self.ittoc = self.program.getFastToc(self.runner, self.device)
 
         # already show us some info based on this
         self.program.getRipResult(self.ittoc.getCDDBDiscId())
-        sys.stdout.write("CDDB disc id: %s\n" % self.ittoc.getCDDBDiscId())
+        print("CDDB disc id: %s" % self.ittoc.getCDDBDiscId())
         self.mbdiscid = self.ittoc.getMusicBrainzDiscId()
-        sys.stdout.write("MusicBrainz disc id %s\n" % self.mbdiscid)
+        print("MusicBrainz disc id %s" % self.mbdiscid)
 
-        sys.stdout.write("MusicBrainz lookup URL %s\n" %
-                         self.ittoc.getMusicBrainzSubmitURL())
+        print("MusicBrainz lookup URL %s" %
+              self.ittoc.getMusicBrainzSubmitURL())
 
         self.program.metadata = (
             self.program.getMusicBrainz(self.ittoc, self.mbdiscid,
@@ -120,12 +118,12 @@ def do(self):
             cddbid = self.ittoc.getCDDBValues()
             cddbmd = self.program.getCDDB(cddbid)
             if cddbmd:
-                sys.stdout.write('FreeDB identifies disc as %s\n' % cddbmd)
+                logger.info('FreeDB identifies disc as %s', cddbmd)
 
             # also used by rip cd info
             if not getattr(self.options, 'unknown', False):
                 logger.critical("unable to retrieve disc metadata, "
-                                "--unknown not passed")
+                                "--unknown argument not passed")
                 return -1
 
         self.program.result.isCdr = cdrdao.DetectCdr(self.device)
@@ -236,8 +234,7 @@ def add_arguments(self):
         if info:
             try:
                 default_offset = config.Config().getReadOffset(*info)
-                sys.stdout.write("Using configured read offset %d\n" %
-                                 default_offset)
+                logger.info("using configured read offset %d", default_offset)
             except KeyError:
                 pass
 
@@ -340,7 +337,8 @@ def doCommand(self):
                 logger.critical(msg)
                 raise RuntimeError(msg)
         else:
-            print("creating output directory %s" % dirname.encode('utf-8'))
+            logger.info("creating output directory %s",
+                        dirname.encode('utf-8'))
             os.makedirs(dirname)
 
         # FIXME: turn this into a method
@@ -381,11 +379,11 @@ def _ripIfNotRipped(number):
                     logger.debug('previous result %r, expected %r' % (
                         trackResult.filename, path))
 
-                sys.stdout.write('Verifying track %d of %d: %s\n' % (
-                    number, len(self.itable.tracks),
-                    os.path.basename(path).encode('utf-8')))
+                logger.info('verifying track %d of %d: %s', (
+                            number, len(self.itable.tracks),
+                            os.path.basename(path).encode('utf-8')))
                 if not self.program.verifyTrack(self.runner, trackResult):
-                    sys.stdout.write('Verification failed, reripping...\n')
+                    logger.warning('verification failed, reripping...')
                     os.unlink(path)
 
             if not os.path.exists(path):
@@ -399,9 +397,9 @@ def _ripIfNotRipped(number):
                     tries += 1
                     if tries > 1:
                         extra = " (try %d)" % tries
-                    sys.stdout.write('Ripping track %d of %d%s: %s\n' % (
-                        number, len(self.itable.tracks), extra,
-                        os.path.basename(path).encode('utf-8')))
+                    logger.info('ripping track %d of %d%s: %s', (
+                                number, len(self.itable.tracks), extra,
+                                os.path.basename(path).encode('utf-8')))
                     try:
                         logger.debug('ripIfNotRipped: track %d, try %d',
                                      number, tries)
@@ -427,17 +425,14 @@ def _ripIfNotRipped(number):
                         "track can't be ripped. "
                         "Rip attempts number is equal to 'MAX_TRIES'")
                 if trackResult.testcrc == trackResult.copycrc:
-                    sys.stdout.write('CRCs match for track %d\n' % number)
+                    logger.info('CRCs match for track %d', number)
                 else:
                     raise RuntimeError(
-                        "CRCs did not match for track %d\n" % number
+                        "CRCs did not match for track %d" % number
                     )
 
-                sys.stdout.write(
-                    'Peak level: {}\n'.format(trackResult.peak))
-
-                sys.stdout.write(
-                    'Rip quality: {:.2%}\n'.format(trackResult.quality))
+                print('Peak level: %.6f' % (trackResult.peak / 32768.0))
+                print('Rip quality: {:.2%}'.format(trackResult.quality))
 
             # overlay this rip onto the Table
             if number == 0:
@@ -452,8 +447,7 @@ def _ripIfNotRipped(number):
                     logger.debug('Unlinking %r', trackResult.filename)
                     os.unlink(trackResult.filename)
                     trackResult.filename = None
-                    sys.stdout.write(
-                        'HTOA discarded, contains digital silence\n')
+                    logger.info('HTOA discarded, contains digital silence')
                 else:
                     self.itable.setFile(1, 0, trackResult.filename,
                                         self.ittoc.getTrackStart(1), number)
@@ -467,14 +461,15 @@ def _ripIfNotRipped(number):
         htoa = self.program.getHTOA()
         if htoa:
             start, stop = htoa
-            print('found Hidden Track One Audio from frame %d to %d' % (
-                  start, stop))
+            logger.info('found Hidden Track One Audio from frame %d to %d', (
+                        start, stop))
             _ripIfNotRipped(0)
 
         for i, track in enumerate(self.itable.tracks):
             # FIXME: rip data tracks differently
             if not track.audio:
-                print('skipping data track %d, not implemented' % (i + 1))
+                logger.warning('skipping data track %d, not implemented',
+                               (i + 1))
                 # FIXME: make it work for now
                 track.indexes[1].relative = 0
                 continue
@@ -489,7 +484,7 @@ def _ripIfNotRipped(number):
         try:
             self.program.verifyImage(self.runner, self.ittoc)
         except accurip.EntryNotFound:
-            print('AccurateRip entry not found')
+            logger.warning('AccurateRip entry not found')
 
         accurip.print_report(self.program.result)
 

whipper/command/drive.py

@@ -18,8 +18,6 @@
 # You should have received a copy of the GNU General Public License
 # along with whipper.  If not, see <http://www.gnu.org/licenses/>.
 
-import sys
-
 from whipper.command.basecommand import BaseCommand
 from whipper.common import config, drive
 from whipper.extern.task import task
@@ -40,24 +38,21 @@ def do(self):
         runner.run(t)
 
         if t.defeatsCache is None:
-            sys.stdout.write(
-                'Cannot analyze the drive.  Is there a CD in it?\n')
+            logger.critical('cannot analyze the drive: is there a CD in it?')
             return
         if not t.defeatsCache:
-            sys.stdout.write(
-                'cdparanoia cannot defeat the audio cache on this drive.\n')
+            logger.info('cdparanoia cannot defeat the audio cache '
+                        'on this drive')
         else:
-            sys.stdout.write(
-                'cdparanoia can defeat the audio cache on this drive.\n')
+            logger.info('cdparanoia can defeat the audio cache on this drive')
 
         info = drive.getDeviceInfo(self.options.device)
         if not info:
-            sys.stdout.write('Drive caching behaviour not saved:'
-                             'could not get device info (requires pycdio).\n')
+            logger.error('Drive caching behaviour not saved: '
+                         'could not get device info')
             return
 
-        sys.stdout.write(
-            'Adding drive cache behaviour to configuration file.\n')
+        logger.info('adding drive cache behaviour to configuration file')
 
         config.Config().setDefeatsCache(
             info[0], info[1], info[2], t.defeatsCache)
@@ -72,48 +67,38 @@ def do(self):
         self.config = config.Config()
 
         if not paths:
-            sys.stdout.write('No drives found.\n')
-            sys.stdout.write('Create /dev/cdrom if you have a CD drive, \n')
-            sys.stdout.write('or install pycdio for better detection.\n')
-
+            logger.critical('No drives found. Create /dev/cdrom '
+                            'if you have a CD drive, or install '
+                            'pycdio for better detection')
             return
 
         try:
             import cdio as _  # noqa: F401 (TODO: fix it in a separate PR?)
         except ImportError:
-            sys.stdout.write(
-                'Install pycdio for vendor/model/release detection.\n')
+            logger.error('install pycdio for vendor/model/release detection')
             return
 
         for path in paths:
             vendor, model, release = drive.getDeviceInfo(path)
-            sys.stdout.write(
-                "drive: %s, vendor: %s, model: %s, release: %s\n" % (
-                    path, vendor, model, release))
+            print("drive: %s, vendor: %s, model: %s, release: %s" % (
+                  path, vendor, model, release))
 
             try:
                 offset = self.config.getReadOffset(
                     vendor, model, release)
-                sys.stdout.write(
-                    "       Configured read offset: %d\n" % offset)
+                print("       Configured read offset: %d" % offset)
             except KeyError:
                 # Note spaces at the beginning for pretty terminal output
-                sys.stdout.write("       "
-                                 "No read offset found.  "
-                                 "Run 'whipper offset find'\n")
+                logger.warning("no read offset found. "
+                               "Run 'whipper offset find'")
 
             try:
                 defeats = self.config.getDefeatsCache(
                     vendor, model, release)
-                sys.stdout.write(
-                    "       Can defeat audio cache: %s\n" % defeats)
+                print("       Can defeat audio cache: %s" % defeats)
             except KeyError:
-                sys.stdout.write(
-                    "       Unknown whether audio cache can be defeated. "
-                    "Run 'whipper drive analyze'\n")
-
-        if not paths:
-            sys.stdout.write('No drives found.\n')
+                logger.warning("unknown whether audio cache can be "
+                               "defeated. Run 'whipper drive analyze'")
 
 
 class Drive(BaseCommand):

whipper/command/main.py

@@ -19,12 +19,7 @@
 
 
 def main():
-    try:
-        server = config.Config().get_musicbrainz_server()
-    except KeyError as e:
-        sys.stderr.write('whipper: %s\n' % str(e))
-        sys.exit()
-
+    server = config.Config().get_musicbrainz_server()
     musicbrainzngs.set_hostname(server)
     # register plugins with pkg_resources
     distributions, _ = pkg_resources.working_set.find_plugins(
@@ -35,7 +30,7 @@ def main():
         cmd = Whipper(sys.argv[1:], os.path.basename(sys.argv[0]), None)
         ret = cmd.do()
     except SystemError as e:
-        sys.stderr.write('whipper: error: %s\n' % e)
+        logger.critical("SystemError: %s", e)
         if (isinstance(e, common.EjectError) and
                 cmd.options.eject in ('failure', 'always')):
             eject_device(e.device)
@@ -51,18 +46,17 @@ def main():
         if isinstance(e.exception, ImportError):
             raise ImportError(e.exception)
         elif isinstance(e.exception, common.MissingDependencyException):
-            sys.stderr.write('whipper: error: missing dependency "%s"\n' %
-                             e.exception.dependency)
+            logger.critical('missing dependency "%s"', e.exception.dependency)
             return 255
 
         if isinstance(e.exception, common.EmptyError):
             logger.debug("EmptyError: %r", str(e.exception))
-            sys.stderr.write('whipper: error: Could not create encoded file.\n')  # noqa: E501
+            logger.critical('could not create encoded file')
             return 255
 
         # in python3 we can instead do `raise e.exception` as that would show
         # the exception's original context
-        sys.stderr.write(e.exceptionMessage)
+        logger.critical(e.exceptionMessage)
         return 255
     return ret if ret else 0