magic-proxy does not gracefully handle error conditions

Bug #1946520 reported by Pat Viafore
14
This bug affects 2 people
Affects Status Importance Assigned to Milestone
livecd-rootfs (Ubuntu)
Fix Released
Undecided
Thomas Bechtold
Focal
Fix Released
Undecided
Unassigned
Hirsute
Fix Released
Undecided
Thomas Bechtold
Impish
Fix Released
Undecided
Thomas Bechtold

Bug Description

[Impact]
The fixes for this bug (including the fixes for LP:#1944906) need to be backported to hirsute, focal and bionic) to be able to re-enable the "repo-snapshot-stamp" feature for image builds. That feature is important to get consistent image builds (means the same set of packages included in the different images) when doing multiple builds (eg. for AWS, Azure and GCE).

[Test plan]
1) sudo iptables -v -t nat -A OUTPUT -p tcp --dport 80 -m owner ! --uid-owner daemon -j REDIRECT --to 8080
2) sudo ./magic-proxy --address="127.0.0.1" --port=8080 --run-as=daemon --cutoff-time=1632467595 --setsid --log-file mp.log
3) curl http://169.254.169.254/latest/meta-data/instance-id
(there should be no route to that host to trigger the error case, so don't do that in an EC2 instance)
4) sudo killall magic-proxy
5) cat mp.log
6) The problem "AttributeError: 'TimeoutError' object has no attribute 'replace'" should not be in the logfile

[Where problems could occur]
The codepath that will be changed is only executed in livecd-rootfs if the repo-snapshot-stamp feature is enabled. AFAIK this is only enabled for CPC builds so if there are problems, it will only affect CPC team builds. And there, builds (at least for AWS) are currently broken anyway due to this bug.

[Original description]
During an impish build of ubuntu-cpc images with magic-proxy enabled, the installation of certain packages tried to reach an internet endpoint (specifically http://169.254.169.254/latest/meta-data/instance-id - which appears to be used for EC2 metadata)

The magic-proxy log indicated :

10.10.10.2 - - [01/Oct/2021 13:21:26] urlopen() failed for http://169.254.169.254/2009-04-04/meta-data/instance-id with [Errno 110] Connection timed out
10.10.10.2 - - [01/Oct/2021 13:21:26] code 501, message [Errno 110] Connection timed out
10.10.10.2 - - [01/Oct/2021 13:21:26] "GET /2009-04-04/meta-data/instance-id HTTP/1.1" 501 -
----------------------------------------
Exception occurred during processing of request from ('10.10.10.2', 49672)
Traceback (most recent call last):
  File "/usr/lib/python3.9/urllib/request.py", line 1346, in do_open
    h.request(req.get_method(), req.selector, req.data, headers,
  File "/usr/lib/python3.9/http/client.py", line 1279, in request
    self._send_request(method, url, body, headers, encode_chunked)
  File "/usr/lib/python3.9/http/client.py", line 1325, in _send_request
    self.endheaders(body, encode_chunked=encode_chunked)
  File "/usr/lib/python3.9/http/client.py", line 1274, in endheaders
    self._send_output(message_body, encode_chunked=encode_chunked)
  File "/usr/lib/python3.9/http/client.py", line 1034, in _send_output
    self.send(msg)
  File "/usr/lib/python3.9/http/client.py", line 974, in send
    self.connect()
  File "/usr/lib/python3.9/http/client.py", line 945, in connect
    self.sock = self._create_connection(
  File "/usr/lib/python3.9/socket.py", line 844, in create_connection
    raise err
  File "/usr/lib/python3.9/socket.py", line 832, in create_connection
    sock.connect(sa)
TimeoutError: [Errno 110] Connection timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/share/livecd-rootfs/magic-proxy", line 873, in __get_request
    with urllib.request.urlopen(
  File "/usr/lib/python3.9/urllib/request.py", line 214, in urlopen
    return opener.open(url, data, timeout)
  File "/usr/lib/python3.9/urllib/request.py", line 517, in open
    response = self._open(req, data)
  File "/usr/lib/python3.9/urllib/request.py", line 534, in _open
    result = self._call_chain(self.handle_open, protocol, protocol +
  File "/usr/lib/python3.9/urllib/request.py", line 494, in _call_chain
    result = func(*args)
  File "/usr/lib/python3.9/urllib/request.py", line 1375, in http_open
    return self.do_open(http.client.HTTPConnection, req)
  File "/usr/lib/python3.9/urllib/request.py", line 1349, in do_open
    raise URLError(err)
urllib.error.URLError: <urlopen error [Errno 110] Connection timed out>

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.9/socketserver.py", line 683, in process_request_thread
    self.finish_request(request, client_address)
  File "/usr/lib/python3.9/socketserver.py", line 360, in finish_request
    self.RequestHandlerClass(request, client_address, self)
  File "/usr/lib/python3.9/socketserver.py", line 747, in __init__
    self.handle()
  File "/usr/lib/python3.9/http/server.py", line 427, in handle
    self.handle_one_request()
  File "/usr/lib/python3.9/http/server.py", line 415, in handle_one_request
    method()
  File "/usr/share/livecd-rootfs/magic-proxy", line 787, in do_GET
    self.__get_request()
  File "/usr/share/livecd-rootfs/magic-proxy", line 887, in __get_request
    self.send_error(501, e.reason)
  File "/usr/lib/python3.9/http/server.py", line 473, in send_error
    'message': html.escape(message, quote=False),
  File "/usr/lib/python3.9/html/__init__.py", line 19, in escape
    s = s.replace("&", "&amp;") # Must be done first!
AttributeError: 'TimeoutError' object has no attribute 'replace'

Because magic-proxy is proxying all traffic to port 80, it will intercept these sort of messages. The TimeoutError ends up bubbling up to the serversocket handling code, which will then cause a broken pipe for all future communications, effectively breaking future apt calls from within the build environment.

The concrete problem here is that inside magic-proxy, self.send_error is called with the argument of e.reason, which can be a string (no error) or an exception (in case of a nested exception). If the nested exception is passed into self.send_error, html.replace will try to be called on the exception, hence the above exception.

In addition to fixing this specific problem, magic-proxy's request handling should catch all exceptions to not interfere with higher up socketserver handling.

Related branches

Revision history for this message
Launchpad Janitor (janitor) wrote :

Status changed to 'Confirmed' because the bug affects multiple users.

Changed in livecd-rootfs (Ubuntu):
status: New → Confirmed
Changed in livecd-rootfs (Ubuntu):
assignee: nobody → Thomas Bechtold (toabctl)
status: Confirmed → In Progress
Revision history for this message
Thomas Bechtold (toabctl) wrote :
Revision history for this message
Thomas Bechtold (toabctl) wrote :

Note: given that the code is maintained in git, please merge https://code.launchpad.net/~toabctl/livecd-rootfs/+git/livecd-rootfs-1/+merge/410585 when uploading the deb to the archive.

Changed in livecd-rootfs (Ubuntu):
assignee: Thomas Bechtold (toabctl) → nobody
Utkarsh Gupta (utkarsh)
Changed in livecd-rootfs (Ubuntu):
assignee: nobody → Thomas Bechtold (toabctl)
description: updated
Changed in livecd-rootfs (Ubuntu Impish):
assignee: nobody → Thomas Bechtold (toabctl)
status: New → In Progress
Changed in livecd-rootfs (Ubuntu Hirsute):
assignee: nobody → Thomas Bechtold (toabctl)
status: New → In Progress
Revision history for this message
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package livecd-rootfs - 2.743

---------------
livecd-rootfs (2.743) jammy; urgency=medium

  * magic-proxy: fix exception handling for URLError. LP: #1946520

 -- Thomas Bechtold <email address hidden> Mon, 25 Oct 2021 12:22:16 +0200

Changed in livecd-rootfs (Ubuntu):
status: In Progress → Fix Released
Revision history for this message
Brian Murray (brian-murray) wrote :

I've sponsored this for all of the relevant releases of Ubuntu.

Changed in livecd-rootfs (Ubuntu Focal):
status: New → In Progress
Revision history for this message
Łukasz Zemczak (sil2100) wrote : Please test proposed package

Hello Pat, or anyone else affected,

Accepted livecd-rootfs into impish-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/livecd-rootfs/2.742.1 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, what testing has been performed on the package and change the tag from verification-needed-impish to verification-done-impish. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-impish. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

Changed in livecd-rootfs (Ubuntu Impish):
status: In Progress → Fix Committed
tags: added: verification-needed verification-needed-impish
Changed in livecd-rootfs (Ubuntu Hirsute):
status: In Progress → Fix Committed
Revision history for this message
Łukasz Zemczak (sil2100) wrote :

Hello Pat, or anyone else affected,

Accepted livecd-rootfs into hirsute-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/livecd-rootfs/2.719.4 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, what testing has been performed on the package and change the tag from verification-needed-hirsute to verification-done-hirsute. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-hirsute. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

tags: added: verification-needed-hirsute
Revision history for this message
Łukasz Zemczak (sil2100) wrote :

Hello Pat, or anyone else affected,

Accepted livecd-rootfs into focal-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/livecd-rootfs/2.664.35 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, what testing has been performed on the package and change the tag from verification-needed-focal to verification-done-focal. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-focal. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

Changed in livecd-rootfs (Ubuntu Focal):
status: In Progress → Fix Committed
tags: added: verification-needed-focal
Revision history for this message
Thomas Bechtold (toabctl) wrote :

Did a successful impish testbuild for amd64 and arm64 with repo-snapshot-stamp enabled. See:
- amd64: https://launchpad.net/~toabctl/+livefs/ubuntu/impish/proposed/+build/312979
- arm64: https://launchpad.net/~toabctl/+livefs/ubuntu/impish/proposed/+build/312978

tags: added: verification-done-impish
removed: verification-needed-impish
Revision history for this message
Thomas Bechtold (toabctl) wrote :

Did a successful hirsute testbuild for amd64 and arm64 with repo-snapshot-stamp enabled. See:
- amd64: https://launchpad.net/~toabctl/+livefs/ubuntu/hirsute/proposed/+build/312995
- arm64: https://launchpad.net/~toabctl/+livefs/ubuntu/hirsute/proposed/+build/312996

tags: added: verification-done-hirsute
removed: verification-needed-hirsute
Revision history for this message
Thomas Bechtold (toabctl) wrote (last edit ):

Did a successful focal testbuild for amd64 and arm64 with repo-snapshot-stamp enabled. See:
- amd64: https://launchpad.net/~toabctl/+livefs/ubuntu/focal/proposed/+build/313001
- arm64: https://launchpad.net/~toabctl/+livefs/ubuntu/focal/proposed/+build/313000

tags: added: verification-done verification-done-focal
removed: verification-needed verification-needed-focal
Revision history for this message
Brian Murray (brian-murray) wrote :

Does doing a test build accomplish the same thing as in the Test Case portion of the bug description?

Revision history for this message
Thomas Bechtold (toabctl) wrote :

@Brian, yes. Running a test build does execute all the steps from the test plan. And I checked the magic-proxy.log files . They do not include the "AttributeError".
Sorry for not being clear here.

Revision history for this message
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package livecd-rootfs - 2.742.1

---------------
livecd-rootfs (2.742.1) impish; urgency=medium

  [ Thomas Bechtold ]
  * magic-proxy: fix exception handling for URLError LP: #1946520

 -- Brian Murray <email address hidden> Thu, 18 Nov 2021 15:17:05 -0800

Changed in livecd-rootfs (Ubuntu Impish):
status: Fix Committed → Fix Released
Revision history for this message
Brian Murray (brian-murray) wrote : Update Released

The verification of the Stable Release Update for livecd-rootfs has completed successfully and the package is now being released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.

Revision history for this message
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package livecd-rootfs - 2.719.4

---------------
livecd-rootfs (2.719.4) hirsute; urgency=medium

  [ Thomas Bechtold ]
  * magic-proxy: fix exception handling for URLError (LP: #1946520)

 -- Brian Murray <email address hidden> Thu, 18 Nov 2021 15:25:42 -0800

Changed in livecd-rootfs (Ubuntu Hirsute):
status: Fix Committed → Fix Released
Revision history for this message
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package livecd-rootfs - 2.664.35

---------------
livecd-rootfs (2.664.35) focal; urgency=medium

  [ Thomas Bechtold ]
  * magic-proxy: fix exception handling for URLError (LP: #1946520)

 -- Brian Murray <email address hidden> Thu, 18 Nov 2021 15:42:45 -0800

Changed in livecd-rootfs (Ubuntu Focal):
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers