Change in ProxyCtx.printf function to enable better log tracking

[Budzi]

First, I would like to congratulate to all of the authors on the great work they have done with goproxy. I just recently started using go and I find it very interesting. Also, please excuse my ignorance if something I proposed below is not possible or not a good go code example. I am still learning go language.

I use goproxy as a base for a custom proxy server that is going to be used by a number of clients and I get a lot of requests per second. When logging is enabled I get a detailed log in the file (I use logrus package for logging) but since I have a lot of requests per second, the logs are entangled. The way to untangle them is to use the session ID that is displayed in the log in the form of [xxx], and then I can sort by that session ID, for example:

$ grep 002 proxy.log
time="2021-03-18T16:32:27-06:00" level=info msg="[002] INFO: Got request / showip.net GET http://showip.net/\n"
time="2021-03-18T16:32:27-06:00" level=info msg="[002] INFO: Sending request GET http://showip.net/\n"
time="2021-03-18T16:32:27-06:00" level=info msg="[002] INFO: Received response 200 OK\n"
time="2021-03-18T16:32:27-06:00" level=info msg="[002] INFO: Copying response to client 200 OK [200]\n"
time="2021-03-18T16:32:27-06:00" level=info msg="[002] INFO: Copied 9222 bytes to client error=<nil>\n"

$ grep 003 proxy.log
time="2021-03-18T16:32:54-06:00" level=info msg="[003] INFO: Running 1 CONNECT handlers\n"
time="2021-03-18T16:32:54-06:00" level=info msg="[003] INFO: on 0th handler: &{0 <nil> 0x6d0000} showip.net:443\n"
time="2021-03-18T16:32:54-06:00" level=info msg="[003] INFO: Accepting CONNECT to showip.net:443\n"

However, due to the number of requests that I receive, the session numbers start repeating pretty quickly which makes debugging much harder. I traced the problem to the following function in ctx.go file:

func (ctx *ProxyCtx) printf(msg string, argv ...interface{}) {
    ctx.Proxy.Logger.Printf("[%03d] "+msg+"\n", append([]interface{}{ctx.Session & 0xFF}, argv...)...)
}

There are two things I noticed here:

• the function masks the ctx.Session with 0xFF which allows for maximum 256 values before it starts repeating (if I am not mistaken)
• the function displays the values as a base 10 integer number with maximum of 3 digits

I would like to propose a change in this function in the following way:

• change the mask from 0xFF to 0xFFFFFFFF which would allow for ‭4294967295‬ unique values to be displayed in log
• change the display from base 10 to base 16 (hex) with a maximum of 8 digits

Also, the code above adds a new line character at the end of the line ("\n") which is not needed when using custom logger like logrus. If this does not break any code I would suggest to remove it also.

So the proposed changed code would look like this:

func (ctx *ProxyCtx) printf(msg string, argv ...interface{}) {
    ctx.Proxy.Logger.Printf("[%08x] "+msg, append([]interface{}{ctx.Session & 0xFFFFFFFF}, argv...)...)
}

This would produce following output in log file (again, using logrus as logger):

time="2021-03-18T18:40:52-06:00" level=info msg="[00000001] INFO: Got request / showip.net GET http://showip.net/"
time="2021-03-18T18:40:52-06:00" level=info msg="[00000001] INFO: Sending request GET http://showip.net/"
time="2021-03-18T18:40:52-06:00" level=info msg="[00000001] INFO: Received response 200 OK"
time="2021-03-18T18:40:52-06:00" level=info msg="[00000001] INFO: Copying response to client 200 OK [200]"
time="2021-03-18T18:40:52-06:00" level=info msg="[00000001] INFO: Copied 9222 bytes to client error=<nil>"

time="2021-03-18T18:40:53-06:00" level=info msg="[00000002] INFO: Got request / showip.net GET http://showip.net/"
time="2021-03-18T18:40:53-06:00" level=info msg="[00000002] INFO: Sending request GET http://showip.net/"
time="2021-03-18T18:40:54-06:00" level=info msg="[00000002] INFO: Received response 200 OK"
time="2021-03-18T18:40:54-06:00" level=info msg="[00000002] INFO: Copying response to client 200 OK [200]"
time="2021-03-18T18:40:54-06:00" level=info msg="[00000002] INFO: Copied 9222 bytes to client error=<nil>"

I could clone the goproxy package locally and change this but then I would have to merge/port all of the future changes in my local copy of the goproxy code, which I would like to avoid if possible.

Is this something that you might consider changing in your code?