Staging Mediating Transfers Expires in the mediating node

[agatsoh]

Thanks for filing a bug report :-)

Steps to Reproduce

1. Perform a one hop mediated transfer

I have 3 nodes
light client
0xAa1Ab1fDA93e14c2d564B25Ba08c9d374F5F9541 Main Account
0x9bf12572aBd794b031313fE286040nce727eC6191 Raiden Account
.|
V
0x949e47d1E0C5351eCBb7C50bB5Dcf3fE915468e9 RC
.|
V
0xdD29eA8d403365BcbFFd659a13d4A24370e2d940 RC

Mediated transfers remains Pending in the mediating node and then expires

Expected Result

• Mediated Transfer should be successful

Actual Result

Raiden Python Client version:
1.1.0 Sun Prince

Additional Infos (Optional)

- Browser & version
- Browser console errors
- Device / OS

[agatsoh]

Similar scenario happened on the mainnet on latest master

The initiating node is the light client
0x80593AE89B11Dff1C251500c6A3918C8C3f38B9C
sub key
0x14efA2b271969A46A094A23e0d49E32C1B617f89

Mediating node(and receiver) is the python client
0xF128A427DeFf3a4f792373f4BE38bEecD07d4ffE

Light client logs
raiden_2020-07-07T12_45_10.674Z.log

Mediating node logs
node-F128A4-mainnet.7thJuly2020.log

[christianbrb]

Related to #1933

[agatsoh]

This issue was encountered by me today on the mainnet as well hence uploading the logs of the light client as well as mediating node. Most probably has nothing to do with the LC but only with the python client.

LC logs
raiden_0x14efA2b271969A46A094A23e0d49E32C1B617f89_2020-07-31T12_16_09.934Z.log

mediating python node logs

node-F128A4-mainnet.31thJuly2020.log

Edit:
I have tested this issue after Andres this PR was merged #2009

[christianbrb]

@Dominik1999 Could you take a look at this issue? It seems to be a Python Client issue.

[karlb]

mediating python node logs

node-F128A4-mainnet.31thJuly2020.log

The relevant error message is Invalid LockedTransfer message. Nonce did not change sequentially, expected: 9 got: 7.. Does anyone already have more insight into this (maybe as part of #1933?)? If not, I'll go through the logs and trace the nonce changes.

[christianbrb]

@karlb Thanks a lot for looking into this :)

We haven't done any investigations on the python client yet.

@andrevmatos Is available if you need any support.

[karlb]

I looked at the transfer with the secrethash 0x57f98753b83718e58861c4324572a63deeb94a56bc5fade7ec7d49cf44d713b3 together with Augusto. If I read the light client logs correctly, then the expiration block for the transfer is 0xa12bf1 = 10562545 and the failure "type":"transfer/failure","payload":"RaidenError: Transfer expired. happened at roughly 10567249. This indicates that the transfer is rightfully expired (10562545 < 10567249). Maybe the light client had an outdated state when initiating the transfer?

I also see many retried messages in the logs. So probably there's also some problem with the handling of delivered/processed messages between the light client and the python client.

[andrevmatos]

I'll add more informative errors there as well, to tell which was the expected and received nonce. As you said, it really looks like the transfer was rightfully expired, but old messages should be retried as per our current algorithm.
Eventually, I'd like to add messages to inform the BalanceProof of nonce we're stuck on, this may allow clients to recover state loss.