Adding RBD disk with ValueError: No JSON object could be decoded

[liushaobot]

After creating iSCSI gateways successfully, I add RBD disk by using

create pool=rbd image=iscsi-test-16T size=16T

Then, I got the following error

ValueError: No JSON object could be decoded

The rbd-target-api daemon is

[root@ceph-gw-1 ~]# journalctl -u rbd-target-api
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]: (LUN.allocate) created rbd/iscsi-test-16T successfully
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]: (LUN.add_dev_to_lio) Adding image 'rbd.iscsi-test-16T' to LIO
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]: 127.0.0.1 - - [10/Nov/2017 12:00:18] "PUT /api/_disk/rbd.iscsi-test-16T HTTP/1.1" 500 -
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]: Traceback (most recent call last):
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib64/python2.7/site-packages/flask/app.py", line 1997, in __call__
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     return self.wsgi_app(environ, start_response)
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib64/python2.7/site-packages/flask/app.py", line 1985, in wsgi_app
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     response = self.handle_exception(e)
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib64/python2.7/site-packages/flask/app.py", line 1540, in handle_exception
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     reraise(exc_type, exc_value, tb)
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib64/python2.7/site-packages/flask/app.py", line 1982, in wsgi_app
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     response = self.full_dispatch_request()
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib64/python2.7/site-packages/flask/app.py", line 1614, in full_dispatch_req
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     rv = self.handle_user_exception(e)
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib64/python2.7/site-packages/flask/app.py", line 1517, in handle_user_excep
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     reraise(exc_type, exc_value, tb)
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib64/python2.7/site-packages/flask/app.py", line 1612, in full_dispatch_req
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     rv = self.dispatch_request()
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib64/python2.7/site-packages/flask/app.py", line 1598, in dispatch_request
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     return self.view_functions[rule.endpoint](**req.view_args)
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib/python2.7/site-packages/gwcli-2.5-py2.7.egg/EGG-INFO/scripts/rbd-target-
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib/python2.7/site-packages/gwcli-2.5-py2.7.egg/EGG-INFO/scripts/rbd-target-
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "build/bdist.linux-x86_64/egg/ceph_iscsi_config/lun.py", line 426, in allocate
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     lun = self.add_dev_to_lio()
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "build/bdist.linux-x86_64/egg/ceph_iscsi_config/lun.py", line 612, in add_dev_to_l
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     wwn=in_wwn)
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib/python2.7/site-packages/rtslib_fb/tcm.py", line 815, in __init__
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     self._configure(config, size, wwn, hw_max_sectors)
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib/python2.7/site-packages/rtslib_fb/tcm.py", line 831, in _configure
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     self._enable()
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib/python2.7/site-packages/rtslib_fb/tcm.py", line 172, in _enable
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     fwrite(path, "1\n")
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib/python2.7/site-packages/rtslib_fb/utils.py", line 79, in fwrite
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     file_fd.write(str(string))
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]: IOError: [Errno 2] No such file or directory
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]: _disk change on 127.0.0.1 failed with 500
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]: 127.0.0.1 - - [10/Nov/2017 12:00:18] "PUT /api/disk/rbd.iscsi-test-16T HTTP/1.1" 500 -
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]: Traceback (most recent call last):
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib64/python2.7/site-packages/flask/app.py", line 1997, in __call__
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     return self.wsgi_app(environ, start_response)
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib64/python2.7/site-packages/flask/app.py", line 1985, in wsgi_app
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     response = self.handle_exception(e)
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib64/python2.7/site-packages/flask/app.py", line 1540, in handle_exception
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     reraise(exc_type, exc_value, tb)
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib64/python2.7/site-packages/flask/app.py", line 1982, in wsgi_app
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     response = self.full_dispatch_request()
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib64/python2.7/site-packages/flask/app.py", line 1614, in full_dispatch_req
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     rv = self.handle_user_exception(e)
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib64/python2.7/site-packages/flask/app.py", line 1517, in handle_user_excep
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     reraise(exc_type, exc_value, tb)
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib64/python2.7/site-packages/flask/app.py", line 1612, in full_dispatch_req
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     rv = self.dispatch_request()
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib64/python2.7/site-packages/flask/app.py", line 1598, in dispatch_request
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     return self.view_functions[rule.endpoint](**req.view_args)
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib/python2.7/site-packages/gwcli-2.5-py2.7.egg/EGG-INFO/scripts/rbd-target-
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib/python2.7/site-packages/gwcli-2.5-py2.7.egg/EGG-INFO/scripts/rbd-target-
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib/python2.7/site-packages/gwcli-2.5-py2.7.egg/EGG-INFO/scripts/rbd-target-
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib/python2.7/site-packages/requests/models.py", line 866, in json
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     return complexjson.loads(self.text, **kwargs)
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib64/python2.7/json/__init__.py", line 339, in loads
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     return _default_decoder.decode(s)
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib64/python2.7/json/decoder.py", line 364, in decode
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:   File "/usr/lib64/python2.7/json/decoder.py", line 382, in raw_decode
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]:     raise ValueError("No JSON object could be decoded")
11月 10 12:00:18 ceph-gw-1 rbd-target-api[779]: ValueError: No JSON object could be decoded

And the log file: /var/log/rbd-target-api.log

[root@ceph-gw-1 log]# tail rbd-target-api.log
2017-11-10 12:00:18,133    DEBUG [lun.py:323:allocate()] - rados pool 'rbd' contains the following - [u'iscsi-test-8T']
2017-11-10 12:00:18,133    DEBUG [lun.py:328:allocate()] - Hostname Check - this host is ceph-gw-1, target host for allocations is ceph-gw-1
2017-11-10 12:00:18,594    DEBUG [common.py:256:add_item()] - (Config.add_item) config updated to {u'updated': u'2017/11/10 01:50:09', u'disks': {'rbd.iscsi-test-16T': {'created': '2017/11/10 04:00:18'}}, u'created': u'2017/11/08 07:36:52', u'clients': {}, u'epoch': 4, u'version': 3, u'gateways': {u'iqn': u'iqn.2017-11.com.ctcloud.iscsi-gw:ceph-igw', u'created': u'2017/11/09 08:56:41', u'ceph-gw-1': {u'gateway_ip_list': [u'192.168.100.248', u'192.168.100.246'], u'active_luns': 0, u'created': u'2017/11/10 00:30:31', u'updated': u'2017/11/10 01:20:25', u'iqn': u'iqn.2017-11.com.ctcloud.iscsi-gw:ceph-igw', u'inactive_portal_ips': [u'192.168.100.246'], u'portal_ip_address': u'192.168.100.248', u'tpgs': 2}, u'ip_list': [u'192.168.100.248', u'192.168.100.246'], u'ceph-gw-2': {u'gateway_ip_list': [u'192.168.100.248', u'192.168.100.246'], u'active_luns': 0, u'created': u'2017/11/10 01:50:09', u'updated': u'2017/11/10 01:50:09', u'iqn': u'iqn.2017-11.com.ctcloud.iscsi-gw:ceph-igw', u'inactive_portal_ips': [u'192.168.100.248'], u'portal_ip_address': u'192.168.100.246', u'tpgs': 2}}, u'groups': {}}
2017-11-10 12:00:18,594     INFO [lun.py:344:allocate()] - (LUN.allocate) created rbd/iscsi-test-16T successfully
2017-11-10 12:00:18,595    DEBUG [lun.py:384:allocate()] - Check the rbd image size matches the request
2017-11-10 12:00:18,595    DEBUG [lun.py:407:allocate()] - Begin processing LIO mapping
2017-11-10 12:00:18,595     INFO [lun.py:598:add_dev_to_lio()] - (LUN.add_dev_to_lio) Adding image 'rbd.iscsi-test-16T' to LIO
2017-11-10 12:00:18,633     INFO [_internal.py:87:_log()] - 127.0.0.1 - - [10/Nov/2017 12:00:18] "PUT /api/_disk/rbd.iscsi-test-16T HTTP/1.1" 500 -
2017-11-10 12:00:18,640    ERROR [rbd-target-api:1266:call_api()] - _disk change on 127.0.0.1 failed with 500
2017-11-10 12:00:18,651     INFO [_internal.py:87:_log()] - 127.0.0.1 - - [10/Nov/2017 12:00:18] "PUT /api/disk/rbd.iscsi-test-16T HTTP/1.1" 500 -

And I tried touch a new file in /sys/kernel/config/target/, but I failed.

What is it? How could I solve the problem? Thanks!

[mikechristie]

The rbd image addition to tcmu-runner failed.

Whats in /var/log/tcmu-runner.log and the kernel log at this time?

[mikechristie]

And what kernel version is this with?

[liushaobot]

When I use targetcli to create iscsi target, everything is OK. However, I get the above error when using gwcli.

And I get following error in /var/log/tcmu-runner.log

2017-11-21 09:58:09.601 894 [WARN] timer_check_and_set_def:229 rbd/rbd.iscsi-test-16T: osd op timeout ((null)) must be larger than osd heartbeat grace (20) + interval (6)!
2017-11-21 09:58:09.601 894 [WARN] timer_check_and_set_def:248 rbd/rbd.iscsi-test-16T: Will set the osd op timeout to 31 instead!
2017-11-21 09:58:09.641 894 [ERROR] tcmu_rbd_image_open:298 rbd/rbd.iscsi-test-16T: Could not open image ha-image/osd_op_timeout=30. (Err -2)
2017-11-21 09:58:09.645 894 [ERROR] add_device:496: handler open failed for uio0

@mikechristie

[mikechristie]

Does your version of tcmu-runner have this patch

open-iscsi/tcmu-runner@897242e

1.3.0-rc3 and newer will have it.

[liushaobot]

Yes, I use the newest tcmu-runner-1.3.0-rc4.

[liushaobot]

All packages are the newest release versions:
tcmu-runner-1.3.0-rc4
ceph-iscsi-config-2.3
ceph-iscsi-cli-2.5

[liushaobot]

The image name should be iscsi-test-16T. However, there is a suffix /osd_op_timeout=30.

open-iscsi/tcmu-runner#335 (comment)
I am wondering on which versions the mismatch issue between tcmu-runner and ceph-iscsi-config/ceph-iscsi-cli will be resolved/has been resolved.
@mikechristie

[mikechristie]

You need to use the ceph-iscsi-config from GitHub master. It has this patch:

ceph/ceph-iscsi-config@5d8396b

which 2.3 does not.

[liushaobot]

Thanks!