[CORE-16] [Bug] Uncolored stdout when using the --use-colors flag

[jbonatakis]

Is there an existing issue for this?

• I have searched the existing issues

Current Behavior

When running models via the CLI with the --use-colors flag, the output is still uncolored.
dbt --use-colors run --select <models>

Expected Behavior

I would expect the output to be colored.

Steps To Reproduce

Running dbt via the CLI, execute: dbt --use-colors run --select <models>

Relevant log output

No response

Environment

- OS: macOS BigSur 11.6.1
- Python: 3.9
- dbt: 1.0.0 (installed via dbt-bigquery)

What database are you using dbt with?

bigquery

Additional Context

I am running this in a Docker container via a shell script and the full command, including Docker commands, is:

docker run --rm \
  -e DBT_DEV_PROJECT=$DBT_DEV_PROJECT \
  -p 8080:8080 \
  -v $HOME/.config/:/root/.config \
  -v ${DBT_HOME}/dbt:/dbt \
  $target_image \
  "$@"

where the values passed ("$@") are dbt --use-colors run --select <models>

If I rebuild my image using dbt v0.21.0 then the same command results in colored output.

[jtcohen6]

@jbonatakis Thanks for the report, and thanks for upgrading to v1.0 so quickly!

I'm seeing colorized output when I use dbt --use-colors run --select <models> locally, though I'm not running dbt via Docker.

There are two possibilities here:

• The --use-colors flag / global config is not working properly within dbt-core
• Your terminal is not displaying color-tagged fields as colorized

A few ways to dig into this:

• In logs/dbt.log, do you see color tags such as [33mWARNING [0m], [ [32mOK [0m in 1.09s], [32mCompleted successfully [0m? Alternatively, if you add --log-format json to your command, and check the msg fields of the resulting CLI output, do you see the color tags there?
• Could you try outputting explicitly color-tagged text in your terminal, e.g. echo -e '\033[32mThis is in green\033[0m'?

[jbonatakis]

@jtcohen6 Thanks for the suggestions!

• I ran echo -e '\033[32mThis is in green\033[0m' and it printed green.

• I checked logs/dbt.log and it formats the color tags like this: [�[32mOK�[0m in 0.98s]

If I rebuild my image using v0.21.0 and run the same command I get colored output, but oddly enough there are no color tags in the dbt.log file.

Console (v0.21.0):

Log file (v0.21.0):

When I run v1.0.0.0 with the --log-format json option, the output does include the color tags:
"\u001b[32mCompleted successfully\u001b[0m". Again, if I run that by itself in my console, I get green output
echo -e "\u001b[32mCompleted successfully\u001b[0m"

This seems like an encoding issue.

My Dockerfile is based on python:3.9-slim-bullseye (link to source Dockerfile), which itself is based off of debian:bullseye-slim

[varun-dc]

I've noticed something similar

dbt --use-colors run --profile dc_dbt_int_snowflake --target dev

You'll get color in the terminal

Whereas,

dbt --use-colors run --profile dc_dbt_int_snowflake --target dev | less

You'll get no color because it's not a tty?

The --use-colors flag doesn't make a difference in both of these examples.

I'm running this in a regular terminal, with color output working in all other places (other CLI programs).

[varun-dc]

In our case, we would like colors to be output even if we're piping to another program vs piping out into a terminal's output. The --use-colors should force colors to still be output.

For example, grep ... | less by default isn't outputting colors, but grep ... --color=always | less does output color escape codes.

Is this related to #4379 and/or #4354 ?

[jtcohen6]

I haven't had a chance to dig further into this, but just want to drop a few quick notes:

• It's quite likely that these changes are related to the rework of structured logging in v1
• It sounds like we might not be using the right color tags for the system? What do you see if you cat logs/dbt.log?
• In earlier versions of dbt (such as v0.21), logs/dbt.log only contained debug-level events, and excluded info-level logs that were printed to the CLI. Those tend to the be the only logs with color. That's why, in earlier versions, you won't see color tags in logs/dbt.log, but you should see them in v1
• Colorizing logs is on by default, so in general the --use-colors flag is unnecessary. The flag is only needed to override if you've set DBT_USE_COLORS=False (env var) or use_colors: False (in profiles.yml). See docs on global configs: https://docs.getdbt.com/reference/global-configs

@nathaniel-may Sounds like we should add a spike for this to the list for #4441

[varun-dc]

I'm not seeing any colors escape codes in <dbt project>/logs/dbt.log with dbt==1.0.0.
Sorry my mistake. Yes, I do see color if I cat logs/dbt.log.

But my concern is about piping and sub shells (specifically we're invoking dbt from another application) and we're no longer seeing color in the stdout of dbt in such cases.

[jbonatakis]

I get color output if I cat logs/dbt.log

[nathaniel-may]

It looks like docker's default shell does not understand 16-bit unicode-encoded escape sequences, namely: \u001b, but it does understand ANSI, namely: \033.

Reproduction

Open the docker cli and run the following two commands:
unicode: (no color, displays escape sequences)

echo -e "\u001b[32mCompleted successfully\u001b[0m"

ansi: (is green, no escape sequences)

echo -e "\033[32mCompleted successfully\033[0m"

Workaround

From your host machine (not the docker cli) you can run the following command which will open a new shell which does understand unicode escape sequences the way dbt v1.0.0 is emitting them:

% docker exec -it my-container env TERM=xterm-256color script -q -c "/bin/bash" /dev/null

Solution

Although unicode escape sequences are part of a good standard that has been around a very long time, they are unfortunately not supported by some modern and commonly used shells. For compatibility reasons we should revert to using the older ANSI encoding.

[nathaniel-may]

It looks like it's non-trivial to revert escape sequences via our color library while also maintaining windows support for color. I'm closing this ticket because there is a workaround.