Debugging DecodingErrors

[cweickhmann]

Hi! I keep getting DecodingErrors intermittently that crash mmcterm (example below) when connecting on either channels.
I have my doubts that it's a hardware problem, but I'd like to find out more.

What's a good way to debug this?

---

Example exception, while in MMC console via network (mmcterm -c 0 IPADDR 0x76):

pyipmi exception: short SDUException in thread rx:
Traceback (most recent call last):
  File "/home/cweickhm/.local/lib/python3.12/site-packages/mmcterm/mmcterm.py", line 421, in reader
    status, rx_data = self.ipmi.poll_xchg(bytearray(tx_part))
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/cweickhm/.local/lib/python3.12/site-packages/mmcterm/mmcterm.py", line 152, in poll_xchg
    return self.raw_cmd(IpmiCode.SOI_POLL_XCHG, tx_data)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/cweickhm/.local/lib/python3.12/site-packages/mmcterm/mmcterm.py", line 110, in raw_cmd
    raw_reply = self.conn.raw_command(0, 0x30, data)
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/cweickhm/.local/lib/python3.12/site-packages/pyipmi/__init__.py", line 225, in raw_command
    return self.interface.send_and_receive_raw(self.target, lun, netfn,
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/cweickhm/.local/lib/python3.12/site-packages/pyipmi/interfaces/rmcp.py", line 656, in send_and_receive_raw
    return self._send_and_receive(target=target,
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/cweickhm/.local/lib/python3.12/site-packages/pyipmi/interfaces/rmcp.py", line 613, in _send_and_receive
    rx_data = self._receive_ipmi_msg(self.ignore_sdu_length)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/cweickhm/.local/lib/python3.12/site-packages/pyipmi/interfaces/rmcp.py", line 439, in _receive_ipmi_msg
    data = msg.unpack(pdu)
           ^^^^^^^^^^^^^^^
  File "/home/cweickhm/.local/lib/python3.12/site-packages/pyipmi/interfaces/rmcp.py", line 328, in unpack
    raise DecodingError('short SDU')
pyipmi.errors.DecodingError: short SDU

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.12/threading.py", line 1073, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.12/threading.py", line 1010, in run
    self._target(*self._args, **self._kwargs)
  File "/home/cweickhm/.local/lib/python3.12/site-packages/mmcterm/mmcterm.py", line 423, in reader
    self.reader_abort(f'pyipmi exception: {e}')
  File "/home/cweickhm/.local/lib/python3.12/site-packages/mmcterm/mmcterm.py", line 396, in reader_abort
    self.console.cancel()
  File "/home/cweickhm/.local/lib/python3.12/site-packages/mmcterm/mmcterm.py", line 333, in cancel
    fcntl.ioctl(self.fd, termios.TIOCSTI, b'\0')
OSError: [Errno 5] Input/output error

[patrislav1]

Looks like a IPMI protocol error (i.e. message from the MCH could not be decoded on transport level). Which MCH are you using? Try raising the polling interval (-t, default 10ms), sometimes MCHs get overwhelmed when queried too fast.

[cweickhmann]

I'll test with longer poll intervals. So far (50 ms and 100 ms) it does not change much, but maybe time between errors gets longer.
It's a NAT-MCH V2.23.6 (that should be more or less the most current patch level).

[cweickhmann]

I did test with longer intervals and did not observe any change in failure rate.
However, we're polling IPMI for crate health data, so I'll switch this off and test again.

[cweickhmann]

Alright, so switching off IPMI polling did solve the issue with mmcterm crashing on malformed data. Here are two example cases as screencasts:

• IMPI polling enabled (crashes): https://asciinema.org/a/TyTRMMf6Qbrv3kbkKugvnNkmA
• IMPI polling disabled (no more crashes): https://asciinema.org/a/Ne29v1n6QnXy84Sgs3HLExvjH

Looks like the issue is indeed MCH related. As soon as I get my hands on a different model, I'll check if this helps.

[patrislav1]

I don't know what you mean exactly with "IPMI scraping" or "polling for crate health data" but I guess you have a separate process somewhere generating IPMI traffic. I can confirm that errors during mmcterm usage happen more often when 1) the mmcterm polling interval (-t option) is faster and 2) when there's other processes or devices generating IPMI traffic to the same MCH in parallel.
I have the impression that the NAT MCH's IPMI stack is not very robust and can easily get overwhelmed with traffic, even when we set the mmcterm polling interval to slower values (e.g. 250 or 500 ms).
I have not seen the error that you are reporting however, you are seeing a IPMI protocol error, I tend to rather see IPMI timeout errors. But this may be down to the particular MCH version. Probably different MCH versions have different bugs 🙃

[patrislav1]

There's two issues at the heart of the problem here,

1. the MicroTCA IPMI standard doesn't support events generated on the AMC side (other than hotplug and status events), so we are forced to poll the AMC in request/response style for serial console data.
2. the NAT MCH doesn't seem to have a robust IPMI stack and gets overwhelmed when IPMI requests are incoming faster than it can handle them.

We have no control over either of these points, and we can only mitigate 2) somewhat by slowing down the polling (mmcterm -t option) at the cost of higher latency / worse user experience.

[patrislav1]

You can also check different options for packet size (-m), e.g. -m 100.
See also: https://github.com/MicroTCA-Tech-Lab/mmcterm?tab=readme-ov-file#max-packet-size

Setting higher packet sizes could potentially reduce the number of IPMI requests/responses in total, especially when combined with slower polling interval (-t).