Bug: unable to parse payment with large (>2^63-1) channel ID

[danielbroll]

de.cotto.lndmanagej.payments.Payments#getPaymentsAfter tries to fetch payments every 10 seconds.

2022-04-28 13:50:55,417 ERROR org.springframework.scheduling.support.TaskUtils$LoggingErrorHandler: Unexpected error occurred in scheduled taskjava.lang.IllegalArgumentException: Illegal channel ID -41198662732003782 at de.cotto.lndmanagej.model.ChannelId.fromShortChannelId(ChannelId.java:18) ~[model-plain.jar!/:na] at de.cotto.lndmanagej.grpc.GrpcPayments.toHop(GrpcPayments.java:90) ~[grpc-adapter-plain.jar!/:na] at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) ~[na:na] at java.base/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:179) ~[na:na] at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1625) ~[na:na] at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509) ~[na:na] at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499) ~[na:na] at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:575) ~[na:na] at java.base/java.util.stream.AbstractPipeline.evaluateToArrayNode(AbstractPipeline.java:260) ~[na:na] at java.base/java.util.stream.ReferencePipeline.toArray(ReferencePipeline.java:616) ~[na:na] at java.base/java.util.stream.ReferencePipeline.toArray(ReferencePipeline.java:622) ~[na:na] at java.base/java.util.stream.ReferencePipeline.toList(ReferencePipeline.java:627) ~[na:na] at de.cotto.lndmanagej.grpc.GrpcPayments.toPaymentRoute(GrpcPayments.java:84) ~[grpc-adapter-plain.jar!/:na] at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) ~[na:na] at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1625) ~[na:na] at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509) ~[na:na] at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499) ~[na:na] at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:575) ~[na:na] at java.base/java.util.stream.AbstractPipeline.evaluateToArrayNode(AbstractPipeline.java:260) ~[na:na] at java.base/java.util.stream.ReferencePipeline.toArray(ReferencePipeline.java:616) ~[na:na] at java.base/java.util.stream.ReferencePipeline.toArray(ReferencePipeline.java:622) ~[na:na] at java.base/java.util.stream.ReferencePipeline.toList(ReferencePipeline.java:627) ~[na:na] at de.cotto.lndmanagej.grpc.GrpcPayments.toPayment(GrpcPayments.java:76) ~[grpc-adapter-plain.jar!/:na] at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) ~[na:na] at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1625) ~[na:na] at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509) ~[na:na] at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499) ~[na:na] at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:575) ~[na:na] at java.base/java.util.stream.AbstractPipeline.evaluateToArrayNode(AbstractPipeline.java:260) ~[na:na] at java.base/java.util.stream.ReferencePipeline.toArray(ReferencePipeline.java:616) ~[na:na] at java.base/java.util.stream.ReferencePipeline.toArray(ReferencePipeline.java:622) ~[na:na] at java.base/java.util.stream.ReferencePipeline.toList(ReferencePipeline.java:627) ~[na:na] at de.cotto.lndmanagej.grpc.GrpcPayments.getPaymentsAfter(GrpcPayments.java:43) ~[grpc-adapter-plain.jar!/:na] at de.cotto.lndmanagej.payments.Payments.refresh(Payments.java:25) ~[payments-plain.jar!/:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[na:na] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na] at java.base/java.lang.reflect.Method.invoke(Method.java:568) ~[na:na] at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84) ~[spring-context-5.3.19.jar!/:5.3.19] at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-5.3.19.jar!/:5.3.19] at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[na:na] at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[na:na] at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[na:na] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[na:na] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[na:na] at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]

The exception is thrown because channel ids should not be smaller than NOT_BEFORE = 430_103_660_018_532_352L; // January 1st 2016

The payment that leads to the error is (directly retrieved via lncli)

{
            "payment_hash": "xxx",
            "value": "100",
            "creation_date": "1607550448",
            "fee": "2",
            "payment_preimage": "xxx",
            "value_sat": "100",
            "value_msat": "100000",
            "payment_request": "xxx",
            "status": "SUCCEEDED",
            "fee_sat": "2",
            "fee_msat": "2010",
            "creation_time_ns": "1607550448942463612",
            "htlcs": [
                {
                    "attempt_id": "1000",
                    "status": "SUCCEEDED",
                    "route": {
                        "total_time_lock": 660879,
                        "total_fees": "2",
                        "total_amt": "102",
                        "hops": [
                            {
                                "chan_id": "726318689695105025",
                                "chan_capacity": "102",
                                "amt_to_forward": "101",
                                "fee": "1",
                                "expiry": 660839,
                                "amt_to_forward_msat": "101010",
                                "fee_msat": "1000",
                                "pub_key": "0242a4ae0c5bef18048fbecf995094b74bfb0f7391418d71ed394784373f41e4f3",
                                "tlv_payload": true,
                                "mpp_record": null,
                                "amp_record": null,
                                "custom_records": {
                                }
                            },
                            {
                                "chan_id": "668973660760834049",
                                "chan_capacity": "101",
                                "amt_to_forward": "100",
                                "fee": "1",
                                "expiry": 660695,
                                "amt_to_forward_msat": "100000",
                                "fee_msat": "1010",
                                "pub_key": "03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f",
                                "tlv_payload": true,
                                "mpp_record": null,
                                "amp_record": null,
                                "custom_records": {
                                }
                            },
                            {
                                "chan_id": "18405545410977547834",
                                "chan_capacity": "100",
                                "amt_to_forward": "100",
                                "fee": "0",
                                "expiry": 660695,
                                "amt_to_forward_msat": "100000",
                                "fee_msat": "0",
                                "pub_key": "02fd382c0bdca952e8fb221c153a58ab3d90a4daf1ebef55ac716da208d6a3463a",
                                "tlv_payload": true,
                                "mpp_record": {
                                    "payment_addr": "807e987dc08c14be17d70c0b4311101bc74d784747f4ddec10f1b8aedccce672",
                                    "total_amt_msat": "100000"
                                },
                                "amp_record": null,
                                "custom_records": {
                                }
                            }
                        ],
                        "total_fees_msat": "2010",
                        "total_amt_msat": "102010"
                    },
                    "attempt_time_ns": "1607550449033089244",
                    "resolve_time_ns": "1607550451943029784",
                    "failure": null,
                    "preimage": "xxx"
                }
            ],
            "payment_index": "4",
            "failure_reason": "FAILURE_REASON_NONE"
        },

The third payment hop channel id leads to the exception.

"chan_id": "726318689695105025",
"chan_id": "668973660760834049",
"chan_id": "18405545410977547834", <- this one.

The timestamp of the payment looks weird as well. creation_time_ns "1607550448942463612" converts to UTC +52911-03-31T23:22:22.463Z

Ignoring payment hops with such a "weird" channel Id once solved the problem, since payments IndexOffset is updated and from this point only new payments are fetched.

Not sure if there is anything to do here since my LND node is already about three years old and was running many different versions.

[C-Otto]

Garbage in, garbage out. The channel ID is invalid (too large, in this case). I don't expect lnd-manageJ to work on corrupted data. Ignoring stuff can be more harmful than just alerting the user to the error.

[C-Otto]

The timestamp looks fine to me, though. https://www.unixtimestamp.com/

[danielbroll]

Yes, rejecting invalid data is the way to go. I was more thinking about a mechanism where the user specifies from which date or payment index onwards he wants to fetch payments. (or other data) Because the stacktrace was repeating every 10 seconds in my logs and I was a bit stuck. This might be worth considering if other users run into the same problem.

For now adding a dummy payment with a high enough payment_index via SQL could be the easiest solution without a manual code change.

[C-Otto]

I disagree. The issue isn't in lnd-manageJ, as you're feeding it data that's garbage. You need to fix your lnd instance to provide useful data. This isn't something I can do within lnd-manageJ.

[danielbroll]

You were right, this was to way to go. Luckily only 6 payments were affected and I was able to clean them up via lncli deletepayments --payment_hash ...

Thank you for pointing me in the right direction!

The only thing left to consider is if the logging could be improved. The initial stacktrace does not help identifying which payments are affected.

[dannydeezy]

I'm hitting this issue as well. @danielbroll how did you find all the affected payments? and any idea why the payments are like this?

[dannydeezy]

I'm hitting this issue as well. @danielbroll how did you find all the affected payments? and any idea why the payments are like this?

haha ok, so I just did lncli listpayments and then searched for "chan_id": "1 and found a payment with an invalid channel ID 15950331660920403271 (note this is different than the error message I received, which was something like Illegal channel ID -41198662732003782, i.e. a negative number presumably due to reading the number as a signed vs unsigned int or something)

anyway, using that hack I found the bad payment hash, and did lncli deletepayments --payment_hash <bad one> and now we're good to go.

[C-Otto]

I just added a commit that prints an error message including the payment hash, I hope that helps.

[dannydeezy]

I just added a commit that prints an error message including the payment hash, I hope that helps.

epic, thanks!

[C-Otto]

I just hit the same issue and finally understand what's going on. In my case I sent a payment via a channel created with the Phoenix wallet. This channel doesn't really exist in the blockchain, and the corresponding channel ID doesn't make a lot of sense. This is fine, as ACINQ still knows how to route the payment to its destination.

However, the channel ID is larger than 2^63-1, which is the maximum value allowed for Java's long type. The actual value can be represented with 64 bits, though. As Java does not have something like uint64, stuffing a number larger than 2^63-1 but smaller than 2^64 into long results in Java interpreting the number as being negative. This triggers a health check (channel IDs must be positive) in lnd-manageJ, even though the (64bit, positive) channel ID should be considered valid.