Error when creating milestones in parallel

[maxceem]

During project creation in connect-app we create a timeline, and after, create several milestones for the timeline. To make it work faster, milestones for the timeline are created in parallel.

When there are 5 milestones for one timeline are being created in parallel, 4 of them are created successfully, while during creation of the 5th one server respsond with the next error

{
  "id": "3a71a86a-441e-45df-beb1-c623279b448e",
  "result": {
    "success": false,
    "status": 500,
    "content": {
      "message": "could not serialize access due to concurrent update"
    },
    "debug": "SequelizeDatabaseError: could not serialize access due to concurrent update\n
        at Query.formatError (/usr/src/app/node_modules/sequelize/lib/dialects/postgres/query.js:357:14)\n
        at Query.<anonymous> (/usr/src/app/node_modules/sequelize/lib/dialects/postgres/query.js:88:19)\n
        at emitOne (events.js:115:13)\n
        at Query.emit (events.js:210:7)\n
        at Query.handleError (/usr/src/app/node_modules/pg/lib/query.js:108:8)\n
        at Connection.<anonymous> (/usr/src/app/node_modules/pg/lib/client.js:171:26)\n
        at emitOne (events.js:115:13)\n
        at Connection.emit (events.js:210:7)\n
        at Socket.<anonymous> (/usr/src/app/node_modules/pg/lib/connection.js:109:12)\n
        at emitOne (events.js:115:13)\n
        at Socket.emit (events.js:210:7)\n
        at addChunk (_stream_readable.js:252:12)\n
        at readableAddChunk (_stream_readable.js:239:11)\n
        at Socket.Readable.push (_stream_readable.js:197:10)\n
        at TCP.onread [as _originalOnread] (net.js:589:20)\n
        at TCP.onread (/usr/src/app/node_modules/async-listener/glue.js:188:31)\n
    From previous event:\n
        at Query.run (/usr/src/app/node_modules/sequelize/lib/dialects/postgres/query.js:74:17)\n
        at /usr/src/app/node_modules/sequelize/lib/sequelize.js:849:20\n
        at /usr/src/app/node_modules/retry-as-promised/index.js:39:21\n
    From previous event:\n
        at retryAsPromised (/usr/src/app/node_modules/retry-as-promised/index.js:29:10)\n
        at /usr/src/app/node_modules/sequelize/lib/sequelize.js:848:12\n
    From previous event:\n
        at Promise.then (/usr/src/app/node_modules/sequelize/lib/promise.js:21:17)\n
        at transactionResolver (/usr/src/app/node_modules/sequelize/lib/sequelize.js:1284:40)\n
        at /usr/src/app/node_modules/continuation-local-storage/context.js:84:17\n
    From previous event:\n
        at Sequelize.transaction (/usr/src/app/node_modules/sequelize/lib/sequelize.js:1313:12)\n
        at module.exports (/usr/src/app/dist/routes/milestones/create.js:94:37)\n
        at Layer.handle [as handle_request] (/usr/src/app/node_modules/express/lib/router/layer.js:95:5)\n
        at next (/usr/src/app/node_modules/express/lib/router/route.js:137:13)\n
        at authorizer.can.then (/usr/src/app/node_modules/tc-core-library-js/lib/middleware/permissions.js:10:9)\n
        at propagateAslWrapper (/usr/src/app/node_modules/async-listener/index.js:478:23)\n
        at /usr/src/app/node_modules/async-listener/glue.js:188:31\n
        at /usr/src/app/node_modules/async-listener/index.js:515:70\n
        at /usr/src/app/node_modules/async-listener/glue.js:188:31\n
        at <anonymous>\n
        at process._tickDomainCallback [as _tickCallback] (internal/process/next_tick.js:228:7)"
  }
}

This issue may be ignored if the bulk milestone creation is implemented regarding #108

Thouhg it could make sense taking a look anyway, to check if this issue may occur in other situations.

[vikasrohit]

#108 is implemented, so we do not need to create milestones in parallel. However, we do need to investigate the error because it can occur when there are two projects created at the exact same time, we might see similar issue at that time. May be we should increase the lock wait time to improve the threshold.

[gondzo]

Similar issue is present in GET /projects/{projectId}/phases/{phaseId} when running tests on CI
https://circleci.com/gh/topcoder-platform/tc-project-service/714

[vikasrohit]

@coderReview I have committed few changes for fixing this as it was causing issues with the front end development. We may use this issue, as part of the challenge, to verify that the issue no longer there.

[vikasrohit]

@gondzo I have tried to fix the issue with phases and other models as well. Basically, we were returning the HTTP response before committing the transaction. That might have been taking the time which is causing other calls to fail.

[maxceem]

I come across this issue at another place.
When we update startDate together with the status of the phase, frontend updates it, and also make a cascading update of the timeline and first milestone. For example, if update startDate and status of the phase in this project http://connect.topcoder-dev.com/projects/6954/phase/1143
It works like this:

• update phase - OK
• update timeline - OK
• update first milestone - ERROR

{
  "id": "8c2ccaa9-f6fc-4c2e-815b-22176228cad8",
  "result": {
    "success": false,
    "status": 500,
    "content": {
      "message": "could not serialize access due to concurrent update"
    },
    "debug": "SequelizeDatabaseError: could not serialize access due to concurrent update\n    at Query.formatError (/usr/src/app/node_modules/sequelize/lib/dialects/postgres/query.js:357:14)\n    at Query.<anonymous> (/usr/src/app/node_modules/sequelize/lib/dialects/postgres/query.js:88:19)\n    at emitOne (events.js:115:13)\n    at Query.emit (events.js:210:7)\n    at Query.handleError (/usr/src/app/node_modules/pg/lib/query.js:108:8)\n    at Connection.<anonymous> (/usr/src/app/node_modules/pg/lib/client.js:171:26)\n    at emitOne (events.js:115:13)\n    at Connection.emit (events.js:210:7)\n    at Socket.<anonymous> (/usr/src/app/node_modules/pg/lib/connection.js:109:12)\n    at emitOne (events.js:115:13)\n    at Socket.emit (events.js:210:7)\n    at addChunk (_stream_readable.js:252:12)\n    at readableAddChunk (_stream_readable.js:239:11)\n    at Socket.Readable.push (_stream_readable.js:197:10)\n    at TCP.onread [as _originalOnread] (net.js:589:20)\n    at TCP.onread (/usr/src/app/node_modules/async-listener/glue.js:188:31)\nFrom previous event:\n    at Query.run (/usr/src/app/node_modules/sequelize/lib/dialects/postgres/query.js:74:17)\n    at /usr/src/app/node_modules/sequelize/lib/sequelize.js:849:20\n    at /usr/src/app/node_modules/retry-as-promised/index.js:39:21\nFrom previous event:\n    at retryAsPromised (/usr/src/app/node_modules/retry-as-promised/index.js:29:10)\n    at /usr/src/app/node_modules/sequelize/lib/sequelize.js:848:12\n    at /usr/src/app/node_modules/continuation-local-storage/context.js:84:17\nFrom previous event:\n    at Promise.then (/usr/src/app/node_modules/sequelize/lib/promise.js:21:17)\n    at transactionResolver (/usr/src/app/node_modules/sequelize/lib/sequelize.js:1284:40)\n    at /usr/src/app/node_modules/continuation-local-storage/context.js:84:17\nFrom previous event:\n    at Sequelize.transaction (/usr/src/app/node_modules/sequelize/lib/sequelize.js:1313:12)\n    at module.exports (/usr/src/app/dist/routes/milestones/update.js:152:37)\n    at Layer.handle [as handle_request] (/usr/src/app/node_modules/express/lib/router/layer.js:95:5)\n    at next (/usr/src/app/node_modules/express/lib/router/route.js:137:13)\n    at authorizer.can.then (/usr/src/app/node_modules/tc-core-library-js/lib/middleware/permissions.js:10:9)\n    at propagateAslWrapper (/usr/src/app/node_modules/async-listener/index.js:478:23)\n    at /usr/src/app/node_modules/async-listener/glue.js:188:31\n    at /usr/src/app/node_modules/async-listener/index.js:515:70\n    at /usr/src/app/node_modules/async-listener/glue.js:188:31\n    at <anonymous>\n    at process._tickDomainCallback [as _tickCallback] (internal/process/next_tick.js:228:7)"
  }
}

[vikasrohit]

@coderReview Do you know what exactly was fixed for this issue in the F2F? I didn't see any specific changes for this issue.

[vikasrohit]

update first milestone - ERROR

@maxceem we have the logic in backend to automatically update the dates of the the first milestone according to the changes in the dates of the timeline. So, you don't need to make a separate call to update the dates of the first milestone when you have updated the dates of the timeline. However, I think when you need to update the status of the first milestone for the same user action, you need to make a call to PATCH the status of the individual milestone. I think for now you can make those calls sequential, i.e. send PATCH to update milestone's status only after timeline's update is returned successfully.
Other alternative is to maintain a status field on timeline as well and front end would just send the single patch request to update both startDate and status of the timeline and it should take care of the appropriate status of the first milestone. However, I think that would increase one more status field maintenance and might cause more confusion and inconsistencies in future. So, I would like to go with first approach, unless we have a very solid argument to not do so.

[coderReview]

@vikasrohit I think you said you provided a fix yourself.