Public bug reported:

When trying to use apt I noticed that actions that required the proxy
were taking a long time to complete. I tracked that down to the squid-
deb-proxy-client package, in particular the apt-avahi-discover script,
which was taking more than 2 minutes to complete.

Current output:
$ time /usr/share/squid-deb-proxy-client/apt-avahi-discover --debug
avahi-browse output:
<snipped>
no timeout set, using default '2'
error: uncaptured python exception, closing channel <AptAvahiClient> 
('192.168.86.60', 127): 9223372036854775807 (<class 'socket.error'>:[Errno 110] 
Connection timed out [/usr/lib/python2.7/asyncore.py|readwrite|108] 
[/usr/lib/python2.7/asyncore.py|handle_read_event|446] 
[/usr/lib/python2.7/asyncore.py|handle_connect_event|454])
sorted hosts: '[<AptAvahiClient> ('192.168.86.30', 8000): 0.00731706619263, 
<AptAvahiClient> ('10.113.100.1', 8000): 0.00739908218384, <AptAvahiClient> 
('fd42:6e97:d27c:25bc::1', 8000, 0, 0): 0.00753402709961, <AptAvahiClient> 
('192.168.86.60', 127): 9223372036854775807]'
http://192.168.86.30:8000/
/usr/share/squid-deb-proxy-client/apt-avahi-discover --debug  0.03s user 0.01s 
system 0% cpu 2:12.20 total

Here 192.168.86.30 is the "localhost", which also runs lxd (thus the
10.113.1001 address) and the squid-deb-proxy service. My laptop is
192.168.86.60 and also runs its own squid-deb-proxy service.

My laptop (192.168.86.60) is firewalled, so although its own avahi-
daemon contacted the other server (192.168.86.30) to announce the
service, the other server can't really access it (thus the huge int for
the "response" time.

Interrupting the calls led me to:
<snipped>
Traceback (most recent call last):
  File "/usr/share/squid-deb-proxy-client/apt-avahi-discover", line 130, in 
<module>
    address = get_proxy_host_port_from_avahi()
  File "/usr/share/squid-deb-proxy-client/apt-avahi-discover", line 116, in 
get_proxy_host_port_from_avahi
    asyncore.loop(timeout=timeout)
  File "/usr/lib/python2.7/asyncore.py", line 216, in loop
    poll_fun(timeout, map)
  File "/usr/lib/python2.7/asyncore.py", line 145, in poll
    r, w, e = select.select(r, w, e, timeout)

So what happens is that the asyncore.loop() call will hang until the
sockets timeout.

I have tried a few things such as: 
- setting default timeout to 1 
- setting the socket.settimeout(DEFAULT_CONNECT_TIMEOUT_SEC)
  inside AptAvahiClient before the connect call
but neither of the above worked.

What finally worked was to set asyncore.loop(timeout=timeout, count=1).
It seems that the timeout alone is not enough because the select() call
will simply loop over the timeout [1,2].


Output with asyncore.loop(timeout=timeout, count=1):
$ time /usr/share/squid-deb-proxy-client/apt-avahi-discover --debug
avahi-browse output:
<snipped>
no timeout set, using default '2'
sorted hosts: '[<AptAvahiClient> ('192.168.86.30', 8000): 0.00732398033142, 
<AptAvahiClient> ('10.113.100.1', 8000): 0.00736904144287, <AptAvahiClient> 
('fd42:6e97:d27c:25bc::1', 8000, 0, 0): 0.00745701789856, <AptAvahiClient> 
('192.168.86.60', 127): 9223372036854775807]'
http://192.168.86.30:8000/
/usr/share/squid-deb-proxy-client/apt-avahi-discover --debug  0.02s user 0.01s 
system 2% cpu 1.027 total

So, around 1 seconds, way better.

I also tried using other values for count, here is a small table with timeout = 
2 (the default):
count =  1 ->  1 second
count =  2 ->  3 seconds
count =  3 ->  5 seconds
count =  4 ->  7 seconds
count =  5 ->  9 seconds
count =  8 -> 15 seconds
count = 15 -> 29 seconds

For timeout = 5:
count =  1 ->  1 second
count =  2 ->  6 seconds
count =  3 -> 11 seconds
count =  4 -> 16 seconds
count =  5 -> 21 seconds


For the time measurements I ran the commands at least 5 times to check for any 
outliers, the few changes I saw there mostly corresponded to the timing 
variation from just the avahi-browse call [3].

It seems that the very first try "timeouts" pretty quick (under a
second), but the following retries (if count > 1) do take the set
timeout into account. Thus, for my tests, the actual timeout is around:
((timeout * (count -1)) + 1. Remember that the +1 comes from the avahi-
browser in my environment, if it takes longer or shorter than that won't
really affect (or be affected by) my proposed fix.

I'm attaching a patch that uses count=2 which should give a timeout
pretty close to the one set by the user (or the default), but that might
need additional review as I'm not sure what are the possible drawbacks
from setting count to such a low value.

Additional info:
$cat /etc/os-release 
NAME="Ubuntu"
VERSION="17.10 (Artful Aardvark)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 17.10"
VERSION_ID="17.10"
HOME_URL="https://www.ubuntu.com/";
SUPPORT_URL="https://help.ubuntu.com/";
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/";
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy";
VERSION_CODENAME=artful
UBUNTU_CODENAME=artful

$ apt-cache policy squid-deb-proxy
squid-deb-proxy:
  Installed: 0.8.14
  Candidate: 0.8.14
  Version table:
 *** 0.8.14 500
        500 http://br.archive.ubuntu.com/ubuntu artful/universe amd64 Packages
        500 http://br.archive.ubuntu.com/ubuntu artful/universe i386 Packages
        100 /var/lib/dpkg/status


[1] https://stackoverflow.com/a/15842027
[2] https://stackoverflow.com/a/14485737
[3] The "avahi-browse -kprtf _apt_proxy._tcp" command (called by 
apt-avahi-discover) runs in around 1 second most of the time, but it did take 
3+ seconds a couple times.

** Affects: squid-deb-proxy (Ubuntu)
     Importance: Undecided
         Status: New


** Tags: artful bionic patch

** Patch added: "apt-avahi-discover_timeout-fix.patch"
   
https://bugs.launchpad.net/bugs/1733694/+attachment/5012439/+files/apt-avahi-discover_timeout-fix.patch

-- 
You received this bug notification because you are a member of Ubuntu
Bugs, which is subscribed to Ubuntu.
https://bugs.launchpad.net/bugs/1733694

Title:
  apt-avahi-discover can take a long time when the destination service
  port is blocked

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/squid-deb-proxy/+bug/1733694/+subscriptions

-- 
ubuntu-bugs mailing list
ubuntu-bugs@lists.ubuntu.com
https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs

Reply via email to