NumberFormatExceptions followed by "snapshot name is in use for volume ..."

[blampe]

I'm trying to setup snapshot shipping via CSI (#142) without much success. Most recently I had a flood of errors around parse failures, but there's not enough detail to figure out what it's failing to parse. I thought maybe it had something to do with my VolumeClassName ("linstor.minio") having a period in the name maybe throwing off parsing, but I was able to create another backup (from a significantly smaller volume) using the same class. This all might be a red herring...

It seems after these NumberFormatExceptions happen the system gets into a mixed up state as you can see below -- namely it tries to re-assign an existing snapshot name to a different PVC.

apiVersion: snapshot.storage.k8s.io/v1
kind: VolumeSnapshot
metadata:
  creationTimestamp: "2022-08-29T08:31:01Z"
  finalizers:
  - snapshot.storage.kubernetes.io/volumesnapshot-as-source-protection
  - snapshot.storage.kubernetes.io/volumesnapshot-bound-protection
  generateName: velero-vmsingle-vm-victoria-metrics-k8s-stack-
  generation: 1
  labels:
    velero.io/backup-name: linstor-20220829080004
  name: velero-vmsingle-vm-victoria-metrics-k8s-stack-844m6
  namespace: prometheus
  resourceVersion: "56560018"
  uid: 17660871-6cf4-4d07-8c11-8c9f5922625a
spec:
  source:
    persistentVolumeClaimName: vmsingle-vm-victoria-metrics-k8s-stack
  volumeSnapshotClassName: linstor.minio
status:
  boundVolumeSnapshotContentName: snapcontent-17660871-6cf4-4d07-8c11-8c9f5922625a
  error:
    message: 'Failed to check and update snapshot content: failed to take snapshot
      of the volume pvc-7ca5e665-9bd1-4f9d-8209-92dcb8474edf: "rpc error: code = AlreadyExists
      desc = can''t use \"snapshot-17660871-6cf4-4d07-8c11-8c9f5922625a\" for snapshot
      name for volume \"pvc-7ca5e665-9bd1-4f9d-8209-92dcb8474edf\", snapshot name
      is in use for volume \"pvc-157c3fce-5720-4ca0-ba11-e2cab638ea93\""'
    time: "2022-08-29T14:58:59Z"
  readyToUse: false

pvc-157c3fce-5720-4ca0-ba11-e2cab638ea93 is indeed another volume that was snapshotted around the same time as this one. Is there perhaps a race condition where creating multiple snapshots around the same time can cause names to not be unique?

# linstor err l

| 630C4D06-00000-000045 | 2022-08-29 13:29:19 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000046 | 2022-08-29 13:29:19 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000047 | 2022-08-29 13:30:30 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000048 | 2022-08-29 13:30:30 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000049 | 2022-08-29 13:31:19 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000050 | 2022-08-29 13:31:19 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000051 | 2022-08-29 13:38:20 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000052 | 2022-08-29 13:38:20 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000053 | 2022-08-29 13:53:45 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000054 | 2022-08-29 13:53:45 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000055 | 2022-08-29 14:00:40 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000056 | 2022-08-29 14:00:40 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000057 | 2022-08-29 14:04:54 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000058 | 2022-08-29 14:04:54 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000059 | 2022-08-29 14:08:40 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000060 | 2022-08-29 14:08:40 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000061 | 2022-08-29 14:08:41 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000062 | 2022-08-29 14:08:41 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000063 | 2022-08-29 14:16:47 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000064 | 2022-08-29 14:16:47 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000065 | 2022-08-29 14:21:52 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000066 | 2022-08-29 14:21:52 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000067 | 2022-08-29 14:26:04 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: For input string: ".2022022E4.2022022E4"              |
| 630C4D06-00000-000068 | 2022-08-29 14:28:44 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000069 | 2022-08-29 14:28:44 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000070 | 2022-08-29 14:30:09 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000071 | 2022-08-29 14:30:09 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000072 | 2022-08-29 14:31:58 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000073 | 2022-08-29 14:31:58 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000074 | 2022-08-29 14:44:20 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |
| 630C4D06-00000-000075 | 2022-08-29 14:44:20 | C|piraeus-op-cs-controller-5b8ff7f4c8-lfbk2 | NumberFormatException: multiple points                                       |

# linstor err show (multiple points)

ERROR REPORT 630C4D06-00000-000066

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

Application:                        LINBIT�� LINSTOR
Module:                             Controller
Version:                            1.19.1
Build ID:                           a758bf07796c374fd2004465b0d8690209b74356
Build time:                         2022-07-27T06:36:54+00:00
Error time:                         2022-08-29 14:21:52
Node:                               piraeus-op-cs-controller-5b8ff7f4c8-lfbk2

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

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

Category:                           RuntimeException
Class name:                         NumberFormatException
Class canonical name:               java.lang.NumberFormatException
Generated at:                       Method 'readJavaFormatString', Source file 'FloatingDecimal.java', Line #1890

Error message:                      multiple points

Call backtrace:

    Method                                   Native Class:Line number
    readJavaFormatString                     N      jdk.internal.math.FloatingDecimal:1890
    parseDouble                              N      jdk.internal.math.FloatingDecimal:110
    parseDouble                              N      java.lang.Double:543
    getDouble                                N      java.text.DigitList:169
    parse                                    N      java.text.DecimalFormat:2126
    subParse                                 N      java.text.SimpleDateFormat:1931
    parse                                    N      java.text.SimpleDateFormat:1541
    parse                                    N      java.text.DateFormat:393
    <init>                                   N      com.linbit.linstor.backupshipping.S3MetafileNameInfo:46
    listBackups                              N      com.linbit.linstor.core.apicallhandler.controller.backup.CtrlBackupApiCallHandler:679
    lambda$listBackups$0                     N      com.linbit.linstor.api.rest.v1.Backups:304
    doInScope                                N      com.linbit.linstor.api.rest.v1.RequestHelper:231
    doInScope                                N      com.linbit.linstor.api.rest.v1.RequestHelper:203
    listBackups                              N      com.linbit.linstor.api.rest.v1.Backups:298
    invoke                                   N      jdk.internal.reflect.GeneratedMethodAccessor194: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$ResponseOutInvoker:176
    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.

# linstor err show (For input string)

ERROR REPORT 630C4D06-00000-000067

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

Application:                        LINBIT�� LINSTOR
Module:                             Controller
Version:                            1.19.1
Build ID:                           a758bf07796c374fd2004465b0d8690209b74356
Build time:                         2022-07-27T06:36:54+00:00
Error time:                         2022-08-29 14:26:04
Node:                               piraeus-op-cs-controller-5b8ff7f4c8-lfbk2

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

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

Category:                           RuntimeException
Class name:                         NumberFormatException
Class canonical name:               java.lang.NumberFormatException
Generated at:                       Method 'readJavaFormatString', Source file 'FloatingDecimal.java', Line #2054

Error message:                      For input string: ".2022022E4.2022022E4"

Call backtrace:

    Method                                   Native Class:Line number
    readJavaFormatString                     N      jdk.internal.math.FloatingDecimal:2054
    parseDouble                              N      jdk.internal.math.FloatingDecimal:110
    parseDouble                              N      java.lang.Double:543
    getDouble                                N      java.text.DigitList:169
    parse                                    N      java.text.DecimalFormat:2126
    subParse                                 N      java.text.SimpleDateFormat:1931
    parse                                    N      java.text.SimpleDateFormat:1541
    parse                                    N      java.text.DateFormat:393
    <init>                                   N      com.linbit.linstor.backupshipping.S3MetafileNameInfo:46
    listBackups                              N      com.linbit.linstor.core.apicallhandler.controller.backup.CtrlBackupApiCallHandler:679
    lambda$listBackups$0                     N      com.linbit.linstor.api.rest.v1.Backups:304
    doInScope                                N      com.linbit.linstor.api.rest.v1.RequestHelper:231
    doInScope                                N      com.linbit.linstor.api.rest.v1.RequestHelper:203
    listBackups                              N      com.linbit.linstor.api.rest.v1.Backups:298
    invoke                                   N      jdk.internal.reflect.GeneratedMethodAccessor194: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$ResponseOutInvoker:176
    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.

[WanzenBug]

Weird. Since the error seems to be in listBackups (which gets called by the CSI driver on creation) I assume it's not actually about any snapshot it tries to create, but about what files already exist in the bucket. This looks like an issue that needs to be fixed upstream: https://github.com/LINBIT/linstor-server/issues

[blampe]

Running with --log-level=debug shed a little more light on this...

time="2022-09-02T02:10:03Z" level=debug msg="no snapshot matching id found, trying backups" func="github.com/piraeusdatastore/linstor-csi/pkg/client.(*Linstor).snapOrBackupById" file="/src/pkg/client/linstor.go:1367" id=snapshot-6b4f6adb-7a82-4d2f-a72c-2bc987d70dba linstorCSIComponent=client
time="2022-09-02T02:10:03Z" level=debug msg="curl -X 'GET' -H 'Accept: application/json' 'https://piraeus-op-cs.piraeus.svc:3371/v1/remotes/s3'"
time="2022-09-02T02:10:03Z" level=debug msg="listing backups in remote" func="github.com/piraeusdatastore/linstor-csi/pkg/client.(*Linstor).snapOrBackupById" file="/src/pkg/client/linstor.go:1377" id=snapshot-6b4f6adb-7a82-4d2f-a72c-2bc987d70dba linstorCSIComponent=client remote=minio
time="2022-09-02T02:10:03Z" level=debug msg="curl -X 'GET' -H 'Accept: application/json' 'https://piraeus-op-cs.piraeus.svc:3371/v1/remotes/minio/backups?snap_name=snapshot-6b4f6adb-7a82-4d2f-a72c-2bc987d70dba'"

time="2022-09-02T02:10:03Z" level=debug msg="found existing snapshot" func=github.com/piraeusdatastore/linstor-csi/pkg/driver.Driver.CreateSnapshot file="/src/pkg/driver/driver.go:965" existingSnapshot="snapshot_id:\"snapshot-dc295533-ba78-4e3f-b110-54175f1386f1\" source_volume_id:\"pvc-621a06d8-0503-4cf3-84af-d75e1bf40508\" creation_time:<seconds:1662034561 > " linstorCSIComponent=driver nodeID=pi4c provisioner=linstor.csi.linbit.com requestedSnapshotName=snapshot-1a9289d2-b984-4527-baf4-522b42908e0e requestedSnapshotSourceVolume=pvc-d2ec0c0d-f114-4fe2-9c30-a56279e356b6 version=v0.20.0-d514e41db7cdcb580769cc69f1c1ef2b8a5def5d

That last line is interesting... It queries for a backup with snap_name=snapshot-6b4f6adb-7a82-4d2f-a72c-2bc987d70dba and it gets a result... but that result is a totally different one (snapshot-dc295533-ba78-4e3f-b110-54175f1386f1) than the one it asked for?

Furthermore the snapshot returned is unrecoverable. That should at least unblock me (I can delete it), although I'm surprised it wasn't deleted/cleaned up automatically (it was totally hidden in the CLI, which is as good as deleted, anyway).

root@piraeus-op-cs-controller-5b8ff7f4c8-nqns5:/# linstor backup l minio -s snapshot-6b4f6adb-7a82-4d2f-a72c-2bc987d70dba -p
+------------------------------------------------------------------------------------------------------------------------------------+
| Resource                                 | Snapshot                                      | Finished at | Based On | Status         |
|====================================================================================================================================|
| pvc-621a06d8-0503-4cf3-84af-d75e1bf40508 | snapshot-dc295533-ba78-4e3f-b110-54175f1386f1 |             |          | Not restorable |
+------------------------------------------------------------------------------------------------------------------------------------+

What's still confusing me (and where there's maybe room for the CSI to improve) is why this UUID keeps getting recycled for so many different volumes. I know very little about CSI, but naively it seems like each snapshot request should have its own UUID, making collisions like this impossible. The only way I can see that happening is if CompatibleSnapshotId gets the same invalid name for multiple snapshots... some of my PVCs do have identical names, if that's relevant? Is there any downside to adding entropy to the fallback ID that's generated?

[blampe]

@WanzenBug take a look at LINBIT/linstor-server#314 -- the presence of any backups in the cluster completely breaks snapshotting.