Backendless Support
 
In Progress

Task execution is aborted due to timeout (JS) v.4.0b10

Hi again, I've started to receive a lot of this error type.

I have very basic custom business logic written in JS. All it does is changing INT value to desired value and sending message to status channel:

  1. /**

    * @param {Number} status

    * @returns {Promise.<void>}

    */

    changeStatus(status) {

    let TAG = 'EventsService.changeStatus - ';

    if (status === null) {

    throw new Error('Invalid Request, no status provided');

    }

    if (this.request.context.userId === null) {

    throw new Error('Please login first!');

    }

    //Create UserObject

    let currentUser = new Backendless.User();

    currentUser.objectId = this.request.context.userId;

    currentUser.online = status;

    let usersStorage = Backendless.Persistence.of(Backendless.User);

    return usersStorage.save(currentUser).then(function (updateUser) {

    //Notify users about change

    var message = updateUser.name + "is offline";

    if (status === 1) {

    message = updateUser.name + "is offline";

    }

    let channel = "Status",

    pubOps = new Backendless.PublishOptions({

    subtopic: "CHN-" + currentUser.objectId,

    headers: {

    userID: currentUser.objectId,

    userName: updateUser.name,

    status: status

    }

    }),

    deliveryOptions = new Backendless.DeliveryOptions({

    pushPolicy: "PUBSUB"

    });

    return Backendless.Messaging.publish(channel, message, pubOps, deliveryOptions)

    .then(function (response) {

    return updateUser;

    })

    .catch(function (error) {

    console.error(TAG + " Publish status " + JSON.stringify(error));

    throw error;

    });

    }).catch(function (updateErr) {

    console.error(TAG + " Update currentUser " + JSON.stringify(updateErr));

    throw updateErr;

    });

    }

But this method is failing roughly 50% of tries with error:

400 - Task execution is aborted due to timeout

OR

It works perfecly

23:31:34.773 - [5BBA19DB-773F-F004-FF5F-0F5B4257FA00] [INVOKE SERVICE] services.EventsService.changeStatus

23:31:36.000 - [5BBA19DB-773F-F004-FF5F-0F5B4257FA00] Processing finished

BUT all of this happens only in production, if there is debugging session online, it work fine in 100% of tries

Leave a Comment

Comments (19)

photo
1

Your code returns a promise from Backendless.Persistence.save. In the callback of that promise you publish a message and return another promise.

Take a look at the following support topic:

http://support.backendless.com/topic/production-mode-problem

Notice how Promise.all is used in the return value. I believe this is what should be done here is well, but I will defer to our JS guys to confirm.

photo
1

Thank you for reply, like this it seems to work:

  1. /**

    * @param {Number} status

    * @returns {Promise.<void>}

    */

    changeStatus(status) {

    let TAG = 'EventsService.changeStatus - ';

    if (status === null) {

    throw new Error('Invalid Request, no status provided');

    }

    if (this.request.context.userId === null) {

    throw new Error('Please login first!');

    }

    //Create UserObject

    let currentUser = new Backendless.User();

    currentUser.objectId = this.request.context.userId;

    currentUser.online = status;

    let usersStorage = Backendless.Persistence.of(Backendless.User);

    let updateCurrentUser = usersStorage.save(currentUser);

    let sendMessage = function (updateUser) {

    return new Promise((resolve, reject) => {

    log(TAG, JSON.stringify(updateUser));

    //Notify users about change

    var message = updateUser.name + "is offline";

    if (status === 1) {

    message = updateUser.name + "is offline";

    }

    let channel = "Status",

    pubOps = new Backendless.PublishOptions({

    subtopic: "CHN-" + currentUser.objectId,

    headers: {

    userID: currentUser.objectId,

    userName: updateUser.name,

    status: status

    }

    }),

    deliveryOptions = new Backendless.DeliveryOptions({

    pushPolicy: "PUBSUB"

    });

    Backendless.Messaging.publish(channel, message, pubOps, deliveryOptions)

    .then(response => {

    log(TAG, JSON.stringify(response));

    Promise.resolve(updateUser);

    })

    .catch(function (error) {

    log(TAG, JSON.stringify(error));

    return Promise.reject(error);

    });

    });

    };

    return Promise.all([updateCurrentUser,sendMessage]).catch(function (err) {

    throw err;

    });

    }

Could somebody explain, why chaining of promises is not working ?

http://solutionoptimist.com/2013/12/27/javascript-promise-chains-2/

photo
1

More complex method:

  1. /**

    * @param {String} message

    * @param {String} toUserId

    * @returns {Promise.<void>}

    */

    sendMessage(message, toUserId) {

    let TAG = 'EventsService.sendMessage - ';

    if ((message === null) || (toUserId === null)) {

    throw new Error('Invalid Request, no message or toUserId provided');

    }

    if (this.request.context.userId === null) {

    throw new Error('Please login first!');

    }

    let pushMessage = this.pushMessage;

    let requestedUser = new Backendless.User();

    requestedUser.objectId = toUserId;

    let firstStage = new Promise((resolve, reject) => {

    let messagesStorage = Backendless.Persistence.of(Messages);

    let usersStorage = Backendless.Persistence.of(Backendless.User);

    let reqQueryBuilder = Backendless.DataQueryBuilder.create();

    reqQueryBuilder.setProperties(["objectID", "name"]);

    let reqWhere = "objectId = '" + this.request.context.userId + "'";

    reqQueryBuilder.setWhereClause(reqWhere);

    let newMessage = new Messages();

    //Define Message object

    newMessage.message = message;

    newMessage.msg_type = 100;

    Promise.all([usersStorage.find(reqQueryBuilder), messagesStorage.save(newMessage)]).then(function (result) {

    let loadedUser = result[0];

    let savedObject = result[1];

    let fromRelationPromise = messagesStorage.setRelation(savedObject, "from", loadedUser);

    let toRelationPromise = messagesStorage.setRelation(savedObject, "to", [requestedUser]);

    let pushMessagePromise = pushMessage([loadedUser[0].objectId], savedObject.message, savedObject.msg_type, loadedUser[0].objectId, loadedUser[0].name);

    Promise.all([fromRelationPromise, toRelationPromise, pushMessagePromise]).then(function (from, to, push) {

    savedObject.from = loadedUser;

    savedObject.to = requestedUser;

    log(TAG, JSON.stringify(savedObject));

    resolve(savedObject);

    }).catch(function (err) {

    reject(err);

    })

    }).catch(function (err) {

    reject(err);

    });

    });

    return firstStage;

    }

This method takes in debug mode:

23:14:06.622 - [01A0546C-2438-558D-FF8E-B4474A2BEC00] New task arrived!

23:14:06.624 - [01A0546C-2438-558D-FF8E-B4474A2BEC00] [INVOKE SERVICE] services.EventsService.sendMessage

23:14:07.690 - [01A0546C-2438-558D-FF8E-B4474A2BEC00] Processing finished

23:14:12.523 - [D5E6B862-D077-CD80-FFB5-400CB7ED4700] New task arrived!

23:14:12.524 - [D5E6B862-D077-CD80-FFB5-400CB7ED4700] [INVOKE SERVICE] services.EventsService.sendMessage

23:14:13.612 - [D5E6B862-D077-CD80-FFB5-400CB7ED4700] Processing finished

23:14:18.766 - [BB378976-1356-D430-FF0B-34F3895E0700] New task arrived!

23:14:18.767 - [BB378976-1356-D430-FF0B-34F3895E0700] [INVOKE SERVICE] services.EventsService.sendMessage

23:14:19.879 - [BB378976-1356-D430-FF0B-34F3895E0700] Processing finished

About 1second to process, but in production i got many times timeout errors :(

photo
1

Please see the following post. I believe this is what's going on in your case as well:

http://support.backendless.com/topic/two-external-hosts-not-working-even-though-approved

photo
1

Yes I understood what u said last time, so I've started refactoring that code.

So now every async call in order:

  1. findCurrentUser
  2. saveMessageObject

Are in one Promise.all -> returning CurrentUser and SavedObject

Then:

  1. addRelation To
  2. addRelation From
  3. sendPush Nofitication

Are all again wrapped in Promise.all

And to make sure that nothing stays unresolved I've placed these to into one root Promise, and resolve/reject manually (returning savedObject/error)

photo
1

What is the timestamp of the following log call?

log(TAG, JSON.stringify(savedObject));

Is it in the log?

photo
1

  1. 00:07:02.718 - [428BA09F-7F24-4721-FF8E-286EE359C100] New task arrived!
  2. 00:07:02.726 - [428BA09F-7F24-4721-FF8E-286EE359C100] [INVOKE SERVICE] services.EventsService.sendMessage
  3. 00:07:03 GMT+0200 (CEST).285 - EventsService.pushMessage - "[\"5DF302D1-CBFC-9D3A-FF64-71D1B84CEC00\"]"
  4. 00:07:03 GMT+0200 (CEST).286 - EventsService.pushMessage - " send message to = CHN-5DF302D1-CBFC-9D3A-FF64-71D1B84CEC00"
  5. 00:07:03 GMT+0200 (CEST).880 - EventsService.sendMessage - "{\"___class\":\"Messages\",\"ownerId\":\"5DF302D1-CBFC-9D3A-FF64-71D1B84CEC00\",\"objectId\":\"A19C6AA0-17A5-9CF3-FFBF-166C183E5B00\",\"created\":1497910000191,\"updated\":null,\"to\":{\"objectId\":\"5DF302D1-CBFC-9D3A-FF64-71D1B84CEC00\"},\"from\":[{\"name\":\"Test Ip7\",\"___class\":\"Users\",\"objectId\":\"5DF302D1-CBFC-9D3A-FF64-71D1B84CEC00\",\"__meta\":\"{\\\"relationRemovalIds\\\":{},\\\"selectedProperties\\\":[\\\"name\\\",\\\"___class\\\",\\\"objectId\\\"],\\\"relatedObjects\\\":{}}\"}],\"message\":\"test\",\"msg_type\":100,\"__meta\":\"{\\\"relationRemovalIds\\\":{},\\\"selectedProperties\\\":[\\\"created\\\",\\\"___saved\\\",\\\"___class\\\",\\\"msg_type\\\",\\\"from\\\",\\\"to\\\",\\\"message\\\",\\\"ownerId\\\",\\\"updated\\\",\\\"objectId\\\"],\\\"relatedObjects\\\":{}}\"}"
  6. 00:07:03.882 - [428BA09F-7F24-4721-FF8E-286EE359C100] Processing finished

photo
1

So it took 1s 162ms to reach that point

photo
1

What about when it is in production? Is there a message about interrupted processing in the log file? What do the timestamps look like there?

photo
1

I have no idea how to connect debugger to production. These logfiles are generated only when they like and with delay.

photo
photo
1

Use console.log for logging, deploy the code to prod, run it and then see the log file in Backendless console (Files > /logging)

photo
1

Ok i will do it in morning its 00:30 for me. Thx anyway i hope that its something small

photo
1

Logs attached

photo
1

The log tells me that in some cases the business logic does not complete in the timeframe allowed by the current plan (all apps in Backendless 4 now run with the limits of the Cloud99 plan). The limit for the cloud code execution is 10 seconds. So here's an example when the interruption takes place:

  1. 2017-06-20 06:07:42,952 | SERVER_CODE | INFO | [1252] [350FB512-D397-9352-FFCF-13C8B4BB6D00] [INVOKE SERVICE] services.EventsService.sendMessage
  2. 2017-06-20 06:07:42,954 | SERVER_CODE | INFO | [1252] Building ServerCode Model for path (/var/lib/backendless/repo/02e0b487-71ce-db1e-ff7f-79892d128500/files/servercode/services/623FE1F9-0828-B7AF-FFA5-E76FF9403800)
  3. 2017-06-20 06:07:42,955 | SERVER_CODE | INFO | [1252] Reading models/GroupMessages.js...
  4. 2017-06-20 06:07:42,957 | SERVER_CODE | INFO | [1252] Reading models/Groups.js...
  5. 2017-06-20 06:07:42,958 | SERVER_CODE | INFO | [1252] Reading models/Messages.js...
  6. 2017-06-20 06:07:42,958 | SERVER_CODE | INFO | [1252] Reading models/Requests.js...
  7. 2017-06-20 06:07:42,959 | SERVER_CODE | INFO | [1252] Reading services/events-service.js...
  8. 2017-06-20 06:07:42,964 | SERVER_CODE | INFO | [1252] ServerCode Model built in 10ms
  9. 2017-06-20 06:07:48,135 | SERVER_CODE | INFO | 06:07:48 GMT+0000 (UTC).135 - EventsService.pushMessage - "[\"5DF302D1-CBFC-9D3A-FF64-71D1B84CEC00\"]"
  10. 2017-06-20 06:07:48,135 | plusco | DEBUG | EventsService.pushMessage - "[\"5DF302D1-CBFC-9D3A-FF64-71D1B84CEC00\"]"
  11. 2017-06-20 06:07:48,136 | SERVER_CODE | INFO | 06:07:48 GMT+0000 (UTC).135 - EventsService.pushMessage - " send message to = CHN-5DF302D1-CBFC-9D3A-FF64-71D1B84CEC00"
  12. 2017-06-20 06:07:48,136 | plusco | DEBUG | EventsService.pushMessage - " send message to = CHN-5DF302D1-CBFC-9D3A-FF64-71D1B84CEC00"
  13. 2017-06-20 06:07:53,000 | SERVER_CODE | ERROR | [1252] Error: Task execution is aborted due to timeout
  14. 2017-06-20 06:07:53,001 | SERVER_CODE | INFO | [1252] Processing finished

In this case the processing starts at 06:07:42,952.

Ten seconds later, at 06:07:53,000 there is a message about the task being aborted.

photo
1

Ok Iam really starting having headache about it...

So here is just one promise, one method, extremely simple:

  1. /**

    * @param {String} message

    * @param {String} toUserId

    * @returns {Promise.<void>}

    */

    testCall(message, toUserId) {

    let TAG = 'EventsService.testCall - ';

    if ((message === null) || (toUserId === null)) {

    throw new Error('Invalid Request, no message or toUserId provided');

    }

    if (this.request.context.userId === null) {

    throw new Error('Please login first!');

    }

    let messagesStorage = Backendless.Persistence.of(Messages);

    let newMessage = new Messages();

    let requestedUser = new Backendless.User();

    requestedUser.objectId = toUserId;

    //Define Message object

    newMessage.objectId = "82B3311B-0349-191D-FF1E-816D433C9F00";

    return messagesStorage.setRelation(newMessage, "to", [requestedUser]);

    }

It only tries to set relation to existing object in DB.

If you look at attached logs, you will see that most of the time

this operation takes like 300ms to complete:

2017-06-21 06:19:39,616 | SERVER_CODE | INFO | [1452] [6D6B65FB-38BD-8E9A-FF49-FBB7AD7E6D00] [INVOKE SERVICE] services.EventsService.testCall

2017-06-21 06:19:39,619 | SERVER_CODE | INFO | [1452] Building ServerCode Model for path (/var/lib/backendless/repo/02e0b487-71ce-db1e-ff7f-79892d128500/files/servercode/JS/default/PRODUCTION)

2017-06-21 06:19:39,626 | SERVER_CODE | INFO | [1452] ServerCode Model built in 7ms

2017-06-21 06:19:39,865 | SERVER_CODE | INFO | [1452] Processing finished

But sometimes for some reason, it takes 5s and 196ms:

2017-06-21 06:20:24,557 | SERVER_CODE | INFO | [31048] [44D3856F-8C26-747A-FF75-BF8E43D03C00] [INVOKE SERVICE] services.EventsService.testCall

2017-06-21 06:20:24,561 | SERVER_CODE | INFO | [31048] Building ServerCode Model for path (/var/lib/backendless/repo/02e0b487-71ce-db1e-ff7f-79892d128500/files/servercode/JS/default/PRODUCTION)

2017-06-21 06:20:24,571 | SERVER_CODE | INFO | [31048] ServerCode Model built in 10ms

2017-06-21 06:20:29,753 | SERVER_CODE | INFO | [31048] Processing finished

For that we can hardly blame bad programming or promises, dont you think ?

photo
1

We are going to run some benchmark scripts on relation management and optimize where we can before 4.0 goes out of Beta. There must be something that causes the occasional delay.

photo
1

Were you able to obtain some results ?

photo
1

Hi Tomas,

There are a few performance improvements going to be deployed soon. For now, a few quick questions which would help us identify the case. How much data do you have in your Users and Messages tables? Does the timeout happen constantly or from time to time only?

photo
1

It pretty regular, maybe every second or third call of same function there is a delay.

About Users/Messages this is in real development stage, so they are pretty empty. (5users, maybe 50messages)

photo