All new uploads fail to process (425 Too Early)

Gentoli commented 7 months ago

Describe the bug

After creating a new ocis deployment on k8s, uploading a folder (~16,000 files, 17GiB) to a space with windows client, part of the uploaded folder and any new upload will stuck in processing.

Steps to reproduce

create ocis with external NATS cluster
create space
copy/upload 16000 files to space (mostly files smaller than 2MB)
upload any new file

Expected behavior

Uploads does not break and can be downloaded

Actual behavior

Any upload stucks in processing (425 Too Early):

Setup

`owncloud/ocis:5.0.0-rc.2` default helm settings with: - pvc for all persistence - `nats:4222` for all nats address - security context gid/uid overwrite to `1001190000` (required by OKD/OpenShift) - s3ng with ceph rgw - tracing targeting in-memory jaeger (added after uploads stopped working for debugging)

Additional context

ocis is stuck as is, happy to run any command or tools to troubleshoot this

Some observations:

I have tried restarting all services but no improvements
looks like there are a bunch of files stuck in the storageuser pv (e.g. /var/lib/ocis/storage/users/spaces/4b/b99030-b757-45f7-8541-2dc888287070/nodes/4b/b9/90/30/-b757-45f7-8541-2dc888287070/install.sh)
no error in traces/ui for the new upload
- storage users do not have incompetence upload in list
```
/var/lib/ocis $ ocis storage-users uploads list
Incomplete uploads:
/var/lib/ocis $
```

logs

from ocdav

{"level":"error","service":"ocdav","name":"com.owncloud.web.ocdav","traceid":"180ed7d75a012876ab67fb7d2cb26cd2","request-id":"4659f8b3-512d-41e6-bfaa-5d2198277279","path":"/incomplete-pieces","spaceid":"be3a412d-1c2d-4cb0-b07a-cca0b07ed484$c78b6634-dd68-43ab-b000-af9d59ed921a","error":"rpc error: code = ResourceExhausted desc = grpc: received message larger than max (11429948 vs. 10240000)","time":"2024-03-24T10:23:01Z","line":"github.com/cs3org/reva/v2@v2.18.1-0.20240104084554-e85441869c2b/internal/http/services/owncloud/ocdav/propfind/propfind.go:753","message":"error sending list container grpc request"}

a lots of upload not found in storageusers during the initial upload of 16000 files, no error logs for new upload after. not sure if it's related to https://github.com/owncloud/ocis/issues/7026 as with only this message, I was able to download newly uploaded files
```
{"level":"error","error":"upload not found","uploadID":"fc88fa74-de2d-468a-882d-66000f400401","time":"2024-03-24T10:19:59Z","message":"Failed to get upload"}`
```

from storagesystem, looks like it's scattered around even before the initial upload

{"level":"warn","service":"storage-system","pkg":"rhttp","traceid":"82220a0336036ff28751f8468f3a167c","host":"10.105.1.159","method":"GET","uri":"/data/spaces/jsoncs3-share-manager-metadata%21jsoncs3-share-manager-metadata/users/02a8759c-ffa0-45c0-a955-546b4918137b/received.json","url":"/users/02a8759c-ffa0-45c0-a955-546b4918137b/received.json","proto":"HTTP/1.1","status":404,"size":0,"start":"24/Mar/2024:09:33:10 +0000","end":"24/Mar/2024:09:33:10 +0000","time_ns":1084890,"time":"2024-03-24T09:33:10Z","line":"github.com/cs3org/reva/v2@v2.18.1-0.20240104084554-e85441869c2b/internal/http/interceptors/log/log.go:112","message":"http"}

wkloucek commented 7 months ago

@Gentoli could you please upgrade to oCIS 5.0.0 by using the latest chart version from main branch (eg. https://github.com/owncloud/ocis-charts/commit/5ca20867637b3a5a4cc0a7ba5d9f47cb25cea28a).

You'd either want to enable the postprocessing restart cronjob: https://github.com/owncloud/ocis-charts/blob/5ca20867637b3a5a4cc0a7ba5d9f47cb25cea28a/charts/ocis/values.yaml#L1414-L1420

or run this command in a postprocessing pod: ocis postprocessing restart -s finished

Gentoli commented 7 months ago

@wkloucek

Looks like that did the trick. Do you know what can I setup to capture what caused post processing to stop?

here are some logs from post processing: initial upload

Mar 24, 2024, 05:47:24.918 {"level":"error","service":"postprocessing","error":"Error publishing message to topic: nats: timeout","time":"2024-03-24T09:47:20Z","line":"github.com/owncloud/ocis/v2/services/postprocessing/pkg/service/service.go:178","message":"unable to publish event"}
Mar 24, 2024, 06:20:38.533 nats: slow consumer, messages dropped on connection [59] for subscription on "main-queue"

after restart

Mar 26, 2024, 02:52:03.987 {"level":"error","service":"postprocessing","uploadID":"5d65701d-7f7d-4d4a-bee8-24be5b72403a","error":"Failed to delete data: nats: timeout","time":"2024-03-26T06:51:54Z","line":"github.com/owncloud/ocis/v2/services/postprocessing/pkg/service/service.go:155","message":"cannot delete upload"}

wkloucek commented 7 months ago

@Gentoli I also experienced a setup where creating / modifying streams via NACK (Nats Stream Controller Kubernetes Operator) and starting oCIS at the same time lead to open connections to NATS that were somehow not functioning. Sadly I didn't find the time yet to build a reproducer outside that special environment. Probably you ran into the same issue. Do you use NACK by any chance, too? (see also https://github.com/owncloud/ocis-charts/blob/5ca20867637b3a5a4cc0a7ba5d9f47cb25cea28a/deployments/ocis-nats/helmfile.yaml#L51-L70)

kobergj commented 7 months ago

@Gentoli are you sure the uploads were really stuck in postprocessing? If there is some "bottleneck" in postprocessing (e.g. virusscan), events might only be handled sequentially. So if 1 service needs to work off 16.000 events, and needs 2 seconds to finish one, this will take a long time. Meanwhile other uploads (also new ones) will look stuck as they are waiting for antivirus to scan them. If that is the case, the system will simply heal itself after it has finished processing all uploads.

Gentoli commented 7 months ago

@kobergj

are you sure the uploads were really stuck in postprocessing?

I think so, they are ready for postprocessing but nothing is done. The whole service uses less than 100m cpu after it got stuck and I don't have anything enabled manually. Even just before enabling the cornjob (a day after the initial upload), new uploads still fail.

Gentoli commented 7 months ago

@wkloucek

Oh, I didn't know there is an example for using external NATS.

I didn't find any documentation for how NATS should be setup for ocis. So I used the official chart for a cluster. I don't have NACK or any NATS k8s CRDs

Here is the helm values I used:

cluster:
  enabled: true
jetstream:
  enabled: true
  fileStore:
    pvc:
      enabled: true
      size: 200Gi
      storageClassName: ceph-fs-replicated-ssd
  memoryStore:
    enabled: true
    maxSize: 4Gi

wkloucek commented 7 months ago

Your values look good. The example also is using the official NATS chart.

Do I get right that you recreated all oCIS pods (eg. kubectl rollout restart deploy) and uploads are still not available immediately?

Gentoli commented 7 months ago

@wkloucek

Yes, that's what I did for the restart. I have also rolled NATS.

wkloucek commented 2 months ago

Does the problem still persist with a newer version? With 5.0.6 we are not noticing any problems on a larger installations.

micbar commented 2 months ago

Let us close here. I have no knowledge of new reports of this problem.

owncloud / ocis