[CT-582] stdout colouring broken on dbt-core on Windows

[marksabincarnivaluk]

Is there an existing issue for this?

• I have searched the existing issues

Current Behavior

Red/green colouring is no longer visible in dbt v1.1 on Windows.
Instead we see unexpected characters such as [←[32mPASS←[0m in 0.82s]

Possibly caused by #4792

(dbt-env) C:\work\dbt-cuk>dbt test -m dim_booking
07:13:33 Running with dbt=1.1.0
07:13:35 Found 280 models, 593 tests, 1 snapshot, 0 analyses, 403 macros, 2 operations, 5 seed files, 388 sources, 0 exposures, 0 metrics
07:13:35
07:13:39 Concurrency: 4 threads (target='dev')
07:13:39
07:13:39 1 of 12 START test not_null_dim_booking_booking_id ............................. [RUN]
07:13:39 2 of 12 START test not_null_dim_booking_booking_ref ............................ [RUN]
07:13:39 3 of 12 START test not_null_dim_booking_booking_status_code .................... [RUN]
07:13:39 4 of 12 START test not_null_dim_booking_brand_code ............................. [RUN]
07:13:40 4 of 12 PASS not_null_dim_booking_brand_code ................................... [←[32mPASS←[0m in 1.28s]
07:13:40 5 of 12 START test not_null_dim_booking_cruise_code ............................ [RUN]
07:13:40 2 of 12 PASS not_null_dim_booking_booking_ref .................................. [←[32mPASS←[0m in 1.40s]
07:13:40 6 of 12 START test not_null_dim_booking_holiday_end_date ....................... [RUN]
07:13:40 3 of 12 PASS not_null_dim_booking_booking_status_code .......................... [←[32mPASS←[0m in 1.43s]
07:13:40 7 of 12 START test not_null_dim_booking_holiday_start_date ..................... [RUN]
07:13:41 1 of 12 PASS not_null_dim_booking_booking_id ................................... [←[32mPASS←[0m in 2.08s]
07:13:41 8 of 12 START test not_null_dim_booking_is_commercial_booking .................. [RUN]
07:13:41 5 of 12 PASS not_null_dim_booking_cruise_code .................................. [←[32mPASS←[0m in 0.89s]
07:13:41 9 of 12 START test not_null_dim_booking_logical_cruise_buskey .................. [RUN]
07:13:41 7 of 12 PASS not_null_dim_booking_holiday_start_date ........................... [←[32mPASS←[0m in 0.82s]
07:13:41 10 of 12 START test not_null_dim_booking_ship_code ............................. [RUN]
07:13:42 6 of 12 PASS not_null_dim_booking_holiday_end_date ............................. [←[32mPASS←[0m in 1.41s]
07:13:42 11 of 12 START test unique_dim_booking_booking_id .............................. [RUN]
07:13:42 8 of 12 PASS not_null_dim_booking_is_commercial_booking ........................ [←[32mPASS←[0m in 1.06s]
07:13:42 12 of 12 START test unique_dim_booking_booking_ref ............................. [RUN]
07:13:42 9 of 12 PASS not_null_dim_booking_logical_cruise_buskey ........................ [←[32mPASS←[0m in 1.01s]
07:13:43 11 of 12 PASS unique_dim_booking_booking_id .................................... [←[32mPASS←[0m in 0.89s]
07:13:43 12 of 12 PASS unique_dim_booking_booking_ref ................................... [←[32mPASS←[0m in 0.86s]
07:13:43 10 of 12 PASS not_null_dim_booking_ship_code ................................... [←[32mPASS←[0m in 1.89s]
07:13:43
07:13:43 Running 2 on-run-end hooks
07:13:43 1 of 2 START hook: cuk_project.on-run-end.0 .................................... [RUN]
07:13:45 1 of 2 OK hook: cuk_project.on-run-end.0 ....................................... [←[32mSUCCESS 1←[0m in 2.14s]
07:13:45 2 of 2 START hook: cuk_project.on-run-end.1 .................................... [RUN]
07:13:45 2 of 2 OK hook: cuk_project.on-run-end.1 ....................................... [←[32mSUCCESS 1←[0m in 0.12s]
07:13:45
07:13:46
07:13:46 Finished running 12 tests, 2 hooks in 10.20s.
07:13:46
07:13:46 ←[32mCompleted successfully←[0m
07:13:46
07:13:46 Done. PASS=12 WARN=0 ERROR=0 SKIP=0 TOTAL=12
07:13:51 Error sending message, disabling tracking

Expected Behavior

dbt v1.05 shows PASS/SUCCESS is green and FAIL in red.

07:24:28 Running with dbt=1.0.5
07:24:29 Unable to do partial parsing because of a dbt version mismatch. Saved manifest version: 1.1.0. Current version: 1.0.5.
07:24:38 Found 280 models, 593 tests, 1 snapshot, 0 analyses, 401 macros, 2 operations, 5 seed files, 388 sources, 0 exposures, 0 metrics
07:24:38
07:24:41 Concurrency: 4 threads (target='dev')
07:24:41
07:24:41 1 of 12 START test not_null_dim_booking_booking_id.............................. [RUN]
07:24:41 2 of 12 START test not_null_dim_booking_booking_ref............................. [RUN]
07:24:41 3 of 12 START test not_null_dim_booking_booking_status_code..................... [RUN]
07:24:41 4 of 12 START test not_null_dim_booking_brand_code.............................. [RUN]
07:24:42 1 of 12 PASS not_null_dim_booking_booking_id.................................... [PASS in 0.95s]
07:24:42 5 of 12 START test not_null_dim_booking_cruise_code............................. [RUN]
07:24:42 4 of 12 PASS not_null_dim_booking_brand_code.................................... [PASS in 1.06s]
07:24:42 6 of 12 START test not_null_dim_booking_holiday_end_date........................ [RUN]
07:24:42 3 of 12 PASS not_null_dim_booking_booking_status_code........................... [PASS in 1.10s]
07:24:42 7 of 12 START test not_null_dim_booking_holiday_start_date...................... [RUN]
07:24:42 2 of 12 PASS not_null_dim_booking_booking_ref................................... [PASS in 1.15s]
07:24:42 8 of 12 START test not_null_dim_booking_is_commercial_booking................... [RUN]
07:24:43 6 of 12 PASS not_null_dim_booking_holiday_end_date.............................. [PASS in 0.85s]
07:24:43 9 of 12 START test not_null_dim_booking_logical_cruise_buskey................... [RUN]
07:24:43 5 of 12 PASS not_null_dim_booking_cruise_code................................... [PASS in 1.18s]
07:24:43 10 of 12 START test not_null_dim_booking_ship_code.............................. [RUN]
07:24:43 7 of 12 PASS not_null_dim_booking_holiday_start_date............................ [PASS in 1.05s]
07:24:43 11 of 12 START test unique_dim_booking_booking_id............................... [RUN]
07:24:43 8 of 12 PASS not_null_dim_booking_is_commercial_booking......................... [PASS in 1.00s]
07:24:43 12 of 12 START test unique_dim_booking_booking_ref.............................. [RUN]
07:24:44 11 of 12 PASS unique_dim_booking_booking_id..................................... [PASS in 0.80s]
07:24:44 9 of 12 PASS not_null_dim_booking_logical_cruise_buskey......................... [PASS in 1.13s]
07:24:44 10 of 12 PASS not_null_dim_booking_ship_code.................................... [PASS in 0.95s]
07:24:44 12 of 12 PASS unique_dim_booking_booking_ref.................................... [PASS in 1.13s]
07:24:44
07:24:44 Running 2 on-run-end hooks
07:24:44 1 of 2 START hook: cuk_project.on-run-end.0..................................... [RUN]
07:24:47 1 of 2 OK hook: cuk_project.on-run-end.0........................................ [SUCCESS 1 in 2.53s]
07:24:47 2 of 2 START hook: cuk_project.on-run-end.1..................................... [RUN]
07:24:47 2 of 2 OK hook: cuk_project.on-run-end.1........................................ [SUCCESS 1 in 0.10s]
07:24:47
07:24:47
07:24:47 Finished running 12 tests, 2 hooks in 9.13s.
07:24:47
07:24:47 Completed successfully
07:24:47
07:24:47 Done. PASS=12 WARN=0 ERROR=0 SKIP=0 TOTAL=12
07:24:53 Error sending message, disabling tracking

Steps To Reproduce

On Windows, install dbt v1.1.0.
Run a command such as dbt test in the console.
Inspect output.

Relevant log output

No response

Environment

- OS:Windows
- Python:3.8.2
- dbt:v1.1.0

What database are you using dbt with?

snowflake

Additional Context

No response

[jtcohen6]

Possibly related to: #4443

[iknox-fa]

Hi @marksabincarnivaluk, thanks for the bug ticket. Based on the output I'm seeing the correct color tags are there but they're being shown as raw text for some reason ([←[32m should be the correct windows color code for green).

Can you test your windows console by running this echo?
echo �[32mThis is green�[0m

[marksabincarnivaluk]

Hi Ian, Thanks for looking into this. I get no colour with that echo. (dbt-env) C:\work\dbt-cuk>echo �[32mThis is green�[0m �[32mThis is green�[0m And also in Python:

>> print("\033[31mThis is red\033[0m")

←[31mThis is red←[0m Regards Mark

[marksabincarnivaluk]

Hi,

I've found that these key sequences do result in colours at the command prompt:

echo Ctrl+[ [32m This is green Ctrl+[ [0m

or

echo alt 027 [32m This is green alt 027 [0m

Both Ctrl+[ and alt 027 produce the escape character.

Also in python, this works:

`import os
os.system("color") # Alternative - os.system("")

TCOLOR = "\033[31;3m"
ENDC = "\033[m"
print (TCOLOR + "This is red" + ENDC)`

I see you are using colorama.

The following code, based on dbt's logger.py, does give the colours as expected.
The PR #4792 altered logger.py so it no longer calls
colorama.init(wrap=True)

Although colorama.init(wrap=False) is subsequently called, it seems that it must be called first with wrap=True to make it work on Windows.

`import colorama
from colorama import Fore, Back, Style
import sys

# Remove the next 2 lines to break it
colorama_wrap = True
colorama.init(wrap=colorama_wrap)

if sys.platform == "win32" and not os.getenv("TERM"):
colorama_wrap = False
colorama_stdout = colorama.AnsiToWin32(sys.stdout).stream

colorama.init(wrap=False)

print(Fore.RED + 'some red text')
print(Back.GREEN + 'and with a green background')
print(Style.DIM + 'and in dim text')
print(Style.RESET_ALL)
print('back to normal now')`

[iknox-fa]

I've been able to confirm this is a bug in 1.1.0 on a windows machine. We'll get this prioritized ASAP @marksabincarnivaluk

[jtcohen6]

Wow, this is some weird code! Seems like a direct result of #4792:

Unless this statement has a side-effect or is being used externally, it appears to be deadcode

Sounds like we're talking about just such a side-effect?