Audit log will be truncated in each of the log msg when splitting into several logs.

Products

• VMware NSX

Issue/Introduction

Symptoms:
Audit logs are experiencing truncation when they are split into multiple log messages. Users are unable to view the complete audit log message when logs are split across files, specifically within the files `/var/log/nsx-audit-write.log` and `/var/log/nsx-audit.log`.
 

Example: /var/log/nsx-audit-write.log

(This is the " splitIndex="1 of 2") 
The Log starts here:
<182>1 2023-06-23T23:56:12.125Z nsxmgr1 NSX 4794 - [nsx@6876 audit="true" comp="nsx-manager" level="INFO" reqId="<UUID_1>" splitId="<USERNAME>" splitIndex="1 of 2" subcomp="manager" update="true"] UserName="admin", ModuleName="Policy", Operation="PatchInfra", Operation status="success", Old value=[{"action":"DROP","resource_type":"Rule","id":"Rule_1","display_name":"Rule 1a","path":"/infra/domains/default/security-policies/First_Policy/rules/Rule_1","relative_path":"Rule_1","parent_path":"/infra/domains/default/security-policies/First_Policy","unique_id":"########-####-####-####-########2025","realization_id":"########-####-####-####-########2025","owner_id":"########-####-####-####-########a714","origin_site_id":"########-####-####-####-########a714","marked_for_delete":false,"overridden":false,"rule_id":2025,"sequence_number":10,"sources_excluded":false,"destinations_excluded":false,"source_groups":["/infra/domains/default/groups/1-test","/infra/domains/default/groups/3-test","/infra/domains/default/groups/Lab","/infra/domains/default/groups/4-test","/infra/domains/default/groups/2-test"],"destination_groups":["/infra/domains/default/groups/2-test","/infra/domains/default/groups/1-test","/infra/domains/default/groups/3-test","/infra/domains/default/groups/NSX"],"services":["/infra/services/Active_Directory_Server_UDP"],"profiles":["ANY"],"logged":false,"scope":["ANY"],"disabled":true,"direction":"IN_OUT","ip_protocol":"IPV4_IPV6","is_default":false,"_create_time":1687534181077,"_create_user":"admin","_last_modified_time":1687563927451,"_last_modified_user":"admin","_system_owned":false,"_protection":"NOT_PROTECTED","_revision":7}{"action":"ALLOW","resource_type":"Rule","id":"Rule_2","display_name":"Rule 2a","path":"/infra/domains/default/security-policies/First_Policy/rules/Rule_2","relative_path":"Rule_2","parent_path":"/infra/domains/default/security-policies/First_Policy","unique_id":"########-####-####-####-########2024","realization_id":"########-####-####-####-########2024","owner_id":"########-####-####-####-########a714","origin_site_id":"########-####-####-####-########a714","marked_for_delete":false,"overridden":false,"rule_id":2024,"sequence_number":5,"sources_excluded":false,"destinations_excluded":false,"source_groups":["/infra/domains/default/groups/########-####-####-####-########0957","/infra/domains/default/groups/1-test","/infra/domains/default/groups/3-test","/infra/domains/default/groups/4-test","/infra/domains/default/groups/2-test"],"destination_groups":["/infra/domains/default/groups/2-test","/infra/domains/default/groups/1-test","/infra/domains/default/groups/3-test","/infra/domains/default/groups/4-test"],"services":["/infra/services/AD_Server","/infra/services/DNS-UDP"],"profiles":["ANY"],"logged":false,"scope":["ANY"],"disabled":false,"direction":"IN_OUT","ip_protocol":"IPV4_IPV6","is_default":false,"_create_time":1687534181050,"_create_user":"admin","_last_modified_time":1687563927434,"_last_modified_user":"admin","_system_owned":false,"_protection":"NOT_PROTECTED","_revision":7}{"action":"ALLOW","resource_type":"Rule","id":"Rule_4","display_name":"Rule 4","path":"/infra/domains/default/security-policies/First_Policy/rules/Rule_4","relative_path":"Rule_4","parent_path":"/infra/domains/default/security-policies/First_Policy","unique_id":"########-####-####-####-########2028","realization_id":"########-####-####-####-########2028","owner_id":"########-####-####-####-########a714","origin_site_id":"########-####-####-####-########a714","marked_for_delete":false,"overridden":false,"rule_id":2028,"sequence_number":1,"sources_excluded":false,"destinations_excluded":false,"source_groups":["/infra/domains/default/groups/1-test","/infra/domains/default/groups/3-test","/infra/domains/default/groups/5-test","/infra/domains/default/groups/2-test"],"destination_groups":["/infra/domains/default/groups/2-test","/infra/domains/default/groups/1-test","/infra/domains/default/groups/6-test"],"services":["/infra/services/Active_Directory_Server","/infra/services/CIM-HTTP"],"profiles":["ANY"],"logged":false,"scope":["ANY"],"disabled":false,"direction":"IN_OUT","ip_protocol":"IPV4_IPV6","is_default":false,"_create_time":1687538427295,"_create_user":"admin","_last_modified_time":1687563927400,"_last_modified_user":"admin","_system_owned":false,"_protection":"NOT_PROTECTED","_revision":4}{"action":"ALLOW","resource_type":"Rule","id":"Rule_3a","display_name":"Rule 3a","path":"/infra/domains/default/security-policies/First_Policy/rules/Rule_3a","relative_path":"Rule_3a","parent_path":"/infra/domains/default/security-policies/First_Policy","unique_id":"########-####-####-####-########2027","realization_id":"########-####-####-####-########2027","owner_id":"########-####-####-####-########a714","origin_site_id":"########-####-####-####-########a714","marked_for_delete":false,"overridden":false,"rule_id":2027,"sequence_number":2,"sources_excluded":false,"destinations_excluded":false,"source_groups":["/infra/domains/default/groups/1-test","/infra/domains/default/groups/3-test","/infra/domains/default/groups/2-test"],"destination_groups":["/infra/domains/default/groups/2-test","/infra/domains/default/groups/1-test","/infra/domains/default/groups/3-test","/infra/domains/default/groups/4-test"],"services":["/infra/services/AD_Server","/infra/services/Active_Directory_Server_UDP"],"profiles":["ANY"],"logged":false,"scope":["ANY"],"disabled":false,"direction":"IN_OUT","ip_protocol":"IPV4_IPV6","is_default":false,"_create_time":1687538042443,"_create_user":"admin","_last_modified_time":1687563927420,"_last_modified_user":"admin","_system_owned":false,"_protection":"NOT_PROTECTED","_revision":5}], New value=[{"enforce_revision_check":true} {"resource_type":"Infra","children":[{"children":[{"SecurityPolicy":{"logging_enabled":false,"target_type":"DFW","resource_type":"SecurityPolicy","id":"First_Policy","display_name":"First Policy","path":"/infra/domains/default/security-policies/First_Policy","unique_id":"########-####-####-####-########63b5","realization_id":"########-####-####-####-########63b5","owner_id":"########-####-####-####-########a714","origin_site_id":"########-####-####-####-########a714","children":[{"Rule":{"action":"ALLOW","resource_type":"Rule","id":"Rule_4","display_name":"Rule 4","path":"/infra/domains/default/security-policies/First_Policy/rules/Rule_4","unique_id":"########-####-####-####-########2028","realization_id":"########-####-####-####-########2028","owner_id":"########-####-####-####-########a714","origin_site_id":"########-####-####-####-########a714","marked_for_delete":false,"overridden":false,"rule_id":2028,"sequence_number":1,"sources_excluded":false,"destinations_excluded":false,"source_groups":["/infra/domains/default/groups/1-test","/infra/domains/default/groups/3-test","/infra/domains/default/groups/5-test","/infra/domains/default/groups/2-test"],"destination_groups":["/infra/domains/default/groups/2-test","/infra/domains/default/groups/1-test","/infra/domains/default/groups/6-test","/infra/domains/default/groups/3-test"],"services":["/infra/services/Active_Directory_Server","/infra/services/CIM-HTTP"],"profiles":["ANY"],"logged":false,"scope":["ANY"],"disabled":false,"direction":"IN_OUT","ip_protocol":"IPV4_IPV6","is_default":false,"_revision":4},"resource_type":"ChildRule","marked_for_delete":false,"mark_for_override":false},{"Rule":{"action":"ALLOW","resource_type":"Rule","id":"Rule_3a","display_name":"Rule 3a","path":"/infra/domains/default/security-policies/First_Policy/rules/Rule_3a","unique_id":"########-####-####-####-########2027","realization_id":"########-####-####-####-########2027","owner_id":"########-####-####-####-########a714","origin_site_id":"########-####-####-####-########a714","marked_for_delete":false,"overridden":false,"rule_id":2027,"sequence_number":2,"sources_excluded":false,"destinations_excluded":false,"source_groups":["/infra/domains/default/groups/1-test","/infra/domains/default/groups/3-test","/infra/domains/default/groups/2-test","/infra/domains/defaul ---> The log is split here ending with the word "defaul" instead of "default/and some other missed data". Then, the second part of the log starts without adding the data missed.

(This is the splitIndex="2 of 2")   
Second log starts: 
<182>1 2023-06-23T23:56:12.125Z nsxmgr1 NSX 4794 - [nsx@6876 audit="true" comp="nsx-manager" level="INFO" reqId="<UUID_1>" splitId="<USERNAME>" splitIndex="2 of 2" subcomp="manager" update="true"] false,"scope":["ANY"],"disabled":false,"direction":"IN_OUT","ip_protocol":"IPV4_IPV6","is_default":false,"_revision":5},"resource_type":"ChildRule","marked_for_delete":false,"mark_for_override":false},{"Rule":{"action":"ALLOW","resource_type":"Rule","id":"Rule_2","display_name":"Rule 2a","path":"/infra/domains/default/security-policies/First_Policy/rules/Rule_2","unique_id":"########-####-####-####-########2024","realization_id":"########-####-####-####-########2024","owner_id":"########-####-####-####-########a714","origin_site_id":"########-####-####-####-########a714","marked_for_delete":false,"overridden":false,"rule_id":2024,"sequence_number":5,"sources_excluded":false,"destinations_excluded":false,"source_groups":["/infra/domains/default/groups/########-####-####-####-########0957","/infra/domains/default/groups/1-test","/infra/domains/default/groups/3-test","/infra/domains/default/groups/4-test","/infra/domains/default/groups/2-test"],"destination_groups":["/infra/domains/default/groups/2-test","/infra/domains/default/groups/1-test","/infra/domains/default/groups/3-test","/infra/domains/default/groups/4-test","/infra/domains/default/groups/5-test"],"services":["/infra/services/AD_Server","/infra/services/DNS-UDP"],"profiles":["ANY"],"logged":false,"scope":["ANY"],"disabled":false,"direction":"IN_OUT","ip_protocol":"IPV4_IPV6","is_default":false,"_revision":7},"resource_type":"ChildRule","marked_for_delete":false,"mark_for_override":false},{"Rule":{"action":"DROP","resource_type":"Rule","id":"Rule_1","display_name":"Rule 1a","path":"/infra/domains/default/security-policies/First_Policy/rules/Rule_1","unique_id":"########-####-####-####-########2025","realization_id":"########-####-####-####-########2025","owner_id":"########-####-####-####-########a714","origin_site_id":"########-####-####-####-########a714","marked_for_delete":false,"overridden":false,"rule_id":2025,"sequence_number":10,"sources_excluded":false,"destinations_excluded":false,"source_groups":["/infra/domains/default/groups/1-test","/infra/domains/default/groups/3-test","/infra/domains/default/groups/Lab","/infra/domains/default/groups/4-test","/infra/domains/default/groups/2-test"],"destination_groups":["/infra/domains/default/groups/2-test","/infra/domains/default/groups/1-test","/infra/domains/default/groups/3-test","/infra/domains/default/groups/NSX","/infra/domains/default/groups/4-test"],"services":["/infra/services/Active_Directory_Server_UDP"],"profiles":["ANY"],"logged":false,"scope":["ANY"],"disabled":true,"direction":"IN_OUT","ip_protocol":"IPV4_IPV6","is_default":false,"_revision":7},"resource_type":"ChildRule","marked_for_delete":false,"mark_for_override":false}],"marked_for_delete":false,"overridden":false,"sequence_number":10,"internal_sequence_number":60000010,"category":"Application","stateful":true,"tcp_strict":true,"locked":false,"lock_modified_time":0,"scope":["ANY"],"is_default":false,"_revision":2},"resource_type":"ChildSecurityPolicy","marked_for_delete":false,"mark_for_override":false}],"target_type":"Domain","resource_type":"ChildResourceReference","id":"default","marked_for_delete":false,"mark_for_override":false}],"marked_for_delete":false,"overridden":false,"_revision":-1}]  <----The log ends here

Environment

VMware NSX-T

Cause

There is a logic to truncate the long log message into smaller chunks while ensuring that each chunk doesn't exceed 8192. It tries to split the log at the specified delimiter character: colon if possible, making the split log segments more meaningful. If colon is not found within the wrapLength, it still splits the log to avoid exceeding the length limit.But, when the issue is presented, the logs are split incorrectly without following the the structure explained before.

Resolution

Before, the log's truncate point was hard coded to 8192 characters for log msg(without header, eg.time, structure data) in code and split happened here. But this truncate point is larger than rsyslog.conf defined 8096 characters(by default, and this is for the full msg which include the header). So that is why the log will be truncate after split, it is done by rsyslog.conf. In our fix. We add logic to adjust the code defined truncate point by referring to the rsyslog.conf's config. And make sure to reserve 300 characters for log's header(eg. time, structure data in the complete log msg)

Workaround:
No available

Additional Information

Versions where this is a known issue: Version before 4.1.2

Impact/Risks:
The truncation and splitting issue can result in users missing vital information when viewing the split logs in '/var/log/nsx-audit-write.log' and '/var/log/nsx-audit.log'.