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.

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

Various attempts to improve AppVeyor Windows builds #5034

Closed
wants to merge 5 commits into from

Conversation

@mback2k
Copy link
Member

mback2k commented Mar 3, 2020

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

[skip azp]

@mback2k
Copy link
Member Author

mback2k commented Mar 3, 2020

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
Copy link
Member

bagder commented Mar 4, 2020

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
Copy link
Member Author

mback2k commented Mar 4, 2020

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
Copy link
Member Author

mback2k commented Mar 4, 2020

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
Copy link
Member

jay commented Mar 4, 2020

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

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

@mback2k
Copy link
Member Author

mback2k commented Mar 4, 2020

Maybe sockfilt is not flushing and closing logs correctly?

@jay
Copy link
Member

jay commented Mar 4, 2020

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
Copy link
Member Author

mback2k commented Mar 4, 2020

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

@mback2k mback2k force-pushed the mback2k:debug-appveyor-builds branch 2 times, most recently from 4f34d2b to b6be7be Mar 5, 2020
@mback2k 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 mback2k changed the title appveyor: various attempts to improve Windows builds [WIP] Various attempts to improve Windows builds Mar 6, 2020
@mback2k mback2k force-pushed the mback2k:debug-appveyor-builds branch 4 times, most recently from afddbe0 to cc7c836 Mar 6, 2020
@mback2k mback2k changed the title [WIP] Various attempts to improve Windows builds [WIP] Various attempts to improve AppVeyor Windows builds Mar 9, 2020
@mback2k mback2k force-pushed the mback2k:debug-appveyor-builds branch from cc7c836 to be1219e Mar 9, 2020
@mback2k mback2k force-pushed the mback2k:debug-appveyor-builds branch from be1219e to da464ed Mar 10, 2020
@mback2k mback2k force-pushed the mback2k:debug-appveyor-builds branch 2 times, most recently from 2f9dc2d to 5647b1a Mar 10, 2020
@mback2k
Copy link
Member Author

mback2k commented Mar 13, 2020

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

@mback2k mback2k force-pushed the mback2k:debug-appveyor-builds branch 3 times, most recently from 22bec78 to c0268e8 Mar 19, 2020
@mback2k mback2k force-pushed the mback2k:debug-appveyor-builds branch 2 times, most recently from e9fb273 to d3e00ad Mar 24, 2020
mback2k added 5 commits Mar 5, 2020
@mback2k mback2k force-pushed the mback2k:debug-appveyor-builds branch from d3e00ad to b1bdffc Apr 3, 2020
mback2k added a commit that referenced this pull request Apr 5, 2020
Related to #5034 and #5063
@mback2k mback2k changed the title [WIP] Various attempts to improve AppVeyor Windows builds Various attempts to improve AppVeyor Windows builds Apr 5, 2020
@mback2k mback2k marked this pull request as ready for review Apr 5, 2020
@mback2k mback2k closed this in 45b843c Apr 5, 2020
@mback2k
Copy link
Member Author

mback2k commented Apr 5, 2020

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked issues

Successfully merging this pull request may close these issues.

None yet

3 participants
You can’t perform that action at this time.