Various Fixes to multistructlog

- Force color output on structured-color formatter
- Add log levels and timestamps to output
- Fix reinitialization issue
- Cleanup/clarify README, add changelog

Change-Id: I11433f362e7c1ab8c1ee9fbca2081e136b57f22c
diff --git a/.gitignore b/.gitignore
index 036ac49..f050059 100644
--- a/.gitignore
+++ b/.gitignore
@@ -1,5 +1,6 @@
 *.pyc
 dist
+build
 .tox
 __pycache__
 *.egg-info
diff --git a/README.rst b/README.rst
index 2339a25..d0bdce6 100644
--- a/README.rst
+++ b/README.rst
@@ -8,23 +8,25 @@
 The API consists of a single function: ``create_logger()``.
 
 Args:
-   logging_config (dict):    Input to logging.config.dictConfig
-   level(logging.loglevel):  Overrides logging level for all loggers (not handlers!)
+    logging_config (dict):    Input to logging.config.dictConfig
+
+    level(logging.loglevel):  Overrides logging level for all loggers (not handlers!)
 
 Returns:
-   log: structlog logger object
+    log: structlog Logger object
 
 It can be invoked as follows:
 
     logging_config = ...
 
     log = multistructlog.create_logger(config, level=logging.INFO)
+
     log.info('Entered function', foo='bar')
 
 To create a ``logging_config`` dictionary, see these docs:
 
- https://docs.python.org/2.7/library/logging.config.html#logging.config.dictConfig
- http://www.structlog.org/en/stable/standard-library.html#rendering-using-structlog-based-formatters-within-logging
+- https://docs.python.org/2.7/library/logging.config.html#logging.config.dictConfig
+- http://www.structlog.org/en/stable/standard-library.html#rendering-using-structlog-based-formatters-within-logging
 
 There are no required arguments to `create_logger()` - any missing parts of the
 config will be filled in with defaults that print structured logs to the
@@ -33,9 +35,9 @@
 If you don't specify a ``formatters`` section in your config, three will be
 created which can be used in handlers:
 
- - ``json``: renders one JSON dictionary per message
- - ``structured``: prints structured logs with the ``structlog.dev.ConsoleRenderer``
- - ``structured-color``: same as ``structured`` but in color
+- ``json``: renders one JSON dictionary per message
+- ``structured``: prints structured logs with the ``structlog.dev.ConsoleRenderer``
+- ``structured-color``: same as ``structured`` but with forced color output
 
 If you don't specify a ``handlers`` section, a handler will be added that logs
 to console with ``logging.StreamHandler`` with format ``structured`` at level
@@ -47,13 +49,31 @@
 
 When setting log level, the higher of ``logging_config['loggers'][*]['level']``
 and ``logging_config['handlers'][*]['level']`` is used. The ``level`` parameter
-overrides the ``loggers`` value of level, not the ``handlers`` one.
+overrides the ``loggers`` value of level, not the ``handlers`` level.
 
 If the handler's level is set to ``DEBUG`` but the logger's level is set to
-``ERROR``, the handler will only log ``ERROR`` level messages.
+``ERROR``, the handler will be overridden and only log ``ERROR`` level messages.
 
 Multistructlog also adds a ``TRACE`` log level (integer level 5) that is below
 "DEBUG" to both standard library ``Logger`` and Structlog ``BoundLogger``.
 
 List of standard logging levels:
  https://docs.python.org/2.7/library/logging.html#logging-levels
+
+Changelog
+---------
+1.x versions
+
+- legacy
+
+2.0.0
+
+- Substantial refactor/rewrite
+- Cache logger objects
+- Add trace levels
+
+2.1.0
+
+- Force color on when using structured-color formatter
+- Print timestamp and loglevel by default
+- Fix issues with reinitialziaton of logger
diff --git a/VERSION b/VERSION
index 227cea2..7ec1d6d 100644
--- a/VERSION
+++ b/VERSION
@@ -1 +1 @@
-2.0.0
+2.1.0
diff --git a/multistructlog.py b/multistructlog.py
index 49338d0..632b820 100644
--- a/multistructlog.py
+++ b/multistructlog.py
@@ -89,16 +89,19 @@
     global CURRENT_LOGGER
     global CURRENT_LOGGER_PARAMS
 
+    # if config provided, copy to prevent changes to dict from being pushed
+    # back to caller, otherwise use default config
+    if logging_config:
+        logging_config = copy.deepcopy(logging_config)
+    else:
+        logging_config = {'version': 1, "disable_existing_loggers": False}
+
     if CURRENT_LOGGER and CURRENT_LOGGER_PARAMS == (logging_config, level):
         return CURRENT_LOGGER
 
     # store unmodified config, which is changed later
     CURRENT_LOGGER_PARAMS = (copy.deepcopy(logging_config), level)
 
-    # set bare minimum config if not set
-    if not logging_config:
-        logging_config = {'version': 1}
-
     # check if formatters exists in logging_config, set defaults if not set
     if "formatters" not in logging_config:
 
@@ -109,7 +112,8 @@
             },
             'structured-color': {
                 '()': structlog.stdlib.ProcessorFormatter,
-                'processor': structlog.dev.ConsoleRenderer(colors=True),
+                'processor': structlog.dev.ConsoleRenderer(colors=True,
+                                                           force_colors=True),
             },
             'structured': {
                 '()': structlog.stdlib.ProcessorFormatter,
@@ -157,8 +161,12 @@
     # configure structlog
     structlog.configure(
         processors=[
+            structlog.stdlib.filter_by_level,
+            structlog.stdlib.add_log_level,
+            structlog.stdlib.PositionalArgumentsFormatter(),
             structlog.processors.StackInfoRenderer(),
             structlog.processors.format_exc_info,
+            structlog.processors.TimeStamper(fmt="iso"),
             structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
         ],
         context_class=dict,
diff --git a/tests/test_multistructlog.py b/tests/test_multistructlog.py
index 2e7171a..88814ed 100644
--- a/tests/test_multistructlog.py
+++ b/tests/test_multistructlog.py
@@ -115,19 +115,28 @@
 
         # check contents of file1
         with open(f1) as f1fh:
-            f1_desired = '''should be in both files        extra={'number': 42}
-'''
-            self.assertEqual(f1fh.read(), f1_desired)
+
+            # regex at start should roughly match ISO8601 datetime
+            f1_desired = r"[\dTZ\-\.\:]+ \[warning  \] should be in both files        extra={'number': 42}"
+            self.assertRegexpMatches(f1fh.read(), f1_desired)
 
         # check contents of file2
         f2_read = []
         f2_desired = [
-            {"event": "should be in both files", "extra": {"number": 42}},
-            {"event": "should only be in file2"},
+            {"event": "should be in both files", "extra": {"number": 42},
+             "level": "warning", "timestamp": "removed"},
+            {"event": "should only be in file2",
+             "level": "info", "timestamp": "removed"},
         ]
 
         with open(f2) as f2fh:
             for line in f2fh:
-                f2_read.append(json.loads(line))
+                jl = json.loads(line)
+
+                # assert there is a timestamp, and remove it as it changes
+                self.assertTrue(True if "timestamp" in jl else False)
+                jl['timestamp'] = "removed"
+
+                f2_read.append(jl)
 
         self.assertEqual(f2_read, f2_desired)
diff --git a/tox.ini b/tox.ini
index bd840cf..f1e9673 100644
--- a/tox.ini
+++ b/tox.ini
@@ -26,3 +26,5 @@
   nose2 --verbose --junit-xml
   flake8
 
+[flake8]
+max-line-length = 120