[BUG] Flag log_request_body is not honored when logging compliance diff for document updates

[expani]

What is the bug?

When we enable Compliance logging with diffs ( write_log_diffs ) and disable writing metadata ( write_metadata_only ) , request body is always logged even when log_request_body is disabled and it's not the first document insert.

How can one reproduce the bug?

• Launch Opensearch 2.13.0 cluster locally and enable security using the default configurations.

• Additionally, set plugins.security.audit.type in opensearch.yml to log4j to see the audit logs generated easily.

• Update the audit logging config as follows :

curl -XPUT -kv -H 'Content-Type: application/json' https://localhost:9200/_opendistro/_security/api/audit/config -u 'admin:xx' -d '{
  "enabled": true,
  "audit": {
    "ignore_users": [],
    "ignore_requests": [],
    "disabled_rest_categories": [
      "AUTHENTICATED"
    ],
    "disabled_transport_categories": [
      "AUTHENTICATED"
    ],
    "log_request_body": false,
    "resolve_indices": false,
    "resolve_bulk_requests": false,
    "exclude_sensitive_headers": true,
    "enable_transport": false,
    "enable_rest": true
  },
  "compliance": {
    "enabled": true,
    "write_log_diffs": true,
    "read_watched_fields": {},
    "read_ignore_users": [],
    "write_watched_indices": ["index1"],
    "write_ignore_users": [],
    "read_metadata_only": true,
    "write_metadata_only": false,
    "external_config": false,
    "internal_config": true
  }
}'

• Insert a document in an index

curl -XPUT -kv -H 'Content-Type: application/json' https://localhost:9200/index1/_doc/4 -u 'admin:xx' -d '{
  "name": "helloworld",
  "age": 18
}'

Audit log generated will look like

{
    "audit_compliance_operation": "UPDATE",
    "audit_cluster_name": "opensearch",
    "audit_node_name": "example.com",
    "audit_category": "COMPLIANCE_DOC_WRITE",
    "audit_request_origin": "REST",
    "audit_compliance_doc_version": 2,
    "audit_request_body": "{\n  \"name\": \"helloworld\",\n  \"age\": 18\n}",
    "audit_node_id": "oenHT55bTNW4XB358NS7Qw",
    "@timestamp": "2024-07-09T06:56:04.947+00:00",
    "audit_compliance_diff_is_noop": true,
    "audit_format_version": 4,
    "audit_request_remote_address": "::1",
    "audit_trace_doc_id": "4",
    "audit_node_host_address": "127.0.0.1",
    "audit_request_effective_user": "admin",
    "audit_trace_shard_id": 0,
    "audit_trace_indices": ["index1"],
    "audit_trace_resolved_indices": ["index1"],
    "audit_node_host_name": "127.0.0.1"
}

Since, this is the first time inserting the doc, audit_compliance_diff_is_noop is true and it makes sense for audit_request_body to be logged.

• Update one field in the same document

curl -XPUT -kv -H 'Content-Type: application/json' https://localhost:9200/index1/_doc/4 -u 'admin:xx' -d '{
  "name": "helloword",
  "age": 18
}'

Audit log generated looks like

{
    "audit_compliance_operation": "UPDATE",
    "audit_cluster_name": "opensearch",
    "audit_node_name": "example.com",
    "audit_category": "COMPLIANCE_DOC_WRITE",
    "audit_request_origin": "REST",
    "audit_compliance_doc_version": 3,
    "audit_request_body": "{\n  \"name\": \"helloword\",\n  \"age\": 18\n}",
    "audit_node_id": "oenHT55bTNW4XB358NS7Qw",
    "@timestamp": "2024-07-09T06:56:35.601+00:00",
    "audit_compliance_diff_is_noop": false,
    "audit_format_version": 4,
    "audit_request_remote_address": "::1",
    "audit_trace_doc_id": "4",
    "audit_compliance_diff_content": "[{\"op\":\"replace\",\"path\":\"/name\",\"value\":\"helloword\"}]",
    "audit_node_host_address": "127.0.0.1",
    "audit_request_effective_user": "admin",
    "audit_trace_shard_id": 0,
    "audit_trace_indices": ["index1"],
    "audit_trace_resolved_indices": ["index1"],
    "audit_node_host_name": "127.0.0.1"
}

Note both audit_request_body and audit_compliance_diff_content are getting logged even if log_request_body is disabled and we are updating the same document.

What is the expected behavior?
audit_request_body should not be always logged for compliance audit logs when log_request_body is disabled and it's not the first document insert.

What is your host/environment?

• OS: MacOS

Do you have any additional context?
We check that write_metadata_only == false and write_log_diffs == true here before logging audit_compliance_diff_content

Whereas we only check write_metadata_only == false before logging audit_request_body here
A simple fix is to also add log_request_body == true at the same place AND ensure that it's not the first time when document is being inserted.

[cwperks]

[Triage] Thank you for filing this issue with detailed steps to reproduce. Marking the issue as triaged.

[cwperks]

I believe the full request body being added is because of this line which gets executed when read_metadata_only is set to true.

I'm not familiar with the history of this file so I will see if I can dig into why the full request body is being logged here.

Edit: I believe the body is getting audit logged here for this request. The logic in place is to audit log the whole body is write_metadata_only is false and the request is on the security index.

Edit2: This was already identified in the issue itself. I support the fix proposed:

A simple fix is to also add log_request_body == true at the same place AND ensure that it's not the first time when document is being inserted.

[cwperks]

I created a quick POC pr on my fork here: cwperks#31

Currently, there is a test for a non-security index that is configured with write_watched_indices, but another similar test should be added utilizing security APIs to create and modify security resources and ensure that the diffs are audit logged or the entire body is audit logged when a resource is first created.

[cwperks]

Closing this issue now that #4832 is merged. This will be released in v2.19.0.