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

[core,gateway] use TcpConnectTimeout for read as well #10288

Merged
merged 3 commits into from
Jun 25, 2024

Conversation

akallabeth
Copy link
Member

@akallabeth akallabeth commented Jun 19, 2024

http_response_recv might never receive an answer, so do wait for input and fail if the timeout is exceeded.

@progxaker you might test this branch and it should now at least fail with a timeout instead of idling forever

@akallabeth akallabeth added this to the 3.6.0 milestone Jun 19, 2024
@akallabeth akallabeth linked an issue Jun 19, 2024 that may be closed by this pull request
Copy link

@github-actions github-actions bot left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

clang-tidy made some suggestions

libfreerdp/core/gateway/http.c Outdated Show resolved Hide resolved
libfreerdp/core/gateway/http.c Show resolved Hide resolved
@freerdp-bot
Copy link

Refer to this link for build results (access rights to CI server needed):
https://ci.freerdp.com//job/PullRequestTester/12188/

Copy link

clang-tidy review says "All clean, LGTM! 👍"

@freerdp-bot
Copy link

Refer to this link for build results (access rights to CI server needed):
https://ci.freerdp.com//job/PullRequestTester/12189/

Copy link

clang-tidy review says "All clean, LGTM! 👍"

@freerdp-bot
Copy link

Refer to this link for build results (access rights to CI server needed):
https://ci.freerdp.com//job/PullRequestTester/12190/

@akallabeth
Copy link
Member Author

@freerdp-bot test please

@freerdp-bot
Copy link

Refer to this link for build results (access rights to CI server needed):
https://ci.freerdp.com//job/PullRequestTester/12191/

@akallabeth
Copy link
Member Author

@freerdp-bot test please

@freerdp-bot
Copy link

Refer to this link for build results (access rights to CI server needed):
https://ci.freerdp.com//job/PullRequestTester/12194/

Copy link

clang-tidy review says "All clean, LGTM! 👍"

@akallabeth akallabeth marked this pull request as ready for review June 19, 2024 13:16
@freerdp-bot
Copy link

Refer to this link for build results (access rights to CI server needed):
https://ci.freerdp.com//job/PullRequestTester/12196/

@akallabeth
Copy link
Member Author

@freerdp-bot test please

@freerdp-bot
Copy link

Refer to this link for build results (access rights to CI server needed):
https://ci.freerdp.com//job/PullRequestTester/12197/

@akallabeth
Copy link
Member Author

@freerdp-bot test please

@freerdp-bot
Copy link

Refer to this link for build results (access rights to CI server needed):
https://ci.freerdp.com//job/PullRequestTester/12198/

@progxaker
Copy link
Contributor

progxaker commented Jun 20, 2024

Hello @akallabeth. Thank you for the pull request.

Unfortunately, the changes refuse to let me connect. FreeRDP asks for a redirect URL, and after I pass it on, I get
[10:05:39:277] [170306:00029949] [ERROR][com.freerdp.core.gateway.http] - [http_response_recv]: [BIO_wait] timeout exceeded.

Details
10:05:14:310] [170306:00029949] [DEBUG][com.freerdp.core] - [freerdp_connect_begin]: resetting error state
[10:05:14:310] [170306:00029949] [TRACE][com.freerdp.api] - [freerdp_channels_process_message]: IFCALL(message->Free) == NULL
[10:05:14:310] [170306:00029949] [DEBUG][com.freerdp.client.common.cmdline] - [freerdp_client_load_static_channel_addin]: loading channelEx rdpdr
[10:05:14:310] [170306:00029949] [DEBUG][com.freerdp.client.common.cmdline] - [freerdp_client_load_static_channel_addin]: loading channelEx rdpsnd
[10:05:14:310] [170306:00029949] [DEBUG][com.freerdp.channels.drdynvc.client] - [drdynvc_VirtualChannelEntryEx]: VirtualChannelEntryEx
[10:05:14:310] [170306:00029949] [DEBUG][com.freerdp.client.common.cmdline] - [freerdp_client_load_static_channel_addin]: loading channelEx drdynvc
[10:05:14:310] [170306:00029949] [DEBUG][com.freerdp.primitives] - [primitives_autodetect_best]: primitives benchmark: only one backend, skipping...
[10:05:14:311] [170306:00029949] [DEBUG][com.freerdp.primitives] - [primitives_autodetect_best]: primitives autodetect, using generic
[10:05:14:441] [170306:00029949] [DEBUG][com.freerdp.core] - [freerdp_tcp_default_connect]: resetting error state
[10:05:14:441] [170306:00029949] [DEBUG][com.freerdp.core] - [freerdp_tcp_default_connect]: connecting to peer [REDACTED]
[10:05:14:474] [170306:00029949] [DEBUG][com.freerdp.core.gateway.arm] - [arm_tls_connect]: connecting to [REDACTED] 443
Browse to: https://login.microsoftonline.com/common/oauth2/v2.0/authorize?client_id=a85cf173-4192-42f8-81fa-777a763e6e2c&response_type=code&scope=https%3A%2F%2Fwww.wvd.microsoft.com%2F.default&redirect_uri=https%3A%2F%2Flogin.microsoftonline.com%2Fcommon%2Foauth2%2Fnativeclient
Paste redirect URL here: 
[REDACTED]
[10:05:15:309] [170306:00029944] [TRACE][com.freerdp.client.SDL] - [OnTimer]: checking for display changes...
[10:05:39:277] [170306:00029949] [ERROR][com.freerdp.core.connection] - [rdp_client_connect]: error retrieving ARM configuration
D [0x00000304]
[10:05:38:878] [170306:00029949] [DEBUG][com.freerdp.utils.http] - [freerdp_http_request]: headers:
POST /common/oauth2/v2.0/token HTTP/1.1
Host: login.microsoftonline.com
Content-Type: application/x-www-form-urlencoded
Content-Length: 1037


[10:05:39:013] [170306:00029949] [DEBUG][com.freerdp.utils.http] - [freerdp_http_request]: body:
grant_type=authorization_code&code=[REDACTED]&client_id=[REDACTED]&scope=https%3A%2F%2Fwww.wvd.microsoft.com%2F.default&redirect_uri=https%3A%2F%2Flogin.microsoftonline.com%2Fcommon%2Foauth2%2Fnativeclient
[10:05:39:278] [170306:00029949] [DEBUG][com.freerdp.core.rdp] - [rdp_finalize_reset_flags][0x5c72ddb4f280]: [CONNECTION_STATE_INITIAL] reset finalize_sc_pdus
[10:05:39:278] [170306:00029949] [DEBUG][com.freerdp.core.rdp] - [rdp_client_transition_to_state][0x5c72ddb4f280]: CONNECTION_STATE_INITIAL --> CONNECTION_STATE_INITIAL
[10:05:39:284] [170306:00029949] [TRACE][com.freerdp.api] - [freerdp_channels_process_message]: IFCALL(message->Free) == NULL
[10:05:39:284] [170306:00029949] [DEBUG][com.freerdp.client.SDL] - [error_info_to_error]: Terminate with SDL_EXIT_SUCCESS due to ERROR_INFO ERRINFO_SUCCESS [0x00000000]: Success.

@akallabeth
Copy link
Member Author

@progxaker ok, so it works as intended ;)
the connection terminates after waiting 15 seconds for a response, but does not get one.

@progxaker
Copy link
Contributor

progxaker commented Jun 20, 2024

But the AVD instance was off, and I wanted to wait for the auto-reconnect mechanism to start it up automatically. Instead, FreeRDP drops the connection after 15 seconds, i.e., it doesn't wait for the instance is up.

@akallabeth
Copy link
Member Author

@progxaker hmm, for that there should be a response from the remote end, see your previous logs with entries like [arm_handle_bad_request]: Session Host with ID = '[REDACTED]' has been deallocated we are starting the session host for you. Please retry connecting after 5 minutes.
you can try to increase timeouts with /timeout:<time in ms> if your connection / remote end is slow

@progxaker
Copy link
Contributor

Hello @akallabeth. I don't think the timeout parameter helps here. I set it to 20000ms (/timeout:20000), but still got the error.
If we look at the time, I provided a token in 200ms, then got a response after 6 seconds, and after 400ms FreeRDP said timeout reached. I think this happened because wstatus is equal 0 in any case.

Logs
[06:57:58:489] [39427:00009a0a] [DEBUG][com.freerdp.core.gateway.arm] - [arm_tls_connect]: connecting to [REDACTED] 443
Browse to: https://login.microsoftonline.com/common/oauth2/v2.0/authorize?client_id=a85cf173-4192-42f8-81fa-777a763e6e2c&response_type=code&scope=https%3A%2F%2Fwww.wvd.microsoft.com%2F.default&r
edirect_uri=https%3A%2F%2Flogin.microsoftonline.com%2Fcommon%2Foauth2%2Fnativeclient
Paste redirect URL here:
[06:57:58:623] [39427:00009a03] [INFO][com.freerdp.client.SDL] - [winpr_LogOutputFunction]: [SDL_LOG_CATEGORY_RENDER] OpenGL shaders: ENABLED
...
[06:57:58:691] [39427:00009a03] [INFO][com.freerdp.client.SDL] - [winpr_LogOutputFunction]: https://login.microsoftonline.com/common/oauth2/nativeclient?code=[REDACTED]&session_state=5b723fba-fa50-4236-b5c9-cd9befcebb8d
...
[06:57:59:291] [39427:00009a05] [TRACE][com.freerdp.client.SDL] - [OnTimer]: checking for display changes...
...
[06:58:04:401] [39427:00009a0a] [DEBUG][com.freerdp.utils.http] - [freerdp_http_request]: headers:
POST /common/oauth2/v2.0/token HTTP/1.1
Host: login.microsoftonline.com
Cont[06:58:04:855] [39427:00009a0a] [ERROR][com.freerdp.core.gateway.http] - [http_response_recv]: [BIO_wait] timeout exceeded
[06:58:04:855] [39427:00009a0a] [ERROR][com.freerdp.core.connection] - [rdp_client_connect]: error retrieving ARM configuration
ent-Type: application/x-www-form-urlencoded
Content-Length: 1041


[06:58:04:568] [39427:00009a0a] [DEBUG][com.freerdp.utils.http] - [freerdp_http_request]: body:
grant_type=authorization_code&code=[REDACTED]&client_id=[REDACTED]&scope=https%3A%2F%2Fwww.wvd.microsoft.com%2F.default&redirect_uri=https%3A%2F%2Flogin.microsoftonline.com%2Fcommon%2Foauth2%2Fnativeclient
[06:58:04:856] [39427:00009a0a] [DEBUG][com.freerdp.core.rdp] - [rdp_finalize_reset_flags][0x5796b89d8280]: [CONNECTION_STATE_INITIAL] reset finalize_sc_pdus
[06:58:04:856] [39427:00009a0a] [DEBUG][com.freerdp.core.rdp] - [rdp_client_transition_to_state][0x5796b89d8280]: CONNECTION_STATE_INITIAL --> CONNECTION_STATE_INITIAL
[06:58:04:861] [39427:00009a0a] [TRACE][com.freerdp.api] - [freerdp_channels_process_message]: IFCALL(message->Free) == NULL
[06:58:04:861] [39427:00009a0a] [DEBUG][com.freerdp.client.SDL] - [error_info_to_error]: Terminate with SDL_EXIT_SUCCESS due to ERROR_INFO ERRINFO_SUCCESS [0x00000000]: Success.
...
[06:58:19:862] [39427:00009a03] [INFO][com.freerdp.client.SDL] - [winpr_LogOutputFunction]: [SDL_LOG_CATEGORY_APPLICATION] got event SDL_USEREVENT_RETRY_DIALOG [0x0000800e]

UPD: yes, it looks like.

Details

I added the WLog_ERR function to print wstatus.

diff --git a/libfreerdp/core/gateway/http.c b/libfreerdp/core/gateway/http.c
index dce527804..f4ecbed17 100644
--- a/libfreerdp/core/gateway/http.c
+++ b/libfreerdp/core/gateway/http.c
@@ -1240,6 +1240,7 @@ HttpResponse* http_response_recv(rdpTls* tls, BOOL readContentLength)
                /* Read until we encounter \r\n\r\n */
                ERR_clear_error();
                const int wstatus = BIO_wait_read(tls->bio, timeout);
+               WLog_ERR(TAG, "[BIO_wait_read] wstatus: %i", wstatus);
                if (wstatus < 0)
                {
                        if (!BIO_should_retry(tls->bio))

and got

[41333:0000a17c] [ERROR][com.freerdp.core.gateway.http] - [http_response_recv]: [BIO_wait_read] wstatus: 0

P.S. This is also not related to the reconnection mechanism, because in the second attempt (with the log function) AVD was started (by first FreeRDP run).

http_response_recv might never receive an answer, so do wait for input
and fail if the timeout is exceeded.
@akallabeth
Copy link
Member Author

akallabeth commented Jun 24, 2024

@progxaker ok, there was indeed a bug with the timeout handling in the custom BIO implementations.
should be fixed now (timeout returns 0 and errno = ETIMEDOUT

Copy link

clang-tidy review says "All clean, LGTM! 👍"

@freerdp-bot
Copy link

Refer to this link for build results (access rights to CI server needed):
https://ci.freerdp.com//job/PullRequestTester/12204/

BIO_C_WAIT_READ and BIO_C_WAIT_WRITE now set errno = ETIMEDOUT
if a timeout occurred.
Copy link

clang-tidy review says "All clean, LGTM! 👍"

@freerdp-bot
Copy link

Refer to this link for build results (access rights to CI server needed):
https://ci.freerdp.com//job/PullRequestTester/12205/

@akallabeth akallabeth merged commit 370975c into FreeRDP:master Jun 25, 2024
7 checks passed
@akallabeth akallabeth deleted the http_read_timeout branch June 25, 2024 07:17
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

FreeRDP hangs after applying a changed host key
3 participants