Issue with Log Analytics Add-on

[ryantwx]

Hi @jkat54 or fellow Splunkers,

I'm having trouble onboarding the events from the Log Analytics TA.
Note the very last line of the ERROR logs seem to indicate that there's a connection error, though I do not think there's any problem reaching out to the localhost IP and port.

12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py"" Traceback (most recent call last):
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""   File "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\ta_ms_loganalytics\modinput_wrapper\base_modinput.py", line 113, in stream_events
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""     self.parse_input_args(input_definition)
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""   File "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\ta_ms_loganalytics\modinput_wrapper\base_modinput.py", line 152, in parse_input_args
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""     self._parse_input_args_from_global_config(inputs)
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""   File "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\ta_ms_loganalytics\modinput_wrapper\base_modinput.py", line 171, in _parse_input_args_from_global_config
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""     ucc_inputs = global_config.inputs.load(input_type=self.input_type)
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""   File "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\ta_ms_loganalytics\splunktaucclib\global_config\configuration.py", line 270, in load
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""     input_item['entity']
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""   File "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\ta_ms_loganalytics\splunktaucclib\global_config\configuration.py", line 175, in _load_endpoint
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""     **query
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""   File "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\ta_ms_loganalytics\solnlib\packages\splunklib\binding.py", line 287, in wrapper
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""     return request_fun(self, *args, **kwargs)
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""   File "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\ta_ms_loganalytics\solnlib\packages\splunklib\binding.py", line 69, in new_f
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""     val = f(*args, **kwargs)
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""   File "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\ta_ms_loganalytics\solnlib\packages\splunklib\binding.py", line 665, in get
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""     response = self.http.get(path, self._auth_headers, **query)
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""   File "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\ta_ms_loganalytics\solnlib\packages\splunklib\binding.py", line 1160, in get
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""     return self.request(url, { 'method': "GET", 'headers': headers })
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""   File "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\ta_ms_loganalytics\solnlib\packages\splunklib\binding.py", line 1218, in request
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""     response = self.handler(url, message, **kwargs)
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""   File "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\ta_ms_loganalytics\solnlib\splunk_rest_client.py", line 140, in request
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""     verify=verify, proxies=proxies, cert=cert, **kwargs)
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""   File "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\ta_ms_loganalytics\solnlib\packages\requests\api.py", line 53, in request
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""     return session.request(method=method, url=url, **kwargs)
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""   File "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\ta_ms_loganalytics\solnlib\packages\requests\sessions.py", line 468, in request
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""     resp = self.send(prep, **send_kwargs)
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""   File "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\ta_ms_loganalytics\solnlib\packages\requests\sessions.py", line 576, in send
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""     r = adapter.send(request, **kwargs)
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""   File "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\ta_ms_loganalytics\solnlib\packages\requests\adapters.py", line 437, in send
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py""     raise ConnectionError(e, request=request)
12-10-2019 12:37:52.801 +1000 ERROR ExecProcessor - message from "python "C:\Program Files\Splunk\etc\apps\TA-ms-loganalytics\bin\log_analytics.py"" ConnectionError: HTTPSConnectionPool(host='127.0.0.1', port=8089): Max retries exceeded with url: /servicesNS/nobody/TA-ms-loganalytics/TA_ms_loganalytics_log_analytics?count=0&--cred--=1&output_mode=json (Caused by NewConnectionError('<solnlib.packages.requests.packages.urllib3.connection.VerifiedHTTPSConnection object at 0x0000017B294B1BA8>: Failed to establish a new connection: [Errno 10061] No connection could be made because the target machine actively refused it',))

I have tested running the "| rest /servicesNS/nobody/TA-ms-loganalytics/TA_ms_loganalytics_log_analytics" command on the Splunk web of the HF, no issue there, a result is returned.

The debug logs do not indicate any issue, but posting here in case you need them.

2019-12-10 13:12:30,045 DEBUG pid=17312 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-ms-loganalytics/storage/collections/config/TA_ms_loganalytics_checkpointer (body: {})
2019-12-10 13:12:30,051 DEBUG pid=17312 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-ms-loganalytics/storage/collections/config/TA_ms_loganalytics_checkpointer HTTP/1.1" 200 5633
2019-12-10 13:12:30,052 DEBUG pid=17312 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-ms-loganalytics/storage/collections/config/ (body: {'search': 'TA_ms_loganalytics_checkpointer', 'offset': 0, 'count': -1})
2019-12-10 13:12:30,055 DEBUG pid=17312 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-ms-loganalytics/storage/collections/config/?search=TA_ms_loganalytics_checkpointer&offset=0&count=-1 HTTP/1.1" 200 4821
2019-12-10 13:12:30,065 DEBUG pid=17312 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-ms-loganalytics/storage/collections/data/TA_ms_loganalytics_checkpointer/QIC_Prod (body: {})
2019-12-10 13:12:30,069 DEBUG pid=17312 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-ms-loganalytics/storage/collections/data/TA_ms_loganalytics_checkpointer/Prod_Input HTTP/1.1" 200 80
2019-12-10 13:12:30,069 DEBUG pid=17312 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-ms-loganalytics/storage/collections/data/TA_ms_loganalytics_checkpointer/QIC_Prod (body: {})
2019-12-10 13:12:30,072 DEBUG pid=17312 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-ms-loganalytics/storage/collections/data/TA_ms_loganalytics_checkpointer/Prod_Input HTTP/1.1" 200 80
2019-12-10 13:12:30,569 DEBUG pid=17312 tid=MainThread file=connectionpool.py:_new_conn:809 | Starting new HTTPS connection (1): api.loganalytics.io
2019-12-10 13:12:31,019 DEBUG pid=17312 tid=MainThread file=connectionpool.py:_make_request:400 | https://api.loganalytics.io:443 "POST /v1/workspaces/5dd416a5-1914-4a07-8bfd-ae195a219306/query HTTP/1.1" 200 None
2019-12-10 13:12:31,023 DEBUG pid=17312 tid=MainThread file=binding.py:post:736 | POST request to https://127.0.0.1:8089/servicesNS/nobody/TA-ms-loganalytics/storage/collections/data/TA_ms_loganalytics_checkpointer/batch_save (body: {'body': '[{"state": "\\"10/12/2019 02:57:30\\"", "_key": "Prod_Input"}]'})
2019-12-10 13:12:31,075 DEBUG pid=17312 tid=MainThread file=connectionpool.py:_make_request:387 | "POST /servicesNS/nobody/TA-ms-loganalytics/storage/collections/data/TA_ms_loganalytics_checkpointer/batch_save HTTP/1.1" 200 14

My inputs.conf in the TA.
[log_analytics://Prod_Input]
application_id = XXX
application_key = *****
event_delay_lag_time = 15
index = XXX
interval = 300
log_analytics_query = XXX
resource_group = XXX
start_date = 01/06/2019 00:00:00
subscription_id = XXX
tenant_id = XXX
workspace_id = XXX

Let me know if I have misconfigured anything to have caused this issue to occur.
Much appreciated.

[jkat54]

That's really weird that it makes all those connections to itself successfully in the debug log but is stack tracing a connection error to itself.

It's probably an unhandled exception you've found. Can you try increasing event_delay_lag_time to a number greater than interval?

I think that may be the problem because it does math involving both numbers and might be coming with a negative number of seconds when it needs a positive instead.

[ryantwx]

The event delay / lag time is already greater than interval since it's in minutes, no?
I have it set to 60 seconds interval and 30 minutes delay.
Still no events ingested.

2019-12-11 15:17:22,440 INFO pid=10000 tid=MainThread file=connectionpool.py:_new_conn:758 | Starting new HTTPS connection (1): 127.0.0.1
2019-12-11 15:17:29,000 INFO pid=10000 tid=MainThread file=connectionpool.py:_new_conn:758 | Starting new HTTPS connection (1): 127.0.0.1
2019-12-11 15:17:41,605 INFO pid=10000 tid=MainThread file=splunk_rest_client.py:_request_handler:100 | Use HTTP connection pooling
2019-12-11 15:17:41,607 DEBUG pid=10000 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-ms-loganalytics/storage/collections/config/TA_ms_loganal... (body: {})
2019-12-11 15:17:41,608 INFO pid=10000 tid=MainThread file=connectionpool.py:_new_conn:758 | Starting new HTTPS connection (1): 127.0.0.1
2019-12-11 15:17:41,612 DEBUG pid=10000 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-ms-loganalytics/storage/collections/config/TA_ms_loganalytics_checkpointer HTTP/1.1" 200 5633
2019-12-11 15:17:41,614 DEBUG pid=10000 tid=MainThread file=binding.py:new_f:71 | Operation took 0:00:00.007000
2019-12-11 15:17:41,614 DEBUG pid=10000 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-ms-loganalytics/storage/collections/config/ (body: {'count': -1, 'offset': 0, 'search': 'TA_ms_loganalytics_checkpointer'})
2019-12-11 15:17:41,622 DEBUG pid=10000 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-ms-loganalytics/storage/collections/config/?count=-1&offset=0&search=TA_ms_loganalytics_checkpointer HTTP/1.1" 200 4821
2019-12-11 15:17:41,627 DEBUG pid=10000 tid=MainThread file=binding.py:new_f:71 | Operation took 0:00:00.013000
2019-12-11 15:17:41,631 DEBUG pid=10000 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-ms-loganalytics/storage/collections/data/TA_ms_loganalyt... (body: {})
2019-12-11 15:17:41,634 DEBUG pid=10000 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-ms-loganalytics/storage/collections/data/TA_ms_loganalytics_checkpointer/Prod_Input HTTP/1.1" 200 86
2019-12-11 15:17:41,635 DEBUG pid=10000 tid=MainThread file=binding.py:new_f:71 | Operation took 0:00:00.004000
2019-12-11 15:17:41,635 DEBUG pid=10000 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-ms-loganalytics/storage/collections/data/TA_ms_loganalyt... (body: {})
2019-12-11 15:17:41,640 DEBUG pid=10000 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-ms-loganalytics/storage/collections/data/TA_ms_loganalytics_checkpointer/Prod_Input HTTP/1.1" 200 86
2019-12-11 15:17:41,640 DEBUG pid=10000 tid=MainThread file=binding.py:new_f:71 | Operation took 0:00:00.004000
2019-12-11 15:17:41,645 DEBUG pid=10000 tid=MainThread file=log.py:debug:108 | XXXXXXXXXXX-e034-4038-b317-XXXXXXXXXXX - Authority:Performing instance discovery: https://login.microsoftonline.com/XXXXXX-XXXXX-XXXXXX-XXXXX-XXXXXX
2019-12-11 15:17:41,647 DEBUG pid=10000 tid=MainThread file=log.py:debug:108 | XXXXXXXXXXX-e034-4038-b317-XXXXXXXXXXX - Authority:Performing static instance discovery
2019-12-11 15:17:41,647 DEBUG pid=10000 tid=MainThread file=log.py:debug:108 | XXXXXXXXXXX-e034-4038-b317-XXXXXXXXXXX - Authority:Authority validated via static instance discovery
2019-12-11 15:17:41,647 INFO pid=10000 tid=MainThread file=log.py:info:103 | XXXXXXXXXXX-e034-4038-b317-XXXXXXXXXXX - TokenRequest:Getting token with client credentials.
2019-12-11 15:17:41,647 DEBUG pid=10000 tid=MainThread file=log.py:debug:108 | XXXXXXXXXXX-e034-4038-b317-XXXXXXXXXXX - TokenRequest:No user_id passed for cache query
2019-12-11 15:17:41,647 DEBUG pid=10000 tid=MainThread file=log.py:debug:108 | XXXXXXXXXXX-e034-4038-b317-XXXXXXXXXXX - OAuth2Client:finding with query: {"_clientId": "XXXXX-XXXXX-XXXXX-XXXXX-XXXXX"}
2019-12-11 15:17:41,647 DEBUG pid=10000 tid=MainThread file=log.py:debug:108 | XXXXXXXXXXX-e034-4038-b317-XXXXXXXXXXX - OAuth2Client:Looking for potential cache entries:
2019-12-11 15:17:41,647 DEBUG pid=10000 tid=MainThread file=log.py:debug:108 | XXXXXXXXXXX-e034-4038-b317-XXXXXXXXXXX - OAuth2Client:{"_clientId": "XXXXX-XXXXX-XXXXX-XXXXX-XXXXX"}
2019-12-11 15:17:41,647 DEBUG pid=10000 tid=MainThread file=log.py:debug:108 | XXXXXXXXXXX-e034-4038-b317-XXXXXXXXXXX - OAuth2Client:Found 0 potential entries.
2019-12-11 15:17:41,653 DEBUG pid=10000 tid=MainThread file=connectionpool.py:_new_conn:809 | Starting new HTTPS connection (1): login.microsoftonline.com
2019-12-11 15:17:42,198 DEBUG pid=10000 tid=MainThread file=connectionpool.py:_make_request:400 | https://login.microsoftonline.com:443 "POST /XXXXX-XXXX-XXXX-XXXX-XXXXX/oauth2/token?api-version=1.0 HTTP/1.1" 200 1335
2019-12-11 15:17:42,203 INFO pid=10000 tid=MainThread file=log.py:info:103 | XXXXXXXXXXX-e034-4038-b317-XXXXXXXXXXX - OAuth2Client:Get Token Server returned this correlation_id: XXXXX-XXXX-XXXX-XXXX-XXXXXX
2019-12-11 15:17:42,203 DEBUG pid=10000 tid=MainThread file=log.py:debug:108 | XXXXXXXXXXX-e034-4038-b317-XXXXXXXXXXX - OAuth2Client:Adding entry AccessTokenId: XXXXXXXXXXXXXXXXXXXXXX
2019-12-11 15:17:42,203 DEBUG pid=10000 tid=MainThread file=log.py:debug:108 | XXXXXXXXXXX-e034-4038-b317-XXXXXXXXXXX - OAuth2Client:Added entry is MRRT
2019-12-11 15:17:42,204 DEBUG pid=10000 tid=MainThread file=connectionpool.py:_new_conn:809 | Starting new HTTPS connection (1): api.loganalytics.io
2019-12-11 15:17:42,440 DEBUG pid=10000 tid=MainThread file=connectionpool.py:_make_request:400 | https://api.loganalytics.io:443 "POST /v1/workspaces/XXXXX-1914-XXXXX-8bfd-XXXXXXXXX/query HTTP/1.1" 200 None
2019-12-11 15:17:42,443 DEBUG pid=10000 tid=MainThread file=base_modinput.py:log_debug:286 | OMSInputName="Prod_Input" status="200" step="Post Query" search_params="{'timespan': '2019-12-11T04:46:39/2019-12-11T04:47:41', 'query': 'InformationProtectionEvents | where Time > ago(15m)'}'
2019-12-11 15:17:42,443 DEBUG pid=10000 tid=MainThread file=binding.py:post:736 | POST request to https://127.0.0.1:8089/servicesNS/nobody/TA-ms-loganalytics/storage/collections/data/TA_ms_loganalyt... (body: {'body': '[{"state": "\\"11/12/2019 04:47:41\\"", "_key": "Prod_Input"}]'})
2019-12-11 15:17:42,457 DEBUG pid=10000 tid=MainThread file=connectionpool.py:_make_request:387 | "POST /servicesNS/nobody/TA-ms-loganalytics/storage/collections/data/TA_ms_loganalytics_checkpointer/batch_save HTTP/1.1" 200 20
2019-12-11 15:17:42,459 DEBUG pid=10000 tid=MainThread file=binding.py:new_f:71 | Operation took 0:00:00.016000

[Azeemering]

Could it be blocked because of a proxy?

[jkat54]

Any luck with this?

[jkat54]

Yes. The application doesn't support proxy settings, but you can set global proxy settings on your server and restart splunk to enable them.