Shellspec can not collect data with the profile option enabled

Hello, I try to use the profile option, but the formatter get no proper data.

# shellspec --profile spec/em_spec.sh
Running: /bin/bash [bash 5.1.4(1)-release]
............/lib/shellspec/lib/general.sh: line 538: * 10: syntax error: operand expected (error token is "* 10")
Aborted with status code [executor: 0] [reporter: 0] [error handler: 102]
Fatal error occurred, terminated with exit status 102.

This is a problem in shellspec_shift10() because "$2" is empty. Therefore, I try find the way the function will be called.

But this ended because I can not find the code where "$time_real" filled with proper values. See /lib/shellspec/lib/libexec/reporter/profiler_formatter.sh in profiler_end() in the line

  read_profiler callback "$profiler_tick_total" "$time_real" \
    < "$SHELLSPEC_PROFILER_LOG" \
    > "$SHELLSPEC_PROFILER_REPORT"

The time_real is empty, is ''. If I assign "0" to the empty "$time_real" I get no useful report but Shellspec finished without an error.

My question, where the variable "$time_real" came from?

Sorry, I can not find, what is going wrong, Lutz

p.s. I use shellspec 0.28.1 dist version.

I currently have the same issue

• Are you running shellspec using Cygwin on Windows?
• Do you see this line (near the end) when running it?

  [...]
  Finished in ? seconds (user ? seconds, sys ? seconds)
  [...]
  

I think it's something related to the timing (see following output from --help) since i always see the lines mentioned before.

$ shellspec -h | grep profile
    -p, --{no-}profile              Enable profiling and list the slowest examples [default: disabled]

My question, where the variable "$time_real" came from?

Those variables seems to be generated here: https://github.com/shellspec/shellspec/blob/f800240b606ed8d60f27ca687400836c0083e76a/lib/libexec/reporter.sh#L20

TL;DR;

Run export LC_ALL=C before running the shellspec command and the profiler will work as expected. 😃

🐞 Bug?

As you can see in the screenshot below, in my current situation if i run shellspec:

• Without --profile: No error, but at the same time no timing is shown (Finished in ? seconds (user ? seconds, sys ? seconds))
• With --profile: Fatal error, shellspec breaks as the OP already said before, also no timing is shown.

However... Look what happens if i first change my locale to the POSIX locale:

Now everything works as expected!

When does it happen?

It seems that this problem happens when i run shellcheck with locales different than the English (which the C/POSIX defaults to)... If i set the locale to one that is not installed on my system, the fallback seems to always be the C locale (POSIX) so it works too.

Locale	Installed	Working?
it_IT	Yes	No
es_ES	Yes	No
fr_FR	Yes	No
en_US	Yes	Yes
ja_JP	No	Yes
ko_KR	No	Yes
C	Always	Yes

As you can see the only language that works all the time is the C locale (this link provides interesting info). We need to check WHAT causes this behaviour to change based on the selected locale.

I'll try to look into this problem and see what i can find, but i think only @ko1nksm can give us a real answer...

🖥 System Info

I'm using Cygwin on Windows 10 19044:

$ uname -a
CYGWIN_NT-10.0-19044 Desktop-Luca 3.3.6-341.x86_64 2022-09-05 11:15 UTC x86_64 Cygwin

🚧 Workaround

Run export LC_ALL=C before running the shellspec command.

UPDATE

I did a little dive after a ☕ and I think i have found what is the problem...

As I suspected before, the bug is indeed in the read_time_log function: https://github.com/shellspec/shellspec/blob/f800240b606ed8d60f27ca687400836c0083e76a/lib/libexec/reporter.sh#L17-L30

In the line 25 it is checked if the second space-separated value is a number, and if so, it is skipped: https://github.com/shellspec/shellspec/blob/f800240b606ed8d60f27ca687400836c0083e76a/lib/libexec/reporter.sh#L25

By adding set -x at the start of the function we can see what's happening:

+ set +x
Line: real 0,99
+ eval 'time_real='\'''\'' time_user='\'''\'' time_sys='\'''\'''
Line: user 0,24
++ time_real=
Line: sys 0,48
++ time_user=
++ time_sys=
+ '[' -r /tmp/shellspec.1668189685.7137/.shellspec-time.log ']'
+ IFS=
+ read -r line
+ echo 'Line: real 0,99'
+ case $line in
+ case ${line##*[ $TAB]} in
+ continue
+ IFS=
+ read -r line
+ echo 'Line: user 0,24'
+ case $line in
+ case ${line##*[ $TAB]} in
+ continue
+ IFS=
+ read -r line
+ echo 'Line: sys 0,48'
+ case $line in
+ case ${line##*[ $TAB]} in
+ continue
+ IFS=
+ read -r line
+ :
+ eval '[ "$time_real" ] && [ "$time_user" ] && [ "$time_sys" ]'
++ '[' '' ']'
+ set +x

Basically every line is skipped because in these locales (tested with italian and spanish) the decimal separator is the comma (,) and not the period (.), so the glob pattern (*[!0-9.]*) will never match!

This is confirmed by looking at the same output when using the en_US locale:

+ eval 'time_real='\'''\'' time_user='\'''\'' time_sys='\'''\'''
Line: user 0.19
++ time_real=
Line: sys 0.44
++ time_user=
++ time_sys=
+ '[' -r /tmp/shellspec.1668189953.7388/.shellspec-time.log ']'
+ IFS=
+ read -r line
+ echo 'Line: real 0.96'
+ case $line in
+ case ${line##*[ $TAB]} in
+ eval 'time_real="${line##*[ $TAB]}"'
++ time_real=0.96
+ IFS=
+ read -r line
+ echo 'Line: user 0.19'
+ case $line in
+ case ${line##*[ $TAB]} in
+ eval 'time_user="${line##*[ $TAB]}"'
++ time_user=0.19
+ IFS=
+ read -r line
+ echo 'Line: sys 0.44'
+ case $line in
+ case ${line##*[ $TAB]} in
+ eval 'time_sys="${line##*[ $TAB]}"'
++ time_sys=0.44
+ IFS=
+ read -r line
+ :
+ eval '[ "$time_real" ] && [ "$time_user" ] && [ "$time_sys" ]'
++ '[' 0.96 ']'
++ '[' 0.19 ']'
++ '[' 0.44 ']'
+ set +x

You can see that this time the eval 'time_user="${line##*[ $TAB]}"' line is correctly executed.

We can easily reproduce the bug by writing this on the console:

✅ Solutions

Solution n°1

A quick solution that can solve this "bug" is adding the other decimal separator to the glob pattern:

• Before: (*[!0-9.]*)
• After: (*[!0-9.,]*)

https://github.com/shellspec/shellspec/blob/f800240b606ed8d60f27ca687400836c0083e76a/lib/libexec/reporter.sh#L25

Tests

Solution n°2

The most correct solution however would be to start the $SHELLSPEC_TIME command with the LC_ALL environment variable already set to C. https://github.com/shellspec/shellspec/blob/f800240b606ed8d60f27ca687400836c0083e76a/libexec/shellspec-runner.sh#L69

This line would be:

LC_ALL=C $SHELLSPEC_TIME $SHELLSPEC_SHELL "$executor" "$@" 3>&2 2>"$SHELLSPEC_TIME_LOG"

⚠ Help needed ⚠

This would be the best solution, since it would remove the problem from the root. However, it also could introduce new unexpected bugs, because:

• I don't really know the implications of setting the LC_ALL variable in other shells;
• This line is responsible of the initiation of the $SHELLSPEC_SHELL "$executor" script, which (from what i could understand) will actually execute your code. This introduces us to the main problems:
  1. Will the environment variable LC_ALL be propagated to all subprocesses created by the $executor script?
  2. If so, could it be a risk of unexpected values from the end-user point of view (i.e. error messages or numbers not formatted in the expected language)?
  3. Either way, could the fact that ONLY the $executor script has the LC_ALL varable set to C collide with other subshells that could have the user locale (i'm talking about internal shellspec functions)?

To implement this solution we would absolutely need @ko1nksm, since it could break something...

Final result

Now the profiler works with all (hopefully) the locales and the time is shown as it should:

@ko1nksm I'll make a PR for the 1st solution as soon as I can 😄

Thanks for all the suggestion/help Luca. Maybe, Koichi Nakashima will spend some time to Shellspec again.

I use Shellspec in a MacOS, Linux and AIX environment. In my old MacOS system, with Bash 3.2.57, Shellspec create profile data (LANG is de_DE.UTF-8). In Linux (and AIX) it does not create profile data.

Lutz

Appendage: The profile data in a MacOS environment.

lutz% shellspec --profile spec/em_spec.sh
Running: /bin/sh [bash 3.2.57(1)-release]
............

Finished in 44.99 seconds (user 1.74 seconds, sys 1.44 seconds)
12 examples, 0 failures

# Top 10 slowest examples of the 12 examples
#   1 30.7176 spec/em_spec.sh:66-83
#   2 10.2671 spec/em_spec.sh:87-92
#   3 1.8422 spec/em_spec.sh:8-12
#   4 0.2166 spec/em_spec.sh:36-42
#   5 0.2000 spec/em_spec.sh:22-27
#   6 0.1997 spec/em_spec.sh:101-105
#   7 0.1790 spec/em_spec.sh:52-58
#   8 0.1763 spec/em_spec.sh:44-50
#   9 0.1692 spec/em_spec.sh:14-18
#  10 0.1593 spec/em_spec.sh:60-64

Maybe, Koichi Nakashima will spend some time to Shellspec again.

I hope so too.

@lutzmad Does #281 fix your issue? How did you resolve the problem otherwise?

In Linux (and AIX) it does not create profile data.

What do you mean? What shell/locale are you using?

Hello Luca, I try to add your suggested modification tomorrow. I used my MacOS, but Shellspec collect profile data as expected in the MacOS environment. Lutz

p.s. I use the Bash shell in the Linux (and AIX) environment. The LANG is not C, we use de_DE with/without UTF-8 in general.

In a MacOS environment, the time output does not depend to the used LANG.

$ export LANG=de_DE (or en_US)
$ time -p id
uid= ...
real 0.00
user 0.00
sys 0.00

In the AIX ksh environment (my default shell, but I like the ksh, sorry), the time output honour the used LANG. This is the time command used by Shellspec, I think.

# export LANG=en_US
# /usr/bin/time -p id
uid= ...

Real   0.00
User   0.00
System 0.00
# export LANG=de_DE
# /usr/bin/time -p id
uid= ...

real   0,01
user   0,00
sys    0,00

And in the Linux and AIX bash environment, also.

# export LANG=de_DE
# time -p id
uid= ...
real 0,00
user 0,00
sys 0,00
# export LANG=en_US
# time -p id
uid= ...
real 0.00
user 0.00
sys 0.00

Hello Luke, you are right, as long as the US number format is used everything works well. But sometimes (in some environments, I switched to LANG=en_US), the output from the used "time" command looks different to the expected output.

The output (in a AIX environment) evaluated by read_time_log() echoed to the terminal (see lines prefixed by "#### ").

# shellspec --profile spec/em_spec.sh   Running: /bin/bash [bash 5.1.16(1)-release]
............#### /home/lutz/lib/shellspec/libexec/shellspec-executor.sh: line 9: [: : integer expression expected
####
#### Real   6.86
#### User   0.82
#### System 0.46
#### /home/lutz/lib/shellspec/libexec/shellspec-executor.sh: line 9: [: : integer expression expected
####
#### Real   6.86
#### User   0.82
#### System 0.46


Finished in 6.86 seconds (user 0.82 seconds, sys 0.46 seconds)
12 examples, 0 failures

# Top 10 slowest examples of the 12 examples
#   1 0.7171 spec/em_spec.sh:66-83
#   2 0.6268 spec/em_spec.sh:36-42
#   3 0.6197 spec/em_spec.sh:101-105
#   4 0.5499 spec/em_spec.sh:52-58
#   5 0.5480 spec/em_spec.sh:44-50
#   6 0.5409 spec/em_spec.sh:60-64
#   7 0.5192 spec/em_spec.sh:87-92
#   8 0.4966 spec/em_spec.sh:8-12
#   9 0.4908 spec/em_spec.sh:14-18
#  10 0.4787 spec/em_spec.sh:29-34

And sometimes (in a Linux environment), the output evaluated looks like this (see lines prefixed by "#### ").

> shellspec --profile spec/em_spec.sh
Running: /bin/sh [bash 4.3.48(1)-release]
............#### /usr/local/lib/shellspec/libexec/shellspec-executor.sh: line 9: [: : integer expression expected
#### real 42.09
#### user 1.63
#### sys 0.67
#### /usr/local/lib/shellspec/libexec/shellspec-executor.sh: line 9: [: : integer expression expected
#### real 42.09
#### user 1.63
#### sys 0.67


Finished in 42.09 seconds (user 1.63 seconds, sys 0.67 seconds)
12 examples, 0 failures

# Top 10 slowest examples of the 12 examples
#   1 30.2448 spec/em_spec.sh:66-83
#   2 10.1672 spec/em_spec.sh:87-92
#   3 0.1492 spec/em_spec.sh:36-42
#   4 0.1449 spec/em_spec.sh:44-50
#   5 0.1439 spec/em_spec.sh:52-58
#   6 0.1416 spec/em_spec.sh:101-105
#   7 0.1375 spec/em_spec.sh:14-18
#   8 0.1361 spec/em_spec.sh:8-12
#   9 0.1346 spec/em_spec.sh:60-64
#  10 0.1306 spec/em_spec.sh:22-27

Therefore, my suggested patch to handle the output use some additional lines of code, to handle Linux and AIX environments and your change.

--- shellspec/lib/libexec/reporter.sh.orig      2021-01-11 06:58:16.000000000 +0100
+++ shellspec/lib/libexec/reporter.sh   2024-02-02 10:58:14.827350190 +0100
@@ -17,15 +17,25 @@
# $1: prefix, $2: filename
read_time_log() {
   eval "$1_real='' $1_user='' $1_sys=''"
   [ -r "$2" ] || return 1
   # shellcheck disable=SC2034
   while IFS= read -r line; do
-    case $line in (real[\ $TAB]*|user[\ $TAB]*|sys[\ $TAB]*)
-      case ${line##*[ $TAB]} in (*[!0-9.]*) continue; esac
-      eval "$1_${line%%[ $TAB]*}=\"\${line##*[ \$TAB]}\""
+    case $line in ([Rr]eal[\ $TAB]*|[Uu]ser[\ $TAB]*|[Ss]ys[\ $TAB]*|[Ss]ystem[\ $TAB]*)
+      case ${line##*[ $TAB]} in (*[!0-9.,]*) continue; esac
+      case $line in
+        [Rr]eal[\ $TAB]*)
+          eval "$1_real=\"\${line##*[ \$TAB]}\"";;
+        [Uu]ser[\ $TAB]*)
+          eval "$1_user=\"\${line##*[ \$TAB]}\"";;
+        [Ss]ys[\ $TAB]*)
+          eval "$1_sys=\"\${line##*[ \$TAB]}\"";;
+        [Ss]ystem[\ $TAB]*)
+          eval "$1_sys=\"\${line##*[ \$TAB]}\"";;
+        *) eval "$1_${line%%[ $TAB]*}=\"\${line##*[ \$TAB]}\"";;
+      esac
     esac
   done < "$2" &&:
   eval "[ \"\$$1_real\" ] && [ \"\$$1_user\" ] && [ \"\$$1_sys\" ]"
}

field_description() {

Based on your suggested patch (handle '.' and ',') and some additional lines Shellspec is able to profile the scripts in Linux, AIX (and MacOS) enviroments, in some more/bad weather conditions.

Nice, thanks for your investigations, Lutz