Use logging in mininode.py

This commit adds a TestFramework.mininode Logger to the mininode module.
This is a child logger of TestFramework, so the handlers set up in
test_framework.py will receive records from this logger and emit them
to the log file and console as appropriate.
This commit is contained in:
John Newbery 2017-02-15 12:21:22 -05:00
parent 553a976929
commit 6d0e3250bb

View file

@ -51,6 +51,8 @@ NODE_GETUTXO = (1 << 1)
NODE_BLOOM = (1 << 2) NODE_BLOOM = (1 << 2)
NODE_WITNESS = (1 << 3) NODE_WITNESS = (1 << 3)
logger = logging.getLogger("TestFramework.mininode")
# Keep our own socket map for asyncore, so that we can track disconnects # Keep our own socket map for asyncore, so that we can track disconnects
# ourselves (to workaround an issue with closing an asyncore socket when # ourselves (to workaround an issue with closing an asyncore socket when
# using select) # using select)
@ -1502,8 +1504,7 @@ class NodeConnCB(object):
try: try:
getattr(self, 'on_' + message.command.decode('ascii'))(conn, message) getattr(self, 'on_' + message.command.decode('ascii'))(conn, message)
except: except:
print("ERROR delivering %s (%s)" % (repr(message), logger.exception("ERROR delivering %s" % repr(message))
sys.exc_info()[0]))
def on_version(self, conn, message): def on_version(self, conn, message):
if message.nVersion >= 209: if message.nVersion >= 209:
@ -1615,7 +1616,6 @@ class NodeConn(asyncore.dispatcher):
def __init__(self, dstaddr, dstport, rpc, callback, net="regtest", services=NODE_NETWORK, send_version=True): def __init__(self, dstaddr, dstport, rpc, callback, net="regtest", services=NODE_NETWORK, send_version=True):
asyncore.dispatcher.__init__(self, map=mininode_socket_map) asyncore.dispatcher.__init__(self, map=mininode_socket_map)
self.log = logging.getLogger("NodeConn(%s:%d)" % (dstaddr, dstport))
self.dstaddr = dstaddr self.dstaddr = dstaddr
self.dstport = dstport self.dstport = dstport
self.create_socket(socket.AF_INET, socket.SOCK_STREAM) self.create_socket(socket.AF_INET, socket.SOCK_STREAM)
@ -1640,8 +1640,7 @@ class NodeConn(asyncore.dispatcher):
vt.addrFrom.port = 0 vt.addrFrom.port = 0
self.send_message(vt, True) self.send_message(vt, True)
print('MiniNode: Connecting to Bitcoin Node IP # ' + dstaddr + ':' \ logger.info('Connecting to Bitcoin Node: %s:%d' % (self.dstaddr, self.dstport))
+ str(dstport))
try: try:
self.connect((dstaddr, dstport)) self.connect((dstaddr, dstport))
@ -1649,18 +1648,14 @@ class NodeConn(asyncore.dispatcher):
self.handle_close() self.handle_close()
self.rpc = rpc self.rpc = rpc
def show_debug_msg(self, msg):
self.log.debug(msg)
def handle_connect(self): def handle_connect(self):
if self.state != "connected": if self.state != "connected":
self.show_debug_msg("MiniNode: Connected & Listening: \n") logger.debug("Connected & Listening: %s:%d" % (self.dstaddr, self.dstport))
self.state = "connected" self.state = "connected"
self.cb.on_open(self) self.cb.on_open(self)
def handle_close(self): def handle_close(self):
self.show_debug_msg("MiniNode: Closing Connection to %s:%d... " logger.debug("Closing connection to: %s:%d" % (self.dstaddr, self.dstport))
% (self.dstaddr, self.dstport))
self.state = "closed" self.state = "closed"
self.recvbuf = b"" self.recvbuf = b""
self.sendbuf = b"" self.sendbuf = b""
@ -1742,17 +1737,14 @@ class NodeConn(asyncore.dispatcher):
t.deserialize(f) t.deserialize(f)
self.got_message(t) self.got_message(t)
else: else:
self.show_debug_msg("Unknown command: '" + command + "' " + logger.warning("Received unknown command from %s:%d: '%s' %s" % (self.dstaddr, self.dstport, command, repr(msg)))
repr(msg))
except Exception as e: except Exception as e:
print('got_data:', repr(e)) logger.exception('got_data:', repr(e))
# import traceback
# traceback.print_tb(sys.exc_info()[2])
def send_message(self, message, pushbuf=False): def send_message(self, message, pushbuf=False):
if self.state != "connected" and not pushbuf: if self.state != "connected" and not pushbuf:
raise IOError('Not connected, no pushbuf') raise IOError('Not connected, no pushbuf')
self.show_debug_msg("Send %s" % repr(message)) logger.debug("Send message to %s:%d: %s" % (self.dstaddr, self.dstport, repr(message)))
command = message.command command = message.command
data = message.serialize() data = message.serialize()
tmsg = self.MAGIC_BYTES[self.network] tmsg = self.MAGIC_BYTES[self.network]
@ -1774,7 +1766,7 @@ class NodeConn(asyncore.dispatcher):
self.messagemap[b'ping'] = msg_ping_prebip31 self.messagemap[b'ping'] = msg_ping_prebip31
if self.last_sent + 30 * 60 < time.time(): if self.last_sent + 30 * 60 < time.time():
self.send_message(self.messagemap[b'ping']()) self.send_message(self.messagemap[b'ping']())
self.show_debug_msg("Recv %s" % repr(message)) logger.debug("Received message from %s:%d: %s" % (self.dstaddr, self.dstport, repr(message)))
self.cb.deliver(self, message) self.cb.deliver(self, message)
def disconnect_node(self): def disconnect_node(self):