Utilize the logging module in python instead of print statements

[AWegnerGitHub]

Current Smokey has print lines all over the place. We should utilize the logging module instead.

Benefits:

• We can adjust how much/little to log by changing the log level. DEBUG/INFO/CRITICAL
• Logs can be routed to more than one location and have different formats for each. Meaning, we can still log to a console with one format and log to a file with another. Additionally, each location can have a different log level, so the console could be watching for critical errors only while the log file gets everything.

[ArtOfCode-]

Current Smokey actually doesn't have a load of print statements any more; I replaced them with helpers.log. Any reason we can't copy that over and make that method use the logging module?

[AWegnerGitHub]

It's still a print statement.

With true logging we can do something like this:

helper.py

import logging
def setup_logging(file_name, file_level=logging.INFO, console_level=logging.INFO):
	logger = logging.getLogger("smokey_logs")
	logger.setLevel(logging.DEBUG)

	# Create Console handler
	console_log = logging.StreamHandler()
	console_log.setLevel(console_level)
	formatter = logging.Formatter('%(asctime)s - %(levelname)-8s - %(name)-12s - %(message)s')
	console_log.setFormatter(formatter)
	logger.addHandler(console_log)

	# Log file
	file_log = logging.FileHandler('logs/{}.log'.format(file_name), 'a', encoding='UTF-8')
	file_log.setLevel(file_level)
	formatter = logging.Formatter('%(asctime)s - %(levelname)-8s - %(name)-12s - %(message)s')
	file_log.setFormatter(formatter)
	logger.addHandler(file_log)

	return logger

ws.py

import logging
import helper
import module1
logger = helper.setup_logging("smokey_logs", file_level=logging.INFO, console_level=logging.INFO)
logger.info("In Main!")

module1.py

import logging
logger = logging.getLogger("smokey_logs")

def test_func():
	logger.info("Called 'test_func'")

When ws.py is run, it will output the following to both the console and the file logs/smokey_logs.log

2017-04-26 08:31:40,628 - INFO     - smokey_logs  - In Main!
2017-04-26 08:31:40,630 - INFO     - smokey_logs  - Called 'test_func'

We can make this even easier for troubleshooting by modifying the module1.py setup slightly:

logger = logging.getLogger("smokey_logs.module1")

Which changes the log to:

2017-04-26 08:37:40,441 - INFO     - smokey_logs  - In Main!
2017-04-26 08:37:40,443 - INFO     - smokey_logs.module1 - Called 'test_func'

Notice on the second line we now have the module1 indication too.

[ArtOfCode-]

That'd work, yeah.

[AWegnerGitHub]

The first commits for this are in my Branch_logging branch. Right now, a basic start up, login, respond to a simple command looks like this:

2017-04-26 23:16:38,178 -     INFO - smokey_logs.entry    - Started via 'entry.py'
2017-04-26 23:16:38,178 -    DEBUG - smokey_logs.entry    - Secret store not already open: started without daemon?
2017-04-26 23:16:47,789 -    DEBUG - smokey_logs.chat     - Loading rooms.json
2017-04-26 23:16:47,790 -    DEBUG - smokey_logs.chat     -    Room loaded: {('stackexchange.com', '1')} => ['debug', 'commands']
2017-04-26 23:16:48,742 -    DEBUG - smokey_logs.chat     - Joined Sandbox (Room ID: (stackexchange.com, 1))
2017-04-26 23:16:48,747 -    DEBUG - smokey_logs.chat     - Message sent to [Sandbox]: [ [SmokeDetector-ng](https://github.com/Charcoal-SE/SmokeDetector-ng) ] SmokeDetector-ng started at revision [f2c1b99](https://github.com/Charcoal-SE/SmokeDetector-ng/commit/f2c1b997871dddeb3fb267fb50a87db9e8a69e88).
2017-04-26 23:16:48,915 -     INFO - smokey_logs.ws       - Websocket to real time feed started.
2017-04-26 23:17:04,753 -    DEBUG - smokey_logs.chat     - Command Received in [Sandbox]: ??!/wut
2017-04-26 23:17:04,754 -    DEBUG - smokey_logs.commands - Command: wut
2017-04-26 23:17:26,940 -    DEBUG - smokey_logs.chat     - Command Received in [Sandbox]: ??!/stappit
2017-04-26 23:17:26,941 -    DEBUG - smokey_logs.commands - Command: stappit

I've got everything being logged right now, but will probably change that to be INFO by default before the final PR. I'll also pull the log levels out into the config, like I did with the log_name.

To do:

• Document logger so that others can add stuff as appropriate
• Throw a log line on an exception with logger.exception() method to get exception info
• More log lines throughout system