Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

System Configuration can not be saved #27

Closed
johnhihi opened this issue Apr 10, 2017 · 11 comments
Closed

System Configuration can not be saved #27

johnhihi opened this issue Apr 10, 2017 · 11 comments

Comments

@johnhihi
Copy link

Hi

We tried to modify "Timeout" for auto-boot setting in Petitboot System Configuration and choose "OK" on Zaius system.
After we "reboot" the system, the value we previously set in configuration page will not remain. It turns back to the default value.

We use this open-power/op-build@316265f to build zaius pnor image.

@sammj
Copy link
Contributor

sammj commented Apr 10, 2017

Before rebooting please run pb-sos in the Petitboot shell and post the result.

@johnhihi
Copy link
Author

Please refer to the attachment. Thank you.

diag.tar.gz

@sammj
Copy link
Contributor

sammj commented Apr 11, 2017

Running command:
 exe:  nvram
 argv: 'nvram' '--update-config' 'petitboot,bootdevs=network any ' '--partition' 'common'
Running command:
 exe:  nvram
 argv: 'nvram' '--update-config' 'petitboot,console=/dev/hvc0 [IPMI / Serial]' '--partition' 'common'
tftp: timeout
Running command:
 exe:  nvram
 argv: 'nvram' '--update-config' 'petitboot,timeout=30' '--partition' 'common'

Petitboot is recognising the change and updating it, so the issue may be with a different layer.
After updating, but before rebooting, what is the output of nvram --print-config? Please also post /sys/firmware/opal/msglog.

@johnhihi
Copy link
Author

# nvram --print-config
"common" Partition
---------------------
petitboot,bootdevs=network any 
petitboot,console=/dev/hvc0 [IPMI / Serial]
petitboot,timeout=30
#
#
#
# cat /sys/firmware/opal/msglog
[  275.313760184,5] SkiBoot skiboot-5.5.0-rc2 starting...
[  275.313764115,5] initial console log level: memory 7, driver 5
[  275.313766928,6] CPU: P9 generation processor(max 4 threads/core)
[  275.313769615,7] CPU: Boot CPU PIR is 0x083c PVR is 0x004e0100
[  275.313772324,7] CPU: Initial max PIR set to 0x7fff
[  275.314910223,5] OPAL table: 0x300d2740 .. 0x300d2c00, branch table: 0x30002000
[  275.314917216,7] Parsing HDAT...
[  275.314919106,5] SPIRA-S found.
[  275.314923868,6] BMC #0: HW version 3, SW version 2, chip DD1.0
[  275.314928629,6] SP Family is ibm,ast2500,openbmc
[  275.314936497,7] LPC: IOPATH chip id = 0
[  275.314938402,7] LPC: FW BAR       = f0000000
[  275.314940477,7] LPC: MEM BAR      = e0000000
[  275.314942533,7] LPC: IO BAR       = d0010000
[  275.314944573,7] LPC: Internal BAR = c0012000
[  275.314961643,7] LPC UART: base addr = 3f8 (3f8) size = 1 clk = 1843200, baud = 115200
[  275.314965461,7] LPC: BT [0, 0] sms_int: 0, bmc_int: 0
[  275.315566701,5] UART: Using UART at 0x60300d00103f8
[  275.315598685,6] Got PCIA !
[  275.315601502,6] CORE[0]: HW_PROC_ID=0 PROC_CHIP_ID=0 EC=0x12 OK
[  275.315604972,6] CORE[0]: PIR=00000008 OK (4 threads)
[  275.315608633,6]     Cache: I=32 D=32/512/10240/0
[  275.315643397,6] CORE[1]: HW_PROC_ID=1 PROC_CHIP_ID=0 EC=0x12 OK
[  275.315646652,6] CORE[1]: PIR=0000000c OK (4 threads)
[  275.315649781,6]     Cache: I=32 D=32/512/10240/0
[  275.315674743,6] CORE[2]: HW_PROC_ID=2 PROC_CHIP_ID=0 EC=0x12 OK
[  275.315677812,6] CORE[2]: PIR=00000018 OK (4 threads)
[  275.315680923,6]     Cache: I=32 D=32/512/10240/0
[  275.315715618,6] CORE[3]: HW_PROC_ID=3 PROC_CHIP_ID=0 EC=0x12 OK
[  275.315718839,6] CORE[3]: PIR=0000001c OK (4 threads)
[  275.315721952,6]     Cache: I=32 D=32/512/10240/0
[  275.315747306,6] CORE[4]: HW_PROC_ID=0 PROC_CHIP_ID=1 EC=0x12 OK
[  275.315750390,6] CORE[4]: PIR=00000838 OK (4 threads)
[  275.315753524,6]     Cache: I=32 D=32/512/10240/0
[  275.315789432,6] CORE[5]: HW_PROC_ID=1 PROC_CHIP_ID=1 EC=0x12 OK
[  275.315792688,6] CORE[5]: PIR=0000083c OK [boot] (4 threads)
[  275.315796205,6]     Cache: I=32 D=32/512/10240/0
[  275.315822335,6] CORE[6]: HW_PROC_ID=2 PROC_CHIP_ID=1 EC=0x12 OK
[  275.315825422,6] CORE[6]: PIR=00000858 OK (4 threads)
[  275.315828522,6]     Cache: I=32 D=32/512/10240/0
[  275.315866244,6] CORE[7]: HW_PROC_ID=3 PROC_CHIP_ID=1 EC=0x12 OK
[  275.315869441,6] CORE[7]: PIR=0000085c OK (4 threads)
[  275.315872531,6]     Cache: I=32 D=32/512/10240/0
[  275.315902885,6] IPLPARAMS: v0x70 Platform family/type: ingrasys,p9/ingrasys,zaius
[  275.315911570,7] MS VPD: is at 0x31202780
[  275.315913721,7] MS VPD: MSAC is at 0x312027f0
[  275.315916290,7] MS VPD: TCMS is at 0x3120280c
[  275.315918370,7] MS VPD: Maximum configured address: 0x8000203fffffffff
[  275.315921176,7] MS VPD: Maximum possible address: 0x8000203fffffffff
[  275.315924298,7] MS VPD: 0x31202780, area 0: installed functional shared
[  275.316168396,7]   Range: 0x0000000000000000..0x0000004000000000 on Chip 0x0 mattr: 0xff0000
[  275.316178844,7] MS VPD: 0x31202780, area 1: installed functional shared
[  275.316191674,7]   Range: 0x0000000000000000..0x0000004000000000 on Chip 0x0 mattr: 0xff0000
[  275.316198131,7] MS VPD: 0x31202780, area 2: installed functional shared
[  275.316211031,7]   Range: 0x0000000000000000..0x0000004000000000 on Chip 0x0 mattr: 0xff0000
[  275.316217194,7] MS VPD: 0x31202780, area 3: installed functional shared
[  275.316230059,7]   Range: 0x0000000000000000..0x0000004000000000 on Chip 0x0 mattr: 0xff0000
[  275.316236083,7] MS VPD: 0x31202780, area 4: installed functional shared
[  275.316249049,7]   Range: 0x0000000000000000..0x0000004000000000 on Chip 0x0 mattr: 0xff0000
[  275.316255051,7] MS VPD: 0x31202780, area 5: installed functional shared
[  275.316268118,7]   Range: 0x0000000000000000..0x0000004000000000 on Chip 0x0 mattr: 0xff0000
[  275.316274161,7] MS VPD: 0x31202780, area 6: installed functional shared
[  275.316287309,7]   Range: 0x0000000000000000..0x0000004000000000 on Chip 0x0 mattr: 0xff0000
[  275.316293345,7] MS VPD: 0x31202780, area 7: installed functional shared
[  275.316306441,7]   Range: 0x0000000000000000..0x0000004000000000 on Chip 0x0 mattr: 0xff0000
[  275.316312462,7] MS VPD: 0x31202780, area 8: installed functional shared
[  275.316326108,7]   Range: 0x0000200000000000..0x0000204000000000 on Chip 0x8 mattr: 0xff0000
[  275.316336710,7] MS VPD: 0x31202780, area 9: installed functional shared
[  275.316350618,7]   Range: 0x0000200000000000..0x0000204000000000 on Chip 0x8 mattr: 0xff0000
[  275.316356952,7] MS VPD: 0x31202780, area 10: installed functional shared
[  275.316371105,7]   Range: 0x0000200000000000..0x0000204000000000 on Chip 0x8 mattr: 0xff0000
[  275.316377288,7] MS VPD: 0x31202780, area 11: installed functional shared
[  275.316391267,7]   Range: 0x0000200000000000..0x0000204000000000 on Chip 0x8 mattr: 0xff0000
[  275.316397397,7] MS VPD: 0x31202780, area 12: installed functional shared
[  275.316411650,7]   Range: 0x0000200000000000..0x0000204000000000 on Chip 0x8 mattr: 0xff0000
[  275.316417807,7] MS VPD: 0x31202780, area 13: installed functional shared
[  275.316432141,7]   Range: 0x0000200000000000..0x0000204000000000 on Chip 0x8 mattr: 0xff0000
[  275.316438321,7] MS VPD: 0x31202780, area 14: installed functional shared
[  275.316452833,7]   Range: 0x0000200000000000..0x0000204000000000 on Chip 0x8 mattr: 0xff0000
[  275.316459008,7] MS VPD: 0x31202780, area 15: installed functional shared
[  275.316463312,7]   Range: 0x0000200000000000..0x0000204000000000 on Chip 0x8 mattr: 0xff0000
[  275.316470286,7] MEM: Reserve 'ibm,hbrt-vpd-image' 203ffd700000-203ffd7fffff (type/inst=0x01000000)
[  275.316476114,7] MEM: Reserve 'ibm,hbrt-target-image' 203ffd690000-203ffd6f0fff (type/inst=0x01000000)
[  275.316482280,7] MEM: Reserve 'ibm,hbrt-code-image' 203ffd460000-203ffd6842af (type/inst=0x01000000)
[  275.316487728,7] MEM: Ignoring zero length range
[  275.316489812,7] MEM: Ignoring zero length range
[  275.316491894,7] MEM: Ignoring zero length range
[  275.316494042,7] MEM: Ignoring zero length range
[  275.316496100,7] MEM: Ignoring zero length range
[  275.316498218,7] MEM: Ignoring zero length range
[  275.316500305,7] MEM: Ignoring zero length range
[  275.316502365,7] MEM: Ignoring zero length range
[  275.316504453,7] MEM: Ignoring zero length range
[  275.316506522,7] MEM: Ignoring zero length range
[  275.316508556,6] MS VPD: Total MB of RAM: 0x80000
[  275.316511134,6] XSCOM: Found HW ID 0x0 (PCID 0x0) @ 0x603fc00000000
[  275.316735794,6] XSCOM: Found HW ID 0x8 (PCID 0x1) @ 0x623fc00000000
[  275.316956761,6] BMC #0: HW version 3, SW version 2, chip DD1.0
[  275.316970667,7] CHIPTOD: Found on chip 0x0 [primary]
[  275.316987340,7] CHIPTOD: Found on chip 0x8 [secondary]
[  275.316993456,6] CEC: HUB FRU 0 is CPU Card
[  275.316995778,6] CEC:   1 chips in FRU
[  275.316997634,7] CEC:   IO Hub Chip #0 OK
[  275.316999556,7] CEC:   PChip: 0 HUB ID: 0022 [EC=0x12] Hub#=0)
[  275.317002401,6] CEC:     Nimbus !
[  275.317004138,6] CEC:     HW CHIP=0x0, HW TOPO=0x0000
[  275.317016666,5] IOHUB: PHB4 active bridge mask f0
[  275.317070848,7] CEC:     ibm,loc-code: UOPWR.BAR.0000000-Node0-Proc0 (SLCA rsrc 0x1000)
[  275.317077204,6] CEC: Added PHB4 PBCQ 0 with 1 stacks
[  275.317090054,7] CEC:     ibm,loc-code: UOPWR.BAR.0000000-Node0-Proc0 (SLCA rsrc 0x1000)
[  275.317096359,6] CEC: Added PHB4 PBCQ 1 with 2 stacks
[  275.317112315,7] CEC:     ibm,loc-code: UOPWR.BAR.0000000-Node0-Proc0 (SLCA rsrc 0x1000)
[  275.317118643,6] CEC: Added PHB4 PBCQ 2 with 3 stacks
[  275.317121146,6] CEC: HUB FRU 1 is CPU Card
[  275.317123442,6] CEC:   1 chips in FRU
[  275.317125309,7] CEC:   IO Hub Chip #0 OK
[  275.317127233,7] CEC:   PChip: 1 HUB ID: 0022 [EC=0x12] Hub#=1)
[  275.317130041,6] CEC:     Nimbus !
[  275.317131772,6] CEC:     HW CHIP=0x8, HW TOPO=0x0000
[  275.317146981,5] IOHUB: PHB4 active bridge mask fc
[  275.317195839,7] CEC:     ibm,loc-code: UOPWR.BAR.0000000-Node0-Proc1 (SLCA rsrc 0x1001)
[  275.317202121,6] CEC: Added PHB4 PBCQ 0 with 1 stacks
[  275.317214702,7] CEC:     ibm,loc-code: UOPWR.BAR.0000000-Node0-Proc1 (SLCA rsrc 0x1001)
[  275.317220984,6] CEC: Added PHB4 PBCQ 1 with 2 stacks
[  275.317237120,7] CEC:     ibm,loc-code: UOPWR.BAR.0000000-Node0-Proc1 (SLCA rsrc 0x1001)
[  275.317243372,6] CEC: Added PHB4 PBCQ 2 with 3 stacks
[  275.317274368,6] Parsing HDAT...done
[  275.317310179,5] P9 DD1.02 detected
[  275.317347196,5] XSCOM: chip 0x0 at 0x603fc00000000 [P9N DD1.0]
[  275.317390072,5] P9 DD1.02 detected
[  275.317410075,5] XSCOM: chip 0x8 at 0x623fc00000000 [P9N DD1.0]
[  275.317446740,6] XSTOP: ibm,sw-checkstop-fir prop not found
[  275.317449367,6] MFSI 0:0: Initialized
[  275.317451293,6] MFSI 0:2: Initialized
[  275.317453226,6] MFSI 0:1: Initialized
[  275.317455391,6] MFSI 8:0: Initialized
[  275.317457298,6] MFSI 8:2: Initialized
[  275.317459206,6] MFSI 8:1: Initialized
[  275.317500966,5] LPC: LPC[000]: Initialized, access via MMIO @0x6030000000000
[  275.317572844,5] LPC: LPC: Default bus on chip 0x0
[  275.317634662,6] MEM: parsing reserved memory from reserved-names/-ranges properties
[  275.317638126,7] HOMER: Init chip 0
[  275.317641098,7]   PBA BAR0 : 0x6000203ffd800000
[  275.317643409,7]   PBA MASK0: 0x0000000000300000
[  275.317645716,7]   HOMER Image at 0x203ffd800000 size 4MB
[  275.317648369,4] HOMER image is not reserved! Reserving
[  275.317694186,7]   PBA BAR2 : 0x0000000000000000
[  275.317696449,7]   PBA MASK2: 0x0000000000000000
[  275.317698771,7] HOMER: Init chip 8
[  275.317701393,7]   PBA BAR0 : 0x6000203ffdc00000
[  275.317703639,7]   PBA MASK0: 0x0000000000300000
[  275.317705932,7]   HOMER Image at 0x203ffdc00000 size 4MB
[  275.317708526,4] HOMER image is not reserved! Reserving
[  275.317749987,7]   PBA BAR2 : 0x0000000000000000
[  275.317752249,7]   PBA MASK2: 0x0000000000000000
[  275.317762866,7] CPU idle state device tree init
[  275.317766755,5] SLW: Enabling: stop0_lite
[  275.317838943,7] AST: PNOR LPC offset: 0x0c000000
[  275.317868573,5] PLAT: Using virtual UART
[  275.317998642,7] UART: Using LPC IRQ 4
[  275.318006014,7] LPC-MBOX: Attempting mbox init
[  275.318016027,7] LPC: LPC: Routing irq 9, policy: 0 (r=1)
[  275.318018847,7] LPC: LPC: SerIRQ 9 using route 0 targetted at OPAL
[  275.318110449,7] LPC-MBOX: Enabled on chip 0, IO port 0x1000, IRQ 9
[  275.318117416,5] PLAT: Detected Zaius platform
[  275.318145528,7] CPU: decrementer bits 56
[  275.318149370,6] CPU: CPU from DT PIR=0x0008 Server#=0x8 State=3
[  275.318155995,6] CPU:  4 secondary threads
[  275.318159257,6] CPU: CPU from DT PIR=0x000c Server#=0xc State=3
[  275.318165482,6] CPU:  4 secondary threads
[  275.318168733,6] CPU: CPU from DT PIR=0x0018 Server#=0x18 State=3
[  275.318174946,6] CPU:  4 secondary threads
[  275.318178141,6] CPU: CPU from DT PIR=0x001c Server#=0x1c State=3
[  275.318184273,6] CPU:  4 secondary threads
[  275.318187436,6] CPU: CPU from DT PIR=0x0838 Server#=0x838 State=3
[  275.318193653,6] CPU:  4 secondary threads
[  275.318196954,6] CPU: CPU from DT PIR=0x083c Server#=0x83c State=3
[  275.318202994,6] CPU:  4 secondary threads
[  275.318206215,6] CPU: CPU from DT PIR=0x0858 Server#=0x858 State=3
[  275.318212328,6] CPU:  4 secondary threads
[  275.318215470,6] CPU: CPU from DT PIR=0x085c Server#=0x85c State=3
[  275.318221586,6] CPU:  4 secondary threads
[  275.318224185,7] CPU: New max PIR set to 0x85f
[  275.318737647,7] XIVE[ IC 00  ] Initializing, block ID 0...
[  275.318757194,7] XIVE[ IC 00  ] Handling interrupts [00000000..000fffff]
[  275.318761110,4] XIVE[ IC 00  ] IC BAR invalid, reconfiguring
[  275.318841738,7] XIVE[ IC 00  ] IC: 0x6030203100000 [0x000000080000/16]
[  275.318845271,7] XIVE[ IC 00  ] TM: 0x6030203180000 [0x000000040000/16]
[  275.318848632,7] XIVE[ IC 00  ] PC: 0x6018000000000 [0x001000000000]
[  275.318851874,7] XIVE[ IC 00  ] VC: 0x6010000000000 [0x008000000000]
[  275.318864016,7]  CQ_CFG_PB_GEN = 5000000000000000
[  275.318866421,7]  CQ_MSGSND     = ffffff0000000000
[  275.319358341,7] XIVE[ IC 00  ] SBE at 0x52040000 size 0x800000
[  275.322146895,7] XIVE[ IC 00  ] IVT at 0x52800000 size 0x800000
[  275.322174060,7] XIVE[ IC 00  ] EQi at 0x53010000 size 0x10000
[  275.322197421,7] XIVE[ IC 00  ] VPi at 0x53030000 size 0x10000
[  275.322203459,7] XIVE[ IC 00  ] Allocating pages 0 to 0 of VPs (for 128 VPs)
[  275.322226737,7] XIVE[ IC 00  ] VP0 at 0x53050000 size 0x10000
[  275.322234972,7] IRQ: Registering 0000..fffff ops @0x300a3af8 (data 0x0) [secondary]
[  275.322240112,7] IRQ: Registering 1000000..10fffff ops @0x300a3af8 (data 0x0)
[  275.322248878,7] XIVE[ IC 08  ] Initializing, block ID 1...
[  275.322268210,7] XIVE[ IC 08  ] Handling interrupts [00100000..001fffff]
[  275.322272060,4] XIVE[ IC 08  ] IC BAR invalid, reconfiguring
[  275.322330045,7] XIVE[ IC 08  ] IC: 0x6230203100000 [0x000000080000/16]
[  275.322333284,7] XIVE[ IC 08  ] TM: 0x6030203180000 [0x000000040000/16]
[  275.322336501,7] XIVE[ IC 08  ] PC: 0x6218000000000 [0x001000000000]
[  275.322339572,7] XIVE[ IC 08  ] VC: 0x6210000000000 [0x008000000000]
[  275.322347555,7]  CQ_CFG_PB_GEN = 5000000000000000
[  275.322349852,7]  CQ_MSGSND     = ffffff0000000000
[  275.322842991,7] XIVE[ IC 08  ] SBE at 0x200000440000 size 0x800000
[  275.324213538,7] XIVE[ IC 08  ] IVT at 0x200000800000 size 0x800000
[  275.324238852,7] XIVE[ IC 08  ] EQi at 0x200001010000 size 0x10000
[  275.324261678,7] XIVE[ IC 08  ] VPi at 0x200001030000 size 0x10000
[  275.324266494,7] XIVE[ IC 08  ] Allocating pages 0 to 0 of VPs (for 128 VPs)
[  275.324289509,7] XIVE[ IC 08  ] VP0 at 0x200001050000 size 0x10000
[  275.324295630,7] IRQ: Registering 100000..1fffff ops @0x300a3af8 (data 0x0) [secondary]
[  275.324299993,7] IRQ: Registering 1100000..11fffff ops @0x300a3af8 (data 0x0)
[  275.324303953,6] XIVE: 2 chips considered for VP allocations
[  275.339682153,7] XIVE[CPU 0008] Setting up special BAR
[  275.339684986,7] XIVE[CPU 0008] NCU_SPEC_BAR_XA[10011410]=c006030203180000
[  275.339690833,7] XIVE[CPU 0008] CPU IPI is irq 00000010
[  275.339694246,7] XIVE[ IC 00  ] Indirect empty, provisioning from local pool
[  275.339753827,7] XIVE[CPU 0009] CPU IPI is irq 00000011
[  275.339785125,7] XIVE[CPU 000a] CPU IPI is irq 00000012
[  275.339816407,7] XIVE[CPU 000b] CPU IPI is irq 00000013
[  275.339847212,7] XIVE[CPU 000c] Setting up special BAR
[  275.339849488,7] XIVE[CPU 000c] NCU_SPEC_BAR_XA[10011410]=c006030203180000
[  275.339853890,7] XIVE[CPU 000c] CPU IPI is irq 00000014
[  275.339885341,7] XIVE[CPU 000d] CPU IPI is irq 00000015
[  275.339916655,7] XIVE[CPU 000e] CPU IPI is irq 00000016
[  275.339947998,7] XIVE[CPU 000f] CPU IPI is irq 00000017
[  275.339978777,7] XIVE[CPU 0018] Setting up special BAR
[  275.339981073,7] XIVE[CPU 0018] NCU_SPEC_BAR_XA[11011410]=c006030203180000
[  275.339985490,7] XIVE[CPU 0018] CPU IPI is irq 00000018
[  275.340016834,7] XIVE[CPU 0019] CPU IPI is irq 00000019
[  275.340047881,7] XIVE[CPU 001a] CPU IPI is irq 0000001a
[  275.340079666,7] XIVE[CPU 001b] CPU IPI is irq 0000001b
[  275.340110380,7] XIVE[CPU 001c] Setting up special BAR
[  275.340112696,7] XIVE[CPU 001c] NCU_SPEC_BAR_XA[11011410]=c006030203180000
[  275.340117087,7] XIVE[CPU 001c] CPU IPI is irq 0000001c
[  275.340148470,7] XIVE[CPU 001d] CPU IPI is irq 0000001d
[  275.340179654,7] XIVE[CPU 001e] CPU IPI is irq 0000001e
[  275.340211008,7] XIVE[CPU 001f] CPU IPI is irq 0000001f
[  275.340257233,7] XIVE[CPU 0838] Setting up special BAR
[  275.340259592,7] XIVE[CPU 0838] NCU_SPEC_BAR_XA[13011410]=c006030203180000
[  275.340263893,7] XIVE[CPU 0838] CPU IPI is irq 00100000
[  275.340266412,7] XIVE[ IC 08  ] Indirect empty, provisioning from local pool
[  275.340317120,7] XIVE[CPU 0839] CPU IPI is irq 00100001
[  275.340345874,7] XIVE[CPU 083a] CPU IPI is irq 00100002
[  275.340374423,7] XIVE[CPU 083b] CPU IPI is irq 00100003
[  275.340402245,7] XIVE[CPU 083c] Setting up special BAR
[  275.340404596,7] XIVE[CPU 083c] NCU_SPEC_BAR_XA[13011410]=c006030203180000
[  275.340408774,7] XIVE[CPU 083c] CPU IPI is irq 00100004
[  275.340437295,7] XIVE[CPU 083d] CPU IPI is irq 00100005
[  275.340465828,7] XIVE[CPU 083e] CPU IPI is irq 00100006
[  275.340494265,7] XIVE[CPU 083f] CPU IPI is irq 00100007
[  275.340522778,7] XIVE[CPU 0858] Setting up special BAR
[  275.340525127,7] XIVE[CPU 0858] NCU_SPEC_BAR_XA[15011410]=c006030203180000
[  275.340529471,7] XIVE[CPU 0858] CPU IPI is irq 00100008
[  275.340558237,7] XIVE[CPU 0859] CPU IPI is irq 00100009
[  275.340586795,7] XIVE[CPU 085a] CPU IPI is irq 0010000a
[  275.340615320,7] XIVE[CPU 085b] CPU IPI is irq 0010000b
[  275.340643581,7] XIVE[CPU 085c] Setting up special BAR
[  275.340645886,7] XIVE[CPU 085c] NCU_SPEC_BAR_XA[15011410]=c006030203180000
[  275.340650229,7] XIVE[CPU 085c] CPU IPI is irq 0010000c
[  275.340678840,7] XIVE[CPU 085d] CPU IPI is irq 0010000d
[  275.340707194,7] XIVE[CPU 085e] CPU IPI is irq 0010000e
[  275.340735622,7] XIVE[CPU 085f] CPU IPI is irq 0010000f
[  275.340792867,7] XIVE[CPU 083c] Initialized interrupt management area
[  275.340837333,5] PSI[0x000]: ESB MMIO invalid, reconfiguring...
[  275.340892479,5] PSI[0x000]: ESB MMIO at @0x60302031c0000
[  275.340931536,7] PSI[0x000]: Interrupts sources registered for P9 DD1.x
[  275.340935083,7] IRQ: Registering ffff0..ffffd ops @0x300a3af8 (data 0x303db090)
[  275.340952644,5] PSI[0x000]: Found PSI bridge [active=0]
[  275.341008740,5] PSI[0x008]: ESB MMIO invalid, reconfiguring...
[  275.341050032,5] PSI[0x008]: ESB MMIO at @0x62302031c0000
[  275.341083281,7] PSI[0x008]: Interrupts sources registered for P9 DD1.x
[  275.341086292,7] IRQ: Registering 1ffff0..1ffffd ops @0x300a3af8 (data 0x303db4a0)
[  275.341103398,5] PSI[0x008]: Found PSI bridge [active=0]
[  275.341155148,6] CPU: Setting up secondary CPU state
[  275.341158113,6] CPU: Calling in all processors...
[  275.341160842,7] INIT: CPU PIR 0x083e called in
[  275.356646875,7] INIT: CPU PIR 0x085d called in
[  275.352138797,7] INIT: CPU PIR 0x000b called in
[  275.342442249,7] INIT: CPU PIR 0x001c called in
[  275.342442248,7] INIT: CPU PIR 0x001f called in
[  275.342442289,7] INIT: CPU PIR 0x0018 called in
[  275.342442290,7] INIT: CPU PIR 0x001b called in
[  275.335361583,7] INIT: CPU PIR 0x0008 called in
[  275.342442248,7] INIT: CPU PIR 0x001d called in
[  275.342543245,7] XIVE[CPU 0018] Initialized interrupt management area
[  275.342507569,7] XIVE[CPU 001c] Initialized interrupt management area
[  275.342442286,7] INIT: CPU PIR 0x001a called in
[  275.341160828,7] INIT: CPU PIR 0x0839 called in
[  275.341160795,7] INIT: CPU PIR 0x083d called in
[  275.341404741,7] XIVE[CPU 0839] Initialized interrupt management area
[  275.341160880,7] INIT: CPU PIR 0x0838 called in
[  275.341160826,7] INIT: CPU PIR 0x083a called in
[  275.341463123,7] XIVE[CPU 0838] Initialized interrupt management area
[  275.341420016,7] XIVE[CPU 083d] Initialized interrupt management area
[  275.342666493,7] XIVE[CPU 001a] Initialized interrupt management area
[  275.352183942,7] XIVE[CPU 000b] Initialized interrupt management area
[  275.352138811,7] INIT: CPU PIR 0x000e called in
[  275.341161004,7] INIT: CPU PIR 0x083f called in
[  275.341481189,7] XIVE[CPU 083a] Initialized interrupt management area
[  275.341161009,7] INIT: CPU PIR 0x083b called in
[  275.341614217,7] XIVE[CPU 083f] Initialized interrupt management area
[  275.341644975,7] XIVE[CPU 083b] Initialized interrupt management area
[  275.341173877,7] XIVE[CPU 083e] Initialized interrupt management area
[  275.342560638,7] XIVE[CPU 001b] Initialized interrupt management area
[  275.356647096,7] INIT: CPU PIR 0x085c called in
[  275.339869662,7] INIT: CPU PIR 0x085b called in
[  275.356676323,7] XIVE[CPU 085d] Initialized interrupt management area
[  275.339869553,7] INIT: CPU PIR 0x085a called in
[  275.335500786,7] XIVE[CPU 0008] Initialized interrupt management area
[  275.352138800,7] INIT: CPU PIR 0x0009 called in
[  275.352138814,7] INIT: CPU PIR 0x000c called in
[  275.352794803,7] XIVE[CPU 0009] Initialized interrupt management area
[  275.342442289,7] INIT: CPU PIR 0x0019 called in
[  275.342598206,7] XIVE[CPU 001d] Initialized interrupt management area
[  275.342442246,7] INIT: CPU PIR 0x001e called in
[  275.343137675,7] XIVE[CPU 0019] Initialized interrupt management area
[  275.357216313,7] XIVE[CPU 085c] Initialized interrupt management area
[  275.339869586,7] INIT: CPU PIR 0x0859 called in
[  275.340454456,7] XIVE[CPU 085b] Initialized interrupt management area
[  275.356647251,7] INIT: CPU PIR 0x085f called in
[  275.339869591,7] INIT: CPU PIR 0x0858 called in
[  275.356646869,7] INIT: CPU PIR 0x085e called in
[  275.343169762,7] XIVE[CPU 001e] Initialized interrupt management area
[  275.342525605,7] XIVE[CPU 001f] Initialized interrupt management area
[  275.352138814,7] INIT: CPU PIR 0x000f called in
[  275.352574452,7] XIVE[CPU 000e] Initialized interrupt management area
[  275.352138800,7] INIT: CPU PIR 0x000a called in
[  275.353008361,7] XIVE[CPU 000f] Initialized interrupt management area
[  275.353028875,7] XIVE[CPU 000a] Initialized interrupt management area
[  275.352138813,7] INIT: CPU PIR 0x000d called in
[  275.352810161,7] XIVE[CPU 000c] Initialized interrupt management area
[  275.353056776,7] XIVE[CPU 000d] Initialized interrupt management area
[  275.340643435,7] XIVE[CPU 0859] Initialized interrupt management area
[  275.340689972,7] XIVE[CPU 0858] Initialized interrupt management area
[  275.357454564,7] XIVE[CPU 085f] Initialized interrupt management area
[  275.357480954,7] XIVE[CPU 085e] Initialized interrupt management area
[  275.342087988,5] CPU: All 32 processors called in...
[  275.340493673,7] XIVE[CPU 085a] Initialized interrupt management area
[  275.342249204,6] CPU: enabling power management
[  275.342276661,6] CHIPTOD: Calculated MCBS is 0x26 (Cfreq=2050000000 Tfreq=32000000)
[  275.342280561,7] CHIPTOD: Base TFMR=0x2612000000000000
[  275.336485143,7] CHIPTOD: Master sync on CPU PIR 0x0008...
[  275.373749342,7] CHIPTOD: Slave sync on CPU PIR 0x000c...
[  275.384538159,7] CHIPTOD: Slave sync on CPU PIR 0x0018...
[  275.405023069,7] CHIPTOD: Slave sync on CPU PIR 0x001c...
[  275.424235249,7] CHIPTOD: Slave sync on CPU PIR 0x0838...
[  275.444717610,7] CHIPTOD: Slave sync on CPU PIR 0x083c...
[  275.461395532,7] CHIPTOD: Slave sync on CPU PIR 0x0858...
[  275.502116701,7] CHIPTOD: Slave sync on CPU PIR 0x085c...
[    0.143968944,7] CHIPTOD: PIR 0x0008 TB=894caa0
[    0.149089808,7] CHIPTOD: PIR 0x000c TB=8e2ee00
[    0.154211024,7] CHIPTOD: PIR 0x0018 TB=93112d0
[    0.159331840,7] CHIPTOD: PIR 0x001c TB=97f3600
[    0.164460992,7] CHIPTOD: PIR 0x0838 TB=9cd79b0
[    0.169581408,7] CHIPTOD: PIR 0x083c TB=a1b9b50
[    0.169584528,7] CHIPTOD: PIR 0x0858 TB=a1ba780
[    0.174705376,7] CHIPTOD: PIR 0x085c TB=a69cae0
[    0.179836976,7] CHIPTOD: TOD Topology in Use: Primary
[    0.179839408,7] CHIPTOD:   Primary configuration:
[    0.179841408,7] CHIPTOD:   Chip id: 0, Role: MDMT, Status: Active Master
[    0.179844816,7] CHIPTOD:   Secondary configuration:
[    0.179846768,7] CHIPTOD:   Chip id: 8, Role: MDMT, Status: Backup Master
[    0.179965280,7] LPC-MBOX: Sending BMC interrupt
[    0.282383200,4] LPC-MBOX: BMC reset detected
[    0.282425920,3] LPC-MBOX: Got a status bit set that don't know about: 0xfe
[    0.282470976,7] LPC-MBOX: Sending BMC interrupt
[    0.384885872,6] FLASH: registering flash device (unnamed) (size 0x4000000, blocksize 0x10000)
[    0.384894880,7] LPC-MBOX: Sending BMC interrupt
[    0.487306448,7] MBOX-FLASH: Adjusting the window
[    0.487312928,7] LPC-MBOX: Sending BMC interrupt
[    1.077735280,7] FFS: Partition map size: 0x1000
[    1.078590352,5] FLASH: Found system flash:  id:0
[    1.078636064,6] FLASH: registered system flash device 
[    1.078638144,6] FLASH: probing for NVRAM
[    1.078654608,5] BT: Interface initialized, IO 0x00e4
[    1.078694432,7] LPC: LPC: Routing irq 10, policy: 0 (r=1)
[    1.078697328,7] LPC: LPC: SerIRQ 10 using route 1 targetted at OPAL
[    1.078763904,7] BT: seq 0x00 netfn 0x06 cmd 0x36: Message sent to host
[    1.078766816,7] BT: Using LPC IRQ 10
[    1.181187072,7] BT: seq 0x00 netfn 0x06 cmd 0x36: IPMI MSG done
[    1.181190192,7] BT: Got a input buffer len (63) cap which differs from the default
[    1.181193216,7] BT: Got a output buffer len (63) cap which differs from the default
[    1.181196080,7] BT: BMC BT capabilities received:
[    1.181198032,7] BT: buffer sizes: 64 input 64 output
[    1.181200080,7] BT: number of requests: 1
[    1.181201824,7] BT: msg timeout: 10 max retries: 1
[    1.181208752,7] BT: seq 0x01 netfn 0x06 cmd 0x24: Message sent to host
[    1.283622224,7] BT: seq 0x01 netfn 0x06 cmd 0x24: IPMI MSG done
[    1.283627520,7] BT: seq 0x02 netfn 0x06 cmd 0x22: Message sent to host
[    1.386040704,7] BT: seq 0x02 netfn 0x06 cmd 0x22: IPMI MSG done
[    1.437248272,7] BT: seq 0x03 netfn 0x06 cmd 0x22: Message sent to host
[    1.488459616,7] BT: seq 0x03 netfn 0x06 cmd 0x22: IPMI MSG done
[    2.027668896,7] BT: seq 0x04 netfn 0x0a cmd 0x48: Message sent to host
[    2.027694400,6] IPMI: setting power state: sys 80, dev 7f
[    2.027717680,5] NVRAM: Size is 576 KB
[    2.148648208,3] NVRAM: Partition at offset 0xffff0 extends beyond end of nvram !
[    2.148704960,3] NVRAM: Re-initializing (size: 0x00090000)
[    2.148750816,7] NVRAM: Created 'ibm,skiboot' partition at 0x00000000 for size 0x00000100 with cksum 0xb5
[    2.148755360,7] NVRAM: Created 'common' partition at 0x00001000 for size 0x00001000 with cksum 0x0c
[    2.148759104,7] NVRAM: Created 'wwwwwwwwwwww' partition at 0x00011000 for size 0x00007f00 with cksum 0x98
[    2.148764544,7] MBOX-FLASH: Adjusting the window
[    2.148771248,7] LPC-MBOX: Sending BMC interrupt
[    2.251180800,7] BT: seq 0x04 netfn 0x0a cmd 0x48: IPMI MSG done
[    2.251187888,7] BT: seq 0x05 netfn 0x06 cmd 0x06: Message sent to host
[    2.333609088,7] LPC-MBOX: Sending BMC interrupt
[    2.436017024,7] BT: seq 0x05 netfn 0x06 cmd 0x06: IPMI MSG done
[    2.436022608,7] BT: seq 0x06 netfn 0x06 cmd 0x2e: Message sent to host
[    3.026432208,7] BT: seq 0x06 netfn 0x06 cmd 0x2e: IPMI MSG done
[    6.026488752,5] STB: secure and trusted boot not supported
[    6.026548416,5] OPAL: Using OPAL UART console
[    6.026576640,7] LPC: LPC: Routing irq 4, policy: 1 (r=2)
[    6.026579168,7] LPC: LPC: SerIRQ 4 using route 2 targetted at OS
[    6.026641472,7] UART: Enabled as OS pass-through
[    6.026643808,5] SLW: Init chip 0x0
[    6.026668992,5] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[    6.026712800,5] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[    6.026747584,5] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[    6.026790752,5] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[    6.026835616,5] SLW: Init chip 0x8
[    6.026872576,5] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[    6.026920800,5] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[    6.026955472,5] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[    6.026990240,5] SLW: EC_PPM_SPECIAL_WKUP_HYP read  0x0000000000000000
[    6.027047392,5] CAPI: WARNING: no compat thing found
[    6.027079072,5] FLASH: Queueing preload of 0/0
[    6.027107392,5] FLASH: Queueing preload of 1/0
[    6.027135072,7] LPC-MBOX: Sending BMC interrupt
[    6.027227808,5] PHB: Chip 0 Found PHB4 PBCQ0 Stack 0 at /xscom@603fc00000000/pbcq@4010c00/stack@0
[    6.027290080,7] PHB[0:0] X[PE]=0x04010c00/0x04010c40 X[PCI]=0x0d010800/0x0d010840 X[ETU]=0x0d010900
[    6.027294688,3] PHB[0:0] No PHB BAR set ! Overriding
[    6.027326752,3] PHB[0:0] REGS     = 0x000600c3c0000000 [4k]
[    6.027356816,3] PHB[0:0] No IRQ BAR set ! Overriding
[    6.027386080,3] PHB[0:0] ESB      = 0x000600c300000000 [...]
[    6.027416320,3] PHB[0:0] No MMIO BAR set ! Overriding
[    6.027447248,7] PHB[0:0] MMIO0    = 0x0006000000000000 [0x0000002000000000]
[    6.027451184,7] PHB[0:0] MMIO1    = 0x000600c000000000 [0x0000000080000000]
[    6.027455728,3] ETU reset: 0
[    6.027985072,3] Version reg: 0x000000a400000001
[    6.028041568,5] PHB: Chip 0 Found PHB4 PBCQ1 Stack 0 at /xscom@603fc00000000/pbcq@4011000/stack@0
[    6.028093232,7] PHB[0:1] X[PE]=0x04011000/0x04011040 X[PCI]=0x0e010800/0x0e010840 X[ETU]=0x0e010900
[    6.028097408,3] PHB[0:1] No PHB BAR set ! Overriding
[    6.028129104,3] PHB[0:1] REGS     = 0x000600c3c0100000 [4k]
[    6.028158592,3] PHB[0:1] No IRQ BAR set ! Overriding
[    6.028191920,3] PHB[0:1] ESB      = 0x000600c320000000 [...]
[    6.028222128,3] PHB[0:1] No MMIO BAR set ! Overriding
[    6.028254848,7] PHB[0:1] MMIO0    = 0x0006002000000000 [0x0000002000000000]
[    6.028258672,7] PHB[0:1] MMIO1    = 0x000600c080000000 [0x0000000080000000]
[    6.028262944,3] ETU reset: 0
[    6.028793440,3] Version reg: 0x000000a400000001
[    6.028851728,5] PHB: Chip 0 Found PHB4 PBCQ1 Stack 1 at /xscom@603fc00000000/pbcq@4011000/stack@1
[    6.028906176,7] PHB[0:2] X[PE]=0x04011000/0x04011080 X[PCI]=0x0e010800/0x0e010880 X[ETU]=0x0e010940
[    6.028910336,3] PHB[0:2] No PHB BAR set ! Overriding
[    6.028938784,3] PHB[0:2] REGS     = 0x000600c3c0200000 [4k]
[    6.028972768,3] PHB[0:2] No IRQ BAR set ! Overriding
[    6.029000224,3] PHB[0:2] ESB      = 0x000600c340000000 [...]
[    6.029029920,3] PHB[0:2] No MMIO BAR set ! Overriding
[    6.029058192,7] PHB[0:2] MMIO0    = 0x0006004000000000 [0x0000002000000000]
[    6.029061984,7] PHB[0:2] MMIO1    = 0x000600c100000000 [0x0000000080000000]
[    6.029066256,3] ETU reset: 0
[    6.029600304,3] Version reg: 0x000000a400000001
[    6.029649152,5] PHB: Chip 0 Found PHB4 PBCQ2 Stack 0 at /xscom@603fc00000000/pbcq@4011400/stack@0
[    6.029702656,7] PHB[0:3] X[PE]=0x04011400/0x04011440 X[PCI]=0x0f010800/0x0f010840 X[ETU]=0x0f010900
[    6.029706864,3] PHB[0:3] No PHB BAR set ! Overriding
[    6.029735344,3] PHB[0:3] REGS     = 0x000600c3c0300000 [4k]
[    6.029767008,3] PHB[0:3] No IRQ BAR set ! Overriding
[    6.029793920,3] PHB[0:3] ESB      = 0x000600c360000000 [...]
[    6.029824400,3] PHB[0:3] No MMIO BAR set ! Overriding
[    6.029853888,7] PHB[0:3] MMIO0    = 0x0006006000000000 [0x0000002000000000]
[    6.029857728,7] PHB[0:3] MMIO1    = 0x000600c180000000 [0x0000000080000000]
[    6.029862016,3] ETU reset: 0
[    6.030392928,3] Version reg: 0x000000a400000001
[    6.030445024,5] PHB: Chip 8 Found PHB4 PBCQ0 Stack 0 at /xscom@623fc00000000/pbcq@4010c00/stack@0
[    6.030499088,7] PHB[8:0] X[PE]=0x04010c00/0x04010c40 X[PCI]=0x0d010800/0x0d010840 X[ETU]=0x0d010900
[    6.030503136,3] PHB[8:0] No PHB BAR set ! Overriding
[    6.030532240,3] PHB[8:0] REGS     = 0x000620c3c0000000 [4k]
[    6.030564016,3] PHB[8:0] No IRQ BAR set ! Overriding
[    6.030590656,3] PHB[8:0] ESB      = 0x000620c300000000 [...]
[    6.030620672,3] PHB[8:0] No MMIO BAR set ! Overriding
[    6.030648928,7] PHB[8:0] MMIO0    = 0x0006200000000000 [0x0000002000000000]
[    6.030652560,7] PHB[8:0] MMIO1    = 0x000620c000000000 [0x0000000080000000]
[    6.030656624,3] ETU reset: 0
[    6.031185760,3] Version reg: 0x000000a400000001
[    6.031240352,5] PHB: Chip 8 Found PHB4 PBCQ1 Stack 0 at /xscom@623fc00000000/pbcq@4011000/stack@0
[    6.031295168,7] PHB[8:1] X[PE]=0x04011000/0x04011040 X[PCI]=0x0e010800/0x0e010840 X[ETU]=0x0e010900
[    6.031299216,3] PHB[8:1] No PHB BAR set ! Overriding
[    6.031327392,3] PHB[8:1] REGS     = 0x000620c3c0100000 [4k]
[    6.031359088,3] PHB[8:1] No IRQ BAR set ! Overriding
[    6.031385872,3] PHB[8:1] ESB      = 0x000620c320000000 [...]
[    6.031418528,3] PHB[8:1] No MMIO BAR set ! Overriding
[    6.031446800,7] PHB[8:1] MMIO0    = 0x0006202000000000 [0x0000002000000000]
[    6.031450464,7] PHB[8:1] MMIO1    = 0x000620c080000000 [0x0000000080000000]
[    6.031454576,3] ETU reset: 0
[    6.031985120,3] Version reg: 0x000000a400000001
[    6.032046352,5] PHB: Chip 8 Found PHB4 PBCQ1 Stack 1 at /xscom@623fc00000000/pbcq@4011000/stack@1
[    6.032106464,7] PHB[8:2] X[PE]=0x04011000/0x04011080 X[PCI]=0x0e010800/0x0e010880 X[ETU]=0x0e010940
[    6.032110512,3] PHB[8:2] No PHB BAR set ! Overriding
[    6.032140224,3] PHB[8:2] REGS     = 0x000620c3c0200000 [4k]
[    6.032169776,3] PHB[8:2] No IRQ BAR set ! Overriding
[    6.032198176,3] PHB[8:2] ESB      = 0x000620c340000000 [...]
[    6.032232880,3] PHB[8:2] No MMIO BAR set ! Overriding
[    6.032261424,7] PHB[8:2] MMIO0    = 0x0006204000000000 [0x0000002000000000]
[    6.032265040,7] PHB[8:2] MMIO1    = 0x000620c100000000 [0x0000000080000000]
[    6.032269248,3] ETU reset: 0
[    6.032798560,3] Version reg: 0x000000a400000001
[    6.032861056,5] PHB: Chip 8 Found PHB4 PBCQ2 Stack 0 at /xscom@623fc00000000/pbcq@4011400/stack@0
[    6.032921488,7] PHB[8:3] X[PE]=0x04011400/0x04011440 X[PCI]=0x0f010800/0x0f010840 X[ETU]=0x0f010900
[    6.032925536,3] PHB[8:3] No PHB BAR set ! Overriding
[    6.032954736,3] PHB[8:3] REGS     = 0x000620c3c0300000 [4k]
[    6.032993360,3] PHB[8:3] No IRQ BAR set ! Overriding
[    6.033034592,3] PHB[8:3] ESB      = 0x000620c360000000 [...]
[    6.033065024,3] PHB[8:3] No MMIO BAR set ! Overriding
[    6.033092720,7] PHB[8:3] MMIO0    = 0x0006206000000000 [0x0000002000000000]
[    6.033096352,7] PHB[8:3] MMIO1    = 0x000620c180000000 [0x0000000080000000]
[    6.033100432,3] ETU reset: 0
[    6.033630240,3] Version reg: 0x000000a400000001
[    6.033691136,5] PHB: Chip 8 Found PHB4 PBCQ2 Stack 1 at /xscom@623fc00000000/pbcq@4011400/stack@1
[    6.033751936,7] PHB[8:4] X[PE]=0x04011400/0x04011480 X[PCI]=0x0f010800/0x0f010880 X[ETU]=0x0f010940
[    6.033755984,3] PHB[8:4] No PHB BAR set ! Overriding
[    6.033785376,3] PHB[8:4] REGS     = 0x000620c3c0400000 [4k]
[    6.033814992,3] PHB[8:4] No IRQ BAR set ! Overriding
[    6.033842544,3] PHB[8:4] ESB      = 0x000620c380000000 [...]
[    6.033883344,3] PHB[8:4] No MMIO BAR set ! Overriding
[    6.033911664,7] PHB[8:4] MMIO0    = 0x0006208000000000 [0x0000002000000000]
[    6.033915296,7] PHB[8:4] MMIO1    = 0x000620c200000000 [0x0000000080000000]
[    6.033919392,3] ETU reset: 0
[    6.034451872,3] Version reg: 0x000000a400000001
[    6.034512848,5] PHB: Chip 8 Found PHB4 PBCQ2 Stack 2 at /xscom@623fc00000000/pbcq@4011400/stack@2
[    6.034579200,7] PHB[8:5] X[PE]=0x04011400/0x040114c0 X[PCI]=0x0f010800/0x0f0108c0 X[ETU]=0x0f010980
[    6.034583248,3] PHB[8:5] No PHB BAR set ! Overriding
[    6.034611200,3] PHB[8:5] REGS     = 0x000620c3c0500000 [4k]
[    6.034642576,3] PHB[8:5] No IRQ BAR set ! Overriding
[    6.034675072,3] PHB[8:5] ESB      = 0x000620c3a0000000 [...]
[    6.034706064,3] PHB[8:5] No MMIO BAR set ! Overriding
[    6.034733792,7] PHB[8:5] MMIO0    = 0x000620a000000000 [0x0000002000000000]
[    6.034737440,7] PHB[8:5] MMIO1    = 0x000620c280000000 [0x0000000080000000]
[    6.034741520,3] ETU reset: 0
[    6.035284048,3] Version reg: 0x000000a400000001
[    6.035373024,7] PHB#0000:00:00.0 PCI: Registered PHB
[    6.035376752,6] PHB#0000[0:0]: Found /pciex@600c3c0000000 @0x600c3c0000000
[    6.035380768,6] PHB#0000[0:0]:   M32 [0x000600c000000000..0x000600c07fffffff]
[    6.035384032,6] PHB#0000[0:0]:   M64 [0x0006000000000000..0x0006001fffffffff]
[    6.035387472,3] PHB#0000[0:0]: Base location code not found !
[    6.035438080,7] PHB#0000[0:0]: Core revision 0xa40001
[    6.035440688,7] PHB#0000[0:0]: Found 512 max PEs and 4096 IRQs 
[    6.035443840,6] PHB#0000[0:0]: Max link speed: GEN2
[    6.035796464,7] PHB#0000[0:0]: Initializing PHB4...
[    6.035799264,7] PHB#0000[0:0]: Default system config: 0x4410000040400000
[    6.035802320,7] PHB#0000[0:0]: New system config    : 0x4410000020400000
[    6.035805360,7] PHB#0000[0:0]: Initial PHB CRESET is 0xe000000000000000
[    6.035809616,7] PHB#0000[0:0]: Reset state SRC_ID: 0ff8000000000000
[    6.036851824,7] PHB#0000[0:0]: Initialization complete
[    6.036854880,7] IRQ: Registering fe000..feff7 ops @0x300a3af8 (data 0x0)
[    6.036858288,7] IRQ: Registering feff8..fefff ops @0x300a3af8 (data 0x30552540)
[    6.036879504,7] PHB#0001:00:00.0 PCI: Registered PHB
[    6.036882672,6] PHB#0001[0:1]: Found /pciex@600c3c0100000 @0x600c3c0100000
[    6.036886688,6] PHB#0001[0:1]:   M32 [0x000600c080000000..0x000600c0ffffffff]
[    6.036889744,6] PHB#0001[0:1]:   M64 [0x0006002000000000..0x0006003fffffffff]
[    6.036893088,3] PHB#0001[0:1]: Base location code not found !
[    6.036950752,7] PHB#0001[0:1]: Core revision 0xa40001
[    6.036953376,7] PHB#0001[0:1]: Found 256 max PEs and 2048 IRQs 
[    6.036956224,6] PHB#0001[0:1]: Max link speed: GEN2
[    6.037273792,7] PHB#0001[0:1]: Initializing PHB4...
[    6.037276480,7] PHB#0001[0:1]: Default system config: 0x4210000040200000
[    6.037279536,7] PHB#0001[0:1]: New system config    : 0x4210000020200000
[    6.037282576,7] PHB#0001[0:1]: Initial PHB CRESET is 0xe000000000000000
[    6.037285936,7] PHB#0001[0:1]: Reset state SRC_ID: 0ff8000000000000
[    6.038165296,7] PHB#0001[0:1]: Initialization complete
[    6.038168080,7] IRQ: Registering fd800..fdff7 ops @0x300a3af8 (data 0x0)
[    6.038171392,7] IRQ: Registering fdff8..fdfff ops @0x300a3af8 (data 0x30597f70)
[    6.038192752,7] PHB#0002:00:00.0 PCI: Registered PHB
[    6.038196000,6] PHB#0002[0:2]: Found /pciex@600c3c0200000 @0x600c3c0200000
[    6.038199936,6] PHB#0002[0:2]:   M32 [0x000600c100000000..0x000600c17fffffff]
[    6.038202992,6] PHB#0002[0:2]:   M64 [0x0006004000000000..0x0006005fffffffff]
[    6.038206496,3] PHB#0002[0:2]: Base location code not found !
[    6.038257712,7] PHB#0002[0:2]: Core revision 0xa40001
[    6.038260288,7] PHB#0002[0:2]: Found 256 max PEs and 2048 IRQs 
[    6.038263088,6] PHB#0002[0:2]: Max link speed: GEN2
[    6.038582912,7] PHB#0002[0:2]: Initializing PHB4...
[    6.038585584,7] PHB#0002[0:2]: Default system config: 0x4210000040200000
[    6.038588592,7] PHB#0002[0:2]: New system config    : 0x4210000020200000
[    6.038591504,7] PHB#0002[0:2]: Initial PHB CRESET is 0xe000000000000000
[    6.038594928,7] PHB#0002[0:2]: Reset state SRC_ID: 0ff8000000000000
[    6.039474000,7] PHB#0002[0:2]: Initialization complete
[    6.039476768,7] IRQ: Registering fd000..fd7f7 ops @0x300a3af8 (data 0x0)
[    6.039480112,7] IRQ: Registering fd7f8..fd7ff ops @0x300a3af8 (data 0x305dd9a0)
[    6.039501392,7] PHB#0003:00:00.0 PCI: Registered PHB
[    6.039504432,6] PHB#0003[0:3]: Found /pciex@600c3c0300000 @0x600c3c0300000
[    6.039508352,6] PHB#0003[0:3]:   M32 [0x000600c180000000..0x000600c1ffffffff]
[    6.039511440,6] PHB#0003[0:3]:   M64 [0x0006006000000000..0x0006007fffffffff]
[    6.039514784,3] PHB#0003[0:3]: Base location code not found !
[    6.039574320,7] PHB#0003[0:3]: Core revision 0xa40001
[    6.039576896,7] PHB#0003[0:3]: Found 512 max PEs and 4096 IRQs 
[    6.039579712,6] PHB#0003[0:3]: Max link speed: GEN2
[    6.039928624,7] PHB#0003[0:3]: Initializing PHB4...
[    6.039931344,7] PHB#0003[0:3]: Default system config: 0x4410000040400000
[    6.039934384,7] PHB#0003[0:3]: New system config    : 0x4410000020400000
[    6.039937280,7] PHB#0003[0:3]: Initial PHB CRESET is 0xe000000000000000
[    6.039940688,7] PHB#0003[0:3]: Reset state SRC_ID: 0ff8000000000000
[    6.040980736,7] PHB#0003[0:3]: Initialization complete
[    6.040983504,7] IRQ: Registering fc000..fcff7 ops @0x300a3af8 (data 0x0)
[    6.040986832,7] IRQ: Registering fcff8..fcfff ops @0x300a3af8 (data 0x306233d0)
[    6.041007952,7] PHB#0030:00:00.0 PCI: Registered PHB
[    6.041011136,6] PHB#0030[8:0]: Found /pciex@620c3c0000000 @0x620c3c0000000
[    6.041015120,6] PHB#0030[8:0]:   M32 [0x000620c000000000..0x000620c07fffffff]
[    6.041018224,6] PHB#0030[8:0]:   M64 [0x0006200000000000..0x0006201fffffffff]
[    6.041021664,3] PHB#0030[8:0]: Base location code not found !
[    6.041072592,7] PHB#0030[8:0]: Core revision 0xa40001
[    6.041075040,7] PHB#0030[8:0]: Found 512 max PEs and 4096 IRQs 
[    6.041077856,6] PHB#0030[8:0]: Max link speed: GEN2
[    6.041424224,7] PHB#0030[8:0]: Initializing PHB4...
[    6.041426784,7] PHB#0030[8:0]: Default system config: 0x4410000040400000
[    6.041429696,7] PHB#0030[8:0]: New system config    : 0x4410000020400000
[    6.041432544,7] PHB#0030[8:0]: Initial PHB CRESET is 0xe000000000000000
[    6.041435696,7] PHB#0030[8:0]: Reset state SRC_ID: 0ff8000000000000
[    6.042321184,7] PHB#0030[8:0]: Initialization complete
[    6.042323984,7] IRQ: Registering 1fe000..1feff7 ops @0x300a3af8 (data 0x0)
[    6.042327424,7] IRQ: Registering 1feff8..1fefff ops @0x300a3af8 (data 0x30668e00)
[    6.042348656,7] PHB#0031:00:00.0 PCI: Registered PHB
[    6.042351792,6] PHB#0031[8:1]: Found /pciex@620c3c0100000 @0x620c3c0100000
[    6.042355712,6] PHB#0031[8:1]:   M32 [0x000620c080000000..0x000620c0ffffffff]
[    6.042358784,6] PHB#0031[8:1]:   M64 [0x0006202000000000..0x0006203fffffffff]
[    6.042362176,3] PHB#0031[8:1]: Base location code not found !
[    6.042420960,7] PHB#0031[8:1]: Core revision 0xa40001
[    6.042423408,7] PHB#0031[8:1]: Found 256 max PEs and 2048 IRQs 
[    6.042426208,6] PHB#0031[8:1]: Max link speed: GEN2
[    6.042738944,7] PHB#0031[8:1]: Initializing PHB4...
[    6.042741440,7] PHB#0031[8:1]: Default system config: 0x4210000040200000
[    6.042744320,7] PHB#0031[8:1]: New system config    : 0x4210000020200000
[    6.042747168,7] PHB#0031[8:1]: Initial PHB CRESET is 0xe000000000000000
[    6.042750304,7] PHB#0031[8:1]: Reset state SRC_ID: 0ff8000000000000
[    6.043549536,7] PHB#0031[8:1]: Initialization complete
[    6.043552304,7] IRQ: Registering 1fd800..1fdff7 ops @0x300a3af8 (data 0x0)
[    6.043555808,7] IRQ: Registering 1fdff8..1fdfff ops @0x300a3af8 (data 0x306ae830)
[    6.043576896,7] PHB#0032:00:00.0 PCI: Registered PHB
[    6.043579856,6] PHB#0032[8:2]: Found /pciex@620c3c0200000 @0x620c3c0200000
[    6.043583792,6] PHB#0032[8:2]:   M32 [0x000620c100000000..0x000620c17fffffff]
[    6.043586896,6] PHB#0032[8:2]:   M64 [0x0006204000000000..0x0006205fffffffff]
[    6.043590256,3] PHB#0032[8:2]: Base location code not found !
[    6.043649248,7] PHB#0032[8:2]: Core revision 0xa40001
[    6.043651696,7] PHB#0032[8:2]: Found 256 max PEs and 2048 IRQs 
[    6.043654496,6] PHB#0032[8:2]: Max link speed: GEN2
[    6.043969712,7] PHB#0032[8:2]: Initializing PHB4...
[    6.043972256,7] PHB#0032[8:2]: Default system config: 0x4210000040200000
[    6.043975120,7] PHB#0032[8:2]: New system config    : 0x4210000020200000
[    6.043977936,7] PHB#0032[8:2]: Initial PHB CRESET is 0xe000000000000000
[    6.043981088,7] PHB#0032[8:2]: Reset state SRC_ID: 0ff8000000000000
[    6.044780336,7] PHB#0032[8:2]: Initialization complete
[    6.044783120,7] IRQ: Registering 1fd000..1fd7f7 ops @0x300a3af8 (data 0x0)
[    6.044786544,7] IRQ: Registering 1fd7f8..1fd7ff ops @0x300a3af8 (data 0x306f4260)
[    6.044807856,7] PHB#0033:00:00.0 PCI: Registered PHB
[    6.044810976,6] PHB#0033[8:3]: Found /pciex@620c3c0300000 @0x620c3c0300000
[    6.044814944,6] PHB#0033[8:3]:   M32 [0x000620c180000000..0x000620c1ffffffff]
[    6.044818016,6] PHB#0033[8:3]:   M64 [0x0006206000000000..0x0006207fffffffff]
[    6.044821376,3] PHB#0033[8:3]: Base location code not found !
[    6.044880416,7] PHB#0033[8:3]: Core revision 0xa40001
[    6.044882928,7] PHB#0033[8:3]: Found 512 max PEs and 4096 IRQs 
[    6.044885728,6] PHB#0033[8:3]: Max link speed: GEN2
[    6.045229584,7] PHB#0033[8:3]: Initializing PHB4...
[    6.045232128,7] PHB#0033[8:3]: Default system config: 0x4410000040400000
[    6.045235040,7] PHB#0033[8:3]: New system config    : 0x4410000020400000
[    6.045237888,7] PHB#0033[8:3]: Initial PHB CRESET is 0xe000000000000000
[    6.045240992,7] PHB#0033[8:3]: Reset state SRC_ID: 0ff8000000000000
[    6.046126560,7] PHB#0033[8:3]: Initialization complete
[    6.046129344,7] IRQ: Registering 1fc000..1fcff7 ops @0x300a3af8 (data 0x0)
[    6.046132800,7] IRQ: Registering 1fcff8..1fcfff ops @0x300a3af8 (data 0x30739c90)
[    6.046154080,7] PHB#0034:00:00.0 PCI: Registered PHB
[    6.046157184,6] PHB#0034[8:4]: Found /pciex@620c3c0400000 @0x620c3c0400000
[    6.046161088,6] PHB#0034[8:4]:   M32 [0x000620c200000000..0x000620c27fffffff]
[    6.046164208,6] PHB#0034[8:4]:   M64 [0x0006208000000000..0x0006209fffffffff]
[    6.046167520,3] PHB#0034[8:4]: Base location code not found !
[    6.046224224,7] PHB#0034[8:4]: Core revision 0xa40001
[    6.046226640,7] PHB#0034[8:4]: Found 256 max PEs and 2048 IRQs 
[    6.046229504,6] PHB#0034[8:4]: Max link speed: GEN2
[    6.046542336,7] PHB#0034[8:4]: Initializing PHB4...
[    6.046545008,7] PHB#0034[8:4]: Default system config: 0x4210000040200000
[    6.046548016,7] PHB#0034[8:4]: New system config    : 0x4210000020200000
[    6.046550848,7] PHB#0034[8:4]: Initial PHB CRESET is 0xe000000000000000
[    6.046553952,7] PHB#0034[8:4]: Reset state SRC_ID: 0ff8000000000000
[    6.047353232,7] PHB#0034[8:4]: Initialization complete
[    6.047356112,7] IRQ: Registering 1fb800..1fbff7 ops @0x300a3af8 (data 0x0)
[    6.047359632,7] IRQ: Registering 1fbff8..1fbfff ops @0x300a3af8 (data 0x3077f6c0)
[    6.047380784,7] PHB#0035:00:00.0 PCI: Registered PHB
[    6.047383936,6] PHB#0035[8:5]: Found /pciex@620c3c0500000 @0x620c3c0500000
[    6.047387904,6] PHB#0035[8:5]:   M32 [0x000620c280000000..0x000620c2ffffffff]
[    6.047390960,6] PHB#0035[8:5]:   M64 [0x000620a000000000..0x000620bfffffffff]
[    6.047394288,3] PHB#0035[8:5]: Base location code not found !
[    6.047453328,7] PHB#0035[8:5]: Core revision 0xa40001
[    6.047455744,7] PHB#0035[8:5]: Found 256 max PEs and 2048 IRQs 
[    6.047458624,6] PHB#0035[8:5]: Max link speed: GEN2
[    6.047773520,7] PHB#0035[8:5]: Initializing PHB4...
[    6.047776064,7] PHB#0035[8:5]: Default system config: 0x4210000040200000
[    6.047778976,7] PHB#0035[8:5]: New system config    : 0x4210000020200000
[    6.047781840,7] PHB#0035[8:5]: Initial PHB CRESET is 0xe000000000000000
[    6.047784960,7] PHB#0035[8:5]: Reset state SRC_ID: 0ff8000000000000
[    6.048584000,7] PHB#0035[8:5]: Initialization complete
[    6.048586832,7] IRQ: Registering 1fb000..1fb7f7 ops @0x300a3af8 (data 0x0)
[    6.048590352,7] IRQ: Registering 1fb7f8..1fb7ff ops @0x300a3af8 (data 0x307c50f0)
[    6.048700208,5] PCI: Resetting PHBs...
[    6.048748688,7] PHB#0000[0:0]: FRESET: Starts
[    6.048750432,7] PHB#0002[0:2]: FRESET: Starts
[    6.048749296,7] PHB#0001[0:1]: FRESET: Starts
[    6.048752560,7] PHB#0000[0:0]: hp_status=0x0020000000000000, dlp_train_ctl=0x0000000101000000
[    6.048754016,7] PHB#0001[0:1]: hp_status=0x0000000000000000, dlp_train_ctl=0x0000000101000000
[    6.048759520,7] PHB#0000[0:0]: FRESET: Prepare for link down
[    6.048760928,7] PHB#0003[0:3]: FRESET: Starts
[    6.048761024,7] PHB#0001[0:1]: FRESET: Prepare for link down
[    6.048753024,7] PHB#0002[0:2]: hp_status=0x0000000000000000, dlp_train_ctl=0x0000000101000000
[    6.048773008,7] PHB#0001[0:1]: FRESET: Assert skipped
[    6.048782384,7] PHB#0002[0:2]: FRESET: Prepare for link down
[    6.048775360,7] PHB#0030[8:0]: FRESET: Starts
[    6.048798416,7] PHB#0002[0:2]: FRESET: Assert skipped
[    6.048788512,7] PHB#0001[0:1]: FRESET: Deassert
[    6.048812944,7] PHB#0002[0:2]: FRESET: Deassert
[    6.048804528,7] PHB#0030[8:0]: hp_status=0x0020000000000000, dlp_train_ctl=0x0000000101000000
[    6.048797376,7] PHB#0031[8:1]: FRESET: Starts
[    6.048769856,7] PHB#0003[0:3]: hp_status=0x0020000000000000, dlp_train_ctl=0x0000000101000000
[    6.048837152,7] PHB#0031[8:1]: hp_status=0x0000000000000000, dlp_train_ctl=0x0000000101000000
[    6.048834160,7] PHB#0030[8:0]: FRESET: Prepare for link down
[    6.048851968,7] PHB#0031[8:1]: FRESET: Prepare for link down
[    6.048858864,7] PHB#0030[8:0]: FRESET: Assert skipped
[    6.048863888,7] PHB#0031[8:1]: FRESET: Assert skipped
[    6.048867296,7] PHB#0030[8:0]: FRESET: Deassert
[    6.048872528,7] PHB#0031[8:1]: FRESET: Deassert
[    6.048845616,7] PHB#0003[0:3]: FRESET: Prepare for link down
[    6.048844064,7] PHB#0033[8:3]: FRESET: Starts
[    6.048884720,7] PHB#0035[8:5]: FRESET: Starts
[    6.048766704,7] PHB#0000[0:0]: FRESET: Assert skipped
[    6.048866080,7] PHB#0034[8:4]: FRESET: Starts
[    6.048895648,7] PHB#0033[8:3]: hp_status=0x0000000000000000, dlp_train_ctl=0x0000000101000000
[    6.048908112,7] PHB#0000[0:0]: FRESET: Deassert
[    6.048905072,7] PHB#0035[8:5]: hp_status=0x0000000000000000, dlp_train_ctl=0x0000000101000000
[    6.048885888,7] PHB#0003[0:3]: FRESET: Assert skipped
[    6.048951856,7] PHB#0035[8:5]: FRESET: Prepare for link down
[    6.048920224,7] PHB#0034[8:4]: hp_status=0x0000000000000000, dlp_train_ctl=0x0000000101000000
[    6.048956624,7] PHB#0035[8:5]: FRESET: Assert skipped
[    6.048822048,7] PHB#0032[8:2]: FRESET: Starts
[    6.048939328,7] PHB#0033[8:3]: FRESET: Prepare for link down
[    6.048977232,7] PHB#0034[8:4]: FRESET: Prepare for link down
[    6.048980096,7] PHB#0035[8:5]: FRESET: Deassert
[    6.048954784,7] PHB#0003[0:3]: FRESET: Deassert
[    6.048989024,7] PHB#0032[8:2]: hp_status=0x0000000000000000, dlp_train_ctl=0x0000000101000000
[    6.049001888,7] PHB#0033[8:3]: FRESET: Assert skipped
[    6.049014832,7] PHB#0034[8:4]: FRESET: Assert skipped
[    6.049030752,7] PHB#0032[8:2]: FRESET: Prepare for link down
[    6.049039232,7] PHB#0033[8:3]: FRESET: Deassert
[    6.049048144,7] PHB#0034[8:4]: FRESET: Deassert
[    6.049056224,7] PHB#0032[8:2]: FRESET: Assert skipped
[    6.049070464,7] PHB#0032[8:2]: FRESET: Deassert
[    6.129550640,7] MBOX-FLASH: Adjusting the window
[    6.129556400,7] LPC-MBOX: Sending BMC interrupt
[    6.231978528,7] FFS: Partition map size: 0x1000
[    6.232753312,7] FLASH: BOOTKERNEL partition doesn't have ECC
[    6.233514272,7] FLASH: BOOTKERNEL partition isn't signed
[    6.233517472,7] FLASH: computed BOOTKERNEL size 13866600
[    7.048819984,7] PHB#0001[0:1]: LINK: Start polling
[    7.048826400,7] PHB#0002[0:2]: LINK: Start polling
[    7.048877488,7] PHB#0030[8:0]: LINK: Start polling
[    7.048882208,7] PHB#0031[8:1]: LINK: Start polling
[    7.048948752,7] PHB#0000[0:0]: LINK: Start polling
[    7.049016992,7] PHB#0035[8:5]: LINK: Start polling
[    7.049019936,7] PHB#0003[0:3]: LINK: Start polling
[    7.049064048,7] PHB#0033[8:3]: LINK: Start polling
[    7.049069584,7] PHB#0034[8:4]: LINK: Start polling
[    7.049072848,7] PHB#0032[8:2]: LINK: Start polling
[    7.100023216,7] PHB#0001[0:1]: LINK: Electrical link detected
[    7.100028848,7] PHB#0002[0:2]: LINK: Electrical link detected
[    7.100084752,7] PHB#0031[8:1]: LINK: Electrical link detected
[    7.100219456,7] PHB#0035[8:5]: LINK: Electrical link detected
[    7.100266784,7] PHB#0033[8:3]: LINK: Electrical link detected
[    7.100272512,7] PHB#0034[8:4]: LINK: Electrical link detected
[    7.100275392,7] PHB#0032[8:2]: LINK: Electrical link detected
[    7.151225904,7] PHB#0001[0:1]: LINK: Link is up
[    7.151231392,7] PHB#0002[0:2]: LINK: Link is up
[    7.151287456,7] PHB#0031[8:1]: LINK: Link is up
[    7.151422368,7] PHB#0035[8:5]: LINK: Link is up
[    7.151469504,7] PHB#0033[8:3]: LINK: Link is up
[    7.151475392,7] PHB#0034[8:4]: LINK: Link is up
[    7.151478304,7] PHB#0032[8:2]: LINK: Link is up
[    9.100083920,7] PHB#0030[8:0]: LINK: Timeout waiting for electrical link
[    9.100086688,7] PHB#0030[8:0]: LINK: DLP train control: 0x0000000101000000
[    9.100089632,7] PHB#0030[8:0]: Retry state 00000301
[    9.100091888,7] PHB#0030[8:0]: FRESET: Assert
[    9.100155872,7] PHB#0000[0:0]: LINK: Timeout waiting for electrical link
[    9.100158832,7] PHB#0000[0:0]: LINK: DLP train control: 0x0000000101000000
[    9.100161728,7] PHB#0000[0:0]: Retry state 00000301
[    9.100164048,7] PHB#0000[0:0]: FRESET: Assert
[    9.100227856,7] PHB#0003[0:3]: LINK: Timeout waiting for electrical link
[    9.100230640,7] PHB#0003[0:3]: LINK: DLP train control: 0x0000000101000000
[    9.100233568,7] PHB#0003[0:3]: Retry state 00000301
[    9.100235872,7] PHB#0003[0:3]: FRESET: Assert
[   10.100094240,7] PHB#0030[8:0]: FRESET: Deassert
[   10.100166272,7] PHB#0000[0:0]: FRESET: Deassert
[   10.100238368,7] PHB#0003[0:3]: FRESET: Deassert
[   11.100096528,7] PHB#0030[8:0]: LINK: Start polling
[   11.100168960,7] PHB#0000[0:0]: LINK: Start polling
[   11.100240928,7] PHB#0003[0:3]: LINK: Start polling
[   12.212038944,5] STB: sb_verify skipped resource 0, secure_mode=0
[   12.212105200,5] STB: tb_measure skipped resource 0, trusted_mode=0
[   12.212152032,7] LPC-MBOX: Sending BMC interrupt
[   12.314573600,7] FFS: Partition map size: 0x1000
[   12.315339360,3] FLASH: Failed to get ROOTFS partition info
[   13.151302480,7] PHB#0030[8:0]: LINK: Timeout waiting for electrical link
[   13.151305248,7] PHB#0030[8:0]: LINK: DLP train control: 0x0000000101000000
[   13.151375392,7] PHB#0000[0:0]: LINK: Timeout waiting for electrical link
[   13.151378352,7] PHB#0000[0:0]: LINK: DLP train control: 0x0000000101000000
[   13.151448640,7] PHB#0003[0:3]: LINK: Timeout waiting for electrical link
[   13.151451408,7] PHB#0003[0:3]: LINK: DLP train control: 0x0000000101000000
[   13.153193536,5] PCI: Probing slots...
[   13.153236272,7] PHB#0000:00:00.0 Link down
[   13.153236528,7] PHB#0001:00:00.0 Link up at x8 width
[   13.153239072,7] PHB#0000:00:00.0 Scanning (upstream only)...
[   13.153241104,7] PHB#0001:00:00.0 Scanning (upstream+downsteam)...
[   13.153238224,7] PHB#0003:00:00.0 Link down
[   13.153237328,7] PHB#0002:00:00.0 Link up at x2 width
[   13.153246816,7] PHB#0003:00:00.0 Scanning (upstream only)...
[   13.153247856,7] PHB#0002:00:00.0 Scanning (upstream+downsteam)...
[   13.153250096,7] PHB#0001:00:00.0 Found VID:1014 DEV:04c1 TYP:4 MF- BR+ EX+
[   13.153250112,7] PHB#0000:00:00.0 Found VID:1014 DEV:04c1 TYP:4 MF- BR+ EX+
[   13.153256592,7] PHB#0002:00:00.0 Found VID:1014 DEV:04c1 TYP:4 MF- BR+ EX+
[   13.153253808,7] PHB#0003:00:00.0 Found VID:1014 DEV:04c1 TYP:4 MF- BR+ EX+
[   13.153277392,7] PHB#0002:00:00.0 Bus 01..ff  scanning...
[   13.153282624,7] PHB#0032:00:00.0 Link up at x1 width
[   13.153248464,7] PHB#0030:00:00.0 Link down
[   13.153264656,7] PHB#0001:00:00.0 Bus 01..ff  scanning...
[   13.153302896,7] PHB#0034:00:00.0 Link up at x4 width
[   13.153304160,7] PHB#0035:00:00.0 Link up at x1 width
[   13.153300176,7] PHB#0002:00:00.0 waiting for link... 
[   13.153283248,7] PHB#0033:00:00.0 Link up at x8 width
[   13.153333248,7] PHB#0034:00:00.0 Scanning (upstream+downsteam)...
[   13.153261696,7] PHB#0031:00:00.0 Link up at x8 width
[   13.153300848,7] PHB#0032:00:00.0 Scanning (upstream+downsteam)...
[   13.153342752,7] PHB#0035:00:00.0 Scanning (upstream+downsteam)...
[   13.153351536,7] PHB#0002:00:00.0 end wait for link...
[   13.153320176,7] PHB#0001:00:00.0 waiting for link... 
[   13.153413040,7] PHB#0035:00:00.0 Found VID:1014 DEV:04c1 TYP:4 MF- BR+ EX+
[   13.153388912,7] PHB#0031:00:00.0 Scanning (upstream+downsteam)...
[   13.153424096,7] PHB#0001:00:00.0 end wait for link...
[   13.153384976,7] PHB#0034:00:00.0 Found VID:1014 DEV:04c1 TYP:4 MF- BR+ EX+
[   13.153365792,7] PHB#0033:00:00.0 Scanning (upstream+downsteam)...
[   13.153467360,7] PHB#0034:00:00.0 Bus 01..ff  scanning...
[   13.153306480,7] PHB#0030:00:00.0 Scanning (upstream only)...
[   13.153435200,7] PHB#0035:00:00.0 Bus 01..ff  scanning...
[   13.153404432,7] PHB#0032:00:00.0 Found VID:1014 DEV:04c1 TYP:4 MF- BR+ EX+
[   13.153489760,7] PHB#0034:00:00.0 waiting for link... 
[   13.153484384,7] PHB#0033:00:00.0 Found VID:1014 DEV:04c1 TYP:4 MF- BR+ EX+
[   13.153517536,7] PHB#0034:00:00.0 end wait for link...
[   13.153536272,7] PHB#0033:00:00.0 Bus 01..ff  scanning...
[   13.153497792,7] PHB#0030:00:00.0 Found VID:1014 DEV:04c1 TYP:4 MF- BR+ EX+
[   13.153501248,7] PHB#0035:00:00.0 waiting for link... 
[   13.153556848,7] PHB#0033:00:00.0 waiting for link... 
[   13.153443872,7] PHB#0031:00:00.0 Found VID:1014 DEV:04c1 TYP:4 MF- BR+ EX+
[   13.153510416,7] PHB#0032:00:00.0 Bus 01..ff  scanning...
[   13.153580880,7] PHB#0031:00:00.0 Bus 01..ff  scanning...
[   13.153587040,7] PHB#0032:00:00.0 waiting for link... 
[   13.153590992,7] PHB#0031:00:00.0 waiting for link... 
[   13.153594016,7] PHB#0032:00:00.0 end wait for link...
[   13.153597632,7] PHB#0031:00:00.0 end wait for link...
[   13.153569280,7] PHB#0035:00:00.0 end wait for link...
[   13.153574272,7] PHB#0033:00:00.0 end wait for link...
[   13.204621728,7] PHB#0002:01:00.0 Found VID:1b4b DEV:9235 TYP:1 MF- BR- EX+
[   13.204756848,7] PHB#0034:01:00.0 Found VID:14e4 DEV:1657 TYP:0 MF- BR- EX+
[   13.204814640,7] PHB#0031:01:00.0 Found VID:1000 DEV:005d TYP:0 MF- BR- EX+
[   13.204816672,7] PHB#0032:01:00.0 Found VID:1912 DEV:0014 TYP:0 MF- BR- EX+
[   13.204820944,7] PHB#0035:01:00.0 Found VID:1a03 DEV:1150 TYP:7 MF- BR+ EX+
[   13.204829440,7] PHB#0035:01:00.0 Bus 02..ff  scanning...
[   13.204836832,7] PHB#0001:01:00.0 Found VID:15b3 DEV:1007 TYP:0 MF- BR- EX+
[   13.204844048,7] PHB#0035:02:00.0 Found VID:1a03 DEV:2000 TYP:1 MF- BR- EX-
[   13.204890912,7] PHB#0033:01:00.0 Found VID:15b3 DEV:1015 TYP:0 MF+ BR- EX+
[   13.205008016,7] PHB#0033:01:00.1 Found VID:15b3 DEV:1015 TYP:0 MF+ BR- EX+
[   13.209629392,7] PCI Summary:
[   13.209638176,5] PHB#0000:00:00.0 [ROOT] 1014 04c1 R:00 C:060400 B:00..00 
[   13.209709952,5] PHB#0001:00:00.0 [ROOT] 1014 04c1 R:00 C:060400 B:01..01 
[   13.209791600,5] PHB#0001:01:00.0 [EP  ] 15b3 1007 R:00 C:020000 (      ethernet) 
[   13.209850240,5] PHB#0002:00:00.0 [ROOT] 1014 04c1 R:00 C:060400 B:01..01 
[   13.209897872,5] PHB#0002:01:00.0 [LGCY] 1b4b 9235 R:11 C:010601 (          sata) 
[   13.209946864,5] PHB#0003:00:00.0 [ROOT] 1014 04c1 R:00 C:060400 B:00..00 
[   13.209990432,5] PHB#0030:00:00.0 [ROOT] 1014 04c1 R:00 C:060400 B:00..00 
[   13.210035824,5] PHB#0031:00:00.0 [ROOT] 1014 04c1 R:00 C:060400 B:01..01 
[   13.210086752,5] PHB#0031:01:00.0 [EP  ] 1000 005d R:02 C:010400 (          raid) 
[   13.210132480,5] PHB#0032:00:00.0 [ROOT] 1014 04c1 R:00 C:060400 B:01..01 
[   13.210185248,5] PHB#0032:01:00.0 [EP  ] 1912 0014 R:03 C:0c0330 (      usb-xhci) 
[   13.210237072,5] PHB#0033:00:00.0 [ROOT] 1014 04c1 R:00 C:060400 B:01..01 
[   13.210296768,5] PHB#0033:01:00.0 [EP  ] 15b3 1015 R:00 C:020000 (      ethernet) 
[   13.210359888,5] PHB#0033:01:00.1 [EP  ] 15b3 1015 R:00 C:020000 (      ethernet) 
[   13.210410368,5] PHB#0034:00:00.0 [ROOT] 1014 04c1 R:00 C:060400 B:01..01 
[   13.210470464,5] PHB#0034:01:00.0 [EP  ] 14e4 1657 R:01 C:020000 (      ethernet) 
[   13.210526928,5] PHB#0035:00:00.0 [ROOT] 1014 04c1 R:00 C:060400 B:01..02 
[   13.210573504,5] PHB#0035:01:00.0 [ETOX] 1a03 1150 R:04 C:060400 B:02..02 
[   13.210672896,5] PHB#0035:02:00.0 [PCID] 1a03 2000 R:41 C:030000 (           vga) 
[   13.230708848,5] irq ffff0 name: psi:fsp (7/0)
[   13.230748688,5] irq ffff1 name: psi:occ (7/8)
[   13.230777456,5] irq ffff2 name: psi:fsi (7/16)
[   13.230816208,5] irq ffff3 name: psi:lpchc (9/24)
[   13.230849104,5] irq ffff4 name: psi:local_err (13/34)
[   13.230886384,5] irq ffff5 name: psi:global_err (14/48)
[   13.230913536,5] irq ffff6 name: psi:external (12/63)
[   13.230942064,5] irq ffff7 name: psi:lpc_serirq_mux0 (19/76)
[   13.230978624,5] irq ffff8 name: psi:lpc_serirq_mux1 (19/96)
[   13.231011792,5] irq ffffa name: psi:lpc_serirq_mux3 (19/116)
[   13.231043360,5] irq ffffb name: psi:i2c (7/136)
[   13.231073552,5] irq ffffc name: psi:dio (7/144)
[   13.231099472,5] irq ffffd name: psi:psu (7/152)
[   13.231125232,5] irq 1ffff0 name: psi:fsp (7/160)
[   13.231152560,5] irq 1ffff1 name: psi:occ (7/168)
[   13.231180544,5] irq 1ffff2 name: psi:fsi (7/176)
[   13.231208976,5] irq 1ffff3 name: psi:lpchc (9/184)
[   13.231237728,5] irq 1ffff4 name: psi:local_err (13/194)
[   13.231268704,5] irq 1ffff5 name: psi:global_err (14/208)
[   13.231297072,5] irq 1ffff6 name: psi:external (12/223)
[   13.231329168,5] irq 1ffffb name: psi:i2c (7/236)
[   13.231362416,5] irq 1ffffc name: psi:dio (7/244)
[   13.231388768,5] irq 1ffffd name: psi:psu (7/252)
[   13.231690496,5] Releasing unused memory:
[   13.231736608,5]     ibm,firmware-heap: 5359264/13631488 used
[   13.231769040,5]     ibm,firmware-allocs-memory@200000000000: 22552576/274835963904 used
[   13.231823296,5]     ibm,firmware-allocs-memory@0: 25706496/273506369536 used
[   13.231869248,5]     ibm,firmware-allocs-memory@200000000000: 0/33554432 used
[   13.231925040,5] Reserved regions:
[   13.231947888,5]   0x203ffdc00000..203ffdffffff : ibm,homer-image
[   13.231983216,5]   0x203ffd800000..203ffdbfffff : ibm,homer-image
[   13.232023824,5]   0x000031c00000..000033d7ffff : ibm,firmware-stacks
[   13.232062592,5]   0x000031000000..000031bfffff : ibm,firmware-data
[   13.232103584,5]   0x000030300000..000030ffffff : ibm,firmware-heap
[   13.232142048,5]   0x000030000000..0000302fffff : ibm,firmware-code
[   13.232181920,5]   0x200000000000..200001581fff : ibm,firmware-allocs-memory@200000000000
[   13.232245072,5]   0x203ffd460000..203ffd6842ae : ibm,hbrt-code-image
[   13.232283168,5]   0x203ffd690000..203ffd6f0ffe : ibm,hbrt-target-image
[   13.232325472,5]   0x203ffd700000..203ffd7ffffe : ibm,hbrt-vpd-image
[   13.232364944,5]   0x000051c00000..000053483fff : ibm,firmware-allocs-memory@0
[   13.232420192,7] BT: seq 0x07 netfn 0x06 cmd 0x24: Message sent to host
[   13.232447568,5] INIT: Waiting for kernel...
[   13.232475680,5] INIT: Kernel loaded, size: 13866600 bytes (0 = unknown preload)
[   13.232515728,5] INIT: 64-bit LE kernel discovered
[   13.232544144,5] INIT: 64-bit kernel entry at 0x20010000, size 0xd39668
[   13.240417632,5] Free space in HEAP memory regions:
[   13.240488672,5] Region ibm,firmware-heap free: 765d00
[   13.240525936,5] Region ibm,firmware-allocs-memory@200000000000 free: 6755c0
[   13.240571648,5] Region ibm,firmware-allocs-memory@0 free: 9f9620
[   13.240608336,5] Total free: 24987872
[   13.240627408,6] CPU: disabling power management
[   13.240629520,5] INIT: stdout-path: /lpcm-opb@6030000000000/lpc@0/serial@i3f8
[   13.240690336,5] INIT: Starting kernel at 0x20010000, fdt at 0x3081cdd0 187270 bytes)
[   14.508445536,7] OPAL: CPU re-init with flags: 0x2
[   14.508449104,5] OPAL: Switch to little-endian OS
[   14.508554960,6] CPU: Switching HILE on all CPUs to 1
[   14.508559840,7] CPU: [00000008] HID0 set to 0x0800000000000000
[   14.508570080,7] BT: seq 0x07 netfn 0x06 cmd 0x24: IPMI MSG done
[   15.001697520,7] CPU: [00000009] HID0 set to 0x0800000000000000
[   15.006818640,7] CPU: [0000000a] HID0 set to 0x0800000000000000
[   15.011939696,7] CPU: [0000000b] HID0 set to 0x0800000000000000
[   15.017060784,7] CPU: [0000000c] HID0 set to 0x0800000000000000
[   15.022181728,7] CPU: [0000000d] HID0 set to 0x0800000000000000
[   15.027302640,7] CPU: [0000000e] HID0 set to 0x0800000000000000
[   15.032423696,7] CPU: [0000000f] HID0 set to 0x0800000000000000
[   15.037545088,7] CPU: [00000018] HID0 set to 0x0800000000000000
[   15.042665632,7] CPU: [00000019] HID0 set to 0x0800000000000000
[   15.047786672,7] CPU: [0000001a] HID0 set to 0x0800000000000000
[   15.052907616,7] CPU: [0000001b] HID0 set to 0x0800000000000000
[   15.058028672,7] CPU: [0000001c] HID0 set to 0x0800000000000000
[   15.063149568,7] CPU: [0000001d] HID0 set to 0x0800000000000000
[   15.068270496,7] CPU: [0000001e] HID0 set to 0x0800000000000000
[   15.073391504,7] CPU: [0000001f] HID0 set to 0x0800000000000000
[   15.078521120,7] CPU: [00000838] HID0 set to 0x0800000000000000
[   15.083641664,7] CPU: [00000839] HID0 set to 0x0800000000000000
[   15.088762352,7] CPU: [0000083a] HID0 set to 0x0800000000000000
[   15.093883152,7] CPU: [0000083b] HID0 set to 0x0800000000000000
[   15.099003136,7] CPU: [0000083c] HID0 set to 0x0800000000000000
[   15.099006672,7] CPU: [0000083d] HID0 set to 0x0800000000000000
[   15.104130320,7] CPU: [0000083e] HID0 set to 0x0800000000000000
[   15.109251216,7] CPU: [0000083f] HID0 set to 0x0800000000000000
[   15.114372240,7] CPU: [00000858] HID0 set to 0x0800000000000000
[   15.119492832,7] CPU: [00000859] HID0 set to 0x0800000000000000
[   15.124613840,7] CPU: [0000085a] HID0 set to 0x0800000000000000
[   15.129734560,7] CPU: [0000085b] HID0 set to 0x0800000000000000
[   15.134855584,7] CPU: [0000085c] HID0 set to 0x0800000000000000
[   15.139976384,7] CPU: [0000085d] HID0 set to 0x0800000000000000
[   15.145097344,7] CPU: [0000085e] HID0 set to 0x0800000000000000
[   15.150218288,7] CPU: [0000085f] HID0 set to 0x0800000000000000
[   15.251953840,7] PHB#0000[0:0]: Purging all IODA tables...
[   15.254663744,7] PHB#0001[0:1]: Purging all IODA tables...
[   15.257220992,7] PHB#0002[0:2]: Purging all IODA tables...
[   15.259801328,7] PHB#0003[0:3]: Purging all IODA tables...
[   15.262497680,7] PHB#0030[8:0]: Purging all IODA tables...
[   15.265050240,7] PHB#0031[8:1]: Purging all IODA tables...
[   15.267520800,7] PHB#0032[8:2]: Purging all IODA tables...
[   15.270020656,7] PHB#0033[8:3]: Purging all IODA tables...
[   15.272598416,7] PHB#0034[8:4]: Purging all IODA tables...
[   15.275052944,7] PHB#0035[8:5]: Purging all IODA tables...
[   16.385766256,7] OPAL: Start CPU 0x0008 (PIR 0x0008) -> 0x000000000000a7e8
[   16.386318160,7] OPAL: Start CPU 0x0009 (PIR 0x0009) -> 0x000000000000a7e8
[   16.386616992,7] OPAL: Start CPU 0x000a (PIR 0x000a) -> 0x000000000000a7e8
[   16.387150896,7] OPAL: Start CPU 0x000b (PIR 0x000b) -> 0x000000000000a7e8
[   16.387564096,7] OPAL: Start CPU 0x000c (PIR 0x000c) -> 0x000000000000a7e8
[   16.387967488,7] OPAL: Start CPU 0x000d (PIR 0x000d) -> 0x000000000000a7e8
[   16.388494960,7] OPAL: Start CPU 0x000e (PIR 0x000e) -> 0x000000000000a7e8
[   16.388818848,7] OPAL: Start CPU 0x000f (PIR 0x000f) -> 0x000000000000a7e8
[   16.389256832,7] OPAL: Start CPU 0x0018 (PIR 0x0018) -> 0x000000000000a7e8
[   16.389809952,7] OPAL: Start CPU 0x0019 (PIR 0x0019) -> 0x000000000000a7e8
[   16.390120032,7] OPAL: Start CPU 0x001a (PIR 0x001a) -> 0x000000000000a7e8
[   16.390579040,7] OPAL: Start CPU 0x001b (PIR 0x001b) -> 0x000000000000a7e8
[   16.391040704,7] OPAL: Start CPU 0x001c (PIR 0x001c) -> 0x000000000000a7e8
[   16.391374320,7] OPAL: Start CPU 0x001d (PIR 0x001d) -> 0x000000000000a7e8
[   16.391818512,7] OPAL: Start CPU 0x001e (PIR 0x001e) -> 0x000000000000a7e8
[   16.392307952,7] OPAL: Start CPU 0x001f (PIR 0x001f) -> 0x000000000000a7e8
[   16.393587728,7] OPAL: Start CPU 0x0838 (PIR 0x0838) -> 0x000000000000a7e8
[   16.393999248,7] OPAL: Start CPU 0x0839 (PIR 0x0839) -> 0x000000000000a7e8
[   16.394374144,7] OPAL: Start CPU 0x083a (PIR 0x083a) -> 0x000000000000a7e8
[   16.394924032,7] OPAL: Start CPU 0x083b (PIR 0x083b) -> 0x000000000000a7e8
[   16.395462608,7] OPAL: Start CPU 0x083d (PIR 0x083d) -> 0x000000000000a7e8
[   16.396095856,7] OPAL: Start CPU 0x083e (PIR 0x083e) -> 0x000000000000a7e8
[   16.396933680,7] OPAL: Start CPU 0x083f (PIR 0x083f) -> 0x000000000000a7e8
[   16.397557808,7] OPAL: Start CPU 0x0858 (PIR 0x0858) -> 0x000000000000a7e8
[   16.398261216,7] OPAL: Start CPU 0x0859 (PIR 0x0859) -> 0x000000000000a7e8
[   16.398834176,7] OPAL: Start CPU 0x085a (PIR 0x085a) -> 0x000000000000a7e8
[   16.399615952,7] OPAL: Start CPU 0x085b (PIR 0x085b) -> 0x000000000000a7e8
[   16.400059120,7] OPAL: Start CPU 0x085c (PIR 0x085c) -> 0x000000000000a7e8
[   16.400611216,7] OPAL: Start CPU 0x085d (PIR 0x085d) -> 0x000000000000a7e8
[   16.401106960,7] OPAL: Start CPU 0x085e (PIR 0x085e) -> 0x000000000000a7e8
[   16.401832960,7] OPAL: Start CPU 0x085f (PIR 0x085f) -> 0x000000000000a7e8
[   16.451517632,7] MBOX-FLASH: Adjusting the window
[   16.451528352,7] LPC-MBOX: Sending BMC interrupt
[   17.041955392,7] LPC-MBOX: Sending BMC interrupt
[   17.246787184,7] LPC-MBOX: Sending BMC interrupt
[   24.366704896,7] opal_ipmi_send(cmd: 0x08 netfn: 0x06 len: 0x00)
[   24.366718640,7] BT: seq 0x08 netfn 0x06 cmd 0x08: Message sent to host
[   24.378350112,7] BT: seq 0x08 netfn 0x06 cmd 0x08: IPMI MSG done
[   24.378360864,7] opal_ipmi_recv(cmd: 0x08 netfn: 0x07 resp_size: 0x10)
[   25.461002320,7] BT: seq 0x09 netfn 0x0a cmd 0x48: Message sent to host
[   25.476138928,7] BT: seq 0x09 netfn 0x0a cmd 0x48: IPMI MSG done
[   26.020195424,7] BT: seq 0x0a netfn 0x0a cmd 0x48: Message sent to host
[   26.033118016,7] BT: seq 0x0a netfn 0x0a cmd 0x48: IPMI MSG done
[   27.137825776,7] opal_ipmi_send(cmd: 0x09 netfn: 0x00 len: 0x03)
[   27.137841392,7] BT: seq 0x0b netfn 0x00 cmd 0x09: Message sent to host
[   27.157913248,7] BT: seq 0x0b netfn 0x00 cmd 0x09: IPMI MSG done
[   27.157925328,7] opal_ipmi_recv(cmd: 0x09 netfn: 0x01 resp_size: 0x07)
[   27.157956096,7] opal_ipmi_send(cmd: 0x09 netfn: 0x00 len: 0x03)
[   27.157964656,7] BT: seq 0x0c netfn 0x00 cmd 0x09: Message sent to host
[   27.175072224,7] BT: seq 0x0c netfn 0x00 cmd 0x09: IPMI MSG done
[   27.175076288,7] IPMI: Got error response 0xff
[   27.175082704,7] opal_ipmi_recv(cmd: 0x09 netfn: 0x01 resp_size: 0x1a)
[   27.175197312,7] opal_ipmi_send(cmd: 0x09 netfn: 0x00 len: 0x03)
[   27.175206176,7] BT: seq 0x0d netfn 0x00 cmd 0x09: Message sent to host
[   27.198315776,7] BT: seq 0x0d netfn 0x00 cmd 0x09: IPMI MSG done
[   27.198326752,7] opal_ipmi_recv(cmd: 0x09 netfn: 0x01 resp_size: 0x07)
[   27.198392864,7] opal_ipmi_send(cmd: 0x09 netfn: 0x00 len: 0x03)
[   27.198402608,7] BT: seq 0x0e netfn 0x00 cmd 0x09: Message sent to host
[   27.216064320,7] BT: seq 0x0e netfn 0x00 cmd 0x09: IPMI MSG done
[   27.216068640,7] IPMI: Got error response 0xff
[   27.216074704,7] opal_ipmi_recv(cmd: 0x09 netfn: 0x01 resp_size: 0x1a)
[   27.216103616,7] opal_ipmi_send(cmd: 0x09 netfn: 0x00 len: 0x03)
[   27.216114064,7] BT: seq 0x0f netfn 0x00 cmd 0x09: Message sent to host
[   27.236598720,7] BT: seq 0x0f netfn 0x00 cmd 0x09: IPMI MSG done
[   27.236605808,7] opal_ipmi_recv(cmd: 0x09 netfn: 0x01 resp_size: 0x07)
[   27.236627744,7] opal_ipmi_send(cmd: 0x09 netfn: 0x00 len: 0x03)
[   27.236636416,7] BT: seq 0x10 netfn 0x00 cmd 0x09: Message sent to host
[   27.253882016,7] BT: seq 0x10 netfn 0x00 cmd 0x09: IPMI MSG done
[   27.253887664,7] IPMI: Got error response 0xff
[   27.253895376,7] opal_ipmi_recv(cmd: 0x09 netfn: 0x01 resp_size: 0x1a)
[   27.253929040,7] opal_ipmi_send(cmd: 0x09 netfn: 0x00 len: 0x03)
[   27.253939936,7] BT: seq 0x11 netfn 0x00 cmd 0x09: Message sent to host
[   27.274128704,7] BT: seq 0x11 netfn 0x00 cmd 0x09: IPMI MSG done
[   27.274136288,7] opal_ipmi_recv(cmd: 0x09 netfn: 0x01 resp_size: 0x07)
[   27.274189792,7] opal_ipmi_send(cmd: 0x09 netfn: 0x00 len: 0x03)
[   27.274198560,7] BT: seq 0x12 netfn 0x00 cmd 0x09: Message sent to host
[   27.297662624,7] BT: seq 0x12 netfn 0x00 cmd 0x09: IPMI MSG done
[   27.297668032,7] IPMI: Got error response 0xff
[   27.297674336,7] opal_ipmi_recv(cmd: 0x09 netfn: 0x01 resp_size: 0x1a)
[   27.297789952,7] opal_ipmi_send(cmd: 0x02 netfn: 0x0c len: 0x04)
[   27.297798864,7] BT: seq 0x13 netfn 0x0c cmd 0x02: Message sent to host
[   27.370817568,7] BT: seq 0x13 netfn 0x0c cmd 0x02: IPMI MSG done
[   27.370826080,7] opal_ipmi_recv(cmd: 0x02 netfn: 0x0d resp_size: 0x07)
[   27.370847920,7] opal_ipmi_send(cmd: 0x01 netfn: 0x06 len: 0x00)
[   27.370855584,7] BT: seq 0x14 netfn 0x06 cmd 0x01: Message sent to host
[   27.383177968,7] BT: seq 0x14 netfn 0x06 cmd 0x01: IPMI MSG done
[   27.383184992,7] opal_ipmi_recv(cmd: 0x01 netfn: 0x07 resp_size: 0x0f)
[   27.383242064,7] opal_ipmi_send(cmd: 0x1a netfn: 0x3a len: 0x00)
[   27.383248976,7] BT: seq 0x15 netfn 0x3a cmd 0x1a: Message sent to host
[   27.386227744,7] BT: seq 0x15 netfn 0x3a cmd 0x1a: IPMI MSG done
[   27.386232144,7] IPMI: Got error response 0xc1
[   27.386237968,7] opal_ipmi_recv(cmd: 0x1a netfn: 0x3b resp_size: 0x00)
[   27.386531376,7] MBOX-FLASH: Adjusting the window
[   27.386539728,7] LPC-MBOX: Sending BMC interrupt
[   49.182568544,7] MBOX-FLASH: Adjusting the window
[   49.182579680,7] LPC-MBOX: Sending BMC interrupt
[   49.294264928,7] LPC-MBOX: Sending BMC interrupt
[   50.001763280,7] LPC-MBOX: Sending BMC interrupt
[   50.221164960,7] LPC-MBOX: Sending BMC interrupt

@sammj
Copy link
Contributor

sammj commented Apr 12, 2017

[    2.027717680,5] NVRAM: Size is 576 KB
[    2.148648208,3] NVRAM: Partition at offset 0xffff0 extends beyond end of nvram !
[    2.148704960,3] NVRAM: Re-initializing (size: 0x00090000)
[    2.148750816,7] NVRAM: Created 'ibm,skiboot' partition at 0x00000000 for size 0x00000100 with cksum 0xb5
[    2.148755360,7] NVRAM: Created 'common' partition at 0x00001000 for size 0x00001000 with cksum 0x0c
[    2.148759104,7] NVRAM: Created 'wwwwwwwwwwww' partition at 0x00011000 for size 0x00007f00 with cksum 0x98

Skiboot is re-initialising the NVRAM partition on boot which would explain why the changes don't persist. When you "reboot" the system is that via a clean reboot or are you hard-powering off the system? Perhaps this is an issue with the new MBOX mechanism.

@johnhihi
Copy link
Author

Because our BMC have issues for rebooting system. So we type "reboot" in petitboot, after BMC cut the system power and then we have to AC cycle to power on system again.
But if the data is in NVRAM, the data should persist even AC cycle system. Right?

@sammj
Copy link
Contributor

sammj commented Apr 18, 2017

Yep, that normally should be fine. I wonder if the new mbox interface is not flushing something in time. @cyrilbur-ibm or @sjitindarsingh do you have any ideas here?

@sjitindarsingh
Copy link

So it seems to me like either the write back to flash is failing under the hood and due to the fact that this is cached we're still seeing the changed in the nvram tool even if they weren't successful. Additionally I'm not sure of the state the daemon is in after all this power cycling etc.

Can you run the following commands 3 times:

  1. After running nvram --update-config and before powering off the host.
  2. After powering off the host and before power cycling the bmc
  3. After power cycling the bmc and before powering the host back on again.

Commands:
pflash -r /tmp/tmp -P NVRAM; hexdump -C /tmp/tmp
journalctl -u mboxd

Please post the results stating which is which

@johnhihi
Copy link
Author

1. After running nvram --update-config and before powering off the host.

root@zaius:# pflash -r /tmp/tmp -P NVRAM; hexdump -C /tmp/tmp
Reading to "/tmp/tmp" from 0x02580000..0x02610000 !
[==================================================] 100%
00000000 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
*
00001000 70 0c 10 00 63 6f 6d 6d 6f 6e 00 00 00 00 00 00 |p...common......|
00001010 70 65 74 69 74 62 6f 6f 74 2c 62 6f 6f 74 64 65 |petitboot,bootde|
00001020 76 73 3d 61 6e 79 20 6e 65 74 77 6f 72 6b 20 00 |vs=any network .|
00001030 70 65 74 69 74 62 6f 6f 74 2c 63 6f 6e 73 6f 6c |petitboot,consol|
00001040 65 3d 2f 64 65 76 2f 68 76 63 30 20 5b 49 50 4d |e=/dev/hvc0 [IPM|
00001050 49 20 2f 20 53 65 72 69 61 6c 5d 00 70 65 74 69 |I / Serial].peti|
00001060 74 62 6f 6f 74 2c 74 69 6d 65 6f 75 74 3d 35 30 |tboot,timeout=50|
00001070 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
00011000 a0 4f 00 fb 6c 6e 78 2c 6f 6f 70 73 2d 6c 6f 67 |.O..lnx,oops-log|
00011010 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
00011fb0 7f 9c 7e 05 77 77 77 77 77 77 77 77 77 77 77 77 |..~.wwwwwwwwwwww|
00011fc0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
00090000
root@zaius:#
root@zaius:# journalctl -u mboxd | cat
-- Logs begin at Tue 2017-02-07 00:32:23 UTC, end at Tue 2017-02-07 00:51:03 UTC. --
Feb 07 00:32:29 zaius systemd[1]: Started Phosphor MBOX Daemon.
Feb 07 00:32:29 zaius mboxd[796]: [ 1486427549.914430102] Verbose logging
Feb 07 00:32:29 zaius mboxd[796]: [ 1486427549.919056728] Registering SigHUP hander
Feb 07 00:32:29 zaius mboxd[796]: [ 1486427549.922741860] Starting
Feb 07 00:32:29 zaius mboxd[796]: [ 1486427549.926181254] Opening /dev/aspeed-mbox
Feb 07 00:32:29 zaius mboxd[796]: [ 1486427549.929720688] Opening /dev/aspeed-lpc-ctrl
Feb 07 00:32:29 zaius mboxd[796]: [ 1486427549.933240769] Getting buffer size...
Feb 07 00:32:29 zaius mboxd[796]: [ 1486427549.937003961] Pointing HOST LPC bus at the actual flash
Feb 07 00:32:29 zaius mboxd[796]: [ 1486427549.940475880] Assuming 64MB of flash: HOST LPC 0x0c000000
Feb 07 00:32:29 zaius mboxd[796]: [ 1486427549.944166506] Mapping /dev/aspeed-lpc-ctrl for 67108864
Feb 07 00:32:29 zaius mboxd[796]: [ 1486427549.950586425] Opening /dev/mtd7
Feb 07 00:32:29 zaius mboxd[796]: [ 1486427549.954231072] Loading flash into ram at 0x72f3c000 for 0x04000000 bytes
Feb 07 00:33:51 zaius mboxd[796]: [ 1486427631.820357874] Setting all MBOX regs to 0xff individually...
Feb 07 00:33:51 zaius mboxd[796]: [ 1486427631.824444904] Entering polling loop
Feb 07 00:35:08 zaius mboxd[796]: [ 1486427708.553921807] Pointing HOST LPC bus at the actual flash
Feb 07 00:35:08 zaius mboxd[796]: [ 1486427708.554078493] Assuming 64MB of flash: HOST LPC 0x0c000000
Feb 07 00:35:08 zaius mboxd[796]: [ 1486427708.554192594] Loading flash into ram at 0x72f3c000 for 0x04000000 bytes
Feb 07 00:37:09 zaius mboxd[796]: [ 1486427829.672774919] Pointing HOST LPC bus at the actual flash
Feb 07 00:37:09 zaius mboxd[796]: [ 1486427829.672926434] Assuming 64MB of flash: HOST LPC 0x0c000000
Feb 07 00:37:09 zaius mboxd[796]: [ 1486427829.673040818] Loading flash into ram at 0x72f3c000 for 0x04000000 bytes
Feb 07 00:39:49 zaius mboxd[796]: [ 1486427989.521299957] Pointing HOST LPC bus at the actual flash
Feb 07 00:39:49 zaius mboxd[796]: [ 1486427989.521455755] Assuming 64MB of flash: HOST LPC 0x0c000000
Feb 07 00:39:49 zaius mboxd[796]: [ 1486427989.521573088] Loading flash into ram at 0x72f3c000 for 0x04000000 bytes
Feb 07 00:42:11 zaius mboxd[796]: [ 1486428131.621736547] Dispatched to mbox
Feb 07 00:42:11 zaius mboxd[796]: [ 1486428131.621919901] Got data in with command 2
Feb 07 00:42:11 zaius mboxd[796]: [ 1486428131.622012951] LPC_CTRL_IOCTL_MAP to 0x0c000000 for 0x04000000
Feb 07 00:42:11 zaius mboxd[796]: [ 1486428131.622110850] Writing response to MBOX regs
Feb 07 00:42:11 zaius mboxd[796]: [ 1486428131.821968547] Dispatched to mbox
Feb 07 00:42:11 zaius mboxd[796]: [ 1486428131.822154244] Got data in with command 3
Feb 07 00:42:11 zaius mboxd[796]: [ 1486428131.822250568] Writing response to MBOX regs
Feb 07 00:42:12 zaius mboxd[796]: [ 1486428132.021998487] Dispatched to mbox
Feb 07 00:42:12 zaius mboxd[796]: [ 1486428132.022186810] Got data in with command 3
Feb 07 00:42:12 zaius mboxd[796]: [ 1486428132.022289517] Writing response to MBOX regs
Feb 07 00:42:12 zaius mboxd[796]: [ 1486428132.222051618] Dispatched to mbox
Feb 07 00:42:12 zaius mboxd[796]: [ 1486428132.222236224] Got data in with command 4
Feb 07 00:42:12 zaius mboxd[796]: [ 1486428132.222331537] Writing response to MBOX regs
Feb 07 00:42:13 zaius mboxd[796]: [ 1486428133.538484750] Dispatched to mbox
Feb 07 00:42:13 zaius mboxd[796]: [ 1486428133.538660467] Got data in with command 6
Feb 07 00:42:13 zaius mboxd[796]: [ 1486428133.538754972] Writing response to MBOX regs
Feb 07 00:42:13 zaius mboxd[796]: [ 1486428133.885486528] Dispatched to mbox
Feb 07 00:42:13 zaius mboxd[796]: [ 1486428133.885672790] Got data in with command 7
Feb 07 00:42:13 zaius mboxd[796]: [ 1486428133.885769962] Erasing 0x02580000 for 0x00090000 (aligned: 0x00090000)
Feb 07 00:42:17 zaius mboxd[796]: [ 1486428137.183766892] Writing response to MBOX regs
Feb 07 00:42:17 zaius mboxd[796]: [ 1486428137.287583821] Dispatched to mbox
Feb 07 00:42:17 zaius mboxd[796]: [ 1486428137.333225478] Got data in with command 3
Feb 07 00:42:17 zaius mboxd[796]: [ 1486428137.337210973] Writing response to MBOX regs
Feb 07 00:42:17 zaius mboxd[796]: [ 1486428137.486073922] Dispatched to mbox
Feb 07 00:42:17 zaius mboxd[796]: [ 1486428137.490364306] Got data in with command 4
Feb 07 00:42:17 zaius mboxd[796]: [ 1486428137.494299942] Writing response to MBOX regs
Feb 07 00:42:22 zaius mboxd[796]: [ 1486428142.869732064] Dispatched to mbox
Feb 07 00:42:22 zaius mboxd[796]: [ 1486428142.869912226] Got data in with command 3
Feb 07 00:42:22 zaius mboxd[796]: [ 1486428142.870008307] Writing response to MBOX regs
Feb 07 00:42:27 zaius mboxd[796]: [ 1486428147.641087298] Dispatched to mbox
Feb 07 00:42:27 zaius mboxd[796]: [ 1486428147.641273762] Got data in with command 6
Feb 07 00:42:27 zaius mboxd[796]: [ 1486428147.641369197] Writing response to MBOX regs
Feb 07 00:42:28 zaius mboxd[796]: [ 1486428147.841164267] Dispatched to mbox
Feb 07 00:42:28 zaius mboxd[796]: [ 1486428147.841344712] Got data in with command 7
Feb 07 00:42:28 zaius mboxd[796]: [ 1486428147.841442732] Erasing 0x02591000 for 0x00000010 (aligned: 0x00010000)
Feb 07 00:42:28 zaius mboxd[796]: [ 1486428148.199641722] Writing response to MBOX regs
Feb 07 00:42:28 zaius mboxd[796]: [ 1486428148.241233884] Dispatched to mbox
Feb 07 00:42:28 zaius mboxd[796]: [ 1486428148.245098368] Got data in with command 7
Feb 07 00:42:28 zaius mboxd[796]: [ 1486428148.248955379] Erasing 0x02591000 for 0x00000010 (aligned: 0x00010000)
Feb 07 00:42:28 zaius mboxd[796]: [ 1486428148.616262813] Writing response to MBOX regs
Feb 07 00:44:06 zaius mboxd[796]: [ 1486428246.798206669] Dispatched to mbox
Feb 07 00:44:06 zaius mboxd[796]: [ 1486428246.798398386] Got data in with command 6
Feb 07 00:44:06 zaius mboxd[796]: [ 1486428246.798501093] Writing response to MBOX regs
Feb 07 00:44:07 zaius mboxd[796]: [ 1486428247.014561416] Dispatched to mbox
Feb 07 00:44:07 zaius mboxd[796]: [ 1486428247.014758022] Got data in with command 7
Feb 07 00:44:07 zaius mboxd[796]: [ 1486428247.014865093] Erasing 0x02581000 for 0x00010000 (aligned: 0x00010000)
Feb 07 00:44:07 zaius mboxd[796]: [ 1486428247.378220648] Writing response to MBOX regs
Feb 07 00:44:07 zaius mboxd[796]: [ 1486428247.438755073] Dispatched to mbox
Feb 07 00:44:07 zaius mboxd[796]: [ 1486428247.442820770] Got data in with command 7
Feb 07 00:44:07 zaius mboxd[796]: [ 1486428247.444538305] Erasing 0x02581000 for 0x00010000 (aligned: 0x00010000)
Feb 07 00:44:07 zaius mboxd[796]: [ 1486428247.808314345] Writing response to MBOX regs
Feb 07 00:44:07 zaius mboxd[796]: [ 1486428247.861427881] Dispatched to mbox
Feb 07 00:44:07 zaius mboxd[796]: [ 1486428247.865461133] Got data in with command 7
Feb 07 00:44:07 zaius mboxd[796]: [ 1486428247.869456406] Erasing 0x02581000 for 0x00010000 (aligned: 0x00010000)
Feb 07 00:44:08 zaius mboxd[796]: [ 1486428248.236443436] Writing response to MBOX regs
Feb 07 00:45:19 zaius mboxd[796]: [ 1486428319.272905914] Dispatched to mbox
Feb 07 00:45:19 zaius mboxd[796]: [ 1486428319.277435934] Got data in with command 7
Feb 07 00:45:19 zaius mboxd[796]: [ 1486428319.281539691] Erasing 0x02581000 for 0x00010000 (aligned: 0x00010000)
Feb 07 00:45:19 zaius mboxd[796]: [ 1486428319.646707893] Writing response to MBOX regs
Feb 07 00:45:19 zaius mboxd[796]: [ 1486428319.695212580] Dispatched to mbox
Feb 07 00:45:19 zaius mboxd[796]: [ 1486428319.699263974] Got data in with command 7
Feb 07 00:45:19 zaius mboxd[796]: [ 1486428319.703256661] Erasing 0x02581000 for 0x00010000 (aligned: 0x00010000)
Feb 07 00:45:20 zaius mboxd[796]: [ 1486428320.067026399] Writing response to MBOX regs
Feb 07 00:45:20 zaius mboxd[796]: [ 1486428320.117522399] Dispatched to mbox
Feb 07 00:45:20 zaius mboxd[796]: [ 1486428320.121565308] Got data in with command 7
Feb 07 00:45:20 zaius mboxd[796]: [ 1486428320.125173550] Erasing 0x02581000 for 0x00010000 (aligned: 0x00010000)
Feb 07 00:45:20 zaius mboxd[796]: [ 1486428320.489694237] Writing response to MBOX regs
Feb 07 00:47:55 zaius mboxd[796]: [ 1486428475.620570264] Pointing HOST LPC bus at the actual flash
Feb 07 00:47:55 zaius mboxd[796]: [ 1486428475.620720082] Assuming 64MB of flash: HOST LPC 0x0c000000
Feb 07 00:47:55 zaius mboxd[796]: [ 1486428475.620837537] Loading flash into ram at 0x72f3c000 for 0x04000000 bytes
Feb 07 00:50:17 zaius mboxd[796]: [ 1486428617.251426976] Dispatched to mbox
Feb 07 00:50:17 zaius mboxd[796]: [ 1486428617.251607703] Got data in with command 2
Feb 07 00:50:17 zaius mboxd[796]: [ 1486428617.251702289] LPC_CTRL_IOCTL_MAP to 0x0c000000 for 0x04000000
Feb 07 00:50:17 zaius mboxd[796]: [ 1486428617.251803057] Writing response to MBOX regs
Feb 07 00:50:17 zaius mboxd[796]: [ 1486428617.451485279] Dispatched to mbox
Feb 07 00:50:17 zaius mboxd[796]: [ 1486428617.451669925] Got data in with command 3
Feb 07 00:50:17 zaius mboxd[796]: [ 1486428617.451769925] Writing response to MBOX regs
Feb 07 00:50:17 zaius mboxd[796]: [ 1486428617.651560673] Dispatched to mbox
Feb 07 00:50:17 zaius mboxd[796]: [ 1486428617.651745643] Got data in with command 3
Feb 07 00:50:17 zaius mboxd[796]: [ 1486428617.651839138] Writing response to MBOX regs
Feb 07 00:50:17 zaius mboxd[796]: [ 1486428617.851610572] Dispatched to mbox
Feb 07 00:50:17 zaius mboxd[796]: [ 1486428617.851793117] Got data in with command 4
Feb 07 00:50:17 zaius mboxd[796]: [ 1486428617.851889764] Writing response to MBOX regs
Feb 07 00:50:19 zaius mboxd[796]: [ 1486428619.190853562] Dispatched to mbox
Feb 07 00:50:19 zaius mboxd[796]: [ 1486428619.191032067] Got data in with command 6
Feb 07 00:50:19 zaius mboxd[796]: [ 1486428619.191127784] Writing response to MBOX regs
Feb 07 00:50:19 zaius mboxd[796]: [ 1486428619.553761966] Dispatched to mbox
Feb 07 00:50:19 zaius mboxd[796]: [ 1486428619.553952996] Got data in with command 7
Feb 07 00:50:19 zaius mboxd[796]: [ 1486428619.554051906] Erasing 0x02580000 for 0x00090000 (aligned: 0x00090000)
Feb 07 00:50:22 zaius mboxd[796]: [ 1486428622.830983179] Writing response to MBOX regs
Feb 07 00:50:22 zaius mboxd[796]: [ 1486428622.955896229] Dispatched to mbox
Feb 07 00:50:23 zaius mboxd[796]: [ 1486428622.997812351] Got data in with command 3
Feb 07 00:50:23 zaius mboxd[796]: [ 1486428623.001767906] Writing response to MBOX regs
Feb 07 00:50:23 zaius mboxd[796]: [ 1486428623.154440835] Dispatched to mbox
Feb 07 00:50:23 zaius mboxd[796]: [ 1486428623.158633563] Got data in with command 4
Feb 07 00:50:23 zaius mboxd[796]: [ 1486428623.162608108] Writing response to MBOX regs
Feb 07 00:50:30 zaius mboxd[796]: [ 1486428630.324683140] Dispatched to mbox
Feb 07 00:50:30 zaius mboxd[796]: [ 1486428630.324868594] Got data in with command 3
Feb 07 00:50:30 zaius mboxd[796]: [ 1486428630.324962130] Writing response to MBOX regs
Feb 07 00:50:33 zaius mboxd[796]: [ 1486428633.545038453] Dispatched to mbox
Feb 07 00:50:33 zaius mboxd[796]: [ 1486428633.545221726] Got data in with command 6
Feb 07 00:50:33 zaius mboxd[796]: [ 1486428633.545314413] Writing response to MBOX regs
Feb 07 00:50:33 zaius mboxd[796]: [ 1486428633.745119908] Dispatched to mbox
Feb 07 00:50:33 zaius mboxd[796]: [ 1486428633.745299585] Got data in with command 7
Feb 07 00:50:33 zaius mboxd[796]: [ 1486428633.745390817] Erasing 0x02591000 for 0x00000010 (aligned: 0x00010000)
Feb 07 00:50:34 zaius mboxd[796]: [ 1486428634.106211908] Writing response to MBOX regs
Feb 07 00:50:34 zaius mboxd[796]: [ 1486428634.145201767] Dispatched to mbox
Feb 07 00:50:34 zaius mboxd[796]: [ 1486428634.149116312] Got data in with command 7
Feb 07 00:50:34 zaius mboxd[796]: [ 1486428634.152933807] Erasing 0x02591000 for 0x00000010 (aligned: 0x00010000)
Feb 07 00:50:34 zaius mboxd[796]: [ 1486428634.523079949] Writing response to MBOX regs
Feb 07 00:51:02 zaius mboxd[796]: [ 1486428662.231777610] Dispatched to mbox
Feb 07 00:51:02 zaius mboxd[796]: [ 1486428662.231962095] Got data in with command 6
Feb 07 00:51:02 zaius mboxd[796]: [ 1486428662.232058903] Writing response to MBOX regs
Feb 07 00:51:02 zaius mboxd[796]: [ 1486428662.450012762] Dispatched to mbox
Feb 07 00:51:02 zaius mboxd[796]: [ 1486428662.450197610] Got data in with command 7
Feb 07 00:51:02 zaius mboxd[796]: [ 1486428662.450294095] Erasing 0x02581000 for 0x00010000 (aligned: 0x00010000)
Feb 07 00:51:02 zaius mboxd[796]: [ 1486428662.824863994] Writing response to MBOX regs
Feb 07 00:51:02 zaius mboxd[796]: [ 1486428662.874423873] Dispatched to mbox
Feb 07 00:51:02 zaius mboxd[796]: [ 1486428662.878353529] Got data in with command 7
Feb 07 00:51:02 zaius mboxd[796]: [ 1486428662.882171065] Erasing 0x02581000 for 0x00010000 (aligned: 0x00010000)
Feb 07 00:51:03 zaius mboxd[796]: [ 1486428663.249593853] Writing response to MBOX regs
Feb 07 00:51:03 zaius mboxd[796]: [ 1486428663.298712923] Dispatched to mbox
Feb 07 00:51:03 zaius mboxd[796]: [ 1486428663.302575590] Got data in with command 7
Feb 07 00:51:03 zaius mboxd[796]: [ 1486428663.306376317] Erasing 0x02581000 for 0x00010000 (aligned: 0x00010000)
Feb 07 00:51:03 zaius mboxd[796]: [ 1486428663.676161731] Writing response to MBOX regs
root@zaius:#

2. After powering off the host and before power cycling the bmc

root@zaius:# pflash -r /tmp/tmp -P NVRAM; hexdump -C /tmp/tmp
Reading to "/tmp/tmp" from 0x02580000..0x02610000 !
[==================================================] 100%
00000000 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
*
00001000 70 0c 10 00 63 6f 6d 6d 6f 6e 00 00 00 00 00 00 |p...common......|
00001010 70 65 74 69 74 62 6f 6f 74 2c 62 6f 6f 74 64 65 |petitboot,bootde|
00001020 76 73 3d 61 6e 79 20 6e 65 74 77 6f 72 6b 20 00 |vs=any network .|
00001030 70 65 74 69 74 62 6f 6f 74 2c 63 6f 6e 73 6f 6c |petitboot,consol|
00001040 65 3d 2f 64 65 76 2f 68 76 63 30 20 5b 49 50 4d |e=/dev/hvc0 [IPM|
00001050 49 20 2f 20 53 65 72 69 61 6c 5d 00 70 65 74 69 |I / Serial].peti|
00001060 74 62 6f 6f 74 2c 74 69 6d 65 6f 75 74 3d 35 30 |tboot,timeout=50|
00001070 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
00011000 a0 4f 00 fb 6c 6e 78 2c 6f 6f 70 73 2d 6c 6f 67 |.O..lnx,oops-log|
00011010 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
00011fb0 7f 9c 7e 05 77 77 77 77 77 77 77 77 77 77 77 77 |..~.wwwwwwwwwwww|
00011fc0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
00090000
root@zaius:#
root@zaius:# journalctl -u mboxd | cat
-- Logs begin at Tue 2017-02-28 19:27:51 UTC, end at Tue 2017-02-28 19:36:05 UTC. --
Feb 28 19:29:20 zaius systemd[1]: Started Phosphor MBOX Daemon.
Feb 28 19:29:20 zaius mboxd[971]: [ 1488310160.565365995] Verbose logging
Feb 28 19:29:20 zaius mboxd[971]: [ 1488310160.569833793] Registering SigHUP hander
Feb 28 19:29:20 zaius mboxd[971]: [ 1488310160.573629308] Starting
Feb 28 19:29:20 zaius mboxd[971]: [ 1488310160.577265349] Opening /dev/aspeed-mbox
Feb 28 19:29:20 zaius mboxd[971]: [ 1488310160.580974682] Opening /dev/aspeed-lpc-ctrl
Feb 28 19:29:20 zaius mboxd[971]: [ 1488310160.584697915] Getting buffer size...
Feb 28 19:29:20 zaius mboxd[971]: [ 1488310160.588532420] Pointing HOST LPC bus at the actual flash
Feb 28 19:29:20 zaius mboxd[971]: [ 1488310160.592236702] Assuming 64MB of flash: HOST LPC 0x0c000000
Feb 28 19:29:20 zaius mboxd[971]: [ 1488310160.596129510] Mapping /dev/aspeed-lpc-ctrl for 67108864
Feb 28 19:29:20 zaius mboxd[971]: [ 1488310160.602723975] Opening /dev/mtd6
Feb 28 19:29:20 zaius mboxd[971]: [ 1488310160.606513793] Loading flash into ram at 0x72fdf000 for 0x04000000 bytes
Feb 28 19:29:51 zaius mboxd[971]: [ 1488310191.346674607] Setting all MBOX regs to 0xff individually...
Feb 28 19:29:51 zaius mboxd[971]: [ 1488310191.350558203] Entering polling loop
Feb 28 19:31:32 zaius mboxd[971]: [ 1488310292.697045170] Dispatched to mbox
Feb 28 19:31:32 zaius mboxd[971]: [ 1488310292.697248281] Got data in with command 2
Feb 28 19:31:32 zaius mboxd[971]: [ 1488310292.697346382] LPC_CTRL_IOCTL_MAP to 0x0c000000 for 0x04000000
Feb 28 19:31:32 zaius mboxd[971]: [ 1488310292.697445453] Writing response to MBOX regs
Feb 28 19:31:32 zaius mboxd[971]: [ 1488310292.897286625] Dispatched to mbox
Feb 28 19:31:32 zaius mboxd[971]: [ 1488310292.897466705] Got data in with command 3
Feb 28 19:31:32 zaius mboxd[971]: [ 1488310292.897567150] Writing response to MBOX regs
Feb 28 19:31:33 zaius mboxd[971]: [ 1488310293.097312685] Dispatched to mbox
Feb 28 19:31:33 zaius mboxd[971]: [ 1488310293.097500443] Got data in with command 3
Feb 28 19:31:33 zaius mboxd[971]: [ 1488310293.097603271] Writing response to MBOX regs
Feb 28 19:31:33 zaius mboxd[971]: [ 1488310293.297361655] Dispatched to mbox
Feb 28 19:31:33 zaius mboxd[971]: [ 1488310293.297542867] Got data in with command 4
Feb 28 19:31:33 zaius mboxd[971]: [ 1488310293.297641978] Writing response to MBOX regs
Feb 28 19:31:34 zaius mboxd[971]: [ 1488310294.613551877] Dispatched to mbox
Feb 28 19:31:34 zaius mboxd[971]: [ 1488310294.613729292] Got data in with command 6
Feb 28 19:31:34 zaius mboxd[971]: [ 1488310294.613825857] Writing response to MBOX regs
Feb 28 19:31:35 zaius mboxd[971]: [ 1488310294.960233574] Dispatched to mbox
Feb 28 19:31:35 zaius mboxd[971]: [ 1488310294.960417251] Got data in with command 7
Feb 28 19:31:35 zaius mboxd[971]: [ 1488310294.960515150] Erasing 0x02580000 for 0x00090000 (aligned: 0x00090000)
Feb 28 19:31:38 zaius mboxd[971]: [ 1488310298.261855757] Writing response to MBOX regs
Feb 28 19:31:38 zaius mboxd[971]: [ 1488310298.361817454] Dispatched to mbox
Feb 28 19:31:38 zaius mboxd[971]: [ 1488310298.367093858] Got data in with command 3
Feb 28 19:31:38 zaius mboxd[971]: [ 1488310298.372705413] Writing response to MBOX regs
Feb 28 19:31:38 zaius mboxd[971]: [ 1488310298.560917333] Dispatched to mbox
Feb 28 19:31:38 zaius mboxd[971]: [ 1488310298.561096363] Got data in with command 4
Feb 28 19:31:38 zaius mboxd[971]: [ 1488310298.561190222] Writing response to MBOX regs
Feb 28 19:31:44 zaius mboxd[971]: [ 1488310304.025294829] Dispatched to mbox
Feb 28 19:31:44 zaius mboxd[971]: [ 1488310304.025482990] Got data in with command 3
Feb 28 19:31:44 zaius mboxd[971]: [ 1488310304.025582829] Writing response to MBOX regs
Feb 28 19:31:48 zaius mboxd[971]: [ 1488310308.730585496] Dispatched to mbox
Feb 28 19:31:48 zaius mboxd[971]: [ 1488310308.730768486] Got data in with command 6
Feb 28 19:31:48 zaius mboxd[971]: [ 1488310308.730864930] Writing response to MBOX regs
Feb 28 19:31:48 zaius mboxd[971]: [ 1488310308.930664971] Dispatched to mbox
Feb 28 19:31:48 zaius mboxd[971]: [ 1488310308.930845779] Got data in with command 7
Feb 28 19:31:48 zaius mboxd[971]: [ 1488310308.930947597] Erasing 0x02591000 for 0x00000010 (aligned: 0x00010000)
Feb 28 19:31:49 zaius mboxd[971]: [ 1488310309.290526304] Writing response to MBOX regs
Feb 28 19:31:49 zaius mboxd[971]: [ 1488310309.330734021] Dispatched to mbox
Feb 28 19:31:49 zaius mboxd[971]: [ 1488310309.331460001] Got data in with command 7
Feb 28 19:31:49 zaius mboxd[971]: [ 1488310309.331589173] Erasing 0x02591000 for 0x00000010 (aligned: 0x00010000)
Feb 28 19:31:49 zaius mboxd[971]: [ 1488310309.712876890] Writing response to MBOX regs
Feb 28 19:32:25 zaius mboxd[971]: [ 1488310345.327200169] Dispatched to mbox
Feb 28 19:32:25 zaius mboxd[971]: [ 1488310345.327389502] Got data in with command 6
Feb 28 19:32:25 zaius mboxd[971]: [ 1488310345.327494432] Writing response to MBOX regs
Feb 28 19:32:25 zaius mboxd[971]: [ 1488310345.545436492] Dispatched to mbox
Feb 28 19:32:25 zaius mboxd[971]: [ 1488310345.545629502] Got data in with command 7
Feb 28 19:32:25 zaius mboxd[971]: [ 1488310345.545736088] Erasing 0x02581000 for 0x00010000 (aligned: 0x00010000)
Feb 28 19:32:25 zaius mboxd[971]: [ 1488310345.909610068] Writing response to MBOX regs
Feb 28 19:32:26 zaius mboxd[971]: [ 1488310346.169998513] Dispatched to mbox
Feb 28 19:32:26 zaius mboxd[971]: [ 1488310346.170181301] Got data in with command 7
Feb 28 19:32:26 zaius mboxd[971]: [ 1488310346.170286755] Erasing 0x02581000 for 0x00010000 (aligned: 0x00010000)
Feb 28 19:32:26 zaius mboxd[971]: [ 1488310346.534829058] Writing response to MBOX regs
Feb 28 19:32:26 zaius mboxd[971]: [ 1488310346.593329947] Dispatched to mbox
Feb 28 19:32:26 zaius mboxd[971]: [ 1488310346.593520937] Got data in with command 7
Feb 28 19:32:26 zaius mboxd[971]: [ 1488310346.593623119] Erasing 0x02581000 for 0x00010000 (aligned: 0x00010000)
Feb 28 19:32:26 zaius mboxd[971]: [ 1488310346.980531846] Writing response to MBOX regs
Feb 28 19:34:23 zaius mboxd[971]: [ 1488310463.730596392] Pointing HOST LPC bus at the actual flash
Feb 28 19:34:23 zaius mboxd[971]: [ 1488310463.730748877] Assuming 64MB of flash: HOST LPC 0x0c000000
Feb 28 19:34:23 zaius mboxd[971]: [ 1488310463.730864513] Loading flash into ram at 0x72fdf000 for 0x04000000 bytes
root@zaius:#

3. After power cycling the bmc and before powering the host back on again.

root@zaius:# pflash -r /tmp/tmp -P NVRAM; hexdump -C /tmp/tmp
Reading to "/tmp/tmp" from 0x02580000..0x02610000 !
[==================================================] 100%
00000000 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
*
00001000 70 0c 10 00 63 6f 6d 6d 6f 6e 00 00 00 00 00 00 |p...common......|
00001010 70 65 74 69 74 62 6f 6f 74 2c 62 6f 6f 74 64 65 |petitboot,bootde|
00001020 76 73 3d 61 6e 79 20 6e 65 74 77 6f 72 6b 20 00 |vs=any network .|
00001030 70 65 74 69 74 62 6f 6f 74 2c 63 6f 6e 73 6f 6c |petitboot,consol|
00001040 65 3d 2f 64 65 76 2f 68 76 63 30 20 5b 49 50 4d |e=/dev/hvc0 [IPM|
00001050 49 20 2f 20 53 65 72 69 61 6c 5d 00 70 65 74 69 |I / Serial].peti|
00001060 74 62 6f 6f 74 2c 74 69 6d 65 6f 75 74 3d 35 30 |tboot,timeout=50|
00001070 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
00011000 a0 4f 00 fb 6c 6e 78 2c 6f 6f 70 73 2d 6c 6f 67 |.O..lnx,oops-log|
00011010 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
00011fb0 7f 9c 7e 05 77 77 77 77 77 77 77 77 77 77 77 77 |..~.wwwwwwwwwwww|
00011fc0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
00090000
root@zaius:#
root@zaius:# journalctl -u mboxd | cat
-- Logs begin at Tue 2017-02-28 19:27:51 UTC, end at Tue 2017-02-28 19:30:26 UTC. --
Feb 28 19:29:20 zaius systemd[1]: Started Phosphor MBOX Daemon.
Feb 28 19:29:20 zaius mboxd[959]: [ 1488310160.659657510] Verbose logging
Feb 28 19:29:20 zaius mboxd[959]: [ 1488310160.664015005] Registering SigHUP hander
Feb 28 19:29:20 zaius mboxd[959]: [ 1488310160.667122844] Starting
Feb 28 19:29:20 zaius mboxd[959]: [ 1488310160.667249026] Opening /dev/aspeed-mbox
Feb 28 19:29:20 zaius mboxd[959]: [ 1488310160.667413308] Opening /dev/aspeed-lpc-ctrl
Feb 28 19:29:20 zaius mboxd[959]: [ 1488310160.667580662] Getting buffer size...
Feb 28 19:29:20 zaius mboxd[959]: [ 1488310160.667687450] Pointing HOST LPC bus at the actual flash
Feb 28 19:29:20 zaius mboxd[959]: [ 1488310160.667762521] Assuming 64MB of flash: HOST LPC 0x0c000000
Feb 28 19:29:20 zaius mboxd[959]: [ 1488310160.668081915] Mapping /dev/aspeed-lpc-ctrl for 67108864
Feb 28 19:29:20 zaius mboxd[959]: [ 1488310160.671087005] Opening /dev/mtd6
Feb 28 19:29:20 zaius mboxd[959]: [ 1488310160.671308460] Loading flash into ram at 0x72f92000 for 0x04000000 bytes
Feb 28 19:29:40 zaius mboxd[959]: [ 1488310180.713765150] Setting all MBOX regs to 0xff individually...
Feb 28 19:29:40 zaius mboxd[959]: [ 1488310180.717647049] Entering polling loop
root@zaius:#

@sjitindarsingh
Copy link

Further investigation has determined that this is due to a bug in the mailbox daemon (mboxd) running on the bmc. When the nvram is updated it is erasing the skiboot partition and not writing it back again. This means that on every boot skiboot is detecting that the nvram in invalid and reinitialising it meaning that any changes aren't persistent across reboots.

To fix this I recommend updating to the latest mailbox daemon available in OpenBMC which has a fix for this problem.

The current state of your system means I believe it is impossible for nvram to be persistent through the skiboot boot process.

@johnhihi
Copy link
Author

Hi,

After I tried using tag v1.99.5@OpenBMC to validate, I found it is good for saving changed configurations.
Thank you for looking into this issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants