Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Appveyor test failures #6972

Closed
kevinburke opened this issue Apr 27, 2021 · 2 comments
Closed

Appveyor test failures #6972

kevinburke opened this issue Apr 27, 2021 · 2 comments
Labels
CI Continuous Integration tests

Comments

@kevinburke
Copy link
Contributor

PR's are consistently failing but it seems like the failing tests are not well correlated to the proposed patch or other test failures, i.e. they suggest that some of the tests may be flaky. Further, it seems unlikely that literally every single PR breaks the tests, as is currently the case.

Here are some of the test failures:

Test 1348/1381

These tests FTP download. Here is the output on the Appveyor server - it looks like the generated command didn't write a QUIT message.

test 1348...[FTP download, file without Content-Disposition inside, using -O]
Warning: server logs lock timeout (2 seconds) expired
 1348: protocol FAILED:
--- log/check-expected	2021-04-26 21:08:41.080589300 +0000
+++ log/check-generated	2021-04-26 21:08:41.080589300 +0000
@@ -6,4 +6,3 @@
 TYPE I[CR][LF]
 SIZE file1348[CR][LF]
 RETR file1348[CR][LF]
-QUIT[CR][LF]
== Contents of files in the log/ dir after test 1348
=== Start of file check-expected
 USER anonymous[CR][LF]
 PASS ftp@example.com[CR][LF]
 PWD[CR][LF]
 CWD path[CR][LF]
 EPSV[CR][LF]
 TYPE I[CR][LF]
 SIZE file1348[CR][LF]
 RETR file1348[CR][LF]
 QUIT[CR][LF]
=== End of file check-expected
=== Start of file check-generated
 USER anonymous[CR][LF]
 PASS ftp@example.com[CR][LF]
 PWD[CR][LF]
 CWD path[CR][LF]
 EPSV[CR][LF]
 TYPE I[CR][LF]
 SIZE file1348[CR][LF]
 RETR file1348[CR][LF]
=== End of file check-generated
=== Start of file commands.log
 ../src/curl.exe --trace-ascii log/trace1348 --trace-time ftp://127.0.0.1:2491/path/file1348 -O >log/stdout1348 2>log/stderr1348
=== End of file commands.log
=== Start of file file1348
 fooo
 mooo
=== End of file file1348
=== Start of file ftp_server.log
 21:07:34.658713 ====> Client connect
 21:07:34.659163 FTPD: Getting commands from log/ftpserver.cmd
 21:07:34.659287 FTPD: run test case number: 1348
 21:07:34.659523 > "220-        _   _ ____  _     [CR][LF]220-    ___| | | |  _ \| |    [CR][LF]220-   / __| | | | |_) | |    [CR][LF]220-  | (__| |_| |  _ {| |___ [CR][LF]220    \___|\___/|_| \_\_____|[CR][LF]"
 21:07:34.660817 < "USER anonymous"
 21:07:34.660948 > "331 We are happy you popped in![CR][LF]"
 21:07:34.661807 < "PASS ftp@example.com"
 21:07:34.661924 > "230 Welcome you silly person[CR][LF]"
 21:07:34.662796 < "PWD"
 21:07:34.662914 > "257 "/" is current directory[CR][LF]"
 21:07:34.663859 < "CWD path"
 21:07:34.663973 > "250 CWD command successful.[CR][LF]"
 21:07:34.664931 < "EPSV"
 21:07:34.665037 ====> Passive DATA channel requested by client
 21:07:34.665125 DATA sockfilt for passive data channel starting...
 21:07:34.698046 DATA sockfilt for passive data channel started (pid 7282)
 21:07:34.698989 DATA sockfilt for passive data channel listens on port 8897
 21:07:34.699125 > "229 Entering Passive Mode (|||8897|)[LF]"
 21:07:34.699230 Client has been notified that DATA conn will be accepted on port 8897
 21:07:34.700133 Client connects to port 8897
 21:07:34.700253 ====> Client established passive DATA connection on port 8897
 21:07:34.700636 < "TYPE I"
 21:07:34.700755 > "200 I modify TYPE as you wanted[CR][LF]"
 21:07:34.701777 < "SIZE file1348"
 21:07:34.702195 > "213 10[CR][LF]"
 21:07:34.702977 < "RETR file1348"
 21:07:34.703259 > "150 Binary data connection for 1348 () (10 bytes).[CR][LF]"
 21:07:38.564964 =====> Closing passive DATA connection...
 21:07:38.565152 Server disconnects passive DATA connection
 21:07:38.565909 Server disconnected passive DATA connection
 21:07:38.566016 DATA sockfilt for passive data channel quits (pid 69560)
=== End of file ftp_server.log
=== Start of file ftp_sockctrl.log
 21:07:34.609000 [select_ws] 152 is readable
 21:07:34.609000 ====> Client connect
 21:07:34.609000 [select_ws_wait_thread] PeekNamedPipe len: 10
 21:07:34.609000 [select_ws_wait_thread] data available, PIPE: 0x134
 21:07:34.609000 [select_ws] 0 is readable
 21:07:34.609000 Received DATA (on stdin)
 21:07:34.609000 > 160 bytes data, server => client
 21:07:34.609000 '220-        _   _ ____  _     \r\n220-    ___| | | |  _ \| | '
 21:07:34.609000 '   \r\n220-   / __| | | | |_) | |    \r\n220-  | (__| |_| |  '
 21:07:34.609000 '_ {| |___ \r\n220    \___|\___/|_| \_\_____|\r\n'
 21:07:34.609000 [select_ws] 348 is readable
 21:07:34.609000 < 16 bytes data, client => server
 21:07:34.609000 'USER anonymous\r\n'
 21:07:34.609000 [select_ws_wait_thread] PeekNamedPipe len: 43
 21:07:34.609000 [select_ws_wait_thread] data available, PIPE: 0x134
 21:07:34.609000 [select_ws] 0 is readable
 21:07:34.609000 Received DATA (on stdin)
 21:07:34.609000 > 33 bytes data, server => client
 21:07:34.609000 '331 We are happy you popped in!\r\n'
 21:07:34.609000 [select_ws] 348 is readable
 21:07:34.609000 < 22 bytes data, client => server
 21:07:34.609000 'PASS ftp@example.com\r\n'
 21:07:34.609000 [select_ws_wait_thread] PeekNamedPipe len: 40
 21:07:34.609000 [select_ws_wait_thread] data available, PIPE: 0x134
 21:07:34.609000 [select_ws] 0 is readable
 21:07:34.609000 Received DATA (on stdin)
 21:07:34.609000 > 30 bytes data, server => client
 21:07:34.609000 '230 Welcome you silly person\r\n'
 21:07:34.609000 [select_ws] 348 is readable
 21:07:34.609000 < 5 bytes data, client => server
 21:07:34.609000 'PWD\r\n'
 21:07:34.609000 [select_ws_wait_thread] PeekNamedPipe len: 10
 21:07:34.609000 [select_ws_wait_thread] data available, PIPE: 0x134
 21:07:34.609000 [select_ws] 0 is readable
 21:07:34.609000 Received DATA (on stdin)
 21:07:34.609000 > 30 bytes data, server => client
 21:07:34.609000 '257 "/" is current directory\r\n'
 21:07:34.609000 [select_ws] 348 is readable
 21:07:34.609000 < 10 bytes data, client => server
 21:07:34.609000 'CWD path\r\n'
 21:07:34.609000 [select_ws_wait_thread] PeekNamedPipe len: 10
 21:07:34.609000 [select_ws_wait_thread] data available, PIPE: 0x134
 21:07:34.609000 [select_ws] 0 is readable
 21:07:34.609000 Received DATA (on stdin)
 21:07:34.609000 > 29 bytes data, server => client
 21:07:34.609000 '250 CWD command successful.\r\n'
 21:07:34.609000 [select_ws] 348 is readable
 21:07:34.609000 < 6 bytes data, client => server
 21:07:34.609000 'EPSV\r\n'
 21:07:34.656000 [select_ws_wait_thread] PeekNamedPipe len: 10
 21:07:34.656000 [select_ws_wait_thread] data available, PIPE: 0x134
 21:07:34.656000 [select_ws] 0 is readable
 21:07:34.656000 Received DATA (on stdin)
 21:07:34.656000 > 37 bytes data, server => client
 21:07:34.656000 '229 Entering Passive Mode (|||8897|)\n'
 21:07:34.656000 [select_ws] 348 is readable
 21:07:34.656000 < 8 bytes data, client => server
 21:07:34.656000 'TYPE I\r\n'
 21:07:34.656000 [select_ws_wait_thread] PeekNamedPipe len: 10
 21:07:34.656000 [select_ws_wait_thread] data available, PIPE: 0x134
 21:07:34.656000 [select_ws] 0 is readable
 21:07:34.656000 Received DATA (on stdin)
 21:07:34.656000 > 33 bytes data, server => client
 21:07:34.656000 '200 I modify TYPE as you wanted\r\n'
 21:07:34.656000 [select_ws] 348 is readable
 21:07:34.656000 < 15 bytes data, client => server
 21:07:34.656000 'SIZE file1348\r\n'
 21:07:34.656000 [select_ws_wait_thread] PeekNamedPipe len: 18
 21:07:34.656000 [select_ws_wait_thread] data available, PIPE: 0x134
 21:07:34.656000 [select_ws] 0 is readable
 21:07:34.656000 Received DATA (on stdin)
 21:07:34.656000 > 8 bytes data, server => client
 21:07:34.656000 '213 10\r\n'
 21:07:34.656000 [select_ws] 348 is readable
 21:07:34.656000 < 15 bytes data, client => server
 21:07:34.656000 'RETR file1348\r\n'
 21:07:34.656000 [select_ws_wait_thread] PeekNamedPipe len: 62
 21:07:34.656000 [select_ws_wait_thread] data available, PIPE: 0x134
 21:07:34.656000 [select_ws] 0 is readable
 21:07:34.656000 Received DATA (on stdin)
 21:07:34.656000 > 52 bytes data, server => client
 21:07:34.656000 '150 Binary data connection for 1348 () (10 bytes).\r\n'
 21:08:38.531000 [select_ws] 348 is readable
 21:08:38.531000 ====> Client disconnect
=== End of file ftp_sockctrl.log
=== Start of file ftp_sockdata.log
 21:07:34.640000 Running IPv4 version
 21:07:34.656000 Listening on port 8897
 21:07:34.656000 Wrote pid 69560 to ./.ftp_sockdata.pid
 21:07:34.656000 [select_ws_wait_thread] PeekNamedPipe len: 5
 21:07:34.656000 [select_ws_wait_thread] data available, PIPE: 0x144
 21:07:34.656000 [select_ws] 0 is readable
 21:07:34.656000 Received PING (on stdin)
 21:07:34.656000 [select_ws_wait_thread] PeekNamedPipe len: 5
 21:07:34.656000 [select_ws_wait_thread] data available, PIPE: 0x144
 21:07:34.656000 [select_ws] 0 is readable
 21:07:34.656000 Received PORT (on stdin)
 21:07:34.656000 [select_ws] 164 is readable
 21:07:34.656000 ====> Client connect
 21:07:34.656000 [select_ws_wait_thread] PeekNamedPipe len: 30
 21:07:34.656000 [select_ws_wait_thread] data available, PIPE: 0x144
 21:07:34.656000 [select_ws] 0 is readable
 21:07:34.656000 Received DATA (on stdin)
 21:07:34.656000 > 5 bytes data, server => client
 21:07:34.656000 'fooo\n'
 21:07:34.656000 [select_ws_wait_thread] PeekNamedPipe len: 15
 21:07:34.656000 [select_ws_wait_thread] data available, PIPE: 0x144
 21:07:34.656000 [select_ws] 0 is readable
 21:07:34.656000 Received DATA (on stdin)
 21:07:34.656000 > 5 bytes data, server => client
 21:07:34.656000 'mooo\n'
 21:07:38.515000 [select_ws_wait_thread] PeekNamedPipe len: 5
 21:07:38.515000 [select_ws_wait_thread] data available, PIPE: 0x144
 21:07:38.515000 [select_ws] 0 is readable
 21:07:38.515000 Received DISC (on stdin)
 21:07:38.515000 ====> Client forcibly disconnected
 21:07:38.515000 [select_ws_wait_thread] PeekNamedPipe len: 5
 21:07:38.515000 [select_ws_wait_thread] data available, PIPE: 0x144
 21:07:38.515000 [select_ws] 0 is readable
 21:07:38.515000 Received QUIT (on stdin)
 21:07:38.515000 quits
 21:07:38.515000 ============> sockfilt quits
=== End of file ftp_sockdata.log
=== Start of file ftpserver.cmd
 Testnum 1348
=== End of file ftpserver.cmd
=== Start of file server.input
 USER anonymous
 PASS ftp@example.com
 PWD
 CWD path
 EPSV
 TYPE I
 SIZE file1348
 RETR file1348
=== End of file server.input
=== Start of file stderr1348
   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                  Dload  Upload   Total   Spent    Left  Speed
 
   0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
 100    10  100    10    0     0      8      0  0:00:01  0:00:01 --:--:--     8
 100    10  100    10    0     0      4      0  0:00:02  0:00:02 --:--:--     4
 100    10  100    10    0     0      3      0  0:00:03  0:00:03 --:--:--     3
 100    10  100    10    0     0      2      0  0:00:05  0:00:03  0:00:02     2
 100    10  100    10    0     0      2      0  0:00:05  0:00:04  0:00:01     2
 100    10  100    10    0     0      1      0  0:00:10  0:00:05  0:00:05     0
 100    10  100    10    0     0      1      0  0:00:10  0:00:06  0:00:04     0
 100    10  100    10    0     0      1      0  0:00:10  0:00:07  0:00:03     0
 100    10  100    10    0     0      1      0  0:00:10  0:00:08  0:00:02     0
 100    10  100    10    0     0      1      0  0:00:10  0:00:09  0:00:01     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:10 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:11 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:12 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:13 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:14 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:15 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:17 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:18 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:19 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:20 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:21 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:22 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:23 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:24 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:25 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:26 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:27 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:28 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:29 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:30 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:31 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:32 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:33 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:34 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:35 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:36 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:37 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:38 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:39 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:40 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:41 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:42 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:43 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:44 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:45 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:46 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:47 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:48 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:49 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:50 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:51 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:52 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:53 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:54 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:55 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:56 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:57 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:58 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:00:59 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:01:00 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:01:01 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:01:02 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:01:03 --:--:--     0
 100    10    0    10    0     0      0      0 --:--:--  0:01:03 --:--:--     0
 curl: (28) FTP response timeout
=== End of file stderr1348
=== Start of file trace1348
 21:07:34.638439 == Info: STATE: INIT => CONNECT handle 0xd5d1d8; line 1753 (connection #-5000)
 21:07:34.639054 == Info: Added connection 0. The cache now contains 1 members
 21:07:34.639083 == Info: family0 == v4, family1 == v6
 21:07:34.639163 == Info:   Trying 127.0.0.1:2491...
 21:07:34.639320 == Info: STATE: CONNECT => CONNECTING handle 0xd5d1d8; line 1814 (connection #0)
 21:07:34.639738 == Info: Connected to 127.0.0.1 (127.0.0.1) port 2491 (#0)
 21:07:34.639746 == Info: STATE: CONNECTING => PROTOCONNECT handle 0xd5d1d8; line 1946 (connection #0)
 21:07:34.639762 == Info: FTP 0xd5cd48 (line 3162) state change from STOP to WAIT220
 21:07:34.639772 == Info: STATE: PROTOCONNECT => PROTOCONNECTING handle 0xd5d1d8; line 1964 (connection #0)
 21:07:34.641088 <= Recv header, 32 bytes (0x20)
 0000: 220-        _   _ ____  _     
 21:07:34.641163 <= Recv header, 32 bytes (0x20)
 0000: 220-    ___| | | |  _ \| |    
 21:07:34.641192 <= Recv header, 32 bytes (0x20)
 0000: 220-   / __| | | | |_) | |    
 21:07:34.641215 <= Recv header, 32 bytes (0x20)
 0000: 220-  | (__| |_| |  _ {| |___ 
 21:07:34.641238 <= Recv header, 32 bytes (0x20)
 0000: 220    \___|\___/|_| \_\_____|
 21:07:34.641281 => Send header, 16 bytes (0x10)
 0000: USER anonymous
 21:07:34.641290 == Info: FTP 0xd5cd48 (line 785) state change from WAIT220 to USER
 21:07:34.642377 <= Recv header, 33 bytes (0x21)
 0000: 331 We are happy you popped in
 21:07:34.642424 => Send header, 22 bytes (0x16)
 0000: PASS ftp@example.com
 21:07:34.642435 == Info: FTP 0xd5cd48 (line 2597) state change from USER to PASS
 21:07:34.643365 <= Recv header, 30 bytes (0x1e)
 0000: 230 Welcome you silly person
 21:07:34.643410 => Send header, 5 bytes (0x5)
 0000: PWD
 21:07:34.643418 == Info: FTP 0xd5cd48 (line 796) state change from PASS to PWD
 21:07:34.644355 <= Recv header, 30 bytes (0x1e)
 0000: 257 "/" is current directory
 21:07:34.644418 == Info: Entry path is '/'
 21:07:34.644424 == Info: FTP 0xd5cd48 (line 2912) state change from PWD to STOP
 21:07:34.644428 == Info: protocol connect phase DONE
 21:07:34.644433 == Info: STATE: PROTOCONNECTING => DO handle 0xd5d1d8; line 1983 (connection #0)
 21:07:34.644454 == Info: DO phase starts
 21:07:34.644474 => Send header, 10 bytes (0xa)
 0000: CWD path
 21:07:34.644484 == Info: FTP 0xd5cd48 (line 902) state change from STOP to CWD
 21:07:34.644492 == Info: ftp_perform ends with SECONDARY: 0
 21:07:34.644497 == Info: STATE: DO => DOING handle 0xd5d1d8; line 2028 (connection #0)
 21:07:34.645504 <= Recv header, 29 bytes (0x1d)
 0000: 250 CWD command successful.
 21:07:34.645555 => Send header, 6 bytes (0x6)
 0000: EPSV
 21:07:34.645564 == Info: FTP 0xd5cd48 (line 1341) state change from CWD to PASV
 21:07:34.645569 == Info: Connect data stream passively
 21:07:34.680599 <= Recv header, 37 bytes (0x25)
 0000: 229 Entering Passive Mode (|||8897|).
 21:07:34.680676 == Info: family0 == v4, family1 == v6
 21:07:34.680713 == Info:   Trying 127.0.0.1:8897...
 21:07:34.680816 == Info: Connecting to 127.0.0.1 (127.0.0.1) port 8897
 21:07:34.680826 == Info: FTP 0xd5cd48 (line 2026) state change from PASV to STOP
 21:07:34.680831 == Info: DO phase is complete2
 21:07:34.680836 == Info: STATE: DOING => DOING_MORE handle 0xd5d1d8; line 2111 (connection #0)
 21:07:34.680902 == Info: Connected to 127.0.0.1 (127.0.0.1) port 2491 (#0)
 21:07:34.680908 == Info: DO-MORE connected phase starts
 21:07:34.681023 => Send header, 8 bytes (0x8)
 0000: TYPE I
 21:07:34.681035 == Info: FTP 0xd5cd48 (line 3501) state change from STOP to RETR_TYPE
 21:07:34.682349 <= Recv header, 33 bytes (0x21)
 0000: 200 I modify TYPE as you wanted
 21:07:34.682400 => Send header, 15 bytes (0xf)
 0000: SIZE file1348
 21:07:34.682416 == Info: FTP 0xd5cd48 (line 1770) state change from RETR_TYPE to RETR_SIZE
 21:07:34.683648 <= Recv header, 8 bytes (0x8)
 0000: 213 10
 21:07:34.683693 => Send header, 15 bytes (0xf)
 0000: RETR file1348
 21:07:34.683703 == Info: FTP 0xd5cd48 (line 2277) state change from RETR_SIZE to RETR
 21:07:34.684793 <= Recv header, 52 bytes (0x34)
 0000: 150 Binary data connection for 1348 () (10 bytes).
 21:07:34.684847 == Info: Maxdownload = -1
 21:07:34.684852 == Info: Getting file with size: 10
 21:07:34.684857 == Info: FTP 0xd5cd48 (line 468) state change from RETR to STOP
 21:07:34.684863 == Info: STATE: DOING_MORE => DID handle 0xd5d1d8; line 2135 (connection #0)
 21:07:34.684869 == Info: STATE: DID => PERFORMING handle 0xd5d1d8; line 2160 (connection #0)
 21:07:34.685317 <= Recv data, 5 bytes (0x5)
 0000: fooo.
 21:07:34.685977 <= Recv data, 5 bytes (0x5)
 0000: mooo.
 21:07:38.549411 == Info: readwrite_data: we're done
 21:07:38.549421 == Info: nread <= 0, server closed connection, bailing
 21:07:38.549453 == Info: STATE: PERFORMING => DONE handle 0xd5d1d8; line 2359 (connection #0)
 21:07:38.549459 == Info: multi_done
 21:07:38.549469 == Info: Remembering we are in dir "path/"
 21:08:38.553183 == Info: FTP response timeout
 21:08:38.553194 == Info: control connection looks dead
 21:08:38.553242 == Info: The cache now contains 0 members
 21:08:38.553268 == Info: Closing connection 0
=== End of file trace1348

And test 1381.

 test 1381...[FTP DL, file without C-D inside, using -o fname -J -D file]
  
   1381: protocol FAILED:
  --- log/check-expected	2021-04-26 23:25:24.821225500 +0000
  +++ log/check-generated	2021-04-26 23:25:24.821225500 +0000
  @@ -6,4 +6,3 @@
   TYPE I[CR][LF]
   SIZE file1381[CR][LF]
   RETR file1381[CR][LF]
  -QUIT[CR][LF]
  == Contents of files in the log/ dir after test 1381
  === Start of file check-expected
   USER anonymous[CR][LF]
   PASS ftp@example.com[CR][LF]
   PWD[CR][LF]
   CWD path[CR][LF]
   EPSV[CR][LF]
   TYPE I[CR][LF]
   SIZE file1381[CR][LF]
   RETR file1381[CR][LF]
   QUIT[CR][LF]
  === End of file check-expected
  === Start of file check-generated
   USER anonymous[CR][LF]
   PASS ftp@example.com[CR][LF]
   PWD[CR][LF]
   CWD path[CR][LF]
   EPSV[CR][LF]
   TYPE I[CR][LF]
   SIZE file1381[CR][LF]
   RETR file1381[CR][LF]
  === End of file check-generated
  === Start of file commands.log
   ../src/curl.exe --trace-ascii log/trace1381 --trace-time ftp://127.0.0.1:2507/path/file1381 -o log/download1381 -J -D log/heads1381 >log/stdout1381 2>log/stderr1381
  === End of file commands.log
  === Start of file ftp_server.log
   23:22:40.258390 ====> Client connect
   23:22:40.258855 FTPD: Getting commands from log/ftpserver.cmd
   23:22:40.258982 FTPD: run test case number: 1381
   23:22:40.259305 > "220-        _   _ ____  _     [CR][LF]220-    ___| | | |  _ \| |    [CR][LF]220-   / __| | | | |_) | |    [CR][LF]220-  | (__| |_| |  _ {| |___ [CR][LF]220    \___|\___/|_| \_\_____|[CR][LF]"
   23:22:40.261145 < "USER anonymous"
   23:22:40.261270 > "331 We are happy you popped in![CR][LF]"
   23:22:40.262506 < "PASS ftp@example.com"
   23:22:40.262621 > "230 Welcome you silly person[CR][LF]"
   23:22:40.263786 < "PWD"
   23:22:40.263897 > "257 "/" is current directory[CR][LF]"
   23:22:40.265264 < "CWD path"
   23:22:40.265372 > "250 CWD command successful.[CR][LF]"
   23:22:40.266584 < "EPSV"
   23:22:40.266684 ====> Passive DATA channel requested by client
   23:22:40.266766 DATA sockfilt for passive data channel starting...
   23:22:40.299689 DATA sockfilt for passive data channel started (pid 7424)
   23:22:40.301421 DATA sockfilt for passive data channel listens on port 9221
   23:22:40.301569 > "229 Entering Passive Mode (|||9221|)[LF]"
   23:22:40.301689 Client has been notified that DATA conn will be accepted on port 9221
   23:22:50.320890 FTP server timed out awaiting data connection on port 9221
   23:22:50.320890 accept failed or connection not even attempted
   23:22:50.320981 DATA sockfilt killed now
   23:23:23.789638 DATA sockfilt not running
   23:23:23.789638 < "TYPE I"
   23:23:23.789756 > "200 I modify TYPE as you wanted[CR][LF]"
   23:23:23.791011 < "SIZE file1381"
   23:23:23.791374 > "213 10[CR][LF]"
   23:23:23.792508 < "RETR file1381"
   23:25:24.805266 MAIN sockfilt said DISC
   23:25:24.805266 ====> Client disconnected
   23:25:24.805522 Awaiting input
  === End of file ftp_server.log
  === Start of file ftp_sockctrl.log
   23:22:40.406000 [select_ws] 160 is readable
   23:22:40.406000 ====> Client connect
   23:22:40.406000 [select_ws_wait_thread] PeekNamedPipe len: 170
   23:22:40.406000 [select_ws_wait_thread] data available, PIPE: 0x140
   23:22:40.406000 [select_ws] 0 is readable
   23:22:40.406000 Received DATA (on stdin)
   23:22:40.406000 > 160 bytes data, server => client
   23:22:40.406000 '220-        _   _ ____  _     \r\n220-    ___| | | |  _ \| | '
   23:22:40.406000 '   \r\n220-   / __| | | | |_) | |    \r\n220-  | (__| |_| |  '
   23:22:40.406000 '_ {| |___ \r\n220    \___|\___/|_| \_\_____|\r\n'
   23:22:40.406000 [select_ws] 1008 is readable
   23:22:40.406000 < 16 bytes data, client => server
   23:22:40.406000 'USER anonymous\r\n'
   23:22:40.406000 [select_ws_wait_thread] PeekNamedPipe len: 43
   23:22:40.406000 [select_ws_wait_thread] data available, PIPE: 0x140
   23:22:40.406000 [select_ws] 0 is readable
   23:22:40.406000 Received DATA (on stdin)
   23:22:40.406000 > 33 bytes data, server => client
   23:22:40.406000 '331 We are happy you popped in!\r\n'
   23:22:40.406000 [select_ws] 1008 is readable
   23:22:40.406000 < 22 bytes data, client => server
   23:22:40.406000 'PASS ftp@example.com\r\n'
   23:22:40.406000 [select_ws_wait_thread] PeekNamedPipe len: 40
   23:22:40.406000 [select_ws_wait_thread] data available, PIPE: 0x140
   23:22:40.406000 [select_ws] 0 is readable
   23:22:40.406000 Received DATA (on stdin)
   23:22:40.406000 > 30 bytes data, server => client
   23:22:40.406000 '230 Welcome you silly person\r\n'
   23:22:40.406000 [select_ws] 1008 is readable
   23:22:40.406000 < 5 bytes data, client => server
   23:22:40.406000 'PWD\r\n'
   23:22:40.421000 [select_ws_wait_thread] PeekNamedPipe len: 40
   23:22:40.421000 [select_ws_wait_thread] data available, PIPE: 0x140
   23:22:40.421000 [select_ws] 0 is readable
   23:22:40.421000 Received DATA (on stdin)
   23:22:40.421000 > 30 bytes data, server => client
   23:22:40.421000 '257 "/" is current directory\r\n'
   23:22:40.421000 [select_ws] 1008 is readable
   23:22:40.421000 < 10 bytes data, client => server
   23:22:40.421000 'CWD path\r\n'
   23:22:40.421000 [select_ws_wait_thread] PeekNamedPipe len: 39
   23:22:40.421000 [select_ws_wait_thread] data available, PIPE: 0x140
   23:22:40.421000 [select_ws] 0 is readable
   23:22:40.421000 Received DATA (on stdin)
   23:22:40.421000 > 29 bytes data, server => client
   23:22:40.421000 '250 CWD command successful.\r\n'
   23:22:40.421000 [select_ws] 1008 is readable
   23:22:40.421000 < 6 bytes data, client => server
   23:22:40.421000 'EPSV\r\n'
   23:22:40.453000 [select_ws_wait_thread] PeekNamedPipe len: 10
   23:22:40.453000 [select_ws_wait_thread] data available, PIPE: 0x140
   23:22:40.453000 [select_ws] 0 is readable
   23:22:40.453000 Received DATA (on stdin)
   23:22:40.453000 > 37 bytes data, server => client
   23:22:40.453000 '229 Entering Passive Mode (|||9221|)\n'
   23:22:50.687000 [select_ws] 1008 is readable
   23:22:50.687000 < 8 bytes data, client => server
   23:22:50.687000 'TYPE I\r\n'
   23:23:23.937000 [select_ws_wait_thread] PeekNamedPipe len: 10
   23:23:23.937000 [select_ws_wait_thread] data available, PIPE: 0x140
   23:23:23.937000 [select_ws] 0 is readable
   23:23:23.937000 Received DATA (on stdin)
   23:23:23.937000 > 33 bytes data, server => client
   23:23:23.937000 '200 I modify TYPE as you wanted\r\n'
   23:23:23.937000 [select_ws] socket 1008 is ready
   23:23:23.937000 [select_ws] 1008 is readable
   23:23:23.937000 < 15 bytes data, client => server
   23:23:23.937000 'SIZE file1381\r\n'
   23:23:23.937000 [select_ws_wait_thread] PeekNamedPipe len: 18
   23:23:23.937000 [select_ws_wait_thread] data available, PIPE: 0x140
   23:23:23.937000 [select_ws] 0 is readable
   23:23:23.937000 Received DATA (on stdin)
   23:23:23.937000 > 8 bytes data, server => client
   23:23:23.937000 '213 10\r\n'
   23:23:23.937000 [select_ws] socket 1008 is ready
   23:23:23.937000 [select_ws] 1008 is readable
   23:23:23.937000 < 15 bytes data, client => server
   23:23:23.937000 'RETR file1381\r\n'
   23:25:24.953000 [select_ws] 1008 is readable
   23:25:24.953000 ====> Client disconnect
  === End of file ftp_sockctrl.log
  === Start of file ftp_sockdata.log
   23:22:40.453000 Running IPv4 version
   23:22:40.453000 Listening on port 9221
   23:22:40.453000 Wrote pid 68844 to ./.ftp_sockdata.pid
   23:22:40.453000 [select_ws_wait_thread] PeekNamedPipe len: 5
   23:22:40.453000 [select_ws_wait_thread] data available, PIPE: 0x154
   23:22:40.453000 [select_ws] 0 is readable
   23:22:40.453000 Received PING (on stdin)
   23:22:40.453000 [select_ws_wait_thread] PeekNamedPipe len: 5
   23:22:40.453000 [select_ws_wait_thread] data available, PIPE: 0x154
   23:22:40.453000 [select_ws] 0 is readable
   23:22:40.453000 Received PORT (on stdin)
   23:22:50.687000 [select_ws] 168 is readable
   23:22:50.687000 ====> Client connect
  === End of file ftp_sockdata.log
  === Start of file ftpserver.cmd
   Testnum 1381
  === End of file ftpserver.cmd
  === Start of file heads1381
   220-        _   _ ____  _     
   220-    ___| | | |  _ \| |    
   220-   / __| | | | |_) | |    
   220-  | (__| |_| |  _ {| |___ 
   220    \___|\___/|_| \_\_____|
   331 We are happy you popped in
   230 Welcome you silly person
   257 "/" is current directory
   250 CWD command successful.
   229 Entering Passive Mode (|||9221|)
   200 I modify TYPE as you wanted
   213 10
  === End of file heads1381
  === Start of file server.input
   USER anonymous
   PASS ftp@example.com
   PWD
   CWD path
   EPSV
   TYPE I
   SIZE file1381
   RETR file1381
  === End of file server.input
  === Start of file stderr1381
     % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                    Dload  Upload   Total   Spent    Left  Speed
   
     0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:10 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:11 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:12 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:13 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:14 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:15 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:16 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:17 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:18 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:19 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:20 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:21 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:22 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:23 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:24 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:25 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:26 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:27 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:28 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:29 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:30 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:31 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:32 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:33 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:34 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:35 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:36 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:37 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:38 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:39 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:40 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:41 --:--:--     0
     0     0    0     0    0     0      0      0 --:--:--  0:00:42 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:00:44 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:00:45 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:00:46 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:00:47 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:00:48 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:00:49 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:00:50 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:00:51 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:00:52 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:00:53 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:00:54 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:00:55 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:00:56 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:00:57 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:00:58 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:00:59 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:00 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:01 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:02 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:03 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:04 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:05 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:06 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:07 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:08 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:09 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:10 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:11 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:12 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:13 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:14 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:15 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:16 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:17 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:18 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:19 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:20 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:21 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:22 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:23 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:24 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:25 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:26 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:27 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:28 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:29 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:30 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:31 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:32 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:33 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:35 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:36 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:37 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:38 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:39 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:40 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:41 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:42 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:43 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:44 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:45 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:46 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:47 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:48 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:49 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:50 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:51 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:52 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:53 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:54 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:55 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:56 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:57 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:58 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:01:59 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:00 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:01 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:02 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:03 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:04 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:05 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:06 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:07 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:08 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:09 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:10 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:11 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:12 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:13 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:14 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:15 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:16 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:17 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:18 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:19 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:20 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:21 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:22 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:23 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:24 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:25 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:26 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:27 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:28 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:29 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:30 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:31 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:32 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:33 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:34 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:35 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:36 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:37 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:38 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:39 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:40 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:41 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:42 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:43 --:--:--     0
     0    10    0     0    0     0      0      0 --:--:--  0:02:44 --:--:--     0
   curl: (28) server response timeout
  === End of file stderr1381
  === Start of file trace1381
   23:22:40.447509 == Info: STATE: INIT => CONNECT handle 0xa659a8; line 1753 (connection #-5000)
   23:22:40.448354 == Info: Added connection 0. The cache now contains 1 members
   23:22:40.448405 == Info: family0 == v4, family1 == v6
   23:22:40.448499 == Info:   Trying 127.0.0.1:2507...
   23:22:40.448668 == Info: STATE: CONNECT => CONNECTING handle 0xa659a8; line 1814 (connection #0)
   23:22:40.449158 == Info: Connected to 127.0.0.1 (127.0.0.1) port 2507 (#0)
   23:22:40.449171 == Info: STATE: CONNECTING => PROTOCONNECT handle 0xa659a8; line 1946 (connection #0)
   23:22:40.449191 == Info: FTP 0xa651a8 (line 3162) state change from STOP to WAIT220
   23:22:40.449206 == Info: STATE: PROTOCONNECT => PROTOCONNECTING handle 0xa659a8; line 1964 (connection #0)
   23:22:40.450878 <= Recv header, 32 bytes (0x20)
   0000: 220-        _   _ ____  _     
   23:22:40.451008 <= Recv header, 32 bytes (0x20)
   0000: 220-    ___| | | |  _ \| |    
   23:22:40.451057 <= Recv header, 32 bytes (0x20)
   0000: 220-   / __| | | | |_) | |    
   23:22:40.451100 <= Recv header, 32 bytes (0x20)
   0000: 220-  | (__| |_| |  _ {| |___ 
   23:22:40.451138 <= Recv header, 32 bytes (0x20)
   0000: 220    \___|\___/|_| \_\_____|
   23:22:40.451212 => Send header, 16 bytes (0x10)
   0000: USER anonymous
   23:22:40.451231 == Info: FTP 0xa651a8 (line 785) state change from WAIT220 to USER
   23:22:40.452678 <= Recv header, 33 bytes (0x21)
   0000: 331 We are happy you popped in
   23:22:40.452763 => Send header, 22 bytes (0x16)
   0000: PASS ftp@example.com
   23:22:40.452783 == Info: FTP 0xa651a8 (line 2597) state change from USER to PASS
   23:22:40.453991 <= Recv header, 30 bytes (0x1e)
   0000: 230 Welcome you silly person
   23:22:40.454070 => Send header, 5 bytes (0x5)
   0000: PWD
   23:22:40.454085 == Info: FTP 0xa651a8 (line 796) state change from PASS to PWD
   23:22:40.455356 <= Recv header, 30 bytes (0x1e)
   0000: 257 "/" is current directory
   23:22:40.455419 == Info: Entry path is '/'
   23:22:40.455428 == Info: FTP 0xa651a8 (line 2912) state change from PWD to STOP
   23:22:40.455437 == Info: protocol connect phase DONE
   23:22:40.455449 == Info: STATE: PROTOCONNECTING => DO handle 0xa659a8; line 1983 (connection #0)
   23:22:40.455479 == Info: DO phase starts
   23:22:40.455505 => Send header, 10 bytes (0xa)
   0000: CWD path
   23:22:40.455522 == Info: FTP 0xa651a8 (line 902) state change from STOP to CWD
   23:22:40.455535 == Info: ftp_perform ends with SECONDARY: 0
   23:22:40.455544 == Info: STATE: DO => DOING handle 0xa659a8; line 2028 (connection #0)
   23:22:40.456752 <= Recv header, 29 bytes (0x1d)
   0000: 250 CWD command successful.
   23:22:40.456832 => Send header, 6 bytes (0x6)
   0000: EPSV
   23:22:40.456847 == Info: FTP 0xa651a8 (line 1341) state change from CWD to PASV
   23:22:40.456857 == Info: Connect data stream passively
   23:22:40.492914 <= Recv header, 37 bytes (0x25)
   0000: 229 Entering Passive Mode (|||9221|).
   23:22:50.720825 == Info: family0 == v4, family1 == v6
   23:22:50.720892 == Info:   Trying 127.0.0.1:9221...
   23:22:50.721131 == Info: Connecting to 127.0.0.1 (127.0.0.1) port 9221
   23:22:50.721148 == Info: FTP 0xa651a8 (line 2026) state change from PASV to STOP
   23:22:50.721158 == Info: DO phase is complete2
   23:22:50.721167 == Info: STATE: DOING => DOING_MORE handle 0xa659a8; line 2111 (connection #0)
   23:22:50.721260 == Info: Connected to 127.0.0.1 (127.0.0.1) port 2507 (#0)
   23:22:50.721270 == Info: DO-MORE connected phase starts
   23:22:50.721322 => Send header, 8 bytes (0x8)
   0000: TYPE I
   23:22:50.721345 == Info: FTP 0xa651a8 (line 3501) state change from STOP to RETR_TYPE
   23:23:23.980157 <= Recv header, 33 bytes (0x21)
   0000: 200 I modify TYPE as you wanted
   23:23:23.980256 => Send header, 15 bytes (0xf)
   0000: SIZE file1381
   23:23:23.980275 == Info: FTP 0xa651a8 (line 1770) state change from RETR_TYPE to RETR_SIZE
   23:23:23.981756 <= Recv header, 8 bytes (0x8)
   0000: 213 10
   23:23:23.981861 => Send header, 15 bytes (0xf)
   0000: RETR file1381
   23:23:23.981880 == Info: FTP 0xa651a8 (line 2277) state change from RETR_SIZE to RETR
   23:25:24.986017 == Info: server response timeout
   23:25:24.986035 == Info: multi_done
   23:25:24.986168 == Info: The cache now contains 0 members
   23:25:24.986193 == Info: Closing connection 0
  === End of file trace1381

Test 1509

This tests multi http through a proxy tunnel. Seems like a somewhat similar failure to 1381, check-generated has a "DISCONNECT" message but check-expected does not. https://ci.appveyor.com/project/curlorg/curl/builds/38884687/job/16hg93datmmhvd6y

test 1509...[simple multi http:// through proxytunnel with authentication info]
 1509: proxy FAILED:
--- log/check-expected	2021-04-26 23:21:26.192243600 +0000
+++ log/check-generated	2021-04-26 23:21:26.192243600 +0000
@@ -2,3 +2,4 @@
 Host: the.old.moo.1509:1064[CR][LF]
 Proxy-Connection: Keep-Alive[CR][LF]
 [CR][LF]
+[DISCONNECT][LF]
== Contents of files in the log/ dir after test 1509
=== Start of file check-expected
 CONNECT the.old.moo.1509:1064 HTTP/1.1[CR][LF]
 Host: the.old.moo.1509:1064[CR][LF]
 Proxy-Connection: Keep-Alive[CR][LF]
 [CR][LF]
=== End of file check-expected
=== Start of file check-generated
 CONNECT the.old.moo.1509:1064 HTTP/1.1[CR][LF]
 Host: the.old.moo.1509:1064[CR][LF]
 Proxy-Connection: Keep-Alive[CR][LF]
 [CR][LF]
 [DISCONNECT][LF]
=== End of file check-generated
=== Start of file commands.log
 ./libtest/lib1509.exe http://the.old.moo.1509:1064/1509 127.0.0.1:1633 >log/stdout1509 2>log/stderr1509
=== End of file commands.log
=== Start of file ftpserver.cmd
 connection-monitor
 Testnum 1509
=== End of file ftpserver.cmd
=== Start of file http2_server.log
 23:21:21.531000 ====> Client connect
 23:21:21.531000 accept_connection 204 returned 288
 23:21:21.531000 accept_connection 204 returned 0
 23:21:21.531000 Read 101 bytes
 23:21:21.531000 Process 101 bytes request
 23:21:21.531000 Received a CONNECT the.old.moo.1509:1064 HTTP/1.1 request
 23:21:21.531000 Port number: 1064, test case number: -4
 23:21:21.531000 Requested test number 1509 part 0 (from host name)
 23:21:21.531000 enabled connection monitoring
 23:21:21.531000 - request found to be complete (1509)
 23:21:21.531000 enabled connection monitoring
 23:21:21.531000 Wrote request (101 bytes) input to log/proxy.input
 23:21:21.531000 Send response test1509 section <connect>
 23:21:21.531000 Response sent (80 bytes) and written to log/proxy.response
 23:21:22.062000 about to connect to 127.0.0.1:1064
 23:21:22.062000 connected fine to 127.0.0.1:1064, now tunnel
 23:21:22.062000 [CTRL] READ 64 bytes from client
 23:21:22.062000 [CTRL] READ "GET /1509 HTTP/1.1%0d%0aHost: the.old.moo.1509:1064%0d%0aAccept: */*%0d%0a%0d%0a"
 23:21:22.062000 [CTRL] SENT 64 bytes to server
 23:21:22.062000 [CTRL] SENT "GET /1509 HTTP/1.1%0d%0aHost: the.old.moo.1509:1064%0d%0aAccept: */*%0d%0a%0d%0a"
 23:21:22.062000 [CTRL] READ 20 bytes from server
 23:21:22.062000 [CTRL] READ "HTTP/1.1 200 OK swsc"
 23:21:22.062000 [CTRL] READ 145 bytes from server
 23:21:22.062000 [CTRL] READ "lose%0d%0aDate: Tue, 09 Nov 2010 14:49:00 GMT%0d%0aServer: test-server/fake%0d%0aLast-Modified: Tue, 13 Jun 2000 12:10:00 GMT%0d%0aETag: "21025-dc7-39462498"%0d%0a%0d%0a"
 23:21:22.062000 [CTRL] SENT 165 bytes to client
 23:21:22.062000 [CTRL] SENT "HTTP/1.1 200 OK swsclose%0d%0aDate: Tue, 09 Nov 2010 14:49:00 GMT%0d%0aServer: test-server/fake%0d%0aLast-Modified: Tue, 13 Jun 2000 12:10:00 GMT%0d%0aETag: "21025-dc7-39462498"%0d%0a%0d%0a"
 23:21:22.125000 [CTRL] got 0, STOP READING server
 23:21:22.125000 [CTRL] DISABLED WRITING client
 23:21:22.390000 [CTRL] got 0, STOP READING client
 23:21:22.390000 [CTRL] DISABLED WRITING server
 23:21:22.656000 [CTRL] CLOSING client socket
 23:21:22.656000 [CTRL] CLOSING server socket
 23:21:22.656000 [CTRL] ENDING
 23:21:22.656000 ====> Client disconnect 1
 23:21:22.656000 Wrote request (13 bytes) input to log/proxy.input
 23:21:22.656000 Error removing lock file log/serverlogs.lock error: 2 No such file or directory
=== End of file http2_server.log
=== Start of file http_server.log
 23:21:21.062000 ====> Client connect
 23:21:21.062000 accept_connection 196 returned 372
 23:21:21.062000 accept_connection 196 returned 0
 23:21:21.062000 Read 64 bytes
 23:21:21.062000 Process 64 bytes request
 23:21:21.062000 Got request: GET /1509 HTTP/1.1
 23:21:21.062000 Requested test number 1509 part 0
 23:21:21.062000 enabled connection monitoring
 23:21:21.062000 - request found to be complete (1509)
 23:21:21.062000 enabled connection monitoring
 23:21:21.062000 Wrote request (64 bytes) input to log/server.input
 23:21:21.062000 Send response test1509 section <data>
 23:21:21.062000 connection close instruction "swsclose" found in response
 23:21:21.062000 Response sent (165 bytes) and written to log/server.response
 23:21:21.062000 instructed to close connection after server-reply
 23:21:21.062000 ====> Client disconnect 1
 23:21:21.062000 Wrote request (13 bytes) input to log/server.input
=== End of file http_server.log
=== Start of file proxy.input
 CONNECT the.old.moo.1509:1064 HTTP/1.1
 Host: the.old.moo.1509:1064
 Proxy-Connection: Keep-Alive
 [DISCONNECT]
=== End of file proxy.input
=== Start of file proxy.response
 HTTP/1.1 200 Mighty fine indeed
 Server: the beast that eats naughty clients
=== End of file proxy.response
=== Start of file server.input
 GET /1509 HTTP/1.1
 Host: the.old.moo.1509:1064
 Accept: */*
 [DISCONNECT]
=== End of file server.input
=== Start of file server.response
 HTTP/1.1 200 OK swsclose
 Date: Tue, 09 Nov 2010 14:49:00 GMT
 Server: test-server/fake
 Last-Modified: Tue, 13 Jun 2000 12:10:00 GMT
 ETag: "21025-dc7-39462498"
=== End of file server.response
=== Start of file stderr1509
 URL: http://the.old.moo.1509:1064/1509
 * STATE: INIT => CONNECT handle 0x3fa820; line 1753 (connection #-5000)
 * Added connection 0. The cache now contains 1 members
 * family0 == v4, family1 == v6
 *   Trying 127.0.0.1:1633...
 * STATE: CONNECT => CONNECTING handle 0x3fa820; line 1814 (connection #0)
 * Connected to 127.0.0.1 (127.0.0.1) port 1633 (#0)
 * STATE: CONNECTING => TUNNELING handle 0x3fa820; line 1946 (connection #0)
 * allocate connect buffer
 * Establish HTTP proxy tunnel to the.old.moo.1509:1064
 > CONNECT the.old.moo.1509:1064 HTTP/1.1
 Host: the.old.moo.1509:1064
 Proxy-Connection: Keep-Alive
 < HTTP/1.1 200 Mighty fine indeed
 < Server: the beast that eats naughty clients
 < 
 * Proxy replied 200 to CONNECT request
 * CONNECT phase completed
 * STATE: TUNNELING => PROTOCONNECT handle 0x3fa820; line 1918 (connection #0)
 * CONNECT phase completed
 * CONNECT phase completed
 * STATE: PROTOCONNECT => DO handle 0x3fa820; line 1967 (connection #0)
 > GET /1509 HTTP/1.1
 Host: the.old.moo.1509:1064
 Accept: */*
 * STATE: DO => DID handle 0x3fa820; line 2041 (connection #0)
 * STATE: DID => PERFORMING handle 0x3fa820; line 2160 (connection #0)
 * Mark bundle as not supporting multiuse
 * HTTP 1.1 or later with persistent connection
 < HTTP/1.1 200 OK swsclose
 < Date: Tue, 09 Nov 2010 14:49:00 GMT
 < Server: test-server/fake
 < Last-Modified: Tue, 13 Jun 2000 12:10:00 GMT
 < ETag: "21025-dc7-39462498"
 * no chunk, no close, no size. Assume close to signal end
 < 
 * STATE: PERFORMING => DONE handle 0x3fa820; line 2359 (connection #0)
 * multi_done
 * The cache now contains 0 members
 * Closing connection 0
=== End of file stderr1509
=== Start of file stdout1509
 HTTP/1.1 200 Mighty fine indeed
 Server: the beast that eats naughty clients
 HTTP/1.1 200 OK swsclose
 Date: Tue, 09 Nov 2010 14:49:00 GMT
 Server: test-server/fake
 Last-Modified: Tue, 13 Jun 2000 12:10:00 GMT
 ETag: "21025-dc7-39462498"
 header length is ........: 245
 header length should be..: 245
=== End of file stdout1509
=== Start of file test1509.txt
 foo
    bar
 bar
    foo
 moo
=== End of file test1509.txt
@bagder bagder added the CI Continuous Integration label Apr 27, 2021
@bagder
Copy link
Member

bagder commented Apr 27, 2021

Some of the windows builds on Azure also share this flakiness.

@bagder
Copy link
Member

bagder commented Apr 27, 2021

The problem is of course that these are flaky tests. I've not been able to spot the pattern and there seems to be a rather wide variety of tests that can fail - simply disabling them all in these builds have felt a bit too invasive. I don't have any good ideas on how to fix this situation.

@jay jay added the tests label Apr 27, 2021
@bagder bagder closed this as completed in 738fb63 Jul 5, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
CI Continuous Integration tests
Milestone
No milestone
Development

No branches or pull requests
3 participants
@bagder @kevinburke @jay