snapd

Snapd stuck after a request timeout error

Bug #1891618 reported by Sebastien Bacher on 2020-08-14

This bug affects 4 people

Affects		Status	Importance	Assigned to	Milestone
	snapd	Confirmed	Critical	Unassigned

Bug Description

Today snapd is stucked refreshing a snap on my focal system

$ snap version
snap 2.45.1+git1648.gf492c71
snapd 2.45.1+git1648.gf492c71
series 16
ubuntu 20.04
kernel 5.6.0-1007-oem

$ snap changes
...
315 Doing today at 08:59 CEST - Actualiser automatiquement les paquets Snap "openstackclients", "ubuntu-bug-triage", "snapcraft"

$ snap watch 315
Télécharger un paquet Snap "ubuntu-bug-triage" (205) à partir du canal "latest/stable" 56% 4.46MB/s 615ms

but it's stuck on 56% for over an hour now (on a 19M snap)

doing Ctrl-C doesn't exit the snap watch but just display a new line on the buffer and keeps updating the status

$ systemctl status snapd
...
snapd[1336]: 2020/08/14 09:00:03 Unsolicited response received on idle HTTP channel starting with "HTTP/1.0 408 Request Time-out\r\nCache-Control: no-cache\r\nConnection: close\r\nContent-Type: text/html\r\n\r\n<html><body><h1>408 Request Time-out</h1>\nYour browser didn't send a complete request in time.\n</body></html>\n"; err=<nil>

Paweł Stołowski (stolowski) on 2020-08-14

Changed in snapd:
status:	New → Confirmed
importance:	Undecided → High

Revision history for this message

Sebastien Bacher (seb128) wrote on 2020-08-14:

output of 'snap change 315' Edit (5.0 KiB, text/plain)

Paweł Stołowski (stolowski) on 2020-08-14

Changed in snapd:
importance:	High → Critical

Revision history for this message

Zygmunt Krynicki (zyga) wrote on 2020-09-29:

This looks like a http / go bug:

snapd[1336]: 2020/08/14 09:00:03 Unsolicited response received on idle HTTP channel starting with "HTTP/1.0 408 Request Time-out\r\nCache-Control: no-cache\r\nConnection: close\r\nContent-Type: text/html\r\n\r\n<html><body><h1>408 Request Time-out</h1>\nYour browser didn't send a complete request in time.\n</body></html>\n"; err=<nil>

It seems that we make a request, some part of the stack thinks that request has timed out and forgets about it but then we get a response that the stack thinks is unsolicited.

summary:

- Snapd stucked after a request timeout error
+ Snapd stuck after a request timeout error

a59ff5 (a59ff5a59ff5) on 2021-03-29

Changed in snapd:
status:	Confirmed → Invalid
status:	Invalid → Fix Released

Ian Johnson (anonymouse67) on 2021-03-29

Changed in snapd:
status:	Fix Released → Confirmed

Revision history for this message

Paweł Stołowski (stolowski) wrote on 2021-06-01:

We got a few reports about this problem over last couple of months but so far haven't been able to reproduce it (I tried several times in a VM with network traffic shaping, simulating slow network with packet losses) nor pinpoint a problem. It is under investigation but very elusive, any extra info may help.

If anyone hits this issue, then the following information may help:
- `snap changes` and `snap change <X>` output
- journalctl -u snapd output (ideally, running snapd with SNAPD_DEBUG=1 environment variable set when the problem occured).
- `systemctl status snapd` output
- information on the quality of network in use (stability, whether it drops frequently etc.)

Revision history for this message

Pak Jiddat (pakjiddat) wrote on 2021-08-07 (last edit on 2021-08-07):

I was having problems with building a snap application. The command: snapcraft --debug was failing with the error:

Consider re-refresh of "snapd" (cannot query the store for updates: got unexpected HTTP status code 503 via POST ...

The /var/log/syslog showed the following:

Aug 7 07:49:34 nadir-X551MA snapd[779]: 2021/08/07 07:49:34 Unsolicited response received on idle HTTP channel starting with "HTTP/1.1 408 Re
quest Time-out\r\ncontent-length: 110\r\ncache-control: no-cache\r\ncontent-type: text/html\r\nconnection: close\r\n\r\n<html><body><h1>408 Re
quest Time-out</h1>\nYour browser didn't send a complete request in time.\n</body></html>\n"; err=<nil>

This is the same error that was mentioned by the bug reporter

Also the Apparmor logs showed errors. Following is the output of the command: sudo apparmor_status:

5 profiles are in complain mode.
   libreoffice-oopslash
   libreoffice-soffice
   snap.code.code
   snap.code.url-handler
   snap.snapcraft.snapcraft

I think the problem I had was related to multipass. multipass is used by snapcraft to build snaps. The log messages in /var/log/syslog showed that multipass is not able to reserve an ip address via DHCP. My local wireless router was configured to allow 6 devices to get an ip address via DHCP. All ip addresses were allocated and new devices could not be assigned an ip address. I increased the range of DHCP addresses and rebooted the router. I also rebooted my local computer. After that the command: snapcraft --debug worked without problems.

However the sudo apparmor_status command still showed snap.snapcraft.snapcraft in complain mode.

Revision history for this message

Ian Johnson (anonymouse67) wrote on 2021-08-14 (last edit on 2021-08-14):

Getting a 503 error is not an issue with snapcraft, that is an issue with the snap store at that point in time.