REAP-enabled snapshots failing on the legacy branch

[sviho]

Hi,

I am trying to re-run the experiment from the ASPLOS'21 paper's Figure 8 locally, but I am running into errors. From the docs, since REAP isn't supported in the latest version of vHive, I am running this on the legacy-firecracker-v0.24.0-with-upf-support branch.

With firecracker-containerd launched, I am using the following command to run the test (similar to #657) with the -upfTest flag to enable REAP:

sudo env "PATH=$PATH" go test -v -run TestBenchServe -args -iter 3 -benchDirTest ~/vHive/logs -metricsTest -funcName image_rotate -snapshotsTest -upfTest 1>~/vHive/logs/vhive.out 2>/dev/null

The test runs successfully without the -upfTest flag, but it fails with the following logs when the flag is set. I would appreciate any help on this!

This is the log from the go test side:

time="2024-07-03T03:40:17.290815776Z" level=info msg="Orchestrator snapshots enabled: true"
time="2024-07-03T03:40:17.290895953Z" level=info msg="Orchestrator UPF enabled: true"
time="2024-07-03T03:40:17.290900533Z" level=info msg="Orchestrator lazy serving mode enabled: false"
time="2024-07-03T03:40:17.290903416Z" level=info msg="Orchestrator UPF metrics enabled: true"
time="2024-07-03T03:40:17.290905395Z" level=info msg="Drop cache: true"
time="2024-07-03T03:40:17.290907352Z" level=info msg="Bench dir: /home/lana/vHive/logs"
time="2024-07-03T03:40:17.292035935Z" level=info msg="Registering bridges for tap manager"
time="2024-07-03T03:40:17.292585451Z" level=info msg="Creating containerd client"
time="2024-07-03T03:40:17.292914535Z" level=info msg="Created containerd client"
time="2024-07-03T03:40:17.292920886Z" level=info msg="Creating firecracker client"
time="2024-07-03T03:40:17.292961084Z" level=info msg="Created firecracker client"
time="2024-07-03T03:40:17.292965561Z" level=info msg="Creating image manager"
=== RUN   TestBenchServe
time="2024-07-03T03:40:17.293056276Z" level=info msg="pulling image"
time="2024-07-03T03:40:17.293079073Z" level=info msg="New function added" fID=plr-fnc image="ghcr.io/ease-lab/image_rotate:var_workload" isPinned=true servedTh=0
time="2024-07-03T03:40:22.392495871Z" level=warning msg="Failed to Fetch k8s dns clusterIP exit status 1\nThe connection to the server localhost:8080 was refused - did you specify the right host or port?\n\n"
time="2024-07-03T03:40:22.392528246Z" level=warning msg="Using google dns 8.8.8.8\n"
time="2024-07-03T03:40:23.909080310Z" level=info msg="creating snapshots"
time="2024-07-03T03:40:23.909123003Z" level=info msg="New function added" fID=0 image="ghcr.io/ease-lab/image_rotate:var_workload" isPinned=true servedTh=0
time="2024-07-03T03:40:23.960706350Z" level=warning msg="Failed to Fetch k8s dns clusterIP exit status 1\nThe connection to the server localhost:8080 was refused - did you specify the right host or port?\n\n"
time="2024-07-03T03:40:23.960732665Z" level=warning msg="Using google dns 8.8.8.8\n"
time="2024-07-03T03:40:25.534446889Z" level=info msg="creating records"
time="2024-07-03T03:40:25.621861799Z" level=error msg="Failed to load snapshot of the VM: rpc error: code = Unknown desc = Put \"http+unix://firecracker/snapshot/load\": EOF" vmID=0-0
time="2024-07-03T03:40:26.535860149Z" level=error msg="Failed to dial within the context timeout"
time="2024-07-03T03:40:26.535876563Z" level=error msg="Failed to get uffd" vmID=0-0
time="2024-07-03T03:40:26.535884932Z" level=warning msg="Failed to activate VM in the memory managerdial unix /var/lib/firecracker-containerd/shim-base/firecracker-containerd/0-0/firecracker.upfsock: i/o timeout" vmID=0-0
time="2024-07-03T03:40:26.535895604Z" level=panic msg="encountered multiple errors:\n\t... rpc error: code = Unknown desc = Put \"http+unix://firecracker/snapshot/load\": EOF\n\t... dial unix /var/lib/firecracker-containerd/shim-base/firecracker-containerd/0-0/firecracker.upfsock: i/o timeout"
panic: (*logrus.Entry) 0xc00024ca80

goroutine 927 [running]:
github.com/sirupsen/logrus.(*Entry).log(0xc00024c0e0, 0x0, {0xc00038e0f0, 0xe8})
   /root/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/entry.go:260 +0x4a7
github.com/sirupsen/logrus.(*Entry).Log(0xc00024c0e0, 0x0, {0xc0005cd610?, 0x0?, 0x0?})
   /root/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/entry.go:304 +0x4f
github.com/sirupsen/logrus.(*Logger).Log(0xc000158000, 0x0, {0xc0005cd610, 0x1, 0x1})
   /root/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/logger.go:204 +0x65
github.com/sirupsen/logrus.(*Logger).Panic(...)
   /root/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/logger.go:253
github.com/sirupsen/logrus.Panic(...)
   /root/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/exported.go:129
github.com/vhive-serverless/vhive.(*Function).LoadInstance(0xc0003f4420, {0xc00092211c, 0x3})
   /home/lana/vHive/functions.go:499 +0x271
github.com/vhive-serverless/vhive.(*Function).AddInstance(0xc0003f4420)
   /home/lana/vHive/functions.go:361 +0x216
github.com/vhive-serverless/vhive.(*Function).Serve.func1()
   /home/lana/vHive/functions.go:259 +0xbb
sync.(*Once).doSlow(0x15326a0?, 0xc00046c9f0?)
   /usr/local/go/src/sync/once.go:74 +0xc2
sync.(*Once).Do(...)
   /usr/local/go/src/sync/once.go:65
github.com/vhive-serverless/vhive.(*Function).Serve(0xc0003f4420, {0x16b1d17?, 0x1?}, {0x16ba5e9?, 0x2a?}, {0x0?, 0x0?}, {0x168af33, 0x6})
   /home/lana/vHive/functions.go:253 +0x31a
github.com/vhive-serverless/vhive.(*FuncPool).Serve(0x0?, {0x18427d8, 0xc000038098}, {0x16b1d17, 0x1}, {0x16ba5e9, 0x2a}, {0x168af33, 0x6})
   /home/lana/vHive/functions.go:123 +0x96
github.com/vhive-serverless/vhive.createRecords.func1({0x16b1d17, 0x1})
   /home/lana/vHive/bench_test.go:326 +0xd8
created by github.com/vhive-serverless/vhive.createRecords
   /home/lana/vHive/bench_test.go:322 +0x5d
exit status 2
FAIL	github.com/vhive-serverless/vhive	9.254s

This is the full log from the launched firecracker-containerd side:

WARN[0000] deprecated version : `1`, please switch to version `2` 
INFO[2024-07-03T04:43:11.536214024Z] starting containerd                           revision=4a8adae2660e3db2ea9b5b7b057b4388b9f5bab8 version=1.5.2+unknown
INFO[2024-07-03T04:43:11.550321794Z] loading plugin "io.containerd.content.v1.content"...  type=io.containerd.content.v1
INFO[2024-07-03T04:43:11.550404977Z] loading plugin "io.containerd.snapshotter.v1.devmapper"...  type=io.containerd.snapshotter.v1
INFO[2024-07-03T04:43:11.550440350Z] initializing pool device "fc-dev-thinpool"   
INFO[2024-07-03T04:43:11.551602427Z] using dmsetup:
Library version:   1.02.185 (2022-05-18)
Driver version:    4.48.0 
INFO[2024-07-03T04:43:11.553292157Z] loading plugin "io.containerd.snapshotter.v1.overlayfs"...  type=io.containerd.snapshotter.v1
INFO[2024-07-03T04:43:11.553807832Z] loading plugin "io.containerd.metadata.v1.bolt"...  type=io.containerd.metadata.v1
INFO[2024-07-03T04:43:11.553848082Z] metadata content store policy set             policy=shared
INFO[2024-07-03T04:43:11.554332957Z] loading plugin "io.containerd.differ.v1.walking"...  type=io.containerd.differ.v1
INFO[2024-07-03T04:43:11.554346071Z] loading plugin "io.containerd.gc.v1.scheduler"...  type=io.containerd.gc.v1
INFO[2024-07-03T04:43:11.554367042Z] loading plugin "io.containerd.service.v1.introspection-service"...  type=io.containerd.service.v1
INFO[2024-07-03T04:43:11.554380790Z] loading plugin "io.containerd.service.v1.containers-service"...  type=io.containerd.service.v1
INFO[2024-07-03T04:43:11.554388724Z] loading plugin "io.containerd.service.v1.content-service"...  type=io.containerd.service.v1
INFO[2024-07-03T04:43:11.554397277Z] loading plugin "io.containerd.service.v1.diff-service"...  type=io.containerd.service.v1
INFO[2024-07-03T04:43:11.554406884Z] loading plugin "io.containerd.service.v1.images-service"...  type=io.containerd.service.v1
INFO[2024-07-03T04:43:11.554415634Z] loading plugin "io.containerd.service.v1.leases-service"...  type=io.containerd.service.v1
INFO[2024-07-03T04:43:11.554424489Z] loading plugin "io.containerd.service.v1.namespaces-service"...  type=io.containerd.service.v1
INFO[2024-07-03T04:43:11.554432450Z] loading plugin "io.containerd.service.v1.snapshots-service"...  type=io.containerd.service.v1
INFO[2024-07-03T04:43:11.554441433Z] loading plugin "io.containerd.runtime.v1.linux"...  type=io.containerd.runtime.v1
INFO[2024-07-03T04:43:11.554487813Z] loading plugin "io.containerd.runtime.v2.task"...  type=io.containerd.runtime.v2
INFO[2024-07-03T04:43:11.554527275Z] loading plugin "io.containerd.monitor.v1.cgroups"...  type=io.containerd.monitor.v1
INFO[2024-07-03T04:43:11.554687465Z] loading plugin "io.containerd.service.v1.tasks-service"...  type=io.containerd.service.v1
INFO[2024-07-03T04:43:11.554700414Z] loading plugin "io.containerd.service.v1.fc-control"...  type=io.containerd.service.v1
DEBU[2024-07-03T04:43:11.554707793Z] initializing fc-control plugin (root: "/var/lib/firecracker-containerd/containerd/io.containerd.service.v1.fc-control") 
INFO[2024-07-03T04:43:11.554875952Z] loading plugin "io.containerd.internal.v1.restart"...  type=io.containerd.internal.v1
INFO[2024-07-03T04:43:11.554908930Z] loading plugin "io.containerd.grpc.v1.containers"...  type=io.containerd.grpc.v1
INFO[2024-07-03T04:43:11.554918803Z] loading plugin "io.containerd.grpc.v1.content"...  type=io.containerd.grpc.v1
INFO[2024-07-03T04:43:11.554932183Z] loading plugin "io.containerd.grpc.v1.diff"...  type=io.containerd.grpc.v1
INFO[2024-07-03T04:43:11.554940331Z] loading plugin "io.containerd.grpc.v1.events"...  type=io.containerd.grpc.v1
INFO[2024-07-03T04:43:11.554948421Z] loading plugin "io.containerd.grpc.v1.healthcheck"...  type=io.containerd.grpc.v1
INFO[2024-07-03T04:43:11.554957515Z] loading plugin "io.containerd.grpc.v1.images"...  type=io.containerd.grpc.v1
INFO[2024-07-03T04:43:11.554965949Z] loading plugin "io.containerd.grpc.v1.leases"...  type=io.containerd.grpc.v1
INFO[2024-07-03T04:43:11.554975248Z] loading plugin "io.containerd.grpc.v1.namespaces"...  type=io.containerd.grpc.v1
INFO[2024-07-03T04:43:11.554988194Z] loading plugin "io.containerd.internal.v1.opt"...  type=io.containerd.internal.v1
INFO[2024-07-03T04:43:11.555011658Z] loading plugin "io.containerd.grpc.v1.snapshots"...  type=io.containerd.grpc.v1
INFO[2024-07-03T04:43:11.555019910Z] loading plugin "io.containerd.grpc.v1.tasks"...  type=io.containerd.grpc.v1
INFO[2024-07-03T04:43:11.555027927Z] loading plugin "io.containerd.grpc.v1.version"...  type=io.containerd.grpc.v1
INFO[2024-07-03T04:43:11.555035378Z] loading plugin "io.containerd.grpc.v1.fc-control-service"...  type=io.containerd.grpc.v1
DEBU[2024-07-03T04:43:11.555041001Z] initializing fc-control-service plugin       
INFO[2024-07-03T04:43:11.555050261Z] loading plugin "io.containerd.grpc.v1.introspection"...  type=io.containerd.grpc.v1
INFO[2024-07-03T04:43:11.555161009Z] serving...                                    address=/run/firecracker-containerd/containerd.sock.ttrpc
INFO[2024-07-03T04:43:11.555200475Z] serving...                                    address=/run/firecracker-containerd/containerd.sock
DEBU[2024-07-03T04:43:11.555208278Z] sd notification                               error="<nil>" notified=false state="READY=1"
INFO[2024-07-03T04:43:11.555216308Z] containerd successfully booted in 0.019511s  
DEBU[2024-07-03T04:43:11.654740805Z] garbage collected                             d="138.099µs"
DEBU[2024-07-03T04:48:54.132588610Z] (*service).Write started                      expected="sha256:d6043a1f17efb4c20f3bd635ed20ac9978c88fbbadece77c7ec6e9c00dd20eeb" ref="manifest-sha256:d6043a1f17efb4c20f3bd635ed20ac9978c88fbbadece77c7ec6e9c00dd20eeb" total=2209
DEBU[2024-07-03T04:48:54.172225668Z] (*service).Write started                      expected="sha256:588189a4f5c311aee7dc7aa62787592708930eedf2ae7b572d855047a6567941" ref="config-sha256:588189a4f5c311aee7dc7aa62787592708930eedf2ae7b572d855047a6567941" total=8559
DEBU[2024-07-03T04:48:54.256905219Z] stat snapshot                                 key="sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10"
DEBU[2024-07-03T04:48:54.257047638Z] prepare snapshot                              key="extract-256991966-Xw-a sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10" parent=
DEBU[2024-07-03T04:48:54.257189201Z] prepare                                       key="firecracker-containerd/1/extract-256991966-Xw-a sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10" parent=
DEBU[2024-07-03T04:48:54.257383506Z] creating new thin device 'fc-dev-thinpool-snap-1' 
DEBU[2024-07-03T04:48:54.276333459Z] mkfs.ext4 -E nodiscard,lazy_itable_init=0,lazy_journal_init=0 /dev/mapper/fc-dev-thinpool-snap-1 
DEBU[2024-07-03T04:48:54.521378021Z] mkfs:
mke2fs 1.47.0 (5-Feb-2023)
Creating filesystem with 2621440 4k blocks and 655360 inodes
Filesystem UUID: be3ad218-dc46-454a-91e1-08f03037a8a9
Superblock backups stored on blocks: 
   32768, 98304, 163840, 229376, 294912, 819200, 884736, 1605632

Allocating group tables: done                            
Writing inode tables: done                            
Creating journal (16384 blocks): done
Writing superblocks and filesystem accounting information: done 

DEBU[2024-07-03T04:48:54.524657347Z] event published                               ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2024-07-03T04:48:54.524984662Z] (*service).Write started                      expected="sha256:2cc5ad85d9abaadf23d5ae53c3f32e7ccb2df1956869980bfd2491ff396d348a" ref="layer-sha256:2cc5ad85d9abaadf23d5ae53c3f32e7ccb2df1956869980bfd2491ff396d348a" total=301261
DEBU[2024-07-03T04:48:54.524988696Z] (*service).Write started                      expected="sha256:61614c1a5710c76af6b2a9c7170a81eb0dd76ccf90e921abc0c9dcc1d5ed490e" ref="layer-sha256:61614c1a5710c76af6b2a9c7170a81eb0dd76ccf90e921abc0c9dcc1d5ed490e" total=31506523
DEBU[2024-07-03T04:48:54.525002757Z] (*service).Write started                      expected="sha256:e2a79086342d3b977046e655782cd75e24a14160750c76daac9c4d2200589e9f" ref="layer-sha256:e2a79086342d3b977046e655782cd75e24a14160750c76daac9c4d2200589e9f" total=2346
DEBU[2024-07-03T04:48:54.524996402Z] (*service).Write started                      expected="sha256:c9b1b535fdd91a9855fb7f82348177e5f019329a58c53c47272962dd60f71fc9" ref="layer-sha256:c9b1b535fdd91a9855fb7f82348177e5f019329a58c53c47272962dd60f71fc9" total=2802957
DEBU[2024-07-03T04:48:54.525019538Z] (*service).Write started                      expected="sha256:407da27a03363f6b9d368ec6e131f7f2db7c8cb2a149160d913d6f3698905a5d" ref="layer-sha256:407da27a03363f6b9d368ec6e131f7f2db7c8cb2a149160d913d6f3698905a5d" total=1887472
DEBU[2024-07-03T04:48:54.525041236Z] (*service).Write started                      expected="sha256:5995ac165d0d2c499ba4fd36b906de6145f6889a30e5c6514d08e3f7ee0ccc95" ref="layer-sha256:5995ac165d0d2c499ba4fd36b906de6145f6889a30e5c6514d08e3f7ee0ccc95" total=1033378
DEBU[2024-07-03T04:48:54.525041205Z] (*service).Write started                      expected="sha256:137112f2985dc0bfe0e1fa772d8bffe9f5f5a3f26ba8fe6e0ce22145aeb15e00" ref="layer-sha256:137112f2985dc0bfe0e1fa772d8bffe9f5f5a3f26ba8fe6e0ce22145aeb15e00" total=205929
DEBU[2024-07-03T04:48:54.525090782Z] (*service).Write started                      expected="sha256:117c33855025f288345e517f4d3c0c3ae77d191a30e894544363cf54de85e9ff" ref="layer-sha256:117c33855025f288345e517f4d3c0c3ae77d191a30e894544363cf54de85e9ff" total=21842527
DEBU[2024-07-03T04:48:54.525118037Z] (*service).Write started                      expected="sha256:0522d30cde10ac29ae2c555b9bde76c2b50aafc7ef7435bbc7e19de706bcadcd" ref="layer-sha256:0522d30cde10ac29ae2c555b9bde76c2b50aafc7ef7435bbc7e19de706bcadcd" total=230
DEBU[2024-07-03T04:48:54.627970429Z] unpigz not found, falling back to go gzip     error="exec: \"unpigz\": executable file not found in $PATH"
DEBU[2024-07-03T04:48:54.725176827Z] diff applied                                  d=97.305576ms digest="sha256:c9b1b535fdd91a9855fb7f82348177e5f019329a58c53c47272962dd60f71fc9" media=application/vnd.docker.image.rootfs.diff.tar.gzip size=2802957
DEBU[2024-07-03T04:48:54.725384275Z] commit snapshot                               key="extract-256991966-Xw-a sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10" name="sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10"
DEBU[2024-07-03T04:48:54.725484093Z] commit                                        key="firecracker-containerd/1/extract-256991966-Xw-a sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10" name="firecracker-containerd/2/sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10"
DEBU[2024-07-03T04:48:54.760275544Z] event published                               ns=firecracker-containerd topic=/snapshot/commit type=containerd.events.SnapshotCommit
DEBU[2024-07-03T04:48:54.761319924Z] stat snapshot                                 key="sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5"
DEBU[2024-07-03T04:48:54.761777134Z] prepare snapshot                              key="extract-761409359-Yh1y sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5" parent="sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10"
DEBU[2024-07-03T04:48:54.762017540Z] prepare                                       key="firecracker-containerd/3/extract-761409359-Yh1y sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5" parent="firecracker-containerd/2/sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10"
DEBU[2024-07-03T04:48:54.762130394Z] creating snapshot device 'fc-dev-thinpool-snap-2' from 'fc-dev-thinpool-snap-1' 
DEBU[2024-07-03T04:48:54.786294052Z] event published                               ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2024-07-03T04:48:54.821025899Z] diff applied                                  d=34.51921ms digest="sha256:2cc5ad85d9abaadf23d5ae53c3f32e7ccb2df1956869980bfd2491ff396d348a" media=application/vnd.docker.image.rootfs.diff.tar.gzip size=301261
DEBU[2024-07-03T04:48:54.821199186Z] commit snapshot                               key="extract-761409359-Yh1y sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5" name="sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5"
DEBU[2024-07-03T04:48:54.821286628Z] commit                                        key="firecracker-containerd/3/extract-761409359-Yh1y sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5" name="firecracker-containerd/4/sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5"
DEBU[2024-07-03T04:48:54.853325017Z] event published                               ns=firecracker-containerd topic=/snapshot/commit type=containerd.events.SnapshotCommit
DEBU[2024-07-03T04:48:54.853827082Z] stat snapshot                                 key="sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa"
DEBU[2024-07-03T04:48:54.853999471Z] prepare snapshot                              key="extract-853923676-lWbH sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa" parent="sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5"
DEBU[2024-07-03T04:48:54.854142727Z] prepare                                       key="firecracker-containerd/5/extract-853923676-lWbH sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa" parent="firecracker-containerd/4/sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5"
DEBU[2024-07-03T04:48:54.854178429Z] creating snapshot device 'fc-dev-thinpool-snap-3' from 'fc-dev-thinpool-snap-2' 
DEBU[2024-07-03T04:48:54.892767837Z] event published                               ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2024-07-03T04:48:57.594466875Z] diff applied                                  d=849.458638ms digest="sha256:61614c1a5710c76af6b2a9c7170a81eb0dd76ccf90e921abc0c9dcc1d5ed490e" media=application/vnd.docker.image.rootfs.diff.tar.gzip size=31506523
DEBU[2024-07-03T04:48:57.595208143Z] commit snapshot                               key="extract-853923676-lWbH sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa" name="sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa"
DEBU[2024-07-03T04:48:57.595304660Z] commit                                        key="firecracker-containerd/5/extract-853923676-lWbH sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa" name="firecracker-containerd/6/sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa"
DEBU[2024-07-03T04:48:57.626827676Z] event published                               ns=firecracker-containerd topic=/snapshot/commit type=containerd.events.SnapshotCommit
DEBU[2024-07-03T04:48:57.627556344Z] stat snapshot                                 key="sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f"
DEBU[2024-07-03T04:48:57.627724510Z] prepare snapshot                              key="extract-627647955-TRAD sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f" parent="sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa"
DEBU[2024-07-03T04:48:57.627892110Z] prepare                                       key="firecracker-containerd/7/extract-627647955-TRAD sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f" parent="firecracker-containerd/6/sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa"
DEBU[2024-07-03T04:48:57.627929458Z] creating snapshot device 'fc-dev-thinpool-snap-4' from 'fc-dev-thinpool-snap-3' 
DEBU[2024-07-03T04:48:57.652379886Z] event published                               ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2024-07-03T04:48:57.656829264Z] diff applied                                  d=4.105352ms digest="sha256:0522d30cde10ac29ae2c555b9bde76c2b50aafc7ef7435bbc7e19de706bcadcd" media=application/vnd.docker.image.rootfs.diff.tar.gzip size=230
DEBU[2024-07-03T04:48:57.657008629Z] commit snapshot                               key="extract-627647955-TRAD sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f" name="sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f"
DEBU[2024-07-03T04:48:57.657091058Z] commit                                        key="firecracker-containerd/7/extract-627647955-TRAD sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f" name="firecracker-containerd/8/sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f"
DEBU[2024-07-03T04:48:57.691313899Z] event published                               ns=firecracker-containerd topic=/snapshot/commit type=containerd.events.SnapshotCommit
DEBU[2024-07-03T04:48:57.691919799Z] stat snapshot                                 key="sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270"
DEBU[2024-07-03T04:48:57.692099252Z] prepare snapshot                              key="extract-692024839-fE17 sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270" parent="sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f"
DEBU[2024-07-03T04:48:57.692294501Z] prepare                                       key="firecracker-containerd/9/extract-692024839-fE17 sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270" parent="firecracker-containerd/8/sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f"
DEBU[2024-07-03T04:48:57.692336924Z] creating snapshot device 'fc-dev-thinpool-snap-5' from 'fc-dev-thinpool-snap-4' 
DEBU[2024-07-03T04:48:57.715442825Z] event published                               ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2024-07-03T04:48:57.804738330Z] diff applied                                  d=89.146598ms digest="sha256:407da27a03363f6b9d368ec6e131f7f2db7c8cb2a149160d913d6f3698905a5d" media=application/vnd.docker.image.rootfs.diff.tar.gzip size=1887472
DEBU[2024-07-03T04:48:57.805029942Z] commit snapshot                               key="extract-692024839-fE17 sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270" name="sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270"
DEBU[2024-07-03T04:48:57.805111806Z] commit                                        key="firecracker-containerd/9/extract-692024839-fE17 sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270" name="firecracker-containerd/10/sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270"
DEBU[2024-07-03T04:48:57.841404563Z] event published                               ns=firecracker-containerd topic=/snapshot/commit type=containerd.events.SnapshotCommit
DEBU[2024-07-03T04:48:57.841917975Z] stat snapshot                                 key="sha256:6ed576b842619a8e58f9775692fe924004a09e40e6ee282c4507c015d2a0f184"
DEBU[2024-07-03T04:48:57.842066482Z] prepare snapshot                              key="extract-842008200-uwQH sha256:6ed576b842619a8e58f9775692fe924004a09e40e6ee282c4507c015d2a0f184" parent="sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270"
DEBU[2024-07-03T04:48:57.842208585Z] prepare                                       key="firecracker-containerd/11/extract-842008200-uwQH sha256:6ed576b842619a8e58f9775692fe924004a09e40e6ee282c4507c015d2a0f184" parent="firecracker-containerd/10/sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270"
DEBU[2024-07-03T04:48:57.842246782Z] creating snapshot device 'fc-dev-thinpool-snap-6' from 'fc-dev-thinpool-snap-5' 
DEBU[2024-07-03T04:48:57.861874068Z] event published                               ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2024-07-03T04:48:57.865953756Z] diff applied                                  d=3.908312ms digest="sha256:e2a79086342d3b977046e655782cd75e24a14160750c76daac9c4d2200589e9f" media=application/vnd.docker.image.rootfs.diff.tar.gzip size=2346
DEBU[2024-07-03T04:48:57.866186884Z] commit snapshot                               key="extract-842008200-uwQH sha256:6ed576b842619a8e58f9775692fe924004a09e40e6ee282c4507c015d2a0f184" name="sha256:6ed576b842619a8e58f9775692fe924004a09e40e6ee282c4507c015d2a0f184"
DEBU[2024-07-03T04:48:57.866282712Z] commit                                        key="firecracker-containerd/11/extract-842008200-uwQH sha256:6ed576b842619a8e58f9775692fe924004a09e40e6ee282c4507c015d2a0f184" name="firecracker-containerd/12/sha256:6ed576b842619a8e58f9775692fe924004a09e40e6ee282c4507c015d2a0f184"
DEBU[2024-07-03T04:48:57.899422845Z] event published                               ns=firecracker-containerd topic=/snapshot/commit type=containerd.events.SnapshotCommit
DEBU[2024-07-03T04:48:57.899889173Z] stat snapshot                                 key="sha256:7cdf6aac469074c7deb6131dd863c121a26b24e63eceb6a7db1ddf2aaaa57f2e"
DEBU[2024-07-03T04:48:57.900038232Z] prepare snapshot                              key="extract-899969989-0eLG sha256:7cdf6aac469074c7deb6131dd863c121a26b24e63eceb6a7db1ddf2aaaa57f2e" parent="sha256:6ed576b842619a8e58f9775692fe924004a09e40e6ee282c4507c015d2a0f184"
DEBU[2024-07-03T04:48:57.900226042Z] prepare                                       key="firecracker-containerd/13/extract-899969989-0eLG sha256:7cdf6aac469074c7deb6131dd863c121a26b24e63eceb6a7db1ddf2aaaa57f2e" parent="firecracker-containerd/12/sha256:6ed576b842619a8e58f9775692fe924004a09e40e6ee282c4507c015d2a0f184"
DEBU[2024-07-03T04:48:57.900268904Z] creating snapshot device 'fc-dev-thinpool-snap-7' from 'fc-dev-thinpool-snap-6' 
DEBU[2024-07-03T04:48:57.936896262Z] event published                               ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2024-07-03T04:48:57.943818523Z] diff applied                                  d=6.742024ms digest="sha256:137112f2985dc0bfe0e1fa772d8bffe9f5f5a3f26ba8fe6e0ce22145aeb15e00" media=application/vnd.docker.image.rootfs.diff.tar.gzip size=205929
DEBU[2024-07-03T04:48:57.943996474Z] commit snapshot                               key="extract-899969989-0eLG sha256:7cdf6aac469074c7deb6131dd863c121a26b24e63eceb6a7db1ddf2aaaa57f2e" name="sha256:7cdf6aac469074c7deb6131dd863c121a26b24e63eceb6a7db1ddf2aaaa57f2e"
DEBU[2024-07-03T04:48:57.944071828Z] commit                                        key="firecracker-containerd/13/extract-899969989-0eLG sha256:7cdf6aac469074c7deb6131dd863c121a26b24e63eceb6a7db1ddf2aaaa57f2e" name="firecracker-containerd/14/sha256:7cdf6aac469074c7deb6131dd863c121a26b24e63eceb6a7db1ddf2aaaa57f2e"
DEBU[2024-07-03T04:48:57.978697263Z] event published                               ns=firecracker-containerd topic=/snapshot/commit type=containerd.events.SnapshotCommit
DEBU[2024-07-03T04:48:57.979187322Z] stat snapshot                                 key="sha256:acb8bb772ae5cbe178f27fb9ceda983794edfb96aba9dce591792d9bb76fa6ee"
DEBU[2024-07-03T04:48:57.979319161Z] prepare snapshot                              key="extract-979266500-SYGF sha256:acb8bb772ae5cbe178f27fb9ceda983794edfb96aba9dce591792d9bb76fa6ee" parent="sha256:7cdf6aac469074c7deb6131dd863c121a26b24e63eceb6a7db1ddf2aaaa57f2e"
DEBU[2024-07-03T04:48:57.979459987Z] prepare                                       key="firecracker-containerd/15/extract-979266500-SYGF sha256:acb8bb772ae5cbe178f27fb9ceda983794edfb96aba9dce591792d9bb76fa6ee" parent="firecracker-containerd/14/sha256:7cdf6aac469074c7deb6131dd863c121a26b24e63eceb6a7db1ddf2aaaa57f2e"
DEBU[2024-07-03T04:48:57.979499463Z] creating snapshot device 'fc-dev-thinpool-snap-8' from 'fc-dev-thinpool-snap-7' 
DEBU[2024-07-03T04:48:58.005971023Z] event published                               ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2024-07-03T04:48:58.567832529Z] diff applied                                  d=561.713137ms digest="sha256:117c33855025f288345e517f4d3c0c3ae77d191a30e894544363cf54de85e9ff" media=application/vnd.docker.image.rootfs.diff.tar.gzip size=21842527
DEBU[2024-07-03T04:48:58.568162362Z] commit snapshot                               key="extract-979266500-SYGF sha256:acb8bb772ae5cbe178f27fb9ceda983794edfb96aba9dce591792d9bb76fa6ee" name="sha256:acb8bb772ae5cbe178f27fb9ceda983794edfb96aba9dce591792d9bb76fa6ee"
DEBU[2024-07-03T04:48:58.568243271Z] commit                                        key="firecracker-containerd/15/extract-979266500-SYGF sha256:acb8bb772ae5cbe178f27fb9ceda983794edfb96aba9dce591792d9bb76fa6ee" name="firecracker-containerd/16/sha256:acb8bb772ae5cbe178f27fb9ceda983794edfb96aba9dce591792d9bb76fa6ee"
DEBU[2024-07-03T04:48:58.597543500Z] event published                               ns=firecracker-containerd topic=/snapshot/commit type=containerd.events.SnapshotCommit
DEBU[2024-07-03T04:48:58.598141856Z] stat snapshot                                 key="sha256:731e6e142984882c5f15f3b4e94235a3436ef36b8d2b605d4dc03b96e5d3ae22"
DEBU[2024-07-03T04:48:58.598295275Z] prepare snapshot                              key="extract-598226360-Wtho sha256:731e6e142984882c5f15f3b4e94235a3436ef36b8d2b605d4dc03b96e5d3ae22" parent="sha256:acb8bb772ae5cbe178f27fb9ceda983794edfb96aba9dce591792d9bb76fa6ee"
DEBU[2024-07-03T04:48:58.598470039Z] prepare                                       key="firecracker-containerd/17/extract-598226360-Wtho sha256:731e6e142984882c5f15f3b4e94235a3436ef36b8d2b605d4dc03b96e5d3ae22" parent="firecracker-containerd/16/sha256:acb8bb772ae5cbe178f27fb9ceda983794edfb96aba9dce591792d9bb76fa6ee"
DEBU[2024-07-03T04:48:58.598520077Z] creating snapshot device 'fc-dev-thinpool-snap-9' from 'fc-dev-thinpool-snap-8' 
DEBU[2024-07-03T04:48:58.625386945Z] event published                               ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2024-07-03T04:48:58.660617329Z] diff applied                                  d=35.072833ms digest="sha256:5995ac165d0d2c499ba4fd36b906de6145f6889a30e5c6514d08e3f7ee0ccc95" media=application/vnd.docker.image.rootfs.diff.tar.gzip size=1033378
DEBU[2024-07-03T04:48:58.660897658Z] commit snapshot                               key="extract-598226360-Wtho sha256:731e6e142984882c5f15f3b4e94235a3436ef36b8d2b605d4dc03b96e5d3ae22" name="sha256:731e6e142984882c5f15f3b4e94235a3436ef36b8d2b605d4dc03b96e5d3ae22"
DEBU[2024-07-03T04:48:58.660989702Z] commit                                        key="firecracker-containerd/17/extract-598226360-Wtho sha256:731e6e142984882c5f15f3b4e94235a3436ef36b8d2b605d4dc03b96e5d3ae22" name="firecracker-containerd/18/sha256:731e6e142984882c5f15f3b4e94235a3436ef36b8d2b605d4dc03b96e5d3ae22"
DEBU[2024-07-03T04:48:58.699251123Z] event published                               ns=firecracker-containerd topic=/snapshot/commit type=containerd.events.SnapshotCommit
DEBU[2024-07-03T04:48:58.700125359Z] create image                                  name="ghcr.io/ease-lab/image_rotate:var_workload" target="sha256:d6043a1f17efb4c20f3bd635ed20ac9978c88fbbadece77c7ec6e9c00dd20eeb"
DEBU[2024-07-03T04:48:58.700337931Z] event published                               ns=firecracker-containerd topic=/images/create type=containerd.services.images.v1.ImageCreate
DEBU[2024-07-03T04:48:58.706484769Z] garbage collected                             d="158.407µs"
DEBU[2024-07-03T04:48:58.737142888Z] create VM request: VMID:"plr-fnc-0" MachineCfg:<MemSizeMib:256 VcpuCount:1 > KernelArgs:"ro noapic reboot=k panic=1 pci=off nomodules systemd.log_color=false systemd.unit=firecracker.target init=/sbin/overlay-init tsc=reliable quiet 8250.nr_uarts=0 ipv6.disable=1" NetworkInterfaces:<StaticConfig:<MacAddress:"02:FC:00:00:00:00" HostDevName:"plr-fnc-0_tap" IPConfig:<PrimaryAddr:"190.128.0.2/10" GatewayAddr:"190.128.0.1" Nameservers:"8.8.8.8" > > > TimeoutSeconds:100  
DEBU[2024-07-03T04:48:58.737159787Z] using namespace: firecracker-containerd      
DEBU[2024-07-03T04:48:58.737336673Z] starting containerd-shim-aws-firecracker      vmID=plr-fnc-0
INFO[2024-07-03T04:48:58.758017660Z] starting signal loop                          namespace=firecracker-containerd path=/var/lib/firecracker-containerd/shim-base/firecracker-containerd/plr-fnc-0 pid=135842
INFO[2024-07-03T04:48:58.758602451Z] creating new VM                               runtime=aws.firecracker vmID=plr-fnc-0
INFO[2024-07-03T04:48:58.758828787Z] Called startVMM(), setting up a VMM on firecracker.sock  runtime=aws.firecracker
INFO[2024-07-03T04:48:58.770709469Z] refreshMachineConfiguration: [GET /machine-config][200] getMachineConfigurationOK  &{CPUTemplate:T2 HtEnabled:0xc0003a0fe3 MemSizeMib:0xc0003a0fd8 TrackDirtyPages:false VcpuCount:0xc0003a0fd0}  runtime=aws.firecracker
INFO[2024-07-03T04:48:58.770818575Z] PutGuestBootSource: [PUT /boot-source][204] putGuestBootSourceNoContent   runtime=aws.firecracker
INFO[2024-07-03T04:48:58.770826167Z] Attaching drive /var/lib/firecracker-containerd/runtime/default-rootfs.img, slot root_drive, root true.  runtime=aws.firecracker
INFO[2024-07-03T04:48:58.771008268Z] Attached drive /var/lib/firecracker-containerd/runtime/default-rootfs.img: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent   runtime=aws.firecracker
INFO[2024-07-03T04:48:58.771022675Z] Attaching drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/plr-fnc-0/ctrstub0, slot MN2HE43UOVRDA, root false.  runtime=aws.firecracker
INFO[2024-07-03T04:48:58.771132264Z] Attached drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/plr-fnc-0/ctrstub0: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent   runtime=aws.firecracker
INFO[2024-07-03T04:48:58.771147236Z] Attaching NIC plr-fnc-0_tap (hwaddr 02:FC:00:00:00:00) at index 1  runtime=aws.firecracker
INFO[2024-07-03T04:48:58.795256604Z] startInstance successful: [PUT /actions][204] createSyncActionNoContent   runtime=aws.firecracker
INFO[2024-07-03T04:48:58.795272033Z] calling agent                                 runtime=aws.firecracker vmID=plr-fnc-0
INFO[2024-07-03T04:48:59.395664551Z] successfully started the VM                   runtime=aws.firecracker vmID=plr-fnc-0
DEBU[2024-07-03T04:48:59.395935489Z] event forwarded                               ns=firecracker-containerd topic=/firecracker-vm/start type=VMStart
DEBU[2024-07-03T04:48:59.397853369Z] prepare snapshot                              key=plr-fnc-0 parent="sha256:731e6e142984882c5f15f3b4e94235a3436ef36b8d2b605d4dc03b96e5d3ae22"
DEBU[2024-07-03T04:48:59.398064453Z] prepare                                       key=firecracker-containerd/19/plr-fnc-0 parent="firecracker-containerd/18/sha256:731e6e142984882c5f15f3b4e94235a3436ef36b8d2b605d4dc03b96e5d3ae22"
DEBU[2024-07-03T04:48:59.398115211Z] creating snapshot device 'fc-dev-thinpool-snap-10' from 'fc-dev-thinpool-snap-9' 
DEBU[2024-07-03T04:48:59.431942950Z] event published                               ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2024-07-03T04:48:59.433247717Z] get snapshot mounts                           key=plr-fnc-0
DEBU[2024-07-03T04:48:59.433275736Z] mounts                                        key=firecracker-containerd/19/plr-fnc-0
DEBU[2024-07-03T04:48:59.437438609Z] event published                               ns=firecracker-containerd topic=/containers/create type=containerd.events.ContainerCreate
DEBU[2024-07-03T04:48:59.438091872Z] get snapshot mounts                           key=plr-fnc-0
DEBU[2024-07-03T04:48:59.438111810Z] mounts                                        key=firecracker-containerd/19/plr-fnc-0
DEBU[2024-07-03T04:48:59.439477130Z] garbage collected                             d="197.047µs"
time="2024-07-03T04:48:59.457166322Z" level=debug msg=StartShim runtime=aws.firecracker task_id=plr-fnc-0
DEBU[2024-07-03T04:48:59.457748180Z] create VM request: VMID:"plr-fnc-0"          
DEBU[2024-07-03T04:48:59.457767293Z] using namespace: firecracker-containerd      
time="2024-07-03T04:48:59.457983532Z" level=info msg="successfully started shim (git commit: 4a8adae2660e3db2ea9b5b7b057b4388b9f5bab8)." runtime=aws.firecracker task_id=plr-fnc-0 vmID=plr-fnc-0
INFO[2024-07-03T04:48:59.459089446Z] PatchGuestDrive successful                    runtime=aws.firecracker
DEBU[2024-07-03T04:48:59.545823767Z] event forwarded                               ns=firecracker-containerd topic=/tasks/create type=containerd.events.TaskCreate
INFO[2024-07-03T04:48:59.572697067Z] successfully created task                     ExecID= TaskID=plr-fnc-0 pid_in_vm=719 runtime=aws.firecracker vmID=plr-fnc-0
DEBU[2024-07-03T04:48:59.577213019Z] event forwarded                               ns=firecracker-containerd topic=/tasks/start type=containerd.events.TaskStart
DEBU[2024-07-03T04:48:59.978735022Z] pause VM request: VMID:"plr-fnc-0"           
DEBU[2024-07-03T04:48:59.979617292Z] create snapshot request: VMID:"plr-fnc-0" SnapshotFilePath:"/fccd/snapshots/plr-fnc-0/snap_file" MemFilePath:"/fccd/snapshots/plr-fnc-0/mem_file"  
DEBU[2024-07-03T04:49:00.257518068Z] resume VM request: VMID:"plr-fnc-0"          
DEBU[2024-07-03T04:49:00.306568564Z] create VM request: VMID:"0-0" MachineCfg:<MemSizeMib:256 VcpuCount:1 > KernelArgs:"ro noapic reboot=k panic=1 pci=off nomodules systemd.log_color=false systemd.unit=firecracker.target init=/sbin/overlay-init tsc=reliable quiet 8250.nr_uarts=0 ipv6.disable=1" NetworkInterfaces:<StaticConfig:<MacAddress:"02:FC:00:00:00:01" HostDevName:"0-0_tap" IPConfig:<PrimaryAddr:"190.128.0.3/10" GatewayAddr:"190.128.0.1" Nameservers:"8.8.8.8" > > > TimeoutSeconds:100  
DEBU[2024-07-03T04:49:00.306595164Z] using namespace: firecracker-containerd      
DEBU[2024-07-03T04:49:00.306784064Z] starting containerd-shim-aws-firecracker      vmID=0-0
INFO[2024-07-03T04:49:00.328011941Z] starting signal loop                          namespace=firecracker-containerd path=/var/lib/firecracker-containerd/shim-base/firecracker-containerd/0-0 pid=135937
INFO[2024-07-03T04:49:00.328208730Z] creating new VM                               runtime=aws.firecracker vmID=0-0
INFO[2024-07-03T04:49:00.328428648Z] Called startVMM(), setting up a VMM on firecracker.sock  runtime=aws.firecracker
INFO[2024-07-03T04:49:00.339354639Z] refreshMachineConfiguration: [GET /machine-config][200] getMachineConfigurationOK  &{CPUTemplate:T2 HtEnabled:0xc000400f33 MemSizeMib:0xc000400f18 TrackDirtyPages:false VcpuCount:0xc000400f10}  runtime=aws.firecracker
INFO[2024-07-03T04:49:00.339453946Z] PutGuestBootSource: [PUT /boot-source][204] putGuestBootSourceNoContent   runtime=aws.firecracker
INFO[2024-07-03T04:49:00.339462813Z] Attaching drive /var/lib/firecracker-containerd/runtime/default-rootfs.img, slot root_drive, root true.  runtime=aws.firecracker
INFO[2024-07-03T04:49:00.339603518Z] Attached drive /var/lib/firecracker-containerd/runtime/default-rootfs.img: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent   runtime=aws.firecracker
INFO[2024-07-03T04:49:00.339609964Z] Attaching drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/0-0/ctrstub0, slot MN2HE43UOVRDA, root false.  runtime=aws.firecracker
INFO[2024-07-03T04:49:00.339688444Z] Attached drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/0-0/ctrstub0: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent   runtime=aws.firecracker
INFO[2024-07-03T04:49:00.339694068Z] Attaching NIC 0-0_tap (hwaddr 02:FC:00:00:00:01) at index 1  runtime=aws.firecracker
INFO[2024-07-03T04:49:00.368595414Z] startInstance successful: [PUT /actions][204] createSyncActionNoContent   runtime=aws.firecracker
INFO[2024-07-03T04:49:00.368605931Z] calling agent                                 runtime=aws.firecracker vmID=0-0
INFO[2024-07-03T04:49:00.968878960Z] successfully started the VM                   runtime=aws.firecracker vmID=0-0
DEBU[2024-07-03T04:49:00.969172083Z] event forwarded                               ns=firecracker-containerd topic=/firecracker-vm/start type=VMStart
DEBU[2024-07-03T04:49:00.970701051Z] prepare snapshot                              key=0-0 parent="sha256:731e6e142984882c5f15f3b4e94235a3436ef36b8d2b605d4dc03b96e5d3ae22"
DEBU[2024-07-03T04:49:00.970883297Z] prepare                                       key=firecracker-containerd/20/0-0 parent="firecracker-containerd/18/sha256:731e6e142984882c5f15f3b4e94235a3436ef36b8d2b605d4dc03b96e5d3ae22"
DEBU[2024-07-03T04:49:00.970932347Z] creating snapshot device 'fc-dev-thinpool-snap-11' from 'fc-dev-thinpool-snap-9' 
DEBU[2024-07-03T04:49:01.016250098Z] event published                               ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2024-07-03T04:49:01.017457186Z] get snapshot mounts                           key=0-0
DEBU[2024-07-03T04:49:01.017485698Z] mounts                                        key=firecracker-containerd/20/0-0
DEBU[2024-07-03T04:49:01.021418923Z] event published                               ns=firecracker-containerd topic=/containers/create type=containerd.events.ContainerCreate
DEBU[2024-07-03T04:49:01.022837109Z] get snapshot mounts                           key=0-0
DEBU[2024-07-03T04:49:01.022875395Z] mounts                                        key=firecracker-containerd/20/0-0
DEBU[2024-07-03T04:49:01.025111528Z] garbage collected                             d="229.525µs"
time="2024-07-03T04:49:01.043387041Z" level=debug msg=StartShim runtime=aws.firecracker task_id=0-0
DEBU[2024-07-03T04:49:01.044033490Z] create VM request: VMID:"0-0"                
DEBU[2024-07-03T04:49:01.044045913Z] using namespace: firecracker-containerd      
time="2024-07-03T04:49:01.044213370Z" level=info msg="successfully started shim (git commit: 4a8adae2660e3db2ea9b5b7b057b4388b9f5bab8)." runtime=aws.firecracker task_id=0-0 vmID=0-0
INFO[2024-07-03T04:49:01.045254764Z] PatchGuestDrive successful                    runtime=aws.firecracker
DEBU[2024-07-03T04:49:01.131543095Z] event forwarded                               ns=firecracker-containerd topic=/tasks/create type=containerd.events.TaskCreate
INFO[2024-07-03T04:49:01.160760193Z] successfully created task                     ExecID= TaskID=0-0 pid_in_vm=718 runtime=aws.firecracker vmID=0-0
DEBU[2024-07-03T04:49:01.164877719Z] event forwarded                               ns=firecracker-containerd topic=/tasks/start type=containerd.events.TaskStart
DEBU[2024-07-03T04:49:01.569927511Z] pause VM request: VMID:"0-0"                 
DEBU[2024-07-03T04:49:01.570655477Z] create snapshot request: VMID:"0-0" SnapshotFilePath:"/fccd/snapshots/0-0/snap_file" MemFilePath:"/fccd/snapshots/0-0/mem_file"  
DEBU[2024-07-03T04:49:01.849541824Z] resume VM request: VMID:"0-0"                
DEBU[2024-07-03T04:49:01.850143189Z] offload request: VMID:"0-0"                  
ERRO[2024-07-03T04:49:01.858890895Z] error while forwarding events from VM agent   error="ttrpc: closed" runtime=aws.firecracker vmID=0-0
ERRO[2024-07-03T04:49:01.858904791Z] error waiting for exit                        ExecID= TaskID=0-0 error="ttrpc: closed" runtime=aws.firecracker vmID=0-0
ERRO[2024-07-03T04:49:01.859007768Z] error copying io                              ExecID= TaskID=0-0 error="reading from a closed fifo" runtime=aws.firecracker stream=stdin vmID=0-0
ERRO[2024-07-03T04:49:01.859053384Z] error closing io stream                       ExecID= TaskID=0-0 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stdin vmID=0-0
DEBU[2024-07-03T04:49:01.878637600Z] load snapshot request: VMID:"0-0" SnapshotFilePath:"/fccd/snapshots/0-0/snap_file" MemFilePath:"/fccd/snapshots/0-0/mem_file" EnableUserPF:true  
WARN[2024-07-03T04:49:01.891258780Z] firecracker exited: signal: killed            runtime=aws.firecracker
ERRO[2024-07-03T04:49:01.965593687Z] Failed to send load snapshot request          error="Put \"http+unix://firecracker/snapshot/load\": EOF" runtime=aws.firecracker vmID=0-0
ERRO[2024-07-03T04:49:01.965674934Z]                                               error="rpc error: code = Unknown desc = Put \"http+unix://firecracker/snapshot/load\": EOF"
ERRO[2024-07-03T04:49:06.859119142Z] error closing io stream                       ExecID= TaskID=0-0 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stdout vmID=0-0
ERRO[2024-07-03T04:49:06.859165065Z] error closing io stream                       ExecID= TaskID=0-0 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stderr vmID=0-0

[ustiugov]

hi @sviho, this is an I/O timeout error. Are you running REAP on an SSD or HDD? could you provide the details of your platform?
also, if your goal is to just reproduce, it is better to use our artifact: https://zenodo.org/records/4545584