Re: [RFC] IPMI state machine regression

[Corey Minyard <minyard@acm.org>]

On 08/23/2018 11:52 AM, Andrew Banman wrote:
>
>> I don't have any real hardware with a BT interface, just the one in qemu,
>> but I've never seen it there.
>>
>> It actually looks like the state machine is working ok.  But the BMC is
>> responding to a "Get Device ID" command with:
>>
>>     Recv::  1c 08 d5
> That completion code is spoofed in after bt_start_transaction when bt->state
> is in WR_CONSUME. This is pretty visible from the message trace, but here
> is another with an explicit debug printk (below).
>
> Maybe I'm totally reading this wrong, but I think that err gets passed
> on to the upper layer:
>
> 	start_transaction: return 0xD5 -> return_hosed_msg -> deliver_recv_msg
> 		-> ipmi_smi_msg_received

Ah, yes, you are right.  I didn't write the BT state machine, so I'm not 
terribly
familiar with how it works.  I'm pretty sure the author is no longer 
with HP.

>
> [  120.367379] BT: IDLE [ ] TO=5000000 - 0
> [  120.367384] BT: CAP_BEGIN [ ] TO=5000000 - 0
> [  120.376634] **Timer: 1534434704.376633453
> [  120.376646] BT: XACTION [ ] TO=5000000 - 92000
> [  120.376683] BT: WR_BYTES [ ] TO=4908000 - 0
> [  120.376995] BT: WR_CONSUME [ H2B ] TO=4908000 - 0
> [  120.377025] Send:  18 08
> [  120.377027] **Enqueue: 1534434704.377028726
> [  120.377028] **Start2: 1534434704.377029859

So what appears to be happening is that the BT state machine sends the
BT capabilities commands to the BMC.  While this is going on the upper
layer sends a messages, but the state machine can't send because it's
in the middle of another operation.

The "device" in qemu is almost instantaneous, so you would never
see it there.

So this is almost certainly due to the timing and messaging changes.
in the upper layer.  Another step may be necessary in initialization
to allow this to happen.

Let me poke at this a bit and I'll send another patch.

Thanks,

-corey

> # Added DBG # [  120.377028] bt_start_transaction returned IPMI_NOT_IN_MY_STATE_ERR 0xd5
> # Added DBG # [  120.377030]  18
> # Added DBG # [  120.377030]  08
> # Added DBG # [  120.377030]
> [  120.377061] BT: WR_CONSUME [ ] TO=4908000 - 0
> [  120.377137] BT: RD_WAIT [ ] TO=4908000 - 0
> [  120.377140] Recv::  1c 08 d5
> [  120.377156] Send:  18 01
> [  120.377161] **Enqueue: 1534434704.377161047
> [  120.377164] **Start2: 1534434704.377164751
> # Added DBG # [  120.377165] bt_start_transaction returned IPMI_NOT_IN_MY_STATE_ERR 0xd5
> # Added DBG # [  120.377166]  18
> # Added DBG # [  120.377167]  01
> # Added DBG # [  120.377168]
> [  120.377226] BT: RD_WAIT [ ] TO=4908000 - 0
> [  120.377237] Recv::  1c 01 d5
> [  120.377242] ipmi_si IPI0001:00: IPMI message handler: device id demangle failed: -22
> [  120.377252] ipmi_si IPI0001:00: Unable to get the device id: -5
> [  120.377252] ipmi_si IPI0001:00: Unable to register device: error -5
>
>