Add some logging

Signed-off-by: Hector Martin <[email protected]>

Author: marcan

src/diskutil.py

@@ -1,5 +1,5 @@
 # SPDX-License-Identifier: MIT
-import plistlib, subprocess, sys
+import plistlib, subprocess, sys, logging
 from dataclasses import dataclass
 
 @dataclass
@@ -21,21 +21,23 @@ def __init__(self):
         self.verbose = "-v" in sys.argv
 
     def action(self, *args, verbose=False):
-        if verbose and self.verbose:
-            print(" + diskutil " + " ".join(args))
+        logging.info(f"run: diskutil {args!r}")
         subprocess.run(["diskutil"] + list(args), check=True, capture_output=(not self.verbose))
 
     def get(self, *args):
+        logging.info(f"get: diskutil {args!r}")
         result = subprocess.run(["diskutil"] + list(args),
                                 stdout=subprocess.PIPE, check=True)
         return plistlib.loads(result.stdout)
 
     def get_list(self):
+        logging.info(f"DiskUtil.get_list()")
         self.list = self.get("list", "-plist")
         self.disk_list = self.list["WholeDisks"]
         self.disk_parts = {dsk["DeviceIdentifier"]: dsk for dsk in self.list["AllDisksAndPartitions"]}
 
     def get_apfs_list(self, dev=None):
+        logging.info(f"DiskUtil.get_apfs_list()")
         if dev:
             apfs = self.get("apfs", "list", dev, "-plist")
         else:
@@ -47,18 +49,21 @@ def get_apfs_list(self, dev=None):
             self.ctnr_by_store[ctnr["DesignatedPhysicalStore"]] = ctnr
 
     def get_disk_info(self):
+        logging.info(f"DiskUtil.get_disk_info()")
         self.disks = {}
         for i in self.disk_list:
             self.disks[i] = self.get("info", "-plist", i)
 
     def get_info(self):
+        logging.info(f"DiskUtil.get_info()")
         self.get_list()
         self.ctnr_by_ref = {}
         self.ctnr_by_store = {}
         self.get_apfs_list()
         self.get_disk_info()
 
     def find_system_disk(self):
+        logging.info(f"DiskUtil.find_system_disk()")
         for name, dsk in self.disks.items():
             try:
                 if dsk["VirtualOrPhysical"] == "Virtual":
@@ -67,12 +72,14 @@ def find_system_disk(self):
                     continue
                 parts = self.disk_parts[name]["Partitions"]
                 if parts[0]["Content"] == "Apple_APFS_ISC":
+                    logging.info(f"System disk: {name}")
                     return name
             except (KeyError, IndexError):
                 continue
         raise Exception("Could not find system disk")
 
     def get_partition_info(self, dev, refresh_apfs=False):
+        logging.info(f"DiskUtil.get_partition_info({dev=!r}, {refresh_apfs=!r})")
         partinfo = self.get("info", "-plist", dev)
         off = partinfo["PartitionMapPartitionOffset"]
         part = Partition(name=partinfo["DeviceIdentifier"], free=False,
@@ -96,6 +103,7 @@ def get_partition_info(self, dev, refresh_apfs=False):
         return part
 
     def get_partitions(self, dskname):
+        logging.info(f"DiskUtil.get_partitions({dskname!r})")
         dsk = self.disk_parts[dskname]
         parts = []
         total_size = dsk["Size"]
@@ -120,6 +128,7 @@ def get_partitions(self, dskname):
         return parts2
 
     def refresh_part(self, part):
+        logging.info(f"DiskUtil.refresh_part({part.name=!r})")
         self.get_apfs_list(part.container["ContainerReference"])
         part.container = self.ctnr_by_store[part.name]
 

src/firmware/__init__.py

@@ -1,5 +1,5 @@
 # SPDX-License-Identifier: MIT
-import tarfile, io, os
+import tarfile, io, os, logging
 from hashlib import sha256
 
 class FWFile(object):
@@ -42,6 +42,7 @@ def add_file(self, name, data):
             self.hashes[data.sha] = name
             self.manifest.append(f"FILE {name} SHA256 {data.sha}")
 
+        logging.info(f"+ {self.manifest[-1]}")
         self.tarfile.addfile(ti, fd)
 
     def add_files(self, it):

src/firmware/wifi.py

@@ -1,5 +1,5 @@
 # SPDX-License-Identifier: MIT
-import sys, os, os.path, pprint, statistics
+import sys, os, os.path, pprint, statistics, logging
 
 from . import FWFile
 

src/main.py

@@ -446,4 +446,6 @@ def main(self):
             sys.exit(0)
 
 if __name__ == "__main__":
+    logging.basicConfig(level=logging.INFO)
+    logging.info("Startup")
     InstallerMain().main()

src/stub.py

@@ -1,5 +1,5 @@
 # SPDX-License-Identifier: MIT
-import os, plistlib, shutil, sys, stat, subprocess, urlcache, zipfile
+import os, os.path, plistlib, shutil, sys, stat, subprocess, urlcache, zipfile, logging
 import osenum
 from util import split_ver
 
@@ -18,13 +18,15 @@ def __init__(self, sysinfo, dutil, osinfo, ipsw_info):
         print()
 
     def prepare_volume(self, part):
+        logging.info(f"StubInstaller.prepare_volume({part.name=!r})")
         self.part = part
 
         by_role = {}
 
         ctref = self.part.container["ContainerReference"]
 
         print("Preparing target volumes...")
+        logging.info("Preparing target volumes")
 
         for volume in self.part.container["Volumes"]:
             by_role.setdefault(tuple(volume["Roles"]), []).append(volume)
@@ -62,13 +64,13 @@ def prepare_volume(self, part):
             self.dutil.addVolume(ctref, "Recovery", role="R")
 
         self.dutil.refresh_part(self.part)
-        if self.verbose:
-            print()
 
     def check_volume(self, part=None):
         if part:
             self.part = part
 
+        logging.info(f"StubInstaller.check_volume({self.part.name=!r})")
+
         print("Checking volumes...")
         os = self.osinfo.collect_part(self.part)
 
@@ -133,14 +135,19 @@ def extract_tree(self, src, dest):
                 self.ucache.flush_progress()
 
     def chflags(self, flags, path):
+        logging.info(f"chflags {flags} {path}")
         subprocess.run(["chflags", flags, path], check=True)
 
     def install_files(self, cur_os):
+        logging.info("StubInstaller.install_files()")
+        logging.info(f"VGID: {self.osi.vgid}")
+        logging.info(f"OS info: {self.osi}")
+
         print("Beginning stub OS install...")
         ipsw = self.ipsw
 
-        if self.verbose:
-            print("Parsing metadata...")
+        logging.info("Parsing metadata...")
+
         sysver = plistlib.load(ipsw.open("SystemVersion.plist"))
         manifest = plistlib.load(ipsw.open("BuildManifest.plist"))
         bootcaches = plistlib.load(ipsw.open("usr/standalone/bootcaches.plist"))
@@ -157,13 +164,12 @@ def install_files(self, cur_os):
         else:
             raise Exception("Failed to locate a usable build identity for this device")
 
-        if self.verbose:
-            print(f'Using OS build {identity["Info"]["BuildNumber"]} for {self.sysinfo.device_class}')
-            print()
+        logging.info(f'Using OS build {identity["Info"]["BuildNumber"]} for {self.sysinfo.device_class}')
 
         manifest["BuildIdentities"] = [identity]
 
         print("Setting up System volume...")
+        logging.info("Setting up System volume")
 
         self.extract("usr/standalone/bootcaches.plist", self.osi.system)
         shutil.copy("logo.icns", os.path.join(self.osi.system, ".VolumeIcon.icns"))
@@ -178,6 +184,7 @@ def install_files(self, cur_os):
 
         # Make the icon work
         try:
+            logging.info(f"xattr -wx com.apple.FinderInfo .... {self.osi.system}")
             subprocess.run(["xattr", "-wx", "com.apple.FinderInfo",
                            "0000000000000000040000000000000000000000000000000000000000000000",
                            self.osi.system], check=True)
@@ -198,12 +205,12 @@ def install_files(self, cur_os):
         if self.verbose:
             print()
         print("Setting up Data volume...")
+        logging.info("Setting up Data volume")
 
         os.makedirs(os.path.join(self.osi.data, "private/var/db/dslocal"), exist_ok=True)
 
-        if self.verbose:
-            print()
         print("Setting up Preboot volume...")
+        logging.info("Setting up Preboot volume")
 
         pb_vgid = os.path.join(self.osi.preboot, self.osi.vgid)
         os.makedirs(pb_vgid, exist_ok=True)
@@ -255,21 +262,20 @@ def install_files(self, cur_os):
             os.unlink(sys_restore_bundle)
         os.symlink(restore_bundle, sys_restore_bundle)
 
-        if self.verbose:
-            print()
         print("Setting up Recovery volume...")
+        logging.info("Setting up Recovery volume")
 
         rec_vgid = os.path.join(self.osi.recovery, self.osi.vgid)
         os.makedirs(rec_vgid, exist_ok=True)
 
         basesystem_path = os.path.join(rec_vgid, "usr/standalone/firmware")
         os.makedirs(basesystem_path, exist_ok=True)
 
+        logging.info("Extracting arm64eBaseSystem.dmg")
         self.extract_file(identity["Manifest"]["BaseSystem"]["Info"]["Path"],
                           os.path.join(basesystem_path, "arm64eBaseSystem.dmg"))
         self.ucache.flush_progress()
 
-        if self.verbose:
-            print()
         print("Stub OS installation complete.")
+        logging.info("Stub OS installed")
         print()

src/urlcache.py

@@ -1,5 +1,5 @@
 # SPDX-License-Identifier: MIT
-import os, sys, os.path, time
+import os, sys, os.path, time, logging
 from dataclasses import dataclass
 
 from urllib import request
@@ -45,7 +45,8 @@ def get_partial(self, off, size):
         return fd.read()
 
     def get_block(self, blk):
-        #print("get_block", blk)
+        logging.debug(f"get_block {blk}")
+
         if blk in self.cache:
             return self.cache[blk]
 
@@ -61,11 +62,12 @@ def get_block(self, blk):
         retries = 5
         for retry in range(retries + 1):
             try:
+                logging.debug(f"get_partial {off} {size}")
                 data = self.get_partial(off, size)
             except Exception as e:
                 if retry == retries:
                     print(f"Exceeded maximum retries downloading data.")
-                    sys.exit(1)
+                    raise
                 print(f"Error downloading data ({e}), retrying... ({retry + 1}/{retries})")
                 time.sleep(1)
             else:

src/util.py

@@ -1,5 +1,5 @@
 # SPDX-License-Identifier: MIT
-import re
+import re, logging
 
 def ssize(v):
     suffixes = ["B", "KB", "MB", "GB", "TB"]