Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Source Chargebee: cannot sync transaction objects #17657

Closed
kevinyeung-3p opened this issue Oct 6, 2022 · 14 comments
Closed

Source Chargebee: cannot sync transaction objects #17657

kevinyeung-3p opened this issue Oct 6, 2022 · 14 comments
Assignees
@artem1205
Labels
autoteam community connectors/source/chargebee team/connectors-python type/bug Something isn't working

Comments

@kevinyeung-3p
Copy link

Environment

  • Airbyte version: 0.40.10
  • OS Version / Instance: both AWS EC2 using docker-compose and helm and k8s
  • Deployment: both docker and k8s
  • Source Connector and version: Chargebee 0.1.15
  • Destination Connector and version: Postgres 0.3.24
  • Step where error happened: Sync job

Current Behavior

Keep getting chargebee.api_error.InvalidRequestError and backoffs and never succeeded.

Expected Behavior

Syncs Chargebee transactions to a table.

Logs


2022-10-06 04:57:21 source > Backing off _send_request(...) for 90.0s (chargebee.api_error.InvalidRequestError: Sorry, unable to complete the operation due to db communication failure. Please try after some time)

2022-10-06 04:59:57 source > Sorry, unable to complete the operation due to db communication failure. Please try after some time

2022-10-06 04:59:57 source > Caught retryable error after 1 tries. Waiting 90 seconds then retrying...

2022-10-06 04:59:57 source > Backing off _send_request(...) for 180.0s (chargebee.api_error.InvalidRequestError: Sorry, unable to complete the operation due to db communication failure. Please try after some time)

2022-10-06 05:04:03 source > Sorry, unable to complete the operation due to db communication failure. Please try after some time

2022-10-06 05:04:03 source > Caught retryable error after 2 tries. Waiting 180 seconds then retrying...

2022-10-06 05:04:03 source > Backing off _send_request(...) for 360.0s (chargebee.api_error.InvalidRequestError: Sorry, unable to complete the operation due to db communication failure. Please try after some time)

2022-10-06 05:11:09 source > Sorry, unable to complete the operation due to db communication failure. Please try after some time

2022-10-06 05:11:09 source > Caught retryable error after 3 tries. Waiting 360 seconds then retrying...

2022-10-06 05:11:09 source > Backing off _send_request(...) for 720.0s (chargebee.api_error.InvalidRequestError: Sorry, unable to complete the operation due to db communication failure. Please try after some time)

Steps to Reproduce

  1. Set up Chargebee source connector
  2. Set up Postgres destination connector
  3. Sync transaction objects

Are you willing to submit a PR?

Yes, if there's guidance given.
@kevinyeung-3p kevinyeung-3p added needs-triage type/bug Something isn't working labels Oct 6, 2022
@sh4sh
Copy link
Contributor

sh4sh commented Oct 6, 2022

Hey @kevinyeung-3p, could you provide the complete logs from when this happened in case there is useful information before or after this snippet?

@sh4sh
Copy link
Contributor

sh4sh commented Oct 6, 2022

I was not able to reproduce this issue - can you confirm that your other connections are syncing successfully?

@kevinyeung-3p
Copy link
Author

Hi @sh4sh , thanks for your reply. I've added more log lines surround the error. Meanwhile, I'll also try syncing transaction alone without other objects, although it's not going to help me much even if succeeds but hopefully that will be signals to you.

2022-10-06 04:44:59 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 343000 (517 MB)
2022-10-06 04:45:27 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 344000 (518 MB)
2022-10-06 04:45:55 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 345000 (519 MB)
2022-10-06 04:46:06 destination > Flushing subscription: 7941 records (24 MB)
2022-10-06 04:46:23 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 346000 (519 MB)
2022-10-06 04:46:51 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 347000 (520 MB)
2022-10-06 04:47:18 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 348000 (521 MB)
2022-10-06 04:47:44 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 349000 (522 MB)
2022-10-06 04:48:11 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 350000 (522 MB)
2022-10-06 04:48:35 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 351000 (523 MB)
2022-10-06 04:49:05 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 352000 (524 MB)
2022-10-06 04:49:32 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 353000 (525 MB)
2022-10-06 04:50:00 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 354000 (526 MB)
2022-10-06 04:49:43 destination > Flushing subscription: 7878 records (24 MB)
2022-10-06 04:50:26 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 355000 (526 MB)
2022-10-06 04:50:52 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 356000 (527 MB)
2022-10-06 04:51:20 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 357000 (528 MB)
2022-10-06 04:51:46 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 358000 (529 MB)
2022-10-06 04:52:12 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 359000 (530 MB)
2022-10-06 04:52:37 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 360000 (530 MB)
2022-10-06 04:53:04 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 361000 (531 MB)
2022-10-06 04:53:12 destination > Flushing subscription: 7854 records (24 MB)
2022-10-06 04:53:31 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 362000 (532 MB)
2022-10-06 04:53:58 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 363000 (533 MB)
2022-10-06 04:54:23 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 364000 (533 MB)
2022-10-06 04:54:50 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 365000 (534 MB)
2022-10-06 04:55:17 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 366000 (535 MB)
2022-10-06 04:55:44 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 367000 (536 MB)
2022-10-06 04:56:11 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):352 - Records read: 368000 (537 MB)
2022-10-06 04:56:15 source > Read 139165 records from subscription stream
2022-10-06 04:56:15 source > Finished syncing subscription
2022-10-06 04:56:15 source > SourceChargebee runtimes:
Syncing stream credit_note 0:05:35.894270
Syncing stream invoice 1:06:36.107182
Syncing stream subscription 1:03:26.516163
2022-10-06 04:56:15 source > Syncing stream: transaction 
2022-10-06 04:57:21 source > Backing off _send_request(...) for 90.0s (chargebee.api_error.InvalidRequestError: Sorry, unable to complete the operation due to db communication failure. Please try after some time)
2022-10-06 04:59:57 source > Sorry, unable to complete the operation due to db communication failure. Please try after some time
2022-10-06 04:59:57 source > Caught retryable error after 1 tries. Waiting 90 seconds then retrying...
2022-10-06 04:59:57 source > Backing off _send_request(...) for 180.0s (chargebee.api_error.InvalidRequestError: Sorry, unable to complete the operation due to db communication failure. Please try after some time)
2022-10-06 05:04:03 source > Sorry, unable to complete the operation due to db communication failure. Please try after some time
2022-10-06 05:04:03 source > Caught retryable error after 2 tries. Waiting 180 seconds then retrying...
2022-10-06 05:04:03 source > Backing off _send_request(...) for 360.0s (chargebee.api_error.InvalidRequestError: Sorry, unable to complete the operation due to db communication failure. Please try after some time)
2022-10-06 05:11:09 source > Sorry, unable to complete the operation due to db communication failure. Please try after some time
2022-10-06 05:11:09 source > Caught retryable error after 3 tries. Waiting 360 seconds then retrying...
2022-10-06 05:11:09 source > Backing off _send_request(...) for 720.0s (chargebee.api_error.InvalidRequestError: Sorry, unable to complete the operation due to db communication failure. Please try after some time)
2022-10-06 05:24:11 source > Sorry, unable to complete the operation due to db communication failure. Please try after some time
2022-10-06 05:24:11 source > Caught retryable error after 4 tries. Waiting 720 seconds then retrying...
2022-10-06 05:24:11 source > Backing off _send_request(...) for 1440.0s (chargebee.api_error.InvalidRequestError: Sorry, unable to complete the operation due to db communication failure. Please try after some time)
2022-10-06 05:49:17 source > Sorry, unable to complete the operation due to db communication failure. Please try after some time
2022-10-06 05:49:17 source > Caught retryable error after 5 tries. Waiting 1440 seconds then retrying...
2022-10-06 05:49:17 source > Backing off _send_request(...) for 2880.0s (chargebee.api_error.InvalidRequestError: Sorry, unable to complete the operation due to db communication failure. Please try after some time)
2022-10-06 06:38:23 source > Sorry, unable to complete the operation due to db communication failure. Please try after some time
2022-10-06 06:38:23 source > Caught retryable error after 6 tries. Waiting 2880 seconds then retrying...
2022-10-06 06:38:23 source > Backing off _send_request(...) for 5760.0s (chargebee.api_error.InvalidRequestError: Sorry, unable to complete the operation due to db communication failure. Please try after some time)
2022-10-06 08:15:29 source > Sorry, unable to complete the operation due to db communication failure. Please try after some time
2022-10-06 08:15:29 source > Caught retryable error after 7 tries. Waiting 5760 seconds then retrying...
2022-10-06 08:15:29 source > Backing off _send_request(...) for 11520.0s (chargebee.api_error.InvalidRequestError: Sorry, unable to complete the operation due to db communication failure. Please try after some time)
2022-10-06 11:28:35 source > Sorry, unable to complete the operation due to db communication failure. Please try after some time
2022-10-06 11:28:35 source > Caught retryable error after 8 tries. Waiting 11520 seconds then retrying...
2022-10-06 11:28:35 source > Backing off _send_request(...) for 23040.0s (chargebee.api_error.InvalidRequestError: Sorry, unable to complete the operation due to db communication failure. Please try after some time)
2022-10-06 17:53:41 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):355 - Source has no more messages, closing connection.
2022-10-06 17:53:41 source > Sorry, unable to complete the operation due to db communication failure. Please try after some time
2022-10-06 17:53:42 INFO i.a.w.p.KubePodProcess(close):737 - (pod: airbyte / source-chargebee-read-1-0-qqmqm) - Closed all resources for pod
2022-10-06 17:53:42 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):363 - Total records read: 368251 (537 MB)
2022-10-06 17:53:42 WARN i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$5):366 - Schema validation errors found for stream credit_note. Error messages: [$.reason_code is of an incorrect type.]
2022-10-06 17:53:42 WARN i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$5):366 - Schema validation errors found for stream invoice. Error messages: [$.status is of an incorrect type.]
2022-10-06 17:53:42 INFO i.a.w.g.DefaultReplicationWorker(run):182 - One of source or destination thread complete. Waiting on the other.
2022-10-06 17:54:19 INFO i.a.w.g.DefaultReplicationWorker(lambda$getDestinationOutputRunnable$7):445 - State in DefaultReplicationWorker from destination: io.airbyte.protocol.models.AirbyteMessage@2f9ded77[type=STATE,log=<null>,spec=<null>,connectionStatus=<null>,catalog=<null>,record=<null>,state=io.airbyte.protocol.models.AirbyteStateMessage@4ddaacc3[type=STREAM,stream=io.airbyte.protocol.models.AirbyteStreamState@56f0750b[streamDescriptor=io.airbyte.protocol.models.StreamDescriptor@51b8995[name=credit_note,namespace=<null>,additionalProperties={}],streamState={"updated_at":1665024035},additionalProperties={}],global=<null>,data={"credit_note":{"updated_at":1665024035}},additionalProperties={}],trace=<null>,additionalProperties={}]
2022-10-06 17:54:19 INFO i.a.w.g.DefaultReplicationWorker(lambda$getDestinationOutputRunnable$7):445 - State in DefaultReplicationWorker from destination: io.airbyte.protocol.models.AirbyteMessage@4309750f[type=STATE,log=<null>,spec=<null>,connectionStatus=<null>,catalog=<null>,record=<null>,state=io.airbyte.protocol.models.AirbyteStateMessage@60035a2a[type=STREAM,stream=io.airbyte.protocol.models.AirbyteStreamState@d5b0feb[streamDescriptor=io.airbyte.protocol.models.StreamDescriptor@297f7db1[name=invoice,namespace=<null>,additionalProperties={}],streamState={"updated_at":1665028326},additionalProperties={}],global=<null>,data={"credit_note":{"updated_at":1665024035},"invoice":{"updated_at":1665028326}},additionalProperties={}],trace=<null>,additionalProperties={}]
2022-10-06 17:54:19 INFO i.a.w.g.DefaultReplicationWorker(lambda$getDestinationOutputRunnable$7):445 - State in DefaultReplicationWorker from destination: io.airbyte.protocol.models.AirbyteMessage@e0f7045[type=STATE,log=<null>,spec=<null>,connectionStatus=<null>,catalog=<null>,record=<null>,state=io.airbyte.protocol.models.AirbyteStateMessage@5ccf06c0[type=STREAM,stream=io.airbyte.protocol.models.AirbyteStreamState@4b2a4be1[streamDescriptor=io.airbyte.protocol.models.StreamDescriptor@60bb50ba[name=subscription,namespace=<null>,additionalProperties={}],streamState={"updated_at":1665032162},additionalProperties={}],global=<null>,data={"credit_note":{"updated_at":1665024035},"invoice":{"updated_at":1665028326},"subscription":{"updated_at":1665032162}},additionalProperties={}],trace=<null>,additionalProperties={}]
2022-10-06 17:54:19 INFO i.a.w.g.DefaultReplicationWorker(lambda$getDestinationOutputRunnable$7):445 - State in DefaultReplicationWorker from destination: io.airbyte.protocol.models.AirbyteMessage@28f2545f[type=STATE,log=<null>,spec=<null>,connectionStatus=<null>,catalog=<null>,record=<null>,state=io.airbyte.protocol.models.AirbyteStateMessage@1276ef7b[type=STREAM,stream=io.airbyte.protocol.models.AirbyteStreamState@1b717a8c[streamDescriptor=io.airbyte.protocol.models.StreamDescriptor@590bd538[name=transaction,namespace=<null>,additionalProperties={}],streamState={},additionalProperties={}],global=<null>,data={"credit_note":{"updated_at":1665024035},"invoice":{"updated_at":1665028326},"subscription":{"updated_at":1665032162},"transaction":{}},additionalProperties={}],trace=<null>,additionalProperties={}]
2022-10-06 17:54:20 INFO i.a.w.p.KubePodProcess(close):737 - (pod: airbyte / destination-postgres-write-1-0-cvlnz) - Closed all resources for pod
2022-10-06 17:54:20 INFO i.a.w.g.DefaultReplicationWorker(run):184 - Source and destination threads complete.
2022-10-06 17:54:20 INFO i.a.w.g.DefaultReplicationWorker(run):279 - Source output at least one state message
2022-10-06 17:54:20 INFO i.a.w.g.DefaultReplicationWorker(run):285 - State capture: Updated state to: Optional[io.airbyte.config.State@50129195[state=[{"type":"STREAM","stream":{"stream_descriptor":{"name":"credit_note"},"stream_state":{"updated_at":1665024035}},"data":{"credit_note":{"updated_at":1665024035}}},{"type":"STREAM","stream":{"stream_descriptor":{"name":"transaction"},"stream_state":{}},"data":{"credit_note":{"updated_at":1665024035},"invoice":{"updated_at":1665028326},"subscription":{"updated_at":1665032162},"transaction":{}}},{"type":"STREAM","stream":{"stream_descriptor":{"name":"subscription"},"stream_state":{"updated_at":1665032162}},"data":{"credit_note":{"updated_at":1665024035},"invoice":{"updated_at":1665028326},"subscription":{"updated_at":1665032162}}},{"type":"STREAM","stream":{"stream_descriptor":{"name":"invoice"},"stream_state":{"updated_at":1665028326}},"data":{"credit_note":{"updated_at":1665024035},"invoice":{"updated_at":1665028326}}}]]]
2022-10-06 17:54:20 INFO i.a.w.g.DefaultReplicationWorker(run):300 - sync summary: {
  "status" : "completed",
  "recordsSynced" : 364603,
  "bytesSynced" : 563400670,
  "startTime" : 1665024030441,
  "endTime" : 1665078860103,
  "totalStats" : {
    "recordsEmitted" : 364603,
    "bytesEmitted" : 563400670,
    "sourceStateMessagesEmitted" : 3648,
    "destinationStateMessagesEmitted" : 4,
    "recordsCommitted" : 364603,
    "meanSecondsBeforeSourceStateMessageEmitted" : 46646,
    "maxSecondsBeforeSourceStateMessageEmitted" : 46646,
    "maxSecondsBetweenStateMessageEmittedandCommitted" : 54818,
    "meanSecondsBetweenStateMessageEmittedandCommitted" : 39956
  },
  "streamStats" : [ {
    "streamName" : "credit_note",
    "stats" : {
      "recordsEmitted" : 16681,
      "bytesEmitted" : 27730701,
      "recordsCommitted" : 16681
    }
  }, {
    "streamName" : "invoice",
    "stats" : {
      "recordsEmitted" : 208757,
      "bytesEmitted" : 418994370,
      "recordsCommitted" : 208757
    }
  }, {
    "streamName" : "subscription",
    "stats" : {
      "recordsEmitted" : 139165,
      "bytesEmitted" : 116675599,
      "recordsCommitted" : 139165
    }
  } ]
}
2022-10-06 17:54:20 INFO i.a.w.g.DefaultReplicationWorker(run):301 - failures: [ ]
2022-10-06 17:54:20 INFO i.a.w.t.TemporalAttemptExecution(get):134 - Stopping cancellation check scheduling...
2022-10-06 17:54:20 INFO i.a.c.i.LineGobbler(voidCall):114 - 
2022-10-06 17:54:20 INFO i.a.c.i.LineGobbler(voidCall):114 - ----- END REPLICATION -----
2022-10-06 17:54:20 INFO i.a.c.i.LineGobbler(voidCall):114 -

@kevinyeung-3p
Copy link
Author

I was not able to reproduce this issue - can you confirm that your other connections are syncing successfully?

MySQL to Postgres, also Salesforce to Postgres sync beautifully.

@kevinyeung-3p
Copy link
Author

kevinyeung-3p commented Oct 7, 2022 •
edited
Loading

Just an update. I changed my Chargebee source setting start date to 2022-10-01T00:00:00Z and it worked. Once I reverted it to 2022-07-01T00:00:00Z it stops working. In fact, it seems beyond a certain date Chargebee stops working:

2022-10-01T00:00:00Z - works
2022-09-30T00:00:00Z - works
2022-09-28T00:00:00Z - does not work
2022-09-01T00:00:00Z - does not work
2022-07-01T00:00:00Z - does not work

@sh4sh
Copy link
Contributor

sh4sh commented Oct 12, 2022

@kevinyeung-3p Very weird, I tried with those dates and earlier, all the way back to 2021 but it seems to work fine for my Chargebee data. It sounds like their database is not providing this data for some reason, could you open a support ticket with them to see if they can take a look?

@marcosmarxm marcosmarxm changed the title Cannot sync Chargebee transaction objects Source Chargebee: cannot sync transaction objects Nov 30, 2022
@vmendi
Copy link

vmendi commented Dec 9, 2022

@kevinyeung-3p We are seeing the same, but in our case not even 2022-12-01 works. We'll also open a support ticket with them, but I would appreciate if any known workaround was shared here.

@vmendi
Copy link

vmendi commented Dec 9, 2022

I wrote a quick Python program to test the transaction/ endpoint and see if the problem reproduces but it doesn't. This makes me think that the connector is sending something that makes the Chargebee server trip over.

@vmendi
Copy link

vmendi commented Dec 9, 2022 •
edited
Loading

I've been able to reproduce the issue. It happens because the connector sends:

'sort_by[asc]': 'date'

instead of:

'sort_by[asc]': 'updated_at'.

Line 310 in streams.py harcodes the sort_field to date:

airbyte/airbyte-integrations/connectors/source-chargebee/source_chargebee/streams.py

Line 310 in a3c00fa

params["sort_by[asc]"] = "date"

It was introduced in this PR by @mustangJaro:
#14672

Why do we need that particular line? Let me explain:

By default sort_field is assigned here:

airbyte/airbyte-integrations/connectors/source-chargebee/source_chargebee/streams.py

Line 171 in a3c00fa

params["sort_by[asc]"] = self.cursor_field

And this assignment seems to me the only thing we should do. The default cursor_field for Transactions is 'updated_at', which works well (doesn't make Chargebee's server to freak out) for the sort[asc] parameter.

@vmendi
Copy link

vmendi commented Dec 9, 2022

@sh4sh I don't understand why in your case it's working.

If I might ask, what version of the connector are you using?
Did you change the default cursor_field from 'updated_at' to something else?

@mustangJaro
Copy link
Contributor

I have no issues with changing this again. I struggled to find the proper fields in Chargebees documentation. If you found the 'updated-at' field then that's fantastic news!

@vmendi
Copy link

vmendi commented Dec 9, 2022

Hi @mustangJaro I think the right thing to do is to let line 171 do its job and remove line 310. What do you think?

@vmendi
Copy link

vmendi commented Dec 20, 2022

I removed line 310 and rebuilt the container in our self-hosted deployment, and the connector has been working for > 1 week with no issues.

I wonder what the intention of the original author with that line was. I bet that the issue is that there's no "updated_at" field for dates before 2016, and that's why the sort field had to be hardcoded to "created_at" or "date".

@artem1205
Copy link
Collaborator

Fixed in #21688

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@artem1205 artem1205

Labels
autoteam community connectors/source/chargebee team/connectors-python type/bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
7 participants
@vmendi @marcosmarxm @sh4sh @mustangJaro @artem1205 @kevinyeung-3p @octavia-squidington-iv