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

Quieter HTTP 206 logging: #550

Merged
merged 21 commits into from
Nov 21, 2024

Conversation

jacobweinstock
Copy link
Member

@jacobweinstock jacobweinstock commented Nov 17, 2024

Description

Logging all 206 partial content requests from the middleware package creates a lot of messages per ISO request. In testing this was around 3000 requests. This is too many logs and will create too much noise.

There is an HTTP middleware in Smee that logs a single line for all requests. This PR stops the middleware logger from logging anything when the X-Global-Logging header is set in the HTTP response. This allows HTTP handler functions to decide if middleware logging should occur or not.

For the ISO HTTP handler function we disable the middleware logging and only sample the HTTP 206 request messages. The following is an example output from an ISO mount using the 0.002% sampling rate. My estimate is that this sampling rate us about 5 - 10 log messages per ISO mount.

The first 8 lines are from when the system is booting up the ISO mounted as a virtual CDROM/DVD. The last 3 lines are from when HookOS boots up and mounts the ISO as a CDROM device.

{"level":"info","ts":1732046233.118308,"caller":"iso/iso.go:195","msg":"magic string found, patching the content","method":"GET","urlPath":"/hook-latest-lts-x86_64-efi-initrd.iso/iso/de-ad-be-ef-fe-ed/hook.iso","xff":"192.168.2.205, 192.168.2.205","remoteAddr":"192.168.2.205:35630","totalCount":48,"contentRange":"bytes 195100672-195133439/195420160"}
{"level":"info","ts":1732046241.343277,"caller":"iso/iso.go:152","msg":"HTTP GET method received with a 206 status code","method":"GET","urlPath":"/hook-latest-lts-x86_64-efi-initrd.iso/iso/de-ad-be-ef-fe-ed/hook.iso","xff":"192.168.2.205, 192.168.2.205","remoteAddr":"192.168.2.205:58796","totalCount":512}
{"level":"info","ts":1732046246.5436597,"caller":"iso/iso.go:152","msg":"HTTP GET method received with a 206 status code","method":"GET","urlPath":"/hook-latest-lts-x86_64-efi-initrd.iso/iso/de-ad-be-ef-fe-ed/hook.iso","xff":"192.168.2.205, 192.168.2.205","remoteAddr":"192.168.2.205:35488","totalCount":828}
{"level":"info","ts":1732046257.9578667,"caller":"iso/iso.go:152","msg":"HTTP GET method received with a 206 status code","method":"GET","urlPath":"/hook-latest-lts-x86_64-efi-initrd.iso/iso/de-ad-be-ef-fe-ed/hook.iso","xff":"192.168.2.205, 192.168.2.205","remoteAddr":"192.168.2.205:60176","totalCount":1424}
{"level":"info","ts":1732046269.1992714,"caller":"iso/iso.go:152","msg":"HTTP GET method received with a 206 status code","method":"GET","urlPath":"/hook-latest-lts-x86_64-efi-initrd.iso/iso/de-ad-be-ef-fe-ed/hook.iso","xff":"192.168.2.205, 192.168.2.205","remoteAddr":"192.168.2.205:46840","totalCount":2089}
{"level":"info","ts":1732046273.146468,"caller":"iso/iso.go:152","msg":"HTTP GET method received with a 206 status code","method":"GET","urlPath":"/hook-latest-lts-x86_64-efi-initrd.iso/iso/de-ad-be-ef-fe-ed/hook.iso","xff":"192.168.2.205, 192.168.2.205","remoteAddr":"192.168.2.205:49070","totalCount":2334}
{"level":"info","ts":1732046282.2612996,"caller":"iso/iso.go:152","msg":"HTTP GET method received with a 206 status code","method":"GET","urlPath":"/hook-latest-lts-x86_64-efi-initrd.iso/iso/de-ad-be-ef-fe-ed/hook.iso","xff":"192.168.2.205, 192.168.2.205","remoteAddr":"192.168.2.205:39434","totalCount":2897}
{"level":"info","ts":1732046282.5963988,"caller":"iso/iso.go:152","msg":"HTTP GET method received with a 206 status code","method":"GET","urlPath":"/hook-latest-lts-x86_64-efi-initrd.iso/iso/de-ad-be-ef-fe-ed/hook.iso","xff":"192.168.2.205, 192.168.2.205","remoteAddr":"192.168.2.205:39606","totalCount":2917}
{"level":"info","ts":1732046385.6623178,"caller":"iso/iso.go:142","msg":"HTTP HEAD method received","method":"HEAD","urlPath":"/hook-latest-lts-x86_64-efi-initrd.iso/iso/de-ad-be-ef-fe-ed/hook.iso","xff":"192.168.2.205, 192.168.2.205","remoteAddr":"192.168.2.205:36474","totalCount":3010}
{"level":"info","ts":1732046393.1938548,"caller":"iso/iso.go:142","msg":"HTTP HEAD method received","method":"HEAD","urlPath":"/hook-latest-lts-x86_64-efi-initrd.iso/iso/de-ad-be-ef-fe-ed/hook.iso","xff":"192.168.2.205, 192.168.2.205","remoteAddr":"192.168.2.205:36502","totalCount":3012}
{"level":"info","ts":1732046393.6070883,"caller":"iso/iso.go:195","msg":"magic string found, patching the content","method":"GET","urlPath":"/hook-latest-lts-x86_64-efi-initrd.iso/iso/de-ad-be-ef-fe-ed/hook.iso","xff":"192.168.2.205, 192.168.2.205","remoteAddr":"192.168.2.205:36814","totalCount":3045,"contentRange":"bytes 195035136-195158015/195420160"}

Also added is some checking/validation around content-size. A max content size of 512Kb is implemented.

And finally, the Tiltfile was updated and implements live updates. Any associated kustomize directories and files were removed and deploying Smee is done via the stack helm chart.

Why is this needed

Fixes: #

How Has This Been Tested?

How are existing users impacted? What migration steps/scripts do we need?

Checklist:

I have:

  • updated the documentation and/or roadmap (if required)
  • added unit or e2e tests
  • provided instructions on how to upgrade

Copy link

codecov bot commented Nov 18, 2024

Codecov Report

Attention: Patch coverage is 37.50000% with 55 lines in your changes missing coverage. Please review.

Project coverage is 50%. Comparing base (e74e9fa) to head (edd662d).
Report is 22 commits behind head on main.

Files with missing lines Patch % Lines
internal/iso/iso.go 40% 41 Missing and 7 partials ⚠️
internal/ipxe/http/middleware.go 0% 6 Missing ⚠️
cmd/smee/main.go 0% 1 Missing ⚠️
Additional details and impacted files
@@         Coverage Diff         @@
##           main   #550   +/-   ##
===================================
  Coverage    49%    50%           
===================================
  Files        27     27           
  Lines      2951   2975   +24     
===================================
+ Hits       1461   1502   +41     
+ Misses     1447   1421   -26     
- Partials     43     52    +9     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.


🚨 Try these New Features:

@jacobweinstock jacobweinstock force-pushed the quieter-logging-for-iso branch 2 times, most recently from 753dc2d to ef7a651 Compare November 18, 2024 18:49
internal/iso/iso.go Outdated Show resolved Hide resolved
internal/iso/iso_test.go Outdated Show resolved Hide resolved
internal/iso/iso.go Outdated Show resolved Hide resolved
internal/iso/iso.go Outdated Show resolved Hide resolved
internal/iso/iso.go Outdated Show resolved Hide resolved
cmd/smee/main.go Outdated Show resolved Hide resolved
cmd/smee/main.go Outdated Show resolved Hide resolved
@jacobweinstock jacobweinstock force-pushed the quieter-logging-for-iso branch from a309391 to 1befe8a Compare November 18, 2024 23:38
@jacobweinstock jacobweinstock changed the title Clean up and make logging quieter: Quieter HTTP 206 logging: Nov 19, 2024
@jacobweinstock jacobweinstock force-pushed the quieter-logging-for-iso branch 2 times, most recently from c973dc0 to b2279f9 Compare November 19, 2024 21:42
internal/iso/iso.go Outdated Show resolved Hide resolved
@jacobweinstock jacobweinstock force-pushed the quieter-logging-for-iso branch 2 times, most recently from 6a07cea to c3fb60b Compare November 20, 2024 20:20
Logging all 206 partial content requests from
the middleware package creates a lot of messages
per ISO request. This stops the middleware logger
from logging anything and lets the ISO http func handler
decide what to log. In the happy path case we only
log that patching happened successfully.

Signed-off-by: Jacob Weinstock <[email protected]>
This library allows for sampling log messages
that match some certain criteria. I have not implemented
this in Smee, but this could allow for sampling each
unique mac address in the url path. This would be as
opposed to having all traffic be sampled together.
This needs tested to see if it's worth it. If it's
not there are other ways to do the sampling in the same
way without needing to import a library.

Signed-off-by: Jacob Weinstock <[email protected]>
Remove all old manifests and use Tilt to
deploy the stack via Helm and rebuild Smee
and deploy a new image on changes.

Signed-off-by: Jacob Weinstock <[email protected]>
There was a merge conflict and I removed
needed go.sum lines. This adds them back.

Signed-off-by: Jacob Weinstock <[email protected]>
The sampling import isn't needed for now.
The most simple case of using a random number
below a percentage will suffice for now.

Signed-off-by: Jacob Weinstock <[email protected]>
Signed-off-by: Jacob Weinstock <[email protected]>
This is needed for clients that request the entire
ISO in one request as opposed to the 206 partial
content requests.

Signed-off-by: Jacob Weinstock <[email protected]>
This creates a test ISO, patches it
and validates the patch. I need to clean it
up a bit though.

Signed-off-by: Jacob Weinstock <[email protected]>
This library seems more maintained and allows
for reading files in an ISO without having to mount
it to the disk.

Signed-off-by: Jacob Weinstock <[email protected]>
This adds logging output to the test
results and makes them more difficult to
read.

Signed-off-by: Jacob Weinstock <[email protected]>
Signed-off-by: Jacob Weinstock <[email protected]>
Signed-off-by: Jacob Weinstock <[email protected]>
Signed-off-by: Jacob Weinstock <[email protected]>
I was just ignoring the error, so an error
is now just returned as 0.

Signed-off-by: Jacob Weinstock <[email protected]>
Signed-off-by: Jacob Weinstock <[email protected]>
This allows us to avoid having to write a
file to disk in a unit test.

Signed-off-by: Jacob Weinstock <[email protected]>
This is a work in progress to handle ranges that
could cause the patching to read into memory
large chunk sizes. This could cause OOM killing
and/or DOS the service.

Signed-off-by: Jacob Weinstock <[email protected]>
The live update makes the development loop
quite fast.

Signed-off-by: Jacob Weinstock <[email protected]>
@jacobweinstock jacobweinstock force-pushed the quieter-logging-for-iso branch from c3fb60b to 4b18a16 Compare November 21, 2024 07:00
If the request is a partial content request,
we need to validate the Content-Range header.
Because we read the entire response body into
memory for patching, we need to ensure that the
Content-Range is within a reasonable size.
For now, we are limiting the size to 500Kb.

Signed-off-by: Jacob Weinstock <[email protected]>
Remove reference to my local machine.

Signed-off-by: Jacob Weinstock <[email protected]>
Signed-off-by: Jacob Weinstock <[email protected]>
@jacobweinstock jacobweinstock force-pushed the quieter-logging-for-iso branch from 1000e95 to edd662d Compare November 21, 2024 18:36
@jacobweinstock jacobweinstock merged commit 9a66ea8 into tinkerbell:main Nov 21, 2024
4 of 5 checks passed
@jacobweinstock jacobweinstock deleted the quieter-logging-for-iso branch November 21, 2024 18:51
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants