dbt docs 0.16 don't build on Windows

[joshpeng-quibi]

Describe the bug

dbt docs generate with dbt 0.16 doesn't work on Windows with ValueError: Invalid format string. The exact same dbt project when ran from dbt 0.15.2 builds the catalog perfectly.

Steps To Reproduce

1. pip install -U dbt
2. dbt docs generate <-- errors with ValueError: Invalid format string
3. pip install -U dbt==0.15.2
4. dbt docs generate <-- works

Expected behavior

dbt should be able to build the docs.

Screenshots and log output

2020-03-31 05:11:08.098742 (MainThread): Encountered an error:
2020-03-31 05:11:08.098742 (MainThread): Invalid format string
2020-03-31 05:11:08.101771 (MainThread): Traceback (most recent call last):
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\main.py", line 81, in main
    results, succeeded = handle_and_check(args)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\main.py", line 159, in handle_and_check
    task, res = run_from_args(parsed)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\main.py", line 212, in run_from_args
    results = task.run()
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\task\generate.py", line 194, in run
    compile_results = CompileTask.run(self)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\task\runnable.py", line 351, in run
    self._runtime_initialize()
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\task\runnable.py", line 107, in _runtime_initialize
    super()._runtime_initialize()
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\task\runnable.py", line 75, in _runtime_initialize
    self.load_manifest()
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\task\runnable.py", line 63, in load_manifest
    self.manifest = get_full_manifest(self.config)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\perf_utils.py", line 23, in get_full_manifest
    return load_manifest(config, internal, set_header)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\parser\manifest.py", line 646, in load_manifest
    return ManifestLoader.load_all(config, internal_manifest, macro_hook)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\parser\manifest.py", line 336, in load_all
    loader.load(internal_manifest=internal_manifest)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\parser\manifest.py", line 208, in load
    self.parse_project(project, macro_manifest, old_results)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\parser\manifest.py", line 182, in parse_project
    self.parse_with_cache(path, parser, old_results)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\parser\manifest.py", line 138, in parse_with_cache
    parser.parse_file(block)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\parser\base.py", line 380, in parse_file
    self.parse_node(file_block)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\parser\base.py", line 353, in parse_node
    self.render_update(node, config)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\parser\base.py", line 330, in render_update
    self.update_parsed_node(node, config)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\parser\base.py", line 314, in update_parsed_node
    get_rendered(hook.sql, context, parsed_node, capture_macros=True)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\clients\jinja.py", line 415, in get_rendered
    return render_template(template, ctx, node)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\clients\jinja.py", line 409, in render_template
    return template.render(ctx)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\jinja2\asyncsupport.py", line 76, in render
    return original_render(self, *args, **kwargs)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\jinja2\environment.py", line 1008, in render
    return self.environment.handle_exception(exc_info, True)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\jinja2\environment.py", line 780, in handle_exception
    reraise(exc_type, exc_value, tb)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\jinja2\_compat.py", line 37, in reraise
    raise value.with_traceback(tb)
  File "<template>", line 1, in top-level template code
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\jinja2\sandbox.py", line 440, in call
    return __context.call(__obj, *args, **kwargs)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\clients\jinja.py", line 231, in __call__
    return self.call_macro(*args, **kwargs)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\dbt\clients\jinja.py", line 161, in call_macro
    return macro(*args, **kwargs)
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\jinja2\runtime.py", line 574, in _invoke
    rv = self._func(*arguments)
  File "<template>", line 27, in macro
  File "c:\users\josh\anaconda3\envs\dbt\lib\site-packages\jinja2\sandbox.py", line 440, in call
    return __context.call(__obj, *args, **kwargs)
ValueError: Invalid format string

System information

Which database are you using dbt with?

• [x] bigquery

The output of dbt --version:

installed version: 0.16.0
   latest version: 0.16.0

Up to date!

The operating system you're using:
Windows 10 x64

The output of python --version:
Python 3.7.4

Additional context

Add any other context about the problem here.

[beckjake]

Hi @joshpeng-quibi, thanks for the bug report!

Do you have any interesting pre/post model hooks going on? I see this in the stack trace:

• get_rendered(hook.sql, context, parsed_node, capture_macros=True)

dbt is trying to parse a model hook in your file and something about a macro in that hook is making jinja mad (it could very well be a macro from dbt!).

There must be _something_ about your project/environment that's causing this, even if it's just triggering a latent bug in dbt - dbt==0.16.0 generates docs just fine as it is in our integration test suite, even on windows.

dbt also looks like it's not catching that ValueError and showing any useful context - that is a bug for sure.

[joshpeng-quibi]

Interesting, interesting. Seems like the issue is indeed a post-hook that was doing something with this: {{ run_started_at.strftime("%s") }}. According to Stackoverflow, %s doesn't work on Windows. I swapped it to be {{ run_started_at.timestamp()|int }}. Thanks.

[beckjake]

Ok, good that you found it! @drewbanin we should check 0.17.0's new error handling behavior fixes this (I doubt it) and then if not, open a new issue about catching errors like that in macros and providing better errors - I doubt we can be perfect, but we can at least point to the offending macro. (extra cool-points: could we extract any nested python stack trace to get what line of Python caused the ValueError?)

You shouldn't have to read a stack trace and know how many macro calls deep you are to find out that run_started_at.strftime("s") is causing an error, that's just unreasonable.

[drewbanin]

Sure thing @beckjake - let's close this one, but can you open a new issue for the change you're describing and link back to it here?