httpOptions.timeout not used as expected

[mriedem]

This is more of a question about how the httpOptions.timeout config option is supposed to work or be applied.

I'm overriding that to 5 seconds and verified it's showing up in the S3 service object instance I'm using:

Service {
  config: Config {
    credentials: Credentials {
      expired: true,
      expireTime: null,
      serviceInstanceId: 'crn:v1:bluemix:public:cloud-object-storage:global:a/3f0eacee15cc4551a4b51313a4a1f2d2:d4cc5fd0-490d-424c-bbb7-75cf269eb8f9::',
      authCallback: undefined,
      tokenManager: undefined,
      ibmAuthEndpoint: undefined,
      accessKeyId: '***',
      sessionToken: undefined,
      httpOptions: [Object]
    },
    credentialProvider: CredentialProviderChain {
      providers: [Array],
      resolveCallbacks: []
    },
    region: 'us-east-1',
    logger: Logger {
      _events: [Object: null prototype] {},
      _eventsCount: 0,
      _maxListeners: undefined,
      _level: 30,
      streams: [Array],
      serializers: [Object],
      src: false,
      fields: [Object],
      log: [Function],
      [Symbol(kCapture)]: false
    },
    apiVersions: {},
    apiVersion: null,
    endpoint: 'https://s3.private.us-south.cloud-object-storage.appdomain.cloud',
    httpOptions: { timeout: 5000 },
    maxRetries: undefined,
    maxRedirects: 10,
    paramValidation: true,
    sslEnabled: true,
    s3ForcePathStyle: false,
    s3BucketEndpoint: false,
    s3DisableBodySigning: true,
    computeChecksums: true,
    convertResponseTypes: true,
    correctClockSkew: false,
    customUserAgent: null,
    dynamoDbCrc32: true,
    systemClockOffset: 0,
    signatureVersion: 'v4',
    signatureCache: true,
    retryDelayOptions: { base: 100 },
    useAccelerateEndpoint: false,
    apiKeyId: '***',
    serviceInstanceId: 'crn:v1:bluemix:public:cloud-object-storage:global:a/3f0eacee15cc4551a4b51313a4a1f2d2:d4cc5fd0-490d-424c-bbb7-75cf269eb8f9::',
    accessKeyId: '***',
    secretAccessKey: '***',
    params: { Bucket: 'ibmq-jupyterhub-userdirs-staging' }
  },
  endpoint: Endpoint {
    protocol: 'https:',
    host: 's3.private.us-south.cloud-object-storage.appdomain.cloud',
    port: 443,
    hostname: 's3.private.us-south.cloud-object-storage.appdomain.cloud',
    pathname: '/',
    path: '/',
    href: 'https://s3.private.us-south.cloud-object-storage.appdomain.cloud/'
  },
  _clientId: 1
}

I'm intentionally trying to test the timeout is working by using a private endpoint (https://s3.private.us-south.cloud-object-storage.appdomain.cloud/) and running locally rather than in the IBM Cloud so I get an error:

$ curl -H "x-access-token: ${TOKEN}" http://localhost:3000/home/.bash_history
connect ECONNREFUSED 10.1.129.97:443

The confusing thing is that the timeout is after about 86 seconds rather than the expected 5 seconds - from the server logs:

{"name":"app-server","hostname":"osboxes","pid":3719,"level":50,"err":{"message":"connect ECONNREFUSED 10.1.129.97:443","name":"NetworkingError","stack":"Error: connect ECONNREFUSED 10.1.129.97:443\n    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1141:16)","code":"NetworkingError"},"msg":"GET /home/.bash_history","time":"2020-10-28T13:00:36.458Z","v":0}
{"name":"app-server","hostname":"osboxes","pid":3719,"level":30,"msg":"GET /home/.bash_history 500 36 - 86219.764 ms\n","time":"2020-10-28T13:00:36.462Z","v":0}

In this case the s3 API I'm using is listObjectsV2.

Does the httpOptions.timeout value only apply once a connection to S3 is successfully made and then we can timeout while waiting for a response on the listObjectsV2 request? Based on the description in the docs [1]:

timeout [Integer] — The number of milliseconds to wait before giving up on a connection attempt. Defaults to two minutes (120000).

I figured "connection attempt" would apply to even trying to make a connection to the s3 endpoint.

I'm using this version:

$ npm ls ibm-cos-sdk
ibmq-jupyterhub-cos-api@0.8.0 /home/osboxes/ibmq/ibmq-jupyterhub-cos-api
└── ibm-cos-sdk@1.7.0 

Like I said, this is more a question for understanding on how the timeout is applied, I'm not saying this is a bug.

[1] https://ibm.github.io/ibm-cos-sdk-js/AWS/Config.html#httpOptions-property

[mriedem]

Just as a comparison, I switched back to the public s3 endpoint and changed the timeout to 100ms and was able to trigger the timeout:

{"name":"app-server","hostname":"osboxes","pid":5811,"level":50,"err":{"message":"Missing credentials in config","name":"TimeoutError","stack":"TimeoutError: Missing credentials in config\n    at ClientRequest.<anonymous> (/home/osboxes/ibmq/ibmq-jupyterhub-cos-api/node_modules/ibm-cos-sdk/lib/http/node.js:86:34)\n    at Object.onceWrapper (events.js:416:28)\n    at ClientRequest.emit (events.js:310:20)\n    at ClientRequest.EventEmitter.emit (domain.js:482:12)\n    at TLSSocket.emitRequestTimeout (_http_client.js:714:9)\n    at Object.onceWrapper (events.js:416:28)\n    at TLSSocket.emit (events.js:310:20)\n    at TLSSocket.EventEmitter.emit (domain.js:482:12)\n    at TLSSocket.Socket._onTimeout (net.js:479:8)\n    at listOnTimeout (internal/timers.js:549:17)","code":"CredentialsError"},"msg":"GET /health","time":"2020-10-28T13:39:03.395Z","v":0}
{"name":"app-server","hostname":"osboxes","pid":5811,"level":30,"msg":"GET /health 500 29 - 1147.369 ms\n","time":"2020-10-28T13:39:03.406Z","v":0}

The CredentialsError seems a bit weird for that but at least the name of the error is TimeoutError.

[IBM-Justin]

Hi @mriedem,

Thank you for reaching out in regards to how httpOptions.timeout works.

Per the NodeJS timer documentation: https://nodejs.org/en/docs/guides/timers-in-node/

Language-Specific Assumptions/Information

The assumption provided by the NodeJS documentation is that there will be variability in the setTimeout function because it’s competing for the event loop to burn down its timing mechanism to execute. Per the documentation “The only guarantee is that the timeout will not execute sooner than the declared timeout interval.”

This competition for the event loop introduces variability in execution time, which given the workload of a particular system should fall within some average range (hopefully not too far from the timeout set). This is a language-specific nuance.

SDK Implementation Information:

The timeouts are ONLY set during operation requests, not during authentication/credential requests.

The IBM NodeJS SDK implements the httpOptions.timeout setting through setTimout() callbacks. 

I set up a unit-test to run a few general operations with a timeout of 1 millisecond(with enhanced logging on authentication and httpOptions.timeout registration) which produced the following results.

Timeout Testing
===========================
Start Token Manager
End Token Manager
Start Token Refresh
End Token Refresh
===========================
Setting Timeout: node.js line: 82
Timeout Called: node.js line: 88
===========================
createbucket: 7.520ms

Key Takeaways:

• Token Logic is not restricted to the httpOptions.timeout setting.
• We can assume the operation HTTP request was less than 7.520ms, some of this overall execution time is from loading the underlying SDK sub-function calls on the stack, auth requests, etc..
• The setTimeout function was called at some point on the create bucket operation (but was => the 1-millisecond timeout).

[mriedem]

The timeouts are ONLY set during operation requests, not during authentication/credential requests.

OK that confirms what I was suspecting above when I said:

Does the httpOptions.timeout value only apply once a connection to S3 is successfully made and then we can timeout while waiting for a response on the listObjectsV2 request?

It would also explain why when it times out (long after the 5 second timeout I had set) that I'm getting CredentialsError so it's failing to authenticate but the timeout appears to not be applied there / yet.

Thanks for investigating this and providing information. I'm not sure if the documentation should be updated to be more specified about how/where the timeout is applied, but I'll close this out since my question was answered.