>>> Server output: Jun 16 10:26:09.898218 INFO performing build for groups {"plan": "whitenoise", "groups": ["sender", "receiver"], "builder": "exec:go"} Jun 16 10:26:13.190850 INFO build succeeded {"plan": "whitenoise", "groups": ["sender", "receiver"], "builder": "exec:go", "artifact": "/datadrive/testground/data/work/exec-go--whitenoise-e9088b50340b"} Jun 16 10:26:13.190945 INFO performing healthcheck on runner Jun 16 10:26:13.196330 INFO healthcheck: ok Jun 16 10:26:13.196406 INFO starting run {"run_id": "c34t3gaa4c9r7gpmup2g", "plan": "whitenoise", "case": "transfer", "runner": "local:exec", "instances": 2} Jun 16 10:26:13.196546 INFO starting test case instance {"plan": "whitenoise", "group": "sender", "number": 0, "total": 1} Jun 16 10:26:13.196800 INFO starting test case instance {"plan": "whitenoise", "group": "receiver", "number": 0, "total": 2} Jun 16 10:26:13.207179 INFO 0.0104s MESSAGE << sender[000] >> registering default http handler at: http://[::]:6060/ (pprof: http://[::]:6060/debug/pprof/) Jun 16 10:26:13.207279 INFO 0.0105s START << sender[000] >> {"plan":"whitenoise","case":"transfer","run":"c34t3gaa4c9r7gpmup2g","outputs_path":"/datadrive/testground/data/outputs/local_exec/whitenoise/c34t3gaa4c9r7gpmup2g/sender/0","instances":2,"params":{"interrupt":"0/0","linkshape":"null","size":"4GiB"},"group":"sender","group_instances":1,"network":"127.1.0.0/16","start_time":"0001-01-01T00:00:00Z"} Jun 16 10:26:13.207318 INFO 0.0109s OTHER << sender[000] >> {"ts":1623839173207007517,"msg":"writing cpu profile","group_id":"sender","run_id":"c34t3gaa4c9r7gpmup2g"} Jun 16 10:26:13.207340 INFO 0.0109s OTHER << sender[000] >> {"ts":1623839173207325821,"msg":"writing heap profile every 5s","group_id":"sender","run_id":"c34t3gaa4c9r7gpmup2g"} Jun 16 10:26:13.207380 INFO 0.0105s MESSAGE << receiver[000] >> registering default http handler at: http://[::]:41305/ (pprof: http://[::]:41305/debug/pprof/) Jun 16 10:26:13.207417 INFO 0.0105s START << receiver[000] >> {"plan":"whitenoise","case":"transfer","run":"c34t3gaa4c9r7gpmup2g","outputs_path":"/datadrive/testground/data/outputs/local_exec/whitenoise/c34t3gaa4c9r7gpmup2g/receiver/0","instances":2,"params":{"interrupt":"0/0","linkshape":"null","size":"32MiB"},"group":"receiver","group_instances":1,"network":"127.1.0.0/16","start_time":"0001-01-01T00:00:00Z"} Jun 16 10:26:13.207433 INFO 0.0110s OTHER << receiver[000] >> {"ts":1623839173206998583,"msg":"writing cpu profile","group_id":"receiver","run_id":"c34t3gaa4c9r7gpmup2g"} Jun 16 10:26:13.207447 INFO 0.0110s OTHER << receiver[000] >> {"ts":1623839173207298876,"msg":"writing heap profile every 5s","group_id":"receiver","run_id":"c34t3gaa4c9r7gpmup2g"} Jun 16 10:26:13.208813 INFO 0.0123s MESSAGE << receiver[000] >> waiting for network to initialize Jun 16 10:26:13.208844 INFO 0.0124s MESSAGE << sender[000] >> waiting for network to initialize Jun 16 10:26:13.209033 INFO 0.0126s MESSAGE << receiver[000] >> network initialisation successful Jun 16 10:26:13.209061 INFO 0.0126s MESSAGE << sender[000] >> network initialisation successful Jun 16 10:26:13.209111 INFO 0.0127s MESSAGE << receiver[000] >> network initialization complete Jun 16 10:26:13.209131 INFO 0.0127s MESSAGE << sender[000] >> network initialization complete Jun 16 10:26:13.209223 INFO 0.0128s MESSAGE << receiver[000] >> claimed sequence numbers; global=1, group(receiver)=1 Jun 16 10:26:13.209251 INFO 0.0128s MESSAGE << receiver[000] >> Running transfer with Graphsync v0.7 Jun 16 10:26:13.209272 INFO 0.0128s MESSAGE << sender[000] >> claimed sequence numbers; global=2, group(sender)=1 Jun 16 10:26:13.209288 INFO 0.0128s MESSAGE << sender[000] >> Running transfer with Graphsync v0.7 Jun 16 10:26:13.383119 INFO 0.1866s MESSAGE << sender[000] >> creating badger blockstore Jun 16 10:26:13.398576 INFO 0.2021s MESSAGE << sender[000] >> data transfer manager initialized Jun 16 10:26:13.419375 INFO 0.2229s MESSAGE << receiver[000] >> creating badger blockstore Jun 16 10:26:13.462990 INFO 0.2664s MESSAGE << receiver[000] >> data transfer manager initialized Jun 16 10:26:13.463420 INFO 0.2669s MESSAGE << sender[000] >> one other peer found Jun 16 10:26:13.463444 INFO 0.2670s MESSAGE << sender[000] >> interruptor loop started Jun 16 10:26:13.463474 INFO 0.2670s MESSAGE << sender[000] >> we are the sender Jun 16 10:26:13.463657 INFO 0.2672s MESSAGE << receiver[000] >> one other peer found Jun 16 10:26:13.463679 INFO 0.2672s MESSAGE << receiver[000] >> interruptor loop started Jun 16 10:26:13.463701 INFO 0.2672s MESSAGE << receiver[000] >> we are the receiver Jun 16 10:27:46.071406 INFO 92.8749s MESSAGE << sender[000] >> import took: 1m32.607825755s Jun 16 10:27:46.075175 INFO 92.8786s MESSAGE << sender[000] >> opening the push data channel Jun 16 10:27:47.075954 INFO 93.8794s MESSAGE << sender[000] >> channel state: Ongoing (sent 339041951) Jun 16 10:27:48.076317 INFO 94.8798s MESSAGE << sender[000] >> channel state: Ongoing (sent 685943881) Jun 16 10:27:49.076726 INFO 95.8802s MESSAGE << sender[000] >> channel state: Ongoing (sent 1031526659) Jun 16 10:27:50.077215 INFO 96.8806s MESSAGE << sender[000] >> channel state: Ongoing (sent 1378952905) Jun 16 10:27:51.077514 INFO 97.8810s MESSAGE << sender[000] >> channel state: Ongoing (sent 1730041001) Jun 16 10:27:52.078086 INFO 98.8815s MESSAGE << sender[000] >> channel state: Ongoing (sent 2078778037) Jun 16 10:27:53.078434 INFO 99.8819s MESSAGE << sender[000] >> channel state: Ongoing (sent 2436166287) Jun 16 10:27:54.078817 INFO 100.8822s MESSAGE << sender[000] >> channel state: Ongoing (sent 2791719431) Jun 16 10:27:55.079243 INFO 101.8826s MESSAGE << sender[000] >> channel state: Ongoing (sent 3146215581) Jun 16 10:27:56.082025 INFO 102.8855s MESSAGE << sender[000] >> channel state: Ongoing (sent 3500457935) Jun 16 10:27:57.080200 INFO 103.8837s MESSAGE << sender[000] >> channel state: Ongoing (sent 3850243603) Jun 16 10:27:58.080494 INFO 104.8839s MESSAGE << sender[000] >> channel state: Ongoing (sent 4201864377) Jun 16 10:27:59.081630 INFO 105.8851s MESSAGE << sender[000] >> channel state: TransferFinished (sent 4295988814) Jun 16 10:27:59.081692 INFO 105.8851s MESSAGE << sender[000] >> transfer took (from sender's perspective): 13.006509877s Jun 16 10:27:59.081991 INFO 105.8855s OK << sender[000] >> Jun 16 10:27:59.464496 INFO 106.2678s OK << receiver[000] >> Jun 16 10:28:00.154421 INFO run finished successfully {"run_id": "c34t3gaa4c9r7gpmup2g", "plan": "whitenoise", "case": "transfer", "runner": "local:exec", "instances": 2} >>> Result: Jun 16 10:28:02.416954 INFO finished run with ID: c34t3gaa4c9r7gpmup2g >>> Result: Jun 16 10:28:02.610510 INFO created file: c34t3gaa4c9r7gpmup2g.tgz