search

microsoftgraph / msgraph-sdk-serviceissues

Tracks service issues for follow up.
5 stars 0 forks source link

[BUG Report] SUPER LARGE body appears when set "Prefer" header with "outlook.body-content-type=text" #42

Open Code2Life opened 3 years ago

Code2Life commented 3 years ago

Hi, I found a issue which cause huge performance impact while calling a simple HTTP Graph API to retrieve one single calendar event.

Expected behavior

If adding Prefer" header with "outlook.body-content-type=text" in request, the response should only retrieve small size of data, contains only basic text information of the calendar event

Actual behavior

There were more than 130MB data transit, cause hight CPU and I/O pressure (I think in both Microsoft serverside and our side), actual text data are very very very long meaningless unicodes string like following:

\u5c7b\u7472\u3166\u615c\u6564\u6c66\u6e61\u3167\u3230\u5c35\u6e61\u6973\u615c\u736e\u6369\u6770\u3231\u3235\u755c\u3163\u615c\u6564\u6666\u3133\u3035\u5c37\u6564\u6666\u5c30\u7473\u6873\u6466\u6362\u3368\u3531\u3630\u735c\u7374\u6668\u6f6c\u6863\u3133\u3035\u5c36\u7473\u6873\u6866\u6369\u3368\u3531\u3630\u735c\u7374\u6668\u6962\u3133\u3035\u5c37\u6564\u6c66\u6e61\u3167\u3330\u5c33\u6564\u6c66\u6e61\u6667\u3165\u3330\u5c33\u6874\u6d65\u6c65\u6e61\u3167\u3330\u5c33\u6874\u6d65\u6c65\u6e61\u6667\u3065\u745c\u6568\u656d\u616c\u676e\u7363\u7b30\u665c\u6e6f\u7474\u6c62\u5c7b\u3066\u665c\u6962\u6964\u5c20\u7266\u6d6f\u6e61\u665c\u6863\u7261\u6573\u3074\u665c\u7270\u3271\u5c7b\u5c2a\u6170\u6f6e\u6573\u3020\u3032\u3032\u3036\u3033

Steps to reproduce the behavior

The ID of the calendar event suffering this issue: ”AAMkADRhMGMxYjUyLTgyYjYtNDIwYS1iYjgyLTRiNjVmYjkxYWQxYQBGAAAAAAB5piFWeqIJTZB1v9qMUzfNBwBdbbNfzlsmR7vvrwsgwHvoAAABZJvuAAAHJU38s5RAT7JgxjwwB9pbAAXktfpzAAA=“

The time we send getItem request (UTC): 2020-12-08 18:02 ~ 2020-12-08 18:05

The way we send http request:

LinkedList<Option> requestOptions = new LinkedList<>();
requestOptions.add(new HeaderOption("Prefer", "outlook.body-content-type=text"));
graphServiceClient.me().events(changedEventId).buildRequest(requestOptions).get();

I don't know why a simple event could result in hundreds of MB data, I suspect it's a bug in Microsoft serverside, the implementation of handling response for text preferred requests.

MIchaelMainer commented 3 years ago

Do you have a requestId from the response headers that you can share with us?

baywet commented 3 years ago

Also, can you tell us which version of the SDK you are using? If not using latest (2.5.0 for this library and 1.0.5 for core) can you try the the latest versions and let us know if you're still experiencing this issue please?

Code2Life commented 3 years ago

@MIchaelMainer Hi, I managed to grab the Response object content from heapdump:

The request id is:
request-id: 97715ca3-c55f-43fd-b80d-46ce7e33e653 client-request-id: 2ce84b38-b605-4a4e-8def-78d0004fdd3f x-ms-ags-diagnostic: {"ServerInfo":{"DataCenter":"EastUS","Slice":"SliceC","Ring":"5","ScaleUnit":"004","RoleInstance":"AGSFE_IN_4"}}

image

@baywet The sdk version is microsoft-graph@2.3.2

I think it might not be SDK bug, i looked into the stacktrace, the HUGE response came from InputStream of Response, i suspected it was some fault on office365 server.

image

SDK Stack Trace:

"cal-task-18" prio=5 tid=156 RUNNABLE
    at java.io.Reader.read(Reader.java:99)
       Local Variable: java.io.InputStreamReader#1
       Local Variable: java.nio.HeapCharBuffer#6
    at java.util.Scanner.readInput(Scanner.java:804)
    at java.util.Scanner.next(Scanner.java:1369)
    at com.microsoft.graph.http.CoreHttpProvider.streamToString(CoreHttpProvider.java:562)
       Local Variable: java.util.Scanner#1
    at com.microsoft.graph.http.CoreHttpProvider.handleJsonResponse(CoreHttpProvider.java:531)
       Local Variable: class com.microsoft.graph.models.extensions.Event
       Local Variable: java.util.TreeMap#660
    at com.microsoft.graph.http.CoreHttpProvider.sendRequestInternal(CoreHttpProvider.java:448)
       Local Variable: java.io.BufferedInputStream#2
       Local Variable: com.microsoft.graph.http.CoreHttpProvider#1
       Local Variable: okhttp3.Response#1
    at com.microsoft.graph.http.CoreHttpProvider.send(CoreHttpProvider.java:220)
    at com.microsoft.graph.http.CoreHttpProvider.send(CoreHttpProvider.java:200)
    at com.microsoft.graph.http.BaseRequest.send(BaseRequest.java:345)
    at com.microsoft.graph.requests.extensions.EventRequest.get(EventRequest.java:75)
    at
Code2Life commented 3 years ago

btw, according to the screenshoot of heapdump above, the ContentLength from response is -1, it seems to be another abnormal behavior.

baywet commented 3 years ago

We did get a community contribution to improve this method's reliability (see microsoftgraph/msgraph-sdk-java#566) that was released with 2.4.1. Can you try with the latest version (2.5.0) and see if you still run into the issue please?

Code2Life commented 3 years ago

@baywet cool, I will try the new version

Code2Life commented 3 years ago

@baywet the new SDK version took no effect, HUGE response still exists. btw, we tried to remove the header: "Prefer" ="outlook.body-content-type=text", also no effect on this issue.

baywet commented 3 years ago

Thanks for trying with the newest version. We (the SDK team) don't have access to your tenant's data for obvious data ownership and privacy reasons. Do you have any visibility over why this message is 100+ MB in size? Any large picture that's inline? or a lot of pictures maybe? Can you access that message via OWA? if so does looking at the source of the message show anything in particular? Can you query that message using the graph explorer? Thanks!

Code2Life commented 3 years ago

You are welcome, but I couldn't access the data for privacy reasons, either, since it's a customer of our OAuth app. All info provided before were grabbed from logs and heapdump, I think it's enough because the request id and event ID were printed.

I plan to dismiss the responses of "Content-Length=-1" to avoid this issue, which caused high cpu consumption, though it might affect user experiences.

Code2Life commented 3 years ago

Could you please escalate the issue to serverside developers, to find out in what condition, the response gets Content-Length=-1 header ? I still suspect that the issue is caused by serverside, rather than SDK according to personal service development experiences.

baywet commented 3 years ago

We (the SDK team) have little access to backend logs and support tickets raised by customers are a higher priority than the ones we raise. It'd be much better if you (or the customer) raised a support ticket from the impacted tenant. Not only it'll grant the support team access to the logs of the tenant but also it will have a higher investigation priority. I'm going to transfer this issue to the service issues repository since it's not an issue with the SDK itself.

petrhollayms commented 7 months ago

Thank you for reporting this issue. This appears to be an issue or limitation with the service APIs. Unfortunately, as the Microsoft Graph SDK team, we do not have ownership of the APIs that are causing you issues. We invite you to create a question about the service API to Microsoft Q&A and tagged with one of the [microsoft-graph-*] tags, that way it will get routed to the appropriate team for them to triage:

https://aka.ms/msgraphsupport or directly https://aka.ms/askgraph

For now, we will close the issue on our side but feel free to open it in the relevant repository if you think the issue is specific to SDK. Please let us know if this helps!

Note: We will close this repository on April 19, 2024.