#729941 liblzma5: returns LZMA_OK with avail_in == 0 before done

Package:
liblzma5
Source:
xz-utils
Description:
XZ-format compression library
Submitter:
Adam Borowski
Date:
2013-12-17 21:57:05 UTC
Severity:
minor
#729941#5
Date:
2013-11-19 02:53:24 UTC
From:
To:
For some reason, apt-cacher-ng gets spooked by some Package files.  I've
seen this before on other repositories, currently it's experimental/non-free
that fails.  I attached a copy of this file (as it's likely to have changed
by the time you take a look).


When using the cache, apt says:
-----
Err http://apt.angband.pl:3142 experimental/non-free amd64 Packages

Hit http://apt.angband.pl:3142 experimental/non-free amd64 Packages
-----
(with a mysterious newline, but that's a weirdness in apt).


Whenever the nightly cronjob comes, it spams, asking for manually expiring
the cache via a web interface.  This one says:
-----
Parsing metadata in debrep/dists/experimental/non-free/binary-amd64/Packages.xz
An error occured while reading this file, some contents may have been ignored. Tag
-----
which persists even after asking it to remove it.  Manually deleting just
this one file (
/var/cache/apt-cacher-ng/debrep/dists/experimental/non-free/binary-amd64/Packages.xz
) lets expiration succeed, but running an apt update brings it back.


I tried nuking the whole of /var/cache/apt-cacher-ng as well (which you
probably noticed from #729939), didn't help.

#729941#10
Date:
2013-11-19 11:28:53 UTC
From:
To:
Hallo Adam,

* Adam Borowski [Tue, Nov 19 2013, 03:53:24AM]:

As you suspected, I have trouble reproducing it. Could you send your
/etc/apt-cacher-ng/*.conf files please?

Could you also turn up debug= value to 7 and send me your logs after a
couple of days?

Thanks,
Eduard.

#729941#15
Date:
2013-11-19 11:40:28 UTC
From:
To:
I brought them to the stock state when trying reinstalling, the only change
currently is:

244c244
< # ConnectProto: v6 v4
---

(as my IPv6 goes through SiXXS which is slower than native IPv4).

Sure, I've just set it ("Debug:7" in acng.conf).

#729941#20
Date:
2013-11-21 23:20:59 UTC
From:
To:
Attached.  This comes without a manual intervention since nuking the cache
on Tuesday.  This time, the failures include experimental/main/binary-armhf
in addition to experimental/non-free/binary-amd64 (I got amd64, i386 and
armhf installs at home).

Meow!

#729941#23
Date:
2013-12-01 19:54:44 UTC
From:
To:
Eduard Bloch wrote:

I have been seeing the exact same problem for the past few weeks.  The
problem is with experimental main for me.

  deb http://ftp.us.debian.org/debian experimental main

I am experiencing this with 0.7.11-1 since the proxy is a Stable
Wheezy machine.

I suspect that the file on my system would be the same as the one
previously reported.  But I would happily provide mine if it were
beneficial.

  ls -lh /var/cache/apt-cacher-ng/debrep/dists/experimental/main/binary-amd64/Packages.xz
  -rw-r--r-- 1 apt-cacher-ng apt-cacher-ng 426K Dec  1 12:38 /var/cache/apt-cacher-ng/debrep/dists/experimental/main/binary-amd64/Packages.xz

Running the expiration from the web interface reports:

  Parsing metadata in debrep/dists/experimental/main/binary-amd64/Packages.xz
  An error occured while reading this file, some contents may have been ignored. [ ] Tag

I am not familiar with the internals.  Is there a command that I could
run from the command line to have apt-cacher-ng parse that file and
report debug information directly?  Perhaps at that point I could even
debug it to root cause.

Thanks,
Bob

#729941#28
Date:
2013-12-08 23:51:13 UTC
From:
To:
reassign 729941 liblzma5
thanks

Hallo Adam,
* Adam Borowski [Fri, Nov 22 2013, 12:20:59AM]:

Thanks. After all, I was able to reproduce it on my system with the
current version of the mentioned Packages.xz file and... it turned out
to be a weird behaviour of
ii  liblzma5:amd64 5.1.1alpha+2 amd64        XZ-format compression library

Apparently, on the last cycle of lzma_code(&strm, LZMA_RUN) it does not
return LZMA_STREAM_END but LZMA_OK although the strm.avail_in value
is zero which means that there is no more data to be expected. I am not
sure why the problem occurs on exactly this file but I can reproduce it
(for reproduction: sample code below, to be used with an output buffer
of 20000 bytes size, the FLAG_* constants are internal flag bits, just
ignore).

The problematic file is also attached. I will a workaround for now to
apt-cacher-ng.

Regards,
Eduard.

#ifdef HAVE_LZMA
#include <lzma.h>

class tXzDec : public IDecompressor
{
	lzma_stream strm;
public:
	tXzDec(bool lzmaFormat=false)
	{
		::memset(&strm, 0, sizeof(strm));
		if(lzmaFormat)
			inited = (LZMA_OK == lzma_alone_decoder(&strm,
					EXTREME_MEMORY_SAVING ? 32000000 : MAX_VAL(uint64_t)));
		else
			inited = (LZMA_OK == lzma_stream_decoder(&strm,
				EXTREME_MEMORY_SAVING ? 32000000 : MAX_VAL(uint64_t),
						LZMA_TELL_UNSUPPORTED_CHECK | LZMA_CONCATENATED));
	}
	~tXzDec()
	{
		lzma_end(&strm);
		inited = false;
	}
	virtual UINT UncompMore(char *szInBuf, size_t nBufSize, size_t &nBufPos, acbuf &UncompBuf)
	{
		strm.next_in = (uint8_t*) szInBuf + nBufPos;
		strm.avail_in = nBufSize - nBufPos;
		strm.next_out = (uint8_t*) UncompBuf.wptr();
		strm.avail_out = UncompBuf.freecapa();

		lzma_ret ret=lzma_code(&strm, LZMA_RUN);
		if (ret == LZMA_STREAM_END || ret == LZMA_OK)
		{
			nBufPos = nBufSize - strm.avail_in;
			if(!strm.avail_in)
				ret == LZMA_STREAM_END; // looks like liblzma bug, working around
			unsigned int nGotBytes = UncompBuf.freecapa() - strm.avail_out;
			UncompBuf.got(nGotBytes);
			return ret == LZMA_STREAM_END ? FLAG_COMPEOF : 0;
		}
		// or corrupted data?
		return (FLAG_COMPEOF | FLAG_ERROR);
	}
};
#end

#729941#37
Date:
2013-12-09 22:37:05 UTC
From:
To:
clone 729941 -1
reassign -1 apt-cacher-ng 0.7.19-1
retitle 729941 liblzma5: returns LZMA_OK with avail_in == 0 before done
found 729941 xz-utils/5.1.1alpha+20120614-2
tags 729941 + moreinfo
quit

Hi Eduard,

Eduard Bloch wrote:
strm.avail_in is zero, that means there is no more output to be
expected?

Just like zlib, if lzma_code() returns LZMA_OK and strm.avail_in is 0,
decompression is not necessarily finished yet.  liblzma has internal
buffers, so output is potentially incomplete unless you keep running
lzma_code() until it returns LZMA_STREAM_END or LZMA_BUF_ERROR.

[...]

Is the workaround as described above?  That's the intended API, so I
don't consider it a workaround.

Any idea how this could be documented better to help people running
into this in the future?

Hope that helps,
Jonathan

#729941#50
Date:
2013-12-09 23:36:12 UTC
From:
To:
Hallo Jonathan,
* Jonathan Nieder [Mon, Dec 09 2013, 02:37:05PM]:

Ok, fair enough... there is still a bug.

It doesn't but my code assumed that if avail_in is zero and the last
output buffer was not completely consumed then we are done and stopped
looping but a "sanity check" somewhere else kicked in and and reported
an error when the stream decoder work was not finished (which means:
LZMA_STREAM_END was not returned).

Maybe really like zlib, maybe not. As far as I remember, zlib always
returned ..._END when the result stream was completely written into the
output buffer. And I have seen liblzma behaving the same way but it's
not the case for the mentioned file(s) according to gdb. Here, the
returned data (n time return buffer size plus one incomplete buffer)
summs up to the total size of the stream but in the last cycle lzma_code
returns LZMA_OK and not LZMA_STREAM_END. Maybe it will become
LZMA_STREAM_END the next time when lzma_code is called but why should we
do the extra round?

Well, no, the thing was/is buggy and the workaround is incorrect, I have
actually realized that myself after double-reading the code. This needs
a fix RSN.

Maybe it should state that one has to wait for LZMA_STREAM_END to be
returned (or any !=LZMA_OK for errors) and not to add other funny
checks for input/output buffer state.

Regards,
Eduard.

#729941#55
Date:
2013-12-10 00:14:20 UTC
From:
To:
tags 729941 + upstream - moreinfo
# documentation
severity 729941 minor
quit

Eduard Bloch wrote:

Ah, so the confusing behavior is that an LZMA_OK result neither
guarantees that there's more output coming nor that there's no more
output coming?  Ok.

[...]

Makes sense.  Will think more and hopefully send a patch soon.

Thanks,
Jonathan

#729941#66
Date:
2013-12-10 09:05:07 UTC
From:
To:
Eduard Bloch dixit:

Quick semi-educated guess: maybe because you can concatenate
multiple partial xz streams.

bye,
//mirabilos

#729941#71
Date:
2013-12-12 17:49:07 UTC
From:
To:
Hallo,
* Jonathan Nieder [Mon, Dec 09 2013, 04:14:20PM]:
zlib. And there is a clear rule:

| deflate() returns Z_OK if some progress has been made (more input
| processed or more output produced), Z_STREAM_END if all input has been
| consumed and all output has been produced (only when flush is set to
| Z_FINISH), Z_STREAM_ERROR if...

The problem with lzma was: I have set LZMA_CONCATENATED a while ago
without reading about all it's consequences and I didn't bother about
LZMA_FINISH. And for some weird reason, even in this operation mode
LZMA_STREAM_END was returned for almost all files I tested with so the
problem hasn't showed up untill a few weeks ago something changed in the
non-free archive.

If you wish to improve the documentation, please mention
LZMA_CONCATENATED and LZMA_FINISH in the description of LZMA_STREAM_END.

Regards,
Eduard.

#729941#76
Date:
2013-12-17 21:49:19 UTC
From:
To:
We believe that the bug you reported is fixed in the latest version of
apt-cacher-ng, which is due to be installed in the Debian FTP archive.

A summary of the changes between this version and the previous one is
attached.

Thank you for reporting the bug, which will now be closed.  If you
have further comments please address them to 729941@bugs.debian.org,
and the maintainer will reopen the bug report if appropriate.

Debian distribution maintenance software
pp.
Eduard Bloch <blade@debian.org> (supplier of updated apt-cacher-ng package)

(This message was generated automatically at their request; if you
believe that there is a problem with it please contact the archive
administrators by mailing ftpmaster@ftp-master.debian.org)
Format: 1.8
Date: Tue, 17 Dec 2013 21:18:15 +0100
Source: apt-cacher-ng
Binary: apt-cacher-ng
Architecture: source amd64
Version: 0.7.23-1
Distribution: unstable
Urgency: medium
Maintainer: Eduard Bloch <blade@debian.org>
Changed-By: Eduard Bloch <blade@debian.org>
Description:
 apt-cacher-ng - caching proxy server for software repositories
Closes: 726656 729508 729941 731804
Changes:
 apt-cacher-ng (0.7.23-1) unstable; urgency=medium
 .
   * New upstream version
     + fixes reading of certain .xz files (closes: #729941, #731804)
     + HTTPS support (closes: #729508)
   * more debconf controlled settings injected through a separate config
     file, partially based on the patch from
     Geert Stappers <stappers@stappers.nl> (closes: #726656)
   * policy version bump, and no longer recommending perl, there are enough
     functionality replacements implemented to work with just perl-base
   * changed maximum version counts in lograte configuration to lower numbers
Checksums-Sha1:
 3ea2d3a938a0bab1e6fdfc6c0d3f2a265725b70a 1276 apt-cacher-ng_0.7.23-1.dsc
 0d3a61bacf1db3b4993824bf9b5eab6f7f6e3ab4 271888 apt-cacher-ng_0.7.23.orig.tar.xz
 ed2afe8467680f9cff16862befab41318ca40bc5 29008 apt-cacher-ng_0.7.23-1.debian.tar.xz
 db90bd802740af29731201d9a4bce261ab5a02fe 436392 apt-cacher-ng_0.7.23-1_amd64.deb
Checksums-Sha256:
 3cf01c22064bb369a5bf9f310a04749ec74a538b30e6696779a685cab26cbe33 1276 apt-cacher-ng_0.7.23-1.dsc
 f78876388674b5f52221e31c157d8c5417160d2ebcd844cb60671ae6bd6e61a5 271888 apt-cacher-ng_0.7.23.orig.tar.xz
 74bfdf5aeaa349971bbc341be1080ae5f2575fd5b0fde90e2ed07ff16cf0ca3a 29008 apt-cacher-ng_0.7.23-1.debian.tar.xz
 895fa818fb67fce0360175fb126ea8eea9a94667c8617a4497f5d1da80bdcddd 436392 apt-cacher-ng_0.7.23-1_amd64.deb
Files:
 4ea0dc3570258597accc81da06db0bf3 1276 net optional apt-cacher-ng_0.7.23-1.dsc
 4cd86c3da11bd6bcfe6f7565a586520d 271888 net optional apt-cacher-ng_0.7.23.orig.tar.xz
 ce8fffe1dc23169e9fdef44b64c39a21 29008 net optional apt-cacher-ng_0.7.23-1.debian.tar.xz
 60c308f5c421f3041b7650f88c186469 436392 net optional apt-cacher-ng_0.7.23-1_amd64.deb
iD8DBQFSsL+/4QZIHu3wCMURAkDNAJ9Tzic7ENcI8BICmA/Z+A4ueg1DRQCfQLk6
GeqyCsyrpUBCqk5iLgAA71Y=
=Nrqo
-----END PGP SIGNATURE-----