Intermittent token authorisation failure

[jwulf]

Integration tests are still intermittently failing on authorisation.

Periodically a unit test will fail with 401: UNAUTHORISED.

If I "re-run failed jobs" is will reliably pass on the second run.

My hypothesis is that the API client involved in the test is attempting to make its calls with an expired token.

Token expiry is handled in the SDK in the OAuth component. This component encapsulates retrieving tokens from the token endpoint, caching them in memory and on disk, and providing a token to an API client when the API client wants to make an API call.

The OAuth client should be checking if it has a token in-memory or on-disk (the on-disk caching is for when applications are restarted), then checking if the token is expired or is likely to expire soon (there is a threshold setting that represents "this might expire before the call makes the roundtrip") and either requesting a new token from the endpoint to pass on or passing on the cached token.

Some tests - notably the Tasklist ones - will fail multiple calls when they do fail.

Otherwise, I've noticed that it happens later in the test suite, which leads me to think that it happens when a 300 second validity token expires and there is some race condition or logic error that means it is not correctly refreshed before being passed to the API client.

This is difficult to reproduce reliably.

Maybe it needs some specific test of the token refresh timing logic? Or maybe there is something obvious in the code that I am missing.

[jwulf]

Perfect example, it just failed in CI:

Run npm run test:multitenancy

> @camunda8/sdk@8.5.0 test:multitenancy
> jest --runInBand --testPathIgnorePatterns disconnection --testPathIgnorePatterns admin --testPathIgnorePatterns __tests__/config - --detectOpenHandles --verbose true -u

Running global setup...
Removing all cached OAuth tokens...
Removing any running test process instances...
PASS src/__tests__/oauth/OAuthProvider.spec.ts (6.855 s)
  ✓ Throws in the constructor if there in no clientId credentials (5 ms)
  ✓ Throws in the constructor if there in no clientSecret credentials (1 ms)
  ✓ Throws in the constructor if there are insufficient credentials (2 ms)
  ✓ Gets the token cache dir from the environment (2 ms)
  ✓ Creates the token cache dir if it does not exist (6 ms)
  ✓ Throws in the constructor if the token cache is not writable (2 ms)
  ✓ In-memory cache is populated and evicted after timeout (2234 ms)
  ✓ In-memory cache is populated and evicted respecting CAMUNDA_OAUTH_TOKEN_REFRESH_THRESHOLD_MS (4118 ms)
  ✓ Uses form encoding for request (6 ms)
  ✓ Uses a custom audience for an Operate token, if one is configured (9 ms)
  ✓ Passes scope, if provided (12 ms)
  ✓ Can get scope from environment (10 ms)
  ✓ Creates the token cache dir if it does not exist (2 ms)
  ✓ Gets the token cache dir from the environment (2 ms)
  ✓ Uses an explicit token cache over the environment (2 ms)
  ✓ Throws in the constructor if the token cache is not writable (2 ms)
  ✓ Can set a custom user agent (3 ms)
  ✓ Passes no audience for Modeler API when self-hosted (6 ms)
  ✓ Throws if you try to get a Modeler token from SaaS without console creds (1 ms)
  ✓ Throws if you try to get a Modeler token from Self-hosted without application creds (2 ms)

PASS src/__tests__/lib/LosslessJsonParser.spec.ts
  ✓ LosslessJsonParser correctly handles nested Dtos (3 ms)
  ✓ LosslessJsonParser can handle an array (2 ms)
  ✓ LosslessJsonParser will throw when passed an unsafe int64 number and no Dto
  ✓ LosslessJsonParser will throw when passed an unsafe int64 number and a Dto without a mapping for it (1 ms)
  ✓ LosslessJsonParser will parse a BigInt when passed an int64 number and a mapped Dto (2 ms)
  ✓ LosslessJsonParser with safe numbers and no Dto works like JSON.parse (2 ms)
  ✓ LosslessJsonParser parses unexpected numbers as number at runtime
  ✓ LosslessJsonParser is ok with missing optional fields at runtime
  ✓ LosslessJsonParser will throw if an unexpected type is encountered at runtime
  ✓ LosslessJsonParser throws for unexpected unsafe numbers at runtime (1 ms)
  ✓ LosslessJsonParser/Stringify correctly handles array of nested Dtos (2 ms)
  ✓ LosslessStringify parses safe unexpected numbers as number at runtime (1 ms)
  ✓ LosslessStringify correctly handles nested Dtos (2 ms)

PASS src/__tests__/tasklist/tasklist.integration.spec.ts (125.265 s)
  TasklistApiClient
    Read operations
      ✓ can request all tasks (13873 ms)
      ✓ can request a task with parameters (13123 ms)
      ✓ gets all fields for a task (13098 ms)
      ✓ can request a specific task (13180 ms)
      ✓ can retrieve an embedded form (13116 ms)
    Write operations
      ✓ can claim a task (13316 ms)
      ✓ will not allow a task to be claimed twice (14055 ms)
      ✓ can unclaim task ([15](https://github.com/camunda/camunda-8-js-sdk/actions/runs/8607568978/job/23588294953#step:8:16)987 ms)
      ✓ can complete a Task (14492 ms)

PASS src/__tests__/zeebe/integration/Worker-Failure.spec.ts (24.367 s)
  ✓ Causes a retry with complete.failure() (1068 ms)
  ✓ Does not fail a process when the handler throws, by default (20142 ms)
  ✓ Fails a process when the handler throws and options.failProcessOnException is set (1933 ms)

PASS src/__tests__/zeebe/integration/Worker-1.0-complete.spec.ts
  ✓ Can service a task (417 ms)
  ✓ Can service a task with complete.success (391 ms)
  ✓ Can update process variables with complete.success() (404 ms)

PASS src/__tests__/zeebe/integration/Worker-Failure-Retries.spec.ts
  ✓ Decrements the retries count by default (935 ms)
  ✓ Set the retries to a specific number when provided with one via simple signature (856 ms)
  ✓ Set the retries to a specific number when provided with one via object signature (766 ms)

PASS src/__tests__/zeebe/integration/Worker-integration.spec.ts
  ✓ Can service a task (398 ms)
  ✓ Can service a task with complete.success (380 ms)
  ✓ Can update process variables with complete.success() (407 ms)

PASS src/__tests__/zeebe/multitenancy/deployprocess-mt.spec.ts
  ✓ Will throw an error if non-existent tenantId is provided when deploying a process to multi-tenant Zeebe (90 ms)
  ✓ Will not throw an error if tenantId is provided when connecting to multi-tenant Zeebe (61 ms)
  ✓ Can deploy to red tenant (88 ms)
  ✓ Process deployed to red tenant cannot be started by default tenant client (105 ms)
  ✓ Process instance started in red tenant can be started by red tenant (114 ms)

PASS src/__tests__/zeebe/integration/Client-MigrateProcessInstance.spec.ts
  ✓ ZeebeGrpcClient can migrate a process instance (1431 ms)

PASS src/__tests__/zeebe/multitenancy/signalbroadcast-mt.spec.ts
  ✓ Multi-tenant Zeebe: Will throw an error if no tenantId is provided when broadcasting a signal to multi-tenant-enabled Zeebe broker (123 ms)
  ✓ Multi-tenant Zeebe: Will throw an error if wrong tenantId is provided when broadcasting a signal to multi-tenant-enabled Zeebe broker (33 ms)
  ✓ Multi-tenant Zeebe: No error if tenantId is provided when broadcasting a signal to multi-tenant-enabled Zeebe broker (37 ms)
  ✓ Signal broadcast to red tenant is received (141 ms)

PASS src/__tests__/lib/Configuration.spec.ts
  CamundaEnvironmentConfigurator
    ✓ Can read correct env vars (1 ms)
    ✓ Can read correct env vars (2 ms)
    ✓ It can merge explicit configuration with environment (1 ms)
    ✓ It can override the environment with an empty string (1 ms)

PASS src/__tests__/zeebe/integration/Client-CreateProcessInstanceWithResult.spec.ts (23.28 s)
  ✓ Awaits a process outcome (1234 ms)
  ✓ can override the gateway timeout (20292 ms)
  ✓ fetches a subset of variables (1029 ms)

PASS src/__tests__/zeebe/integration/Client-startProcess.spec.ts
  ✓ Can start a process (66 ms)
  ✓ Can start a process at an arbitrary point (400 ms)

PASS src/__tests__/zeebe/integration/Worker-onReady.spec.ts (48.404 s)
  ✓ Worker emits the ready event once if there is a broker (12080 ms)
  ✓ Does set connected: true if there is a broker and eagerConnection: true (7017 ms)
  ✓ Does not set connected: true if there is a broker and eagerConnection: false (7029 ms)
  ✓ Does not call the onReady handler if there is no broker (5033 ms)
  ✓ Does not emit the ready event if there is no broker (5031 ms)
  ✓ Worker calls the onReady handler once if there is a broker (12024 ms)

PASS src/__tests__/zeebe/integration/Client-setVariables.spec.ts
  ✓ Can update process variables with setVariables (430 ms)

PASS src/__tests__/zeebe/stringifyVariables.spec.ts
  ✓ stringifyVariables returns a new object (1 ms)
  ✓ stringifyVariables stringifies the variables key of a job object (1 ms)
  ✓ parseVariables returns a new object (1 ms)
  ✓ parseVariables parses the payload key of a job object to JSON (1 ms)
  ✓ parseVariables correctly parses the payload string (1 ms)
  ✓ parseVariables returns an object with all the keys of the original (1 ms)

PASS src/__tests__/zeebe/integration/Worker-Failure-Backoff-Retry.spec.ts
  ✓ Can specify a retryBackoff with complete.failure() (2827 ms)

PASS src/__tests__/operate/operate.spec.ts
  ✓ Censtructor throws without base url (2 ms)
  ✓ Can get construct a client (1 ms)
  ✓ Can add tenant id to filter (1 ms)
  ✓ Adds tenant id if no filter (1 ms)
  ✓ Does not add a tenantId if none given (1 ms)
  ✓ Adds tenant id from environment (2 ms)

PASS src/__tests__/zeebe/integration/Client-ThrowError.spec.ts
  ✓ Throws a business error that is caught in the process (447 ms)
  ✓ Can set variables when throwing a BPMN Error (408 ms)

PASS src/__tests__/zeebe/BpmnParser.spec.ts
  ✓ parses a bpmn file to an Object (1 ms)
  ✓ can parse a file with a message with no name (4 ms)
  ✓ gets a unique list of task types when passed an object (1 ms)
  ✓ gets a list of unique task types when passed an array (2 ms)
  ✓ gets a list of unique message names when passed an object (1 ms)
  ✓ gets a list of unique message names when passed an array (2 ms)
  ✓ Returns a constants file for a single Bpmn file (3 ms)
  ✓ Returns a constants file for an array of Bpmn files (8 ms)

PASS src/__tests__/zeebe/integration/Client-integration.spec.ts
  ✓ Can get the broker topology (102 ms)
  ✓ Can create a worker (93 ms)
  ✓ Can cancel a process (195 ms)
  ✓ does not retry to cancel a process instance that doesn't exist (132 ms)

PASS src/__tests__/zeebe/integration/Worker-RaiseIncident.spec.ts
  ✓ Can raise an Operate incident with complete.failure() (446 ms)

PASS src/__tests__/zeebe/ZeebeGrpcClient.spec.ts
  ✓ ZeebeGrpcClient constructor throws is OAuth is not explicitly disabled and insufficient environment variables are set (19 ms)
  ✓ ZeebeGrpcClient constructor creates a new ZeebeGrpcClient (65 ms)
  ✓ ZeebeGrpcClient constructor creates a new ZeebeGrpcClient (19 ms)

PASS src/__tests__/zeebe/integration/Client-ConnectionError.spec.ts (24.28 s)
  ✓ Calls the onConnectionError handler if there is no broker and eagerConnection: true (7071 ms)
  ✓ Sets connected:false if there is no broker and no setting of eagerConnection (5014 ms)
  ✓ Sets connected:false if there is no broker and eagerConnection: true (5015 ms)
  ✓ Does emit the connectionError event if there is no broker and eagerConnection: true (7014 ms)

PASS src/__tests__/zeebe/integration/Client-DeployResource.spec.ts
  ✓ deploys a process (45 ms)
  ✓ deploys a process from a file (31 ms)
  ✓ deploys a DMN table from a filename ([16](https://github.com/camunda/camunda-8-js-sdk/actions/runs/8607568978/job/23588294953#step:8:17)3 ms)
  ✓ deploys a DMN table (138 ms)
  ✓ deploys a Form (81 ms)

PASS src/__tests__/zeebe/multitenancy/createProcessInstance-mt.spec.ts
  ✓ Will not throw an error if tenantId is provided when starting a process instance on multi-tenant Zeebe (64 ms)
  ✓ Will throw an error if no tenantId is provided when starting a process instance on multi-tenant Zeebe (44 ms)

PASS src/__tests__/operate/multitenancy/operate-mt.spec.ts (8.423 s)
  Operate multi-tenancy
    ✓ It can get the process instance from green tenant and not the red tenant (8243 ms)

PASS src/__tests__/zeebe/integration/Worker-fetchVariable.spec.ts
  ✓ Can retrieve only specified variables using fetchVariable (391 ms)

PASS src/__tests__/zeebe/integration/Client-onReady.spec.ts (22.337 s)
  ✓ Does not call the onReady handler if there is no broker (4064 ms)
  ✓ Does call the onReady handler if there is a broker and eagerConnection is true (6015 ms)
  ✓ Does set connected to true if there is a broker (6014 ms)
  ✓ Does emit the ready event if there is a broker and eagerConnection: true (6011 ms)

PASS src/__tests__/zeebe/integration/Client-ModifyProcessInstance.spec.ts
  ✓ Modify Process Instance (353 ms)

FAIL src/__tests__/zeebe/integration/Client-MessageStart.spec.ts (45.496 s)
  ✕ Can start a process with a message (45002 ms)

  ● Can start a process with a message

    16 UNAUTHENTICATED: Failed to parse bearer token, see cause for details

      651 | 							}
      652 | 						}
    > 653 | 						return nxt(callStatus)
          | 						       ^
      654 | 					},
      655 | 				}
      656 | 				next(metadata, newListener)

      at callErrorFromStatus (node_modules/@grpc/grpc-js/src/call.ts:82:[17](https://github.com/camunda/camunda-8-js-sdk/actions/runs/8607568978/job/23588294953#step:8:18))
      at Object.onReceiveStatus (node_modules/@grpc/grpc-js/src/client.ts:360:55)
      at node_modules/@grpc/grpc-js/src/call-interface.ts:149:27
      at Object.onReceiveStatus (src/zeebe/lib/GrpcClient.ts:653:14)
      at InterceptingListenerImpl.onReceiveStatus (node_modules/@grpc/grpc-js/src/call-interface.ts:145:19)
      at Object.onReceiveStatus (node_modules/@grpc/grpc-js/src/client-interceptors.ts:458:34)
      at Object.onReceiveStatus (node_modules/@grpc/grpc-js/src/client-interceptors.ts:419:48)
      at node_modules/@grpc/grpc-js/src/resolving-call.ts:132:24
      for call at
      at ServiceClientImpl.makeUnaryRequest (node_modules/@grpc/grpc-js/src/client.ts:325:42)
      at ServiceClientImpl.<anonymous> (node_modules/@grpc/grpc-js/src/make-client.ts:[18](https://github.com/camunda/camunda-8-js-sdk/actions/runs/8607568978/job/23588294953#step:8:19)9:15)
      at src/zeebe/lib/GrpcClient.ts:388:26

  ● Can start a process with a message

    thrown: "Exceeded timeout of 45000 ms for a test while waiting for `done()` to be called.
    Add a timeout value to this test to increase the timeout, if this is a long-running test. See https://jestjs.io/docs/api#testname-fn-timeout."

      25 | })
      26 |
    > 27 | test('Can start a process with a message', (done) => {
         | ^
      28 | 	const randomId = uuid()
      29 |
      30 | 	// Wait 1 second to make sure the deployment is complete

      at Object.<anonymous> (src/__tests__/zeebe/integration/Client-MessageStart.spec.ts:27:1)

PASS src/__tests__/zeebe/ZeebeGrpcClient-unmocked.spec.ts
  ✓ ZeebeGrpcClient constructor throws an exception when there is no broker and retry is false (132 ms)
  ✓ cancelProcessInstance throws an exception when workflowInstanceKey is malformed (37 ms)

PASS src/__tests__/zeebe/integration/Client-PublishMessage.spec.ts
  ✓ Can publish a message (1357 ms)

PASS src/__tests__/zeebe/integration/Client-BroadcastSignal.spec.ts
  ✓ Can start a process with a signal (377 ms)

PASS src/__tests__/zeebe/integration/Worker-LongPoll.spec.ts (30.369 s)
  ✓ Does long poll by default (30020 ms)

PASS src/__tests__/oauth/OAuthProvider-integration.spec.ts
  ✓ Can get an Operate token from the environment vars (4 ms)
  ✓ Can get Operate token (1 ms)
  ✓ Can get Optimize token (13 ms)
  ✓ Can get Tasklist token (12 ms)
  ✓ Can get Zeebe token (1 ms)
  ✓ Can get a console token from the environment vars (9 ms)

PASS src/__tests__/zeebe/integration/Client-DeleteResource.spec.ts
  ✓ can delete a resource (422 ms)

PASS src/__tests__/modeler/modeler.spec.ts
  ✓ Constructor does not throws without base url (1 ms)
  ✓ Can get construct a client (1 ms)

PASS src/__tests__/zeebe/integration/Client-EvaluateDecision.spec.ts
  ✓ EvaluateDecision (359 ms)

PASS src/__tests__/optimize/optimize.spec.ts
  ✓ Censtructor throws without base url (2 ms)
  ✓ Can get construct a client (4 ms)

PASS src/__tests__/tasklist/tasklist.spec.ts
  ✓ Constructor throws without base url (1 ms)
  ✓ Can get construct a client (1 ms)

PASS src/__tests__/zeebe/integration/Worker-Dto.spec.ts
  ✓ Let's test worker handler signatures (1 ms)

PASS src/__tests__/zeebe/integration/Client-BrokenBpmn.spec.ts
  ✓ does not retry the deployment of a broken BPMN file (43 ms)

PASS src/__tests__/zeebe/integration/Client-DeployProcess.spec.ts
  ✓ deploys a process (117 ms)

PASS src/__tests__/optimize/optimize.integration.spec.ts
  ✓ Can get readiness (20 ms)
  ○ skipped Can get Dashboards

PASS src/__tests__/zeebe/integration/TypeSurfaceAreaTest.spec.ts
  ✓ Has not broken any public type contracts (86 ms)

PASS src/__tests__/modeler/modeler-integration.spec.ts
  ✓ It can get info (274 ms)
  ✓ Can create project (339 ms)

PASS src/__tests__/zeebe/integration/Topology.spec.ts
  ✓ it can get the topology ([19](https://github.com/camunda/camunda-8-js-sdk/actions/runs/8607568978/job/23588294953#step:8:20) ms)

PASS src/__tests__/exports.spec.ts
  ✓ exports as expected (1 ms)

[jwulf]

16: UNAUTHENTICATED is what the Zeebe GRPC API client will throw.

401: UNAUTHORIZED is what the REST APIs clients will throw.

[pepopowitz]

@jwulf I'm unsure about what I'm chasing.

• I don't see any failing recent runs of the unit tests workflow that indicate an auth error
• I don't see any existing workflows that run integration tests
• When I look back at all failing workflows, I do see some failing integration tests. I don't think the workflow exists anymore to run them? Regardless....
• Almost all recent integration tests that failed for a non-trivial reason failed for a timeout, but I rarely see anything about auth in the error message.
• The CI output you pasted above, I can't find a corresponding workflow run.

Can you point me to some failed workflows that have the auth error you're talking about?

[jwulf]

I re-run the failed workflows, and they pass - so there are no historical examples.

The tests are the integration tests. None of the unit tests trigger it that I know of.

To run the test suite that fails locally, put Camunda SaaS credentials in the environment and run:

npm run test:integration

[jwulf]

@pepopowitz pointed out that the token is cached on the server, so proactively expiring the token doesn't work.

We'll retry once on a 401: UNAUTHORISED with a new token request.

[jwulf]

According to the Identity team, the server cached token is removed 30s before it expires, so if we hardcode a 10s window we should get a new token.

Which invalidates our original hypothesis. The previous (configurable) window of 10s should work.

[jwulf]

The expiry time of the token was calculated from in the SDK from the retrieval time plus the validity period. Since cached tokens are returned by a call for a token, such a token will not be valid for the entire validity duration.

I've changed it to decode the token and use its expiry time.