Bug #48390
openCEPH-ISCSI fails when restarting rbd-target-api and won't work anymore with mgr error - BUG
0%
Description
I have an issue on ceph-iscsi ( ubuntu 20 LTS and Ceph 15.2.6) after I restart rbd-target-api, it fails and not starting again:
```
sudo systemctl status rbd-target-api.service
● rbd-target-api.service - Ceph iscsi target configuration API
Loaded: loaded (/lib/systemd/system/rbd-target-api.service; enabled; vendor preset: enabled)
Active: deactivating (stop-sigterm) since Sat 2020-11-28 17:01:40 +0330; 20s ago
Main PID: 37651 (rbd-target-api)
Tasks: 55 (limit: 9451)
Memory: 141.4M
CGroup: /system.slice/rbd-target-api.service
├─15289 /usr/bin/python3 /usr/bin/rbd-target-api
└─37651 /usr/bin/python3 /usr/bin/rbd-target-api
Nov 28 14:36:53 dev11 systemd1: Started Ceph iscsi target configuration API.
Nov 28 14:36:54 dev11 rbd-target-api37651: Started the configuration object watcher
Nov 28 14:36:54 dev11 rbd-target-api37651: Processing osd blacklist entries for this node
Nov 28 14:36:54 dev11 rbd-target-api37651: Checking for config object changes every 1s
Nov 28 14:36:55 dev11 rbd-target-api37651: Reading the configuration object to update local LIO configuration
Nov 28 14:36:55 dev11 rbd-target-api37651: Processing Gateway configuration
Nov 28 14:36:55 dev11 rbd-target-api37651: Setting up iqn.2003-01.com.redhat.iscsi-gw:iscsi-igw
Nov 28 14:36:55 dev11 rbd-target-api37651: (Gateway.load_config) successfully loaded existing target definition
Nov 28 17:01:40 dev11 systemd1: Stopping Ceph iscsi target configuration API...
```
journalctl:
```
Nov 28 17:00:01 dev11 kernel: Unable to locate Target Portal Group on iqn.2003-01.com.redhat.iscsi-gw:iscsi-igw
Nov 28 17:00:01 dev11 kernel: iSCSI Login negotiation failed.
Nov 28 17:00:04 dev11 kernel: Unable to locate Target Portal Group on iqn.2003-01.com.redhat.iscsi-gw:iscsi-igw
Nov 28 17:00:04 dev11 kernel: iSCSI Login negotiation failed.
Nov 28 17:00:06 dev11 ceph-mgr3184: [172.16.1.3:57002] [GET] [500] [45.074s] [admin] [513.0B] /api/health/minimal
Nov 28 17:00:06 dev11 ceph-mgr3184: [b'{"status": "500 Internal Server Error", "detail": "The server encountered an unexpected condition which prevented it from fulfilling the request.", "request_id": "68eed46b-3ece-4e60-bc17-a172358f2d76"} ']
Nov 28 17:00:06 dev11 ceph-mgr3184: [172.16.1.3:60128] [GET] [500] [45.070s] [admin] [513.0B] /api/health/minimal
Nov 28 17:00:06 dev11 ceph-mgr3184: [b'{"status": "500 Internal Server Error", "detail": "The server encountered an unexpected condition which prevented it from fulfilling the request.", "request_id": "5b6fdaa2-dc70-48a7-b01f-ca554ecfec41"} ']
Nov 28 17:00:07 dev11 kernel: Unable to locate Target Portal Group on iqn.2003-01.com.redhat.iscsi-gw:iscsi-igw
Nov 28 17:00:07 dev11 kernel: iSCSI Login negotiation failed.
Nov 28 17:00:11 dev11 kernel: Unable to locate Target Portal Group on iqn.2003-01.com.redhat.iscsi-gw:iscsi-igw
Nov 28 17:00:11 dev11 kernel: iSCSI Login negotiation failed.
Nov 28 17:00:11 dev11 ceph-mgr3184: ::ffff:127.0.0.1 - - [28/Nov/2020:17:00:11] "GET /metrics HTTP/1.1" 200 151419 "" "Prometheus/2.7.2"
Nov 28 17:00:14 dev11 kernel: Unable to locate Target Portal Group on iqn.2003-01.com.redhat.iscsi-gw:iscsi-igw
Nov 28 17:00:14 dev11 kernel: iSCSI Login negotiation failed.
Nov 28 17:00:17 dev11 kernel: Unable to locate Target Portal Group on iqn.2003-01.com.redhat.iscsi-gw:iscsi-igw
Nov 28 17:00:17 dev11 kernel: iSCSI Login negotiation failed.
Nov 28 17:00:20 dev11 kernel: Unable to locate Target Portal Group on iqn.2003-01.com.redhat.iscsi-gw:iscsi-igw
Nov 28 17:00:20 dev11 kernel: iSCSI Login negotiation failed.
Nov 28 17:00:22 dev11 ceph-mgr3184: [172.16.1.3:59834] [GET] [500] [45.062s] [admin] [513.0B] /api/health/minimal
Nov 28 17:00:22 dev11 ceph-mgr3184: [b'{"status": "500 Internal Server Error", "detail": "The server encountered an unexpected condition which prevented it from fulfilling the request.", "request_id": "1ba61331-1dfd-43e7-8ced-9f28aeb8a39c"} ']
Nov 28 17:00:23 dev11 kernel: Unable to locate Target Portal Group on iqn.2003-01.com.redhat.iscsi-gw:iscsi-igw
Nov 28 17:00:23 dev11 kernel: iSCSI Login negotiation failed.
Nov 28 17:00:26 dev11 kernel: Unable to locate Target Portal Group on iqn.2003-01.com.redhat.iscsi-gw:iscsi-igw
Nov 28 17:00:26 dev11 kernel: iSCSI Login negotiation failed.
Nov 28 17:00:26 dev11 ceph-mgr3184: ::ffff:127.0.0.1 - - [28/Nov/2020:17:00:26] "GET /metrics HTTP/1.1" 200 151420 "" "Prometheus/2.7.2"
Nov 28 17:00:27 dev11 ceph-mgr3184: [172.16.1.3:60132] [GET] [500] [45.081s] [admin] [513.0B] /api/health/minimal
Nov 28 17:00:27 dev11 ceph-mgr3184: [b'{"status": "500 Internal Server Error", "detail": "The server encountered an unexpected condition which prevented it from fulfilling the request.", "request_id": "9c1dd49b-07fb-4c49-a033-f5d8d82d9cbe"} ']
Nov 28 17:00:29 dev11 kernel: Unable to locate Target Portal Group on iqn.2003-01.com.redhat.iscsi-gw:iscsi-igw
Nov 28 17:00:29 dev11 kernel: iSCSI Login negotiation failed.
Nov 28 17:00:32 dev11 kernel: Unable to locate Target Portal Group on iqn.2003-01.com.redhat.iscsi-gw:iscsi-igw
Nov 28 17:00:32 dev11 kernel: iSCSI Login negotiation failed.
Nov 28 17:00:35 dev11 kernel: Unable to locate Target Portal Group on iqn.2003-01.com.redhat.iscsi-gw:iscsi-igw
Nov 28 17:00:35 dev11 kernel: iSCSI Login negotiation failed.
```
What should I do for this problem?
Updated by Hamidreza Hosseini over 3 years ago
logs in another location:
In installation step I have this error:
```
Setting up python3-itsdangerous (1.1.0-1) ...
Setting up python3-urwid (2.0.1-3) ...
/usr/lib/python3/dist-packages/urwid/tests/test_canvas.py:141: SyntaxWarning: 'str' object is not callable; perhaps you missed a comma?
assert result expected, "got: %r expected: %r" (result, expected)
/usr/lib/python3/dist-packages/urwid/tests/test_canvas.py:145: SyntaxWarning: 'str' object is not callable; perhaps you missed a comma?
assert result expected, "got: %r expected: %r" (result, expected)
/usr/lib/python3/dist-packages/urwid/tests/test_canvas.py:149: SyntaxWarning: 'str' object is not callable; perhaps you missed a comma?
assert result expected, "got: %r expected: %r" (result, expected)
/usr/lib/python3/dist-packages/urwid/tests/test_canvas.py:232: SyntaxWarning: 'str' object is not callable; perhaps you missed a comma?
assert result expected, "got: %r expected: %r" (result, expected)
Setting up python3-configshell-fb (1:1.1.27-0ubuntu1) ...
Setting up python3-pyudev (0.21.0-3ubuntu1) ...
```
When I run the rbd-target-api manually:
```
root@dev11:/etc/ceph# /usr/bin/rbd-target-api
Traceback (most recent call last):
File "/usr/bin/rbd-target-api", line 2952, in <module>
main()
File "/usr/bin/rbd-target-api", line 2862, in main
osd_state_ok = ceph_gw.osd_blacklist_cleanup()
File "/usr/lib/python3/dist-packages/ceph_iscsi_config/gateway.py", line 110, in osd_blacklist_cleanup
rm_ok = self.ceph_rm_blacklist(blacklist_entry.split(' ')[0])
File "/usr/lib/python3/dist-packages/ceph_iscsi_config/gateway.py", line 46, in ceph_rm_blacklist
if ("un-blacklisting" in result) or ("isn't blacklisted" in result):
TypeError: a bytes-like object is required, not 'str'
```
```
root@dev13:/home/test# systemctl status rbd-target-api
● rbd-target-api.service - Ceph iscsi target configuration API
Loaded: loaded (/lib/systemd/system/rbd-target-api.service; enabled; vendor preset: enabled)
Active: active (running) since Sun 2020-11-29 10:32:59 +0330; 2h 55min ago
Main PID: 54182 (rbd-target-api)
Tasks: 27 (limit: 9451)
Memory: 73.7M
CGroup: /system.slice/rbd-target-api.service
└─54182 /usr/bin/python3 /usr/bin/rbd-target-api
Nov 29 13:27:09 dev13 rbd-target-api54182: ::ffff:192.168.200.23 - - [29/Nov/2020 13:27:09] "GET /api/_ping HTTP/1.1" 200 -
Nov 29 13:27:09 dev13 rbd-target-api54182: ::ffff:192.168.200.23 - - [29/Nov/2020 13:27:09] "GET /api/_ping HTTP/1.1" 200 -
Nov 29 13:27:19 dev13 rbd-target-api54182: ::ffff:192.168.200.23 - - [29/Nov/2020 13:27:19] "GET /api/_ping HTTP/1.1" 200 -
Nov 29 13:27:20 dev13 rbd-target-api54182: _read_config_object object not found
Nov 29 13:27:20 dev13 rbd-target-api54182: Unhandled Exception
Traceback (most recent call last):
File "/usr/lib/python3/dist-packages/flask/app.py", line 1949, in full_dispatch_request
rv = self.dispatch_request()
File "/usr/lib/python3/dist-packages/flask/app.py", line 1935, in dispatch_request
return self.view_functions[rule.endpoint](**req.view_args)
File "/usr/bin/rbd-target-api", line 106, in decorated
return f(*args, **kwargs)
File "/usr/bin/rbd-target-api", line 508, in get_config
config.refresh()
File "/usr/lib/python3/dist-packages/ceph_iscsi_config/common.py", line 506, in refresh
self.config = self.get_config()
File "/usr/lib/python3/dist-packages/ceph_iscsi_config/common.py", line 441, in get_config
return self._get_ceph_config()
File "/usr/lib/python3/dist-packages/ceph_iscsi_config/common.py", line 154, in _get_ceph_config
cfg_data = self._read_config_object(ioctx)
File "/usr/lib/python3/dist-packages/ceph_iscsi_config/common.py", line 113, in _read_config_object
size, mtime = ioctx.stat(self.config_name)
File "rados.pyx", line 578, in rados.requires.wrapper.validate_func
File "rados.pyx", line 3209, in rados.Ioctx.stat
rados.ObjectNotFound: [errno 2] RADOS object not found (Failed to stat b'gateway.conf')
Nov 29 13:27:20 dev13 rbd-target-api54182: ::ffff:127.0.0.1 - - [29/Nov/2020 13:27:20] "GET /api/config HTTP/1.1" 500 -
Nov 29 13:27:29 dev13 rbd-target-api54182: ::ffff:192.168.200.23 - - [29/Nov/2020 13:27:29] "GET /api/_ping HTTP/1.1" 200 -
Nov 29 13:27:39 dev13 rbd-target-api54182: ::ffff:192.168.200.23 - - [29/Nov/2020 13:27:39] "GET /api/_ping HTTP/1.1" 200 -
Nov 29 13:27:49 dev13 rbd-target-api54182: ::ffff:192.168.200.23 - - [29/Nov/2020 13:27:49] "GET /api/_ping HTTP/1.1" 200 -
Nov 29 13:27:59 dev13 rbd-target-api54182: ::ffff:192.168.200.23 - - [29/Nov/2020 13:27:59] "GET /api/_ping HTTP/1.1" 200 -
```