microsoftgraph / microsoft-graph-comms-samples

Microsoft Graph Communications Samples
MIT License
211 stars 236 forks source link

Callee could not be reached #752

Open j40903272 opened 3 months ago

j40903272 commented 3 months ago

Describe the issue Starting from last week, my bot cannot answer calls and will run into error "Callee could not be reached". I did not change the server for more than half year. I checked my connections and bot configurations, but everything seems fine. Can you tell me what might be the problem and how to fix this?

Expected behavior The bot to answer the call successfully.

Graph SDK (please complete the following information):

<PackageReference Include="Microsoft.Bot.Builder.Integration.AspNet.Core" Version="4.17.2" />
<PackageReference Include="Microsoft.CognitiveServices.Speech" Version="1.24.1" />
<PackageReference Include="Azure.Identity" Version="1.9.0" />
<PackageReference Include="Microsoft.Graph" Version="4.54.0" />
<PackageReference Include="Microsoft.Graph.Communications.Calls.Media" Version="1.2.0.7270" />
<PackageReference Include="Microsoft.Graph.Communications.Core" Version="1.2.0.7270" />
<PackageReference Include="Microsoft.Graph.Communications.Calls" Version="1.2.0.7270" />
<PackageReference Include="Microsoft.Skype.Bots.Media" Version="1.27.0.2-alpha" />
<PackageReference Include="System.Net.Http.Formatting.Extension" Version="5.2.3" />
<PackageReference Include="AdaptiveCards" Version="2.7.3" />
<PackageReference Include="AdaptiveCards.Templating" Version="1.3.1" />

Call ID 1a008480-2b3e-4c3e-b4d3-f04d5c0f8757 timestamp 1724125433

Logs

$>2024-08-20T03:30:46.6532057Z Info: CommunicationsClientExtensions.cs:158 LogAndCreateResponse
ScenarioId: 3ee52050-835e-4191-807c-570e172d8e19
AppId: 9bc53939-e548-42d6-8444-82005bed5c41
AppName: CallingBot
TransactionDirection: Incoming
TraceType: HttpResponse
ResponseTime: 22
request: POST http://localhost:3978/callback
response: 202 Accepted
headers:
  Client-Request-Id: 2397909a-addc-4484-a176-ad66f8ef6e75
  Scenario-Id: 3ee52050-835e-4191-807c-570e172d8e19
$>2024-08-20T03:30:46.6529454Z Info: CommunicationsClientExtensions.cs:156 LogAndCreateResponse
ScenarioId: 3ee52050-835e-4191-807c-570e172d8e19
AppId: 9bc53939-e548-42d6-8444-82005bed5c41
AppName: CallingBot
TransactionDirection: Incoming
TraceType: HttpRequest
request: POST http://localhost:3978/callback
headers:
  Accept: application/json
  Host: localhost:3978
  User-Agent: Microsoft-Skype/3.0,(Calling/1.0)
  Accept-Encoding: (redacted)
  Authorization: (redacted)
  Ms-Teams-Partition: (redacted)
  Ms-Teams-Region: (redacted)
  Ms-Teams-Ring: (redacted)
  X-Forwarded-For: (redacted)
  X-Forwarded-Host: bce6-52-184-85-143.ngrok-free.app
  X-Forwarded-Proto: https
  X-Microsoft-Skype-Chain-Id: 3ee52050-835e-4191-807c-570e172d8e19
  X-Microsoft-Skype-Message-Id: 2397909a-addc-4484-a176-ad66f8ef6e75
{
  "@odata.type": "#microsoft.graph.commsNotifications",
  "value": [
    {
      "@odata.type": "#microsoft.graph.commsNotification",
      "changeType": "Deleted",
      "resourceUrl": "/communications/calls/1a008480-2b3e-4c3e-b4d3-f04d5c0f8757",
      "resource": "/app/calls/1a008480-2b3e-4c3e-b4d3-f04d5c0f8757",
      "resourceData": {
        "@odata.type": "#microsoft.graph.call",
        "callbackUri": "https://bce6-52-184-85-143.ngrok-free.app/callback",
        "callChainId": "3ee52050-835e-4191-807c-570e172d8e19",
        "direction": "Incoming",
        "incomingContext": {
          "@odata.type": "#microsoft.graph.incomingContext",
          "sourceParticipantId": "f0c9a605-ecb7-4dd6-b1a6-fd4815dd9bf9"
        },
        "myParticipantId": "7b2fb7b2-5e1e-4982-8284-3d2fb165696d",
        "resultInfo": {
          "@odata.type": "#microsoft.graph.resultInfo",
          "code": 408,
          "message": "Callee could not be reached.",
          "subcode": 8544
        },
        "source": {
          "@odata.type": "#microsoft.graph.participantInfo",
          "endpointType": "Default",
          "identity": {
            "@odata.type": "#microsoft.graph.identitySet",
            "user": {
              "@odata.type": "#microsoft.graph.identity",
              "id": "4b75189b-c195-403b-bac4-bf03f2295ebc",
              "tenantId": "34f52fbd-4f7e-4551-baa6-228553fac9f1"
            }
          },
          "languageId": "en-US",
          "region": "apac",
          "id": "f0c9a605-ecb7-4dd6-b1a6-fd4815dd9bf9"
        },
        "state": "Terminated",
        "targets": [
          {
            "@odata.type": "#microsoft.graph.invitationParticipantInfo",
            "identity": {
              "@odata.type": "#microsoft.graph.identitySet",
              "application": {
                "@odata.type": "#microsoft.graph.identity",
                "id": "9bc53939-e548-42d6-8444-82005bed5c41"
              }
            },
            "endpointType": "(Generic: 9hgMb3WF)",
            "id": "7b2fb7b2-5e1e-4982-8284-3d2fb165696d",
            "region": "",
            "languageId": ""
          }
        ],
        "tenantId": "34f52fbd-4f7e-4551-baa6-228553fac9f1",
        "id": "1a008480-2b3e-4c3e-b4d3-f04d5c0f8757",
        "terminationReason": "(Generic: 9Sv8SlIq)",
        "mediaHostedRegion": "Unknown",
        "applicationMetadata": {
          "botData": {
            "isMultiParty": false,
            "applicationType": null
          }
        }
      }
    }
  ]
}
$>2024-08-20T03:30:35.5052349Z Error: Bot.cs:494 CallsOnIncoming
ScenarioId: 3ee52050-835e-4191-807c-570e172d8e19
CallId: 1a008480-2b3e-4c3e-b4d3-f04d5c0f8757
TenantId: 34f52fbd-4f7e-4551-baa6-228553fac9f1
AppId: 9bc53939-e548-42d6-8444-82005bed5c41
AppName: CallingBot
Caught an Exception running the task: Answering call 1a008480-2b3e-4c3e-b4d3-f04d5c0f8757 with scenario 3ee52050-835e-4191-807c-570e172d8e19.
exception: Code: UnknownError
Message: <!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01//EN""http://www.w3.org/TR/html4/strict.dtd">
<HTML><HEAD><TITLE>Bad Request</TITLE>
<META HTTP-EQUIV="Content-Type" Content="text/html; charset=us-ascii"></HEAD>
<BODY><h2>Bad Request - Request Too Long</h2>
<hr><p>HTTP Error 400. The size of the request headers is too long.</p>
</BODY></HTML>

Scenario Id: 3ee52050-835e-4191-807c-570e172d8e19
Inner error:
    AdditionalData:
    date: 2024-08-20T03:30:35
    request-id: 8f1fd730-c15b-4f70-a2c6-a39a0deee4b7
    client-request-id: 6b18715e-cfdf-49c1-b8d4-f5d9f8eb323a

Code: UnknownError
Message: <!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01//EN""http://www.w3.org/TR/html4/strict.dtd">
<HTML><HEAD><TITLE>Bad Request</TITLE>
<META HTTP-EQUIV="Content-Type" Content="text/html; charset=us-ascii"></HEAD>
<BODY><h2>Bad Request - Request Too Long</h2>
<hr><p>HTTP Error 400. The size of the request headers is too long.</p>
</BODY></HTML>

Inner error:
    AdditionalData:
    date: 2024-08-20T03:30:35
    request-id: 8f1fd730-c15b-4f70-a2c6-a39a0deee4b7
    client-request-id: 6b18715e-cfdf-49c1-b8d4-f5d9f8eb323a

StackTrace:    at Microsoft.Graph.Communications.Client.Transport.GraphAuthClient.ValidateResponseAsync(HttpResponseMessage response)
   at Microsoft.Graph.Communications.Client.Transport.GraphAuthClient.SendHttpRequestAsync[T1,T2](IGraphRequest`1 graphRequest, CancellationToken cancellationToken)
   at Microsoft.Graph.Communications.Client.Transport.GraphClientWrapper.ValidateAndWrapAsync[T](GraphClientContext context, Func`1 func)
$>2024-08-20T03:30:35.4967459Z Error: GraphAuthClient.cs:125 SendHttpRequestAsync
ScenarioId: 3ee52050-835e-4191-807c-570e172d8e19
AppId: 9bc53939-e548-42d6-8444-82005bed5c41
AppName: CallingBot
CallId: 1a008480-2b3e-4c3e-b4d3-f04d5c0f8757
TenantId: 34f52fbd-4f7e-4551-baa6-228553fac9f1
TransactionDirection: Outgoing
TraceType: HttpResponse
ResponseTime: 558
request: POST https://graph.microsoft.com/v1.0/communications/calls/1a008480-2b3e-4c3e-b4d3-f04d5c0f8757/microsoft.graph.answer
response: 400 BadRequest
headers:
  Transfer-Encoding: chunked
  Strict-Transport-Security: max-age=31536000
  request-id: 8f1fd730-c15b-4f70-a2c6-a39a0deee4b7
  client-request-id: 6b18715e-cfdf-49c1-b8d4-f5d9f8eb323a
  x-ms-ags-diagnostic: {"ServerInfo":{"DataCenter":"Korea Central","Slice":"E","Ring":"4","ScaleUnit":"002","RoleInstance":"SE1PEPF00000823"}}
  Date: Tue, 20 Aug 2024 03:30:35 GMT
  Content-Type: application/json
{
  "@odata.type": "#microsoft.graph.errorResponse",
  "error": {
    "@odata.type": "#microsoft.graph.error",
    "code": "UnknownError",
    "message": "<!DOCTYPE HTML PUBLIC \"-//W3C//DTD HTML 4.01//EN\"\"http://www.w3.org/TR/html4/strict.dtd\">\r\n<HTML><HEAD><TITLE>Bad Request</TITLE>\r\n<META HTTP-EQUIV=\"Content-Type\" Content=\"text/html; charset=us-ascii\"></HEAD>\r\n<BODY><h2>Bad Request - Request Too Long</h2>\r\n<hr><p>HTTP Error 400. The size of the request headers is too long.</p>\r\n</BODY></HTML>\r\n",
    "innererror": {
      "@odata.type": "#microsoft.graph.error",
      "date": "2024-08-20T03:30:35",
      "request-id": "8f1fd730-c15b-4f70-a2c6-a39a0deee4b7",
      "client-request-id": "6b18715e-cfdf-49c1-b8d4-f5d9f8eb323a"
    }
  }
}
$>2024-08-20T03:30:34.9356841Z Info: GraphAuthClient.cs:108 SendHttpRequestAsync
ScenarioId: 3ee52050-835e-4191-807c-570e172d8e19
AppId: 9bc53939-e548-42d6-8444-82005bed5c41
AppName: CallingBot
CallId: 1a008480-2b3e-4c3e-b4d3-f04d5c0f8757
TenantId: 34f52fbd-4f7e-4551-baa6-228553fac9f1
TransactionDirection: Outgoing
TraceType: HttpRequest
request: POST https://graph.microsoft.com/v1.0/communications/calls/1a008480-2b3e-4c3e-b4d3-f04d5c0f8757/microsoft.graph.answer
headers:
  Scenario-Id: 3ee52050-835e-4191-807c-570e172d8e19
  Client-Request-Id: 6b18715e-cfdf-49c1-b8d4-f5d9f8eb323a
  User-Agent: GraphCommunicationsClient-CallingBot/1.2.0.7270
  Authorization: (redacted)
  Content-Type: application/json; charset=utf-8
{
  "$id": "1",
  "callbackUri": "https://bce6-52-184-85-143.ngrok-free.app/callback",
  "mediaConfig": {
    "@odata.type": "#microsoft.graph.appHostedMediaConfig",
    "blob": "{\"mpUri\":null,\"mpHttpUri\":\"https://www.jobfsd.com:15616/MediaProcessor/v1\",\"audioRenderContexts\":[\"07c3cbd7-0176-4449-9b10-fa105397dd9c\"],\"videoRenderContexts\":[\"deac8fe7-e247-4720-92fe-fd3b6e64cda5\",\"edb96387-f419-4933-8b55-1c382b280346\",\"3ed53c0c-6ae0-4a57-aed3-cf5132170f66\",\"905497c5-3f2a-4f4c-aac3-66844b88f8bb\"],\"vbssRenderContexts\":[\"03991715-553e-46b9-94ea-11826f811d49\"],\"audioSourceContexts\":[\"5ea0f7d8-8bcf-4abb-9991-2fdf864b1bc6\"],\"videoSourceContexts\":[\"d4fd253b-1ff9-465a-af08-1eb9b2cb32be\"],\"vbssSourceContexts\":[\"3ba9a66c-d015-42d7-bd8a-1cfaa855a8a8\"],\"dataRenderContexts\":null,\"dataSourceContexts\":null,\"supportedAudioFormat\":\"Pcm16K\",\"videoSinkEncodingFormats\":[\"H264\",\"H264\",\"H264\",\"H264\"],\"vbssSinkEncodingFormats\":[\"H264\"],\"initialScreenSharingRole\":\"Viewer\",\"mpMediaSessionId\":\"577479ff-99cb-44f0-b81b-f99ff02b83c4\",\"regionAffinity\":null,\"skypeMediaBotsVersion\":\"1.27.0.0002\",\"mediaStackVersion\":\"2023.27.1.5\",\"mpVersion\":\"8.0.0.3354\",\"callId\":\"1a008480-2b3e-4c3e-b4d3-f04d5c0f8757\",\"targetFrameworkVersion\":\"net6.0\"}"
  },
  "acceptedModalities": [
    "Audio",
    "Video",
    "VideoBasedScreenSharing"
  ],
  "participantCapacity": 0
}
$>2024-08-20T03:30:33.9239946Z Info: CommunicationsClientExtensions.cs:158 LogAndCreateResponse
ScenarioId: 3ee52050-835e-4191-807c-570e172d8e19
AppId: 9bc53939-e548-42d6-8444-82005bed5c41
AppName: CallingBot
TransactionDirection: Incoming
TraceType: HttpResponse
ResponseTime: 2228
request: POST http://localhost:3978/callback
response: 202 Accepted
headers:
  Client-Request-Id: 687a9444-f767-47c3-b3cf-6dd696cf37f5
  Scenario-Id: 3ee52050-835e-4191-807c-570e172d8e19
$>2024-08-20T03:30:33.9133065Z Info: CommunicationsClientExtensions.cs:156 LogAndCreateResponse
ScenarioId: 3ee52050-835e-4191-807c-570e172d8e19
AppId: 9bc53939-e548-42d6-8444-82005bed5c41
AppName: CallingBot
TransactionDirection: Incoming
TraceType: HttpRequest
request: POST http://localhost:3978/callback
headers:
  Accept: application/json
  Host: localhost:3978
  User-Agent: Microsoft-Skype/3.0,(Calling/1.0)
  Accept-Encoding: (redacted)
  Authorization: (redacted)
  Ms-Teams-Partition: (redacted)
  Ms-Teams-Region: (redacted)
  Ms-Teams-Ring: (redacted)
  X-Forwarded-For: (redacted)
  X-Forwarded-Host: bce6-52-184-85-143.ngrok-free.app
  X-Forwarded-Proto: https
  X-Microsoft-Skype-Caller-Region: apac
  X-Microsoft-Skype-Chain-Id: 3ee52050-835e-4191-807c-570e172d8e19
  X-Microsoft-Skype-Message-Id: 687a9444-f767-47c3-b3cf-6dd696cf37f5
{
  "@odata.type": "#microsoft.graph.commsNotifications",
  "value": [
    {
      "@odata.type": "#microsoft.graph.commsNotification",
      "changeType": "Created",
      "resourceUrl": "/communications/calls/1a008480-2b3e-4c3e-b4d3-f04d5c0f8757",
      "resource": "/app/calls/1a008480-2b3e-4c3e-b4d3-f04d5c0f8757",
      "resourceData": {
        "@odata.type": "#microsoft.graph.call",
        "callbackUri": "https://bce6-52-184-85-143.ngrok-free.app/callback",
        "callChainId": "3ee52050-835e-4191-807c-570e172d8e19",
        "direction": "Incoming",
        "incomingContext": {
          "@odata.type": "#microsoft.graph.incomingContext",
          "sourceParticipantId": "f0c9a605-ecb7-4dd6-b1a6-fd4815dd9bf9"
        },
        "myParticipantId": "7b2fb7b2-5e1e-4982-8284-3d2fb165696d",
        "source": {
          "@odata.type": "#microsoft.graph.participantInfo",
          "endpointType": "Default",
          "identity": {
            "@odata.type": "#microsoft.graph.identitySet",
            "user": {
              "@odata.type": "#microsoft.graph.identity",
              "id": "4b75189b-c195-403b-bac4-bf03f2295ebc",
              "tenantId": "34f52fbd-4f7e-4551-baa6-228553fac9f1"
            }
          },
          "languageId": "en-US",
          "region": "apac",
          "id": "f0c9a605-ecb7-4dd6-b1a6-fd4815dd9bf9"
        },
        "state": "Incoming",
        "targets": [
          {
            "@odata.type": "#microsoft.graph.invitationParticipantInfo",
            "identity": {
              "@odata.type": "#microsoft.graph.identitySet",
              "application": {
                "@odata.type": "#microsoft.graph.identity",
                "id": "9bc53939-e548-42d6-8444-82005bed5c41"
              }
            },
            "endpointType": "(Generic: 9hgMb3WF)",
            "id": "7b2fb7b2-5e1e-4982-8284-3d2fb165696d",
            "region": "",
            "languageId": ""
          }
        ],
        "tenantId": "34f52fbd-4f7e-4551-baa6-228553fac9f1",
        "id": "1a008480-2b3e-4c3e-b4d3-f04d5c0f8757",
        "mediaHostedRegion": "Unknown",
        "applicationMetadata": {
          "botData": {
            "isMultiParty": false,
            "applicationType": null
          }
        }
      }
    }
  ]
}
ssulzer commented 3 months ago

In that particular call, there is an error with the bot's attempt to answer it:

Caught an Exception running the task: Answering call 1a008480-2b3e-4c3e-b4d3-f04d5c0f8757 with scenario 3ee52050-835e-4191-807c-570e172d8e19. exception: Code: UnknownError Message: <!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01//EN""http://www.w3.org/TR/html4/strict.dtd">

Bad Request

Bad Request - Request Too Long


HTTP Error 400. The size of the request headers is too long.

yundatsai commented 2 months ago

Hi, do you know what may cause the problem? I have not change any of the code for a long while but this suddenly came up starting two weeks ago. And there is only one sdk function call for the 'CallsOnIncoming'. How can i troubleshoot? should i capture the request and look at the header? is it possible that the ngrok causing the header size problem while redirecting?

private void CallsOnIncoming(ICallCollection sender, CollectionEventArgs<ICall> args)
{
    try
    {
        args.AddedResources.ForEach(async call =>
        {
            if (!CallHandlers.ContainsKey(call.Id))
            {
                CallHandler callHandler = null;
                try
                {

                    var mediaSession = Guid.TryParse(call.Id, out Guid callId)
                        ? this.CreateLocalMediaSession(callId)
                        : this.CreateLocalMediaSession();

                    // Answer call and start video playback
                    await call?.AnswerAsync(mediaSession).ForgetAndLogExceptionAsync(
                        call.GraphLogger,
                        $"Answering call {call.Id} with scenario {call.ScenarioId}.");

                    call.GraphLogger.Info($"Call creation complete: {call.Id}");
                    Logger2.LogError($"Call creation complete: {call.Id}");
                }
                catch (Exception)
                {
                    // clean up
                    callHandler?.Dispose();
                    throw;
                }
            }
        });
    }
    catch (Exception ex)
    {
        Logger2.LogError("AnswerAsync Failed");
        Logger2.LogError(ex.ToString());
    }
    Logger2.LogError("Complete CallsOnIncoming");
}
yundatsai commented 2 months ago

@ssulzer may I ask where causes the header size too long error? Is it when the sdk tries to answer the call but the remote refuses? How can i trouble shoot this issue since I am only answering the call with await call?.AnswerAsync(mediaSession)

ssulzer commented 2 months ago

@jackry @jackry2023

yundatsai commented 2 months ago

Hi @ssulzer , the problem seems to be resolved after I removed some of the bot application permission and remain only the necessary ones. I suspect that the bot api permissions are all put inside the header and causes the problem. Hope this can be fixed in the future.

ssulzer commented 2 months ago

Hi @yundatsai What bot api permissions did you remove?

j40903272 commented 2 months ago

I removed all of the api permission and add back the necessary permission (6 of them). I did not record what permission exactly. But from the error shown "header length too long", I would suspect that it is about the amount of api permission that cause the problem. I had > 40 api permission for my bot account when the error happened.