Upgrade from 0.11 to 0.12 break support for interactive shells

[kacperk]

The interactive shells stopped working after updating from 0.11 to 0.12. It works fine for previous versions (before 0.11).

We are using envcosnul to run ruby on rails console for doing some admin and maintenance work on different environments.
Until the update to version 0.12, it worked perfectly fine with envconsul. Version 0.12 breaks the support for any interactive shell - you can reproduce using bash command

Envconsul version

0.12.1

Command

Running any interactive shell

envconsul -once -prefix elk --log-level=debug  bash

Debug output

0.11.0

2022/07/12 07:55:15.319193 [INFO] (runner) running
2022/07/12 07:55:15.319293 [DEBUG] (runner) setting cluster/uuid="tSsnC2QLSy6BpR_LTT4fXQ" from kv.list(elk)
2022/07/12 07:55:15.319340 [INFO] (runner) environment was the same
2022/07/12 07:55:15.319346 [INFO] (runner) running
2022/07/12 07:55:15.319352 [DEBUG] (runner) setting cluster/uuid="tSsnC2QLSy6BpR_LTT4fXQ" from kv.list(elk)
2022/07/12 07:55:15.319363 [INFO] (runner) environment was the same
2022/07/12 07:55:15.319374 [INFO] (cli) subprocess exited
2022/07/12 07:55:15.319378 [INFO] (runner) stopping
2022/07/12 07:55:15.319383 [DEBUG] (runner) stopping watcher
2022/07/12 07:55:15.319389 [DEBUG] (watcher) stopping all views
2022/07/12 07:55:15.319785 [DEBUG] (runner) stopping child process
2022/07/12 07:55:15.319805 [INFO] (child) stopping process
2022/07/12 07:55:15.319813 [DEBUG] (child) Kill() called but process dead; not waiting for splay.
root@docker-desktop:/# envconsul -once -prefix elk --log-level=debug  bash
2022/07/12 07:55:18.692765 [INFO] envconsul v0.11.0 (9f66f6c5)
2022/07/12 07:55:18.692818 [INFO] (runner) creating new runner (once: true)
2022/07/12 07:55:18.693307 [DEBUG] (runner) final config: {"Consul":{"Address":"https://consul.*****.co","Namespace":"","Auth":{"Enabled":false,"Username":"","Password":""},"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true},"SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":false,"Key":"","ServerName":"","Verify":true},"Token":"","Transport":{"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":6,"TLSHandshakeTimeout":10000000000}},"Exec":{"Command":"bash","Enabled":true,"Env":{"Denylist":[],"Custom":[],"Pristine":false,"Allowlist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":0},"KillSignal":2,"LogLevel":"debug","MaxStale":2000000000,"PidFile":"","Prefixes":[{"Format":"","NoPrefix":null,"Path":"elk"}],"Pristine":false,"ReloadSignal":1,"Sanitize":false,"Secrets":[],"Syslog":{"Enabled":false,"Facility":"LOCAL0","Name":""},"Upcase":false,"Vault":{"Address":"","Enabled":false,"Namespace":"","RenewToken":false,"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true},"SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":true,"Key":"","ServerName":"","Verify":true},"Transport":{"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":6,"TLSHandshakeTimeout":10000000000},"UnwrapToken":false},"Wait":{"Enabled":false,"Min":0,"Max":0}}
2022/07/12 07:55:18.693519 [INFO] (runner) creating watcher
2022/07/12 07:55:18.694342 [INFO] (runner) starting
2022/07/12 07:55:18.694414 [DEBUG] (watcher) adding kv.list(elk)
2022/07/12 07:55:19.053981 [DEBUG] (runner) receiving dependency kv.list(elk)
2022/07/12 07:55:19.054008 [INFO] (runner) running
2022/07/12 07:55:19.054038 [DEBUG] (runner) setting cluster/uuid="tSsnC2QLSy6BpR_LTT4fXQ" from kv.list(elk)
2022/07/12 07:55:19.054078 [INFO] (child) spawning: bash
root@docker-desktop:/# env
cluster/uuid=tSsnC2QLSy6BpR_LTT4fXQ
HOSTNAME=docker-desktop
PWD=/
HOME=/root
LS_COLORS=rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:mi=00:su=37;41:sg=30;43:ca=30;41:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.lha=01;31:*.lz4=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t7z=01;31:*.zip=01;31:*.z=01;31:*.dz=01;31:*.gz=01;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.zst=01;31:*.tzst=01;31:*.bz2=01;31:*.bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.alz=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.cab=01;31:*.wim=01;31:*.swm=01;31:*.dwm=01;31:*.esd=01;31:*.jpg=01;35:*.jpeg=01;35:*.mjpg=01;35:*.mjpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.webm=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.cgm=01;35:*.emf=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=00;36:*.au=00;36:*.flac=00;36:*.m4a=00;36:*.mid=00;36:*.midi=00;36:*.mka=00;36:*.mp3=00;36:*.mpc=00;36:*.ogg=00;36:*.ra=00;36:*.wav=00;36:*.oga=00;36:*.opus=00;36:*.spx=00;36:*.xspf=00;36:
TERM=xterm
SHLVL=2
PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
CONSUL_HTTP_ADDR=https://consul.int.lb4.co
_=/usr/bin/env
root@docker-desktop:/# exit
2022/07/12 07:55:24.865012 [INFO] (runner) running
2022/07/12 07:55:24.865115 [DEBUG] (runner) setting cluster/uuid="tSsnC2QLSy6BpR_LTT4fXQ" from kv.list(elk)
2022/07/12 07:55:24.865163 [INFO] (runner) environment was the same
2022/07/12 07:55:24.865172 [DEBUG] (cli) receiving signal "child exited"
2022/07/12 07:55:24.865238 [INFO] (cli) subprocess exited
2022/07/12 07:55:24.865256 [INFO] (runner) stopping
2022/07/12 07:55:24.865261 [DEBUG] (runner) stopping watcher
2022/07/12 07:55:24.865265 [DEBUG] (watcher) stopping all views
2022/07/12 07:55:24.865271 [INFO] (runner) running
2022/07/12 07:55:24.865294 [DEBUG] (runner) setting cluster/uuid="tSsnC2QLSy6BpR_LTT4fXQ" from kv.list(elk)
2022/07/12 07:55:24.865304 [INFO] (runner) environment was the same
2022/07/12 07:55:24.865648 [DEBUG] (runner) stopping child process
2022/07/12 07:55:24.865669 [INFO] (child) stopping process
2022/07/12 07:55:24.865705 [DEBUG] (child) Kill() called but process dead; not waiting for splay.

0.12.1

2022-07-12T08:02:40.742Z [INFO]  v0.12.1 (265f933)
2022-07-12T08:02:40.742Z [INFO] (runner) creating new runner (once: true)
2022-07-12T08:02:40.742Z [DEBUG] (runner) final config: {"Consul":{"Address":"https://consul.******.co","Namespace":"","Auth":{"Enabled":false,"Username":"","Password":""},"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true},"SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":false,"Key":"","ServerName":"","Verify":true},"Token":"","Transport":{"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":6,"TLSHandshakeTimeout":10000000000}},"Exec":{"Command":"bash","Enabled":true,"Env":{"Denylist":[],"Custom":[],"Pristine":false,"Allowlist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":0},"KillSignal":2,"LogLevel":"debug","MaxStale":2000000000,"PidFile":"","Prefixes":[{"Format":"","NoPrefix":null,"Path":"elk","Keys":null}],"Pristine":false,"ReloadSignal":1,"Sanitize":false,"Secrets":[],"Services":[],"Syslog":{"Enabled":false,"Facility":"LOCAL0","Name":"consul-template"},"Upcase":false,"Vault":{"Address":"","Enabled":false,"Namespace":"","RenewToken":false,"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true},"SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":true,"Key":"","ServerName":"","Verify":true},"Transport":{"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":6,"TLSHandshakeTimeout":10000000000},"UnwrapToken":false,"DefaultLeaseDuration":300000000000},"Wait":{"Enabled":false,"Min":0,"Max":0}}
2022-07-12T08:02:40.743Z [INFO] (runner) creating watcher
2022-07-12T08:02:40.744Z [INFO] (runner) starting
2022-07-12T08:02:40.744Z [DEBUG] (watcher) adding kv.list(elk)
2022-07-12T08:02:40.975Z [DEBUG] (cli) receiving signal "urgent I/O condition"
2022-07-12T08:02:40.991Z [DEBUG] (cli) receiving signal "urgent I/O condition"
2022-07-12T08:02:40.993Z [DEBUG] (cli) receiving signal "urgent I/O condition"
2022-07-12T08:02:40.993Z [DEBUG] (cli) receiving signal "urgent I/O condition"
2022-07-12T08:02:40.995Z [DEBUG] (cli) receiving signal "urgent I/O condition"
2022-07-12T08:02:40.995Z [DEBUG] (cli) receiving signal "urgent I/O condition"
2022-07-12T08:02:41.012Z [DEBUG] (cli) receiving signal "urgent I/O condition"
2022-07-12T08:02:41.102Z [DEBUG] (runner) receiving dependency kv.list(elk)
2022-07-12T08:02:41.102Z [INFO] (runner) running
2022-07-12T08:02:41.102Z [DEBUG] (runner) setting cluster/uuid="tSsnC2QLSy6BpR_LTT4fXQ" from kv.list(elk)
2022-07-12T08:02:41.102Z [INFO] (child) spawning: bash
2022-07-12T08:02:41.104Z [DEBUG] (cli) receiving signal "child exited"

test
ls
^C2022-07-12T08:02:48.835Z [DEBUG] (cli) receiving signal "interrupt"
Cleaning up...
2022-07-12T08:02:48.835Z [INFO] (runner) stopping
2022-07-12T08:02:48.835Z [DEBUG] (runner) stopping watcher
2022-07-12T08:02:48.835Z [DEBUG] (watcher) stopping all views
2022-07-12T08:02:48.835Z [DEBUG] (runner) stopping child process
2022-07-12T08:02:48.835Z [INFO] (child) stopping process

Expected behavior

Update to a newer version shouldn't break previous behaviour

Actual behavior

Interactive shell stoped working on update 0.11 -> 0.12

Steps to reproduce

1. Install version 0.11.0
2. Run envconsul -once -prefix elk --log-level=debug bash - works fine (you can replace prefix with any other configuration)
3. Update envconsul to 0.12.1
4. Run envconsul -once -prefix elk --log-level=debug bash - bash doesn't work anymore

[eikenb]

Thanks for the bug report @kacperk! I'm working on envconsul now and will see what I can do about this.

[eikenb]

Seems related to #283

[eikenb]

It looks like this one is caused by the use of setpgid for the command call that was added to ensure signal propagation in consul-template (hashicorp/consul-template@5717544).

It was added due to the change to wrap many commands in 'sh -c [...]' and the setpgid was required to be sure the signals were propagated through that wrapping shell call to the underlying process.

I'll look into ways to mitigate this issue.

[eikenb]

Initial idea is to revisit the setpgid logic in consul-template. It was added as a way to deal with migrating from a bad shell parsing library to just using 'sh -c' around the commands.. to be sure the signals to that wrapping sub-shell were propagated to the command called in it. So the idea is to restrict it to just that case.. if the command is 'sh' and the first arg is '-c' then setpgid, otherwise don't.

Need to think on this a bit though.

[eikenb]

Found more on interactive sub-processes specifically.

Here are 2 related stack overflow questions about setpgid breaking interactive commands on child processes.
https://stackoverflow.com/questions/66627808/using-setpgid-in-a-mini-shell-breaks-interactive-commands
https://stackoverflow.com/questions/29898716/setpgid-makes-interactive-programs-vim-emacs-ncurses-to-infinite-loops

There is a go issue that deals with a bug in how this was implemented (and fixed).
The bug. golang/go#37217
The commit that fixed it. golang/go@7d22c21

[eikenb]

So I've gone down 2 paths.

The first is based on the above. Changing the child call to take setpgid flag and only setting it when the command parser has detected a script like command and wrapped it with sh -c, targeting only the code I originally wanted the setpgid for (to maintain backwards compatibility with signal propagation).

The other path checks that Std{in,out,err} is open and if so adds the Foreground on the command's SysProcAttr struct.

These both fix the problem.

I'm leaning toward the first case as it reduces the number of system flags/calls and should keep things working in a normal manner most of the time without the added overhead of what the side effects of setpgid. Where the second keeps that and adds a new variable, the Foreground flag.

I'm going to start working on the first option. Please chime in if you have any thoughts on this. Thanks!

[eikenb]

PR to consul-template with the require changes up for review.

hashicorp/consul-template#1600

Once merged I'll bump up the envconsul dependency.