Shopify / toxiproxy

:alarm_clock: :fire: A TCP proxy to simulate network and system conditions for chaos and resiliency testing
https://github.com/shopify/toxiproxy
MIT License
10.83k stars 449 forks source link

Fails to connect after peer-reset #465

Closed mpet closed 1 year ago

mpet commented 2 years ago

Hi again :-)

I am using the following code ( see below).

This is the scenario:

  1. I put a breakpoint here: System.out.println("before toxi") and one after at System.out.println("after toxi");
  2. Then I run debug and it stops at first breakpoint.
  3. I connect with a ssh client and a send a NETCONF message. ssh netconf@localhost -p 58127 -s netconf < rpc.xml

Port is from this line: LOGGER.info("mapped port for toxiproxy {}",toxiproxy.getMappedPort(8666));

This is successful!! I can connect.

  1. Then I step debugger. I reset peer for 10 seconds to "simulate" a Netopeer2 down.

netopeer2Proxy.toxics().resetPeer("reset-peer-down", ToxicDirection.UPSTREAM, 10);

I test: ssh netconf@localhost -p 58127 -s netconf < rpc.xml kex_exchange_identification: Connection closed by remote host Connection closed by ::1 port 58127

That seems ok! No connection since we reset peer.

  1. Then I move to last line: System.out.println("after toxi");

I try to connect using.

ssh netconf@localhost -p 58127 -s netconf < rpc.xml kex_exchange_identification: Connection closed by remote host Connection closed by ::1 port 58127 But this time it does not work!

Any hints! Do you know if anyone tried with SSH?

br,

//mike

Code used: `public class ToxiProxyTest {

private static final Network network = Network.newNetwork();
private static Proxy netopeer2Proxy;

private static final int NETCONF_SSH_PORT = 830;

//private static GenericContainer<?> netopeer2;

private static final Logger LOGGER = LoggerFactory.getLogger(ToxiProxyTest.class.getSimpleName());

@BeforeClass
public void setup() throws Exception {
    //create the toxyproxy image and start.
    final ToxiproxyContainer toxiproxy = new ToxiproxyContainer("ghcr.io/shopify/toxiproxy:2.5.0")
            .withNetwork(network);
    toxiproxy.start();

    //create the NETCONF server and start (listens on port 830 for SSH).
    final GenericContainer netopeer2 = new GenericContainer("sysrepo/sysrepo-netopeer2:latest").withExposedPorts(NETCONF_SSH_PORT).withNetwork(network).withNetworkAliases("netopeer2");
    netopeer2.start();

    // configure toxiproxy.
    LOGGER.info("toxiProxy host {} port {}", toxiproxy.getHost(), toxiproxy.getControlPort());
    ToxiproxyClient toxiproxyClient = new ToxiproxyClient(toxiproxy.getHost(), toxiproxy.getControlPort());

    LOGGER.info("mapped port for netopeer2 {}",netopeer2.getMappedPort(830));

    // listen on 8666 and transfer to 830
    netopeer2Proxy = toxiproxyClient.createProxy("netopeer2", "0.0.0.0:8666", "netopeer2:830");

    LOGGER.info("mapped port for toxiproxy {}",toxiproxy.getMappedPort(8666));

}

@Test(enabled = true, description = "", groups = { "netopeer2" })
public void testSshutdownWoClosingNetopeer2() throws Exception {
    // wait
    System.out.println("before toxi");
    netopeer2Proxy.toxics().resetPeer("reset-peer-down", ToxicDirection.UPSTREAM, 10);  
    System.out.println("after toxi");

}`
mpet commented 2 years ago

This is the log from the ToxiProxy docker instance.

`ToxiProxy log

Successful connect

{"level":"info","host":"0.0.0.0","port":"8474","version":"2.5.0","caller":"api.go:119","time":"2022-11-16T16:44:13Z","message":"Starting HTTP server on endpoint 0.0.0.0:8474"}

{"level":"info","name":"netopeer2","listen":"0.0.0.0:8666","upstream":"netopeer2:830","caller":"proxy.go:118","time":"2022-11-16T16:44:16Z","message":"Started proxy"}

{"level":"info","name":"netopeer2","listen":"0.0.0.0:8666","upstream":"netopeer2:830","client":"192.168.144.1:33614","caller":"proxy.go:186","time":"2022-11-16T16:44:39Z","message":"Accepted client"}

Rest peer:

{"level":"warn","name":"netopeer2","listen":"0.0.0.0:8666","upstream":"netopeer2:830","bytes":2257,"error":"read tcp 192.168.144.2:8666->192.168.144.1:33614: use of closed network connection","caller":"link.go:127","time":"2022-11-16T16:45:48Z","message":"Source terminated"}

New ssh connection after reset peer.

After reset:

{"level":"info","name":"netopeer2","listen":"0.0.0.0:8666","upstream":"netopeer2:830","client":"192.168.144.1:35340","caller":"proxy.go:186","time":"2022-11-16T16:47:21Z","message":"Accepted client"}

{"level":"warn","name":"netopeer2","listen":"0.0.0.0:8666","upstream":"netopeer2:830","bytes":22,"error":"read tcp 192.168.144.2:57290->192.168.144.3:830: use of closed network connection","caller":"link.go:127","time":"2022-11-16T16:47:21Z","message":"Source terminated"}

{"level":"warn","name":"netopeer2","listen":"0.0.0.0:8666","upstream":"netopeer2:830","bytes":21,"error":"read tcp 192.168.144.2:8666->192.168.144.1:35340: use of closed network connection","caller":"link.go:127","time":"2022-11-16T16:47:21Z","message":"Source terminated"} `

mpet commented 1 year ago

Bump! Anyone with input? What am I missing for SSH connections?

miry commented 1 year ago

@mpet There is no 24/7 support for such type of questions. You should take in account, that I have work to do and does not have time to help with networking debugging, without have environment similar to yours.

I can only suggest to use tools like Wireshark or tcpdump to debug network packets. If you find some issue with Toxiproxy could not process packates, than I would like to work on it.

If you want see more logs from Toxiproxy you can add environment LOG_LEVEL=debug.

Thank you for understanding.

mpet commented 1 year ago

@miry I perfectly understand since I maintained an opensource plugin for clearcase and eclipse for a long time. But it is natural to turn to maintainers when you have problems since the experts are you. I mean you could have experience of similar situations that happened in the past. If nothing from the past has happened I guess your hints could be a step on the way.

//mike

mpet commented 1 year ago

I have now verified that the issue is with toxiproxy.

I have tested with just the regular ssh client, OpenSSH_9.0

Setup is as before with the following modification:

OpenSSH client -- SSH --> ToxiProxy -- SSH --> Netopeer2

Then I debug my attached testcase and stop at first breakpoint.

System.out.println("before toxi");

At this point is possible to perform a successful SSH connect. See log below:

`$ ssh -v netconf@localhost -p 54456 -s netconf OpenSSH_9.0p1, OpenSSL 1.1.1o 3 May 2022 debug1: Reading configuration data /etc/ssh/ssh_config debug1: Connecting to localhost [::1] port 54456. debug1: Connection established. debug1: identity file /c/Users/eraonel/.ssh/id_rsa type 0 debug1: identity file /c/Users/eraonel/.ssh/id_rsa-cert type -1 debug1: identity file /c/Users/eraonel/.ssh/id_ecdsa type -1 debug1: identity file /c/Users/eraonel/.ssh/id_ecdsa-cert type -1 debug1: identity file /c/Users/eraonel/.ssh/id_ecdsa_sk type -1 debug1: identity file /c/Users/eraonel/.ssh/id_ecdsa_sk-cert type -1 debug1: identity file /c/Users/eraonel/.ssh/id_ed25519 type -1 debug1: identity file /c/Users/eraonel/.ssh/id_ed25519-cert type -1 debug1: identity file /c/Users/eraonel/.ssh/id_ed25519_sk type -1 debug1: identity file /c/Users/eraonel/.ssh/id_ed25519_sk-cert type -1 debug1: identity file /c/Users/eraonel/.ssh/id_xmss type -1 debug1: identity file /c/Users/eraonel/.ssh/id_xmss-cert type -1 debug1: identity file /c/Users/eraonel/.ssh/id_dsa type -1 debug1: identity file /c/Users/eraonel/.ssh/id_dsa-cert type -1 debug1: Local version string SSH-2.0-OpenSSH_9.0 debug1: Remote protocol version 2.0, remote software version libssh_0.9.5 debug1: compat_banner: no match: libssh_0.9.5 debug1: Authenticating to localhost:54456 as 'netconf' debug1: load_hostkeys: fopen /c/Users/eraonel/.ssh/known_hosts2: No such file or directory debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory debug1: SSH2_MSG_KEXINIT sent debug1: SSH2_MSG_KEXINIT received debug1: kex: algorithm: curve25519-sha256 debug1: kex: host key algorithm: rsa-sha2-512 debug1: kex: server->client cipher: aes128-ctr MAC: hmac-sha2-256-etm@openssh.com compression: none debug1: kex: client->server cipher: aes128-ctr MAC: hmac-sha2-256-etm@openssh.com compression: none debug1: expecting SSH2_MSG_KEX_ECDH_REPLY debug1: SSH2_MSG_KEX_ECDH_REPLY received debug1: Server host key: ssh-rsa SHA256:4dfREFhjQJ9Mpv1PJOJHaM2n0NTM4oJLoLIx8z+xAJU debug1: load_hostkeys: fopen /c/Users/eraonel/.ssh/known_hosts2: No such file or directory debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory debug1: checking without port identifier debug1: load_hostkeys: fopen /c/Users/eraonel/.ssh/known_hosts2: No such file or directory debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory debug1: hostkeys_find_by_key_cb: found matching key in ~/.ssh/known_hosts:22 debug1: hostkeys_find_by_key_cb: found matching key in ~/.ssh/known_hosts:23 debug1: hostkeys_find_by_key_cb: found matching key in ~/.ssh/known_hosts:24 debug1: hostkeys_find_by_key_cb: found matching key in ~/.ssh/known_hosts:25 debug1: hostkeys_find_by_key_cb: found matching key in ~/.ssh/known_hosts:26 debug1: hostkeys_find_by_key_cb: found matching key in ~/.ssh/known_hosts:27 debug1: hostkeys_find_by_key_cb: found matching key in ~/.ssh/known_hosts:28 debug1: hostkeys_find_by_key_cb: found matching key in ~/.ssh/known_hosts:29 debug1: hostkeys_find_by_key_cb: found matching key in ~/.ssh/known_hosts:30 debug1: hostkeys_find_by_key_cb: found matching key in ~/.ssh/known_hosts:31 debug1: hostkeys_find_by_key_hostfile: hostkeys file /c/Users/eraonel/.ssh/known_hosts2 does not exist debug1: hostkeys_find_by_key_hostfile: hostkeys file /etc/ssh/ssh_known_hosts does not exist debug1: hostkeys_find_by_key_hostfile: hostkeys file /etc/ssh/ssh_known_hosts2 does not exist The authenticity of host '[localhost]:54456 ([::1]:54456)' can't be established. RSA key fingerprint is SHA256:4dfREFhjQJ9Mpv1PJOJHaM2n0NTM4oJLoLIx8z+xAJU. This host key is known by the following other names/addresses: ~/.ssh/known_hosts:22: [localhost]:53619 ~/.ssh/known_hosts:23: [localhost]:57115 ~/.ssh/known_hosts:24: [localhost]:57798 ~/.ssh/known_hosts:25: [localhost]:57880 ~/.ssh/known_hosts:26: [localhost]:58041 ~/.ssh/known_hosts:27: [localhost]:58127 ~/.ssh/known_hosts:28: [localhost]:58130 ~/.ssh/known_hosts:29: [localhost]:58351 (2 additional names omitted) Are you sure you want to continue connecting (yes/no/[fingerprint])? y Please type 'yes', 'no' or the fingerprint: yes Warning: Permanently added '[localhost]:54456' (RSA) to the list of known hosts. debug1: rekey out after 4294967296 blocks debug1: SSH2_MSG_NEWKEYS sent debug1: expecting SSH2_MSG_NEWKEYS debug1: SSH2_MSG_NEWKEYS received debug1: rekey in after 4294967296 blocks debug1: Will attempt key: /c/Users/eraonel/.ssh/id_rsa RSA SHA256:t6hityJf63hWTgutnks2UPKCbKlnpi41TUOd3qVtfWw debug1: Will attempt key: /c/Users/eraonel/.ssh/id_ecdsa debug1: Will attempt key: /c/Users/eraonel/.ssh/id_ecdsa_sk debug1: Will attempt key: /c/Users/eraonel/.ssh/id_ed25519 debug1: Will attempt key: /c/Users/eraonel/.ssh/id_ed25519_sk debug1: Will attempt key: /c/Users/eraonel/.ssh/id_xmss debug1: Will attempt key: /c/Users/eraonel/.ssh/id_dsa debug1: SSH2_MSG_EXT_INFO received debug1: kex_input_ext_info: server-sig-algs=ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-dss-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss debug1: SSH2_MSG_SERVICE_ACCEPT received debug1: Authentications that can continue: publickey,keyboard-interactive,password debug1: Next authentication method: publickey debug1: Offering public key: /c/Users/eraonel/.ssh/id_rsa RSA SHA256:t6hityJf63hWTgutnks2UPKCbKlnpi41TUOd3qVtfWw debug1: Authentications that can continue: publickey,keyboard-interactive,password debug1: Trying private key: /c/Users/eraonel/.ssh/id_ecdsa debug1: Trying private key: /c/Users/eraonel/.ssh/id_ecdsa_sk debug1: Trying private key: /c/Users/eraonel/.ssh/id_ed25519 debug1: Trying private key: /c/Users/eraonel/.ssh/id_ed25519_sk debug1: Trying private key: /c/Users/eraonel/.ssh/id_xmss debug1: Trying private key: /c/Users/eraonel/.ssh/id_dsa debug1: Next authentication method: keyboard-interactive Interactive SSH Authentication Type your password: (netconf@localhost) Password: Authenticated to localhost ([::1]:54456) using "keyboard-interactive". debug1: channel 0: new [client-session] debug1: Entering interactive session. debug1: pledge: filesystem debug1: Sending subsystem: netconf

urn:ietf:params:netconf:base:1.0urn:ietf:params:netconf:base:1.1urn:ietf:params:netconf:capability:writable-running:1.0urn:ietf:params:netconf:capability:candidate:1.0urn:ietf:params:netconf:capability:rollback-on-error:1.0urn:ietf:params:netconf:capability:validate:1.1urn:ietf:params:netconf:capability:startup:1.0urn:ietf:params:netconf:capability:xpath:1.0urn:ietf:params:netconf:capability:with-defaults:1.0?basic-mode=explicit&also-supported=report-all,report-all-tagged,trim,expliciturn:ietf:params:netconf:capability:notification:1.0urn:ietf:params:netconf:capability:interleave:1.0urn:ietf:params:xml:ns:yang:ietf-yang-metadata?module=ietf-yang-metadata&revision=2016-08-05urn:ietf:params:xml:ns:yang:1?module=yang&revision=2017-02-20urn:ietf:params:xml:ns:yang:ietf-inet-types?module=ietf-inet-types&revision=2013-07-15urn:ietf:params:xml:ns:yang:ietf-yang-types?module=ietf-yang-types&revision=2013-07-15urn:ietf:params:netconf:capability:yang-library:1.1?revision=2019-01-04&content-id=32urn:sysrepo:plugind?module=sysrepo-plugind&revision=2020-12-10urn:ietf:params:xml:ns:yang:ietf-netconf-acm?module=ietf-netconf-acm&revision=2018-02-14urn:ietf:params:xml:ns:netconf:base:1.0?module=ietf-netconf&revision=2013-09-29&features=writable-running,candidate,rollback-on-error,validate,startup,url,xpathurn:ietf:params:xml:ns:yang:ietf-netconf-with-defaults?module=ietf-netconf-with-defaults&revision=2011-06-01urn:ietf:params:xml:ns:yang:ietf-netconf-notifications?module=ietf-netconf-notifications&revision=2012-02-06urn:ietf:params:xml:ns:yang:ietf-netconf-monitoring?module=ietf-netconf-monitoring&revision=2010-10-04urn:ietf:params:xml:ns:netconf:notification:1.0?module=notifications&revision=2008-07-14urn:ietf:params:xml:ns:netmod:notification?module=nc-notifications&revision=2008-07-14urn:ietf:params:xml:ns:yang:ietf-x509-cert-to-name?module=ietf-x509-cert-to-name&revision=2014-12-10urn:ietf:params:xml:ns:yang:iana-crypt-hash?module=iana-crypt-hash&revision=2014-08-061]]>]]> ` Then I step past and execute the toxiproxy line: netopeer2Proxy.toxics().resetPeer("reset-peer-down", ToxicDirection.UPSTREAM, 10); Then I assume that the toxic should be gone after 10 seconds and we can connect again. **Correct?**' So I stop debugger at the last line: System.out.println("after toxi"); _Then I try to connect with SSH client and it fails._ `$ ssh -v netconf@localhost -p 54456 -s netconf OpenSSH_9.0p1, OpenSSL 1.1.1o 3 May 2022 debug1: Reading configuration data /etc/ssh/ssh_config debug1: Connecting to localhost [::1] port 54456. debug1: Connection established. debug1: identity file /c/Users/eraonel/.ssh/id_rsa type 0 debug1: identity file /c/Users/eraonel/.ssh/id_rsa-cert type -1 debug1: identity file /c/Users/eraonel/.ssh/id_ecdsa type -1 debug1: identity file /c/Users/eraonel/.ssh/id_ecdsa-cert type -1 debug1: identity file /c/Users/eraonel/.ssh/id_ecdsa_sk type -1 debug1: identity file /c/Users/eraonel/.ssh/id_ecdsa_sk-cert type -1 debug1: identity file /c/Users/eraonel/.ssh/id_ed25519 type -1 debug1: identity file /c/Users/eraonel/.ssh/id_ed25519-cert type -1 debug1: identity file /c/Users/eraonel/.ssh/id_ed25519_sk type -1 debug1: identity file /c/Users/eraonel/.ssh/id_ed25519_sk-cert type -1 debug1: identity file /c/Users/eraonel/.ssh/id_xmss type -1 debug1: identity file /c/Users/eraonel/.ssh/id_xmss-cert type -1 debug1: identity file /c/Users/eraonel/.ssh/id_dsa type -1 debug1: identity file /c/Users/eraonel/.ssh/id_dsa-cert type -1 debug1: Local version string SSH-2.0-OpenSSH_9.0 debug1: Remote protocol version 2.0, remote software version libssh_0.9.5 debug1: compat_banner: no match: libssh_0.9.5 debug1: Authenticating to localhost:54456 as 'netconf' debug1: load_hostkeys: fopen /c/Users/eraonel/.ssh/known_hosts2: No such file or directory debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory debug1: SSH2_MSG_KEXINIT sent Connection closed by ::1 port 54456` The connection is closed by ToxiProxy, see last line. And Netopeer2 is up and running. So the issue is that it is not possible to connect to ToxiProxy after these 10 seconds. I also checked with the Netopeer2 people and there is no problem in Netopeer2 for SSH. So yes I would like to report this as a bug. I found this: https://github.com/Shopify/toxiproxy/issues/238 but I did not see any verification of the function from user @holyjak I am using: - toxyproxy 2.5.0 docker image it uses toxiproxy-java 2.1.7 client - Docker Desktop 4.8.2 - ssh client OpenSSH_9.0p1 br, //mike [toxiproxybug.zip](https://github.com/Shopify/toxiproxy/files/10057348/toxiproxybug.zip)
mpet commented 1 year ago

@miry skip above I found out why mine is not working. I should not use proxy.disable and enable. It took some reading to find since it was not listed under toxies() method.