moby: fail with failed to register layer: Error processing tar file(exit status 1): invalid argument

Behavior

I’m building vm image for openstack, I wanna pull some docker images during build image process. some how it can’t start docker daemon during package installation.

so i just start daemon manually

here is my script:

cgroups-mount

/usr/bin/dockerd --dns 8.8.8.8 -b none -H unix:///var/run/docker.sock -s aufs --iptables=False --log-level debug & 

docker pull alpine

kill `cat /var/run/docker.pid`

looks like pull image correctly, but have some problem while register layer

Steps to reproduce the behavior

Output of docker version:

17.06.2~ce-0~ubuntu

Output of docker info:

Setting up aufs-tools (1:3.2+20130722-1.1) ...
Setting up docker-ce (17.06.2~ce-0~ubuntu) ...
runlevel:/var/run/utmp: No such file or directory
invoke-rc.d: policy-rc.d denied execution of start.
Setting up cgroup-lite (1.9) ...
invoke-rc.d: unknown initscript, /etc/init.d/cgroup-lite not found.
runlevel:/var/run/utmp: No such file or directory
invoke-rc.d: policy-rc.d denied execution of start.
Processing triggers for libc-bin (2.19-0ubuntu6.13) ...
Processing triggers for ureadahead (0.100.0-16) ...
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 59997  100 59997    0     0   929k      0 --:--:-- --:--:-- --:--:--  930k
dib-run-parts Tue Sep 12 07:46:45 UTC 2017 50-install-additional-packages completed
dib-run-parts Tue Sep 12 07:46:45 UTC 2017 Running /tmp/in_target.d/install.d/51-docker-images
time="2017-09-12T07:46:45.841186534Z" level=debug msg="Listener created for HTTP on unix (/var/run/docker.sock)" 
time="2017-09-12T07:46:45.841256478Z" level=warning msg="libcontainerd: makeUpgradeProof could not open /var/run/docker/libcontainerd/containerd" 
time="2017-09-12T07:46:45.841932965Z" level=info msg="libcontainerd: new containerd process, pid: 22038" 
time="2017-09-12T07:46:45.849166862Z" level=warning msg="containerd: low RLIMIT_NOFILE changing to max" current=1024 max=4096 
time="2017-09-12T07:46:46.342647631Z" level=debug msg="libcontainerd: containerd health check returned error: rpc error: code = 14 desc = grpc: the connection is unavailable" 
time="2017-09-12T07:46:46.844230634Z" level=warning msg="failed to rename /var/lib/docker/tmp for background deletion: rename /var/lib/docker/tmp /var/lib/docker/tmp-old: no such file or directory. Deleting synchronously" 
time="2017-09-12T07:46:46.844719706Z" level=debug msg="Using default logging driver json-file" 
time="2017-09-12T07:46:46.844820700Z" level=debug msg="Golang's threads limit set to 56250" 
time="2017-09-12T07:46:46.848800256Z" level=debug msg="[graphdriver] trying provided driver: aufs" 
time="2017-09-12T07:46:46.862405669Z" level=debug msg="Using graph driver aufs" 
time="2017-09-12T07:46:46.862679897Z" level=debug msg="Max Concurrent Downloads: 3" 
time="2017-09-12T07:46:46.862736284Z" level=debug msg="Max Concurrent Uploads: 5" 
time="2017-09-12T07:46:46.906451232Z" level=info msg="Graph migration to content-addressability took 0.00 seconds" 
time="2017-09-12T07:46:46.906626634Z" level=warning msg="Your kernel does not support swap memory limit" 
time="2017-09-12T07:46:46.906655174Z" level=warning msg="Your kernel does not support cgroup rt period" 
time="2017-09-12T07:46:46.906661351Z" level=warning msg="Your kernel does not support cgroup rt runtime" 
time="2017-09-12T07:46:46.906898102Z" level=info msg="Loading containers: start." 
time="2017-09-12T07:46:46.906932703Z" level=debug msg="Option Experimental: false" 
time="2017-09-12T07:46:46.906937260Z" level=debug msg="Option DefaultDriver: bridge" 
time="2017-09-12T07:46:46.906940556Z" level=debug msg="Option DefaultNetwork: bridge" 
time="2017-09-12T07:46:46.922846010Z" level=warning msg="Running modprobe nf_nat failed with message: `modprobe: ERROR: ../libkmod/libkmod.c:556 kmod_search_moddep() could not open moddep file '/lib/modules/4.4.0-93-generic/modules.dep.bin'`, error: exit status 1" 
time="2017-09-12T07:46:46.923721507Z" level=warning msg="Running modprobe xt_conntrack failed with message: `modprobe: ERROR: ../libkmod/libkmod.c:556 kmod_search_moddep() could not open moddep file '/lib/modules/4.4.0-93-generic/modules.dep.bin'`, error: exit status 1" 
time="2017-09-12T07:46:46.923766009Z" level=debug msg="Fail to initialize firewalld: Failed to connect to D-Bus system bus: dial unix /var/run/dbus/system_bus_socket: connect: no such file or directory, using raw iptables instead" 
time="2017-09-12T07:46:46.927622414Z" level=debug msg="/sbin/iptables, [--wait -t filter -n -L DOCKER-USER]" 
time="2017-09-12T07:46:46.928346271Z" level=debug msg="/sbin/iptables, [--wait -t filter -C DOCKER-USER -j RETURN]" 
time="2017-09-12T07:46:46.929089104Z" level=debug msg="/sbin/iptables, [--wait -t filter -C FORWARD -j DOCKER-USER]" 
time="2017-09-12T07:46:46.929869057Z" level=debug msg="/sbin/iptables, [--wait -D FORWARD -j DOCKER-USER]" 
time="2017-09-12T07:46:46.930622067Z" level=debug msg="/sbin/iptables, [--wait -I FORWARD -j DOCKER-USER]" 
time="2017-09-12T07:46:46.938301931Z" level=debug msg="/sbin/iptables, [--wait -t filter -n -L DOCKER-USER]" 
time="2017-09-12T07:46:46.940604244Z" level=debug msg="/sbin/iptables, [--wait -t filter -C DOCKER-USER -j RETURN]" 
time="2017-09-12T07:46:46.941493566Z" level=debug msg="/sbin/iptables, [--wait -t filter -C FORWARD -j DOCKER-USER]" 
time="2017-09-12T07:46:46.942392307Z" level=debug msg="/sbin/iptables, [--wait -D FORWARD -j DOCKER-USER]" 
time="2017-09-12T07:46:46.945492259Z" level=debug msg="/sbin/iptables, [--wait -I FORWARD -j DOCKER-USER]" 
time="2017-09-12T07:46:46.949221920Z" level=info msg="Loading containers: done." 
time="2017-09-12T07:46:46.956669087Z" level=info msg="Daemon has completed initialization" 
time="2017-09-12T07:46:46.956696913Z" level=info msg="Docker daemon" commit=cec0b72 graphdriver=aufs version=17.06.2-ce 
time="2017-09-12T07:46:46.956759608Z" level=debug msg="Registering routers" 
time="2017-09-12T07:46:46.956770351Z" level=debug msg="Registering GET, /containers/{name:.*}/checkpoints" 
time="2017-09-12T07:46:46.956970690Z" level=debug msg="Registering POST, /containers/{name:.*}/checkpoints" 
time="2017-09-12T07:46:46.957054481Z" level=debug msg="Registering DELETE, /containers/{name}/checkpoints/{checkpoint}" 
time="2017-09-12T07:46:46.957250059Z" level=debug msg="Registering HEAD, /containers/{name:.*}/archive" 
time="2017-09-12T07:46:46.957374431Z" level=debug msg="Registering GET, /containers/json" 
time="2017-09-12T07:46:46.957438891Z" level=debug msg="Registering GET, /containers/{name:.*}/export" 
time="2017-09-12T07:46:46.957508212Z" level=debug msg="Registering GET, /containers/{name:.*}/changes" 
time="2017-09-12T07:46:46.957577889Z" level=debug msg="Registering GET, /containers/{name:.*}/json" 
time="2017-09-12T07:46:46.957645371Z" level=debug msg="Registering GET, /containers/{name:.*}/top" 
time="2017-09-12T07:46:46.957707085Z" level=debug msg="Registering GET, /containers/{name:.*}/logs" 
time="2017-09-12T07:46:46.957780435Z" level=debug msg="Registering GET, /containers/{name:.*}/stats" 
time="2017-09-12T07:46:46.957843015Z" level=debug msg="Registering GET, /containers/{name:.*}/attach/ws" 
time="2017-09-12T07:46:46.957921415Z" level=debug msg="Registering GET, /exec/{id:.*}/json" 
time="2017-09-12T07:46:46.957991724Z" level=debug msg="Registering GET, /containers/{name:.*}/archive" 
time="2017-09-12T07:46:46.958058852Z" level=debug msg="Registering POST, /containers/create" 
time="2017-09-12T07:46:46.958102384Z" level=debug msg="Registering POST, /containers/{name:.*}/kill" 
time="2017-09-12T07:46:46.958171987Z" level=debug msg="Registering POST, /containers/{name:.*}/pause" 
time="2017-09-12T07:46:46.958235523Z" level=debug msg="Registering POST, /containers/{name:.*}/unpause" 
time="2017-09-12T07:46:46.958302224Z" level=debug msg="Registering POST, /containers/{name:.*}/restart" 
time="2017-09-12T07:46:46.958377908Z" level=debug msg="Registering POST, /containers/{name:.*}/start" 
time="2017-09-12T07:46:46.958442832Z" level=debug msg="Registering POST, /containers/{name:.*}/stop" 
time="2017-09-12T07:46:46.958500438Z" level=debug msg="Registering POST, /containers/{name:.*}/wait" 
time="2017-09-12T07:46:46.958566183Z" level=debug msg="Registering POST, /containers/{name:.*}/resize" 
time="2017-09-12T07:46:46.958631195Z" level=debug msg="Registering POST, /containers/{name:.*}/attach" 
time="2017-09-12T07:46:46.958701367Z" level=debug msg="Registering POST, /containers/{name:.*}/copy" 
time="2017-09-12T07:46:46.958762347Z" level=debug msg="Registering POST, /containers/{name:.*}/exec" 
time="2017-09-12T07:46:46.958820651Z" level=debug msg="Registering POST, /exec/{name:.*}/start" 
time="2017-09-12T07:46:46.958879781Z" level=debug msg="Registering POST, /exec/{name:.*}/resize" 
time="2017-09-12T07:46:46.958935906Z" level=debug msg="Registering POST, /containers/{name:.*}/rename" 
time="2017-09-12T07:46:46.958998332Z" level=debug msg="Registering POST, /containers/{name:.*}/update" 
time="2017-09-12T07:46:46.959067277Z" level=debug msg="Registering POST, /containers/prune" 
time="2017-09-12T07:46:46.959113579Z" level=debug msg="Registering PUT, /containers/{name:.*}/archive" 
time="2017-09-12T07:46:46.959207347Z" level=debug msg="Registering DELETE, /containers/{name:.*}" 
time="2017-09-12T07:46:46.959268953Z" level=debug msg="Registering GET, /images/json" 
time="2017-09-12T07:46:46.959311836Z" level=debug msg="Registering GET, /images/search" 
time="2017-09-12T07:46:46.959350012Z" level=debug msg="Registering GET, /images/get" 
time="2017-09-12T07:46:46.959391976Z" level=debug msg="Registering GET, /images/{name:.*}/get" 
time="2017-09-12T07:46:46.959450012Z" level=debug msg="Registering GET, /images/{name:.*}/history" 
time="2017-09-12T07:46:46.959511671Z" level=debug msg="Registering GET, /images/{name:.*}/json" 
time="2017-09-12T07:46:46.959569289Z" level=debug msg="Registering POST, /commit" 
time="2017-09-12T07:46:46.959606936Z" level=debug msg="Registering POST, /images/load" 
time="2017-09-12T07:46:46.959644950Z" level=debug msg="Registering POST, /images/create" 
time="2017-09-12T07:46:46.959697912Z" level=debug msg="Registering POST, /images/{name:.*}/push" 
time="2017-09-12T07:46:46.959754983Z" level=debug msg="Registering POST, /images/{name:.*}/tag" 
time="2017-09-12T07:46:46.959808560Z" level=debug msg="Registering POST, /images/prune" 
time="2017-09-12T07:46:46.959856570Z" level=debug msg="Registering DELETE, /images/{name:.*}" 
time="2017-09-12T07:46:46.959944768Z" level=debug msg="Registering OPTIONS, /{anyroute:.*}" 
time="2017-09-12T07:46:46.959993832Z" level=debug msg="Registering GET, /_ping" 
time="2017-09-12T07:46:46.960029460Z" level=debug msg="Registering GET, /events" 
time="2017-09-12T07:46:46.960066584Z" level=debug msg="Registering GET, /info" 
time="2017-09-12T07:46:46.960094732Z" level=debug msg="Registering GET, /version" 
time="2017-09-12T07:46:46.960128437Z" level=debug msg="Registering GET, /system/df" 
time="2017-09-12T07:46:46.960202150Z" level=debug msg="Registering POST, /auth" 
time="2017-09-12T07:46:46.960250046Z" level=debug msg="Registering GET, /volumes" 
time="2017-09-12T07:46:46.960310614Z" level=debug msg="Registering GET, /volumes/{name:.*}" 
time="2017-09-12T07:46:46.960405276Z" level=debug msg="Registering POST, /volumes/create" 
time="2017-09-12T07:46:46.960478597Z" level=debug msg="Registering POST, /volumes/prune" 
time="2017-09-12T07:46:46.960541346Z" level=debug msg="Registering DELETE, /volumes/{name:.*}" 
time="2017-09-12T07:46:46.960626760Z" level=debug msg="Registering POST, /build" 
time="2017-09-12T07:46:46.960671564Z" level=debug msg="Registering POST, /swarm/init" 
time="2017-09-12T07:46:46.960717861Z" level=debug msg="Registering POST, /swarm/join" 
time="2017-09-12T07:46:46.960768119Z" level=debug msg="Registering POST, /swarm/leave" 
time="2017-09-12T07:46:46.960814957Z" level=debug msg="Registering GET, /swarm" 
time="2017-09-12T07:46:46.960868199Z" level=debug msg="Registering GET, /swarm/unlockkey" 
time="2017-09-12T07:46:46.960919349Z" level=debug msg="Registering POST, /swarm/update" 
time="2017-09-12T07:46:46.960967175Z" level=debug msg="Registering POST, /swarm/unlock" 
time="2017-09-12T07:46:46.961012632Z" level=debug msg="Registering GET, /services" 
time="2017-09-12T07:46:46.961055063Z" level=debug msg="Registering GET, /services/{id}" 
time="2017-09-12T07:46:46.961138931Z" level=debug msg="Registering POST, /services/create" 
time="2017-09-12T07:46:46.961219037Z" level=debug msg="Registering POST, /services/{id}/update" 
time="2017-09-12T07:46:46.961287692Z" level=debug msg="Registering DELETE, /services/{id}" 
time="2017-09-12T07:46:46.961354258Z" level=debug msg="Registering GET, /services/{id}/logs" 
time="2017-09-12T07:46:46.961425767Z" level=debug msg="Registering GET, /nodes" 
time="2017-09-12T07:46:46.961462849Z" level=debug msg="Registering GET, /nodes/{id}" 
time="2017-09-12T07:46:46.961534267Z" level=debug msg="Registering DELETE, /nodes/{id}" 
time="2017-09-12T07:46:46.961601559Z" level=debug msg="Registering POST, /nodes/{id}/update" 
time="2017-09-12T07:46:46.961689765Z" level=debug msg="Registering GET, /tasks" 
time="2017-09-12T07:46:46.961731801Z" level=debug msg="Registering GET, /tasks/{id}" 
time="2017-09-12T07:46:46.961813595Z" level=debug msg="Registering GET, /tasks/{id}/logs" 
time="2017-09-12T07:46:46.961877073Z" level=debug msg="Registering GET, /secrets" 
time="2017-09-12T07:46:46.961926186Z" level=debug msg="Registering POST, /secrets/create" 
time="2017-09-12T07:46:46.961972564Z" level=debug msg="Registering DELETE, /secrets/{id}" 
time="2017-09-12T07:46:46.962040685Z" level=debug msg="Registering GET, /secrets/{id}" 
time="2017-09-12T07:46:46.962109431Z" level=debug msg="Registering POST, /secrets/{id}/update" 
time="2017-09-12T07:46:46.962184855Z" level=debug msg="Registering GET, /configs" 
time="2017-09-12T07:46:46.962245771Z" level=debug msg="Registering POST, /configs/create" 
time="2017-09-12T07:46:46.962297871Z" level=debug msg="Registering DELETE, /configs/{id}" 
time="2017-09-12T07:46:46.962365402Z" level=debug msg="Registering GET, /configs/{id}" 
time="2017-09-12T07:46:46.962425197Z" level=debug msg="Registering POST, /configs/{id}/update" 
time="2017-09-12T07:46:46.962490396Z" level=debug msg="Registering GET, /plugins" 
time="2017-09-12T07:46:46.962536142Z" level=debug msg="Registering GET, /plugins/{name:.*}/json" 
time="2017-09-12T07:46:46.962602849Z" level=debug msg="Registering GET, /plugins/privileges" 
time="2017-09-12T07:46:46.962655615Z" level=debug msg="Registering DELETE, /plugins/{name:.*}" 
time="2017-09-12T07:46:46.962727748Z" level=debug msg="Registering POST, /plugins/{name:.*}/enable" 
time="2017-09-12T07:46:46.962789580Z" level=debug msg="Registering POST, /plugins/{name:.*}/disable" 
time="2017-09-12T07:46:46.962851635Z" level=debug msg="Registering POST, /plugins/pull" 
time="2017-09-12T07:46:46.962904623Z" level=debug msg="Registering POST, /plugins/{name:.*}/push" 
time="2017-09-12T07:46:46.962969998Z" level=debug msg="Registering POST, /plugins/{name:.*}/upgrade" 
time="2017-09-12T07:46:46.963038959Z" level=debug msg="Registering POST, /plugins/{name:.*}/set" 
time="2017-09-12T07:46:46.963097214Z" level=debug msg="Registering POST, /plugins/create" 
time="2017-09-12T07:46:46.963145027Z" level=debug msg="Registering GET, /distribution/{name:.*}/json" 
time="2017-09-12T07:46:46.963220209Z" level=debug msg="Registering GET, /networks" 
time="2017-09-12T07:46:46.963268201Z" level=debug msg="Registering GET, /networks/" 
time="2017-09-12T07:46:46.963311555Z" level=debug msg="Registering GET, /networks/{id:.+}" 
time="2017-09-12T07:46:46.965407887Z" level=debug msg="Registering POST, /networks/create" 
time="2017-09-12T07:46:46.965571717Z" level=debug msg="Registering POST, /networks/{id:.*}/connect" 
time="2017-09-12T07:46:46.965762049Z" level=debug msg="Registering POST, /networks/{id:.*}/disconnect" 
time="2017-09-12T07:46:46.965966488Z" level=debug msg="Registering POST, /networks/prune" 
time="2017-09-12T07:46:46.966109467Z" level=debug msg="Registering DELETE, /networks/{id:.*}" 
time="2017-09-12T07:46:46.966516421Z" level=info msg="API listen on /var/run/docker.sock" 
No LSB modules are available.
4.4.0-93-generic
cgroup on /sys/fs/cgroup type tmpfs (rw,uid=0,gid=0,mode=0755)
time="2017-09-12T07:46:50.902380841Z" level=debug msg="Calling GET /_ping" 
time="2017-09-12T07:46:50.902872916Z" level=debug msg="Calling GET /v1.30/info" 
Containers: 0
 Running: 0
 Paused: 0
 Stopped: 0
Images: 0
Server Version: 17.06.2-ce
Storage Driver: aufs
 Root Dir: /var/lib/docker/aufs
 Backing Filesystem: extfs
 Dirs: 0
 Dirperm1 Supported: false
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins: 
 Volume: local
 Network: bridge host macvlan null overlay
 Log: awslogs fluentd gcplogs gelf journald json-file logentries splunk syslog
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: 6e23458c129b551d5c9871e5174f6b1b7f6d1170
runc version: 810190ceaa507aa2727d7ae6f4790c76ec150bd2
init version: 949e6fa
Kernel Version: 4.4.0-93-generic
Operating System: Ubuntu 14.04.5 LTS
OSType: linux
Architecture: x86_64
CPUs: 8
Total Memory: 7.677GiB
Name: linarnan-ubuntu
ID: 32WC:PI6F:A6XW:ZF5N:EKJP:USNE:GA6L:NLRB:KILC:EIPB:WIZQ:2OUO
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
Experimental: false
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false

WARNING: No swap limit support
time="2017-09-12T07:46:50.924403992Z" level=debug msg="Calling GET /_ping" 
Using default tag: latest
time="2017-09-12T07:46:50.925360600Z" level=debug msg="Calling GET /v1.30/info" 
time="2017-09-12T07:46:50.930831875Z" level=debug msg="Calling POST /v1.30/images/create?fromImage=alpine&tag=latest" 
time="2017-09-12T07:46:50.930995245Z" level=debug msg="Trying to pull alpine from https://registry-1.docker.io v2" 
time="2017-09-12T07:46:53.767696147Z" level=debug msg="Pulling ref from V2 registry: alpine:latest" 
time="2017-09-12T07:46:53.768241384Z" level=debug msg="pulling blob \"sha256:88286f41530e93dffd4b964e1db22ce4939fffa4a4c665dab8591fbab03d4926\"" 
latest: Pulling from library/alpine
88286f41530e: Pulling fs layer
time="2017-09-12T07:46:54.996123647Z" level=debug msg="Downloaded 88286f41530e to tempfile /var/lib/docker/tmp/GetImageBlob038532157" 
88286f41530e: Verifying Checksum
88286f41530e: Download complete
time="2017-09-12T07:46:55.091570957Z" level=debug msg="Cleaning up layer 1d1338d1db3fbe094657d373fbf6e4207c991b5eb55e821ea21a88232db4025a: Error processing tar file(exit status 1): invalid argument" 
time="2017-09-12T07:46:55.092338058Z" level=info msg="Attempting next endpoint for pull after error: failed to register layer: Error processing tar file(exit status 1): invalid argument" 
failed to register layer: Error processing tar file(exit status 1): invalid argument
time="2017-09-12T07:46:55.094321606Z" level=info msg="Processing signal 'terminated'" 
time="2017-09-12T07:46:55.094438723Z" level=debug msg="start clean shutdown of all containers with a 15 seconds timeout..." 
time="2017-09-12T07:46:55.141214245Z" level=debug msg="Cleaning up old mountid : start." 
time="2017-09-12T07:46:55.141348230Z" level=debug msg="Unix socket /run/docker/libnetwork/b8db334499e7acaf341a778fd03eded45f53be028998b28848daa7e9802bb9c8.sock doesn't exist. cannot accept client connections" 
time="2017-09-12T07:46:55.141464758Z" level=debug msg="Cleaning up old mountid : done." 
time="2017-09-12T07:46:55.141480523Z" level=debug msg="Clean shutdown succeeded" 
time="2017-09-12T07:46:55.141583725Z" level=info msg="stopping containerd after receiving terminated" 
time="2017-09-12T07:46:55.342442516Z" level=debug msg="libcontainerd: containerd health check returned error: rpc error: code = 9 desc = grpc: the client connection is closing"

Additional environment details (AWS, VirtualBox, physical, etc.) vm disk image building process (use https://docs.openstack.org/diskimage-builder/latest/index.html)