diff mbox

ipmi: Log exact NetFn value in OPAL logs

Message ID 1456519406-10087-1-git-send-email-vipin@linux.vnet.ibm.com
State Accepted
Headers show

Commit Message

Vipin K Parashar Feb. 26, 2016, 8:43 p.m. UTC 
As per IPMI message format NetFn value in present in first 6 bits
while last 2 bits contain LUN value. This needs to be taken care
while printing NetFn value in OPAL logs which is useful while debugging
fails.

[root@fir01 /]# ipmitool raw 0x0a 0x48
 47 b1 d0 56
[root@fir01 /]#

From OPAL Logs
---------------
[133969609199,7] BT: seq 0x3d netfn 0x0a cmd 0x48: Message sent to host
[133975465455,7] BT: seq 0x3d netfn 0x0a cmd 0x48: IPMI MSG done

From BMC Logs
--------------
IPMIMain: [693 WARNING][corecmdselect.c:913]
 Request: Channel:f; Netfn:a; Cmd:48;
IPMIMain: [693 INFO][corecmdselect.c:924]
 Response: Channel:f; Netfn:a; Cmd:48; Data:0 47 b1 d0 56

Signed-off-by: Vipin K Parashar <vipin@linux.vnet.ibm.com>
---
 core/ipmi.c | 2 +-
 hw/bt.c     | 5 +++--
 2 files changed, 4 insertions(+), 3 deletions(-)

Comments

Cyril Bur Feb. 29, 2016, 12:52 a.m. UTC | #1 
On Sat, 27 Feb 2016 02:13:26 +0530
Vipin K Parashar <vipin@linux.vnet.ibm.com> wrote:

Hi Vipin,

> As per IPMI message format NetFn value in present in first 6 bits
> while last 2 bits contain LUN value. This needs to be taken care
> while printing NetFn value in OPAL logs which is useful while debugging
> fails.
> 

At the moment it is confusing that the netfn/lun byte is printed as the netfn,
good idea.

> [root@fir01 /]# ipmitool raw 0x0a 0x48
>  47 b1 d0 56
> [root@fir01 /]#
> 
> From OPAL Logs
> ---------------
> [133969609199,7] BT: seq 0x3d netfn 0x0a cmd 0x48: Message sent to host
> [133975465455,7] BT: seq 0x3d netfn 0x0a cmd 0x48: IPMI MSG done
> 
> From BMC Logs
> --------------
> IPMIMain: [693 WARNING][corecmdselect.c:913]
>  Request: Channel:f; Netfn:a; Cmd:48;
> IPMIMain: [693 INFO][corecmdselect.c:924]
>  Response: Channel:f; Netfn:a; Cmd:48; Data:0 47 b1 d0 56
> 
> Signed-off-by: Vipin K Parashar <vipin@linux.vnet.ibm.com>
> ---
>  core/ipmi.c | 2 +-
>  hw/bt.c     | 5 +++--
>  2 files changed, 4 insertions(+), 3 deletions(-)
> 
> diff --git a/core/ipmi.c b/core/ipmi.c
> index 60e9640..6fdb9a7 100644
> --- a/core/ipmi.c
> +++ b/core/ipmi.c
> @@ -141,7 +141,7 @@ void ipmi_cmd_done(uint8_t cmd, uint8_t netfn, uint8_t cc, struct ipmi_msg *msg)
>  	}
>  
>  	if ((msg->netfn >> 2) + 1 != (netfn >> 2)) {
> -		prerror("IPMI: Incorrect netfn 0x%02x in response\n", netfn);
> +		prerror("IPMI: Incorrect netfn 0x%02x in response\n", netfn >> 2);
>  		cc = IPMI_ERR_UNSPECIFIED;

This change makes sense as the error reported is the failure of the condition
which is looking at strictly the netfn.

>  	}
>  	msg->netfn = netfn;
> diff --git a/hw/bt.c b/hw/bt.c
> index 3325f69..ca8bd1e 100644
> --- a/hw/bt.c
> +++ b/hw/bt.c
> @@ -15,6 +15,7 @@
>   */
>  
>  #define pr_fmt(fmt) "BT: " fmt
> +
>  #include <skiboot.h>
>  #include <lpc.h>
>  #include <lock.h>
> @@ -80,7 +81,7 @@
>  #define _BT_Q_LOG(level, msg, fmt, args...) \
>  	do { if (msg) \
>  			prlog(level, "seq 0x%02x netfn 0x%02x cmd 0x%02x: " fmt "\n", \
> -			(msg)->seq, (msg)->ipmi_msg.netfn, (msg)->ipmi_msg.cmd, ##args); \
> +			(msg)->seq, ((msg)->ipmi_msg.netfn >> 2), (msg)->ipmi_msg.cmd, ##args); \
>  		else \
>  			prlog(level, "seq 0x?? netfn 0x?? cmd 0x??: " fmt "\n", ##args); \
>  	} while(0)
> @@ -346,7 +347,7 @@ static void bt_get_resp(void)
>  	if (!bt_msg) {
>  		/* A response to a message we no longer care about. */
>  		prlog(PR_INFO, "Nobody cared about a response to an BT/IPMI message"
> -		       "(seq 0x%02x netfn 0x%02x cmd 0x%02x)\n", seq, netfn, cmd);
> +		       "(seq 0x%02x netfn 0x%02x cmd 0x%02x)\n", seq, (netfn >> 2), cmd);
>  		bt_flush_msg();
>  		return;

These two hunks are debug prints which actually show all the bytes that aren't
data bytes. Perhaps renaming the label to 'netfn/lun' makes more sense here as
it keeps more information for debugging (I'm assuming that someone debugging
will know how the netfn/lun is put in one byte obviously...).


Thanks,

Cyril
>  	}
Vipin K Parashar Feb. 29, 2016, 10:54 a.m. UTC | #2 
Hi Cyril,
            Thanks!! for review.  One observation as below:

On Monday 29 February 2016 06:22 AM, Cyril Bur wrote:
> On Sat, 27 Feb 2016 02:13:26 +0530
> Vipin K Parashar <vipin@linux.vnet.ibm.com> wrote:
>
> Hi Vipin,
>
>> As per IPMI message format NetFn value in present in first 6 bits
>> while last 2 bits contain LUN value. This needs to be taken care
>> while printing NetFn value in OPAL logs which is useful while debugging
>> fails.
>>
> At the moment it is confusing that the netfn/lun byte is printed as the netfn,
> good idea.
>
>> [root@fir01 /]# ipmitool raw 0x0a 0x48
>>   47 b1 d0 56
>> [root@fir01 /]#
>>
>>  From OPAL Logs
>> ---------------
>> [133969609199,7] BT: seq 0x3d netfn 0x0a cmd 0x48: Message sent to host
>> [133975465455,7] BT: seq 0x3d netfn 0x0a cmd 0x48: IPMI MSG done
>>
>>  From BMC Logs
>> --------------
>> IPMIMain: [693 WARNING][corecmdselect.c:913]
>>   Request: Channel:f; Netfn:a; Cmd:48;
>> IPMIMain: [693 INFO][corecmdselect.c:924]
>>   Response: Channel:f; Netfn:a; Cmd:48; Data:0 47 b1 d0 56
>>
>> Signed-off-by: Vipin K Parashar <vipin@linux.vnet.ibm.com>
>> ---
>>   core/ipmi.c | 2 +-
>>   hw/bt.c     | 5 +++--
>>   2 files changed, 4 insertions(+), 3 deletions(-)
>>
>> diff --git a/core/ipmi.c b/core/ipmi.c
>> index 60e9640..6fdb9a7 100644
>> --- a/core/ipmi.c
>> +++ b/core/ipmi.c
>> @@ -141,7 +141,7 @@ void ipmi_cmd_done(uint8_t cmd, uint8_t netfn, uint8_t cc, struct ipmi_msg *msg)
>>   	}
>>   
>>   	if ((msg->netfn >> 2) + 1 != (netfn >> 2)) {
>> -		prerror("IPMI: Incorrect netfn 0x%02x in response\n", netfn);
>> +		prerror("IPMI: Incorrect netfn 0x%02x in response\n", netfn >> 2);
>>   		cc = IPMI_ERR_UNSPECIFIED;
> This change makes sense as the error reported is the failure of the condition
> which is looking at strictly the netfn.
>
>>   	}
>>   	msg->netfn = netfn;
>> diff --git a/hw/bt.c b/hw/bt.c
>> index 3325f69..ca8bd1e 100644
>> --- a/hw/bt.c
>> +++ b/hw/bt.c
>> @@ -15,6 +15,7 @@
>>    */
>>   
>>   #define pr_fmt(fmt) "BT: " fmt
>> +
>>   #include <skiboot.h>
>>   #include <lpc.h>
>>   #include <lock.h>
>> @@ -80,7 +81,7 @@
>>   #define _BT_Q_LOG(level, msg, fmt, args...) \
>>   	do { if (msg) \
>>   			prlog(level, "seq 0x%02x netfn 0x%02x cmd 0x%02x: " fmt "\n", \
>> -			(msg)->seq, (msg)->ipmi_msg.netfn, (msg)->ipmi_msg.cmd, ##args); \
>> +			(msg)->seq, ((msg)->ipmi_msg.netfn >> 2), (msg)->ipmi_msg.cmd, ##args); \
>>   		else \
>>   			prlog(level, "seq 0x?? netfn 0x?? cmd 0x??: " fmt "\n", ##args); \
>>   	} while(0)
>> @@ -346,7 +347,7 @@ static void bt_get_resp(void)
>>   	if (!bt_msg) {
>>   		/* A response to a message we no longer care about. */
>>   		prlog(PR_INFO, "Nobody cared about a response to an BT/IPMI message"
>> -		       "(seq 0x%02x netfn 0x%02x cmd 0x%02x)\n", seq, netfn, cmd);
>> +		       "(seq 0x%02x netfn 0x%02x cmd 0x%02x)\n", seq, (netfn >> 2), cmd);
>>   		bt_flush_msg();
>>   		return;
> These two hunks are debug prints which actually show all the bytes that aren't
> data bytes. Perhaps renaming the label to 'netfn/lun' makes more sense here as
> it keeps more information for debugging (I'm assuming that someone debugging
> will know how the netfn/lun is put in one byte obviously...).

hmm, actually LUN is always 0 in OPAL and exact netfn value is more sought
after. ipmitool raw command and BMC traces also use/print exact netfn value
So printing exact netfn value with BT_Q_LOG/ DBG / INFO label takes it more
closer to what we see see with BMC traces and can directly use with 
ipmitool
raw command. It also enables any netfn based grep to run unmodified on OPAL
logs and BMC traces while debugging fails.
    Though its always helpful to print out more info like response data 
obtained,
netfn/lun value with PR_DEBUG option in OPAL logs, but in my opinion 
printing
exact netfn might of immediate use as if now.

>
> Thanks,
>
> Cyril
>>   	}
Cyril Bur March 7, 2016, 3:33 a.m. UTC | #3 
On Mon, 29 Feb 2016 16:24:46 +0530
Vipin K Parashar <vipin@linux.vnet.ibm.com> wrote:

> Hi Cyril,
>             Thanks!! for review.  One observation as below:
> 
> On Monday 29 February 2016 06:22 AM, Cyril Bur wrote:
> > On Sat, 27 Feb 2016 02:13:26 +0530
> > Vipin K Parashar <vipin@linux.vnet.ibm.com> wrote:
> >
> > Hi Vipin,
> >  
> >> As per IPMI message format NetFn value in present in first 6 bits
> >> while last 2 bits contain LUN value. This needs to be taken care
> >> while printing NetFn value in OPAL logs which is useful while debugging
> >> fails.
> >>  
> > At the moment it is confusing that the netfn/lun byte is printed as the netfn,
> > good idea.
> >  
> >> [root@fir01 /]# ipmitool raw 0x0a 0x48
> >>   47 b1 d0 56
> >> [root@fir01 /]#
> >>
> >>  From OPAL Logs
> >> ---------------
> >> [133969609199,7] BT: seq 0x3d netfn 0x0a cmd 0x48: Message sent to host
> >> [133975465455,7] BT: seq 0x3d netfn 0x0a cmd 0x48: IPMI MSG done
> >>
> >>  From BMC Logs
> >> --------------
> >> IPMIMain: [693 WARNING][corecmdselect.c:913]
> >>   Request: Channel:f; Netfn:a; Cmd:48;
> >> IPMIMain: [693 INFO][corecmdselect.c:924]
> >>   Response: Channel:f; Netfn:a; Cmd:48; Data:0 47 b1 d0 56
> >>
> >> Signed-off-by: Vipin K Parashar <vipin@linux.vnet.ibm.com>
> >> ---
> >>   core/ipmi.c | 2 +-
> >>   hw/bt.c     | 5 +++--
> >>   2 files changed, 4 insertions(+), 3 deletions(-)
> >>
> >> diff --git a/core/ipmi.c b/core/ipmi.c
> >> index 60e9640..6fdb9a7 100644
> >> --- a/core/ipmi.c
> >> +++ b/core/ipmi.c
> >> @@ -141,7 +141,7 @@ void ipmi_cmd_done(uint8_t cmd, uint8_t netfn, uint8_t cc, struct ipmi_msg *msg)
> >>   	}
> >>   
> >>   	if ((msg->netfn >> 2) + 1 != (netfn >> 2)) {
> >> -		prerror("IPMI: Incorrect netfn 0x%02x in response\n", netfn);
> >> +		prerror("IPMI: Incorrect netfn 0x%02x in response\n", netfn >> 2);
> >>   		cc = IPMI_ERR_UNSPECIFIED;  
> > This change makes sense as the error reported is the failure of the condition
> > which is looking at strictly the netfn.
> >  
> >>   	}
> >>   	msg->netfn = netfn;
> >> diff --git a/hw/bt.c b/hw/bt.c
> >> index 3325f69..ca8bd1e 100644
> >> --- a/hw/bt.c
> >> +++ b/hw/bt.c
> >> @@ -15,6 +15,7 @@
> >>    */
> >>   
> >>   #define pr_fmt(fmt) "BT: " fmt
> >> +
> >>   #include <skiboot.h>
> >>   #include <lpc.h>
> >>   #include <lock.h>
> >> @@ -80,7 +81,7 @@
> >>   #define _BT_Q_LOG(level, msg, fmt, args...) \
> >>   	do { if (msg) \
> >>   			prlog(level, "seq 0x%02x netfn 0x%02x cmd 0x%02x: " fmt "\n", \
> >> -			(msg)->seq, (msg)->ipmi_msg.netfn, (msg)->ipmi_msg.cmd, ##args); \
> >> +			(msg)->seq, ((msg)->ipmi_msg.netfn >> 2), (msg)->ipmi_msg.cmd, ##args); \
> >>   		else \
> >>   			prlog(level, "seq 0x?? netfn 0x?? cmd 0x??: " fmt "\n", ##args); \
> >>   	} while(0)
> >> @@ -346,7 +347,7 @@ static void bt_get_resp(void)
> >>   	if (!bt_msg) {
> >>   		/* A response to a message we no longer care about. */
> >>   		prlog(PR_INFO, "Nobody cared about a response to an BT/IPMI message"
> >> -		       "(seq 0x%02x netfn 0x%02x cmd 0x%02x)\n", seq, netfn, cmd);
> >> +		       "(seq 0x%02x netfn 0x%02x cmd 0x%02x)\n", seq, (netfn >> 2), cmd);
> >>   		bt_flush_msg();
> >>   		return;  
> > These two hunks are debug prints which actually show all the bytes that aren't
> > data bytes. Perhaps renaming the label to 'netfn/lun' makes more sense here as
> > it keeps more information for debugging (I'm assuming that someone debugging
> > will know how the netfn/lun is put in one byte obviously...).  
> 
> hmm, actually LUN is always 0 in OPAL and exact netfn value is more sought
> after. ipmitool raw command and BMC traces also use/print exact netfn value
> So printing exact netfn value with BT_Q_LOG/ DBG / INFO label takes it more
> closer to what we see see with BMC traces and can directly use with 
> ipmitool
> raw command. It also enables any netfn based grep to run unmodified on OPAL
> logs and BMC traces while debugging fails.
>     Though its always helpful to print out more info like response data 
> obtained,
> netfn/lun value with PR_DEBUG option in OPAL logs, but in my opinion 
> printing
> exact netfn might of immediate use as if now.

Sure...

Reviewed-by: Cyril Bur <cyrilbur@gmail.com>

> 
> >
> > Thanks,
> >
> > Cyril  
> >>   	}  
>
Stewart Smith March 7, 2016, 3:39 a.m. UTC | #4 
Vipin K Parashar <vipin@linux.vnet.ibm.com> writes:
> As per IPMI message format NetFn value in present in first 6 bits
> while last 2 bits contain LUN value. This needs to be taken care
> while printing NetFn value in OPAL logs which is useful while debugging
> fails.
>
> [root@fir01 /]# ipmitool raw 0x0a 0x48
>  47 b1 d0 56
> [root@fir01 /]#
>
> From OPAL Logs
> ---------------
> [133969609199,7] BT: seq 0x3d netfn 0x0a cmd 0x48: Message sent to host
> [133975465455,7] BT: seq 0x3d netfn 0x0a cmd 0x48: IPMI MSG done
>
> From BMC Logs
> --------------
> IPMIMain: [693 WARNING][corecmdselect.c:913]
>  Request: Channel:f; Netfn:a; Cmd:48;
> IPMIMain: [693 INFO][corecmdselect.c:924]
>  Response: Channel:f; Netfn:a; Cmd:48; Data:0 47 b1 d0 56
>
> Signed-off-by: Vipin K Parashar <vipin@linux.vnet.ibm.com>
> ---
>  core/ipmi.c | 2 +-
>  hw/bt.c     | 5 +++--
>  2 files changed, 4 insertions(+), 3 deletions(-)
>

Thanks, merged to master as of 361000f
diff mbox

Patch

diff --git a/core/ipmi.c b/core/ipmi.c
index 60e9640..6fdb9a7 100644
--- a/core/ipmi.c
+++ b/core/ipmi.c
@@ -141,7 +141,7 @@  void ipmi_cmd_done(uint8_t cmd, uint8_t netfn, uint8_t cc, struct ipmi_msg *msg)
 	}
 
 	if ((msg->netfn >> 2) + 1 != (netfn >> 2)) {
-		prerror("IPMI: Incorrect netfn 0x%02x in response\n", netfn);
+		prerror("IPMI: Incorrect netfn 0x%02x in response\n", netfn >> 2);
 		cc = IPMI_ERR_UNSPECIFIED;
 	}
 	msg->netfn = netfn;
diff --git a/hw/bt.c b/hw/bt.c
index 3325f69..ca8bd1e 100644
--- a/hw/bt.c
+++ b/hw/bt.c
@@ -15,6 +15,7 @@ 
  */
 
 #define pr_fmt(fmt) "BT: " fmt
+
 #include <skiboot.h>
 #include <lpc.h>
 #include <lock.h>
@@ -80,7 +81,7 @@ 
 #define _BT_Q_LOG(level, msg, fmt, args...) \
 	do { if (msg) \
 			prlog(level, "seq 0x%02x netfn 0x%02x cmd 0x%02x: " fmt "\n", \
-			(msg)->seq, (msg)->ipmi_msg.netfn, (msg)->ipmi_msg.cmd, ##args); \
+			(msg)->seq, ((msg)->ipmi_msg.netfn >> 2), (msg)->ipmi_msg.cmd, ##args); \
 		else \
 			prlog(level, "seq 0x?? netfn 0x?? cmd 0x??: " fmt "\n", ##args); \
 	} while(0)
@@ -346,7 +347,7 @@  static void bt_get_resp(void)
 	if (!bt_msg) {
 		/* A response to a message we no longer care about. */
 		prlog(PR_INFO, "Nobody cared about a response to an BT/IPMI message"
-		       "(seq 0x%02x netfn 0x%02x cmd 0x%02x)\n", seq, netfn, cmd);
+		       "(seq 0x%02x netfn 0x%02x cmd 0x%02x)\n", seq, (netfn >> 2), cmd);
 		bt_flush_msg();
 		return;
 	}