mirror: <file>: file size decreased during transfer

[rechtem]

Hello, I am using version 4.9.2 and got corrupted files using this scenario:

open <account>@<server>
mirror --verbose --use-cache \
    --delete \
    --exclude-rx-from=lftp.exclude \
    ~/tlt ~/Documents

Most files are transferred OK, but one gave: mirror: : file size decreased during transfer

Not to say the relevant file gets corrupted.

I thought this bug had been fixed earlier.

Thanks

[lavv17]

Is it sftp protocol?

On Tue, 13 Oct 2020 at 14:22, rechtem [email protected] wrote:

Hello, I am using version 4.9.2 and got corrupted files using this scenario:

open @ mirror --verbose --use-cache
--delete
--exclude-rx-from=lftp.exclude
~/tlt ~/Documents

Most files are transferred OK, but one gave: mirror: : file size decreased during transfer

Not to say the relevant file gets corrupted.

I thought this bug had been fixed earlier.

Thanks

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/lavv17/lftp/issues/606, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAHLWXHCLOGH2XTWUB2F44TSKQ2ALANCNFSM4SOU33BA .

-- Alexander.

[rechtem]

plain ftp

[xdolnak]

Hi, i am also noticing this error

mirror: : file size decreased during transfer

when running lftp with sftp protocol and mirror -c and verbose options. It occurs during the transmission of .zip files.

[rechtem]

Regarding the offending file, this was a LibreOffice odt, which is some kind of zip file too.

[xdolnak]

Regarding the offending file, this was a LibreOffice odt, which is some kind of zip file too.

I can also confirm that some of the files which have different size are corrupted.

[xdolnak]

I was using 4.8.4 version and saw this closed issue https://github.com/lavv17/lftp/issues/551 so I built 4.9.2 version from source. The latest version also show the same errors.

[leshik]

@lavv17 I stumbled upon this with SFTP protocol, and wonder if there is a way to work around it.

There is some weird SFTP server implementation from Infosys that exists. When they enable encryption-at-rest on their side, things go broke. And the reason is, they report the encrypted file sizes in ls etc, while the actual download (that is unencrypted) size is different.

As I understand that's a blatant violation of standards, anyway would be great to have some workaround. --ignore-size doesn't help because I think it serves a different purpose (at the stage of making a decision, rather than checking the actual download).

[mrechte]

@leshik, did you notice that this is not a sftp issue: it occurs with plain ftp mirror ?

[leshik]

Idk, I don't use plain FTP. Might be the same if an FTP server reports wrong file sizes.

[tibkiss]

@lavv17 : first, thanks for creating lftp. I'm using it for years now, it is the single most awesome cli transfer tool I know.

second, regarding this puzzling issue - which admittedly made me search for alternatives (but stayed with lftp as it is the best):

I ran into this issue very frequently using ubuntu 20.04 with lftp 4.8.4 using sftp target (SSH-2.0-AWS_SFTP_1.1). Then I tried to compile (vanilla) lftp-4.8.0 as a launchpad ticket suggested that version didn't have any problems.

Lo and behold: didn't observe any problem with 4.8.0 on ubuntu-20.04 with the same sftp target.

So must be some regression between 4.8.0 and 4.8.4.

[lavv17]

@tibkiss Please also try 4.8.1, 4.8.2, 4.8.3, it will help to locate the problem in the code.

Also use "debug 10" and send the relevant debug trace.

[toecto]

Current workaround is to use set sftp:max-packets-in-flight 1;

@lavv17 Here is debug 10 for lftp 4.8.4 Ubuntu 20 Default settings Note in the end expected pos=7969002, actual pos=7503872

debug1: Local version string SSH-2.0-OpenSSH_8.2p1 Ubuntu-4ubuntu0.5
debug1: Remote protocol version 2.0, remote software version AWS_SFTP_1.1

2023-03-24 01:14:42 ---- path on wire is `/FILE1.csv'
2023-03-24 01:14:42 ---> sending a packet, length=79, type=3(OPEN), id=506
2023-03-24 01:14:42 <--- got a packet, length=25, type=101(STATUS), id=504
2023-03-24 01:14:42 ---- status code=1(EOF), message=
2023-03-24 01:14:42 <--- got a packet, length=32, type=101(STATUS), id=505
2023-03-24 01:14:42 ---- status code=0(OK), message=Success
2023-03-24 01:14:42 <--- got a packet, length=10, type=102(HANDLE), id=506
2023-03-24 01:14:42 ---- got file handle 33 (1)
2023-03-24 01:14:42 ---> sending a packet, length=10, type=8(FSTAT), id=507
2023-03-24 01:14:42 <--- got a packet, length=29, type=105(ATTRS), id=507
2023-03-24 01:14:42 ---- file info: size=7969002, date=Thu Mar 16 07:11:29 2023
2023-03-24 01:14:42 ---> sending a packet, length=22, type=5(READ), id=508
2023-03-24 01:14:42 ---> sending a packet, length=22, type=5(READ), id=509
Skipped ... (no missed packets so far)
2023-03-24 01:14:43 ---> sending a packet, length=22, type=5(READ), id=748
2023-03-24 01:14:43 <--- got a packet, length=32777, type=103(DATA), id=736
2023-03-24 01:14:43 ---- put a packet with id=736 on out-of-order chain (need_pos=7176192 packet_pos=7471104)
2023-03-24 01:14:43 ---> sending a packet, length=22, type=5(READ), id=749
2023-03-24 01:14:43 <--- got a packet, length=32777, type=103(DATA), id=738
2023-03-24 01:14:43 ---- put a packet with id=738 on out-of-order chain (need_pos=7176192 packet_pos=7536640)
2023-03-24 01:14:43 ---> sending a packet, length=22, type=5(READ), id=750
2023-03-24 01:14:43 <--- got a packet, length=32777, type=103(DATA), id=734
2023-03-24 01:14:43 ---- put a packet with id=734 on out-of-order chain (need_pos=7176192 packet_pos=7405568)
2023-03-24 01:14:43 ---> sending a packet, length=22, type=5(READ), id=751
2023-03-24 01:14:43 <--- got a packet, length=32777, type=103(DATA), id=735
2023-03-24 01:14:43 ---- put a packet with id=735 on out-of-order chain (need_pos=7176192 packet_pos=7438336)
2023-03-24 01:14:43 <--- got a packet, length=32777, type=103(DATA), id=727
2023-03-24 01:14:43 ---- data packet: pos=7176192, size=32768
2023-03-24 01:14:43 ---- data packet: pos=7208960, size=32768
2023-03-24 01:14:43 ---- data packet: pos=7241728, size=32768
2023-03-24 01:14:43 ---- data packet: pos=7274496, size=32768
2023-03-24 01:14:43 ---- data packet: pos=7307264, size=32768
2023-03-24 01:14:43 ---- data packet: pos=7340032, size=32768
2023-03-24 01:14:43 ---- data packet: pos=7372800, size=32768
2023-03-24 01:14:43 ---- data packet: pos=7405568, size=32768
2023-03-24 01:14:43 ---- data packet: pos=7438336, size=32768
2023-03-24 01:14:43 ---- data packet: pos=7471104, size=32768
2023-03-24 01:14:43 <--- got a packet, length=32777, type=103(DATA), id=739
2023-03-24 01:14:43 ---- put a packet with id=739 on out-of-order chain (need_pos=7503872 packet_pos=7569408)
2023-03-24 01:14:43 <--- got a packet, length=32777, type=103(DATA), id=740
2023-03-24 01:14:43 ---- put a packet with id=740 on out-of-order chain (need_pos=7503872 packet_pos=7602176)
2023-03-24 01:14:43 <--- got a packet, length=32777, type=103(DATA), id=741
2023-03-24 01:14:43 ---- put a packet with id=741 on out-of-order chain (need_pos=7503872 packet_pos=7634944)
2023-03-24 01:14:43 <--- got a packet, length=32777, type=103(DATA), id=742
2023-03-24 01:14:43 ---- put a packet with id=742 on out-of-order chain (need_pos=7503872 packet_pos=7667712)
2023-03-24 01:14:43 <--- got a packet, length=32777, type=103(DATA), id=746
2023-03-24 01:14:43 ---- put a packet with id=746 on out-of-order chain (need_pos=7503872 packet_pos=7798784)
2023-03-24 01:14:43 <--- got a packet, length=32777, type=103(DATA), id=748
2023-03-24 01:14:43 ---- put a packet with id=748 on out-of-order chain (need_pos=7503872 packet_pos=7864320)
2023-03-24 01:14:43 <--- got a packet, length=32777, type=103(DATA), id=747
2023-03-24 01:14:43 ---- put a packet with id=747 on out-of-order chain (need_pos=7503872 packet_pos=7831552)
2023-03-24 01:14:43 <--- got a packet, length=32777, type=103(DATA), id=745
2023-03-24 01:14:43 ---- put a packet with id=745 on out-of-order chain (need_pos=7503872 packet_pos=7766016)
2023-03-24 01:14:43 <--- got a packet, length=32777, type=103(DATA), id=743
2023-03-24 01:14:43 ---- put a packet with id=743 on out-of-order chain (need_pos=7503872 packet_pos=7700480)
2023-03-24 01:14:43 <--- got a packet, length=32777, type=103(DATA), id=744
2023-03-24 01:14:43 ---- put a packet with id=744 on out-of-order chain (need_pos=7503872 packet_pos=7733248)
2023-03-24 01:14:43 <--- got a packet, length=6387, type=103(DATA), id=751
2023-03-24 01:14:43 ---- put a packet with id=751 on out-of-order chain (need_pos=7503872 packet_pos=7962624)
2023-03-24 01:14:43 <--- got a packet, length=32777, type=103(DATA), id=750
2023-03-24 01:14:43 ---- put a packet with id=750 on out-of-order chain (need_pos=7503872 packet_pos=7929856)
2023-03-24 01:14:43 <--- got a packet, length=32777, type=103(DATA), id=749
2023-03-24 01:14:43 ---- put a packet with id=749 on out-of-order chain (need_pos=7503872 packet_pos=7897088)
2023-03-24 01:14:43 ---> sending a packet, length=22, type=5(READ), id=752
2023-03-24 01:14:43 <--- got a packet, length=25, type=101(STATUS), id=752
2023-03-24 01:14:43 ---- status code=1(EOF), message=
2023-03-24 01:14:43 ---- eof
2023-03-24 01:14:43 copy-peer: EOF on sftp://login@server/FILE1.csv
2023-03-24 01:14:43 ---> sending a packet, length=10, type=4(CLOSE), id=753
2023-03-24 01:14:43 copy: get hit eof
2023-03-24 01:14:43 expected pos=7969002, actual pos=7503872
2023-03-24 01:14:43 ---- path on wire is `/FILE2.csv'
2023-03-24 01:14:43 ---> sending a packet, length=79, type=3(OPEN), id=754
2023-03-24 01:14:43 <--- got a packet, length=32777, type=103(DATA), id=737
2023-03-24 01:14:43 <--- got a packet, length=32, type=101(STATUS), id=753
2023-03-24 01:14:43 ---- status code=0(OK), message=Success

Error:

mget: FILE1.csv: file size decreased during transfer

[tibkiss]

I also sometimes have **** Too many out-of-order packets in the log:

mirror: x_2018-06-20.zip: file size decreased during transfer
expected pos=9732616, actual pos=9732096
mirror: x_2018-08-23.zip: file size decreased during transfer
expected pos=9867916, actual pos=9863168
mirror: x_2018-09-12.zip: file size decreased during transfer
**** Too many out-of-order packets
expected pos=12672574, actual pos=12648448
mirror: x_2019-04-01.zip: file size decreased during transfer
expected pos=13212310, actual pos=13205504