lnworker: nicer logs/error msgs for payment failure

try to decode onion error and log it in human-readable form

electrum/lnmsg.py

@@ -7,7 +7,11 @@ from collections import OrderedDict
 from .lnutil import OnionFailureCodeMetaFlag
 
 
-class MalformedMsg(Exception): pass
+class FailedToParseMsg(Exception): pass
+
+class MalformedMsg(FailedToParseMsg): pass
+class UnknownMsgType(FailedToParseMsg): pass
+
 class UnknownMsgFieldType(MalformedMsg): pass
 class UnexpectedEndOfStream(MalformedMsg): pass
 class FieldEncodingNotMinimal(MalformedMsg): pass
@@ -465,13 +469,17 @@ class LNSerializer:
         Decode Lightning message by reading the first
         two bytes to determine message type.
 
-        Returns message type string and parsed message contents dict
+        Returns message type string and parsed message contents dict,
+        or raises FailedToParseMsg.
         """
         #print(f"decode_msg >>> {data.hex()}")
         assert len(data) >= 2
         msg_type_bytes = data[:2]
         msg_type_int = int.from_bytes(msg_type_bytes, byteorder="big", signed=False)
-        scheme = self.msg_scheme_from_type[msg_type_bytes]
+        try:
+            scheme = self.msg_scheme_from_type[msg_type_bytes]
+        except KeyError:
+            raise UnknownMsgType(f"msg_type={msg_type_int}")  # TODO even/odd type?
         assert scheme[0][2] == msg_type_int
         msg_type_name = scheme[0][1]
         parsed = {}

electrum/lnonion.py

@@ -25,7 +25,7 @@
 
 import io
 import hashlib
-from typing import Sequence, List, Tuple, NamedTuple, TYPE_CHECKING
+from typing import Sequence, List, Tuple, NamedTuple, TYPE_CHECKING, Dict, Any, Optional
 from enum import IntEnum, IntFlag
 
 from . import ecc
@@ -33,7 +33,7 @@ from .crypto import sha256, hmac_oneshot, chacha20_encrypt
 from .util import bh2u, profiler, xor_bytes, bfh
 from .lnutil import (get_ecdh, PaymentFailure, NUM_MAX_HOPS_IN_PAYMENT_PATH,
                      NUM_MAX_EDGES_IN_PAYMENT_PATH, ShortChannelID, OnionFailureCodeMetaFlag)
-from .lnmsg import OnionWireSerializer, read_bigsize_int, write_bigsize_int
+from .lnmsg import OnionWireSerializer, read_bigsize_int, write_bigsize_int, UnknownMsgType
 
 if TYPE_CHECKING:
     from .lnrouter import LNPaymentRoute
@@ -431,7 +431,7 @@ class OnionRoutingFailure(Exception):
         try:
             failure_code = OnionFailureCode(failure_code)
         except ValueError:
-            pass  # uknown failure code
+            pass  # unknown failure code
         failure_data = failure_msg[2:]
         return OnionRoutingFailure(failure_code, failure_data)
 
@@ -440,6 +440,13 @@ class OnionRoutingFailure(Exception):
             return str(self.code.name)
         return f"Unknown error ({self.code!r})"
 
+    def decode_data(self) -> Optional[Dict[str, Any]]:
+        try:
+            message_type, payload = OnionWireSerializer.decode_msg(self.to_bytes())
+        except UnknownMsgType:
+            payload = None
+        return payload
+
 
 def construct_onion_error(
         reason: OnionRoutingFailure,

electrum/lnutil.py

@@ -30,7 +30,7 @@ from .transaction import BCDataStream
 if TYPE_CHECKING:
     from .lnchannel import Channel, AbstractChannel
     from .lnrouter import LNPaymentRoute
-    from .lnonion import OnionRoutingFailureMessage
+    from .lnonion import OnionRoutingFailure
 
 
 # defined in BOLT-03:
@@ -263,7 +263,7 @@ class HtlcLog(NamedTuple):
     route: Optional['LNPaymentRoute'] = None
     preimage: Optional[bytes] = None
     error_bytes: Optional[bytes] = None
-    failure_msg: Optional['OnionRoutingFailureMessage'] = None
+    failure_msg: Optional['OnionRoutingFailure'] = None
     sender_idx: Optional[int] = None
 
     def formatted_tuple(self):

electrum/lnworker.py

@@ -65,7 +65,7 @@ from .lnutil import (Outpoint, LNPeerAddr,
 from .lnutil import ln_dummy_address, ln_compare_features, IncompatibleLightningFeatures
 from .lnrouter import TrampolineEdge
 from .transaction import PartialTxOutput, PartialTransaction, PartialTxInput
-from .lnonion import OnionFailureCode, process_onion_packet, OnionPacket, OnionRoutingFailure
+from .lnonion import OnionFailureCode, OnionRoutingFailure
 from .lnmsg import decode_msg
 from .i18n import _
 from .lnrouter import (RouteEdge, LNPaymentRoute, LNPaymentPath, is_route_sane_to_use,
@@ -1115,7 +1115,7 @@ class LNWallet(LNWorker):
                 full_path=full_path)
             success = True
         except PaymentFailure as e:
-            self.logger.exception('')
+            self.logger.info(f'payment failure: {e!r}')
             success = False
             reason = str(e)
         if success:
@@ -1207,7 +1207,8 @@ class LNWallet(LNWorker):
             sender_idx = htlc_log.sender_idx
             failure_msg = htlc_log.failure_msg
             code, data = failure_msg.code, failure_msg.data
-            self.logger.info(f"UPDATE_FAIL_HTLC {repr(code)} {data}")
+            self.logger.info(f"UPDATE_FAIL_HTLC. code={repr(code)}. "
+                             f"decoded_data={failure_msg.decode_data()}. data={data.hex()}")
             self.logger.info(f"error reported by {bh2u(route[sender_idx].node_id)}")
             if code == OnionFailureCode.MPP_TIMEOUT:
                 raise PaymentFailure(failure_msg.code_name())
@@ -1222,7 +1223,8 @@ class LNWallet(LNWorker):
                 else:
                     raise PaymentFailure(failure_msg.code_name())
             else:
-                self.handle_error_code_from_failed_htlc(route, sender_idx, failure_msg, code, data)
+                self.handle_error_code_from_failed_htlc(
+                    route=route, sender_idx=sender_idx, failure_msg=failure_msg)
 
     async def pay_to_route(
             self, *,
@@ -1263,8 +1265,13 @@ class LNWallet(LNWorker):
             self.sent_buckets[payment_secret] = amount_sent, amount_failed
         util.trigger_callback('htlc_added', chan, htlc, SENT)
 
-
+    def handle_error_code_from_failed_htlc(
-    def handle_error_code_from_failed_htlc(self, route, sender_idx, failure_msg, code, data):
+            self,
+            *,
+            route: LNPaymentRoute,
+            sender_idx: int,
+            failure_msg: OnionRoutingFailure) -> None:
+        code, data = failure_msg.code, failure_msg.data
         # handle some specific error codes
         failure_codes = {
             OnionFailureCode.TEMPORARY_CHANNEL_FAILURE: 0,
@@ -1299,7 +1306,7 @@ class LNWallet(LNWorker):
             try:
                 short_chan_id = route[sender_idx + 1].short_channel_id
             except IndexError:
-                raise PaymentFailure('payment destination reported error')
+                raise PaymentFailure(f'payment destination reported error: {failure_msg.code_name()}') from None
             # TODO: for MPP we need to save the amount for which
             # we saw temporary channel failure
             self.logger.info(f'blacklisting channel {short_chan_id}')

electrum/tests/test_lnmsg.py

@@ -3,7 +3,9 @@ import io
 from electrum.lnmsg import (read_bigsize_int, write_bigsize_int, FieldEncodingNotMinimal,
                             UnexpectedEndOfStream, LNSerializer, UnknownMandatoryTLVRecordType,
                             MalformedMsg, MsgTrailingGarbage, MsgInvalidFieldOrder, encode_msg,
-                            decode_msg, UnexpectedFieldSizeForEncoder)
+                            decode_msg, UnexpectedFieldSizeForEncoder, OnionWireSerializer,
+                            UnknownMsgType)
+from electrum.lnonion import OnionRoutingFailure
 from electrum.util import bfh
 from electrum.lnutil import ShortChannelID, LnFeatures
 from electrum import constants
@@ -383,3 +385,16 @@ class TestLNMsg(TestCaseForTestnet):
                                   {'chains': b'CI\x7f\xd7\xf8&\x95q\x08\xf4\xa3\x0f\xd9\xce\xc3\xae\xbay\x97 \x84\xe9\x0e\xad\x01\xea3\t\x00\x00\x00\x00'}
                           }}),
                          decode_msg(bfh("001000022200000302aaa2012043497fd7f826957108f4a30fd9cec3aeba79972084e90ead01ea330900000000")))
+
+    def test_decode_onion_error(self):
+        orf = OnionRoutingFailure.from_bytes(bfh("400f0000000017d2d8b0001d9458"))
+        self.assertEqual(('incorrect_or_unknown_payment_details', {'htlc_msat': 399694000, 'height': 1938520}),
+                         OnionWireSerializer.decode_msg(orf.to_bytes()))
+        self.assertEqual({'htlc_msat': 399694000, 'height': 1938520},
+                         orf.decode_data())
+
+        orf2 = OnionRoutingFailure(26399, bytes.fromhex("0000000017d2d8b0001d9458"))
+        with self.assertRaises(UnknownMsgType):
+            OnionWireSerializer.decode_msg(orf2.to_bytes())
+        self.assertEqual(None, orf2.decode_data())
+