ocis sometimes fails to start

[individual-it]

In nightly tests the server sometimes fails to start:
Possible errors
https://drone.owncloud.com/owncloud/ocis/9537/43/5

{"level":"fatal","service":"nats","time":"2022-02-22T01:09:20Z","message":"STREAM: Failed to start: read tcp 127.0.0.1:50472->127.0.0.1:4222: i/o timeout"}

https://drone.owncloud.com/owncloud/ocis/9537/51/5

{"level":"error","pid":9,"error":"rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 127.0.0.1:9142: connect: connection refused\"","time":"2022-02-22T01:09:36Z","message":"error registering app provider: error calling add app provider"}

{"level":"error","service":"storage","error":"unable to register services: rgrpc: error creating unary interceptor: eventsmiddleware,: error connecting to nats cluster test-cluster: stan: connect request timeout (possibly wrong cluster ID?)","time":"2022-02-22T01:09:37Z","message":"error starting the grpc server"}

[individual-it]

this night an API test fail
https://drone.owncloud.com/owncloud/ocis/9598/23/3

{"level":"error","error":"remove /srv/app/tmp/ocis/storage/metadata/nodes/root.flock: no such file or directory","time":"2022-02-24T01:12:07Z","caller":"/go/pkg/mod/github.com/cs3org/[email protected]/pkg/storage/fs/ocis/ocis.go:48","message":"could not setup tree"}

{"level":"error","service":"storage","error":"unable to register services: rgrpc: grpc service storageprovider could not be started,: could not setup tree: remove /srv/app/tmp/ocis/storage/metadata/nodes/root.flock: no such file or directory","time":"2022-02-24T01:12:07Z","message":"error starting the grpc server"}

[phil-davis]

I had similar late yesterday in PR #3226

https://drone.owncloud.com/owncloud/ocis/9590/41/5

{"level":"error","error":"remove /srv/app/tmp/ocis/storage/metadata/nodes/root.flock: no such file or directory","time":"2022-02-23T15:21:30Z","caller":"/go/pkg/mod/github.com/cs3org/[email protected]/pkg/storage/fs/ocis/ocis.go:48","message":"could not setup tree"}

{"level":"error","service":"storage","error":"http service dataprovider could not be started,: could not setup tree: remove /srv/app/tmp/ocis/storage/metadata/nodes/root.flock: no such file or directory","time":"2022-02-23T15:21:30Z","message":"error starting the http server"}

ocis did not start.

[phil-davis]

And again: https://drone.owncloud.com/owncloud/ocis/9599/27/3 (a core API test pipeline)

latest: Pulling from owncloudci/alpine
Digest: sha256:326b0ab9ec8a2fe12247b5c54e37f7afd2daa179fe7bd2a3d376b2d3139d2297
Status: Image is up to date for owncloudci/alpine:latest
+ ocis/bin/ocis server
{"level":"error","error":"remove /srv/app/tmp/ocis/storage/metadata/nodes/root.flock: no such file or directory","time":"2022-02-24T05:12:14Z","caller":"/go/pkg/mod/github.com/cs3org/[email protected]/pkg/storage/fs/ocis/ocis.go:48","message":"could not setup tree"}
{"level":"error","service":"storage","error":"http service dataprovider could not be started,: could not setup tree: remove /srv/app/tmp/ocis/storage/metadata/nodes/root.flock: no such file or directory","time":"2022-02-24T05:12:14Z","message":"error starting the http server"}

(a
And the same in pipeline https://drone.owncloud.com/owncloud/ocis/9599/37/5 a web test pipeline.

So it can happen in any of the test pipelines.

[micbar]

Fix in reva has been merged. cs3org/reva#2582

[micbar]

Fixed by #3231

[individual-it]

happened again

can't connect to nats (stan) server, retrying in 376.305592ms
{"level":"fatal","service":"nats","time":"2022-03-04T01:04:43Z","message":"STREAM: Failed to start: read tcp 127.0.0.1:53876->127.0.0.1:9233: i/o timeout"}

https://drone.owncloud.com/owncloud/ocis/9762/33/5

[nikslor]

Run into the "can't connect to nats (stan) server, retrying in xyz ms" with 1.18.0 as well.

[pascalwengerter]

Run into the "can't connect to nats (stan) server, retrying in xyz ms" with 1.18.0 as well.

Did it happen over and over again @nikslor ? I sometimes do see it once but then it seems to connect fine (in the past, I had retry logs over and over, also this issue is about oCIS crashing in CI since it can't connect to the nats service at all)

[nikslor]

Yes, with 1.18.0 I can reproduce it (at least with my setup). This is how I call ocis:

OCIS_BASE_DATA_PATH=/var/lib/ocis ACCOUNTS_DEMO_USERS_AND_GROUPS=false PROXY_HTTP_ADDR=0.0.0.0:443 OCIS_URL=https://storage.0x17.ch PROXY_TRANSPORT_TLS_KEY=/etc/letsencrypt/live/storage.0x17.ch/privkey.pem PROXY_TRANSPORT_TLS_CERT=/etc/letsencrypt/live/storage.0x17.ch/fullchain.pem OCIS_INSECURE=false PROXY_ENABLE_BASIC_AUTH=true ./ocis server

Let me know if I can help you debug the issue or give you more details.

[serzagit]

Facing a similar problem when trying to start ocis server in a 32-bit machine with debian 11.

Does anybody has an insight about what could be wrong ? Or how could I help to debug this ?

`serza@acer-debian:~$ ocis server
{"level":"error","error":"error connecting to nats cluster ocis-cluster: error connecting to nats at 127.0.0.1:9233 with tls enabled (false): nats: no servers available for connection","time":"2022-07-26T20:34:43.140539377-03:00","caller":"github.com/cs3org/reva/[email protected]/pkg/events/server/nats.go:65","message":"can't connect to nats (jetstream) server, retrying in 1.149704951s"}
{"level":"error","error":"error connecting to nats cluster ocis-cluster: error connecting to nats at 127.0.0.1:9233 with tls enabled (false): nats: no servers available for connection","time":"2022-07-26T20:34:44.039810507-03:00","caller":"github.com/cs3org/reva/[email protected]/pkg/events/server/nats.go:65","message":"can't connect to nats (jetstream) server, retrying in 1.129263415s"}
{"level":"error","error":"error connecting to nats cluster ocis-cluster: error connecting to nats at 127.0.0.1:9233 with tls enabled (false): nats: no servers available for connection","time":"2022-07-26T20:34:44.214695036-03:00","caller":"github.com/cs3org/reva/[email protected]/pkg/events/server/nats.go:65","message":"can't connect to nats (jetstream) server, retrying in 1.328811761s"}
{"level":"error","error":"error connecting to nats cluster ocis-cluster: error connecting to nats at 127.0.0.1:9233 with tls enabled (false): nats: no servers available for connection","time":"2022-07-26T20:34:44.56518388-03:00","caller":"github.com/cs3org/reva/[email protected]/pkg/events/server/nats.go:65","message":"can't connect to nats (jetstream) server, retrying in 1.553074138s"}
{"level":"error","error":"error connecting to nats cluster ocis-cluster: error connecting to nats at 127.0.0.1:9233 with tls enabled (false): nats: no servers available for connection","time":"2022-07-26T20:34:44.9237403-03:00","caller":"github.com/cs3org/reva/[email protected]/pkg/events/server/nats.go:65","message":"can't connect to nats (jetstream) server, retrying in 3.334896886s"}
{"level":"error","error":"error connecting to nats cluster ocis-cluster: error connecting to nats at 127.0.0.1:9233 with tls enabled (false): nats: no servers available for connection","time":"2022-07-26T20:34:45.688535669-03:00","caller":"github.com/cs3org/reva/[email protected]/pkg/events/server/nats.go:65","message":"can't connect to nats (jetstream) server, retrying in 3.421492733s"}
{"level":"error","error":"error connecting to nats cluster ocis-cluster: error connecting to nats at 127.0.0.1:9233 with tls enabled (false): nats: no servers available for connection","time":"2022-07-26T20:34:46.033774823-03:00","caller":"github.com/cs3org/reva/[email protected]/pkg/events/server/nats.go:65","message":"can't connect to nats (jetstream) server, retrying in 1.650862525s"}
{"level":"error","error":"error connecting to nats cluster ocis-cluster: error connecting to nats at 127.0.0.1:9233 with tls enabled (false): nats: no servers available for connection","time":"2022-07-26T20:34:46.171282742-03:00","caller":"github.com/cs3org/reva/[email protected]/pkg/events/server/nats.go:65","message":"can't connect to nats (jetstream) server, retrying in 2.312673955s"}
{"level":"error","service":"users","error":"unable to register services: rgrpc: grpc service userprovider could not be started,: Error reading LDAP CA Cert '/home/serza/.ocis/idm/ldap.crt.': open /home/serza/.ocis/idm/ldap.crt: no such file or directory","time":"2022-07-26T20:34:48.520289414-03:00","message":"error starting the grpc server"}`

[micbar]

should be fixed by #8880