Harbor: Core logs error "failed to verify token: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts" after switch to S3 storage -- excessive warning messages.
Expected behavior and actual behavior:
On a Harbor installation (Kubernetes using harbor-helm), I'm seeing the following error for all requests to the core server:
2020-06-16T11:32:11Z [WARNING] [/server/middleware/security/idtoken.go:45][requestID="a4f074b4-2cd2-4976-a68c-5f378fbc4882"]: failed to verify token: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts
2020/06/16 11:32:11.281 [D] [transaction.go:62] | 10.217.5.96| 200 | 502.279µs| match| GET /api/v2.0/ping r:/api/v2.0/ping
2020-06-16T11:32:14Z [WARNING] [/server/middleware/security/idtoken.go:45][requestID="29e92515-252d-4218-b16c-7530880cb5a6"]: failed to verify token: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts
2020/06/16 11:32:14.062 [D] [transaction.go:62] | 10.217.5.96| 200 | 294.838µs| match| GET /api/v2.0/ping r:/api/v2.0/ping
If I switch the installation back to using PersistentVolumeClaims, the errors go away (and leave just the regular ping's).
Steps to reproduce the problem:
Seem to be related to using a S3 backend, likely in combination with us using oAuth for Single Sign-On.
Versions:
Please specify the versions of following systems.
- harbor version: 2.0.0
- harbor-helm 1.4.0
- kubernetes: 1.17.3
- oAuth server is dex (https://github.com/dexidp/dex)
Additional context:
(I was unable to locate any meaningful configuration file on the core server pod. Relevant logs reproduced above.)
msiebuhr
All 18 comments
Please elaborate on how you reproduce it, did you use a curl command to call Harbor's API?
I don't think it's related to S3 or local disk.
It seems b/c you are using OIDC auth mode but the request is not carrying valid ID token.
reasonerjt
on 17 Jun 2020
It is deployed to Kubernetes using the neighboring harbor-helm chart.
lease elaborate on how you reproduce it, did you use a curl command to call Harbor's API?
The /ping requests are done by Kubernete's health-check. As Kubernetes does not restart the server, I guess it's returning something OK.
I don't think it's related to S3 or local disk.
Neither do I. But when I changed the helm-chart from HDD to S3 storage for images and helm-charts, these errors began appearing. When I switched it back, they stopped (so so forth). I'm in the midst of re-deploying the whole thing to a upgraded cluster, so I'll see if I can reproduce it there...
It seems b/c you are using OIDC auth mode but the request is not carrying valid ID token.
That would be my guess too, but Kubernets healthcheck-requests AFAIK shouldn't have to carry ID tokens...
msiebuhr
on 18 Jun 2020
That would be my guess too, but Kubernets healthcheck-requests AFAIK shouldn't have to carry ID tokens...
So could you please clarify do the "errors", which seem warnings, impact you calling any API or using your Harbor instance?
I think we may probably ignore the warnings safely. I am not sure if we should update the log to remove the warnings, they do help when there are real erros happening.
reasonerjt
on 18 Jun 2020
This is one of the logs from our production systems , is it possible to suppress the ping logs for jwt warnings as there is no token passed
2020/06/18 23:30:01.897 [D] [transaction.go:62] | 10.161.40.88| 200 | 231.166µs| match| GET /api/v2.0/ping r:/api/v2.0/ping
2020-06-18T23:30:09Z [WARNING] [/server/middleware/security/idtoken.go:45][requestID="473dfbc4-0ce9-4db3-bde5-671479e41120"]: failed to verify token: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts
2020/06/18 23:30:09.983 [D] [transaction.go:62] | 10.161.40.88| 200 | 240.118µs| match| GET /api/v2.0/ping r:/api/v2.0/ping
2020-06-18T23:30:11Z [WARNING] [/server/middleware/security/idtoken.go:45][requestID="a6624c06-8ab2-4ec0-bb63-2055e1be0a2e"]: failed to verify token: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts
2020/06/18 23:30:11.897 [D] [transaction.go:62] | 10.161.40.88| 200 | 230.858µs| match| GET /api/v2.0/ping r:/api/v2.0/ping
2020-06-18T23:30:20Z [WARNING] [/server/middleware/security/idtoken.go:45][requestID="90e6bb55-95b9-4aec-9d94-63b0f35de84c"]: failed to verify token: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts
2020/06/18 23:30:20.217 [D] [transaction.go:62] | 10.161.40.88| 200 | 254.327µs| match| GET /api/v2.0/ping r:/api/v2.0/ping
2020-06-18T23:30:21Z [WARNING] [/server/middleware/security/idtoken.go:45][requestID="84caf698-f071-4d9c-8c5e-02a96187bba9"]: failed to verify token: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts
2020/06/18 23:30:21.897 [D] [transaction.go:62] | 10.161.40.88| 200 | 272.758µs| match| GET /api/v2.0/ping r:/api/v2.0/ping
2020-06-18T23:30:29Z [WARNING] [/server/middleware/security/idtoken.go:45][requestID="dc26f59b-50db-4950-8545-20ffc5f093ea"]: failed to verify token: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts
2020/06/18 23:30:29.969 [D] [transaction.go:62] | 10.161.40.88| 200 | 1.301521ms| match| GET /api/v2.0/ping r:/api/v2.0/ping
2020-06-18T23:30:31Z [WARNING] [/server/middleware/security/idtoken.go:45][requestID="ad5eb405-a13f-41dc-8aaf-4158af875684"]: failed to verify token: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts
2020/06/18 23:30:31.897 [D] [transaction.go:62] | 10.161.40.88| 200 | 246.229µs| match| GET /api/v2.0/ping r:/api/v2.0/ping
2020-06-18T23:30:39Z [WARNING] [/server/middleware/security/idtoken.go:45][requestID="49ac5682-bd72-47df-8ae5-a2928087014d"]: failed to verify token: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts
2020/06/18 23:30:39.976 [D] [transaction.go:62] | 10.161.40.88| 200 | 219.098µs| match| GET /api/v2.0/ping r:/api/v2.0/ping
2020-06-18T23:30:41Z [WARNING] [/server/middleware/security/idtoken.go:45][requestID="56fdc52e-6398-4226-8d50-36f154394908"]: failed to verify token: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts
2020/06/18 23:30:41.897 [D] [transaction.go:62] | 10.161.40.88| 200 | 256.223µs| match| GET /api/v2.0/ping r:/api/v2.0/ping
2020-06-18T23:30:49Z [WARNING] [/server/middleware/security/idtoken.go:45][requestID="7c0b2a55-92e9-4d3d-a8f9-4b7971944c5f"]: failed to verify token: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts
2020/06/18 23:30:49.970 [D] [transaction.go:62] | 10.161.40.88| 200 | 225.957µs| match| GET /api/v2.0/ping r:/api/v2.0/ping
2020-06-18T23:30:51Z [WARNING] [/server/middleware/security/idtoken.go:45][requestID="74252a81-632e-44d0-8e5d-8d9e7c4a4b41"]: failed to verify token: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts
2020/06/18 23:30:51.897 [D] [transaction.go:62] | 10.161.40.88| 200 | 233.083µs| match| GET /api/v2.0/ping r:/api/v2.0/ping
ajayk
on 19 Jun 2020
@ajayk
It's do-able by updating the code. I'll take a look to try to make the message more reasonable, i.e. print warning only when there is obviously a problem.
reasonerjt
on 19 Jun 2020
2020-06-23T01:19:43Z [WARNING] [/server/middleware/security/idtoken.go:45][requestID="c29e43eb-f660-4127-856a-86a73e7f3299"]: failed to verify token: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts
2020/06/23 01:19:43.952 [D] [transaction.go:62] | 10.253.5.42| 200 | 962.992µs| match| GET /api/v2.0/ping r:/api/v2.0/ping
2020-06-23T01:19:49Z [WARNING] [/server/middleware/security/idtoken.go:45][requestID="d5debf3b-7250-4855-8417-bdd6a84129d2"]: failed to verify token: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts
2020/06/23 01:19:49.760 [D] [transaction.go:62] | 10.253.5.42| 200 | 1.100142ms| match| GET /api/v2.0/ping r:/api/v2.0/ping
2020-06-23T01:19:53Z [WARNING] [/server/middleware/security/idtoken.go:45][requestID="6cd74763-e07b-4189-acc7-a6718e945baf"]: failed to verify token: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts
2020/06/23 01:19:53.953 [D] [transaction.go:62] | 10.253.5.42| 200 | 976.755µs| match| GET /api/v2.0/ping r:/api/v2.0/ping
2020-06-23T01:19:59Z [WARNING] [/server/middleware/security/idtoken.go:45][requestID="945207bd-a9f5-4d1a-96a6-5bb2a7811813"]: failed to verify token: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts
2020/06/23 01:19:59.759 [D] [transaction.go:62] | 10.253.5.42| 200 | 606.271µs| match| GET /api/v2.0/ping r:/api/v2.0/ping
Getting the same thing with a Kubernetes deployment from the neighboring Helm chart. The spam is making finding actual issues (which I'm also having) extremely tedious.
pard68
on 23 Jun 2020
I'm getting the same warnings using both Chrome and Firefox. Everything seems to be working except those warning messages in logs. I had a look at the request cookies and there's no valid JWT token set (valid as base64 encoded strings in three parts separated via dots). X-Request-Id header matched with the log file entries using /api/v2.0/scans/schedule/metrics endpoint in this particular case.
My environment has been setup with docker-compose instead of Kubernetes, but I'm using as well:
- Harbor versions 2.0.0 and 2.0.1
- OIDC authentication with Dex 2.24 having GitHub Enterprise as authentication backend
- S3 storage
rofafor
on 6 Jul 2020
+1 from here
- Harbor version 2.0.1 and 2.0.2
- GCS Backend
- OIDC Auth w/Azure
brondum
on 20 Jul 2020
Same issue here.
- Azure Storage Account as the backend
- OIDC Auth w/Azure
- Harbor version 2.0.1
fl-max
on 27 Jul 2020
+1 with:
- Harbor version 2.0.2
- OIDC Auth with Keycloak
- Ceph S3 Backend
l4z41
on 17 Aug 2020
For me it affects docker login as well see #12851
promasu
on 22 Aug 2020
Guys for short term you may just ignore the this WARNING message.
reasonerjt
on 23 Sep 2020
I'm trying to debug an issue where Harbor 2.1.0 seem to crash whenever I try pull-through caching from Docker hub. Turning the log-level to debug means that every request to /ping logs a stanza like this every five seconds [1]:
2020-09-30T07:28:46Z [DEBUG] [/common/config/manager.go:192]: failed to get key oidc_user_claim, error: the configure value is not set
2020-09-30T07:28:46Z [DEBUG] [/server/middleware/log/log.go:30]: attach request id 0051d8e0-2bbf-4c3d-8e93-d13065c5a181 to the logger for the request GET /api/v2.0/ping
2020-09-30T07:28:46Z [DEBUG] [/server/middleware/artifactinfo/artifact_info.go:52]: In artifact info middleware, url: /api/v2.0/ping
2020-09-30T07:28:46Z [DEBUG] [/common/utils/oidc/helper.go:194]: Raw ID token for verification:
2020-09-30T07:28:46Z [WARNING] [/server/middleware/security/idtoken.go:45][requestID="0051d8e0-2bbf-4c3d-8e93-d13065c5a181"]: failed to verify token: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts
2020-09-30T07:28:46Z [DEBUG] [/server/middleware/security/unauthorized.go:29][requestID="0051d8e0-2bbf-4c3d-8e93-d13065c5a181"]: an unauthorized security context generated for request GET /api/v2.0/ping
This amount of noise makes it _very_ hard to figure out what's actually going on (besides unauthenticated ping-requests, that is).
[1] Harbor's Helm-chart runs liveness- and readiness-probes every 10s each. Both call /api/v2.0/ping.
msiebuhr
on 30 Sep 2020
It seems to me when oidc is enabled all requests to the api/v2.0 endpoint require a valid JWT payload. Since the healthchecks do not we see the log spam.
claims, err := oidc.VerifyToken(req.Context(), bearerToken(req))
if err != nil {
log.Warningf("failed to verify token: %v", err)
return nil
}
IMO we should add something like:
if strings.Contains(req.URL.Path, substr "ping") {
return nil
}
sharkymcdongles
on 16 Oct 2020
This issue may be fixed by this PR https://github.com/goharbor/harbor/pull/13422
heww
on 9 Nov 2020
I think it is, closing this issue, thanks @heww
reasonerjt
on 14 Dec 2020
not solved with #13422 after upgrade to 2.1.2, reopen?
beer1970
on 23 Dec 2020
not solved with #13422 after upgrade to 2.1.2, reopen?
Yep, not fixed. With debug logging enabled, the error/warning is:
2020-12-29T17:03:32Z [DEBUG] [/server/middleware/log/log.go:30]: attach request id 112e95d5-1cd1-4031-b592-911a8ec527a2 to the logger for the request GET /api/v2.0/ping
2020-12-29T17:03:32Z [DEBUG] [/server/middleware/artifactinfo/artifact_info.go:52]: In artifact info middleware, url: /api/v2.0/ping
2020-12-29T17:03:32Z [DEBUG] [/common/utils/oidc/helper.go:194]: Raw ID token for verification:
2020-12-29T17:03:32Z [WARNING] [/server/middleware/security/idtoken.go:45][requestID="112e95d5-1cd1-4031-b592-911a8ec527a2"]: failed to verify token: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts
2020-12-29T17:03:32Z [DEBUG] [/server/middleware/security/unauthorized.go:29][requestID="112e95d5-1cd1-4031-b592-911a8ec527a2"]: an unauthorized security context generated for request GET /api/v2.0/ping
Related issues
pingcrosby
·
3Comments
andrewtchin
·
3Comments
xiaosadexiaohai
·
3Comments
protochron
·
3Comments
a-kinder
·
3Comments
Most helpful comment
+1 with: