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

Misleading log messages about opening connections #2511

Closed
beckjake opened this issue Jun 3, 2020 · 5 comments · Fixed by #2513
Closed

Misleading log messages about opening connections #2511

beckjake opened this issue Jun 3, 2020 · 5 comments · Fixed by #2513
Labels
bug Something isn't working good_first_issue Straightforward + self-contained changes, good for new contributors!

Comments

@beckjake
Copy link
Contributor

beckjake commented Jun 3, 2020

Describe the bug

When dbt is parsing, it assigns a "connection name" for each model it's parsing, just in case it's needed. This goes through set_connection_name, which logs that it is Acquiring new postgres connection ... and Opening a new connection, .... This behavior was very reasonable before dbt lazy-loaded connections, because it's the last centralized place before we end up in the adapter-specific open classmethod, so it's a nice place to send that message.

Since dbt doesn't generally need to access adapter connections during parsing, this log message is extremely misleading, and leads users who inspect the debug logs to believe that what's taking a long time is opening a ton of connections. What's actually (probably) taking a long time is parsing jinja. It would be good to know either way!

We should move the message about Opening a new connection into the part of LazyHandle that calls open.

I would like Acquiring to stay (though I'm very open to rewording it) as it's a very useful message in the event of weird threading-related connection issues. We haven't had any of those in a while, but I assume that as soon as we remove the message we'll introduce a slew of connection management problems somehow...

Steps To Reproduce

  • install dbt
  • make a few simple models like select 1 as id
  • run dbt ls
  • watch dbt claim to acquire a bunch of connections

Expected behavior

At the end of the day, I don't expect dbt to log that it's "Opening" a connection unless we're opening a socket (or at least trying to).

Screenshots and log output

$ dbt ls
...
2020-06-03 16:46:16.243448 (MainThread): Opening a new connection, currently in state init
2020-06-03 16:46:16.253313 (MainThread): Acquiring new snowflake connection "test.project.some_test".

System information

Any database, any supported python version, any OS, dbt >= 0.15.1

@beckjake beckjake added bug Something isn't working good_first_issue Straightforward + self-contained changes, good for new contributors! triage and removed triage labels Jun 3, 2020
@beckjake
Copy link
Contributor Author

beckjake commented Jun 3, 2020

@jtalmi You asked if we had any more good first issues - I think this is a great one! I know that was a month ago, but let me know if you're interested in picking this up.

@southpolemonkey
Copy link
Contributor

I'd like to take this issue if it hasn't been assigned yet.

@drewbanin
Copy link
Contributor

@southpolemonkey go for it! Let us know if there's anything we can do to help out :)

@southpolemonkey
Copy link
Contributor

@drewbanin awesome! which branch should I base off?

@drewbanin
Copy link
Contributor

you're going to want dev/marian-anderson :)

southpolemonkey added a commit to southpolemonkey/dbt that referenced this issue Jun 4, 2020
beckjake added a commit that referenced this issue Jun 8, 2020
(#2511) Remove log messages about opening connections in set_connecti…
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working good_first_issue Straightforward + self-contained changes, good for new contributors!
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants