Add utils for logging to the command line

README.md

@@ -393,6 +393,37 @@ Usage:
 ```
 
 ---
+### Logger
+#### pretty_time ([source](macros/logger/pretty_time.sql))
+This macro returns a string of the current timestamp, optionally taking a datestring format.
+```sql
+{#- This will return a string like '14:50:34' -#}
+{{ dbt_utils.pretty_time() }}
+
+{#- This will return a string like '2019-05-02 14:50:34' -#}
+{{ dbt_utils.pretty_time(format='%Y-%m-%d %H:%M:%S') }}
+```
+
+#### pretty_log_format ([source](macros/logger/pretty_log_format.sql))
+This macro formats the input in a way that will print nicely to the command line when you `log` it.
+```sql
+{#- This will return a string like:
+"11:07:31 + my pretty message"
+-#}
+
+{{ dbt_utils.pretty_log_format("my pretty message") }}
+```
+### log_info ([source](macros/logger/log_info.sql))
+This macro logs a formatted message (with a timestamp) to the command line.
+```sql
+{{ log_info(dbt_utils.log_info("my pretty message")) }}
+```
+
+```
+11:07:28 | 1 of 1 START table model analytics.fct_orders........................ [RUN]
+11:07:31 + my pretty message
+```
+
 ### Materializations
 #### insert_by_period ([source](macros/materializations/insert_by_period_materialization.sql))
 `insert_by_period` allows dbt to insert records into a table one period (i.e. day, week) at a time.

integration_tests/tests/logger/assert_pretty_output_msg_is_string.sql

@@ -0,0 +1,7 @@
+{% if dbt_utils.pretty_log_format() is string %}
+    {# Return 0 rows for the test to pass #}
+    select 1 where false
+{% else %}
+    {# Return >0 rows for the test to fail #}
+    select 1
+{% endif %}

integration_tests/tests/logger/assert_pretty_time_is_string.sql

@@ -0,0 +1,7 @@
+{% if dbt_utils.pretty_time() is string %}
+    {# Return 0 rows for the test to pass #}
+    select 1 where false
+{% else %}
+    {# Return >0 rows for the test to fail #}
+    select 1
+{% endif %}

macros/logger/log_info.sql

@@ -0,0 +1,5 @@
+{% macro log_info(message) %}
+
+    {{ log(dbt_utils.pretty_log_format(message), info=True) }}
+
+{% endmacro %}

macros/logger/pretty_log_format.sql

@@ -0,0 +1,5 @@
+{% macro pretty_log_format(message) %}
+
+    {{ return( dbt_utils.pretty_time() ~ ' + ' ~ message) }}
+
+{% endmacro %}

macros/logger/pretty_time.sql

@@ -0,0 +1,5 @@
+{% macro pretty_time(format='%H:%M:%S') %}
+
+    {{ return(modules.datetime.datetime.now().strftime(format)) }}
+
+{% endmacro %}

macros/materializations/insert_by_period_materialization.sql

@@ -115,7 +115,7 @@
   -- commit each period as a separate transaction
   {% for i in range(num_periods) -%}
     {%- set msg = "Running for " ~ period ~ " " ~ (i + 1) ~ " of " ~ (num_periods) -%}
-    {{log("         + " ~ modules.datetime.datetime.now().strftime('%H:%M:%S') ~ " " ~ msg, info=True)}}
+    {{ dbt_utils.log_info(msg) }}
 
     {%- set tmp_identifier = model['name'] ~ '__dbt_incremental_period' ~ i ~ '_tmp' -%}
     {%- set tmp_relation = api.Relation.create(identifier=tmp_identifier,
@@ -147,7 +147,7 @@
     {%- if loop_vars.update({'sum_rows_inserted': sum_rows_inserted}) %} {% endif -%}
 
     {%- set msg = "Ran for " ~ period ~ " " ~ (i + 1) ~ " of " ~ (num_periods) ~ "; " ~ rows_inserted ~ " records inserted" -%}
-    {{log("         + " ~ modules.datetime.datetime.now().strftime('%H:%M:%S') ~ " " ~ msg, info=True)}}
+    {{ dbt_utils.log_info(msg) }}
 
   {%- endfor %}