ipfs / boxo

A set of reference libraries for building IPFS applications and implementations in Go.
https://github.com/ipfs/boxo#readme
Other
216 stars 98 forks source link

Bitswap.GetBlockRequest retrieval is extremely slow. #316

Closed jclab-joseph closed 1 year ago

jclab-joseph commented 1 year ago

Client has only one Bootstrap node connected to it. Interestingly, even if the PeerId is different, the CID requested from the same IP is quickly received. (Block is not stored locally, I used InMemoryDatastore.)

In the log below QmZe65rbJhncNTmaCXMq54FRG69hgJZodyorLKVmBCX2Sx is taking very long. However, the CID can be immediately obtained from the bootstrap node.

2023-05-26T18:19:39.285+0900    DEBUG  blockservice    blockservice/blockservice.go:247        BlockService: Searching
2023-05-26T18:19:39.288+0900    DEBUG  bitswap getter/getter.go:86     Bitswap.GetBlockRequest.Start   {"cid": "QmT8dh24LEW5JmQ4NdC2DXqRMErbqZyjBpk9GnvzpCCap8"}
2023-05-26T18:19:39.290+0900    INFO   bs:sess session/session.go:460  No peers - broadcasting {"session": 1, "want-count": 1}
2023-05-26T18:19:39.290+0900    DEBUG  bs:sess session/session.go:467  broadcastWantHaves      {"session": 1, "cids": [{"/":"QmT8dh24LEW5JmQ4NdC2DXqRMErbqZyjBpk9GnvzpCCap8"}]}
2023-05-26T18:19:39.307+0900    DEBUG  swarm2  swarm/swarm.go:365      [12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag] opening stream to peer [12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM]
2023-05-26T18:19:39.310+0900    DEBUG  swarm2  swarm/swarm.go:365      [12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag] opening stream to peer [12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM]
2023-05-26T18:19:39.311+0900    DEBUG  bitswap messagequeue/messagequeue.go:663        sent message    {"type": "WANT_HAVE", "cid": "QmT8dh24LEW5JmQ4NdC2DXqRMErbqZyjBpk9GnvzpCCap8", "local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "to": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM"}
2023-05-26T18:19:39.349+0900    DEBUG  basichost       basic/basic_host.go:432 negotiated: /ipfs/bitswap/1.2.0 (took 0s)
2023-05-26T18:19:39.349+0900    DEBUG  bitswap_network network/ipfs_impl.go:427        bitswap net handleNewStream from 12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM
2023-05-26T18:19:39.359+0900    DEBUG  bitswap-client  client/client.go:354    [recv] block; cid=QmT8dh24LEW5JmQ4NdC2DXqRMErbqZyjBpk9GnvzpCCap8, peer=12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM
2023-05-26T18:19:39.359+0900    DEBUG  bs:sess session/session.go:218  Bitswap <- block        {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "cid": "QmT8dh24LEW5JmQ4NdC2DXqRMErbqZyjBpk9GnvzpCCap8", "session": 1}
2023-05-26T18:19:39.359+0900    DEBUG  engine  decision/engine.go:854  Bitswap engine <- block {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "cid": "QmT8dh24LEW5JmQ4NdC2DXqRMErbqZyjBpk9GnvzpCCap8", "size": 112}
2023-05-26T18:19:39.359+0900    DEBUG  bs:sprmgr       sessionpeermanager/sessionpeermanager.go:68     Bitswap: Added peer to session    {"session": 1, "peer": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "peerCount": 1}
2023-05-26T18:19:39.359+0900    DEBUG  bitswap-client  client/client.go:332    Bitswap.GetBlockRequest.End     {"cid": "QmT8dh24LEW5JmQ4NdC2DXqRMErbqZyjBpk9GnvzpCCap8"}
2023-05-26T18:19:39.359+0900    DEBUG  bs:sess session/session.go:218  Bitswap <- block        {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "", "cid": "QmT8dh24LEW5JmQ4NdC2DXqRMErbqZyjBpk9GnvzpCCap8", "session": 1}
2023-05-26T18:19:39.359+0900    DEBUG  blockservice    blockservice/blockservice.go:261        BlockService.BlockFetched QmT8dh24LEW5JmQ4NdC2DXqRMErbqZyjBpk9GnvzpCCap8
2023-05-26T18:19:39.359+0900    DEBUG  bitswap-server  server/server.go:502    Bitswap.ProvideWorker.Loop
2023-05-26T18:19:39.359+0900    DEBUG  bitswap-server  server/server.go:488    Bitswap.ProvideWorker.Start     {"ID": 2, "cid": "QmT8dh24LEW5JmQ4NdC2DXqRMErbqZyjBpk9GnvzpCCap8"}
2023-05-26T18:19:39.359+0900    DEBUG  dht     go-libp2p-kad-dht@v0.22.0/routing.go:380        providing       {"cid": "QmT8dh24LEW5JmQ4NdC2DXqRMErbqZyjBpk9GnvzpCCap8", "mh": "bciqeonsqeho6xbaeywsispbcfvqkszoc6bkrv7vdogx2nlqgsf7y7wi"}
2023-05-26T18:19:39.359+0900    WARN   bitswap-server  server/server.go:495    failed to find any peer in table
2023-05-26T18:19:39.359+0900    DEBUG  bitswap-server  server/server.go:497    Bitswap.ProvideWorker.End       {"ID": 2, "cid": "QmT8dh24LEW5JmQ4NdC2DXqRMErbqZyjBpk9GnvzpCCap8"}
2023-05-26T18:19:39.359+0900    DEBUG  blockservice    blockservice/blockservice.go:247        BlockService: Searching
2023-05-26T18:19:39.359+0900    DEBUG  bitswap getter/getter.go:86     Bitswap.GetBlockRequest.Start   {"cid": "QmetrebQdwAnLyr6wvXVN5puL2smSuZjDzEoynqqakTQwY"}
2023-05-26T18:19:39.359+0900    INFO   bs:sess session/session.go:460  No peers - broadcasting {"session": 2, "want-count": 1}
2023-05-26T18:19:39.359+0900    DEBUG  bs:sess session/session.go:467  broadcastWantHaves      {"session": 2, "cids": [{"/":"QmetrebQdwAnLyr6wvXVN5puL2smSuZjDzEoynqqakTQwY"}]}
2023-05-26T18:19:39.369+0900    DEBUG  bitswap messagequeue/messagequeue.go:654        sent message    {"type": "CANCEL_WANT_BLOCK", "cid": "QmT8dh24LEW5JmQ4NdC2DXqRMErbqZyjBpk9GnvzpCCap8", "local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "to": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM"}
2023-05-26T18:19:39.369+0900    DEBUG  bitswap messagequeue/messagequeue.go:663        sent message    {"type": "WANT_HAVE", "cid": "QmetrebQdwAnLyr6wvXVN5puL2smSuZjDzEoynqqakTQwY", "local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "to": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM"}
2023-05-26T18:19:39.393+0900    DEBUG  basichost       basic/basic_host.go:432 negotiated: /ipfs/bitswap/1.2.0 (took 13.8536ms)
2023-05-26T18:19:39.395+0900    DEBUG  bitswap_network network/ipfs_impl.go:427        bitswap net handleNewStream from 12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM
2023-05-26T18:19:39.396+0900    DEBUG  bitswap-client  client/client.go:354    [recv] block; cid=QmetrebQdwAnLyr6wvXVN5puL2smSuZjDzEoynqqakTQwY, peer=12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM
2023-05-26T18:19:39.396+0900    DEBUG  bs:sess session/session.go:218  Bitswap <- block        {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "cid": "QmetrebQdwAnLyr6wvXVN5puL2smSuZjDzEoynqqakTQwY", "session": 2}
2023-05-26T18:19:39.396+0900    DEBUG  engine  decision/engine.go:854  Bitswap engine <- block {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "cid": "QmetrebQdwAnLyr6wvXVN5puL2smSuZjDzEoynqqakTQwY", "size": 104}
2023-05-26T18:19:39.397+0900    DEBUG  bitswap-client  client/client.go:332    Bitswap.GetBlockRequest.End     {"cid": "QmetrebQdwAnLyr6wvXVN5puL2smSuZjDzEoynqqakTQwY"}
2023-05-26T18:19:39.396+0900    DEBUG  bs:sprmgr       sessionpeermanager/sessionpeermanager.go:68     Bitswap: Added peer to session    {"session": 2, "peer": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "peerCount": 1}
2023-05-26T18:19:39.397+0900    DEBUG  bs:sess session/session.go:218  Bitswap <- block        {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "", "cid": "QmetrebQdwAnLyr6wvXVN5puL2smSuZjDzEoynqqakTQwY", "session": 2}
2023-05-26T18:19:39.398+0900    DEBUG  blockservice    blockservice/blockservice.go:261        BlockService.BlockFetched QmetrebQdwAnLyr6wvXVN5puL2smSuZjDzEoynqqakTQwY
2023-05-26T18:19:39.398+0900    DEBUG  bitswap messagequeue/messagequeue.go:654        sent message    {"type": "CANCEL_WANT_BLOCK", "cid": "QmetrebQdwAnLyr6wvXVN5puL2smSuZjDzEoynqqakTQwY", "local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "to": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM"}
2023-05-26T18:19:39.398+0900    DEBUG  bitswap-server  server/server.go:502    Bitswap.ProvideWorker.Loop
2023-05-26T18:19:39.398+0900    DEBUG  bitswap-server  server/server.go:488    Bitswap.ProvideWorker.Start     {"ID": 3, "cid": "QmetrebQdwAnLyr6wvXVN5puL2smSuZjDzEoynqqakTQwY"}
2023-05-26T18:19:39.398+0900    DEBUG  dht     go-libp2p-kad-dht@v0.22.0/routing.go:380        providing       {"cid": "QmetrebQdwAnLyr6wvXVN5puL2smSuZjDzEoynqqakTQwY", "mh": "bciqpl6ytuetnjt547n6nbbv2mu5aoriiqfab3ngr65h3t3gkifcm55y"}
2023-05-26T18:19:39.399+0900    WARN   bitswap-server  server/server.go:495    failed to find any peer in table
2023-05-26T18:19:39.399+0900    DEBUG  bitswap-server  server/server.go:497    Bitswap.ProvideWorker.End       {"ID": 3, "cid": "QmetrebQdwAnLyr6wvXVN5puL2smSuZjDzEoynqqakTQwY"}
2023-05-26T18:19:39.403+0900    DEBUG  bitswap getter/getter.go:86     Bitswap.GetBlockRequest.Start   {"cid": "QmTgYpt47GcQpXKxZDmaBUSaCKG83FdwLBysdCiimcvCsK"}
2023-05-26T18:19:39.403+0900    DEBUG  bitswap getter/getter.go:86     Bitswap.GetBlockRequest.Start   {"cid": "QmTNBxB9PuqhdZfDvRUgSr5y6UN4Lqk1UMWvHoUgCRnicq"}
2023-05-26T18:19:39.403+0900    INFO   bs:sess session/session.go:460  No peers - broadcasting {"session": 3, "want-count": 2}
2023-05-26T18:19:39.403+0900    DEBUG  bs:sess session/session.go:467  broadcastWantHaves      {"session": 3, "cids": [{"/":"QmTgYpt47GcQpXKxZDmaBUSaCKG83FdwLBysdCiimcvCsK"},{"/":"QmTNBxB9PuqhdZfDvRUgSr5y6UN4Lqk1UMWvHoUgCRnicq"}]}
2023-05-26T18:19:39.420+0900    DEBUG  bitswap messagequeue/messagequeue.go:663        sent message    {"type": "WANT_HAVE", "cid": "QmTgYpt47GcQpXKxZDmaBUSaCKG83FdwLBysdCiimcvCsK", "local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "to": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM"}
2023-05-26T18:19:39.420+0900    DEBUG  bitswap messagequeue/messagequeue.go:663        sent message    {"type": "WANT_HAVE", "cid": "QmTNBxB9PuqhdZfDvRUgSr5y6UN4Lqk1UMWvHoUgCRnicq", "local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "to": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM"}
2023-05-26T18:19:39.432+0900    DEBUG  basichost       basic/basic_host.go:432 negotiated: /ipfs/bitswap/1.2.0 (took 0s)
2023-05-26T18:19:39.432+0900    DEBUG  bitswap_network network/ipfs_impl.go:427        bitswap net handleNewStream from 12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM
2023-05-26T18:19:39.433+0900    DEBUG  bs:sess session/session.go:221  Bitswap <- HAVE {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "cid": "QmTgYpt47GcQpXKxZDmaBUSaCKG83FdwLBysdCiimcvCsK", "session": 3}
2023-05-26T18:19:39.433+0900    DEBUG  bs:sess session/session.go:221  Bitswap <- HAVE {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "cid": "QmTNBxB9PuqhdZfDvRUgSr5y6UN4Lqk1UMWvHoUgCRnicq", "session": 3}
2023-05-26T18:19:39.433+0900    DEBUG  bs:sprmgr       sessionpeermanager/sessionpeermanager.go:68     Bitswap: Added peer to session    {"session": 3, "peer": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "peerCount": 1}
2023-05-26T18:19:39.450+0900    DEBUG  bitswap messagequeue/messagequeue.go:670        sent message    {"type": "WANT_BLOCK", "cid": "QmTNBxB9PuqhdZfDvRUgSr5y6UN4Lqk1UMWvHoUgCRnicq", "local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "to": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM"}
2023-05-26T18:19:39.453+0900    DEBUG  bitswap messagequeue/messagequeue.go:670        sent message    {"type": "WANT_BLOCK", "cid": "QmTgYpt47GcQpXKxZDmaBUSaCKG83FdwLBysdCiimcvCsK", "local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "to": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM"}
2023-05-26T18:19:39.500+0900    INFO   bitswap messagequeue/messagequeue.go:217        Bitswap: timeout waiting for blocks       {"cids": [{"/":"QmTNBxB9PuqhdZfDvRUgSr5y6UN4Lqk1UMWvHoUgCRnicq"},{"/":"QmTgYpt47GcQpXKxZDmaBUSaCKG83FdwLBysdCiimcvCsK"}], "peer": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM"}
2023-05-26T18:19:39.500+0900    DEBUG  basichost       basic/basic_host.go:432 negotiated: /ipfs/bitswap/1.2.0 (took 14.4271ms)
2023-05-26T18:19:39.500+0900    DEBUG  bs:sess session/session.go:224  Bitswap <- DONT_HAVE    {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "cid": "QmTNBxB9PuqhdZfDvRUgSr5y6UN4Lqk1UMWvHoUgCRnicq", "session": 3}
2023-05-26T18:19:39.502+0900    DEBUG  bs:sess session/session.go:224  Bitswap <- DONT_HAVE    {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "cid": "QmTgYpt47GcQpXKxZDmaBUSaCKG83FdwLBysdCiimcvCsK", "session": 3}
2023-05-26T18:19:39.530+0900    DEBUG  basichost       basic/basic_host.go:432 negotiated: /ipfs/bitswap/1.2.0 (took 62.1µs)
2023-05-26T18:19:39.536+0900    DEBUG  bitswap_network network/ipfs_impl.go:427        bitswap net handleNewStream from 12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM
2023-05-26T18:19:39.536+0900    DEBUG  bitswap-client  client/client.go:354    [recv] block; cid=QmTgYpt47GcQpXKxZDmaBUSaCKG83FdwLBysdCiimcvCsK, peer=12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM
2023-05-26T18:19:39.537+0900    DEBUG  bs:sess session/session.go:218  Bitswap <- block        {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "cid": "QmTgYpt47GcQpXKxZDmaBUSaCKG83FdwLBysdCiimcvCsK", "session": 3}
2023-05-26T18:19:39.537+0900    DEBUG  engine  decision/engine.go:854  Bitswap engine <- block {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "cid": "QmTgYpt47GcQpXKxZDmaBUSaCKG83FdwLBysdCiimcvCsK", "size": 78603}
2023-05-26T18:19:39.538+0900    DEBUG  bitswap-client  client/client.go:332    Bitswap.GetBlockRequest.End     {"cid": "QmTgYpt47GcQpXKxZDmaBUSaCKG83FdwLBysdCiimcvCsK"}
2023-05-26T18:19:39.538+0900    DEBUG  bs:sess session/session.go:218  Bitswap <- block        {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "", "cid": "QmTgYpt47GcQpXKxZDmaBUSaCKG83FdwLBysdCiimcvCsK", "session": 3}
2023-05-26T18:19:39.538+0900    DEBUG  bitswap-server  server/server.go:502    Bitswap.ProvideWorker.Loop
2023-05-26T18:19:39.538+0900    DEBUG  bitswap messagequeue/messagequeue.go:654        sent message    {"type": "CANCEL_WANT_BLOCK", "cid": "QmTgYpt47GcQpXKxZDmaBUSaCKG83FdwLBysdCiimcvCsK", "local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "to": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM"}
2023-05-26T18:19:39.538+0900    DEBUG  bitswap-server  server/server.go:488    Bitswap.ProvideWorker.Start     {"ID": 4, "cid": "QmTgYpt47GcQpXKxZDmaBUSaCKG83FdwLBysdCiimcvCsK"}
2023-05-26T18:19:39.539+0900    DEBUG  dht     go-libp2p-kad-dht@v0.22.0/routing.go:380        providing       {"cid": "QmTgYpt47GcQpXKxZDmaBUSaCKG83FdwLBysdCiimcvCsK", "mh": "bciqe6y3gbzz2wdwgwklfexe4r4ot4h6ifvs2szxbh7ejr7ielcxjbkq"}
2023-05-26T18:19:39.539+0900    WARN   bitswap-server  server/server.go:495    failed to find any peer in table
2023-05-26T18:19:39.539+0900    DEBUG  bitswap-server  server/server.go:497    Bitswap.ProvideWorker.End       {"ID": 4, "cid": "QmTgYpt47GcQpXKxZDmaBUSaCKG83FdwLBysdCiimcvCsK"}
2023-05-26T18:19:39.540+0900    DEBUG  bitswap_network network/ipfs_impl.go:427        bitswap net handleNewStream from 12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM
2023-05-26T18:19:39.541+0900    DEBUG  bitswap-client  client/client.go:354    [recv] block; cid=QmTNBxB9PuqhdZfDvRUgSr5y6UN4Lqk1UMWvHoUgCRnicq, peer=12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM
2023-05-26T18:19:39.541+0900    DEBUG  bs:sess session/session.go:218  Bitswap <- block        {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "cid": "QmTNBxB9PuqhdZfDvRUgSr5y6UN4Lqk1UMWvHoUgCRnicq", "session": 3}
2023-05-26T18:19:39.541+0900    DEBUG  engine  decision/engine.go:854  Bitswap engine <- block {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "cid": "QmTNBxB9PuqhdZfDvRUgSr5y6UN4Lqk1UMWvHoUgCRnicq", "size": 262158}
2023-05-26T18:19:39.541+0900    DEBUG  bitswap-client  client/client.go:332    Bitswap.GetBlockRequest.End     {"cid": "QmTNBxB9PuqhdZfDvRUgSr5y6UN4Lqk1UMWvHoUgCRnicq"}
2023-05-26T18:19:39.541+0900    DEBUG  bs:sess session/session.go:218  Bitswap <- block        {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "", "cid": "QmTNBxB9PuqhdZfDvRUgSr5y6UN4Lqk1UMWvHoUgCRnicq", "session": 3}
2023-05-26T18:19:39.542+0900    DEBUG  bitswap-server  server/server.go:502    Bitswap.ProvideWorker.Loop
2023-05-26T18:19:39.542+0900    DEBUG  bitswap-server  server/server.go:488    Bitswap.ProvideWorker.Start     {"ID": 5, "cid": "QmTNBxB9PuqhdZfDvRUgSr5y6UN4Lqk1UMWvHoUgCRnicq"}
2023-05-26T18:19:39.543+0900    DEBUG  bitswap messagequeue/messagequeue.go:654        sent message    {"type": "CANCEL_WANT_BLOCK", "cid": "QmTNBxB9PuqhdZfDvRUgSr5y6UN4Lqk1UMWvHoUgCRnicq", "local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "to": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM"}
2023-05-26T18:19:39.543+0900    DEBUG  dht     go-libp2p-kad-dht@v0.22.0/routing.go:380        providing       {"cid": "QmTNBxB9PuqhdZfDvRUgSr5y6UN4Lqk1UMWvHoUgCRnicq", "mh": "bciqevl2xnzpjammlxe2wphzdj25s4dvw33lxbq3trrqw6rhahogrzcq"}
2023-05-26T18:19:39.543+0900    WARN   bitswap-server  server/server.go:495    failed to find any peer in table
2023-05-26T18:19:39.543+0900    DEBUG  bitswap-server  server/server.go:497    Bitswap.ProvideWorker.End       {"ID": 5, "cid": "QmTNBxB9PuqhdZfDvRUgSr5y6UN4Lqk1UMWvHoUgCRnicq"}
2023-05-26T18:19:39.751+0900    DEBUG  blockservice    blockservice/blockservice.go:247        BlockService: Searching
2023-05-26T18:19:39.751+0900    DEBUG  bitswap getter/getter.go:86     Bitswap.GetBlockRequest.Start   {"cid": "QmRHfqbAxoP9RZCBHhNSMsVP5mWfDBQFC77tYV4YgowYBX"}
2023-05-26T18:19:39.761+0900    INFO   bs:sess session/session.go:460  No peers - broadcasting {"session": 4, "want-count": 1}
2023-05-26T18:19:39.763+0900    DEBUG  bs:sess session/session.go:467  broadcastWantHaves      {"session": 4, "cids": [{"/":"QmRHfqbAxoP9RZCBHhNSMsVP5mWfDBQFC77tYV4YgowYBX"}]}
2023-05-26T18:19:39.780+0900    DEBUG  bitswap messagequeue/messagequeue.go:663        sent message    {"type": "WANT_HAVE", "cid": "QmRHfqbAxoP9RZCBHhNSMsVP5mWfDBQFC77tYV4YgowYBX", "local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "to": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM"}
2023-05-26T18:19:39.802+0900    DEBUG  basichost       basic/basic_host.go:432 negotiated: /ipfs/bitswap/1.2.0 (took 3.1465ms)
2023-05-26T18:19:39.803+0900    DEBUG  bitswap_network network/ipfs_impl.go:427        bitswap net handleNewStream from 12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM
2023-05-26T18:19:39.803+0900    DEBUG  bitswap-client  client/client.go:354    [recv] block; cid=QmRHfqbAxoP9RZCBHhNSMsVP5mWfDBQFC77tYV4YgowYBX, peer=12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM
2023-05-26T18:19:39.803+0900    DEBUG  bs:sess session/session.go:218  Bitswap <- block        {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "cid": "QmRHfqbAxoP9RZCBHhNSMsVP5mWfDBQFC77tYV4YgowYBX", "session": 4}
2023-05-26T18:19:39.803+0900    DEBUG  engine  decision/engine.go:854  Bitswap engine <- block {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "cid": "QmRHfqbAxoP9RZCBHhNSMsVP5mWfDBQFC77tYV4YgowYBX", "size": 110}
2023-05-26T18:19:39.803+0900    DEBUG  bs:sprmgr       sessionpeermanager/sessionpeermanager.go:68     Bitswap: Added peer to session    {"session": 4, "peer": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "peerCount": 1}
2023-05-26T18:19:39.804+0900    DEBUG  bitswap-client  client/client.go:332    Bitswap.GetBlockRequest.End     {"cid": "QmRHfqbAxoP9RZCBHhNSMsVP5mWfDBQFC77tYV4YgowYBX"}
2023-05-26T18:19:39.804+0900    DEBUG  bs:sess session/session.go:218  Bitswap <- block        {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "", "cid": "QmRHfqbAxoP9RZCBHhNSMsVP5mWfDBQFC77tYV4YgowYBX", "session": 4}
2023-05-26T18:19:39.805+0900    DEBUG  bitswap messagequeue/messagequeue.go:654        sent message    {"type": "CANCEL_WANT_BLOCK", "cid": "QmRHfqbAxoP9RZCBHhNSMsVP5mWfDBQFC77tYV4YgowYBX", "local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "to": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM"}
2023-05-26T18:19:39.805+0900    DEBUG  bitswap-server  server/server.go:488    Bitswap.ProvideWorker.Start     {"ID": 6, "cid": "QmRHfqbAxoP9RZCBHhNSMsVP5mWfDBQFC77tYV4YgowYBX"}
2023-05-26T18:19:39.805+0900    DEBUG  blockservice    blockservice/blockservice.go:261        BlockService.BlockFetched QmRHfqbAxoP9RZCBHhNSMsVP5mWfDBQFC77tYV4YgowYBX
2023-05-26T18:19:39.805+0900    DEBUG  bitswap-server  server/server.go:502    Bitswap.ProvideWorker.Loop
2023-05-26T18:19:39.805+0900    DEBUG  dht     go-libp2p-kad-dht@v0.22.0/routing.go:380        providing       {"cid": "QmRHfqbAxoP9RZCBHhNSMsVP5mWfDBQFC77tYV4YgowYBX", "mh": "bciqcxt4yjysveokmhrvdy5bb4pgb6uaajy4y5g5dbqltlsgnwdhydlq"}
2023-05-26T18:19:39.805+0900    DEBUG  blockservice    blockservice/blockservice.go:247        BlockService: Searching
2023-05-26T18:19:39.806+0900    WARN   bitswap-server  server/server.go:495    failed to find any peer in table
2023-05-26T18:19:39.806+0900    DEBUG  bitswap getter/getter.go:86     Bitswap.GetBlockRequest.Start   {"cid": "QmQiYvZhv1JR1xmQc3D9948bG3u6JM9or7mfxvAZP8TT1o"}
2023-05-26T18:19:39.806+0900    DEBUG  bitswap-server  server/server.go:497    Bitswap.ProvideWorker.End       {"ID": 6, "cid": "QmRHfqbAxoP9RZCBHhNSMsVP5mWfDBQFC77tYV4YgowYBX"}
2023-05-26T18:19:39.806+0900    INFO   bs:sess session/session.go:460  No peers - broadcasting {"session": 5, "want-count": 1}
2023-05-26T18:19:39.806+0900    DEBUG  bs:sess session/session.go:467  broadcastWantHaves      {"session": 5, "cids": [{"/":"QmQiYvZhv1JR1xmQc3D9948bG3u6JM9or7mfxvAZP8TT1o"}]}
2023-05-26T18:19:39.824+0900    DEBUG  bitswap messagequeue/messagequeue.go:663        sent message    {"type": "WANT_HAVE", "cid": "QmQiYvZhv1JR1xmQc3D9948bG3u6JM9or7mfxvAZP8TT1o", "local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "to": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM"}
2023-05-26T18:19:39.834+0900    DEBUG  basichost       basic/basic_host.go:432 negotiated: /ipfs/bitswap/1.2.0 (took 5.297ms)
2023-05-26T18:19:39.834+0900    DEBUG  bitswap_network network/ipfs_impl.go:427        bitswap net handleNewStream from 12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM
2023-05-26T18:19:39.835+0900    DEBUG  bs:sess session/session.go:221  Bitswap <- HAVE {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "cid": "QmQiYvZhv1JR1xmQc3D9948bG3u6JM9or7mfxvAZP8TT1o", "session": 5}
2023-05-26T18:19:39.835+0900    DEBUG  bs:sprmgr       sessionpeermanager/sessionpeermanager.go:68     Bitswap: Added peer to session    {"session": 5, "peer": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "peerCount": 1}
2023-05-26T18:19:39.852+0900    DEBUG  bitswap messagequeue/messagequeue.go:670        sent message    {"type": "WANT_BLOCK", "cid": "QmQiYvZhv1JR1xmQc3D9948bG3u6JM9or7mfxvAZP8TT1o", "local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "to": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM"}
2023-05-26T18:19:39.868+0900    DEBUG  basichost       basic/basic_host.go:432 negotiated: /ipfs/bitswap/1.2.0 (took 12.0115ms)
2023-05-26T18:19:39.869+0900    DEBUG  bitswap_network network/ipfs_impl.go:427        bitswap net handleNewStream from 12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM
2023-05-26T18:19:39.869+0900    DEBUG  bitswap-client  client/client.go:354    [recv] block; cid=QmQiYvZhv1JR1xmQc3D9948bG3u6JM9or7mfxvAZP8TT1o, peer=12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM
2023-05-26T18:19:39.869+0900    DEBUG  bs:sess session/session.go:218  Bitswap <- block        {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "cid": "QmQiYvZhv1JR1xmQc3D9948bG3u6JM9or7mfxvAZP8TT1o", "session": 5}
2023-05-26T18:19:39.869+0900    DEBUG  engine  decision/engine.go:854  Bitswap engine <- block {"local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "from": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM", "cid": "QmQiYvZhv1JR1xmQc3D9948bG3u6JM9or7mfxvAZP8TT1o", "size": 4888}
2023-05-26T18:19:39.870+0900    DEBUG  bitswap-client  client/client.go:332    Bitswap.GetBlockRequest.End     {"cid": "QmQiYvZhv1JR1xmQc3D9948bG3u6JM9or7mfxvAZP8TT1o"}
2023-05-26T18:19:39.870+0900    DEBUG  blockservice    blockservice/blockservice.go:261        BlockService.BlockFetched QmQiYvZhv1JR1xmQc3D9948bG3u6JM9or7mfxvAZP8TT1o
2023-05-26T18:19:39.870+0900    DEBUG  bitswap-server  server/server.go:502    Bitswap.ProvideWorker.Loop
2023-05-26T18:19:39.870+0900    DEBUG  bitswap-server  server/server.go:488    Bitswap.ProvideWorker.Start     {"ID": 7, "cid": "QmQiYvZhv1JR1xmQc3D9948bG3u6JM9or7mfxvAZP8TT1o"}
2023-05-26T18:19:39.871+0900    DEBUG  bitswap messagequeue/messagequeue.go:654        sent message    {"type": "CANCEL_WANT_BLOCK", "cid": "QmQiYvZhv1JR1xmQc3D9948bG3u6JM9or7mfxvAZP8TT1o", "local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "to": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM"}
2023-05-26T18:19:39.871+0900    DEBUG  dht     go-libp2p-kad-dht@v0.22.0/routing.go:380        providing       {"cid": "QmQiYvZhv1JR1xmQc3D9948bG3u6JM9or7mfxvAZP8TT1o", "mh": "bciqcgu44hsjoc2fwblz3zanln52pbaowcmvo2r27pzy5h7l3c25r5fq"}
2023-05-26T18:19:39.871+0900    WARN   bitswap-server  server/server.go:495    failed to find any peer in table
2023-05-26T18:19:39.871+0900    DEBUG  bitswap-server  server/server.go:497    Bitswap.ProvideWorker.End       {"ID": 7, "cid": "QmQiYvZhv1JR1xmQc3D9948bG3u6JM9or7mfxvAZP8TT1o"}
2023-05-26T18:19:39.995+0900    DEBUG  blockservice    blockservice/blockservice.go:247        BlockService: Searching
2023-05-26T18:19:40.004+0900    DEBUG  bitswap getter/getter.go:86     Bitswap.GetBlockRequest.Start   {"cid": "QmZe65rbJhncNTmaCXMq54FRG69hgJZodyorLKVmBCX2Sx"}
2023-05-26T18:19:40.004+0900    INFO   bs:sess session/session.go:460  No peers - broadcasting {"session": 6, "want-count": 1}
2023-05-26T18:19:40.004+0900    DEBUG  bs:sess session/session.go:467  broadcastWantHaves      {"session": 6, "cids": [{"/":"QmZe65rbJhncNTmaCXMq54FRG69hgJZodyorLKVmBCX2Sx"}]}
2023-05-26T18:19:40.014+0900    DEBUG  bitswap messagequeue/messagequeue.go:663        sent message    {"type": "WANT_HAVE", "cid": "QmZe65rbJhncNTmaCXMq54FRG69hgJZodyorLKVmBCX2Sx", "local": "12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag", "to": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM"}
2023-05-26T18:19:41.005+0900    DEBUG  bs:sess session/session.go:467  broadcastWantHaves      {"session": 6, "cids": [{"/":"QmZe65rbJhncNTmaCXMq54FRG69hgJZodyorLKVmBCX2Sx"}]}
2023-05-26T18:19:41.005+0900    DEBUG  bs:sess session/session.go:361  FindMorePeers   {"session": 6, "cid": "QmZe65rbJhncNTmaCXMq54FRG69hgJZodyorLKVmBCX2Sx", "pending": 1}
2023-05-26T18:19:41.008+0900    DEBUG  bitswap providerquerymanager/providerquerymanager.go:329        New Provider Query on cid: QmZe65rbJhncNTmaCXMq54FRG69hgJZodyorLKVmBCX2Sx
2023-05-26T18:19:41.008+0900    DEBUG  bitswap providerquerymanager/providerquerymanager.go:234        Beginning Find Provider Request for cid: QmZe65rbJhncNTmaCXMq54FRG69hgJZodyorLKVmBCX2Sx
2023-05-26T18:19:41.008+0900    DEBUG  dht     go-libp2p-kad-dht@v0.22.0/routing.go:479        finding providers
        {"cid": "QmZe65rbJhncNTmaCXMq54FRG69hgJZodyorLKVmBCX2Sx", "mh": "bciqkp2a7dta6tebtjlpnmjeb7zozbo5q6o2kjdpnkuszxlrv443jrji"}
2023-05-26T18:19:41.009+0900    DEBUG  dht     go-libp2p-kad-dht@v0.22.0/routing.go:479        finding providers
        {"cid": "QmZe65rbJhncNTmaCXMq54FRG69hgJZodyorLKVmBCX2Sx", "mh": "bciqkp2a7dta6tebtjlpnmjeb7zozbo5q6o2kjdpnkuszxlrv443jrji"}
2023-05-26T18:19:41.009+0900    DEBUG  bitswap providerquerymanager/providerquerymanager.go:329        Finished Provider Query on cid: QmZe65rbJhncNTmaCXMq54FRG69hgJZodyorLKVmBCX2Sx
2023-05-26T18:19:42.016+0900    DEBUG  bs:sess session/session.go:467  broadcastWantHaves      {"session": 6, "cids": [{"/":"QmZe65rbJhncNTmaCXMq54FRG69hgJZodyorLKVmBCX2Sx"}]}
2023-05-26T18:19:43.399+0900    DEBUG  basichost       basic/basic_host.go:335 failed to fetch local IPv6 address        {"error": "Element not found."}
2023-05-26T18:19:44.033+0900    DEBUG  bs:sess session/session.go:467  broadcastWantHaves      {"session": 6, "cids": [{"/":"QmZe65rbJhncNTmaCXMq54FRG69hgJZodyorLKVmBCX2Sx"}]}
2023-05-26T18:19:48.337+0900    INFO   basichost       basic/natmgr.go:93      DiscoverNAT error:no NAT found
2023-05-26T18:19:48.888+0900    DEBUG  basichost       basic/basic_host.go:335 failed to fetch local IPv6 address        {"error": "Element not found."}
2023-05-26T18:19:51.902+0900    DEBUG  bs:sess session/session.go:467  broadcastWantHaves      {"session": 6, "cids": [{"/":"QmZe65rbJhncNTmaCXMq54FRG69hgJZodyorLKVmBCX2Sx"}]}
2023-05-26T18:19:53.402+0900    DEBUG  basichost       basic/basic_host.go:335 failed to fetch local IPv6 address        {"error": "Element not found."}
2023-05-26T18:19:55.904+0900    DEBUG  bs:sess session/session.go:467  broadcastWantHaves      {"session": 6, "cids": [{"/":"QmZe65rbJhncNTmaCXMq54FRG69hgJZodyorLKVmBCX2Sx"}]}
2023-05-26T18:19:58.401+0900    DEBUG  basichost       basic/basic_host.go:335 failed to fetch local IPv6 address        {"error": "Element not found."}
2023-05-26T18:20:00.919+0900    DEBUG  bs:sess session/session.go:467  broadcastWantHaves      {"session": 6, "cids": [{"/":"QmZe65rbJhncNTmaCXMq54FRG69hgJZodyorLKVmBCX2Sx"}]}
2023-05-26T18:20:03.394+0900    DEBUG  basichost       basic/basic_host.go:335 failed to fetch local IPv6 address        {"error": "Element not found."}
2023-05-26T18:20:06.931+0900    DEBUG  bs:sess session/session.go:467  broadcastWantHaves      {"session": 6, "cids": [{"/":"QmZe65rbJhncNTmaCXMq54FRG69hgJZodyorLKVmBCX2Sx"}]}
2023-05-26T18:20:08.390+0900    DEBUG  basichost       basic/basic_host.go:335 failed to fetch local IPv6 address        {"error": "Element not found."}
2023-05-26T18:20:13.390+0900    DEBUG  basichost       basic/basic_host.go:335 failed to fetch local IPv6 address        {"error": "Element not found."}
2023-05-26T18:20:13.937+0900    DEBUG  bs:sess session/session.go:467  broadcastWantHaves      {"session": 6, "cids": [{"/":"QmZe65rbJhncNTmaCXMq54FRG69hgJZodyorLKVmBCX2Sx"}]}
2023-05-26T18:20:18.399+0900    DEBUG  basichost       basic/basic_host.go:335 failed to fetch local IPv6 address        {"error": "Element not found."}
2023-05-26T18:20:21.947+0900    DEBUG  bs:sess session/session.go:467  broadcastWantHaves      {"session": 6, "cids": [{"/":"QmZe65rbJhncNTmaCXMq54FRG69hgJZodyorLKVmBCX2Sx"}]}
2023-05-26T18:20:23.393+0900    DEBUG  basichost       basic/basic_host.go:335 failed to fetch local IPv6 address        {"error": "Element not found."}
2023-05-26T18:20:28.394+0900    DEBUG  basichost       basic/basic_host.go:335 failed to fetch local IPv6 address        {"error": "Element not found."}
2023-05-26T18:20:30.962+0900    DEBUG  bs:sess session/session.go:467  broadcastWantHaves      {"session": 6, "cids": [{"/":"QmZe65rbJhncNTmaCXMq54FRG69hgJZodyorLKVmBCX2Sx"}]}
2023-05-26T18:20:33.398+0900    DEBUG  basichost       basic/basic_host.go:335 failed to fetch local IPv6 address        {"error": "Element not found."}
2023-05-26T18:20:38.403+0900    DEBUG  basichost       basic/basic_host.go:335 failed to fetch local IPv6 address        {"error": "Element not found."}
2023-05-26T18:20:38.426+0900    DEBUG  dht     go-libp2p-kad-dht@v0.22.0/routing.go:380        providing       {"cid": "bafkreichgzicdxplqqcmljejhqrc2yfjmxbpavi272rxdl5gvydjc74p3e", "mh": "bciqeonsqeho6xbaeywsispbcfvqkszoc6bkrv7vdogx2nlqgsf7y7wi"}
2023-05-26T18:20:38.426+0900    DEBUG  reprovider.simple       simple/reprovide.go:136 Failed to provide key: failed to find any peer in table
2023-05-26T18:20:38.982+0900    DEBUG  dht     go-libp2p-kad-dht@v0.22.0/routing.go:380        providing       {"cid": "bafkreichgzicdxplqqcmljejhqrc2yfjmxbpavi272rxdl5gvydjc74p3e", "mh": "bciqeonsqeho6xbaeywsispbcfvqkszoc6bkrv7vdogx2nlqgsf7y7wi"}
2023-05-26T18:20:38.983+0900    DEBUG  reprovider.simple       simple/reprovide.go:136 Failed to provide key: failed to find any peer in table
2023/05/26 18:20:39 context deadline exceeded

Bootstrap node's swarm streams:

# ipfs swarm peers --streams
/ip4/172.30.42.175/tcp/4001/p2p/12D3KooWHfPzNawb4yt5KmYTLu4nDDgtLvp3eXiUsF9dx2cPNBv8 # Other Node
  /ipfs/bitswap/1.2.0
  /ipfs/bitswap/1.2.0
  /ipfs/lan/kad/1.0.0

/ip4/172.30.42.185/tcp/37548/wss/p2p/12D3KooWLLiPVfTUiaFESgAnLmCpv4cu5Fj3mu8PZXLbqPQy3sag # Client Node
  /ipfs/bitswap/1.2.0
  /ipfs/lan/kad/1.0.0

Similar Possible Issues: https://github.com/ipfs/kubo/issues/8346

Bootstrap Node: ipfs version 0.19.2 Client: github.com/ipfs/boxo v0.8.0

lidel commented 1 year ago
jclab-joseph commented 1 year ago

It is the same even if you use Level-DB.


package main

import (
    "context"
    "encoding/hex"
    "github.com/ipfs/go-cid"
    leveldb "github.com/ipfs/go-ds-leveldb"
    blockstore "github.com/ipfs/go-ipfs-blockstore"
    format "github.com/ipfs/go-ipld-format"
    "github.com/libp2p/go-libp2p/core/crypto"
    "github.com/libp2p/go-libp2p/core/peer"
    "github.com/multiformats/go-multiaddr"
    "log"
    "os"
    "path/filepath"
    "time"
)

func main() {
    ctx, cancel := context.WithCancel(context.Background())
    defer cancel()

    ds, err := leveldb.NewDatastore("./datastore/", nil)
    if err != nil {
        log.Fatalln(err)
    }

    priv, _, err := crypto.GenerateKeyPair(crypto.Ed25519, 0)
    if err != nil {
        panic(err)
    }

    listen, _ := multiaddr.NewMultiaddr("/ip4/0.0.0.0/tcp/12345")

    psk, _ := hex.DecodeString("...")
    h, dht, err := ipfslite.SetupLibp2p(
        ctx,
        priv,
        psk,
        []multiaddr.Multiaddr{listen},
        ds,
        nil,
        nil,
        ipfslite.Libp2pOptionsExtra...,
    )

    if err != nil {
        panic(err)
    }

    lite, err := ipfslite.New(ctx, ds, nil, h, dht, &ipfslite.Config{
        //UncachedBlockstore: false,
    })
    if err != nil {
        panic(err)
    }

    lite.Bootstrap([]peer.AddrInfo{
       // ...
    })
    println("bootstrap end")

    go func() {
        peerStore := h.Peerstore()
        for {
            peerIds := peerStore.Peers()
            for i, peerId := range peerIds {
                peerInfo := peerStore.PeerInfo(peerId)
                encoded, err := peerInfo.MarshalJSON()
                if err == nil {
                    log.Printf("PEER[%d]: %s: %s\n", i, peerId.String(), string(encoded))
                }
            }
            log.Printf("-----------")
            time.Sleep(time.Second * 1)
        }
    }()

        // It takes an long time on the next line.
    c, _ := cid.Decode("QmW6S34r12rr6DCSfVS24jCjx4zagtQvhFmsWS2FV32Gtm")
    node, err := lite.Get(ctx, c)
    if err != nil {
        log.Fatalln(err)
    }
}

I have discovered one thing. If you bootstrap with TCP Peer, it will be received normally and quickly. However, bootstrapping with Websocket Peer causes the same problem.

In more detail, the websocket bootstrap node is behind nginx-ingress. Therefore, the Advertise Address and the actual connection address are different.

jclab-joseph commented 1 year ago

This was my mistake. The cause was that the ipfs-cluster was configured incorrectly and the pin was not pinned.