connext / indra

[LEGACY] Monorepo containing everything related to the core Connext protocols and network.
MIT License
84 stars 38 forks source link

Client fails to receive a payment and does not recover #871

Closed Jannis closed 4 years ago

Jannis commented 4 years ago

Describe the bug

I have the following system set up (all using Connext 4.2.0):

After a few payments back and forth, client C logged this:

error: [NodeApiClient] Failed to execute callback while lock is held: Error: No multisig address exists for the given appInstanceId
    at Store.getMultisigAddressFromAppInstance (/opt/-/node_modules/@connext/cf-core/dist/src/store.js:53:15)
(node:1) UnhandledPromiseRejectionWarning: Error: No multisig address exists for the given appInstanceId
    at Store.getMultisigAddressFromAppInstance (/opt/-/node_modules/@connext/cf-core/dist/src/store.js:53:15)

It still continued to receive payments from A and was able to send payments back to A. But it no longer received anything from B.

After a restart, client C logged the following when trying to run connext.connect(). Additional restarts don't help, it keeps logging the same (except with a different receovered 0x... address every time):

(node:1) UnhandledPromiseRejectionWarning: Error: Validating a signature with expected signer 0xBC692b38cBbBd891Fe8Cd2E256285E0785431c94 but recovered 0x5cF1c11753995a839c23E2c046B418B7D95985b2 for commitment hash 0xacc6811e57a47fd23dd275765f88b8e6f71c3a3a68739ed122a9d3c2c32b236b.
    at Object.assertIsValidSignature (/opt/-/node_modules/@connext/cf-core/dist/src/protocol/utils/signature-validator.js:13:15)
    at /opt/-/node_modules/@connext/cf-core/dist/src/protocol/propose.js:116:35
    at Generator.next (<anonymous>)
    at resume (/opt/-/node_modules/@connext/cf-core/dist/src/protocol/propose.js:8:44)
    at /opt/-/node_modules/@connext/cf-core/dist/src/protocol/propose.js:7:121
    at new Promise (<anonymous>)
    at Object.i.(anonymous function) [as next] (/opt/-/node_modules/@connext/cf-core/dist/src/protocol/propose.js:7:63)
    at ProtocolRunner.runProtocol (/opt/-/node_modules/@connext/cf-core/dist/src/machine/protocol-runner.js:75:39)
    at ProtocolRunner.runProtocolWithMessage (/opt/-/node_modules/@connext/cf-core/dist/src/machine/protocol-runner.js:42:21)
    at handleReceivedProtocolMessage (/opt/-/node_modules/@connext/cf-core/dist/src/message-handling/handle-protocol-message.js:26:63)
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 2)
(node:1) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

error: [ResolveConditionController] Failed to resolve linked transfer 0x508993e04ed4126f51461f7d3828d99ba3f36cc1f1cdea4801704adea029e805: Error: Failed to send message: Request timed out.
    at NodeApiClient.<anonymous> (/opt/-/node_modules/@connext/client/dist/node.js:278:23)
    at Generator.throw (<anonymous>)
    at rejected (/opt/-/node_modules/@connext/client/dist/node.js:6:65)
error: [ConnextConnect] Could not reclaim pending async transfers: Error: Failed to send message: Request timed out.... will attempt again on next connection

After the timeout, client C manages to continue, but when it then tries to deposit something into the state channel, that times out as well:

error: [DepositController] Error proposing app: Error: App proposal took longer than 90 seconds
    at Timeout.setTimeout [as _onTimeout] (/opt/-/node_modules/@connext/client/dist/lib/utils.js:50:90)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10)

Your Environment

Jannis commented 4 years ago

Node logs (excerpt):

[Nest] 1   - 02/27/2020, 6:59:57 PM   [LockService] Failed to execute callback while lock is held: IO_SEND_AND_WAIT timed out after 90s waiting for counterparty reply in propose +238ms
Error: IO_SEND_AND_WAIT timed out after 90s waiting for counterparty reply in propose
    at eval (webpack:///./node_modules/@connext/cf-core/dist/src/node.js?:107:23)
    at async ProtocolRunner.runProtocol (webpack:///./node_modules/@connext/cf-core/dist/src/machine/protocol-runner.js?:80:33)
    at async ProposeInstallController.executeMethodImplementation (webpack:///./node_modules/@connext/cf-core/dist/src/methods/app-instance/propose-install/controller.js?:52:9)
[Nest] 1   - 02/27/2020, 6:59:57 PM   [LockService] Releasing lock for 0xC7c4175D538A7300f2cAc20AA613257C4F072Ab3 with secret b91e4102da31410fc2e71b7e8dfe0617
[Nest] 1   - 02/27/2020, 6:59:57 PM   [LockService] Failed to release the lock due to expired ttl: LockError: Unable to fully release the lock on resource "0xC7c4175D538A7300f2cAc20AA613257C4F072Ab3".;
[Nest] 1   - 02/27/2020, 6:59:57 PM   [LockService] No return value found from task with lockName: 0xC7c4175D538A7300f2cAc20AA613257C4F072Ab3, and failed to release due to expired ttl: Unable to fully release the lock on resource "0xC7c4175D538A7300f2cAc20AA613257C4F072Ab3". +1ms
LockError: Unable to fully release the lock on resource "0xC7c4175D538A7300f2cAc20AA613257C4F072Ab3".
    at loop (/root/node_modules/redlock/redlock.js:265:18)
    at tryCatcher (/root/node_modules/standard-as-callback/built/utils.js:11:23)
    at /root/node_modules/standard-as-callback/built/index.js:19:49
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (internal/process/task_queues.js:93:5)
debug: [NatsMessagingService] Publishing _INBOX.U56JYA7BUUUQI5FCZ9HQYL.U56JYA7BUUUQI5FCZ9HQTP: {"err":"LockError: Unable to fully release the lock on resource \"0xC7c4175D538A7300f2cAc20AA613257C4F072Ab3\".","message":"Error during processor function: "}
[Nest] 1   - 02/27/2020, 6:59:57 PM   [MessagingProvider] Error processing message transfer.resolve-linked.xpub6EVQvyzRp3zNKiQwSNdc7yLCqoqXqAM9jYv724yGmLfDbUn3AAqPaunpxg1cJQgTbm3TCBVVLfvh4gkkAu6tA9uYUkWPJ2JWnPiU2RnBw7v: Unable to fully release the lock on resource "0xC7c4175D538A7300f2cAc20AA613257C4F072Ab3". +5ms
LockError: Unable to fully release the lock on resource "0xC7c4175D538A7300f2cAc20AA613257C4F072Ab3".
    at loop (/root/node_modules/redlock/redlock.js:265:18)
    at tryCatcher (/root/node_modules/standard-as-callback/built/utils.js:11:23)
    at /root/node_modules/standard-as-callback/built/index.js:19:49
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (internal/process/task_queues.js:93:5)