sockfilt: fix race-condition between threads and event-processing

[mback2k]

Fix race-condition of waiting threads finishing while events are
already being processed which lead to invalid or skipped events.

[mback2k]

Once ready, I will squash the commits into logical chunks for rebase and merge.

[mback2k]

@bagder I am seeing a random issue with test 715, but I do not think that sockfilt is causing the error here. Would you mind taking a look and giving me your insights about this proxy related test?
https://ci.appveyor.com/project/curlorg/curl/builds/31826331/job/ffwe3km7j2h8wj3s?fullLog=true#L2527

[mback2k]

I have been running test 715 in an endless loop for nearly 1 hour now and cannot reproduce the failure:
while ./runtests.pl -d -k 715; do :; done

Maybe the failure happens only on a slow CI machine? I will have to figure out how to make my machine "slower"...

[bagder]

It seems to be a problem in sws when it runs as a CONNECT proxy. See the http2_server.log after the failure:

 16:41:38.046000 [CTRL] SENT "150 Binary data connection for 715 () (14 bytes).%0d%0a"
 16:41:38.046000 [DATA] READ 14 bytes from server
 16:41:38.046000 [DATA] READ "silly content%0a"
 16:41:38.046000 [DATA] SENT 14 bytes to client
 16:41:38.046000 [DATA] SENT "silly content%0a"
 16:41:44.093000 CONNECT proxy timeout after 6 idle seconds
 16:41:44.093000 [DATA] CLOSING server socket (cleanup)
 16:41:44.093000 [DATA] CLOSING client socket (cleanup)

It gets the "silly content" and passes that on and then it does nothing more until it times out. It doesn't seem to detect the end if that transfer.

Compare that to a functioning test case (on my Linux host):

20:00:37.187877 [CTRL] SENT "150 Binary data connection for 715 () (14 bytes).%0d%0a"
20:00:37.187907 [DATA] READ 14 bytes from server
20:00:37.187931 [DATA] READ "silly content%0a"
20:00:37.187958 [DATA] got 0, STOP READING server
20:00:37.188028 [DATA] SENT 14 bytes to client
20:00:37.188055 [DATA] SENT "silly content%0a"
20:00:37.188078 [DATA] DISABLED WRITING client
20:00:37.438417 [CTRL] READ 28 bytes from server
20:00:37.438495 [CTRL] READ "226 File transfer complete%0d%0a"
20:00:37.438524 [DATA] got 0, STOP READING client
20:00:37.438548 [DATA] DISABLED WRITING server
20:00:37.688894 [DATA] CLOSING client socket
20:00:37.688991 [DATA] CLOSING server socket
20:00:37.689020 [DATA] ENDING

[mback2k]

It doesn't seem to detect the end if that transfer.

Thanks, can you tell me how that end of transfer should normally be signaled?

Edit: I can see that it is checking for sread returning <= 0, so I guess the socket should be closed. But by whom? Is it a socket managed by sockfilt on the other end in this case? Is there some difference in the logs regarding that?

[bagder]

This:

20:00:37.187958 [DATA] got 0, STOP READING server

Ie it should get signaled to read and then read zero bytes.

[mback2k]

I mean on the other side of the connection. What is on the other side? sockfilt? And if yes, what makes sockfilt close the connection?

[mback2k]

I will create another PR to handle the remaining issues regarding waitpid on Windows.

For now my focus is to get this PR ready for merge to avoid the race-condition in sockfilt.

[MarcelRaad]

👍

[bagder]

Maybe remove [WIP] from the title to better signal this is ready?

[bagder]

This is all Windows code. I'm not qualified to review it...

[mback2k]

Maybe remove [WIP] from the title to better signal this is ready?

Good idea. Forgot that after pressing the "Ready for review" button.

This is all Windows code. I'm not qualified to review it...

Maybe, but I still think you are the right person to review code style and C code in general. 😄