Use logging framework for logging

.docker/marvin/Dockerfile

@@ -1,7 +1,7 @@
 FROM python:3-alpine
 
 COPY . /app
-RUN mkdir -p /app
+RUN mkdir -p /app/logs
 WORKDIR /app
 
 RUN python3 -m pip install -r .requirements.txt

.gitignore

@@ -4,6 +4,7 @@ aggregate.error
 aggregate.ignore
 aggregate.log
 db.sqlite
+logs/
 # pycharm
 .idea/
 marvin_config.json

bot.py

@@ -5,14 +5,18 @@
 Module for the common base class for all Bots
 """
 
+import logging
 import re
 
+LOG = logging.getLogger("bot")
+
 class Bot():
     """Base class for things common between different protocols"""
     def __init__(self):
         self.CONFIG = {}
         self.ACTIONS = []
         self.GENERAL_ACTIONS = []
+        self.MSG_LOG = logging.getLogger("message")
 
     def getConfig(self):
         """Return the current configuration"""
@@ -24,16 +28,16 @@ def setConfig(self, config):
 
     def registerActions(self, actions):
         """Register actions to use"""
-        print("Adding actions:")
+        LOG.info("Adding actions")
         for action in actions:
-            print(" - " + action.__name__)
+            LOG.info("Adding action: %s", action.__name__)
         self.ACTIONS.extend(actions)
 
     def registerGeneralActions(self, actions):
         """Register general actions to use"""
-        print("Adding general actions:")
+        LOG.info("Adding actions")
         for action in actions:
-            print(" - " + action.__name__)
+            LOG.info("Adding action: %s", action.__name__)
         self.GENERAL_ACTIONS.extend(actions)
 
     @staticmethod

discord_bot.py

@@ -7,10 +7,13 @@
 Connecting, sending and receiving messages and doing custom actions.
 """
 
+import logging
+
 import discord
 
 from bot import Bot
 
+
 class DiscordBot(discord.Client, Bot):
     """Bot implementing the discord protocol"""
     def __init__(self):
@@ -42,7 +45,7 @@ async def checkMarvinActions(self, message):
 
     async def on_message(self, message):
         """Hook run on every message"""
-        print(f"#{message.channel.name} <{message.author}> {message.content}")
+        self.MSG_LOG.debug("#%s <%s> %s", message.channel.name, message.author, message.content)
         if message.author.name == self.user.name:
             # don't react to own messages
             return

irc_bot.py

@@ -11,6 +11,7 @@
 from collections import deque
 from datetime import datetime
 import json
+import logging
 import os
 import re
 import shutil
@@ -20,6 +21,8 @@
 
 from bot import Bot
 
+LOG = logging.getLogger("bot")
+
 class IrcBot(Bot):
     """Bot implementing the IRC protocol"""
     def __init__(self):
@@ -54,10 +57,10 @@ def connectToServer(self):
 
         if server and port:
             self.SOCKET = socket.socket()
-            print("Connecting: {SERVER}:{PORT}".format(SERVER=server, PORT=port))
+            LOG.info("Connecting: %s:%d", server, port)
             self.SOCKET.connect((server, port))
         else:
-            print("Failed to connect, missing server or port in configuration.")
+            LOG.error("Failed to connect, missing server or port in configuration.")
             return
 
         # Send the nick to server
@@ -66,7 +69,7 @@ def connectToServer(self):
             msg = 'NICK {NICK}\r\n'.format(NICK=nick)
             self.sendMsg(msg)
         else:
-            print("Ignore sending nick, missing nick in configuration.")
+            LOG.info("Ignore sending nick, missing nick in configuration.")
 
         # Present yourself
         realname = self.CONFIG["realname"]
@@ -77,26 +80,27 @@ def connectToServer(self):
         if ident:
             self.sendMsg('PRIVMSG nick IDENTIFY {IDENT}\r\n'.format(IDENT=ident))
         else:
-            print("Ignore identifying with password, ident is not set.")
+            LOG.info("Ignore identifying with password, ident is not set.")
 
         # Join a channel
         channel = self.CONFIG["channel"]
         if channel:
             self.sendMsg('JOIN {CHANNEL}\r\n'.format(CHANNEL=channel))
         else:
-            print("Ignore joining channel, missing channel name in configuration.")
+            LOG.info("Ignore joining channel, missing channel name in configuration.")
 
     def sendPrivMsg(self, message, channel):
         """Send and log a PRIV message"""
         if channel == self.CONFIG["channel"]:
             self.ircLogAppend(user=self.CONFIG["nick"].ljust(8), message=message)
+            self.MSG_LOG.debug("%s <%s>  %s", channel, self.CONFIG["nick"], message)
 
         msg = "PRIVMSG {CHANNEL} :{MSG}\r\n".format(CHANNEL=channel, MSG=message)
         self.sendMsg(msg)
 
     def sendMsg(self, msg):
         """Send and occasionally print the message sent"""
-        print("SEND: " + msg.rstrip('\r\n'))
+        LOG.debug("SEND: %s", msg.rstrip("\r\n"))
         self.SOCKET.send(msg.encode())
 
     def decode_irc(self, raw, preferred_encs=None):
@@ -135,7 +139,7 @@ def receive(self):
             lines = lines.split("\n")
             buf = lines.pop()
         except Exception as err:
-            print("Error reading incoming message. " + err)
+            LOG.error("Error reading incoming message %s", err)
 
         return lines
 
@@ -178,6 +182,7 @@ def readincoming(self):
             try:
                 shutil.move(filename, self.CONFIG["dirDone"])
             except Exception:
+                LOG.warning("Failed to move %s to %s. Deleting.", filename, self.CONFIG["dirDone"])
                 os.remove(filename)
 
     def mainLoop(self):
@@ -192,7 +197,7 @@ def mainLoop(self):
             self.readincoming()
 
             for line in self.receive():
-                print(line)
+                LOG.debug(line)
                 words = line.strip().split()
 
                 if not words:
@@ -220,6 +225,10 @@ def checkIrcActions(self, words):
     def checkMarvinActions(self, words):
         """Check if Marvin should perform any actions"""
         if words[1] == 'PRIVMSG' and words[2] == self.CONFIG["channel"]:
+            self.MSG_LOG.debug("%s <%s>  %s",
+                               words[2],
+                               words[0].split(":")[1].split("!")[0],
+                               " ".join(words[3:]))
             self.ircLogAppend(words)
 
         if words[1] == 'PRIVMSG':

logging.json

@@ -0,0 +1,45 @@
+{
+  "version": 1,
+  "disable_existing_loggers": false,
+  "formatters": {
+    "standard": {
+      "format": "%(asctime)s %(threadName)s %(levelname)s  %(module)s - %(message)s",
+      "datefmt": "%Y-%m-%dT%H:%M:%S%z"
+    },
+    "message": {
+      "format": "%(asctime)s  %(message)s",
+      "datefmt": "%Y-%m-%dT%H:%M:%S%z"
+    }
+  },
+  "handlers": {
+    "stdout": {
+      "class": "logging.StreamHandler",
+      "formatter": "standard",
+      "stream": "ext://sys.stdout"
+    },
+    "message": {
+      "class": "logging.handlers.RotatingFileHandler",
+      "formatter": "message",
+      "filename": "logs/messages.log",
+      "maxBytes": 10485760,
+      "backupCount": 10
+    }
+  },
+  "loggers": {
+    "root": {
+      "level": "DEBUG"
+    },
+    "main": {
+      "handlers": ["stdout"]
+    },
+    "bot": {
+      "handlers": ["stdout"]
+    },
+    "action": {
+      "handlers": ["stdout"]
+    },
+    "message": {
+      "handlers": ["message"]
+    }
+  }
+}

main.py

@@ -41,6 +41,8 @@
 
 import argparse
 import json
+import logging
+import logging.config
 import os
 import sys
 
@@ -59,6 +61,7 @@
 VERSION = "0.3.0"
 MSG_VERSION = "{program} version {version}.".format(program=PROGRAM, version=VERSION)
 
+LOG = logging.getLogger("main")
 
 
 def printVersion():
@@ -79,12 +82,10 @@ def mergeOptionsWithConfigFile(options, configFile):
 
         options.update(data)
         res = json.dumps(options, sort_keys=True, indent=4, separators=(',', ': '))
-
-        msg = "Read configuration from config file '{file}'. Current configuration is:\n{config}"
-        print(msg.format(config=res, file=configFile))
-
+        LOG.info("Read configuration from config file '%s'.", configFile)
+        LOG.info("Current configuration is: %s", res)
     else:
-        print("Config file '{file}' is not readable, skipping.".format(file=configFile))
+        LOG.info("Config file '{%s}' is not readable, skipping.", configFile)
 
     return options
 
@@ -113,7 +114,7 @@ def parseOptions(options):
             options[parameter] = args[parameter]
 
     res = json.dumps(options, sort_keys=True, indent=4, separators=(',', ': '))
-    print("Configuration updated after cli options:\n{config}".format(config=res))
+    LOG.info("Configuration updated after cli options: %s", res)
 
     return options
 
@@ -135,10 +136,17 @@ def createBot(protocol):
     raise ValueError(f"Unsupported protocol: {protocol}")
 
 
+def setupLogging():
+    """Set up the logging config"""
+    with open("logging.json", encoding="UTF-8") as f:
+        config = json.load(f)
+    logging.config.dictConfig(config)
+
 def main():
     """
     Main function to carry out the work.
     """
+    setupLogging()
     protocol = determineProtocol()
     bot = createBot(protocol)
     options = bot.getConfig()

marvin_actions.py

@@ -9,11 +9,13 @@
 import calendar
 import datetime
 import json
+import logging
 import random
 import requests
 
 from bs4 import BeautifulSoup
 
+LOG = logging.getLogger("action")
 
 def getAllActions():
     """
@@ -350,7 +352,8 @@ def marvinSun(row):
             msg = getString("sun", "msg").format(sunrise, sunset)
             return msg
 
-        except Exception:
+        except Exception as e:
+            LOG.error("Failed to get sun times: %s", e)
             return getString("sun", "error")
 
     return msg
@@ -371,7 +374,8 @@ def marvinWeather(row):
                 soup.h4.findNextSibling("p").text
             )
 
-        except Exception:
+        except Exception as e:
+            LOG.error("Failed to get weather: %s", e)
             msg = getString("smhi", "failed")
 
     return msg
@@ -485,7 +489,8 @@ def marvinBirthday(row):
             else:
                 msg = getString("birthday", "somebody").format(my_strings)
 
-        except Exception:
+        except Exception as e:
+            LOG.error("Failed to get birthday: %s", e)
             msg = getString("birthday", "error")
 
     return msg
@@ -507,7 +512,8 @@ def marvinNameday(row):
                 msg = getString("nameday", "somebody").format(",".join(names))
             else:
                 msg = getString("nameday", "nobody")
-        except Exception:
+        except Exception as e:
+            LOG.error("Failed to get nameday: %s", e)
             msg = getString("nameday", "error")
     return msg
 
@@ -553,7 +559,8 @@ def getJoke():
         r = requests.get(url, timeout=5)
         joke_data = r.json()
         return joke_data["value"]
-    except Exception:
+    except Exception as e:
+        LOG.error("Failed to get joke: %s", e)
         return getString("joke", "error")
 
 def marvinJoke(row):
@@ -575,7 +582,8 @@ def getCommit():
         res = r.text.strip()
         msg = f"Använd detta meddelandet: '{res}'"
         return msg
-    except Exception:
+    except Exception as e:
+        LOG.error("Failed to get commit message: %s", e)
         return getString("commit", "error")
 
 def marvinCommit(row):