TA-dmarc add-on version 3.2.1: Unable to add data to index with stable connection and add-on is reading messages.

[att35]

Hi,

We are using the latest version for TA-dmarc add-on for Splunk (3.2.1). Connection seems to be successful and debug logs show that add-on is able to read the messages:

2020-05-21 09:00:54,162 DEBUG pid=165192 tid=MainThread file=base_modinput.py:log_debug:286 | get_dmarc_messages: successfully connected to x.y.com
2020-05-21 09:00:54,769 INFO pid=165192 tid=MainThread file=base_modinput.py:log_info:293 | get_dmarc_messages: 5 messages in folder INBOX
2020-05-21 09:00:54,916 INFO pid=165192 tid=MainThread file=base_modinput.py:log_info:293 | get_dmarc_messages: 5 messages in folder INBOX match subject "Report domain:"

For new messages I can also see Add-on writing the data.

2020-05-21 09:30:54,469 DEBUG pid=131084 tid=MainThread file=base_modinput.py:log_debug:286 | write_part_to_file: saved file /tmp/tmpEH0vFq/test.com!xyz.com!1589932800!1590019200!star.xml from uid 48

But I do not see anything showing up under index=dmarc (This is the index set in the config).

I do see the following repeated:

2020-05-21 09:00:54,938 DEBUG pid=165192 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-dmarc/storage/collections/data/TA_dmarc_checkpointer/x.y... (body: {})
2020-05-21 09:00:54,942 DEBUG pid=165192 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-dmarc/storage/collections/data/TA_dmarc_checkpointer/x.y.com_dmarc%40xyz.com_28 HTTP/1.1" 200 389
2020-05-21 09:00:54,943 DEBUG pid=165192 tid=MainThread file=binding.py:new_f:71 | Operation took 0:00:00.005052
2020-05-21 09:00:50,982 INFO pid=165192 tid=MainThread file=connectionpool.py:_new_conn:758 | Starting new HTTPS connection (1): 127.0.0.1
2020-05-21 09:00:51,953 INFO pid=165192 tid=MainThread file=connectionpool.py:_new_conn:758 | Starting new HTTPS connection (1): 127.0.0.1
2020-05-21 09:00:52,712 INFO pid=165192 tid=MainThread file=connectionpool.py:_new_conn:758 | Starting new HTTPS connection (1): 127.0.0.1
2020-05-21 09:00:54,026 DEBUG pid=165192 tid=MainThread file=base_modinput.py:log_debug:286 | Success creating temporary directory /tmp/tmptGt5ME
2020-05-21 09:00:54,026 INFO pid=165192 tid=MainThread file=base_modinput.py:log_info:293 | Start processing imap server x.y.com with use_ssl True
2020-05-21 09:00:54,162 DEBUG pid=165192 tid=MainThread file=base_modinput.py:log_debug:286 | get_dmarc_messages: successfully connected to x.y.com
2020-05-21 09:00:54,769 INFO pid=165192 tid=MainThread file=base_modinput.py:log_info:293 | get_dmarc_messages: 5 messages in folder INBOX
2020-05-21 09:00:54,916 INFO pid=165192 tid=MainThread file=base_modinput.py:log_info:293 | get_dmarc_messages: 5 messages in folder INBOX match subject "Report domain:"
2020-05-21 09:00:54,917 INFO pid=165192 tid=MainThread file=splunk_rest_client.py:_request_handler:100 | Use HTTP connection pooling
2020-05-21 09:00:54,917 DEBUG pid=165192 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-dmarc/storage/collections/config/TA_dmarc_checkpointer (body: {})
2020-05-21 09:00:54,918 INFO pid=165192 tid=MainThread file=connectionpool.py:_new_conn:758 | Starting new HTTPS connection (1): 127.0.0.1
2020-05-21 09:00:54,927 DEBUG pid=165192 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-dmarc/storage/collections/config/TA_dmarc_checkpointer HTTP/1.1" 200 5241
2020-05-21 09:00:54,928 DEBUG pid=165192 tid=MainThread file=binding.py:new_f:71 | Operation took 0:00:00.010589
2020-05-21 09:00:54,928 DEBUG pid=165192 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-dmarc/storage/collections/config/ (body: {'offset': 0, 'count': -1, 'search': 'TA_dmarc_checkpointer'})
2020-05-21 09:00:54,931 DEBUG pid=165192 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-dmarc/storage/collections/config/?offset=0&count=-1&search=TA_dmarc_checkpointer HTTP/1.1" 200 4439
2020-05-21 09:00:54,932 DEBUG pid=165192 tid=MainThread file=binding.py:new_f:71 | Operation took 0:00:00.003590
2020-05-21 09:00:54,934 DEBUG pid=165192 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-dmarc/storage/collections/data/TA_dmarc_checkpointer/x.y... (body: {})
2020-05-21 09:00:54,937 DEBUG pid=165192 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-dmarc/storage/collections/data/TA_dmarc_checkpointer/x.y.com_dmarc%40xyz.com_25 HTTP/1.1" 200 388
2020-05-21 09:00:54,938 DEBUG pid=165192 tid=MainThread file=binding.py:new_f:71 | Operation took 0:00:00.003830
2020-05-21 09:00:54,938 DEBUG pid=165192 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-dmarc/storage/collections/data/TA_dmarc_checkpointer/x.y... (body: {})
2020-05-21 09:00:54,942 DEBUG pid=165192 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-dmarc/storage/collections/data/TA_dmarc_checkpointer/x.y.com_dmarc%40xyz.com_28 HTTP/1.1" 200 389
2020-05-21 09:00:54,943 DEBUG pid=165192 tid=MainThread file=binding.py:new_f:71 | Operation took 0:00:00.005052
2020-05-21 09:00:54,943 DEBUG pid=165192 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-dmarc/storage/collections/data/TA_dmarc_checkpointer/x.y... (body: {})
2020-05-21 09:00:54,947 DEBUG pid=165192 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-dmarc/storage/collections/data/TA_dmarc_checkpointer/x.y.com_dmarc%40xyz.com_31 HTTP/1.1" 200 340
2020-05-21 09:00:54,948 DEBUG pid=165192 tid=MainThread file=binding.py:new_f:71 | Operation took 0:00:00.004498
2020-05-21 09:00:54,948 DEBUG pid=165192 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-dmarc/storage/collections/data/TA_dmarc_checkpointer/x.y... (body: {})
2020-05-21 09:00:54,952 DEBUG pid=165192 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-dmarc/storage/collections/data/TA_dmarc_checkpointer/x.y.com_dmarc%40xyz.com_38 HTTP/1.1" 200 388
2020-05-21 09:00:54,953 DEBUG pid=165192 tid=MainThread file=binding.py:new_f:71 | Operation took 0:00:00.004457
2020-05-21 09:00:54,953 DEBUG pid=165192 tid=MainThread file=binding.py:get:664 | GET request to https://127.0.0.1:8089/servicesNS/nobody/TA-dmarc/storage/collections/data/TA_dmarc_checkpointer/x.y... (body: {})
2020-05-21 09:00:54,956 DEBUG pid=165192 tid=MainThread file=connectionpool.py:_make_request:387 | "GET /servicesNS/nobody/TA-dmarc/storage/collections/data/TA_dmarc_checkpointer/x.y.com_dmarc%40xyz.com_42 HTTP/1.1" 200 340
2020-05-21 09:00:54,957 DEBUG pid=165192 tid=MainThread file=binding.py:new_f:71 | Operation took 0:00:00.004431
2020-05-21 09:00:54,958 DEBUG pid=165192 tid=MainThread file=base_modinput.py:log_debug:286 | filter_seen_messages: uids on imap   set([25, 42, 28, 38, 31])
2020-05-21 09:00:54,958 DEBUG pid=165192 tid=MainThread file=base_modinput.py:log_debug:286 | filter_seen_messages: uids on imap   set([25, 42, 28, 38, 31])
2020-05-21 09:00:54,958 DEBUG pid=165192 tid=MainThread file=base_modinput.py:log_debug:286 | filter_seen_messages: uids in checkp set([25, 42, 28, 38, 31])
2020-05-21 09:00:54,958 DEBUG pid=165192 tid=MainThread file=base_modinput.py:log_debug:286 | filter_seen_messages: uids new       set([])
2020-05-21 09:00:54,958 INFO pid=165192 tid=MainThread file=base_modinput.py:log_info:293 | Ended processing imap server x.y.com
2020-05-21 09:00:54,959 DEBUG pid=165192 tid=MainThread file=base_modinput.py:log_debug:286 | Success deleting temporary directory /tmp/tmptGt5ME

How can I troubleshoot this further?

Thanks,

~ Abhi

[jorritf]

You could try to clean the checkpointing data in kvstore with this snippet below, so the addon will process the missing emails again. Other than that I dont see anything weird in the logs, in fact these look just like regular logs from a working TA-dmarc deployment.

|inputlookup ta_dmarc_checkpointer_lookup
|search state!="*input=dmarc_imap, server=*"
|outputlookup ta_dmarc_checkpointer_lookup

[Arpit_12]

Hi, 

I am running into similar issue. The data isn't being written to the index. I check the checkpoint CSV and could see the info there, as per you suggestion I emptied the file but that too didn't help in getting the data in.

Anything else that I shall do?