search

ibm-openbmc / openbmc

https://github.com
Other
19 stars 51 forks source link

SBE dump parse fail #279

Closed lili-lilili closed 1 year ago

lili-lilili commented 1 year ago

I tried to parse SBE trace from sbe dump, but encountered some problems. Some error report here: https://github.com/open-power/sbe/blob/c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbe-debug.py#L178 Is the tool version on github consistent with the one you @skumar8j

Here is the log: li@Ubuntu-li:~/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug$ ./sbe-debug.py -l trace -t FILE -r System_Dump_Entry_SBE_30000004 -f plat_dump/30000004.0_0_SbeData_p10_p10_pibmem_dump

Symbol File: [/home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbe_DD1.syms] Parsing the Dump header Missing section indicator is 0x0 BMC System: 1 Running command [hexdump -v -e '1/8 "%016x"' -e '"\n"' plat_dump/30000004.0_0_SbeData_p10_p10_pibmem_dump| xxd -r -p > output_file] hexdump: x: bad byte count Running command [cp output_file plat_dump/30000004.0_0_SbeData_p10_p10_pibmem_dump]

Trace buffer symbol addr: [fffd2e80] Trace Buffer Length: [00000838]

String File: [/home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbeStringFile_DD1] Running command [/home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/ppe2fsp /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/DumpPIBMEM /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbetrace.bin ] Failed converting ppe trace to fsp trace. rc = 6 PPE trace buffer must be version 2. ERROR running command: 1536

fsp-trace: [/home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/fsp-trace] Running command [/home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/fsp-trace -s /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbeStringFile_DD1 /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbetrace.bin > /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbe_0_0_tracMERG] fsp-trace.c is_smartDump [503]: read 40 bytes of /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbetrace.bin = 0, 19: No such device fsp-trace.c parse_opt: file /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbetrace.bin: not an fsp-trace file (Incorrect Version?) adal_parse.c trace_adal_read_stringfile: stringfile magic cookie not found or corrupted. fsp-trace.c read_stringfiles: cannot read stringfile '/home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbeStringFile_DD1' ERROR running command: 512 Running command [mv /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/DumpPIBMEM /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/dumpPibMem_trace]

lili-lilili commented 1 year ago

Here for more information https://github.com/ibm-openbmc/openbmc/issues/263

skumar8j commented 1 year ago

Failed converting ppe trace to fsp trace. rc = 6 PPE trace buffer must be version 2. ERROR running command: 1536

Can you check the progress code of SBE. before parsing the dump. Whether it is measurement, verification or runtime.

You can dump the messaging register and look for the progress code. Based on the progress code, you can use -i option in sbe sbe-debug.py.

eg. sbe-debug.py -t FILE -l trace -f -I <SBE / VSBE / MSBE> or you can use the forced-trace option instead of trace

lili-lilili commented 1 year ago

The sbe is running measurement rom. I think there is some error in the sbe-debug.py.

The result without modify the sbe-debug.py tool:

$ ./sbe-debug.py -i MSBE -t FILE -l forced-trace -r System_Dump_Entry_SBE_30000001 -f plat_dump/30000001.0_0_SbeData_p10_p10_pibmem_dump 

 Symbol File: [/home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbe_measurement_seeprom.syms]
Parsing the Dump header
Missing section indicator is 0x0
BMC System: 1
Running command [hexdump -v -e '1/8 "%016x"' -e '"\n"' plat_dump/30000001.0_0_SbeData_p10_p10_pibmem_dump| xxd -r -p > output_file]
hexdump: x: bad byte count
Running command [cp output_file plat_dump/30000001.0_0_SbeData_p10_p10_pibmem_dump]

 String File: [/home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbeMeasurementStringFile]

 Forced Trace, Pibmem Offset: [0x00] Pibmem Length: [0x7D400]
Traceback (most recent call last):
  File "./sbe-debug.py", line 874, in <module>
    main( sys.argv )
  File "./sbe-debug.py", line 841, in main
    forcedCollectTrace(sbe_string_file,sbe_tracMERG_file)
  File "./sbe-debug.py", line 225, in forcedCollectTrace
    data_read = data_read[1:]+[ord(byte)]
TypeError: ord() expected a character, but string of length 0 found

Then i modify the sbe-debug.py, and it can prase the trace with the forced-trace option.

li@Ubuntu-li:~/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug$ ./sbe-debug-m.py -i MSBE -t FILE -l forced-trace -r System_Dump_Entry_SBE_30000001 -f plat_dump/30000001.0_0_SbeData_p10_p10_pibmem_dump 

 Symbol File: [/home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbe_measurement_seeprom.syms]
Parsing the Dump header
Missing section indicator is 0x0
BMC System: 1
Running command [cp plat_dump/30000001.0_0_SbeData_p10_p10_pibmem_dumprw plat_dump/30000001.0_0_SbeData_p10_p10_pibmem_dump]

 String File: [/home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbeMeasurementStringFile]

 Forced Trace, Pibmem Offset: [0x00] Pibmem Length: [0x7D400]
Running command [/home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/ppe2fsp /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/DumpPIBMEM /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbetrace.bin ]

 fsp-trace: [/home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/fsp-trace]
Running command [/home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/fsp-trace -s /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbeMeasurementStringFile /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbetrace.bin > /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbe_measurement_seeprom_0_tracMERG]
Running command [mv /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/DumpPIBMEM /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/dumpPibMem_trace]
$ cat sbe_measurement_seeprom_0_tracMERG 
-------------------------------------------------------------------------------
TRACEBUFFER: Mixed buffer
-------------------------------------------------------------------------------
 Sec    Usec      PID Comp             Line Entry Data
-------------------------------------------------------------------------------
3133643895.637280252|    0|SBE_TRACE       |412360464|I>Scanning PAU DPLL on DD2
3133643895.637289333|    0|SBE_TRACE       |412326384|I>Measurement_main HW Path of setting PAU DPLL
3133643895.637291211|    0|SBE_TRACE       |412290416|I>CBS_ENVSTAT_REG value is 0x3C000020 00000000
3133643895.637292252|    0|SBE_TRACE       |412270240|I>SCRTATCH_REG 8 is 0xFEC80000 00000000
3133643895.637293325|    0|SBE_TRACE       |412327632|I>SCRATCH_REG 6 is 0x00000080 00000000
3133643895.637294081|    0|SBE_TRACE       |412264128|I>SBE Role is Master
3133643895.637294772|    0|SBE_TRACE       |412243792|I>Measurement_main SBE Role is 0
00000000.000003536|    0|SBE_TRACE       |412284736|I>Measurement_main Completed PK init for Measurement Image with Freq [0x1D535300]
00000000.000004284|    0|SBE_TRACE       |412342992|I>Measurement_main LFR clock divider and round trip delay = [0x0030 0x01]
00000000.000005032|    0|SBE_TRACE       |412296688|I>Measurement_main TPM SPI Clock divider and round trip delay and Frequency = [0x000A 0x07 0x16]
00000000.000076430|    0|SBE_TRACE       |412220288|I>sbemSecureBoot_thread thread initilised
00000000.000079276|    0|SBE_TRACE       |412445792|I> performTPMSequences Perform TPM sequence to Read Vendor and DeviceID
00000000.000080146|    0|SBE_TRACE       |412253776|I> Read TPM_DID_VID_0 (Vendor and device ID offset xF00)

Here is the modify:

$ diff -arupN sbe-debug.py sbe-debug-m.py 
--- sbe-debug.py    2022-11-24 21:02:24.000000000 +0800
+++ sbe-debug-m.py  2023-04-12 14:39:28.178430985 +0800
@@ -175,12 +175,40 @@ def collectTrace(string_file,tracMERG_fi
         if(endianChar == "<"):
             #Convert the complete pibmem dump from Little Endian to Big endian, and
             #lets use same tools as used for denali pibmem dumps.
-            invokeOsCmd("hexdump -v -e \'1/8 \"%016x\"\' -e \'\"\\n\"\' " + file_path + "| xxd -r -p > output_file")
-            invokeOsCmd("cp output_file " + file_path)
+            #invokeOsCmd("hexdump -v -e \'1/8 \"%016x\"\' -e \'\"\\n\"\' " + file_path + "| xxd -r -p > output_file")
+            #invokeOsCmd("cp output_file " + file_path)
+            with open(file_path+"rw", "w") as fw:
+                with open(file_path, "r") as fr:
+                    fr.seek(0, os.SEEK_END)
+                    count = fr.tell()
+                    idx = 0
+                    while idx < count:
+                        if idx + 8 > count:
+                            c = count - idx
+                        else:
+                            c = 8
+                        i = 0
+                        while i < c:
+                            fr.seek(idx+c-i-1)
+                            d=fr.read(1)
+                            fw.write(d)
+                            i += 1
+                        idx += 8
+                        #fw.write('\n')
+                    fr.close()
+                fw.close()
+            #invokeOsCmd("cat " + file_path+"rw | xxd -r -p > output_file")
+            invokeOsCmd("cp " + file_path+"rw " + file_path)

     getSymbolVal('g_pk_trace_buf' )
     stringFile = getFilePath(string_file)
     print("\n String File: [" + stringFile + "]")
+
+    if(target == 'FILE'):
+        createPibmemDumpFile( offset, length );
+    else:
+        createPibmemDump( offset, length )
+        
     invokeOsCmd( getFilePath("ppe2fsp")+ " " + output_path + "DumpPIBMEM "+\
             output_path +"sbetrace.bin " )
     invokeOsCmd( getTraceFilePath() + " -s " + stringFile + " "+ output_path +"sbetrace.bin > "+\
@@ -195,8 +223,30 @@ def forcedCollectTrace(string_file,tracM
         if(endianChar == "<"):
             #Convert the complete pibmem dump from Little Endian to Big endian, and
             #lets use same tools as used for denali pibmem dumps.
-            invokeOsCmd("hexdump -v -e \'1/8 \"%016x\"\' -e \'\"\\n\"\' " + file_path + "| xxd -r -p > output_file")
-            invokeOsCmd("cp output_file " + file_path)
+            #invokeOsCmd("hexdump -v -e \'1/8 \"%016x\"\' -e \'\"\\n\"\' " + file_path + "| xxd -r -p > output_file")
+            #invokeOsCmd("cp output_file " + file_path)
+            with open(file_path+"rw", "w") as fw:
+                with open(file_path, "r") as fr:
+                    fr.seek(0, os.SEEK_END)
+                    count = fr.tell()
+                    idx = 0
+                    while idx < count:
+                        if idx + 8 > count:
+                            c = count - idx
+                        else:
+                            c = 8
+                        i = 0
+                        while i < c:
+                            fr.seek(idx+c-i-1)
+                            d=fr.read(1)
+                            fw.write(d)
+                            i += 1
+                        idx += 8
+                        #fw.write('\n')
+                    fr.close()
+                fw.close()
+            #invokeOsCmd("cat " + file_path+"rw | xxd -r -p > output_file")
+            invokeOsCmd("cp " + file_path+"rw " + file_path)

     stringFile = getFilePath(string_file)
     print("\n String File: [" + stringFile + "]")
lili-lilili commented 1 year ago

@skumar8j
Please help confirm if the tool in the open source community is a working version? https://github.com/open-power/sbe/blob/release-fw1030/src/tools/debug/sbe-debug.py

skumar8j commented 1 year ago

I do not see any difference in the file which is in open source community.

I see you have tried with -l forced-trace with -i option. Have you tried? If you are sure of the progress code, always use trace option. forced-option is kind of deprecated.

$ ./sbe-debug.py -i MSBE -t FILE -l trace -r System_Dump_Entry_SBE_30000001 -f

if you are getting below error, that means pibmem dump and symbol file used are different. So please double check.

Failed converting ppe trace to fsp trace. rc = 6 PPE trace buffer must be version 2. ERROR running command: 1536

lili-lilili commented 1 year ago

I have tried with "-l trace" and "-l forced-trace". With out modify the tool (sbe-debug.py), all of them will return same error. Also i confirm that: the firmware create the SBE dump file and the symbol file used to prase the dump file are come from the same source code.

Here is the error log of “-l trace”:

$ ./sbe-debug.py -i MSBE -t FILE -l trace -r System_Dump_Entry_SBE_30000001 -f plat_dump/30000001.0_0_SbeData_p10_p10_pibmem_dump 

 Symbol File: [/home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbe_measurement_seeprom.syms]
Parsing the Dump header
Missing section indicator is 0x0
BMC System: 1
Running command [hexdump -v -e '1/8 "%016x"' -e '"\n"' plat_dump/30000001.0_0_SbeData_p10_p10_pibmem_dump| xxd -r -p > output_file]
hexdump: x: bad byte count
Running command [cp output_file plat_dump/30000001.0_0_SbeData_p10_p10_pibmem_dump]

 Trace buffer symbol addr: [fff86990] Trace Buffer Length: [00001038]

 String File: [/home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbeMeasurementStringFile]
Running command [/home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/ppe2fsp /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/DumpPIBMEM /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbetrace.bin ]
Failed converting ppe trace to fsp trace. rc = 6
PPE trace buffer must be version 2.
ERROR running command: 1536 

 fsp-trace: [/home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/fsp-trace]
Running command [/home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/fsp-trace -s /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbeMeasurementStringFile /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbetrace.bin > /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbe_measurement_seeprom_0_tracMERG]
fsp-trace.c is_smartDump [503]: read 40 bytes of /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbetrace.bin = 0, 19: No such device
fsp-trace.c parse_opt: file /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbetrace.bin: not an fsp-trace file (Incorrect Version?)
fsp-trace.c main: failed to parse all files (skipped 1 files)
ERROR running command: 5632 
Running command [mv /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/DumpPIBMEM /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/dumpPibMem_trace]

Let check the error "Failed converting ppe trace to fsp trace. rc = 6".

It report by ppe2fsp:

/home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/ppe2fsp 
    /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/DumpPIBMEM 
    /home/li/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug/sbetrace.bin

I guess DumpPIBMEM is a input file, it will be copy to dumpPibMem_trace at last, please note that dumpPibMem_trace file size is zero.

I think this is cuased by the following error.

Running command [hexdump -v -e '1/8 "%016x"' -e '"\n"' plat_dump/30000001.0_0_SbeData_p10_p10_pibmem_dump| xxd -r -p > output_file]
hexdump: x: bad byte count
li@Ubuntu-li:~/works/P10/fw1030-master/output/build/sbe-p10-c74232131c91c41b418e711f6fc181ff3b881d7a/src/tools/debug$ ll
total 1872
drwxr-xr-x  4 li li   4096 4月  14 14:24 ./
drwxr-xr-x 12 li li   4096 11月 24 21:02 ../
-rw-rw-r--  1 li li      0 4月  14 14:24 dumpPibMem_trace
-rw-r--r--  1 li li   4192 11月 24 21:02 extractMpiplDump.py
-rwxr-xr-x  1 li li 338480 4月  12 14:09 fsp-trace*
-rwxr-xr-x  1 li li  24576 11月 24 21:02 hbbl.bin*
-rw-r--r--  1 li li    202 1月   1  1970 info.yaml
-rw-rw-r--  1 li li  20857 4月  14 14:24 output.binary
-rw-rw-r--  1 li li      0 4月  14 14:24 output_file
drwxrwxr-x  2 li li   4096 4月  14 14:24 plat_dump/
-rwxr-xr-x  1 li li  28312 4月  12 14:08 ppe2fsp*
-rwxr-xr-x  1 li li 638944 4月  12 14:09 ppetracepp*
-rw-r--r--  1 li li 141556 4月  12 14:07 sbe_DD1.syms
-rwxrwxr-x  1 li li  36865 4月  12 14:39 sbe-debug-m.py*
-rwxr-xr-x  1 li li  34928 11月 24 21:02 sbe-debug.py*
-rw-rw-r--  1 li li      0 4月  14 14:24 sbe_measurement_seeprom_0_tracMERG
-rw-r--r--  1 li li  21376 4月  12 14:08 sbe_measurement_seeprom.syms
-rw-r--r--  1 li li 165937 4月  12 14:08 sbeMeasurementStringFile
-rwxr-xr-x  1 li li   7574 11月 24 21:02 sbeModifyPGvalue.py*
-rw-rw-r--  1 li li 157377 4月  12 14:08 sbeStringFile_DD1
-rw-rw-r--  1 li li      0 4月  14 14:24 sbetrace.bin
-rw-rw-r--  1 li li 171314 4月  12 14:08 sbeVerificationStringFile
-rw-r--r--  1 li li  20866 4月  12 14:07 sbe_verification.syms
drwxr-xr-x  2 li li   4096 11月 24 21:02 simics/
-rwxr-xr-x  1 li li  14182 11月 24 21:02 simics-debug-framework.py*
-rwxr-xr-x  1 li li  10540 11月 24 21:02 simics-debug-framework_rainier.py*
-rw-r--r--  1 li li  22089 4月  12 14:37 System_Dump_Entry_SBE_30000001
skumar8j commented 1 year ago

Do you know which measurement version you were running? There are two measurement version 2.13 and 2.14

You can use Cronus to query the measurement version. And once again verify if the symbol file used to parse the SBE dump is correct one.