search

hpe-storage / truenas-csp

TrueNAS Container Storage Provider for HPE CSI Driver for Kubernetes
https://scod.hpedev.io
MIT License
65 stars 8 forks source link

Missing extents are not created when target exists #55

Closed kingnarmer closed 4 months ago

kingnarmer commented 7 months ago

We're currently experiencing a technical issue with the 'truenas-csp' plugin. After removing and then recreating the NFS storage class, we've encountered a problem: all NFS pods are now stuck in the 'ContainerCreating' state. The Kubernetes event log reports the following error: 'Unable to attach or mount volumes: unmounted volumes=[hpe-nfs-f1ebd7ee-b31c-4f50-a790-a5299313518a], unattached volumes=[hpe-nfs-f1ebd7ee-b31c-4f50-a790-a5299313518a]; failed to process volumes=[]: timed out waiting for the condition.'

Our working theory is that the NFS pods, created under the old storage class, are unable to locate it and, as a result, cannot start."

Not sure where to look to resolve ?

Thanks

kingnarmer commented 7 months ago

Update : I am seeing this error repeated on csp pod logs 

time="2024-01-25T18:37:23Z" level=info msg="Adding connection to CSP at IP trunas01.domain.tld, port 8080, context path , with username root and serviceName truenas-csp-svc" file="driver.go:322"
time="2024-01-25T18:37:23Z" level=info msg="About to attempt login to CSP for backend trunas01.domain.tld" file="container_storage_provider.go:108"
time="2024-01-25T18:37:35Z" level=error msg="Failed to login to CSP.  Status code: 0.  Error: Post \"http://truenas-csp-svc:8080/containers/v1/tokens\": http: ContentLength=86 with Body length 0" file="container_storage_provider.go:84"
time="2024-01-25T18:37:35Z" level=error msg="Failed to create new CSP connection from given parameters" file="driver.go:328"
time="2024-01-25T18:37:35Z" level=error msg="err: Post \"http://truenas-csp-svc:8080/containers/v1/tokens\": http: ContentLength=86 with Body length 0" file="driver.go:431"
time="2024-01-25T18:37:35Z" level=error msg="Failed to get volume tank_k8s_iscsi1_pvc-67162b91-3565-44ce-80b5-b2559f80341b, err: rpc error: code = Unavailable desc = Failed to get storage provider from secrets, Post \"http://truenas-csp-svc:8080/containers/v1/tokens\": http: ContentLength=86 with Body length 0" file="controller_server.go:808"
time="2024-01-25T18:37:35Z" level=error msg="Error controller publishing volume tank_k8s_iscsi1_pvc-67162b91-3565-44ce-80b5-b2559f80341b, err: rpc error: code = Unavailable desc = Failed to get storage provider from secrets, Post \"http://truenas-csp-svc:8080/containers/v1/tokens\": http: ContentLength=86 with Body length 0" file="controller_server.go:730"
time="2024-01-25T18:37:35Z" level=error msg="GRPC error: rpc error: code = Unavailable desc = Failed to get storage provider from secrets, Post \"http://truenas-csp-svc:8080/containers/v1/tokens\": http: ContentLength=86 with Body length 0" file="utils.go:73"

time="2024-01-25T18:40:01Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerUnpublishVolume:tank_k8s_iscsi1_pvc-67162b91-3565-44ce-80b5-b2559f80341b:33e0db71-744a-6c7e-fc7e-c2bf1bc196a6" file="utils.go:73"
time="2024-01-25T18:40:01Z" level=info msg="GRPC response: {\"publish_context\":{\"accessProtocol\":\"iscsi\",\"discoveryIps\":\"xx.xx.xx.xx\",\"fsCreateOptions\":\"\",\"fsMode\":\"0777\",\"fsOwner\":\"\",\"fsType\":\"ext4\",\"lunId\":\"0\",\"readOnly\":\"false\",\"serialNumber\":\"6589cfc000000ba4ddef8d5e7222e6d4\",\"targetNames\":\"iqn.2011-08.org.truenas.ctl:pvc-0b4865be-0fc9-40f3-a151-7193503a188c\",\"targetScope\":\"volume\",\"volumeAccessMode\":\"mount\"}}" file="utils.go:75"

`

kingnarmer commented 7 months ago

Another errors I see in csp container logs 

time="2024-01-25T18:48:33Z" level=error msg="status code was 500 Internal Server Error for request: action=PUT path=http://truenas-csp-svc:8080/containers/v1/volumes/tank_k8s_iscsi1_pvc-e2d7aaa1-e64b-4cf6-a102-286eaa025e2d/actions/publish, attempting to decode error response." file="client.go:184"
time="2024-01-25T18:48:33Z" level=error msg="HTTP error 500.  Error payload: Error code (Exception) and message (Traceback (most recent call last):\n  File \"/app/truenascsp.py\", line 213, in on_put\n    'serial_number': extent.get('naa').lstrip('0x'),\n                     ^^^^^^^^^^^^^^^^^^^^^^^^\nAttributeError: 'NoneType' object has no attribute 'lstrip'\n)" file="container_storage_provider.go:956"
time="2024-01-25T18:48:33Z" level=error msg="Failed to publish volume tank_k8s_iscsi1_pvc-e2d7aaa1-e64b-4cf6-a102-286eaa025e2d, err: Request failed with status code 500 and errors Error code (Exception) and message (Traceback (most recent call last):\n  File \"/app/truenascsp.py\", line 213, in on_put\n    'serial_number': extent.get('naa').lstrip('0x'),\n                     ^^^^^^^^^^^^^^^^^^^^^^^^\nAttributeError: 'NoneType' object has no attribute 'lstrip'\n)" file="controller_server.go:872"
time="2024-01-25T18:48:33Z" level=error msg="Error controller publishing volume tank_k8s_iscsi1_pvc-e2d7aaa1-e64b-4cf6-a102-286eaa025e2d, err: rpc error: code = Internal desc = Failed to add ACL to volume tank_k8s_iscsi1_pvc-e2d7aaa1-e64b-4cf6-a102-286eaa025e2d for node &{ dev-library0-wdc-new-worker-1a434609-jg8hm 6fc0a87c-6c6e-060f-0bfd-f169730670e1 [0xc000670440] [0xc000670480 0xc000670490] []  } via CSP, err: Request failed with status code 500 and errors Error code (Exception) and message (Traceback (most recent call last):\n  File \"/app/truenascsp.py\", line 213, in on_put\n    'serial_number': extent.get('naa').lstrip('0x'),\n                     ^^^^^^^^^^^^^^^^^^^^^^^^\nAttributeError: 'NoneType' object has no attribute 'lstrip'\n)" file="controller_server.go:730"
time="2024-01-25T18:48:33Z" level=error msg="GRPC error: rpc error: code = Internal desc = Failed to add ACL to volume tank_k8s_iscsi1_pvc-e2d7aaa1-e64b-4cf6-a102-286eaa025e2d for node &{ dev-library0-wdc-new-worker-1a434609-jg8hm 6fc0a87c-6c6e-060f-0bfd-f169730670e1 [0xc000670440] [0xc000670480 0xc000670490] []  } via CSP, err: Request failed with status code 500 and errors Error code (Exception) and message (Traceback (most recent call last):\n  File \"/app/truenascsp.py\", line 213, in on_put\n    'serial_number': extent.get('naa').lstrip('0x'),\n                     ^^^^^^^^^^^^^^^^^^^^^^^^\nAttributeError: 'NoneType' object has no attribute 'lstrip'\n)" file="utils.go:73"
kingnarmer commented 7 months ago

I confirmed I can login with secret in truenas-csp namespace.

datamattsson commented 7 months ago

What changed in the StorageClass? What is the log of the actual TrueNAS CSP? The log entries posted above are from CSI driver components.

kingnarmer commented 7 months ago

Lots of "error syncing volume" . Appreciate help , we're are hard down since morning. 

E0125 20:26:16.967760       1 controller.go:1512] delete "pvc-12252d23-78ee-4694-8597-bd4e1637e329": volume deletion failed: persistentvolume pvc-12252d23-78ee-4694-8597-bd4e1637e329 is still attached to node hostanmeA0-DC-new-worker-fa32bcba-f2dl4
W0125 20:26:16.967798       1 controller.go:989] Retrying syncing volume "pvc-12252d23-78ee-4694-8597-bd4e1637e329", failure 8
E0125 20:26:16.967818       1 controller.go:1007] error syncing volume "pvc-12252d23-78ee-4694-8597-bd4e1637e329": persistentvolume pvc-12252d23-78ee-4694-8597-bd4e1637e329 is still attached to node hostanmeA0-DC-new-worker-fa32bcba-f2dl4
I0125 20:26:16.967831       1 event.go:298] Event(v1.ObjectReference{Kind:"PersistentVolume", Namespace:"", Name:"pvc-12252d23-78ee-4694-8597-bd4e1637e329", UID:"aabccd35-e0bc-4703-94b3-14624243e440", APIVersion:"v1", ResourceVersion:"88394111", FieldPath:""}): type: 'Warning' reason: 'VolumeFailedDelete' persistentvolume pvc-12252d23-78ee-4694-8597-bd4e1637e329 is still attached to node hostanmeA0-DC-new-worker-fa32bcba-f2dl4
I0125 20:27:07.706910       1 reflector.go:788] k8s.io/client-go/informers/factory.go:150: Watch close - *v1.PersistentVolumeClaim total 2 items received
I0125 20:27:37.792953       1 reflector.go:788] sigs.k8s.io/sig-storage-lib-external-provisioner/v9/controller/controller.go:848: Watch close - *v1.StorageClass total 0 items received
I0125 20:28:43.705197       1 reflector.go:788] k8s.io/client-go/informers/factory.go:150: Watch close - *v1.VolumeAttachment total 0 items received
I0125 20:30:32.960969       1 controller.go:1151] handleProtectionFinalizer Volume : &PersistentVolume{ObjectMeta:{pvc-d9414af7-af1c-40ae-af6f-4e3e9d13487e    004886c8-137a-42e5-8755-4860c0c9db97 88393886 0 2024-01-25 18:03:56 +0000 UTC <nil> <nil> map[] map[pv.kubernetes.io/provisioned-by:csi.hpe.com volume.kubernetes.io/provisioner-deletion-secret-name:truenas-secret volume.kubernetes.io/provisioner-deletion-secret-namespace:truenas-csp] [] [kubernetes.io/pv-protection external-attacher/csi-hpe-com] [{csi-provisioner Update v1 2024-01-25 18:03:56 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{".":{},"f:pv.kubernetes.io/provisioned-by":{},"f:volume.kubernetes.io/provisioner-deletion-secret-name":{},"f:volume.kubernetes.io/provisioner-deletion-secret-namespace":{}}},"f:spec":{"f:accessModes":{},"f:capacity":{".":{},"f:storage":{}},"f:claimRef":{".":{},"f:apiVersion":{},"f:kind":{},"f:name":{},"f:namespace":{},"f:resourceVersion":{},"f:uid":{}},"f:csi":{".":{},"f:controllerExpandSecretRef":{},"f:controllerPublishSecretRef":{},"f:driver":{},"f:fsType":{},"f:nodePublishSecretRef":{},"f:nodeStageSecretRef":{},"f:volumeAttributes":{".":{},"f:allowOverrides":{},"f:compression":{},"f:csi.storage.k8s.io/pv/name":{},"f:csi.storage.k8s.io/pvc/name":{},"f:csi.storage.k8s.io/pvc/namespace":{},"f:deduplication":{},"f:description":{},"f:fsMode":{},"f:fsType":{},"f:hostEncryption":{},"f:nfsNamespace":{},"f:nfsResources":{},"f:root":{},"f:storage.kubernetes.io/csiProvisionerIdentity":{},"f:sync":{},"f:targetScope":{},"f:volblocksize":{},"f:volumeAccessMode":{}},"f:volumeHandle":{}},"f:persistentVolumeReclaimPolicy":{},"f:storageClassName":{},"f:volumeMode":{}}} } {csi-attacher Update v1 2024-01-25 18:04:06 +0000 UTC FieldsV1 {"f:metadata":{"f:finalizers":{"v:\"external-attacher/csi-hpe-com\"":{}}}} } {kube-controller-manager Update v1 2024-01-25 18:35:02 +0000 UTC FieldsV1 {"f:status":{"f:phase":{}}} status}]},Spec:PersistentVolumeSpec{Capacity:ResourceList{storage: {{16106127360 0} {<nil>} 15Gi BinarySI},},PersistentVolumeSource:PersistentVolumeSource{GCEPersistentDisk:nil,AWSElasticBlockStore:nil,HostPath:nil,Glusterfs:nil,NFS:nil,RBD:nil,ISCSI:nil,Cinder:nil,CephFS:nil,FC:nil,Flocker:nil,FlexVolume:nil,AzureFile:nil,VsphereVolume:nil,Quobyte:nil,AzureDisk:nil,PhotonPersistentDisk:nil,PortworxVolume:nil,ScaleIO:nil,Local:nil,StorageOS:nil,CSI:&CSIPersistentVolumeSource{Driver:csi.hpe.com,VolumeHandle:d9414af7-af1c-40ae-af6f-4e3e9d13487e,ReadOnly:false,FSType:ext4,VolumeAttributes:map[string]string{allowOverrides: sparse,compression,deduplication,volblocksize,sync,description,compression: LZ4,csi.storage.k8s.io/pv/name: pvc-12252d23-78ee-4694-8597-bd4e1637e329,csi.storage.k8s.io/pvc/name: hpe-nfs-d9414af7-af1c-40ae-af6f-4e3e9d13487e,csi.storage.k8s.io/pvc/namespace: truenas-csp,deduplication: OFF,description: hostanmeA0: NFS Volume provisioned by TrueNAS-CSP ,fsMode: 0777,fsType: ext4,hostEncryption: false,nfsNamespace: truenas-csp,nfsResources: true,root: tank/k8s/nfs1,storage.kubernetes.io/csiProvisionerIdentity: 1706201227379-9996-csi.hpe.com,sync: STANDARD,targetScope: volume,volblocksize: 8K,volumeAccessMode: mount,},ControllerPublishSecretRef:&SecretReference{Name:truenas-secret,Namespace:truenas-csp,},NodeStageSecretRef:&SecretReference{Name:truenas-secret,Namespace:truenas-csp,},NodePublishSecretRef:&SecretReference{Name:truenas-secret,Namespace:truenas-csp,},ControllerExpandSecretRef:&SecretReference{Name:truenas-secret,Namespace:truenas-csp,},NodeExpandSecretRef:nil,},},AccessModes:[ReadWriteMany],ClaimRef:&ObjectReference{Kind:PersistentVolumeClaim,Namespace:testing,Name:app-rwx,UID:d9414af7-af1c-40ae-af6f-4e3e9d13487e,APIVersion:v1,ResourceVersion:88340342,FieldPath:,},PersistentVolumeReclaimPolicy:Delete,StorageClassName:truenas-csp-nfs,MountOptions:[],VolumeMode:*Filesystem,NodeAffinity:nil,},Status:PersistentVolumeStatus{Phase:Released,Message:,Reason:,},}
I0125 20:30:32.961413       1 controller.go:1502] delete "pvc-d9414af7-af1c-40ae-af6f-4e3e9d13487e": started
E0125 20:30:32.967035       1 controller.go:1512] delete "pvc-d9414af7-af1c-40ae-af6f-4e3e9d13487e": volume deletion failed: persistentvolume pvc-d9414af7-af1c-40ae-af6f-4e3e9d13487e is still attached to node hostanmeA0-DC-new-worker-fa32bcba-54254
W0125 20:30:32.967176       1 controller.go:989] Retrying syncing volume "pvc-d9414af7-af1c-40ae-af6f-4e3e9d13487e", failure 9
E0125 20:30:32.967290       1 controller.go:1007] error syncing volume "pvc-d9414af7-af1c-40ae-af6f-4e3e9d13487e": persistentvolume pvc-d9414af7-af1c-40ae-af6f-4e3e9d13487e is still attached to node hostanmeA0-DC-new-worker-fa32bcba-54254
I0125 20:30:32.967208       1 event.go:298] Event(v1.ObjectReference{Kind:"PersistentVolume", Namespace:"", Name:"pvc-d9414af7-af1c-40ae-af6f-4e3e9d13487e", UID:"004886c8-137a-42e5-8755-4860c0c9db97", APIVersion:"v1", ResourceVersion:"88393886", FieldPath:""}): type: 'Warning' reason: 'VolumeFailedDelete' persistentvolume pvc-d9414af7-af1c-40ae-af6f-4e3e9d13487e is still attached to node hostanmeA0-DC-new-worker-fa32bcba-54254
I0125 20:30:32.968543       1 controller.go:1151] handleProtectionFinalizer Volume : &PersistentVolume{ObjectMeta:{pvc-12252d23-78ee-4694-8597-bd4e1637e329    aabccd35-e0bc-4703-94b3-14624243e440 88394111 0 2024-01-25 18:02:12 +0000 UTC <nil> <nil> map[nfs-parent-volume-id:d9414af7-af1c-40ae-af6f-4e3e9d13487e] map[pv.kubernetes.io/provisioned-by:csi.hpe.com volume.kubernetes.io/provisioner-deletion-secret-name:truenas-secret volume.kubernetes.io/provisioner-deletion-secret-namespace:truenas-csp] [] [kubernetes.io/pv-protection external-attacher/csi-hpe-com] [{csi-attacher Update v1 2024-01-25 18:02:12 +0000 UTC FieldsV1 {"f:metadata":{"f:finalizers":{"v:\"external-attacher/csi-hpe-com\"":{}}}} } {csi-provisioner Update v1 2024-01-25 18:02:12 +0000 UTC FieldsV1 {"f:metadata":{"f:annotations":{".":{},"f:pv.kubernetes.io/provisioned-by":{},"f:volume.kubernetes.io/provisioner-deletion-secret-name":{},"f:volume.kubernetes.io/provisioner-deletion-secret-namespace":{}}},"f:spec":{"f:accessModes":{},"f:capacity":{".":{},"f:storage":{}},"f:claimRef":{".":{},"f:apiVersion":{},"f:kind":{},"f:name":{},"f:namespace":{},"f:resourceVersion":{},"f:uid":{}},"f:csi":{".":{},"f:controllerExpandSecretRef":{},"f:controllerPublishSecretRef":{},"f:driver":{},"f:fsType":{},"f:nodePublishSecretRef":{},"f:nodeStageSecretRef":{},"f:volumeAttributes":{".":{},"f:allowOverrides":{},"f:compression":{},"f:csi.storage.k8s.io/pv/name":{},"f:csi.storage.k8s.io/pvc/name":{},"f:csi.storage.k8s.io/pvc/namespace":{},"f:deduplication":{},"f:description":{},"f:fsMode":{},"f:fsType":{},"f:hostEncryption":{},"f:nfsNamespace":{},"f:nfsPVC":{},"f:nfsResources":{},"f:root":{},"f:storage.kubernetes.io/csiProvisionerIdentity":{},"f:sync":{},"f:targetScope":{},"f:volblocksize":{},"f:volumeAccessMode":{}},"f:volumeHandle":{}},"f:persistentVolumeReclaimPolicy":{},"f:storageClassName":{},"f:volumeMode":{}}} } {csi-driver Update v1 2024-01-25 18:03:12 +0000 UTC FieldsV1 {"f:metadata":{"f:labels":{".":{},"f:nfs-parent-volume-id":{}}}} } {kube-controller-manager Update v1 2024-01-25 18:35:27 +0000 UTC FieldsV1 {"f:status":{"f:phase":{}}} status}]},Spec:PersistentVolumeSpec{Capacity:ResourceList{storage: {{16106127360 0} {<nil>} 15Gi BinarySI},},PersistentVolumeSource:PersistentVolumeSource{GCEPersistentDisk:nil,AWSElasticBlockStore:nil,HostPath:nil,Glusterfs:nil,NFS:nil,RBD:nil,ISCSI:nil,Cinder:nil,CephFS:nil,FC:nil,Flocker:nil,FlexVolume:nil,AzureFile:nil,VsphereVolume:nil,Quobyte:nil,AzureDisk:nil,PhotonPersistentDisk:nil,PortworxVolume:nil,ScaleIO:nil,Local:nil,StorageOS:nil,CSI:&CSIPersistentVolumeSource{Driver:csi.hpe.com,VolumeHandle:tank_k8s_nfs1_pvc-12252d23-78ee-4694-8597-bd4e1637e329,ReadOnly:false,FSType:ext4,VolumeAttributes:map[string]string{allowOverrides: sparse,compression,deduplication,volblocksize,sync,description,compression: LZ4,csi.storage.k8s.io/pv/name: pvc-12252d23-78ee-4694-8597-bd4e1637e329,csi.storage.k8s.io/pvc/name: hpe-nfs-d9414af7-af1c-40ae-af6f-4e3e9d13487e,csi.storage.k8s.io/pvc/namespace: truenas-csp,deduplication: OFF,description: hostanmeA0: NFS Volume provisioned by TrueNAS-CSP ,fsMode: 0777,fsType: ext4,hostEncryption: false,nfsNamespace: truenas-csp,nfsPVC: true,nfsResources: true,root: tank/k8s/nfs1,storage.kubernetes.io/csiProvisionerIdentity: 1706201227379-9996-csi.hpe.com,sync: STANDARD,targetScope: volume,volblocksize: 8K,volumeAccessMode: mount,},ControllerPublishSecretRef:&SecretReference{Name:truenas-secret,Namespace:truenas-csp,},NodeStageSecretRef:&SecretReference{Name:truenas-secret,Namespace:truenas-csp,},NodePublishSecretRef:&SecretReference{Name:truenas-secret,Namespace:truenas-csp,},ControllerExpandSecretRef:&SecretReference{Name:truenas-secret,Namespace:truenas-csp,},NodeExpandSecretRef:nil,},},AccessModes:[ReadWriteOnce],ClaimRef:&ObjectReference{Kind:PersistentVolumeClaim,Namespace:truenas-csp,Name:hpe-nfs-d9414af7-af1c-40ae-af6f-4e3e9d13487e,UID:12252d23-78ee-4694-8597-bd4e1637e329,APIVersion:v1,ResourceVersion:88376958,FieldPath:,},PersistentVolumeReclaimPolicy:Delete,StorageClassName:truenas-csp-nfs,MountOptions:[],VolumeMode:*Filesystem,NodeAffinity:nil,},Status:PersistentVolumeStatus{Phase:Released,Message:,Reason:,},}
I0125 20:30:32.968796       1 controller.go:1502] delete "pvc-12252d23-78ee-4694-8597-bd4e1637e329": started
E0125 20:30:32.976986       1 controller.go:1512] delete "pvc-12252d23-78ee-4694-8597-bd4e1637e329": volume deletion failed: persistentvolume pvc-12252d23-78ee-4694-8597-bd4e1637e329 is still attached to node hostanmeA0-DC-new-worker-fa32bcba-f2dl4
W0125 20:30:32.977029       1 controller.go:989] Retrying syncing volume "pvc-12252d23-78ee-4694-8597-bd4e1637e329", failure 9
I0125 20:30:32.977100       1 event.go:298] Event(v1.ObjectReference{Kind:"PersistentVolume", Namespace:"", Name:"pvc-12252d23-78ee-4694-8597-bd4e1637e329", UID:"aabccd35-e0bc-4703-94b3-14624243e440", APIVersion:"v1", ResourceVersion:"88394111", FieldPath:""}): type: 'Warning' reason: 'VolumeFailedDelete' persistentvolume pvc-12252d23-78ee-4694-8597-bd4e1637e329 is still attached to node hostanmeA0-DC-new-worker-fa32bcba-f2dl4
E0125 20:30:32.977228       1 controller.go:1007] error syncing volume "pvc-12252d23-78ee-4694-8597-bd4e1637e329": persistentvolume pvc-12252d23-78ee-4694-8597-bd4e1637e329 is still attached to node hostanmeA0-DC-new-worker-fa32bcba-f2dl4
I0125 20:30:48.793019       1 reflector.go:788] sigs.k8s.io/sig-storage-lib-external-provisioner/v9/controller/controller.go:845: Watch close - *v1.PersistentVolume total 5 items received
kingnarmer commented 7 months ago

Errors I see on CSP

Thu, 25 Jan 2024 21:05:48 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
  File "/app/backend.py", line 356, in delete
    self.req_backend.raise_for_status()
  File "/usr/lib/python3.11/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/988

Thu, 25 Jan 2024 21:05:48 +0000 backend INFO Volume published: tank_k8s_nfs1_pvc-b19d7518-b044-435a-aeaf-a72962ecf509
Thu, 25 Jan 2024 21:05:50 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
  File "/app/backend.py", line 356, in delete
    self.req_backend.raise_for_status()
  File "/usr/lib/python3.11/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/988

Thu, 25 Jan 2024 21:05:50 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-e6fde167-2321-44b4-8840-1b81e1cb41a6
Thu, 25 Jan 2024 21:05:51 +0000 backend ERROR Backend Request (POST) Exception: Traceback (most recent call last):
  File "/app/backend.py", line 316, in post
    self.req_backend.raise_for_status()
  File "/usr/lib/python3.11/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/extent

Thu, 25 Jan 2024 21:05:51 +0000 backend ERROR Backend Request (POST) Exception: Traceback (most recent call last):
  File "/app/backend.py", line 316, in post
    self.req_backend.raise_for_status()
  File "/usr/lib/python3.11/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/targetextent

Thu, 25 Jan 2024 21:05:51 +0000 backend ERROR Exception: Traceback (most recent call last):
  File "/app/truenascsp.py", line 213, in on_put
    'serial_number': extent.get('naa').lstrip('0x'),
                     ^^^^^^^^^^^^^^^^^^^^^^^^
AttributeError: 'NoneType' object has no attribute 'lstrip'

Thu, 25 Jan 2024 21:05:51 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
  File "/app/backend.py", line 356, in delete
    self.req_backend.raise_for_status()
  File "/usr/lib/python3.11/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/988

Thu, 25 Jan 2024 21:05:52 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-97e87f46-279d-4d00-bfe8-e19e21abda64
kingnarmer commented 7 months ago

@datamattsson the change was adding this to SC which I reverted this morning once I got "attach errors". Still not resolved. 

nfsResourceLimitsCpuM: 0m
nfsResourceLimitsMemoryMi: 0Mi
datamattsson commented 7 months ago

This is all what I see on csp .

If this is all you see, then the CSP is not being reached servicing the requests.

kingnarmer commented 7 months ago

@datamattsson this full log fo csp after pod restart 

[2024-01-25 20:59:54 +0000] [1] [INFO] Starting gunicorn 21.2.0
[2024-01-25 20:59:54 +0000] [1] [INFO] Listening at: http://0.0.0.0:8080 (1)
[2024-01-25 20:59:54 +0000] [1] [INFO] Using worker: sync
[2024-01-25 20:59:54 +0000] [7] [INFO] Booting worker with pid: 7
[2024-01-25 20:59:54 +0000] [8] [INFO] Booting worker with pid: 8
[2024-01-25 20:59:55 +0000] [9] [INFO] Booting worker with pid: 9
Thu, 25 Jan 2024 21:00:26 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:00:26 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:00:26 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:00:26 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:00:28 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-f1b92233-f674-4e74-b268-61d8f8334de0
Thu, 25 Jan 2024 21:00:28 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-05593c40-ba4d-4c74-bb64-aec666d7cba1
Thu, 25 Jan 2024 21:00:28 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-c8851c0f-ece9-4964-8e03-ceffa22d96c4
Thu, 25 Jan 2024 21:00:28 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:00:29 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-67162b91-3565-44ce-80b5-b2559f80341b
Thu, 25 Jan 2024 21:00:31 +0000 backend INFO Host updated: 6899609e-90e7-4dcc-a805-bb9ef2e5060c
Thu, 25 Jan 2024 21:00:31 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:00:32 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-b69c87dc-d7d9-4c6e-8585-e8e0ff0d2d47
Thu, 25 Jan 2024 21:00:33 +0000 backend INFO Host updated: 1a662d7a-877c-9609-56f6-39e2e125add5
Thu, 25 Jan 2024 21:00:36 +0000 backend INFO Host updated: 1a662d7a-877c-9609-56f6-39e2e125add5
Thu, 25 Jan 2024 21:00:37 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-5c4d718e-1a0a-4778-bc5d-e8d40bdb14a2
Thu, 25 Jan 2024 21:00:37 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:00:39 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:00:41 +0000 backend INFO Volume published: tank_k8s_nfs1_pvc-f1b92233-f674-4e74-b268-61d8f8334de0
Thu, 25 Jan 2024 21:00:43 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-2d406c71-0053-4acd-97c5-1949197597e0
Thu, 25 Jan 2024 21:00:46 +0000 backend INFO Volume published: tank_k8s_nfs1_pvc-05593c40-ba4d-4c74-bb64-aec666d7cba1
Thu, 25 Jan 2024 21:00:51 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-c8851c0f-ece9-4964-8e03-ceffa22d96c4
Thu, 25 Jan 2024 21:00:52 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:00:53 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-e6fde167-2321-44b4-8840-1b81e1cb41a6
Thu, 25 Jan 2024 21:00:58 +0000 backend INFO Volume unpublished: tank_k8s_nfs1_pvc-b69c87dc-d7d9-4c6e-8585-e8e0ff0d2d47
Thu, 25 Jan 2024 21:01:02 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-67162b91-3565-44ce-80b5-b2559f80341b
Thu, 25 Jan 2024 21:01:04 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-05593c40-ba4d-4c74-bb64-aec666d7cba1
Thu, 25 Jan 2024 21:01:05 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-f1b92233-f674-4e74-b268-61d8f8334de0
Thu, 25 Jan 2024 21:01:05 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:01:06 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:01:07 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-97e87f46-279d-4d00-bfe8-e19e21abda64
Thu, 25 Jan 2024 21:01:09 +0000 backend INFO Volume unpublished: tank_k8s_iscsi1_pvc-5c4d718e-1a0a-4778-bc5d-e8d40bdb14a2
Thu, 25 Jan 2024 21:01:11 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:01:11 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:01:13 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-a2ca4050-3517-4eb9-b372-44b226581d4c
Thu, 25 Jan 2024 21:01:14 +0000 backend INFO Host updated: 1a662d7a-877c-9609-56f6-39e2e125add5
Thu, 25 Jan 2024 21:01:15 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-67162b91-3565-44ce-80b5-b2559f80341b
Thu, 25 Jan 2024 21:01:17 +0000 backend INFO Host updated: 6899609e-90e7-4dcc-a805-bb9ef2e5060c
Thu, 25 Jan 2024 21:01:18 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-c8851c0f-ece9-4964-8e03-ceffa22d96c4
Thu, 25 Jan 2024 21:01:19 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-2d406c71-0053-4acd-97c5-1949197597e0
Thu, 25 Jan 2024 21:01:19 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-b69c87dc-d7d9-4c6e-8585-e8e0ff0d2d47
Thu, 25 Jan 2024 21:01:20 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:01:21 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-27fd2b27-f008-4370-aa92-0aebd8cf04fe
Thu, 25 Jan 2024 21:01:22 +0000 backend INFO Host updated: 5d4a82d5-5fdc-9a53-e6b6-270b5615541e
Thu, 25 Jan 2024 21:01:25 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-e6fde167-2321-44b4-8840-1b81e1cb41a6
Thu, 25 Jan 2024 21:01:26 +0000 backend INFO Host updated: 2480ad62-17e9-25d0-607b-f314b8416e6e
Thu, 25 Jan 2024 21:01:29 +0000 backend INFO Volume published: tank_k8s_nfs1_pvc-05593c40-ba4d-4c74-bb64-aec666d7cba1
Thu, 25 Jan 2024 21:01:31 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:01:31 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:01:32 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-b69c87dc-d7d9-4c6e-8585-e8e0ff0d2d47
Thu, 25 Jan 2024 21:01:34 +0000 backend INFO Volume published: tank_k8s_nfs1_pvc-f1b92233-f674-4e74-b268-61d8f8334de0
Thu, 25 Jan 2024 21:01:35 +0000 backend INFO Host updated: 1a662d7a-877c-9609-56f6-39e2e125add5
Thu, 25 Jan 2024 21:01:38 +0000 backend INFO Host updated: 1a662d7a-877c-9609-56f6-39e2e125add5
Thu, 25 Jan 2024 21:01:40 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-97e87f46-279d-4d00-bfe8-e19e21abda64
Thu, 25 Jan 2024 21:01:40 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:01:42 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-5c4d718e-1a0a-4778-bc5d-e8d40bdb14a2
Thu, 25 Jan 2024 21:01:42 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-a2ca4050-3517-4eb9-b372-44b226581d4c
Thu, 25 Jan 2024 21:01:45 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-67162b91-3565-44ce-80b5-b2559f80341b
Thu, 25 Jan 2024 21:01:47 +0000 backend INFO Host updated: d2e212fc-18fe-3aae-d38d-8b727ab99d9b
Thu, 25 Jan 2024 21:01:48 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-d5cb5c35-091d-46b7-80ea-a231b5297ba2
Thu, 25 Jan 2024 21:01:49 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:01:50 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-5c4d718e-1a0a-4778-bc5d-e8d40bdb14a2
Thu, 25 Jan 2024 21:01:50 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-c8851c0f-ece9-4964-8e03-ceffa22d96c4
Thu, 25 Jan 2024 21:01:52 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-e6fde167-2321-44b4-8840-1b81e1cb41a6
Thu, 25 Jan 2024 21:01:52 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-97e87f46-279d-4d00-bfe8-e19e21abda64
Thu, 25 Jan 2024 21:01:53 +0000 backend INFO Volume published: tank_k8s_nfs1_pvc-27fd2b27-f008-4370-aa92-0aebd8cf04fe
Thu, 25 Jan 2024 21:02:00 +0000 backend INFO Host updated: 1a662d7a-877c-9609-56f6-39e2e125add5
Thu, 25 Jan 2024 21:02:00 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:02:01 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-a62837c2-c81c-4179-80fd-fad10dd4b3fa
Thu, 25 Jan 2024 21:02:03 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-5c4d718e-1a0a-4778-bc5d-e8d40bdb14a2
Thu, 25 Jan 2024 21:02:04 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-2d406c71-0053-4acd-97c5-1949197597e0
Thu, 25 Jan 2024 21:02:05 +0000 backend INFO Host updated: 1a662d7a-877c-9609-56f6-39e2e125add5
Thu, 25 Jan 2024 21:02:06 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-05593c40-ba4d-4c74-bb64-aec666d7cba1
Thu, 25 Jan 2024 21:02:12 +0000 backend INFO Volume published: tank_k8s_nfs1_pvc-b69c87dc-d7d9-4c6e-8585-e8e0ff0d2d47
Thu, 25 Jan 2024 21:02:13 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-f1b92233-f674-4e74-b268-61d8f8334de0
Thu, 25 Jan 2024 21:02:14 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:02:15 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-67162b91-3565-44ce-80b5-b2559f80341b
Thu, 25 Jan 2024 21:02:16 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-c8851c0f-ece9-4964-8e03-ceffa22d96c4
Thu, 25 Jan 2024 21:02:18 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-e841408d-0b6e-4431-b41c-35e799e0f979
Thu, 25 Jan 2024 21:02:18 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:02:18 +0000 backend INFO Host updated: 5d4a82d5-5fdc-9a53-e6b6-270b5615541e
Thu, 25 Jan 2024 21:02:23 +0000 backend INFO Host updated: 5d4a82d5-5fdc-9a53-e6b6-270b5615541e
Thu, 25 Jan 2024 21:02:25 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:02:27 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-5c4d718e-1a0a-4778-bc5d-e8d40bdb14a2
Thu, 25 Jan 2024 21:02:29 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-d5cb5c35-091d-46b7-80ea-a231b5297ba2
Thu, 25 Jan 2024 21:02:31 +0000 backend INFO Host updated: 1a662d7a-877c-9609-56f6-39e2e125add5
Thu, 25 Jan 2024 21:02:33 +0000 backend INFO Host updated: 6899609e-90e7-4dcc-a805-bb9ef2e5060c
Thu, 25 Jan 2024 21:02:36 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-e6fde167-2321-44b4-8840-1b81e1cb41a6
Thu, 25 Jan 2024 21:02:38 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:02:39 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-e2d7aaa1-e64b-4cf6-a102-286eaa025e2d
Thu, 25 Jan 2024 21:02:40 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:02:41 +0000 backend INFO Host updated: 1a662d7a-877c-9609-56f6-39e2e125add5
Thu, 25 Jan 2024 21:02:43 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:02:46 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-97e87f46-279d-4d00-bfe8-e19e21abda64
Thu, 25 Jan 2024 21:02:48 +0000 backend INFO Volume published: tank_k8s_nfs1_pvc-a62837c2-c81c-4179-80fd-fad10dd4b3fa
Thu, 25 Jan 2024 21:02:50 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-2d406c71-0053-4acd-97c5-1949197597e0
Thu, 25 Jan 2024 21:02:52 +0000 backend INFO Volume published: tank_k8s_nfs1_pvc-05593c40-ba4d-4c74-bb64-aec666d7cba1
Thu, 25 Jan 2024 21:02:55 +0000 backend INFO Volume published: tank_k8s_nfs1_pvc-f1b92233-f674-4e74-b268-61d8f8334de0
Thu, 25 Jan 2024 21:02:55 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:02:56 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-5226fb85-4ca8-4dfb-9c33-c947470fa1d3
Thu, 25 Jan 2024 21:02:57 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-67162b91-3565-44ce-80b5-b2559f80341b
Thu, 25 Jan 2024 21:02:59 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:03:00 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-a2ca4050-3517-4eb9-b372-44b226581d4c
Thu, 25 Jan 2024 21:03:01 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-c8851c0f-ece9-4964-8e03-ceffa22d96c4
Thu, 25 Jan 2024 21:03:02 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-b69c87dc-d7d9-4c6e-8585-e8e0ff0d2d47
Thu, 25 Jan 2024 21:03:04 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-27fd2b27-f008-4370-aa92-0aebd8cf04fe
Thu, 25 Jan 2024 21:03:04 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-5c4d718e-1a0a-4778-bc5d-e8d40bdb14a2
Thu, 25 Jan 2024 21:03:05 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-e841408d-0b6e-4431-b41c-35e799e0f979
Thu, 25 Jan 2024 21:03:05 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-d5cb5c35-091d-46b7-80ea-a231b5297ba2
Thu, 25 Jan 2024 21:03:05 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-a62837c2-c81c-4179-80fd-fad10dd4b3fa
Thu, 25 Jan 2024 21:03:05 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:03:06 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-52f6c7a7-9425-4cfa-8f2b-b9812d162d73
Thu, 25 Jan 2024 21:03:08 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-e6fde167-2321-44b4-8840-1b81e1cb41a6
Thu, 25 Jan 2024 21:03:10 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-97e87f46-279d-4d00-bfe8-e19e21abda64
Thu, 25 Jan 2024 21:03:11 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:03:13 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-e2d7aaa1-e64b-4cf6-a102-286eaa025e2d
Thu, 25 Jan 2024 21:03:18 +0000 backend INFO Host updated: 2480ad62-17e9-25d0-607b-f314b8416e6e
Thu, 25 Jan 2024 21:03:20 +0000 backend INFO Host updated: d2e212fc-18fe-3aae-d38d-8b727ab99d9b
Thu, 25 Jan 2024 21:03:22 +0000 backend INFO Host updated: 1a662d7a-877c-9609-56f6-39e2e125add5
Thu, 25 Jan 2024 21:03:24 +0000 backend INFO Host updated: 1a662d7a-877c-9609-56f6-39e2e125add5
Thu, 25 Jan 2024 21:03:24 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:03:26 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-373158b9-191a-4015-b8d3-a0075a788c82
Thu, 25 Jan 2024 21:03:27 +0000 backend INFO Host updated: 1a662d7a-877c-9609-56f6-39e2e125add5
Thu, 25 Jan 2024 21:03:29 +0000 backend INFO Host updated: 5d4a82d5-5fdc-9a53-e6b6-270b5615541e
Thu, 25 Jan 2024 21:03:31 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-2d406c71-0053-4acd-97c5-1949197597e0
Thu, 25 Jan 2024 21:03:34 +0000 backend INFO Host updated: 5d4a82d5-5fdc-9a53-e6b6-270b5615541e
Thu, 25 Jan 2024 21:03:35 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-05593c40-ba4d-4c74-bb64-aec666d7cba1
Thu, 25 Jan 2024 21:03:36 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:03:38 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-f1b92233-f674-4e74-b268-61d8f8334de0
Thu, 25 Jan 2024 21:03:38 +0000 backend INFO Host updated: 5d4a82d5-5fdc-9a53-e6b6-270b5615541e
Thu, 25 Jan 2024 21:03:39 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-67162b91-3565-44ce-80b5-b2559f80341b
Thu, 25 Jan 2024 21:03:40 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-c8851c0f-ece9-4964-8e03-ceffa22d96c4
Thu, 25 Jan 2024 21:03:44 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-5226fb85-4ca8-4dfb-9c33-c947470fa1d3
Thu, 25 Jan 2024 21:03:46 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-a2ca4050-3517-4eb9-b372-44b226581d4c
Thu, 25 Jan 2024 21:03:49 +0000 backend INFO Volume published: tank_k8s_nfs1_pvc-b69c87dc-d7d9-4c6e-8585-e8e0ff0d2d47
Thu, 25 Jan 2024 21:03:50 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-3028d574-1f7a-42f6-ae84-4c27d6a8d1e8
Thu, 25 Jan 2024 21:03:50 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:03:51 +0000 backend INFO Volume published: tank_k8s_nfs1_pvc-27fd2b27-f008-4370-aa92-0aebd8cf04fe
Thu, 25 Jan 2024 21:03:53 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-5c4d718e-1a0a-4778-bc5d-e8d40bdb14a2
Thu, 25 Jan 2024 21:03:55 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:03:58 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-d5cb5c35-091d-46b7-80ea-a231b5297ba2
Thu, 25 Jan 2024 21:04:00 +0000 backend INFO Volume published: tank_k8s_nfs1_pvc-a62837c2-c81c-4179-80fd-fad10dd4b3fa
Thu, 25 Jan 2024 21:04:02 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:04:05 +0000 backend INFO Volume published: tank_k8s_nfs1_pvc-52f6c7a7-9425-4cfa-8f2b-b9812d162d73
Thu, 25 Jan 2024 21:04:07 +0000 backend INFO Host updated: 1a662d7a-877c-9609-56f6-39e2e125add5
Thu, 25 Jan 2024 21:04:09 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-e6fde167-2321-44b4-8840-1b81e1cb41a6
Thu, 25 Jan 2024 21:04:11 +0000 backend INFO Host updated: 6899609e-90e7-4dcc-a805-bb9ef2e5060c
Thu, 25 Jan 2024 21:04:14 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-97e87f46-279d-4d00-bfe8-e19e21abda64
Thu, 25 Jan 2024 21:04:16 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:04:17 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-1b18d98d-d9c5-4c1e-b575-709e8fe9fea7
Thu, 25 Jan 2024 21:04:17 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:04:19 +0000 backend INFO Host updated: 1a662d7a-877c-9609-56f6-39e2e125add5
Thu, 25 Jan 2024 21:04:21 +0000 backend INFO Host updated: 2480ad62-17e9-25d0-607b-f314b8416e6e
Thu, 25 Jan 2024 21:04:24 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-373158b9-191a-4015-b8d3-a0075a788c82
Thu, 25 Jan 2024 21:04:26 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-2d406c71-0053-4acd-97c5-1949197597e0
Thu, 25 Jan 2024 21:04:28 +0000 backend INFO Volume published: tank_k8s_nfs1_pvc-05593c40-ba4d-4c74-bb64-aec666d7cba1
Thu, 25 Jan 2024 21:04:31 +0000 backend INFO Volume published: tank_k8s_nfs1_pvc-f1b92233-f674-4e74-b268-61d8f8334de0
Thu, 25 Jan 2024 21:04:31 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:04:32 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-785fd99a-ab3f-4637-8def-6285cbc140bf
Thu, 25 Jan 2024 21:04:33 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-67162b91-3565-44ce-80b5-b2559f80341b
Thu, 25 Jan 2024 21:04:35 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:04:35 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:04:37 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-53aa28dc-b762-4749-a53b-271ab00d5417
Thu, 25 Jan 2024 21:04:38 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-c8851c0f-ece9-4964-8e03-ceffa22d96c4
Thu, 25 Jan 2024 21:04:40 +0000 backend INFO Volume published: tank_k8s_nfs1_pvc-3028d574-1f7a-42f6-ae84-4c27d6a8d1e8
Thu, 25 Jan 2024 21:04:42 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-327fa05c-1ad1-4a57-9af8-f63d9770774f
Thu, 25 Jan 2024 21:04:42 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:04:42 +0000 backend INFO Host updated: 2480ad62-17e9-25d0-607b-f314b8416e6e
Thu, 25 Jan 2024 21:04:45 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-1b18d98d-d9c5-4c1e-b575-709e8fe9fea7
Thu, 25 Jan 2024 21:04:45 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:04:47 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-c6cdc784-a688-41e9-b3b7-9be116a678d3
Thu, 25 Jan 2024 21:04:47 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:04:47 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:04:49 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-43cad45a-33a3-4f09-b5d6-8d1299457206
Thu, 25 Jan 2024 21:04:50 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:04:52 +0000 backend INFO Volume published: tank_k8s_nfs1_pvc-785fd99a-ab3f-4637-8def-6285cbc140bf
Thu, 25 Jan 2024 21:04:54 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-55a4084b-1de6-4b69-95f3-9ce04b06f84a
Thu, 25 Jan 2024 21:04:54 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:04:54 +0000 backend INFO Host updated: 1a662d7a-877c-9609-56f6-39e2e125add5
Thu, 25 Jan 2024 21:04:57 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-53aa28dc-b762-4749-a53b-271ab00d5417
Thu, 25 Jan 2024 21:05:00 +0000 backend INFO Host updated: 1a662d7a-877c-9609-56f6-39e2e125add5
Thu, 25 Jan 2024 21:05:00 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:05:02 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-b19d7518-b044-435a-aeaf-a72962ecf509
Thu, 25 Jan 2024 21:05:03 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-327fa05c-1ad1-4a57-9af8-f63d9770774f
Thu, 25 Jan 2024 21:05:04 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-e841408d-0b6e-4431-b41c-35e799e0f979
Thu, 25 Jan 2024 21:05:05 +0000 backend INFO Host updated: 1a662d7a-877c-9609-56f6-39e2e125add5
Thu, 25 Jan 2024 21:05:06 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-e2d7aaa1-e64b-4cf6-a102-286eaa025e2d
Thu, 25 Jan 2024 21:05:06 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-5226fb85-4ca8-4dfb-9c33-c947470fa1d3
Thu, 25 Jan 2024 21:05:08 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-52f6c7a7-9425-4cfa-8f2b-b9812d162d73
Thu, 25 Jan 2024 21:05:08 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-373158b9-191a-4015-b8d3-a0075a788c82
Thu, 25 Jan 2024 21:05:08 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-c6cdc784-a688-41e9-b3b7-9be116a678d3
Thu, 25 Jan 2024 21:05:09 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-785fd99a-ab3f-4637-8def-6285cbc140bf
Thu, 25 Jan 2024 21:05:09 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-3028d574-1f7a-42f6-ae84-4c27d6a8d1e8
Thu, 25 Jan 2024 21:05:10 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-1b18d98d-d9c5-4c1e-b575-709e8fe9fea7
Thu, 25 Jan 2024 21:05:11 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-53aa28dc-b762-4749-a53b-271ab00d5417
Thu, 25 Jan 2024 21:05:11 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-e841408d-0b6e-4431-b41c-35e799e0f979
Thu, 25 Jan 2024 21:05:11 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:05:13 +0000 backend INFO Volume published: tank_k8s_nfs1_pvc-43cad45a-33a3-4f09-b5d6-8d1299457206
Thu, 25 Jan 2024 21:05:16 +0000 backend INFO Host updated: 33e0db71-744a-6c7e-fc7e-c2bf1bc196a6
Thu, 25 Jan 2024 21:05:19 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:05:21 +0000 backend INFO Volume published: tank_k8s_iscsi1_pvc-55a4084b-1de6-4b69-95f3-9ce04b06f84a
Thu, 25 Jan 2024 21:05:23 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:05:25 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:05:27 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-a2ca4050-3517-4eb9-b372-44b226581d4c
Thu, 25 Jan 2024 21:05:28 +0000 backend INFO Host updated: 5d4a82d5-5fdc-9a53-e6b6-270b5615541e
Thu, 25 Jan 2024 21:05:30 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:05:32 +0000 backend INFO Host updated: 2480ad62-17e9-25d0-607b-f314b8416e6e
Thu, 25 Jan 2024 21:05:34 +0000 backend INFO Host updated: 2480ad62-17e9-25d0-607b-f314b8416e6e
Thu, 25 Jan 2024 21:05:37 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:05:38 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-b69c87dc-d7d9-4c6e-8585-e8e0ff0d2d47
Thu, 25 Jan 2024 21:05:38 +0000 backend INFO Token created (not logged)
Thu, 25 Jan 2024 21:05:39 +0000 backend INFO Host updated: 6fc0a87c-6c6e-060f-0bfd-f169730670e1
Thu, 25 Jan 2024 21:05:39 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-b4328f46-67ad-45ff-a653-cdf3040f226b
Thu, 25 Jan 2024 21:05:41 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-27fd2b27-f008-4370-aa92-0aebd8cf04fe
Thu, 25 Jan 2024 21:05:41 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-5c4d718e-1a0a-4778-bc5d-e8d40bdb14a2
Thu, 25 Jan 2024 21:05:43 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-d5cb5c35-091d-46b7-80ea-a231b5297ba2
Thu, 25 Jan 2024 21:05:43 +0000 backend INFO Volume found: tank_k8s_nfs1_pvc-a62837c2-c81c-4179-80fd-fad10dd4b3fa
Thu, 25 Jan 2024 21:05:48 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
  File "/app/backend.py", line 356, in delete
    self.req_backend.raise_for_status()
  File "/usr/lib/python3.11/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/988

Thu, 25 Jan 2024 21:05:48 +0000 backend INFO Volume published: tank_k8s_nfs1_pvc-b19d7518-b044-435a-aeaf-a72962ecf509
Thu, 25 Jan 2024 21:05:50 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
  File "/app/backend.py", line 356, in delete
    self.req_backend.raise_for_status()
  File "/usr/lib/python3.11/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/988

Thu, 25 Jan 2024 21:05:50 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-e6fde167-2321-44b4-8840-1b81e1cb41a6
Thu, 25 Jan 2024 21:05:51 +0000 backend ERROR Backend Request (POST) Exception: Traceback (most recent call last):
  File "/app/backend.py", line 316, in post
    self.req_backend.raise_for_status()
  File "/usr/lib/python3.11/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/extent

Thu, 25 Jan 2024 21:05:51 +0000 backend ERROR Backend Request (POST) Exception: Traceback (most recent call last):
  File "/app/backend.py", line 316, in post
    self.req_backend.raise_for_status()
  File "/usr/lib/python3.11/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/targetextent

Thu, 25 Jan 2024 21:05:51 +0000 backend ERROR Exception: Traceback (most recent call last):
  File "/app/truenascsp.py", line 213, in on_put
    'serial_number': extent.get('naa').lstrip('0x'),
                     ^^^^^^^^^^^^^^^^^^^^^^^^
AttributeError: 'NoneType' object has no attribute 'lstrip'

Thu, 25 Jan 2024 21:05:51 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
  File "/app/backend.py", line 356, in delete
    self.req_backend.raise_for_status()
  File "/usr/lib/python3.11/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/988

Thu, 25 Jan 2024 21:05:52 +0000 backend INFO Volume found: tank_k8s_iscsi1_pvc-97e87f46-279d-4d00-bfe8-e19e21abda64
datamattsson commented 7 months ago

requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/988

I have a sneaking suspicion that this API call fails on the TrueNAS because you've run out of target IDs. I remember seeing something similar years ago.

kingnarmer commented 7 months ago

What is the max target IDs ? You mean iscsi zvol or iscsi extents ?

datamattsson commented 7 months ago

iSCSI extents. I recall hacking around on the iSCSI target on the CLI and I think you'll be able to find errors logged on the iSCSI daemon. I don't have a system around right now to reproduce.

kingnarmer commented 7 months ago

@datamattsson I removed/deleted several extents and restarted CSP again . Seeing this error . What this error indicates ? 

Thu, 25 Jan 2024 23:27:18 +0000 backend ERROR Exception: Traceback (most recent call last):
  File "/app/truenascsp.py", line 213, in on_put
    'serial_number': extent.get('naa').lstrip('0x'),
                     ^^^^^^^^^^
AttributeError: 'NoneType' object has no attribute 'get'
datamattsson commented 7 months ago

@datamattsson I removed/deleted several extents and restarted CSP again . Seeing this error . What this error indicates ?

It indicates that whatever is being returned by the TrueNAS API isn't what the CSP expects. If you curl the URL, what does it return? https://truenas1.domain.tld/api/v2.0/iscsi/target/id/988 (not entirely sure how to provide the credentials, I think you can do basic auth.

kingnarmer commented 7 months ago

I get empty string for 988 , however I get valid response to the following commands . I don't see 988 in error logs anymore. 

curl -X GET "http://truenas1.domain.tld/api/v2.0/iscsi/extent" -u 'root:xxxxxxxx' -H  "accept: */*"
curl -X GET "http://truenas1.domain.tld/api/v2.0/iscsi/target" -u 'root:xxxxx' -H  "accept: */*"

This error is one I see across all clusters.

'serial_number': extent.get('naa').lstrip('0x')

datamattsson commented 7 months ago

If you do a GET on an extent that is working, what do you get back?

kingnarmer commented 7 months ago

This is what I get .

curl -k -u 'root:xxxxxx' -X GET "https://truenas1.domain.tld/api/v2.0/iscsi/target/id/993" -H 'accept: application/json' { "id": 993, "name": "pvc-be39a402-6d9f-4265-822b-7505b4359fc0", "alias": null, "mode": "ISCSI", "groups": [ { "portal": 1, "initiator": 75, "auth": null, "authmethod": "NONE" } ] }

datamattsson commented 7 months ago

I think a POST fails silently (returns 2xx when it should be 3xx, 4xx or 5xx) to iscsi/extent, it should return the extent, that extent is later used to pull out the serial number etc.

If you install the Helm chart with logDebug=true it should reveal more clues. You can also edit the CSP deployment and add this to the Pod:

          env:
            - name: LOG_DEBUG
              value: "1"
kingnarmer commented 7 months ago

I enabled debug , csp logs show same error 


Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG Assume Basic Auth for authentication.
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG TrueNAS GET request URI: core/ping
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG TrueNAS response: "pong"
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG API fetch caught 1 item
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG HPE CSI Request <==============================>
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG          uri: http://truenas-csp-svc:8080/containers/v1/volumes/tank_k8s_iscsi1_pvc-e841408d-0b6e-4431-b41c-35e799e0f979
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG         body: None
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG        query:
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG       method: GET
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG content_type: application/json
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG      headers: {"HOST": "truenas-csp-svc:8080", "USER-AGENT": "Go-http-client/1.1", "CONNECTION": "close", "ACCEPT": "application/json", "CONTENT-TYPE": "application/json", "X-ARRAY-IP": "w-tuvault-m.ocis.temple.edu", "X-AUTH-TOKEN": "*****", "ACCEPT-ENCODING": "gzip"}
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG Assume Basic Auth for authentication.
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG TrueNAS GET request URI: pool/dataset
Fri, 26 Jan 2024 01:07:24 +0000 backend DEBUG TrueNAS response: [

List of all extents 

Fri, 26 Jan 2024 01:07:30 +0000 backend ERROR Exception: Traceback (most recent call last):
  File "/app/truenascsp.py", line 213, in on_put
    'serial_number': extent.get('naa').lstrip('0x'),
                     ^^^^^^^^^^
AttributeError: 'NoneType' object has no attribute 'get'

Fri, 26 Jan 2024 01:07:30 +0000 backend DEBUG Falcon Response (to HPE CSI): 500 Internal Server Error
Fri, 26 Jan 2024 01:07:30 +0000 backend DEBUG Last backend requests Response: 200 OK
datamattsson commented 7 months ago

I enabled debug , csp logs show same error

Is this the full log surrounding the issue? The first part looks truncated.

kingnarmer commented 7 months ago

I had "List of all extents" between the first section and last section. The output was 3458 lines. 

Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG Assume Basic Auth for authentication.
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG TrueNAS GET request URI: core/ping
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG TrueNAS response: "pong"
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG API fetch caught 1 item
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG HPE CSI Request <==============================>
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG          uri: http://truenas-csp-svc:8080/containers/v1/volumes/tank_k8s_iscsi1_pvc-e841408d-0b6e-4431-b41c-35e799e0f979
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG         body: None
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG        query:
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG       method: GET
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG content_type: application/json
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG      headers: {"HOST": "truenas-csp-svc:8080", "USER-AGENT": "Go-http-client/1.1", "CONNECTION": "close", "ACCEPT": "application/json", "CONTENT-TYPE": "application/json", "X-ARRAY-IP": "w-tuvault-m.ocis.temple.edu", "X-AUTH-TOKEN": "*****", "ACCEPT-ENCODING": "gzip"}
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG Assume Basic Auth for authentication.
Fri, 26 Jan 2024 01:07:23 +0000 backend DEBUG TrueNAS GET request URI: pool/dataset
Fri, 26 Jan 2024 01:07:24 +0000 backend DEBUG TrueNAS response: [
 {
  "id": "tank",
  "type": "FILESYSTEM",
  "children": [
   {
    "id": "tank/k8s",
    "type": "FILESYSTEM",
    "children": [
     {
      "id": "tank/k8s/iscsi1",
      "type": "FILESYSTEM",
      "children": [
       {
        "id": "tank/k8s/iscsi1/pvc-d9230ab0-526a-45d4-923a-754386fb4130",
        "type": "VOLUME",
        "children": [],
        "name": "tank/k8s/iscsi1/pvc-d9230ab0-526a-45d4-923a-754386fb4130",
        "pool": "tank",
        "encrypted": false,
        "encryption_root": null,
        "key_loaded": false,
        "mountpoint": null,
        "comments": {
         "value": "xxxxxx: iSCSi Volume provisioned by TrueNAS-CSP",
         "rawvalue": "xxxxxxx: iSCSi Volume provisioned by TrueNAS-CSP",
         "source": "LOCAL",
         "parsed": "xxxxxxx: iSCSi Volume provisioned by TrueNAS-CSP"
        },

**The list of extents and their details were omitted for space.

Then last entry before the error** 

{
  "id": 881,
  "name": "pvc-0b4865be-0fc9-40f3-a151-7193503a188c",
  "serial": "3cecef5fccec880",
  "type": "DISK",
  "path": "zvol/tank/k8s/nfs1/pvc-0b4865be-0fc9-40f3-a151-7193503a188c",
  "filesize": "0",
  "blocksize": 512,
  "pblocksize": false,
  "avail_threshold": null,
  "comment": "Managed by HPE CSI Driver for Kubernetes",
  "naa": "0x6589cfc000000278140ebfd04ab6c5f2",
  "insecure_tpc": true,
  "xen": false,
  "rpm": "SSD",
  "ro": false,
  "enabled": true,
  "vendor": "TrueNAS",
  "disk": "zvol/tank/k8s/nfs1/pvc-0b4865be-0fc9-40f3-a151-7193503a188c",
  "locked": false
 }
]
Fri, 26 Jan 2024 01:07:30 +0000 backend ERROR Exception: Traceback (most recent call last):
  File "/app/truenascsp.py", line 213, in on_put
    'serial_number': extent.get('naa').lstrip('0x'),
                     ^^^^^^^^^^
AttributeError: 'NoneType' object has no attribute 'get'

Fri, 26 Jan 2024 01:07:30 +0000 backend DEBUG Falcon Response (to HPE CSI): 500 Internal Server Error
Fri, 26 Jan 2024 01:07:30 +0000 backend DEBUG Last backend requests Response: 200 OK
datamattsson commented 7 months ago

We're looking for an error that doesn't look like an error.

From what I can tell from what you're not posting, it's a PUT to iscsi/target/id/ (with an ID) and subsequently a "Target updated: ".

It would be easier if I had the whole file to look at.

kingnarmer commented 7 months ago

@datamattsson file attached log2.zip

datamattsson commented 7 months ago

I'm seeing at least one bug here. We're assuming extent exist just because the target exist, an attempt is made to fetch the extent but it it's empty (the None value the extent.get is operating on. If you delete the target, a new target and extent should be created.

Restart CSP, delete the affected target, send me the log file.

kingnarmer commented 7 months ago

@datamattsson Which targets to delete ? I have lots of pvcs and I want to be careful .

datamattsson commented 7 months ago

The target of a failing PVC.

On Thu, Jan 25, 2024, 8:14 PM kingnarmer @.***> wrote:

@datamattsson https://github.com/datamattsson Which targets to delete ? I have lots of pvcs and I want to be careful .

— Reply to this email directly, view it on GitHub https://github.com/hpe-storage/truenas-csp/issues/55#issuecomment-1911453743, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABVTK2GGADQ6D5TJ5QR2JPDYQMUQTAVCNFSM6AAAAABCKULKGOVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTSMJRGQ2TGNZUGM . You are receiving this because you were mentioned.Message ID: @.***>

kingnarmer commented 7 months ago

Thanks. Will delete failed targets one at a time and restart CSP and let you know how it goes.

kingnarmer commented 7 months ago

Thanks a lot for help. The elimination of ID 1058 enabled the functionality of other mounts. It took several hours for all the mounts to be reestablished. On a few clusters, I encountered difficulties when attempting to remount PVCs, ultimately requiring me to delete and recreate them, which proved effective. On some cases I may not be able to remove pvcs and recreate.

How can I prevent a recurrence of this issue in the future?

datamattsson commented 7 months ago

How can I prevent a recurrence of this issue in the future?

I think this is a limitation in the TrueNAS API server. I've isolated where it breaks and understand that better now. Things like the missing extent when you had a target already I think I can mitigate quite easily in the CSP but I'm contemplating persisting the targets and extents (today they are removed on unpublish and created on publish) and only update the ACLs instead, I think that would help until you get into the 1000s of zvols.

I'm going to try reproduce issue and see what I can do. There will be something addressing parts of this in the next release for sure.

kingnarmer commented 7 months ago

Thanks for help with issue last week. I am still seeing errors across all clusters. PVCs are mounted , not sure if I should be concerned about this error.

I have attached updated logs as well. 

Mon, 29 Jan 2024 13:58:10 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
  File "/app/backend.py", line 356, in delete
    self.req_backend.raise_for_status()
  File "/usr/lib/python3.11/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/1058

Mon, 29 Jan 2024 13:58:10 +0000 backend DEBUG Target deletion retried: tank_k8s_iscsi1_pvc-5c4d718e-1a0a-4778-bc5d-e8d40bdb14a2
Mon, 29 Jan 2024 13:58:10 +0000 backend DEBUG Assume Basic Auth for authentication.
Mon, 29 Jan 2024 13:58:10 +0000 backend DEBUG TrueNAS GET request URI: iscsi/target

...

[2024-01-29 13:59:07 +0000] [1] [ERROR] Worker (pid:2188) exited with code 1
[2024-01-29 13:59:07 +0000] [1] [ERROR] Worker (pid:2188) exited with code 1.

logs9.gz

datamattsson commented 7 months ago

Yeah, those retries are not pretty, let's see if I can do something about that. I think what you're seeing is harmless.

kingnarmer commented 7 months ago

@datamattsson The issue came again , all what I see in debug log is this message for different lun IDs. The issue started 9 hours ago across all clusters. Some of the LUNs recovered but after 6 hours of being unavailable. Still lots not recovered. I don't see one extent persistent in all logs like before. Appreciate any help to get to root cause . Thanks for your help. 

backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
  File "/app/backend.py", line 356, in delete
    self.req_backend.raise_for_status()
  File "/usr/lib/python3.11/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/xxxx
kingnarmer commented 7 months ago

On TrueNAS , I see lots of errors "no LUNs defined for target". On truenas , kern.cam.ctl.max_luns is set to 4096 and kern.cam.ctl.max_ports set to 1024.

How to force recreation of "Associated Targets" for failing Targets/extents ?

datamattsson commented 7 months ago

I'm sorry you're hitting this again. If you scale down your your workloads to ensure there's no PVs attached, you can safely delete all targets and extents associated with the PVC/PV. Scale up your workloads and they will be recreated when the PV is published.

kingnarmer commented 7 months ago

Will test it now.

kingnarmer commented 7 months ago

Followed steps and removed targets/extents then scaled up workload without succesds. I did restart csi controller/Daemonset/truenas-csp as well . The errors "no LUNs defined for target" on TruenAS messages are not showing anymore , however I am seeing different error for multiple initiators. " (iqn.1993-08.org.debian:01:9d3c14f25bd4): read: Connection reset by peer>

datamattsson commented 7 months ago

The connection reset by peer is related to dead iSCSI sessions on the hosts. What errors are you seeing in the the CSP log now?

kingnarmer commented 6 months ago

Errors I see in debug logs. 

Fri, 09 Feb 2024 22:01:49 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/1468
Fri, 09 Feb 2024 22:01:50 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/1079
Fri, 09 Feb 2024 22:01:50 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/1469
Fri, 09 Feb 2024 22:01:51 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/1468
Fri, 09 Feb 2024 22:01:52 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/1079
Fri, 09 Feb 2024 22:01:52 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/1469
Fri, 09 Feb 2024 22:01:53 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/1468
Fri, 09 Feb 2024 22:01:54 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/1079
Fri, 09 Feb 2024 22:01:54 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/1469
Fri, 09 Feb 2024 22:01:55 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/1468
Fri, 09 Feb 2024 22:01:56 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/1079
Fri, 09 Feb 2024 22:01:56 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/1469
Fri, 09 Feb 2024 22:01:57 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/1468
Fri, 09 Feb 2024 22:01:58 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/1079
Fri, 09 Feb 2024 22:01:58 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/1469
Fri, 09 Feb 2024 22:01:58 +0000 backend ERROR Backend Request (DELETE) Exception: Traceback (most recent call last):
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 422 Client Error: Unprocessable Entity for url: https://truenas1.domain.tld/api/v2.0/iscsi/target/id/1468
kingnarmer commented 6 months ago

pods --> pvc still not recovered. What might have caused this issue ?

datamattsson commented 6 months ago

The one time I saw something similar it was on a system where I have had a high degree of churn with ID numbers in the thousands. I suspect there are API errors that are not handled properly.

Attach the debug logs from the CSI node, controller (hpe-csi-driver containers) and the TrueNAS CSP and I'll have a look.

datamattsson commented 4 months ago

Thanks for collaborating on this. v2.4.2 has been released with the fixes.