search

LINBIT / linstor-server

High Performance Software-Defined Block Storage for container, cloud and virtualisation. Fully integrated with Docker, Kubernetes, Openstack, Proxmox etc.
https://docs.linbit.com/docs/linstor-guide/
GNU General Public License v3.0
984 stars 76 forks source link

Corruption of internal state after volume deletion #338

Closed chemicstry closed 1 year ago

chemicstry commented 1 year ago

This is a continuation of https://github.com/piraeusdatastore/piraeus-operator/issues/397.

Deleting resource definitions caused an internal state corruption with errors like Access to deleted volume. Most of the commands except few (node list) do not work.

My setup is 1 controller using k8s CRDs as storage with 3 satellites using the following piraeus-operator configuration:

etcd:
  enabled: false
operator:
  controller:
    # Store state in k8s CRDs
    dbConnectionURL: k8s
  satelliteSet:
    kernelModuleInjectionMode: None
    # This was later removed, which caused operator to attempt delete storage pool
    # with existing volumes, which might have contributed to the issue
    #
    # storagePools:
    #   lvmThinPools:
    #   - name: lvm-thin
    #     thinVolume: thinpool
    #     volumeGroup: linstor_thinpool
    #     devicePaths:
    #     - /dev/sdb
haController:
  enabled: true

Shell log leading up to the incident:

User@13600K MINGW64 /d/Dev/redacted/cloud/k3s-test
$ kubectl exec -it -n piraeus piraeus-op-cs-controller-557b5dc475-czxbh -- linstor resource list
╭──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────╮
┊ ResourceName                             ┊ Node                     ┊ Port ┊ Usage  ┊ Conns ┊    State ┊ CreatedOn           ┊
╞══════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════╡
┊ pvc-5cb38cc7-8715-4a7f-9a2f-3d11ccde7121 ┊ k3s-node1.redacted.lt ┊ 7002 ┊ Unused ┊ Ok    ┊ UpToDate ┊ 2023-01-30 01:40:42 ┊
┊ pvc-5cb38cc7-8715-4a7f-9a2f-3d11ccde7121 ┊ k3s-node2.redacted.lt ┊ 7002 ┊ Unused ┊ Ok    ┊ UpToDate ┊ 2023-01-30 01:40:43 ┊
┊ pvc-5cb38cc7-8715-4a7f-9a2f-3d11ccde7121 ┊ k3s-node3.redacted.lt ┊ 7002 ┊ Unused ┊ Ok    ┊ UpToDate ┊ 2023-01-30 01:40:39 ┊
┊ pvc-cc2085b3-b460-48f9-bd88-db0773050e4c ┊ k3s-node1.redacted.lt ┊ 7001 ┊ Unused ┊ Ok    ┊ UpToDate ┊ 2023-01-29 17:16:56 ┊
┊ pvc-cc2085b3-b460-48f9-bd88-db0773050e4c ┊ k3s-node2.redacted.lt ┊ 7001 ┊ Unused ┊ Ok    ┊ UpToDate ┊ 2023-01-29 17:16:52 ┊
┊ pvc-cc2085b3-b460-48f9-bd88-db0773050e4c ┊ k3s-node3.redacted.lt ┊ 7001 ┊ Unused ┊ Ok    ┊ UpToDate ┊ 2023-01-29 17:16:56 ┊
┊ pvc-cf0af9dc-3170-4783-a1e6-b79f7ce6d5c8 ┊ k3s-node2.redacted.lt ┊ 7000 ┊ Unused ┊ Ok    ┊ UpToDate ┊ 2023-01-29 17:10:00 ┊
╰──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────╯

User@13600K MINGW64 /d/Dev/redacted/cloud/k3s-test
$ kubectl exec -it -n piraeus piraeus-op-cs-controller-557b5dc475-czxbh -- linstor rd list
╭───────────────────────────────────────────────────────────────────────────────────────────────────╮
┊ ResourceName                             ┊ Port ┊ ResourceGroup                           ┊ State ┊
╞═══════════════════════════════════════════════════════════════════════════════════════════════════╡
┊ pvc-5cb38cc7-8715-4a7f-9a2f-3d11ccde7121 ┊ 7002 ┊ sc-980eb5bb-d263-59cb-86c4-01fced4f347d ┊ ok    ┊
┊ pvc-cc2085b3-b460-48f9-bd88-db0773050e4c ┊ 7001 ┊ sc-980eb5bb-d263-59cb-86c4-01fced4f347d ┊ ok    ┊
┊ pvc-cf0af9dc-3170-4783-a1e6-b79f7ce6d5c8 ┊ 7000 ┊ sc-d664f4a1-cc22-51ae-b4ba-7c755fb91a07 ┊ ok    ┊
╰───────────────────────────────────────────────────────────────────────────────────────────────────╯

User@13600K MINGW64 /d/Dev/redacted/cloud/k3s-test
$ kubectl exec -it -n piraeus piraeus-op-cs-controller-557b5dc475-czxbh -- linstor rd delete pvc-5cb38cc7-8715-4a7f-9a2f-3d11ccde7121
SUCCESS:
Description:
    Resource definition 'pvc-5cb38cc7-8715-4a7f-9a2f-3d11ccde7121' marked for deletion.
Details:
    Resource definition 'pvc-5cb38cc7-8715-4a7f-9a2f-3d11ccde7121' UUID is: 596d0fc2-3f55-4733-8e8f-501ea796e2db
SUCCESS:
    Resource 'pvc-5cb38cc7-8715-4a7f-9a2f-3d11ccde7121' on 'k3s-node3.redacted.lt' deleted
SUCCESS:
    Resource 'pvc-5cb38cc7-8715-4a7f-9a2f-3d11ccde7121' on 'k3s-node2.redacted.lt' deleted
SUCCESS:
    Resource 'pvc-5cb38cc7-8715-4a7f-9a2f-3d11ccde7121' on 'k3s-node1.redacted.lt' deleted
SUCCESS:
Description:
    Resource definition 'pvc-5cb38cc7-8715-4a7f-9a2f-3d11ccde7121' deleted.
Details:
    Resource definition 'pvc-5cb38cc7-8715-4a7f-9a2f-3d11ccde7121' UUID was: 596d0fc2-3f55-4733-8e8f-501ea796e2db

User@13600K MINGW64 /d/Dev/redacted/cloud/k3s-test
$ kubectl exec -it -n piraeus piraeus-op-cs-controller-557b5dc475-czxbh -- linstor r list
╭──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────╮
┊ ResourceName                             ┊ Node                     ┊ Port ┊ Usage  ┊ Conns ┊    State ┊ CreatedOn           ┊
╞══════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════╡
┊ pvc-cc2085b3-b460-48f9-bd88-db0773050e4c ┊ k3s-node1.redacted.lt ┊ 7001 ┊ Unused ┊ Ok    ┊ UpToDate ┊ 2023-01-29 17:16:56 ┊
┊ pvc-cc2085b3-b460-48f9-bd88-db0773050e4c ┊ k3s-node2.redacted.lt ┊ 7001 ┊ Unused ┊ Ok    ┊ UpToDate ┊ 2023-01-29 17:16:52 ┊
┊ pvc-cc2085b3-b460-48f9-bd88-db0773050e4c ┊ k3s-node3.redacted.lt ┊ 7001 ┊ Unused ┊ Ok    ┊ UpToDate ┊ 2023-01-29 17:16:56 ┊
┊ pvc-cf0af9dc-3170-4783-a1e6-b79f7ce6d5c8 ┊ k3s-node2.redacted.lt ┊ 7000 ┊ Unused ┊ Ok    ┊ UpToDate ┊ 2023-01-29 17:10:00 ┊
╰──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────╯

User@13600K MINGW64 /d/Dev/redacted/cloud/k3s-test
$ kubectl exec -it -n piraeus piraeus-op-cs-controller-557b5dc475-czxbh -- linstor rd delete pvc-cc2085b3-b460-48f9-bd88-db0773050e4c
SUCCESS:
Description:
    Resource definition 'pvc-cc2085b3-b460-48f9-bd88-db0773050e4c' marked for deletion.
Details:
    Resource definition 'pvc-cc2085b3-b460-48f9-bd88-db0773050e4c' UUID is: 406dbcb8-5db7-4d90-b7c1-e536723745d7
SUCCESS:
    Resource 'pvc-cc2085b3-b460-48f9-bd88-db0773050e4c' on 'k3s-node3.redacted.lt' deleted
SUCCESS:
    Resource 'pvc-cc2085b3-b460-48f9-bd88-db0773050e4c' on 'k3s-node1.redacted.lt' deleted
SUCCESS:
    Resource 'pvc-cc2085b3-b460-48f9-bd88-db0773050e4c' on 'k3s-node2.redacted.lt' deleted
SUCCESS:
Description:
    Resource definition 'pvc-cc2085b3-b460-48f9-bd88-db0773050e4c' deleted.
Details:
    Resource definition 'pvc-cc2085b3-b460-48f9-bd88-db0773050e4c' UUID was: 406dbcb8-5db7-4d90-b7c1-e536723745d7

User@13600K MINGW64 /d/Dev/redacted/cloud/k3s-test
$ kubectl exec -it -n piraeus piraeus-op-cs-controller-557b5dc475-czxbh -- linstor r list
ERROR:
    Access to deleted volume
Show reports:
    linstor error-reports show 63D6A55F-00000-003146
command terminated with exit code 10

Error report:

User@13600K MINGW64 /d/Dev/redacted/cloud/k3s-test
$ kubectl exec -it -n piraeus piraeus-op-cs-controller-557b5dc475-czxbh -- linstor error-reports show 63D6A55F-00000-003146
ERROR REPORT 63D6A55F-00000-003146

============================================================

Application:                        LINBIT�� LINSTOR
Module:                             Controller
Version:                            1.20.2
Build ID:                           58a983a5c2f49eb8d22c89b277272e6c4299457a
Build time:                         2022-12-14T14:21:28+00:00
Error time:                         2023-01-30 01:59:01
Node:                               piraeus-op-cs-controller-557b5dc475-czxbh

============================================================

Reported error:
===============

Category:                           RuntimeException
Class name:                         AccessToDeletedDataException
Class canonical name:               com.linbit.linstor.AccessToDeletedDataException
Generated at:                       Method 'checkDeleted', Source file 'AbsVolume.java', Line #110

Error message:                      Access to deleted volume

Asynchronous stage backtrace:

    Error has been observed at the following site(s):
        |_ checkpoint ? Fetch volume allocated
    Stack trace:

Call backtrace:

    Method                                   Native Class:Line number
    checkDeleted                             N      com.linbit.linstor.core.objects.AbsVolume:110

Suppressed exception 1 of 1:
===============
Category:                           RuntimeException
Class name:                         OnAssemblyException
Class canonical name:               reactor.core.publisher.FluxOnAssembly.OnAssemblyException
Generated at:                       Method 'checkDeleted', Source file 'AbsVolume.java', Line #110

Error message:
Error has been observed at the following site(s):
        |_ checkpoint ��� Fetch volume allocated
Stack trace:

Call backtrace:

    Method                                   Native Class:Line number
    checkDeleted                             N      com.linbit.linstor.core.objects.AbsVolume:110
    getResourceDefinition                    N      com.linbit.linstor.core.objects.AbsVolume:97
    lambda$hasThinVlms$8                     N      com.linbit.linstor.core.apicallhandler.controller.VlmAllocatedFetcherProto:142
    accept                                   N      java.util.stream.ReferencePipeline$3$1:195
    tryAdvance                               N      java.util.TreeMap$ValueSpliterator:2914
    accept                                   N      java.util.stream.ReferencePipeline$7$1:278
    accept                                   N      java.util.stream.ReferencePipeline$2$1:177
    accept                                   N      java.util.stream.ReferencePipeline$2$1:177
    tryAdvance                               N      java.util.TreeMap$ValueSpliterator:2914
    forEachWithCancel                        N      java.util.stream.ReferencePipeline:127
    copyIntoWithCancel                       N      java.util.stream.AbstractPipeline:502
    copyInto                                 N      java.util.stream.AbstractPipeline:488
    wrapAndCopyInto                          N      java.util.stream.AbstractPipeline:474
    evaluateSequential                       N      java.util.stream.MatchOps$MatchOp:230
    evaluateSequential                       N      java.util.stream.MatchOps$MatchOp:196
    evaluate                                 N      java.util.stream.AbstractPipeline:234
    anyMatch                                 N      java.util.stream.ReferencePipeline:528
    hasThinVlms                              N      com.linbit.linstor.core.apicallhandler.controller.VlmAllocatedFetcherProto:144
    lambda$requestVlmAllocated$2             N      com.linbit.linstor.core.apicallhandler.controller.VlmAllocatedFetcherProto:119
    accept                                   N      java.util.stream.ReferencePipeline$2$1:176
    forEachRemaining                         N      java.util.TreeMap$ValueSpliterator:2890
    copyInto                                 N      java.util.stream.AbstractPipeline:484
    wrapAndCopyInto                          N      java.util.stream.AbstractPipeline:474
    evaluateSequential                       N      java.util.stream.ReduceOps$ReduceOp:913
    evaluate                                 N      java.util.stream.AbstractPipeline:234
    collect                                  N      java.util.stream.ReferencePipeline:578
    requestVlmAllocated                      N      com.linbit.linstor.core.apicallhandler.controller.VlmAllocatedFetcherProto:123
    lambda$fetchVlmAllocated$0               N      com.linbit.linstor.core.apicallhandler.controller.VlmAllocatedFetcherProto:102
    doInScope                                N      com.linbit.linstor.core.apicallhandler.ScopeRunner:150
    lambda$fluxInScope$0                     N      com.linbit.linstor.core.apicallhandler.ScopeRunner:76
    call                                     N      reactor.core.publisher.MonoCallable:91
    trySubscribeScalarMap                    N      reactor.core.publisher.FluxFlatMap:126
    subscribeOrReturn                        N      reactor.core.publisher.MonoFlatMapMany:49
    subscribe                                N      reactor.core.publisher.Flux:8343
    onNext                                   N      reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain:188
    request                                  N      reactor.core.publisher.Operators$ScalarSubscription:2344
    onSubscribe                              N      reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain:134
    subscribe                                N      reactor.core.publisher.MonoCurrentContext:35
    subscribe                                N      reactor.core.publisher.Mono:4252
    subscribeWith                            N      reactor.core.publisher.Mono:4363
    subscribe                                N      reactor.core.publisher.Mono:4223
    subscribe                                N      reactor.core.publisher.Mono:4159
    subscribe                                N      reactor.core.publisher.Mono:4131
    doFlux                                   N      com.linbit.linstor.api.rest.v1.RequestHelper:304
    lambda$viewResources$0                   N      com.linbit.linstor.api.rest.v1.View:95
    safeAsyncResponse                        N      com.linbit.linstor.api.rest.v1.RequestHelper:324
    viewResources                            N      com.linbit.linstor.api.rest.v1.View:89
    invoke                                   N      jdk.internal.reflect.GeneratedMethodAccessor252:unknown
    invoke                                   N      jdk.internal.reflect.DelegatingMethodAccessorImpl:43
    invoke                                   N      java.lang.reflect.Method:566
    lambda$static$0                          N      org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory:52
    run                                      N      org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1:124
    invoke                                   N      org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher:167
    doDispatch                               N      org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$VoidOutInvoker:159
    dispatch                                 N      org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher:79
    invoke                                   N      org.glassfish.jersey.server.model.ResourceMethodInvoker:469
    apply                                    N      org.glassfish.jersey.server.model.ResourceMethodInvoker:391
    apply                                    N      org.glassfish.jersey.server.model.ResourceMethodInvoker:80
    run                                      N      org.glassfish.jersey.server.ServerRuntime$1:253
    call                                     N      org.glassfish.jersey.internal.Errors$1:248
    call                                     N      org.glassfish.jersey.internal.Errors$1:244
    process                                  N      org.glassfish.jersey.internal.Errors:292
    process                                  N      org.glassfish.jersey.internal.Errors:274
    process                                  N      org.glassfish.jersey.internal.Errors:244
    runInScope                               N      org.glassfish.jersey.process.internal.RequestScope:265
    process                                  N      org.glassfish.jersey.server.ServerRuntime:232
    handle                                   N      org.glassfish.jersey.server.ApplicationHandler:680
    service                                  N      org.glassfish.jersey.grizzly2.httpserver.GrizzlyHttpContainer:356
    run                                      N      org.glassfish.grizzly.http.server.HttpHandler$1:200
    doWork                                   N      org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker:569
    run                                      N      org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker:549
    run                                      N      java.lang.Thread:829

END OF ERROR REPORT.

Controller logs:

time="2023-01-29T16:57:01Z" level=info msg="running k8s-await-election" version=refs/tags/v0.3.1
I0129 16:57:01.343235       1 leaderelection.go:248] attempting to acquire leader lease piraeus/piraeus-op-cs...
I0129 16:57:01.426303       1 leaderelection.go:258] successfully acquired lease piraeus/piraeus-op-cs
time="2023-01-29T16:57:01Z" level=info msg="long live our new leader: 'piraeus-op-cs-controller-557b5dc475-czxbh'!"
time="2023-01-29T16:57:01Z" level=info msg="starting command '/usr/bin/piraeus-entry.sh' with arguments: '[startController]'"
LINSTOR, Module Controller
Version:            1.20.2 (58a983a5c2f49eb8d22c89b277272e6c4299457a)
Build time:         2022-12-14T14:21:28+00:00
Java Version:       11
Java VM:            Debian, Version 11.0.16+8-post-Debian-1deb11u1
Operating system:   Linux, Version 5.10.0-21-amd64
Environment:        amd64, 1 processors, 928 MiB memory reserved for allocations

System components initialization in progress

Loading configuration file "/etc/linstor/linstor.toml"
16:57:05.142 [main] INFO  LINSTOR/Controller - SYSTEM - ErrorReporter DB first time init.
16:57:05.146 [main] INFO  LINSTOR/Controller - SYSTEM - Log directory set to: '/var/log/linstor-controller'
16:57:05.239 [main] INFO  LINSTOR/Controller - SYSTEM - Database type is Kubernetes-CRD
16:57:05.243 [Main] INFO  LINSTOR/Controller - SYSTEM - Loading API classes started.
16:57:06.470 [Main] INFO  LINSTOR/Controller - SYSTEM - API classes loading finished: 1226ms
16:57:06.471 [Main] INFO  LINSTOR/Controller - SYSTEM - Dependency injection started.
16:57:06.506 [Main] INFO  LINSTOR/Controller - SYSTEM - Attempting dynamic load of extension module "com.linbit.linstor.modularcrypto.FipsCryptoModule"
16:57:06.525 [Main] INFO  LINSTOR/Controller - SYSTEM - Extension module "com.linbit.linstor.modularcrypto.FipsCryptoModule" is not installed
16:57:06.526 [Main] INFO  LINSTOR/Controller - SYSTEM - Attempting dynamic load of extension module "com.linbit.linstor.modularcrypto.JclCryptoModule"
16:57:06.564 [Main] INFO  LINSTOR/Controller - SYSTEM - Dynamic load of extension module "com.linbit.linstor.modularcrypto.JclCryptoModule" was successful
16:57:06.566 [Main] INFO  LINSTOR/Controller - SYSTEM - Attempting dynamic load of extension module "com.linbit.linstor.spacetracking.ControllerSpaceTrackingModule"
16:57:06.576 [Main] INFO  LINSTOR/Controller - SYSTEM - Dynamic load of extension module "com.linbit.linstor.spacetracking.ControllerSpaceTrackingModule" was successful
16:57:09.799 [Main] INFO  LINSTOR/Controller - SYSTEM - Dependency injection finished: 3328ms
16:57:09.801 [Main] INFO  LINSTOR/Controller - SYSTEM - Cryptography provider: Using default cryptography module
16:57:10.438 [Main] INFO  LINSTOR/Controller - SYSTEM - Initializing authentication subsystem
16:57:11.290 [Main] INFO  LINSTOR/Controller - SYSTEM - SpaceTracking using K8sCrd driver
16:57:11.305 [Main] INFO  LINSTOR/Controller - SYSTEM - SpaceTrackingService: Instance added as a system service
16:57:11.308 [Main] INFO  LINSTOR/Controller - SYSTEM - Starting service instance 'TimerEventService' of type TimerEventService
16:57:11.313 [Main] INFO  LINSTOR/Controller - SYSTEM - Initializing the k8s crd database connector
16:57:11.318 [Main] INFO  LINSTOR/Controller - SYSTEM - Kubernetes-CRD connection URL is "k8s"
16:58:21.680 [Main] INFO  LINSTOR/Controller - SYSTEM - Starting service instance 'K8sCrdDatabaseService' of type K8sCrdDatabaseService
16:58:21.707 [Main] INFO  LINSTOR/Controller - SYSTEM - Loading security objects
16:58:22.558 [Main] INFO  LINSTOR/Controller - SYSTEM - Current security level is NO_SECURITY
16:58:23.179 [Main] INFO  LINSTOR/Controller - SYSTEM - Core objects load from database is in progress
16:58:26.671 [Main] INFO  LINSTOR/Controller - SYSTEM - Core objects load from database completed
16:58:26.672 [Main] INFO  LINSTOR/Controller - SYSTEM - Starting service instance 'TaskScheduleService' of type TaskScheduleService
16:58:26.673 [Main] INFO  LINSTOR/Controller - SYSTEM - Initializing network communications services
16:58:26.674 [Main] WARN  LINSTOR/Controller - SYSTEM - The SSL network communication service 'DebugSslConnector' could not be started because the keyStore file (/etc/linstor/ssl/keystore.jks) is missing
16:58:26.682 [Main] INFO  LINSTOR/Controller - SYSTEM - Created network communication service 'PlainConnector'
16:58:26.682 [Main] WARN  LINSTOR/Controller - SYSTEM - The SSL network communication service 'SslConnector' could not be started because the keyStore file (/etc/linstor/ssl/keystore.jks) is missing
16:58:26.682 [Main] INFO  LINSTOR/Controller - SYSTEM - Created network communication service 'SslConnector'
16:58:26.830 [Main] INFO  LINSTOR/Controller - SYSTEM - No known nodes.
16:58:26.833 [Main] INFO  LINSTOR/Controller - SYSTEM - Starting service instance 'SpaceTrackingService' of type SpaceTrackingService
16:58:26.834 [Main] INFO  LINSTOR/Controller - SYSTEM - Starting service instance 'ScheduleBackupService' of type ScheduleBackupService
16:58:26.834 [Main] INFO  LINSTOR/Controller - SYSTEM - Starting service instance 'EbsStatusPoll' of type EbsStatusPoll
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by com.sun.xml.bind.v2.runtime.reflect.opt.Injector (file:/usr/share/linstor-server/lib/jaxb-impl-2.2.11.jar) to method java.lang.ClassLoader.defineClass(java.lang.String,byte[],int,int)
WARNING: Please consider reporting this to the maintainers of com.sun.xml.bind.v2.runtime.reflect.opt.Injector
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
Jan 29, 2023 4:58:28 PM org.glassfish.jersey.internal.Errors logErrors
WARNING: The following warnings have been detected: WARNING: A resource, Resource{"v1/action", 0 child resources, 0 resource methods, 0 sub-resource locator, 0 method handler classes, 0 method handler instances}, with path "v1/action" is empty. It has no resource (or sub resource) methods neither sub resource locators defined.

Jan 29, 2023 4:58:28 PM org.glassfish.grizzly.http.server.NetworkListener start
INFO: Started listener bound to [[::]:3370]
Jan 29, 2023 4:58:28 PM org.glassfish.grizzly.http.server.HttpServer start
INFO: [HttpServer] Started.
16:58:28.893 [Main] WARN  LINSTOR/Controller - SYSTEM - Not calling 'systemd-notify' as NOTIFY_SOCKET is null
16:58:28.893 [Main] INFO  LINSTOR/Controller - SYSTEM - Controller initialized

16:58:28.894 [TaskScheduleService] INFO  LINSTOR/Controller - SYSTEM - LogArchive: Running log archive on directory: /var/log/linstor-controller
16:58:28.898 [TaskScheduleService] INFO  LINSTOR/Controller - SYSTEM - LogArchive: No logs to archive.
17:00:27.625 [MainWorkerPool-1] INFO  LINSTOR/Controller - SYSTEM - Satellite k3s-node3.redacted.lt reports a capacity of 20926464 kiB, allocated space 0 kiB, no errors
17:00:27.690 [MainWorkerPool-1] INFO  LINSTOR/Controller - SYSTEM - Satellite k3s-node1.redacted.lt reports a capacity of 20926464 kiB, allocated space 0 kiB, no errors
17:00:27.709 [MainWorkerPool-1] INFO  LINSTOR/Controller - SYSTEM - Satellite k3s-node2.redacted.lt reports a capacity of 20926464 kiB, allocated space 0 kiB, no errors
17:00:27.731 [SpaceTrackingService] INFO  LINSTOR/Controller - SYSTEM - SpaceTracking: Aggregate capacity is 62779392 kiB, allocated space is 0 kiB, usable space is 0 kiB
17:09:56.554 [grizzly-http-server-1] INFO  LINSTOR/Controller - SYSTEM - New volume group with number '0' of resource group 'sc-d664f4a1-cc22-51ae-b4ba-7c755fb91a07' created.
17:09:57.339 [grizzly-http-server-1] INFO  LINSTOR/Controller - SYSTEM - New volume definition with number '0' of resource definition 'pvc-cf0af9dc-3170-4783-a1e6-b79f7ce6d5c8' created.
17:09:57.945 [MainWorkerPool-1] INFO  LINSTOR/Controller - SYSTEM - Drbd-auto-verify-Algo for pvc-cf0af9dc-3170-4783-a1e6-b79f7ce6d5c8 automatically set to crct10dif-pclmul
17:16:49.977 [grizzly-http-server-1] INFO  LINSTOR/Controller - SYSTEM - New volume group with number '0' of resource group 'sc-980eb5bb-d263-59cb-86c4-01fced4f347d' created.
17:16:50.675 [grizzly-http-server-1] INFO  LINSTOR/Controller - SYSTEM - New volume definition with number '0' of resource definition 'pvc-cc2085b3-b460-48f9-bd88-db0773050e4c' created.
17:16:51.140 [MainWorkerPool-1] INFO  LINSTOR/Controller - SYSTEM - Drbd-auto-verify-Algo for pvc-cc2085b3-b460-48f9-bd88-db0773050e4c automatically set to crct10dif-pclmul
01:15:01.312 [MainWorkerPool-1] INFO  LINSTOR/Controller - SYSTEM - Satellite k3s-node1.redacted.lt reports a capacity of 20926464 kiB, allocated space 4930275 kiB, no errors
01:15:01.333 [MainWorkerPool-1] INFO  LINSTOR/Controller - SYSTEM - Satellite k3s-node3.redacted.lt reports a capacity of 20926464 kiB, allocated space 4930275 kiB, no errors
01:15:01.357 [MainWorkerPool-1] INFO  LINSTOR/Controller - SYSTEM - Satellite k3s-node2.redacted.lt reports a capacity of 20926464 kiB, allocated space 8780745 kiB, no errors
01:15:01.374 [SpaceTrackingService] INFO  LINSTOR/Controller - SYSTEM - SpaceTracking: Aggregate capacity is 62779392 kiB, allocated space is 18641295 kiB, usable space is 10485760 kiB
01:23:02.455 [SslConnector] INFO  LINSTOR/Controller - SYSTEM - Remote satellite peer /5.75.254.161:3366 has closed the connection.
01:23:02.566 [grizzly-http-server-0] ERROR LINSTOR/Controller - SYSTEM - The specified storage pool 'lvm-thin' on node 'k3s-node2.redacted.lt' can not be deleted as volumes / snapshot-volumes are still using it. [Report number 63D6A55F-00000-000000]

01:23:02.647 [SslConnector] INFO  LINSTOR/Controller - SYSTEM - Remote satellite peer /65.108.250.14:3366 has closed the connection.
01:23:02.709 [grizzly-http-server-1] ERROR LINSTOR/Controller - SYSTEM - The specified storage pool 'lvm-thin' on node 'k3s-node1.redacted.lt' can not be deleted as volumes / snapshot-volumes are still using it. [Report number 63D6A55F-00000-000001]

01:23:02.745 [grizzly-http-server-0] ERROR LINSTOR/Controller - SYSTEM - The specified storage pool 'lvm-thin' on node 'k3s-node3.redacted.lt' can not be deleted as volumes / snapshot-volumes are still using it. [Report number 63D6A55F-00000-000002]

01:23:02.762 [SslConnector] INFO  LINSTOR/Controller - SYSTEM - Remote satellite peer /167.235.58.80:3366 has closed the connection.
01:25:06.213 [grizzly-http-server-0] ERROR LINSTOR/Controller - SYSTEM - The specified storage pool 'lvm-thin' on node 'k3s-node2.redacted.lt' can not be deleted as volumes / snapshot-volumes are still using it. [Report number 63D6A55F-00000-000003]

01:25:06.278 [grizzly-http-server-1] ERROR LINSTOR/Controller - SYSTEM - The specified storage pool 'lvm-thin' on node 'k3s-node1.redacted.lt' can not be deleted as volumes / snapshot-volumes are still using it. [Report number 63D6A55F-00000-000004]

01:25:06.298 [grizzly-http-server-0] ERROR LINSTOR/Controller - SYSTEM - The specified storage pool 'lvm-thin' on node 'k3s-node3.redacted.lt' can not be deleted as volumes / snapshot-volumes are still using it. [Report number 63D6A55F-00000-000005]

01:25:08.071 [grizzly-http-server-1] ERROR LINSTOR/Controller - SYSTEM - The specified storage pool 'lvm-thin' on node 'k3s-node3.redacted.lt' can not be deleted as volumes / snapshot-volumes are still using it. [Report number 63D6A55F-00000-000006]

01:25:08.087 [grizzly-http-server-0] ERROR LINSTOR/Controller - SYSTEM - The specified storage pool 'lvm-thin' on node 'k3s-node1.redacted.lt' can not be deleted as volumes / snapshot-volumes are still using it. [Report number 63D6A55F-00000-000007]

*** SAME ERROR SPAM ***

01:58:27.938 [grizzly-http-server-0] ERROR LINSTOR/Controller - SYSTEM - The specified storage pool 'lvm-thin' on node 'k3s-node3.redacted.lt' can not be deleted as volumes / snapshot-volumes are still using it. [Report number 63D6A55F-00000-003140]

01:58:29.901 [grizzly-http-server-1] ERROR LINSTOR/Controller - SYSTEM - Failure executing: POST at: https://10.43.0.1/apis/internal.linstor.linbit.com/v1/rollback. Message: rollback.internal.linstor.linbit.com "rollback" already exists. Received status: Status(apiVersion=v1, code=409, details=StatusDetails(causes=[], group=internal.linstor.linbit.com, kind=rollback, name=rollback, retryAfterSeconds=null, uid=null, additionalProperties={}), kind=Status, message=rollback.internal.linstor.linbit.com "rollback" already exists, metadata=ListMeta(_continue=null, remainingItemCount=null, resourceVersion=null, selfLink=null, additionalProperties={}), reason=AlreadyExists, status=Failure, additionalProperties={}). [Report number 63D6A55F-00000-003141]

01:58:29.911 [grizzly-http-server-0] ERROR LINSTOR/Controller - SYSTEM - Access to deleted volume [Report number 63D6A55F-00000-003142]

01:58:29.922 [grizzly-http-server-1] ERROR LINSTOR/Controller - SYSTEM - Access to deleted volume [Report number 63D6A55F-00000-003143]

01:58:35.553 [MainWorkerPool-1] ERROR LINSTOR/Controller - SYSTEM - Failure executing: POST at: https://10.43.0.1/apis/internal.linstor.linbit.com/v1-19-1/propscontainers. Message: propscontainers.internal.linstor.linbit.com "b4862cc142dd1dd1e14ab202c78539585eca8cd72e7aed98ea68059aad1d1eda" already exists. Received status: Status(apiVersion=v1, code=409, details=StatusDetails(causes=[], group=internal.linstor.linbit.com, kind=propscontainers, name=b4862cc142dd1dd1e14ab202c78539585eca8cd72e7aed98ea68059aad1d1eda, retryAfterSeconds=null, uid=null, additionalProperties={}), kind=Status, message=propscontainers.internal.linstor.linbit.com "b4862cc142dd1dd1e14ab202c78539585eca8cd72e7aed98ea68059aad1d1eda" already exists, metadata=ListMeta(_continue=null, remainingItemCount=null, resourceVersion=null, selfLink=null, additionalProperties={}), reason=AlreadyExists, status=Failure, additionalProperties={}). [Report number 63D6A55F-00000-003144]

01:58:36.075 [MainWorkerPool-1] ERROR LINSTOR/Controller - SYSTEM - Failure executing: POST at: https://10.43.0.1/apis/internal.linstor.linbit.com/v1-19-1/propscontainers. Message: propscontainers.internal.linstor.linbit.com "11b303713416bb0d18986249a26eca04edc76e86cc7b63d360e1183c85c89683" already exists. Received status: Status(apiVersion=v1, code=409, details=StatusDetails(causes=[], group=internal.linstor.linbit.com, kind=propscontainers, name=11b303713416bb0d18986249a26eca04edc76e86cc7b63d360e1183c85c89683, retryAfterSeconds=null, uid=null, additionalProperties={}), kind=Status, message=propscontainers.internal.linstor.linbit.com "11b303713416bb0d18986249a26eca04edc76e86cc7b63d360e1183c85c89683" already exists, metadata=ListMeta(_continue=null, remainingItemCount=null, resourceVersion=null, selfLink=null, additionalProperties={}), reason=AlreadyExists, status=Failure, additionalProperties={}). [Report number 63D6A55F-00000-003145]

01:58:36.080 [MainWorkerPool-1] WARN  LINSTOR/Controller - SYSTEM - RetryTask: Failed resource 'pvc-cf0af9dc-3170-4783-a1e6-b79f7ce6d5c8' of node 'k3s-node2.redacted.lt' added for retry.
01:59:01.060 [grizzly-http-server-1] ERROR LINSTOR/Controller - SYSTEM - Access to deleted volume [Report number 63D6A55F-00000-003146]

01:59:14.886 [grizzly-http-server-1] ERROR LINSTOR/Controller - SYSTEM - Access to deleted volume [Report number 63D6A55F-00000-003147]

02:01:26.695 [TaskScheduleService] ERROR LINSTOR/Controller - SYSTEM - Unhandled exception caught in com.linbit.linstor.tasks.TaskScheduleService [Report number 63D6A55F-00000-003148]

Unfortunatelly restarting the controller as suggested in https://github.com/piraeusdatastore/piraeus-operator/issues/397 did not fix the issue. First restart lead to a new error Access to deleted storage pool when calling linstor r list and second restart lead to a controller crash loop:

time="2023-01-30T13:08:49Z" level=info msg="running k8s-await-election" version=refs/tags/v0.3.1
I0130 13:08:49.400285       1 leaderelection.go:248] attempting to acquire leader lease piraeus/piraeus-op-cs...
I0130 13:08:49.452831       1 leaderelection.go:258] successfully acquired lease piraeus/piraeus-op-cs
time="2023-01-30T13:08:49Z" level=info msg="long live our new leader: 'piraeus-op-cs-controller-557b5dc475-nkgtw'!"
time="2023-01-30T13:08:49Z" level=info msg="starting command '/usr/bin/piraeus-entry.sh' with arguments: '[startController]'"
LINSTOR, Module Controller
Version:            1.20.2 (58a983a5c2f49eb8d22c89b277272e6c4299457a)
Build time:         2022-12-14T14:21:28+00:00
Java Version:       11
Java VM:            Debian, Version 11.0.16+8-post-Debian-1deb11u1
Operating system:   Linux, Version 5.10.0-21-amd64
Environment:        amd64, 1 processors, 928 MiB memory reserved for allocations
System components initialization in progress
Loading configuration file "/etc/linstor/linstor.toml"
13:08:51.545 [main] INFO  LINSTOR/Controller - SYSTEM - ErrorReporter DB first time init.
13:08:51.547 [main] INFO  LINSTOR/Controller - SYSTEM - Log directory set to: '/var/log/linstor-controller'
13:08:51.585 [main] INFO  LINSTOR/Controller - SYSTEM - Database type is Kubernetes-CRD
13:08:51.586 [Main] INFO  LINSTOR/Controller - SYSTEM - Loading API classes started.
13:08:52.382 [Main] INFO  LINSTOR/Controller - SYSTEM - API classes loading finished: 795ms
13:08:52.382 [Main] INFO  LINSTOR/Controller - SYSTEM - Dependency injection started.
13:08:52.410 [Main] INFO  LINSTOR/Controller - SYSTEM - Attempting dynamic load of extension module "com.linbit.linstor.modularcrypto.FipsCryptoModule"
13:08:52.411 [Main] INFO  LINSTOR/Controller - SYSTEM - Extension module "com.linbit.linstor.modularcrypto.FipsCryptoModule" is not installed
13:08:52.411 [Main] INFO  LINSTOR/Controller - SYSTEM - Attempting dynamic load of extension module "com.linbit.linstor.modularcrypto.JclCryptoModule"
13:08:52.421 [Main] INFO  LINSTOR/Controller - SYSTEM - Dynamic load of extension module "com.linbit.linstor.modularcrypto.JclCryptoModule" was successful
13:08:52.422 [Main] INFO  LINSTOR/Controller - SYSTEM - Attempting dynamic load of extension module "com.linbit.linstor.spacetracking.ControllerSpaceTrackingModule"
13:08:52.423 [Main] INFO  LINSTOR/Controller - SYSTEM - Dynamic load of extension module "com.linbit.linstor.spacetracking.ControllerSpaceTrackingModule" was successful
13:08:54.288 [Main] INFO  LINSTOR/Controller - SYSTEM - Dependency injection finished: 1906ms
13:08:54.289 [Main] INFO  LINSTOR/Controller - SYSTEM - Cryptography provider: Using default cryptography module
13:08:54.821 [Main] INFO  LINSTOR/Controller - SYSTEM - Initializing authentication subsystem
13:08:55.464 [Main] INFO  LINSTOR/Controller - SYSTEM - SpaceTracking using K8sCrd driver
13:08:55.468 [Main] INFO  LINSTOR/Controller - SYSTEM - SpaceTrackingService: Instance added as a system service
13:08:55.471 [Main] INFO  LINSTOR/Controller - SYSTEM - Starting service instance 'TimerEventService' of type TimerEventService
13:08:55.472 [Main] INFO  LINSTOR/Controller - SYSTEM - Initializing the k8s crd database connector
13:08:55.474 [Main] INFO  LINSTOR/Controller - SYSTEM - Kubernetes-CRD connection URL is "k8s"
13:08:57.872 [Main] INFO  LINSTOR/Controller - SYSTEM - Starting service instance 'K8sCrdDatabaseService' of type K8sCrdDatabaseService
13:08:57.893 [Main] INFO  LINSTOR/Controller - SYSTEM - Loading security objects
13:08:58.201 [Main] INFO  LINSTOR/Controller - SYSTEM - Current security level is NO_SECURITY
13:08:58.488 [Main] INFO  LINSTOR/Controller - SYSTEM - Core objects load from database is in progress
13:08:59.085 [Main] ERROR LINSTOR/Controller - SYSTEM - Problem of type 'java.lang.NullPointerException' logged to report number 63D7C162-00000-000000
13:08:59.100 [Main] ERROR LINSTOR/Controller - SYSTEM - Unhandled exception [Report number 63D7C162-00000-000001]
13:08:59.101 [Thread-2] INFO  LINSTOR/Controller - SYSTEM - Shutdown in progress
13:08:59.118 [Thread-2] INFO  LINSTOR/Controller - SYSTEM - Shutting down service instance 'EbsStatusPoll' of type EbsStatusPoll
13:08:59.119 [Thread-2] INFO  LINSTOR/Controller - SYSTEM - Waiting for service instance 'EbsStatusPoll' to complete shutdown
13:08:59.119 [Thread-2] INFO  LINSTOR/Controller - SYSTEM - Shutting down service instance 'ScheduleBackupService' of type ScheduleBackupService
13:08:59.119 [Thread-2] INFO  LINSTOR/Controller - SYSTEM - Waiting for service instance 'ScheduleBackupService' to complete shutdown
13:08:59.119 [Thread-2] INFO  LINSTOR/Controller - SYSTEM - Shutting down service instance 'SpaceTrackingService' of type SpaceTrackingService
13:08:59.120 [Thread-2] INFO  LINSTOR/Controller - SYSTEM - Waiting for service instance 'SpaceTrackingService' to complete shutdown
13:08:59.120 [Thread-2] INFO  LINSTOR/Controller - SYSTEM - Shutting down service instance 'TaskScheduleService' of type TaskScheduleService
13:08:59.121 [Thread-2] INFO  LINSTOR/Controller - SYSTEM - Waiting for service instance 'TaskScheduleService' to complete shutdown
13:08:59.122 [Thread-2] INFO  LINSTOR/Controller - SYSTEM - Shutting down service instance 'K8sCrdDatabaseService' of type K8sCrdDatabaseService
13:08:59.132 [Thread-2] INFO  LINSTOR/Controller - SYSTEM - Waiting for service instance 'K8sCrdDatabaseService' to complete shutdown
13:08:59.133 [Thread-2] INFO  LINSTOR/Controller - SYSTEM - Shutting down service instance 'TimerEventService' of type TimerEventService
13:08:59.133 [Thread-2] INFO  LINSTOR/Controller - SYSTEM - Waiting for service instance 'TimerEventService' to complete shutdown
13:08:59.134 [Thread-2] INFO  LINSTOR/Controller - SYSTEM - Shutdown complete
time="2023-01-30T13:08:59Z" level=fatal msg="failed to run" err="exit status 20"

I'm not sure how to check error reports when linstor server is in a crash loop. Are they stored in CRDs?

Let me know if there is any additional information that you need.

chemicstry commented 1 year ago

It seems that the storage pool was deleted, but volumes/resources that referenced said storage pool were still hanging in kubernetes CRDs. After manually deleting everything that had references to the storage pool I was able to bring the controller back up.

So the issue here is two fold:

chemicstry commented 1 year ago

I believe this was fixed by 1.20.3 - Fixed storage pool definition delete not checking if there are still other storage pools. There was a pending storage pool delete operation after changing piraeus-operator values, but it couldn't execute, because there were still volumes in the storage pool. However, when I deleted the 3-replica volume and there was only 1-replica volume left, the storage pool delete operation succeeded on nodes that were empty (due to a bug fixed in 1.20.3).

I will close this issue, but it would be nice to have some kind of recovery mode and not a total failure if something like this happens

raltnoeder commented 1 year ago
  • Linstor can't recover from corrupted database and crashes. I think this is a big one. I would expect controller to throw errors about corrupted database entries (i.e. resource with missing storage pool), but it should still start and load everything else that is valid.

The reason why it does not is that if a resource exists, but its entries are corrupted in LINSTOR's data, then ignoring the entries would cause more errors, e.g. because the unique minor number or node ID for DRBD resources would then be unknown to the controller, and creating new resources would reuse those numbers, causing a collision with the already in-use numbers. While such desyncs between stored data and in-memory data should not happen in the first place and require fixes in LINSTOR's code, one reason why there are no additional safeguards against corruption of the data in K8s CRD is that CRD is not a database. LINSTOR is able to use various databases, and those have many internal constraints that enforce consistency and prevent corruption, such as duplicate entries, dangling references, out of range values, or invalid data. CRD does not have these capabilities, and while it may be more convenient to use in combination with Kubernetes, the use of a real database results in much higher robustness against various sorts of corruption or inconsistency.

boedy commented 1 year ago

I've run into similar issues regarding corrupted state

LINSTOR is able to use various databases, and those have many internal constraints that enforce consistency and prevent corruption, such as duplicate entries, dangling references, out of range values, or invalid data. CRD does not have these capabilities, and while it may be more convenient to use in combination with Kubernetes, the use of a real database results in much higher robustness against various sorts of corruption or inconsistency.

Based on @raltnoeder reply. Is it recommend to use an etcd, mariadb or postgresql database for production setups?

raltnoeder commented 1 year ago

Based on @raltnoeder reply. Is it recommend to use an etcd, mariadb or postgresql database for production setups?

PostgreSQL is the most capable and well-tested, it can even run modifications of the database's structure (like adding or removing columns from a table or changing constraints) in a transaction. etcd is functionally comparable to CRD, it's not a database.