Merge pull request #1400 from chenjr0719/add_tests_for_log

Add test for sanic.root logger and update the docs of logging

docs/sanic/logging.md

@@ -9,17 +9,32 @@ A simple example using default settings would be like this:
 
 ```python
 from sanic import Sanic
+from sanic.log import logger
+from sanic.response import text
 
 app = Sanic('test')
 
 @app.route('/')
 async def test(request):
-    return response.text('Hello World!')
+    logger.info('Here is your log')
+    return text('Hello World!')
 
 if __name__ == "__main__":
   app.run(debug=True, access_log=True)
 ```
 
+After the server is running, you can see some messages looks like:
+```
+[2018-11-06 21:16:53 +0800] [24622] [INFO] Goin' Fast @ http://127.0.0.1:8000
+[2018-11-06 21:16:53 +0800] [24667] [INFO] Starting worker [24667]
+```
+
+You can send a request to server and it will print the log messages:
+```
+[2018-11-06 21:18:53 +0800] [25685] [INFO] Here is your log
+[2018-11-06 21:18:53 +0800] - (sanic.access)[INFO][127.0.0.1:57038]: GET http://localhost:8000/  200 12
+```
+
 To use your own logging config, simply use `logging.config.dictConfig`, or
 pass `log_config` when you initialize `Sanic` app:
 
@@ -49,7 +64,7 @@ By default, log_config parameter is set to use sanic.log.LOGGING_CONFIG_DEFAULTS
 
 There are three `loggers` used in sanic, and **must be defined if you want to create your own logging configuration**:
 
-- root:<br>
+- sanic.root:<br>
   Used to log internal messages.
 
 - sanic.error:<br>

tests/test_logging.py

@@ -11,6 +11,7 @@ import sanic
 from sanic.response import text
 from sanic.log import LOGGING_CONFIG_DEFAULTS
 from sanic import Sanic
+from sanic.log import logger
 
 
 logging_format = '''module: %(module)s; \
@@ -46,7 +47,7 @@ def test_log(app):
 
 
 def test_logging_defaults():
-    reset_logging()
+    # reset_logging()
     app = Sanic("test_logging")
 
     for fmt in [h.formatter for h in logging.getLogger('sanic.root').handlers]:
@@ -60,7 +61,7 @@ def test_logging_defaults():
 
 
 def test_logging_pass_customer_logconfig():
-    reset_logging()
+    # reset_logging()
 
     modified_config = LOGGING_CONFIG_DEFAULTS
     modified_config['formatters']['generic']['format'] = '%(asctime)s - (%(name)s)[%(levelname)s]: %(message)s'
@@ -104,6 +105,25 @@ def test_log_connection_lost(app, debug, monkeypatch):
         assert 'Connection lost before response written @' not in log
 
 
+def test_logger(caplog):
+    rand_string = str(uuid.uuid4())
+
+    app = Sanic()
+
+    @app.get('/')
+    def log_info(request):
+        logger.info(rand_string)
+        return text('hello')
+
+    with caplog.at_level(logging.INFO):
+        request, response = app.test_client.get('/')
+
+    assert caplog.record_tuples[0] == ('sanic.root', logging.INFO, 'Goin\' Fast @ http://127.0.0.1:42101')
+    assert caplog.record_tuples[1] == ('sanic.root', logging.INFO, 'http://127.0.0.1:42101/')
+    assert caplog.record_tuples[2] == ('sanic.root', logging.INFO, rand_string)
+    assert caplog.record_tuples[-1] == ('sanic.root', logging.INFO, 'Server Stopped')
+
+
 def test_logging_modified_root_logger_config():
     reset_logging()
 
@@ -113,4 +133,3 @@ def test_logging_modified_root_logger_config():
     app = Sanic("test_logging", log_config=modified_config)
 
     assert logging.getLogger('sanic.root').getEffectiveLevel() == logging.DEBUG
-