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.

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

Remote snapshotter example fails on docker image with failed to mount <...>: no such file or directory: unknown error #761

Open
CuriousGeorgiy opened this issue Aug 28, 2023 · 2 comments

Comments

@CuriousGeorgiy
Copy link

CuriousGeorgiy commented Aug 28, 2023

I followed the remote snapshotter getting starting guide for the instance setup (I am using the latest firecracker version) and the instructions from the remote snapshotter example README, but when I launch the example with my public image, it fails with the following error:

glebedev@node-0:~/firecracker-containerd/examples/cmd/remote-snapshotter$ sudo ./remote-snapshotter docker.io/curiousgeorgiy/nginx:1.17-alpine-esgz
Docker username: <...>
Docker password: <...>
Creating VM
Setting docker credential metadata
Pulling the image
failed to extract layer sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61: failed to mount /var/lib/firecracker-containerd/containerd/tmpmounts/containerd-mount2395756787: no such file or directory: unknown
panic: protobuf tag not enough fields in Status.state:

goroutine 53 [running]:
github.com/gogo/protobuf/proto.(*unmarshalInfo).computeUnmarshalInfo(0xc0000f81e0)
	/users/glebedev/go/pkg/mod/github.com/gogo/[email protected]/proto/table_unmarshal.go:341 +0x138a
github.com/gogo/protobuf/proto.(*unmarshalInfo).unmarshal(0xc0000f81e0, {0xc0005d4b40?}, {0xc0002ca1e2, 0x20, 0x20})
	/users/glebedev/go/pkg/mod/github.com/gogo/[email protected]/proto/table_unmarshal.go:138 +0x67
github.com/gogo/protobuf/proto.makeUnmarshalMessagePtr.func1({0xc0002ca1e1, 0x21, 0x21}, {0xc0000c0be0?}, 0x7207f3?)
	/users/glebedev/go/pkg/mod/github.com/gogo/[email protected]/proto/table_unmarshal.go:1826 +0x151
github.com/gogo/protobuf/proto.(*unmarshalInfo).unmarshal(0xc0000f8140, {0xee27c0?}, {0xc0002ca1e0?, 0xc0000c0da0?, 0x716d07?})
	/users/glebedev/go/pkg/mod/github.com/gogo/[email protected]/proto/table_unmarshal.go:175 +0x35f
github.com/gogo/protobuf/proto.(*InternalMessageInfo).Unmarshal(0xc0003644c0?, {0x10a1c88, 0xc000364460}, {0xc0002ca1e0?, 0x22?, 0x22?})
	/users/glebedev/go/pkg/mod/github.com/gogo/[email protected]/proto/table_unmarshal.go:63 +0xd0
github.com/gogo/protobuf/proto.(*Buffer).Unmarshal(0xc0002a9e18, {0x10a1c88, 0xc000364460})
	/users/glebedev/go/pkg/mod/github.com/gogo/[email protected]/proto/decode.go:424 +0x153
github.com/gogo/protobuf/proto.Unmarshal({0xc0002ca1e0, 0x22, 0x22}, {0x10a1c88, 0xc000364460})
	/users/glebedev/go/pkg/mod/github.com/gogo/[email protected]/proto/decode.go:342 +0xe6
github.com/containerd/ttrpc.(*Client).recv(0xc00049a0e0?, 0x0?, 0x0?)
	/users/glebedev/go/pkg/mod/github.com/containerd/[email protected]/client.go:378 +0xf5
github.com/containerd/ttrpc.(*Client).run.func2()
	/users/glebedev/go/pkg/mod/github.com/containerd/[email protected]/client.go:318 +0x24b
created by github.com/containerd/ttrpc.(*Client).run
	/users/glebedev/go/pkg/mod/github.com/containerd/[email protected]/client.go:286 +0x17b```

The following errors appear in the firecracker-containerd logs:

glebedev@node-0:~$ sudo /usr/local/bin/firecracker-containerd --config /etc/firecracker-containerd/config.toml
WARN[0000] containerd config version `1` has been deprecated and will be removed in containerd v2.0, please switch to version `2`, see https://github.com/containerd/containerd/blob/main/docs/PLUGINS.md#version-header
INFO[2023-08-28T08:28:53.444296225-04:00] starting containerd                           revision=5e898e2012a5bed61d57a01393494e62b2dc5675 version=1.6.20+unknown
INFO[2023-08-28T08:28:53.464251852-04:00] loading plugin "io.containerd.content.v1.content"...  type=io.containerd.content.v1
INFO[2023-08-28T08:28:53.464390456-04:00] loading plugin "io.containerd.snapshotter.v1.devmapper"...  type=io.containerd.snapshotter.v1
INFO[2023-08-28T08:28:53.464454256-04:00] initializing pool device "fc-dev-thinpool"
INFO[2023-08-28T08:28:53.465914790-04:00] using dmsetup:
Library version:   1.02.167 (2019-11-30)
Driver version:    4.41.0
INFO[2023-08-28T08:28:53.469370701-04:00] loading plugin "io.containerd.snapshotter.v1.overlayfs"...  type=io.containerd.snapshotter.v1
INFO[2023-08-28T08:28:53.469736074-04:00] loading plugin "io.containerd.snapshotter.v1.proxy"...  type=io.containerd.snapshotter.v1
INFO[2023-08-28T08:28:53.469873153-04:00] loading plugin "io.containerd.metadata.v1.bolt"...  type=io.containerd.metadata.v1
INFO[2023-08-28T08:28:53.469953228-04:00] metadata content store policy set             policy=shared
INFO[2023-08-28T08:28:53.470872585-04:00] loading plugin "io.containerd.differ.v1.walking"...  type=io.containerd.differ.v1
INFO[2023-08-28T08:28:53.470907626-04:00] loading plugin "io.containerd.event.v1.exchange"...  type=io.containerd.event.v1
INFO[2023-08-28T08:28:53.470929973-04:00] loading plugin "io.containerd.gc.v1.scheduler"...  type=io.containerd.gc.v1
INFO[2023-08-28T08:28:53.470976721-04:00] loading plugin "io.containerd.service.v1.introspection-service"...  type=io.containerd.service.v1
INFO[2023-08-28T08:28:53.471005780-04:00] loading plugin "io.containerd.service.v1.containers-service"...  type=io.containerd.service.v1
INFO[2023-08-28T08:28:53.471033362-04:00] loading plugin "io.containerd.service.v1.content-service"...  type=io.containerd.service.v1
INFO[2023-08-28T08:28:53.471067354-04:00] loading plugin "io.containerd.service.v1.diff-service"...  type=io.containerd.service.v1
INFO[2023-08-28T08:28:53.471092876-04:00] loading plugin "io.containerd.service.v1.images-service"...  type=io.containerd.service.v1
INFO[2023-08-28T08:28:53.471113996-04:00] loading plugin "io.containerd.service.v1.leases-service"...  type=io.containerd.service.v1
INFO[2023-08-28T08:28:53.471134871-04:00] loading plugin "io.containerd.service.v1.namespaces-service"...  type=io.containerd.service.v1
INFO[2023-08-28T08:28:53.471155034-04:00] loading plugin "io.containerd.service.v1.snapshots-service"...  type=io.containerd.service.v1
INFO[2023-08-28T08:28:53.471174960-04:00] loading plugin "io.containerd.runtime.v1.linux"...  type=io.containerd.runtime.v1
INFO[2023-08-28T08:28:53.471292351-04:00] loading plugin "io.containerd.runtime.v2.task"...  type=io.containerd.runtime.v2
INFO[2023-08-28T08:28:53.471395051-04:00] loading plugin "io.containerd.monitor.v1.cgroups"...  type=io.containerd.monitor.v1
INFO[2023-08-28T08:28:53.471970942-04:00] loading plugin "io.containerd.service.v1.tasks-service"...  type=io.containerd.service.v1
DEBU[2023-08-28T08:28:53.472024969-04:00] No RDT config file specified, RDT not configured
INFO[2023-08-28T08:28:53.472052579-04:00] loading plugin "io.containerd.service.v1.fc-control"...  type=io.containerd.service.v1
DEBU[2023-08-28T08:28:53.472077547-04:00] initializing fc-control plugin (root: "/var/lib/firecracker-containerd/containerd/io.containerd.service.v1.fc-control")
INFO[2023-08-28T08:28:53.492619048-04:00] loading plugin "io.containerd.grpc.v1.introspection"...  type=io.containerd.grpc.v1
INFO[2023-08-28T08:28:53.492686055-04:00] loading plugin "io.containerd.internal.v1.restart"...  type=io.containerd.internal.v1
INFO[2023-08-28T08:28:53.492811272-04:00] loading plugin "io.containerd.grpc.v1.containers"...  type=io.containerd.grpc.v1
INFO[2023-08-28T08:28:53.492853989-04:00] loading plugin "io.containerd.grpc.v1.content"...  type=io.containerd.grpc.v1
INFO[2023-08-28T08:28:53.492893959-04:00] loading plugin "io.containerd.grpc.v1.diff"...  type=io.containerd.grpc.v1
INFO[2023-08-28T08:28:53.492941235-04:00] loading plugin "io.containerd.grpc.v1.events"...  type=io.containerd.grpc.v1
INFO[2023-08-28T08:28:53.492984452-04:00] loading plugin "io.containerd.grpc.v1.healthcheck"...  type=io.containerd.grpc.v1
INFO[2023-08-28T08:28:53.493014209-04:00] loading plugin "io.containerd.grpc.v1.images"...  type=io.containerd.grpc.v1
INFO[2023-08-28T08:28:53.493039642-04:00] loading plugin "io.containerd.grpc.v1.leases"...  type=io.containerd.grpc.v1
INFO[2023-08-28T08:28:53.493067838-04:00] loading plugin "io.containerd.grpc.v1.namespaces"...  type=io.containerd.grpc.v1
INFO[2023-08-28T08:28:53.493100580-04:00] loading plugin "io.containerd.internal.v1.opt"...  type=io.containerd.internal.v1
INFO[2023-08-28T08:28:53.493172804-04:00] loading plugin "io.containerd.grpc.v1.snapshots"...  type=io.containerd.grpc.v1
INFO[2023-08-28T08:28:53.493206245-04:00] loading plugin "io.containerd.grpc.v1.tasks"...  type=io.containerd.grpc.v1
INFO[2023-08-28T08:28:53.493232074-04:00] loading plugin "io.containerd.grpc.v1.version"...  type=io.containerd.grpc.v1
INFO[2023-08-28T08:28:53.493259028-04:00] loading plugin "io.containerd.grpc.v1.fc-control-service"...  type=io.containerd.grpc.v1
DEBU[2023-08-28T08:28:53.493278895-04:00] initializing fc-control-service plugin
INFO[2023-08-28T08:28:53.493519626-04:00] serving...                                    address=/run/firecracker-containerd/containerd.sock.ttrpc
INFO[2023-08-28T08:28:53.493601995-04:00] serving...                                    address=/run/firecracker-containerd/containerd.sock
DEBU[2023-08-28T08:28:53.493633454-04:00] sd notification                               error="<nil>" notified=false state="READY=1"
INFO[2023-08-28T08:28:53.493673215-04:00] containerd successfully booted in 0.050202s
DEBU[2023-08-28T08:28:53.572099685-04:00] garbage collected                             d="380.025µs"
DEBU[2023-08-28T08:29:04.716139133-04:00] create VM request: VMID:"vm1" NetworkInterfaces:<AllowMMDS:true CNIConfig:<NetworkName:"fcnet" InterfaceName:"veth0" > >
DEBU[2023-08-28T08:29:04.716215109-04:00] using namespace: vm1
DEBU[2023-08-28T08:29:04.716833137-04:00] starting containerd-shim-aws-firecracker      vmID=vm1
INFO[2023-08-28T08:29:04.760720612-04:00] loading plugin "io.containerd.service.v1.introspection-service"...  runtime=aws.firecracker type=io.containerd.service.v1
INFO[2023-08-28T08:29:04.760856223-04:00] loading plugin "io.containerd.grpc.v1.introspection"...  runtime=aws.firecracker type=io.containerd.grpc.v1
INFO[2023-08-28T08:29:04.760892162-04:00] loading plugin "io.containerd.event.v1.publisher"...  runtime=aws.firecracker type=io.containerd.event.v1
INFO[2023-08-28T08:29:04.760934186-04:00] loading plugin "io.containerd.ttrpc.v1.task"...  runtime=aws.firecracker type=io.containerd.ttrpc.v1
DEBU[2023-08-28T08:29:04.760963874-04:00] registering ttrpc service                     id=io.containerd.ttrpc.v1.task
INFO[2023-08-28T08:29:04.760986115-04:00] loading plugin "io.containerd.internal.v1.shutdown"...  runtime=aws.firecracker type=io.containerd.internal.v1
DEBU[2023-08-28T08:29:04.761145062-04:00] serving api on socket                         socket="[inherited from parent]"
INFO[2023-08-28T08:29:04.761193492-04:00] starting signal loop                          namespace=vm1 path="/var/lib/firecracker-containerd/shim-base/vm1#vm1" pid=207515 runtime=aws.firecracker
INFO[2023-08-28T08:29:04.761203721-04:00] creating new VM                               runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:04.761302915-04:00] noop operation returning shim dir for JailPath  jailer=noop runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:04.761386271-04:00] using socket path: firecracker.sock           runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:04.761419662-04:00] noop operation returning shim dir for JailPath  jailer=noop runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:04.761524841-04:00] noop operation for StubDrivesOptions          jailer=noop runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:04.761574235-04:00] noop operation returning shim dir for JailPath  jailer=noop runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:04.761643376-04:00] noop operation for BuildJailedMachine         jailer=noop runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:04.761664428-04:00] No balloon device is setup                    runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:04.761775942-04:00] Called NewMachine()                           runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.761796987-04:00] Called Machine.Start()                        runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.761811756-04:00] Marking Machine as Started                    runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.761828201-04:00] Running handler validate.NetworkCfg           runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.761852715-04:00] Running handler validate.Cfg                  runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.761886111-04:00] Running handler fcinit.SetupNetwork           runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.926461964-04:00] Running handler fcinit.SetupKernelArgs        runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.926602798-04:00] Running handler fcinit.StartVMM               runtime=aws.firecracker
INFO[2023-08-28T08:29:04.926647405-04:00] Called startVMM(), setting up a VMM on firecracker.sock  runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.926712530-04:00] Starting [/usr/local/bin/firecracker --api-sock firecracker.sock --id vm1]  runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.927686013-04:00] VMM started socket path is firecracker.sock   runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.928216366-04:00] Setting up signal handler: [interrupt quit terminated hangup aborted]  runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.939560882-04:00] returning from startVMM()                     runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.939603062-04:00] Running handler fcinit.CreateLogFilesHandler  runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.939713193-04:00] Created metrics and logging fifos.            runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.939737361-04:00] Running handler fcinit.BootstrapLogging       runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.940389610-04:00] Configured VMM logging to /var/lib/firecracker-containerd/shim-base/vm1#vm1/fc-logs.fifo  runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.940947655-04:00] Configured VMM metrics to /var/lib/firecracker-containerd/shim-base/vm1#vm1/fc-metrics.fifo  runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.940982317-04:00] setup logging: success                        runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.941000064-04:00] Running handler fcinit.CreateMachine          runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.941390156-04:00] PutMachineConfiguration returned              runtime=aws.firecracker
INFO[2023-08-28T08:29:04.941749482-04:00] refreshMachineConfiguration: [GET /machine-config][200] getMachineConfigurationOK  &{CPUTemplate:T2 MemSizeMib:0xc0001ec8f8 Smt:0xc0001ec903 TrackDirtyPages:0xc0001ec906 VcpuCount:0xc0001ec8f0}  runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.941792160-04:00] createMachine returning                       runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.941815302-04:00] Running handler fcinit.CreateBootSource       runtime=aws.firecracker
INFO[2023-08-28T08:29:04.942364919-04:00] PutGuestBootSource: [PUT /boot-source][204] putGuestBootSourceNoContent   runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.942407016-04:00] Running handler fcinit.AttachDrives           runtime=aws.firecracker
INFO[2023-08-28T08:29:04.942427654-04:00] Attaching drive /var/lib/firecracker-containerd/runtime/default-rootfs.img, slot root_drive, root true.  runtime=aws.firecracker
INFO[2023-08-28T08:29:04.943194172-04:00] Attached drive /var/lib/firecracker-containerd/runtime/default-rootfs.img: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent   runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.943233026-04:00] attachDrive returned for /var/lib/firecracker-containerd/runtime/default-rootfs.img  runtime=aws.firecracker
INFO[2023-08-28T08:29:04.943252712-04:00] Attaching drive /var/lib/firecracker-containerd/shim-base/vm1#vm1/ctrstub0, slot MN2HE43UOVRDA, root false.  runtime=aws.firecracker
INFO[2023-08-28T08:29:04.943819644-04:00] Attached drive /var/lib/firecracker-containerd/shim-base/vm1#vm1/ctrstub0: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent   runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.943870694-04:00] attachDrive returned for /var/lib/firecracker-containerd/shim-base/vm1#vm1/ctrstub0  runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.943893700-04:00] Running handler fcinit.CreateNetworkInterfaces  runtime=aws.firecracker
INFO[2023-08-28T08:29:04.943913976-04:00] Attaching NIC tap0 (hwaddr 8a:18:27:6f:0d:06) at index 1  runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.945043328-04:00] PutGuestNetworkInterfaceByID: [PUT /network-interfaces/{iface_id}][204] putGuestNetworkInterfaceByIdNoContent   runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.945084057-04:00] createNetworkInterface returned for tap0      runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.945102900-04:00] Running handler fcinit.AddVsocks              runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.945774323-04:00] Attach vsock firecracker.vsock successful: [PUT /vsock][204] putGuestVsockNoContent   runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.945815468-04:00] Running handler fcinit.ConfigMmds             runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.946370016-04:00] SetMmdsConfig successful                      runtime=aws.firecracker
DEBU[2023-08-28T08:29:04.946411921-04:00] Running handler firecracker-containerd-jail-pid-handler  runtime=aws.firecracker
INFO[2023-08-28T08:29:04.976415808-04:00] startInstance successful: [PUT /actions][204] createSyncActionNoContent   runtime=aws.firecracker
INFO[2023-08-28T08:29:04.976452729-04:00] calling agent                                 runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:04.996155844-04:00] [    0.000000] Linux version 5.10.192 (@d4b5b0f861f9) (gcc (Ubuntu 11.3.0-1ubuntu1~22.04.1) 11.3.0, GNU ld (GNU Binutils for Ubuntu) 2.38) #1 SMP Mon Aug 28 08:55:20 UTC 2023  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.001187337-04:00] [    0.000000] Command line: systemd.journald.forward_to_console systemd.unit=firecracker.target console=ttyS0 pci=off panic=1 nomodules ro init=/sbin/overlay-init ip=192.168.1.2::192.168.1.1:255.255.255.0:::off:198.22.255.3:: noapic reboot=k root=/dev/vda ro virtio_mmio.device=4K@0xd0000000:5 virtio_mmio.device=4K@0xd0001000:6 virtio_mmio.device=4K@0xd0002000:7 virtio_mmio.device=4K@0xd0003000:8  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.001840792-04:00] [    0.000000] BIOS-provided physical RAM map:  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.002857947-04:00] [    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.003924575-04:00] [    0.000000] BIOS-e820: [mem 0x0000000000100000-0x0000000007ffffff] usable  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.004695783-04:00] [    0.000000] NX (Execute Disable) protection: active  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.005281012-04:00] [    0.000000] DMI not present or invalid.    jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.005845711-04:00] [    0.000000] Hypervisor detected: KVM       jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.006648219-04:00] [    0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.007510093-04:00] [    0.000000] kvm-clock: cpu 0, msr 2c01001, primary cpu clock  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.008385107-04:00] [    0.000001] kvm-clock: using sched offset of 9905184 cycles  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.009924727-04:00] [    0.000016] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.010636090-04:00] [    0.000034] tsc: Detected 2199.998 MHz processor  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.011453674-04:00] [    0.000325] last_pfn = 0x8000 max_arch_pfn = 0x400000000  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.011815498-04:00] [    0.000421] Disabled                       jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.012765965-04:00] [    0.000428] x86/PAT: MTRRs disabled, skipping PAT initialization too.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.013538030-04:00] [    0.000456] CPU MTRRs all blank - virtualized system.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.014614895-04:00] [    0.000480] x86/PAT: Configuration [0-7]: WB  WT  UC- UC  WB  WT  UC- UC    jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.015498023-04:00] [    0.000566] found SMP MP-table at [mem 0x0009fc00-0x0009fc0f]  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.016382212-04:00] [    0.000659] check: Scanning 1 areas for low memory corruption  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.017241186-04:00] [    0.000876] ACPI: Early table checksum verification disabled  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.018409335-04:00] [    0.001024] ACPI BIOS Error (bug): A valid RSDP was not found (20200925/tbxfroot-210)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.019012386-04:00] [    0.001096] No NUMA configuration found    jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.020067008-04:00] [    0.001098] Faking a node at [mem 0x0000000000000000-0x0000000007ffffff]  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.020945475-04:00] [    0.001117] NODE_DATA(0) allocated [mem 0x07fde000-0x07ffffff]  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.021368850-04:00] [    0.001414] Zone ranges:                   jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.022308208-04:00] [    0.001419]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.023264491-04:00] [    0.001422]   DMA32    [mem 0x0000000001000000-0x0000000007ffffff]  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.023724687-04:00] [    0.001424]   Normal   empty               jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.024374129-04:00] [    0.001426] Movable zone start for each node  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.024937362-04:00] [    0.001431] Early memory node ranges       jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.025884259-04:00] [    0.001433]   node   0: [mem 0x0000000000001000-0x000000000009efff]  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.026831795-04:00] [    0.001435]   node   0: [mem 0x0000000000100000-0x0000000007ffffff]  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.027919962-04:00] [    0.001441] Initmem setup node 0 [mem 0x0000000000001000-0x0000000007ffffff]  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.028810317-04:00] [    0.001475] On node 0, zone DMA: 1 pages in unavailable ranges  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.029727654-04:00] [    0.001809] On node 0, zone DMA: 97 pages in unavailable ranges  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.030462832-04:00] [    0.004330] Intel MultiProcessor Specification v1.4  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.031030921-04:00] [    0.004338] MPTABLE: OEM ID: FC            jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.031741648-04:00] [    0.004340] MPTABLE: Product ID: 000000000000  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.032358882-04:00] [    0.004342] MPTABLE: APIC at: 0xFEE00000   jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.032930254-04:00] [    0.004362] Processor #0 (Bootup-CPU)      jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.033979163-04:00] [    0.004476] IOAPIC[0]: apic_id 2, version 17, address 0xfec00000, GSI 0-23  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.034405997-04:00] [    0.004481] Processors: 1                  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.035026092-04:00] [    0.004490] TSC deadline timer available   jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.035804394-04:00] [    0.004493] smpboot: Allowing 1 CPUs, 0 hotplug CPUs  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.036554254-04:00] [    0.004520] kvm-guest: KVM setup pv remote TLB flush  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.037201909-04:00] [    0.004537] kvm-guest: setup PV sched yield  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.038336482-04:00] [    0.004571] PM: hibernation: Registered nosave memory: [mem 0x00000000-0x00000fff]  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.039459918-04:00] [    0.004575] PM: hibernation: Registered nosave memory: [mem 0x0009f000-0x000fffff]  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.040399506-04:00] [    0.004578] [mem 0x08000000-0xffffffff] available for PCI devices  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.041128597-04:00] [    0.004580] Booting paravirtualized kernel on KVM  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.042756177-04:00] [    0.004584] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.043934778-04:00] [    0.004595] setup_percpu: NR_CPUS:128 nr_cpumask_bits:128 nr_cpu_ids:1 nr_node_ids:1  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.044907981-04:00] [    0.007722] percpu: Embedded 52 pages/cpu s176128 r8192 d28672 u2097152  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.045673084-04:00] [    0.007764] kvm-guest: stealtime: cpu 0, msr 7a2a080  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.046509549-04:00] [    0.007770] kvm-guest: PV spinlocks disabled, single CPU  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.047509444-04:00] [    0.007782] Built 1 zonelists, mobility grouping on.  Total pages: 32137  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.047986370-04:00] [    0.007783] Policy zone: DMA32             jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.053166894-04:00] [    0.007785] Kernel command line: systemd.journald.forward_to_console systemd.unit=firecracker.target console=ttyS0 pci=off panic=1 nomodules ro init=/sbin/overlay-init ip=192.168.1.2::192.168.1.1:255.255.255.0:::off:198.22.255.3:: noapic reboot=k root=/dev/vda ro virtio_mmio.device=4K@0xd0000000:5 virtio_mmio.device=4K@0xd0001000:6 virtio_mmio.device=4K@0xd0002000:7 virtio_mmio.device=4K@0xd0003000:8  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.054297246-04:00] [    0.008091] Dentry cache hash table entries: 16384 (order: 5, 131072 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.055385313-04:00] [    0.008149] Inode-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.056326078-04:00] [    0.008205] mem auto-init: stack:off, heap alloc:off, heap free:off  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.058302408-04:00] [    0.008600] Memory: 96964K/130680K available (10243K kernel code, 7813K rwdata, 1956K rodata, 1680K init, 6780K bss, 33460K reserved, 0K cma-reserved)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.059271849-04:00] [    0.008757] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.060050214-04:00] [    0.008778] Kernel/User page tables isolation: enabled  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.060757799-04:00] [    0.008991] rcu: Hierarchical RCU implementation.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.061752567-04:00] [    0.008997] rcu: 	RCU restricting CPUs from NR_CPUS=128 to nr_cpu_ids=1.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.062468476-04:00] [    0.008998] 	Tracing variant of Tasks RCU enabled.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.063592548-04:00] [    0.009003] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.064591834-04:00] [    0.009004] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.065455432-04:00] [    0.009026] NR_IRQS: 4352, nr_irqs: 48, preallocated irqs: 16  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.066126257-04:00] [    0.009308] Console: colour dummy device 80x25  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.066763883-04:00] [    0.081713] printk: console [ttyS0] enabled  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.067542520-04:00] [    0.082379] APIC: Switch to symmetric I/O mode setup  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.068568380-04:00] [    0.083124] Not enabling interrupt remapping due to skipped IO-APIC setup  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.069124323-04:00] [    0.084154] kvm-guest: setup PV IPIs       jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.070730667-04:00] [    0.084744] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x1fb63109b96, max_idle_ns: 440795265316 ns  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.071996796-04:00] [    0.086318] Calibrating delay loop (skipped) preset value.. 4399.99 BogoMIPS (lpj=8799992)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.072943216-04:00] [    0.087690] Last level iTLB entries: 4KB 512, 2MB 8, 4MB 8  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.073868270-04:00] [    0.088527] Last level dTLB entries: 4KB 512, 2MB 0, 4MB 0, 1GB 4  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.075169506-04:00] [    0.089465] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.075875092-04:00] [    0.090314] Spectre V2 : Mitigation: Retpolines  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.077113108-04:00] [    0.090314] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.078129289-04:00] [    0.090314] Spectre V2 : Spectre v2 / SpectreRSB : Filling RSB on VMEXIT  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.079186902-04:00] [    0.090314] Spectre V2 : Enabling Restricted Speculation for firmware calls  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.080494997-04:00] [    0.090314] Spectre V2 : mitigation: Enabling conditional Indirect Branch Prediction Barrier  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.081957462-04:00] [    0.090314] Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl and seccomp  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.082635726-04:00] [    0.090314] MDS: Mitigation: Clear CPU buffers  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.083783033-04:00] [    0.090314] MMIO Stale Data: Vulnerable: Clear CPU buffers attempted, no microcode  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.084967724-04:00] [    0.090314] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.085931917-04:00] [    0.090314] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.086898906-04:00] [    0.090314] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.087852393-04:00] [    0.090314] x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.089235683-04:00] [    0.090314] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.112430123-04:00] [    0.090314] Freeing SMP alternatives memory: 32K  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.113861232-04:00] [    0.090314] pid_max: default: 32768 minimum: 301  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.114637964-04:00] [    0.090314] LSM: Security Framework initializing  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.115212058-04:00] [    0.090314] SELinux:  Initializing.        jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.116372626-04:00] [    0.090314] Mount-cache hash table entries: 512 (order: 0, 4096 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.117532184-04:00] [    0.090314] Mountpoint-cache hash table entries: 512 (order: 0, 4096 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.119503950-04:00] [    0.090314] smpboot: CPU0: Intel(R) Xeon(R) Processor @ 2.20GHz (family: 0x6, model: 0x3f, stepping: 0x2)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.121087366-04:00] [    0.090314] Performance Events: unsupported p6 CPU model 63 no PMU driver, software events only.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.121907104-04:00] [    0.090314] rcu: Hierarchical SRCU implementation.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.123027138-04:00] [    0.090566] smp: Bringing up secondary CPUs ...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.123628801-04:00] [    0.091268] smp: Brought up 1 node, 1 CPU  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.124280388-04:00] [    0.091873] smpboot: Max logical packages: 1  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.125272953-04:00] [    0.092525] smpboot: Total of 1 processors activated (4399.99 BogoMIPS)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.125937881-04:00] [    0.093668] devtmpfs: initialized          jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.126643288-04:00] [    0.094238] x86/mm: Memory block size: 128MB  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.128458939-04:00] [    0.094674] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.129477266-04:00] [    0.096132] futex hash table entries: 256 (order: 2, 16384 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.130498935-04:00] [    0.097493] NET: Registered protocol family 16  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.131708391-04:00] [    0.098313] DMA: preallocated 128 KiB GFP_KERNEL pool for atomic allocations  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.132964782-04:00] [    0.098396] DMA: preallocated 128 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.134167290-04:00] [    0.099579] DMA: preallocated 128 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.134995626-04:00] [    0.100776] audit: initializing netlink subsys (disabled)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.136306791-04:00] [    0.101980] thermal_sys: Registered thermal governor 'fair_share'  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.137224412-04:00] [    0.101982] thermal_sys: Registered thermal governor 'step_wise'  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.138148367-04:00] [    0.102323] thermal_sys: Registered thermal governor 'user_space'  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.138763350-04:00] [    0.103237] cpuidle: using governor ladder  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.139356132-04:00] [    0.104769] cpuidle: using governor menu   jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.141522315-04:00] [    0.106929] Kprobes globally optimized     jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.145768043-04:00] [    0.110466] audit: type=2000 audit(1693225745.005:1): state=initialized audit_enabled=0 res=1  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.156502968-04:00] [    0.121432] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.158405133-04:00] [    0.123626] ACPI: Interpreter disabled.    jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.159063651-04:00] [    0.124298] SCSI subsystem initialized     jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.159840768-04:00] [    0.124897] pps_core: LinuxPPS API ver. 1 registered  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.161195802-04:00] [    0.125651] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <[email protected]>  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.161816193-04:00] [    0.126336] PTP clock support registered   jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.162473830-04:00] [    0.127067] NetLabel: Initializing         jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.163132637-04:00] [    0.127590] NetLabel:  domain hash size = 128  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.163991448-04:00] [    0.128249] NetLabel:  protocols = UNLABELED CIPSOv4 CALIPSO  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.164850221-04:00] [    0.129128] NetLabel:  unlabeled traffic allowed by default  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.166521707-04:00] [    0.130222] clocksource: Switched to clocksource kvm-clock  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.167162218-04:00] [    0.130222] VFS: Disk quotas dquot_6.6.0   jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.168214547-04:00] [    0.130222] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.168797586-04:00] [    0.130222] pnp: PnP ACPI: disabled        jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.172303002-04:00] [    0.130608] NET: Registered protocol family 2  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.173408977-04:00] [    0.130608] IP idents hash table entries: 2048 (order: 2, 16384 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.174797153-04:00] [    0.134959] tcp_listen_portaddr_hash hash table entries: 256 (order: 0, 4096 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.175948732-04:00] [    0.136205] TCP established hash table entries: 1024 (order: 1, 8192 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.177024905-04:00] [    0.137364] TCP bind hash table entries: 1024 (order: 2, 16384 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.177975479-04:00] [    0.138429] TCP: Hash tables configured (established 1024 bind 1024)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.178969554-04:00] [    0.139400] UDP hash table entries: 256 (order: 1, 8192 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.180022280-04:00] [    0.140376] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.180731222-04:00] [    0.141474] NET: Registered protocol family 1  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.184353314-04:00] [    0.144494] virtio-mmio: Registering device virtio-mmio.0 at 0xd0000000-0xd0000fff, IRQ 5.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.185620653-04:00] [    0.145794] virtio-mmio: Registering device virtio-mmio.1 at 0xd0001000-0xd0001fff, IRQ 6.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.186865138-04:00] [    0.147038] virtio-mmio: Registering device virtio-mmio.2 at 0xd0002000-0xd0002fff, IRQ 7.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.188123070-04:00] [    0.148283] virtio-mmio: Registering device virtio-mmio.3 at 0xd0003000-0xd0003fff, IRQ 8.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.189637848-04:00] [    0.149562] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x1fb63109b96, max_idle_ns: 440795265316 ns  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.190630857-04:00] [    0.151279] clocksource: Switched to clocksource tsc  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.191798263-04:00] [    0.152050] platform rtc_cmos: registered platform RTC device (no PNP device found)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.193178115-04:00] [    0.153599] check: Scanning for low memory corruption every 60 seconds  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.194184304-04:00] [    0.154898] Initialise system trusted keyrings  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.194808284-04:00] [    0.155595] Key type blacklist registered  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.196301048-04:00] [    0.156723] workingset: timestamp_bits=36 max_order=15 bucket_order=0  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.198603511-04:00] [    0.159122] squashfs: version 4.0 (2009/01/31) Phillip Lougher  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.199222135-04:00] [    0.160005] fuse: init (API version 7.32)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.211592558-04:00] [    0.172351] Key type asymmetric registered  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.212340066-04:00] [    0.172992] Asymmetric key parser 'x509' registered  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.213486454-04:00] [    0.173769] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.215186074-04:00] [    0.175623] Serial: 8250/16550 driver, 1 ports, IRQ sharing disabled  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.216508263-04:00] [    0.176726] serial8250: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.308709152-04:00] [    0.269261] loop: module loaded            jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.311371236-04:00] [    0.270754] virtio_blk virtio0: [vda] 207792 512-byte logical blocks (106 MB/101 MiB)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.312781396-04:00] [    0.272774] vda: detected capacity change from 0 to 106389504  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.325648031-04:00] [    0.285695] virtio_blk virtio1: [vdb] 1 512-byte logical blocks (512 B/512 B)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.326627847-04:00] [    0.287048] vdb: detected capacity change from 0 to 512  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.337128937-04:00] [    0.297300] Loading iSCSI transport class v2.0-870.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.339498911-04:00] [    0.299811] iscsi: registered transport (tcp)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.340782595-04:00] [    0.300910] tun: Universal TUN/TAP device driver, 1.6  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.343100536-04:00] [    0.303333] i8042: PNP: No PS/2 controller found.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.344156285-04:00] [    0.304504] i8042: Probing ports directly.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.354117380-04:00] [    0.314309] i8042: Failed to disable AUX port, but continuing anyway... Is this a SiS?  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.355277884-04:00] [    0.315513] i8042: If AUX port is really absent please use the 'i8042.noaux' option  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.609405692-04:00] [    0.569390] serio: i8042 KBD port at 0x60,0x64 irq 1  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.611064486-04:00] [    0.571171] intel_pstate: CPU model not supported  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.612609252-04:00] [    0.572500] hid: raw HID events driver (C) Jiri Kosina  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.614218991-04:00] [    0.574374] Initializing XFRM netlink socket  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.615778764-04:00] [    0.575880] NET: Registered protocol family 10  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.618424272-04:00] [    0.578747] Segment Routing with IPv6      jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.619767789-04:00] [    0.579875] NET: Registered protocol family 17  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.620433527-04:00] [    0.581187] Bridge firewalling registered  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.621205301-04:00] [    0.581896] NET: Registered protocol family 40  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.622783038-04:00] [    0.583545] IPI shorthand broadcast: enabled  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.624059128-04:00] [    0.584238] sched_clock: Marking stable (504065176, 77090656)->(635333154, -54177322)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.624248657-04:00]                                               attempt=1 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:05.624986513-04:00] [    0.585735] registered taskstats version 1  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.625783298-04:00] [    0.586435] Loading compiled-in X.509 certificates  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.626011220-04:00]                                               attempt=2 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:05.628603610-04:00] [    0.588474] Loaded X.509 cert 'Build time autogenerated kernel key: 52d66e54fd7c12a9956528531fdb949547d0d5bb'  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.629319642-04:00] [    0.590095] Key type .fscrypt registered   jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.630099504-04:00] [    0.590714] Key type fscrypt-provisioning registered  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.630940677-04:00] [    0.591700] Key type encrypted registered  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:05.677867946-04:00]                                               attempt=3 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:05.777891417-04:00]                                               attempt=4 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:05.877949155-04:00]                                               attempt=5 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:05.978061789-04:00]                                               attempt=6 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:06.078119873-04:00]                                               attempt=7 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:06.122467065-04:00] [    1.081865] input: AT Raw Set 2 keyboard as /devices/platform/i8042/serio0/input/input0  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.140755820-04:00] [    1.101168] IP-Config: Complete:           jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.143580133-04:00] [    1.102135]      device=eth0, hwaddr=8a:18:27:6f:0d:06, ipaddr=192.168.1.2, mask=255.255.255.0, gw=192.168.1.1  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.145266580-04:00] [    1.104956]      host=192.168.1.2, domain=, nis-domain=(none)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.147441747-04:00] [    1.106661]      bootserver=255.255.255.255, rootserver=255.255.255.255, rootpath=  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.148664915-04:00] [    1.106664]      nameserver0=198.22.255.3  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.154342184-04:00] [    1.113550] VFS: Mounted root (squashfs filesystem) readonly on device 254:0.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.155915942-04:00] [    1.116496] devtmpfs: mounted              jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.157400148-04:00] [    1.118027] Freeing unused decrypted memory: 2036K  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.159070395-04:00] [    1.119516] Freeing unused kernel image (initmem) memory: 1680K  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.160628515-04:00] [    1.121135] Write protecting the kernel read-only data: 14336k  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.163388095-04:00] [    1.123792] Freeing unused kernel image (text/rodata gap) memory: 2044K  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.164546099-04:00] [    1.124930] Freeing unused kernel image (rodata/data gap) memory: 92K  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.165329419-04:00] [    1.125963] Run /sbin/overlay-init as init process  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.178393294-04:00]                                               attempt=8 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:06.276906397-04:00]                                               attempt=9 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:06.287231294-04:00] SELinux:  Could not open policy file <= /etc/selinux/targeted/policy/policy.33:  No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.293326763-04:00] [    1.253443] systemd[1]: Failed to look up module alias 'autofs4': Function not implemented  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.300107062-04:00] [    1.258114] systemd[1]: systemd 247.3-7+deb11u2 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +ZSTD +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=unified)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.300997902-04:00] [    1.261600] systemd[1]: Detected virtualization kvm.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.301791421-04:00] [    1.262379] systemd[1]: Detected architecture x86-64.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.305186480-04:00]                                               jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.305796250-04:00] Welcome to Debian GNU/Linux 11 (bullseye)!  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.305893417-04:00]                                               jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.307007097-04:00] [    1.267661] systemd[1]: Set hostname to <microvm>.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.377612086-04:00]                                               attempt=10 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:06.442311794-04:00] [    1.402443] systemd[1]: Queued start job for default target Firecracker containerd VM.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.444330700-04:00] [    1.404785] systemd[1]: Created slice system-modprobe.slice.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.445202085-04:00] [  OK  ] Created slice system-modprobe.slice.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.446560539-04:00] [    1.406747] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.447555534-04:00] [  OK  ] Started Dispatch Password …ts to Console Directory Watch.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.449209230-04:00] [    1.409057] systemd[1]: Starting of Arbitrary Executable File Formats File System Automount Point not supported.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.450326549-04:00] [UNSUPP] Starting of Arbitrary Exec…Automount Point not supported.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.451335157-04:00] [    1.411791] systemd[1]: Reached target Local Encrypted Volumes.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.452165164-04:00] [  OK  ] Reached target Local Encrypted Volumes.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.452937737-04:00] [    1.413642] systemd[1]: Reached target Paths.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.453589225-04:00] [  OK  ] Reached target Paths.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.454359379-04:00] [    1.415048] systemd[1]: Reached target Slices.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.455017066-04:00] [  OK  ] Reached target Slices.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.455801311-04:00] [    1.416480] systemd[1]: Reached target Swap.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.456459291-04:00] [  OK  ] Reached target Swap.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.457608262-04:00] [    1.417997] systemd[1]: Listening on initctl Compatibility Named Pipe.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.458456966-04:00] [  OK  ] Listening on initctl Compatibility Named Pipe.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.460031506-04:00] [    1.420556] systemd[1]: Listening on Journal Audit Socket.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.460834635-04:00] [  OK  ] Listening on Journal Audit Socket.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.461966984-04:00] [    1.422446] systemd[1]: Listening on Journal Socket (/dev/log).  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.462771248-04:00] [  OK  ] Listening on Journal Socket (/dev/log).  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.463805500-04:00] [    1.424404] systemd[1]: Listening on Journal Socket.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.464529351-04:00] [  OK  ] Listening on Journal Socket.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.466409190-04:00] [    1.426961] systemd[1]: Listening on udev Control Socket.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.467195405-04:00] [  OK  ] Listening on udev Control Socket.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.468235631-04:00] [    1.428784] systemd[1]: Listening on udev Kernel Socket.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.469027324-04:00] [  OK  ] Listening on udev Kernel Socket.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.469811770-04:00] [    1.430487] systemd[1]: Reached target Sockets.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.470466445-04:00] [  OK  ] Reached target Sockets.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.472375466-04:00] [    1.432888] systemd[1]: Mounting Huge Pages File System...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.473094991-04:00]          Mounting Huge Pages File System...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.475176696-04:00] [    1.435605] systemd[1]: Mounting POSIX Message Queue File System...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.476000751-04:00]          Mounting POSIX Message Queue File System...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.477330744-04:00]                                               attempt=11 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:06.481782672-04:00] [    1.442284] systemd[1]: Mounting Kernel Debug File System...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.482493197-04:00]          Mounting Kernel Debug File System...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.487908557-04:00] [    1.448005] systemd[1]: Condition check resulted in Kernel Trace File System being skipped.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.495771695-04:00] [    1.455455] systemd[1]: Condition check resulted in Create list of static device nodes for the current kernel being skipped.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.499536586-04:00] [    1.459997] systemd[1]: Starting Load Kernel Module configfs...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.500302184-04:00]          Starting Load Kernel Module configfs...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.502289530-04:00] [    1.462810] systemd[1]: Starting Load Kernel Module fuse...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.502974994-04:00]          Starting Load Kernel Module fuse...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.506596761-04:00] [    1.466610] systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.509085171-04:00] [    1.469699] systemd[1]: Starting Journal Service...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.509722789-04:00]          Starting Journal Service...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.512135843-04:00] [    1.472693] systemd[1]: Starting Load Kernel Modules...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.516421107-04:00]          Starting Load Kernel Modules...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.528536434-04:00] [    1.488857] systemd[1]: Starting Remount Root and Kernel File Systems...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.536549944-04:00]          Starting Remount Root and Kernel File Systems...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.541250040-04:00] [    1.501731] systemd[1]: Starting Coldplug All udev Devices...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.541981501-04:00]          Starting Coldplug All udev Devices...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.549969078-04:00] [    1.510496] systemd[1]: Mounted Huge Pages File System.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.550704642-04:00] [  OK  ] Mounted Huge Pages File System.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.558385506-04:00] [    1.518832] systemd[1]: Mounted POSIX Message Queue File System.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.559194245-04:00] [  OK  ] Mounted POSIX Message Queue File System.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.565714592-04:00] [    1.526250] systemd[1]: Mounted Kernel Debug File System.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.566492879-04:00] [  OK  ] Mounted Kernel Debug File System.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.571131869-04:00] [    1.531555] systemd[1]: [email protected]: Succeeded.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.577613066-04:00]                                               attempt=12 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:06.578526156-04:00] [    1.539004] systemd[1]: Finished Load Kernel Module configfs.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.579336613-04:00] [  OK  ] Finished Load Kernel Module configfs.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.583684342-04:00] [    1.544206] systemd[1]: [email protected]: Succeeded.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.586593726-04:00] [    1.547117] systemd[1]: Finished Load Kernel Module fuse.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.587369087-04:00] [  OK  ] Finished Load Kernel Module fuse.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.597404620-04:00] [    1.557963] systemd[1]: Finished Load Kernel Modules.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.598121173-04:00] [  OK  ] Finished Load Kernel Modules.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.604923375-04:00] [    1.565242] systemd[1]: Finished Remount Root and Kernel File Systems.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.605812657-04:00] [  OK  ] Finished Remount Root and Kernel File Systems.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.610467616-04:00] [    1.570958] systemd[1]: Mounting FUSE Control File System...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.624493551-04:00]          Mounting FUSE Control File System...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.629349992-04:00] [    1.589328] systemd[1]: Condition check resulted in Kernel Configuration File System being skipped.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.634005579-04:00] [    1.594089] systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.635482144-04:00] [    1.595427] systemd[1]: Condition check resulted in Platform Persistent Storage Archival being skipped.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.641251794-04:00] [    1.524174] systemd[511]: [email protected]: Executable /sbin/modprobe missing, skipping: No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.643000202-04:00] [    1.525998] systemd[512]: [email protected]: Executable /sbin/modprobe missing, skipping: No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.644732497-04:00] [    1.605261] systemd[1]: Starting Load/Save Random Seed...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.645417087-04:00]          Starting Load/Save Random Seed...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.658618575-04:00] [    1.541779] systemd-random-seed[606]: Kernel entropy pool is not initialized yet, waiting until it is.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.659708530-04:00] [    1.620223] systemd[1]: Starting Apply Kernel Variables...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.664445688-04:00]          Starting Apply Kernel Variables...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.670218594-04:00] [    1.630777] systemd[1]: Starting Create System Users...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.670889091-04:00]          Starting Create System Users...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.677476741-04:00]                                               attempt=13 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:06.681372455-04:00] [    1.641992] systemd[1]: Started Journal Service.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.682064675-04:00] [  OK  ] Started Journal Service.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.696639708-04:00] [    1.580179] systemd[1]: Mounted FUSE Control File System.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.703008236-04:00] [  OK  ] Mounted FUSE Control File System.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.710151159-04:00] [    1.593719] systemd[1]: Finished Apply Kernel Variables.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.711098397-04:00] [  OK  ] Finished Apply Kernel Variables.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.715854213-04:00] [    1.599183] systemd-sysusers[608]: Creating group systemd-timesync with gid 999.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.716953130-04:00] [    1.600524] systemd[1]: Finished Coldplug All udev Devices.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.717908556-04:00] [  OK  ] Finished Coldplug All udev Devices.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.720555655-04:00] [    1.603508] systemd-sysusers[608]: Creating user systemd-timesync (systemd Time Synchronization) with uid 999 and gid 999.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.722125218-04:00] [    1.605478] systemd-sysusers[608]: Creating group systemd-coredump with gid 998.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.725255187-04:00] [    1.608279] systemd-sysusers[608]: Creating user systemd-coredump (systemd Core Dumper) with uid 998 and gid 998.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.726611073-04:00]          Starting Flush Journal to Persistent Storage...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.737169681-04:00] [    1.620588] systemd[1]: Starting Flush Journal to Persistent Storage...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.738287362-04:00] [  OK  ] Finished Create System Users.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.739838205-04:00] [    1.623414] systemd[1]: Finished Create System Users.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.742723011-04:00]          Starting Create Static Device Nodes in /dev...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.743752707-04:00] [    1.627182] systemd[1]: Starting Create Static Device Nodes in /dev...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.753337215-04:00] [    1.713487] systemd-journald[513]: Received client request to flush runtime journal.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.765990950-04:00] [  OK  ] Finished Flush Journal to Persistent Storage.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.767199370-04:00] [    1.650675] systemd[1]: Finished Flush Journal to Persistent Storage.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.771341697-04:00] [  OK  ] Finished Create Static Device Nodes in /dev.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.772402879-04:00] [  OK  ] Reached target Local File Systems (Pre).  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.773403650-04:00] [    1.656876] systemd[1]: Finished Create Static Device Nodes in /dev.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.774303412-04:00] [    1.657818] systemd[1]: Reached target Local File Systems (Pre).  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.775261044-04:00] [  OK  ] Reached target Local File Systems.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.777933506-04:00]          Starting Create Volatile Files and Directories...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.778097216-04:00]                                               attempt=14 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:06.778975176-04:00] [    1.662559] systemd[1]: Reached target Local File Systems.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.779995301-04:00] [    1.663390] systemd[1]: Starting Create Volatile Files and Directories...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.793202312-04:00]          Starting Rule-based Manage…for Device Events and Files...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.794240973-04:00] [    1.677593] systemd[1]: Starting Rule-based Manager for Device Events and Files...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.811858676-04:00] [    1.694825] systemd-tmpfiles[754]: Detected unsafe path transition /var → /var/lib during canonicalization of /var/lib.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.816629126-04:00] [    1.699508] systemd-tmpfiles[754]: Detected unsafe path transition /var → /var/lib during canonicalization of /var/lib/systemd.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.819061483-04:00] [    1.702016] systemd-tmpfiles[754]: Detected unsafe path transition /var → /var/lib during canonicalization of /var/lib/systemd.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.824010153-04:00] [    1.706955] systemd-tmpfiles[754]: Detected unsafe path transition /var → /var/lib during canonicalization of /var/lib.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.829765222-04:00] [    1.712809] systemd-tmpfiles[754]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.832471857-04:00] [  OK  ] Finished Create Volatile Files and Directories.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.834847223-04:00] [  OK  ] Started Entropy Daemon based on the HAVEGE algorithm.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.836498296-04:00] [    1.719423] systemd-tmpfiles[754]: Detected unsafe path transition /var → /var/cache during canonicalization of /var/cache.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.851527331-04:00] [    1.734361] systemd-tmpfiles[754]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.860479257-04:00] [    1.743414] systemd-tmpfiles[754]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.861744183-04:00]          Starting Update UTMP about System Boot/Shutdown...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.873702810-04:00] [    1.756723] systemd-tmpfiles[754]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.877297442-04:00]                                               attempt=15 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:06.878548416-04:00] [  OK  ] Started Rule-based Manager for Device Events and Files.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.881366507-04:00] [    1.764310] systemd-tmpfiles[754]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log/journal.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.893541287-04:00] [    1.776460] systemd-tmpfiles[754]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log/journal.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.897962747-04:00] [    1.780905] systemd-tmpfiles[754]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log/journal.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.906482239-04:00] [    1.789161] systemd-tmpfiles[754]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log/journal/d9d2a514ecd64b45aca42e0adcd4b566.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.910109227-04:00] [  OK  ] Finished Update UTMP about System Boot/Shutdown.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.911146384-04:00] [  OK  ] Reached target System Initialization.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.917403633-04:00] [  OK  ] Started Periodic ext4 Onli…ata Check for All Filesystems.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.919665011-04:00] [    1.802333] systemd-tmpfiles[754]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log/journal/d9d2a514ecd64b45aca42e0adcd4b566.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.923284581-04:00] [  OK  ] Started Discard unused blocks once a week.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.924269717-04:00] [  OK  ] Started Daily Cleanup of Temporary Directories.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.930022941-04:00] [    1.813531] haveged[756]: haveged: command socket is listening at fd 3  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.932654248-04:00] [  OK  ] Reached target Basic System.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.934458329-04:00] [    1.817164] systemd-tmpfiles[754]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log/journal/d9d2a514ecd64b45aca42e0adcd4b566.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.936960469-04:00] [  OK  ] Reached target Timers.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.944704926-04:00] [    1.827118] systemd-tmpfiles[754]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log/journal/d9d2a514ecd64b45aca42e0adcd4b566/system.journal.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.946391087-04:00] [  OK  ] Started Firecracker VM agent.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.953870032-04:00] [    1.836427] systemd-tmpfiles[754]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log/journal/d9d2a514ecd64b45aca42e0adcd4b566/system.journal.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.964752714-04:00]          Starting Stargz Snapshotter...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.966836639-04:00] [    1.850286] systemd[1]: Finished Create Volatile Files and Directories.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.977403298-04:00]                                               attempt=16 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:06.978354708-04:00] [    1.861747] systemd[1]: Started Entropy Daemon based on the HAVEGE algorithm.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.982443815-04:00] [  OK  ] Started Stargz Snapshotter.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.986043455-04:00] [    1.869522] systemd[1]: Starting Update UTMP about System Boot/Shutdown...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.989967106-04:00] [    1.873358] systemd[1]: Started Rule-based Manager for Device Events and Files.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:06.998590879-04:00] [    1.882031] systemd[1]: Finished Update UTMP about System Boot/Shutdown.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.009205054-04:00] [  OK  ] Started Metrics Socat.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.011027155-04:00] [    1.894532] systemd[1]: Reached target System Initialization.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.020320793-04:00] [    1.901374] systemd[1]: Started Periodic ext4 Online Metadata Check for All Filesystems.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.028805747-04:00] [  OK  ] Started Socat.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.029908475-04:00] [  OK  ] Reached target Firecracker containerd VM.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.032856274-04:00] [    1.916368] systemd[1]: Started Discard unused blocks once a week.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.040853933-04:00] [    1.924277] systemd[1]: Started Daily Cleanup of Temporary Directories.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.049924649-04:00] [    1.933570] systemd[1]: Reached target Basic System.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.053072551-04:00] [    1.936679] systemd[1]: Reached target Timers.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.064995538-04:00] [    1.948605] systemd[1]: Started Firecracker VM agent.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.070537790-04:00] [    1.954109] systemd[1]: Starting Stargz Snapshotter...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.077513868-04:00]                                               attempt=17 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:07.082148698-04:00] [    1.965807] systemd[1]: Started Stargz Snapshotter.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.088019785-04:00] [    1.971624] systemd[1]: Started Metrics Socat.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.096154223-04:00] [    1.979861] systemd[1]: Started Socat.     jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.099419090-04:00] [    1.982894] systemd[1]: Reached target Firecracker containerd VM.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.176928284-04:00]                                               attempt=18 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:07.278447632-04:00]                                               attempt=19 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:07.377669435-04:00]                                               attempt=20 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:07.477350751-04:00]                                               attempt=21 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:07.530764990-04:00] [    2.414112] systemd-udevd[762]: Using default interface naming scheme 'v247'.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.577655309-04:00]                                               attempt=22 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:07.591818226-04:00] [    2.474821] systemd-udevd[765]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.677520989-04:00]                                               attempt=23 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:07.777260334-04:00]                                               attempt=24 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:07.796840525-04:00] [    2.679760] systemd-udevd[762]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.813024729-04:00] [    2.696299] agent[767]: time="2023-08-28T12:29:07Z" level=info msg="creating task service"  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
INFO[2023-08-28T08:29:07.877972765-04:00] successfully started the VM                   runtime=aws.firecracker vmID=vm1
DEBU[2023-08-28T08:29:07.878074579-04:00] event published                               ns=vm1 runtime=aws.firecracker topic=/firecracker-vm/start type=VMStart
DEBU[2023-08-28T08:29:07.878754710-04:00] event forwarded                               ns=vm1 topic=/firecracker-vm/start type=VMStart
DEBU[2023-08-28T08:29:07.878817460-04:00] Setting vm metadata
INFO[2023-08-28T08:29:07.879127205-04:00] setting VM metadata                           runtime=aws.firecracker vmID=vm1
INFO[2023-08-28T08:29:07.879528630-04:00] SetMetadata successful                        runtime=aws.firecracker
DEBU[2023-08-28T08:29:07.957480047-04:00] [    2.840417] haveged[756]: haveged: ver: 1.9.14; arch: x86; vend: GenuineIntel; build: (gcc 10.2.1 ITV); collect: 128K  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.961379089-04:00] [    2.844436] haveged[756]: haveged: cpu: (L4 VC); data: 32K (L4 V); inst: 32K (L4 V); idx: 24/40; sz: 32154/54019  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.964950526-04:00] [    2.848062] haveged[756]: haveged: tot tests(BA8): A:1/1 B:1/1 continuous tests(B):  last entropy estimate 8.00509  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.966182142-04:00] [    2.849796] haveged[756]: haveged: fills: 0, generated: 0  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.988321869-04:00] [    2.949123] random: crng init done         jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.992508279-04:00] [  OK  ] Finished Load/Save Random Seed.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.993610255-04:00] [    2.877194] systemd[1]: Finished Load/Save Random Seed.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.995176925-04:00] [    2.878466] systemd[1]: Condition check resulted in First Boot Complete being skipped.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.996552231-04:00] [    2.879668] systemd[1]: Condition check resulted in Store a System Token in an EFI Variable being skipped.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:07.999085153-04:00] [    2.882201] systemd[1]: Condition check resulted in Commit a transient machine-id on disk being skipped.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:08.001804855-04:00] [    2.885079] systemd[1]: Startup finished in 1.151s (kernel) + 1.728s (userspace) = 2.879s.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:08.226468048-04:00] [    3.109262] systemd[1]: var-lib-containerd\x2dstargz\x2dgrpc-snapshotter-multiple\x2dlowerdir\x2dcheck4022269400-merged.mount: Succeeded.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:08.241984324-04:00] (*service).Write started                      expected="sha256:cf7691888080f0f3e1e9ed2a7046be7d751a455f03b0bf71464084f3eb2ebcb4" ref="index-sha256:cf7691888080f0f3e1e9ed2a7046be7d751a455f03b0bf71464084f3eb2ebcb4" total=289
DEBU[2023-08-28T08:29:08.308352931-04:00] (*service).Write started                      expected="sha256:139c53359e4e6460f1ee4212ef7e687796ee65b91844091a7912719114efcd89" ref="manifest-sha256:139c53359e4e6460f1ee4212ef7e687796ee65b91844091a7912719114efcd89" total=935
DEBU[2023-08-28T08:29:08.395882794-04:00] (*service).Write started                      expected="sha256:88621c9e6fbcf744b05c7b39b1646cddedb0ef215afe41545285d0c46650b260" ref="config-sha256:88621c9e6fbcf744b05c7b39b1646cddedb0ef215afe41545285d0c46650b260" total=6851
DEBU[2023-08-28T08:29:08.509879816-04:00] stat snapshot                                 key="sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61"
DEBU[2023-08-28T08:29:08.510851628-04:00] prepare snapshot                              key="extract-510332230-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61" parent=
DEBU[2023-08-28T08:29:08.516531211-04:00] get VM info: VMID:"vm1"
DEBU[2023-08-28T08:29:08.652851995-04:00] [    3.533997] containerd-stargz-grpc[770]: {"key":"vm1/1/extract-510332230-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"info","msg":"preparing filesystem mount at mountpoint=/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","parent":"","time":"2023-08-28T12:29:08.517953986Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:08.658205196-04:00] [    3.538534] containerd-stargz-grpc[770]: {"key":"vm1/1/extract-510332230-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"resolving","parent":"","src":"docker.io/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:009329cdd843a5a2ed181a54e741661f850ea6202db9f50c7931f4e8cc221827","time":"2023-08-28T12:29:08.521719649Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:08.666663587-04:00] [    3.546649] containerd-stargz-grpc[770]: {"key":"vm1/1/extract-510332230-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"resolving","parent":"","src":"docker.io/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:afecc368122865dbe98d4dc69abea6831dfa77f12be80d7fbc74067e9ba64336","time":"2023-08-28T12:29:08.527748189Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:08.675309348-04:00] [    3.554079] containerd-stargz-grpc[770]: {"digest":"sha256:afecc368122865dbe98d4dc69abea6831dfa77f12be80d7fbc74067e9ba64336","error":null,"key":"vm1/1/extract-510332230-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"using default handler","parent":"","ref":"docker.io/curiousgeorgiy/nginx:1.17-alpine-esgz","src":"docker.io/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:afecc368122865dbe98d4dc69abea6831dfa77f12be80d7fbc74067e9ba64336","time":"2023-08-28T12:29:08.528040655Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:08.680982661-04:00] [    3.559812] containerd-stargz-grpc[770]: {"digest":"sha256:009329cdd843a5a2ed181a54e741661f850ea6202db9f50c7931f4e8cc221827","error":null,"key":"vm1/1/extract-510332230-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"using default handler","parent":"","ref":"docker.io/curiousgeorgiy/nginx:1.17-alpine-esgz","src":"docker.io/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:009329cdd843a5a2ed181a54e741661f850ea6202db9f50c7931f4e8cc221827","time":"2023-08-28T12:29:08.521817798Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:08.801102860-04:00] [    3.679023] containerd-stargz-grpc[770]: {"key":"vm1/1/extract-510332230-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"info","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"Received status code: 401 Unauthorized. Refreshing creds...","parent":"","src":"docker.io/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:009329cdd843a5a2ed181a54e741661f850ea6202db9f50c7931f4e8cc221827","time":"2023-08-28T12:29:08.663288049Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:08.810321694-04:00] [    3.690147] containerd-stargz-grpc[770]: {"key":"vm1/1/extract-510332230-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"info","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"Received status code: 401 Unauthorized. Refreshing creds...","parent":"","src":"docker.io/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:afecc368122865dbe98d4dc69abea6831dfa77f12be80d7fbc74067e9ba64336","time":"2023-08-28T12:29:08.672298568Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:08.883301997-04:00] [    3.759175] containerd-stargz-grpc[770]: {"error":"failed to resolve layer \"sha256:afecc368122865dbe98d4dc69abea6831dfa77f12be80d7fbc74067e9ba64336\" from \"docker.io/curiousgeorgiy/nginx:1.17-alpine-esgz\": failed to resolve the blob: failed to resolve the source: cannot resolve layer: failed to redirect (host \"registry-1.docker.io\", ref:\"docker.io/curiousgeorgiy/nginx:1.17-alpine-esgz\", digest:\"sha256:afecc368122865dbe98d4dc69abea6831dfa77f12be80d7fbc74067e9ba64336\"): failed to request: error getting credentials - err: exit status 1, out: `no key for https://index.docker.io/v1/`: failed to resolve: failed to resolve target","key":"vm1/1/extract-510332230-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"failed to resolve layer","parent":"","time":"2023-08-28T12:29:08.743509624Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:08.899563363-04:00] [    3.775243] containerd-stargz-grpc[770]: {"error":"failed to resolve layer: failed to resolve layer \"sha256:afecc368122865dbe98d4dc69abea6831dfa77f12be80d7fbc74067e9ba64336\" from \"docker.io/curiousgeorgiy/nginx:1.17-alpine-esgz\": failed to resolve the blob: failed to resolve the source: cannot resolve layer: failed to redirect (host \"registry-1.docker.io\", ref:\"docker.io/curiousgeorgiy/nginx:1.17-alpine-esgz\", digest:\"sha256:afecc368122865dbe98d4dc69abea6831dfa77f12be80d7fbc74067e9ba64336\"): failed to request: error getting credentials - err: exit status 1, out: `no key for https://index.docker.io/v1/`: failed to resolve: failed to resolve target","key":"vm1/1/extract-510332230-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"warning","msg":"failed to prepare remote snapshot","parent":"","remote-snapshot-prepared":"false","time":"2023-08-28T12:29:08.756023306Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-28T08:29:08.909257910-04:00] event published                               ns=vm1 topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2023-08-28T08:29:08.910023877-04:00] (*service).Write started                      expected="sha256:009329cdd843a5a2ed181a54e741661f850ea6202db9f50c7931f4e8cc221827" ref="layer-sha256:009329cdd843a5a2ed181a54e741661f850ea6202db9f50c7931f4e8cc221827" total=6259681
DEBU[2023-08-28T08:29:08.910026794-04:00] (*service).Write started                      expected="sha256:afecc368122865dbe98d4dc69abea6831dfa77f12be80d7fbc74067e9ba64336" ref="layer-sha256:afecc368122865dbe98d4dc69abea6831dfa77f12be80d7fbc74067e9ba64336" total=2831473
DEBU[2023-08-28T08:29:08.915267372-04:00] [    3.792488] containerd-stargz-grpc[770]: {"error":"failed to resolve the blob: failed to resolve the source: cannot resolve layer: failed to redirect (host \"registry-1.docker.io\", ref:\"docker.io/curiousgeorgiy/nginx:1.17-alpine-esgz\", digest:\"sha256:009329cdd843a5a2ed181a54e741661f850ea6202db9f50c7931f4e8cc221827\"): failed to request: error getting credentials - err: exit status 1, out: `no key for https://index.docker.io/v1/`: failed to resolve","key":"vm1/1/extract-510332230-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"failed to pre-resolve","parent":"","time":"2023-08-28T12:29:08.776746222Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout

docker login on the same host with the same credentials succeeds.

If I try to pull the same image from the GHCR, providing my GitHub PAT as the password, the example also fails:

glebedev@node-0:~/vhive/firecracker-containerd/examples/cmd/remote-snapshotter$ sudo ./remote-snapshotter ghcr.io/curiousgeorgiy/vhive/nginx:1.17-alpine-esgz
Docker username: curiousgeorgiy
Docker password: <redacted>
Creating VM
Setting docker credential metadata
Pulling the image
INFO[0012] trying next host                              error="failed to authorize: failed to fetch anonymous token: unexpected status: 401 Unauthorized" host=ghcr.io
failed to resolve reference "ghcr.io/curiousgeorgiy/vhive/nginx:1.17-alpine-esgz": failed to authorize: failed to fetch anonymous token: unexpected status: 401 Unauthorized

If I try to pull the same image from a local docker registry, which doesn't require any authentication, I get the same error as in the first case:

glebedev@node-0:~/firecracker-containerd/examples/cmd/remote-snapshotter$ sudo ./remote-snapshotter localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz
Docker username: user
Docker password: pass
Creating VM
Setting docker credential metadata
Pulling the image
failed to extract layer sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61: failed to mount /var/lib/firecracker-containerd/containerd/tmpmounts/containerd-mount3583055747: no such file or directory: unknown

The following errors appear in the firecracker-containerd logs:

DEBU[2023-08-30T08:43:27.818474963-04:00] get VM info: VMID:"vm1"
DEBU[2023-08-30T08:44:07.505892892-04:00] create VM request: VMID:"vm1" NetworkInterfaces:<AllowMMDS:true CNIConfig:<NetworkName:"fcnet" InterfaceName:"veth0" > >
DEBU[2023-08-30T08:44:07.505978291-04:00] using namespace: vm1
DEBU[2023-08-30T08:44:07.506537751-04:00] starting containerd-shim-aws-firecracker      vmID=vm1
INFO[2023-08-30T08:44:07.548349560-04:00] loading plugin "io.containerd.service.v1.introspection-service"...  runtime=aws.firecracker type=io.containerd.service.v1
INFO[2023-08-30T08:44:07.548497633-04:00] loading plugin "io.containerd.grpc.v1.introspection"...  runtime=aws.firecracker type=io.containerd.grpc.v1
INFO[2023-08-30T08:44:07.548532474-04:00] loading plugin "io.containerd.event.v1.publisher"...  runtime=aws.firecracker type=io.containerd.event.v1
INFO[2023-08-30T08:44:07.548564213-04:00] loading plugin "io.containerd.ttrpc.v1.task"...  runtime=aws.firecracker type=io.containerd.ttrpc.v1
DEBU[2023-08-30T08:44:07.548593551-04:00] registering ttrpc service                     id=io.containerd.ttrpc.v1.task
INFO[2023-08-30T08:44:07.548615330-04:00] loading plugin "io.containerd.internal.v1.shutdown"...  runtime=aws.firecracker type=io.containerd.internal.v1
DEBU[2023-08-30T08:44:07.548746012-04:00] serving api on socket                         socket="[inherited from parent]"
INFO[2023-08-30T08:44:07.548779129-04:00] starting signal loop                          namespace=vm1 path="/var/lib/firecracker-containerd/shim-base/vm1#vm1" pid=64452 runtime=aws.firecracker
INFO[2023-08-30T08:44:07.548896470-04:00] creating new VM                               runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:07.549017377-04:00] noop operation returning shim dir for JailPath  jailer=noop runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:07.549111796-04:00] using socket path: firecracker.sock           runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:07.549148905-04:00] noop operation returning shim dir for JailPath  jailer=noop runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:07.549259009-04:00] noop operation for StubDrivesOptions          jailer=noop runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:07.549310559-04:00] noop operation returning shim dir for JailPath  jailer=noop runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:07.549385150-04:00] noop operation for BuildJailedMachine         jailer=noop runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:07.549407747-04:00] No balloon device is setup                    runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:07.549494583-04:00] Called NewMachine()                           runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.549518803-04:00] Called Machine.Start()                        runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.549554787-04:00] Marking Machine as Started                    runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.549570802-04:00] Running handler validate.NetworkCfg           runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.549594475-04:00] Running handler validate.Cfg                  runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.549636816-04:00] Running handler fcinit.SetupNetwork           runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.762950531-04:00] Running handler fcinit.SetupKernelArgs        runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.763081033-04:00] Running handler fcinit.StartVMM               runtime=aws.firecracker
INFO[2023-08-30T08:44:07.763116444-04:00] Called startVMM(), setting up a VMM on firecracker.sock  runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.763167855-04:00] Starting [/usr/local/bin/firecracker --api-sock firecracker.sock --id vm1]  runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.763880022-04:00] VMM started socket path is firecracker.sock   runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.763939686-04:00] Setting up signal handler: [interrupt quit terminated hangup aborted]  runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.775727062-04:00] returning from startVMM()                     runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.775764318-04:00] Running handler fcinit.CreateLogFilesHandler  runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.775856548-04:00] Created metrics and logging fifos.            runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.775885945-04:00] Running handler fcinit.BootstrapLogging       runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.776618229-04:00] Configured VMM logging to /var/lib/firecracker-containerd/shim-base/vm1#vm1/fc-logs.fifo  runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.777215270-04:00] Configured VMM metrics to /var/lib/firecracker-containerd/shim-base/vm1#vm1/fc-metrics.fifo  runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.777253171-04:00] setup logging: success                        runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.777275425-04:00] Running handler fcinit.CreateMachine          runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.777729723-04:00] PutMachineConfiguration returned              runtime=aws.firecracker
INFO[2023-08-30T08:44:07.778145414-04:00] refreshMachineConfiguration: [GET /machine-config][200] getMachineConfigurationOK  &{CPUTemplate:T2 MemSizeMib:0xc000036128 Smt:0xc000036133 TrackDirtyPages:0xc000036136 VcpuCount:0xc000036120}  runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.778182383-04:00] createMachine returning                       runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.778200363-04:00] Running handler fcinit.CreateBootSource       runtime=aws.firecracker
INFO[2023-08-30T08:44:07.778612411-04:00] PutGuestBootSource: [PUT /boot-source][204] putGuestBootSourceNoContent   runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.778646965-04:00] Running handler fcinit.AttachDrives           runtime=aws.firecracker
INFO[2023-08-30T08:44:07.778667839-04:00] Attaching drive /var/lib/firecracker-containerd/runtime/default-rootfs.img, slot root_drive, root true.  runtime=aws.firecracker
INFO[2023-08-30T08:44:07.779343283-04:00] Attached drive /var/lib/firecracker-containerd/runtime/default-rootfs.img: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent   runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.779370468-04:00] attachDrive returned for /var/lib/firecracker-containerd/runtime/default-rootfs.img  runtime=aws.firecracker
INFO[2023-08-30T08:44:07.779389300-04:00] Attaching drive /var/lib/firecracker-containerd/shim-base/vm1#vm1/ctrstub0, slot MN2HE43UOVRDA, root false.  runtime=aws.firecracker
INFO[2023-08-30T08:44:07.779858367-04:00] Attached drive /var/lib/firecracker-containerd/shim-base/vm1#vm1/ctrstub0: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent   runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.779903539-04:00] attachDrive returned for /var/lib/firecracker-containerd/shim-base/vm1#vm1/ctrstub0  runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.779927619-04:00] Running handler fcinit.CreateNetworkInterfaces  runtime=aws.firecracker
INFO[2023-08-30T08:44:07.779948643-04:00] Attaching NIC tap0 (hwaddr 42:9f:50:a8:e1:97) at index 1  runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.781095127-04:00] PutGuestNetworkInterfaceByID: [PUT /network-interfaces/{iface_id}][204] putGuestNetworkInterfaceByIdNoContent   runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.781134985-04:00] createNetworkInterface returned for tap0      runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.781157003-04:00] Running handler fcinit.AddVsocks              runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.781751549-04:00] Attach vsock firecracker.vsock successful: [PUT /vsock][204] putGuestVsockNoContent   runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.781792061-04:00] Running handler fcinit.ConfigMmds             runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.782252447-04:00] SetMmdsConfig successful                      runtime=aws.firecracker
DEBU[2023-08-30T08:44:07.782283485-04:00] Running handler firecracker-containerd-jail-pid-handler  runtime=aws.firecracker
INFO[2023-08-30T08:44:07.809217311-04:00] startInstance successful: [PUT /actions][204] createSyncActionNoContent   runtime=aws.firecracker
INFO[2023-08-30T08:44:07.809255802-04:00] calling agent                                 runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:07.829187407-04:00] [    0.000000] Linux version 5.10.192 (@d4b5b0f861f9) (gcc (Ubuntu 11.3.0-1ubuntu1~22.04.1) 11.3.0, GNU ld (GNU Binutils for Ubuntu) 2.38) #1 SMP Mon Aug 28 08:55:20 UTC 2023  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.834396099-04:00] [    0.000000] Command line: systemd.unit=firecracker.target console=ttyS0 noapic reboot=k panic=1 ro pci=off nomodules systemd.journald.forward_to_console init=/sbin/overlay-init ip=192.168.1.4::192.168.1.1:255.255.255.0:::off:198.22.255.3:: root=/dev/vda ro virtio_mmio.device=4K@0xd0000000:5 virtio_mmio.device=4K@0xd0001000:6 virtio_mmio.device=4K@0xd0002000:7 virtio_mmio.device=4K@0xd0003000:8  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.835034390-04:00] [    0.000000] BIOS-provided physical RAM map:  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.836078843-04:00] [    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.837118321-04:00] [    0.000000] BIOS-e820: [mem 0x0000000000100000-0x0000000007ffffff] usable  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.837861344-04:00] [    0.000000] NX (Execute Disable) protection: active  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.838457277-04:00] [    0.000000] DMI not present or invalid.    jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.839009422-04:00] [    0.000000] Hypervisor detected: KVM       jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.839807384-04:00] [    0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.840672179-04:00] [    0.000000] kvm-clock: cpu 0, msr 2c01001, primary cpu clock  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.841531549-04:00] [    0.000001] kvm-clock: using sched offset of 10268173 cycles  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.843122080-04:00] [    0.000020] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.843837457-04:00] [    0.000043] tsc: Detected 2200.000 MHz processor  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.844646116-04:00] [    0.000401] last_pfn = 0x8000 max_arch_pfn = 0x400000000  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.844993131-04:00] [    0.000523] Disabled                       jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.845973613-04:00] [    0.000533] x86/PAT: MTRRs disabled, skipping PAT initialization too.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.846746373-04:00] [    0.000567] CPU MTRRs all blank - virtualized system.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.847826080-04:00] [    0.000582] x86/PAT: Configuration [0-7]: WB  WT  UC- UC  WB  WT  UC- UC    jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.848703513-04:00] [    0.000691] found SMP MP-table at [mem 0x0009fc00-0x0009fc0f]  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.849579806-04:00] [    0.000806] check: Scanning 1 areas for low memory corruption  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.850438696-04:00] [    0.001079] ACPI: Early table checksum verification disabled  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.851634272-04:00] [    0.001266] ACPI BIOS Error (bug): A valid RSDP was not found (20200925/tbxfroot-210)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.852228291-04:00] [    0.001355] No NUMA configuration found    jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.853255059-04:00] [    0.001358] Faking a node at [mem 0x0000000000000000-0x0000000007ffffff]  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.854150134-04:00] [    0.001381] NODE_DATA(0) allocated [mem 0x07fde000-0x07ffffff]  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.854548801-04:00] [    0.001751] Zone ranges:                   jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.855492320-04:00] [    0.001758]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.856439578-04:00] [    0.001762]   DMA32    [mem 0x0000000001000000-0x0000000007ffffff]  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.856914461-04:00] [    0.001765]   Normal   empty               jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.857540557-04:00] [    0.001767] Movable zone start for each node  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.858095560-04:00] [    0.001773] Early memory node ranges       jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.859053754-04:00] [    0.001775]   node   0: [mem 0x0000000000001000-0x000000000009efff]  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.860017534-04:00] [    0.001778]   node   0: [mem 0x0000000000100000-0x0000000007ffffff]  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.861096449-04:00] [    0.001786] Initmem setup node 0 [mem 0x0000000000001000-0x0000000007ffffff]  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.861985977-04:00] [    0.001831] On node 0, zone DMA: 1 pages in unavailable ranges  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.862888181-04:00] [    0.002217] On node 0, zone DMA: 97 pages in unavailable ranges  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.863644704-04:00] [    0.005127] Intel MultiProcessor Specification v1.4  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.864203839-04:00] [    0.005135] MPTABLE: OEM ID: FC            jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.864877317-04:00] [    0.005137] MPTABLE: Product ID: 000000000000  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.865484470-04:00] [    0.005139] MPTABLE: APIC at: 0xFEE00000   jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.866054980-04:00] [    0.005161] Processor #0 (Bootup-CPU)      jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.867094632-04:00] [    0.005290] IOAPIC[0]: apic_id 2, version 17, address 0xfec00000, GSI 0-23  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.867512310-04:00] [    0.005296] Processors: 1                  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.868121703-04:00] [    0.005305] TSC deadline timer available   jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.868881067-04:00] [    0.005309] smpboot: Allowing 1 CPUs, 0 hotplug CPUs  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.869637815-04:00] [    0.005337] kvm-guest: KVM setup pv remote TLB flush  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.870281448-04:00] [    0.005355] kvm-guest: setup PV sched yield  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.871426236-04:00] [    0.005392] PM: hibernation: Registered nosave memory: [mem 0x00000000-0x00000fff]  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.872581146-04:00] [    0.005395] PM: hibernation: Registered nosave memory: [mem 0x0009f000-0x000fffff]  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.873517948-04:00] [    0.005399] [mem 0x08000000-0xffffffff] available for PCI devices  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.874243314-04:00] [    0.005401] Booting paravirtualized kernel on KVM  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.875828183-04:00] [    0.005404] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.876993899-04:00] [    0.005416] setup_percpu: NR_CPUS:128 nr_cpumask_bits:128 nr_cpu_ids:1 nr_node_ids:1  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.877998936-04:00] [    0.007760] percpu: Embedded 52 pages/cpu s176128 r8192 d28672 u2097152  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.878756607-04:00] [    0.007802] kvm-guest: stealtime: cpu 0, msr 7a2a080  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.879578906-04:00] [    0.007808] kvm-guest: PV spinlocks disabled, single CPU  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.880594744-04:00] [    0.007819] Built 1 zonelists, mobility grouping on.  Total pages: 32137  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.881070125-04:00] [    0.007820] Policy zone: DMA32             jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.886365756-04:00] [    0.007822] Kernel command line: systemd.unit=firecracker.target console=ttyS0 noapic reboot=k panic=1 ro pci=off nomodules systemd.journald.forward_to_console init=/sbin/overlay-init ip=192.168.1.4::192.168.1.1:255.255.255.0:::off:198.22.255.3:: root=/dev/vda ro virtio_mmio.device=4K@0xd0000000:5 virtio_mmio.device=4K@0xd0001000:6 virtio_mmio.device=4K@0xd0002000:7 virtio_mmio.device=4K@0xd0003000:8  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.887536762-04:00] [    0.008130] Dentry cache hash table entries: 16384 (order: 5, 131072 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.888652836-04:00] [    0.008189] Inode-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.889608457-04:00] [    0.008243] mem auto-init: stack:off, heap alloc:off, heap free:off  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.891644816-04:00] [    0.008637] Memory: 96964K/130680K available (10243K kernel code, 7813K rwdata, 1956K rodata, 1680K init, 6780K bss, 33460K reserved, 0K cma-reserved)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.892635832-04:00] [    0.008792] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.893418482-04:00] [    0.008812] Kernel/User page tables isolation: enabled  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.894141444-04:00] [    0.009022] rcu: Hierarchical RCU implementation.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.895155016-04:00] [    0.009028] rcu: 	RCU restricting CPUs from NR_CPUS=128 to nr_cpu_ids=1.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.895895553-04:00] [    0.009029] 	Tracing variant of Tasks RCU enabled.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.897037049-04:00] [    0.009034] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.898054378-04:00] [    0.009035] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.898935549-04:00] [    0.009058] NR_IRQS: 4352, nr_irqs: 48, preallocated irqs: 16  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.899623140-04:00] [    0.009337] Console: colour dummy device 80x25  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.900272476-04:00] [    0.082193] printk: console [ttyS0] enabled  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.901066351-04:00] [    0.082867] APIC: Switch to symmetric I/O mode setup  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.902101708-04:00] [    0.083635] Not enabling interrupt remapping due to skipped IO-APIC setup  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.902659143-04:00] [    0.084672] kvm-guest: setup PV IPIs       jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.904299497-04:00] [    0.085264] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x1fb633008a4, max_idle_ns: 440795292230 ns  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.905583148-04:00] [    0.086865] Calibrating delay loop (skipped) preset value.. 4400.00 BogoMIPS (lpj=8800000)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.906543032-04:00] [    0.088253] Last level iTLB entries: 4KB 512, 2MB 8, 4MB 8  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.907496530-04:00] [    0.089097] Last level dTLB entries: 4KB 512, 2MB 0, 4MB 0, 1GB 4  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.908777431-04:00] [    0.090050] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.909491565-04:00] [    0.090861] Spectre V2 : Mitigation: Retpolines  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.910748880-04:00] [    0.090861] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.911787685-04:00] [    0.090861] Spectre V2 : Spectre v2 / SpectreRSB : Filling RSB on VMEXIT  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.912855123-04:00] [    0.090861] Spectre V2 : Enabling Restricted Speculation for firmware calls  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.914143053-04:00] [    0.090861] Spectre V2 : mitigation: Enabling conditional Indirect Branch Prediction Barrier  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.915607299-04:00] [    0.090861] Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl and seccomp  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.916305937-04:00] [    0.090861] MDS: Mitigation: Clear CPU buffers  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.917461735-04:00] [    0.090861] MMIO Stale Data: Vulnerable: Clear CPU buffers attempted, no microcode  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.918660098-04:00] [    0.090861] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.919643732-04:00] [    0.090861] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.920624340-04:00] [    0.090861] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.921571858-04:00] [    0.090861] x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.922971503-04:00] [    0.090861] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.945903447-04:00] [    0.090861] Freeing SMP alternatives memory: 32K  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.947297741-04:00] [    0.090861] pid_max: default: 32768 minimum: 301  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.948082135-04:00] [    0.090861] LSM: Security Framework initializing  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.948652526-04:00] [    0.090861] SELinux:  Initializing.        jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.949818145-04:00] [    0.090861] Mount-cache hash table entries: 512 (order: 0, 4096 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.950988987-04:00] [    0.090861] Mountpoint-cache hash table entries: 512 (order: 0, 4096 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.952977804-04:00] [    0.090861] smpboot: CPU0: Intel(R) Xeon(R) Processor @ 2.20GHz (family: 0x6, model: 0x3f, stepping: 0x2)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.954573147-04:00] [    0.090861] Performance Events: unsupported p6 CPU model 63 no PMU driver, software events only.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.955402938-04:00] [    0.090861] rcu: Hierarchical SRCU implementation.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.956550292-04:00] [    0.091162] smp: Bringing up secondary CPUs ...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.957170925-04:00] [    0.091880] smp: Brought up 1 node, 1 CPU  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.957829325-04:00] [    0.092502] smpboot: Max logical packages: 1  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.958840976-04:00] [    0.093162] smpboot: Total of 1 processors activated (4400.00 BogoMIPS)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.959514824-04:00] [    0.094316] devtmpfs: initialized          jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.960246130-04:00] [    0.094906] x86/mm: Memory block size: 128MB  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.962054935-04:00] [    0.095913] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.963093911-04:00] [    0.097382] futex hash table entries: 256 (order: 2, 16384 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.964136613-04:00] [    0.098770] NET: Registered protocol family 16  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.965417655-04:00] [    0.099070] DMA: preallocated 128 KiB GFP_KERNEL pool for atomic allocations  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.966593281-04:00] [    0.100149] DMA: preallocated 128 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.967800950-04:00] [    0.101324] DMA: preallocated 128 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.968640296-04:00] [    0.102534] audit: initializing netlink subsys (disabled)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.969948822-04:00] [    0.103233] thermal_sys: Registered thermal governor 'fair_share'  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.970860339-04:00] [    0.103234] thermal_sys: Registered thermal governor 'step_wise'  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.971808126-04:00] [    0.104168] thermal_sys: Registered thermal governor 'user_space'  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.972433803-04:00] [    0.105087] cpuidle: using governor ladder  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.973042217-04:00] [    0.106651] cpuidle: using governor menu   jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.975195689-04:00] [    0.108424] Kprobes globally optimized     jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.982390208-04:00] [    0.114873] audit: type=2000 audit(1693399447.842:1): state=initialized audit_enabled=0 res=1  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.990763979-04:00] [    0.123510] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.992549194-04:00] [    0.125737] ACPI: Interpreter disabled.    jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.993226327-04:00] [    0.126423] SCSI subsystem initialized     jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.994037713-04:00] [    0.126905] pps_core: LinuxPPS API ver. 1 registered  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.995426627-04:00] [    0.127670] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <[email protected]>  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.996038295-04:00] [    0.129058] PTP clock support registered   jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.996711076-04:00] [    0.129802] NetLabel: Initializing         jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.997375454-04:00] [    0.130338] NetLabel:  domain hash size = 128  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.998249442-04:00] [    0.130867] NetLabel:  protocols = UNLABELED CIPSOv4 CALIPSO  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:07.999126305-04:00] [    0.131753] NetLabel:  unlabeled traffic allowed by default  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.000870032-04:00] [    0.133487] clocksource: Switched to clocksource kvm-clock  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.001520317-04:00] [    0.134392] VFS: Disk quotas dquot_6.6.0   jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.002605656-04:00] [    0.134861] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.003232972-04:00] [    0.134861] pnp: PnP ACPI: disabled        jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.007141903-04:00] [    0.138137] NET: Registered protocol family 2  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.008281235-04:00] [    0.138850] IP idents hash table entries: 2048 (order: 2, 16384 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.009669893-04:00] [    0.140089] tcp_listen_portaddr_hash hash table entries: 256 (order: 0, 4096 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.010840022-04:00] [    0.141350] TCP established hash table entries: 1024 (order: 1, 8192 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.011938645-04:00] [    0.142525] TCP bind hash table entries: 1024 (order: 2, 16384 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.012912629-04:00] [    0.143615] TCP: Hash tables configured (established 1024 bind 1024)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.013966723-04:00] [    0.144607] UDP hash table entries: 256 (order: 1, 8192 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.015038852-04:00] [    0.145654] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes, linear)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.015757972-04:00] [    0.146755] NET: Registered protocol family 1  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.019361272-04:00] [    0.149738] virtio-mmio: Registering device virtio-mmio.0 at 0xd0000000-0xd0000fff, IRQ 5.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.020669560-04:00] [    0.151072] virtio-mmio: Registering device virtio-mmio.1 at 0xd0001000-0xd0001fff, IRQ 6.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.021947017-04:00] [    0.152361] virtio-mmio: Registering device virtio-mmio.2 at 0xd0002000-0xd0002fff, IRQ 7.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.023256890-04:00] [    0.153658] virtio-mmio: Registering device virtio-mmio.3 at 0xd0003000-0xd0003fff, IRQ 8.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.024795310-04:00] [    0.154948] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x1fb633008a4, max_idle_ns: 440795292230 ns  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.025876478-04:00] [    0.156776] clocksource: Switched to clocksource tsc  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.027066127-04:00] [    0.157569] platform rtc_cmos: registered platform RTC device (no PNP device found)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.028350759-04:00] [    0.159008] check: Scanning for low memory corruption every 60 seconds  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.029360169-04:00] [    0.160341] Initialise system trusted keyrings  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.030001496-04:00] [    0.161045] Key type blacklist registered  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.031521713-04:00] [    0.162194] workingset: timestamp_bits=36 max_order=15 bucket_order=0  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.033795982-04:00] [    0.164573] squashfs: version 4.0 (2009/01/31) Phillip Lougher  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.034420539-04:00] [    0.165469] fuse: init (API version 7.32)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.046208703-04:00] [    0.177219] Key type asymmetric registered  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.046981113-04:00] [    0.177898] Asymmetric key parser 'x509' registered  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.048119527-04:00] [    0.178667] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.049840335-04:00] [    0.180533] Serial: 8250/16550 driver, 1 ports, IRQ sharing disabled  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.051172201-04:00] [    0.181666] serial8250: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.142957221-04:00] [    0.273798] loop: module loaded            jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.145256530-04:00] [    0.275220] virtio_blk virtio0: [vda] 207792 512-byte logical blocks (106 MB/101 MiB)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.146514670-04:00] [    0.276927] vda: detected capacity change from 0 to 106389504  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.160123770-04:00] [    0.290271] virtio_blk virtio1: [vdb] 1 512-byte logical blocks (512 B/512 B)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.161234403-04:00] [    0.291795] vdb: detected capacity change from 0 to 512  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.171158858-04:00] [    0.301786] Loading iSCSI transport class v2.0-870.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.173156024-04:00] [    0.303900] iscsi: registered transport (tcp)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.174230570-04:00] [    0.304840] tun: Universal TUN/TAP device driver, 1.6  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.176222181-04:00] [    0.306878] i8042: PNP: No PS/2 controller found.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.177073557-04:00] [    0.307881] i8042: Probing ports directly.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.186223825-04:00] [    0.316652] i8042: Failed to disable AUX port, but continuing anyway... Is this a SiS?  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.187400566-04:00] [    0.317896] i8042: If AUX port is really absent please use the 'i8042.noaux' option  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.471686345-04:00] [    0.601951] serio: i8042 KBD port at 0x60,0x64 irq 1  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.473145520-04:00] [    0.603670] intel_pstate: CPU model not supported  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.474395320-04:00] [    0.604843] hid: raw HID events driver (C) Jiri Kosina  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.475744674-04:00] [    0.606374] Initializing XFRM netlink socket  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.476991127-04:00] [    0.607608] NET: Registered protocol family 10  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.479136214-04:00] [    0.609932] Segment Routing with IPv6      jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.480237993-04:00] [    0.610855] NET: Registered protocol family 17  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.481209878-04:00] [    0.611936] Bridge firewalling registered  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.482351842-04:00] [    0.612965] NET: Registered protocol family 40  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.484392629-04:00] [    0.615392] IPI shorthand broadcast: enabled  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.485628394-04:00] [    0.616107] sched_clock: Marking stable (536417724, 77607010)->(664914740, -50890006)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.485800656-04:00]                                               attempt=1 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:08.486108614-04:00]                                               attempt=2 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:08.486812770-04:00] [    0.617839] registered taskstats version 1  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.487560330-04:00] [    0.618484] Loading compiled-in X.509 certificates  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.489995925-04:00] [    0.620155] Loaded X.509 cert 'Build time autogenerated kernel key: 52d66e54fd7c12a9956528531fdb949547d0d5bb'  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.490665175-04:00] [    0.621719] Key type .fscrypt registered   jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.491423761-04:00] [    0.622331] Key type fscrypt-provisioning registered  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.492255210-04:00] [    0.623292] Key type encrypted registered  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:08.509947640-04:00]                                               attempt=3 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:08.610948408-04:00]                                               attempt=4 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:08.711014636-04:00]                                               attempt=5 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:08.811092639-04:00]                                               attempt=6 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:08.910272803-04:00]                                               attempt=7 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:08.985186406-04:00] [    1.114347] input: AT Raw Set 2 keyboard as /devices/platform/i8042/serio0/input/input0  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.003161980-04:00] [    1.133694] IP-Config: Complete:           jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.005625496-04:00] [    1.134817]      device=eth0, hwaddr=42:9f:50:a8:e1:97, ipaddr=192.168.1.4, mask=255.255.255.0, gw=192.168.1.1  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.007039195-04:00] [    1.137284]      host=192.168.1.4, domain=, nis-domain=(none)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.008934060-04:00] [    1.138714]      bootserver=255.255.255.255, rootserver=255.255.255.255, rootpath=  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.009962472-04:00] [    1.138716]      nameserver0=198.22.255.3  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.010273945-04:00]                                               attempt=8 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:09.014663374-04:00] [    1.144538] VFS: Mounted root (squashfs filesystem) readonly on device 254:0.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.015891244-04:00] [    1.146857] devtmpfs: mounted              jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.017819556-04:00] [    1.148409] Freeing unused decrypted memory: 2036K  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.019940459-04:00] [    1.150466] Freeing unused kernel image (initmem) memory: 1680K  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.022923901-04:00] [    1.153677] Write protecting the kernel read-only data: 14336k  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.025657876-04:00] [    1.156305] Freeing unused kernel image (text/rodata gap) memory: 2044K  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.026783308-04:00] [    1.157457] Freeing unused kernel image (rodata/data gap) memory: 92K  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.027548487-04:00] [    1.158464] Run /sbin/overlay-init as init process  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.110813742-04:00]                                               attempt=9 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:09.151066533-04:00] SELinux:  Could not open policy file <= /etc/selinux/targeted/policy/policy.33:  No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.156914110-04:00] [    1.287278] systemd[1]: Failed to look up module alias 'autofs4': Function not implemented  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.163677377-04:00] [    1.291846] systemd[1]: systemd 247.3-7+deb11u2 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +ZSTD +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=unified)  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.164551796-04:00] [    1.295435] systemd[1]: Detected virtualization kvm.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.165336065-04:00] [    1.296213] systemd[1]: Detected architecture x86-64.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.168814153-04:00]                                               jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.169400103-04:00] Welcome to Debian GNU/Linux 11 (bullseye)!  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.169479785-04:00]                                               jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.170602843-04:00] [    1.301508] systemd[1]: Set hostname to <microvm>.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.210222369-04:00]                                               attempt=10 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:09.304357024-04:00] [    1.434620] systemd[1]: rom.mount: Unit is bound to inactive unit dev-vda.device. Stopping, too.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.305994714-04:00] [    1.436405] systemd[1]: Queued start job for default target Firecracker containerd VM.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.307963224-04:00] [    1.438722] systemd[1]: Created slice system-modprobe.slice.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.308792884-04:00] [  OK  ] Created slice system-modprobe.slice.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.310184327-04:00] [    1.440604] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.310365190-04:00]                                               attempt=11 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:09.311290999-04:00] [  OK  ] Started Dispatch Password …ts to Console Directory Watch.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.312969921-04:00] [    1.443062] systemd[1]: Starting of Arbitrary Executable File Formats File System Automount Point not supported.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.314057822-04:00] [UNSUPP] Starting of Arbitrary Exec…Automount Point not supported.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.315084592-04:00] [    1.445817] systemd[1]: Reached target Local Encrypted Volumes.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.315889735-04:00] [  OK  ] Reached target Local Encrypted Volumes.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.316663741-04:00] [    1.447634] systemd[1]: Reached target Paths.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.317303201-04:00] [  OK  ] Reached target Paths.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.318098007-04:00] [    1.449044] systemd[1]: Reached target Slices.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.318761372-04:00] [  OK  ] Reached target Slices.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.319521342-04:00] [    1.450499] systemd[1]: Reached target Swap.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.320144944-04:00] [  OK  ] Reached target Swap.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.321302911-04:00] [    1.451948] systemd[1]: Listening on initctl Compatibility Named Pipe.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.322184089-04:00] [  OK  ] Listening on initctl Compatibility Named Pipe.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.323742942-04:00] [    1.454535] systemd[1]: Listening on Journal Audit Socket.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.324503731-04:00] [  OK  ] Listening on Journal Audit Socket.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.325638293-04:00] [    1.456377] systemd[1]: Listening on Journal Socket (/dev/log).  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.326460075-04:00] [  OK  ] Listening on Journal Socket (/dev/log).  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.328332493-04:00] [    1.459146] systemd[1]: Listening on udev Control Socket.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.329090236-04:00] [  OK  ] Listening on udev Control Socket.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.330143692-04:00] [    1.460967] systemd[1]: Listening on udev Kernel Socket.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.330920937-04:00] [  OK  ] Listening on udev Kernel Socket.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.332338672-04:00] [    1.463332] systemd[1]: Unmounting /rom...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.332864390-04:00]          Unmounting /rom...      jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.335514751-04:00] [    1.465498] systemd[508]: rom.mount: Failed to connect stdout to the journal socket, ignoring: No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.348402470-04:00] [    1.478844] systemd[1]: rom.mount: Mount process exited, code=exited, status=32/n/a  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.349122686-04:00] [    1.480068] systemd[1]: Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.349798168-04:00] [FAILED] Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.351246725-04:00] [    1.481557] systemd[1]: rom.mount: Unit is bound to inactive unit dev-vda.device. Stopping, too.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.352385780-04:00] [    1.483367] systemd[1]: Unmounting /rom...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.352922511-04:00]          Unmounting /rom...      jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.355038270-04:00] [    1.485034] systemd[509]: rom.mount: Failed to connect stdout to the journal socket, ignoring: No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.358356303-04:00] [    1.488822] systemd[1]: rom.mount: Mount process exited, code=exited, status=32/n/a  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.359116359-04:00] [    1.490060] systemd[1]: Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.359803735-04:00] [FAILED] Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.361257348-04:00] [    1.491559] systemd[1]: rom.mount: Unit is bound to inactive unit dev-vda.device. Stopping, too.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.362342544-04:00] [    1.493345] systemd[1]: Unmounting /rom...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.362940473-04:00]          Unmounting /rom...      jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.365178045-04:00] [    1.495169] systemd[510]: rom.mount: Failed to connect stdout to the journal socket, ignoring: No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.368459450-04:00] [    1.498915] systemd[1]: rom.mount: Mount process exited, code=exited, status=32/n/a  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.369177436-04:00] [    1.500122] systemd[1]: Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.369854144-04:00] [FAILED] Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.371346563-04:00] [    1.501651] systemd[1]: rom.mount: Unit is bound to inactive unit dev-vda.device. Stopping, too.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.372463901-04:00] [    1.503451] systemd[1]: Unmounting /rom...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.372992297-04:00]          Unmounting /rom...      jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.375115554-04:00] [    1.505109] systemd[511]: rom.mount: Failed to connect stdout to the journal socket, ignoring: No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.378398747-04:00] [    1.508855] systemd[1]: rom.mount: Mount process exited, code=exited, status=32/n/a  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.379149708-04:00] [    1.510097] systemd[1]: Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.379841550-04:00] [FAILED] Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.381291288-04:00] [    1.511598] systemd[1]: rom.mount: Unit is bound to inactive unit dev-vda.device. Stopping, too.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.382455334-04:00] [    1.513459] systemd[1]: Unmounting /rom...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.383044559-04:00]          Unmounting /rom...      jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.385176655-04:00] [    1.515166] systemd[512]: rom.mount: Failed to connect stdout to the journal socket, ignoring: No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.388464320-04:00] [    1.518935] systemd[1]: rom.mount: Mount process exited, code=exited, status=32/n/a  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.389182091-04:00] [    1.520127] systemd[1]: Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.389864036-04:00] [FAILED] Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.391351277-04:00] [    1.521661] systemd[1]: rom.mount: Unit is bound to inactive unit dev-vda.device. Stopping, too.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.392440558-04:00] [    1.523443] systemd[1]: Unmounting /rom...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.392982437-04:00]          Unmounting /rom...      jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.395089412-04:00] [    1.525092] systemd[513]: rom.mount: Failed to connect stdout to the journal socket, ignoring: No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.398457070-04:00] [    1.528907] systemd[1]: rom.mount: Mount process exited, code=exited, status=32/n/a  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.399211152-04:00] [    1.530148] systemd[1]: Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.399902104-04:00] [FAILED] Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.401344391-04:00] [    1.531656] systemd[1]: rom.mount: Unit is bound to inactive unit dev-vda.device. Stopping, too.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.402423006-04:00] [    1.533427] systemd[1]: Unmounting /rom...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.402998232-04:00]          Unmounting /rom...      jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.405142946-04:00] [    1.535136] systemd[514]: rom.mount: Failed to connect stdout to the journal socket, ignoring: No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.408417098-04:00] [    1.538874] systemd[1]: rom.mount: Mount process exited, code=exited, status=32/n/a  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.409135981-04:00] [    1.540078] systemd[1]: Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.409837200-04:00] [FAILED] Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.410004057-04:00]                                               attempt=12 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:09.411389769-04:00] [    1.541700] systemd[1]: rom.mount: Unit is bound to inactive unit dev-vda.device. Stopping, too.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.412570802-04:00] [    1.543574] systemd[1]: Unmounting /rom...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.413095494-04:00]          Unmounting /rom...      jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.415226139-04:00] [    1.545216] systemd[515]: rom.mount: Failed to connect stdout to the journal socket, ignoring: No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.418487230-04:00] [    1.548941] systemd[1]: rom.mount: Mount process exited, code=exited, status=32/n/a  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.419235092-04:00] [    1.550178] systemd[1]: Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.419918662-04:00] [FAILED] Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.421365009-04:00] [    1.551675] systemd[1]: rom.mount: Unit is bound to inactive unit dev-vda.device. Stopping, too.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.422444898-04:00] [    1.553447] systemd[1]: Unmounting /rom...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.423019146-04:00]          Unmounting /rom...      jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.425159097-04:00] [    1.555154] systemd[516]: rom.mount: Failed to connect stdout to the journal socket, ignoring: No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.428548667-04:00] [    1.559001] systemd[1]: rom.mount: Mount process exited, code=exited, status=32/n/a  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.429263592-04:00] [    1.560211] systemd[1]: Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.429935933-04:00] [FAILED] Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.431426177-04:00] [    1.561736] systemd[1]: rom.mount: Unit is bound to inactive unit dev-vda.device. Stopping, too.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.432545636-04:00] [    1.563524] systemd[1]: Unmounting /rom...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.433064303-04:00]          Unmounting /rom...      jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.435193077-04:00] [    1.565190] systemd[517]: rom.mount: Failed to connect stdout to the journal socket, ignoring: No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.438474629-04:00] [    1.568937] systemd[1]: rom.mount: Mount process exited, code=exited, status=32/n/a  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.439224182-04:00] [    1.570165] systemd[1]: Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.439918239-04:00] [FAILED] Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.441365018-04:00] [    1.571674] systemd[1]: rom.mount: Unit is bound to inactive unit dev-vda.device. Stopping, too.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.442452838-04:00] [    1.573457] systemd[1]: Unmounting /rom...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.443043062-04:00]          Unmounting /rom...      jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.445282961-04:00] [    1.575280] systemd[518]: rom.mount: Failed to connect stdout to the journal socket, ignoring: No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.448571727-04:00] [    1.579025] systemd[1]: rom.mount: Mount process exited, code=exited, status=32/n/a  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.449298076-04:00] [    1.580233] systemd[1]: Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.449979896-04:00] [FAILED] Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.451476921-04:00] [    1.581773] systemd[1]: rom.mount: Unit is bound to inactive unit dev-vda.device. Stopping, too.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.452555515-04:00] [    1.583558] systemd[1]: Unmounting /rom...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.453089386-04:00]          Unmounting /rom...      jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.455229398-04:00] [    1.585223] systemd[519]: rom.mount: Failed to connect stdout to the journal socket, ignoring: No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.458521795-04:00] [    1.588983] systemd[1]: rom.mount: Mount process exited, code=exited, status=32/n/a  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.459278194-04:00] [    1.590221] systemd[1]: Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.459965516-04:00] [FAILED] Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.461408498-04:00] [    1.591718] systemd[1]: rom.mount: Unit is bound to inactive unit dev-vda.device. Stopping, too.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.462579684-04:00] [    1.593583] systemd[1]: Unmounting /rom...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.463166333-04:00]          Unmounting /rom...      jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.465313771-04:00] [    1.595308] systemd[520]: rom.mount: Failed to connect stdout to the journal socket, ignoring: No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.468587722-04:00] [    1.599044] systemd[1]: rom.mount: Mount process exited, code=exited, status=32/n/a  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.469301241-04:00] [    1.600248] systemd[1]: Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.470007402-04:00] [FAILED] Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.471477831-04:00] [    1.601781] systemd[1]: rom.mount: Unit is bound to inactive unit dev-vda.device. Stopping, too.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.472559291-04:00] [    1.603560] systemd[1]: Unmounting /rom...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.473087695-04:00]          Unmounting /rom...      jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.475251577-04:00] [    1.605227] systemd[521]: rom.mount: Failed to connect stdout to the journal socket, ignoring: No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.478615273-04:00] [    1.609062] systemd[1]: rom.mount: Mount process exited, code=exited, status=32/n/a  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.479357366-04:00] [    1.610304] systemd[1]: Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.480044966-04:00] [FAILED] Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.481487058-04:00] [    1.611795] systemd[1]: rom.mount: Unit is bound to inactive unit dev-vda.device. Stopping, too.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.482573203-04:00] [    1.613572] systemd[1]: Unmounting /rom...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.483149381-04:00]          Unmounting /rom...      jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.485296262-04:00] [    1.615292] systemd[522]: rom.mount: Failed to connect stdout to the journal socket, ignoring: No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.488570740-04:00] [    1.619027] systemd[1]: rom.mount: Mount process exited, code=exited, status=32/n/a  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.489285723-04:00] [    1.620231] systemd[1]: Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.489974955-04:00] [FAILED] Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.491480561-04:00] [    1.621774] systemd[1]: rom.mount: Unit is bound to inactive unit dev-vda.device. Stopping, too.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.492678431-04:00] [    1.623660] systemd[1]: Unmounting /rom...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.493206840-04:00]          Unmounting /rom...      jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.495341002-04:00] [    1.625330] systemd[523]: rom.mount: Failed to connect stdout to the journal socket, ignoring: No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.498631712-04:00] [    1.629097] systemd[1]: rom.mount: Mount process exited, code=exited, status=32/n/a  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.499375665-04:00] [    1.630323] systemd[1]: Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.500074164-04:00] [FAILED] Failed unmounting /rom.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.502042336-04:00] [    1.631814] systemd[1]: rom.mount: Unit is bound to inactive unit dev-vda.device, but not stopping since we tried this too often recently.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.503078744-04:00] [    1.633952] systemd[1]: Listening on Journal Socket.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.503796901-04:00] [  OK  ] Listening on Journal Socket.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.504615830-04:00] [    1.635560] systemd[1]: Reached target Sockets.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.505276902-04:00] [  OK  ] Reached target Sockets.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.507234123-04:00] [    1.638026] systemd[1]: Mounting Huge Pages File System...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.507958205-04:00]          Mounting Huge Pages File System...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.510054814-04:00] [    1.640726] systemd[1]: Mounting POSIX Message Queue File System...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.510360976-04:00]                                               attempt=13 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:09.513079987-04:00]          Mounting POSIX Message Queue File System...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.517292567-04:00] [    1.648047] systemd[1]: Mounting Kernel Debug File System...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.518004139-04:00]          Mounting Kernel Debug File System...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.519584682-04:00] [    1.649941] systemd[1]: Condition check resulted in Kernel Trace File System being skipped.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.521349087-04:00] [    1.651302] systemd[1]: Condition check resulted in Create list of static device nodes for the current kernel being skipped.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.525522906-04:00] [    1.656245] systemd[1]: Starting Load Kernel Module configfs...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.526264407-04:00]          Starting Load Kernel Module configfs...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.528235092-04:00] [    1.659006] systemd[1]: Starting Load Kernel Module fuse...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.528920207-04:00]          Starting Load Kernel Module fuse...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.532604836-04:00] [    1.662859] systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.535083964-04:00] [    1.665972] systemd[1]: Starting Journal Service...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.535716900-04:00]          Starting Journal Service...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.538142436-04:00] [    1.668960] systemd[1]: Starting Load Kernel Modules...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.542735812-04:00]          Starting Load Kernel Modules...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.554889830-04:00] [    1.685475] systemd[1]: Starting Remount Root and Kernel File Systems...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.556398338-04:00]          Starting Remount Root and Kernel File Systems...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.567973221-04:00] [    1.698640] systemd[1]: Starting Coldplug All udev Devices...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.568667727-04:00]          Starting Coldplug All udev Devices...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.576670023-04:00] [    1.707447] systemd[1]: Mounted Huge Pages File System.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.577390520-04:00] [  OK  ] Mounted Huge Pages File System.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.584680126-04:00] [    1.715373] systemd[1]: Mounted POSIX Message Queue File System.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.585497453-04:00] [  OK  ] Mounted POSIX Message Queue File System.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.591998157-04:00] [    1.722779] systemd[1]: Mounted Kernel Debug File System.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.592766015-04:00] [  OK  ] Mounted Kernel Debug File System.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.599144563-04:00] [    1.729889] systemd[1]: [email protected]: Succeeded.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.602988805-04:00] [    1.733680] systemd[1]: Finished Load Kernel Module configfs.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.603813793-04:00] [  OK  ] Finished Load Kernel Module configfs.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.610619185-04:00] [    1.741388] systemd[1]: [email protected]: Succeeded.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.610783642-04:00]                                               attempt=14 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:09.613190091-04:00] [    1.743952] systemd[1]: Finished Load Kernel Module fuse.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.613954559-04:00] [  OK  ] Finished Load Kernel Module fuse.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.620682307-04:00] [    1.751512] systemd[1]: Finished Load Kernel Modules.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.621396043-04:00] [  OK  ] Finished Load Kernel Modules.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.631152745-04:00] [    1.761740] systemd[1]: Finished Remount Root and Kernel File Systems.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.632029264-04:00] [  OK  ] Finished Remount Root and Kernel File Systems.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.636291273-04:00] [    1.767043] systemd[1]: Mounting FUSE Control File System...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.637038705-04:00]          Mounting FUSE Control File System...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.655610924-04:00] [    1.785816] systemd[1]: Condition check resulted in Kernel Configuration File System being skipped.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.660201439-04:00] [    1.790515] systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.661712406-04:00] [    1.791903] systemd[1]: Condition check resulted in Platform Persistent Storage Archival being skipped.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.668372701-04:00] [    1.721070] systemd[527]: [email protected]: Executable /sbin/modprobe missing, skipping: No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.669864556-04:00] [    1.800662] systemd[1]: Starting Load/Save Random Seed...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.670544589-04:00]          Starting Load/Save Random Seed...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.672284886-04:00] [    1.725051] systemd[528]: [email protected]: Executable /sbin/modprobe missing, skipping: No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.685171224-04:00] [    1.815924] systemd[1]: Starting Apply Kernel Variables...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.685844558-04:00]          Starting Apply Kernel Variables...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.687504546-04:00] [    1.740401] systemd-random-seed[622]: Kernel entropy pool is not initialized yet, waiting until it is.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.696855203-04:00] [    1.827651] systemd[1]: Starting Create System Users...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.697509082-04:00]          Starting Create System Users...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.710252613-04:00]                                               attempt=15 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:09.725365551-04:00] [    1.856229] systemd[1]: Started Journal Service.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.726247099-04:00] [  OK  ] Started Journal Service.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.746977659-04:00] [    1.800281] systemd[1]: Mounted FUSE Control File System.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.751956376-04:00] [  OK  ] Mounted FUSE Control File System.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.757551347-04:00] [    1.810876] systemd[1]: Finished Coldplug All udev Devices.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.758510959-04:00] [  OK  ] Finished Coldplug All udev Devices.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.761708921-04:00] [    1.815061] systemd[1]: Finished Apply Kernel Variables.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.762674651-04:00] [  OK  ] Finished Apply Kernel Variables.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.765183833-04:00] [    1.818316] systemd-sysusers[624]: Creating group systemd-timesync with gid 999.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.769239067-04:00] [    1.821963] systemd-sysusers[624]: Creating user systemd-timesync (systemd Time Synchronization) with uid 999 and gid 999.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.770991705-04:00] [    1.824105] systemd-sysusers[624]: Creating group systemd-coredump with gid 998.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.772770154-04:00] [    1.825600] systemd-sysusers[624]: Creating user systemd-coredump (systemd Core Dumper) with uid 998 and gid 998.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.774735155-04:00]          Starting Flush Journal to Persistent Storage...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.778659442-04:00] [    1.831858] systemd[1]: Starting Flush Journal to Persistent Storage...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.787566370-04:00] [  OK  ] Finished Create System Users.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.789851171-04:00] [    1.920276] systemd-journald[529]: Received client request to flush runtime journal.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.792451836-04:00]          Starting Create Static Device Nodes in /dev...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.808585213-04:00] [  OK  ] Finished Flush Journal to Persistent Storage.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.809813189-04:00] [    1.863145] systemd[1]: Finished Create System Users.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.809971381-04:00]                                               attempt=16 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:09.812571886-04:00] [    1.865769] systemd[1]: Starting Create Static Device Nodes in /dev...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.818800437-04:00] [  OK  ] Finished Create Static Device Nodes in /dev.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.828459488-04:00] [  OK  ] Reached target Local File Systems (Pre).  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.829205109-04:00] [  OK  ] Reached target Local File Systems.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.829950234-04:00] [    1.875663] systemd[1]: Finished Flush Journal to Persistent Storage.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.830809234-04:00] [    1.884153] systemd[1]: Finished Create Static Device Nodes in /dev.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.831631685-04:00] [    1.884960] systemd[1]: Reached target Local File Systems (Pre).  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.832368193-04:00] [    1.885789] systemd[1]: Reached target Local File Systems.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.834377841-04:00]          Starting Create Volatile Files and Directories...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.835284906-04:00] [    1.888607] systemd[1]: Starting Create Volatile Files and Directories...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.851462010-04:00] [    1.904646] systemd[1]: Starting Rule-based Manager for Device Events and Files...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.852581039-04:00]          Starting Rule-based Manage…for Device Events and Files...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.870704626-04:00] [    1.923583] systemd-tmpfiles[770]: Detected unsafe path transition /var → /var/lib during canonicalization of /var/lib.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.873007169-04:00] [    1.925853] systemd-tmpfiles[770]: Detected unsafe path transition /var → /var/lib during canonicalization of /var/lib/systemd.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.875050905-04:00] [    1.927861] systemd-tmpfiles[770]: Detected unsafe path transition /var → /var/lib during canonicalization of /var/lib/systemd.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.879281414-04:00] [    1.932112] systemd-tmpfiles[770]: Detected unsafe path transition /var → /var/lib during canonicalization of /var/lib.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.882186600-04:00] [    1.935083] systemd-tmpfiles[770]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.886751883-04:00] [    1.939624] systemd-tmpfiles[770]: Detected unsafe path transition /var → /var/cache during canonicalization of /var/cache.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.888015326-04:00] [  OK  ] Finished Create Volatile Files and Directories.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.890382947-04:00] [  OK  ] Started Entropy Daemon based on the HAVEGE algorithm.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.899513258-04:00] [    1.952284] systemd-tmpfiles[770]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.903121694-04:00]          Starting Update UTMP about System Boot/Shutdown...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.910872011-04:00]                                               attempt=17 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:09.912340850-04:00] [    1.965204] systemd-tmpfiles[770]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.923389876-04:00] [    1.976288] systemd-tmpfiles[770]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.929424212-04:00] [    1.982244] systemd-tmpfiles[770]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log/journal.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.932707692-04:00] [  OK  ] Finished Update UTMP about System Boot/Shutdown.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.935835838-04:00] [    1.988668] systemd-tmpfiles[770]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log/journal.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.942850932-04:00] [    1.995640] systemd-tmpfiles[770]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log/journal.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.944930047-04:00] [  OK  ] Started Rule-based Manager for Device Events and Files.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.945739817-04:00] [  OK  ] Reached target System Initialization.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.947189286-04:00] [  OK  ] Started Periodic ext4 Onli…ata Check for All Filesystems.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.948123934-04:00] [  OK  ] Started Discard unused blocks once a week.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.948994542-04:00] [  OK  ] Started Daily Cleanup of Temporary Directories.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.949702401-04:00] [  OK  ] Reached target Basic System.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.950405316-04:00] [  OK  ] Reached target Timers.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.955777895-04:00] [    2.008338] systemd-tmpfiles[770]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log/journal/d9d2a514ecd64b45aca42e0adcd4b566.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.957302776-04:00] [    2.009915] systemd-tmpfiles[770]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log/journal/d9d2a514ecd64b45aca42e0adcd4b566.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.958911970-04:00] [    2.011469] systemd-tmpfiles[770]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log/journal/d9d2a514ecd64b45aca42e0adcd4b566.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.971589030-04:00] [  OK  ] Started Firecracker VM agent.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.974808150-04:00] [    2.027236] systemd-tmpfiles[770]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log/journal/d9d2a514ecd64b45aca42e0adcd4b566/system.journal.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.983146213-04:00] [    2.036461] haveged[772]: haveged: command socket is listening at fd 3  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.989536586-04:00]          Starting Stargz Snapshotter...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:09.994156597-04:00] [    2.046587] systemd-tmpfiles[770]: Detected unsafe path transition /var → /var/log during canonicalization of /var/log/journal/d9d2a514ecd64b45aca42e0adcd4b566/system.journal.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.006387355-04:00] [  OK  ] Started Stargz Snapshotter.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.007418812-04:00] [    2.060743] systemd[1]: Finished Create Volatile Files and Directories.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.008439523-04:00] [    2.061706] systemd[1]: Started Entropy Daemon based on the HAVEGE algorithm.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.009466470-04:00] [    2.062732] systemd[1]: Starting Update UTMP about System Boot/Shutdown...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.009852154-04:00]                                               attempt=18 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:10.024855556-04:00] [    2.078108] systemd[1]: Finished Update UTMP about System Boot/Shutdown.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.029461944-04:00] [    2.082682] systemd[1]: Started Rule-based Manager for Device Events and Files.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.039953451-04:00] [  OK  ] Started Metrics Socat.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.044461547-04:00] [    2.097849] systemd[1]: Reached target System Initialization.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.049175415-04:00] [    2.102350] systemd[1]: Started Periodic ext4 Online Metadata Check for All Filesystems.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.052755377-04:00] [  OK  ] Started Socat.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.061791081-04:00] [    2.115120] systemd[1]: Started Discard unused blocks once a week.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.064118038-04:00] [  OK  ] Reached target Firecracker containerd VM.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.072528627-04:00] [    2.125810] systemd[1]: Started Daily Cleanup of Temporary Directories.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.079058486-04:00] [    2.132494] systemd[1]: Reached target Basic System.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.084597311-04:00] [    2.138059] systemd[1]: Reached target Timers.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.091445537-04:00] [    2.144840] systemd[1]: Started Firecracker VM agent.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.104112607-04:00] [    2.157512] systemd[1]: Starting Stargz Snapshotter...  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.110471198-04:00] [    2.163798] systemd[1]: Started Stargz Snapshotter.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.110654868-04:00]                                               attempt=19 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:10.117898193-04:00] [    2.171390] systemd[1]: Started Metrics Socat.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.124099258-04:00] [    2.177497] systemd[1]: Started Socat.     jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.131068225-04:00] [    2.184377] systemd[1]: Reached target Firecracker containerd VM.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.211054299-04:00]                                               attempt=20 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:10.309944121-04:00]                                               attempt=21 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:10.411121372-04:00]                                               attempt=22 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:10.510020098-04:00]                                               attempt=23 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:10.611287854-04:00]                                               attempt=24 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:10.615271198-04:00] [    2.668113] systemd-udevd[777]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.710783494-04:00]                                               attempt=25 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:10.811467229-04:00]                                               attempt=26 error="temporary vsock dial failure: vsock ack message failure: failed to read \"OK <port>\" within 1s: EOF" runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:10.814246291-04:00] [    2.867326] agent[786]: time="2023-08-30T12:44:10Z" level=info msg="creating task service"  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.896798256-04:00] [    2.949961] systemd-udevd[779]: Using default interface naming scheme 'v247'.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
INFO[2023-08-30T08:44:10.910694968-04:00] successfully started the VM                   runtime=aws.firecracker vmID=vm1
DEBU[2023-08-30T08:44:10.910828953-04:00] event published                               ns=vm1 runtime=aws.firecracker topic=/firecracker-vm/start type=VMStart
DEBU[2023-08-30T08:44:10.911519498-04:00] event forwarded                               ns=vm1 topic=/firecracker-vm/start type=VMStart
DEBU[2023-08-30T08:44:10.911807068-04:00] Setting vm metadata
INFO[2023-08-30T08:44:10.912229160-04:00] setting VM metadata                           runtime=aws.firecracker vmID=vm1
INFO[2023-08-30T08:44:10.912669259-04:00] SetMetadata successful                        runtime=aws.firecracker
DEBU[2023-08-30T08:44:10.923134365-04:00] (*service).Write started                      expected="sha256:de4c1bb95c15e4c46d37c1822b51b7f0f918823fd00fe1aa8054eb4d94ff279a" ref="manifest-sha256:de4c1bb95c15e4c46d37c1822b51b7f0f918823fd00fe1aa8054eb4d94ff279a" total=739
ERRO[2023-08-30T08:44:10.934744324-04:00] aws.firecracker: publisher not closed         shim_stream=stderr vmID=vm1
DEBU[2023-08-30T08:44:10.937722391-04:00] (*service).Write started                      expected="sha256:88621c9e6fbcf744b05c7b39b1646cddedb0ef215afe41545285d0c46650b260" ref="config-sha256:88621c9e6fbcf744b05c7b39b1646cddedb0ef215afe41545285d0c46650b260" total=6851
DEBU[2023-08-30T08:44:10.947648848-04:00] [    3.000343] systemd-udevd[779]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.952627464-04:00] stat snapshot                                 key="sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61"
DEBU[2023-08-30T08:44:10.953417284-04:00] prepare snapshot                              key="extract-952984902-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61" parent=
DEBU[2023-08-30T08:44:10.955642550-04:00] get VM info: VMID:"vm1"
DEBU[2023-08-30T08:44:10.995970956-04:00] [    3.048879] haveged[772]: haveged: ver: 1.9.14; arch: x86; vend: GenuineIntel; build: (gcc 10.2.1 ITV); collect: 128K  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.997458216-04:00] [    3.050355] haveged[772]: haveged: cpu: (L4 VC); data: 32K (L4 V); inst: 32K (L4 V); idx: 24/40; sz: 32154/54019  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:10.999203678-04:00] [    3.052093] haveged[772]: haveged: tot tests(BA8): A:1/1 B:1/1 continuous tests(B):  last entropy estimate 8.00047  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:11.002946559-04:00] [    3.056340] haveged[772]: haveged: fills: 0, generated: 0  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:11.024931220-04:00] [    3.156026] random: crng init done         jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:11.028871867-04:00] [  OK  ] Finished Load/Save Random Seed.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:11.029748796-04:00] [    3.083164] systemd[1]: Finished Load/Save Random Seed.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:11.031176534-04:00] [    3.084321] systemd[1]: Condition check resulted in First Boot Complete being skipped.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:11.032426068-04:00] [    3.085400] systemd[1]: Condition check resulted in Store a System Token in an EFI Variable being skipped.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:11.034481405-04:00] [    3.087482] systemd[1]: Condition check resulted in Commit a transient machine-id on disk being skipped.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:11.036501167-04:00] [    3.089653] systemd[1]: Startup finished in 1.185s (kernel) + 1.899s (userspace) = 3.085s.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:11.063373699-04:00] [    3.113849] socat[804]: 2023/08/30 12:44:10 socat[804] E connect(5, AF=1 "/run/containerd-stargz-grpc/containerd-stargz-grpc.sock", 57): No such file or directory  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:11.244312860-04:00] [    3.296821] systemd[1]: var-lib-containerd\x2dstargz\x2dgrpc-snapshotter-multiple\x2dlowerdir\x2dcheck2347827970-merged.mount: Succeeded.  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:12.195616342-04:00] [    4.246774] containerd-stargz-grpc[789]: {"key":"vm1/3/extract-952984902-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"info","msg":"preparing filesystem mount at mountpoint=/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","parent":"","time":"2023-08-30T12:44:12.063767038Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:12.205021074-04:00] [    4.255252] containerd-stargz-grpc[789]: {"key":"vm1/3/extract-952984902-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"resolving","parent":"","src":"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:39101e45ea8f759456d6919a66a7f9a79fef04873be9d7ecb634e11b087b3556","time":"2023-08-30T12:44:12.072606843Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:12.210603541-04:00] [    4.260799] containerd-stargz-grpc[789]: {"key":"vm1/3/extract-952984902-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"resolving","parent":"","src":"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749","time":"2023-08-30T12:44:12.077796645Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:12.220646514-04:00] [    4.269341] containerd-stargz-grpc[789]: {"digest":"sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749","error":null,"key":"vm1/3/extract-952984902-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"using default handler","parent":"","ref":"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz","src":"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749","time":"2023-08-30T12:44:12.077914480Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:12.226085528-04:00] [    4.274898] containerd-stargz-grpc[789]: {"digest":"sha256:39101e45ea8f759456d6919a66a7f9a79fef04873be9d7ecb634e11b087b3556","error":null,"key":"vm1/3/extract-952984902-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"using default handler","parent":"","ref":"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz","src":"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:39101e45ea8f759456d6919a66a7f9a79fef04873be9d7ecb634e11b087b3556","time":"2023-08-30T12:44:12.084468006Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:12.231591069-04:00] [    4.280182] containerd-stargz-grpc[789]: {"error":"Get \"http://localhost:5000/v2/curiousgeorgiy/nginx/blobs/sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749\": dial tcp [::1]:5000: connect: connection refused","key":"vm1/3/extract-952984902-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"Retrying request","parent":"","src":"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749","time":"2023-08-30T12:44:12.086537589Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:12.236999939-04:00] [    4.285684] containerd-stargz-grpc[789]: {"error":"Get \"http://localhost:5000/v2/curiousgeorgiy/nginx/blobs/sha256:39101e45ea8f759456d6919a66a7f9a79fef04873be9d7ecb634e11b087b3556\": dial tcp [::1]:5000: connect: connection refused","key":"vm1/3/extract-952984902-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"Retrying request","parent":"","src":"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:39101e45ea8f759456d6919a66a7f9a79fef04873be9d7ecb634e11b087b3556","time":"2023-08-30T12:44:12.086656497Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:12.254951860-04:00] [    4.300945] containerd-stargz-grpc[789]: {"error":"Get \"http://localhost:5000/v2/curiousgeorgiy/nginx/blobs/sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749\": dial tcp [::1]:5000: connect: connection refused","key":"vm1/3/extract-952984902-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"Retrying request","parent":"","src":"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749","time":"2023-08-30T12:44:12.118246120Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:12.280633097-04:00] [    4.325222] containerd-stargz-grpc[789]: {"error":"Get \"http://localhost:5000/v2/curiousgeorgiy/nginx/blobs/sha256:39101e45ea8f759456d6919a66a7f9a79fef04873be9d7ecb634e11b087b3556\": dial tcp [::1]:5000: connect: connection refused","key":"vm1/3/extract-952984902-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"Retrying request","parent":"","src":"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:39101e45ea8f759456d6919a66a7f9a79fef04873be9d7ecb634e11b087b3556","time":"2023-08-30T12:44:12.142386497Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:12.364918845-04:00] [    4.409043] containerd-stargz-grpc[789]: {"error":"Get \"http://localhost:5000/v2/curiousgeorgiy/nginx/blobs/sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749\": dial tcp [::1]:5000: connect: connection refused","key":"vm1/3/extract-952984902-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"Retrying request","parent":"","src":"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749","time":"2023-08-30T12:44:12.226120131Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:12.371915209-04:00] [    4.420617] containerd-stargz-grpc[789]: {"error":"Get \"http://localhost:5000/v2/curiousgeorgiy/nginx/blobs/sha256:39101e45ea8f759456d6919a66a7f9a79fef04873be9d7ecb634e11b087b3556\": dial tcp [::1]:5000: connect: connection refused","key":"vm1/3/extract-952984902-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"Retrying request","parent":"","src":"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:39101e45ea8f759456d6919a66a7f9a79fef04873be9d7ecb634e11b087b3556","time":"2023-08-30T12:44:12.237899979Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:12.491617951-04:00] [    4.534218] containerd-stargz-grpc[789]: {"error":"Get \"http://localhost:5000/v2/curiousgeorgiy/nginx/blobs/sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749\": dial tcp [::1]:5000: connect: connection refused","key":"vm1/3/extract-952984902-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"Retrying request","parent":"","src":"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749","time":"2023-08-30T12:44:12.351370855Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:12.512376654-04:00] [    4.557958] containerd-stargz-grpc[789]: {"error":"Get \"http://localhost:5000/v2/curiousgeorgiy/nginx/blobs/sha256:39101e45ea8f759456d6919a66a7f9a79fef04873be9d7ecb634e11b087b3556\": dial tcp [::1]:5000: connect: connection refused","key":"vm1/3/extract-952984902-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"Retrying request","parent":"","src":"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:39101e45ea8f759456d6919a66a7f9a79fef04873be9d7ecb634e11b087b3556","time":"2023-08-30T12:44:12.375254147Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:12.815577158-04:00] [    4.859481] containerd-stargz-grpc[789]: {"error":"Get \"http://localhost:5000/v2/curiousgeorgiy/nginx/blobs/sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749\": dial tcp [::1]:5000: connect: connection refused","key":"vm1/3/extract-952984902-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"Retrying request","parent":"","src":"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749","time":"2023-08-30T12:44:12.676650718Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:12.886914036-04:00] [    4.930651] containerd-stargz-grpc[789]: {"error":"Get \"http://localhost:5000/v2/curiousgeorgiy/nginx/blobs/sha256:39101e45ea8f759456d6919a66a7f9a79fef04873be9d7ecb634e11b087b3556\": dial tcp [::1]:5000: connect: connection refused","key":"vm1/3/extract-952984902-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"Retrying request","parent":"","src":"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:39101e45ea8f759456d6919a66a7f9a79fef04873be9d7ecb634e11b087b3556","time":"2023-08-30T12:44:12.747865202Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:13.418611991-04:00] [    5.462240] containerd-stargz-grpc[789]: {"error":"Get \"http://localhost:5000/v2/curiousgeorgiy/nginx/blobs/sha256:39101e45ea8f759456d6919a66a7f9a79fef04873be9d7ecb634e11b087b3556\": dial tcp [::1]:5000: connect: connection refused","key":"vm1/3/extract-952984902-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"Retrying request","parent":"","src":"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:39101e45ea8f759456d6919a66a7f9a79fef04873be9d7ecb634e11b087b3556","time":"2023-08-30T12:44:13.278208073Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:13.426712243-04:00] [    5.472705] containerd-stargz-grpc[789]: {"error":"failed to resolve the blob: failed to resolve the source: cannot resolve layer: failed to redirect (host \"localhost:5000\", ref:\"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz\", digest:\"sha256:39101e45ea8f759456d6919a66a7f9a79fef04873be9d7ecb634e11b087b3556\"): failed to request: GET http://localhost:5000/v2/curiousgeorgiy/nginx/blobs/sha256:39101e45ea8f759456d6919a66a7f9a79fef04873be9d7ecb634e11b087b3556 giving up after 6 attempt(s): Get \"http://localhost:5000/v2/curiousgeorgiy/nginx/blobs/sha256:39101e45ea8f759456d6919a66a7f9a79fef04873be9d7ecb634e11b087b3556\": dial tcp [::1]:5000: connect: connection refused: failed to resolve","key":"vm1/3/extract-952984902-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"failed to pre-resolve","parent":"","time":"2023-08-30T12:44:13.278569073Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:13.489549622-04:00] event published                               ns=vm1 topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2023-08-30T08:44:13.490324596-04:00] (*service).Write started                      expected="sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749" ref="layer-sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749" total=2825362
DEBU[2023-08-30T08:44:13.490324730-04:00] (*service).Write started                      expected="sha256:39101e45ea8f759456d6919a66a7f9a79fef04873be9d7ecb634e11b087b3556" ref="layer-sha256:39101e45ea8f759456d6919a66a7f9a79fef04873be9d7ecb634e11b087b3556" total=5827292
DEBU[2023-08-30T08:44:13.497261573-04:00] [    5.542391] containerd-stargz-grpc[789]: {"error":"Get \"http://localhost:5000/v2/curiousgeorgiy/nginx/blobs/sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749\": dial tcp [::1]:5000: connect: connection refused","key":"vm1/3/extract-952984902-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"Retrying request","parent":"","src":"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz/sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749","time":"2023-08-30T12:44:13.356765687Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:13.507005236-04:00] [    5.551587] containerd-stargz-grpc[789]: {"error":"failed to resolve layer \"sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749\" from \"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz\": failed to resolve the blob: failed to resolve the source: cannot resolve layer: failed to redirect (host \"localhost:5000\", ref:\"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz\", digest:\"sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749\"): failed to request: GET http://localhost:5000/v2/curiousgeorgiy/nginx/blobs/sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749 giving up after 6 attempt(s): Get \"http://localhost:5000/v2/curiousgeorgiy/nginx/blobs/sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749\": dial tcp [::1]:5000: connect: connection refused: failed to resolve: failed to resolve target","key":"vm1/3/extract-952984902-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"debug","mountpoint":"/var/lib/containerd-stargz-grpc/snapshotter/snapshots/1/fs","msg":"failed to resolve layer","parent":"","time":"2023-08-30T12:44:13.357095941Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout
DEBU[2023-08-30T08:44:13.516660466-04:00] [    5.561102] containerd-stargz-grpc[789]: {"error":"failed to resolve layer: failed to resolve layer \"sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749\" from \"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz\": failed to resolve the blob: failed to resolve the source: cannot resolve layer: failed to redirect (host \"localhost:5000\", ref:\"localhost:5000/curiousgeorgiy/nginx:1.17-alpine-esgz\", digest:\"sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749\"): failed to request: GET http://localhost:5000/v2/curiousgeorgiy/nginx/blobs/sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749 giving up after 6 attempt(s): Get \"http://localhost:5000/v2/curiousgeorgiy/nginx/blobs/sha256:8144743f1ee986a69ee2cceda7e902bb72cb9908ad794c42025b9fd3803ba749\": dial tcp [::1]:5000: connect: connection refused: failed to resolve: failed to resolve target","key":"vm1/3/extract-952984902-ByGC sha256:be13cd5a2600b1272ee3ceb62ab3bb516fd3f4943b02a5099ecadad4baddee61","level":"warning","msg":"failed to prepare remote snapshot","parent":"","remote-snapshot-prepared":"false","time":"2023-08-30T12:44:13.359105721Z"}  jailer=noop runtime=aws.firecracker vmID=vm1 vmm_stream=stdout

Again, I can pull from the local registry using docker just fine.

@CuriousGeorgiy CuriousGeorgiy changed the title Remote snapshotter example fails with ttrpc: refusing connection after handshake error Remote snapshotter example fails on docker image with failed to mount <...>: no such file or directory: unknown error Aug 28, 2023
@andre-j3sus
Copy link

I fixed the issue with pulling images from docker.io. The error indicated a problem retrieving credentials:

error getting credentials - err: exit status 1, out: `no key for https://index.docker.io/v1/`

The code in the example was setting the key as docker.io, but containerd-stargz-grpc expects credentials with the key https://index.docker.io/v1/. To resolve this, I added the following if statement to handle docker.io:

dockerHost := refSpec.Hostname()
// Adjust host key for Docker Hub
if dockerHost == "docker.io" {
    dockerHost = "https://index.docker.io/v1/"
}

With this change, the custom image was successfully pulled, and the container started as expected.

Next, I’ll address the issue with the local registry.

@andre-j3sus
Copy link

I fixed the issue when pulling from a local registry. First, we shouldn't use localhost:5000 as the image host because the stargz snapshotter runs inside the microVM. In this context, localhost refers to the microVM itself, not the host machine, so the snapshotter cannot find the registry: failed to redirect (host "localhost:5000").

Next, I encountered an issue related to the local registry using HTTP. After reviewing the stargz documentation, I discovered that we can configure insecure connections for specific registries. To resolve this, I updated the configuration file located at tools\image-builder\files_stargz\etc\containerd-stargz-grpc\config.toml to include the necessary settings. I then ran make image-stargz to rebuild the image with the updated configuration.

Finally, I used Docker to pull your image, tagged it, and pushed it to my own repository. However, I encountered issues when pulling the image using the snapshotter, similar to what is described here. As suggested here, I switched to using nerdctl to perform the commands, and everything worked as expected. I’m still unsure why this approach doesn't work with Docker.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants