Shield duplicates _search api audits

[bobbyhubbard]

A standard GET by ID results in a single log entry in the audit log. Search (_search) results in two identical log entries. Every time.

• Default ES 1.6.0 installation.
• Added latest Shield.
• Added "search_admin" user.

Everything works great out of the box except I get _search audits duplicated in the log. ONLY "SearchRequest" audits. I haven't found any other api yet which results in this strange behavior.

[2015-06-16 18:37:24,705] [esdev-shieldpoc01] [transport] [access_granted]      origin_type=[rest], origin_address=[/10.30.24.36:55308], principal=[search_admin], action=[indices:data/read/search], indices=[test], request=[SearchRequest]
[2015-06-16 18:37:24,705] [esdev-shieldpoc01] [transport] [access_granted]      origin_type=[rest], origin_address=[/10.30.24.36:55308], principal=[search_admin], action=[indices:data/read/search], indices=[test], request=[SearchRequest]

[clintongormley]

@jaymode please could you take a look?

[jaymode]

@bobbyhubbard thanks for reporting this. This behavior isn't ideal and we'll look at if/how we can improve this. What you're seeing is a side effect of how auditing is implemented and how search requests are executed. Shield audits the individual actions that are executed by elasticsearch.

The indices:data/read/search action name corresponds to multiple actions for search. The reason that you are seeing the message twice, is the API executes a TransportSearchAction, which in turn executes a action corresponding to the search type; the default type query_then_fetch corresponds to the TransportSearchQueryThenFetchAction and the execution of this action is what causes the second log message.

[javanna]

This seems to have to do with the fact that the main TransportSearchAction uses an inner TransportSearchTypeAction (there is a different impl for each search type). Last time I checked I noticed some code that gets executed twice while it shouldn't (e.g. request validation), and a side effect is also the double audit log line. Maybe this inner action shouldn't be a transport action after all? The two (outer and inner) execute calls happen on the same node all the time, seems like also the transport handler registration that happens in TransportSearchTypeAction has no actual effect as it's already registered by TransportSearchAction with same name, so only used for audit logging.

[bobbyhubbard]

This bit us again today when someone else in our org setup a new log drain from shield. It reported nearly double the number of rest requests as expected. Then I remembered this issue... The workaround is simple enough...to hash each message (fingerprint in logstash) and use the hash as the message id. But this WILL bite every single Shield customer who is measuring and auditing rest calls. (How many are reporting invalid results now because they dont even know about this bug like one team here almost did?)