search

status-im / status-desktop

Status Desktop client made in Nim & QML
https://status.app
Mozilla Public License 2.0
288 stars 78 forks source link

Contact requests, messages etc. take longer to receive #15315

Closed Valentina1133 closed 2 months ago

Valentina1133 commented 3 months ago

Description

We noticed in nightly runs that it takes longer then usual to receive contact requests, messages etc.

I also attach some app logs from nightly runs - maybe it will help. Tried to get geth.log locally but couldn't reproduce the scenario.

Additional Information

App logs from nightly

message2.txt message-2.txt

anastasiyaig commented 3 months ago

we need geth logs here :/

Valentina1133 commented 3 months ago

we need geth logs here :/

I know, but we only have app logs on ci :( And locally I was not able to reproduce when I tried to get geth.log

anastasiyaig commented 3 months ago

ya thats okay , i know 🙏

Valentina1133 commented 3 months ago

message-4.txt

I got get.log after running test, attached. So I managed to reproduce bug locally. There is no community invitation in chat for a long time

Valentina1133 commented 3 months ago

The issue is still actual (so https://github.com/status-im/status-go/pull/5430 didn't help).

anastasiyaig commented 3 months ago

@Valentina1133 i added geth log to allure report, please attach them to this issue

Valentina1133 commented 3 months ago

data_attachments_d6668997c897e9f4.txt

data_attachments_661a6024b139dbec.txt

chaitanyaprem commented 3 months ago

data_attachments_d6668997c897e9f4.txt

data_attachments_661a6024b139dbec.txt

data_attachments_d6668997c897e9f4 - receiver data_attachments_661a6024b139dbec - sender

After going through these logs , found that contact request is received by receiver and maybe got discarded at message filter layer or somewhere above in status-go. cc @cammellos please take a look.

Logs from sender which shows messageHash for contact-request

21056 DEBUG[07-01|05:40:28.305|github.com/status-im/status-go/protocol/common/message_sender.go:756] sent-message: public message recipien t=[] messageID=0xd2ae895e892c0752fb4b1ce07d3fd2a6250991ff2ba9d4743f72e202150b687a contentType=CONTACT_CODE_ADVERTISEMENT messageType=public hashes=[0x9a0b48fc2ccd7cee 05a84239d0bd95c5526a23b01e4ebda294560112a910ac14]

Logs on receiver side which has received the request messageHash - 0x9a0b48fc2ccd7cee 05a84239d0bd95c5526a23b01e4ebda294560112a910ac14, but looks like UI is not shown as contact request received.

DEBUG[07-01|05:40:28.571|github.com/status-im/status-go/wakuv2/waku.go:1550]                                         received new envelope                    messageType=0 envelopeHash=0x9a0b48fc2ccd7cee05a84239d0bd95c5526a23b01e4ebda294560112a910ac14 contentTopic=/waku/1/0x13de0a1b/rfc26 timestamp=1,719,812,428,305,802,990
DEBUG[07-01|05:40:28.571|github.com/status-im/status-go/wakuv2/waku.go:1594]                                         cached w envelope                        envelopeHash=0x9a0b48fc2ccd7cee05a84239d0bd95c5526a23b01e4ebda294560112a910ac14
DEBUG[07-01|05:40:28.571|github.com/status-im/status-go/wakuv2/waku.go:1604]                                         posting event                            envelopeHash=0x9a0b48fc2ccd7cee05a84239d0bd95c5526a23b01e4ebda294560112a910ac14
DEBUG[07-01|05:40:28.571|github.com/status-im/status-go/wakuv2/common/filter.go:234]                                 no filters available for this topic      message=0x9a0b48fc2ccd7cee05a84239d0bd95c5526a23b01e4ebda294560112a910ac14 pubsubTopic=/waku/2/rs/16/32 contentTopic=0x13de0a1b
DEBUG[07-01|05:40:28.571|github.com/status-im/status-go/wakuv2/waku.go:1664]                                         filters did not match                    envelopeHash=0x9a0b48fc2ccd7cee05a84239d0bd95c5526a23b01e4ebda294560112a910ac14 pubsubTopic=/waku/2/rs/16/32 contentTopic=/waku/1/0x13de0a1b/rfc26 timestamp=1,719,812,428,305,802,990

UI on receiver

image

cammellos commented 3 months ago

data_attachments_d6668997c897e9f4.txt data_attachments_661a6024b139dbec.txt

data_attachments_d6668997c897e9f4 - receiver data_attachments_661a6024b139dbec - sender

After going through these logs , found that contact request is received by receiver and maybe got discarded at message filter layer or somewhere above in status-go. cc @cammellos please take a look.

Logs from sender which shows messageHash for contact-request

21056 DEBUG[07-01|05:40:28.305|github.com/status-im/status-go/protocol/common/message_sender.go:756] sent-message: public message recipien t=[] messageID=0xd2ae895e892c0752fb4b1ce07d3fd2a6250991ff2ba9d4743f72e202150b687a contentType=CONTACT_CODE_ADVERTISEMENT messageType=public hashes=[0x9a0b48fc2ccd7cee 05a84239d0bd95c5526a23b01e4ebda294560112a910ac14]

Logs on receiver side which has received the request messageHash - 0x9a0b48fc2ccd7cee 05a84239d0bd95c5526a23b01e4ebda294560112a910ac14, but looks like UI is not shown as contact request received.

DEBUG[07-01|05:40:28.571|github.com/status-im/status-go/wakuv2/waku.go:1550]                                         received new envelope                    messageType=0 envelopeHash=0x9a0b48fc2ccd7cee05a84239d0bd95c5526a23b01e4ebda294560112a910ac14 contentTopic=/waku/1/0x13de0a1b/rfc26 timestamp=1,719,812,428,305,802,990
DEBUG[07-01|05:40:28.571|github.com/status-im/status-go/wakuv2/waku.go:1594]                                         cached w envelope                        envelopeHash=0x9a0b48fc2ccd7cee05a84239d0bd95c5526a23b01e4ebda294560112a910ac14
DEBUG[07-01|05:40:28.571|github.com/status-im/status-go/wakuv2/waku.go:1604]                                         posting event                            envelopeHash=0x9a0b48fc2ccd7cee05a84239d0bd95c5526a23b01e4ebda294560112a910ac14
DEBUG[07-01|05:40:28.571|github.com/status-im/status-go/wakuv2/common/filter.go:234]                                 no filters available for this topic      message=0x9a0b48fc2ccd7cee05a84239d0bd95c5526a23b01e4ebda294560112a910ac14 pubsubTopic=/waku/2/rs/16/32 contentTopic=0x13de0a1b
DEBUG[07-01|05:40:28.571|github.com/status-im/status-go/wakuv2/waku.go:1664]                                         filters did not match                    envelopeHash=0x9a0b48fc2ccd7cee05a84239d0bd95c5526a23b01e4ebda294560112a910ac14 pubsubTopic=/waku/2/rs/16/32 contentTopic=/waku/1/0x13de0a1b/rfc26 timestamp=1,719,812,428,305,802,990

UI on receiver

image

I can have a look @chaitanyaprem , but the message you highlighted is not a contact request, contact requests are not public messages, and don't have the type CONTACT_CODE_ADVERTISEMENT

chaitanyaprem commented 3 months ago

data_attachments_d6668997c897e9f4.txt data_attachments_661a6024b139dbec.txt

data_attachments_d6668997c897e9f4 - receiver data_attachments_661a6024b139dbec - sender After going through these logs , found that contact request is received by receiver and maybe got discarded at message filter layer or somewhere above in status-go. cc @cammellos please take a look. Logs from sender which shows messageHash for contact-request 21056 DEBUG[07-01|05:40:28.305|github.com/status-im/status-go/protocol/common/message_sender.go:756] sent-message: public message recipien t=[] messageID=0xd2ae895e892c0752fb4b1ce07d3fd2a6250991ff2ba9d4743f72e202150b687a contentType=CONTACT_CODE_ADVERTISEMENT messageType=public hashes=[0x9a0b48fc2ccd7cee 05a84239d0bd95c5526a23b01e4ebda294560112a910ac14] Logs on receiver side which has received the request messageHash - 0x9a0b48fc2ccd7cee 05a84239d0bd95c5526a23b01e4ebda294560112a910ac14, but looks like UI is not shown as contact request received.

DEBUG[07-01|05:40:28.571|github.com/status-im/status-go/wakuv2/waku.go:1550]                                         received new envelope                    messageType=0 envelopeHash=0x9a0b48fc2ccd7cee05a84239d0bd95c5526a23b01e4ebda294560112a910ac14 contentTopic=/waku/1/0x13de0a1b/rfc26 timestamp=1,719,812,428,305,802,990
DEBUG[07-01|05:40:28.571|github.com/status-im/status-go/wakuv2/waku.go:1594]                                         cached w envelope                        envelopeHash=0x9a0b48fc2ccd7cee05a84239d0bd95c5526a23b01e4ebda294560112a910ac14
DEBUG[07-01|05:40:28.571|github.com/status-im/status-go/wakuv2/waku.go:1604]                                         posting event                            envelopeHash=0x9a0b48fc2ccd7cee05a84239d0bd95c5526a23b01e4ebda294560112a910ac14
DEBUG[07-01|05:40:28.571|github.com/status-im/status-go/wakuv2/common/filter.go:234]                                 no filters available for this topic      message=0x9a0b48fc2ccd7cee05a84239d0bd95c5526a23b01e4ebda294560112a910ac14 pubsubTopic=/waku/2/rs/16/32 contentTopic=0x13de0a1b
DEBUG[07-01|05:40:28.571|github.com/status-im/status-go/wakuv2/waku.go:1664]                                         filters did not match                    envelopeHash=0x9a0b48fc2ccd7cee05a84239d0bd95c5526a23b01e4ebda294560112a910ac14 pubsubTopic=/waku/2/rs/16/32 contentTopic=/waku/1/0x13de0a1b/rfc26 timestamp=1,719,812,428,305,802,990

UI on receiver image

I can have a look @chaitanyaprem , but the message you highlighted is not a contact request, contact requests are not public messages, and don't have the type CONTACT_CODE_ADVERTISEMENT

Ah, Thanks...what would the message to look for then? I will look accordingly in the logs.

cammellos commented 3 months ago

The only one I could see:

Sender

DEBUG[07-01|05:40:28.318|github.com/status-im/status-go/protocol/messenger.go:2514]                                  inside sendChatMessage                   id=0x674347543728cef4c1e15ea1235d5a6cf0ed1e3e2c42593585a30eb5ab394e20 text="Hello athletic" from=0x04b6ccdd1627de86b73447f8572ecc5ab095aad07f02d44b44a1eab312875388274601a18eb159ed91b64af365124552f5456e9dbb1b2fd550b79a012e863a6575 displayName=squisher ChatId=0x0453b9091c30e83ddcf8bf1f813fa752f3842ecc8c2f52dbcc5d69918172293f9c0e411b13fa9c1842054725f78945592a9a688670c46cb3a552338c2c17e3f60b Clock=1719812428313 Timestamp=1719812428313
DEBUG[07-01|05:40:28.321|rpc/handler.go:307]                                                                         Served wakuext_sendContactRequest        reqid=81 duration=54.992508ms

and to check for the corresponding hash:

DEBUG[07-01|05:40:28.702|github.com/status-im/status-go/protocol/messenger_peersyncing.go:414]                       sent private messages                    messageIDs=[0x674347543728cef4c1e15ea1235d5a6cf0ed1e3e2c42593585a30eb5ab394e20] hashes=[0x7e2cfd280f94104e0bd022820a47a48afc117d5cfd32f44031bc78745845ac79]

Receiver

DEBUG[07-01|05:40:29.525|github.com/status-im/status-go/wakuv2/common/filter.go:249]                                 processing message: decrypted            envelopeHash=0x7e2cfd280f94104e0bd022820a47a48afc117d5cfd32f44031bc78745845ac79
DEBUG[07-01|05:40:29.525|github.com/status-im/status-go/wakuv2/common/filter.go:234]                                 no filters available for this topic      message=0xf030a6b0f588b07926cd683af20fdd775c222f3fd10a2cbfad19330a187eb523 pubsubTopic=/waku/2/rs/16/32 contentTopic=0xbc0a6d4a
DEBUG[07-01|05:40:29.525|github.com/status-im/status-go/wakuv2/waku.go:1669]                                         filters did match                        envelopeHash=0x7e2cfd280f94104e0bd022820a47a48afc117d5cfd32f44031bc78745845ac79 pubsubTopic=/waku/2/rs/16/32 contentTopic=/waku/1/0x2d5233f8/rfc26 timestamp=1,719,812,428,702,589,054

but processing stops there, last log is at:

DEBUG[07-01|05:40:35.835|github.com/status-im/mvds/node/node.go:220]                                                 Epoch processing                         namespace=mvds node=0453b909 epoch=111

So roughly 6 seconds after receiving the message.

One thing to note, is that it looks like messages are being processed very slowly, so that might be the reason:

for example:

DEBUG[07-01|05:40:35.791|github.com/status-im/status-go/protocol/common/message_segmentation.go:237]                 handling message segment                 site=handleSegmentationLayerV2 hash=0x955b9c9e70d7bf0de507cb8688d1a8d3a0baf8b03e5e892ac3c74f0e20aff8f7 EntireMessageHash=0xd06d22abab8aa08beb903d543a382aa35c0d646ff64ff74027c65d658e72525d510d65ff6f7db91d20cb3f57b30902a488091d148acc21dee651dd4a05d0fab500 Index=0 SegmentsCount=79 ParitySegmentIndex=0 ParitySegmentsCount=0

it's processed at 05:40:35.791

but received from store nodes:

INFO [07-01|05:40:08.135|github.com/status-im/status-go/wakuv2/waku.go:1282]                                         received waku2 store message             requestID=0x81ffc088653ed7a7bc66e606695c7762e7f3acb1dde017c7f3f5101676a1723b peerID=16Uiu2HAm9aDJPkhGxc2SFcEACTFdZ91Q5TJjp76qZEhq9iF59x7R envelopeHash=0x955b9c9e70d7bf0de507cb8688d1a8d3a0baf8b03e5e892ac3c74f0e20aff8f7 pubsubTopic=/waku/2/rs/16/64 timestamp=1,719,755,480,639,636,774

05:40:08.135

so almost 30s later

anastasiyaig commented 3 months ago

that would explain why my test is failing, we dont wait for 30 seconds to receive a contact request. Should we? what is acceptable timeframe? @cammellos

cammellos commented 3 months ago

@anastasiyaig 30s is plenty, especially since it's due to processing, 5/10 seconds is already plenty, I think we need to figure out why the node is so busy. Best guess for now is that it's retrieving a lot of messages from store nodes and it struggles to process them, but we'd have to check