Installation crashes if proxy server is specified in subiquity

[Frank Heimes]

Usually I do installation without using a proxy, since that is not needed in the environment that I use.
But trying to recreate a certain situation I specified a proxy in subiquity (not in the early basic network setup that is done at the console), subiquity crashed on the next screen.
I tried 3 different settings and the crash occurred with all of them:
1)
http://squid.internal:3128
2)
http://squid.internal:3128/
3)
http://<IP address>:3128/
Then I did an exact same installation on the same system, just w/o specifying a proxy and the installation was successful.

This happened for me on an s390x LPAR, but I don't think it's really related to s390x per-se (maybe related to the network environment the s390x is in.)

I've attached the logs and crash file of all 3 cases, even if I'm sure that it's always the same root cause.

 2022-11-17 12:28:30,321 DEBUG root:37 start: subiquity/Install/install/configure_apt/cmd-in-target: curtin command in-target
 2022-11-17 12:28:34,659 ERROR root:37 finish: subiquity/Install/install/configure_apt: FAIL: Command '['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.2206', '--property', 'PrivateMounts=yes', '--setenv', 'PATH=/snap/subiquity/4005/bin:/snap/subiquity/4005/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4005/bin:/snap/subiquity/4005/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4005/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4005/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4005', '--', '/snap/subiquity/4005/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.2206.2"}}', 'in-target', '-t', '/tmp/tmpnsi0z5q9/mount', '--', 'apt-get', 'update']' returned non-zero exit status 100.
 2022-11-17 12:28:34,660 DEBUG subiquity.common.errorreport:384 generating crash report
 2022-11-17 12:28:34,662 INFO subiquity.common.errorreport:406 saving crash report 'install failed crashed with CalledProcessError' to /var/crash/1668688114.660152674.install_fail.crash
 2022-11-17 12:28:34,662 ERROR root:37 finish: subiquity/Install/install: FAIL: Command '['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.2206', '--property', 'PrivateMounts=yes', '--setenv', 'PATH=/snap/subiquity/4005/bin:/snap/subiquity/4005/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4005/bin:/snap/subiquity/4005/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4005/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4005/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4005', '--', '/snap/subiquity/4005/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.2206.2"}}', 'in-target', '-t', '/tmp/tmpnsi0z5q9/mount', '--', 'apt-get', 'update']' returned non-zero exit status 100.
 2022-11-17 12:28:34,662 INFO root:37 start: subiquity/ErrorReporter/1668688114.660152674.install_fail/add_info:
InstallerServerLogInfo:
 2022-11-17 12:27:03,110 INFO subiquity:152 Starting Subiquity server revision 4005
 2022-11-17 12:27:03,110 INFO subiquity:153 Arguments passed: ['/snap/subiquity/4005/lib/python3.8/site-packages/subiquity/cmd/server.py']
 2022-11-17 12:27:03,232 INFO aiohttp.access:233 [17/Nov/2022:12:27:03 +0000] "GET /meta/status?cur=null HTTP/1.1" 200 419 "-" "Python/3.8 aiohttp/3.6.2"
 2022-11-17 12:27:03,974 INFO aiohttp.access:233 [17/Nov/2022:12:27:03 +0000] "GET /meta/status?cur=null HTTP/1.1" 200 419 "-" "Python/3.8 aiohttp/3.6.2"

(Btw. I've tried this on kinetic only so far ...)

[Olivier Gayot (ogayot)]

The root cause is indeed the same in both three reports. The proxy server returns HTTP 403 Forbidden when trying to download files through apt-get update.

Nov 17 13:57:42 ubuntu-server subiquity_log.2216[3059]: Err:5 http://ports.ubuntu.com/ubuntu-ports kinetic InRelease
Nov 17 13:57:42 ubuntu-server subiquity_log.2216[3059]: 403 Forbidden [IP: 185.125.188.85 3128]
Nov 17 13:57:42 ubuntu-server subiquity_log.2216[3059]: Err:6 http://ports.ubuntu.com/ubuntu-ports kinetic-updates InRelease
Nov 17 13:57:42 ubuntu-server subiquity_log.2216[3059]: 403 Forbidden [IP: 185.125.188.85 3128]
Nov 17 13:57:42 ubuntu-server subiquity_event.2216[2216]: curtin command in-target
Nov 17 13:57:42 ubuntu-server subiquity_log.2216[3059]: Err:7 http://ports.ubuntu.com/ubuntu-ports kinetic-backports InRelease
Nov 17 13:57:42 ubuntu-server subiquity_log.2216[3059]: 403 Forbidden [IP: 185.125.188.85 3128]
Nov 17 13:57:43 ubuntu-server subiquity_log.2216[3059]: Err:8 http://ports.ubuntu.com/ubuntu-ports kinetic-security InRelease
Nov 17 13:57:43 ubuntu-server subiquity_log.2216[3059]: 403 Forbidden [IP: 185.125.188.85 3128]

You can try reaching the website manually through your proxy, and check if additional settings are needed.

 $ curl --proxy http://squid.internal:3128 http://ports.ubuntu.com/ubuntu-ports

On a side note, there is ongoing work in subiquity to make it show the output of `$ apt-get update` to the user ; and to give the user an opportunity to fix any issue by adjusting some of the settings. In other words, we are planning on "testing" the mirror before proceeding with the install. Hopefully this should give the user a better experience.

As for your test, maybe you could try a different proxy :)

[Frank Heimes (fheimes)]

Hi Olivier, thanks having a look at this.
Yes I've noticed that not all locations are accessible using the (our) proxy (already realized it in earlier use cases), but that's the nature of a proxy, that it often allows only selective access to the 'outside'.

But I think this must not lead to a crash and should be caught properly, to make installations (esp. in enterprise environments) more robust, no?!

Usually I do not need a proxy at all in my environment - it was just a test, trying to recreated a different situation (LP#1996006 and LP#1996006 - and I think that this could be related, but since I'm unsure, I've created this separate bug).