2022-05-23 20:48:50 INFO i.a.w.w.WorkerRun(call):49 - Executing worker wrapper. Airbyte version: 0.38.2-alpha 2022-05-23 20:48:50 INFO i.a.w.t.TemporalAttemptExecution(get):108 - Docker volume job log path: /tmp/workspace/21/0/logs.log 2022-05-23 20:48:50 INFO i.a.w.t.TemporalAttemptExecution(get):113 - Executing worker wrapper. Airbyte version: 0.38.2-alpha 2022-05-23 20:48:50 INFO i.a.w.DefaultReplicationWorker(run):107 - start sync worker. job id: 21 attempt id: 0 2022-05-23 20:48:50 INFO i.a.w.DefaultReplicationWorker(run):119 - configured sync modes: {null.ad_account=full_refresh - append} 2022-05-23 20:48:50 INFO i.a.w.p.a.DefaultAirbyteDestination(start):69 - Running destination... 2022-05-23 20:48:50 INFO i.a.c.i.LineGobbler(voidCall):82 - Checking if airbyte/destination-mssql:0.1.17 exists... 2022-05-23 20:48:50 INFO i.a.c.i.LineGobbler(voidCall):82 - airbyte/destination-mssql:0.1.17 was found locally. 2022-05-23 20:48:50 INFO i.a.w.p.DockerProcessFactory(create):108 - Creating docker job ID: 21 2022-05-23 20:48:50 INFO i.a.w.p.DockerProcessFactory(create):163 - Preparing command: docker run --rm --init -i -w /data/21/0 --log-driver none --name destination-mssql-write-21-0-ieqtc --network host -v airbyte_workspace:/data -v /tmp/airbyte_local:/local -e WORKER_CONNECTOR_IMAGE=airbyte/destination-mssql:0.1.17 -e WORKER_JOB_ATTEMPT=0 -e WORKER_ENVIRONMENT=DOCKER -e AIRBYTE_ROLE= -e AIRBYTE_VERSION=0.38.2-alpha -e WORKER_JOB_ID=21 airbyte/destination-mssql:0.1.17 write --config destination_config.json --catalog destination_catalog.json 2022-05-23 20:48:50 INFO i.a.c.i.LineGobbler(voidCall):82 - Checking if airbyte/source-facebook-marketing:0.2.48 exists... 2022-05-23 20:48:50 INFO i.a.c.i.LineGobbler(voidCall):82 - airbyte/source-facebook-marketing:0.2.48 was found locally. 2022-05-23 20:48:50 INFO i.a.w.p.DockerProcessFactory(create):108 - Creating docker job ID: 21 2022-05-23 20:48:50 INFO i.a.w.p.DockerProcessFactory(create):163 - Preparing command: docker run --rm --init -i -w /data/21/0 --log-driver none --name source-facebook-marketing-read-21-0-vpjfu --network host -v airbyte_workspace:/data -v /tmp/airbyte_local:/local -e WORKER_CONNECTOR_IMAGE=airbyte/source-facebook-marketing:0.2.48 -e WORKER_JOB_ATTEMPT=0 -e WORKER_ENVIRONMENT=DOCKER -e AIRBYTE_ROLE= -e AIRBYTE_VERSION=0.38.2-alpha -e WORKER_JOB_ID=21 airbyte/source-facebook-marketing:0.2.48 read --config source_config.json --catalog source_catalog.json --state input_state.json 2022-05-23 20:48:50 INFO i.a.w.DefaultReplicationWorker(lambda$getDestinationOutputRunnable$6):358 - Destination output thread started. 2022-05-23 20:48:50 INFO i.a.w.DefaultReplicationWorker(run):161 - Waiting for source and destination threads to complete. 2022-05-23 20:48:50 INFO i.a.w.DefaultReplicationWorker(lambda$getReplicationRunnable$5):283 - Replication thread started. 2022-05-23 20:48:51 destination > SLF4J: Class path contains multiple SLF4J bindings. 2022-05-23 20:48:51 destination > SLF4J: Found binding in [jar:file:/airbyte/lib/log4j-slf4j-impl-2.17.1.jar!/org/slf4j/impl/StaticLoggerBinder.class] 2022-05-23 20:48:51 destination > SLF4J: Found binding in [jar:file:/airbyte/lib/slf4j-log4j12-1.7.25.jar!/org/slf4j/impl/StaticLoggerBinder.class] 2022-05-23 20:48:51 destination > SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation. 2022-05-23 20:48:51 destination > SLF4J: Actual binding is of type [org.apache.logging.slf4j.Log4jLoggerFactory] 2022-05-23 20:48:51 source > Starting syncing SourceFacebookMarketing 2022-05-23 20:48:51 source > Syncing stream: ad_account 2022-05-23 20:48:52 destination > 2022-05-23 20:48:52 INFO i.a.i.d.m.MSSQLDestination(main):102 - starting destination: class io.airbyte.integrations.destination.mssql.MSSQLDestination 2022-05-23 20:48:52 destination > 2022-05-23 20:48:52 INFO i.a.i.b.IntegrationCliParser(parseOptions):118 - integration args: {catalog=destination_catalog.json, write=null, config=destination_config.json} 2022-05-23 20:48:52 destination > 2022-05-23 20:48:52 INFO i.a.i.b.IntegrationRunner(runInternal):121 - Running integration: io.airbyte.integrations.base.ssh.SshWrappedDestination 2022-05-23 20:48:52 destination > 2022-05-23 20:48:52 INFO i.a.i.b.IntegrationRunner(runInternal):122 - Command: WRITE 2022-05-23 20:48:52 destination > 2022-05-23 20:48:52 INFO i.a.i.b.IntegrationRunner(runInternal):123 - Integration config: IntegrationConfig{command=WRITE, configPath='destination_config.json', catalogPath='destination_catalog.json', statePath='null'} 2022-05-23 20:48:52 destination > 2022-05-23 20:48:52 WARN c.n.s.JsonMetaSchema(newValidator):338 - Unknown keyword order - you should define your own Meta Schema. If the keyword is irrelevant for validation, just use a NonValidationKeyword 2022-05-23 20:48:52 destination > 2022-05-23 20:48:52 WARN c.n.s.JsonMetaSchema(newValidator):338 - Unknown keyword examples - you should define your own Meta Schema. If the keyword is irrelevant for validation, just use a NonValidationKeyword 2022-05-23 20:48:52 destination > 2022-05-23 20:48:52 WARN c.n.s.JsonMetaSchema(newValidator):338 - Unknown keyword airbyte_secret - you should define your own Meta Schema. If the keyword is irrelevant for validation, just use a NonValidationKeyword 2022-05-23 20:48:52 source > '1016791331TQ0001' is not of type 'null', 'number' 2022-05-23 20:48:52 destination > 2022-05-23 20:48:52 WARN c.n.s.JsonMetaSchema(newValidator):338 - Unknown keyword multiline - you should define your own Meta Schema. If the keyword is irrelevant for validation, just use a NonValidationKeyword 2022-05-23 20:48:52 WARN i.a.w.DefaultReplicationWorker(lambda$getReplicationRunnable$5):298 - Record schema validation failed. Errors: json schema validation failed when comparing the data to the json schema. Errors: $.tax_id: string found, but [null, number] is required Schema: { "type" : "object", "properties" : { "id" : { "type" : [ "null", "string" ] }, "age" : { "type" : [ "null", "number" ] }, "name" : { "type" : [ "null", "string" ] }, "owner" : { "type" : [ "null", "number" ] }, "tax_id" : { "type" : [ "null", "number" ] }, "balance" : { "type" : [ "null", "string" ] }, "partner" : { "type" : [ "null", "number" ] }, "rf_spec" : { "type" : [ "null", "object" ], "properties" : { "countries" : { "type" : [ "null", "array" ], "items" : { "type" : [ "null", "string" ] } }, "min_reach_limits" : { "type" : [ "null", "object" ], "additionalProperties" : true }, "max_days_to_finish" : { "type" : [ "null", "object" ], "additionalProperties" : true }, "max_campaign_duration" : { "type" : [ "null", "object" ], "additionalProperties" : true }, "min_campaign_duration" : { "type" : [ "null", "object" ], "additionalProperties" : true }, "global_io_max_campaign_duration" : { "type" : [ "null", "integer" ] } } }, "business" : { "type" : [ "null", "object" ], "properties" : { "id" : { "type" : [ "null", "string" ] }, "name" : { "type" : [ "null", "string" ] } } }, "currency" : { "type" : [ "null", "string" ] }, "fb_entity" : { "type" : [ "null", "number" ] }, "io_number" : { "type" : [ "null", "number" ] }, "spend_cap" : { "type" : [ "null", "string" ] }, "account_id" : { "type" : [ "null", "string" ] }, "user_tasks" : { "type" : [ "null", "array" ], "items" : { "type" : [ "null", "string" ] } }, "is_personal" : { "type" : [ "null", "number" ] }, "tax_id_type" : { "type" : [ "null", "string" ] }, "timezone_id" : { "type" : [ "null", "number" ] }, "amount_spent" : { "type" : [ "null", "string" ] }, "business_zip" : { "type" : [ "null", "string" ] }, "capabilities" : { "type" : [ "null", "array" ], "items" : { "type" : "string" } }, "created_time" : { "type" : "string", "format" : "date-time" }, "line_numbers" : { "type" : [ "null", "number" ] }, "media_agency" : { "type" : [ "null", "number" ] }, "tos_accepted" : { "type" : [ "null", "object" ], "properties" : { "web_custom_audience_tos" : { "type" : [ "null", "integer" ] } } }, "business_city" : { "type" : [ "null", "string" ] }, "business_name" : { "type" : [ "null", "string" ] }, "tax_id_status" : { "type" : [ "null", "number" ] }, "timezone_name" : { "type" : [ "null", "string" ] }, "account_status" : { "type" : [ "null", "integer" ] }, "business_state" : { "type" : [ "null", "string" ] }, "disable_reason" : { "type" : [ "null", "number" ] }, "end_advertiser" : { "type" : [ "null", "number" ] }, "funding_source" : { "type" : [ "null", "number" ] }, "business_street" : { "type" : [ "null", "string" ] }, "business_street2" : { "type" : [ "null", "string" ] }, "min_daily_budget" : { "type" : [ "null", "number" ] }, "is_prepay_account" : { "type" : [ "null", "boolean" ] }, "user_tos_accepted" : { "type" : [ "null", "object" ], "properties" : { "web_custom_audience_tos" : { "type" : [ "null", "integer" ] } } }, "is_tax_id_required" : { "type" : [ "null", "boolean" ] }, "end_advertiser_name" : { "type" : [ "null", "string" ] }, "business_country_code" : { "type" : [ "null", "string" ] }, "failed_delivery_checks" : { "type" : [ "null", "number" ] }, "funding_source_details" : { "type" : [ "null", "object" ], "properties" : { "id" : { "type" : [ "null", "string" ] }, "type" : { "type" : [ "null", "integer" ] }, "display_string" : { "type" : [ "null", "string" ] } } }, "is_direct_deals_enabled" : { "type" : [ "null", "boolean" ] }, "has_migrated_permissions" : { "type" : [ "null", "boolean" ] }, "is_notifications_enabled" : { "type" : [ "null", "boolean" ] }, "timezone_offset_hours_utc" : { "type" : [ "null", "number" ] }, "can_create_brand_lift_study" : { "type" : [ "null", "boolean" ] }, "offsite_pixels_tos_accepted" : { "type" : [ "null", "boolean" ] }, "has_advertiser_opted_in_odax" : { "type" : [ "null", "boolean" ] }, "min_campaign_group_spend_cap" : { "type" : [ "null", "number" ] }, "extended_credit_invoice_group" : { "type" : [ "null", "number" ] }, "is_attribution_spec_system_default" : { "type" : [ "null", "boolean" ] }, "is_in_3ds_authorization_enabled_market" : { "type" : [ "null", "boolean" ] } }, "additionalProperties" : true, "$schema" : "http://json-schema.org/draft-07/schema#" } 2022-05-23 20:48:52 source > Read 1 records from ad_account stream 2022-05-23 20:48:52 source > Finished syncing ad_account 2022-05-23 20:48:52 source > SourceFacebookMarketing runtimes: Syncing stream ad_account 0:00:00.707945 2022-05-23 20:48:52 source > Finished syncing SourceFacebookMarketing 2022-05-23 20:48:52 destination > 2022-05-23 20:48:52 INFO i.a.i.b.s.SshTunnel(getInstance):170 - Starting connection with method: NO_TUNNEL 2022-05-23 20:48:52 INFO i.a.w.DefaultReplicationWorker(lambda$getReplicationRunnable$5):316 - Source has no more messages, closing connection. 2022-05-23 20:48:52 INFO i.a.w.DefaultReplicationWorker(lambda$getReplicationRunnable$5):324 - Total records read: 1 (15 KB) 2022-05-23 20:48:52 INFO i.a.w.DefaultReplicationWorker(run):166 - One of source or destination thread complete. Waiting on the other. 2022-05-23 20:48:52 destination > 2022-05-23 20:48:52 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$toWriteConfig$0):97 - Write config: WriteConfig{streamName=ad_account, namespace=null, outputSchemaName=dbo, tmpTableName=_airbyte_tmp_rkb_ad_account, outputTableName=_airbyte_raw_ad_account, syncMode=append} 2022-05-23 20:48:52 destination > 2022-05-23 20:48:52 INFO i.a.i.d.b.BufferedStreamConsumer(startTracked):116 - class io.airbyte.integrations.destination.buffered_stream_consumer.BufferedStreamConsumer started. 2022-05-23 20:48:52 destination > 2022-05-23 20:48:52 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$onStartFunction$1):122 - Preparing tmp tables in destination started for 1 streams 2022-05-23 20:48:52 destination > 2022-05-23 20:48:52 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$onStartFunction$1):126 - Preparing tmp table in destination started for stream ad_account. schema: dbo, tmp table name: _airbyte_tmp_rkb_ad_account 2022-05-23 20:48:53 destination > 2022-05-23 20:48:53 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$onStartFunction$1):132 - Preparing tables in destination completed. 2022-05-23 20:48:53 destination > 2022-05-23 20:48:53 INFO i.a.i.b.FailureTrackingAirbyteMessageConsumer(close):65 - Airbyte message consumer: succeeded. 2022-05-23 20:48:53 destination > 2022-05-23 20:48:53 INFO i.a.i.d.b.BufferedStreamConsumer(close):170 - executing on success close procedure. 2022-05-23 20:48:53 destination > 2022-05-23 20:48:53 INFO i.a.i.d.r.InMemoryRecordBufferingStrategy(lambda$flushAll$1):84 - Flushing ad_account: 1 records (63 KB) 2022-05-23 20:48:53 destination > 2022-05-23 20:48:53 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$onCloseFunction$3):161 - Finalizing tables in destination started for 1 streams 2022-05-23 20:48:53 destination > 2022-05-23 20:48:53 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$onCloseFunction$3):166 - Finalizing stream ad_account. schema dbo, tmp table _airbyte_tmp_rkb_ad_account, final table _airbyte_raw_ad_account 2022-05-23 20:48:53 destination > 2022-05-23 20:48:53 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$onCloseFunction$3):179 - Executing finalization of tables. 2022-05-23 20:48:53 destination > 2022-05-23 20:48:53 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$onCloseFunction$3):181 - Finalizing tables in destination completed. 2022-05-23 20:48:53 destination > 2022-05-23 20:48:53 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$onCloseFunction$3):184 - Cleaning tmp tables in destination started for 1 streams 2022-05-23 20:48:53 destination > 2022-05-23 20:48:53 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$onCloseFunction$3):188 - Cleaning tmp table in destination started for stream ad_account. schema dbo, tmp table name: _airbyte_tmp_rkb_ad_account 2022-05-23 20:48:53 destination > 2022-05-23 20:48:53 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$onCloseFunction$3):193 - Cleaning tmp tables in destination completed. 2022-05-23 20:48:53 destination > 2022-05-23 20:48:53 INFO i.a.i.b.IntegrationRunner(runInternal):169 - Completed integration: io.airbyte.integrations.base.ssh.SshWrappedDestination 2022-05-23 20:48:53 destination > 2022-05-23 20:48:53 INFO i.a.i.d.m.MSSQLDestination(main):104 - completed destination: class io.airbyte.integrations.destination.mssql.MSSQLDestination 2022-05-23 20:48:53 INFO i.a.w.DefaultReplicationWorker(run):168 - Source and destination threads complete. 2022-05-23 20:48:53 INFO i.a.w.DefaultReplicationWorker(run):231 - sync summary: io.airbyte.config.ReplicationAttemptSummary@4389599[status=completed,recordsSynced=1,bytesSynced=16146,startTime=1653338930507,endTime=1653338933703,totalStats=io.airbyte.config.SyncStats@6cc3ca2a[recordsEmitted=1,bytesEmitted=16146,stateMessagesEmitted=0,recordsCommitted=1],streamStats=[io.airbyte.config.StreamSyncStats@381888d7[streamName=ad_account,stats=io.airbyte.config.SyncStats@16b06f8a[recordsEmitted=1,bytesEmitted=16146,stateMessagesEmitted=,recordsCommitted=1]]]] 2022-05-23 20:48:53 INFO i.a.w.DefaultReplicationWorker(run):253 - Source did not output any state messages 2022-05-23 20:48:53 WARN i.a.w.DefaultReplicationWorker(run):261 - State capture: No new state, falling back on input state: io.airbyte.config.State@5664a498[state={}] 2022-05-23 20:48:53 INFO i.a.w.t.TemporalAttemptExecution(get):134 - Stopping cancellation check scheduling... 2022-05-23 20:48:53 INFO i.a.w.t.s.ReplicationActivityImpl(lambda$replicate$3):157 - sync summary: io.airbyte.config.StandardSyncOutput@536929b5[standardSyncSummary=io.airbyte.config.StandardSyncSummary@166bbdbc[status=completed,recordsSynced=1,bytesSynced=16146,startTime=1653338930507,endTime=1653338933703,totalStats=io.airbyte.config.SyncStats@6cc3ca2a[recordsEmitted=1,bytesEmitted=16146,stateMessagesEmitted=0,recordsCommitted=1],streamStats=[io.airbyte.config.StreamSyncStats@381888d7[streamName=ad_account,stats=io.airbyte.config.SyncStats@16b06f8a[recordsEmitted=1,bytesEmitted=16146,stateMessagesEmitted=,recordsCommitted=1]]]],normalizationSummary=,state=io.airbyte.config.State@5664a498[state={}],outputCatalog=io.airbyte.protocol.models.ConfiguredAirbyteCatalog@453f42de[streams=[io.airbyte.protocol.models.ConfiguredAirbyteStream@27b72f71[stream=io.airbyte.protocol.models.AirbyteStream@3d098eb3[name=ad_account,jsonSchema={"type":"object","properties":{"id":{"type":["null","string"]},"age":{"type":["null","number"]},"name":{"type":["null","string"]},"owner":{"type":["null","number"]},"tax_id":{"type":["null","number"]},"balance":{"type":["null","string"]},"partner":{"type":["null","number"]},"rf_spec":{"type":["null","object"],"properties":{"countries":{"type":["null","array"],"items":{"type":["null","string"]}},"min_reach_limits":{"type":["null","object"],"additionalProperties":true},"max_days_to_finish":{"type":["null","object"],"additionalProperties":true},"max_campaign_duration":{"type":["null","object"],"additionalProperties":true},"min_campaign_duration":{"type":["null","object"],"additionalProperties":true},"global_io_max_campaign_duration":{"type":["null","integer"]}}},"business":{"type":["null","object"],"properties":{"id":{"type":["null","string"]},"name":{"type":["null","string"]}}},"currency":{"type":["null","string"]},"fb_entity":{"type":["null","number"]},"io_number":{"type":["null","number"]},"spend_cap":{"type":["null","string"]},"account_id":{"type":["null","string"]},"user_tasks":{"type":["null","array"],"items":{"type":["null","string"]}},"is_personal":{"type":["null","number"]},"tax_id_type":{"type":["null","string"]},"timezone_id":{"type":["null","number"]},"amount_spent":{"type":["null","string"]},"business_zip":{"type":["null","string"]},"capabilities":{"type":["null","array"],"items":{"type":"string"}},"created_time":{"type":"string","format":"date-time"},"line_numbers":{"type":["null","number"]},"media_agency":{"type":["null","number"]},"tos_accepted":{"type":["null","object"],"properties":{"web_custom_audience_tos":{"type":["null","integer"]}}},"business_city":{"type":["null","string"]},"business_name":{"type":["null","string"]},"tax_id_status":{"type":["null","number"]},"timezone_name":{"type":["null","string"]},"account_status":{"type":["null","integer"]},"business_state":{"type":["null","string"]},"disable_reason":{"type":["null","number"]},"end_advertiser":{"type":["null","number"]},"funding_source":{"type":["null","number"]},"business_street":{"type":["null","string"]},"business_street2":{"type":["null","string"]},"min_daily_budget":{"type":["null","number"]},"is_prepay_account":{"type":["null","boolean"]},"user_tos_accepted":{"type":["null","object"],"properties":{"web_custom_audience_tos":{"type":["null","integer"]}}},"is_tax_id_required":{"type":["null","boolean"]},"end_advertiser_name":{"type":["null","string"]},"business_country_code":{"type":["null","string"]},"failed_delivery_checks":{"type":["null","number"]},"funding_source_details":{"type":["null","object"],"properties":{"id":{"type":["null","string"]},"type":{"type":["null","integer"]},"display_string":{"type":["null","string"]}}},"is_direct_deals_enabled":{"type":["null","boolean"]},"has_migrated_permissions":{"type":["null","boolean"]},"is_notifications_enabled":{"type":["null","boolean"]},"timezone_offset_hours_utc":{"type":["null","number"]},"can_create_brand_lift_study":{"type":["null","boolean"]},"offsite_pixels_tos_accepted":{"type":["null","boolean"]},"has_advertiser_opted_in_odax":{"type":["null","boolean"]},"min_campaign_group_spend_cap":{"type":["null","number"]},"extended_credit_invoice_group":{"type":["null","number"]},"is_attribution_spec_system_default":{"type":["null","boolean"]},"is_in_3ds_authorization_enabled_market":{"type":["null","boolean"]}},"additionalProperties":true},supportedSyncModes=[full_refresh],sourceDefinedCursor=,defaultCursorField=[],sourceDefinedPrimaryKey=[[id]],namespace=,additionalProperties={}],syncMode=full_refresh,cursorField=[],destinationSyncMode=append,primaryKey=[[id]],additionalProperties={}]],additionalProperties={}],failures=[]] 2022-05-23 20:48:53 INFO i.a.w.t.TemporalUtils(withBackgroundHeartbeat):236 - Stopping temporal heartbeating... 2022-05-23 20:48:53 INFO i.a.c.p.ConfigRepository(updateConnectionState):774 - Updating connection 065c387f-f9ba-4530-a03a-baecc8d9e287 state: io.airbyte.config.State@5780a5bb[state={}] 2022-05-23 20:48:53 INFO i.a.w.t.TemporalAttemptExecution(get):108 - Docker volume job log path: /tmp/workspace/21/0/logs.log 2022-05-23 20:48:53 INFO i.a.w.t.TemporalAttemptExecution(get):113 - Executing worker wrapper. Airbyte version: 0.38.2-alpha 2022-05-23 20:48:53 INFO i.a.w.DefaultNormalizationWorker(run):47 - Running normalization. 2022-05-23 20:48:53 INFO i.a.w.n.DefaultNormalizationRunner(runProcess):122 - Running with normalization version: airbyte/normalization-mssql:0.1.78 2022-05-23 20:48:53 INFO i.a.c.i.LineGobbler(voidCall):82 - Checking if airbyte/normalization-mssql:0.1.78 exists... 2022-05-23 20:48:53 INFO i.a.c.i.LineGobbler(voidCall):82 - airbyte/normalization-mssql:0.1.78 was found locally. 2022-05-23 20:48:53 INFO i.a.w.p.DockerProcessFactory(create):108 - Creating docker job ID: 21 2022-05-23 20:48:53 INFO i.a.w.p.DockerProcessFactory(create):163 - Preparing command: docker run --rm --init -i -w /data/21/0/normalize --log-driver none --name normalization-mssql-normalize-21-0-fayjl --network host -v airbyte_workspace:/data -v /tmp/airbyte_local:/local -e WORKER_ENVIRONMENT=DOCKER -e AIRBYTE_ROLE= -e AIRBYTE_VERSION=0.38.2-alpha airbyte/normalization-mssql:0.1.78 run --integration-type mssql --config destination_config.json --catalog destination_catalog.json 2022-05-23 20:48:54 normalization > Running: transform-config --config destination_config.json --integration-type mssql --out /data/21/0/normalize 2022-05-23 20:48:54 normalization > Namespace(config='destination_config.json', integration_type=, out='/data/21/0/normalize') 2022-05-23 20:48:54 normalization > transform_mssql 2022-05-23 20:48:54 normalization > Running: transform-catalog --integration-type mssql --profile-config-dir /data/21/0/normalize --catalog destination_catalog.json --out /data/21/0/normalize/models/generated/ --json-column _airbyte_data 2022-05-23 20:48:54 normalization > Processing destination_catalog.json... 2022-05-23 20:48:54 normalization > Generating airbyte_ctes/dbo/ad_account_ab1.sql from ad_account 2022-05-23 20:48:54 normalization > Generating airbyte_ctes/dbo/ad_account_ab2.sql from ad_account 2022-05-23 20:48:54 normalization > Generating airbyte_ctes/dbo/ad_account_ab3.sql from ad_account 2022-05-23 20:48:54 normalization > Generating airbyte_incremental/dbo/ad_account.sql from ad_account 2022-05-23 20:48:54 normalization > Generating airbyte_ctes/dbo/ad_account_rf_spec_ab1.sql from ad_account/rf_spec 2022-05-23 20:48:54 normalization > Generating airbyte_ctes/dbo/ad_account_rf_spec_ab2.sql from ad_account/rf_spec 2022-05-23 20:48:54 normalization > Generating airbyte_ctes/dbo/ad_account_rf_spec_ab3.sql from ad_account/rf_spec 2022-05-23 20:48:54 normalization > Generating airbyte_incremental/dbo/ad_account_rf_spec.sql from ad_account/rf_spec 2022-05-23 20:48:54 normalization > Generating airbyte_ctes/dbo/ad_account_business_ab1.sql from ad_account/business 2022-05-23 20:48:54 normalization > Generating airbyte_ctes/dbo/ad_account_business_ab2.sql from ad_account/business 2022-05-23 20:48:54 normalization > Generating airbyte_ctes/dbo/ad_account_business_ab3.sql from ad_account/business 2022-05-23 20:48:54 normalization > Generating airbyte_incremental/dbo/ad_account_business.sql from ad_account/business 2022-05-23 20:48:54 normalization > Ignoring stream 'user_tasks' from ad_account/user_tasks because properties list is empty 2022-05-23 20:48:54 normalization > Ignoring stream 'capabilities' from ad_account/capabilities because properties list is empty 2022-05-23 20:48:54 normalization > Generating airbyte_ctes/dbo/ad_account_tos_accepted_ab1.sql from ad_account/tos_accepted 2022-05-23 20:48:54 normalization > Generating airbyte_ctes/dbo/ad_account_tos_accepted_ab2.sql from ad_account/tos_accepted 2022-05-23 20:48:54 normalization > Generating airbyte_ctes/dbo/ad_account_tos_accepted_ab3.sql from ad_account/tos_accepted 2022-05-23 20:48:54 normalization > Generating airbyte_incremental/dbo/ad_account_tos_accepted.sql from ad_account/tos_accepted 2022-05-23 20:48:54 normalization > Generating airbyte_ctes/dbo/ad_account_user_tos_accepted_ab1.sql from ad_account/user_tos_accepted 2022-05-23 20:48:54 normalization > Generating airbyte_ctes/dbo/ad_account_user_tos_accepted_ab2.sql from ad_account/user_tos_accepted 2022-05-23 20:48:54 normalization > Generating airbyte_ctes/dbo/ad_account_user_tos_accepted_ab3.sql from ad_account/user_tos_accepted 2022-05-23 20:48:54 normalization > Generating airbyte_incremental/dbo/ad_account_user_tos_accepted.sql from ad_account/user_tos_accepted 2022-05-23 20:48:54 normalization > Generating airbyte_ctes/dbo/ad_account_funding_source_details_ab1.sql from ad_account/funding_source_details 2022-05-23 20:48:54 normalization > Generating airbyte_ctes/dbo/ad_account_funding_source_details_ab2.sql from ad_account/funding_source_details 2022-05-23 20:48:54 normalization > Generating airbyte_ctes/dbo/ad_account_funding_source_details_ab3.sql from ad_account/funding_source_details 2022-05-23 20:48:54 normalization > Generating airbyte_incremental/dbo/ad_account_funding_source_details.sql from ad_account/funding_source_details 2022-05-23 20:48:54 normalization > Ignoring stream 'countries' from ad_account/rf_spec/countries because properties list is empty 2022-05-23 20:48:54 normalization > detected no config file for ssh, assuming ssh is off. 2022-05-23 20:48:57 normalization > [--event-buffer-size EVENT_BUFFER_SIZE] 2022-05-23 20:48:57 normalization > --event-buffer-size EVENT_BUFFER_SIZE 2022-05-23 20:48:57 normalization > 2022-05-23 20:48:57 normalization > DBT >=1.0.0 detected; using 10K event buffer size 2022-05-23 20:48:57 normalization > 2022-05-23 20:49:01 normalization > 20:49:01 Running with dbt=1.0.0 2022-05-23 20:49:01 normalization > 20:49:01 Partial parse save file not found. Starting full parse. 2022-05-23 20:49:03 normalization > 20:49:03 [WARNING]: Configuration paths exist in your dbt_project.yml file which do not apply to any resources. 2022-05-23 20:49:03 normalization > There are 2 unused configuration paths: 2022-05-23 20:49:03 normalization > - models.airbyte_utils.generated.airbyte_tables 2022-05-23 20:49:03 normalization > - models.airbyte_utils.generated.airbyte_views 2022-05-23 20:49:03 normalization > 2022-05-23 20:49:03 normalization > 20:49:03 Found 24 models, 0 tests, 0 snapshots, 0 analyses, 543 macros, 0 operations, 0 seed files, 1 source, 0 exposures, 0 metrics 2022-05-23 20:49:03 normalization > 20:49:03 2022-05-23 20:49:04 normalization > 20:49:04 Concurrency: 8 threads (target='prod') 2022-05-23 20:49:04 normalization > 20:49:04 2022-05-23 20:49:04 normalization > 20:49:04 1 of 6 START incremental model dbo.ad_account........................................................................... [RUN] 2022-05-23 20:49:05 normalization > 20:49:05 Unhandled error while executing model.airbyte_utils.ad_account 2022-05-23 20:49:05 normalization > ('42000', '[42000] [Microsoft][ODBC Driver 17 for SQL Server][SQL Server]Error converting data type nvarchar to float. (8114) (SQLMoreResults)') 2022-05-23 20:49:05 normalization > 20:49:05 1 of 6 ERROR creating incremental model dbo.ad_account.................................................................. [ERROR in 0.29s] 2022-05-23 20:49:05 normalization > 20:49:05 2 of 6 SKIP relation dbo.ad_account_business............................................................................ [SKIP] 2022-05-23 20:49:05 normalization > 20:49:05 3 of 6 SKIP relation dbo.ad_account_funding_source_details.............................................................. [SKIP] 2022-05-23 20:49:05 normalization > 20:49:05 4 of 6 SKIP relation dbo.ad_account_rf_spec............................................................................. [SKIP] 2022-05-23 20:49:05 normalization > 20:49:05 5 of 6 SKIP relation dbo.ad_account_tos_accepted........................................................................ [SKIP] 2022-05-23 20:49:05 normalization > 20:49:05 6 of 6 SKIP relation dbo.ad_account_user_tos_accepted................................................................... [SKIP] 2022-05-23 20:49:05 normalization > 20:49:05 2022-05-23 20:49:05 normalization > 20:49:05 Finished running 6 incremental models in 1.79s. 2022-05-23 20:49:05 normalization > 20:49:05 2022-05-23 20:49:05 normalization > 20:49:05 Completed with 1 error and 0 warnings: 2022-05-23 20:49:05 normalization > 20:49:05 2022-05-23 20:49:05 normalization > 20:49:05 ('42000', '[42000] [Microsoft][ODBC Driver 17 for SQL Server][SQL Server]Error converting data type nvarchar to float. (8114) (SQLMoreResults)') 2022-05-23 20:49:05 normalization > 20:49:05 2022-05-23 20:49:05 normalization > 20:49:05 Done. PASS=0 WARN=0 ERROR=1 SKIP=5 TOTAL=6 2022-05-23 20:49:05 normalization > 2022-05-23 20:49:05 normalization > Diagnosing dbt debug to check if destination is available for dbt and well configured (1): 2022-05-23 20:49:05 normalization > 2022-05-23 20:49:08 normalization > 20:49:08 Running with dbt=1.0.0 2022-05-23 20:49:08 normalization > dbt version: 1.0.0 2022-05-23 20:49:08 normalization > python version: 3.9.9 2022-05-23 20:49:08 normalization > python path: /usr/local/bin/python 2022-05-23 20:49:08 normalization > os info: Linux-5.10.16.3-microsoft-standard-WSL2-x86_64-with-glibc2.31 2022-05-23 20:49:08 normalization > Using profiles.yml file at /data/21/0/normalize/profiles.yml 2022-05-23 20:49:08 normalization > Using dbt_project.yml file at /data/21/0/normalize/dbt_project.yml 2022-05-23 20:49:08 normalization > 2022-05-23 20:49:08 normalization > Configuration: 2022-05-23 20:49:08 normalization > profiles.yml file [OK found and valid] 2022-05-23 20:49:08 normalization > dbt_project.yml file [OK found and valid] 2022-05-23 20:49:08 normalization > 2022-05-23 20:49:08 normalization > Required dependencies: 2022-05-23 20:49:08 normalization > - git [OK found] 2022-05-23 20:49:08 normalization > 2022-05-23 20:49:08 normalization > Connection: 2022-05-23 20:49:08 normalization > server: host.docker.internal 2022-05-23 20:49:08 normalization > database: dev 2022-05-23 20:49:08 normalization > schema: dbo 2022-05-23 20:49:08 normalization > port: 1433 2022-05-23 20:49:08 normalization > UID: sa 2022-05-23 20:49:08 normalization > client_id: None 2022-05-23 20:49:08 normalization > authentication: sql 2022-05-23 20:49:08 normalization > encrypt: False 2022-05-23 20:49:08 normalization > trust_cert: False 2022-05-23 20:49:08 normalization > Connection test: [OK connection ok] 2022-05-23 20:49:08 normalization > 2022-05-23 20:49:08 normalization > All checks passed! 2022-05-23 20:49:08 normalization > 2022-05-23 20:49:08 normalization > Forward dbt output logs to diagnose/debug errors (0): 2022-05-23 20:49:08 normalization > 2022-05-23 20:49:08 normalization > 2022-05-23 20:49:08 normalization > 2022-05-23 20:49:08 normalization > ============================== 2022-05-23 20:49:01.078780 | d5318e9c-eec0-476b-bb1c-0c26b847334b ============================== 2022-05-23 20:49:08 normalization > 20:49:01.078780 [info ] [MainThread]: Running with dbt=1.0.0 2022-05-23 20:49:08 normalization > 20:49:01.079529 [debug] [MainThread]: running dbt with arguments Namespace(record_timing_info=None, debug=None, log_format=None, write_json=None, use_colors=None, printer_width=None, warn_error=None, version_check=None, partial_parse=None, single_threaded=False, use_experimental_parser=None, static_parser=None, profiles_dir='/data/21/0/normalize', send_anonymous_usage_stats=None, fail_fast=None, event_buffer_size='10000', project_dir='/data/21/0/normalize', profile=None, target=None, vars='{}', log_cache_events=False, threads=None, select=None, exclude=None, selector_name=None, state=None, defer=None, full_refresh=False, cls=, which='run', rpc_method='run') 2022-05-23 20:49:08 normalization > 20:49:01.079841 [debug] [MainThread]: Tracking: do not track 2022-05-23 20:49:08 normalization > 20:49:01.108727 [info ] [MainThread]: Partial parse save file not found. Starting full parse. 2022-05-23 20:49:08 normalization > 20:49:01.140950 [debug] [MainThread]: Parsing macros/configuration.sql 2022-05-23 20:49:08 normalization > 20:49:01.144876 [debug] [MainThread]: Parsing macros/get_custom_schema.sql 2022-05-23 20:49:08 normalization > 20:49:01.145647 [debug] [MainThread]: Parsing macros/incremental.sql 2022-05-23 20:49:08 normalization > 20:49:01.154298 [debug] [MainThread]: Parsing macros/star_intersect.sql 2022-05-23 20:49:08 normalization > 20:49:01.163290 [debug] [MainThread]: Parsing macros/should_full_refresh.sql 2022-05-23 20:49:08 normalization > 20:49:01.170501 [debug] [MainThread]: Parsing macros/cross_db_utils/quote.sql 2022-05-23 20:49:08 normalization > 20:49:01.172674 [debug] [MainThread]: Parsing macros/cross_db_utils/columns.sql 2022-05-23 20:49:08 normalization > 20:49:01.176730 [debug] [MainThread]: Parsing macros/cross_db_utils/concat.sql 2022-05-23 20:49:08 normalization > 20:49:01.179567 [debug] [MainThread]: Parsing macros/cross_db_utils/json_operations.sql 2022-05-23 20:49:08 normalization > 20:49:01.232408 [debug] [MainThread]: Parsing macros/cross_db_utils/datatypes.sql 2022-05-23 20:49:08 normalization > 20:49:01.247667 [debug] [MainThread]: Parsing macros/cross_db_utils/surrogate_key.sql 2022-05-23 20:49:08 normalization > 20:49:01.250459 [debug] [MainThread]: Parsing macros/cross_db_utils/current_timestamp.sql 2022-05-23 20:49:08 normalization > 20:49:01.251338 [debug] [MainThread]: Parsing macros/cross_db_utils/array.sql 2022-05-23 20:49:08 normalization > 20:49:01.307383 [debug] [MainThread]: Parsing macros/cross_db_utils/type_conversions.sql 2022-05-23 20:49:08 normalization > 20:49:01.319474 [debug] [MainThread]: Parsing macros/cross_db_utils/except.sql 2022-05-23 20:49:08 normalization > 20:49:01.320574 [debug] [MainThread]: Parsing macros/cross_db_utils/hash.sql 2022-05-23 20:49:08 normalization > 20:49:01.321369 [debug] [MainThread]: Parsing macros/schema_tests/equality.sql 2022-05-23 20:49:08 normalization > 20:49:01.331261 [debug] [MainThread]: Parsing macros/schema_tests/equal_rowcount.sql 2022-05-23 20:49:08 normalization > 20:49:01.332862 [debug] [MainThread]: Parsing macros/adapters.sql 2022-05-23 20:49:08 normalization > 20:49:01.333081 [debug] [MainThread]: Parsing macros/adapters/columns.sql 2022-05-23 20:49:08 normalization > 20:49:01.340394 [debug] [MainThread]: Parsing macros/adapters/relation.sql 2022-05-23 20:49:08 normalization > 20:49:01.349034 [debug] [MainThread]: Parsing macros/adapters/persist_docs.sql 2022-05-23 20:49:08 normalization > 20:49:01.349299 [debug] [MainThread]: Parsing macros/adapters/freshness.sql 2022-05-23 20:49:08 normalization > 20:49:01.349769 [debug] [MainThread]: Parsing macros/adapters/indexes.sql 2022-05-23 20:49:08 normalization > 20:49:01.363251 [debug] [MainThread]: Parsing macros/adapters/schema.sql 2022-05-23 20:49:08 normalization > 20:49:01.368054 [debug] [MainThread]: Parsing macros/adapters/metadata.sql 2022-05-23 20:49:08 normalization > 20:49:01.375178 [debug] [MainThread]: Parsing macros/materializations/tests/helpers.sql 2022-05-23 20:49:08 normalization > 20:49:01.377011 [debug] [MainThread]: Parsing macros/materializations/tests/test.sql 2022-05-23 20:49:08 normalization > 20:49:01.385105 [debug] [MainThread]: Parsing macros/materializations/seeds/helpers.sql 2022-05-23 20:49:08 normalization > 20:49:01.396856 [debug] [MainThread]: Parsing macros/materializations/snapshots/snapshot_merge.sql 2022-05-23 20:49:08 normalization > 20:49:01.397756 [debug] [MainThread]: Parsing macros/materializations/snapshots/snapshot.sql 2022-05-23 20:49:08 normalization > 20:49:01.399718 [debug] [MainThread]: Parsing macros/materializations/snapshots/strategies.sql 2022-05-23 20:49:08 normalization > 20:49:01.401651 [debug] [MainThread]: Parsing macros/materializations/models/incremental/merge.sql 2022-05-23 20:49:08 normalization > 20:49:01.404401 [debug] [MainThread]: Parsing macros/materializations/models/view/create_view_as.sql 2022-05-23 20:49:08 normalization > 20:49:01.406387 [debug] [MainThread]: Parsing macros/materializations/models/table/create_table_as.sql 2022-05-23 20:49:08 normalization > 20:49:01.410205 [debug] [MainThread]: Parsing macros/adapters/columns.sql 2022-05-23 20:49:08 normalization > 20:49:01.425669 [debug] [MainThread]: Parsing macros/adapters/relation.sql 2022-05-23 20:49:08 normalization > 20:49:01.442502 [debug] [MainThread]: Parsing macros/adapters/persist_docs.sql 2022-05-23 20:49:08 normalization > 20:49:01.450138 [debug] [MainThread]: Parsing macros/adapters/freshness.sql 2022-05-23 20:49:08 normalization > 20:49:01.454507 [debug] [MainThread]: Parsing macros/adapters/indexes.sql 2022-05-23 20:49:08 normalization > 20:49:01.458592 [debug] [MainThread]: Parsing macros/adapters/schema.sql 2022-05-23 20:49:08 normalization > 20:49:01.461807 [debug] [MainThread]: Parsing macros/adapters/metadata.sql 2022-05-23 20:49:08 normalization > 20:49:01.473266 [debug] [MainThread]: Parsing macros/get_custom_name/get_custom_schema.sql 2022-05-23 20:49:08 normalization > 20:49:01.477791 [debug] [MainThread]: Parsing macros/get_custom_name/get_custom_database.sql 2022-05-23 20:49:08 normalization > 20:49:01.480326 [debug] [MainThread]: Parsing macros/get_custom_name/get_custom_alias.sql 2022-05-23 20:49:08 normalization > 20:49:01.482514 [debug] [MainThread]: Parsing macros/etc/datetime.sql 2022-05-23 20:49:08 normalization > 20:49:01.496223 [debug] [MainThread]: Parsing macros/etc/statement.sql 2022-05-23 20:49:08 normalization > 20:49:01.503044 [debug] [MainThread]: Parsing macros/generic_test_sql/unique.sql 2022-05-23 20:49:08 normalization > 20:49:01.504048 [debug] [MainThread]: Parsing macros/generic_test_sql/not_null.sql 2022-05-23 20:49:08 normalization > 20:49:01.504784 [debug] [MainThread]: Parsing macros/generic_test_sql/relationships.sql 2022-05-23 20:49:08 normalization > 20:49:01.506091 [debug] [MainThread]: Parsing macros/generic_test_sql/accepted_values.sql 2022-05-23 20:49:08 normalization > 20:49:01.508247 [debug] [MainThread]: Parsing macros/materializations/configs.sql 2022-05-23 20:49:08 normalization > 20:49:01.512029 [debug] [MainThread]: Parsing macros/materializations/hooks.sql 2022-05-23 20:49:08 normalization > 20:49:01.517980 [debug] [MainThread]: Parsing macros/materializations/tests/where_subquery.sql 2022-05-23 20:49:08 normalization > 20:49:01.520660 [debug] [MainThread]: Parsing macros/materializations/tests/helpers.sql 2022-05-23 20:49:08 normalization > 20:49:01.523492 [debug] [MainThread]: Parsing macros/materializations/tests/test.sql 2022-05-23 20:49:08 normalization > 20:49:01.530512 [debug] [MainThread]: Parsing macros/materializations/seeds/helpers.sql 2022-05-23 20:49:08 normalization > 20:49:01.557382 [debug] [MainThread]: Parsing macros/materializations/seeds/seed.sql 2022-05-23 20:49:08 normalization > 20:49:01.566924 [debug] [MainThread]: Parsing macros/materializations/snapshots/snapshot_merge.sql 2022-05-23 20:49:08 normalization > 20:49:01.569412 [debug] [MainThread]: Parsing macros/materializations/snapshots/snapshot.sql 2022-05-23 20:49:08 normalization > 20:49:01.587960 [debug] [MainThread]: Parsing macros/materializations/snapshots/strategies.sql 2022-05-23 20:49:08 normalization > 20:49:01.615551 [debug] [MainThread]: Parsing macros/materializations/snapshots/helpers.sql 2022-05-23 20:49:08 normalization > 20:49:01.635104 [debug] [MainThread]: Parsing macros/materializations/models/incremental/on_schema_change.sql 2022-05-23 20:49:08 normalization > 20:49:01.662079 [debug] [MainThread]: Parsing macros/materializations/models/incremental/merge.sql 2022-05-23 20:49:08 normalization > 20:49:01.681714 [debug] [MainThread]: Parsing macros/materializations/models/incremental/incremental.sql 2022-05-23 20:49:08 normalization > 20:49:01.697834 [debug] [MainThread]: Parsing macros/materializations/models/incremental/is_incremental.sql 2022-05-23 20:49:08 normalization > 20:49:01.700540 [debug] [MainThread]: Parsing macros/materializations/models/incremental/column_helpers.sql 2022-05-23 20:49:08 normalization > 20:49:01.708840 [debug] [MainThread]: Parsing macros/materializations/models/view/create_or_replace_view.sql 2022-05-23 20:49:08 normalization > 20:49:01.713017 [debug] [MainThread]: Parsing macros/materializations/models/view/helpers.sql 2022-05-23 20:49:08 normalization > 20:49:01.714877 [debug] [MainThread]: Parsing macros/materializations/models/view/view.sql 2022-05-23 20:49:08 normalization > 20:49:01.726021 [debug] [MainThread]: Parsing macros/materializations/models/view/create_view_as.sql 2022-05-23 20:49:08 normalization > 20:49:01.729412 [debug] [MainThread]: Parsing macros/materializations/models/table/create_table_as.sql 2022-05-23 20:49:08 normalization > 20:49:01.733773 [debug] [MainThread]: Parsing macros/materializations/models/table/table.sql 2022-05-23 20:49:08 normalization > 20:49:01.745212 [debug] [MainThread]: Parsing tests/generic/builtin.sql 2022-05-23 20:49:08 normalization > 20:49:01.749701 [debug] [MainThread]: Parsing macros/cross_db_utils/split_part.sql 2022-05-23 20:49:08 normalization > 20:49:01.752472 [debug] [MainThread]: Parsing macros/cross_db_utils/literal.sql 2022-05-23 20:49:08 normalization > 20:49:01.753771 [debug] [MainThread]: Parsing macros/cross_db_utils/datediff.sql 2022-05-23 20:49:08 normalization > 20:49:01.769970 [debug] [MainThread]: Parsing macros/cross_db_utils/_is_ephemeral.sql 2022-05-23 20:49:08 normalization > 20:49:01.772866 [debug] [MainThread]: Parsing macros/cross_db_utils/date_trunc.sql 2022-05-23 20:49:08 normalization > 20:49:01.775040 [debug] [MainThread]: Parsing macros/cross_db_utils/any_value.sql 2022-05-23 20:49:08 normalization > 20:49:01.776834 [debug] [MainThread]: Parsing macros/cross_db_utils/bool_or.sql 2022-05-23 20:49:08 normalization > 20:49:01.779183 [debug] [MainThread]: Parsing macros/cross_db_utils/dateadd.sql 2022-05-23 20:49:08 normalization > 20:49:01.783447 [debug] [MainThread]: Parsing macros/cross_db_utils/safe_cast.sql 2022-05-23 20:49:08 normalization > 20:49:01.786281 [debug] [MainThread]: Parsing macros/cross_db_utils/last_day.sql 2022-05-23 20:49:08 normalization > 20:49:01.791577 [debug] [MainThread]: Parsing macros/cross_db_utils/length.sql 2022-05-23 20:49:08 normalization > 20:49:01.793494 [debug] [MainThread]: Parsing macros/cross_db_utils/identifier.sql 2022-05-23 20:49:08 normalization > 20:49:01.795918 [debug] [MainThread]: Parsing macros/cross_db_utils/concat.sql 2022-05-23 20:49:08 normalization > 20:49:01.797341 [debug] [MainThread]: Parsing macros/cross_db_utils/datatypes.sql 2022-05-23 20:49:08 normalization > 20:49:01.806320 [debug] [MainThread]: Parsing macros/cross_db_utils/current_timestamp.sql 2022-05-23 20:49:08 normalization > 20:49:01.811696 [debug] [MainThread]: Parsing macros/cross_db_utils/right.sql 2022-05-23 20:49:08 normalization > 20:49:01.815093 [debug] [MainThread]: Parsing macros/cross_db_utils/escape_single_quotes.sql 2022-05-23 20:49:08 normalization > 20:49:01.817777 [debug] [MainThread]: Parsing macros/cross_db_utils/_is_relation.sql 2022-05-23 20:49:08 normalization > 20:49:01.819409 [debug] [MainThread]: Parsing macros/cross_db_utils/position.sql 2022-05-23 20:49:08 normalization > 20:49:01.821657 [debug] [MainThread]: Parsing macros/cross_db_utils/replace.sql 2022-05-23 20:49:08 normalization > 20:49:01.823458 [debug] [MainThread]: Parsing macros/cross_db_utils/cast_bool_to_text.sql 2022-05-23 20:49:08 normalization > 20:49:01.825614 [debug] [MainThread]: Parsing macros/cross_db_utils/intersect.sql 2022-05-23 20:49:08 normalization > 20:49:01.827242 [debug] [MainThread]: Parsing macros/cross_db_utils/width_bucket.sql 2022-05-23 20:49:08 normalization > 20:49:01.835586 [debug] [MainThread]: Parsing macros/cross_db_utils/except.sql 2022-05-23 20:49:08 normalization > 20:49:01.837068 [debug] [MainThread]: Parsing macros/cross_db_utils/hash.sql 2022-05-23 20:49:08 normalization > 20:49:01.839062 [debug] [MainThread]: Parsing macros/web/get_url_host.sql 2022-05-23 20:49:08 normalization > 20:49:01.841985 [debug] [MainThread]: Parsing macros/web/get_url_path.sql 2022-05-23 20:49:08 normalization > 20:49:01.845846 [debug] [MainThread]: Parsing macros/web/get_url_parameter.sql 2022-05-23 20:49:08 normalization > 20:49:01.848158 [debug] [MainThread]: Parsing macros/sql/star.sql 2022-05-23 20:49:08 normalization > 20:49:01.854819 [debug] [MainThread]: Parsing macros/sql/safe_add.sql 2022-05-23 20:49:08 normalization > 20:49:01.857227 [debug] [MainThread]: Parsing macros/sql/pivot.sql 2022-05-23 20:49:08 normalization > 20:49:01.863633 [debug] [MainThread]: Parsing macros/sql/nullcheck_table.sql 2022-05-23 20:49:08 normalization > 20:49:01.865993 [debug] [MainThread]: Parsing macros/sql/unpivot.sql 2022-05-23 20:49:08 normalization > 20:49:01.878778 [debug] [MainThread]: Parsing macros/sql/union.sql 2022-05-23 20:49:08 normalization > 20:49:01.895262 [debug] [MainThread]: Parsing macros/sql/nullcheck.sql 2022-05-23 20:49:08 normalization > 20:49:01.897655 [debug] [MainThread]: Parsing macros/sql/haversine_distance.sql 2022-05-23 20:49:08 normalization > 20:49:01.906582 [debug] [MainThread]: Parsing macros/sql/generate_series.sql 2022-05-23 20:49:08 normalization > 20:49:01.913102 [debug] [MainThread]: Parsing macros/sql/get_relations_by_pattern.sql 2022-05-23 20:49:08 normalization > 20:49:01.918501 [debug] [MainThread]: Parsing macros/sql/surrogate_key.sql 2022-05-23 20:49:08 normalization > 20:49:01.923917 [debug] [MainThread]: Parsing macros/sql/date_spine.sql 2022-05-23 20:49:08 normalization > 20:49:01.931217 [debug] [MainThread]: Parsing macros/sql/get_tables_by_pattern_sql.sql 2022-05-23 20:49:08 normalization > 20:49:01.941292 [debug] [MainThread]: Parsing macros/sql/get_column_values.sql 2022-05-23 20:49:08 normalization > 20:49:01.949258 [debug] [MainThread]: Parsing macros/sql/groupby.sql 2022-05-23 20:49:08 normalization > 20:49:01.951172 [debug] [MainThread]: Parsing macros/sql/get_tables_by_prefix_sql.sql 2022-05-23 20:49:08 normalization > 20:49:01.953630 [debug] [MainThread]: Parsing macros/sql/get_query_results_as_dict.sql 2022-05-23 20:49:08 normalization > 20:49:01.957092 [debug] [MainThread]: Parsing macros/sql/get_table_types_sql.sql 2022-05-23 20:49:08 normalization > 20:49:01.958907 [debug] [MainThread]: Parsing macros/sql/get_relations_by_prefix.sql 2022-05-23 20:49:08 normalization > 20:49:01.964212 [debug] [MainThread]: Parsing macros/jinja_helpers/pretty_log_format.sql 2022-05-23 20:49:08 normalization > 20:49:01.965795 [debug] [MainThread]: Parsing macros/jinja_helpers/pretty_time.sql 2022-05-23 20:49:08 normalization > 20:49:01.967538 [debug] [MainThread]: Parsing macros/jinja_helpers/slugify.sql 2022-05-23 20:49:08 normalization > 20:49:01.969267 [debug] [MainThread]: Parsing macros/jinja_helpers/log_info.sql 2022-05-23 20:49:08 normalization > 20:49:01.970973 [debug] [MainThread]: Parsing macros/materializations/insert_by_period_materialization.sql 2022-05-23 20:49:08 normalization > 20:49:02.009016 [debug] [MainThread]: Parsing macros/schema_tests/expression_is_true.sql 2022-05-23 20:49:08 normalization > 20:49:02.011670 [debug] [MainThread]: Parsing macros/schema_tests/not_accepted_values.sql 2022-05-23 20:49:08 normalization > 20:49:02.014798 [debug] [MainThread]: Parsing macros/schema_tests/cardinality_equality.sql 2022-05-23 20:49:08 normalization > 20:49:02.017746 [debug] [MainThread]: Parsing macros/schema_tests/test_not_null_where.sql 2022-05-23 20:49:08 normalization > 20:49:02.019762 [debug] [MainThread]: Parsing macros/schema_tests/sequential_values.sql 2022-05-23 20:49:08 normalization > 20:49:02.024271 [debug] [MainThread]: Parsing macros/schema_tests/not_null_proportion.sql 2022-05-23 20:49:08 normalization > 20:49:02.027642 [debug] [MainThread]: Parsing macros/schema_tests/recency.sql 2022-05-23 20:49:08 normalization > 20:49:02.030317 [debug] [MainThread]: Parsing macros/schema_tests/accepted_range.sql 2022-05-23 20:49:08 normalization > 20:49:02.034166 [debug] [MainThread]: Parsing macros/schema_tests/mutually_exclusive_ranges.sql 2022-05-23 20:49:08 normalization > 20:49:02.049448 [debug] [MainThread]: Parsing macros/schema_tests/equality.sql 2022-05-23 20:49:08 normalization > 20:49:02.055098 [debug] [MainThread]: Parsing macros/schema_tests/relationships_where.sql 2022-05-23 20:49:08 normalization > 20:49:02.058541 [debug] [MainThread]: Parsing macros/schema_tests/not_constant.sql 2022-05-23 20:49:08 normalization > 20:49:02.060337 [debug] [MainThread]: Parsing macros/schema_tests/at_least_one.sql 2022-05-23 20:49:08 normalization > 20:49:02.062192 [debug] [MainThread]: Parsing macros/schema_tests/test_unique_where.sql 2022-05-23 20:49:08 normalization > 20:49:02.064254 [debug] [MainThread]: Parsing macros/schema_tests/unique_combination_of_columns.sql 2022-05-23 20:49:08 normalization > 20:49:02.068668 [debug] [MainThread]: Parsing macros/schema_tests/fewer_rows_than.sql 2022-05-23 20:49:08 normalization > 20:49:02.071236 [debug] [MainThread]: Parsing macros/schema_tests/equal_rowcount.sql 2022-05-23 20:49:08 normalization > 20:49:02.696097 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_ctes/dbo/ad_account_user_tos_accepted_ab1.sql 2022-05-23 20:49:08 normalization > 20:49:02.735516 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_ctes/dbo/ad_account_user_tos_accepted_ab1.sql 2022-05-23 20:49:08 normalization > 20:49:02.737716 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_ctes/dbo/ad_account_business_ab1.sql 2022-05-23 20:49:08 normalization > 20:49:02.746672 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_ctes/dbo/ad_account_business_ab1.sql 2022-05-23 20:49:08 normalization > 20:49:02.748183 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_ctes/dbo/ad_account_business_ab3.sql 2022-05-23 20:49:08 normalization > 20:49:02.777589 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_ctes/dbo/ad_account_business_ab3.sql 2022-05-23 20:49:08 normalization > 20:49:02.779239 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_ctes/dbo/ad_account_tos_accepted_ab2.sql 2022-05-23 20:49:08 normalization > 20:49:02.790236 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_ctes/dbo/ad_account_tos_accepted_ab2.sql 2022-05-23 20:49:08 normalization > 20:49:02.791912 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_ctes/dbo/ad_account_business_ab2.sql 2022-05-23 20:49:08 normalization > 20:49:02.800635 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_ctes/dbo/ad_account_business_ab2.sql 2022-05-23 20:49:08 normalization > 20:49:02.802530 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_ctes/dbo/ad_account_tos_accepted_ab3.sql 2022-05-23 20:49:08 normalization > 20:49:02.812793 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_ctes/dbo/ad_account_tos_accepted_ab3.sql 2022-05-23 20:49:08 normalization > 20:49:02.814451 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_ctes/dbo/ad_account_user_tos_accepted_ab3.sql 2022-05-23 20:49:08 normalization > 20:49:02.823648 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_ctes/dbo/ad_account_user_tos_accepted_ab3.sql 2022-05-23 20:49:08 normalization > 20:49:02.827224 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_ctes/dbo/ad_account_ab1.sql 2022-05-23 20:49:08 normalization > 20:49:02.906794 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_ctes/dbo/ad_account_ab1.sql 2022-05-23 20:49:08 normalization > 20:49:02.908583 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_ctes/dbo/ad_account_rf_spec_ab3.sql 2022-05-23 20:49:08 normalization > 20:49:02.927958 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_ctes/dbo/ad_account_rf_spec_ab3.sql 2022-05-23 20:49:08 normalization > 20:49:02.929695 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_ctes/dbo/ad_account_funding_source_details_ab2.sql 2022-05-23 20:49:08 normalization > 20:49:02.938807 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_ctes/dbo/ad_account_funding_source_details_ab2.sql 2022-05-23 20:49:08 normalization > 20:49:02.941097 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_ctes/dbo/ad_account_funding_source_details_ab1.sql 2022-05-23 20:49:08 normalization > 20:49:02.953166 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_ctes/dbo/ad_account_funding_source_details_ab1.sql 2022-05-23 20:49:08 normalization > 20:49:02.955072 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_ctes/dbo/ad_account_ab3.sql 2022-05-23 20:49:08 normalization > 20:49:02.989888 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_ctes/dbo/ad_account_ab3.sql 2022-05-23 20:49:08 normalization > 20:49:02.991557 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_ctes/dbo/ad_account_user_tos_accepted_ab2.sql 2022-05-23 20:49:08 normalization > 20:49:03.000683 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_ctes/dbo/ad_account_user_tos_accepted_ab2.sql 2022-05-23 20:49:08 normalization > 20:49:03.002301 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_ctes/dbo/ad_account_rf_spec_ab2.sql 2022-05-23 20:49:08 normalization > 20:49:03.013721 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_ctes/dbo/ad_account_rf_spec_ab2.sql 2022-05-23 20:49:08 normalization > 20:49:03.015696 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_ctes/dbo/ad_account_tos_accepted_ab1.sql 2022-05-23 20:49:08 normalization > 20:49:03.024076 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_ctes/dbo/ad_account_tos_accepted_ab1.sql 2022-05-23 20:49:08 normalization > 20:49:03.026252 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_ctes/dbo/ad_account_rf_spec_ab1.sql 2022-05-23 20:49:08 normalization > 20:49:03.039718 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_ctes/dbo/ad_account_rf_spec_ab1.sql 2022-05-23 20:49:08 normalization > 20:49:03.041295 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_ctes/dbo/ad_account_funding_source_details_ab3.sql 2022-05-23 20:49:08 normalization > 20:49:03.050759 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_ctes/dbo/ad_account_funding_source_details_ab3.sql 2022-05-23 20:49:08 normalization > 20:49:03.052791 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_ctes/dbo/ad_account_ab2.sql 2022-05-23 20:49:08 normalization > 20:49:03.097532 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_ctes/dbo/ad_account_ab2.sql 2022-05-23 20:49:08 normalization > 20:49:03.099941 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_incremental/dbo/ad_account_user_tos_accepted.sql 2022-05-23 20:49:08 normalization > 20:49:03.107673 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_incremental/dbo/ad_account_user_tos_accepted.sql 2022-05-23 20:49:08 normalization > 20:49:03.109799 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_incremental/dbo/ad_account_rf_spec.sql 2022-05-23 20:49:08 normalization > 20:49:03.117483 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_incremental/dbo/ad_account_rf_spec.sql 2022-05-23 20:49:08 normalization > 20:49:03.119750 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_incremental/dbo/ad_account_funding_source_details.sql 2022-05-23 20:49:08 normalization > 20:49:03.127510 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_incremental/dbo/ad_account_funding_source_details.sql 2022-05-23 20:49:08 normalization > 20:49:03.129662 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_incremental/dbo/ad_account_business.sql 2022-05-23 20:49:08 normalization > 20:49:03.138278 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_incremental/dbo/ad_account_business.sql 2022-05-23 20:49:08 normalization > 20:49:03.140440 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_incremental/dbo/ad_account.sql 2022-05-23 20:49:08 normalization > 20:49:03.148347 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_incremental/dbo/ad_account.sql 2022-05-23 20:49:08 normalization > 20:49:03.150453 [debug] [MainThread]: 1603: static parser failed on generated/airbyte_incremental/dbo/ad_account_tos_accepted.sql 2022-05-23 20:49:08 normalization > 20:49:03.157759 [debug] [MainThread]: 1602: parser fallback to jinja rendering on generated/airbyte_incremental/dbo/ad_account_tos_accepted.sql 2022-05-23 20:49:08 normalization > 20:49:03.288670 [warn ] [MainThread]: [WARNING]: Configuration paths exist in your dbt_project.yml file which do not apply to any resources. 2022-05-23 20:49:08 normalization > There are 2 unused configuration paths: 2022-05-23 20:49:08 normalization > - models.airbyte_utils.generated.airbyte_tables 2022-05-23 20:49:08 normalization > - models.airbyte_utils.generated.airbyte_views 2022-05-23 20:49:08 normalization > 2022-05-23 20:49:08 normalization > 20:49:03.312193 [info ] [MainThread]: Found 24 models, 0 tests, 0 snapshots, 0 analyses, 543 macros, 0 operations, 0 seed files, 1 source, 0 exposures, 0 metrics 2022-05-23 20:49:08 normalization > 20:49:03.314831 [info ] [MainThread]: 2022-05-23 20:49:08 normalization > 20:49:03.315423 [debug] [MainThread]: Acquiring new sqlserver connection "master" 2022-05-23 20:49:08 normalization > 20:49:03.317699 [debug] [ThreadPool]: Acquiring new sqlserver connection "list_dev" 2022-05-23 20:49:08 normalization > 20:49:03.333849 [debug] [ThreadPool]: Opening a new connection, currently in state init 2022-05-23 20:49:08 normalization > 20:49:03.359416 [debug] [ThreadPool]: On list_dev: Close 2022-05-23 20:49:08 normalization > 20:49:03.361518 [debug] [ThreadPool]: Acquiring new sqlserver connection "list_dev_dbo" 2022-05-23 20:49:08 normalization > 20:49:03.369948 [debug] [ThreadPool]: Opening a new connection, currently in state closed 2022-05-23 20:49:08 normalization > 20:49:03.415386 [debug] [ThreadPool]: On list_dev_dbo: ROLLBACK 2022-05-23 20:49:08 normalization > 20:49:03.415672 [debug] [ThreadPool]: On list_dev_dbo: Close 2022-05-23 20:49:08 normalization > 20:49:04.283834 [debug] [MainThread]: On master: COMMIT 2022-05-23 20:49:08 normalization > 20:49:04.284367 [info ] [MainThread]: Concurrency: 8 threads (target='prod') 2022-05-23 20:49:08 normalization > 20:49:04.284731 [info ] [MainThread]: 2022-05-23 20:49:08 normalization > 20:49:04.304838 [debug] [Thread-1 ]: Began running node model.airbyte_utils.ad_account_ab1 2022-05-23 20:49:08 normalization > 20:49:04.305361 [debug] [Thread-1 ]: Acquiring new sqlserver connection "model.airbyte_utils.ad_account_ab1" 2022-05-23 20:49:08 normalization > 20:49:04.305521 [debug] [Thread-1 ]: Began compiling node model.airbyte_utils.ad_account_ab1 2022-05-23 20:49:08 normalization > 20:49:04.305705 [debug] [Thread-1 ]: Compiling model.airbyte_utils.ad_account_ab1 2022-05-23 20:49:08 normalization > 20:49:04.371649 [debug] [Thread-1 ]: On "model.airbyte_utils.ad_account_ab1": cache miss for schema "{self.database}.{self.schema}", this is inefficient 2022-05-23 20:49:08 normalization > 20:49:04.375679 [debug] [Thread-1 ]: Opening a new connection, currently in state closed 2022-05-23 20:49:08 normalization > 20:49:04.400984 [debug] [Thread-1 ]: with database=dev, schema=_airbyte_dbo, relations=[] 2022-05-23 20:49:08 normalization > 20:49:04.401393 [debug] [Thread-1 ]: Writing injected SQL for node "model.airbyte_utils.ad_account_ab1" 2022-05-23 20:49:08 normalization > 20:49:04.402145 [debug] [Thread-1 ]: finished collecting timing info 2022-05-23 20:49:08 normalization > 20:49:04.402365 [debug] [Thread-1 ]: On model.airbyte_utils.ad_account_ab1: ROLLBACK 2022-05-23 20:49:08 normalization > 20:49:04.402516 [debug] [Thread-1 ]: On model.airbyte_utils.ad_account_ab1: Close 2022-05-23 20:49:08 normalization > 20:49:04.403237 [debug] [Thread-1 ]: Finished running node model.airbyte_utils.ad_account_ab1 2022-05-23 20:49:08 normalization > 20:49:04.404373 [debug] [Thread-3 ]: Began running node model.airbyte_utils.ad_account_ab2 2022-05-23 20:49:08 normalization > 20:49:04.404998 [debug] [Thread-3 ]: Acquiring new sqlserver connection "model.airbyte_utils.ad_account_ab2" 2022-05-23 20:49:08 normalization > 20:49:04.405251 [debug] [Thread-3 ]: Began compiling node model.airbyte_utils.ad_account_ab2 2022-05-23 20:49:08 normalization > 20:49:04.405480 [debug] [Thread-3 ]: Compiling model.airbyte_utils.ad_account_ab2 2022-05-23 20:49:08 normalization > 20:49:04.441190 [debug] [Thread-3 ]: On "model.airbyte_utils.ad_account_ab2": cache miss for schema "{self.database}.{self.schema}", this is inefficient 2022-05-23 20:49:08 normalization > 20:49:04.444354 [debug] [Thread-3 ]: Opening a new connection, currently in state init 2022-05-23 20:49:08 normalization > 20:49:04.461774 [debug] [Thread-3 ]: with database=dev, schema=_airbyte_dbo, relations=[] 2022-05-23 20:49:08 normalization > 20:49:04.554406 [debug] [Thread-3 ]: Writing injected SQL for node "model.airbyte_utils.ad_account_ab2" 2022-05-23 20:49:08 normalization > 20:49:04.554794 [debug] [Thread-3 ]: finished collecting timing info 2022-05-23 20:49:08 normalization > 20:49:04.554980 [debug] [Thread-3 ]: On model.airbyte_utils.ad_account_ab2: ROLLBACK 2022-05-23 20:49:08 normalization > 20:49:04.555249 [debug] [Thread-3 ]: On model.airbyte_utils.ad_account_ab2: Close 2022-05-23 20:49:08 normalization > 20:49:04.555796 [debug] [Thread-3 ]: Finished running node model.airbyte_utils.ad_account_ab2 2022-05-23 20:49:08 normalization > 20:49:04.556936 [debug] [Thread-5 ]: Began running node model.airbyte_utils.ad_account_ab3 2022-05-23 20:49:08 normalization > 20:49:04.557454 [debug] [Thread-5 ]: Acquiring new sqlserver connection "model.airbyte_utils.ad_account_ab3" 2022-05-23 20:49:08 normalization > 20:49:04.557644 [debug] [Thread-5 ]: Began compiling node model.airbyte_utils.ad_account_ab3 2022-05-23 20:49:08 normalization > 20:49:04.557798 [debug] [Thread-5 ]: Compiling model.airbyte_utils.ad_account_ab3 2022-05-23 20:49:08 normalization > 20:49:04.591133 [debug] [Thread-5 ]: On "model.airbyte_utils.ad_account_ab3": cache miss for schema "{self.database}.{self.schema}", this is inefficient 2022-05-23 20:49:08 normalization > 20:49:04.594191 [debug] [Thread-5 ]: Opening a new connection, currently in state init 2022-05-23 20:49:08 normalization > 20:49:04.613767 [debug] [Thread-5 ]: with database=dev, schema=_airbyte_dbo, relations=[] 2022-05-23 20:49:08 normalization > 20:49:04.781315 [debug] [Thread-5 ]: Writing injected SQL for node "model.airbyte_utils.ad_account_ab3" 2022-05-23 20:49:08 normalization > 20:49:04.781771 [debug] [Thread-5 ]: finished collecting timing info 2022-05-23 20:49:08 normalization > 20:49:04.781990 [debug] [Thread-5 ]: On model.airbyte_utils.ad_account_ab3: ROLLBACK 2022-05-23 20:49:08 normalization > 20:49:04.782149 [debug] [Thread-5 ]: On model.airbyte_utils.ad_account_ab3: Close 2022-05-23 20:49:08 normalization > 20:49:04.782981 [debug] [Thread-5 ]: Finished running node model.airbyte_utils.ad_account_ab3 2022-05-23 20:49:08 normalization > 20:49:04.784357 [debug] [Thread-7 ]: Began running node model.airbyte_utils.ad_account 2022-05-23 20:49:08 normalization > 20:49:04.784894 [info ] [Thread-7 ]: 1 of 6 START incremental model dbo.ad_account........................................................................... [RUN] 2022-05-23 20:49:08 normalization > 20:49:04.785624 [debug] [Thread-7 ]: Acquiring new sqlserver connection "model.airbyte_utils.ad_account" 2022-05-23 20:49:08 normalization > 20:49:04.785812 [debug] [Thread-7 ]: Began compiling node model.airbyte_utils.ad_account 2022-05-23 20:49:08 normalization > 20:49:04.785991 [debug] [Thread-7 ]: Compiling model.airbyte_utils.ad_account 2022-05-23 20:49:08 normalization > 20:49:04.823579 [debug] [Thread-7 ]: Opening a new connection, currently in state init 2022-05-23 20:49:08 normalization > 20:49:04.903403 [debug] [Thread-7 ]: Writing injected SQL for node "model.airbyte_utils.ad_account" 2022-05-23 20:49:08 normalization > 20:49:04.903960 [debug] [Thread-7 ]: finished collecting timing info 2022-05-23 20:49:08 normalization > 20:49:04.904129 [debug] [Thread-7 ]: Began executing node model.airbyte_utils.ad_account 2022-05-23 20:49:08 normalization > 20:49:05.077722 [debug] [Thread-7 ]: finished collecting timing info 2022-05-23 20:49:08 normalization > 20:49:05.078031 [debug] [Thread-7 ]: On model.airbyte_utils.ad_account: ROLLBACK 2022-05-23 20:49:08 normalization > 20:49:05.078181 [debug] [Thread-7 ]: On model.airbyte_utils.ad_account: Close 2022-05-23 20:49:08 normalization > 20:49:05.078706 [error] [Thread-7 ]: Unhandled error while executing model.airbyte_utils.ad_account 2022-05-23 20:49:08 normalization > ('42000', '[42000] [Microsoft][ODBC Driver 17 for SQL Server][SQL Server]Error converting data type nvarchar to float. (8114) (SQLMoreResults)') 2022-05-23 20:49:08 normalization > 20:49:05.079273 [debug] [Thread-7 ]: 2022-05-23 20:49:08 normalization > 20:49:05.079906 [error] [Thread-7 ]: 1 of 6 ERROR creating incremental model dbo.ad_account.................................................................. [ERROR in 0.29s] 2022-05-23 20:49:08 normalization > 20:49:05.080526 [debug] [Thread-7 ]: Finished running node model.airbyte_utils.ad_account 2022-05-23 20:49:08 normalization > 20:49:05.082204 [debug] [Thread-2 ]: Began running node model.airbyte_utils.ad_account_business_ab1 2022-05-23 20:49:08 normalization > 20:49:05.082579 [debug] [Thread-1 ]: Began running node model.airbyte_utils.ad_account_funding_source_details_ab1 2022-05-23 20:49:08 normalization > 20:49:05.082829 [debug] [Thread-4 ]: Began running node model.airbyte_utils.ad_account_rf_spec_ab1 2022-05-23 20:49:08 normalization > 20:49:05.083084 [debug] [Thread-2 ]: Finished running node model.airbyte_utils.ad_account_business_ab1 2022-05-23 20:49:08 normalization > 20:49:05.083274 [debug] [Thread-3 ]: Began running node model.airbyte_utils.ad_account_tos_accepted_ab1 2022-05-23 20:49:08 normalization > 20:49:05.083594 [debug] [Thread-6 ]: Began running node model.airbyte_utils.ad_account_user_tos_accepted_ab1 2022-05-23 20:49:08 normalization > 20:49:05.083850 [debug] [Thread-1 ]: Finished running node model.airbyte_utils.ad_account_funding_source_details_ab1 2022-05-23 20:49:08 normalization > 20:49:05.084150 [debug] [Thread-4 ]: Finished running node model.airbyte_utils.ad_account_rf_spec_ab1 2022-05-23 20:49:08 normalization > 20:49:05.084597 [debug] [Thread-3 ]: Finished running node model.airbyte_utils.ad_account_tos_accepted_ab1 2022-05-23 20:49:08 normalization > 20:49:05.085241 [debug] [Thread-6 ]: Finished running node model.airbyte_utils.ad_account_user_tos_accepted_ab1 2022-05-23 20:49:08 normalization > 20:49:05.085508 [debug] [Thread-8 ]: Began running node model.airbyte_utils.ad_account_business_ab2 2022-05-23 20:49:08 normalization > 20:49:05.086712 [debug] [Thread-3 ]: Began running node model.airbyte_utils.ad_account_funding_source_details_ab2 2022-05-23 20:49:08 normalization > 20:49:05.087666 [debug] [Thread-2 ]: Began running node model.airbyte_utils.ad_account_rf_spec_ab2 2022-05-23 20:49:08 normalization > 20:49:05.087995 [debug] [Thread-8 ]: Finished running node model.airbyte_utils.ad_account_business_ab2 2022-05-23 20:49:08 normalization > 20:49:05.088374 [debug] [Thread-1 ]: Began running node model.airbyte_utils.ad_account_tos_accepted_ab2 2022-05-23 20:49:08 normalization > 20:49:05.088609 [debug] [Thread-3 ]: Finished running node model.airbyte_utils.ad_account_funding_source_details_ab2 2022-05-23 20:49:08 normalization > 20:49:05.088815 [debug] [Thread-4 ]: Began running node model.airbyte_utils.ad_account_user_tos_accepted_ab2 2022-05-23 20:49:08 normalization > 20:49:05.089158 [debug] [Thread-2 ]: Finished running node model.airbyte_utils.ad_account_rf_spec_ab2 2022-05-23 20:49:08 normalization > 20:49:05.089942 [debug] [Thread-1 ]: Finished running node model.airbyte_utils.ad_account_tos_accepted_ab2 2022-05-23 20:49:08 normalization > 20:49:05.090227 [debug] [Thread-6 ]: Began running node model.airbyte_utils.ad_account_business_ab3 2022-05-23 20:49:08 normalization > 20:49:05.090872 [debug] [Thread-4 ]: Finished running node model.airbyte_utils.ad_account_user_tos_accepted_ab2 2022-05-23 20:49:08 normalization > 20:49:05.091377 [debug] [Thread-5 ]: Began running node model.airbyte_utils.ad_account_funding_source_details_ab3 2022-05-23 20:49:08 normalization > 20:49:05.092947 [debug] [Thread-6 ]: Finished running node model.airbyte_utils.ad_account_business_ab3 2022-05-23 20:49:08 normalization > 20:49:05.093144 [debug] [Thread-3 ]: Began running node model.airbyte_utils.ad_account_rf_spec_ab3 2022-05-23 20:49:08 normalization > 20:49:05.093445 [debug] [Thread-7 ]: Began running node model.airbyte_utils.ad_account_tos_accepted_ab3 2022-05-23 20:49:08 normalization > 20:49:05.093971 [debug] [Thread-5 ]: Finished running node model.airbyte_utils.ad_account_funding_source_details_ab3 2022-05-23 20:49:08 normalization > 20:49:05.094445 [debug] [Thread-8 ]: Began running node model.airbyte_utils.ad_account_user_tos_accepted_ab3 2022-05-23 20:49:08 normalization > 20:49:05.095156 [debug] [Thread-3 ]: Finished running node model.airbyte_utils.ad_account_rf_spec_ab3 2022-05-23 20:49:08 normalization > 20:49:05.095333 [debug] [Thread-4 ]: Began running node model.airbyte_utils.ad_account_business 2022-05-23 20:49:08 normalization > 20:49:05.095647 [debug] [Thread-7 ]: Finished running node model.airbyte_utils.ad_account_tos_accepted_ab3 2022-05-23 20:49:08 normalization > 20:49:05.096284 [debug] [Thread-8 ]: Finished running node model.airbyte_utils.ad_account_user_tos_accepted_ab3 2022-05-23 20:49:08 normalization > 20:49:05.096516 [debug] [Thread-6 ]: Began running node model.airbyte_utils.ad_account_funding_source_details 2022-05-23 20:49:08 normalization > 20:49:05.097253 [info ] [Thread-4 ]: 2 of 6 SKIP relation dbo.ad_account_business............................................................................ [SKIP] 2022-05-23 20:49:08 normalization > 20:49:05.097447 [debug] [Thread-2 ]: Began running node model.airbyte_utils.ad_account_rf_spec 2022-05-23 20:49:08 normalization > 20:49:05.098567 [info ] [Thread-6 ]: 3 of 6 SKIP relation dbo.ad_account_funding_source_details.............................................................. [SKIP] 2022-05-23 20:49:08 normalization > 20:49:05.098867 [debug] [Thread-8 ]: Began running node model.airbyte_utils.ad_account_tos_accepted 2022-05-23 20:49:08 normalization > 20:49:05.099546 [debug] [Thread-5 ]: Began running node model.airbyte_utils.ad_account_user_tos_accepted 2022-05-23 20:49:08 normalization > 20:49:05.100024 [info ] [Thread-2 ]: 4 of 6 SKIP relation dbo.ad_account_rf_spec............................................................................. [SKIP] 2022-05-23 20:49:08 normalization > 20:49:05.100493 [debug] [Thread-4 ]: Finished running node model.airbyte_utils.ad_account_business 2022-05-23 20:49:08 normalization > 20:49:05.101261 [info ] [Thread-8 ]: 5 of 6 SKIP relation dbo.ad_account_tos_accepted........................................................................ [SKIP] 2022-05-23 20:49:08 normalization > 20:49:05.101583 [debug] [Thread-6 ]: Finished running node model.airbyte_utils.ad_account_funding_source_details 2022-05-23 20:49:08 normalization > 20:49:05.101839 [info ] [Thread-5 ]: 6 of 6 SKIP relation dbo.ad_account_user_tos_accepted................................................................... [SKIP] 2022-05-23 20:49:08 normalization > 20:49:05.102733 [debug] [Thread-2 ]: Finished running node model.airbyte_utils.ad_account_rf_spec 2022-05-23 20:49:08 normalization > 20:49:05.104048 [debug] [Thread-8 ]: Finished running node model.airbyte_utils.ad_account_tos_accepted 2022-05-23 20:49:08 normalization > 20:49:05.104822 [debug] [Thread-5 ]: Finished running node model.airbyte_utils.ad_account_user_tos_accepted 2022-05-23 20:49:08 normalization > 20:49:05.107628 [debug] [MainThread]: Acquiring new sqlserver connection "master" 2022-05-23 20:49:08 normalization > 20:49:05.107898 [debug] [MainThread]: On master: COMMIT 2022-05-23 20:49:08 normalization > 20:49:05.108371 [info ] [MainThread]: 2022-05-23 20:49:08 normalization > 20:49:05.108720 [info ] [MainThread]: Finished running 6 incremental models in 1.79s. 2022-05-23 20:49:08 normalization > 20:49:05.109101 [debug] [MainThread]: Connection 'master' was properly closed. 2022-05-23 20:49:08 normalization > 20:49:05.109369 [debug] [MainThread]: Connection 'model.airbyte_utils.ad_account_ab1' was properly closed. 2022-05-23 20:49:08 normalization > 20:49:05.109553 [debug] [MainThread]: Connection 'model.airbyte_utils.ad_account_ab2' was properly closed. 2022-05-23 20:49:08 normalization > 20:49:05.109803 [debug] [MainThread]: Connection 'model.airbyte_utils.ad_account_ab3' was properly closed. 2022-05-23 20:49:08 normalization > 20:49:05.109958 [debug] [MainThread]: Connection 'model.airbyte_utils.ad_account' was properly closed. 2022-05-23 20:49:08 normalization > 20:49:05.125646 [info ] [MainThread]: 2022-05-23 20:49:08 normalization > 20:49:05.126016 [info ] [MainThread]: Completed with 1 error and 0 warnings: 2022-05-23 20:49:08 normalization > 20:49:05.126406 [info ] [MainThread]: 2022-05-23 20:49:08 normalization > 20:49:05.126796 [error] [MainThread]: ('42000', '[42000] [Microsoft][ODBC Driver 17 for SQL Server][SQL Server]Error converting data type nvarchar to float. (8114) (SQLMoreResults)') 2022-05-23 20:49:08 normalization > 20:49:05.127298 [info ] [MainThread]: 2022-05-23 20:49:08 normalization > 20:49:05.127689 [info ] [MainThread]: Done. PASS=0 WARN=0 ERROR=1 SKIP=5 TOTAL=6 2022-05-23 20:49:08 INFO i.a.w.t.TemporalAttemptExecution(lambda$getWorkerThread$2):161 - Completing future exceptionally... io.airbyte.workers.WorkerException: Normalization Failed. at io.airbyte.workers.DefaultNormalizationWorker.run(DefaultNormalizationWorker.java:61) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] at io.airbyte.workers.DefaultNormalizationWorker.run(DefaultNormalizationWorker.java:19) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] at io.airbyte.workers.temporal.TemporalAttemptExecution.lambda$getWorkerThread$2(TemporalAttemptExecution.java:158) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] at java.lang.Thread.run(Thread.java:833) [?:?] Caused by: io.airbyte.workers.WorkerException: Normalization Failed. at io.airbyte.workers.DefaultNormalizationWorker.run(DefaultNormalizationWorker.java:58) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] ... 3 more Suppressed: io.airbyte.workers.WorkerException: Normalization process wasn't successful at io.airbyte.workers.normalization.DefaultNormalizationRunner.close(DefaultNormalizationRunner.java:162) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] at io.airbyte.workers.DefaultNormalizationWorker.run(DefaultNormalizationWorker.java:46) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] at io.airbyte.workers.DefaultNormalizationWorker.run(DefaultNormalizationWorker.java:19) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] at io.airbyte.workers.temporal.TemporalAttemptExecution.lambda$getWorkerThread$2(TemporalAttemptExecution.java:158) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] at java.lang.Thread.run(Thread.java:833) [?:?] 2022-05-23 20:49:08 INFO i.a.w.t.TemporalAttemptExecution(get):134 - Stopping cancellation check scheduling... 2022-05-23 20:49:08 INFO i.a.w.t.TemporalUtils(withBackgroundHeartbeat):236 - Stopping temporal heartbeating... 2022-05-23 20:49:08 WARN i.t.i.a.POJOActivityTaskHandler(activityFailureToResult):307 - Activity failure. ActivityId=7e02016d-14f0-3c9f-bc34-8b6f36b0f2be, activityType=Normalize, attempt=1 java.lang.RuntimeException: io.temporal.serviceclient.CheckedExceptionWrapper: java.util.concurrent.ExecutionException: io.airbyte.workers.WorkerException: Normalization Failed. at io.airbyte.workers.temporal.TemporalUtils.withBackgroundHeartbeat(TemporalUtils.java:234) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] at io.airbyte.workers.temporal.sync.NormalizationActivityImpl.normalize(NormalizationActivityImpl.java:75) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?] at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?] at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?] at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?] at io.temporal.internal.activity.POJOActivityTaskHandler$POJOActivityInboundCallsInterceptor.execute(POJOActivityTaskHandler.java:214) ~[temporal-sdk-1.8.1.jar:?] at io.temporal.internal.activity.POJOActivityTaskHandler$POJOActivityImplementation.execute(POJOActivityTaskHandler.java:180) ~[temporal-sdk-1.8.1.jar:?] at io.temporal.internal.activity.POJOActivityTaskHandler.handle(POJOActivityTaskHandler.java:120) ~[temporal-sdk-1.8.1.jar:?] at io.temporal.internal.worker.ActivityWorker$TaskHandlerImpl.handle(ActivityWorker.java:204) ~[temporal-sdk-1.8.1.jar:?] at io.temporal.internal.worker.ActivityWorker$TaskHandlerImpl.handle(ActivityWorker.java:164) ~[temporal-sdk-1.8.1.jar:?] at io.temporal.internal.worker.PollTaskExecutor.lambda$process$0(PollTaskExecutor.java:93) ~[temporal-sdk-1.8.1.jar:?] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?] at java.lang.Thread.run(Thread.java:833) [?:?] Caused by: io.temporal.serviceclient.CheckedExceptionWrapper: java.util.concurrent.ExecutionException: io.airbyte.workers.WorkerException: Normalization Failed. at io.temporal.serviceclient.CheckedExceptionWrapper.wrap(CheckedExceptionWrapper.java:56) ~[temporal-serviceclient-1.8.1.jar:?] at io.temporal.internal.sync.WorkflowInternal.wrap(WorkflowInternal.java:448) ~[temporal-sdk-1.8.1.jar:?] at io.temporal.activity.Activity.wrap(Activity.java:51) ~[temporal-sdk-1.8.1.jar:?] at io.airbyte.workers.temporal.TemporalAttemptExecution.get(TemporalAttemptExecution.java:138) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] at io.airbyte.workers.temporal.sync.NormalizationActivityImpl.lambda$normalize$3(NormalizationActivityImpl.java:103) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] at io.airbyte.workers.temporal.TemporalUtils.withBackgroundHeartbeat(TemporalUtils.java:229) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] ... 14 more Caused by: java.util.concurrent.ExecutionException: io.airbyte.workers.WorkerException: Normalization Failed. at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:396) ~[?:?] at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2073) ~[?:?] at io.airbyte.workers.temporal.TemporalAttemptExecution.get(TemporalAttemptExecution.java:132) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] at io.airbyte.workers.temporal.sync.NormalizationActivityImpl.lambda$normalize$3(NormalizationActivityImpl.java:103) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] at io.airbyte.workers.temporal.TemporalUtils.withBackgroundHeartbeat(TemporalUtils.java:229) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] ... 14 more Caused by: io.airbyte.workers.WorkerException: Normalization Failed. at io.airbyte.workers.DefaultNormalizationWorker.run(DefaultNormalizationWorker.java:61) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] at io.airbyte.workers.DefaultNormalizationWorker.run(DefaultNormalizationWorker.java:19) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] at io.airbyte.workers.temporal.TemporalAttemptExecution.lambda$getWorkerThread$2(TemporalAttemptExecution.java:158) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] ... 1 more Caused by: io.airbyte.workers.WorkerException: Normalization Failed. at io.airbyte.workers.DefaultNormalizationWorker.run(DefaultNormalizationWorker.java:58) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] at io.airbyte.workers.DefaultNormalizationWorker.run(DefaultNormalizationWorker.java:19) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] at io.airbyte.workers.temporal.TemporalAttemptExecution.lambda$getWorkerThread$2(TemporalAttemptExecution.java:158) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] ... 1 more Suppressed: io.airbyte.workers.WorkerException: Normalization process wasn't successful at io.airbyte.workers.normalization.DefaultNormalizationRunner.close(DefaultNormalizationRunner.java:162) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] at io.airbyte.workers.DefaultNormalizationWorker.run(DefaultNormalizationWorker.java:46) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] at io.airbyte.workers.DefaultNormalizationWorker.run(DefaultNormalizationWorker.java:19) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] at io.airbyte.workers.temporal.TemporalAttemptExecution.lambda$getWorkerThread$2(TemporalAttemptExecution.java:158) ~[io.airbyte-airbyte-workers-0.38.2-alpha.jar:?] at java.lang.Thread.run(Thread.java:833) [?:?]