topic Re: Version 1.1.0 doesn't get message trace in All Apps and Add-ons

Version 1.1.0 doesn't get message trace

wstarowicz — Tue, 29 May 2018 13:03:36 GMT

It seems that there is something wrong with the new version. It doesn't download message trace at all. After copy past url from the log there is an info:
There is an unterminated literal at position 102 in 'StartDate eq datetime'2018-05-24T15:52:07.838523Z' and EndDate eq datetime'2018-05-24T16:52:07.838523Z'.

Re: Version 1.1.0 doesn't get message trace

jconger — Tue, 29 May 2018 15:26:04 GMT

Was this an upgrade or a new install of the add-on? Also, can you post some more detail from the _internal index?

Re: Version 1.1.0 doesn't get message trace

wstarowicz — Wed, 30 May 2018 15:08:56 GMT

I also just reinstalled the app and still no logs (but URL seems to be fine now).

Re: Version 1.1.0 doesn't get message trace

wstarowicz — Tue, 29 Sep 2020 19:47:07 GMT

It was an update. See log below (nothing special I think):

2018-05-30 14:55:01,287 DEBUG pid=24525 tid=MainThread file=binding.py:new_f:71 | Operation took 0:00:00.002906
2018-05-30 14:55:01,287 DEBUG pid=24525 tid=MainThread file=base_modinput.py:log_debug:286 | Start date: 2018-05-25 15:46:10.659534, End date: 2018-05-25 16:46:10.659534
2018-05-30 14:55:01,287 DEBUG pid=24525 tid=MainThread file=base_modinput.py:log_debug:286 | Endpoint URL: https://reports.office365.com/ecp/reportingwebservice/reporting.svc/MessageTrace?$filter=StartDate eq datetime'2018-05-25T15:46:10.659534Z' and EndDate eq datetime'2018-05-25T16:46:10.659534Z'
2018-05-30 14:55:01,288 INFO pid=24525 tid=MainThread file=setup_util.py:log_info:114 | Proxy is not enabled!
2018-05-30 14:55:01,291 DEBUG pid=24525 tid=MainThread file=connectionpool.py:_new_conn:809 | Starting new HTTPS connection (1): reports.office365.com
2018-05-30 14:55:07,405 DEBUG pid=24525 tid=MainThread file=connectionpool.py:_make_request:400 | https://reports.office365.com:443 "GET /ecp/reportingwebservice/reporting.svc/MessageTrace?$filter=StartDate%20eq%20datetime'2018-05-25T15:46:10.659534Z'%20and%20EndDate%20eq%20datetime'2018-05-25T16:46:10.659534Z' HTTP/1.1" 200 None
2018-05-30 14:55:07,613 DEBUG pid=24525 tid=MainThread file=base_modinput.py:log_debug:286 | Number of messages returned: 1696
2018-05-30 14:55:07,613 DEBUG pid=24525 tid=MainThread file=base_modinput.py:log_debug:286 | Max date before getting message: 2018-05-25 15:46:10.659534
2018-05-30 14:55:08,013 DEBUG pid=24525 tid=MainThread file=base_modinput.py:log_debug:286 | Max date after getting messages: 2018-05-25 16:46:10.035204
2018-05-30 14:55:08,014 DEBUG pid=24525 tid=MainThread file=binding.py:post:736 | POST request to https://127.0.0.1:8089/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/data/TA_MS_O365_Reporting_checkpointer/batch_save (body: {'body': '[{"state": "{\"max_date\": \"2018-05-25 16:46:10.035204\"}", "_key": "msgtrace_obj_checkpoint"}]'})
2018-05-30 14:55:08,051 DEBUG pid=24525 tid=MainThread file=connectionpool.py:_make_request:387 | "POST /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/data/TA_MS_O365_Reporting_checkpointer/batch_save HTTP/1.1" 200 29
2018-05-30 14:55:08,052 DEBUG pid=24525 tid=MainThread file=binding.py:new_f:71 | Operation took 0:00:00.038370
2018-05-30 15:54:57,332 INFO pid=30681 tid=MainThread file=connectionpool.py:_new_conn:758 | Starting new HTTPS connection (1): 127.0.0.1
2018-05-30 15:54:58,204 INFO pid=30681 tid=MainThread file=connectionpool.py:_new_conn:758 | Starting new HTTPS connection (1): 127.0.0.1
2018-05-30 15:54:59,693 INFO pid=30681 tid=MainThread file=connectionpool.py:_new_conn:758 | Starting new HTTPS connection (1): 127.0.0.1
2018-05-30 15:55:01,155 INFO pid=30681 tid=MainThread file=splunk_rest_client.py:_request_handler:100 | Use HTTP connection pooling
2018-05-30 15:55:01,155 DEBUG pid=30681 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/TA_MS_O365_Reporting_checkpointer (body: {})
2018-05-30 15:55:01,156 INFO pid=30681 tid=MainThread file=connectionpool.py:_new_conn:758 | Starting new HTTPS connection (1): 127.0.0.1
2018-05-30 15:55:01,160 DEBUG pid=30681 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/TA_MS_O365_Reporting_checkpointer HTTP/1.1" 200 5516
2018-05-30 15:55:01,161 DEBUG pid=30681 tid=MainThread file=binding.py:new_f:71 | Operation took 0:00:00.005667
2018-05-30 15:55:01,161 DEBUG pid=30681 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/ (body: {'offset': 0, 'search': 'TA_MS_O365_Reporting_checkpointer', 'count': -1})
2018-05-30 15:55:01,166 DEBUG pid=30681 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/?offset=0&search=TA_MS_O365_Reporting_checkpointer&count=-1 HTTP/1.1" 200 7417
2018-05-30 15:55:01,166 DEBUG pid=30681 tid=MainThread file=binding.py:new_f:71 | Operation took 0:00:00.004694
2018-05-30 15:55:01,168 DEBUG pid=30681 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/data/TA_MS_O365_Reporting_checkpointer/msgtrace_obj_checkpoint (body: {})
2018-05-30 15:55:01,171 DEBUG pid=30681 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/data/TA_MS_O365_Reporting_checkpointer/msgtrace_obj_checkpoint HTTP/1.1" 200 118
2018-05-30 15:55:01,171 DEBUG pid=30681 tid=MainThread file=binding.py:new_f:71 | Operation took 0:00:00.003147
2018-05-30 15:55:01,172 DEBUG pid=30681 tid=MainThread file=base_modinput.py:log_debug:286 | Start date: 2018-05-25 16:46:10.035204, End date: 2018-05-25 17:46:10.035204
2018-05-30 15:55:01,172 DEBUG pid=30681 tid=MainThread file=base_modinput.py:log_debug:286 | Endpoint URL: https://reports.office365.com/ecp/reportingwebservice/reporting.svc/MessageTrace?$filter=StartDate eq datetime'2018-05-25T16:46:10.035204Z' and EndDate eq datetime'2018-05-25T17:46:10.035204Z'
2018-05-30 15:55:01,172 INFO pid=30681 tid=MainThread file=setup_util.py:log_info:114 | Proxy is not enabled!
2018-05-30 15:55:01,175 DEBUG pid=30681 tid=MainThread file=connectionpool.py:_new_conn:809 | Starting new HTTPS connection (1): reports.office365.com
2018-05-30 15:55:07,207 DEBUG pid=30681 tid=MainThread file=connectionpool.py:_make_request:400 | https://reports.office365.com:443 "GET /ecp/reportingwebservice/reporting.svc/MessageTrace?$filter=StartDate%20eq%20datetime'2018-05-25T16:46:10.035204Z'%20and%20EndDate%20eq%20datetime'2018-05-25T17:46:10.035204Z' HTTP/1.1" 200 None
2018-05-30 15:55:07,990 DEBUG pid=30681 tid=MainThread file=base_modinput.py:log_debug:286 | Number of messages returned: 1631
2018-05-30 15:55:07,990 DEBUG pid=30681 tid=MainThread file=base_modinput.py:log_debug:286 | Max date before getting message: 2018-05-25 16:46:10.035204
2018-05-30 15:55:08,380 DEBUG pid=30681 tid=MainThread file=base_modinput.py:log_debug:286 | Max date after getting messages: 2018-05-25 17:46:04.759034
2018-05-30 15:55:08,380 DEBUG pid=30681 tid=MainThread file=binding.py:post:736 | POST request to https://127.0.0.1:8089/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/data/TA_MS_O365_Reporting_checkpointer/batch_save (body: {'body': '[{"state": "{\"max_date\": \"2018-05-25 17:46:04.759034\"}", "_key": "msgtrace_obj_checkpoint"}]'})
2018-05-30 15:55:08,399 DEBUG pid=30681 tid=MainThread file=connectionpool.py:_make_request:387 | "POST /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/data/TA_MS_O365_Reporting_checkpointer/batch_save HTTP/1.1" 200 29
2018-05-30 15:55:08,400 DEBUG pid=30681 tid=MainThread file=binding.py:new_f:71 | Operation took 0:00:00.019649

Re: Version 1.1.0 doesn't get message trace

jconger — Thu, 31 May 2018 14:58:07 GMT

The debug logs above indicate that message traces are being returned by the text "Number of messages returned: 1631". The input is polling for an hour's worth of data is seems by comparing the max date before and after the input runs. Are you searching your index for "All Time"? The data collection started a few days back and is pulling in an hour's worth of data each run, so there will be some catch up time.

Re: Version 1.1.0 doesn't get message trace

wstarowicz — Fri, 01 Jun 2018 11:14:28 GMT

Ok, so I assume that first it has to download all older message traces.
I also just checked 'All Time' and there are events with date i.e. "31/05/2018 12:05:02.614" - I do not know why it doesn't show in last 24h.

Re: Version 1.1.0 doesn't get message trace

wstarowicz — Fri, 01 Jun 2018 12:10:37 GMT

Actually the question is: what do you think are the optimum values for Query window size and Delay throttle to get "almost" realtime traces?

Re: Version 1.1.0 doesn't get message trace

shirishkamat84 — Tue, 29 Sep 2020 19:48:47 GMT

I had the same issue after upgrading to the new app, it would query upto last 6days and when it come to last 24hrs the input fails with error "end_date is greater than the specified delay throttle [start_date=2018-05-30 23:08:16.241651 end_date=2018-05-31 00:08:16.241651 utc_now=2018-05-31 23:53:58.493033] Skipping..."

I used the default values since i did not knew what values I need to set.

Re: Version 1.1.0 doesn't get message trace

snrnbrem — Mon, 11 Jun 2018 08:38:07 GMT

Hi!

Had the same issues, but i played around with the settings and found something that worked for me:

Interval: 300 seconds
Query windows size: 30 minutes
Delay throttle: 32 minutes

Probably not optimal settings, but at least it works better than the default values 🙂

Re: Version 1.1.0 doesn't get message trace

templier — Wed, 13 Jun 2018 09:21:31 GMT

Hello, confirm it.
Re-create inputs with your parameters - all work.But If change back - nothing work.

Re: Version 1.1.0 doesn't get message trace

templier — Wed, 13 Jun 2018 14:15:18 GMT

Use this:
Interval: 300 seconds
Query windows size: 30 minutes
Delay throttle: 32 minutes

Re: Version 1.1.0 doesn't get message trace

JScordo — Tue, 24 Jul 2018 16:17:15 GMT

Has there been any word from Splunk as to what the optimal settings should be? It's strange that the default numbers for the configs throw errors and doesn't return actual results.

Re: Version 1.1.0 doesn't get message trace

templier — Wed, 25 Jul 2018 06:17:33 GMT

Hello,
Have't information from Splunk.
In first release all work fine with a default value, but after update we hade trouble.

Re: Version 1.1.0 doesn't get message trace

bcatoe112 — Wed, 01 Aug 2018 10:20:53 GMT

Same issue here, after upgrading we no longer are getting message trace logs. Has anyone been able to fix this?

Re: Version 1.1.0 doesn't get message trace

ChrisBell04 — Wed, 03 Oct 2018 00:03:35 GMT

jconger [Splunk]

Will a newer version be [re]released any time soon? I see some on the forum mentioning 1.1.3, when splunkbase only has 1.1.0.

I ask, because like several others, a fresh install of 1.1.0 is getting 404 for the data in continuous mode. When I tried an index-once, it successfully downloaded ~2 weeks of events.

2018-10-02 16:57:10,598 DEBUG pid=7676 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/TA_MS_O365_Reporting_checkpointer (body: {})
2018-10-02 16:57:10,599 INFO pid=7676 tid=MainThread file=connectionpool.py:_new_conn:758 | Starting new HTTPS connection (1): 127.0.0.1
2018-10-02 16:57:10,602 DEBUG pid=7676 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/TA_MS_O365_Reporting_checkpointer HTTP/1.1" 200 5516
2018-10-02 16:57:10,604 DEBUG pid=7676 tid=MainThread file=binding.py:new_f:71 | Operation took 0:00:00.005000
2018-10-02 16:57:10,604 DEBUG pid=7676 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/ (body: {'search': 'TA_MS_O365_Reporting_checkpointer', 'count': -1, 'offset': 0})
2018-10-02 16:57:10,605 DEBUG pid=7676 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/config/?search=TA_MS_O365_Reporting_checkpointer&count=-1&offset=0 HTTP/1.1" 200 7407
2018-10-02 16:57:10,607 DEBUG pid=7676 tid=MainThread file=binding.py:new_f:71 | Operation took 0:00:00.003000
2018-10-02 16:57:10,611 DEBUG pid=7676 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/data/TA_MS_O365_Reporting_checkpointer/MYORG_continuous_obj_checkpoint (body: {})
2018-10-02 16:57:10,614 DEBUG pid=7676 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-MS_O365_Reporting/storage/collections/data/TA_MS_O365_Reporting_checkpointer/MYORG_continuous_obj_checkpoint HTTP/1.1" 404 140
2018-10-02 16:57:10,615 DEBUG pid=7676 tid=MainThread file=base_modinput.py:log_debug:286 | Start date: 2018-10-01 00:00:00, End date: 2018-10-01 00:30:00
2018-10-02 16:57:10,615 DEBUG pid=7676 tid=MainThread file=base_modinput.py:log_debug:286 | Endpoint URL: https://reports.office365.com/ecp/reportingwebservice/reporting.svc/MessageTrace?$filter=StartDate eq datetime'2018-10-01T00:00:00Z' and EndDate eq datetime'2018-10-01T00:30:00Z'
2018-10-02 16:57:10,615 INFO pid=7676 tid=MainThread file=setup_util.py:log_info:114 | Proxy is not enabled!
2018-10-02 16:57:10,619 DEBUG pid=7676 tid=MainThread file=connectionpool.py:_new_conn:809 | Starting new HTTPS connection (1): reports.office365.com
2018-10-02 16:57:10,974 DEBUG pid=7676 tid=MainThread file=connectionpool.py:_make_request:400 | https://reports.office365.com:443 "GET /ecp/reportingwebservice/reporting.svc/MessageTrace?$filter=StartDate%20eq%20datetime'2018-10-01T00:00:00Z'%20and%20EndDate%20eq%20datetime'2018-10-01T00:30:00Z' HTTP/1.1" 404 115
2018-10-02 16:57:10,979 ERROR pid=7676 tid=MainThread file=base_modinput.py:log_error:307 | HTTP Request error: 404 Client Error: Not Found for url: https://reports.office365.com/ecp/reportingwebservice/reporting.svc/MessageTrace?$filter=StartDate%20eq%20datetime'2018-10-01T00:00:00Z'%20and%20EndDate%20eq%20datetime'2018-10-01T00:30:00Z';

Re: Version 1.1.0 doesn't get message trace

omuelle1 — Tue, 29 Sep 2020 23:55:47 GMT

Hi,

even with those settings I am still seeing the error:

Interval: 300 seconds
Query windows size: 30 minutes
Delay throttle: 32 minutes

2019-04-02 11:38:32,983 DEBUG pid=7604 tid=MainThread file=base_modinput.py:log_debug:286 | end_date is greater than the specified delay throttle [start_date=2019-04-02 14:49:40.649092 end_date=2019-04-02 15:19:40.649092 utc_now=2019-04-02 15:38:32.983000] Skipping...

Re: Version 1.1.0 doesn't get message trace

martinnepolean — Tue, 03 Mar 2020 11:54:59 GMT

i am facing the same issue? anyone have fix for above issue?