search

goldmann / docker-squash

Docker image squashing tool
MIT License
848 stars 109 forks source link

Marker files re-added can cause failures when importing the image #181

Closed goldmann closed 5 years ago

goldmann commented 5 years ago

Sometimes, when image is imported into Docker, the API returns no error, but the image cannot be found. When I try to manually import the tar archive generated by docker-squash using the Docker CLI,I get following output:

$ docker load -i ./image.tar                                                   
a57dc9e495aa: Loading layer [==================================================>]   156 MB/156 MB
Error processing tar file(exit status 1): not a directory
goldmann commented 5 years ago

Here is the debug log from Docker:

May 09 15:21:25 mistress dockerd-current[18982]: time="2019-05-09T15:21:25.467600618+02:00" level=debug msg="Calling POST /v1.26/images/load?quiet=0"
May 09 15:21:25 mistress dockerd-current[18982]: time="2019-05-09T15:21:25.467659862+02:00" level=debug msg="Unable to determine container for images"
May 09 15:21:25 mistress dockerd-current[18982]: time="2019-05-09T15:21:25.467775467+02:00" level=debug msg="{Action=load, Username=goldmann, LoginUID=1000, PID=19118}"
May 09 15:21:25 mistress dockerd-current[18982]: time="2019-05-09T15:21:25.467930222+02:00" level=debug msg="AuthZ request using plugin rhel-push-plugin"
May 09 15:21:26 mistress dockerd-current[18982]: time="2019-05-09T15:21:26.089070864+02:00" level=debug msg="Applying tar in /var/lib/docker/overlay2/b37033f6ef97a83ad8f258db47b295f7855d818a53dbddec0a221c7942027b40/diff"
May 09 15:21:26 mistress dockerd-current[18982]: time="2019-05-09T15:21:26.694191060+02:00" level=debug msg="Cleaning up layer b37033f6ef97a83ad8f258db47b295f7855d818a53dbddec0a221c7942027b40: Error processing tar file(exit status 1): not a directory"
May 09 15:21:26 mistress dockerd-current[18982]: time="2019-05-09T15:21:26.779698856+02:00" level=debug msg="AuthZ response using plugin rhel-push-plugin"
goldmann commented 5 years ago

Podman was able to load the image just fine:

$ podman load -i image.tar
Getting image source signatures
Copying blob a57dc9e495aa done
Copying blob b0176b436fa4 done
Copying blob 472721478dc5 done
Copying blob ba5e2a65d9d3 done
Copying blob 048edd935320 done
Copying config 3e95f98bf1 done
Writing manifest to image destination
Storing signatures
Loaded image(s): localhost/long:squashed
goldmann commented 5 years ago 
$ podman images | grep long                     
localhost/long                                                             squashed     3e95f98bf12d   2 hours ago    1.38 GB
goldmann commented 5 years ago

I'm trying to create a minimal reproducer, but so far I'm failing at it.

spolti commented 5 years ago

@goldmann A different issue start to happen today, the squash fail when I call cekit from a Makefile. here is the issue: https://pastebin.com/qaUbq8q9

I created other issue with the details.

goldmann commented 5 years ago

@spolti I'll review that one later, although I think this is, kind of, expected in cases where the image to squash is tagged multiple times. This can happen if you build the image, for example using the same source, multiple times and some tags were already assigned to it. Then you run it again, cached image is used and we are going to squash it. In a clean run, this issue should not exist, because we operate on image ID's and tag only when the process is successful.

Either case, I'll tackle this in https://github.com/goldmann/docker-squash/issues/182.

goldmann commented 5 years ago

I'm continuing investigation of this issue. I suspect that it is related to the openshift3/apb-base:v3.11 image used as a base for your image. I tried various different combinations, different base images, different packages installed, different labels, no labels, no modules, etc. I can only reproduce it when these two requirements are met together:

  1. openshift3/apb-base:v3.11 base image is used
  2. yum command is invoked to collect metadata (doesn't matter if as makecache or actual installation of some package)
goldmann commented 5 years ago

The best part is that the Docker API is happily returning 200 code:

2019-05-10 11:22:29,275 urllib3.connectionpool DEBUG    http://localhost:None "POST /v1.26/images/load HTTP/1.1" 200 None

But the Docker debug log shows that it actually fails to load it:

May 10 11:22:29 mistress dockerd-current[1354]: time="2019-05-10T11:22:29.106559375+02:00" level=debug msg="Applying tar in /var/lib/docker/overlay2/4e512091116f83e131bcbaa538efd3fcc89e3168c6b9a869fb55972a433f9855/diff"
May 10 11:22:29 mistress dockerd-current[1354]: time="2019-05-10T11:22:29.200864008+02:00" level=debug msg="Cleaning up layer 4e512091116f83e131bcbaa538efd3fcc89e3168c6b9a869fb55972a433f9855: Error processing tar file(exit status 1): not a directory"
goldmann commented 5 years ago

Here is the squash log for reference.

2019-05-10 11:22:09,525 root         DEBUG    Running version 1.0.7
2019-05-10 11:22:09,526 root         DEBUG    Preparing Docker client...
2019-05-10 11:22:09,526 docker.utils.config DEBUG    Trying paths: ['/home/goldmann/.docker/config.json', '/home/goldmann/.dockercfg']
2019-05-10 11:22:09,526 docker.utils.config DEBUG    No config file found
2019-05-10 11:22:09,526 docker.utils.config DEBUG    Trying paths: ['/home/goldmann/.docker/config.json', '/home/goldmann/.dockercfg']
2019-05-10 11:22:09,526 docker.utils.config DEBUG    No config file found
2019-05-10 11:22:09,530 urllib3.connectionpool DEBUG    http://localhost:None "GET /version HTTP/1.1" 200 290
2019-05-10 11:22:09,533 urllib3.connectionpool DEBUG    http://localhost:None "GET /v1.26/_ping HTTP/1.1" 200 2
2019-05-10 11:22:09,533 root         DEBUG    Docker client ready
2019-05-10 11:22:09,535 urllib3.connectionpool DEBUG    http://localhost:None "GET /v1.26/version HTTP/1.1" 200 290
2019-05-10 11:22:09,535 root         INFO     docker-squash version 1.0.7, Docker 1185cfd/1.13.1, API 1.26...
2019-05-10 11:22:09,535 root         INFO     Using v2 image format
2019-05-10 11:22:09,536 root         DEBUG    Using /tmp/docker-squash-7mnr12ep as the temporary directory
2019-05-10 11:22:09,539 urllib3.connectionpool DEBUG    http://localhost:None "GET /v1.26/images/131ab7d659fd/json HTTP/1.1" 200 None
2019-05-10 11:22:09,548 urllib3.connectionpool DEBUG    http://localhost:None "GET /v1.26/images/sha256:131ab7d659fd3d3e97698a29a4242bf7dcbffb450a83cce152fb7225163d0acb/history HTTP/1.1" 200 None
2019-05-10 11:22:09,549 root         INFO     Old image has 15 layers
2019-05-10 11:22:09,549 root         DEBUG    Old layers: ['<missing>', '<missing>', '<missing>', 'sha256:a6dfc06eb2f5f0da3acb0b9b5b4b8a2826f0391b3734ee90a4a56fc06f64eb26', 'sha256:3e9d897b1f9f0c41ff6746e5938c21934cdc26c0026a55ef5ab0dde41b539ad6', 'sha256:9cd6703d5f9dc93a544b71952b98db5d4581cec99dd6aa1f1de1cac797fd2a66', 'sha256:ca6d5724f14b835f09543f00f9c19069c01bfb592bd8fdf9389779cb2fae1eff', 'sha256:f3b9eb75a4d1d7433b8bc685145d837f3265678210e0e92f47f6ff7cb0d8aedb', 'sha256:1c0ba06b3c8dd8af9da434d0448f622a9d3b43ca1e84ac587352f23219fb2b1c', 'sha256:1c942be980f1153021cf6f2f86bb064c6edcec879aa91ab84287961dec3b330e', 'sha256:8d1bc6f8436efba3f613bc0e31f0e745a890171fd6fa80dd7c0702a91b5de7a8', 'sha256:95d488ff68997e3161c5b6baad8dd7fc777feb4d1a533315b9f008015bb2082d', 'sha256:23aeb14e1dcb64d00efd7efa5f626e5a1762c11b6542de765d849ad52c730544', 'sha256:ea01ea39f3fbdd2647fbc998409cc4d2b99343ad365012010eb317c660ee5f7c', 'sha256:131ab7d659fd3d3e97698a29a4242bf7dcbffb450a83cce152fb7225163d0acb']
2019-05-10 11:22:09,549 root         DEBUG    We detected number of layers as the argument to squash
2019-05-10 11:22:09,549 root         INFO     Checking if squashing is necessary...
2019-05-10 11:22:09,549 root         INFO     Attempting to squash last 11 layers...
2019-05-10 11:22:09,549 root         DEBUG    Layers to squash: ['sha256:3e9d897b1f9f0c41ff6746e5938c21934cdc26c0026a55ef5ab0dde41b539ad6', 'sha256:9cd6703d5f9dc93a544b71952b98db5d4581cec99dd6aa1f1de1cac797fd2a66', 'sha256:ca6d5724f14b835f09543f00f9c19069c01bfb592bd8fdf9389779cb2fae1eff', 'sha256:f3b9eb75a4d1d7433b8bc685145d837f3265678210e0e92f47f6ff7cb0d8aedb', 'sha256:1c0ba06b3c8dd8af9da434d0448f622a9d3b43ca1e84ac587352f23219fb2b1c', 'sha256:1c942be980f1153021cf6f2f86bb064c6edcec879aa91ab84287961dec3b330e', 'sha256:8d1bc6f8436efba3f613bc0e31f0e745a890171fd6fa80dd7c0702a91b5de7a8', 'sha256:95d488ff68997e3161c5b6baad8dd7fc777feb4d1a533315b9f008015bb2082d', 'sha256:23aeb14e1dcb64d00efd7efa5f626e5a1762c11b6542de765d849ad52c730544', 'sha256:ea01ea39f3fbdd2647fbc998409cc4d2b99343ad365012010eb317c660ee5f7c', 'sha256:131ab7d659fd3d3e97698a29a4242bf7dcbffb450a83cce152fb7225163d0acb']
2019-05-10 11:22:09,549 root         DEBUG    Layers to move: ['<missing>', '<missing>', '<missing>', 'sha256:a6dfc06eb2f5f0da3acb0b9b5b4b8a2826f0391b3734ee90a4a56fc06f64eb26']
2019-05-10 11:22:09,549 root         INFO     Saving image sha256:131ab7d659fd3d3e97698a29a4242bf7dcbffb450a83cce152fb7225163d0acb to /tmp/docker-squash-7mnr12ep/old directory...
2019-05-10 11:22:09,549 root         DEBUG    Try #1...
2019-05-10 11:22:19,410 urllib3.connectionpool DEBUG    http://localhost:None "GET /v1.26/images/sha256:131ab7d659fd3d3e97698a29a4242bf7dcbffb450a83cce152fb7225163d0acb/get HTTP/1.1" 200 None
2019-05-10 11:22:19,411 root         DEBUG    Extracting image using iterator over raw data
2019-05-10 11:22:23,374 root         INFO     Image saved!
2019-05-10 11:22:23,374 root         INFO     Squashing image '131ab7d659fd'...
2019-05-10 11:22:23,374 root         DEBUG    Reading '/tmp/docker-squash-7mnr12ep/old/manifest.json' JSON file...
2019-05-10 11:22:23,374 root         DEBUG    Reading '/tmp/docker-squash-7mnr12ep/old/131ab7d659fd3d3e97698a29a4242bf7dcbffb450a83cce152fb7225163d0acb.json' JSON file...
2019-05-10 11:22:23,375 root         INFO     Starting squashing...
2019-05-10 11:22:23,375 root         DEBUG    Generating list of files in layer 'd9f9a2145b0fb9eab484b597854872beb55025cc1ce86c0f5932afa95c99a66e'...
2019-05-10 11:22:23,825 root         DEBUG    Done, found 11647 files
2019-05-10 11:22:23,825 root         DEBUG    Generating list of files in layer '4f6836b44ebd4c3e497852885255177564139738d3c56aa8ef4647266638f236'...
2019-05-10 11:22:23,829 root         DEBUG    Done, found 7 files
2019-05-10 11:22:23,829 root         DEBUG    Generating list of files in layer 'd04653cb4068dbb022eba8274429de8193bea89a926af5a78fb9eb78cf9b363c'...
2019-05-10 11:22:24,316 root         DEBUG    Done, found 13323 files
2019-05-10 11:22:24,316 root         DEBUG    Generating list of files in layer '32c0828556216ffddd689f3e03679c6d545aaef95f873823ae9a26aac589772c'...
2019-05-10 11:22:24,637 root         DEBUG    Done, found 8035 files
2019-05-10 11:22:24,639 root         INFO     Squashing file '/tmp/docker-squash-7mnr12ep/old/6e861398b55e8fbdb1e048b4922b39c03aec0a93e7c2b578160ff755b6a6c39a/layer.tar'...
2019-05-10 11:22:24,639 root         DEBUG    Searching for marker files in '/tmp/docker-squash-7mnr12ep/old/6e861398b55e8fbdb1e048b4922b39c03aec0a93e7c2b578160ff755b6a6c39a/layer.tar' archive...
2019-05-10 11:22:24,639 root         DEBUG    Found 'etc/yum.repos.d/.wh.content_sets_odcs.repo' marker file
2019-05-10 11:22:24,639 root         DEBUG    Done, found 1 files
2019-05-10 11:22:24,639 root         DEBUG    Searching for symbolic links in '/tmp/docker-squash-7mnr12ep/old/6e861398b55e8fbdb1e048b4922b39c03aec0a93e7c2b578160ff755b6a6c39a/layer.tar' archive...
2019-05-10 11:22:24,639 root         DEBUG    Done, found 0 files
2019-05-10 11:22:24,639 root         DEBUG    Skipping '/etc/yum.repos.d/.wh.content_sets_odcs.repo' marker file, at the end of squashing we'll see if it's necessary to add it back
2019-05-10 11:22:24,639 root         INFO     Squashing file '/tmp/docker-squash-7mnr12ep/old/522520d221db657d8c4082f00600e58816984e9d890b3df059a55cbe2937f84d/layer.tar'...
2019-05-10 11:22:24,641 root         DEBUG    Searching for marker files in '/tmp/docker-squash-7mnr12ep/old/522520d221db657d8c4082f00600e58816984e9d890b3df059a55cbe2937f84d/layer.tar' archive...
2019-05-10 11:22:24,641 root         DEBUG    Found 'var/cache/.wh.yum' marker file
2019-05-10 11:22:24,641 root         DEBUG    Done, found 1 files
2019-05-10 11:22:24,641 root         DEBUG    Searching for symbolic links in '/tmp/docker-squash-7mnr12ep/old/522520d221db657d8c4082f00600e58816984e9d890b3df059a55cbe2937f84d/layer.tar' archive...
2019-05-10 11:22:24,641 root         DEBUG    Done, found 0 files
2019-05-10 11:22:24,641 root         DEBUG    Skipping '/var/cache/.wh.yum' marker file, at the end of squashing we'll see if it's necessary to add it back
2019-05-10 11:22:24,657 root         INFO     Squashing file '/tmp/docker-squash-7mnr12ep/old/3799407b3a6e461557350e4913b7929525d0ae1c172e1f3f20906232a82ee929/layer.tar'...
2019-05-10 11:22:24,663 root         DEBUG    Searching for marker files in '/tmp/docker-squash-7mnr12ep/old/3799407b3a6e461557350e4913b7929525d0ae1c172e1f3f20906232a82ee929/layer.tar' archive...
2019-05-10 11:22:24,663 root         DEBUG    Found 'var/cache/yum/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/.wh..wh..opq' marker file
2019-05-10 11:22:24,663 root         DEBUG    Found 'var/cache/yum/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/.wh..wh..opq' marker file
2019-05-10 11:22:24,663 root         DEBUG    Found 'var/cache/yum/x86_64/7Server/rhel-7-server-extras-rpms/.wh..wh..opq' marker file
2019-05-10 11:22:24,663 root         DEBUG    Found 'var/cache/yum/x86_64/7Server/rhel-7-server-ose-3.11-rpms/.wh..wh..opq' marker file
2019-05-10 11:22:24,664 root         DEBUG    Found 'var/cache/yum/x86_64/7Server/rhel-7-server-rpms/.wh.c724cc42620ebf088b7fa5008751bc4fdd02d674-primary.sqlite.bz2' marker file
2019-05-10 11:22:24,664 root         DEBUG    Found 'var/cache/yum/x86_64/7Server/rhel-7-server-rpms/.wh.e71e9e80d3b89c4e0ab80b0ce8bc0521e01771d6-updateinfo.xml.gz' marker file
2019-05-10 11:22:24,664 root         DEBUG    Found 'var/lib/yum/repos/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/.wh..wh..opq' marker file
2019-05-10 11:22:24,664 root         DEBUG    Found 'var/lib/yum/repos/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/.wh..wh..opq' marker file
2019-05-10 11:22:24,664 root         DEBUG    Found 'var/lib/yum/repos/x86_64/7Server/rhel-7-server-extras-rpms/.wh..wh..opq' marker file
2019-05-10 11:22:24,664 root         DEBUG    Found 'var/lib/yum/repos/x86_64/7Server/rhel-7-server-ose-3.11-rpms/.wh..wh..opq' marker file
2019-05-10 11:22:24,664 root         DEBUG    Done, found 10 files
2019-05-10 11:22:24,664 root         DEBUG    Searching for symbolic links in '/tmp/docker-squash-7mnr12ep/old/3799407b3a6e461557350e4913b7929525d0ae1c172e1f3f20906232a82ee929/layer.tar' archive...
2019-05-10 11:22:24,664 root         DEBUG    Done, found 0 files
2019-05-10 11:22:24,664 root         DEBUG    Skipping '/run' file because it's older than file already added to the archive
2019-05-10 11:22:24,664 root         DEBUG    Skipping '/run/rhsm' file because it's older than file already added to the archive
2019-05-10 11:22:24,664 root         DEBUG    Skipping '/var' file because it's older than file already added to the archive
2019-05-10 11:22:24,664 root         DEBUG    Skipping '/var/cache' file because it's older than file already added to the archive
2019-05-10 11:22:24,664 root         DEBUG    Skipping '/var/cache/yum' file because it's on the list to skip files
2019-05-10 11:22:24,664 root         DEBUG    Skipping '/var/cache/yum/x86_64' file because it's on the list to skip files
2019-05-10 11:22:24,664 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server' file because it's on the list to skip files
2019-05-10 11:22:24,664 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-2.7-rpms' file because it's on the list to skip files
2019-05-10 11:22:24,665 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/.wh..wh..opq' marker file, at the end of squashing we'll see if it's necessary to add it back
2019-05-10 11:22:24,665 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/64e7ecaaef5aeb3a4eec3d61c417e57979b061f034e1d29ecbd3d5a73adafa85-other.sqlite.bz2' file because it's on the list to skip files
2019-05-10 11:22:24,665 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/6dabfa83a766047f7126fb74742bd1ef885c814977ec5852e15fa81d6ccabc6d-filelists.sqlite.bz2' file because it's on the list to skip files
2019-05-10 11:22:24,665 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/8aab89a3983925c945028851b743796cfd47675f8040f4f25e44e053237849a4-primary.sqlite.bz2' file because it's on the list to skip files
2019-05-10 11:22:24,665 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/a27718cc28ec6d71432e0ef3e6da544b7f9d93f6bb7d0a55aacd592d03144b70-comps.xml' file because it's on the list to skip files
2019-05-10 11:22:24,665 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/cachecookie' file because it's on the list to skip files
2019-05-10 11:22:24,665 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/d5457e7264098e8dd8dca9a14572671bdde722aa3cf9af07095c981c2cf61244-updateinfo.xml.gz' file because it's on the list to skip files
2019-05-10 11:22:24,665 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/gen' file because it's on the list to skip files
2019-05-10 11:22:24,665 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/gen/filelists_db.sqlite' file because it's on the list to skip files
2019-05-10 11:22:24,665 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/gen/other_db.sqlite' file because it's on the list to skip files
2019-05-10 11:22:24,665 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/gen/primary_db.sqlite' file because it's on the list to skip files
2019-05-10 11:22:24,665 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/gen/updateinfo.xml' file because it's on the list to skip files
2019-05-10 11:22:24,665 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/packages' file because it's on the list to skip files
2019-05-10 11:22:24,665 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/productid' file because it's on the list to skip files
2019-05-10 11:22:24,665 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/repomd.xml' file because it's on the list to skip files
2019-05-10 11:22:24,665 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms' file because it's on the list to skip files
2019-05-10 11:22:24,665 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/.wh..wh..opq' marker file, at the end of squashing we'll see if it's necessary to add it back
2019-05-10 11:22:24,665 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/391a121755e190f402de34f5a727d550b44acb56fb11d71859de3200511cb41d-filelists.sqlite.bz2' file because it's on the list to skip files
2019-05-10 11:22:24,665 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/5c8f948a349937d373f20f7f90d4fb31e4dd4db7fde49ffa9730a45990a152e8-primary.sqlite.bz2' file because it's on the list to skip files
2019-05-10 11:22:24,665 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/7429598fd90c0621e30258427e206b6f33978c9bf33415d628a0df410cbcec16-updateinfo.xml.gz' file because it's on the list to skip files
2019-05-10 11:22:24,665 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/8e99a047bfe969a22320c459304968a77c9a66bdd1784a535ce62e7ed1853cec-other.sqlite.bz2' file because it's on the list to skip files
2019-05-10 11:22:24,666 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/96400d633d6502ada5217d26eb9765dc61a3f65fb946ac79c8c92b7af9857def' file because it's on the list to skip files
2019-05-10 11:22:24,666 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/cachecookie' file because it's on the list to skip files
2019-05-10 11:22:24,666 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/cb329cadcd7701d5b4f752e6ef8fbe7fe2bbc3a74b971d47c3ab3682c5e67121-comps.xml' file because it's on the list to skip files
2019-05-10 11:22:24,666 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/gen' file because it's on the list to skip files
2019-05-10 11:22:24,666 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/gen/filelists_db.sqlite' file because it's on the list to skip files
2019-05-10 11:22:24,666 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/gen/other_db.sqlite' file because it's on the list to skip files
2019-05-10 11:22:24,666 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/gen/primary_db.sqlite' file because it's on the list to skip files
2019-05-10 11:22:24,666 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/gen/updateinfo.xml' file because it's on the list to skip files
2019-05-10 11:22:24,666 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/packages' file because it's on the list to skip files
2019-05-10 11:22:24,666 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/repomd.xml' file because it's on the list to skip files
2019-05-10 11:22:24,666 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-extras-rpms' file because it's on the list to skip files
2019-05-10 11:22:24,666 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-extras-rpms/.wh..wh..opq' marker file, at the end of squashing we'll see if it's necessary to add it back
2019-05-10 11:22:24,666 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-extras-rpms/19bfab1cdd3807fc6744dd632388c6b909119dbe-other.sqlite.bz2' file because it's on the list to skip files
2019-05-10 11:22:24,666 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-extras-rpms/7a747e6dc73c3ccef57c839995d90b6ef4c76092-comps.xml' file because it's on the list to skip files
2019-05-10 11:22:24,666 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-extras-rpms/7a84c46396f06164afd4d67fcbd6603784e0d321-updateinfo.xml.gz' file because it's on the list to skip files
2019-05-10 11:22:24,666 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-extras-rpms/9d5116dbeb0ca7f5cb163f379101ab898dab9a84-primary.sqlite.bz2' file because it's on the list to skip files
2019-05-10 11:22:24,666 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-extras-rpms/cachecookie' file because it's on the list to skip files
2019-05-10 11:22:24,666 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-extras-rpms/f37e7707209fcc50b5e53127f9aff8d2a2aacc3e-filelists.sqlite.bz2' file because it's on the list to skip files
2019-05-10 11:22:24,666 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-extras-rpms/gen' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-extras-rpms/gen/filelists_db.sqlite' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-extras-rpms/gen/other_db.sqlite' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-extras-rpms/gen/primary_db.sqlite' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-extras-rpms/gen/updateinfo.xml' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-extras-rpms/packages' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-extras-rpms/productid' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-extras-rpms/repomd.xml' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ose-3.11-rpms' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ose-3.11-rpms/.wh..wh..opq' marker file, at the end of squashing we'll see if it's necessary to add it back
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ose-3.11-rpms/4642c3d3263ea1ada6f620f8e5f5145bea34d0fee0359c7c9b3fa97da6e4c150-primary.sqlite.bz2' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ose-3.11-rpms/7c39a5e489f978f1e3a58dd6a203fdd5bd9cf1fed9ad83ee032378b300b97802-other.sqlite.bz2' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ose-3.11-rpms/7fdd79fc84dfecece407d1bfa084e726792d4cac683c39c742456c656638acab-updateinfo.xml.gz' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ose-3.11-rpms/a27718cc28ec6d71432e0ef3e6da544b7f9d93f6bb7d0a55aacd592d03144b70-comps.xml' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ose-3.11-rpms/c512cb247eb4e8be866a94c181936e0245c706cd9b8f88b4ff8ffe0aa02f685a-filelists.sqlite.bz2' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ose-3.11-rpms/cachecookie' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ose-3.11-rpms/gen' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ose-3.11-rpms/gen/filelists_db.sqlite' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ose-3.11-rpms/gen/other_db.sqlite' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ose-3.11-rpms/gen/primary_db.sqlite' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ose-3.11-rpms/gen/updateinfo.xml' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ose-3.11-rpms/packages' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ose-3.11-rpms/productid' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-ose-3.11-rpms/repomd.xml' file because it's on the list to skip files
2019-05-10 11:22:24,667 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-rpms' file because it's on the list to skip files
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-rpms/15afe92629733be9990852443a362b63e6e82530-other.sqlite.bz2' file because it's on the list to skip files
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-rpms/258b1d2a0d102c73682cfd982e15d905f00cc8f9-comps.xml' file because it's on the list to skip files
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-rpms/5247afb742076b3f5887ccbd5cf9589d511ba7e4-primary.sqlite.bz2' file because it's on the list to skip files
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-rpms/9ceb3c302b8fe3180d23a36a42a33fb02603ce74-filelists.sqlite.bz2' file because it's on the list to skip files
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-rpms/a87fa6f8af8c3e5650c6353f8cbcc9b4b8e32c9c-updateinfo.xml.gz' file because it's on the list to skip files
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-rpms/.wh.c724cc42620ebf088b7fa5008751bc4fdd02d674-primary.sqlite.bz2' marker file, at the end of squashing we'll see if it's necessary to add it back
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-rpms/cachecookie' file because it's on the list to skip files
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-rpms/.wh.e71e9e80d3b89c4e0ab80b0ce8bc0521e01771d6-updateinfo.xml.gz' marker file, at the end of squashing we'll see if it's necessary to add it back
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-rpms/gen' file because it's on the list to skip files
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-rpms/gen/filelists_db.sqlite' file because it's on the list to skip files
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-rpms/gen/other_db.sqlite' file because it's on the list to skip files
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-rpms/gen/primary_db.sqlite' file because it's on the list to skip files
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-rpms/gen/updateinfo.xml' file because it's on the list to skip files
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-rpms/productid' file because it's on the list to skip files
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/rhel-7-server-rpms/repomd.xml' file because it's on the list to skip files
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/cache/yum/x86_64/7Server/timedhosts' file because it's on the list to skip files
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/lib' file because it's older than file already added to the archive
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/lib/rpm' file because it's older than file already added to the archive
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/lib/rpm/.dbenv.lock' file because it's older than file already added to the archive
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/lib/rpm/.rpm.lock' file because it's older than file already added to the archive
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/lib/rpm/Basenames' file because it's older than file already added to the archive
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/lib/rpm/Conflictname' file because it's older than file already added to the archive
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/lib/rpm/Dirnames' file because it's older than file already added to the archive
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/lib/rpm/Group' file because it's older than file already added to the archive
2019-05-10 11:22:24,668 root         DEBUG    Skipping '/var/lib/rpm/Installtid' file because it's older than file already added to the archive
2019-05-10 11:22:24,669 root         DEBUG    Skipping '/var/lib/rpm/Name' file because it's older than file already added to the archive
2019-05-10 11:22:24,669 root         DEBUG    Skipping '/var/lib/rpm/Obsoletename' file because it's older than file already added to the archive
2019-05-10 11:22:24,669 root         DEBUG    Skipping '/var/lib/rpm/Packages' file because it's older than file already added to the archive
2019-05-10 11:22:24,669 root         DEBUG    Skipping '/var/lib/rpm/Providename' file because it's older than file already added to the archive
2019-05-10 11:22:24,669 root         DEBUG    Skipping '/var/lib/rpm/Requirename' file because it's older than file already added to the archive
2019-05-10 11:22:24,669 root         DEBUG    Skipping '/var/lib/rpm/Sha1header' file because it's older than file already added to the archive
2019-05-10 11:22:24,669 root         DEBUG    Skipping '/var/lib/rpm/Sigmd5' file because it's older than file already added to the archive
2019-05-10 11:22:24,669 root         DEBUG    Skipping '/var/lib/rpm/Triggername' file because it's older than file already added to the archive
2019-05-10 11:22:24,669 root         DEBUG    Skipping '/var/lib/rpm/__db.001' file because it's older than file already added to the archive
2019-05-10 11:22:24,669 root         DEBUG    Skipping '/var/lib/rpm/__db.002' file because it's older than file already added to the archive
2019-05-10 11:22:24,669 root         DEBUG    Skipping '/var/lib/rpm/__db.003' file because it's older than file already added to the archive
2019-05-10 11:22:24,669 root         DEBUG    Skipping '/var/lib/yum/repos/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/.wh..wh..opq' marker file, at the end of squashing we'll see if it's necessary to add it back
2019-05-10 11:22:24,669 root         DEBUG    Skipping '/var/lib/yum/repos/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/.wh..wh..opq' marker file, at the end of squashing we'll see if it's necessary to add it back
2019-05-10 11:22:24,670 root         DEBUG    Skipping '/var/lib/yum/repos/x86_64/7Server/rhel-7-server-extras-rpms/.wh..wh..opq' marker file, at the end of squashing we'll see if it's necessary to add it back
2019-05-10 11:22:24,670 root         DEBUG    Skipping '/var/lib/yum/repos/x86_64/7Server/rhel-7-server-ose-3.11-rpms/.wh..wh..opq' marker file, at the end of squashing we'll see if it's necessary to add it back
2019-05-10 11:22:24,670 root         DEBUG    Skipping '/var/log' file because it's older than file already added to the archive
2019-05-10 11:22:24,670 root         DEBUG    Skipping '/var/log/rhsm' file because it's older than file already added to the archive
2019-05-10 11:22:24,670 root         DEBUG    Skipping '/var/log/rhsm/rhsm.log' file because it's older than file already added to the archive
2019-05-10 11:22:24,670 root         DEBUG    Skipping '/var/log/yum.log' file because it's older than file already added to the archive
2019-05-10 11:22:24,670 root         INFO     Squashing file '/tmp/docker-squash-7mnr12ep/old/7ea2b003ba26e1b0e22335efbf55ffe3f19a2300a72e12f2e4ed32e5d70c87d1/layer.tar'...
2019-05-10 11:22:24,670 root         DEBUG    Searching for marker files in '/tmp/docker-squash-7mnr12ep/old/7ea2b003ba26e1b0e22335efbf55ffe3f19a2300a72e12f2e4ed32e5d70c87d1/layer.tar' archive...
2019-05-10 11:22:24,671 root         DEBUG    Done, found 0 files
2019-05-10 11:22:24,671 root         DEBUG    Searching for symbolic links in '/tmp/docker-squash-7mnr12ep/old/7ea2b003ba26e1b0e22335efbf55ffe3f19a2300a72e12f2e4ed32e5d70c87d1/layer.tar' archive...
2019-05-10 11:22:24,671 root         DEBUG    Done, found 0 files
2019-05-10 11:22:24,671 root         DEBUG    Skipping '/etc' file because it's older than file already added to the archive
2019-05-10 11:22:24,671 root         DEBUG    Skipping '/etc/yum.repos.d' file because it's older than file already added to the archive
2019-05-10 11:22:24,671 root         DEBUG    Skipping '/etc/yum.repos.d/content_sets_odcs.repo' file because it's on the list to skip files
2019-05-10 11:22:24,671 root         DEBUG    Marker files to add: ['etc/yum.repos.d/.wh.content_sets_odcs.repo', 'var/cache/.wh.yum', 'var/cache/yum/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/.wh..wh..opq', 'var/cache/yum/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/.wh..wh..opq', 'var/cache/yum/x86_64/7Server/rhel-7-server-extras-rpms/.wh..wh..opq', 'var/cache/yum/x86_64/7Server/rhel-7-server-ose-3.11-rpms/.wh..wh..opq', 'var/cache/yum/x86_64/7Server/rhel-7-server-rpms/.wh.c724cc42620ebf088b7fa5008751bc4fdd02d674-primary.sqlite.bz2', 'var/cache/yum/x86_64/7Server/rhel-7-server-rpms/.wh.e71e9e80d3b89c4e0ab80b0ce8bc0521e01771d6-updateinfo.xml.gz', 'var/lib/yum/repos/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/.wh..wh..opq', 'var/lib/yum/repos/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/.wh..wh..opq', 'var/lib/yum/repos/x86_64/7Server/rhel-7-server-extras-rpms/.wh..wh..opq', 'var/lib/yum/repos/x86_64/7Server/rhel-7-server-ose-3.11-rpms/.wh..wh..opq']
2019-05-10 11:22:24,671 root         DEBUG    Skipping 'etc/yum.repos.d/.wh.content_sets_odcs.repo' marker file...
2019-05-10 11:22:24,672 root         DEBUG    Adding 'var/cache/.wh.yum' marker file back...
2019-05-10 11:22:24,672 root         DEBUG    Skipping 'var/cache/yum/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/.wh..wh..opq' marker file...
2019-05-10 11:22:24,673 root         DEBUG    Skipping 'var/cache/yum/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/.wh..wh..opq' marker file...
2019-05-10 11:22:24,673 root         DEBUG    Skipping 'var/cache/yum/x86_64/7Server/rhel-7-server-extras-rpms/.wh..wh..opq' marker file...
2019-05-10 11:22:24,674 root         DEBUG    Skipping 'var/cache/yum/x86_64/7Server/rhel-7-server-ose-3.11-rpms/.wh..wh..opq' marker file...
2019-05-10 11:22:24,674 root         DEBUG    Adding 'var/cache/yum/x86_64/7Server/rhel-7-server-rpms/.wh.c724cc42620ebf088b7fa5008751bc4fdd02d674-primary.sqlite.bz2' marker file back...
2019-05-10 11:22:24,675 root         DEBUG    Adding 'var/cache/yum/x86_64/7Server/rhel-7-server-rpms/.wh.e71e9e80d3b89c4e0ab80b0ce8bc0521e01771d6-updateinfo.xml.gz' marker file back...
2019-05-10 11:22:24,675 root         DEBUG    Skipping 'var/lib/yum/repos/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/.wh..wh..opq' marker file...
2019-05-10 11:22:24,676 root         DEBUG    Skipping 'var/lib/yum/repos/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/.wh..wh..opq' marker file...
2019-05-10 11:22:24,677 root         DEBUG    Skipping 'var/lib/yum/repos/x86_64/7Server/rhel-7-server-extras-rpms/.wh..wh..opq' marker file...
2019-05-10 11:22:24,677 root         DEBUG    Skipping 'var/lib/yum/repos/x86_64/7Server/rhel-7-server-ose-3.11-rpms/.wh..wh..opq' marker file...
2019-05-10 11:22:24,677 root         INFO     Squashing finished!
2019-05-10 11:22:27,449 root         DEBUG    Moving unmodified layer 'd9f9a2145b0fb9eab484b597854872beb55025cc1ce86c0f5932afa95c99a66e'...
2019-05-10 11:22:27,449 root         DEBUG    Moving unmodified layer '4f6836b44ebd4c3e497852885255177564139738d3c56aa8ef4647266638f236'...
2019-05-10 11:22:27,449 root         DEBUG    Moving unmodified layer 'd04653cb4068dbb022eba8274429de8193bea89a926af5a78fb9eb78cf9b363c'...
2019-05-10 11:22:27,449 root         DEBUG    Moving unmodified layer '32c0828556216ffddd689f3e03679c6d545aaef95f873823ae9a26aac589772c'...
2019-05-10 11:22:27,449 root         DEBUG    Removing from disk already squashed layers...
2019-05-10 11:22:27,505 root         INFO     Original image size: 2101.49 MB
2019-05-10 11:22:27,505 root         INFO     Squashed image size: 1188.61 MB
2019-05-10 11:22:27,505 root         INFO     Image size decreased by 43.44 %
2019-05-10 11:22:27,505 root         INFO     New squashed image ID is ed78f81223e24c07a83a35c510aaaa657e0542baab7bf36cdc3e8210b77a6443
2019-05-10 11:22:27,505 root         DEBUG    Generating tar archive for the squashed image...
2019-05-10 11:22:28,118 root         DEBUG    Archive generated
2019-05-10 11:22:28,119 root         DEBUG    Loading squashed image...
2019-05-10 11:22:29,275 urllib3.connectionpool DEBUG    http://localhost:None "POST /v1.26/images/load HTTP/1.1" 200 None
2019-05-10 11:22:29,275 root         DEBUG    Image loaded!
2019-05-10 11:22:29,361 root         INFO     Image registered in Docker daemon as test-makecache:squashed
2019-05-10 11:22:29,361 root         DEBUG    Cleaning up /tmp/docker-squash-7mnr12ep temporary directory
2019-05-10 11:22:29,432 root         INFO     Done
goldmann commented 5 years ago

Found it finally! This looks like a squashing bug.

In our image we have a line like this near the end of Dockerfile:

RUN yum clean all && [ ! -d /var/cache/yum ] || rm -rf /var/cache/yum

It does clean the yum metadata and additionally it remove the yum cache directory if it exists. Such approach is perfectly fine and should be handled properly.

In case of the openshift3/apb-base:v3.11 image, the installation of package is done there, but the yum cache directory is not removed. Here is the specific line of Dockerfile used to build this image:

RUN yum -y install atomic-openshift-clients python-openshift ansible ansible-kubernetes-modules ansible-asb-modules apb-base-scripts git \
  && yum clean all

This means that the openshift3/apb-base:v3.11 will still contain the /var/cache/yum directory. Which is fine, there is no requirement to remove that directory, although this is a good practice.

$ docker run -it --rm --entrypoint "bash" openshift3/apb-base:v3.11 -c "ls -hall /var/cache/yum"
total 0
drwxr-xr-x. 1 root root 20 May  7 17:19 .
drwxr-xr-x. 1 root root 33 Apr  9 05:57 ..
drwxr-xr-x. 1 root root 21 May  7 17:19 x86_64

So, the base image contains the directory and we are removing it our image. The end result should be that the /var/cache/yum should be a marker file inside of the tar archive that would actually hide this directory in the resulting image.

We can see it happening in the squash logs:

2019-05-10 11:22:24,672 root         DEBUG    Adding 'var/cache/.wh.yum' marker file back...

Unfortunately a few lines later we can see:

2019-05-10 11:22:24,674 root         DEBUG    Adding 'var/cache/yum/x86_64/7Server/rhel-7-server-rpms/.wh.c724cc42620ebf088b7fa5008751bc4fdd02d674-primary.sqlite.bz2' marker file back...
2019-05-10 11:22:24,675 root         DEBUG    Adding 'var/cache/yum/x86_64/7Server/rhel-7-server-rpms/.wh.e71e9e80d3b89c4e0ab80b0ce8bc0521e01771d6-updateinfo.xml.gz' marker file back...

Which means that we are adding additional marker files under the already marked directory. I suspect this is the root cause of this issue.

A reproducer can be found here:

FROM openshift3/apb-base:v3.11
USER root
COPY repos/content_sets_odcs.repo /etc/yum.repos.d/
RUN yum makecache
RUN rm -rf /var/cache/yum
goldmann commented 5 years ago

To reproduce it:

$ docker build -t image:latest .
$ docker-squash -v -f 4 -t image:squashed image:latest

The image:squashed image will not be found in Docker afterwards.

goldmann commented 5 years ago

Here is the tar content of the squashed layer:

$ tar tf f4055d9ee2a4b1e8796eb4d07b0daf282a81b923f9f5882a43166eec6acb7671/layer.tar
var/
var/cache/
run/
run/rhsm/
var/lib/
var/lib/rpm/
var/lib/rpm/.dbenv.lock
var/lib/rpm/.rpm.lock
var/lib/rpm/Basenames
var/lib/rpm/Conflictname
var/lib/rpm/Dirnames
var/lib/rpm/Group
var/lib/rpm/Installtid
var/lib/rpm/Name
var/lib/rpm/Obsoletename
var/lib/rpm/Packages
var/lib/rpm/Providename
var/lib/rpm/Requirename
var/lib/rpm/Sha1header
var/lib/rpm/Sigmd5
var/lib/rpm/Triggername
var/lib/rpm/__db.001
var/lib/rpm/__db.002
var/lib/rpm/__db.003
var/lib/yum/
var/lib/yum/repos/
var/lib/yum/repos/x86_64/
var/lib/yum/repos/x86_64/7Server/
var/lib/yum/repos/x86_64/7Server/rhel-7-server-ansible-2.7-rpms/
var/lib/yum/repos/x86_64/7Server/rhel-7-server-ansible-runner-1.1-rpms/
var/lib/yum/repos/x86_64/7Server/rhel-7-server-extras-rpms/
var/lib/yum/repos/x86_64/7Server/rhel-7-server-ose-3.11-rpms/
var/log/
var/log/rhsm/
var/log/rhsm/rhsm.log
var/log/yum.log
etc/
etc/yum.repos.d/
etc/yum.repos.d/content_sets_odcs.repo
var/cache/.wh.yum
var/cache/yum/x86_64/7Server/rhel-7-server-rpms/.wh.c724cc42620ebf088b7fa5008751bc4fdd02d674-primary.sqlite.bz2
var/cache/yum/x86_64/7Server/rhel-7-server-rpms/.wh.e71e9e80d3b89c4e0ab80b0ce8bc0521e01771d6-updateinfo.xml.gz

Last 3 lines show these 3 marker files I mentioned above. Last two files are NOT expected to be there.

goldmann commented 5 years ago

I was able to write a test for this issue, working on a fix now.

goldmann commented 5 years ago

I have a fix locally, but it's a bit ugly. I'll work next week to polish it.

spolti commented 5 years ago

@goldmann great news, looking forward for the fix. :)

Thanks.

goldmann commented 5 years ago

Proposed fix is available in #183.

spolti commented 5 years ago

Great, any idea about when will this be available on cekit3?

goldmann commented 5 years ago

Releases of these two projects are not tied together. After releasing 1.0.8 you need to upgrade CEKit dependencies. Upgrade process depends on the way you installed them in the first place. RPM will be available later, but upgrading using pip should be possible immediately after release.

spolti commented 5 years ago

Sounds good, thanks.