pubbot: Add more detail to logging

Wrap raw pubnub messages in a metadata object containing:
- time
- our hostname
- our pid
- any inferred information

Plus make a message-less log write on startup so we know where there might be gaps.

Also do more error handling so that we don't completely lose messages on error.

zulip_bots/zulip_bots/pubbot.py

@@ -1,6 +1,8 @@
 
 import json
 import logging
+import os
+import socket
 import time
 
 from .config import get_config
@@ -49,7 +51,7 @@ def get_giveaway():
 	return g
 
 
-def main(conf_file, message_log_file):
+def main(conf_file, message_log_file, name=socket.gethostname()):
 	"""Config:
 		zulip_url
 		zulip_email
@@ -59,47 +61,84 @@ def main(conf_file, message_log_file):
 
 	config = get_config(conf_file)
 	client = Client(config["zulip_url"], config["zulip_email"], config["zulip_api_key"])
+
 	message_log = open(message_log_file, "a")
+	def write_log(log):
+		message_log.write(json.dumps(log) + '\n')
+
+	write_log({
+		"type": "startup",
+		"host": name,
+		"pid": os.getpid(),
+		"time": time.time(),
+	})
 
 	prizes = {}
 	total = None
 	for msg in stream():
-		message_log.write(json.dumps(msg) + '\n')
+		log = {
-
+			"type": "unknown",
-		if msg["c"] == "db_total":
+			"host": name,
-			increase = None if total is None else msg["d"] - total
+			"pid": os.getpid(),
-			increase_str = "" if increase is None else " (+${:.2f})".format(msg["d"] - total)
+			"time": time.time(),
-			giveaway = get_giveaway()
+			"message": msg,
-			entries_str = ""
+		}
-			if increase is not None and giveaway is not None:
+
-				amount = giveaway["amount"]
+		try:
-				if (increase + 0.005) % amount < 0.01:
+			try:
-					entries = int((increase + 0.005) / amount)
+				message_time = float(msg["p"]["t"]) / 10000000
-					entries_str = " ({} entries of ${:.2f})".format(entries, amount)
+			except (KeyError, ValueError):
-			logging.info("New donation total: {}{}{}".format(msg["d"], increase_str, entries_str))
+				message_time = None
-			client.send_to_stream("bot-spam", "Donation Firehose", "Donation total is now ${:.2f}{}{}".format(msg["d"], increase_str, entries_str))
+
-			if increase is not None and increase >= 500:
+			log["message_time"] = message_time
-				client.send_to_stream("bot-spam", "Notable Donations", "Large donation of ${:.2f} (total ${:.2f}){}".format(increase, msg['d'], entries_str))
+
-			total = msg["d"]
+			if msg["c"] == "db_total":
-
+				log["type"] == "total"
-		elif msg["c"] == "db_vue" and msg["d"].get("channel").startswith("prize:"):
+				increase = None if total is None else msg["d"] - total
-			d = msg["d"]
+				log["increase"] = increase
-			prize_id = msg["d"]["channel"].split(":")[1]
+				increase_str = "" if increase is None else " (+${:.2f})".format(msg["d"] - total)
-			data = d["data"]
+				giveaway = get_giveaway()
-			logging.info(f"Prize update for {prize_id}: {data}")
+				entries_str = ""
-			if prize_id not in prizes:
+				if increase is not None and giveaway is not None:
-				prizes[prize_id] = get_prize(prize_id)
+					amount = giveaway["amount"]
-			if "bidder" in data and "bid" in data:
+					if (increase + 0.005) % amount < 0.01:
-				client.send_to_stream("bot-spam", "Bids", "At <time:{time}>, {bidder} bid ${bid:.2f} for [{title}](https://desertbus.org/prize/{prize_id})".format(
+						entries = int((increase + 0.005) / amount)
-					time = float(msg["p"]["t"]) / 10000000,
+						log["giveaway_amount"] = amount
-					bidder = data["bidder"],
+						log["giveaway_entries"] = entries
-					bid = data["bid"],
+						entries_str = " ({} entries of ${:.2f})".format(entries, amount)
-					title = prizes[prize_id]["title"],
+				logging.info("New donation total: {}{}{}".format(msg["d"], increase_str, entries_str))
-					prize_id = prize_id,
+				client.send_to_stream("bot-spam", "Donation Firehose", "Donation total is now ${:.2f}{}{}".format(msg["d"], increase_str, entries_str))
-				))
+				if increase is not None and increase >= 500:
-
+					client.send_to_stream("bot-spam", "Notable Donations", "Large donation of ${:.2f} (total ${:.2f}){}".format(increase, msg['d'], entries_str))
-		else:
+				total = msg["d"]
-			logging.warning("Unknown message: {}".format(msg))
+
+			elif msg["c"] == "db_vue" and msg["d"].get("channel").startswith("prize:"):
+				log["type"] = "prize"
+				d = msg["d"]
+				prize_id = msg["d"]["channel"].split(":")[1]
+				data = d["data"]
+				logging.info(f"Prize update for {prize_id}: {data}")
+				if prize_id not in prizes:
+					prizes[prize_id] = get_prize(prize_id)
+				log["prize_id"] = prize_id
+				if "bidder" in data and "bid" in data:
+					log["bidder"] = data["bidder"]
+					log["bid"] = data["bid"]
+					client.send_to_stream("bot-spam", "Bids", "At <time:{time}>, {bidder} bid ${bid:.2f} for [{title}](https://desertbus.org/prize/{prize_id})".format(
+						time = message_time,
+						bidder = data["bidder"],
+						bid = data["bid"],
+						title = prizes[prize_id]["title"],
+						prize_id = prize_id,
+					))
+
+			else:
+				logging.warning("Unknown message: {}".format(msg))
+		except Exception:
+			logging.exception(f"Failed to handle message {msg}")
+			log["type"] = "error"
+
+		write_log(log)
 
 
 if __name__ == '__main__':