CreateHome fails #2995

kulmann · 2022-01-20T09:46:06Z

Describe the bug

Sometimes ™️ the CreateHome grpc request fails on first user login. As a result the logged in user sees a Resource not found page, which is yielded by a 404 from PROPFIND on the user home.
What I noticed in the filesystem is that the following folder structure was created, with a symlink to a non-existing folder:

.
├── blobs
├── nodes
│   └── root
│       └── ddc2004c-0977-11eb-9d3f-a793888cd0f8 -> ../ddc2004c-0977-11eb-9d3f-a793888cd0f8
├── spaces
│   ├── personal
│   └── share
├── trash
└── uploads

Steps to reproduce

Steps to reproduce the behavior:

unknown, seemingly random

A hunch that I thought I had, but still couldn't reproduce it in a stable way:

delete ~/.ocis
start ocis single binary (in my case it was with a WEB_ASSET_PATH set to a locally build web): WEB_ASSET_PATH=/path/to/web/dist OCIS_INSECURE=true ./bin/ocis server
try to login via https://localhost:9200 (failing)
have a 2022/01/20 10:23:35 [ERR] mdns: Failed to bind to udp port: listen udp4 0.0.0.0:0: socket: too many open files listen udp6 [::]:0: socket: too many open files
restart ocis with same command as above
try to login again (succeeding)
see the Resource not found page as described above
see the ocis error log as quoted below

Again, I don't

Expected behavior

User home gets provisioned reliably

Actual behavior

User home sometimes doesn't get provisioned

Setup

oCIS single binary from current master at fdb2f55b77532c1ea52452664d8f7577e2bf8805

Additional context

oCIS error log

2022-01-18T10:48:44+01:00 ERR failed to create storage space error="Decomposedfs: root has no parent" pkg=rgrpc request={"name":"Admin","opaque":{"map":{"space_id":{"decoder":"plain","value":"ZGRjMjAwNGMtMDk3Ny0xMWViLTlkM2YtYTc5Mzg4OGNkMGY4"}}},"owner":{"display_name":"Admin","gid_number":30000,"groups":["users"],"id":{"idp":"https://localhost:9200","opaque_id":"ddc2004c-0977-11eb-9d3f-a793888cd0f8","type":1},"mail":"[email protected]","mail_verified":true,"opaque":{"map":{"roles":{"decoder":"json","value":"WyI3MTg4MTg4My0xNzY4LTQ2YmQtYTI0ZC1hMzU2YTJhZmRmN2YiXQ=="}}},"uid_number":20004,"username":"admin"},"type":"personal"} service=storage status={"code":15,"message":"error listing spaces","trace":"00000000000000000000000000000000"} traceid=00000000000000000000000000000000
2022-01-18T10:48:44+01:00 ERR error when calling Createhome error="gateway: grpc failed with code CODE_INTERNAL" service=proxy

OS

macOS 11.5.2
I only have 256 file descriptors configured, but then again, I'm not even sure that the too many open files mdns error is related in any way. Of course oCIS is not fully functioning when I have the error, but I'm not sure if this is the thing that leads to the error with the failing CreateHome.

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

wkloucek · 2022-01-20T10:07:44Z

Also happens on continuously deployed demo instances (eg. https://ocis.ocis-web.latest.owncloud.works/).

I did a dump of the user storage (storage-users.zip), that is similar to @kulmann s example, that can be use to reproduce the state oCIS is in after the CreateHome didn't succeed... Though it doesn't bring us futher to the answer why this happens at all.

tree ~/.ocis/storage/users/
/home/kloucek/.ocis/storage/users/
├── blobs
├── nodes
│   ├── 9bde6eee-1537-4228-a699-0a2afb6accc7
│   ├── ddc2004c-0977-11eb-9d3f-a793888cd0f8
│   └── root
│       ├── 4c510ada-c86b-4815-8820-42cdf82c3d51 -> ../4c510ada-c86b-4815-8820-42cdf82c3d51
│       └── ddc2004c-0977-11eb-9d3f-a793888cd0f8 -> ../ddc2004c-0977-11eb-9d3f-a793888cd0f8
├── spaces
│   ├── personal
│   │   └── ddc2004c-0977-11eb-9d3f-a793888cd0f8 -> ../../nodes/ddc2004c-0977-11eb-9d3f-a793888cd0f8
│   └── share
├── trash
└── uploads

12 directories, 1 file

wkloucek · 2022-01-20T10:09:35Z

@butonic can you please have a look again?

kulmann · 2022-01-20T10:23:13Z

@wkloucek did you see any too many open files log lines on the demo deployments? Would like to get a feeling if that's related or unrelated.

wkloucek · 2022-01-20T11:53:59Z

Possible fix: cs3org/reva#2457

pascalwengerter · 2022-01-24T14:48:54Z

Side note: Started the WOPI deployment example today and ran into this issue multiple times

wkloucek · 2022-01-24T15:10:11Z

Side note: Started the WOPI deployment example today and ran into this issue multiple times

which version of oCIS did you use? (if latest, could you please post your docker image digest?)

pascalwengerter · 2022-01-24T15:12:41Z

Side note: Started the WOPI deployment example today and ran into this issue multiple times

which version of oCIS did you use? (if latest, could you please post your docker image digest?)

sha256:55f2b4d71249d06d45241b83780a396eea83aa6c1d906fbbd1e5f90bf9e373e9

wkloucek · 2022-01-24T15:24:52Z

55f2b4d71249d06d45241b83780a396eea83aa6c1d906fbbd1e5f90bf9e373e9

did you start from scratch (no volumes present before) or did you have pre-existing volumes? You can check that by running docker inspect ocis_web_ocis-data (which should also be name of the volume on your side). It will stat the creation date in the CreatedAt field.

Background: It was potentially fixed in cs3org/reva#2457. It is already included in your image but if you have a old volume, the bug will be persisted forever...

pascalwengerter · 2022-01-24T15:34:18Z

55f2b4d71249d06d45241b83780a396eea83aa6c1d906fbbd1e5f90bf9e373e9

did you start from scratch (no volumes present before) or did you have pre-existing volumes? You can check that by running docker inspect ocis_web_ocis-data (which should also be name of the volume on your side). It will stat the creation date in the CreatedAt field.

Background: It was potentially fixed in cs3org/reva#2457. It is already included in your image but if you have a old volume, the bug will be persisted forever...

I thought I had removed the volumes before starting the newly pulled images, but "CreatedAt": "2021-10-14T09:50:18+02:00" suggests otherwise 🤔 weirddd

pascalwengerter · 2022-01-24T15:45:44Z

55f2b4d71249d06d45241b83780a396eea83aa6c1d906fbbd1e5f90bf9e373e9

did you start from scratch (no volumes present before) or did you have pre-existing volumes? You can check that by running docker inspect ocis_web_ocis-data (which should also be name of the volume on your side). It will stat the creation date in the CreatedAt field.

Background: It was potentially fixed in cs3org/reva#2457. It is already included in your image but if you have a old volume, the bug will be persisted forever...

Had some issues because volumes seemed not to be deleted the way I expected them to...now they're all fresh but the problem persists, yes

pascalwengerter · 2022-02-08T17:09:02Z

Just set up a new machine (and both pulled fresh docker images & compiled oCIS locally), still an issue

rpocklin · 2022-02-13T23:25:29Z

I have the issue with current owncloud/ocis:latest build (image id: 70d9f96b99e6) - seems to occur inconsistency (eg every 3 or 4th time when you provision a new docker image, even when deleting volumes).

After creating the container and logging in, (I was using admin:admin), every 3rd or 4th time the API request fails with a 404 (proxy makes request to storage-frontend which fails).

Screenshot

Error Log (in container)

{"level":"debug","service":"storage","pkg":"rgrpc","traceid":"00000000000000000000000000000000","user-agent":"grpc-go/1.44.1-dev","from":"tcp://127.0.0.1:48818","uri":"/cs3.storage.registry.v1beta1.RegistryAPI/GetStorageProviders","start":"11/Feb/2022:01:30:07 +0000","end":"11/Feb/2022:01:30:07 +0000","time_ns":103300,"code":"OK","time":"2022-02-11T01:30:07Z","message":"unary"}

{"level":"error","service":"storage","pkg":"rgrpc","traceid":"00000000000000000000000000000000","error":"Decomposedfs: root has no parent","status":{"code":15,"message":"error creating space","trace":"00000000000000000000000000000000"},"request":{"opaque":{"map":{"space_id":{"decoder":"plain","value":"ZGRjMjAwNGMtMDk3Ny0xMWViLTlkM2YtYTc5Mzg4OGNkMGY4"}}},"owner":{"id":{"idp":"https://ocis.owncloud.test","opaque_id":"ddc2004c-0977-11eb-9d3f-a793888cd0f8","type":1},"username":"admin","mail":"[email protected]","mail_verified":true,"display_name":"Admin","groups":["users"],"opaque":{"map":{"roles":{"decoder":"json","value":"WyI3MTg4MTg4My0xNzY4LTQ2YmQtYTI0ZC1hMzU2YTJhZmRmN2YiXQ=="}}},"uid_number":20004,"gid_number":30000},"type":"personal","name":"Admin"},"time":"2022-02-11T01:30:07Z","message":"failed to create storage space"}

{"level":"debug","service":"storage","pkg":"rgrpc","traceid":"00000000000000000000000000000000","user-agent":"grpc-go/1.44.1-dev","from":"tcp://127.0.0.1:43778","uri":"/cs3.storage.provider.v1beta1.ProviderAPI/CreateStorageSpace","start":"11/Feb/2022:01:30:07 +0000","end":"11/Feb/2022:01:30:07 +0000","time_ns":127600,"code":"OK","time":"2022-02-11T01:30:07Z","message":"unary"}

{"level":"debug","service":"storage","pkg":"rgrpc","traceid":"00000000000000000000000000000000","user-agent":"grpc-go/1.44.1-dev","from":"tcp://127.0.0.1:48750","uri":"/cs3.gateway.v1beta1.GatewayAPI/CreateHome","start":"11/Feb/2022:01:30:07 +0000","end":"11/Feb/2022:01:30:07 +0000","time_ns":1073000,"code":"OK","time":"2022-02-11T01:30:07Z","message":"unary"}

2022-02-11T01:30:07Z ERR error when calling Createhome error="gateway: grpc failed with code CODE_INTERNAL" service=proxy

2022-02-11T01:30:07Z DBG director found path=/remote.php/webdav/ policy=ocis prefix=/remote.php/ routeType=prefix service=proxy

{"level":"debug","service":"storage","pkg":"rhttp","traceid":"00000000000000000000000000000000","time":"2022-02-11T01:30:07Z","message":"access token is already provided"}

I did not see any error relating to too many open files in my case (running in Ubuntu under WSL2 in Windows 10).

See #3152 for original (probable duplicate) bug report.

nealey · 2022-06-07T19:09:10Z

I seem to be able to reproduce this 100% of the time if the backing filesystem is a tmpfs.

For example, with the following argument to docker run

-v /tmp/ocis/data:/var/lib/ocis

butonic · 2022-06-20T08:05:10Z

@nealey IIRC tmpfs does not support extended attributes in the user.* namespace, which is required by the decomposed filesystem ocis uses by default: https://cateee.net/lkddb/web-lkddb/TMPFS_XATTR.html Try using a different filesystem, or use a docker volume.

butonic · 2022-06-20T08:09:42Z

Reading this thread it seems to either be the default (low) ulimit on macos or conservative oses, or a filesystem without extattr support. There have also been a lot of fixes with regards to file locking and atomicity, so this should no longer be a problem. Closing. Please open a new issue if you think you are still encountering this.

kulmann added the Type:Bug label Jan 20, 2022

wkloucek added the Storage:OCIS label Jan 20, 2022

wkloucek mentioned this issue Jan 20, 2022

access ocis before docker container fully started breaks it #2964

Closed

kulmann mentioned this issue Feb 11, 2022

Webdav endpoint fails (immediately after logging in) #3152

Closed

kulmann mentioned this issue Mar 17, 2022

In e2e test Personal Page doesn't load properly (oc10) owncloud/web#6610

Closed

micbar added the Priority:p2-high Escalation, on top of current planning, release blocker label Jun 14, 2022

butonic closed this as completed Jun 20, 2022

micbar moved this to Done in Infinite Scale Team Board Dec 16, 2022

micbar added this to Infinite Scale Team Board Dec 16, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

CreateHome fails #2995

CreateHome fails #2995

kulmann commented Jan 20, 2022 •

edited

Loading

wkloucek commented Jan 20, 2022 •

edited

Loading

wkloucek commented Jan 20, 2022

kulmann commented Jan 20, 2022 •

edited

Loading

wkloucek commented Jan 20, 2022

pascalwengerter commented Jan 24, 2022

wkloucek commented Jan 24, 2022

pascalwengerter commented Jan 24, 2022

wkloucek commented Jan 24, 2022

pascalwengerter commented Jan 24, 2022

pascalwengerter commented Jan 24, 2022

pascalwengerter commented Feb 8, 2022

rpocklin commented Feb 13, 2022 •

edited

Loading

nealey commented Jun 7, 2022 •

edited

Loading

butonic commented Jun 20, 2022

butonic commented Jun 20, 2022

CreateHome fails #2995

CreateHome fails #2995

Comments

kulmann commented Jan 20, 2022 • edited Loading

Describe the bug

Steps to reproduce

Expected behavior

Actual behavior

Setup

Additional context

oCIS error log

OS

wkloucek commented Jan 20, 2022 • edited Loading

wkloucek commented Jan 20, 2022

kulmann commented Jan 20, 2022 • edited Loading

wkloucek commented Jan 20, 2022

pascalwengerter commented Jan 24, 2022

wkloucek commented Jan 24, 2022

pascalwengerter commented Jan 24, 2022

wkloucek commented Jan 24, 2022

pascalwengerter commented Jan 24, 2022

pascalwengerter commented Jan 24, 2022

pascalwengerter commented Feb 8, 2022

rpocklin commented Feb 13, 2022 • edited Loading

nealey commented Jun 7, 2022 • edited Loading

butonic commented Jun 20, 2022

butonic commented Jun 20, 2022

kulmann commented Jan 20, 2022 •

edited

Loading

wkloucek commented Jan 20, 2022 •

edited

Loading

kulmann commented Jan 20, 2022 •

edited

Loading

rpocklin commented Feb 13, 2022 •

edited

Loading

nealey commented Jun 7, 2022 •

edited

Loading