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

feature/501-add_trace_id_to_logs_of_erroneous_requests_at_middleware #525

Merged
alexvanin merged 2 commits from r.loginov/frostfs-s3-gw:feature/501-add_trace_id_to_logs_of_erroneous_requests_at_middleware into master 2024-11-02 08:51:49 +00:00
Conversation 2 Commits 2 Files changed 24 +456 -437
r.loginov commented 2024-10-25 02:11:52 +00:00
Member
Copy link

close #501

As part of this task, support was also made for using the request logger in the logAndSendError function. Based on this comment, it was planned to do so in the future. Thanks to this, we can not store the trace id in ReqInfo, but instead add it to the request logger once.

Examples of log output for comparison:

  1. successful put-object:

before:

2024-10-28T11:46:57.218+0300    info    request start   {"request_id": "fe04b982-0eb3-42c2-bca8-08a6dbc80691", "host": "localhost", "remote_host": "127.0.0.1", "namespace": ""}
2024-10-28T11:46:57.224+0300    debug   successful auth {"request_id": "fe04b982-0eb3-42c2-bca8-08a6dbc80691", "accessKeyID": "DqvGvcqXh4zMAjCbh7zuBFsgjZQhiV4NQ63qNrh9KMPf05BGqjJ85Ybzq2gkLV2SBHYK5Ui6WtF4Lm3TVTPXDsiWw"}
2024-10-28T11:46:57.224+0300    debug   policy request  {"request_id": "fe04b982-0eb3-42c2-bca8-08a6dbc80691", "action": "s3:PutObject", "resource": "arn:aws:s3:::cats/testss", "request properties": {"AccessBox-Attribute/FilePath":"1730103779_access.box","AccessBox-Attribute/IAM-MFA":"false","AccessBox-Attribute/Timestamp":"1730103779","AccessBox-Attribute/__SYSTEM__EXPIRATION_EPOCH":"10801","Owner":"NWeByJPgNC97F83hTUnSbnZSBKaFvk5HNw","frostfs:sourceIP":"127.0.0.1","frostfsid:groupID":""}, "resource properties": {}}
2024-10-28T11:46:57.225+0300    info    resolve bucket  {"request_id": "fe04b982-0eb3-42c2-bca8-08a6dbc80691", "cid": "CzdPyXFS5DFg4ne19wv43hVMu6KBbTqZMxjTmTEE1dUi"}
2024-10-28T11:46:57.267+0300    debug   put object      {"request_id": "fe04b982-0eb3-42c2-bca8-08a6dbc80691", "cid": "CzdPyXFS5DFg4ne19wv43hVMu6KBbTqZMxjTmTEE1dUi", "oid": "6Z9j2Q24oCu46Q85mjbi4PVU6HEGZ3hqYdc8NDBv2CAk"}
2024-10-28T11:46:57.269+0300    debug   tree request error      {"request_id": "fe04b982-0eb3-42c2-bca8-08a6dbc80691", "remaining attempts": 0, "address": "localhost:8080", "error": "empty result"}
2024-10-28T11:46:57.271+0300    info    request end     {"request_id": "fe04b982-0eb3-42c2-bca8-08a6dbc80691", "status": 200, "description": "OK", "method": "PutObject", "bucket": "cats", "object": "testss", "user": "NWeByJPgNC97F83hTUnSbnZSBKaFvk5HNw", "trace_id": "06fd38bfaa4fd4d3eb1519d4fe90d800"}

now:

2024-10-28T11:39:33.509+0300    info    request start   {"request_id": "674a3ae0-4f4c-463e-baea-b292430ccbf8", "trace_id": "077d7573bc5852cd3d88c75acd70c9e5", "host": "localhost", "remote_host": "127.0.0.1", "namespace": ""}
2024-10-28T11:39:33.509+0300    debug   successful auth {"request_id": "674a3ae0-4f4c-463e-baea-b292430ccbf8", "trace_id": "077d7573bc5852cd3d88c75acd70c9e5", "accessKeyID": "DqvGvcqXh4zMAjCbh7zuBFsgjZQhiV4NQ63qNrh9KMPf05BGqjJ85Ybzq2gkLV2SBHYK5Ui6WtF4Lm3TVTPXDsiWw"}
2024-10-28T11:39:33.510+0300    debug   policy request  {"request_id": "674a3ae0-4f4c-463e-baea-b292430ccbf8", "trace_id": "077d7573bc5852cd3d88c75acd70c9e5", "action": "s3:PutObject", "resource": "arn:aws:s3:::cats/test", "request properties": {"AccessBox-Attribute/FilePath":"1730103779_access.box","AccessBox-Attribute/IAM-MFA":"false","AccessBox-Attribute/Timestamp":"1730103779","AccessBox-Attribute/__SYSTEM__EXPIRATION_EPOCH":"10801","Owner":"NWeByJPgNC97F83hTUnSbnZSBKaFvk5HNw","frostfs:sourceIP":"127.0.0.1","frostfsid:groupID":""}, "resource properties": {}}
2024-10-28T11:39:33.510+0300    info    resolve bucket  {"request_id": "674a3ae0-4f4c-463e-baea-b292430ccbf8", "trace_id": "077d7573bc5852cd3d88c75acd70c9e5", "cid": "CzdPyXFS5DFg4ne19wv43hVMu6KBbTqZMxjTmTEE1dUi"}
2024-10-28T11:39:33.552+0300    debug   put object      {"request_id": "674a3ae0-4f4c-463e-baea-b292430ccbf8", "trace_id": "077d7573bc5852cd3d88c75acd70c9e5", "cid": "CzdPyXFS5DFg4ne19wv43hVMu6KBbTqZMxjTmTEE1dUi", "oid": "2hmH7fdBuEfhaGaW47KAHnXT3ZrwKW3DrMXFPM94ophG"}
2024-10-28T11:39:33.553+0300    debug   tree request error      {"request_id": "674a3ae0-4f4c-463e-baea-b292430ccbf8", "remaining attempts": 0, "address": "localhost:8080", "error": "not found: rpc error: code = Unknown desc = tree not found"}
2024-10-28T11:39:33.554+0300    info    request end     {"request_id": "674a3ae0-4f4c-463e-baea-b292430ccbf8", "trace_id": "077d7573bc5852cd3d88c75acd70c9e5", "status": 200, "description": "OK", "method": "PutObject", "bucket": "cats", "object": "test", "user": "NWeByJPgNC97F83hTUnSbnZSBKaFvk5HNw"}
  1. creating a bucket with the wrong policy:

before:

2024-10-28T11:47:33.042+0300    info    request start   {"request_id": "ce543568-c325-4ce7-969b-771cff39fa0e", "host": "localhost", "remote_host": "127.0.0.1", "namespace": ""}
2024-10-28T11:47:33.042+0300    debug   successful auth {"request_id": "ce543568-c325-4ce7-969b-771cff39fa0e", "accessKeyID": "DqvGvcqXh4zMAjCbh7zuBFsgjZQhiV4NQ63qNrh9KMPf05BGqjJ85Ybzq2gkLV2SBHYK5Ui6WtF4Lm3TVTPXDsiWw"}
2024-10-28T11:47:33.042+0300    debug   policy request  {"request_id": "ce543568-c325-4ce7-969b-771cff39fa0e", "action": "s3:CreateBucket", "resource": "arn:aws:s3:::dogss", "request properties": {"AccessBox-Attribute/FilePath":"1730103779_access.box","AccessBox-Attribute/IAM-MFA":"false","AccessBox-Attribute/Timestamp":"1730103779","AccessBox-Attribute/__SYSTEM__EXPIRATION_EPOCH":"10801","Owner":"NWeByJPgNC97F83hTUnSbnZSBKaFvk5HNw","frostfs:sourceIP":"127.0.0.1","frostfsid:groupID":""}, "resource properties": {}}
2024-10-28T11:47:33.042+0300    error   request failed  {"request_id": "ce543568-c325-4ce7-969b-771cff39fa0e", "method": "CreateBucket", "bucket": "dogss", "object": "", "description": "could not parse canned ACL", "user": "NWeByJPgNC97F83hTUnSbnZSBKaFvk5HNw", "error": "unknown acl: poblic-read-write", "status": 500, "trace_id": "5dd927cea2b2194c113c0ea961d72c85"}

now:

2024-10-28T11:40:24.545+0300    info    request start   {"request_id": "fc4b9c62-6e8f-457d-8c1b-ea88b85cfe10", "trace_id": "83a2bad171758b3bfef5eeca893858b2", "host": "localhost", "remote_host": "127.0.0.1", "namespace": ""}
2024-10-28T11:40:24.545+0300    debug   successful auth {"request_id": "fc4b9c62-6e8f-457d-8c1b-ea88b85cfe10", "trace_id": "83a2bad171758b3bfef5eeca893858b2", "accessKeyID": "DqvGvcqXh4zMAjCbh7zuBFsgjZQhiV4NQ63qNrh9KMPf05BGqjJ85Ybzq2gkLV2SBHYK5Ui6WtF4Lm3TVTPXDsiWw"}
2024-10-28T11:40:24.545+0300    debug   policy request  {"request_id": "fc4b9c62-6e8f-457d-8c1b-ea88b85cfe10", "trace_id": "83a2bad171758b3bfef5eeca893858b2", "action": "s3:CreateBucket", "resource": "arn:aws:s3:::dogs", "request properties": {"AccessBox-Attribute/FilePath":"1730103779_access.box","AccessBox-Attribute/IAM-MFA":"false","AccessBox-Attribute/Timestamp":"1730103779","AccessBox-Attribute/__SYSTEM__EXPIRATION_EPOCH":"10801","Owner":"NWeByJPgNC97F83hTUnSbnZSBKaFvk5HNw","frostfs:sourceIP":"127.0.0.1","frostfsid:groupID":""}, "resource properties": {}}
2024-10-28T11:40:24.545+0300    error   request failed  {"request_id": "fc4b9c62-6e8f-457d-8c1b-ea88b85cfe10", "trace_id": "83a2bad171758b3bfef5eeca893858b2", "method": "CreateBucket", "bucket": "dogs", "object": "", "description": "could not parse canned ACL", "user": "NWeByJPgNC97F83hTUnSbnZSBKaFvk5HNw", "error": "unknown acl: poblic-read-write", "status": 500}
  1. uploading an object to a non-existent bucket (error at the middleware level):

before:

2024-10-28T11:48:02.108+0300    info    request start   {"request_id": "fe6882c3-4f6c-4928-8f41-2cd0a1851f07", "host": "localhost", "remote_host": "127.0.0.1", "namespace": ""}
2024-10-28T11:48:02.108+0300    debug   successful auth {"request_id": "fe6882c3-4f6c-4928-8f41-2cd0a1851f07", "accessKeyID": "DqvGvcqXh4zMAjCbh7zuBFsgjZQhiV4NQ63qNrh9KMPf05BGqjJ85Ybzq2gkLV2SBHYK5Ui6WtF4Lm3TVTPXDsiWw"}
2024-10-28T11:48:02.109+0300    debug   policy request  {"request_id": "fe6882c3-4f6c-4928-8f41-2cd0a1851f07", "action": "s3:PutObject", "resource": "arn:aws:s3:::catsdfef/testssfw", "request properties": {"AccessBox-Attribute/FilePath":"1730103779_access.box","AccessBox-Attribute/IAM-MFA":"false","AccessBox-Attribute/Timestamp":"1730103779","AccessBox-Attribute/__SYSTEM__EXPIRATION_EPOCH":"10801","Owner":"NWeByJPgNC97F83hTUnSbnZSBKaFvk5HNw","frostfs:sourceIP":"127.0.0.1","frostfsid:groupID":""}, "resource properties": {}}
2024-10-28T11:48:02.109+0300    error   policy validation failed        {"request_id": "fe6882c3-4f6c-4928-8f41-2cd0a1851f07", "error": "NoSuchBucket: 404 => The specified bucket does not exist: nns: couldn't resolve container 'catsdfef': contract invocation: invocation failed: at instruction 3441 (THROW): unhandled exception: \"token not found\""}

now:

2024-10-28T11:40:57.753+0300    info    request start   {"request_id": "abfca710-2727-4905-8c8f-7145371481ca", "trace_id": "9614e9d9402980ab0a0eebc6aa7e8422", "host": "localhost", "remote_host": "127.0.0.1", "namespace": ""}
2024-10-28T11:40:57.759+0300    debug   successful auth {"request_id": "abfca710-2727-4905-8c8f-7145371481ca", "trace_id": "9614e9d9402980ab0a0eebc6aa7e8422", "accessKeyID": "DqvGvcqXh4zMAjCbh7zuBFsgjZQhiV4NQ63qNrh9KMPf05BGqjJ85Ybzq2gkLV2SBHYK5Ui6WtF4Lm3TVTPXDsiWw"}
2024-10-28T11:40:57.759+0300    debug   policy request  {"request_id": "abfca710-2727-4905-8c8f-7145371481ca", "trace_id": "9614e9d9402980ab0a0eebc6aa7e8422", "action": "s3:PutObject", "resource": "arn:aws:s3:::catsddd/test", "request properties": {"AccessBox-Attribute/FilePath":"1730103779_access.box","AccessBox-Attribute/IAM-MFA":"false","AccessBox-Attribute/Timestamp":"1730103779","AccessBox-Attribute/__SYSTEM__EXPIRATION_EPOCH":"10801","Owner":"NWeByJPgNC97F83hTUnSbnZSBKaFvk5HNw","frostfs:sourceIP":"127.0.0.1","frostfsid:groupID":""}, "resource properties": {}}
2024-10-28T11:40:57.760+0300    error   policy validation failed        {"request_id": "abfca710-2727-4905-8c8f-7145371481ca", "trace_id": "9614e9d9402980ab0a0eebc6aa7e8422", "error": "NoSuchBucket: 404 => The specified bucket does not exist: nns: couldn't resolve container 'catsddd': contract invocation: invocation failed: at instruction 3441 (THROW): unhandled exception: \"token not found\""}
close #501 As part of this task, support was also made for using the request logger in the `logAndSendError` function. Based on this comment, it was planned to do so in the future. Thanks to this, we can not store the trace id in `ReqInfo`, but instead add it to the request logger once. Examples of log output for comparison: 1. successful put-object: before: ``` 2024-10-28T11:46:57.218+0300 info request start {"request_id": "fe04b982-0eb3-42c2-bca8-08a6dbc80691", "host": "localhost", "remote_host": "127.0.0.1", "namespace": ""} 2024-10-28T11:46:57.224+0300 debug successful auth {"request_id": "fe04b982-0eb3-42c2-bca8-08a6dbc80691", "accessKeyID": "DqvGvcqXh4zMAjCbh7zuBFsgjZQhiV4NQ63qNrh9KMPf05BGqjJ85Ybzq2gkLV2SBHYK5Ui6WtF4Lm3TVTPXDsiWw"} 2024-10-28T11:46:57.224+0300 debug policy request {"request_id": "fe04b982-0eb3-42c2-bca8-08a6dbc80691", "action": "s3:PutObject", "resource": "arn:aws:s3:::cats/testss", "request properties": {"AccessBox-Attribute/FilePath":"1730103779_access.box","AccessBox-Attribute/IAM-MFA":"false","AccessBox-Attribute/Timestamp":"1730103779","AccessBox-Attribute/__SYSTEM__EXPIRATION_EPOCH":"10801","Owner":"NWeByJPgNC97F83hTUnSbnZSBKaFvk5HNw","frostfs:sourceIP":"127.0.0.1","frostfsid:groupID":""}, "resource properties": {}} 2024-10-28T11:46:57.225+0300 info resolve bucket {"request_id": "fe04b982-0eb3-42c2-bca8-08a6dbc80691", "cid": "CzdPyXFS5DFg4ne19wv43hVMu6KBbTqZMxjTmTEE1dUi"} 2024-10-28T11:46:57.267+0300 debug put object {"request_id": "fe04b982-0eb3-42c2-bca8-08a6dbc80691", "cid": "CzdPyXFS5DFg4ne19wv43hVMu6KBbTqZMxjTmTEE1dUi", "oid": "6Z9j2Q24oCu46Q85mjbi4PVU6HEGZ3hqYdc8NDBv2CAk"} 2024-10-28T11:46:57.269+0300 debug tree request error {"request_id": "fe04b982-0eb3-42c2-bca8-08a6dbc80691", "remaining attempts": 0, "address": "localhost:8080", "error": "empty result"} 2024-10-28T11:46:57.271+0300 info request end {"request_id": "fe04b982-0eb3-42c2-bca8-08a6dbc80691", "status": 200, "description": "OK", "method": "PutObject", "bucket": "cats", "object": "testss", "user": "NWeByJPgNC97F83hTUnSbnZSBKaFvk5HNw", "trace_id": "06fd38bfaa4fd4d3eb1519d4fe90d800"} ``` now: ``` 2024-10-28T11:39:33.509+0300 info request start {"request_id": "674a3ae0-4f4c-463e-baea-b292430ccbf8", "trace_id": "077d7573bc5852cd3d88c75acd70c9e5", "host": "localhost", "remote_host": "127.0.0.1", "namespace": ""} 2024-10-28T11:39:33.509+0300 debug successful auth {"request_id": "674a3ae0-4f4c-463e-baea-b292430ccbf8", "trace_id": "077d7573bc5852cd3d88c75acd70c9e5", "accessKeyID": "DqvGvcqXh4zMAjCbh7zuBFsgjZQhiV4NQ63qNrh9KMPf05BGqjJ85Ybzq2gkLV2SBHYK5Ui6WtF4Lm3TVTPXDsiWw"} 2024-10-28T11:39:33.510+0300 debug policy request {"request_id": "674a3ae0-4f4c-463e-baea-b292430ccbf8", "trace_id": "077d7573bc5852cd3d88c75acd70c9e5", "action": "s3:PutObject", "resource": "arn:aws:s3:::cats/test", "request properties": {"AccessBox-Attribute/FilePath":"1730103779_access.box","AccessBox-Attribute/IAM-MFA":"false","AccessBox-Attribute/Timestamp":"1730103779","AccessBox-Attribute/__SYSTEM__EXPIRATION_EPOCH":"10801","Owner":"NWeByJPgNC97F83hTUnSbnZSBKaFvk5HNw","frostfs:sourceIP":"127.0.0.1","frostfsid:groupID":""}, "resource properties": {}} 2024-10-28T11:39:33.510+0300 info resolve bucket {"request_id": "674a3ae0-4f4c-463e-baea-b292430ccbf8", "trace_id": "077d7573bc5852cd3d88c75acd70c9e5", "cid": "CzdPyXFS5DFg4ne19wv43hVMu6KBbTqZMxjTmTEE1dUi"} 2024-10-28T11:39:33.552+0300 debug put object {"request_id": "674a3ae0-4f4c-463e-baea-b292430ccbf8", "trace_id": "077d7573bc5852cd3d88c75acd70c9e5", "cid": "CzdPyXFS5DFg4ne19wv43hVMu6KBbTqZMxjTmTEE1dUi", "oid": "2hmH7fdBuEfhaGaW47KAHnXT3ZrwKW3DrMXFPM94ophG"} 2024-10-28T11:39:33.553+0300 debug tree request error {"request_id": "674a3ae0-4f4c-463e-baea-b292430ccbf8", "remaining attempts": 0, "address": "localhost:8080", "error": "not found: rpc error: code = Unknown desc = tree not found"} 2024-10-28T11:39:33.554+0300 info request end {"request_id": "674a3ae0-4f4c-463e-baea-b292430ccbf8", "trace_id": "077d7573bc5852cd3d88c75acd70c9e5", "status": 200, "description": "OK", "method": "PutObject", "bucket": "cats", "object": "test", "user": "NWeByJPgNC97F83hTUnSbnZSBKaFvk5HNw"} ``` 2. creating a bucket with the wrong policy: before: ``` 2024-10-28T11:47:33.042+0300 info request start {"request_id": "ce543568-c325-4ce7-969b-771cff39fa0e", "host": "localhost", "remote_host": "127.0.0.1", "namespace": ""} 2024-10-28T11:47:33.042+0300 debug successful auth {"request_id": "ce543568-c325-4ce7-969b-771cff39fa0e", "accessKeyID": "DqvGvcqXh4zMAjCbh7zuBFsgjZQhiV4NQ63qNrh9KMPf05BGqjJ85Ybzq2gkLV2SBHYK5Ui6WtF4Lm3TVTPXDsiWw"} 2024-10-28T11:47:33.042+0300 debug policy request {"request_id": "ce543568-c325-4ce7-969b-771cff39fa0e", "action": "s3:CreateBucket", "resource": "arn:aws:s3:::dogss", "request properties": {"AccessBox-Attribute/FilePath":"1730103779_access.box","AccessBox-Attribute/IAM-MFA":"false","AccessBox-Attribute/Timestamp":"1730103779","AccessBox-Attribute/__SYSTEM__EXPIRATION_EPOCH":"10801","Owner":"NWeByJPgNC97F83hTUnSbnZSBKaFvk5HNw","frostfs:sourceIP":"127.0.0.1","frostfsid:groupID":""}, "resource properties": {}} 2024-10-28T11:47:33.042+0300 error request failed {"request_id": "ce543568-c325-4ce7-969b-771cff39fa0e", "method": "CreateBucket", "bucket": "dogss", "object": "", "description": "could not parse canned ACL", "user": "NWeByJPgNC97F83hTUnSbnZSBKaFvk5HNw", "error": "unknown acl: poblic-read-write", "status": 500, "trace_id": "5dd927cea2b2194c113c0ea961d72c85"} ``` now: ``` 2024-10-28T11:40:24.545+0300 info request start {"request_id": "fc4b9c62-6e8f-457d-8c1b-ea88b85cfe10", "trace_id": "83a2bad171758b3bfef5eeca893858b2", "host": "localhost", "remote_host": "127.0.0.1", "namespace": ""} 2024-10-28T11:40:24.545+0300 debug successful auth {"request_id": "fc4b9c62-6e8f-457d-8c1b-ea88b85cfe10", "trace_id": "83a2bad171758b3bfef5eeca893858b2", "accessKeyID": "DqvGvcqXh4zMAjCbh7zuBFsgjZQhiV4NQ63qNrh9KMPf05BGqjJ85Ybzq2gkLV2SBHYK5Ui6WtF4Lm3TVTPXDsiWw"} 2024-10-28T11:40:24.545+0300 debug policy request {"request_id": "fc4b9c62-6e8f-457d-8c1b-ea88b85cfe10", "trace_id": "83a2bad171758b3bfef5eeca893858b2", "action": "s3:CreateBucket", "resource": "arn:aws:s3:::dogs", "request properties": {"AccessBox-Attribute/FilePath":"1730103779_access.box","AccessBox-Attribute/IAM-MFA":"false","AccessBox-Attribute/Timestamp":"1730103779","AccessBox-Attribute/__SYSTEM__EXPIRATION_EPOCH":"10801","Owner":"NWeByJPgNC97F83hTUnSbnZSBKaFvk5HNw","frostfs:sourceIP":"127.0.0.1","frostfsid:groupID":""}, "resource properties": {}} 2024-10-28T11:40:24.545+0300 error request failed {"request_id": "fc4b9c62-6e8f-457d-8c1b-ea88b85cfe10", "trace_id": "83a2bad171758b3bfef5eeca893858b2", "method": "CreateBucket", "bucket": "dogs", "object": "", "description": "could not parse canned ACL", "user": "NWeByJPgNC97F83hTUnSbnZSBKaFvk5HNw", "error": "unknown acl: poblic-read-write", "status": 500} ``` 3. uploading an object to a non-existent bucket (error at the middleware level): before: ``` 2024-10-28T11:48:02.108+0300 info request start {"request_id": "fe6882c3-4f6c-4928-8f41-2cd0a1851f07", "host": "localhost", "remote_host": "127.0.0.1", "namespace": ""} 2024-10-28T11:48:02.108+0300 debug successful auth {"request_id": "fe6882c3-4f6c-4928-8f41-2cd0a1851f07", "accessKeyID": "DqvGvcqXh4zMAjCbh7zuBFsgjZQhiV4NQ63qNrh9KMPf05BGqjJ85Ybzq2gkLV2SBHYK5Ui6WtF4Lm3TVTPXDsiWw"} 2024-10-28T11:48:02.109+0300 debug policy request {"request_id": "fe6882c3-4f6c-4928-8f41-2cd0a1851f07", "action": "s3:PutObject", "resource": "arn:aws:s3:::catsdfef/testssfw", "request properties": {"AccessBox-Attribute/FilePath":"1730103779_access.box","AccessBox-Attribute/IAM-MFA":"false","AccessBox-Attribute/Timestamp":"1730103779","AccessBox-Attribute/__SYSTEM__EXPIRATION_EPOCH":"10801","Owner":"NWeByJPgNC97F83hTUnSbnZSBKaFvk5HNw","frostfs:sourceIP":"127.0.0.1","frostfsid:groupID":""}, "resource properties": {}} 2024-10-28T11:48:02.109+0300 error policy validation failed {"request_id": "fe6882c3-4f6c-4928-8f41-2cd0a1851f07", "error": "NoSuchBucket: 404 => The specified bucket does not exist: nns: couldn't resolve container 'catsdfef': contract invocation: invocation failed: at instruction 3441 (THROW): unhandled exception: \"token not found\""} ``` now: ``` 2024-10-28T11:40:57.753+0300 info request start {"request_id": "abfca710-2727-4905-8c8f-7145371481ca", "trace_id": "9614e9d9402980ab0a0eebc6aa7e8422", "host": "localhost", "remote_host": "127.0.0.1", "namespace": ""} 2024-10-28T11:40:57.759+0300 debug successful auth {"request_id": "abfca710-2727-4905-8c8f-7145371481ca", "trace_id": "9614e9d9402980ab0a0eebc6aa7e8422", "accessKeyID": "DqvGvcqXh4zMAjCbh7zuBFsgjZQhiV4NQ63qNrh9KMPf05BGqjJ85Ybzq2gkLV2SBHYK5Ui6WtF4Lm3TVTPXDsiWw"} 2024-10-28T11:40:57.759+0300 debug policy request {"request_id": "abfca710-2727-4905-8c8f-7145371481ca", "trace_id": "9614e9d9402980ab0a0eebc6aa7e8422", "action": "s3:PutObject", "resource": "arn:aws:s3:::catsddd/test", "request properties": {"AccessBox-Attribute/FilePath":"1730103779_access.box","AccessBox-Attribute/IAM-MFA":"false","AccessBox-Attribute/Timestamp":"1730103779","AccessBox-Attribute/__SYSTEM__EXPIRATION_EPOCH":"10801","Owner":"NWeByJPgNC97F83hTUnSbnZSBKaFvk5HNw","frostfs:sourceIP":"127.0.0.1","frostfsid:groupID":""}, "resource properties": {}} 2024-10-28T11:40:57.760+0300 error policy validation failed {"request_id": "abfca710-2727-4905-8c8f-7145371481ca", "trace_id": "9614e9d9402980ab0a0eebc6aa7e8422", "error": "NoSuchBucket: 404 => The specified bucket does not exist: nns: couldn't resolve container 'catsddd': contract invocation: invocation failed: at instruction 3441 (THROW): unhandled exception: \"token not found\""} ```
r.loginov self-assigned this 2024-10-25 02:11:52 +00:00
r.loginov added 2 commits 2024-10-25 02:11:52 +00:00 
Signed-off-by: Roman Loginov <r.loginov@yadro.com>
[#501] Add the trace id to the logs of middlware
All checks were successful
/ DCO (pull_request) Successful in 47s
Details
/ Vulncheck (pull_request) Successful in 57s
Details
/ Builds (pull_request) Successful in 1m30s
Details
/ Lint (pull_request) Successful in 3m5s
Details
/ Tests (pull_request) Successful in 1m43s
Details
50bb21210e 
Signed-off-by: Roman Loginov <r.loginov@yadro.com>
r.loginov force-pushed feature/501-add_trace_id_to_logs_of_erroneous_requests_at_middleware from 50bb21210e to 6a00aa2269 2024-10-25 02:16:49 +00:00 Compare
r.loginov commented 2024-10-25 02:34:12 +00:00
Author
Member
Copy link

Ideally, I would also like to display the trace id in the request start log. However, I will not be able to figure out how to do it in a beautiful way. We cannot move the tracing middleware before the request middleware, because the tracing uses the request id from ReqInfo, which in turn is formed in the request middleware. The only option that can be considered is to move the span initialization logic from tracing middleware to request middleware. However, it seems that this violates the SRP.

Ideally, I would also like to display the trace id in the [request start log](https://git.frostfs.info/TrueCloudLab/frostfs-s3-gw/src/branch/master/api/middleware/reqinfo.go#L193). However, I will not be able to figure out how to do it in a beautiful way. We cannot move the tracing middleware before the request middleware, because the tracing uses the request id from ReqInfo, which in turn is formed in the request middleware. The only option that can be considered is to move the [span initialization](https://git.frostfs.info/TrueCloudLab/frostfs-s3-gw/src/branch/master/api/middleware/tracing.go#L19) logic from tracing middleware to request middleware. However, it seems that this violates the SRP.
r.loginov requested review from alexvanin 2024-10-25 02:35:35 +00:00
r.loginov requested review from dkirillov 2024-10-25 02:35:35 +00:00
r.loginov requested review from pogpp 2024-10-25 02:35:35 +00:00
r.loginov requested review from mbiryukova 2024-10-25 02:35:35 +00:00
r.loginov requested review from nzinkevich 2024-10-25 02:35:36 +00:00
dkirillov approved these changes 2024-10-25 14:12:36 +00:00
Dismissed
dkirillov left a comment
Member
Copy link

LGTM

LGTM
dkirillov commented 2024-10-25 14:16:28 +00:00
Member
Copy link

Ideally, I would also like to display the trace id in the request start log. However, I will not be able to figure out how to do it in a beautiful way. We cannot move the tracing middleware before the request middleware, because the tracing uses the request id from ReqInfo, which in turn is formed in the request middleware. The only option that can be considered is to move the span initialization logic from tracing middleware to request middleware. However, it seems that this violates the SRP.

I don't mind to move trace initialization into Request middleware

> Ideally, I would also like to display the trace id in the [request start log](https://git.frostfs.info/TrueCloudLab/frostfs-s3-gw/src/branch/master/api/middleware/reqinfo.go#L193). However, I will not be able to figure out how to do it in a beautiful way. We cannot move the tracing middleware before the request middleware, because the tracing uses the request id from ReqInfo, which in turn is formed in the request middleware. The only option that can be considered is to move the [span initialization](https://git.frostfs.info/TrueCloudLab/frostfs-s3-gw/src/branch/master/api/middleware/tracing.go#L19) logic from tracing middleware to request middleware. However, it seems that this violates the SRP. I don't mind to move trace initialization into `Request` middleware
👍 1
r.loginov force-pushed feature/501-add_trace_id_to_logs_of_erroneous_requests_at_middleware from 6a00aa2269 to 3357706e60 2024-10-28 08:49:00 +00:00 Compare
r.loginov dismissed dkirillov's review 2024-10-28 08:49:01 +00:00
Reason:

New commits pushed, approval review dismissed automatically according to repository settings

mbiryukova approved these changes 2024-10-28 09:00:58 +00:00
dkirillov approved these changes 2024-10-28 09:04:30 +00:00
alexvanin approved these changes 2024-11-02 08:51:44 +00:00
alexvanin merged commit 539dab8680 into master 2024-11-02 08:51:49 +00:00
alexvanin deleted branch feature/501-add_trace_id_to_logs_of_erroneous_requests_at_middleware 2024-11-02 08:51:53 +00:00
Sign in to join this conversation.
Reviewers
No reviewers
pogpp
nzinkevich
mbiryukova
dkirillov
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
r.loginov
4 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#525
No description provided.
Delete branch "r.loginov/frostfs-s3-gw:feature/501-add_trace_id_to_logs_of_erroneous_requests_at_middleware"

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?