[WIP] fix: circuit-go-rv1-go #496

lidel · 2022-09-08T22:15:26Z

This reuses #462 + add some debug configs

This PR is a sandbox to try to fix circuit go-rv1-go test that fails on CI:

Updates deps and adds types to tests. BREAKING CHANGE: needs ESM release of ipfs/libp2p

achingbrain · 2022-09-09T15:04:35Z

~~I see this from both go instances in the go-rv1-go test:~~

2022-09-09T14:33:52.431Z ipfsd-ctl:daemon:stderr 2022-09-09T14:33:52.420Z	ERROR	provider.queue	queue/queue.go:124	Failed to enqueue cid: leveldb: closed

This is a red herring, there's no error like this with [email protected] but it's still broken.

achingbrain · 2022-09-09T18:15:39Z

The problem is that the relay daemon doesn't always start up.

This build passed - https://github.com/ipfs/interop/actions/runs/3024182787/attempts/1 - I restarted the build, no changes between and it failed: https://github.com/ipfs/interop/actions/runs/3024182787/attempts/2

Successful (notice RelayV1 is running!):

circuit
    v1
      go-rv1-go
Starting relayd_v1..
scripts/libp2p-relay-daemon -config scripts/relayd_v1.config.json -id scripts/relayd_v1.identity
Generating peer identity in scripts/relayd_v1.identity

I am 12D3KooWPtFNMUscrU8wwe4k9zRTVf6qEw3UKkbJGdHjnvBaBof7

Public Addresses:

	/ip4/127.0.0.1/tcp/14111/ws/p2p/12D3KooWPtFNMUscrU8wwe4k9zRTVf6qEw3UKkbJGdHjnvBaBof7

The pprof debug is disabled

Starting RelayV1...
RelayV1 is running!

2022-09-09T17:22:17.2[21](https://github.com/ipfs/interop/runs/8275349685?check_suite_focus=true#step:5:22)Z ipfsd-ctl:daemon:stdout generating ED[25](https://github.com/ipfs/interop/runs/8275349685?check_suite_focus=true#step:5:26)519 keypair...done
peer identity: 12D3KooWRpiGjgudF2jbNbY5XX1rBmFHrt9HirHnitZEVm2rk5Hz
initializing IPFS node at /tmp/go_ipfs_-do6[39](https://github.com/ipfs/interop/runs/8275349685?check_suite_focus=true#step:5:40)0RkPR7fKkfy5ilx
to get started, enter:
... more output

Failure (notice no RelayV1 is running!):

circuit
    v1
      go-rv1-go
Starting relayd_v1..
scripts/libp2p-relay-daemon -config scripts/relayd_v1.config.json -id scripts/relayd_v1.identity
20[22](https://github.com/ipfs/interop/runs/8275773530?check_suite_focus=true#step:5:23)-09-09T17:50:14.132Z ipfsd-ctl:daemon:stdout generating ED[25](https://github.com/ipfs/interop/runs/8275773530?check_suite_focus=true#step:5:26)519 keypair...done
peer identity: 12D3KooWNHmhF1tpQ93TfeSysgxTh5mZKcqWPoCBaJCkZQVfpC1G
initializing IPFS node at /tmp/go_ipfs_s8ADoSJFYlDhNKuDRcZEd
to get started, enter:
... more output

SgtPooki · 2022-09-09T19:44:03Z

Working test run with GOLOG_LOG_LEVEL: https://github.com/ipfs/interop/runs/8277122415?check_suite_focus=true
log output: successlog.notimestamps.log

Failed test run with GOLOG_LOG_LEVEL: https://github.com/ipfs/interop/runs/8277153592?check_suite_focus=true
log output: faillog.notimestamps.log

Things missing from the failed run that are found in the successful run:

comm -13 ~/Downloads/go-rv1-go-fail/faillog.notimestamps.log ~/Downloads/go-rv1-go-success/successlog.notimestamps.log
TIMESTAMP [19:18:41] tsc [started]
TIMESTAMP [19:18:44] tsc [completed]
TIMESTAMP [19:18:44] esbuild [started]
TIMESTAMP [19:18:44] esbuild [completed]
TIMESTAMP TIMESTAMP	INFO	tcp-tpt	tcp/reuseport.go:21	REUSEPORT disabled (LIBP2P_TCP_REUSEPORT=false)
TIMESTAMP
TIMESTAMP Generating peer identity in scripts/relayd_v1.identity
TIMESTAMP
TIMESTAMP TIMESTAMP	DEBUG	rcmgr	[email protected]/limit.go:75	initializing new limiter with config	{"limits": {"System":{"Streams":3528,"StreamsInbound":1764,"StreamsOutbound":3528,"Conns":220,"ConnsInbound":110,"ConnsOutbound":220,"FD":32768,"Memory":910163968},"Transient":{"Streams":441,"StreamsInbound":220,"StreamsOutbound":441,"Conns":87,"ConnsInbound":43,"ConnsOutbound":87,"FD":8192,"Memory":130547712},"AllowlistedSystem":{"Streams":3528,"StreamsInbound":1764,"StreamsOutbound":3528,"Conns":220,"ConnsInbound":110,"ConnsOutbound":220,"FD":32768,"Memory":910163968},"AllowlistedTransient":{"Streams":441,"StreamsInbound":220,"StreamsOutbound":441,"Conns":87,"ConnsInbound":43,"ConnsOutbound":87,"FD":8192,"Memory":130547712},"ServiceDefault":{"Streams":5576,"StreamsInbound":1394,"StreamsOutbound":5576,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":164102144},"Service":{"libp2p.autonat":{"Streams":66,"StreamsInbound":66,"StreamsOutbound":66,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":5709824},"libp2p.holepunch":{"Streams":75,"StreamsInbound":37,"StreamsOutbound":37,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":7225344},"libp2p.identify":{"Streams":220,"StreamsInbound":110,"StreamsOutbound":110,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":7225344},"libp2p.ping":{"Streams":110,"StreamsInbound":110,"StreamsOutbound":110,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":7225344},"libp2p.relay/v1":{"Streams":441,"StreamsInbound":441,"StreamsOutbound":441,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":28901376},"libp2p.relay/v2":{"Streams":441,"StreamsInbound":441,"StreamsOutbound":441,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":28901376}},"ServicePeerDefault":{"Streams":261,"StreamsInbound":130,"StreamsOutbound":261,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":19808256},"ServicePeer":{"libp2p.autonat":{"Streams":2,"StreamsInbound":2,"StreamsOutbound":2,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":1048576},"libp2p.holepunch":{"Streams":2,"StreamsInbound":2,"StreamsOutbound":2,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":1048576},"libp2p.identify":{"Streams":32,"StreamsInbound":16,"StreamsOutbound":16,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":1048576},"libp2p.ping":{"Streams":4,"StreamsInbound":2,"StreamsOutbound":3,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":8590458880},"libp2p.relay/v1":{"Streams":64,"StreamsInbound":64,"StreamsOutbound":64,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":1048576},"libp2p.relay/v2":{"Streams":64,"StreamsInbound":64,"StreamsOutbound":64,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":1048576}},"ProtocolDefault":{"Streams":2418,"StreamsInbound":697,"StreamsOutbound":2418,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":191381504},"Protocol":{"/ipfs/id/1.0.0":{"Streams":220,"StreamsInbound":110,"StreamsOutbound":110,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":7225344},"/ipfs/id/push/1.0.0":{"Streams":220,"StreamsInbound":110,"StreamsOutbound":110,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":7225344},"/ipfs/ping/1.0.0":{"Streams":110,"StreamsInbound":110,"StreamsOutbound":110,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":7225344},"/libp2p/autonat/1.0.0":{"Streams":66,"StreamsInbound":66,"StreamsOutbound":66,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":5709824},"/libp2p/circuit/relay/0.1.0":{"Streams":1102,"StreamsInbound":1102,"StreamsOutbound":1102,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":28901376},"/libp2p/circuit/relay/0.2.0/hop":{"Streams":1102,"StreamsInbound":1102,"StreamsOutbound":1102,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":28901376},"/libp2p/circuit/relay/0.2.0/stop":{"Streams":1102,"StreamsInbound":1102,"StreamsOutbound":1102,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":28901376},"/libp2p/dcutr":{"Streams":75,"StreamsInbound":37,"StreamsOutbound":37,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":7225344},"/p2p/id/delta/1.0.0":{"Streams":220,"StreamsInbound":110,"StreamsOutbound":110,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":7225344}},"ProtocolPeerDefault":{"Streams":267,"StreamsInbound":66,"StreamsOutbound":133,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":16777218},"ProtocolPeer":{"/ipfs/id/1.0.0":{"Streams":32,"StreamsInbound":16,"StreamsOutbound":16,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":8590458880},"/ipfs/id/push/1.0.0":{"Streams":32,"StreamsInbound":16,"StreamsOutbound":16,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":8590458880},"/ipfs/ping/1.0.0":{"Streams":4,"StreamsInbound":2,"StreamsOutbound":3,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":8590458880},"/libp2p/autonat/1.0.0":{"Streams":2,"StreamsInbound":2,"StreamsOutbound":2,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":1048576},"/libp2p/circuit/relay/0.1.0":{"Streams":128,"StreamsInbound":128,"StreamsOutbound":128,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":33554432},"/libp2p/circuit/relay/0.2.0/hop":{"Streams":128,"StreamsInbound":128,"StreamsOutbound":128,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":33554432},"/libp2p/circuit/relay/0.2.0/stop":{"Streams":128,"StreamsInbound":128,"StreamsOutbound":128,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":33554432},"/libp2p/dcutr":{"Streams":2,"StreamsInbound":2,"StreamsOutbound":2,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":1048576},"/p2p/id/delta/1.0.0":{"Streams":32,"StreamsInbound":16,"StreamsOutbound":16,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":8590458880}},"PeerDefault":{"Streams":697,"StreamsInbound":348,"StreamsOutbound":697,"Conns":8,"ConnsInbound":4,"ConnsOutbound":8,"FD":512,"Memory":164102144},"Conn":{"Streams":0,"StreamsInbound":0,"StreamsOutbound":0,"Conns":1,"ConnsInbound":1,"ConnsOutbound":1,"FD":1,"Memory":1048576},"Stream":{"Streams":1,"StreamsInbound":1,"StreamsOutbound":1,"Conns":0,"ConnsInbound":0,"ConnsOutbound":0,"FD":0,"Memory":16777216}}}
TIMESTAMP
TIMESTAMP TIMESTAMP	DEBUG	basichost	basic/basic_host.go:313	failed to fetch local IPv6 address	{"error": "no route found for ::"}
TIMESTAMP
TIMESTAMP I am 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH
TIMESTAMP Public Addresses:
TIMESTAMP
TIMESTAMP 	/ip4/127.0.0.1/tcp/14111/ws/p2p/12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH
TIMESTAMP The pprof debug is disabled
TIMESTAMP
TIMESTAMP TIMESTAMP	DEBUG	basichost	basic/basic_host.go:313	failed to fetch local IPv6 address	{"error": "no route found for ::"}
TIMESTAMP
TIMESTAMP TIMESTAMP	DEBUG	basichost	basic/basic_host.go:313	failed to fetch local IPv6 address	{"error": "no route found for ::"}
TIMESTAMP
TIMESTAMP Starting RelayV1...
TIMESTAMP
TIMESTAMP RelayV1 is running!
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stdout generating ED25519 keypair...done
TIMESTAMP peer identity: 12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv
TIMESTAMP initializing IPFS node at /tmp/go_ipfs_mEfGXMP6QC1phSC4Dz5Wm
TIMESTAMP TIMESTAMP	DEBUG	cmd/ipfs	ipfs/main.go:140	config path is /tmp/go_ipfs_mEfGXMP6QC1phSC4Dz5Wm
TIMESTAMP TIMESTAMP	DEBUG	lock	[email protected]/fslock.go:64	File doesn't exist: /tmp/go_ipfs_mEfGXMP6QC1phSC4Dz5Wm/repo.lock
TIMESTAMP TIMESTAMP	DEBUG	namesys	[email protected]/publisher.go:130	error when determining the last published IPNS record for 12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv: datastore: key not found
TIMESTAMP TIMESTAMP	DEBUG	namesys	[email protected]/publisher.go:301	Storing ipns entry at: 2f69706e732f00240801122007b5fe1d84376c2575cbbccf240852c49552181a278aa8c2435465774e17289f
TIMESTAMP TIMESTAMP	DEBUG	blockservice	[email protected]/blockservice.go:401	blockservice is shutting down...
TIMESTAMP peer identity: 12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd
TIMESTAMP initializing IPFS node at /tmp/go_ipfs_3ul_dCdk_0ZLV9xYO_tLx
TIMESTAMP TIMESTAMP	DEBUG	cmd/ipfs	ipfs/main.go:140	config path is /tmp/go_ipfs_3ul_dCdk_0ZLV9xYO_tLx
TIMESTAMP TIMESTAMP	DEBUG	lock	[email protected]/fslock.go:64	File doesn't exist: /tmp/go_ipfs_3ul_dCdk_0ZLV9xYO_tLx/repo.lock
TIMESTAMP TIMESTAMP	DEBUG	namesys	[email protected]/publisher.go:130	error when determining the last published IPNS record for 12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd: datastore: key not found
TIMESTAMP TIMESTAMP	DEBUG	namesys	[email protected]/publisher.go:301	Storing ipns entry at: 2f69706e732f0024080112206638634d355efd5d841544b9f5d069aab0fc9eb3419722fcb1a5dbdd4ad3218e
TIMESTAMP TIMESTAMP	DEBUG	blockservice	[email protected]/blockservice.go:401	blockservice is shutting down...
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	cmd/ipfs	ipfs/main.go:140	config path is /tmp/go_ipfs_mEfGXMP6QC1phSC4Dz5Wm
TIMESTAMP
TIMESTAMP Kubo version: 0.15.0
TIMESTAMP Repo version: 12
TIMESTAMP System version: amd64/linux
TIMESTAMP Golang version: go1.18.5
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	INFO	tcp-tpt	tcp/reuseport.go:21	REUSEPORT disabled (LIBP2P_TCP_REUSEPORT=false)
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	p2pnode	libp2p/rcmgr.go:109	libp2p resource manager is disabled
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	basichost	basic/basic_host.go:313	failed to fetch local IPv6 address	{"error": "no route found for ::"}
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	INFO	p2pnode	libp2p/addrs.go:132	Swarm listening at: [/p2p-circuit /ip4/127.0.0.1/tcp/44087/ws]
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	INFO	peering	peering/peering.go:190	starting
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	WARN	bootstrap	bootstrap/bootstrap.go:82	no bootstrap nodes configured: go-ipfs may have difficulty connecting to the network
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	autorelay	autorelay/relay_finder.go:591	starting relay finder
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	cmd/ipfs	ipfs/main.go:140	config path is /tmp/go_ipfs_3ul_dCdk_0ZLV9xYO_tLx
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stdout Initializing daemon...
TIMESTAMP
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	basichost	basic/basic_host.go:313	failed to fetch local IPv6 address	{"error": "no route found for ::"}
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	basichost	basic/basic_host.go:313	failed to fetch local IPv6 address	{"error": "no route found for ::"}
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	bitswap-server	server/server.go:261	Bitswap.TaskWorker.Loop	{"ID": 0}
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	bitswap-server	server/server.go:261	Bitswap.TaskWorker.Loop	{"ID": 1}
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	bitswap-server	server/server.go:261	Bitswap.TaskWorker.Loop	{"ID": 2}
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	bitswap-server	server/server.go:261	Bitswap.TaskWorker.Loop	{"ID": 3}
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	bitswap-server	server/server.go:261	Bitswap.TaskWorker.Loop	{"ID": 4}
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	bitswap-server	server/server.go:261	Bitswap.TaskWorker.Loop	{"ID": 5}
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	bitswap-server	server/server.go:261	Bitswap.TaskWorker.Loop	{"ID": 6}
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	bitswap-server	server/server.go:261	Bitswap.TaskWorker.Loop	{"ID": 7}
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	bitswap-server	server/server.go:481	Bitswap.ProvideWorker.Loop
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	INFO	provider.simple	simple/provider.go:111	announce - start - QmQy6xmJhrcC5QLboAcGFcAE1tC8CrwDVkrHdEYJkLscrQ
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	WARN	provider.simple	simple/provider.go:113	Unable to provide entry: QmQy6xmJhrcC5QLboAcGFcAE1tC8CrwDVkrHdEYJkLscrQ, routing: operation or key not supported
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	INFO	provider.simple	simple/provider.go:115	announce - end - QmQy6xmJhrcC5QLboAcGFcAE1tC8CrwDVkrHdEYJkLscrQ
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	INFO	provider.simple	simple/provider.go:111	announce - start - QmPZ9gcCEpqKTo6aq61g2nXGUhM4iCL3ewB6LDXZCtioEB
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	WARN	provider.simple	simple/provider.go:113	Unable to provide entry: QmPZ9gcCEpqKTo6aq61g2nXGUhM4iCL3ewB6LDXZCtioEB, routing: operation or key not supported
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	INFO	provider.simple	simple/provider.go:115	announce - end - QmPZ9gcCEpqKTo6aq61g2nXGUhM4iCL3ewB6LDXZCtioEB
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	INFO	provider.simple	simple/provider.go:111	announce - start - QmU5k7ter3RdjZXu3sHghsga1UQtrztnQxmTL22nPnsu3g
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	WARN	provider.simple	simple/provider.go:113	Unable to provide entry: QmU5k7ter3RdjZXu3sHghsga1UQtrztnQxmTL22nPnsu3g, routing: operation or key not supported
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	INFO	provider.simple	simple/provider.go:115	announce - end - QmU5k7ter3RdjZXu3sHghsga1UQtrztnQxmTL22nPnsu3g
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	INFO	provider.simple	simple/provider.go:111	announce - start - QmYCvbfNbCwFR45HiNP45rwJgvatpiW38D961L5qAhUM5Y
TIMESTAMP
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	INFO	provider.simple	simple/provider.go:115	announce - end - QmYCvbfNbCwFR45HiNP45rwJgvatpiW38D961L5qAhUM5Y
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	INFO	provider.simple	simple/provider.go:111	announce - start - QmQ5vhrL7uv6tuoN9KeVBwd4PwfQkXdVVmDLUZuTNxqgvm
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	WARN	provider.simple	simple/provider.go:113	Unable to provide entry: QmQ5vhrL7uv6tuoN9KeVBwd4PwfQkXdVVmDLUZuTNxqgvm, routing: operation or key not supported
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	INFO	provider.simple	simple/provider.go:115	announce - end - QmQ5vhrL7uv6tuoN9KeVBwd4PwfQkXdVVmDLUZuTNxqgvm
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	INFO	provider.simple	simple/provider.go:111	announce - start - QmQGiYLVAdSHJQKYFRTJZMG4BXBHqKperaZtyKGmCRLmsF
TIMESTAMP
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	INFO	provider.simple	simple/provider.go:115	announce - end - QmQGiYLVAdSHJQKYFRTJZMG4BXBHqKperaZtyKGmCRLmsF
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	INFO	provider.simple	simple/provider.go:111	announce - start - QmejvEPop4D7YUadeGqYWmZxHhLc4JBUCzJJHWMzdcMe2y
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	WARN	provider.simple	simple/provider.go:113	Unable to provide entry: QmejvEPop4D7YUadeGqYWmZxHhLc4JBUCzJJHWMzdcMe2y, routing: operation or key not supported
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	INFO	provider.simple	simple/provider.go:115	announce - end - QmejvEPop4D7YUadeGqYWmZxHhLc4JBUCzJJHWMzdcMe2y
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	bootstrap	bootstrap/bootstrap.go:142	12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv no more bootstrap peers to create 4 connections
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	bootstrap	bootstrap/bootstrap.go:90	12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv bootstrap error: not enough bootstrap peers to bootstrap
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	INFO	provider.simple	simple/provider.go:111	announce - start - QmQPeNsJPyVWPFDVHb77w8G42Fvo15z4bG2X8D2GhfbSXc
TIMESTAMP TIMESTAMP	WARN	provider.simple	simple/provider.go:113	Unable to provide entry: QmQPeNsJPyVWPFDVHb77w8G42Fvo15z4bG2X8D2GhfbSXc, routing: operation or key not supported
TIMESTAMP TIMESTAMP	INFO	provider.simple	simple/provider.go:115	announce - end - QmQPeNsJPyVWPFDVHb77w8G42Fvo15z4bG2X8D2GhfbSXc
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stdout Swarm listening on /ip4/127.0.0.1/tcp/44087/ws
TIMESTAMP Swarm listening on /p2p-circuit
TIMESTAMP Swarm announcing /ip4/127.0.0.1/tcp/44087/ws
TIMESTAMP API server listening on /ip4/127.0.0.1/tcp/43141
TIMESTAMP WebUI: http://127.0.0.1:43141/webui
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	p2pnode	libp2p/rcmgr.go:109	libp2p resource manager is disabled
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stdout Gateway (readonly) server listening on /ip4/127.0.0.1/tcp/36997
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stdout Daemon is ready
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	INFO	core/server	corehttp/metrics.go:28	Init OpenCensus
TIMESTAMP TIMESTAMP	INFO	core/server	corehttp/metrics.go:59	Init OpenCensus with default prometheus registry
TIMESTAMP TIMESTAMP	INFO	core/server	corehttp/commands.go:63	Using API.HTTPHeaders:map[Access-Control-Allow-Methods:[PUT POST GET] Access-Control-Allow-Origin:[*]]
TIMESTAMP TIMESTAMP	INFO	core/server	corehttp/commands.go:63	Using API.HTTPHeaders:map[Access-Control-Allow-Methods:[PUT POST GET] Access-Control-Allow-Origin:[*]]
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	basichost	basic/basic_host.go:313	failed to fetch local IPv6 address	{"error": "no route found for ::"}
TIMESTAMP TIMESTAMP	INFO	p2pnode	libp2p/addrs.go:132	Swarm listening at: [/p2p-circuit /ip4/127.0.0.1/tcp/46651/ws]
TIMESTAMP TIMESTAMP	INFO	peering	peering/peering.go:190	starting
TIMESTAMP TIMESTAMP	WARN	bootstrap	bootstrap/bootstrap.go:82	no bootstrap nodes configured: go-ipfs may have difficulty connecting to the network
TIMESTAMP TIMESTAMP	DEBUG	autorelay	autorelay/relay_finder.go:591	starting relay finder
TIMESTAMP TIMESTAMP	DEBUG	basichost	basic/basic_host.go:313	failed to fetch local IPv6 address	{"error": "no route found for ::"}
TIMESTAMP TIMESTAMP	DEBUG	basichost	basic/basic_host.go:313	failed to fetch local IPv6 address	{"error": "no route found for ::"}
TIMESTAMP TIMESTAMP	DEBUG	bitswap-server	server/server.go:261	Bitswap.TaskWorker.Loop	{"ID": 0}
TIMESTAMP TIMESTAMP	DEBUG	bitswap-server	server/server.go:261	Bitswap.TaskWorker.Loop	{"ID": 1}
TIMESTAMP TIMESTAMP	DEBUG	bitswap-server	server/server.go:261	Bitswap.TaskWorker.Loop	{"ID": 2}
TIMESTAMP TIMESTAMP	DEBUG	bitswap-server	server/server.go:261	Bitswap.TaskWorker.Loop	{"ID": 3}
TIMESTAMP TIMESTAMP	DEBUG	bitswap-server	server/server.go:261	Bitswap.TaskWorker.Loop	{"ID": 4}
TIMESTAMP TIMESTAMP	DEBUG	bitswap-server	server/server.go:261	Bitswap.TaskWorker.Loop	{"ID": 5}
TIMESTAMP TIMESTAMP	DEBUG	bitswap-server	server/server.go:261	Bitswap.TaskWorker.Loop	{"ID": 6}
TIMESTAMP TIMESTAMP	DEBUG	bitswap-server	server/server.go:261	Bitswap.TaskWorker.Loop	{"ID": 7}
TIMESTAMP TIMESTAMP	DEBUG	bitswap-server	server/server.go:481	Bitswap.ProvideWorker.Loop
TIMESTAMP TIMESTAMP	INFO	provider.simple	simple/provider.go:111	announce - start - QmQy6xmJhrcC5QLboAcGFcAE1tC8CrwDVkrHdEYJkLscrQ
TIMESTAMP TIMESTAMP	WARN	provider.simple	simple/provider.go:113	Unable to provide entry: QmQy6xmJhrcC5QLboAcGFcAE1tC8CrwDVkrHdEYJkLscrQ, routing: operation or key not supported
TIMESTAMP TIMESTAMP	INFO	provider.simple	simple/provider.go:115	announce - end - QmQy6xmJhrcC5QLboAcGFcAE1tC8CrwDVkrHdEYJkLscrQ
TIMESTAMP TIMESTAMP	INFO	provider.simple	simple/provider.go:111	announce - start - QmPZ9gcCEpqKTo6aq61g2nXGUhM4iCL3ewB6LDXZCtioEB
TIMESTAMP TIMESTAMP	WARN	provider.simple	simple/provider.go:113	Unable to provide entry: QmPZ9gcCEpqKTo6aq61g2nXGUhM4iCL3ewB6LDXZCtioEB, routing: operation or key not supported
TIMESTAMP TIMESTAMP	INFO	provider.simple	simple/provider.go:115	announce - end - QmPZ9gcCEpqKTo6aq61g2nXGUhM4iCL3ewB6LDXZCtioEB
TIMESTAMP TIMESTAMP	INFO	provider.simple	simple/provider.go:111	announce - start - QmU5k7ter3RdjZXu3sHghsga1UQtrztnQxmTL22nPnsu3g
TIMESTAMP TIMESTAMP	WARN	provider.simple	simple/provider.go:113	Unable to provide entry: QmU5k7ter3RdjZXu3sHghsga1UQtrztnQxmTL22nPnsu3g, routing: operation or key not supported
TIMESTAMP TIMESTAMP	INFO	provider.simple	simple/provider.go:115	announce - end - QmU5k7ter3RdjZXu3sHghsga1UQtrztnQxmTL22nPnsu3g
TIMESTAMP TIMESTAMP	INFO	provider.simple	simple/provider.go:111	announce - start - QmYCvbfNbCwFR45HiNP45rwJgvatpiW38D961L5qAhUM5Y
TIMESTAMP TIMESTAMP	WARN	provider.simple	simple/provider.go:113	Unable to provide entry: QmYCvbfNbCwFR45HiNP45rwJgvatpiW38D961L5qAhUM5Y, routing: operation or key not supported
TIMESTAMP TIMESTAMP	INFO	provider.simple	simple/provider.go:115	announce - end - QmYCvbfNbCwFR45HiNP45rwJgvatpiW38D961L5qAhUM5Y
TIMESTAMP TIMESTAMP	INFO	provider.simple	simple/provider.go:111	announce - start - QmQ5vhrL7uv6tuoN9KeVBwd4PwfQkXdVVmDLUZuTNxqgvm
TIMESTAMP TIMESTAMP	WARN	provider.simple	simple/provider.go:113	Unable to provide entry: QmQ5vhrL7uv6tuoN9KeVBwd4PwfQkXdVVmDLUZuTNxqgvm, routing: operation or key not supported
TIMESTAMP TIMESTAMP	INFO	provider.simple	simple/provider.go:115	announce - end - QmQ5vhrL7uv6tuoN9KeVBwd4PwfQkXdVVmDLUZuTNxqgvm
TIMESTAMP TIMESTAMP	INFO	provider.simple	simple/provider.go:111	announce - start - QmQGiYLVAdSHJQKYFRTJZMG4BXBHqKperaZtyKGmCRLmsF
TIMESTAMP TIMESTAMP	WARN	provider.simple	simple/provider.go:113	Unable to provide entry: QmQGiYLVAdSHJQKYFRTJZMG4BXBHqKperaZtyKGmCRLmsF, routing: operation or key not supported
TIMESTAMP TIMESTAMP	INFO	provider.simple	simple/provider.go:115	announce - end - QmQGiYLVAdSHJQKYFRTJZMG4BXBHqKperaZtyKGmCRLmsF
TIMESTAMP TIMESTAMP	INFO	provider.simple	simple/provider.go:111	announce - start - QmejvEPop4D7YUadeGqYWmZxHhLc4JBUCzJJHWMzdcMe2y
TIMESTAMP TIMESTAMP	WARN	provider.simple	simple/provider.go:113	Unable to provide entry: QmejvEPop4D7YUadeGqYWmZxHhLc4JBUCzJJHWMzdcMe2y, routing: operation or key not supported
TIMESTAMP TIMESTAMP	INFO	provider.simple	simple/provider.go:115	announce - end - QmejvEPop4D7YUadeGqYWmZxHhLc4JBUCzJJHWMzdcMe2y
TIMESTAMP TIMESTAMP	DEBUG	bootstrap	bootstrap/bootstrap.go:142	12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd no more bootstrap peers to create 4 connections
TIMESTAMP TIMESTAMP	DEBUG	bootstrap	bootstrap/bootstrap.go:90	12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd bootstrap error: not enough bootstrap peers to bootstrap
TIMESTAMP TIMESTAMP	INFO	core/server	corehttp/metrics.go:28	Init OpenCensus
TIMESTAMP TIMESTAMP	INFO	core/server	corehttp/metrics.go:59	Init OpenCensus with default prometheus registry
TIMESTAMP TIMESTAMP	INFO	core/server	corehttp/commands.go:63	Using API.HTTPHeaders:map[Access-Control-Allow-Methods:[PUT POST GET] Access-Control-Allow-Origin:[*]]
TIMESTAMP TIMESTAMP	INFO	core/server	corehttp/commands.go:63	Using API.HTTPHeaders:map[Access-Control-Allow-Methods:[PUT POST GET] Access-Control-Allow-Origin:[*]]
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stdout Swarm listening on /ip4/127.0.0.1/tcp/46651/ws
TIMESTAMP Swarm listening on /p2p-circuit
TIMESTAMP Swarm announcing /ip4/127.0.0.1/tcp/46651/ws
TIMESTAMP API server listening on /ip4/127.0.0.1/tcp/42587
TIMESTAMP WebUI: http://127.0.0.1:42587/webui
TIMESTAMP Gateway (readonly) server listening on /ip4/127.0.0.1/tcp/41767
TIMESTAMP Daemon is ready
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	cmds/http	http/handler.go:90	incoming API request: /id
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	cmds/http	http/handler.go:90	incoming API request: /id
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	cmds/http	http/handler.go:90	incoming API request: /id
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	cmds/http	http/handler.go:90	incoming API request: /id
TIMESTAMP
TIMESTAMP connect A (12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd) to relay at /ip4/127.0.0.1/tcp/14111/ws/p2p/12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	cmds/http	http/handler.go:90	incoming API request: /swarm/connect?arg=%2Fip4%2F127.0.0.1%2Ftcp%2F14111%2Fws%2Fp2p%2F12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	basichost	basic/basic_host.go:777	host 12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd dialing 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	swarm2	swarm/swarm_dial.go:237	dialing peer	{"from": "12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd", "to": "12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH"}
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	swarm2	swarm/limiter.go:193	[limiter] adding a dial job through limiter: /ip4/127.0.0.1/tcp/14111/ws
TIMESTAMP TIMESTAMP	DEBUG	swarm2	swarm/limiter.go:161	[limiter] taking FD token: peer: 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH; addr: /ip4/127.0.0.1/tcp/14111/ws; prev consuming: 0
TIMESTAMP TIMESTAMP	DEBUG	swarm2	swarm/limiter.go:167	[limiter] executing dial; peer: 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH; addr: /ip4/127.0.0.1/tcp/14111/ws; FD consuming: 1; waiting: 0
TIMESTAMP TIMESTAMP	DEBUG	swarm2	swarm/swarm_dial.go:381	12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd swarm dialing 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH /ip4/127.0.0.1/tcp/14111/ws
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	swarm2	swarm/limiter.go:73	[limiter] freeing FD token; waiting: 0; consuming: 1
TIMESTAMP TIMESTAMP	DEBUG	swarm2	swarm/limiter.go:100	[limiter] freeing peer token; peer 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH; addr: /ip4/127.0.0.1/tcp/14111/ws; active for peer: 1; waiting on peer limit: 0
TIMESTAMP TIMESTAMP	DEBUG	swarm2	swarm/limiter.go:201	[limiter] clearing all peer dials: 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH
TIMESTAMP TIMESTAMP	DEBUG	basichost	basic/basic_host.go:409	protocol negotiation took 23.2µs
TIMESTAMP TIMESTAMP	DEBUG	net/identify	identify/id.go:408	/ipfs/id/1.0.0 sent message to 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH /ip4/127.0.0.1/tcp/14111/ws
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	net/identify	identify/id.go:440	/ipfs/id/1.0.0 received message from 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH /ip4/127.0.0.1/tcp/14111/ws
TIMESTAMP TIMESTAMP	DEBUG	net/identify	identify/id.go:636	12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd received listen addrs for 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH: [/ip4/127.0.0.1/tcp/14111/ws]
TIMESTAMP TIMESTAMP	DEBUG	basichost	basic/basic_host.go:794	host 12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd finished dialing 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH
TIMESTAMP
TIMESTAMP connect B (12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv) to relay at /ip4/127.0.0.1/tcp/14111/ws/p2p/12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	cmds/http	http/handler.go:90	incoming API request: /swarm/connect?arg=%2Fip4%2F127.0.0.1%2Ftcp%2F14111%2Fws%2Fp2p%2F12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	basichost	basic/basic_host.go:777	host 12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv dialing 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH
TIMESTAMP TIMESTAMP	DEBUG	swarm2	swarm/swarm_dial.go:237	dialing peer	{"from": "12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv", "to": "12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH"}
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	swarm2	swarm/limiter.go:193	[limiter] adding a dial job through limiter: /ip4/127.0.0.1/tcp/14111/ws
TIMESTAMP TIMESTAMP	DEBUG	swarm2	swarm/limiter.go:161	[limiter] taking FD token: peer: 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH; addr: /ip4/127.0.0.1/tcp/14111/ws; prev consuming: 0
TIMESTAMP TIMESTAMP	DEBUG	swarm2	swarm/limiter.go:167	[limiter] executing dial; peer: 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH; addr: /ip4/127.0.0.1/tcp/14111/ws; FD consuming: 1; waiting: 0
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	swarm2	swarm/swarm_dial.go:381	12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv swarm dialing 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH /ip4/127.0.0.1/tcp/14111/ws
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	swarm2	swarm/limiter.go:73	[limiter] freeing FD token; waiting: 0; consuming: 1
TIMESTAMP TIMESTAMP	DEBUG	swarm2	swarm/limiter.go:100	[limiter] freeing peer token; peer 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH; addr: /ip4/127.0.0.1/tcp/14111/ws; active for peer: 1; waiting on peer limit: 0
TIMESTAMP TIMESTAMP	DEBUG	swarm2	swarm/limiter.go:201	[limiter] clearing all peer dials: 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH
TIMESTAMP TIMESTAMP	DEBUG	basichost	basic/basic_host.go:409	protocol negotiation took 20.001µs
TIMESTAMP TIMESTAMP	DEBUG	net/identify	identify/id.go:408	/ipfs/id/1.0.0 sent message to 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH /ip4/127.0.0.1/tcp/14111/ws
TIMESTAMP TIMESTAMP	DEBUG	net/identify	identify/id.go:440	/ipfs/id/1.0.0 received message from 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH /ip4/127.0.0.1/tcp/14111/ws
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	net/identify	identify/id.go:636	12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv received listen addrs for 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH: [/ip4/127.0.0.1/tcp/14111/ws]
TIMESTAMP TIMESTAMP	DEBUG	basichost	basic/basic_host.go:794	host 12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv finished dialing 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH
TIMESTAMP
TIMESTAMP connect A to B over circuit /ip4/127.0.0.1/tcp/14111/ws/p2p/12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH/p2p-circuit/p2p/12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	cmds/http	http/handler.go:90	incoming API request: /swarm/connect?arg=%2Fip4%2F127.0.0.1%2Ftcp%2F14111%2Fws%2Fp2p%2F12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH%2Fp2p-circuit%2Fp2p%2F12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	basichost	basic/basic_host.go:777	host 12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd dialing 12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv
TIMESTAMP TIMESTAMP	DEBUG	swarm2	swarm/swarm_dial.go:237	dialing peer	{"from": "12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd", "to": "12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv"}
TIMESTAMP
TIMESTAMP done!
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	swarm2	swarm/limiter.go:193	[limiter] adding a dial job through limiter: /ip4/127.0.0.1/tcp/14111/ws/p2p/12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH/p2p-circuit
TIMESTAMP TIMESTAMP	DEBUG	swarm2	swarm/limiter.go:167	[limiter] executing dial; peer: 12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv; addr: /ip4/127.0.0.1/tcp/14111/ws/p2p/12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH/p2p-circuit; FD consuming: 0; waiting: 0
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	swarm2	swarm/swarm_dial.go:381	12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd swarm dialing 12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv /ip4/127.0.0.1/tcp/14111/ws/p2p/12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH/p2p-circuit
TIMESTAMP TIMESTAMP	DEBUG	p2p-circuit	client/dial.go:120	dialing peer 12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv through relay 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH
TIMESTAMP TIMESTAMP	DEBUG	swarm2	swarm/swarm.go:336	[12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd] opening stream to peer [12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH]
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	basichost	basic/basic_host.go:409	protocol negotiation took 24.8µs
TIMESTAMP TIMESTAMP	DEBUG	p2p-circuit	client/handlers.go:93	new relay/v1 stream from: 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH
TIMESTAMP TIMESTAMP	DEBUG	p2p-circuit	client/handlers.go:160	incoming relay connection from: 12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd
TIMESTAMP TIMESTAMP	DEBUG	p2p-circuit	client/listen.go:30	accepted relay connection from 12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd through /ip4/127.0.0.1/tcp/14111/ws/p2p/12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH/p2p-circuit
TIMESTAMP TIMESTAMP	DEBUG	upgrader	upgrader/listener.go:109	listener <stream.Listener /p2p-circuit> got connection: /ip4/127.0.0.1/tcp/47570/ws <---> /ip4/127.0.0.1/tcp/14111/ws/p2p/12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH/p2p-circuit
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	upgrader	upgrader/listener.go:133	listener <stream.Listener /p2p-circuit> accepted connection: <stream.Conn /ip4/127.0.0.1/tcp/47570/ws (12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv) <-> /ip4/127.0.0.1/tcp/14111/ws/p2p/12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH/p2p-circuit (12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd)>
TIMESTAMP TIMESTAMP	DEBUG	swarm2	swarm/swarm_listen.go:130	swarm listener accepted connection: /ip4/127.0.0.1/tcp/47570/ws <-> /ip4/127.0.0.1/tcp/14111/ws/p2p/12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH/p2p-circuit
TIMESTAMP TIMESTAMP	DEBUG	net/identify	identify/id.go:440	/ipfs/id/1.0.0 received message from 12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd /ip4/127.0.0.1/tcp/14111/ws/p2p/12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH/p2p-circuit
TIMESTAMP TIMESTAMP	DEBUG	net/identify	identify/id.go:636	12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv received listen addrs for 12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd: [/ip4/127.0.0.1/tcp/46651/ws]
TIMESTAMP TIMESTAMP	DEBUG	basichost	basic/basic_host.go:409	protocol negotiation took 13.1µs
TIMESTAMP TIMESTAMP	DEBUG	net/identify	identify/id.go:408	/ipfs/id/1.0.0 sent message to 12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd /ip4/127.0.0.1/tcp/14111/ws/p2p/12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH/p2p-circuit
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	swarm2	swarm/limiter.go:100	[limiter] freeing peer token; peer 12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv; addr: /ip4/127.0.0.1/tcp/14111/ws/p2p/12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH/p2p-circuit; active for peer: 1; waiting on peer limit: 0
TIMESTAMP TIMESTAMP	DEBUG	swarm2	swarm/limiter.go:201	[limiter] clearing all peer dials: 12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv
TIMESTAMP TIMESTAMP	DEBUG	basichost	basic/basic_host.go:409	protocol negotiation took 13.9µs
TIMESTAMP TIMESTAMP	DEBUG	net/identify	identify/id.go:408	/ipfs/id/1.0.0 sent message to 12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv /ip4/127.0.0.1/tcp/14111/ws/p2p/12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH/p2p-circuit
TIMESTAMP TIMESTAMP	DEBUG	net/identify	identify/id.go:440	/ipfs/id/1.0.0 received message from 12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv /ip4/127.0.0.1/tcp/14111/ws/p2p/12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH/p2p-circuit
TIMESTAMP TIMESTAMP	DEBUG	net/identify	identify/id.go:636	12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd received listen addrs for 12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv: [/ip4/127.0.0.1/tcp/44087/ws]
TIMESTAMP TIMESTAMP	DEBUG	basichost	basic/basic_host.go:794	host 12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd finished dialing 12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	cmds/http	http/handler.go:90	incoming API request: /swarm/peers
TIMESTAMP
TIMESTAMP nodeA has connections [
TIMESTAMP   '/ip4/127.0.0.1/tcp/14111/ws',
TIMESTAMP   '/ip4/127.0.0.1/tcp/14111/ws/p2p/12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH/p2p-circuit'
TIMESTAMP ]
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	cmds/http	http/handler.go:90	incoming API request: /swarm/peers
TIMESTAMP
TIMESTAMP nodeB has connections [
TIMESTAMP   '/ip4/127.0.0.1/tcp/14111/ws',
TIMESTAMP   '/ip4/127.0.0.1/tcp/14111/ws/p2p/12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH/p2p-circuit'
TIMESTAMP ]
TIMESTAMP         ✔ connect (1075ms)
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	cmds/http	http/handler.go:90	incoming API request: /add?stream-channels=true&progress=false
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	blockservice	[email protected]/blockservice.go:205	BlockService.BlockAdded 1 blocks
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	bitswap-server	server/server.go:481	Bitswap.ProvideWorker.Loop
TIMESTAMP TIMESTAMP	DEBUG	bitswap-server	server/server.go:467	Bitswap.ProvideWorker.Start	{"ID": 2, "cid": "QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL"}
TIMESTAMP TIMESTAMP	WARN	bitswap-server	server/server.go:474	routing: operation or key not supported
TIMESTAMP TIMESTAMP	DEBUG	bitswap-server	server/server.go:476	Bitswap.ProvideWorker.End	{"ID": 2, "cid": "QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL"}
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	blockservice	[email protected]/blockservice.go:157	BlockService.BlockAdded QmSZdq93SgC4BoFBSSS7n9UdSUzTkg3eZVA4RRjnXP2znW
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	bitswap-server	server/server.go:481	Bitswap.ProvideWorker.Loop
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	bitswap-server	server/server.go:467	Bitswap.ProvideWorker.Start	{"ID": 3, "cid": "QmSZdq93SgC4BoFBSSS7n9UdSUzTkg3eZVA4RRjnXP2znW"}
TIMESTAMP TIMESTAMP	WARN	bitswap-server	server/server.go:474	routing: operation or key not supported
TIMESTAMP TIMESTAMP	DEBUG	bitswap-server	server/server.go:476	Bitswap.ProvideWorker.End	{"ID": 3, "cid": "QmSZdq93SgC4BoFBSSS7n9UdSUzTkg3eZVA4RRjnXP2znW"}
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	INFO	provider.simple	simple/provider.go:111	announce - start - QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL
TIMESTAMP TIMESTAMP	WARN	provider.simple	simple/provider.go:113	Unable to provide entry: QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL, routing: operation or key not supported
TIMESTAMP TIMESTAMP	INFO	provider.simple	simple/provider.go:115	announce - end - QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	cmds/http	http/handler.go:90	incoming API request: /cat?arg=QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	blockservice	[email protected]/blockservice.go:247	Blockservice: Searching bitswap
TIMESTAMP TIMESTAMP	DEBUG	bitswap	getter/getter.go:86	Bitswap.GetBlockRequest.Start	{"cid": "QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL"}
TIMESTAMP TIMESTAMP	INFO	bs:sess	session/session.go:465	No peers - broadcasting	{"session": 1, "want-count": 1}
TIMESTAMP TIMESTAMP	DEBUG	bs:sess	session/session.go:472	broadcastWantHaves	{"session": 1, "cids": [{"/":"QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL"}]}
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	swarm2	swarm/swarm.go:336	[12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv] opening stream to peer [12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd]
TIMESTAMP TIMESTAMP	DEBUG	bitswap	messagequeue/messagequeue.go:663	sent message	{"type": "WANT_HAVE", "cid": "QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL", "local": "12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv", "to": "12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd"}
TIMESTAMP TIMESTAMP	DEBUG	swarm2	swarm/swarm.go:336	[12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv] opening stream to peer [12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd]
TIMESTAMP TIMESTAMP	DEBUG	swarm2	swarm/swarm.go:336	[12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv] opening stream to peer [12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH]
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	basichost	basic/basic_host.go:409	protocol negotiation took 13.8µs
TIMESTAMP TIMESTAMP	DEBUG	bitswap_network	network/ipfs_impl.go:433	bitswap net handleNewStream from 12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd
TIMESTAMP TIMESTAMP	DEBUG	bitswap-client	client/client.go:354	[recv] block; cid=QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL, peer=12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd
TIMESTAMP TIMESTAMP	DEBUG	bs:sess	session/session.go:221	Bitswap <- block	{"local": "12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv", "from": "12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd", "cid": "QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL", "session": 1}
TIMESTAMP TIMESTAMP	DEBUG	engine	decision/engine.go:818	Bitswap engine <- block	{"local": "12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv", "from": "12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd", "cid": "QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL", "size": 139}
TIMESTAMP TIMESTAMP	DEBUG	bitswap-client	client/client.go:332	Bitswap.GetBlockRequest.End	{"cid": "QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL"}
TIMESTAMP TIMESTAMP	DEBUG	bs:sprmgr	sessionpeermanager/sessionpeermanager.go:68	Bitswap: Added peer to session	{"session": 1, "peer": "12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd", "peerCount": 1}
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	basichost	basic/basic_host.go:409	protocol negotiation took 18.6µs
TIMESTAMP TIMESTAMP	DEBUG	basichost	basic/basic_host.go:409	protocol negotiation took 8.601µs
TIMESTAMP TIMESTAMP	DEBUG	bitswap_network	network/ipfs_impl.go:433	bitswap net handleNewStream from 12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv
TIMESTAMP TIMESTAMP	DEBUG	engine	decision/engine.go:623	Bitswap engine <- msg	{"local": "12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd", "from": "12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv", "entryCount": 1}
TIMESTAMP TIMESTAMP	DEBUG	engine	decision/engine.go:627	Bitswap engine <- want-have	{"local": "12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd", "from": "12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv", "cid": "QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL"}
TIMESTAMP TIMESTAMP	DEBUG	engine	decision/ledger.go:32	peer 12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv wants QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL
TIMESTAMP TIMESTAMP	DEBUG	engine	decision/engine.go:740	Bitswap engine: block found	{"local": "12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd", "from": "12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv", "cid": "QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL", "isWantBlock": true}
TIMESTAMP TIMESTAMP	DEBUG	engine	decision/engine.go:529	Bitswap process tasks	{"local": "12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd", "taskCount": 1}
TIMESTAMP TIMESTAMP	DEBUG	engine	decision/engine.go:582	Bitswap engine -> msg	{"local": "12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd", "to": "12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv", "blockCount": 1, "presenceCount": 0, "size": 139}
TIMESTAMP TIMESTAMP	DEBUG	swarm2	swarm/swarm.go:336	[12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd] opening stream to peer [12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv]
TIMESTAMP TIMESTAMP	DEBUG	bitswap-server	server/server.go:323	sent message	{"type": "BLOCK", "cid": "QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL", "local": "12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd", "to": "12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv"}
TIMESTAMP TIMESTAMP	DEBUG	bitswap-server	server/server.go:358	sent message	{"peer": "12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv"}
TIMESTAMP TIMESTAMP	DEBUG	bitswap-server	server/server.go:261	Bitswap.TaskWorker.Loop	{"ID": 7}
TIMESTAMP TIMESTAMP	DEBUG	ping	ping/ping.go:69	stream reset
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	INFO	bitswap	messagequeue/messagequeue.go:518	Could not open message sender to peer 12D3KooWRSeSvL97bKMydpx5Gb57FhmdZEXh9MeB7xgYh13ARDqH: protocol not supported
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	bitswap	messagequeue/messagequeue.go:654	sent message	{"type": "CANCEL_WANT_BLOCK", "cid": "QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL", "local": "12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv", "to": "12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd"}
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	bitswap_network	network/ipfs_impl.go:433	bitswap net handleNewStream from 12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv
TIMESTAMP TIMESTAMP	DEBUG	engine	decision/engine.go:623	Bitswap engine <- msg	{"local": "12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd", "from": "12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv", "entryCount": 1}
TIMESTAMP TIMESTAMP	DEBUG	engine	decision/engine.go:684	Bitswap engine <- cancel	{"local": "12D3KooWGhPd8TfHjFmSEgkzN6wNwSjNVCohjkyQfotnrqHSF4kd", "from": "12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv", "cid": "QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL"}
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	bs:sess	session/session.go:221	Bitswap <- block	{"local": "12D3KooWALTyfvtps9y3fQ9ocBVWLKjfd1Eqb6hAL9dDr53RFLLv", "from": "", "cid": "QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL", "session": 1}
TIMESTAMP
TIMESTAMP TIMESTAMP ipfsd-ctl:daemon:stderr TIMESTAMP	DEBUG	blockservice	[email protected]/blockservice.go:261	BlockService.BlockFetched QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL
TIMESTAMP TIMESTAMP	DEBUG	bitswap-server	server/server.go:481	Bitswap.ProvideWorker.Loop
TIMESTAMP TIMESTAMP	DEBUG	bitswap-server	server/server.go:467	Bitswap.ProvideWorker.Start	{"ID": 2, "cid": "QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL"}
TIMESTAMP TIMESTAMP	WARN	bitswap-server	server/server.go:474	routing: operation or key not supported
TIMESTAMP TIMESTAMP	DEBUG	bitswap-server	server/server.go:476	Bitswap.ProvideWorker.End	{"ID": 2, "cid": "QmSTUF5vAfAeYGDAufH6ZCvxdW47QygZyf3d3SGKGPowWL"}
TIMESTAMP
TIMESTAMP         ✔ send
TIMESTAMP
TIMESTAMP
TIMESTAMP   2 passing (4s)
TIMESTAMP

SgtPooki · 2022-09-09T20:06:47Z

The most interesting part seems to be the lines between 'REUSEPORT' and RelayV1 is running. In the successful run, there is a lot going on that is missing from the failed run. The First two things missing in the failed run is

Generating peer identity in scripts/relayd_v1.identity
rcmgr [email protected]/limit.go:75 initializing new limiter with config ...

What starts the "generating peer identity" log entry, and why is there no failure in the failed workflow?

What starts the "initializing new limiter with config" log entry, and why is there no failure in the failed workflow?

https://github.com/libp2p/go-libp2p-resource-manager/blob/v0.5.1/limit.go#L75
- This package is archived...

SgtPooki · 2022-09-09T23:17:28Z

Set ACTIONS_RUNNER_DEBUG=true & ACTIONS_RUNNER_DEBUG=true in this repo's secrets per https://docs.github.com/en/actions/monitoring-and-troubleshooting-workflows/enabling-debug-logging. re-running the node-test workflow: https://github.com/ipfs/interop/actions/runs/3024796231

achingbrain · 2022-09-10T11:18:38Z

This seems to be a combination of issues.

When the Generating peer identity message appears, the relay daemon cannot find an identity file at the passed path so generates a new peer id. If that message does not appear, it means there was a file at the path we pass to the daemon. For whatever reason the daemon fails to read the file and seems to hang with no further output.
The electron tests were failing to start the relay daemon at all with (node:1811) UnhandledPromiseRejectionWarning: Error: spawn scripts/libp2p-relay-daemon ENOENT - this might be because the daemon is downloaded as a post-install action - if there's a cache hit for current commit the cached directories are restored and ./scripts isn't in the list. The CI file is from unified ci so adding the scripts dir is not straightforward. This error only happens in feat!: upgrade to esm libp2p/ipfs #462 and not master because we're not running tests under electron-main in master, yet..

To fix 1 I've made relay daemon use a random temporary file for it's identity so it's guaranteed to create a new peer id on every run.

To fix 2 I've made the relay daemon setup script download the daemon binary on-demand, similar to how aegir downloads electron on-demand when it's first used.

I've applied these fixes to #462 which should hopefully start to look a bit more healthy now.

lidel · 2022-09-12T20:30:49Z

Thank you @achingbrain ❤️ I assume this PR is no longer useful – closing.
Let's continue in #462

achingbrain added 30 commits May 9, 2022 11:28

feat: upgrade to esm libp2p/ipfs

46b7554

Updates deps and adds types to tests. BREAKING CHANGE: needs ESM release of ipfs/libp2p

chore: upgrade ipfsd-ctl

4314291

fix: update files

99e5750

fix: deps

f28aaeb

chore: update test

a316b01

chore: run browser interop tests

b6191c7

chore: update files tests

72248b7

chore: refactor ipns pubsub tests to remove asserting on failure

2ec9f4e

chore: only run one dht test temporarily

347fb03

chore: run more tests

d328428

chore: run more tests

fd977dd

chore: longer delay

a14d853

chore: delay after creating network?

c8970fb

chore: revert

316abaf

chore: fewer tests

0487037

chore: wip

afe6577

chore: check routing tables before test

6c68ded

chore: run more

4177511

chore: check routing tables before tests

40a51b2

chore: shorten timeout

6954e3a

chore: wait for all nodes to be connected

2552897

chore: update test

104df78

fix: skip flaky test

59ec9f1

chore: fix ws filters

e4b86d3

chore: correct from type

9ef44ef

chore: update deps

fe1ee57

chore: update deps

0c01130

chore: update deps

b3bc8d2

chore: update project config

ca5e256

chore: update project config

71cdf22

lidel force-pushed the fix/circuit-go-rv1-go branch from 3f4f269 to 11dd674 Compare September 9, 2022 13:53

chore: test against lts and latest nodejs

29e3775

lidel force-pushed the fix/circuit-go-rv1-go branch from 11dd674 to 29e3775 Compare September 9, 2022 13:56

chore: try just go-rv1-go with logging

10dbcbb

achingbrain added 11 commits September 9, 2022 16:28

chore: try downgrade

65372a4

chore: revert

421846d

chore: cjs aegir

f3ceb4f

chore: remove coverage files

2a9669a

chore: import esm

608e229

chore: revert

6f8ce59

chore: relayd is not starting

b923efc

chore: linting

7f57135

chore: chmod executable

25c61d5

chore: run test

e78c0f1

chore: linting

06c094c

SgtPooki mentioned this pull request Sep 9, 2022

RFM Proposal: Data on usage of libp2p circuit relay v1 probe-lab/network-measurements#20

Open

chore: add GOLOG_LOG_LEVEL to test:node

041c5aa

achingbrain added 4 commits September 10, 2022 08:11

chore: use random identity file

13b7667

chore: timeout relayd startup

0038c7f

chore: actually time out

6295ef4

Merge remote-tracking branch 'origin/master' into fix/circuit-go-rv1-go

7034460

lidel closed this Sep 12, 2022

lidel deleted the fix/circuit-go-rv1-go branch September 18, 2022 13:33

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[WIP] fix: circuit-go-rv1-go #496

[WIP] fix: circuit-go-rv1-go #496

lidel commented Sep 8, 2022 •

edited

Loading

achingbrain commented Sep 9, 2022 •

edited

Loading

achingbrain commented Sep 9, 2022

SgtPooki commented Sep 9, 2022 •

edited

Loading

SgtPooki commented Sep 9, 2022 •

edited

Loading

SgtPooki commented Sep 9, 2022

achingbrain commented Sep 10, 2022 •

edited

Loading

lidel commented Sep 12, 2022

[WIP] fix: circuit-go-rv1-go #496

[WIP] fix: circuit-go-rv1-go #496

Conversation

lidel commented Sep 8, 2022 • edited Loading

achingbrain commented Sep 9, 2022 • edited Loading

achingbrain commented Sep 9, 2022

SgtPooki commented Sep 9, 2022 • edited Loading

SgtPooki commented Sep 9, 2022 • edited Loading

SgtPooki commented Sep 9, 2022

achingbrain commented Sep 10, 2022 • edited Loading

lidel commented Sep 12, 2022

lidel commented Sep 8, 2022 •

edited

Loading

achingbrain commented Sep 9, 2022 •

edited

Loading

SgtPooki commented Sep 9, 2022 •

edited

Loading

SgtPooki commented Sep 9, 2022 •

edited

Loading

achingbrain commented Sep 10, 2022 •

edited

Loading