TISTUD-9107 : Introducing timeout for getEnvironment() call

[ppedduri]

On MacOS machines, when a native call to get 'env' are issued, it waits forever. We needed a timeout here, as this may cause studio to be hung.

Introducing a 10 second timeout in this particular case.

[ppedduri]

@kolipakakondal , incorporated review suggestion. Please review again.

[ppedduri]

@ssekhri , please consider the following comments for the issues found during FR:

1. i) The verifying status keeps showing for 30 secs irrespective of 10sec timeout introduced. -> Fixed, this had an issue with my overwritten commit. Apologies.

1. ii) After that it infact launches studio with anonymous user. This doesnt happen with studio 5.1.0 which shows login screen. -> Fixed, same as above. You should now see login screen.

1.iii) logs show the output of the custom env command as error which are extra logs not required to be logged as error. -> Unreproducible, post this fix. However, login won't function in splash screen (when the env command doesn't return expected output). You would always get an error even with valid credentials. The reason being, Studio won't get an executable shell to run any 'appc' command. So, any issue pertaining to login failure (in case of a non-functioning env file) is expected.

2. Remove the /usr/bin/env file. The result is opposite of the first scenario. With this PR code the login screen is shown whereas studio 5.1.0 launches studio as anonymous user. -> This should now work similar to 5.1 or 5.0 with the latest fix. Please revalidate.

[ssekhri]

@ppedduri still see the same issue of getting logged into studio as anonymous when the env file exists but doesnt return anything valid in timely manner (with a custom env file that just waits for 30s and then prints something)

[ppedduri]

@ssekhri , Can we try the below approach to see if timers are working. I have tried the approach you explained me and felt that chances of users falling into a missing env file are close to zero, as that involves in switching to recovery mode.

In order to see the timer value working, please modify com.aptana.core/src/com/aptana/core/ShellExecutable.java as described below. Within the if block at line #278 change the env command value to any custom script that you would like to run. And add print statements to see executed time.

Code to be changed:

if (shellPath != null)
            {
                // OK, we do have a shell.
                String envCommand = "~/junkEnv_tOut_correct.sh"; //$NON-NLS-1$ 
                if (!PlatformUtil.isWindows())
                {
                    try
                    {
                        long beginTime = System.currentTimeMillis();
                        IStatus status = ProcessUtil.processResultWithTimeout(run(envCommand, workingDirectory, null), 10000);
                        long endTime = System.currentTimeMillis();
                        System.out.println("Time taken to run 'env' command (in seconds): "+ (endTime-beginTime)/1000);

                        if (status.isOK())
                        {
                            result = buildEnvironment(status.getMessage());
                        }
                        else
                        {
                            IdeLog.logError(CorePlugin.getDefault(),
                                    "Get shell environment failed: " + status.getMessage()); //$NON-NLS-1$
                        }
                    }
                    catch (Exception e)
                    {
                        IdeLog.logError(CorePlugin.getDefault(), "Get shell environment failed.", e); //$NON-NLS-1$
                        // failed to generate an env, we'll use JVM env and not
                        // cache, see below...
                    }
                }
            }

Diff should look like the following (left one is the modified code):

I modified the file you shared with me, to two different files, one with workable output and executes within 10 seconds and another with 30 seconds wait and no output.

File that runs within 10 seconds and returns env output -

Prashanths-Mac-Book:studio3 ppedduri$ cat ~/junkEnv_tOut_correct.sh 
date
echo "started"
sleep 8s
env
echo "end"
date

File that waits for 30 seconds and doesn't return any valid output -

Prashanths-Mac-Book:studio3 ppedduri$ cat ~/junkEnv_tOut_incorrect.sh 
date
echo "started"
sleep 30s
echo "end"
date

In order to test non-existence of env file, replace the value within the line String envCommand = "~/junkEnv_tOut_correct.sh"; //$NON-NLS-1$ to any file that doesn't exist and it would result in Studio prompting for credentials, as shown below:

and upon giving correct credentials, it still fails (this is expected, due to missing env file and it doesn't have a bash to run appc commands), as shown below:

Please try this approach with correct file in /usr/bin/env and let me know if you have any questions.

[ssekhri]

@ppedduri I would check it with the way you have detailed. However there is no issue when env file is missing. The issue was when env file is present but it had modified contents so as to sleep for 30S. I would also try to not replace the original env file altogether but just a sleep in the original one.

[ssekhri]

@ppedduri I tried the approach you mentioned in your comments. Used the "junkEnv_tOut_incorrect.sh" file exactly as in your comment. Got the same issue as I was getting earlier. The studio logged in as anonymous.

[ppedduri]

@ssekhri , thats strange!

Even if you modify envCommand as below, it lets you login to the studio as anonymous is it? String envCommand = "~/junkEnv_tOut_incorrect.sh"; //$NON-NLS-1$

May I know whats the value the following line prints on console? System.out.println("Time taken to run 'env' command (in seconds): "+ (endTime-beginTime)/1000);

[ssekhri]

it prints twice. Here is part of the console output: ` Time taken to run 'env' command (in seconds): 10

!ENTRY com.aptana.core 4 0 2018-09-21 13:00:36.836 !MESSAGE (Build 5.2.0.qualifier) [ERROR] Get shell environment failed: Fri Sep 21 13:00:26 IST 2018 started (Build 5.2.0.qualifier) [ERROR] Get shell environment failed: Fri Sep 21 13:00:26 IST 2018 started Time taken to run 'env' command (in seconds): 10

!ENTRY com.aptana.core 4 0 2018-09-21 13:00:47.130 !MESSAGE (Build 5.2.0.qualifier) [ERROR] Get shell environment failed: Fri Sep 21 13:00:37 IST 2018 started (Build 5.2.0.qualifier) [ERROR] Get shell environment failed: Fri Sep 21 13:00:37 IST 2018 started

!ENTRY com.appcelerator.titanium.rcp 4 0 2018-09-21 13:00:47.799 !MESSAGE (Build 5.2.0.qualifier) [ERROR] env: node: No such file or directory (Build 5.2.0.qualifier) [ERROR] env: node: No such file or directory

!ENTRY com.appcelerator.titanium.core 4 0 2018-09-21 13:00:47.933 !MESSAGE (Build 5.2.0.qualifier) [ERROR] Unrecognized token 'env': was expecting ('true', 'false' or 'null') at [Source: env: node: No such file or directory; line: 1, column: 4] `

[ppedduri]

Okay, Time taken to run 'env' command (in seconds): 10 clearly means timer is working fine. It must be some other issue thats letting user login anonymously. Unfortunately, I, with same set of lines couldn't reproduce this issue.

The change in this PR targets to release lock if the command is taking more than 10 seconds, and thats being met.

[ppedduri]

Let me elaborate the use cases -

1. Correct 'env' file which runs within 10 seconds Expectation: Studio should work without any issue.

2. Correct 'env' file which runs more than 10 seconds Expectation: Studio logs in with previous user found from preferences (as appc-cli won't work without env), and errors are seen as soon as studio launches.

3. Incorrect 'env' output which returns within 10 seconds Expectation: Studio logs in but errors are seen.

4. Incorrect 'env' which takes more than 10 seconds Expectation: Same as point 2.

In my view, the objective of this PR is to let the user not get blocked (since the bug talks about user being blocked) from launching the studio and not to make it work without an env file's output (be it time taking env or incorrect env file).

[ssekhri]

1. Works as explained
2. Cannot determine the behaviour as this scenario is hard to reproduce
3. It shows the login screen
4. This is where I am getting the issue that studio logs in as Anonymous.

I agree the original issue regarding studio getting hung is solved but the result of point 4 is a major issue.

[ppedduri]

My bad, Pt.3 's output is login screen as you mentioned.

Pt. 2 & 4 are kind of same as its the timer which runs out and releases lock such that Studio launches. Anonymous user login could be due to un-found user within preferences and I would say its the rare scenario as unavailability of 'env' doesn't guarantee studio to function properly.

To reproduce Pt.2, please add 'env' after timeout (of 30 sec) within junkEnv_tOut_correct.sh file.

There are two angles to this scenario, one being launch time 'env' output fetch and another being anytime after launch of Studio (updater/dashboard/any background process). Launch time hang is resolved with the timer and all other scenarios post launch should result in errors (again due to timeout) as fetching env is the pivotal thing for any CLI command to be run.

[ppedduri]

Summarising what has been discussed so far -

1. The PR's purpose of 10 seconds timeout is achieved.
2. With this change, Studio doesn't hang on fetching env and hence no frozen splash screen.

The open questions/observations are pertaining to missing /usr/bin/env file and malfunctioning /usr/bin/env file (by malfunctioned, I meant the file doesn't yield required output). These two cases hold true with earlier versions of Studio as well and can be dealt in a separate thread.

@kolipakakondal & @ssekhri - Please let me know your thoughts on this and help in concluding/merging this PR.

[ssekhri]

Just checked the use case 2 "Correct 'env' file which runs more than 10 seconds". Did this by modifying the ShellExecutable.java file as mentioned in one of the above comments. The modification was to use a custom shell file that first sleeps for 30S and then calls env command.

Result: Logs into studio as anonymous.

SO effectively whenever the call to env command takes longer, whether the env file is malfunctioned or not it logs in as anonymous. The studio does not hang now on splash screen but logs in as anonymous.

The difference between this PR behaviour and older version of studio is that the older versions used to show login screen when env was malfunctioned. The older version would log in as anonymous when env file was not present. Whereas this PR code would show login screen when env file is not present.

[kolipakakondal]

If I understand from above, the only issue here is logging as "anonymous" user and this happens only for @ssekhri

Looking at the code, this can only happen when studio is unable to fetch the user name from the eclipse secure storage which was stored in the earlier session of the studio. https://github.com/appcelerator/titanium_studio/blob/ed32875ff313fdcbf2de7b14b72619562ca79e96/bundles/com.appcelerator.titanium.core/src/com/appcelerator/titanium/core/user/TitaniumUserManager.java#L761

so, it's clear that - there is a problem in accessing the secure storage from your studio.

To dig deeper into this problem, you can verify the secure storage for your studio. Here you go, Studio Preferences -> General -> Security -> Secure Storage

In the contents section, you can check the "Storage location" and navigate to the file system. /Users/kkolipaka/.eclipse/org.eclipse.equinox.security/secure_storage

You can look if you see any entries for 'Appcelerator.studio.core.ACCOUNT_USERNAME" in the above file?

You can try resetting secure_storage from the preferences. https://stackoverflow.com/questions/4223059/eclipse-secure-storage

Still the problem persists after doing above all - I think it's better to log a new ticket with medium priority and track it.

[ssekhri]

@kolipakakondal @ppedduri So clearing the existing secure storage does help. However have to login once successfully before env file has issue else it would log in as Anonymous. So would create a separate issue for it as it is not so severe. There is a related question. With this PR we don't let the flow freeze on the splash screen but even if we let it login into studio with last logged in user but the user cannot perform actions like create, build, updates etc. What are your take on such behaviour?. The user isn't even aware that its an issue with env command but it simply feels tons of issue with studio.

[ppedduri]

@ssekhri @kolipakakondal ,

In my opinion, the behaviour pertaining to missing/malfunctioned usr/bin/env is discoverable through the error reporting or Studio log. And the chances of users falling under that category of missing/malfunctioning /usr/bin/env are slim (given the tedious process to remove env file).

Using prior versions of Studio(and the current PR), a missing/malfunctioning env file (post launch of studio), fails to perform any operation that requires session/environment.

If there are no other open questions, and if you all agree - can we merge this PR and have other issues discussed in a separate ticket?

Edit: Added a screenshot depicting the error report that is shown to the user.