Prefix in listObjects throws 500 error

[nicam]

Hi there

I was connecting the headless CMS Directus towards Pydio which was working fine for uploads but upon deletion it caused a 500 server error.

After a lengthy debug session I noticed the following pattern in Pydio Cells:

`const S3 = require('aws-sdk/clients/s3'); this.$driver = new S3({ accessKeyId: config.key, secretAccessKey: config.secret, ...config, });

             const response = await this.$driver
				.listObjectsV2({
					Bucket: this.$bucket,
					Prefix: '/does-not-exist',
					ContinuationToken: continuationToken,
					MaxKeys: 1000,
				})
				.promise();``

If you use the standard AWS-SDK S3 Client, and execute the method listObjectsV2, with a prefix that does not find anything, the S3 Client throws an Exception.

If the prefix finds something, then there's no error and everything works. This behaviour is not present with other S3 Vendors such as Minio.

S3 Client Error message `UnknownException: E_UNKNOWN: An unknown error happened with the file directus.

Error code: InternalError Original stack: InternalError: We encountered an internal error, please try again. at Request.extractError (/directus/packages/drive-s3/node_modules/aws-sdk/lib/services/s3.js:714:35) at Request.callListeners (/directus/packages/drive-s3/node_modules/aws-sdk/lib/sequential_executor.js:106:20) at Request.emit (/directus/packages/drive-s3/node_modules/aws-sdk/lib/sequential_executor.js:78:10) at Request.emit (/directus/packages/drive-s3/node_modules/aws-sdk/lib/request.js:688:14) at Request.transition (/directus/packages/drive-s3/node_modules/aws-sdk/lib/request.js:22:10) at AcceptorStateMachine.runTo (/directus/packages/drive-s3/node_modules/aws-sdk/lib/state_machine.js:14:12) at /directus/packages/drive-s3/node_modules/aws-sdk/lib/state_machine.js:26:10 at Request. (/directus/packages/drive-s3/node_modules/aws-sdk/lib/request.js:38:9) at Request. (/directus/packages/drive-s3/node_modules/aws-sdk/lib/request.js:690:12) at Request.callListeners (/directus/packages/drive-s3/node_modules/aws-sdk/lib/sequential_executor.js:116:18) at handleError (/directus/packages/drive-s3/src/AmazonWebServicesS3Storage.ts:30:11) at AmazonWebServicesS3Storage.flatList (/directus/packages/drive-s3/src/AmazonWebServicesS3Storage.ts:304:11) at processTicksAndRejections (node:internal/process/task_queues:93:5) at async /directus/packages/drive-s3/src/test.ts:16:28 { raw: Error [InternalError]: We encountered an internal error, please try again. at Request.extractError (/directus/packages/drive-s3/node_modules/aws-sdk/lib/services/s3.js:714:35) at Request.callListeners (/directus/packages/drive-s3/node_modules/aws-sdk/lib/sequential_executor.js:106:20) at Request.emit (/directus/packages/drive-s3/node_modules/aws-sdk/lib/sequential_executor.js:78:10) at Request.emit (/directus/packages/drive-s3/node_modules/aws-sdk/lib/request.js:688:14) at Request.transition (/directus/packages/drive-s3/node_modules/aws-sdk/lib/request.js:22:10) at AcceptorStateMachine.runTo (/directus/packages/drive-s3/node_modules/aws-sdk/lib/state_machine.js:14:12) at /directus/packages/drive-s3/node_modules/aws-sdk/lib/state_machine.js:26:10 at Request. (/directus/packages/drive-s3/node_modules/aws-sdk/lib/request.js:38:9) at Request. (/directus/packages/drive-s3/node_modules/aws-sdk/lib/request.js:690:12) at Request.callListeners (/directus/packages/drive-s3/node_modules/aws-sdk/lib/sequential_executor.js:116:18) { code: 'InternalError', region: null, time: 2021-08-18T14:08:56.460Z, requestId: '169C6BD7043D4EAC', extendedRequestId: undefined, cfId: undefined, statusCode: 500, retryable: true } }`

The error of Pydio is attached below:

| 2021-08-18T09:32:58.191Z DEBUG pydio.gateway.data jwt rawIdToken verify: failed {"error": "request_unauthorized", "errorVerbose": "request_unauthorized github.com/pydio/cells/vendor/github.com/ory/fosite.(*Fosite).IntrospectToken \tgithub.com/pydio/cells/vendor/github.com/ory/fosite/introspect.go:69 github.com/pydio/cells/common/auth.(*oryprovider).Verify \tgithub.com/pydio/cells/common/auth/jwt_ory.go:382 github.com/pydio/cells/common/auth.(*JWTVerifier).verifyTokenWithRetry \tgithub.com/pydio/cells/common/auth/jwt.go:246 github.com/pydio/cells/common/auth.(*JWTVerifier).Verify \tgithub.com/pydio/cells/common/auth/jwt.go:294 github.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd.pydioAuthHandler.ServeHTTP \tgithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/gateway-pydio-auth-handler.go:83 github.com/pydio/cells/common/service/context.HttpSpanHandlerWrapper.func1 \tgithub.com/pydio/cells/common/service/context/span.go:178 net/http.HandlerFunc.ServeHTTP \tnet/http/server.go:2042 github.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd.criticalErrorHandler.ServeHTTP \tgithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/generic-handlers.go:775 github.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/http.(*Server).Start.func1 \tgithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/http/server.go:115 net/http.HandlerFunc.ServeHTTP \tnet/http/server.go:2042 net/http.serverHandler.ServeHTTP \tnet/http/server.go:2843 net/http.(*conn).serve \tnet/http/server.go:1925 runtime.goexit \truntime/asm_amd64.s:1374"} dms_1 | 2021-08-18T09:32:58.196Z DEBUG pydio.gateway.data jwt rawIdToken verify: failed {"error": "{\"id\":\"\",\"code\":0,\"detail\":\"request_unauthorized\",\"status\":\"\"}"} dms_1 | 2021-08-18T09:32:58.206Z DEBUG Users Search Query {"q": "SELECTt.uuid, t.level, t.mpath1, t.mpath2, t.mpath3, t.mpath4, t.name, t.leaf, t.etag, t.mtimeFROMidm_user_idx_treeASt WHERE (t.uuid= ?) ORDER BYt.nameASC", "q2 length": 1} dms_1 | 2021-08-18T09:32:58.225Z DEBUG pydio.grpc.tree No user/claims found - skipping user metas on metaStreamers init! dms_1 | 2021-08-18T09:32:58.226Z DEBUG pydio.grpc.tree ReadNode {"uuid": "DATASOURCE:personal"} dms_1 | 2021-08-18T09:32:58.231Z DEBUG pydio.grpc.data.index.personal ReadNode {"time": "1.182ms", "req": "Node:<Uuid:\"ROOT\" > ", "resp": "Success:true Node:<Uuid:\"ROOT\" Path:\"/\" Type:COLLECTION Size:474121 MTime:1629268303 MetaStore:<key:\"name\" value:\"\\\"\\\"\" > MetaStore:<key:\"pydio:meta-data-source-name\" value:\"\\\"personal\\\"\" > > "} dms_1 | 2021-08-18T09:32:58.232Z DEBUG pydio.grpc.tree [Look Up] Found node {"uuid": "DATASOURCE:personal", "datasource": "personal"} dms_1 | 2021-08-18T09:32:58.232Z DEBUG pydio.grpc.tree Response after lookUp {"path": "personal/"} dms_1 | 2021-08-18T09:32:58.233Z DEBUG pydio.grpc.meta ReadNodeStream {"path": "personal/"} dms_1 | 2021-08-18T09:32:58.235Z DEBUG pydio.grpc.tree EnrichMetaProvider - Average time spent {"pydio.grpc.meta": "1.8817ms"} dms_1 | 2021-08-18T09:32:58.235Z DEBUG pydio.grpc.tree ReadNode {"time": "8.8924ms", "req": "Node:<Uuid:\"DATASOURCE:personal\" > ", "resp": "Node:<Uuid:\"DATASOURCE:personal\" Path:\"personal/\" Type:COLLECTION Size:474121 MTime:1629268303 MetaStore:<key:\"name\" value:\"\\\"\\\"\" > MetaStore:<key:\"pydio:meta-data-source-name\" value:\"\\\"personal\\\"\" > MetaStore:<key:\"pydio:meta-data-source-path\" value:\"\\\"\\\"\" > MetaStore:<key:\"pydio:meta-loaded-pydio.grpc.meta\" value:\"true\" > > "} dms_1 | 2021-08-18T09:32:58.247Z DEBUG Users Search Query {"q": "SELECTt.uuid, t.level, t.mpath1, t.mpath2, t.mpath3, t.mpath4, t.name, t.leaf, t.etag, t.mtimeFROMidm_user_idx_treeASt WHERE ((t.name = ?) AND (t.leaf= ?)) ORDER BYt.nameASC", "q2 length": 1} dms_1 | 2021-08-18T09:32:58.252Z DEBUG pydio.grpc.data.index.personal ReadNode {"time": "2.0158ms", "req": "Node:<Path:\"ad36a715-621e-4bb1-b0f4-8bc8a1863cb0\" > ", "resp": ""} dms_1 | 2021-08-18T09:32:58.254Z DEBUG pydio.grpc.tree ReadNode {"time": "4.9506ms", "req": "Node:<Path:\"personal/ad36a715-621e-4bb1-b0f4-8bc8a1863cb0\" MetaStore:<key:\"pydio:meta-data-source-path\" value:\"\\\"ad36a715-621e-4bb1-b0f4-8bc8a1863cb0\\\"\" > > ", "resp": ""} dms_1 | 2021-08-18T09:32:58.254Z DEBUG pydio.grpc.tree ListNodes {"time": "15.2313ms", "req": "Node:<Path:\"personal/ad36a715-621e-4bb1-b0f4-8bc8a1863cb0\" MetaStore:<key:\"pydio:meta-data-source-path\" value:\"\\\"ad36a715-621e-4bb1-b0f4-8bc8a1863cb0\\\"\" > > Ancestors:true ", "resp": {}} dms_1 | 2021-08-18T09:32:58.257Z DEBUG Users Search Query {"q": "SELECTt.uuid, t.level, t.mpath1, t.mpath2, t.mpath3, t.mpath4, t.name, t.leaf, t.etag, t.mtimeFROMidm_user_idx_treeASt WHERE ((t.name = ?) AND (t.leaf= ?)) ORDER BYt.name ASC", "q2 length": 1} dms_1 | 2021-08-18T09:32:58.310Z DEBUG pydio.gateway.data jwt rawIdToken verify: failed {"error": "request_unauthorized", "errorVerbose": "request_unauthorized github.com/pydio/cells/vendor/github.com/ory/fosite.(*Fosite).IntrospectToken \tgithub.com/pydio/cells/vendor/github.com/ory/fosite/introspect.go:69 github.com/pydio/cells/common/auth.(*oryprovider).Verify \tgithub.com/pydio/cells/common/auth/jwt_ory.go:382 github.com/pydio/cells/common/auth.(*JWTVerifier).verifyTokenWithRetry \tgithub.com/pydio/cells/common/auth/jwt.go:246 github.com/pydio/cells/common/auth.(*JWTVerifier).Verify \tgithub.com/pydio/cells/common/auth/jwt.go:294 github.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd.pydioAuthHandler.ServeHTTP \tgithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/gateway-pydio-auth-handler.go:83 github.com/pydio/cells/common/service/context.HttpSpanHandlerWrapper.func1 \tgithub.com/pydio/cells/common/service/context/span.go:178 net/http.HandlerFunc.ServeHTTP \tnet/http/server.go:2042 github.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd.criticalErrorHandler.ServeHTTP \tgithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/generic-handlers.go:775 github.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/http.(*Server).Start.func1 \tgithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/http/server.go:115 net/http.HandlerFunc.ServeHTTP \tnet/http/server.go:2042 net/http.serverHandler.ServeHTTP \tnet/http/server.go:2843 net/http.(*conn).serve \tnet/http/server.go:1925 runtime.goexit \truntime/asm_amd64.s:1374"} dms_1 | 2021-08-18T09:32:58.315Z DEBUG pydio.gateway.data jwt rawIdToken verify: failed {"error": "{\"id\":\"\",\"code\":0,\"detail\":\"request_unauthorized\",\"status\":\"\"}"} dms_1 | 2021-08-18T09:32:58.343Z DEBUG pydio.grpc.data.index.personal ReadNode {"time": "894.9µs", "req": "Node:<Path:\"ad36a715-621e-4bb1-b0f4-8bc8a1863cb0\" > ", "resp": ""} dms_1 | 2021-08-18T09:32:58.345Z DEBUG pydio.grpc.tree ReadNode {"time": "4.1047ms", "req": "Node:<Path:\"personal/ad36a715-621e-4bb1-b0f4-8bc8a1863cb0\" MetaStore:<key:\"pydio:meta-data-source-path\" value:\"\\\"ad36a715-621e-4bb1-b0f4-8bc8a1863cb0\\\"\" > > ", "resp": ""} dms_1 | 2021-08-18T09:32:58.345Z DEBUG pydio.grpc.tree ListNodes {"time": "13.7849ms", "req": "Node:<Path:\"personal/ad36a715-621e-4bb1-b0f4-8bc8a1863cb0\" MetaStore:<key:\"pydio:meta-data-source-path\" value:\"\\\"ad36a715-621e-4bb1-b0f4-8bc8a1863cb0\\\"\" > > Ancestors:true ", "resp": {}} dms_1 | 2021-08-18T09:32:58.487Z DEBUG pydio.gateway.data jwt rawIdToken verify: failed {"error": "request_unauthorized", "errorVerbose": "request_unauthorized github.com/pydio/cells/vendor/github.com/ory/fosite.(*Fosite).IntrospectToken \tgithub.com/pydio/cells/vendor/github.com/ory/fosite/introspect.go:69 github.com/pydio/cells/common/auth.(*oryprovider).Verify \tgithub.com/pydio/cells/common/auth/jwt_ory.go:382 github.com/pydio/cells/common/auth.(*JWTVerifier).verifyTokenWithRetry \tgithub.com/pydio/cells/common/auth/jwt.go:246 github.com/pydio/cells/common/auth.(*JWTVerifier).Verify \tgithub.com/pydio/cells/common/auth/jwt.go:294 github.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd.pydioAuthHandler.ServeHTTP \tgithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/gateway-pydio-auth-handler.go:83 github.com/pydio/cells/common/service/context.HttpSpanHandlerWrapper.func1 \tgithub.com/pydio/cells/common/service/context/span.go:178 net/http.HandlerFunc.ServeHTTP \tnet/http/server.go:2042 github.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd.criticalErrorHandler.ServeHTTP \tgithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/generic-handlers.go:775 github.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/http.(*Server).Start.func1 \tgithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/http/server.go:115 net/http.HandlerFunc.ServeHTTP \tnet/http/server.go:2042 net/http.serverHandler.ServeHTTP \tnet/http/server.go:2843 net/http.(*conn).serve \tnet/http/server.go:1925 runtime.goexit \truntime/asm_amd64.s:1374"} dms_1 | 2021-08-18T09:32:58.491Z DEBUG pydio.gateway.data jwt rawIdToken verify: failed {"error": "{\"id\":\"\",\"code\":0,\"detail\":\"request_unauthorized\",\"status\":\"\"}"} dms_1 | 2021-08-18T09:32:58.525Z DEBUG pydio.grpc.data.index.personal ReadNode {"time": "909µs", "req": "Node:<Path:\"ad36a715-621e-4bb1-b0f4-8bc8a1863cb0\" > ", "resp": ""} dms_1 | 2021-08-18T09:32:58.526Z DEBUG pydio.grpc.tree ReadNode {"time": "4.9094ms", "req": "Node:<Path:\"personal/ad36a715-621e-4bb1-b0f4-8bc8a1863cb0\" MetaStore:<key:\"pydio:meta-data-source-path\" value:\"\\\"ad36a715-621e-4bb1-b0f4-8bc8a1863cb0\\\"\" > > ", "resp": ""} dms_1 | 2021-08-18T09:32:58.527Z DEBUG pydio.grpc.tree ListNodes {"time": "17.7057ms", "req": "Node:<Path:\"personal/ad36a715-621e-4bb1-b0f4-8bc8a1863cb0\" MetaStore:<key:\"pydio:meta-data-source-path\" value:\"\\\"ad36a715-621e-4bb1-b0f4-8bc8a1863cb0\\\"\" > > Ancestors:true ", "resp": {}} dms_1 | 2021-08-18T09:32:58.720Z DEBUG pydio.gateway.data jwt rawIdToken verify: failed {"error": "request_unauthorized", "errorVerbose": "request_unauthorized github.com/pydio/cells/vendor/github.com/ory/fosite.(*Fosite).IntrospectToken \tgithub.com/pydio/cells/vendor/github.com/ory/fosite/introspect.go:69 github.com/pydio/cells/common/auth.(*oryprovider).Verify \tgithub.com/pydio/cells/common/auth/jwt_ory.go:382 github.com/pydio/cells/common/auth.(*JWTVerifier).verifyTokenWithRetry \tgithub.com/pydio/cells/common/auth/jwt.go:246 github.com/pydio/cells/common/auth.(*JWTVerifier).Verify \tgithub.com/pydio/cells/common/auth/jwt.go:294 github.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd.pydioAuthHandler.ServeHTTP \tgithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/gateway-pydio-auth-handler.go:83 github.com/pydio/cells/common/service/context.HttpSpanHandlerWrapper.func1 \tgithub.com/pydio/cells/common/service/context/span.go:178 net/http.HandlerFunc.ServeHTTP \tnet/http/server.go:2042 github.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd.criticalErrorHandler.ServeHTTP \tgithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/generic-handlers.go:775 github.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/http.(*Server).Start.func1 \tgithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/http/server.go:115 net/http.HandlerFunc.ServeHTTP \tnet/http/server.go:2042 net/http.serverHandler.ServeHTTP \tnet/http/server.go:2843 net/http.(*conn).serve \tnet/http/server.go:1925 runtime.goexit \truntime/asm_amd64.s:1374"} dms_1 | 2021-08-18T09:32:58.724Z DEBUG pydio.gateway.data jwt rawIdToken verify: failed {"error": "{\"id\":\"\",\"code\":0,\"detail\":\"request_unauthorized\",\"status\":\"\"}"} dms_1 | 2021-08-18T09:32:58.757Z DEBUG pydio.grpc.data.index.personal ReadNode {"time": "846.1µs", "req": "Node:<Path:\"ad36a715-621e-4bb1-b0f4-8bc8a1863cb0\" > ", "resp": ""} dms_1 | 2021-08-18T09:32:58.757Z DEBUG pydio.grpc.tree ReadNode {"time": "3.3138ms", "req": "Node:<Path:\"personal/ad36a715-621e-4bb1-b0f4-8bc8a1863cb0\" MetaStore:<key:\"pydio:meta-data-source-path\" value:\"\\\"ad36a715-621e-4bb1-b0f4-8bc8a1863cb0\\\"\" > > ", "resp": ""} dms_1 | 2021-08-18T09:32:58.758Z DEBUG pydio.grpc.tree ListNodes {"time": "14.1787ms", "req": "Node:<Path:\"personal/ad36a715-621e-4bb1-b0f4-8bc8a1863cb0\" MetaStore:<key:\"pydio:meta-data-source-path\" value:\"\\\"ad36a715-621e-4bb1-b0f4-8bc8a1863cb0\\\"\" > > Ancestors:true ", "resp": {}}

[nicam]

Some more Context: https://forum.pydio.com/t/deletion-fails-when-using-pydio-cells-as-s3-storage-provider/3991

[cdujeu]

hello @nicam can you test with v3 ?

[nicam]

Hi Charles

I'll test it, I'm still on holodays this week :)

all the best

Pascal

[nicam]

Hi Charles

I wanted to give it a shot with Pydio 3.0.1. But it seems I'm not able to access the buckets anymore even when using Cyberduck, which was possible before.

What I did was: Setup pydio with the image (pydio/cells:3.0.1). Login to pydio and create a new workspace called "directus"

Give the admin user permissions to it

Create a token through the CLI

✔ This token for admin will expire on Sunday, 09-Nov-31 07:55:36 UTC

Use Cyberduck to access it

which then gives me

Did anything change regarding the tokens?

I also tried switching access key and secret access key which then gives:

[nicam]

Despite Cyberduck not being able to connect, I managed to get it working for a moment with directus directly.

Uploading images works, deletion of images does not longer throw a 500, but it doesn't delete the file either.

While trying to enable increased logging it stopped working again and now I also get the signature error from directus as well:

SignatureDoesNotMatch: The request signature we calculated does not match the signature you provided. Check your key and signing method.
cms_1                |     at Request.extractError (/directus/node_modules/aws-sdk/lib/services/s3.js:714:35)
cms_1                |     at Request.callListeners (/directus/node_modules/aws-sdk/lib/sequential_executor.js:106:20)
cms_1                |     at Request.emit (/directus/node_modules/aws-sdk/lib/sequential_executor.js:78:10)
cms_1                |     at Request.emit (/directus/node_modules/aws-sdk/lib/request.js:688:14)
cms_1                |     at Request.transition (/directus/node_modules/aws-sdk/lib/request.js:22:10)
cms_1                |     at AcceptorStateMachine.runTo (/directus/node_modules/aws-sdk/lib/state_machine.js:14:12)
cms_1                |     at /directus/node_modules/aws-sdk/lib/state_machine.js:26:10
cms_1                |     at Request.<anonymous> (/directus/node_modules/aws-sdk/lib/request.js:38:9)
cms_1                |     at Request.<anonymous> (/directus/node_modules/aws-sdk/lib/request.js:690:12)
cms_1                |     at Request.callListeners (/directus/node_modules/aws-sdk/lib/sequential_executor.js:116:18)

[cdujeu]

hello @nicam if you are still using cells, can you have a round of tests with v4 ? ;-)