Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Clone from Snapshot] CloneCommand never send #536

Open
Ornias1993 opened this issue May 19, 2024 · 28 comments
Open

[Clone from Snapshot] CloneCommand never send #536

Ornias1993 opened this issue May 19, 2024 · 28 comments
Labels
bug Something isn't working. cannot reproduce Issue is not reproducible by the maintainer org need more info More information is needed from user, need reproduction steps

Comments

@Ornias1993
Copy link

Ornias1993 commented May 19, 2024

What steps did you take and what happened:
When creating a pvc as a clone from a snapshot of another PVC, the clone command never gets send

ZFS command log:

2024-05-19.17:46:29 zfs create -o quota=274877906944 -o recordsize=64k -o dedup=off -o compression=zstd-6 -o encryption=off -o mountpoint=legacy NVME/app-pvc/pvc-b44a3c8a-4cae-4d63-aed1-fafe853f8e8b
2024-05-19.17:46:29 zfs create -o quota=1073741824 -o recordsize=64k -o dedup=off -o compression=zstd-6 -o encryption=off -o mountpoint=legacy NVME/app-pvc/pvc-176eff42-3b84-4ce6-8fe9-a06192320869
2024-05-19.17:46:52 zfs snapshot NVME/app-pvc/pvc-b44a3c8a-4cae-4d63-aed1-fafe853f8e8b@snapshot-08240c13-7fcb-4425-838d-79eacfc27407
2024-05-19.18:57:04 zfs clone NVME/app-pvc/pvc-b44a3c8a-4cae-4d63-aed1-fafe853f8e8b@snapshot-08240c13-7fcb-4425-838d-79eacfc27407 NVME/app-pvc/testclone

Notice "testclone" which was ran manually, the log never showed any attempt at running the clone command, successfull or otherwise.

What did you expect to happen:

It should at least send the clone command, failure or success regardless.

The output of the following commands will help us better understand what's going on:

  • All OpenZFS pods and containers are running, healthy, latest and able to create normal PVC defined datasets.
  • zfsvolumes cr for origin PVC is present
  • zfssnapshot cr for originPVC is present
  • zfs snapshot itself for origin PVC is present
  • zfs snapshot itself for origin PVC can be cloned manually
  • zfsvolume for targetPVC is present
  • dataset for targetPVC is missing
  • clonecommand never send

zfsvolume cr for targetPVC

Name:         pvc-095889bb-2da5-4b40-838e-d54c499b2ab0
Annotations:  <none>
API Version:  zfs.openebs.io/v1
Kind:         ZFSVolume
Spec:
  Capacity:        274877906944
  Compression:     zstd-6
  Dedup:           off
  Encryption:      off
  Fs Type:         zfs
  Owner Node ID:   ix-truenas
  Pool Name:       NVME/app-pvc
  Recordsize:      64k
  Shared:          yes
  Snapname:        pvc-b44a3c8a-4cae-4d63-aed1-fafe853f8e8b@snapshot-08240c13-7fcb-4425-838d-79eacfc27407
  Thin Provision:  yes
  Volume Type:     DATASET
Status:
  State:  Failed
Events:   <none>

volume for origin is all correct.
target and origin share the same (known-good) storageClass

Anything else you would like to add:

Everything works perfectly fine and the PVC is also created fine.
Other PVC creation works fine.
All OpenEBS pods and components are fine
volumesnapshot objects are present and fine, as-well-as ZFS snapshots.

But regardless of this, at least the clone command should've been send.

Environment:

  • Verified Latest
  • Verified Latest
  • Platform independent (tested multiple)
  • Debian/TrueNAS/and-others
@Ornias1993
Copy link
Author

Ornias1993 commented May 19, 2024

I've also noticed that the clone feature support is not tested in any way either, or at least I don't see it being ran.

That being said, with the lack of logging it's REALLY hard to bugtrace.

@tiagolobocastro
Copy link

I've also noticed that the clone feature support is not tested in any way either, or at least I don't see it being ran.

I took a few notes the other day of what should be done about lacking test for the local engines. I'll write it up on a ticket so we can track progress on addressing it.
Some e2e-test infra is also lost since archival, so that will have to be replaced somehow.

@Ornias1993
Copy link
Author

Ornias1993 commented May 20, 2024

I took a few notes the other day of what should be done about lacking test for the local engines.

Ahh good to soo activity on that!

I'll write it up on a ticket so we can track progress on addressing it.

Yes that would be great as well!

Some e2e-test infra is also lost since archival, so that will have to be replaced somehow.

I noticed, I think it might be best to fix the tests first and go from there?
If this issue is correct, it would show itself when tests get implemented anyway...


Edit/Addition

On another note is the lack of verbosity though...
Lot of errors come down to "no worky", it would be nice to at least more easily trace it back to the step in the provisioning/creation process thats failing.

@tiagolobocastro
Copy link

tiagolobocastro commented May 20, 2024

Yes that would be great as well!

I've raised openebs/openebs#3726
Hopefully more folks will pitch in, correct anything I've said wrong and provide more details.

I noticed, I think it might be best to fix the tests first and go from there? If this issue is correct, it would show itself when tests get implemented anyway...

Yes that makes sense. I'd also like to see how much of these local engines (lvm, zfs...) test we can "unify". Basic CSI etc functionality should work exactly the same, so presumably the same basic tests should apply to all?

On another note is the lack of verbosity though... Lot of errors come down to "no worky", it would be nice to at least more easily trace it back to the step in the provisioning/creation process thats failing.

So you're saying even if you increase verbosity there's nothing else being added? Maybe we can track this as an enhancement too. CC @sinhaashish

EDIT: sorry mouse slip...

@Ornias1993
Copy link
Author

On another note is the lack of verbosity though... Lot of errors come down to "no worky", it would be nice to at least more easily trace it back to the step in the provisioning/creation process thats failing.

So you're saying even if you increase verbosity there's nothing else being added? Maybe we can track this as an enhancement too. CC @sinhaashish

EDIT: sorry mouse slip...

Is there even a verbosity option?

@Ornias1993
Copy link
Author

Doubt verbosity would've helped much in this case btw, as I manually tracked the log messages through the code and it never even hit the function that should've send the zfs-clone command.

@tiagolobocastro
Copy link

Is there even a verbosity option?

sigh, sorry my mistake for making this assumption, seems there's not..

@Ornias1993
Copy link
Author

@jnels124 Can you confirm on here that you also see this behavior as well?

@w3aman
Copy link
Contributor

w3aman commented May 29, 2024

Hey @Ornias1993, I tried to reproduce this issue but it seems it is working for me. I tried on Debian 12, k8s 1.26.15, with zfs-2.1.11-1. I am able to successfully created clone out of a snapshot which was created on a thinProvisioned, and shared mount volume.

Can i get more specific details so that i can see how to reproduce this issue (what exact steps you performed, with yaml if possible)?

Logs doesn't seems to be useful here, i just see bunch of repeating following lines for different PVCs
Started PVC processing "ix-authelia/authelia-cnpg-main-1-wal No need to resize PVC "ix-wg-easy/wg-easy-config"

@Ornias1993
Copy link
Author

Ornias1993 commented May 29, 2024

Logs doesn't seems to be useful here

I've not added all logs yet, but the issue is also that there is no verbosity at all.
So the logs are, sorry to say, completely useless crap.

Those "this no worky" errors are not useable log output anyway.

i just see bunch of repeating following lines for different PVCs

Obviously this is a running system so the logs do contain things that aren't related.

Can i get more specific details so that i can see how to reproduce this issue

Primarily the use is through VolSync, so I cannot provide YAML for you.
However, I verified everything on VolSync is green, it's just waiting on the clone-from-snapshot to be created by OpenEBS. Which, obviously, never happens as it errors out

However, everything works perfectly fine, except that the PVC volsync creates throws a vague error and OpenEBS never executes the clone command. But due to the insane lack of any way of bugtracing it (because there is no verbosity anywhere), I've no way of even trying to fix it myself.

@Ornias1993
Copy link
Author

Ornias1993 commented May 29, 2024

@w3aman Can you share your way of testing this in yaml format?

@w3aman
Copy link
Contributor

w3aman commented May 29, 2024

@w3aman Can you share your way of testing this in yaml format?

I tried to replicated spec from your zfsvolume and these are my yamls (zfs_yaml.txt) and they work perfectly fine.

here is my zfsvolume for target pvc:

Name:         pvc-ef52066b-fd78-42c6-ab1f-9a08d1e94da1
Namespace:    openebs
Labels:       kubernetes.io/nodename=debian-worker
Annotations:  <none>
API Version:  zfs.openebs.io/v1
Kind:         ZFSVolume
Metadata:
  Creation Timestamp:  2024-05-29T11:46:47Z
  Finalizers:
    zfs.openebs.io/finalizer
  Generation:        2
  Resource Version:  14262
  UID:               8d15a359-1a88-440c-9c06-bd43e771ef54
Spec:
  Capacity:        2147483648
  Compression:     zstd-6
  Dedup:           off
  Fs Type:         zfs
  Owner Node ID:   debian-worker
  Pool Name:       NVME/app-pvc
  Recordsize:      64k
  Shared:          yes
  Snapname:        pvc-b56509a2-2d22-4419-b6e1-78084883aaa6@snapshot-8c0db664-5cb6-4e9f-93b1-32ff009cfdfb
  Thin Provision:  yes
  Volume Type:     DATASET
Status:
  State:  Ready
Events:   <none>```


@w3aman
Copy link
Contributor

w3aman commented May 29, 2024

Can you send me the output for this command for the node agent pod on the node ix-truenas?

kubectl logs openebs-zfs-node-[xxxx] -n openebs -c openebs-zfs-plugin | grep pvc-095889bb-2da5-4b40-838e-d54c499b2ab0

@Ornias1993
Copy link
Author

I already uploaded those logs:
https://gist.github.com/Ornias1993/991e63fbc41fd68e71a35c2f8f2e3a62

Its not my personal system, I went through a troubleshooting session with one of our users.

@Abhinandan-Purkait Abhinandan-Purkait added bug Something isn't working. need more info More information is needed from user, need reproduction steps cannot reproduce Issue is not reproducible by the maintainer org labels May 31, 2024
@jnels124
Copy link
Contributor

@Ornias1993 I do see this behavior as well. However, I am creating the snapshots with different tooling. We deploy citusdb (postgrsql extension) via stackgres. Stackgres provides the snapshotting ability.

  1. We create the snapshots in stackgres... This creates The appropriate k8s volumesnapshot resource which in turn creates the appropriate zfssnapshot resource. When restoring, the correct zfsvolume definition is created and references the snapshot. Give me some time to get some of the old logs together and provide replication steps

@jnels124
Copy link
Contributor

@Ornias1993 are you setting the openebs.io/nodeid label to something other than the node name?

@jnels124
Copy link
Contributor

jnels124 commented May 31, 2024

@Abhinandan-Purkait

In my case, I believe the issue is caused by the opens.io/nodeid being different than the nodename.

The issue appears to be with driver/controller.go and the CreateVolume method

This block is problematic. Because the value of selected in the first two blocks comes from the resource spec OwnerNodeId and in the last case selected will be the nodename.

if contentSource != nil && contentSource.GetSnapshot() != nil {
		snapshotID := contentSource.GetSnapshot().GetSnapshotId()

		selected, err = CreateSnapClone(ctx, req, snapshotID)
	} else if contentSource != nil && contentSource.GetVolume() != nil {
		srcVol := contentSource.GetVolume().GetVolumeId()
		selected, err = CreateVolClone(ctx, req, srcVol)
	} else {
		selected, err = CreateZFSVolume(ctx, req)
	}

This means that we are able to create fresh volumes correctly, but not from volume clones, or snapshot clones because a few lines down we have.

nodeid, err := zfs.GetNodeID(selected)

That method will fail when the value of selected is the OwnerNodeId. The code should be updated so that selected is populated from the correct field

@Ornias1993
Copy link
Author

@Ornias1993 are you setting the openebs.io/nodeid label to something other than the node name?

Interesting, i'm not explicitly doing that, but maybe VolSync is doing that?
Is there an issue in that label NOT being set?

@Abhinandan-Purkait
Copy link
Member

@Abhinandan-Purkait

In my case, I believe the issue is caused by the opens.io/nodeid being different than the nodename.

The issue appears to be with driver/controller.go and the CreateVolume method

This block is problematic. Because the value of selected in the first two blocks comes from the resource spec OwnerNodeId and in the last case selected will be the nodename.

if contentSource != nil && contentSource.GetSnapshot() != nil {
		snapshotID := contentSource.GetSnapshot().GetSnapshotId()

		selected, err = CreateSnapClone(ctx, req, snapshotID)
	} else if contentSource != nil && contentSource.GetVolume() != nil {
		srcVol := contentSource.GetVolume().GetVolumeId()
		selected, err = CreateVolClone(ctx, req, srcVol)
	} else {
		selected, err = CreateZFSVolume(ctx, req)
	}

This means that we are able to create fresh volumes correctly, but not from volume clones, or snapshot clones because a few lines down we have.

nodeid, err := zfs.GetNodeID(selected)

That method will fail when the value of selected is the OwnerNodeId. The code should be updated so that selected is populated from the correct field

I believe the reason for the using the OwnerNodeId is to ensure that we select the node where the parent volume's pool is present, since snapshot, restore, clone all of them need to go to the same node.

You said that the nodename is different from openebs.io/nodeid's value. From the code seems like we fetch the node before setting the topology and if that succeeds we set this to openebs.io/nodeid. Can you point out when can we end up in your situation?

node, err := k8sapi.GetNode(ns.driver.config.Nodename)
if err != nil {
  klog.Errorf("failed to get the node %s", ns.driver.config.Nodename)
  return nil, err
}

if _, ok := topology[zfs.ZFSTopologyKey]; !ok {
  topology[zfs.ZFSTopologyKey] = ns.driver.config.Nodename
}

@jnels124
Copy link
Contributor

jnels124 commented Jun 3, 2024

@Abhinandan-Purkait
We pre-label (before starting zfs components) our nodes with unique identifiers for openebs.io/nodeid and these identifiers differ from the node name. So in the snippet you provided, topology[zfs.ZFSTopologyKey] will already be set and assigned to ok and therefore will not be reassigned ns.driver.config.Nodename. See the block above the one you posted which initializes the topology map to the node labels when the allowed topologies is all as is the case in the default config and our config.

So with this configuration, I am able to create new ZFS volumes without issue. However, when you attempt to create a zfs volume from a snapshot definition it fails.

In the logs I can see failed to get the node {VALUE_OF_OPENEBS_NODEID} which highlights the issue mentioned in my previous comment. This GetNodeID method in volume.go only works when it is passed the nodename.

In the case of creating a new volume this method is called with the nodename but when it is from a volume clone or a snapshot it gets called with the value of openebs.io/nodeid. This is because this block here in driver/controller.go in the CreateVolume method:

if contentSource != nil && contentSource.GetSnapshot() != nil {
		snapshotID := contentSource.GetSnapshot().GetSnapshotId()

		selected, err = CreateSnapClone(ctx, req, snapshotID)
	} else if contentSource != nil && contentSource.GetVolume() != nil {
		srcVol := contentSource.GetVolume().GetVolumeId()
		selected, err = CreateVolClone(ctx, req, srcVol)
	} else {
		selected, err = CreateZFSVolume(ctx, req)
	}

CreateSnapClone --> returns spec.OwnerNodeId
CreateVolClone --> returns spec.OwnerNodeId
CreateZFSVolume --> returns nodename loop variable

Replication steps:

  1. Label node(s) with unique value for openebs.io/nodeid
  2. Deploy zfs components
  3. Create a pvc with zfs storage class
  4. Identify volume created successfully
  5. Create a snapshot and ensure the appropriate zfs and k8s resources exist
  6. Create a new pvc defined to be created from snapshot
  7. Notice zfs volume created and after 10 minutes goes to pending
  8. Logs will indicate unable to find node with nodeid value from the owning node

@jnels124
Copy link
Contributor

jnels124 commented Jun 3, 2024

@Ornias1993 are you setting the openebs.io/nodeid label to something other than the node name?

Interesting, i'm not explicitly doing that, but maybe VolSync is doing that? Is there an issue in that label NOT being set?

I reviewed some of your logs that i didn't see before and saw that these two values match in your case. can ignore that.

@Abhinandan-Purkait
Copy link
Member

@Abhinandan-Purkait We pre-label (before starting zfs components) our nodes with unique identifiers for openebs.io/nodeid and these identifiers differ from the node name. So in the snippet you provided, topology[zfs.ZFSTopologyKey] will already be set and assigned to ok and therefore will not be reassigned ns.driver.config.Nodename. See the block above the one you posted which initializes the topology map to the node labels when the allowed topologies is all as is the case in the default config and our config.

So with this configuration, I am able to create new ZFS volumes without issue. However, when you attempt to create a zfs volume from a snapshot definition it fails.

In the logs I can see failed to get the node {VALUE_OF_OPENEBS_NODEID} which highlights the issue mentioned in my previous comment. This GetNodeID method in volume.go only works when it is passed the nodename.

In the case of creating a new volume this method is called with the nodename but when it is from a volume clone or a snapshot it gets called with the value of openebs.io/nodeid. This is because this block here in driver/controller.go in the CreateVolume method:

if contentSource != nil && contentSource.GetSnapshot() != nil {
		snapshotID := contentSource.GetSnapshot().GetSnapshotId()

		selected, err = CreateSnapClone(ctx, req, snapshotID)
	} else if contentSource != nil && contentSource.GetVolume() != nil {
		srcVol := contentSource.GetVolume().GetVolumeId()
		selected, err = CreateVolClone(ctx, req, srcVol)
	} else {
		selected, err = CreateZFSVolume(ctx, req)
	}

CreateSnapClone --> returns spec.OwnerNodeId CreateVolClone --> returns spec.OwnerNodeId CreateZFSVolume --> returns nodename loop variable

Replication steps:

  1. Label node(s) with unique value for openebs.io/nodeid
  2. Deploy zfs components
  3. Create a pvc with zfs storage class
  4. Identify volume created successfully
  5. Create a snapshot and ensure the appropriate zfs and k8s resources exist
  6. Create a new pvc defined to be created from snapshot
  7. Notice zfs volume created and after 10 minutes goes to pending
  8. Logs will indicate unable to find node with nodeid value from the owning node

@jnels124 Thanks for explaining your use case. It moreover seems pre-labeling the node was not a part of the design and thus I feel as per current design it's not supposed to work or do you think the way it works is fundamentally wrong and needs refactoring. Can you please create an enhancement or refactoring issue and explain what can be done here so that it can be worked upon?

Having said that, there are two issues here. One is @jnels124 use case and the other reported by @Ornias1993, both of them seem to have different scope and might need different resolution.

Unfortunately we haven't been able to reproduce the latter, even with same volume specs and environment, as reported by @w3aman.

@Ornias1993
Copy link
Author

Ornias1993 commented Jun 6, 2024

Unfortunately we haven't been able to reproduce the latter, even with same volume specs and environment, as reported by @w3aman.

Yeah thats a shame for sure...
Haven't have the time to look into it further either, as we're currently putting a lot of work on moving away from OpenEBS ZFS-LocalPV due to this issue

Worth of note:
You can 100% certainly reproduce it when using VolSync and all the resources created by VolSync are 100% correct. It simply keeps waiting on OpenEBS ZFS LocalPV to clone, which never happens.


btw @Abhinandan-Purkait I still owe you an apology for my previous remark calling you an intern an incompetent. In hindsight, you shouldn't have been blamed by me solely and personally.

@Abhinandan-Purkait
Copy link
Member

Abhinandan-Purkait commented Jun 6, 2024

Haven't have the time to look into it further either, as we're currently putting a lot of work on moving away from OpenEBS ZFS-LocalPV due to this issue

That's unfortunate. Alright we can try this out with the VolSync and let you know the findings.

@Ornias1993
Copy link
Author

Haven't have the time to look into it further either, as we're currently putting a lot of work on moving away from OpenEBS ZFS-LocalPV due to this issue

That's unfortunate. Alright we can try this out with the VolSync and let you know the findings.

That would be completely awesome, thank you!
My best educated guess would be a race condition between... well... something...

I see the request being filed for the clone, but it just... well... doesn't pass through the complete codepath...
When you've some spare time, it might be worth while having some extra verbosity (flag), so we can more easily trace where in the path issues like this occur next time.

@Abhinandan-Purkait
Copy link
Member

Haven't have the time to look into it further either, as we're currently putting a lot of work on moving away from OpenEBS ZFS-LocalPV due to this issue

That's unfortunate. Alright we can try this out with the VolSync and let you know the findings.

That would be completely awesome, thank you! My best educated guess would be a race condition between... well... something...

I see the request being filed for the clone, but it just... well... doesn't pass through the complete codepath... When you've some spare time, it might be worth while having some extra verbosity (flag), so we can more easily trace where in the path issues like this occur next time.

Can you provide some information about the VolSync configuration? Like what is the replication method is being used and what is the copyMethod that is being used for that.

@Ornias1993
Copy link
Author

  • Restic, Snapshot, using the ReplicationDestination Volume Populator

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working. cannot reproduce Issue is not reproducible by the maintainer org need more info More information is needed from user, need reproduction steps
Projects
None yet
Development

No branches or pull requests

5 participants