build fails on 1-core VM

[bmwiedemann]

While working on reproducible builds for openSUSE, I found that
our yast2-ruby-bindings package fails build tests on 1-core-VMs

Steps to reproduce:

osc co openSUSE:Factory/yast2-ruby-bindings && cd $_
osc build --noservice --vm-type=kvm -j1 standard

Actual result:

[...]
 25: stdout: tty before importing UI
 25: stdout: TERM=screen
 25: stdout: NCurses is using the tty       
 25: stdout: tty is free again                     
 25: .                                                    
 25:                                                             
 25: Finished in 0.01194 seconds (files took 0.20178 seconds to load)   
 25: 1 example, 0 failures                                                     
 25:
 25: pure virtual method called
 25: terminate called without an active exception                              
 25/29 Test #25: integration .......................................................................................***Failed    0.55 sec

[...]

 97% tests passed, 1 tests failed out of 29

 Total Test time (real) =  33.88 sec

 The following tests FAILED:
         25 - integration (Failed)
 Errors while running CTest

[shundhammer]

Wild guess: Not only just a single CPU core (which should not be a problem at all), but also low RAM? Out of memory when trying to load shared libs?

[bmwiedemann]

No, same RAM as the -j4 build that always works. One try might even have been with 26GB RAM.

[shundhammer]

I am really confused about this "pure virtual method called" message. This would explain a failure, but why only when there is just one CPU core?

[bmwiedemann]

Have you tried the reproducer?
Linux process scheduling is very different in 1-core environments, e.g. try this one-liner with different numbers (e.g. 1,3,7,f) after taskset:

taskset 1 perl -e 'for(1..5) {my $pid=fork(); if($pid==0){print "$_\n"; exit 0}}'

So if there is a place where you have two processes interacting, one can try to connect to the other but fail because it is too early and the other did not start yet.

[ancorgs]

I created a corresponding card to track this in the private trello board used by the YaST Team at SUSE to coordinate and prioritize: https://trello.com/c/Tor31iYm/4608-yast-ruby-bindings-build-fails-on-1-core-vm

[mvidner]

Thanks, @bmwiedemann !
Reproduced in a git checkout:

$ mkdir build; cd build; cmake ..; make -j $(nproc) all; taskset 1 ruby /home/martin/svn/yast-ruby-bindings/tests/integration/run.rb
bash: řádek 1: 31346 Neúspěšně ukončen (SIGABRT)        (core dumped [obraz paměti uložen]) rspec /home/martin/svn/yast-ruby-bindings/tests/integration/std_streams_spec.rb > /tmp/test_cmd_output 2>&1
Outside tmux output:

Test failed: 'rspec /home/martin/svn/yast-ruby-bindings/tests/integration/std_streams_spec.rb >/tmp/test_cmd_output 2>&1'.
result: '134
'
Output was:
stderr: tty before importing UI
stderr: TERM=screen
stderr: NCurses is using the tty
stderr: tty is free again
stdout: tty before importing UI
stdout: TERM=screen
stdout: NCurses is using the tty
stdout: tty is free again
.

Finished in 0.00555 seconds (files took 0.08034 seconds to load)
1 example, 0 failures

pure virtual method called
terminate called without an active exception

[mvidner]

(taskset 1 limits the command to the 1st logical CPU, taskset 3 to the first pair of them)

Y2DEBUG=1 taskset 1 rspec /home/martin/svn/yast-ruby-bindings/tests/integration/std_streams_spec.rb

tail y2log:

2021-06-11 12:11:39 <1> ohmu(31814) [ui] YUILoader.cc(deleteUI):234 Shutting down UI
2021-06-11 12:11:39 <1> ohmu(31814) [ncurses] YNCursesUI.cc(~YNCursesUI):120 Stop YNCursesUI
2021-06-11 12:11:39 <3> ohmu(31814) [ui] YUI.cc(~YUI):94 shutdownThreads() was never called!
2021-06-11 12:11:39 <3> ohmu(31814) [ui] YUI.cc(~YUI):95 shutting down now - this might segfault
2021-06-11 12:11:39 <0> ohmu(31814) [ui] YUI.cc(terminateUIThread):254 Sending shutdown message to UI thread

With taskset 3, tail y2log:

2021-06-11 12:14:40 <1> ohmu(31972) [ui] YUILoader.cc(deleteUI):234 Shutting down UI
2021-06-11 12:14:40 <1> ohmu(31972) [ncurses] YNCursesUI.cc(~YNCursesUI):120 Stop YNCursesUI
2021-06-11 12:14:40 <3> ohmu(31972) [ui] YUI.cc(~YUI):94 shutdownThreads() was never called!
2021-06-11 12:14:40 <3> ohmu(31972) [ui] YUI.cc(~YUI):95 shutting down now - this might segfault
2021-06-11 12:14:40 <0> ohmu(31972) [ui] YUI.cc(terminateUIThread):254 Sending shutdown message to UI thread
2021-06-11 12:14:40 <0> ohmu(31972) [ui] YUI.cc(uiThreadMainLoop):378 Shutting down UI main loop
2021-06-11 12:14:40 <0> ohmu(31972) [ui] YUI.cc(terminateUIThread):261 UI thread shut down correctly
2021-06-11 12:14:40 <1> ohmu(31972) [ncurses] NCurses.cc(~NCurses):145 Shutdown NCurses...
2021-06-11 12:14:40 <1> ohmu(31972) [ncurses] NCurses.cc(~NCurses):164 NCurses down
2021-06-11 12:14:40 <0> ohmu(31972) [YCPDeclarations] ../../src/YCPDeclarations.cc(~YCPDeclarations):221 Destructor called

https://github.com/yast/yast-ruby-bindings/blob/ac490204f0c4d5b11f4a44fdf975315d6cc0449d/tests/integration/std_streams_spec.rb is exercising the API in a singular way, probably exposing a race condition.