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. #12261

msiebuhr · 2020-06-16T11:48:54Z

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.)

The text was updated successfully, but these errors were encountered:

reasonerjt · 2020-06-17T17:27:21Z

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.

msiebuhr · 2020-06-18T09:40:58Z

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...

reasonerjt · 2020-06-18T17:03:02Z

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.

ajayk · 2020-06-18T23:33:28Z

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

reasonerjt · 2020-06-19T06:43:23Z

@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.

ispringle · 2020-06-23T01:21:04Z

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.

rofafor · 2020-07-06T14:15:45Z

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

brondum · 2020-07-20T12:42:06Z

+1 from here

Harbor version 2.0.1 and 2.0.2
GCS Backend
OIDC Auth w/Azure

fl-max · 2020-07-27T20:43:08Z

Same issue here.

Azure Storage Account as the backend
OIDC Auth w/Azure
Harbor version 2.0.1

l4z41 · 2020-08-17T08:00:29Z

+1 with:

Harbor version 2.0.2
OIDC Auth with Keycloak
Ceph S3 Backend

promasu · 2020-08-22T21:29:47Z

For me it affects docker login as well see #12851

reasonerjt · 2020-09-23T05:42:59Z

Guys for short term you may just ignore the this WARNING message.

msiebuhr · 2020-09-30T07:37:52Z

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] [/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.

sharkymcdongles · 2020-10-16T14:59:56Z

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
	}

heww · 2020-11-09T13:45:09Z

This issue may be fixed by this PR #13422

reasonerjt · 2020-12-14T07:26:36Z

I think it is, closing this issue, thanks @heww

beer1970 · 2020-12-23T20:52:45Z

not solved with #13422 after upgrade to 2.1.2, reopen?

fl-max · 2020-12-29T17:07:59Z

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

If the request does not have bearer token in the header, do not decode the empty string. Fixes goharbor#12261 Signed-off-by: Daniel Jiang <jiangd@vmware.com>

reasonerjt self-assigned this Jun 17, 2020

reasonerjt added the pending-for-more-info label Jun 18, 2020

reasonerjt added area/oidc and removed pending-for-more-info labels Jun 19, 2020

reasonerjt added kind/debt candidate/2.2.0 labels Sep 16, 2020

sharkymcdongles mentioned this issue Oct 16, 2020

add whitelisting in idtoken for ping endpoint #13286

Closed

sharkymcdongles mentioned this issue Nov 9, 2020

feat: skip middlewares require db for ping #13422

Merged

reasonerjt closed this as completed Dec 14, 2020

prudhvigodithi mentioned this issue Jan 12, 2021

failed to verify token: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts goharbor/harbor-helm#833

Closed

reasonerjt reopened this Jan 28, 2021

reasonerjt added a commit to reasonerjt/harbor that referenced this issue Jan 28, 2021

Reduce warning logs in OIDC middleware

2dd499b

If the request does not have bearer token in the header, do not decode the empty string. Fixes goharbor#12261 Signed-off-by: Daniel Jiang <jiangd@vmware.com>

reasonerjt mentioned this issue Jan 28, 2021

Reduce warning logs in OIDC middleware #14116

Merged

ywk253100 closed this as completed in #14116 Feb 1, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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. #12261

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. #12261

msiebuhr commented Jun 16, 2020

reasonerjt commented Jun 17, 2020 •

edited

msiebuhr commented Jun 18, 2020

reasonerjt commented Jun 18, 2020

ajayk commented Jun 18, 2020

reasonerjt commented Jun 19, 2020 •

edited

ispringle commented Jun 23, 2020

rofafor commented Jul 6, 2020

brondum commented Jul 20, 2020 •

edited

fl-max commented Jul 27, 2020

l4z41 commented Aug 17, 2020

promasu commented Aug 22, 2020

reasonerjt commented Sep 23, 2020

msiebuhr commented Sep 30, 2020 •

edited

sharkymcdongles commented Oct 16, 2020

heww commented Nov 9, 2020

reasonerjt commented Dec 14, 2020

beer1970 commented Dec 23, 2020

fl-max commented Dec 29, 2020

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. #12261

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. #12261

Comments

msiebuhr commented Jun 16, 2020

reasonerjt commented Jun 17, 2020 • edited

msiebuhr commented Jun 18, 2020

reasonerjt commented Jun 18, 2020

ajayk commented Jun 18, 2020

reasonerjt commented Jun 19, 2020 • edited

ispringle commented Jun 23, 2020

rofafor commented Jul 6, 2020

brondum commented Jul 20, 2020 • edited

fl-max commented Jul 27, 2020

l4z41 commented Aug 17, 2020

promasu commented Aug 22, 2020

reasonerjt commented Sep 23, 2020

msiebuhr commented Sep 30, 2020 • edited

sharkymcdongles commented Oct 16, 2020

heww commented Nov 9, 2020

reasonerjt commented Dec 14, 2020

beer1970 commented Dec 23, 2020

fl-max commented Dec 29, 2020

reasonerjt commented Jun 17, 2020 •

edited

reasonerjt commented Jun 19, 2020 •

edited

brondum commented Jul 20, 2020 •

edited

msiebuhr commented Sep 30, 2020 •

edited