Grype DB parsing of vunnel logs fails to capture tracebacks at error level

[westonsteimel]

Please provide a set of steps on how to reproduce the issue

Ensure slim logging is false:

log:
  slim: false
  level: debug

Disable network connection and attempt to execute the nvd provider:

go run cmd/grype-db/main.go pull --provider-name nvd -g

[0000]  INFO grype-db version: [not provided] (adhoc-build)
[0001]  INFO aggregating vulnerability data providers=[nvd]
[0001]  INFO running vulnerability provider provider=nvd
[0001]  INFO nvd: WARNING: The requested image's platform (linux/amd64) does not match the detected host platform (linux/arm64/v8) and no specific platform was requested
[0003]  INFO nvd: running nvd provider
[0003]  WARN nvd: <function NvdAPI._request at 0x7ffffd1328c0> failed. Retrying in 3 seconds (attempt 1 of 5)
[0006]  WARN nvd: <function NvdAPI._request at 0x7ffffd1328c0> failed. Retrying in 6 seconds (attempt 2 of 5)
[0012]  WARN nvd: <function NvdAPI._request at 0x7ffffd1328c0> failed. Retrying in 12 seconds (attempt 3 of 5)
[0024]  WARN nvd: <function NvdAPI._request at 0x7ffffd1328c0> failed. Retrying in 24 seconds (attempt 4 of 5)
[0049]  WARN nvd: <function NvdAPI._request at 0x7ffffd1328c0> failed. Retrying in 48 seconds (attempt 5 of 5)
[0097]  INFO nvd: wrote 0 entries
[0097] ERROR nvd: error during update: max retries reached, failed to execute function
[0097]  INFO nvd: Traceback (most recent call last):
[0097]  INFO nvd: File "/usr/local/bin/vunnel", line 8, in <module>
[0097]  INFO nvd: sys.exit(run())
[0097]  INFO nvd: File "/usr/local/lib/python3.10/site-packages/vunnel/cli/__init__.py", line 5, in run
[0097]  INFO nvd: cli()
[0097]  INFO nvd: File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1130, in __call__
[0097]  INFO nvd: return self.main(*args, **kwargs)
[0097]  INFO nvd: File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1055, in main
[0097]  INFO nvd: rv = self.invoke(ctx)
[0097]  INFO nvd: File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1657, in invoke
[0097]  INFO nvd: return _process_result(sub_ctx.command.invoke(sub_ctx))
[0097]  INFO nvd: File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1404, in invoke
[0097]  INFO nvd: return ctx.invoke(self.callback, **ctx.params)
[0097]  INFO nvd: File "/usr/local/lib/python3.10/site-packages/click/core.py", line 760, in invoke
[0097]  INFO nvd: return __callback(*args, **kwargs)
[0097]  INFO nvd: File "/usr/local/lib/python3.10/site-packages/click/decorators.py", line 38, in new_func
[0097]  INFO nvd: return f(get_current_context().obj, *args, **kwargs)
[0097]  INFO nvd: File "/usr/local/lib/python3.10/site-packages/vunnel/cli/cli.py", line 154, in run_provider
[0097]  INFO nvd: provider.run()
[0097]  INFO nvd: File "/usr/local/lib/python3.10/site-packages/vunnel/provider.py", line 166, in run
[0097]  INFO nvd: self._on_error(e)
[0097]  INFO nvd: File "/usr/local/lib/python3.10/site-packages/vunnel/provider.py", line 176, in _on_error
[0097]  INFO nvd: raise e
[0097]  INFO nvd: File "/usr/local/lib/python3.10/site-packages/vunnel/provider.py", line 164, in run
[0097]  INFO nvd: self._update()
[0097]  INFO nvd: File "/usr/local/lib/python3.10/site-packages/vunnel/provider.py", line 136, in _update
[0097]  INFO nvd: urls, count = self.update(last_updated=last_updated)
[0097]  INFO nvd: File "/usr/local/lib/python3.10/site-packages/vunnel/providers/nvd/__init__.py", line 67, in update
[0097]  INFO nvd: for identifier, record in self.manager.get(
[0097]  INFO nvd: File "/usr/local/lib/python3.10/site-packages/vunnel/providers/nvd/manager.py", line 35, in get
[0097]  INFO nvd: yield from self._download_updates(last_updated)  # type: ignore
[0097]  INFO nvd: File "/usr/local/lib/python3.10/site-packages/vunnel/providers/nvd/manager.py", line 67, in _download_updates
[0097]  INFO nvd: for idx, response in enumerate(self.api.cve(last_mod_start_date=last_updated, last_mod_end_date=now)):
[0097]  INFO nvd: File "/usr/local/lib/python3.10/site-packages/vunnel/providers/nvd/api.py", line 95, in cve
[0097]  INFO nvd: yield from self._request_all_pages(
[0097]  INFO nvd: File "/usr/local/lib/python3.10/site-packages/vunnel/providers/nvd/api.py", line 113, in _request_all_pages
[0097]  INFO nvd: response = self._request(url, parameters, headers)
[0097]  INFO nvd: File "/usr/local/lib/python3.10/site-packages/vunnel/utils/__init__.py", line 40, in wrapper
[0097]  INFO nvd: raise RuntimeError("max retries reached, failed to execute function")
[0097]  INFO nvd: RuntimeError: max retries reached, failed to execute function
[0097] ERROR 1 error occurred:
	* failed to pull data from "nvd" provider: command failed: 1


error: 1 error occurred:
	* failed to pull data from "nvd" provider: command failed: 1

exit status 1

What happened:

Notice we get the error level line ERROR nvd: error during update: max retries reached, failed to execute function; however, the following traceback and python exception line end up logged as just INFO

What you expected to happen:

We would like to ensure these end up logged as ERROR so it is easier to understand the details around why a particular provider may have failed.

Anything else we need to know?:

The current log parsing logic is at

grype-db/pkg/provider/providers/external/log_writer.go

Lines 71 to 118 in c12c4d7

	func processLogLine(line string) (string, string) {
	line = strings.TrimRight(line, "\n")
	groups := matchNamedCaptureGroups(logLevelPattern, line)
	level, ok := groups["level"]
	if !ok || level == "" {
	return defaultLogLevel, line
	}
	prefix, ok := groups["prefix"]
	if !ok {
	return defaultLogLevel, line
	}
	suffix, ok := groups["suffix"]
	if !ok {
	return defaultLogLevel, line
	}
	message := fmt.Sprintf("%s%s", prefix, suffix)
	return strings.ToUpper(level), message
	}
	func (lw logWriter) Write(p []byte) (n int, err error) {
	for _, line := range strings.Split(string(p), "\n") {
	level, line := processLogLine(line)
	if line != "" {
	message := fmt.Sprintf("[%s]", lw.name) + line
	switch level {
	case "TRACE":
	log.Trace(message)
	case "DEBUG":
	log.Debug(message)
	case "INFO":
	log.Info(message)
	case "WARN", "WARNING":
	log.Warn(message)
	case "ERROR":
	log.Error(message)
	default:
	log.Info(message)
	}
	}
	}
	return len(p), nil
	}

. The difficulty here is that it currently processes these line-by-line and the traceback lines and following don't have a log level coming from python since they came from the raised exception rather than from the logger. It may make sense to use the previously known log level until another is explicitly found or something like that?