Feature/loggging of schema changes

[AlexanderMann]

Motivation

Issues posted by users of this codebase sometimes have a lack of usable logs present. Additionally, when testing, or debugging in production, more fine grained information can be quite useful.

Notes

This is all opt-in-enabled by setting the new config option: logging_level, to DEBUG or lower.

This pr adds special logging with durations for:

sql_base.upsert_table_helper

Each decision which modifies the table in some manner is logged:

INFO Table Schema Change [`root`.`('id',)`:`id`] New column (took 1 millis)
INFO Table Schema Change [`root`.`('changing_literal_type',)`:`changing_literal_type`] New column (took 1 millis)
INFO Table Schema Change [`root`.`('_sdc_received_at',)`:`_sdc_received_at`] New column (took 1 millis)
INFO Table Schema Change [`root`.`('_sdc_sequence',)`:`_sdc_sequence`] New column (took 1 millis)
INFO Table Schema Change [`root`.`('_sdc_table_version',)`:`_sdc_table_version`] New column (took 2 millis)
INFO Table Schema Change [`root`.`('_sdc_batched_at',)`:`_sdc_batched_at`] New column (took 2 millis)
INFO Table Schema Change [`root`.`('changing_literal_type',)`:`changing_literal_type__i`] Splitting changing_literal_type into changing_literal_type__f and changing_literal_type__i. New column matches existing column path, but the types are incompatible. (took 6 millis)
INFO Table Schema Change [`root`.`('changing_literal_type',)`:`changing_literal_type__b`] Adding new column to split column ('changing_literal_type',). New column matches existing column's path, but no types were compatible. (took 1 millis)

INFO Table Schema Change [`cats`.`('id',)`:`id`] New column (took 2 millis)
INFO Table Schema Change [`cats`.`('name',)`:`name`] New column (took 6 millis)
INFO Table Schema Change [`cats`.`('name',)`:`name`] Made existing column nullable. New column is nullable, existing column is not (took 3 millis)

psycopg2.connection/psycopg2.cursor queries

Every query run will output logs similar to:

extras.py                  422 DEBUG    0 millis spent executing: b'ALTER TABLE "public"."cats" ADD COLUMN "age" bigint;'
extras.py                  422 DEBUG    1 millis spent executing: b"\n            SELECT EXISTS (\n                SELECT 1 FROM pg_tables\n                WHERE schemaname = 'public' AND\n                      tablename = 'cats');"
extras.py                  422 DEBUG    0 millis spent executing: b'SELECT description FROM pg_description WHERE objoid = \'"public"."cats"\'::regclass;'
extras.py                  422 DEBUG    0 millis spent executing: b'COMMENT ON TABLE "public"."cats" IS \'{"version": null, "schema_version": 1, "table_mappings": [{"type": "TABLE", "from": ["cats"], "to": "cats"}], "key_properties": ["id"], "mappings": {"id": {"type": ["integer"], "from": ["id"]}, "name": {"type": ["string"], "from": ["name"]}, "paw_size": {"type": ["integer"], "from": ["paw_size"]}, "paw_colour": {"type": ["string"], "from": ["paw_colour"]}, "flea_check_complete": {"type": ["boolean"], "from": ["flea_check_complete"]}, "pattern": {"type": ["string", "null"], "from": ["pattern"]}, "age": {"type": ["integer", "null"], "from": ["age"]}}}\';'

Suggested Musical Pairing

Windows creeking from the cold