Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

Bitswap.GetBlockRequest retrieval is extremely slow. #316

Closed
jclab-joseph opened this issue May 26, 2023 · 3 comments
Closed

Bitswap.GetBlockRequest retrieval is extremely slow. #316

jclab-joseph opened this issue May 26, 2023 · 3 comments
Labels
need/author-input Needs input from the original author need/triage Needs initial labeling and prioritization

Comments

@jclab-joseph
Copy link

jclab-joseph commented May 26, 2023 •
edited
Loading

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     [email protected]/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     [email protected]/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     [email protected]/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     [email protected]/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     [email protected]/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     [email protected]/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     [email protected]/routing.go:479        finding providers
        {"cid": "QmZe65rbJhncNTmaCXMq54FRG69hgJZodyorLKVmBCX2Sx", "mh": "bciqkp2a7dta6tebtjlpnmjeb7zozbo5q6o2kjdpnkuszxlrv443jrji"}
2023-05-26T18:19:41.009+0900    DEBUG  dht     [email protected]/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     [email protected]/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     [email protected]/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: ipfs/kubo#8346

Bootstrap Node: ipfs version 0.19.2
Client: github.com/ipfs/boxo v0.8.0
@jclab-joseph jclab-joseph added the need/triage Needs initial labeling and prioritization label May 26, 2023
@ipfs ipfs deleted a comment from welcome bot Jun 5, 2023
@lidel
Copy link
Member

lidel commented Jun 5, 2023

  • unsure which InMemoryDatastore you use, mind sharing the code you use?
  • try switching away from map-based store to in-memory leveldb or something similar

@lidel lidel added the need/author-input Needs input from the original author label Jun 5, 2023
@jclab-joseph
Copy link
Author

jclab-joseph commented Jun 8, 2023 •
edited
Loading

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
Copy link
Author

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
need/author-input Needs input from the original author need/triage Needs initial labeling and prioritization
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@lidel @jclab-joseph