WIP add sync example

[rklaehn]

Seems to get stuck somehow...

Plan would be:

• [ ] sync a movie
• [ ] make sure it is not slower than go-ipfs
• [ ] ...
• [ ] profit

[rklaehn]

Console output:

rklaehn@linux-box:~/projects_git/ipfs-embed$ RUST_LOG=debug cargo run --example sync
    Finished dev [unoptimized + debuginfo] target(s) in 0.14s
     Running `target/debug/examples/sync`
Feb 15 23:15:09.428 DEBUG libp2p_tcp: dialing 54.173.33.96:4001    
Feb 15 23:15:09.584 DEBUG multistream_select::dialer_select: Dialer: Proposed protocol: /noise    
Feb 15 23:15:09.789 DEBUG multistream_select::dialer_select: Dialer: Received confirmation for protocol: /noise    
Feb 15 23:15:09.913 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Feb 15 23:15:09.914 DEBUG multistream_select::dialer_select: Dialer: Proposed protocol: /yamux/1.0.0    
Feb 15 23:15:10.309 DEBUG multistream_select::dialer_select: Dialer: Received confirmation for protocol: /yamux/1.0.0    
Feb 15 23:15:10.310 DEBUG yamux::connection: new connection: d9e53d04 (Client)    
Feb 15 23:15:10.310 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Feb 15 23:15:10.311 DEBUG libp2p_swarm: Connection established: Connected { endpoint: Dialer { address: "/ip4/54.173.33.96/tcp/4001" }, peer_id: PeerId("QmRSGx67Kq8w7xSBDia7hQfbfuvauMQGgxcwSWw976x4BS") }; Total (peer): 1.    
Feb 15 23:15:10.311  INFO libp2p_gossipsub::behaviour: New peer connected: QmRSGx67Kq8w7xSBDia7hQfbfuvauMQGgxcwSWw976x4BS    
Feb 15 23:15:10.312 DEBUG multistream_select::listener_select: Listener: confirming protocol: /ipfs/id/1.0.0    
Feb 15 23:15:10.312 DEBUG multistream_select::listener_select: Listener: sent confirmed protocol: /ipfs/id/1.0.0    
Feb 15 23:15:10.312 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Feb 15 23:15:10.313 DEBUG yamux::connection: d9e53d04: new outbound (Stream d9e53d04/1) of (Connection d9e53d04 Client (streams 2))    
Feb 15 23:15:10.314 DEBUG multistream_select::dialer_select: Dialer: Proposed protocol: /ipfs/ping/1.0.0    
Feb 15 23:15:10.314 DEBUG libp2p_identify::protocol: Sending identify info to client    
Feb 15 23:15:10.315 DEBUG yamux::connection: d9e53d04: new outbound (Stream d9e53d04/3) of (Connection d9e53d04 Client (streams 2))    
Feb 15 23:15:10.316 DEBUG multistream_select::dialer_select: Dialer: Proposed protocol: /ipfs/id/1.0.0    
Feb 15 23:15:10.316 DEBUG yamux::connection: d9e53d04: new outbound (Stream d9e53d04/5) of (Connection d9e53d04 Client (streams 3))    
Feb 15 23:15:10.317 DEBUG multistream_select::dialer_select: Dialer: Proposed protocol: /t/1/ipfs-embed/bitswap/1.0.0    
Feb 15 23:15:10.720 DEBUG multistream_select::listener_select: Listener: confirming protocol: /meshsub/1.1.0    
Feb 15 23:15:10.721 DEBUG multistream_select::listener_select: Listener: sent confirmed protocol: /meshsub/1.1.0    
Feb 15 23:15:10.721 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Feb 15 23:15:10.721 DEBUG multistream_select::dialer_select: Dialer: Received rejection of protocol: /t/1/ipfs-embed/bitswap/1.0.0    
Feb 15 23:15:10.721 DEBUG multistream_select::dialer_select: Dialer: Received confirmation for protocol: /ipfs/ping/1.0.0    
Feb 15 23:15:10.722 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Feb 15 23:15:10.722 DEBUG multistream_select::dialer_select: Dialer: Received confirmation for protocol: /ipfs/id/1.0.0    
Feb 15 23:15:10.723 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Feb 15 23:15:10.723 DEBUG libp2p_ping::protocol: Preparing ping payload [99, 75, 3, 114, 152, 175, 32, 102, 185, 31, 228, 19, 171, 70, 87, 172, 220, 48, 79, 242, 138, 52, 18, 188, 101, 67, 168, 91, 54, 83, 191, 221]    
Feb 15 23:15:10.723 DEBUG libp2p_ping::protocol: Awaiting pong for [99, 75, 3, 114, 152, 175, 32, 102, 185, 31, 228, 19, 171, 70, 87, 172, 220, 48, 79, 242, 138, 52, 18, 188, 101, 67, 168, 91, 54, 83, 191, 221]    
Feb 15 23:15:10.724 DEBUG ipfs_embed_net::behaviour: has external address /ip4/193.159.79.12/tcp/38224
Feb 15 23:15:10.726 DEBUG libp2p_gossipsub::behaviour: New peer type found: Gossipsub v1.1 for peer: QmRSGx67Kq8w7xSBDia7hQfbfuvauMQGgxcwSWw976x4BS    
Feb 15 23:15:10.726 DEBUG yamux::connection: d9e53d04: new outbound (Stream d9e53d04/7) of (Connection d9e53d04 Client (streams 2))    
Feb 15 23:15:10.726 DEBUG libp2p_gossipsub::behaviour: Handling subscriptions: [GossipsubSubscription { action: Subscribe, topic_hash: TopicHash { hash: "/record/L2lwbnMvEiAuA_FXNEWwECQCwdh_N_kzdpiXwAlhMAg7JHO6pi37cQ" } }], from source: QmRSGx67Kq8w7xSBDia7hQfbfuvauMQGgxcwSWw976x4BS    
Feb 15 23:15:10.726 DEBUG multistream_select::dialer_select: Dialer: Proposed protocol: /ipfs/bitswap/1.2.0    
Feb 15 23:15:10.727 DEBUG libp2p_gossipsub::behaviour: SUBSCRIPTION: Adding gossip peer: QmRSGx67Kq8w7xSBDia7hQfbfuvauMQGgxcwSWw976x4BS to topic: TopicHash { hash: "/record/L2lwbnMvEiAuA_FXNEWwECQCwdh_N_kzdpiXwAlhMAg7JHO6pi37cQ" }    
Feb 15 23:15:11.029 DEBUG multistream_select::dialer_select: Dialer: Received confirmation for protocol: /ipfs/bitswap/1.2.0    
Feb 15 23:15:11.030 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Feb 15 23:15:11.145 DEBUG multistream_select::listener_select: Listener: confirming protocol: /ipfs/bitswap/1.2.0    
Feb 15 23:15:11.145 DEBUG multistream_select::listener_select: Listener: sent confirmed protocol: /ipfs/bitswap/1.2.0    
Feb 15 23:15:11.146 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
got single block. len = 9
Feb 15 23:15:14.425 DEBUG ipfs_embed_sqlite: gc_loop running incremental gc
Feb 15 23:15:14.426 DEBUG ipfs_sqlite_block_store::db: gc took 329us
Feb 15 23:15:14.428 DEBUG libp2p_gossipsub::behaviour: Starting heartbeat    
Feb 15 23:15:14.428 DEBUG libp2p_gossipsub::behaviour: Completed Heartbeat    

[rklaehn]

I guess to support syncing a movie you would also have to support unixfs v1 codec, but sync does not even work with a tiny dag-cbor dag.

[dvc94ch]

when running this locally with RUST_LOG=ipfs_embed,libp2p_bitswap I get:

Feb 15 23:28:38.275 TRACE ipfs_embed_net::peers: adding address /ip4/54.173.33.96/tcp/4001 for peer QmRSGx67Kq8w7xSBDia7hQfbfuvauMQGgxcwSWw976x4BS from User
Feb 15 23:28:38.276 TRACE libp2p_bitswap::query: 0 0 get
Feb 15 23:28:38.276 TRACE libp2p_bitswap::query: 0 1 providers
Feb 15 23:28:39.389 TRACE ipfs_embed_net::behaviour: kademlia event RoutingUpdated { peer: PeerId("QmRSGx67Kq8w7xSBDia7hQfbfuvauMQGgxcwSWw976x4BS"), addresses: ["/ip4/54.173.33.96/tcp/4001"], old_peer: None }
Feb 15 23:28:39.390 TRACE libp2p_bitswap::query: 0 1 providers 1
Feb 15 23:28:39.390 TRACE libp2p_bitswap::query: 0 2 block
Feb 15 23:28:39.903 TRACE ipfs_embed_net::behaviour: ping: rtt to QmRSGx67Kq8w7xSBDia7hQfbfuvauMQGgxcwSWw976x4BS is 308 ms
Feb 15 23:28:39.904 DEBUG ipfs_embed_net::behaviour: has external address /ip4/213.55.225.247/tcp/18118
Feb 15 23:28:39.904 TRACE libp2p_bitswap::behaviour: bitswap outbound failure QmRSGx67Kq8w7xSBDia7hQfbfuvauMQGgxcwSWw976x4BS 1 UnsupportedProtocols
Feb 15 23:28:40.256 TRACE libp2p_bitswap::query: 0 2 block true
Feb 15 23:28:40.256 TRACE libp2p_bitswap::query: 0 0 get ok
got single block. len = 9
Feb 15 23:28:40.257 TRACE libp2p_bitswap::query: 3 3 get
Feb 15 23:28:40.257 TRACE libp2p_bitswap::query: 3 4 providers
Feb 15 23:28:43.272 DEBUG ipfs_embed_sqlite: gc_loop running incremental gc
Feb 15 23:28:43.274 TRACE libp2p_bitswap::query: 3 4 providers 1
Feb 15 23:28:43.274 TRACE libp2p_bitswap::query: 3 5 block
Feb 15 23:28:48.273 DEBUG ipfs_embed_sqlite: gc_loop running incremental delete orphaned
Feb 15 23:28:53.274 DEBUG ipfs_embed_sqlite: gc_loop running incremental gc
Feb 15 23:28:55.103 TRACE ipfs_embed_net::behaviour: ping: rtt to QmRSGx67Kq8w7xSBDia7hQfbfuvauMQGgxcwSWw976x4BS is 198 ms
Feb 15 23:28:58.274 DEBUG ipfs_embed_sqlite: gc_loop running incremental delete orphaned
Feb 15 23:29:03.275 DEBUG ipfs_embed_sqlite: gc_loop running incremental gc
Feb 15 23:29:08.276 DEBUG ipfs_embed_sqlite: gc_loop running incremental delete orphaned
Feb 15 23:29:09.599 DEBUG ipfs_embed_net::behaviour: has external address /ip4/213.55.225.247/tcp/18120
Feb 15 23:29:09.600 TRACE libp2p_bitswap::behaviour: bitswap outbound failure QmRSGx67Kq8w7xSBDia7hQfbfuvauMQGgxcwSWw976x4BS 2 UnsupportedProtocols
Feb 15 23:29:09.802 TRACE ipfs_embed_net::behaviour: ping: rtt to QmRSGx67Kq8w7xSBDia7hQfbfuvauMQGgxcwSWw976x4BS is 203 ms
Feb 15 23:29:10.111 TRACE libp2p_bitswap::query: 3 5 block true
Feb 15 23:29:10.111 TRACE libp2p_bitswap::query: 3 3 get ok
got single block. len = 44
Feb 15 23:29:10.113 TRACE libp2p_bitswap::query: 6 6 sync
Feb 15 23:29:10.113 TRACE libp2p_bitswap::query: 6 7 missing-blocks
starting sync of large file
Feb 15 23:29:10.275 TRACE libp2p_bitswap::query: 6 7 missing-blocks 0
Feb 15 23:29:10.275 TRACE libp2p_bitswap::query: 6 6 sync ok
Complete(Ok(()))

[dvc94ch]

missing-blocks seems to errouneously return 0

[dvc94ch]

there also seems to be a problem with the gc loop accumulating ticks, the above log was produced compiling in debug mode

[rklaehn]

Do we already have code to allow getting links out of unixfsv1 files? I think an example syncing a movie is both a good benchmark and also a nice example for third parties.

[rklaehn]

Hm, it seems to get stuck after the first sync, and then gets unstuck after 30s:

rklaehn@linux-box:~/projects_git/ipfs-embed$ time cargo run --example sync
    Finished dev [unoptimized + debuginfo] target(s) in 0.13s
     Running `target/debug/examples/sync`
got single block. len = 9
got single block. len = 44
starting sync of large file
Complete(Ok(()))

real    0m32,241s
user    0m0,341s
sys 0m0,041s

Same with your run:

Feb 15 23:28:40.256 TRACE libp2p_bitswap::query: 0 0 get ok
got single block. len = 9

...30s difference

Feb 15 23:29:10.111 TRACE libp2p_bitswap::query: 3 3 get ok
got single block. len = 44

I thought it got terminally stuck because I was not patient enough to wait 30s, but obviously this is still a bug.

[rklaehn]

What's bitswap outbound failure?

[dvc94ch]

That's expected with a goipfs node. It tries the default bitswap and if it falls due to unsupported protocol it tries the compat one

[rklaehn]

So this is where it asks for the second block

Feb 15 23:28:43.274 TRACE libp2p_bitswap::query: 3 5 block

and this is where it gets it

Feb 15 23:29:10.111 TRACE libp2p_bitswap::query: 3 5 block true

?

[dvc94ch]

Yes

[rklaehn]

So why is it immediate for the first block, but 30s for the second one? Would be good to see all pl bitswap msgs flying by.

It seems to be roughly 30s always.