Update logging. Finally!

We have logging levels.  debug/info/warning/error.
We can turn off debug messages in production.

config.py

@@ -1,6 +1,7 @@
 from subprocess import check_output
 import yaml
 import os
+import logging, logging.handlers
 
 
 def config_load(filename: str):
@@ -14,6 +15,30 @@ if os.path.exists("config_dev.yaml"):
 else:
     config_load("config.yaml")
 
+currentdir = os.path.dirname( os.path.abspath( __file__ ) )
+
+if 'debug' in config and config['debug']:
+    level = logging.DEBUG
+else:
+    level = logging.INFO
+
+root = logging.getLogger(None)
+ch = logging.StreamHandler()
+ch.setLevel( level )
+formatter = logging.Formatter( '%(asctime)s - %(filename)s (%(lineno)d) - %(name)s - %(levelname)s - %(message)s' )
+ch.setFormatter( formatter )
+root.addHandler( ch )
+
+if 'logfile' in config and config['logfile']:
+    fhlog = logging.handlers.TimedRotatingFileHandler( filename = os.path.join( currentdir, 'twgs_proxy.log' ), when = 'midnight', backupCount = 7 )
+    fhlog.setFormatter( formatter )
+    fhlog.setLevel( level )
+    root.addHandler(fhlog)
+    root.setLevel(level)
+
+# with open('logging.config', 'r') as fp:
+#     LOGGING_CONFIG = yaml.safe_load(fp)
+    
 # Extract the version information from git.
 # The match gives us only tags starting with v[0-9]*  Using anything else trips up on double digits.
 version = check_output(

flexible.py

@@ -2,7 +2,7 @@ from twisted.internet import reactor
 from twisted.internet import task
 from twisted.internet import defer
 from colorama import Fore, Back, Style
-from twisted.python import log
+# from twisted.python import log
 from twisted.internet.task import coiterate
 from twisted.internet.defer import gatherResults
 
@@ -11,6 +11,9 @@ import pendulum
 from pprint import pformat
 from galaxy import GameData, PORT_CLASSES, CLASSES_PORT
 from boxes import Boxes
+import logging
+
+log = logging.getLogger(__name__)
 
 class SpinningCursor(object):
     """ Spinner class, that handles every so many clicks 
@@ -71,7 +74,7 @@ class PlayerInput(object):
     d.addCallback(ask.output)
 
     def show_values(show):
-        log.msg(show)
+        log.debug(show)
         self.queue_game.put(pformat(show).replace("\n", "\n\r") + self.nl)
 
     d.addCallback(lambda ignore: show_values(ask.keep))
@@ -107,7 +110,7 @@ class PlayerInput(object):
         self.cp = cp
 
     def alive(self):
-        log.msg("PlayerInput.alive()")
+        log.debug("PlayerInput.alive()")
         self.game.queue_player.put(" ")
 
     def prompt(self, user_prompt, limit, **kw):
@@ -125,7 +128,7 @@ class PlayerInput(object):
         digits : Only allow 0-9 to be entered.
 
         """
-        log.msg("PlayerInput({0}, {1}, {2}".format(user_prompt, limit, kw))
+        log.debug("PlayerInput({0}, {1}, {2}".format(user_prompt, limit, kw))
         self.limit = limit
         self.input = ""
         self.kw = kw
@@ -153,7 +156,7 @@ class PlayerInput(object):
         assert self.deferred is None
         d = defer.Deferred()
         self.deferred = d
-        log.msg("Return deferred ...", self.deferred)
+        log.debug("Return deferred ...", self.deferred)
         return d
 
     def get_input(self, chunk):
@@ -169,11 +172,11 @@ class PlayerInput(object):
                     self.queue_game.put("\a")
             elif ch == "\r":
                 self.queue_game.put(self.r + self.nl)
-                log.msg("Restore observer dispatch", self.save)
+                log.debug("Restore observer dispatch", self.save)
                 assert not self.save is None
                 self.observer.load(self.save)
                 self.save = None
-                log.msg("Disable keepalive")
+                log.debug("Disable keepalive")
                 self.keepalive.stop()
                 self.keepalive = None
                 line = self.input
@@ -189,7 +192,7 @@ class PlayerInput(object):
                     # Abort on blank input
                     if line.strip() == "":
                         # Yes, input is blank, abort.
-                        log.msg("errback, abort_blank")
+                        log.info("errback, abort_blank")
                         reactor.callLater(
                             0, self.deferred.errback, Exception("abort_blank")
                         )
@@ -216,7 +219,7 @@ class PlayerInput(object):
 
     def output(self, line):
         """ A default display of what they just input. """
-        log.msg("PlayerInput.output({0})".format(line))
+        log.debug("PlayerInput.output({0})".format(line))
         self.game.queue_game.put(self.r + "[{0}]".format(line) + self.nl)
         return line
 
@@ -300,7 +303,7 @@ class CIMWarpReport(object):
         self.game.gamedata.warp_to(sector, *parts)
 
     def __del__(self):
-        log.msg("CIMWarpReport {0} RIP".format(self))
+        log.debug("CIMWarpReport {0} RIP".format(self))
 
     def whenDone(self):
         self.defer = defer.Deferred()
@@ -311,7 +314,7 @@ class CIMWarpReport(object):
         """ Data from player (in bytes). """
         chunk = chunk.decode("latin-1", "ignore")
         key = chunk.upper()
-        log.msg("CIMWarpReport.player({0}) : I AM stopping...".format(key))
+        log.warn("CIMWarpReport.player({0}) : I AM stopping...".format(key))
 
         # Stop the keepalive if we are activating something else
         # or leaving...
@@ -372,7 +375,7 @@ class CIMPortReport(object):
         # If we want it, it's here.
         self.defer = None
         self.to_player = self.game.to_player
-        log.msg("to_player (stored)", self.to_player)
+        log.debug("to_player (stored)", self.to_player)
 
         # Hide what's happening from the player
         self.game.to_player = False
@@ -452,10 +455,10 @@ class CIMPortReport(object):
             self.game.gamedata.set_port(port, data)
             # self.portdata[port] = data
         else:
-            log.msg("CIMPortReport:", line, "???")
+            log.error("CIMPortReport:", line, "???")
 
     def __del__(self):
-        log.msg("CIMPortReport {0} RIP".format(self))
+        log.debug("CIMPortReport {0} RIP".format(self))
 
     def whenDone(self):
         self.defer = defer.Deferred()
@@ -466,7 +469,7 @@ class CIMPortReport(object):
         """ Data from player (in bytes). """
         chunk = chunk.decode("latin-1", "ignore")
         key = chunk.upper()
-        log.msg("CIMPortReport.player({0}) : I AM stopping...".format(key))
+        log.warn("CIMPortReport.player({0}) : I AM stopping...".format(key))
 
         # Stop the keepalive if we are activating something else
         # or leaving...
@@ -549,7 +552,7 @@ class ScriptPort(object):
 
     def deactivate(self):
         self.state = 0
-        log.msg("ScriptPort.deactivate ({0})".format(self.times_left))
+        log.debug("ScriptPort.deactivate ({0})".format(self.times_left))
         assert(not self.save is None)
         self.observer.load(self.save)
         self.save = None
@@ -562,12 +565,12 @@ class ScriptPort(object):
         self.deactivate()
 
     def game_prompt(self, prompt: str):
-        log.msg("{0} : {1}".format(self.state, prompt))
+        log.debug("{0} : {1}".format(self.state, prompt))
         if self.state == 3:
-            log.msg("game_prompt: ", prompt)
+            # log.("game_prompt: ", prompt)
             if re.match(r"Command \[TL=.* \(\?=Help\)\? :", prompt):
                 self.state = 4
-                log.msg("Ok, state 4")
+                log.debug("Ok, state 4")
                 if self.sector2 is None:
                     # Ok, we need to prompt for this.
                     self.queue_game.put(self.r + self.nl + 
@@ -578,7 +581,7 @@ class ScriptPort(object):
                     
                     pi = PlayerInput(self.game)
                     def got_need1(*_):
-                        log.msg("Ok, I have:", pi.keep)
+                        log.debug("Ok, I have:", pi.keep)
                         if pi.keep['count'].strip() == '':
                             self.deactivate()
                             return
@@ -625,7 +628,7 @@ class ScriptPort(object):
                             self.deactivate()
                             return
                         self.times_left = int(pi.keep['count'])
-                        log.msg("Ok, I have:", pi.keep)
+                        log.debug("Ok, I have:", pi.keep)
                         # self.queue_game.put(pformat(pi.keep).replace("\n", "\n\r"))
                         self.state = 5
                         self.trade()
@@ -637,7 +640,7 @@ class ScriptPort(object):
             if re.match(r"Command \[TL=.* \(\?=Help\)\? :", prompt):
                 if self.fixable:
                     self.queue_game.put("Ok! Let's fix this by going to the other sector..." + self.nl)
-                    log.msg("Fixing...")
+                    log.debug("Fixing...")
                     if self.this_sector == self.sector1:
                         self.this_sector = self.sector2
                         self.queue_player.put("{0}\r".format(self.sector2))
@@ -665,7 +668,7 @@ class ScriptPort(object):
                         self.last_credits = self.credits
                     else:
                         if self.credits <= self.last_credits:
-                            log.msg("We don't seem to be making any money here...")
+                            log.warn("We don't seem to be making any money here...")
                             self.queue_game.put(self.r + self.nl + "We don't seem to be making any money here.  I'm stopping!" + self.nl)
                             self.deactivate()
                             return
@@ -684,7 +687,7 @@ class ScriptPort(object):
                     else:
                         self.sell_pct += 1
                     price = amount * self.sell_pct // 100
-                    log.msg("start: {0} % {1} price {2}".format(amount, self.sell_perc, price))
+                    log.debug("start: {0} % {1} price {2}".format(amount, self.sell_perc, price))
                     if self.sell_pct > 100:
                         self.sell_pct -= 1
                     else:
@@ -743,7 +746,7 @@ class ScriptPort(object):
                         self.last_credits = self.credits
                     else:
                         if self.credits <= self.last_credits:
-                            log.msg("We don't seem to be making any money here...")
+                            log.warn("We don't seem to be making any money here...")
                             self.deactivate()
                             return                        
                     self.this_sector = self.sector1
@@ -755,7 +758,7 @@ class ScriptPort(object):
         
     def trade(self, *_):
         # state 5
-        log.msg("trade!")
+        log.debug("trade!")
         self.queue_player.put("pt")   # Port Trade
 
         self.this_port = self.game.gamedata.ports[self.this_sector]
@@ -787,7 +790,7 @@ class ScriptPort(object):
         if line.startswith("You have ") and 'credits and' in line:
             parts = line.replace(',', '').split()
             credits = int(parts[2])
-            log.msg("Credits: {0}".format(credits))
+            log.debug("Credits: {0}".format(credits))
             self.credits = credits
 
         if self.state == 1:
@@ -802,9 +805,9 @@ class ScriptPort(object):
                 # Warps to Sector(s) :  397 - (562) - (639)
                 _, _, warps = line.partition(':')
                 warps = warps.replace('-', '').replace('(', '').replace(')', '').strip()
-                log.msg("Warps: [{0}]".format(warps))
+                log.debug("Warps: [{0}]".format(warps))
                 self.warps = [ int(x) for x in re.split("\s+", warps)]
-                log.msg("Warps: [{0}]".format(self.warps))
+                log.debug("Warps: [{0}]".format(self.warps))
                 self.state = 2
         elif self.state == 2:
             if line == "":
@@ -815,7 +818,7 @@ class ScriptPort(object):
                 if True:
                     if not self.this_sector in self.game.gamedata.ports:
                         self.state = 0
-                        log.msg("Current sector {0} not in portdata.".format(self.this_sector))
+                        log.debug("Current sector {0} not in portdata.".format(self.this_sector))
                         self.queue_game.put(self.r + self.nl + "I can't find the current sector in the portdata." + self.nl)
                         self.deactivate()
                         return
@@ -823,13 +826,13 @@ class ScriptPort(object):
                         # Ok, we are in the portdata
                         pd = self.game.gamedata.ports[self.this_sector]
                         if GameData.port_burnt(pd):
-                            log.msg("Current sector {0} port is burnt (<= 20%).".format(self.this_sector))
+                            log.debug("Current sector {0} port is burnt (<= 20%).".format(self.this_sector))
                             self.queue_game.put(self.r + self.nl + "Current sector port is burnt out. <= 20%." + self.nl)
                             self.deactivate()
                             return
 
                     possible = [ x for x in self.warps if x in self.game.gamedata.ports ]
-                    log.msg("Possible:", possible)
+                    log.debug("Possible:", possible)
 
                     # BUG:  Sometimes links to another sector, don't link back!
                     # This causes the game to plot a course / autopilot.
@@ -846,7 +849,7 @@ class ScriptPort(object):
                         return
 
                     possible = [ x for x in possible if not GameData.port_burnt(self.game.gamedata.ports[x]) ]
-                    log.msg("Possible:", possible)
+                    log.debug("Possible:", possible)
 
                     if len(possible) == 0:
                         self.state = 0
@@ -873,7 +876,7 @@ class ScriptPort(object):
                     return
                 else:
                     self.state = 0
-                    log.msg("We don't have any portdata!")
+                    log.warn("We don't have any portdata!")
                     self.queue_game.put(self.r + self.nl + "I have no portdata.  Please run CIM Port Report." + self.nl)
                     self.deactivate()
                     return
@@ -893,10 +896,10 @@ class ScriptPort(object):
             if line.startswith('Fuel Ore') or line.startswith('Organics') or line.startswith('Equipment'):
                 work = line.replace('Fuel Ore', 'Fuel')
                 parts = re.split(r"\s+", work)
-                # log.msg(parts)
+                # log.debug(parts)
                 # Equipment, Selling xxx x% xxx
                 if parts[-1] != '0' and parts[2] != '0' and parts[1] != 'Buying':
-                    log.msg("We have a problem -- they aren't buying what we have in stock!")
+                    log.warn("We have a problem -- they aren't buying what we have in stock!")
                     stuff = line[0]  # F O or E.
                     if stuff == 'F':
                         spos = 0
@@ -914,7 +917,7 @@ class ScriptPort(object):
                     self.deactivate()
                     return
             if "We're not interested." in line:
-                log.msg("Try, try again.  :(")
+                log.warn("Try, try again.  :(")
                 self.state = 5
                 self.trade()
 
@@ -926,7 +929,7 @@ class ScriptPort(object):
                 parts = line.replace(',', '').split()
                 start_price = int(parts[4])
                 price = start_price * self.sell_perc // 100
-                log.msg("start: {0} % {1} price {2}".format(start_price, self.sell_perc, price))
+                log.debug("start: {0} % {1} price {2}".format(start_price, self.sell_perc, price))
                 self.sell_perc -= 1
                 self.queue_player.put("{0}\r".format(price))
             if "We are selling up to" in line:
@@ -934,17 +937,17 @@ class ScriptPort(object):
                 self.state = 8
                 self.sell_perc = 100 - self.percent      
             if "We're not interested." in line:
-                log.msg("Try, try again.  :(")
+                log.info("Try, try again.  :(")
                 self.state = 5
                 self.trade()    
             if "WHAT?!@!? you must be crazy!" in line:
-                log.msg("fix offer")
+                log.warn("fix offer")
                 self.fix_offer = 1
             if "So, you think I'm as stupid as you look?" in line:
-                log.msg("fix offer")                
+                log.warn("fix offer")                
                 self.fix_offer = 1
             if "Quit playing around, you're wasting my time!" in line:
-                log.msg("fix offer")                
+                log.warn("fix offer")                
                 self.fix_offer = 1
 
         elif self.state == 8:
@@ -955,11 +958,11 @@ class ScriptPort(object):
                 parts = line.replace(',', '').split()
                 start_price = int(parts[4])
                 price = start_price * self.sell_perc // 100
-                log.msg("start: {0} % {1} price {2}".format(start_price, self.sell_perc, price))                
+                log.debug("start: {0} % {1} price {2}".format(start_price, self.sell_perc, price))                
                 self.sell_perc += 1
                 self.queue_player.put("{0}\r".format(price))
             if "We're not interested." in line:
-                log.msg("Try, try again.  :(")
+                log.info("Try, try again.  :(")
                 self.state = 5
                 self.trade()                
 
@@ -971,7 +974,7 @@ class ScriptPort(object):
                 # self.trade()
 
         # elif self.state == 3:
-        #     log.msg("At state 3 [{0}]".format(line))
+        #     log.debug("At state 3 [{0}]".format(line))
         #     self.queue_game.put("At state 3.")
         #     self.deactivate()
         #     return
@@ -983,7 +986,7 @@ class ScriptExplore(object):
         WARNINGS:
          We assume the player has a Holo-Scanner!
          We assume the player has lots o turns, or unlimited turns!
-         We assume the player is aware we run infinitly until we can't find new sectors to move to!
+         We assume the player is aware we run infinitely until we can't find new sectors to move to!
     """
     def __init__(self, game):
         self.game = game
@@ -1021,7 +1024,7 @@ class ScriptExplore(object):
         
         def settimes(*_):
             times = ask.keep['times'].strip()
-            log.msg("settimes got '{0}'".format(times))
+            log.debug("settimes got '{0}'".format(times))
             if times == '':
                 self.deactivate()
             else:
@@ -1044,7 +1047,7 @@ class ScriptExplore(object):
     
     def deactivate(self):
         self.state = 0
-        log.msg("ScriptExplore.deactivate()")
+        log.debug("ScriptExplore.deactivate()")
         assert(not self.save is None)
         self.observer.load(self.save)
         self.save = None
@@ -1071,7 +1074,7 @@ class ScriptExplore(object):
         self.clear = []
         self.highwarp = 0
         self.highsector = 0
-        log.msg("ScriptExplore.resetStuff()")
+        log.debug("ScriptExplore.resetStuff()")
 
     def dead_end(self):
         """ We've reached a dead end.  
@@ -1096,13 +1099,13 @@ class ScriptExplore(object):
         self.deactivate()
 
     def game_prompt(self, prompt: str):
-        # log.msg("{0} : {1}".format(self.state, prompt))
+        log.debug("{0} : {1}".format(self.state, prompt))
         if self.state == 2:
             if "Select (H)olo Scan or (D)ensity Scan or (Q)uit" in prompt:
                 self.send2game("D")
                 # self.state += 1
         elif self.state == 5:
-            log.msg("dense is {0} sectors big".format(len(self.dense)))
+            log.debug("dense is {0} sectors big".format(len(self.dense)))
             self.state += 1
             self.send2game("SH")
         elif self.state == 12:
@@ -1115,7 +1118,7 @@ class ScriptExplore(object):
                 self.state += 1
             # Arriving sector :1691  Autopilot disengaging.
             if re.match(r"Command \[TL=.* \(\?=Help\)\? :", prompt):            
-                log.msg("We made it to where we wanted to go!")
+                log.info("We made it to where we wanted to go!")
                 # can't init state 1, because we're at a prompt, so...
                 self.send2game("S")
                 self.state = 2
@@ -1126,7 +1129,7 @@ class ScriptExplore(object):
                 self.travel_path.pop(0)
                 self.state = 12
             if re.match(r"Command \[TL=.* \(\?=Help\)\? :", prompt):            
-                log.msg("We made it to where we wanted to go!")
+                log.info("We made it to where we wanted to go!")
                 # can't init state 1, because we're at a prompt, so...
                 self.send2game("S")
                 self.state = 2
@@ -1139,7 +1142,7 @@ class ScriptExplore(object):
                 # this should re-trigger a scan
     
     def game_line(self, line: str):
-        log.msg("{0} | {1}".format(self.state, line))
+        log.debug("{0} | {1}".format(self.state, line))
         #if "Mine Control" in line: # If we don't have a Holo-Scanner and we attempted to do a Holo-scan, abort
         #    self.deactivate()
 
@@ -1150,7 +1153,7 @@ class ScriptExplore(object):
             if "Relative Density Scan" in line:
                 self.state = 3
             elif "You don't have a long range scanner." in line:
-                log.msg("FATAL: No Long Range Scanner Installed!")
+                log.warn("FATAL: No Long Range Scanner Installed!")
                 self.send2player(Boxes.alert("You need a Long Range Scanner!"))
                 self.deactivate()
                 return
@@ -1163,7 +1166,7 @@ class ScriptExplore(object):
                 new_sector = '(' in line
                 work = line.replace(':', '').replace(')', '').replace('(', '').replace('%', '').replace('==>', '')
                 work = re.split(r"\s+", work)
-                log.msg(work)
+                log.debug(work)
                 # 'Sector', '8192', '0', 'Warps', '4', 'NavHaz', '0', 'Anom', 'No'
                 # 'Sector', '(', '8192)', '0', 'Warps', '4', 'NavHaz', '0', 'Anom', 'No'
 
@@ -1177,7 +1180,7 @@ class ScriptExplore(object):
                     #self.dense.append( {'sector': int(work[1]), 'density': int(work[2]), 'warps': int(work[4]), 'navhaz': int(work[6]), 'anom': temp} )
 
                     self.dense.append( {'sector': int(work[1]), 'density': int(work[2]), 'warps': int(work[4]), 'navhaz': int(work[6]), 'anom': work[8] == 'Yes'} )
-                    log.msg(self.dense)
+                    log.debug(self.dense)
                     # {'sector': 8192, 'density': 0, 'warps': 4, 'navhaz': 0, 'anom': False}
                 
             elif line == "":
@@ -1190,11 +1193,11 @@ class ScriptExplore(object):
         if self.state == 4:
             # Begin Processing our data we got from density scan and find highest warp count in what sectors
             # Remove sectors with one warp
-            log.msg("state 4: {0}".format(self.dense))
+            log.debug("state 4: {0}".format(self.dense))
 
             # Do we have a new place to go? (That is also worth going to)
             if not self.dense: # Dense contains no new sectors, abort
-                log.msg("No New Sectors Found!")
+                log.info("No New Sectors Found!")
                 self.dead_end()
                 return
 
@@ -1222,7 +1225,7 @@ class ScriptExplore(object):
 
             # if not any( w['warps'] > 1 for w in self.dense):
             #     # If there are no sectors with more that 1 warp, abort
-            #     log.msg("No Sectors Found except one move sector!")
+            #     log.debug("No Sectors Found except one move sector!")
             #     self.dead_end()
             #     return
 
@@ -1248,7 +1251,7 @@ class ScriptExplore(object):
             #                     self.clear.append(d['sector'])
             
             if self.clear: # We have sector(s) we can move to!
-                log.msg("Clear Sectors: {0}".format(len(self.clear)))
+                log.debug("Clear Sectors: {0}".format(len(self.clear)))
                 # This was state 5 but why can't we reduce number of states? ( Yeah let's kick California and New York out of the US, oh wrong states :P )
                 # Sort to find greatest warp count
 
@@ -1265,10 +1268,10 @@ class ScriptExplore(object):
                 #                        self.highsector = d['sector']
                 
                 # if self.highwarp and self.highsector:
-                log.msg("Sector: {0:5d} Warps: {1}".format(self.highsector, self.highwarp))
+                log.info("Sector: {0:5d} Warps: {1}".format(self.highsector, self.highwarp))
                 self.state += 1
             else:
-                log.msg("No (safe) sectors to move to!")
+                log.warn("No (safe) sectors to move to!")
                 # Let's try this?!
                 # self.dead_end()   # NO!
                 self.game_over("No SAFE moves.")
@@ -1292,7 +1295,7 @@ class ScriptExplore(object):
             # Warning! Yes we can and will eat all the turns! :P
             if self.times == 0:
                 self.send2player(Boxes.alert("Completed {0}".format(self.maxtimes), base="green"))
-                log.msg("Completed {0}".format(self.maxtimes))
+                log.info("Completed {0}".format(self.maxtimes))
                 self.deactivate()
                 return
 
@@ -1306,11 +1309,11 @@ class ScriptExplore(object):
 
         elif self.state == 10:
             if line.startswith("You are already in that sector!"):
-                log.msg("Already here.  (Whoops!)")
+                log.info("Already here.  (Whoops!)")
                 self.state = 1
                 return
             if line.startswith("Sector  : {0}".format(self.highsector)):
-                log.msg("We're here!")
+                log.info("We're here!")
                 # Ok, we're already there!  no autopilot needed!
                 self.state = 1
                 return
@@ -1320,8 +1323,9 @@ class ScriptExplore(object):
                 # Ok, we've got a path.
                 self.state += 1
         elif self.state == 11:
+            # TOFIX: This can be multiple lines
             self.travel_path = line.replace('(', '').replace(')', '').split(' > ')
-            log.msg("Travel path: {0}".format(self.travel_path))
+            log.debug("Travel path: {0}".format(self.travel_path))
             self.state += 1
             self.travel_path.pop(0) # First sector is one we're in.
             self.stophere = False
@@ -1329,7 +1333,7 @@ class ScriptExplore(object):
         elif self.state == 12:
             # Arriving sector :1691  Autopilot disengaging.
             if 'Autopilot disengaging.' in line:
-                log.msg("We made it to where we wanted to go!")
+                log.info("We made it to where we wanted to go!")
                 self.state = 1
                 return
         elif self.state == 13:
@@ -1337,22 +1341,22 @@ class ScriptExplore(object):
                 self.state += 1
         elif self.state == 14:
             if line == "":
-                log.msg("PATH: {0}".format(self.travel_path))
+                log.debug("PATH: {0}".format(self.travel_path))
 
                 # end of the scan, decision time
                 if self.stophere:
-                    log.msg("STOPHERE")
+                    log.info("STOPHERE")
                     # Ok, let's stop here!
                     # Re-save the sector we were trying to get to.  (we didn't make it there)
                     self.stacksector.add(self.highsector)
                     self.state = 20
                 else:
                     if self.go_on:
-                        log.msg("GO ON")
+                        log.info("GO ON")
                         # Ok, carry on!
                         self.state = 15
                     else:
-                        log.msg("Our way is blocked...")
+                        log.warn("Our way is blocked...")
                         self.stacksector.add(self.highsector)
                         self.state = 20
 
@@ -1375,10 +1379,10 @@ class ScriptExplore(object):
                         self.stophere = True
 
                     next_stop = self.travel_path[0]
-                    log.msg("next_stop {0} from {1}".format(next_stop, self.travel_path))
-                    log.msg("parts: {0}".format(parts))
+                    log.debug("next_stop {0} from {1}".format(next_stop, self.travel_path))
+                    log.debug("parts: {0}".format(parts))
                     if parts[1] == next_stop:
-                        log.msg("next_stop {0} found...".format(next_stop))
+                        log.info("next_stop {0} found...".format(next_stop))
                         # Ok, this is our next stop.  Is it safe to travel to?
                         if parts[2] not in ('100', '0', '1', '101'):
                             # Ok, it's not safe to go on.
@@ -1444,7 +1448,7 @@ class ScriptSpace(object):
 
     def deactivate(self):
         self.state = 0
-        log.msg("ScriptPort.deactivate ({0})".format(self.times_left))
+        log.debug("ScriptPort.deactivate ({0})".format(self.times_left))
         assert(not self.save is None)
         self.observer.load(self.save)
         self.save = None
@@ -1472,7 +1476,7 @@ class ScriptSpace(object):
                         if pos not in seen:
                             next_possible.add(pos)
                 else:
-                    log.msg("unknown found:", s)
+                    log.debug("unknown found:", s)
                     self.unknown = s
                     done = True
                     break
@@ -1480,12 +1484,12 @@ class ScriptSpace(object):
                 seen.add(s)
 
             if self.unknown is None:
-                log.msg("possible:", next_possible)
+                log.debug("possible:", next_possible)
                 possible = next_possible
                 yield
 
     def find_unknown(self, starting_sector):
-        log.msg("find_unknown( {0})".format(starting_sector))
+        log.debug("find_unknown( {0})".format(starting_sector))
         d = defer.Deferred()
         # Process things
 
@@ -1499,11 +1503,11 @@ class ScriptSpace(object):
         if sector is None:
             self.deactivate()
             return
-        log.msg("Travel to {0}...".format(sector))
+        log.debug("Travel to {0}...".format(sector))
         self.queue_player.put("{0}\r".format(sector))
 
     def game_prompt(self, prompt: str):
-        log.msg("{0} : {1}".format(self.state, prompt))
+        log.debug("{0} : {1}".format(self.state, prompt))
         if self.state == 3:
             if re.match(r"Command \[TL=.* \(\?=Help\)\? :", prompt):
                 # this_sector code isn't working -- so!  Get sector from prompt
@@ -1512,7 +1516,7 @@ class ScriptSpace(object):
                 sector, _, _ = sector.partition(']')
                 self.this_sector = int(sector)
                 # Ok, we're done with Density Scan, and we're back at the command prompt
-                log.msg("Go find the nearest unknown...")
+                log.debug("Go find the nearest unknown...")
                 d = self.find_unknown(sector)
                 d.addCallback(self.show_unknown)
         elif self.state == 6:
@@ -1526,11 +1530,11 @@ class ScriptSpace(object):
                         self.queue_player.put("S")
                         self.this_sector = sector
                     else:
-                        log.msg("FATAL: Density for {0} is {1}".format(sector, self.density[sector]))
+                        log.warn("FATAL: Density for {0} is {1}".format(sector, self.density[sector]))
                         self.deactivate()
                         return
                 else:
-                    log.msg("{0} not in density scan? (how's that possible?)".format(sector))                
+                    log.error("{0} not in density scan? (how's that possible?)".format(sector))                
                     self.deactivate()
                     return
         elif self.state == 7:
@@ -1555,32 +1559,32 @@ class ScriptSpace(object):
                         self.state = 7
                         self.this_sector = sector
                     else:
-                        log.msg("FATAL: Density for {0} is {1}".format(sector, self.density[sector]))
+                        log.warn("FATAL: Density for {0} is {1}".format(sector, self.density[sector]))
                         self.deactivate()
                         return
                 else:
-                    log.msg("{0} not in density scane? (how's that possible...)".format(sector))
+                    log.error("{0} not in density scane? (how's that possible...)".format(sector))
                     self.deactivate()
                     return
 
     def next_unknown(self, sector):
-        log.msg("Unknown is :", sector)
+        log.info("Unknown is :", sector)
         self.deactivate()
 
     def game_line(self, line: str):
-        log.msg("line {0} : {1}".format(self.state, line))
+        log.debug("line {0} : {1}".format(self.state, line))
 
         if line.startswith('Sector  : '):
             work = line.strip()
             parts = re.split(r"\s+", work)
             self.this_sector = int(parts[2])
-            log.msg("game_line sector", self.this_sector)
+            log.debug("game_line sector", self.this_sector)
         elif line.startswith("Command [TL=]"):
             # Ok, get the current sector from this
             _, _, sector = line.partition("]:[")
             sector, _, _ = sector.partition("]")
             self.this_sector = int(sector)
-            log.msg("current sector: {0}".format(self.this_sector))
+            log.debug("current sector: {0}".format(self.this_sector))
         elif line.startswith('Warps to Sector(s) :'):
             # Warps to Sector(s) :  5468
             _, _, work = line.partition(':')
@@ -1598,20 +1602,20 @@ class ScriptSpace(object):
             if line == '':
                 # End of Density Scan
                 self.state += 1
-                log.msg("Density: {0}".format(self.density))
+                log.debug("Density: {0}".format(self.density))
                 # self.deactivate()            
             elif line.startswith('Sector'):
                 # Parse Density Scan values
                 work = line.replace('(', '').replace(')', '').replace(':', '').replace('%', '').replace(',', '')
                 parts = re.split(r'\s+', work)
-                log.msg("Sector", parts)
+                log.debug("Sector", parts)
                 sector = int(parts[1])
                 self.density[sector] = int(parts[3])
                 if parts[7] != '0':
-                    log.msg("NavHaz {0} : {1}".format(parts[7], work))
+                    log.warn("NavHaz {0} : {1}".format(parts[7], work))
                     self.density[sector] += 99
                 if parts[9] != 'No':
-                    log.msg("Anom {0} : {1}".format(parts[9], work))
+                    log.warn("Anom {0} : {1}".format(parts[9], work))
                     self.density[sector] += 990
         elif self.state == 4:
             # Looking for shortest path message / warp info
@@ -1631,18 +1635,18 @@ class ScriptSpace(object):
             else:
                 work = line.replace("(", "").replace(")", "").replace(">", "").strip()
                 self.path = [int(x) for x in work.split()]
-                log.msg("Path:", self.path)
+                log.debug("Path:", self.path)
 
                 # Verify
                 current = self.path.pop(0)
                 if current != self.this_sector:
-                    log.msg("Failed: {0} != {1}".format(current, self.this_sector))
+                    log.warn("Failed: {0} != {1}".format(current, self.this_sector))
                     self.deactivate()
                     return
         elif self.state == 7:
             if self.unknown == self.this_sector:
                 # We have arrived!
-                log.msg("We're here!")
+                log.info("We're here!")
                 self.deactivate()
 
 
@@ -1698,7 +1702,7 @@ class ProxyMenu(object):
         self.menu()
 
     def __del__(self):
-        log.msg("ProxyMenu {0} RIP".format(self))
+        log.debug("ProxyMenu {0} RIP".format(self))
 
     def whenDone(self):
         self.defer = defer.Deferred()
@@ -1742,7 +1746,7 @@ class ProxyMenu(object):
         self.queue_game.put("   " + self.c + "-=>" + self.r + " ")
 
     def awake(self):
-        log.msg("ProxyMenu.awake()")
+        log.info("ProxyMenu.awake()")
         self.game.queue_player.put(" ")
 
     def port_report(self, portdata: dict):
@@ -1758,7 +1762,7 @@ class ProxyMenu(object):
         self.welcome_back()
 
     def make_trade_report(self):
-        log.msg("make_trade_report()")
+        log.debug("make_trade_report()")
         ok_trades = []
         best_trades = []
 
@@ -1820,7 +1824,7 @@ class ProxyMenu(object):
         """ Data from player (in bytes). """
         chunk = chunk.decode("latin-1", "ignore")
         key = chunk.upper()
-        log.msg("ProxyMenu.player({0})".format(key))
+        log.debug("ProxyMenu.player({0})".format(key))
 
         # Stop the keepalive if we are activating something else
         # or leaving...
@@ -1906,7 +1910,7 @@ class ProxyMenu(object):
             d.addCallback(ask.output)
 
             def show_values(show):
-                log.msg(show)
+                log.debug(show)
                 self.queue_game.put(pformat(show).replace("\n", "\n\r") + self.nl)
 
             d.addCallback(lambda ignore: show_values(ask.keep))
@@ -2019,7 +2023,7 @@ class ProxyMenu(object):
 
 
     def welcome_back(self, *_):
-        log.msg("welcome_back")
+        log.debug("welcome_back")
         self.keepalive.start(30, True)
         self.menu()
 

galaxy.py

@@ -1,9 +1,13 @@
 import jsonlines
 import os
-from twisted.python import log
+import logging
+
+# from twisted.python import log
 from pprint import pprint
 from colorama import Fore, Back, Style
 
+log = logging.getLogger(__name__)
+
 
 def merge(color_string):
     """ Given a string of colorama ANSI, merge them if you can. """
@@ -68,7 +72,7 @@ class GameData(object):
 
             for warp in sorted(self.warps.keys()):
                 sectors = self.warps[warp]
-                # log.msg("save:", warp, sectors)
+                # log.debug("save:", warp, sectors)
                 sects = sorted(list(sectors))  # make a list
                 w["warp"][warp] = sects
                 if len(w["warp"]) >= self.warp_groups:
@@ -76,7 +80,7 @@ class GameData(object):
                     w = {"warp": {}}
                     yield
 
-                # log.msg(w)
+                # log.debug(w)
                 # writer.write(w)
                 # yield
 
@@ -96,7 +100,7 @@ class GameData(object):
             if len(p["port"]) > 1:
                 writer.write(p)
 
-        log.msg("Saved {0} {1}/{2}".format(filename, len(self.ports), len(self.warps)))
+        log.info("Saved {0} {1}/{2}".format(filename, len(self.ports), len(self.warps)))
 
     def load(self):
         filename = self.storage_filename()
@@ -109,7 +113,7 @@ class GameData(object):
                 for obj in reader:
                     if "warp" in obj:
                         for s, w in obj["warp"].items():
-                            # log.msg(s, w)
+                            # log.debug(s, w)
                             self.warps[int(s)] = set(w)
                         # self.warps.update(obj["warp"])
                     if "port" in obj:
@@ -117,7 +121,9 @@ class GameData(object):
                             self.ports[int(s)] = p
                         # self.ports.update(obj["port"])
                     yield
-        log.msg("Loaded {0} {1}/{2}".format(filename, len(self.ports), len(self.warps)))
+        log.info(
+            "Loaded {0} {1}/{2}".format(filename, len(self.ports), len(self.warps))
+        )
 
     def untwisted_load(self):
         """ Load file without twisted deferred 
@@ -134,14 +140,16 @@ class GameData(object):
                 for obj in reader:
                     if "warp" in obj:
                         for s, w in obj["warp"].items():
-                            # log.msg(s, w)
+                            # log.debug(s, w)
                             self.warps[int(s)] = set(w)
                         # self.warps.update(obj["warp"])
                     if "port" in obj:
                         for s, p in obj["port"].items():
                             self.ports[int(s)] = p
                         # self.ports.update(obj["port"])
-        log.msg("Loaded {0} {1}/{2}".format(filename, len(self.ports), len(self.warps)))
+        log.info(
+            "Loaded {0} {1}/{2}".format(filename, len(self.ports), len(self.warps))
+        )
 
     def get_warps(self, sector: int):
         if sector in self.warps:
@@ -151,7 +159,7 @@ class GameData(object):
     def warp_to(self, source: int, *dest):
         """ connect sector source to destination. 
         """
-        log.msg("Warp {0} to {1}".format(source, dest))
+        log.debug("Warp {0} to {1}".format(source, dest))
         if source not in self.warps:
             self.warps[source] = set()
 
@@ -160,7 +168,7 @@ class GameData(object):
                 self.warps[source].add(d)
 
     def set_port(self, sector: int, data: dict):
-        log.msg("Port {0} : {1}".format(sector, data))
+        log.debug("Port {0} : {1}".format(sector, data))
         if sector not in self.ports:
             self.ports[sector] = dict()
         self.ports[sector].update(data)
@@ -175,7 +183,7 @@ class GameData(object):
                 )
                 self.ports[sector]["port"] = port
                 self.ports[sector]["class"] = CLASSES_PORT[port]
-                log.msg("completed {0} : {1}".format(sector, self.ports[sector]))
+                log.debug("completed {0} : {1}".format(sector, self.ports[sector]))
 
     @staticmethod
     def port_burnt(port: dict):

proxy.py

@@ -6,7 +6,8 @@ from twisted.internet import protocol
 from twisted.internet import reactor
 from twisted.internet import task
 from twisted.internet.task import coiterate
-from twisted.python import log
+# from twisted.python import log
+import logging
 
 import pendulum
 from colorama import Fore, Back, Style
@@ -15,6 +16,8 @@ from pprint import pformat
 
 from config import config, version
 
+log = logging.getLogger(__name__)
+
 def merge(color_string: str):
     """ Given a string of colorama ANSI, merge them if you can. """
     return color_string.replace("m\x1b[", ";")
@@ -60,7 +63,7 @@ class Game(protocol.Protocol):
         self.linestate = ""
 
     def connectionMade(self):
-        log.msg("Connected to Game Server")
+        log.info("Connected to Game Server")
         self.queue_player = self.factory.queue_player
         self.queue_game = self.factory.queue_game
         self.observer = self.factory.observer
@@ -70,7 +73,7 @@ class Game(protocol.Protocol):
 
     def show_game(self, game: tuple):
         self.usergame = game
-        log.msg("## User-Game:", game)
+        log.info("## User-Game: {0}".format(game))
         if game[1] is None:
             if self.gamedata is not None:
                 # start the save
@@ -88,7 +91,7 @@ class Game(protocol.Protocol):
     def playerDataReceived(self, chunk):
         if chunk is False:
             self.queue_player = None
-            log.msg("Player: disconnected, close connection to game")
+            log.info("Player: disconnected, close connection to game")
             # I don't believe I need this if I'm using protocol.Factory
             self.factory.continueTrying = False
             self.transport.loseConnection()
@@ -96,14 +99,14 @@ class Game(protocol.Protocol):
             # Pass received data to the server
             if type(chunk) == str:
                 self.transport.write(chunk.encode('latin-1'))
-                log.msg(">> [{0}]".format(chunk))
+                log.debug(">> [{0}]".format(chunk))
             else:
                 self.transport.write(chunk)
-                log.msg(">> [{0}]".format(chunk.decode("latin-1", "ignore")))
+                log.debug(">> [{0}]".format(chunk.decode("latin-1", "ignore")))
             self.setPlayerReceived()
 
     def warpline(self, line: str):
-        log.msg("warp:", line)
+        log.debug("warp:", line)
         # 1 > 3 > 5 > 77 > 999
         last_sector = self.lastwarp
         line = line.replace("(", "").replace(")", "").replace(">", "").strip()
@@ -116,7 +119,7 @@ class Game(protocol.Protocol):
             self.lastwarp = sector
 
     def cimline(self, line: str):
-        # log.msg(self.linestate, ":", line)
+        # log.debug(self.linestate, ":", line)
         if line[-1] == "%":
             self.linestate = "portcim"
 
@@ -166,7 +169,7 @@ class Game(protocol.Protocol):
                 self.linestate = "cim"
 
     def sectorline(self, line: str):
-        log.msg("sector:", self.current_sector, ':', line)
+        log.debug("sector:", self.current_sector, ':', line)
         if line.startswith('Beacon  : '):
             pass # get beacon text
         elif line.startswith('Ports   : '):
@@ -214,14 +217,14 @@ class Game(protocol.Protocol):
             _, _, work = line.partition(':')
             work = work.strip().replace('(', '').replace(')', '').replace(' - ', ' ')
             parts = [ int(x) for x in work.split(' ')]
-            log.msg("Sectorline warps", parts)
+            log.debug("Sectorline warps", parts)
             self.gamedata.warp_to(self.current_sector, *parts)
             self.sector_state = 'normal'
             self.linestate = ''
 
     def portline(self, line: str):
         # Map these items to which keys
-        log.msg("portline({0}): {1}".format(self.current_sector, line))
+        log.debug("portline({0}): {1}".format(self.current_sector, line))
         mapto = { 'Fuel': 'fuel', 'Organics': 'org', 'Equipment': 'equ'}
 
         if '%' in line:
@@ -229,14 +232,14 @@ class Game(protocol.Protocol):
             work = line.replace('Fuel Ore', 'Fuel').replace('%', '')
             parts = re.split(r"\s+", work)
             data = { mapto[parts[0]] : { 'sale': parts[1][0], 'units': parts[2], 'pct': int(parts[3]) } }
-            # log.msg("Setting {0} to {1}".format(self.current_sector, data))
+            # log.debug("Setting {0} to {1}".format(self.current_sector, data))
             self.gamedata.set_port(self.current_sector, data)
-            # log.msg("NOW: {0}".format(self.gamedata.ports[self.current_sector]))
+            # log.debug("NOW: {0}".format(self.gamedata.ports[self.current_sector]))
 
     def lineReceived(self, line: str):
         """ line received from the game. """
         if "log_lines" in config and config["log_lines"]:
-            log.msg("<< [{0}]".format(line))
+            log.debug("<< [{0}]".format(line))
 
         if "TradeWars Game Server" in line and "Copyright (C) EIS" in line:
             # We are not in a game
@@ -248,7 +251,7 @@ class Game(protocol.Protocol):
             game = line[-1]
             if game >= "A" and game < "Q":
                 self.game = game
-                log.msg("Game: {0}".format(self.game))
+                log.info("Game: {0}".format(self.game))
                 self.observer.emit("user-game", (self.factory.player.user, self.game))
 
         # Process.pas parse line
@@ -257,7 +260,7 @@ class Game(protocol.Protocol):
             _, _, sector = line.partition("]:[")
             sector, _, _ = sector.partition("]")
             self.current_sector = int(sector)
-            log.msg("current sector: {0}".format(self.current_sector))
+            log.info("current sector: {0}".format(self.current_sector))
 
         if line.startswith("The shortest path (") or line.startswith("  TO > "):
             self.linestate = "warpline"
@@ -327,7 +330,7 @@ class Game(protocol.Protocol):
         # Store the text into the buffer before we inject into it.
 
         self.buffer += chunk.decode("latin-1", "ignore")
-        # log.msg("data: [{0}]".format(repr(chunk)))
+        # log.debug("data: [{0}]".format(repr(chunk)))
 
         if b"TWGS v2.20b" in chunk and b"www.eisonline.com" in chunk:
             # Ok, we have a possible target.
@@ -379,7 +382,7 @@ class Game(protocol.Protocol):
         self.observer.emit("prompt", self.getPrompt())
 
     def connectionLost(self, why):
-        log.msg("Game connectionLost because: %s" % why)
+        log.info("Game connectionLost because: %s" % why)
         self.observer.emit("close", why)
         self.queue_game.put(False)
         self.transport.loseConnection()
@@ -428,7 +431,7 @@ class Player(protocol.Protocol):
             elif type(chunk) == str:
                 self.transport.write(chunk.encode('latin-1'))
             else:
-                log.err("gameDataReceived: type (%s) given!".format(type(chunk)))
+                log.error("gameDataReceived: type (%s) given!".format(type(chunk)))
                 self.transport.write(chunk)
             self.setGameReceived()
 
@@ -440,7 +443,7 @@ class Player(protocol.Protocol):
             if len(parts) >= 5:
                 # rlogin we have the username
                 self.user = parts[1]
-                log.msg("User: {0}".format(self.user))
+                log.info("User: {0}".format(self.user))
                 zpos = self.buffer.rindex("\x00")
                 self.buffer = self.buffer[zpos + 1 :]
                 # but I don't need the buffer anymore, so:
@@ -472,7 +475,7 @@ class Player(protocol.Protocol):
                 nl = "\n\r"
                 r = Style.RESET_ALL
 
-                log.msg("NNY!")
+                log.warn("NNY!")
                 prompt = self.game.buffer
                 self.queue_game.put(
                     r
@@ -489,12 +492,12 @@ class Player(protocol.Protocol):
                 # self.observer.emit("notyet", prompt)
 
     def connectionLost(self, why):
-        log.msg("lost connection %s" % why)
+        log.info("lost connection %s" % why)
         self.observer.emit("close", why)
         self.queue_player.put(False)
 
     def connectionFailed(self, why):
-        log.msg("connectionFailed: %s" % why)
+        log.error("connectionFailed: %s" % why)
 
 
 
@@ -511,20 +514,20 @@ class GlueFactory(protocol.ClientFactory):
         self.game = None
 
     def closeIt(self):
-        log.msg("closeIt")
+        log.info("closeIt")
         self.queue_game.put(False)
 
     def getUser(self, user):
-        log.msg("getUser( %s )" % user)
+        log.info("getUser( %s )" % user)
         self.twgs.logUser(user)
 
     # This was needed when I replaced ClientFactory with Factory.
     # def clientConnectionLost(self, connector, why):
-    #     log.msg("clientconnectionlost: %s" % why)
+    #     log.debug("clientconnectionlost: %s" % why)
     #     self.queue_client.put(False)
 
     def clientConnectionFailed(self, connector, why):
-        log.msg("connection to game failed: %s" % why)
+        log.error("connection to game failed: %s" % why)
         self.queue_game.put(b"Sorry!  I'm Unable to connect to the game server.\r\n")
 
         # syncterm gets cranky/locks up if we close this here.

twgs-proxy.py

@@ -3,17 +3,24 @@
 import sys
 from twisted.internet import reactor
 from twisted.internet import protocol
+import logging
+import logging.config
 from twisted.python import log
-from twisted.python.logfile import DailyLogFile
+
+# from twisted.python.logfile import DailyLogFile
 from config import config, version
 from proxy import Player
 
-if "logfile" in config and config["logfile"]:
-    log.startLogging(DailyLogFile("proxy.log", "."))
-else:
-    log.startLogging(sys.stdout)
+logger = logging.getLogger(__name__)
+
+log.PythonLoggingObserver().start()
+
+# if "logfile" in config and config["logfile"]:
+#     log.startLogging(DailyLogFile("proxy.log", "."))
+# else:
+#     log.startLogging(sys.stdout)
 
-log.msg("This is version: {0}".format(version))
+logger.error("This is version: {0}".format(version))
 factory = protocol.Factory()
 factory.protocol = Player
 reactor.listenTCP(config["listen_port"], factory, interface=config["listen_on"])