Add per-context debugging configuration

[zikaeroh]

Fixes #569.

This is my attempt at adding per-context debugging as per #569 in a fully backwards-compatible manner. In addition to the boolean, I also added control over the writer used for the debugging, which I think makes sense to go with overriding the other global. This is especially useful for testing, where a writer that goes to testing.T.Logf can be used (for example). I use something like:

type TestLogger interface {
	Helper()
	Logf(format string, args ...interface{})
}

type Writer struct {
	T TestLogger
}

func (tw Writer) Write(p []byte) (n int, err error) {
	tw.T.Helper()
	tw.T.Logf("%s", bytes.TrimSpace(p))
	return len(p), nil
}

(Even though it's hacky due to the intermediary io.Writer...)

The naming of ContextDebug and IsDebug WithDebug, IsDebug, WithDebugWriter, and DebugWriterFrom are certainly not set in stone and I'd happily improve them.

I had to modify templates in order to make this change and tried to follow the instructions to update generated files as best I could, but I'm having trouble testing things to make sure this works. I'm also unsure about the performance penalty of checking for a context key on each query, but I doubt that it's significant compared to the query itself.

[derekperkins]

As an api user, I think debug and the debug writer should be handled separately, both for setting and retrieving them. I see how it is convenient in your code the way you implemented the templating, but I think having them separate should still be fairly simple.

For naming, this would be my vote for function signatures. I feel like With... is pretty standard for storing something inside of context.

WithDebug(ctx context.Context, debug bool) context.Context
IsDebug(ctx context.Context) bool

WithDebugWriter(ctx context.Context, writer io.Writer) context.Context
DebugWriter(ctx context.Context) io.Writer

Thanks for tackling this!

[zikaeroh]

Unfortunately, DebugWriter is already the name of the global variable that goes with DebugMode. I had been going for two sets like you have above, but realized I couldn't name things consistently and merged them. WithDebug is certainly a better name, I just took the suggested one.

Having two is probably fine, but would mean double context value lookups, and my thought was that they'd be looked up together in every case.

[zikaeroh]

I've split things apart and renamed as suggested. DebugWriterFrom(ctx) doesn't seem like a bad compromise in lieu of DebugWriter(ctx).

[glerchundi]

Why not create a wrapping database driver for debugging purposes? a la opencensus database driver?

[zikaeroh]

That would work for some cases, but it's definitely not as flexible. Doing it via the context means logging can be done per-query, rather than being forced to log everything that goes through the database connection. It's easy for me to throw in a ctx = boil.WithDebug(ctx, true) right at the call site I'm working with, then let it be written out. Easier than digging through the entire database output.

Doing a driver wrap like that can definitely make some sense if you're using OpenTracing/OpenCensus (and I actually do that already, just not in testing), but for quick debugging, it's pretty heavy handed.

For me personally, I have a custom scripting language for my project that my units test run so I don't have to write as much code. I have a directive boil_debug which sets boil.DebugMode and boil.DebugWriter, but it's only usable when I start filtering tests down to the single one, disable parallelism, and so on, to avoid mixing outputs. Having a way to set it for the context makes this super easy, but by the point the test scripts are running, it's too late for me to be changing the database driver that's being used.

[zikaeroh]

My main issue with this feature would be the performance implication of doing a full context value lookup on every query, one that is almost certainly going to fail every time for "normal" scenarios (as debugging won't be disabled). But, sqlboiler already has context values like TimestampsAreSkipped and HooksAreSkipped which force that cost to be paid (though not for every single query), so I'm not sure it's really going to end up being any worse. I suppose if the context lookups become a problem, one could explicitly set some of these to fall close to the query, such that the context lookups terminate quickly.

[derekperkins]

@zikaeroh I know that you're using both of the values internally together, but I don't think users are going to necessarily want to set both of them together. We would use the debug setting per query, but probably not the writer. There may also be use cases where people want to set the writer but not debug settings.

In the scope of the roundtrip query, I'm doubtful that context lookups are going to have a meaningful impact on total latency. Like you said, if you see issues because you have a deep context tree, there's a reasonable workaround for it.

[zikaeroh]

@derekperkins I think you might have missed it, but I did update the PR to split things apart as you suggested, after I picked a name that didn't conflict for the writer. 😃

[derekperkins]

Thanks, sorry I missed it!

[glerchundi]

That would work for some cases, but it's definitely not as flexible. Doing it via the context means logging can be done per-query, rather than being forced to log everything that goes through the database connection. It's easy for me to throw in a ctx = boil.WithDebug(ctx, true) right at the call site I'm working with, then let it be written out. Easier than digging through the entire database output.

Make sense, thanks for taking the time to clarify. Perhaps a rationale on the commit and adding a note in the README explaining the use case and why it's per-query would definitly help.

[aarondl]

I think that if we have a debug.go file, the DebugMode and DebugWriter declarations should also belong in it so the debugging pieces are not strewn about.

A note on context lookups that have been brought up: This is fine, if people are okay with leaving context on (there's a way to turn it off) then they're prepared for context to be used. Obviously we should be cautious and only add what's necessary, but as this is a feature we wanted we'll do the lookups where necessary.

Originally the proposal did not cover a DebugWriter. Is there a use case where this is useful? Would you ever actually log two statements to different writers? What are the costs to adding this feature? Have we considered it?

This "request changes" review is mainly about moving the debugging declarations into the appropriate flie, though I do expect there to be some reasoning or thought behind why we're adding the ctx DebugWriter given that was not previously agreed upon.

Thanks for your work so far @zikaeroh it's looking good.

[zikaeroh]

Thanks for taking a look. I'll make those changes later tonight.

Originally the proposal did not cover a DebugWriter. Is there a use case where this is useful? Would you ever actually log two statements to different writers? What are the costs to adding this feature? Have we considered it?

It'd be incredibly useful for me. I use a "real" database in my unit tests, spawned using dockertest and used via parallel tests which ask for their own database (using an initial schema as a template, which is then used to give each test their own connection independent from any other's).

Since all of the tests are running in the same process, if I want to use SQLBoiler's debugging features I have to go out of my way to avoid breaking things. I need to first disable test parallelism, then if I want the output to actually go to the testing.T instance's logger (and be associated with the test, rather than printed out-of-band in stdout at the top totally separately from any logging), I have to go set the global DebugWriter to that, then ensure that it's put back before another test can run. You can see some code where I handle the debugging setting in my script tests here: https://github.com/hortbot/hortbot/blob/d7b1057d52eac2fdca5c2a93fa05d7a1b8a3e656/internal/bot/btest/script_tester.go#L226-L237

If I can set the DebugWriter once for the test, everything else sorts itself out, because I can just do WithDebug and WithDebugWriter once for the test's context and move on.

In terms of "costs", I don't see this as being any more costly than the original feature request of letting DebugMode be controlled per-context.

[derekperkins]

While we're discussing logging, I have been thinking separately about proposing a change away from a writer to a context logging func.

type DebugLogFunc(ctx context.Context, log string)

By having the context passed back to my logging function, I can use all my context vars, request/trace ids, etc for log correlation, which is lost when using the writer.

[aarondl]

@zikaeroh Understood, thanks for the reply. Seems like it's a well thought out use case to me and because there's no lookup until you actually enter the DebugMode if statement I don't think it matters if it's there or not (given that debugging doesn't need to be fast).

@derekperkins It's possible in v4 we can update the logging mechanism in it's entirety. There's an issue to stop splitting writes that I'd like to fix finally. That has always been a bad idea. It's possible we can send context through as part of the logging interface. It does belong in a separate issue though, feel free to make one.

[zikaeroh]

The debugging globals have been moved to debug.go. I also took the liberty to move the context keys to their own file as well (since they were with the hooks), and update a few comments.

[zikaeroh]

FWIW this will probably need more testing before it gets merged. As I said, I've had some trouble trying to run all of them as it seems like they require all of the different databases running locally.

For example, I'm testing it on my own project and am getting:

Error: unable to generate output: failed to execute template: templates/10_relationship_to_one_setops.go.tpl: template: templates/10_relationship_to_one_setops.go.tpl:67:6: executing "templates/10_relationship_to_one_setops.go.tpl" at <.NoContext>: can't evaluate field NoContext in type drivers.ForeignKey

So some of these don't run with the same template contexts...

[aarondl]

@zikaeroh It's untrue that you need all databases to run them. They don't really run with different contexts, that error you're getting seems to be that you're inside a control structure (like a loop or something) in the template. In which case you should be using $.NoContext. See docs for the text/template library about this.

[zikaeroh]

I'm feeling pretty dumb about testing this. go test ./... gives:

?   	github.com/volatiletech/sqlboiler	[no test files]
ok  	github.com/volatiletech/sqlboiler/boil	(cached)
ok  	github.com/volatiletech/sqlboiler/boilingcore	(cached)
ok  	github.com/volatiletech/sqlboiler/drivers	(cached)
?   	github.com/volatiletech/sqlboiler/drivers/mocks	[no test files]
?   	github.com/volatiletech/sqlboiler/drivers/sqlboiler-mssql	[no test files]
--- FAIL: TestDriver (0.00s)
    mssql_test.go:56: mssql output:
        
    mssql_test.go:57: exec: "sqlcmd": executable file not found in $PATH
FAIL
FAIL	github.com/volatiletech/sqlboiler/drivers/sqlboiler-mssql/driver	0.047s
?   	github.com/volatiletech/sqlboiler/drivers/sqlboiler-mysql	[no test files]
--- FAIL: TestDriver (0.00s)
    mysql_test.go:47: mysql output:
        
    mysql_test.go:48: exec: "mysql": executable file not found in $PATH
FAIL
FAIL	github.com/volatiletech/sqlboiler/drivers/sqlboiler-mysql/driver	0.009s
?   	github.com/volatiletech/sqlboiler/drivers/sqlboiler-psql	[no test files]
--- FAIL: TestAssemble (0.00s)
    psql_test.go:48: psql output:
        psql: could not connect to server: Connection refused
        	Is the server running on host "localhost" (::1) and accepting
        	TCP/IP connections on port 5432?
        could not connect to server: Connection refused
        	Is the server running on host "localhost" (127.0.0.1) and accepting
        	TCP/IP connections on port 5432?
        
    psql_test.go:49: exit status 2
FAIL
FAIL	github.com/volatiletech/sqlboiler/drivers/sqlboiler-psql/driver	0.008s
ok  	github.com/volatiletech/sqlboiler/importers	(cached)
ok  	github.com/volatiletech/sqlboiler/queries	0.004s
?   	github.com/volatiletech/sqlboiler/queries/qm	[no test files]
?   	github.com/volatiletech/sqlboiler/queries/qmhelper	[no test files]
ok  	github.com/volatiletech/sqlboiler/randomize	(cached)
ok  	github.com/volatiletech/sqlboiler/strmangle	(cached)
?   	github.com/volatiletech/sqlboiler/templatebin	[no test files]
ok  	github.com/volatiletech/sqlboiler/types	(cached)
?   	github.com/volatiletech/sqlboiler/types/pgeo	[no test files]

Since I don't have any of these databases installed or running. And ./boil.sh gen psql just gives:

+ ./sqlboiler --wipe psql
failed to find key user in config
Error: unable to initialize tables: unable to fetch table data: driver (/home/jake/go/src/github.com/volatiletech/sqlboiler/sqlboiler-psql) exited non-zero: exit status 1

Which to me implies that I'm supposed to be running this somewhere other than the sqlboiler checkout I have, given there's no sqlboiler.toml there.

I have at least been able to generate the models for my project (so psql), and point it to my fork, and things appear to work, but that doesn't feel all too comprehensive. This looks great:

=== RUN   TestScripts
=== RUN   TestScripts/access_level
=== PAUSE TestScripts/access_level
=== CONT  TestScripts/access_level
--- PASS: TestScripts (0.01s)
    --- PASS: TestScripts/access_level (0.31s)
        print.go:266: SELECT "id", "updated_at", "delay" FROM "repeated_commands" WHERE ("repeated_commands"."enabled" = $1);
        print.go:266: [true]
        print.go:266: SELECT "id", "updated_at", "cron_expression" FROM "scheduled_commands" WHERE ("scheduled_commands"."enabled" = $1);
        print.go:266: [true]
...

[aarondl]

I ensured that the normal tests passed for this.

[aarondl]

Thanks for the PR :)