Repeatedly "storage error [503 Inconsistent file state], last errno: File exists

[Paul Boven]

Since upgrading to Bionic (18.04) our apt-cacher-ng often reports this error in its log:
"storage error [503 Inconsistent file state], last errno: File exists"

This results in the client not being served the file in question, and 'apt update' failing.

The problem happens especially often with some 'local' repositories, where the 'Release' file sometimes gets cached properly, and moments later, is not available anymore on the next 'apt update' run. And a few minutes later, the file may be available again.

Running acng with 'Debug: 7' results in this:

Returning to last state, 6
Decoded request URI: http://install/Xenial-16.04-amd64/binary/Release
Processing new job, GET http://install/Xenial-16.04-amd64/binary/Release HTTP/1.1
Download started, storeHeader for install/Xenial-16.04-amd64/binary/Release, current status: 1
install/Xenial-16.04-amd64/binary/Release storage error [503 Inconsistent file state], last errno: File exists
Response header to be sent in the next cycle:
HTTP/1.1 503 Inconsistent file state
Content-Length: 145
Content-Type: text/html
Date: Thu Apr 25 13:02:08 2019
Server: Debian Apt-Cacher NG/3.1
X-Original-Source: http://install/Xenial-16.04-amd64/binary/Release
Connection: Keep-Alive

A few minutes later (from the same client, and without restarting acng, it works again:

Returning to last state, 6
Decoded request URI: http://install/Xenial-16.04-amd64/binary/Release
Processing new job, GET http://install/Xenial-16.04-amd64/binary/Release HTTP/1.1
Download started, storeHeader for install/Xenial-16.04-amd64/binary/Release, current status: 1
Response header to be sent in the next cycle:
HTTP/1.1 200 OK
Content-Length: 1658
Content-Type: application/octet-stream
Date: Thu Apr 25 13:04:30 2019
Server: Debian Apt-Cacher NG/3.1
X-Original-Source: http://install/Xenial-16.04-amd64/binary/Release
Connection: Keep-Alive

apt policy apt-cacher-ng:
apt-cacher-ng:
  Installed: 3.1-1build1
  Candidate: 3.1-1build1

lsb_release -rd:
Description: Ubuntu 18.04.2 LTS
Release: 18.04

The apt-cacher-ng is running on a virtual machine, with the above configuration. There is plenty of diskspace available. The problem even occurs after removing acng, clearing /var/cache/apt-cacher-ng/, and re-installing the package.

[Paul Boven (p-boven)]

Further analysis shows that this problem is due to a fun interaction between lighttpd an ACNG. We use lighttpd to serve a local Debian/Ubuntu package repository. In about half the cases where we run 'apt update', it will fail with error 503 on the 'Release' file of such a repository.

What happens is:

1) Client asks ACNG for a new file. ACNG downloads it, serves it to the client, adds it to /var/cache/apt-cacher-ng/<somewhere>

2) Subsequent requests for this file will work as expected

3) If the file hasn't been requested for a while, ACNG will run 'fileitem::DoDelayedUnregAndCheck'

4) The file is still in /var/cache/apt-cacher-ng/<somewhere>, but ACNG has forgotten about it. A new request will fail with error 503 because ACNG detects the file being in the cache ('Inconsistent File State'). ACNG deletes the file in question, and the next request will work.

This only happens if there is no 'Last Modified' HTTP header sent by lighttpd. I've modified the lighttpd.conf to add this header, and ACNG no longer gives the '503 Inconsistent File State' error.

Lighttpd.conf addition (from https://www.anexia-it.com/blog/en/the-tale-of-lighttpd-not-sending-the-last-modified-header/ ):

mimetype.assign += ("" => "application/octet-stream" )

This still seems like a bug in ACNG, but this work-around might be useful for some.

[Emmanuel Fusté (emmanuel-fuste-thalesgroup)]

Same bug different cause:
VfileUseRangeOps: 0
is no longer usable.
Ubuntu dis-upgrader-all tar.gz files (for do-release-upgrade) always trigger the same bug with the "storage error [503 Inconsistent file state], last errno: File exists".

As our proxys seems to be fixed regarding if-range header, using the default "VfileUseRangeOps: 1" fixed our problem.

[Launchpad Janitor (janitor)]

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

[Emmanuel Fusté (emmanuel-fuste-thalesgroup)]

Hoo my....
Our proxys are NOT fixed.
I go back to VfileUseRangeOps: 0.
I need to choose between a functional repository for daily updates or a functional repository for distribution release upgrade.
Will try if with VfileUseRangeOps: -1 I could get both.

[Steve Dodd (anarchetic)]

acng seems totally broken in bionic. I'm not knowingly behind a proxy - can't completely rule out ISP doing something evil though. Anyone have any pointers on this? Very few google hits, nothing on bugs.debian.org that I can see, very little activity for acng on salsa.debian.org ..

[Paul Boven (p-boven)]

Hi Steve,

On 8/15/19 11:04 PM, Steve Dodd wrote:
> acng seems totally broken in bionic. I'm not knowingly behind a proxy -
> can't completely rule out ISP doing something evil though. Anyone have
> any pointers on this? Very few google hits, nothing on bugs.debian.org
> that I can see, very little activity for acng on salsa.debian.org ..

Could you perhaps be a bit more specific in the bug tracker about how it
is totally broken?

It works fine for us (on Bionic), with the workarounds noted in this
bug, and in
https://bugs.launchpad.net/ubuntu/+source/update-manager/+bug/1771914

Regards, Paul Boven.

[Steve Dodd (anarchetic)]

Well, touch wood, something I've done has made things happier. I moved everything from the cache directory to a subfolder, made it inaccessible, removed apt lists from clients and ran apt-get update, then linked all the original cache files into _import and made acng reimport them.

The first time I did this, it didn't seem to help. After the second time, so far, everything is OK. I also reinstalled the package and let it overwrite my config, but looking at the actual uncommented options in each version, they're basically identical. All very odd...

[Steve Dodd (anarchetic)]

I was seeing the dreaded "503 Inconsistent file state" talking to the canonical (sorry) package repositories. As I said, there are no explicit upstream proxies, but who knows what the ISP is doing (this would be a big argument in favour of running apt-get over https to my mind..)

Anyway, at the moment after a cycles of intelligent nuking (trying to retain my cache contents while rebuilding it) things seem OK. I feel bad for not going into full-on debug mode and trying to get to the bottom of it, but I'm got a huge mountain of stuff to do and just needed this working so I could get on :(

[Emmanuel Fusté (emmanuel-fuste-thalesgroup)]

VfileUseRangeOps: -1 fixed all my use cases.

[Dariusz Działak (ddzialak)]

For us change `VfileUseRangeOps: -1` did not solve the problem. It was happening with our custom repository only, let say `repo.xxx.com` (unsure why, maybe because it was changing quite often?) and after upgrade host from Xenial or Bionic (doesn't matter) to Focal the error started to appear very often. The problem disappeared after adding to config entry like below:

DontCacheRequested: .*repo.xxx.com.*InRelease

Good news is also that, the cache for that repo still works (it was crucial for us, because we are charged for that private repo).
Unsure if it does any matter, but apt-cacher-ng is accessed over HTTP protocol while private repo.xxx.com use HTTPS.
Steps to reproduce were very easy:
- start apt-cacher-ng
- use wget "http://localhost:3142/HTTPS///repo.xxx.com/repository_name/deb/ubuntu/dists/focal/InRelease
  (in this step first request download file from original repository, next requests are very fast and do not involve external repo)
- after ~ 20 seconds, in apt-cacher.err logs appears message like:
  > Wed Apr 6 19:22:13 2022|fileitem::DoDelayedUnregAndCheck, nextRunTime now: 9223372036854775805
- now repeating wget command cause the response will appear immediately with "503 Inconsistent file state"