ASR 1002 ios-xe update failure, physmap-flash errors, INVALID_BOOT_TRACE_CFG, Confreg corrupted

[wayfaring]

Not clear yet if all of these problems are related.  Main issue is that attempt to update from asr1000rp1-advipservicesk9.03.03.00.S.151-2.S.bin to asr1000rp1-adventerprisek9.03.13.05.S.154-3.S5-ext.bin is failing.  Verify /md5 result for the new image matches the Cisco hash.  New config boot lines are skipped and it reverts to the currently running default image.  The long series of physmap-flash errors occur after a reload regardless of whether an update was attempted.  Haven't run into these problems on our older IOS routers, any help with this beast is appreciated -

Current config before update attempt:

asr#sh ver
Cisco IOS Software, IOS-XE Software (PPC_LINUX_IOSD-ADVIPSERVICESK9-M), Version 15.1(2)S, RELEASE SOFTWARE (fc1)
Technical Support: http://www.cisco.com/techsupport
Copyright (c) 1986-2011 by Cisco Systems, Inc.
Compiled Thu 24-Mar-11 23:32 by mcpre

ROM: IOS-XE ROMMON

System returned to ROM by reload
System image file is "bootflash:/asr1000rp1-advipservicesk9.03.03.00.S.151-2.S.bin"
Last reload reason: Reload Command

cisco ASR1002 (2RU) processor with 1706515K/6147K bytes of memory.
4 Gigabit Ethernet interfaces
32768K bytes of non-volatile configuration memory.
4194304K bytes of physical memory.
7757823K bytes of eUSB flash at bootflash:.

Configuration register is 0x2101 (will be 0xFFFF at next reload)

asr#sh run | inc boot
boot-start-marker
boot-end-marker

Config that was written during update attempt:

asr#sh run | inc boot
boot-start-marker
boot system flash bootflash:asr1000rp1-adventerprisek9.03.13.05.S.154-3.S5-ext.bin
boot system flash bootflash:asr1000rp1-advipservicesk9.03.03.00.S.151-2.S.bin
boot-end-marker

asr#dir bootflash:
Directory of bootflash:/

   11  drwx       16384  Jan 11 2012 09:39:11 -07:00  lost+found
680065  drwx        4096  Jan 11 2012 09:40:13 -07:00  .installer
809601  drwx        4096  Jan 11 2012 10:12:58 -07:00  core
599105  drwx        4096   Mar 7 2016 19:47:20 -07:00  .prst_sync
615297  drwx        4096  Jan 11 2012 10:13:07 -07:00  .rollback_timer
   13  -rw-           0  Jan 11 2012 10:13:41 -07:00  tracelogs.606
566721  drwx        8192   Mar 7 2016 19:52:46 -07:00  tracelogs
   14  -rw-   304628024  Nov 15 2012 08:10:57 -07:00  asr1000rp1-advipservicesk9.03.03.00.S.151-2.S.bin
   12  -rw-   370973308   Mar 7 2016 16:06:12 -07:00  asr1000rp1-adventerprisek9.03.13.05.S.154-3.S5-ext.bin

asr#reload
Proceed with reload? [confirm]

*Mar  8 02:55:15.131: %SYS-5-RELOAD: Reload requested by admin on console. Reload Reason: Reload Command.
Mar  7 19:55:28.998 R0/0: %PMAN-5-EXITACTION: Process manager is exiting: process exit with reload chassis code

System Bootstrap, Version 12.2(33r)XNC, RELEASE SOFTWARE (fc1)
Technical Support: http://www.cisco.com/techsupport
Copyright (c) 2009 by cisco Systems, Inc.

SPD PROM contents for slot 0
8008080E 0A614800 05304502 82080800 0C083801 1005033D 5050603C 1E3C2D01
20271017 3C1E1E00 063C7F80 18220F00 00000000 00000000 00000000 00001247
calculated chksum = 00000047; stored chksum = 00000047

SPD PROM contents for slot 1
8008080E 0A614800 05304502 82080800 0C083801 1005033D 5050603C 1E3C2D01
20271017 3C1E1E00 063C7F80 18220F00 00000000 00000000 00000000 00001247
calculated chksum = 00000047; stored chksum = 00000047

Clearing bss... done

CPU Version: 2.1.x
CPU Clock freqs: sys:100000000 CCB:400000000 Core:1400000000
                 local:50000000 i2c:97656 MII:1785714
CPLD Version: 23 (MM/DD/YY): 01/10/08 ASR1002-RP1 Slot:0

Current image running: Boot ROM0
Last reset cause: LocalSoft
Last reset at: Tue Mar 08 02:55:47 UTC 2016

Confreg is corrupted, using default 0x8000

Correcting the primary nv_flash

ASR1002-RP1 platform with 4194303 Kbytes of main memory

boot: unsupported boot device "flash"
autoboot: boot failed, restarting...

System Bootstrap, Version 12.2(33r)XNC, RELEASE SOFTWARE (fc1)
Technical Support: http://www.cisco.com/techsupport
Copyright (c) 2009 by cisco Systems, Inc.

Current image running: Boot ROM0
Last reset cause: LocalSoft
Last reset at: Tue Mar 08 02:56:07 UTC 2016

ASR1002-RP1 platform with 4194303 Kbytes of main memory

boot: unsupported boot device "flash"
autoboot: boot failed, restarting...

System Bootstrap, Version 12.2(33r)XNC, RELEASE SOFTWARE (fc1)
Technical Support: http://www.cisco.com/techsupport
Copyright (c) 2009 by cisco Systems, Inc.

Current image running: Boot ROM0
Last reset cause: LocalSoft
Last reset at: Tue Mar 08 02:56:28 UTC 2016

ASR1002-RP1 platform with 4194303 Kbytes of main memory

no valid BOOT image found
Final autoboot attempt from default boot device...
Located tracelogs.606
Image size 0 inode num 13, bks cnt 0 blk size 8*512

Boot image size = 0 (0x0) bytes
Located asr1000rp1-advipservicesk9.03.03.00.S.151-2.S.bin
Image size 304628024 inode num 14, bks cnt 74373 blk size 8*512
#############################################################################

Boot image size = 304628024 (0x12284138) bytes

Missing or illegal ip address for variable DEFAULT_GATEWAY
Using midplane macaddr
Missing or illegal ip address for variable IP_ADDRESS
Missing or illegal ip address for variable IP_SUBNET_MASK
Package header rev 0 structure detected
Calculating SHA-1 hash...done
validate_package: SHA-1 hash:
        calculated 8a599bb4:81792bce:6e6023aa:c61924cb:1c909603
        expected   8a599bb4:81792bce:6e6023aa:c61924cb:1c909603
Image validated

Cisco IOS Software, IOS-XE Software (PPC_LINUX_IOSD-ADVIPSERVICESK9-M), Version 15.1(2)S, RELEASE SOFTWARE (fc1)
Technical Support: http://www.cisco.com/techsupport
Copyright (c) 1986-2011 by Cisco Systems, Inc.
Compiled Thu 24-Mar-11 23:32 by mcpre

cisco ASR1002 (2RU) processor with 1706515K/6147K bytes of memory.
4 Gigabit Ethernet interfaces
32768K bytes of non-volatile configuration memory.
4194304K bytes of physical memory.
7757823K bytes of eUSB flash at bootflash:.

User Access Verification

Username:
% Username:  timeout expired!
Username:
% Username:  timeout expired!
Username:
*Mar  8 03:01:56.211: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:01:56.211: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d27d4 failed. returned -62, retlen 44
*Mar  8 03:01:56.915: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:01:56.915: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:01:56.915: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:01:57.649: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:01:58.362: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:01:58.362: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:01:58.362: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:01:59.106: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:01:59.106: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:01:59.106: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:01:59.841: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:00.557: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:00.557: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:00.557: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:01.331: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:01.331: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:01.331: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:02.092: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:02.092: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:02.092: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:02.938: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:02.938: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:02.938: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:03.851: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:03.851: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:03.851: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:04.854: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:04.854: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:04.854: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:05.735: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:05.735: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:05.735: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:06.545: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:06.545: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:06.545: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:07.276: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:07.276: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:07.276: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:08.006: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:08.006: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:08.006: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:08.752: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:08.752: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:08.752: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:09.479: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:09.479: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:09.479: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:10.184: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:10.184: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:10.184: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:10.883: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:10.883: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:10.883: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:11.652: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:11.652: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:11.652: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:12.383: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:12.383: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:12.383: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:13.095: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:13.095: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:13.095: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:13.820: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:13.820: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:13.820: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:14.556: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:14.556: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:14.556: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:15.269: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:15.269: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:15.269: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:16.031: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:16.031: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:16.031: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:16.743: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:16.743: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:16.743: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:17.473: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xstatus = c4, status = c4
*Mar  8 03:02:17.473: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62, retlen 0
*Mar  8 03:02:17.473: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because the flash driver returned retlen zero
*Mar  8 03:02:18.192: %IOSXE-3-PLATFORM: R0/0: kernel: physmap-flash.0: Chip not ready for buffer write. Xsta= c4
*Mar  8 03:02:18.192: %IOSXE-5-PLATFORM: R0/0: kernel: Write of 104 bytes at 0x001d283c failed. returned -62,
*Mar  8 03:02:18.192: %IOSXE-5-PLATFORM: R0/0: kernel: Not marking the space at 0x001d283c as dirty because teturned retlen zero

[Iulian Vaideanu · Accepted solution]

First of all, I'd check the ROMMON versions ("show platform") and upgrade to the latest available - 12.2(33r)XNC is way too old for IOS XE 3.13S anyway, and newer ROMMONs also fix bugs.

Second, I'd be curious about what "fsck bootflash:" says...

[wayfaring]

you are correct, cisco documentation indicated the rommon version was below the threshold for the ios-xe version: 

http://www.cisco.com/c/en/us/td/docs/routers/asr1000/release/notes/asr1k_rn_rel_notes/asr1k_rn_sys_req.html#19706

Table 6 Minimum ROMmon Release Supported for RP and ESP FRUs

Cisco IOS XE Release   FRU ASR 1002 RP1

3.13.x                                    XND1

Table 8 Recommended ROMmon Release for RP and ESP FRUs

Cisco IOS XE Release       FRU ASR 1002 RP1

3.13.x                  15.5(3r)S1

In the end we did get around the problems or bug without upgrading rommon.  manually booting the new image from rommon and setting confreg was required to permit ios-xe update to move forward and subsequent reloads no longer have errors.  rough notes from the process -

erase nvram
confreg 0x2142
reload
confreg is 0x2101
erase nvram
conf t
config-register 0x0
reload
goes to rommon
dir bootflash:
boot bootflash:imagename.bin
system loads
change to 0x2102
reload

success!