Message trace log ingestion failure in the Splunk Add-on for Microsoft Office 365 due to 'too many 500 error responses'

Applicability

Description

Multiple users reported failures in ingesting Message Trace logs using the Splunk Add-on for Microsoft Office 365. This issue persists across various configurations where users have set query window sizes under 60 minutes. Analysis shows that the ingestion process fails when the add-on receives an incorrect @odata.nextLink URL in the response from Microsoft’s API, leading to repeated HTTP 500 errors.

Log analysis confirms that the add-on initiates data collection correctly and iterates over the paginated results. Microsoft typically includes a nextLink URL to retrieve subsequent pages, but occasionally provides a malformed or incorrect URL. These faulty URLs deviate from the expected format (.../reportingwebservice/reporting.svc/MessageTrace) and instead point to an incomplete or invalid endpoint, causing the ingestion process to fail with a "Max retries exceeded" error.

This behavior appears intermittent but consistent in all failing instances, rendering the ingestion process unreliable and incomplete.

Investigation

While reviewing the issue and applying an SPL query for investigation:

index=_internal datainput=<input name> ERROR

1. For the fresh data collection of particular time window, add-on makes the API call and starts the data collection.
   
   
2. Please note that in single page, microsoft only provides 2000 messages along with the nextlink to access the further pages of the response.
   
   
3. Add-on iterates over 2-3 pages and intermittently gets the wrong nextlink url from microsoft which won't provide any response and results into 500 server error.

After running the SPL search, the following error has been reported along with an explanation for error inspection and understanding:

"2025-05-03 06:05:59,854 level=INFO pid=11562 tid=MainThread logger=splunk_ta_o365.modinputs.message_trace pos=__init__.py:_get_events_continuous:228 | datainput=""sbux_o365_messagetrace"" start_time=1746252322 | message=""Collecting the data between Start date: 2025-05-02 14:32:55.331956, End date: 2025-05-02 14:37:55.331956""
"2025-05-03 06:06:03,554 level=DEBUG pid=11562 tid=MainThread logger=splunk_ta_o365.modinputs.message_trace pos=__init__.py:_process_messages:466 | datainput=""sbux_o365_messagetrace"" start_time=1746252322 | message=""nextLink URL (@odata.nextLink): https://reports.office365.com/ecp/reportingwebservice/reporting.svc/MessageTrace?$filter=StartDate%20eq%20datetime'2025-05-02T14%3A32%3A55.331956Z'%20and%20EndDate%20eq%20datetime'2025-05-02T14%3A37%3A55.331956Z'&$skiptoken=1999"" ",
"2025-05-03 06:06:08,726 level=DEBUG pid=11562 tid=MainThread logger=splunk_ta_o365.modinputs.message_trace pos=__init__.py:_process_messages:466 | datainput=""sbux_o365_messagetrace"" start_time=1746252322 | message=""nextLink URL (@odata.nextLink): https://reports.office365.com/ecp/reportingwebservice/reporting.svc/MessageTrace?$filter=StartDate%20eq%20datetime'2025-05-02T14%3A32%3A55.331956Z'%20and%20EndDate%20eq%20datetime'2025-05-02T14%3A37%3A55.331956Z'&$skiptoken=3999"" ",
"2025-05-03 06:06:13,853 level=DEBUG pid=11562 tid=MainThread logger=splunk_ta_o365.modinputs.message_trace pos=__init__.py:_process_messages:466 | datainput=""sbux_o365_messagetrace"" start_time=1746252322 | message=""nextLink URL (@odata.nextLink): https://reports.office365.com/ecp/MessageTrace?$filter=StartDate%20eq%20datetime'2025-05-02T14%3A32%3A55.331956Z'%20and%20EndDate%20eq%20datetime'2025-05-02T14%3A37%3A55.331956Z'&$skiptoken=5999"" ",
"2025-05-03 06:06:19,995 level=ERROR pid=11562 tid=MainThread logger=splunk_ta_o365.modinputs.message_trace pos=__init__.py:run:588 | datainput=""sbux_o365_messagetrace"" start_time=1746252322 | message=""An error occurred while collecting data"" stack_info=True
ERROR_TRACEBACK
requests.exceptions.RetryError: HTTPSConnectionPool(host='reports.office365.com', port=443): Max retries exceeded with url: /ecp/MessageTrace?$filter=StartDate%20eq%20datetime'2025-05-02T14%3A32%3A55.331956Z'%20and%20EndDate%20eq%20datetime'2025-05-02T14%3A37%3A55.331956Z'&$skiptoken=5999 (Caused by ResponseError('too many 500 error responses'))",

• The received nextLink is printed in the debug log with the prefix: "nextLink URL (@odata.nextLink):
  
  
• Based on the logs, the add-on initiated data collection between 2025-05-02 14:32:55.331956 and 2025-05-02 14:37:55.331956. A nextLink was received for the second page:
  https://reports.office365.com/ecp/reportingwebservice/reporting.svc/MessageTrace?$filter=...&$skiptoken=1999.
  
  
• The data from this page was successfully collected, and a nextLink for the third page was obtained:
  https://reports.office365.com/ecp/reportingwebservice/reporting.svc/MessageTrace?$filter=...&$skiptoken=3999.
  
  
• Again, the data from this page was successfully collected, resulting in the following nextLink for the fourth page:
  https://reports.office365.com/ecp/MessageTrace?$filter=...&$skiptoken=5999, which caused a 500 server error.
  
  
• Generally, nextlink url would be something like ../../reportingwebservice/reporting.svc/MessageTrace?$filter= in the @odata.nextLinkparameter of the response. Hence, to make a call, we remove the ../../ from the response's nextlink and add base url https://reports.office365.com/ecp/ .
  
  
• However, in the problematic instance, ignoring the base URL reveals that the nextLink starts with MessageTrace?$filter=... instead of the expected
  reportingwebservice/reporting.svc/MessageTrace?$filter=....
  
  
• This suggests that Microsoft intermittently returns an incorrectly formatted nextLink URL in the response, which leads to 500 Internal Server Errors. Similar anomalies were observed in nearly all error instances found in the provided log file.

Here's the another example:

"2025-05-02 03:55:00,174 level=INFO pid=30478 tid=MainThread logger=splunk_ta_o365.modinputs.message_trace pos=__init__.py:_get_events_continuous:229 | datainput=b'sbux_o365_messagetrace' start_time=1746158099 | message=""Collecting the data between Start date: 2025-05-02 02:47:55.331956, End date: 2025-05-02 02:52:55.331956""
"2025-05-02 03:55:00,517 level=INFO pid=30478 tid=MainThread logger=splunk_ta_o365.common.portal pos=portal.py:get_messagetrace_token_by_psk:258 | datainput=b'sbux_o365_messagetrace' start_time=1746158099 | message=""Acquire access token success."" expires_on=1746161699.5169265"
"2025-05-02 03:55:03,839 level=DEBUG pid=30478 tid=MainThread logger=splunk_ta_o365.modinputs.message_trace pos=__init__.py:_process_messages:464 | datainput=b'sbux_o365_messagetrace' start_time=1746158099 | message=""nextLink URL (@odata.nextLink): https://reports.office365.com/ecp/reportingwebservice/reporting.svc/MessageTrace?$filter=StartDate%20eq%20datetime'2025-05-02T02%3A47%3A55.331956Z'%20and%20EndDate%20eq%20datetime'2025-05-02T02%3A52%3A55.331956Z'&$skiptoken=1999"" "
"2025-05-02 03:55:12,066 level=DEBUG pid=30478 tid=MainThread logger=splunk_ta_o365.modinputs.message_trace pos=__init__.py:_process_messages:464 | datainput=b'sbux_o365_messagetrace' start_time=1746158099 | message=""nextLink URL (@odata.nextLink): https://reports.office365.com/ecp/MessageTrace?$filter=StartDate%20eq%20datetime'2025-05-02T02%3A47%3A55.331956Z'%20and%20EndDate%20eq%20datetime'2025-05-02T02%3A52%3A55.331956Z'&$skiptoken=3999"" "
ERROR: Max retries exceeded with url: /ecp/MessageTrace?$filter=StartDate%20eq%20datetime'2025-05-02T02%3A47%3A55.331956Z'%20and%20EndDate%20eq%20datetime'2025-05-02T02%3A52%3A55.331956Z'&$skiptoken=3999 (Caused by ResponseError('too many 500 error responses'))"

• Data collection started, successful for first and second page, 500 error for third page's nextlink.
  
  
• next link of second page: https://reports.office365.com/ecp/reportingwebservice/reporting.svc/MessageTrace?$filter.....
  
  
• next link of third page:  https://reports.office365.com/ecp/MessageTrace?$filter......

Resolution

The issue stems from the Microsoft API returning inconsistent or malformed @odata.nextLink values. As this behavior originates from the upstream service, it is recommended to reduce the query_window_size. This adjustment will decrease the data load in each chunk and minimize the number of pages to skip in the event of a failure.