Invite to matrix room takes 9 minutes

palango commented 5 years ago

Problem Definition

While working on #5204 and running the BF1 scenario again I constantly run into an expiring lock on the first transfer.

After debugging this with @hackaugusto we found out that the problem is related to the invite to the matrix taking ~10 mins to reach the mediator.

Detailed information

In the scenario (https://github.com/raiden-network/raiden/blob/develop/raiden/tests/scenarios/bf1_basic_functionality.yaml) a payment is send from node 3 to node 1, it is mediated by node 4.

Initiator

0xE7Ff1153b09aF58a20464a96F6629A48c4992880

The initiator tries to send the LockedTransfer at 11:04. As no room exists yet, it is created and the mediator invited.

  "event": "No room for peer, trying to create",
  "timestamp": "2019-11-06 11:04:21.476535"

  "event": "Room created successfully",
  "timestamp": "2019-11-06 11:04:24.294599"

Mediator

0x054EBf559cd96e1c815EE7263018644D754c3890

The Mediator triggers the ActionInitMediator state change. This is processed, calls mediate_transfer and then forward_transfer_pair. There the following check fails: https://github.com/raiden-network/raiden/blob/dc6e2a339b9b22e75f053e96ac6bb46730ef06bc/raiden/transfer/mediated_transfer/mediator.py#L437-L443

(Pdb++) safe_to_use_channel
False
(Pdb++) lock_timeout
-8

This means that the LockedTransfer is received to late, when the lock is already expired.

When looking after the invite we find the following logs:

{
  "current_user": "@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network",
  "event": "Sync called",
  "logger": "raiden.network.transport.matrix.client",
  "level": "debug",
  "greenlet_name": "GMatrixClient.listen_forever user_id:@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network",
  "timestamp": "2019-11-06 11:13:00.596804"
}
{"response": {"our_address": "0x054EBf559cd96e1c815EE7263018644D754c3890"}, "status_code": 200, "event": "Request successful", "logger": "raiden.api.rest", "level": "debug", "timestamp": "2019-11-06 11:13:00.872144"}
{"response": {"our_address": "0x054EBf559cd96e1c815EE7263018644D754c3890"}, "status_code": 200, "event": "Request successful", "logger": "raiden.api.rest", "level": "debug", "timestamp": "2019-11-06 11:13:01.381899"}
{"response": {"our_address": "0x054EBf559cd96e1c815EE7263018644D754c3890"}, "status_code": 200, "event": "Request successful", "logger": "raiden.api.rest", "level": "debug", "timestamp": "2019-11-06 11:13:01.886420"}
{"response": {"our_address": "0x054EBf559cd96e1c815EE7263018644D754c3890"}, "status_code": 200, "event": "Request successful", "logger": "raiden.api.rest", "level": "debug", "timestamp": "2019-11-06 11:13:02.390365"}
{"first_sync": false, "sync_token": "s124805_80212_0_1_116_1_1_77332_1", "current_user": "@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network", "event": "Starting handle greenlet", "logger": "raiden.network.transport.matrix.client", "level": "debug", "greenlet_name": "GMatrixClient.listen_forever user_id:@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network", "timestamp": "2019-11-06 11:13:02.746009"}
{
  "current_user": "@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network",
  "event": "Sync called",
  "logger": "raiden.network.transport.matrix.client",
  "level": "debug",
  "greenlet_name": "GMatrixClient.listen_forever user_id:@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network",
  "timestamp": "2019-11-06 11:13:02.746414"
}

...

{
  "current_user": "@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network",
  "node": "0x054EBf559cd96e1c815EE7263018644D754c3890",
  "transport_uuid": "fff798bd-a04a-4aff-9e90-9c2071aa5ea5",
  "room_id": "!tqoqeugqcmJIVxsxCh:transport01.raiden.network",
  "event": "Got invite",
  "logger": "raiden.network.transport.matrix.transport",
  "level": "debug",
  "greenlet_name": "GMatrixClient._sync user_id:@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network sync_token:s124805_80212_0_1_116_1_1_77332_1",
  "timestamp": "2019-11-06 11:13:10.137012"
}

This means that the invite was received by the mediator 9 minutes after it was send by the initiator.

The reason for this is unclear at the moment.

Logs

Archive 2.zip

System Description

(venv) ➜  raiden git:(develop) ✗ uname -a
command -v solc && solc --version
command -v geth && geth version
command -v parity && parity --version
command -v raiden && raiden version
[ -d .git ] && git rev-parse HEAD
Darwin Pauls-MacBook-Pro-2.local 18.7.0 Darwin Kernel Version 18.7.0: Sat Oct 12 00:02:19 PDT 2019; root:xnu-4903.278.12~1/RELEASE_X86_64 x86_64
/usr/local/bin/solc
solc, the solidity compiler commandline interface
Version: 0.5.4+commit.9549d8ff.Darwin.appleclang
/usr/local/bin/geth
Geth
Version: 1.9.6-stable
Architecture: amd64
Protocol Versions: [63]
Network Id: 1
Go Version: go1.13.1
Operating System: darwin
GOPATH=
GOROOT=/usr/local/Cellar/go/1.13.1/libexec
/Users/paul/Projects/brainbot/raiden/venv/bin/raiden
{
  "raiden": "0.100.5a1.dev716+gc9cb0ff8a.d20191106",
  "raiden_db_version": 23,
  "python_implementation": "CPython",
  "python_version": "3.7.5",
  "system": "macOS 10.14.6 64bit",
  "architecture": "x86_64",
  "distribution": "source"
}
56c49a47330805a5d0ce07989966e087ec5af9de

konradkonrad commented 5 years ago

Clarification question: Title says

takes 9s

Description says

9 minutes after

palango commented 5 years ago

@konradkonrad It's 9+ minutes.

Dominik1999 commented 5 years ago

Wow, thanks for digging into it. Damn

andrevmatos commented 5 years ago

A possible reason for this is that, if somehow the "inviter" has some room for "invitee" on account_data, it may not invite immediately. I've seen this happening with the Light Client. A way to trigger the reinvite from the invitee perspective is going offline and after e.g. 30s coming back online. The status change should trigger the re-invite. A proper fix is the inviter checking in more events if invitee is in the room and reinviting, possibly including #4715 and/or other invite retries.

hackaugusto commented 5 years ago

A possible reason for this is that, if somehow the "inviter" has some room for "invitee" on account_data, it may not invite immediately.

The invite is done in the same RPC call that creates the room, here:

https://github.com/raiden-network/raiden/blob/960c4749a41f4b1c99254a79f8922615c7ab5d5c/raiden/network/transport/matrix/transport.py#L1083

If the room was created then the partner should have been invited.

palango commented 5 years ago

@ulope I don't see the mediator going offline from the initiators view:

{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 10:51:37.987986"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 10:52:08.431428"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 10:52:38.862162"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 10:53:09.894212"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 10:53:40.346870"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 10:54:10.751850"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 10:54:41.181961"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 10:55:11.597581"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 10:55:42.716165"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 10:56:13.113750"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 10:56:43.528172"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 10:57:14.439774"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 10:57:44.834013"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 10:58:16.221066"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 10:58:46.784790"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 10:59:18.187315"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 10:59:48.716834"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:00:19.238487"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:00:49.802743"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:01:20.602279"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:01:51.570258"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:02:22.113169"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:02:53.850168"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:03:24.360046"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:03:55.821701"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:04:26.375491"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:04:56.925368"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:05:28.011623"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:05:59.629853"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:06:30.475320"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:07:01.228953"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:07:32.259216"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:08:02.807036"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:08:33.938854"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:09:04.609680"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:09:35.150636"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:10:05.693788"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:10:36.207958"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:11:07.808583"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:11:38.950846"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:12:09.759231"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:12:40.292548"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:13:11.102537"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:13:41.671625"}
{"addresses_uids_and_presence": {"0xd006EA009c3E85C39F27a183768213B442C1e86B": {"@0xd006ea009c3e85c39f27a183768213b442c1e86b:transport03.raiden.network": "online"}, "0x054EBf559cd96e1c815EE7263018644D754c3890": {"@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network": "online"}, "0xA0cd100392168Ec7F6c87c723254CdDA96EC86AE": {"@0xa0cd100392168ec7f6c87c723254cdda96ec86ae:transport01.raiden.network": "online"}}, "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network", "event": "Presences refreshed - current Matrix address manager status:", "logger": "raiden.network.transport.matrix.utils", "level": "debug", "timestamp": "2019-11-06 11:14:12.192382"}

Any other ideas?

ulope commented 5 years ago

You could look for the following log events on the inviters side:

Waiting for peer to join from invite
Peer has not joined from invite yet, should join eventually
Inviting (I wouldn't expect this one to appear, it only happens when a peer we're interested in comes back online)

palango commented 5 years ago

➜  node_4_003 cat run-004.log |  grep "Waiting for peer to join from invite"| jq .
{
  "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network",
  "node": "0xE7Ff1153b09aF58a20464a96F6629A48c4992880",
  "transport_uuid": "01b0c859-fe2e-4a41-a0d7-79a297704556",
  "room": "<Room id='!tqoqeugqcmJIVxsxCh:transport01.raiden.network' alias='#raiden_goerli_0x054ebf559cd96e1c815ee7263018644d754c3890_0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network'>",
  "peer_address": "0x054EBf559cd96e1c815EE7263018644D754c3890",
  "event": "Waiting for peer to join from invite",
  "logger": "raiden.network.transport.matrix.transport",
  "level": "debug",
  "greenlet_name": "RetryQueue node:0xE7Ff1153b09aF58a20464a96F6629A48c4992880 recipient:0x054EBf559cd96e1c815EE7263018644D754c3890",
  "timestamp": "2019-11-06 11:04:24.444022"
}
➜  node_4_003 cat run-004.log |  grep "Peer has not joined from invite yet, should join eventually"| jq .
{
  "current_user": "@0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network",
  "node": "0xE7Ff1153b09aF58a20464a96F6629A48c4992880",
  "transport_uuid": "01b0c859-fe2e-4a41-a0d7-79a297704556",
  "room": "<Room id='!tqoqeugqcmJIVxsxCh:transport01.raiden.network' alias='#raiden_goerli_0x054ebf559cd96e1c815ee7263018644d754c3890_0xe7ff1153b09af58a20464a96f6629a48c4992880:transport01.raiden.network'>",
  "peer_address": "0x054EBf559cd96e1c815EE7263018644D754c3890",
  "event": "Peer has not joined from invite yet, should join eventually",
  "logger": "raiden.network.transport.matrix.transport",
  "level": "error",
  "greenlet_name": "RetryQueue node:0xE7Ff1153b09aF58a20464a96F6629A48c4992880 recipient:0x054EBf559cd96e1c815EE7263018644D754c3890",
  "timestamp": "2019-11-06 11:04:41.217893"
}
➜  node_4_003 cat run-004.log |  grep "Inviting"| jq .
➜  node_4_003

palango commented 5 years ago

The synapse logs for 6th November for transport 01 and 02: tp1_synapse_19_11_06.log tp2_synapse_19_11_06.log

Synchrotron logs: Archive.zip

palango commented 5 years ago

I looked through the synchrotron logs and found this. It seems like the last sync request was made at 10:50 before the payment started, and then again at 11:13. This would mean there was no request for 23 mins.

>  rg --smart-case 0x054e *.log
tp2_synchrotron4_19_11_06.log
...
4193:{"log":"2019-11-06 10:50:06,615 - synapse.handlers.sync - 935 - INFO - GET-26572 - Calculating sync response for @0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network between StreamToken(room_key='s124804', presence_key='80212', typing_key='0', receipt_key='1', account_data_key='116', push_rules_key='1', to_device_key='1', device_list_key='77332', groups_key='1') and StreamToken(room_key='s124805', presence_key=80212, typing_key=0, receipt_key=1, account_data_key=116, push_rules_key=1, to_device_key=1, device_list_key=77332, groups_key=1)\n","stream":"stderr","time":"2019-11-06T10:50:06.624795622Z"}
4194:{"log":"2019-11-06 10:50:06,622 - synapse.access.http.8008 - 302 - INFO - GET-26572 - 172.19.0.20 - 8008 - {@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network} Processed request: 20.009sec/0.001sec (0.007sec, 0.000sec) (0.000sec/0.000sec/0) 320B 200 \"GET /_matrix/client/r0/sync?timeout=20000\u0026since=s124804_80212_0_1_116_1_1_77332_1\u0026access_token=\u003credacted\u003e HTTP/1.1\" \"python-requests/2.22.0\" [0 dbevts]\n","stream":"stderr","time":"2019-11-06T10:50:06.624869233Z"}
4350:{"log":"2019-11-06 11:13:00,762 - synapse.util.caches.response_cache - 148 - INFO - GET-26573 - [sync]: no cached result for [(@0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network, 20000, 's124805_80212_0_1_116_1_1_77332_1', None, False, 'FLWZCRHHJQ')], calculating new one\n","stream":"stderr","time":"2019-11-06T11:13:00.763219455Z"}
4351:{"log":"2019-11-06 11:13:00,763 - synapse.handlers.sync - 935 - INFO - GET-26573 - Calculating sync response for @0x054ebf559cd96e1c815ee7263018644d754c3890:transport02.raiden.network between StreamToken(room_key='s124805', presence_key='80212', typing_key='0', receipt_key='1', account_data_key='116', push_rules_key='1', to_device_key='1', device_list_key='77332', groups_key='1') and StreamToken(room_key='s124833', presence_key=81245, typing_key=0, receipt_key=1, account_data_key=116, push_rules_key=1, to_device_key=1, device_list_key=77336, groups_key=1)\n","stream":"stderr","time":"2019-11-06T11:13:00.763627658Z"}
...

This also fits the node logs:

➜  bf1_basic_functionality cat node_4_004/run-004.log | grep "Sync called" | jq .timestamp
"2019-11-06 10:49:21.340545"
"2019-11-06 10:49:34.676062"
"2019-11-06 10:49:46.504693"
"2019-11-06 11:13:00.596804"
"2019-11-06 11:13:02.746414"
"2019-11-06 11:13:13.775814"
"2019-11-06 11:13:14.699779"
"2019-11-06 11:13:18.408459"
"2019-11-06 11:13:19.053594"
"2019-11-06 11:13:20.067729"
"2019-11-06 11:13:20.876180"
"2019-11-06 11:13:41.222580"
"2019-11-06 11:13:54.072355"
"2019-11-06 11:13:54.779747"
"2019-11-06 11:13:55.697842"
"2019-11-06 11:13:56.132430"
"2019-11-06 11:13:56.531417"
"2019-11-06 11:13:57.596292"
"2019-11-06 11:14:01.994599"
"2019-11-06 11:14:03.023591"
"2019-11-06 11:14:03.449388"
"2019-11-06 11:14:22.419046"
"2019-11-06 11:14:23.265434"
"2019-11-06 11:14:23.647781"
"2019-11-06 11:14:24.570630"
"2019-11-06 11:14:25.067519"

palango commented 5 years ago

I ran the same scenario again on top of https://github.com/raiden-network/raiden/pull/5273 and this fixes the delay at the first sync.


{"current_user": "@0xcf4c965a203fef827e0d07fc6f3eb6aced7258b2:transport02.raiden.network", "event": "Sync called", "logger": "raiden.network.transport.matrix.client", "level": "debug", "greenlet_name": "GMatrixClient.listen_forever user_id:@0xcf4c965a203fef827e0d07fc6f3eb6aced7258b2:transport02.raiden.network", "timestamp": "2019-11-12 15:48:15.062458"}
{"items": 3049, "event": "presence update", "logger": "raiden.network.transport.matrix.client", "level": "debug", "greenlet_name": "GMatrixClient._sync user_id:@0xcf4c965a203fef827e0d07fc6f3eb6aced7258b2:transport02.raiden.network sync_token:s134773_106396_0_1_126_1_1_219964_1", "timestamp": "2019-11-12 15:48:15.064450"}
{"items": 0, "event": "to_device_message", "logger": "raiden.network.transport.matrix.client", "level": "debug", "greenlet_name": "GMatrixClient._sync user_id:@0xcf4c965a203fef827e0d07fc6f3eb6aced7258b2:transport02.raiden.network sync_token:s134773_106396_0_1_126_1_1_219964_1", "timestamp": "2019-11-12 15:48:15.175598"}

palango commented 4 years ago

Fixed by #5273

raiden-network / raiden