Fire typed events in tests.integration.base instead of AdapterLogger

[jtcohen6]

Nightly runs have been failing since dbt-labs/dbt-core#4266 was merged:

• https://github.com/dbt-labs/dbt-redshift/actions/runs/1474953855
• https://github.com/dbt-labs/dbt-redshift/actions/runs/1470106194

In particular, a handful of tests that use --vars were failing here:

tests/integration/simple_snapshot_test/test_simple_snapshot.py:95: in _run_snapshot_test
    self.run_dbt(['snapshot', '--vars', '{seed_name: seed_newcol}'])
tests/integration/base.py:409: in run_dbt
    res, success = self.run_dbt_and_check(args=args, profiles_dir=profiles_dir)
tests/integration/base.py:444: in run_dbt_and_check
    logger.info("Invoking dbt with {}".format(final_args))

Complaining about key errors in the *args being passed along:

>       msg = self.base_msg.format(*self.args)
E       KeyError: 'seed_name'

I'm guessing this has to do with the lazy evaluation for log messages that we spent time pulling apart and understanding in dbt-labs/dbt-core#4266. I'm just surprised this started failing after we merged those fixes.

For the time being, I was able to get these tests passing again locally by making tests/integration/base.py look more like it does in dbt-core: fire typed events (IntegrationTestInfo, IntegrationTestDebug, IntegrationTestException), instead of plumbing through AdapterLogger.

We very badly need to (a) improve this integration testing scaffold, and (b) consolidate its logic into a single module (package?) that can be reused across core + all our adapters. For now, these need to be manual fixups.

[emmyoop]

Is this really only failing in integration tests? Have we locally triggered log messages in adapters that use args? Looks like Redshift only has one in connections.py.

[nathaniel-may]

It looks like the underlying problem here is with lines like the following:

>>> "dict: {'k':'v'}".format()
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
KeyError: "'k'"

Here's what I see happening:

1. redshift calls logger.info("Invoking dbt with {}".format(final_args))
2. dbt.events.types.py::AdapterEventBase::message calls msg = self.base_msg.format(*self.args) which triggers a KeyError like the example above does.

Since this could be triggered by any other log messages in the adapters, I suggest we use the solution in dbt-core#4305 instead. I'm not opposed to using test events here, but I think I'd like adapters to use one form of logging to make community contributions simpler to navigate.

[jtcohen6]

Closing in favor of dbt-labs/dbt-core#4305.

We should still aim for a future where all adapters can use the exact same integration testing scaffold as dbt-core + dbt-postgres, and where we don't have to coordinate small updates to tests.integration.base across several repos