Sporadic interactive test failures

[aryler]

The interactive tests will fail sometimes.
This seems to have started with 8.2.

$ cd /path/to/jim/tests
$ while true; do jimsh interactive.test; done

[aryler]

Looks like terminal control characters at the end.

$ cat -v interactive_test.log
interactive-1.1 ERR basic command
/usr/ports/pobj/jimtcl-0.83/jimtcl-0.83/tests/interactive.test:37:Error test failure
Expected: {lindex linsert list}
Got     : {invalid command name "istory"}

interactive-1.2 ERR command line completion
/usr/ports/pobj/jimtcl-0.83/jimtcl-0.83/tests/interactive.test:48:Error test failure
Expected: {3 0}
Got     : {0 1}

interactive-1.3 ERR history show
/usr/ports/pobj/jimtcl-0.83/jimtcl-0.83/tests/interactive.test:66:Error test failure
Expected: {   1 history load test_history^M
   2 lsort [info commands li*]^M
   3 list^M
   4 history show^M
}
Got     : {invalid command name "ifhistory"^M
^[[6n^M^[[0K[error] . ^M^[[10C}

[aryler]

$ hexdump -C interactive_test.log
00000000  69 6e 74 65 72 61 63 74  69 76 65 2d 31 2e 31 20  |interactive-1.1 |
00000010  45 52 52 20 62 61 73 69  63 20 63 6f 6d 6d 61 6e  |ERR basic comman|
00000020  64 0a 2f 75 73 72 2f 70  6f 72 74 73 2f 70 6f 62  |d./usr/ports/pob|
00000030  6a 2f 6a 69 6d 74 63 6c  2d 30 2e 38 33 2f 6a 69  |j/jimtcl-0.83/ji|
00000040  6d 74 63 6c 2d 30 2e 38  33 2f 74 65 73 74 73 2f  |mtcl-0.83/tests/|
00000050  69 6e 74 65 72 61 63 74  69 76 65 2e 74 65 73 74  |interactive.test|
00000060  3a 33 37 3a 45 72 72 6f  72 20 74 65 73 74 20 66  |:37:Error test f|
00000070  61 69 6c 75 72 65 0a 45  78 70 65 63 74 65 64 3a  |ailure.Expected:|
00000080  20 7b 6c 69 6e 64 65 78  20 6c 69 6e 73 65 72 74  | {lindex linsert|
00000090  20 6c 69 73 74 7d 0a 47  6f 74 20 20 20 20 20 3a  | list}.Got     :|
000000a0  20 7b 69 6e 76 61 6c 69  64 20 63 6f 6d 6d 61 6e  | {invalid comman|
000000b0  64 20 6e 61 6d 65 20 22  69 73 74 6f 72 79 22 7d  |d name "istory"}|
000000c0  0a 0a 69 6e 74 65 72 61  63 74 69 76 65 2d 31 2e  |..interactive-1.|
000000d0  32 20 45 52 52 20 63 6f  6d 6d 61 6e 64 20 6c 69  |2 ERR command li|
000000e0  6e 65 20 63 6f 6d 70 6c  65 74 69 6f 6e 0a 2f 75  |ne completion./u|
000000f0  73 72 2f 70 6f 72 74 73  2f 70 6f 62 6a 2f 6a 69  |sr/ports/pobj/ji|
00000100  6d 74 63 6c 2d 30 2e 38  33 2f 6a 69 6d 74 63 6c  |mtcl-0.83/jimtcl|
00000110  2d 30 2e 38 33 2f 74 65  73 74 73 2f 69 6e 74 65  |-0.83/tests/inte|
00000120  72 61 63 74 69 76 65 2e  74 65 73 74 3a 34 38 3a  |ractive.test:48:|
00000130  45 72 72 6f 72 20 74 65  73 74 20 66 61 69 6c 75  |Error test failu|
00000140  72 65 0a 45 78 70 65 63  74 65 64 3a 20 7b 33 20  |re.Expected: {3 |
00000150  30 7d 0a 47 6f 74 20 20  20 20 20 3a 20 7b 30 20  |0}.Got     : {0 |
00000160  31 7d 0a 0a 69 6e 74 65  72 61 63 74 69 76 65 2d  |1}..interactive-|
00000170  31 2e 33 20 45 52 52 20  68 69 73 74 6f 72 79 20  |1.3 ERR history |
00000180  73 68 6f 77 0a 2f 75 73  72 2f 70 6f 72 74 73 2f  |show./usr/ports/|
00000190  70 6f 62 6a 2f 6a 69 6d  74 63 6c 2d 30 2e 38 33  |pobj/jimtcl-0.83|
000001a0  2f 6a 69 6d 74 63 6c 2d  30 2e 38 33 2f 74 65 73  |/jimtcl-0.83/tes|
000001b0  74 73 2f 69 6e 74 65 72  61 63 74 69 76 65 2e 74  |ts/interactive.t|
000001c0  65 73 74 3a 36 36 3a 45  72 72 6f 72 20 74 65 73  |est:66:Error tes|
000001d0  74 20 66 61 69 6c 75 72  65 0a 45 78 70 65 63 74  |t failure.Expect|
000001e0  65 64 3a 20 7b 20 20 20  31 20 68 69 73 74 6f 72  |ed: {   1 histor|
000001f0  79 20 6c 6f 61 64 20 74  65 73 74 5f 68 69 73 74  |y load test_hist|
00000200  6f 72 79 0d 0a 20 20 20  32 20 6c 73 6f 72 74 20  |ory..   2 lsort |
00000210  5b 69 6e 66 6f 20 63 6f  6d 6d 61 6e 64 73 20 6c  |[info commands l|
00000220  69 2a 5d 0d 0a 20 20 20  33 20 6c 69 73 74 0d 0a  |i*]..   3 list..|
00000230  20 20 20 34 20 68 69 73  74 6f 72 79 20 73 68 6f  |   4 history sho|
00000240  77 0d 0a 7d 0a 47 6f 74  20 20 20 20 20 3a 20 7b  |w..}.Got     : {|
00000250  69 6e 76 61 6c 69 64 20  63 6f 6d 6d 61 6e 64 20  |invalid command |
00000260  6e 61 6d 65 20 22 69 66  68 69 73 74 6f 72 79 22  |name "ifhistory"|
00000270  0d 0a 1b 5b 36 6e 0d 1b  5b 30 4b 5b 65 72 72 6f  |...[6n..[0K[erro|
00000280  72 5d 20 2e 20 0d 1b 5b  31 30 43 7d 0a           |r] . ..[10C}.|

[msteveb]

What platform are you on? I can't reproduce this

[aryler]

I can reliably reproduce on OpenBSD-current, i386 (32 bit) and amd64 (64 bit).
Problem goes away if I configure with --disable-lineedit.

[msteveb]

OK,thanks. I don't have openbsd available right now but when I do I'll try to reproduce

[sgbeal]

While trying to reproduce this on an OpenBSD VM i notice that a fresh checkout of jimtcl fails to build because of that braindead linker output OpenBSD generates:

$ ./configure --prefix=$HOME
No installed jimsh or tclsh, building local bootstrap jimsh0
./configure[4]: ld: warning: jimsh0.c(/tmp/stephan/jimsh0-815d7e.o:(Jim_FormatString)): warning: sprintf() is often misused, please use snprintf()
ld: warning: jimsh0.c(/tmp/stephan/jimsh0-815d7e.o:(Jim_InteractivePrompt)): warning: strcpy() is almost always misused, please use strlcpy()
ld: warning: jimsh0.c(/tmp/stephan/jimsh0-815d7e.o:(JimPrngInit)): warning: rand() may return deterministic values, is that what you want?
/home/stephan/src/jimtcl/jimsh0: not found

Re-running configure a second time works - it's only the extra output which confuses it.

That was already resolved in upstream autosetup.

[sgbeal]

fwiw this is reproducible on an OpenBSD 7.6 vm:

[stephan@obvm:~/src/jimtcl/tests]$ while true; do ../jimsh interactive.test ; done
interactive.test: Total     7   Passed     7  Skipped     0  Failed     0
<approx. 21 identical lines snipped>

interactive-1.1 ERR basic command
interactive.test:37:Error test failure
Expected: {lindex linsert list}
Got     : {invalid command name "istory"}

interactive-1.2 ERR command line completion
interactive.test:48:Error test failure
Expected: {3 0}
Got     : {0 1}

interactive-1.3 ERR history show
interactive.test:66:Error test failure
Expected: {   1 history load test_history
   2 lsort [info commands li*]
   3 list
   4 history show
}
Got     : {invalid command name "ifhistory"
[error] . }

^[[40;1Rinteractive.test: Total     7   Passed     4  Skipped     0  Failed     3
------------------------------------------------------------
FAILED: 3
	interactive.test:37	interactive-1.1
	interactive.test:48	interactive-1.2
	interactive.test:66	interactive-1.3
------------------------------------------------------------
^C

[msteveb]

While trying to reproduce this on an OpenBSD VM i notice that a fresh checkout of jimtcl fails to build because of that braindead linker output OpenBSD generates:

$ ./configure --prefix=$HOME
No installed jimsh or tclsh, building local bootstrap jimsh0
./configure[4]: ld: warning: jimsh0.c(/tmp/stephan/jimsh0-815d7e.o:(Jim_FormatString)): warning: sprintf() is often misused, please use snprintf()
ld: warning: jimsh0.c(/tmp/stephan/jimsh0-815d7e.o:(Jim_InteractivePrompt)): warning: strcpy() is almost always misused, please use strlcpy()
ld: warning: jimsh0.c(/tmp/stephan/jimsh0-815d7e.o:(JimPrngInit)): warning: rand() may return deterministic values, is that what you want?
/home/stephan/src/jimtcl/jimsh0: not found

Re-running configure a second time works - it's only the extra output which confuses it.

That was already resolved in upstream autosetup.

What version? Is this master (3a2cfdf). Should be fixed there.

[sgbeal]

What version? Is this master (3a2cfdf). Should be fixed there.

It was a freshly-cloned copy of [3a2cfdf].

It repros consistently here with:

$ make distclean
...

$ ./configure
No installed jimsh or tclsh, building local bootstrap jimsh0
./configure[4]: ld: warning: jimsh0.c(/tmp/stephan/jimsh0-d0efe1.o:(Jim_FormatString)): warning: sprintf() is often misused, please use snprintf()
ld: warning: jimsh0.c(/tmp/stephan/jimsh0-d0efe1.o:(Jim_InteractivePrompt)): warning: strcpy() is almost always misused, please use strlcpy()
ld: warning: jimsh0.c(/tmp/stephan/jimsh0-d0efe1.o:(JimPrngInit)): warning: rand() may return deterministic values, is that what you want?
/home/stephan/src/jimtcl/jimsh0: not found

$ ./configure
... works as expected

$ uname -a
OpenBSD obvm.fritz.box 7.6 GENERIC.MP#338 amd64

[msteveb]

Thanks. I'll hopefully be able to fire up an openbsd vm soon and reproduce this.

[msteveb]

OK, two separate issues here. The configure problem is because we don't have the redirection order correct in autosetup-find-tclsh

The occasional test failures are do do with how linenoise waits for the window size response to be returned. It has some fixed timeouts that don't seem to work well on OpenBSD (at least in a VM). I'll have to investigate further to see how to make this more reliable.

[msteveb]

Because the child process is being controlled via pty pair, the window size is not available. Sometimes the first char is eaten by the code waiting for the window size response and then everything goes downhill from there.

[msteveb]

I've pushed some changes to branch openbsd-fix
Let me know if that resolves the issue for you

[aryler]

Thanks, that's quite a bit of work!
The original problem may be fixed but now this:

$ cat -vt jimtesterr
interactive-1.1 ERR basic command
interactive.test:37:Error test failure
Expected: {lindex linsert list}
Got     : {^[[6n^M^[[0K. ^M^[[2C^M^[[0K. l^M^[[3C^M^[[0K. ls^M^[[4C^M^[[0K. lso^M^[[5C^M^[[0K. lsor^M^[[6C^M^[[0K. lsort^M^[[7C^M^[[0K. lsort ^M^[[8C^M^[[0K. lsort [^M^[[9C^M^[[0K. lsort [i^M^[[10C^M^[[0K. lsort [in^M^[[11C^M^[[0K. lsort [inf^M^[[12C^M^[[0K. lsort [info^M^[[13C^M^[[0K. lsort [info ^M^[[14C^M^[[0K. lsort [info c^M^[[15C^M^[[0K. lsort [info co^M^[[16C^M^[[0K. lsort [info com^M^[[17C^M^[[0K. lsort [info comm^M^[[18C^M^[[0K. lsort [info comma^M^[[19C^M^[[0K. lsort [info comman^M^[[20C^M^[[0K. lsort [info command^M^[[21C^M^[[0K. lsort [info commands^M^[[22C^M^[[0K. lsort [info commands ^M^[[23C^M^[[0K. lsort [info commands l^M^[[24C^M^[[0K. lsort [info commands li^M^[[25C^M^[[0K. lsort [info commands li*^M^[[26C^M^[[0K. lsort [info commands li*]^M^[[27C^M^[[0K. lsort [info commands li*]^M^[[27C}

interactive.test: Total     7   Passed     6  Skipped     0  Failed     1
------------------------------------------------------------
FAILED: 1
^Iinteractive.test:37^Iinteractive-1.1
------------------------------------------------------------

$ hexdump -C jimtesterr
00000000  69 6e 74 65 72 61 63 74  69 76 65 2d 31 2e 31 20  |interactive-1.1 |
00000010  45 52 52 20 62 61 73 69  63 20 63 6f 6d 6d 61 6e  |ERR basic comman|
00000020  64 0a 69 6e 74 65 72 61  63 74 69 76 65 2e 74 65  |d.interactive.te|
00000030  73 74 3a 33 37 3a 45 72  72 6f 72 20 74 65 73 74  |st:37:Error test|
00000040  20 66 61 69 6c 75 72 65  0a 45 78 70 65 63 74 65  | failure.Expecte|
00000050  64 3a 20 7b 6c 69 6e 64  65 78 20 6c 69 6e 73 65  |d: {lindex linse|
00000060  72 74 20 6c 69 73 74 7d  0a 47 6f 74 20 20 20 20  |rt list}.Got    |
00000070  20 3a 20 7b 1b 5b 36 6e  0d 1b 5b 30 4b 2e 20 0d  | : {.[6n..[0K. .|
00000080  1b 5b 32 43 0d 1b 5b 30  4b 2e 20 6c 0d 1b 5b 33  |.[2C..[0K. l..[3|
00000090  43 0d 1b 5b 30 4b 2e 20  6c 73 0d 1b 5b 34 43 0d  |C..[0K. ls..[4C.|
000000a0  1b 5b 30 4b 2e 20 6c 73  6f 0d 1b 5b 35 43 0d 1b  |.[0K. lso..[5C..|
000000b0  5b 30 4b 2e 20 6c 73 6f  72 0d 1b 5b 36 43 0d 1b  |[0K. lsor..[6C..|
000000c0  5b 30 4b 2e 20 6c 73 6f  72 74 0d 1b 5b 37 43 0d  |[0K. lsort..[7C.|
000000d0  1b 5b 30 4b 2e 20 6c 73  6f 72 74 20 0d 1b 5b 38  |.[0K. lsort ..[8|
000000e0  43 0d 1b 5b 30 4b 2e 20  6c 73 6f 72 74 20 5b 0d  |C..[0K. lsort [.|
000000f0  1b 5b 39 43 0d 1b 5b 30  4b 2e 20 6c 73 6f 72 74  |.[9C..[0K. lsort|
00000100  20 5b 69 0d 1b 5b 31 30  43 0d 1b 5b 30 4b 2e 20  | [i..[10C..[0K. |
00000110  6c 73 6f 72 74 20 5b 69  6e 0d 1b 5b 31 31 43 0d  |lsort [in..[11C.|
00000120  1b 5b 30 4b 2e 20 6c 73  6f 72 74 20 5b 69 6e 66  |.[0K. lsort [inf|
00000130  0d 1b 5b 31 32 43 0d 1b  5b 30 4b 2e 20 6c 73 6f  |..[12C..[0K. lso|
00000140  72 74 20 5b 69 6e 66 6f  0d 1b 5b 31 33 43 0d 1b  |rt [info..[13C..|
00000150  5b 30 4b 2e 20 6c 73 6f  72 74 20 5b 69 6e 66 6f  |[0K. lsort [info|
00000160  20 0d 1b 5b 31 34 43 0d  1b 5b 30 4b 2e 20 6c 73  | ..[14C..[0K. ls|
00000170  6f 72 74 20 5b 69 6e 66  6f 20 63 0d 1b 5b 31 35  |ort [info c..[15|
00000180  43 0d 1b 5b 30 4b 2e 20  6c 73 6f 72 74 20 5b 69  |C..[0K. lsort [i|
00000190  6e 66 6f 20 63 6f 0d 1b  5b 31 36 43 0d 1b 5b 30  |nfo co..[16C..[0|
000001a0  4b 2e 20 6c 73 6f 72 74  20 5b 69 6e 66 6f 20 63  |K. lsort [info c|
000001b0  6f 6d 0d 1b 5b 31 37 43  0d 1b 5b 30 4b 2e 20 6c  |om..[17C..[0K. l|
000001c0  73 6f 72 74 20 5b 69 6e  66 6f 20 63 6f 6d 6d 0d  |sort [info comm.|
000001d0  1b 5b 31 38 43 0d 1b 5b  30 4b 2e 20 6c 73 6f 72  |.[18C..[0K. lsor|
000001e0  74 20 5b 69 6e 66 6f 20  63 6f 6d 6d 61 0d 1b 5b  |t [info comma..[|
000001f0  31 39 43 0d 1b 5b 30 4b  2e 20 6c 73 6f 72 74 20  |19C..[0K. lsort |
00000200  5b 69 6e 66 6f 20 63 6f  6d 6d 61 6e 0d 1b 5b 32  |[info comman..[2|
00000210  30 43 0d 1b 5b 30 4b 2e  20 6c 73 6f 72 74 20 5b  |0C..[0K. lsort [|
00000220  69 6e 66 6f 20 63 6f 6d  6d 61 6e 64 0d 1b 5b 32  |info command..[2|
00000230  31 43 0d 1b 5b 30 4b 2e  20 6c 73 6f 72 74 20 5b  |1C..[0K. lsort [|
00000240  69 6e 66 6f 20 63 6f 6d  6d 61 6e 64 73 0d 1b 5b  |info commands..[|
00000250  32 32 43 0d 1b 5b 30 4b  2e 20 6c 73 6f 72 74 20  |22C..[0K. lsort |
00000260  5b 69 6e 66 6f 20 63 6f  6d 6d 61 6e 64 73 20 0d  |[info commands .|
00000270  1b 5b 32 33 43 0d 1b 5b  30 4b 2e 20 6c 73 6f 72  |.[23C..[0K. lsor|
00000280  74 20 5b 69 6e 66 6f 20  63 6f 6d 6d 61 6e 64 73  |t [info commands|
00000290  20 6c 0d 1b 5b 32 34 43  0d 1b 5b 30 4b 2e 20 6c  | l..[24C..[0K. l|
000002a0  73 6f 72 74 20 5b 69 6e  66 6f 20 63 6f 6d 6d 61  |sort [info comma|
000002b0  6e 64 73 20 6c 69 0d 1b  5b 32 35 43 0d 1b 5b 30  |nds li..[25C..[0|
000002c0  4b 2e 20 6c 73 6f 72 74  20 5b 69 6e 66 6f 20 63  |K. lsort [info c|
000002d0  6f 6d 6d 61 6e 64 73 20  6c 69 2a 0d 1b 5b 32 36  |ommands li*..[26|
000002e0  43 0d 1b 5b 30 4b 2e 20  6c 73 6f 72 74 20 5b 69  |C..[0K. lsort [i|
000002f0  6e 66 6f 20 63 6f 6d 6d  61 6e 64 73 20 6c 69 2a  |nfo commands li*|
00000300  5d 0d 1b 5b 32 37 43 0d  1b 5b 30 4b 2e 20 6c 73  |]..[27C..[0K. ls|
00000310  6f 72 74 20 5b 69 6e 66  6f 20 63 6f 6d 6d 61 6e  |ort [info comman|
00000320  64 73 20 6c 69 2a 5d 0d  1b 5b 32 37 43 7d 0a 0a  |ds li*]..[27C}..|
00000330  69 6e 74 65 72 61 63 74  69 76 65 2e 74 65 73 74  |interactive.test|
00000340  3a 20 54 6f 74 61 6c 20  20 20 20 20 37 20 20 20  |: Total     7   |
00000350  50 61 73 73 65 64 20 20  20 20 20 36 20 20 53 6b  |Passed     6  Sk|
00000360  69 70 70 65 64 20 20 20  20 20 30 20 20 46 61 69  |ipped     0  Fai|
00000370  6c 65 64 20 20 20 20 20  31 0a 2d 2d 2d 2d 2d 2d  |led     1.------|
00000380  2d 2d 2d 2d 2d 2d 2d 2d  2d 2d 2d 2d 2d 2d 2d 2d  |----------------|
*
000003b0  2d 2d 2d 2d 2d 2d 0a 46  41 49 4c 45 44 3a 20 31  |------.FAILED: 1|
000003c0  0a 09 69 6e 74 65 72 61  63 74 69 76 65 2e 74 65  |..interactive.te|
000003d0  73 74 3a 33 37 09 69 6e  74 65 72 61 63 74 69 76  |st:37.interactiv|
000003e0  65 2d 31 2e 31 0a 2d 2d  2d 2d 2d 2d 2d 2d 2d 2d  |e-1.1.----------|
000003f0  2d 2d 2d 2d 2d 2d 2d 2d  2d 2d 2d 2d 2d 2d 2d 2d  |----------------|
*
00000420  2d 2d 0a                                          |--.|
00000423

[aryler]

linenoise.c line 930

/* If it every fails, don't try again */

[msteveb]

OK, I've made a couple of more fixes. Please let me know how it goes.

[aryler]

Here's what I've got so far:

32bit machine: over 16000 test iterations without fail.
64bit machine 2: over 16000 test iterations without fail.
64bit machine 1: failures observed at ~12000 and ~6000 iterations.

I don't think those numbers are significant, just random.
Also, I'm a tad suspicious of the machine with failures.

I'll do some more testing and report back.