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

API Request using Refit and System.Net.HTTP.DelegatingHandler / System.Net.Http.HttpClient fails with System.Net.Http.HttpIOException: The response ended prematurely. (ResponseEnded) and no Inner Exception #104296

Closed
amasidlovermedoc opened this issue Jul 2, 2024 · 14 comments
Closed

API Request using Refit and System.Net.HTTP.DelegatingHandler / System.Net.Http.HttpClient fails with System.Net.Http.HttpIOException: The response ended prematurely. (ResponseEnded) and no Inner Exception #104296

amasidlovermedoc opened this issue Jul 2, 2024 · 14 comments
Labels
area-System.Net.Http question Answer questions and provide assistance, not an issue with source code or documentation.
Milestone
9.0.0

Comments

@amasidlovermedoc
Copy link

Description

My code makes an API request to one of our servers using Refit with a DelegatingHandler to add authentication and a DelegatingHandler for logging - the UI is Avalonia with ReactiveUI, however, I can also reproduce the issue when I write a command line program that directly calls the API wrapping code.

The API returns results in 'pages' with the full data covering 510 'pages'. I have two branches of code one which requests each page sequentially and another which uses a List and WhenAny() / Any() to retrieve multiple pages at once.

The sequential version retrieves all 510 pages successfully. The parallel version (with max 6 tasks at a time) has 2 or 3 failing requests (they come in batches) every 10-20 pages.

The failing requests give the exception:

      [ae1475b2-b5a6-4bf5-8c94-eaaa8ec04221 -   Request] Exception occurred: System.Net.Http.HttpRequestException: An error occurred while sending the request.
       ---> System.Net.Http.HttpIOException: The response ended prematurely. (ResponseEnded)
         at System.Net.Http.HttpConnection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
         --- End of inner exception stack trace ---
         at System.Net.Http.HttpConnection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
         at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
         at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
         at ZymonicServices.HttpLoggingHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /home/amasidlover/workspace/zymonic-dev/ZymonicApp/ZymonicServices/Classes/HttpLoggingHandler.cs:line 45

When I add a breakpoint in the debugger on the exception handling in the http logging handler (which is the innermost of my DelegatingHandlers) - the inner Exception is either the same as the outer or empty.

I'm relatively new to C# and .NET so quite prepared to be told that its my implementation that is wrong - also because of the fact our servers are not publicly available I can't easily create a minimal reproduction without starting from scratch.

The server logs and debugs report that the server responded with 200 status code and a complete JSON response.

Reproduction Steps

My Api is called as follows:

			List<TResult> apiResults = await GetApiResults(debugMode, requireAuthenticated, cancellationToken, page++).ConfigureAwait(false);
			await StoreApiResults(apiResults, cancellationToken).ConfigureAwait(true);
			await RefreshCache().ConfigureAwait(false);

			if (parallelMode)
			{
				var downloadTasks = new List<Task<List<TResult>>>();

				for (int i = 0; i < maximumFetchTasks; i++)
				{
					downloadTasks.Add(Task.Run(() => GetApiResults(debugMode, requireAuthenticated, cancellationToken, page++)));
				}

				while (downloadTasks.Any())
				{
					Task<List<TResult>> finishedTask = await Task.WhenAny(downloadTasks);
					downloadTasks.Remove(finishedTask);
					apiResults = await finishedTask;
					await StoreApiResults(apiResults, cancellationToken).ConfigureAwait(true);
					cancellationToken.ThrowIfCancellationRequested();
					await RefreshCache().ConfigureAwait(false);

					if (pageCount > page)
					{
						// Run get token with a longer margin here to ensure that we don't try and refresh the token in
						// a background task and then fail to write to the DB
						await _authService.GetToken(60).ConfigureAwait(true);
						downloadTasks.Add(Task.Run(() => GetApiResults(debugMode, requireAuthenticated, cancellationToken, page++)));
					}
				}
			}
			else
			{
				// Retained for testing
				while (pageCount > page)
				{
					apiResults = await GetApiResults(debugMode, requireAuthenticated, cancellationToken, page++).ConfigureAwait(false);
					await StoreApiResults(apiResults, cancellationToken);
					cancellationToken.ThrowIfCancellationRequested();
					await RefreshCache().ConfigureAwait(false);
				}
			}

The HTTPClient is set-up as a static and initialised in the constructor (previously I was creating one each time the method above was called:

	static HttpClient singleHttpClient;

In Constructor:

		singleHttpClient = new HttpClient(new ZymonicAPIHandler(_logger, _authService, new HttpLoggingHandler(_logger)))
		{
			BaseAddress = new Uri(_settings.BaseUri()),
			Timeout = TimeSpan.FromSeconds(30)
		};

The ZymonicAPIHandler has:

  protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
  {

    var token = await authTokenStore.GetToken();

    request.Headers.Authorization = new AuthenticationHeaderValue("Bearer", token);

    try
    {

      var result = await base.SendAsync(request, cancellationToken).ConfigureAwait(true);

      result.EnsureSuccessStatusCode();

      return result;
    }
    catch (Exception e)
    {
      debugInnerException(e);

      throw;
    }

  }

The logging handler is as follows:

	async protected override Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
	{
		var req = request;
		var id = Guid.NewGuid().ToString();
		var msg = $"[{id} -   Request]";

		_logger.LogInformation($"{msg}========Start==========");
		_logger.LogInformation($"{msg} {req.Method} {req.RequestUri.PathAndQuery} {req.RequestUri.Scheme}/{req.Version}");
		_logger.LogInformation($"{msg} Host: {req.RequestUri.Scheme}://{req.RequestUri.Host}");

		foreach (var header in req.Headers)
			_logger.LogInformation($"{msg} {header.Key}: {string.Join(", ", header.Value)}");

		if (req.Content != null)
		{
			foreach (var header in req.Content.Headers)
				_logger.LogInformation($"{msg} {header.Key}: {string.Join(", ", header.Value)}");

			if (req.Content is StringContent || this.IsTextBasedContentType(req.Headers) || this.IsTextBasedContentType(req.Content.Headers))
			{
				var result = await req.Content.ReadAsStringAsync();

				_logger.LogInformation($"{msg} Content:");
				_logger.LogInformation($"{msg} {string.Join("", result.Cast<char>().Take(5000))}...");

			}
		}

		var start = DateTime.Now;

		try
		{

			var response = await base.SendAsync(request, cancellationToken).ConfigureAwait(false);



			var end = DateTime.Now;

			_logger.LogInformation($"{msg} Duration: {end - start}");
			_logger.LogInformation($"{msg}==========End==========");

			msg = $"[{id} - Response]";
			_logger.LogInformation($"{msg}=========Start=========");

			var resp = response;

			_logger.LogInformation($"{msg} {req.RequestUri.Scheme.ToUpper()}/{resp.Version} {(int)resp.StatusCode} {resp.ReasonPhrase}");

			foreach (var header in resp.Headers)
				_logger.LogInformation($"{msg} {header.Key}: {string.Join(", ", header.Value)}");

			if (resp.Content != null)
			{
				foreach (var header in resp.Content.Headers)
					_logger.LogInformation($"{msg} {header.Key}: {string.Join(", ", header.Value)}");

				if (resp.Content is StringContent || this.IsTextBasedContentType(resp.Headers) || this.IsTextBasedContentType(resp.Content.Headers))
				{
					start = DateTime.Now;
					var result = await resp.Content.ReadAsStringAsync();
					end = DateTime.Now;

					_logger.LogInformation($"{msg} Content:");
					_logger.LogInformation($"{msg} {string.Join("", result.Cast<char>().Take(5000))}...");
					_logger.LogInformation($"{msg} Duration: {end - start}");
				}
			}

			_logger.LogInformation($"{msg}==========End==========");
			return response;
		}
		catch (Exception e)
		{
			var end = DateTime.Now;
			_logger.LogInformation($"{msg} Duration: {end - start}");
			_logger.LogError($"{msg} Exception occurred: {e.ToString()}");
			throw;
		}
	}

Expected behavior

The expected behaviour is that following the initial request that gets a page count up to maximumFetchTasks run in parallel and retrieve the remaining pages.

Each response should look like:

info: Program[0]
      GetApiResults Running on thread 14
info: Program[0]
      Token expires at 02/07/2024 10:38:53 - currently 02/07/2024 10:27:30
info: Program[0]
      [2bebc456-b25a-4f1c-9461-1bd3fbfc659f -   Request]========Start==========
info: Program[0]
      [2bebc456-b25a-4f1c-9461-1bd3fbfc659f -   Request] POST /zymonicmp https/1.1
info: Program[0]
      [2bebc456-b25a-4f1c-9461-1bd3fbfc659f -   Request] Host: https://md5.zednax.com
info: Program[0]
      [2bebc456-b25a-4f1c-9461-1bd3fbfc659f -   Request] Authorization: Bearer MTcxOTkxNjAxMy03MzkxMDgtMC42MTY4MTg3MTkwODU2NjgtcFdsZGxvdG84UDRTUFhicnExV0huVUoxTjFhSWhi
info: Program[0]
      [2bebc456-b25a-4f1c-9461-1bd3fbfc659f -   Request] Content-Type: application/json; charset=utf-8
info: Program[0]
      [2bebc456-b25a-4f1c-9461-1bd3fbfc659f -   Request] Content:
info: Program[0]
      [2bebc456-b25a-4f1c-9461-1bd3fbfc659f -   Request] {"cbos_fil_stock_lookup":{"search":"Refresh Results","refresh_this_filter_mvs":"true","report_pagenum":31},"ZymonicHeader":{"system":"ztsm","webservicemode":"filter","debug":"true","compact_output":"true","output_authentication_status":"true"}}...
info: Program[0]
      [e70af968-6df0-4dc7-973a-22b51aeb49cc - Response] Content:
info: Program[0]
      [e70af968-6df0-4dc7-973a-22b51aeb49cc - Response] {"cbos_fil_stock_lookup":{"search_fields":{"record":{"cbos_stock_levels_sum_amount_start_autosearchfield":"","f_short_code_sl":"","cbos_stock_levels_colour":"","cbos_stock_levels_branch":"","f_stock_levels_preorder_end_autosearchfield":"","cbos_stock_levels_actual_amount_sum_start_autosearchfield":"","current_fieldgroup":"","cbos_stock_levels_sum_amount_end_autosearchfield":"","f_stock_levels_preorder_start_autosearchfield":"","cbos_stock_levels_hide_personalisation_items_sff":"H","cbos_stock_levels_branch_num":"","cbos_stock_levels_actual_amount_sum_end_autosearchfield":"","cbos_stock_levels_barcode":"","cbos_stock_levels_description":"","cbos_stock_levels_reserve_end_autosearchfield":"","f_catalogue_code_sl":"","cbos_stock_levels_stock_range":"","ident":"_cbos_fil_stock_lookup_searchfieldsrecord_","cbos_stock_levels_status":"","cbos_stock_levels_sizes":"","cbos_stock_levels_reserve_start_autosearchfield":""},"type":"Form","ident":"_cbos_fil_stock_lookup_"},"ztsm_stocklevels_group_branch":{"type":"GroupBy","ident":"_cbos_fil_stock_lookup_ztsm_stocklevels_group_branch","DisplayName":"Branch"},"report":{"group_ident":"_cbos_fil_stock_lookup_ztsm_stocklevels_group_branch","ident":"_cbos_fil_stock_lookup_ztsm_stocklevels_group_branch","has_headers":"true","signature":"c8c4ee5a41a100b7d079d519d09f0756","group_level":0,"navigation":{"current_page":"25","last_page":511,"error":[]},"expanded":"true","result_count":12762,"result":[{"f_short_code_sl":"610210","f_stock_levels_quantity":"1000.00","ZZid":{"ztsm_stockid":3996,"ztsm_stock_variants_to_levelsstock_holding_id":10140,"ztsm_stock_to_process_tjprocessid":6591,"ztsm_stock_to_variantsid":26196,"cbos_stock_levels_to_branchesid":843},"f_stock_levels_preorder":"0.00","cbos_stock_levels_branch_num":"10","cbos_stock_levels_personalisation_item":"","cbos_stock_levels_main_barcode":"0103029945939","cbos_zero_stock_held":"N","cbos_stock_levels_barcode":"0103029945939,0101550026002,4004020014227,5055035640221,610210","cbos_stock_levels_branch_has_stock_levels":"Y","f_catalogue_code_sl":"GENB004","cbos_stock_levels_branch":"Test","cbos_stock_levels_colour":"CHARCOAL","cbos_stock_levels_reserve":"0.00","cbos_stock_levels_stock_variant_id":"26196","parent_process_id":"6591","cbos_stock_levels_stock_image":"","cbos_stock_levels_actual_amount_sum":"1000.00","cbos_stock_levels_actual_amount":"1000.00","cbos_stock_levels_description":"SPEED SUBBUTEO T-SHIRT","cbos_stock_levels_stock_held_at_other_branch":"","cbos_stock_levels_sum_amount":"1000.00","ZRC_row_counter":601,"report":[],"cbos_stock_levels_sizes":"S"},{"cbos_stock_levels_personalisation_item":"","cbos_zero_stock_held":"N","cbos_stock_levels_barcode":null,"cbos_stock_levels_main_barcode":null,"cbos_stock_levels_branch_has_stock_levels":"Y","f_catalogue_code_sl":"GENB004","f_short_code_sl":"610211","f_stock_levels_quantity":"1000.00","ZZid":{"ztsm_stockid":3996,"ztsm_stock_variants_to_levelsstock_holding_id":10137,"cbos_stock_levels_to_branchesid":843,"ztsm_stock_to_variantsid":26205,"ztsm_stock_to_process_tjprocessid":6591},"f_stock_levels_preorder":"0.00","cbos_stock_levels_branch_num":"10","parent_process_id":"6591","cbos_stock_levels_stock_variant_id":"26205","cbos_stock_levels_actual_amount_sum":"1000.00","cbos_stock_levels_stock_image":"","cbos_stock_levels_actual_amount":"1000.00","cbos_stock_levels_description":"SPEED SUBBUTEO T-SHIRT","cbos_stock_levels_sum_amount":"1000.00","cbos_stock_levels_stock_held_at_other_branch":"","ZRC_row_counter":601,"report":[],"cbos_stock_levels_sizes":"XL","cbos_stock_levels_colour":"CHARCOAL","cbos_stock_levels_branch":"Test","cbos_stock_levels_reserve":"0.00"},{"cbos_stock_levels_stock_variant_id":"26208","parent_process_id":"6591","cbos_stock_levels_actual_amount_sum":"1000.00","cbos_stock_levels_stock_image":"","cbos_stock_levels_actual_amount":"1000.00","cbos_stock_levels_description":"SPEED SUBBUTEO T-SHIRT","cbos_stock_levels_sum_amount":"1000.00","cbos_stock_levels_stock_held_at_other_branch":"","ZRC_row_counter":601,"report":[],"cbos_stock_levels_sizes":"2XL","cbos_stock_levels_colour":"CHARCOAL","cbos_stock_levels_branch":"Test","cbos_stock_levels_reserve":"0.00","cbos_stock_levels_personalisation_item":"","cbos_zero_stock_held":"N","cbos_stock_levels_barcode":null,"cbos_stock_levels_main_barcode":null,"cbos_stock_levels_branch_has_stock_levels":"Y","f_catalogue_code_sl":"GENB004","f_short_code_sl":"610212","f_stock_levels_quantity":"1000.00","ZZid":{"ztsm_stock_variants_to_levelsstock_holding_id":10139,"ztsm_stockid":3996,"ztsm_stock_to_variantsid":26208,"cbos_stock_levels_to_branchesid":843,"ztsm_stock_to_process_tjprocessid":6591},"f_stock_levels_preorder":"0.00","cbos_stock_levels_branch_num":"10"},{"cbos_stock_levels_description":"STRACHAN SUBBUTEO T-SHIRT","cbos_stock_levels_sum_amount":"1000.00","cbos_stock_levels_stock_held_at_other_branch":"","report":[],"ZRC_row_counter":601,"cbos_stock_levels_sizes":"3XL","cbos_stock_levels_stock_variant_id":"26232","parent_p...
info: Program[0]
      [e70af968-6df0-4dc7-973a-22b51aeb49cc - Response] Duration: 00:00:00.0795456
info: Program[0]
      [e70af968-6df0-4dc7-973a-22b51aeb49cc - Response]==========End==========
info: Program[0]
      StoreApiResults Running on thread 5
info: Program[0]
      Adding 3996.10140.6591.26196.843 to DB
info: Program[0]
      Adding 3996.10137.6591.26205.843 to DB
info: Program[0]
      Adding 3996.10139.6591.26208.843 to DB
info: Program[0]
      Adding 3999.10146.6594.26232.843 to DB
info: Program[0]
      Adding 3999.10145.6594.26235.843 to DB
info: Program[0]
      Adding 3999.10142.6594.26223.843 to DB
info: Program[0]
      Adding 3999.10147.6594.26220.843 to DB
info: Program[0]
      Adding 3999.10141.6594.26217.843 to DB
info: Program[0]
      Adding 3999.10143.6594.26226.843 to DB
info: Program[0]
      Adding 3999.10144.6594.26229.843 to DB
info: Program[0]
      Adding 4005.10157.6600.26274.843 to DB
info: Program[0]
      Adding 4005.10155.6600.26277.843 to DB
info: Program[0]
      Adding 4005.10161.6600.26265.843 to DB
info: Program[0]
      Adding 4005.10159.6600.26262.843 to DB
info: Program[0]
      Adding 4005.10160.6600.26259.843 to DB
info: Program[0]
      Adding 4005.10158.6600.26268.843 to DB
info: Program[0]
      Adding 4005.10156.6600.26271.843 to DB
info: Program[0]
      Adding 3804.9785.6369.25152.843 to DB
info: Program[0]
      Adding 3804.9782.6369.25149.843 to DB
info: Program[0]
      Adding 3804.9780.6369.25155.843 to DB
info: Program[0]
      Adding 3804.9786.6369.25137.843 to DB
info: Program[0]
      Adding 3804.9781.6369.25134.843 to DB
info: Program[0]
      Adding 3804.9779.6369.25131.843 to DB
info: Program[0]
      Adding 3804.9784.6369.25140.843 to DB
info: Program[0]
      Adding 3804.9778.6369.25128.843 to DB
info: Program[0]
      Token expires at 02/07/2024 10:38:53 - currently 02/07/2024 10:27:30
info: Program[0]

Actual behavior

Every 10-20 pages then 2-3 of the following errors are reported:

info: Program[0]
      GetApiResults Running on thread 5
info: Program[0]
      Token expires at 02/07/2024 10:38:53 - currently 02/07/2024 10:27:30
info: Program[0]
      [0f25c481-1577-449d-8d02-04764681ab72 -   Request]========Start==========
info: Program[0]
      [0f25c481-1577-449d-8d02-04764681ab72 -   Request] POST /zymonicmp https/1.1
info: Program[0]
      [0f25c481-1577-449d-8d02-04764681ab72 -   Request] Host: https://md5.zednax.com
info: Program[0]
      [0f25c481-1577-449d-8d02-04764681ab72 -   Request] Authorization: Bearer MTcxOTkxNjAxMy03MzkxMDgtMC42MTY4MTg3MTkwODU2NjgtcFdsZGxvdG84UDRTUFhicnExV0huVUoxTjFhSWhi
info: Program[0]
      [0f25c481-1577-449d-8d02-04764681ab72 -   Request] Content-Type: application/json; charset=utf-8
info: Program[0]
      [0f25c481-1577-449d-8d02-04764681ab72 -   Request] Content:
info: Program[0]
      [0f25c481-1577-449d-8d02-04764681ab72 -   Request] {"cbos_fil_stock_lookup":{"search":"Refresh Results","refresh_this_filter_mvs":"true","report_pagenum":32},"ZymonicHeader":{"system":"ztsm","webservicemode":"filter","debug":"true","compact_output":"true","output_authentication_status":"true"}}...
info: Program[0]
      [0f25c481-1577-449d-8d02-04764681ab72 -   Request] Duration: 00:00:00.8892747
fail: Program[0]
      [0f25c481-1577-449d-8d02-04764681ab72 -   Request] Exception occurred: System.Net.Http.HttpRequestException: An error occurred while sending the request.
       ---> System.Net.Http.HttpIOException: The response ended prematurely. (ResponseEnded)
         at System.Net.Http.HttpConnection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
         --- End of inner exception stack trace ---
         at System.Net.Http.HttpConnection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
         at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
         at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
         at ZymonicServices.HttpLoggingHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /home/amasidlover/workspace/zymonic-dev/ZymonicApp/ZymonicServices/Classes/HttpLoggingHandler.cs:line 45
fail: Program[0]
      System.Net.Http.HttpRequestException: An error occurred while sending the request.
       ---> System.Net.Http.HttpIOException: The response ended prematurely. (ResponseEnded)
         at System.Net.Http.HttpConnection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
         --- End of inner exception stack trace ---
         at System.Net.Http.HttpConnection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
         at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
         at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
         at ZymonicServices.HttpLoggingHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /home/amasidlover/workspace/zymonic-dev/ZymonicApp/ZymonicServices/Classes/HttpLoggingHandler.cs:line 45
         at ZymonicServices.ZymonicAPIHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /home/amasidlover/workspace/zymonic-dev/ZymonicApp/ZymonicServices/Classes/ZymonicAPIHandler.cs:line 32
fail: Program[0]
      System.Net.Http.HttpIOException: The response ended prematurely. (ResponseEnded)
         at System.Net.Http.HttpConnection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
fail: Program[0]
      System.Net.Http.HttpRequestException: An error occurred while sending the request.
       ---> System.Net.Http.HttpIOException: The response ended prematurely. (ResponseEnded)
         at System.Net.Http.HttpConnection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
         --- End of inner exception stack trace ---
         at System.Net.Http.HttpConnection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
         at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
         at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
         at ZymonicServices.HttpLoggingHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /home/amasidlover/workspace/zymonic-dev/ZymonicApp/ZymonicServices/Classes/HttpLoggingHandler.cs:line 45
         at ZymonicServices.ZymonicAPIHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /home/amasidlover/workspace/zymonic-dev/ZymonicApp/ZymonicServices/Classes/ZymonicAPIHandler.cs:line 32
         at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken)
         at Refit.RequestBuilderImplementation.<>c__DisplayClass14_0`2.<<BuildCancellableTaskFuncForMethod>b__0>d.MoveNext() in /_/Refit/RequestBuilderImplementation.cs:line 256
      --- End of stack trace from previous location ---
         at ZymonicServices.ZymonicFilter`5.GetApiResults(Boolean debugMode, Boolean requireAuthenticated, CancellationToken ct, Int32 page) in /home/amasidlover/workspace/zymonic-dev/ZymonicApp/ZymonicServices/Classes/ZymonicFilter.cs:line 213

The error and access logs on the server show:

[Tue Jul 02 11:57:40] amasidlover@md5 ~ $ sudo tail /var/log/apache2/ssl_error_log
[Mon Jul 01 14:39:10.005048 2024] [ssl:error] [pid 10608] [client 44.220.185.62:42262] AH02042: rejecting client initiated renegotiation
[Tue Jul 02 11:57:45] amasidlover@md5 ~ $ sudo tail /var/log/apache2/ssl_access_log
148.252.144.144 - - [02/Jul/2024:11:52:11 +0100] "POST /zymonicmp/ztsm/oauth/tokend HTTP/1.1" 200 297
148.252.144.144 - - [02/Jul/2024:11:52:12 +0100] "POST /zymonicmp HTTP/1.1" 200 29522
148.252.144.144 - - [02/Jul/2024:11:52:19 +0100] "POST /zymonicmp HTTP/1.1" 200 29600
148.252.144.144 - - [02/Jul/2024:11:52:19 +0100] "POST /zymonicmp HTTP/1.1" 200 29481
148.252.144.144 - - [02/Jul/2024:11:52:19 +0100] "POST /zymonicmp HTTP/1.1" 200 29543
148.252.144.144 - - [02/Jul/2024:11:52:20 +0100] "POST /zymonicmp HTTP/1.1" 200 29515
148.252.144.144 - - [02/Jul/2024:11:52:25 +0100] "POST /zymonicmp HTTP/1.1" 200 29490
148.252.144.144 - - [02/Jul/2024:11:52:26 +0100] "POST /zymonicmp HTTP/1.1" 200 29653
148.252.144.144 - - [02/Jul/2024:11:52:26 +0100] "POST /zymonicmp HTTP/1.1" 200 29071
148.252.144.144 - - [02/Jul/2024:11:52:29 +0100] "POST /zymonicmp HTTP/1.1" 200 28615

Regression?

Not known...

Known Workarounds

Running the retrieval tasks sequentially.

Configuration

Dotnet version 8.0.104

Fedora Linux 40 (Workstation Edition)

Linux madai 6.9.5-200.fc40.x86_64 #1 SMP PREEMPT_DYNAMIC Sun Jun 16 15:47:09 UTC 2024 x86_64 GNU/Linux

Other information

My best guess is that its something related to multi-threading (as it doesn't happen with the single awaited variant) and that there is an exception being thrown somewhere that doesn't get caught properly because of my use of async / await - if I stop the code in the debugger then I see 'MoveNext' as part of the caller stack :

" at System.Net.Http.HttpConnection.d__57.MoveNext()"

I've spent some time watching videos and reading up on async/await to try and ensure I'm using good practices and this issue has persisted throughout my various attempts.

The only change I've been able to make that has completely worked around the issue is adding the parallelMode code branch and just doing one request at a time.

Finally, I've just noticed there's something wrong with the duration of both working and non-working request as they don't match the server side duration logged (even though the content of the logged response does match) - but I don't think that's significant.
@dotnet-policy-service dotnet-policy-service bot added the untriaged New issue has not been triaged by the area owner label Jul 2, 2024
@ManickaP
Copy link
Member

ManickaP commented Jul 2, 2024

Can you share more of the code? GetApiResults, StoreApiResults and how you call the HttpClient.

@ManickaP ManickaP added question Answer questions and provide assistance, not an issue with source code or documentation. needs-author-action An issue or pull request that requires more info or actions from the author. and removed untriaged New issue has not been triaged by the area owner labels Jul 2, 2024
@ManickaP ManickaP added this to the 9.0.0 milestone Jul 2, 2024
@amasidlovermedoc
Copy link
Author

Sure - there is a lot of code and I was trying to make the report as concise as I could...

GetApiResults (which is where the HttpClient is passed in to Refit and is then called):

	private async Task<List<TResult>> GetApiResults(bool debugMode, bool requireAuthenticated, CancellationToken ct, int page = 1)
	{
		List<TResult> retrievedResults = new List<TResult>();

		_logger.LogInformation($"GetApiResults Running on thread {System.Threading.Thread.CurrentThread.ManagedThreadId.ToString()}");
		// Set-up the search parameters
		TSearchAPI searchAPI = new TSearchAPI();
		searchAPI.ZymonicHeader = new ZymonicAPIHeader(_settings.SystemName(), "filter", debugMode);
		// Since we're now paginating we need to set-up a copy of the search parameters.
		TSearch apiSearchParameters = (TSearch)searchParameters.Clone();
		apiSearchParameters.report_pagenum = page;
		searchAPI.searchFields = apiSearchParameters;

		// Json Options
		JsonSerializerOptions jsonOptions = new()
		{
			DefaultIgnoreCondition = JsonIgnoreCondition.WhenWritingNull,
			NumberHandling = JsonNumberHandling.AllowReadingFromString
		};

		var api = RestService.For<IZymonicFilterApi<TSearch, TSearchAPI, TResult, TFilterResults, TFilterResultsAPI>>(singleHttpClient,
		new RefitSettings
		{
			ContentSerializer = new SystemTextJsonContentSerializer(jsonOptions)
		});

		try
		{
			var apiResponse = await api.FilterResults(searchAPI, ct).ConfigureAwait(true);


			// Note that generic Zymonic / HTTP error handling is covered in the ZymonicAPIHandler

			// Can do checking of the headers / statuses using apiResponse...
			TFilterResultsAPI apiDecodedResponse = apiResponse.Content;

			if (requireAuthenticated && apiDecodedResponse.Authenticated != "Y")
			{
				// Update our settings etc. with any post-logout tasks
				_authService.Logout();
				throw new UnauthenticatedFilterResponseException();
			}

			TFilterResults apiResults = apiDecodedResponse.filterResults;
			retrievedResults = apiResults.GetResults();

			// Update the result and page counts
			resultCount = apiDecodedResponse.filterResults.report.result_count ?? 0;
			pageCount = apiDecodedResponse.filterResults.report.navigation.last_page ?? 0;
			var current_page = apiDecodedResponse.filterResults.report.navigation.current_page ?? 0;

			if (current_page != page)
			{
				throw new WrongPageReturnedException()
				{
					PageRequested = page,
					PageReturned = current_page
				};
			}


		}
		catch (Exception ex)
		{
			_logger.LogError(ex.ToString());

		}

		return retrievedResults;
	}

StoreApiResults:

	private async Task StoreApiResults(List<TResult> apiResults, CancellationToken cancellationToken)
	{
		_logger.LogInformation($"StoreApiResults Running on thread {System.Threading.Thread.CurrentThread.ManagedThreadId.ToString()}");
		// add to DB - This can't be done in parallel because EFCore contexts can be used in parallel
		foreach (var result in apiResults)
		{
			cancellationToken.ThrowIfCancellationRequested();
			// Update the timestamp
			result.dateUpdated = DateTime.Now;
			var existingResult = _context.Set<TResult>().Find(result.uid);
			if (existingResult == null)
			{
				_logger.LogInformation($"Adding {result.uid} to DB");
				_context.Set<TResult>().Add(result);
			}
			else
			{
				_logger.LogInformation($"Updating {result.uid} in DB");
				_context.Set<TResult>().Entry(existingResult).CurrentValues.SetValues(result);
			}
		}

		// We await to ensure we don't try and save multiple results at once
		await _context.SaveChangesAsync().ConfigureAwait(false);
	}

@dotnet-policy-service dotnet-policy-service bot added needs-further-triage Issue has been initially triaged, but needs deeper consideration or reconsideration and removed needs-author-action An issue or pull request that requires more info or actions from the author. labels Jul 2, 2024
@rzikm
Copy link
Member

rzikm commented Jul 2, 2024 •
edited
Loading

downloadTasks.Add(Task.Run(() => GetApiResults(debugMode, requireAuthenticated, cancellationToken, page++)));

btw. this code is subtly wrong, you have individual tasks racing to increment the page variable. You should use Interlocked.Increment at the very least.

Maybe something like Parallel.ForAsync might be a better choice here?

@amasidlovermedoc
Copy link
Author

Yes, I also noticed when I was pasting that there are a couple of other issues with the parallelisation of the tasks (_auth.Logout() for example will use the DBContext and that's not thread safe) - plus pagecount could change unexpectedly.

Plus I still need to look at the expected exception handling to ensure that all the expected error cases are properly handled.

However, I'm reluctant to spend much more time on refactoring until I understand how to debug/fix the "response ended prematurely" Exception coming from HttpClient - since that has persisted through every parallel variant I've tried.

@amasidlovermedoc
Copy link
Author

I don't think I can use Parallel.ForAsync because I need to do the StoreApiResults part of the overall task (get -> store -> refresh cache) on one thread so that the DBContext is never used by two threads at the same time.

@ManickaP
Copy link
Member

ManickaP commented Jul 2, 2024 •
edited
Loading

"response ended prematurely" means the server closed the connection while we still expected data. There might be many reasons why we'd expect more data:

  • not finished headers
  • less than content length received
  • chunked encoding
    ...

I think you need to simplify your program to figure out what's going on. Try to call the API without all the libraries just with HttpClient, collect packet captures to see what is exchanged between client and the server etc. There isn't much with which we could help right now...

@amasidlovermedoc
Copy link
Author

I'm still very much learning .net so I'm afraid I'm either going to need some guidance or some pointers to specific documentation (ideally with examples) - specifically:

"Try to call the API without all the libraries" - Are you suggesting that I manually assemble the JSON string that is the request and assemble it into an HttpContent then use HttpClient.PostAsync to post it wrapped in a while loop that matches my current While/Any()/WhenAny() structure.

" collect packet captures" - using Wireshark or similar? Or using something internal to dotnet?

I'll give it a go, but its worth noting that if I switch off 'parallelMode' and let the tasks run sequentially there are no issues whatsoever - which makes me very tempted to just stick with the sequential implementation rather than rebuild the current version from the ground up until the issue presents itself.

I'd be quite happy to get deeper into the SendAsync method, but when I try and disable 'justMyCode' VS Code tells me : Property justMyCode is not allowed. It feels like being able to debug the System.Net.Http libraries would be my quickest way forward but I'm not sure how to get to the source of a NuGet installed package to add breakpoints to it. Do I need to check out the whole dotnet repo and build it on my machine and then link it as a project in my solution?

@ManickaP
Copy link
Member

ManickaP commented Jul 2, 2024

Are you suggesting ... use HttpClient.PostAsync

Yes.

using Wireshark

Yes.

which makes me very tempted to just stick with the sequential implementation

Feel free to do that, there's nothing wrong with that approach.

Do I need to check out the whole dotnet repo and build it on my machine

No, this should work from VS, use Step Into to open .NET source code, once that's opened, you can put break points in there.

To add to that, you can turn on private logging for System.Net.Http and match the logging message with code to see what's going on, example code: https://github.com/dotnet/runtime/blob/main/src/libraries/Common/tests/TestUtilities/TestEventListener.cs

Also the comment about the increment from @rzikm is very much true and you need to fix that in your parallel branch.

@amasidlovermedoc
Copy link
Author

Thanks for that! I will try the private logging for System.Net.Http first and see if that is illuminating. If that fails I will have a think about whether its worth trying to do a ground-up rebuild to try and get a minimal reproduction case - I'm still at the phase of learning where I make a minor change and spend hours trying to get to the bottom of one error message; so a full rewrite is quite daunting!

Everything I can find on Stack Overflow etc says I should be able to step into the .NET source code but when I try I get:

Step into: Stepping over non-user code 'ZymonicServices.HttpLoggingHandler.<>n__0'

And it steps over the line instead - and trying to disable JustMyCode in launch.json gives a 'property not allowed error'.

@ManickaP
Copy link
Member

ManickaP commented Jul 2, 2024

It might be because you're not stepping into .NET code but rather into some 3rd party library code.

I'm still at the phase of learning where I make a minor change and spend hours trying to get to the bottom of one error message; so a full rewrite is quite daunting!

I think that part of the problem is that you didn't start with minimal code and slowly build on that. You're starting with quite a bit of machinery there which obviously is hard to debug, change etc. You need to understand what's going on underneath first.

@ManickaP ManickaP removed the needs-further-triage Issue has been initially triaged, but needs deeper consideration or reconsideration label Jul 2, 2024
@amasidlovermedoc
Copy link
Author

To be fair to myself I did start with a command line version (which still works - and exhibits the same; "works in sequence/fails in parallelMode") and uses the same classes but it still uses Refit, Rx.Net and EFCore - because those were the examples I found that gave the functionality I needed and appeared well maintained - so even my first version wasn't bare bones. But I am gradually getting deeper into the machinery underneath as I go along...

I've added in the private logging as follows:

	async protected override Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
	{
		var req = request;
		var id = Guid.NewGuid().ToString();
		var msg = $"[{id} -   Request]";

		_logger.LogInformation($"{msg}========Start==========");
		_logger.LogInformation($"{msg} {req.Method} {req.RequestUri.PathAndQuery} {req.RequestUri.Scheme}/{req.Version}");
		_logger.LogInformation($"{msg} Host: {req.RequestUri.Scheme}://{req.RequestUri.Host}");

		foreach (var header in req.Headers)
			_logger.LogInformation($"{msg} {header.Key}: {string.Join(", ", header.Value)}");

		if (req.Content != null)
		{
			foreach (var header in req.Content.Headers)
				_logger.LogInformation($"{msg} {header.Key}: {string.Join(", ", header.Value)}");

			if (req.Content is StringContent || this.IsTextBasedContentType(req.Headers) || this.IsTextBasedContentType(req.Content.Headers))
			{
				var result = await req.Content.ReadAsStringAsync();

				_logger.LogInformation($"{msg} Content:");
				_logger.LogInformation($"{msg} {string.Join("", result.Cast<char>().Take(5000))}...");

			}
		}

		var start = DateTime.Now;

		try
		{

			using var listener = new TestEventListener((m) => { _logger.LogInformation($"{msg} - {m}"); }, TestEventListener.NetworkingEvents);

			var response = await base.SendAsync(request, cancellationToken).ConfigureAwait(false);



			var end = DateTime.Now;

			_logger.LogInformation($"{msg} Duration: {end - start}");
			_logger.LogInformation($"{msg}==========End==========");

			msg = $"[{id} - Response]";
			_logger.LogInformation($"{msg}=========Start=========");

			var resp = response;

			_logger.LogInformation($"{msg} {req.RequestUri.Scheme.ToUpper()}/{resp.Version} {(int)resp.StatusCode} {resp.ReasonPhrase}");

			foreach (var header in resp.Headers)
				_logger.LogInformation($"{msg} {header.Key}: {string.Join(", ", header.Value)}");

			if (resp.Content != null)
			{
				foreach (var header in resp.Content.Headers)
					_logger.LogInformation($"{msg} {header.Key}: {string.Join(", ", header.Value)}");

				if (resp.Content is StringContent || this.IsTextBasedContentType(resp.Headers) || this.IsTextBasedContentType(resp.Content.Headers))
				{
					start = DateTime.Now;
					var result = await resp.Content.ReadAsStringAsync();
					end = DateTime.Now;

					_logger.LogInformation($"{msg} Content:");
					_logger.LogInformation($"{msg} {string.Join("", result.Cast<char>().Take(5000))}...");
					_logger.LogInformation($"{msg} Duration: {end - start}");
				}
			}

			_logger.LogInformation($"{msg}==========End==========");
			return response;
		}
		catch (Exception e)
		{
			var end = DateTime.Now;
			_logger.LogInformation($"{msg} Duration: {end - start}");
			_logger.LogError($"{msg} Exception occurred: {e.ToString()}");
			throw;
		}
	}

That produces the attached log httplogginghandler_DetailedLog.txt - I set the debugger to stop on any exception and have confirmed that the exception it stopped on is:
"System.Net.Http.HttpRequestException: An error occurred while sending the request.\n ---> System.Net.Http.HttpIOException: The response ended prematurely. (ResponseEnded)\n at System.Net.Http.HttpConnection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)\n --- End of inner exception stack trace ---\n at System.Net.Http.HttpConnection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)\n at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)\n at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)\n at ZymonicServices.HttpLoggingHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /home/amasidlover/workspace/zymonic-dev/ZymonicApp/ZymonicServices/Classes/HttpLoggingHandler.cs:line 47"

I added in the guid from the task to try and make sure that I only get messages from the async request that fails - however, I'm not ruling out that it includes messages from other tasks because of the way the http connection pool works.

The last few lines of logging are:

[INFO]	ZymonicApp	[feade07e-a34d-47c8-b449-9c056c12a628 -   Request] - 13:28:05.2301834[RequestLeftQueue] timeOnQueueMilliseconds: 3836.2962, versionMajor: 1, versionMinor: 1
[INFO]	ZymonicApp	[feade07e-a34d-47c8-b449-9c056c12a628 -   Request] - 13:28:05.2396437[HandlerMessage] poolId: 56990719, workerId: 54616604, requestId: 31773610, memberName: SendAsync, message: Sending request: Method: POST, RequestUri: 'https://md5-public.zednax.com:10443/zymonicmp', Version: 1.1, Content: System.Net.Http.PushStreamContent, Headers:
{
  Authorization: Bearer MTcxOTkyNjUzNy0yNzM1MTUtMC4yMjk1NDcwMTI1MzU5NjQtcmxDZnhCV1NTTzBvYVY1bXZzSXVYQ1pZOFRoaUVT
  Content-Type: application/json; charset=utf-8
  Content-Length: 243
}
[INFO]	ZymonicApp	[feade07e-a34d-47c8-b449-9c056c12a628 -   Request] - 13:28:05.2443061[RequestHeadersStart] connectionId: 5
[INFO]	ZymonicApp	[feade07e-a34d-47c8-b449-9c056c12a628 -   Request] - 13:28:05.2585744[RequestHeadersStop]
[INFO]	ZymonicApp	[feade07e-a34d-47c8-b449-9c056c12a628 -   Request] - 13:28:05.2835066[HandlerMessage] poolId: 56990719, workerId: 54616604, requestId: 31773610, memberName: SendAsync, message: Request content is not null, start processing it. hasExpectContinueHeader = False
[INFO]	ZymonicApp	[feade07e-a34d-47c8-b449-9c056c12a628 -   Request] - 13:28:05.3386838[RequestContentStart]

And then it stops and the debugger shows it stopped at the exception - which leads me to theorise that the issue is not with the communications but with trying to generate the content of the request that's about to be sent to the server.
This matches the server logs which show no evidence of any failed or aborted requests.

I discovered a couple of days ago that because I'm serialising objects to generate requests I need to clone the object that contains the page number to change page (which is contained in another object that is actually serialised to form the reqest) - is it possible that I need to either deepclone / create a new object to being serialised to form the request body - and that not having done so is causing some kind of exception if two threads try and serialise the same object?

@amasidlovermedoc
Copy link
Author

Actually, double checking my code and each GetApiResults tasks has its own objects:

		// Set-up the search parameters
		TSearchAPI searchAPI = new TSearchAPI();
		searchAPI.ZymonicHeader = new ZymonicAPIHeader(_settings.SystemName(), "filter", debugMode);
		// Since we're now paginating we need to set-up a copy of the search parameters.
		TSearch apiSearchParameters = (TSearch)searchParameters.Clone();
		apiSearchParameters.report_pagenum = page;
		searchAPI.searchFields = apiSearchParameters;

@ManickaP
Copy link
Member

ManickaP commented Jul 2, 2024 •
edited
Loading

using var listener = new TestEventListener((m) => { _logger.LogInformation($"{msg} - {m}"); }, TestEventListener.NetworkingEvents);

This has to be on the program level to log information from all paralel requests. Also make sure _logger can be invoked from multiple threads at the same time.

Run it without debugger to collect the logs so that you have a full picture. Fix that increment. Use Fiddler and/or WireShark to see whats happening on the network level.

Either way, it's highly unlikely this is a bug in HttpClient. There isn't anything actionable for us at the moment. We've given you some tips how to debug this issue, now it's up to you to dig into it. If you have any concrete questions about HttpClient behavior feel free to continue the discussion. I'll close this issue for now.

@ManickaP ManickaP closed this as completed Jul 2, 2024
@amasidlovermedoc
Copy link
Author

I moved the listener to the wrapping class and the trace output is much tidier and showed a 0 byte response from the server.

I used Wireshark plugged into mitmproxy (since #37915 doesn't look to be available until release 9) - and discovered that it is indeed the server closing the connection - eventually tracked it down to an out of memory error server side; hence no server side log - and why it was occurring on sequential requests.

Thanks for all the help; can happily confirm the HttpClient exception was indeed correct.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
area-System.Net.Http question Answer questions and provide assistance, not an issue with source code or documentation.
Projects
None yet
Milestone
9.0.0
Development

No branches or pull requests
3 participants
@ManickaP @rzikm @amasidlovermedoc