debug

lbry/wallet/network.py

@@ -77,7 +77,7 @@ class ClientSession(BaseClientSession):
             self.synchronous_close()
             raise
         except asyncio.CancelledError:
-            log.info("cancelled sending %s to %s:%i", method, *self.server)
+            log.warning("cancelled sending %s to %s:%i", method, *self.server)
             self.synchronous_close()
             raise
         finally:
@@ -90,6 +90,7 @@ class ClientSession(BaseClientSession):
         while True:
             try:
                 if self.is_closing():
+                    log.warning("is closing, reconnect")
                     await self.create_connection(self.timeout)
                     await self.ensure_server_version()
                     self._on_connect_cb()
@@ -99,10 +100,14 @@ class ClientSession(BaseClientSession):
             except RPCError as e:
                 log.warning("Server error, ignoring for 1h: %s:%d -- %s", *self.server, e.message)
                 retry_delay = 60 * 60
-            except (asyncio.TimeoutError, OSError):
+            except asyncio.TimeoutError:
+                log.error("closing due to timeout")
                 await self.close()
                 retry_delay = min(60, retry_delay * 2)
-                log.debug("Wallet server timeout (retry in %s seconds): %s:%d", retry_delay, *self.server)
+                log.warning("Wallet server timeout (retry in %s seconds): %s:%d", retry_delay, *self.server)
+            except Exception:
+                log.exception("unexpected error")
+                raise
             try:
                 await asyncio.wait_for(self.trigger_urgent_reconnect.wait(), timeout=retry_delay)
             except asyncio.TimeoutError:
@@ -127,7 +132,7 @@ class ClientSession(BaseClientSession):
         controller.add(request.args)
 
     def connection_lost(self, exc):
-        log.debug("Connection lost: %s:%d", *self.server)
+        log.warning("Connection lost: %s:%d", *self.server)
         super().connection_lost(exc)
         self.response_time = None
         self.connection_latency = None
@@ -223,7 +228,8 @@ class Network:
                 except asyncio.TimeoutError:
                     log.warning("Wallet server call timed out, retrying.")
                 except ConnectionError:
-                    pass
+                    log.warning("Ignoring connection error")
+        log.warning("Raising cancelled error")
         raise asyncio.CancelledError()  # if we got here, we are shutting down
 
     def _update_remote_height(self, header_args):

lbry/wallet/rpc/session.py

@@ -115,6 +115,7 @@ class SessionBase(asyncio.Protocol):
         try:
             await asyncio.wait_for(self._can_send.wait(), secs)
         except asyncio.TimeoutError:
+            self.logger.warning("abort connection after limited wait (%s)", secs)
             self.abort()
             raise asyncio.TimeoutError(f'task timed out after {secs}s')
 
@@ -131,6 +132,7 @@ class SessionBase(asyncio.Protocol):
             self.transport.write(framed_message)
 
     def _bump_errors(self):
+        self.logger.warning("bump errors %i", self.errors)
         self.errors += 1
         if self.errors >= self.max_errors:
             # Don't await self.close() because that is self-cancelling
@@ -181,6 +183,7 @@ class SessionBase(asyncio.Protocol):
         """Called by asyncio when the connection closes.
 
         Tear down things done in connection_made."""
+        self.logger.error("connection lost to %s - %s", self.peer_address_str(), exc)
         self._address = None
         self.transport = None
         self._task_group.cancel()
@@ -220,12 +223,14 @@ class SessionBase(asyncio.Protocol):
 
     def abort(self):
         """Forcefully close the connection."""
+        self.logger.warning("abort connection")
         if self.transport:
             self.transport.abort()
 
     # TODO: replace with synchronous_close
     async def close(self, *, force_after=30):
         """Close the connection and return when closed."""
+        self.logger.warning("close connection")
         self._close()
         if self._pm_task:
             with suppress(CancelledError):
@@ -234,6 +239,7 @@ class SessionBase(asyncio.Protocol):
                 await self._pm_task
 
     def synchronous_close(self):
+        self.logger.warning("synchronous close")
         self._close()
         if self._pm_task and not self._pm_task.done():
             self._pm_task.cancel()
@@ -394,7 +400,7 @@ class RPCSession(SessionBase):
             try:
                 requests = self.connection.receive_message(message)
             except ProtocolError as e:
-                self.logger.debug(f'{e}')
+                self.logger.warning(f'protocol error {e}')
                 if e.error_message:
                     await self._send_message(e.error_message)
                 if e.code == JSONRPC.PARSE_ERROR: