Hang when `cat` is aliased to `bat`

[jtyers]

Just come across this and I love the idea, but I'm struggling to get the example working. Given this script, based on your example:

#!/usr/bin/env zsh
source $(antibody path mafredri/zsh-async)/async.zsh
async_init

worker_try() {
  echo 1 2 3 trtying!
}

COMPLETED=0
completed_callback() {
    COMPLETED=$(( COMPLETED + 1 ))
    print $@
}

async_start_worker my_worker -n
async_register_callback my_worker completed_callback

async_job my_worker worker_try
async_job my_worker print hello
async_job my_worker sleep 0.3

while (( COMPLETED < 3 )); do
    print "Waiting..."
    sleep 0.1
done

print "Completed $COMPLETED tasks!"

I simply get Waiting... repeatedly. Pressing Ctrl-C ends it with no additional output. I'm not sure of the underlying implementation but looking in the process tree for zpty yields nothing. (When calling this script as ./test.zsh, so not sourcing.)

Am I doing something wrong?

zsh 5.8 on Arch.

[jtyers]

And for completeness here are my other plugins:

  10   agkozak/zsh-z
  12   zdharma/fast-syntax-highlighting
  13   chrissicool/zsh-256color
  14   kutsan/zsh-system-clipboard
  15   
  16   romkatv/powerlevel10k
  17   
  18   mafredri/zsh-async
  19   sindresorhus/pure

[mafredri]

I can't see anything wrong in your example, and it works perfectly fine for me on macOS zsh 5.8 and Debian zsh 5.7.1.

Additionally, since you're running the file (and not sourcing), your other plugins shouldn't matter as your regular prompt environment won't be loaded (assuming you keep your configuration in .zshrc).

Try adding setopt xtrace at the very top of the file (but after the shebang), it might provide some clues as to what's happening (or not happening).

[mafredri]

Another thing you can try adding at the very top, emulate -R zsh (before xtrace, as it will reset the option). What it does is reset all settable options to their default values for the emulation mode (in this case zsh). Should allow us to see if it's a configuration on your system that causes it.

[jtyers]

Thanks for the prompt reply. emulate sadly made no difference; here's the trace below.

I noticed async_start_worker (6) zpty -t my_worker returned non-zero (the 1 on the following line).

0 ./another.zsh (5) source ./async.zsh
0 ./async.zsh (11) typeset -g ASYNC_VERSION=1.8.5
0 ./async.zsh (13) typeset -g ASYNC_DEBUG=0
0 ./async.zsh (669) async
0 async (1) async_init
0 async_init (1) ((  ASYNC_INIT_DONE  ))
1 async_init (2) typeset -g ASYNC_INIT_DONE=1
0 async_init (4) zmodload zsh/zpty
0 async_init (5) zmodload zsh/datetime
0 async_init (8) autoload -Uz is-at-least
0 async_init (12) typeset -g ASYNC_ZPTY_RETURNS_FD=0
0 async_init (13) [[ -o interactive ]]
1 ./another.zsh (6) async_init
1 async_init (1) ((  ASYNC_INIT_DONE  ))
0 async_init (1) return
0 ./another.zsh (9) async_start_worker my_worker -n
0 async_start_worker (1) setopt localoptions noshwordsplit noclobber
0 async_start_worker (3) local worker=my_worker
0 async_start_worker (3) shift
0 async_start_worker (4) local -a args
0 async_start_worker (5) args=( -n ) 
0 async_start_worker (6) zpty -t my_worker
1 async_start_worker (8) typeset -gA ASYNC_PTYS
0 async_start_worker (9) typeset -h REPLY
0 async_start_worker (10) typeset has_xtrace=0
0 async_start_worker (12) [[ -o interactive ]]
0 async_start_worker (30) integer errfd=-1
0 async_start_worker (33) is-at-least 5.0.8
0 is-at-least (23) emulate -L zsh
0 is-at-least (25) local IFS=.- min_cnt=0 ver_cnt=0 part min_ver version order
0 is-at-least (27) min_ver=( 5 0 8 ) 
0 is-at-least (28) version=( 5 8 0 ) 
0 is-at-least (30) ((  0 <= 3  ))
0 is-at-least (31) [[ '' != <-> ]]
0 is-at-least (32) ((  ++ver_cnt > 3  ))
1 is-at-least (33) [[ 5 = *[0-9][^0-9]* ]]
0 is-at-least (45) part=5 
0 is-at-least (31) [[ 5 != <-> ]]
0 is-at-least (48) true
0 is-at-least (49) ((  ++min_cnt > 3  ))
1 is-at-least (50) [[ 5 = <-> ]]
0 is-at-least (50) break
0 is-at-least (53) ((  part > min_ver[min_cnt]  ))
1 is-at-least (54) ((  part < min_ver[min_cnt]  ))
1 is-at-least (55) part='' 
0 is-at-least (30) ((  1 <= 3  ))
0 is-at-least (31) [[ '' != <-> ]]
0 is-at-least (32) ((  ++ver_cnt > 3  ))
1 is-at-least (33) [[ 8 = *[0-9][^0-9]* ]]
0 is-at-least (45) part=8 
0 is-at-least (31) [[ 8 != <-> ]]
0 is-at-least (48) true
0 is-at-least (49) ((  ++min_cnt > 3  ))
1 is-at-least (50) [[ 0 = <-> ]]
0 is-at-least (50) break
0 is-at-least (53) ((  part > min_ver[min_cnt]  ))
0 is-at-least (53) return 0
0 async_start_worker (39) [[ -o xtrace ]]
0 async_start_worker (40) has_xtrace=1 
0 async_start_worker (41) unsetopt xtrace
0 async_start_worker (53) ((  errfd != -1  ))
0 async_start_worker (55) ((  ret  ))
0 async_start_worker (60) is-at-least 5.0.8
0 is-at-least (23) emulate -L zsh
0 is-at-least (25) local IFS=.- min_cnt=0 ver_cnt=0 part min_ver version order
0 is-at-least (27) min_ver=( 5 0 8 ) 
0 is-at-least (28) version=( 5 8 0 ) 
0 is-at-least (30) ((  0 <= 3  ))
0 is-at-least (31) [[ '' != <-> ]]
0 is-at-least (32) ((  ++ver_cnt > 3  ))
1 is-at-least (33) [[ 5 = *[0-9][^0-9]* ]]
0 is-at-least (45) part=5 
0 is-at-least (31) [[ 5 != <-> ]]
0 is-at-least (48) true
0 is-at-least (49) ((  ++min_cnt > 3  ))
1 is-at-least (50) [[ 5 = <-> ]]
0 is-at-least (50) break
0 is-at-least (53) ((  part > min_ver[min_cnt]  ))
1 is-at-least (54) ((  part < min_ver[min_cnt]  ))
1 is-at-least (55) part='' 
0 is-at-least (30) ((  1 <= 3  ))
0 is-at-least (31) [[ '' != <-> ]]
0 is-at-least (32) ((  ++ver_cnt > 3  ))
1 is-at-least (33) [[ 8 = *[0-9][^0-9]* ]]
0 is-at-least (45) part=8 
0 is-at-least (31) [[ 8 != <-> ]]
0 is-at-least (48) true
0 is-at-least (49) ((  ++min_cnt > 3  ))
1 is-at-least (50) [[ 0 = <-> ]]
0 is-at-least (50) break
0 is-at-least (53) ((  part > min_ver[min_cnt]  ))
0 is-at-least (53) return 0
0 async_start_worker (67) [[ -o interactive ]]
0 ./another.zsh (12) COMPLETED=0 
0 ./another.zsh (19) async_register_callback my_worker completed_callback
0 async_register_callback (1) setopt localoptions noshwordsplit nolocaltraps
0 async_register_callback (3) typeset -gA ASYNC_PTYS ASYNC_CALLBACKS
0 async_register_callback (4) local worker=my_worker
0 async_register_callback (4) shift
0 async_register_callback (6) ASYNC_CALLBACKS[$worker]=completed_callback 
0 async_register_callback (10) [[ ! -o interactive ]]
0 async_register_callback (11) trap _async_notify_trap WINCH
0 ./another.zsh (22) async_job my_worker print hello
0 async_job (1) setopt localoptions noshwordsplit noksharrays noposixidentifiers noposixstrings
0 async_job (3) local worker=my_worker
0 async_job (3) shift
0 async_job (5) local -a cmd
0 async_job (6) cmd=( print hello ) 
0 async_job (7) ((  2 > 1  ))
0 async_job (8) cmd=( print hello ) 
0 async_job (11) _async_send_job async_job my_worker 'print hello'
0 _async_send_job (1) setopt localoptions noshwordsplit noksharrays noposixidentifiers noposixstrings
0 _async_send_job (3) local caller=async_job
0 _async_send_job (4) local worker=my_worker
0 _async_send_job (5) shift 2
0 _async_send_job (7) zpty -t my_worker
0 _async_send_job (19) zpty -w my_worker $'print hello\C-@'
0 ./another.zsh (23) async_job my_worker sleep 0.3
0 async_job (1) setopt localoptions noshwordsplit noksharrays noposixidentifiers noposixstrings
0 async_job (3) local worker=my_worker
0 async_job (3) shift
0 async_job (5) local -a cmd
0 async_job (6) cmd=( sleep 0.3 ) 
0 async_job (7) ((  2 > 1  ))
0 async_job (8) cmd=( sleep 0.3 ) 
0 async_job (11) _async_send_job async_job my_worker 'sleep 0.3'
0 _async_send_job (1) setopt localoptions noshwordsplit noksharrays noposixidentifiers noposixstrings
0 _async_send_job (3) local caller=async_job
0 _async_send_job (4) local worker=my_worker
0 _async_send_job (5) shift 2
0 _async_send_job (7) zpty -t my_worker
0 _async_send_job (19) zpty -w my_worker $'sleep 0.3\C-@'
0 ./another.zsh (26) ((  COMPLETED < 2  ))
0 ./another.zsh (27) print Waiting...
Waiting...
0 ./another.zsh (28) sleep 0.1
0 ./another.zsh (26) ((  COMPLETED < 2  ))
0 ./another.zsh (27) print Waiting...
Waiting...
0 ./another.zsh (28) sleep 0.1
0 ./another.zsh (26) ((  COMPLETED < 2  ))
0 ./another.zsh (27) print Waiting...
Waiting...
0 ./another.zsh (28) sleep 0.1
0 ./another.zsh (26) ((  COMPLETED < 2  ))
0 ./another.zsh (27) print Waiting...
Waiting...

[jtyers]

This looks like it. Running that same line at an interactive prompt:

❯ zpty -t my_worker; echo $?
zpty: no such pty command: my_worker
1

[jtyers]

Scratch that, I've just found the manual for zpty and understood what that is doing. Peppering my code with zpty -L/zpty -r my_worker seems to show the pty is created, but no output is read from it.

[mafredri]

Hmm, interesting, your trace output is formatted differently than mine:

+./another.zsh:5> source ./async.zsh
+./async.zsh:11> typeset -g ASYNC_VERSION=1.8.5
...

I wonder if this suggests your zsh configuration is not being reset, even with emulate -R zsh? Edit: Never mind, had a bit of a Freudian slip, of course all configuration isn't reset 🤦🏻‍♂️. But I guess it also means that you have some configuration, not originating from .zshrc that could be the cause of this issue.

I noticed two other things:

1. The order in your trace suggests COMPLETED=0 is set after async_start_worker my_worker -n (unlike the example in your original post)
2. The line +./another.zsh:21> async_job my_worker worker_try is missing from your trace suggesting it's not run, for whatever reason

[jtyers]

Ah, well I've specifically configured $PS4 to show the output in that way, which I set in my ~/.zshenv. There's nothing in there that looks like it would interfere with async (it sets env vars, contains aliases, setopts and a few alias-functions), other than setopt notify, but unsetting that option has no impact. Are you aware of any settings etc that could impact this or tips where I should start looking?

Apologies yes I did re-order things, after finding a comment you made in another issue that functions/variables used by a worker need to be declared before that worker is started. It seems to make no difference in my case. The code as it stands now:

#!/usr/bin/env zsh
emulate -R zsh
setopt xtrace
unsetopt notify

COMPLETED=0
completed_callback() {
    COMPLETED=$(( COMPLETED + 1 ))
    print $@
}

source ./async.zsh
async_init

async_start_worker my_worker -n

echo "zptys: $(zpty -L)"

async_register_callback my_worker completed_callback

echo "zptys: $(zpty -L)"

async_job my_worker ps
async_job my_worker sleep 0.3

while (( COMPLETED < 2 )); do
    echo "zptys: $(zpty -L)"
    print "Waiting... ($COMPLETED)"

    sleep 0.1
done

print "Completed $COMPLETED tasks!"

Still no joy though.

[jtyers]

On your second point, yes, worker_try never gets run.

Edit: did you mean a different function? My copy of async.zsh has no such function (on master, commit bbbc92bd)

[mafredri]

On your second point, yes, worker_try never gets run.

Edit: did you mean a different function? My copy of async.zsh has no such function (on master, commit bbbc92bd)

Ah no, it was part of your first example. But not an issue, obviously it's missing when it's not part of the script 😂.

Now. I managed to reproduce your issue with the missing ps output. And hopefully a fix in #45. The problem was that we were outputting too much data on the fd, and for some reason this can result in data loss.

Especially when the zpty is being both written to from both ends simultaneously. By running your first example in an endless for, loop, this resulted in me (re)discovering a second bug, one that has likely been haunting this project since #18.

Please do give #45 a spin.

I've also added the ability to debug the async worker, example:

ASYNC_DEBUG=1
ASYNC_DEBUG_WORKER_STDERR=/tmp/my_worker_err.log
async_start_worker my_worker -n

---

Apologies yes I did re-order things, after finding a comment you made in another issue that functions/variables used by a worker need to be declared before that worker is started. It seems to make no difference in my case.

Ah. The sourceing makes no difference, actually. It's the async_start_worker line that's the critical one.

Consider:

myfunc() {
    print hi
}
async_start_worker mywork
async_job mywork myfunc

vs.

async_start_worker mywork
myfunc() {
    print hi
}
async_job mywork myfunc

In the latter case, the myfunc will not be defined inside the worker, and async_job will produce a command not found.

[jtyers]

Interesting! I'm afraid I get the same behaviour on that branch. I've added the new debugging flags, and also a sleep at the start of the loop, but to no avail.

while (( COMPLETED < 2 )); do
    sleep 2.1
    echo "zptys: $(zpty -L)"
    print "Waiting... ($COMPLETED)"

done

I also ran the test suite from that branch - it hangs on the first test

> ./test.zsh -v
=== RUN   test__async_job_multiple_commands

Here is the trace from running my script with the new sleep as above:

0 _async_worker (26) is-at-least 5.4.1
0 is-at-least (23) emulate -L zsh
0 is-at-least (25) local IFS=.- min_cnt=0 ver_cnt=0 part min_ver version order
0 is-at-least (27) min_ver=( 5 4 1 ) 
0 is-at-least (28) version=( 5 8 0 ) 
0 is-at-least (30) ((  0 <= 3  ))
0 is-at-least (31) [[ '' != <-> ]]
0 is-at-least (32) ((  ++ver_cnt > 3  ))
1 is-at-least (33) [[ 5 = *[0-9][^0-9]* ]]
0 is-at-least (45) part=5 
0 is-at-least (31) [[ 5 != <-> ]]
0 is-at-least (48) true
0 is-at-least (49) ((  ++min_cnt > 3  ))
1 is-at-least (50) [[ 5 = <-> ]]
0 is-at-least (50) break
0 is-at-least (53) ((  part > min_ver[min_cnt]  ))
1 is-at-least (54) ((  part < min_ver[min_cnt]  ))
1 is-at-least (55) part='' 
0 is-at-least (30) ((  1 <= 3  ))
0 is-at-least (31) [[ '' != <-> ]]
0 is-at-least (32) ((  ++ver_cnt > 3  ))
1 is-at-least (33) [[ 8 = *[0-9][^0-9]* ]]
0 is-at-least (45) part=8 
0 is-at-least (31) [[ 8 != <-> ]]
0 is-at-least (48) true
0 is-at-least (49) ((  ++min_cnt > 3  ))
1 is-at-least (50) [[ 4 = <-> ]]
0 is-at-least (50) break
0 is-at-least (53) ((  part > min_ver[min_cnt]  ))
0 is-at-least (53) return 0
0 _async_worker (32) local -A storage
0 _async_worker (33) local unique=0
0 _async_worker (34) local notify_parent=0
0 _async_worker (35) local parent_pid=0
0 _async_worker (36) local coproc_pid=0
0 _async_worker (37) local processing=0
0 _async_worker (39) local -a zsh_hooks zsh_hook_functions
0 _async_worker (40) zsh_hooks=( chpwd periodic precmd preexec zshexit zshaddhistory ) 
0 _async_worker (41) zsh_hook_functions=( chpwd_functions periodic_functions precmd_functions preexec_functions zshexit_functions zshaddhistory_functions ) 
0 _async_worker (42) unfunction chpwd periodic precmd preexec zshexit zshaddhistory
1 _async_worker (43) unset chpwd_functions periodic_functions precmd_functions preexec_functions zshexit_functions zshaddhistory_functions
0 _async_worker (44) unset zsh_hooks zsh_hook_functions
0 _async_worker (59) trap close_idle_coproc CHLD
0 _async_worker (62) getopts np:uz opt
0 _async_worker (63) case p (n)
0 _async_worker (63) case p (p)
0 _async_worker (65) parent_pid=1841041 
0 _async_worker (62) getopts np:uz opt
0 _async_worker (63) case n (n)
0 _async_worker (64) notify_parent=1 
0 _async_worker (62) getopts np:uz opt
0 _async_worker (70) (( !notify_parent ))
0 _async_worker (108) local request do_eval=0
0 _async_worker (109) local -a cmd
0 _async_worker (110) :
0 _async_worker (112) read -r -d $'\C-@' request
0 _async_worker (130) request=ps 
0 _async_worker (133) case ps (_killjobs)
0 _async_worker (133) case ps (_async_eval*)
0 _async_worker (140) cmd=( ps ) 
0 _async_worker (143) local job=ps
0 _async_worker (147) ((  !do_eval  ))
0 _async_worker (147) ((  unique  ))
0 _async_worker (158) processing=1 
0 _async_worker (162) ((  ! coproc_pid  ))
0 _async_worker (165) coproc_pid=1841046 
0 _async_worker (167) print -n -p t
0 _async_worker (170) ((  do_eval  ))
0 _async_worker (177) storage[$job]=1841047 
0 _async_worker (180) processing=0 
0 _async_worker (182) ((  do_eval  ))
1 _async_worker (175) _async_job 1841041 ps
0 _async_worker (110) :
1 _async_job (2) float -F duration=1603404178.8125591278
0 _async_worker (112) read -r -d $'\C-@' request
0 _async_job (5) local parent_pid=1841041
0 _async_worker (130) request='sleep 0.3' 
0 _async_worker (133) case sleep 0.3 (_killjobs)
0 _async_worker (133) case sleep 0.3 (_async_eval*)
0 _async_worker (140) cmd=( sleep 0.3 ) 
0 _async_worker (143) local job=sleep
0 _async_worker (164) bat
0 _async_job (5) shift
0 _async_worker (147) ((  !do_eval  ))
0 _async_worker (147) ((  unique  ))
0 _async_worker (158) processing=1 
0 _async_worker (162) ((  ! coproc_pid  ))
0 _async_worker (170) ((  do_eval  ))
0 _async_worker (177) storage[$job]=1841048 
0 _async_worker (180) processing=0 
0 _async_worker (182) ((  do_eval  ))
1 _async_worker (175) _async_job 1841041 sleep 0.3
0 _async_job (13) local jobname=ps out
0 _async_worker (110) :
1 _async_job (2) float -F duration=1603404178.8156440258
0 _async_job (14) out=0 _async_worker (112) read -r -d $'\C-@' request
0 _async_job (15) local stdout stderr ret tok
0 _async_job (5) local parent_pid=1841041
0 _async_job (19) setopt noxtrace
0 _async_job (5) shift
0 _async_job (13) local jobname=sleep out
0 _async_job (14) out=0 _async_job (15) local stdout stderr ret tok
0 _async_job (19) setopt noxtrace
0 _async_job (14) out=$'\C-@ps 0 \\ \\ \\ \\ PID\\ TTY\\ \\ \\ \\ \\ \\ \\ \\ \\ \\ TIME\\ CMD$\'\\n\'1841042\\ pts/17\\ \\ \\ 00:00:00\\ zsh$\'\\n\'1841046\\ pts/17\\ \\ \\ 00:00:00\\ bat$\'\\n\'1841047\\ pts/17\\ \\ \\ 00:00:00\\ zsh$\'\\n\'1841048\\ pts/17\\ \\ \\ 00:00:00\\ zsh$\'\\n\'1841049\\ pts/17\\ \\ \\ 00:00:00\\ zsh$\'\\n\'1841050\\ pts/17\\ \\ \\ 00:00:00\\ zsh$\'\\n\'1841051\\ pts/17\\ \\ \\ 00:00:00\\ zsh$\'\\n\'1841052\\ pts/17\\ \\ \\ 00:00:00\\ bat$\'\\n\'1841053\\ pts/17\\ \\ \\ 00:00:00\\ zsh$\'\\n\'1841054\\ pts/17\\ \\ \\ 00:00:00\\ zsh$\'\\n\'1841055\\ pts/17\\ \\ \\ 00:00:00\\ zsh$\'\\n\'1841056\\ pts/17\\ \\ \\ 00:00:00\\ bat$\'\\n\'1841057\\ pts/17\\ \\ \\ 00:00:00\\ ps 0.0220668316 \'\'\C-@' 
0 _async_job (28) [[ $'\C-@ps 0 \\ \\ \\ \\ PID\\ TTY\\ \\ \\ \\ \\ \\ \\ \\ \\ \\ TIME\\ CMD$\'\\n\'1841042\\ pts/17\\ \\ \\ 00:00:00\\ zsh$\'\\n\'1841046\\ pts/17\\ \\ \\ 00:00:00\\ bat$\'\\n\'1841047\\ pts/17\\ \\ \\ 00:00:00\\ zsh$\'\\n\'1841048\\ pts/17\\ \\ \\ 00:00:00\\ zsh$\'\\n\'1841049\\ pts/17\\ \\ \\ 00:00:00\\ zsh$\'\\n\'1841050\\ pts/17\\ \\ \\ 00:00:00\\ zsh$\'\\n\'1841051\\ pts/17\\ \\ \\ 00:00:00\\ zsh$\'\\n\'1841052\\ pts/17\\ \\ \\ 00:00:00\\ bat$\'\\n\'1841053\\ pts/17\\ \\ \\ 00:00:00\\ zsh$\'\\n\'1841054\\ pts/17\\ \\ \\ 00:00:00\\ zsh$\'\\n\'1841055\\ pts/17\\ \\ \\ 00:00:00\\ zsh$\'\\n\'1841056\\ pts/17\\ \\ \\ 00:00:00\\ bat$\'\\n\'1841057\\ pts/17\\ \\ \\ 00:00:00\\ ps 0.0220668316 \'\'\C-@' != * ]]
0 _async_job (34) read -r -k 1 -p tok
0 _async_job (14) out=$'\C-@sleep 0 \'\' 0.3132193089 \'\'\C-@' 
0 _async_job (28) [[ $'\C-@sleep 0 \'\' 0.3132193089 \'\'\C-@' != * ]]
0 _async_job (34) read -r -k 1 -p tok

[jtyers]

Right, found the culprit. I have this alias defined:

alias cat='bat'

Now bat aims to be totally cat-like but the trace above suggests using bat as a coproc is the cause of the hang. Removing that alias causes the example to work again, plus the tests.

[jtyers]

See #47 for a fix

[jtyers]

Thanks @mafredri for your patience! Works a treat :+1:

[mafredri]

No problem, and glad to hear! Is that with #45 or without, btw? Well, either way, your issue resulted in quite a few improvements, so thanks to you too! 😄