- 
                Notifications
    You must be signed in to change notification settings 
- Fork 1
feat: runtime-configurable upstream request logging #37
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
base: main
Are you sure you want to change the base?
Conversation
cade1ee    to
    6f25879      
    Compare
  
    Signed-off-by: Danny Kopping <[email protected]>
Signed-off-by: Danny Kopping <[email protected]>
Signed-off-by: Danny Kopping <[email protected]>
Signed-off-by: Danny Kopping <[email protected]>
Signed-off-by: Danny Kopping <[email protected]>
6f25879    to
    7a3c4bf      
    Compare
  
    | 
 This stack of pull requests is managed by Graphite. Learn more about stacking. | 
|  | ||
| import "go.uber.org/atomic" | ||
|  | ||
| type ProviderConfig struct { | 
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This is a lot especially given that the baseURL and key won't change during a provider's lifetime within Coder.
Have you considered moving the methods for changing upstream logging settings to the provider rather than having the config be mutable? In Coder for example, we don't change the coderd.Options type after passing it to the API.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I'll have a look.
| upstreamLoggingDir atomic.String | ||
| enableUpstreamLogging atomic.Bool | 
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Does this need to be two values? An empty string could denote that it's disabled
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
An empty upstreamLoggingDir defaults to os.TempDir. We may want to allow configuration of the path in the future, so this is forward-looking.
| resLogger := log.New(resLogFile, "", log.LstdFlags) | ||
|  | ||
| return func(req *http.Request, next func(*http.Request) (*http.Response, error)) (*http.Response, error) { | ||
| logUpstreamRequest(reqLogger, id, model, req) | 
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
They're all going to be appended to the same file, which might make it confusing. I'd argue for moving the OpenFile calls into the middleware itself and appending an integer that is incremented on each request. E.g. ${interception_id}-${i}.req.log
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Each interception is generally a single upstream request, so it'll be separate files.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
For interceptions with injected tool calls this is not the case, so I'm suggesting that for those requests we have separate files like -1 -2 -3 etc. for each request
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Ah yes, good point 👍
| reqLogPath := filepath.Join(logDir, fmt.Sprintf("%s.req.log", id)) | ||
| resLogPath := filepath.Join(logDir, fmt.Sprintf("%s.res.log", id)) | ||
|  | ||
| reqLogFile, err := os.OpenFile(reqLogPath, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0644) | 
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Never closed?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
If the OpenFile was moved into the actual middleware function like I suggested in another comment, would make it much easier to defer it.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Doh!
Middleware will make this more difficult; I'll keep it as-is but add closing logic, thanks.
| reqLogger := log.New(reqLogFile, "", log.LstdFlags) | ||
| resLogger := log.New(resLogFile, "", log.LstdFlags) | 
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
The log package isn't really doing much for you here, I think you'd pretty much get the same effect by just fmt.Fprintlning to the file directly.
| baseDir = os.TempDir() | ||
| } | ||
|  | ||
| logDir := filepath.Join(baseDir, provider, safeModel) | 
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I could see the argument for subdividing directories based on provider (or endpoint), but don't fully understand what splitting by model does.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Claude Code does this ugly thing where it sends a bunch of requests to the Haiku class of models, so I wanted to split that out from normal prompts (presumably using Sonnet or Opus).
| "\"", repl, | ||
| "<", repl, | ||
| ">", repl, | ||
| "|", repl, | 
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
^.$ or ^..$ need to be changed to something else or they'll trip filepath.Join
|  | ||
| // UpstreamLoggingDir returns the base directory for upstream logging. | ||
| // If empty, the OS's tempdir will be used. | ||
| // Logs are written to $UpstreamLoggingDir/$provider/$model/$interceptionID.{req,res}.log | 
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
File per interception seems like a lot of files. For short debugging it should be fine but not in general. Maybe instead of directory structure / separate files structured logging could work?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Structured logging won't be easy to read because of the large payloads.
You're correct it'll be a lot of files. The point of the runtime enable/disable is so that it can be turned on for short periods of time.
I'll add docs to coder/coder#20414 to indicate this.
| } | ||
|  | ||
| if reqDump, err := httputil.DumpRequest(req, true); err == nil { | ||
| logger.Printf("[req] [%s] [%s] %s", id, model, reqDump) | 
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Since model name is already in the filename (well sanitized) then maybe it is not needed in log prefix?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
You're right, thanks! I added the model name to the path later. I'll remove this.
| return | ||
| } | ||
|  | ||
| if respDump, err := httputil.DumpResponse(resp, true); err == nil { | 
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
err is ignored
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Not much we can do if there is an err, is there?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
yeah, just linter may complain

Disclaimer: largely implemented by Claude Code.
It's often very useful to see the exact requests made to, and responses received from, upstream providers.
This is both useful for development and for production troubleshooting.
See coder/coder#20414 for the concomitant changes in coder/coder.