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:

/**
 * @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

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/t/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.

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

/**
 * @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/

More complex method:

/**
 * @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 :frowning:

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

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

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

So now every async call in order:

    findCurrentUser saveMessageObject
Are in one Promise.all -> returning CurrentUser and SavedObject Then:
    addRelation To addRelation From 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)

What is the timestamp of the following log call?

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

Is it in the log?


00:07:02.718 - [428BA09F-7F24-4721-FF8E-286EE359C100] New task arrived!
00:07:02.726 - [428BA09F-7F24-4721-FF8E-286EE359C100] [INVOKE SERVICE] services.EventsService.sendMessage
00:07:03 GMT+0200 (CEST).285 - EventsService.pushMessage - "[\"5DF302D1-CBFC-9D3A-FF64-71D1B84CEC00\"]"
00:07:03 GMT+0200 (CEST).286 - EventsService.pushMessage - " send message to = CHN-5DF302D1-CBFC-9D3A-FF64-71D1B84CEC00"
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\\\":{}}\"}"
00:07:03.882 - [428BA09F-7F24-4721-FF8E-286EE359C100] Processing finished

So it took 1s 162ms to reach that point

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?

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

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

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

Logs attached

Jun 20 2017.log.txt (20.55kB)

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:

2017-06-20 06:07:42,952 | SERVER_CODE |  INFO | [1252] [350FB512-D397-9352-FFCF-13C8B4BB6D00] [INVOKE SERVICE] services.EventsService.sendMessage
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)
2017-06-20 06:07:42,955 | SERVER_CODE |  INFO | [1252] Reading models/GroupMessages.js...
2017-06-20 06:07:42,957 | SERVER_CODE |  INFO | [1252] Reading models/Groups.js...
2017-06-20 06:07:42,958 | SERVER_CODE |  INFO | [1252] Reading models/Messages.js...
2017-06-20 06:07:42,958 | SERVER_CODE |  INFO | [1252] Reading models/Requests.js...
2017-06-20 06:07:42,959 | SERVER_CODE |  INFO | [1252] Reading services/events-service.js...
2017-06-20 06:07:42,964 | SERVER_CODE |  INFO | [1252] ServerCode Model built in 10ms
2017-06-20 06:07:48,135 | SERVER_CODE |  INFO | 06:07:48 GMT+0000 (UTC).135 - EventsService.pushMessage - "[\"5DF302D1-CBFC-9D3A-FF64-71D1B84CEC00\"]"
2017-06-20 06:07:48,135 | plusco | DEBUG | EventsService.pushMessage - "[\"5DF302D1-CBFC-9D3A-FF64-71D1B84CEC00\"]"
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"
2017-06-20 06:07:48,136 | plusco | DEBUG | EventsService.pushMessage - " send message to = CHN-5DF302D1-CBFC-9D3A-FF64-71D1B84CEC00"
2017-06-20 06:07:53,000 | SERVER_CODE | ERROR | [1252] Error: Task execution is aborted due to timeout
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.

Ok Iam really starting having headache about it…

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

/**
 * @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 ?

Jun 21 2017.log.txt (110.06kB)

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.

Were you able to obtain some results ?

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?

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)