[CT-1917] [Regression] Non-error log is not silenced by -q flag.

[elongl]

Is this a regression in a recent version of dbt-core?

• I believe this is a regression in dbt-core functionality
• I have searched the existing issues, and I could not find an existing issue for this regression

Current Behavior

According to -q:

Suppress all non-error logging to stdout. Does not affect {{ print() }} macro calls.

A new log is printed even though it's not an error.

(elementary) ☁  dbt_project [main] dbt run-operation hello
14:22:47  target not specified in profile 'elementary', using 'default'
14:22:47  Running with dbt=1.4.0
hello
(elementary) ☁  dbt_project [main] dbt -q run-operation hello
14:22:56  target not specified in profile 'elementary', using 'default'
hello

Expected/Previous Behavior

Previously, the log was omitted when passing the -q flag.

(elementary) ☁  dbt_project [main] dbt run-operation hello
14:22:15  target not specified in profile 'elementary', using 'default'
14:22:16  Running with dbt=1.3.0
hello
(elementary) ☁  dbt_project [main] dbt -q run-operation hello
hello

Steps To Reproduce

1. Name a default target without having a target defined.
2. Run a dbt command with the -q flag.

Relevant log output

No response

Environment

- OS: macOS
- Python: 3.9.6
- dbt (working version): 1.3.0
- dbt (regression version): 1.4.0

Which database adapter are you using with dbt?

No response

Additional Context

I'd love to contribute.

[jtcohen6]

My suspicion here is:

• We set up a basic event logger before we have the full set of information we need to initialize it for real (all flags & configs resolved, including --quiet mode). This ensures that any real initialization errors don't get swallowed. Relevant: [CT-1652] [Regression] [main/1.4] Failure to raise initialization exception #6434, Paw/ct 1652 restore default logging #6447.
• In order to resolve global configs, we have to look at UserConfig, which today is defined in profiles.yml, so we have to render profiles.yml. (Should it be? Almost certainly not: [CT-1470] Whither UserConfig? #6207)
• The event you're seeing, MissingProfileTarget, is raised during render_profile, which is happening during initialization and before we call setup_event_logger here:
  

  dbt-core/core/dbt/main.py

  Lines 225 to 232 in c65ba11

  	task = parsed.cls.from_args(args=parsed)
  	# Set up logging
  	log_path = None
  	if task.config is not None:
  	log_path = getattr(task.config, "log_path", None)
  	log_manager.set_path(log_path)
  	setup_event_logger(log_path or "logs")

Confirmed:

ipdb> task = parsed.cls.from_args(args=parsed)
15:01:43  target not specified in profile 'my-profile', using 'default'

Options:

1. We document that --quiet doesn't work for warnings/errors during initialization
2. We turn the initial stdout logger (before we've resolved configs) into ERROR-level only:
   

   dbt-core/core/dbt/events/functions.py

   Lines 112 to 118 in c65ba11

   	# Since dbt-rpc does not do its own log setup, and since some events can
   	# currently fire before logs can be configured by setup_event_logger(), we
   	# create a default configuration with default settings and no file output.
   	EVENT_MANAGER: EventManager = EventManager()
   	EVENT_MANAGER.add_logger(
   	_get_logbook_log_config() if flags.ENABLE_LEGACY_LOGGER else _get_stdout_config()
   	)

[elongl]

Hi @jtcohen6 , thanks a lot for replying.
I personally tend to favor (2) because I think that if a user is using --quiet they'd generally like to keep a program quiet at its entirety except for logs made by them (print()) and it doesn't really matter at what phase the execution is.
What do you think?

If that resonates, care to share any guidelines on how can I make this contribution?

[jtcohen6]

I think it would be as simple as modifying line 117 to pass a level override into _get_stdout_config:

 EVENT_MANAGER.add_logger( 
     _get_logbook_log_config() if flags.ENABLE_LEGACY_LOGGER else _get_stdout_config(EventLevel.ERROR) 
 ) 

@peterallenwebb How does this approach sound to you? The downside is, I think we'd never actually log MissingProfileTarget (or any other initialization-time logging below that isn't error-level) — whether or not the user is actually passing the --quiet flag, because we haven't resolved flags before this default logger is set up.

[peterallenwebb]

The approach would work, and it would indeed have the consequences you described.

We could, however, add some log configuration code right after command line arguments are parsed so that we can turn on quiet mode as soon as possible, if it is specified. I think I actually like that approach better?

[jtcohen6]

@peterallenwebb Let's give it a shot! While it might not work perfectly for "quiet mode," if set via env var or user config, I generally expect users to pass it in as a CLI flag, as @elongl is showing above.