Possibly an issue while executing gotemplate via ssh exec channel #175

anticootheone · 2022-04-08T13:58:20Z

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... =\

The text was updated successfully, but these errors were encountered:

MrEcco · 2022-05-11T11:11:57Z

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 · 2022-05-11T11:13:17Z

The simplest way to reproduce this bug:

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

anticootheone changed the title ~~Possibly issue while executing gotemplate via ssh exec channel~~ Possibly an issue while executing gotemplate via ssh exec channel Apr 8, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Possibly an issue while executing gotemplate via ssh exec channel #175

Possibly an issue while executing gotemplate via ssh exec channel #175

anticootheone commented Apr 8, 2022 •

edited

Loading

MrEcco commented May 11, 2022

MrEcco commented May 11, 2022

Possibly an issue while executing gotemplate via ssh exec channel #175

Possibly an issue while executing gotemplate via ssh exec channel #175

Comments

anticootheone commented Apr 8, 2022 • edited Loading

MrEcco commented May 11, 2022

MrEcco commented May 11, 2022

anticootheone commented Apr 8, 2022 •

edited

Loading