sfdx force:lightning:test:install fails with "Cannot read property 'indexOf' of undefined"

[maniax89]

I've been seeing this error more frequently lately:

$ sfdx force:lightning:test:install -u my_org

fails with

  ▸    Cannot read property 'indexOf' of undefined

I know it is a problem with the CLI, but this was intermittent and becoming more of a burden during CI testing (it will pass 1/10 times now)

Are there any suggestions on things like waiting time, retry logic, etc. after creating a new scratch org that I can employ in order to reduce the times this install fails?

Any help is greatly appreciated

[esalman-sfdc]

If you have any evidence (e.g. logging the time its taking for the command, and then looking if its over the default wait of 2 mins in failure cases) to suggest that it wait time related, you could try increasing the wait via '-w'

I know its not really ideal, but it should get easier to debug, once the CLI bug (W-4442231)that is masking the actual error message is resolved.

I'll also try checking with the CLI team for any additional tips/tricks.

[amphro]

Can you get the stack trace from ~/.sfdx/sfdx.log?

[maniax89]

Sure:

{"name":"sfdx","hostname":"turge.local","pid":62201,"log":"Org","config":{"username":"test-promkwgaqpiu@turge.net"},"level":40,"msg":"failed to read directory /Users/andrewturgeon/Dev/my_project/.sfdx/orgs/test-promkwgaqpiu@turge.net","time":"2017-12-06T15:49:21.452Z","v":0}

so it looks like it isn't able to read that org, maybe that file didn't get created correctly when running the create command?

sfdx force:org:create         \
  --setalias my_test_org \
  --definitionfile ./config/project-scratch-def.json

where the project-scratch-def.json looks like:

{
    "orgName": "my_test_org",
    "country": "US",
    "language": "en",
    "edition": "Developer",
    "hasSampleData": true,
    "orgPreferences" : {
        "enabled": ["S1DesktopEnabled"]
    }
}

so it might be a problem with the org:create rather than the lightning:install but I cannot be sure

[amphro]

That log file seems wrong as it should have the error Cannot read property 'indexOf' of undefined in it.

The other error you got does seem problematic, but my_project/.sfdx/orgs/test-promkwgaqpiu@turge.net is created on source:push, not org:create. Are you pushing your tests to your org? I don't know when that file is attempted to be read by lighting:install. @esalman-sfdc ?

[maniax89]

Yes I would figure to see that error in the logs as well, but I can't find it in the home directory log ~/.sfdx/sfdx.log - is it found in a different log file?

[esalman-sfdc]

I don’t think that the install command reads that file. Flow is to install the package and then use push.

May be try changing log level, https://developer.salesforce.com/docs/atlas.en-us.sfdx_dev.meta/sfdx_dev/sfdx_dev_cli_log_messages.htm

[maniax89]

Running the following command 5 times (retries)

Command:

$ sfdx force:lightning:test:install -u turge -t mocha --loglevel DEBUG

Output:

 ▸    Cannot read property 'indexOf' of undefined
 ▸    Cannot read property 'indexOf' of undefined
 ▸    Cannot read property 'indexOf' of undefined
 ▸    Cannot read property 'indexOf' of undefined
 ▸    Cannot read property 'indexOf' of undefined
 ▸    Cannot read property 'indexOf' of undefined

Log:

{"name":"sfdx","hostname":"turge.local","pid":64984,"log":"Org","config":{"username":"test-jwcg5oienyof@turge.net"},"level":40,"msg":"failed to read directory /Users/andrewturgeon/Dev/my_project/.sfdx/orgs/test-jwcg5oienyof@turge.net","time":"2017-12-06T18:38:12.029Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65060,"log":"crypto","level":20,"msg":"process.env.SFDX_DISABLE_ENCRYPTION: undefined","time":"2017-12-06T18:38:53.609Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65060,"log":"crypto","level":20,"msg":"retryStatus: undefined","time":"2017-12-06T18:38:53.610Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65060,"log":"keyChainImpl","level":20,"msg":"platform: darwin","time":"2017-12-06T18:38:53.610Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65060,"log":"keyChainImpl","level":20,"msg":"keyPath: /Users/andrewturgeon/.sfdx/key.json","time":"2017-12-06T18:38:53.610Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65060,"log":"keyChainImpl","level":20,"msg":"keyPath not found","time":"2017-12-06T18:38:53.612Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65060,"log":"keyChainImpl","level":20,"msg":"isUsingGenericKeychain: false","time":"2017-12-06T18:38:53.613Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65060,"log":"keyChainImpl","level":20,"msg":"hasAuthentications: true","time":"2017-12-06T18:38:53.613Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65060,"log":"crypto","level":20,"msg":"keychain retrieved","time":"2017-12-06T18:38:53.613Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65060,"log":"crypto","level":20,"msg":"password retrieved from keychain","time":"2017-12-06T18:38:53.658Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65060,"level":20,"msg":"Invoking 'force:force:lightning:test:install' on username 'test-ondq03lwpyur@turge.net' with parameters: {\"targetusername\":\"turge\",\"packagetype\":\"mocha\",\"loglevel\":\"DEBUG\"}","time":"2017-12-06T18:38:53.690Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65071,"log":"crypto","level":20,"msg":"process.env.SFDX_DISABLE_ENCRYPTION: undefined","time":"2017-12-06T18:38:55.289Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65071,"log":"crypto","level":20,"msg":"retryStatus: undefined","time":"2017-12-06T18:38:55.290Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65071,"log":"keyChainImpl","level":20,"msg":"platform: darwin","time":"2017-12-06T18:38:55.290Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65071,"log":"keyChainImpl","level":20,"msg":"keyPath: /Users/andrewturgeon/.sfdx/key.json","time":"2017-12-06T18:38:55.290Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65071,"log":"keyChainImpl","level":20,"msg":"keyPath not found","time":"2017-12-06T18:38:55.291Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65071,"log":"keyChainImpl","level":20,"msg":"isUsingGenericKeychain: false","time":"2017-12-06T18:38:55.292Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65071,"log":"keyChainImpl","level":20,"msg":"hasAuthentications: true","time":"2017-12-06T18:38:55.292Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65071,"log":"crypto","level":20,"msg":"keychain retrieved","time":"2017-12-06T18:38:55.292Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65071,"log":"crypto","level":20,"msg":"password retrieved from keychain","time":"2017-12-06T18:38:55.340Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65071,"level":20,"msg":"Invoking 'force:force:lightning:test:install' on username 'test-ondq03lwpyur@turge.net' with parameters: {\"targetusername\":\"turge\",\"packagetype\":\"mocha\",\"loglevel\":\"DEBUG\"}","time":"2017-12-06T18:38:55.371Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65082,"log":"crypto","level":20,"msg":"process.env.SFDX_DISABLE_ENCRYPTION: undefined","time":"2017-12-06T18:38:56.907Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65082,"log":"crypto","level":20,"msg":"retryStatus: undefined","time":"2017-12-06T18:38:56.907Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65082,"log":"keyChainImpl","level":20,"msg":"platform: darwin","time":"2017-12-06T18:38:56.907Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65082,"log":"keyChainImpl","level":20,"msg":"keyPath: /Users/andrewturgeon/.sfdx/key.json","time":"2017-12-06T18:38:56.908Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65082,"log":"keyChainImpl","level":20,"msg":"keyPath not found","time":"2017-12-06T18:38:56.909Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65082,"log":"keyChainImpl","level":20,"msg":"isUsingGenericKeychain: false","time":"2017-12-06T18:38:56.909Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65082,"log":"keyChainImpl","level":20,"msg":"hasAuthentications: true","time":"2017-12-06T18:38:56.909Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65082,"log":"crypto","level":20,"msg":"keychain retrieved","time":"2017-12-06T18:38:56.909Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65082,"log":"crypto","level":20,"msg":"password retrieved from keychain","time":"2017-12-06T18:38:56.957Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65082,"level":20,"msg":"Invoking 'force:force:lightning:test:install' on username 'test-ondq03lwpyur@turge.net' with parameters: {\"targetusername\":\"turge\",\"packagetype\":\"mocha\",\"loglevel\":\"DEBUG\"}","time":"2017-12-06T18:38:56.985Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65092,"log":"crypto","level":20,"msg":"process.env.SFDX_DISABLE_ENCRYPTION: undefined","time":"2017-12-06T18:38:58.555Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65092,"log":"crypto","level":20,"msg":"retryStatus: undefined","time":"2017-12-06T18:38:58.556Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65092,"log":"keyChainImpl","level":20,"msg":"platform: darwin","time":"2017-12-06T18:38:58.556Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65092,"log":"keyChainImpl","level":20,"msg":"keyPath: /Users/andrewturgeon/.sfdx/key.json","time":"2017-12-06T18:38:58.556Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65092,"log":"keyChainImpl","level":20,"msg":"keyPath not found","time":"2017-12-06T18:38:58.557Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65092,"log":"keyChainImpl","level":20,"msg":"isUsingGenericKeychain: false","time":"2017-12-06T18:38:58.558Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65092,"log":"keyChainImpl","level":20,"msg":"hasAuthentications: true","time":"2017-12-06T18:38:58.558Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65092,"log":"crypto","level":20,"msg":"keychain retrieved","time":"2017-12-06T18:38:58.558Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65092,"log":"crypto","level":20,"msg":"password retrieved from keychain","time":"2017-12-06T18:38:58.606Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65092,"level":20,"msg":"Invoking 'force:force:lightning:test:install' on username 'test-ondq03lwpyur@turge.net' with parameters: {\"targetusername\":\"turge\",\"packagetype\":\"mocha\",\"loglevel\":\"DEBUG\"}","time":"2017-12-06T18:38:58.636Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65102,"log":"crypto","level":20,"msg":"process.env.SFDX_DISABLE_ENCRYPTION: undefined","time":"2017-12-06T18:39:00.356Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65102,"log":"crypto","level":20,"msg":"retryStatus: undefined","time":"2017-12-06T18:39:00.356Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65102,"log":"keyChainImpl","level":20,"msg":"platform: darwin","time":"2017-12-06T18:39:00.357Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65102,"log":"keyChainImpl","level":20,"msg":"keyPath: /Users/andrewturgeon/.sfdx/key.json","time":"2017-12-06T18:39:00.357Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65102,"log":"keyChainImpl","level":20,"msg":"keyPath not found","time":"2017-12-06T18:39:00.358Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65102,"log":"keyChainImpl","level":20,"msg":"isUsingGenericKeychain: false","time":"2017-12-06T18:39:00.358Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65102,"log":"keyChainImpl","level":20,"msg":"hasAuthentications: true","time":"2017-12-06T18:39:00.358Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65102,"log":"crypto","level":20,"msg":"keychain retrieved","time":"2017-12-06T18:39:00.359Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65102,"log":"crypto","level":20,"msg":"password retrieved from keychain","time":"2017-12-06T18:39:00.407Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65102,"level":20,"msg":"Invoking 'force:force:lightning:test:install' on username 'test-ondq03lwpyur@turge.net' with parameters: {\"targetusername\":\"turge\",\"packagetype\":\"mocha\",\"loglevel\":\"DEBUG\"}","time":"2017-12-06T18:39:00.436Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65112,"log":"crypto","level":20,"msg":"process.env.SFDX_DISABLE_ENCRYPTION: undefined","time":"2017-12-06T18:39:02.077Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65112,"log":"crypto","level":20,"msg":"retryStatus: undefined","time":"2017-12-06T18:39:02.078Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65112,"log":"keyChainImpl","level":20,"msg":"platform: darwin","time":"2017-12-06T18:39:02.078Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65112,"log":"keyChainImpl","level":20,"msg":"keyPath: /Users/andrewturgeon/.sfdx/key.json","time":"2017-12-06T18:39:02.078Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65112,"log":"keyChainImpl","level":20,"msg":"keyPath not found","time":"2017-12-06T18:39:02.080Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65112,"log":"keyChainImpl","level":20,"msg":"isUsingGenericKeychain: false","time":"2017-12-06T18:39:02.080Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65112,"log":"keyChainImpl","level":20,"msg":"hasAuthentications: true","time":"2017-12-06T18:39:02.080Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65112,"log":"crypto","level":20,"msg":"keychain retrieved","time":"2017-12-06T18:39:02.080Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65112,"log":"crypto","level":20,"msg":"password retrieved from keychain","time":"2017-12-06T18:39:02.130Z","v":0}
{"name":"sfdx","hostname":"turge.local","pid":65112,"level":20,"msg":"Invoking 'force:force:lightning:test:install' on username 'test-ondq03lwpyur@turge.net' with parameters: {\"targetusername\":\"turge\",\"packagetype\":\"mocha\",\"loglevel\":\"DEBUG\"}","time":"2017-12-06T18:39:02.161Z","v":0}

should I go down to TRACE?

[amphro]

No, trace won't help. Somehow that error isn't bubbling up to the CLI lifecycle to report the stack. My thought is the lighting:test:install is starting its own promise chain and isn't returning back to the CLI @esalman-sfdc - which would explain why the error never gets reported.

[maniax89]

I can dive deeper into the CLI code to figure out where it is actually erroring out potentially, but I figured I wouldn't be alone in this?

[maniax89]

I believe I have figured out the issue.

In the salesforce-alm code, there is a file ./dist/lib/lightning/lightningTestInstallCommand.js that has some lines that look like this:

  execute(context) {
        const org = this.org;
        const releaseVersion = context.releaseversion ?
            `tags/${context.releaseversion}` : 'latest';
        const uri = `https://api.github.com/repos/forcedotcom/LightningTestingService/releases/${releaseVersion}`;
        return new Promise((resolve, reject) => {
            request({
                headers: {
                    'User-Agent': 'LTS'
                },
                uri
            }, (err, res, body) => {
                if (err) {
                    return reject(new Error(err));
                }
                const content = JSON.parse(body);
                if (content.message === 'Not Found') {
                    return reject(new Error(messages.getMessage('invalidVersion', [context.releaseversion], 'lightning_test')));
                }
                // ====== I ADDED THIS LINE =====
                console.log(content);
                // ====== BACK TO THE CODE =====
                const releaseMsg = content.body;
                const ids = [];
                let idx = 0;
                for (let i = 0; i < 3; i++) {
                    idx = releaseMsg.indexOf('p0=', ++idx);
                    ids[i] = releaseMsg.substring(idx + 3, idx + 18);
                }
                let id = '';
                const packagetype = context.packagetype ? context.packagetype.toLowerCase() : 'full';
                if (packagetype === 'jasmine') {
                    id = ids[0];
                }
                else if (packagetype === 'mocha') {
                    id = ids[1];
                }
                else if (packagetype === 'full') {
                    id = ids[2];
                }
                else {
                    return reject(new Error(messages.getMessage('invalidType', [packagetype], 'lightning_test')));
                }
                const ctx = {
                    org,
                    flags: {
                        id,
                        wait: context.wait ? context.wait : 2
                    }
                };
                return resolve(packageInstallCommand.execute(ctx));
            });
        });
    }

checking out the console, I see this:

{ message: 'API rate limit exceeded for 129.42.208.179. (But here\'s the good news: Authenticated requests get a higher rate limit. Check out the documentation for more details.)',
  documentation_url: 'https://developer.github.com/v3/#rate-limiting' }

The for-loop subsequently explodes:

for (let i = 0; i < 3; i++) {
  idx = releaseMsg.indexOf('p0=', ++idx);
  ids[i] = releaseMsg.substring(idx + 3, idx + 18);
}

because it is looking for the indexOf p0= which it will not find...

[maniax89]

I believe as of 12/6/2017, the 3 IDs it is looking for are as follows:

const ids = ['04tJ00000006jBu', '04tJ00000006jBz', '04tJ00000006jC4'];

after putting that code in and re-running, all is well

[esalman-sfdc]

Thanks @maniax89 for digging into this. That code should have some better error handling and fallback mechanism. Lets leave this issue open until we are able to get the plugin updated.

By the way, according to https://developer.github.com/v3/#rate-limiting limit for unauthenticated requests to github are 60 per hour (tied to originating IP address). Does that match your setup (e.g. do you guys have multiple CI jobs running on the same box?)

For now, another workaround you may be able to use is to fallback to sfdx force:package:install which requires package-id instead of trying to figure out correct version automagically.

[chendagit]

I also have this bug when build with travis ci $ sfdx force:lightning:test:install -u ciorg ▸ Cannot read property 'indexOf' of undefined

Also this error is always happening on dirty scratch org and travis ci build too. sfdx force:lightning:test:run Invoking Lightning tests... ▸ ERROR: Cannot read property 'endsWith' of undefined. I think this issue is not yet solved: https://github.com/forcedotcom/LightningTestingService/issues/38

[maniax89]

@esalman-sfdc yes that is our current setup (same IP address for all the builds) - short term solution I can definitely use your workaround

long term it might be beneficial to allow a github token to be provided for any requests like these, maybe specify some environment variable + fallback. the other option would be to provide the package ID instead of package type as a parameter, but i guess that is exactly what sfdx force:package:install does.

Overall, maybe providing a way to show a stack trace or something for developers to point at when raising issues (even if it is just in the logs). I am guessing that is the intent but somehow this slipped through

[esalman-sfdc]

Update: We are trying to get the propagation of error messages fixed for install and run commands in version 42. With the change, you guys should see more meaningful error messages for the cases being reported on this thread along with additional info logged in the log file.

@chendagit for install, I think you may also me hitting the github limit discussed above, so for now try using the force:package:install workaround described above. For run, follow the recommendation here which is similar to what we are doing for this repo's travis setup as well.

[esalman-sfdc]

Update: Propagation of error messages has been fixed and additional logging (via --loglevel debug) has been added in version 42 of the sfdx plugin (currently available under 'pre-release' dist-tag (salesforce@pre-release). It will become the default as part of Spring'18 release).