Merge pull request #466 from azavea/rde/feature/logging-update

Updates to logging PR with some additional fixes

src/MANIFEST.in

@@ -0,0 +1 @@
+include rastervision/backend/model_defaults.json

src/rastervision/__init__.py

@@ -1,4 +1,5 @@
 # flake8: noqa
+import logging
 
 from rastervision.core import ConfigError
 from rastervision.analyzer.api import *
@@ -17,6 +18,14 @@
 
 from rastervision.registry import Registry
 
+root_logger = logging.getLogger('rastervision')
+sh = logging.StreamHandler()
+sh.setLevel(logging.DEBUG)
+formatter = logging.Formatter(
+    '%(asctime)s:%(name)s: %(levelname)s - %(message)s', '%Y-%m-%d %H:%M:%S')
+sh.setFormatter(formatter)
+root_logger.addHandler(sh)
+
 _registry = None
 
 

src/rastervision/backend/keras_classification/core/trainer.py

@@ -1,9 +1,11 @@
 import os
 from pathlib import Path
 from subprocess import Popen
+import logging
 
 from rastervision.utils.misc import terminate_at_exit
 from rastervision.backend.keras_classification.utils import make_dir
+log = logging.getLogger(__name__)
 
 
 def get_nb_images(image_dir):
@@ -68,7 +70,7 @@ def schedule(curr_epoch):
                 for lr_schedule_item in lr_schedule:
                     if curr_epoch >= lr_schedule_item.epoch:
                         if self.options.debug:
-                            print('New lr: {}'.format(lr_schedule_item.lr))
+                            log.info('New lr: {}'.format(lr_schedule_item.lr))
                         return lr_schedule_item.lr
 
             lr_scheduler = keras.callbacks.LearningRateScheduler(schedule)

src/rastervision/backend/tf_deeplab.py

@@ -6,6 +6,7 @@
 from typing import (Dict, List, Tuple)
 from os.path import join
 from subprocess import Popen
+import logging
 
 import numpy as np
 from google.protobuf import (json_format)
@@ -32,6 +33,8 @@
 INPUT_TENSOR_NAME = 'ImageTensor:0'
 OUTPUT_TENSOR_NAME = 'SemanticPredictions:0'
 
+log = logging.getLogger(__name__)
+
 
 def make_tf_examples(training_data: TrainingData, class_map: ClassMap) -> List:
     """Take training data and a class map and return a list of TFRecords.
@@ -46,12 +49,10 @@ def make_tf_examples(training_data: TrainingData, class_map: ClassMap) -> List:
 
     """
     tf_examples = []
-    print('Creating TFRecord', end='', flush=True)
+    log.info('Creating TFRecord', end='', flush=True)
     for chip, window, labels in training_data:
         tf_example = create_tf_example(chip, window, labels, class_map)
         tf_examples.append(tf_example)
-        print('.', end='', flush=True)
-    print()
     return tf_examples
 
 
@@ -71,14 +72,12 @@ def merge_tf_records(output_path: str, src_records: List[str]) -> None:
 
     records = 0
     with tf.python_io.TFRecordWriter(output_path) as writer:
-        print('Merging TFRecords', end='', flush=True)
+        log.info('Merging TFRecords', end='', flush=True)
         for src_record in src_records:
             for string_record in tf.python_io.tf_record_iterator(src_record):
                 writer.write(string_record)
                 records = records + 1
-            print('.', end='', flush=True)
-        print('{} records'.format(records))
-        print()
+        log.info('{} records'.format(records))
 
 
 def make_debug_images(record_path: str, output_dir: str, class_map: ClassMap,
@@ -122,7 +121,7 @@ def _image_fn(pixel: int) -> int:
 
     image_fn = np.vectorize(_image_fn, otypes=[np.uint64])
 
-    print('Generating debug chips', end='', flush=True)
+    log.info('Generating debug chips', end='', flush=True)
     tfrecord_iter = tf.python_io.tf_record_iterator(record_path)
     for ind, example in enumerate(tfrecord_iter):
         if np.random.rand() <= p:
@@ -147,8 +146,6 @@ def _image_fn(pixel: int) -> int:
 
             output_path = join(output_dir, '{}.png'.format(ind))
             save_img(im_unpacked, output_path)
-        print('.', end='', flush=True)
-    print()
 
 
 def parse_tf_example(example) -> Tuple[np.ndarray, np.ndarray]:
@@ -346,9 +343,9 @@ def get_training_args(train_py: str, train_logdir_local: str, tfic_ckpt: str,
     env = os.environ.copy()
     for field in env_fields:
         field_value = tfdl_config.__getattribute__(field)
-        print('{}={}'.format(field.upper(), field_value))
+        log.info('{}={}'.format(field.upper(), field_value))
         env[field.upper()] = str(field_value)
-    print('DL_CUSTOM_CLASSES={}'.format(num_classes))
+    log.info('DL_CUSTOM_CLASSES={}'.format(num_classes))
     env['DL_CUSTOM_CLASSES'] = str(num_classes)
 
     return (args, env)
@@ -526,7 +523,7 @@ def train(self, tmp_dir: str) -> None:
             tmp_dir = train_restart_dir
 
         # Setup local input and output directories
-        print('Setting up local input and output directories')
+        log.info('Setting up local input and output directories')
         train_logdir = self.backend_config.training_output_uri
         train_logdir_local = get_local_path(train_logdir, tmp_dir)
         dataset_dir = self.backend_config.training_data_uri
@@ -536,11 +533,11 @@ def train(self, tmp_dir: str) -> None:
         make_dir(dataset_dir_local)
 
         # Download training data
-        print('Downloading training data')
+        log.info('Downloading training data')
         download_if_needed(get_record_uri(dataset_dir, TRAIN), tmp_dir)
 
         # Download and untar initial checkpoint.
-        print('Downloading and untarring initial checkpoint')
+        log.info('Downloading and untarring initial checkpoint')
         tf_initial_checkpoints_uri = self.backend_config.pretrained_model_uri
         download_if_needed(tf_initial_checkpoints_uri, tmp_dir)
         tfic_tarball = get_local_path(tf_initial_checkpoints_uri, tmp_dir)
@@ -571,8 +568,8 @@ def train(self, tmp_dir: str) -> None:
             # Setup TFDL config
             tfdl_config = json_format.ParseDict(
                 self.backend_config.tfdl_config, TrainingParametersMsg())
-            print('tfdl_config={}'.format(tfdl_config))
-            print('Training steps={}'.format(
+            log.info('tfdl_config={}'.format(tfdl_config))
+            log.info('Training steps={}'.format(
                 tfdl_config.training_number_of_steps))
 
             # Additional training options
@@ -585,25 +582,25 @@ def train(self, tmp_dir: str) -> None:
                 num_classes, tfdl_config)
 
             # Start training
-            print('Starting training process')
+            log.info('Starting training process')
             train_process = Popen(train_args, env=train_env)
             terminate_at_exit(train_process)
 
             if self.backend_config.train_options.do_monitoring:
                 # Start tensorboard
-                print('Starting tensorboard process')
+                log.info('Starting tensorboard process')
                 tensorboard_process = Popen(
                     ['tensorboard', '--logdir={}'.format(train_logdir_local)])
                 terminate_at_exit(tensorboard_process)
 
             # Wait for training and tensorboard
-            print('Waiting for training process')
+            log.info('Waiting for training and tensorboard processes')
             train_process.wait()
             if self.backend_config.train_options.do_monitoring:
                 tensorboard_process.terminate()
 
             # Export frozen graph
-            print(
+            log.info(
                 'Exporting frozen graph ({}/model)'.format(train_logdir_local))
             export_args = get_export_args(export_py, train_logdir_local,
                                           num_classes, tfdl_config)

src/rastervision/backend/tf_object_detection.py

@@ -9,6 +9,7 @@
 import glob
 import re
 import uuid
+import logging
 from copy import deepcopy
 
 from PIL import Image
@@ -27,6 +28,8 @@
 TRAIN = 'train'
 VALIDATION = 'validation'
 
+log = logging.getLogger(__name__)
+
 
 def save_debug_image(im, labels, class_map, output_path):
     from object_detection.utils import visualization_utils as vis_util
@@ -127,12 +130,10 @@ def merge_tf_records(output_path, src_records):
     import tensorflow as tf
 
     with tf.python_io.TFRecordWriter(output_path) as writer:
-        print('Merging TFRecords', end='', flush=True)
+        log.info('Merging TFRecords')
         for src_record in src_records:
             for string_record in tf.python_io.tf_record_iterator(src_record):
                 writer.write(string_record)
-            print('.', end='', flush=True)
-        print()
 
 
 def make_tf_class_map(class_map):
@@ -156,12 +157,10 @@ def save_tf_class_map(tf_class_map, class_map_path):
 
 def make_tf_examples(training_data, class_map):
     tf_examples = []
-    print('Creating TFRecord', end='', flush=True)
+    log.info('Creating TFRecord')
     for chip, window, labels in training_data:
         tf_example = create_tf_example(chip, window, labels, class_map)
         tf_examples.append(tf_example)
-        print('.', end='', flush=True)
-    print()
     return tf_examples
 
 
@@ -197,21 +196,19 @@ def make_debug_images(record_path, class_map, output_dir):
 
     make_dir(output_dir, check_empty=True)
 
-    print('Generating debug chips', end='', flush=True)
+    log.info('Generating debug chips')
     tfrecord_iter = tf.python_io.tf_record_iterator(record_path)
     for ind, example in enumerate(tfrecord_iter):
         example = tf.train.Example.FromString(example)
         im, labels = parse_tfexample(example)
         # Can't create debug images for non-3band images
         if im.shape[2] != 3:
-            print(
+            log.warning(
                 'WARNING: Skipping debug images - Images are not 3 band rasters.'
             )
             return
         output_path = join(output_dir, '{}.png'.format(ind))
         save_debug_image(im, labels, class_map, output_path)
-        print('.', end='', flush=True)
-    print()
 
 
 def train(config_path,
@@ -232,7 +229,7 @@ def train(config_path,
         '--sample_1_of_n_eval_examples={}'.format(1)
     ]
 
-    print('Running train command: {}'.format(' '.join(train_cmd)))
+    log.info('Running train command: {}'.format(' '.join(train_cmd)))
 
     train_process = Popen(train_cmd, stdout=PIPE, stderr=STDOUT)
     terminate_at_exit(train_process)
@@ -244,7 +241,7 @@ def train(config_path,
             '--checkpoint_dir={}'.format(output_train_dir),
             '--model_dir={}'.format(output_eval_dir)
         ]
-        print('Running eval command: {}'.format(' '.join(eval_cmd)))
+        log.info('Running eval command: {}'.format(' '.join(eval_cmd)))
 
         # Don't let the eval process take up GPU space
         env = deepcopy(os.environ)
@@ -258,9 +255,9 @@ def train(config_path,
 
     with train_process:
         for line in train_process.stdout:
-            print(line.decode('utf-8'), end='', flush=True)
+            log.info(line.decode('utf-8'))
 
-    print('-----DONE TRAINING----')
+    log.info('-----DONE TRAINING----')
     if do_monitoring:
         eval_process.terminate()
         tensorboard_process.terminate()
@@ -291,9 +288,9 @@ def export_inference_graph(train_root_dir,
                  '/opt/tf-models/object_detection/export_inference_graph.py')
     checkpoint_path = get_last_checkpoint_path(train_root_dir)
     if checkpoint_path is None:
-        print('No checkpoints could be found.')
+        log.warning('No checkpoints could be found.')
     else:
-        print('Exporting checkpoint {}...'.format(checkpoint_path))
+        log.info('Exporting checkpoint {}...'.format(checkpoint_path))
 
         train_process = Popen([
             'python', export_py, '--input_type', 'image_tensor',

src/rastervision/cli/main.py

@@ -3,12 +3,15 @@
 import os
 
 import click
+import logging
 
 import rastervision as rv
 from rastervision.experiment import (ExperimentLoader, LoaderError)
 from rastervision.runner import (ExperimentRunner)
 from rastervision.rv_config import RVConfig
 
+log = logging.getLogger(__name__)
+
 
 def print_error(msg):
     click.echo(click.style(msg, fg='red'), err=True)

src/rastervision/cli/verbosity.py

@@ -2,7 +2,7 @@
 
 
 class Verbosity:
-    QUITE = 0
+    QUIET = 0
     NORMAL = 1
     VERBOSE = 2
     VERY_VERBOSE = 3

src/rastervision/command/bundle_command.py

@@ -1,12 +1,15 @@
 import os
 import zipfile
+import logging
 
 import click
 from google.protobuf import json_format
 
 from rastervision.command import Command
 from rastervision.utils.files import (upload_or_copy, make_dir)
 
+log = logging.getLogger(__name__)
+
 
 class BundleCommand(Command):
     """Bundles all the necessary files together into a prediction package."""
@@ -30,7 +33,7 @@ def run(self, tmp_dir=None):
 
         msg = 'Bundling prediction package to {}...'.format(
             self.task_config.predict_package_uri)
-        click.echo(click.style(msg, fg='green'))
+        log.info(msg)
         bundle_dir = os.path.join(tmp_dir, 'bundle')
         make_dir(bundle_dir)
         package_path = os.path.join(tmp_dir, 'predict_package.zip')

src/rastervision/data/raster_source/geotiff_source.py

@@ -1,12 +1,15 @@
 import subprocess
 import os
 import rasterio
+import logging
 
 from rastervision.data.raster_source.rasterio_source \
     import RasterioRasterSource
 from rastervision.data.crs_transformer import RasterioCRSTransformer
 from rastervision.utils.files import download_if_needed
 
+log = logging.getLogger(__name__)
+
 
 def build_vrt(vrt_path, image_paths):
     """Build a VRT for a set of TIFF files."""
@@ -16,7 +19,7 @@ def build_vrt(vrt_path, image_paths):
 
 
 def download_and_build_vrt(image_uris, temp_dir):
-    print('Downloading and building VRT...')
+    log.info('Downloading and building VRT...')
     image_paths = [download_if_needed(uri, temp_dir) for uri in image_uris]
     image_path = os.path.join(temp_dir, 'index.vrt')
     build_vrt(image_path, image_paths)
@@ -30,7 +33,7 @@ def __init__(self, uris, raster_transformers, temp_dir,
         super().__init__(raster_transformers, temp_dir, channel_order)
 
     def build_image_dataset(self, temp_dir):
-        print('Loading GeoTiff files...')
+        log.info('Loading GeoTiff files...')
         if len(self.uris) == 1:
             imagery_path = download_if_needed(self.uris[0], temp_dir)
         else: