Microsoft Office 365 Reporting Add-on not obeying interval configuration

becksyboy — Mon, 23 Nov 2020 16:53:44 GMT

Hi,

we are using version 1.2.4 on Splunk 7.3.7, and we noticed our interval setting of (interval=600 / 10 mins) is not being obeyed. We can see when it does make a successful connection and pull the logs, we see at the start of the connection "HTTP connection pooling" in the logs. However, what we see subsequently are continuous connections every minute or so. We tried a splunk restart to see if this made a difference but it hasn't changed it's behaviour. So now we see connections from every 30-40 mins or longer.

Below is an example of the logs:

2020-11-23 15:42:12,824 INFO pid=32193 tid=MainThread file=splunk_rest_client.py:_request_handler:105 | Use HTTP connection pooling
2020-11-23 15:42:12,824 DEBUG pid=32193 tid=MainThread file=binding.py:get:677 | GET request to https://127.0.0.1:9001/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/TA_MS_O365_Reporting_checkpointer (body: {})
2020-11-23 15:42:12,826 DEBUG pid=32193 tid=MainThread file=connectionpool.py:_new_conn:959 | Starting new HTTPS connection (1): 127.0.0.1:9001
2020-11-23 15:42:12,834 DEBUG pid=32193 tid=MainThread file=connectionpool.py:_make_request:437 | https://127.0.0.1:9001 "GET /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/TA_MS_O365_Reporting_checkpointer HTTP/1.1" 200 5509
2020-11-23 15:42:12,835 DEBUG pid=32193 tid=MainThread file=binding.py:new_f:73 | Operation took 0:00:00.010786
2020-11-23 15:42:12,836 DEBUG pid=32193 tid=MainThread file=binding.py:get:677 | GET request to https://127.0.0.1:9001/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/ (body: {'count': -1, 'search': 'TA_MS_O365_Reporting_checkpointer', 'offset': 0})
2020-11-23 15:42:12,842 DEBUG pid=32193 tid=MainThread file=connectionpool.py:_make_request:437 | https://127.0.0.1:9001 "GET /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/?count=-1&search=TA_MS_O365_Reporting_checkpointer&offset=0 HTTP/1.1" 200 7403
2020-11-23 15:42:12,844 DEBUG pid=32193 tid=MainThread file=binding.py:new_f:73 | Operation took 0:00:00.007860
2020-11-23 15:42:12,852 DEBUG pid=32193 tid=MainThread file=binding.py:get:677 | GET request to https://127.0.0.1:9001/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/data/TA_MS_O365_Reporting_checkpointer/index_continuously_obj_checkpoint (body: {})
2020-11-23 15:42:12,857 DEBUG pid=32193 tid=MainThread file=connectionpool.py:_make_request:437 | https://127.0.0.1:9001 "GET /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/data/TA_MS_O365_Reporting_checkpointer/index_continuously_obj_checkpoint HTTP/1.1" 200 128
2020-11-23 15:42:12,857 DEBUG pid=32193 tid=MainThread file=binding.py:new_f:73 | Operation took 0:00:00.005903
2020-11-23 15:42:12,858 DEBUG pid=32193 tid=MainThread file=base_modinput.py:log_debug:288 | _Splunk_ Start date: 2020-11-23 14:21:59.057785, End date: 2020-11-23 14:31:59.057785
2020-11-23 15:42:12,858 DEBUG pid=32193 tid=MainThread file=base_modinput.py:log_debug:288 | Endpoint URL: https://reports.office365.com/ecp/reportingwebservice/reporting.svc/MessageTrace?\$filter=StartDate eq datetime'2020-11-23T14:21:59.057785Z' and EndDate eq datetime'2020-11-23T14:31:59.057785Z'
2020-11-23 15:42:12,863 DEBUG pid=32193 tid=MainThread file=connectionpool.py:_new_conn:959 | Starting new HTTPS connection (1): reports.office365.com:443
2020-11-23 15:42:16,000 DEBUG pid=32193 tid=MainThread file=connectionpool.py:_make_request:437 | https://reports.office365.com:443 "GET /ecp/reportingwebservice/reporting.svc/MessageTrace?%5C$filter=StartDate%20eq%20datetime'2020-11-23T14:21:59.057785Z'%20and%20EndDate%20eq%20datetime'2020-11-23T14:31:59.057785Z' HTTP/1.1" 200 None
2020-11-23 15:42:16,073 DEBUG pid=32193 tid=MainThread file=base_modinput.py:log_debug:288 | _Splunk_ max date before getting message: 2020-11-23 14:21:59.057785
2020-11-23 15:42:16,893 DEBUG pid=32193 tid=MainThread file=base_modinput.py:log_debug:288 | _Splunk_ max date after getting messages: 2020-11-23 15:41:50.582546
2020-11-23 15:42:16,894 DEBUG pid=32193 tid=MainThread file=binding.py:post:750 | POST request to https://127.0.0.1:9001/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/data/TA_MS_O365_Reporting_checkpointer/batch_save (body: {'body': '[{"state": "{\\"max_date\\": \\"2020-11-23 15:41:50.582546\\"}", "_key": "index_continuously_obj_checkpoint"}]'})
2020-11-23 15:42:16,926 DEBUG pid=32193 tid=MainThread file=connectionpool.py:_make_request:437 | https://127.0.0.1:9001 "POST /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/data/TA_MS_O365_Reporting_checkpointer/batch_save HTTP/1.1" 200 39
2020-11-23 15:42:16,928 DEBUG pid=32193 tid=MainThread file=binding.py:new_f:73 | Operation took 0:00:00.033994
2020-11-23 15:42:16,928 DEBUG pid=32193 tid=MainThread file=base_modinput.py:log_debug:288 | _Splunk_ nextLink URL (@odata.nextLink): https://reports.office365.com/ecp/reportingwebservice/reporting.svc/MessageTrace?$skiptoken=1999
2020-11-23 15:42:16,928 DEBUG pid=32193 tid=MainThread file=base_modinput.py:log_debug:288 | Endpoint URL: https://reports.office365.com/ecp/reportingwebservice/reporting.svc/MessageTrace?$skiptoken=1999
2020-11-23 15:42:16,932 DEBUG pid=32193 tid=MainThread file=connectionpool.py:_new_conn:959 | Starting new HTTPS connection (1): reports.office365.com:443
2020-11-23 15:42:18,938 DEBUG pid=32193 tid=MainThread file=connectionpool.py:_make_request:437 | https://reports.office365.com:443 "GET /ecp/reportingwebservice/reporting.svc/MessageTrace?$skiptoken=1999 HTTP/1.1" 200 None
2020-11-23 15:42:19,777 DEBUG pid=32193 tid=MainThread file=base_modinput.py:log_debug:288 | _Splunk_ max date after getting messages: 2020-11-23 15:41:50.582546
2020-11-23 15:42:19,778 DEBUG pid=32193 tid=MainThread file=binding.py:post:750 | POST request to https://127.0.0.1:9001/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/data/TA_MS_O365_Reporting_checkpointer/batch_save (body: {'body': '[{"state": "{\\"max_date\\": \\"2020-11-23 15:41:50.582546\\"}", "_key": "index_continuously_obj_checkpoint"}]'})
2020-11-23 15:42:19,827 DEBUG pid=32193 tid=MainThread file=connectionpool.py:_make_request:437 | https://127.0.0.1:9001 "POST /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/data/TA_MS_O365_Reporting_checkpointer/batch_save HTTP/1.1" 200 39
2020-11-23 15:42:19,829 DEBUG pid=32193 tid=MainThread file=binding.py:new_f:73 | Operation took 0:00:00.051431
2020-11-23 15:42:19,830 DEBUG pid=32193 tid=MainThread file=base_modinput.py:log_debug:288 | _Splunk_ nextLink URL (@odata.nextLink): https://reports.office365.com/ecp/reportingwebservice/reporting.svc/MessageTrace?$skiptoken=3999
2020-11-23 15:42:19,830 DEBUG pid=32193 tid=MainThread file=base_modinput.py:log_debug:288 | Endpoint URL: https://reports.office365.com/ecp/reportingwebservice/reporting.svc/MessageTrace?$skiptoken=3999
2020-11-23 15:42:19,834 DEBUG pid=32193 tid=MainThread file=connectionpool.py:_new_conn:959 | Starting new HTTPS connection (1): reports.office365.com:443
2020-11-23 15:42:21,872 DEBUG pid=32193 tid=MainThread file=connectionpool.py:_make_request:437 | https://reports.office365.com:443 "GET /ecp/reportingwebservice/reporting.svc/MessageTrace?$skiptoken=3999

thanks

Re: Microsoft Office 365 Reporting Add-on not obeying interval configuration

apeadape — Wed, 30 Jun 2021 20:25:44 GMT

We are seeing the same thing, did you ever find a solution for this?

Re: Microsoft Office 365 Reporting Add-on not obeying interval configuration

becksyboy — Thu, 01 Jul 2021 08:09:14 GMT

Hi there, nope we still have the issue. Sometimes it obeys the interval, but it tend to pull in logs at random intervals. We had to write a simple alert to notify us if we don't see any logs after 4 hrs. We still see the continuous connections every minute or so.

Re: Microsoft Office 365 Reporting Add-on not obeying interval configuration

apeadape — Tue, 06 Jul 2021 19:09:41 GMT

What is your query window size and delay throttle set at? We had ours at 30 minutes delay throttle and 30 minutes query window size and were seeing drop off of logs every night around 10 pm - midnight.

Over the weekend I updated our config settings to be delay throttle 30 minutes and query window size 60 minutes and it hasn't dropped off for 2 days. Hoping this is a longer term fix, but not holding my breath just yet.

Re: Microsoft Office 365 Reporting Add-on not obeying interval configuration

becksyboy — Thu, 08 Jul 2021 07:37:11 GMT

Our query size window is set to 10, and delay throttle of 5.

However, below are the actual times data was pulled into Splunk:

08/07/2021/05:58:56

08/07/2021/04:48:29

08/07/2021/04:32:54

08/07/2021/02:58:49

08/07/2021/01:50:45

08/07/2021/00:18:25

topic Re: Microsoft Office 365 Reporting Add-on not obeying interval configuration in Splunk Search

Microsoft Office 365 Reporting Add-on not obeying interval configuration

Re: Microsoft Office 365 Reporting Add-on not obeying interval configuration

Re: Microsoft Office 365 Reporting Add-on not obeying interval configuration

Re: Microsoft Office 365 Reporting Add-on not obeying interval configuration

Re: Microsoft Office 365 Reporting Add-on not obeying interval configuration