libtool test failure: assert_intercepted: failed: expected greater or equal 6, but got 5

[gyakovlev]

Describe the bug
Hi!
new libtool test (added in 80eb9e4) fails on gentoo
not sure what's going on yet.
any pointers will be helpful, I can poke this system.

1: ******************** TEST 'bear :: cases/intercept/wrapper/libtool_commands_captured.sh' FAILED ********************
1: Script:                                                
1: --                                                     
1: : 'RUN: at line 4';   /var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/stage/bin/intercept --wrapper /var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/stage/lib64/bear/wrapper --library /var/tmp/portage/dev
-util/bear-3.0.17/work/Bear-3.0.17_build/stage/lib64/bear/libexec.so --wrapper-dir /var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/stage/lib64/bear/wrapper.d --force-wrapper --verbose --output /var/tmp/portage/dev-util/
bear-3.0.17/work/Bear-3.0.17_build/subprojects/Build/BearTest/cases/intercept/wrapper/Output/libtool_commands_captured.sh.tmp.json -- /usr/sbin/sh /var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17/test/cases/intercept/wrapper/l
ibtool_commands_captured.sh                               
1: : 'RUN: at line 5';   assert_intercepted /var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/subprojects/Build/BearTest/cases/intercept/wrapper/Output/libtool_commands_captured.sh.tmp.json count -ge 6
1: : 'RUN: at line 6';   assert_intercepted /var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/subprojects/Build/BearTest/cases/intercept/wrapper/Output/libtool_commands_captured.sh.tmp.json contains -program /usr/sbin/cc 
-arguments /usr/sbin/cc -g -O -c main.c -o main.o
1: : 'RUN: at line 7';   assert_intercepted /var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/subprojects/Build/BearTest/cases/intercept/wrapper/Output/libtool_commands_captured.sh.tmp.json contains -program /usr/sbin/cc 
-arguments /usr/sbin/cc -g -O -c hello.c -o hello.o
1: --                                                     
1: Exit Code: 1                                           
1:                                                        
1: Command Output (stdout):                               
1: --                                                     
1: $ ":" "RUN: at line 4"                                 
1: $ "/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/stage/bin/intercept" "--wrapper" "/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/stage/lib64/bear/wrapper" "--library" "/var/tmp/portage/dev-util/bear-
3.0.17/work/Bear-3.0.17_build/stage/lib64/bear/libexec.so" "--wrapper-dir" "/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/stage/lib64/bear/wrapper.d" "--force-wrapper" "--verbose" "--output" "/var/tmp/portage/dev-util
/bear-3.0.17/work/Bear-3.0.17_build/subprojects/Build/BearTest/cases/intercept/wrapper/Output/libtool_commands_captured.sh.tmp.json" "--" "/usr/sbin/sh" "/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17/test/cases/intercept/wr
apper/libtool_commands_captured.sh"
1: # command output:
1: libtool: compile:  cc -g -O -c main.c  -fPIC -DPIC -o .libs/main.o
1: libtool: compile:  cc -g -O -c main.c -o main.o >/dev/null 2>&1
1: libtool: compile:  cc -g -O -c hello.c  -fPIC -DPIC -o .libs/hello.o
1: libtool: compile:  cc -g -O -c hello.c -o hello.o >/dev/null 2>&1
1: libtool: link: powerpc64le-unknown-linux-gnu-ar cru .libs/libhello.a .libs/hello.o 
1: libtool: link: powerpc64le-unknown-linux-gnu-ranlib .libs/libhello.a
1: libtool: link: ( cd ".libs" && rm -f "libhello.la" && ln -s "../libhello.la" "libhello.la" )
1: libtool: link: cc -g -O -o libtool_test .libs/main.o  ./.libs/libhello.a 
1:                                                        
1: # command stderr:                                      
1: [20:04:22.340913, ic, 3332] intercept: 3.0.17
1: [20:04:22.341098, ic, 3332] arguments: ["/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/stage/bin/intercept", "--wrapper", "/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/stage/lib64/bear/wrapper", "--
library", "/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/stage/lib64/bear/libexec.so", "--wrapper-dir", "/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/stage/lib64/bear/wrapper.d", "--force-wrapper", "--
verbose", "--output", "/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/subprojects/Build/BearTest/cases/intercept/wrapper/Output/libtool_commands_captured.sh.tmp.json", "--", "/usr/sbin/sh", "/var/tmp/portage/dev-util/b
ear-3.0.17/work/Bear-3.0.17/test/cases/intercept/wrapper/libtool_commands_captured.sh"]
1: [20:04:22.341117, ic, 3332] environment: ["PATH=/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17/test/bin:/var/tmp/portage/dev-util/bear-3.0.17/temp/python3.10/bin:/usr/lib/portage/python3.10/ebuild-helpers/xattr:/usr/lib/p
ortage/python3.10/ebuild-helpers:/usr/local/sbin:/usr/sbin:/sbin:/bin:/usr/local/bin:/usr/bin:/opt/bin:/usr/lib/llvm/13/bin", "LLVM_DISABLE_CRASH_REPORT=1", "TERM=xterm-256color", "TMPDIR=/var/tmp/portage/dev-util/bear-3.0.17/temp",
 "TMP=/var/tmp/portage/dev-util/bear-3.0.17/temp", "TEMP=/var/tmp/portage/dev-util/bear-3.0.17/temp", "LC_CTYPE=en_US.UTF-8", "TRUE=/usr/sbin/true", "FALSE=/usr/sbin/false", "ECHO=/usr/sbin/echo", "SLEEP=/usr/sbin/sleep", "CC=/usr/s
bin/cc", "CXX=/usr/sbin/c++", "LIBTOOL=/usr/sbin/libtool"] 
1: [20:04:22.341130, ic, 3332] sysname: Linux
1: [20:04:22.341136, ic, 3332] release: 5.15.10
1: [20:04:22.341142, ic, 3332] version: #1 SMP Fri Dec 17 12:55:16 PST 2021
1: [20:04:22.341149, ic, 3332] machine: ppc64le
1: [20:04:22.341167, ic, 3332] arguments parsed: {program: /var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/stage/bin/intercept, arguments: [{--: [/usr/sbin/sh, /var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17/test
/cases/intercept/wrapper/libtool_commands_captured.sh]}, {--force-wrapper: []}, {--library: [/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/stage/lib64/bear/libexec.so]}, {--output: [/var/tmp/portage/dev-util/bear-3.0.
17/work/Bear-3.0.17_build/subprojects/Build/BearTest/cases/intercept/wrapper/Output/libtool_commands_captured.sh.tmp.json]}, {--verbose: []}, {--wrapper: [/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/stage/lib64/bear
/wrapper]}, {--wrapper-dir: [/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/stage/lib64/bear/wrapper.d]}]}
1: [20:04:22.346521, ic, 3332] session initialized with: wrapper_dir: /var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/stage/lib64/bear/wrapper.d
1: [20:04:22.346563, ic, 3332] session initialized with: mapping: [{ "ar": "/usr/sbin/ar" }, { "as": "/usr/sbin/as" }, { "bison": "/usr/sbin/bison" }, { "c++": "/usr/sbin/c++" }, { "cc": "/usr/sbin/cc" }, { "clang": "/usr/lib/llvm/1
3/bin/clang" }, { "clang++": "/usr/lib/llvm/13/bin/clang++" }, { "cpp": "/usr/sbin/cpp" }, { "flex": "/usr/sbin/flex" }, { "g++": "/usr/sbin/g++" }, { "gcc": "/usr/sbin/gcc" }, { "ld": "/usr/sbin/ld" }, { "lex": "/usr/sbin/lex" }, {
 "makeinfo": "/usr/sbin/makeinfo" }, { "nm": "/usr/sbin/nm" }, { "objcopy": "/usr/sbin/objcopy" }, { "objdump": "/usr/sbin/objdump" }, { "ranlib": "/usr/sbin/ranlib" }, { "readelf": "/usr/sbin/readelf" }, { "strip": "/usr/sbin/strip
" }, { "yacc": "/usr/sbin/yacc" }]
1: [20:04:22.346580, ic, 3332] session initialized with: override: [{ "CC": "cc" }, { "CXX": "c++" }]
1: [20:04:22.350929, ic, 3332] Running gRPC server. dns:///localhost:34781
1: [20:04:22.358282, ic, 3332] Process spawned. [pid: 3355, command: [/usr/sbin/sh, /var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17/test/cases/intercept/wrapper/libtool_commands_captured.sh]]
1: [20:04:22.358379, ic, 3332] Process wait requested. [pid: 3355]
1: [20:04:22.455192, wr, 3505, ppid: 3362] wrapper: 3.0.17 
1: [20:04:22.455333, wr, 3505, ppid: 3362] arguments: ["cc", "-g", "-O", "-c", "main.c", "-fPIC", "-DPIC", "-o", ".libs/main.o"]
1: [20:04:22.455356, wr, 3505, ppid: 3362] environment: ["INTERCEPT_REPORT_DESTINATION=dns:///localhost:34781", "LLVM_DISABLE_CRASH_REPORT=1", "ECHO=printf %s\n", "PWD=/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/sub
projects/Build/BearTest/cases/intercept/wrapper", "TRUE=/usr/sbin/true", "CXX=c++", "LIBTOOL=/usr/sbin/libtool", "FALSE=/usr/sbin/false", "TMPDIR=/var/tmp/portage/dev-util/bear-3.0.17/temp", "TERM=xterm-256color", "INTERCEPT_VERBOSE
=true", "TEMP=/var/tmp/portage/dev-util/bear-3.0.17/temp", "SHLVL=2", "DUALCASE=1", "LC_CTYPE=en_US.UTF-8", "TMP=/var/tmp/portage/dev-util/bear-3.0.17/temp", "PATH=/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/stage/l
ib64/bear/wrapper.d:/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17/test/bin:/var/tmp/portage/dev-util/bear-3.0.17/temp/python3.10/bin:/usr/lib/portage/python3.10/ebuild-helpers/xattr:/usr/lib/portage/python3.10/ebuild-helper
s:/usr/local/sbin:/usr/sbin:/sbin:/bin:/usr/local/bin:/usr/bin:/opt/bin:/usr/lib/llvm/13/bin", "CC=powerpc64le-unknown-linux-gnu-gcc", "SLEEP=/usr/sbin/sleep", "_=/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/stage/li
b64/bear/wrapper.d/cc"]                                   
1: [20:04:22.457062, wr, 3505, ppid: 3362] gRPC call requested: supervise::Supervisor::Resolve
1: [20:04:22.462570, ic, 3332] trying to resolve for wrapper: cc
1: [20:04:22.463338, wr, 3505, ppid: 3362] gRPC call [Resolve] finished: true
1: [20:04:22.463878, wr, 3505, ppid: 3362] Process spawned. [pid: 3538, command: [/usr/sbin/cc, -g, -O, -c, main.c, -fPIC, -DPIC, -o, .libs/main.o]]
1: [20:04:22.463957, wr, 3505, ppid: 3362] gRPC call requested: supervise::Interceptor::Register
1: [20:04:22.470811, wr, 3505, ppid: 3362] gRPC call [Register] finished: true
1: [20:04:22.471018, wr, 3505, ppid: 3362] Process wait requested. [pid: 3538]
1: [20:04:22.511118, wr, 3505, ppid: 3362] Process wait request: done. [pid: 3538]
1: [20:04:22.511152, wr, 3505, ppid: 3362] gRPC call requested: supervise::Interceptor::Register
1: [20:04:22.512596, wr, 3505, ppid: 3362] gRPC call [Register] finished: true
1: [20:04:22.515098, wr, 3505, ppid: 3362] succeeded with: 0
1: [20:04:22.535564, ic, 3332] trying to resolve for wrapper: cc
1: [20:04:22.657983, wr, 3657, ppid: 3637] wrapper: 3.0.17 
1: [20:04:22.658135, wr, 3657, ppid: 3637] arguments: ["cc", "-g", "-O", "-c", "hello.c", "-fPIC", "-DPIC", "-o", ".libs/hello.o"]
1: [20:04:22.658158, wr, 3657, ppid: 3637] environment: ["INTERCEPT_REPORT_DESTINATION=dns:///localhost:34781", "LLVM_DISABLE_CRASH_REPORT=1", "ECHO=printf %s\n", "PWD=/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/sub
projects/Build/BearTest/cases/intercept/wrapper", "TRUE=/usr/sbin/true", "CXX=c++", "LIBTOOL=/usr/sbin/libtool", "FALSE=/usr/sbin/false", "TMPDIR=/var/tmp/portage/dev-util/bear-3.0.17/temp", "TERM=xterm-256color", "INTERCEPT_VERBOSE
=true", "TEMP=/var/tmp/portage/dev-util/bear-3.0.17/temp", "SHLVL=2", "DUALCASE=1", "LC_CTYPE=en_US.UTF-8", "TMP=/var/tmp/portage/dev-util/bear-3.0.17/temp", "PATH=/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/stage/l
ib64/bear/wrapper.d:/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17/test/bin:/var/tmp/portage/dev-util/bear-3.0.17/temp/python3.10/bin:/usr/lib/portage/python3.10/ebuild-helpers/xattr:/usr/lib/portage/python3.10/ebuild-helper
s:/usr/local/sbin:/usr/sbin:/sbin:/bin:/usr/local/bin:/usr/bin:/opt/bin:/usr/lib/llvm/13/bin", "CC=powerpc64le-unknown-linux-gnu-gcc", "SLEEP=/usr/sbin/sleep", "_=/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/stage/li
b64/bear/wrapper.d/cc"]                                   
1: [20:04:22.659360, wr, 3657, ppid: 3637] gRPC call requested: supervise::Supervisor::Resolve
1: [20:04:22.661549, ic, 3332] trying to resolve for wrapper: cc
1: [20:04:22.662027, wr, 3657, ppid: 3637] gRPC call [Resolve] finished: true
1: [20:04:22.662441, wr, 3657, ppid: 3637] Process spawned. [pid: 3671, command: [/usr/sbin/cc, -g, -O, -c, hello.c, -fPIC, -DPIC, -o, .libs/hello.o]]
1: [20:04:22.662515, wr, 3657, ppid: 3637] gRPC call requested: supervise::Interceptor::Register
1: [20:04:22.664207, wr, 3657, ppid: 3637] gRPC call [Register] finished: true
1: [20:04:22.664320, wr, 3657, ppid: 3637] Process wait requested. [pid: 3671]
1: [20:04:22.708615, wr, 3657, ppid: 3637] Process wait request: done. [pid: 3671]
1: [20:04:22.708639, wr, 3657, ppid: 3637] gRPC call requested: supervise::Interceptor::Register
1: [20:04:22.709203, wr, 3657, ppid: 3637] gRPC call [Register] finished: true
1: [20:04:22.710056, wr, 3657, ppid: 3637] succeeded with: 0
1: [20:04:22.730086, ic, 3332] trying to resolve for wrapper: cc
1: [20:04:23.007424, wr, 3948, ppid: 3849] wrapper: 3.0.17 
1: [20:04:23.007559, wr, 3948, ppid: 3849] arguments: ["cc", "-g", "-O", "-o", "libtool_test", ".libs/main.o", "./.libs/libhello.a"]
1: [20:04:23.007581, wr, 3948, ppid: 3849] environment: ["INTERCEPT_REPORT_DESTINATION=dns:///localhost:34781", "LLVM_DISABLE_CRASH_REPORT=1", "ECHO=printf %s\n", "PWD=/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/sub
projects/Build/BearTest/cases/intercept/wrapper", "TRUE=/usr/sbin/true", "CXX=c++", "LIBTOOL=/usr/sbin/libtool", "FALSE=/usr/sbin/false", "TMPDIR=/var/tmp/portage/dev-util/bear-3.0.17/temp", "TERM=xterm-256color", "INTERCEPT_VERBOSE
=true", "TEMP=/var/tmp/portage/dev-util/bear-3.0.17/temp", "SHLVL=2", "DUALCASE=1", "LC_CTYPE=C", "TMP=/var/tmp/portage/dev-util/bear-3.0.17/temp", "PATH=/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/stage/lib64/bear/
wrapper.d:/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17/test/bin:/var/tmp/portage/dev-util/bear-3.0.17/temp/python3.10/bin:/usr/lib/portage/python3.10/ebuild-helpers/xattr:/usr/lib/portage/python3.10/ebuild-helpers:/usr/loc
al/sbin:/usr/sbin:/sbin:/bin:/usr/local/bin:/usr/bin:/opt/bin:/usr/lib/llvm/13/bin", "CC=powerpc64le-unknown-linux-gnu-gcc", "SLEEP=/usr/sbin/sleep", "_=/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/stage/lib64/bear/w
rapper.d/cc"]                                             
1: [20:04:23.008692, wr, 3948, ppid: 3849] gRPC call requested: supervise::Supervisor::Resolve
1: [20:04:23.010735, ic, 3332] trying to resolve for wrapper: cc
1: [20:04:23.011379, wr, 3948, ppid: 3849] gRPC call [Resolve] finished: true
1: [20:04:23.011710, wr, 3948, ppid: 3849] Process spawned. [pid: 3956, command: [/usr/sbin/cc, -g, -O, -o, libtool_test, .libs/main.o, ./.libs/libhello.a]]
1: [20:04:23.011764, wr, 3948, ppid: 3849] gRPC call requested: supervise::Interceptor::Register
1: [20:04:23.012869, wr, 3948, ppid: 3849] gRPC call [Register] finished: true
1: [20:04:23.013003, wr, 3948, ppid: 3849] Process wait requested. [pid: 3956]
1: [20:04:23.052745, wr, 3948, ppid: 3849] Process wait request: done. [pid: 3956]
1: [20:04:23.052767, wr, 3948, ppid: 3849] gRPC call requested: supervise::Interceptor::Register
1: [20:04:23.053317, wr, 3948, ppid: 3849] gRPC call [Register] finished: true
1: [20:04:23.054303, wr, 3948, ppid: 3849] succeeded with: 0
1: [20:04:23.057401, ic, 3332] Process wait request: done. [pid: 3355]
1: [20:04:23.057493, ic, 3332] Running command. [Exited with 0]
1: [20:04:23.057509, ic, 3332] Stopping gRPC server.
1: [20:04:23.058327, ic, 3332] succeeded with: 0
1:                                                     

1: $ ":" "RUN: at line 5"                                 
1: $ "assert_intercepted" "/var/tmp/portage/dev-util/bear-3.0.17/work/Bear-3.0.17_build/subprojects/Build/BearTest/cases/intercept/wrapper/Output/libtool_commands_captured.sh.tmp.json" "count" "-ge" "6"
1: # command stderr:                                      
1: assert_intercepted: failed: expected greater or equal 6, but got 5
1:                                                        
1: error: command failed with exit status: 1

To Reproduce
Steps to reproduce the behavior:
build bear, run tests

Expected behavior
test passes

Environment:

• OS name: linux
• OS version: gentoo (rolling)
• OS architecture: ppc64le
• Bear version: 3.0.17
• Bear install method: package

Additional context
libtool-2.4.6-r6

[rizsotto]

Thanks @gyakovlev for this bug report. Will look at it next week. My only question, if the test fails only on this architecture or x86_64 fails too?

[gyakovlev]

I'll check on something else, don't know yet.

[rizsotto]

This should be fixed now. Will be released in the next few weeks. (Available on devel branch now.)

[gyakovlev]

sorry I lost track of it, but I'll leave comment anyway, better late than never ;-)
I confirm it no longer happens in 3.0.19 and all tests pass on ppc64le and other arches I tested it on.