1

MacOS Yosemite (10.10.5). I know this is the Unix/Linux section...but figure this question probably fits better here than in MacOS land.

My terminal started hanging on startup before showing a prompt...and the CPU usage spiked at the same time. I can CTRL-C and then get a prompt (presumably exiting some hanging/running .bashrc/.profile/etc).

I figured out quickly that certain lines in my .bashrc were causing the hang. This is new (ie I didn't change anything in my .bashrc and everything used to work fine), so something changed on the system.

It seems piping certain longer strings results in the hang/CPU spike.

I can reproduce this by piping a string to tr -d '\n' and seeing if it hangs.

macattack:~ $ openssl rand -base64 93  | tr -d '\n'
eDsz4JqFX/HAVjplNI6WDWwPRp9l9snp6UKp/pLn+GbBvJx0+ZMvSJFS/SuCwjMRRXVXfUvBdkaH1R0UgCr2UOf283MvHVTRusLFEVPcGCIz1t3sFMU/3foRzNWVmattp@macattack:~ $ openssl rand -base64 94 | tr -d '\n'
^C
mattp@macattack:~ $ openssl rand -base64 94 | tr -du '\n'
^C

Seems like 93 characters is the magic number where tr starts to hang. openssl isn't hanging (ie if I remove the pipe to tr everything exits). However my original problem line happened to be different length.

mattp@macattack:~ $ echo 'echo -e "$TS\t${TERM_SESSION_ID}\t$(pwd)\t$(history 1 | cut -c 8-)\n" >> $HOME/.history/history-$(date "+%Y-%m-%d")-${USER}.log;' | tr -d '\n'
^C-bash: echo: write error: Interrupted system call

mattp@macattack:~ $ echo 'echo -e "$TS\t${TERM_SESSION_ID}\t$(pwd)\t$(history 1 | cut -c 8-)\n" >> $HOME/.history/history-$(date "+%Y-%m-%d")-${USER}.log' | tr -d '\n'

mattp@macattack:~ $ echo 'echo -e "$TS\t${TERM_SESSION_ID}\t$(pwd)\t$(history 1 | cut -c 8-)\n" >> $HOME/.history/history-$(date "+%Y-%m-%d")-${USER}.log' | wc -c
     128
mattp@macattack:~ $

This is probably a pipe issue rather than a tr issue. I can reproduce the same issue with sed (command doesn't make sense...just illustrates hang).

mattp@macattack:~ $ echo 'echo -e "$TS\t${TERM_SESSION_ID}\t$(pwd)\t$(history 1 | cut -c 8-)\n" >> $HOME/.history/history-$(date "+%Y-%m-%d")-${USER}.log;'  | sed 's/\n/ /g'
^C-bash: echo: write error: Interrupted system call

mattp@macattack:~ $ echo 'echo -e "$TS\t${TERM_SESSION_ID}\t$(pwd)\t$(history 1 | cut -c 8-)\n" >> $HOME/.history/history-$(date "+%Y-%m-%d")-${USER}.log'  | sed 's/\n/ /g'
echo -e "$TS\t${TERM_SESSION_ID}\t$(pwd)\t$(history 1 | cut -c 8-)\n" >> $HOME/.history/history-$(date "+%Y-%m-%d")-${USER}.log
mattp@macattack:~

I have run out of ideas to troubleshoot this.
The hanging commands run fine on a random centos linux server. The commands ran fine on macos until recently. I've never run into pipe hanging before. I thought maybe it was strange characters in the input causing an issue...but the openssl random string shows otherwise. The ulimits are the same as on another mac that does NOT have this same issue.

mattp@macattack:~ $ ulimit -a
core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
file size               (blocks, -f) unlimited
max locked memory       (kbytes, -l) unlimited
max memory size         (kbytes, -m) unlimited
open files                      (-n) 7168
pipe size            (512 bytes, -p) 1
stack size              (kbytes, -s) 8192
cpu time               (seconds, -t) unlimited
max user processes              (-u) 709
virtual memory          (kbytes, -v) unlimited

Using dtruss on tr it seems to hang on read_nocancel call.

Update

Making progress. Found a comment around hanging and pipe buffer sizes. Stole a test script from here: How big is the pipe buffer?

Running while the problem is happening shows a pipe buffer of 128 bytes. Reboot (problem temporarily goes away) and the pipe buffer is 65536 bytes. See test output below.

So now the question is, why/how is "something" reducing the pipe buffer size on the system.

With problem

$ /bin/bash -c 'for p in {0..18}; do pipe-buffer-test.sh $((2 ** $p)) 0.5; done'
write size:          1; bytes successfully before error: 128
write size:          2; bytes successfully before error: 128
write size:          4; bytes successfully before error: 128
write size:          8; bytes successfully before error: 128
write size:         16; bytes successfully before error: 128
write size:         32; bytes successfully before error: 128
write size:         64; bytes successfully before error: 128
write size:        128; bytes successfully before error: 128
write size:        256; bytes successfully before error: 0
write size:        512; bytes successfully before error: 0
write size:       1024; bytes successfully before error: 0
write size:       2048; bytes successfully before error: 0
write size:       4096; bytes successfully before error: 0
write size:       8192; bytes successfully before error: 0
write size:      16384; bytes successfully before error: 0
write size:      32768; bytes successfully before error: 0
write size:      65536; bytes successfully before error: 0
write size:     131072; bytes successfully before error: 0
write size:     262144; bytes successfully before error: 0

After reboot (problem temporarily gone)

$ /bin/bash -c 'for p in {0..18}; do pipe-buffer-test.sh $((2 ** $p)) 0.5; done'
write size:          1; bytes successfully before error: 65536
write size:          2; bytes successfully before error: 65536
write size:          4; bytes successfully before error: 65536
write size:          8; bytes successfully before error: 65536
write size:         16; bytes successfully before error: 65536
write size:         32; bytes successfully before error: 65536
write size:         64; bytes successfully before error: 65536
write size:        128; bytes successfully before error: 65536
write size:        256; bytes successfully before error: 65536
write size:        512; bytes successfully before error: 65536
write size:       1024; bytes successfully before error: 65536
write size:       2048; bytes successfully before error: 65536
write size:       4096; bytes successfully before error: 65536
write size:       8192; bytes successfully before error: 65536
write size:      16384; bytes successfully before error: 65536
write size:      32768; bytes successfully before error: 65536
write size:      65536; bytes successfully before error: 65536
write size:     131072; bytes successfully before error: 0
write size:     262144; bytes successfully before error: 0
  • I can't reproduce this in Snow Leopard or El Capitan. I suspect something specific to your environment. – Barmar May 22 '17 at 20:19
  • Why do you think it's hanging in the fstat64 call? The trace shows that the call successfully returned 0. It looks like it's hanging in read_nocancel(), it's the one that got interrupted by the signal from Ctl-C. – Barmar May 22 '17 at 20:21
  • It seems like some kind of pipe deadlock. The writing process is blocking because the pipe is full, but for some reason the reading process isn't reading what's in the pipe. – Barmar May 22 '17 at 20:28
  • Do you have the same problem if you use a different shell, such as ksh or zsh? – Barmar May 22 '17 at 20:29
  • I don't understand: why the tr -d '\n' ?? This will just cause some problems with some commands (wc, for exemple, will not count the last line if it is not "\n" terminated, as wc counts words, lines, etc, in unix files, and a file in unix have to have a terminating newline). You may be on a red herring? Try just to add : set -x at the beginning of the .bashrc and see if (and where) it hangs in there? – Olivier Dulac May 23 '17 at 8:43
0

Based on @Barmar's comment about leaking kernel buffers I took a look at the current non-OS kexts. I realized there was a relatively new one from a recent install of BlockBlock (https://objective-see.com/products/blockblock.html).

Uninstalled BlockBlock, restarted and the problem has not recurred. So BlockBlock was the culprit in this case and I reported the issue to the author.

However this isn't particularly satisfying since I took a mostly guess-and-check approach to figuring out the cause and to be honest I don't really understand the root cause (in terms of the OS) which means I am none-the-wiser for troubleshooting this kind of problem in the future.

If someone comes across this and can explain what was happening in more detail and provide a troubleshooting approach, it would be a much better answer than "uninstall BlockBlock".

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.