docker.cleanup.image of Docker driver doesn't work as expected.

[weslleycamilo]

Nomad version

0.7.1

Operating system and Environment details

Ubuntu 16.10

Issue

Docker cleanup doesn't work as it is mentioned on the documentation https://www.nomadproject.io/docs/drivers/docker.html

It says it is default to true to cleanup the images but it doesn't clean even if I set it to true.

Reproduction steps

weslley@br:/home/weslley# docker images
REPOSITORY                                TAG                 IMAGE ID            CREATED             SIZE
xxxxxxxx/pontoweb                           latest              1d0b579f7e43        3 minutes ago       884MB
xxxxxxx/pontoweb                           <none>              97d18d340fbe        3 hours ago         884MB
xxxxxxx/pontoweb                           <none>              54796fcb36bf        2 days ago          884MB
xxxxxxx/pontoweb                           <none>              35588652e38f        3 days ago          884MB
xxxxxx/pontoweb                           <none>              480ce14b76ce        6 days ago          884MB
xxxxxxx/pontoweb                           <none>              cb0a3bf595f1        6 days ago          884MB

I did set it to true.

 options {
      docker.cleanup.image = true
    }

and I still got the same images.

Nomad Server logs (if appropriate)

CGroup: /system.slice/nomad-server.service
└─5982 /usr/local/bin/nomad agent --config server.hcl

Nov 16 20:02:09 runner1 nomad[5982]: Desired Changes for "aplicacao": (place 2) (inplace 0) (destructive 0) (stop 0) (migrate 0) (ignore 0) (canary 0)
Nov 16 20:02:09 runner1 nomad[5982]:     2017/11/16 20:02:09.303799 [DEBUG] http: Request /v1/jobs (6.083749ms)
Nov 16 20:02:09 runner1 nomad[5982]:     2017/11/16 20:02:09.305198 [DEBUG] http: Request /v1/evaluation/493660bb-7916-a212-0e23-d5883d51efe2 (138.905µs)
Nov 16 20:02:09 runner1 nomad[5982]:     2017/11/16 20:02:09.305404 [DEBUG] worker: submitted plan for evaluation 493660bb-7916-a212-0e23-d5883d51efe2
Nov 16 20:02:09 runner1 nomad[5982]:     2017/11/16 20:02:09.305429 [DEBUG] sched: <Eval "493660bb-7916-a212-0e23-d5883d51efe2" JobID: "pontoweb" Namespace: "default">: setting status to complete
Nov 16 20:02:09 runner1 nomad[5982]:     2017/11/16 20:02:09.306519 [DEBUG] worker: updated evaluation <Eval "493660bb-7916-a212-0e23-d5883d51efe2" JobID: "pontoweb" Namespace: "default">
Nov 16 20:02:09 runner1 nomad[5982]:     2017/11/16 20:02:09.306574 [DEBUG] worker: ack for evaluation 493660bb-7916-a212-0e23-d5883d51efe2
Nov 16 20:02:09 runner1 nomad[5982]:     2017/11/16 20:02:09.307657 [DEBUG] http: Request /v1/evaluation/493660bb-7916-a212-0e23-d5883d51efe2/allocations (154.645µs)
Nov 16 20:02:10 runner1 nomad[5982]:     2017/11/16 20:02:10.309594 [DEBUG] http: Request /v1/evaluation/493660bb-7916-a212-0e23-d5883d51efe2 (386.017µs)
Nov 16 20:02:10 runner1 nomad[5982]:     2017/11/16 20:02:10.311354 [DEBUG] http: Request /v1/evaluation/493660bb-7916-a212-0e23-d5883d51efe2/allocations (457.034µs)

Nomad Client logs (if appropriate)

           └─5136 /usr/local/bin/nomad executor {"LogFile":"/etc/nomad.d/alloc/677ee716-1a7f-7cc8-3073-2cc057f1fcf8/pontoweb/executor.out","LogLevel":"DEBUG"}

Nov 16 18:02:10 bro5 nomad[3287]:     2017/11/16 18:02:10.249072 [INFO] driver.docker: created container d56a913452b95437d6ac234ce28a040c55ec08cd0469595b029373350e4bc77f
Nov 16 18:02:10 bro5 nomad[3287]:     2017/11/16 18:02:10.374057 [INFO] driver.docker: started container d56a913452b95437d6ac234ce28a040c55ec08cd0469595b029373350e4bc77f
Nov 16 18:02:10 bro5 nomad[3287]:     2017/11/16 18:02:10.386020 [WARN] client: error fetching stats of task pontoweb: stats collection hasn't started yet
Nov 16 18:02:10 bro5 nomad[3287]:     2017/11/16 18:02:10.412015 [WARN] client.alloc_watcher: failed to lookup Consul registrations for allocation "677ee716-1a7f-7cc8-3073-2cc057f1fcf8": Get http://127.0.0.1:8500/v1/agent/services:
Nov 16 18:02:10 bro5 nomad[3287]:     2017/11/16 18:02:10.690785 [DEBUG] client: updated allocations at index 12230 (total 7) (pulled 4) (filtered 3)
Nov 16 18:02:10 bro5 nomad[3287]:     2017/11/16 18:02:10.690956 [DEBUG] client: allocs: (added 0) (removed 0) (updated 4) (ignore 3)
Nov 16 18:02:10 bro5 nomad[3287]:     2017/11/16 18:02:10.691531 [DEBUG] client: dropping update to terminal alloc '27c255a0-2b43-6cf0-4620-74b13c221fe9'
Nov 16 18:02:10 bro5 nomad[3287]:     2017/11/16 18:02:10.691554 [DEBUG] client: dropping update to terminal alloc '355d152b-132f-7c8e-fb1b-7aa8a7256670'
Nov 16 18:02:10 bro5 nomad[3287]:     2017/11/16 18:02:10.691563 [DEBUG] client: dropping update to terminal alloc 'd11aa41c-4353-7d61-e2e1-8f21a9126517'
Nov 16 18:02:10 bro5 nomad[3287]:     2017/11/16 18:02:10.691572 [DEBUG] client: dropping update to terminal alloc 'eb9a3e2e-c296-4f23-6c09-fa9076011903'

[schmichael]

I tested locally and images were cleaned up after the default 3 minute delay.

Going to close for now but if you can provide client logs that show driver.docker not cleaning it up feel free to reopen! Server logs shouldn't be necessary.

The expected logs would be something like:

# When the example job starts:
2017/11/16 17:14:24.660544 [DEBUG] driver.docker: image "redis:3.2" (sha256:d3f696a9f23068ee7801fa2216721b6b29eb1680ed60a6dceb37c09d868ce388) reference count incremented: 1
# ...when it stops:
2017/11/16 17:14:36.757296 [DEBUG] driver.docker: image id "sha256:d3f696a9f23068ee7801fa2216721b6b29eb1680ed60a6dceb37c09d868ce388" reference count decremented: 0
# ...3 minutes later it is removed:
2017/11/16 17:17:36.895441 [DEBUG] driver.docker: cleanup removed downloaded image: "sha256:d3f696a9f23068ee7801fa2216721b6b29eb1680ed60a6dceb37c09d868ce388"

[weslleycamilo]

here is the log.

output.log

I've two nomad clients and one of them is cleaning the old images and I can see the logs you mentioned above, but on this one I can't see the removed report.

[dadgar]

@weslleycamilo Is it specific to when your restart Nomad/Docker?

[weslleycamilo]

@dadgar

I am not restarting them, just the job as my testing with Nomad.

So I've been restarting the job, stopped it , started it and so on.

[github-actions]

I'm going to lock this issue because it has been closed for 120 days ⏳. This helps our maintainers find and focus on the active issues.
If you have found a problem that seems similar to this, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.