View Issue Details

IDProjectCategoryView StatusLast Update
0000670Other Unix PortBugpublic2018-10-16 02:17
ReporterLewisR Assigned Topsmedley  
PrioritynormalSeveritymajorReproducibilityalways
Status assignedResolutionopen 
Summary0000670: tnftp breaks binary transfers
Descriptiontnftp-20170409.zip

Have not tested uploads, nor have I tested text transfers. Binaries fail, with Interrupted system call.
Additional Informationls
[...]
-rwxrwxrwx 1 ftp -A--N 11578584 Dec 31 11:22 updates_31st_december_
2016.zip
226 Transfer complete.
mget updates_*
mget updates_31st_december_2016.zip [anpqy?]? y
227 Entering passive mode (192,168,100,2,199,214)
150 Opening BINARY mode data connection for file updates_31st_december_2016.zip (11578584 bytes).
 14% |**** | 1599 KiB 1.50 MiB/s 00:06 ETAt
nftp.exe: Reading from network: Interrupted system call
  0% | | -1 0.00 KiB/s --:-- ETA
426 Transfer failed.

Resulting file:

 4-09-17 11:20 1,637,752 124 updates_31st_december_2016.zip

[j:\]unzip -t updates_31st_december_2016.zip
Archive: updates_31st_december_2016.zip
  End-of-central-directory signature not found. Either this file is not
  a zipfile, or it constitutes one disk of a multi-part archive. In the
  latter case the central directory and zipfile comment will be found on
  the last disk(s) of this archive.
TagsNo tags attached.

Activities

LewisR

2017-04-09 15:39

developer   ~0003135

Tested with explicitly setting binary mode; same result.

ASCII transfers in both directions seem to work just fine, however, as does paging using the configured PAGER (less, in my case).

psmedley

2017-04-09 20:11

administrator   ~0003136

I wonder if I broke this by modifying the code for non-blocking - will try and investigate this evening

psmedley

2017-04-10 09:03

administrator   ~0003137

Yep, seems messing around with O_NONBLOCK broke ftp downloads. http://smedley.id.au/tmp/tnftp-20170410.zip seems to address

LewisR

2017-04-10 22:39

developer   ~0003138

Sorry, Paul, but this did not do it:

 4-10-17 4:59 1,799,788 124 tnftp.exe

mget blue*
mget bluelion-4.9.1-en.7z [anpqy?]? y
227 Entering passive mode (192,168,100,2,207,82)
150 Opening BINARY mode data connection for file bluelion-4.9.1-en.7z (846488957
 bytes).
  0% | | 4054 KiB 3.80 MiB/s 03:31 ETAt
nftp.exe: Reading from network: Interrupted system call
  0% | | -1 0.00 KiB/s --:-- ETA
426 Transfer failed.

Try again?

psmedley

2017-04-11 09:33

administrator   ~0003139

i'll try with a bigger test file, the file I tried was quite small

psmedley

2017-04-11 09:39

administrator   ~0003140

Last edited: 2017-04-11 09:48

mget *.zip
mget client-4.x.zip [anpqy?]? y
227 Entering Passive Mode (192,168,1,200,252,222).
150 Opening BINARY mode data connection for client-4.x.zip (20234082 bytes).
100% |***********************************| 19759 KiB 7.22 MiB/s 00:00 ETA
226 Transfer complete.
20234082 bytes received in 00:02 (7.21 MiB/s)

Any environment variables set or anything to modify tnftp from the default settings?

i'm just using:
tnftp 192.168.1.200 21

to connect to a local ftp server

LewisR

2017-04-12 21:18

developer   ~0003141

First, the exe I'm using has an md5sum of:

2ee94ed85add1385fe2644e407615bc1

(just to be sure we're using the same build)

Next, I started tnftp from a prompt, then:

o hawking
<username>
<password>
cd /ftp/arcanoae/bluelion/betas

and the above.

Hawking is on the local LAN segment, so there's no firewall or NAT traversal to be made. I'll try with a smaller file...

Nope:

mget *2017-04*
mget rpm-yum-base-os2-i686-2017-04-08.exe [anpqy?]? y
227 Entering passive mode (192,168,100,2,220,20)
150 Opening BINARY mode data connection for file rpm-yum-base-os2-i686-2017-04-0
8.exe (44382826 bytes).
  0% | | 0 0.00 KiB/s --:-- ETAt
nftp.exe: Reading from network: Interrupted system call
  0% | | -1 0.00 KiB/s --:-- ETA
426 Transfer failed.
mget rpm-yum-base-os2-i686-2017-04-08.zip [anpqy?]? n
binary
200 OK
get rpm-yum-base-os2-i686-2017-04-08.zip
local: rpm-yum-base-os2-i686-2017-04-08.zip remote: rpm-yum-base-os2-i686-2017-0
4-08.zip
227 Entering passive mode (192,168,100,2,220,31)
150 Opening BINARY mode data connection for file rpm-yum-base-os2-i686-2017-04-0
8.zip (44343605 bytes).
 13% |**** | 5798 KiB 1.37 MiB/s 00:26 ETAt
nftp.exe: Reading from network: Interrupted system call
  0% | | -1 0.00 KiB/s --:-- ETA
426 Transfer failed.

Local filesystem is JFS, though that should not matter, in this case.

Smaller test:

-rwxrwxrwx 1 ftp -A--N 5426 Aug 8 2014 zwrotlogs.txt
226 Transfer complete.
get zwrotlogs.exe
local: zwrotlogs.exe remote: zwrotlogs.exe
227 Entering passive mode (192,168,100,2,220,87)
150 Opening BINARY mode data connection for file zwrotlogs.exe (87928 bytes).
100% |***********************************| 87928 1.94 MiB/s 00:00 ETA
226 Transfer complete, closing data connection.
87928 bytes received in 00:00 (1.71 MiB/s)

That works, as does:

get whois.exe
local: whois.exe remote: whois.exe
227 Entering passive mode (192,168,100,2,220,106)
150 Opening BINARY mode data connection for file whois.exe (135867 bytes).
100% |***********************************| 132 KiB 132.68 KiB/s --:-- ETA
226 Transfer complete, closing data connection.
135867 bytes received in 00:00 (132.68 KiB/s)

So, it would seem that there is some size thing happening somewhere. Both of those smaller binaries came down intact.

psmedley

2017-04-25 04:41

administrator   ~0003142

Last edited: 2017-04-25 04:57

ok, finally got around to trying to reproduce and succeeded on a larger file :)
tnftp.exe: Reading from network: Interrupted system call

OK, please try http://smedley.id.au/tmp/tnftp-20170425.zip

read() was failing with EINTR - added some code to workaround this :)

psmedley

2017-04-25 09:53

administrator   ~0003143

OK upload was similarly broken, zip refreshed with the fix

psmedley

2017-04-25 10:04

administrator   ~0003144

hmmmm except the file ends up corrupt.... need to think more on this and why read() is reporting EINTR and how to prevent this... setting the socket non-blocking didn't help.

I changed:
        while (bufrem > 0) {
            inc = read(infd, buf, MIN((off_t)bufsize, bufrem));
            if ((inc <= 0) && (errno != EINTR))
                goto copy_done;
            bytes += inc;
            bufrem -= inc;

to:
        while (bufrem > 0) {
            inc = read(infd, buf, MIN((off_t)bufsize, bufrem));
            if (inc <= 0)
                goto copy_done;
            bytes += inc;
            bufrem -= inc;

thinking now, of course this corrupts the file as inc is later used to change the amount of data to still be read, I probably need to reset inc to 0 if EINTR is received. Will play more tomorrow, at least I know where it's failing :)

LewisR

2017-11-12 22:00

developer   ~0003149

Reminder sent to: Steven Levine

Steve, as we were looking at this as a poss9ible replacement for IBM's FTP in ArcaOS, when you have a few minutes to look at the code, your thoughts would be appreciated. The server email hiccup today served as a good reminder that this issue was still sort of hanging.

LewisR

2018-10-16 02:17

developer   ~0003202

This has become something of an issue (again), Paul. FWIW, I attempted to download a 2MB file from Hobbes with the 20170425 build, and got a 56KB chunk before "interrupted system call" was reported. Further testing with tracing (-t) and debug enabled showed:

---> RETR qk.zip
150 Opening BINARY mode data connection for qk.zip (2103580 bytes).
 15% |*****                              |   322 KiB  314.54 KiB/s    00:05 ETAt
nftp.exe: Reading from network: Interrupted system call
  0% |                                   |    -1        0.00 KiB/s    --:-- ETA
426 Failure writing network stream.
xferbuf 512k
Socket buffer sizes: send 524288, receive 524288.
get qk.zip
local: qk.zip remote: qk.zip
---> SIZE qk.zip
213 2103580
---> PASV
227 Entering Passive Mode (128,123,34,6,44,253).
tnftp.exe: Unable to set sndbuf size 524288: No buffer space available
tnftp.exe: Unable to set rcvbuf size 524288: No buffer space available
---> RETR qk.zip
150 Opening BINARY mode data connection for qk.zip (2103580 bytes).
 32% |***********                        |   677 KiB  328.26 KiB/s    00:04 ETAt
nftp.exe: Reading from network: Interrupted system call
  0% |                                   |    -1        0.00 KiB/s    --:-- ETA
426 Failure writing network stream.
xferbuf 256k
Socket buffer sizes: send 262144, receive 262144.
get qk.zip
local: qk.zip remote: qk.zip
---> SIZE qk.zip
213 2103580
---> PASV
227 Entering Passive Mode (128,123,34,6,105,135).
tnftp.exe: Unable to set sndbuf size 262144: No buffer space available
tnftp.exe: Unable to set rcvbuf size 262144: No buffer space available
---> RETR qk.zip
150 Opening BINARY mode data connection for qk.zip (2103580 bytes).
 13% |****                               |   276 KiB  270.58 KiB/s    00:06 ETAt
nftp.exe: Reading from network: Interrupted system call
  0% |                                   |    -1        0.00 KiB/s    --:-- ETA
426 Failure writing network stream.
xferbuf 128k
Socket buffer sizes: send 131072, receive 131072.
get qk.zip
local: qk.zip remote: qk.zip
---> SIZE qk.zip
213 2103580
---> PASV
227 Entering Passive Mode (128,123,34,6,148,81).
---> RETR qk.zip
150 Opening BINARY mode data connection for qk.zip (2103580 bytes).
  2% |                                   | 45540       44.07 KiB/s    00:45 ETAt
nftp.exe: Reading from network: Interrupted system call
  0% |                                   |    -1        0.00 KiB/s    --:-- ETA
426 Failure writing network stream.
xferbuf 64k
Socket buffer sizes: send 65536, receive 65536.
get qk.zip
local: qk.zip remote: qk.zip
---> SIZE qk.zip
213 2103580
---> PASV
227 Entering Passive Mode (128,123,34,6,92,130).
---> RETR qk.zip
150 Opening BINARY mode data connection for qk.zip (2103580 bytes).
  1% |                                   | 34500       32.74 KiB/s    01:01 ETAt
nftp.exe: Reading from network: Interrupted system call
  0% |                                   |    -1        0.00 KiB/s    --:-- ETA
426 Failure writing network stream.


I would have expected to have enough buffer space for 256K, even if I didn't for 512K. Not having 64K doesn't seem reasonable.

Issue History

Date Modified Username Field Change
2017-04-09 15:32 LewisR New Issue
2017-04-09 15:32 LewisR Status new => assigned
2017-04-09 15:32 LewisR Assigned To => psmedley
2017-04-09 15:39 LewisR Note Added: 0003135
2017-04-09 20:11 psmedley Note Added: 0003136
2017-04-10 09:03 psmedley Note Added: 0003137
2017-04-10 22:39 LewisR Note Added: 0003138
2017-04-11 09:33 psmedley Note Added: 0003139
2017-04-11 09:39 psmedley Note Added: 0003140
2017-04-11 09:48 psmedley Note Edited: 0003140
2017-04-12 21:18 LewisR Note Added: 0003141
2017-04-25 04:41 psmedley Note Added: 0003142
2017-04-25 04:57 psmedley Note Edited: 0003142
2017-04-25 09:53 psmedley Note Added: 0003143
2017-04-25 10:04 psmedley Note Added: 0003144
2017-11-12 22:00 LewisR Note Added: 0003149
2018-10-16 02:17 LewisR Note Added: 0003202