Trouble with Logging Changes

stressedstrain · June 26, 2022, 6:41pm

Hello,

in Caddy 2.5, logging remote_addr was depreciated in favor of remote_ip. I maintain the RealIP plugin which changes the remote_addr of a request to be the value of a specific header, usually X-Forwarded-For:

Historically the operation of the plugin has always been a bit weird, since if you look directly at the system logs you see the unaltered IP as remote_addr, but if you enable access logging with common_log format you’d see the replaced value

That is because the original request was logged before passing to the handlers. However the common_log variables got updated after the handlers as shown at these 2 lines prior to v2.5:

github.com

caddyserver/caddy/blob/937ec342010894f7a6239883b10f6a107ff82c9f/modules/caddyhttp/server.go#L157

      
        
            		}
            	}
            
            
	repl := caddy.NewReplacer()
            	r = PrepareRequest(r, repl, w, s)
            
            
	// encode the request for logging purposes before
            	// it enters any handler chain; this is necessary
            	// to capture the original request in case it gets
            	// modified during handling
            	loggableReq := zap.Object("request", LoggableHTTPRequest{r})
            	errLog := s.errorLogger.With(loggableReq)
            
            
	var duration time.Duration
            
            
	if s.shouldLogRequest(r) {
            		wrec := NewResponseRecorder(w, nil, nil)
            		w = wrec
            
            
		// capture the original version of the request
            		accLog := s.accessLogger.With(loggableReq)

github.com

caddyserver/caddy/blob/937ec342010894f7a6239883b10f6a107ff82c9f/modules/caddyhttp/server.go#L185

      
        
            			if s.Logs != nil {
            				logger = s.Logs.wrapLogger(logger, r.Host)
            			}
            
            
			log := logger.Info
            			if wrec.Status() >= 400 {
            				log = logger.Error
            			}
            
            
			log("handled request",
            				zap.String("common_log", repl.ReplaceAll(commonLogFormat, commonLogEmptyValue)),
            				zap.Duration("duration", duration),
            				zap.Int("size", wrec.Size()),
            				zap.Int("status", wrec.Status()),
            				zap.Object("resp_headers", LoggableHTTPHeader(wrec.Header())),
            			)
            		}()
            	}
            
            
	start := time.Now()

With Caddy 2.5, the request variables that would allow the plugin to function are not updated after the request passes thru the handlers as shown here:

github.com

caddyserver/caddy/blob/10f85558ead15e119f8e9abd81c8ad55eb865f8b/modules/caddyhttp/server.go#L207

      
        
            				logger = s.Logs.wrapLogger(logger, r.Host)
            			}
            
            
			log := logger.Info
            			if wrec.Status() >= 400 {
            				log = logger.Error
            			}
            
            
			userID, _ := repl.GetString("http.auth.user.id")
            
            
			log("handled request",
            				zap.String("user_id", userID),
            				zap.Duration("duration", duration),
            				zap.Int("size", wrec.Size()),
            				zap.Int("status", wrec.Status()),
            				zap.Object("resp_headers", LoggableHTTPHeader{
            					Header:               wrec.Header(),
            					ShouldLogCredentials: shouldLogCredentials,
            				}),
            			)
            		}()

What options would be available to repair the original functionality?

francislavoie · June 26, 2022, 11:22pm

I don’t think we can reasonably make it possible for a request handler to modify the logs being output. Your plugin has a flawed design, it’s trying to mutate something that’s inherently immutable. The point of the request log is to show the request as Caddy received it.

The correct thing to do would be to use the PROXY protocol for your downstream proxy to pass the original client IP. See https://www.haproxy.org/download/1.8/doc/proxy-protocol.txt and GitHub - mastercactapus/caddy2-proxyprotocol.

Or alternatively, post-process the logs with some tool/script to read the X-Forwarded-For header values in the log and shove it in the remote_ip field.

gcss · June 27, 2022, 2:58am

I just wanted to leave a note to Thank You for writing this very useful plugin.

Would you plan to use the PROXY protocol for your downstream proxy to pass the original client IP? It would open up the plugin a lot

stressedstrain · June 27, 2022, 3:52am

thanks for the info @francislavoie

@gcss thank you, i need some time to look into this and figure out options.

system · July 26, 2022, 6:42pm

This topic was automatically closed after 30 days. New replies are no longer allowed.