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

C. Where is the possible cause of the difference between the pointer address of the request object and the pointer address of the r object? #2413

Closed
3 tasks done
JellyZero opened this issue Mar 1, 2023 · 32 comments
Labels

Comments

@JellyZero
Copy link

JellyZero commented Mar 1, 2023

Issue Description

Checklist

  • Dependencies installed
  • No typos
  • Searched existing issues and docs

Expected behaviour

Actual behaviour

Steps to reproduce

Working code to debug

package main

func main() {
}

Version/commit

image

C. Where is the possible cause of the difference between the pointer address of the request object and the pointer address of the r object? After the middleware processing, how can the middleware overwrite the pointer object of the original r?

@JellyZero
Copy link
Author

After repetition, the middleware c.request object is different from the r object,

package main

import (
	"errors"
	"fmt"
	"io"
	"net/http"
	"os"
	"strings"

	"github.com/labstack/echo-contrib/jaegertracing"
	"github.com/labstack/echo/v4"
	"github.com/opentracing/opentracing-go"
	"github.com/opentracing/opentracing-go/log"
)

func upload(c echo.Context) error {
	// Read form fields
	name := c.FormValue("name")
	email := c.FormValue("email")

	//-----------
	// Read file
	//-----------

	// Source
	file, err := c.FormFile("file")
	if err != nil {
		return err
	}
	src, err := file.Open()
	if err != nil {
		return err
	}
	defer src.Close()

	// Destination
	dst, err := os.Create(file.Filename)
	if err != nil {
		return err
	}
	defer dst.Close()

	// Copy
	if _, err = io.Copy(dst, src); err != nil {
		return err
	}

	return c.HTML(http.StatusOK, fmt.Sprintf("<p>File %s uploaded successfully with fields name=%s and email=%s.</p>", file.Filename, name, email))
}

func main() {
	e := echo.New()
	tracer := createMockTracer()
	e.Use(jaegertracing.TraceWithConfig(jaegertracing.TraceConfig{
		Tracer:        tracer,
		ComponentName: "EchoTracer",
		OperationNameFunc: func(c echo.Context) string {
			// This is an example of operation name customization
			// In most cases default formatting is more than enough
			req := c.Request()
			opName := "HTTP " + req.Method

			path := c.Path()
			paramNames := c.ParamNames()

			for _, name := range paramNames {
				from := ":" + name
				to := "{" + name + "}"
				path = strings.ReplaceAll(path, from, to)
			}

			return opName + " " + path
		},
	}))
	e.Static("/", "public")
	e.POST("/upload", upload)

	e.Logger.Fatal(e.Start(":1323"))
}

// Mock opentracing.Span
type mockSpan struct {
	tracer   opentracing.Tracer
	tags     map[string]interface{}
	logs     map[string]interface{}
	opName   string
	finished bool
}

func createSpan(tracer opentracing.Tracer) *mockSpan {
	return &mockSpan{
		tracer: tracer,
		tags:   make(map[string]interface{}),
		logs:   make(map[string]interface{}),
	}
}

func (sp *mockSpan) isFinished() bool {
	return sp.finished
}

func (sp *mockSpan) getOpName() string {
	return sp.opName
}

func (sp *mockSpan) getTag(key string) interface{} {
	return sp.tags[key]
}

func (sp *mockSpan) getLog(key string) interface{} {
	return sp.logs[key]
}

func (sp *mockSpan) Finish() {
	sp.finished = true
}
func (sp *mockSpan) FinishWithOptions(opts opentracing.FinishOptions) {
}
func (sp *mockSpan) Context() opentracing.SpanContext {
	return nil
}
func (sp *mockSpan) SetOperationName(operationName string) opentracing.Span {
	sp.opName = operationName
	return sp
}
func (sp *mockSpan) SetTag(key string, value interface{}) opentracing.Span {
	sp.tags[key] = value
	return sp
}
func (sp *mockSpan) LogFields(fields ...log.Field) {
}
func (sp *mockSpan) LogKV(alternatingKeyValues ...interface{}) {
	for i := 0; i < len(alternatingKeyValues); i += 2 {
		ikey := alternatingKeyValues[i]
		value := alternatingKeyValues[i+1]
		if key, ok := ikey.(string); ok {
			sp.logs[key] = value
		}
	}
}
func (sp *mockSpan) SetBaggageItem(restrictedKey, value string) opentracing.Span {
	return sp
}
func (sp *mockSpan) BaggageItem(restrictedKey string) string {
	return ""
}
func (sp *mockSpan) Tracer() opentracing.Tracer {
	return sp.tracer
}
func (sp *mockSpan) LogEvent(event string) {
}
func (sp *mockSpan) LogEventWithPayload(event string, payload interface{}) {
}
func (sp *mockSpan) Log(data opentracing.LogData) {
}

// Mock opentracing.Tracer
type mockTracer struct {
	span                   *mockSpan
	hasStartSpanWithOption bool
}

func (tr *mockTracer) currentSpan() *mockSpan {
	return tr.span
}

func (tr *mockTracer) StartSpan(operationName string, opts ...opentracing.StartSpanOption) opentracing.Span {
	tr.hasStartSpanWithOption = len(opts) > 0
	if tr.span != nil {
		tr.span.opName = operationName
		return tr.span
	}
	span := createSpan(tr)
	span.opName = operationName
	return span
}

func (tr *mockTracer) Inject(sm opentracing.SpanContext, format interface{}, carrier interface{}) error {
	return nil
}

func (tr *mockTracer) Extract(format interface{}, carrier interface{}) (opentracing.SpanContext, error) {
	if tr.span != nil {
		return nil, nil
	}
	return nil, errors.New("no span")
}

func createMockTracer() *mockTracer {
	tracer := mockTracer{}
	span := createSpan(&tracer)
	tracer.span = span
	return &tracer
}

@JellyZero
Copy link
Author

JellyZero commented Mar 1, 2023

CLICK ME image

@aldas
Copy link
Contributor

aldas commented Mar 1, 2023

You are using jaegertracing middleware and it replaces request here https://github.com/labstack/echo-contrib/blob/5bb0f68fcbfa500642b965c9ca0be75230e19417/jaegertracing/jaegertracing.go#L200

@aldas aldas added the question label Mar 1, 2023
@JellyZero
Copy link
Author

Yes, how can I keep the pointer address unchanged? Because I found that if the r object has a file, the http response will eventually clean up the file, and it can't go after a lot of logic changes

@aldas
Copy link
Contributor

aldas commented Mar 1, 2023

How do you test this?

When I post file as multipart curl -F file=@Makefile http://localhost:8080/upload I can see that upload handler receives that file file, err := c.FormFile("file")

NB: You can not send/post files with x-www-form-urlencoded and need to use multipart/form-data .

@JellyZero
Copy link
Author

Use the code I gave above to reproduce the problem. Add a breakpoint on line 667 of the 'ServeHTTP' method of echo to reproduce the problem. The version used is v4.10.2.

@JellyZero
Copy link
Author

test curl

curl --location --request POST 'http://127.0.0.1:1323/upload' --form 'file=@"xxxx/222.zip"' 

@JellyZero
Copy link
Author

JellyZero commented Mar 1, 2023

CLICK ME ![image](https://user-images.githubusercontent.com/109566229/222148867-6a363485-063e-4b9d-a945-2d4797ace3f4.png)

@aldas
Copy link
Contributor

aldas commented Mar 1, 2023

x@x:~/$ curl -v -F "name=test" -F "email=xxx" -F file=@Makefile http://localhost:8080/upload
*   Trying 127.0.0.1:8080...
* Connected to localhost (127.0.0.1) port 8080 (#0)
> POST /upload HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.85.0
> Accept: */*
> Content-Length: 3022
> Content-Type: multipart/form-data; boundary=------------------------826930f239e33ed9
> 
* We are completely uploaded and fine
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< Content-Type: text/html; charset=UTF-8
< Date: Wed, 01 Mar 2023 13:11:46 GMT
< Content-Length: 79
< 
* Connection #0 to host localhost left intact
<p>File Makefile uploaded successfully with fields name=test and email=xxx.</p>

I am using your example with different port

@JellyZero
Copy link
Author

Use the following code to test

package main

import (
	["errors"](https://pkg.go.dev/errors)
	["fmt"](https://pkg.go.dev/fmt)
	["io"](https://pkg.go.dev/io)
	["net/http"](https://pkg.go.dev/net/http)
	["os"](https://pkg.go.dev/os)
	["strings"](https://pkg.go.dev/strings)

	https://github.com/labstack/echo-contrib/tree/master/jaegertracing
	"github.com/labstack/echo/v4"
	"github.com/opentracing/opentracing-go"
	https://github.com/opentracing/opentracing-go/tree/master/log
)

func upload(c echo.Context) error {
	// Read form fields
	name := c.FormValue("name")
	email := c.FormValue("email")

	//-----------
	// Read file
	//-----------

	// Source
	file, err := c.FormFile("file")
	if err != nil {
		return err
	}
	src, err := file.Open()
	if err != nil {
		return err
	}
	defer src.Close()

	// Destination
	dst, err := os.Create(file.Filename)
	if err != nil {
		return err
	}
	defer dst.Close()

	// Copy
	if _, err = io.Copy(dst, src); err != nil {
		return err
	}

	return c.HTML(http.StatusOK, fmt.Sprintf("<p>File %s uploaded successfully with fields name=%s and email=%s.</p>", file.Filename, name, email))
}

func main() {
	e := echo.New()
	tracer := createMockTracer()
	e.Use(jaegertracing.TraceWithConfig(jaegertracing.TraceConfig{
		Tracer:        tracer,
		ComponentName: "EchoTracer",
		OperationNameFunc: func(c echo.Context) string {
			// This is an example of operation name customization
			// In most cases default formatting is more than enough
			req := c.Request()
			opName := "HTTP " + req.Method

			path := c.Path()
			paramNames := c.ParamNames()

			for _, name := range paramNames {
				from := ":" + name
				to := "{" + name + "}"
				path = strings.ReplaceAll(path, from, to)
			}

			return opName + " " + path
		},
	}))
	e.Static("/", "public")
	e.POST("/upload", upload)

	e.Logger.Fatal(e.Start(":1323"))
}

// Mock opentracing.Span
type mockSpan struct {
	tracer   opentracing.Tracer
	tags     map[string]interface{}
	logs     map[string]interface{}
	opName   string
	finished bool
}

func createSpan(tracer opentracing.Tracer) *mockSpan {
	return &mockSpan{
		tracer: tracer,
		tags:   make(map[string]interface{}),
		logs:   make(map[string]interface{}),
	}
}

func (sp *mockSpan) isFinished() bool {
	return sp.finished
}

func (sp *mockSpan) getOpName() string {
	return sp.opName
}

func (sp *mockSpan) getTag(key string) interface{} {
	return sp.tags[key]
}

func (sp *mockSpan) getLog(key string) interface{} {
	return sp.logs[key]
}

func (sp *mockSpan) Finish() {
	sp.finished = true
}
func (sp *mockSpan) FinishWithOptions(opts opentracing.FinishOptions) {
}
func (sp *mockSpan) Context() opentracing.SpanContext {
	return nil
}
func (sp *mockSpan) SetOperationName(operationName string) opentracing.Span {
	sp.opName = operationName
	return sp
}
func (sp *mockSpan) SetTag(key string, value interface{}) opentracing.Span {
	sp.tags[key] = value
	return sp
}
func (sp *mockSpan) LogFields(fields ...log.Field) {
}
func (sp *mockSpan) LogKV(alternatingKeyValues ...interface{}) {
	for i := 0; i < len(alternatingKeyValues); i += 2 {
		ikey := alternatingKeyValues[i]
		value := alternatingKeyValues[i+1]
		if key, ok := ikey.(string); ok {
			sp.logs[key] = value
		}
	}
}
func (sp *mockSpan) SetBaggageItem(restrictedKey, value string) opentracing.Span {
	return sp
}
func (sp *mockSpan) BaggageItem(restrictedKey string) string {
	return ""
}
func (sp *mockSpan) Tracer() opentracing.Tracer {
	return sp.tracer
}
func (sp *mockSpan) LogEvent(event string) {
}
func (sp *mockSpan) LogEventWithPayload(event string, payload interface{}) {
}
func (sp *mockSpan) Log(data opentracing.LogData) {
}

// Mock opentracing.Tracer
type mockTracer struct {
	span                   *mockSpan
	hasStartSpanWithOption bool
}

func (tr *mockTracer) currentSpan() *mockSpan {
	return tr.span
}

func (tr *mockTracer) StartSpan(operationName string, opts ...opentracing.StartSpanOption) opentracing.Span {
	tr.hasStartSpanWithOption = len(opts) > 0
	if tr.span != nil {
		tr.span.opName = operationName
		return tr.span
	}
	span := createSpan(tr)
	span.opName = operationName
	return span
}

func (tr *mockTracer) Inject(sm opentracing.SpanContext, format interface{}, carrier interface{}) error {
	return nil
}

func (tr *mockTracer) Extract(format interface{}, carrier interface{}) (opentracing.SpanContext, error) {
	if tr.span != nil {
		return nil, nil
	}
	return nil, errors.New("no span")
}

func createMockTracer() *mockTracer {
	tracer := mockTracer{}
	span := createSpan(&tracer)
	tracer.span = span
	return &tracer
}

@aldas
Copy link
Contributor

aldas commented Mar 1, 2023

This is exactly the same (except port nr) as I use. And I set breakpoint in upload function and see that file and its contents is there.

@JellyZero
Copy link
Author

JellyZero commented Mar 1, 2023

CLICK ME ![image](https://user-images.githubusercontent.com/109566229/222149803-c70aa129-b633-458b-b3c3-390ada366ff1.png) ![image](https://user-images.githubusercontent.com/109566229/222149997-bf6f5f32-199b-424c-b2b6-b3a5398c6f8a.png)
```go // setup request context - add opentracing span req = req.WithContext(opentracing.ContextWithSpan(req.Context(), sp)) c.SetRequest(req) ```

You can see that the 'WithContext' method of the http request object will reinitialize a request object to overwrite the current request object, so this is the problem that causes the pointer address to change. How can I ensure that it remains unchanged?

@JellyZero
Copy link
Author

JellyZero commented Mar 1, 2023

Yes, there is no problem with the way you operate. The problem I said is that after calling the 'WithContext' method of http request through some middleware, the pointer address of the original request variable changes, which will lead to the final inconsistency between the r object and the 'c.request' object of the 'ServeHTTP' method of echo, thus unable to release file resources

@aldas
Copy link
Contributor

aldas commented Mar 1, 2023

You can not with current implementation of jaegertracing middleware.

Please describe your problem better and please do not at the moment fixate on the symptom

You said that

? Because I found that if the r object has a file, the http response will eventually clean up the file, and it can't go after a lot of logic changes

What do you mean by eventually clean up the file? I can see that uploaded file is save to disk. How and when does that saved file change? When you reupload file with same name?

@JellyZero
Copy link
Author

JellyZero commented Mar 1, 2023

CLICK ME ![image](https://user-images.githubusercontent.com/109566229/222151842-1cda48da-114b-4169-ab30-cc62a00c6dcf.png)

@aldas
Copy link
Contributor

aldas commented Mar 1, 2023

So you are describing leaking file descriptors or leaking memory?

and please do not post these pictures - I already saw from first picture that pointer address is different. Lets discuss what is the problem.

@JellyZero
Copy link
Author

It means that c.request.MultipartForm has a value, while r.MultipartForm has no value,

@JellyZero
Copy link
Author

JellyZero commented Mar 1, 2023

https://cs.opensource.google/go/go/+/refs/tags/go1.20.1:src/net/http/server.go;l=1660

It means that c.request.MultipartForm has a value, while r.MultipartForm has no value, so http's server.go

if w.req.MultipartForm != nil {

w.req.MultipartForm.RemoveAll()

}

Unable to execute

The temporary file was not deleted

@aldas
Copy link
Contributor

aldas commented Mar 1, 2023

alright, to summarize this situation:

we are leaking temporary files because when jaegertracing replaces original Request object with new one with its span added to the context.Context.

https://github.com/labstack/echo-contrib/blob/5bb0f68fcbfa500642b965c9ca0be75230e19417/jaegertracing/jaegertracing.go#L200

			req = req.WithContext(opentracing.ContextWithSpan(req.Context(), sp))
			c.SetRequest(req)

problem with that is when c.FormValue or c.FormFile is used in handler (upload) that new Request object parses multipartform object. Creates new temporary file and sets form as it field.

now these temporary form files are cleaned up at the end of the request by go standard library HERE but http server does not have access to that new Request object - it still works on that old Request object that does not have parsed form, therefore does not know anything about temporary files.

@JellyZero
Copy link
Author

alright, to summarize this situation:

we are leaking temporary files because when jaegertracing replaces original Request object with new one with its span added to the context.Context.

https://github.com/labstack/echo-contrib/blob/5bb0f68fcbfa500642b965c9ca0be75230e19417/jaegertracing/jaegertracing.go#L200

			req = req.WithContext(opentracing.ContextWithSpan(req.Context(), sp))
			c.SetRequest(req)

problem with that is when c.FormValue or c.FormFile is used in handler (upload) that new Request object parses multipartform object. Creates new temporary file and sets form as it field.

now these temporary form files are cleaned up at the end of the request by go standard library HERE but http server does not have access to that new Request object - it still works on that old Request object that does not have parsed form, therefore does not know anything about temporary files.

Yes, how can I solve this problem? Do you manually call 'MultipartForm. RemoveAll()' in the ServHTTP method of echo

if c.request.MultipartForm != nil {



c.request.MultipartForm.RemoveAll()



}

@aldas
Copy link
Contributor

aldas commented Mar 1, 2023

you can clean multipartform at the end of handler by adding defer

	file, err := c.FormFile("file")
	if err != nil {
		return err
	}
	defer func() {
		 c.Request().MultipartForm.RemoveAll()
	}()

@JellyZero
Copy link
Author

you can clean multipartform at the end of handler by adding defer

	file, err := c.FormFile("file")
	if err != nil {
		return err
	}
	defer func() {
		 c.Request().MultipartForm.RemoveAll()
	}()

Yes, I know I can call it manually, but should the framework theoretically support this function? Because the finishRequest () of the default http standard library does this, the general user will not think of using the WithContext method to cause finishRequest to fail to work normally, but will have to manually call c.Request(). MultipartForm. RemoveAll() to clean up the temporary file manually

@aldas
Copy link
Contributor

aldas commented Mar 1, 2023

Yep, jaegertracing middleware should be changed to

https://github.com/labstack/echo-contrib/blob/5bb0f68fcbfa500642b965c9ca0be75230e19417/jaegertracing/jaegertracing.go#L200

			req = req.WithContext(opentracing.ContextWithSpan(req.Context(), sp))
			c.SetRequest(req)
			defer func() {
				if req.MultipartForm != nil {
					req.MultipartForm.RemoveAll()
				}
			}()

to clean up the problem it causes.

p.s. repo for that mw is https://github.com/labstack/echo-contrib not this repository

@JellyZero
Copy link
Author

Yep, jaegertracing middleware should be changed to

https://github.com/labstack/echo-contrib/blob/5bb0f68fcbfa500642b965c9ca0be75230e19417/jaegertracing/jaegertracing.go#L200

			req = req.WithContext(opentracing.ContextWithSpan(req.Context(), sp))
			c.SetRequest(req)
			defer func() {
				if c.Request().MultipartForm != nil {
					c.Request().MultipartForm.RemoveAll()
				}
			}()

to clean up the problem it causes.

p.s. repo for that mw is https://github.com/labstack/echo-contrib not this repository

Echo does not guarantee that the middleware does not call the WithContext method. I think it should be cleaned manually in the ServHTTP method of echo

@aldas
Copy link
Contributor

aldas commented Mar 1, 2023

echo.ServHTTP responsibility is not to fix problems that faulty middlewares/handlers cause. Problems should be fixed as near where they are created.

@aldas
Copy link
Contributor

aldas commented Mar 1, 2023

I'll create PR for jaegertracing mw in echo-contrib

@JellyZero
Copy link
Author

But the user does not know that the middleware will not clean up the file resources after calling WithContext

@JellyZero
Copy link
Author

We can't guarantee that the middleware used by the user will not use the finishRequest() method of the http standard library after calling WithContext

@aldas
Copy link
Contributor

aldas commented Mar 1, 2023

We can not guarantee that there would not be multiple chained middlewares replacing request objects in row. Therefore we can not assume that at the end of echo.ServerHTTP request, some other middleware, have not been already overwritten Request object we just created, with instance that does not have multipartform, thus leaking temporary files because Request object we see when bubbling up in middleware chain and eventually reach back to echo.ServeHTTP could be already replaced with something else - which does not have temporary files.

problem must be fixed where it is introduced. - jaegertracing middleware must clean multipartform files at the end of its lifecycle.

@aldas
Copy link
Contributor

aldas commented Mar 1, 2023

I'll merge that fix in echo-contrib in couple of hours and tag a new release.

@JellyZero
Copy link
Author

Thank you

@aldas
Copy link
Contributor

aldas commented Mar 1, 2023

@JellyZero try this https://github.com/labstack/echo-contrib/releases/tag/v0.14.1 and if it is not enough - create issue in that repository

@aldas aldas closed this as completed Mar 1, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants