Possibly an issue while executing gotemplate via ssh exec channel

[anticootheone]

Hello,

I'm working on the replacement of the other tool to gotemplate as a primary tool to work with golang syntax templates in my project.

In my case, gotemplate usage is wrapped into the python code, where it's called using subprocess.run(). This script is being used in various workflows, including the case, where it called remotely via ssh command execuction channel.

In my recent tests I faced with an issue while working with my script by calling it remotely via ssh: script was failing with rc=1 on the stage when it renders the templates, without templates being rendered on gotemplate exit.

After a bit of debugging, I believe I might have found something strange in gotemplate execution behaviour over ssh exec channel.

There are two cases presented down below with some execution attempts. In both cases gotemplate exited with exit code = 1, but in the second case, when I added -n option to ssh command, it failed, but the templates were rendered (I was thinking there is an issue with fd0/1/2, so I tried -n).

1. First case (quite close to the way how my script called remotely). No templates rendered, exit code = 1:

The command is: ssh -vvvv testhost 'bash -ic "gotemplate --import=/gotemplate_debugging/values.yaml --color --no-razor --internal-log-level=trace --template-log-level=trace /gotemplate_debugging/vars.yaml"'

Snippet of gotemplate strace output:

<... skipped a lot of output stating all the files in ~/ ...> newfstatat(AT_FDCWD, "../../gotemplate_debugging/vars.yaml", {st_mode=S_IFREG|0644, st_size=76, ...}, 0) = 0 read(0, ^^^^^ gotemplate hung on this stage

< I pressed CTRL+C to kill the ssh session>

"", 512) = 0 futex(0x108b098, FUTEX_WAKE_PRIVATE, 1) = 1 futex(0x108af98, FUTEX_WAKE_PRIVATE, 1) = 1 openat(AT_FDCWD, "../../gotemplate_debugging/vars.yaml", O_RDONLY|O_CLOEXEC) = 3 epoll_ctl(4, EPOLL_CTL_ADD, 3, {events=EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET, data={u32=2397536048, u64=140593857003312}}) = -1 EPERM (Operation not permitted) epoll_ctl(4, EPOLL_CTL_DEL, 3, 0xc0000e142c) = -1 EPERM (Operation not permitted) fstat(3, {st_mode=S_IFREG|0644, st_size=76, ...}) = 0 read(3, "fff: {{ .asd }}\n\nasddd:\n json: "..., 512) = 76 read(3, "", 436) = 0 close(3) = 0 write(2, "\33[3;32m[gotemplate-internal] \33[0"..., 133) = -1 EPIPE (Broken pipe) --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=60522, si_uid=1000} --- rt_sigreturn({mask=[]}) = -1 EPIPE (Broken pipe) rt_sigprocmask(SIG_UNBLOCK, [PIPE], NULL, 8) = 0 getpid() = 60522 gettid() = 60522 tgkill(60522, 60522, SIGPIPE) = 0 --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_TKILL, si_pid=60522, si_uid=1000} --- rt_sigaction(SIGPIPE, {sa_handler=SIG_DFL, sa_mask=~[RTMIN RT_1], sa_flags=SA_RESTORER|SA_ONSTACK|SA_RESTART|SA_SIGINFO, sa_restorer=0x7fdeb7352520}, NULL, 8) = 0 rt_sigprocmask(SIG_UNBLOCK, [PIPE], NULL, 8) = 0 getpid() = 60522 gettid() = 60522 tgkill(60522, 60522, SIGPIPE) = 0 --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_TKILL, si_pid=60522, si_uid=1000} --- +++ killed by SIGPIPE +++

Snippet of the ssh debug output:

debug1: Sending command: bash -ic "gotemplate --import=/gotemplate_debugging/platform.yaml --color --no-razor --internal-log-level=trace --template-log-level=trace /gotemplate_debugging/values.yaml" debug2: channel 0: request exec confirm 1 debug3: send packet: type 98 debug2: channel_input_open_confirmation: channel 0: callback done debug2: channel 0: open confirm rwindow 0 rmax 32768 debug2: channel 0: rcvd adjust 2097152 debug3: receive packet: type 99 debug2: channel_input_status_confirm: type 99 id 0 debug2: exec request accepted on channel 0 debug2: channel 0: rcvd ext data 112 bash: cannot set terminal process group (-1): Inappropriate ioctl for device bash: no job control in this shell debug2: channel 0: written 112 to efd 6 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ ssh session hung here

^Cdebug3: send packet: type 1 debug1: channel 0: free: client-session, nchannels 1 debug3: channel 0: status: The following connections are open:

0 client-session (t4 r0 i0/0 o0/0 e[write]/0 fd 4/5/6 sock -1 cc -1)

debug3: fd 1 is not O_NONBLOCK Killed by signal 2.

2. Second case. Exit code = 1, but templates are rendered, behavior changed when I added -n option to the ssh command:

The command is: ssh -n -vvvv testhost 'bash -ic "gotemplate --import=/gotemplate_debugging/values.yaml --color --no-razor --internal-log-level=trace --template-log-level=trace /gotemplate_debugging/vars.yaml"'

Snippet of gotemplate strace output:

<... skipped a lot of output to stat all the files in ~/ ...> newfstatat(AT_FDCWD, "../../gotemplate_debugging/vars.yaml", {st_mode=S_IFREG|0644, st_size=76, ...}, 0) = 0 read(0, "", 512) = 0 openat(AT_FDCWD, "../../gotemplate_debugging/vars.yaml", O_RDONLY|O_CLOEXEC) = 3 epoll_ctl(4, EPOLL_CTL_ADD, 3, {events=EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET, data={u32=2954555376, u64=140366780755952}}) = -1 EPERM (Operation not permitted) epoll_ctl(4, EPOLL_CTL_DEL, 3, 0xc0000e142c) = -1 EPERM (Operation not permitted) fstat(3, {st_mode=S_IFREG|0644, st_size=76, ...}) = 0 read(3, "fff: {{ .asd }}\n\nasddd:\n json: "..., 512) = 76 read(3, "", 436) = 0 close(3) = 0 write(2, "\33[3;32m[gotemplate-internal] \33[0"..., 133) = 133 newfstatat(AT_FDCWD, ".", {st_mode=S_IFDIR|0750, st_size=4096, ...}, 0) = 0 newfstatat(AT_FDCWD, "/home/antic", {st_mode=S_IFDIR|0750, st_size=4096, ...}, 0) = 0 futex(0xc000080150, FUTEX_WAKE_PRIVATE, 1) = 1 openat(AT_FDCWD, "/gotemplate_debugging/ttt.json", O_RDONLY|O_CLOEXEC) = 3 epoll_ctl(4, EPOLL_CTL_ADD, 3, {events=EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET, data={u32=2954555376, u64=140366780755952}}) = -1 EPERM (Operation not permitted) --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=74455, si_uid=1000} --- rt_sigreturn({mask=[]}) = -1 EPERM (Operation not permitted) epoll_ctl(4, EPOLL_CTL_DEL, 3, 0xc0000e0494) = -1 EPERM (Operation not permitted) fstat(3, {st_mode=S_IFREG|0644, st_size=84, ...}) = 0 read(3, "{\n \"dada1\" : [\"asdasdasd\",\n "..., 512) = 84 read(3, "", 428) = 0 close(3) = 0 futex(0xc000080d50, FUTEX_WAKE_PRIVATE, 1) = 1 newfstatat(AT_FDCWD, "../../gotemplate_debugging/vars.yaml", {st_mode=S_IFREG|0644, st_size=76, ...}, 0) = 0 write(2, "\33[3;32m[gotemplate-internal] \33[0"..., 148) = 148 newfstatat(AT_FDCWD, "../../gotemplate_debugging/vars.yaml.original", 0xc0002582a8, AT_SYMLINK_NOFOLLOW) = -1 ENOENT (No such file or directory) renameat(AT_FDCWD, "../../gotemplate_debugging/vars.yaml", AT_FDCWD, "../../gotemplate_debugging/vars.yaml.original") = 0 write(2, "\33[3;32m[gotemplate-internal] \33[0"..., 125) = 125 openat(AT_FDCWD, "/gotemplate_debugging/vars.yaml", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0644) = 3 epoll_ctl(4, EPOLL_CTL_ADD, 3, {events=EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET, data={u32=2954555376, u64=140366780755952}}) = -1 EPERM (Operation not permitted) epoll_ctl(4, EPOLL_CTL_DEL, 3, 0xc0000e1474) = -1 EPERM (Operation not permitted) write(3, "fff: ddd\n\nasddd:\n json: |\n "..., 140) = 140 close(3) = 0 openat(AT_FDCWD, "", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) write(2, "\33[31mopen : no such file or dire"..., 42) = 42 newfstatat(AT_FDCWD, "/usr/local/sbin/terraform", 0xc000258378, 0) = -1 ENOENT (No such file or directory) newfstatat(AT_FDCWD, "/usr/local/bin/terraform", 0xc000258448, 0) = -1 ENOENT (No such file or directory) newfstatat(AT_FDCWD, "/usr/sbin/terraform", 0xc000258518, 0) = -1 ENOENT (No such file or directory) newfstatat(AT_FDCWD, "/usr/bin/terraform", 0xc0002585e8, 0) = -1 ENOENT (No such file or directory) newfstatat(AT_FDCWD, "/sbin/terraform", 0xc0002586b8, 0) = -1 ENOENT (No such file or directory) newfstatat(AT_FDCWD, "/bin/terraform", 0xc000258788, 0) = -1 ENOENT (No such file or directory) newfstatat(AT_FDCWD, "/usr/games/terraform", 0xc000258858, 0) = -1 ENOENT (No such file or directory) newfstatat(AT_FDCWD, "/usr/local/games/terraform", 0xc000258928, 0) = -1 ENOENT (No such file or directory) newfstatat(AT_FDCWD, "/snap/bin/terraform", 0xc0002589f8, 0) = -1 ENOENT (No such file or directory) unlinkat(AT_FDCWD, "/tmp/gotemplate-202352630", 0) = -1 EISDIR (Is a directory) unlinkat(AT_FDCWD, "/tmp/gotemplate-202352630", AT_REMOVEDIR) = 0 exit_group(1) = ? +++ exited with 1 +++

Snippet of the ssh debug output:

debug1: Sending command: bash -ic "gotemplate --import=/gotemplate_debugging/values.yaml --color --no-razor --internal-log-level=trace --template-log-level=trace /gotemplate_debugging/vars.yaml" debug2: channel 0: request exec confirm 1 debug3: send packet: type 98 debug2: channel_input_open_confirmation: channel 0: callback done debug2: channel 0: open confirm rwindow 0 rmax 32768 debug2: channel 0: rcvd adjust 2097152 debug3: receive packet: type 99 debug2: channel_input_status_confirm: type 99 id 0 debug2: exec request accepted on channel 0 debug2: channel 0: read<=0 rfd 4 len 0 debug2: channel 0: read failed debug2: channel 0: chan_shutdown_read (i0 o0 sock -1 wfd 4 efd 6 [write]) debug2: channel 0: input open -> drain debug2: channel 0: ibuf empty debug2: channel 0: send eof debug3: send packet: type 96 debug2: channel 0: input drain -> closed debug2: channel 0: rcvd ext data 112 bash: cannot set terminal process group (-1): Inappropriate ioctl for device bash: no job control in this shell debug2: channel 0: written 112 to efd 6 debug2: channel 0: rcvd ext data 133 [gotemplate-internal] 2022/04/08 12:02:28.574 DEBUG GoTemplate processing of ../../gotemplate_debugging/vars.yaml debug2: channel 0: written 133 to efd 6 debug2: channel 0: rcvd ext data 148 [gotemplate-internal] 2022/04/08 12:02:28.578 INFO ../../gotemplate_debugging/vars.yaml => ../../gotemplate_debugging/vars.yaml.original debug2: channel 0: written 148 to efd 6 debug2: channel 0: rcvd ext data 125 debug2: channel 0: rcvd ext data 42 [gotemplate-internal] 2022/04/08 12:02:28.578 INFO Writing file ../../gotemplate_debugging/vars.yaml open : no such file or directory ^^^^^^^^^^^^^^^^^^^^^^^ note this, no filename in the output debug2: channel 0: written 167 to efd 6 debug3: receive packet: type 96 debug2: channel 0: rcvd eof debug2: channel 0: output open -> drain debug2: channel 0: obuf empty debug2: channel 0: chan_shutdown_write (i3 o1 sock -1 wfd 5 efd 6 [write]) debug2: channel 0: output drain -> closed debug3: receive packet: type 98 debug1: client_input_channel_req: channel 0 rtype exit-status reply 0 debug3: receive packet: type 97 debug2: channel 0: rcvd close debug3: channel 0: will not send data after close debug2: channel 0: almost dead debug2: channel 0: gc: notify user debug2: channel 0: gc: user detached debug2: channel 0: send close debug3: send packet: type 97 debug2: channel 0: is dead debug2: channel 0: garbage collecting debug1: channel 0: free: client-session, nchannels 1 debug3: channel 0: status: The following connections are open:

0 client-session (t4 r0 i3/0 o3/0 e[write]/0 fd -1/-1/6 sock -1 cc -1)

debug3: send packet: type 1 debug3: fd 1 is not O_NONBLOCK Transferred: sent 4396, received 3856 bytes, in 0.6 seconds Bytes per second: sent 6866.3, received 6022.9 debug1: Exit status 1

In the tests gotemplate was executed over these files: vars.yaml:

fff: {{ .asd }}

asddd:
  json: |
    {{ include "ttt.json" . | indent 4 }}

ttt.json:

{
  "dada1" : ["asdasdasd",
             "fafafafafaf",
             "gfgsdgsdg"]
}

values.yaml: asd: ddd

Workaround to the issue (not the great one...): call the script via ssh with -n option and not to handle exit codes of gotemplate in the python code.

There are no issues with executing gotemplate over ssh with --version or list --functions --all arguments.

P.S. Sorry for this mess with debugging info, I'm not good at golang code debugging... =\

[MrEcco]

There is the problem of binding to /proc/self/fd/0 file. gomplate just trying to read from this file and don't solve this error.

The quick solution is here:

• For ssh you can use flag -T:

  ssh -T username@hostname gotemplate --arg --arg --arg

• For complex cases you can try to use popen syscall, for any language this must exists (python: subprocess.Popen class, etc)

[MrEcco]

The simplest way to reproduce this bug:

true | gotemplate --arg --arg --arg 2>&1 | cat