Bug 656246 – app-shells/fish-2.7.1 Testing file printf.in ... fail

• Product: Gentoo Linux
• Status: RESOLVED FIXED

[Description ernsteiswuerfel 2018-05-21 20:50:21 UTC]

Created attachment 532588 [details]
emerge --info

Testing file printf.in ... fail
Output differs for file printf.in. Diff follows:
--- printf.tmp.out	2018-05-21 22:38:25.450315216 +0200
+++ printf.out	2017-12-22 17:16:29.000000000 +0100
@@ -1,5 +1,5 @@
 Hello 1 2 3.000000 4.000000 5 6
-a B 0 18446744073709551615
+a B 10 18446744073709551615

[Comment 1 ernsteiswuerfel 2018-05-21 20:52:12 UTC]

Created attachment 532590 [details]
build.log

[Comment 2 Georgy Yakovlev 2018-05-21 21:21:04 UTC]

Created attachment 532592 [details, diff]
fish-2.7.1-ppc-656246.patch

This is known and already reported upstream

https://github.com/fish-shell/fish-shell/pull/4444

I haven't backported it to 2.7.1 in ::gentoo, but it should be trivial.

Can you please test it with the attached patch?

[Comment 3 ernsteiswuerfel 2018-05-21 22:02:47 UTC]

The patch applies but "Testing high level script functionality" is broken now.

[...]
Testing file invocation/version.invoke ... ok
Encountered 0 errors in the invocation tests (out of 17).
rm -rf test
/bin/mkdir -p test/data test/home test/temp
/bin/mkdir -p test/root
cd tests; ../test/root/bin/fish test.fish
/bin/sh: ../test/root/bin/fish: No such file or directory
make: *** [Makefile:385: test_fishscript] Error 127

[Comment 4 Georgy Yakovlev 2018-05-21 23:14:19 UTC]

Can't reproduce on my amd64 machine

Maybe you can try building with -j1?
Sometimes those tests fail with high -j value, like -j32 or so.


On the other hand it may be related to that we install fish to /bin/fish, and not /usr/bin/fish.

That change is also planned for 3.0, it'll also require  baselayout change or user intervention, because gentoo's default /etc/shells specifies path to fish as /bin/fish

Relevant bug report, it's cmake related (fish-3.0 is built using cmake)
https://github.com/fish-shell/fish-shell/issues/4883

but looks quite similar.
I need full test and build logs to figure this out, preferably all files from ${WORKDIR}

[Comment 5 ernsteiswuerfel 2018-05-21 23:35:37 UTC]

I did the build with -j3 on my PowerMac G5.

I could mail you the compressed workdir, it's too big to upload it here (~ 4,6 MiB).

[Comment 6 Georgy Yakovlev 2018-05-22 00:47:15 UTC]

sure, that'll work. I'll check the data.
use email provided here, it's the same as in metadata.xml for fish.

[Comment 7 ernsteiswuerfel 2018-05-22 19:09:51 UTC]

Mail sent.

[Comment 8 Georgy Yakovlev 2018-05-23 03:39:53 UTC]

Got it.

Ok I think I know what's the deal.

Can you please install fish with the provided patch, but without tests.

And emerge fish once again, with tests enabled. It'll probably pass with flying colors.

As far as I remember those tests required fish installed on the host to run.

[Comment 9 ernsteiswuerfel 2018-05-23 18:08:42 UTC]

Well, this certainly improved the situation! high level script functionality passes all tests, now I am getting a different test failure. ;)

[...]
cd tests; ../test/root/bin/fish interactive.fish
Testing interactive functionality
Testing file bind.expect ... ok
Testing file commandline.expect ... ok
Testing file exit.expect ... ok
Testing file fkr.expect ... ok
Testing file generic.expect ... ok
Testing file histfile.expect ... fail
Output differs for file histfile.expect. Diff follows:
--- histfile.expect.tmp.out	2018-05-23 20:04:37.603851282 +0200
+++ histfile.expect.out	2017-12-22 17:16:29.000000000 +0100
@@ -3,3 +3,5 @@
 cmd2 not found in default histfile
 cmd3 found in default histfile
 cmd3 not found in my histfile
+cmd4 found in env histfile
+cmd4 not found in default histfile
Error output differs for file histfile.expect. Diff follows:
--- histfile.expect.tmp.err	2018-05-23 20:04:37.623852305 +0200
+++ histfile.expect.err	2017-12-22 17:16:29.000000000 +0100
@@ -1,7 +0,0 @@
-expect: spawn id  not open
-    while executing
-"expect {*}$expargs"
-    (procedure "expect_prompt" line 97)
-    invoked from within
-"expect_prompt"
-    (file "histfile.expect" line 103)
Exit status differs for file histfile.expect.
Unexpected test exit status 1.
Testing file history.expect ... ok
Testing file read.expect ... ok
Testing file signals.expect ... ok
1 test failed

[Comment 10 Georgy Yakovlev 2018-05-23 19:11:10 UTC]

ok, we have progress =) Almost there.

those expect test are really timing sensitive and do fail every once in a while, especially on older/slower systems.
Tests even fail on my ultrafast machine every 1 of 15 runs.

what I suggest to do is to emerge fish several times with -j1 and see if it changes the situation.
If you use PORTAGE_NICENESS, please unset it, or make it 0.
just to make sure it's getting the same priority and the resource distribution is fair.
 
an easy way to test without polluting logs or changing the system is just doing:

  nice -n0 env MAKEOPTS=-j1 ebuild /usr/portage/app-shells/fish/fish-2.7.1.ebuild clean test

If you get the same test failure every time when it may be a bug.
If the test failure is intermittent, then it's timing/race issue.


I'm sorry that I have to ask you to buildtest fish several more times, hope it's not a big hassle for you.

some details:

the error is

expect: spawn id  not open

Whenever a new process spawned with spawn command, then expect will save the spawn_id for that expect process into expect_out(spawn_id)
Something went wrong and either it did not start in time or exited and reference to spawn_id turned out to be invalid.

this error comes from that code:

# Spawn a new shell.
set prompt_counter 1
set fish_pid [spawn $fish]
expect_prompt


so either new shell took too long to launch, or exited early or there was some weird timing/race issue.

[Comment 11 ernsteiswuerfel 2018-05-23 21:32:17 UTC]

Nope, unfortunately building with -j1 did not work out. Tried 3 times and everytime I get the same test failure:

Testing file histfile.expect ... fail
Output differs for file histfile.expect. Diff follows:
--- histfile.expect.tmp.out	2018-05-23 23:28:40.116483169 +0200
+++ histfile.expect.out	2017-12-22 17:16:29.000000000 +0100
@@ -3,3 +3,5 @@
 cmd2 not found in default histfile
 cmd3 found in default histfile
 cmd3 not found in my histfile
+cmd4 found in env histfile
+cmd4 not found in default histfile
Error output differs for file histfile.expect. Diff follows:
--- histfile.expect.tmp.err	2018-05-23 23:28:40.136484054 +0200
+++ histfile.expect.err	2017-12-22 17:16:29.000000000 +0100
@@ -1,7 +0,0 @@
-expect: spawn id  not open
-    while executing
-"expect {*}$expargs"
-    (procedure "expect_prompt" line 97)
-    invoked from within
-"expect_prompt"
-    (file "histfile.expect" line 103)
Exit status differs for file histfile.expect.
Unexpected test exit status 1.
Testing file history.expect ... ok
Testing file read.expect ... ok
Testing file signals.expect ... ok
1 test failed
make: *** [Makefile:389: test_interactive] Error 1

[Comment 12 Georgy Yakovlev 2018-05-23 22:21:06 UTC]

Those expect tests are stupid, I've tested fish today like 100 times and they fail randomly with fixed inputs, purely timing/load related.

I'm seriously thinking to disable those or making optional.


nice -n20 env SHOW_INTERACTIVE_LOG=1 ebuild fish-2.7.1.ebuild clean test

and post the failure.
It'll print exact expect errors.

[Comment 13 ernsteiswuerfel 2018-05-23 22:53:45 UTC]

Testing file histfile.expect ... fail
Output differs for file histfile.expect. Diff follows:
--- histfile.expect.tmp.out	2018-05-24 00:50:16.244085710 +0200
+++ histfile.expect.out	2017-12-22 17:16:29.000000000 +0100
@@ -3,3 +3,5 @@
 cmd2 not found in default histfile
 cmd3 found in default histfile
 cmd3 not found in my histfile
+cmd4 found in env histfile
+cmd4 not found in default histfile
Error output differs for file histfile.expect. Diff follows:
--- histfile.expect.tmp.err	2018-05-24 00:50:16.264085990 +0200
+++ histfile.expect.err	2017-12-22 17:16:29.000000000 +0100
@@ -1,7 +0,0 @@
-expect: spawn id  not open
-    while executing
-"expect {*}$expargs"
-    (procedure "expect_prompt" line 97)
-    invoked from within
-"expect_prompt"
-    (file "histfile.expect" line 103)
Exit status differs for file histfile.expect.
Unexpected test exit status 1.
Log for file histfile.expect:
[INFO] spawn ../test/root/bin/fish
[DEBUG] spawn ../test/root/bin/fish: code 0, result 27148
[INFO] expecting prompt 1
[DEBUG] entering expect
[DEBUG] expect finished: ⏎                                                                                                                                                                                                                 \r⏎ \r\e[2K\rprompt 1>
[INFO] send {echo 27148 default histfile\r}
[INFO] expecting prompt 2
[DEBUG] entering expect
[DEBUG] expect finished: \rprompt 1>echo 27148 default histfile\rprompt 1>echo 27148 default histfile\r\n27148 default histfile\r\n⏎                                                                                                                                                                                                                 \r⏎ \r\e[2K\rprompt 2>
[INFO] send {history --save\r}
[INFO] expecting prompt 3
[DEBUG] entering expect
[DEBUG] expect finished: \rprompt 2>history --save\rprompt 2>history --save\r\n⏎                                                                                                                                                                                                                 \r⏎ \r\e[2K\rprompt 3>
[INFO] send {grep '^- cmd: echo 27148 default histfile' ../test/data/fish/fish_history\r}
[INFO] expecting prompt 4 + [-re {
- cmd: echo 27148 default histfile
}]
[DEBUG] entering expect
[DEBUG] matched extra pattern to expect_prompt: \r\n- cmd: echo 27148 default histfile\r\n
[DEBUG] exp_continue after consuming: \rprompt 3>grep '^- cmd: echo 27148 default histfile' ../test/data/fish/fish_history\rprompt 3>grep '^- cmd: echo 27148 default histfile' ../test/data/fish/fish_history\r\n- cmd: echo 27148 default histfile\r\n
[DEBUG] expect finished: ⏎                                                                                                                                                                                                                 \r⏎ \r\e[2K\rprompt 4>
[INFO] send {set fish_history my\r}
[INFO] expecting prompt 5
[DEBUG] entering expect
[DEBUG] expect finished: \rprompt 4>set fish_history my\rprompt 4>set fish_history my\r\n⏎                                                                                                                                                                                                                 \r⏎ \r\e[2K\rprompt 5>
[INFO] send {echo 27148 my histfile\r}
[INFO] expecting prompt 6
[DEBUG] entering expect
[DEBUG] expect finished: \rprompt 5>echo 27148 my histfile\rprompt 5>echo 27148 my histfile\r\n27148 my histfile\r\n⏎                                                                                                                                                                                                                 \r⏎ \r\e[2K\rprompt 6>
[INFO] send {history --save\r}
[INFO] expecting prompt 7
[DEBUG] entering expect
[DEBUG] expect finished: \rprompt 6>history --save\rprompt 6>history --save\r\n⏎                                                                                                                                                                                                                 \r⏎ \r\e[2K\rprompt 7>
[INFO] send {grep '^- cmd: echo 27148 my histfile' ../test/data/fish/my_history\r}
[INFO] expecting prompt 8 + [-re {
- cmd: echo 27148 my histfile
}]
[DEBUG] entering expect
[DEBUG] matched extra pattern to expect_prompt: \r\n- cmd: echo 27148 my histfile\r\n
[DEBUG] exp_continue after consuming: \rprompt 7>grep '^- cmd: echo 27148 my histfile' ../test/data/fish/my_history\rprompt 7>grep '^- cmd: echo 27148 my histfile' ../test/data/fish/my_history\r\n- cmd: echo 27148 my histfile\r\n
[DEBUG] expect finished: ⏎                                                                                                                                                                                                                 \r⏎ \r\e[2K\rprompt 8>
[INFO] send {grep '^- cmd: echo 27148 my histfile' ../test/data/fish/fish_history\r}
[INFO] expecting prompt 9 + [-re {
- cmd: echo 27148 my histfile
}]
[DEBUG] entering expect
[DEBUG] triggered unmatched action in expect_prompt
[DEBUG] expect buffer: \rprompt 8>grep '^- cmd: echo 27148 my histfile' ../test/data/fish/fish_history\rprompt 8>grep '^- cmd: echo 27148 my histfile' ../test/data/fish/fish_history\r\n⏎                                                                                                                                                                                                                 \r⏎ \r\e[2K\rprompt 9>
[DEBUG] expect finished: \rprompt 8>grep '^- cmd: echo 27148 my histfile' ../test/data/fish/fish_history\rprompt 8>grep '^- cmd: echo 27148 my histfile' ../test/data/fish/fish_history\r\n⏎                                                                                                                                                                                                                 \r⏎ \r\e[2K\rprompt 9>
[INFO] send {set fish_history default\r}
[INFO] expecting prompt 10
[DEBUG] entering expect
[DEBUG] expect finished: \rprompt 9>set fish_history default\rprompt 9>set fish_history default\r\n⏎                                                                                                                                                                                                                 \r⏎ \r\e[2K\rprompt 10>
[INFO] send {echo 27148 default histfile again\r}
[INFO] expecting prompt 11
[DEBUG] entering expect
[DEBUG] expect finished: \rprompt 10>echo 27148 default histfile again\rprompt 10>echo 27148 default histfile again\r\n27148 default histfile again\r\n⏎                                                                                                                                                                                                                 \r⏎ \r\e[2K\rprompt 11>
[INFO] send {history --save\r}
[INFO] expecting prompt 12
[DEBUG] entering expect
[DEBUG] expect finished: \rprompt 11>history --save\rprompt 11>history --save\r\n⏎                                                                                                                                                                                                                 \r⏎ \r\e[2K\rprompt 12>
[INFO] send {grep '^- cmd: echo 27148 default histfile again' ../test/data/fish/fish_history\r}
[INFO] expecting prompt 13 + [-re {
- cmd: echo 27148 default histfile again
}]
[DEBUG] entering expect
[DEBUG] matched extra pattern to expect_prompt: \r\n- cmd: echo 27148 default histfile again\r\n
[DEBUG] exp_continue after consuming: \rprompt 12>grep '^- cmd: echo 27148 default histfile again' ../test/data/fish/fish_history\rprompt 12>grep '^- cmd: echo 27148 default histfile again' ../test/data/fish/fish_history\r\n- cmd: echo 27148 default histfile again\r\n
[DEBUG] expect finished: ⏎                                                                                                                                                                                                                 \r⏎ \r\e[2K\rprompt 13>
[INFO] send {grep '^- cmd: echo 27148 default histfile again' ../test/data/fish/my_history\r}
[INFO] expecting prompt 14 + [-re {
- cmd: echo 27148 default histfile again
}]
[DEBUG] entering expect
[DEBUG] triggered unmatched action in expect_prompt
[DEBUG] expect buffer: \rprompt 13>grep '^- cmd: echo 27148 default histfile again' ../test/data/fish/my_history\rprompt 13>grep '^- cmd: echo 27148 default histfile again' ../test/data/fish/my_history\r\n⏎                                                                                                                                                                                                                 \r⏎ \r\e[2K\rprompt 14>
[DEBUG] expect finished: \rprompt 13>grep '^- cmd: echo 27148 default histfile again' ../test/data/fish/my_history\rprompt 13>grep '^- cmd: echo 27148 default histfile again' ../test/data/fish/my_history\r\n⏎                                                                                                                                                                                                                 \r⏎ \r\e[2K\rprompt 14>
[INFO] send {exit\r}
[INFO] spawn ../test/root/bin/fish
[DEBUG] spawn ../test/root/bin/fish: code 0, result 27242
[INFO] expecting prompt 1
[DEBUG] entering expect
[DEBUG] expect returned code 1
expect: spawn id  not open
    while executing
"expect {*}$expargs"
    (procedure "expect_prompt" line 97)
    invoked from within
"expect_prompt"
    (file "histfile.expect" line 103)
Testing file history.expect ... ok
Testing file read.expect ... ok
Testing file signals.expect ... ok
1 test failed

[Comment 14 Georgy Yakovlev 2018-05-28 00:49:11 UTC]

I don't have a clue what's going on, need some HW to trace it myself.
There is a possibility I'll get a power machine within next couple of months, so I'll leave this open for now.

Thank you for for running tests. I'll get back to it once I get the machine or find time to set up qemu for ppc.

[Comment 15 ernsteiswuerfel 2018-06-03 00:08:00 UTC]

Many thanks for your work! Setting up qemu for ppc probably might give you faster performance unless you get a G5 Quad or some more recent ppc gear. ;)

[Comment 16 Larry the Git Cow 2018-07-19 02:19:42 UTC]

The bug has been referenced in the following commit(s):

https://gitweb.gentoo.org/repo/gentoo.git/commit/?id=4ba06b5ba1fef6cbd2d1c120f84b09c06932a13f

commit 4ba06b5ba1fef6cbd2d1c120f84b09c06932a13f
Author:     Georgy Yakovlev <[e-mail]>
AuthorDate: 2018-07-19 02:18:38 +0000
Commit:     Georgy Yakovlev <[e-mail]>
CommitDate: 2018-07-19 02:18:38 +0000

    app-shells/fish: fix 'printf "%o"' handling on ppc
    
    Backport as a patch, that is already upstream
    https://github.com/fish-shell/fish-shell/pull/4444
    Run tests with -j1 and be verbose
    Run tests only if fish is already installed
    
    Reported-by: Sergei Trofimovich <[e-mail]>
    Bug: https://bugs.gentoo.org/656246
    Package-Manager: Portage-2.3.43, Repoman-2.3.10

 .../fish/files/fish-2.7.1-fix-printf-o-handling-on-ppc.patch | 12 ++++++++++++
 app-shells/fish/fish-2.7.1.ebuild                            |  8 +++++++-
 2 files changed, 19 insertions(+), 1 deletion(-)

[Comment 17 Georgy Yakovlev 2018-07-19 02:22:16 UTC]

(In reply to ernsteiswuerfel from comment #15)
> Many thanks for your work! Setting up qemu for ppc probably might give you
> faster performance unless you get a G5 Quad or some more recent ppc gear. ;)

Ok I've become a dev recently and will request access to some ppc big iron and will try to figure it out rest of test failures.

I've committed the patch posted here, don't forget to remove it from /etc/portage/patches if you are going to reinstall fish.

[Comment 18 Georgy Yakovlev 2019-01-05 02:03:15 UTC]

hey, you still here?
I could not reproduce this on quemu-chroot, but it does still fail randomly, same way as on amd64.

what about fish-3.0  we have in the tree now? can you check it? it haven't failed a single test for me yet on amd64.

[Comment 19 ernsteiswuerfel 2019-01-05 12:36:52 UTC]

Created attachment 559992 [details]
build.log (3.0.0-r1, ppc)

3.0.0-r1 passes printf.in but fails histfile.expect:

Testing file histfile.expect ... fail
Output differs for file histfile.expect. Diff follows:
--- histfile.expect.tmp.out	2019-01-05 13:30:12.216085805 +0100
+++ histfile.expect.out	2019-01-05 13:29:31.731344665 +0100
@@ -3,3 +3,5 @@
 cmd2 not found in default histfile
 cmd3 found in default histfile
 cmd3 not found in my histfile
+cmd4 found in env histfile
+cmd4 not found in default histfile
Error output differs for file histfile.expect. Diff follows:
--- histfile.expect.tmp.err	2019-01-05 13:30:12.229417492 +0100
+++ histfile.expect.err	2019-01-05 13:29:31.808000830 +0100
@@ -1,7 +0,0 @@
-expect: spawn id  not open
-    while executing
-"expect {*}$expargs"
-    (procedure "expect_prompt" line 97)
-    invoked from within
-"expect_prompt"
-    (file "histfile.expect" line 103)
Exit status differs for file histfile.expect.
Unexpected test exit status 1.
Testing file history.expect ... ok (0 sec)
Testing file read.expect ... ok (5 sec)
Testing file signals.expect ... ok (0 sec)
Testing file wait.expect ... ok (17 sec)
1 test failed
FAILED: CMakeFiles/test_interactive 
cd /var/tmp/portage/app-shells/fish-3.0.0-r1/work/fish-3.0.0_build && cd tests && /var/tmp/portage/app-shells/fish-3.0.0-r1/work/fish-3.0.0_build/test/root/bin/fish interactive.fish
ninja: build stopped: subcommand failed.
 * ERROR: app-shells/fish-3.0.0-r1::gentoo failed (test phase):
 *   ninja -v -j34 -l32 -j1 test failed

[Comment 20 Georgy Yakovlev 2019-01-09 01:27:16 UTC]

Created attachment 560480 [details, diff]
prompt test fix

thanks for re-running the test!

can you try once more with this patch please? should apply to both 2.7.1 and 3.0, so just drop in into "/etc/portage/patches/app-shells/fish"

[Comment 21 Larry the Git Cow 2019-01-10 09:06:40 UTC]

The bug has been closed via the following commit(s):

https://gitweb.gentoo.org/repo/gentoo.git/commit/?id=3df1fcdb8134cbf3c03ed18301323eef84113221

commit 3df1fcdb8134cbf3c03ed18301323eef84113221
Author:     Georgy Yakovlev <[e-mail]>
AuthorDate: 2019-01-10 09:00:12 +0000
Commit:     Georgy Yakovlev <[e-mail]>
CommitDate: 2019-01-10 09:00:45 +0000

    app-shells/fish: fix single test failing on 32bit arches
    
    Closes: https://bugs.gentoo.org/656246
    Package-Manager: Portage-2.3.54, Repoman-2.3.12
    Signed-off-by: Georgy Yakovlev <[e-mail]>

 .../fish/files/fix-histfile-test-on-ppc.patch      | 31 ++++++++++++++++++++++
 app-shells/fish/fish-2.7.1.ebuild                  |  5 ++--
 app-shells/fish/fish-3.0.0-r1.ebuild               |  4 ++-
 3 files changed, 37 insertions(+), 3 deletions(-)

[Comment 22 ernsteiswuerfel 2019-01-10 22:14:19 UTC]

With this patch both versions pass the tests now. Thanks!