Skip Menu |

This queue is for tickets about the Net-OpenSSH CPAN distribution.

Report information
The Basics
Id: 128658
Status: open
Priority: 0/
Queue: Net-OpenSSH
People
Owner: Nobody in particular
Requestors: avv314 [...] gmail.com
Cc:
AdminCc:
Bug Information
Severity: (no value)
Broken in: (no value)
Fixed in: (no value)

History Show all quoted text
  Wed Feb 27 15:09:16 2019 avv314 [...] gmail.com - Ticket created
Subject: freebsd 11.2 bug
Date: Wed, 27 Feb 2019 23:08:51 +0300
To: bug-Net-OpenSSH [...] rt.cpan.org
From: Andrew Vylegzhanin <avv314 [...] gmail.com>
Hi! I've successfully used Net::OpenSSH for couple years under FeeBSD 9.3-RELEASE. It's simple perl script invoked by propraetry billing system for handling external events by coping files via scp. Here is fragment: open( my $stderr_fh, ">>", $LOGDIR."vg-arcd-ssh.log" ) || warn "Can't log\n"; my $tm = localtime; print $stderr_fh "$tm [$$] \n"; $Net::OpenSSH::debug_fh = $stderr_fh; $Net::OpenSSH::debug = ~0; my $ssh = Net::OpenSSH->new( 'cptctrl@2.2.2.2:8844', default_stderr_fh => $stderr_fh, default_stdout_fh => $stderr_fh, async => 0 ); if( $ssh->error ) { syslog( "Couldn't establish SSH connection: ". $ssh->error ); syslog( "Moving job file to queue" ); rename( $DATADIR.$tmpfile, $DATADIR."jobs/".$tmpfile ); } else { syslog( "DEBUG: before scp" ); $ssh->scp_put( {async => 0, timeout => 10 }, $DATADIR.$tmpfile, "jobs" ) || syslog( "DEBUG: scp failed: " . $ssh->error ); syslog( "DEBUG: after scp" ); if( $ssh->error ) { syslog( "scp_put to remote host failed: ".$ssh->error ); syslog( "Moving job file to queue" ); rename( $DATADIR.$tmpfile, $DATADIR."jobs/".$tmpfile ); } else { syslog( "Copied" ); unlink( $DATADIR.$tmpfile ); } } After upgrading to FreeBSD 11.2-RELEASE I've got following problem: - when I run this script from command line (from bash), everything is ok, always. - when this script invoked from billing system (from FreeBSD process, written on C++ mostly AFAIK), it's perl process ends without errors on OpenSSH->new or after $ssh->scp_put (so sometimes it copied files) Here is debug output from $Net::OpenSSH::debug = ~0 From command line: # open_ex: ['ssh','-V'] # io3 mloop, cin: 0, cout: 1, cerr: 0 # io3 fast, cin: 0, cout: 1, cerr: 0 # stdout, bytes read: 51 at offset 0 #> 4f 70 65 6e 53 53 48 5f 37 2e 35 70 31 2c 20 4f 70 65 6e 53 53 4c 20 31 2e 30 2e 32 6f 2d 66 72 | OpenSSH_7.5p1, OpenSSL 1.0.2o-fr #> 65 65 62 73 64 20 20 32 37 20 4d 61 72 20 32 30 31 38 0a | eebsd 27 Mar 2018. # io3 fast, cin: 0, cout: 1, cerr: 0 # stdout, bytes read: 0 at offset 51 # leaving _io3() # _waitpid(50657) => pid: 50657, rc: 0, err: # OpenSSH version is 7.5p1, # ctl_path: /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, ctl_dir: /root/.libnet-openssh-perl/ # _is_secure_path(dir: /root/.libnet-openssh-perl, file mode: 16832, file uid: 0, euid: 0 # _is_secure_path(dir: /root, file mode: 16877, file uid: 0, euid: 0 # set_error(0 - 0) # call args: ['ssh','-o','ServerAliveInterval=30','-o','ControlPersist=no','-2MNx','-S','/root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb','-l','cptctrl','-p','8844','2.2.2.2','--'] # tracer attached, ssh pid: 50658, tracer pid: 50659 # master state jumping from _STATE_START to _STATE_AWAITING_MUX # file object not yet found at /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, state:_STATE_AWAITING_MUX # file object not yet found at /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, state:_STATE_AWAITING_MUX # file object not yet found at /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, state:_STATE_AWAITING_MUX # file object not yet found at /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, state:_STATE_AWAITING_MUX # file object not yet found at /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, state:_STATE_AWAITING_MUX # file object not yet found at /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, state:_STATE_AWAITING_MUX # file object not yet found at /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, state:_STATE_AWAITING_MUX # file object not yet found at /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, state:_STATE_AWAITING_MUX # file object not yet found at /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, state:_STATE_AWAITING_MUX # file object not yet found at /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, state:_STATE_AWAITING_MUX # file object not yet found at /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, state:_STATE_AWAITING_MUX # file object not yet found at /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, state:_STATE_AWAITING_MUX # file object not yet found at /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, state:_STATE_AWAITING_MUX # file object not yet found at /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, state:_STATE_AWAITING_MUX # file object not yet found at /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, state:_STATE_AWAITING_MUX # file object not yet found at /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, state:_STATE_AWAITING_MUX # file object not yet found at /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, state:_STATE_AWAITING_MUX # file object not yet found at /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, state:_STATE_AWAITING_MUX # file object found at /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb # master state jumping from _STATE_AWAITING_MUX to _STATE_RUNNING # call args: ['ssh','-O','check','-T','-S','/root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb','-l','cptctrl','-p','8844','2.2.2.2','--'] # open_ex: ['ssh','-O','check','-T','-S','/root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb','-l','cptctrl','-p','8844','2.2.2.2 # io3 mloop, cin: 0, cout: 1, cerr: 0 # io3 fast, cin: 0, cout: 1, cerr: 0 # stdout, bytes read: 28 at offset 0 #> 4d 61 73 74 65 72 20 72 75 6e 6e 69 6e 67 20 28 70 69 64 3d 35 30 36 35 38 29 0d 0a | Master running (pid=50658).. # io3 fast, cin: 0, cout: 1, cerr: 0 # stdout, bytes read: 0 at offset 28 # leaving _io3() # _waitpid(50668) => pid: 50668, rc: 0, err: # scp call args: ['scp','-q','-o','ControlPath=/root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb','-S','ssh','-P','8844','--','/prov/tsey/cpt.job.50656r','cptctrl@2.2.2.2: jobs'] # open_ex: ['scp','-q','-o','ControlPath=/root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb','-S','ssh','-P','8844','--','/prov/tsey/cpt.job.50656r','cptctrl@2.2.2.2: jobs'] # _waitpid(50669) => pid: 50669, rc: 0, err: Interrupted system call # DESTROY(Net::OpenSSH=HASH(0x80259f288), pid: 50658) # sending exit control to master # call args: ['ssh','-O','exit','-T','-S','/root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb','-l','cptctrl','-p','8844','2.2.2.2','--'] # open_ex: ['ssh','-O','exit','-T','-S','/root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb','-l','cptctrl','-p','8844','2.2.2.2','--'] # io3 mloop, cin: 0, cout: 1, cerr: 0 # io3 fast, cin: 0, cout: 1, cerr: 0 # stdout, bytes read: 20 at offset 0 #> 45 78 69 74 20 72 65 71 75 65 73 74 20 73 65 6e 74 2e 0d 0a | Exit request sent... # io3 fast, cin: 0, cout: 1, cerr: 0 # stdout, bytes read: 0 at offset 20 # leaving _io3() # _waitpid(50671) => pid: 50671, rc: 0, err: # set_error(1 - aborted) # master state jumping from _STATE_RUNNING to _STATE_KILLING # killing master # _master_kill: 50658 # waitpid(master: 50658) => pid: 0, rc: # waitpid(master: 50658) => pid: 50658, rc: Interrupted system call # master state jumping from _STATE_KILLING to _STATE_GONE Invoked from billing system: # open_ex: ['ssh','-V'] # io3 mloop, cin: 0, cout: 1, cerr: 0 # io3 fast, cin: 0, cout: 1, cerr: 0 # stdout, bytes read: 51 at offset 0 #> 4f 70 65 6e 53 53 48 5f 37 2e 35 70 31 2c 20 4f 70 65 6e 53 53 4c 20 31 2e 30 2e 32 6f 2d 66 72 | OpenSSH_7.5p1, OpenSSL 1.0.2o-fr #> 65 65 62 73 64 20 20 32 37 20 4d 61 72 20 32 30 31 38 0a | eebsd 27 Mar 2018. # io3 fast, cin: 0, cout: 1, cerr: 0 # stdout, bytes read: 0 at offset 51 # leaving _io3() # _waitpid(62488) => pid: 62488, rc: 0, err: # OpenSSH version is 7.5p1, # ctl_path: /root/.libnet-openssh-perl/ca9523a03741dc7955578d7fb1933c0d, ctl_dir: /root/.libnet-openssh-perl/ # _is_secure_path(dir: /root/.libnet-openssh-perl, file mode: 16832, file uid: 0, euid: 0 # _is_secure_path(dir: /root, file mode: 16877, file uid: 0, euid: 0 # set_error(0 - 0) # call args: ['ssh','-o','ServerAliveInterval=30','-o','ControlPersist=no','-2MNx','-S','/root/.libnet-openssh-perl/ca9523a03741dc7955578d7fb1933c0d','-l','cptctrl','-p','8844','2.2.2.2','--'] # tracer attached, ssh pid: 62489, tracer pid: 62490 What I should look for? -- Andrew

Message body is not shown because it is too large.

  Fri Mar 01 03:27:01 2019 sfandino [...] yahoo.com - Correspondence added
Subject: Re: [rt.cpan.org #128658] freebsd 11.2 bug
Date: Fri, 1 Mar 2019 09:26:46 +0100
To: bug-Net-OpenSSH [...] rt.cpan.org
From: Salvador Fandiño <sfandino [...] yahoo.com>
On 2/27/19 9:09 PM, Andrew Vylegzhanin via RT wrote: Show quoted text
> Wed Feb 27 15:09:16 2019: Request 128658 was acted upon. > Transaction: Ticket created by avv314@gmail.com > Queue: Net-OpenSSH > Subject: freebsd 11.2 bug > Broken in: (no value) > Severity: (no value) > Owner: Nobody > Requestors: avv314@gmail.com > Status: new > Ticket <URL: https://rt.cpan.org/Ticket/Display.html?id=128658 > > > > Hi! > I've successfully used Net::OpenSSH for couple years under FeeBSD > 9.3-RELEASE. > It's simple perl script invoked by propraetry billing system for handling > external events by coping files via scp. > Here is fragment: > > open( my $stderr_fh, ">>", $LOGDIR."vg-arcd-ssh.log" ) || warn "Can't > log\n"; > > my $tm = localtime; > > print $stderr_fh "$tm [$$] \n"; > > > $Net::OpenSSH::debug_fh = $stderr_fh; > > $Net::OpenSSH::debug = ~0; > > my $ssh = Net::OpenSSH->new( 'cptctrl@2.2.2.2:8844', default_stderr_fh > => $stderr_fh, default_stdout_fh => $stderr_fh, async => 0 ); > > > if( $ssh->error ) { > > syslog( "Couldn't establish SSH connection: ". $ssh->error ); > > syslog( "Moving job file to queue" ); > > rename( $DATADIR.$tmpfile, $DATADIR."jobs/".$tmpfile ); > > } > > > else { > > syslog( "DEBUG: before scp" ); > > $ssh->scp_put( {async => 0, timeout => 10 }, $DATADIR.$tmpfile, > "jobs" ) || syslog( "DEBUG: scp failed: " . $ssh->error ); > > syslog( "DEBUG: after scp" ); > > if( $ssh->error ) { > > syslog( "scp_put to remote host failed: ".$ssh->error ); > > syslog( "Moving job file to queue" ); > > rename( $DATADIR.$tmpfile, $DATADIR."jobs/".$tmpfile ); > > } > > > else { > > syslog( "Copied" ); > > unlink( $DATADIR.$tmpfile ); > > } > > } > > After upgrading to FreeBSD 11.2-RELEASE I've got following problem: > - when I run this script from command line (from bash), everything is ok, > always. > - when this script invoked from billing system (from FreeBSD process, > written on C++ mostly AFAIK), it's perl process ends without errors on > OpenSSH->new or after $ssh->scp_put (so sometimes it copied files) > > Here is debug output from $Net::OpenSSH::debug = ~0 > > From command line: > > # open_ex: ['ssh','-V'] > > # io3 mloop, cin: 0, cout: 1, cerr: 0 > > # io3 fast, cin: 0, cout: 1, cerr: 0 > > # stdout, bytes read: 51 at offset 0 > > #> 4f 70 65 6e 53 53 48 5f 37 2e 35 70 31 2c 20 4f 70 65 6e 53 53 4c 20 31 > 2e 30 2e 32 6f 2d 66 72 | OpenSSH_7.5p1, OpenSSL 1.0.2o-fr > > #> 65 65 62 73 64 20 20 32 37 20 4d 61 72 20 32 30 31 38 0a > | eebsd 27 Mar 2018. > > # io3 fast, cin: 0, cout: 1, cerr: 0 > > # stdout, bytes read: 0 at offset 51 > > # leaving _io3() > > # _waitpid(50657) => pid: 50657, rc: 0, err: > > # OpenSSH version is 7.5p1, > > # ctl_path: /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, > ctl_dir: /root/.libnet-openssh-perl/ > > # _is_secure_path(dir: /root/.libnet-openssh-perl, file mode: 16832, file > uid: 0, euid: 0 > > # _is_secure_path(dir: /root, file mode: 16877, file uid: 0, euid: 0 > > # set_error(0 - 0) > > # call args: > ['ssh','-o','ServerAliveInterval=30','-o','ControlPersist=no','-2MNx','-S','/root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb','-l','cptctrl','-p','8844','2.2.2.2','--'] > > # tracer attached, ssh pid: 50658, tracer pid: 50659 > > # master state jumping from _STATE_START to _STATE_AWAITING_MUX > > # file object not yet found at > /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, > state:_STATE_AWAITING_MUX > > # file object not yet found at > /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, > state:_STATE_AWAITING_MUX > > # file object not yet found at > /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, > state:_STATE_AWAITING_MUX > > # file object not yet found at > /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, > state:_STATE_AWAITING_MUX > > # file object not yet found at > /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, > state:_STATE_AWAITING_MUX > > # file object not yet found at > /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, > state:_STATE_AWAITING_MUX > > # file object not yet found at > /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, > state:_STATE_AWAITING_MUX > > # file object not yet found at > /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, > state:_STATE_AWAITING_MUX > > # file object not yet found at > /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, > state:_STATE_AWAITING_MUX > > # file object not yet found at > /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, > state:_STATE_AWAITING_MUX > > # file object not yet found at > /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, > state:_STATE_AWAITING_MUX > > # file object not yet found at > /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, > state:_STATE_AWAITING_MUX > > # file object not yet found at > /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, > state:_STATE_AWAITING_MUX > > # file object not yet found at > /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, > state:_STATE_AWAITING_MUX > > # file object not yet found at > /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, > state:_STATE_AWAITING_MUX > > # file object not yet found at > /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, > state:_STATE_AWAITING_MUX > > # file object not yet found at > /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, > state:_STATE_AWAITING_MUX > > # file object not yet found at > /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb, > state:_STATE_AWAITING_MUX > > # file object found at > /root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb > > # master state jumping from _STATE_AWAITING_MUX to _STATE_RUNNING > > # call args: > ['ssh','-O','check','-T','-S','/root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb','-l','cptctrl','-p','8844','2.2.2.2','--'] > > # open_ex: > ['ssh','-O','check','-T','-S','/root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb','-l','cptctrl','-p','8844','2.2.2.2 > > # io3 mloop, cin: 0, cout: 1, cerr: 0 > > # io3 fast, cin: 0, cout: 1, cerr: 0 > > # stdout, bytes read: 28 at offset 0 > > #> 4d 61 73 74 65 72 20 72 75 6e 6e 69 6e 67 20 28 70 69 64 3d 35 30 36 35 > 38 29 0d 0a | Master running (pid=50658).. > > # io3 fast, cin: 0, cout: 1, cerr: 0 > > # stdout, bytes read: 0 at offset 28 > > # leaving _io3() > > # _waitpid(50668) => pid: 50668, rc: 0, err: > > # scp call args: > ['scp','-q','-o','ControlPath=/root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb','-S','ssh','-P','8844','--','/prov/tsey/cpt.job.50656r','cptctrl@2.2.2.2: > jobs'] > > # open_ex: > ['scp','-q','-o','ControlPath=/root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb','-S','ssh','-P','8844','--','/prov/tsey/cpt.job.50656r','cptctrl@2.2.2.2: > jobs'] > > # _waitpid(50669) => pid: 50669, rc: 0, err: Interrupted system call > > # DESTROY(Net::OpenSSH=HASH(0x80259f288), pid: 50658) > > # sending exit control to master > > # call args: > ['ssh','-O','exit','-T','-S','/root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb','-l','cptctrl','-p','8844','2.2.2.2','--'] > > # open_ex: > ['ssh','-O','exit','-T','-S','/root/.libnet-openssh-perl/0c3865501b7c522fd3404c3e5c0e36cb','-l','cptctrl','-p','8844','2.2.2.2','--'] > > # io3 mloop, cin: 0, cout: 1, cerr: 0 > > # io3 fast, cin: 0, cout: 1, cerr: 0 > > # stdout, bytes read: 20 at offset 0 > > #> 45 78 69 74 20 72 65 71 75 65 73 74 20 73 65 6e 74 2e 0d 0a > | Exit request sent... > > # io3 fast, cin: 0, cout: 1, cerr: 0 > > # stdout, bytes read: 0 at offset 20 > > # leaving _io3() > > # _waitpid(50671) => pid: 50671, rc: 0, err: > > # set_error(1 - aborted) > > # master state jumping from _STATE_RUNNING to _STATE_KILLING > > # killing master > > # _master_kill: 50658 > > # waitpid(master: 50658) => pid: 0, rc: > > # waitpid(master: 50658) => pid: 50658, rc: Interrupted system call > > # master state jumping from _STATE_KILLING to _STATE_GONE > > > Invoked from billing system: > > # open_ex: ['ssh','-V'] > > # io3 mloop, cin: 0, cout: 1, cerr: 0 > > # io3 fast, cin: 0, cout: 1, cerr: 0 > > # stdout, bytes read: 51 at offset 0 > > #> 4f 70 65 6e 53 53 48 5f 37 2e 35 70 31 2c 20 4f 70 65 6e 53 53 4c 20 31 > 2e 30 2e 32 6f 2d 66 72 | OpenSSH_7.5p1, OpenSSL 1.0.2o-fr > > #> 65 65 62 73 64 20 20 32 37 20 4d 61 72 20 32 30 31 38 0a > | eebsd 27 Mar 2018. > > # io3 fast, cin: 0, cout: 1, cerr: 0 > > # stdout, bytes read: 0 at offset 51 > > # leaving _io3() > > # _waitpid(62488) => pid: 62488, rc: 0, err: > > # OpenSSH version is 7.5p1, > > # ctl_path: /root/.libnet-openssh-perl/ca9523a03741dc7955578d7fb1933c0d, > ctl_dir: /root/.libnet-openssh-perl/ > > # _is_secure_path(dir: /root/.libnet-openssh-perl, file mode: 16832, file > uid: 0, euid: 0 > > # _is_secure_path(dir: /root, file mode: 16877, file uid: 0, euid: 0 > > # set_error(0 - 0) > > # call args: > ['ssh','-o','ServerAliveInterval=30','-o','ControlPersist=no','-2MNx','-S','/root/.libnet-openssh-perl/ca9523a03741dc7955578d7fb1933c0d','-l','cptctrl','-p','8844','2.2.2.2','--'] > > # tracer attached, ssh pid: 62489, tracer pid: 62490
Is that really all the debugging output you get from the Perl script? Is it ending or hanging? It should also be leaving a ktrace file at /tmp/net_openssh_master*, you can use kdump to examine it and see what the script was doing at the OS level just before finishing. Also, as the debugging output ends just after invoking ktrace on itself, you can try disabling it. Change the line where you activate debugging to...     $Net::OpenSSH::debug = (~512); And finally, you can also try activating debugging for the ssh process from the Net::OpenSSH constructor...    my $ssh = Net::OpenSSH->new(..., master_opts => '-vvv')
  Fri Mar 01 03:27:02 2019 The RT System itself - Status changed from 'new' to 'open'
  Sat Mar 02 21:07:18 2019 avv314 [...] gmail.com - Correspondence added
Subject: Re: [rt.cpan.org #128658] freebsd 11.2 bug
Date: Sun, 3 Mar 2019 05:06:56 +0300
To: bug-Net-OpenSSH [...] rt.cpan.org
From: Andrew Vylegzhanin <avv314 [...] gmail.com>
пт, 1 мар. 2019 г. в 11:27, Salvador \"Fandiño\" via RT < bug-Net-OpenSSH@rt.cpan.org>: Show quoted text
> <URL: https://rt.cpan.org/Ticket/Display.html?id=128658 > > > > On 2/27/19 9:09 PM, Andrew Vylegzhanin via RT wrote:
> > Wed Feb 27 15:09:16 2019: Request 128658 was acted upon. > > Transaction: Ticket created by avv314@gmail.com > > Queue: Net-OpenSSH > > Subject: freebsd 11.2 bug > > Broken in: (no value) > > Severity: (no value) > > Owner: Nobody > > Requestors: avv314@gmail.com > > Status: new > > Ticket <URL: https://rt.cpan.org/Ticket/Display.html?id=128658 > > > > > > > # set_error(0 - 0) > > > > # call args: > >
> ['ssh','-o','ServerAliveInterval=30','-o','ControlPersist=no','-2MNx','-S','/root/.libnet-openssh-perl/ca9523a03741dc7955578d7fb1933c0d','-l','cptctrl','-p','8844','2.2.2.2','--']
> > > > # tracer attached, ssh pid: 62489, tracer pid: 62490
> > Is that really all the debugging output you get from the Perl script? Is > it ending or hanging? > >
The script is ending on But ssh process (and remote ssh server on target host) lives up to kill -9. 48377 - S 0:00.21 ssh -o ServerAliveInterval=30 -o ControlPersist=no -2MNx -S /root/.libnet-openssh-perl/6ed6a5277b133de750bfce98bcdbec16 -l cptctrl -p 8844 2.2.2.2 -- 48860 - I 0:00.20 ssh -o ServerAliveInterval=30 -o ControlPersist=no -2MNx -S /root/.libnet-openssh-perl/e738e184529e56573683b7ebb59901a0 -l cptctrl -p 8844 2.2.2.2 -- 52049 - S 0:00.07 ssh -o ServerAliveInterval=30 -o ControlPersist=no -2MNx -S /root/.libnet-openssh-perl/f6cd719e430a9f3f4db0cf5db6d783d0 -l cptctrl -p 8844 2.2.2.2 -- It should also be leaving a ktrace file at /tmp/net_openssh_master*, you Show quoted text
> can use kdump to examine it and see what the script was doing at the OS > level just before finishing. > >
It's loop around select/read/write up to manual killing: 52444 ssh RET read 28/0x1c 52444 ssh CALL select(0x5,0x8020161e0,0x8020161b8,0,0x7fffffffa860) 52444 ssh RET select 0 52444 ssh CALL getpid 52444 ssh RET getpid 52444/0xccdc 52444 ssh CALL select(0x5,0x8020161e0,0x8020161b8,0,0x7fffffffa860) 52444 ssh RET select 1 52444 ssh CALL write(0x3,0x8021215f0,0x34) 52444 ssh GIO fd 3 wrote 52 bytes # ls -la /tmp/*ktrace -rw------- 1 root wheel 1977306 Mar 2 08:13 /tmp/net_openssh_master.33903.ktrace -rw------- 1 root wheel 1943930 Mar 2 08:13 /tmp/net_openssh_master.34146.ktrace -rw------- 1 root wheel 281090 Mar 2 08:14 /tmp/net_openssh_master.44790.ktrace -rw------- 1 root wheel 2605599 Mar 3 04:39 /tmp/net_openssh_master.48377.ktrace -rw------- 1 root wheel 2531559 Mar 3 04:39 /tmp/net_openssh_master.48860.ktrace -rw------- 1 root wheel 225249 Feb 25 23:52 /tmp/net_openssh_master.50586.ktrace -rw------- 1 root wheel 224801 Feb 25 23:55 /tmp/net_openssh_master.50658.ktrace -rw------- 1 root wheel 2026151 Mar 3 04:39 /tmp/net_openssh_master.52049.ktrace -rw------- 1 root wheel 1980855 Mar 3 04:39 /tmp/net_openssh_master.52353.ktrace ....... So, it seems, the problem is in perl module not in OpenSSH itself Any ideas? -- Andrew Show quoted text
> Also, as the debugging output ends just after invoking ktrace on itself, > you can try disabling it. Change the line where you activate debugging > to... > > $Net::OpenSSH::debug = (~512); > > And finally, you can also try activating debugging for the ssh process > from the Net::OpenSSH constructor... > > my $ssh = Net::OpenSSH->new(..., master_opts => '-vvv') > >
  Sun Mar 03 03:06:39 2019 sfandino [...] yahoo.com - Correspondence added
Subject: Re: [rt.cpan.org #128658] freebsd 11.2 bug
Date: Sun, 3 Mar 2019 09:06:25 +0100
To: bug-Net-OpenSSH [...] rt.cpan.org
From: Salvador Fandiño <sfandino [...] yahoo.com>
On 3/3/19 3:07 AM, Andrew Vylegzhanin via RT wrote: Show quoted text
> Queue: Net-OpenSSH > Ticket <URL: https://rt.cpan.org/Ticket/Display.html?id=128658 > > > пт, 1 мар. 2019 г. в 11:27, Salvador \"Fandiño\" via RT < > bug-Net-OpenSSH@rt.cpan.org>: >
>> <URL: https://rt.cpan.org/Ticket/Display.html?id=128658 > >> >> >> On 2/27/19 9:09 PM, Andrew Vylegzhanin via RT wrote:
>>> Wed Feb 27 15:09:16 2019: Request 128658 was acted upon. >>> Transaction: Ticket created by avv314@gmail.com >>> Queue: Net-OpenSSH >>> Subject: freebsd 11.2 bug >>> Broken in: (no value) >>> Severity: (no value) >>> Owner: Nobody >>> Requestors: avv314@gmail.com >>> Status: new >>> Ticket <URL: https://rt.cpan.org/Ticket/Display.html?id=128658 > >>> >>> >>> # set_error(0 - 0) >>> >>> # call args: >>>
>> ['ssh','-o','ServerAliveInterval=30','-o','ControlPersist=no','-2MNx','-S','/root/.libnet-openssh-perl/ca9523a03741dc7955578d7fb1933c0d','-l','cptctrl','-p','8844','2.2.2.2','--']
>>> # tracer attached, ssh pid: 62489, tracer pid: 62490
>> Is that really all the debugging output you get from the Perl script? Is >> it ending or hanging? >> >>
> The script is ending on > But ssh process (and remote ssh server on target host) lives up to kill -9. > > 48377 - S 0:00.21 ssh -o ServerAliveInterval=30 -o > ControlPersist=no -2MNx -S > /root/.libnet-openssh-perl/6ed6a5277b133de750bfce98bcdbec16 -l cptctrl -p > 8844 2.2.2.2 -- > > 48860 - I 0:00.20 ssh -o ServerAliveInterval=30 -o > ControlPersist=no -2MNx -S > /root/.libnet-openssh-perl/e738e184529e56573683b7ebb59901a0 -l cptctrl -p > 8844 2.2.2.2 -- > 52049 - S 0:00.07 ssh -o ServerAliveInterval=30 -o > ControlPersist=no -2MNx -S > /root/.libnet-openssh-perl/f6cd719e430a9f3f4db0cf5db6d783d0 -l cptctrl -p > 8844 2.2.2.2 -- > > It should also be leaving a ktrace file at /tmp/net_openssh_master*, you
>> can use kdump to examine it and see what the script was doing at the OS >> level just before finishing. >> >>
> It's loop around select/read/write up to manual killing: > > 52444 ssh RET read 28/0x1c > > 52444 ssh CALL select(0x5,0x8020161e0,0x8020161b8,0,0x7fffffffa860) > > 52444 ssh RET select 0 > > 52444 ssh CALL getpid > > 52444 ssh RET getpid 52444/0xccdc > > 52444 ssh CALL select(0x5,0x8020161e0,0x8020161b8,0,0x7fffffffa860) > > 52444 ssh RET select 1 > > 52444 ssh CALL write(0x3,0x8021215f0,0x34) > 52444 ssh GIO fd 3 wrote 52 bytes
This looks like the dump for some ssh subprocess. I would like to see the dump for the perl script instead (or probably both processes). Also, just some line would not make it, actually it would be better if you include the full dump but be aware that that could expose sensitive information as passwords. Show quoted text
> # ls -la /tmp/*ktrace > > -rw------- 1 root wheel 1977306 Mar 2 08:13 > /tmp/net_openssh_master.33903.ktrace > > -rw------- 1 root wheel 1943930 Mar 2 08:13 > /tmp/net_openssh_master.34146.ktrace > > -rw------- 1 root wheel 281090 Mar 2 08:14 > /tmp/net_openssh_master.44790.ktrace > > -rw------- 1 root wheel 2605599 Mar 3 04:39 > /tmp/net_openssh_master.48377.ktrace > > -rw------- 1 root wheel 2531559 Mar 3 04:39 > /tmp/net_openssh_master.48860.ktrace > > -rw------- 1 root wheel 225249 Feb 25 23:52 > /tmp/net_openssh_master.50586.ktrace > > -rw------- 1 root wheel 224801 Feb 25 23:55 > /tmp/net_openssh_master.50658.ktrace > > -rw------- 1 root wheel 2026151 Mar 3 04:39 > /tmp/net_openssh_master.52049.ktrace > > -rw------- 1 root wheel 1980855 Mar 3 04:39 > /tmp/net_openssh_master.52353.ktrace > > .......
Every time you run the script with full debugging enabled, a new ktrace file is created.
  Sat Mar 09 14:32:00 2019 avv314 [...] gmail.com - Correspondence added
Subject: Re: [rt.cpan.org #128658] freebsd 11.2 bug
Date: Sat, 9 Mar 2019 22:31:39 +0300
To: bug-Net-OpenSSH [...] rt.cpan.org
From: Andrew Vylegzhanin <avv314 [...] gmail.com>
вс, 3 мар. 2019 г. в 11:06, Salvador \"Fandiño\" via RT < bug-Net-OpenSSH@rt.cpan.org>: Show quoted text
> > <URL: https://rt.cpan.org/Ticket/Display.html?id=128658 > >
> > 52444 ssh CALL write(0x3,0x8021215f0,0x34) > > 52444 ssh GIO fd 3 wrote 52 bytes
> > This looks like the dump for some ssh subprocess. I would like to see
Of course this is ssh subprocess started by Net::OpenSSH->new. Show quoted text
> the dump for the perl script instead (or probably both processes). Also, > just some line would not make it, actually it would be better if you > include the full dump but be aware that that could expose sensitive > information as passwords. >
After adding shell wrapper for tracing perl script like this: #!/bin/sh ktrace -f vgarcd.out.$$ vg-arcd.pl $0 $1 $2 $3 $4 $5 The problem is disappeared! Net::OpenSSH->new now is returing normal state and scp working. So, I will try to start via perl wrapper later for to check if perl is affecting. -- Andrew