1
0

logging: basics

This commit is contained in:
SomberNight
2019-04-26 18:52:26 +02:00
parent 4d64e132d7
commit 3385a94753
68 changed files with 681 additions and 563 deletions

View File

@@ -37,7 +37,7 @@ from aiorpcx import RPCSession, Notification, NetAddress
from aiorpcx.curio import timeout_after, TaskTimeout
import certifi
from .util import PrintError, ignore_exceptions, log_exceptions, bfh, SilentTaskGroup
from .util import ignore_exceptions, log_exceptions, bfh, SilentTaskGroup
from . import util
from . import x509
from . import pem
@@ -46,6 +46,7 @@ from . import blockchain
from .blockchain import Blockchain
from . import constants
from .i18n import _
from .logging import Logger
if TYPE_CHECKING:
from .network import Network
@@ -98,7 +99,7 @@ class NotificationSession(RPCSession):
else:
raise Exception(f'unexpected request. not a notification')
except Exception as e:
self.interface.print_error(f"error handling request {request}. exc: {repr(e)}")
self.interface.logger.info(f"error handling request {request}. exc: {repr(e)}")
await self.close()
async def send_request(self, *args, timeout=None, **kwargs):
@@ -148,7 +149,7 @@ class NotificationSession(RPCSession):
def maybe_log(self, msg: str) -> None:
if not self.interface: return
if self.interface.debug or self.interface.network.debug:
self.interface.print_error(msg)
self.interface.logger.debug(msg)
class GracefulDisconnect(Exception): pass
@@ -180,7 +181,7 @@ def serialize_server(host: str, port: Union[str, int], protocol: str) -> str:
return str(':'.join([host, str(port), protocol]))
class Interface(PrintError):
class Interface(Logger):
verbosity_filter = 'i'
def __init__(self, network: 'Network', server: str, proxy: Optional[dict]):
@@ -189,6 +190,7 @@ class Interface(PrintError):
self.server = server
self.host, self.port, self.protocol = deserialize_server(self.server)
self.port = int(self.port)
Logger.__init__(self)
assert network.config.path
self.cert_path = os.path.join(network.config.path, 'certs', self.host)
self.blockchain = None
@@ -209,7 +211,7 @@ class Interface(PrintError):
self.group = SilentTaskGroup()
def diagnostic_name(self):
return self.host
return f"{self.host}:{self.port}"
def _set_proxy(self, proxy: dict):
if proxy:
@@ -263,18 +265,18 @@ class Interface(PrintError):
try:
b = pem.dePem(contents, 'CERTIFICATE')
except SyntaxError as e:
self.print_error("error parsing already saved cert:", e)
self.logger.info(f"error parsing already saved cert: {e}")
raise ErrorParsingSSLCert(e) from e
try:
x = x509.X509(b)
except Exception as e:
self.print_error("error parsing already saved cert:", e)
self.logger.info(f"error parsing already saved cert: {e}")
raise ErrorParsingSSLCert(e) from e
try:
x.check_date()
return True
except x509.CertificateError as e:
self.print_error("certificate has expired:", e)
self.logger.info(f"certificate has expired: {e}")
os.unlink(self.cert_path) # delete pinned cert only in this case
return False
@@ -306,7 +308,7 @@ class Interface(PrintError):
try:
return await func(self, *args, **kwargs)
except GracefulDisconnect as e:
self.print_error("disconnecting gracefully. {}".format(repr(e)))
self.logger.info(f"disconnecting gracefully. {repr(e)}")
finally:
await self.network.connection_down(self)
self.got_disconnected.set_result(1)
@@ -321,12 +323,12 @@ class Interface(PrintError):
try:
ssl_context = await self._get_ssl_context()
except (ErrorParsingSSLCert, ErrorGettingSSLCertFromServer) as e:
self.print_error('disconnecting due to: {}'.format(repr(e)))
self.logger.info(f'disconnecting due to: {repr(e)}')
return
try:
await self.open_session(ssl_context)
except (asyncio.CancelledError, OSError, aiorpcx.socks.SOCKSError) as e:
self.print_error('disconnecting due to: {}'.format(repr(e)))
self.logger.info(f'disconnecting due to: {repr(e)}')
return
def mark_ready(self):
@@ -343,7 +345,7 @@ class Interface(PrintError):
self.blockchain = chain
assert self.blockchain is not None
self.print_error("set blockchain with height", self.blockchain.height())
self.logger.info(f"set blockchain with height {self.blockchain.height()}")
self.ready.set_result(1)
@@ -353,7 +355,7 @@ class Interface(PrintError):
for _ in range(10):
dercert = await self.get_certificate()
if dercert:
self.print_error("succeeded in getting cert")
self.logger.info("succeeded in getting cert")
with open(self.cert_path, 'w') as f:
cert = ssl.DER_cert_to_PEM_cert(dercert)
# workaround android bug
@@ -380,7 +382,7 @@ class Interface(PrintError):
return None
async def get_block_header(self, height, assert_mode):
self.print_error('requesting block header {} in mode {}'.format(height, assert_mode))
self.logger.info(f'requesting block header {height} in mode {assert_mode}')
# use lower timeout as we usually have network.bhi_lock here
timeout = self.network.get_network_timeout_seconds(NetworkTimeout.Urgent)
res = await self.session.send_request('blockchain.block.header', [height], timeout=timeout)
@@ -390,7 +392,7 @@ class Interface(PrintError):
index = height // 2016
if can_return_early and index in self._requested_chunks:
return
self.print_error("requesting chunk from height {}".format(height))
self.logger.info(f"requesting chunk from height {height}")
size = 2016
if tip is not None:
size = min(size, tip - index * 2016 + 1)
@@ -425,7 +427,7 @@ class Interface(PrintError):
if not self.network.check_interface_against_healthy_spread_of_connected_servers(self):
raise GracefulDisconnect(f'too many connected servers already '
f'in bucket {self.bucket_based_on_ipaddress()}')
self.print_error("connection established. version: {}".format(ver))
self.logger.info(f"connection established. version: {ver}")
async with self.group as group:
await group.spawn(self.ping)
@@ -472,7 +474,7 @@ class Interface(PrintError):
async with self.network.bhi_lock:
if self.blockchain.height() >= height and self.blockchain.check_header(header):
# another interface amended the blockchain
self.print_error("skipping header", height)
self.logger.info(f"skipping header {height}")
return
_, height = await self.step(height, header)
# in the simple case, height == self.tip+1
@@ -518,13 +520,13 @@ class Interface(PrintError):
can_connect = blockchain.can_connect(header) if 'mock' not in header else header['mock']['connect'](height)
if not can_connect:
self.print_error("can't connect", height)
self.logger.info(f"can't connect {height}")
height, header, bad, bad_header = await self._search_headers_backwards(height, header)
chain = blockchain.check_header(header) if 'mock' not in header else header['mock']['check'](header)
can_connect = blockchain.can_connect(header) if 'mock' not in header else header['mock']['connect'](height)
assert chain or can_connect
if can_connect:
self.print_error("could connect", height)
self.logger.info(f"could connect {height}")
height += 1
if isinstance(can_connect, Blockchain): # not when mocking
self.blockchain = can_connect
@@ -543,7 +545,7 @@ class Interface(PrintError):
while True:
assert good < bad, (good, bad)
height = (good + bad) // 2
self.print_error("binary step. good {}, bad {}, height {}".format(good, bad, height))
self.logger.info(f"binary step. good {good}, bad {bad}, height {height}")
header = await self.get_block_header(height, 'binary')
chain = blockchain.check_header(header) if 'mock' not in header else header['mock']['check'](header)
if chain:
@@ -561,7 +563,7 @@ class Interface(PrintError):
raise Exception('unexpected bad header during binary: {}'.format(bad_header))
_assert_header_does_not_check_against_any_chain(bad_header)
self.print_error("binary search exited. good {}, bad {}".format(good, bad))
self.logger.info(f"binary search exited. good {good}, bad {bad}")
return good, bad, bad_header
async def _resolve_potential_chain_fork_given_forkpoint(self, good, bad, bad_header):
@@ -575,12 +577,12 @@ class Interface(PrintError):
assert bh >= good, (bh, good)
if bh == good:
height = good + 1
self.print_error("catching up from {}".format(height))
self.logger.info(f"catching up from {height}")
return 'no_fork', height
# this is a new fork we don't yet have
height = bad + 1
self.print_error(f"new fork at bad height {bad}")
self.logger.info(f"new fork at bad height {bad}")
forkfun = self.blockchain.fork if 'mock' not in bad_header else bad_header['mock']['fork']
b = forkfun(bad_header) # type: Blockchain
self.blockchain = b
@@ -614,7 +616,7 @@ class Interface(PrintError):
height = self.tip - 2 * delta
_assert_header_does_not_check_against_any_chain(bad_header)
self.print_error("exiting backward mode at", height)
self.logger.info(f"exiting backward mode at {height}")
return height, header, bad, bad_header
@classmethod