Various attempts to improve AppVeyor Windows builds #5034

mback2k · 2020-03-03T23:18:19Z

PR just to debug the random issues with the AppVeyor builds. Not intended to be merged (yet).

[skip azp]

mback2k · 2020-03-03T23:51:16Z

First observation: the localhost API ports are really random, ranging from at least 1033 to 50078 as first observed in #5022. Therefore collisions between the localhost API port and test servers ports are a matter of randomness. My plan would be to make runtests.pl detect and avoid the API port.

bagder · 2020-03-04T07:08:45Z

But if it's a port collision, surely the test server in question would then fail to start and we'd notice that somewhat differently than just a test fail?

mback2k · 2020-03-04T07:38:19Z

I am not sure about that. I was seeing the test servers running, but my AppVeyor API requests landed in them before. I am just writing down ideas at the moment and still need to dig deeper.

mback2k · 2020-03-04T08:08:17Z

https://ci.appveyor.com/project/curlorg/curl/builds/31228457/job/udilxdp31s3gpv7d/tests

test 0110...[FTP download resume with set limit]
Warning: server logs lock timeout (2 seconds) expired
 110: protocol FAILED:
--- log/check-expected	2020-03-04 06:48:01.149452500 +0000
+++ log/check-generated	2020-03-04 06:48:01.149452500 +0000
@@ -7,4 +7,3 @@
 SIZE 110[CR][LF]
 REST 20[CR][LF]
 RETR 110[CR][LF]
-QUIT[CR][LF]
== Contents of files in the log/ dir after test 110
=== Start of file check-expected
 USER anonymous[CR][LF]
 PASS ftp@example.com[CR][LF]
 PWD[CR][LF]
 EPSV[CR][LF]
 PASV[CR][LF]
 TYPE I[CR][LF]
 SIZE 110[CR][LF]
 REST 20[CR][LF]
 RETR 110[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]
 EPSV[CR][LF]
 PASV[CR][LF]
 TYPE I[CR][LF]
 SIZE 110[CR][LF]
 REST 20[CR][LF]
 RETR 110[CR][LF]
=== End of file check-generated
=== Start of file commands.log
 ../src/curl.exe --output log/curl110.out  --include --trace-ascii log/trace110 --trace-time ftp://127.0.0.1:8992/110 -C 20 >log/stdout110 2>log/stderr110
=== End of file commands.log
=== Start of file curl110.out
 expected to be a file without the first part
 but we emulate that
=== End of file curl110.out
=== Start of file ftp_server.log
 06:46:58.587545 ====> Client connect
 06:46:58.588043 FTPD: Getting commands from log/ftpserver.cmd
 06:46:58.588258 FTPD: set custom reply for EPSV command
 06:46:58.588423 > "220-        _   _ ____  _     [CR][LF]220-    ___| | | |  _ \| |    [CR][LF]220-   / __| | | | |_) | |    [CR][LF]220-  | (__| |_| |  _ {| |___ [CR][LF]220    \___|\___/|_| \_\_____|[CR][LF]"
 06:46:58.589493 < "USER anonymous"
 06:46:58.589637 > "331 We are happy you popped in![CR][LF]"
 06:46:58.590423 < "PASS ftp@example.com"
 06:46:58.590583 > "230 Welcome you silly person[CR][LF]"
 06:46:58.591233 < "PWD"
 06:46:58.591382 > "257 "/" is current directory[CR][LF]"
 06:46:58.592141 < "EPSV"
 06:46:58.592291 > "500 no such command[CR][LF]"
 06:46:58.592946 < "PASV"
 06:46:58.593067 ====> Passive DATA channel requested by client
 06:46:58.593159 DATA sockfilt for passive data channel starting...
 06:46:58.623944 DATA sockfilt for passive data channel started (pid 1367)
 06:46:58.624508 DATA sockfilt for passive data channel listens on port 1634
 06:46:58.624648 > "227 Entering Passive Mode (127,0,0,1,6,98)[LF]"
 06:46:58.624795 Client has been notified that DATA conn will be accepted on port 1634
 06:46:58.625593 Client connects to port 1634
 06:46:58.625713 ====> Client established passive DATA connection on port 1634
 06:46:58.630289 < "TYPE I"
 06:46:58.630443 > "200 I modify TYPE as you wanted[CR][LF]"
 06:46:58.631293 < "SIZE 110"
 06:46:58.631667 > "213 85[LF][CR][LF]"
 06:46:58.632537 < "REST 20"
 06:46:58.632676 > "350 Yeah yeah we set it there for you[CR][LF]"
 06:46:58.632776 Set REST position to 20
 06:46:58.633646 < "RETR 110"
 06:46:58.633985 REST 20 was removed from size, makes 45 left
 06:46:58.634107 > "150 Binary data connection for 110 () (45 bytes).[CR][LF]"
 06:46:58.634392 =====> Closing passive DATA connection...
 06:46:58.634643 Server disconnects passive DATA connection
=== End of file ftp_server.log
=== Start of file ftp_sockctrl.log
 06:46:58.656000 select_ws: 160 is readable
 06:46:58.656000 ====> Client connect
 06:46:58.656000 select_ws: 0 is readable
 06:46:58.656000 Received DATA (on stdin)
 06:46:58.656000 > 160 bytes data, server => client
 06:46:58.656000 '220-        _   _ ____  _     \r\n220-    ___| | | |  _ \| | '
 06:46:58.656000 '   \r\n220-   / __| | | | |_) | |    \r\n220-  | (__| |_| |  '
 06:46:58.656000 '_ {| |___ \r\n220    \___|\___/|_| \_\_____|\r\n'
 06:46:58.656000 select_ws: 168 is readable
 06:46:58.656000 < 16 bytes data, client => server
 06:46:58.656000 'USER anonymous\r\n'
 06:46:58.656000 select_ws: 0 is readable
 06:46:58.656000 Received DATA (on stdin)
 06:46:58.656000 > 33 bytes data, server => client
 06:46:58.656000 '331 We are happy you popped in!\r\n'
 06:46:58.656000 select_ws: 168 is readable
 06:46:58.656000 < 22 bytes data, client => server
 06:46:58.656000 'PASS ftp@example.com\r\n'
 06:46:58.656000 select_ws: 0 is readable
 06:46:58.656000 Received DATA (on stdin)
 06:46:58.656000 > 30 bytes data, server => client
 06:46:58.656000 '230 Welcome you silly person\r\n'
 06:46:58.656000 select_ws: 168 is readable
 06:46:58.656000 < 5 bytes data, client => server
 06:46:58.656000 'PWD\r\n'
 06:46:58.656000 select_ws: 0 is readable
 06:46:58.656000 Received DATA (on stdin)
 06:46:58.656000 > 30 bytes data, server => client
 06:46:58.656000 '257 "/" is current directory\r\n'
 06:46:58.656000 select_ws: 168 is readable
 06:46:58.656000 < 6 bytes data, client => server
 06:46:58.656000 'EPSV\r\n'
 06:46:58.656000 select_ws: 0 is readable
 06:46:58.656000 Received DATA (on stdin)
 06:46:58.656000 > 21 bytes data, server => client
 06:46:58.656000 '500 no such command\r\n'
 06:46:58.656000 select_ws: 168 is readable
 06:46:58.656000 < 6 bytes data, client => server
 06:46:58.656000 'PASV\r\n'
 06:46:58.687000 select_ws: 0 is readable
 06:46:58.687000 Received DATA (on stdin)
 06:46:58.687000 > 43 bytes data, server => client
 06:46:58.687000 '227 Entering Passive Mode (127,0,0,1,6,98)\n'
 06:46:58.703000 select_ws: 168 is readable
 06:46:58.703000 < 8 bytes data, client => server
 06:46:58.703000 'TYPE I\r\n'
 06:46:58.703000 select_ws: 0 is readable
 06:46:58.703000 Received DATA (on stdin)
 06:46:58.703000 > 33 bytes data, server => client
 06:46:58.703000 '200 I modify TYPE as you wanted\r\n'
 06:46:58.703000 select_ws: 168 is readable
 06:46:58.703000 < 10 bytes data, client => server
 06:46:58.703000 'SIZE 110\r\n'
 06:46:58.703000 select_ws: 0 is readable
 06:46:58.703000 Received DATA (on stdin)
 06:46:58.703000 > 9 bytes data, server => client
 06:46:58.703000 '213 85\n\r\n'
 06:46:58.703000 select_ws: 168 is readable
 06:46:58.703000 < 9 bytes data, client => server
 06:46:58.703000 'REST 20\r\n'
 06:46:58.703000 select_ws: 0 is readable
 06:46:58.703000 Received DATA (on stdin)
 06:46:58.703000 > 39 bytes data, server => client
 06:46:58.703000 '350 Yeah yeah we set it there for you\r\n'
 06:46:58.703000 select_ws: 168 is readable
 06:46:58.703000 < 10 bytes data, client => server
 06:46:58.703000 'RETR 110\r\n'
 06:46:58.703000 select_ws: 0 is readable
 06:46:58.703000 Received DATA (on stdin)
 06:46:58.703000 > 51 bytes data, server => client
 06:46:58.703000 '150 Binary data connection for 110 () (45 bytes).\r\n'
 06:47:58.718000 select_ws: 168 is readable
 06:47:58.718000 select_ws: 168 is excepted
 06:47:58.718000 ====> Client disconnect
=== End of file ftp_sockctrl.log
=== Start of file ftp_sockdata.log
 06:46:58.687000 Running IPv4 version
 06:46:58.687000 Listening on port 1634
 06:46:58.687000 Wrote pid 1292 to ./.ftp_sockdata.pid
 06:46:58.687000 select_ws: 0 is readable
 06:46:58.687000 Received PING (on stdin)
 06:46:58.687000 select_ws: 0 is readable
 06:46:58.687000 Received PORT (on stdin)
 06:46:58.687000 select_ws: 160 is readable
 06:46:58.687000 ====> Client connect
 06:46:58.703000 select_ws: 0 is readable
 06:46:58.703000 Received DATA (on stdin)
 06:46:58.703000 > 45 bytes data, server => client
 06:46:58.703000 'expected to be a file without the first part\n'
 06:46:58.703000 select_ws: 0 is readable
 06:46:58.703000 Received DATA (on stdin)
 06:46:58.703000 > 20 bytes data, server => client
 06:46:58.703000 'but we emulate that\n'
 06:46:58.703000 select_ws: 0 is readable
 06:46:58.703000 Received DISC (on stdin)
 06:46:58.703000 ====> Client forcibly disconnected
 06:46:58.703000 select_ws: 0 is readable
 06:46:58.703000 Received QUIT (on stdin)
 06:46:58.703000 quits
 06:46:58.703000 ============> sockfilt quits
=== End of file ftp_sockdata.log
=== Start of file server.input
 USER anonymous
 PASS ftp@example.com
 PWD
 EPSV
 PASV
 TYPE I
 SIZE 110
 REST 20
 RETR 110
=== End of file server.input
=== Start of file stderr110
 ** Resuming transfer from byte position 20
   % 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    65  100    65    0     0     62      0  0:00:01  0:00:01 --:--:--    62
 100    65  100    65    0     0     31      0  0:00:02  0:00:02 --:--:--    31
 100    65  100    65    0     0     21      0  0:00:03  0:00:03 --:--:--    21
 100    65  100    65    0     0     15      0  0:00:04  0:00:04 --:--:--    15
 100    65  100    65    0     0     12      0  0:00:05  0:00:05 --:--:--    12
 100    65  100    65    0     0     10      0  0:00:06  0:00:06 --:--:--     0
 100    65  100    65    0     0      9      0  0:00:07  0:00:07 --:--:--     0
 100    65  100    65    0     0      8      0  0:00:08  0:00:08 --:--:--     0
 100    65  100    65    0     0      7      0  0:00:09  0:00:09 --:--:--     0
 100    65  100    65    0     0      6      0  0:00:10  0:00:10 --:--:--     0
 100    65  100    65    0     0      5      0  0:00:13  0:00:11  0:00:02     0
 100    65  100    65    0     0      5      0  0:00:13  0:00:12  0:00:01     0
 100    65  100    65    0     0      4      0  0:00:16  0:00:13  0:00:03     0
 100    65  100    65    0     0      4      0  0:00:16  0:00:14  0:00:02     0
 100    65  100    65    0     0      4      0  0:00:16  0:00:15  0:00:01     0
 100    65  100    65    0     0      4      0  0:00:16  0:00:16 --:--:--     0
 100    65  100    65    0     0      3      0  0:00:21  0:00:17  0:00:04     0
 100    65  100    65    0     0      3      0  0:00:21  0:00:18  0:00:03     0
 100    65  100    65    0     0      3      0  0:00:21  0:00:19  0:00:02     0
 100    65  100    65    0     0      3      0  0:00:21  0:00:20  0:00:01     0
 100    65  100    65    0     0      3      0  0:00:21  0:00:21 --:--:--     0
 100    65  100    65    0     0      2      0  0:00:32  0:00:22  0:00:10     0
 100    65  100    65    0     0      2      0  0:00:32  0:00:23  0:00:09     0
 100    65  100    65    0     0      2      0  0:00:32  0:00:24  0:00:08     0
 100    65  100    65    0     0      2      0  0:00:32  0:00:25  0:00:07     0
 100    65  100    65    0     0      2      0  0:00:32  0:00:26  0:00:06     0
 100    65  100    65    0     0      2      0  0:00:32  0:00:27  0:00:05     0
 100    65  100    65    0     0      2      0  0:00:32  0:00:28  0:00:04     0
 100    65  100    65    0     0      2      0  0:00:32  0:00:29  0:00:03     0
 100    65  100    65    0     0      2      0  0:00:32  0:00:30  0:00:02     0
 100    65  100    65    0     0      2      0  0:00:32  0:00:31  0:00:01     0
 100    65  100    65    0     0      2      0  0:00:32  0:00:32 --:--:--     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:33  0:00:32     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:34  0:00:31     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:35  0:00:30     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:36  0:00:29     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:37  0:00:28     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:38  0:00:27     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:39  0:00:26     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:40  0:00:25     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:41  0:00:24     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:42  0:00:23     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:43  0:00:22     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:44  0:00:21     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:45  0:00:20     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:46  0:00:19     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:47  0:00:18     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:48  0:00:17     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:49  0:00:16     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:50  0:00:15     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:51  0:00:14     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:52  0:00:13     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:53  0:00:12     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:54  0:00:11     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:55  0:00:10     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:56  0:00:09     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:57  0:00:08     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:58  0:00:07     0
 100    65  100    65    0     0      1      0  0:01:05  0:00:59  0:00:06     0
 100    65  100    65    0     0      1      0  0:01:05  0:01:00  0:00:05     0
 curl: (28) FTP response timeout
=== End of file stderr110
=== Start of file trace110
 06:46:58.681641 == Info: STATE: INIT => CONNECT handle 0x86ba70; line 1617 (connection #-5000)
 06:46:58.682501 == Info: Added connection 0. The cache now contains 1 members
 06:46:58.682585 == Info:   Trying 127.0.0.1:8992...
 06:46:58.682714 == Info: STATE: CONNECT => WAITCONNECT handle 0x86ba70; line 1673 (connection #0)
 06:46:58.682874 == Info: Connected to 127.0.0.1 (127.0.0.1) port 8992 (#0)
 06:46:58.682884 == Info: STATE: WAITCONNECT => SENDPROTOCONNECT handle 0x86ba70; line 1793 (connection #0)
 06:46:58.682895 == Info: Marked for [keep alive]: FTP default
 06:46:58.682904 == Info: FTP 0xa3a4a0 (line 3102) state change from STOP to WAIT220
 06:46:58.682916 == Info: STATE: SENDPROTOCONNECT => PROTOCONNECT handle 0x86ba70; line 1808 (connection #0)
 06:46:58.684471 <= Recv header, 32 bytes (0x20)
 0000: 220-        _   _ ____  _     
 06:46:58.684552 <= Recv header, 32 bytes (0x20)
 0000: 220-    ___| | | |  _ \| |    
 06:46:58.684567 <= Recv header, 32 bytes (0x20)
 0000: 220-   / __| | | | |_) | |    
 06:46:58.684577 <= Recv header, 32 bytes (0x20)
 0000: 220-  | (__| |_| |  _ {| |___ 
 06:46:58.684586 <= Recv header, 32 bytes (0x20)
 0000: 220    \___|\___/|_| \_\_____|
 06:46:58.684629 => Send header, 16 bytes (0x10)
 0000: USER anonymous
 06:46:58.684642 == Info: FTP 0xa3a4a0 (line 779) state change from WAIT220 to USER
 06:46:58.685577 <= Recv header, 33 bytes (0x21)
 0000: 331 We are happy you popped in
 06:46:58.685623 => Send header, 22 bytes (0x16)
 0000: PASS ftp@example.com
 06:46:58.685637 == Info: FTP 0xa3a4a0 (line 2530) state change from USER to PASS
 06:46:58.686430 <= Recv header, 30 bytes (0x1e)
 0000: 230 Welcome you silly person
 06:46:58.686468 => Send header, 5 bytes (0x5)
 0000: PWD
 06:46:58.686479 == Info: FTP 0xa3a4a0 (line 791) state change from PASS to PWD
 06:46:58.687232 <= Recv header, 30 bytes (0x1e)
 0000: 257 "/" is current directory
 06:46:58.687252 == Info: Entry path is '/'
 06:46:58.687257 == Info: FTP 0xa3a4a0 (line 2854) state change from PWD to STOP
 06:46:58.687263 == Info: protocol connect phase DONE
 06:46:58.687268 == Info: STATE: PROTOCONNECT => DO handle 0x86ba70; line 1827 (connection #0)
 06:46:58.687321 == Info: Request has same path as previous transfer
 06:46:58.687328 == Info: DO phase starts
 06:46:58.687357 => Send header, 6 bytes (0x6)
 0000: EPSV
 06:46:58.687370 == Info: FTP 0xa3a4a0 (line 1324) state change from STOP to PASV
 06:46:58.687376 == Info: Connect data stream passively
 06:46:58.687385 == Info: ftp_perform ends with SECONDARY: 0
 06:46:58.687391 == Info: STATE: DO => DOING handle 0x86ba70; line 1869 (connection #0)
 06:46:58.688146 <= Recv header, 21 bytes (0x15)
 0000: 500 no such command
 06:46:58.688162 == Info: Failed EPSV attempt. Disabling EPSV
 06:46:58.688188 => Send header, 6 bytes (0x6)
 0000: PASV
 06:46:58.720631 <= Recv header, 43 bytes (0x2b)
 0000: 227 Entering Passive Mode (127,0,0,1,6,98).
 06:46:58.720722 == Info:   Trying 127.0.0.1:1634...
 06:46:58.720827 == Info: Connecting to 127.0.0.1 (127.0.0.1) port 1634
 06:46:58.720839 == Info: FTP 0xa3a4a0 (line 1974) state change from PASV to STOP
 06:46:58.720845 == Info: DO phase is complete2
 06:46:58.720851 == Info: STATE: DOING => DO_MORE handle 0x86ba70; line 1953 (connection #0)
 06:46:58.725407 == Info: Connected to 127.0.0.1 (127.0.0.1) port 8992 (#0)
 06:46:58.725414 == Info: DO-MORE connected phase starts
 06:46:58.725425 == Info: RANGE 20 to end of file
 06:46:58.725430 == Info: range-download from 20 to 0, totally -1 bytes
 06:46:58.725556 => Send header, 8 bytes (0x8)
 0000: TYPE I
 06:46:58.725573 == Info: FTP 0xa3a4a0 (line 3426) state change from STOP to RETR_TYPE
 06:46:58.726488 <= Recv header, 33 bytes (0x21)
 0000: 200 I modify TYPE as you wanted
 06:46:58.726525 => Send header, 10 bytes (0xa)
 0000: SIZE 110
 06:46:58.726537 == Info: FTP 0xa3a4a0 (line 1740) state change from RETR_TYPE to RETR_SIZE
 06:46:58.727711 <= Recv header, 7 bytes (0x7)
 0000: 213 85.
 06:46:58.727722 == Info: Curl_pp_readresp_ 2 bytes of trailing server response left
 06:46:58.727733 == Info: Instructs server to resume from offset 20
 06:46:58.727757 => Send header, 9 bytes (0x9)
 0000: REST 20
 06:46:58.727798 == Info: FTP 0xa3a4a0 (line 2219) state change from RETR_SIZE to RETR_REST
 06:46:58.728840 <= Recv header, 2 bytes (0x2)
 0000: 
 06:46:58.728859 <= Recv header, 39 bytes (0x27)
 0000: 350 Yeah yeah we set it there for you
 06:46:58.728889 => Send header, 10 bytes (0xa)
 0000: RETR 110
 06:46:58.728901 == Info: FTP 0xa3a4a0 (line 2314) state change from RETR_REST to RETR
 06:46:58.730426 <= Recv header, 51 bytes (0x33)
 0000: 150 Binary data connection for 110 () (45 bytes).
 06:46:58.730444 == Info: Maxdownload = -1
 06:46:58.730448 == Info: Getting file with size: 65
 06:46:58.730454 == Info: FTP 0xa3a4a0 (line 465) state change from RETR to STOP
 06:46:58.730462 == Info: STATE: DO_MORE => DO_DONE handle 0x86ba70; line 1978 (connection #0)
 06:46:58.730469 == Info: STATE: DO_DONE => PERFORM handle 0x86ba70; line 2003 (connection #0)
 06:46:58.730488 <= Recv data, 45 bytes (0x2d)
 0000: expected to be a file without the first part.
 06:46:58.730754 <= Recv data, 20 bytes (0x14)
 0000: but we emulate that.
 06:46:58.731070 == Info: readwrite_data: we're done
 06:46:58.731076 == Info: nread <= 0, server closed connection, bailing
 06:46:58.731083 == Info: STATE: PERFORM => DONE handle 0x86ba70; line 2193 (connection #0)
 06:46:58.731089 == Info: multi_done
 06:46:58.731101 == Info: Remembering we are in dir ""
 06:47:58.741133 == Info: FTP response timeout
 06:47:58.741144 == Info: control connection looks dead
 06:47:58.741150 == Info: Marked for [closure]: Timeout or similar in FTP DONE operation
 06:47:58.741230 == Info: Closing connection 0
 06:47:58.741279 == Info: The cache now contains 0 members
 06:47:58.741363 == Info: Expire cleared (transfer 0x86ba70)
=== End of file trace110

Interesting part: Warning: server logs lock timeout (2 seconds) expired and the QUIT is missing.

jay · 2020-03-04T08:10:50Z

Interesting part: Warning: server logs lock timeout (2 seconds) expired

I see that as well, I asked about it on the list.

mback2k · 2020-03-04T08:13:36Z

Maybe sockfilt is not flushing and closing logs correctly?

jay · 2020-03-04T08:27:10Z

I don't know, I can't reproduce it. I figured maybe ASAN was slowing things down.

curl/tests/runtests.pl

Lines 3817 to 3833 in b8d1366

    
           # If a server logs advisor read lock file exists, it is an indication 
        
           # that the server has not yet finished writing out all its log files, 
        
           # including server request log files used for protocol verification. 
        
           # So, if the lock file exists the script waits here a certain amount 
        
           # of time until the server removes it, or the given time expires. 
        
           if($serverlogslocktimeout) { 
        
               my $lockretry = $serverlogslocktimeout * 20; 
        
               while((-f $SERVERLOGS_LOCK) && $lockretry--) { 
        
                   select(undef, undef, undef, 0.05); 
        
               } 
        
               if(($lockretry < 0) && 
        
                  ($serverlogslocktimeout >= $defserverlogslocktimeout)) { 
        
                   logmsg "Warning: server logs lock timeout ", 
        
                          "($serverlogslocktimeout seconds) expired\n"; 
        
               } 
        
           }

mback2k · 2020-03-04T08:39:46Z

At least on Windows select(undef, undef, undef, is rather suspicious:
https://perldoc.perl.org/perlport.html#select

mback2k · 2020-03-13T20:15:01Z

This PR is waiting on the results of #5086 to have more stable test results first.

Related to #5034 and #5063

mback2k · 2020-04-05T15:46:13Z

I have now squashed the commits of this PR into logical chunks and merged them, because the changes make sense regardless of the pending issue described in #5086, #5156 and #5178.

mback2k self-assigned this Mar 3, 2020

mback2k added FTP tests Windows Windows-specific connecting & proxies labels Mar 3, 2020

mback2k mentioned this pull request Mar 4, 2020

tests: try to make sleeping portable by avoiding select #5035

Closed

mback2k force-pushed the debug-appveyor-builds branch 2 times, most recently from 4f34d2b to b6be7be Compare March 5, 2020 17:58

mback2k changed the title ~~appveyor: echo API URL to check if it conflicts with test server ports~~ appveyor: various attempts to improve Windows builds Mar 5, 2020

mback2k changed the title ~~appveyor: various attempts to improve Windows builds~~ [WIP] Various attempts to improve Windows builds Mar 6, 2020

This was referenced Mar 6, 2020

Improvements for the Perl-based testsuite running on Windows #5054

Closed

Fix test 198 failing due to missing ftruncate on Windows #5055

Closed

mback2k force-pushed the debug-appveyor-builds branch 4 times, most recently from afddbe0 to cc7c836 Compare March 9, 2020 12:36

mback2k changed the title ~~[WIP] Various attempts to improve Windows builds~~ [WIP] Various attempts to improve AppVeyor Windows builds Mar 9, 2020

mback2k force-pushed the debug-appveyor-builds branch from cc7c836 to be1219e Compare March 9, 2020 12:51

This was referenced Mar 9, 2020

appveyor: add Unicode winbuild jobs #5063

Closed

Fix additional test servers on Windows and log used port range #5064

Closed

tests/data: fix static ip:port instead of dynamic values being used #5065

Closed

mback2k force-pushed the debug-appveyor-builds branch from be1219e to da464ed Compare March 10, 2020 02:58

mback2k force-pushed the debug-appveyor-builds branch 2 times, most recently from 2f9dc2d to 5647b1a Compare March 11, 2020 13:18

mback2k mentioned this pull request Mar 12, 2020

[WIP] Debug sockfilt on Windows regarding waiting on stdin readability #5086

Closed

mback2k force-pushed the debug-appveyor-builds branch 3 times, most recently from 22bec78 to c0268e8 Compare March 20, 2020 20:06

mback2k mentioned this pull request Mar 24, 2020

[WIP] First steps to rebalance CI jobs with focus on macOS - squash me! #5124

Closed

mback2k force-pushed the debug-appveyor-builds branch 2 times, most recently from e9fb273 to d3e00ad Compare March 26, 2020 15:29

mback2k added 5 commits April 3, 2020 12:42

appveyor: turn disabled tests into ignored result tests

60969db

appveyor: show failed tests in message log even if test is ignored

5964a9e

appveyor: print API response with newline if there is one

2d4f1a1

appveyor: order builds more logically and add two new variants

a3cf271

appveyor: avoid conflicts of test server ports with APPVEYOR_API_URL

b1bdffc

mback2k force-pushed the debug-appveyor-builds branch from d3e00ad to b1bdffc Compare April 3, 2020 10:42

mback2k added a commit that referenced this pull request Apr 5, 2020

appveyor: sort builds by type and add two new variants

b667bbe

Related to #5034 and #5063

mback2k changed the title ~~[WIP] Various attempts to improve AppVeyor Windows builds~~ Various attempts to improve AppVeyor Windows builds Apr 5, 2020

mback2k marked this pull request as ready for review April 5, 2020 15:40

mback2k closed this in 45b843c Apr 5, 2020

mback2k mentioned this pull request Apr 5, 2020

tests: fix conflict between Cygwin/msys and Windows PIDs #5188

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Various attempts to improve AppVeyor Windows builds #5034

Various attempts to improve AppVeyor Windows builds #5034

mback2k commented Mar 3, 2020 •

edited

mback2k commented Mar 3, 2020 •

edited

bagder commented Mar 4, 2020

mback2k commented Mar 4, 2020 •

edited

mback2k commented Mar 4, 2020

jay commented Mar 4, 2020

mback2k commented Mar 4, 2020

jay commented Mar 4, 2020

mback2k commented Mar 4, 2020 •

edited

mback2k commented Mar 13, 2020

mback2k commented Apr 5, 2020

Various attempts to improve AppVeyor Windows builds #5034

Various attempts to improve AppVeyor Windows builds #5034

Conversation

mback2k commented Mar 3, 2020 • edited

mback2k commented Mar 3, 2020 • edited

bagder commented Mar 4, 2020

mback2k commented Mar 4, 2020 • edited

mback2k commented Mar 4, 2020

jay commented Mar 4, 2020

mback2k commented Mar 4, 2020

jay commented Mar 4, 2020

mback2k commented Mar 4, 2020 • edited

mback2k commented Mar 13, 2020

mback2k commented Apr 5, 2020

mback2k commented Mar 3, 2020 •

edited

mback2k commented Mar 3, 2020 •

edited

mback2k commented Mar 4, 2020 •

edited

mback2k commented Mar 4, 2020 •

edited