audit: Fix duplicated request logs #1659

elebedeva · 2025-03-03T06:27:54Z

elebedeva commented

2025-03-03 06:27:54 +00:00

When we do object put with audit enabled we get two entries in logs: with and without object id:

info        audit/request.go:42        audit event log record        {"operation": "/neo.fs.v2.object.ObjectService/Put", "object": "ChHV5uWYNG43chL1h93MJsC5aEiGpvXHSFvy8o2kYQia/empty", "subject": "0231f92b6e2584bdb941030ea600956be61537cd69ec3fe157c0cbd62cddbf10a2", "success": true, "trace_id": "2db6b49b130c3ffb3f1ba98f02da575d"}
info        audit/request.go:42        audit event log record        {"operation": "/neo.fs.v2.object.ObjectService/Put", "object": "ChHV5uWYNG43chL1h93MJsC5aEiGpvXHSFvy8o2kYQia/CWpd8EH9hReo6JJTk9zodPW8N9VjG2RkHDgYhmywxPWk", "subject": "0231f92b6e2584bdb941030ea600956be61537cd69ec3fe157c0cbd62cddbf10a2", "success": true, "trace_id": "2db6b49b130c3ffb3f1ba98f02da575d"}

Now:

info	audit/request.go:42	audit event log record	{"operation": "/neo.fs.v2.object.ObjectService/Put", "object": "GyERdgH1p8uXwDNTtRKQ4Pzj4xiHKiGsfidZdL9Jv8fL/ATYYHNnwr4bkoHzqKS1s1rKzyFNzSMJ6jeDrECBfqAFi", "subject": "031a6c6fbbdf02ca351745fa86b9ba5a9452d785ac4f7fc2b7548ca2a46c4fcf4a", "success": true, "trace_id": "ab575477fee1038dd93c5c0a3c2fac94"}

Signed-off-by: Ekaterina Lebedeva ekaterina.lebedeva@yadro.com

When we do `object put` with audit enabled we get two entries in logs: with and without object id: ``` info audit/request.go:42 audit event log record {"operation": "/neo.fs.v2.object.ObjectService/Put", "object": "ChHV5uWYNG43chL1h93MJsC5aEiGpvXHSFvy8o2kYQia/empty", "subject": "0231f92b6e2584bdb941030ea600956be61537cd69ec3fe157c0cbd62cddbf10a2", "success": true, "trace_id": "2db6b49b130c3ffb3f1ba98f02da575d"} info audit/request.go:42 audit event log record {"operation": "/neo.fs.v2.object.ObjectService/Put", "object": "ChHV5uWYNG43chL1h93MJsC5aEiGpvXHSFvy8o2kYQia/CWpd8EH9hReo6JJTk9zodPW8N9VjG2RkHDgYhmywxPWk", "subject": "0231f92b6e2584bdb941030ea600956be61537cd69ec3fe157c0cbd62cddbf10a2", "success": true, "trace_id": "2db6b49b130c3ffb3f1ba98f02da575d"} ``` Now: ``` info audit/request.go:42 audit event log record {"operation": "/neo.fs.v2.object.ObjectService/Put", "object": "GyERdgH1p8uXwDNTtRKQ4Pzj4xiHKiGsfidZdL9Jv8fL/ATYYHNnwr4bkoHzqKS1s1rKzyFNzSMJ6jeDrECBfqAFi", "subject": "031a6c6fbbdf02ca351745fa86b9ba5a9452d785ac4f7fc2b7548ca2a46c4fcf4a", "success": true, "trace_id": "ab575477fee1038dd93c5c0a3c2fac94"} ``` Signed-off-by: Ekaterina Lebedeva <ekaterina.lebedeva@yadro.com>

elebedeva added 1 commit 2025-03-03 06:27:55 +00:00

[#1659 ] audit: Fix duplicated request logs

Vulncheck / Vulncheck (pull_request) Successful in 1m6s

Details

Pre-commit hooks / Pre-commit (pull_request) Successful in 1m17s

Details

Tests and linters / Run gofumpt (pull_request) Successful in 2m36s

Details

Tests and linters / Staticcheck (pull_request) Successful in 2m56s

Details

Tests and linters / Tests (pull_request) Successful in 3m3s

Details

Tests and linters / Tests with -race (pull_request) Successful in 3m0s

Details

Tests and linters / Lint (pull_request) Successful in 3m5s

Details

Tests and linters / gopls check (pull_request) Successful in 3m40s

Details

DCO action / DCO (pull_request) Successful in 26s

Details

Build / Build Components (pull_request) Successful in 1m26s

Details

cab33ead2e

When we do `object put` with audit enabled we get two entries in
logs: with and without object id.
This fix is supposed to keep only one audit log entry with OID.

Signed-off-by: Ekaterina Lebedeva <ekaterina.lebedeva@yadro.com>

requested reviews from storage-core-committers, storage-core-developers

2025-03-03 06:27:55 +00:00

fyrchik reviewed 2025-03-03 06:29:54 +00:00

pkg/services/object/audit.go Outdated

					
				@ -164,3 +164,3 @@

						a.failed = true

					}

					if !errors.Is(err, util.ErrAbortStream) { // CloseAndRecv will not be called, so log here

					if !errors.Is(err, util.ErrAbortStream) && a.objectID != nil { // CloseAndRecv will not be called, so log here

fyrchik commented

2025-03-03 06:29:54 +00:00

Could you explain, why this was called multiple times?
I would expect that if there is an error, that is it, finish.

Could you explain, **why** this was called multiple times? I would expect that if there is an error, that is it, finish.

fyrchik commented

2025-03-03 06:30:30 +00:00

The explanation should be a part of the commit message.

elebedeva commented

2025-03-06 09:41:08 +00:00

Updated commit message.

When we do object put with audit enabled we get several entries in logs: with and without object id.

object put request is logged in 2 places:

(*auditPutStream) CloseAndRecv() - when the client closes the request stream or when stream gets aborted.
(*auditPutStream) Send() - when stream was NOT aborted.

Send() does error check for ErrAbortStream because if there is any other error - CloseAndRecv will not be called and there won't be any audit log about failed request.
It led to logging on every object chunck put, even if err == nil.

Updated commit message. When we do `object put` with audit enabled we get several entries in logs: with and without object id. `object put` request is logged in 2 places: 1. `(*auditPutStream) CloseAndRecv()` - when the client closes the request stream or when stream gets aborted. 2. `(*auditPutStream) Send()` - when stream was NOT aborted. `Send()` does error check for `ErrAbortStream` because if there is any other error - CloseAndRecv will not be called and there won't be any audit log about failed request. It led to logging on every object chunck put, even if `err == nil`.

fyrchik commented

2025-03-06 10:19:54 +00:00

Ok, this PR is approved by me.

But why do we call CloseAndRecv() only for this specific error and not for others? It seems there could be multiple logic errors, and if CloseAndRecv() does some kind of a graceful shutdown, we should always do it.

Ok, this PR is approved by me. But why do we call `CloseAndRecv()` only for this specific error and not for others? It seems there could be multiple logic errors, and if `CloseAndRecv()` does some kind of a graceful shutdown, we should always do it.

dstepanov-yadro commented

2025-03-06 10:51:34 +00:00

See

if err := stream.Send(gStream.Context(), patchReq); err != nil {

I don't know why this was done this way.

See https://git.frostfs.info/TrueCloudLab/frostfs-node/src/commit/4c8f9580a16eb5d30320d670849585fe25c1d04d/pkg/network/transport/object/grpc/service.go#L54 I don't know why this was done this way.

fyrchik commented

2025-03-06 11:20:44 +00:00

Did some digging
It was introduced in 7f5fb130c0 (diff-f9fb9a9419164dc9a10f6de9003e9b0d771cfa48)
And it seems we use it to treat signature error as a status error.

Did some digging It was introduced in https://git.frostfs.info/TrueCloudLab/frostfs-node/commit/7f5fb130c006337de41e5b141d8861bdb581a2d4#diff-f9fb9a9419164dc9a10f6de9003e9b0d771cfa48 And it seems we use it to treat signature error as a status error.