[$100] Deadlock on dev

[jmgasper]

@atelomycterus - This was seen in the logs on dev:

I'm wondering if:

1. Maybe we should add a retry mechanism to the challenge forum processor?
2. If this is a bug in our version of Vanilla that has been fixed in a more recent update?

2021-07-06T10:40:07.680-04:00	{ Error: cannot POST /api/v2/categories?access_token=va.HNbQh52LEsnvn6KQgJCmS10Zv_-jAJ9M.xzFBcg.3yMpRqr (500)
2021-07-06T10:40:07.680-04:00	at Response.toError (/challenge-forum-processor/node_modules/superagent/lib/node/response.js:98:13)
2021-07-06T10:40:07.680-04:00	at ResponseBase._setStatusProperties (/challenge-forum-processor/node_modules/superagent/lib/response-base.js:119:48)
2021-07-06T10:40:07.680-04:00	at new Response (/challenge-forum-processor/node_modules/superagent/lib/node/response.js:44:8)
2021-07-06T10:40:07.680-04:00	at Request._emitResponse (/challenge-forum-processor/node_modules/superagent/lib/node/index.js:918:18)
2021-07-06T10:40:07.680-04:00	at /challenge-forum-processor/node_modules/superagent/lib/node/index.js:1114:42
2021-07-06T10:40:07.680-04:00	at IncomingMessage.<anonymous> (/challenge-forum-processor/node_modules/superagent/lib/node/parsers/json.js:22:7)
2021-07-06T10:40:07.680-04:00	at emitNone (events.js:111:20)
2021-07-06T10:40:07.680-04:00	at IncomingMessage.emit (events.js:208:7)
2021-07-06T10:40:07.680-04:00	at endReadableNT (_stream_readable.js:1064:12)
2021-07-06T10:40:07.680-04:00	at _combinedTickCallback (internal/process/next_tick.js:139:11)
2021-07-06T10:40:07.680-04:00	at process._tickCallback (internal/process/next_tick.js:181:9)
2021-07-06T10:40:07.680-04:00	status: 500,
2021-07-06T10:40:07.680-04:00	text: '{\n "message": "Deadlock found when trying to get lock; try restarting transaction|Gdn_Database|Query|update `GDN_Category` `Category`\\nset `TreeLeft` = :TreeLeft,\\n `TreeRight` = :TreeRight,\\n `Depth` = :Depth,\\n `PermissionCategoryID` = :PermissionCategoryID,\\n `ParentCategoryID` = :ParentCategoryID,\\n `Sort` = :Sort\\nwhere `CategoryID` = :CategoryID"\n}',
2021-07-06T10:40:07.680-04:00	method: 'POST',
2021-07-06T10:40:07.680-04:00	path: '/api/v2/categories?access_token=va.HNbQh52LEsnvn6KQgJCmS10Zv_-jAJ9M.xzFBcg.3yMpRqr' },
2021-07-06T10:40:07.680-04:00	created: false,
2021-07-06T10:40:07.680-04:00	accepted: false,
2021-07-06T10:40:07.680-04:00	noContent: false,
2021-07-06T10:40:07.680-04:00	badRequest: false,
2021-07-06T10:40:07.680-04:00	unauthorized: false,
2021-07-06T10:40:07.680-04:00	notAcceptable: false,
2021-07-06T10:40:07.680-04:00	forbidden: false,
2021-07-06T10:40:07.680-04:00	notFound: false,
2021-07-06T10:40:07.680-04:00	unprocessableEntity: false,
2021-07-06T10:40:07.680-04:00	type: 'application/json',
2021-07-06T10:40:07.680-04:00	charset: 'utf-8',
2021-07-06T10:40:07.680-04:00	links: {},
2021-07-06T10:40:07.680-04:00	setEncoding: [Function: bound ],
2021-07-06T10:40:07.680-04:00	redirects: [],
2021-07-06T10:40:07.680-04:00	pipe: [Function] } }

[jmgasper]

Challenge https://www.topcoder.com/challenges/d9fe1246-9da7-40a9-b512-824395922a1a has been created for this ticket.

This is an automated message for ghostar via Topcoder X

[jmgasper]

Challenge https://www.topcoder.com/challenges/d9fe1246-9da7-40a9-b512-824395922a1a has been assigned to obog.

This is an automated message for ghostar via Topcoder X

[atelomycterus]

@jmgasper Please apply PR-topcoder-platform/challenge-forum-processor#64.

This error has already appeared periodically before and is not related to our customizations. I see the errors in the logs from March. This error occurs when a challenge forum processor receives several 'challenge.notification.update' and / or challenge.action.resource.create events at the same time.

In other words, multiple REST API requests (/categories (POST, PATCH)) were executed every 10-15 milliseconds. Both REST API methods call the rebuildCategoryTree method to update the category table.

I have already looked at the Vanilla Category Rest API. We need to leave only the fields necessary for updating and remove the unmodifiable fields (parentCategoryID). Thus, /category (PATCH) request will not call the rebuild category tree.

I've fixed a challenge forum processor. Let me know if you notice any issues. Thanks!

Logs

challenge.action.resource.create events: Adding a new category

�[33m2021-03-30T05:47:18.993Z�[39m [�[31merror�[39m]: { Error: Internal Server Error
    at Request.callback (/challenge-forum-processor/node_modules/superagent/lib/node/index.js:871:15)
    at /challenge-forum-processor/node_modules/superagent/lib/node/index.js:1114:20
    at IncomingMessage.<anonymous> (/challenge-forum-processor/node_modules/superagent/lib/node/parsers/json.js:22:7)
    at emitNone (events.js:111:20)
    at IncomingMessage.emit (events.js:208:7)
    at endReadableNT (_stream_readable.js:1064:12)
    at _combinedTickCallback (internal/process/next_tick.js:139:11)
    at process._tickCallback (internal/process/next_tick.js:181:9)
  status: 500,
  response: 
   Response {
     domain: null,
     _events: {},
     _eventsCount: 0,
     _maxListeners: undefined,
     res: 
      IncomingMessage {
        _readableState: [Object],
        readable: false,
        domain: null,
        _events: [Object],
        _eventsCount: 4,
        _maxListeners: undefined,
        socket: [Object],
        connection: [Object],
        httpVersionMajor: 1,
        httpVersionMinor: 1,
        httpVersion: '1.1',
        complete: true,
        headers: [Object],
        rawHeaders: [Array],
        trailers: {},
        rawTrailers: [],
        upgrade: false,
        url: '',
        method: null,
        statusCode: 500,
        statusMessage: 'Internal Server Error',
        client: [Object],
        _consuming: true,
        _dumped: false,
        req: [Object],
        text: '{\n    "message": "Deadlock found when trying to get lock; try restarting transaction|Gdn_Database|Query|update `GDN_Category` `Category`\\nset `TreeLeft` = :TreeLeft,\\n `TreeRight` = :TreeRight,\\n `Depth` = :Depth,\\n `PermissionCategoryID` = :PermissionCategoryID,\\n `ParentCategoryID` = :ParentCategoryID,\\n `Sort` = :Sort\\nwhere `CategoryID` = :CategoryID"\n}',
        read: [Function] },
     request: 
      Request {
        domain: null,
        _events: [Object],
        _eventsCount: 1,
        _maxListeners: undefined,
        _enableHttp2: false,
        _agent: false,
        _formData: null,
        method: 'POST',
        url: 'https://vanilla.topcoder-dev.com/api/v2/categories?access_token=va.HNbQh52LEsnvn6KQgJCmS10Zv_-jAJ9M.xzFBcg.3yMpRqr',
        _header: [Object],
        header: [Object],
        writable: true,
        _redirects: 0,
        _maxRedirects: 5,
        cookies: '',
        qs: {},
        _query: [],
        qsRaw: [],
        _redirectList: [],
        _streamRequest: false,
        _data: [Object],
        req: [Object],
        protocol: 'https:',
        host: 'vanilla.topcoder-dev.com',
        _endCalled: true,
        _callback: [Function],
        _fullfilledPromise: [Object],
        res: [Object],
        _resBuffered: true,
        response: [Circular],
        called: true },
     req: 
      ClientRequest {
        domain: null,
        _events: [Object],
        _eventsCount: 3,
        _maxListeners: undefined,
        output: [],
        outputEncodings: [],
        outputCallbacks: [],
        outputSize: 0,
        writable: true,
        _last: true,
        upgrading: false,
        chunkedEncoding: false,
        shouldKeepAlive: false,
        useChunkedEncodingByDefault: true,
        sendDate: false,
        _removedConnection: false,
        _removedContLen: false,
        _removedTE: false,
        _contentLength: 138,
        _hasBody: true,
        _trailer: '',
        finished: true,
        _headerSent: true,
        socket: [Object],
        connection: [Object],
        _header: 'POST /api/v2/categories?access_token=va.HNbQh52LEsnvn6KQgJCmS10Zv_-jAJ9M.xzFBcg.3yMpRqr HTTP/1.1\r\nHost: vanilla.topcoder-dev.com\r\nAccept-Encoding: gzip, deflate\r\nContent-Type: application/json\r\nContent-Length: 138\r\nConnection: close\r\n\r\n',
        _onPendingData: [Function: noopPendingOutput],
        agent: [Object],
        socketPath: undefined,
        timeout: undefined,
        method: 'POST',
        path: '/api/v2/categories?access_token=va.HNbQh52LEsnvn6KQgJCmS10Zv_-jAJ9M.xzFBcg.3yMpRqr',
        _ended: true,
        res: [Object],
        aborted: undefined,
        timeoutCb: null,
        upgradeOrConnect: false,
        parser: null,
        maxHeadersCount: null,
        [Symbol(outHeadersKey)]: [Object] },
     text: '{\n    "message": "Deadlock found when trying to get lock; try restarting transaction|Gdn_Database|Query|update `GDN_Category` `Category`\\nset `TreeLeft` = :TreeLeft,\\n `TreeRight` = :TreeRight,\\n `Depth` = :Depth,\\n `PermissionCategoryID` = :PermissionCategoryID,\\n `ParentCategoryID` = :ParentCategoryID,\\n `Sort` = :Sort\\nwhere `CategoryID` = :CategoryID"\n}', 

challenge.notification.update: Patch a category

�[33m2021-03-30T06:54:23.997Z�[39m [�[31merror�[39m]: { Error: Internal Server Error
    at Request.callback (/challenge-forum-processor/node_modules/superagent/lib/node/index.js:871:15)
    at /challenge-forum-processor/node_modules/superagent/lib/node/index.js:1114:20
    at IncomingMessage.<anonymous> (/challenge-forum-processor/node_modules/superagent/lib/node/parsers/json.js:22:7)
    at emitNone (events.js:111:20)
    at IncomingMessage.emit (events.js:208:7)
    at endReadableNT (_stream_readable.js:1064:12)
    at _combinedTickCallback (internal/process/next_tick.js:139:11)
    at process._tickCallback (internal/process/next_tick.js:181:9)
  status: 500,
  response: 
   Response {
     domain: null,
     _events: {},
     _eventsCount: 0,
     _maxListeners: undefined,
     res: 
      IncomingMessage {
        _readableState: [Object],
        readable: false,
        domain: null,
        _events: [Object],
        _eventsCount: 4,
        _maxListeners: undefined,
        socket: [Object],
        connection: [Object],
        httpVersionMajor: 1,
        httpVersionMinor: 1,
        httpVersion: '1.1',
        complete: true,
        headers: [Object],
        rawHeaders: [Array],
        trailers: {},
        rawTrailers: [],
        upgrade: false,
        url: '',
        method: null,
        statusCode: 500,
        statusMessage: 'Internal Server Error',
        client: [Object],
        _consuming: true,
        _dumped: false,
        req: [Object],
        text: '{\n    "message": "Deadlock found when trying to get lock; try restarting transaction|Gdn_Database|Query|update GDN_Category p\\njoin GDN_Category c\\n\\ton c.ParentCategoryID = p.CategoryID\\nset c.Depth = p.Depth + 1\\nwhere p.Depth = :depth;"\n}',
        read: [Function] },
     request: 
      Request {
        domain: null,
        _events: [Object],
        _eventsCount: 1,
        _maxListeners: undefined,
        _enableHttp2: false,
        _agent: false,
        _formData: null,
        method: 'PATCH',
        url: 'https://vanilla.topcoder-dev.com/api/v2/categories/3671?access_token=va.HNbQh52LEsnvn6KQgJCmS10Zv_-jAJ9M.xzFBcg.3yMpRqr',
        _header: [Object],
        header: [Object],
        writable: true,
        _redirects: 0,
        _maxRedirects: 5,
        cookies: '',
        qs: {},
        _query: [],
        qsRaw: [],
        _redirectList: [],
        _streamRequest: false,
        _data: [Object],
        req: [Object],
        protocol: 'https:',
        host: 'vanilla.topcoder-dev.com',
        _endCalled: true,
        _callback: [Function],
        _fullfilledPromise: [Object],
        res: [Object],
        _resBuffered: true,
        response: [Circular],
        called: true },
     req: 
      ClientRequest {
        domain: null,
        _events: [Object],
        _eventsCount: 3,
        _maxListeners: undefined,
        output: [],
        outputEncodings: [],
        outputCallbacks: [],
        outputSize: 0,
        writable: true,
        _last: true,
        upgrading: false,
        chunkedEncoding: false,
        shouldKeepAlive: false,
        useChunkedEncodingByDefault: true,
        sendDate: false,
        _removedConnection: false,
        _removedContLen: false,
        _removedTE: false,
        _contentLength: 167,
        _hasBody: true,
        _trailer: '',
        finished: true,
        _headerSent: true,
        socket: [Object],
        connection: [Object],
        _header: 'PATCH /api/v2/categories/3671?access_token=va.HNbQh52LEsnvn6KQgJCmS10Zv_-jAJ9M.xzFBcg.3yMpRqr HTTP/1.1\r\nHost: vanilla.topcoder-dev.com\r\nAccept-Encoding: gzip, deflate\r\nContent-Type: application/json\r\nContent-Length: 167\r\nConnection: close\r\n\r\n',
        _onPendingData: [Function: noopPendingOutput],
        agent: [Object],
        socketPath: undefined,
        timeout: undefined,
        method: 'PATCH',
        path: '/api/v2/categories/3671?access_token=va.HNbQh52LEsnvn6KQgJCmS10Zv_

[jmgasper]

Seems OK - I'll keep testing and let you know if we run into this again, thanks!

[jmgasper]

Payment task has been updated: https://www.topcoder.com/challenges/d9fe1246-9da7-40a9-b512-824395922a1a
Payments Complete
Winner: obog
Copilot: ghostar
Challenge d9fe1246-9da7-40a9-b512-824395922a1a has been paid and closed.

This is an automated message for ghostar via Topcoder X