Timeout errors from Cloud Connector after it completes

matt-lee · February 13, 2023, 2:54pm

My SaaS Connector seems to be hitting some kind of backend timeout when performing aggregations for users. I can use it just fine with small sets of test users, but any attempts to use it on a slightly larger sized workload results in a timeout visible in IDN.

When I look at the connector logs with sail conn logs I can see that the stdAccountList handler completes and all of the accounts have presumably left the connector space and arrived in the IDN space.

Is there some kind of job timeout setting IDN side I need to set for my connector or perhaps some extra visibility I can get regarding why I am getting these timeouts generated after my connector code is completed?

Error from IDN

java.lang.RuntimeException - java.lang.IllegalStateException: Command timed out - java.lang.RuntimeException: java.lang.IllegalStateException: Command timed out
   at com.sailpoint.mantis.qpoc.message.AccountAggregation.iterateResourceObjects(AccountAggregation.java:628 undefined)
   at com.sailpoint.mantis.qpoc.message.AccountAggregation.handleMessage_aroundBody0(AccountAggregation.java:333 undefined)
   at com.sailpoint.mantis.qpoc.message.AccountAggregation$AjcClosure1.run(AccountAggregation.java:1 undefined)
   at org.aspectj.runtime.reflect.JoinPointImpl.proceed(JoinPointImpl.java:167 undefined)
   at com.sailpoint.atlas.metrics.MessageMetricsAspect.meterMessageTimeAndExceptions(MessageMetricsAspect.java:68 undefined)
   at com.sailpoint.mantis.qpoc.message.AccountAggregation.handleMessage(AccountAggregation.java:320 undefined)
   at com.sailpoint.atlas.messaging.server.TypeMessageHandler.handleMessage(TypeMessageHandler.java:87 undefined)
   at com.sailpoint.mantis.qpoc.QpocMessageHandler.handleMessage(QpocMessageHandler.java:50 undefined)
   at com.sailpoint.mantis.platform.message.ObjectConfigMessageHandler.handleMessage(ObjectConfigMessageHandler.java:33 undefined)
   at com.sailpoint.atlas.tracing.plugin.TracingMessageHandler.handleMessage(TracingMessageHandler.java:88 undefined)
   at com.sailpoint.atlas.message.DynamicMessageHandler$ChainedMessageHandlerAdapter.handleMessage(DynamicMessageHandler.java:46 undefined)
   at com.sailpoint.atlas.usage.plugin.UsageMessageHandler.handleMessage(UsageMessageHandler.java:36 undefined)
   at com.sailpoint.atlas.message.DynamicMessageHandler$ChainedMessageHandlerAdapter.handleMessage(DynamicMessageHandler.java:46 undefined)
   at com.sailpoint.atlas.message.DynamicMessageHandler.handleMessage(DynamicMessageHandler.java:36 undefined)
   at com.sailpoint.mantis.platform.message.SailPointContextMessageHandler.handleMessage(SailPointContextMessageHandler.java:55 undefined)
   at com.sailpoint.atlas.message.FailureNotificationHandler.handleMessage(FailureNotificationHandler.java:55 undefined)
   at com.sailpoint.atlas.message.RequestContextMessageHandler.handleMessage(RequestContextMessageHandler.java:72 undefined)
   at com.sailpoint.mantis.platform.message.ExceptionMessageHandler.handleMessage(ExceptionMessageHandler.java:49 undefined)
   at com.sailpoint.atlas.messaging.server.MessageProcessor.handleJobMessage(MessageProcessor.java:196 undefined)
   at com.sailpoint.atlas.messaging.server.MessageProcessor.handleMessage(MessageProcessor.java:129 undefined)
   at com.sailpoint.atlas.messaging.server.MessageProcessor.lambda$null$0(MessageProcessor.java:99 undefined)
   at com.sailpoint.atlas.messaging.server.MessageProcessor.withOrgLogging(MessageProcessor.java:171 undefined)
   at com.sailpoint.atlas.messaging.server.MessageProcessor.lambda$asyncHandleMessage$1(MessageProcessor.java:99 undefined)
   at com.sailpoint.atlas.messaging.server.impl.SourceRunnableImpl.run(SourceRunnableImpl.java:77 undefined)
   at com.sailpoint.atlas.messaging.server.impl.BufferedSourceQueue$IncrementingSourceRunnable.run(BufferedSourceQueue.java:181 undefined)
   at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515 undefined)
   at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264 undefined)
   at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128 undefined)
   at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628 undefined)
   at java.base/java.lang.Thread.run(Thread.java:829 undefined) Caused by: java.lang.IllegalStateException: Command timed out
   at com.sailpoint.connector.cloud.spconnect.SpConnectProxy.pollNextResult(SpConnectProxy.java:336 undefined)
   at com.sailpoint.connector.cloud.spconnect.SpConnectProxy.access$000(SpConnectProxy.java:67 undefined)
   at com.sailpoint.connector.cloud.spconnect.SpConnectProxy$1.nextResponse(SpConnectProxy.java:264 undefined)
   at sailpoint.connector.cloud.CloudConnector$CloudBridgeIterator.buildDataBlockIterator(CloudConnector.java:1055 undefined)
   at sailpoint.connector.cloud.CloudConnector$CloudBridgeIterator.checkForMoreData(CloudConnector.java:1043 undefined)
   at sailpoint.connector.cloud.CloudConnector$CloudBridgeIterator.hasNext(CloudConnector.java:969 undefined)
   at sailpoint.connector.ConnectorProxy$CustomizingIterator.peek(ConnectorProxy.java:738 undefined)
   at sailpoint.connector.ConnectorProxy$CustomizingIterator.hasNext(ConnectorProxy.java:765 undefined)
   at com.sailpoint.mantis.qpoc.message.AccountAggregation.iterateResourceObjects(AccountAggregation.java:596 undefined) ... 29 more

sail conn logs output

[2023-02-13T07:48:50.314-06:00] INFO  | connectorMessage ▶︎ {"commandType":"std:account:list","invocationId":"825fc149-9733-44f7-b3db-50f554b375e6","message":"stdAccountList sent 3148 accounts","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.351-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":211958,"message":"command response processed. Response count: 100","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.351-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":211958,"message":"command response processed. Response count: 200","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.352-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":211959,"message":"command response processed. Response count: 300","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.464-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212071,"message":"command response processed. Response count: 400","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.464-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212071,"message":"command response processed. Response count: 500","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.464-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212071,"message":"command response processed. Response count: 600","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.464-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212071,"message":"command response processed. Response count: 700","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.540-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212147,"message":"command response processed. Response count: 800","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.540-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212147,"message":"command response processed. Response count: 900","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.540-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212147,"message":"command response processed. Response count: 1000","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.540-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212147,"message":"command response processed. Response count: 1100","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.592-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212199,"message":"command response processed. Response count: 1200","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.592-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212199,"message":"command response processed. Response count: 1300","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.592-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212199,"message":"command response processed. Response count: 1400","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.592-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212199,"message":"command response processed. Response count: 1500","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.644-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212252,"message":"command response processed. Response count: 1600","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.644-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212252,"message":"command response processed. Response count: 1700","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.645-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212252,"message":"command response processed. Response count: 1800","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.645-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212252,"message":"command response processed. Response count: 1900","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.696-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212304,"message":"command response processed. Response count: 2000","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.696-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212304,"message":"command response processed. Response count: 2100","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.696-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212304,"message":"command response processed. Response count: 2200","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.696-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212304,"message":"command response processed. Response count: 2300","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.750-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212357,"message":"command response processed. Response count: 2400","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.750-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212357,"message":"command response processed. Response count: 2500","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.750-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212357,"message":"command response processed. Response count: 2600","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.750-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212357,"message":"command response processed. Response count: 2700","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.824-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212431,"message":"command response processed. Response count: 2800","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.824-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212431,"message":"command response processed. Response count: 2900","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.824-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212431,"message":"command response processed. Response count: 3000","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.824-06:00] INFO  | commandResponse  ▶︎ {"commandType":"std:account:list","completed":false,"elapsed":212431,"message":"command response processed. Response count: 3100","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}
[2023-02-13T07:48:50.906-06:00] INFO  | commandOutcome   ▶︎ {"commandType":"std:account:list","completed":true,"elapsed":212514,"message":"command completed","requestId":"a01b55c0b8e04734aff876f81e978a23","version":42}

stdAccountList function from index.ts snippet

        .stdAccountList(async (context: Context, input: undefined, res: Response<StdAccountListOutput>) => {
            const accounts = await myClient.getAllAccounts()

            for (const account of accounts) {
                res.send({
                    identity: account.UserId,
                    uuid: account.UserId,
                    attributes: {
                        UserName: account.UserName,
                        UserId: account.UserId,
                        Formatted: account.Name?.Formatted,
                        FamilyName: account.Name?.FamilyName,
                        GivenName: account.Name?.GivenName,
                        MiddleName: account.Name?.MiddleName,
                        DisplayName: account?.DisplayName,
                        NickName: account?.NickName,
                        Email: account?.Emails?.find((obj: { Primary: boolean }) => {return obj.Primary}).Value,
                        PreferredLanguage: account?.PreferredLanguage,
                        Locale: account?.Locale,
                        entitlements: account?.entitlements!.map((v: { GroupId: any }) => v.GroupId)
                    },
                })
            }
            logger.info(`stdAccountList sent ${accounts.length} accounts`)
        })

fangming_ning · February 13, 2023, 3:51pm

Hey @matt-lee thanks for the feedback. In our Cloud Connectivity platform, we set a 3-minute timeout that we must receive something back during the list commands. This is a way that helps us to make sure the connector process is still working and not hanging or dead.

From your connector code, it seems like you are reading all accounts into memory and then starts to return them at once. That’s why it works on a small set of data where the read all process is done under 3 minutes. The suggestion here is to use pagination and make sure at least one batch of accounts are returned within 3 minutes. This will not only solve this timeout problem, but also makes sure that your connector uses small memory footprint. The connector only has around 200 MB of memory and it can work on multiple commands at once.

Please let me know if you have any questions.

matt-lee · February 13, 2023, 3:52pm

Thanks Fangming, I’ll give that a shot and report back!

matt-lee · February 13, 2023, 4:04pm

I just went to look at the two example connectors provided by Sailpoint and they both use the retrieve all and report all pattern that you have recommended I move away from. Do you have any connectors with examples of your recommended approach?

Existing Sailpoint Examples

github.com

sailpoint-oss/airtable-example-connector/blob/main/src/index.ts

import {
    AttributeChange,
    AttributeChangeOp,
    ConnectorError,
    Context,
    createConnector,
    readConfig,
    Response,
    StdAccountCreateInput,
    StdAccountCreateOutput,
    StdAccountDeleteInput,
    StdAccountDeleteOutput,
    StdAccountDisableInput,
    StdAccountDisableOutput,
    StdAccountDiscoverSchemaOutput,
    StdAccountEnableInput,
    StdAccountEnableOutput,
    StdAccountListOutput,
    StdAccountReadInput,
    StdAccountReadOutput,

This file has been truncated. show original

github.com

sailpoint-oss/saas-conn-discourse/blob/main/src/index.ts

import {
    Context,
    ConnectorError,
    createConnector,
    readConfig,
    Response,
    StdAccountCreateInput,
    StdAccountCreateOutput,
    StdAccountListOutput,
    StdAccountReadInput,
    StdAccountReadOutput,
    StdAccountUpdateInput,
    StdAccountUpdateOutput,
    StdAccountDeleteInput,
    StdAccountDeleteOutput,
    StdEntitlementListOutput,
    StdEntitlementReadOutput,
    StdEntitlementReadInput,
    StdTestConnectionOutput,
    AttributeChangeOp,

This file has been truncated. show original

fangming_ning · February 13, 2023, 4:19pm

@matt-lee Here is some pseudocode for pagination where you can constantly read the next page of accounts and return them to us before reading the new batch. But this process could also depend on what pagination protocol your target system supports.

let offset = 0
let limit = 10
let accounts = []

do {
  accounts = getNextBatch(offset, limit)
  
  for (let account of accounts) {
      res.send({...})
  }
  offset ++
} while (accounts.length > 0)

matt-lee · February 17, 2023, 3:34pm

Perhaps I am thinking about it wrong, but it feels like there is supposed to be some separation of IDN logic and connector source logic and I have been trying to keep source stuff in my client code and IDN stuff in index.ts.

In trying to keep in the spirit of that I opted to use a generator instead and that appears to be working just fine since it results in a quickly started stream of objects. This updated snippet is is completing my aggregation now, but I am curious your thoughts on the approach and if I am heading towards any other challenges perhaps? I’m not super fluent in TypeScript so any input is appreciated.

Btw I really like the sass connectors capability so thank you!

index.ts snippet

        .stdAccountList(async (context: Context, input: undefined, res: Response<StdAccountListOutput>) => {
            for await (const account of myClient.getAllAccounts()) {
                res.send({
                    identity: account.UserId,
                    uuid: account.UserId,
                    attributes: {
                        UserName: account.UserName,
                        UserId: account.UserId,
                        Formatted: account.Name?.Formatted,
                        FamilyName: account.Name?.FamilyName,
                        GivenName: account.Name?.GivenName,
                        MiddleName: account.Name?.MiddleName,
                        DisplayName: account?.DisplayName,
                        NickName: account?.NickName,
                        Email: account?.Emails?.find((obj: { Primary: boolean }) => {return obj.Primary}).Value,
                        PreferredLanguage: account?.PreferredLanguage,
                        Locale: account?.Locale,
                        entitlements: account?.entitlements!.map((v: { GroupId: any }) => v.GroupId)
                    },
                })
            }
        })

my-client.ts snippet

    async* getAllAccounts(): AsyncIterable<any> {
        let done = false
        let nextToken: any | undefined = undefined

        do {
            let page: any = await this.getSomeAccounts(nextToken)

            for (const account of page.Users) {
                account.entitlements = await this.getUserGroups(account.UserId, undefined)
                yield account
            }

            if (page.NextToken) {
                nextToken = page.NextToken
            } else {
                done = true
            }
        } while (!done)
    }

colin_mckibben · February 17, 2023, 3:51pm

I’m not familiar with AsyncIterable, but seems like it is handling the pagination correctly. You’re now able to get the aggregation working. If your target service has any rate limiting, I would also take that into consideration, but depending on how fast the accounts are being sent back to IDN, rate limiting might not be an issue.

matt-lee · February 17, 2023, 3:54pm

For sure. I am handling rate limiting responses in the functions that make each actual api call and stuttering as needed. Thank you!

Topic		Replies	Views
ConnectorError with new connector that uses SaaS Connectivity framework ISC Discussion and Questions saas-connector , custom-connector , identity-security-cloud	14	665	August 9, 2023
SaaS Connectivity connector timeout ISC Discussion and Questions saas-connector , aggregation , identity-security-cloud	3	303	December 9, 2023
SAP GRC Group Aggregation Time Out IdentityIQ (IIQ)	5	2314	February 15, 2022
SaaS Web Service Connector - Error: Command Timed Out ISC Discussion and Questions webservice-connector , identity-security-cloud	6	559	October 17, 2023
Oracle Aggregation is timing out ISC Discussion and Questions apis , aggregation	3	428	July 12, 2023