Remove duplicate logging during integration tests

[jtcohen6]

This attemps to fix behavior that is unique to our integration testing framework. Adding (and re-adding) multiple log handlers, for multiple invocations-within-invocations, isn't something that should ever happen in real-world dbt use.

• Try clearing existing FILE_LOG handlers before adding new one
• Try clearing existing STDOUT_LOG handlers before adding new one. The catch: only clear TextIOWrapper handlers, to avoid messing up StringIO stdout handler used by run_dbt_and_capture

Before

$ python3 -m pytest -m profile_postgres test/integration/001_simple_copy_test/ -s
============================================================== test session starts ==============================================================
platform darwin -- Python 3.8.9, pytest-6.2.5, py-1.10.0, pluggy-1.0.0
rootdir: /Users/jerco/dev/product/dbt, configfile: tox.ini
plugins: csv-3.0.0, logbook-1.2.0, flaky-3.7.0, xdist-2.4.0, dotenv-0.5.2, forked-1.3.0
collected 6 items

test/integration/001_simple_copy_test/test_simple_copy.py 15:38:40 | [ info  ] | Integration Test: Invoking dbt with ['seed', '--profiles-dir', '/var/folders/7h/hj5_fw9j291c58hwfdvy5xbm0000gp/T/dbt-int-test-atu19b64', '--log-cache-events']
15:38:40 | [ info  ] | Running with dbt=1.0.0-rc1
15:38:40 | [ info  ] | Partial parse save file not found. Starting full parse.
15:38:40 | [ info  ] | Partial parse save file not found. Starting full parse.
15:38:40 | [ warn  ] | [WARNING]: Test 'test.test.unique_disabled_id.a14f65086d' (models/schema.yml) depends on a node named 'disabled' which is disabled
15:38:40 | [ warn  ] | [WARNING]: Test 'test.test.unique_disabled_id.a14f65086d' (models/schema.yml) depends on a node named 'disabled' which is disabled
15:38:40 | [ info  ] | Found 8 models, 0 tests, 0 snapshots, 0 analyses, 165 macros, 0 operations, 1 seed file, 0 sources, 0 exposures, 0 metrics
15:38:40 | [ info  ] | Found 8 models, 0 tests, 0 snapshots, 0 analyses, 165 macros, 0 operations, 1 seed file, 0 sources, 0 exposures, 0 metrics
15:38:40 | [ info  ] |
15:38:40 | [ info  ] |
15:38:40 | [ info  ] | Concurrency: 4 threads (target='default2')
15:38:40 | [ info  ] | Concurrency: 4 threads (target='default2')
15:38:40 | [ info  ] |
15:38:40 | [ info  ] |
15:38:40 | [ info  ] | 1 of 1 START seed file test16367279223558005339_simple_copy_001.seed............ [RUN]
15:38:40 | [ info  ] | 1 of 1 START seed file test16367279223558005339_simple_copy_001.seed............ [RUN]
15:38:40 | [ info  ] | 1 of 1 OK loaded seed file test16367279223558005339_simple_copy_001.seed........ [INSERT 100 in 0.13s]
15:38:40 | [ info  ] | 1 of 1 OK loaded seed file test16367279223558005339_simple_copy_001.seed........ [INSERT 100 in 0.13s]
15:38:40 | [ info  ] |
15:38:40 | [ info  ] |
15:38:40 | [ info  ] | Finished running 1 seed in 0.24s.
15:38:40 | [ info  ] | Finished running 1 seed in 0.24s.
15:38:40 | [ info  ] |
15:38:40 | [ info  ] |
15:38:40 | [ info  ] | Completed successfully
15:38:40 | [ info  ] | Completed successfully
15:38:40 | [ info  ] |
Done. PASS=1 WARN=0 ERROR=0 SKIP=0 TOTAL=1
15:38:40 | [ info  ] |
Done. PASS=1 WARN=0 ERROR=0 SKIP=0 TOTAL=1
15:38:40 | [ info  ] | Integration Test: Invoking dbt with ['run', '--profiles-dir', '/var/folders/7h/hj5_fw9j291c58hwfdvy5xbm0000gp/T/dbt-int-test-atu19b64', '--log-cache-events']
15:38:40 | [ info  ] | Integration Test: Invoking dbt with ['run', '--profiles-dir', '/var/folders/7h/hj5_fw9j291c58hwfdvy5xbm0000gp/T/dbt-int-test-atu19b64', '--log-cache-events']
15:38:40 | [ info  ] | Running with dbt=1.0.0-rc1
15:38:40 | [ info  ] | Running with dbt=1.0.0-rc1
15:38:40 | [ info  ] | Found 8 models, 0 tests, 0 snapshots, 0 analyses, 165 macros, 0 operations, 1 seed file, 0 sources, 0 exposures, 0 metrics
15:38:40 | [ info  ] | Found 8 models, 0 tests, 0 snapshots, 0 analyses, 165 macros, 0 operations, 1 seed file, 0 sources, 0 exposures, 0 metrics
15:38:40 | [ info  ] | Found 8 models, 0 tests, 0 snapshots, 0 analyses, 165 macros, 0 operations, 1 seed file, 0 sources, 0 exposures, 0 metrics
15:38:40 | [ info  ] |
15:38:40 | [ info  ] |
15:38:40 | [ info  ] |
15:38:40 | [ info  ] | Concurrency: 4 threads (target='default2')
15:38:40 | [ info  ] | Concurrency: 4 threads (target='default2')
15:38:40 | [ info  ] | Concurrency: 4 threads (target='default2')

After

$ python3 -m pytest -m profile_postgres test/integration/001_simple_copy_test/ -s
============================================================== test session starts ==============================================================
platform darwin -- Python 3.8.9, pytest-6.2.5, py-1.10.0, pluggy-1.0.0
rootdir: /Users/jerco/dev/product/dbt, configfile: tox.ini
plugins: csv-3.0.0, logbook-1.2.0, flaky-3.7.0, xdist-2.4.0, dotenv-0.5.2, forked-1.3.0
collected 6 items

test/integration/001_simple_copy_test/test_simple_copy.py 15:39:25 | [ info  ] | Integration Test: Invoking dbt with ['seed', '--profiles-dir', '/var/folders/7h/hj5_fw9j291c58hwfdvy5xbm0000gp/T/dbt-int-test-vhtwd3xm', '--log-cache-events']
15:39:25 | [ info  ] | Running with dbt=1.0.0-rc1
15:39:25 | [ info  ] | Partial parse save file not found. Starting full parse.
15:39:25 | [ warn  ] | [WARNING]: Test 'test.test.unique_disabled_id.a14f65086d' (models/schema.yml) depends on a node named 'disabled' which is disabled
15:39:25 | [ info  ] | Found 8 models, 0 tests, 0 snapshots, 0 analyses, 165 macros, 0 operations, 1 seed file, 0 sources, 0 exposures, 0 metrics
15:39:25 | [ info  ] |
15:39:25 | [ info  ] | Concurrency: 4 threads (target='default2')
15:39:25 | [ info  ] |
15:39:25 | [ info  ] | 1 of 1 START seed file test16367279671834065649_simple_copy_001.seed............ [RUN]
15:39:25 | [ info  ] | 1 of 1 OK loaded seed file test16367279671834065649_simple_copy_001.seed........ [INSERT 100 in 0.12s]
15:39:25 | [ info  ] |
15:39:25 | [ info  ] | Finished running 1 seed in 0.22s.
15:39:25 | [ info  ] |
15:39:25 | [ info  ] | Completed successfully
15:39:25 | [ info  ] |
Done. PASS=1 WARN=0 ERROR=0 SKIP=0 TOTAL=1
15:39:25 | [ info  ] | Integration Test: Invoking dbt with ['run', '--profiles-dir', '/var/folders/7h/hj5_fw9j291c58hwfdvy5xbm0000gp/T/dbt-int-test-vhtwd3xm', '--log-cache-events']
15:39:25 | [ info  ] | Running with dbt=1.0.0-rc1
15:39:25 | [ info  ] | Found 8 models, 0 tests, 0 snapshots, 0 analyses, 165 macros, 0 operations, 1 seed file, 0 sources, 0 exposures, 0 metrics
15:39:25 | [ info  ] |
15:39:25 | [ info  ] | Concurrency: 4 threads (target='default2')

[nathaniel-may]

Alright. If it works it works. Thanks for finding this fix!