await Event.insert({...}) is resolving, but not always found in the DB

[Kilian Gosewisch]

Hi, i was pointed to here when i got problems :)

Here I am.

await Promise.all(userIds.map(async userId => {

   const newEvent: EventInterface = {

     chatId: newGroupChat.id.toString(),

     createdAt: new Date(),

     event: 'ADD_USER_TO_GROUP_CHAT',

     id: v4(),

     values: {

       executor: user.id.toString(),

       target: userId

     }

   }

   await Event.insert(newEvent)

   return await pubsub.publish(subscriptions.privateMessages, {

     privateMessages: {

       message: { __type: 'Event', ...newEvent },

       participants: newGroupChat.participants,

       chatId: newGroupChat.id.toString(),

       action: 'created'

     }

   })

 }))

This is what I'm doing in an API call.
Maybe i should use batches(just heard about them, but did not research yet, about to go home).
The await Event.insert is called and i added logs after the insert line and i could verify that it was indeed called 8 times. The desired amount.
I also put a console.log after the Promise.all and it resolved after all Event.inserts were awaited.
I get no errors, nothing. Our project is pretty big and we have many calls like this and similar in our code. But this one gives me some troubles.
Is there a cassandra log where i sould have a first look? Do you see something obvious i did wrong? Any help is appreciated :)

Cheers, Kilian

[Jorge Bay Gondra]

Hi Kilian,

What consistency level are you using for inserting and selecting? If you are using the default, it's LOCAL_ONE. If you want the written data to be available for subsequent reads, you should use LOCAL_QUORUM for writes and reads.

http://cassandra.apache.org/doc/latest/architecture/dynamo.html#tunable-consistency

You can set the consistency level for all queries when creating the Client instance:

const cassandra = require('cassandra-driver');

const client = new cassandra.Client({

  // ... other settings ...

  queryOptions: { consistency: cassandra.types.consistencies.localQuorum }

});

The code looks good, there's no need to use batches. 

Cheers,

Jorge

--
To unsubscribe from this group and stop receiving emails from it, send an email to nodejs-driver-u...@lists.datastax.com.

[Kilian Gosewisch]

Hi Jorge,
i just try localQuorum and nothing changed (even though i dont need the data for subsequent reads).
Event.insert got called 8 times, but i only have 5 entries in my table. No errors.

To unsubscribe from this group and stop receiving emails from it, send an email to nodejs-driver-user+unsub...@lists.datastax.com.

[Kilian Gosewisch]

When i try to log the result of the insert, my code crashes.
https://github.com/datastax/nodejs-driver/blob/424c9ade587f404f20404169ba7ada0e9e04406b/lib/mapping/result.js#L115

TypeError: Cannot read property 'map' of undefined

      at Result.toArray (/usr/src/app/node_modules/cassandra-driver/lib/mapping/result.js:115:26)

      at Result.[nodejs.util.inspect.custom] (/usr/src/app/node_modules/cassandra-driver/lib/mapping/result.js:132:17)

      at formatValue (internal/util/inspect.js:550:31)

      at formatProperty (internal/util/inspect.js:1366:11)

      at formatRaw (internal/util/inspect.js:761:9)

      at formatValue (internal/util/inspect.js:567:10)

      at inspect (internal/util/inspect.js:221:10)

      at formatWithOptions (internal/util/inspect.js:1651:40)

      at Object.Console.<computed> (internal/console/constructor.js:272:10)

      at Object.log (internal/console/constructor.js:282:61)

[Jorge Bay Gondra]

Hi,

The error you obtained when inspecting the result is not related.

Nice findings! I've filed a ticket for it: https://datastax-oss.atlassian.net/browse/NODEJS-546

Back to the original issue,

1) Do the rest of the rows ever appear?

2) Could you try to reproduce the same behaviour outside of a loop / map() statement ?

3) Can you enable logging and try to reproduce again? https://docs.datastax.com/en/developer/nodejs-driver/4.1/features/logging/#logging

Thanks,

Jorge

--
To unsubscribe from this group and stop receiving emails from it, send an email to nodejs-driver-u...@lists.datastax.com.

[Kilian Gosewisch]

Hi,

cool, will follow this issue.

1) No

2) Will try after 3.

3) Will do this right now

To unsubscribe from this group and stop receiving emails from it, send an email to nodejs-driver-user+unsub...@lists.datastax.com.

[Kilian Gosewisch]

3) all i see is this:

log event: verbose -- Sent stream #52 to 10.135.2xx.xx:9042

log event: verbose -- Received frame #40 from 10.135.2xx.xx:9042

log event: verbose -- Sent stream #40 to 10.135.2xx.xx:9042

log event: verbose -- Received frame #52 from 10.135.2xx.xx:9042

 no anomalies, errors or warnings.

It's a bit more complicated for me to test 2) because userIds array has variable length.
What i just tried, was putting Event.insert into a setTimeout. But i changed nothing

[Jorge Bay Gondra]

ok, let me know when you have more info.

You should obtain get a pair of "Sent stream #n"  "Received frame #n" per query executed, you could include a timestamp in the log message to make it easier to troubleshoot.

To unsubscribe from this group and stop receiving emails from it, send an email to nodejs-driver-u...@lists.datastax.com.

--
To unsubscribe from this group and stop receiving emails from it, send an email to nodejs-driver-u...@lists.datastax.com.

[Kilian Gosewisch]

Maybe this tells us something

log event: verbose -- Sent stream #93 to 10.135.255.87:9042

log event: verbose -- Sent stream #53 to 10.135.255.87:9042

log event: verbose -- Sent stream #86 to 10.135.255.87:9042

log event: verbose -- Sent stream #97 to 10.135.255.87:9042

log event: verbose -- Sent stream #96 to 10.135.255.87:9042

log event: verbose -- Sent stream #32 to 10.135.255.87:9042

log event: verbose -- Sent stream #14 to 10.135.255.87:9042

log event: verbose -- Received frame #96 from 10.135.255.87:9042

log event: verbose -- Received frame #97 from 10.135.255.87:9042

log event: verbose -- Received frame #32 from 10.135.255.87:9042

log event: verbose -- Received frame #14 from 10.135.255.87:9042

log event: verbose -- Received frame #86 from 10.135.255.87:9042

log event: verbose -- Received frame #53 from 10.135.255.87:9042

log event: verbose -- Received frame #93 from 10.135.255.87:9042

log event: verbose -- Sent stream #93 to 10.135.255.87:9042

log event: verbose -- Received frame #93 from 10.135.255.87:9042

log event: verbose -- Sent stream #53 to 10.135.255.87:9042

log event: verbose -- Received frame #53 from 10.135.255.87:9042

log event: verbose -- Sent stream #53 to 10.135.255.87:9042

log event: verbose -- Received frame #53 from 10.135.255.87:9042

log event: verbose -- Sent stream #93 to 10.135.255.87:9042

log event: verbose -- Sent stream #86 to 10.135.255.87:9042

log event: verbose -- Sent stream #14 to 10.135.255.87:9042

log event: verbose -- Sent stream #32 to 10.135.255.87:9042

log event: verbose -- Sent stream #97 to 10.135.255.87:9042

log event: verbose -- Sent stream #96 to 10.135.255.87:9042

log event: verbose -- Sent stream #85 to 10.135.255.87:9042

log event: verbose -- Sent stream #75 to 10.135.255.87:9042

log event: verbose -- Received frame #97 from 10.135.255.87:9042

log event: verbose -- Received frame #32 from 10.135.255.87:9042

log event: verbose -- Received frame #85 from 10.135.255.87:9042

log event: verbose -- Received frame #96 from 10.135.255.87:9042

log event: verbose -- Received frame #75 from 10.135.255.87:9042

log event: verbose -- Received frame #14 from 10.135.255.87:9042

log event: verbose -- Received frame #86 from 10.135.255.87:9042

log event: verbose -- Received frame #93 from 10.135.255.87:9042

{

  newEvent: {

    chatId: 'aaf647c4-f929-489c-8e0e-67ddb1ee7f2a',

    createdAt: 2019-09-05T12:03:41.745Z,

    event: 'ADD_USER_TO_GROUP_CHAT',

    id: '07f7d88b-b5fc-42f0-94a0-5804ae8e1db9',

    values: {

      executor: 'c4be5e9a-d8bd-4476-ade9-e3a0b26c7413',

      target: '168a433a-fee6-4236-bf58-39c196e3b814'

    }

  }

}

{

  newEvent: {

    chatId: 'aaf647c4-f929-489c-8e0e-67ddb1ee7f2a',

    createdAt: 2019-09-05T12:03:41.746Z,

    event: 'ADD_USER_TO_GROUP_CHAT',

    id: '6ecda735-9979-4451-bf3b-1ffcc807ec67',

    values: {

      executor: 'c4be5e9a-d8bd-4476-ade9-e3a0b26c7413',

      target: 'c9b5bcfc-2d25-4d76-b2b1-0bbb4d1fca9a'

    }

  }

}

{

  newEvent: {

    chatId: 'aaf647c4-f929-489c-8e0e-67ddb1ee7f2a',

    createdAt: 2019-09-05T12:03:41.747Z,

    event: 'ADD_USER_TO_GROUP_CHAT',

    id: '21e655ae-20ae-4965-860d-b0189d9720ff',

    values: {

      executor: 'c4be5e9a-d8bd-4476-ade9-e3a0b26c7413',

      target: '0999c116-7353-4505-b6ac-22b68e0d798d'

    }

  }

}

{

  newEvent: {

    chatId: 'aaf647c4-f929-489c-8e0e-67ddb1ee7f2a',

    createdAt: 2019-09-05T12:03:41.748Z,

    event: 'ADD_USER_TO_GROUP_CHAT',

    id: 'd36e8103-9a2e-4d0a-a3e5-42c28d351a34',

    values: {

      executor: 'c4be5e9a-d8bd-4476-ade9-e3a0b26c7413',

      target: 'd81991bf-9b83-4dbd-8b90-8c1874dca741'

    }

  }

}

{

  newEvent: {

    chatId: 'aaf647c4-f929-489c-8e0e-67ddb1ee7f2a',

    createdAt: 2019-09-05T12:03:41.751Z,

    event: 'ADD_USER_TO_GROUP_CHAT',

    id: '797c05ad-e826-4c3d-b213-2a63c89c65f6',

    values: {

      executor: 'c4be5e9a-d8bd-4476-ade9-e3a0b26c7413',

      target: '7cf59dea-fb62-490e-86c6-cc4fc4efcd09'

    }

  }

}

{

  newEvent: {

    chatId: 'aaf647c4-f929-489c-8e0e-67ddb1ee7f2a',

    createdAt: 2019-09-05T12:03:41.752Z,

    event: 'ADD_USER_TO_GROUP_CHAT',

    id: '69080f19-08d7-4f8d-ba27-7c7cbe3577ed',

    values: {

      executor: 'c4be5e9a-d8bd-4476-ade9-e3a0b26c7413',

      target: '4d448816-e3aa-4d50-890f-061ef37c69b4'

    }

  }

}

{

  newEvent: {

    chatId: 'aaf647c4-f929-489c-8e0e-67ddb1ee7f2a',

    createdAt: 2019-09-05T12:03:41.753Z,

    event: 'ADD_USER_TO_GROUP_CHAT',

    id: '220afa76-5e08-429c-85cc-2b3220f1b38d',

    values: {

      executor: 'c4be5e9a-d8bd-4476-ade9-e3a0b26c7413',

      target: 'cbcd9b63-4674-4a33-be99-8682787aed5e'

    }

  }

}

{

  newEvent: {

    chatId: 'aaf647c4-f929-489c-8e0e-67ddb1ee7f2a',

    createdAt: 2019-09-05T12:03:41.753Z,

    event: 'ADD_USER_TO_GROUP_CHAT',

    id: 'f6fb14da-0db5-472d-92de-613ce1ea0c8a',

    values: {

      executor: 'c4be5e9a-d8bd-4476-ade9-e3a0b26c7413',

      target: 'c4be5e9a-d8bd-4476-ade9-e3a0b26c7413'

    }

  }

}

log event: verbose -- Sent stream #93 to 10.135.255.87:9042

log event: verbose -- Sent stream #86 to 10.135.255.87:9042

log event: verbose -- Sent stream #14 to 10.135.255.87:9042

AWAITED

log event: verbose -- Received frame #86 from 10.135.255.87:9042

log event: verbose -- Received frame #93 from 10.135.255.87:9042

log event: verbose -- Received frame #14 from 10.135.255.87:9042

log event: verbose -- Sent stream #93 to 10.135.255.87:9042

log event: verbose -- Sent stream #86 to 10.135.255.87:9042

log event: verbose -- Sent stream #75 to 10.135.255.87:9042

log event: verbose -- Sent stream #96 to 10.135.255.87:9042

log event: verbose -- Sent stream #85 to 10.135.255.87:9042

log event: verbose -- Sent stream #32 to 10.135.255.87:9042

log event: verbose -- Sent stream #97 to 10.135.255.87:9042

log event: verbose -- Sent stream #53 to 10.135.255.87:9042

log event: verbose -- Sent stream #14 to 10.135.255.87:9042

log event: verbose -- Sent stream #13 to 10.135.255.87:9042

log event: verbose -- Received frame #93 from 10.135.255.87:9042

log event: verbose -- Received frame #85 from 10.135.255.87:9042

log event: verbose -- Received frame #32 from 10.135.255.87:9042

log event: verbose -- Received frame #97 from 10.135.255.87:9042

log event: verbose -- Received frame #53 from 10.135.255.87:9042

log event: verbose -- Received frame #96 from 10.135.255.87:9042

log event: verbose -- Received frame #75 from 10.135.255.87:9042

log event: verbose -- Received frame #86 from 10.135.255.87:9042

log event: verbose -- Received frame #13 from 10.135.255.87:9042

log event: verbose -- Received frame #14 from 10.135.255.87:9042

log event: verbose -- Sent stream #14 to 10.135.255.87:9042

log event: verbose -- Sent stream #13 to 10.135.255.87:9042

log event: verbose -- Received frame #13 from 10.135.255.87:9042

log event: verbose -- Received frame #14 from 10.135.255.87:9042

log event: verbose -- Sent stream #14 to 10.135.255.87:9042

log event: verbose -- Sent stream #13 to 10.135.255.87:9042

log event: verbose -- Received frame #13 from 10.135.255.87:9042

log event: verbose -- Received frame #14 from 10.135.255.87:9042

There are Received Frame logs (which seem to be connected to the Event.insert) after the AWAITED log which is called after "await Promise.all(...)"

if i interpret this correctly, the code continues before cassandra actually finished processing all the requests

[Jorge Bay Gondra]

Hi Kilian,

I'm trying to think of possible reasons that could cause something similar to what are you describing and I can't find a possible scenario.

There are more than 50 integration tests and 80 unit tests around the Mapper, I wrote one today with a similar use case to what are you describing and its passing on CI: https://github.com/datastax/nodejs-driver/blob/9f70c4387b29f81cfba691e11355f9535ac3e55c/test/integration/short/mapping/model-mapper-tests.js#L276-L301

I would recommend that you try to reproduce it reducing as much as possible the amount of code and logic, like in a synthetic script, try to insert n and read n rows.

I'm sorry I can't be of more help. Hope you let us know if there's a way to reproduce the issue you describe.

Thanks,

Jorge

--

[Kilian Gosewisch]

Hi Jorge,

i will surely tackle this issue in the upcoming days some more and will let you know if i find something.

It probably is just a really really stupid mistake :)
Thank you for your support! Great to have you in this community!

[Kilian Gosewisch]

Sooooo,

i solved it.

It was really really really dumb. Probably because I'm new to cassandra.
My table looks like this:

CREATE TABLE maet.chat_events_created_at (

    chat_id uuid,

    created_at timestamp,

    event text,

    id uuid,

    values map<text, text>,

    PRIMARY KEY (chat_id, created_at)

) WITH CLUSTERING ORDER BY (created_at ASC)

In the loop i create a "new Date()" which is, as you can see, the clustering key. Because the loops take less than 1ms, i create entries which have the same primary_key (chat_id) and clustering key(created_at).
I use a very dirty but functional workaround now. Maybe you could correct me in my table design so i can correctly work around this issue.
My dirty workaround:

const now = new Date()
await Promise.all(userIds.map(async (userId, index) => {

    const newEvent: EventInterface = {

      chatId: newGroupChat.id.toString(),

      createdAt: new Date(now.getTime() + index),

      event: 'ADD_USER_TO_GROUP_CHAT',

      id: v4(),

      values: {

        executor: user.id.toString(),

        target: userId

      }

    }

    const bla = await Event.insert(newEvent)

    console.log(bla.first())

    await pubsub.publish(subscriptions.privateMessages, {

      privateMessages: {

        message: { __type: 'Event', ...newEvent },

        participants: newGroupChat.participants,

        chatId: newGroupChat.id.toString(),

        action: 'created'

      }

    })

    return

  }))

[Jorge Bay Gondra]

Ahh, I should have thought of the schema :)

Glad to know that you've found the issue!

You should change your schema to use unique values. You could use a TimeUuid, that are conflict free timestamps: 

https://docs.datastax.com/en/archived/cql/3.3/cql/cql_reference/uuid_type_r.html

https://docs.datastax.com/en/developer/nodejs-driver/4.1/features/datatypes/uuids/#time-uuid

[Kilian Gosewisch]

I thought i have to design it like this, because my query looks like this. With my current knowledge i cant think of another structure.

Event.find({ chatId: chatId }, { orderBy: { createdAt: 'desc' } })

To unsubscribe from this group and stop receiving emails from it, send an email to nodejs-driver-user+unsub...@lists.datastax.com.

[Jorge Bay Gondra]

timeuuid as clustering key are ordered based on timestamp on C* side.

So you should get the same behaviour :)

You can also extract the date portion of the timeuuid for a UI to display the date.

To unsubscribe from this group and stop receiving emails from it, send an email to nodejs-driver-u...@lists.datastax.com.

--
To unsubscribe from this group and stop receiving emails from it, send an email to nodejs-driver-u...@lists.datastax.com.

[Kilian Gosewisch]

Oh, i didn't know that!
This sounds promising! Will try this right now.
Do you have a link where i can buy you a beer?

[Jorge Bay Gondra]

I appreciate the offer :)

The driver is an open source project by DataStax and we are engineers working for the company to improve and maintain it.

Happy to help, and in case you want to contribute in source code, documentation or any other way, you are welcome to: https://github.com/datastax/nodejs-driver

--