Created a logging configuration that supports various log levels, multiple output streams, and is inherently thread-safe. Changed some print calls to logger calls in bitmessagemain

.gitignore

@@ -1,5 +1,6 @@
 **pyc
 **dat
 **.DS_Store
+*.log
 src/build
 src/dist

src/bitmessagemain.py

@@ -47,6 +47,8 @@ import json
 from subprocess import call  # used when the API must execute an outside program
 import singleton
 import proofofwork
+# Logging
+from debug import logger
 
 # For each stream to which we connect, several outgoingSynSender threads
 # will exist and will collectively create 8 connections with peers.
@@ -95,9 +97,10 @@ class outgoingSynSender(threading.Thread):
             sock.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
             sock.settimeout(20)
             if shared.config.get('bitmessagesettings', 'socksproxytype') == 'none' and verbose >= 2:
-                shared.printLock.acquire()
+                #shared.printLock.acquire()
-                print 'Trying an outgoing connection to', HOST, ':', PORT
+                #print 'Trying an outgoing connection to', HOST, ':', PORT
-                shared.printLock.release()
+                logger.info('Trying an outgoing connection to %s:%s' % (HOST, PORT))
+                #shared.printLock.release()
                 # sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
             elif shared.config.get('bitmessagesettings', 'socksproxytype') == 'SOCKS4a':
                 if verbose >= 2:
@@ -672,13 +675,9 @@ class receiveDataThread(threading.Thread):
         sleepTime = lengthOfTimeWeShouldUseToProcessThisMessage - \
             (time.time() - self.messageProcessingStartTime)
         if sleepTime > 0:
-            shared.printLock.acquire()
+            logger.info('Timing attack mitigation: Sleeping for %s seconds' % str(sleepTime))
-            print 'Timing attack mitigation: Sleeping for', sleepTime, 'seconds.'
-            shared.printLock.release()
             time.sleep(sleepTime)
-        shared.printLock.acquire()
+        logger.info('Total message processing time: %ss' % str(time.time() - self.messageProcessingStartTime))
-        print 'Total message processing time:', time.time() - self.messageProcessingStartTime, 'seconds.'
-        shared.printLock.release()
 
     # A broadcast message has a valid time and POW and requires processing.
     # The recbroadcast function calls this one.
@@ -715,9 +714,8 @@ class receiveDataThread(threading.Thread):
                 sendersHash = data[readPosition:readPosition + 20]
                 if sendersHash not in shared.broadcastSendersForWhichImWatching:
                     # Display timing data
-                    shared.printLock.acquire()
+                    logger.info('Time spent deciding that we are not interested in this v1 broadcast: %s' %
-                    print 'Time spent deciding that we are not interested in this v1 broadcast:', time.time() - self.messageProcessingStartTime
+                                str(time.time() - self.messageProcessingStartTime))
-                    shared.printLock.release()
                     return
                 # At this point, this message claims to be from sendersHash and
                 # we are interested in it. We still have to hash the public key
@@ -749,11 +747,11 @@ class receiveDataThread(threading.Thread):
                 signature = data[readPosition:readPosition + signatureLength]
                 try:
                     if not highlevelcrypto.verify(data[12:readPositionAtBottomOfMessage], signature, sendersPubSigningKey.encode('hex')):
-                        print 'ECDSA verify failed'
+                        logger.info('ECDSA verify failed')
                         return
-                    print 'ECDSA verify passed'
+                    logger.info('ECDSA verify passed')
                 except Exception as err:
-                    print 'ECDSA verify failed', err
+                    logger.debug('ECDSA verify failed: %s' % str(err))
                     return
                 # verify passed
 
@@ -1059,13 +1057,9 @@ class receiveDataThread(threading.Thread):
         sleepTime = lengthOfTimeWeShouldUseToProcessThisMessage - \
             (time.time() - self.messageProcessingStartTime)
         if sleepTime > 0:
-            shared.printLock.acquire()
+            logger.info('Timing attack mitigation: Sleeping for %s seconds' % str(sleepTime))
-            print 'Timing attack mitigation: Sleeping for', sleepTime, 'seconds.'
-            shared.printLock.release()
             time.sleep(sleepTime)
-        shared.printLock.acquire()
+        logger.info('Total message processing time: %ss' % str(time.time() - self.messageProcessingStartTime))
-        print 'Total message processing time:', time.time() - self.messageProcessingStartTime, 'seconds.'
-        shared.printLock.release()
 
     # A msg message has a valid time and POW and requires processing. The
     # recmsg function calls this one.
@@ -1089,10 +1083,8 @@ class receiveDataThread(threading.Thread):
                 strftime(shared.config.get('bitmessagesettings', 'timeformat'), localtime(int(time.time()))), 'utf-8')))))
             return
         else:
-            shared.printLock.acquire()
+            logger.info('This was NOT on acknowledgement bound for me.')
-            print 'This was NOT an acknowledgement bound for me.'
+            # logger.info("Ack data for which I'm watching: %s" % ackdataForWhichImWatching)
-            # print 'ackdataForWhichImWatching', ackdataForWhichImWatching
-            shared.printLock.release()
 
         # This is not an acknowledgement bound for me. See if it is a message
         # bound for me by trying to decrypt it with my private keys.
@@ -1109,9 +1101,8 @@ class receiveDataThread(threading.Thread):
                 # print 'cryptorObject.decrypt Exception:', err
         if not initialDecryptionSuccessful:
             # This is not a message bound for me.
-            shared.printLock.acquire()
+            logger.info('Length of time program spent failing to decrypt this message %s seconds' %
-            print 'Length of time program spent failing to decrypt this message:', time.time() - self.messageProcessingStartTime, 'seconds.'
+                        str(time.time() - self.messageProcessingStartTime))
-            shared.printLock.release()
         else:
             # This is a message bound for me.
             toAddress = shared.myAddressesByHash[

src/debug.py

@@ -0,0 +1,45 @@
+#!/usr/bin/env python2.7
+
+import logging
+import logging.config
+
+log_level = 'DEBUG' # Get from a config file at some point?
+
+logging.config.dictConfig({
+    'version': 1,
+    'formatters': {
+        'default': {
+            'format': '%(asctime)s - %(levelname)s - %(message)s',
+        },
+    },
+    'handlers': {
+        'console': {
+            'class': 'logging.StreamHandler',
+            'formatter': 'default',
+            'level': log_level,
+            'stream': 'ext://sys.stdout'
+        },
+        'file': {
+            'class': 'logging.handlers.RotatingFileHandler',
+            'formatter': 'default',
+            'level': log_level,
+            'filename': 'bm.log',
+            'maxBytes': 1024,
+            'backupCount': 0,
+        }
+    },
+    'loggers': {
+        'console_only': {
+            'handlers': ['console']
+        },
+        'both': {
+            'handlers': ['console', 'file']
+        },
+    },
+    'root': {
+        'level': log_level,
+        'handlers': ['console']
+    },
+})
+
+logger = logging.getLogger('console_only')