Bug 2281609
| Summary: | [2 GW config] Upon a failover nvmeof service on Active GW will be down for few seconds making all GWs Unavailable | ||
|---|---|---|---|
| Product: | [Red Hat Storage] Red Hat Ceph Storage | Reporter: | Rahul Lepakshi <rlepaksh> |
| Component: | NVMeOF | Assignee: | Aviv Caro <acaro> |
| Status: | CLOSED DUPLICATE | QA Contact: | Rahul Lepakshi <rlepaksh> |
| Severity: | urgent | Docs Contact: | ceph-doc-bot <ceph-doc-bugzilla> |
| Priority: | unspecified | ||
| Version: | 7.1 | CC: | cephqe-warriors, owasserm |
| Target Milestone: | --- | ||
| Target Release: | 7.1 | ||
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2024-05-23 17:01:07 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
@rahul.lepakshi it looks to me like 46-51 is having some network issues and that's why it dies. From your log: May 16 16:39:31 dhcp46-51 ceph-7cb10714-12cc-11ef-a234-005056ba118c-nvmeof-nvmeof_pool-dhcp46-51-ltnjmw[27028]: [16-May-2024 11:09:31] DEBUG grpc.py:2459: Received request to get subsystems, context: <grpc._server._Context object at 0x7f717c226730>, client address: IPv4 10.70.46.51:43146 May 16 16:39:33 dhcp46-51 ceph-7cb10714-12cc-11ef-a234-005056ba118c-nvmeof-nvmeof_pool-dhcp46-51-ltnjmw[27028]: [16-May-2024 11:09:33] DEBUG grpc.py:2459: Received request to get subsystems, context: <grpc._server._Context object at 0x7f717c226a00>, client address: IPv4 10.70.46.51:43154 May 16 16:40:20 dhcp46-51 ceph-7cb10714-12cc-11ef-a234-005056ba118c-nvmeof-nvmeof_pool-dhcp46-51-ltnjmw[27028]: [2024-05-16 11:10:20.545440] ctrlr.c: 178:nvmf_ctrlr_keep_alive_poll: *NOTICE*: Disconnecting host nqn.2014-08.org.nvmexpress:uuid:cdda3442-e62a-6977-3b53-287b0c4e71fb from subsystem nqn.2016-06.io.spdk:cnode1 due to keep alive timeout. May 16 16:40:27 dhcp46-51 ceph-7cb10714-12cc-11ef-a234-005056ba118c-nvmeof-nvmeof_pool-dhcp46-51-ltnjmw[27028]: [2024-05-16 11:10:27.615035] ctrlr.c: 178:nvmf_ctrlr_keep_alive_poll: *NOTICE*: Disconnecting host nqn.2014-08.org.nvmexpress:uuid:cdda3442-e62a-6977-3b53-287b0c4e71fb from subsystem nqn.2016-06.io.spdk:cnode2 due to keep alive timeout. May 16 16:40:30 dhcp46-51 ceph-7cb10714-12cc-11ef-a234-005056ba118c-nvmeof-nvmeof_pool-dhcp46-51-ltnjmw[27028]: [2024-05-16 11:10:30.306569] posix.c: 273:posix_sock_getaddr: *ERROR*: getpeername() failed (errno=107) May 16 16:40:30 dhcp46-51 ceph-7cb10714-12cc-11ef-a234-005056ba118c-nvmeof-nvmeof_pool-dhcp46-51-ltnjmw[27028]: [2024-05-16 11:10:30.307151] tcp.c:1330:nvmf_tcp_handle_connect: *ERROR*: spdk_sock_getaddr() failed of tqpair=0xb5ca9a0 May 16 16:40:30 dhcp46-51 ceph-7cb10714-12cc-11ef-a234-005056ba118c-nvmeof-nvmeof_pool-dhcp46-51-ltnjmw[27028]: [2024-05-16 11:10:30.526762] ctrlr.c: 178:nvmf_ctrlr_keep_alive_poll: *NOTICE*: Disconnecting host nqn.2014-08.org.nvmexpress:uuid:cdda3442-e62a-6977-3b53-287b0c4e71fb from subsystem nqn.2016-06.io.spdk:cnode1 due to keep alive timeout. May 16 16:40:30 dhcp46-51 ceph-7cb10714-12cc-11ef-a234-005056ba118c-nvmeof-nvmeof_pool-dhcp46-51-ltnjmw[27028]: terminate called after throwing an instance of 'std::runtime_error' May 16 16:40:31 dhcp46-51 ceph-7cb10714-12cc-11ef-a234-005056ba118c-nvmeof-nvmeof_pool-dhcp46-51-ltnjmw[27028]: what(): Lost connection to the monitor (gw map unavailable). May 16 16:40:31 dhcp46-51 ceph-7cb10714-12cc-11ef-a234-005056ba118c-nvmeof-nvmeof_pool-dhcp46-51-ltnjmw[27028]: *** Caught signal (Aborted) ** So we can see that both SPDK and nvmeof monitor client complains at the same time about networking issues. The SPDK says it is not getting KA from the initiator, and the nvmeof monitor client complains it cannot communicate to the monitor. o we can see that both SPDK and nvmeof monitor client complains at the same time about networking issues. The SPDK says it is not getting KA from the initiator, and the nvmeof monitor client complains it cannot communicate to the monitor. Can you see if this is reproduced? *** This bug has been marked as a duplicate of bug 2281800 *** |
Description of problem: Upon a failover, Live GW will kind of reboot for few seconds and comes back. This creates DU for a while [ceph: root@dhcp44-55 /]# ceph nvme-gw show nvmeof_pool '' { "epoch": 680, "pool": "nvmeof_pool", "group": "", "num gws": 2, "Anagrp list": "[ 1 2 ]" } { "gw-id": "client.nvmeof.nvmeof_pool.dhcp46-49.aqdhlx", "anagrp-id": 1, "performed-full-startup": 0, "Availability": "UNAVAILABLE", "ana states": " 1: STANDBY , 2: STANDBY ," } { "gw-id": "client.nvmeof.nvmeof_pool.dhcp46-51.ltnjmw", "anagrp-id": 2, "performed-full-startup": 1, "Availability": "AVAILABLE", "ana states": " 1: ACTIVE , 2: ACTIVE ," } [ceph: root@dhcp44-55 /]# ceph nvme-gw show nvmeof_pool '' { "epoch": 681, "pool": "nvmeof_pool", "group": "", "num gws": 2, "Anagrp list": "[ 1 2 ]" } { "gw-id": "client.nvmeof.nvmeof_pool.dhcp46-49.aqdhlx", "anagrp-id": 1, "performed-full-startup": 0, "Availability": "UNAVAILABLE", "ana states": " 1: STANDBY , 2: STANDBY ," ------------------------------>>> This is expected because of Failover } { "gw-id": "client.nvmeof.nvmeof_pool.dhcp46-51.ltnjmw", "anagrp-id": 2, "performed-full-startup": 0, "Availability": "UNAVAILABLE", "ana states": " 1: STANDBY , 2: STANDBY ," -------------->>> This is not expected and is a Data Unavailability. GW service kind of reboots (This is strange) } [ceph: root@dhcp44-55 /]# ceph nvme-gw show nvmeof_pool '' { "epoch": 691, "pool": "nvmeof_pool", "group": "", "num gws": 2, "Anagrp list": "[ 1 2 ]" } { "gw-id": "client.nvmeof.nvmeof_pool.dhcp46-49.aqdhlx", "anagrp-id": 1, "performed-full-startup": 0, "Availability": "UNAVAILABLE", "ana states": " 1: STANDBY , 2: STANDBY ," } { "gw-id": "client.nvmeof.nvmeof_pool.dhcp46-51.ltnjmw", "anagrp-id": 2, "performed-full-startup": 1, "Availability": "AVAILABLE", "ana states": " 1: ACTIVE , 2: ACTIVE ," } Version-Release number of selected component (if applicable): [ceph: root@dhcp44-55 /]# ceph version ceph version 18.2.1-173.el9cp (6820b327efd7c9026508bce15c960bb8c75297d3) reef (stable) nvmeof - icr.io/ibm-ceph-beta/nvmeof-rhel9:1.2.7-1 How reproducible:1/2 Steps to Reproduce: 1. Deploy nvmeof service on 2 GWs 2. Perform Failover on GW-A - successful failover 3. After few seconds, observe GW-B also going to Unavailable state Actual results: Both GWs were down for few seocnds which is an issue as whole nvmeof is down for initiators Expected results: We should not expect GW-B also going down for reasons we do not / we intentionally did not bring it down Additional info: [16-May-2024 11:09:26] DEBUG grpc.py:884: set_ana_state bdev_rbd_wait_for_latest_osdmap cluster='cluster_context_1_5' [2024-05-16 11:09:26.288187] bdev_rbd.c:1039:_bdev_rbd_wait_for_latest_osdmap: *ERROR*: rados_wait_for_latest_osdmap cluster: cluster_context_1_6 elapsed time: 0.026807 seconds [16-May-2024 11:09:26] DEBUG grpc.py:884: set_ana_state bdev_rbd_wait_for_latest_osdmap cluster='cluster_context_1_6' [16-May-2024 11:09:26] DEBUG grpc.py:887: set_ana_state nvmf_subsystem_listener_set_ana_state nqn='nqn.2016-06.io.spdk:cnode1' listener=('ipv4', '10.70.46.51', 4420) ana_state='optimized' grp_id=1 [16-May-2024 11:09:26] DEBUG grpc.py:900: set_ana_state nvmf_subsystem_listener_set_ana_state response ret=True [16-May-2024 11:09:26] DEBUG grpc.py:2091: Subsystem nqn.2016-06.io.spdk:cnode2 enable_ha: True [16-May-2024 11:09:26] DEBUG grpc.py:864: Iterate over nqn='nqn.2016-06.io.spdk:cnode2' self.subsystem_listeners[nqn]={('ipv4', '10.70.46.51', 4420)} [16-May-2024 11:09:26] DEBUG grpc.py:866: listener=('ipv4', '10.70.46.51', 4420) [16-May-2024 11:09:26] DEBUG grpc.py:887: set_ana_state nvmf_subsystem_listener_set_ana_state nqn='nqn.2016-06.io.spdk:cnode2' listener=('ipv4', '10.70.46.51', 4420) ana_state='optimized' grp_id=1 [16-May-2024 11:09:26] DEBUG grpc.py:900: set_ana_state nvmf_subsystem_listener_set_ana_state response ret=True [16-May-2024 11:09:27] DEBUG grpc.py:2459: Received request to get subsystems, context: <grpc._server._Context object at 0x7f7178178970>, client address: IPv4 10.70.46.51:43120 [16-May-2024 11:09:29] DEBUG grpc.py:2459: Received request to get subsystems, context: <grpc._server._Context object at 0x7f717c3a8a60>, client address: IPv4 10.70.46.51:43132 [2024-05-16 11:09:30.686645] ctrlr.c: 178:nvmf_ctrlr_keep_alive_poll: *NOTICE*: Disconnecting host nqn.2014-08.org.nvmexpress:uuid:cdda3442-e62a-6977-3b53-287b0c4e71fb from subsystem nqn.2016-06.io.spdk:cnode2 due to keep alive timeout. [16-May-2024 11:09:31] DEBUG grpc.py:2459: Received request to get subsystems, context: <grpc._server._Context object at 0x7f717c226730>, client address: IPv4 10.70.46.51:43146 [16-May-2024 11:09:33] DEBUG grpc.py:2459: Received request to get subsystems, context: <grpc._server._Context object at 0x7f717c226a00>, client address: IPv4 10.70.46.51:43154 [2024-05-16 11:10:20.545440] ctrlr.c: 178:nvmf_ctrlr_keep_alive_poll: *NOTICE*: Disconnecting host nqn.2014-08.org.nvmexpress:uuid:cdda3442-e62a-6977-3b53-287b0c4e71fb from subsystem nqn.2016-06.io.spdk:cnode1 due to keep alive timeout. [2024-05-16 11:10:27.615035] ctrlr.c: 178:nvmf_ctrlr_keep_alive_poll: *NOTICE*: Disconnecting host nqn.2014-08.org.nvmexpress:uuid:cdda3442-e62a-6977-3b53-287b0c4e71fb from subsystem nqn.2016-06.io.spdk:cnode2 due to keep alive timeout. [2024-05-16 11:10:30.306569] posix.c: 273:posix_sock_getaddr: *ERROR*: getpeername() failed (errno=107) [2024-05-16 11:10:30.307151] tcp.c:1330:nvmf_tcp_handle_connect: *ERROR*: spdk_sock_getaddr() failed of tqpair=0xb5ca9a0 [2024-05-16 11:10:30.526762] ctrlr.c: 178:nvmf_ctrlr_keep_alive_poll: *NOTICE*: Disconnecting host nqn.2014-08.org.nvmexpress:uuid:cdda3442-e62a-6977-3b53-287b0c4e71fb from subsystem nqn.2016-06.io.spdk:cnode1 due to keep alive timeout. terminate called after throwing an instance of 'std::runtime_error' what(): Lost connection to the monitor (gw map unavailable). *** Caught signal (Aborted) ** in thread 7f7679e0a640 thread_name:ms_dispatch ceph version 18.2.1-173.el9cp (6820b327efd7c9026508bce15c960bb8c75297d3) reef (stable) 1: /lib64/libc.so.6(+0x3e6f0) [0x7f767f0dc6f0] 2: /lib64/libc.so.6(+0x8b94c) [0x7f767f12994c] 3: raise() 4: abort() 5: /lib64/libstdc++.so.6(+0xa1b21) [0x7f767f440b21] 6: /lib64/libstdc++.so.6(+0xad52c) [0x7f767f44c52c] 7: /lib64/libstdc++.so.6(+0xad597) [0x7f767f44c597] 8: /lib64/libstdc++.so.6(+0xad7f9) [0x7f767f44c7f9] 9: /usr/bin/ceph-nvmeof-monitor-client(+0x8a758) [0x5632b4984758] 10: (NVMeofGwMonitorClient::ms_dispatch2(boost::intrusive_ptr<Message> const&)+0x185) [0x5632b4a18e25] 11: (DispatchQueue::entry()+0x542) [0x7f767fe93f52] 12: /usr/lib64/ceph/libceph-common.so.2(+0x3fad81) [0x7f767ff2bd81] 13: /lib64/libc.so.6(+0x89c02) [0x7f767f127c02] 14: /lib64/libc.so.6(+0x10ec40) [0x7f767f1acc40] [16-May-2024 11:10:33] ERROR server.py:42: GatewayServer: SIGCHLD received signum=17 [16-May-2024 11:10:33] ERROR server.py:109: GatewayServer exception occurred: Traceback (most recent call last): File "/remote-source/ceph-nvmeof/app/control/__main__.py", line 44, in <module> gateway.keep_alive() File "/remote-source/ceph-nvmeof/app/control/server.py", line 490, in keep_alive alive = self._ping() File "/remote-source/ceph-nvmeof/app/control/server.py", line 503, in _ping ret = spdk.rpc.spdk_get_version(self.spdk_rpc_ping_client) File "/usr/local/lib/python3.9/site-packages/spdk/rpc/__init__.py", line 78, in spdk_get_version return client.call('spdk_get_version') File "/usr/local/lib/python3.9/site-packages/spdk/rpc/client.py", line 189, in call response = self.recv() File "/usr/local/lib/python3.9/site-packages/spdk/rpc/client.py", line 166, in recv newdata = self.sock.recv(4096) File "/remote-source/ceph-nvmeof/app/control/server.py", line 54, in sigchld_handler raise SystemExit(f"Gateway subprocess terminated {pid=} {exit_code=}") SystemExit: Gateway subprocess terminated pid=19 exit_code=-6 [16-May-2024 11:10:33] INFO server.py:409: Aborting (client.nvmeof.nvmeof_pool.dhcp46-51.ltnjmw) pid 19... [16-May-2024 11:10:33] INFO server.py:409: Aborting (client.nvmeof.nvmeof_pool.dhcp46-51.ltnjmw) pid 54... [16-May-2024 11:11:33] ERROR server.py:415: (client.nvmeof.nvmeof_pool.dhcp46-51.ltnjmw) pid 54 timeout occurred while terminating sub process: Traceback (most recent call last): File "/remote-source/ceph-nvmeof/app/control/__main__.py", line 44, in <module> gateway.keep_alive() File "/remote-source/ceph-nvmeof/app/control/server.py", line 490, in keep_alive alive = self._ping() File "/remote-source/ceph-nvmeof/app/control/server.py", line 503, in _ping ret = spdk.rpc.spdk_get_version(self.spdk_rpc_ping_client) File "/usr/local/lib/python3.9/site-packages/spdk/rpc/__init__.py", line 78, in spdk_get_version return client.call('spdk_get_version') File "/usr/local/lib/python3.9/site-packages/spdk/rpc/client.py", line 189, in call response = self.recv() File "/usr/local/lib/python3.9/site-packages/spdk/rpc/client.py", line 166, in recv newdata = self.sock.recv(4096) File "/remote-source/ceph-nvmeof/app/control/server.py", line 54, in sigchld_handler raise SystemExit(f"Gateway subprocess terminated {pid=} {exit_code=}") SystemExit: Gateway subprocess terminated pid=19 exit_code=-6 During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/remote-source/ceph-nvmeof/app/control/server.py", line 413, in _stop_subprocess proc.communicate(timeout=timeout) File "/usr/lib64/python3.9/subprocess.py", line 1134, in communicate stdout, stderr = self._communicate(input, endtime, timeout) File "/usr/lib64/python3.9/subprocess.py", line 2021, in _communicate self.wait(timeout=self._remaining_time(endtime)) File "/usr/lib64/python3.9/subprocess.py", line 1189, in wait return self._wait(timeout=timeout) File "/usr/lib64/python3.9/subprocess.py", line 1925, in _wait raise TimeoutExpired(self.args, timeout) subprocess.TimeoutExpired: Command '['/usr/local/bin/nvmf_tgt', '-u', '-r', '/var/tmp/spdk.sock', '--cpumask=0xF']' timed out after 59.999969070995576 seconds [16-May-2024 11:11:34] INFO server.py:123: Stopping the server... [16-May-2024 11:11:34] INFO server.py:441: Terminating discovery service... [16-May-2024 11:11:36] INFO server.py:448: Discovery service terminated [16-May-2024 11:11:36] INFO server.py:130: Exiting the gateway process. [16-May-2024 11:11:37] INFO utils.py:392: Will compress log file /var/log/ceph/nvmeof-client.nvmeof.nvmeof_pool.dhcp46-51.ltnjmw/nvmeof-log to /var/log/ceph/nvmeof-client.nvmeof.nvmeof_pool.dhcp46-51.ltnjmw/nvmeof-log.gz Gateway subprocess terminated pid=19 exit_code=-6 May 16 16:41:45 dhcp46-51 podman[499695]: 2024-05-16 16:41:45.383159798 +0530 IST m=+0.119908584 container died 530abe92eb2a7a72f5e1135fd29c5f86faf2d430637d3386ed329953f2799b77 2024-05-16T11:09:25.998+0000 7f700c0bf640 10 nvmeofgw virtual void NVMeofGwMon::update_from_paxos(bool*) NVMeGW loading version 680 679 2024-05-16T11:09:25.998+0000 7f700c0bf640 10 nvmeofgw void NVMeofGwMon::check_subs(bool) count 0 2024-05-16T11:09:25.998+0000 7f700c0bf640 10 nvmeofgw virtual void NVMeofGwMon::create_pending() pending NVMeofGwMap [ Created_gws: nvmeofgw { NvmeGroupKey {nvmeof_pool,} } -> { nvmeofgw gw_id: client.nvmeof.nvmeof_pool.dhcp46-49.aqdhlx [ ==Internal map ==NvmeGwCreated { ana_group_id 0 osd_epochs: 0: 0:1 1: 0:1 nvmeofgw nonces: nvmeofgw ana_grp: 0 [ 10.70.46.49:0/3056921583 10.70.46.49:0/3557748576 10.70.46.49:0/1030381799 10.70.46.49:0/798930233 10.70.46.49:0/1793142366 10.70.46.49:0/3595577003 10.70.46.49:0/2566383124 ] nvmeofgw ana_grp: 1 [ 10.70.46.49:0/3380609428 10.70.46.49:0/1658102602 10.70.46.49:0/2311753931 10.70.46.49:0/2619487039 10.70.46.49:0/1471376401 10.70.46.49:0/3133509586 10.70.46.49:0/3795208795 ] nvmeofgw } 0: STANDBY , 1: STANDBY ,] nvmeofgw availability UNAVAILABLE full-startup 0 ]] nvmeofgw gw_id: client.nvmeof.nvmeof_pool.dhcp46-51.ltnjmw [ ==Internal map ==NvmeGwCreated { ana_group_id 1 osd_epochs: 0: 0:1 1: 0:1 nvmeofgw nonces: nvmeofgw ana_grp: 0 [ 10.70.46.51:0/4157594848 10.70.46.51:0/577298829 10.70.46.51:0/685961554 10.70.46.51:0/4054848657 10.70.46.51:0/145262826 10.70.46.51:0/1197956956 10.70.46.51:0/3666315236 ] nvmeofgw ana_grp: 1 [ 10.70.46.51:0/2680632929 10.70.46.51:0/2837358542 10.70.46.51:0/919296944 10.70.46.51:0/4015199542 10.70.46.51:0/2335507883 10.70.46.51:0/2073867443 10.70.46.51:0/2741063863 ] nvmeofgw } 0: ACTIVE , 1: ACTIVE ,] nvmeofgw availability AVAILABLE full-startup 1 ]] nvmeofgw }] 2024-05-16T11:09:26.420+0000 7f700e8c4640 10 nvmeofgw bool NVMeofGwMon::preprocess_command(MonOpRequestRef) 2024-05-16T11:09:26.420+0000 7f700e8c4640 10 nvmeofgw bool NVMeofGwMon::preprocess_command(MonOpRequestRef) MonCommand : nvme-gw show 2024-05-16T11:09:26.420+0000 7f700e8c4640 10 nvmeofgw bool NVMeofGwMon::prepare_command(MonOpRequestRef) 2024-05-16T11:09:26.420+0000 7f700e8c4640 10 nvmeofgw bool NVMeofGwMon::prepare_command(MonOpRequestRef) MonCommand : nvme-gw show 2024-05-16T11:09:26.420+0000 7f700e8c4640 10 nvmeofgw bool NVMeofGwMon::prepare_command(MonOpRequestRef) nvme-gw show pool nvmeof_pool group 2024-05-16T11:09:43.720+0000 7f70110c9640 10 nvmeofgw virtual void NVMeofGwMon::tick() beacon timeout for GW client.nvmeof.nvmeof_pool.dhcp46-51.ltnjmw