Transfer unsuccessful message even though node shows payment as incoming

[taleldayekh]

Steps to Reproduce

1. Send a direct transfer

Expected Result

• Expecting free PFS to be selected and the final modal to show a progress spinner and checkmark when done

Actual Result

• Free PFS is selected but when clicking transfer the modal displays a Token transfer unsuccessful message right away even though the receiving node is displaying a payment incoming notification.

Additional Infos (Optional)

[andrevmatos]

This error doesn't happen on a direct transfer, it was actually a mediated transfer. You got a fee=0 from PFS, even though it wasn't, sent a mediated transfer without adding any fees, then got a SecretRequest with an amount smaller than you expected to reach target, and therefore rejected revealing the secret, and transfer failed; the transfer will eventually expire.
So, the root cause of the error is PFS misinforming the fee to us. We saw that this happen when PFS, for any reason, doesn't have our side of the channel's capacity. I'm working on the fix, which consist of ensuring we send a pfsCapacityUpdate at least once for each channel, and on deposit. We'll do it on the beginning of the session. The user may be bothered by one signature prompt for each channel (if not using subkey) a couple of seconds of debouncing after connecting, but this is the safest approach for now.

[nephix]

I can still reproduce this with freshly set up accounts and the fix from #1121
Prior to the mediated transfer, I did a direct transfer to the mediator which worked. Similar to #914 and #397

Logs: raiden_2020-03-03T12_22_59.202Z.log

Application State

{
  "address": "0x91D6d1a8eC95c7AbAE47F103AFDe2D3D9472d924",
  "version": 1,
  "chainId": 5,
  "registry": "0x9b0c8C8C75904CEf5B7a8dbF59c3459Ea85c6526",
  "blockNumber": 2280455,
  "config": {
    "pfsSafetyMargin": 1.1,
    "pfs": "https://pfs.raidentransport.test001.env.raiden.network",
    "matrixServer": "https://raidentransport.test001.env.raiden.network"
  },
  "channels": {
    "0x2001E8851d33CA476e209e37ED8db1BB9E72334F": {
      "0x9c77700E645268A62a7DCCDe7dAbF635d01F1B22": {
        "state": "open",
        "own": {
          "deposit": "9990000000000000",
          "locks": [
            {
              "amount": "11100000000",
              "expiration": "2280552",
              "secrethash": "0xc70d0175d8d3d7ed25778fe7b1340fb95969d81caa5b9aa93d1d949c3c62ff74"
            }
          ],
          "balanceProof": {
            "chainId": "5",
            "tokenNetworkAddress": "0x2001E8851d33CA476e209e37ED8db1BB9E72334F",
            "channelId": "19",
            "nonce": "5",
            "transferredAmount": "8000770000000000",
            "lockedAmount": "11100000000",
            "locksroot": "0xf9c4d6d5ec154c2edfb350fe32ec75e4dc03df3ee2c85c6fe03b4b29930fbab2",
            "messageHash": "0xbb9423543bf2d7665405e08ea98e08b0f6ba1bd3ad14c6bd31a1236797ca8a67",
            "signature": "0x6d9b1633d837830038c1be0e1443f2f3f3e9be601d7419f96866f6f6220f250606cec5de7481ec7de63b3b055305923c34f0e03f4f9774e7f27a7aec2e3554351b",
            "sender": "0x91D6d1a8eC95c7AbAE47F103AFDe2D3D9472d924"
          }
        },
        "partner": {
          "deposit": "0"
        },
        "id": 19,
        "settleTimeout": 500,
        "isFirstParticipant": true,
        "openBlock": 2280406
      }
    }
  },
  "tokens": {
    "0xE2b702eD684bEb02850ac604278f078A4ce8b6E6": "0x2001E8851d33CA476e209e37ED8db1BB9E72334F"
  },
  "transport": {
    "matrix": {
      "server": "https://raidentransport.test001.env.raiden.network",
      "setup": {
        "userId": "@0x91d6d1a8ec95c7abae47f103afde2d3d9472d924:raidentransport.test001.env.raiden.network",
        "accessToken": "MDAzOGxvY2F0aW9uIHJhaWRlbnRyYW5zcG9ydC50ZXN0MDAxLmVudi5yYWlkZW4ubmV0d29yawowMDEzaWRlbnRpZmllciBrZXkKMDAxMGNpZCBnZW4gPSAxCjAwNjljaWQgdXNlcl9pZCA9IEAweDkxZDZkMWE4ZWM5NWM3YWJhZTQ3ZjEwM2FmZGUyZDNkOTQ3MmQ5MjQ6cmFpZGVudHJhbnNwb3J0LnRlc3QwMDEuZW52LnJhaWRlbi5uZXR3b3JrCjAwMTZjaWQgdHlwZSA9IGFjY2VzcwowMDIxY2lkIG5vbmNlID0geW5IOnhpejs4K34mR004OAowMDJmc2lnbmF0dXJlIFmzo9rjIrH8JG-3_9GUVC7KIp6IOLCxiJEqehr43GWnCg",
        "deviceId": "KUWYEIXWJL",
        "displayName": "0xef2f0987f9ee98cdcf8b134417d0d8b5270ed95c50d44d7e78fddf29f3fbee04470036b04325c62ef4ce9fde647fc318a92095e65995132bd695534aaf77fc951c"
      },
      "rooms": {
        "0x9c77700E645268A62a7DCCDe7dAbF635d01F1B22": [
          "!SYYOavDpXlojUPskrc:raidentransport.test001.env.raiden.network"
        ],
        "0xb2a47e3b20738d40539d29eDeAe5946f0F35B9c2": [
          "!LelWdRRCfZxFYbkHqb:raidentransport.test001.env.raiden.network"
        ]
      }
    }
  },
  "sent": {
    "0xff58fa03517677bcca412ec968104e84a2991b170a4fb5bdffc03f4290a90d76": {
      "transfer": [
        1583237670870,
        {
          "type": "LockedTransfer",
          "message_identifier": "1583237665495",
          "chain_id": "5",
          "token_network_address": "0x2001E8851d33CA476e209e37ED8db1BB9E72334F",
          "channel_identifier": "19",
          "nonce": "1",
          "transferred_amount": "0",
          "locked_amount": "770000000000",
          "locksroot": "0xe1a5d7a4cc308b6f37035cd2b87f1812e458a4b6f112395480e8ffad849b40d8",
          "payment_identifier": "13070197311764359472",
          "token": "0xE2b702eD684bEb02850ac604278f078A4ce8b6E6",
          "recipient": "0x9c77700E645268A62a7DCCDe7dAbF635d01F1B22",
          "lock": {
            "amount": "770000000000",
            "expiration": "2280521",
            "secrethash": "0xff58fa03517677bcca412ec968104e84a2991b170a4fb5bdffc03f4290a90d76"
          },
          "target": "0x9c77700E645268A62a7DCCDe7dAbF635d01F1B22",
          "initiator": "0x91D6d1a8eC95c7AbAE47F103AFDe2D3D9472d924",
          "metadata": {
            "routes": [
              {
                "route": [
                  "0x9c77700E645268A62a7DCCDe7dAbF635d01F1B22"
                ]
              }
            ]
          },
          "signature": "0x17c52ce5692459605479ebd747939c39621032c338a38e1f2a7172c14b29b3b90326d5a4f73a0ee7c08452f3bd8572d1fbcf331930f81572144a6e4a5219e62a1c"
        }
      ],
      "fee": "0",
      "secret": [
        1583237670885,
        {
          "value": "0xfaf50dc2bb0e61422562604196f5e5d3ed0e97a4e8128d7cea4d34d17e5b6ccc",
          "registerBlock": 0
        }
      ],
      "transferProcessed": [
        1583237672206,
        {
          "message_identifier": "1583237665495",
          "signature": "0xa82732768b87daa2d4d85ae7873e1cdb385f49b9bb414f80797fc7888e1bb808442258b625efe36c3f629afe58e8babfb7404cee5f3cfb2b2426e142981a760a1c",
          "type": "Processed"
        }
      ],
      "secretRequest": [
        1583237677301,
        {
          "message_identifier": "12371625795886963175",
          "secrethash": "0xff58fa03517677bcca412ec968104e84a2991b170a4fb5bdffc03f4290a90d76",
          "signature": "0x64bfd692910522009280daa3bda20ef14cb98613c29e3f88b7998933dbffab3d25d4a88a4f406cd36c8ec4fb92c8a14c3757a33d809a1917dcbd8aadfd713f2a1c",
          "expiration": "2280521",
          "payment_identifier": "13070197311764359472",
          "amount": "770000000000",
          "type": "SecretRequest"
        }
      ],
      "secretReveal": [
        1583237677989,
        {
          "type": "RevealSecret",
          "message_identifier": "1583237672258",
          "secret": "0xfaf50dc2bb0e61422562604196f5e5d3ed0e97a4e8128d7cea4d34d17e5b6ccc",
          "signature": "0x5be666074501aea353ba496492ef44659d5590dbe8aedaf2b287e324acb7580f7d6fd862c0f61e8a84c583b7076a75f509cda04fe63bc8b5757cac5bed4f612b1b"
        }
      ],
      "unlock": [
        1583237681387,
        {
          "type": "Unlock",
          "message_identifier": "1583237678767",
          "chain_id": "5",
          "token_network_address": "0x2001E8851d33CA476e209e37ED8db1BB9E72334F",
          "channel_identifier": "19",
          "nonce": "2",
          "transferred_amount": "770000000000",
          "locked_amount": "0",
          "locksroot": "0xc5d2460186f7233c927e7db2dcc703c0e500b653ca82273b7bfad8045d85a470",
          "payment_identifier": "13070197311764359472",
          "secret": "0xfaf50dc2bb0e61422562604196f5e5d3ed0e97a4e8128d7cea4d34d17e5b6ccc",
          "signature": "0xe0704387383911d4c799828c54ece27128abb1ba0cedca7c7195b48303a022d054c690e18a40ee9fe672bbbbc1c41d9795a8d6fd18db0ecfddd445ef9b92c8ac1c"
        }
      ],
      "unlockProcessed": [
        1583237682391,
        {
          "message_identifier": "1583237678767",
          "signature": "0x337b9646becb5fc8b8a67ea57105daa000910185384bc9d1039c1369d1254ec20144dd56c18fb9f98cb1b904faec12ce29e2a53acf4f319c3f2b96ad114865e71c",
          "type": "Processed"
        }
      ]
    },
    "0x09ed57531519a3c9f5e0474f0366a1e66f02e45ef641b73e894cab52cbfa7a1d": {
      "transfer": [
        1583237707867,
        {
          "type": "LockedTransfer",
          "message_identifier": "1583237702439",
          "chain_id": "5",
          "token_network_address": "0x2001E8851d33CA476e209e37ED8db1BB9E72334F",
          "channel_identifier": "19",
          "nonce": "3",
          "transferred_amount": "770000000000",
          "locked_amount": "8000000000000000",
          "locksroot": "0x18b17bcecdb39b3f5df82f50681f4698aea0b9050157001c0677a1587153a99d",
          "payment_identifier": "8762876887915670026",
          "token": "0xE2b702eD684bEb02850ac604278f078A4ce8b6E6",
          "recipient": "0x9c77700E645268A62a7DCCDe7dAbF635d01F1B22",
          "lock": {
            "amount": "8000000000000000",
            "expiration": "2280524",
            "secrethash": "0x09ed57531519a3c9f5e0474f0366a1e66f02e45ef641b73e894cab52cbfa7a1d"
          },
          "target": "0x9c77700E645268A62a7DCCDe7dAbF635d01F1B22",
          "initiator": "0x91D6d1a8eC95c7AbAE47F103AFDe2D3D9472d924",
          "metadata": {
            "routes": [
              {
                "route": [
                  "0x9c77700E645268A62a7DCCDe7dAbF635d01F1B22"
                ]
              }
            ]
          },
          "signature": "0xa1bad16e72be26921400dae33a2f9313d6504d1cdee66cd6e995e47fd4a2a352136b38f4530531fad46f9b708c1ed54c8bc3afed6286623f76c3fc3c01c2bb4e1b"
        }
      ],
      "fee": "0",
      "secret": [
        1583237707893,
        {
          "value": "0xa54befa1b431b8b42e75afcaaf3eea20bd2541a6b97fe711b7059a75fdaad822",
          "registerBlock": 0
        }
      ],
      "transferProcessed": [
        1583237708680,
        {
          "message_identifier": "1583237702439",
          "signature": "0x3d4be9f1ea37c4faeff21cea67cbcf6cd00ed4b798ff4fc1e88e9fb9967251433ac81033cde6370202f6ae4f3e4d0596f0edc39f1d11ea78c357d8d61eb62b3c1b",
          "type": "Processed"
        }
      ],
      "secretRequest": [
        1583237714114,
        {
          "message_identifier": "9633783340710295329",
          "secrethash": "0x09ed57531519a3c9f5e0474f0366a1e66f02e45ef641b73e894cab52cbfa7a1d",
          "signature": "0xc49acda435515dbb37b7d599dd4a3ac5bb0569c4120933977d4e751afbd0d7951360202c0405e36c4d793e4b166284c0df64ef6d7593ab304cfca843511a59e61c",
          "expiration": "2280524",
          "payment_identifier": "8762876887915670026",
          "amount": "8000000000000000",
          "type": "SecretRequest"
        }
      ],
      "secretReveal": [
        1583237714227,
        {
          "type": "RevealSecret",
          "message_identifier": "1583237708705",
          "secret": "0xa54befa1b431b8b42e75afcaaf3eea20bd2541a6b97fe711b7059a75fdaad822",
          "signature": "0x8d63163ef4392fbc3be9d361a8dbe9549a6be326e145f1e3c1e613cb522e0d6946f96c17af37abc114e8f01524f6245ee1480c0387b4b98f0e5f5c692df80ed01c"
        }
      ],
      "unlock": [
        1583237721206,
        {
          "type": "Unlock",
          "message_identifier": "1583237715665",
          "chain_id": "5",
          "token_network_address": "0x2001E8851d33CA476e209e37ED8db1BB9E72334F",
          "channel_identifier": "19",
          "nonce": "4",
          "transferred_amount": "8000770000000000",
          "locked_amount": "0",
          "locksroot": "0xc5d2460186f7233c927e7db2dcc703c0e500b653ca82273b7bfad8045d85a470",
          "payment_identifier": "8762876887915670026",
          "secret": "0xa54befa1b431b8b42e75afcaaf3eea20bd2541a6b97fe711b7059a75fdaad822",
          "signature": "0x1913430651b3fd6c9e87f3fe54f9ac4504d3792beaee08b78545060c57c27c4e4c245db5805606d952b1a0433ddb8c0596671a5bf7fec4d3c41f196d60f2e7721c"
        }
      ],
      "unlockProcessed": [
        1583237722243,
        {
          "message_identifier": "1583237715665",
          "signature": "0x75a2df4ab78c89cab11c596999c7afe9fab8339ecbe9117d3499f3721482f2534edd95a12af3254c7e6e234777f3b0adeafff1098ccf802db189872e37dcf0061b",
          "type": "Processed"
        }
      ]
    },
    "0xc70d0175d8d3d7ed25778fe7b1340fb95969d81caa5b9aa93d1d949c3c62ff74": {
      "transfer": [
        1583238126774,
        {
          "type": "LockedTransfer",
          "message_identifier": "1583238119818",
          "chain_id": "5",
          "token_network_address": "0x2001E8851d33CA476e209e37ED8db1BB9E72334F",
          "channel_identifier": "19",
          "nonce": "5",
          "transferred_amount": "8000770000000000",
          "locked_amount": "11100000000",
          "locksroot": "0xf9c4d6d5ec154c2edfb350fe32ec75e4dc03df3ee2c85c6fe03b4b29930fbab2",
          "payment_identifier": "9183333739826324608",
          "token": "0xE2b702eD684bEb02850ac604278f078A4ce8b6E6",
          "recipient": "0x9c77700E645268A62a7DCCDe7dAbF635d01F1B22",
          "lock": {
            "amount": "11100000000",
            "expiration": "2280552",
            "secrethash": "0xc70d0175d8d3d7ed25778fe7b1340fb95969d81caa5b9aa93d1d949c3c62ff74"
          },
          "target": "0xb2a47e3b20738d40539d29eDeAe5946f0F35B9c2",
          "initiator": "0x91D6d1a8eC95c7AbAE47F103AFDe2D3D9472d924",
          "metadata": {
            "routes": [
              {
                "route": [
                  "0x9c77700E645268A62a7DCCDe7dAbF635d01F1B22",
                  "0xb2a47e3b20738d40539d29eDeAe5946f0F35B9c2"
                ]
              }
            ]
          },
          "signature": "0x6d9b1633d837830038c1be0e1443f2f3f3e9be601d7419f96866f6f6220f250606cec5de7481ec7de63b3b055305923c34f0e03f4f9774e7f27a7aec2e3554351b"
        }
      ],
      "fee": "0",
      "secret": [
        1583238126820,
        {
          "value": "0x70e5806b952ff241004cdfb6f0989f5073bdb62de1590c5c22ef9af6fee88238",
          "registerBlock": 0
        }
      ],
      "transferProcessed": [
        1583238128265,
        {
          "message_identifier": "1583238119818",
          "signature": "0x9786ee49521992a53131144c40a410536485a19f07763ca19f8bb71578f5fd775b67eef69595c695245040c9b8cf45ed312f38da7a080fad03ab32af8bd13a0e1c",
          "type": "Processed"
        }
      ],
      "secretRequest": [
        1583238135048,
        {
          "secrethash": "0xc70d0175d8d3d7ed25778fe7b1340fb95969d81caa5b9aa93d1d949c3c62ff74",
          "signature": "0xb7f2665426c4269dd58d1f8a93994e9002bfcfb0d4d265f294f302e9e8aabd4a77c26f6808336b279d1cff44126df4bb32296d28dc6ac3fe60028aa328e1c55a1b",
          "payment_identifier": "9183333739826324608",
          "message_identifier": "14928040293174807747",
          "expiration": "2280552",
          "amount": "10996826888",
          "type": "SecretRequest"
        }
      ]
    }
  },
  "path": {
    "iou": {
      "0x2001E8851d33CA476e209e37ED8db1BB9E72334F": {
        "0x975bFb356daD12D30FD013bc7Cf5BABdF526Bd31": {
          "sender": "0x91D6d1a8eC95c7AbAE47F103AFDe2D3D9472d924",
          "receiver": "0x975bFb356daD12D30FD013bc7Cf5BABdF526Bd31",
          "chain_id": "5",
          "amount": "100",
          "one_to_n_address": "0xe4C2C47F070152c03a564C2c681C3FbD78234156",
          "expiration_block": "2480452",
          "signature": "0x9d9f4148928a8e85474d1f4e7125b547a650d239add60a30d2b09c3ca9f4cc513e73f2541c5a717b88ef0f5c3879fad2e071dfbe1b880e960e478df34205f5291b"
        }
      }
    }
  },
  "pendingTxs": [

  ]
}

On a second attempt the mediated transfer worked as well. I received non-zero fees from Pathfinding and the mediated transfer was successful: raiden_2020-03-03T12_29_55.561Z.log

Since then I was not able to encounter the same issue

[karlb]

I can look into the python client and PFS side of this. I'm not used to reading the light client logs, which of the payments in the above log is going wrong?
Am I right that you assume that the mediating node acts correctly, but the PFS sends a wrong fee estimation?

[andrevmatos]

@karlb you can grep for channel_?id.*\b0x13\b|channel_?id.*\b19\b on the logs above, it'll show you the messages and transfers sent on this channel;

[karlb]

I've created two tickets which might help with this issue: raiden-network/raiden-services#735 and raiden-network/raiden-services#736.

For an immediate solution, you will probably have to send frequent PFSCapacityUpdates or add a safety margin based on the payment amount (this approach could be improved by raiden-network/raiden-services#569).

[nephix]

Encountered it again: raiden_2020-03-03T17_39_08.184Z.log

Always seems to happen after freshly set up accounts and after the first time I mint/deposit to UDC the SVT in order to pay for a route request

[nephix]

One more time: raiden_2020-03-03T18_25_17.533Z.log

Again with a new wallet and first time SVT mint/UDC deposit. This time I didn't do any prior transfers and went straight from opening channel to mediated transfer. PFS even returned some mediation fees this time

[andrevmatos]

I think I've found the issue:
I could reproduce it locally, on interactive accounts, by having the distinctUntilChanged pick the first balance proof (the one with the locked amount). When debounceTime applied to the channel state before the end of a transfer, together with the capacity not changing between the locked state and the final state (after a transfer with fees), the end PFSCapacityUpdate that went to PFS had nonce n, but after the transfer, the partner also sent his side of the capacity update, with other_nonce (ours) as n+1, i.e. the nonce of the unlocked state.
The nonce difference somehow seems to make PFS go nuts on next PFS request, and send a fee too small (maybe it doesn't consider our previous update, even though the capacity didn't change?).
The fix in our side is to ensure we don't distinctUntilChanged, and debounceTime to always send a PFSCapacityUpdate for the last state and nonce. I could reliably do first-transfers here on 3 accounts.
If this issue kicks in again, we should open an issue on PFS's repo, there's already too much on it here.