Add-on for Microsoft Office 365 Reporting Web Service 404 and 400 errors?

[stephanfreeman]

I am struggling to get the MS O365 reporting app working with OAuth. Here's the error in ta_ms_o365_reporting_ms_o365_message_trace_oauth.log:

2022-10-21 16:24:38,096 INFO pid=91299 tid=MainThread file=splunk_rest_client.py:_request_handler:99 | Use HTTP connection pooling
2022-10-21 16:24:38,097 DEBUG pid=91299 tid=MainThread file=binding.py:get:695 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/TA_MS_O365_... (body: {})
2022-10-21 16:24:38,100 DEBUG pid=91299 tid=MainThread file=connectionpool.py:_new_conn:975 | Starting new HTTPS connection (1): 127.0.0.1:8089
2022-10-21 16:24:38,122 DEBUG pid=91299 tid=MainThread file=connectionpool.py:_make_request:461 | https://127.0.0.1:8089 "GET /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/TA_MS_O365_Reporting_checkpointer HTTP/1.1" 200 5562
2022-10-21 16:24:38,123 DEBUG pid=91299 tid=MainThread file=binding.py:new_f:74 | Operation took 0:00:00.025611
2022-10-21 16:24:38,124 DEBUG pid=91299 tid=MainThread file=binding.py:get:695 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/ (body: {'count': -1, 'offset': 0, 'search': 'TA_MS_O365_Reporting_checkpointer'})
2022-10-21 16:24:38,136 DEBUG pid=91299 tid=MainThread file=connectionpool.py:_make_request:461 | https://127.0.0.1:8089 "GET /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/?count=-1&offset=0&search=TA_MS_O365_Reporting_checkpointer HTTP/1.1" 200 4714
2022-10-21 16:24:38,137 DEBUG pid=91299 tid=MainThread file=binding.py:new_f:74 | Operation took 0:00:00.013834
2022-10-21 16:24:38,141 DEBUG pid=91299 tid=MainThread file=binding.py:get:695 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/data/TA_MS_O365_Re... (body: {})
2022-10-21 16:24:38,149 DEBUG pid=91299 tid=MainThread file=connectionpool.py:_make_request:461 | https://127.0.0.1:8089 "GET /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/data/TA_MS_O365_Reporting_checkpointer/Testing_obj_checkpoint_oauth HTTP/1.1" 404 140
2022-10-21 16:24:38,151 DEBUG pid=91299 tid=MainThread file=base_modinput.py:log_debug:298 | _Splunk_ Start date: 2022-10-16 16:24:38.151205, End date: 2022-10-16 17:24:38.151205
2022-10-21 16:24:38,151 DEBUG pid=91299 tid=MainThread file=base_modinput.py:log_debug:298 | _Splunk_ message trace URL: https://reports.office365.com/ecp/reportingwebservice/reporting.svc/MessageTrace?$filter=StartDate eq datetime'2022-10-16T16:24:38.151205Z' and EndDate eq datetime'2022-10-16T17:24:38.151205Z'
2022-10-21 16:24:38,151 DEBUG pid=91299 tid=MainThread file=base_modinput.py:log_debug:298 | _Splunk_ Getting proxy server.
2022-10-21 16:24:38,151 INFO pid=91299 tid=MainThread file=setup_util.py:log_info:142 | Proxy is not enabled!
2022-10-21 16:24:38,154 DEBUG pid=91299 tid=MainThread file=connectionpool.py:_new_conn:975 | Starting new HTTPS connection (1): login.windows.net:443
2022-10-21 16:24:38,284 DEBUG pid=91299 tid=MainThread file=connectionpool.py:_make_request:461 | https://login.windows.net:443 "POST /[TENANT ID]/oauth2/token HTTP/1.1" 400 747
2022-10-21 16:24:38,290 ERROR pid=91299 tid=MainThread file=base_modinput.py:log_error:316 | Get error when collecting events.
Traceback (most recent call last):
File "/opt/splunk/etc/apps/TA-MS_O365_Reporting/lib/splunktaucclib/modinput_wrapper/base_modinput.py", line 140, in stream_events
self.collect_events(ew)
File "/opt/splunk/etc/apps/TA-MS_O365_Reporting/bin/ms_o365_message_trace_oauth.py", line 362, in collect_events
get_events_continuous(helper, ew)
File "/opt/splunk/etc/apps/TA-MS_O365_Reporting/bin/ms_o365_message_trace_oauth.py", line 98, in get_events_continuous
if 'value' in message_response:
TypeError: argument of type 'NoneType' is not iterable

I've highlighted the requests that got a HTTP repsonse code of 200 in blue, and the 404 and 400 errors in red.

If I use curl to access the URL with the 404 error I get:

<?xml version="1.0" encoding="UTF-8"?>
<response>
<messages>
<msg type="ERROR">Could not find object.</msg>
</messages>
</response>

It looks like this is trying to access a "storage" directory inside /opt/splunk/etc/apps/TA-MS_O365_Reporting, which doesn't exist

Looking at splunkd_access.log, when running curl, I get:

127.0.0.1 - splunk-system-user [21/Oct/2022:16:53:37.043 +0100] "GET /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/data/TA_MS_O365_Reporting_checkpointer/Testing_obj_checkpoint_oauth HTTP/1.1" 404 140 "-" "curl" - - - 5ms

What I've tried and checked:

• Splunk is running as the splunk user
• I've checked and reset the filesystem permissions for /opt/splunk
• I've deleted and recreated the inputs and the accounts
• I've deleted the app and re-installed, both through the CLI and Splunk Web

Things that are less likely to be related, but I've done anyway:

• I've created new credentials in Azure for my enterprise app
• I've checked the permissions in Azure and confirmed that the permissions have been correctly granted
• The enterprise app in Azure is in the Global Reader and Exchange Administrator roles

I'm out of ideas so any help is gratefully received! I'm giessing that resolving the 404 may resolve the 400 to.

Splunk v. 9.0.1

Splunk Add-on for Microsoft Office 365 Reporting Web Service v. 2.0.1

Ubuntu 20.04.5 LTS on VMware 7

20 CPUs, 24GB RAM

Thank you!

[jconger]

The 404 message about the checkpoint is not unexpected.  Here's why:

• When the input runs, it has to calculate a date range to ask for data from the API
• The start date in that range is calculated like this:
  • Look for a checkpoint value
  • If there is no checkpoint value, look for a start date specified in the input
  • If there is no start date specified on the input, use a date 5 days in the past
• Once a start date is identified, an end date is calculated by adding the number of minutes specified in the query window size
• Once data is collected, a checkpoint will be set to the largest time stamp seen during collection
  • When the input runs again to calculate a start date, the checkpoint value will be used

So, if you have never collected data, you'll get a 404 trying to retrieve a checkpoint that doesn't yet exist.

It looks like your query window size is set to 60 based on the logging messages.  This is typically okay in a production environment, but you may need to increase it if you're testing a low-volume environment.  I've seen this in dev/test environments and set the window to 1440 (24 hours) to ensure some data is retrieved.

[stephanfreeman]

Thanks for the reply! So, I've set a start date of 3 days ago, and increased the query size to 1440. And checked that there's been some mail sent or received in that window (there has) but I'm getting the same error:

<snip>

2022-10-31 09:28:00,492 INFO pid=89545 tid=MainThread file=splunk_rest_client.py:_request_handler:99 | Use HTTP connection pooling
2022-10-31 09:28:00,494 DEBUG pid=89545 tid=MainThread file=binding.py:get:695 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/TA_MS_O365_... (body: {})
2022-10-31 09:28:00,497 DEBUG pid=89545 tid=MainThread file=connectionpool.py:_new_conn:975 | Starting new HTTPS connection (1): 127.0.0.1:8089
2022-10-31 09:28:00,519 DEBUG pid=89545 tid=MainThread file=connectionpool.py:_make_request:461 | https://127.0.0.1:8089 "GET /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/TA_MS_O365_Reporting_checkpointer HTTP/1.1" 200 5562
2022-10-31 09:28:00,520 DEBUG pid=89545 tid=MainThread file=binding.py:new_f:74 | Operation took 0:00:00.026095
2022-10-31 09:28:00,521 DEBUG pid=89545 tid=MainThread file=binding.py:get:695 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/ (body: {'count': -1, 'offset': 0, 'search': 'TA_MS_O365_Reporting_checkpointer'})
2022-10-31 09:28:00,533 DEBUG pid=89545 tid=MainThread file=connectionpool.py:_make_request:461 | https://127.0.0.1:8089 "GET /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/?count=-1&offset=0&search=TA_MS_O365_Reporting_checkpointer HTTP/1.1" 200 4714
2022-10-31 09:28:00,534 DEBUG pid=89545 tid=MainThread file=binding.py:new_f:74 | Operation took 0:00:00.013241
2022-10-31 09:28:00,538 DEBUG pid=89545 tid=MainThread file=binding.py:get:695 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/data/TA_MS_O365_Re... (body: {})
2022-10-31 09:28:00,546 DEBUG pid=89545 tid=MainThread file=connectionpool.py:_make_request:461 | https://127.0.0.1:8089 "GET /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/data/TA_MS_O365_Reporting_checkpointer/Test_obj_checkpoint_oauth HTTP/1.1" 404 140
2022-10-31 09:28:00,548 DEBUG pid=89545 tid=MainThread file=base_modinput.py:log_debug:298 | _Splunk_ Start date: 2022-10-28 00:00:01, End date: 2022-10-29 00:00:01
2022-10-31 09:28:00,548 DEBUG pid=89545 tid=MainThread file=base_modinput.py:log_debug:298 | _Splunk_ message trace URL: https://reports.office365.com/ecp/reportingwebservice/reporting.svc/MessageTrace?$filter=StartDate eq datetime'2022-10-28T00:00:01Z' and EndDate eq datetime'2022-10-29T00:00:01Z'
2022-10-31 09:28:00,548 DEBUG pid=89545 tid=MainThread file=base_modinput.py:log_debug:298 | _Splunk_ Getting proxy server.
2022-10-31 09:28:00,548 INFO pid=89545 tid=MainThread file=setup_util.py:log_info:142 | Proxy is not enabled!
2022-10-31 09:28:00,551 DEBUG pid=89545 tid=MainThread file=connectionpool.py:_new_conn:975 | Starting new HTTPS connection (1): login.windows.net:443
2022-10-31 09:28:00,683 DEBUG pid=89545 tid=MainThread file=connectionpool.py:_make_request:461 | https://login.windows.net:443 "POST /71477e1d-2b72-4543-a318-e4b4a93b25c8/oauth2/token HTTP/1.1" 400 747
2022-10-31 09:28:00,688 ERROR pid=89545 tid=MainThread file=base_modinput.py:log_error:316 | Get error when collecting events.
Traceback (most recent call last):
File "/opt/splunk/etc/apps/TA-MS_O365_Reporting/lib/splunktaucclib/modinput_wrapper/base_modinput.py", line 140, in stream_events
self.collect_events(ew)
File "/opt/splunk/etc/apps/TA-MS_O365_Reporting/bin/ms_o365_message_trace_oauth.py", line 362, in collect_events
get_events_continuous(helper, ew)
File "/opt/splunk/etc/apps/TA-MS_O365_Reporting/bin/ms_o365_message_trace_oauth.py", line 98, in get_events_continuous
if 'value' in message_response:
TypeError: argument of type 'NoneType' is not iterable

</snip>

I thought I'd try this on a completely separate system with more mail flowing. I confirmed at least 250 messages in the period I've selected but I still get:

<snip>

2022-10-31 09:41:25,161 INFO pid=5298 tid=MainThread file=splunk_rest_client.py:_request_handler:99 | Use HTTP connection pooling
2022-10-31 09:41:25,162 DEBUG pid=5298 tid=MainThread file=binding.py:get:695 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/TA_MS_O365_... (body: {})
2022-10-31 09:41:25,163 DEBUG pid=5298 tid=MainThread file=connectionpool.py:_new_conn:941 | Starting new HTTPS connection (1): 127.0.0.1:8089
2022-10-31 09:41:25,166 DEBUG pid=5298 tid=MainThread file=connectionpool.py:_make_request:442 | https://127.0.0.1:8089 "GET /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/TA_MS_O365_Reporting_checkpointer HTTP/1.1" 200 5851
2022-10-31 09:41:25,167 DEBUG pid=5298 tid=MainThread file=binding.py:new_f:74 | Operation took 0:00:00.005282
2022-10-31 09:41:25,167 DEBUG pid=5298 tid=MainThread file=binding.py:get:695 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/ (body: {'count': -1, 'offset': 0, 'search': 'TA_MS_O365_Reporting_checkpointer'})
2022-10-31 09:41:25,171 DEBUG pid=5298 tid=MainThread file=connectionpool.py:_make_request:442 | https://127.0.0.1:8089 "GET /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/?count=-1&offset=0&search=TA_MS_O365_Reporting_checkpointer HTTP/1.1" 200 5003
2022-10-31 09:41:25,171 DEBUG pid=5298 tid=MainThread file=binding.py:new_f:74 | Operation took 0:00:00.004004
2022-10-31 09:41:25,172 DEBUG pid=5298 tid=MainThread file=binding.py:get:695 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/data/TA_MS_O365_Re... (body: {})
2022-10-31 09:41:25,174 DEBUG pid=5298 tid=MainThread file=connectionpool.py:_make_request:442 | https://127.0.0.1:8089 "GET /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/data/TA_MS_O365_Reporting_checkpointer/InstallationTechnology_obj_checkpoint_oauth HTTP/1.1" 404 140
2022-10-31 09:41:25,175 DEBUG pid=5298 tid=MainThread file=base_modinput.py:log_debug:298 | _Splunk_ Start date: 2022-10-27 00:00:01, End date: 2022-10-28 00:00:01
2022-10-31 09:41:25,175 DEBUG pid=5298 tid=MainThread file=base_modinput.py:log_debug:298 | _Splunk_ message trace URL: https://reports.office365.com/ecp/reportingwebservice/reporting.svc/MessageTrace?$filter=StartDate eq datetime'2022-10-27T00:00:01Z' and EndDate eq datetime'2022-10-28T00:00:01Z'
2022-10-31 09:41:25,175 DEBUG pid=5298 tid=MainThread file=base_modinput.py:log_debug:298 | _Splunk_ Getting proxy server.
2022-10-31 09:41:25,175 INFO pid=5298 tid=MainThread file=setup_util.py:log_info:142 | Proxy is not enabled!
2022-10-31 09:41:25,176 DEBUG pid=5298 tid=MainThread file=connectionpool.py:_new_conn:941 | Starting new HTTPS connection (1): login.windows.net:443
2022-10-31 09:41:25,303 DEBUG pid=5298 tid=MainThread file=connectionpool.py:_make_request:442 | https://login.windows.net:443 "POST /a323165a-9318-4e8b-9cf7-321bc355d592/oauth2/token HTTP/1.1" 400 758
2022-10-31 09:41:25,306 ERROR pid=5298 tid=MainThread file=base_modinput.py:log_error:316 | Get error when collecting events.
Traceback (most recent call last):
File "/mnt/hd2/splunk/etc/apps/TA-MS_O365_Reporting/lib/splunktaucclib/modinput_wrapper/base_modinput.py", line 140, in stream_events
self.collect_events(ew)
File "/opt/splunk/etc/apps/TA-MS_O365_Reporting/bin/ms_o365_message_trace_oauth.py", line 362, in collect_events
get_events_continuous(helper, ew)
File "/opt/splunk/etc/apps/TA-MS_O365_Reporting/bin/ms_o365_message_trace_oauth.py", line 98, in get_events_continuous
if 'value' in message_response:
TypeError: argument of type 'NoneType' is not iterable

</snip>

So, still can't get it to work...