[Locked] macOS runner can't handle `yes |` #2352

kousu · 2020-12-25T10:08:44Z

kousu
Dec 25, 2020

In several scripts I help maintain we use yes | something in order to make something non-interactive; I I know it's not good modern practice but it's there and I have to deal with it for the time being.

I've been porting our CI to Actions and discovered that this construction fails on macos-latest. It's really bizarre. something will run to completion but then the job will hang indefinitely.

Example

I've made a minimal test case here: https://github.com/kousu/hanging-actions/. It basically just tests:

yes | head -n 7

plus collecting some context for debugging.

The symptom is that the Linux builds finish immediately while the macOS build hangs in yellow forever:

For example, on this Actions Workflow and this this Travis script for comparison, everything finishes in about a minute except for Actions-macOS.

Actions Ubuntu: https://github.com/kousu/hanging-actions/runs/1608143472 actions-ubuntu.txt
Actions macOS: https://github.com/kousu/hanging-actions/runs/1608143479 (hung) actions-macos.txt
Actions CentOS: https://github.com/kousu/hanging-actions/runs/1608143484 actions-centos.txt
Travis Ubuntu: https://travis-ci.com/github/kousu/hanging-actions/jobs/464777666 travis-ubuntu.txt
Travis macOS: https://travis-ci.com/github/kousu/hanging-actions/jobs/464777667 travis-macos.txt

This should only take a moment; e.g. on Travis, 20s:

but on Actions it's at 3 minutes and counting:

Debugging

I've figured out enough to guess that yes is refusing to quit even though head has closed its stdin. But why?

diffing the logs

Travis and Actions use slightly different log formats -- and they set $PS4 differently and have different ideas about when to use \rs -- but we can clean that all up with shell gunk:

# tr kills DOS line endings
# awk filters for only lines after a given keyword
# cut kills off Github's timestamp prefixes
diff -u \
  <(cat travis-macos.txt | 
         tr -d '\r' |
         awk 'BEGIN { P=0 } /\+ echo/ { P = 1 } P==1 { print }' |
         tee travis-macos.cleaned.txt
    ) \
  <(cat actions-macos.txt |
        tr -d '\r' |
        cut -f 2- -d ' ' |
        awk 'BEGIN { P=0 } /\+ echo/ { P = 1 } P==1 { print }' |
        tee actions-macos.cleaned.txt
    )

(
Intermediates, for orienting yourself if you take a look; there's a lot of output!:

)

full diff

(- is Travis, + is Actions here)

--- /dev/fd/63	2020-12-25 04:53:46.691750457 -0500
+++ /dev/fd/62	2020-12-25 04:53:46.691750457 -0500
@@ -5,15 +5,15 @@
 + echo --------
 --------
 + uname -a
-Darwin Traviss-Mac.local 19.6.0 Darwin Kernel Version 19.6.0: Mon Aug 31 22:12:52 PDT 2020; root:xnu-6153.141.2~1/RELEASE_X86_64 x86_64
+Darwin Mac-1608887842659.local 19.6.0 Darwin Kernel Version 19.6.0: Thu Oct 29 22:56:45 PDT 2020; root:xnu-6153.141.2.2~1/RELEASE_X86_64 x86_64
 + whoami
-travis
+runner
 + set
-ANSI_CLEAR='\033[0K'
-ANSI_GREEN='\033[32;1m'
-ANSI_RED='\033[31;1m'
-ANSI_RESET='\033[0m'
-ANSI_YELLOW='\033[33;1m'
+AGENT_TOOLSDIRECTORY=/Users/runner/hostedtoolcache
+ANDROID_HOME=/Users/runner/Library/Android/sdk
+ANDROID_NDK_18R_PATH=/Users/runner/Library/Android/sdk/ndk/18.1.5063045
+ANDROID_NDK_HOME=/Users/runner/Library/Android/sdk/ndk-bundle
+ANDROID_SDK_ROOT=/Users/runner/Library/Android/sdk
 BASH=/bin/bash
 BASH_ARGC=()
 BASH_ARGV=()
@@ -21,106 +21,100 @@
 BASH_SOURCE=([0]="./test.sh")
 BASH_VERSINFO=([0]="3" [1]="2" [2]="57" [3]="1" [4]="release" [5]="x86_64-apple-darwin19")
 BASH_VERSION='3.2.57(1)-release'
+BOOTSTRAP_HASKELL_NONINTERACTIVE=1
+CHROMEWEBDRIVER=/usr/local/Caskroom/chromedriver/87.0.4280.20
 CI=true
-CONTINUOUS_INTEGRATION=true
-DEBIAN_FRONTEND=noninteractive
+CONDA=/usr/local/miniconda
 DIRSTACK=()
-DISPLAY=/private/tmp/com.apple.launchd.22HnXAfEhM/org.macosforge.xquartz:0
+DOTNET_MULTILEVEL_LOOKUP=0
+DOTNET_ROOT=/Users/runner/.dotnet
+EDGEWEBDRIVER=/usr/local/share/edge_driver
 EUID=501
-GEM_HOME=/Users/travis/.rvm/gems/ruby-2.6.6
-GEM_PATH=/Users/travis/.rvm/gems/ruby-2.6.6:/Users/travis/.rvm/gems/ruby-2.6.6@global
-GIT_ASKPASS=echo
+GECKOWEBDRIVER=/usr/local/opt/geckodriver/bin
+GITHUB_ACTION=run
+GITHUB_ACTIONS=true
+GITHUB_ACTION_REF=
+GITHUB_ACTION_REPOSITORY=
+GITHUB_ACTOR=kousu
+GITHUB_API_URL=https://api.github.com
+GITHUB_BASE_REF=
+GITHUB_ENV=/Users/runner/work/_temp/_runner_file_commands/set_env_6ae3b7b2-45b8-4c53-8a92-21771c0328f6
+GITHUB_EVENT_NAME=push
+GITHUB_EVENT_PATH=/Users/runner/work/_temp/_github_workflow/event.json
+GITHUB_GRAPHQL_URL=https://api.github.com/graphql
+GITHUB_HEAD_REF=
+GITHUB_JOB=test
+GITHUB_PATH=/Users/runner/work/_temp/_runner_file_commands/add_path_6ae3b7b2-45b8-4c53-8a92-21771c0328f6
+GITHUB_REF=refs/heads/trunk
+GITHUB_REPOSITORY=kousu/hanging-actions
+GITHUB_REPOSITORY_OWNER=kousu
+GITHUB_RETENTION_DAYS=90
+GITHUB_RUN_ID=443835833
+GITHUB_RUN_NUMBER=18
+GITHUB_SERVER_URL=https://github.com
+GITHUB_SHA=9357e35e8d52329e61ba761c2f62ea6359217d21
+GITHUB_WORKFLOW=CI
+GITHUB_WORKSPACE=/Users/runner/work/hanging-actions/hanging-actions
 GROUPS=()
-HAS_JOSH_K_SEAL_OF_APPROVAL=true
-HOME=/Users/travis
-HOMEBREW_NO_INSTALL_CLEANUP=1
-HOSTNAME=Traviss-Mac.local
+HOME=/Users/runner
+HOMEBREW_CASK_OPTS=--no-quarantine
+HOMEBREW_NO_AUTO_UPDATE=1
+HOSTNAME=Mac-1608887842659.local
 HOSTTYPE=x86_64
 IFS=$' \t\n'
-IRBRC=/Users/travis/.rvm/rubies/ruby-2.6.6/.irbrc
+ImageOS=macos1015
+ImageVersion=20201212.1
+JAVA_HOME=/Library/Java/JavaVirtualMachines/adoptopenjdk-8.jdk/Contents/Home
+JAVA_HOME_11_X64=/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home
+JAVA_HOME_12_X64=/Library/Java/JavaVirtualMachines/adoptopenjdk-12.jdk/Contents/Home
+JAVA_HOME_13_X64=/Library/Java/JavaVirtualMachines/adoptopenjdk-13.jdk/Contents/Home
+JAVA_HOME_14_X64=/Library/Java/JavaVirtualMachines/adoptopenjdk-14.jdk/Contents/Home
+JAVA_HOME_7_X64=/Library/Java/JavaVirtualMachines/zulu-7.jdk/Contents/Home
+JAVA_HOME_8_X64=/Library/Java/JavaVirtualMachines/adoptopenjdk-8.jdk/Contents/Home
 LANG=en_US.UTF-8
 LC_ALL=en_US.UTF-8
-LOGNAME=travis
+LC_CTYPE=en_US.UTF-8
+LOGNAME=runner
 MACHTYPE=x86_64-apple-darwin19
-MY_RUBY_HOME=/Users/travis/.rvm/rubies/ruby-2.6.6
-NVM_BIN=/Users/travis/.nvm/versions/node/v15.1.0/bin
+NUNIT3_PATH=/Library/Developer/nunit/3.6.0
+NUNIT_BASE_PATH=/Library/Developer/nunit
 NVM_CD_FLAGS=
-NVM_DIR=/Users/travis/.nvm
-NVM_INC=/Users/travis/.nvm/versions/node/v15.1.0/include/node
+NVM_DIR=/Users/runner/.nvm
 OPTERR=1
 OPTIND=1
 OSTYPE=darwin19
-PAGER=cat
-PATH=/Users/travis/.rvm/gems/ruby-2.6.6/bin:/Users/travis/.rvm/gems/ruby-2.6.6@global/bin:/Users/travis/.rvm/rubies/ruby-2.6.6/bin:/Users/travis/.rvm/bin:/Users/travis/bin:/Users/travis/.local/bin:/Users/travis/.nvm/versions/node/v15.1.0/bin:/usr/local/bin:/usr/bin:/bin:/usr/sbin:/sbin:/opt/X11/bin:/Library/Apple/usr/bin
+PATH=/usr/local/opt/pipx_bin:/Users/runner/.cargo/bin:/usr/local/lib/ruby/gems/2.7.0/bin:/usr/local/opt/ruby/bin:/usr/local/opt/curl/bin:/usr/local/bin:/usr/local/sbin:/Users/runner/bin:/Users/runner/.yarn/bin:/usr/local/go/bin:/Users/runner/Library/Android/sdk/tools:/Users/runner/Library/Android/sdk/platform-tools:/Users/runner/Library/Android/sdk/ndk-bundle:/Library/Frameworks/Mono.framework/Versions/Current/Commands:/usr/bin:/bin:/usr/sbin:/sbin:/Users/runner/.dotnet/tools:/Users/runner/.ghcup/bin:/Users/runner/hostedtoolcache/stack/2.5.1/x64
+PERFLOG_LOCATION_SETTING=RUNNER_PERFLOG
 PIPESTATUS=([0]="0")
-PPID=1186
+PIPX_BIN_DIR=/usr/local/opt/pipx_bin
+PIPX_HOME=/usr/local/opt/pipx
+POWERSHELL_DISTRIBUTION_CHANNEL=GitHub-Actions-macos1015
+PPID=1125
 PS4='+ '
-PWD=/Users/travis/build/kousu/hanging-actions
-RUBY_VERSION=ruby-2.6.6
+***
+RCT_NO_LAUNCH_PACKAGER=1
+RUNNER_OS=macOS
+RUNNER_PERFLOG=/usr/local/opt/runner/perflog
+RUNNER_TEMP=/Users/runner/work/_temp
+RUNNER_TOOL_CACHE=/Users/runner/hostedtoolcache
+RUNNER_TRACKING_ID=github_577b5a7a-3c20-4a28-87fa-761ca1468d79
+RUNNER_WORKSPACE=/Users/runner/work/hanging-actions
 SHELL=/bin/bash
 SHELLOPTS=braceexpand:hashall:interactive-comments:xtrace
-SHLVL=2
-SSH_AUTH_SOCK=/private/tmp/com.apple.launchd.OrS36HPkaE/Listeners
-TERM=xterm
-TMPDIR=/var/folders/z3/_825pg0s3jvf0hb_q8kzmg5h0000gn/T/
-TRAVIS=true
-TRAVIS_ALLOW_FAILURE=
-TRAVIS_APP_HOST=build.travis-ci.com
-TRAVIS_APT_PROXY=http://build-cache.travisci.net
-TRAVIS_ARCH=amd64
-TRAVIS_BRANCH=trunk
-TRAVIS_BUILD_DIR=/Users/travis/build/kousu/hanging-actions
-TRAVIS_BUILD_ID=210564868
-TRAVIS_BUILD_NUMBER=16
-TRAVIS_BUILD_STAGE_NAME=
-TRAVIS_BUILD_WEB_URL=https://travis-ci.com/kousu/hanging-actions/builds/210564868
-TRAVIS_CMD=./test.sh
-TRAVIS_COMMIT=9357e35e8d52329e61ba761c2f62ea6359217d21
-TRAVIS_COMMIT_MESSAGE='Demonstrate hanging on Github'\''s macOS VMs'
-TRAVIS_COMMIT_RANGE=5846aac52ee9...9357e35e8d52
-TRAVIS_CPU_ARCH=amd64
-TRAVIS_DIST=notset
-TRAVIS_ENABLE_INFRA_DETECTION=true
-TRAVIS_EVENT_TYPE=push
-TRAVIS_HOME=/Users/travis
-TRAVIS_INFRA=macstadium
-TRAVIS_INIT=notset
-TRAVIS_INTERNAL_RUBY_REGEX='^ruby-(2\.[0-4]\.[0-9]|1\.9\.3)'
-TRAVIS_JOB_ID=464777667
-TRAVIS_JOB_NAME='OSX 10.15 (Catalina)'
-TRAVIS_JOB_NUMBER=16.2
-TRAVIS_JOB_WEB_URL=https://travis-ci.com/kousu/hanging-actions/jobs/464777667
-TRAVIS_LANGUAGE=ruby
-TRAVIS_OSX_IMAGE=xcode12.2
-TRAVIS_OS_NAME=osx
-TRAVIS_PULL_REQUEST=false
-TRAVIS_PULL_REQUEST_BRANCH=
-TRAVIS_PULL_REQUEST_SHA=
-TRAVIS_PULL_REQUEST_SLUG=
-TRAVIS_REPO_SLUG=kousu/hanging-actions
-TRAVIS_ROOT=/
-TRAVIS_RUBY_VERSION=default
-TRAVIS_SECURE_ENV_VARS=false
-TRAVIS_SUDO=true
-TRAVIS_TAG=
-TRAVIS_TEST_RESULT=
-TRAVIS_TIMER_ID=072d0238
-TRAVIS_TIMER_START_TIME=1608888989287773000
-TRAVIS_TMPDIR=/var/folders/z3/_825pg0s3jvf0hb_q8kzmg5h0000gn/T/tmp.qhZht3j7
+SHLVL=3
+SSH_AUTH_SOCK=/private/tmp/com.apple.launchd.r8ce0Aj0d6/Listeners
+TERM=dumb
+TMPDIR=/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/
 UID=501
-USER=travis
+USER=runner
+VCPKG_INSTALLATION_ROOT=/usr/local/share/vcpkg
+XCODE_10_DEVELOPER_DIR=/Applications/Xcode_10.3.app/Contents/Developer
+XCODE_11_DEVELOPER_DIR=/Applications/Xcode_11.7.app/Contents/Developer
+XCODE_12_DEVELOPER_DIR=/Applications/Xcode_12.3.app/Contents/Developer
 XPC_FLAGS=0x0
 XPC_SERVICE_NAME=0
 _=whoami
-__CF_USER_TEXT_ENCODING=0x1F5:0x0:0x0
-rvm_bin_path=/Users/travis/.rvm/bin
-rvm_path=/Users/travis/.rvm
-rvm_prefix=/Users/travis
-rvm_version='1.29.9 (latest)'
-shell_session_update () 
-{ 
-    :
-}
+__CF_USER_TEXT_ENCODING=0x1F5:0:0
 + echo
 
 + echo Test:
@@ -138,9 +132,15 @@
 y
 y
 y
-+ echo 'Great, I see you'\''re finished.'
-Great, I see you're finished.
-travis_time:end:072d0238:start=1608888989287773000,finish=1608888989436442000,duration=148669000,event=script�[0K�[32;1mThe command "./test.sh" exited with 0.�[0m
-
-
-Done. Your build exited with 0.
+##[error]The operation was canceled.
+Post job cleanup.
+[command]/usr/local/bin/git version
+git version 2.29.2
+[command]/usr/local/bin/git config --local --name-only --get-regexp core\.sshCommand
+[command]/usr/local/bin/git submodule foreach --recursive git config --local --name-only --get-regexp 'core\.sshCommand' && git config --local --unset-all 'core.sshCommand' || :
+[command]/usr/local/bin/git config --local --name-only --get-regexp http\.https\:\/\/github\.com\/\.extraheader
+http.https://github.com/.extraheader
+[command]/usr/local/bin/git config --local --unset-all http.https://github.com/.extraheader
+[command]/usr/local/bin/git submodule foreach --recursive git config --local --name-only --get-regexp 'http\.https\:\/\/github\.com\/\.extraheader' && git config --local --unset-all 'http.https://github.com/.extraheader' || :
+Cleaning up orphan processes
+Terminate orphan process: pid (1129) (yes)

Points in this diff that stand out to me:

The VMs are separated by 2 months of updates.

-Darwin Traviss-Mac.local 19.6.0 Darwin Kernel Version 19.6.0: Mon Aug 31 22:12:52 PDT 2020; root:xnu-6153.141.2~1/RELEASE_X86_64 x86_64
+Darwin Mac-1608887842659.local 19.6.0 Darwin Kernel Version 19.6.0: Thu Oct 29 22:56:45 PDT 2020; root:xnu-6153.141.2.2~1/RELEASE_X86_64 x86_64

Indeed, yes is refusing to die like I thought:

+Terminate orphan process: pid (1129) (yes)

Github has TERM=dumb set? As in, not TERM=xterm like Travis. TERM often messes up interactive scripts, but I don't see why that would affect yes, it's too simple.
Github has LC_CTYPE=en_US.UTF-8 set? But again, why would that matter?

theories

Maybe Github's runner is doing something bizarre with hooking stdout of every subprocess and failing to pass along the broken pipe error to yes?

Workarounds

I can solve most of this by switching to use flags like NONINTERACTIVE=1 for brew, apt-get -y, yum -y, pacman --noconfirm. But it's really bugging me that there's something weird I don't understand about pipes on this specific runner. I'd like to understand!

By the way, I'm a bit unclear if this is the right forum for this. If there's somewhere better I should be directing this please help me find it and I'll totter over there.

Thanks in advance for any insight. I thought I was pretty good with pipes and fds and weird unix corners but this one has me stumped.

maxim-lobanov · 2020-12-25T10:38:50Z

maxim-lobanov
Dec 25, 2020
Maintainer

Hello @kousu ,
Unfortunately, I am not sure about root cause of this behavior but a few thoughts and experiments from my side:

I have login to VM that was generated based on this repository (exact same VM that we deploy to Hosted pools) and everything works as expected on that VM. It took less than seconds to run:

Then I have installed runner to VM and added this machine as self-hosted to my GitHub repo. And added simple YAML:

name: CI
on:
  push:
  workflow_dispatch:
jobs:
  build:
    runs-on: self-hosted
    steps:
      - name: Run a one-line script
        run: |
          yes | head -n 7

And it hangs in the same way:

I think the issue comes from https://github.com/actions/runner because I have confirmed above that VM itself doesn't have such issue.
Probably, it could be some specific, how actions/runner runs commands but I don't have much context with it to dig deeper.

0 replies

maxim-lobanov · 2020-12-25T11:15:41Z

maxim-lobanov
Dec 25, 2020
Maintainer

One more interesting thing is that I can't reproduce it on Azure DevOps.
Azure DevOps uses absolutely same images but azure-pipelines-agent instead of actions/runner.
Since it is not reproducible in Azure DevOps, I think it could be some bug or feature (😄) of actions/runner

0 replies

kousu · 2020-12-25T19:08:39Z

kousu
Dec 25, 2020
Author

Wow, thanks for being as thorough as you could, and on the holidays no less.

Not seeing it on Azure seals the deal for me I think. I'll go file this with https://github.com/actions/runner and wait for someone with more experience to have time to devote to it.

Happy holidays! 🌴 🎋 🎄 🌳 🌲

0 replies

AlenaSviridenko · 2021-02-09T08:07:26Z

AlenaSviridenko
Feb 9, 2021

Locking this convo since the issue is related to the runner, not the image

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[Locked] macOS runner can't handle `yes |` #2352

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 4 comments

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

Select a reply

[Locked] macOS runner can't handle yes | #2352

kousu Dec 25, 2020

Example

Debugging

diffing the logs

theories

Workarounds

Replies: 4 comments

maxim-lobanov Dec 25, 2020 Maintainer

maxim-lobanov Dec 25, 2020 Maintainer

kousu Dec 25, 2020 Author

AlenaSviridenko Feb 9, 2021

[Locked] macOS runner can't handle `yes |` #2352

kousu
Dec 25, 2020

maxim-lobanov
Dec 25, 2020
Maintainer

maxim-lobanov
Dec 25, 2020
Maintainer

kousu
Dec 25, 2020
Author

AlenaSviridenko
Feb 9, 2021