Skip to content

PAC CLI: copilot publish fails on first attempt with "Invalid response format" due to race condition #1307

@arun-sr07

Description

@arun-sr07

Bug Description

pac copilot publish consistently fails on the first attempt with an "Invalid response format" error, but succeeds on the second attempt without any changes.

Error Message

FTL | bolt.Session :: Invalid response format (Parameter 'rawResponse')
EXCEPTION: System.ArgumentException: Invalid response format (Parameter 'rawResponse')
   at bolt.module.copilot.CopilotPublishStatus.FromJsonString(Guid botId, Object rawResponse)
   at bolt.module.copilot.verbs.CopilotVerbBase.GetCopilotPublishStatusAsync(...)

Root Cause

The CLI checks publish status immediately after initiating the publish operation (within ~0.5 seconds), but the Dataverse backend hasn't initialized the status object yet. This causes FromJsonString() to receive invalid/null data and fail deserialization.

Steps to Reproduce

  1. Run: pac copilot publish --bot <bot-id> --environment <env-name>
  2. First attempt fails with "Invalid response format"
  3. Run same command again immediately
  4. Second attempt succeeds (backend has had time to initialize)

Expected Behavior

The CLI should:

  • Check if the response is null/invalid before deserialization
  • Retry status checks with backoff if data is not ready
  • Not crash on first publish attempt

Actual Behavior

  • First attempt: Crashes at CopilotPublishStatus.FromJsonString()
  • Second attempt: Works fine (40+ seconds have passed)

Environment

  • PAC CLI Version: 2.1.1+gefbf518
  • OS: Windows
  • Date: February 11, 2026

Workaround

Adding retry logic works 100% of the time - second attempt always succeeds.

Suggested Fix

Add null/validation check in CopilotPublishStatus.FromJsonString() or implement retry logic in GetCopilotPublishStatusAsync() before deserializing the response.

Complete Logs:
2026-02-11 05:18:50.9038 | INF | bolt.dataverse.client.actions.GetEntityDefinitionAction :: Executing GetEntityDefinitionAction
2026-02-11 05:18:50.9946 | INF | bolt.dataverse.client.actions.GetEntityDefinitionAction :: GetEntityDefinitionAction execution is complete
2026-02-11 05:18:50.9946 | INF | bolt.dataverse.client.actions.GetEntityRecordAction :: Executing GetEntityRecordAction
2026-02-11 05:18:51.0652 | INF | bolt.dataverse.client.actions.GetEntityRecordAction :: GetEntityRecordAction execution is complete
2026-02-11 05:18:51.4184 | FTL | bolt.Session :: Invalid response format (Parameter 'rawResponse')|EXCEPTION: System.ArgumentException: Invalid response format (Parameter 'rawResponse')
at bolt.module.copilot.CopilotPublishStatus.FromJsonString(Guid botId, Object rawResponse) in C:__w\1\s\src\cli\bolt.module.copilot\CopilotPublishStatus.cs:line 96
at bolt.module.copilot.verbs.CopilotVerbBase.GetCopilotPublishStatusAsync(ICdsClient cdsClient, AuthProfile authProfile, Uri environmentUrl, Guid botId, String jobId) in C:__w\1\s\src\cli\bolt.module.copilot\verbs\CopilotVerbBase.cs:line 194
at bolt.module.copilot.verbs.CopilotPublishVerb.PublishCopilotAsync(Uri environmentUrl, Guid botId) in C:__w\1\s\src\cli\bolt.module.copilot\verbs\CopilotPublishVerb.cs:line 93
at bolt.module.copilot.verbs.CopilotPublishVerb.ExecuteAsync(Command command, CancellationToken cancellationToken) in C:__w\1\s\src\cli\bolt.module.copilot\verbs\CopilotPublishVerb.cs:line 60
at bolt.cli.CommandLine.VerbExecutor.ExecuteImplAsync(VerbBase verbInstance, Command command, CancellationToken cancellationToken) in C:__w\1\s\src\cli\bolt.cli\CommandLine\VerbExecutor.cs:line 184
at bolt.cli.CommandLine.VerbExecutor.<>c__DisplayClass8_1.<b__2>d.MoveNext() in C:__w\1\s\src\cli\bolt.cli\CommandLine\VerbExecutor.cs:line 62
--- End of stack trace from previous location ---
at bolt.cli.CommandLine.VerbExecutor.ExecuteWithTelemetryAsync(VerbExecutionContext execContext, Func1 executeCoreFn) in C:\__w\1\s\src\cli\bolt.cli\CommandLine\VerbExecutor.cs:line 227 at bolt.cli.CommandLine.VerbExecutor.ExecuteAsync(VerbExecutionContext execContext, CancellationToken cancellationToken) in C:\__w\1\s\src\cli\bolt.cli\CommandLine\VerbExecutor.cs:line 58 at bolt.cli.Verb.RunVerbExecutorAsync(IProcessCommandContext context, Command command, CancellationToken cancellationToken) in C:\__w\1\s\src\cli\bolt.cli\Verb.cs:line 226 at bolt.cli.Verb.ExecuteWithOutputAsync(IProcessCommandContext context, Command command, Queue1 nextCommands, CancellationToken cancellationToken) in C:__w\1\s\src\cli\bolt.cli\Verb.cs:line 172
at bolt.cli.Verb.ExecuteAsync(IProcessCommandContext context, Command command, Queue1 nextCommands, CancellationToken cancellationToken) in C:\__w\1\s\src\cli\bolt.cli\Verb.cs:line 78 at bolt.cli.CommandProcessor.ProcessCommands(Queue1 commands, IVerbFactory factory) in C:__w\1\s\src\cli\bolt.cli\CommandProcessor.cs:line 172
at bolt.cli.CommandProcessor.LaunchCommand(IReadOnlyList1 args, UserHelpText userHelpText, Boolean isNonInteractiveModeEnabled) in C:\__w\1\s\src\cli\bolt.cli\CommandProcessor.cs:line 87 at bolt.cli.ModeManager.Dispatch(ProgramArguments args, Boolean checkForBlockedFiles) in C:\__w\1\s\src\cli\bolt.cli\ModeManager.cs:line 44 at bolt.Session.Run(ProgramArguments args) in C:\__w\1\s\src\cli\bolt\Session.cs:line 303 2026-02-11 05:18:51.4184 | ERR | bolt.Session :: at bolt.module.copilot.CopilotPublishStatus.FromJsonString(Guid botId, Object rawResponse) in C:\__w\1\s\src\cli\bolt.module.copilot\CopilotPublishStatus.cs:line 96 at bolt.module.copilot.verbs.CopilotVerbBase.GetCopilotPublishStatusAsync(ICdsClient cdsClient, AuthProfile authProfile, Uri environmentUrl, Guid botId, String jobId) in C:\__w\1\s\src\cli\bolt.module.copilot\verbs\CopilotVerbBase.cs:line 194 at bolt.module.copilot.verbs.CopilotPublishVerb.PublishCopilotAsync(Uri environmentUrl, Guid botId) in C:\__w\1\s\src\cli\bolt.module.copilot\verbs\CopilotPublishVerb.cs:line 93 at bolt.module.copilot.verbs.CopilotPublishVerb.ExecuteAsync(Command command, CancellationToken cancellationToken) in C:\__w\1\s\src\cli\bolt.module.copilot\verbs\CopilotPublishVerb.cs:line 60 at bolt.cli.CommandLine.VerbExecutor.ExecuteImplAsync(VerbBase verbInstance, Command command, CancellationToken cancellationToken) in C:\__w\1\s\src\cli\bolt.cli\CommandLine\VerbExecutor.cs:line 184 at bolt.cli.CommandLine.VerbExecutor.<>c__DisplayClass8_1.<<ExecuteAsync>b__2>d.MoveNext() in C:\__w\1\s\src\cli\bolt.cli\CommandLine\VerbExecutor.cs:line 62 --- End of stack trace from previous location --- at bolt.cli.CommandLine.VerbExecutor.ExecuteWithTelemetryAsync(VerbExecutionContext execContext, Func1 executeCoreFn) in C:__w\1\s\src\cli\bolt.cli\CommandLine\VerbExecutor.cs:line 227
at bolt.cli.CommandLine.VerbExecutor.ExecuteAsync(VerbExecutionContext execContext, CancellationToken cancellationToken) in C:__w\1\s\src\cli\bolt.cli\CommandLine\VerbExecutor.cs:line 58
at bolt.cli.Verb.RunVerbExecutorAsync(IProcessCommandContext context, Command command, CancellationToken cancellationToken) in C:__w\1\s\src\cli\bolt.cli\Verb.cs:line 226
at bolt.cli.Verb.ExecuteWithOutputAsync(IProcessCommandContext context, Command command, Queue1 nextCommands, CancellationToken cancellationToken) in C:\__w\1\s\src\cli\bolt.cli\Verb.cs:line 172 at bolt.cli.Verb.ExecuteAsync(IProcessCommandContext context, Command command, Queue1 nextCommands, CancellationToken cancellationToken) in C:__w\1\s\src\cli\bolt.cli\Verb.cs:line 78
at bolt.cli.CommandProcessor.ProcessCommands(Queue1 commands, IVerbFactory factory) in C:\__w\1\s\src\cli\bolt.cli\CommandProcessor.cs:line 172 at bolt.cli.CommandProcessor.LaunchCommand(IReadOnlyList1 args, UserHelpText userHelpText, Boolean isNonInteractiveModeEnabled) in C:__w\1\s\src\cli\bolt.cli\CommandProcessor.cs:line 87
at bolt.cli.ModeManager.Dispatch(ProgramArguments args, Boolean checkForBlockedFiles) in C:__w\1\s\src\cli\bolt.cli\ModeManager.cs:line 44
at bolt.Session.Run(ProgramArguments args) in C:__w\1\s\src\cli\bolt\Session.cs:line 303
2026-02-11 05:18:51.4184 | INF | bolt.Session :: End session.

2026-02-11 05:19:22.2372 | INF | bolt.Session :: Product Version: 2.1.1+gefbf518; File Version: 2.1.1
2026-02-11 05:19:22.2372 | INF | bolt.Session :: Start new session. nonInteractiveMode: False)
2026-02-11 05:19:22.3093 | INF | bolt.cli.Verb :: Executing verb 'copilot publish' with arguments --bot,--environment.
2026-02-11 05:19:22.3093 | INF | bolt.cli.CommandLine.VerbExecutor :: PerformAuthenticationAsync - Getting auth profile with following options: { AuthKind = DATAVERSE, IsRequired = True, ShowProfileMessages = True, VerbDisableAutoOSLogin = False, SkipValidation = False }

2026-02-11 05:19:23.4367 | INF | bolt.cli.EnvironmentResolver :: ResolveEnvironmentLookupSpecAsync: Using the environment configured in the auth profile as it matches the desired environment.
2026-02-11 05:19:23.5005 | INF | Microsoft.PowerPlatform.Dataverse.Client.ServiceClient :: Attempting to Connect to Uri https://org2903e5cc.crm8.dynamics.com/XRMServices/2011/Organization.svc
2026-02-11 05:19:23.5059 | INF | Microsoft.PowerPlatform.Dataverse.Client.ServiceClient :: Organization Service URI is 'https://org2903e5cc.crm8.dynamics.com/XRMServices/2011/Organization.svc'
2026-02-11 05:19:23.5059 | INF | Microsoft.PowerPlatform.Dataverse.Client.ServiceClient :: ConnectAndInitService - Requesting connection to Organization with Dataverse Version: No organization data available
2026-02-11 05:19:23.6067 | INF | bolt.authentication.store.AuthTokenStore :: Successfully acquired a token using profile of type User for scope 'https://org2903e5cc.crm8.dynamics.com//.default'
2026-02-11 05:19:23.6846 | INF | Microsoft.PowerPlatform.Dataverse.Client.ServiceClient :: ConnectAndInitService - Proxy created, total elapsed time: 00:00:00.1775969
2026-02-11 05:19:23.6846 | INF | Microsoft.PowerPlatform.Dataverse.Client.ServiceClient :: Direct Login Process Succeeded - duration 00:00:00.1855423
2026-02-11 05:19:23.6846 | INF | Microsoft.PowerPlatform.Dataverse.Client.ServiceClient :: Querying Organization Instance Details. Request ID: 5a4b7fd7-dc58-4a3c-a390-2a6fe3b91c55
2026-02-11 05:19:23.6890 | INF | Microsoft.PowerPlatform.Dataverse.Client.ServiceClient :: Execute Command - RetrieveCurrentOrganizationRequest : RequestId=5a4b7fd7-dc58-4a3c-a390-2a6fe3b91c55
2026-02-11 05:19:23.9072 | INF | Microsoft.PowerPlatform.Dataverse.Client.ServiceClient :: Executed Command - RetrieveCurrentOrganizationRequest : RequestId=5a4b7fd7-dc58-4a3c-a390-2a6fe3b91c55 : total duration: 00:00:00.2185162

2026-02-11 05:19:23.9099 | WRN | bolt.cli.TelemetryImplementation.LoggingGeoLocationMapper :: TryMapLocationToGeo missing mapping from location 'IND' to GeoShortCode.
2026-02-11 05:19:23.9099 | INF | bolt.dataverse.client.actions.GetEntityTableAction :: Executing GetEntityTableAction
2026-02-11 05:19:25.3452 | INF | bolt.dataverse.client.actions.GetEntityTableAction :: GetEntityTableAction execution is complete

2026-02-11 05:19:25.8212 | INF | bolt.dataverse.client.actions.GetEntityDefinitionAction :: Executing GetEntityDefinitionAction
2026-02-11 05:19:26.1577 | INF | bolt.dataverse.client.actions.GetEntityDefinitionAction :: GetEntityDefinitionAction execution is complete
2026-02-11 05:19:26.1588 | INF | bolt.dataverse.client.actions.GetEntityRecordAction :: Executing GetEntityRecordAction
2026-02-11 05:19:26.5557 | INF | bolt.dataverse.client.actions.GetEntityRecordAction :: GetEntityRecordAction execution is complete
2026-02-11 05:19:26.5557 | INF | bolt.dataverse.client.actions.GetEntityDefinitionAction :: Executing GetEntityDefinitionAction
2026-02-11 05:19:26.5557 | INF | bolt.dataverse.client.actions.GetEntityDefinitionAction :: GetEntityDefinitionAction execution is complete
2026-02-11 05:19:26.5557 | INF | bolt.dataverse.client.actions.GetEntityRecordAction :: Executing GetEntityRecordAction
2026-02-11 05:19:26.6925 | INF | bolt.dataverse.client.actions.GetEntityRecordAction :: GetEntityRecordAction execution is complete
2026-02-11 05:19:31.7040 | INF | bolt.dataverse.client.actions.GetEntityDefinitionAction :: Executing GetEntityDefinitionAction
2026-02-11 05:19:31.7040 | INF | bolt.dataverse.client.actions.GetEntityDefinitionAction :: GetEntityDefinitionAction execution is complete
2026-02-11 05:19:31.7067 | INF | bolt.dataverse.client.actions.GetEntityRecordAction :: Executing GetEntityRecordAction
2026-02-11 05:19:31.7714 | INF | bolt.dataverse.client.actions.GetEntityRecordAction :: GetEntityRecordAction execution is complete
2026-02-11 05:19:36.7779 | INF | bolt.dataverse.client.actions.GetEntityDefinitionAction :: Executing GetEntityDefinitionAction
2026-02-11 05:19:36.7779 | INF | bolt.dataverse.client.actions.GetEntityDefinitionAction :: GetEntityDefinitionAction execution is complete
2026-02-11 05:19:36.7779 | INF | bolt.dataverse.client.actions.GetEntityRecordAction :: Executing GetEntityRecordAction
2026-02-11 05:19:36.8512 | INF | bolt.dataverse.client.actions.GetEntityRecordAction :: GetEntityRecordAction execution is complete
2026-02-11 05:19:41.8539 | INF | bolt.dataverse.client.actions.GetEntityDefinitionAction :: Executing GetEntityDefinitionAction
2026-02-11 05:19:41.8539 | INF | bolt.dataverse.client.actions.GetEntityDefinitionAction :: GetEntityDefinitionAction execution is complete
2026-02-11 05:19:41.8539 | INF | bolt.dataverse.client.actions.GetEntityRecordAction :: Executing GetEntityRecordAction
2026-02-11 05:19:41.9269 | INF | bolt.dataverse.client.actions.GetEntityRecordAction :: GetEntityRecordAction execution is complete

2026-02-11 05:19:42.2220 | INF | bolt.Session :: End session.

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions