Error status but can't find the actual error

[FionaYiZhao]

Hi team,

Our SFMC extract was reported in error states for many days. This morning it turned to normal, we didn't actually do or change anything. We are trying to understand the cause of the errors. Could anybody help here? Attached is one of the log (truncated some middle session):

2021-09-11 02:48:39,022Z main - INFO Running tap-exacttarget version 1.6.1 and target-stitch version 3.2.0
2021-09-11 02:48:40,204Z main - INFO [smart-services] building smart service producer: topic( com.stitchdata.extractionJobStarted ), use_ssl( true )
2021-09-11 02:48:40,208Z main - INFO [smart-services] building smart service producer: topic( com.stitchdata.extractionJobFinished ), use_ssl( true )
2021-09-11 02:48:40,209Z main - INFO [smart-services] building smart service producer: topic( com.stitchdata.streamRecordCount ), use_ssl( true )
2021-09-11 02:48:41,211Z main - INFO [smart-services] event successfully sent to kafka: com.stitchdata.extractionJobStarted [24] at offset None
2021-09-11 02:48:41,214Z main - INFO Starting tap to discover schemas: tap-env/bin/tap-exacttarget --config /tmp/tap_discover_config.json --discover
2021-09-11 02:48:41,607Z tap - INFO Starting discovery.
2021-09-11 02:48:41,608Z tap - INFO Generating auth stub...
2021-09-11 02:48:41,608Z tap - INFO Authentication URL is: https://XXXXX.auth.marketingcloudapis.com/v1/requestToken
2021-09-11 02:48:41,608Z tap - INFO Trying to authenticate using V1 endpoint
2021-09-11 02:48:42,042Z tap - INFO Failed to auth using V1 endpoint
2021-09-11 02:48:42,042Z tap - INFO Trying to authenticate using V2 endpoint
2021-09-11 02:48:42,042Z tap - INFO Authentication URL is: https://XXXX.auth.marketingcloudapis.com
2021-09-11 02:48:42,857Z tap - INFO Success.
2021-09-11 02:48:42,858Z tap - INFO Making RETRIEVE call to 'DataExtension' endpoint with no filters.
2021-09-11 02:48:45,602Z tap - INFO Getting more results from 'DataExtension' endpoint
2021-09-11 02:48:46,200Z tap - INFO Fetched 311 results from 'DataExtension' endpoint
2021-09-11 02:48:46,202Z tap - INFO Done retrieving results from 'DataExtension' endpoint
2021-09-11 02:48:46,203Z tap - INFO Making RETRIEVE call to 'DataExtensionField' endpoint with no filters.
2021-09-11 02:49:05,197Z tap - INFO Getting more results from 'DataExtensionField' endpoint
2021-09-11 02:49:23,594Z tap - INFO Fetched 2500 results from 'DataExtensionField' endpoint
.....
data_extension.PROD_Newsletter_September_2018_Cancelled_B (tap_stream_id: data_extension.846EB774-70DD-41F6-AAE2-6BDC0A48049E)
................................
2021-09-11 04:59:04,841Z tap - INFO Making RETRIEVE call to 'sent' endpoint with filters '{'Property': 'EventDate', 'SimpleOperator': 'between', 'Value': ['2008-08-31T00:30:00Z', '2008-08-31T00:40:00Z']}'.
2021-09-11 05:00:35,262Z tap - ERROR The read operation timed out
2021-09-11 05:00:35,262Z tap - Traceback (most recent call last):
2021-09-11 05:00:35,262Z tap - File "/code/orchestrator/tap-env/lib/python3.5/site-packages/tap_exacttarget/init.py", line 136, in do_sync
2021-09-11 05:00:35,262Z tap - stream_accessor.sync()
2021-09-11 05:00:35,263Z tap - File "/code/orchestrator/tap-env/lib/python3.5/site-packages/tap_exacttarget/dao.py", line 74, in sync
2021-09-11 05:00:35,263Z tap - return self.sync_data()
2021-09-11 05:00:35,263Z tap - File "/code/orchestrator/tap-env/lib/python3.5/site-packages/tap_exacttarget/endpoints/events.py", line 90, in sync_data
2021-09-11 05:00:35,263Z tap - for event in stream:
2021-09-11 05:00:35,263Z tap - File "/code/orchestrator/tap-env/lib/python3.5/site-packages/tap_exacttarget/client.py", line 139, in request_from_cursor
2021-09-11 05:00:35,263Z tap - response = cursor.get()
2021-09-11 05:00:35,263Z tap - File "/code/orchestrator/tap-env/lib/python3.5/site-packages/FuelSDK/rest.py", line 303, in get
2021-09-11 05:00:35,263Z tap - obj = ET_Get(self.auth_stub, self.obj_type, props, search_filter, options)
2021-09-11 05:00:35,263Z tap - File "/code/orchestrator/tap-env/lib/python3.5/site-packages/FuelSDK/rest.py", line 203, in init
2021-09-11 05:00:35,263Z tap - response = auth_stub.soap_client.service.Retrieve(ws_retrieveRequest)
2021-09-11 05:00:35,263Z tap - File "/code/orchestrator/tap-env/lib/python3.5/site-packages/suds/client.py", line 521, in call
2021-09-11 05:00:35,263Z tap - return client.invoke(args, kwargs)
2021-09-11 05:00:35,263Z tap - File "/code/orchestrator/tap-env/lib/python3.5/site-packages/suds/client.py", line 581, in invoke
2021-09-11 05:00:35,263Z tap - result = self.send(soapenv)
2021-09-11 05:00:35,263Z tap - File "/code/orchestrator/tap-env/lib/python3.5/site-packages/suds/client.py", line 613, in send
2021-09-11 05:00:35,263Z tap - reply = self.options.transport.send(request)
2021-09-11 05:00:35,263Z tap - File "/code/orchestrator/tap-env/lib/python3.5/site-packages/suds/transport/https.py", line 66, in send
2021-09-11 05:00:35,263Z tap - return HttpTransport.send(self, request)
2021-09-11 05:00:35,263Z tap - File "/code/orchestrator/tap-env/lib/python3.5/site-packages/suds/transport/http.py", line 82, in send
2021-09-11 05:00:35,264Z tap - fp = self.u2open(u2request)
2021-09-11 05:00:35,264Z main - INFO State update: changing bookmarks.bounce.last_record from "2021-09-11T03:32:51Z" to "2021-09-11T04:52:51Z"
2021-09-11 05:00:35,264Z tap - File "/code/orchestrator/tap-env/lib/python3.5/site-packages/suds/transport/http.py", line 132, in u2open
2021-09-11 05:00:35,265Z tap - return url.open(u2request, timeout=tm)
2021-09-11 05:00:35,265Z tap - File "/root/.pyenv/versions/3.5.2/lib/python3.5/urllib/request.py", line 466, in open
2021-09-11 05:00:35,266Z tap - response = self._open(req, data)
2021-09-11 05:00:35,266Z tap - File "/root/.pyenv/versions/3.5.2/lib/python3.5/urllib/request.py", line 484, in _open
2021-09-11 05:00:35,266Z tap - '_open', req)
2021-09-11 05:00:35,266Z tap - File "/root/.pyenv/versions/3.5.2/lib/python3.5/urllib/request.py", line 444, in _call_chain
2021-09-11 05:00:35,266Z tap - result = func(*args)
2021-09-11 05:00:35,266Z tap - File "/root/.pyenv/versions/3.5.2/lib/python3.5/urllib/request.py", line 1297, in https_open
2021-09-11 05:00:35,266Z tap - context=self._context, check_hostname=self._check_hostname)
2021-09-11 05:00:35,266Z tap - File "/root/.pyenv/versions/3.5.2/lib/python3.5/urllib/request.py", line 1257, in do_open
2021-09-11 05:00:35,266Z tap - r = h.getresponse()
2021-09-11 05:00:35,266Z tap - File "/root/.pyenv/versions/3.5.2/lib/python3.5/http/client.py", line 1197, in getresponse
2021-09-11 05:00:35,267Z tap - response.begin()
2021-09-11 05:00:35,267Z tap - File "/root/.pyenv/versions/3.5.2/lib/python3.5/http/client.py", line 297, in begin
2021-09-11 05:00:35,267Z tap - version, status, reason = self._read_status()
2021-09-11 05:00:35,267Z tap - File "/root/.pyenv/versions/3.5.2/lib/python3.5/http/client.py", line 258, in _read_status
2021-09-11 05:00:35,267Z tap - line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
2021-09-11 05:00:35,267Z tap - File "/root/.pyenv/versions/3.5.2/lib/python3.5/socket.py", line 575, in readinto
2021-09-11 05:00:35,267Z tap - return self._sock.recv_into(b)
2021-09-11 05:00:35,267Z tap - File "/root/.pyenv/versions/3.5.2/lib/python3.5/ssl.py", line 929, in recv_into
2021-09-11 05:00:35,267Z tap - return self.read(nbytes, buffer)
2021-09-11 05:00:35,267Z tap - File "/root/.pyenv/versions/3.5.2/lib/python3.5/ssl.py", line 791, in read
2021-09-11 05:00:35,267Z tap - return self._sslobj.read(len, buffer)
2021-09-11 05:00:35,267Z tap - File "/root/.pyenv/versions/3.5.2/lib/python3.5/ssl.py", line 575, in read
2021-09-11 05:00:35,267Z tap - v = self._sslobj.read(len, buffer)
2021-09-11 05:00:35,267Z tap - socket.timeout: The read operation timed out
2021-09-11 05:00:35,267Z tap - ERROR Failed to sync endpoint, moving on!
2021-09-11 05:00:35,267Z tap - INFO Syncing stream folder with accessor FolderDataAccessObject
2021-09-11 05:00:35,267Z tap - INFO Making RETRIEVE call to 'Folder' endpoint with filters '{'Property': 'ModifiedDate', 'SimpleOperator': 'greaterThan', 'Value': '2021-09-09T14:09:07Z'}'.
2021-09-11 05:00:35,827Z tap - INFO Done retrieving results from 'Folder' endpoint
2021-09-11 05:00:35,828Z tap - INFO Updating state.
2021-09-11 05:00:35,828Z tap - INFO Syncing stream list with accessor ListDataAccessObject
2021-09-11 05:00:35,828Z target - INFO Serializing batch with 2 messages for table folder
2021-09-11 05:00:35,828Z target - INFO Sending batch of 3193 bytes to https://api.stitchdata.com/v2/import/batch
2021-09-11 05:00:35,829Z tap - INFO Making RETRIEVE call to 'List' endpoint with filters '{'Property': 'ModifiedDate', 'SimpleOperator': 'greaterThan', 'Value': '2020-11-24T13:34:27Z'}'.
2021-09-11 05:00:35,836Z target - INFO [smart-services] event successfully sent to kafka: com.stitchdata.streamRecordCount [0] at offset None
2021-09-11 05:00:35,836Z target - INFO replicated 2 records from "folder" endpoint
2021-09-11 05:00:36,276Z tap - INFO Done retrieving results from 'List' endpoint
...............
2021-09-11 05:17:42,616Z target - INFO replicated 177 records from "list_subscriber" endpoint
2021-09-11 05:17:42,616Z target - INFO Serializing batch with 177 messages for table subscriber
2021-09-11 05:17:42,616Z target - INFO Sending batch of 55479 bytes to https://api.stitchdata.com/v2/import/batch
2021-09-11 05:17:42,622Z target - INFO [smart-services] event successfully sent to kafka: com.stitchdata.streamRecordCount [4] at offset None
2021-09-11 05:17:42,622Z target - INFO replicated 177 records from "subscriber" endpoint
2021-09-11 05:17:45,247Z tap - INFO Done retrieving results from 'Send' endpoint
2021-09-11 05:17:45,248Z tap - INFO Updating state.
2021-09-11 05:17:45,249Z tap - INFO Updating state.
2021-09-11 05:17:45,249Z tap - INFO Run failed, exiting.
2021-09-11 05:17:45,481Z target - INFO Serializing batch with 122 messages for table send
2021-09-11 05:17:45,482Z target - INFO Sending batch of 94967 bytes to https://api.stitchdata.com/v2/import/batch
2021-09-11 05:17:45,490Z target - INFO [smart-services] event successfully sent to kafka: com.stitchdata.streamRecordCount [1] at offset None
2021-09-11 05:17:45,490Z target - INFO replicated 122 records from "send" endpoint
2021-09-11 05:17:45,597Z main - INFO State update: changing bookmarks.send.last_record from "2021-09-10T20:26:20Z" to "2021-09-10T23:17:33Z"
2021-09-11 05:17:45,599Z target - INFO Requests complete, stopping loop
2021-09-11 05:17:45,651Z main - INFO Target exited normally with status 0
2021-09-11 05:17:46,847Z main - INFO [smart-services] event successfully sent to kafka: com.stitchdata.extractionJobFinished [0] at offset None
2021-09-11 05:17:46,848Z main - INFO No tunnel subprocess to tear down
2021-09-11 05:17:46,848Z main - INFO Exit status is: Discovery succeeded. Tap failed with code 1. Target succeeded.

[KolinMboorom]

+1

[shedd]

We have also been seeing errors. In general, we've always seen a range of errors from this tap for the DataExtension table replications, however, the sync was generally able to complete. However, starting on the 14th, these errors caused the entire sync to die prematurely. We've had to not replicate our DataExtension tables to get the sync to complete. To our knowledge, nothing has changed with in the Marketing Cloud account.

[FionaYiZhao]

actually the error came back. but I do see tables got updated in our BQ destination..

…

On Fri, Sep 17, 2021 at 1:20 PM Robert Shedd ***@***.***> wrote: We have also been seeing errors. In general, we've always seen a range of errors from this tap for the DataExtension table replications, however, the sync was generally able to complete. However, starting on the 14th, these errors caused the entire sync to die prematurely. We've had to not replicate our DataExtension tables to get the sync to complete. To our knowledge, nothing has changed with in the Marketing Cloud account. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#69 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ARN5BL42X4KKRWSTH6HAPNTUCN2GTANCNFSM5EHJX4UA> . Triage notifications on the go with GitHub Mobile for iOS <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> or Android <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>.

[ekselan]

We've just started replicating tables from SFMC using Stitch, and running into a similar issue. The latest email from Stitch regarding errors had a blank space where the error should be ...

We're not replicating any of the data_extension tables but still see data_extension referenced in the logs - is that normal?

Some tables are replicating into our warehouse, but not the email or campaign tables, and I've been unable to identify the cause. Looks like there aren't any known workarounds for this?

[rdeshmukh15]

@FionaYiZhao and @shedd: Are you still facing this issue?

[kayamsmith]

We are still facing this issue.

[kayamsmith]

Additionally we started getting a a new error today as well:

Full logs:

2022-12-07 21:57:01,781Z    tap - CRITICAL 'metadata'
2022-12-07 21:57:01,785Z    tap - Traceback (most recent call last):
2022-12-07 21:57:01,785Z    tap -   File "tap-env/bin/tap-exacttarget", line 33, in <module>
2022-12-07 21:57:01,785Z    tap -     sys.exit(load_entry_point('tap-exacttarget==1.7.1', 'console_scripts', 'tap-exacttarget')())
2022-12-07 21:57:01,786Z    tap -   File "/code/orchestrator/tap-env/lib/python3.5/site-packages/singer/utils.py", line 229, in wrapped
2022-12-07 21:57:01,786Z    tap -     return fnc(*args, **kwargs)
2022-12-07 21:57:01,786Z    tap -   File "/code/orchestrator/tap-env/lib/python3.5/site-packages/tap_exacttarget/__init__.py", line 168, in main
2022-12-07 21:57:01,786Z    tap -     do_discover(args)
2022-12-07 21:57:01,786Z    tap -   File "/code/orchestrator/tap-env/lib/python3.5/site-packages/tap_exacttarget/__init__.py", line 70, in do_discover
2022-12-07 21:57:01,786Z    tap -     catalog += stream_accessor.generate_catalog()
2022-12-07 21:57:01,786Z    tap -   File "/code/orchestrator/tap-env/lib/python3.5/site-packages/tap_exacttarget/endpoints/data_extensions.py", line 229, in generate_catalog
2022-12-07 21:57:01,786Z    tap -     extensions_catalog_with_fields = self._get_fields(extensions_catalog)
2022-12-07 21:57:01,786Z    tap -   File "/code/orchestrator/tap-env/lib/python3.5/site-packages/backoff/_sync.py", line 94, in retry
2022-12-07 21:57:01,786Z    tap -     ret = target(*args, **kwargs)
2022-12-07 21:57:01,786Z    tap -   File "/code/orchestrator/tap-env/lib/python3.5/site-packages/tap_exacttarget/dao.py", line 44, in wrapper
2022-12-07 21:57:01,786Z    tap -     return fnc(*args, **kwargs)
2022-12-07 21:57:01,786Z    tap -   File "/code/orchestrator/tap-env/lib/python3.5/site-packages/tap_exacttarget/endpoints/data_extensions.py", line 187, in _get_fields
2022-12-07 21:57:01,786Z    tap -     to_return[extension_id]['metadata'].append({
2022-12-07 21:57:01,786Z    tap - KeyError: 'metadata'
2022-12-07 21:57:02,467Z   main - INFO Tap exited abnormally with status 1
2022-12-07 21:57:03,878Z   main - INFO [smart-services] event successfully sent to kafka: com.stitchdata.extractionJobFinished [42] at offset None
2022-12-07 21:57:03,883Z   main - INFO No tunnel subprocess to tear down
2022-12-07 21:57:03,883Z   main - INFO Exit status is: Discovery failed with code 1 and error message: "'metadata'".