Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Parse external request id from request headers, and print it in access log #22906

Merged
merged 24 commits into from
Mar 10, 2023

Conversation

sillyguodong
Copy link
Contributor

@sillyguodong sillyguodong commented Feb 14, 2023

Close: #22890.


Configure in .ini file:

[log]
REQUEST_ID_HEADERS = X-Request-ID, X-Trace-Id

Params in Request Header

X-Trace-ID: trace-id-1q2w3e4r

image

Log output:

image

@wxiaoguang
Copy link
Contributor

Maybe these headers could be added to access log, but not the routing log. Although in most cases you see the routing logs and treat them as access logs, but the routing logs are mainly for debug purpose, and are always subjected to be changed.

@GiteaBot GiteaBot added the lgtm/need 2 This PR needs two approvals by maintainers to be considered for merging. label Feb 14, 2023
@sillyguodong
Copy link
Contributor Author

Maybe these headers could be added to access log, but not the routing log. Although in most cases you see the routing logs and treat them as access logs, but the routing logs are mainly for debug purpose, and are always subjected to be changed.

I think you're right. i will put it into access log. thank you for your suggestion!

@sillyguodong sillyguodong changed the title Parse external request id from request headers, and print it in router log Parse external request id from request headers, and print it in access log Feb 14, 2023
@sillyguodong
Copy link
Contributor Author

sillyguodong commented Feb 14, 2023

Now, if user specify the location of the RequestID in ACCESS_LOG_TEMPLATE like this:
image

We can see it in access.log:
image

@zeripath
Copy link
Contributor

linting is failing I'm afraid

@sillyguodong
Copy link
Contributor Author

linting is failing I'm afraid

It should be ok now.

@pboguslawski
Copy link
Contributor

BTW: chi router uses value from X-Request-ID request header as request ID instead of own generated request ID.

@sillyguodong
Copy link
Contributor Author

BTW: chi router uses value from X-Request-ID request header as request ID instead of own generated request ID.

hi.
i don't find it that we use RequestID middleware in gitea's web router.
So, i think it won't be conflict?

@pboguslawski
Copy link
Contributor

pboguslawski commented Feb 14, 2023

So, i think it won't be conflict?

Agree. Just pointed to chi solution in case gitea will need reqid in the future in other places also not just for logging (passing reqid with context sounds good).

@techknowlogick
Copy link
Member

Thanks for this PR :)

I wonder if it should only accept overrides from the trusted reverse proxy setting to prevent an end user being able to set the request ID (same protections we have in place for accepting forwarded IPs)

@pboguslawski
Copy link
Contributor

pboguslawski commented Feb 14, 2023

I wonder if it should only accept overrides from the trusted reverse proxy

Fetching reqid from header should be disabled by default and enabled only if admin knows what they are doing. Don't know giteas forwarded IPs protections and if they are suitable here.

@wolfogre
Copy link
Member

... to prevent an end user being able to set the request ID ...

That's incorrect, unlike X-Forwarded-For, X-Request-ID is designed for an end user, they should be able to set it and use it to trace requests. It doesn't make sense if the ID has been overrided by reverse proxy.

However, you reminded me, we should have some protection, maybe length limitation is enough, to prevent printing a huge request id in log.

@sillyguodong
Copy link
Contributor Author

now, if length of X-Request-ID (or other header) is more than 256 bits, the id will be printed like this:
image

@pboguslawski
Copy link
Contributor

pboguslawski commented Feb 15, 2023

now, if length of X-Request-ID (or other header) is more than 256 bits, the id will be printed like this

Consider limiting to 36 or 40 bytes for UUID not to be truncated in logs.

@pboguslawski
Copy link
Contributor

pboguslawski commented Feb 15, 2023

It doesn't make sense if the ID has been overrided by reverse proxy

It makes sense if someone wants to trace request flow between many internal systems and sets such header on front proxy (replacing any value provided by client).

@wolfogre
Copy link
Member

It doesn't make sense if the ID has been overrided by reverse proxy

It makes sense if someone wants to trace request flow between many internal systems and sets such header on front proxy (replacing any value provided by client).

I understand, as you said, "only if admin knows what they are doing".

@wxiaoguang
Copy link
Contributor

Fetching reqid from header should be disabled by default

It doesn't make sense if the ID has been overrided by reverse proxy

It makes sense if someone wants to trace request flow between many internal systems and sets such header on front proxy (replacing any value provided by client).

In this case, the header is always set by the front proxy, still no need to disable it if it doesn't come from "trusted-ip".

IMO this request header is just like host oruser-agent, it could just be passed as it is, and it can be set by reverse proxies, since it's not related to security logic (that's different from X-Real-Ip)

enabled only if admin knows what they are doing.

Admins could just use access logs without the RequestID field if they do not want to see or trust the RequestID.

At least, this header shouldn't be mixed with trusted reverse proxy which is dedicated for X-Real-Ip related headers.

@lafriks
Copy link
Member

lafriks commented Feb 20, 2023

What about X-Correlation-Id and Correlation-Id?

;; * E.g:
;; * In reuqest Header: X-Request-ID: test-id-123
;; * Configuration in app.ini: REQUEST_ID_HEADERS = X-Request-ID
;; * Print in log: 127.0.0.1:58384 - - [14/Feb/2023:16:33:51 +0800] "test-id-123"
Copy link
Contributor

@wxiaoguang wxiaoguang Feb 20, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh wait, the + should be +. There is no HTML, do not use HTML entity.

(And below, many +)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

emmm...
It seems that template.Execute() escapes the + to the HTML entity.
I will try to fix it

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh wait, the + should be +. There is no HTML, do not use HTML entity.

(And below, many +)

I solved the problem.
Use "text/template" instead of "html/template" and no escaping will occur~
But this PR have been passed, do I keep pushing on my own branch?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sorry, I don't understand why you need text/template or html/template. Aren't these just some comments? Feel free to ignore my comment if that's done by purpose.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

image
In the image, upper part is the output of "html/template", + is indeed escaped.
The comment in app.example.ini was copied from access.log directly. But I did not find this problem at the time.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This may be a previous bug? Need to create a new PR?

"html/template"

logTemplate, _ := template.New("log").Parse(setting.Log.AccessLogTemplate)

err := logTemplate.Execute(buf, routerLoggerOptions{

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The bug was introduced by #14475 . Before, it used text/template as my expectation. But #14475 used the incorrect html/template ...... since then, nobody ever found this bug because the logger is rarely used .....

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This may be a previous bug? Need to create a new PR?

It depends. If I was the PR author, I would fix the bug together to save maintainer's time.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

okey, I get it~thx

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@sillyguodong Could you also merge #23013 into this PR?

@sillyguodong
Copy link
Contributor Author

What about X-Correlation-Id and Correlation-Id?

Hi, you can configure it in app.ini file like this:
REQUEST_ID_HEADERS = X-Correlation-Id
The key of the specific request header can be fully customized...

@wolfogre wolfogre reopened this Feb 21, 2023
lunny added a commit that referenced this pull request Feb 21, 2023
Backport #23013

Fix #22906 (comment)

Co-authored-by: Lunny Xiao <xiaolunwen@gmail.com>
Codeberg-org pushed a commit to Codeberg-org/gitea that referenced this pull request Feb 23, 2023
…o-gitea#23025)

Backport go-gitea#23013

Fix go-gitea#22906 (comment)

Co-authored-by: Lunny Xiao <xiaolunwen@gmail.com>
(cherry picked from commit 8fa62be)
@lunny lunny added the reviewed/wait-merge This pull request is part of the merge queue. It will be merged soon. label Mar 9, 2023
;; * E.g:
;; * In reuqest Header: X-Trace-ID: trace-id-1q2w3e4r
;; * Configuration in app.ini: REQUEST_ID_HEADERS = X-Request-ID, X-Trace-ID, X-Req-ID
;; * Print in log: 127.0.0.1:58384 - - [14/Feb/2023:16:33:51 &#43;0800] "trace-id-1q2w3e4r"
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The &#43; should be fixed.

@codecov-commenter
Copy link

Codecov Report

Merging #22906 (29283b1) into main (e6df743) will decrease coverage by 0.03%.
The diff coverage is 5.88%.

❗ Current head 29283b1 differs from pull request most recent head b387a1e. Consider uploading reports for the commit b387a1e to get more accurate results

📣 This organization is not using Codecov’s GitHub App Integration. We recommend you install it so Codecov can continue to function properly for your repositories. Learn more

@@            Coverage Diff             @@
##             main   #22906      +/-   ##
==========================================
- Coverage   47.61%   47.58%   -0.03%     
==========================================
  Files        1147     1147              
  Lines      151196   151213      +17     
==========================================
- Hits        71985    71950      -35     
- Misses      70700    70761      +61     
+ Partials     8511     8502       -9     
Impacted Files Coverage Δ
modules/context/access_log.go 0.00% <0.00%> (ø)
modules/setting/log.go 58.42% <100.00%> (+0.15%) ⬆️

... and 11 files with indirect coverage changes

Help us with your feedback. Take ten seconds to tell us how you rate us. Have a feature suggestion? Share it here.

@jolheiser
Copy link
Member

🎺 🤖

@jolheiser jolheiser merged commit 5155ec3 into go-gitea:main Mar 10, 2023
@jolheiser jolheiser removed the reviewed/wait-merge This pull request is part of the merge queue. It will be merged soon. label Mar 10, 2023
zjjhot added a commit to zjjhot/gitea that referenced this pull request Mar 13, 2023
* giteaofficial/main:
  Scoped label display and documentation tweaks (go-gitea#23430)
  Deduplicate template code for label selection menu (go-gitea#23431)
  Show edit/close/delete button on organization wide repositories (go-gitea#23388)
  Sync the class change of Edit Column Button to JS code (go-gitea#23400)
  Preserve file size when creating attachments (go-gitea#23406)
  [skip ci] Updated translations via Crowdin
  Use buildkit for docker builds (go-gitea#23415)
  Refactor branch/tag selector dropdown (first step) (go-gitea#23394)
  [skip ci] Updated translations via Crowdin
  Hide target selector if tag exists when creating new release (go-gitea#23171)
  Parse external request id from request headers, and print it in access log (go-gitea#22906)
  Add missing tabs to org projects page (go-gitea#22705)
  Add user webhooks (go-gitea#21563)
  Handle OpenID discovery URL errors a little nicer when creating/editing sources (go-gitea#23397)
  Split CI pipelines (go-gitea#23385)
@go-gitea go-gitea locked and limited conversation to collaborators May 3, 2023
@sillyguodong sillyguodong deleted the feature/issue_22890 branch February 29, 2024 03:31
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
lgtm/done This PR has enough approvals to get merged. There are no important open reservations anymore. type/enhancement An improvement of existing functionality
Projects
None yet
Development

Successfully merging this pull request may close these issues.

External request ID logging