[Bug] "RecursionError: maximum recursion depth exceeded" in Python3.10

[s2terminal]

Is there an existing issue for this?

• I have searched the existing issues

Current Behavior

When I run dbt run or dbt docs generate in Python 3.10, the standard output continues indefinitely. I think the program is in an infinite loop.

The following is an excerpt of some of the output.

RecursionError: maximum recursion depth exceeded
Logged from file /usr/local/lib/python3.10/site-packages/logbook/concurrency.py, line 141
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/logbook/handlers.py", line 216, in handle
    self.emit(record)
  File "/usr/local/lib/python3.10/site-packages/dbt/logger.py", line 467, in emit
    super().emit(record)
  File "/usr/local/lib/python3.10/site-packages/logbook/handlers.py", line 836, in emit
    msg = self.format(record)
  File "/usr/local/lib/python3.10/site-packages/dbt/logger.py", line 454, in format
    msg = super().format(record)
  File "/usr/local/lib/python3.10/site-packages/logbook/handlers.py", line 195, in format
    return self.formatter(record, self)
  File "/usr/local/lib/python3.10/site-packages/logbook/handlers.py", line 387, in __call__
    line = self.format_record(record, handler)
  File "/usr/local/lib/python3.10/site-packages/logbook/handlers.py", line 371, in format_record
    return self._formatter.format(record=record, handler=handler)
  File "/usr/local/lib/python3.10/site-packages/logbook/helpers.py", line 283, in __get__
    value = self.func(obj)
  File "/usr/local/lib/python3.10/site-packages/logbook/base.py", line 675, in thread_name
    return thread_get_name()
  File "/usr/local/lib/python3.10/site-packages/logbook/concurrency.py", line 141, in thread_get_name
    return currentThread().getName()
  File "/usr/local/lib/python3.10/threading.py", line 1442, in currentThread
    warnings.warn('currentThread() is deprecated, use current_thread() instead',
RecursionError: maximum recursion depth exceeded
Logged from file /usr/local/lib/python3.10/site-packages/logbook/concurrency.py, line 141

Expected Behavior

dbt run is succeed.

By using the Python 3.9.9, I was able to confirm that the same configuration would be successful.

Steps To Reproduce

Environment: Python 3.10.1-slim in docker

$ docker run --interactive --tty --rm --volume $(pwd):/app --workdir /app python:3.10.1-slim bash

install and initialize dbt

# pip install dbt-bigquery
# dbt init test
# cd test/

run

# dbt run

Relevant log output

no log


# wc logs/dbt.log
0 0 0 logs/dbt.log

Environment

- OS: [Docker Python official image](https://hub.docker.com/_/python) python:3.10.1-slim debian 11.2
- Python:3.10.1
- dbt:1.0.1

What database are you using dbt with?

bigquery

Additional Context

No response

[pgoslatara]

Hey @s2terminal, dbt does not support Python 3.10 (yet!) and as such the recommended action is what you have already done, downgrade to 3.9 until 3.10 is officially supported.

Looking at the error message it appears this is not caused by dbt but by the Logbook module. In fact this module looks to no longer be updated. Logbook is defined as a dependency here.

[s2terminal]

@pgoslatara Thanks for the answer, I will downgrade the python version to 3.9.

[haf]

I don't think this bug is completed, as I presume dbt-core will at some point support python 3.10 and this is a problem still. logbook hasn't received updates since 2019 so it might be worth migrating off it ASAP.

[jtcohen6]

Hey @haf -

• dbt-core v1.1+ added official support for Python 3.10
• We're aware that logbook is unsupported. In v1.0, we created a new logging system that no longer relies on logbook by default. However, we've left the legacy logging system in place for now, to provide a migration path for other projects that have tight integrations with dbt-core's logging (including the to-be-deprecated dbt-RPC server). We're planning to remove it for good in an upcoming version (potentially v1.4 or v1.5)

[haf]

@jtcohen6 Thanks for clarifying that. While I have you on the line, what's the process for adjusting the logging level for dbt-core in 1.1+ when using dbt as a python module?

[haf]

@jtcohen6 And also; I tried upgrading to dbt-core v1.2 and the deprecation this thread is about is spammed relentlessly in the output. How does the support relate to fixing this issue? (because it's an issue despite upgrading)

[koconnor-ampion]

this is rather bizarre, but I am installing dbt-bigquery@1.0.0 and the first thing it installs is python 3.10?!?! Isn't that rather a problem?

% brew install dbt-bigquery@1.0.0                                
==> Downloading https://ghcr.io/v2/homebrew/core/python/3.10/manifests/3.10.8-1
Already downloaded: /Users/koconnor/Library/Caches/Homebrew/downloads/d4e394cc5e1801239d2f498385a78f2f7b8cf39ba249179edb256c978697bc1b--python@3.10-3.10.8-1.bottle_manifest.json
==> Downloading https://ghcr.io/v2/homebrew/core/python/3.10/blobs/sha256:017d295e8091cf75e95c8002806865dca73d47b898984fff0a4d00df63a28962
Already downloaded: /Users/koconnor/Library/Caches/Homebrew/downloads/29058597e14d4a159d738fabb14e55c6cb8d19f32891cb63fc96ffd2dc17ec90--python@3.10--3.10.8.monterey.bottle.1.tar.gz
==> Downloading https://files.pythonhosted.org/packages/ae/0e/34231b11f1b80463f64c5be7d7279de5a5609a47c59c0e34ba7016e4e333/agate-1.6.3.tar.gz

I had thought the install was just looking for the latest version of python3, so just prior to this install, I had uninstalled python 3.10 explicitly and installed 3.9. I am using a model that was developed under dbt 1.0.0, so I'm a bit loathe to use dbt 1.1 against that model. Any pointers?

[TrololoLi]

@koconnor-ampion I have the same thing for dbt-snowflake@1.0.0 - it installs python 3.10 . Recursion error made my day =) I had to uninstall dbt-snowflake 1.0.0, then installed python 3.9, then found a new version of dbt-snowflake - 1.3.0 and it didn't cause the problem (I tried to install snowflake1.0.0 after python 3.9 installation, but it still was trying to install python 3.10, so I interrupted it). I hope there is a new package for bigquery as well. Not sure whether new dbt-snowflake package picked my python 3.9 or perhaps you can try skip this part.

[haf]

So what's the status of this? Can I opt into the new logging methods?

According to the docs 3.10 is now supported https://docs.getdbt.com/faqs/core/install-python-compatibility

[peterallenwebb]

@haf You shouldn't need to opt in to the new logging behavior in dbt, but one thing to check is whether you have the DBT_ENABLE_LEGACY_LOGGER environment variable set. If so, you'll want to get rid of it.

Assuming that is not the problem, could you share more details about the steps you're taking to generate the error message you're getting? Most people using dbt 1.4 with Python 3.10 are not encountering this issue, so it will be helpful to have as much information about your scenario as possible.

[haf]

dbt-logging-repro.zip

@peterallenwebb Here's a repro. A regex from Jinja was being fed into the old logging infrastructure and got interpreted.

Seems like you might have yourself a log4j here https://logging.apache.org/log4j/2.x/security.html — but I'm not feeling up for finding an expansion that executes; infinite recursion is enough for a DoS. ;) Of course since it requires you to use dbt as a package, this has a pretty small blast radius.

[peterallenwebb]

Thank you for the repro project, @haf. Unfortunately, even after I spent an hour trying to reproduce your issue with various dbt versions and configuration, I haven't had luck. The runs just succeed for me:

(env310) ~/Code/dbt-labs/issue-4560-repro/repro# dbt run
21:37:28  Running with dbt=1.4.4
21:37:28  Unable to do partial parsing because saved manifest not found. Starting full parse.
21:37:28  Found 2 models, 4 tests, 0 snapshots, 0 analyses, 290 macros, 0 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics
21:37:28
21:37:29  Concurrency: 4 threads (target='dev')
21:37:29
21:37:29  1 of 2 START sql table model dbt_alice.my_first_dbt_model  [RUN]
21:37:29  1 of 2 OK created sql table model dbt_alice.my_first_dbt_model  [SELECT 2 in 0.17s]
21:37:29  2 of 2 START sql view model dbt_alice.my_second_dbt_model  [RUN]
21:37:29  2 of 2 OK created sql view model dbt_alice.my_second_dbt_model  [CREATE VIEW in 0.13s]
21:37:29
21:37:29  Finished running 1 table model, 1 view model in 0 hours 0 minutes and 0.86 seconds (0.86s).
21:37:29
21:37:29  Completed successfully
21:37:29
21:37:29  Done. PASS=2 WARN=0 ERROR=0 SKIP=0 TOTAL=2

If you'd like to continue investigating, can you provide the following?

1. OS + version
2. Full Python version
3. dbt version
4. Which adapter you are using + version
5. Exact command line invocation which triggers the issue

[haf]

https://drive.haf.se/d/s/sdJFlr4G4hkk8urRMIflLEKrXj1524uT/69GnOfWQwY9DussCMV5PVdAMs-x3dY0P-FLRgSluJQwo

@dbeatty10 it should all be in the repro, but here's a screen recording of following the readme in case it's a mac-specific issue

Also thank you for investigating!🙏

[haf]

@peterallenwebb ping, any progress the last two weeks? From your pasted output, it doesn't seem like you're running with poetry like the repro is?

[peterallenwebb]

@haf Yes. You're right. I was able to reproduce the issue using your video. Thanks for that.

Using dbt as a library in this way isn't technically a supported use case for dbt yet, though we are making steps in that direction for 1.5 and future versions. Even so, I'll set aside some time on Monday to see if I can suggest a solution for you.

[jaceksan]

I hit this issue as well.
Not using dbt as library.
dbt finishes OK with postgres target.
dbt fails with this error with vertica target.

I tried to create a new macro vertica__create_constraints, copying from the Postgres version, and updating SQL queries for Vertica.

Hard to say where I made a mistake, very hard to debug this.

Using:
Python 3.10 in venv. Ubuntu 22.04.
dbt-postgres==1.4.4
dbt-snowflake==1.4.2
dbt-vertica==1.4.4

Will try to derive the new Vertica macro from Snowflake, it looks more mature, maybe I will succeed.

[cwegener]

The new logbook maintainer has now reached this bug in the process of clearing the long backlog.

getlogbook/logbook#333
getlogbook/logbook#320

The additionally confusing part is that dbt-core says in a code comment that logbook is legacy and is not used since dbt 1.0 but is clearly being imported in dbt.logger ...

dbt-core/core/setup.py

Lines 55 to 58 in 7fbfd53

	# ----
	# Legacy: This package has not been updated since 2019, and it is unused in dbt's logging system (since v1.0)
	# The dependency here will be removed along with the removal of 'legacy logging', in a future release of dbt-core
	"logbook>=1.5,<1.6",

dbt-core/core/dbt/logger.py

Line 5 in 7fbfd53

import logging

[jtcohen6]

Correct - we've kept the "legacy logger" around to keep supporting some older integrations, but we disable it unless a specific env var is switched on:

dbt-core/core/dbt/logger.py

Lines 454 to 455 in 7fbfd53

	if not dbt.flags.ENABLE_LEGACY_LOGGER:
	logger.disable()

We're planning to remove it (finally) in dbt-core v1.7 (October):

• [CT-2786] Remove "legacy logger" #8027

[jimmymaise]

it seems to be that logbook still exists in the latest version of dbt. Currently we have issue with logbook when using auditwheel to build dbt.
https://github.com/dbt-labs/dbt-core/blob/main/core/dbt/logger.py

So can you just remove it from dbt-core or upgrade it to the new version?

amd64_build_1 | subprocess run: auditwheel repair /tmp/tmpj8avu2jh/Logbook-1.5.3-cp38-cp38-linux_x86_64.whl --wheel-dir /dist/
amd64_build_1 | INFO:auditwheel.main_repair:Repairing Logbook-1.5.3-cp38-cp38-linux_x86_64.whl
amd64_build_1 | INFO:auditwheel.main_repair:This does not look like a platform wheel, no ELF executable or shared library file (including compiled Python C extension) found in the wheel archive