[PATCH v3 00/11] sysupgrade: reword and organize log lines

[Yousong Zhou]

The series mainly aims to make sysupgrade log output more organized and
less disturbing, in the following aspects

 - Hide "write error: Broken pipe" from cat command and its friends
 - Hide "F+P records in/out" lines from dd command
 - Make log lines from sysupgrade command itself more distinguishable
   than other commands by using common.sh function "v"

The series should at least partially address concerns raised at FS#3140

Ref: https://bugs.openwrt.org/index.php?do=details&task_id=3140

v3 <- v2

 - rework get_image_dd to not mix stderr/stdout content and filter only on
   stderr messages
 - reword the "comment as log" commit to reflect current status of this series
 - add vn, _vn, _v variant for lines needing "echo -n".  E.g. "Sending xx to
   remaining processes", "Supported devices: ..."

v2 <- v1

 - Make date command available in ramdisk and prefix log lines with datetime
 - Hide "F+P records in/out" stderr output from dd command

Sysupgrade stdio dumps attached below for comparison

v3

  Tue Nov 10 13:40:34 UTC 2020 upgrade: Image metadata not present
  Tue Nov 10 13:40:34 UTC 2020 upgrade: Reading partition table from bootdisk...
  Tue Nov 10 13:40:34 UTC 2020 upgrade: Extract boot sector from the image
  Tue Nov 10 13:40:35 UTC 2020 upgrade: Reading partition table from image...
  Tue Nov 10 13:40:35 UTC 2020 upgrade: Commencing upgrade. Closing all shell sessions.
  killall: telnetd: no process killed
  Tue Nov 10 13:40:35 UTC 2020 upgrade: Sending TERM to remaining processes ... ubusd askfirst urngd logd netifd odhcpd xl2tpd ntpd dnsmasq
  Tue Nov 10 13:40:38 UTC 2020 upgrade: Sending KILL to remaining processes ...
  Tue Nov 10 13:40:39 UTC 2020 upgrade: Switching to ramdisk...
  [  108.061617] EXT4-fs (vda2): re-mounted. Opts: (null)
  Tue Nov 10 13:40:39 UTC 2020 upgrade: Performing system upgrade...
  Tue Nov 10 13:40:39 UTC 2020 upgrade: Reading partition table from bootdisk...
  Tue Nov 10 13:40:39 UTC 2020 upgrade: Extract boot sector from the image
  Tue Nov 10 13:40:39 UTC 2020 upgrade: Reading partition table from image...
  Tue Nov 10 13:40:39 UTC 2020 upgrade: Writing image to /dev/vda1...
  Tue Nov 10 13:40:40 UTC 2020 upgrade: Writing image to /dev/vda2...
  Tue Nov 10 13:40:45 UTC 2020 upgrade: Writing new UUID to /dev/vda...
  [  113.637564] F2FS-fs (vda1): Magic Mismatch, valid(0xf2f52010) - read(0x0)
  [  113.645289] F2FS-fs (vda1): Can't find valid F2FS filesystem in 1th superblock
  [  113.656026] F2FS-fs (vda1): Magic Mismatch, valid(0xf2f52010) - read(0x6020601)
  [  113.667033] F2FS-fs (vda1): Can't find valid F2FS filesystem in 2th superblock
  Tue Nov 10 13:40:45 UTC 2020 upgrade: Upgrading bootloader on /dev/vda...
  Tue Nov 10 13:40:51 UTC 2020 upgrade: Upgrade completed
  Tue Nov 10 13:40:52 UTC 2020 upgrade: Rebooting system...
  umount: can't unmount /dev: Resource busy
  umount: can't unmount /tmp: Resource busy
  [  121.226308] Unregister pv shared memory for cpu 0
  [  121.236284] reboot: Restarting system
  [  121.241691] reboot: machine restart

v2

  Tue Nov 10 02:04:04 UTC 2020 upgrade: Image metadata not present
  Tue Nov 10 02:04:04 UTC 2020 upgrade: Reading partition table from bootdisk...
  Tue Nov 10 02:04:04 UTC 2020 upgrade: Extract boot sector from the image
  Tue Nov 10 02:04:05 UTC 2020 upgrade: Reading partition table from image...
  Tue Nov 10 02:04:05 UTC 2020 upgrade: Commencing upgrade. Closing all shell sessions.
  killall: telnetd: no process killed
  Sending TERM to remaining processes ... ubusd askfirst urngd logd netifd odhcpd xl2tpd ntpd dnsmasq
  Sending KILL to remaining processes ...
  Tue Nov 10 02:04:09 UTC 2020 upgrade: Switching to ramdisk...
  [   25.995408] EXT4-fs (vda2): re-mounted. Opts: (null)
  Tue Nov 10 02:04:09 UTC 2020 upgrade: Performing system upgrade...
  Tue Nov 10 02:04:09 UTC 2020 upgrade: Reading partition table from bootdisk...
  Tue Nov 10 02:04:10 UTC 2020 upgrade: Extract boot sector from the image
  Tue Nov 10 02:04:10 UTC 2020 upgrade: Reading partition table from image...
  Tue Nov 10 02:04:10 UTC 2020 upgrade: Writing image to /dev/vda1...
  Tue Nov 10 02:04:11 UTC 2020 upgrade: Writing image to /dev/vda2...
  Tue Nov 10 02:04:15 UTC 2020 upgrade: Writing new UUID to /dev/vda...
  [   31.582751] F2FS-fs (vda1): Magic Mismatch, valid(0xf2f52010) - read(0x0)
  [   31.598842] F2FS-fs (vda1): Can't find valid F2FS filesystem in 1th superblock
  [   31.613440] F2FS-fs (vda1): Magic Mismatch, valid(0xf2f52010) - read(0x6020601)
  [   31.623241] F2FS-fs (vda1): Can't find valid F2FS filesystem in 2th superblock
  Tue Nov 10 02:04:15 UTC 2020 upgrade: Upgrading bootloader on /dev/vda...
  Tue Nov 10 02:04:22 UTC 2020 upgrade: Upgrade completed
  Tue Nov 10 02:04:23 UTC 2020 upgrade: Rebooting system...
  umount: can't unmount /dev: Resource busy
  umount: can't unmount /tmp: Resource busy
  [   39.168155] Unregister pv shared memory for cpu 0
  [   39.177657] reboot: Restarting system
  [   39.183596] reboot: machine restart

v1

  root at OpenWrt:/# sysupgrade -n -v /tmp/x86.gz
  == upgrade: Image metadata not present
  == upgrade: Reading partition table from bootdisk...
  == upgrade: Extract boot sector from the image
  54+9 records in
  54+9 records out
  == upgrade: Reading partition table from image...
  == upgrade: Commencing upgrade. Closing all shell sessions.
  killall: telnetd: no process killed
  Sending TERM to remaining processes ... ubusd askfirst urngd logd netifd odhcpd xl2tpd ntpd dnsmasq
  Sending KILL to remaining processes ...
  == upgrade: Switching to ramdisk...
  == upgrade: Performing system upgrade...
  == upgrade: Reading partition table from bootdisk...
  == upgrade: Extract boot sector from the image
  0+63 records in
  0+63 records out
  == upgrade: Reading partition table from image...
  == upgrade: Writing image to /dev/vda1...
  65535+0 records in
  31+1 records out
  == upgrade: Writing image to /dev/vda2...
  262143+0 records in
  127+1 records out
  == upgrade: Writing new UUID to /dev/vda...
  4+0 records in
  4+0 records out
  [   98.737664] F2FS-fs (vda1): Magic Mismatch, valid(0xf2f52010) - read(0x0)
  [   98.747115] F2FS-fs (vda1): Can't find valid F2FS filesystem in 1th superblock
  [   98.757250] F2FS-fs (vda1): Magic Mismatch, valid(0xf2f52010) - read(0x6020601)
  [   98.770807] F2FS-fs (vda1): Can't find valid F2FS filesystem in 2th superblock
  == upgrade: Upgrading bootloader on /dev/vda...
  == upgrade: Upgrade completed
  == upgrade: Rebooting system...
  umount: can't unmount /dev: Resource busy
  umount: can't unmount /tmp: Resource busy
  [  106.922638] Unregister pv shared memory for cpu 0
  [  106.931062] reboot: Restarting system
  [  106.936009] reboot: machine restart

Original

  root@(none):/# sysupgrade -n -v /tmp/x86.gz
  Image metadata not found
  Reading partition table from bootdisk...
  zcat: write error: Broken pipe
  zcat: write: Broken pipe
  Reading partition table from image...
  Commencing upgrade. Closing all shell sessions.
  killall: telnetd: no process killed
  Sending TERM to remaining processes ... ubusd askfirst urngd logd netifd odhcpd ntpd dnsmasq
  Sending KILL to remaining processes ...
  Switching to ramdisk...
  Performing system upgrade...
  Reading partition table from bootdisk...
  0+63 records in
  0+63 records out
  zcat: write error: Broken pipe
  zcat: write: Broken pipe
  Reading partition table from image...
  Writing image to /dev/vda1...
  zcat: write error: Broken pipe
  zcat: write: Broken pipe
  32767+0 records in
  15+1 records out
  Writing image to /dev/vda2...
  212991+0 records in
  103+1 records out
  Writing new UUID to /dev/vda...
  4+0 records in
  4+0 records out
  zcat: write error: Broken pipe
  zcat: write: Broken pipe
  [   31.461949] F2FS-fs (vda1): Magic Mismatch, valid(0xf2f52010) - read(0x0)
  [   31.470274] F2FS-fs (vda1): Can't find valid F2FS filesystem in 1th superblock
  [   31.480216] F2FS-fs (vda1): Magic Mismatch, valid(0xf2f52010) - read(0x6020601)
  [   31.491775] F2FS-fs (vda1): Can't find valid F2FS filesystem in 2th superblock
  Upgrading bootloader on /dev/vda...
  Upgrade completed
  Rebooting system...
  umount: can't unmount /dev: Resource busy
  umount: can't unmount /tmp: Resource busy
  [   38.511806] Unregister pv shared memory for cpu 0
  [   38.519259] reboot: Restarting system
  [   38.523725] reboot: machine restart

Yousong Zhou (11):
  base-files: upgrade: log with date prefix
  base-files: upgrade: add vn and variants
  base-files: upgrade: use stdin redirection to replace cat command
  base-files: upgrade: add get_image_dd()
  base-files: upgrade: fwtool.sh: use v for log lines
  base-files: upgrade: fwtool.sh: rewording logs
  base-files: upgrade: stage2: use v for log lines
  base-files: bump PKG_RELEASE
  x86: upgrade: use v function for writting logs
  x86: upgrade: use get_image_dd
  x86: upgrade: make code comment appear as log lines

 package/base-files/Makefile                   |  2 +-
 .../base-files/files/lib/upgrade/common.sh    | 27 ++++++++++++++--
 .../base-files/files/lib/upgrade/fwtool.sh    | 26 +++++++--------
 package/base-files/files/lib/upgrade/stage2   | 16 +++++-----
 .../x86/base-files/lib/upgrade/platform.sh    | 32 +++++++++----------
 5 files changed, 62 insertions(+), 41 deletions(-)