Rare inconsistent result.

[memoryruins]

While testing gluon with rexpect, there has been one inconsistent test, specicially the hello_world test. It may be a problem of how I used the api or a rare bug with the repl. Rexpect has worked consistently with every other test that's been thrown at it.

There are a few different variations tried in here, including the original without expecting anything after the first sent import line, expecting a regex, and using execute -- https://github.com/gluon-lang/gluon/pull/478.

It would be great to get your eyes on this if you spot anything I'm missing while using rexpect :)

[philippkeller]

Hey @memoryruins!

I had a look at your issue thread and going the direction of send the line and then wait for an output string is certainly the right direction. You spotted the execute method which is in spawn_bash part of the session. IMO this could be moved over to spawn so you could use it.

But anyway, you added exp_ after the send_line which is what execute does anyway. So in theory you should not see issues. In practice I needed to fix a lot of this race conditions in the past (which was the hardest part of this project so far), and I thought I caught them all, but apparently not.

What would be helpful is if I could reproduce this. So it'd be great if you could answer me:

• is it mainly happening on windows?
• can you share me that loop you did with the progress bar?

Also it'd be good if I could just try a session manually, but somehow cargo build did not produce target/debug/gluon (which seems to be executed in the text), only target/debug/gluon-8e2882e72dd62560 which doesn't take -i as a parameter

[Marwes]

@philippkeller You need to do cargo build -p gluon_repl for the gluon executable.

is it mainly happening on windows?

Seems to happens more commonly on 32-bit (as found when running tests on travis/linux). (expect can't be used on Windows unless it is ran in the linux subsystem)

[memoryruins]

For travis ci, it pops up on 32-bit most commonly, and I'm testing the variations of the below loop locally on a x86_64 linux laptop and desktop. Left the statics in to match the cargo tests.

Cargo.toml

[dependencies]
rexpect = "0.3.0"
pbr = "1.0.0"

main.rs

extern crate rexpect;
extern crate pbr;

use rexpect::spawn;
use rexpect::errors::*;

use pbr::ProgressBar;

static COMMAND: &str = "gluon -i"; // set your gluon path
static TIMEOUT: u64 = 10_000;
static PROMPT: &str = "> ";

fn main() {
    let count = 10_000;
    let mut pb = ProgressBar::new(count);
    pb.format("╢▌▌░╟");

    for _i in 1..count {
        pb.inc();
        || -> Result<()> { 
            let mut repl = spawn(COMMAND, Some(TIMEOUT))?;
            repl.exp_string(PROMPT)?;

            repl.send_line("let io = import! std.io")?;
            repl.exp_regex("\\{[^}]+\\}")?;

            repl.send_line("\"UNIQUE\"")?;
            repl.exp_string("GcStr(\"UNIQUE\")")?;

            repl.send_line("io.println \"Hello world\"")?;
            repl.exp_string("Hello world")?;  

            Ok(())
        }().unwrap_or_else(|err| panic!("{}", err));
    }

    pb.finish_print("success");
}

[memoryruins]

Ran 20k loops of hello_world of gluon and the loop on both release and debug without an issue on x86_64 today. Checked the recent jobs, and with a twist, the jobs' recent issue was not with hello_world and it was on x86_64. It failed on the expression_types test, with a similar timeout error while waiting for the expected string.

---- expression_types stdout ----
    thread 'expression_types' panicked at 'Timeout Error: Expected "Int -> Int" but got "

[philippkeller]

thanks for your code. I'm currently testing on my local linux machine (64bit) and also on a EC2 32bit machine..

[philippkeller]

I think the problem lies somewhere in the first regex repl.exp_regex("\\{[^}]+\\}")?; matches up and until the first closing }. When I issue let io = import! std.io in the gluon shell, then I get about ten times }. I guess the sending of "UNIQUE" is just too early.

I couldn't find a good exp_string though, because gluon seems to send quite a bit of escape characters. When doing this just after exp_regex:

            while let Some(a) = repl.try_read() {
                println!("{:?}", a);
            }

Then I'll get:

...
's'
'c'
'r'
'i'
'p'
't'
'>'
','
'\r'
'\n'
'}'
'\r'
'\n'
'\r'
'\u{1b}'
'['
'0'
'K'
'\u{1b}'
'['
'1'
'A'
'\r'
'\u{1b}'
'['
'0'
'K'
'\u{1b}'
'['
'1'
'A'
'\r'
'\u{1b}'
'['
'0'
'K'
'>'
' '
'\r'
'\u{1b}'
'['
'1'
'C'

[memoryruins]

and thank you for helping us test this. There are a few layers where something could go wrong. I should've most likely used the "load_script" string at the end gluon's import instead of the regex, as I see the above is what Marwes was hinting about the match.

The expression_types test above seems to include a mistake on my part, as ":t 5 + 5" should return "Int" instead of "Int -> Int". It's strange that the expression_types test had passed on the other platforms / tests up until now though, and that the but got " gets cutoff in the error message.

[philippkeller]

Ok, I think I have something which works:

static COMMAND: &str = "/usr/local/bin/gluon -i"; // set your gluon path
static TIMEOUT: u64 = 2_000;
static PROMPT: &str = "\u{1b}[0K> ";

fn main() {
    let count = 10_000;
    let mut pb = ProgressBar::new(count);
    pb.format("╢▌▌░╟");

    for _i in 1..count {
        pb.inc();
        || -> Result<()> { 
            let mut repl = spawn(COMMAND, Some(TIMEOUT))?;
            repl.exp_string(PROMPT)?;

            repl.send_line("let io = import! std.io")?;
            // input is prompted in REPL, read back first..
            repl.exp_string("let io = import! std.io")?;
            repl.exp_string(PROMPT)?;

            repl.send_line("\"UNIQUE\"")?;
            // input is prompted in REPL, read back first..
            repl.exp_string("\"UNIQUE\"")?;
            repl.exp_string("\"UNIQUE\"")?;
            repl.exp_string(PROMPT)?;

            repl.send_line("io.println \"Hello world\"")?;
            // input is prompted in REPL, read back first..
            repl.exp_string("io.println \"Hello world\"")?;
            repl.exp_string("Hello world")?;

            Ok(())
        }().unwrap_or_else(|err| panic!("{}", err));
    }

Explanation: In your regex you match the first closing }. First not all output was consumed from gluon and second I experienced that the prompt is sometimes coming a bit later than the last }. So I inspected the exact byte sequence which is sent and adapted the prompt variable to this.

I also enhanced the output of the timeout error so that carriage returns and newlines are printed as \r and \n and escapes are escaped instead of just printed (invisibly) to the terminal.

IMO that should solve your issues. If not, keep posting here!

btw: I did not publish to crates.io yet, as maybe there are still some other things wrong which need fixing.

[memoryruins]

Wow, the additional prompt exp_string lines make sense. Expected needing after when the repl launched, but it makes sense to follow the other lines as well and it's thorough. I'll add to the other tests as well. You've been a huge help!

[philippkeller]

yeah, I just added the "reading back prompt" 1 minute ago because I ran in another corner case..

these things are really not obvious at start, but when you start thinking about it it makes sense. I needed some time to get into the right thinking habit myself now. If you have any idea how to improve the error messages or the "flow" then I'm very open for suggestions

[Marwes]

So the solution is to wait for the PROMPT before continuing with the next command? That makes sense, thanks! I guess there isn't a way for rexpect to provide a "wait on prompt" method since the prompt is 100% implementation specific?

[memoryruins]

I'll wrap rexpect with an interface thats a bit more repl/gluon specific so we can toss the repeated statements in there (and ensure we don't forget them). https://github.com/gluon-lang/gluon/pull/486

[philippkeller]

the new code looks good! I took some ideas into account and now added a PtyReplSession into rexpect which is now used e.g. by spawn_bash. If you want you could use it from your code as well. send_line now also waits for the echo if echo_on is set to True.

The code above would now look like this:

static COMMAND: &str = "/usr/local/bin/gluon -i";
static TIMEOUT: u64 = 2_000;
static PROMPT: &str = "\u{1b}[0K> ";

fn new() -> Result<(PtyReplSession)> {
    let mut repl = PtyReplSession{
        pty_session: spawn(COMMAND, Some(TIMEOUT))?,
        prompt: PROMPT.to_string(),
        echo_on: true,
        quit_command: Some(":q".to_string())
    };
    repl.wait_for_prompt()?;
    Ok(repl)
}

fn main() {
    let count = 10_000;
    let mut pb = ProgressBar::new(count);
    pb.format("╢▌▌░╟");

    for _i in 1..count {
        pb.inc();
        || -> Result<()> { 
            let mut repl = new()?;

            repl.send_line("let io = import! std.io")?;
            repl.exp_string(PROMPT)?;

            repl.send_line("\"UNIQUE\"")?;
            repl.exp_string("\"UNIQUE\"")?;
            repl.wait_for_prompt()?;

            repl.send_line("io.println \"Hello world\"")?;
            repl.exp_string("Hello world")?;

            Ok(())
        }().unwrap_or_else(|err| panic!("{}", err));
    }

    pb.finish_print("success");
}

Note that the quit_command is sent at drop time of PtyReplSession, just before rexpect sends the SIGTERM.

[philippkeller]

setting this to closed right now. Still happy for comments though!