Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

11/WAKU2-RELAY: Large files not accepted #739

Closed
D4nte opened this issue Oct 12, 2021 · 21 comments
Closed

11/WAKU2-RELAY: Large files not accepted #739

D4nte opened this issue Oct 12, 2021 · 21 comments
Assignees

Comments

@D4nte
Copy link
Contributor

D4nte commented Oct 12, 2021

The Status app currently sends images over Waku v1.

To attempt the same over Waku v2 as part of the DappConnect Chat SDK, we have tried sending messages of ~100kb. However, it fails.

The issue seem related to this error message:

 TRC 2021-10-12 12:09:39.709+11:00 Exception occurred in PubSubPeer.handle    topics="libp2p pubsubpeer" tid=3578495 file=pubsubpeer.nim:156 conn=QmY*kfeH1F:6164e04dbc59820630030e27 peer=QmY*kfeH1F closed=true exc="Message exceeds maximum length"

Please find full logs below for a 500kb payload size:

DBG 2021-10-12 12:09:33.534+11:00 1/6 Setting up storage                     topics="wakunode.setup" tid=3578495 file=wakunode2.nim:874
DBG 2021-10-12 12:09:33.534+11:00 2/6 Initializing node                      topics="wakunode.setup" tid=3578495 file=wakunode2.nim:887
INF 2021-10-12 12:09:33.538+11:00 Initializing networking                    topics="wakunode.setup" tid=3578495 file=wakunode2.nim:137 hostAddress=/ip4/127.0.0.1/tcp/61615 announcedAddresses=@[]
TRC 2021-10-12 12:09:33.538+11:00 registering protocols                      topics="libp2p multistream" tid=3578495 file=multistream.nim:189 protos="@[\"/ipfs/id/1.0.0\"]"
DBG 2021-10-12 12:09:33.538+11:00 3/6 Mounting protocols                     topics="wakunode.setup" tid=3578495 file=wakunode2.nim:897
DBG 2021-10-12 12:09:33.538+11:00 initWakuRelay                              topics="wakurelay" tid=3578495 file=waku_relay.nim:49
DBG 2021-10-12 12:09:33.538+11:00 init WakuRelay                             topics="wakurelay" tid=3578495 file=waku_relay.nim:26
DBG 2021-10-12 12:09:33.538+11:00 init WakuRelay                             topics="wakurelay" tid=3578495 file=waku_relay.nim:26
INF 2021-10-12 12:09:33.538+11:00 mounting relay                             topics="wakunode" tid=3578495 file=wakunode2.nim:501 rlnRelayEnabled=false relayMessages=true
TRC 2021-10-12 12:09:33.538+11:00 registering protocols                      topics="libp2p multistream" tid=3578495 file=multistream.nim:189 protos="@[\"/vac/waku/relay/2.0.0\", \"/vac/waku/relay/2.0.0\"]"
INF 2021-10-12 12:09:33.538+11:00 relay mounted successfully                 topics="wakunode" tid=3578495 file=wakunode2.nim:526
INF 2021-10-12 12:09:33.538+11:00 mounting libp2p ping protocol              topics="wakunode" tid=3578495 file=wakunode2.nim:545
TRC 2021-10-12 12:09:33.538+11:00 registering protocols                      topics="libp2p multistream" tid=3578495 file=multistream.nim:189 protos="@[\"/ipfs/ping/1.0.0\"]"
INF 2021-10-12 12:09:33.538+11:00 mounting swap                              topics="wakunode" tid=3578495 file=wakunode2.nim:381 mode=Soft
INF 2021-10-12 12:09:33.538+11:00 wakuSwap init 2                            topics="wakunode" tid=3578495 file=waku_swap.nim:285
INF 2021-10-12 12:09:33.538+11:00 wakuSwap init 1                            topics="wakuswap" tid=3578495 file=waku_swap.nim:218
TRC 2021-10-12 12:09:33.538+11:00 registering protocols                      topics="libp2p multistream" tid=3578495 file=multistream.nim:189 protos="@[\"/vac/waku/swap/2.0.0-beta1\"]"
INF 2021-10-12 12:09:33.538+11:00 mounting store                             topics="wakunode" tid=3578495 file=wakunode2.nim:388
DBG 2021-10-12 12:09:33.538+11:00 mounting store with swap                   topics="wakunode" tid=3578495 file=wakunode2.nim:394
DBG 2021-10-12 12:09:33.538+11:00 init                                       topics="wakunode" tid=3578495 file=waku_store.nim:430
TRC 2021-10-12 12:09:33.538+11:00 registering protocols                      topics="libp2p multistream" tid=3578495 file=multistream.nim:189 protos="@[\"/vac/waku/store/2.0.0-beta3\"]"
DBG 2021-10-12 12:09:33.538+11:00 4/6 Starting node and mounted protocols    topics="wakunode.setup" tid=3578495 file=wakunode2.nim:904
TRC 2021-10-12 12:09:33.538+11:00 starting switch for peer                   topics="libp2p switch" tid=3578495 file=switch.nim:207 peerInfo="(peerId: \"16Uiu2HAmGCUKNU1C4mL2Kwn6TjznR45kku7sMxXsN2HJCxL2itbT\", addrs: @[\"/ip4/127.0.0.1/tcp/61615\"], protocols: @[\"/ipfs/id/1.0.0\", \"/vac/waku/relay/2.0.0\", \"/ipfs/ping/1.0.0\", \"/vac/waku/swap/2.0.0-beta1\", \"/vac/waku/store/2.0.0-beta3\"], protoVersion: \"ipfs/0.1.0\", agentVersion: \"nim-libp2p/0.0.1\")"
TRC 2021-10-12 12:09:33.538+11:00 starting transport                         topics="libp2p transport" tid=3578495 file=transport.nim:42 address=/ip4/127.0.0.1/tcp/61615
TRC 2021-10-12 12:09:33.538+11:00 Starting TCP transport                     topics="libp2p tcptransport" tid=3578495 file=tcptransport.nim:148
TRC 2021-10-12 12:09:33.538+11:00 Listening on                               topics="libp2p tcptransport" tid=3578495 file=tcptransport.nim:158 address=/ip4/127.0.0.1/tcp/61615
DBG 2021-10-12 12:09:33.538+11:00 About to accept incoming connection        topics="libp2p switch" tid=3578495 file=switch.nim:167
TRC 2021-10-12 12:09:33.538+11:00 Acquired slot                              topics="libp2p semaphore" tid=3578495 file=semaphore.nim:38 available=3 queue=0
TRC 2021-10-12 12:09:33.538+11:00 Tracking incoming connection               topics="libp2p connmanager" tid=3578495 file=connmanager.nim:449
TRC 2021-10-12 12:09:33.538+11:00 Acquired slot                              topics="libp2p semaphore" tid=3578495 file=semaphore.nim:38 available=49 queue=0
DBG 2021-10-12 12:09:33.539+11:00 Started libp2p node                        topics="libp2p switch" tid=3578495 file=switch.nim:222 peer="(peerId: \"16Uiu2HAmGCUKNU1C4mL2Kwn6TjznR45kku7sMxXsN2HJCxL2itbT\", addrs: @[\"/ip4/127.0.0.1/tcp/61615\"], protocols: @[\"/ipfs/id/1.0.0\", \"/vac/waku/relay/2.0.0\", \"/ipfs/ping/1.0.0\", \"/vac/waku/swap/2.0.0-beta1\", \"/vac/waku/store/2.0.0-beta3\"], protoVersion: \"ipfs/0.1.0\", agentVersion: \"nim-libp2p/0.0.1\")"
INF 2021-10-12 12:09:33.539+11:00 PeerInfo                                   topics="wakunode" tid=3578495 file=wakunode2.nim:656 peerId=16U*L2itbT addrs=@[/ip4/127.0.0.1/tcp/61615]
INF 2021-10-12 12:09:33.539+11:00 Listening on                               topics="wakunode" tid=3578495 file=wakunode2.nim:659 full=/ip4/127.0.0.1/tcp/61615/p2p/16Uiu2HAmGCUKNU1C4mL2Kwn6TjznR45kku7sMxXsN2HJCxL2itbT
INF 2021-10-12 12:09:33.539+11:00 starting relay                             topics="wakunode" tid=3578495 file=wakunode2.nim:457
INF 2021-10-12 12:09:33.539+11:00 subscribe                                  topics="wakunode" tid=3578495 file=wakunode2.nim:169 topic=/waku/2/default-waku/proto
DBG 2021-10-12 12:09:33.539+11:00 Registering default handler                topics="wakunode" tid=3578495 file=wakunode2.nim:190 topic=/waku/2/default-waku/proto
DBG 2021-10-12 12:09:33.539+11:00 subscribe                                  topics="wakurelay" tid=3578495 file=waku_relay.nim:69 pubSubTopic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:33.539+11:00 subscribing to topic                       topics="libp2p pubsub" tid=3578495 file=pubsub.nim:454 name=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:33.539+11:00 rebalancing mesh                           tid=3578495 file=behavior.nim:258 mesh=0 gossipsub=0 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:33.539+11:00 replenishing mesh                          tid=3578495 file=behavior.nim:267 peers=0 mesh=0 gossipsub=0 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:33.539+11:00 grafting                                   tid=3578495 file=behavior.nim:291 grafting=0 mesh=0 gossipsub=0 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:33.539+11:00 mesh balanced                              tid=3578495 file=behavior.nim:450 mesh=0 gossipsub=0 topic=/waku/2/default-waku/proto
INF 2021-10-12 12:09:33.539+11:00 subscribe                                  topics="wakunode" tid=3578495 file=wakunode2.nim:169 topic=/waku/2/default-waku/proto
DBG 2021-10-12 12:09:33.539+11:00 start                                      topics="wakurelay" tid=3578495 file=waku_relay.nim:95
TRC 2021-10-12 12:09:33.539+11:00 gossipsub start                            topics="libp2p gossipsub" tid=3578495 file=gossipsub.nim:515
TRC 2021-10-12 12:09:33.539+11:00 running heartbeat                          tid=3578495 file=behavior.nim:615 instance=140637430378568
TRC 2021-10-12 12:09:33.539+11:00 updating scores                            tid=3578495 file=scoring.nim:118 peers=0
TRC 2021-10-12 12:09:33.539+11:00 updated scores                             tid=3578495 file=scoring.nim:289 peers=0
TRC 2021-10-12 12:09:33.539+11:00 rebalancing mesh                           tid=3578495 file=behavior.nim:258 mesh=0 gossipsub=0 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:33.539+11:00 replenishing mesh                          tid=3578495 file=behavior.nim:267 peers=0 mesh=0 gossipsub=0 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:33.539+11:00 grafting                                   tid=3578495 file=behavior.nim:291 grafting=0 mesh=0 gossipsub=0 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:33.539+11:00 mesh balanced                              tid=3578495 file=behavior.nim:450 mesh=0 gossipsub=0 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:33.539+11:00 getting gossip peers (iHave)               tid=3578495 file=behavior.nim:499 ntopics=0
INF 2021-10-12 12:09:33.539+11:00 relay started successfully                 topics="wakunode" tid=3578495 file=wakunode2.nim:482
INF 2021-10-12 12:09:33.539+11:00 Node started successfully                  topics="wakunode" tid=3578495 file=wakunode2.nim:664
INF 2021-10-12 12:09:33.539+11:00 connectToNodes                             topics="wakunode" tid=3578495 file=wakunode2.nim:621 node=/ip4/127.0.0.1/tcp/35071/p2p/QmYcZdJFTxHH83gZcbHkgZcP8v3GBfVPU2hBQTCokfeH1F
INF 2021-10-12 12:09:33.539+11:00 dialPeer                                   topics="wakunode" tid=3578495 file=wakunode2.nim:589 address=/ip4/127.0.0.1/tcp/35071/p2p/QmYcZdJFTxHH83gZcbHkgZcP8v3GBfVPU2hBQTCokfeH1F
INF 2021-10-12 12:09:33.539+11:00 Dialing peer                               topics="wakunode" tid=3578495 file=wakunode2.nim:593 wireAddr=/ip4/127.0.0.1/tcp/35071 peerId=QmY*kfeH1F
TRC 2021-10-12 12:09:33.539+11:00 Adding newly dialed peer to manager        topics="wakupeers" tid=3578495 file=peer_manager.nim:241 peerId=QmY*kfeH1F addr=/ip4/127.0.0.1/tcp/35071 proto=/vac/waku/relay/2.0.0
DBG 2021-10-12 12:09:33.539+11:00 Adding peer to manager                     topics="wakupeers" tid=3578495 file=peer_manager.nim:172 peerId=QmY*kfeH1F addr=/ip4/127.0.0.1/tcp/35071 proto=/vac/waku/relay/2.0.0
INF 2021-10-12 12:09:33.539+11:00 Dialing peer from manager                  topics="wakupeers" tid=3578495 file=peer_manager.nim:49 wireAddr=/ip4/127.0.0.1/tcp/35071 peerId=QmY*kfeH1F
TRC 2021-10-12 12:09:33.539+11:00 Dialing (new)                              topics="libp2p dialer" tid=3578495 file=dialer.nim:213 peerId=QmY*kfeH1F protos="@[\"/vac/waku/relay/2.0.0\"]"
TRC 2021-10-12 12:09:33.539+11:00 connection not found                       topics="libp2p connmanager" tid=3578495 file=connmanager.nim:362 peerId=QmY*kfeH1F
DBG 2021-10-12 12:09:33.539+11:00 Dialing peer                               topics="libp2p dialer" tid=3578495 file=dialer.nim:50 peerId=QmY*kfeH1F
TRC 2021-10-12 12:09:33.539+11:00 Dialing address                            topics="libp2p dialer" tid=3578495 file=dialer.nim:62 address=/ip4/127.0.0.1/tcp/35071 peerId=QmY*kfeH1F
TRC 2021-10-12 12:09:33.539+11:00 Tracking outgoing connection               topics="libp2p connmanager" tid=3578495 file=connmanager.nim:470 count=49 max=50
TRC 2021-10-12 12:09:33.539+11:00 Acquired slot                              topics="libp2p semaphore" tid=3578495 file=semaphore.nim:38 available=48 queue=0
TRC 2021-10-12 12:09:33.539+11:00 Dialing remote peer                        topics="libp2p tcptransport" tid=3578495 file=tcptransport.nim:213 address=/ip4/127.0.0.1/tcp/35071
TRC 2021-10-12 12:09:33.539+11:00 Handling tcp connection                    topics="libp2p tcptransport" tid=3578495 file=tcptransport.nim:79 address=/ip4/127.0.0.1/tcp/35071 dir=Out clients=0
TRC 2021-10-12 12:09:33.539+11:00 Stream created                             topics="libp2p lpstream" tid=3578495 file=lpstream.nim:133 s=6164e04dbc59820630030e21 objName=ChronosStream dir=Out
TRC 2021-10-12 12:09:33.539+11:00 Monitoring for timeout                     topics="libp2p connection" tid=3578495 file=connection.nim:81 s=6164e04dbc59820630030e21 timeout=10m0ns
TRC 2021-10-12 12:09:33.539+11:00 Got connection                             topics="libp2p connmanager" tid=3578495 file=connmanager.nim:420 conn=6164e04dbc59820630030e21
TRC 2021-10-12 12:09:33.539+11:00 Upgrading outgoing connection              topics="libp2p muxedupgrade" tid=3578495 file=muxedupgrade.nim:82 conn=QmY*kfeH1F:6164e04dbc59820630030e21
TRC 2021-10-12 12:09:33.539+11:00 initiating handshake                       topics="libp2p multistream" tid=3578495 file=multistream.nim:59 conn=QmY*kfeH1F:6164e04dbc59820630030e21 codec="\x13/multistream/1.0.0\n"
TRC 2021-10-12 12:09:33.539+11:00 selecting proto                            topics="libp2p multistream" tid=3578495 file=multistream.nim:63 conn=QmY*kfeH1F:6164e04dbc59820630030e21 proto=/noise
TRC 2021-10-12 12:09:33.546+11:00 multistream handshake success              topics="libp2p multistream" tid=3578495 file=multistream.nim:73 conn=QmY*kfeH1F:6164e04dbc59820630030e21
TRC 2021-10-12 12:09:33.549+11:00 reading first requested proto              topics="libp2p multistream" tid=3578495 file=multistream.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e21
TRC 2021-10-12 12:09:33.549+11:00 successfully selected                      topics="libp2p multistream" tid=3578495 file=multistream.nim:82 conn=QmY*kfeH1F:6164e04dbc59820630030e21 proto=/noise
TRC 2021-10-12 12:09:33.549+11:00 Securing connection                        topics="libp2p upgrade" tid=3578495 file=upgrade.nim:58 conn=QmY*kfeH1F:6164e04dbc59820630030e21 codec=/noise
TRC 2021-10-12 12:09:33.549+11:00 Starting Noise handshake                   topics="libp2p noise" tid=3578495 file=noise.nim:501 conn=QmY*kfeH1F:6164e04dbc59820630030e21 initiator=true
TRC 2021-10-12 12:09:33.549+11:00 mixHash                                    topics="libp2p noise" tid=3578495 file=noise.nim:198 hash=f3d15e6108ed...2e0958dc002d
TRC 2021-10-12 12:09:33.549+11:00 noise write e                              topics="libp2p noise" tid=3578495 file=noise.nim:237
TRC 2021-10-12 12:09:33.549+11:00 mixHash                                    topics="libp2p noise" tid=3578495 file=noise.nim:198 hash=315614c5150b...46033b996989
TRC 2021-10-12 12:09:33.549+11:00 mixHash                                    topics="libp2p noise" tid=3578495 file=noise.nim:198 hash=c6b0e485bed5...71a7b2f7a49a
TRC 2021-10-12 12:09:33.549+11:00 writeFrame                                 topics="libp2p noise" tid=3578495 file=noise.nim:323 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=32 data=f228be5f156a...e6114f45f31a
TRC 2021-10-12 12:09:33.561+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=659
TRC 2021-10-12 12:09:33.561+11:00 noise read e                               topics="libp2p noise" tid=3578495 file=noise.nim:276 size=659
TRC 2021-10-12 12:09:33.561+11:00 mixHash                                    topics="libp2p noise" tid=3578495 file=noise.nim:198 hash=199e26c0026d...6d44b23fdd1e
TRC 2021-10-12 12:09:33.561+11:00 noise dh ee                                topics="libp2p noise" tid=3578495 file=noise.nim:249
TRC 2021-10-12 12:09:33.561+11:00 mixKey                                     topics="libp2p noise" tid=3578495 file=noise.nim:190 key=34cc9f452e75...079a4beaf908
TRC 2021-10-12 12:09:33.561+11:00 noise read s                               topics="libp2p noise" tid=3578495 file=noise.nim:287 size=627
TRC 2021-10-12 12:09:33.561+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=6bbde281ec8e...d127004f39cf tagOut=6bbde281ec8e...d127004f39cf nonce=0
TRC 2021-10-12 12:09:33.561+11:00 mixHash                                    topics="libp2p noise" tid=3578495 file=noise.nim:198 hash=8eb3dd8a4244...9514d0e32974
TRC 2021-10-12 12:09:33.561+11:00 noise dh es                                topics="libp2p noise" tid=3578495 file=noise.nim:254
TRC 2021-10-12 12:09:33.561+11:00 mixKey                                     topics="libp2p noise" tid=3578495 file=noise.nim:190 key=b7299ad95c0a...5136b71502f5
TRC 2021-10-12 12:09:33.561+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=cbc6aaa115ab...10c7580ee1be tagOut=cbc6aaa115ab...10c7580ee1be nonce=0
TRC 2021-10-12 12:09:33.561+11:00 mixHash                                    topics="libp2p noise" tid=3578495 file=noise.nim:198 hash=87aff8a34528...616e0743dd83
TRC 2021-10-12 12:09:33.561+11:00 noise write s                              topics="libp2p noise" tid=3578495 file=noise.nim:244
TRC 2021-10-12 12:09:33.561+11:00 encryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:157 tag=b9d8968535f5ff113a9346e4045f2eff data=205f443a9158...46e4045f2eff nonce=1
TRC 2021-10-12 12:09:33.561+11:00 mixHash                                    topics="libp2p noise" tid=3578495 file=noise.nim:198 hash=4d7e06bdc10e...8281ce13558b
TRC 2021-10-12 12:09:33.561+11:00 noise dh se                                topics="libp2p noise" tid=3578495 file=noise.nim:262
TRC 2021-10-12 12:09:33.562+11:00 mixKey                                     topics="libp2p noise" tid=3578495 file=noise.nim:190 key=5e0828faab0c...74d0e82f84b0
TRC 2021-10-12 12:09:33.562+11:00 encryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:157 tag=e4901e65d6da3f66d6091b67def2da04 data=3ecf4ace35fa...1b67def2da04 nonce=0
TRC 2021-10-12 12:09:33.562+11:00 mixHash                                    topics="libp2p noise" tid=3578495 file=noise.nim:198 hash=fb82cac10bbc...b7c89489b636
TRC 2021-10-12 12:09:33.562+11:00 writeFrame                                 topics="libp2p noise" tid=3578495 file=noise.nim:323 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=175 data=205f443a9158...1b67def2da04
TRC 2021-10-12 12:09:33.562+11:00 Remote signature verified                  topics="libp2p noise" tid=3578495 file=noise.nim:548 conn=QmY*kfeH1F:6164e04dbc59820630030e21
TRC 2021-10-12 12:09:33.562+11:00 Stream created                             topics="libp2p lpstream" tid=3578495 file=lpstream.nim:133 s=6164e04dbc59820630030e22 objName=SecureConn dir=Out
TRC 2021-10-12 12:09:33.562+11:00 Monitoring for timeout                     topics="libp2p connection" tid=3578495 file=connection.nim:81 s=QmY*kfeH1F:6164e04dbc59820630030e22 timeout=5m0ns
TRC 2021-10-12 12:09:33.562+11:00 Noise handshake completed!                 topics="libp2p noise" tid=3578495 file=noise.nim:582 initiator=true peer="(peerId: \"QmYcZdJFTxHH83gZcbHkgZcP8v3GBfVPU2hBQTCokfeH1F\", addrs: @[\"/ip4/127.0.0.1/tcp/35071\"], protocols: @[], protoVersion: \"\", agentVersion: \"\")"
TRC 2021-10-12 12:09:33.562+11:00 Muxing connection                          topics="libp2p muxedupgrade" tid=3578495 file=muxedupgrade.nim:46 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.562+11:00 initiating handshake                       topics="libp2p multistream" tid=3578495 file=multistream.nim:59 conn=QmY*kfeH1F:6164e04dbc59820630030e22 codec="\x13/multistream/1.0.0\n"
TRC 2021-10-12 12:09:33.562+11:00 selecting proto                            topics="libp2p multistream" tid=3578495 file=multistream.nim:63 conn=QmY*kfeH1F:6164e04dbc59820630030e22 proto=/mplex/6.7.0
TRC 2021-10-12 12:09:33.568+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=36
TRC 2021-10-12 12:09:33.569+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=1133d2225a4e...6aa96b0bc7c9 tagOut=1133d2225a4e...6aa96b0bc7c9 nonce=0
TRC 2021-10-12 12:09:33.569+11:00 multistream handshake success              topics="libp2p multistream" tid=3578495 file=multistream.nim:73 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.572+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=30
TRC 2021-10-12 12:09:33.572+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=4ca23a0ac872...805ab3d7928d tagOut=4ca23a0ac872...805ab3d7928d nonce=1
TRC 2021-10-12 12:09:33.572+11:00 reading first requested proto              topics="libp2p multistream" tid=3578495 file=multistream.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.572+11:00 successfully selected                      topics="libp2p multistream" tid=3578495 file=multistream.nim:82 conn=QmY*kfeH1F:6164e04dbc59820630030e22 proto=/mplex/6.7.0
TRC 2021-10-12 12:09:33.572+11:00 Found a muxer                              topics="libp2p muxedupgrade" tid=3578495 file=muxedupgrade.nim:56 conn=QmY*kfeH1F:6164e04dbc59820630030e22 muxerName=/mplex/6.7.0
TRC 2021-10-12 12:09:33.572+11:00 Stored connection                          topics="libp2p connmanager" tid=3578495 file=connmanager.nim:406 conn=QmY*kfeH1F:6164e04dbc59820630030e22 direction=Out connections=1
TRC 2021-10-12 12:09:33.572+11:00 Starting mplex handler                     topics="libp2p mplex" tid=3578495 file=mplex.nim:125 m=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.572+11:00 waiting for data                           topics="libp2p mplex" tid=3578495 file=mplex.nim:128 m=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.572+11:00 Stored muxer                               topics="libp2p connmanager" tid=3578495 file=connmanager.nim:511 muxer=QmY*kfeH1F:6164e04dbc59820630030e22 handle=true connections=1
TRC 2021-10-12 12:09:33.572+11:00 Triggering connect events                  topics="libp2p connmanager" tid=3578495 file=connmanager.nim:293 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.572+11:00 About to trigger peer events               topics="libp2p connmanager" tid=3578495 file=connmanager.nim:185 peer=QmY*kfeH1F
TRC 2021-10-12 12:09:33.572+11:00 triggering peer events                     topics="libp2p connmanager" tid=3578495 file=connmanager.nim:198 peer=QmY*kfeH1F event="(kind: Joined, initiator: true)"
DBG 2021-10-12 12:09:33.572+11:00 created new pubsub peer                    topics="libp2p pubsub" tid=3578495 file=pubsub.nim:287 peerId=QmY*kfeH1F
TRC 2021-10-12 12:09:33.572+11:00 Dialing (existing)                         topics="libp2p dialer" tid=3578495 file=dialer.nim:185 peerId=QmY*kfeH1F protos="@[\"/vac/waku/relay/2.0.0\", \"/vac/waku/relay/2.0.0\"]"
TRC 2021-10-12 12:09:33.572+11:00 Stream created                             topics="libp2p lpstream" tid=3578495 file=lpstream.nim:133 s=6164e04dbc59820630030e24 objName=LPChannel dir=Out
TRC 2021-10-12 12:09:33.572+11:00 Monitoring for timeout                     topics="libp2p connection" tid=3578495 file=connection.nim:81 s=6164e04dbc59820630030e24 timeout=5m0ns
TRC 2021-10-12 12:09:33.572+11:00 BufferStream created                       topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:59 s=6164e04dbc59820630030e24
TRC 2021-10-12 12:09:33.572+11:00 Created new lpchannel                      topics="libp2p mplex" tid=3578495 file=lpchannel.nim:231 s=QmY*kfeH1F:6164e04dbc59820630030e24 id=1 initiator=true
TRC 2021-10-12 12:09:33.572+11:00 Creating new channel                       topics="libp2p mplex" tid=3578495 file=mplex.nim:101 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e24 id=1 initiator=true name=
TRC 2021-10-12 12:09:33.572+11:00 Opening channel                            topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:67 s=QmY*kfeH1F:6164e04dbc59820630030e24 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.572+11:00 writing mplex message                      topics="libp2p mplexcoder" tid=3578495 file=coder.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e22 id=1 msgType=New data=24 encoded=26
TRC 2021-10-12 12:09:33.572+11:00 About to trigger connection events         topics="libp2p connmanager" tid=3578495 file=connmanager.nim:139 peer=QmY*kfeH1F
TRC 2021-10-12 12:09:33.572+11:00 triggering connection events               topics="libp2p connmanager" tid=3578495 file=connmanager.nim:141 peer=QmY*kfeH1F event=Connected
TRC 2021-10-12 12:09:33.572+11:00 Stream created                             topics="libp2p lpstream" tid=3578495 file=lpstream.nim:133 s=6164e04dbc59820630030e25 objName=LPChannel dir=Out
TRC 2021-10-12 12:09:33.572+11:00 Monitoring for timeout                     topics="libp2p connection" tid=3578495 file=connection.nim:81 s=6164e04dbc59820630030e25 timeout=5m0ns
TRC 2021-10-12 12:09:33.572+11:00 BufferStream created                       topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:59 s=6164e04dbc59820630030e25
TRC 2021-10-12 12:09:33.572+11:00 Created new lpchannel                      topics="libp2p mplex" tid=3578495 file=lpchannel.nim:231 s=QmY*kfeH1F:6164e04dbc59820630030e25 id=2 initiator=true
TRC 2021-10-12 12:09:33.572+11:00 Creating new channel                       topics="libp2p mplex" tid=3578495 file=mplex.nim:101 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e25 id=2 initiator=true name=
TRC 2021-10-12 12:09:33.572+11:00 Opening channel                            topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:67 s=QmY*kfeH1F:6164e04dbc59820630030e25 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.572+11:00 writing mplex message                      topics="libp2p mplexcoder" tid=3578495 file=coder.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e22 id=2 msgType=New data=24 encoded=26
TRC 2021-10-12 12:09:33.572+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=57
TRC 2021-10-12 12:09:33.572+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=285591fb260e...ac57fee7e0a7 tagOut=285591fb260e...ac57fee7e0a7 nonce=2
TRC 2021-10-12 12:09:33.572+11:00 Negotiating stream                         topics="libp2p dialer" tid=3578495 file=dialer.nim:169 conn=QmY*kfeH1F:6164e04dbc59820630030e24 protos="@[\"/vac/waku/relay/2.0.0\", \"/vac/waku/relay/2.0.0\"]"
TRC 2021-10-12 12:09:33.572+11:00 initiating handshake                       topics="libp2p multistream" tid=3578495 file=multistream.nim:59 conn=QmY*kfeH1F:6164e04dbc59820630030e24 codec="\x13/multistream/1.0.0\n"
TRC 2021-10-12 12:09:33.572+11:00 write msg                                  topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:194 s=QmY*kfeH1F:6164e04dbc59820630030e24 conn=QmY*kfeH1F:6164e04dbc59820630030e22 len=20
TRC 2021-10-12 12:09:33.572+11:00 writing mplex message                      topics="libp2p mplexcoder" tid=3578495 file=coder.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e22 id=1 msgType=MsgOut data=20 encoded=22
TRC 2021-10-12 12:09:33.572+11:00 initiating handshake                       topics="libp2p multistream" tid=3578495 file=multistream.nim:59 conn=QmY*kfeH1F:6164e04dbc59820630030e25 codec="\x13/multistream/1.0.0\n"
TRC 2021-10-12 12:09:33.572+11:00 write msg                                  topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:194 s=QmY*kfeH1F:6164e04dbc59820630030e25 conn=QmY*kfeH1F:6164e04dbc59820630030e22 len=20
TRC 2021-10-12 12:09:33.572+11:00 writing mplex message                      topics="libp2p mplexcoder" tid=3578495 file=coder.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e22 id=2 msgType=MsgOut data=20 encoded=22
TRC 2021-10-12 12:09:33.572+11:00 read header varint                         topics="libp2p mplexcoder" tid=3578495 file=coder.nim:47 varint=0 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.572+11:00 read data                                  topics="libp2p mplexcoder" tid=3578495 file=coder.nim:50 dataLen=1 data=30 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.572+11:00 read message from connection               topics="libp2p mplex" tid=3578495 file=mplex.nim:139 m=QmY*kfeH1F:6164e04dbc59820630030e22 data=30 msgType=New id=0 initiator=false size=1
TRC 2021-10-12 12:09:33.572+11:00 Stream created                             topics="libp2p lpstream" tid=3578495 file=lpstream.nim:133 s=6164e04dbc59820630030e26 objName=LPChannel dir=In
TRC 2021-10-12 12:09:33.572+11:00 Monitoring for timeout                     topics="libp2p connection" tid=3578495 file=connection.nim:81 s=6164e04dbc59820630030e26 timeout=5m0ns
TRC 2021-10-12 12:09:33.572+11:00 BufferStream created                       topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:59 s=6164e04dbc59820630030e26
TRC 2021-10-12 12:09:33.572+11:00 Created new lpchannel                      topics="libp2p mplex" tid=3578495 file=lpchannel.nim:231 s=QmY*kfeH1F:6164e04dbc59820630030e26:0 id=0 initiator=false
TRC 2021-10-12 12:09:33.572+11:00 Creating new channel                       topics="libp2p mplex" tid=3578495 file=mplex.nim:101 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e26:0 id=0 initiator=false name=0
TRC 2021-10-12 12:09:33.572+11:00 Processing channel message                 topics="libp2p mplex" tid=3578495 file=mplex.nim:158 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e26:0 data=30 msgType=New id=0 initiator=false size=1
TRC 2021-10-12 12:09:33.572+11:00 created channel                            topics="libp2p mplex" tid=3578495 file=mplex.nim:162 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e26:0 msgType=New id=0 initiator=false size=1
TRC 2021-10-12 12:09:33.572+11:00 Starting stream handler                    tid=3578495 file=muxedupgrade.nim:213 conn=QmY*kfeH1F:6164e04dbc59820630030e26
TRC 2021-10-12 12:09:33.572+11:00 Starting multistream handler               topics="libp2p multistream" tid=3578495 file=multistream.nim:129 conn=QmY*kfeH1F:6164e04dbc59820630030e26 handshaked=false
TRC 2021-10-12 12:09:33.572+11:00 waiting for data                           topics="libp2p mplex" tid=3578495 file=mplex.nim:128 m=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.573+11:00 read header varint                         topics="libp2p mplexcoder" tid=3578495 file=coder.nim:47 varint=2 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.573+11:00 read data                                  topics="libp2p mplexcoder" tid=3578495 file=coder.nim:50 dataLen=36 data=132f6d756c74...312e302e300a conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.573+11:00 read message from connection               topics="libp2p mplex" tid=3578495 file=mplex.nim:139 m=QmY*kfeH1F:6164e04dbc59820630030e22 data=132f6d756c74...312e302e300a msgType=MsgOut id=0 initiator=false size=36
TRC 2021-10-12 12:09:33.573+11:00 Processing channel message                 topics="libp2p mplex" tid=3578495 file=mplex.nim:158 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e26:0 data=132f6d756c74...312e302e300a msgType=MsgOut id=0 initiator=false size=36
TRC 2021-10-12 12:09:33.573+11:00 pushing data to channel                    topics="libp2p mplex" tid=3578495 file=mplex.nim:175 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e26:0 len=36 msgType=MsgOut id=0 initiator=false size=36
TRC 2021-10-12 12:09:33.573+11:00 Pushing data                               topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:93 s=QmY*kfeH1F:6164e04dbc59820630030e26 data=36
TRC 2021-10-12 12:09:33.573+11:00 pushed data to channel                     topics="libp2p mplex" tid=3578495 file=mplex.nim:177 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e26:0 len=36 msgType=MsgOut id=0 initiator=false size=36
TRC 2021-10-12 12:09:33.573+11:00 waiting for data                           topics="libp2p mplex" tid=3578495 file=mplex.nim:128 m=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.573+11:00 add leftovers                              topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:163 s=QmY*kfeH1F:6164e04dbc59820630030e26 len=35
TRC 2021-10-12 12:09:33.573+11:00 selecting proto                            topics="libp2p multistream" tid=3578495 file=multistream.nim:63 conn=QmY*kfeH1F:6164e04dbc59820630030e24 proto=/vac/waku/relay/2.0.0
TRC 2021-10-12 12:09:33.573+11:00 write msg                                  topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:194 s=QmY*kfeH1F:6164e04dbc59820630030e24 conn=QmY*kfeH1F:6164e04dbc59820630030e22 len=23
TRC 2021-10-12 12:09:33.573+11:00 writing mplex message                      topics="libp2p mplexcoder" tid=3578495 file=coder.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e22 id=1 msgType=MsgOut data=23 encoded=25
TRC 2021-10-12 12:09:33.573+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e26:0 bytes=1
TRC 2021-10-12 12:09:33.573+11:00 selecting proto                            topics="libp2p multistream" tid=3578495 file=multistream.nim:63 conn=QmY*kfeH1F:6164e04dbc59820630030e25 proto=/ipfs/id/1.0.0
TRC 2021-10-12 12:09:33.573+11:00 write msg                                  topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:194 s=QmY*kfeH1F:6164e04dbc59820630030e25 conn=QmY*kfeH1F:6164e04dbc59820630030e22 len=16
TRC 2021-10-12 12:09:33.573+11:00 writing mplex message                      topics="libp2p mplexcoder" tid=3578495 file=coder.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e22 id=2 msgType=MsgOut data=16 encoded=18
TRC 2021-10-12 12:09:33.573+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e26:0 bytes=19
TRC 2021-10-12 12:09:33.573+11:00 handle: got request                        topics="libp2p multistream" tid=3578495 file=multistream.nim:141 conn=QmY*kfeH1F:6164e04dbc59820630030e26 ms=/multistream/1.0.0
TRC 2021-10-12 12:09:33.573+11:00 write msg                                  topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:194 s=QmY*kfeH1F:6164e04dbc59820630030e26:0 conn=QmY*kfeH1F:6164e04dbc59820630030e22 len=20
TRC 2021-10-12 12:09:33.573+11:00 writing mplex message                      topics="libp2p mplexcoder" tid=3578495 file=coder.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e22 id=0 msgType=MsgIn data=20 encoded=22
TRC 2021-10-12 12:09:33.573+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e26:0 bytes=1
TRC 2021-10-12 12:09:33.573+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e26:0 bytes=15
TRC 2021-10-12 12:09:33.573+11:00 handle: got request                        topics="libp2p multistream" tid=3578495 file=multistream.nim:141 conn=QmY*kfeH1F:6164e04dbc59820630030e26 ms=/ipfs/id/1.0.0
TRC 2021-10-12 12:09:33.573+11:00 found handler                              topics="libp2p multistream" tid=3578495 file=multistream.nim:170 conn=QmY*kfeH1F:6164e04dbc59820630030e26 protocol=/ipfs/id/1.0.0
TRC 2021-10-12 12:09:33.573+11:00 write msg                                  topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:194 s=QmY*kfeH1F:6164e04dbc59820630030e26:0 conn=QmY*kfeH1F:6164e04dbc59820630030e22 len=16
TRC 2021-10-12 12:09:33.573+11:00 writing mplex message                      topics="libp2p mplexcoder" tid=3578495 file=coder.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e22 id=0 msgType=MsgIn data=16 encoded=18
TRC 2021-10-12 12:09:33.573+11:00 handling identify request                  topics="libp2p identify" tid=3578495 file=identify.nim:125 conn=QmY*kfeH1F:6164e04dbc59820630030e26
TRC 2021-10-12 12:09:33.573+11:00 write msg                                  topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:194 s=QmY*kfeH1F:6164e04dbc59820630030e26:0 conn=QmY*kfeH1F:6164e04dbc59820630030e22 len=205
TRC 2021-10-12 12:09:33.573+11:00 writing mplex message                      topics="libp2p mplexcoder" tid=3578495 file=coder.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e22 id=0 msgType=MsgIn data=205 encoded=208
TRC 2021-10-12 12:09:33.573+11:00 exiting identify handler                   topics="libp2p identify" tid=3578495 file=identify.nim:133 conn=QmY*kfeH1F:6164e04dbc59820630030e26
TRC 2021-10-12 12:09:33.573+11:00 Closing with EOF                           topics="libp2p lpstream" tid=3578495 file=lpstream.nim:298 s=6164e04dbc59820630030e26
TRC 2021-10-12 12:09:33.573+11:00 Closing channel                            topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:122 s=QmY*kfeH1F:6164e04dbc59820630030e26:0 conn=QmY*kfeH1F:6164e04dbc59820630030e22 len=0
TRC 2021-10-12 12:09:33.573+11:00 writing mplex message                      topics="libp2p mplexcoder" tid=3578495 file=coder.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e22 id=0 msgType=CloseIn data=0 encoded=2
TRC 2021-10-12 12:09:33.573+11:00 Closed channel                             topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:138 s=QmY*kfeH1F:6164e04dbc59820630030e26:0 len=0
TRC 2021-10-12 12:09:33.575+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=38
TRC 2021-10-12 12:09:33.575+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=866c6be4a39b...ecb1a96d18ec tagOut=866c6be4a39b...ecb1a96d18ec nonce=3
TRC 2021-10-12 12:09:33.575+11:00 read header varint                         topics="libp2p mplexcoder" tid=3578495 file=coder.nim:47 varint=9 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.575+11:00 read data                                  topics="libp2p mplexcoder" tid=3578495 file=coder.nim:50 dataLen=20 data=132f6d756c74...312e302e300a conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.575+11:00 read message from connection               topics="libp2p mplex" tid=3578495 file=mplex.nim:139 m=QmY*kfeH1F:6164e04dbc59820630030e22 data=132f6d756c74...312e302e300a msgType=MsgIn id=1 initiator=true size=20
TRC 2021-10-12 12:09:33.575+11:00 Processing channel message                 topics="libp2p mplex" tid=3578495 file=mplex.nim:158 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e24 data=132f6d756c74...312e302e300a msgType=MsgIn id=1 initiator=true size=20
TRC 2021-10-12 12:09:33.575+11:00 pushing data to channel                    topics="libp2p mplex" tid=3578495 file=mplex.nim:175 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e24 len=20 msgType=MsgIn id=1 initiator=true size=20
TRC 2021-10-12 12:09:33.575+11:00 Pushing data                               topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:93 s=QmY*kfeH1F:6164e04dbc59820630030e24 data=20
TRC 2021-10-12 12:09:33.575+11:00 pushed data to channel                     topics="libp2p mplex" tid=3578495 file=mplex.nim:177 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e24 len=20 msgType=MsgIn id=1 initiator=true size=20
TRC 2021-10-12 12:09:33.575+11:00 waiting for data                           topics="libp2p mplex" tid=3578495 file=mplex.nim:128 m=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.575+11:00 add leftovers                              topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:163 s=QmY*kfeH1F:6164e04dbc59820630030e24 len=19
TRC 2021-10-12 12:09:33.575+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e24 bytes=1
TRC 2021-10-12 12:09:33.575+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e24 bytes=19
TRC 2021-10-12 12:09:33.575+11:00 multistream handshake success              topics="libp2p multistream" tid=3578495 file=multistream.nim:73 conn=QmY*kfeH1F:6164e04dbc59820630030e24
TRC 2021-10-12 12:09:33.575+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=38
TRC 2021-10-12 12:09:33.575+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=59960cdda6da...1463d91f6998 tagOut=59960cdda6da...1463d91f6998 nonce=4
TRC 2021-10-12 12:09:33.575+11:00 read header varint                         topics="libp2p mplexcoder" tid=3578495 file=coder.nim:47 varint=17 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.575+11:00 read data                                  topics="libp2p mplexcoder" tid=3578495 file=coder.nim:50 dataLen=20 data=132f6d756c74...312e302e300a conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.575+11:00 read message from connection               topics="libp2p mplex" tid=3578495 file=mplex.nim:139 m=QmY*kfeH1F:6164e04dbc59820630030e22 data=132f6d756c74...312e302e300a msgType=MsgIn id=2 initiator=true size=20
TRC 2021-10-12 12:09:33.575+11:00 Processing channel message                 topics="libp2p mplex" tid=3578495 file=mplex.nim:158 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e25 data=132f6d756c74...312e302e300a msgType=MsgIn id=2 initiator=true size=20
TRC 2021-10-12 12:09:33.575+11:00 pushing data to channel                    topics="libp2p mplex" tid=3578495 file=mplex.nim:175 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e25 len=20 msgType=MsgIn id=2 initiator=true size=20
TRC 2021-10-12 12:09:33.575+11:00 Pushing data                               topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:93 s=QmY*kfeH1F:6164e04dbc59820630030e25 data=20
TRC 2021-10-12 12:09:33.575+11:00 pushed data to channel                     topics="libp2p mplex" tid=3578495 file=mplex.nim:177 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e25 len=20 msgType=MsgIn id=2 initiator=true size=20
TRC 2021-10-12 12:09:33.575+11:00 waiting for data                           topics="libp2p mplex" tid=3578495 file=mplex.nim:128 m=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.575+11:00 add leftovers                              topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:163 s=QmY*kfeH1F:6164e04dbc59820630030e25 len=19
TRC 2021-10-12 12:09:33.575+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e25 bytes=1
TRC 2021-10-12 12:09:33.575+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e25 bytes=19
TRC 2021-10-12 12:09:33.575+11:00 multistream handshake success              topics="libp2p multistream" tid=3578495 file=multistream.nim:73 conn=QmY*kfeH1F:6164e04dbc59820630030e25
TRC 2021-10-12 12:09:33.617+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=41
TRC 2021-10-12 12:09:33.617+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=1159a3ec25c8...8317c693f059 tagOut=1159a3ec25c8...8317c693f059 nonce=5
TRC 2021-10-12 12:09:33.617+11:00 read header varint                         topics="libp2p mplexcoder" tid=3578495 file=coder.nim:47 varint=9 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.618+11:00 read data                                  topics="libp2p mplexcoder" tid=3578495 file=coder.nim:50 dataLen=23 data=162f7661632f...322e302e300a conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.618+11:00 read message from connection               topics="libp2p mplex" tid=3578495 file=mplex.nim:139 m=QmY*kfeH1F:6164e04dbc59820630030e22 data=162f7661632f...322e302e300a msgType=MsgIn id=1 initiator=true size=23
TRC 2021-10-12 12:09:33.618+11:00 Processing channel message                 topics="libp2p mplex" tid=3578495 file=mplex.nim:158 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e24 data=162f7661632f...322e302e300a msgType=MsgIn id=1 initiator=true size=23
TRC 2021-10-12 12:09:33.618+11:00 pushing data to channel                    topics="libp2p mplex" tid=3578495 file=mplex.nim:175 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e24 len=23 msgType=MsgIn id=1 initiator=true size=23
TRC 2021-10-12 12:09:33.618+11:00 Pushing data                               topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:93 s=QmY*kfeH1F:6164e04dbc59820630030e24 data=23
TRC 2021-10-12 12:09:33.618+11:00 pushed data to channel                     topics="libp2p mplex" tid=3578495 file=mplex.nim:177 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e24 len=23 msgType=MsgIn id=1 initiator=true size=23
TRC 2021-10-12 12:09:33.618+11:00 waiting for data                           topics="libp2p mplex" tid=3578495 file=mplex.nim:128 m=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.618+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=34
TRC 2021-10-12 12:09:33.618+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=359f3754ac99...bc9d435b73b4 tagOut=359f3754ac99...bc9d435b73b4 nonce=6
TRC 2021-10-12 12:09:33.618+11:00 read header varint                         topics="libp2p mplexcoder" tid=3578495 file=coder.nim:47 varint=17 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.618+11:00 read data                                  topics="libp2p mplexcoder" tid=3578495 file=coder.nim:50 dataLen=16 data=0f2f69706673...312e302e300a conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.618+11:00 read message from connection               topics="libp2p mplex" tid=3578495 file=mplex.nim:139 m=QmY*kfeH1F:6164e04dbc59820630030e22 data=0f2f69706673...312e302e300a msgType=MsgIn id=2 initiator=true size=16
TRC 2021-10-12 12:09:33.618+11:00 Processing channel message                 topics="libp2p mplex" tid=3578495 file=mplex.nim:158 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e25 data=0f2f69706673...312e302e300a msgType=MsgIn id=2 initiator=true size=16
TRC 2021-10-12 12:09:33.618+11:00 pushing data to channel                    topics="libp2p mplex" tid=3578495 file=mplex.nim:175 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e25 len=16 msgType=MsgIn id=2 initiator=true size=16
TRC 2021-10-12 12:09:33.618+11:00 Pushing data                               topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:93 s=QmY*kfeH1F:6164e04dbc59820630030e25 data=16
TRC 2021-10-12 12:09:33.618+11:00 pushed data to channel                     topics="libp2p mplex" tid=3578495 file=mplex.nim:177 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e25 len=16 msgType=MsgIn id=2 initiator=true size=16
TRC 2021-10-12 12:09:33.618+11:00 waiting for data                           topics="libp2p mplex" tid=3578495 file=mplex.nim:128 m=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.618+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=1180
TRC 2021-10-12 12:09:33.618+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=9c35efca2510...8558c3b37e06 tagOut=9c35efca2510...8558c3b37e06 nonce=7
TRC 2021-10-12 12:09:33.618+11:00 read header varint                         topics="libp2p mplexcoder" tid=3578495 file=coder.nim:47 varint=17 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.618+11:00 read data                                  topics="libp2p mplexcoder" tid=3578495 file=coder.nim:50 dataLen=1159 data=85090aab0208...982d6586e261 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.618+11:00 read message from connection               topics="libp2p mplex" tid=3578495 file=mplex.nim:139 m=QmY*kfeH1F:6164e04dbc59820630030e22 data=85090aab0208...982d6586e261 msgType=MsgIn id=2 initiator=true size=1159
TRC 2021-10-12 12:09:33.618+11:00 Processing channel message                 topics="libp2p mplex" tid=3578495 file=mplex.nim:158 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e25 data=85090aab0208...982d6586e261 msgType=MsgIn id=2 initiator=true size=1159
TRC 2021-10-12 12:09:33.618+11:00 pushing data to channel                    topics="libp2p mplex" tid=3578495 file=mplex.nim:175 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e25 len=1159 msgType=MsgIn id=2 initiator=true size=1159
TRC 2021-10-12 12:09:33.618+11:00 Pushing data                               topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:93 s=QmY*kfeH1F:6164e04dbc59820630030e25 data=1159
TRC 2021-10-12 12:09:33.618+11:00 add leftovers                              topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:163 s=QmY*kfeH1F:6164e04dbc59820630030e24 len=22
TRC 2021-10-12 12:09:33.618+11:00 add leftovers                              topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:163 s=QmY*kfeH1F:6164e04dbc59820630030e25 len=15
TRC 2021-10-12 12:09:33.618+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e24 bytes=1
TRC 2021-10-12 12:09:33.618+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e25 bytes=1
TRC 2021-10-12 12:09:33.618+11:00 pushed data to channel                     topics="libp2p mplex" tid=3578495 file=mplex.nim:177 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e25 len=1159 msgType=MsgIn id=2 initiator=true size=1159
TRC 2021-10-12 12:09:33.618+11:00 waiting for data                           topics="libp2p mplex" tid=3578495 file=mplex.nim:128 m=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.618+11:00 read header varint                         topics="libp2p mplexcoder" tid=3578495 file=coder.nim:47 varint=19 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.618+11:00 read data                                  topics="libp2p mplexcoder" tid=3578495 file=coder.nim:50 dataLen=0 data= conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.618+11:00 read message from connection               topics="libp2p mplex" tid=3578495 file=mplex.nim:139 m=QmY*kfeH1F:6164e04dbc59820630030e22 data= msgType=CloseIn id=2 initiator=true size=0
TRC 2021-10-12 12:09:33.618+11:00 Processing channel message                 topics="libp2p mplex" tid=3578495 file=mplex.nim:158 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e25 data= msgType=CloseIn id=2 initiator=true size=0
TRC 2021-10-12 12:09:33.618+11:00 Pushing EOF                                topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:111 s=QmY*kfeH1F:6164e04dbc59820630030e25
TRC 2021-10-12 12:09:33.618+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e24 bytes=22
TRC 2021-10-12 12:09:33.618+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e25 bytes=15
TRC 2021-10-12 12:09:33.618+11:00 reading first requested proto              topics="libp2p multistream" tid=3578495 file=multistream.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e24
TRC 2021-10-12 12:09:33.618+11:00 successfully selected                      topics="libp2p multistream" tid=3578495 file=multistream.nim:82 conn=QmY*kfeH1F:6164e04dbc59820630030e24 proto=/vac/waku/relay/2.0.0
TRC 2021-10-12 12:09:33.618+11:00 reading first requested proto              topics="libp2p multistream" tid=3578495 file=multistream.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e25
TRC 2021-10-12 12:09:33.618+11:00 successfully selected                      topics="libp2p multistream" tid=3578495 file=multistream.nim:82 conn=QmY*kfeH1F:6164e04dbc59820630030e25 proto=/ipfs/id/1.0.0
TRC 2021-10-12 12:09:33.618+11:00 initiating identify                        topics="libp2p identify" tid=3578495 file=identify.nim:142 conn=QmY*kfeH1F:6164e04dbc59820630030e25
TRC 2021-10-12 12:09:33.618+11:00 add leftovers                              topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:163 s=QmY*kfeH1F:6164e04dbc59820630030e25 len=1158
TRC 2021-10-12 12:09:33.618+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e25 bytes=1
TRC 2021-10-12 12:09:33.618+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e25 bytes=1
TRC 2021-10-12 12:09:33.618+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e25 bytes=1157
DBG 2021-10-12 12:09:33.618+11:00 decodeMsg: decoded message                 topics="libp2p identify" tid=3578495 file=identify.nim:104 pubkey="RSA ke...10001\n" addresses="@[/ip4/127.0.0.1/tcp/35071, /ip4/192.168.178.251/tcp/35071, /ip4/10.29.0.11/tcp/35071]" protocols="@[\"/libp2p/circuit/relay/0.1.0\", \"/ipfs/id/1.0.0\", \"/ipfs/id/push/1.0.0\", \"/ipfs/ping/1.0.0\", \"/vac/waku/relay/2.0.0-beta2\", \"/vac/waku/relay/2.0.0\"]" observable_address=Some(/ip4/127.0.0.1/tcp/58360) proto_version="Some(\"ipfs/0.1.0\")" agent_version="Some(\"js-libp2p/0.32.4\")"
TRC 2021-10-12 12:09:33.618+11:00 About to trigger peer events               topics="libp2p connmanager" tid=3578495 file=connmanager.nim:185 peer=QmY*kfeH1F
TRC 2021-10-12 12:09:33.618+11:00 triggering peer events                     topics="libp2p connmanager" tid=3578495 file=connmanager.nim:198 peer=QmY*kfeH1F event="(kind: Identified)"
TRC 2021-10-12 12:09:33.618+11:00 identified remote peer                     topics="libp2p upgrade" tid=3578495 file=upgrade.nim:95 conn=QmY*kfeH1F:6164e04dbc59820630030e25 peerInfo="(peerId: \"QmYcZdJFTxHH83gZcbHkgZcP8v3GBfVPU2hBQTCokfeH1F\", addrs: @[\"/ip4/127.0.0.1/tcp/35071\", \"/ip4/192.168.178.251/tcp/35071\", \"/ip4/10.29.0.11/tcp/35071\"], protocols: @[\"/libp2p/circuit/relay/0.1.0\", \"/ipfs/id/1.0.0\", \"/ipfs/id/push/1.0.0\", \"/ipfs/ping/1.0.0\", \"/vac/waku/relay/2.0.0-beta2\", \"/vac/waku/relay/2.0.0\"], protoVersion: \"ipfs/0.1.0\", agentVersion: \"js-libp2p/0.32.4\")"
TRC 2021-10-12 12:09:33.618+11:00 Get new send connection                    topics="libp2p pubsubpeer" tid=3578495 file=pubsubpeer.nim:172 p=QmY*kfeH1F newConn=QmY*kfeH1F:6164e04dbc59820630030e24
TRC 2021-10-12 12:09:33.618+11:00 sending pubsub message to peer             topics="libp2p pubsub" tid=3578495 file=pubsub.nim:125 peer=QmY*kfeH1F msg="(subscriptions: @[(subscribe: true, topic: \"/waku/2/default-waku/proto\")], messages: @[], control: (ihave: @[], iwant: @[], graft: @[], prune: @[]))"
TRC 2021-10-12 12:09:33.618+11:00 sending msg to peer                        topics="libp2p pubsubpeer" tid=3578495 file=pubsubpeer.nim:256 peer=QmY*kfeH1F rpcMsg="(subscriptions: @[(subscribe: true, topic: \"/waku/2/default-waku/proto\")], messages: @[], control: (ihave: @[], iwant: @[], graft: @[], prune: @[]))"
TRC 2021-10-12 12:09:33.618+11:00 encodeRpcMsg: encoding message             topics="pubsubprotobuf" tid=3578495 file=protobuf.nim:311 msg="(subscriptions: @[(subscribe: true, topic: \"/waku/2/default-waku/proto\")], messages: @[], control: (ihave: @[], iwant: @[], graft: @[], prune: @[]))"
TRC 2021-10-12 12:09:33.618+11:00 sending encoded msgs to peer               topics="libp2p pubsubpeer" tid=3578495 file=pubsubpeer.nim:213 conn=QmY*kfeH1F:6164e04dbc59820630030e24 encoded=0a1e0801121a...2f70726f746f
TRC 2021-10-12 12:09:33.618+11:00 write msg                                  topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:194 s=QmY*kfeH1F:6164e04dbc59820630030e24 conn=QmY*kfeH1F:6164e04dbc59820630030e22 len=33
TRC 2021-10-12 12:09:33.618+11:00 writing mplex message                      topics="libp2p mplexcoder" tid=3578495 file=coder.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e22 id=1 msgType=MsgOut data=33 encoded=35
DBG 2021-10-12 12:09:33.618+11:00 starting pubsub read loop                  topics="libp2p pubsubpeer" tid=3578495 file=pubsubpeer.nim:115 conn=QmY*kfeH1F:6164e04dbc59820630030e24 peer=QmY*kfeH1F closed=false
TRC 2021-10-12 12:09:33.618+11:00 waiting for data                           topics="libp2p pubsubpeer" tid=3578495 file=pubsubpeer.nim:120 conn=QmY*kfeH1F:6164e04dbc59820630030e24 peer=QmY*kfeH1F closed=false
TRC 2021-10-12 12:09:33.618+11:00 Closing with EOF                           topics="libp2p lpstream" tid=3578495 file=lpstream.nim:298 s=6164e04dbc59820630030e25
TRC 2021-10-12 12:09:33.619+11:00 Closing channel                            topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:122 s=QmY*kfeH1F:6164e04dbc59820630030e25 conn=QmY*kfeH1F:6164e04dbc59820630030e22 len=0
TRC 2021-10-12 12:09:33.619+11:00 writing mplex message                      topics="libp2p mplexcoder" tid=3578495 file=coder.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e22 id=2 msgType=CloseOut data=0 encoded=2
TRC 2021-10-12 12:09:33.619+11:00 waiting for data                           topics="libp2p mplex" tid=3578495 file=mplex.nim:128 m=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.619+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=18
TRC 2021-10-12 12:09:33.619+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=4490c8a3b0df...65480c3028c3 tagOut=4490c8a3b0df...65480c3028c3 nonce=8
TRC 2021-10-12 12:09:33.619+11:00 read header varint                         topics="libp2p mplexcoder" tid=3578495 file=coder.nim:47 varint=4 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.619+11:00 read data                                  topics="libp2p mplexcoder" tid=3578495 file=coder.nim:50 dataLen=0 data= conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.619+11:00 read message from connection               topics="libp2p mplex" tid=3578495 file=mplex.nim:139 m=QmY*kfeH1F:6164e04dbc59820630030e22 data= msgType=CloseOut id=0 initiator=false size=0
TRC 2021-10-12 12:09:33.619+11:00 Processing channel message                 topics="libp2p mplex" tid=3578495 file=mplex.nim:158 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e26:0 data= msgType=CloseOut id=0 initiator=false size=0
TRC 2021-10-12 12:09:33.619+11:00 Pushing EOF                                topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:111 s=QmY*kfeH1F:6164e04dbc59820630030e26
TRC 2021-10-12 12:09:33.619+11:00 waiting for data                           topics="libp2p mplex" tid=3578495 file=mplex.nim:128 m=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.619+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=70
TRC 2021-10-12 12:09:33.619+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=fe8e7851321c...8de2803d46e1 tagOut=fe8e7851321c...8de2803d46e1 nonce=9
TRC 2021-10-12 12:09:33.619+11:00 read header varint                         topics="libp2p mplexcoder" tid=3578495 file=coder.nim:47 varint=8 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.619+11:00 read data                                  topics="libp2p mplexcoder" tid=3578495 file=coder.nim:50 dataLen=1 data=31 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.619+11:00 read message from connection               topics="libp2p mplex" tid=3578495 file=mplex.nim:139 m=QmY*kfeH1F:6164e04dbc59820630030e22 data=31 msgType=New id=1 initiator=false size=1
TRC 2021-10-12 12:09:33.619+11:00 Stream created                             topics="libp2p lpstream" tid=3578495 file=lpstream.nim:133 s=6164e04dbc59820630030e27 objName=LPChannel dir=In
TRC 2021-10-12 12:09:33.619+11:00 Monitoring for timeout                     topics="libp2p connection" tid=3578495 file=connection.nim:81 s=6164e04dbc59820630030e27 timeout=5m0ns
TRC 2021-10-12 12:09:33.619+11:00 BufferStream created                       topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:59 s=6164e04dbc59820630030e27
TRC 2021-10-12 12:09:33.619+11:00 Created new lpchannel                      topics="libp2p mplex" tid=3578495 file=lpchannel.nim:231 s=QmY*kfeH1F:6164e04dbc59820630030e27:1 id=1 initiator=false
TRC 2021-10-12 12:09:33.619+11:00 Creating new channel                       topics="libp2p mplex" tid=3578495 file=mplex.nim:101 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e27:1 id=1 initiator=false name=1
TRC 2021-10-12 12:09:33.619+11:00 Processing channel message                 topics="libp2p mplex" tid=3578495 file=mplex.nim:158 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e27:1 data=31 msgType=New id=1 initiator=false size=1
TRC 2021-10-12 12:09:33.619+11:00 created channel                            topics="libp2p mplex" tid=3578495 file=mplex.nim:162 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e27:1 msgType=New id=1 initiator=false size=1
TRC 2021-10-12 12:09:33.619+11:00 Starting stream handler                    tid=3578495 file=muxedupgrade.nim:213 conn=QmY*kfeH1F:6164e04dbc59820630030e27
TRC 2021-10-12 12:09:33.619+11:00 Starting multistream handler               topics="libp2p multistream" tid=3578495 file=multistream.nim:129 conn=QmY*kfeH1F:6164e04dbc59820630030e27 handshaked=false
TRC 2021-10-12 12:09:33.619+11:00 waiting for data                           topics="libp2p mplex" tid=3578495 file=mplex.nim:128 m=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.619+11:00 read header varint                         topics="libp2p mplexcoder" tid=3578495 file=coder.nim:47 varint=10 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.619+11:00 read data                                  topics="libp2p mplexcoder" tid=3578495 file=coder.nim:50 dataLen=49 data=132f6d756c74...62657461320a conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.619+11:00 read message from connection               topics="libp2p mplex" tid=3578495 file=mplex.nim:139 m=QmY*kfeH1F:6164e04dbc59820630030e22 data=132f6d756c74...62657461320a msgType=MsgOut id=1 initiator=false size=49
TRC 2021-10-12 12:09:33.619+11:00 Processing channel message                 topics="libp2p mplex" tid=3578495 file=mplex.nim:158 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e27:1 data=132f6d756c74...62657461320a msgType=MsgOut id=1 initiator=false size=49
TRC 2021-10-12 12:09:33.619+11:00 pushing data to channel                    topics="libp2p mplex" tid=3578495 file=mplex.nim:175 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e27:1 len=49 msgType=MsgOut id=1 initiator=false size=49
TRC 2021-10-12 12:09:33.619+11:00 Pushing data                               topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:93 s=QmY*kfeH1F:6164e04dbc59820630030e27 data=49
TRC 2021-10-12 12:09:33.619+11:00 pushed data to channel                     topics="libp2p mplex" tid=3578495 file=mplex.nim:177 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e27:1 len=49 msgType=MsgOut id=1 initiator=false size=49
TRC 2021-10-12 12:09:33.619+11:00 waiting for data                           topics="libp2p mplex" tid=3578495 file=mplex.nim:128 m=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.619+11:00 EOF                                        topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:154 s=QmY*kfeH1F:6164e04dbc59820630030e26
TRC 2021-10-12 12:09:33.619+11:00 add leftovers                              topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:163 s=QmY*kfeH1F:6164e04dbc59820630030e27 len=48
TRC 2021-10-12 12:09:33.619+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e26:0 bytes=0
TRC 2021-10-12 12:09:33.619+11:00 Closing BufferStream                       topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:182 s=QmY*kfeH1F:6164e04dbc59820630030e26 len=0
TRC 2021-10-12 12:09:33.619+11:00 Closed BufferStream                        topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:218 s=QmY*kfeH1F:6164e04dbc59820630030e26
TRC 2021-10-12 12:09:33.619+11:00 Closing connection                         topics="libp2p connection" tid=3578495 file=connection.nim:91 s=QmY*kfeH1F:6164e04dbc59820630030e26
TRC 2021-10-12 12:09:33.619+11:00 Closed connection                          topics="libp2p connection" tid=3578495 file=connection.nim:101 s=QmY*kfeH1F:6164e04dbc59820630030e26
TRC 2021-10-12 12:09:33.619+11:00 Closing stream                             topics="libp2p lpstream" tid=3578495 file=lpstream.nim:266 s=6164e04dbc59820630030e26 objName=LPChannel dir=In
TRC 2021-10-12 12:09:33.619+11:00 Closed stream                              topics="libp2p lpstream" tid=3578495 file=lpstream.nim:270 s=6164e04dbc59820630030e26 objName=LPChannel dir=In
TRC 2021-10-12 12:09:33.619+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e27:1 bytes=1
TRC 2021-10-12 12:09:33.619+11:00 sent pubsub message to remote              topics="libp2p pubsubpeer" tid=3578495 file=pubsubpeer.nim:219 conn=QmY*kfeH1F:6164e04dbc59820630030e24
TRC 2021-10-12 12:09:33.619+11:00 Closed channel                             topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:138 s=QmY*kfeH1F:6164e04dbc59820630030e25 len=0
TRC 2021-10-12 12:09:33.619+11:00 cleaned up channel                         topics="libp2p mplex" tid=3578495 file=mplex.nim:66 m=QmY*kfeH1F:6164e04dbc59820630030e22 chann=QmY*kfeH1F:6164e04dbc59820630030e26:0
TRC 2021-10-12 12:09:33.619+11:00 EOF                                        topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:154 s=QmY*kfeH1F:6164e04dbc59820630030e25
TRC 2021-10-12 12:09:33.619+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e25 bytes=0
TRC 2021-10-12 12:09:33.619+11:00 Closing BufferStream                       topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:182 s=QmY*kfeH1F:6164e04dbc59820630030e25 len=0
TRC 2021-10-12 12:09:33.619+11:00 Closed BufferStream                        topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:218 s=QmY*kfeH1F:6164e04dbc59820630030e25
TRC 2021-10-12 12:09:33.619+11:00 Closing connection                         topics="libp2p connection" tid=3578495 file=connection.nim:91 s=QmY*kfeH1F:6164e04dbc59820630030e25
TRC 2021-10-12 12:09:33.619+11:00 Closed connection                          topics="libp2p connection" tid=3578495 file=connection.nim:101 s=QmY*kfeH1F:6164e04dbc59820630030e25
TRC 2021-10-12 12:09:33.619+11:00 Closing stream                             topics="libp2p lpstream" tid=3578495 file=lpstream.nim:266 s=6164e04dbc59820630030e25 objName=LPChannel dir=Out
TRC 2021-10-12 12:09:33.619+11:00 Closed stream                              topics="libp2p lpstream" tid=3578495 file=lpstream.nim:270 s=6164e04dbc59820630030e25 objName=LPChannel dir=Out
TRC 2021-10-12 12:09:33.619+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e27:1 bytes=19
TRC 2021-10-12 12:09:33.619+11:00 cleaned up channel                         topics="libp2p mplex" tid=3578495 file=mplex.nim:66 m=QmY*kfeH1F:6164e04dbc59820630030e22 chann=QmY*kfeH1F:6164e04dbc59820630030e25
TRC 2021-10-12 12:09:33.619+11:00 Already closed                             topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:118 s=QmY*kfeH1F:6164e04dbc59820630030e26:0
TRC 2021-10-12 12:09:33.619+11:00 handle: got request                        topics="libp2p multistream" tid=3578495 file=multistream.nim:141 conn=QmY*kfeH1F:6164e04dbc59820630030e27 ms=/multistream/1.0.0
TRC 2021-10-12 12:09:33.619+11:00 write msg                                  topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:194 s=QmY*kfeH1F:6164e04dbc59820630030e27:1 conn=QmY*kfeH1F:6164e04dbc59820630030e22 len=20
TRC 2021-10-12 12:09:33.619+11:00 writing mplex message                      topics="libp2p mplexcoder" tid=3578495 file=coder.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e22 id=1 msgType=MsgIn data=20 encoded=22
TRC 2021-10-12 12:09:33.619+11:00 Closing with EOF                           topics="libp2p lpstream" tid=3578495 file=lpstream.nim:298 s=6164e04dbc59820630030e26
TRC 2021-10-12 12:09:33.619+11:00 Already closed                             topics="libp2p lpstream" tid=3578495 file=lpstream.nim:300
TRC 2021-10-12 12:09:33.619+11:00 Stream handler done                        tid=3578495 file=muxedupgrade.nim:222 conn=QmY*kfeH1F:6164e04dbc59820630030e26
TRC 2021-10-12 12:09:33.619+11:00 Upgraded outgoing connection               topics="libp2p muxedupgrade" tid=3578495 file=muxedupgrade.nim:104 conn=QmY*kfeH1F:6164e04dbc59820630030e21 sconn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.619+11:00 finished handling stream                   topics="libp2p mplex" tid=3578495 file=mplex.nim:118 m=QmY*kfeH1F:6164e04dbc59820630030e22 chann=QmY*kfeH1F:6164e04dbc59820630030e26:0
DBG 2021-10-12 12:09:33.619+11:00 Dial successful                            topics="libp2p dialer" tid=3578495 file=dialer.nim:102 conn=QmY*kfeH1F:6164e04dbc59820630030e22 peerInfo="(peerId: \"QmYcZdJFTxHH83gZcbHkgZcP8v3GBfVPU2hBQTCokfeH1F\", addrs: @[\"/ip4/127.0.0.1/tcp/35071\", \"/ip4/192.168.178.251/tcp/35071\", \"/ip4/10.29.0.11/tcp/35071\"], protocols: @[\"/libp2p/circuit/relay/0.1.0\", \"/ipfs/id/1.0.0\", \"/ipfs/id/push/1.0.0\", \"/ipfs/ping/1.0.0\", \"/vac/waku/relay/2.0.0-beta2\", \"/vac/waku/relay/2.0.0\"], protoVersion: \"ipfs/0.1.0\", agentVersion: \"js-libp2p/0.32.4\")"
TRC 2021-10-12 12:09:33.619+11:00 Opening stream                             topics="libp2p dialer" tid=3578495 file=dialer.nim:215 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.619+11:00 Stream created                             topics="libp2p lpstream" tid=3578495 file=lpstream.nim:133 s=6164e04dbc59820630030e28 objName=LPChannel dir=Out
TRC 2021-10-12 12:09:33.619+11:00 Monitoring for timeout                     topics="libp2p connection" tid=3578495 file=connection.nim:81 s=6164e04dbc59820630030e28 timeout=5m0ns
TRC 2021-10-12 12:09:33.619+11:00 BufferStream created                       topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:59 s=6164e04dbc59820630030e28
TRC 2021-10-12 12:09:33.619+11:00 Created new lpchannel                      topics="libp2p mplex" tid=3578495 file=lpchannel.nim:231 s=QmY*kfeH1F:6164e04dbc59820630030e28 id=3 initiator=true
TRC 2021-10-12 12:09:33.620+11:00 Creating new channel                       topics="libp2p mplex" tid=3578495 file=mplex.nim:101 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e28 id=3 initiator=true name=
TRC 2021-10-12 12:09:33.620+11:00 Opening channel                            topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:67 s=QmY*kfeH1F:6164e04dbc59820630030e28 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.620+11:00 writing mplex message                      topics="libp2p mplexcoder" tid=3578495 file=coder.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e22 id=3 msgType=New data=24 encoded=26
TRC 2021-10-12 12:09:33.620+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e27:1 bytes=1
TRC 2021-10-12 12:09:33.620+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e27:1 bytes=28
TRC 2021-10-12 12:09:33.620+11:00 handle: got request                        topics="libp2p multistream" tid=3578495 file=multistream.nim:141 conn=QmY*kfeH1F:6164e04dbc59820630030e27 ms=/vac/waku/relay/2.0.0-beta2
DBG 2021-10-12 12:09:33.620+11:00 no handlers                                topics="libp2p multistream" tid=3578495 file=multistream.nim:174 conn=QmY*kfeH1F:6164e04dbc59820630030e27 protocol=/vac/waku/relay/2.0.0-beta2
TRC 2021-10-12 12:09:33.620+11:00 write msg                                  topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:194 s=QmY*kfeH1F:6164e04dbc59820630030e27:1 conn=QmY*kfeH1F:6164e04dbc59820630030e22 len=4
TRC 2021-10-12 12:09:33.620+11:00 writing mplex message                      topics="libp2p mplexcoder" tid=3578495 file=coder.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e22 id=1 msgType=MsgIn data=4 encoded=6
TRC 2021-10-12 12:09:33.620+11:00 Negotiating stream                         topics="libp2p dialer" tid=3578495 file=dialer.nim:169 conn=QmY*kfeH1F:6164e04dbc59820630030e28 protos="@[\"/vac/waku/relay/2.0.0\"]"
TRC 2021-10-12 12:09:33.620+11:00 initiating handshake                       topics="libp2p multistream" tid=3578495 file=multistream.nim:59 conn=QmY*kfeH1F:6164e04dbc59820630030e28 codec="\x13/multistream/1.0.0\n"
TRC 2021-10-12 12:09:33.620+11:00 write msg                                  topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:194 s=QmY*kfeH1F:6164e04dbc59820630030e28 conn=QmY*kfeH1F:6164e04dbc59820630030e22 len=20
TRC 2021-10-12 12:09:33.620+11:00 writing mplex message                      topics="libp2p mplexcoder" tid=3578495 file=coder.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e22 id=3 msgType=MsgOut data=20 encoded=22
TRC 2021-10-12 12:09:33.620+11:00 selecting proto                            topics="libp2p multistream" tid=3578495 file=multistream.nim:63 conn=QmY*kfeH1F:6164e04dbc59820630030e28 proto=/vac/waku/relay/2.0.0
TRC 2021-10-12 12:09:33.620+11:00 write msg                                  topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:194 s=QmY*kfeH1F:6164e04dbc59820630030e28 conn=QmY*kfeH1F:6164e04dbc59820630030e22 len=23
TRC 2021-10-12 12:09:33.620+11:00 writing mplex message                      topics="libp2p mplexcoder" tid=3578495 file=coder.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e22 id=3 msgType=MsgOut data=23 encoded=25
TRC 2021-10-12 12:09:33.634+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=41
TRC 2021-10-12 12:09:33.634+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=b9d0c893987b...62acfd860f13 tagOut=b9d0c893987b...62acfd860f13 nonce=10
TRC 2021-10-12 12:09:33.634+11:00 read header varint                         topics="libp2p mplexcoder" tid=3578495 file=coder.nim:47 varint=10 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.634+11:00 read data                                  topics="libp2p mplexcoder" tid=3578495 file=coder.nim:50 dataLen=23 data=162f7661632f...322e302e300a conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.634+11:00 read message from connection               topics="libp2p mplex" tid=3578495 file=mplex.nim:139 m=QmY*kfeH1F:6164e04dbc59820630030e22 data=162f7661632f...322e302e300a msgType=MsgOut id=1 initiator=false size=23
TRC 2021-10-12 12:09:33.634+11:00 Processing channel message                 topics="libp2p mplex" tid=3578495 file=mplex.nim:158 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e27:1 data=162f7661632f...322e302e300a msgType=MsgOut id=1 initiator=false size=23
TRC 2021-10-12 12:09:33.634+11:00 pushing data to channel                    topics="libp2p mplex" tid=3578495 file=mplex.nim:175 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e27:1 len=23 msgType=MsgOut id=1 initiator=false size=23
TRC 2021-10-12 12:09:33.634+11:00 Pushing data                               topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:93 s=QmY*kfeH1F:6164e04dbc59820630030e27 data=23
TRC 2021-10-12 12:09:33.634+11:00 pushed data to channel                     topics="libp2p mplex" tid=3578495 file=mplex.nim:177 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e27:1 len=23 msgType=MsgOut id=1 initiator=false size=23
TRC 2021-10-12 12:09:33.634+11:00 waiting for data                           topics="libp2p mplex" tid=3578495 file=mplex.nim:128 m=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.634+11:00 add leftovers                              topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:163 s=QmY*kfeH1F:6164e04dbc59820630030e27 len=22
TRC 2021-10-12 12:09:33.634+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e27:1 bytes=1
TRC 2021-10-12 12:09:33.634+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e27:1 bytes=22
TRC 2021-10-12 12:09:33.634+11:00 handle: got request                        topics="libp2p multistream" tid=3578495 file=multistream.nim:141 conn=QmY*kfeH1F:6164e04dbc59820630030e27 ms=/vac/waku/relay/2.0.0
TRC 2021-10-12 12:09:33.634+11:00 found handler                              topics="libp2p multistream" tid=3578495 file=multistream.nim:170 conn=QmY*kfeH1F:6164e04dbc59820630030e27 protocol=/vac/waku/relay/2.0.0
TRC 2021-10-12 12:09:33.634+11:00 write msg                                  topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:194 s=QmY*kfeH1F:6164e04dbc59820630030e27:1 conn=QmY*kfeH1F:6164e04dbc59820630030e22 len=23
TRC 2021-10-12 12:09:33.634+11:00 writing mplex message                      topics="libp2p mplexcoder" tid=3578495 file=coder.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e22 id=1 msgType=MsgIn data=23 encoded=25
DBG 2021-10-12 12:09:33.634+11:00 Incoming WakuRelay connection              topics="wakurelay" tid=3578495 file=waku_relay.nim:34
DBG 2021-10-12 12:09:33.634+11:00 starting pubsub read loop                  topics="libp2p pubsubpeer" tid=3578495 file=pubsubpeer.nim:115 conn=QmY*kfeH1F:6164e04dbc59820630030e27 peer=QmY*kfeH1F closed=false
TRC 2021-10-12 12:09:33.634+11:00 waiting for data                           topics="libp2p pubsubpeer" tid=3578495 file=pubsubpeer.nim:120 conn=QmY*kfeH1F:6164e04dbc59820630030e27 peer=QmY*kfeH1F closed=false
TRC 2021-10-12 12:09:33.634+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=38
TRC 2021-10-12 12:09:33.634+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=647f9f992c55...b0e6db39431d tagOut=647f9f992c55...b0e6db39431d nonce=11
TRC 2021-10-12 12:09:33.634+11:00 read header varint                         topics="libp2p mplexcoder" tid=3578495 file=coder.nim:47 varint=25 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.634+11:00 read data                                  topics="libp2p mplexcoder" tid=3578495 file=coder.nim:50 dataLen=20 data=132f6d756c74...312e302e300a conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.634+11:00 read message from connection               topics="libp2p mplex" tid=3578495 file=mplex.nim:139 m=QmY*kfeH1F:6164e04dbc59820630030e22 data=132f6d756c74...312e302e300a msgType=MsgIn id=3 initiator=true size=20
TRC 2021-10-12 12:09:33.634+11:00 Processing channel message                 topics="libp2p mplex" tid=3578495 file=mplex.nim:158 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e28 data=132f6d756c74...312e302e300a msgType=MsgIn id=3 initiator=true size=20
TRC 2021-10-12 12:09:33.634+11:00 pushing data to channel                    topics="libp2p mplex" tid=3578495 file=mplex.nim:175 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e28 len=20 msgType=MsgIn id=3 initiator=true size=20
TRC 2021-10-12 12:09:33.634+11:00 Pushing data                               topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:93 s=QmY*kfeH1F:6164e04dbc59820630030e28 data=20
TRC 2021-10-12 12:09:33.634+11:00 pushed data to channel                     topics="libp2p mplex" tid=3578495 file=mplex.nim:177 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e28 len=20 msgType=MsgIn id=3 initiator=true size=20
TRC 2021-10-12 12:09:33.634+11:00 waiting for data                           topics="libp2p mplex" tid=3578495 file=mplex.nim:128 m=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.634+11:00 add leftovers                              topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:163 s=QmY*kfeH1F:6164e04dbc59820630030e28 len=19
TRC 2021-10-12 12:09:33.634+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e28 bytes=1
TRC 2021-10-12 12:09:33.634+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e28 bytes=19
TRC 2021-10-12 12:09:33.634+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=41
TRC 2021-10-12 12:09:33.634+11:00 multistream handshake success              topics="libp2p multistream" tid=3578495 file=multistream.nim:73 conn=QmY*kfeH1F:6164e04dbc59820630030e28
TRC 2021-10-12 12:09:33.634+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=5b500de42e6d...fae9bb030e19 tagOut=5b500de42e6d...fae9bb030e19 nonce=12
TRC 2021-10-12 12:09:33.634+11:00 read header varint                         topics="libp2p mplexcoder" tid=3578495 file=coder.nim:47 varint=25 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.634+11:00 read data                                  topics="libp2p mplexcoder" tid=3578495 file=coder.nim:50 dataLen=23 data=162f7661632f...322e302e300a conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.634+11:00 read message from connection               topics="libp2p mplex" tid=3578495 file=mplex.nim:139 m=QmY*kfeH1F:6164e04dbc59820630030e22 data=162f7661632f...322e302e300a msgType=MsgIn id=3 initiator=true size=23
TRC 2021-10-12 12:09:33.634+11:00 Processing channel message                 topics="libp2p mplex" tid=3578495 file=mplex.nim:158 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e28 data=162f7661632f...322e302e300a msgType=MsgIn id=3 initiator=true size=23
TRC 2021-10-12 12:09:33.634+11:00 pushing data to channel                    topics="libp2p mplex" tid=3578495 file=mplex.nim:175 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e28 len=23 msgType=MsgIn id=3 initiator=true size=23
TRC 2021-10-12 12:09:33.634+11:00 Pushing data                               topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:93 s=QmY*kfeH1F:6164e04dbc59820630030e28 data=23
TRC 2021-10-12 12:09:33.634+11:00 pushed data to channel                     topics="libp2p mplex" tid=3578495 file=mplex.nim:177 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e28 len=23 msgType=MsgIn id=3 initiator=true size=23
TRC 2021-10-12 12:09:33.634+11:00 waiting for data                           topics="libp2p mplex" tid=3578495 file=mplex.nim:128 m=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.635+11:00 add leftovers                              topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:163 s=QmY*kfeH1F:6164e04dbc59820630030e28 len=22
TRC 2021-10-12 12:09:33.635+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e28 bytes=1
TRC 2021-10-12 12:09:33.635+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e28 bytes=22
TRC 2021-10-12 12:09:33.635+11:00 reading first requested proto              topics="libp2p multistream" tid=3578495 file=multistream.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e28
TRC 2021-10-12 12:09:33.635+11:00 successfully selected                      topics="libp2p multistream" tid=3578495 file=multistream.nim:82 conn=QmY*kfeH1F:6164e04dbc59820630030e28 proto=/vac/waku/relay/2.0.0
INF 2021-10-12 12:09:33.635+11:00 Post peerManager dial                      topics="wakunode" tid=3578495 file=wakunode2.nim:596
TRC 2021-10-12 12:09:33.636+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=51
TRC 2021-10-12 12:09:33.636+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=2430f0929845...c3a1699d3fc2 tagOut=2430f0929845...c3a1699d3fc2 nonce=13
TRC 2021-10-12 12:09:33.636+11:00 read header varint                         topics="libp2p mplexcoder" tid=3578495 file=coder.nim:47 varint=10 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.636+11:00 read data                                  topics="libp2p mplexcoder" tid=3578495 file=coder.nim:50 dataLen=33 data=200a1e080112...2f70726f746f conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.636+11:00 read message from connection               topics="libp2p mplex" tid=3578495 file=mplex.nim:139 m=QmY*kfeH1F:6164e04dbc59820630030e22 data=200a1e080112...2f70726f746f msgType=MsgOut id=1 initiator=false size=33
TRC 2021-10-12 12:09:33.636+11:00 Processing channel message                 topics="libp2p mplex" tid=3578495 file=mplex.nim:158 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e27:1 data=200a1e080112...2f70726f746f msgType=MsgOut id=1 initiator=false size=33
TRC 2021-10-12 12:09:33.636+11:00 pushing data to channel                    topics="libp2p mplex" tid=3578495 file=mplex.nim:175 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e27:1 len=33 msgType=MsgOut id=1 initiator=false size=33
TRC 2021-10-12 12:09:33.636+11:00 Pushing data                               topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:93 s=QmY*kfeH1F:6164e04dbc59820630030e27 data=33
TRC 2021-10-12 12:09:33.636+11:00 pushed data to channel                     topics="libp2p mplex" tid=3578495 file=mplex.nim:177 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e27:1 len=33 msgType=MsgOut id=1 initiator=false size=33
TRC 2021-10-12 12:09:33.636+11:00 waiting for data                           topics="libp2p mplex" tid=3578495 file=mplex.nim:128 m=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:33.636+11:00 add leftovers                              topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:163 s=QmY*kfeH1F:6164e04dbc59820630030e27 len=32
TRC 2021-10-12 12:09:33.636+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e27:1 bytes=1
TRC 2021-10-12 12:09:33.636+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e27:1 bytes=32
TRC 2021-10-12 12:09:33.636+11:00 read data from peer                        topics="libp2p pubsubpeer" tid=3578495 file=pubsubpeer.nim:123 conn=QmY*kfeH1F:6164e04dbc59820630030e27 peer=QmY*kfeH1F closed=false data=0a1e0801121a...2f70726f746f
TRC 2021-10-12 12:09:33.636+11:00 decodeRpcMsg: decoding message             topics="pubsubprotobuf" tid=3578495 file=protobuf.nim:324 msg=0a1e0801121a...2f70726f746f
TRC 2021-10-12 12:09:33.636+11:00 decodeMessages: decoding message           topics="pubsubprotobuf" tid=3578495 file=protobuf.nim:299
TRC 2021-10-12 12:09:33.636+11:00 decodeMessages: no messages found          topics="pubsubprotobuf" tid=3578495 file=protobuf.nim:307
TRC 2021-10-12 12:09:33.636+11:00 decodeSubscriptions: decoding message      topics="pubsubprotobuf" tid=3578495 file=protobuf.nim:254
TRC 2021-10-12 12:09:33.636+11:00 decodeSubscriptions: read subscriptions    topics="pubsubprotobuf" tid=3578495 file=protobuf.nim:259 count=1
TRC 2021-10-12 12:09:33.636+11:00 decodeSubscription: decoding message       topics="pubsubprotobuf" tid=3578495 file=protobuf.nim:238
TRC 2021-10-12 12:09:33.636+11:00 decodeSubscription: read subscribe         topics="pubsubprotobuf" tid=3578495 file=protobuf.nim:243 subscribe=1
TRC 2021-10-12 12:09:33.636+11:00 decodeSubscription: read topic             topics="pubsubprotobuf" tid=3578495 file=protobuf.nim:247 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:33.636+11:00 decodeControl: decoding message            topics="pubsubprotobuf" tid=3578495 file=protobuf.nim:205
TRC 2021-10-12 12:09:33.636+11:00 decoded msg from peer                      topics="libp2p pubsubpeer" tid=3578495 file=pubsubpeer.nim:136 conn=QmY*kfeH1F:6164e04dbc59820630030e27 peer=QmY*kfeH1F closed=false msg="(subscriptions: @[(subscribe: true, topic: \"/waku/2/default-waku/proto\")], messages: @[], control: (ihave: @[], iwant: @[], graft: @[], prune: @[]))"
TRC 2021-10-12 12:09:33.636+11:00 peer subscribed to topic                   topics="libp2p gossipsub" tid=3578495 file=gossipsub.nim:227 peer=QmY*kfeH1F topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:33.636+11:00 gossip peers                               topics="libp2p gossipsub" tid=3578495 file=gossipsub.nim:243 peers=1 topic=/waku/2/default-waku/proto peer=QmY*kfeH1F
TRC 2021-10-12 12:09:33.636+11:00 waiting for data                           topics="libp2p pubsubpeer" tid=3578495 file=pubsubpeer.nim:120 conn=QmY*kfeH1F:6164e04dbc59820630030e27 peer=QmY*kfeH1F closed=false
TRC 2021-10-12 12:09:34.540+11:00 running heartbeat                          tid=3578495 file=behavior.nim:615 instance=140637430378568
TRC 2021-10-12 12:09:34.540+11:00 updating scores                            tid=3578495 file=scoring.nim:118 peers=1
TRC 2021-10-12 12:09:34.540+11:00 updating peer score                        tid=3578495 file=scoring.nim:131 peer=QmY*kfeH1F
TRC 2021-10-12 12:09:34.540+11:00 updated peer's score                       tid=3578495 file=scoring.nim:275 peer=QmY*kfeH1F score=0.0 n_topics=0 is_grafted=0
TRC 2021-10-12 12:09:34.540+11:00 updated scores                             tid=3578495 file=scoring.nim:289 peers=1
TRC 2021-10-12 12:09:34.540+11:00 rebalancing mesh                           tid=3578495 file=behavior.nim:258 mesh=0 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:34.540+11:00 replenishing mesh                          tid=3578495 file=behavior.nim:267 peers=0 mesh=0 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:34.540+11:00 grafting                                   tid=3578495 file=behavior.nim:291 grafting=1 mesh=0 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:34.540+11:00 grafted                                    tid=3578495 file=behavior.nim:40 peer=QmY*kfeH1F topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:34.541+11:00 mesh balanced                              tid=3578495 file=behavior.nim:450 mesh=1 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:34.541+11:00 broadcasting messages to peers             tid=3578495 file=pubsub.nim:174 peers=1 msg="(subscriptions: @[], messages: @[], control: (ihave: @[], iwant: @[], graft: @[(topicID: \"/waku/.../proto\")], prune: @[]))"
TRC 2021-10-12 12:09:34.541+11:00 encodeRpcMsg: encoding message             topics="pubsubprotobuf" tid=3578495 file=protobuf.nim:311 msg="(subscriptions: @[], messages: @[], control: (ihave: @[], iwant: @[], graft: @[(topicID: \"/waku/.../proto\")], prune: @[]))"
TRC 2021-10-12 12:09:34.541+11:00 sending encoded msgs to peer               topics="libp2p pubsubpeer" tid=3578495 file=pubsubpeer.nim:213 conn=QmY*kfeH1F:6164e04dbc59820630030e24 encoded=1a1e1a1c0a1a...2f70726f746f
TRC 2021-10-12 12:09:34.541+11:00 write msg                                  topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:194 s=QmY*kfeH1F:6164e04dbc59820630030e24 conn=QmY*kfeH1F:6164e04dbc59820630030e22 len=33
TRC 2021-10-12 12:09:34.541+11:00 writing mplex message                      topics="libp2p mplexcoder" tid=3578495 file=coder.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e22 id=1 msgType=MsgOut data=33 encoded=35
TRC 2021-10-12 12:09:34.541+11:00 getting gossip peers (iHave)               tid=3578495 file=behavior.nim:499 ntopics=1
TRC 2021-10-12 12:09:34.541+11:00 no messages to emit                        tid=3578495 file=behavior.nim:507
TRC 2021-10-12 12:09:34.541+11:00 sent pubsub message to remote              topics="libp2p pubsubpeer" tid=3578495 file=pubsubpeer.nim:219 conn=QmY*kfeH1F:6164e04dbc59820630030e24
TRC 2021-10-12 12:09:35.542+11:00 running heartbeat                          tid=3578495 file=behavior.nim:615 instance=140637430378568
TRC 2021-10-12 12:09:35.542+11:00 updating scores                            tid=3578495 file=scoring.nim:118 peers=1
TRC 2021-10-12 12:09:35.542+11:00 updating peer score                        tid=3578495 file=scoring.nim:131 peer=QmY*kfeH1F
TRC 2021-10-12 12:09:35.542+11:00 updated peer's score                       tid=3578495 file=scoring.nim:275 peer=QmY*kfeH1F score=0.0 n_topics=0 is_grafted=0
TRC 2021-10-12 12:09:35.542+11:00 updated scores                             tid=3578495 file=scoring.nim:289 peers=1
TRC 2021-10-12 12:09:35.542+11:00 rebalancing mesh                           tid=3578495 file=behavior.nim:258 mesh=1 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:35.542+11:00 replenishing mesh                          tid=3578495 file=behavior.nim:267 peers=1 mesh=1 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:35.542+11:00 grafting                                   tid=3578495 file=behavior.nim:291 grafting=0 mesh=1 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:35.542+11:00 mesh balanced                              tid=3578495 file=behavior.nim:450 mesh=1 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:35.542+11:00 getting gossip peers (iHave)               tid=3578495 file=behavior.nim:499 ntopics=1
TRC 2021-10-12 12:09:35.542+11:00 no messages to emit                        tid=3578495 file=behavior.nim:507
TRC 2021-10-12 12:09:36.543+11:00 running heartbeat                          tid=3578495 file=behavior.nim:615 instance=140637430378568
TRC 2021-10-12 12:09:36.543+11:00 updating scores                            tid=3578495 file=scoring.nim:118 peers=1
TRC 2021-10-12 12:09:36.543+11:00 updating peer score                        tid=3578495 file=scoring.nim:131 peer=QmY*kfeH1F
TRC 2021-10-12 12:09:36.543+11:00 updated peer's score                       tid=3578495 file=scoring.nim:275 peer=QmY*kfeH1F score=0.0 n_topics=0 is_grafted=0
TRC 2021-10-12 12:09:36.543+11:00 updated scores                             tid=3578495 file=scoring.nim:289 peers=1
TRC 2021-10-12 12:09:36.543+11:00 rebalancing mesh                           tid=3578495 file=behavior.nim:258 mesh=1 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:36.544+11:00 replenishing mesh                          tid=3578495 file=behavior.nim:267 peers=1 mesh=1 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:36.544+11:00 grafting                                   tid=3578495 file=behavior.nim:291 grafting=0 mesh=1 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:36.544+11:00 mesh balanced                              tid=3578495 file=behavior.nim:450 mesh=1 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:36.544+11:00 getting gossip peers (iHave)               tid=3578495 file=behavior.nim:499 ntopics=1
TRC 2021-10-12 12:09:36.544+11:00 no messages to emit                        tid=3578495 file=behavior.nim:507
TRC 2021-10-12 12:09:37.544+11:00 running heartbeat                          tid=3578495 file=behavior.nim:615 instance=140637430378568
TRC 2021-10-12 12:09:37.544+11:00 updating scores                            tid=3578495 file=scoring.nim:118 peers=1
TRC 2021-10-12 12:09:37.544+11:00 updating peer score                        tid=3578495 file=scoring.nim:131 peer=QmY*kfeH1F
TRC 2021-10-12 12:09:37.544+11:00 updated peer's score                       tid=3578495 file=scoring.nim:275 peer=QmY*kfeH1F score=0.0 n_topics=0 is_grafted=0
TRC 2021-10-12 12:09:37.544+11:00 updated scores                             tid=3578495 file=scoring.nim:289 peers=1
TRC 2021-10-12 12:09:37.544+11:00 rebalancing mesh                           tid=3578495 file=behavior.nim:258 mesh=1 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:37.544+11:00 replenishing mesh                          tid=3578495 file=behavior.nim:267 peers=1 mesh=1 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:37.545+11:00 grafting                                   tid=3578495 file=behavior.nim:291 grafting=0 mesh=1 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:37.545+11:00 mesh balanced                              tid=3578495 file=behavior.nim:450 mesh=1 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:37.545+11:00 getting gossip peers (iHave)               tid=3578495 file=behavior.nim:499 ntopics=1
TRC 2021-10-12 12:09:37.545+11:00 no messages to emit                        tid=3578495 file=behavior.nim:507
TRC 2021-10-12 12:09:38.546+11:00 running heartbeat                          tid=3578495 file=behavior.nim:615 instance=140637430378568
TRC 2021-10-12 12:09:38.546+11:00 updating scores                            tid=3578495 file=scoring.nim:118 peers=1
TRC 2021-10-12 12:09:38.546+11:00 updating peer score                        tid=3578495 file=scoring.nim:131 peer=QmY*kfeH1F
TRC 2021-10-12 12:09:38.546+11:00 updated peer's score                       tid=3578495 file=scoring.nim:275 peer=QmY*kfeH1F score=0.0 n_topics=0 is_grafted=0
TRC 2021-10-12 12:09:38.546+11:00 updated scores                             tid=3578495 file=scoring.nim:289 peers=1
TRC 2021-10-12 12:09:38.546+11:00 rebalancing mesh                           tid=3578495 file=behavior.nim:258 mesh=1 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:38.546+11:00 replenishing mesh                          tid=3578495 file=behavior.nim:267 peers=1 mesh=1 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:38.546+11:00 grafting                                   tid=3578495 file=behavior.nim:291 grafting=0 mesh=1 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:38.546+11:00 mesh balanced                              tid=3578495 file=behavior.nim:450 mesh=1 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:38.546+11:00 getting gossip peers (iHave)               tid=3578495 file=behavior.nim:499 ntopics=1
TRC 2021-10-12 12:09:38.546+11:00 no messages to emit                        tid=3578495 file=behavior.nim:507
DBG 2021-10-12 12:09:38.635+11:00 5/6 Starting monitoring and external interfaces topics="wakunode.setup" tid=3578495 file=wakunode2.nim:911
INF 2021-10-12 12:09:38.635+11:00 Starting JSON-RPC HTTP server              topics="JSONRPC-HTTP-SERVER" tid=3578495 file=httpserver.nim:213 url=http://127.0.0.1:10160
DBG 2021-10-12 12:09:38.635+11:00 Adding API topic handler for existing subscription topics="relay api" tid=3578495 file=relay_api.nim:47 topic=/waku/2/default-waku/proto
INF 2021-10-12 12:09:38.635+11:00 subscribe                                  topics="wakunode" tid=3578495 file=wakunode2.nim:169 topic=/waku/2/default-waku/proto
DBG 2021-10-12 12:09:38.635+11:00 Registering handler                        topics="wakunode" tid=3578495 file=wakunode2.nim:194 topic=/waku/2/default-waku/proto
DBG 2021-10-12 12:09:38.635+11:00 subscribe                                  topics="wakurelay" tid=3578495 file=waku_relay.nim:69 pubSubTopic=/waku/2/default-waku/proto
DBG 2021-10-12 12:09:38.635+11:00 MessageCache for topic                     topics="relay api" tid=3578495 file=relay_api.nim:52 topic=/waku/2/default-waku/proto
DBG 2021-10-12 12:09:38.635+11:00 HTTP RPC server started                    topics="JSONRPC-HTTP-SERVER" tid=3578495 file=httpserver.nim:334 address=127.0.0.1:10160
INF 2021-10-12 12:09:38.635+11:00 RPC Server started                         topics="wakunode.setup" tid=3578495 file=waku_setup.nim:66 ta=127.0.0.1:10160
DBG 2021-10-12 12:09:38.635+11:00 6/6 Setting up shutdown hooks              topics="wakunode.setup" tid=3578495 file=wakunode2.nim:918
DBG 2021-10-12 12:09:38.635+11:00 Node setup complete                        topics="wakunode.setup" tid=3578495 file=wakunode2.nim:944
TRC 2021-10-12 12:09:39.547+11:00 running heartbeat                          tid=3578495 file=behavior.nim:615 instance=140637430378568
TRC 2021-10-12 12:09:39.547+11:00 updating scores                            tid=3578495 file=scoring.nim:118 peers=1
TRC 2021-10-12 12:09:39.547+11:00 updating peer score                        tid=3578495 file=scoring.nim:131 peer=QmY*kfeH1F
TRC 2021-10-12 12:09:39.547+11:00 updated peer's score                       tid=3578495 file=scoring.nim:275 peer=QmY*kfeH1F score=0.0 n_topics=0 is_grafted=0
TRC 2021-10-12 12:09:39.547+11:00 updated scores                             tid=3578495 file=scoring.nim:289 peers=1
TRC 2021-10-12 12:09:39.547+11:00 rebalancing mesh                           tid=3578495 file=behavior.nim:258 mesh=1 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:39.547+11:00 replenishing mesh                          tid=3578495 file=behavior.nim:267 peers=1 mesh=1 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:39.548+11:00 grafting                                   tid=3578495 file=behavior.nim:291 grafting=0 mesh=1 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:39.548+11:00 mesh balanced                              tid=3578495 file=behavior.nim:450 mesh=1 gossipsub=1 topic=/waku/2/default-waku/proto
TRC 2021-10-12 12:09:39.548+11:00 getting gossip peers (iHave)               tid=3578495 file=behavior.nim:499 ntopics=1
TRC 2021-10-12 12:09:39.548+11:00 no messages to emit                        tid=3578495 file=behavior.nim:507
TRC 2021-10-12 12:09:39.689+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=65535
TRC 2021-10-12 12:09:39.689+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=36a153c95633...1f134a0034b5 tagOut=36a153c95633...1f134a0034b5 nonce=14
TRC 2021-10-12 12:09:39.690+11:00 read header varint                         topics="libp2p mplexcoder" tid=3578495 file=coder.nim:47 varint=10 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:39.695+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=65535
TRC 2021-10-12 12:09:39.696+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=517e5a42cc32...afb2ca3c91ae tagOut=517e5a42cc32...afb2ca3c91ae nonce=15
TRC 2021-10-12 12:09:39.697+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=65535
TRC 2021-10-12 12:09:39.698+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=cf1a00da9baf...e97a9bba6c4f tagOut=cf1a00da9baf...e97a9bba6c4f nonce=16
TRC 2021-10-12 12:09:39.698+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=65535
TRC 2021-10-12 12:09:39.699+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=40a69551ba8f...f5e9b7e59648 tagOut=40a69551ba8f...f5e9b7e59648 nonce=17
TRC 2021-10-12 12:09:39.700+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=65535
TRC 2021-10-12 12:09:39.700+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=9deb5c969a2f...df26b33834b2 tagOut=9deb5c969a2f...df26b33834b2 nonce=18
TRC 2021-10-12 12:09:39.701+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=65535
TRC 2021-10-12 12:09:39.702+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=4c4c022006ee...aad8224e5c6f tagOut=4c4c022006ee...aad8224e5c6f nonce=19
TRC 2021-10-12 12:09:39.703+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=65535
TRC 2021-10-12 12:09:39.705+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=bb8830ba9ade...58dc8fd5c5b9 tagOut=bb8830ba9ade...58dc8fd5c5b9 nonce=20
TRC 2021-10-12 12:09:39.705+11:00 readFrame                                  topics="libp2p noise" tid=3578495 file=noise.nim:309 sconn=QmY*kfeH1F:6164e04dbc59820630030e21 size=41468
TRC 2021-10-12 12:09:39.705+11:00 decryptWithAd                              topics="libp2p noise" tid=3578495 file=noise.nim:169 tagIn=f870ad49470d...74c248177600 tagOut=f870ad49470d...74c248177600 nonce=21
TRC 2021-10-12 12:09:39.706+11:00 read data                                  topics="libp2p mplexcoder" tid=3578495 file=coder.nim:50 dataLen=500081 data=eec21e12e8c2...726f746f1a00 conn=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:39.707+11:00 read message from connection               topics="libp2p mplex" tid=3578495 file=mplex.nim:139 m=QmY*kfeH1F:6164e04dbc59820630030e22 data=eec21e12e8c2...726f746f1a00 msgType=MsgOut id=1 initiator=false size=500081
TRC 2021-10-12 12:09:39.707+11:00 Processing channel message                 topics="libp2p mplex" tid=3578495 file=mplex.nim:158 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e27:1 data=eec21e12e8c2...726f746f1a00 msgType=MsgOut id=1 initiator=false size=500081
TRC 2021-10-12 12:09:39.707+11:00 pushing data to channel                    topics="libp2p mplex" tid=3578495 file=mplex.nim:175 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e27:1 len=500081 msgType=MsgOut id=1 initiator=false size=500081
TRC 2021-10-12 12:09:39.707+11:00 Pushing data                               topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:93 s=QmY*kfeH1F:6164e04dbc59820630030e27 data=500081
TRC 2021-10-12 12:09:39.708+11:00 pushed data to channel                     topics="libp2p mplex" tid=3578495 file=mplex.nim:177 m=QmY*kfeH1F:6164e04dbc59820630030e22 channel=QmY*kfeH1F:6164e04dbc59820630030e27:1 len=500081 msgType=MsgOut id=1 initiator=false size=500081
TRC 2021-10-12 12:09:39.708+11:00 waiting for data                           topics="libp2p mplex" tid=3578495 file=mplex.nim:128 m=QmY*kfeH1F:6164e04dbc59820630030e22
TRC 2021-10-12 12:09:39.709+11:00 add leftovers                              topics="libp2p bufferstream" tid=3578495 file=bufferstream.nim:163 s=QmY*kfeH1F:6164e04dbc59820630030e27 len=500080
TRC 2021-10-12 12:09:39.709+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e27:1 bytes=1
TRC 2021-10-12 12:09:39.709+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e27:1 bytes=1
TRC 2021-10-12 12:09:39.709+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e27:1 bytes=1
TRC 2021-10-12 12:09:39.709+11:00 Closing channel                            topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:122 s=QmY*kfeH1F:6164e04dbc59820630030e27:1 conn=QmY*kfeH1F:6164e04dbc59820630030e22 len=500078
TRC 2021-10-12 12:09:39.709+11:00 writing mplex message                      topics="libp2p mplexcoder" tid=3578495 file=coder.nim:80 conn=QmY*kfeH1F:6164e04dbc59820630030e22 id=1 msgType=CloseIn data=0 encoded=2
TRC 2021-10-12 12:09:39.709+11:00 Closed channel                             topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:138 s=QmY*kfeH1F:6164e04dbc59820630030e27:1 len=500078
TRC 2021-10-12 12:09:39.709+11:00 Exception occurred in PubSubPeer.handle    topics="libp2p pubsubpeer" tid=3578495 file=pubsubpeer.nim:156 conn=QmY*kfeH1F:6164e04dbc59820630030e27 peer=QmY*kfeH1F closed=true exc="Message exceeds maximum length"
DBG 2021-10-12 12:09:39.709+11:00 exiting pubsub read loop                   topics="libp2p pubsubpeer" tid=3578495 file=pubsubpeer.nim:159 conn=QmY*kfeH1F:6164e04dbc59820630030e27 peer=QmY*kfeH1F closed=true
TRC 2021-10-12 12:09:39.709+11:00 pubsub peer handler ended                  topics="libp2p pubsub" tid=3578495 file=pubsub.nim:364 conn=QmY*kfeH1F:6164e04dbc59820630030e27
TRC 2021-10-12 12:09:39.709+11:00 Closing with EOF                           topics="libp2p lpstream" tid=3578495 file=lpstream.nim:298 s=6164e04dbc59820630030e27
TRC 2021-10-12 12:09:39.709+11:00 Already closed                             topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:118 s=QmY*kfeH1F:6164e04dbc59820630030e27:1
TRC 2021-10-12 12:09:39.709+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:160 s=QmY*kfeH1F:6164e04dbc59820630030e27:1 bytes=8
DBG 2021-10-12 12:09:39.709+11:00 Unexpected bytes while waiting for EOF     topics="libp2p lpstream" tid=3578495 file=lpstream.nim:314 s=6164e04dbc59820630030e27
TRC 2021-10-12 12:09:39.709+11:00 Already closed                             topics="libp2p mplexchannel" tid=3578495 file=lpchannel.nim:118 s=QmY*kfeH1F:6164e04dbc59820630030e27:1
TRC 2021-10-12 12:09:39.709+11:00 Closing with EOF                           topics="libp2p lpstream" tid=3578495 file=lpstream.nim:298 s=6164e04dbc59820630030e27
TRC 2021-10-12 12:09:39.709+11:00 Already closed                             topics="libp2p lpstream" tid=3578495 file=lpstream.nim:300
TRC 2021-10-12 12:09:39.709+11:00 Stream handler done                        tid=3578495 file=muxedupgrade.nim:222 conn=QmY*kfeH1F:6164e04dbc59820630030e27
TRC 2021-10-12 12:09:39.709+11:00 finished handling stream                   topics="libp2p mplex" tid=3578495 file=mplex.nim:118 m=QmY*kfeH1F:6164e04dbc59820630030e22 chann=QmY*kfeH1F:6164e04dbc59820630030e27:1

Here are partial log for 100kb payload size (same error):

TRC 2021-10-12 12:16:46.218+11:00 readFrame                                  topics="libp2p noise" tid=3586705 file=noise.nim:309 sconn=QmN*aJYmYF:6164e1f87a42807773b7034e size=65535
TRC 2021-10-12 12:16:46.218+11:00 decryptWithAd                              topics="libp2p noise" tid=3586705 file=noise.nim:169 tagIn=98b9bcda0784...46f29eed8b61 tagOut=98b9bcda0784...46f29eed8b61 nonce=14
TRC 2021-10-12 12:16:46.218+11:00 read header varint                         topics="libp2p mplexcoder" tid=3586705 file=coder.nim:47 varint=10 conn=QmN*aJYmYF:6164e1f87a42807773b7034f
TRC 2021-10-12 12:16:46.222+11:00 readFrame                                  topics="libp2p noise" tid=3586705 file=noise.nim:309 sconn=QmN*aJYmYF:6164e1f87a42807773b7034e size=34582
TRC 2021-10-12 12:16:46.222+11:00 decryptWithAd                              topics="libp2p noise" tid=3586705 file=noise.nim:169 tagIn=58edb414341b...0dfaa1c787d9 tagOut=58edb414341b...0dfaa1c787d9 nonce=15
TRC 2021-10-12 12:16:46.222+11:00 read data                                  topics="libp2p mplexcoder" tid=3586705 file=coder.nim:50 dataLen=100081 data=ee8d0612e88d...726f746f1a00 conn=QmN*aJYmYF:6164e1f87a42807773b7034f
TRC 2021-10-12 12:16:46.223+11:00 read message from connection               topics="libp2p mplex" tid=3586705 file=mplex.nim:139 m=QmN*aJYmYF:6164e1f87a42807773b7034f data=ee8d0612e88d...726f746f1a00 msgType=MsgOut id=1 initiator=false size=100081
TRC 2021-10-12 12:16:46.223+11:00 Processing channel message                 topics="libp2p mplex" tid=3586705 file=mplex.nim:158 m=QmN*aJYmYF:6164e1f87a42807773b7034f channel=QmN*aJYmYF:6164e1f87a42807773b70354:1 data=ee8d0612e88d...726f746f1a00 msgType=MsgOut id=1 initiator=false size=100081
TRC 2021-10-12 12:16:46.223+11:00 pushing data to channel                    topics="libp2p mplex" tid=3586705 file=mplex.nim:175 m=QmN*aJYmYF:6164e1f87a42807773b7034f channel=QmN*aJYmYF:6164e1f87a42807773b70354:1 len=100081 msgType=MsgOut id=1 initiator=false size=100081
TRC 2021-10-12 12:16:46.223+11:00 Pushing data                               topics="libp2p bufferstream" tid=3586705 file=bufferstream.nim:93 s=QmN*aJYmYF:6164e1f87a42807773b70354 data=100081
TRC 2021-10-12 12:16:46.223+11:00 pushed data to channel                     topics="libp2p mplex" tid=3586705 file=mplex.nim:177 m=QmN*aJYmYF:6164e1f87a42807773b7034f channel=QmN*aJYmYF:6164e1f87a42807773b70354:1 len=100081 msgType=MsgOut id=1 initiator=false size=100081
TRC 2021-10-12 12:16:46.223+11:00 waiting for data                           topics="libp2p mplex" tid=3586705 file=mplex.nim:128 m=QmN*aJYmYF:6164e1f87a42807773b7034f
TRC 2021-10-12 12:16:46.223+11:00 add leftovers                              topics="libp2p bufferstream" tid=3586705 file=bufferstream.nim:163 s=QmN*aJYmYF:6164e1f87a42807773b70354 len=100080
TRC 2021-10-12 12:16:46.223+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3586705 file=lpchannel.nim:160 s=QmN*aJYmYF:6164e1f87a42807773b70354:1 bytes=1
TRC 2021-10-12 12:16:46.223+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3586705 file=lpchannel.nim:160 s=QmN*aJYmYF:6164e1f87a42807773b70354:1 bytes=1
TRC 2021-10-12 12:16:46.223+11:00 readOnce                                   topics="libp2p mplexchannel" tid=3586705 file=lpchannel.nim:160 s=QmN*aJYmYF:6164e1f87a42807773b70354:1 bytes=1
TRC 2021-10-12 12:16:46.223+11:00 Closing channel                            topics="libp2p mplexchannel" tid=3586705 file=lpchannel.nim:122 s=QmN*aJYmYF:6164e1f87a42807773b70354:1 conn=QmN*aJYmYF:6164e1f87a42807773b7034f len=100078
TRC 2021-10-12 12:16:46.223+11:00 writing mplex message                      topics="libp2p mplexcoder" tid=3586705 file=coder.nim:80 conn=QmN*aJYmYF:6164e1f87a42807773b7034f id=1 msgType=CloseIn data=0 encoded=2
TRC 2021-10-12 12:16:46.223+11:00 Closed channel                             topics="libp2p mplexchannel" tid=3586705 file=lpchannel.nim:138 s=QmN*aJYmYF:6164e1f87a42807773b70354:1 len=100078
TRC 2021-10-12 12:16:46.223+11:00 Exception occurred in PubSubPeer.handle    topics="libp2p pubsubpeer" tid=3586705 file=pubsubpeer.nim:156 conn=QmN*aJYmYF:6164e1f87a42807773b70354 peer=QmN*aJYmYF closed=true exc="Message exceeds maximum length"
@Menduist
Copy link
Contributor

This is coming from here: https://github.com/status-im/nim-libp2p/blob/1681197d67e695e6adccccf56ce0e2d586317d67/libp2p/protocols/pubsub/pubsubpeer.nim#L122
64kb max size per message in gossipsub.

I've opened a PR in libp2p to allow programs to tweak this number vacp2p/nim-libp2p#634

Note that this is not a good long term solution. With dLow = 6, for each valid message you receive, you'll relay it to at least 6 peers. If I can send you a 1Mb message, you'll upload 6Mb worth of messages. If I can do that every second, I just saturated most home connections uplink

@arnetheduck
Copy link
Contributor

It's worth noting also that other gossipsub implementations will have similar limits, meaning that even if one node supports a higher value, it's not a given that the other does - one way of handling these kinds of issues is to gossip a URI of some kind that the end recipient can retrieve from elsewhere

@D4nte
Copy link
Contributor Author

D4nte commented Oct 13, 2021

Agreed with all comments above. At this stage I think we should aim for feature parity with Waku v1.
According to @cammellos:

we heavily compress [images] to try to get them < 1MB (they need to be maximum 500/600k), waku max filesize limit is 1MB but effectively is less because of POW

So if we could get the limit raised to 600kb I understand it should be enough.

Then, yes, ultimately images (and videos and other files) should not be transferred of the Waku network.
I assume that the aim would be for files to be stored on dagger and uri be exchanged via Waku.

@Menduist
Copy link
Contributor

Menduist commented Oct 13, 2021

Could someone on waku side check that my PR allows you to fix your issue? @jm-clius @D4nte
If so, I'll merge it this week, thanks :)

This was referenced Oct 14, 2021
@jm-clius
Copy link
Contributor

Could someone on waku side check that my PR allows you to fix your issue? @jm-clius @D4nte If so, I'll merge it this week, thanks :)

Thanks, @Menduist. LGTM. Once merged I'll also make this a separate config item for Waku.

@arnetheduck
Copy link
Contributor

should not be transferred

this will be difficult to change, down the line, because old clients will work according to one rule while newer clients will want to have a lower limit - lowering the limit is a backwards-incompatible change.

I'd look for creative solutions to this problem - for example chunking or other techniques - chunking doesn't make the bandwidth problem go away but it might have a more attractive compatibility profile.

@arnetheduck
Copy link
Contributor

With dLow = 6,

for waku, I suspect this can be lowered to 4 which is the "standard" libp2p mesh connectivity level.

@oskarth
Copy link
Contributor

oskarth commented Oct 18, 2021

Agree that chunking would be a better approach that is worth exploring here. Should be doable at application layer without changing Waku relay / gossipsub limits.

@Menduist
Copy link
Contributor

@oskarth so should we merge in libp2p?
It's ready for merge if you want it, but since it's a workaround I would rather not have it

@D4nte
Copy link
Contributor Author

D4nte commented Oct 20, 2021

@cammellos @iurimatias

FYI, we are looking at the chunking approach at an application level which would mean modifying the ChatMessage protobuf files to allow for sequencing of the image chunks.

Thoughts?

@oskarth
Copy link
Contributor

oskarth commented Oct 20, 2021

@Menduist I'd say we hold off and explore chunking first. If there is a good way of doing it that works for Status protocol that'd be best. Agree it'd be better not to have it in, especially since it is a decision that is hard to reverse.

The problem is really two: (1) chunking images/large messages (2) dealing with bridging. For the bridging, we might have to get creative here, for example by chunking up large messages w/o understanding content, then assembling them on client.

@arnetheduck
Copy link
Contributor

next up: progressive jpegs - history repeats itself :)

@Menduist
Copy link
Contributor

Uppon better reading of the spec (thanks @cskiraly), we've noticed that we should allow applications to tune the size
(And that the default "may" be 1mb, we'll not update the default in nim-libp2p since "may" is not a spec)
So we'll merge on our side, and you are free to use it or not :)

@D4nte
Copy link
Contributor Author

D4nte commented Oct 22, 2021

Uppon better reading of the spec (thanks @cskiraly), we've noticed that we should allow applications to tune the size (And that the default "may" be 1mb, we'll not update the default in nim-libp2p since "may" is not a spec) So we'll merge on our side, and you are free to use it or not :)

So the 64kb is an arbitrary size? Or does it originate from another libp2p implementation?

To go around this problem, @Szymx95 (from EthWorks, working on DappConnect Chat SDK) is going to implement a PoC in js-waku that would do the following:

Define new fields on Waku v2 WakuMessage:

syntax = "proto3";

message WakuMessage {
  bytes payload = 1;
  string contentTopic = 2;
  uint32 version = 3;
  double timestamp = 4;
  uint32 chunkSeq = 10; // sequence number of this chunk, only set if message is a chunk
  uint32 totalChunk = 11; // total number of chunks, only set if message is a chunk
  bytes payloadHash = 12; // SHA-256 has of the total payload, before chunkin
}

Note: it was also proposed to have these new field in the ContentTopic but as partial search of the content topic is not available. I'd thought we try new fields first.

Other alternative would be to add the fields in the payload field instead so we do not change the WakuMessage strict.
First POC iteration will be with the new fields so it's clearer/easier/less decisions to make and we can discuss more and move them in the payload and or contact topic

For Waku v2 node

Outbound

If an outbound Waku Message wakuMessage is larger than 60kb:

  • Calculate the sha-256 hash of wakuMessage.payload;
    Note, the payload may or may not be encrypted.
  • Split the messages in chunks so that each chunk is 60kb or less:
<---------------------------------- payload 200kb --------------------------------->
<-- chunk 0; 60kb --><-- chunk 1; 60kb --><-- chunk 2; 60kb --><-- chunk 3; 20kb -->

For each chunk, send a new Waku Message with

  • chunkSeq: the chunk sequence number from 0 to totalChunk - 1,
  • totalChunk: the total number of chunks,
  • payloadHash: the hash of the total payload

Send all chunk messages.

Inbound

If an inbound Waku Message has all the new fields set then:

  • Gather all messages with the same payloadHash.
  • If there is a missing chunk, potential use waku store or discard the message as corrupted after time X (to be defined)
  • Concatenate chunks together as figure above
  • Check payload integrety by comparing total payload hash with payloadHash.
  • Pass Waku Message to application layer as any normal message.

For Waku v1<>v2 bridge

For messages received on v1 side over 50kb, do as per outbound section above before forwarding to v2 network.

For chunk messages received on v2 side, do as per inbound section above before forwarding to v1 network.

Let me know your thoughts, we can discussion in more details once the PoC is ready.

@Menduist
Copy link
Contributor

So the 64kb is an arbitrary size? Or does it originate from another libp2p implementation?

AFAICT, yes. However, upon discussing with the nimbus team, they also need a 1mb default, and since this seems to be the norm around libp2p implementations, we'll also switch to a 1mb default

@oskarth
Copy link
Contributor

oskarth commented Oct 25, 2021

since this seems to be the norm around libp2p implementations

Interesting, so I guess the problem took care of itself? :D

If you see ten troubles coming down the road, you can be sure that nine will run into the ditch before they reach you.

That seems to imply:

  1. We probably don't need to do chunking at bridge level
  2. Chunking of images is still valuable but maybe less prioritized (should perhaps come from app teams based on specific user stories)

@Menduist
Copy link
Contributor

Menduist commented Oct 25, 2021

Merged in libp2p

so I guess the problem took care of itself? :D

All our points still holds, you may encounter a libp2p with smaller default (since the default is "hinted" in the spec, instead of enforced), and this is still bad in terms of bandwidth

But that should hold for now :)

If you have the possibility, add per-topic size validation, to at least stop relaying big messages where it does not make sense

@D4nte
Copy link
Contributor Author

D4nte commented Oct 25, 2021

Agreed and thanks for the clarification.

We will halt bridge compatible chunking on our side.

Yes medial file chunking could be done in the future at application level.

Cc @Szymx95

@D4nte
Copy link
Contributor Author

D4nte commented Nov 26, 2021

@jm-clius Does nim-waku v0.6 uses the nim-libp2p version with a limit of 1mb?

@jm-clius
Copy link
Contributor

@jm-clius Does nim-waku v0.6 uses the nim-libp2p version with a limit of 1mb?

Yup! We now proudly support larger message sizes

@jm-clius
Copy link
Contributor

@D4nte I believe this issue is now sorted? I've also opened a PR that takes care of some truncated input stream reads with the larger message size: #800.

Closing, but feel free to reopen if there's still something to be done.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants