bug#41625: [PATCH v2] offload: Handle a possible EOF response from read-repl-response.

[Ludovic Courtès]

Hi Maxim,

Maxim Cournoyer <maxim.cournoyer@gmail.com> skribis:

> My previous strace output didn't follow the 'clone' syscall; the one
> attached does.  It's compressed with lzip.

--8<---------------cut here---------------start------------->8---
11457 sendto(3, "<86>May 27 19:03:45 sshd[11457]: pam_unix(sshd:session): 
session opened for user maxim by (uid=0)", 97, MSG_NOSIGNAL, NULL, 0) = 97
11457 socketpair(AF_UNIX, SOCK_STREAM, 0, [5, 7]) = 0
11457 fcntl(5, F_SETFD, FD_CLOEXEC)     = 0
11457 fcntl(7, F_SETFD, FD_CLOEXEC)     = 0
11457 clone(child_stack=NULL, 
flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD <unfinished ...>
11459 set_robust_list(0xffff9d2e10f0, 24 <unfinished ...>
11457 <... clone resumed>, child_tidptr=0xffff9d2e10e0) = 11459

[…]

11459 clone(child_stack=NULL, 
flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD <unfinished ...>
11460 set_robust_list(0xffff9d2e10f0, 24 <unfinished ...>
11459 <... clone resumed>, child_tidptr=0xffff9d2e10e0) = 11460

[…]

11460 
execve("/gnu/store/6b5gnpnbi73l0pasan0fip4w3f1afizi-bash-5.0.16/bin/bash", 
["bash", "-c", "guix repl -t machine"], 0xaaaacfb78470 /* 16 vars */) = 0

[…]

11460 <... read resumed>"(use-modules (gnu))\n", 4096) = 20

[…]

11459 read(4, "", 16384)                = 0
11459 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
11459 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
11459 close(11)                         = 0
11459 close(10)                         = 0
11459 close(13)                         = 0
11459 close(4)                          = 0
11459 brk(0xaaaacfba7000)               = 0xaaaacfba7000
11459 write(5, "\0\0\0\0012", 5)        = 5
11457 <... ppoll resumed>)              = 1 ([{fd=7, revents=POLLIN}])
11459 exit_group(0 <unfinished ...>

[…]

11457 sendto(3, "<86>May 27 19:04:08 sshd[11457]: pam_unix(sshd:session): 
session closed for user maxim", 86, MSG_NOSIGNAL, NULL, 0) = 86

[…]

11460 openat(AT_FDCWD, 
"/gnu/store/83vzpl9pl5v86ncb8jy2gbfgsac0amjv-guix-module-union/lib/guile/3.0/site-ccache/gnu/packages/mtools.go",
 O_RDONLY|O_CLOEXEC) = 14
11460 lseek(14, 0, SEEK_END)            = 72707
11460 mmap(NULL, 72707, PROT_READ, MAP_PRIVATE, 14, 0) = 0xffff90194000
11460 close(14)                         = 0
11460 mprotect(0xffff901a4000, 3432, PROT_READ|PROT_WRITE) = 0
11460 newfstatat(AT_FDCWD, 
"/gnu/store/83vzpl9pl5v86ncb8jy2gbfgsac0amjv-guix-module-union/share/guile/site/3.0/gnu/packages/patches/u-boot-rockchip-inno-usb.patch",
 {st_mode=S_IFREG|0444, st_size=10450, ...}, 0) = 0
11460 write(1, "(values (non-self-quoting 2052 \"#<unspecified>\"))\n", 50) = 
-1 EPIPE (Broken pipe)
11460 --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=11460, 
si_uid=30013} ---
--8<---------------cut here---------------end--------------->8---

(‘guix repl’ is PID 11460.)

It looks like the SSH session gets closed while ‘guix repl’ is still
running, and thus the client never sees the reply from ‘guix repl’
(‘guix repl’ itself eventually gets EPIPE because its parent process
terminated and there’s no one listening to it.)

So the bug may be on the client side, in ‘guix offload’, which for some
reason drops the session too early.  Can you enable libssh debugging
there, reproduce the problem, and share the libssh debug info from that
run?

Do enable libssh debugging, you can drop something like this in (guix
scripts offload) for instance:

  (use-modules (ssh log))
  (set-log-verbosity! 'protocol)

The available logging levels, from Guile-SSH’s log.c, are:

--8<---------------cut here---------------start------------->8---
struct symbol_mapping log_verbosity[] = {
  /* 0, No logging at all */
  { "nolog",              SSH_LOG_NOLOG     },
  /* 1, Only rare and noteworthy events */
  { "rare",               SSH_LOG_RARE      },
  /* 2, High level protocol information */
  { "protocol",           SSH_LOG_PROTOCOL  },
  /* 3, Lower level protocol infomations, packet level */
  { "packet",             SSH_LOG_PACKET    },
  /* 4, Every function path */
  { "functions",          SSH_LOG_FUNCTIONS },
  { NULL,                 -1                }
};
--8<---------------cut here---------------end--------------->8---

HTH!

Ludo’.