oCIS can crash sometimes

[saw-jan]

Builds: https://drone.owncloud.com/owncloud/ocis/24598/54/3, https://drone.owncloud.com/owncloud/ocis/24578/54/3

2023/07/19 09:54:48 [ociswrapper] Restarting oCIS server...
panic: runtime error: invalid memory address or nil pointer dereference [recovered]
	panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x8 pc=0xe6ca98]

goroutine 474 [running]:
go.opentelemetry.io/otel/sdk/trace.(*recordingSpan).End.func1()
	/drone/src/vendor/go.opentelemetry.io/otel/sdk/trace/span.go:383 +0x2a
go.opentelemetry.io/otel/sdk/trace.(*recordingSpan).End(0xc0018b2180, {0x0, 0x0, 0xc00184de00?})
	/drone/src/vendor/go.opentelemetry.io/otel/sdk/trace/span.go:421 +0xa29
panic({0x2b82440, 0x5d99cd0})
	/usr/local/go/src/runtime/panic.go:884 +0x213
github.com/rogpeppe/go-internal/lockedfile.(*File).Close(0x0?)
	/drone/src/vendor/github.com/rogpeppe/go-internal/lockedfile/lockedfile.go:84 +0x18
github.com/cs3org/reva/v2/pkg/storage/utils/decomposedfs/metadata.MessagePackBackend.saveAttributes({{0xc001235a80?, 0x7f67ae59c488?}, {0x44b7180?, 0xc0019c63c0?}}, {0x44ae9d0?, 0xc001aba150?}, {0xc002192480, 0x75}, 0x458d92?, {0x0, ...}, ...)
	/drone/src/vendor/github.com/cs3org/reva/v2/pkg/storage/utils/decomposedfs/metadata/messagepack_backend.go:157 +0x631
github.com/cs3org/reva/v2/pkg/storage/utils/decomposedfs/metadata.MessagePackBackend.SetMultiple(...)
	/drone/src/vendor/github.com/cs3org/reva/v2/pkg/storage/utils/decomposedfs/metadata/messagepack_backend.go:119
github.com/cs3org/reva/v2/pkg/storage/utils/decomposedfs/metadata.MessagePackBackend.Set(...)
	/drone/src/vendor/github.com/cs3org/reva/v2/pkg/storage/utils/decomposedfs/metadata/messagepack_backend.go:114
github.com/cs3org/reva/v2/pkg/storage/utils/decomposedfs/node.(*Node).SetXattrString(0xc00190c630, {0x44ae9d0, 0xc001aba150}, {0x3185617, 0x10}, {0xc000480260, 0x1e})
	/drone/src/vendor/github.com/cs3org/reva/v2/pkg/storage/utils/decomposedfs/node/xattrs.go:83 +0x1b5
github.com/cs3org/reva/v2/pkg/storage/utils/decomposedfs/node.(*Node).SetTMTime(0x0?, {0x44ae9d0, 0xc001aba150}, 0xc001aba150?)
	/drone/src/vendor/github.com/cs3org/reva/v2/pkg/storage/utils/decomposedfs/node/node.go:903 +0xd0
github.com/cs3org/reva/v2/pkg/storage/utils/decomposedfs.(*Decomposedfs).Postprocessing(0xc000d9c630, 0xc0009d0fc0?)
	/drone/src/vendor/github.com/cs3org/reva/v2/pkg/storage/utils/decomposedfs/decomposedfs.go:284 +0x1558
created by github.com/cs3org/reva/v2/pkg/storage/utils/decomposedfs.New
	/drone/src/vendor/github.com/cs3org/reva/v2/pkg/storage/utils/decomposedfs/decomposedfs.go:228 +0x9e5

And leads to following wrapper error:

2023/07/19 09:54:53 [ociswrapper] Restarting oCIS server...
2023/07/19 09:54:53 [ociswrapper] os: process already finished
2023/07/19 09:54:53 http: panic serving 192.168.3.2:36858: [ociswrapper] os: process already finished
goroutine 292 [running]:
net/http.(*conn).serve.func1()
	/usr/local/go/src/net/http/server.go:1854 +0xbf
panic({0x789fe0, 0xc00010f140})
	/usr/local/go/src/runtime/panic.go:890 +0x263
log.Panic({0xc00028e980?, 0x1c?, 0x8a4da0?})
	/usr/local/go/src/log/log.go:384 +0x65
ociswrapper/log.Panic({0x8a4da0?, 0xc00007e320?})
	/drone/src/tests/ociswrapper/log/log.go:10 +0x73
ociswrapper/ocis.Stop()
	/drone/src/tests/ociswrapper/ocis/ocis.go:77 +0x45
ociswrapper/ocis.Restart(0x0)
	/drone/src/tests/ociswrapper/ocis/ocis.go:115 +0x7a
ociswrapper/wrapper/handlers.RollbackHandler({0x8a8060, 0xc0003a80e0}, 0x0?)
	/drone/src/tests/ociswrapper/wrapper/handlers/handler.go:65 +0x69
net/http.HandlerFunc.ServeHTTP(0xc000139300?, {0x8a8060?, 0xc0003a80e0?}, 0x40f92a?)
	/usr/local/go/src/net/http/server.go:2122 +0x2f
net/http.(*ServeMux).ServeHTTP(0x0?, {0x8a8060, 0xc0003a80e0}, 0xc00013f900)
	/usr/local/go/src/net/http/server.go:2500 +0x149
net/http.serverHandler.ServeHTTP({0xc000391680?}, {0x8a8060, 0xc0003a80e0}, 0xc00013f900)
	/usr/local/go/src/net/http/server.go:2936 +0x316
net/http.(*conn).serve(0xc0003a6240, {0x8a8258, 0xc0000a8fc0})
	/usr/local/go/src/net/http/server.go:1995 +0x612
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:3089 +0x5ed

Could this be due to constant restart of ocis server?

[kobergj]

Doesn't seem related to the ocis wrapper.

The first panic comes from here: https://github.com/cs3org/reva/blob/edge/pkg/storage/utils/decomposedfs/metadata/messagepack_backend.go#L154 This is a bug - it tries to close the file even in an error case which will naturally lead to a panic.

The second panic is intended from the ocis wrapper if it can't stop ocis: https://github.com/owncloud/ocis/blob/master/tests/ociswrapper/ocis/ocis.go#L77 (it can't stop ocis because it already paniced)

[saw-jan]

So then it's ocis bug that needs attention from the dev team?

[kobergj]

Yes needs attention from dev team. We need to avoid the first panic.

[2403905]

@saw-jan https://github.com/owncloud/ocis/blob/master/tests/ociswrapper/ocis/ocis.go#L77
Could we use log.Fatal() here?

[saw-jan]

@saw-jan https://github.com/owncloud/ocis/blob/master/tests/ociswrapper/ocis/ocis.go#L77 Could we use log.Fatal() here?

Yeah, we can. I think we need to just print the error message so that the set maximum retries are done.

But maybe terminating the program is a good idea so that we know that something went wrong like in this case, we found the nil pointer issue with oCIS.

@2403905 Could you clarify why log.Fatal() instead of Panic? I don't know the differences and its effects

[Salipa-Gurung]

Reoccured in 2024-01-17 https://drone.owncloud.com/owncloud/ocis/31012/31/3

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x10 pc=0x2726c1a]

goroutine 509 [running]:
github.com/owncloud/ocis/v2/services/search/pkg/search.ResolveReference({0x4500470, 0xc003513b60}, 0xc002f76480, 0x0, {0x44dc3a0?, 0xc00108a640?})
	/drone/src/services/search/pkg/search/search.go:35 +0x11a
github.com/owncloud/ocis/v2/services/search/pkg/search.(*Service).resInfo(0xc0019d46c0, 0x1?, 0x2a54c60?)
	/drone/src/services/search/pkg/search/service.go:606 +0x174
github.com/owncloud/ocis/v2/services/search/pkg/search.(*Service).MoveItem(0xc0019d46c0, 0x3200226?, 0x0?)
	/drone/src/services/search/pkg/search/service.go:585 +0x33
github.com/owncloud/ocis/v2/services/search/pkg/search.HandleEvents.func4.1()
	/drone/src/services/search/pkg/search/events.go:89 +0x699
created by github.com/owncloud/ocis/v2/services/search/pkg/search.HandleEvents.func4 in goroutine 640
	/drone/src/services/search/pkg/search/events.go:77 +0x93
2024/01/17 00:51:46 [ociswrapper] oCIS server exited with code 2
2024/01/17 00:51:46 [ociswrapper] Retry starting oCIS server... (retry 3)
{"level":"error","service":"search","error":"entity not found","Id":{"storage_id":"303bca31-6ffe-4d06-9be8-45b15bc338e7","opaque_id":"f47feca7-18be-4c84-b0b1-c385d5f0e9b8","space_id":"42f59a59-1832-4256-a741-610a3d3f6ce5"},"time":"2024-01-17T00:51:53Z","message":"failed to remove item from index"}
{"level":"error","service":"search","error":"entity not found","Id":{"storage_id":"303bca31-6ffe-4d06-9be8-45b15bc338e7","opaque_id":"d60ff399-84d6-4f6c-964c-cd46bc095971","space_id":"66099315-3c08-4044-b8b6-8ad187d83ed8"},"time":"2024-01-17T00:51:53Z","message":"failed to remove item from index"}
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x10 pc=0x2726c1a]

[kobergj]

It's a different panic. Nothing to do with the previous ones. I'll file a fix.