box-node-sdk icon indicating copy to clipboard operation
box-node-sdk copied to clipboard

still getting 429 error - SDK does not seem to retry properly

Open wimdecorte opened this issue 3 years ago • 4 comments

Node app using service account / JWT with these retry settings: var sdk = BoxSDK.getPreconfiguredInstance(config); sdk.configure({ retryIntervalMS: 4000, // increase the base retry delay from 2s (default) to 4s numMaxRetries: 25, // increase the number of retries from 5 (default) to 10 }); var client = sdk.getAppAuthClient('enterprise');

With the default settings I was getting 429 errors trying to build a tree of all files and folders under a given folder. There are 30,000 folders and 100,000 files.

Adjusted the retry settings above to try and avoid the 429 errors but I'm still getting them, see error output below. Why would these still occur? My understanding is that the SDK will wait sufficiently long, even with the default settings to continue through the task.

phlt052:hooverBox wdecorte$ node standalone_tree.js (node:11916) TimeoutOverflowWarning: 2998087007 does not fit into a 32-bit signed integer. Timeout duration was set to 1. (node:11916) TimeoutOverflowWarning: 2885536496 does not fit into a 32-bit signed integer. Timeout duration was set to 1. (node:11916) TimeoutOverflowWarning: 3082915500 does not fit into a 32-bit signed integer. Timeout duration was set to 1. Error: 429 - Too Many Requests at APIRequest._handleResponse (/Users/wdecorte/Documents/GitHub/hooverBox/node_modules/box-node-sdk/lib/api-request.js:161:19) at Request.self.callback (/Users/wdecorte/Documents/GitHub/hooverBox/node_modules/request/request.js:185:22) at Request.emit (events.js:315:20) at Request. (/Users/wdecorte/Documents/GitHub/hooverBox/node_modules/request/request.js:1154:10) at Request.emit (events.js:315:20) at IncomingMessage. (/Users/wdecorte/Documents/GitHub/hooverBox/node_modules/request/request.js:1076:12) at Object.onceWrapper (events.js:421:28) at IncomingMessage.emit (events.js:327:22) at endReadableNT (_stream_readable.js:1220:12) at processTicksAndRejections (internal/process/task_queues.js:84:21) { request: Request { _events: [Object: null prototype] { error: [Function: bound ], complete: [Function: bound ], pipe: [Function], data: [Function], end: [Function] }, _eventsCount: 5, _maxListeners: undefined, strictSSL: true, agentClass: [Function: Agent], agentOptions: { keepAlive: true }, encoding: null, followRedirect: false, headers: { 'User-Agent': 'Box Node.js SDK v1.37.2 (Node v12.18.3)', Authorization: '[REMOVED BY SDK]', 'X-Box-UA': 'agent=box-node-sdk/1.37.2; env=Node/12.18.3', accept: 'application/json' }, method: 'GET', callback: [Function], readable: true, writable: true, explicitMethod: true, _qs: Querystring { request: [Circular], lib: [Object], useQuerystring: undefined, parseOptions: {}, stringifyOptions: {} }, _auth: Auth { request: [Circular], hasAuth: false, sentAuth: false, bearerToken: null, user: null, pass: null }, _oauth: OAuth { request: [Circular], params: null }, _multipart: Multipart { request: [Circular], boundary: '9fb529de-34dc-4a46-a7c9-b938eace2937', chunked: false, body: null }, _redirect: Redirect { request: [Circular], followRedirect: true, followRedirects: false, followAllRedirects: false, followOriginalHttpMethod: false, allowRedirect: [Function], maxRedirects: 10, redirects: [], redirectsFollowed: 0, removeRefererHeader: false }, _tunnel: Tunnel { request: [Circular], proxyHeaderWhiteList: [Array], proxyHeaderExclusiveList: [] }, setHeader: [Function], hasHeader: [Function], getHeader: [Function], removeHeader: [Function], localAddress: undefined, pool: { 'https:': [Agent] }, dests: [], __isRequestRequest: true, _callback: [Function: bound ], uri: Url { protocol: 'https:', slashes: true, auth: null, host: 'api.box.com', port: null, hostname: 'api.box.com', hash: null, search: '?fields=name%2Cmodified_at&sort=date&direction=DESC', query: 'fields=name%2Cmodified_at&sort=date&direction=DESC', pathname: '/2.0/folders/21824142453/items', path: '/2.0/folders/21824142453/items?fields=name%2Cmodified_at&sort=date&direction=DESC', href: 'https://api.box.com/2.0/folders/21824142453/items?fields=name%2Cmodified_at&sort=date&direction=DESC' }, proxy: null, tunnel: true, setHost: true, originalCookieHeader: undefined, _disableCookies: true, _jar: undefined, port: 443, host: 'api.box.com', url: Url { protocol: 'https:', slashes: true, auth: null, host: 'api.box.com', port: null, hostname: 'api.box.com', hash: null, search: '?fields=name%2Cmodified_at&sort=date&direction=DESC', query: 'fields=name%2Cmodified_at&sort=date&direction=DESC', pathname: '/2.0/folders/21824142453/items', path: '/2.0/folders/21824142453/items?fields=name%2Cmodified_at&sort=date&direction=DESC', href: 'https://api.box.com/2.0/folders/21824142453/items?fields=name%2Cmodified_at&sort=date&direction=DESC' }, path: '/2.0/folders/21824142453/items?fields=name%2Cmodified_at&sort=date&direction=DESC', _json: true, httpModule: { Agent: [Function: Agent], globalAgent: [Agent], Server: [Function: Server], createServer: [Function: createServer], get: [Function: get], request: [Function: request] }, agent: Agent { _events: [Object: null prototype], _eventsCount: 2, _maxListeners: undefined, defaultPort: 443, protocol: 'https:', options: [Object], requests: {}, sockets: [Object], freeSockets: [Object], keepAliveMsecs: 1000, keepAlive: true, maxSockets: Infinity, maxFreeSockets: 256, maxCachedSessions: 100, _sessionCache: [Object], [Symbol(kCapture)]: false }, _started: true, href: 'https://api.box.com/2.0/folders/21824142453/items?fields=name%2Cmodified_at&sort=date&direction=DESC', req: ClientRequest { _events: [Object: null prototype], _eventsCount: 5, _maxListeners: undefined, outputData: [], outputSize: 0, writable: true, _last: true, chunkedEncoding: false, shouldKeepAlive: true, useChunkedEncodingByDefault: false, sendDate: false, _removedConnection: false, _removedContLen: false, _removedTE: false, _contentLength: 0, _hasBody: true, _trailer: '', finished: true, _headerSent: true, socket: [TLSSocket], connection: [TLSSocket], _header: 'GET /2.0/folders/21824142453/items?fields=name%2Cmodified_at&sort=date&direction=DESC HTTP/1.1\r\n' + 'User-Agent: Box Node.js SDK v1.37.2 (Node v12.18.3)\r\n' + 'Authorization: Bearer hSDmsycyzBgu4rRedxvvspioxdoQNHiG\r\n' + 'X-Box-UA: agent=box-node-sdk/1.37.2; env=Node/12.18.3\r\n' + 'host: api.box.com\r\n' + 'accept: application/json\r\n' + 'Connection: keep-alive\r\n' + '\r\n', _onPendingData: [Function: noopPendingOutput], agent: [Agent], socketPath: undefined, method: 'GET', insecureHTTPParser: undefined, path: '/2.0/folders/21824142453/items?fields=name%2Cmodified_at&sort=date&direction=DESC', _ended: true, res: [IncomingMessage], aborted: false, timeoutCb: null, upgradeOrConnect: false, parser: null, maxHeadersCount: null, reusedSocket: true, [Symbol(kCapture)]: false, [Symbol(kNeedDrain)]: false, [Symbol(corked)]: 0, [Symbol(kOutHeaders)]: [Object: null prototype] }, ntick: true, response: IncomingMessage { _readableState: [ReadableState], readable: false, _events: [Object: null prototype], _eventsCount: 4, _maxListeners: undefined, socket: [TLSSocket], connection: [TLSSocket], httpVersionMajor: 1, httpVersionMinor: 1, httpVersion: '1.1', complete: true, headers: [Object], rawHeaders: [Array], trailers: {}, rawTrailers: [], aborted: false, upgrade: false, url: '', method: null, statusCode: 429, statusMessage: 'Too Many Requests', client: [TLSSocket], _consuming: true, _dumped: false, req: [ClientRequest], request: [Circular], toJSON: [Function: responseToJSON], caseless: [Caseless], body: [Object], [Symbol(kCapture)]: false }, originalHost: 'api.box.com', originalHostHeaderName: 'host', responseContent: IncomingMessage { _readableState: [ReadableState], readable: false, _events: [Object: null prototype], _eventsCount: 4, _maxListeners: undefined, socket: [TLSSocket], connection: [TLSSocket], httpVersionMajor: 1, httpVersionMinor: 1, httpVersion: '1.1', complete: true, headers: [Object], rawHeaders: [Array], trailers: {}, rawTrailers: [], aborted: false, upgrade: false, url: '', method: null, statusCode: 429, statusMessage: 'Too Many Requests', client: [TLSSocket], _consuming: true, _dumped: false, req: [ClientRequest], request: [Circular], toJSON: [Function: responseToJSON], caseless: [Caseless], body: [Object], [Symbol(kCapture)]: false }, _destdata: true, _ended: true, _callbackCalled: true, [Symbol(kCapture)]: false }, response: IncomingMessage { _readableState: ReadableState { objectMode: false, highWaterMark: 16384, buffer: BufferList { head: null, tail: null, length: 0 }, length: 0, pipes: null, pipesCount: 0, flowing: true, ended: true, endEmitted: true, reading: false, sync: false, needReadable: false, emittedReadable: false, readableListening: false, resumeScheduled: false, emitClose: true, autoDestroy: false, destroyed: false, defaultEncoding: 'utf8', awaitDrainWriters: null, multiAwaitDrain: false, readingMore: false, decoder: null, encoding: null, [Symbol(kPaused)]: false }, readable: false, _events: [Object: null prototype] { end: [Array], close: [Array], data: [Function], error: [Function] }, _eventsCount: 4, _maxListeners: undefined, socket: TLSSocket { _tlsOptions: [Object], _secureEstablished: true, _securePending: false, _newSessionPending: false, _controlReleased: true, secureConnecting: true, _SNICallback: null, servername: 'api.box.com', alpnProtocol: false, authorized: true, authorizationError: null, encrypted: true, _events: [Object: null prototype], _eventsCount: 11, connecting: false, _hadError: false, _parent: null, _host: 'api.box.com', _readableState: [ReadableState], readable: true, _maxListeners: undefined, _writableState: [WritableState], writable: true, allowHalfOpen: false, _sockname: null, _pendingData: null, _pendingEncoding: '', server: undefined, _server: null, ssl: [TLSWrap], _requestCert: true, _rejectUnauthorized: true, parser: [HTTPParser], _httpMessage: [ClientRequest], timeout: 0, [Symbol(res)]: [TLSWrap], [Symbol(verified)]: true, [Symbol(pendingSession)]: null, [Symbol(asyncId)]: 7265212, [Symbol(kHandle)]: [TLSWrap], [Symbol(kSetNoDelay)]: false, [Symbol(lastWriteQueueSize)]: 331, [Symbol(timeout)]: null, [Symbol(kBuffer)]: null, [Symbol(kBufferCb)]: null, [Symbol(kBufferGen)]: null, [Symbol(kCapture)]: false, [Symbol(kBytesRead)]: 0, [Symbol(kBytesWritten)]: 0, [Symbol(connect-options)]: [Object] }, connection: TLSSocket { _tlsOptions: [Object], _secureEstablished: true, _securePending: false, _newSessionPending: false, _controlReleased: true, secureConnecting: true, _SNICallback: null, servername: 'api.box.com', alpnProtocol: false, authorized: true, authorizationError: null, encrypted: true, _events: [Object: null prototype], _eventsCount: 11, connecting: false, _hadError: false, _parent: null, _host: 'api.box.com', _readableState: [ReadableState], readable: true, _maxListeners: undefined, _writableState: [WritableState], writable: true, allowHalfOpen: false, _sockname: null, _pendingData: null, _pendingEncoding: '', server: undefined, _server: null, ssl: [TLSWrap], _requestCert: true, _rejectUnauthorized: true, parser: [HTTPParser], _httpMessage: [ClientRequest], timeout: 0, [Symbol(res)]: [TLSWrap], [Symbol(verified)]: true, [Symbol(pendingSession)]: null, [Symbol(asyncId)]: 7265212, [Symbol(kHandle)]: [TLSWrap], [Symbol(kSetNoDelay)]: false, [Symbol(lastWriteQueueSize)]: 331, [Symbol(timeout)]: null, [Symbol(kBuffer)]: null, [Symbol(kBufferCb)]: null, [Symbol(kBufferGen)]: null, [Symbol(kCapture)]: false, [Symbol(kBytesRead)]: 0, [Symbol(kBytesWritten)]: 0, [Symbol(connect-options)]: [Object] }, httpVersionMajor: 1, httpVersionMinor: 1, httpVersion: '1.1', complete: true, headers: { date: 'Sun, 24 Oct 2021 18:28:39 GMT', 'content-type': 'application/json', 'transfer-encoding': 'chunked', connection: 'keep-alive', 'x-envoy-upstream-service-time': '69', 'box-request-id': '07b250677018068560cf9f34cffe66f91', 'retry-after': '9', 'cache-control': 'no-cache, no-store', 'strict-transport-security': 'max-age=31536000' }, rawHeaders: [ 'Date', 'Sun, 24 Oct 2021 18:28:39 GMT', 'Content-Type', 'application/json', 'Transfer-Encoding', 'chunked', 'Connection', 'keep-alive', 'x-envoy-upstream-service-time', '69', 'box-request-id', '07b250677018068560cf9f34cffe66f91', 'retry-after', '9', 'cache-control', 'no-cache, no-store', 'strict-transport-security', 'max-age=31536000' ], trailers: {}, rawTrailers: [], aborted: false, upgrade: false, url: '', method: null, statusCode: 429, statusMessage: 'Too Many Requests', client: TLSSocket { _tlsOptions: [Object], _secureEstablished: true, _securePending: false, _newSessionPending: false, _controlReleased: true, secureConnecting: true, _SNICallback: null, servername: 'api.box.com', alpnProtocol: false, authorized: true, authorizationError: null, encrypted: true, _events: [Object: null prototype], _eventsCount: 11, connecting: false, _hadError: false, _parent: null, _host: 'api.box.com', _readableState: [ReadableState], readable: true, _maxListeners: undefined, _writableState: [WritableState], writable: true, allowHalfOpen: false, _sockname: null, _pendingData: null, _pendingEncoding: '', server: undefined, _server: null, ssl: [TLSWrap], _requestCert: true, _rejectUnauthorized: true, parser: [HTTPParser], _httpMessage: [ClientRequest], timeout: 0, [Symbol(res)]: [TLSWrap], [Symbol(verified)]: true, [Symbol(pendingSession)]: null, [Symbol(asyncId)]: 7265212, [Symbol(kHandle)]: [TLSWrap], [Symbol(kSetNoDelay)]: false, [Symbol(lastWriteQueueSize)]: 331, [Symbol(timeout)]: null, [Symbol(kBuffer)]: null, [Symbol(kBufferCb)]: null, [Symbol(kBufferGen)]: null, [Symbol(kCapture)]: false, [Symbol(kBytesRead)]: 0, [Symbol(kBytesWritten)]: 0, [Symbol(connect-options)]: [Object] }, _consuming: true, _dumped: false, req: ClientRequest { _events: [Object: null prototype], _eventsCount: 5, _maxListeners: undefined, outputData: [], outputSize: 0, writable: true, _last: true, chunkedEncoding: false, shouldKeepAlive: true, useChunkedEncodingByDefault: false, sendDate: false, _removedConnection: false, _removedContLen: false, _removedTE: false, _contentLength: 0, _hasBody: true, _trailer: '', finished: true, _headerSent: true, socket: [TLSSocket], connection: [TLSSocket], _header: 'GET /2.0/folders/21824142453/items?fields=name%2Cmodified_at&sort=date&direction=DESC HTTP/1.1\r\n' + 'User-Agent: Box Node.js SDK v1.37.2 (Node v12.18.3)\r\n' + 'Authorization: Bearer hSDmsycyzBgu4rRedxvvspioxdoQNHiG\r\n' + 'X-Box-UA: agent=box-node-sdk/1.37.2; env=Node/12.18.3\r\n' + 'host: api.box.com\r\n' + 'accept: application/json\r\n' + 'Connection: keep-alive\r\n' + '\r\n', _onPendingData: [Function: noopPendingOutput], agent: [Agent], socketPath: undefined, method: 'GET', insecureHTTPParser: undefined, path: '/2.0/folders/21824142453/items?fields=name%2Cmodified_at&sort=date&direction=DESC', _ended: true, res: [Circular], aborted: false, timeoutCb: null, upgradeOrConnect: false, parser: null, maxHeadersCount: null, reusedSocket: true, [Symbol(kCapture)]: false, [Symbol(kNeedDrain)]: false, [Symbol(corked)]: 0, [Symbol(kOutHeaders)]: [Object: null prototype] }, request: Request { _events: [Object: null prototype], _eventsCount: 5, _maxListeners: undefined, strictSSL: true, agentClass: [Function: Agent], agentOptions: [Object], encoding: null, followRedirect: false, headers: [Object], method: 'GET', callback: [Function], readable: true, writable: true, explicitMethod: true, _qs: [Querystring], _auth: [Auth], _oauth: [OAuth], _multipart: [Multipart], _redirect: [Redirect], _tunnel: [Tunnel], setHeader: [Function], hasHeader: [Function], getHeader: [Function], removeHeader: [Function], localAddress: undefined, pool: [Object], dests: [], __isRequestRequest: true, _callback: [Function: bound ], uri: [Url], proxy: null, tunnel: true, setHost: true, originalCookieHeader: undefined, _disableCookies: true, _jar: undefined, port: 443, host: 'api.box.com', url: [Url], path: '/2.0/folders/21824142453/items?fields=name%2Cmodified_at&sort=date&direction=DESC', _json: true, httpModule: [Object], agent: [Agent], _started: true, href: 'https://api.box.com/2.0/folders/21824142453/items?fields=name%2Cmodified_at&sort=date&direction=DESC', req: [ClientRequest], ntick: true, response: [Circular], originalHost: 'api.box.com', originalHostHeaderName: 'host', responseContent: [Circular], _destdata: true, _ended: true, _callbackCalled: true, [Symbol(kCapture)]: false }, toJSON: [Function: responseToJSON], caseless: Caseless { dict: [Object] }, body: { type: 'error', status: 429, code: 'rate_limit_exceeded', help_url: 'http://developers.box.com/docs/#errors', message: 'Request rate limit exceeded, please try again later', request_id: 'aozie0gvqypn0ddd' }, [Symbol(kCapture)]: false }, statusCode: 429, maxRetriesExceeded: true } (node:11916) TimeoutOverflowWarning: 3203498104 does not fit into a 32-bit signed integer. Timeout duration was set to 1.

wimdecorte avatar Oct 25 '21 10:10 wimdecorte

This is a really bad catch 22, if I try to slow down my code now I'm getting

response: Error: Expired Auth: Auth code or refresh token has expired [401 Unauthorized |

So the SDK doesn't even try to keep track of the token expiry and refresh it?

wimdecorte avatar Oct 26 '21 16:10 wimdecorte

Hi @wimdecorte

Thanks for reaching out to us!

Adjusted the retry settings above to try and avoid the 429 errors but I'm still getting them, see error output below. Why would these still occur? My understanding is that the SDK will wait sufficiently long, even with the default settings to continue through the task.

The SDK will attempt to retry the request for status codes 429 and 500+. It will stop trying to do this if you hit your limit defined in the configuration by numMaxRetries. This is to prevent the request from retrying indefinitely.

So the SDK doesn't even try to keep track of the token expiry and refresh it?

The SDK will attempt to refresh the token if it has expired.

Also regarding the 401 error, could you provide some example code and/or a stack trace? My guess is that "slowing down" the code may cause some issues with tokens.

Thanks, @mwwoda

mwwoda avatar Oct 27 '21 13:10 mwwoda

I'm seeing neither of those happen, see the output in my two posts. I do see error 429 and the token expiry error.

wimdecorte avatar Oct 27 '21 13:10 wimdecorte

When a client makes initial request and no token is provided, there will be call for the token before the request. For the each subsequent call, the token will be checked for validity based on the TTL of the token (the expires_in field) before the request is sent. If it is no longer valid, a call will be made for a new token. I can confirm that this behaviour still applies to the newest SDK version. I couldn't reproduce your issue with the sample provided. If the slowdown you mentioned was applied between the token validation and the request itself, this could cause the unexpected error you are seeing.

As for the 429 error. You can use either the default retry strategy (which relies on the retry-after header, or retryInterval if there isn't one) or you can define your own strategy. It could be the case that you are hitting the limits of your configuration. Please refer to the rate limit documentation and try adjust it accordingly.

mwwoda avatar Oct 27 '21 15:10 mwwoda

This issue has been automatically marked as stale because it has not been updated in the last 30 days. It will be closed if no further activity occurs within the next 7 days. Feel free to reach out or mention Box SDK team member for further help and resources if they are needed.

stale[bot] avatar Dec 19 '22 19:12 stale[bot]

This issue has been automatically closed due to maximum period of being stale. Thank you for your contribution to Box Node SDK and feel free to open another PR/issue at any time.

stale[bot] avatar Dec 26 '22 20:12 stale[bot]