cli icon indicating copy to clipboard operation
cli copied to clipboard
verified publisher icon forcedotcom

force:source:push keeps timing out

Open filiprafalowicz opened this issue 3 years ago • 10 comments

Summary

Every time I try to do full source push of my project I get "Metadata API request failed: The client has timed out.". It doesn't happen when I use legacy command.

Steps To Reproduce:

  1. Have a project with ~8500 components
  2. Call sfdx force:source:push

Expected result

Source is pushed to the scratch org.

Actual result

ERROR running force:source:push: Metadata API request failed: The client has timed out.

System Information

{
        "cliVersion": "sfdx-cli/7.151.1",
        "architecture": "darwin-x64",
        "nodeVersion": "node-v16.15.0",
        "pluginVersions": [
                "@oclif/plugin-autocomplete 0.3.0 (core)",
                "@oclif/plugin-commands 1.3.0 (core)",
                "@oclif/plugin-help 3.3.1 (core)",
                "@oclif/plugin-not-found 1.2.6 (core)",
                "@oclif/plugin-plugins 1.10.11 (core)",
                "@oclif/plugin-update 1.5.0 (core)",
                "@oclif/plugin-warn-if-update-available 1.7.3 (core)",
                "@oclif/plugin-which 1.0.4 (core)",
                "@salesforce/lwc-dev-server 2.11.0",
                "@salesforce/sfdx-plugin-lwc-test 0.1.7 (core)",
                "alias 2.0.0 (core)",
                "apex 0.11.0 (core)",
                "auth 2.0.2 (core)",
                "community 1.1.4 (core)",
                "config 1.4.6 (core)",
                "custom-metadata 1.1.0 (core)",
                "data 2.0.0 (core)",
                "generator 2.0.1 (core)",
                "info 2.0.0 (core)",
                "limits 2.0.0 (core)",
                "org 1.13.1 (core)",
                "salesforce-alm 54.4.0 (core)",
                "schema 2.1.0 (core)",
                "sfdx-cli 7.151.1 (core)",
                "signups 1.1.0 (core)",
                "source 1.9.8 (core)",
                "telemetry 2.0.0 (core)",
                "templates 54.7.0 (core)",
                "trust 1.1.0 (core)",
                "user 1.7.1 (core)"
        ],
        "osVersion": "Darwin 21.3.0"
}

Additional information

force:source:legacy:push command doesn't have this issue.

filiprafalowicz avatar May 20 '22 12:05 filiprafalowicz

Thank you for filing this issue. We appreciate your feedback and will review the issue as soon as possible. Remember, however, that GitHub isn't a mechanism for receiving support under any agreement or SLA. If you require immediate assistance, contact Salesforce Customer Support.

github-actions[bot] avatar May 20 '22 12:05 github-actions[bot]

Hey @filiprafalowicz, there's an ongoing performance degradation that's causing sfdx to timeout, see https://trailblazer.salesforce.com/issues_view?title=performance-degradation-message-queue-processing-on-multiple-sandbox-instances&Id=a1p4V00000212Ja

We don't think this is related to sfdx, but I'll keep the issue open so we can provide updates.

cristiand391 avatar May 30 '22 21:05 cristiand391

We have determined that the issue you reported exists in code owned by another team that uses only the official support channels. To ensure that your issue is addressed, open an official Salesforce customer support ticket with a link to this issue. We encourage anyone experiencing this issue to do the same to increase the priority. We will keep this issue open for the community to collaborate on.

github-actions[bot] avatar Jun 02 '22 13:06 github-actions[bot]

@cristiand391 are you sure this is related? I see this issue only when I use new source commands and if I use legacy ones everything works fine. New source commands fail for me every time, no matter on what instance my scratch org is and legacy commands work fine on the same instances.

filiprafalowicz avatar Jun 02 '22 13:06 filiprafalowicz

@filiprafalowicz - can you please post the last ~25 lines of debug output when you run the force:source:push command with --dev-debug? It's possible this is fixed in the latest source plugin but not sure. In fact, you might be able to test this if you install the latest version of that plugin and try that command. To do that, sfdx plugins:install source@latest and run the push command. Remember to uninstall that version of the plugin with, sfdx plugins:uninstall source

shetzel avatar Jun 21 '22 17:06 shetzel

@shetzel I tried with most recent sfdx version and then I tried with latest version of source plugin and got the same error. Here is the debug output I got at the end:

sf:MetadataApiDeploy DEBUG MDAPI status update: InProgress +11s
  sfdx:Lifecycle A lifecycle event with the name POLLING_TIME_OUT does not exist. An event must be registered before it can be emitted. +33m
  sf:PollingClient DEBUG Polling timed out +0ms

ERROR running force:source:push:  Metadata API request failed: The client has timed out. 
*** Internal Diagnostic ***

MetadataTransferError: Metadata API request failed: The client has timed out.
    at MetadataApiDeploy.pollStatus (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@salesforce/source-deploy-retrieve/lib/src/client/metadataTransfer.js:83:27)
    at async Push.deploy (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@salesforce/plugin-source/lib/commands/force/source/push.js:80:28)
    at async Push.run (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@salesforce/plugin-source/lib/commands/force/source/push.js:29:9)
    at async Push._run (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@salesforce/command/lib/sfdxCommand.js:89:40)
    at async Config.runCommand (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@oclif/config/lib/config.js:173:24)
    at async SfdxMain.run (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@oclif/command/lib/main.js:27:9)
    at async SfdxMain._run (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@oclif/command/lib/command.js:43:20)
    at async Object.run (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/dist/cli.js:162:47)
DUE TO:
PollingClientTimeout: The client has timed out.
    at PollingClient.subscribe (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@salesforce/core/lib/status/pollingClient.js:92:19)
    at async MetadataApiDeploy.pollStatus (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@salesforce/source-deploy-retrieve/lib/src/client/metadataTransfer.js:71:43)
    at async Push.deploy (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@salesforce/plugin-source/lib/commands/force/source/push.js:80:28)
    at async Push.run (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@salesforce/plugin-source/lib/commands/force/source/push.js:29:9)
    at async Push._run (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@salesforce/command/lib/sfdxCommand.js:89:40)
    at async Config.runCommand (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@oclif/config/lib/config.js:173:24)
    at async SfdxMain.run (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@oclif/command/lib/main.js:27:9)
    at async SfdxMain._run (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@oclif/command/lib/command.js:43:20)
    at async Object.run (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/dist/cli.js:162:47)
******

  sf:Push ERROR [
  sf:Push   '\x1B[1mERROR running force:source:push: \x1B[22m',
  sf:Push   '\x1B[31mMetadata API request failed: The client has timed out.\x1B[39m',
  sf:Push   '\x1B[31m\x1B[39m\n' +
  sf:Push     '\x1B[31m*** Internal Diagnostic ***\x1B[39m\n' +
  sf:Push     '\x1B[31m\x1B[39m\n' +
  sf:Push     '\x1B[31mMetadataTransferError: Metadata API request failed: The client has timed out.\x1B[39m\n' +
  sf:Push     '\x1B[31m    at MetadataApiDeploy.pollStatus (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@salesforce/source-deploy-retrieve/lib/src/client/metadataTransfer.js:83:27)\x1B[39m\n' +
  sf:Push     '\x1B[31m    at async Push.deploy (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@salesforce/plugin-source/lib/commands/force/source/push.js:80:28)\x1B[39m\n' +
  sf:Push     '\x1B[31m    at async Push.run (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@salesforce/plugin-source/lib/commands/force/source/push.js:29:9)\x1B[39m\n' +
  sf:Push     '\x1B[31m    at async Push._run (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@salesforce/command/lib/sfdxCommand.js:89:40)\x1B[39m\n' +
  sf:Push     '\x1B[31m    at async Config.runCommand (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@oclif/config/lib/config.js:173:24)\x1B[39m\n' +
  sf:Push     '\x1B[31m    at async SfdxMain.run (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@oclif/command/lib/main.js:27:9)\x1B[39m\n' +
  sf:Push     '\x1B[31m    at async SfdxMain._run (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@oclif/command/lib/command.js:43:20)\x1B[39m\n' +
  sf:Push     '\x1B[31m    at async Object.run (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/dist/cli.js:162:47)\x1B[39m\n' +
  sf:Push     '\x1B[31mDUE TO:\x1B[39m\n' +
  sf:Push     '\x1B[31mPollingClientTimeout: The client has timed out.\x1B[39m\n' +
  sf:Push     '\x1B[31m    at PollingClient.subscribe (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@salesforce/core/lib/status/pollingClient.js:92:19)\x1B[39m\n' +
  sf:Push     '\x1B[31m    at async MetadataApiDeploy.pollStatus (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@salesforce/source-deploy-retrieve/lib/src/client/metadataTransfer.js:71:43)\x1B[39m\n' +
  sf:Push     '\x1B[31m    at async Push.deploy (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@salesforce/plugin-source/lib/commands/force/source/push.js:80:28)\x1B[39m\n' +
  sf:Push     '\x1B[31m    at async Push.run (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@salesforce/plugin-source/lib/commands/force/source/push.js:29:9)\x1B[39m\n' +
  sf:Push     '\x1B[31m    at async Push._run (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@salesforce/command/lib/sfdxCommand.js:89:40)\x1B[39m\n' +
  sf:Push     '\x1B[31m    at async Config.runCommand (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@oclif/config/lib/config.js:173:24)\x1B[39m\n' +
  sf:Push     '\x1B[31m    at async SfdxMain.run (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@oclif/command/lib/main.js:27:9)\x1B[39m\n' +
  sf:Push     '\x1B[31m    at async SfdxMain._run (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/node_modules/@oclif/command/lib/command.js:43:20)\x1B[39m\n' +
  sf:Push     '\x1B[31m    at async Object.run (/Users/FRafal/.local/share/sfdx/client/7.157.0-adf40ea/dist/cli.js:162:47)\x1B[39m\n' +
  sf:Push     '\x1B[31m******\x1B[39m\n' +
  sf:Push     '\x1B[31m\x1B[39m'
  sf:Push ] +33m

filiprafalowicz avatar Jul 04 '22 19:07 filiprafalowicz

Are there any clues in the org? Is the deployment completing successfully, or failing with some error?

About how long is the deploy taking before the timeout message occurs, and how long before it completes?

mshanemc avatar Jul 13 '22 20:07 mshanemc

@mshanemc yes, deployment completes successfully in the org. I am not 100% sure how long it takes before we see the timeout, but deployment took 43 minutes on the SF side. It timed out at 8451/8496 components so I would say it was probably after 35-40 minutes.

Can we have this issue reopened?

filiprafalowicz avatar Aug 04 '22 12:08 filiprafalowicz

@filiprafalowicz I was wondering if you could open a Salesforce support ticket for this issue?

peternhale avatar Aug 04 '22 13:08 peternhale

@filiprafalowicz would it be possible to get the deploy job id and the org id where this issue is occurring. I would also need the timeframe of the push attempt.

peternhale avatar Aug 04 '22 14:08 peternhale

@peternhale sorry for the delay - I just reproduced the issue and here are the details: Org ID = 00D1900000062B5 Deployment ID = 0Af1900001fx2IL Start Time = 9/5/2022, 7:23 AM End Time = 9/5/2022, 8:22 AM It failed around 9/5/2022, 7:50 AM

filiprafalowicz avatar Sep 05 '22 15:09 filiprafalowicz

This issue has not received a response in 7 days. It will auto-close in 7 days unless a response is posted.

github-actions[bot] avatar Sep 30 '22 02:09 github-actions[bot]

@peternhale did you have a chance to review what I provided?

filiprafalowicz avatar Sep 30 '22 11:09 filiprafalowicz

Hey @filiprafalowicz, the force:source:push command polls the org for the status of the metadata transfer request when pushing changes.

The polling will timeout after 33 minutes unless you specify a longer timeout with the --wait flag, in your comment above you said sfdx timed out after 35-40min so that might explain the issue. Can you try specifying a longer time like --wait 100 to see if that fixes your issue?

I'm also curious why the legacy:push command works as it also defaults to 33min for the polling timeout.

cristiand391 avatar Sep 30 '22 15:09 cristiand391

This issue has not received a response in 7 days. It will auto-close in 7 days unless a response is posted.

github-actions[bot] avatar Oct 08 '22 02:10 github-actions[bot]

@cristiand391 seems that it fixed the issue. I didn't try this initially as it was not required in the legacy push command so I assumed there is something else that's causing this. Thanks for your help, I am closing this issue now.

filiprafalowicz avatar Oct 10 '22 13:10 filiprafalowicz