long output to exec hangs

[knitzsche]

With multipass 0.6.1 752 beta canonical✓ classic

A command with very long output hangs, such as
$ multipass exec vm -- dpkg -l

This gets part way through displaying the long output and then the terminal becomes unresponsive (until stopping the vm).

[Saviq]

Hmm I can't reproduce that @knitzsche, could you please try on the edge channel?

[knitzsche]

@Saviq I tried it with multipass from edge, and it also happens (intermittently, but most times). This time I tried with a very simple snap: I ran snapcraft init, then modified the snapcraft.yaml to have base: core18. then about 2 times in 3 the command result does not fully show and the terminal because unresponsive until I delete the vm (with snapcraft clean or multipass delete)

[Saviq]

@knitzsche so you're seeing this through snapcraft? Care to share the yaml?

I just tried exec directly with journalctl and dmesg and didn't get any hangs…

[knitzsche]

host is xenial. snapcraft.yaml is:

name: test-multipass-issue # you probably want to 'snapcraft register <name>'
base: core16 # the base snap is the execution environment for this snap
version: '0.1' # just for humans, typically '1.2+git' or '1.3.2'
summary: Single-line elevator pitch for your amazing snap # 79 char long summary
base: core16
description: |
  This is my-snap's description. You have a paragraph or two to tell the
  most important story about your snap. Keep it under 100 words though,
  we live in tweetspace and your description wants to look good in the snap
  store.

grade: devel # must be 'stable' to release into candidate/stable channels
confinement: devmode # use 'strict' once you have the right plugs and slots

parts:
  my-part:
    # See 'snapcraft plugins'
    plugin: nil

[Saviq]

It just snapped fine here…

snapcraft
Using 'snapcraft.yaml': Project assets will be searched for from the 'snap' directory.
Launching a VM.
Launched: snapcraft-test-multipass-issue                                        
2019-05-09T21:26:11Z INFO Waiting for restart...
core 16-2.38.1 from Canonical✓ installed
snapcraft 3.4.1 from Canonical✓ installed
core16 16-20190110 from Canonical✓ installed
Hit:1 http://archive.ubuntu.com/ubuntu xenial InRelease
Hit:2 http://archive.ubuntu.com/ubuntu xenial-updates InRelease                                      
Hit:3 http://archive.ubuntu.com/ubuntu xenial-backports InRelease                                    
Hit:4 http://security.ubuntu.com/ubuntu xenial-security InRelease       
Reading package lists... Done                     
Building dependency tree       
Reading state information... Done
8 packages can be upgraded. Run 'apt list --upgradable' to see them.
Using 'snapcraft.yaml': Project assets will be searched for from the 'snap' directory.
Pulling my-part 
Building my-part 
Staging my-part 
Priming my-part 
Snapping 'test-multipass-issue' |                                                                                                                                                                                              
Snapped test-multipass-issue_0.1_amd64.snap

My host is disco, though, wonder if that somehow affects you… When it does hang, could you try and attach gdb to it and see where it's stuck? Thanks!

[knitzsche]

snapping works. What does not work reliably is getting long output from multipass: $ multipass exec vm -- dpkg -l

…

On Thu, May 9, 2019 at 5:29 PM Michał Sawicz ***@***.***> wrote: It just snapped fine here… snapcraft Using 'snapcraft.yaml': Project assets will be searched for from the 'snap' directory. Launching a VM. Launched: snapcraft-test-multipass-issue 2019-05-09T21:26:11Z INFO Waiting for restart... core 16-2.38.1 from Canonical✓ installed snapcraft 3.4.1 from Canonical✓ installed core16 16-20190110 from Canonical✓ installed Hit:1 http://archive.ubuntu.com/ubuntu xenial InRelease Hit:2 http://archive.ubuntu.com/ubuntu xenial-updates InRelease Hit:3 http://archive.ubuntu.com/ubuntu xenial-backports InRelease Hit:4 http://security.ubuntu.com/ubuntu xenial-security InRelease Reading package lists... Done Building dependency tree Reading state information... Done 8 packages can be upgraded. Run 'apt list --upgradable' to see them. Using 'snapcraft.yaml': Project assets will be searched for from the 'snap' directory. Pulling my-part Building my-part Staging my-part Priming my-part Snapping 'test-multipass-issue' | Snapped test-multipass-issue_0.1_amd64.snap My host is disco, though, wonder if that somehow affects you… When it does hang, could you try and attach gdb to it and see where it's stuck? Thanks! — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#772 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ABPAZ63Y5ZFPS2ZTP253NQ3PUSJUVANCNFSM4HLUEFEQ> .

[Saviq]

OK managed to reproduce in the end with a loop:

while multipass exec direct-squeaker -- dpkg -l; do sleep 1; done

It's stuck here, polling ssh:

#0  0x00007f12b5e2a74d in poll () from /snap/core/current/lib/x86_64-linux-gnu/libc.so.6
#1  0x00007f12b758acb5 in poll (__timeout=<optimized out>, __nfds=<optimized out>, __fds=<optimized out>) at /usr/include/x86_64-linux-gnu/bits/poll2.h:46                                                                                   
#2  ssh_poll (fds=<optimized out>, nfds=<optimized out>, timeout=<optimized out>) at /root/parts/multipass/src/3rd-party/libssh/libssh/src/poll.c:96                                                                                         
#3  0x00007f12b758b068 in ssh_poll_ctx_dopoll (ctx=0x20ea2e0, timeout=timeout@entry=60000) at /root/parts/multipass/src/3rd-party/libssh/libssh/src/poll.c:679                                                                               
#4  0x00007f12b758b3e2 in ssh_event_dopoll (event=event@entry=0x2086c70, timeout=timeout@entry=60000) at /root/parts/multipass/src/3rd-party/libssh/libssh/src/poll.c:962                                                                    
#5  0x00000000005a593a in multipass::SSHClient::handle_ssh_events (this=0x7ffcdbe80a40) at /root/parts/multipass/src/src/ssh/ssh_client.cpp:95                                                                                               
#6  0x00000000005a5cd4 in multipass::SSHClient::exec (this=this@entry=0x7ffcdbe80a40, args=...) at /root/parts/multipass/src/src/ssh/ssh_client.cpp:65                                                                                       
#7  0x00000000005833f3 in multipass::cmd::Exec::exec_success (reply=..., args=..., term=0x20774f0) at /root/parts/multipass/src/src/client/cmd/exec.cpp:80                                                                                   
#8  0x0000000000583da8 in multipass::cmd::Exec::<lambda(multipass::SSHInfoReply&)>::operator() (reply=..., __closure=0x7ffcdbe81000) at /root/parts/multipass/src/src/client/cmd/exec.cpp:40                                                 
#9  multipass::cmd::Command::dispatch<std::unique_ptr<grpc::ClientReader<multipass::SSHInfoReply> > (multipass::Rpc::Stub::*&)(grpc::ClientContext*, const multipass::SSHInfoRequest&), multipass::SSHInfoRequest, multipass::cmd::Exec::run(multipass::ArgParser*)::<lambda(multipass::SSHInfoReply&)>&, multipass::cmd::Exec::run(multipass::ArgParser*)::<lambda(grpc::Status&)>&, multipass::cmd::Command::dispatch(RpcFunc&&, const Request&, SuccessCallable&&, FailureCallable&&) [with RpcFunc = std::unique_ptr<grpc::ClientReader<multipass::SSHInfoReply> > (multipass::Rpc::Stub::*)(grpc::ClientContext*, const multipass::SSHInfoRequest&); Request = multipass::SSHInfoRequest; SuccessCallable = multipass::cmd::Exec::run(multipass::ArgParser*)::<lambda(multipass::SSHInfoReply&)>&; FailureCallable = multipass::cmd::Exec::run(multipass::ArgParser*)::<lambda(grpc::Status&)>&]::<lambda(ReplyType&)> >(std::unique_ptr<grpc::ClientReader<multipass::SSHInfoReply>, std::default_delete<grpc::ClientReader<multipass::SSHInfoReply> > > (multipass::Rpc::Stub::*&)(multipass::Rpc::Stub * const, grpc::ClientContext *, const multipass::SSHInfoRequest &), const multipass::SSHInfoRequest &, multipass::cmd::Exec::<lambda(multipass::SSHInfoReply&)> &, multipass::cmd::Exec::<lambda(grpc::Status&)> &, multipass::cmd::Command::<lambda(ReplyType&)> &&) (this=<optimized out>, rpc_func=                                                              
    @0x7ffcdbe81010: (std::unique_ptr<grpc::ClientReader<multipass::SSHInfoReply>, std::default_delete<grpc::ClientReader<multipass::SSHInfoReply> > > (multipass::Rpc::Stub::*)(multipass::Rpc::Stub * const, grpc::ClientContext *, const multipass::SSHInfoRequest &)) 0x56b020 <multipass::Rpc::Stub::ssh_info(grpc::ClientContext*, multipass::SSHInfoRequest const&)>, request=..., on_success=..., on_failure=..., streaming_callback=..., this=<optimized out>,                    
    this=<optimized out>, this=<optimized out>, this=<optimized out>, this=<optimized out>, this=<optimized out>, this=<optimized out>, this=<optimized out>, this=<optimized out>, this=<optimized out>, this=<optimized out>,              
    this=<optimized out>, this=<optimized out>, this=<optimized out>, this=<optimized out>) at /root/parts/multipass/src/include/multipass/cli/command.h:88                                                                                  
#10 0x0000000000584654 in multipass::cmd::Command::dispatch<std::unique_ptr<grpc::ClientReader<multipass::SSHInfoReply> > (multipass::Rpc::Stub::*)(grpc::ClientContext*, const multipass::SSHInfoRequest&), multipass::SSHInfoRequest, multipass::cmd::Exec::run(multipass::ArgParser*)::<lambda(multipass::SSHInfoReply&)>&, multipass::cmd::Exec::run(multipass::ArgParser*)::<lambda(grpc::Status&)>&> (on_failure=..., on_success=..., request=..., rpc_func=                         
    @0x7ffcdbe81010: (std::unique_ptr<grpc::ClientReader<multipass::SSHInfoReply>, std::default_delete<grpc::ClientReader<multipass::SSHInfoReply> > > (multipass::Rpc::Stub::*)(multipass::Rpc::Stub * const, grpc::ClientContext *, const multipass::SSHInfoRequest &)) 0x56b020 <multipass::Rpc::Stub::ssh_info(grpc::ClientContext*, multipass::SSHInfoRequest const&)>, this=0x20ae500) at /root/parts/multipass/src/include/multipass/cli/command.h:127                              
#11 multipass::cmd::Exec::run (this=0x20ae500, parser=0x7ffcdbe810d0) at /root/parts/multipass/src/src/client/cmd/exec.cpp:45                                                                                                                
#12 0x00000000005529c3 in multipass::Client::run (this=this@entry=0x7ffcdbe811d0, arguments=...) at /root/parts/multipass/src/src/client/client.cpp:128                                                                                      
#13 0x000000000054d8fc in main (argc=6, argv=<optimized out>) at /root/parts/multipass/src/src/client/main.cpp:64

FWIW it's just the client that's stuck, pkill multipass makes it go away.

[Saviq]

This may also be related to #667.

[gerboland]

I can reproduce this issue, the multipass console occasionally hangs mid-print of a long command output. Some form of input is required to make it resume printing (i.e. any key press).

I cannot reproduce the same issue when using openssh client into the VM.

My suspicion is libssh because as far as I can tell, nothing has actually hung (the backtrace above is perfectly normal), but the to-be-printed text is in a buffer which is neglected. libssh is fdoing all the work of creating the PTY, polling FDs and copying buffers between them. Investigation still ongoing.