[Fuego] [LTSI-dev] ssh timeout problem - was RE: Fuego installation

Bird, Timothy Tim.Bird at am.sony.com
Tue Oct 25 19:02:39 UTC 2016


anirudh,

(Sorry for the duplicate message.  I forgot to copy the lists in my reply)

These logs are not the full logs for each command.  They're missing the lines I'm interested in.
In particular, in wanted to see the "debug1: sending command" and "debug1: Exit status" lines
for each ssh invocation.

See more comments/questions inline below.

> -----Original Message-----
> From: anirudh vasudevan [mailto:vasuanirudh at gmail.com]
> Sent: Tuesday, October 25, 2016 8:37 AM
> To: Bird, Timothy <Tim.Bird at am.sony.com>
> Cc: ltsi-dev at lists.linuxfoundation.org; fuego at lists.linuxfoundation.org
> Subject: Re: [LTSI-dev] ssh timeout problem - was RE: [Fuego] Fuego
> installation
> 
> Here is test you had asked for
> 
> Host : ifconfig
> 
> docker0   Link encap:Ethernet
>           inet addr:172.17.0.1  Bcast:0.0.0.0  Mask:255.255.0.0
>           UP BROADCAST MULTICAST  MTU:1500  Metric:1
>           RX packets:0 errors:0 dropped:0 overruns:0 frame:0
>           TX packets:0 errors:0 dropped:0 overruns:0 carrier:0
>           collisions:0 txqueuelen:0
>           RX bytes:0 (0.0 B)  TX bytes:0 (0.0 B)
> 
> eth0   Link encap:Ethernet
>           inet addr:192.168.1.27  Bcast:192.168.1.255  Mask:255.255.255.0
>           inet6 addr: fe80::96a4:8e81:cf71:7a2c/64 Scope:Link
>           UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
>           RX packets:5360 errors:0 dropped:0 overruns:0 frame:0
>           TX packets:4990 errors:0 dropped:0 overruns:0 carrier:0
>           collisions:0 txqueuelen:1000
>           RX bytes:2956455 (2.9 MB)  TX bytes:648438 (648.4 KB)
>           Interrupt:17
> 
> 
> 
> Target: VAR
> 
> 
> 
> ap0       Link encap:Ethernet
>           inet6 addr: fe80::be66:41ff:fe30:a456/64 Scope:Link
>           UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
>           RX packets:0 errors:0 dropped:0 overruns:0 frame:0
>           TX packets:286 errors:0 dropped:0 overruns:0 carrier:0
>           collisions:0 txqueuelen:1000
>           RX bytes:0 (0.0 B)  TX bytes:17772 (17.3 KiB)
> 
> br0       Link encap:Ethernet
>           inet addr:10.15.140.230  Bcast:10.255.255.255  Mask:255.0.0.0
>           inet6 addr: fe80::8625:3fff:fe0f:8ce6/64 Scope:Link
>           UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
>           RX packets:3189 errors:0 dropped:0 overruns:0 frame:0
>           TX packets:4094 errors:0 dropped:0 overruns:0 carrier:0
>           collisions:0 txqueuelen:1000
>           RX bytes:215833 (210.7 KiB)  TX bytes:4057937 (3.8 MiB)
> 
> eth0      Link encap:Ethernet
>           inet addr:192.168.1.56  Bcast:192.168.1.255  Mask:255.255.255.0
>           inet6 addr: fe80::fadc:7aff:fe05:6d00/64 Scope:Link
>           UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
>           RX packets:4988 errors:0 dropped:0 overruns:0 frame:0
>           TX packets:3993 errors:0 dropped:0 overruns:0 carrier:0
>           collisions:0 txqueuelen:1000
>           RX bytes:4402058 (4.1 MiB)  TX bytes:372918 (364.1 KiB)
> 
> 
> 
> 
> ssh command with verbose which you told me to run outside and inside of
> the docker container works, am able to ssh to the target by providing the
> password.


OK
> 
> 
> Below results are the ones from the console after I added verbose on the
> base-params.fuegoclass scripts.
> 
> 
> There are series of ssh commands which takes place and it is successfully
> getting the firmware version from the board it is failing after which it fetches
> the firmware version.
> 
> +++ target_cleanup Functional.bc
> +++ cmd 'rm -rf /home/a/* /tmp/* /home/a/.local'
> +++ report_devlog 'cmd: rm -rf /home/a/* /tmp/* /home/a/.local'
> +++ mkdir -p /home/jenkins/logs/Functional.bc/devlogs
> +++ echo 'cmd: rm -rf /home/a/* /tmp/* /home/a/.local'
> +++ ov_transport_cmd 'rm -rf /home/a/* /tmp/* /home/a/.local'
> +++ case "$TRANSPORT" in
> +++ sshpass -e ssh -vvv -o ServerAliveInterval=30 -o
> StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o
> ConnectTimeout=35 -p 22 root at 192.168.1.56 <mailto:root at 192.168.1.56>
> 'rm -rf /home/a/* /tmp/* /home/a/.local'
> OpenSSH_6.7p1 Debian-5+deb8u3, OpenSSL 1.0.1t  3 May 2016
> debug1: Reading configuration data /etc/ssh/ssh_config
> debug1: /etc/ssh/ssh_config line 19: Applying options for *
> debug2: ssh_connect: needpriv 0
> debug1: Connecting to 192.168.1.56 [192.168.1.56] port 22.
> debug2: fd 3 setting O_NONBLOCK
> debug1: fd 3 clearing O_NONBLOCK
> debug1: Connection established.
> debug3: timeout: 35000 ms remain after connect
> debug1: key_load_public: No such file or directory
> debug1: identity file /var/lib/jenkins/.ssh/id_rsa type -1
> debug1: key_load_public: No such file or directory
> debug1: identity file /var/lib/jenkins/.ssh/id_rsa-cert type -1
> debug1: key_load_public: No such file or directory
> debug1: identity file /var/lib/jenkins/.ssh/id_dsa type -1
> debug1: key_load_public: No such file or directory
> debug1: identity file /var/lib/jenkins/.ssh/id_dsa-cert type -1
> debug1: key_load_public: No such file or directory
> debug1: identity file /var/lib/jenkins/.ssh/id_ecdsa type -1
> debug1: key_load_public: No such file or directory
> debug1: identity file /var/lib/jenkins/.ssh/id_ecdsa-cert type -1
> debug1: key_load_public: No such file or directory
> debug1: identity file /var/lib/jenkins/.ssh/id_ed25519 type -1
> debug1: key_load_public: No such file or directory
> debug1: identity file /var/lib/jenkins/.ssh/id_ed25519-cert type -1
> debug1: Enabling compatibility mode for protocol 2.0
> debug1: Local version string SSH-2.0-OpenSSH_6.7p1 Debian-5+deb8u3
> debug1: Remote protocol version 2.0, remote software version
> OpenSSH_6.7p1 Debian-5+deb8u3
> debug1: match: OpenSSH_6.7p1 Debian-5+deb8u3 pat OpenSSH* compat
> 0x04000000
> debug2: fd 3 setting O_NONBLOCK
> debug3: load_hostkeys: loading entries for host "192.168.1.56" from file
> "/dev/null"
> debug3: load_hostkeys: loaded 0 keys
> debug1: SSH2_MSG_KEXINIT sent
> debug1: SSH2_MSG_KEXINIT received
> debug2: kex_parse_kexinit:
> debug2: kex_parse_kexinit:
> debug2: kex_parse_kexinit: first_kex_follows 0
> debug2: kex_parse_kexinit: reserved 0
> debug2: kex_parse_kexinit: curve25519-sha256 at libssh.org
> <mailto:curve25519-sha256 at libssh.org> ,ecdh-sha2-nistp256,ecdh-sha2-
> nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-
> hellman-group14-sha1
> debug2: kex_parse_kexinit: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256,ssh-
> ed25519
> debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,aes128-
> gcm at openssh.com <mailto:aes128-gcm at openssh.com> ,aes256-
> gcm at openssh.com <mailto:aes256-gcm at openssh.com> ,chacha20-
> poly1305 at openssh.com <mailto:chacha20-poly1305 at openssh.com>
> debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,aes128-
> gcm at openssh.com <mailto:aes128-gcm at openssh.com> ,aes256-
> gcm at openssh.com <mailto:aes256-gcm at openssh.com> ,chacha20-
> poly1305 at openssh.com <mailto:chacha20-poly1305 at openssh.com>
> debug2: kex_parse_kexinit: umac-64-etm at openssh.com <mailto:umac-64-
> etm at openssh.com> ,umac-128-etm at openssh.com <mailto:umac-128-
> etm at openssh.com> ,hmac-sha2-256-etm at openssh.com <mailto:hmac-
> sha2-256-etm at openssh.com> ,hmac-sha2-512-etm at openssh.com
> <mailto:hmac-sha2-512-etm at openssh.com> ,hmac-sha1-
> etm at openssh.com <mailto:hmac-sha1-etm at openssh.com> ,umac-
> 64 at openssh.com <mailto:umac-64 at openssh.com> ,umac-
> 128 at openssh.com <mailto:umac-128 at openssh.com> ,hmac-sha2-
> 256,hmac-sha2-512,hmac-sha1
> debug2: kex_parse_kexinit: umac-64-etm at openssh.com <mailto:umac-64-
> etm at openssh.com> ,umac-128-etm at openssh.com <mailto:umac-128-
> etm at openssh.com> ,hmac-sha2-256-etm at openssh.com <mailto:hmac-
> sha2-256-etm at openssh.com> ,hmac-sha2-512-etm at openssh.com
> <mailto:hmac-sha2-512-etm at openssh.com> ,hmac-sha1-
> etm at openssh.com <mailto:hmac-sha1-etm at openssh.com> ,umac-
> 64 at openssh.com <mailto:umac-64 at openssh.com> ,umac-
> 128 at openssh.com <mailto:umac-128 at openssh.com> ,hmac-sha2-
> 256,hmac-sha2-512,hmac-sha1
> debug2: kex_parse_kexinit: none,zlib at openssh.com
> <mailto:zlib at openssh.com>
> debug2: kex_parse_kexinit: none,zlib at openssh.com
> <mailto:zlib at openssh.com>
> debug2: kex_parse_kexinit:
> debug2: kex_parse_kexinit:
> debug2: kex_parse_kexinit: first_kex_follows 0
> debug2: kex_parse_kexinit: reserved 0
> debug2: mac_setup: setup umac-64-etm at openssh.com <mailto:umac-64-
> etm at openssh.com>
> debug1: kex: server->client aes128-ctr umac-64-etm at openssh.com
> <mailto:umac-64-etm at openssh.com>  none
> debug2: mac_setup: setup umac-64-etm at openssh.com <mailto:umac-64-
> etm at openssh.com>
> debug1: kex: client->server aes128-ctr umac-64-etm at openssh.com
> <mailto:umac-64-etm at openssh.com>  none
> debug1: sending SSH2_MSG_KEX_ECDH_INIT
> debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
> debug1: Server host key: ECDSA
> 81:cb:85:b4:3f:f5:26:22:a0:d6:63:85:c2:75:ca:d2
> debug3: load_hostkeys: loading entries for host "192.168.1.56" from file
> "/dev/null"
> debug3: load_hostkeys: loaded 0 keys
> Warning: Permanently added '192.168.1.56' (ECDSA) to the list of known
> hosts.
> debug2: kex_derive_keys
> debug2: set_newkeys: mode 1
> debug1: SSH2_MSG_NEWKEYS sent
> debug1: expecting SSH2_MSG_NEWKEYS
> debug2: set_newkeys: mode 0
> debug1: SSH2_MSG_NEWKEYS received
> debug1: SSH2_MSG_SERVICE_REQUEST sent
> debug2: service_accept: ssh-userauth
> debug1: SSH2_MSG_SERVICE_ACCEPT received
> debug2: key: /var/lib/jenkins/.ssh/id_rsa ((nil)),
> debug2: key: /var/lib/jenkins/.ssh/id_dsa ((nil)),
> debug2: key: /var/lib/jenkins/.ssh/id_ecdsa ((nil)),
> debug2: key: /var/lib/jenkins/.ssh/id_ed25519 ((nil)),
> debug1: Authentications that can continue: publickey,password
> debug3: start over, passed a different list publickey,password
> debug3: preferred gssapi-keyex,gssapi-with-mic,publickey,keyboard-
> interactive,password
> debug3: authmethod_lookup publickey
> debug3: remaining preferred: keyboard-interactive,password
> debug3: authmethod_is_enabled publickey
> debug1: Next authentication method: publickey
> debug1: Trying private key: /var/lib/jenkins/.ssh/id_rsa
> debug3: no such identity: /var/lib/jenkins/.ssh/id_rsa: No such file or
> directory
> debug1: Trying private key: /var/lib/jenkins/.ssh/id_dsa
> debug3: no such identity: /var/lib/jenkins/.ssh/id_dsa: No such file or
> directory
> debug1: Trying private key: /var/lib/jenkins/.ssh/id_ecdsa
> debug3: no such identity: /var/lib/jenkins/.ssh/id_ecdsa: No such file or
> directory
> debug1: Trying private key: /var/lib/jenkins/.ssh/id_ed25519
> debug3: no such identity: /var/lib/jenkins/.ssh/id_ed25519: No such file or
> directory
> debug2: we did not send a packet, disable method
> debug3: authmethod_lookup password
> debug3: remaining preferred: ,password
> debug3: authmethod_is_enabled password
> debug1: Next authentication method: password
> debug2: we sent a password packet, wait for reply
> debug1: Authentication succeeded (password).
> Authenticated to 192.168.1.56 ([192.168.1.56]:22).
> debug2: fd 4 setting O_NONBLOCK
> debug2: fd 5 setting O_NONBLOCK
> debug3: fd 6 is O_NONBLOCK
> debug1: channel 0: new [client-session]
> debug3: ssh_session2_open: channel_new: 0
> debug2: channel 0: send open
> debug1: Requesting no-more-sessions at openssh.com <mailto:no-more-
> sessions at openssh.com>
> debug1: Entering interactive session.
> debug2: callback start
> debug2: fd 3 setting TCP_NODELAY
> debug3: packet_set_tos: set IP_TOS 0x08
> debug2: client_session2_setup: id 0
> debug1: Sending environment.
> debug3: Ignored env BUILD_URL
> debug3: Ignored env variableEnvFunctional.bc0
> debug3: Ignored env HUDSON_SERVER_COOKIE
> debug3: Ignored env SHELL
> debug3: Ignored env TERM
> debug3: Ignored env BOARD_OVERLAY
> debug3: Ignored env BUILD_TAG
> debug3: Ignored env Rebuild
> debug3: Ignored env TESTPLAN
> debug3: Ignored env Device
> debug3: Ignored env WORKSPACE
> debug3: Ignored env FUEGO_ENGINE_PATH
> debug3: Ignored env JOB_URL
> debug3: Ignored env USER
> debug3: Ignored env FUEGO_LOGS_PATH
> debug3: Ignored env JENKINS_HOME
> debug3: Ignored env PATH
> debug3: Ignored env MAIL
> debug3: Ignored env PWD
> debug3: Ignored env HUDSON_URL
> debug3: Ignored env JOB_NAME
> debug3: Ignored env FUEGO_SCRIPTS_PATH
> debug3: Ignored env JENKINS_URL
> debug3: Ignored env BUILD_ID
> debug3: Ignored env HOME
> debug3: Ignored env SHLVL
> debug3: Ignored env SSHPASS
> debug3: Ignored env $JOB_NAME
> debug3: Ignored env JENKINS_SERVER_COOKIE
> debug3: Ignored env EXECUTOR_NUMBER
> debug3: Ignored env NODE_LABELS
> debug3: Ignored env LOGNAME
> debug3: Ignored env HUDSON_HOME
> debug3: Ignored env FUEGO_PARSER_PATH
> debug3: Ignored env FUEGO_TESTS_PATH
> debug3: Ignored env SLAVEJAR_URL
> debug3: Ignored env NODE_NAME
> debug3: Ignored env BUILD_NUMBER
> debug3: Ignored env HUDSON_COOKIE
> debug3: Ignored env Reboot
> debug3: Ignored env Target_Cleanup
> debug3: Ignored env DISTRIB
> debug3: Ignored env _
> debug1: Sending command: rm -rf /home/a/* /tmp/* /home/a/.local
> debug2: channel 0: request exec confirm 1
> debug2: callback done
> debug2: channel 0: open confirm rwindow 0 rmax 32768
> debug2: channel 0: rcvd adjust 2097152
> 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: close_read
> debug2: channel 0: input open -> drain
> debug2: channel 0: ibuf empty
> debug2: channel 0: send eof
> debug2: channel 0: input drain -> closed
> debug2: channel 0: rcvd eof
> debug2: channel 0: output open -> drain
> debug2: channel 0: obuf empty
> debug2: channel 0: close_write
> debug2: channel 0: output drain -> closed
> debug1: client_input_channel_req: channel 0 rtype exit-status reply 0
> 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
> 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 fd -1/-1 cc -1)
> 
> debug1: fd 0 clearing O_NONBLOCK
> debug1: fd 1 clearing O_NONBLOCK
> debug3: fd 2 is not O_NONBLOCK
> Transferred: sent 2500, received 1476 bytes, in 0.1 seconds
> Bytes per second: sent 32307.3, received 19074.2
>

What is the exit status of this command?

What about for the 'true' command, which is also run during the pre-test phase?
 
> 
> SSH command failing here
Is this commenting on the ssh operation above or below?  I presume below...

> 
> 
> +++ sshpass -e ssh -vvv -o ServerAliveInterval=30 -o
> StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o
> ConnectTimeout=35 -p 22 root at 192.168.1.56 <mailto:root at 192.168.1.56>
> 'echo "Firmware revision:" 4.7.4-IMX6.VAR_R17'
> OpenSSH_6.7p1 Debian-5+deb8u3, OpenSSL 1.0.1t  3 May 2016
> debug1: Reading configuration data /etc/ssh/ssh_config
> debug1: /etc/ssh/ssh_config line 19: Applying options for *
> debug2: ssh_connect: needpriv 0
> debug1: Connecting to 192.168.1.56 [192.168.1.56] port 22.
> debug2: fd 3 setting O_NONBLOCK
> 
> debug1: connect to address 192.168.1.56 port 22: Connection timed out
> ssh: connect to host 192.168.1.56 port 22: Connection timed out
> +++ abort_job 'Error while ROOTFS_FWVER command execution on target'
> +++ set +x
> 

There are 3 commands before the 'echo "Firmware revision" ...' command.
 * rm -rf /home/a/* /tmp/* /home/a/.local
 * true
 * uname -r | xargs echo

I presume that all these commands run OK on the target, and that:
 * 'echo "Firmware revision:" 4.7.4-IMX6.VAR_R17'
is the first one that times out?

Is this consistent?  Does the timeout occur on any other commands or is it
always this one?

Given what I see above, I think you have an honest-to-goodness networking
problem between your host and your target.  The TCP connection (before
doing all the authentication stuff for SSH) is not getting established on this execution
of ssh.  You should be seeing the following two lines, after the lines trying to 
stabling the connection:
debug1: fd 3 clearing O_NONBLOCK
debug1: Connection established

After this error occurs, is there anything in the kernel messages on the target about
the Ethernet link dropping?

If you run the test again, do the first three commands work again?

If the board has fundamental networking problems (ie the networking is flaky),
then we can't really do any testing with it, with current Fuego.  We have plans
to work on support for operating on boards that only have serial console support,
but that work won't be done for a few months.

Sorry to not be able to help more.
 -- Tim



More information about the Fuego mailing list