time="2021-03-24T17:03:24.373355399Z" level=info msg="starting containerd" revision=10cc33c3c603d9ac8025fd243826cb3b1edbdead version=1.3.4+unknown time="2021-03-24T17:03:24.412271574Z" level=info msg="loading plugin \"io.containerd.content.v1.content\"..." type=io.containerd.content.v1 time="2021-03-24T17:03:24.412335879Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.devmapper\"..." type=io.containerd.snapshotter.v1 time="2021-03-24T17:03:24.412397702Z" level=info msg="initializing pool device \"9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool\"" time="2021-03-24T17:03:24.414856757Z" level=info msg="using dmsetup:\nLibrary version: 1.02.167 (2019-11-30)\nDriver version: 4.37.0" time="2021-03-24T17:03:24.427683906Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.overlayfs\"..." type=io.containerd.snapshotter.v1 time="2021-03-24T17:03:24.428074931Z" level=info msg="loading plugin \"io.containerd.metadata.v1.bolt\"..." type=io.containerd.metadata.v1 time="2021-03-24T17:03:24.428132019Z" level=info msg="metadata content store policy set" policy=shared time="2021-03-24T17:03:24.428237810Z" level=info msg="loading plugin \"io.containerd.differ.v1.walking\"..." type=io.containerd.differ.v1 time="2021-03-24T17:03:24.428257733Z" level=info msg="loading plugin \"io.containerd.gc.v1.scheduler\"..." type=io.containerd.gc.v1 time="2021-03-24T17:03:24.428286204Z" level=info msg="loading plugin \"io.containerd.service.v1.containers-service\"..." type=io.containerd.service.v1 time="2021-03-24T17:03:24.428299962Z" level=info msg="loading plugin \"io.containerd.service.v1.content-service\"..." type=io.containerd.service.v1 time="2021-03-24T17:03:24.428310628Z" level=info msg="loading plugin \"io.containerd.service.v1.diff-service\"..." type=io.containerd.service.v1 time="2021-03-24T17:03:24.428322343Z" level=info msg="loading plugin \"io.containerd.service.v1.images-service\"..." type=io.containerd.service.v1 time="2021-03-24T17:03:24.428333317Z" level=info msg="loading plugin \"io.containerd.service.v1.leases-service\"..." type=io.containerd.service.v1 time="2021-03-24T17:03:24.428344129Z" level=info msg="loading plugin \"io.containerd.service.v1.namespaces-service\"..." type=io.containerd.service.v1 time="2021-03-24T17:03:24.428354671Z" level=info msg="loading plugin \"io.containerd.service.v1.snapshots-service\"..." type=io.containerd.service.v1 time="2021-03-24T17:03:24.428365139Z" level=info msg="loading plugin \"io.containerd.runtime.v1.linux\"..." type=io.containerd.runtime.v1 time="2021-03-24T17:03:24.428403672Z" level=info msg="loading plugin \"io.containerd.runtime.v2.task\"..." type=io.containerd.runtime.v2 time="2021-03-24T17:03:24.428443389Z" level=debug msg="loading tasks in namespace" namespace=firecracker-containerd time="2021-03-24T17:03:24.428748726Z" level=warning msg="cleaning up after shim disconnected" id=10 namespace=firecracker-containerd time="2021-03-24T17:03:24.428762958Z" level=info msg="cleaning up dead shim" time="2021-03-24T17:03:24.460094974Z" level=warning msg="failed to clean up after shim disconnected" error="aws.firecracker: failed to connect: dial unix /run/firecracker-containerd/containerd.sock.ttrpc: connect: connection refused\n: exit status 1" id=10 namespace=firecracker-containerd time="2021-03-24T17:03:24.460235901Z" level=debug msg="event published" ns=firecracker-containerd topic=/tasks/exit type=containerd.events.TaskExit time="2021-03-24T17:03:24.460292477Z" level=debug msg="event published" ns=firecracker-containerd topic=/tasks/delete type=containerd.events.TaskDelete time="2021-03-24T17:03:24.460663342Z" level=warning msg="cleaning up after shim disconnected" id=11 namespace=firecracker-containerd time="2021-03-24T17:03:24.460680988Z" level=info msg="cleaning up dead shim" time="2021-03-24T17:03:24.494279056Z" level=warning msg="failed to clean up after shim disconnected" error="aws.firecracker: failed to connect: dial unix /run/firecracker-containerd/containerd.sock.ttrpc: connect: connection refused\n: exit status 1" id=11 namespace=firecracker-containerd time="2021-03-24T17:03:24.494347520Z" level=debug msg="event published" ns=firecracker-containerd topic=/tasks/exit type=containerd.events.TaskExit time="2021-03-24T17:03:24.494367517Z" level=debug msg="event published" ns=firecracker-containerd topic=/tasks/delete type=containerd.events.TaskDelete time="2021-03-24T17:03:24.494633608Z" level=warning msg="cleaning up after shim disconnected" id=12 namespace=firecracker-containerd time="2021-03-24T17:03:24.494646369Z" level=info msg="cleaning up dead shim" time="2021-03-24T17:03:24.524262698Z" level=warning msg="failed to clean up after shim disconnected" error="aws.firecracker: failed to connect: dial unix /run/firecracker-containerd/containerd.sock.ttrpc: connect: connection refused\n: exit status 1" id=12 namespace=firecracker-containerd time="2021-03-24T17:03:24.524358422Z" level=debug msg="event published" ns=firecracker-containerd topic=/tasks/exit type=containerd.events.TaskExit time="2021-03-24T17:03:24.524397834Z" level=debug msg="event published" ns=firecracker-containerd topic=/tasks/delete type=containerd.events.TaskDelete time="2021-03-24T17:03:24.524586517Z" level=warning msg="cleaning up after shim disconnected" id=13 namespace=firecracker-containerd time="2021-03-24T17:03:24.524608064Z" level=info msg="cleaning up dead shim" time="2021-03-24T17:03:24.529351403Z" level=debug msg="garbage collected" d="794.75µs" time="2021-03-24T17:03:24.552611955Z" level=warning msg="failed to clean up after shim disconnected" error="aws.firecracker: failed to connect: dial unix /run/firecracker-containerd/containerd.sock.ttrpc: connect: connection refused\n: exit status 1" id=13 namespace=firecracker-containerd time="2021-03-24T17:03:24.552704435Z" level=debug msg="event published" ns=firecracker-containerd topic=/tasks/exit type=containerd.events.TaskExit time="2021-03-24T17:03:24.552753924Z" level=debug msg="event published" ns=firecracker-containerd topic=/tasks/delete type=containerd.events.TaskDelete time="2021-03-24T17:03:24.553156813Z" level=warning msg="cleaning up after shim disconnected" id=9 namespace=firecracker-containerd time="2021-03-24T17:03:24.553187588Z" level=info msg="cleaning up dead shim" time="2021-03-24T17:03:24.582984719Z" level=warning msg="failed to clean up after shim disconnected" error="aws.firecracker: failed to connect: dial unix /run/firecracker-containerd/containerd.sock.ttrpc: connect: connection refused\n: exit status 1" id=9 namespace=firecracker-containerd time="2021-03-24T17:03:24.583023857Z" level=debug msg="event published" ns=firecracker-containerd topic=/tasks/exit type=containerd.events.TaskExit time="2021-03-24T17:03:24.583041357Z" level=debug msg="event published" ns=firecracker-containerd topic=/tasks/delete type=containerd.events.TaskDelete time="2021-03-24T17:03:24.584155106Z" level=info msg="loading plugin \"io.containerd.monitor.v1.cgroups\"..." type=io.containerd.monitor.v1 time="2021-03-24T17:03:24.584983551Z" level=info msg="loading plugin \"io.containerd.service.v1.tasks-service\"..." type=io.containerd.service.v1 time="2021-03-24T17:03:24.585075693Z" level=info msg="loading plugin \"io.containerd.service.v1.fc-control\"..." type=io.containerd.service.v1 time="2021-03-24T17:03:24.585111036Z" level=debug msg="initializing fc-control plugin (root: \"/var/lib/firecracker-containerd/containerd/io.containerd.service.v1.fc-control\")" time="2021-03-24T17:03:24.585572740Z" level=info msg="loading plugin \"io.containerd.internal.v1.restart\"..." type=io.containerd.internal.v1 time="2021-03-24T17:03:24.585620055Z" level=info msg="loading plugin \"io.containerd.grpc.v1.containers\"..." type=io.containerd.grpc.v1 time="2021-03-24T17:03:24.585633658Z" level=info msg="loading plugin \"io.containerd.grpc.v1.content\"..." type=io.containerd.grpc.v1 time="2021-03-24T17:03:24.585644914Z" level=info msg="loading plugin \"io.containerd.grpc.v1.diff\"..." type=io.containerd.grpc.v1 time="2021-03-24T17:03:24.585655915Z" level=info msg="loading plugin \"io.containerd.grpc.v1.events\"..." type=io.containerd.grpc.v1 time="2021-03-24T17:03:24.585677536Z" level=info msg="loading plugin \"io.containerd.grpc.v1.healthcheck\"..." type=io.containerd.grpc.v1 time="2021-03-24T17:03:24.585689148Z" level=info msg="loading plugin \"io.containerd.grpc.v1.images\"..." type=io.containerd.grpc.v1 time="2021-03-24T17:03:24.585715521Z" level=info msg="loading plugin \"io.containerd.grpc.v1.leases\"..." type=io.containerd.grpc.v1 time="2021-03-24T17:03:24.585725973Z" level=info msg="loading plugin \"io.containerd.grpc.v1.namespaces\"..." type=io.containerd.grpc.v1 time="2021-03-24T17:03:24.585735968Z" level=info msg="loading plugin \"io.containerd.internal.v1.opt\"..." type=io.containerd.internal.v1 time="2021-03-24T17:03:24.585768484Z" level=info msg="loading plugin \"io.containerd.grpc.v1.snapshots\"..." type=io.containerd.grpc.v1 time="2021-03-24T17:03:24.585992291Z" level=info msg="loading plugin \"io.containerd.grpc.v1.tasks\"..." type=io.containerd.grpc.v1 time="2021-03-24T17:03:24.586009695Z" level=info msg="loading plugin \"io.containerd.grpc.v1.version\"..." type=io.containerd.grpc.v1 time="2021-03-24T17:03:24.586021084Z" level=info msg="loading plugin \"io.containerd.grpc.v1.fc-control-service\"..." type=io.containerd.grpc.v1 time="2021-03-24T17:03:24.586029893Z" level=debug msg="initializing fc-control-service plugin" time="2021-03-24T17:03:24.586047233Z" level=info msg="loading plugin \"io.containerd.grpc.v1.introspection\"..." type=io.containerd.grpc.v1 time="2021-03-24T17:03:24.586676789Z" level=info msg=serving... address=/run/firecracker-containerd/containerd.sock.ttrpc time="2021-03-24T17:03:24.586857880Z" level=info msg=serving... address=/run/firecracker-containerd/containerd.sock time="2021-03-24T17:03:24.586921145Z" level=info msg="containerd successfully booted in 0.214912s" time="2021-03-24T17:10:12.911493727Z" level=debug msg="(*service).Write started" expected="sha256:12dc6715ed1a8306f246ceaf7742c09e38a52a79d17421e4a50d7e0e09fdbc25" ref="manifest-sha256:12dc6715ed1a8306f246ceaf7742c09e38a52a79d17421e4a50d7e0e09fdbc25" total=1998 time="2021-03-24T17:10:12.916203265Z" level=debug msg="(*service).Write started" expected="sha256:c09d5cdb7367fff0d581bb8003e3520dc3e8bd78811dfb51c92df81e58c3a50d" ref="layer-sha256:c09d5cdb7367fff0d581bb8003e3520dc3e8bd78811dfb51c92df81e58c3a50d" total=637463 time="2021-03-24T17:10:12.916242191Z" level=debug msg="(*service).Write started" expected="sha256:2cc5ad85d9abaadf23d5ae53c3f32e7ccb2df1956869980bfd2491ff396d348a" ref="layer-sha256:2cc5ad85d9abaadf23d5ae53c3f32e7ccb2df1956869980bfd2491ff396d348a" total=301261 time="2021-03-24T17:10:12.916286654Z" level=debug msg="(*service).Write started" expected="sha256:0522d30cde10ac29ae2c555b9bde76c2b50aafc7ef7435bbc7e19de706bcadcd" ref="layer-sha256:0522d30cde10ac29ae2c555b9bde76c2b50aafc7ef7435bbc7e19de706bcadcd" total=230 time="2021-03-24T17:10:12.916328816Z" level=debug msg="(*service).Write started" expected="sha256:c9b1b535fdd91a9855fb7f82348177e5f019329a58c53c47272962dd60f71fc9" ref="layer-sha256:c9b1b535fdd91a9855fb7f82348177e5f019329a58c53c47272962dd60f71fc9" total=2802957 time="2021-03-24T17:10:12.916330962Z" level=debug msg="(*service).Write started" expected="sha256:a87533385b75fd1d476d8a1112a0c5db953e3d5b44d4f9db814b1e2e6abb8734" ref="config-sha256:a87533385b75fd1d476d8a1112a0c5db953e3d5b44d4f9db814b1e2e6abb8734" total=8312 time="2021-03-24T17:10:12.916345687Z" level=debug msg="(*service).Write started" expected="sha256:0d776ee02572ee50935002da7bd7fcda4a60be4a48c4ace5dd3216c327e6767a" ref="layer-sha256:0d776ee02572ee50935002da7bd7fcda4a60be4a48c4ace5dd3216c327e6767a" total=20365161 time="2021-03-24T17:10:12.917033696Z" level=debug msg="(*service).Write started" expected="sha256:92b614cff45fafd028cec952e0cb2584e8d931bf0321e7d14bfafdf7a50ac3fa" ref="layer-sha256:92b614cff45fafd028cec952e0cb2584e8d931bf0321e7d14bfafdf7a50ac3fa" total=2233 time="2021-03-24T17:10:12.916842421Z" level=debug msg="(*service).Write started" expected="sha256:61614c1a5710c76af6b2a9c7170a81eb0dd76ccf90e921abc0c9dcc1d5ed490e" ref="layer-sha256:61614c1a5710c76af6b2a9c7170a81eb0dd76ccf90e921abc0c9dcc1d5ed490e" total=31506523 time="2021-03-24T17:10:12.917097821Z" level=debug msg="(*service).Write started" expected="sha256:407da27a03363f6b9d368ec6e131f7f2db7c8cb2a149160d913d6f3698905a5d" ref="layer-sha256:407da27a03363f6b9d368ec6e131f7f2db7c8cb2a149160d913d6f3698905a5d" total=1887472 time="2021-03-24T17:10:12.936475522Z" level=debug msg="stat snapshot" key="sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10" time="2021-03-24T17:10:12.936558626Z" level=debug msg=stat key="firecracker-containerd/2/sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10" time="2021-03-24T17:10:12.937167771Z" level=debug msg="stat snapshot" key="sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5" time="2021-03-24T17:10:12.937242372Z" level=debug msg=stat key="firecracker-containerd/4/sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5" time="2021-03-24T17:10:12.937660181Z" level=debug msg="stat snapshot" key="sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa" time="2021-03-24T17:10:12.937731395Z" level=debug msg=stat key="firecracker-containerd/6/sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa" time="2021-03-24T17:10:12.938231570Z" level=debug msg="stat snapshot" key="sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f" time="2021-03-24T17:10:12.938283278Z" level=debug msg=stat key="firecracker-containerd/8/sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f" time="2021-03-24T17:10:12.944068194Z" level=debug msg="stat snapshot" key="sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270" time="2021-03-24T17:10:12.944143738Z" level=debug msg=stat key="firecracker-containerd/10/sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270" time="2021-03-24T17:10:12.944450754Z" level=debug msg="create image" name="docker.io/vhiveease/helloworld:var_workload" target="sha256:12dc6715ed1a8306f246ceaf7742c09e38a52a79d17421e4a50d7e0e09fdbc25" time="2021-03-24T17:10:12.944671301Z" level=debug msg="stat snapshot" key="sha256:e4226272b56cdeb334d6c3377374a6760ceae26f704fddedd5ff871e52d19784" time="2021-03-24T17:10:12.944735114Z" level=debug msg=stat key="firecracker-containerd/12/sha256:e4226272b56cdeb334d6c3377374a6760ceae26f704fddedd5ff871e52d19784" time="2021-03-24T17:10:12.945114700Z" level=debug msg="stat snapshot" key="sha256:046f313f5e6a5160dd5c71cdf40aed78bb816bce9030b7b1617dc499a623dac8" time="2021-03-24T17:10:12.945164263Z" level=debug msg=stat key="firecracker-containerd/14/sha256:046f313f5e6a5160dd5c71cdf40aed78bb816bce9030b7b1617dc499a623dac8" time="2021-03-24T17:10:12.945260651Z" level=debug msg="event published" ns=firecracker-containerd topic=/images/update type=containerd.services.images.v1.ImageUpdate time="2021-03-24T17:10:12.945491927Z" level=debug msg="stat snapshot" key="sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:10:12.945527432Z" level=debug msg=stat key="firecracker-containerd/16/sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:10:12.981388256Z" level=debug msg="garbage collected" d="628.734µs" time="2021-03-24T17:10:13.040058612Z" level=debug msg="create VM request: VMID:\"1\" MachineCfg: KernelArgs:\"ro noapic reboot=k panic=1 pci=off nomodules systemd.log_color=false systemd.unit=firecracker.target init=/sbin/overlay-init tsc=reliable quiet 8250.nr_uarts=0 ipv6.disable=1\" NetworkInterfaces: > > TimeoutSeconds:100 " time="2021-03-24T17:10:13.040107082Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:10:13.040460910Z" level=debug msg="starting containerd-shim-aws-firecracker" vmID=1 time="2021-03-24T17:10:13.074389524Z" level=info msg="starting signal loop" namespace=firecracker-containerd path=/var/lib/firecracker-containerd/shim-base/firecracker-containerd/1 pid=74005 time="2021-03-24T17:10:13.075571229Z" level=info msg="creating new VM" runtime=aws.firecracker vmID=1 time="2021-03-24T17:10:13.075969001Z" level=info msg="Called startVMM(), setting up a VMM on firecracker.sock" runtime=aws.firecracker setupLogging setupMetrics time="2021-03-24T17:10:13.088469715Z" level=info msg="VMM metrics disabled." runtime=aws.firecracker time="2021-03-24T17:10:13.088903144Z" level=info msg="refreshMachineConfiguration: [GET /machine-config][200] getMachineConfigurationOK &{CPUTemplate:T2 HtEnabled:0xc00049a9e3 MemSizeMib:0xc00049a9c8 VcpuCount:0xc00049a9c0}" runtime=aws.firecracker time="2021-03-24T17:10:13.089170096Z" level=info msg="PutGuestBootSource: [PUT /boot-source][204] putGuestBootSourceNoContent " runtime=aws.firecracker time="2021-03-24T17:10:13.089209034Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/runtime/default-rootfs.img, slot root_drive, root true." runtime=aws.firecracker time="2021-03-24T17:10:13.089648086Z" level=info msg="Attached drive /var/lib/firecracker-containerd/runtime/default-rootfs.img: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:10:13.089689112Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/1/ctrstub0, slot MN2HE43UOVRDA, root false." runtime=aws.firecracker time="2021-03-24T17:10:13.089984348Z" level=info msg="Attached drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/1/ctrstub0: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:10:13.090008588Z" level=info msg="Attaching NIC 1_tap (hwaddr 02:FC:00:00:00:00) at index 1" runtime=aws.firecracker time="2021-03-24T17:10:13.170004908Z" level=info msg="startInstance successful: [PUT /actions][204] createSyncActionNoContent " runtime=aws.firecracker time="2021-03-24T17:10:13.170054427Z" level=info msg="calling agent" runtime=aws.firecracker vmID=1 time="2021-03-24T17:10:14.270521246Z" level=info msg="successfully started the VM" runtime=aws.firecracker vmID=1 time="2021-03-24T17:10:14.271215460Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/firecracker-vm/start type=VMStart time="2021-03-24T17:10:14.274241939Z" level=debug msg="prepare snapshot" key=1 parent="sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:10:14.274376267Z" level=debug msg=prepare key=firecracker-containerd/36/1 parent="firecracker-containerd/16/sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:10:14.274535233Z" level=debug msg="creating snapshot device '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-25' from '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-8'" time="2021-03-24T17:10:14.371310008Z" level=debug msg="event published" ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare time="2021-03-24T17:10:14.375470083Z" level=debug msg="get snapshot mounts" key=1 time="2021-03-24T17:10:14.375575156Z" level=debug msg=mounts key=firecracker-containerd/36/1 time="2021-03-24T17:10:14.436636720Z" level=debug msg="event published" ns=firecracker-containerd topic=/containers/create type=containerd.events.ContainerCreate time="2021-03-24T17:10:14.438929009Z" level=debug msg="get snapshot mounts" key=1 time="2021-03-24T17:10:14.438971570Z" level=debug msg=mounts key=firecracker-containerd/36/1 time="2021-03-24T17:10:14.453238538Z" level=debug msg="garbage collected" d="574.527µs" time="2021-03-24T17:10:14.470266752Z" level=debug msg=StartShim runtime=aws.firecracker task_id=1 time="2021-03-24T17:10:14.471119252Z" level=debug msg="create VM request: VMID:\"1\" " time="2021-03-24T17:10:14.471141778Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:10:14.471432527Z" level=info msg="successfully started shim (git commit: 10cc33c3c603d9ac8025fd243826cb3b1edbdead)." runtime=aws.firecracker task_id=1 vmID=1 time="2021-03-24T17:10:14.473035328Z" level=info msg="PatchGuestDrive successful" runtime=aws.firecracker time="2021-03-24T17:10:14.619552284Z" level=info msg="successfully created task" ExecID= TaskID=1 pid_in_vm=725 runtime=aws.firecracker vmID=1 time="2021-03-24T17:10:14.619870209Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/create type=containerd.events.TaskCreate time="2021-03-24T17:10:14.633229404Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/start type=containerd.events.TaskStart time="2021-03-24T17:10:19.664428601Z" level=debug msg="(*service).Write started" expected="sha256:12dc6715ed1a8306f246ceaf7742c09e38a52a79d17421e4a50d7e0e09fdbc25" ref="manifest-sha256:12dc6715ed1a8306f246ceaf7742c09e38a52a79d17421e4a50d7e0e09fdbc25" total=1998 time="2021-03-24T17:10:19.686127229Z" level=debug msg="(*service).Write started" expected="sha256:c09d5cdb7367fff0d581bb8003e3520dc3e8bd78811dfb51c92df81e58c3a50d" ref="layer-sha256:c09d5cdb7367fff0d581bb8003e3520dc3e8bd78811dfb51c92df81e58c3a50d" total=637463 time="2021-03-24T17:10:19.686183187Z" level=debug msg="(*service).Write started" expected="sha256:a87533385b75fd1d476d8a1112a0c5db953e3d5b44d4f9db814b1e2e6abb8734" ref="config-sha256:a87533385b75fd1d476d8a1112a0c5db953e3d5b44d4f9db814b1e2e6abb8734" total=8312 time="2021-03-24T17:10:19.686234173Z" level=debug msg="(*service).Write started" expected="sha256:61614c1a5710c76af6b2a9c7170a81eb0dd76ccf90e921abc0c9dcc1d5ed490e" ref="layer-sha256:61614c1a5710c76af6b2a9c7170a81eb0dd76ccf90e921abc0c9dcc1d5ed490e" total=31506523 time="2021-03-24T17:10:19.686233831Z" level=debug msg="(*service).Write started" expected="sha256:0522d30cde10ac29ae2c555b9bde76c2b50aafc7ef7435bbc7e19de706bcadcd" ref="layer-sha256:0522d30cde10ac29ae2c555b9bde76c2b50aafc7ef7435bbc7e19de706bcadcd" total=230 time="2021-03-24T17:10:19.686271718Z" level=debug msg="(*service).Write started" expected="sha256:2cc5ad85d9abaadf23d5ae53c3f32e7ccb2df1956869980bfd2491ff396d348a" ref="layer-sha256:2cc5ad85d9abaadf23d5ae53c3f32e7ccb2df1956869980bfd2491ff396d348a" total=301261 time="2021-03-24T17:10:19.686282510Z" level=debug msg="(*service).Write started" expected="sha256:0d776ee02572ee50935002da7bd7fcda4a60be4a48c4ace5dd3216c327e6767a" ref="layer-sha256:0d776ee02572ee50935002da7bd7fcda4a60be4a48c4ace5dd3216c327e6767a" total=20365161 time="2021-03-24T17:10:19.686298736Z" level=debug msg="(*service).Write started" expected="sha256:c9b1b535fdd91a9855fb7f82348177e5f019329a58c53c47272962dd60f71fc9" ref="layer-sha256:c9b1b535fdd91a9855fb7f82348177e5f019329a58c53c47272962dd60f71fc9" total=2802957 time="2021-03-24T17:10:19.686928168Z" level=debug msg="(*service).Write started" expected="sha256:407da27a03363f6b9d368ec6e131f7f2db7c8cb2a149160d913d6f3698905a5d" ref="layer-sha256:407da27a03363f6b9d368ec6e131f7f2db7c8cb2a149160d913d6f3698905a5d" total=1887472 time="2021-03-24T17:10:19.686947353Z" level=debug msg="(*service).Write started" expected="sha256:92b614cff45fafd028cec952e0cb2584e8d931bf0321e7d14bfafdf7a50ac3fa" ref="layer-sha256:92b614cff45fafd028cec952e0cb2584e8d931bf0321e7d14bfafdf7a50ac3fa" total=2233 time="2021-03-24T17:10:19.716990278Z" level=debug msg="stat snapshot" key="sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10" time="2021-03-24T17:10:19.717088953Z" level=debug msg=stat key="firecracker-containerd/2/sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10" time="2021-03-24T17:10:19.717840165Z" level=debug msg="stat snapshot" key="sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5" time="2021-03-24T17:10:19.717908127Z" level=debug msg=stat key="firecracker-containerd/4/sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5" time="2021-03-24T17:10:19.718207133Z" level=debug msg="stat snapshot" key="sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa" time="2021-03-24T17:10:19.718277625Z" level=debug msg=stat key="firecracker-containerd/6/sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa" time="2021-03-24T17:10:19.718569809Z" level=debug msg="stat snapshot" key="sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f" time="2021-03-24T17:10:19.718599441Z" level=debug msg=stat key="firecracker-containerd/8/sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f" time="2021-03-24T17:10:19.719409907Z" level=debug msg="stat snapshot" key="sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270" time="2021-03-24T17:10:19.719483437Z" level=debug msg=stat key="firecracker-containerd/10/sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270" time="2021-03-24T17:10:19.719804883Z" level=debug msg="create image" name="docker-registry.registry.svc.cluster.local:5000/vhiveease/helloworld:var_workload" target="sha256:12dc6715ed1a8306f246ceaf7742c09e38a52a79d17421e4a50d7e0e09fdbc25" time="2021-03-24T17:10:19.719907554Z" level=debug msg="stat snapshot" key="sha256:e4226272b56cdeb334d6c3377374a6760ceae26f704fddedd5ff871e52d19784" time="2021-03-24T17:10:19.719972236Z" level=debug msg=stat key="firecracker-containerd/12/sha256:e4226272b56cdeb334d6c3377374a6760ceae26f704fddedd5ff871e52d19784" time="2021-03-24T17:10:19.720306659Z" level=debug msg="stat snapshot" key="sha256:046f313f5e6a5160dd5c71cdf40aed78bb816bce9030b7b1617dc499a623dac8" time="2021-03-24T17:10:19.720362811Z" level=debug msg=stat key="firecracker-containerd/14/sha256:046f313f5e6a5160dd5c71cdf40aed78bb816bce9030b7b1617dc499a623dac8" time="2021-03-24T17:10:19.720751980Z" level=debug msg="event published" ns=firecracker-containerd topic=/images/update type=containerd.services.images.v1.ImageUpdate time="2021-03-24T17:10:19.720802528Z" level=debug msg="stat snapshot" key="sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:10:19.720849799Z" level=debug msg=stat key="firecracker-containerd/16/sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:10:19.738309260Z" level=debug msg="garbage collected" d=8.577238ms time="2021-03-24T17:10:19.816950415Z" level=debug msg="create VM request: VMID:\"2\" MachineCfg: KernelArgs:\"ro noapic reboot=k panic=1 pci=off nomodules systemd.log_color=false systemd.unit=firecracker.target init=/sbin/overlay-init tsc=reliable quiet 8250.nr_uarts=0 ipv6.disable=1\" NetworkInterfaces: > > TimeoutSeconds:100 " time="2021-03-24T17:10:19.817034840Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:10:19.817293905Z" level=debug msg="starting containerd-shim-aws-firecracker" vmID=2 time="2021-03-24T17:10:19.852673829Z" level=info msg="starting signal loop" namespace=firecracker-containerd path=/var/lib/firecracker-containerd/shim-base/firecracker-containerd/2 pid=74562 time="2021-03-24T17:10:19.853512129Z" level=info msg="creating new VM" runtime=aws.firecracker vmID=2 time="2021-03-24T17:10:19.853865462Z" level=info msg="Called startVMM(), setting up a VMM on firecracker.sock" runtime=aws.firecracker setupLogging setupMetrics time="2021-03-24T17:10:19.865956495Z" level=info msg="VMM metrics disabled." runtime=aws.firecracker time="2021-03-24T17:10:19.866571660Z" level=info msg="refreshMachineConfiguration: [GET /machine-config][200] getMachineConfigurationOK &{CPUTemplate:T2 HtEnabled:0xc000582703 MemSizeMib:0xc0005826f8 VcpuCount:0xc0005826f0}" runtime=aws.firecracker time="2021-03-24T17:10:19.866974354Z" level=info msg="PutGuestBootSource: [PUT /boot-source][204] putGuestBootSourceNoContent " runtime=aws.firecracker time="2021-03-24T17:10:19.867013456Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/runtime/default-rootfs.img, slot root_drive, root true." runtime=aws.firecracker time="2021-03-24T17:10:19.867578810Z" level=info msg="Attached drive /var/lib/firecracker-containerd/runtime/default-rootfs.img: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:10:19.867637007Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/2/ctrstub0, slot MN2HE43UOVRDA, root false." runtime=aws.firecracker time="2021-03-24T17:10:19.868008865Z" level=info msg="Attached drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/2/ctrstub0: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:10:19.868041675Z" level=info msg="Attaching NIC 2_tap (hwaddr 02:FC:00:00:00:01) at index 1" runtime=aws.firecracker time="2021-03-24T17:10:19.891112124Z" level=info msg="startInstance successful: [PUT /actions][204] createSyncActionNoContent " runtime=aws.firecracker time="2021-03-24T17:10:19.891161827Z" level=info msg="calling agent" runtime=aws.firecracker vmID=2 time="2021-03-24T17:10:20.891687795Z" level=info msg="successfully started the VM" runtime=aws.firecracker vmID=2 time="2021-03-24T17:10:20.892182431Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/firecracker-vm/start type=VMStart time="2021-03-24T17:10:20.895921199Z" level=debug msg="prepare snapshot" key=2 parent="sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:10:20.896044231Z" level=debug msg=prepare key=firecracker-containerd/37/2 parent="firecracker-containerd/16/sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:10:20.896207898Z" level=debug msg="creating snapshot device '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-26' from '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-8'" time="2021-03-24T17:10:20.983306975Z" level=debug msg="event published" ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare time="2021-03-24T17:10:20.986542524Z" level=debug msg="get snapshot mounts" key=2 time="2021-03-24T17:10:20.986596529Z" level=debug msg=mounts key=firecracker-containerd/37/2 time="2021-03-24T17:10:21.020638687Z" level=debug msg="event published" ns=firecracker-containerd topic=/containers/create type=containerd.events.ContainerCreate time="2021-03-24T17:10:21.022156763Z" level=debug msg="get snapshot mounts" key=2 time="2021-03-24T17:10:21.022206138Z" level=debug msg=mounts key=firecracker-containerd/37/2 time="2021-03-24T17:10:21.036835853Z" level=debug msg="garbage collected" d="829.679µs" time="2021-03-24T17:10:21.058071187Z" level=debug msg=StartShim runtime=aws.firecracker task_id=2 time="2021-03-24T17:10:21.058858365Z" level=debug msg="create VM request: VMID:\"2\" " time="2021-03-24T17:10:21.058896566Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:10:21.059396337Z" level=info msg="successfully started shim (git commit: 10cc33c3c603d9ac8025fd243826cb3b1edbdead)." runtime=aws.firecracker task_id=2 vmID=2 time="2021-03-24T17:10:21.061206375Z" level=info msg="PatchGuestDrive successful" runtime=aws.firecracker time="2021-03-24T17:10:21.214440008Z" level=info msg="successfully created task" ExecID= TaskID=2 pid_in_vm=725 runtime=aws.firecracker vmID=2 time="2021-03-24T17:10:21.214632674Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/create type=containerd.events.TaskCreate time="2021-03-24T17:10:21.224846298Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/start type=containerd.events.TaskStart time="2021-03-24T17:10:28.309179309Z" level=debug msg="create VM request: VMID:\"3\" MachineCfg: KernelArgs:\"ro noapic reboot=k panic=1 pci=off nomodules systemd.log_color=false systemd.unit=firecracker.target init=/sbin/overlay-init tsc=reliable quiet 8250.nr_uarts=0 ipv6.disable=1\" NetworkInterfaces: > > TimeoutSeconds:100 " time="2021-03-24T17:10:28.309264036Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:10:28.309493624Z" level=debug msg="starting containerd-shim-aws-firecracker" vmID=3 time="2021-03-24T17:10:28.339056777Z" level=info msg="starting signal loop" namespace=firecracker-containerd path=/var/lib/firecracker-containerd/shim-base/firecracker-containerd/3 pid=75194 time="2021-03-24T17:10:28.340059256Z" level=info msg="creating new VM" runtime=aws.firecracker vmID=3 time="2021-03-24T17:10:28.340465090Z" level=info msg="Called startVMM(), setting up a VMM on firecracker.sock" runtime=aws.firecracker setupLogging setupMetrics time="2021-03-24T17:10:28.352963241Z" level=info msg="VMM metrics disabled." runtime=aws.firecracker time="2021-03-24T17:10:28.353370475Z" level=info msg="refreshMachineConfiguration: [GET /machine-config][200] getMachineConfigurationOK &{CPUTemplate:T2 HtEnabled:0xc00010ea43 MemSizeMib:0xc00010ea38 VcpuCount:0xc00010ea30}" runtime=aws.firecracker time="2021-03-24T17:10:28.353663950Z" level=info msg="PutGuestBootSource: [PUT /boot-source][204] putGuestBootSourceNoContent " runtime=aws.firecracker time="2021-03-24T17:10:28.353691220Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/runtime/default-rootfs.img, slot root_drive, root true." runtime=aws.firecracker time="2021-03-24T17:10:28.354222134Z" level=info msg="Attached drive /var/lib/firecracker-containerd/runtime/default-rootfs.img: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:10:28.354253778Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/3/ctrstub0, slot MN2HE43UOVRDA, root false." runtime=aws.firecracker time="2021-03-24T17:10:28.354469588Z" level=info msg="Attached drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/3/ctrstub0: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:10:28.354497252Z" level=info msg="Attaching NIC 3_tap (hwaddr 02:FC:00:00:00:02) at index 1" runtime=aws.firecracker time="2021-03-24T17:10:28.375247930Z" level=info msg="startInstance successful: [PUT /actions][204] createSyncActionNoContent " runtime=aws.firecracker time="2021-03-24T17:10:28.375290384Z" level=info msg="calling agent" runtime=aws.firecracker vmID=3 time="2021-03-24T17:10:29.375822617Z" level=info msg="successfully started the VM" runtime=aws.firecracker vmID=3 time="2021-03-24T17:10:29.376225700Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/firecracker-vm/start type=VMStart time="2021-03-24T17:10:29.379245884Z" level=debug msg="prepare snapshot" key=3 parent="sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:10:29.379704482Z" level=debug msg=prepare key=firecracker-containerd/38/3 parent="firecracker-containerd/16/sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:10:29.379874698Z" level=debug msg="creating snapshot device '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-27' from '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-8'" time="2021-03-24T17:10:29.487214391Z" level=debug msg="event published" ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare time="2021-03-24T17:10:29.492123979Z" level=debug msg="get snapshot mounts" key=3 time="2021-03-24T17:10:29.492203399Z" level=debug msg=mounts key=firecracker-containerd/38/3 time="2021-03-24T17:10:29.548662216Z" level=debug msg="event published" ns=firecracker-containerd topic=/containers/create type=containerd.events.ContainerCreate time="2021-03-24T17:10:29.550455805Z" level=debug msg="get snapshot mounts" key=3 time="2021-03-24T17:10:29.550530934Z" level=debug msg=mounts key=firecracker-containerd/38/3 time="2021-03-24T17:10:29.591816244Z" level=debug msg=StartShim runtime=aws.firecracker task_id=3 time="2021-03-24T17:10:29.592768712Z" level=debug msg="create VM request: VMID:\"3\" " time="2021-03-24T17:10:29.592841286Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:10:29.593273916Z" level=info msg="successfully started shim (git commit: 10cc33c3c603d9ac8025fd243826cb3b1edbdead)." runtime=aws.firecracker task_id=3 vmID=3 time="2021-03-24T17:10:29.595146083Z" level=info msg="PatchGuestDrive successful" runtime=aws.firecracker time="2021-03-24T17:10:29.654969147Z" level=debug msg="garbage collected" d=1.054646ms time="2021-03-24T17:10:29.734638323Z" level=info msg="successfully created task" ExecID= TaskID=3 pid_in_vm=725 runtime=aws.firecracker vmID=3 time="2021-03-24T17:10:29.734941464Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/create type=containerd.events.TaskCreate time="2021-03-24T17:10:29.743183023Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/start type=containerd.events.TaskStart time="2021-03-24T17:10:45.662239820Z" level=debug msg="(*service).Write started" expected="sha256:75d39d67fbb3ca85eb89ece0b38e24ab7dadb2fccf9576a00cd87588aad7c460" ref="manifest-sha256:75d39d67fbb3ca85eb89ece0b38e24ab7dadb2fccf9576a00cd87588aad7c460" total=1998 time="2021-03-24T17:10:45.668516188Z" level=debug msg="(*service).Write started" expected="sha256:d02232cde789f60bfefd38a38c22df68cb75f0b4a6e17f11876650bc1845acaf" ref="layer-sha256:d02232cde789f60bfefd38a38c22df68cb75f0b4a6e17f11876650bc1845acaf" total=637463 time="2021-03-24T17:10:45.668515867Z" level=debug msg="(*service).Write started" expected="sha256:adc08e00a651383f0333647c65bedddc8826225b3a3d8da06c4f8e678f935b71" ref="layer-sha256:adc08e00a651383f0333647c65bedddc8826225b3a3d8da06c4f8e678f935b71" total=20418883 time="2021-03-24T17:10:45.668515720Z" level=debug msg="(*service).Write started" expected="sha256:c9b1b535fdd91a9855fb7f82348177e5f019329a58c53c47272962dd60f71fc9" ref="layer-sha256:c9b1b535fdd91a9855fb7f82348177e5f019329a58c53c47272962dd60f71fc9" total=2802957 time="2021-03-24T17:10:45.668625868Z" level=debug msg="(*service).Write started" expected="sha256:00a47c8ade3f6bcd1061541f4387e56d3fcba420f67b4234ade01d51635572f4" ref="layer-sha256:00a47c8ade3f6bcd1061541f4387e56d3fcba420f67b4234ade01d51635572f4" total=2435 time="2021-03-24T17:10:45.668523214Z" level=debug msg="(*service).Write started" expected="sha256:2cc5ad85d9abaadf23d5ae53c3f32e7ccb2df1956869980bfd2491ff396d348a" ref="layer-sha256:2cc5ad85d9abaadf23d5ae53c3f32e7ccb2df1956869980bfd2491ff396d348a" total=301261 time="2021-03-24T17:10:45.668537499Z" level=debug msg="(*service).Write started" expected="sha256:407da27a03363f6b9d368ec6e131f7f2db7c8cb2a149160d913d6f3698905a5d" ref="layer-sha256:407da27a03363f6b9d368ec6e131f7f2db7c8cb2a149160d913d6f3698905a5d" total=1887472 time="2021-03-24T17:10:45.668557157Z" level=debug msg="(*service).Write started" expected="sha256:61614c1a5710c76af6b2a9c7170a81eb0dd76ccf90e921abc0c9dcc1d5ed490e" ref="layer-sha256:61614c1a5710c76af6b2a9c7170a81eb0dd76ccf90e921abc0c9dcc1d5ed490e" total=31506523 time="2021-03-24T17:10:45.668565811Z" level=debug msg="(*service).Write started" expected="sha256:0522d30cde10ac29ae2c555b9bde76c2b50aafc7ef7435bbc7e19de706bcadcd" ref="layer-sha256:0522d30cde10ac29ae2c555b9bde76c2b50aafc7ef7435bbc7e19de706bcadcd" total=230 time="2021-03-24T17:10:45.668634649Z" level=debug msg="(*service).Write started" expected="sha256:3691e79f01ef2ba64a855ef7621b04b3dbb0b4c689d27ebaa8644d4cb1a7e28f" ref="config-sha256:3691e79f01ef2ba64a855ef7621b04b3dbb0b4c689d27ebaa8644d4cb1a7e28f" total=8312 time="2021-03-24T17:10:45.679700868Z" level=debug msg="create image" name="docker.io/vhiveease/pyaes:var_workload" target="sha256:75d39d67fbb3ca85eb89ece0b38e24ab7dadb2fccf9576a00cd87588aad7c460" time="2021-03-24T17:10:45.680532874Z" level=debug msg="event published" ns=firecracker-containerd topic=/images/update type=containerd.services.images.v1.ImageUpdate time="2021-03-24T17:10:45.684890302Z" level=debug msg="stat snapshot" key="sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10" time="2021-03-24T17:10:45.684958455Z" level=debug msg=stat key="firecracker-containerd/2/sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10" time="2021-03-24T17:10:45.685389792Z" level=debug msg="stat snapshot" key="sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5" time="2021-03-24T17:10:45.685455997Z" level=debug msg=stat key="firecracker-containerd/4/sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5" time="2021-03-24T17:10:45.685847328Z" level=debug msg="stat snapshot" key="sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa" time="2021-03-24T17:10:45.685886105Z" level=debug msg=stat key="firecracker-containerd/6/sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa" time="2021-03-24T17:10:45.686230743Z" level=debug msg="stat snapshot" key="sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f" time="2021-03-24T17:10:45.686305321Z" level=debug msg=stat key="firecracker-containerd/8/sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f" time="2021-03-24T17:10:45.686774183Z" level=debug msg="stat snapshot" key="sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270" time="2021-03-24T17:10:45.686838347Z" level=debug msg=stat key="firecracker-containerd/10/sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270" time="2021-03-24T17:10:45.687291896Z" level=debug msg="stat snapshot" key="sha256:cf144147664338bb0a5b647411ad7e6c14b7c87d243cc114550f3f1c07d80edc" time="2021-03-24T17:10:45.687348589Z" level=debug msg=stat key="firecracker-containerd/21/sha256:cf144147664338bb0a5b647411ad7e6c14b7c87d243cc114550f3f1c07d80edc" time="2021-03-24T17:10:45.687766946Z" level=debug msg="stat snapshot" key="sha256:66a1cfe2f05ed05d825c22c11c95890bcedc47070570e361a2afbd6fbade7ea2" time="2021-03-24T17:10:45.687838296Z" level=debug msg=stat key="firecracker-containerd/23/sha256:66a1cfe2f05ed05d825c22c11c95890bcedc47070570e361a2afbd6fbade7ea2" time="2021-03-24T17:10:45.688278845Z" level=debug msg="stat snapshot" key="sha256:e172bf8795d813920c658a6772bb108238dc2cf13f1fc1ee1ac5c595c37da14a" time="2021-03-24T17:10:45.688331910Z" level=debug msg=stat key="firecracker-containerd/25/sha256:e172bf8795d813920c658a6772bb108238dc2cf13f1fc1ee1ac5c595c37da14a" time="2021-03-24T17:10:45.754612007Z" level=debug msg="garbage collected" d="994.335µs" time="2021-03-24T17:10:45.782731261Z" level=debug msg="create VM request: VMID:\"4\" MachineCfg: KernelArgs:\"ro noapic reboot=k panic=1 pci=off nomodules systemd.log_color=false systemd.unit=firecracker.target init=/sbin/overlay-init tsc=reliable quiet 8250.nr_uarts=0 ipv6.disable=1\" NetworkInterfaces: > > TimeoutSeconds:100 " time="2021-03-24T17:10:45.782822010Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:10:45.783127696Z" level=debug msg="starting containerd-shim-aws-firecracker" vmID=4 time="2021-03-24T17:10:45.824802626Z" level=info msg="starting signal loop" namespace=firecracker-containerd path=/var/lib/firecracker-containerd/shim-base/firecracker-containerd/4 pid=76103 time="2021-03-24T17:10:45.825722568Z" level=info msg="creating new VM" runtime=aws.firecracker vmID=4 time="2021-03-24T17:10:45.826223622Z" level=info msg="Called startVMM(), setting up a VMM on firecracker.sock" runtime=aws.firecracker setupLogging setupMetrics time="2021-03-24T17:10:45.837819564Z" level=info msg="VMM metrics disabled." runtime=aws.firecracker time="2021-03-24T17:10:45.838165302Z" level=info msg="refreshMachineConfiguration: [GET /machine-config][200] getMachineConfigurationOK &{CPUTemplate:T2 HtEnabled:0xc00080e993 MemSizeMib:0xc00080e988 VcpuCount:0xc00080e980}" runtime=aws.firecracker time="2021-03-24T17:10:45.838350258Z" level=info msg="PutGuestBootSource: [PUT /boot-source][204] putGuestBootSourceNoContent " runtime=aws.firecracker time="2021-03-24T17:10:45.838375489Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/runtime/default-rootfs.img, slot root_drive, root true." runtime=aws.firecracker time="2021-03-24T17:10:45.838629329Z" level=info msg="Attached drive /var/lib/firecracker-containerd/runtime/default-rootfs.img: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:10:45.838642707Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/4/ctrstub0, slot MN2HE43UOVRDA, root false." runtime=aws.firecracker time="2021-03-24T17:10:45.838787094Z" level=info msg="Attached drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/4/ctrstub0: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:10:45.838799609Z" level=info msg="Attaching NIC 4_tap (hwaddr 02:FC:00:00:00:03) at index 1" runtime=aws.firecracker time="2021-03-24T17:10:45.861965183Z" level=info msg="startInstance successful: [PUT /actions][204] createSyncActionNoContent " runtime=aws.firecracker time="2021-03-24T17:10:45.862019502Z" level=info msg="calling agent" runtime=aws.firecracker vmID=4 time="2021-03-24T17:10:46.862598030Z" level=info msg="successfully started the VM" runtime=aws.firecracker vmID=4 time="2021-03-24T17:10:46.863092132Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/firecracker-vm/start type=VMStart time="2021-03-24T17:10:46.868097307Z" level=debug msg="prepare snapshot" key=4 parent="sha256:e172bf8795d813920c658a6772bb108238dc2cf13f1fc1ee1ac5c595c37da14a" time="2021-03-24T17:10:46.868220553Z" level=debug msg=prepare key=firecracker-containerd/39/4 parent="firecracker-containerd/25/sha256:e172bf8795d813920c658a6772bb108238dc2cf13f1fc1ee1ac5c595c37da14a" time="2021-03-24T17:10:46.868419071Z" level=debug msg="creating snapshot device '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-28' from '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-14'" time="2021-03-24T17:10:46.975294124Z" level=debug msg="event published" ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare time="2021-03-24T17:10:46.978351782Z" level=debug msg="get snapshot mounts" key=4 time="2021-03-24T17:10:46.978442906Z" level=debug msg=mounts key=firecracker-containerd/39/4 time="2021-03-24T17:10:47.020808088Z" level=debug msg="event published" ns=firecracker-containerd topic=/containers/create type=containerd.events.ContainerCreate time="2021-03-24T17:10:47.022376114Z" level=debug msg="get snapshot mounts" key=4 time="2021-03-24T17:10:47.022458490Z" level=debug msg=mounts key=firecracker-containerd/39/4 time="2021-03-24T17:10:47.059340738Z" level=debug msg=StartShim runtime=aws.firecracker task_id=4 time="2021-03-24T17:10:47.060497554Z" level=debug msg="create VM request: VMID:\"4\" " time="2021-03-24T17:10:47.060539235Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:10:47.060959505Z" level=info msg="successfully started shim (git commit: 10cc33c3c603d9ac8025fd243826cb3b1edbdead)." runtime=aws.firecracker task_id=4 vmID=4 time="2021-03-24T17:10:47.062768056Z" level=info msg="PatchGuestDrive successful" runtime=aws.firecracker time="2021-03-24T17:10:47.076766203Z" level=debug msg="garbage collected" d="666.862µs" time="2021-03-24T17:10:47.193496108Z" level=info msg="successfully created task" ExecID= TaskID=4 pid_in_vm=724 runtime=aws.firecracker vmID=4 time="2021-03-24T17:10:47.194013761Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/create type=containerd.events.TaskCreate time="2021-03-24T17:10:47.201401106Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/start type=containerd.events.TaskStart time="2021-03-24T17:12:03.290635661Z" level=info msg=exited ExecID= TaskID=1 exit_status=137 exited_at="2021-03-24 17:12:03.284656552 +0000 UTC" runtime=aws.firecracker vmID=1 time="2021-03-24T17:12:03.290689370Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/exit type=containerd.events.TaskExit time="2021-03-24T17:12:03.290695714Z" level=info msg="connection was closed: read /proc/self/fd/15: file already closed" ExecID= TaskID=1 runtime=aws.firecracker stream=stdin vmID=1 time="2021-03-24T17:12:03.290774137Z" level=error msg="error closing io stream" ExecID= TaskID=1 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stdin vmID=1 time="2021-03-24T17:12:03.802740861Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/delete type=containerd.events.TaskDelete time="2021-03-24T17:12:03.811434910Z" level=info msg="PatchGuestDrive successful" runtime=aws.firecracker time="2021-03-24T17:12:03.812027996Z" level=info msg="shim disconnected" id=1 time="2021-03-24T17:12:03.813283725Z" level=debug msg="remove snapshot" key=1 time="2021-03-24T17:12:03.813765533Z" level=debug msg="event published" ns=firecracker-containerd topic=/snapshot/remove type=containerd.events.SnapshotRemove time="2021-03-24T17:12:03.814456552Z" level=debug msg="event published" ns=firecracker-containerd topic=/containers/delete type=containerd.events.ContainerDelete time="2021-03-24T17:12:03.814717177Z" level=debug msg="stop VM: VMID:\"1\" " time="2021-03-24T17:12:03.814957634Z" level=info msg="stopping the VM" runtime=aws.firecracker vmID=1 time="2021-03-24T17:12:03.815817207Z" level=error msg="error while forwarding events from VM agent" error="rpc error: code = Canceled desc = context canceled" runtime=aws.firecracker vmID=1 time="2021-03-24T17:12:03.831113060Z" level=debug msg="schedule snapshotter cleanup" snapshotter=devmapper time="2021-03-24T17:12:03.831169894Z" level=debug msg=walk time="2021-03-24T17:12:03.831300983Z" level=debug msg=remove key=firecracker-containerd/36/1 time="2021-03-24T17:12:03.961717480Z" level=debug msg="removed snapshot" key=firecracker-containerd/36/1 snapshotter=devmapper time="2021-03-24T17:12:03.961751625Z" level=debug msg="snapshot garbage collected" d=130.60534ms snapshotter=devmapper time="2021-03-24T17:12:03.961823269Z" level=debug msg="garbage collected" d="891.405µs" time="2021-03-24T17:12:04.206387893Z" level=info msg="firecracker exited: status=0" runtime=aws.firecracker time="2021-03-24T17:12:04.206928246Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/firecracker-vm/stop type=VMStop time="2021-03-24T17:12:08.290866579Z" level=error msg="error closing io stream" ExecID= TaskID=1 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stderr vmID=1 time="2021-03-24T17:12:08.290866585Z" level=error msg="error closing io stream" ExecID= TaskID=1 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stdout vmID=1 time="2021-03-24T17:12:09.207114138Z" level=error msg="aws.firecracker: publisher not closed" shim_stream=stderr vmID=1 time="2021-03-24T17:12:09.208650001Z" level=debug msg="shim has been terminated" error="exit status 1" vmID=1 time="2021-03-24T17:12:11.325935431Z" level=info msg=exited ExecID= TaskID=2 exit_status=137 exited_at="2021-03-24 17:12:11.318467126 +0000 UTC" runtime=aws.firecracker vmID=2 time="2021-03-24T17:12:11.326083597Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/exit type=containerd.events.TaskExit time="2021-03-24T17:12:11.326079989Z" level=info msg="connection was closed: read /proc/self/fd/15: file already closed" ExecID= TaskID=2 runtime=aws.firecracker stream=stdin vmID=2 time="2021-03-24T17:12:11.326195604Z" level=error msg="error closing io stream" ExecID= TaskID=2 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stdin vmID=2 time="2021-03-24T17:12:11.839588721Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/delete type=containerd.events.TaskDelete time="2021-03-24T17:12:11.849887523Z" level=info msg="PatchGuestDrive successful" runtime=aws.firecracker time="2021-03-24T17:12:11.850410583Z" level=info msg="shim disconnected" id=2 time="2021-03-24T17:12:11.851572645Z" level=debug msg="remove snapshot" key=2 time="2021-03-24T17:12:11.861335189Z" level=debug msg="event published" ns=firecracker-containerd topic=/snapshot/remove type=containerd.events.SnapshotRemove time="2021-03-24T17:12:11.878107676Z" level=debug msg="event published" ns=firecracker-containerd topic=/containers/delete type=containerd.events.ContainerDelete time="2021-03-24T17:12:11.878522663Z" level=debug msg="stop VM: VMID:\"2\" " time="2021-03-24T17:12:11.879023804Z" level=info msg="stopping the VM" runtime=aws.firecracker vmID=2 time="2021-03-24T17:12:11.880375107Z" level=error msg="error while forwarding events from VM agent" error="rpc error: code = Canceled desc = context canceled" runtime=aws.firecracker vmID=2 time="2021-03-24T17:12:11.902142958Z" level=debug msg="schedule snapshotter cleanup" snapshotter=devmapper time="2021-03-24T17:12:11.902222778Z" level=debug msg=walk time="2021-03-24T17:12:11.902361676Z" level=debug msg=remove key=firecracker-containerd/37/2 time="2021-03-24T17:12:12.031554671Z" level=debug msg="removed snapshot" key=firecracker-containerd/37/2 snapshotter=devmapper time="2021-03-24T17:12:12.031583640Z" level=debug msg="snapshot garbage collected" d=129.383251ms snapshotter=devmapper time="2021-03-24T17:12:12.031623692Z" level=debug msg="garbage collected" d="662.433µs" time="2021-03-24T17:12:12.274343737Z" level=info msg="firecracker exited: status=0" runtime=aws.firecracker time="2021-03-24T17:12:12.275020893Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/firecracker-vm/stop type=VMStop time="2021-03-24T17:12:16.326013016Z" level=error msg="error closing io stream" ExecID= TaskID=2 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stderr vmID=2 time="2021-03-24T17:12:16.326013330Z" level=error msg="error closing io stream" ExecID= TaskID=2 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stdout vmID=2 time="2021-03-24T17:12:17.275037460Z" level=error msg="aws.firecracker: publisher not closed" shim_stream=stderr vmID=2 time="2021-03-24T17:12:17.276708119Z" level=debug msg="shim has been terminated" error="exit status 1" vmID=2 time="2021-03-24T17:12:23.387716742Z" level=info msg=exited ExecID= TaskID=3 exit_status=137 exited_at="2021-03-24 17:12:23.382223968 +0000 UTC" runtime=aws.firecracker vmID=3 time="2021-03-24T17:12:23.387850127Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/exit type=containerd.events.TaskExit time="2021-03-24T17:12:23.387931176Z" level=info msg="connection was closed: read /proc/self/fd/15: file already closed" ExecID= TaskID=3 runtime=aws.firecracker stream=stdin vmID=3 time="2021-03-24T17:12:23.387997622Z" level=error msg="error closing io stream" ExecID= TaskID=3 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stdin vmID=3 time="2021-03-24T17:12:23.901646674Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/delete type=containerd.events.TaskDelete time="2021-03-24T17:12:23.911233722Z" level=info msg="PatchGuestDrive successful" runtime=aws.firecracker time="2021-03-24T17:12:23.911965482Z" level=info msg="shim disconnected" id=3 time="2021-03-24T17:12:23.913739559Z" level=debug msg="remove snapshot" key=3 time="2021-03-24T17:12:23.920573338Z" level=debug msg="event published" ns=firecracker-containerd topic=/snapshot/remove type=containerd.events.SnapshotRemove time="2021-03-24T17:12:23.921399978Z" level=debug msg="event published" ns=firecracker-containerd topic=/containers/delete type=containerd.events.ContainerDelete time="2021-03-24T17:12:23.921856943Z" level=debug msg="stop VM: VMID:\"3\" " time="2021-03-24T17:12:23.922140398Z" level=info msg="stopping the VM" runtime=aws.firecracker vmID=3 time="2021-03-24T17:12:23.923400549Z" level=error msg="error while forwarding events from VM agent" error="rpc error: code = Canceled desc = context canceled" runtime=aws.firecracker vmID=3 time="2021-03-24T17:12:23.967026805Z" level=debug msg="schedule snapshotter cleanup" snapshotter=devmapper time="2021-03-24T17:12:23.967138799Z" level=debug msg=walk time="2021-03-24T17:12:23.967247580Z" level=debug msg=remove key=firecracker-containerd/38/3 time="2021-03-24T17:12:24.107512521Z" level=debug msg="removed snapshot" key=firecracker-containerd/38/3 snapshotter=devmapper time="2021-03-24T17:12:24.107548879Z" level=debug msg="snapshot garbage collected" d=140.432762ms snapshotter=devmapper time="2021-03-24T17:12:24.107578668Z" level=debug msg="garbage collected" d=9.411395ms time="2021-03-24T17:12:24.314435071Z" level=info msg="firecracker exited: status=0" runtime=aws.firecracker time="2021-03-24T17:12:24.315129642Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/firecracker-vm/stop type=VMStop time="2021-03-24T17:12:28.387993713Z" level=error msg="error closing io stream" ExecID= TaskID=3 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stdout vmID=3 time="2021-03-24T17:12:28.388025240Z" level=error msg="error closing io stream" ExecID= TaskID=3 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stderr vmID=3 time="2021-03-24T17:12:29.315212422Z" level=error msg="aws.firecracker: publisher not closed" shim_stream=stderr vmID=3 time="2021-03-24T17:12:29.316895674Z" level=debug msg="shim has been terminated" error="exit status 1" vmID=3 time="2021-03-24T17:12:36.448799620Z" level=info msg=exited ExecID= TaskID=4 exit_status=137 exited_at="2021-03-24 17:12:36.443763037 +0000 UTC" runtime=aws.firecracker vmID=4 time="2021-03-24T17:12:36.448875942Z" level=info msg="connection was closed: read /proc/self/fd/15: file already closed" ExecID= TaskID=4 runtime=aws.firecracker stream=stdin vmID=4 time="2021-03-24T17:12:36.448961960Z" level=error msg="error closing io stream" ExecID= TaskID=4 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stdin vmID=4 time="2021-03-24T17:12:36.449347722Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/exit type=containerd.events.TaskExit time="2021-03-24T17:12:36.961740661Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/delete type=containerd.events.TaskDelete time="2021-03-24T17:12:36.973266731Z" level=info msg="PatchGuestDrive successful" runtime=aws.firecracker time="2021-03-24T17:12:36.974068359Z" level=info msg="shim disconnected" id=4 time="2021-03-24T17:12:36.975543430Z" level=debug msg="remove snapshot" key=4 time="2021-03-24T17:12:36.976090576Z" level=debug msg="event published" ns=firecracker-containerd topic=/snapshot/remove type=containerd.events.SnapshotRemove time="2021-03-24T17:12:36.976761218Z" level=debug msg="event published" ns=firecracker-containerd topic=/containers/delete type=containerd.events.ContainerDelete time="2021-03-24T17:12:36.977009263Z" level=debug msg="stop VM: VMID:\"4\" " time="2021-03-24T17:12:36.977353120Z" level=info msg="stopping the VM" runtime=aws.firecracker vmID=4 time="2021-03-24T17:12:36.978440094Z" level=error msg="error while forwarding events from VM agent" error="rpc error: code = Canceled desc = context canceled" runtime=aws.firecracker vmID=4 time="2021-03-24T17:12:37.085511798Z" level=debug msg="schedule snapshotter cleanup" snapshotter=devmapper time="2021-03-24T17:12:37.085627329Z" level=debug msg=walk time="2021-03-24T17:12:37.085872078Z" level=debug msg=remove key=firecracker-containerd/39/4 time="2021-03-24T17:12:37.181389785Z" level=debug msg="removed snapshot" key=firecracker-containerd/39/4 snapshotter=devmapper time="2021-03-24T17:12:37.181414012Z" level=debug msg="snapshot garbage collected" d=95.839684ms snapshotter=devmapper time="2021-03-24T17:12:37.181472020Z" level=debug msg="garbage collected" d="921.653µs" time="2021-03-24T17:12:37.370813430Z" level=info msg="firecracker exited: status=0" runtime=aws.firecracker time="2021-03-24T17:12:37.371731926Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/firecracker-vm/stop type=VMStop time="2021-03-24T17:12:41.449077628Z" level=error msg="error closing io stream" ExecID= TaskID=4 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stderr vmID=4 time="2021-03-24T17:12:41.449110011Z" level=error msg="error closing io stream" ExecID= TaskID=4 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stdout vmID=4 time="2021-03-24T17:12:42.371759070Z" level=error msg="aws.firecracker: publisher not closed" shim_stream=stderr vmID=4 time="2021-03-24T17:12:42.373321375Z" level=debug msg="shim has been terminated" error="exit status 1" vmID=4 time="2021-03-24T17:14:21.523581128Z" level=debug msg="create VM request: VMID:\"5\" MachineCfg: KernelArgs:\"ro noapic reboot=k panic=1 pci=off nomodules systemd.log_color=false systemd.unit=firecracker.target init=/sbin/overlay-init tsc=reliable quiet 8250.nr_uarts=0 ipv6.disable=1\" NetworkInterfaces: > > TimeoutSeconds:100 " time="2021-03-24T17:14:21.523673317Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:14:21.523979833Z" level=debug msg="starting containerd-shim-aws-firecracker" vmID=5 time="2021-03-24T17:14:21.559663493Z" level=info msg="starting signal loop" namespace=firecracker-containerd path=/var/lib/firecracker-containerd/shim-base/firecracker-containerd/5 pid=84879 time="2021-03-24T17:14:21.560576940Z" level=info msg="creating new VM" runtime=aws.firecracker vmID=5 time="2021-03-24T17:14:21.560957252Z" level=info msg="Called startVMM(), setting up a VMM on firecracker.sock" runtime=aws.firecracker setupLogging setupMetrics time="2021-03-24T17:14:21.573077416Z" level=info msg="VMM metrics disabled." runtime=aws.firecracker time="2021-03-24T17:14:21.573734582Z" level=info msg="refreshMachineConfiguration: [GET /machine-config][200] getMachineConfigurationOK &{CPUTemplate:T2 HtEnabled:0xc000630403 MemSizeMib:0xc0006303f8 VcpuCount:0xc0006303f0}" runtime=aws.firecracker time="2021-03-24T17:14:21.574166013Z" level=info msg="PutGuestBootSource: [PUT /boot-source][204] putGuestBootSourceNoContent " runtime=aws.firecracker time="2021-03-24T17:14:21.574205116Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/runtime/default-rootfs.img, slot root_drive, root true." runtime=aws.firecracker time="2021-03-24T17:14:21.574707665Z" level=info msg="Attached drive /var/lib/firecracker-containerd/runtime/default-rootfs.img: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:14:21.574738209Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/5/ctrstub0, slot MN2HE43UOVRDA, root false." runtime=aws.firecracker time="2021-03-24T17:14:21.575031914Z" level=info msg="Attached drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/5/ctrstub0: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:14:21.575073341Z" level=info msg="Attaching NIC 5_tap (hwaddr 02:FC:00:00:00:04) at index 1" runtime=aws.firecracker time="2021-03-24T17:14:21.596864263Z" level=info msg="startInstance successful: [PUT /actions][204] createSyncActionNoContent " runtime=aws.firecracker time="2021-03-24T17:14:21.596916068Z" level=info msg="calling agent" runtime=aws.firecracker vmID=5 time="2021-03-24T17:14:22.597463046Z" level=info msg="successfully started the VM" runtime=aws.firecracker vmID=5 time="2021-03-24T17:14:22.598018923Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/firecracker-vm/start type=VMStart time="2021-03-24T17:14:22.601133332Z" level=debug msg="prepare snapshot" key=5 parent="sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:14:22.601269755Z" level=debug msg=prepare key=firecracker-containerd/40/5 parent="firecracker-containerd/16/sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:14:22.601439146Z" level=debug msg="creating snapshot device '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-29' from '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-8'" time="2021-03-24T17:14:22.695182056Z" level=debug msg="event published" ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare time="2021-03-24T17:14:22.698633575Z" level=debug msg="get snapshot mounts" key=5 time="2021-03-24T17:14:22.698729838Z" level=debug msg=mounts key=firecracker-containerd/40/5 time="2021-03-24T17:14:22.747316016Z" level=debug msg="event published" ns=firecracker-containerd topic=/containers/create type=containerd.events.ContainerCreate time="2021-03-24T17:14:22.749129402Z" level=debug msg="get snapshot mounts" key=5 time="2021-03-24T17:14:22.749165950Z" level=debug msg=mounts key=firecracker-containerd/40/5 time="2021-03-24T17:14:22.768321121Z" level=debug msg="garbage collected" d="566.093µs" time="2021-03-24T17:14:22.782661087Z" level=debug msg=StartShim runtime=aws.firecracker task_id=5 time="2021-03-24T17:14:22.783280763Z" level=debug msg="create VM request: VMID:\"5\" " time="2021-03-24T17:14:22.783316050Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:14:22.783813277Z" level=info msg="successfully started shim (git commit: 10cc33c3c603d9ac8025fd243826cb3b1edbdead)." runtime=aws.firecracker task_id=5 vmID=5 time="2021-03-24T17:14:22.785399431Z" level=info msg="PatchGuestDrive successful" runtime=aws.firecracker time="2021-03-24T17:14:22.926726018Z" level=info msg="successfully created task" ExecID= TaskID=5 pid_in_vm=724 runtime=aws.firecracker vmID=5 time="2021-03-24T17:14:22.926991794Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/create type=containerd.events.TaskCreate time="2021-03-24T17:14:22.935789388Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/start type=containerd.events.TaskStart time="2021-03-24T17:14:25.209044600Z" level=debug msg="create VM request: VMID:\"6\" MachineCfg: KernelArgs:\"ro noapic reboot=k panic=1 pci=off nomodules systemd.log_color=false systemd.unit=firecracker.target init=/sbin/overlay-init tsc=reliable quiet 8250.nr_uarts=0 ipv6.disable=1\" NetworkInterfaces: > > TimeoutSeconds:100 " time="2021-03-24T17:14:25.209123089Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:14:25.209397537Z" level=debug msg="starting containerd-shim-aws-firecracker" vmID=6 time="2021-03-24T17:14:25.246551089Z" level=info msg="starting signal loop" namespace=firecracker-containerd path=/var/lib/firecracker-containerd/shim-base/firecracker-containerd/6 pid=85219 time="2021-03-24T17:14:25.247538887Z" level=info msg="creating new VM" runtime=aws.firecracker vmID=6 time="2021-03-24T17:14:25.247950880Z" level=info msg="Called startVMM(), setting up a VMM on firecracker.sock" runtime=aws.firecracker setupLogging setupMetrics time="2021-03-24T17:14:25.260209452Z" level=info msg="VMM metrics disabled." runtime=aws.firecracker time="2021-03-24T17:14:25.260630819Z" level=info msg="refreshMachineConfiguration: [GET /machine-config][200] getMachineConfigurationOK &{CPUTemplate:T2 HtEnabled:0xc0008109f3 MemSizeMib:0xc0008109e8 VcpuCount:0xc0008109e0}" runtime=aws.firecracker time="2021-03-24T17:14:25.261011999Z" level=info msg="PutGuestBootSource: [PUT /boot-source][204] putGuestBootSourceNoContent " runtime=aws.firecracker time="2021-03-24T17:14:25.261041031Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/runtime/default-rootfs.img, slot root_drive, root true." runtime=aws.firecracker time="2021-03-24T17:14:25.261563021Z" level=info msg="Attached drive /var/lib/firecracker-containerd/runtime/default-rootfs.img: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:14:25.261593248Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/6/ctrstub0, slot MN2HE43UOVRDA, root false." runtime=aws.firecracker time="2021-03-24T17:14:25.261878220Z" level=info msg="Attached drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/6/ctrstub0: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:14:25.261908166Z" level=info msg="Attaching NIC 6_tap (hwaddr 02:FC:00:00:00:05) at index 1" runtime=aws.firecracker time="2021-03-24T17:14:25.285695691Z" level=info msg="startInstance successful: [PUT /actions][204] createSyncActionNoContent " runtime=aws.firecracker time="2021-03-24T17:14:25.285746039Z" level=info msg="calling agent" runtime=aws.firecracker vmID=6 time="2021-03-24T17:14:26.286283066Z" level=info msg="successfully started the VM" runtime=aws.firecracker vmID=6 time="2021-03-24T17:14:26.286839560Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/firecracker-vm/start type=VMStart time="2021-03-24T17:14:26.290764862Z" level=debug msg="prepare snapshot" key=6 parent="sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:14:26.290875816Z" level=debug msg=prepare key=firecracker-containerd/41/6 parent="firecracker-containerd/16/sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:14:26.291041110Z" level=debug msg="creating snapshot device '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-30' from '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-8'" time="2021-03-24T17:14:26.403431106Z" level=debug msg="event published" ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare time="2021-03-24T17:14:26.406098743Z" level=debug msg="get snapshot mounts" key=6 time="2021-03-24T17:14:26.406174463Z" level=debug msg=mounts key=firecracker-containerd/41/6 time="2021-03-24T17:14:26.444069788Z" level=debug msg="event published" ns=firecracker-containerd topic=/containers/create type=containerd.events.ContainerCreate time="2021-03-24T17:14:26.445730066Z" level=debug msg="get snapshot mounts" key=6 time="2021-03-24T17:14:26.445766116Z" level=debug msg=mounts key=firecracker-containerd/41/6 time="2021-03-24T17:14:26.477571792Z" level=debug msg=StartShim runtime=aws.firecracker task_id=6 time="2021-03-24T17:14:26.478191492Z" level=debug msg="create VM request: VMID:\"6\" " time="2021-03-24T17:14:26.478218276Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:14:26.478618913Z" level=info msg="successfully started shim (git commit: 10cc33c3c603d9ac8025fd243826cb3b1edbdead)." runtime=aws.firecracker task_id=6 vmID=6 time="2021-03-24T17:14:26.479764666Z" level=debug msg="garbage collected" d="677.756µs" time="2021-03-24T17:14:26.480460448Z" level=info msg="PatchGuestDrive successful" runtime=aws.firecracker time="2021-03-24T17:14:26.631318600Z" level=info msg="successfully created task" ExecID= TaskID=6 pid_in_vm=724 runtime=aws.firecracker vmID=6 time="2021-03-24T17:14:26.631728524Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/create type=containerd.events.TaskCreate time="2021-03-24T17:14:26.644123663Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/start type=containerd.events.TaskStart time="2021-03-24T17:14:29.611393783Z" level=debug msg="create VM request: VMID:\"7\" MachineCfg: KernelArgs:\"ro noapic reboot=k panic=1 pci=off nomodules systemd.log_color=false systemd.unit=firecracker.target init=/sbin/overlay-init tsc=reliable quiet 8250.nr_uarts=0 ipv6.disable=1\" NetworkInterfaces: > > TimeoutSeconds:100 " time="2021-03-24T17:14:29.611522522Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:14:29.611791919Z" level=debug msg="starting containerd-shim-aws-firecracker" vmID=7 time="2021-03-24T17:14:29.644418594Z" level=info msg="starting signal loop" namespace=firecracker-containerd path=/var/lib/firecracker-containerd/shim-base/firecracker-containerd/7 pid=85661 time="2021-03-24T17:14:29.645742507Z" level=info msg="creating new VM" runtime=aws.firecracker vmID=7 time="2021-03-24T17:14:29.646231135Z" level=info msg="Called startVMM(), setting up a VMM on firecracker.sock" runtime=aws.firecracker setupLogging setupMetrics time="2021-03-24T17:14:29.658738945Z" level=info msg="VMM metrics disabled." runtime=aws.firecracker time="2021-03-24T17:14:29.659330178Z" level=info msg="refreshMachineConfiguration: [GET /machine-config][200] getMachineConfigurationOK &{CPUTemplate:T2 HtEnabled:0xc00049ab53 MemSizeMib:0xc00049ab08 VcpuCount:0xc00049ab00}" runtime=aws.firecracker time="2021-03-24T17:14:29.659776035Z" level=info msg="PutGuestBootSource: [PUT /boot-source][204] putGuestBootSourceNoContent " runtime=aws.firecracker time="2021-03-24T17:14:29.659808682Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/runtime/default-rootfs.img, slot root_drive, root true." runtime=aws.firecracker time="2021-03-24T17:14:29.660361955Z" level=info msg="Attached drive /var/lib/firecracker-containerd/runtime/default-rootfs.img: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:14:29.660397699Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/7/ctrstub0, slot MN2HE43UOVRDA, root false." runtime=aws.firecracker time="2021-03-24T17:14:29.660685033Z" level=info msg="Attached drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/7/ctrstub0: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:14:29.660714718Z" level=info msg="Attaching NIC 7_tap (hwaddr 02:FC:00:00:00:06) at index 1" runtime=aws.firecracker time="2021-03-24T17:14:29.683034363Z" level=info msg="startInstance successful: [PUT /actions][204] createSyncActionNoContent " runtime=aws.firecracker time="2021-03-24T17:14:29.683087398Z" level=info msg="calling agent" runtime=aws.firecracker vmID=7 time="2021-03-24T17:14:29.711448597Z" level=debug msg="create VM request: VMID:\"8\" MachineCfg: KernelArgs:\"ro noapic reboot=k panic=1 pci=off nomodules systemd.log_color=false systemd.unit=firecracker.target init=/sbin/overlay-init tsc=reliable quiet 8250.nr_uarts=0 ipv6.disable=1\" NetworkInterfaces: > > TimeoutSeconds:100 " time="2021-03-24T17:14:29.711531102Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:14:29.711802939Z" level=debug msg="starting containerd-shim-aws-firecracker" vmID=8 time="2021-03-24T17:14:29.745304323Z" level=info msg="starting signal loop" namespace=firecracker-containerd path=/var/lib/firecracker-containerd/shim-base/firecracker-containerd/8 pid=85709 time="2021-03-24T17:14:29.745704198Z" level=info msg="creating new VM" runtime=aws.firecracker vmID=8 time="2021-03-24T17:14:29.746171450Z" level=info msg="Called startVMM(), setting up a VMM on firecracker.sock" runtime=aws.firecracker setupLogging setupMetrics time="2021-03-24T17:14:29.758524550Z" level=info msg="VMM metrics disabled." runtime=aws.firecracker time="2021-03-24T17:14:29.759347414Z" level=info msg="refreshMachineConfiguration: [GET /machine-config][200] getMachineConfigurationOK &{CPUTemplate:T2 HtEnabled:0xc000794113 MemSizeMib:0xc000794108 VcpuCount:0xc000794100}" runtime=aws.firecracker time="2021-03-24T17:14:29.759665167Z" level=info msg="PutGuestBootSource: [PUT /boot-source][204] putGuestBootSourceNoContent " runtime=aws.firecracker time="2021-03-24T17:14:29.759699724Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/runtime/default-rootfs.img, slot root_drive, root true." runtime=aws.firecracker time="2021-03-24T17:14:29.760192639Z" level=info msg="Attached drive /var/lib/firecracker-containerd/runtime/default-rootfs.img: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:14:29.760214277Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/8/ctrstub0, slot MN2HE43UOVRDA, root false." runtime=aws.firecracker time="2021-03-24T17:14:29.760480381Z" level=info msg="Attached drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/8/ctrstub0: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:14:29.760522850Z" level=info msg="Attaching NIC 8_tap (hwaddr 02:FC:00:00:00:07) at index 1" runtime=aws.firecracker time="2021-03-24T17:14:29.781260568Z" level=info msg="startInstance successful: [PUT /actions][204] createSyncActionNoContent " runtime=aws.firecracker time="2021-03-24T17:14:29.781309760Z" level=info msg="calling agent" runtime=aws.firecracker vmID=8 time="2021-03-24T17:14:30.783613021Z" level=info msg="successfully started the VM" runtime=aws.firecracker vmID=7 time="2021-03-24T17:14:30.784090947Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/firecracker-vm/start type=VMStart time="2021-03-24T17:14:30.788545454Z" level=debug msg="prepare snapshot" key=7 parent="sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:14:30.788670133Z" level=debug msg=prepare key=firecracker-containerd/42/7 parent="firecracker-containerd/16/sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:14:30.788842801Z" level=debug msg="creating snapshot device '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-31' from '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-8'" time="2021-03-24T17:14:30.881829720Z" level=info msg="successfully started the VM" runtime=aws.firecracker vmID=8 time="2021-03-24T17:14:30.882206208Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/firecracker-vm/start type=VMStart time="2021-03-24T17:14:30.899539805Z" level=debug msg="event published" ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare time="2021-03-24T17:14:30.902631301Z" level=debug msg="get snapshot mounts" key=7 time="2021-03-24T17:14:30.902704702Z" level=debug msg=mounts key=firecracker-containerd/42/7 time="2021-03-24T17:14:30.902793024Z" level=debug msg="prepare snapshot" key=8 parent="sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:14:30.902896667Z" level=debug msg=prepare key=firecracker-containerd/43/8 parent="firecracker-containerd/16/sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:14:30.903028060Z" level=debug msg="creating snapshot device '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-32' from '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-8'" time="2021-03-24T17:14:30.979284781Z" level=debug msg="event published" ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare time="2021-03-24T17:14:30.979706517Z" level=debug msg="event published" ns=firecracker-containerd topic=/containers/create type=containerd.events.ContainerCreate time="2021-03-24T17:14:30.982462597Z" level=debug msg="get snapshot mounts" key=8 time="2021-03-24T17:14:30.982544342Z" level=debug msg=mounts key=firecracker-containerd/43/8 time="2021-03-24T17:14:30.985109269Z" level=debug msg="get snapshot mounts" key=7 time="2021-03-24T17:14:30.985188307Z" level=debug msg=mounts key=firecracker-containerd/42/7 time="2021-03-24T17:14:31.018840411Z" level=debug msg=StartShim runtime=aws.firecracker task_id=7 time="2021-03-24T17:14:31.019236469Z" level=debug msg="create VM request: VMID:\"7\" " time="2021-03-24T17:14:31.019273546Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:14:31.019758166Z" level=info msg="successfully started shim (git commit: 10cc33c3c603d9ac8025fd243826cb3b1edbdead)." runtime=aws.firecracker task_id=7 vmID=7 time="2021-03-24T17:14:31.021474281Z" level=info msg="PatchGuestDrive successful" runtime=aws.firecracker time="2021-03-24T17:14:31.039701415Z" level=debug msg="event published" ns=firecracker-containerd topic=/containers/create type=containerd.events.ContainerCreate time="2021-03-24T17:14:31.041392846Z" level=debug msg="get snapshot mounts" key=8 time="2021-03-24T17:14:31.041459838Z" level=debug msg=mounts key=firecracker-containerd/43/8 time="2021-03-24T17:14:31.064665131Z" level=debug msg="garbage collected" d="900.794µs" time="2021-03-24T17:14:31.075674421Z" level=debug msg=StartShim runtime=aws.firecracker task_id=8 time="2021-03-24T17:14:31.076341192Z" level=debug msg="create VM request: VMID:\"8\" " time="2021-03-24T17:14:31.076391330Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:14:31.076841149Z" level=info msg="successfully started shim (git commit: 10cc33c3c603d9ac8025fd243826cb3b1edbdead)." runtime=aws.firecracker task_id=8 vmID=8 time="2021-03-24T17:14:31.078578609Z" level=info msg="PatchGuestDrive successful" runtime=aws.firecracker time="2021-03-24T17:14:31.184917347Z" level=info msg="successfully created task" ExecID= TaskID=7 pid_in_vm=725 runtime=aws.firecracker vmID=7 time="2021-03-24T17:14:31.185451943Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/create type=containerd.events.TaskCreate time="2021-03-24T17:14:31.193107380Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/start type=containerd.events.TaskStart time="2021-03-24T17:14:31.244508034Z" level=info msg="successfully created task" ExecID= TaskID=8 pid_in_vm=723 runtime=aws.firecracker vmID=8 time="2021-03-24T17:14:31.244896285Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/create type=containerd.events.TaskCreate time="2021-03-24T17:14:31.253459940Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/start type=containerd.events.TaskStart time="2021-03-24T17:16:16.476125808Z" level=info msg=exited ExecID= TaskID=5 exit_status=137 exited_at="2021-03-24 17:16:16.467522712 +0000 UTC" runtime=aws.firecracker vmID=5 time="2021-03-24T17:16:16.476183050Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/exit type=containerd.events.TaskExit time="2021-03-24T17:16:16.476240064Z" level=info msg="connection was closed: read /proc/self/fd/15: file already closed" ExecID= TaskID=5 runtime=aws.firecracker stream=stdin vmID=5 time="2021-03-24T17:16:16.476296679Z" level=error msg="error closing io stream" ExecID= TaskID=5 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stdin vmID=5 time="2021-03-24T17:16:16.987113173Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/delete type=containerd.events.TaskDelete time="2021-03-24T17:16:16.999963324Z" level=info msg="PatchGuestDrive successful" runtime=aws.firecracker time="2021-03-24T17:16:17.000610639Z" level=info msg="shim disconnected" id=5 time="2021-03-24T17:16:17.002172927Z" level=debug msg="remove snapshot" key=5 time="2021-03-24T17:16:17.002721772Z" level=debug msg="event published" ns=firecracker-containerd topic=/snapshot/remove type=containerd.events.SnapshotRemove time="2021-03-24T17:16:17.003502920Z" level=debug msg="event published" ns=firecracker-containerd topic=/containers/delete type=containerd.events.ContainerDelete time="2021-03-24T17:16:17.003798680Z" level=debug msg="stop VM: VMID:\"5\" " time="2021-03-24T17:16:17.004264569Z" level=info msg="stopping the VM" runtime=aws.firecracker vmID=5 time="2021-03-24T17:16:17.005278906Z" level=error msg="error while forwarding events from VM agent" error="rpc error: code = Canceled desc = context canceled" runtime=aws.firecracker vmID=5 time="2021-03-24T17:16:17.067038471Z" level=debug msg="schedule snapshotter cleanup" snapshotter=devmapper time="2021-03-24T17:16:17.067109438Z" level=debug msg=walk time="2021-03-24T17:16:17.067221885Z" level=debug msg=remove key=firecracker-containerd/40/5 time="2021-03-24T17:16:17.193731894Z" level=debug msg="removed snapshot" key=firecracker-containerd/40/5 snapshotter=devmapper time="2021-03-24T17:16:17.193766349Z" level=debug msg="snapshot garbage collected" d=126.69434ms snapshotter=devmapper time="2021-03-24T17:16:17.193837006Z" level=debug msg="garbage collected" d="837.029µs" time="2021-03-24T17:16:17.402248825Z" level=info msg="firecracker exited: status=0" runtime=aws.firecracker time="2021-03-24T17:16:17.403058716Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/firecracker-vm/stop type=VMStop time="2021-03-24T17:16:17.484559012Z" level=info msg=exited ExecID= TaskID=6 exit_status=137 exited_at="2021-03-24 17:16:17.47691999 +0000 UTC" runtime=aws.firecracker vmID=6 time="2021-03-24T17:16:17.484720849Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/exit type=containerd.events.TaskExit time="2021-03-24T17:16:17.484759072Z" level=info msg="connection was closed: read /proc/self/fd/15: file already closed" ExecID= TaskID=6 runtime=aws.firecracker stream=stdin vmID=6 time="2021-03-24T17:16:17.485147113Z" level=error msg="error closing io stream" ExecID= TaskID=6 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stdin vmID=6 time="2021-03-24T17:16:17.999303283Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/delete type=containerd.events.TaskDelete time="2021-03-24T17:16:18.008910588Z" level=info msg="PatchGuestDrive successful" runtime=aws.firecracker time="2021-03-24T17:16:18.009653536Z" level=info msg="shim disconnected" id=6 time="2021-03-24T17:16:18.011484413Z" level=debug msg="remove snapshot" key=6 time="2021-03-24T17:16:18.012033371Z" level=debug msg="event published" ns=firecracker-containerd topic=/snapshot/remove type=containerd.events.SnapshotRemove time="2021-03-24T17:16:18.012632245Z" level=debug msg="event published" ns=firecracker-containerd topic=/containers/delete type=containerd.events.ContainerDelete time="2021-03-24T17:16:18.012930315Z" level=debug msg="stop VM: VMID:\"6\" " time="2021-03-24T17:16:18.013325194Z" level=info msg="stopping the VM" runtime=aws.firecracker vmID=6 time="2021-03-24T17:16:18.014525487Z" level=error msg="error while forwarding events from VM agent" error="rpc error: code = Canceled desc = context canceled" runtime=aws.firecracker vmID=6 time="2021-03-24T17:16:18.083682772Z" level=debug msg="schedule snapshotter cleanup" snapshotter=devmapper time="2021-03-24T17:16:18.083763427Z" level=debug msg=walk time="2021-03-24T17:16:18.083899079Z" level=debug msg=remove key=firecracker-containerd/41/6 time="2021-03-24T17:16:18.213227372Z" level=debug msg="removed snapshot" key=firecracker-containerd/41/6 snapshotter=devmapper time="2021-03-24T17:16:18.213292498Z" level=debug msg="snapshot garbage collected" d=129.548644ms snapshotter=devmapper time="2021-03-24T17:16:18.213330224Z" level=debug msg="garbage collected" d="878.407µs" time="2021-03-24T17:16:18.410671719Z" level=info msg="firecracker exited: status=0" runtime=aws.firecracker time="2021-03-24T17:16:18.412466114Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/firecracker-vm/stop type=VMStop time="2021-03-24T17:16:21.476509436Z" level=error msg="error closing io stream" ExecID= TaskID=5 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stdout vmID=5 time="2021-03-24T17:16:21.476524405Z" level=error msg="error closing io stream" ExecID= TaskID=5 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stderr vmID=5 time="2021-03-24T17:16:22.403076793Z" level=error msg="aws.firecracker: publisher not closed" shim_stream=stderr vmID=5 time="2021-03-24T17:16:22.404762199Z" level=debug msg="shim has been terminated" error="exit status 1" vmID=5 time="2021-03-24T17:16:22.484735268Z" level=error msg="error closing io stream" ExecID= TaskID=6 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stderr vmID=6 time="2021-03-24T17:16:22.484770474Z" level=error msg="error closing io stream" ExecID= TaskID=6 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stdout vmID=6 time="2021-03-24T17:16:23.412526600Z" level=error msg="aws.firecracker: publisher not closed" shim_stream=stderr vmID=6 time="2021-03-24T17:16:23.414149450Z" level=debug msg="shim has been terminated" error="exit status 1" vmID=6 time="2021-03-24T17:16:23.522381680Z" level=info msg=exited ExecID= TaskID=7 exit_status=137 exited_at="2021-03-24 17:16:23.514100907 +0000 UTC" runtime=aws.firecracker vmID=7 time="2021-03-24T17:16:23.522537781Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/exit type=containerd.events.TaskExit time="2021-03-24T17:16:23.522589533Z" level=info msg="connection was closed: read /proc/self/fd/15: file already closed" ExecID= TaskID=7 runtime=aws.firecracker stream=stdin vmID=7 time="2021-03-24T17:16:23.522688308Z" level=error msg="error closing io stream" ExecID= TaskID=7 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stdin vmID=7 time="2021-03-24T17:16:24.035801830Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/delete type=containerd.events.TaskDelete time="2021-03-24T17:16:24.047550534Z" level=info msg="PatchGuestDrive successful" runtime=aws.firecracker time="2021-03-24T17:16:24.048184376Z" level=info msg="shim disconnected" id=7 time="2021-03-24T17:16:24.050000295Z" level=debug msg="remove snapshot" key=7 time="2021-03-24T17:16:24.050714877Z" level=debug msg="event published" ns=firecracker-containerd topic=/snapshot/remove type=containerd.events.SnapshotRemove time="2021-03-24T17:16:24.051256744Z" level=debug msg="event published" ns=firecracker-containerd topic=/containers/delete type=containerd.events.ContainerDelete time="2021-03-24T17:16:24.051555190Z" level=debug msg="stop VM: VMID:\"7\" " time="2021-03-24T17:16:24.051889205Z" level=info msg="stopping the VM" runtime=aws.firecracker vmID=7 time="2021-03-24T17:16:24.053102004Z" level=error msg="error while forwarding events from VM agent" error="rpc error: code = Canceled desc = context canceled" runtime=aws.firecracker vmID=7 time="2021-03-24T17:16:24.075748793Z" level=debug msg="schedule snapshotter cleanup" snapshotter=devmapper time="2021-03-24T17:16:24.075860130Z" level=debug msg=walk time="2021-03-24T17:16:24.076067858Z" level=debug msg=remove key=firecracker-containerd/42/7 time="2021-03-24T17:16:24.201005323Z" level=debug msg="removed snapshot" key=firecracker-containerd/42/7 snapshotter=devmapper time="2021-03-24T17:16:24.201035041Z" level=debug msg="snapshot garbage collected" d=125.226012ms snapshotter=devmapper time="2021-03-24T17:16:24.201057381Z" level=debug msg="garbage collected" d="943.22µs" time="2021-03-24T17:16:24.450519683Z" level=info msg="firecracker exited: status=0" runtime=aws.firecracker time="2021-03-24T17:16:24.451258527Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/firecracker-vm/stop type=VMStop time="2021-03-24T17:16:25.533452707Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/exit type=containerd.events.TaskExit time="2021-03-24T17:16:25.533387816Z" level=info msg=exited ExecID= TaskID=8 exit_status=137 exited_at="2021-03-24 17:16:25.524595841 +0000 UTC" runtime=aws.firecracker vmID=8 time="2021-03-24T17:16:25.533569893Z" level=info msg="connection was closed: read /proc/self/fd/15: file already closed" ExecID= TaskID=8 runtime=aws.firecracker stream=stdin vmID=8 time="2021-03-24T17:16:25.533683828Z" level=error msg="error closing io stream" ExecID= TaskID=8 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stdin vmID=8 time="2021-03-24T17:16:26.048471012Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/delete type=containerd.events.TaskDelete time="2021-03-24T17:16:26.059082985Z" level=info msg="PatchGuestDrive successful" runtime=aws.firecracker time="2021-03-24T17:16:26.059774293Z" level=info msg="shim disconnected" id=8 time="2021-03-24T17:16:26.061388354Z" level=debug msg="remove snapshot" key=8 time="2021-03-24T17:16:26.062020057Z" level=debug msg="event published" ns=firecracker-containerd topic=/snapshot/remove type=containerd.events.SnapshotRemove time="2021-03-24T17:16:26.062695704Z" level=debug msg="event published" ns=firecracker-containerd topic=/containers/delete type=containerd.events.ContainerDelete time="2021-03-24T17:16:26.063089094Z" level=debug msg="stop VM: VMID:\"8\" " time="2021-03-24T17:16:26.063512364Z" level=info msg="stopping the VM" runtime=aws.firecracker vmID=8 time="2021-03-24T17:16:26.064523567Z" level=error msg="error while forwarding events from VM agent" error="rpc error: code = Canceled desc = context canceled" runtime=aws.firecracker vmID=8 time="2021-03-24T17:16:26.133516866Z" level=debug msg="schedule snapshotter cleanup" snapshotter=devmapper time="2021-03-24T17:16:26.133621277Z" level=debug msg=walk time="2021-03-24T17:16:26.133816102Z" level=debug msg=remove key=firecracker-containerd/43/8 time="2021-03-24T17:16:26.252647807Z" level=debug msg="removed snapshot" key=firecracker-containerd/43/8 snapshotter=devmapper time="2021-03-24T17:16:26.252680007Z" level=debug msg="snapshot garbage collected" d=119.101283ms snapshotter=devmapper time="2021-03-24T17:16:26.252703966Z" level=debug msg="garbage collected" d="883.951µs" time="2021-03-24T17:16:26.462572383Z" level=info msg="firecracker exited: status=0" runtime=aws.firecracker time="2021-03-24T17:16:26.463211598Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/firecracker-vm/stop type=VMStop time="2021-03-24T17:16:28.522618849Z" level=error msg="error closing io stream" ExecID= TaskID=7 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stderr vmID=7 time="2021-03-24T17:16:28.522624309Z" level=error msg="error closing io stream" ExecID= TaskID=7 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stdout vmID=7 time="2021-03-24T17:16:29.451397985Z" level=error msg="aws.firecracker: publisher not closed" shim_stream=stderr vmID=7 time="2021-03-24T17:16:29.452983932Z" level=debug msg="shim has been terminated" error="exit status 1" vmID=7 time="2021-03-24T17:16:30.533599773Z" level=error msg="error closing io stream" ExecID= TaskID=8 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stdout vmID=8 time="2021-03-24T17:16:30.533627843Z" level=error msg="error closing io stream" ExecID= TaskID=8 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stderr vmID=8 time="2021-03-24T17:16:31.463382548Z" level=error msg="aws.firecracker: publisher not closed" shim_stream=stderr vmID=8 time="2021-03-24T17:16:31.465077337Z" level=debug msg="shim has been terminated" error="exit status 1" vmID=8 time="2021-03-24T17:17:53.435502537Z" level=debug msg="create VM request: VMID:\"9\" MachineCfg: KernelArgs:\"ro noapic reboot=k panic=1 pci=off nomodules systemd.log_color=false systemd.unit=firecracker.target init=/sbin/overlay-init tsc=reliable quiet 8250.nr_uarts=0 ipv6.disable=1\" NetworkInterfaces: > > TimeoutSeconds:100 " time="2021-03-24T17:17:53.435585033Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:17:53.436032591Z" level=debug msg="starting containerd-shim-aws-firecracker" vmID=9 time="2021-03-24T17:17:53.466895345Z" level=info msg="starting signal loop" namespace=firecracker-containerd path=/var/lib/firecracker-containerd/shim-base/firecracker-containerd/9 pid=94101 time="2021-03-24T17:17:53.467985819Z" level=info msg="creating new VM" runtime=aws.firecracker vmID=9 time="2021-03-24T17:17:53.468223860Z" level=error msg="failed to create VM" error="failed to build VM configuration: failed to create container stub drives: failed to create container stub drive: open /var/lib/firecracker-containerd/shim-base/firecracker-containerd/9/ctrstub0: file exists" runtime=aws.firecracker vmID=9 time="2021-03-24T17:17:53.468497084Z" level=error msg="shim CreateVM returned error" error="rpc error: code = Unknown desc = failed to create VM: failed to build VM configuration: failed to create container stub drives: failed to create container stub drive: open /var/lib/firecracker-containerd/shim-base/firecracker-containerd/9/ctrstub0: file exists" time="2021-03-24T17:17:53.469552432Z" level=debug msg="shim has been terminated" error="signal: killed" vmID=9 time="2021-03-24T17:17:53.533591717Z" level=debug msg="create VM request: VMID:\"10\" MachineCfg: KernelArgs:\"ro noapic reboot=k panic=1 pci=off nomodules systemd.log_color=false systemd.unit=firecracker.target init=/sbin/overlay-init tsc=reliable quiet 8250.nr_uarts=0 ipv6.disable=1\" NetworkInterfaces: > > TimeoutSeconds:100 " time="2021-03-24T17:17:53.533667047Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:17:53.533961484Z" level=debug msg="starting containerd-shim-aws-firecracker" vmID=10 time="2021-03-24T17:17:53.566933153Z" level=info msg="starting signal loop" namespace=firecracker-containerd path=/var/lib/firecracker-containerd/shim-base/firecracker-containerd/10 pid=94138 time="2021-03-24T17:17:53.567136672Z" level=info msg="creating new VM" runtime=aws.firecracker vmID=10 time="2021-03-24T17:17:53.567373446Z" level=error msg="failed to create VM" error="failed to build VM configuration: failed to create container stub drives: failed to create container stub drive: open /var/lib/firecracker-containerd/shim-base/firecracker-containerd/10/ctrstub0: file exists" runtime=aws.firecracker vmID=10 time="2021-03-24T17:17:53.567714095Z" level=error msg="shim CreateVM returned error" error="rpc error: code = Unknown desc = failed to create VM: failed to build VM configuration: failed to create container stub drives: failed to create container stub drive: open /var/lib/firecracker-containerd/shim-base/firecracker-containerd/10/ctrstub0: file exists" time="2021-03-24T17:17:53.569178787Z" level=debug msg="shim has been terminated" error="signal: killed" vmID=10 time="2021-03-24T17:17:54.025684918Z" level=debug msg="create VM request: VMID:\"12\" MachineCfg: KernelArgs:\"ro noapic reboot=k panic=1 pci=off nomodules systemd.log_color=false systemd.unit=firecracker.target init=/sbin/overlay-init tsc=reliable quiet 8250.nr_uarts=0 ipv6.disable=1\" NetworkInterfaces: > > TimeoutSeconds:100 " time="2021-03-24T17:17:54.025801746Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:17:54.025991882Z" level=debug msg="starting containerd-shim-aws-firecracker" vmID=12 time="2021-03-24T17:17:54.059032041Z" level=info msg="starting signal loop" namespace=firecracker-containerd path=/var/lib/firecracker-containerd/shim-base/firecracker-containerd/12 pid=94232 time="2021-03-24T17:17:54.060242365Z" level=info msg="creating new VM" runtime=aws.firecracker vmID=12 time="2021-03-24T17:17:54.060471640Z" level=error msg="failed to create VM" error="failed to build VM configuration: failed to create container stub drives: failed to create container stub drive: open /var/lib/firecracker-containerd/shim-base/firecracker-containerd/12/ctrstub0: file exists" runtime=aws.firecracker vmID=12 time="2021-03-24T17:17:54.060756922Z" level=error msg="shim CreateVM returned error" error="rpc error: code = Unknown desc = failed to create VM: failed to build VM configuration: failed to create container stub drives: failed to create container stub drive: open /var/lib/firecracker-containerd/shim-base/firecracker-containerd/12/ctrstub0: file exists" time="2021-03-24T17:17:54.062150593Z" level=debug msg="shim has been terminated" error="signal: killed" vmID=12 time="2021-03-24T17:18:13.452748704Z" level=debug msg="create VM request: VMID:\"17\" MachineCfg: KernelArgs:\"ro noapic reboot=k panic=1 pci=off nomodules systemd.log_color=false systemd.unit=firecracker.target init=/sbin/overlay-init tsc=reliable quiet 8250.nr_uarts=0 ipv6.disable=1\" NetworkInterfaces: > > TimeoutSeconds:100 " time="2021-03-24T17:18:13.452802982Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:18:13.453043615Z" level=debug msg="starting containerd-shim-aws-firecracker" vmID=17 time="2021-03-24T17:18:13.495012783Z" level=info msg="starting signal loop" namespace=firecracker-containerd path=/var/lib/firecracker-containerd/shim-base/firecracker-containerd/17 pid=95077 time="2021-03-24T17:18:13.496182755Z" level=info msg="creating new VM" runtime=aws.firecracker vmID=17 time="2021-03-24T17:18:13.496482776Z" level=info msg="Called startVMM(), setting up a VMM on firecracker.sock" runtime=aws.firecracker setupLogging setupMetrics time="2021-03-24T17:18:13.512705517Z" level=info msg="VMM metrics disabled." runtime=aws.firecracker time="2021-03-24T17:18:13.513262662Z" level=info msg="refreshMachineConfiguration: [GET /machine-config][200] getMachineConfigurationOK &{CPUTemplate:T2 HtEnabled:0xc000908933 MemSizeMib:0xc000908928 VcpuCount:0xc000908920}" runtime=aws.firecracker time="2021-03-24T17:18:13.513686040Z" level=info msg="PutGuestBootSource: [PUT /boot-source][204] putGuestBootSourceNoContent " runtime=aws.firecracker time="2021-03-24T17:18:13.513705997Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/runtime/default-rootfs.img, slot root_drive, root true." runtime=aws.firecracker time="2021-03-24T17:18:13.514113713Z" level=info msg="Attached drive /var/lib/firecracker-containerd/runtime/default-rootfs.img: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:18:13.514148036Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/17/ctrstub0, slot MN2HE43UOVRDA, root false." runtime=aws.firecracker time="2021-03-24T17:18:13.514413232Z" level=info msg="Attached drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/17/ctrstub0: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:18:13.514447997Z" level=info msg="Attaching NIC 17_tap (hwaddr 02:FC:00:00:00:10) at index 1" runtime=aws.firecracker time="2021-03-24T17:18:13.531276260Z" level=info msg="startInstance successful: [PUT /actions][204] createSyncActionNoContent " runtime=aws.firecracker time="2021-03-24T17:18:13.531321520Z" level=info msg="calling agent" runtime=aws.firecracker vmID=17 time="2021-03-24T17:18:13.582440559Z" level=debug msg="create VM request: VMID:\"18\" MachineCfg: KernelArgs:\"ro noapic reboot=k panic=1 pci=off nomodules systemd.log_color=false systemd.unit=firecracker.target init=/sbin/overlay-init tsc=reliable quiet 8250.nr_uarts=0 ipv6.disable=1\" NetworkInterfaces: > > TimeoutSeconds:100 " time="2021-03-24T17:18:13.582511635Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:18:13.582767953Z" level=debug msg="starting containerd-shim-aws-firecracker" vmID=18 time="2021-03-24T17:18:13.628695870Z" level=info msg="starting signal loop" namespace=firecracker-containerd path=/var/lib/firecracker-containerd/shim-base/firecracker-containerd/18 pid=95139 time="2021-03-24T17:18:13.629043380Z" level=info msg="creating new VM" runtime=aws.firecracker vmID=18 time="2021-03-24T17:18:13.629353363Z" level=info msg="Called startVMM(), setting up a VMM on firecracker.sock" runtime=aws.firecracker setupLogging setupMetrics time="2021-03-24T17:18:13.641289704Z" level=info msg="VMM metrics disabled." runtime=aws.firecracker time="2021-03-24T17:18:13.641824109Z" level=info msg="refreshMachineConfiguration: [GET /machine-config][200] getMachineConfigurationOK &{CPUTemplate:T2 HtEnabled:0xc000508883 MemSizeMib:0xc000508878 VcpuCount:0xc000508870}" runtime=aws.firecracker time="2021-03-24T17:18:13.642101525Z" level=info msg="PutGuestBootSource: [PUT /boot-source][204] putGuestBootSourceNoContent " runtime=aws.firecracker time="2021-03-24T17:18:13.642133048Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/runtime/default-rootfs.img, slot root_drive, root true." runtime=aws.firecracker time="2021-03-24T17:18:13.642696988Z" level=info msg="Attached drive /var/lib/firecracker-containerd/runtime/default-rootfs.img: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:18:13.642738392Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/18/ctrstub0, slot MN2HE43UOVRDA, root false." runtime=aws.firecracker time="2021-03-24T17:18:13.643079486Z" level=info msg="Attached drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/18/ctrstub0: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:18:13.643109289Z" level=info msg="Attaching NIC 18_tap (hwaddr 02:FC:00:00:00:11) at index 1" runtime=aws.firecracker time="2021-03-24T17:18:13.664734095Z" level=info msg="startInstance successful: [PUT /actions][204] createSyncActionNoContent " runtime=aws.firecracker time="2021-03-24T17:18:13.664769000Z" level=info msg="calling agent" runtime=aws.firecracker vmID=18 time="2021-03-24T17:18:13.689071822Z" level=debug msg="create VM request: VMID:\"19\" MachineCfg: KernelArgs:\"ro noapic reboot=k panic=1 pci=off nomodules systemd.log_color=false systemd.unit=firecracker.target init=/sbin/overlay-init tsc=reliable quiet 8250.nr_uarts=0 ipv6.disable=1\" NetworkInterfaces: > > TimeoutSeconds:100 " time="2021-03-24T17:18:13.689155979Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:18:13.689470724Z" level=debug msg="starting containerd-shim-aws-firecracker" vmID=19 time="2021-03-24T17:18:13.731947027Z" level=info msg="starting signal loop" namespace=firecracker-containerd path=/var/lib/firecracker-containerd/shim-base/firecracker-containerd/19 pid=95179 time="2021-03-24T17:18:13.732143720Z" level=info msg="creating new VM" runtime=aws.firecracker vmID=19 time="2021-03-24T17:18:13.732359592Z" level=info msg="Called startVMM(), setting up a VMM on firecracker.sock" runtime=aws.firecracker setupLogging setupMetrics time="2021-03-24T17:18:13.745084676Z" level=info msg="VMM metrics disabled." runtime=aws.firecracker time="2021-03-24T17:18:13.745627004Z" level=info msg="refreshMachineConfiguration: [GET /machine-config][200] getMachineConfigurationOK &{CPUTemplate:T2 HtEnabled:0xc000700f13 MemSizeMib:0xc000700ee8 VcpuCount:0xc000700ee0}" runtime=aws.firecracker time="2021-03-24T17:18:13.746056110Z" level=info msg="PutGuestBootSource: [PUT /boot-source][204] putGuestBootSourceNoContent " runtime=aws.firecracker time="2021-03-24T17:18:13.746089151Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/runtime/default-rootfs.img, slot root_drive, root true." runtime=aws.firecracker time="2021-03-24T17:18:13.746714312Z" level=info msg="Attached drive /var/lib/firecracker-containerd/runtime/default-rootfs.img: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:18:13.746745465Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/19/ctrstub0, slot MN2HE43UOVRDA, root false." runtime=aws.firecracker time="2021-03-24T17:18:13.747117557Z" level=info msg="Attached drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/19/ctrstub0: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:18:13.747147982Z" level=info msg="Attaching NIC 19_tap (hwaddr 02:FC:00:00:00:12) at index 1" runtime=aws.firecracker time="2021-03-24T17:18:13.769106704Z" level=info msg="startInstance successful: [PUT /actions][204] createSyncActionNoContent " runtime=aws.firecracker time="2021-03-24T17:18:13.769151192Z" level=info msg="calling agent" runtime=aws.firecracker vmID=19 time="2021-03-24T17:18:14.631791645Z" level=info msg="successfully started the VM" runtime=aws.firecracker vmID=17 time="2021-03-24T17:18:14.632255639Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/firecracker-vm/start type=VMStart time="2021-03-24T17:18:14.637325761Z" level=debug msg="prepare snapshot" key=17 parent="sha256:e172bf8795d813920c658a6772bb108238dc2cf13f1fc1ee1ac5c595c37da14a" time="2021-03-24T17:18:14.637462939Z" level=debug msg=prepare key=firecracker-containerd/44/17 parent="firecracker-containerd/25/sha256:e172bf8795d813920c658a6772bb108238dc2cf13f1fc1ee1ac5c595c37da14a" time="2021-03-24T17:18:14.637615891Z" level=debug msg="creating snapshot device '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-33' from '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-14'" time="2021-03-24T17:18:14.763497228Z" level=debug msg="event published" ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare time="2021-03-24T17:18:14.765177836Z" level=info msg="successfully started the VM" runtime=aws.firecracker vmID=18 time="2021-03-24T17:18:14.765568718Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/firecracker-vm/start type=VMStart time="2021-03-24T17:18:14.766073067Z" level=debug msg="get snapshot mounts" key=17 time="2021-03-24T17:18:14.766184796Z" level=debug msg=mounts key=firecracker-containerd/44/17 time="2021-03-24T17:18:14.768675136Z" level=debug msg="prepare snapshot" key=18 parent="sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:18:14.768791772Z" level=debug msg=prepare key=firecracker-containerd/45/18 parent="firecracker-containerd/16/sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:18:14.768956789Z" level=debug msg="creating snapshot device '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-34' from '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-8'" time="2021-03-24T17:18:14.869654289Z" level=info msg="successfully started the VM" runtime=aws.firecracker vmID=19 time="2021-03-24T17:18:14.870180770Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/firecracker-vm/start type=VMStart time="2021-03-24T17:18:14.895112061Z" level=debug msg="event published" ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare time="2021-03-24T17:18:14.895603305Z" level=debug msg="event published" ns=firecracker-containerd topic=/containers/create type=containerd.events.ContainerCreate time="2021-03-24T17:18:14.897395499Z" level=debug msg="get snapshot mounts" key=17 time="2021-03-24T17:18:14.897430695Z" level=debug msg=mounts key=firecracker-containerd/44/17 time="2021-03-24T17:18:14.897858869Z" level=debug msg="get snapshot mounts" key=18 time="2021-03-24T17:18:14.897940323Z" level=debug msg=mounts key=firecracker-containerd/45/18 time="2021-03-24T17:18:14.898638756Z" level=debug msg="prepare snapshot" key=19 parent="sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:18:14.898771113Z" level=debug msg=prepare key=firecracker-containerd/46/19 parent="firecracker-containerd/16/sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:18:14.899002568Z" level=debug msg="creating snapshot device '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-35' from '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-8'" time="2021-03-24T17:18:14.931260016Z" level=debug msg=StartShim runtime=aws.firecracker task_id=17 time="2021-03-24T17:18:14.932023281Z" level=debug msg="create VM request: VMID:\"17\" " time="2021-03-24T17:18:14.932080870Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:18:14.940802428Z" level=info msg="successfully started shim (git commit: 10cc33c3c603d9ac8025fd243826cb3b1edbdead)." runtime=aws.firecracker task_id=17 vmID=17 time="2021-03-24T17:18:14.942472874Z" level=info msg="PatchGuestDrive successful" runtime=aws.firecracker time="2021-03-24T17:18:15.011563222Z" level=debug msg="event published" ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare time="2021-03-24T17:18:15.012552493Z" level=debug msg="event published" ns=firecracker-containerd topic=/containers/create type=containerd.events.ContainerCreate time="2021-03-24T17:18:15.013874439Z" level=debug msg="garbage collected" d=1.230676ms time="2021-03-24T17:18:15.015231067Z" level=debug msg="get snapshot mounts" key=18 time="2021-03-24T17:18:15.015309942Z" level=debug msg=mounts key=firecracker-containerd/45/18 time="2021-03-24T17:18:15.015763660Z" level=debug msg="get snapshot mounts" key=19 time="2021-03-24T17:18:15.015819331Z" level=debug msg=mounts key=firecracker-containerd/46/19 time="2021-03-24T17:18:15.052872164Z" level=debug msg=StartShim runtime=aws.firecracker task_id=18 time="2021-03-24T17:18:15.053491157Z" level=debug msg="create VM request: VMID:\"18\" " time="2021-03-24T17:18:15.053536348Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:18:15.054023994Z" level=info msg="successfully started shim (git commit: 10cc33c3c603d9ac8025fd243826cb3b1edbdead)." runtime=aws.firecracker task_id=18 vmID=18 time="2021-03-24T17:18:15.055873431Z" level=info msg="PatchGuestDrive successful" runtime=aws.firecracker time="2021-03-24T17:18:15.072649498Z" level=debug msg="event published" ns=firecracker-containerd topic=/containers/create type=containerd.events.ContainerCreate time="2021-03-24T17:18:15.074214622Z" level=debug msg="get snapshot mounts" key=19 time="2021-03-24T17:18:15.074292892Z" level=debug msg=mounts key=firecracker-containerd/46/19 time="2021-03-24T17:18:15.086047917Z" level=info msg="successfully created task" ExecID= TaskID=17 pid_in_vm=724 runtime=aws.firecracker vmID=17 time="2021-03-24T17:18:15.086342566Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/create type=containerd.events.TaskCreate time="2021-03-24T17:18:15.093623396Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/start type=containerd.events.TaskStart time="2021-03-24T17:18:15.095581304Z" level=debug msg="garbage collected" d="967.372µs" time="2021-03-24T17:18:15.116924531Z" level=debug msg=StartShim runtime=aws.firecracker task_id=19 time="2021-03-24T17:18:15.117515819Z" level=debug msg="create VM request: VMID:\"19\" " time="2021-03-24T17:18:15.117555980Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:18:15.117927785Z" level=info msg="successfully started shim (git commit: 10cc33c3c603d9ac8025fd243826cb3b1edbdead)." runtime=aws.firecracker task_id=19 vmID=19 time="2021-03-24T17:18:15.119535187Z" level=info msg="PatchGuestDrive successful" runtime=aws.firecracker time="2021-03-24T17:18:15.206735041Z" level=info msg="successfully created task" ExecID= TaskID=18 pid_in_vm=725 runtime=aws.firecracker vmID=18 time="2021-03-24T17:18:15.207131784Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/create type=containerd.events.TaskCreate time="2021-03-24T17:18:15.214016696Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/start type=containerd.events.TaskStart time="2021-03-24T17:18:15.259745728Z" level=info msg="successfully created task" ExecID= TaskID=19 pid_in_vm=724 runtime=aws.firecracker vmID=19 time="2021-03-24T17:18:15.260035066Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/create type=containerd.events.TaskCreate time="2021-03-24T17:18:15.267507562Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/start type=containerd.events.TaskStart time="2021-03-24T17:18:20.373888689Z" level=debug msg="create VM request: VMID:\"20\" MachineCfg: KernelArgs:\"ro noapic reboot=k panic=1 pci=off nomodules systemd.log_color=false systemd.unit=firecracker.target init=/sbin/overlay-init tsc=reliable quiet 8250.nr_uarts=0 ipv6.disable=1\" NetworkInterfaces: > > TimeoutSeconds:100 " time="2021-03-24T17:18:20.374188015Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:18:20.375115241Z" level=debug msg="starting containerd-shim-aws-firecracker" vmID=20 time="2021-03-24T17:18:20.406014664Z" level=info msg="starting signal loop" namespace=firecracker-containerd path=/var/lib/firecracker-containerd/shim-base/firecracker-containerd/20 pid=95878 time="2021-03-24T17:18:20.406509969Z" level=info msg="creating new VM" runtime=aws.firecracker vmID=20 time="2021-03-24T17:18:20.407251511Z" level=info msg="Called startVMM(), setting up a VMM on firecracker.sock" runtime=aws.firecracker setupLogging setupMetrics time="2021-03-24T17:18:20.418905661Z" level=info msg="VMM metrics disabled." runtime=aws.firecracker time="2021-03-24T17:18:20.419249229Z" level=info msg="refreshMachineConfiguration: [GET /machine-config][200] getMachineConfigurationOK &{CPUTemplate:T2 HtEnabled:0xc00068e3e3 MemSizeMib:0xc00068e3b8 VcpuCount:0xc00068e3b0}" runtime=aws.firecracker time="2021-03-24T17:18:20.419490064Z" level=info msg="PutGuestBootSource: [PUT /boot-source][204] putGuestBootSourceNoContent " runtime=aws.firecracker time="2021-03-24T17:18:20.419509178Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/runtime/default-rootfs.img, slot root_drive, root true." runtime=aws.firecracker time="2021-03-24T17:18:20.419817700Z" level=info msg="Attached drive /var/lib/firecracker-containerd/runtime/default-rootfs.img: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:18:20.419837354Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/20/ctrstub0, slot MN2HE43UOVRDA, root false." runtime=aws.firecracker time="2021-03-24T17:18:20.420027004Z" level=info msg="Attached drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/20/ctrstub0: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:18:20.420236851Z" level=info msg="Attaching NIC 20_tap (hwaddr 02:FC:00:00:00:13) at index 1" runtime=aws.firecracker time="2021-03-24T17:18:20.521264319Z" level=info msg="startInstance successful: [PUT /actions][204] createSyncActionNoContent " runtime=aws.firecracker time="2021-03-24T17:18:20.521293736Z" level=info msg="calling agent" runtime=aws.firecracker vmID=20 time="2021-03-24T17:18:21.621891038Z" level=info msg="successfully started the VM" runtime=aws.firecracker vmID=20 time="2021-03-24T17:18:21.622356519Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/firecracker-vm/start type=VMStart time="2021-03-24T17:18:21.626446000Z" level=debug msg="prepare snapshot" key=20 parent="sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:18:21.626547127Z" level=debug msg=prepare key=firecracker-containerd/47/20 parent="firecracker-containerd/16/sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:18:21.626671985Z" level=debug msg="creating snapshot device '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-36' from '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-8'" time="2021-03-24T17:18:21.756099750Z" level=debug msg="event published" ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare time="2021-03-24T17:18:21.758682379Z" level=debug msg="get snapshot mounts" key=20 time="2021-03-24T17:18:21.758777829Z" level=debug msg=mounts key=firecracker-containerd/47/20 time="2021-03-24T17:18:21.817343859Z" level=debug msg="event published" ns=firecracker-containerd topic=/containers/create type=containerd.events.ContainerCreate time="2021-03-24T17:18:21.818831857Z" level=debug msg="get snapshot mounts" key=20 time="2021-03-24T17:18:21.818893321Z" level=debug msg=mounts key=firecracker-containerd/47/20 time="2021-03-24T17:18:21.829074753Z" level=debug msg="garbage collected" d="831.894µs" time="2021-03-24T17:18:21.853689810Z" level=debug msg=StartShim runtime=aws.firecracker task_id=20 time="2021-03-24T17:18:21.854291106Z" level=debug msg="create VM request: VMID:\"20\" " time="2021-03-24T17:18:21.854335320Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:18:21.854685006Z" level=info msg="successfully started shim (git commit: 10cc33c3c603d9ac8025fd243826cb3b1edbdead)." runtime=aws.firecracker task_id=20 vmID=20 time="2021-03-24T17:18:21.856571511Z" level=info msg="PatchGuestDrive successful" runtime=aws.firecracker time="2021-03-24T17:18:22.019122050Z" level=info msg="successfully created task" ExecID= TaskID=20 pid_in_vm=725 runtime=aws.firecracker vmID=20 time="2021-03-24T17:18:22.019257274Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/create type=containerd.events.TaskCreate time="2021-03-24T17:18:22.032641053Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/start type=containerd.events.TaskStart time="2021-03-24T17:18:32.337314476Z" level=debug msg="create VM request: VMID:\"22\" MachineCfg: KernelArgs:\"ro noapic reboot=k panic=1 pci=off nomodules systemd.log_color=false systemd.unit=firecracker.target init=/sbin/overlay-init tsc=reliable quiet 8250.nr_uarts=0 ipv6.disable=1\" NetworkInterfaces: > > TimeoutSeconds:100 " time="2021-03-24T17:18:32.337386270Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:18:32.337692066Z" level=debug msg="starting containerd-shim-aws-firecracker" vmID=22 time="2021-03-24T17:18:32.369849571Z" level=info msg="starting signal loop" namespace=firecracker-containerd path=/var/lib/firecracker-containerd/shim-base/firecracker-containerd/22 pid=96468 time="2021-03-24T17:18:32.370360348Z" level=info msg="creating new VM" runtime=aws.firecracker vmID=22 time="2021-03-24T17:18:32.371148956Z" level=info msg="Called startVMM(), setting up a VMM on firecracker.sock" runtime=aws.firecracker setupLogging setupMetrics time="2021-03-24T17:18:32.382785640Z" level=info msg="VMM metrics disabled." runtime=aws.firecracker time="2021-03-24T17:18:32.383200898Z" level=info msg="refreshMachineConfiguration: [GET /machine-config][200] getMachineConfigurationOK &{CPUTemplate:T2 HtEnabled:0xc0005446a3 MemSizeMib:0xc000544698 VcpuCount:0xc000544690}" runtime=aws.firecracker time="2021-03-24T17:18:32.383559084Z" level=info msg="PutGuestBootSource: [PUT /boot-source][204] putGuestBootSourceNoContent " runtime=aws.firecracker time="2021-03-24T17:18:32.383585546Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/runtime/default-rootfs.img, slot root_drive, root true." runtime=aws.firecracker time="2021-03-24T17:18:32.384088651Z" level=info msg="Attached drive /var/lib/firecracker-containerd/runtime/default-rootfs.img: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:18:32.384116101Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/22/ctrstub0, slot MN2HE43UOVRDA, root false." runtime=aws.firecracker time="2021-03-24T17:18:32.384332133Z" level=info msg="Attached drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/22/ctrstub0: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker time="2021-03-24T17:18:32.384358142Z" level=info msg="Attaching NIC 22_tap (hwaddr 02:FC:00:00:00:15) at index 1" runtime=aws.firecracker time="2021-03-24T17:18:32.408057784Z" level=info msg="startInstance successful: [PUT /actions][204] createSyncActionNoContent " runtime=aws.firecracker time="2021-03-24T17:18:32.408129639Z" level=info msg="calling agent" runtime=aws.firecracker vmID=22 time="2021-03-24T17:18:33.408635326Z" level=info msg="successfully started the VM" runtime=aws.firecracker vmID=22 time="2021-03-24T17:18:33.409111086Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/firecracker-vm/start type=VMStart time="2021-03-24T17:18:33.412411215Z" level=debug msg="prepare snapshot" key=22 parent="sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:18:33.412529910Z" level=debug msg=prepare key=firecracker-containerd/48/22 parent="firecracker-containerd/16/sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" time="2021-03-24T17:18:33.412678421Z" level=debug msg="creating snapshot device '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-37' from '9263a568aacc848834859add21941c181e5a16f44548ca3b6f0027b674d14630_thinpool-snap-8'" time="2021-03-24T17:18:33.507384256Z" level=debug msg="event published" ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare time="2021-03-24T17:18:33.509751375Z" level=debug msg="get snapshot mounts" key=22 time="2021-03-24T17:18:33.509840922Z" level=debug msg=mounts key=firecracker-containerd/48/22 time="2021-03-24T17:18:33.560152701Z" level=debug msg="event published" ns=firecracker-containerd topic=/containers/create type=containerd.events.ContainerCreate time="2021-03-24T17:18:33.561767360Z" level=debug msg="get snapshot mounts" key=22 time="2021-03-24T17:18:33.561906636Z" level=debug msg=mounts key=firecracker-containerd/48/22 time="2021-03-24T17:18:33.596025706Z" level=debug msg=StartShim runtime=aws.firecracker task_id=22 time="2021-03-24T17:18:33.597379960Z" level=debug msg="create VM request: VMID:\"22\" " time="2021-03-24T17:18:33.597422666Z" level=debug msg="using namespace: firecracker-containerd" time="2021-03-24T17:18:33.597856857Z" level=info msg="successfully started shim (git commit: 10cc33c3c603d9ac8025fd243826cb3b1edbdead)." runtime=aws.firecracker task_id=22 vmID=22 time="2021-03-24T17:18:33.599348035Z" level=info msg="PatchGuestDrive successful" runtime=aws.firecracker time="2021-03-24T17:18:33.603696138Z" level=debug msg="garbage collected" d="967.874µs" time="2021-03-24T17:18:33.741743139Z" level=info msg="successfully created task" ExecID= TaskID=22 pid_in_vm=725 runtime=aws.firecracker vmID=22 time="2021-03-24T17:18:33.742225416Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/create type=containerd.events.TaskCreate time="2021-03-24T17:18:33.749417531Z" level=debug msg="event forwarded" ns=firecracker-containerd topic=/tasks/start type=containerd.events.TaskStart