search

Azure / azure-sdk-for-net

This repository is for active development of the Azure SDK for .NET. For consumers of the SDK we recommend visiting our public developer docs at https://learn.microsoft.com/dotnet/azure/ or our versioned developer docs at https://azure.github.io/azure-sdk-for-net.
MIT License
5.53k stars 4.82k forks source link

[BUG] `AzureEventSourceListener` with `OpenAIClient` v1.0.0-beta.6 while streaming does not function correctly [robch] #38214

Open robch opened 1 year ago

robch commented 1 year ago

Library name and version

Azure.AI.OpenAI 1.0.0-beta.6

Describe the bug

When using AzureEventSourceListener(Action<EventWrittenEventArgs, string>, EventLevel), with OpenAIClient v1.0.0-beta.6 while streaming, I do not get the correct callback data representing the payload (duplicates or not enough chunks).

Expected behavior

My action to be called back for all the response chunks that are present and visible via Fiddler or via the IAsyncEnumerable interfaces. Fiddler always shows the full correct payload response. Use of IAsyncEnumerable via choice.GetMessageStreaming also shows the correct payload data...

Actual behavior

I never see all the data that should be sent via the EventSource. I either only see the first handful of chunks, or I see a chunk representing the first word, that is repeated many times.

Here are two logs that demonstrate what I'm sending and receiving:

[81985]: 75ms AI_DBG_TRACE_INFO: Request:0 Request [f3d2db8a-c46f-4551-86cf-7fccfe48179a] POST https://robch-openai.openai.azure.com/openai/deployments/robch-gpt35-turbo/chat/completions?api-version=2023-07-01-preview\r\nAccept:application/json\r\nContent-Type:application/json\r\nx-ms-client-request-id:f3d2db8a-c46f-4551-86cf-7fccfe48179a\r\nx-ms-return-client-request-id:true\r\nUser-Agent:azsdk-net-AI.OpenAI/1.0.0-beta.6 (.NET 7.0.9; Microsoft Windows 10.0.22621)\r\napi-key:REDACTED\r\nclient assembly: Azure.AI.OpenAI
[81985]: 79ms AI_DBG_TRACE_VERBOSE: RequestContentText:0 Request [f3d2db8a-c46f-4551-86cf-7fccfe48179a] content: {"messages":[{"role":"system","content":"You are an AI assistant that helps people find information regarding Azure AI."},{"role":"user","content":"tell me 5 animal jokes"}],"max_tokens":800,"temperature":0.7,"presence_penalty":0,"frequency_penalty":0,"stream":true}
[631466]: 794ms AI_DBG_TRACE_INFO: Response:0 Response [f3d2db8a-c46f-4551-86cf-7fccfe48179a] 200 OK (00.7s)\r\nCache-Control:no-cache, must-revalidate\r\nTransfer-Encoding:chunked\r\nAccess-Control-Allow-Origin:REDACTED\r\napim-request-id:REDACTED\r\nX-Content-Type-Options:REDACTED\r\nopenai-processing-ms:REDACTED\r\nx-ms-region:REDACTED\r\nx-accel-buffering:REDACTED\r\nX-Request-ID:REDACTED\r\nx-ms-client-request-id:f3d2db8a-c46f-4551-86cf-7fccfe48179a\r\nStrict-Transport-Security:REDACTED\r\nazureml-model-session:REDACTED\r\nazureml-model-group:REDACTED\r\nDate:Tue, 15 Aug 2023 14:41:07 GMT\r\nContent-Type:text/event-stream\r\n
[631860]: 799ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [f3d2db8a-c46f-4551-86cf-7fccfe48179a] content block 0: data: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"role":"assistant"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}},"content_filter_results":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Sure"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[631860]: 808ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [f3d2db8a-c46f-4551-86cf-7fccfe48179a] content block 1: data: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":","},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\nter_results":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Sure"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[631860]: 819ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [f3d2db8a-c46f-4551-86cf-7fccfe48179a] content block 2: data: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":" here"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\nresults":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Sure"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[631860]: 835ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [f3d2db8a-c46f-4551-86cf-7fccfe48179a] content block 3: data: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":" are"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n\nresults":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Sure"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[631860]: 861ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [f3d2db8a-c46f-4551-86cf-7fccfe48179a] content block 4: data: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":" "},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n}\n\n\nresults":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Sure"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[631860]: 875ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [f3d2db8a-c46f-4551-86cf-7fccfe48179a] content block 5: data: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"5"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n}\n\n\nresults":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Sure"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[631860]: 899ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [f3d2db8a-c46f-4551-86cf-7fccfe48179a] content block 6: data: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":" animal"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\nsults":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Sure"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[631860]: 916ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [f3d2db8a-c46f-4551-86cf-7fccfe48179a] content block 7: data: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":" jokes"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n\nsults":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Sure"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[631860]: 940ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [f3d2db8a-c46f-4551-86cf-7fccfe48179a] content block 8: data: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":" for"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n\n\n\nsults":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Sure"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[631860]: 957ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [f3d2db8a-c46f-4551-86cf-7fccfe48179a] content block 9: data: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":" you"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n\n\n\nsults":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Sure"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[631860]: 1010ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [f3d2db8a-c46f-4551-86cf-7fccfe48179a] content block 10: data: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":":\n\n"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n\n\nsults":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Sure"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[631860]: 1015ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [f3d2db8a-c46f-4551-86cf-7fccfe48179a] content block 11: data: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"1"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\nl}\n\n\n\nsults":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npWFTawa2WKPsaQH9oOjkgSlhKna","object":"chat.completion.chunk","created":1692110467,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Sure"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n

and 

[818791]: 891ms AI_DBG_TRACE_INFO: Request:0 Request [1bee95ac-33d6-4df7-90b3-cebe4e722794] POST https://robch-openai.openai.azure.com/openai/deployments/robch-gpt35-turbo/chat/completions?api-version=2023-07-01-preview\r\nAccept:application/json\r\nContent-Type:application/json\r\nx-ms-client-request-id:1bee95ac-33d6-4df7-90b3-cebe4e722794\r\nx-ms-return-client-request-id:true\r\nUser-Agent:azsdk-net-AI.OpenAI/1.0.0-beta.6 (.NET 7.0.9; Microsoft Windows 10.0.22621)\r\napi-key:REDACTED\r\nclient assembly: Azure.AI.OpenAI
[818791]: 895ms AI_DBG_TRACE_VERBOSE: RequestContentText:0 Request [1bee95ac-33d6-4df7-90b3-cebe4e722794] content: {"messages":[{"role":"system","content":"You are an AI assistant that helps people find information regarding Azure AI."},{"role":"user","content":"tell me a joke"}],"max_tokens":800,"temperature":0.7,"presence_penalty":0,"frequency_penalty":0,"stream":true}
[551960]: 1331ms AI_DBG_TRACE_INFO: Response:0 Response [1bee95ac-33d6-4df7-90b3-cebe4e722794] 200 OK (00.4s)\r\nCache-Control:no-cache, must-revalidate\r\nTransfer-Encoding:chunked\r\nAccess-Control-Allow-Origin:REDACTED\r\napim-request-id:REDACTED\r\nX-Content-Type-Options:REDACTED\r\nopenai-processing-ms:REDACTED\r\nx-ms-region:REDACTED\r\nx-accel-buffering:REDACTED\r\nX-Request-ID:REDACTED\r\nx-ms-client-request-id:1bee95ac-33d6-4df7-90b3-cebe4e722794\r\nStrict-Transport-Security:REDACTED\r\nazureml-model-session:REDACTED\r\nazureml-model-group:REDACTED\r\nDate:Tue, 15 Aug 2023 14:40:33 GMT\r\nContent-Type:text/event-stream\r\n
[908906]: 1336ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [1bee95ac-33d6-4df7-90b3-cebe4e722794] content block 0: data: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"role":"assistant"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}},"content_filter_results":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Why"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[908906]: 1346ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [1bee95ac-33d6-4df7-90b3-cebe4e722794] content block 1: data: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":" did"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n_results":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Why"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[908906]: 1389ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [1bee95ac-33d6-4df7-90b3-cebe4e722794] content block 2: data: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":" the"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n_results":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Why"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[908906]: 1413ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [1bee95ac-33d6-4df7-90b3-cebe4e722794] content block 3: data: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":" computer"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\nlts":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Why"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[908906]: 1470ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [1bee95ac-33d6-4df7-90b3-cebe4e722794] content block 4: data: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":" go"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\null}\n\nlts":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Why"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[908906]: 1490ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [1bee95ac-33d6-4df7-90b3-cebe4e722794] content block 5: data: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":" to"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\null}\n\nlts":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Why"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[908906]: 1533ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [1bee95ac-33d6-4df7-90b3-cebe4e722794] content block 6: data: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":" the"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\nll}\n\nlts":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Why"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[908906]: 1553ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [1bee95ac-33d6-4df7-90b3-cebe4e722794] content block 7: data: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":" doctor"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n\n\nlts":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Why"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[908906]: 1596ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [1bee95ac-33d6-4df7-90b3-cebe4e722794] content block 8: data: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"?"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\null}\n\n\n\nlts":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Why"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[908906]: 1617ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [1bee95ac-33d6-4df7-90b3-cebe4e722794] content block 9: data: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":" Because"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n\nlts":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Why"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[908906]: 1648ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [1bee95ac-33d6-4df7-90b3-cebe4e722794] content block 10: data: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":" it"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\nll}\n\n\nlts":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Why"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n
[908906]: 1683ms AI_DBG_TRACE_VERBOSE: ResponseContentTextBlock:0 Response [1bee95ac-33d6-4df7-90b3-cebe4e722794] content block 11: data: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":" had"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\nl}\n\n\nlts":{}}],"usage":null}\n\ndata: {"id":"chatcmpl-7npVhb3LwvLV28A7WG4Mz6gZFXFW3","object":"chat.completion.chunk","created":1692110433,"model":"gpt-35-turbo","choices":[{"index":0,"finish_reason":null,"delta":{"content":"Why"},"content_filter_result":{"error":{"code":"content_filter_error","message":"The contents are not filtered"}}}],"usage":null}\n\n

Reproduction Steps

code something like this:

_azureEventSourceListener = new AzureEventSourceListener((e, message) => EventSourceAiLoggerLog(e, message), System.Diagnostics.Tracing.EventLevel.Verbose);

var options = new OpenAIClientOptions();
options.Diagnostics.IsLoggingContentEnabled = true;
options.Diagnostics.IsLoggingEnabled = true;

var client = new OpenAIClient(new Uri(endpoint!), new AzureKeyCredential(key!), options);

and

private void EventSourceAiLoggerLog(EventWrittenEventArgs e, string message)
{
    message = message.Replace("\r", "\\r").Replace("\n", "\\n");
    Console.WriteLine($"{GetPrefix(message)}: {message}");
}

and 

var options = new ChatCompletionsOptions();

var systemPrompt = "You are an AI assistant that helps people find information regarding Azure AI.";
options.Messages.Add(new ChatMessage(ChatRole.System, systemPrompt);

var userPrompt = "Tell me a joke"; // "Tell me 5 animal jokes";
options.Messages.Add(new ChatMessage(ChatRole.User, userPrompt);

options.MaxTokens = 800;
options.Temperature = .7f;
options.FrequencyPenalty = 0.0f;
options.PresencePenalty = 0.0f;

and 

var response = await client.GetChatCompletionsStreamingAsync(deployment, options);

var completeResponse = string.Empty;
await foreach (var choice in response.Value.GetChoicesStreaming())
{
    await foreach (var message in choice.GetMessageStreaming())
    {
        var str = message.Content;
        if (string.IsNullOrEmpty(str)) continue;

        completeResponse = completeResponse + str;

        str = str.Replace("\n", "\n           ");
        Console.Write(str);
    }
    Console.WriteLine();
}

Environment

Windows 11 x64 latest public build (not insiders).

trrwilson commented 1 year ago

Note: this appears to be an issue with the built-in behavior of the event logger rather than a library-specific problem for OpenAI. I suspect this problem would reproduce in any parallel setup -- it may just be that the non-buffered text/event-stream used here is hitting a condition not previously exercised.

jsquire commented 1 year ago

@annelo-msft : I'm going to move this over to Core to that we can validate the scenario. Given that logging happens in Core, I don't believe there would be anything OpenAI specific here.