TrueCloudLab/frostfs-s3-gw
15
3
Fork 18
Code Issues 28 Pull requests 4 Projects Releases 17 Packages Activity Actions

[#369] Enhanced http requests logging #426

Merged
alexvanin merged 1 commit from nzinkevich/frostfs-s3-gw:feature/9613-enhanced_log into feature/369 2024-09-04 19:51:14 +00:00
Conversation 0 Commits 1 Files changed 12 +211 -70
nzinkevich commented 2024-07-15 07:37:34 +00:00
Member
Copy link

Signed-off-by: Nikita Zinkevich n.zinkevich@yadro.com

Signed-off-by: Nikita Zinkevich <n.zinkevich@yadro.com>
nzinkevich added 1 commit 2024-07-15 07:37:36 +00:00
[#369] Enhanced http requests logging
All checks were successful
/ DCO (pull_request) Successful in 1m47s
Details
/ Vulncheck (pull_request) Successful in 1m48s
Details
/ Lint (pull_request) Successful in 3m52s
Details
/ Tests (1.20) (pull_request) Successful in 2m22s
Details
/ Tests (1.21) (pull_request) Successful in 2m20s
Details
/ Builds (1.20) (pull_request) Successful in 1m15s
Details
/ Builds (1.21) (pull_request) Successful in 1m32s
Details
8e2a927334 
Signed-off-by: Nikita Zinkevich <n.zinkevich@yadro.com>
alexvanin changed title from WIP: [#369] Enhanced http requests logging to WIP: [#369] Enhanced http requests logging 2024-07-15 07:48:46 +00:00
alexvanin changed target branch from master to feature/369 2024-07-15 07:48:47 +00:00
dkirillov reviewed 2024-07-15 08:22:32 +00:00
api/middleware/log_http.go Outdated
@ -0,0 +29,4 @@
httplog = withFieldIfExist(httplog, "query", r.URL.Query())
httplog = withFieldIfExist(httplog, "headers", r.Header)
if r.ContentLength != 0 && r.ContentLength <= settings.MaxBody {
dkirillov commented 2024-07-15 08:22:20 +00:00
Member
Copy link

Sometimes r.ContentLength can be -1 that means unknown length. Now we will try read body and get panic in withBody when try to allocate new buffer var body = make([]byte, r.ContentLength).

Should we ignore such body or log first settings.MaxBody bytes anyway?

Sometimes `r.ContentLength` can be `-1` that means unknown length. Now we will try read body and get panic in `withBody` when try to allocate new buffer `var body = make([]byte, r.ContentLength)`. Should we ignore such body or log first `settings.MaxBody` bytes anyway?
dkirillov marked this conversation as resolved
api/middleware/log_http.go Outdated
@ -0,0 +44,4 @@
func withBody(httplog *zap.Logger, r *http.Request) (*zap.Logger, error) {
var body = make([]byte, r.ContentLength)
_, err := r.Body.Read(body)
dkirillov commented 2024-07-15 08:17:39 +00:00
Member
Copy link

We need close body after read.

Besides, we must preserve initial body in request. After read the body doesn't contain anything and in handlers we get errors. For example:

2024-07-15T11:11:06.778+0300    error   handler/util.go:50      request failed  {"request_id": "07e96f1e-13a7-423c-91f7-b69513209ebd", "method": "PutObject", "bucket": "test", "object": "tmp", "description": "could not upload object", "user": "NbUgTSFvPmsRxmGeWpuuGeJUoRoi6PErcM", "error": "InvalidDigest: 400 => The Content-Md5 you specified is not valid.", "body close errors": [], "status": 400}
We need close body after read. Besides, we must preserve initial body in request. After read the body doesn't contain anything and in handlers we get errors. For example: ``` 2024-07-15T11:11:06.778+0300 error handler/util.go:50 request failed {"request_id": "07e96f1e-13a7-423c-91f7-b69513209ebd", "method": "PutObject", "bucket": "test", "object": "tmp", "description": "could not upload object", "user": "NbUgTSFvPmsRxmGeWpuuGeJUoRoi6PErcM", "error": "InvalidDigest: 400 => The Content-Md5 you specified is not valid.", "body close errors": [], "status": 400} ```
dkirillov marked this conversation as resolved
api/router.go Outdated
@ -129,6 +130,7 @@ type Config struct {
func NewRouter(cfg Config) *chi.Mux {
api := chi.NewRouter()
api.Use(
s3middleware.LogHTTP(cfg.Log, cfg.LogHTTP),
dkirillov commented 2024-07-15 07:59:58 +00:00
Member
Copy link

If enabling this middleware being configured only once (and don't support SIGHUP reload) we can add it conditionally (like s3middleware.FrostfsIDValidation)

If enabling this middleware being configured only once (and don't support SIGHUP reload) we can add it conditionally (like `s3middleware.FrostfsIDValidation`)
cmd/s3-gw/app_settings.go Outdated
@ -75,6 +75,9 @@ const ( // Settings.
cfgLoggerLevel = "logger.level"
cfgLoggerDestination = "logger.destination"
cfgLoggerRequestEnabled = "http_logging.enabled"
dkirillov commented 2024-07-15 08:01:03 +00:00
Member
Copy link

We should mention this params in config/config.env and docs/configuration.md

We should mention this params in `config/config.env` and `docs/configuration.md`
dkirillov commented 2024-07-15 08:01:27 +00:00
Member
Copy link

We should mention this params in config/config.env and docs/configuration.md

We should mention this params in `config/config.env` and `docs/configuration.md`
dkirillov marked this conversation as resolved
cmd/s3-gw/app_settings.go Outdated
@ -76,2 +76,4 @@
cfgLoggerDestination = "logger.destination"
cfgLoggerRequestEnabled = "http_logging.enabled"
cfgLoggerRequestMaxBody = "http_logging.max_body"
dkirillov commented 2024-07-15 08:01:33 +00:00
Member
Copy link

We should mention this params in config/config.env and docs/configuration.md

We should mention this params in `config/config.env` and `docs/configuration.md`
dkirillov marked this conversation as resolved
internal/logs/logs.go Outdated
@ -142,3 +103,1 @@
CouldntCacheSubject = "couldn't cache subject info"
UserGroupsListIsEmpty = "user groups list is empty, subject not found"
CouldntCacheUserKey = "couldn't cache user key"
dkirillov commented 2024-07-15 07:55:51 +00:00
Member
Copy link

Empty line

Empty line
dkirillov marked this conversation as resolved
nzinkevich added 1 commit 2024-07-16 08:01:46 +00:00
[#369] Write log to file
Some checks failed
/ DCO (pull_request) Successful in 1m35s
Details
/ Vulncheck (pull_request) Successful in 2m3s
Details
/ Builds (1.20) (pull_request) Successful in 3m10s
Details
/ Builds (1.21) (pull_request) Successful in 2m15s
Details
/ Lint (pull_request) Failing after 3m19s
Details
/ Tests (1.20) (pull_request) Successful in 3m4s
Details
/ Tests (1.21) (pull_request) Successful in 2m57s
Details
95c2fa7fda 
Signed-off-by: Nikita Zinkevich <n.zinkevich@yadro.com>
nzinkevich force-pushed feature/9613-enhanced_log from 95c2fa7fda to ea51fe6e4b 2024-07-16 12:22:27 +00:00 Compare
alexvanin reviewed 2024-07-17 06:36:22 +00:00
alexvanin left a comment
Owner
Copy link

Overall looks quite pretty. I suppose we can merge it in feature branch after comment fixes.

Overall looks quite pretty. I suppose we can merge it in feature branch after comment fixes.
api/middleware/log_http.go Outdated
@ -0,0 +42,4 @@
return func(h http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
var err error
config.fileLogger, err = getFileLogger(config)
alexvanin commented 2024-07-17 06:26:30 +00:00
Owner
Copy link

It looks quite odd for me to see config field initialized by the function, that reads config as a parameter. Either filerLogger should not be a part of config structure or getFileLogger should be defined as function on config struct. Prefer making pure functions when it is possible and reasonable.

I suggest to do something like

func LogHTTP() Func {
  return func() http.Handler {
    fileLogger, err = getFileLogger(config)
    if err != nil {
        // log error and skip this middleware by returing handler with single h.ServerHTTP(w, r) call
    }
    return http.HandlerFunc(func(w, r) {
      log = fileLogger.With(...)
      ...
      h.ServerHTTP(w, r)
    }
It looks quite odd for me to see `config` field initialized by the function, that reads config as a parameter. Either `filerLogger` should not be a part of config structure or `getFileLogger` should be defined as function on config struct. Prefer making [pure functions](https://en.wikipedia.org/wiki/Pure_function) when it is possible and reasonable. I suggest to do something like ```go func LogHTTP() Func { return func() http.Handler { fileLogger, err = getFileLogger(config) if err != nil { // log error and skip this middleware by returing handler with single h.ServerHTTP(w, r) call } return http.HandlerFunc(func(w, r) { log = fileLogger.With(...) ... h.ServerHTTP(w, r) } ```
alexvanin marked this conversation as resolved
api/middleware/log_http.go Outdated
@ -0,0 +112,4 @@
return err
}
config.sinkPath = SinkName + ":" + pth
alexvanin commented 2024-07-17 06:27:51 +00:00
Owner
Copy link

As previous comment mentioned, try to make this function pure by returing sinkPath instead of config modification. This pattern is valid overall but it doesn't make sense here.

As previous comment mentioned, try to make this function pure by returing `sinkPath` instead of config modification. This pattern is valid overall but it doesn't make sense here.
alexvanin marked this conversation as resolved
docs/configuration.md Outdated
@ -376,0 +389,4 @@
| Parameter | Type | SIGHUP reload | Default value | Description |
|----------------|--------|---------------|---------------|-------------------------------------------------------------------------------------------------------------------------------------------------------------------------|
| `enabled` | bool | yes | false | |
| `max_body` | int | yes | 1024 | Max body size for log output. |
alexvanin commented 2024-07-17 06:33:13 +00:00
Owner
Copy link

Is it bytes, kilobytes, megabytes?

Is it bytes, kilobytes, megabytes?
alexvanin marked this conversation as resolved
docs/configuration.md Outdated
@ -376,0 +390,4 @@
|----------------|--------|---------------|---------------|-------------------------------------------------------------------------------------------------------------------------------------------------------------------------|
| `enabled` | bool | yes | false | |
| `max_body` | int | yes | 1024 | Max body size for log output. |
| `max_log_size` | int | yes | 50 | Log file size threshold (in Megabytes) to be moved in backup file. |
alexvanin commented 2024-07-17 06:32:28 +00:00
Owner
Copy link

Where are backup files are stored? Is it in destination dir?

Where are backup files are stored? Is it in destination dir?
alexvanin marked this conversation as resolved
docs/configuration.md Outdated
@ -376,0 +392,4 @@
| `max_body` | int | yes | 1024 | Max body size for log output. |
| `max_log_size` | int | yes | 50 | Log file size threshold (in Megabytes) to be moved in backup file. |
| `gzip` | bool | yes | false | Whether to enable Gzip compression for backup log files. |
| `destination` | string | yes | stdout | Specify path for log output. Accepts path string (maybe even URL - not tested) to log in file, or "stdout" and "stderr" reserved phrases for printing in output stream. |
alexvanin commented 2024-07-17 06:31:15 +00:00
Owner
Copy link

Do not mention URL if we didn't test it. 😃 Also, can we test it? What do we need to do that?

Also, I suppose destination is a path to dir, not a file, am I right?

Do not mention URL if we didn't test it. 😃 Also, can we test it? What do we need to do that? Also, I suppose `destination` is a path to dir, not a file, am I right?
nzinkevich commented 2024-07-17 07:00:14 +00:00
Author
Member
Copy link

destination specifies path with filename e.g. /var/log/http.log. During backup the filename is added with timestamp. And a new file with initial name creates.
I will append this to configuration.md

`destination` specifies path with filename e.g. /var/log/http.log. During backup the filename is added with timestamp. And a new file with initial name creates. I will append this to configuration.md
alexvanin marked this conversation as resolved
nzinkevich force-pushed feature/9613-enhanced_log from ea51fe6e4b to 7e6212264d 2024-07-17 10:49:14 +00:00 Compare
nzinkevich force-pushed feature/9613-enhanced_log from 7e6212264d to e358e0d8b9 2024-07-17 10:56:09 +00:00 Compare
nzinkevich force-pushed feature/9613-enhanced_log from e358e0d8b9 to 6f3bedc023 2024-07-17 12:20:16 +00:00 Compare
nzinkevich changed title from WIP: [#369] Enhanced http requests logging to [#369] Enhanced http requests logging 2024-07-17 12:52:05 +00:00
alexvanin approved these changes 2024-07-18 06:21:22 +00:00
alexvanin merged commit 6f3bedc023 into feature/369 2024-07-18 06:22:26 +00:00
alexvanin deleted branch feature/9613-enhanced_log 2024-07-18 06:22:34 +00:00
Sign in to join this conversation.
Reviewers
No reviewers
alexvanin
Labels
Clear labels   
P0

Highest

  
P1

High

  
P2

Medium

  
P3

Low

  
good first issue

Good for newcomers

  
Infrastructure

Infrastructure, Automation, CI/CD or DevOps related stuff

  
blocked

The issue or PR is blocked by something

  
bug

Something is not working

  
config

Configuration format update or breaking change

  
discussion

Talking about something in order to reach a decision or to exchange ideas

  
documentation

Documentation related

  
duplicate

This issue or pull request already exists

  
enhancement

New feature

  
go

Language features adoption

  
help wanted

Extra attention is needed

  
internal

   
invalid

Something is wrong

  
kludge

This is a kludge and we know it

  
observability

Related to metrics, tracing and logs

  
perfomance

Perfomance related

  
question

More information is needed

  
refactoring

Refactoring

  
wontfix

This won't be fixed

No labels
P0
P1
P2
P3
good first issue
Infrastructure
blocked
bug
config
discussion
documentation
duplicate
enhancement
go
help wanted
internal
invalid
kludge
observability
perfomance
question
refactoring
wontfix
Milestone
Clear milestone
No items
No milestone
Projects
Clear projects
No items
No project
Assignees
Clear assignees
No assignees
3 participants
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference: TrueCloudLab/frostfs-s3-gw#426
No description provided.
Delete branch "nzinkevich/frostfs-s3-gw:feature/9613-enhanced_log"

Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?