Audit log timestamp is not the time of event, but the time when the line is written to the file

[burdandrei]

Describe the bug
I was debugging some revoke issues and enabled raw audit log according to the Docs

When I compared the lines from regular and raw audit log I found that timestamp on the event is not identical:

To Reproduce

1. Enable regular audit log:

vault audit enable -path=file file \
        file_path=/tmp/audit.log

2. Enable Raw Audit log

vault audit enable -path=file_raw file \
        file_path=/tmp/audit-law.log \
        log_raw=true

3. compare the timestamp of the event

Expected behavior
Event timestamp should be equal across all the logs

Environment:

• Vault Server Version:

$ vault status
Key             Value
---             -----
Seal Type       shamir
Initialized     true
Sealed          false
Total Shares    1
Threshold       1
Version         1.3.2
Cluster Name    vault-cluster-cd519e13
Cluster ID      0f3e572d-f2a9-5565-50c7-210552fd7859
HA Enabled      false

• Vault CLI Version:
  Vault v1.3.2

• Server Operating System/Architecture:
  Ubuntu 18.04 amd64

Vault server configuration file(s):
not applicable, running in vault server -dev mode

[catsby]

Hey @burdandrei!

Thanks for reporting this issue. The timestamps are generated when the audit log entry is formatted:

• vault/audit/format.go

  Line 135 in e6dca6a

  reqEntry.Time = time.Now().UTC().Format(time.RFC3339Nano)

Indeed, using different formatters will generate slightly different timestamps. Fortunately we’ve already begun working internally to address this issue, however the work is not yet complete and we don’t have an exact timeline for completion.

I’ll leave this issue open and marked as a bug, and I’ll optimistically attach this issue to the 1.5 release milestone for review, but I can’t guarantee it will remain there and be included in that release. Thanks again!

[burdandrei]

Thanks, @catsby!

[pbernal]

Some of the audit work we have been working on internally will not be addressing this particular issue in 1.5. Marking this as triaged for now, and will provide an update in the future.

[aphorise]

Thinking aloud - each of these audits are a separate ledger which are typically SHA256 / HMAC-ed and in the raw case a correlating match should already be possible by request.id / response.id (for comparison / selection).

I personally would expect a slight difference in the times between each audit device especially since HMAC entries need to be repeated for as many audits as exist (each audit with different salt). The HMACs are processes at a separate times / per device (discarding hardware factors or size of inputs).

The only thing that I'd expect - that's different to the screenshot you've shared - is for raw / non-HMAC audits to always be faster / 1st since there's no HMAC functions being applied for any field. I confirmed the same behaviour in my testing where all audit devices after raw where always with greater reported time irrespective of the order by which they have been enabled / disabled. The only thing I didnt test is multiple raw audit devices that's not really typical.

hey @catsby @burdandrei I was curious what's the repercussions of the audit times not being co-equal? trying to understand why this may be important.

[heatherezell]

Closing as resolved in #26088