aiohttp.web_exceptions.HTTPNotFound: Not Found

[pablomarin]

Versions

botbuilder-core-4.14.7
botbuilder-integration-aiohttp-4.14.7
botbuilder-schema-4.14.7
botframework-connector-4.14.7
botframework-streaming-4.14.7

Describe the bug

When deploying the bot, this error message/warning shows constantly:

/home/LogFiles/2023_12_14_lw1ldlwk00003Y_default_docker.log (https://webapp-backend-botid-munzn7fvelbuy.scm.azurewebsites.net/api/vfs/LogFiles/2023_12_14_lw1ldlwk00003Y_default_docker.log)
2023-12-14T17:41:28.187782798Z raise self._http_exception
2023-12-14T17:41:28.187786398Z aiohttp.web_exceptions.HTTPNotFound: Not Found
2023-12-14T17:46:28.293964145Z Traceback (most recent call last):
2023-12-14T17:46:28.294010945Z File "/tmp/8dbfbfd4367d347/antenv/lib/python3.10/site-packages/botbuilder/core/integration/aiohttp_channel_service_exception_middleware.py", line 20, in aiohttp_error_middleware
2023-12-14T17:46:28.294018945Z response = await handler(request)
2023-12-14T17:46:28.294023045Z File "/tmp/8dbfbfd4367d347/antenv/lib/python3.10/site-packages/aiohttp/web_urldispatcher.py", line 931, in _handle
2023-12-14T17:46:28.294027545Z raise self._http_exception
2023-12-14T17:46:28.294031445Z aiohttp.web_exceptions.HTTPNotFound: Not Found
/home/LogFiles/2023_12_14_lw1ldlwk00003Y_docker.log (https://webapp-backend-botid-munzn7fvelbuy.scm.azurewebsites.net/api/vfs/LogFiles/2023_12_14_lw1ldlwk00003Y_docker.log)
2023-12-14T13:20:56.577Z INFO -
/home/LogFiles/2023_12_14_lw1ldlwk00003Y_easyauth_docker.log (https://webapp-backend-botid-munzn7fvelbuy.scm.azurewebsites.net/api/vfs/LogFiles/2023_12_14_lw1ldlwk00003Y_easyauth_docker.log)
Ending Log Tail of existing logs ---Starting Live Log Stream ---
2023-12-14T17:46:28.293964145Z Traceback (most recent call last):
2023-12-14T17:46:28.294010945Z File "/tmp/8dbfbfd4367d347/antenv/lib/python3.10/site-packages/botbuilder/core/integration/aiohttp_channel_service_exception_middleware.py", line 20, in aiohttp_error_middleware
2023-12-14T17:46:28.294018945Z response = await handler(request)
2023-12-14T17:46:28.294023045Z File "/tmp/8dbfbfd4367d347/antenv/lib/python3.10/site-packages/aiohttp/web_urldispatcher.py", line 931, in _handle
2023-12-14T17:46:28.294027545Z raise self._http_exception
2023-12-14T17:46:28.294031445Z aiohttp.web_exceptions.HTTPNotFound: Not Found

See attachment.

I can confirm that happens to every single customer. that uses this accelerator:
https://github.com/MSUSAzureAccelerators/Azure-Cognitive-Search-Azure-OpenAI-Accelerator/tree/main

this the code for the app.py and bot.py:
https://github.com/MSUSAzureAccelerators/Azure-Cognitive-Search-Azure-OpenAI-Accelerator/blob/main/apps/backend/app.py
https://github.com/MSUSAzureAccelerators/Azure-Cognitive-Search-Azure-OpenAI-Accelerator/blob/main/apps/backend/bot.py

[Schiiss]

Hello Team! Also experiencing the issue on my side leveraging botbuilder-integration-aiohttp-4.14.7.

[7crabs]

It seems that this issue might be related to the 'Always On' feature in App Service. When 'Always On' is enabled, the front-end load balancer sends a GET request to the application's root every five minutes.

For more details, please refer to:
https://learn.microsoft.com/en-us/azure/app-service/configure-common?tabs=portal#tabpanel_5_portal

[matichudnik]

Hey everyone!
I'm experiencing the same issue, first thought it was a port/configuration issue but that unfortunately wasn't the case.
Does this have any impact on the bot and its replies?

[tracyboehrer]

@7crabs The only thing the bot responds to is POST's to /api/messages. Anything else should result in a 404 since there isn't handler for it. I tested some random GET's to a Python bot, and it doesn't produce this error.

[tracyboehrer]

Does anyone have information on what the request consisted of?

[7crabs]

@7crabs The only thing the bot responds to is POST's to /api/messages. Anything else should result in a 404 since there isn't handler for it. I tested some random GET's to a Python bot, and it doesn't produce this error.

@tracyboehrer, I'm curious about whether your tests were conducted with the botbuilder-core version 4.14.8. There was an update between versions 4.14.7 and 4.14.8 that changed how exceptions are handled. Specifically, aiohttp.web_exceptions.HTTPNotFound exceptions started being caught as HTTPException, preventing traceback.print_exc() from being executed for these errors. This change is detailed in the code diff available here: 4.14.7...4.14.8#diff-b9264a3f51d764c05859a1334fef387f03eef3308afdf5ad0d1d567fd329fbf1R31

To further investigate, I modified the 02.echo-bot sample from the BotBuilder-Samples repository by adding botbuilder-core==4.14.7 to the requirements.txt. I then deployed it to App Service with Always On and App Service logs enabled. This reproduced similar error logs as initially reported, confirming that the behavior is consistent with the 4.14.7 version:

2024-03-20T15:28:32.505Z INFO  - Initiating warmup request to container testbotbuilder20240320_0_e00ae23b for site testbotbuilder20240320
2024-03-20T15:28:43.696Z INFO  - Container testbotbuilder20240320_0_e00ae23b for site testbotbuilder20240320 initialized successfully and is ready to serve requests.
2024-03-20T15:28:30.514638591Z    _____
2024-03-20T15:28:30.514729692Z   /  _  \ __________ _________   ____
2024-03-20T15:28:30.514735992Z  /  /_\  \\___   /  |  \_  __ \_/ __ \
2024-03-20T15:28:30.514739192Z /    |    \/    /|  |  /|  | \/\  ___/
2024-03-20T15:28:30.514764292Z \____|__  /_____ \____/ |__|    \___  >
2024-03-20T15:28:30.514768893Z         \/      \/                  \/
2024-03-20T15:28:30.514771793Z A P P   S E R V I C E   O N   L I N U X
2024-03-20T15:28:30.514774693Z
2024-03-20T15:28:30.514777393Z Documentation: http://aka.ms/webapp-linux
2024-03-20T15:28:30.514780093Z Python 3.10.13
2024-03-20T15:28:30.514782893Z Note: Any data outside '/home' is not persisted
2024-03-20T15:28:34.122711682Z Starting OpenBSD Secure Shell server: sshd.
2024-03-20T15:28:34.344169927Z Site's appCommandLine: python3.10 app.py
2024-03-20T15:28:34.345873845Z Launching oryx with: create-script -appPath /home/site/wwwroot -output /opt/startup/startup.sh -virtualEnvName antenv -defaultApp /opt/defaultsite -userStartupCommand 'python3.10 app.py'
2024-03-20T15:28:34.404153462Z Found build manifest file at '/home/site/wwwroot/oryx-manifest.toml'. Deserializing it...
2024-03-20T15:28:34.413674362Z Build Operation ID: 7208310e55de2660
2024-03-20T15:28:34.414188968Z Oryx Version: 0.2.20240127.1, Commit: 4b7f2dffcc69c214f9806d67a85ec8926e2393e1, ReleaseTagName: 20240127.1
2024-03-20T15:28:34.415884486Z Output is compressed. Extracting it...
2024-03-20T15:28:34.424281075Z Extracting '/home/site/wwwroot/output.tar.gz' to directory '/tmp/8dc48f1a7634078'...
2024-03-20T15:28:38.597051063Z App path is set to '/tmp/8dc48f1a7634078'
2024-03-20T15:28:38.736200549Z Writing output script to '/opt/startup/startup.sh'
2024-03-20T15:28:38.878806572Z Using packages from virtual environment antenv located at /tmp/8dc48f1a7634078/antenv.
2024-03-20T15:28:38.878835572Z Updated PYTHONPATH to '/opt/startup/app_logs:/tmp/8dc48f1a7634078/antenv/lib/python3.10/site-packages'
2024-03-20T15:28:43.687531641Z Traceback (most recent call last):
2024-03-20T15:28:43.687960645Z   File "/tmp/8dc48f1a7634078/antenv/lib/python3.10/site-packages/botbuilder/core/integration/aiohttp_channel_service_exception_middleware.py", line 20, in aiohttp_error_middleware
2024-03-20T15:28:43.687972945Z     response = await handler(request)
2024-03-20T15:28:43.687977346Z   File "/tmp/8dc48f1a7634078/antenv/lib/python3.10/site-packages/aiohttp/web_urldispatcher.py", line 931, in _handle
2024-03-20T15:28:43.687980746Z     raise self._http_exception
2024-03-20T15:28:43.687983746Z aiohttp.web_exceptions.HTTPNotFound: Not Found
2024-03-20T15:30:38  No new trace in the past 1 min(s).
2024-03-20T15:31:38  No new trace in the past 2 min(s).
2024-03-20T15:32:15.590645942Z Traceback (most recent call last):
2024-03-20T15:32:15.590680643Z   File "/tmp/8dc48f1a7634078/antenv/lib/python3.10/site-packages/botbuilder/core/integration/aiohttp_channel_service_exception_middleware.py", line 20, in aiohttp_error_middleware
2024-03-20T15:32:15.590698743Z     response = await handler(request)
2024-03-20T15:32:15.590702243Z   File "/tmp/8dc48f1a7634078/antenv/lib/python3.10/site-packages/aiohttp/web_urldispatcher.py", line 931, in _handle
2024-03-20T15:32:15.590705843Z     raise self._http_exception
2024-03-20T15:32:15.590708943Z aiohttp.web_exceptions.HTTPNotFound: Not Found

[tracyboehrer]

@7crabs I'll check that out.