Cli: Update Source Tracking takes a very long time

[maaaaarco]

Summary

After I push for the first time in a Scratch Org the CLI remains stuck for more than 40mins with this message:

Steps To Reproduce:

1. Create a new Scratch Org
2. Run a push command using a big repository

Repository to reproduce: I cannot share it, it's a private company repo

Expected result

Updating Source tracking should not take that long. Please note that our repository hasn't grown much recently. It contains around 5k components since last year and only recently we are facing the issue.

Additional information

_Feel free to attach a screenshot_.

SFDX CLI Version(to find the version of the CLI engine run sfdx --version):
sfdx-cli/7.70.1-3d8a6229fc darwin-x64 node-v12.18.3

SFDX plugin Version(to find the version of the CLI plugin run sfdx plugins --core)
@oclif/plugin-autocomplete 0.2.0
@oclif/plugin-commands 1.3.0 (core)
@oclif/plugin-not-found 1.2.4 (core)
@oclif/plugin-plugins 1.9.0 (core)
@oclif/plugin-warn-if-update-available 1.7.0 (core)
@oclif/plugin-which 1.0.3 (core)
@salesforce/analytics 0.22.0
@salesforce/lwc-dev-server 2.5.1
├─ @oclif/plugin-help 2.2.1
└─ @oclif/plugin-update 1.3.9
@salesforce/sfdx-trust 3.2.1 (core)
analytics 1.12.0 (core)
generator 1.1.3 (core)
salesforcedx 49.6.1 (core)
├─ custom-metadata 1.0.8 (core)
├─ salesforcedx-templates 49.2.0 (core)
├─ @salesforce/sfdx-plugin-lwc-test 0.1.7 (core)
└─ salesforce-alm 49.6.0 (core)
sfdx-cli 7.70.1 (core)

OS and version:
MacOs Mojave

[shetzel]

@maaaaarco - for 5k components it should definitely not take that long. In last week's patch release we added the SFDX_DISABLE_SOURCE_MEMBER_POLLING env var to disable the polling. Use that if it's completely broken for you or in CI that doesn't care about source tracking. There is also enhanced debugging output around the polling to attempt to find the problem source members. To see that debugging you can set the DEBUG env var to sfdx:MaxRevision and run your command. If there is helpful information learned from the debug output please reply in this thread and mention me. Thanks!

[maaaaarco]

@shetzel thanks for the feedback. The problem is that these are not a Scratch Orgs I'm using in a CLI process. These are the ones we use for our daily tasks. We need Source Tracking to work properly otherwise we wont be able to retrieve changes.

In regards to the DEBUG var you mentioned, I'll be happy to try it out and share valuable information if any. Can you confirm I should run the push command it like this:

DEBUG="sfdx:MaxRevision"
sfdx force:source:push

Thanks

[shetzel]

Correct, something like DEBUG="sfdx:MaxRevision" && sfdx force:source:push

If you used the SFDX_DISABLE_SOURCE_MEMBER_POLLING env var to setup your development scratch org, you would need to wait a few minutes for the SourceMembers to be created for those components, then run sfdx force:source:tracking:reset to reset the state of source tracking to be the current local and remote state.

[maaaaarco]

@shetzel thanks a lot. After updating to the latest version the CLI does not get stuck while updating SourceTracking anymore, seems the timeout now works properly. What I can see from the logs though is that it fails to retrieve the SourceTracking information in the given timeframe. Push is successful but if I run a force:source:status afterwards I get thousands of changes:

2020-09-09T08:27:57.472Z sfdx:MaxRevision INFO Reading config file: /Users/mzeuli/VSCProjects/**********/.sfdx/orgs/[email protected]/maxRevision.json
2020-09-09T08:27:57.921Z sfdx:MaxRevision DEBUG SELECT MemberType, MemberName, IsNameObsolete, RevisionCounter FROM SourceMember WHERE RevisionCounter > 0
2020-09-09T08:27:58.306Z sfdx:MaxRevision DEBUG SELECT MemberType, MemberName, IsNameObsolete, RevisionCounter FROM SourceMember WHERE RevisionCounter > 0
2020-09-09T08:27:58.597Z sfdx:MaxRevision DEBUG Found 0 elements not synced down from server
2020-09-09T08:27:58.604Z sfdx:MaxRevision INFO Writing to config file: /Users/mzeuli/VSCProjects/**********/.sfdx/orgs/[email protected]/maxRevision.json
2020-09-09T08:46:55.953Z sfdx:MaxRevision DEBUG Polling for 5807 SourceMembers from revision 0 with 93 max attempts
2020-09-09T08:46:55.954Z sfdx:MaxRevision DEBUG SELECT MemberType, MemberName, IsNameObsolete, RevisionCounter FROM SourceMember WHERE RevisionCounter > 0
2020-09-09T08:46:56.738Z sfdx:MaxRevision DEBUG [1] Found 62 of 5807 SourceMembers
2020-09-09T08:46:58.049Z sfdx:MaxRevision DEBUG [2] Found 62 of 5807 SourceMembers
2020-09-09T08:46:59.329Z sfdx:MaxRevision DEBUG [3] Found 62 of 5807 SourceMembers
2020-09-09T08:47:00.661Z sfdx:MaxRevision DEBUG [4] Found 62 of 5807 SourceMembers
2020-09-09T08:47:01.958Z sfdx:MaxRevision DEBUG [5] Found 62 of 5807 SourceMembers
2020-09-09T08:47:03.265Z sfdx:MaxRevision DEBUG [6] Found 62 of 5807 SourceMembers
2020-09-09T08:47:04.753Z sfdx:MaxRevision DEBUG [7] Found 62 of 5807 SourceMembers
2020-09-09T08:47:06.065Z sfdx:MaxRevision DEBUG [8] Found 62 of 5807 SourceMembers
2020-09-09T08:47:07.390Z sfdx:MaxRevision DEBUG [9] Found 62 of 5807 SourceMembers
2020-09-09T08:47:08.706Z sfdx:MaxRevision DEBUG [10] Found 62 of 5807 SourceMembers
2020-09-09T08:47:10.014Z sfdx:MaxRevision DEBUG [11] Found 62 of 5807 SourceMembers
2020-09-09T08:47:11.367Z sfdx:MaxRevision DEBUG [12] Found 62 of 5807 SourceMembers
2020-09-09T08:47:12.959Z sfdx:MaxRevision DEBUG [13] Found 62 of 5807 SourceMembers
2020-09-09T08:47:14.278Z sfdx:MaxRevision DEBUG [14] Found 62 of 5807 SourceMembers
2020-09-09T08:47:15.610Z sfdx:MaxRevision DEBUG [15] Found 62 of 5807 SourceMembers
2020-09-09T08:47:16.986Z sfdx:MaxRevision DEBUG [16] Found 62 of 5807 SourceMembers
2020-09-09T08:47:18.330Z sfdx:MaxRevision DEBUG [17] Found 62 of 5807 SourceMembers
2020-09-09T08:47:19.729Z sfdx:MaxRevision DEBUG [18] Found 62 of 5807 SourceMembers
2020-09-09T08:47:21.107Z sfdx:MaxRevision DEBUG [19] Found 62 of 5807 SourceMembers
2020-09-09T08:47:22.467Z sfdx:MaxRevision DEBUG [20] Found 62 of 5807 SourceMembers
2020-09-09T08:47:23.843Z sfdx:MaxRevision DEBUG [21] Found 62 of 5807 SourceMembers
2020-09-09T08:47:25.374Z sfdx:MaxRevision DEBUG [22] Found 62 of 5807 SourceMembers
2020-09-09T08:47:26.973Z sfdx:MaxRevision DEBUG [23] Found 62 of 5807 SourceMembers
2020-09-09T08:47:28.380Z sfdx:MaxRevision DEBUG [24] Found 62 of 5807 SourceMembers
2020-09-09T08:47:29.704Z sfdx:MaxRevision DEBUG [25] Found 62 of 5807 SourceMembers
2020-09-09T08:47:31.093Z sfdx:MaxRevision DEBUG [26] Found 62 of 5807 SourceMembers
2020-09-09T08:47:32.492Z sfdx:MaxRevision DEBUG [27] Found 62 of 5807 SourceMembers
2020-09-09T08:47:33.865Z sfdx:MaxRevision DEBUG [28] Found 62 of 5807 SourceMembers
2020-09-09T08:47:35.252Z sfdx:MaxRevision DEBUG [29] Found 62 of 5807 SourceMembers
2020-09-09T08:47:36.647Z sfdx:MaxRevision DEBUG [30] Found 62 of 5807 SourceMembers
2020-09-09T08:47:38.119Z sfdx:MaxRevision DEBUG [31] Found 62 of 5807 SourceMembers
2020-09-09T08:47:39.520Z sfdx:MaxRevision DEBUG [32] Found 62 of 5807 SourceMembers
2020-09-09T08:47:40.932Z sfdx:MaxRevision DEBUG [33] Found 62 of 5807 SourceMembers
2020-09-09T08:47:42.363Z sfdx:MaxRevision DEBUG [34] Found 62 of 5807 SourceMembers
2020-09-09T08:47:43.791Z sfdx:MaxRevision DEBUG [35] Found 62 of 5807 SourceMembers
2020-09-09T08:47:45.235Z sfdx:MaxRevision DEBUG [36] Found 62 of 5807 SourceMembers
2020-09-09T08:47:46.863Z sfdx:MaxRevision DEBUG [37] Found 62 of 5807 SourceMembers
2020-09-09T08:47:48.595Z sfdx:MaxRevision DEBUG [38] Found 62 of 5807 SourceMembers
2020-09-09T08:47:50.027Z sfdx:MaxRevision DEBUG [39] Found 62 of 5807 SourceMembers
2020-09-09T08:47:51.524Z sfdx:MaxRevision DEBUG [40] Found 62 of 5807 SourceMembers
2020-09-09T08:47:52.973Z sfdx:MaxRevision DEBUG [41] Found 62 of 5807 SourceMembers
2020-09-09T08:47:54.453Z sfdx:MaxRevision DEBUG [42] Found 62 of 5807 SourceMembers
2020-09-09T08:47:55.887Z sfdx:MaxRevision DEBUG [43] Found 62 of 5807 SourceMembers
2020-09-09T08:47:57.377Z sfdx:MaxRevision DEBUG [44] Found 62 of 5807 SourceMembers
2020-09-09T08:47:58.880Z sfdx:MaxRevision DEBUG [45] Found 62 of 5807 SourceMembers
2020-09-09T08:48:00.364Z sfdx:MaxRevision DEBUG [46] Found 62 of 5807 SourceMembers
2020-09-09T08:48:01.888Z sfdx:MaxRevision DEBUG [47] Found 62 of 5807 SourceMembers
2020-09-09T08:48:03.485Z sfdx:MaxRevision DEBUG [48] Found 62 of 5807 SourceMembers
2020-09-09T08:48:05.352Z sfdx:MaxRevision DEBUG [49] Found 62 of 5807 SourceMembers
2020-09-09T08:48:07.013Z sfdx:MaxRevision DEBUG [50] Found 62 of 5807 SourceMembers
2020-09-09T08:48:08.569Z sfdx:MaxRevision DEBUG [51] Found 62 of 5807 SourceMembers
2020-09-09T08:48:10.125Z sfdx:MaxRevision DEBUG [52] Found 62 of 5807 SourceMembers
2020-09-09T08:48:11.657Z sfdx:MaxRevision DEBUG [53] Found 62 of 5807 SourceMembers
2020-09-09T08:48:13.576Z sfdx:MaxRevision DEBUG [54] Found 62 of 5807 SourceMembers
2020-09-09T08:48:15.087Z sfdx:MaxRevision DEBUG [55] Found 62 of 5807 SourceMembers
2020-09-09T08:48:16.611Z sfdx:MaxRevision DEBUG [56] Found 62 of 5807 SourceMembers
2020-09-09T08:48:18.260Z sfdx:MaxRevision DEBUG [57] Found 62 of 5807 SourceMembers
2020-09-09T08:48:19.860Z sfdx:MaxRevision DEBUG [58] Found 62 of 5807 SourceMembers
2020-09-09T08:48:21.408Z sfdx:MaxRevision DEBUG [59] Found 62 of 5807 SourceMembers
2020-09-09T08:48:22.990Z sfdx:MaxRevision DEBUG [60] Found 62 of 5807 SourceMembers
2020-09-09T08:48:24.570Z sfdx:MaxRevision DEBUG [61] Found 62 of 5807 SourceMembers
2020-09-09T08:48:26.151Z sfdx:MaxRevision DEBUG [62] Found 62 of 5807 SourceMembers
2020-09-09T08:48:28.155Z sfdx:MaxRevision DEBUG [63] Found 62 of 5807 SourceMembers
2020-09-09T08:48:29.873Z sfdx:MaxRevision DEBUG [64] Found 62 of 5807 SourceMembers
2020-09-09T08:48:31.601Z sfdx:MaxRevision DEBUG [65] Found 62 of 5807 SourceMembers
2020-09-09T08:48:33.218Z sfdx:MaxRevision DEBUG [66] Found 62 of 5807 SourceMembers
2020-09-09T08:48:34.905Z sfdx:MaxRevision DEBUG [67] Found 62 of 5807 SourceMembers
2020-09-09T08:48:36.529Z sfdx:MaxRevision DEBUG [68] Found 62 of 5807 SourceMembers
2020-09-09T08:48:38.186Z sfdx:MaxRevision DEBUG [69] Found 62 of 5807 SourceMembers
2020-09-09T08:48:39.834Z sfdx:MaxRevision DEBUG [70] Found 62 of 5807 SourceMembers
2020-09-09T08:48:41.483Z sfdx:MaxRevision DEBUG [71] Found 62 of 5807 SourceMembers
2020-09-09T08:48:43.129Z sfdx:MaxRevision DEBUG [72] Found 62 of 5807 SourceMembers
2020-09-09T08:48:45.827Z sfdx:MaxRevision DEBUG [73] Found 62 of 5807 SourceMembers
2020-09-09T08:48:47.508Z sfdx:MaxRevision DEBUG [74] Found 62 of 5807 SourceMembers
2020-09-09T08:48:49.348Z sfdx:MaxRevision DEBUG [75] Found 62 of 5807 SourceMembers
2020-09-09T08:48:51.118Z sfdx:MaxRevision DEBUG [76] Found 62 of 5807 SourceMembers
2020-09-09T08:48:52.885Z sfdx:MaxRevision DEBUG [77] Found 62 of 5807 SourceMembers
2020-09-09T08:48:54.630Z sfdx:MaxRevision DEBUG [78] Found 62 of 5807 SourceMembers
2020-09-09T08:48:56.265Z sfdx:MaxRevision DEBUG [79] Found 62 of 5807 SourceMembers
2020-09-09T08:48:57.922Z sfdx:MaxRevision DEBUG [80] Found 62 of 5807 SourceMembers
2020-09-09T08:48:59.666Z sfdx:MaxRevision DEBUG [81] Found 62 of 5807 SourceMembers
2020-09-09T08:49:01.382Z sfdx:MaxRevision DEBUG [82] Found 62 of 5807 SourceMembers
2020-09-09T08:49:03.114Z sfdx:MaxRevision DEBUG [83] Found 62 of 5807 SourceMembers
2020-09-09T08:49:04.798Z sfdx:MaxRevision DEBUG [84] Found 62 of 5807 SourceMembers
2020-09-09T08:49:06.535Z sfdx:MaxRevision DEBUG [85] Found 62 of 5807 SourceMembers
2020-09-09T08:49:08.307Z sfdx:MaxRevision DEBUG [86] Found 62 of 5807 SourceMembers
2020-09-09T08:49:10.126Z sfdx:MaxRevision DEBUG [87] Found 62 of 5807 SourceMembers
2020-09-09T08:49:11.850Z sfdx:MaxRevision DEBUG [88] Found 62 of 5807 SourceMembers
2020-09-09T08:49:13.588Z sfdx:MaxRevision DEBUG [89] Found 62 of 5807 SourceMembers
2020-09-09T08:49:15.347Z sfdx:MaxRevision DEBUG [90] Found 62 of 5807 SourceMembers
2020-09-09T08:49:17.152Z sfdx:MaxRevision DEBUG [91] Found 62 of 5807 SourceMembers
2020-09-09T08:49:18.970Z sfdx:MaxRevision DEBUG [92] Found 62 of 5807 SourceMembers
2020-09-09T08:49:20.692Z sfdx:MaxRevision DEBUG [93] Found 62 of 5807 SourceMembers
2020-09-09T08:49:20.693Z sfdx:MaxRevision WARN Polling for SourceMembers timed out after 145s and 93 attempts
2020-09-09T08:49:20.694Z sfdx:MaxRevision DEBUG Could not find SourceMembers for 5745 components
2020-09-09T08:49:20.695Z sfdx:MaxRevision DEBUG SELECT MemberType, MemberName, IsNameObsolete, RevisionCounter FROM SourceMember WHERE RevisionCounter > 0
2020-09-09T08:49:21.428Z sfdx:MaxRevision DEBUG inserting Profile__Admin with RevisionCounter: 234
2020-09-09T08:49:21.429Z sfdx:MaxRevision DEBUG SELECT MAX(RevisionCounter) MaxRev FROM SourceMember
2020-09-09T08:49:21.432Z sfdx:MaxRevision INFO Writing to config file: /Users/mzeuli/VSCProjects/**********/.sfdx/orgs/[email protected]/maxRevision.json
2020-09-09T08:49:22.168Z sfdx:MaxRevision DEBUG new serverMaxRevisionCounter = 234
2020-09-09T08:49:22.169Z sfdx:MaxRevision INFO Writing to config file: /Users/mzeuli/VSCProjects/**********/.sfdx/orgs/[email protected]/maxRevision.json
2020-09-09T08:49:22.170Z sfdx:MaxRevision DEBUG updating Profile__Admin to RevisionCounter 234
2020-09-09T08:49:22.170Z sfdx:MaxRevision INFO Writing to config file: /Users/mzeuli/VSCProjects/**********/.sfdx/orgs/[email protected]/maxRevision.json

[maaaaarco]

@shetzel is there a way I can override that timeout? For me it's not an issue having users wait up to 200 or 300 sec to get the SourceTracking updated correctly but it's a big one not being able to allow them to work in a clean environment. Most people in my team are not developers and are not comfortable working with terminal commands.
As of now we have a VsCode task that creates the scratch and then push the components, I could potentially overwrite the timeout there....

[shetzel]

@maaaaarco - there is no way to override the timeout in the current version of the plugin. I'll try to get something added in the next patch release (next week). In the meantime, you could use the sfdx force:source:tracking:reset command to set the source tracking state when all the SourceMembers have been created in the org. I realize this is an inconvenient workaround and I apologize. I'll tweak the default polling behavior and provide a way to override the timeout.

[shetzel]

@maaaaarco - I've made more polling improvements and added a new env var SFDX_SOURCE_MEMBER_POLLING_TIMEOUT where you can override the default (calculated) polling timeout with your own value in seconds. It will be available in the next patch release which is hopefully next Thursday but could possibly be the following Thursday. Thanks for your patience and for working with me on this!

[maaaaarco]

@shetzel I'll try it out and let you know here ;)

[maaaaarco]

@shetzel I'm closing this, by overwriting the default timeout with a longer one we manage to mitigate the issue almost completely (very few exception were the SourceMemeber update takes more than 10 mins).
Thanks for this enhancement :)

P.S.
For reference, we calculated our timeout by adding a minute every 1k components we have in the repository... In our case 5k components so a 5 mins timeout did the job. Enabling the DEBUG="sfdx:MaxRevision" I can see SourceMember table updating after 3, 3.5 minutes

[maaaaarco]

@shetzel this is happening again, even though I set the timeout to 300 secs it's been like these for more than 20mins

[shetzel]

I'd enable debugging to get more info about what's going on. export DEBUG "sfdx:RemoteSourceTrackingService" (the name of the class changed)

[maaaaarco]

@shetzel I was not able to reproduce the issue again... might be that one time exception ;)