azure-search-openai-demo icon indicating copy to clipboard operation
azure-search-openai-demo copied to clipboard

Published 20 hours ago • verified publisher icon Azure-Samples

SyntaxError: Unexpected non-whitespace character after JSON at position 6

Open salvafuentes opened this issue 2 years ago • 15 comments

This issue is for a: (mark with an x)

- [x] bug report -> please search issues before submitting
- [ ] feature request
- [ ] documentation issue or request
- [ ] regression (a behavior that used to work and stopped in a new release)

Minimal steps to reproduce

run azd up, then ask a question

Any log messages given by the failure

"SyntaxError: Unexpected non-whitespace character after JSON at position 6" bug

Expected/desired behavior

an answer to the question made

OS and Version?

Windows 11.

azd version?

azd version 1.0.2 (commit 145e046b1ea9394bd4e1b1d539eb32e860d692fb)

Other details

I have only two files loaded, one in spanish and one in english that basically have the same content. I don't know if that could be part of the problem

salvafuentes avatar Jul 12 '23 21:07 salvafuentes

I've had this problem, if you wait to ask a question or refresh or redeploy, it usually works again.

hwan18 avatar Jul 13 '23 04:07 hwan18

I've had this problem, if you wait to ask a question or refresh or redeploy, it usually works again.

Yeah, that kinda works for me, but is there a way to never get that error?

salvafuentes avatar Jul 13 '23 15:07 salvafuentes

I'm seeing this all the time, there's a long pause while it's generating an answer and then after a period that can be minutes I see, SyntaxError: Unexpected non-whitespace character after JSON at position 6

for me it seems to have started after moving from text-davinci-003 to gpt-35-turbo.

SiPearson avatar Jul 19 '23 09:07 SiPearson

If you are seeing an error like that, it indicates the server experienced a runtime error. Please download the logs from App Service, per the instructions at the end of this blog post: http://blog.pamelafox.org/2023/06/tips-for-debugging-flask-deployments-to.html Please share the logs here if you need help interpreting them. Thanks!

pamelafox avatar Jul 21 '23 16:07 pamelafox

Thanks Pamala, this is what I'm seeing in the logs,

2023-07-24 15:25:41.823 +00:00 [Debug] Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets: Connection id "0HMS9E8G0217Q" received FIN. 2023-07-24 15:25:41.823 +00:00 [Debug] Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets: Connection id "0HMS9E8G0217Q" sending FIN because: "The client closed the connection." 2023-07-24 15:25:41.823 +00:00 [Debug] Microsoft.AspNetCore.Server.Kestrel.Connections: Connection id "0HMS9E8G0217Q" disconnecting.

2023-07-24 15:26:41.920 +00:00 [Error] Middleware: Failed to forward request to http://129.224.130.2:8000. Encountered a System.Threading.Tasks.TaskCanceledException exception after 300063.947ms with message: The request was canceled due to the configured HttpClient.Timeout of 300 seconds elapsing.. Check application logs to verify the application is properly handling HTTP traffic. 2023-07-24 15:26:42.044 +00:00 [Information] Microsoft.AspNetCore.Hosting.Diagnostics: Request finished HTTP/1.1 POST http://app-backend-5vhsfjkbddyfa.azurewebsites.net/chat application/json 249 - 0 - - 300188.7956ms 2023-07-24 15:26:42.050 +00:00 [Debug] Microsoft.AspNetCore.Server.Kestrel.Connections: Connection id "0HMS9E8G0217Q" stopped.

2023-07-24T15:26:41.921916956Z [41m[30mfail[39m[22m[49m: Middleware[0] 2023-07-24T15:26:41.922243255Z Failed to forward request to http://129.224.130.2:8000. Encountered a System.Threading.Tasks.TaskCanceledException exception after 300063.947ms with message: The request was canceled due to the configured HttpClient.Timeout of 300 seconds elapsing.. Check application logs to verify the application is properly handling HTTP traffic.

SiPearson avatar Jul 24 '23 15:07 SiPearson

Hm, that looks like the logs from outside the container, I'm looking for the logs from inside the container. If you downloaded the zip from Advanced Tools, look for the filename that has "default_docker" in it, as that usually has the most helpful logs. It should show the Oryx ASCII art and then startup process.

pamelafox avatar Jul 24 '23 16:07 pamelafox

Sorry, being dim! the Docker log is showing this for the time the issue occured this morning,

2023-07-25T09:50:38.713736353Z 169.254.130.8 - - [25/Jul/2023:09:50:38 +0000] "POST /chat HTTP/1.1" 200 10105 "https://app-backend-5vhsbjkb32tfw.azurewebsites.net/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/115.0.0.0 Safari/537.36 Edg/115.0.1901.183"

2023-07-25T10:00:42.062529156Z [2023-07-25 10:00:42 +0000] [68] [CRITICAL] WORKER TIMEOUT (pid:3887) 2023-07-25T10:00:42.140014626Z [2023-07-25 10:00:42 +0000] [3887] [INFO] Worker exiting (pid: 3887) 2023-07-25T10:00:43.142697844Z [2023-07-25 10:00:43 +0000] [68] [WARNING] Worker with pid 3887 was terminated due to signal 9 2023-07-25T10:00:43.327474634Z [2023-07-25 10:00:43 +0000] [4677] [INFO] Booting worker with pid: 4677

2023-07-25T10:00:58.722862021Z 169.254.130.8 - - [25/Jul/2023:10:00:58 +0000] "GET / HTTP/1.1" 200 0 "-" "AlwaysOn"

SiPearson avatar Jul 25 '23 10:07 SiPearson

@SiPearson How is it going with this? I don't see an error in the logs you posted most recently. Did you work it out?

pamelafox avatar Aug 04 '23 18:08 pamelafox

Hi Pamela, Thank you for your help on this below I have pasted some of the default_docker log file.

These lines seem to be the culprit responsible for the json error: 2023-07-31T15:43:54.113291100Z [2023-07-31 15:43:54 +0000] [70] [CRITICAL] WORKER TIMEOUT (pid:106) 2023-07-31T15:43:54.115633833Z [2023-07-31 15:43:54 +0000] [106] [INFO] Worker exiting (pid: 106) 2023-07-31T15:43:55.129290567Z [2023-07-31 15:43:55 +0000] [70] [WARNING] 2023-07-31T15:43:55.133172621Z [2023-07-31 15:43:55 +0000] [124] [INFO] Booting worker with pid: 124

2023-07-31T15:53:57.627068616Z [2023-07-31 15:53:57 +0000] [70] [CRITICAL] WORKER TIMEOUT (pid:124) 2023-07-31T15:53:57.629513951Z [2023-07-31 15:53:57 +0000] [124] [INFO] Worker exiting (pid: 124)

2023-07-31T15:53:58.642301626Z [2023-07-31 15:53:58 +0000] [70] [WARNING] Worker with pid 124 was terminated due to signal 9 2023-07-31T15:53:58.645619873Z [2023-07-31 15:53:58 +0000] [142] [INFO] Booting worker with pid: 142

2023-07-31T16:04:09.289819680Z [2023-07-31 16:04:09 +0000] [70] [CRITICAL] WORKER TIMEOUT (pid:142) 2023-07-31T16:04:09.292372615Z [2023-07-31 16:04:09 +0000] [142] [INFO] Worker exiting (pid: 142) 2023-07-31T16:04:10.304374847Z [2023-07-31 16:04:10 +0000] [70] [WARNING] Worker with pid 142 was terminated due to signal 9 2023-07-31T16:04:10.308201900Z [2023-07-31 16:04:10 +0000] [160] [INFO] Booting worker with pid: 160

so what causes the signal 9 and what is that means ?

appreciate your help.

2023-07-31T15:03:39.854387382Z _____
2023-07-31T15:03:39.854421983Z / _ \ __________ _________ ____
2023-07-31T15:03:39.854427583Z / /\ \__ / | _ __ _/ __ \ 2023-07-31T15:03:39.854431883Z / | / /| | /| | /\ / 2023-07-31T15:03:39.854435783Z _|__ /_____ _/ || __ > 2023-07-31T15:03:39.854440583Z / / / 2023-07-31T15:03:39.854444983Z A P P S E R V I C E O N L I N U X 2023-07-31T15:03:39.854448883Z 2023-07-31T15:03:39.854452683Z Documentation: http://aka.ms/webapp-linux 2023-07-31T15:03:39.854456883Z Python 3.10.11 2023-07-31T15:03:39.854460483Z Note: Any data outside '/home' is not persisted 2023-07-31T15:03:40.080740230Z Starting OpenBSD Secure Shell server: sshd. 2023-07-31T15:03:40.112741289Z App Command Line not configured, will attempt auto-detect 2023-07-31T15:03:40.180779965Z Starting periodic command scheduler: cron. 2023-07-31T15:03:40.180862667Z Launching oryx with: create-script -appPath /home/site/wwwroot -output /opt/startup/startup.sh -virtualEnvName antenv -defaultApp /opt/defaultsite 2023-07-31T15:03:40.189342488Z Found build manifest file at '/home/site/wwwroot/oryx-manifest.toml'. Deserializing it... 2023-07-31T15:03:40.193328445Z Build Operation ID:xxxxx 2023-07-31T15:03:40.194754266Z Oryx Version: 0.2.20230512.3, Commit: 00000000000, ReleaseTagName: 20230512.3 2023-07-31T15:03:40.194777466Z Output is compressed. Extracting it... 2023-07-31T15:03:40.196422890Z Extracting '/home/site/wwwroot/output.tar.gz' to directory '/tmp/0000'... 2023-07-31T15:03:42.402584148Z App path is set to '/tmp/000' 2023-07-31T15:03:42.472430150Z Detected an app based on Flask 2023-07-31T15:03:42.473619467Z Generating gunicorn command for 'app:app' 2023-07-31T15:03:42.519462325Z Writing output script to '/opt/startup/startup.sh' 2023-07-31T15:03:42.626273558Z Using packages from virtual environment antenv located at /tmp/0000/antenv. 2023-07-31T15:03:42.626310458Z Updated PYTHONPATH to '/opt/startup/app_logs:/tmp/0000/antenv/lib/python3.10/site-packages' 2023-07-31T15:03:43.024946279Z [2023-07-31 15:03:43 +0000] [70] [INFO] Starting gunicorn 20.1.0 2023-07-31T15:03:43.037551660Z [2023-07-31 15:03:43 +0000] [70] [INFO] Listening at: http://0.0.0.0:8000 (70) 2023-07-31T15:03:43.037584760Z [2023-07-31 15:03:43 +0000] [70] [INFO] Using worker: sync 2023-07-31T15:03:43.041084911Z [2023-07-31 15:03:43 +0000] [73] [INFO] Booting worker with pid: 73 2023-07-31T15:03:48.180946696Z 000.000.000.00 - - [31/Jul/2023:15:03:48 +0000] "GET /robots933456.txt HTTP/1.1" 404 207 "-" "HealthCheck/1.0" 2023-07-31T15:03:48.308181114Z 000.000.000.00 - - [31/Jul/2023:15:03:48 +0000] "GET /robots933456.txt HTTP/1.1" 404 207 "-" "HealthCheck/1.0" 2023-07-31T15:03:48.448564419Z 000.000.000.00 - - [31/Jul/2023:15:03:48 +0000] "GET / HTTP/1.1" 200 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36" 2023-07-31T15:03:48.448606120Z 000.000.000.00 - - [31/Jul/2023:15:03:48 +0000] "GET / HTTP/1.1" 200 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/000.0.0.0 Safari/537.36" 2023-07-31T15:03:48.450341245Z 000.000.000.00 - - [31/Jul/2023:15:03:48 +0000] "GET / HTTP/1.1" 200 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/000.0.0.0 Safari/537.36" 2023-07-31T15:03:48.454547305Z 000.000.000.00 - - [31/Jul/2023:15:03:48 +0000] "GET / HTTP/1.1" 200 0 "-" "ReadyForRequest/1.0 (LocalCache)" 2023-07-31T15:03:48.483570719Z 000.000.000.00 - - [31/Jul/2023:15:03:48 +0000] "GET / HTTP/1.1" 200 0 "-" "ReadyForRequest/1.0 (AppInit)" 2023-07-31T15:03:48.597256644Z 000.000.000.00 - - [31/Jul/2023:15:03:48 +0000] "GET /assets/index-0000000.css HTTP/1.1" 200 0 "https://addresstowebapp/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/000.0.0.0 Safari/537.36" 2023-07-31T15:03:48.606291773Z 000.000.000.00 - - [31/Jul/2023:15:03:48 +0000] "GET /assets/index-11111.js HTTP/1.1" 200 0 "https://addresstowebapp/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/000.0.0.0 Safari/537.36" 2023-07-31T15:03:48.623431418Z 000.000.000.00 - - [31/Jul/2023:15:03:48 +0000] "GET /assets/index-11111.js HTTP/1.1" 200 0 "https://addresstowebapp/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36" 2023-07-31T15:03:48.623475318Z 000.000.000.00 - - [31/Jul/2023:15:03:48 +0000] "GET /assets/index-0000000.css HTTP/1.1" 200 0 "https://addresstowebapp/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36" 2023-07-31T15:03:49.208335274Z 000.000.000.00 - - [31/Jul/2023:15:03:49 +0000] "GET /assets/index-11111.js HTTP/1.1" 200 0 "https://addresstowebapp/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/000.0.0.0 Safari/537.36" 2023-07-31T15:03:49.210728208Z 000.000.000.00 - - [31/Jul/2023:15:03:49 +0000] "GET /assets/index-0000000.css HTTP/1.1" 200 0 "https://addresstowebapp/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/000.0.0.0 Safari/537.36" 2023-07-31T15:03:49.404093471Z 000.000.000.00 - - [31/Jul/2023:15:03:49 +0000] "GET /favicon.ico HTTP/1.1" 200 0 "https://addresstowebapp/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36" 2023-07-31T15:03:49.691333675Z 000.000.000.00 - - [31/Jul/2023:15:03:49 +0000] "GET /favicon.ico HTTP/1.1" 200 0 "https://addresstowebapp/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36" 2023-07-31T15:03:50.636239676Z 000.000.000.00 - - [31/Jul/2023:15:03:50 +0000] "GET /favicon.ico HTTP/1.1" 200 0 "https://addresstowebapp/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/000.0.0.0 Safari/537.36"

2023-07-31T15:03:55.772088637Z 000.000.000.00 - - [31/Jul/2023:15:03:55 +0000] "GET / HTTP/1.1" 200 0 "-" "AlwaysOn"

2023-07-31T15:03:58.352338317Z 000.000.000.00 - - [31/Jul/2023:15:03:58 +0000] "POST /chat HTTP/1.1" 200 31071 "https://addresstowebapp/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/000.0.0.0 Safari/537.36" 2023-07-31T15:03:58.355375461Z 000.000.000.00 - - [31/Jul/2023:15:03:58 +0000] "GET / HTTP/1.1" 200 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/000.0.0.0 Safari/537.36" 2023-07-31T15:03:58.437558932Z 000.000.000.00 - - [31/Jul/2023:15:03:58 +0000] "GET / HTTP/1.1" 200 0 "-" "AlwaysOn" 2023-07-31T15:03:58.475783677Z 000.000.000.00 - - [31/Jul/2023:15:03:58 +0000] "GET /assets/index-11111.js HTTP/1.1" 200 0 "https://addresstowebapp/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/000.0.0.0 Safari/537.36" 2023-07-31T15:03:58.486421129Z 000.000.000.00 - - [31/Jul/2023:15:03:58 +0000] "GET /assets/index-0000000.css HTTP/1.1" 200 0 "https://addresstowebapp/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/000.0.0.0 Safari/537.36" 2023-07-31T15:03:59.152742328Z 000.000.000.00 - - [31/Jul/2023:15:03:59 +0000] "GET / HTTP/1.1" 200 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/000.0.0.0 Safari/537.36 Edg/115.0.000.000" 2023-07-31T15:03:59.259317547Z 000.000.000.00 - - [31/Jul/2023:15:03:59 +0000] "GET /assets/index-11111.js HTTP/1.1" 200 0 "https://addresstowebapp/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/000.0.0.0 Safari/537.36 Edg/000.0.0000.000" Chrome/000.0.0.0 Safari/537.36 Edg/000.000.000.0"

2023-07-31T15:16:05.059558380Z 000.000.000.0 - - [31/Jul/2023:15:16:05 +0000] "GET / HTTP/1.1" 304 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/000.0.0.0 Safari/537.36 Edg/000.000.000.0" 2023-07-31T15:16:05.167373492Z 000.000.000.0 - - [31/Jul/2023:15:16:05 +0000] "GET /assets/index-0000000.css HTTP/1.1" 304 0 "https://addresstowebapp/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/000.0.0.0 Safari/537.36 Edg/000.000.000.0" 2023-07-31T15:16:05.171238147Z 000.000.000.00 - - [31/Jul/2023:15:16:05 +0000] "GET /assets/index-11111.js HTTP/1.1" 304 0 "https://addresstowebapp/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/000.0.0.0 Safari/537.36 Edg/000.000.000.0" 2023-07-31T15:16:06.636998108Z 000.000.000.0 - - [31/Jul/2023:15:16:06 +0000] "GET / HTTP/1.1" 200 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/000.0.0.0 Safari/537.36 Edg/000.000.000.0" 2023-07-31T15:16:06.737535819Z 000.000.000.0 - - [31/Jul/2023:15:16:06 +0000] "GET /assets/index-0000000.css HTTP/1.1" 200 0 "https://addresstowebapp/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/000.0.0.0 Safari/537.36 Edg/115.0.0000.000"

2023-07-31T15:43:54.113291100Z [2023-07-31 15:43:54 +0000] [70] [CRITICAL] WORKER TIMEOUT (pid:106) 2023-07-31T15:43:54.115633833Z [2023-07-31 15:43:54 +0000] [106] [INFO] Worker exiting (pid: 106) 2023-07-31T15:43:55.129290567Z [2023-07-31 15:43:55 +0000] [70] [WARNING] 2023-07-31T15:43:55.133172621Z [2023-07-31 15:43:55 +0000] [124] [INFO] Booting worker with pid: 124

2023-07-31T15:53:57.627068616Z [2023-07-31 15:53:57 +0000] [70] [CRITICAL] WORKER TIMEOUT (pid:124) 2023-07-31T15:53:57.629513951Z [2023-07-31 15:53:57 +0000] [124] [INFO] Worker exiting (pid: 124)

2023-07-31T15:53:58.642301626Z [2023-07-31 15:53:58 +0000] [70] [WARNING] Worker with pid 124 was terminated due to signal 9 2023-07-31T15:53:58.645619873Z [2023-07-31 15:53:58 +0000] [142] [INFO] Booting worker with pid: 142

2023-07-31T16:04:09.289819680Z [2023-07-31 16:04:09 +0000] [70] [CRITICAL] WORKER TIMEOUT (pid:142) 2023-07-31T16:04:09.292372615Z [2023-07-31 16:04:09 +0000] [142] [INFO] Worker exiting (pid: 142) 2023-07-31T16:04:10.304374847Z [2023-07-31 16:04:10 +0000] [70] [WARNING] Worker with pid 142 was terminated due to signal 9 2023-07-31T16:04:10.308201900Z [2023-07-31 16:04:10 +0000] [160] [INFO] Booting worker with pid: 160

BitcoinCode avatar Aug 07 '23 12:08 BitcoinCode

I'm seeing the error as Salam by the look of it Pamela,

2023-07-25T10:00:42.062529156Z [2023-07-25 10:00:42 +0000] [68] [CRITICAL] WORKER TIMEOUT (pid:3887) 2023-07-25T10:00:42.140014626Z [2023-07-25 10:00:42 +0000] [3887] [INFO] Worker exiting (pid: 3887) 2023-07-25T10:00:43.142697844Z [2023-07-25 10:00:43 +0000] [68] [WARNING] Worker with pid 3887 was terminated due to signal 9

The same as above by the look of it, terminated due to a signal 9. When it fails the screen will sit there saying Generating Response for a long time, minutes before you get the error message. I've not revisited as I've had other work on and this is a bit of a side project, however I've just been given access to 4.0 so was going to spend some time on it again in the next week or so.

SiPearson avatar Aug 07 '23 12:08 SiPearson

Have you looked into my latest PR that ports to an async framework? https://github.com/Azure-Samples/azure-search-openai-demo/pull/503

Signal 9 may indicate its killing a worker that it thinks is unresponsive, which could happen with very long response times from the various API calls. Another thing to try is to pass a request_timeout to the ChatCompletion.create calls to limit how long they can take, so that a worker doesnt appear unresponsive.

pamelafox avatar Aug 08 '23 05:08 pamelafox

I'm getting this error frequently. Perhaps 1 in 5 calls. Do these logs help?

2023-08-09 07:45:51.847 +00:00 [Information] Microsoft.AspNetCore.Hosting.Diagnostics: Request starting HTTP/1.1 POST http://app-backend-insxh7kban436.azurewebsites.net/chat application/json 8409 2023-08-09 07:45:51.847 +00:00 [Trace] Middleware: Request came in on normal port, sending to normal target http://169.254.129.2:8000/chat 2023-08-09 07:45:51.847 +00:00 [Trace] Middleware: Forwarding request to http://169.254.129.2:8000/chat 2023-08-09 07:45:51.848 +00:00 [Debug] Microsoft.AspNetCore.Server.Kestrel: Connection id "0HMSOL4EAONHJ", Request id "0HMSOL4EAONHJ:00000006": started reading request body. 2023-08-09 07:45:51.848 +00:00 [Debug] Microsoft.AspNetCore.Server.Kestrel: Connection id "0HMSOL4EAONHJ", Request id "0HMSOL4EAONHJ:00000006": done reading request body. 2023-08-09 07:45:56.368 +00:00 [Trace] Middleware: Forwarded request finished in 4520.983ms 200 OK 2023-08-09 07:45:56.368 +00:00 [Debug] Microsoft.AspNetCore.Server.Kestrel.Connections: Connection id "0HMSOL4EAONHJ" completed keep alive response. 2023-08-09 07:45:56.368 +00:00 [Information] Microsoft.AspNetCore.Hosting.Diagnostics: Request finished HTTP/1.1 POST http://app-backend-insxh7kban436.azurewebsites.net/chat application/json 8409 - 200 17960 application/json 4521.7186ms 2023-08-09 07:46:19.259 +00:00 [Information] Microsoft.AspNetCore.Hosting.Diagnostics: Request starting HTTP/1.1 POST http://app-backend-insxh7kban436.azurewebsites.net/chat application/json 9083 2023-08-09 07:46:19.259 +00:00 [Trace] Middleware: Request came in on normal port, sending to normal target http://169.254.129.2:8000/chat 2023-08-09 07:46:19.259 +00:00 [Trace] Middleware: Forwarding request to http://169.254.129.2:8000/chat 2023-08-09 07:46:19.260 +00:00 [Debug] Microsoft.AspNetCore.Server.Kestrel: Connection id "0HMSOL4EAONHJ", Request id "0HMSOL4EAONHJ:00000007": started reading request body. 2023-08-09 07:46:19.260 +00:00 [Debug] Microsoft.AspNetCore.Server.Kestrel: Connection id "0HMSOL4EAONHJ", Request id "0HMSOL4EAONHJ:00000007": done reading request body. 2023-08-09T07:47:38 No new trace in the past 1 min(s). 2023-08-09T07:48:38 No new trace in the past 2 min(s). 2023-08-09T07:49:06.993141552Z ERROR:root:Exception in /chat 2023-08-09T07:49:06.993195254Z Traceback (most recent call last): 2023-08-09T07:49:06.993202254Z File "/tmp/8db989d0ee76ce4/antenv/lib/python3.10/site-packages/urllib3/connectionpool.py", line 536, in _make_request 2023-08-09T07:49:06.993206954Z response = conn.getresponse() 2023-08-09T07:49:06.993211954Z File "/tmp/8db989d0ee76ce4/antenv/lib/python3.10/site-packages/urllib3/connection.py", line 461, in getresponse 2023-08-09T07:49:06.993217054Z httplib_response = super().getresponse() 2023-08-09T07:49:06.993222054Z File "/opt/python/3.10.11/lib/python3.10/http/client.py", line 1375, in getresponse 2023-08-09T07:49:06.993227054Z response.begin() 2023-08-09T07:49:06.993231154Z File "/opt/python/3.10.11/lib/python3.10/http/client.py", line 318, in begin 2023-08-09T07:49:06.993235355Z version, status, reason = self._read_status() 2023-08-09T07:49:06.993239555Z File "/opt/python/3.10.11/lib/python3.10/http/client.py", line 279, in _read_status 2023-08-09T07:49:06.993244355Z line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1") 2023-08-09T07:49:06.993248355Z File "/opt/python/3.10.11/lib/python3.10/socket.py", line 705, in readinto 2023-08-09T07:49:06.993252555Z return self._sock.recv_into(b) 2023-08-09T07:49:06.993256855Z File "/opt/python/3.10.11/lib/python3.10/ssl.py", line 1274, in recv_into 2023-08-09T07:49:06.993261355Z return self.read(nbytes, buffer) 2023-08-09T07:49:06.993265955Z File "/opt/python/3.10.11/lib/python3.10/ssl.py", line 1130, in read 2023-08-09T07:49:06.993270355Z return self._sslobj.read(len, buffer) 2023-08-09T07:49:06.993274355Z TimeoutError: The read operation timed out 2023-08-09T07:49:06.993278455Z 2023-08-09T07:49:06.993282756Z The above exception was the direct cause of the following exception: 2023-08-09T07:49:06.993287156Z 2023-08-09T07:49:06.993291656Z Traceback (most recent call last): 2023-08-09T07:49:06.993295856Z File "/tmp/8db989d0ee76ce4/antenv/lib/python3.10/site-packages/requests/adapters.py", line 486, in send 2023-08-09T07:49:06.993301456Z resp = conn.urlopen( 2023-08-09T07:49:06.993305856Z File "/tmp/8db989d0ee76ce4/antenv/lib/python3.10/site-packages/urllib3/connectionpool.py", line 844, in urlopen 2023-08-09T07:49:06.993310456Z retries = retries.increment( 2023-08-09T07:49:06.993315456Z File "/tmp/8db989d0ee76ce4/antenv/lib/python3.10/site-packages/urllib3/util/retry.py", line 470, in increment 2023-08-09T07:49:06.993319956Z raise reraise(type(error), error, _stacktrace) 2023-08-09T07:49:06.993324056Z File "/tmp/8db989d0ee76ce4/antenv/lib/python3.10/site-packages/urllib3/util/util.py", line 39, in reraise 2023-08-09T07:49:06.993328657Z raise value 2023-08-09T07:49:06.993347357Z File "/tmp/8db989d0ee76ce4/antenv/lib/python3.10/site-packages/urllib3/connectionpool.py", line 790, in urlopen 2023-08-09T07:49:06.993351657Z response = self._make_request( 2023-08-09T07:49:06.993357657Z File "/tmp/8db989d0ee76ce4/antenv/lib/python3.10/site-packages/urllib3/connectionpool.py", line 538, in _make_request 2023-08-09T07:49:06.993361757Z self._raise_timeout(err=e, url=url, timeout_value=read_timeout) 2023-08-09T07:49:06.993365657Z File "/tmp/8db989d0ee76ce4/antenv/lib/python3.10/site-packages/urllib3/connectionpool.py", line 370, in _raise_timeout 2023-08-09T07:49:06.993370058Z raise ReadTimeoutError( 2023-08-09T07:49:06.993373858Z urllib3.exceptions.ReadTimeoutError: HTTPSConnectionPool(host='cog-insxh7kban436.openai.azure.com', port=443): Read timed out. (read timeout=600) 2023-08-09T07:49:06.993378658Z 2023-08-09T07:49:06.993385058Z During handling of the above exception, another exception occurred: 2023-08-09T07:49:06.993388758Z 2023-08-09T07:49:06.993392358Z Traceback (most recent call last): 2023-08-09T07:49:06.993396158Z File "/tmp/8db989d0ee76ce4/antenv/lib/python3.10/site-packages/openai/api_requestor.py", line 596, in request_raw 2023-08-09T07:49:06.993400358Z result = _thread_context.session.request( 2023-08-09T07:49:06.993404358Z File "/tmp/8db989d0ee76ce4/antenv/lib/python3.10/site-packages/requests/sessions.py", line 589, in request 2023-08-09T07:49:06.993408558Z resp = self.send(prep, **send_kwargs) 2023-08-09T07:49:06.993412658Z File "/tmp/8db989d0ee76ce4/antenv/lib/python3.10/site-packages/requests/sessions.py", line 703, in send 2023-08-09T07:49:06.993417159Z r = adapter.send(request, **kwargs) 2023-08-09T07:49:06.993421859Z File "/tmp/8db989d0ee76ce4/antenv/lib/python3.10/site-packages/requests/adapters.py", line 532, in send 2023-08-09T07:49:06.993426259Z raise ReadTimeout(e, request=request) 2023-08-09T07:49:06.993430759Z requests.exceptions.ReadTimeout: HTTPSConnectionPool(host='cog-insxh7kban436.openai.azure.com', port=443): Read timed out. (read timeout=600) 2023-08-09T07:49:06.993434659Z 2023-08-09T07:49:06.993438559Z The above exception was the direct cause of the following exception: 2023-08-09T07:49:06.993442559Z 2023-08-09T07:49:06.993446959Z Traceback (most recent call last): 2023-08-09T07:49:06.993450759Z File "/tmp/8db989d0ee76ce4/app.py", line 104, in chat 2023-08-09T07:49:06.993454759Z r = impl.run(request.json["history"], request.json.get("overrides") or {}) 2023-08-09T07:49:06.993458859Z File "/tmp/8db989d0ee76ce4/approaches/chatreadretrieveread.py", line 80, in run 2023-08-09T07:49:06.993463260Z chat_completion = openai.ChatCompletion.create( 2023-08-09T07:49:06.993467360Z File "/tmp/8db989d0ee76ce4/antenv/lib/python3.10/site-packages/openai/api_resources/chat_completion.py", line 25, in create 2023-08-09T07:49:06.993471860Z return super().create(*args, **kwargs) 2023-08-09T07:49:06.993482260Z File "/tmp/8db989d0ee76ce4/antenv/lib/python3.10/site-packages/openai/api_resources/abstract/engine_api_resource.py", line 153, in create 2023-08-09T07:49:06.993487160Z response, _, api_key = requestor.request( 2023-08-09T07:49:06.993492460Z File "/tmp/8db989d0ee76ce4/antenv/lib/python3.10/site-packages/openai/api_requestor.py", line 288, in request 2023-08-09T07:49:06.993496560Z result = self.request_raw( 2023-08-09T07:49:06.993500560Z File "/tmp/8db989d0ee76ce4/antenv/lib/python3.10/site-packages/openai/api_requestor.py", line 607, in request_raw 2023-08-09T07:49:06.993504860Z raise error.Timeout("Request timed out: {}".format(e)) from e 2023-08-09T07:49:06.993508861Z openai.error.Timeout: Request timed out: HTTPSConnectionPool(host='cog-insxh7kban436.openai.azure.com', port=443): Read timed out. (read timeout=600) 2023-08-09 07:49:29.925 +00:00 [Debug] Microsoft.AspNetCore.Server.Kestrel.Connections: Connection id "0HMSOL4EAONHL" accepted. 2023-08-09 07:49:29.925 +00:00 [Debug] Microsoft.AspNetCore.Server.Kestrel.Connections: Connection id "0HMSOL4EAONHL" started. 2023-08-09 07:49:29.925 +00:00 [Information] Microsoft.AspNetCore.Hosting.Diagnostics: Request starting HTTP/1.1 GET http://app-backend-insxh7kban436.azurewebsites.net/ - - 2023-08-09 07:49:29.925 +00:00 [Trace] Middleware: Request came in on normal port, sending to normal target http://169.254.129.2:8000/ 2023-08-09 07:49:29.925 +00:00 [Trace] Middleware: Forwarding request to http://169.254.129.2:8000/ 2023-08-09 07:49:29.928 +00:00 [Trace] Middleware: Forwarded request finished in 3.311ms 200 OK 2023-08-09 07:49:29.929 +00:00 [Debug] Microsoft.AspNetCore.Server.Kestrel.Connections: Connection id "0HMSOL4EAONHL" completed keep alive response. 2023-08-09 07:49:29.929 +00:00 [Information] Microsoft.AspNetCore.Hosting.Diagnostics: Request finished HTTP/1.1 GET http://app-backend-insxh7kban436.azurewebsites.net/ - - - 200 739 text/html;+charset=utf-8 3.8081ms 2023-08-09 07:50:19.261 +00:00 [Debug] Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets: Connection id "0HMSOL4EAONHJ" received FIN. 2023-08-09 07:50:19.261 +00:00 [Debug] Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets: Connection id "0HMSOL4EAONHJ" sending FIN because: "The client closed the connection." 2023-08-09 07:50:19.261 +00:00 [Debug] Microsoft.AspNetCore.Server.Kestrel.Connections: Connection id "0HMSOL4EAONHJ" disconnecting.

GitTxb2 avatar Aug 09 '23 07:08 GitTxb2

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this issue will be closed.

github-actions[bot] avatar Oct 09 '23 01:10 github-actions[bot]

Facing the same thing.

henriqueArrazao avatar Jul 08 '24 14:07 henriqueArrazao

Can you check the debugging guide here? https://github.com/Azure-Samples/azure-search-openai-demo/blob/main/docs/appservice.md

Then you can share the logs here if you need aid in interpreting the error reported on the server.

pamelafox avatar Jul 10 '24 20:07 pamelafox

Closing since this was likely a configuration bug, and we have better error handling now. Please consult debugging guide if you see an error like this.

pamelafox avatar Oct 04 '24 16:10 pamelafox