search

Seagate / cortx-motr

CORTX Motr is a distributed object and key-value storage system targeting mass capacity storage configurations. It's the core component of CORTX storage system.
https://github.com/Seagate/cortx
Apache License 2.0
59 stars 142 forks source link

Add automatic degraded read write mode #1598

Closed andriytk closed 2 years ago

andriytk commented 2 years ago

Currently, Motr needs the failed notification from Hare about the cluster entity (disk, node, etc.) in order to start working in the degraded mode. This is OK and fine, but we need to add a few more cases for the degraded mode to start ON automatically.

  1. On timeout error. When some unit of the parity group cannot be written or read due to the rpc timeout error - we should 1) report it to Hare and 2) switch to the degraded rw mode automatically.
  2. On an error (disk I/O or network or anything else). Similarly to the above case, we should 1) report the error to Hare and 2) switch to the degraded mode immediately.

In write case, degraded mode means that we don't return error to the user unless there are more than K failures for any parity group written. (Currently, we always return an error to the user if any unit write from any parity group failed to be written.)

In both cases, the client should remember the decision for this cluster entity (disk, node, etc.) and continue working in degraded mode for the next requests which would involve this entity. The client should keep some timer for this decision (like 5 mins) in order to try normal mode again later with this cluster entity. (Unless this entity was reported as failed by Hare, in which case the timer should stop and the normal mode is not started until Hare reported the entity as online.)

See more at https://github.com/Seagate/cortx-motr/blob/documentation/doc/dev/dewrite/index.rst

cc @siningwuseagate

cortx-admin commented 2 years ago

For the convenience of the Seagate development team, this issue has been mirrored in a private Seagate Jira Server: https://jts.seagate.com/browse/CORTX-30727. Note that community members will not be able to access that Jira server but that is not a problem since all activity in that Jira mirror will be copied into this GitHub issue.

cortx-admin commented 2 years ago

Chandradhar Raval commented in Jira Server:

[~520414] - Can we directly open Jira ticket(instead of github) for issues that you create?

Also can you update problem description here?

andriytk commented 2 years ago

Dear @cortx-admin, we find working with github much more convenient and aligned with our CORTX project "Open Everything" paradigm (see the correspondent email from Abhay dated by 25th Jan) than with Jira (which is slow, inconvenient and closed).

The description of this ticket is to be updated by @nikitadanilov, as mentioned there.

andriytk commented 2 years ago

Degraded read when the disk is failed by Hare works fine:

$ ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x29 -prof 0x7000000000000001:0x51 -hax inet:tcp:192.168.180.165@22001 -v /tmp/200m 12345:6789001
2022/04/12 19:57:54 mio.go:556: W: off=0 len=33554432 bs=33554432 gs=16777216 speed=17 (Mbytes/sec)
2022/04/12 19:57:55 mio.go:556: W: off=33554432 len=33554432 bs=33554432 gs=16777216 speed=22 (Mbytes/sec)
2022/04/12 19:57:57 mio.go:556: W: off=67108864 len=33554432 bs=33554432 gs=16777216 speed=24 (Mbytes/sec)
2022/04/12 19:57:58 mio.go:556: W: off=100663296 len=33554432 bs=33554432 gs=16777216 speed=19 (Mbytes/sec)
2022/04/12 19:58:00 mio.go:556: W: off=134217728 len=33554432 bs=33554432 gs=16777216 speed=21 (Mbytes/sec)
2022/04/12 19:58:01 mio.go:556: W: off=167772160 len=33554432 bs=33554432 gs=16777216 speed=19 (Mbytes/sec)
2022/04/12 19:58:02 mio.go:556: W: off=201326592 len=8388608 bs=16777216 gs=16777216 speed=12 (Mbytes/sec)
19:58 ant@rocky83:mcp$ ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x29 -prof 0x7000000000000001:0x51 -hax inet:tcp:192.168.180.165@22001 -v -osz $((200*1024)) 12345:6789001 /tmp/200m.check
2022/04/12 19:58:09 mio.go:628: R: off=0 len=33554432 bs=33554432 gs=16777216 speed=33 (Mbytes/sec)
2022/04/12 19:58:09 mio.go:628: R: off=33554432 len=33554432 bs=33554432 gs=16777216 speed=41 (Mbytes/sec)
2022/04/12 19:58:10 mio.go:628: R: off=67108864 len=33554432 bs=33554432 gs=16777216 speed=44 (Mbytes/sec)
2022/04/12 19:58:11 mio.go:628: R: off=100663296 len=33554432 bs=33554432 gs=16777216 speed=32 (Mbytes/sec)
2022/04/12 19:58:12 mio.go:628: R: off=134217728 len=33554432 bs=33554432 gs=16777216 speed=41 (Mbytes/sec)
2022/04/12 19:58:13 mio.go:628: R: off=167772160 len=33554432 bs=33554432 gs=16777216 speed=34 (Mbytes/sec)
2022/04/12 19:58:14 mio.go:628: R: off=201326592 len=8388608 bs=16777216 gs=16777216 speed=9660 (Kbytes/sec)
19:58 ant@rocky83:mcp$ 
19:58 ant@rocky83:mcp$ cmp /tmp/200m{,.check}
19:58 ant@rocky83:mcp$ 
19:58 ant@rocky83:mcp$ hctl drive-state --json $(jq --null-input --compact-output '{ node: "rocky83", source_type: "drive", device: "/dev/loop1", state: "failed" }')
0
2022-04-12 19:58:47,431 [DEBUG] Bound <class 'hax.common.HaxGlobalState'> to an instance <hax.common.HaxGlobalState object at 0x7fd2fc18e240>
2022-04-12 19:58:47,431 [DEBUG] Created and configured an injector, config=<function di_configuration at 0x7fd2fb7a5ae8>
2022-04-12 19:58:47,436 [DEBUG] Starting new HTTP connection (1): 127.0.0.1:8500
2022-04-12 19:58:47,438 [DEBUG] http://127.0.0.1:8500 "GET /v1/kv/eq-epoch HTTP/1.1" 200 91
2022-04-12 19:58:47,442 [DEBUG] http://127.0.0.1:8500 "PUT /v1/txn HTTP/1.1" 200 219
2022-04-12 19:58:47,443 [INFO] Written to epoch: 2
19:58 ant@rocky83:mcp$ 
19:58 ant@rocky83:mcp$ ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x29 -prof 0x7000000000000001:0x51 -hax inet:tcp:192.168.180.165@22001 -v -osz $((200*1024)) 12345:6789001 /tmp/200m.check
motr[146981]:  c5a0  ERROR  [pool/pool_machine.c:531:spare_usage_arr_update]  <7600000000000001:32>: No free spare space slot is found, this pool version is in DUD state; event_index=1 event_state=2
motr[146981]:  9a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x1906140 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
motr[146981]:  9a90   WARN  [io_req.c:1665:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x1906140 dgmap_nr=4
2022/04/12 19:59:16 mio.go:628: R: off=0 len=33554432 bs=33554432 gs=16777216 speed=15 (Mbytes/sec)
motr[146981]:  3a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7fbc9403ace0 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
motr[146981]:  3a90   WARN  [io_req.c:1665:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x7fbc9403ace0 dgmap_nr=4
2022/04/12 19:59:18 mio.go:628: R: off=33554432 len=33554432 bs=33554432 gs=16777216 speed=19 (Mbytes/sec)
2022/04/12 19:59:19 mio.go:628: R: off=67108864 len=33554432 bs=33554432 gs=16777216 speed=41 (Mbytes/sec)
motr[146981]:  ca00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7fbc9403ace0 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
motr[146981]:  ca90   WARN  [io_req.c:1665:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x7fbc9403ace0 dgmap_nr=4
2022/04/12 19:59:20 mio.go:628: R: off=100663296 len=33554432 bs=33554432 gs=16777216 speed=18 (Mbytes/sec)
motr[146981]:  ca00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7fbc9403ace0 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
motr[146981]:  ca90   WARN  [io_req.c:1665:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x7fbc9403ace0 dgmap_nr=4
2022/04/12 19:59:22 mio.go:628: R: off=134217728 len=33554432 bs=33554432 gs=16777216 speed=19 (Mbytes/sec)
2022/04/12 19:59:23 mio.go:628: R: off=167772160 len=33554432 bs=33554432 gs=16777216 speed=36 (Mbytes/sec)
motr[146981]:  ca00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7fbc9403ace0 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
motr[146981]:  ca90   WARN  [io_req.c:1665:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x7fbc9403ace0 dgmap_nr=4
2022/04/12 19:59:25 mio.go:628: R: off=201326592 len=8388608 bs=16777216 gs=16777216 speed=5009 (Kbytes/sec)
19:59 ant@rocky83:mcp$ 
19:59 ant@rocky83:mcp$ 
19:59 ant@rocky83:mcp$ cmp /tmp/200m{,.check}
19:59 ant@rocky83:mcp$

Versions: motr - 899e8fe43, hare - 16590f0.

andriytk commented 2 years ago

Degraded write works too:

20:02 ant@rocky83:mcp$ ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x29 -prof 0x7000000000000001:0x51 -hax inet:tcp:192.168.180.165@22001 -v /tmp/200m 12345:6789001
motr[150433]:  65a0  ERROR  [pool/pool_machine.c:531:spare_usage_arr_update]  <7600000000000001:32>: No free spare space slot is found, this pool version is in DUD state; event_index=1 event_state=2
motr[150433]:  6a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7f0b5c000e20 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
2022/04/12 20:02:40 mio.go:556: W: off=0 len=33554432 bs=33554432 gs=16777216 speed=9725 (Kbytes/sec)
motr[150433]:  6a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7f0b5c000e20 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
2022/04/12 20:02:43 mio.go:556: W: off=33554432 len=33554432 bs=33554432 gs=16777216 speed=12 (Mbytes/sec)
motr[150433]:  6a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7f0b5c000e20 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
2022/04/12 20:02:45 mio.go:556: W: off=67108864 len=33554432 bs=33554432 gs=16777216 speed=13 (Mbytes/sec)
motr[150433]:  6a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7f0b5c000e20 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
2022/04/12 20:02:48 mio.go:556: W: off=100663296 len=33554432 bs=33554432 gs=16777216 speed=12 (Mbytes/sec)
motr[150433]:  8a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7f0b5c000e20 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
2022/04/12 20:02:50 mio.go:556: W: off=134217728 len=33554432 bs=33554432 gs=16777216 speed=12 (Mbytes/sec)
motr[150433]:  8a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7f0b5c000e20 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
2022/04/12 20:02:52 mio.go:556: W: off=167772160 len=33554432 bs=33554432 gs=16777216 speed=13 (Mbytes/sec)
motr[150433]:  8a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7f0b5c000e20 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
2022/04/12 20:02:54 mio.go:556: W: off=201326592 len=8388608 bs=16777216 gs=16777216 speed=6547 (Kbytes/sec)
20:02 ant@rocky83:mcp$ echo $?
0
20:03 ant@rocky83:mcp$ 
20:03 ant@rocky83:mcp$ ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x29 -prof 0x7000000000000001:0x51 -hax inet:tcp:192.168.180.165@22001 -v /tmp/200m 12345:6789002
motr[151319]:  a5a0  ERROR  [pool/pool_machine.c:531:spare_usage_arr_update]  <7600000000000001:32>: No free spare space slot is found, this pool version is in DUD state; event_index=1 event_state=2
2022/04/12 20:03:29 mio.go:556: W: off=0 len=33554432 bs=33554432 gs=16777216 speed=20 (Mbytes/sec)
2022/04/12 20:03:30 mio.go:556: W: off=33554432 len=33554432 bs=33554432 gs=16777216 speed=20 (Mbytes/sec)
2022/04/12 20:03:32 mio.go:556: W: off=67108864 len=33554432 bs=33554432 gs=16777216 speed=23 (Mbytes/sec)
2022/04/12 20:03:33 mio.go:556: W: off=100663296 len=33554432 bs=33554432 gs=16777216 speed=22 (Mbytes/sec)
2022/04/12 20:03:35 mio.go:556: W: off=134217728 len=33554432 bs=33554432 gs=16777216 speed=19 (Mbytes/sec)
2022/04/12 20:03:36 mio.go:556: W: off=167772160 len=33554432 bs=33554432 gs=16777216 speed=24 (Mbytes/sec)
2022/04/12 20:03:37 mio.go:556: W: off=201326592 len=8388608 bs=16777216 gs=16777216 speed=11 (Mbytes/sec)
20:03 ant@rocky83:mcp$ 
20:03 ant@rocky83:mcp$ 
20:03 ant@rocky83:mcp$ ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x29 -prof 0x7000000000000001:0x51 -hax inet:tcp:192.168.180.165@22001 -v -osz $((200*1024)) 12345:6789002 /tmp/200m.check
motr[152251]:  75a0  ERROR  [pool/pool_machine.c:531:spare_usage_arr_update]  <7600000000000001:32>: No free spare space slot is found, this pool version is in DUD state; event_index=1 event_state=2
2022/04/12 20:04:22 mio.go:628: R: off=0 len=33554432 bs=33554432 gs=16777216 speed=35 (Mbytes/sec)
2022/04/12 20:04:22 mio.go:628: R: off=33554432 len=33554432 bs=33554432 gs=16777216 speed=48 (Mbytes/sec)
2022/04/12 20:04:23 mio.go:628: R: off=67108864 len=33554432 bs=33554432 gs=16777216 speed=39 (Mbytes/sec)
2022/04/12 20:04:24 mio.go:628: R: off=100663296 len=33554432 bs=33554432 gs=16777216 speed=37 (Mbytes/sec)
2022/04/12 20:04:25 mio.go:628: R: off=134217728 len=33554432 bs=33554432 gs=16777216 speed=44 (Mbytes/sec)
2022/04/12 20:04:25 mio.go:628: R: off=167772160 len=33554432 bs=33554432 gs=16777216 speed=46 (Mbytes/sec)
2022/04/12 20:04:26 mio.go:628: R: off=201326592 len=8388608 bs=16777216 gs=16777216 speed=21 (Mbytes/sec)
20:04 ant@rocky83:mcp$ 
20:04 ant@rocky83:mcp$ 
20:04 ant@rocky83:mcp$ cmp /tmp/200m{,.check}
20:04 ant@rocky83:mcp$ 
20:04 ant@rocky83:mcp$ ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x29 -prof 0x7000000000000001:0x51 -hax inet:tcp:192.168.180.165@22001 -v -osz $((200*1024)) 12345:6789001 /tmp/200m.check
motr[153375]:  c5a0  ERROR  [pool/pool_machine.c:531:spare_usage_arr_update]  <7600000000000001:32>: No free spare space slot is found, this pool version is in DUD state; event_index=1 event_state=2
motr[153375]:  9a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x1bf5290 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
motr[153375]:  9a90   WARN  [io_req.c:1665:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x1bf5290 dgmap_nr=4
2022/04/12 20:05:27 mio.go:628: R: off=0 len=33554432 bs=33554432 gs=16777216 speed=18 (Mbytes/sec)
motr[153375]:  9a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7fe94003ace0 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
motr[153375]:  9a90   WARN  [io_req.c:1665:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x7fe94003ace0 dgmap_nr=4
2022/04/12 20:05:28 mio.go:628: R: off=33554432 len=33554432 bs=33554432 gs=16777216 speed=21 (Mbytes/sec)
2022/04/12 20:05:29 mio.go:628: R: off=67108864 len=33554432 bs=33554432 gs=16777216 speed=39 (Mbytes/sec)
motr[153375]:  9a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7fe94003ac00 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
motr[153375]:  9a90   WARN  [io_req.c:1665:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x7fe94003ac00 dgmap_nr=4
2022/04/12 20:05:30 mio.go:628: R: off=100663296 len=33554432 bs=33554432 gs=16777216 speed=25 (Mbytes/sec)
motr[153375]:  9a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7fe94003ac00 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
motr[153375]:  9a90   WARN  [io_req.c:1665:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x7fe94003ac00 dgmap_nr=4
2022/04/12 20:05:32 mio.go:628: R: off=134217728 len=33554432 bs=33554432 gs=16777216 speed=25 (Mbytes/sec)
2022/04/12 20:05:32 mio.go:628: R: off=167772160 len=33554432 bs=33554432 gs=16777216 speed=48 (Mbytes/sec)
motr[153375]:  9a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7fe94003ac00 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
motr[153375]:  9a90   WARN  [io_req.c:1665:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x7fe94003ac00 dgmap_nr=4
2022/04/12 20:05:33 mio.go:628: R: off=201326592 len=8388608 bs=16777216 gs=16777216 speed=9682 (Kbytes/sec)
20:05 ant@rocky83:mcp$ 
20:05 ant@rocky83:mcp$ 
20:05 ant@rocky83:mcp$ cmp /tmp/200m{,.check}
20:05 ant@rocky83:mcp$
andriytk commented 2 years ago

When failing one of the m0d-ios processes (4+2+0 pool of 10 disks, 5 ios by 2 disks each) - client i/o gets stuck:

21:31 ant@rocky83:mcp$ hctl status
Bytecount:
    critical : 0
    damaged : 0
    degraded : 0
    healthy : 436207616
Data pool:
    # fid name
    0x6f00000000000001:0x61 'the pool'
Profile:
    # fid name: pool(s)
    0x7000000000000001:0x95 'default': 'the pool' None None
Services:
    rocky83  (RC)
    [started]  hax                 0x7200000000000001:0xa          inet:tcp:192.168.180.165@22001
    [started]  confd               0x7200000000000001:0xd          inet:tcp:192.168.180.165@21001
    [started]  ioservice           0x7200000000000001:0x10         inet:tcp:192.168.180.165@21002
    [started]  ioservice           0x7200000000000001:0x1d         inet:tcp:192.168.180.165@21003
    [offline]  ioservice           0x7200000000000001:0x2a         inet:tcp:192.168.180.165@21004
    [started]  ioservice           0x7200000000000001:0x37         inet:tcp:192.168.180.165@21005
    [started]  ioservice           0x7200000000000001:0x44         inet:tcp:192.168.180.165@21006
    [offline]  m0_client_other     0x7200000000000001:0x51         inet:tcp:192.168.180.165@21501
    [unknown]  m0_client_other     0x7200000000000001:0x54         inet:tcp:192.168.180.165@21502
21:31 ant@rocky83:mcp$ 
21:31 ant@rocky83:mcp$ 
21:31 ant@rocky83:mcp$ 
21:31 ant@rocky83:mcp$ ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x51 -prof 0x7000000000000001:0x95 -hax inet:tcp:192.168.180.165@22001 -v /tmp/200m 12345:6789001
^C
21:32 ant@rocky83:mcp$ ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x51 -prof 0x7000000000000001:0x95 -hax inet:tcp:192.168.180.165@22001 -v /tmp/200m 12345:6789002

# STUCK!
huanghua78 commented 2 years ago

When failing one of the m0d-ios processes

Did you kill the m0d-ios process? So, Hare and other processes did not know that process was already killed?

So we need to investigate the timeout of RPC on client. It is supposed to get TIMEOUT error, and as you proposed, client should report such error and switch to degraded mode.

andriytk commented 2 years ago

@huanghua78, yes, with kill -9. Hare did know that the process has failed, you can see it in the output of hctl status above.

siningwuseagate commented 2 years ago

@andriytk could you share the cluster configure yaml file? so I also try it myself

andriytk commented 2 years ago

sure:

nodes:
  - hostname: rocky83     # [user@]hostname
    data_iface: ens33        # name of data network interface
    data_iface_ip_addr: null
    transport_type: libfab
    m0_servers:
      - runs_confd: true
        io_disks:
          data: []
          meta_data: null
      - runs_confd: null
        io_disks:
          data:
            - path: /dev/loop0 
            - path: /dev/loop1 
          meta_data: null
      - runs_confd: null
        io_disks:
          data:
            - path: /dev/loop2 
            - path: /dev/loop3 
          meta_data: null
      - runs_confd: null
        io_disks:
          data:
            - path: /dev/loop4 
            - path: /dev/loop5 
          meta_data: null
      - runs_confd: null
        io_disks:
          data:
            - path: /dev/loop6 
            - path: /dev/loop7 
          meta_data: null
      - runs_confd: null
        io_disks:
          data:
            - path: /dev/loop8 
            - path: /dev/loop9 
          meta_data: null
    m0_clients:
      - name: m0_client_other  # name of the motr client
        instances: 2   # Number of instances, this host will run
create_aux: false # optional; supported values: "false" (default), "true"
pools:
  - name: the pool
    type: sns  # optional; supported values: "sns" (default), "dix", "md"
    disk_refs:
      - { path: /dev/loop0, node: rocky83 }
      - { path: /dev/loop1, node: rocky83 }
      - { path: /dev/loop2, node: rocky83 }
      - { path: /dev/loop3, node: rocky83 }
      - { path: /dev/loop4, node: rocky83 }
      - { path: /dev/loop5, node: rocky83 }
      - { path: /dev/loop6, node: rocky83 }
      - { path: /dev/loop7, node: rocky83 }
      - { path: /dev/loop8, node: rocky83 }
      - { path: /dev/loop9, node: rocky83 }
    data_units: 4
    parity_units: 2
    spare_units: 0
    allowed_failures: { site: 0, rack: 0, encl: 0, ctrl: 0, disk: 2 }
andriytk commented 2 years ago

Actually, it prints out timeout errors after some time:

motr[305818]:  99b0  ERROR  [rpc/frmops.c:482:item_done]   item: 0x7f27240445b0 dest_ep=inet:tcp:192.168.180.165@21005 ri_session=0x1626b80 ri_nr_sent_max=1ri_deadline=0 ri_nr_sent=1
motr[305818]:  99b0  ERROR  [rpc/frmops.c:486:item_done]  packet 0x7f2724053d90, item 0x7f27240445b0[32] failed with ri_error=-110
motr[305818]:  99b0  ERROR  [rpc/frmops.c:482:item_done]   item: 0x7f272406a1a0 dest_ep=inet:tcp:192.168.180.165@21005 ri_session=0x160a7c0 ri_nr_sent_max=1ri_deadline=0 ri_nr_sent=1
motr[305818]:  99b0  ERROR  [rpc/frmops.c:486:item_done]  packet 0x7f2724053f60, item 0x7f272406a1a0[32] failed with ri_error=-110
motr[305818]:  99b0  ERROR  [rpc/frmops.c:482:item_done]   item: 0x7f27240472c0 dest_ep=inet:tcp:192.168.180.165@21005 ri_session=0x1634d60 ri_nr_sent_max=1ri_deadline=0 ri_nr_sent=1
motr[305818]:  99b0  ERROR  [rpc/frmops.c:486:item_done]  packet 0x7f2724054fe0, item 0x7f27240472c0[32] failed with ri_error=-110
siningwuseagate commented 2 years ago

@andriytk in your test above, did you run the mcp after m0d was killed? I observed the same thing, mcp is stuck at m0_client_init(). I also tried killing m0d during write, mcp was stuck but with the following output

motr[437646]: c9f0 ERROR [io_req_fop.c:298:io_bottom_half] [0xfe3000] rpc item 0x7f04e4044f30 rc=-110 motr[437646]: c9f0 ERROR [io_req_fop.c:363:io_bottom_half] ioo=0xfe3000 from=inet:tcp:192.168.0.41@3003 rc=-110 ti_rc=-110 @<4300000200003039:67978e> motr[437646]: c9f0 ERROR [io_req_fop.c:298:io_bottom_half] [0xfe3000] rpc item 0x7f04e404f2a0 rc=-110 motr[437646]: c9f0 ERROR [io_req_fop.c:298:io_bottom_half] [0xfe3000] rpc item 0x7f04e4051370 rc=-110 motr[437646]: c9f0 ERROR [io_req_fop.c:298:io_bottom_half] [0xfe3000] rpc item 0x7f04e4046fc0 rc=-110 motr[437646]: c9f0 ERROR [io_req_fop.c:298:io_bottom_half] [0xfe3000] rpc item 0x7f04e42c32e0 rc=-110

andriytk commented 2 years ago

@siningwuseagate yes, but I see the same rc=-110 error (see my previous comment).

andriytk commented 2 years ago

Here's where it gets stuck:

#2  0x00007f344da05350 in m0_semaphore_timeddown (semaphore=0x7ffc0b8bd288, abs_timeout=<optimized out>)
    at lib/user_space/semaphore.c:126
#3  0x00007f344d9f5b85 in m0_chan_timedwait (link=link@entry=0x7ffc0b8bd260, 
    abs_timeout=abs_timeout@entry=18446744073709551615) at lib/chan.c:356
#4  0x00007f344da97840 in m0_sm_timedwait (mach=mach@entry=0x1554f90, states=states@entry=2, deadline=18446744073709551615)
    at sm/sm.c:405
#5  0x00007f344da6d713 in reqh_service_ctx_state_wait (ctx=0x1554270, state=state@entry=1) at reqh/reqh_service.c:809
#6  0x00007f344da6f5ee in m0_reqh_service_connect_wait (ctx=ctx@entry=0x1554270) at reqh/reqh_service.c:826
#7  0x00007f344da65279 in m0_pools_common_service_ctx_connect_sync (pc=pc@entry=0x1420b18) at pool/pool.c:1613
#8  0x00007f344da1e489 in pools_init (m0c=0x141d730) at motr/client_init.c:1052
#9  initlift_pools (mach=0x1426c30) at motr/client_init.c:1087
#10 0x00007f344da98670 in state_set (mach=0x1426c30, state=6, rc=<optimized out>) at sm/sm.c:461
#11 0x00007f344da1ff88 in m0_client_init (m0c_p=0x7cf768 <instance>, conf=0x7cf720 <conf>, init_m0=<optimized out>)
    at motr/client_init.c:1606

Let's check the service's state:

(gdb) f 6
#6  0x00007f344da6f5ee in m0_reqh_service_connect_wait (ctx=ctx@entry=0x1554270) at reqh/reqh_service.c:826
826         int rc = reqh_service_ctx_state_wait(ctx, M0_RSC_ONLINE);
(gdb) l
821 
822 M0_INTERNAL void m0_reqh_service_connect_wait(struct m0_reqh_service_ctx *ctx)
823 {
824 
825     if (ctx->sc_service->co_ha_state == M0_NC_ONLINE) {
826         int rc = reqh_service_ctx_state_wait(ctx, M0_RSC_ONLINE);
827         M0_ASSERT(rc == 0);
828     }
829 }
830 
(gdb) p ctx->sc_service->co_ha_state
$1 = M0_NC_ONLINE
(gdb) p /x ctx->sc_fid
$3 = {f_container = 0x7300000000000001, f_key = 0x39}
(gdb) p /x ctx->sc_fid_process
$4 = {f_container = 0x7200000000000001, f_key = 0x37}

@mssawant, @nikitadanilov any idea why it is online if its enclosing process is offline?

$ hctl status
Bytecount:
    critical : 0
    damaged : 0
    degraded : 0
    healthy : 0
Data pool:
    # fid name
    0x6f00000000000001:0x61 'the pool'
Profile:
    # fid name: pool(s)
    0x7000000000000001:0x95 'default': 'the pool' None None
Services:
    rocky83  (RC)
    [started]  hax                 0x7200000000000001:0xa          inet:tcp:192.168.180.165@22001
    [started]  confd               0x7200000000000001:0xd          inet:tcp:192.168.180.165@21001
    [started]  ioservice           0x7200000000000001:0x10         inet:tcp:192.168.180.165@21002
    [started]  ioservice           0x7200000000000001:0x1d         inet:tcp:192.168.180.165@21003
    [started]  ioservice           0x7200000000000001:0x2a         inet:tcp:192.168.180.165@21004
    [offline]  ioservice           0x7200000000000001:0x37         inet:tcp:192.168.180.165@21005
    [started]  ioservice           0x7200000000000001:0x44         inet:tcp:192.168.180.165@21006
    [offline]  m0_client_other     0x7200000000000001:0x51         inet:tcp:192.168.180.165@21501
    [unknown]  m0_client_other     0x7200000000000001:0x54         inet:tcp:192.168.180.165@21502
$ consul kv get -recurse | grep x37
m0conf/nodes/0x6e00000000000001:0x3/processes/0x7200000000000001:0x37:{"name": "m0_server", "state": "offline"}
m0conf/nodes/0x6e00000000000001:0x3/processes/0x7200000000000001:0x37/services/0x7300000000000001:0x38:{"name": "rms", "state": "M0_NC_UNKNOWN"}
m0conf/nodes/0x6e00000000000001:0x3/processes/0x7200000000000001:0x37/services/0x7300000000000001:0x39:{"name": "ios", "state": "M0_NC_UNKNOWN"}
m0conf/nodes/0x6e00000000000001:0x3/processes/0x7200000000000001:0x37/services/0x7300000000000001:0x39/sdevs/0x6400000000000001:0x3a:{"path": "/dev/loop6", "state": "offline"}
m0conf/nodes/0x6e00000000000001:0x3/processes/0x7200000000000001:0x37/services/0x7300000000000001:0x39/sdevs/0x6400000000000001:0x3c:{"path": "/dev/loop7", "state": "offline"}
m0conf/nodes/0x6e00000000000001:0x3/processes/0x7200000000000001:0x37/services/0x7300000000000001:0x3e:{"name": "sns_rep", "state": "M0_NC_UNKNOWN"}
m0conf/nodes/0x6e00000000000001:0x3/processes/0x7200000000000001:0x37/services/0x7300000000000001:0x3f:{"name": "sns_reb", "state": "M0_NC_UNKNOWN"}
m0conf/nodes/0x6e00000000000001:0x3/processes/0x7200000000000001:0x37/services/0x7300000000000001:0x40:{"name": "addb2", "state": "M0_NC_UNKNOWN"}
m0conf/nodes/0x6e00000000000001:0x3/processes/0x7200000000000001:0x37/services/0x7300000000000001:0x41:{"name": "cas", "state": "M0_NC_UNKNOWN"}
m0conf/nodes/0x6e00000000000001:0x3/processes/0x7200000000000001:0x37/services/0x7300000000000001:0x41/sdevs/0x6400000000000001:0x5d:{"path": "/dev/null", "state": "offline"}
m0conf/nodes/0x6e00000000000001:0x3/processes/0x7200000000000001:0x37/services/0x7300000000000001:0x42:{"name": "iscs", "state": "M0_NC_UNKNOWN"}
m0conf/nodes/0x6e00000000000001:0x3/processes/0x7200000000000001:0x37/services/0x7300000000000001:0x43:{"name": "fdmi", "state": "M0_NC_UNKNOWN"}
processes/0x7200000000000001:0x37:{"state": "M0_CONF_HA_PROCESS_STOPPED", "type": "M0_CONF_HA_PROCESS_M0D"}
andriytk commented 2 years ago

When motr client connects and gets the cluster configuration, the ha_state for the failed process and its service is online (note ha_state=1 and no_state=1), which is wrong, of course:

$ grep '1:3[79]' bb | grep -v -E 'm0_conf_obj_(put|get)'
16624  319549.835.689726  7f3a17588960  CALL    conf/obj_ops.c:142:m0_conf_obj_find   > <7200000000000001:37>
17438  319549.852.616283  7f3a17588ab0  CALL    conf/obj_ops.c:142:m0_conf_obj_find   > <7200000000000001:37>
17455  319549.852.635036  7f3a17588950  CALL    conf/obj_ops.c:142:m0_conf_obj_find   > <7300000000000001:39>
17516  319549.852.710811  7f3a17588ab0  CALL    conf/obj_ops.c:251:m0_conf_obj_fill   < rc=0 dest=<7200000000000001:37> ha_state=1
25365  319550.146.946726  7f3a17588ab0  CALL    conf/obj_ops.c:142:m0_conf_obj_find   > <7300000000000001:39>
25395  319550.146.994985  7f3a17588ab0  CALL    conf/obj_ops.c:251:m0_conf_obj_fill   < rc=0 dest=<7300000000000001:39> ha_state=1
62322  319551.071.493748  7ffe10216b10  DEBUG   ha/note.c:84:m0_ha_state_get   >  [102] <7300000000000001:39>, (0)
62355  319551.071.498602  7ffe10216b10  DEBUG   ha/note.c:84:m0_ha_state_get   >  [135] <7200000000000001:37>, (0)
63319  319553.746.685805  7f3a3fffe7c0  DEBUG   ha/note.c:225:m0_ha_msg_accept   nv_note[102]=(no_id=<7300000000000001:39> no_state=1)
63352  319553.746.690058  7f3a3fffe7c0  DEBUG   ha/note.c:225:m0_ha_msg_accept   nv_note[135]=(no_id=<7200000000000001:37> no_state=1)
63468  319553.746.752451  7f3a3fffe6d0  DEBUG   ha/note.c:176:ha_state_accept   nv_note[102]=(no_id=<7300000000000001:39> no_state=1) obj=(nil) obj->co_status=-1
63501  319553.746.762412  7f3a3fffe6d0  DEBUG   ha/note.c:176:ha_state_accept   nv_note[135]=(no_id=<7200000000000001:37> no_state=1) obj=(nil) obj->co_status=-1
63618  319553.747.615107  7f3a3fffe6d0  DEBUG   ha/note.c:176:ha_state_accept   nv_note[102]=(no_id=<7300000000000001:39> no_state=1) obj=0x7f3a0801b970 obj->co_status=2
63651  319553.747.918421  7f3a3fffe6d0  DEBUG   ha/note.c:176:ha_state_accept   nv_note[135]=(no_id=<7200000000000001:37> no_state=1) obj=0x7f3a08018d30 obj->co_status=2
68253  319553.766.119888  7ffe10216a90  DEBUG   pool/pool.c:910:__service_ctx_create   new svc:<7300000000000001:39> type:2 ep:inet:tcp:192.168.180.165@21005
68254  319553.766.121441  7ffe10216a10  CALL    reqh/reqh_service.c:1261:m0_reqh_service_ctx_create   > <7300000000000001:39>stype:2
68258  319553.766.150289  7ffe10216990  DEBUG   reqh/reqh_service.c:1219:m0_reqh_service_ctx_init   <7300000000000001:39>2
68292  319553.766.584120  7ffe102167a0  DEBUG   rpc/conn.c:378:__conn_ha_subscribe   svc_fid <7300000000000001:39>, cs_type=2
68295  319553.766.588995  7ffe102167a0  CALL    rpc/conn.c:382:__conn_ha_subscribe   < service fid = <7300000000000001:39>
68296  319553.766.606633  7ffe10216830  DEBUG   rpc/conn.c:438:__conn_init   conn 0x28a8e80 has subscribed on rconfc events,           fid <7300000000000001:39>
92430  319555.245.395641  7f3a1858abb0  CALL    rpc/conn.c:1486:reqh_service_ha_state_set   > conn 0x28a8e80, svc_fid <7300000000000001:39>, state M0_NC_TRANSIENT

at least by the time initlift_pools() is called:

63774  319553.748.564814  7ffe10216dc0  CALL    motr/client_init.c:1080:initlift_pools   >
andriytk commented 2 years ago

According to @madhavemuri, "Conf cache in motr clients and m0d's should get the latest (ha) state from Hax." But we see that the state mcp receives for the failed process and its service is online:

63618  319553.747.615107  7f3a3fffe6d0  DEBUG   ha/note.c:176:ha_state_accept   nv_note[102]=(no_id=<7300000000000001:39> no_state=1) obj=0x7f3a0801b970 obj->co_status=2
63651  319553.747.918421  7f3a3fffe6d0  DEBUG   ha/note.c:176:ha_state_accept   nv_note[135]=(no_id=<7200000000000001:37> no_state=1) obj=0x7f3a08018d30 obj->co_status=2

(note: no_state=1)

@mssawant, any idea? Here is the system log since the time mcp was started - hax-log.txt

andriytk commented 2 years ago

With the patch from @mssawant (hare-nvec-offline.patch.txt), I can see the correct ha state in nvec reply now:

63619  70093.228.115398  7fd2f97eb6d0  DEBUG   ha/note.c:176:ha_state_accept   nv_note[102]=(no_id=<7300000000000001:39> no_state=3) obj=0x7fd2bc0149d0 obj->co_status=2
63652  70093.228.365565  7fd2f97eb6d0  DEBUG   ha/note.c:176:ha_state_accept   nv_note[135]=(no_id=<7200000000000001:37> no_state=3) obj=0x7fd2bc0126e0 obj->co_status=2

(note: no_state=3 which means M0_NC_TRANSIENT)

But still - m0_client_init() fails with an error:

$ ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x51 -prof 0x7000000000000001:0x95 -hax inet:tcp:192.168.180.165@22001 -v -trace /tmp/200m 12345:6789002
motr[38681]:  c720  ERROR  [rpc/rpc.c:119:m0_rpc__post_locked]  <! rc=-107
motr[38681]:  cc50  ERROR  [cas/client.c:553:cas_req_failure_ast]  <! rc=-107
motr[38681]:  cd50  ERROR  [idx_dix.c:1502:dix_client_init]  <! rc=-71
motr[38681]:  cd50  ERROR  [idx_dix.c:1525:idx_dix_init]  <! rc=-71
2022/04/14 17:54:53 mio.go:172: m0_client_init() failed: -71

From m0trace log:

107744  70093.577.508548  7fff34f7c720  DEBUG   rpc/rpc.c:118:m0_rpc__post_locked   0x1f4a5b0[REQUEST/230], fop 0x1f4a590, session 0x1efa088, Session isn't established. Hence, not posting the item
107745  70093.577.508830  7fff34f7c720  ERROR   rpc/rpc.c:119:m0_rpc__post_locked   <! rc=-107
madhavemuri commented 2 years ago

@andriytk @sergey-shilov : Can we try with PR https://github.com/Seagate/cortx-motr/pull/1545/files , which handles transient failures ?

madhavemuri commented 2 years ago

As per @sergey-shilov, currently put operations only handled for Transient failures in above PR, work on get operations is pending.

andriytk commented 2 years ago

With the patch from @mssawant (hare-nvec-offline.patch.txt), I can see the correct ha state in nvec reply now:

According to @mssawant, the patch has been landed to Hare in the context of https://github.com/Seagate/cortx-hare/pull/2004.

andriytk commented 2 years ago

But still - m0_client_init() fails with an error:

$ ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x51 -prof 0x7000000000000001:0x95 -hax inet:tcp:192.168.180.165@22001 -v -trace /tmp/200m 12345:6789002
motr[38681]:  c720  ERROR  [rpc/rpc.c:119:m0_rpc__post_locked]  <! rc=-107

PR to fix this error - https://github.com/Seagate/cortx-motr/pull/1654

madhavemuri commented 2 years ago

Degraded write works too:

20:02 ant@rocky83:mcp$ ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x29 -prof 0x7000000000000001:0x51 -hax inet:tcp:192.168.180.165@22001 -v /tmp/200m 12345:6789001
motr[150433]:  65a0  ERROR  [pool/pool_machine.c:531:spare_usage_arr_update]  <7600000000000001:32>: No free spare space slot is found, this pool version is in DUD state; event_index=1 event_state=2
motr[150433]:  6a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7f0b5c000e20 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
2022/04/12 20:02:40 mio.go:556: W: off=0 len=33554432 bs=33554432 gs=16777216 speed=9725 (Kbytes/sec)
motr[150433]:  6a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7f0b5c000e20 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
2022/04/12 20:02:43 mio.go:556: W: off=33554432 len=33554432 bs=33554432 gs=16777216 speed=12 (Mbytes/sec)
motr[150433]:  6a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7f0b5c000e20 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
2022/04/12 20:02:45 mio.go:556: W: off=67108864 len=33554432 bs=33554432 gs=16777216 speed=13 (Mbytes/sec)
motr[150433]:  6a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7f0b5c000e20 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
2022/04/12 20:02:48 mio.go:556: W: off=100663296 len=33554432 bs=33554432 gs=16777216 speed=12 (Mbytes/sec)
motr[150433]:  8a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7f0b5c000e20 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
2022/04/12 20:02:50 mio.go:556: W: off=134217728 len=33554432 bs=33554432 gs=16777216 speed=12 (Mbytes/sec)
motr[150433]:  8a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7f0b5c000e20 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
2022/04/12 20:02:52 mio.go:556: W: off=167772160 len=33554432 bs=33554432 gs=16777216 speed=13 (Mbytes/sec)
motr[150433]:  8a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7f0b5c000e20 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
2022/04/12 20:02:54 mio.go:556: W: off=201326592 len=8388608 bs=16777216 gs=16777216 speed=6547 (Kbytes/sec)
20:02 ant@rocky83:mcp$ echo $?
0
20:03 ant@rocky83:mcp$ 
20:03 ant@rocky83:mcp$ ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x29 -prof 0x7000000000000001:0x51 -hax inet:tcp:192.168.180.165@22001 -v /tmp/200m 12345:6789002
motr[151319]:  a5a0  ERROR  [pool/pool_machine.c:531:spare_usage_arr_update]  <7600000000000001:32>: No free spare space slot is found, this pool version is in DUD state; event_index=1 event_state=2
2022/04/12 20:03:29 mio.go:556: W: off=0 len=33554432 bs=33554432 gs=16777216 speed=20 (Mbytes/sec)
2022/04/12 20:03:30 mio.go:556: W: off=33554432 len=33554432 bs=33554432 gs=16777216 speed=20 (Mbytes/sec)
2022/04/12 20:03:32 mio.go:556: W: off=67108864 len=33554432 bs=33554432 gs=16777216 speed=23 (Mbytes/sec)
2022/04/12 20:03:33 mio.go:556: W: off=100663296 len=33554432 bs=33554432 gs=16777216 speed=22 (Mbytes/sec)
2022/04/12 20:03:35 mio.go:556: W: off=134217728 len=33554432 bs=33554432 gs=16777216 speed=19 (Mbytes/sec)
2022/04/12 20:03:36 mio.go:556: W: off=167772160 len=33554432 bs=33554432 gs=16777216 speed=24 (Mbytes/sec)
2022/04/12 20:03:37 mio.go:556: W: off=201326592 len=8388608 bs=16777216 gs=16777216 speed=11 (Mbytes/sec)
20:03 ant@rocky83:mcp$ 
20:03 ant@rocky83:mcp$ 
20:03 ant@rocky83:mcp$ ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x29 -prof 0x7000000000000001:0x51 -hax inet:tcp:192.168.180.165@22001 -v -osz $((200*1024)) 12345:6789002 /tmp/200m.check
motr[152251]:  75a0  ERROR  [pool/pool_machine.c:531:spare_usage_arr_update]  <7600000000000001:32>: No free spare space slot is found, this pool version is in DUD state; event_index=1 event_state=2
2022/04/12 20:04:22 mio.go:628: R: off=0 len=33554432 bs=33554432 gs=16777216 speed=35 (Mbytes/sec)
2022/04/12 20:04:22 mio.go:628: R: off=33554432 len=33554432 bs=33554432 gs=16777216 speed=48 (Mbytes/sec)
2022/04/12 20:04:23 mio.go:628: R: off=67108864 len=33554432 bs=33554432 gs=16777216 speed=39 (Mbytes/sec)
2022/04/12 20:04:24 mio.go:628: R: off=100663296 len=33554432 bs=33554432 gs=16777216 speed=37 (Mbytes/sec)
2022/04/12 20:04:25 mio.go:628: R: off=134217728 len=33554432 bs=33554432 gs=16777216 speed=44 (Mbytes/sec)
2022/04/12 20:04:25 mio.go:628: R: off=167772160 len=33554432 bs=33554432 gs=16777216 speed=46 (Mbytes/sec)
2022/04/12 20:04:26 mio.go:628: R: off=201326592 len=8388608 bs=16777216 gs=16777216 speed=21 (Mbytes/sec)
20:04 ant@rocky83:mcp$ 
20:04 ant@rocky83:mcp$ 
20:04 ant@rocky83:mcp$ cmp /tmp/200m{,.check}
20:04 ant@rocky83:mcp$ 
20:04 ant@rocky83:mcp$ ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x29 -prof 0x7000000000000001:0x51 -hax inet:tcp:192.168.180.165@22001 -v -osz $((200*1024)) 12345:6789001 /tmp/200m.check
motr[153375]:  c5a0  ERROR  [pool/pool_machine.c:531:spare_usage_arr_update]  <7600000000000001:32>: No free spare space slot is found, this pool version is in DUD state; event_index=1 event_state=2
motr[153375]:  9a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x1bf5290 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
motr[153375]:  9a90   WARN  [io_req.c:1665:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x1bf5290 dgmap_nr=4
2022/04/12 20:05:27 mio.go:628: R: off=0 len=33554432 bs=33554432 gs=16777216 speed=18 (Mbytes/sec)
motr[153375]:  9a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7fe94003ace0 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
motr[153375]:  9a90   WARN  [io_req.c:1665:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x7fe94003ace0 dgmap_nr=4
2022/04/12 20:05:28 mio.go:628: R: off=33554432 len=33554432 bs=33554432 gs=16777216 speed=21 (Mbytes/sec)
2022/04/12 20:05:29 mio.go:628: R: off=67108864 len=33554432 bs=33554432 gs=16777216 speed=39 (Mbytes/sec)
motr[153375]:  9a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7fe94003ac00 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
motr[153375]:  9a90   WARN  [io_req.c:1665:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x7fe94003ac00 dgmap_nr=4
2022/04/12 20:05:30 mio.go:628: R: off=100663296 len=33554432 bs=33554432 gs=16777216 speed=25 (Mbytes/sec)
motr[153375]:  9a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7fe94003ac00 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
motr[153375]:  9a90   WARN  [io_req.c:1665:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x7fe94003ac00 dgmap_nr=4
2022/04/12 20:05:32 mio.go:628: R: off=134217728 len=33554432 bs=33554432 gs=16777216 speed=25 (Mbytes/sec)
2022/04/12 20:05:32 mio.go:628: R: off=167772160 len=33554432 bs=33554432 gs=16777216 speed=48 (Mbytes/sec)
motr[153375]:  9a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7fe94003ac00 from=inet:tcp:192.168.180.165@21002 rc=-5 ti_rc=-5 @<4300000100003039:679789>
motr[153375]:  9a90   WARN  [io_req.c:1665:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x7fe94003ac00 dgmap_nr=4
2022/04/12 20:05:33 mio.go:628: R: off=201326592 len=8388608 bs=16777216 gs=16777216 speed=9682 (Kbytes/sec)
20:05 ant@rocky83:mcp$ 
20:05 ant@rocky83:mcp$ 
20:05 ant@rocky83:mcp$ cmp /tmp/200m{,.check}
20:05 ant@rocky83:mcp$

@andriytk : I think above object is not using the base pool version, it may be using dynamic pool version and doing RMW operation . Degraded write needs some code changes. Can you re-check it ?

andriytk commented 2 years ago

According to @sergey-shilov, degraded mode for DIX is not ready yet, see - CORTX-30872.

andriytk commented 2 years ago

When the drive goes back from offline to online - reading the object returns the broken data silently. Here is the scenario:

  1. start writing an object...
  2. before the write completes - transition some disk to offline state: hctl drive-state --json $(jq --null-input --compact-output '{ node: "rocky83", source_type: "drive", device: "/dev/loop1", state: "offline" }') note: writing will complete successfully, and reading will return the correct data too - both in degraded mode
  3. transition the drive back to online (using the same command as above, just change offline to online)
  4. try to read the object - it will finish without errors, but the returned data won't match the original one
mssawant commented 2 years ago

@andriy diff for me between degraded read (read after drive transitioned to offline) and regular (after transitioning the drive to online) was empty.

[root@ssc-vm-g4-rhev4-0554 ~]# hctl status -d
Bytecount:
    critical : 0
    damaged : 0
    degraded : 0
    healthy : 0
Data pool:
    # fid name
    0x6f00000000000001:0x59 'sns-pool'
Profile:
    # fid name: pool(s)
    0x7000000000000001:0x89 'default': 'sns-pool' None None
Services:
    ssc-vm-g4-rhev4-0554.colo.seagate.com  (RC)
    [started]  hax                 0x7200000000000001:0x9          inet:tcp:10.230.240.235@22001
    [started]  confd               0x7200000000000001:0xc          inet:tcp:10.230.240.235@21002
    [started]  ioservice           0x7200000000000001:0xf          inet:tcp:10.230.240.235@21003
    [started]  ioservice           0x7200000000000001:0x1e         inet:tcp:10.230.240.235@21004
    [started]  ioservice           0x7200000000000001:0x2d         inet:tcp:10.230.240.235@21005
    [started]  ioservice           0x7200000000000001:0x3e         inet:tcp:10.230.240.235@21006
    [unknown]  m0_client_other     0x7200000000000001:0x4b         inet:tcp:10.230.240.235@22501
    [unknown]  m0_client_other     0x7200000000000001:0x4e         inet:tcp:10.230.240.235@22502
Devices:
    ssc-vm-g4-rhev4-0554.colo.seagate.com
    [online]  /dev/sdd
    [online]  /dev/sde
    [online]  /dev/null
    [online]  /dev/sdf
    [online]  /dev/sdg
    [online]  /dev/sdh
    [online]  /dev/null
    [online]  /dev/sdi
    [online]  /dev/null
    [online]  /dev/sdb
    [online]  /dev/sdc
    [online]  /dev/null
(reverse-i-search)`d': hctl status -^C
[root@ssc-vm-g4-rhev4-0554 ~]# hctl drive-state --json '{"node":"ssc-vm-g4-rhev4-0554.colo.seagate.com","source_type":"drive","device":"/dev/sdd","state":"offline"}'
0
2022-04-21 13:45:12,361 [DEBUG] Bound <class 'hax.common.HaxGlobalState'> to an instance <hax.common.HaxGlobalState object at 0x7f6cec3af4a8>
2022-04-21 13:45:12,361 [DEBUG] Created and configured an injector, config=<function di_configuration at 0x7f6cf1585378>
2022-04-21 13:45:12,366 [DEBUG] Starting new HTTP connection (1): 127.0.0.1:8500
2022-04-21 13:45:12,368 [DEBUG] http://127.0.0.1:8500 "GET /v1/kv/eq-epoch HTTP/1.1" 200 91
2022-04-21 13:45:12,413 [DEBUG] http://127.0.0.1:8500 "PUT /v1/txn HTTP/1.1" 200 219
2022-04-21 13:45:12,414 [INFO] Written to epoch: 2
[root@ssc-vm-g4-rhev4-0554 ~]# hctl status -d
Bytecount:
    critical : 0
    damaged : 0
    degraded : 0
    healthy : 0
Data pool:
    # fid name
    0x6f00000000000001:0x59 'sns-pool'
Profile:
    # fid name: pool(s)
    0x7000000000000001:0x89 'default': 'sns-pool' None None
Services:
    ssc-vm-g4-rhev4-0554.colo.seagate.com  (RC)
    [started]  hax                 0x7200000000000001:0x9          inet:tcp:10.230.240.235@22001
    [started]  confd               0x7200000000000001:0xc          inet:tcp:10.230.240.235@21002
    [started]  ioservice           0x7200000000000001:0xf          inet:tcp:10.230.240.235@21003
    [started]  ioservice           0x7200000000000001:0x1e         inet:tcp:10.230.240.235@21004
    [started]  ioservice           0x7200000000000001:0x2d         inet:tcp:10.230.240.235@21005
    [started]  ioservice           0x7200000000000001:0x3e         inet:tcp:10.230.240.235@21006
    [unknown]  m0_client_other     0x7200000000000001:0x4b         inet:tcp:10.230.240.235@22501
    [unknown]  m0_client_other     0x7200000000000001:0x4e         inet:tcp:10.230.240.235@22502
Devices:
    ssc-vm-g4-rhev4-0554.colo.seagate.com
    [offline]  /dev/sdd
    [online]  /dev/sde
    [online]  /dev/null
    [online]  /dev/sdf
    [online]  /dev/sdg
    [online]  /dev/sdh
    [online]  /dev/null
    [online]  /dev/sdi
    [online]  /dev/null
    [online]  /dev/sdb
    [online]  /dev/sdc
    [online]  /dev/null
(reverse-i-search)`m0c': consul kv get -recurse ^Cconf/nodes/ssc-vm-g4-rhev4-0554.colo.seagate.com | egrep -w 'confd|ha' | sed -r 's/.*processes.([0-9]+).*/"service:\1"/'
[root@ssc-vm-g4-rhev4-0554 ~]# m0client -l 'inet:tcp:10.230.240.235@22501' -H 'inet:tcp:10.230.240.235@22001' -p '<0x7000000000000001:0x89>' -P '<0x7200000000000001:0x4b>'
m0client >>write 1048682 /tmp/srcfile 4096 200 50
IO failed! rc = -1
m0client >>write 1048680 /tmp/128M 4096 200 50
m0client >>read 1048680 /tmp/read_1048680 4096 200 50
m0client >>m0client >>m0client >>quit
Help:
touch   OBJ_ID
write   OBJ_ID SRC_FILE BLOCK_SIZE BLOCK_COUNT BLOCKS_PER_IO UPDATE_FLAG OFFSET
read    OBJ_ID DEST_FILE BLOCK_SIZE BLOCK_COUNT BLOCKS_PER_IO
delete  OBJ_ID
help
quit
[root@ssc-vm-g4-rhev4-0554 ~]# hctl status -d
Bytecount:
    critical : 0
    damaged : 0
    degraded : 0
    healthy : 819200
Data pool:
    # fid name
    0x6f00000000000001:0x59 'sns-pool'
Profile:
    # fid name: pool(s)
    0x7000000000000001:0x89 'default': 'sns-pool' None None
Services:
    ssc-vm-g4-rhev4-0554.colo.seagate.com  (RC)
    [started]  hax                 0x7200000000000001:0x9          inet:tcp:10.230.240.235@22001
    [started]  confd               0x7200000000000001:0xc          inet:tcp:10.230.240.235@21002
    [started]  ioservice           0x7200000000000001:0xf          inet:tcp:10.230.240.235@21003
    [started]  ioservice           0x7200000000000001:0x1e         inet:tcp:10.230.240.235@21004
    [started]  ioservice           0x7200000000000001:0x2d         inet:tcp:10.230.240.235@21005
    [started]  ioservice           0x7200000000000001:0x3e         inet:tcp:10.230.240.235@21006
    [offline]  m0_client_other     0x7200000000000001:0x4b         inet:tcp:10.230.240.235@22501
    [unknown]  m0_client_other     0x7200000000000001:0x4e         inet:tcp:10.230.240.235@22502
Devices:
    ssc-vm-g4-rhev4-0554.colo.seagate.com
    [offline]  /dev/sdd
    [online]  /dev/sde
    [online]  /dev/null
    [online]  /dev/sdf
    [online]  /dev/sdg
    [online]  /dev/sdh
    [online]  /dev/null
    [online]  /dev/sdi
    [online]  /dev/null
    [online]  /dev/sdb
    [online]  /dev/sdc
    [online]  /dev/null
(reverse-i-search)`o': consul kv put -acquire -sessi^C=79acfab1-aa9f-63b1-5a7f-cbd603fb5652 leader_new "ssc-vm-g4-rhev4-0554.colo.seagate.com:f6fc86b0"
[root@ssc-vm-g4-rhev4-0554 ~]# hctl drive-state --json '{"node":"ssc-vm-g4-rhev4-0554.colo.seagate.com","source_type":"drive","device":"/dev/sdd","state":"online"}'
0
2022-04-21 14:00:03,216 [DEBUG] Bound <class 'hax.common.HaxGlobalState'> to an instance <hax.common.HaxGlobalState object at 0x7f2da599d518>
2022-04-21 14:00:03,216 [DEBUG] Created and configured an injector, config=<function di_configuration at 0x7f2daaafb378>
2022-04-21 14:00:03,221 [DEBUG] Starting new HTTP connection (1): 127.0.0.1:8500
2022-04-21 14:00:03,222 [DEBUG] http://127.0.0.1:8500 "GET /v1/kv/eq-epoch HTTP/1.1" 200 93
2022-04-21 14:00:03,234 [DEBUG] http://127.0.0.1:8500 "PUT /v1/txn HTTP/1.1" 200 219
2022-04-21 14:00:03,235 [INFO] Written to epoch: 3
[root@ssc-vm-g4-rhev4-0554 ~]# hctl status -d
Bytecount:
    critical : 0
    damaged : 0
    degraded : 0
    healthy : 819200
Data pool:
    # fid name
    0x6f00000000000001:0x59 'sns-pool'
Profile:
    # fid name: pool(s)
    0x7000000000000001:0x89 'default': 'sns-pool' None None
Services:
    ssc-vm-g4-rhev4-0554.colo.seagate.com  (RC)
    [started]  hax                 0x7200000000000001:0x9          inet:tcp:10.230.240.235@22001
    [started]  confd               0x7200000000000001:0xc          inet:tcp:10.230.240.235@21002
    [started]  ioservice           0x7200000000000001:0xf          inet:tcp:10.230.240.235@21003
    [started]  ioservice           0x7200000000000001:0x1e         inet:tcp:10.230.240.235@21004
    [started]  ioservice           0x7200000000000001:0x2d         inet:tcp:10.230.240.235@21005
    [started]  ioservice           0x7200000000000001:0x3e         inet:tcp:10.230.240.235@21006
    [offline]  m0_client_other     0x7200000000000001:0x4b         inet:tcp:10.230.240.235@22501
    [unknown]  m0_client_other     0x7200000000000001:0x4e         inet:tcp:10.230.240.235@22502
Devices:
    ssc-vm-g4-rhev4-0554.colo.seagate.com
    [online]  /dev/sdd
    [online]  /dev/sde
    [online]  /dev/null
    [online]  /dev/sdf
    [online]  /dev/sdg
    [online]  /dev/sdh
    [online]  /dev/null
    [online]  /dev/sdi
    [online]  /dev/null
    [online]  /dev/sdb
    [online]  /dev/sdc
    [online]  /dev/null
[root@ssc-vm-g4-rhev4-0554 ~]# m0client -l 'inet:tcp:10.230.240.235@22501' -H 'inet:tcp:10.230.240.235@22001' -p '<0x7000000000000001:0x89>' -P '<0x7200000000000001:0x4b>'
m0client >>read 1048680 /tmp/read_1048680_online 4096 200 50
m0client >>write 1048681 /tmp/128M 4096 200 50
m0client >>quit
Help:
touch   OBJ_ID
write   OBJ_ID SRC_FILE BLOCK_SIZE BLOCK_COUNT BLOCKS_PER_IO UPDATE_FLAG OFFSET
read    OBJ_ID DEST_FILE BLOCK_SIZE BLOCK_COUNT BLOCKS_PER_IO
delete  OBJ_ID
help
quit
[root@ssc-vm-g4-rhev4-0554 ~]#
[root@ssc-vm-g4-rhev4-0554 ~]# ls -l /tmp
total 136524
...
-rw-r--r-- 1 root   root      819200 Apr 21 13:59 read_1048680
-rw-r--r-- 1 root   root      819200 Apr 21 14:00 read_1048680_online
[root@ssc-vm-g4-rhev4-0554 ~]#
[root@ssc-vm-g4-rhev4-0554 ~]# diff /tmp/read_1048680 /tmp/read_1048680_online
[root@ssc-vm-g4-rhev4-0554 ~]#
andriytk commented 2 years ago

@nikitadanilov suggested to use M0_OOF_NOHOLE flag to return the error when there is no data in cob. By using this flag client can get the error and switch automatically to the degraded read mode.

Currently, the switch to degraded mode does not happen automatically. Here is an example when the disk is back online, but the object was written in degraded mode previously, when the disk was offline, so its cob is missing the needed data:

$ ./m0cat -l inet:tcp:192.168.180.165@22501 -H inet:tcp:192.168.180.165@22001 -p 0x7000000000000001:0x9f -P 0x7200000000000001:0x5b -s 10m -c 20 -L 9 -N -o 0x3039:0x679790 /tmp/200m.check 
pver is : <0:0>
motr[1180755]:  fa00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x1dcb010 from=inet:tcp:192.168.180.165@21003 rc=-5 ti_rc=-5 @<4300000100003039:679790>
motr[1180755]:  fa00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x1dcb010 from=inet:tcp:192.168.180.165@21003 rc=-5 ti_rc=-5 @<4300000100003039:679790>
Reading from object failed!
m0_read failed! rc = -5
$ cmp /tmp/200m{,.check}
cmp: EOF on /tmp/200m.check which is empty

(Note: -N option used in m0cat for M0_OOF_NOHOLE.)

We can see the error (which is good), but the switch to degraded mode read is not happening.

Compare with the same command when the disk is offline and the read happens in degraded mode:

$ ./m0cat -l inet:tcp:192.168.180.165@22501 -H inet:tcp:192.168.180.165@22001 -p 0x7000000000000001:0x9f -P 0x7200000000000001:0x5b -s 10m -c 20 -L 9 -N -o 0x3039:0x679790 /tmp/200m.check 
pver is : <0:0>
motr[1190038]:  2a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x28e61a0 from=inet:tcp:192.168.180.165@21003 rc=-5 ti_rc=-5 @<4300000100003039:679790>
motr[1190038]:  2a90   WARN  [io_req.c:1665:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x28e61a0 dgmap_nr=24
$ cmp /tmp/200m{,.check}
$

So we have to fix the client motr code so that it would switch to the degraded read automatically even when the disk is online, but there is some error when reading from it.

andriytk commented 2 years ago

@Andriy diff for me between degraded read (read after drive transitioned to offline) and regular (after transitioning the drive to online) was empty.

@mssawant looks like you started writing the object already after the drive was failed - this is not the correct scenario.

It's important to start writing the object before the drive is failed, so that the cob will be created for this object for this drive. There must be a situation when the cob exists, but it does not have the needed data for the unit we try to read later from it when the disk is back online.

Without M0_OOF_NOHOLE flag, such reads return zeros without any errors, so the user does not even know if the data is correct or not (unless read-verify mode is ON, of course), and that's why the read data of the object differs from the original one.

siningwuseagate commented 2 years ago

@nikitadanilov suggested to use M0_OOF_NOHOLE flag to return the error when there is no data in cob. By using this flag client can get the error and switch automatically to the degraded read mode.

Currently, the switch to degraded mode does not happen automatically. Here is an example when the disk is back online, but the object was written in degraded mode previously, when the disk was offline, so its cob is missing the needed data:

$ ./m0cat -l inet:tcp:192.168.180.165@22501 -H inet:tcp:192.168.180.165@22001 -p 0x7000000000000001:0x9f -P 0x7200000000000001:0x5b -s 10m -c 20 -L 9 -N -o 0x3039:0x679790 /tmp/200m.check 
pver is : <0:0>
motr[1180755]:  fa00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x1dcb010 from=inet:tcp:192.168.180.165@21003 rc=-5 ti_rc=-5 @<4300000100003039:679790>
motr[1180755]:  fa00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x1dcb010 from=inet:tcp:192.168.180.165@21003 rc=-5 ti_rc=-5 @<4300000100003039:679790>
Reading from object failed!
m0_read failed! rc = -5
$ cmp /tmp/200m{,.check}
cmp: EOF on /tmp/200m.check which is empty

(Note: -N option used in m0cat for M0_OOF_NOHOLE.)

We can see the error (which is good), but the switch to degraded mode read is not happening.

@andriytk from the trace and code, it does call ioreq_dgmode_read(), but the current implementation doesn't switch to degraded read if the target device is in healthy state (https://github.com/Seagate/cortx-motr/blob/c127482d1a7ef9897926666f92af596e33e4d8b8/motr/io_req.c#L1627). I simply comment the lines from 1627 to 1638 (the code checking for device states) to force it switch to degrade read whenever there is an error. It seems work from the test below, but I don't know if it is a correct solution for it, we can discuss further.

motr[3137660]: a9f0 ERROR [io_req_fop.c:363:io_bottom_half] ioo=0x7fd2f0012e60 from=inet:tcp:192.168.0.41@21006 rc=-5 ti_rc=-5 @<4300000600003039:40beb60> motr[3137660]: aa90 WARN [io_req.c:1673:ioreq_dgmode_read] Process failed parity groups in dgmode/read ioo=0x7fd2f0012e60 dgmap_nr=4 2022/04/22 14:15:00 mio.go:658: R: off=201326592 len=8388608 bs=16777216 gs=16777216 speed=1332 (Kbytes/sec) [root@centos8 cortx-motr]# cmp /tmp/200m /tmp/200m.chk [root@centos8 cortx-motr]#

andriytk commented 2 years ago

I simply comment the lines from 1627 to 1638 (the code checking for device states) to force it switch to degrade read whenever there is an error. It seems work from the test below, but I don't know if it is a correct solution for it

@siningwuseagate, it sounds great! And the change looks fine to me.

mssawant commented 2 years ago

@andriytk, @siningwuseagate, This mean all reads will have to use M0_OOF_NOHOLE flag until data dtm is implemented for transient failures, in case of permanent failures repair-rebalance can be used to write the relevant data back to its original location. What if Motr by default returns an error for holes instead of 0s? sns repair does handle non existing cob situation. cc @nikitadanilov

andriytk commented 2 years ago

@mssawant, I don't mind to make M0_OOF_NOHOLE always ON by default. I even don't know - why this flag is relevant for non-existing data after the end of the cob length...

Well, if we start writing to such object with the missing data in some cob - the missing data might become a hole in this cob, yes...

chandradharraval commented 2 years ago

Hi @andriytk, Will this issue be fixed in Motr or Hare or both?

andriytk commented 2 years ago

@chandradharraval, this issue is opened for Motr repo, so... mostly in Motr, yes.

andriytk commented 2 years ago

In write case, degraded mode means that we don't return error to the user unless there are more than K failures for any parity group written.

Implemented at https://github.com/Seagate/cortx-motr/pull/1701.

andriytk commented 2 years ago

After killing m0d-ios process, but before it became offline in hare:

22:23 ant@rocky83:utils$ ./m0cp -l inet:tcp:192.168.180.165@22501 -H inet:tcp:192.168.180.165@22001 -p 0x7000000000000001:0xa2 -P 0x7200000000000001:0x5b -s 16k -c 1 -L 1 /dev/zero -o 0x12345678:0x678900210 -u
motr[646686]:  b810  ERROR  [rpc/session.c:583:m0_rpc_session_validate]  <! rc=-22 Session state M0_RPC_SESSION_INITIALISED is not valid
motr[646686]:  b810  ERROR  [rpc/session.c:583:m0_rpc_session_validate]  <! rc=-22 Session state M0_RPC_SESSION_INITIALISED is not valid
motr[646686]:  b890  ERROR  [rpc/rpc.c:119:m0_rpc__post_locked]  <! rc=-107
motr[646686]:  ba00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x14db270] rpc item 0x7fd5d00448f0 rc=-107
motr[646686]:  ba00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x14db270 from=inet:tcp:192.168.180.165@21004 rc=-107 ti_rc=-107 @<4300000212345678:678900210>
motr[646686]:  ba20  FATAL  [lib/assert.c:50:m0_panic]  panic: (state_get(mach, fail_state)->sd_flags & M0_SDF_FAILURE) at m0_sm_fail() (sm/sm.c:473)  [git: 2.0.0-670-35-ga3e6399f7-dirty] /home/ant/cortx-motr/motr/st/utils/m0trace.646686
Motr panic: (state_get(mach, fail_state)->sd_flags & M0_SDF_FAILURE) at m0_sm_fail() sm/sm.c:473 (errno: 0) (last failed: none) [git: 2.0.0-670-35-ga3e6399f7-dirty] pid: 646686  /home/ant/cortx-motr/motr/st/utils/m0trace.646686

Stack:

#3  0x00007fd5f9787f37 in m0_panic (ctx=ctx@entry=0x7fd5f9cc89c0 <__pctx.7317>) at lib/assert.c:52
#4  0x00007fd5f982af4e in m0_sm_fail (mach=0x14db358, fail_state=fail_state@entry=3, rc=-107) at sm/sm.c:475
#5  0x00007fd5f982afa9 in m0_sm_move (mach=mach@entry=0x14db358, rc=<optimized out>, state=state@entry=3) at sm/sm.c:487
#6  0x00007fd5f97c4423 in ioreq_iosm_handle_executed (grp=<optimized out>, ast=0x14db978) at motr/io_req.c:708
#7  0x00007fd5f98297b3 in m0_sm_asts_run (grp=<optimized out>) at sm/sm.c:175
#8  m0_sm_asts_run (grp=grp@entry=0x11f9e30) at sm/sm.c:150
#9  0x00007fd5f975afdf in loc_handler_thread (th=0x123dee0) at fop/fom.c:925
andriytk commented 2 years ago

It works now with this change:

diff --git a/motr/io_nw_xfer.c b/motr/io_nw_xfer.c
index 7d6d07e01..dbf85ff40 100644
--- a/motr/io_nw_xfer.c
+++ b/motr/io_nw_xfer.c
@@ -1724,14 +1724,6 @@ static void nw_xfer_req_complete(struct nw_xfer_request *xfer, bool rmw)
                               item, item->ri_type->rit_opcode, item->ri_error,
                               item->ri_sm.sm_state);

-                       /* Maintains only the first error encountered. */
-                       if (xfer->nxr_rc == 0 &&
-                           item->ri_sm.sm_state == M0_RPC_ITEM_FAILED) {
-                               xfer->nxr_rc = item->ri_error;
-                               M0_LOG(M0_DEBUG, "[%p] nwxfer rc = %d",
-                                      ioo, xfer->nxr_rc);
-                       }
-
                        M0_ASSERT(ergo(item->ri_sm.sm_state !=
                                       M0_RPC_ITEM_UNINITIALISED,
                                       item->ri_rmachine != NULL));

Note: if needed, the error will be set from ti_rc.

Here is the test that shows that with the 2 processes failures (which we cannot tolerate) the error is returned fine:

23:40 ant@rocky83:mcp$ ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x5b -prof 0x7000000000000001:0xa2 -hax inet:tcp:192.168.180.165@22001 -v /tmp/200m 12345:6789008 & sleep 2; pgrep -a m0d | tail -2 | awk '{print $1}' | xargs sudo kill -9
[1] 695713
23:40 ant@rocky83:mcp$ 
23:40 ant@rocky83:mcp$ 
23:40 ant@rocky83:mcp$ motr[695713]:  e4d0  ERROR  [pool/pool_machine.c:783:m0_poolmach_state_transit]  <7600000000000001:6c>: nr_failures:3 max_failures:2 event_index:8 event_state:3
motr[695713]:  e4d0  ERROR  [pool/pool_machine.c:783:m0_poolmach_state_transit]  <7600000000000001:6c>: nr_failures:4 max_failures:2 event_index:9 event_state:3
motr[695713]:  8a00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x2254360] rpc item 0x7fb1fc0b3c50 rc=-125
motr[695713]:  8a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x2254360 from=inet:tcp:192.168.180.165@21007 rc=-125 ti_rc=-125 @<4300000900003039:679790>
motr[695713]:  8990  ERROR  [io_req.c:1545:device_check]  <! rc=-5 [0x2254360] number of failed units > K (2 > 2), OR number of failed services (1) > 1, OR number of failed nodes (0) > 0
motr[695713]:  8b80  ERROR  [io_req.c:549:ioreq_iosm_handle_executed]  iro_dgmode_write() failed, rc=-5
2022/04/28 23:40:51 mcp.go:140: write 33554432 bytes at 0: io op=11 failed: rc=-125

[1]+  Exit 1                  ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x5b -prof 0x7000000000000001:0xa2 -hax inet:tcp:192.168.180.165@22001 -v /tmp/200m 12345:6789008
23:40 ant@rocky83:mcp$
andriytk commented 2 years ago

Another run of the same test:

23:43 ant@rocky83:mcp$ ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x5b -prof 0x7000000000000001:0xa2 -hax inet:tcp:192.168.180.165@22001 -v /tmp/200m 12345:6789008 & sleep 3; pgrep -a m0d | tail -2 | awk '{print $1}' | xargs sudo kill -9
[1] 698269
2022/04/28 23:43:39 mio.go:564: W: off=0 len=33554432 bs=33554432 gs=16777216 speed=91 (Mbytes/sec)
2022/04/28 23:43:39 mio.go:564: W: off=33554432 len=33554432 bs=33554432 gs=16777216 speed=51 (Mbytes/sec)
23:43 ant@rocky83:mcp$ 2022/04/28 23:43:40 mio.go:564: W: off=67108864 len=33554432 bs=33554432 gs=16777216 speed=64 (Mbytes/sec)
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc069590 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7fa9d0000e20 from=inet:tcp:192.168.180.165@21006 rc=-125 ti_rc=-125 @<4300000600003039:679790>
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc0674c0 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc0653f0 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc063320 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc09a910 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc098840 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc096770 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc0946a0 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc0925d0 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc090500 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc08e430 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc08c360 rc=-125
motr[698269]:  84d0  ERROR  [pool/pool_machine.c:783:m0_poolmach_state_transit]  <7600000000000001:6c>: nr_failures:3 max_failures:2 event_index:8 event_state:3
motr[698269]:  84d0  ERROR  [pool/pool_machine.c:783:m0_poolmach_state_transit]  <7600000000000001:6c>: nr_failures:4 max_failures:2 event_index:9 event_state:3
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc0718d0 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc06f800 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc06d730 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc06b660 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc0aaf90 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc0a8ec0 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc0a6df0 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc0a4d20 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc0a2c50 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc0a0b80 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc09eab0 rc=-125
motr[698269]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x7fa9d0000e20] rpc item 0x7fa9cc09c9e0 rc=-125
motr[698269]:  c990  ERROR  [io_req.c:1545:device_check]  <! rc=-5 [0x7fa9d0000e20] number of failed units > K (0 > 2), OR number of failed services (3) > 1, OR number of failed nodes (0) > 0
motr[698269]:  cb80  ERROR  [io_req.c:549:ioreq_iosm_handle_executed]  iro_dgmode_write() failed, rc=-5
2022/04/28 23:43:51 mcp.go:140: write 33554432 bytes at 100663296: io op=11 failed: rc=-125

[1]+  Exit 1                  ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x5b -prof 0x7000000000000001:0xa2 -hax inet:tcp:192.168.180.165@22001 -v /tmp/200m 12345:6789008
23:43 ant@rocky83:mcp$
stale[bot] commented 2 years ago

This issue/pull request has been marked as needs attention as it has been left pending without new activity for 4 days. Tagging @nkommuri @mehjoshi @huanghua78 for appropriate assignment. Sorry for the delay & Thank you for contributing to CORTX. We will get back to you as soon as possible.

andriytk commented 2 years ago

Here is the test which shows that the object is written in degraded mode (after ios process is killed), and then read in degraded mode successfully:

12:55 ant@rocky83:mcp$ ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x5b -prof 0x7000000000000001:0xa2 -hax inet:tcp:192.168.180.165@22001 -v -trace /tmp/200m 12345:6789010 & sleep 3; pgrep -a m0d | tail -1 | awk '{print $1}' | xargs sudo kill -9
[1] 46950
2022/05/03 13:04:15 mio.go:564: W: off=0 len=33554432 bs=33554432 gs=16777216 speed=72 (Mbytes/sec)
2022/05/03 13:04:16 mio.go:564: W: off=33554432 len=33554432 bs=33554432 gs=16777216 speed=45 (Mbytes/sec)
13:04 ant@rocky83:mcp$ 
13:04 ant@rocky83:mcp$ motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc738051ba0 rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x1335360 from=inet:tcp:192.168.180.165@21007 rc=-125 ti_rc=-125 @<4300000900003039:679792>
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73804b120 rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc738044720 rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc738437d60 rc=-125
2022/05/03 13:04:25 mio.go:564: W: off=67108864 len=33554432 bs=33554432 gs=16777216 speed=3475 (Kbytes/sec)
motr[46950]:  c810  ERROR  [rpc/session.c:578:m0_rpc_session_validate]  <! rc=-125 Cancelled session
motr[46950]:  c810  ERROR  [rpc/session.c:578:m0_rpc_session_validate]  <! rc=-125 Cancelled session
motr[46950]:  c810  ERROR  [rpc/session.c:578:m0_rpc_session_validate]  <! rc=-125 Cancelled session
motr[46950]:  c810  ERROR  [rpc/session.c:578:m0_rpc_session_validate]  <! rc=-125 Cancelled session
motr[46950]:  c890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  c890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  c890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  c890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  c890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  c890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  c890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  c890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc738053460 rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x1335360 from=inet:tcp:192.168.180.165@21007 rc=-125 ti_rc=-125 @<4300000900003039:679792>
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc7384c5250 rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc7384c58a0 rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc7383af030 rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73835ac70 rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73825db60 rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc7382febc0 rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc738246cc0 rc=-125
2022/05/03 13:04:27 mio.go:564: W: off=100663296 len=33554432 bs=33554432 gs=16777216 speed=24 (Mbytes/sec)
motr[46950]:  c810  ERROR  [rpc/session.c:578:m0_rpc_session_validate]  <! rc=-125 Cancelled session
motr[46950]:  c810  ERROR  [rpc/session.c:578:m0_rpc_session_validate]  <! rc=-125 Cancelled session
motr[46950]:  c810  ERROR  [rpc/session.c:578:m0_rpc_session_validate]  <! rc=-125 Cancelled session
motr[46950]:  c810  ERROR  [rpc/session.c:578:m0_rpc_session_validate]  <! rc=-125 Cancelled session
motr[46950]:  c890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  c890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  c890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  c890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  c890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  c890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  c890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  c890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  c890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  c890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  c890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  c890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc7380545f0 rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x1335360 from=inet:tcp:192.168.180.165@21007 rc=-125 ti_rc=-125 @<4300000900003039:679792>
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc738044f30 rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc7383180f0 rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc738373030 rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc7381ec7e0 rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc738388030 rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc738346ce0 rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73841e750 rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73832cc00 rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73828f4a0 rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc7383020d0 rc=-125
motr[46950]:  ca00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc7384f0ae0 rc=-125
2022/05/03 13:04:30 mio.go:564: W: off=134217728 len=33554432 bs=33554432 gs=16777216 speed=11 (Mbytes/sec)
motr[46950]:  e810  ERROR  [rpc/session.c:578:m0_rpc_session_validate]  <! rc=-125 Cancelled session
motr[46950]:  e810  ERROR  [rpc/session.c:578:m0_rpc_session_validate]  <! rc=-125 Cancelled session
motr[46950]:  e810  ERROR  [rpc/session.c:578:m0_rpc_session_validate]  <! rc=-125 Cancelled session
motr[46950]:  e810  ERROR  [rpc/session.c:578:m0_rpc_session_validate]  <! rc=-125 Cancelled session
motr[46950]:  e890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  e890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  e890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  e890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  e890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  e890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  e890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  e890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  ea00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73c0940e0 rc=-125
motr[46950]:  ea00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x1335360 from=inet:tcp:192.168.180.165@21007 rc=-125 ti_rc=-125 @<4300000800003039:679792>
motr[46950]:  ea00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73c0961b0 rc=-125
motr[46950]:  ea00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73c098280 rc=-125
motr[46950]:  ea00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73c09a350 rc=-125
motr[46950]:  ea00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73c06b0e0 rc=-125
motr[46950]:  ea00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73c06d170 rc=-125
motr[46950]:  ea00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73c06f240 rc=-125
motr[46950]:  ea00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73c071310 rc=-125
2022/05/03 13:04:31 mio.go:564: W: off=167772160 len=33554432 bs=33554432 gs=16777216 speed=27 (Mbytes/sec)
motr[46950]:  e810  ERROR  [rpc/session.c:578:m0_rpc_session_validate]  <! rc=-125 Cancelled session
motr[46950]:  e810  ERROR  [rpc/session.c:578:m0_rpc_session_validate]  <! rc=-125 Cancelled session
motr[46950]:  e810  ERROR  [rpc/session.c:578:m0_rpc_session_validate]  <! rc=-125 Cancelled session
motr[46950]:  e810  ERROR  [rpc/session.c:578:m0_rpc_session_validate]  <! rc=-125 Cancelled session
motr[46950]:  e890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  e890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  e890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  e890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  e890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  e890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  e890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  e890  ERROR  [rpc/rpc.c:126:m0_rpc__post_locked]  <! rc=-125
motr[46950]:  ea00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73c215dc0 rc=-125
motr[46950]:  ea00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x1335360 from=inet:tcp:192.168.180.165@21007 rc=-125 ti_rc=-125 @<4300000800003039:679792>
motr[46950]:  ea00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73c217e90 rc=-125
motr[46950]:  ea00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73c375c00 rc=-125
motr[46950]:  ea00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73c377bc0 rc=-125
motr[46950]:  ea00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73c0cc2d0 rc=-125
motr[46950]:  ea00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73c04b980 rc=-125
motr[46950]:  ea00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73c047120 rc=-125
motr[46950]:  ea00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1335360] rpc item 0x7fc73c05f2e0 rc=-125
2022/05/03 13:04:32 mio.go:564: W: off=201326592 len=8388608 bs=16777216 gs=16777216 speed=8150 (Kbytes/sec)

[1]+  Done                    ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x5b -prof 0x7000000000000001:0xa2 -hax inet:tcp:192.168.180.165@22001 -v -trace /tmp/200m 12345:6789010
13:04 ant@rocky83:mcp$ 
13:04 ant@rocky83:mcp$ 
13:04 ant@rocky83:mcp$ sudo systemctl start m0d@0x7200000000000001:0x4c
13:04 ant@rocky83:mcp$ 
13:04 ant@rocky83:mcp$ ./mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x5b -prof 0x7000000000000001:0xa2 -hax inet:tcp:192.168.180.165@22001 -v -osz $((200*1024)) 12345:6789010 /tmp/200m.check
2022/05/03 13:05:13 mio.go:646: R: off=0 len=33554432 bs=33554432 gs=16777216 speed=66 (Mbytes/sec)
2022/05/03 13:05:13 mio.go:646: R: off=33554432 len=33554432 bs=33554432 gs=16777216 speed=95 (Mbytes/sec)
motr[47839]:  da00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7fce44000b80 from=inet:tcp:192.168.180.165@21007 rc=-5 ti_rc=-5 @<4300000900003039:679792>
motr[47839]:  dac0   WARN  [io_req.c:1642:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x7fce44000b80 dgmap_nr=1
2022/05/03 13:05:14 mio.go:646: R: off=67108864 len=33554432 bs=33554432 gs=16777216 speed=64 (Mbytes/sec)
motr[47839]:  da00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7fce44000b80 from=inet:tcp:192.168.180.165@21007 rc=-5 ti_rc=-5 @<4300000900003039:679792>
motr[47839]:  dac0   WARN  [io_req.c:1642:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x7fce44000b80 dgmap_nr=8
2022/05/03 13:05:15 mio.go:646: R: off=100663296 len=33554432 bs=33554432 gs=16777216 speed=24 (Mbytes/sec)
motr[47839]:  da00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7fce44000b80 from=inet:tcp:192.168.180.165@21007 rc=-5 ti_rc=-5 @<4300000800003039:679792>
motr[47839]:  dac0   WARN  [io_req.c:1642:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x7fce44000b80 dgmap_nr=8
2022/05/03 13:05:16 mio.go:646: R: off=134217728 len=33554432 bs=33554432 gs=16777216 speed=33 (Mbytes/sec)
motr[47839]:  da00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7fce44000b80 from=inet:tcp:192.168.180.165@21007 rc=-5 ti_rc=-5 @<4300000900003039:679792>
motr[47839]:  dac0   WARN  [io_req.c:1642:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x7fce44000b80 dgmap_nr=8
2022/05/03 13:05:17 mio.go:646: R: off=167772160 len=33554432 bs=33554432 gs=16777216 speed=25 (Mbytes/sec)
motr[47839]:  da00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x7fce44000b80 from=inet:tcp:192.168.180.165@21007 rc=-5 ti_rc=-5 @<4300000800003039:679792>
motr[47839]:  dac0   WARN  [io_req.c:1642:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x7fce44000b80 dgmap_nr=4
2022/05/03 13:05:18 mio.go:646: R: off=201326592 len=8388608 bs=16777216 gs=16777216 speed=14 (Mbytes/sec)
13:05 ant@rocky83:mcp$ 
13:05 ant@rocky83:mcp$ 
13:05 ant@rocky83:mcp$ cmp /tmp/200m{,.check}
13:05 ant@rocky83:mcp$

Note: we start killed ios process back before reading because degraded dix read is not ready yet. (And m0_client_init() always tries to GET information about the root index.)

andriytk commented 2 years ago

Sometimes motr client gets stuck during write when one of the processes is killed:

(gdb) bt
#0  0x00007f8416440ef2 in do_futex_wait () from /lib64/libpthread.so.0
#1  0x00007f8416441003 in __new_sem_wait_slow () from /lib64/libpthread.so.0
#2  0x00007f84169eea80 in m0_semaphore_timeddown (semaphore=0x7ffef64e41c8, abs_timeout=<optimized out>)
    at lib/user_space/semaphore.c:126
#3  0x00007f84169df8e5 in m0_chan_timedwait (link=link@entry=0x7ffef64e41a0, 
    abs_timeout=abs_timeout@entry=18446744073709551615) at lib/chan.c:356
#4  0x00007f8416a7fed0 in m0_sm_timedwait (mach=mach@entry=0x23fb760, states=states@entry=2, deadline=18446744073709551615)
    at sm/sm.c:405
#5  0x00007f8416a564e3 in reqh_service_ctx_state_wait (ctx=0x23faa40, state=state@entry=1) at reqh/reqh_service.c:809
#6  0x00007f8416a583be in m0_reqh_service_connect_wait (ctx=ctx@entry=0x23faa40) at reqh/reqh_service.c:826
#7  0x00007f8416a4e049 in m0_pools_common_service_ctx_connect_sync (pc=pc@entry=0x225cb18) at pool/pool.c:1613
#8  0x00007f8416a07b49 in pools_init (m0c=0x2259730) at motr/client_init.c:1052
#9  initlift_pools (mach=0x2262c30) at motr/client_init.c:1087
#10 0x00007f8416a80d00 in state_set (mach=0x2262c30, state=6, rc=<optimized out>) at sm/sm.c:461
#11 0x00007f8416a09648 in m0_client_init (m0c_p=0x7d0768 <instance>, conf=0x7d0720 <conf>, init_m0=<optimized out>)
    at motr/client_init.c:1606
#12 0x00000000004aac1f in _cgo_24d45f7574f8_Cfunc_m0_client_init (v=0xc000048c90) at cgo-gcc-prolog:154
#13 0x000000000045ef50 in runtime.asmcgocall () at /usr/lib/golang/src/runtime/asm_amd64.s:765
#14 0x00007f84178f0038 in ?? ()
#15 0x00007ffef64e4478 in ?? ()
#16 0x000000000040f78e in runtime.persistentalloc.func1 () at /usr/lib/golang/src/runtime/malloc.go:1365
#17 0x000000000045d0a9 in runtime.systemstack () at /usr/lib/golang/src/runtime/asm_amd64.s:383
#18 0x0000000000461749 in runtime.newproc (siz=4575141, fn=0x45cf5b <runtime.rt0_go+315>) at <autogenerated>:1
#19 0x00000000004ab920 in crosscall_amd64 ()
#20 0x000000000045cfa5 in runtime.mstart () at /usr/lib/golang/src/runtime/asm_amd64.s:248
#21 0x000000000045cf5b in runtime.rt0_go () at /usr/lib/golang/src/runtime/asm_amd64.s:223
#22 0x000000000000000d in ?? ()
#23 0x00007ffef64e45c8 in ?? ()
#24 0x000000000000000d in ?? ()
#25 0x00007ffef64e45c8 in ?? ()
#26 0x0000000000000000 in ?? ()

Looks like it even did not start the i/o and got stuck on the m0_client_init()...

andriytk commented 2 years ago

Another issue was detected yesterday: when there are two failed devices - the data will be recovered without errors (as it should be on 4+2 EC), but it will be corrupted:

$ hctl status -d
Bytecount:
    critical : 0
    damaged : 0
    degraded : 0
    healthy : 0
Data pool:
    # fid name
    0x6f00000000000001:0x6b 'the pool'
Profile:
    # fid name: pool(s)
    0x7000000000000001:0xa2 'default': 'the pool' None None
Services:
    rocky83  (RC)
    [started]  hax                 0x7200000000000001:0xa          inet:tcp:192.168.180.165@22001
    [started]  confd               0x7200000000000001:0xd          inet:tcp:192.168.180.165@21002
    [started]  ioservice           0x7200000000000001:0x10         inet:tcp:192.168.180.165@21003
    [started]  ioservice           0x7200000000000001:0x1f         inet:tcp:192.168.180.165@21004
    [started]  ioservice           0x7200000000000001:0x2e         inet:tcp:192.168.180.165@21005
    [started]  ioservice           0x7200000000000001:0x3d         inet:tcp:192.168.180.165@21006
    [started]  ioservice           0x7200000000000001:0x4c         inet:tcp:192.168.180.165@21007
    [unknown]  m0_client_other     0x7200000000000001:0x5b         inet:tcp:192.168.180.165@22501
    [unknown]  m0_client_other     0x7200000000000001:0x5e         inet:tcp:192.168.180.165@22502
Devices:
    rocky83
    [online]  /dev/loop0
    [online]  /dev/mapper/bad_disk
    [online]  /dev/null
    [online]  /dev/loop2
    [online]  /dev/mapper/bad_disk2
    [online]  /dev/null
    [online]  /dev/loop4
    [online]  /dev/loop5
    [online]  /dev/null
    [online]  /dev/loop6
    [online]  /dev/loop7
    [online]  /dev/null
    [online]  /dev/loop8
    [online]  /dev/loop9
    [online]  /dev/null
$ mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x5b -prof 0x7000000000000001:0xa2 -hax inet:tcp:192.168.180.165@22001 -v -osz $((200*1024)) -trace 12345:6789011 /tmp/200m.check
motr[199884]:  aa00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x2084250 from=inet:tcp:192.168.180.165@21003 rc=-5 ti_rc=-5 @<4300000100003039:679793>
motr[199884]:  aac0   WARN  [io_req.c:1646:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x2084250 dgmap_nr=8
2022/05/03 19:45:23 mio.go:646: R: off=0 len=33554432 bs=33554432 gs=16777216 speed=9502 (Kbytes/sec)
motr[199884]:  aa00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x2084250 from=inet:tcp:192.168.180.165@21003 rc=-5 ti_rc=-5 @<4300000100003039:679793>
motr[199884]:  aac0   WARN  [io_req.c:1646:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x2084250 dgmap_nr=4
2022/05/03 19:45:25 mio.go:646: R: off=33554432 len=33554432 bs=33554432 gs=16777216 speed=13 (Mbytes/sec)
motr[199884]:  aa00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x2084250 from=inet:tcp:192.168.180.165@21004 rc=-5 ti_rc=-5 @<4300000300003039:679793>
motr[199884]:  aac0   WARN  [io_req.c:1646:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x2084250 dgmap_nr=4
motr[199884]:  aa00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x2084250 from=inet:tcp:192.168.180.165@21003 rc=-5 ti_rc=-5 @<4300000100003039:679793>
2022/05/03 19:45:28 mio.go:646: R: off=67108864 len=33554432 bs=33554432 gs=16777216 speed=10229 (Kbytes/sec)
motr[199884]:  aa00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x2084250 from=inet:tcp:192.168.180.165@21004 rc=-5 ti_rc=-5 @<4300000300003039:679793>
motr[199884]:  aac0   WARN  [io_req.c:1646:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x2084250 dgmap_nr=8
motr[199884]:  aa00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x2084250 from=inet:tcp:192.168.180.165@21004 rc=-5 ti_rc=-5 @<4300000300003039:679793>
2022/05/03 19:45:32 mio.go:646: R: off=100663296 len=33554432 bs=33554432 gs=16777216 speed=9101 (Kbytes/sec)
motr[199884]:  ca00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x2084250 from=inet:tcp:192.168.180.165@21004 rc=-5 ti_rc=-5 @<4300000300003039:679793>
motr[199884]:  cac0   WARN  [io_req.c:1646:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x2084250 dgmap_nr=8
2022/05/03 19:45:33 mio.go:646: R: off=134217728 len=33554432 bs=33554432 gs=16777216 speed=20 (Mbytes/sec)
motr[199884]:  ca00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x2084250 from=inet:tcp:192.168.180.165@21003 rc=-5 ti_rc=-5 @<4300000100003039:679793>
motr[199884]:  cac0   WARN  [io_req.c:1646:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x2084250 dgmap_nr=8
2022/05/03 19:45:35 mio.go:646: R: off=167772160 len=33554432 bs=33554432 gs=16777216 speed=23 (Mbytes/sec)
2022/05/03 19:45:35 mio.go:646: R: off=201326592 len=8388608 bs=16777216 gs=16777216 speed=16 (Mbytes/sec)
$ 
$ cmp /tmp/200m{,.check}
/tmp/200m /tmp/200m.check differ: char 75497473, line 293982

Here is the patch that was used to not fail on the parity unit read error:

diff --git a/motr/io_req.c b/motr/io_req.c
index 1d16de85e..ea75ec32e 100644
--- a/motr/io_req.c
+++ b/motr/io_req.c
@@ -684,6 +684,7 @@ static void ioreq_iosm_handle_executed(struct m0_sm_group *grp,
        }
 done:
        ioo->ioo_nwxfer.nxr_ops->nxo_complete(&ioo->ioo_nwxfer, rmw);
+       ioo->ioo_rc = 0;

 #ifdef CLIENT_FOR_M0T1FS
        /* XXX: TODO: update the inode size on the mds */
diff --git a/motr/io_req_fop.c b/motr/io_req_fop.c
index 6881a7dc1..c1a37c3b8 100644
--- a/motr/io_req_fop.c
+++ b/motr/io_req_fop.c
@@ -364,13 +364,6 @@ ref_dec:
 #undef LOGMSG
        }

-       /*
-        * Sining: don't set the ioo_rc utill replies come back from  dgmode
-        * IO.
-        */
-       if (ioo->ioo_rc == 0 && ioo->ioo_dgmode_io_sent == true)
-               ioo->ioo_rc = rc;
-
        if (irfop->irf_pattr == PA_DATA)
                tioreq->ti_databytes += rbulk->rb_bytes;
        else
andriytk commented 2 years ago

OK, I think the reason why it doesn't work (see my previous comment) is because we don't mark the parity units as PA_READ_FAILED.

The flag is set via the ioreq_fop_dgmode_read() -> pargrp_iomap_dgmode_process() calls from ioreq_dgmode_read(). But in user space client code at motr/io_req.c (in contrast to kernel module m0t1fs code) ioreq_fop_dgmode_read() is not called for the parity units, because of this code in the very beginning of the ioreq_dgmode_read():

https://github.com/Seagate/cortx-motr/blob/d6e93599f7fb0b8c1aff2fc2e2cabccadf2f7900/motr/io_req.c#L1583-L1593

So the recovery is done on the wrong parity data (one of the parity unit is not marked as failed).

andriytk commented 2 years ago

The issue from my previous comment is fixed by https://github.com/Seagate/cortx-motr/pull/1726:

$ mcp -ep inet:tcp:192.168.180.165@21501 -proc 0x7200000000000001:0x5b -prof 0x7000000000000001:0xa2 -hax inet:tcp:192.168.180.165@22001 -v -osz 16 -trace 12345:6789015 /tmp/16k.check
motr[1115840]:  ea00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x1342810 from=inet:tcp:192.168.180.165@21003 rc=-5 ti_rc=-5 @<4300000100003039:679797>
motr[1115840]:  eac0   WARN  [io_req.c:1639:ioreq_dgmode_read]  Process failed parity groups in dgmode/read ioo=0x1342810 dgmap_nr=1
motr[1115840]:  ea00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x1342810 from=inet:tcp:192.168.180.165@21004 rc=-5 ti_rc=-5 @<4300000300003039:679797>
2022/05/05 13:52:15 mio.go:646: R: off=0 len=16384 bs=16384 gs=16384 speed=140 (Kbytes/sec)
$ 
$ cmp /tmp/16k{,.check}
$
andriytk commented 2 years ago

Sometimes, when the process is crashed - there might be two errors: ECANCELED, which will be counted as service failure, and something else, which will be counted as drive error at motr/io_req.c:device_check(). For example:

2022/05/09 18:05:12 mio.go:574: W: off=67108864 len=33554432 bs=33554432 gs=16777216 speed=49 (Mbytes/sec)
motr[66126]:  46d0  ERROR  [rpc/frmops.c:576:item_fail]  packet 0x7f7c9c021c70, item 0x7f7cd45031b0[42] failed with ri_error=-4
motr[66126]:  3a00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1200360] rpc item 0x7f7cd45031b0 rc=-4
motr[66126]:  3a00  ERROR  [io_req_fop.c:363:io_bottom_half]  ioo=0x1200360 from=inet:tcp:192.168.180.165@21003 rc=-4 ti_rc=-4 @<4300000000003039:679794>
motr[66126]:  3a00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1200360] rpc item 0x7f7cd43a2a50 rc=-125
motr[66126]:  3a00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1200360] rpc item 0x7f7cd42eaa50 rc=-125
motr[66126]:  3a00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1200360] rpc item 0x7f7cd40ce200 rc=-125
motr[66126]:  3a00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1200360] rpc item 0x7f7cd41d6bb0 rc=-125
motr[66126]:  3a00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1200360] rpc item 0x7f7cd44d4940 rc=-125
motr[66126]:  3a00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1200360] rpc item 0x7f7cd410e9f0 rc=-125
motr[66126]:  3a00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1200360] rpc item 0x7f7cd4481240 rc=-125
motr[66126]:  3a00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1200360] rpc item 0x7f7cd44bf2c0 rc=-125
motr[66126]:  3a00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1200360] rpc item 0x7f7cd40e1300 rc=-125
motr[66126]:  3a00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1200360] rpc item 0x7f7cd406e1a0 rc=-125
motr[66126]:  3a00  ERROR  [io_req_fop.c:298:io_bottom_half]  [0x1200360] rpc item 0x7f7cd406db50 rc=-125
motr[66126]:  3990  ERROR  [io_req.c:1549:device_check]  <! rc=-5 [0x1200360] number of failed units > K (1 > 2), OR number of failed services (1) > 1, OR number of failed nodes (0) > 0

In this case, it will be counted as service AND an additional disk failure (false positive), and will not pass the simplistic check at at motr/io_req.c:is_pver_dud(), which does not distinguish the disks under the same failed service.

Luckily, this does not happen very often, and only at the moment of the process crash. (I could reproduce it only one time out of 7 tries.)

andriytk commented 2 years ago

I believe, this patch might fix the issue mentioned in the previous comment:

--- a/motr/io_req.c
+++ b/motr/io_req.c
@@ -1515,10 +1515,9 @@ static int device_check(struct m0_op_io *ioo)
                                M0_CNT_INC(fsvc_nr);
                        }
                } else if ((M0_IN(state, (M0_PNDS_FAILED, M0_PNDS_OFFLINE,
-                           M0_PNDS_SNS_REPAIRING, M0_PNDS_SNS_REPAIRED)) &&
-                           !is_session_marked(ioo, ti->ti_session))
-                                        ||
-                           ti->ti_rc != 0) { /* any other error */
+                                 M0_PNDS_SNS_REPAIRING, M0_PNDS_SNS_REPAIRED))
+                            || ti->ti_rc != 0 /* any error */) &&
+                          !is_session_marked(ioo, ti->ti_session)) {
                        /*
                         * The case when multiple devices under the same service
                         * are unavailable.

The problem with the old code is that it doesn't check if the failed target (disk) is under the failed process already, so it's counted as an additional error, making it a false positive.

Updated the patch at https://github.com/Seagate/cortx-motr/pull/1701.

cortx-admin commented 2 years ago

Gaurav Chaudhari commented in Jira Server:

{panel:bgColor=#c1c7d0}h2. motr - main branch build pipeline SUCCESS h3. Build Info:

h3. Image Location :

cortx-admin commented 2 years ago

Chandradhar Raval commented in Jira Server:

Marking this Jira Closed and corresponding PR is merged now

cortx-admin commented 2 years ago

Gaurav Chaudhari commented in Jira Server:

{panel:bgColor=#c1c7d0}h2. motr - main branch build pipeline SUCCESS h3. Build Info:

h3. Image Location :