rbd-target-api fails to create disk for existing image

[hemna]

I'm trying to export an already existing image with gwcli.

When I try and create the disk in gwcli I get an error of

/iscsi-target...:53cac8599be5> disk add volumes/volume-4449256b-bb4e-4be4-9718-58900f578ebc
Failed : disk create/update failed on devstack-20. LUN allocation failure
disk auto-define failed(8), try using the /disks create command

And the rbd-target-api.log has a weird error

The /var/log/rbd-target-api.log

│2020-07-06 12:34:05,301     INFO [_internal.py:113:_log()] - ::ffff:127.0.0.1 - - [06/Jul/2020 12:34:05] "GET /api/_ping HTTP/1.1" 200 -                                                                                                  │
│2020-07-06 12:34:08,967    DEBUG [rbd-target-api:1005:disk()] - this host is devstack-20                                                                                                                                                  │
│2020-07-06 12:34:08,967    DEBUG [common.py:505:refresh()] - config refresh - current config is {'created': '2020/07/06 15:21:33', 'discovery_auth': {'mutual_password': '', 'mutual_password_encryption_enabled': False, 'mutual_username│
│2020-07-06 12:34:08,967    DEBUG [common.py:139:_open_ioctx()] - (_open_ioctx) Opening connection to rbd pool                                                                                                                             │
│2020-07-06 12:34:08,968    DEBUG [common.py:146:_open_ioctx()] - (_open_ioctx) connection opened                                                                                                                                          │
│2020-07-06 12:34:08,968    DEBUG [common.py:118:_read_config_object()] - _read_config_object reading the config object                                                                                                                    │
│2020-07-06 12:34:08,969    DEBUG [common.py:168:_get_ceph_config()] - (_get_rbd_config) config object contains 'b'{\n    "created": "2020/07/06 15:21:33",\n    "discovery_auth": {\n        "mutual_password": "",\n        "mutual_passw│
│2020-07-06 12:34:09,058     INFO [_internal.py:113:_log()] - ::ffff:127.0.0.1 - - [06/Jul/2020 12:34:09] "GET /api/_ping HTTP/1.1" 200 -                                                                                                  │
│2020-07-06 12:34:09,060    DEBUG [rbd-target-api:2673:call_api()] - gateway update order is localhost                                                                                                                                     │
│2020-07-06 12:34:09,060    DEBUG [rbd-target-api:2676:call_api()] - processing GW 'localhost'                                                                                                                                             │
│2020-07-06 12:34:09,063    DEBUG [common.py:505:refresh()] - config refresh - current config is {'created': '2020/07/06 15:21:33', 'discovery_auth': {'mutual_password': '', 'mutual_password_encryption_enabled': False, 'mutual_username│
│2020-07-06 12:34:09,064    DEBUG [common.py:139:_open_ioctx()] - (_open_ioctx) Opening connection to rbd pool                                                                                                                             │
│2020-07-06 12:34:09,064    DEBUG [common.py:146:_open_ioctx()] - (_open_ioctx) connection opened                                                                                                                                          │
│2020-07-06 12:34:09,064    DEBUG [common.py:118:_read_config_object()] - _read_config_object reading the config object                                                                                                                    │
│2020-07-06 12:34:09,065    DEBUG [common.py:168:_get_ceph_config()] - (_get_rbd_config) config object contains 'b'{\n    "created": "2020/07/06 15:21:33",\n    "discovery_auth": {\n        "mutual_password": "",\n        "mutual_passw│
│2020-07-06 12:34:09,081    DEBUG [common.py:139:_open_ioctx()] - (_open_ioctx) Opening connection to rbd pool                                                                                                                             │
│2020-07-06 12:34:09,082    DEBUG [common.py:146:_open_ioctx()] - (_open_ioctx) connection opened                                                                                                                                          │
│2020-07-06 12:34:09,087    DEBUG [common.py:436:init_config()] - (init_config) using pre existing config object                                                                                                                           │
│2020-07-06 12:34:09,088    DEBUG [common.py:139:_open_ioctx()] - (_open_ioctx) Opening connection to rbd pool                                                                                                                             │
│2020-07-06 12:34:09,088    DEBUG [common.py:146:_open_ioctx()] - (_open_ioctx) connection opened                                                                                                                                          │
│2020-07-06 12:34:09,088    DEBUG [common.py:118:_read_config_object()] - _read_config_object reading the config object                                                                                                                    │
│2020-07-06 12:34:09,089    DEBUG [common.py:168:_get_ceph_config()] - (_get_rbd_config) config object contains 'b'{\n    "created": "2020/07/06 15:21:33",\n    "discovery_auth": {\n        "mutual_password": "",\n        "mutual_passw│
│2020-07-06 12:34:09,109    DEBUG [lun.py:586:allocate()] - LUN.allocate starting, listing rbd devices                                                                                                                                     │
│2020-07-06 12:34:09,132    DEBUG [lun.py:588:allocate()] - rados pool 'volumes' contains the following - ['volume-4449256b-bb4e-4be4-9718-58900f578ebc']                                                                                  │
│2020-07-06 12:34:09,132    DEBUG [lun.py:592:allocate()] - Hostname Check - this host is devstack-20, target host for allocations is devstack-20                                                                                          │
│2020-07-06 12:34:09,197    ERROR [lun.py:646:allocate()] - (LUN.allocate) rbd 'volume-4449256b-bb4e-4be4-9718-58900f578ebc' is not compatible with LIO                                                                                    │
│Image features  are not supported                                                                                                                                                                                                         │
│2020-07-06 12:34:09,197    ERROR [rbd-target-api:1210:_disk()] - LUN alloc problem - (LUN.allocate) rbd 'volume-4449256b-bb4e-4be4-9718-58900f578ebc' is not compatible with LIO                                                          │
│Image features  are not supported                                                                                                                                                                                                         │
│2020-07-06 12:34:09,200     INFO [_internal.py:113:_log()] - ::ffff:127.0.0.1 - - [06/Jul/2020 12:34:09] "PUT /api/_disk/volumes/volume-4449256b-bb4e-4be4-9718-58900f578ebc HTTP/1.1" 500 -                                              │
│2020-07-06 12:34:09,202    ERROR [rbd-target-api:2694:call_api()] - _disk change on localhost failed with 500                                                                                                                             │
│2020-07-06 12:34:09,203    DEBUG [rbd-target-api:2719:call_api()] - failed on devstack-20. LUN allocation failure                                                                                                                         │
│2020-07-06 12:34:09,203     INFO [_internal.py:113:_log()] - ::ffff:127.0.0.1 - - [06/Jul/2020 12:34:09] "PUT /api/disk/volumes/volume-4449256b-bb4e-4be4-9718-58900f578ebc HTTP/1.1" 500 -                                               │
│2020-07-06 12:34:15,302     INFO [_internal.py:113:_log()] - ::ffff:127.0.0.1 - - [06/Jul/2020 12:34:15] "GET /api/_ping HTTP/1.1" 200 -                                                                                                  │
│2020-07-06 12:34:25,302     INFO [_internal.py:113:_log()] - ::ffff:127.0.0.1 - - [06/Jul/2020 12:34:25] "GET /api/_ping HTTP/1.1" 200 -

[dillaman]

The error says that "Image features are not supported" -- so what features are/are not enabled on that image?

[hemna]

I had no idea, the error message should have listed the features that were required, but not there in the pool/image.

https://github.com/ceph/ceph-iscsi/blob/master/ceph_iscsi_config/lun.py#L642-L645

The unsupported features list is empty.

FWIW, looking at the code, I was able to see that the required feature list is a single entry here:
https://github.com/ceph/ceph-iscsi/blob/master/ceph_iscsi_config/lun.py#L43-L47

That says the image must contain the feature of exclusive lock. Nowhere in the docs is that stated as being
required. So after creating the image, I then used the rbd command line to force that feature on the image, and
then tried to create the disk on the host, and that worked.

so:

1. The documentation for ceph-iscsi needs to explicitly state that the exclusive-lock feature must exist on every image you plan on exporting
2. the error message that rbd-target-api needs to be fixed to show the missing feature flags on the image.

[dillaman]

so:

1. The documentation for ceph-iscsi needs to explicitly state that the exclusive-lock feature must exist on every image you plan on exporting

2. the error message that rbd-target-api needs to be fixed to show the missing feature flags on the image.

This is an open-source project: please feel free to open a PR to improve the product.

[kevinzs2048]

/assign

[kevinzs2048]

The interest thing is that I can not reproduce this bug now :-)