Possible regression: reading gzip files generates a CRC check failed error in version 0.11.0

[fjossandon]

Hello @rhpvorderman,
Some months ago I reported a bug in the decompression of Gzip files (#60), and today while using cutadapt in a different computer it happened again. I remembered the previous time and checked the compressed files, and found that "zcat" and "gzip -t" were not giving any errors, so I suspected of isal.

In my personal computer I have installed version 0.8.1 which work fine with the files, so without changing anything else I tried installing the next isal versions one by one, and found that the the files are decompressed fine with isal versions 0.9.0 and 0.10.0, but breaks on last version 0.11.0:

fossandon@ubuntu:~/Documents/download$ pip3 install isal==0.11.0
Defaulting to user installation because normal site-packages is not writeable
Collecting isal==0.11.0
  Using cached isal-0.11.0-cp36-cp36m-manylinux_2_17_x86_64.manylinux2014_x86_64.whl (1.0 MB)
Installing collected packages: isal
  Attempting uninstall: isal
    Found existing installation: isal 0.10.0
    Uninstalling isal-0.10.0:
      Successfully uninstalled isal-0.10.0
Successfully installed isal-0.11.0

fossandon@ubuntu:~/Documents/download$ cutadapt -a "AACTTTYARCAAYGGATCTC;max_error_rate=0.1;min_overlap=20" -A "TGATCCYTCCGCAGGT;max_error_rate=0.5;min_overlap=16" --pair-adapters --pair-filter any --cores 2 --output 136727_R1.fastq --paired-output 136727_R2.fastq 136727_S159_L001_R1_001.fastq.gz 136727_S159_L001_R2_001.fastq.gz
This is cutadapt 3.4 with Python 3.6.9
Command line parameters: -a AACTTTYARCAAYGGATCTC;max_error_rate=0.1;min_overlap=20 -A TGATCCYTCCGCAGGT;max_error_rate=0.5;min_overlap=16 --pair-adapters --pair-filter any --cores 2 --output 136727_R1.fastq --paired-output 136727_R2.fastq 136727_S159_L001_R1_001.fastq.gz 136727_S159_L001_R2_001.fastq.gz
Processing reads on 2 cores in paired-end mode ...
ERROR: Traceback (most recent call last):
  File "/home/fossandon/.local/lib/python3.6/site-packages/cutadapt/pipeline.py", line 556, in run
    dnaio.read_paired_chunks(f, f2, self.buffer_size)):
  File "/home/fossandon/Documents/Github_repos/dnaio/src/dnaio/chunks.py", line 118, in read_paired_chunks
    bufend1 = f.readinto(memoryview(buf1)[start1:]) + start1  # type: ignore
  File "/usr/lib/python3.6/gzip.py", line 276, in read
    return self._buffer.read(size)
  File "/usr/lib/python3.6/_compression.py", line 68, in readinto
    data = self.read(len(byte_view))
  File "/home/fossandon/.local/lib/python3.6/site-packages/isal/igzip.py", line 265, in read
    self._read_eof()
  File "/usr/lib/python3.6/gzip.py", line 501, in _read_eof
    hex(self._crc)))
OSError: CRC check failed 0x8b1f001a != 0xd2f5dc20

ERROR: Traceback (most recent call last):
  File "/home/fossandon/.local/lib/python3.6/site-packages/cutadapt/pipeline.py", line 626, in run
    raise e
OSError: CRC check failed 0x8b1f001a != 0xd2f5dc20

Traceback (most recent call last):
  File "/home/fossandon/.local/bin/cutadapt", line 8, in <module>
    sys.exit(main_cli())
  File "/home/fossandon/.local/lib/python3.6/site-packages/cutadapt/__main__.py", line 848, in main_cli
    main(sys.argv[1:])
  File "/home/fossandon/.local/lib/python3.6/site-packages/cutadapt/__main__.py", line 913, in main
    stats = r.run()
  File "/home/fossandon/.local/lib/python3.6/site-packages/cutadapt/pipeline.py", line 825, in run
    raise e
OSError: CRC check failed 0x8b1f001a != 0xd2f5dc20

Inspecting the changes in the last release, I found that a couple of lines added in 0.8.1 fix were modified:

• 0.8.1 fix: 56aa7e3
• 0.11.0 update: 828838e#diff-d05516ceb7e6ea92efd8881aa50518ceab2c1f2d3fed2c63f69fd7a9694c8e4eL232-L233

Could it be that the modification caused a regression??

I shared the the files pair that caused the error in this folder, so you can reproduce it on your end:
https://drive.google.com/drive/folders/1iOqvXbDQQd8NDtnZhzutmOxx4wUONO-k?usp=sharing

Best regards,

[rhpvorderman]

Thank you for reporting this bug.
I am trying to reproduce it, but so far:

$ python3 -m isal.igzip -cd 136727_S159_L001_R1_001.fastq.gz | md5sum
b3b87c83509bd2c2688145cc96156cba  -
$ pigz -cd 136727_S159_L001_R1_001.fastq.gz | md5sum
b3b87c83509bd2c2688145cc96156cba  -
$ python3 -m isal.igzip -cd 136727_S159_L001_R2_001.fastq.gz | md5sum
e9f98fc17c20add55c7fc72ac6e3c0ba  -
$ pigz -cd 136727_S159_L001_R2_001.fastq.gz | md5sum
e9f98fc17c20add55c7fc72ac6e3c0ba  -

It looks like the code functions correctly, and also the automated tests were not triggered (which include concatenated gzip files after you reported the issue).

It is indeed true that 0.11.0 may cause issues as I changed the decompressor backend. The one that is modelled after zlibmodule.c is inefficient. It reports back unprocessed bytes every time the decompress function is called. This means a new python object is created. Which is quite some overhead.
The decompressor backend in 0.11.0 is modelled after bz2module.c in python. This one saves the bytes internally in a C-pointer. It has a needs_input flag that will turn True when there are no bytes left.
Using this structure python -m isal.igzip is now 10% faster than in version 0.10.0. The overhead has been reduced from 20% to 10% (as measured against the igzip utility).

But of course this may cause unforeseen issues. So I am glad that you reported it. I will check some other things to reproduce your issue. Maybe the interaction between dnaio and xopen causes an issue somewhere.

[rhpvorderman]

I did some further testing. It works fine on my machine using my system python (3.7.3) and pip installing cutadapt, but using conda python and cutadapt it fails. Very weird stuff indeed. I will check if there have been some changes in gzip.py from Cpython upstream, as python-isal inherits from that mostly.

[rhpvorderman]

I found the cause of the bug. Same cause as last time. The bitbuffer object in the isal_inflate_state.

The bug occurs when data fed to the decompressor contains a very small amount of gzip trailer. This part of the gzip trailer is still in the bitbuffer and is not reported in unused_data. Because if everything is finished, the bitbuffer is also not checked. (This is inherited from the bz2module.c behaviour but is wrong).
See https://github.com/pycompression/python-isal/blob/develop/src/isal/igzip_lib.pyx#L484 even if avail_in_real == 0 the bitbuffer should still be checked. The check should be removed. It is a pointless optimization. Running Pybytes_fromstringandsize with size 0, returns a new empty bytes object anyway (does not crash).

[rhpvorderman]

This is a very nasty bug. It is only triggered when the data that is read in ends exactly somewhere in the 8-byte wide gzip trailer. This chance is very slim so the bug can only be triggered sporadically. I was only able to reproduce the bug by reproducing the exact circumstances generated by cutadapt as you reported. Thanks to pycharm's excellent debugger I was able to find the cause. (Unused_data was incorrectly reported as b"" while the supposed 'trailer' contained parts of a gzip header, which I was able to recognize because I spent way too much time on gzip headers...).

Now that I know the cause I should be able to make a test case that always does this. Then I will release 0.11.1 with the fix.
I will yank 0.11.0 for now so that nobody installs it until a fix is released.
Thanks again for reporting.

[rhpvorderman]

Ping @marcelm so you know this happened. 0.11.0 is yanked. When issues like this crop up on the cutadapt issue tracker they can be referred here.

[fjossandon]

Awesome detective work! I'm glad that you were able to find the error and fix it. Then I will take down the shared files.
I will checkout your new version as soon as is released. Thanks for that.

[rhpvorderman]

0.11.1 is released. It fixes the issue and contains tests for regression. I tested it with the files you sent. Can you test it yourself as well?

Thanks again for the excellent bug reporting. Having the test files and an exact command to reproduce the issue was vital in solving the bug.

[fjossandon]

hello @rhpvorderman , I just tested new release 0.11.1 with the files and they work perfectly!

fossandon@ubuntu:~/Documents/download$ cutadapt -a "AACTTTYARCAAYGGATCTC;max_error_rate=0.1;min_overlap=20" -A "TGATCCYTCCGCAGGT;max_error_rate=0.5;min_overlap=16" --pair-adapters --pair-filter any --cores 2 --output 136727_R1.fastq --paired-output 136727_R2.fastq 136727_S159_L001_R1_001.fastq.gz 136727_S159_L001_R2_001.fastq.gz
This is cutadapt 3.4 with Python 3.6.9
Command line parameters: -a AACTTTYARCAAYGGATCTC;max_error_rate=0.1;min_overlap=20 -A TGATCCYTCCGCAGGT;max_error_rate=0.5;min_overlap=16 --pair-adapters --pair-filter any --cores 2 --output 136727_R1.fastq --paired-output 136727_R2.fastq 136727_S159_L001_R1_001.fastq.gz 136727_S159_L001_R2_001.fastq.gz
Processing reads on 2 cores in paired-end mode ...
[ 8<---------] 00:00:02       109,557 reads  @     25.9 µs/read;   2.31 M reads/minute
Finished in 2.98 s (27 us/read; 2.20 M reads/minute).

=== Summary ===

Total read pairs processed:            109,557
  Read 1 with adapter:                  98,402 (89.8%)
  Read 2 with adapter:                  98,402 (89.8%)
Pairs written (passing filters):       109,557 (100.0%)

Total basepairs processed:    65,953,314 bp
  Read 1:    32,976,657 bp
  Read 2:    32,976,657 bp
Total written (filtered):     45,161,091 bp (68.5%)
  Read 1:    22,623,109 bp
  Read 2:    22,537,982 bp

Thanks for the fix!
During the weekend I found another pair of files giving the error with the previous version, and they also work with the new version, so everything is good now!