Resolve deadlocks in CAP Node.JS app

[carlonnheim]

Hi,

I am having issues with deadlocks when processing Event Mesh messages in a CAP Node.js application. We have the following context:

• A single queue is receiving frequent messages
• The queue emits 10 concurrent messages to increase throughput
• The queue will retry each message 3 times, since our scenarios often have transient errors

This runs fine most of the time, but I run into deadlocks if/when the error rate increases. We are in essence doing this:

messaging.on('sometopic', async (msg) => {
//... our stuff which locks certain db resources and may throw errors
//... we do not make any "cds.tx" handling or so (done by the framework to our understanding)
});

We can see the locks in the database monitor when it stalls, looking like this:

What surprises me is that there is an idle session which blocks the ones trying to lock an actual resource. I am suspecting that I am somehow preventing one message processing attempt from cleaning up before the retry comes in and tries to lock the same resources.

Is there a way to trace from e.g. the Logical Connection ID (marked 239984 in the scenario above) to which cds transaction it is that started it?

Hoping somebody has advice on how to isolate the root cause in this situation.

Thanks!

//Carl

[david_kunz2]

Hi onnheimc ,

Thanks for reporting this issue!

I think it would be helpful if you could log the database statements which are sent to the database.
You can enable them by setting the environment variable DEBUG=hana.

In your handlers, it is sufficient to write await INSERT.into(xxx) or await SELECT.from(xxx) without cds.tx(msg), we will automatically commit the statements when all handlers are successfully executed. But we should make sure that this is indeed happening by looking at the logs.

Thanks and best regards,
David

[carlonnheim]

Hi david.kunz2 ,

Thanks for the suggestion. I am trying to trace the issue this way. Having DEBUG=hana activated does not show the transaction details though and I do not see anything obvious from the sequence of SQL statements.

I did add some logging to @sap/cds/libx/_runtime/db/Services.js to tag each connection with the transaction identifier I have from the cds context. E.g. doing this:

  /*
   * tx
   */
  async begin() {
    const tx = this.context ? this : this.tx()
    tx.dbc = await tx.acquire(tx.context)
    try {
tx.dbc.setClientInfo('APPLICATION', tx.context.id);
console.log("************BEGIN", tx.context.id);
        await tx.send('BEGIN')
    } catch (e) {
      tx.release(tx.dbc)
      throw e
    }
    return tx
  }

  async commit() {
    // only release on successful commit as otherwise released on rollback
console.log("************COMMIT", this.context.id);
    await this.send('COMMIT')
    this.release(this.dbc)
  }

  async rollback() {
    if (this.dbc) {
      try {
console.log("************ROLLBACK", this.context.id);
        await this.send('ROLLBACK')
      } finally {
        this.release(this.dbc)
      }
    }
  }

Now I can see the transactions starting and stopping but it is still difficult to see which statements to the DB goes into which transaction.It does help me narrow down the attributes of the scenario. It seems I need these ingredients for it to happen:

• Several messages locking the same resources
• Activities within one transaction processing deeply nested structures
• The messages fail to complete and the failures are coming at the COMMIT-stage (e.g. ASSERT_REFERENCE_INTEGRITY coming from CDS)
• Using several async/await patterns and/or Promises throughout the message processing logic

I have tried reproducing the issue in a clean application (having all of the above, but stripped of complexity) so I could share that here, but I am not able to reproduce the lock in such a setting.

I am now suspecting that either my application code is somehow detaching its "async" chain (a missing await somewhere or so) causing some of the queries to fall out into a new transaction which I do not close, or there is something not going right with the CDS assertions to keep the transactions from closing properly.

Is it possible somehow to get a trace of which SQL statements go into which connection on the CAP side? Is it possible to trace on the HANA Cloud side which statements have actually been run on a connection (so I could see where the ones idling but still blocking others are stuck)?

Many thanks in advance!

//Carl

[david_kunz2]

Hi onnheimc ,

Thanks for this additional information!

It's strange that DEBUG=hana doesn't show the SQL statements, that really should be the case. How did you set the DEBUG variable? Locally or on Cloud Foundry (via cf set-env <app-name> DEBUG hana)? Can you make sure that it's correctly set by printing process.env.DEBUG in your Node.js process?

> I am now suspecting that either my application code is somehow detaching its "async" chain

This is one of the most frequent error causes of applications, you need to make sure to not break the Promise chain, otherwise there will be race conditions.

Best regards,
David

[carlonnheim]

Hi david.kunz2 ,

It shows the SQL conditions but not the details of the transactions. I do not see the actual "BEGIN" and "COMMIT" in the log (until I added those logging statements) and I cannot see how they group together (which SQL statement is run in which connection/transaction).

Is there a good way to get this logged? Looking at what comes out now I see one of the message handlers coming to its COMMIT but then it does not proceed. It seems to be "trickle-feeding" statements to do the data integrity assertions (i.e. it selects on the "association to ..." tables to verify the foreign keys), but then it is not moving on. Could there be a need to flush buffers or something which my scenario somehow clogs up?

Can I for example catch the hana client connection when it has been set up? If so I could turn on tracing there using onTrace to see what is going on? I am suspecting that even though my code reaches the "send('COMMIT')" statement above, that commit is not actually reaching the DB (it is doing the CDS assertions first and seems to be stuck there)?

Have I understood the processing chain of the framework correctly?

• Event comes in, framework sets up context, transaction etc. and starts running the handlers
• Handlers run (my application code)
• Framework rolls back if any handler throws
• Framework commits otherwise
• On commit, the CDS framework will first do data consistency validations and then commit to the DB or roll back if anything fails. So an "application layer commit" before the DB-commit?

If that is correct, I think the lock is happening in the last step. Any advice on where I would start placing breakpoints to trace the transactions through there?

Many thanks for your help and support!

//Carl

[david_kunz2]

Hi onnheimc ,

That is correct. Once your handlers execute successfully, we run the integrity checks and then perform a commit on the database (if they succeed), otherwise (handlers reject/throw or integrity checks fail) we perform a rollback.

It might be interesting to see what happens if you disable the integrity checks (for testing purposes).

Could you set cds.features.assert_integrity: 'db' to disable runtime integrity checks?
If you want I can have a look at your code to see if there are some mistakes w.r.t. transaction handling/promises
(doesn't need to be answers.sap.com).

Best regards,
David

[gregorw]

Hi David,

I also see the difference that when you're using sqlite and DEBUG=sqlite the begin of the transaction as well as the commit are shown in the log. But for HANA this is not the case. Would be great if this can be fixed soon. If needed I can file an Incident.

Thanks.

CU
Gregor

[carlonnheim]

Hi david.kunz2 ,

Thanks for the offer to help reviewing code. I started preparing a cleaned up sample of our issue to enable that. In doing so I also got closer to the root cause - it seems the issue comes from the @sap/hana-client package. I do not get any deadlocks when using the hdb module in its place.

The former module is the long term path from what I understand, so we should try to find a solution?

I have put the code demonstrating the issue here. If you run the scenarios there with the hdb module it works fine (except cds seems to swallow throws without a proper error parameter - but this we can of course just make sure to not do...). If you then take the hdb module out and run with @sap/hana-client instead it will start deadlocking (at least it does for me).

Hoping this is possible to reproduce on your end and that somebody with insight into the hana-client module can take a look? I tried tracing through that but got out of my depth...

Again, thanks for the support!

//Carl

[david_kunz2]

Hi gregorw ,

Indeed, I quickly looked over our code to check why this is the case, it might be related to some auto commit functionality, but I will check in more detail why we don't log the transaction information using HANA and see if we can enable that!

Hi onnheimc ,

Thanks a lot for showcasing this error! I think the problem is that you are not creating a right context when using plain express middleware, let me explain that in more details:

Usually, one registers CAP handlers (not express middleware). The main difference is that in CAP handlers, we construct a request object and an async local storage called cds.context where we keep track of the main transaction. After CAP executed all registered CAP handlers, we emit a succeeded event. If a database service was involved, a COMMIT is triggered. Whenever you run await INSERT.into(xxx) or other statements, we use cds.context to link that operation to the current main transaction.

Now in your case: You use express middleware, that means we didn't construct a proper request object as well as cds.context. We also won't perform any succeeded events because the generic code is not run. Or in other words: In express middlewares you're completely responsible for transaction management.

What you can use instead is create a manual transaction using

cds.tx(async tx => {

tx.run(INSERT.into(xxx))

})

, this will automatically be committed.

You can have a look at https://cap.cloud.sap/docs/node.js/transactions for more details.

Best regards,
David

[carlonnheim]

Hi david.kunz2 ,

Thanks for your fast responses!

We are only using express for its routing capabilities here actually, not as middleware. The background of that is that we get all notifications from our source system (SAP Business ByDesign) on one topic in the form of "cloudevents" where a "type" member in the header indicates what happened (which object, create/update/delete etc.). This way I can leverage the routing capability of express to trigger the right processing of each message, use its query parameter handling capabilities etc. In short, I create a pretend-request, pass it to the router and wrap it in a Promise which completes after the routing finishes.

Quite useful in this scenario, but actually unrelated to the locking issue. I included it in the sample code because I also suspected the broken promise chain to came from there, but the same issues occur without it. I have cut this part out of the sample repo now so it goes straight in the regular CAP handler.

I also put a branch "simple" there with just the main scenario and with the @sap/hana-client library in use. It boils down to this

const cds = require('@sap/cds');

module.exports = async srv => {
    const messaging = await cds.connect.to("messaging");

    // Simulate locking of a common resource for one second on each message receipt
    messaging.on('default/my/service/locktest', async msg => {
        const db = await cds.connect.to('db');
        const { Lock, RelatedResource } = db.entities('eventmesh');
        console.log('MSG IN: ', JSON.stringify(msg));
        // Lock a common resource for 1 second, then succeed
        var r = { resource: msg.data.same }
        await INSERT.into(Lock, r);
        await DELETE.from(Lock, r);
        await new Promise((resolve, reject) => setTimeout(resolve, 1000));
    });

    // Emit a bunch of messages
    var payloads = [];
    for (var i = 0; i < 25; i++) payloads.push({ same: 'A', different: i.toString(), often: (i % 3).toString() });
    var promises = payloads.map(x => messaging.emit('default/my/service/locktest', x, x));
    await Promise.all(promises);
}

This should work I think (serializing the requests over the common resource, effectively coming through one message per second), but it locks up. Running it with hdb instead of @sap/hana-client gives the expected result.

Thanks!

//Carl

[david_kunz2]

Hi onnheimc

Yes, this is better. I wonder if there might be too much load on the database and acquiring a client will cause troubles.

Can you set

"amqp": { "incomingSessionWindow": 10 }

in your messaging service configuration? That will force Event Mesh to only send 10 concurrent messages to your app.

After that, can you also set

"outbox": false

in your messaging service configuration. Otherwise a `await messaging.emit(...)` doesn't actually perform the emit, it only waits until the transaction is succeeded and then emits the messages.

Thanks and best regards,
David

[carlonnheim]

Hi david.kunz2,

Thanks for these suggestions. I have tried them but unfortunately had no effect on the locks

Regarding the "outbox":false part it will, if I understand correctly, only affect the filling of the queues? I get the same locks in my deployed scenarios where the messages are filled in a bursty nature from an external system.

Regarding the incomingSessionWindow, I would assume it has similar throttling effects as the maxDeliveredUnackedMsgsPerFlow? I have been using that so far to set different levels of concurrency in the tests. I did some more experiments with those parameters today, concluding:

• No locks with low level of concurrency. If I have maxDeliveredUnackedMsgsPerFlow lower than 5 the process seem to flow nicely.
• If I go beyond 5 concurrent processors the locks start to appear. The lower the concurrency the shorter the duration of the locks it seems. What I mean by that is that I can clearly see the locks appear (the throughput stalls) but it is also resolving after some time (some 10 seconds), keeps eating one message per second for a while, stalls again and so on.
• When I get to ~10 concurrent processors it locks down much harder. These remain until the DB times out the lock acquisitions.

I should also mention that when in the locked state, the node process will not respond to a regular kill signal (Ctrl+C has no effect). It will go down on a "kill -9" but it does not clean up resources (the locks are still in the DB and the network socket remains open - it is noticed when restarting the service again which stops due to a address-in-use). The way I have found to clean up from this state is cancelling the locked sessions on the HANA side. Oddly enough, the lock resolves when I have cancelled the last session waiting to acquire the lock, while trying to cancel the one that actually holds the locks has no effect. Maybe there is a clue to the root cause in that patter?

Since all the scenarios work flawlessly using the hdb driver I think this must be looked at by somebody with insight to the @sap/hana-client. I am happy to engage in this, join troubleshooting sessions etc. if that helps?

Thanks in advance!

//Carl

[david_kunz2]

Hi onnheimc ,

Thanks for your detailed response!

> Regarding the "outbox":false part it will, if I understand correctly, only affect the filling of the queues?

Exactly, that was just to make sure that all messages are emitted correctly.

> regarding the incomingSessionWindow, I would assume it has similar throttling effects as the maxDeliveredUnackedMsgsPerFlow?

The option incomingSessionWindow is used for the AMQP client, here we make sure that there won't be more messages in parallel than the specified ones.

It's really hard to understand the root cause of this, maybe there are some problems with the connection pool (too many 'blocked' connections), hard to tell. It's strange that it seems to work for hdb but not for @sap/hana-client. Maybe the underlying driver has some problems, I will investigate.

For the time being, can you switch to hdb? That is our preferred choice anyway.

Thanks and best regards,
David

[carlonnheim]

Hi david.kunz2 ,

Yes, I have already switched to hdb in our development version. But I got the understanding that @sap/hana-client was the preferred choice (from the docs here).

That is why I was thinking that @sap/hana-client should be the library to use, hence important to get to the bottom of this issue. Is hdb actually the preferred choice? I cannot see any difference in how our apps run, works the same way independent of which one I use, but I want to stay on the "golden path" in general.

I am entering the test phase with this project, so would be great to know what gives - if the recommended way is hdb then I'll just consider that switch permanent and move on (the issue above is still curious, but nothing more...).

I would also suggest to update the documentation if this is the case. The link above and this one for example directs to @sap/hana-client.

Thanks!

//Carl

[david_kunz2]

Hi onnheimc ,

Yes, they write it in their documentation, those extra features are typically not needed if you use it in your CAP app.

For CAP, hdb is the preferred choice.

Best regards,
David

[carlonnheim]

Hi david.kunz2 ,

Have been running on hdb for some time now, much smoother - thanks!

One question tough; I am starting to get "Decimal" datatypes read back from the DB in scientific notation (e.g. '1.01e+3' instead of '1010' (which earlier also used to come as a string, not not in scientific notation). Is this the expected behavior from hdb?

We have a lot of integrations with ByD which accepts string-but-not-scientific formatted decimals. Can I control this behavior centrally somehow (e.g. config option)?

Thanks!

//Carl

[david_kunz2]

Hi onnheimc ,

That's good to hear, glad it works better with hdb!

Regarding the decimals: There's the HTTP header IEEE754Compatible=true/false but I'm not sure if it helps in your case, could you kindly try it out?

Thanks and best regards,
David

[carlonnheim]

Hi david.kunz2 ,

I am not getting them via HTTP calls but rather when I do like:

var myObject = await SELECT.from(MyEntityWithDecimalProperty, { id: 123 });

So I was thinking (hoping) there is some configuration parameters (cds.requires...) which would give me decimals back in non-scientific notation. Now I need to do like so in a lot of places

// myObject.someDecimal is '1.01e+3'
myObject.someDecimal = Number(myObject.someDecimal).toString()
// myObject.someDecimal is '1010' (still a string, but not scientific notation)

Thanks!

//Carl

[david_kunz2]

Hi onnheimc ,

Could you declare precision and scale for that field?

E.g. Decimal(16, 3)? Then it shouldn't return it in scientific notation.

Best regards,
David