These comments were added to enforce using the correct import path for
our packages ("github.com/docker/docker", not "github.com/moby/moby").
However, when working in go module mode (not GOPATH / vendor), they have
no effect, so their impact is limited.
Remove these imports in preparation of migrating our code to become an
actual go module.
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
This was introduced in c817ea2159, but overlooked
that the logs were now produced before (for POST requests) the form-data was
handled and added to the "fields" variable.
This patch changes the logic to wrap the handler and make sure logs are
created before, and after the handler is called (the "form-data" is always
added before the handler is called).
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
commit 1701bce9e0 updated the debug logs
to use structured logs, and to include more information in the logs, such
as the form-data used and the status-code, and combining them into a
single log.
However, for the status-code, we need to wait for the handler to do its
thing and (ahum) this was staring me right in the face, and crossed my
mind, but then I didn't act on it; the handler may take some time to
run, and produce logs, which now means that our nice "handling request"
log will be logged _after_ the request, which is obviously confusing.
This patch splits the log into two;
- a log entry when starting to handle the request
- a log entry if a non-200 status is returned (assuming 200 status
codes are less interesting to log).
Before this patch:
DEBU[2024-10-23T15:23:31.677184128Z] handling HEAD request method=HEAD module=api request-url=/_ping spanID=8180b03fa17f9783 status=200 traceID=a5dfa9b86445467889274145ad31bb9a vars="map[]"
DEBU[2024-10-23T15:23:31.712833045Z] resolving host=registry-1.docker.io spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4
DEBU[2024-10-23T15:23:31.712883670Z] do request host=registry-1.docker.io request.header.accept="application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, */*" request.header.user-agent="docker/dev go/go1.22.8 git-commit/06c2ba1fa02626e242dc8dfe888f022bcd247c52 kernel/6.10.11-linuxkit os/linux arch/arm64 containerd-client/1.7.22+unknown storage-driver/overlayfs UpstreamClient(Docker-Client/27.3.1 \\(darwin\\))" request.method=HEAD spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4 url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
DEBU[2024-10-23T15:23:32.051728378Z] fetch response received host=registry-1.docker.io response.header.content-length=162 response.header.content-type=application/json response.header.date="Wed, 23 Oct 2024 15:23:32 GMT" response.header.docker-distribution-api-version=registry/2.0 response.header.docker-ratelimit-source=94.210.180.92 response.header.strict-transport-security="max-age=31536000" response.header.www-authenticate="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\"" response.status="401 Unauthorized" spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4 url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
DEBU[2024-10-23T15:23:32.051830920Z] Unauthorized header="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\"" host=registry-1.docker.io spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4
DEBU[2024-10-23T15:23:32.051909045Z] do request host=registry-1.docker.io request.header.accept="application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, */*" request.header.user-agent="docker/dev go/go1.22.8 git-commit/06c2ba1fa02626e242dc8dfe888f022bcd247c52 kernel/6.10.11-linuxkit os/linux arch/arm64 containerd-client/1.7.22+unknown storage-driver/overlayfs UpstreamClient(Docker-Client/27.3.1 \\(darwin\\))" request.method=HEAD spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4 url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
DEBU[2024-10-23T15:23:32.544987920Z] fetch response received host=registry-1.docker.io response.header.content-length=162 response.header.content-type=application/json response.header.date="Wed, 23 Oct 2024 15:23:32 GMT" response.header.docker-distribution-api-version=registry/2.0 response.header.docker-ratelimit-source=4203339e-74c0-11e4-bea4-0242ac11001b response.header.strict-transport-security="max-age=31536000" response.header.www-authenticate="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\",error=\"insufficient_scope\"" response.status="401 Unauthorized" spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4 url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
DEBU[2024-10-23T15:23:32.545112212Z] Unauthorized header="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\",error=\"insufficient_scope\"" host=registry-1.docker.io spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4
INFO[2024-10-23T15:23:32.545270087Z] trying next host error="pull access denied, repository does not exist or may require authorization: server message: insufficient_scope: authorization failed" host=registry-1.docker.io spanID=97e231483c8d4d9a traceID=3c01e6c2cf19cf82237fdd01c0294fb4
DEBU[2024-10-23T15:23:32.550666962Z] handling POST request error-response="pull access denied for nosuchimage, repository does not exist or may require 'docker login'" method=POST module=api request-url="/v1.47/images/create?fromImage=nosuchimage&tag=latest" spanID=38286e48a07445ef status=404 traceID=3c01e6c2cf19cf82237fdd01c0294fb4 vars="map[version:1.47]"
With this patch applied:
DEBU[2024-10-23T15:18:18.876346178Z] handling HEAD request method=HEAD module=api request-url=/_ping spanID=7fd5eb011140f546 traceID=80ffd75a39de78a1f51ffda89fc4f227 vars="map[]"
DEBU[2024-10-23T15:18:18.878006428Z] handling POST request method=POST module=api request-url="/v1.47/images/create?fromImage=nosuchimage&tag=latest" spanID=40dea95727e38394 traceID=2f901d99f1cf2105e2614d6929d53d3b vars="map[version:1.47]"
DEBU[2024-10-23T15:18:18.919686136Z] resolving host=registry-1.docker.io spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b
DEBU[2024-10-23T15:18:18.919748094Z] do request host=registry-1.docker.io request.header.accept="application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, */*" request.header.user-agent="docker/dev go/go1.22.8 git-commit/06c2ba1fa02626e242dc8dfe888f022bcd247c52 kernel/6.10.11-linuxkit os/linux arch/arm64 containerd-client/1.7.22+unknown storage-driver/overlayfs UpstreamClient(Docker-Client/27.3.1 \\(darwin\\))" request.method=HEAD spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
DEBU[2024-10-23T15:18:19.258132303Z] fetch response received host=registry-1.docker.io response.header.content-length=162 response.header.content-type=application/json response.header.date="Wed, 23 Oct 2024 15:18:19 GMT" response.header.docker-distribution-api-version=registry/2.0 response.header.docker-ratelimit-source=94.210.180.92 response.header.strict-transport-security="max-age=31536000" response.header.www-authenticate="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\"" response.status="401 Unauthorized" spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
DEBU[2024-10-23T15:18:19.258219803Z] Unauthorized header="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\"" host=registry-1.docker.io spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b
DEBU[2024-10-23T15:18:19.258406886Z] do request host=registry-1.docker.io request.header.accept="application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, */*" request.header.user-agent="docker/dev go/go1.22.8 git-commit/06c2ba1fa02626e242dc8dfe888f022bcd247c52 kernel/6.10.11-linuxkit os/linux arch/arm64 containerd-client/1.7.22+unknown storage-driver/overlayfs UpstreamClient(Docker-Client/27.3.1 \\(darwin\\))" request.method=HEAD spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
DEBU[2024-10-23T15:18:19.755911762Z] fetch response received host=registry-1.docker.io response.header.content-length=162 response.header.content-type=application/json response.header.date="Wed, 23 Oct 2024 15:18:19 GMT" response.header.docker-distribution-api-version=registry/2.0 response.header.docker-ratelimit-source=4203339e-74c0-11e4-bea4-0242ac11001b response.header.strict-transport-security="max-age=31536000" response.header.www-authenticate="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\",error=\"insufficient_scope\"" response.status="401 Unauthorized" spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b url="https://registry-1.docker.io/v2/library/nosuchimage/manifests/latest"
DEBU[2024-10-23T15:18:19.757501928Z] Unauthorized header="Bearer realm=\"https://auth.docker.io/token\",service=\"registry.docker.io\",scope=\"repository:library/nosuchimage:pull\",error=\"insufficient_scope\"" host=registry-1.docker.io spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b
INFO[2024-10-23T15:18:19.757689387Z] trying next host error="pull access denied, repository does not exist or may require authorization: server message: insufficient_scope: authorization failed" host=registry-1.docker.io spanID=74f65a3accb19ad3 traceID=2f901d99f1cf2105e2614d6929d53d3b
DEBU[2024-10-23T15:18:19.763826095Z] error response for POST request error-response="pull access denied for nosuchimage, repository does not exist or may require 'docker login'" method=POST module=api request-url="/v1.47/images/create?fromImage=nosuchimage&tag=latest" spanID=40dea95727e38394 status=404 traceID=2f901d99f1cf2105e2614d6929d53d3b vars="map[version:1.47]"
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
Rewrite the debug-logs produced
- Use structured logs
- Combine into a single log per request, instead of separate log-entry
for the "form-data".
- Include error-messages returned by the handler ("error-response" field)
- Include HTTP status-code returned ("status" field)
- Include the "vars" as a field; these are fields extracted from the URL
and passed to the handler
Examples below are logs for:
docker ps
docker container inspect nosuchcontainer
docker volume create --name foo
Before this change:
DEBU[2024-10-16T10:59:40.484254465Z] Calling HEAD /_ping spanID=43d76043f8e30dbb traceID=04f980a33901f35ba33c3927d3bb4bbb
DEBU[2024-10-16T10:59:40.485551840Z] Calling GET /v1.47/containers/json spanID=b9979f2b36572a43 traceID=5c2167537df2dede6bdbab030f8350bc
DEBU[2024-10-16T11:00:00.374864502Z] Calling HEAD /_ping spanID=d637e39684d56a16 traceID=efaed7838901dd6a597c5446ce3f83e2
DEBU[2024-10-16T11:00:00.384198127Z] Calling GET /v1.47/containers/nosuchcontainer/json spanID=f9cc4520b95d814b traceID=c15ae04ca248929d6e52474e711d48b0
DEBU[2024-10-16T11:00:11.576426632Z] Calling HEAD /_ping spanID=2bc30d2be873a8e5 traceID=53ccc3d2af87aa5425421306906660a6
DEBU[2024-10-16T11:00:11.588877966Z] Calling POST /v1.47/volumes/create spanID=30816d2b51dd75b2 traceID=020b0e612195466468b46eb0d35a8f23
DEBU[2024-10-16T11:00:11.589198966Z] form data: {"Driver":"local","Name":"foo"} spanID=30816d2b51dd75b2 traceID=020b0e612195466468b46eb0d35a8f23
DEBU[2024-10-16T11:00:11.594828216Z] using regular volume spanID=30816d2b51dd75b2 traceID=020b0e612195466468b46eb0d35a8f23
After this:
When using plain-text, we continue encoding the form-data to JSON, but
as it's now in a field, it'll be shown escaped;
DEBU[2024-10-16T11:17:35.465777379Z] handling HEAD request method=HEAD module=api request-url=/_ping spanID=9b7ea0288b2b70c3 status=200 traceID=94ef9345624e92ac0263931fbe9e15db vars="map[]"
DEBU[2024-10-16T11:17:35.468050171Z] handling GET request method=GET module=api request-url=/v1.47/containers/json spanID=04675edee7b5ec9d status=200 traceID=a9d81dcdbf2650fa6d794a7a856fb66b vars="map[version:1.47]"
DEBU[2024-10-16T11:17:38.502289297Z] handling HEAD request method=HEAD module=api request-url=/_ping spanID=7c43a8dfd8fb5043 status=200 traceID=7a2a7c71cd421570e811474749a04ccd vars="map[]"
DEBU[2024-10-16T11:17:38.504847506Z] handling GET request error-response="No such container: nosuchcontainer" method=GET module=api request-url=/v1.47/containers/nosuchcontainer/json spanID=ab721bbbe5cf8035 status=404 traceID=4a08dcd5054fc8090e3af8846beea10d vars="map[name:nosuchcontainer version:1.47]"
DEBU[2024-10-16T11:17:40.788838340Z] handling HEAD request method=HEAD module=api request-url=/_ping spanID=2dbc18ba1334635b status=200 traceID=ea9af681d096dc4a2c2f2ed7338ea417 vars="map[]"
DEBU[2024-10-16T11:17:40.790496465Z] handling POST request form-data="{\"Driver\":\"local\",\"Name\":\"foo\"}" method=POST module=api request-url=/v1.47/volumes/create spanID=03690760b6f6dec4 status=200 traceID=79a985fff0dd5fac7c90d36b04941e0a vars="map[version:1.47]"
The alternative to the above would be to unconditionally set it as-is,
but in that case it would use Go's formatting for `map[string]any`;
DEBU[2024-10-16T11:27:54.937232805Z] handling POST request form-data="map[Driver:local Name:foo]" method=POST module=api request-url=/v1.47/volumes/create spanID=2d7985a900791bf6 status=200 traceID=33feab9fd5feba3b0f4b6ec5a6971a67 vars="map[version:1.47]"
Or to use some trickery to not quote this specific field, but that may limit the
output from being parsable;
DEBU[2024-10-16T11:17:40.790496465Z] handling POST request form-data={"Driver":"local","Name":"foo"} method=POST module=api request-url=/v1.47/volumes/create spanID=03690760b6f6dec4 status=200 traceID=79a985fff0dd5fac7c90d36b04941e0a vars="map[version:1.47]"
When using `--log-format=json`, the form-data is kept as structured, becoming
part of the main JSON struct:
{"level":"debug","method":"HEAD","module":"api","msg":"handling HEAD request","request-url":"/_ping","spanID":"166dc12eeeadf82b","status":200,"time":"2024-10-16T11:16:09.427380423Z","traceID":"7f4f2501eee3b15ae608481ba214bd56","vars":{}}
{"level":"debug","method":"GET","module":"api","msg":"handling GET request","request-url":"/v1.47/containers/json","spanID":"bf95e2ce9eca41c2","status":200,"time":"2024-10-16T11:16:09.429077631Z","traceID":"041b26b30dacc240e8e3afc9c567195d","vars":{"version":"1.47"}}
{"level":"debug","method":"HEAD","module":"api","msg":"handling HEAD request","request-url":"/_ping","spanID":"454953906c36ea6b","status":200,"time":"2024-10-16T11:16:13.455633008Z","traceID":"3ffc0a256d6ec1a56cd7f6bf1008e55d","vars":{}}
{"error-response":"No such container: nosuchcontainer","level":"debug","method":"GET","module":"api","msg":"handling GET request","request-url":"/v1.47/containers/nosuchcontainer/json","spanID":"dcf0d42921928b29","status":404,"time":"2024-10-16T11:16:13.460309925Z","traceID":"fdfd2c89941c9c7a459bec7a05e46ef8","vars":{"name":"nosuchcontainer","version":"1.47"}}
{"level":"debug","method":"HEAD","module":"api","msg":"handling HEAD request","request-url":"/_ping","spanID":"701dc623cf1b0253","status":200,"time":"2024-10-16T11:16:16.155730884Z","traceID":"786885a9f79cbfba99097eeb4145ca1e","vars":{}}
{"form-data":{"Driver":"local","Name":"foo"},"level":"debug","method":"POST","module":"api","msg":"handling POST request","request-url":"/v1.47/volumes/create","spanID":"dc1429c1c636b30a","status":200,"time":"2024-10-16T11:16:16.162002426Z","traceID":"fc49ee4a7acafbbb8eb50ed34c434765","vars":{"version":"1.47"}}
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
The github.com/containerd/containerd/log package was moved to a separate
module, which will also be used by upcoming (patch) releases of containerd.
This patch moves our own uses of the package to use the new module.
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
Path-specific rules were removed, so this is no longer used.
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
(cherry picked from commit 530e63c1a61b105a6f7fc143c5acb9b5cd87f958)
Signed-off-by: Tibor Vass <tibor@docker.com>
Commit 77b8465d7e added a secret update
endpoint to allow updating labels on existing secrets. However, when
implementing the endpoint, the DebugRequestMiddleware was not updated
to scrub the Data field (as is being done when creating a secret).
When updating a secret (to set labels), the Data field should be either
`nil` (not set), or contain the same value as the existing secret. In
situations where the Data field is set, and the `dockerd` daemon is
running with debugging enabled / log-level debug, the base64-encoded
value of the secret is printed to the daemon logs.
The docker cli does not have a `docker secret update` command, but
when using `docker stack deploy`, the docker cli sends the secret
data both when _creating_ a stack, and when _updating_ a stack, thus
leaking the secret data if the daemon runs with debug enabled:
1. Start the daemon in debug-mode
dockerd --debug
2. Initialize swarm
docker swarm init
3. Create a file containing a secret
echo secret > my_secret.txt
4. Create a docker-compose file using that secret
cat > docker-compose.yml <<'EOF'
version: "3.3"
services:
web:
image: nginx:alpine
secrets:
- my_secret
secrets:
my_secret:
file: ./my_secret.txt
EOF
5. Deploy the stack
docker stack deploy -c docker-compose.yml test
6. Verify that the secret is scrubbed in the daemon logs
DEBU[2019-07-01T22:36:08.170617400Z] Calling POST /v1.30/secrets/create
DEBU[2019-07-01T22:36:08.171364900Z] form data: {"Data":"*****","Labels":{"com.docker.stack.namespace":"test"},"Name":"test_my_secret"}
7. Re-deploy the stack to trigger an "update"
docker stack deploy -c docker-compose.yml test
8. Notice that this time, the Data field is not scrubbed, and the base64-encoded secret is logged
DEBU[2019-07-01T22:37:35.828819400Z] Calling POST /v1.30/secrets/w3hgvwpzl8yooq5ctnyp71v52/update?version=34
DEBU[2019-07-01T22:37:35.829993700Z] form data: {"Data":"c2VjcmV0Cg==","Labels":{"com.docker.stack.namespace":"test"},"Name":"test_my_secret"}
This patch modifies `maskSecretKeys` to unconditionally scrub `Data` fields.
Currently, only the `secrets` and `configs` endpoints use a field with this
name, and no other POST API endpoints use a data field, so scrubbing this
field unconditionally will only scrub requests for those endpoints.
If a new endpoint is added in future where this field should not be scrubbed,
we can re-introduce more fine-grained (path-specific) handling.
This patch introduces some change in behavior:
- In addition to secrets, requests to create or update _configs_ will
now have their `Data` field scrubbed. Generally, the actual data should
not be interesting for debugging, so likely will not be problematic.
In addition, scrubbing this data for configs may actually be desirable,
because (even though they are not explicitely designed for this purpose)
configs may contain sensitive data (credentials inside a configuration
file, e.g.).
- Requests that send key/value pairs as a "map" and that contain a
key named "data", will see the value of that field scrubbed. This
means that (e.g.) setting a `label` named `data` on a config, will
scrub/mask the value of that label.
- Note that this is already the case for any label named `jointoken`,
`password`, `secret`, `signingcakey`, or `unlockkey`.
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
(cherry picked from commit c7ce4be93ae8edd2da62a588e01c67313a4aba0c)
Signed-off-by: Tibor Vass <tibor@docker.com>
Since Go 1.7, context is a standard package. Since Go 1.9, everything
that is provided by "x/net/context" is a couple of type aliases to
types in "context".
Many vendored packages still use x/net/context, so vendor entry remains
for now.
Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
With debug logging turned on, we currently log the base64-encoded secret
payload.
Change the middleware code to redact this. Since the field is called
"Data", it requires some context-sensitivity. The URI path is examined
to see which route is being invoked.
Signed-off-by: Aaron Lehmann <aaron.lehmann@docker.com>
- Neither swarm init or swarm update should take an unlock key
- Add an autolock flag to turn on autolock
- Make the necessary docker api changes
- Add SwarmGetUnlockKey API call and use it when turning on autolock
- Add swarm unlock-key subcommand
Signed-off-by: Aaron Lehmann <aaron.lehmann@docker.com>
This makes separating middlewares from the core api easier.
As an example, the authorization middleware is moved to
it's own package.
Initialize all static middlewares when the server is created, reducing
allocations every time a route is wrapper with the middlewares.
Signed-off-by: David Calavera <david.calavera@gmail.com>
