[RPC] WakuRelayMessage does not support `timestamp` property

[D4nte]

js-waku uses v0.4 for interoperability tests. I spent some time today preparing for v0.5 by pulling latest master and testing js-waku against it, commit a41b9ac80b5589a11ac9661b9fa099dff4177e8c

One of the test to ensure js-waku correctly process paginated responses is as follow:

1. Do 15 sequential calls of the post_waku_v2_relay_v1_message RPC API, messages contain an utf-8 string as payload Message 1 to Message5`.
2. Do a history query with page size 10, direction forward.

With v0.4, the messages are returned in expected order (0 to 14). With latest master, the messages are returned in an order that seems random:

  waku:test:store [
  waku:test:store   { timestamp: undefined, payload: 'Message 13' },
  waku:test:store   { timestamp: undefined, payload: 'Message 3' },
  waku:test:store   { timestamp: undefined, payload: 'Message 12' },
  waku:test:store   { timestamp: undefined, payload: 'Message 4' },
  waku:test:store   { timestamp: undefined, payload: 'Message 14' },
  waku:test:store   { timestamp: undefined, payload: 'Message 5' },
  waku:test:store   { timestamp: undefined, payload: 'Message 9' },
  waku:test:store   { timestamp: undefined, payload: 'Message 0' },
  waku:test:store   { timestamp: undefined, payload: 'Message 10' },
  waku:test:store   { timestamp: undefined, payload: 'Message 11' },
  waku:test:store   { timestamp: undefined, payload: 'Message 2' },
  waku:test:store   { timestamp: undefined, payload: 'Message 8' },
  waku:test:store   { timestamp: undefined, payload: 'Message 7' },
  waku:test:store   { timestamp: undefined, payload: 'Message 1' },
  waku:test:store   { timestamp: undefined, payload: 'Message 6' }
  waku:test:store ] +0ms

I added a 100ms sleep between each post RPC call to ensure nim-waku process them in order but it did not help. Not sure why all the timestamps are undefined either, is that the issue?

Note that the order is actually NOT random because it's always the same order....

When using v0.4:

  waku:test:store [
  waku:test:store   { timestamp: undefined, payload: 'Message 0' },
  waku:test:store   { timestamp: undefined, payload: 'Message 1' },
  waku:test:store   { timestamp: undefined, payload: 'Message 2' },
  waku:test:store   { timestamp: undefined, payload: 'Message 3' },
  waku:test:store   { timestamp: undefined, payload: 'Message 4' },
  waku:test:store   { timestamp: undefined, payload: 'Message 5' },
  waku:test:store   { timestamp: undefined, payload: 'Message 6' },
  waku:test:store   { timestamp: undefined, payload: 'Message 7' },
  waku:test:store   { timestamp: undefined, payload: 'Message 8' },
  waku:test:store   { timestamp: undefined, payload: 'Message 9' },
  waku:test:store   { timestamp: undefined, payload: 'Message 10' },
  waku:test:store   { timestamp: undefined, payload: 'Message 11' },
  waku:test:store   { timestamp: undefined, payload: 'Message 12' },
  waku:test:store   { timestamp: undefined, payload: 'Message 13' },
  waku:test:store   { timestamp: undefined, payload: 'Message 14' }
  waku:test:store ] +565ms

I am guessing these are side effect of changes on the sender timestamp?

On my side I will start setting the timestamp as part of the test. Shouldn't the RPC call set the timestamp if not passed?

[oskarth]

@staheri14 thoughts?

[staheri14]

Thanks, @D4nte for sharing the problem, I am looking into it. In the meantime, my initial guess is that this is due to the recent change in the pagination logic. In nim-waku, the sender timestamp + message hash is used for message indexing and paging (as opposed to the previous implementation based on receiver timestamp + message hash). Probably messages are not timestamped by the sender?

[staheri14]

Not sure why all the timestamps are undefined either

post_waku_v2_relay_v1_message receives a WakuRelayMessage which has no timestamp field, which means messages will have no sender timestamp. I believe that is the reason that the timestamp field is undefined. See below for the structure of WakuRelayMessage

  WakuRelayMessage* = object
    payload*: seq[byte]
    contentTopic*: Option[ContentTopic]

~In order to track down the issue, I need to know how do you send the history query? which API do you use? is it through get_waku_v2_store_v1_messages?~ no need for this, I found the cause of this issue! please see my comment below

@D4nte

[staheri14]

Found the issue! @D4nte Due to the absence of sender timestamp, messages are indexed based on their hashes i.e., Hash( msg.payload || msg.contetTopic), and the result that you get matches this logic.

I replicated your test scenario, and the result is exactly the same i.e., messages are correctly sorted based on their hash values:

message: Message 13 message hash: 29ABCDF8D71807B56F7EC14C4D9C1108B2A686215825D9D2B1C5AC584E61A800
message: Message 3 message hash: 3603E173F6EC200816744B242BC696DFB7E433289CE62389FE5F67B05E7C0CB1
message: Message 12 message hash: 449A452D620097325DD2863CE990DBD7648A93AEF3087ECC89D6D9761D24BB67
message: Message 4 message hash: 68666A4168B30D7722AD02E171A09CF6CC2D34108FEC01A8A94C3FD84109819D
message: Message 14 message hash: 9ADA450A12BCAB4CB45BAE8C0F84173370C6FF7D27A782F9E1A764D72B78A912
message: Message 5 message hash: A40D376C5AD52E8A3A088E2A67A66D5F5C108E1EA5CE9FECBE76FE076CDC77B0
message: Message 9 message hash: A4DD3B87AE9EB132F798EA95ED8C9655A6EAFE2E9FB51AC815EDC0C143C9242D
message: Message 0 message hash: AD52D766B253B0E694C07EC1C6F29E83522E50D384509302407097BF894B5E3D
message: Message 10 message hash: BAA1FD5E0FA1AE7A69408FDDF8C29503865ACB8133342F0AA30DED1514A5C55E
message: Message 11 message hash: BE803AA18299B299BCCECD3A59B7D9C214A78B7436BD7179C17082FE7EB8D079
message: Message 2 message hash: CAED135886D9AABB3406C1070228E104483F0CC5F1B7BEE2B0C65193EAF200B0
message: Message 8 message hash: CB230FBC846D8C4EA036FDE50027FE59606499D9871F2C2B18B0AA4D1BFB00AE
message: Message 7 message hash: DB542A624F78A9A1D501932A73F5F9CF945C86802345D78D3744FCFDCE760014
message: Message 1 message hash: E7D6D263F15271F236263BC3D25DCD04AE48646787FA8A6E688DDF29DC03E8DD
message: Message 6 message hash: EC5C1F864239A4A28F79998834664FCFDA77C710744E176DFE56F35CFAD7E3FE

[staheri14]

The solution is to add the sender timestamp field to the WakuRelayMessage type, also, the timestamp should be set from the sender side. I am working on it. @D4nte

[D4nte]

Hi @staheri14, Thank you for the thorough analysis. I fixed the issue by passing a timestamp to the JSO RPC calls, as suggested.

[D4nte]

Sorry, I closed too early, I got mixed up with the wakunode2 version I was running.

When sending this via Rpc:

rpcMessage {
  payload: '4d6573736167652030',
  contentTopic: '/waku/2/default-content/proto',
  timestamp: 1626758547.069
}

the messages are returned without timestamp:

  waku:test:store { timestamp: undefined, payload: 'Message 13' } +0ms
  waku:test:store { timestamp: undefined, payload: 'Message 3' } +0ms
  waku:test:store { timestamp: undefined, payload: 'Message 12' } +0ms
  waku:test:store { timestamp: undefined, payload: 'Message 4' } +0ms
  waku:test:store { timestamp: undefined, payload: 'Message 14' } +0ms
  waku:test:store { timestamp: undefined, payload: 'Message 5' } +0ms
  waku:test:store { timestamp: undefined, payload: 'Message 9' } +1ms
  waku:test:store { timestamp: undefined, payload: 'Message 0' } +0ms
  waku:test:store { timestamp: undefined, payload: 'Message 10' } +0ms
  waku:test:store { timestamp: undefined, payload: 'Message 11' } +0ms
  waku:test:store { timestamp: undefined, payload: 'Message 2' } +0ms
  waku:test:store { timestamp: undefined, payload: 'Message 8' } +0ms
  waku:test:store { timestamp: undefined, payload: 'Message 7' } +0ms
  waku:test:store { timestamp: undefined, payload: 'Message 1' } +0ms
  waku:test:store { timestamp: undefined, payload: 'Message 6' } +0ms

I am using nim-waku 108599a1ed2a26663f911afdafe79604c6b5ffd0

In wakunode2 log, I can see that the timestamp is not set from the RPC call:

TRC 2021-07-20 15:22:27.088+10:00 WakuMessage received                       topics="relay api" tid=2016588 file=relay_api.nim:26 msg="Ok((payload: @[77, 101, 115, 115, 97, 103, 101, 32, 48], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[]))" topic=/waku/2/default-waku/proto

Please find the full log here:

INF 2021-07-20 15:22:27.060+10:00 Initializing networking                    topics="wakunode" tid=2016588 file=wakunode2.nim:137 hostAddress=/ip4/127.0.0.1/tcp/61412 announcedAddresses=@[]
TRC 2021-07-20 15:22:27.060+10:00 registering protocols                      topics="libp2p multistream" tid=2016588 file=multistream.nim:189 protos="@[\"/ipfs/id/1.0.0\"]"
TRC 2021-07-20 15:22:27.061+10:00 starting switch for peer                   topics="libp2p switch" tid=2016588 file=switch.nim:207 peerInfo="(peerId: \"16Uiu2HAm3zv3dBgPe7qu8Rt7ZqaQigB35T6wzsVH3sU7zqRLpVNN\", addrs: @[\"/ip4/127.0.0.1/tcp/61412\"], protocols: @[\"/ipfs/id/1.0.0\"], protoVersion: \"ipfs/0.1.0\", agentVersion: \"nim-libp2p/0.0.1\")"
TRC 2021-07-20 15:22:27.061+10:00 starting transport                         topics="libp2p transport" tid=2016588 file=transport.nim:50 address=/ip4/127.0.0.1/tcp/61412
TRC 2021-07-20 15:22:27.061+10:00 Starting TCP transport                     topics="libp2p tcptransport" tid=2016588 file=tcptransport.nim:144
TRC 2021-07-20 15:22:27.061+10:00 Listening on                               topics="libp2p tcptransport" tid=2016588 file=tcptransport.nim:155 address=/ip4/127.0.0.1/tcp/61412
DBG 2021-07-20 15:22:27.061+10:00 About to accept incoming connection        topics="libp2p switch" tid=2016588 file=switch.nim:167
TRC 2021-07-20 15:22:27.061+10:00 Acquired slot                              topics="libp2p semaphore" tid=2016588 file=semaphore.nim:38 available=3 queue=0
TRC 2021-07-20 15:22:27.061+10:00 Tracking incoming connection               topics="libp2p connmanager" tid=2016588 file=connmanager.nim:449
TRC 2021-07-20 15:22:27.061+10:00 Acquired slot                              topics="libp2p semaphore" tid=2016588 file=semaphore.nim:38 available=49 queue=0
DBG 2021-07-20 15:22:27.061+10:00 Started libp2p node                        topics="libp2p switch" tid=2016588 file=switch.nim:222 peer="(peerId: \"16Uiu2HAm3zv3dBgPe7qu8Rt7ZqaQigB35T6wzsVH3sU7zqRLpVNN\", addrs: @[\"/ip4/127.0.0.1/tcp/61412\"], protocols: @[\"/ipfs/id/1.0.0\"], protoVersion: \"ipfs/0.1.0\", agentVersion: \"nim-libp2p/0.0.1\")"
INF 2021-07-20 15:22:27.061+10:00 PeerInfo                                   topics="wakunode" tid=2016588 file=wakunode2.nim:172 peerId=16U*RLpVNN addrs=@[/ip4/127.0.0.1/tcp/61412]
INF 2021-07-20 15:22:27.061+10:00 Listening on                               topics="wakunode" tid=2016588 file=wakunode2.nim:175 full=/ip4/127.0.0.1/tcp/61412/p2p/16Uiu2HAm3zv3dBgPe7qu8Rt7ZqaQigB35T6wzsVH3sU7zqRLpVNN
INF 2021-07-20 15:22:27.061+10:00 mounting swap                              topics="wakunode" tid=2016588 file=wakunode2.nim:409 mode=Soft
INF 2021-07-20 15:22:27.061+10:00 wakuSwap init 2                            topics="wakunode" tid=2016588 file=waku_swap.nim:285
INF 2021-07-20 15:22:27.061+10:00 wakuSwap init 1                            topics="wakuswap" tid=2016588 file=waku_swap.nim:218
TRC 2021-07-20 15:22:27.061+10:00 registering protocols                      topics="libp2p multistream" tid=2016588 file=multistream.nim:189 protos="@[\"/vac/waku/swap/2.0.0-beta1\"]"
INF 2021-07-20 15:22:27.061+10:00 mounting store                             topics="wakunode" tid=2016588 file=wakunode2.nim:416
DBG 2021-07-20 15:22:27.061+10:00 mounting store with swap                   topics="wakunode" tid=2016588 file=wakunode2.nim:422
DBG 2021-07-20 15:22:27.061+10:00 init                                       topics="wakunode" tid=2016588 file=waku_store.nim:430
TRC 2021-07-20 15:22:27.061+10:00 registering protocols                      topics="libp2p multistream" tid=2016588 file=multistream.nim:189 protos="@[\"/vac/waku/store/2.0.0-beta3\"]"
DBG 2021-07-20 15:22:27.061+10:00 initWakuRelay                              topics="wakurelay" tid=2016588 file=waku_relay.nim:46
DBG 2021-07-20 15:22:27.061+10:00 init                                       topics="wakurelay" tid=2016588 file=waku_relay.nim:24
DBG 2021-07-20 15:22:27.061+10:00 init                                       topics="wakurelay" tid=2016588 file=waku_relay.nim:24
INF 2021-07-20 15:22:27.061+10:00 mounting relay                             topics="wakunode" tid=2016588 file=wakunode2.nim:496 rlnRelayEnabled=false relayMessages=true
TRC 2021-07-20 15:22:27.061+10:00 registering protocols                      topics="libp2p multistream" tid=2016588 file=multistream.nim:189 protos="@[\"/vac/waku/relay/2.0.0\", \"/vac/waku/relay/2.0.0\"]"
INF 2021-07-20 15:22:27.061+10:00 subscribe                                  topics="wakunode" tid=2016588 file=wakunode2.nim:196 topic=/waku/2/default-waku/proto
DBG 2021-07-20 15:22:27.061+10:00 Registering default handler                topics="wakunode" tid=2016588 file=wakunode2.nim:217 topic=/waku/2/default-waku/proto
DBG 2021-07-20 15:22:27.061+10:00 subscribe                                  topics="wakurelay" tid=2016588 file=waku_relay.nim:66 pubSubTopic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.061+10:00 subscribing to topic                       topics="libp2p pubsub" tid=2016588 file=pubsub.nim:454 name=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.061+10:00 rebalancing mesh                           tid=2016588 file=behavior.nim:258 mesh=0 gossipsub=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.061+10:00 replenishing mesh                          tid=2016588 file=behavior.nim:267 peers=0 mesh=0 gossipsub=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.061+10:00 grafting                                   tid=2016588 file=behavior.nim:291 grafting=0 mesh=0 gossipsub=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.061+10:00 mesh balanced                              tid=2016588 file=behavior.nim:450 mesh=0 gossipsub=0 topic=/waku/2/default-waku/proto
INF 2021-07-20 15:22:27.061+10:00 subscribe                                  topics="wakunode" tid=2016588 file=wakunode2.nim:196 topic=/waku/2/default-waku/proto
DBG 2021-07-20 15:22:27.062+10:00 start                                      topics="wakurelay" tid=2016588 file=waku_relay.nim:92
TRC 2021-07-20 15:22:27.062+10:00 gossipsub start                            topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:515
TRC 2021-07-20 15:22:27.062+10:00 running heartbeat                          tid=2016588 file=behavior.nim:615 instance=140194462539848
TRC 2021-07-20 15:22:27.062+10:00 updating scores                            tid=2016588 file=scoring.nim:118 peers=0
TRC 2021-07-20 15:22:27.062+10:00 updated scores                             tid=2016588 file=scoring.nim:289 peers=0
TRC 2021-07-20 15:22:27.062+10:00 rebalancing mesh                           tid=2016588 file=behavior.nim:258 mesh=0 gossipsub=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.062+10:00 replenishing mesh                          tid=2016588 file=behavior.nim:267 peers=0 mesh=0 gossipsub=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.062+10:00 grafting                                   tid=2016588 file=behavior.nim:291 grafting=0 mesh=0 gossipsub=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.062+10:00 mesh balanced                              tid=2016588 file=behavior.nim:450 mesh=0 gossipsub=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.062+10:00 getting gossip peers (iHave)               tid=2016588 file=behavior.nim:499 ntopics=0
INF 2021-07-20 15:22:27.062+10:00 relay mounted and started successfully     topics="wakunode" tid=2016588 file=wakunode2.nim:535
INF 2021-07-20 15:22:27.062+10:00 mounting libp2p ping protocol              topics="wakunode" tid=2016588 file=wakunode2.nim:550
TRC 2021-07-20 15:22:27.062+10:00 registering protocols                      topics="libp2p multistream" tid=2016588 file=multistream.nim:189 protos="@[\"/ipfs/ping/1.0.0\"]"
DBG 2021-07-20 15:22:27.062+10:00 resume                                     topics="wakustore" tid=2016588 file=waku_store.nim:593 currentEpochTime=1626758547.062297
DBG 2021-07-20 15:22:27.062+10:00 the  offline time window is                topics="wakustore" tid=2016588 file=waku_store.nim:599 lastSeenTime=0.0 currentTime=1626958547.062297
DBG 2021-07-20 15:22:27.062+10:00 no candidate list is provided, selecting a random peer topics="wakustore" tid=2016588 file=waku_store.nim:649
ERR 2021-07-20 15:22:27.062+10:00 no suitable remote peers                   topics="wakustore" tid=2016588 file=waku_store.nim:653
INF 2021-07-20 15:22:27.062+10:00 Starting JSON-RPC HTTP server              topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:213 url=http://127.0.0.1:9957
DBG 2021-07-20 15:22:27.062+10:00 Adding API topic handler for existing subscription topics="relay api" tid=2016588 file=relay_api.nim:46 topic=/waku/2/default-waku/proto
INF 2021-07-20 15:22:27.062+10:00 subscribe                                  topics="wakunode" tid=2016588 file=wakunode2.nim:196 topic=/waku/2/default-waku/proto
DBG 2021-07-20 15:22:27.062+10:00 Registering handler                        topics="wakunode" tid=2016588 file=wakunode2.nim:221 topic=/waku/2/default-waku/proto
DBG 2021-07-20 15:22:27.062+10:00 subscribe                                  topics="wakurelay" tid=2016588 file=waku_relay.nim:66 pubSubTopic=/waku/2/default-waku/proto
DBG 2021-07-20 15:22:27.062+10:00 MessageCache for topic                     topics="relay api" tid=2016588 file=relay_api.nim:51 topic=/waku/2/default-waku/proto
DBG 2021-07-20 15:22:27.062+10:00 HTTP RPC server started                    topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:318 address=127.0.0.1:9957
INF 2021-07-20 15:22:27.062+10:00 RPC Server started                         topics="wakunode" tid=2016588 file=wakunode2.nim:693 ta=127.0.0.1:9957
DBG 2021-07-20 15:22:27.088+10:00 Received connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:94 address=127.0.0.1:47398
TRC 2021-07-20 15:22:27.088+10:00 Received valid RPC request                 topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:144 address=127.0.0.1:47398
DBG 2021-07-20 15:22:27.088+10:00 post_waku_v2_relay_v1_message              topics="relay api" tid=2016588 file=relay_api.nim:58
DBG 2021-07-20 15:22:27.088+10:00 publish                                    topics="wakunode" tid=2016588 file=wakunode2.nim:320 topic=/waku/2/default-waku/proto contentTopic=/waku/2/default-content/proto
DBG 2021-07-20 15:22:27.088+10:00 publish                                    topics="wakurelay" tid=2016588 file=waku_relay.nim:74 pubSubTopic=/waku/2/default-waku/proto message="@[10, 9, 77, 101, 115, 115, 97, 103, 101, 32, 48, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.088+10:00 Hit default handler                        topics="wakunode" tid=2016588 file=wakunode2.nim:200 topic=/waku/2/default-waku/proto data="@[10, 9, 77, 101, 115, 115, 97, 103, 101, 32, 48, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.088+10:00 handle message in WakuStore                topics="wakustore" tid=2016588 file=waku_store.nim:446 topic=/waku/2/default-waku/proto msg="(payload: @[77, 101, 115, 115, 97, 103, 101, 32, 48], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[])"
TRC 2021-07-20 15:22:27.088+10:00 Topic handler triggered                    topics="relay api" tid=2016588 file=relay_api.nim:22 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.088+10:00 WakuMessage received                       topics="relay api" tid=2016588 file=relay_api.nim:26 msg="Ok((payload: @[77, 101, 115, 115, 97, 103, 101, 32, 48], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[]))" topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.088+10:00 Publishing message on topic                topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:419 data=0a094d657373...000000aa0100 topic=/waku/2/default-waku/proto
NOT 2021-07-20 15:22:27.089+10:00 No peers for topic, skipping publish       topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:457 peersOnTopic=0 connectedPeers=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.089+10:00 RPC result has been sent                   topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:188 address=127.0.0.1:47398
DBG 2021-07-20 15:22:27.089+10:00 Disconnecting client                       topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:203 address=127.0.0.1:47398
DBG 2021-07-20 15:22:27.089+10:00 Finished connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:207 address=127.0.0.1:47398
DBG 2021-07-20 15:22:27.098+10:00 Received connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:94 address=127.0.0.1:47400
TRC 2021-07-20 15:22:27.098+10:00 Received valid RPC request                 topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:144 address=127.0.0.1:47400
DBG 2021-07-20 15:22:27.098+10:00 post_waku_v2_relay_v1_message              topics="relay api" tid=2016588 file=relay_api.nim:58
DBG 2021-07-20 15:22:27.098+10:00 publish                                    topics="wakunode" tid=2016588 file=wakunode2.nim:320 topic=/waku/2/default-waku/proto contentTopic=/waku/2/default-content/proto
DBG 2021-07-20 15:22:27.098+10:00 publish                                    topics="wakurelay" tid=2016588 file=waku_relay.nim:74 pubSubTopic=/waku/2/default-waku/proto message="@[10, 9, 77, 101, 115, 115, 97, 103, 101, 32, 49, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.098+10:00 Hit default handler                        topics="wakunode" tid=2016588 file=wakunode2.nim:200 topic=/waku/2/default-waku/proto data="@[10, 9, 77, 101, 115, 115, 97, 103, 101, 32, 49, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.098+10:00 handle message in WakuStore                topics="wakustore" tid=2016588 file=waku_store.nim:446 topic=/waku/2/default-waku/proto msg="(payload: @[77, 101, 115, 115, 97, 103, 101, 32, 49], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[])"
TRC 2021-07-20 15:22:27.098+10:00 Topic handler triggered                    topics="relay api" tid=2016588 file=relay_api.nim:22 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.098+10:00 WakuMessage received                       topics="relay api" tid=2016588 file=relay_api.nim:26 msg="Ok((payload: @[77, 101, 115, 115, 97, 103, 101, 32, 49], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[]))" topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.098+10:00 Publishing message on topic                topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:419 data=0a094d657373...000000aa0100 topic=/waku/2/default-waku/proto
NOT 2021-07-20 15:22:27.098+10:00 No peers for topic, skipping publish       topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:457 peersOnTopic=0 connectedPeers=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.098+10:00 RPC result has been sent                   topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:188 address=127.0.0.1:47400
DBG 2021-07-20 15:22:27.098+10:00 Disconnecting client                       topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:203 address=127.0.0.1:47400
DBG 2021-07-20 15:22:27.099+10:00 Finished connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:207 address=127.0.0.1:47400
DBG 2021-07-20 15:22:27.100+10:00 Received connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:94 address=127.0.0.1:47402
TRC 2021-07-20 15:22:27.101+10:00 Received valid RPC request                 topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:144 address=127.0.0.1:47402
DBG 2021-07-20 15:22:27.101+10:00 post_waku_v2_relay_v1_message              topics="relay api" tid=2016588 file=relay_api.nim:58
DBG 2021-07-20 15:22:27.101+10:00 publish                                    topics="wakunode" tid=2016588 file=wakunode2.nim:320 topic=/waku/2/default-waku/proto contentTopic=/waku/2/default-content/proto
DBG 2021-07-20 15:22:27.101+10:00 publish                                    topics="wakurelay" tid=2016588 file=waku_relay.nim:74 pubSubTopic=/waku/2/default-waku/proto message="@[10, 9, 77, 101, 115, 115, 97, 103, 101, 32, 50, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.101+10:00 Hit default handler                        topics="wakunode" tid=2016588 file=wakunode2.nim:200 topic=/waku/2/default-waku/proto data="@[10, 9, 77, 101, 115, 115, 97, 103, 101, 32, 50, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.101+10:00 handle message in WakuStore                topics="wakustore" tid=2016588 file=waku_store.nim:446 topic=/waku/2/default-waku/proto msg="(payload: @[77, 101, 115, 115, 97, 103, 101, 32, 50], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[])"
TRC 2021-07-20 15:22:27.101+10:00 Topic handler triggered                    topics="relay api" tid=2016588 file=relay_api.nim:22 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.101+10:00 WakuMessage received                       topics="relay api" tid=2016588 file=relay_api.nim:26 msg="Ok((payload: @[77, 101, 115, 115, 97, 103, 101, 32, 50], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[]))" topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.101+10:00 Publishing message on topic                topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:419 data=0a094d657373...000000aa0100 topic=/waku/2/default-waku/proto
NOT 2021-07-20 15:22:27.101+10:00 No peers for topic, skipping publish       topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:457 peersOnTopic=0 connectedPeers=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.101+10:00 RPC result has been sent                   topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:188 address=127.0.0.1:47402
DBG 2021-07-20 15:22:27.101+10:00 Disconnecting client                       topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:203 address=127.0.0.1:47402
DBG 2021-07-20 15:22:27.101+10:00 Finished connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:207 address=127.0.0.1:47402
DBG 2021-07-20 15:22:27.103+10:00 Received connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:94 address=127.0.0.1:47404
TRC 2021-07-20 15:22:27.103+10:00 Received valid RPC request                 topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:144 address=127.0.0.1:47404
DBG 2021-07-20 15:22:27.103+10:00 post_waku_v2_relay_v1_message              topics="relay api" tid=2016588 file=relay_api.nim:58
DBG 2021-07-20 15:22:27.103+10:00 publish                                    topics="wakunode" tid=2016588 file=wakunode2.nim:320 topic=/waku/2/default-waku/proto contentTopic=/waku/2/default-content/proto
DBG 2021-07-20 15:22:27.103+10:00 publish                                    topics="wakurelay" tid=2016588 file=waku_relay.nim:74 pubSubTopic=/waku/2/default-waku/proto message="@[10, 9, 77, 101, 115, 115, 97, 103, 101, 32, 51, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.103+10:00 Hit default handler                        topics="wakunode" tid=2016588 file=wakunode2.nim:200 topic=/waku/2/default-waku/proto data="@[10, 9, 77, 101, 115, 115, 97, 103, 101, 32, 51, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.103+10:00 handle message in WakuStore                topics="wakustore" tid=2016588 file=waku_store.nim:446 topic=/waku/2/default-waku/proto msg="(payload: @[77, 101, 115, 115, 97, 103, 101, 32, 51], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[])"
TRC 2021-07-20 15:22:27.104+10:00 Topic handler triggered                    topics="relay api" tid=2016588 file=relay_api.nim:22 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.104+10:00 WakuMessage received                       topics="relay api" tid=2016588 file=relay_api.nim:26 msg="Ok((payload: @[77, 101, 115, 115, 97, 103, 101, 32, 51], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[]))" topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.104+10:00 Publishing message on topic                topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:419 data=0a094d657373...000000aa0100 topic=/waku/2/default-waku/proto
NOT 2021-07-20 15:22:27.104+10:00 No peers for topic, skipping publish       topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:457 peersOnTopic=0 connectedPeers=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.104+10:00 RPC result has been sent                   topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:188 address=127.0.0.1:47404
DBG 2021-07-20 15:22:27.104+10:00 Disconnecting client                       topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:203 address=127.0.0.1:47404
DBG 2021-07-20 15:22:27.104+10:00 Finished connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:207 address=127.0.0.1:47404
DBG 2021-07-20 15:22:27.107+10:00 Received connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:94 address=127.0.0.1:47406
TRC 2021-07-20 15:22:27.107+10:00 Received valid RPC request                 topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:144 address=127.0.0.1:47406
DBG 2021-07-20 15:22:27.107+10:00 post_waku_v2_relay_v1_message              topics="relay api" tid=2016588 file=relay_api.nim:58
DBG 2021-07-20 15:22:27.107+10:00 publish                                    topics="wakunode" tid=2016588 file=wakunode2.nim:320 topic=/waku/2/default-waku/proto contentTopic=/waku/2/default-content/proto
DBG 2021-07-20 15:22:27.107+10:00 publish                                    topics="wakurelay" tid=2016588 file=waku_relay.nim:74 pubSubTopic=/waku/2/default-waku/proto message="@[10, 9, 77, 101, 115, 115, 97, 103, 101, 32, 52, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.107+10:00 Hit default handler                        topics="wakunode" tid=2016588 file=wakunode2.nim:200 topic=/waku/2/default-waku/proto data="@[10, 9, 77, 101, 115, 115, 97, 103, 101, 32, 52, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.107+10:00 handle message in WakuStore                topics="wakustore" tid=2016588 file=waku_store.nim:446 topic=/waku/2/default-waku/proto msg="(payload: @[77, 101, 115, 115, 97, 103, 101, 32, 52], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[])"
TRC 2021-07-20 15:22:27.107+10:00 Topic handler triggered                    topics="relay api" tid=2016588 file=relay_api.nim:22 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.107+10:00 WakuMessage received                       topics="relay api" tid=2016588 file=relay_api.nim:26 msg="Ok((payload: @[77, 101, 115, 115, 97, 103, 101, 32, 52], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[]))" topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.108+10:00 Publishing message on topic                topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:419 data=0a094d657373...000000aa0100 topic=/waku/2/default-waku/proto
NOT 2021-07-20 15:22:27.108+10:00 No peers for topic, skipping publish       topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:457 peersOnTopic=0 connectedPeers=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.108+10:00 RPC result has been sent                   topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:188 address=127.0.0.1:47406
DBG 2021-07-20 15:22:27.108+10:00 Disconnecting client                       topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:203 address=127.0.0.1:47406
DBG 2021-07-20 15:22:27.108+10:00 Finished connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:207 address=127.0.0.1:47406
DBG 2021-07-20 15:22:27.112+10:00 Received connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:94 address=127.0.0.1:47408
TRC 2021-07-20 15:22:27.112+10:00 Received valid RPC request                 topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:144 address=127.0.0.1:47408
DBG 2021-07-20 15:22:27.112+10:00 post_waku_v2_relay_v1_message              topics="relay api" tid=2016588 file=relay_api.nim:58
DBG 2021-07-20 15:22:27.112+10:00 publish                                    topics="wakunode" tid=2016588 file=wakunode2.nim:320 topic=/waku/2/default-waku/proto contentTopic=/waku/2/default-content/proto
DBG 2021-07-20 15:22:27.112+10:00 publish                                    topics="wakurelay" tid=2016588 file=waku_relay.nim:74 pubSubTopic=/waku/2/default-waku/proto message="@[10, 9, 77, 101, 115, 115, 97, 103, 101, 32, 53, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.112+10:00 Hit default handler                        topics="wakunode" tid=2016588 file=wakunode2.nim:200 topic=/waku/2/default-waku/proto data="@[10, 9, 77, 101, 115, 115, 97, 103, 101, 32, 53, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.112+10:00 handle message in WakuStore                topics="wakustore" tid=2016588 file=waku_store.nim:446 topic=/waku/2/default-waku/proto msg="(payload: @[77, 101, 115, 115, 97, 103, 101, 32, 53], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[])"
TRC 2021-07-20 15:22:27.112+10:00 Topic handler triggered                    topics="relay api" tid=2016588 file=relay_api.nim:22 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.112+10:00 WakuMessage received                       topics="relay api" tid=2016588 file=relay_api.nim:26 msg="Ok((payload: @[77, 101, 115, 115, 97, 103, 101, 32, 53], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[]))" topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.112+10:00 Publishing message on topic                topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:419 data=0a094d657373...000000aa0100 topic=/waku/2/default-waku/proto
NOT 2021-07-20 15:22:27.112+10:00 No peers for topic, skipping publish       topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:457 peersOnTopic=0 connectedPeers=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.112+10:00 RPC result has been sent                   topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:188 address=127.0.0.1:47408
DBG 2021-07-20 15:22:27.112+10:00 Disconnecting client                       topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:203 address=127.0.0.1:47408
DBG 2021-07-20 15:22:27.112+10:00 Finished connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:207 address=127.0.0.1:47408
DBG 2021-07-20 15:22:27.116+10:00 Received connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:94 address=127.0.0.1:47410
TRC 2021-07-20 15:22:27.116+10:00 Received valid RPC request                 topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:144 address=127.0.0.1:47410
DBG 2021-07-20 15:22:27.116+10:00 post_waku_v2_relay_v1_message              topics="relay api" tid=2016588 file=relay_api.nim:58
DBG 2021-07-20 15:22:27.116+10:00 publish                                    topics="wakunode" tid=2016588 file=wakunode2.nim:320 topic=/waku/2/default-waku/proto contentTopic=/waku/2/default-content/proto
DBG 2021-07-20 15:22:27.116+10:00 publish                                    topics="wakurelay" tid=2016588 file=waku_relay.nim:74 pubSubTopic=/waku/2/default-waku/proto message="@[10, 9, 77, 101, 115, 115, 97, 103, 101, 32, 54, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.116+10:00 Hit default handler                        topics="wakunode" tid=2016588 file=wakunode2.nim:200 topic=/waku/2/default-waku/proto data="@[10, 9, 77, 101, 115, 115, 97, 103, 101, 32, 54, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.116+10:00 handle message in WakuStore                topics="wakustore" tid=2016588 file=waku_store.nim:446 topic=/waku/2/default-waku/proto msg="(payload: @[77, 101, 115, 115, 97, 103, 101, 32, 54], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[])"
TRC 2021-07-20 15:22:27.117+10:00 Topic handler triggered                    topics="relay api" tid=2016588 file=relay_api.nim:22 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.117+10:00 WakuMessage received                       topics="relay api" tid=2016588 file=relay_api.nim:26 msg="Ok((payload: @[77, 101, 115, 115, 97, 103, 101, 32, 54], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[]))" topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.117+10:00 Publishing message on topic                topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:419 data=0a094d657373...000000aa0100 topic=/waku/2/default-waku/proto
NOT 2021-07-20 15:22:27.117+10:00 No peers for topic, skipping publish       topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:457 peersOnTopic=0 connectedPeers=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.117+10:00 RPC result has been sent                   topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:188 address=127.0.0.1:47410
DBG 2021-07-20 15:22:27.117+10:00 Disconnecting client                       topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:203 address=127.0.0.1:47410
DBG 2021-07-20 15:22:27.117+10:00 Finished connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:207 address=127.0.0.1:47410
DBG 2021-07-20 15:22:27.120+10:00 Received connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:94 address=127.0.0.1:47412
TRC 2021-07-20 15:22:27.120+10:00 Received valid RPC request                 topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:144 address=127.0.0.1:47412
DBG 2021-07-20 15:22:27.120+10:00 post_waku_v2_relay_v1_message              topics="relay api" tid=2016588 file=relay_api.nim:58
DBG 2021-07-20 15:22:27.120+10:00 publish                                    topics="wakunode" tid=2016588 file=wakunode2.nim:320 topic=/waku/2/default-waku/proto contentTopic=/waku/2/default-content/proto
DBG 2021-07-20 15:22:27.120+10:00 publish                                    topics="wakurelay" tid=2016588 file=waku_relay.nim:74 pubSubTopic=/waku/2/default-waku/proto message="@[10, 9, 77, 101, 115, 115, 97, 103, 101, 32, 55, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.120+10:00 Hit default handler                        topics="wakunode" tid=2016588 file=wakunode2.nim:200 topic=/waku/2/default-waku/proto data="@[10, 9, 77, 101, 115, 115, 97, 103, 101, 32, 55, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.120+10:00 handle message in WakuStore                topics="wakustore" tid=2016588 file=waku_store.nim:446 topic=/waku/2/default-waku/proto msg="(payload: @[77, 101, 115, 115, 97, 103, 101, 32, 55], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[])"
TRC 2021-07-20 15:22:27.120+10:00 Topic handler triggered                    topics="relay api" tid=2016588 file=relay_api.nim:22 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.120+10:00 WakuMessage received                       topics="relay api" tid=2016588 file=relay_api.nim:26 msg="Ok((payload: @[77, 101, 115, 115, 97, 103, 101, 32, 55], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[]))" topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.120+10:00 Publishing message on topic                topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:419 data=0a094d657373...000000aa0100 topic=/waku/2/default-waku/proto
NOT 2021-07-20 15:22:27.120+10:00 No peers for topic, skipping publish       topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:457 peersOnTopic=0 connectedPeers=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.120+10:00 RPC result has been sent                   topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:188 address=127.0.0.1:47412
DBG 2021-07-20 15:22:27.120+10:00 Disconnecting client                       topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:203 address=127.0.0.1:47412
DBG 2021-07-20 15:22:27.120+10:00 Finished connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:207 address=127.0.0.1:47412
DBG 2021-07-20 15:22:27.123+10:00 Received connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:94 address=127.0.0.1:47414
TRC 2021-07-20 15:22:27.123+10:00 Received valid RPC request                 topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:144 address=127.0.0.1:47414
DBG 2021-07-20 15:22:27.123+10:00 post_waku_v2_relay_v1_message              topics="relay api" tid=2016588 file=relay_api.nim:58
DBG 2021-07-20 15:22:27.123+10:00 publish                                    topics="wakunode" tid=2016588 file=wakunode2.nim:320 topic=/waku/2/default-waku/proto contentTopic=/waku/2/default-content/proto
DBG 2021-07-20 15:22:27.123+10:00 publish                                    topics="wakurelay" tid=2016588 file=waku_relay.nim:74 pubSubTopic=/waku/2/default-waku/proto message="@[10, 9, 77, 101, 115, 115, 97, 103, 101, 32, 56, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.123+10:00 Hit default handler                        topics="wakunode" tid=2016588 file=wakunode2.nim:200 topic=/waku/2/default-waku/proto data="@[10, 9, 77, 101, 115, 115, 97, 103, 101, 32, 56, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.123+10:00 handle message in WakuStore                topics="wakustore" tid=2016588 file=waku_store.nim:446 topic=/waku/2/default-waku/proto msg="(payload: @[77, 101, 115, 115, 97, 103, 101, 32, 56], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[])"
TRC 2021-07-20 15:22:27.123+10:00 Topic handler triggered                    topics="relay api" tid=2016588 file=relay_api.nim:22 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.123+10:00 WakuMessage received                       topics="relay api" tid=2016588 file=relay_api.nim:26 msg="Ok((payload: @[77, 101, 115, 115, 97, 103, 101, 32, 56], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[]))" topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.123+10:00 Publishing message on topic                topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:419 data=0a094d657373...000000aa0100 topic=/waku/2/default-waku/proto
NOT 2021-07-20 15:22:27.123+10:00 No peers for topic, skipping publish       topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:457 peersOnTopic=0 connectedPeers=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.123+10:00 RPC result has been sent                   topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:188 address=127.0.0.1:47414
DBG 2021-07-20 15:22:27.123+10:00 Disconnecting client                       topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:203 address=127.0.0.1:47414
DBG 2021-07-20 15:22:27.123+10:00 Finished connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:207 address=127.0.0.1:47414
DBG 2021-07-20 15:22:27.126+10:00 Received connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:94 address=127.0.0.1:47416
TRC 2021-07-20 15:22:27.126+10:00 Received valid RPC request                 topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:144 address=127.0.0.1:47416
DBG 2021-07-20 15:22:27.126+10:00 post_waku_v2_relay_v1_message              topics="relay api" tid=2016588 file=relay_api.nim:58
DBG 2021-07-20 15:22:27.126+10:00 publish                                    topics="wakunode" tid=2016588 file=wakunode2.nim:320 topic=/waku/2/default-waku/proto contentTopic=/waku/2/default-content/proto
DBG 2021-07-20 15:22:27.126+10:00 publish                                    topics="wakurelay" tid=2016588 file=waku_relay.nim:74 pubSubTopic=/waku/2/default-waku/proto message="@[10, 9, 77, 101, 115, 115, 97, 103, 101, 32, 57, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.126+10:00 Hit default handler                        topics="wakunode" tid=2016588 file=wakunode2.nim:200 topic=/waku/2/default-waku/proto data="@[10, 9, 77, 101, 115, 115, 97, 103, 101, 32, 57, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.126+10:00 handle message in WakuStore                topics="wakustore" tid=2016588 file=waku_store.nim:446 topic=/waku/2/default-waku/proto msg="(payload: @[77, 101, 115, 115, 97, 103, 101, 32, 57], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[])"
TRC 2021-07-20 15:22:27.126+10:00 Topic handler triggered                    topics="relay api" tid=2016588 file=relay_api.nim:22 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.126+10:00 WakuMessage received                       topics="relay api" tid=2016588 file=relay_api.nim:26 msg="Ok((payload: @[77, 101, 115, 115, 97, 103, 101, 32, 57], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[]))" topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.126+10:00 Publishing message on topic                topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:419 data=0a094d657373...000000aa0100 topic=/waku/2/default-waku/proto
NOT 2021-07-20 15:22:27.126+10:00 No peers for topic, skipping publish       topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:457 peersOnTopic=0 connectedPeers=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.127+10:00 RPC result has been sent                   topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:188 address=127.0.0.1:47416
DBG 2021-07-20 15:22:27.127+10:00 Disconnecting client                       topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:203 address=127.0.0.1:47416
DBG 2021-07-20 15:22:27.127+10:00 Finished connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:207 address=127.0.0.1:47416
DBG 2021-07-20 15:22:27.131+10:00 Received connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:94 address=127.0.0.1:47418
TRC 2021-07-20 15:22:27.131+10:00 Received valid RPC request                 topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:144 address=127.0.0.1:47418
DBG 2021-07-20 15:22:27.131+10:00 post_waku_v2_relay_v1_message              topics="relay api" tid=2016588 file=relay_api.nim:58
DBG 2021-07-20 15:22:27.131+10:00 publish                                    topics="wakunode" tid=2016588 file=wakunode2.nim:320 topic=/waku/2/default-waku/proto contentTopic=/waku/2/default-content/proto
DBG 2021-07-20 15:22:27.131+10:00 publish                                    topics="wakurelay" tid=2016588 file=waku_relay.nim:74 pubSubTopic=/waku/2/default-waku/proto message="@[10, 10, 77, 101, 115, 115, 97, 103, 101, 32, 49, 48, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.131+10:00 Hit default handler                        topics="wakunode" tid=2016588 file=wakunode2.nim:200 topic=/waku/2/default-waku/proto data="@[10, 10, 77, 101, 115, 115, 97, 103, 101, 32, 49, 48, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.131+10:00 handle message in WakuStore                topics="wakustore" tid=2016588 file=waku_store.nim:446 topic=/waku/2/default-waku/proto msg="(payload: @[77, 101, 115, 115, 97, 103, 101, 32, 49, 48], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[])"
TRC 2021-07-20 15:22:27.131+10:00 Topic handler triggered                    topics="relay api" tid=2016588 file=relay_api.nim:22 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.131+10:00 WakuMessage received                       topics="relay api" tid=2016588 file=relay_api.nim:26 msg="Ok((payload: @[77, 101, 115, 115, 97, 103, 101, 32, 49, 48], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[]))" topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.131+10:00 Publishing message on topic                topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:419 data=0a0a4d657373...000000aa0100 topic=/waku/2/default-waku/proto
NOT 2021-07-20 15:22:27.131+10:00 No peers for topic, skipping publish       topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:457 peersOnTopic=0 connectedPeers=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.131+10:00 RPC result has been sent                   topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:188 address=127.0.0.1:47418
DBG 2021-07-20 15:22:27.131+10:00 Disconnecting client                       topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:203 address=127.0.0.1:47418
DBG 2021-07-20 15:22:27.131+10:00 Finished connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:207 address=127.0.0.1:47418
DBG 2021-07-20 15:22:27.134+10:00 Received connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:94 address=127.0.0.1:47420
TRC 2021-07-20 15:22:27.134+10:00 Received valid RPC request                 topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:144 address=127.0.0.1:47420
DBG 2021-07-20 15:22:27.135+10:00 post_waku_v2_relay_v1_message              topics="relay api" tid=2016588 file=relay_api.nim:58
DBG 2021-07-20 15:22:27.135+10:00 publish                                    topics="wakunode" tid=2016588 file=wakunode2.nim:320 topic=/waku/2/default-waku/proto contentTopic=/waku/2/default-content/proto
DBG 2021-07-20 15:22:27.135+10:00 publish                                    topics="wakurelay" tid=2016588 file=waku_relay.nim:74 pubSubTopic=/waku/2/default-waku/proto message="@[10, 10, 77, 101, 115, 115, 97, 103, 101, 32, 49, 49, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.135+10:00 Hit default handler                        topics="wakunode" tid=2016588 file=wakunode2.nim:200 topic=/waku/2/default-waku/proto data="@[10, 10, 77, 101, 115, 115, 97, 103, 101, 32, 49, 49, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.135+10:00 handle message in WakuStore                topics="wakustore" tid=2016588 file=waku_store.nim:446 topic=/waku/2/default-waku/proto msg="(payload: @[77, 101, 115, 115, 97, 103, 101, 32, 49, 49], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[])"
TRC 2021-07-20 15:22:27.135+10:00 Topic handler triggered                    topics="relay api" tid=2016588 file=relay_api.nim:22 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.135+10:00 WakuMessage received                       topics="relay api" tid=2016588 file=relay_api.nim:26 msg="Ok((payload: @[77, 101, 115, 115, 97, 103, 101, 32, 49, 49], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[]))" topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.135+10:00 Publishing message on topic                topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:419 data=0a0a4d657373...000000aa0100 topic=/waku/2/default-waku/proto
NOT 2021-07-20 15:22:27.135+10:00 No peers for topic, skipping publish       topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:457 peersOnTopic=0 connectedPeers=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.135+10:00 RPC result has been sent                   topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:188 address=127.0.0.1:47420
DBG 2021-07-20 15:22:27.135+10:00 Disconnecting client                       topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:203 address=127.0.0.1:47420
DBG 2021-07-20 15:22:27.135+10:00 Finished connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:207 address=127.0.0.1:47420
DBG 2021-07-20 15:22:27.137+10:00 Received connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:94 address=127.0.0.1:47422
TRC 2021-07-20 15:22:27.137+10:00 Received valid RPC request                 topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:144 address=127.0.0.1:47422
DBG 2021-07-20 15:22:27.137+10:00 post_waku_v2_relay_v1_message              topics="relay api" tid=2016588 file=relay_api.nim:58
DBG 2021-07-20 15:22:27.137+10:00 publish                                    topics="wakunode" tid=2016588 file=wakunode2.nim:320 topic=/waku/2/default-waku/proto contentTopic=/waku/2/default-content/proto
DBG 2021-07-20 15:22:27.137+10:00 publish                                    topics="wakurelay" tid=2016588 file=waku_relay.nim:74 pubSubTopic=/waku/2/default-waku/proto message="@[10, 10, 77, 101, 115, 115, 97, 103, 101, 32, 49, 50, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.137+10:00 Hit default handler                        topics="wakunode" tid=2016588 file=wakunode2.nim:200 topic=/waku/2/default-waku/proto data="@[10, 10, 77, 101, 115, 115, 97, 103, 101, 32, 49, 50, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.137+10:00 handle message in WakuStore                topics="wakustore" tid=2016588 file=waku_store.nim:446 topic=/waku/2/default-waku/proto msg="(payload: @[77, 101, 115, 115, 97, 103, 101, 32, 49, 50], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[])"
TRC 2021-07-20 15:22:27.137+10:00 Topic handler triggered                    topics="relay api" tid=2016588 file=relay_api.nim:22 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.137+10:00 WakuMessage received                       topics="relay api" tid=2016588 file=relay_api.nim:26 msg="Ok((payload: @[77, 101, 115, 115, 97, 103, 101, 32, 49, 50], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[]))" topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.137+10:00 Publishing message on topic                topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:419 data=0a0a4d657373...000000aa0100 topic=/waku/2/default-waku/proto
NOT 2021-07-20 15:22:27.137+10:00 No peers for topic, skipping publish       topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:457 peersOnTopic=0 connectedPeers=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.137+10:00 RPC result has been sent                   topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:188 address=127.0.0.1:47422
DBG 2021-07-20 15:22:27.137+10:00 Disconnecting client                       topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:203 address=127.0.0.1:47422
DBG 2021-07-20 15:22:27.137+10:00 Finished connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:207 address=127.0.0.1:47422
DBG 2021-07-20 15:22:27.140+10:00 Received connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:94 address=127.0.0.1:47424
TRC 2021-07-20 15:22:27.140+10:00 Received valid RPC request                 topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:144 address=127.0.0.1:47424
DBG 2021-07-20 15:22:27.140+10:00 post_waku_v2_relay_v1_message              topics="relay api" tid=2016588 file=relay_api.nim:58
DBG 2021-07-20 15:22:27.140+10:00 publish                                    topics="wakunode" tid=2016588 file=wakunode2.nim:320 topic=/waku/2/default-waku/proto contentTopic=/waku/2/default-content/proto
DBG 2021-07-20 15:22:27.140+10:00 publish                                    topics="wakurelay" tid=2016588 file=waku_relay.nim:74 pubSubTopic=/waku/2/default-waku/proto message="@[10, 10, 77, 101, 115, 115, 97, 103, 101, 32, 49, 51, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.140+10:00 Hit default handler                        topics="wakunode" tid=2016588 file=wakunode2.nim:200 topic=/waku/2/default-waku/proto data="@[10, 10, 77, 101, 115, 115, 97, 103, 101, 32, 49, 51, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.140+10:00 handle message in WakuStore                topics="wakustore" tid=2016588 file=waku_store.nim:446 topic=/waku/2/default-waku/proto msg="(payload: @[77, 101, 115, 115, 97, 103, 101, 32, 49, 51], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[])"
TRC 2021-07-20 15:22:27.140+10:00 Topic handler triggered                    topics="relay api" tid=2016588 file=relay_api.nim:22 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.140+10:00 WakuMessage received                       topics="relay api" tid=2016588 file=relay_api.nim:26 msg="Ok((payload: @[77, 101, 115, 115, 97, 103, 101, 32, 49, 51], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[]))" topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.140+10:00 Publishing message on topic                topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:419 data=0a0a4d657373...000000aa0100 topic=/waku/2/default-waku/proto
NOT 2021-07-20 15:22:27.140+10:00 No peers for topic, skipping publish       topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:457 peersOnTopic=0 connectedPeers=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.140+10:00 RPC result has been sent                   topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:188 address=127.0.0.1:47424
DBG 2021-07-20 15:22:27.140+10:00 Disconnecting client                       topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:203 address=127.0.0.1:47424
DBG 2021-07-20 15:22:27.140+10:00 Finished connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:207 address=127.0.0.1:47424
DBG 2021-07-20 15:22:27.144+10:00 Received connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:94 address=127.0.0.1:47426
TRC 2021-07-20 15:22:27.144+10:00 Received valid RPC request                 topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:144 address=127.0.0.1:47426
DBG 2021-07-20 15:22:27.144+10:00 post_waku_v2_relay_v1_message              topics="relay api" tid=2016588 file=relay_api.nim:58
DBG 2021-07-20 15:22:27.144+10:00 publish                                    topics="wakunode" tid=2016588 file=wakunode2.nim:320 topic=/waku/2/default-waku/proto contentTopic=/waku/2/default-content/proto
DBG 2021-07-20 15:22:27.144+10:00 publish                                    topics="wakurelay" tid=2016588 file=waku_relay.nim:74 pubSubTopic=/waku/2/default-waku/proto message="@[10, 10, 77, 101, 115, 115, 97, 103, 101, 32, 49, 52, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.145+10:00 Hit default handler                        topics="wakunode" tid=2016588 file=wakunode2.nim:200 topic=/waku/2/default-waku/proto data="@[10, 10, 77, 101, 115, 115, 97, 103, 101, 32, 49, 52, 18, 29, 47, 119, 97, 107, 117, 47, 50, 47, 100, 101, 102, 97, 117, 108, 116, 45, 99, 111, 110, 116, 101, 110, 116, 47, 112, 114, 111, 116, 111, 24, 0, 33, 0, 0, 0, 0, 0, 0, 0, 0, 170, 1, 0]"
TRC 2021-07-20 15:22:27.145+10:00 handle message in WakuStore                topics="wakustore" tid=2016588 file=waku_store.nim:446 topic=/waku/2/default-waku/proto msg="(payload: @[77, 101, 115, 115, 97, 103, 101, 32, 49, 52], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[])"
TRC 2021-07-20 15:22:27.145+10:00 Topic handler triggered                    topics="relay api" tid=2016588 file=relay_api.nim:22 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.145+10:00 WakuMessage received                       topics="relay api" tid=2016588 file=relay_api.nim:26 msg="Ok((payload: @[77, 101, 115, 115, 97, 103, 101, 32, 49, 52], contentTopic: \"/waku/2/default-content/proto\", version: 0, timestamp: 0.0, proof: @[]))" topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.145+10:00 Publishing message on topic                topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:419 data=0a0a4d657373...000000aa0100 topic=/waku/2/default-waku/proto
NOT 2021-07-20 15:22:27.145+10:00 No peers for topic, skipping publish       topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:457 peersOnTopic=0 connectedPeers=0 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.145+10:00 RPC result has been sent                   topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:188 address=127.0.0.1:47426
DBG 2021-07-20 15:22:27.145+10:00 Disconnecting client                       topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:203 address=127.0.0.1:47426
DBG 2021-07-20 15:22:27.145+10:00 Finished connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:207 address=127.0.0.1:47426
DBG 2021-07-20 15:22:27.449+10:00 Received connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:94 address=127.0.0.1:47428
TRC 2021-07-20 15:22:27.450+10:00 Received valid RPC request                 topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:144 address=127.0.0.1:47428
DBG 2021-07-20 15:22:27.450+10:00 get_waku_v2_debug_v1_info                  topics="debug api" tid=2016588 file=debug_api.nim:15
TRC 2021-07-20 15:22:27.450+10:00 RPC result has been sent                   topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:188 address=127.0.0.1:47428
DBG 2021-07-20 15:22:27.450+10:00 Disconnecting client                       topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:203 address=127.0.0.1:47428
DBG 2021-07-20 15:22:27.450+10:00 Finished connection                        topics="JSONRPC-HTTP-SERVER" tid=2016588 file=httpserver.nim:207 address=127.0.0.1:47428
TRC 2021-07-20 15:22:27.471+10:00 Handling tcp connection                    topics="libp2p tcptransport" tid=2016588 file=tcptransport.nim:79 address=/ip4/127.0.0.1/tcp/52704 dir=In clients=0
TRC 2021-07-20 15:22:27.471+10:00 Stream created                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:133 s=60f65d93203c475a6b49af86 objName=ChronosStream dir=In
TRC 2021-07-20 15:22:27.471+10:00 Monitoring for timeout                     topics="libp2p connection" tid=2016588 file=connection.nim:81 s=60f65d93203c475a6b49af86 timeout=10m0ns
TRC 2021-07-20 15:22:27.471+10:00 Got connection                             topics="libp2p connmanager" tid=2016588 file=connmanager.nim:420 conn=60f65d93203c475a6b49af86
DBG 2021-07-20 15:22:27.472+10:00 Accepted an incoming connection            topics="libp2p switch" tid=2016588 file=switch.nim:193 conn=60f65d93203c475a6b49af86
TRC 2021-07-20 15:22:27.472+10:00 Upgrading incoming connection              topics="libp2p muxedupgrade" tid=2016588 file=muxedupgrade.nim:111 incomingConn=60f65d93203c475a6b49af86
TRC 2021-07-20 15:22:27.472+10:00 initiating handshake                       topics="libp2p multistream" tid=2016588 file=multistream.nim:59 conn=60f65d93203c475a6b49af86 codec="\x13/multistream/1.0.0\n"
DBG 2021-07-20 15:22:27.472+10:00 About to accept incoming connection        topics="libp2p switch" tid=2016588 file=switch.nim:167
TRC 2021-07-20 15:22:27.472+10:00 Acquired slot                              topics="libp2p semaphore" tid=2016588 file=semaphore.nim:38 available=2 queue=0
TRC 2021-07-20 15:22:27.472+10:00 Tracking incoming connection               topics="libp2p connmanager" tid=2016588 file=connmanager.nim:449
TRC 2021-07-20 15:22:27.472+10:00 Acquired slot                              topics="libp2p semaphore" tid=2016588 file=semaphore.nim:38 available=48 queue=0
TRC 2021-07-20 15:22:27.481+10:00 multistream handshake success              topics="libp2p multistream" tid=2016588 file=multistream.nim:73 conn=60f65d93203c475a6b49af86
TRC 2021-07-20 15:22:27.481+10:00 registering proto handler                  topics="libp2p multistream" tid=2016588 file=multistream.nim:205 proto=/noise
TRC 2021-07-20 15:22:27.481+10:00 Starting multistream handler               topics="libp2p multistream" tid=2016588 file=multistream.nim:129 conn=60f65d93203c475a6b49af86 handshaked=true
TRC 2021-07-20 15:22:27.481+10:00 handle: got request                        topics="libp2p multistream" tid=2016588 file=multistream.nim:141 conn=60f65d93203c475a6b49af86 ms=/noise
TRC 2021-07-20 15:22:27.481+10:00 found handler                              topics="libp2p multistream" tid=2016588 file=multistream.nim:170 conn=60f65d93203c475a6b49af86 protocol=/noise
TRC 2021-07-20 15:22:27.481+10:00 Starting secure handler                    topics="libp2p muxedupgrade" tid=2016588 file=muxedupgrade.nim:118 conn=60f65d93203c475a6b49af86
TRC 2021-07-20 15:22:27.481+10:00 Starting Noise handshake                   topics="libp2p noise" tid=2016588 file=noise.nim:501 conn=60f65d93203c475a6b49af86 initiator=false
TRC 2021-07-20 15:22:27.481+10:00 mixHash                                    topics="libp2p noise" tid=2016588 file=noise.nim:198 hash=f3d15e6108ed...2e0958dc002d
TRC 2021-07-20 15:22:27.507+10:00 readFrame                                  topics="libp2p noise" tid=2016588 file=noise.nim:309 sconn=60f65d93203c475a6b49af86 size=32
TRC 2021-07-20 15:22:27.507+10:00 noise read e                               topics="libp2p noise" tid=2016588 file=noise.nim:276 size=32
TRC 2021-07-20 15:22:27.507+10:00 mixHash                                    topics="libp2p noise" tid=2016588 file=noise.nim:198 hash=791fd4708185...d7fb3a8b9790
TRC 2021-07-20 15:22:27.507+10:00 mixHash                                    topics="libp2p noise" tid=2016588 file=noise.nim:198 hash=cd6e71ed8121...2601d90143a3
TRC 2021-07-20 15:22:27.507+10:00 noise write e                              topics="libp2p noise" tid=2016588 file=noise.nim:237
TRC 2021-07-20 15:22:27.507+10:00 mixHash                                    topics="libp2p noise" tid=2016588 file=noise.nim:198 hash=a89152912422...7fe9cab1b51a
TRC 2021-07-20 15:22:27.507+10:00 noise dh ee                                topics="libp2p noise" tid=2016588 file=noise.nim:249
TRC 2021-07-20 15:22:27.508+10:00 mixKey                                     topics="libp2p noise" tid=2016588 file=noise.nim:190 key=5f9215260abd...56c2979c939c
TRC 2021-07-20 15:22:27.508+10:00 noise write s                              topics="libp2p noise" tid=2016588 file=noise.nim:244
TRC 2021-07-20 15:22:27.508+10:00 encryptWithAd                              topics="libp2p noise" tid=2016588 file=noise.nim:157 tag=396f567c69bc7dcb0c5a9e0f6cd0bdbb data=f65c4bf139d2...9e0f6cd0bdbb nonce=0
TRC 2021-07-20 15:22:27.508+10:00 mixHash                                    topics="libp2p noise" tid=2016588 file=noise.nim:198 hash=f5b3ff76339c...d5a8b0c735b4
TRC 2021-07-20 15:22:27.508+10:00 noise dh es                                topics="libp2p noise" tid=2016588 file=noise.nim:254
TRC 2021-07-20 15:22:27.508+10:00 mixKey                                     topics="libp2p noise" tid=2016588 file=noise.nim:190 key=32be39dbaeaf...2f7030d64ec7
TRC 2021-07-20 15:22:27.508+10:00 encryptWithAd                              topics="libp2p noise" tid=2016588 file=noise.nim:157 tag=8f6829532c9a3dcd42081604a5dfcb59 data=86bc6441a385...1604a5dfcb59 nonce=0
TRC 2021-07-20 15:22:27.508+10:00 mixHash                                    topics="libp2p noise" tid=2016588 file=noise.nim:198 hash=dae6d5657827...36fa989cdcc3
TRC 2021-07-20 15:22:27.508+10:00 writeFrame                                 topics="libp2p noise" tid=2016588 file=noise.nim:323 sconn=60f65d93203c475a6b49af86 size=208 data=256c079ad98d...1604a5dfcb59
TRC 2021-07-20 15:22:27.571+10:00 readFrame                                  topics="libp2p noise" tid=2016588 file=noise.nim:309 sconn=60f65d93203c475a6b49af86 size=627
TRC 2021-07-20 15:22:27.571+10:00 noise read s                               topics="libp2p noise" tid=2016588 file=noise.nim:287 size=627
TRC 2021-07-20 15:22:27.571+10:00 decryptWithAd                              topics="libp2p noise" tid=2016588 file=noise.nim:169 tagIn=4c6bd2e66b7a...c7d8b310cb70 tagOut=4c6bd2e66b7a...c7d8b310cb70 nonce=1
TRC 2021-07-20 15:22:27.571+10:00 mixHash                                    topics="libp2p noise" tid=2016588 file=noise.nim:198 hash=c04ba49939c4...153a4d48f4bf
TRC 2021-07-20 15:22:27.571+10:00 noise dh se                                topics="libp2p noise" tid=2016588 file=noise.nim:262
TRC 2021-07-20 15:22:27.571+10:00 mixKey                                     topics="libp2p noise" tid=2016588 file=noise.nim:190 key=d36afbec654e...5159f0769cbc
TRC 2021-07-20 15:22:27.571+10:00 decryptWithAd                              topics="libp2p noise" tid=2016588 file=noise.nim:169 tagIn=776a90094ede...88fa25c9a425 tagOut=776a90094ede...88fa25c9a425 nonce=0
TRC 2021-07-20 15:22:27.571+10:00 mixHash                                    topics="libp2p noise" tid=2016588 file=noise.nim:198 hash=ea243ccf348d...2bc248a5e3d3
TRC 2021-07-20 15:22:27.572+10:00 Remote signature verified                  topics="libp2p noise" tid=2016588 file=noise.nim:548 conn=60f65d93203c475a6b49af86
TRC 2021-07-20 15:22:27.572+10:00 Stream created                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:133 s=60f65d93203c475a6b49af87 objName=SecureConn dir=In
TRC 2021-07-20 15:22:27.572+10:00 Monitoring for timeout                     topics="libp2p connection" tid=2016588 file=connection.nim:81 s=QmP*aKRBqV:60f65d93203c475a6b49af87 timeout=5m0ns
TRC 2021-07-20 15:22:27.572+10:00 Noise handshake completed!                 topics="libp2p noise" tid=2016588 file=noise.nim:582 initiator=false peer="(peerId: \"QmPa3wMicdoXochos9Zop9GEn6tZfMpKyCV6i4cXaKRBqV\", addrs: @[], protocols: @[], protoVersion: \"\", agentVersion: \"\")"
TRC 2021-07-20 15:22:27.572+10:00 registering protocols                      topics="libp2p multistream" tid=2016588 file=multistream.nim:189 protos="@[\"/mplex/6.7.0\"]"
TRC 2021-07-20 15:22:27.572+10:00 Starting multistream handler               topics="libp2p multistream" tid=2016588 file=multistream.nim:129 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 handshaked=false
TRC 2021-07-20 15:22:27.572+10:00 readFrame                                  topics="libp2p noise" tid=2016588 file=noise.nim:309 sconn=QmP*aKRBqV:60f65d93203c475a6b49af86 size=50
TRC 2021-07-20 15:22:27.572+10:00 decryptWithAd                              topics="libp2p noise" tid=2016588 file=noise.nim:169 tagIn=6f1315264ffc...4d8883e00313 tagOut=6f1315264ffc...4d8883e00313 nonce=0
TRC 2021-07-20 15:22:27.572+10:00 handle: got request                        topics="libp2p multistream" tid=2016588 file=multistream.nim:141 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 ms=/multistream/1.0.0
TRC 2021-07-20 15:22:27.572+10:00 handle: got request                        topics="libp2p multistream" tid=2016588 file=multistream.nim:141 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 ms=/mplex/6.7.0
TRC 2021-07-20 15:22:27.572+10:00 found handler                              topics="libp2p multistream" tid=2016588 file=multistream.nim:170 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 protocol=/mplex/6.7.0
TRC 2021-07-20 15:22:27.572+10:00 starting muxer handler                     topics="libp2p muxer" tid=2016588 file=muxer.nim:66 proto=/mplex/6.7.0 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.572+10:00 Starting mplex handler                     topics="libp2p mplex" tid=2016588 file=mplex.nim:125 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.573+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.573+10:00 Stored connection                          topics="libp2p connmanager" tid=2016588 file=connmanager.nim:406 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 direction=In connections=1
TRC 2021-07-20 15:22:27.573+10:00 Stored muxer                               topics="libp2p connmanager" tid=2016588 file=connmanager.nim:511 muxer=QmP*aKRBqV:60f65d93203c475a6b49af87 handle=false connections=1
TRC 2021-07-20 15:22:27.573+10:00 Triggering connect events                  topics="libp2p connmanager" tid=2016588 file=connmanager.nim:293 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.573+10:00 About to trigger peer events               topics="libp2p connmanager" tid=2016588 file=connmanager.nim:185 peer=QmP*aKRBqV
TRC 2021-07-20 15:22:27.573+10:00 triggering peer events                     topics="libp2p connmanager" tid=2016588 file=connmanager.nim:198 peer=QmP*aKRBqV event="(kind: Joined, initiator: false)"
DBG 2021-07-20 15:22:27.573+10:00 created new pubsub peer                    topics="libp2p pubsub" tid=2016588 file=pubsub.nim:287 peerId=QmP*aKRBqV
TRC 2021-07-20 15:22:27.573+10:00 Dialing (existing)                         topics="libp2p dialer" tid=2016588 file=dialer.nim:185 peerId=QmP*aKRBqV protos="@[\"/vac/waku/relay/2.0.0\", \"/vac/waku/relay/2.0.0\"]"
TRC 2021-07-20 15:22:27.573+10:00 Stream created                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:133 s=60f65d93203c475a6b49af89 objName=LPChannel dir=Out
TRC 2021-07-20 15:22:27.573+10:00 Monitoring for timeout                     topics="libp2p connection" tid=2016588 file=connection.nim:81 s=60f65d93203c475a6b49af89 timeout=5m0ns
TRC 2021-07-20 15:22:27.573+10:00 BufferStream created                       topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:59 s=60f65d93203c475a6b49af89
TRC 2021-07-20 15:22:27.573+10:00 Created new lpchannel                      topics="libp2p mplex" tid=2016588 file=lpchannel.nim:231 s=QmP*aKRBqV:60f65d93203c475a6b49af89 id=1 initiator=true
TRC 2021-07-20 15:22:27.573+10:00 Creating new channel                       topics="libp2p mplex" tid=2016588 file=mplex.nim:101 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af89 id=1 initiator=true name=
TRC 2021-07-20 15:22:27.573+10:00 Opening channel                            topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:67 s=QmP*aKRBqV:60f65d93203c475a6b49af89 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.573+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=1 msgType=New data=24 encoded=26
TRC 2021-07-20 15:22:27.574+10:00 About to trigger connection events         topics="libp2p connmanager" tid=2016588 file=connmanager.nim:139 peer=QmP*aKRBqV
TRC 2021-07-20 15:22:27.574+10:00 triggering connection events               topics="libp2p connmanager" tid=2016588 file=connmanager.nim:141 peer=QmP*aKRBqV event=Connected
TRC 2021-07-20 15:22:27.574+10:00 Stream created                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:133 s=60f65d93203c475a6b49af8a objName=LPChannel dir=Out
TRC 2021-07-20 15:22:27.574+10:00 Monitoring for timeout                     topics="libp2p connection" tid=2016588 file=connection.nim:81 s=60f65d93203c475a6b49af8a timeout=5m0ns
TRC 2021-07-20 15:22:27.574+10:00 BufferStream created                       topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:59 s=60f65d93203c475a6b49af8a
TRC 2021-07-20 15:22:27.574+10:00 Created new lpchannel                      topics="libp2p mplex" tid=2016588 file=lpchannel.nim:231 s=QmP*aKRBqV:60f65d93203c475a6b49af8a id=2 initiator=true
TRC 2021-07-20 15:22:27.574+10:00 Creating new channel                       topics="libp2p mplex" tid=2016588 file=mplex.nim:101 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8a id=2 initiator=true name=
TRC 2021-07-20 15:22:27.574+10:00 Opening channel                            topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:67 s=QmP*aKRBqV:60f65d93203c475a6b49af8a conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.574+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=2 msgType=New data=24 encoded=26
TRC 2021-07-20 15:22:27.574+10:00 Connection upgrade succeeded               topics="libp2p switch" tid=2016588 file=switch.nim:149
TRC 2021-07-20 15:22:27.574+10:00 Releasing slot                             topics="libp2p semaphore" tid=2016588 file=semaphore.nim:77 available=2 queue=0
TRC 2021-07-20 15:22:27.574+10:00 Released slot                              topics="libp2p semaphore" tid=2016588 file=semaphore.nim:87 available=3 queue=0
TRC 2021-07-20 15:22:27.574+10:00 Negotiating stream                         topics="libp2p dialer" tid=2016588 file=dialer.nim:169 conn=QmP*aKRBqV:60f65d93203c475a6b49af89 protos="@[\"/vac/waku/relay/2.0.0\", \"/vac/waku/relay/2.0.0\"]"
TRC 2021-07-20 15:22:27.574+10:00 initiating handshake                       topics="libp2p multistream" tid=2016588 file=multistream.nim:59 conn=QmP*aKRBqV:60f65d93203c475a6b49af89 codec="\x13/multistream/1.0.0\n"
TRC 2021-07-20 15:22:27.574+10:00 write msg                                  topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:194 s=QmP*aKRBqV:60f65d93203c475a6b49af89 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=20
TRC 2021-07-20 15:22:27.574+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=1 msgType=MsgOut data=20 encoded=22
TRC 2021-07-20 15:22:27.574+10:00 initiating handshake                       topics="libp2p multistream" tid=2016588 file=multistream.nim:59 conn=QmP*aKRBqV:60f65d93203c475a6b49af8a codec="\x13/multistream/1.0.0\n"
TRC 2021-07-20 15:22:27.574+10:00 write msg                                  topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:194 s=QmP*aKRBqV:60f65d93203c475a6b49af8a conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=20
TRC 2021-07-20 15:22:27.574+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=2 msgType=MsgOut data=20 encoded=22
TRC 2021-07-20 15:22:27.574+10:00 selecting proto                            topics="libp2p multistream" tid=2016588 file=multistream.nim:63 conn=QmP*aKRBqV:60f65d93203c475a6b49af89 proto=/vac/waku/relay/2.0.0
TRC 2021-07-20 15:22:27.574+10:00 write msg                                  topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:194 s=QmP*aKRBqV:60f65d93203c475a6b49af89 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=23
TRC 2021-07-20 15:22:27.574+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=1 msgType=MsgOut data=23 encoded=25
TRC 2021-07-20 15:22:27.574+10:00 selecting proto                            topics="libp2p multistream" tid=2016588 file=multistream.nim:63 conn=QmP*aKRBqV:60f65d93203c475a6b49af8a proto=/ipfs/id/1.0.0
TRC 2021-07-20 15:22:27.574+10:00 write msg                                  topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:194 s=QmP*aKRBqV:60f65d93203c475a6b49af8a conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=16
TRC 2021-07-20 15:22:27.575+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=2 msgType=MsgOut data=16 encoded=18
TRC 2021-07-20 15:22:27.583+10:00 readFrame                                  topics="libp2p noise" tid=2016588 file=noise.nim:309 sconn=QmP*aKRBqV:60f65d93203c475a6b49af86 size=19
TRC 2021-07-20 15:22:27.583+10:00 decryptWithAd                              topics="libp2p noise" tid=2016588 file=noise.nim:169 tagIn=1b5783e3df56...1ed247dc8789 tagOut=1b5783e3df56...1ed247dc8789 nonce=1
TRC 2021-07-20 15:22:27.583+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=0 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.583+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=1 data=30 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.583+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data=30 msgType=New id=0 initiator=false size=1
TRC 2021-07-20 15:22:27.583+10:00 Stream created                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:133 s=60f65d93203c475a6b49af8b objName=LPChannel dir=In
TRC 2021-07-20 15:22:27.583+10:00 Monitoring for timeout                     topics="libp2p connection" tid=2016588 file=connection.nim:81 s=60f65d93203c475a6b49af8b timeout=5m0ns
TRC 2021-07-20 15:22:27.583+10:00 BufferStream created                       topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:59 s=60f65d93203c475a6b49af8b
TRC 2021-07-20 15:22:27.583+10:00 Created new lpchannel                      topics="libp2p mplex" tid=2016588 file=lpchannel.nim:231 s=QmP*aKRBqV:60f65d93203c475a6b49af8b:0 id=0 initiator=false
TRC 2021-07-20 15:22:27.583+10:00 Creating new channel                       topics="libp2p mplex" tid=2016588 file=mplex.nim:101 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8b:0 id=0 initiator=false name=0
TRC 2021-07-20 15:22:27.583+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8b:0 data=30 msgType=New id=0 initiator=false size=1
TRC 2021-07-20 15:22:27.583+10:00 created channel                            topics="libp2p mplex" tid=2016588 file=mplex.nim:162 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8b:0 msgType=New id=0 initiator=false size=1
TRC 2021-07-20 15:22:27.583+10:00 Starting stream handler                    tid=2016588 file=muxedupgrade.nim:213 conn=QmP*aKRBqV:60f65d93203c475a6b49af8b
TRC 2021-07-20 15:22:27.583+10:00 Starting multistream handler               topics="libp2p multistream" tid=2016588 file=multistream.nim:129 conn=QmP*aKRBqV:60f65d93203c475a6b49af8b handshaked=false
TRC 2021-07-20 15:22:27.584+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.625+10:00 readFrame                                  topics="libp2p noise" tid=2016588 file=noise.nim:309 sconn=QmP*aKRBqV:60f65d93203c475a6b49af86 size=102
TRC 2021-07-20 15:22:27.625+10:00 decryptWithAd                              topics="libp2p noise" tid=2016588 file=noise.nim:169 tagIn=5c10bd47c73b...2f5ef2a60d6b tagOut=5c10bd47c73b...2f5ef2a60d6b nonce=2
TRC 2021-07-20 15:22:27.625+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=2 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.625+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=36 data=132f6d756c74...312e302e300a conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.625+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data=132f6d756c74...312e302e300a msgType=MsgOut id=0 initiator=false size=36
TRC 2021-07-20 15:22:27.625+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8b:0 data=132f6d756c74...312e302e300a msgType=MsgOut id=0 initiator=false size=36
TRC 2021-07-20 15:22:27.625+10:00 pushing data to channel                    topics="libp2p mplex" tid=2016588 file=mplex.nim:175 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8b:0 len=36 msgType=MsgOut id=0 initiator=false size=36
TRC 2021-07-20 15:22:27.625+10:00 Pushing data                               topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:93 s=QmP*aKRBqV:60f65d93203c475a6b49af8b data=36
TRC 2021-07-20 15:22:27.625+10:00 pushed data to channel                     topics="libp2p mplex" tid=2016588 file=mplex.nim:177 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8b:0 len=36 msgType=MsgOut id=0 initiator=false size=36
TRC 2021-07-20 15:22:27.625+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.625+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=8 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.625+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=1 data=31 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.625+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data=31 msgType=New id=1 initiator=false size=1
TRC 2021-07-20 15:22:27.625+10:00 Stream created                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:133 s=60f65d93203c475a6b49af8c objName=LPChannel dir=In
TRC 2021-07-20 15:22:27.625+10:00 Monitoring for timeout                     topics="libp2p connection" tid=2016588 file=connection.nim:81 s=60f65d93203c475a6b49af8c timeout=5m0ns
TRC 2021-07-20 15:22:27.625+10:00 BufferStream created                       topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:59 s=60f65d93203c475a6b49af8c
TRC 2021-07-20 15:22:27.625+10:00 Created new lpchannel                      topics="libp2p mplex" tid=2016588 file=lpchannel.nim:231 s=QmP*aKRBqV:60f65d93203c475a6b49af8c:1 id=1 initiator=false
TRC 2021-07-20 15:22:27.625+10:00 Creating new channel                       topics="libp2p mplex" tid=2016588 file=mplex.nim:101 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8c:1 id=1 initiator=false name=1
TRC 2021-07-20 15:22:27.625+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8c:1 data=31 msgType=New id=1 initiator=false size=1
TRC 2021-07-20 15:22:27.625+10:00 created channel                            topics="libp2p mplex" tid=2016588 file=mplex.nim:162 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8c:1 msgType=New id=1 initiator=false size=1
TRC 2021-07-20 15:22:27.625+10:00 Starting stream handler                    tid=2016588 file=muxedupgrade.nim:213 conn=QmP*aKRBqV:60f65d93203c475a6b49af8c
TRC 2021-07-20 15:22:27.625+10:00 Starting multistream handler               topics="libp2p multistream" tid=2016588 file=multistream.nim:129 conn=QmP*aKRBqV:60f65d93203c475a6b49af8c handshaked=false
TRC 2021-07-20 15:22:27.625+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.625+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=10 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.625+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=43 data=132f6d756c74...322e302e300a conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.625+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data=132f6d756c74...322e302e300a msgType=MsgOut id=1 initiator=false size=43
TRC 2021-07-20 15:22:27.625+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8c:1 data=132f6d756c74...322e302e300a msgType=MsgOut id=1 initiator=false size=43
TRC 2021-07-20 15:22:27.625+10:00 pushing data to channel                    topics="libp2p mplex" tid=2016588 file=mplex.nim:175 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8c:1 len=43 msgType=MsgOut id=1 initiator=false size=43
TRC 2021-07-20 15:22:27.625+10:00 Pushing data                               topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:93 s=QmP*aKRBqV:60f65d93203c475a6b49af8c data=43
TRC 2021-07-20 15:22:27.625+10:00 pushed data to channel                     topics="libp2p mplex" tid=2016588 file=mplex.nim:177 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8c:1 len=43 msgType=MsgOut id=1 initiator=false size=43
TRC 2021-07-20 15:22:27.625+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.626+10:00 readFrame                                  topics="libp2p noise" tid=2016588 file=noise.nim:309 sconn=QmP*aKRBqV:60f65d93203c475a6b49af86 size=38
TRC 2021-07-20 15:22:27.626+10:00 decryptWithAd                              topics="libp2p noise" tid=2016588 file=noise.nim:169 tagIn=3e92f07f1772...e2587e9d78be tagOut=3e92f07f1772...e2587e9d78be nonce=3
TRC 2021-07-20 15:22:27.626+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=9 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.626+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=20 data=132f6d756c74...312e302e300a conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.626+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data=132f6d756c74...312e302e300a msgType=MsgIn id=1 initiator=true size=20
TRC 2021-07-20 15:22:27.626+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af89 data=132f6d756c74...312e302e300a msgType=MsgIn id=1 initiator=true size=20
TRC 2021-07-20 15:22:27.626+10:00 pushing data to channel                    topics="libp2p mplex" tid=2016588 file=mplex.nim:175 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af89 len=20 msgType=MsgIn id=1 initiator=true size=20
TRC 2021-07-20 15:22:27.626+10:00 Pushing data                               topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:93 s=QmP*aKRBqV:60f65d93203c475a6b49af89 data=20
TRC 2021-07-20 15:22:27.626+10:00 pushed data to channel                     topics="libp2p mplex" tid=2016588 file=mplex.nim:177 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af89 len=20 msgType=MsgIn id=1 initiator=true size=20
TRC 2021-07-20 15:22:27.626+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.626+10:00 readFrame                                  topics="libp2p noise" tid=2016588 file=noise.nim:309 sconn=QmP*aKRBqV:60f65d93203c475a6b49af86 size=38
TRC 2021-07-20 15:22:27.626+10:00 decryptWithAd                              topics="libp2p noise" tid=2016588 file=noise.nim:169 tagIn=612a5bd567c1...f6cfee3dcd22 tagOut=612a5bd567c1...f6cfee3dcd22 nonce=4
TRC 2021-07-20 15:22:27.626+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=17 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.626+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=20 data=132f6d756c74...312e302e300a conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.626+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data=132f6d756c74...312e302e300a msgType=MsgIn id=2 initiator=true size=20
TRC 2021-07-20 15:22:27.626+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8a data=132f6d756c74...312e302e300a msgType=MsgIn id=2 initiator=true size=20
TRC 2021-07-20 15:22:27.626+10:00 pushing data to channel                    topics="libp2p mplex" tid=2016588 file=mplex.nim:175 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8a len=20 msgType=MsgIn id=2 initiator=true size=20
TRC 2021-07-20 15:22:27.626+10:00 Pushing data                               topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:93 s=QmP*aKRBqV:60f65d93203c475a6b49af8a data=20
TRC 2021-07-20 15:22:27.626+10:00 pushed data to channel                     topics="libp2p mplex" tid=2016588 file=mplex.nim:177 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8a len=20 msgType=MsgIn id=2 initiator=true size=20
TRC 2021-07-20 15:22:27.626+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.626+10:00 readFrame                                  topics="libp2p noise" tid=2016588 file=noise.nim:309 sconn=QmP*aKRBqV:60f65d93203c475a6b49af86 size=59
TRC 2021-07-20 15:22:27.626+10:00 decryptWithAd                              topics="libp2p noise" tid=2016588 file=noise.nim:169 tagIn=03d3073a55d7...bca9fd6c3f78 tagOut=03d3073a55d7...bca9fd6c3f78 nonce=5
TRC 2021-07-20 15:22:27.626+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=9 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.626+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=23 data=162f7661632f...322e302e300a conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.626+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data=162f7661632f...322e302e300a msgType=MsgIn id=1 initiator=true size=23
TRC 2021-07-20 15:22:27.626+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af89 data=162f7661632f...322e302e300a msgType=MsgIn id=1 initiator=true size=23
TRC 2021-07-20 15:22:27.626+10:00 pushing data to channel                    topics="libp2p mplex" tid=2016588 file=mplex.nim:175 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af89 len=23 msgType=MsgIn id=1 initiator=true size=23
TRC 2021-07-20 15:22:27.626+10:00 Pushing data                               topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:93 s=QmP*aKRBqV:60f65d93203c475a6b49af89 data=23
TRC 2021-07-20 15:22:27.626+10:00 add leftovers                              topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:163 s=QmP*aKRBqV:60f65d93203c475a6b49af8b len=35
TRC 2021-07-20 15:22:27.626+10:00 add leftovers                              topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:163 s=QmP*aKRBqV:60f65d93203c475a6b49af8c len=42
TRC 2021-07-20 15:22:27.626+10:00 add leftovers                              topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:163 s=QmP*aKRBqV:60f65d93203c475a6b49af89 len=19
TRC 2021-07-20 15:22:27.626+10:00 add leftovers                              topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:163 s=QmP*aKRBqV:60f65d93203c475a6b49af8a len=19
TRC 2021-07-20 15:22:27.626+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8b:0 bytes=1
TRC 2021-07-20 15:22:27.626+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8c:1 bytes=1
TRC 2021-07-20 15:22:27.626+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af89 bytes=1
TRC 2021-07-20 15:22:27.626+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8a bytes=1
TRC 2021-07-20 15:22:27.626+10:00 pushed data to channel                     topics="libp2p mplex" tid=2016588 file=mplex.nim:177 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af89 len=23 msgType=MsgIn id=1 initiator=true size=23
TRC 2021-07-20 15:22:27.626+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.626+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=17 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.626+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=16 data=0f2f69706673...312e302e300a conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.626+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data=0f2f69706673...312e302e300a msgType=MsgIn id=2 initiator=true size=16
TRC 2021-07-20 15:22:27.626+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8a data=0f2f69706673...312e302e300a msgType=MsgIn id=2 initiator=true size=16
TRC 2021-07-20 15:22:27.626+10:00 pushing data to channel                    topics="libp2p mplex" tid=2016588 file=mplex.nim:175 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8a len=16 msgType=MsgIn id=2 initiator=true size=16
TRC 2021-07-20 15:22:27.626+10:00 Pushing data                               topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:93 s=QmP*aKRBqV:60f65d93203c475a6b49af8a data=16
TRC 2021-07-20 15:22:27.626+10:00 pushed data to channel                     topics="libp2p mplex" tid=2016588 file=mplex.nim:177 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8a len=16 msgType=MsgIn id=2 initiator=true size=16
TRC 2021-07-20 15:22:27.626+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.626+10:00 readFrame                                  topics="libp2p noise" tid=2016588 file=noise.nim:309 sconn=QmP*aKRBqV:60f65d93203c475a6b49af86 size=514
TRC 2021-07-20 15:22:27.626+10:00 decryptWithAd                              topics="libp2p noise" tid=2016588 file=noise.nim:169 tagIn=eca1c0e07a75...747f46200f19 tagOut=eca1c0e07a75...747f46200f19 nonce=6
TRC 2021-07-20 15:22:27.627+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=17 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.627+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=493 data=eb030aab0208...302e33312e37 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.627+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data=eb030aab0208...302e33312e37 msgType=MsgIn id=2 initiator=true size=493
TRC 2021-07-20 15:22:27.627+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8a data=eb030aab0208...302e33312e37 msgType=MsgIn id=2 initiator=true size=493
TRC 2021-07-20 15:22:27.627+10:00 pushing data to channel                    topics="libp2p mplex" tid=2016588 file=mplex.nim:175 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8a len=493 msgType=MsgIn id=2 initiator=true size=493
TRC 2021-07-20 15:22:27.627+10:00 Pushing data                               topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:93 s=QmP*aKRBqV:60f65d93203c475a6b49af8a data=493
TRC 2021-07-20 15:22:27.627+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8b:0 bytes=19
TRC 2021-07-20 15:22:27.627+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8c:1 bytes=19
TRC 2021-07-20 15:22:27.627+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af89 bytes=19
TRC 2021-07-20 15:22:27.627+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8a bytes=19
TRC 2021-07-20 15:22:27.627+10:00 handle: got request                        topics="libp2p multistream" tid=2016588 file=multistream.nim:141 conn=QmP*aKRBqV:60f65d93203c475a6b49af8b ms=/multistream/1.0.0
TRC 2021-07-20 15:22:27.627+10:00 write msg                                  topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:194 s=QmP*aKRBqV:60f65d93203c475a6b49af8b:0 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=20
TRC 2021-07-20 15:22:27.627+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=0 msgType=MsgIn data=20 encoded=22
TRC 2021-07-20 15:22:27.627+10:00 handle: got request                        topics="libp2p multistream" tid=2016588 file=multistream.nim:141 conn=QmP*aKRBqV:60f65d93203c475a6b49af8c ms=/multistream/1.0.0
TRC 2021-07-20 15:22:27.627+10:00 write msg                                  topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:194 s=QmP*aKRBqV:60f65d93203c475a6b49af8c:1 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=20
TRC 2021-07-20 15:22:27.627+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=1 msgType=MsgIn data=20 encoded=22
TRC 2021-07-20 15:22:27.627+10:00 multistream handshake success              topics="libp2p multistream" tid=2016588 file=multistream.nim:73 conn=QmP*aKRBqV:60f65d93203c475a6b49af89
TRC 2021-07-20 15:22:27.627+10:00 add leftovers                              topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:163 s=QmP*aKRBqV:60f65d93203c475a6b49af89 len=22
TRC 2021-07-20 15:22:27.627+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af89 bytes=1
TRC 2021-07-20 15:22:27.627+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af89 bytes=22
TRC 2021-07-20 15:22:27.627+10:00 reading first requested proto              topics="libp2p multistream" tid=2016588 file=multistream.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af89
TRC 2021-07-20 15:22:27.627+10:00 successfully selected                      topics="libp2p multistream" tid=2016588 file=multistream.nim:82 conn=QmP*aKRBqV:60f65d93203c475a6b49af89 proto=/vac/waku/relay/2.0.0
TRC 2021-07-20 15:22:27.627+10:00 multistream handshake success              topics="libp2p multistream" tid=2016588 file=multistream.nim:73 conn=QmP*aKRBqV:60f65d93203c475a6b49af8a
TRC 2021-07-20 15:22:27.627+10:00 add leftovers                              topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:163 s=QmP*aKRBqV:60f65d93203c475a6b49af8a len=15
TRC 2021-07-20 15:22:27.627+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8a bytes=1
TRC 2021-07-20 15:22:27.627+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8a bytes=15
TRC 2021-07-20 15:22:27.627+10:00 reading first requested proto              topics="libp2p multistream" tid=2016588 file=multistream.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af8a
TRC 2021-07-20 15:22:27.627+10:00 successfully selected                      topics="libp2p multistream" tid=2016588 file=multistream.nim:82 conn=QmP*aKRBqV:60f65d93203c475a6b49af8a proto=/ipfs/id/1.0.0
TRC 2021-07-20 15:22:27.627+10:00 initiating identify                        topics="libp2p identify" tid=2016588 file=identify.nim:140 conn=QmP*aKRBqV:60f65d93203c475a6b49af8a
TRC 2021-07-20 15:22:27.627+10:00 add leftovers                              topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:163 s=QmP*aKRBqV:60f65d93203c475a6b49af8a len=492
TRC 2021-07-20 15:22:27.627+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8a bytes=1
TRC 2021-07-20 15:22:27.627+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8a bytes=1
TRC 2021-07-20 15:22:27.627+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8a bytes=491
DBG 2021-07-20 15:22:27.627+10:00 decodeMsg: decoded message                 topics="libp2p identify" tid=2016588 file=identify.nim:102 pubkey="RSA ke...10001\n" addresses=@[] 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\"]" observable_address=Some(/ip4/127.0.0.1/tcp/61412/p2p/16Uiu2HAm3zv3dBgPe7qu8Rt7ZqaQigB35T6wzsVH3sU7zqRLpVNN) proto_version="Some(\"ipfs/0.1.0\")" agent_version="Some(\"js-libp2p/0.31.7\")"
TRC 2021-07-20 15:22:27.627+10:00 About to trigger peer events               topics="libp2p connmanager" tid=2016588 file=connmanager.nim:185 peer=QmP*aKRBqV
TRC 2021-07-20 15:22:27.627+10:00 triggering peer events                     topics="libp2p connmanager" tid=2016588 file=connmanager.nim:198 peer=QmP*aKRBqV event="(kind: Identified)"
TRC 2021-07-20 15:22:27.627+10:00 identified remote peer                     topics="libp2p upgrade" tid=2016588 file=upgrade.nim:95 conn=QmP*aKRBqV:60f65d93203c475a6b49af8a peerInfo="(peerId: \"QmPa3wMicdoXochos9Zop9GEn6tZfMpKyCV6i4cXaKRBqV\", addrs: @[], 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\"], protoVersion: \"ipfs/0.1.0\", agentVersion: \"js-libp2p/0.31.7\")"
TRC 2021-07-20 15:22:27.628+10:00 Get new send connection                    topics="libp2p pubsubpeer" tid=2016588 file=pubsubpeer.nim:172 p=QmP*aKRBqV newConn=QmP*aKRBqV:60f65d93203c475a6b49af89
TRC 2021-07-20 15:22:27.628+10:00 sending pubsub message to peer             topics="libp2p pubsub" tid=2016588 file=pubsub.nim:125 peer=QmP*aKRBqV msg="(subscriptions: @[(subscribe: true, topic: \"/waku/2/default-waku/proto\")], messages: @[], control: (ihave: @[], iwant: @[], graft: @[], prune: @[]))"
TRC 2021-07-20 15:22:27.628+10:00 sending msg to peer                        topics="libp2p pubsubpeer" tid=2016588 file=pubsubpeer.nim:256 peer=QmP*aKRBqV rpcMsg="(subscriptions: @[(subscribe: true, topic: \"/waku/2/default-waku/proto\")], messages: @[], control: (ihave: @[], iwant: @[], graft: @[], prune: @[]))"
TRC 2021-07-20 15:22:27.628+10:00 encodeRpcMsg: encoding message             topics="pubsubprotobuf" tid=2016588 file=protobuf.nim:311 msg="(subscriptions: @[(subscribe: true, topic: \"/waku/2/default-waku/proto\")], messages: @[], control: (ihave: @[], iwant: @[], graft: @[], prune: @[]))"
TRC 2021-07-20 15:22:27.628+10:00 sending encoded msgs to peer               topics="libp2p pubsubpeer" tid=2016588 file=pubsubpeer.nim:213 conn=QmP*aKRBqV:60f65d93203c475a6b49af89 encoded=0a1e0801121a...2f70726f746f
TRC 2021-07-20 15:22:27.628+10:00 write msg                                  topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:194 s=QmP*aKRBqV:60f65d93203c475a6b49af89 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=33
TRC 2021-07-20 15:22:27.628+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=1 msgType=MsgOut data=33 encoded=35
DBG 2021-07-20 15:22:27.628+10:00 starting pubsub read loop                  topics="libp2p pubsubpeer" tid=2016588 file=pubsubpeer.nim:115 conn=QmP*aKRBqV:60f65d93203c475a6b49af89 peer=QmP*aKRBqV closed=false
TRC 2021-07-20 15:22:27.628+10:00 waiting for data                           topics="libp2p pubsubpeer" tid=2016588 file=pubsubpeer.nim:120 conn=QmP*aKRBqV:60f65d93203c475a6b49af89 peer=QmP*aKRBqV closed=false
TRC 2021-07-20 15:22:27.628+10:00 pushed data to channel                     topics="libp2p mplex" tid=2016588 file=mplex.nim:177 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8a len=493 msgType=MsgIn id=2 initiator=true size=493
TRC 2021-07-20 15:22:27.628+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.628+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=19 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.628+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=0 data= conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.628+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data= msgType=CloseIn id=2 initiator=true size=0
TRC 2021-07-20 15:22:27.628+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8a data= msgType=CloseIn id=2 initiator=true size=0
TRC 2021-07-20 15:22:27.628+10:00 Pushing EOF                                topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:111 s=QmP*aKRBqV:60f65d93203c475a6b49af8a
TRC 2021-07-20 15:22:27.628+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.628+10:00 Closing with EOF                           topics="libp2p lpstream" tid=2016588 file=lpstream.nim:298 s=60f65d93203c475a6b49af8a
TRC 2021-07-20 15:22:27.628+10:00 Closing channel                            topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:122 s=QmP*aKRBqV:60f65d93203c475a6b49af8a conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=0
TRC 2021-07-20 15:22:27.628+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=2 msgType=CloseOut data=0 encoded=2
TRC 2021-07-20 15:22:27.628+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8b:0 bytes=1
TRC 2021-07-20 15:22:27.628+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8b:0 bytes=15
TRC 2021-07-20 15:22:27.628+10:00 handle: got request                        topics="libp2p multistream" tid=2016588 file=multistream.nim:141 conn=QmP*aKRBqV:60f65d93203c475a6b49af8b ms=/ipfs/id/1.0.0
TRC 2021-07-20 15:22:27.628+10:00 found handler                              topics="libp2p multistream" tid=2016588 file=multistream.nim:170 conn=QmP*aKRBqV:60f65d93203c475a6b49af8b protocol=/ipfs/id/1.0.0
TRC 2021-07-20 15:22:27.628+10:00 write msg                                  topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:194 s=QmP*aKRBqV:60f65d93203c475a6b49af8b:0 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=16
TRC 2021-07-20 15:22:27.628+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=0 msgType=MsgIn data=16 encoded=18
TRC 2021-07-20 15:22:27.628+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8c:1 bytes=1
TRC 2021-07-20 15:22:27.628+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8c:1 bytes=22
TRC 2021-07-20 15:22:27.628+10:00 handle: got request                        topics="libp2p multistream" tid=2016588 file=multistream.nim:141 conn=QmP*aKRBqV:60f65d93203c475a6b49af8c ms=/vac/waku/relay/2.0.0
TRC 2021-07-20 15:22:27.628+10:00 found handler                              topics="libp2p multistream" tid=2016588 file=multistream.nim:170 conn=QmP*aKRBqV:60f65d93203c475a6b49af8c protocol=/vac/waku/relay/2.0.0
TRC 2021-07-20 15:22:27.628+10:00 write msg                                  topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:194 s=QmP*aKRBqV:60f65d93203c475a6b49af8c:1 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=23
TRC 2021-07-20 15:22:27.628+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=1 msgType=MsgIn data=23 encoded=25
TRC 2021-07-20 15:22:27.628+10:00 sent pubsub message to remote              topics="libp2p pubsubpeer" tid=2016588 file=pubsubpeer.nim:219 conn=QmP*aKRBqV:60f65d93203c475a6b49af89
TRC 2021-07-20 15:22:27.628+10:00 Closed channel                             topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:138 s=QmP*aKRBqV:60f65d93203c475a6b49af8a len=0
TRC 2021-07-20 15:22:27.628+10:00 EOF                                        topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:154 s=QmP*aKRBqV:60f65d93203c475a6b49af8a
TRC 2021-07-20 15:22:27.628+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8a bytes=0
TRC 2021-07-20 15:22:27.628+10:00 Closing BufferStream                       topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:182 s=QmP*aKRBqV:60f65d93203c475a6b49af8a len=0
TRC 2021-07-20 15:22:27.628+10:00 Closed BufferStream                        topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:218 s=QmP*aKRBqV:60f65d93203c475a6b49af8a
TRC 2021-07-20 15:22:27.628+10:00 Closing connection                         topics="libp2p connection" tid=2016588 file=connection.nim:91 s=QmP*aKRBqV:60f65d93203c475a6b49af8a
TRC 2021-07-20 15:22:27.628+10:00 Closed connection                          topics="libp2p connection" tid=2016588 file=connection.nim:101 s=QmP*aKRBqV:60f65d93203c475a6b49af8a
TRC 2021-07-20 15:22:27.628+10:00 Closing stream                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:266 s=60f65d93203c475a6b49af8a objName=LPChannel dir=Out
TRC 2021-07-20 15:22:27.629+10:00 Closed stream                              topics="libp2p lpstream" tid=2016588 file=lpstream.nim:270 s=60f65d93203c475a6b49af8a objName=LPChannel dir=Out
TRC 2021-07-20 15:22:27.629+10:00 cleaned up channel                         topics="libp2p mplex" tid=2016588 file=mplex.nim:66 m=QmP*aKRBqV:60f65d93203c475a6b49af87 chann=QmP*aKRBqV:60f65d93203c475a6b49af8a
TRC 2021-07-20 15:22:27.629+10:00 handling identify request                  topics="libp2p identify" tid=2016588 file=identify.nim:123 conn=QmP*aKRBqV:60f65d93203c475a6b49af8b
TRC 2021-07-20 15:22:27.629+10:00 write msg                                  topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:194 s=QmP*aKRBqV:60f65d93203c475a6b49af8b:0 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=205
TRC 2021-07-20 15:22:27.629+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=0 msgType=MsgIn data=205 encoded=208
DBG 2021-07-20 15:22:27.629+10:00 Incoming WakuRelay connection              topics="wakurelay" tid=2016588 file=waku_relay.nim:31
DBG 2021-07-20 15:22:27.629+10:00 starting pubsub read loop                  topics="libp2p pubsubpeer" tid=2016588 file=pubsubpeer.nim:115 conn=QmP*aKRBqV:60f65d93203c475a6b49af8c peer=QmP*aKRBqV closed=false
TRC 2021-07-20 15:22:27.629+10:00 waiting for data                           topics="libp2p pubsubpeer" tid=2016588 file=pubsubpeer.nim:120 conn=QmP*aKRBqV:60f65d93203c475a6b49af8c peer=QmP*aKRBqV closed=false
TRC 2021-07-20 15:22:27.629+10:00 exiting identify handler                   topics="libp2p identify" tid=2016588 file=identify.nim:131 conn=QmP*aKRBqV:60f65d93203c475a6b49af8b
TRC 2021-07-20 15:22:27.629+10:00 Closing with EOF                           topics="libp2p lpstream" tid=2016588 file=lpstream.nim:298 s=60f65d93203c475a6b49af8b
TRC 2021-07-20 15:22:27.629+10:00 Closing channel                            topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:122 s=QmP*aKRBqV:60f65d93203c475a6b49af8b:0 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=0
TRC 2021-07-20 15:22:27.629+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=0 msgType=CloseIn data=0 encoded=2
TRC 2021-07-20 15:22:27.629+10:00 Closed channel                             topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:138 s=QmP*aKRBqV:60f65d93203c475a6b49af8b:0 len=0
TRC 2021-07-20 15:22:27.633+10:00 readFrame                                  topics="libp2p noise" tid=2016588 file=noise.nim:309 sconn=QmP*aKRBqV:60f65d93203c475a6b49af86 size=18
TRC 2021-07-20 15:22:27.634+10:00 decryptWithAd                              topics="libp2p noise" tid=2016588 file=noise.nim:169 tagIn=2c988b9d32f4...9acd3d9b35f0 tagOut=2c988b9d32f4...9acd3d9b35f0 nonce=7
TRC 2021-07-20 15:22:27.634+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=4 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.634+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=0 data= conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.634+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data= msgType=CloseOut id=0 initiator=false size=0
TRC 2021-07-20 15:22:27.634+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8b:0 data= msgType=CloseOut id=0 initiator=false size=0
TRC 2021-07-20 15:22:27.634+10:00 Pushing EOF                                topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:111 s=QmP*aKRBqV:60f65d93203c475a6b49af8b
TRC 2021-07-20 15:22:27.634+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.634+10:00 EOF                                        topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:154 s=QmP*aKRBqV:60f65d93203c475a6b49af8b
TRC 2021-07-20 15:22:27.634+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8b:0 bytes=0
TRC 2021-07-20 15:22:27.634+10:00 Closing BufferStream                       topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:182 s=QmP*aKRBqV:60f65d93203c475a6b49af8b len=0
TRC 2021-07-20 15:22:27.634+10:00 Closed BufferStream                        topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:218 s=QmP*aKRBqV:60f65d93203c475a6b49af8b
TRC 2021-07-20 15:22:27.634+10:00 Closing connection                         topics="libp2p connection" tid=2016588 file=connection.nim:91 s=QmP*aKRBqV:60f65d93203c475a6b49af8b
TRC 2021-07-20 15:22:27.634+10:00 Closed connection                          topics="libp2p connection" tid=2016588 file=connection.nim:101 s=QmP*aKRBqV:60f65d93203c475a6b49af8b
TRC 2021-07-20 15:22:27.634+10:00 Closing stream                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:266 s=60f65d93203c475a6b49af8b objName=LPChannel dir=In
TRC 2021-07-20 15:22:27.634+10:00 Closed stream                              topics="libp2p lpstream" tid=2016588 file=lpstream.nim:270 s=60f65d93203c475a6b49af8b objName=LPChannel dir=In
TRC 2021-07-20 15:22:27.634+10:00 cleaned up channel                         topics="libp2p mplex" tid=2016588 file=mplex.nim:66 m=QmP*aKRBqV:60f65d93203c475a6b49af87 chann=QmP*aKRBqV:60f65d93203c475a6b49af8b:0
TRC 2021-07-20 15:22:27.634+10:00 Already closed                             topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:118 s=QmP*aKRBqV:60f65d93203c475a6b49af8b:0
TRC 2021-07-20 15:22:27.634+10:00 Closing with EOF                           topics="libp2p lpstream" tid=2016588 file=lpstream.nim:298 s=60f65d93203c475a6b49af8b
TRC 2021-07-20 15:22:27.634+10:00 Already closed                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:300
TRC 2021-07-20 15:22:27.634+10:00 Stream handler done                        tid=2016588 file=muxedupgrade.nim:222 conn=QmP*aKRBqV:60f65d93203c475a6b49af8b
TRC 2021-07-20 15:22:27.634+10:00 finished handling stream                   topics="libp2p mplex" tid=2016588 file=mplex.nim:118 m=QmP*aKRBqV:60f65d93203c475a6b49af87 chann=QmP*aKRBqV:60f65d93203c475a6b49af8b:0
TRC 2021-07-20 15:22:27.637+10:00 readFrame                                  topics="libp2p noise" tid=2016588 file=noise.nim:309 sconn=QmP*aKRBqV:60f65d93203c475a6b49af86 size=19
TRC 2021-07-20 15:22:27.637+10:00 decryptWithAd                              topics="libp2p noise" tid=2016588 file=noise.nim:169 tagIn=59f165b0e82f...cd56872e66f6 tagOut=59f165b0e82f...cd56872e66f6 nonce=8
TRC 2021-07-20 15:22:27.637+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=16 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.638+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=1 data=32 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.638+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data=32 msgType=New id=2 initiator=false size=1
TRC 2021-07-20 15:22:27.638+10:00 Stream created                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:133 s=60f65d93203c475a6b49af8d objName=LPChannel dir=In
TRC 2021-07-20 15:22:27.638+10:00 Monitoring for timeout                     topics="libp2p connection" tid=2016588 file=connection.nim:81 s=60f65d93203c475a6b49af8d timeout=5m0ns
TRC 2021-07-20 15:22:27.638+10:00 BufferStream created                       topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:59 s=60f65d93203c475a6b49af8d
TRC 2021-07-20 15:22:27.638+10:00 Created new lpchannel                      topics="libp2p mplex" tid=2016588 file=lpchannel.nim:231 s=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 id=2 initiator=false
TRC 2021-07-20 15:22:27.638+10:00 Creating new channel                       topics="libp2p mplex" tid=2016588 file=mplex.nim:101 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 id=2 initiator=false name=2
TRC 2021-07-20 15:22:27.638+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 data=32 msgType=New id=2 initiator=false size=1
TRC 2021-07-20 15:22:27.638+10:00 created channel                            topics="libp2p mplex" tid=2016588 file=mplex.nim:162 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 msgType=New id=2 initiator=false size=1
TRC 2021-07-20 15:22:27.638+10:00 Starting stream handler                    tid=2016588 file=muxedupgrade.nim:213 conn=QmP*aKRBqV:60f65d93203c475a6b49af8d
TRC 2021-07-20 15:22:27.638+10:00 Starting multistream handler               topics="libp2p multistream" tid=2016588 file=multistream.nim:129 conn=QmP*aKRBqV:60f65d93203c475a6b49af8d handshaked=false
TRC 2021-07-20 15:22:27.638+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.638+10:00 readFrame                                  topics="libp2p noise" tid=2016588 file=noise.nim:309 sconn=QmP*aKRBqV:60f65d93203c475a6b49af86 size=115
TRC 2021-07-20 15:22:27.638+10:00 decryptWithAd                              topics="libp2p noise" tid=2016588 file=noise.nim:169 tagIn=d0b2c8b62420...0069fa4a115a tagOut=d0b2c8b62420...0069fa4a115a nonce=9
TRC 2021-07-20 15:22:27.638+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=24 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.638+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=1 data=33 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.638+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data=33 msgType=New id=3 initiator=false size=1
TRC 2021-07-20 15:22:27.638+10:00 Stream created                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:133 s=60f65d93203c475a6b49af8e objName=LPChannel dir=In
TRC 2021-07-20 15:22:27.638+10:00 Monitoring for timeout                     topics="libp2p connection" tid=2016588 file=connection.nim:81 s=60f65d93203c475a6b49af8e timeout=5m0ns
TRC 2021-07-20 15:22:27.638+10:00 BufferStream created                       topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:59 s=60f65d93203c475a6b49af8e
TRC 2021-07-20 15:22:27.638+10:00 Created new lpchannel                      topics="libp2p mplex" tid=2016588 file=lpchannel.nim:231 s=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 id=3 initiator=false
TRC 2021-07-20 15:22:27.638+10:00 Creating new channel                       topics="libp2p mplex" tid=2016588 file=mplex.nim:101 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 id=3 initiator=false name=3
TRC 2021-07-20 15:22:27.638+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 data=33 msgType=New id=3 initiator=false size=1
TRC 2021-07-20 15:22:27.638+10:00 created channel                            topics="libp2p mplex" tid=2016588 file=mplex.nim:162 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 msgType=New id=3 initiator=false size=1
TRC 2021-07-20 15:22:27.638+10:00 Starting stream handler                    tid=2016588 file=muxedupgrade.nim:213 conn=QmP*aKRBqV:60f65d93203c475a6b49af8e
TRC 2021-07-20 15:22:27.638+10:00 Starting multistream handler               topics="libp2p multistream" tid=2016588 file=multistream.nim:129 conn=QmP*aKRBqV:60f65d93203c475a6b49af8e handshaked=false
TRC 2021-07-20 15:22:27.638+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.638+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=18 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.638+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=43 data=132f6d756c74...322e302e300a conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.638+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data=132f6d756c74...322e302e300a msgType=MsgOut id=2 initiator=false size=43
TRC 2021-07-20 15:22:27.638+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 data=132f6d756c74...322e302e300a msgType=MsgOut id=2 initiator=false size=43
TRC 2021-07-20 15:22:27.638+10:00 pushing data to channel                    topics="libp2p mplex" tid=2016588 file=mplex.nim:175 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 len=43 msgType=MsgOut id=2 initiator=false size=43
TRC 2021-07-20 15:22:27.638+10:00 Pushing data                               topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:93 s=QmP*aKRBqV:60f65d93203c475a6b49af8d data=43
TRC 2021-07-20 15:22:27.638+10:00 pushed data to channel                     topics="libp2p mplex" tid=2016588 file=mplex.nim:177 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 len=43 msgType=MsgOut id=2 initiator=false size=43
TRC 2021-07-20 15:22:27.638+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.638+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=26 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.638+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=49 data=132f6d756c74...62657461330a conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.638+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data=132f6d756c74...62657461330a msgType=MsgOut id=3 initiator=false size=49
TRC 2021-07-20 15:22:27.638+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 data=132f6d756c74...62657461330a msgType=MsgOut id=3 initiator=false size=49
TRC 2021-07-20 15:22:27.638+10:00 pushing data to channel                    topics="libp2p mplex" tid=2016588 file=mplex.nim:175 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 len=49 msgType=MsgOut id=3 initiator=false size=49
TRC 2021-07-20 15:22:27.638+10:00 Pushing data                               topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:93 s=QmP*aKRBqV:60f65d93203c475a6b49af8e data=49
TRC 2021-07-20 15:22:27.638+10:00 pushed data to channel                     topics="libp2p mplex" tid=2016588 file=mplex.nim:177 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 len=49 msgType=MsgOut id=3 initiator=false size=49
TRC 2021-07-20 15:22:27.638+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.638+10:00 add leftovers                              topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:163 s=QmP*aKRBqV:60f65d93203c475a6b49af8d len=42
TRC 2021-07-20 15:22:27.638+10:00 add leftovers                              topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:163 s=QmP*aKRBqV:60f65d93203c475a6b49af8e len=48
TRC 2021-07-20 15:22:27.638+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 bytes=1
TRC 2021-07-20 15:22:27.638+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 bytes=1
TRC 2021-07-20 15:22:27.638+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 bytes=19
TRC 2021-07-20 15:22:27.639+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 bytes=19
TRC 2021-07-20 15:22:27.639+10:00 handle: got request                        topics="libp2p multistream" tid=2016588 file=multistream.nim:141 conn=QmP*aKRBqV:60f65d93203c475a6b49af8d ms=/multistream/1.0.0
TRC 2021-07-20 15:22:27.639+10:00 write msg                                  topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:194 s=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=20
TRC 2021-07-20 15:22:27.639+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=2 msgType=MsgIn data=20 encoded=22
TRC 2021-07-20 15:22:27.639+10:00 handle: got request                        topics="libp2p multistream" tid=2016588 file=multistream.nim:141 conn=QmP*aKRBqV:60f65d93203c475a6b49af8e ms=/multistream/1.0.0
TRC 2021-07-20 15:22:27.639+10:00 write msg                                  topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:194 s=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=20
TRC 2021-07-20 15:22:27.639+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=3 msgType=MsgIn data=20 encoded=22
TRC 2021-07-20 15:22:27.639+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 bytes=1
TRC 2021-07-20 15:22:27.639+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 bytes=22
TRC 2021-07-20 15:22:27.639+10:00 handle: got request                        topics="libp2p multistream" tid=2016588 file=multistream.nim:141 conn=QmP*aKRBqV:60f65d93203c475a6b49af8d ms=/vac/waku/relay/2.0.0
TRC 2021-07-20 15:22:27.639+10:00 found handler                              topics="libp2p multistream" tid=2016588 file=multistream.nim:170 conn=QmP*aKRBqV:60f65d93203c475a6b49af8d protocol=/vac/waku/relay/2.0.0
TRC 2021-07-20 15:22:27.639+10:00 write msg                                  topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:194 s=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=23
TRC 2021-07-20 15:22:27.639+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=2 msgType=MsgIn data=23 encoded=25
TRC 2021-07-20 15:22:27.639+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 bytes=1
TRC 2021-07-20 15:22:27.639+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 bytes=28
TRC 2021-07-20 15:22:27.639+10:00 handle: got request                        topics="libp2p multistream" tid=2016588 file=multistream.nim:141 conn=QmP*aKRBqV:60f65d93203c475a6b49af8e ms=/vac/waku/store/2.0.0-beta3
TRC 2021-07-20 15:22:27.639+10:00 found handler                              topics="libp2p multistream" tid=2016588 file=multistream.nim:170 conn=QmP*aKRBqV:60f65d93203c475a6b49af8e protocol=/vac/waku/store/2.0.0-beta3
TRC 2021-07-20 15:22:27.639+10:00 write msg                                  topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:194 s=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=29
TRC 2021-07-20 15:22:27.639+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=3 msgType=MsgIn data=29 encoded=31
DBG 2021-07-20 15:22:27.639+10:00 Incoming WakuRelay connection              topics="wakurelay" tid=2016588 file=waku_relay.nim:31
DBG 2021-07-20 15:22:27.639+10:00 starting pubsub read loop                  topics="libp2p pubsubpeer" tid=2016588 file=pubsubpeer.nim:115 conn=QmP*aKRBqV:60f65d93203c475a6b49af8d peer=QmP*aKRBqV closed=false
TRC 2021-07-20 15:22:27.639+10:00 waiting for data                           topics="libp2p pubsubpeer" tid=2016588 file=pubsubpeer.nim:120 conn=QmP*aKRBqV:60f65d93203c475a6b49af8d peer=QmP*aKRBqV closed=false
TRC 2021-07-20 15:22:27.685+10:00 readFrame                                  topics="libp2p noise" tid=2016588 file=noise.nim:309 sconn=QmP*aKRBqV:60f65d93203c475a6b49af86 size=51
TRC 2021-07-20 15:22:27.685+10:00 decryptWithAd                              topics="libp2p noise" tid=2016588 file=noise.nim:169 tagIn=65e8bb68e4f6...11fa816177cf tagOut=65e8bb68e4f6...11fa816177cf nonce=10
TRC 2021-07-20 15:22:27.685+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=18 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.685+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=33 data=200a1e080112...2f70726f746f conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.685+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data=200a1e080112...2f70726f746f msgType=MsgOut id=2 initiator=false size=33
TRC 2021-07-20 15:22:27.685+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 data=200a1e080112...2f70726f746f msgType=MsgOut id=2 initiator=false size=33
TRC 2021-07-20 15:22:27.685+10:00 pushing data to channel                    topics="libp2p mplex" tid=2016588 file=mplex.nim:175 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 len=33 msgType=MsgOut id=2 initiator=false size=33
TRC 2021-07-20 15:22:27.685+10:00 Pushing data                               topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:93 s=QmP*aKRBqV:60f65d93203c475a6b49af8d data=33
TRC 2021-07-20 15:22:27.685+10:00 pushed data to channel                     topics="libp2p mplex" tid=2016588 file=mplex.nim:177 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 len=33 msgType=MsgOut id=2 initiator=false size=33
TRC 2021-07-20 15:22:27.685+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.685+10:00 add leftovers                              topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:163 s=QmP*aKRBqV:60f65d93203c475a6b49af8d len=32
TRC 2021-07-20 15:22:27.686+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 bytes=1
TRC 2021-07-20 15:22:27.686+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 bytes=32
TRC 2021-07-20 15:22:27.686+10:00 readFrame                                  topics="libp2p noise" tid=2016588 file=noise.nim:309 sconn=QmP*aKRBqV:60f65d93203c475a6b49af86 size=126
TRC 2021-07-20 15:22:27.686+10:00 read data from peer                        topics="libp2p pubsubpeer" tid=2016588 file=pubsubpeer.nim:123 conn=QmP*aKRBqV:60f65d93203c475a6b49af8d peer=QmP*aKRBqV closed=false data=0a1e0801121a...2f70726f746f
TRC 2021-07-20 15:22:27.686+10:00 decodeRpcMsg: decoding message             topics="pubsubprotobuf" tid=2016588 file=protobuf.nim:324 msg=0a1e0801121a...2f70726f746f
TRC 2021-07-20 15:22:27.686+10:00 decodeMessages: decoding message           topics="pubsubprotobuf" tid=2016588 file=protobuf.nim:299
TRC 2021-07-20 15:22:27.686+10:00 decodeMessages: no messages found          topics="pubsubprotobuf" tid=2016588 file=protobuf.nim:307
TRC 2021-07-20 15:22:27.686+10:00 decodeSubscriptions: decoding message      topics="pubsubprotobuf" tid=2016588 file=protobuf.nim:254
TRC 2021-07-20 15:22:27.686+10:00 decodeSubscriptions: read subscriptions    topics="pubsubprotobuf" tid=2016588 file=protobuf.nim:259 count=1
TRC 2021-07-20 15:22:27.686+10:00 decodeSubscription: decoding message       topics="pubsubprotobuf" tid=2016588 file=protobuf.nim:238
TRC 2021-07-20 15:22:27.686+10:00 decodeSubscription: read subscribe         topics="pubsubprotobuf" tid=2016588 file=protobuf.nim:243 subscribe=1
TRC 2021-07-20 15:22:27.686+10:00 decodeSubscription: read topic             topics="pubsubprotobuf" tid=2016588 file=protobuf.nim:247 topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.686+10:00 decodeControl: decoding message            topics="pubsubprotobuf" tid=2016588 file=protobuf.nim:205
TRC 2021-07-20 15:22:27.686+10:00 decoded msg from peer                      topics="libp2p pubsubpeer" tid=2016588 file=pubsubpeer.nim:136 conn=QmP*aKRBqV:60f65d93203c475a6b49af8d peer=QmP*aKRBqV closed=false msg="(subscriptions: @[(subscribe: true, topic: \"/waku/2/default-waku/proto\")], messages: @[], control: (ihave: @[], iwant: @[], graft: @[], prune: @[]))"
TRC 2021-07-20 15:22:27.686+10:00 peer subscribed to topic                   topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:227 peer=QmP*aKRBqV topic=/waku/2/default-waku/proto
TRC 2021-07-20 15:22:27.686+10:00 gossip peers                               topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:243 peers=1 topic=/waku/2/default-waku/proto peer=QmP*aKRBqV
TRC 2021-07-20 15:22:27.686+10:00 waiting for data                           topics="libp2p pubsubpeer" tid=2016588 file=pubsubpeer.nim:120 conn=QmP*aKRBqV:60f65d93203c475a6b49af8d peer=QmP*aKRBqV closed=false
TRC 2021-07-20 15:22:27.686+10:00 decryptWithAd                              topics="libp2p noise" tid=2016588 file=noise.nim:169 tagIn=8c99659bad81...fa52fc778849 tagOut=8c99659bad81...fa52fc778849 nonce=11
TRC 2021-07-20 15:22:27.686+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=26 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.686+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=108 data=6b0a24663532...2204080a1801 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.686+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data=6b0a24663532...2204080a1801 msgType=MsgOut id=3 initiator=false size=108
TRC 2021-07-20 15:22:27.686+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 data=6b0a24663532...2204080a1801 msgType=MsgOut id=3 initiator=false size=108
TRC 2021-07-20 15:22:27.686+10:00 pushing data to channel                    topics="libp2p mplex" tid=2016588 file=mplex.nim:175 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 len=108 msgType=MsgOut id=3 initiator=false size=108
TRC 2021-07-20 15:22:27.686+10:00 Pushing data                               topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:93 s=QmP*aKRBqV:60f65d93203c475a6b49af8e data=108
TRC 2021-07-20 15:22:27.686+10:00 pushed data to channel                     topics="libp2p mplex" tid=2016588 file=mplex.nim:177 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 len=108 msgType=MsgOut id=3 initiator=false size=108
TRC 2021-07-20 15:22:27.686+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.686+10:00 readFrame                                  topics="libp2p noise" tid=2016588 file=noise.nim:309 sconn=QmP*aKRBqV:60f65d93203c475a6b49af86 size=18
TRC 2021-07-20 15:22:27.686+10:00 decryptWithAd                              topics="libp2p noise" tid=2016588 file=noise.nim:169 tagIn=ff3a8f159128...7750513a8fc8 tagOut=ff3a8f159128...7750513a8fc8 nonce=12
TRC 2021-07-20 15:22:27.686+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=28 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.686+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=0 data= conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.686+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data= msgType=CloseOut id=3 initiator=false size=0
TRC 2021-07-20 15:22:27.686+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 data= msgType=CloseOut id=3 initiator=false size=0
TRC 2021-07-20 15:22:27.686+10:00 Pushing EOF                                topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:111 s=QmP*aKRBqV:60f65d93203c475a6b49af8e
TRC 2021-07-20 15:22:27.686+10:00 add leftovers                              topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:163 s=QmP*aKRBqV:60f65d93203c475a6b49af8e len=107
TRC 2021-07-20 15:22:27.686+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 bytes=1
TRC 2021-07-20 15:22:27.686+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.686+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 bytes=107
INF 2021-07-20 15:22:27.686+10:00 received query                             topics="wakustore" tid=2016588 file=waku_store.nim:388
INF 2021-07-20 15:22:27.686+10:00 handle store swap test                     topics="wakustore" tid=2016588 file=waku_store.nim:396 text=test
INF 2021-07-20 15:22:27.686+10:00 Crediting peer:                            topics="wakuswap" tid=2016588 file=waku_swap.nim:235 peer=QmP*aKRBqV amount=10
INF 2021-07-20 15:22:27.686+10:00 Accounting state                           topics="wakuswap" tid=2016588 file=waku_swap.nim:240 accounting=-10
INF 2021-07-20 15:22:27.686+10:00 Disconnect threshhold not hit              topics="wakuswap" tid=2016588 file=waku_swap.nim:264
INF 2021-07-20 15:22:27.686+10:00 Payment threshhold not hit                 topics="wakuswap" tid=2016588 file=waku_swap.nim:273
INF 2021-07-20 15:22:27.686+10:00 sending response                           topics="wakustore" tid=2016588 file=waku_store.nim:404 messages=10
TRC 2021-07-20 15:22:27.686+10:00 write msg                                  topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:194 s=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=772
TRC 2021-07-20 15:22:27.686+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=3 msgType=MsgIn data=772 encoded=775
TRC 2021-07-20 15:22:27.686+10:00 Closing channel                            topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:122 s=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=0
TRC 2021-07-20 15:22:27.686+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=3 msgType=CloseIn data=0 encoded=2
TRC 2021-07-20 15:22:27.686+10:00 Closing with EOF                           topics="libp2p lpstream" tid=2016588 file=lpstream.nim:298 s=60f65d93203c475a6b49af8e
TRC 2021-07-20 15:22:27.686+10:00 Already closed                             topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:118 s=QmP*aKRBqV:60f65d93203c475a6b49af8e:3
TRC 2021-07-20 15:22:27.686+10:00 EOF                                        topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:154 s=QmP*aKRBqV:60f65d93203c475a6b49af8e
TRC 2021-07-20 15:22:27.686+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 bytes=0
TRC 2021-07-20 15:22:27.686+10:00 Closing BufferStream                       topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:182 s=QmP*aKRBqV:60f65d93203c475a6b49af8e len=0
TRC 2021-07-20 15:22:27.686+10:00 Closed BufferStream                        topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:218 s=QmP*aKRBqV:60f65d93203c475a6b49af8e
TRC 2021-07-20 15:22:27.686+10:00 Closing connection                         topics="libp2p connection" tid=2016588 file=connection.nim:91 s=QmP*aKRBqV:60f65d93203c475a6b49af8e
TRC 2021-07-20 15:22:27.686+10:00 Closed connection                          topics="libp2p connection" tid=2016588 file=connection.nim:101 s=QmP*aKRBqV:60f65d93203c475a6b49af8e
TRC 2021-07-20 15:22:27.687+10:00 Closing stream                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:266 s=60f65d93203c475a6b49af8e objName=LPChannel dir=In
TRC 2021-07-20 15:22:27.687+10:00 Closed stream                              topics="libp2p lpstream" tid=2016588 file=lpstream.nim:270 s=60f65d93203c475a6b49af8e objName=LPChannel dir=In
TRC 2021-07-20 15:22:27.687+10:00 Stream handler done                        tid=2016588 file=muxedupgrade.nim:222 conn=QmP*aKRBqV:60f65d93203c475a6b49af8e
TRC 2021-07-20 15:22:27.687+10:00 cleaned up channel                         topics="libp2p mplex" tid=2016588 file=mplex.nim:66 m=QmP*aKRBqV:60f65d93203c475a6b49af87 chann=QmP*aKRBqV:60f65d93203c475a6b49af8e:3
TRC 2021-07-20 15:22:27.687+10:00 finished handling stream                   topics="libp2p mplex" tid=2016588 file=mplex.nim:118 m=QmP*aKRBqV:60f65d93203c475a6b49af87 chann=QmP*aKRBqV:60f65d93203c475a6b49af8e:3
TRC 2021-07-20 15:22:27.687+10:00 Already closed                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:276 s=60f65d93203c475a6b49af8e
TRC 2021-07-20 15:22:27.687+10:00 Closed channel                             topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:138 s=QmP*aKRBqV:60f65d93203c475a6b49af8e:3 len=0
TRC 2021-07-20 15:22:27.732+10:00 readFrame                                  topics="libp2p noise" tid=2016588 file=noise.nim:309 sconn=QmP*aKRBqV:60f65d93203c475a6b49af86 size=19
TRC 2021-07-20 15:22:27.732+10:00 decryptWithAd                              topics="libp2p noise" tid=2016588 file=noise.nim:169 tagIn=d5602e46704e...1c22900741e6 tagOut=d5602e46704e...1c22900741e6 nonce=13
TRC 2021-07-20 15:22:27.732+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=32 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.732+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=1 data=34 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.732+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data=34 msgType=New id=4 initiator=false size=1
TRC 2021-07-20 15:22:27.732+10:00 Stream created                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:133 s=60f65d93203c475a6b49af8f objName=LPChannel dir=In
TRC 2021-07-20 15:22:27.732+10:00 Monitoring for timeout                     topics="libp2p connection" tid=2016588 file=connection.nim:81 s=60f65d93203c475a6b49af8f timeout=5m0ns
TRC 2021-07-20 15:22:27.732+10:00 BufferStream created                       topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:59 s=60f65d93203c475a6b49af8f
TRC 2021-07-20 15:22:27.732+10:00 Created new lpchannel                      topics="libp2p mplex" tid=2016588 file=lpchannel.nim:231 s=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 id=4 initiator=false
TRC 2021-07-20 15:22:27.732+10:00 Creating new channel                       topics="libp2p mplex" tid=2016588 file=mplex.nim:101 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 id=4 initiator=false name=4
TRC 2021-07-20 15:22:27.732+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 data=34 msgType=New id=4 initiator=false size=1
TRC 2021-07-20 15:22:27.732+10:00 created channel                            topics="libp2p mplex" tid=2016588 file=mplex.nim:162 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 msgType=New id=4 initiator=false size=1
TRC 2021-07-20 15:22:27.732+10:00 Starting stream handler                    tid=2016588 file=muxedupgrade.nim:213 conn=QmP*aKRBqV:60f65d93203c475a6b49af8f
TRC 2021-07-20 15:22:27.733+10:00 Starting multistream handler               topics="libp2p multistream" tid=2016588 file=multistream.nim:129 conn=QmP*aKRBqV:60f65d93203c475a6b49af8f handshaked=false
TRC 2021-07-20 15:22:27.733+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.775+10:00 readFrame                                  topics="libp2p noise" tid=2016588 file=noise.nim:309 sconn=QmP*aKRBqV:60f65d93203c475a6b49af86 size=67
TRC 2021-07-20 15:22:27.775+10:00 decryptWithAd                              topics="libp2p noise" tid=2016588 file=noise.nim:169 tagIn=fb05fc20c017...ed41bfa7ea38 tagOut=fb05fc20c017...ed41bfa7ea38 nonce=14
TRC 2021-07-20 15:22:27.775+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=34 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.775+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=49 data=132f6d756c74...62657461330a conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.775+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data=132f6d756c74...62657461330a msgType=MsgOut id=4 initiator=false size=49
TRC 2021-07-20 15:22:27.775+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 data=132f6d756c74...62657461330a msgType=MsgOut id=4 initiator=false size=49
TRC 2021-07-20 15:22:27.775+10:00 pushing data to channel                    topics="libp2p mplex" tid=2016588 file=mplex.nim:175 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 len=49 msgType=MsgOut id=4 initiator=false size=49
TRC 2021-07-20 15:22:27.775+10:00 Pushing data                               topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:93 s=QmP*aKRBqV:60f65d93203c475a6b49af8f data=49
TRC 2021-07-20 15:22:27.775+10:00 pushed data to channel                     topics="libp2p mplex" tid=2016588 file=mplex.nim:177 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 len=49 msgType=MsgOut id=4 initiator=false size=49
TRC 2021-07-20 15:22:27.775+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.775+10:00 add leftovers                              topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:163 s=QmP*aKRBqV:60f65d93203c475a6b49af8f len=48
TRC 2021-07-20 15:22:27.775+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 bytes=1
TRC 2021-07-20 15:22:27.775+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 bytes=19
TRC 2021-07-20 15:22:27.775+10:00 handle: got request                        topics="libp2p multistream" tid=2016588 file=multistream.nim:141 conn=QmP*aKRBqV:60f65d93203c475a6b49af8f ms=/multistream/1.0.0
TRC 2021-07-20 15:22:27.775+10:00 write msg                                  topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:194 s=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=20
TRC 2021-07-20 15:22:27.775+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=4 msgType=MsgIn data=20 encoded=22
TRC 2021-07-20 15:22:27.775+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 bytes=1
TRC 2021-07-20 15:22:27.775+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 bytes=28
TRC 2021-07-20 15:22:27.775+10:00 handle: got request                        topics="libp2p multistream" tid=2016588 file=multistream.nim:141 conn=QmP*aKRBqV:60f65d93203c475a6b49af8f ms=/vac/waku/store/2.0.0-beta3
TRC 2021-07-20 15:22:27.775+10:00 found handler                              topics="libp2p multistream" tid=2016588 file=multistream.nim:170 conn=QmP*aKRBqV:60f65d93203c475a6b49af8f protocol=/vac/waku/store/2.0.0-beta3
TRC 2021-07-20 15:22:27.775+10:00 write msg                                  topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:194 s=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=29
TRC 2021-07-20 15:22:27.775+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=4 msgType=MsgIn data=29 encoded=31
TRC 2021-07-20 15:22:27.780+10:00 readFrame                                  topics="libp2p noise" tid=2016588 file=noise.nim:309 sconn=QmP*aKRBqV:60f65d93203c475a6b49af86 size=173
TRC 2021-07-20 15:22:27.780+10:00 decryptWithAd                              topics="libp2p noise" tid=2016588 file=noise.nim:169 tagIn=63e4123b85ee...77edc6391828 tagOut=63e4123b85ee...77edc6391828 nonce=15
TRC 2021-07-20 15:22:27.780+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=34 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.781+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=154 data=98010a246465...973dd8411801 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.781+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data=98010a246465...973dd8411801 msgType=MsgOut id=4 initiator=false size=154
TRC 2021-07-20 15:22:27.781+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 data=98010a246465...973dd8411801 msgType=MsgOut id=4 initiator=false size=154
TRC 2021-07-20 15:22:27.781+10:00 pushing data to channel                    topics="libp2p mplex" tid=2016588 file=mplex.nim:175 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 len=154 msgType=MsgOut id=4 initiator=false size=154
TRC 2021-07-20 15:22:27.781+10:00 Pushing data                               topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:93 s=QmP*aKRBqV:60f65d93203c475a6b49af8f data=154
TRC 2021-07-20 15:22:27.781+10:00 pushed data to channel                     topics="libp2p mplex" tid=2016588 file=mplex.nim:177 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 len=154 msgType=MsgOut id=4 initiator=false size=154
TRC 2021-07-20 15:22:27.781+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.781+10:00 add leftovers                              topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:163 s=QmP*aKRBqV:60f65d93203c475a6b49af8f len=153
TRC 2021-07-20 15:22:27.781+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 bytes=1
TRC 2021-07-20 15:22:27.781+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 bytes=1
TRC 2021-07-20 15:22:27.781+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 bytes=152
TRC 2021-07-20 15:22:27.781+10:00 readFrame                                  topics="libp2p noise" tid=2016588 file=noise.nim:309 sconn=QmP*aKRBqV:60f65d93203c475a6b49af86 size=18
INF 2021-07-20 15:22:27.781+10:00 received query                             topics="wakustore" tid=2016588 file=waku_store.nim:388
INF 2021-07-20 15:22:27.781+10:00 handle store swap test                     topics="wakustore" tid=2016588 file=waku_store.nim:396 text=test
INF 2021-07-20 15:22:27.781+10:00 Crediting peer:                            topics="wakuswap" tid=2016588 file=waku_swap.nim:235 peer=QmP*aKRBqV amount=5
INF 2021-07-20 15:22:27.781+10:00 Accounting state                           topics="wakuswap" tid=2016588 file=waku_swap.nim:240 accounting=-15
INF 2021-07-20 15:22:27.781+10:00 Disconnect threshhold not hit              topics="wakuswap" tid=2016588 file=waku_swap.nim:264
INF 2021-07-20 15:22:27.781+10:00 Payment threshhold not hit                 topics="wakuswap" tid=2016588 file=waku_swap.nim:273
INF 2021-07-20 15:22:27.781+10:00 sending response                           topics="wakustore" tid=2016588 file=waku_store.nim:404 messages=5
TRC 2021-07-20 15:22:27.781+10:00 write msg                                  topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:194 s=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=477
TRC 2021-07-20 15:22:27.781+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=4 msgType=MsgIn data=477 encoded=480
TRC 2021-07-20 15:22:27.781+10:00 decryptWithAd                              topics="libp2p noise" tid=2016588 file=noise.nim:169 tagIn=8b771cd59d67...1be4ef2eca88 tagOut=8b771cd59d67...1be4ef2eca88 nonce=16
TRC 2021-07-20 15:22:27.781+10:00 read header varint                         topics="libp2p mplexcoder" tid=2016588 file=coder.nim:47 varint=36 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.781+10:00 read data                                  topics="libp2p mplexcoder" tid=2016588 file=coder.nim:50 dataLen=0 data= conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.781+10:00 read message from connection               topics="libp2p mplex" tid=2016588 file=mplex.nim:139 m=QmP*aKRBqV:60f65d93203c475a6b49af87 data= msgType=CloseOut id=4 initiator=false size=0
TRC 2021-07-20 15:22:27.781+10:00 Processing channel message                 topics="libp2p mplex" tid=2016588 file=mplex.nim:158 m=QmP*aKRBqV:60f65d93203c475a6b49af87 channel=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 data= msgType=CloseOut id=4 initiator=false size=0
TRC 2021-07-20 15:22:27.781+10:00 Pushing EOF                                topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:111 s=QmP*aKRBqV:60f65d93203c475a6b49af8f
TRC 2021-07-20 15:22:27.781+10:00 waiting for data                           topics="libp2p mplex" tid=2016588 file=mplex.nim:128 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.781+10:00 Closing channel                            topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:122 s=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=0
TRC 2021-07-20 15:22:27.781+10:00 writing mplex message                      topics="libp2p mplexcoder" tid=2016588 file=coder.nim:80 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 id=4 msgType=CloseIn data=0 encoded=2
TRC 2021-07-20 15:22:27.781+10:00 Closing with EOF                           topics="libp2p lpstream" tid=2016588 file=lpstream.nim:298 s=60f65d93203c475a6b49af8f
TRC 2021-07-20 15:22:27.781+10:00 Already closed                             topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:118 s=QmP*aKRBqV:60f65d93203c475a6b49af8f:4
TRC 2021-07-20 15:22:27.781+10:00 EOF                                        topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:154 s=QmP*aKRBqV:60f65d93203c475a6b49af8f
TRC 2021-07-20 15:22:27.781+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 bytes=0
TRC 2021-07-20 15:22:27.781+10:00 Closing BufferStream                       topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:182 s=QmP*aKRBqV:60f65d93203c475a6b49af8f len=0
TRC 2021-07-20 15:22:27.781+10:00 Closed BufferStream                        topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:218 s=QmP*aKRBqV:60f65d93203c475a6b49af8f
TRC 2021-07-20 15:22:27.781+10:00 Closing connection                         topics="libp2p connection" tid=2016588 file=connection.nim:91 s=QmP*aKRBqV:60f65d93203c475a6b49af8f
TRC 2021-07-20 15:22:27.781+10:00 Closed connection                          topics="libp2p connection" tid=2016588 file=connection.nim:101 s=QmP*aKRBqV:60f65d93203c475a6b49af8f
TRC 2021-07-20 15:22:27.781+10:00 Closing stream                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:266 s=60f65d93203c475a6b49af8f objName=LPChannel dir=In
TRC 2021-07-20 15:22:27.781+10:00 Closed stream                              topics="libp2p lpstream" tid=2016588 file=lpstream.nim:270 s=60f65d93203c475a6b49af8f objName=LPChannel dir=In
TRC 2021-07-20 15:22:27.781+10:00 Stream handler done                        tid=2016588 file=muxedupgrade.nim:222 conn=QmP*aKRBqV:60f65d93203c475a6b49af8f
TRC 2021-07-20 15:22:27.781+10:00 cleaned up channel                         topics="libp2p mplex" tid=2016588 file=mplex.nim:66 m=QmP*aKRBqV:60f65d93203c475a6b49af87 chann=QmP*aKRBqV:60f65d93203c475a6b49af8f:4
TRC 2021-07-20 15:22:27.782+10:00 finished handling stream                   topics="libp2p mplex" tid=2016588 file=mplex.nim:118 m=QmP*aKRBqV:60f65d93203c475a6b49af87 chann=QmP*aKRBqV:60f65d93203c475a6b49af8f:4
TRC 2021-07-20 15:22:27.782+10:00 Already closed                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:276 s=60f65d93203c475a6b49af8f
TRC 2021-07-20 15:22:27.782+10:00 Closed channel                             topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:138 s=QmP*aKRBqV:60f65d93203c475a6b49af8f:4 len=0
INF 2021-07-20 15:22:27.789+10:00 Shutting down after receiving SIGINT       topics="wakunode" tid=2016588 file=wakunode2.nim:846
DBG 2021-07-20 15:22:27.789+10:00 stop                                       topics="wakurelay" tid=2016588 file=waku_relay.nim:96
TRC 2021-07-20 15:22:27.789+10:00 gossipsub stop                             topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:526
TRC 2021-07-20 15:22:27.789+10:00 awaiting last heartbeat                    topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:535
TRC 2021-07-20 15:22:27.790+10:00 couldn't read all bytes, stream EOF        topics="libp2p lpstream" tid=2016588 file=lpstream.nim:173 s=60f65d93203c475a6b49af86 nbytes=2 read=0 objName=ChronosStream
TRC 2021-07-20 15:22:27.791+10:00 Closing secure conn                        topics="libp2p secure" tid=2016588 file=secure.nim:67 s=QmP*aKRBqV:60f65d93203c475a6b49af87 dir=In
TRC 2021-07-20 15:22:27.791+10:00 Shutting down chronos stream               topics="libp2p chronosstream" tid=2016588 file=chronosstream.nim:143 address=127.0.0.1:52704 s=QmP*aKRBqV:60f65d93203c475a6b49af86
TRC 2021-07-20 15:22:27.791+10:00 Shutdown chronos stream                    topics="libp2p chronosstream" tid=2016588 file=chronosstream.nim:148 address=127.0.0.1:52704 s=QmP*aKRBqV:60f65d93203c475a6b49af86
TRC 2021-07-20 15:22:27.791+10:00 Closing connection                         topics="libp2p connection" tid=2016588 file=connection.nim:91 s=QmP*aKRBqV:60f65d93203c475a6b49af86
TRC 2021-07-20 15:22:27.791+10:00 Closed connection                          topics="libp2p connection" tid=2016588 file=connection.nim:101 s=QmP*aKRBqV:60f65d93203c475a6b49af86
TRC 2021-07-20 15:22:27.791+10:00 Closing stream                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:266 s=60f65d93203c475a6b49af86 objName=ChronosStream dir=In
TRC 2021-07-20 15:22:27.791+10:00 Closed stream                              topics="libp2p lpstream" tid=2016588 file=lpstream.nim:270 s=60f65d93203c475a6b49af86 objName=ChronosStream dir=In
TRC 2021-07-20 15:22:27.791+10:00 Cleaning up client                         topics="libp2p tcptransport" tid=2016588 file=tcptransport.nim:98 addrs=127.0.0.1:52704 conn=QmP*aKRBqV:60f65d93203c475a6b49af86
TRC 2021-07-20 15:22:27.791+10:00 Already closed                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:276 s=60f65d93203c475a6b49af86
TRC 2021-07-20 15:22:27.791+10:00 Cleaned up client                          topics="libp2p tcptransport" tid=2016588 file=tcptransport.nim:105 addrs=127.0.0.1:52704 conn=QmP*aKRBqV:60f65d93203c475a6b49af86
TRC 2021-07-20 15:22:27.791+10:00 Releasing slot                             topics="libp2p semaphore" tid=2016588 file=semaphore.nim:77 available=48 queue=0
TRC 2021-07-20 15:22:27.791+10:00 Released slot                              topics="libp2p semaphore" tid=2016588 file=semaphore.nim:87 available=49 queue=0
TRC 2021-07-20 15:22:27.791+10:00 Closing connection                         topics="libp2p connection" tid=2016588 file=connection.nim:91 s=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.791+10:00 Closed connection                          topics="libp2p connection" tid=2016588 file=connection.nim:101 s=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.791+10:00 Closing stream                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:266 s=60f65d93203c475a6b49af87 objName=SecureConn dir=In
TRC 2021-07-20 15:22:27.791+10:00 Closed stream                              topics="libp2p lpstream" tid=2016588 file=lpstream.nim:270 s=60f65d93203c475a6b49af87 objName=SecureConn dir=In
TRC 2021-07-20 15:22:27.791+10:00 Connection closed, cleaning up             topics="libp2p connmanager" tid=2016588 file=connmanager.nim:328 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.791+10:00 Removed connection                         topics="libp2p connmanager" tid=2016588 file=connmanager.nim:263 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.791+10:00 Cleaning up muxer                          topics="libp2p connmanager" tid=2016588 file=connmanager.nim:244 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.791+10:00 Closing mplex                              topics="libp2p mplex" tid=2016588 file=mplex.nim:219 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.791+10:00 Closing channel                            topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:122 s=QmP*aKRBqV:60f65d93203c475a6b49af8c:1 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=0
TRC 2021-07-20 15:22:27.791+10:00 Closed channel                             topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:138 s=QmP*aKRBqV:60f65d93203c475a6b49af8c:1 len=0
TRC 2021-07-20 15:22:27.791+10:00 Closing channel                            topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:122 s=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=0
TRC 2021-07-20 15:22:27.791+10:00 Closed channel                             topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:138 s=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 len=0
TRC 2021-07-20 15:22:27.791+10:00 Closing channel                            topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:122 s=QmP*aKRBqV:60f65d93203c475a6b49af89 conn=QmP*aKRBqV:60f65d93203c475a6b49af87 len=0
TRC 2021-07-20 15:22:27.791+10:00 Closed channel                             topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:138 s=QmP*aKRBqV:60f65d93203c475a6b49af89 len=0
TRC 2021-07-20 15:22:27.791+10:00 Already closed                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:276 s=60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.791+10:00 Resetting channel                          topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:94 s=QmP*aKRBqV:60f65d93203c475a6b49af8c:1 len=0
TRC 2021-07-20 15:22:27.791+10:00 Closing BufferStream                       topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:182 s=QmP*aKRBqV:60f65d93203c475a6b49af8c len=0
TRC 2021-07-20 15:22:27.792+10:00 Closed BufferStream                        topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:218 s=QmP*aKRBqV:60f65d93203c475a6b49af8c
TRC 2021-07-20 15:22:27.792+10:00 Closing connection                         topics="libp2p connection" tid=2016588 file=connection.nim:91 s=QmP*aKRBqV:60f65d93203c475a6b49af8c
TRC 2021-07-20 15:22:27.792+10:00 Closed connection                          topics="libp2p connection" tid=2016588 file=connection.nim:101 s=QmP*aKRBqV:60f65d93203c475a6b49af8c
TRC 2021-07-20 15:22:27.792+10:00 Closing stream                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:266 s=60f65d93203c475a6b49af8c objName=LPChannel dir=In
TRC 2021-07-20 15:22:27.792+10:00 Closed stream                              topics="libp2p lpstream" tid=2016588 file=lpstream.nim:270 s=60f65d93203c475a6b49af8c objName=LPChannel dir=In
TRC 2021-07-20 15:22:27.792+10:00 Channel reset                              topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:111 s=QmP*aKRBqV:60f65d93203c475a6b49af8c:1
TRC 2021-07-20 15:22:27.792+10:00 Resetting channel                          topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:94 s=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 len=0
TRC 2021-07-20 15:22:27.792+10:00 Closing BufferStream                       topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:182 s=QmP*aKRBqV:60f65d93203c475a6b49af8d len=0
TRC 2021-07-20 15:22:27.792+10:00 Closed BufferStream                        topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:218 s=QmP*aKRBqV:60f65d93203c475a6b49af8d
TRC 2021-07-20 15:22:27.792+10:00 Closing connection                         topics="libp2p connection" tid=2016588 file=connection.nim:91 s=QmP*aKRBqV:60f65d93203c475a6b49af8d
TRC 2021-07-20 15:22:27.792+10:00 Closed connection                          topics="libp2p connection" tid=2016588 file=connection.nim:101 s=QmP*aKRBqV:60f65d93203c475a6b49af8d
TRC 2021-07-20 15:22:27.792+10:00 Closing stream                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:266 s=60f65d93203c475a6b49af8d objName=LPChannel dir=In
TRC 2021-07-20 15:22:27.792+10:00 Closed stream                              topics="libp2p lpstream" tid=2016588 file=lpstream.nim:270 s=60f65d93203c475a6b49af8d objName=LPChannel dir=In
TRC 2021-07-20 15:22:27.792+10:00 Channel reset                              topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:111 s=QmP*aKRBqV:60f65d93203c475a6b49af8d:2
TRC 2021-07-20 15:22:27.792+10:00 Resetting channel                          topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:94 s=QmP*aKRBqV:60f65d93203c475a6b49af89 len=0
TRC 2021-07-20 15:22:27.792+10:00 Closing BufferStream                       topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:182 s=QmP*aKRBqV:60f65d93203c475a6b49af89 len=0
TRC 2021-07-20 15:22:27.792+10:00 Closed BufferStream                        topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:218 s=QmP*aKRBqV:60f65d93203c475a6b49af89
TRC 2021-07-20 15:22:27.792+10:00 Closing connection                         topics="libp2p connection" tid=2016588 file=connection.nim:91 s=QmP*aKRBqV:60f65d93203c475a6b49af89
TRC 2021-07-20 15:22:27.792+10:00 Closed connection                          topics="libp2p connection" tid=2016588 file=connection.nim:101 s=QmP*aKRBqV:60f65d93203c475a6b49af89
TRC 2021-07-20 15:22:27.792+10:00 Closing stream                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:266 s=60f65d93203c475a6b49af89 objName=LPChannel dir=Out
TRC 2021-07-20 15:22:27.792+10:00 Closed stream                              topics="libp2p lpstream" tid=2016588 file=lpstream.nim:270 s=60f65d93203c475a6b49af89 objName=LPChannel dir=Out
TRC 2021-07-20 15:22:27.792+10:00 Channel reset                              topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:111 s=QmP*aKRBqV:60f65d93203c475a6b49af89
TRC 2021-07-20 15:22:27.792+10:00 Closed mplex                               topics="libp2p mplex" tid=2016588 file=mplex.nim:239 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.792+10:00 Cleaned up muxer                           topics="libp2p connmanager" tid=2016588 file=connmanager.nim:252 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.792+10:00 Already closed                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:276 s=60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.792+10:00 Connection cleaned up                      topics="libp2p connmanager" tid=2016588 file=connmanager.nim:289 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.792+10:00 Triggering peerCleanup                     topics="libp2p connmanager" tid=2016588 file=connmanager.nim:338 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.792+10:00 Triggering disconnect events               topics="libp2p connmanager" tid=2016588 file=connmanager.nim:310 conn=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.792+10:00 About to trigger connection events         topics="libp2p connmanager" tid=2016588 file=connmanager.nim:139 peer=QmP*aKRBqV
TRC 2021-07-20 15:22:27.792+10:00 triggering connection events               topics="libp2p connmanager" tid=2016588 file=connmanager.nim:141 peer=QmP*aKRBqV event=Disconnected
TRC 2021-07-20 15:22:27.792+10:00 About to trigger peer events               topics="libp2p connmanager" tid=2016588 file=connmanager.nim:185 peer=QmP*aKRBqV
TRC 2021-07-20 15:22:27.792+10:00 triggering peer events                     topics="libp2p connmanager" tid=2016588 file=connmanager.nim:198 peer=QmP*aKRBqV event="(kind: Left)"
TRC 2021-07-20 15:22:27.792+10:00 unsubscribing gossipsub peer               topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:172 peer=QmP*aKRBqV
TRC 2021-07-20 15:22:27.792+10:00 unsubscribing floodsub peer                topics="libp2p floodsub" tid=2016588 file=floodsub.nim:80 peer=QmP*aKRBqV
DBG 2021-07-20 15:22:27.792+10:00 unsubscribing pubsub peer                  topics="libp2p pubsub" tid=2016588 file=pubsub.nim:116 peerId=QmP*aKRBqV
TRC 2021-07-20 15:22:27.792+10:00 Already closed                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:276 s=60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.792+10:00 Already closed                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:276 s=60f65d93203c475a6b49af86
TRC 2021-07-20 15:22:27.792+10:00 cleaned up channel                         topics="libp2p mplex" tid=2016588 file=mplex.nim:66 m=QmP*aKRBqV:60f65d93203c475a6b49af87 chann=QmP*aKRBqV:60f65d93203c475a6b49af8c:1
TRC 2021-07-20 15:22:27.792+10:00 cleaned up channel                         topics="libp2p mplex" tid=2016588 file=mplex.nim:66 m=QmP*aKRBqV:60f65d93203c475a6b49af87 chann=QmP*aKRBqV:60f65d93203c475a6b49af8d:2
TRC 2021-07-20 15:22:27.792+10:00 cleaned up channel                         topics="libp2p mplex" tid=2016588 file=mplex.nim:66 m=QmP*aKRBqV:60f65d93203c475a6b49af87 chann=QmP*aKRBqV:60f65d93203c475a6b49af89
TRC 2021-07-20 15:22:27.793+10:00 EOF                                        topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:154 s=QmP*aKRBqV:60f65d93203c475a6b49af8c
TRC 2021-07-20 15:22:27.793+10:00 EOF                                        topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:154 s=QmP*aKRBqV:60f65d93203c475a6b49af8d
TRC 2021-07-20 15:22:27.793+10:00 EOF                                        topics="libp2p bufferstream" tid=2016588 file=bufferstream.nim:154 s=QmP*aKRBqV:60f65d93203c475a6b49af89
TRC 2021-07-20 15:22:27.793+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8c:1 bytes=0
TRC 2021-07-20 15:22:27.793+10:00 Already closed                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:276 s=60f65d93203c475a6b49af8c
TRC 2021-07-20 15:22:27.793+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af8d:2 bytes=0
TRC 2021-07-20 15:22:27.793+10:00 Already closed                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:276 s=60f65d93203c475a6b49af8d
TRC 2021-07-20 15:22:27.793+10:00 readOnce                                   topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:160 s=QmP*aKRBqV:60f65d93203c475a6b49af89 bytes=0
TRC 2021-07-20 15:22:27.793+10:00 Already closed                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:276 s=60f65d93203c475a6b49af89
TRC 2021-07-20 15:22:27.793+10:00 Stream EOF                                 topics="libp2p mplex" tid=2016588 file=mplex.nim:186 m=QmP*aKRBqV:60f65d93203c475a6b49af87 msg="Stream EOF!"
TRC 2021-07-20 15:22:27.793+10:00 Already closed                             topics="libp2p mplex" tid=2016588 file=mplex.nim:215 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.793+10:00 Stopped mplex handler                      topics="libp2p mplex" tid=2016588 file=mplex.nim:191 m=QmP*aKRBqV:60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.793+10:00 Already closed                             topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:118 s=QmP*aKRBqV:60f65d93203c475a6b49af8c:1
TRC 2021-07-20 15:22:27.793+10:00 Exception occurred in PubSubPeer.handle    topics="libp2p pubsubpeer" tid=2016588 file=pubsubpeer.nim:156 conn=QmP*aKRBqV:60f65d93203c475a6b49af8c peer=QmP*aKRBqV closed=true exc="Stream EOF!"
DBG 2021-07-20 15:22:27.793+10:00 exiting pubsub read loop                   topics="libp2p pubsubpeer" tid=2016588 file=pubsubpeer.nim:159 conn=QmP*aKRBqV:60f65d93203c475a6b49af8c peer=QmP*aKRBqV closed=true
TRC 2021-07-20 15:22:27.793+10:00 Already closed                             topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:118 s=QmP*aKRBqV:60f65d93203c475a6b49af8d:2
TRC 2021-07-20 15:22:27.793+10:00 Exception occurred in PubSubPeer.handle    topics="libp2p pubsubpeer" tid=2016588 file=pubsubpeer.nim:156 conn=QmP*aKRBqV:60f65d93203c475a6b49af8d peer=QmP*aKRBqV closed=true exc="Stream EOF!"
DBG 2021-07-20 15:22:27.793+10:00 exiting pubsub read loop                   topics="libp2p pubsubpeer" tid=2016588 file=pubsubpeer.nim:159 conn=QmP*aKRBqV:60f65d93203c475a6b49af8d peer=QmP*aKRBqV closed=true
TRC 2021-07-20 15:22:27.793+10:00 Already closed                             topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:118 s=QmP*aKRBqV:60f65d93203c475a6b49af89
TRC 2021-07-20 15:22:27.793+10:00 Exception occurred in PubSubPeer.handle    topics="libp2p pubsubpeer" tid=2016588 file=pubsubpeer.nim:156 conn=QmP*aKRBqV:60f65d93203c475a6b49af89 peer=QmP*aKRBqV closed=true exc="Stream EOF!"
DBG 2021-07-20 15:22:27.793+10:00 exiting pubsub read loop                   topics="libp2p pubsubpeer" tid=2016588 file=pubsubpeer.nim:159 conn=QmP*aKRBqV:60f65d93203c475a6b49af89 peer=QmP*aKRBqV closed=true
TRC 2021-07-20 15:22:27.793+10:00 pubsub peer handler ended                  topics="libp2p pubsub" tid=2016588 file=pubsub.nim:364 conn=QmP*aKRBqV:60f65d93203c475a6b49af8c
TRC 2021-07-20 15:22:27.793+10:00 Closing with EOF                           topics="libp2p lpstream" tid=2016588 file=lpstream.nim:298 s=60f65d93203c475a6b49af8c
TRC 2021-07-20 15:22:27.793+10:00 Already closed                             topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:118 s=QmP*aKRBqV:60f65d93203c475a6b49af8c:1
TRC 2021-07-20 15:22:27.793+10:00 pubsub peer handler ended                  topics="libp2p pubsub" tid=2016588 file=pubsub.nim:364 conn=QmP*aKRBqV:60f65d93203c475a6b49af8d
TRC 2021-07-20 15:22:27.793+10:00 Closing with EOF                           topics="libp2p lpstream" tid=2016588 file=lpstream.nim:298 s=60f65d93203c475a6b49af8d
TRC 2021-07-20 15:22:27.793+10:00 Already closed                             topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:118 s=QmP*aKRBqV:60f65d93203c475a6b49af8d:2
TRC 2021-07-20 15:22:27.793+10:00 Removing send connection                   topics="libp2p pubsubpeer" tid=2016588 file=pubsubpeer.nim:182 p=QmP*aKRBqV conn=QmP*aKRBqV:60f65d93203c475a6b49af89
TRC 2021-07-20 15:22:27.793+10:00 Already closed                             topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:118 s=QmP*aKRBqV:60f65d93203c475a6b49af89
TRC 2021-07-20 15:22:27.793+10:00 Already closed                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:276 s=60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.794+10:00 Dialing (existing)                         topics="libp2p dialer" tid=2016588 file=dialer.nim:185 peerId=QmP*aKRBqV protos="@[\"/vac/waku/relay/2.0.0\", \"/vac/waku/relay/2.0.0\"]"
TRC 2021-07-20 15:22:27.794+10:00 connection not found                       topics="libp2p connmanager" tid=2016588 file=connmanager.nim:362 peerId=QmP*aKRBqV
DBG 2021-07-20 15:22:27.794+10:00 Could not establish send connection        topics="libp2p pubsubpeer" tid=2016588 file=pubsubpeer.nim:204 msg="Couldn't get muxed stream"
TRC 2021-07-20 15:22:27.794+10:00 Dropping peer                              topics="libp2p connmanager" tid=2016588 file=connmanager.nim:548 peerId=QmP*aKRBqV
TRC 2021-07-20 15:22:27.794+10:00 Peer dropped                               topics="libp2p connmanager" tid=2016588 file=connmanager.nim:567 peerId=QmP*aKRBqV
TRC 2021-07-20 15:22:27.794+10:00 Already closed                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:276 s=60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.794+10:00 Already closed                             topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:118 s=QmP*aKRBqV:60f65d93203c475a6b49af8c:1
TRC 2021-07-20 15:22:27.794+10:00 Already closed                             topics="libp2p mplexchannel" tid=2016588 file=lpchannel.nim:118 s=QmP*aKRBqV:60f65d93203c475a6b49af8d:2
TRC 2021-07-20 15:22:27.794+10:00 Already closed                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:276 s=60f65d93203c475a6b49af87
TRC 2021-07-20 15:22:27.794+10:00 Stopped secure handler                     topics="libp2p muxedupgrade" tid=2016588 file=muxedupgrade.nim:142 conn=QmP*aKRBqV:60f65d93203c475a6b49af86
TRC 2021-07-20 15:22:27.794+10:00 Closing with EOF                           topics="libp2p lpstream" tid=2016588 file=lpstream.nim:298 s=60f65d93203c475a6b49af8c
TRC 2021-07-20 15:22:27.794+10:00 Already closed                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:300
TRC 2021-07-20 15:22:27.794+10:00 Stream handler done                        tid=2016588 file=muxedupgrade.nim:222 conn=QmP*aKRBqV:60f65d93203c475a6b49af8c
TRC 2021-07-20 15:22:27.794+10:00 Closing with EOF                           topics="libp2p lpstream" tid=2016588 file=lpstream.nim:298 s=60f65d93203c475a6b49af8d
TRC 2021-07-20 15:22:27.794+10:00 Already closed                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:300
TRC 2021-07-20 15:22:27.794+10:00 Stream handler done                        tid=2016588 file=muxedupgrade.nim:222 conn=QmP*aKRBqV:60f65d93203c475a6b49af8d
TRC 2021-07-20 15:22:27.794+10:00 Already closed                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:276 s=60f65d93203c475a6b49af86
TRC 2021-07-20 15:22:27.794+10:00 finished handling stream                   topics="libp2p mplex" tid=2016588 file=mplex.nim:118 m=QmP*aKRBqV:60f65d93203c475a6b49af87 chann=QmP*aKRBqV:60f65d93203c475a6b49af8c:1
TRC 2021-07-20 15:22:27.794+10:00 finished handling stream                   topics="libp2p mplex" tid=2016588 file=mplex.nim:118 m=QmP*aKRBqV:60f65d93203c475a6b49af87 chann=QmP*aKRBqV:60f65d93203c475a6b49af8d:2
TRC 2021-07-20 15:22:27.794+10:00 Already closed                             topics="libp2p lpstream" tid=2016588 file=lpstream.nim:276 s=60f65d93203c475a6b49af86
TRC 2021-07-20 15:22:28.062+10:00 heartbeat stopped                          topics="libp2p gossipsub" tid=2016588 file=gossipsub.nim:537
TRC 2021-07-20 15:22:28.062+10:00 Stopping switch                            topics="libp2p switch" tid=2016588 file=switch.nim:226
TRC 2021-07-20 15:22:28.062+10:00 Closing ConnManager                        topics="libp2p connmanager" tid=2016588 file=connmanager.nim:574
TRC 2021-07-20 15:22:28.062+10:00 Closed ConnManager                         topics="libp2p connmanager" tid=2016588 file=connmanager.nim:588
TRC 2021-07-20 15:22:28.062+10:00 Stopping TCP transport                     topics="libp2p tcptransport" tid=2016588 file=tcptransport.nim:164
DBG 2021-07-20 15:22:28.062+10:00 Server was closed                          topics="libp2p tcptransport" tid=2016588 file=tcptransport.nim:218 exc="Server is already closed!"
TRC 2021-07-20 15:22:28.062+10:00 Exception tracking connection              topics="libp2p connmanager" tid=2016588 file=connmanager.nim:432 exc="Transport closed, no more connections!"
TRC 2021-07-20 15:22:28.063+10:00 Transport stopped                          topics="libp2p tcptransport" tid=2016588 file=tcptransport.nim:177
TRC 2021-07-20 15:22:28.063+10:00 Exception tracking connection              topics="libp2p connmanager" tid=2016588 file=connmanager.nim:458 exc="Transport closed, no more connections!"
TRC 2021-07-20 15:22:28.063+10:00 Releasing slot                             topics="libp2p semaphore" tid=2016588 file=semaphore.nim:77 available=49 queue=0
TRC 2021-07-20 15:22:28.063+10:00 Released slot                              topics="libp2p semaphore" tid=2016588 file=semaphore.nim:87 available=50 queue=0
DBG 2021-07-20 15:22:28.063+10:00 Exception in accept loop, exiting          topics="libp2p switch" tid=2016588 file=switch.nim:200 exc="Transport closed, no more connections!"
TRC 2021-07-20 15:22:28.063+10:00 Releasing slot                             topics="libp2p semaphore" tid=2016588 file=semaphore.nim:77 available=3 queue=0
TRC 2021-07-20 15:22:28.063+10:00 Released slot                              topics="libp2p semaphore" tid=2016588 file=semaphore.nim:87 available=4 queue=0
TRC 2021-07-20 15:22:28.063+10:00 Switch stopped                             topics="libp2p switch" tid=2016588 file=switch.nim:251

[D4nte]

I am guessing it is expected as there is no timestamp on the rpc type WakuRelayMessage:

https://github.com/status-im/nim-waku/blob/108599a1ed2a26663f911afdafe79604c6b5ffd0/waku/v2/node/jsonrpc/jsonrpc_types.nim#L18

Is that something we could have for v0.5 please?

[staheri14]

Is that something we could have for v0.5 please?

@D4nte Created this PR to address the issue It will soon be merged into master and be part of v 0.5

[staheri14]

@D4nte The PR is merged, please let me know if the problem with the order of historical messages and their timestamp is resolved.

[D4nte]

@D4nte The PR is merged, please let me know if the problem with the order of historical messages and their timestamp is resolved.

Resolved, then got tricked by the cursor as I did not notice it was changed! all good now 👍