Nodejs Web App on Azure

Question

2020-12-18T17:39:06.652323823Z [41m [30mfail [39m [22m [49m: Middleware[0]
2020-12-18T17:39:06.652355023Z Failed to forward request to application. Encountered a System.Net.Http.HttpRequestException exception after 30585.959ms with message: An error occurred while sending the request.. Check application logs to verify the application is properly handling HTTP traffic.

Have tried to debug my application but havent been able to pin down the exact reason. What maybe causing this error for a nodejs webapp?

Answer 1

@Prakhar Sinha @Alexei Chizmakov @Benoit Lacelle seeing that the exceptions are reporting high timeouts, it may be occurring timing out on the Front-End load balancer. Long running requests upwards of 30s will have significantly high failures counts. @Benoit Lacelle , 5MB doesn't sound large to me but still could be same issue.

https://techcommunity.microsoft.com/t5/apps-on-azure/azure-storage-blob-upload-from-browser/ba-p/392687 is a blog post that provides a workaround for uploading files using Azure Storage and freeing up the web server. You can have your app generate a storage blob's SAS Key with write access which is sent back to the browser and used to upload to storage.

Answer 2

Hey, same issue here.
Operating system: Linux
App Service Plan: P1V2
Enviro: Python 3.9

Log Stream is flooded with:

2022-05-16T06:49:02.898273127Z: [INFO]  Application started. Press Ctrl+C to shut down./appsvctmp/volatile/logs/runtime/6df780ad39d116aac4f5c5e15c55a29e2545439a3ab526520597041594aea3b7.log
2022-05-16T06:42:32.757734882Z: [INFO]  warn: Middleware[0]
2022-05-16T06:42:32.757789282Z: [INFO]        At least one of http20OnlyDestinationHostUrl and http20OnlyListenUrl not provided
2022-05-16T06:42:43.790397987Z: [INFO]  fail: Middleware[0]
2022-05-16T06:42:43.791411080Z: [INFO]        Failed to forward request to http://172.16.0.2. Encountered a System.Net.Http.HttpRequestException exception after 13.924ms with message: Connection refused. Check application logs to verify the application is properly handling HTTP traffic.
2022-05-16T06:42:44.244110635Z: [INFO]  fail: Middleware[0]
2022-05-16T06:42:44.245280127Z: [INFO]        Failed to forward request to http://172.16.0.2. Encountered a System.Net.Http.HttpRequestException exception after 1.842ms with message: Connection refused. Check application logs to verify the application is properly handling HTTP traffic./appsvctmp/volatile/logs/runtime/8ff87a04d7df4ddafde5cd5787c120ab2c68c56d1df255e11f0b9c74166eb8c9.log
2022-05-16T06:31:38.861019815Z: [INFO]  warn: Middleware[0]
2022-05-16T06:31:38.861075515Z: [INFO]        At least one of http20OnlyDestinationHostUrl and http20OnlyListenUrl not provided/appsvctmp/volatile/logs/runtime/9ebac85b9fe5e9b0ba84496f56033df17f3b4b567934a26a30d721738ae61d7d.log
2022-05-16T06:53:08.552836441Z: [INFO]  warn: Middleware[0]
2022-05-16T06:53:08.552932040Z: [INFO]        At least one of http20OnlyDestinationHostUrl and http20OnlyListenUrl not provided/appsvctmp/volatile/logs/runtime/cd8ee0aaf255975b53d6c12ffac53ba16512290bd83bc0bea2b03eb5d5ffb0aa.log
2022-05-16T06:45:30.684772060Z: [INFO]  warn: Middleware[0]
2022-05-16T06:45:30.686718148Z: [INFO]        At least one of http20OnlyDestinationHostUrl and http20OnlyListenUrl not provided
2022-05-16T06:45:40.264909208Z: [INFO]  fail: Middleware[0]
2022-05-16T06:45:40.265824102Z: [INFO]        Failed to forward request to http://172.16.0.2. Encountered a System.Net.Http.HttpRequestException exception after 14.346ms with message: Connection refused. Check application logs to verify the application is properly handling HTTP traffic.
2022-05-16T06:45:40.483248679Z: [INFO]  fail: Middleware[0]
2022-05-16T06:45:40.484008174Z: [INFO]        Failed to forward request to http://172.16.0.2. Encountered a System.Net.Http.HttpRequestException exception after 2.559ms with message: Connection refused. Check application logs to verify the application is properly handling HTTP traffic./appsvctmp/volatile/logs/runtime/1bbda20b502803b8a8b1915db86d0a77bd171da00d823eea1d4a508d24fa766b.log
2022-05-16T06:52:24.503406817Z: [INFO]  Starting OpenBSD Secure Shell server: sshd.
2022-05-16T06:52:36.009651494Z: [INFO]  Hosting environment: Production
2022-05-16T06:52:36.010803987Z: [INFO]  Content root path: /azure-functions-host
2022-05-16T06:52:36.010821786Z: [INFO]  Now listening on: http://[::]:80
2022-05-16T06:52:36.011086785Z: [INFO]  Application started. Press Ctrl+C to shut down./appsvctmp/volatile/logs/runtime/1739b451372e3b73ca898e0d3fa9050459b50c2eec8c634ea0fdafc0eef5b360.log
2022-05-16T06:39:34.198758713Z: [INFO]  warn: Middleware[0]
2022-05-16T06:39:34.198857813Z: [INFO]        At least one of http20OnlyDestinationHostUrl and http20OnlyListenUrl not provided/appsvctmp/volatile/logs/runtime/cf2f370dca58164b5b1d7ab061e0a52241ec52c356f054f6586e37048f7cab8f.log
2022-05-16T06:34:17.632444780Z: [INFO]  Starting OpenBSD Secure Shell server: sshd.
2022-05-16T06:34:35.969545508Z: [INFO]  Hosting environment: Production
2022-05-16T06:34:35.969582108Z: [INFO]  Content root path: /azure-functions-host
2022-05-16T06:34:35.969596808Z: [INFO]  Now listening on: http://[::]:80
2022-05-16T06:34:35.969602608Z: [INFO]  Application started. Press Ctrl+C to shut down./appsvctmp/volatile/logs/runtime/01082313416e824b7a7cbd2b983d823ca5fda43599d5fa19dc4a5e8329cf6b1e.log
2022-05-16T06:36:09.933641501Z: [INFO]  Starting OpenBSD Secure Shell server: sshd.
2022-05-16T06:36:21.425425377Z: [INFO]  Hosting environment: Production
2022-05-16T06:36:21.426412972Z: [INFO]  Content root path: /azure-functions-host
2022-05-16T06:36:21.427247569Z: [INFO]  Now listening on: http://[::]:80
2022-05-16T06:36:21.427265069Z: [INFO]  Application started. Press Ctrl+C to shut down./appsvctmp/volatile/logs/runtime/f0dc03df2d4eb57f2aff69e3d1effdfed37428f68a30bc2478b65cdd5df2eeea.log
2022-05-16T06:36:19.699159566Z: [INFO]  warn: Middleware[0]
2022-05-16T06:36:19.699232566Z: [INFO]        At least one of http20OnlyDestinationHostUrl and http20OnlyListenUrl not provided/appsvctmp/volatile/logs/runtime/0f3cc4eb43944b8b00ef2cca188a60125c5814ae9c5004eb6f037ac8cb5e1aeb.log
2022-05-16T06:41:26.661233324Z: [INFO]  Starting OpenBSD Secure Shell server: sshd.
2022-05-16T06:41:37.377108810Z: [INFO]  Hosting environment: Production
2022-05-16T06:41:37.378020604Z: [INFO]  Content root path: /azure-functions-host
2022-05-16T06:41:37.378707900Z: [INFO]  Now listening on: http://[::]:80
2022-05-16T06:41:37.378738199Z: [INFO]  Application started. Press Ctrl+C to shut down./appsvctmp/volatile/logs/runtime/e666d112823718cd607a8f325e41c9189a87e0d3ab2a418ef8a47a33b0465416.log
2022-05-16T06:44:11.850583767Z: [INFO]  warn: Middleware[0]
2022-05-16T06:44:11.850635567Z: [INFO]        At least one of http20OnlyDestinationHostUrl and http20OnlyListenUrl not

Answer 3

Disabling CORS and authentication seemed to help with this (moved it inside the app). I was always suspicious the root cause was DNS failure and the way it is dealt with in the MS containers

Answer 4

I am having the same problem on a Linux Web App on Azure, that is running PHP 8.
The application seem to run well, but these error worry us a bit.

Starting Live Log Stream ---  
2022-08-09T13:08:38.592233981Z: [ERROR]  127.0.0.1 -  09/Aug/2022:13:08:33 +0000 "GET /index.php" 302  
  
2022-08-09T13:09:43.687377248Z: [INFO]  fail: Middleware[0]  
  
2022-08-09T13:09:43.688504071Z: [INFO]        Failed to forward request to http://169.254.129.4:8080. Encountered a System.IO.IOException exception after 70253.455ms with message: The response ended prematurely.. Check application logs to verify the application is properly handling HTTP traffic.  
  
2022-08-09T13:09:43.734692421Z: [INFO]  fail: Microsoft.AspNetCore.Server.Kestrel[13]  
  
2022-08-09T13:09:43.734750322Z: [INFO]        Connection id "0HMJQ101V7MO3", Request id "0HMJQ101V7MO3:00000002": An unhandled exception was thrown by the application.  
  
2022-08-09T13:09:43.735841144Z: [INFO]  System.InvalidOperationException: StatusCode cannot be set because the response has already started.  
  
2022-08-09T13:09:43.735857745Z: [INFO]     at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ThrowResponseAlreadyStartedException(String value)  
  
2022-08-09T13:09:43.736564059Z: [INFO]     at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.set_StatusCode(Int32 value)  
  
2022-08-09T13:09:43.736581860Z: [INFO]     at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.Microsoft.AspNetCore.Http.Features.IHttpResponseFeature.set_StatusCode(Int32 value)  
  
2022-08-09T13:09:43.736587560Z: [INFO]     at Microsoft.AspNetCore.Http.DefaultHttpResponse.set_StatusCode(Int32 value)  
  
2022-08-09T13:09:43.736592260Z: [INFO]     at Microsoft.Azure.AppService.Middleware.Forwarding.RequestForwarder.OnRequest(HttpContext context) in /EasyAuth/Middleware.Forwarding/RequestForwarder.cs:line 90  
  
2022-08-09T13:09:43.736840865Z: [INFO]     at Microsoft.Azure.AppService.Middleware.NetCore.AppServiceMiddleware.InvokeAsync(HttpContext context) in /EasyAuth/Microsoft.Azure.AppService.Middleware.NetCore/AppServiceMiddleware.cs:line 140  
  
2022-08-09T13:09:43.738523100Z: [INFO]     at Microsoft.Azure.AppService.MiddlewareShim.AutoHealing.AutoHealingMiddleware.Invoke(HttpContext context) in /EasyAuth/Middleware.Host/AutoHealing/AutoHealingMiddleware.cs:line 55  
  
2022-08-09T13:09:43.738557500Z: [INFO]     at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)  
  
2022-08-09T13:09:47.671874675Z: [ERROR]  127.0.0.1 -  09/Aug/2022:13:09:46 +0000 "GET /index.php" 200  
  
2022-08-09T13:10:08.974435654Z: [ERROR]  127.0.0.1 -  09/Aug/2022:13:10:08 +0000 "GET /index.php" 302  
  
2022-08-09T13:10:15.040348709Z: [ERROR]  127.0.0.1 -  09/Aug/2022:13:10:14 +0000 "HEAD /index.php" 302  
  
2022-08-09T13:10:16.359477056Z: [ERROR]  127.0.0.1 -  09/Aug/2022:13:10:16 +0000 "GET /index.php" 302  
  
2022-08-09T13:10:27.838754089Z: [ERROR]  127.0.0.1 -  09/Aug/2022:13:10:27 +0000 "GET /index.php" 302  
  
2022-08-09T13:10:41.709107871Z: [ERROR]  127.0.0.1 -  09/Aug/2022:13:10:41 +0000 "GET /index.php" 302  
  
2022-08-09T13:11:14.073137089Z: [INFO]  fail: Middleware[0]  
  
2022-08-09T13:11:14.074202512Z: [INFO]        Failed to forward request to http://169.254.129.4:8080. Encountered a System.IO.IOException exception after 65317.273ms with message: The response ended prematurely.. Check application logs to verify the application is properly handling HTTP traffic.  
  
2022-08-09T13:11:14.075365237Z: [INFO]  fail: Microsoft.AspNetCore.Server.Kestrel[13]  
  
2022-08-09T13:11:14.075398537Z: [INFO]        Connection id "0HMJQ101V7MO5", Request id "0HMJQ101V7MO5:00000001": An unhandled exception was thrown by the application.  
  
2022-08-09T13:11:14.075405337Z: [INFO]  System.InvalidOperationException: StatusCode cannot be set because the response has already started.  
  
2022-08-09T13:11:14.075421838Z: [INFO]     at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ThrowResponseAlreadyStartedException(String value)  
  
2022-08-09T13:11:14.075426238Z: [INFO]     at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.set_StatusCode(Int32 value)  
  
2022-08-09T13:11:14.075430538Z: [INFO]     at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.Microsoft.AspNetCore.Http.Features.IHttpResponseFeature.set_StatusCode(Int32 value)  
  
2022-08-09T13:11:14.075435138Z: [INFO]     at Microsoft.AspNetCore.Http.DefaultHttpResponse.set_StatusCode(Int32 value)  
  
2022-08-09T13:11:14.075439238Z: [INFO]     at Microsoft.Azure.AppService.Middleware.Forwarding.RequestForwarder.OnRequest(HttpContext context) in /EasyAuth/Middleware.Forwarding/RequestForwarder.cs:line 90  
  
2022-08-09T13:11:14.075443438Z: [INFO]     at Microsoft.Azure.AppService.Middleware.NetCore.AppServiceMiddleware.InvokeAsync(HttpContext context) in /EasyAuth/Microsoft.Azure.AppService.Middleware.NetCore/AppServiceMiddleware.cs:line 140  
  
2022-08-09T13:11:14.075447738Z: [INFO]     at Microsoft.Azure.AppService.MiddlewareShim.AutoHealing.AutoHealingMiddleware.Invoke(HttpContext context) in /EasyAuth/Middleware.Host/AutoHealing/AutoHealingMiddleware.cs:line 55  
  
2022-08-09T13:11:14.075451938Z: [INFO]     at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)  
  
2022-08-09T13:11:21.382398561Z: [INFO]  fail: Middleware[0]  
  
2022-08-09T13:11:21.383315481Z: [INFO]        Failed to forward request to http://169.254.129.4:8080. Encountered a System.IO.IOException exception after 65250.654ms with message: The response ended prematurely.. Check application logs to verify the application is properly handling HTTP traffic.  
  
2022-08-09T13:11:21.409675240Z: [INFO]  fail: Microsoft.AspNetCore.Server.Kestrel[13]  
  
2022-08-09T13:11:21.409706141Z: [INFO]        Connection id "0HMJQ101V7MO7", Request id "0HMJQ101V7MO7:00000003": An unhandled exception was thrown by the application.  
  
2022-08-09T13:11:21.411322575Z: [INFO]  System.InvalidOperationException: StatusCode cannot be set because the response has already started.  
  
2022-08-09T13:11:21.411342975Z: [INFO]     at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ThrowResponseAlreadyStartedException(String value)  
  
2022-08-09T13:11:21.411405277Z: [INFO]     at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.set_StatusCode(Int32 value)  
  
2022-08-09T13:11:21.411413577Z: [INFO]     at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.Microsoft.AspNetCore.Http.Features.IHttpResponseFeature.set_StatusCode(Int32 value)  
  
2022-08-09T13:11:21.411418577Z: [INFO]     at Microsoft.AspNetCore.Http.DefaultHttpResponse.set_StatusCode(Int32 value)  
  
2022-08-09T13:11:21.414006432Z: [INFO]     at Microsoft.Azure.AppService.Middleware.Forwarding.RequestForwarder.OnRequest(HttpContext context) in /EasyAuth/Middleware.Forwarding/RequestForwarder.cs:line 90  
  
2022-08-09T13:11:21.414050433Z: [INFO]     at Microsoft.Azure.AppService.Middleware.NetCore.AppServiceMiddleware.InvokeAsync(HttpContext context) in /EasyAuth/Microsoft.Azure.AppService.Middleware.NetCore/AppServiceMiddleware.cs:line 140  
  
2022-08-09T13:11:21.414058133Z: [INFO]     at Microsoft.Azure.AppService.MiddlewareShim.AutoHealing.AutoHealingMiddleware.Invoke(HttpContext context) in /EasyAuth/Middleware.Host/AutoHealing/AutoHealingMiddleware.cs:line 55  
  
2022-08-09T13:11:21.414062533Z: [INFO]     at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)  
  
2022-08-09T13:11:32.899838400Z: [INFO]  fail: Middleware[0]  
  
2022-08-09T13:11:32.900839428Z: [INFO]        Failed to forward request to http://169.254.129.4:8080. Encountered a System.IO.IOException exception after 65141.117ms with message: The response ended prematurely.. Check application logs to verify the application is properly handling HTTP traffic.  
  
2022-08-09T13:11:32.909000356Z: [INFO]  fail: Microsoft.AspNetCore.Server.Kestrel[13]  
  
2022-08-09T13:11:32.909052758Z: [INFO]        Connection id "0HMJQ101V7MO8", Request id "0HMJQ101V7MO8:00000002": An unhandled exception was thrown by the application.  
  
2022-08-09T13:11:32.910280192Z: [INFO]  System.InvalidOperationException: StatusCode cannot be set because the response has already started.  
  
2022-08-09T13:11:32.910308493Z: [INFO]     at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ThrowResponseAlreadyStartedException(String value)  
  
2022-08-09T13:11:32.910314793Z: [INFO]     at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.set_StatusCode(Int32 value)  
  
2022-08-09T13:11:32.910318993Z: [INFO]     at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.Microsoft.AspNetCore.Http.Features.IHttpResponseFeature.set_StatusCode(Int32 value)  
  
2022-08-09T13:11:32.910322993Z: [INFO]     at Microsoft.AspNetCore.Http.DefaultHttpResponse.set_StatusCode(Int32 value)  
  
2022-08-09T13:11:32.912468353Z: [INFO]     at Microsoft.Azure.AppService.Middleware.Forwarding.RequestForwarder.OnRequest(HttpContext context) in /EasyAuth/Middleware.Forwarding/RequestForwarder.cs:line 90  
  
2022-08-09T13:11:32.912486254Z: [INFO]     at Microsoft.Azure.AppService.Middleware.NetCore.AppServiceMiddleware.InvokeAsync(HttpContext context) in /EasyAuth/Microsoft.Azure.AppService.Middleware.NetCore/AppServiceMiddleware.cs:line 140  
  
2022-08-09T13:11:32.912491654Z: [INFO]     at Microsoft.Azure.AppService.MiddlewareShim.AutoHealing.AutoHealingMiddleware.Invoke(HttpContext context) in /EasyAuth/Middleware.Host/AutoHealing/AutoHealingMiddleware.cs:line 55  
  
2022-08-09T13:11:32.912496254Z: [INFO]     at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)  
  
2022-08-09T13:11:46.781256679Z: [INFO]  fail: Middleware[0]  
  
2022-08-09T13:11:46.783085521Z: [INFO]        Failed to forward request to http://169.254.129.4:8080. Encountered a System.IO.IOException exception after 65159.147ms with message: The response ended prematurely.. Check application logs to verify the application is properly handling HTTP traffic.  
  
2022-08-09T13:11:46.785448276Z: [INFO]  fail: Microsoft.AspNetCore.Server.Kestrel[13]  
  
2022-08-09T13:11:46.785523478Z: [INFO]        Connection id "0HMJQ101V7MO9", Request id "0HMJQ101V7MO9:00000002": An unhandled exception was thrown by the application.  
  
2022-08-09T13:11:46.787296519Z: [INFO]  System.InvalidOperationException: StatusCode cannot be set because the response has already started.  
  
2022-08-09T13:11:46.787314719Z: [INFO]     at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ThrowResponseAlreadyStartedException(String value)  
  
2022-08-09T13:11:46.787320519Z: [INFO]     at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.set_StatusCode(Int32 value)  
  
2022-08-09T13:11:46.787325419Z: [INFO]     at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.Microsoft.AspNetCore.Http.Features.IHttpResponseFeature.set_StatusCode(Int32 value)  
  
2022-08-09T13:11:46.787330019Z: [INFO]     at Microsoft.AspNetCore.Http.DefaultHttpResponse.set_StatusCode(Int32 value)  
  
2022-08-09T13:11:46.787342920Z: [INFO]     at Microsoft.Azure.AppService.Middleware.Forwarding.RequestForwarder.OnRequest(HttpContext context) in /EasyAuth/Middleware.Forwarding/RequestForwarder.cs:line 90  
  
2022-08-09T13:11:46.787348620Z: [INFO]     at Microsoft.Azure.AppService.Middleware.NetCore.AppServiceMiddleware.InvokeAsync(HttpContext context) in /EasyAuth/Microsoft.Azure.AppService.Middleware.NetCore/AppServiceMiddleware.cs:line 140  
  
2022-08-09T13:11:46.787371420Z: [INFO]     at Microsoft.Azure.AppService.MiddlewareShim.AutoHealing.AutoHealingMiddleware.Invoke(HttpContext context) in /EasyAuth/Middleware.Host/AutoHealing/AutoHealingMiddleware.cs:line 55  
  
2022-08-09T13:11:46.787379520Z: [INFO]     at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)  

Answer 5

Has there been any resolutions found for this issue.

I've been experiencing this issue for months now, throwing "Failed to forward request to http://xxx.xxx.xxx.xxx:8000. Encountered a System.Net.Http.HttpRequestException exception after 42045.407ms with message: An error occurred while sending the request.. Check application logs to verify the application is properly handling HTTP traffic."

For us, this occurs roughly once a way, but as we add more services to this app service, it is now starting to show more frequent.

App service is python 3.9, running a FastAPI app.

I've enabled logging against the app itself, and when this error occurs, there is no attempt against the API itself. The communication is lost between the docker layer and the app itself.