First, I answered the bold question in part 1: "Where can I look to find more information about what exactly is happening during this failure?"
The answer was in:
pi@raspberrypi:~ $ sudo systemctl status wpa_supplicant.service
● wpa_supplicant.service - WPA supplicant
Loaded: loaded (/lib/systemd/system/wpa_supplicant.service; enabled; vendor preset: enabled)
Active: failed (Result: exit-code) since Sun 2019-12-22 21:36:14 GMT; 53s ago
Process: 355 ExecStart=/sbin/wpa_supplicant -u -s -c /etc/wpa_supplicant/wpa_supplicant.conf -i wlan0 (code=exited, status=255/EXCEPTION)
Main PID: 355 (code=exited, status=255/EXCEPTION)
Dec 22 21:36:13 raspberrypi systemd: Starting WPA supplicant...
Dec 22 21:36:14 raspberrypi wpa_supplicant: Successfully initialized wpa_supplicant
Dec 22 21:36:14 raspberrypi systemd: Started WPA supplicant.
Dec 22 21:36:14 raspberrypi wpa_supplicant: ctrl_iface exists and seems to be in use - cannot override it
Dec 22 21:36:14 raspberrypi wpa_supplicant: Delete '/var/run/wpa_supplicant/wlan0' manually if it is not used anymore
Dec 22 21:36:14 raspberrypi wpa_supplicant: Failed to initialize control interface '/var/run/wpa_supplicant'.
You may have another wpa_supplicant process already running or the file was
left by an unclean termination of wpa_supplicant in which case you will need
to manually remove this file before starting wpa_supplicant again.
Dec 22 21:36:14 raspberrypi wpa_supplicant: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Dec 22 21:36:14 raspberrypi systemd: wpa_supplicant.service: Main process exited, code=exited, status=255/EXCEPTION
Dec 22 21:36:14 raspberrypi systemd: wpa_supplicant.service: Failed with result 'exit-code'.
So I checked out wpa_supplicant.service which was:
pi@raspberrypi:~ $ sudo cat /lib/systemd/system/wpa_supplicant.service
ExecStart=/sbin/wpa_supplicant -u -s -c /etc/wpa_supplicant/wpa_supplicant.conf -i wlan0
This configuration failed very frequently (at least 50%) of boots. A couple of weeks ago, I tried adding
which helped and lead to my "4 out of 5 times it works" situation. But still left me with those intermittent failures.
It struck me that maybe there is a race condition between the deletion of the stale file and the ExecStart command testing to make sure it was gone. So, just now, I changed ExecStartPre to
where /home/pi/deleteWpaSuppWlan0.sh is
After rebooting 10-15 times with no further problems, this seems like a satisfactory workaround. The 1 second pause gives the file deletion more time to finish deleting before wpa_supplicant tries to actually start up.
Note: The "-" symbol in the commands means that the command doesn't have to exit correctly for the systemd service to be considered started successfully. If /var/run/wpa_supplicant/wlan0 is already gone, we don't want the ExecStartPre command throwing errors. We want it to just move on quietly to wpa_supplicant startup.