QA » openQA Project » openQA Infrastructure

@okurz, Hi Oliver, this issue introdued the majority of VT failures in latest build, see https://openqa.suse.de/tests/overview?distri=sle&version=15-SP5&build=96.1&groupid=264. When do you expect this fixed? @Julie_CAO, To exclude the impact, better to consider if it is needed to temporarily set the worker down based on the reply?

okurz wrote:

Right now I see that https://openqa.suse.de/tests/11030545#live worked to boot the system fine so either the problem does not reproduce or is sporadic.

Don't know why this job survived the ipmitool command, though it failed finally. It is the only survivor today. I just run another test on this machine and it failed again, https://openqa.suse.de/tests/11031023#details.

There might be a problem in the ipmitool command line. The command line option
-C 3 might improve stability by forcing an updated cipher suite. I suggest you use that option and compare statistical stability with and without this option.

-C 3 is the default option of ipmitool for IPMIv2.0.

       -C <ciphersuite>
              The remote server authentication, integrity, and encryption algorithms to use for IPMIv2.0 lanplus con-nections.  See  table  22-19  in  the  IPMIv2.0  specification.   The  default  is  3  which  specifies RAKP-HMAC-SHA1 authentication, HMAC-SHA1-96 integrity, and AES-CBC-128 encryption algorithms.

So far I could observe a fail ratio of 1% when calling ipmitool to establish connection from grenache-1 to ix64ph1075 meaning that I can not reproduce the original problem yet.

Result from linux-28d7, my notebook over VPN: count_fail_ratio: Run: 10000. Fails: 21. Fail ratio 0%. Some fails being "Error: Unable to establish IPMI v2 / RMCP+ session", "Error: no response from RAKP 3 message". Also sometime "Close Session command failed", not counted as error as it does not influence the exit code. However this causes a delay of 10s.
Result from grenache-1, still running in screen session on grenache-1, I should take a look tomorrow.

EDIT: 2023-05-05: 06:17:08.253007 00:00:00.004818 ## count_fail_ratio: Run: 10000. Fails: 264. Fail ratio 2% so the fail ratio decreased a lot over night. I assume conflicting network load or on the host has an impact.

Running the same experiment again with ipmitool options -R 10 -N 10

the ipmi command begun to work today. I rerun 3 times and all worked. It seems the problem is gone.

Maybe firmware update helps? Logging in over web on http://ix64hm1200.qa.suse.de

Firmware Revision : 03.48 IP address : 010.162.028.200
Firmware Build Time : 2016-01-29 BMC MAC address : 00:25:90:9f:9e:12

but we don't know what machine that is. SoL on boot says https://www.supermicro.com/products/archive/motherboard/x9dri-f . https://www.supermicro.com/en/support/resources/downloadcenter/firmware/MBD-X9DRi-F/BMC says there is a new version 3.62. Downloaded and upgrading over firmware update mode in web BMC interface.

We also reviewed https://github.com/ipmitool/ipmitool/ and in particular https://github.com/ipmitool/ipmitool/releases/tag/IPMITOOL_1_8_19 if there is anything new that might help to improve stability.

However anyway we could update the firmware so that is at least something :)

Firmware Revision : 03.62 IP address : 010.162.028.200
Firmware Build Time : 2020-07-15

Retriggered the ipmitool experiment from grenache-1 where we could immediately observe another occurence of "Close Session command failed" so that did not change in behaviour. Also started again on qamaster.

Also updated my "count_fail_ratio" to calculate floating point precision fail ratios as we are often encountering "below 1%" fail ratios, using bc. See https://github.com/okurz/scripts/commit/6a33126f0107383a5285e5a5ef42ce26adc9ce82

Running the experiment with that again also locally as baseline:

runs=10000 count_fail_ratio unbuffer ipmitool -I lanplus -C 3 -o supermicro -H ix64hm1200.qa.suse.de -U admin -P [masked] mc guid 2>&1 | ts -i '%H:%M:%.S' | ts -s '%H:%M:%.S'

It's already obvious that from linux-28d7, my notebook, I don't get "Close Session command failed" often if at all, but at the same time reproduced often from qamaster and grenache-1, both in same rack. I am sure that ipmitool itself is binary-identical for qamaster and linux-28d7, checked with md5sum $(which ipmitool) yielding "6dd56e24f18a89a0725af5de7f390f89 /usr/bin/ipmitool". I checked loaded libraries with ldd and also checked /usr/lib64/libfreeipmi.so.17

On qamaster the error "Close Session command failed" just stopped:

00:13:14.322024 00:00:00.000090 ## Run 73
00:13:24.442356 00:00:10.027833 Close Session command failed
00:13:24.450918 00:00:00.008681 ## count_fail_ratio: Run: 73. Fails: 0. Fail ratio 0%
00:13:24.450958 00:00:00.000039 ## Run 74
00:13:35.575072 00:00:10.031620 Close Session command failed
00:13:35.583449 00:00:00.008413 ## count_fail_ratio: Run: 74. Fails: 0. Fail ratio 0%
00:13:35.583496 00:00:00.000046 ## Run 75
00:13:46.703624 00:00:10.027679 Close Session command failed
00:13:46.712191 00:00:00.008641 ## count_fail_ratio: Run: 75. Fails: 0. Fail ratio 0%
00:13:46.712229 00:00:00.000038 ## Run 76
00:13:47.816701 00:00:00.009188 ## count_fail_ratio: Run: 76. Fails: 0. Fail ratio 0%
00:13:47.816766 00:00:00.000098 ## Run 77
00:13:57.934171 00:00:10.027014 Close Session command failed
00:13:57.942132 00:00:00.007996 ## count_fail_ratio: Run: 77. Fails: 0. Fail ratio 0%
00:13:57.942198 00:00:00.000075 ## Run 78
00:13:58.035694 00:00:00.008616 ## count_fail_ratio: Run: 78. Fails: 0. Fail ratio 0%
00:13:58.035745 00:00:00.000054 ## Run 79
00:13:58.126907 00:00:00.008116 ## count_fail_ratio: Run: 79. Fails: 0. Fail ratio 0%
00:13:58.126960 00:00:00.000038 ## Run 80
00:13:58.220228 00:00:00.008218 ## count_fail_ratio: Run: 80. Fails: 0. Fail ratio 0%
00:13:58.220281 00:00:00.000085 ## Run 81
00:13:58.313960 00:00:00.008244 ## count_fail_ratio: Run: 81. Fails: 0. Fail ratio 0%
00:13:58.314005 00:00:00.000044 ## Run 82
00:13:58.410096 00:00:00.008803 ## count_fail_ratio: Run: 82. Fails: 0. Fail ratio 0%

interesting to see: All showed the error up to run 75, then 76 w/o, 77 error again, 78ff w/o. And now it just seems to start again with run 1960.

But right now fail ratio on grenache-1 is 41 percent. Let's try to restart the switch in rack 2 where ix64ph1075 is located. After the switch was back up again the connection from grenache-1 looks really good.

The connection from grenache-1 to ix64ph1075 is still very stable using the power status command. Latest experiment showed count_fail_ratio: Run: 30000. Fails: 1. Fail ratio 0%. I am trying to look into the still present failures and if multiple retries to ipmitool can help.

On linux-28d7 from 10k runs 4 fails, i.e. fail ratio 0.04%. And the errors that showed up:

$ grep -v '##' ipmi_mc_guid_poo125450_2023-05-08T13:35:14+02:00.log
00:00:27.799559 00:00:01.165539 > Error: no response from RAKP 3 message
00:00:28.204694 00:00:00.176309 Error: Unable to establish IPMI v2 / RMCP+ session
00:08:50.399711 00:00:00.173545 Error: Unable to establish IPMI v2 / RMCP+ session
00:14:14.862245 00:00:01.166526 > Error: no response from RAKP 3 message
00:14:27.908729 00:00:13.046506 Set Session Privilege Level to ADMINISTRATOR failed
00:14:27.908814 00:00:00.000104 Error: Unable to establish IPMI v2 / RMCP+ session
00:18:35.836568 00:00:10.030031 Close Session command failed
00:27:17.824404 00:00:01.153423 > Error: no response from RAKP 1 message
00:43:09.868358 00:00:01.126254 > Error: no response from RAKP 1 message
00:43:56.470334 00:00:01.184566 Error: Unable to establish IPMI v2 / RMCP+ session
00:45:38.892198 00:00:10.026831 Close Session command failed
00:47:52.052188 00:00:01.143234 > Error: no response from RAKP 3 message
00:48:20.016474 00:00:01.147754 > Error: no response from RAKP 3 message
00:49:05.664527 00:00:10.029110 Close Session command failed
00:49:45.595523 00:00:01.141644 > Error: no response from RAKP 3 message
00:52:05.778055 00:00:01.178423 > Error: no response from RAKP 3 message
00:52:06.806498 00:00:01.028391 > Error: no response from RAKP 1 message
00:52:36.678707 00:00:01.120133 > Error: no response from RAKP 1 message
00:53:22.582800 00:00:01.160691 > Error: no response from RAKP 3 message
00:55:25.867893 00:00:01.448023 > Error: no response from RAKP 3 message
00:57:24.914749 00:00:01.149647 > Error: no response from RAKP 3 message
00:57:39.460361 00:00:10.028691 Close Session command failed
00:58:26.276220 00:00:02.245563 > Error: no response from RAKP 3 message

those are both the fatal as well as non-fatal errors.

Running again on grenache-1 with

runs=30000 count_fail_ratio unbuffer ipmitool -I lanplus -C 3 -H ix64hm1200.qa.suse.de -U admin -P [masked] mc guid 2>&1 | ts -i '%H:%M:%.S' | ts -s '%H:%M:%.S' | grep --line-buffered -v 'GUID.*:' | tee -a /tmp/ipmi_mc_guid_poo125450_$(date -Is).log

The latest experiment on grenache-1 showed a fail rate of 0.00%, all 30k ipmi calls succeeded. I don't see where we can improve the use of ipmitool then. The only thing I could think of is some kind of monitoring or ipmitool check where we would do the above regularly so that misbehaving switches and such would show up as alert.