[cogserver] ShellUTest fails (Create rep 29 of 30 in thread N failed)

[Radivarig]

After updating atomspace ShellUTest test fails with many outputs like this just with different thread number:

guile> 
guile> <<<
/home/radivarig/projects/opencog-dev/source/build/tests/shell/../../../tests/shell/ShellUTest.cxxtest:76: Error: Expected (281 <= reso.size()), found (281 > 274)
Error: Create rep 29 of 30 in thread 18 failed
	Got: 274 >>>opencog> Entering scheme shell; use ^D or a single . on a line by itself to exit.
guile> (EvaluationLink
   (PredicateNode "visible face")
   (ListLinkjj
      (NumberNode "28039")
   )
)

I'm using boost162 like suggested in #40 comment, and have also tried with boost 166 but got the same error.

[linas]

😞 I don't beleive that changes to the atomspace should have affected this test. This implies that there's some race condition somewhere, and that boost-1.62 hides it better than 1.67

[Radivarig]

This test no longer fails, it takes around 200 seconds and throws this guile error but completes:

Exception thrown while printing backtrace:
6: In procedure cdr: Wrong type argument in position 1 (expecting pair): ()

Full output

test 6
    Start 6: ShellUTest

6: Test command: /home/radivarig/projects/opencog-dev/source/build/tests/shell/ShellUTest
6: Environment variables: 
6:  GUILE_LOAD_PATH=/nix/store/rzcbj6knwjvi6x4xsz4wv2vbfpnr2gp1-atomspace/share/guile/site:/nix/store/rzcbj6knwjvi6x4xsz4wv2vbfpnr2gp1-atomspace/share/guile/site:/home/radivarig/projects/opencog-dev/source/build/opencog/scm
6: Test timeout computed to be: 10000000
6: Running cxxtest tests (5 tests);;; note: auto-compilation is enabled, set GUILE_AUTO_COMPILE=0
6: ;;;       or pass the --no-auto-compile argument to disable.
6: ;;; compiling /nix/store/rzcbj6knwjvi6x4xsz4wv2vbfpnr2gp1-atomspace/share/guile/site/opencog/base/core_types.scm
6: ;;; opencog/base/core_types.scm:12:0: warning: shadows previous definition of `Notype' at opencog/base/core_types.scm:10:0
6: ;;; opencog/base/core_types.scm:57:0: warning: shadows previous definition of `Atom' at opencog/base/core_types.scm:55:0
6: ;;; opencog/base/core_types.scm:218:0: warning: shadows previous definition of `VariableList' at opencog/base/core_types.scm:216:0
6: ;;; opencog/base/core_types.scm:223:0: warning: shadows previous definition of `VariableSet' at opencog/base/core_types.scm:221:0
6: ;;; opencog/base/core_types.scm:343:0: warning: shadows previous definition of `Type' at opencog/base/core_types.scm:118:0
6: ;;; opencog/base/core_types.scm:363:0: warning: shadows previous definition of `TypeChoice' at opencog/base/core_types.scm:361:0
6: ;;; opencog/base/core_types.scm:538:0: warning: shadows previous definition of `Connector' at opencog/base/core_types.scm:536:0
6: ;;; opencog/base/core_types.scm:543:0: warning: shadows previous definition of `ConnectorDir' at opencog/base/core_types.scm:541:0
6: ;;; opencog/base/core_types.scm:548:0: warning: shadows previous definition of `LinkClass' at opencog/base/core_types.scm:546:0
6: ;;; opencog/base/core_types.scm:553:0: warning: shadows previous definition of `ConnectorSeq' at opencog/base/core_types.scm:551:0
6: ;;; opencog/base/core_types.scm:558:0: warning: shadows previous definition of `Section' at opencog/base/core_types.scm:556:0
6: ;;; compiled /home/radivarig/projects/opencog-dev/source/.cache/guile/ccache/2.2-LE-8-3.A/nix/store/rzcbj6knwjvi6x4xsz4wv2vbfpnr2gp1-atomspace/share/guile/site/opencog/base/core_types.scm.go
6: ;;; compiling /nix/store/rzcbj6knwjvi6x4xsz4wv2vbfpnr2gp1-atomspace/share/guile/site/opencog/base/core-docs.scm
6: ;;; compiled /home/radivarig/projects/opencog-dev/source/.cache/guile/ccache/2.2-LE-8-3.A/nix/store/rzcbj6knwjvi6x4xsz4wv2vbfpnr2gp1-atomspace/share/guile/site/opencog/base/core-docs.scm.go
6: ;;; compiling /nix/store/rzcbj6knwjvi6x4xsz4wv2vbfpnr2gp1-atomspace/share/guile/site/opencog/base/utilities.scm
6: ;;; compiled /home/radivarig/projects/opencog-dev/source/.cache/guile/ccache/2.2-LE-8-3.A/nix/store/rzcbj6knwjvi6x4xsz4wv2vbfpnr2gp1-atomspace/share/guile/site/opencog/base/utilities.scm.go
6: ;;; compiling /nix/store/rzcbj6knwjvi6x4xsz4wv2vbfpnr2gp1-atomspace/share/guile/site/opencog/base/atom-cache.scm
6: ;;; compiled /home/radivarig/projects/opencog-dev/source/.cache/guile/ccache/2.2-LE-8-3.A/nix/store/rzcbj6knwjvi6x4xsz4wv2vbfpnr2gp1-atomspace/share/guile/site/opencog/base/atom-cache.scm.go
6: ;;; compiling /nix/store/rzcbj6knwjvi6x4xsz4wv2vbfpnr2gp1-atomspace/share/guile/site/opencog/base/apply.scm
6: ;;; compiled /home/radivarig/projects/opencog-dev/source/.cache/guile/ccache/2.2-LE-8-3.A/nix/store/rzcbj6knwjvi6x4xsz4wv2vbfpnr2gp1-atomspace/share/guile/site/opencog/base/apply.scm.go
6: ;;; compiling /nix/store/rzcbj6knwjvi6x4xsz4wv2vbfpnr2gp1-atomspace/share/guile/site/opencog/base/tv.scm
6: ;;; compiled /home/radivarig/projects/opencog-dev/source/.cache/guile/ccache/2.2-LE-8-3.A/nix/store/rzcbj6knwjvi6x4xsz4wv2vbfpnr2gp1-atomspace/share/guile/site/opencog/base/tv.scm.go
6: ;;; compiling /nix/store/rzcbj6knwjvi6x4xsz4wv2vbfpnr2gp1-atomspace/share/guile/site/opencog/base/types.scm
6: ;;; compiled /home/radivarig/projects/opencog-dev/source/.cache/guile/ccache/2.2-LE-8-3.A/nix/store/rzcbj6knwjvi6x4xsz4wv2vbfpnr2gp1-atomspace/share/guile/site/opencog/base/types.scm.go
6: ;;; compiling /nix/store/rzcbj6knwjvi6x4xsz4wv2vbfpnr2gp1-atomspace/share/guile/site/opencog/base/file-utils.scm
6: ;;; compiled /home/radivarig/projects/opencog-dev/source/.cache/guile/ccache/2.2-LE-8-3.A/nix/store/rzcbj6knwjvi6x4xsz4wv2vbfpnr2gp1-atomspace/share/guile/site/opencog/base/file-utils.scm.go
6: ;;; compiling /nix/store/rzcbj6knwjvi6x4xsz4wv2vbfpnr2gp1-atomspace/share/guile/site/opencog/base/debug-trace.scm
6: ;;; compiled opencog> Entering scheme shell; use ^D or a single . on a line by itself to exit.
6: guile> (ConceptNode "42")
6: 
6: guile> 
6: guile> opencog> Entering scheme shell; use ^D or a single . on a line by itself to exit.
6: guile> Exiting the shell
6: 4
6: guile> opencog> opencog> Entering scheme shell; use ^D or a single . on a line by itself to exit.
6: guile> (ConceptNode "42")
6: 
6: guile> 
6: guile> opencog> Entering scheme shell; use ^D or a single . on a line by itself to exit.
6: guile> Exiting the shell
6: 4
6: guile> opencog> Listening on port 17333
6: .opencog> Entering scheme shell; use ^D or a single . on a line by itself to exit.
6: guile> guile> Backtrace:
6:            8 (apply-smob/1 #<catch-closure 7f8a3853e500>)
6:            7 (apply-smob/1 #<catch-closure 7f8a38545b20>)
6: In ice-9/boot-9.scm:
6:    2312:4  6 (save-module-excursion #<procedure 7f8a385408c0 at ice-…>)
6: In ice-9/eval-string.scm:
6:      38:6  5 (read-and-eval #<input: string 7f8a310c1e70> #:lang _)
6: In unknown file:
6:            4 (sleep 41)
6: Exception thrown while printing backtrace:
6: In procedure cdr: Wrong type argument in position 1 (expecting pair): ()
6: 
6: ERROR: In procedure apply-smob/1:
6: In procedure SchemeEval::interrupt: User interrupt from keyboard
6: ABORT: user-interrupt
6: opencog> Entering scheme shell; use ^D or a single . on a line by itself to exit.
6: guile> guile> opencog> Entering scheme shell; use ^D or a single . on a line by itself to exit.
6: guile> guile> Backtrace:
6:            8 (apply-smob/1 #<catch-closure 7f8a3194fa80>)
6:            7 (apply-smob/1 #<catch-closure 7f8a31968f60>)
6: In ice-9/boot-9.scm:
6:    2312:4  6 (save-module-excursion #<procedure 7f8a31957040 at ice-…>)
6: In ice-9/eval-string.scm:
6:      38:6  5 (read-and-eval #<input: string 7f8a26a59e70> #:lang _)
6: In unknown file:
6:            4 (sleep 41)
6: Exception thrown while printing backtrace:
6: In procedure cdr: Wrong type argument in position 1 (expecting pair): ()
6: 
6: ERROR: In procedure apply-smob/1:
6: In procedure SchemeEval::interrupt: User interrupt from keyboard
6: ABORT: user-interrupt
6: Listening on port 17333
6: Elapsed: 0
6: First elapsed: 0
6: Second elapsed: 0
6: .Listening on port 17333
6: Received 224 bytes: opencog> Entering scheme shell; use ^D or a single . on a line by itself to exit.
6: guile> (ConceptNode "B")
6: (ConceptNode "C")
6: (ConceptNode "A")
6: (ConceptNode "42")
6: 
6: guile> 
6: .Listening on port 17333
6: .Listening on port 17333 
6: .OK!
6: /home/radivarig/projects/opencog-dev/source/.cache/guile/ccache/2.2-LE-8-3.A/nix/store/rzcbj6knwjvi6x4xsz4wv2vbfpnr2gp1-atomspace/share/guile/site/opencog/base/debug-trace.scm.go
6/6 Test #6: ShellUTest .......................   Passed  186.44 sec

100% tests passed, 0 tests failed out of 6

Total Test time (real) = 187.37 sec
[100%] Built target test

[linas]

I think the spewing output is normal. The test starts an inf-loop of scheme code in the "foreground" thread, and then intentionally sends a ctrl-C over the telnet shell, with the idea that this should kill the inf-loop. What actually happens is that the thread handling the socket, when it receives the magic byte sequence for ^C, then sens a guile interrupt to the "foreground" thread, which will result in some kind of unhappy complaint w/ stack trace from the interrupted thread. The exception is caught, the complaint is serialized to string and sent via socket back to the user, who gets to read it.

[linas]

Oh, and if I recall correctly, the test is designed to run exactly 180 seconds... Its starting dozens of network connections to the server, splatting stuff across each connection, checking to see if the server gets tangled up in handling all this. Three minutes should be enough to expose race conditions, if they exist.

[linas]

Oh, and final remark: once every few dozen(???) runs, the test fails, just as its finishing. There's a short read somewhere; the test harness is still sending data even as the server is shutting down after 3 minutes. Normally, it all terminates correctly, but sometimes not.