[1/2] eSEL: Make sure PANIC logs are sent to BMC before calling assert
diff mbox series

Message ID 20200304085807.10699-1-hegdevasant@linux.vnet.ibm.com
State Accepted
Headers show
Series
  • [1/2] eSEL: Make sure PANIC logs are sent to BMC before calling assert
Related show

Checks

Context Check Description
snowpatch_ozlabs/snowpatch_job_snowpatch-skiboot-dco success Signed-off-by present
snowpatch_ozlabs/snowpatch_job_snowpatch-skiboot success Test snowpatch/job/snowpatch-skiboot on branch master
snowpatch_ozlabs/apply_patch success Successfully applied on branch master (82aed17a5468aff6b600ee1694a10a60f942c018)

Commit Message

Vasant Hegde March 4, 2020, 8:58 a.m. UTC
eSEL logs are split into multiple smaller chunks and sent to BMC.
We use ipmi_queue_msg_sync() interface for sending OPAL_ERROR_PANIC
severity events to BMC. But callback handler (ipmi_cmd_done()) clears
'sync_msg' after getting response to first chunk as its not aware that
we have more data to send.

So in assert()/checkstop path we may endup checkstoping system before
error log is sent to BMC completely. We will miss useful error log.

This patch introduces new wait loop in ipmi_elog_commit(). It will wait
until error log is sent to BMC. I think this is safe because even if
something goes wrong (like BMC reset) we will hit timeout and eventually
we will come out of this loop.

Alternatively we can add additional check in ipmi_cmd_done() path. But
I don't wanted to make this path aware of message type.


Signed-off-by: Vasant Hegde <hegdevasant@linux.vnet.ibm.com>
---
 hw/ipmi/ipmi-sel.c | 17 +++++++++++++++--
 1 file changed, 15 insertions(+), 2 deletions(-)

Comments

Klaus Heinrich Kiwi March 5, 2020, 1:23 p.m. UTC | #1
Disclaimer: I'm far from being acquainted with the code (actually first 
time looking into it), but I did spent some time trying to figure it out..

On 3/4/2020 5:58 AM, Vasant Hegde wrote:
> eSEL logs are split into multiple smaller chunks and sent to BMC.
> We use ipmi_queue_msg_sync() interface for sending OPAL_ERROR_PANIC
> severity events to BMC. But callback handler (ipmi_cmd_done()) clears
> 'sync_msg' after getting response to first chunk as its not aware that
> we have more data to send.
> 
> So in assert()/checkstop path we may endup checkstoping system before
> error log is sent to BMC completely. We will miss useful error log.
> 
> This patch introduces new wait loop in ipmi_elog_commit(). It will wait
> until error log is sent to BMC. I think this is safe because even if
> something goes wrong (like BMC reset) we will hit timeout and eventually
> we will come out of this loop.

FWIW, I couldn't find a better way to do this as well

> Alternatively we can add additional check in ipmi_cmd_done() path. But
> I don't wanted to make this path aware of message type.
> 
>   /* OEM SEL fields */
>   #define SEL_OEM_ID_0		0x55
> @@ -434,10 +435,22 @@ int ipmi_elog_commit(struct errorlog *elog_buf)
> 
>   	msg->error = ipmi_elog_error;
>   	msg->req_size = 0;
> -	if (elog_buf->event_severity == OPAL_ERROR_PANIC)
> +	if (elog_buf->event_severity == OPAL_ERROR_PANIC) {
>   		ipmi_queue_msg_sync(msg);
> -	else
> +
> +		/*
> +		 * eSEL logs are split into multiple smaller chunks and sent
> +		 * to BMC. Lets wait until we finish sending all the chunks
> +		 * to BMC.
> +		 */
> +		while (ipmi_sel_panic_msg.busy != false) {
> +			if (msg->backend->poll)
> +				msg->backend->poll();
I think this works for msg-> because PANIC msg are never de-allocated, 
even if ipmi_sel_free_msg(msg) may have raced with the conditionals 
above it.


But is there a chance there could be a race between ipmi_sel_free_msg() 
setting ->busy to false and another caller/thread immediately setting it 
back to true on a new elog_commit()->ipmi_sel_alloc_msg()? That could 
also mean that this new PANIC is still not expired on the ipmi/bt stack 
(i.e., in theory could cause this loop never to finish if there's always 
a new caller with PANIC waiting to be scheduled, so classify that under 
"nitpicking")


> +			time_wait_ms(10);
> +		}
> +	} else {
>   		ipmi_queue_msg(msg);
> +	}
> 
>   	return 0;
>   }
> 

Thanks,

  -Klaus
Vasant Hegde March 9, 2020, 3:39 p.m. UTC | #2
On 3/5/20 6:53 PM, Klaus Heinrich Kiwi wrote:
> Disclaimer: I'm far from being acquainted with the code (actually first time 
> looking into it), but I did spent some time trying to figure it out..
> 
> On 3/4/2020 5:58 AM, Vasant Hegde wrote:
>> eSEL logs are split into multiple smaller chunks and sent to BMC.
>> We use ipmi_queue_msg_sync() interface for sending OPAL_ERROR_PANIC
>> severity events to BMC. But callback handler (ipmi_cmd_done()) clears
>> 'sync_msg' after getting response to first chunk as its not aware that
>> we have more data to send.
>>
>> So in assert()/checkstop path we may endup checkstoping system before
>> error log is sent to BMC completely. We will miss useful error log.
>>
>> This patch introduces new wait loop in ipmi_elog_commit(). It will wait
>> until error log is sent to BMC. I think this is safe because even if
>> something goes wrong (like BMC reset) we will hit timeout and eventually
>> we will come out of this loop.
> 
> FWIW, I couldn't find a better way to do this as well
> 
>> Alternatively we can add additional check in ipmi_cmd_done() path. But
>> I don't wanted to make this path aware of message type.
>>
>>   /* OEM SEL fields */
>>   #define SEL_OEM_ID_0        0x55
>> @@ -434,10 +435,22 @@ int ipmi_elog_commit(struct errorlog *elog_buf)
>>
>>       msg->error = ipmi_elog_error;
>>       msg->req_size = 0;
>> -    if (elog_buf->event_severity == OPAL_ERROR_PANIC)
>> +    if (elog_buf->event_severity == OPAL_ERROR_PANIC) {
>>           ipmi_queue_msg_sync(msg);
>> -    else
>> +
>> +        /*
>> +         * eSEL logs are split into multiple smaller chunks and sent
>> +         * to BMC. Lets wait until we finish sending all the chunks
>> +         * to BMC.
>> +         */
>> +        while (ipmi_sel_panic_msg.busy != false) {
>> +            if (msg->backend->poll)
>> +                msg->backend->poll();
> I think this works for msg-> because PANIC msg are never de-allocated, even if 
> ipmi_sel_free_msg(msg) may have raced with the conditionals above it.

Yes. That's intentional. We want to avoid allocation in panic path. Hence we 
pre-allocate message and use that in PANIC path.

> 
> 
> But is there a chance there could be a race between ipmi_sel_free_msg() setting 
> ->busy to false and another caller/thread immediately setting it back to true on 
> a new elog_commit()->ipmi_sel_alloc_msg()? That could also mean that this new 
> PANIC is still not expired on the ipmi/bt stack (i.e., in theory could cause 
> this loop never to finish if there's always a new caller with PANIC waiting to 
> be scheduled, so classify that under "nitpicking")

Generally one one thread makes reboot2 call. So we are good.


-Vasant
Klaus Heinrich Kiwi March 9, 2020, 7:39 p.m. UTC | #3
On 3/9/2020 12:39 PM, Vasant Hegde wrote:
>> I think this works for msg-> because PANIC msg are never de-allocated, 
>> even if ipmi_sel_free_msg(msg) may have raced with the conditionals 
>> above it.
> 
> Yes. That's intentional. We want to avoid allocation in panic path. 
> Hence we pre-allocate message and use that in PANIC path.
> 
>>
>>
>> But is there a chance there could be a race between 
>> ipmi_sel_free_msg() setting ->busy to false and another caller/thread 
>> immediately setting it back to true on a new 
>> elog_commit()->ipmi_sel_alloc_msg()? That could also mean that this 
>> new PANIC is still not expired on the ipmi/bt stack (i.e., in theory 
>> could cause this loop never to finish if there's always a new caller 
>> with PANIC waiting to be scheduled, so classify that under "nitpicking")
> 
> Generally one one thread makes reboot2 call. So we are good.

Thanks for the clarification.

Reviewed-by: Klaus Heinrich Kiwi <klaus@linux.vnet.ibm.com>

Patch
diff mbox series

diff --git a/hw/ipmi/ipmi-sel.c b/hw/ipmi/ipmi-sel.c
index 29dcebc59..bfce043fc 100644
--- a/hw/ipmi/ipmi-sel.c
+++ b/hw/ipmi/ipmi-sel.c
@@ -18,6 +18,7 @@ 
 #include <opal-msg.h>
 #include <debug_descriptor.h>
 #include <occ.h>
+#include <timebase.h>
 
 /* OEM SEL fields */
 #define SEL_OEM_ID_0		0x55
@@ -434,10 +435,22 @@  int ipmi_elog_commit(struct errorlog *elog_buf)
 
 	msg->error = ipmi_elog_error;
 	msg->req_size = 0;
-	if (elog_buf->event_severity == OPAL_ERROR_PANIC)
+	if (elog_buf->event_severity == OPAL_ERROR_PANIC) {
 		ipmi_queue_msg_sync(msg);
-	else
+
+		/*
+		 * eSEL logs are split into multiple smaller chunks and sent
+		 * to BMC. Lets wait until we finish sending all the chunks
+		 * to BMC.
+		 */
+		while (ipmi_sel_panic_msg.busy != false) {
+			if (msg->backend->poll)
+				msg->backend->poll();
+			time_wait_ms(10);
+		}
+	} else {
 		ipmi_queue_msg(msg);
+	}
 
 	return 0;
 }