https://linen.dev logo
Join Slack
Powered by
Hi all, having issues with long-running replicatio...
# troubleshooting
p
Hi all, having issues with long-running replication process using 
meltano run ...
. I'm using tap-snowflake (transferwise) and target-duckdb. Process runs for ~6.5 hrs then crashes. Process is running in a detached screen shell on a k8s pod. I don't see a detailed error message. On one occasion, I saw a Forbidden error from tap-snowflake. I tried to replicate it. This time, process ends roughly the same way (after 6.5 hrs) but there is no error stack. Below log runs after a series of records are logged. The state bookmark is updated, but I'm not entirely sure that the records were actually inserted to duckdb. This is using 
meltano run ...
api with an inline stream mapper. ```2023-01-03T080954.845407Z [debug ] tail consumer is next block, wrapping up 2023-01-03T080954.845684Z [info ] time=2023-01-03 080954 name=target_duckdb level=INFO message=Loading 7758 rows into 'analytics."sales_invoice_v"' cmd_type=elb consumer=True name=target-duckdb-staging producer=False stdio=stderr string_id=target-duckdb-staging 2023-01-03T081004.630578Z [debug ] Added to state devtap snowflake sales invoice to target duckdb stagingcc state payload {'singer_state': {'currently_syncing': 'ANALYTICS-SALES_INVOICE_V', 'bookmarks': {'ANALYTICS-SALES_INVOICE_V': {'replication_key': 'UPDATED_TIMESTAMP', 'version': 1670361200499, 'replication_key_value': '2022-08-31T121649.583000+0000+0000'}}}} 2023-01-03T081004.630959Z [info ] Writing state to Local Filesystem 2023-01-03T081004.633253Z [debug ] {'uri': '//project/.meltano/state/devtap snowflake sales invoice to target duckdb stagingcc/lock', 'mode': 'r', 'buffering': -1, 'encoding': None, 'errors': None, 'newline': None, 'closefd': True, 'opener': None, 'compression': 'infer_from_extension', 'transport_params': None} 2023-01-03T081004.635055Z [debug ] {'uri': '//project/.meltano/state/devtap snowflake sales invoice to target duckdb stagingcc/lock', 'mode': 'w+', 'buffering': -1, 'encoding': None, 'errors': None, 'newline': None, 'closefd': True, 'opener': None, 'compression': 'infer_from_extension', 'transport_params': {}} 2023-01-03T081004.643909Z [debug ] {'uri': '//project/.meltano/state/devtap snowflake sales invoice to target duckdb stagingcc/state.json', 'mode': 'w+', 'buffering': -1, 'encoding': None, 'errors': None, 'newline': None, 'closefd': True, 'opener': None, 'compression': 'infer_from_extension', 'transport_params': {}} 2023-01-03T081004.664174Z [info ] Incremental state has been updated at 2023-01-03 081004.664044. 2023-01-03T081004.664278Z [debug ] Incremental state: {'currently_syncing': 'ANALYTICS-SALES_INVOICE_V', 'bookmarks': {'ANALYTICS-SALES_INVOICE_V': {'replication_key': 'UPDATED_TIMESTAMP', 'version': 1670361200499, 'replication_key_value': '2022-08-31T121649.583000+0000+0000'}}} 2023-01-03T081004.664319Z [info ] {"currently_syncing": "ANALYTICS-SAP-SALES_INVOICE_V", "bookmarks": {"ANALYTICS-SALES_INVOICE_V": {"replication_key": "UPDATED_TIMESTAMP", "version": 1670361200499, "replication_key_value": "2022-08-31T121649.583000+0000+0000"}}} cmd_type=elb consumer=True name=target-duckdb-staging producer=False stdio=stdout string_id=target-duckdb-staging 2023-01-03T081005.721434Z [debug ] Deleted configuration at /project/.meltano/run/tap-snowflake-sales-invoice/tap.fad84407-910b-41e6-97b8-f282af3a0c97.config.json 2023-01-03T081005.721740Z [debug ] Deleted configuration at /project/.meltano/run/map-sales-invoice/mapper.a618689d-a999-4467-a404-cb99a891b96f.config.json 2023-01-03T081005.721975Z [debug ] Deleted configuration at /project/.meltano/run/target-duckdb-staging/target.c2f5eab8-15cc-4596-a9c6-59673a1d67dd.config.json 2023-01-03T081006.007373Z [error ] Extractor failed Traceback (most recent call last): File "/.venv/lib/python3.9/site-packages/meltano/core/logging/output_logger.py", line 201, in redirect_logging yield File "/.venv/lib/python3.9/site-pack…
c
meltano.cli.utils.CliError: Run invocation could not be completed as block failed: Extractor failed
yet there does not seem to be any indication of an issue being logged by the 
tap-snowflake
extractor. I suppose that the HTTP 403 "Forbidden" error you mentioned is the best indicator to follow up for now. Are you in a position to compare the experience of using the pipelinewise variant vs the meltanolabs variant of 
tap-snowflake
? The other thing that obviously makes this hard to troubleshoot is the 6.5 hours wait time for an error to occur. I'm not sure what would be the best step here to reduce that time, so you can iterate faster.
p
Last time I tried meltanolabs variant of 
tap-snowflake
- didn't quite work, b/c i intend to incrementally load using replication key. The meltanolabs variant was throwing errors. I'm thinking about using it for bulk loading the initial data, and transferwise variant for incremental loading.
c
Well, the problem that I see for you at the moment is that in extractor output there is absolutely no indication of what the problem is (apart from the "Forbidden" message you mentioned you had seen once). So, I think the first step would be to identify what the problem is and where it lies (i.e. whether the problem is intrinsic to the pipelinewise tap or whether it occurs with both variants of the tap)
p
Copy code
2023-01-04T04:38:41.802248Z [info     ] Writing state to Local Filesystem
2023-01-04T04:38:41.846267Z [info     ] Incremental state has been updated at 2023-01-04 04:38:41.846120.
2023-01-04T04:38:50.128172Z [info     ] time=2023-01-04 04:38:50 name=singer level=INFO message=METRIC: {"type": "counter", "metric": "record_count", "value": 42818, "tags": {"database": "ANALYTICS", "table": "SALES_INVOICE_V"}} cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice
2023-01-04T04:39:18.373086Z [info     ] time=2023-01-04 04:39:18 name=snowflake.connector.result_batch level=ERROR message=Failed to fetch the large result set batch data_2_1_1 for the 1 th time, backing off for 3s for the reason: '000403: HTTP 403: Forbidden' cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice
2023-01-04T04:39:18.373346Z [info     ] Traceback (most recent call last): cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice
2023-01-04T04:39:18.373479Z [info     ]   File "/project/.meltano/extractors/tap-snowflake/venv/lib/python3.9/site-packages/snowflake/connector/result_batch.py", line 314, in _download cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice
2023-01-04T04:39:18.373600Z [info     ]     raise RetryRequest(error)  cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice
2023-01-04T04:39:18.373715Z [info     ] snowflake.connector.network.RetryRequest: 000403: HTTP 403: Forbidden cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice
2023-01-04T04:39:21.381681Z [info     ] time=2023-01-04 04:39:21 name=snowflake.connector.result_batch level=ERROR message=Failed to fetch the large result set batch data_2_1_1 for the 2 th time, backing off for 6s for the reason: '000403: HTTP 403: Forbidden' cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice
2023-01-04T04:39:21.381962Z [info     ] Traceback (most recent call last): cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice
2023-01-04T04:39:21.382123Z [info     ]   File "/project/.meltano/extractors/tap-snowflake/venv/lib/python3.9/site-packages/snowflake/connector/result_batch.py", line 314, in _download cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice
2023-01-04T04:39:21.382277Z [info     ]     raise RetryRequest(error)  cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice
2023-01-04T04:39:21.382421Z [info     ] snowflake.connector.network.RetryRequest: 000403: HTTP 403: Forbidden cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice
it goes on like that for about 1000 lines. 10 retries x 3 times (not sure why), and then the stack trace turns into this:
```2023-01-04T045637.575713Z [info ] time=2023-01-04 045637 name=tap_snowflake level=CRITICAL message=000403: HTTP 403: Forbidden cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice 2023-01-04T045637.575886Z [info ] Traceback (most recent call last): cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice 2023-01-04T045637.576041Z [info ] File "/project/.meltano/extractors/tap-snowflake/venv/lib/python3.9/site-packages/snowflake/connector/result_batch.py", line 314, in _download cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice 2023-01-04T045637.576164Z [info ] raise RetryRequest(error) cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice 2023-01-04T045637.576281Z [info ] snowflake.connector.network.RetryRequest: 000403: HTTP 403: Forbidden cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice 2023-01-04T045637.576396Z [info ] cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice 2023-01-04T045637.576509Z [info ] During handling of the above exception, another exception occurred: cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice 2023-01-04T045637.576629Z [info ] cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice 2023-01-04T045637.576741Z [info ] Traceback (most recent call last): cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice 2023-01-04T045637.576854Z [info ] File "/project/.meltano/extractors/tap-snowflake/venv/bin/tap-snowflake", line 8, in <module> cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice 2023-01-04T045637.576966Z [info ] sys.exit(main()) cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice 2023-01-04T045637.577078Z [info ] File "/project/.meltano/extractors/tap-snowflake/venv/lib/python3.9/site-packages/tap_snowflake/__init__.py", line 499, in main cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice 2023-01-04T045637.577190Z [info ] raise exc cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice 2023-01-04T045637.577301Z [info ] File "/project/.meltano/extractors/tap-snowflake/venv/lib/python3.9/site-packages/tap_snowflake/__init__.py", line 496, in main cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice 2023-01-04T045637.577412Z [info ] main_impl() cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice 2023-01-04T045637.577523Z [info ] File "/project/.meltano/extractors/tap-snowflake/venv/lib/python3.9/site-packages/tap_snowflake/__init__.py", line 485, in main_impl cmd_type=elb consumer=False name=tap-snowflake-sap-sales-invoice producer=True stdio=stderr string_id=tap-snowflake-sap-sales-invoice 2023-01-04T045637.577695Z [info ] do_sync(snowflake_conn, args.config, a…
Copy code
2023-01-04T04:56:57.701999Z [info     ] Writing state to Local Filesystem
2023-01-04T04:56:57.748806Z [info     ] Incremental state has been updated at 2023-01-04 04:56:57.748647.
2023-01-04T04:56:57.822838Z [info     ] time=2023-01-04 04:56:57 name=target_duckdb level=INFO message=Loading 5739 rows into 'analytics_sap."sales_invoice_v"' cmd_type=elb consumer=True name=target-duckdb-staging producer=False stdio=stderr string_id=target-duckdb-staging
2023-01-04T04:57:05.160649Z [info     ] Writing state to Local Filesystem
2023-01-04T04:57:05.199770Z [info     ] Incremental state has been updated at 2023-01-04 04:57:05.199593.
2023-01-04T04:57:06.570110Z [error    ] Extractor failed               
Traceback (most recent call last):
  File "/.venv/lib/python3.9/site-packages/meltano/core/logging/output_logger.py", line 201, in redirect_logging
    yield
  File "/.venv/lib/python3.9/site-packages/meltano/core/block/extract_load.py", line 461, in run
    await self.run_with_job()
  File "/.venv/lib/python3.9/site-packages/meltano/core/block/extract_load.py", line 487, in run_with_job
    await self.execute()
  File "/.venv/lib/python3.9/site-packages/meltano/core/block/extract_load.py", line 453, in execute
    await manager.run()
  File "/.venv/lib/python3.9/site-packages/meltano/core/block/extract_load.py", line 651, in run
    _check_exit_codes(
  File "/.venv/lib/python3.9/site-packages/meltano/core/block/extract_load.py", line 800, in _check_exit_codes
    raise RunnerError("Extractor failed", {PluginType.EXTRACTORS: producer_code})
meltano.core.runner.RunnerError: Extractor failed
2023-01-04T04:57:06.596007Z [error    ] Block run completed.           block_type=ExtractLoadBlocks err=RunnerError('Extractor failed') exit_codes={<PluginType.EXTRACTORS: 'extractors'>: 1} set_number=0 success=False
if i had to guess, snowflake access token for the connection expired 🤷
I would be open to use the meltanolabs variant of tap-snowflake if: 1. it supports incremental loading with replication key 2. i can resolve an issue loading bad data as strings into duckdb: there's a date column with incorrect format that throws an error when loading to duckdb - at the moment, this is resolved with inline stream mapping to fix formatting; alternatively, loading bad data as strings into duckdb and using dbt to fix formatting and typecast would be fine, as i'm using dbt anyway. that said, i understand stream mapping and batching are currently incompatible. i would like to use batch capability, as 
COPY INTO ...
is much more performant.
c
Hmm .. I couldn't comment on the authentication hypothesis ... I don't really have any hands on experience with Snowflake myself. Either Pat Nadolny or Derek Visch might have some insight.
cc @visch
This is the best I can find with a web search ... https://stackoverflow.com/q/67502234/6056177
Apparently it's a problem with the S3 signature that snowflake generates ...
p
Interesting. Good find. Is that something that needs to be addressed in 
tap-snowflake
?
c
I don't believe so. I can't find anything in Snowflake Python Connector library documentation that would somehow cater for this AWS signature issue. At best, the users of the Snowflake Python Connector library (i.e. tap-snowflake) could come up with some clunky workarounds for this behaviour. I'm not a Snowflake user though. So, take my comments with a grain of salt.
p
How does the retry behavior work? Is that baked into Singer, or Meltano? If the process is restarted, I think that would resolve the issue. In a production pipeline, I'll probably restart a container if 
meltano run
fails. Wonder if retry/restart behavior could be pushed down to Meltano?
c
I think the problem might be due to the client_session_keep_alive behaviour https://docs.snowflake.com/en/user-guide/python-connector-api.html#module-snowflake-connector
4 Views
Open in Slack
PreviousNext
Powered by