Cisco NXOS devices time out after upgrading to docker image master-e62e12b

[ffeingold-clmke]

• [ X] I have read and understood docs/Issues.md.

Describe the bug
We are running Oxidized under docker. Yesterday we upgraded to master-e62e12b and some Cisco NXOS devices starting failing (saying it timed out). We enabled debug and saved the SSH log to a device that was failing. We then reverted to master-918108d and it started working again. We also saved the debug log.

To Reproduce
Configure Oxidized, under docker, running latest to backup a Cisco NXOS device. Enable debug.

1. Examine the last line of the debug file. We see:
   sent cmd "exit\n" (but no related receive, so the process just hangs until it times out)

Expected behavior
Setup the same configuration, but use master-918108d instead of latest. Examine the debug log and you will see:

sent cmd "exit\n"
received "exit\r\r\n"

Running environment (please complete the following information):

• OS: Ubuntu 24.04
• oxidized version: Docker image master-e62e12b
• oxidized-web version: N/A
• Manufacturer model an software version: Cisco N9K-C93108TC-EX 10.3(6)
• oxidized model name: NXOS

Additional context
Under the "Unreleased" change log, this seems like it might be related to: "perle: remove trailing \r (the device sends \r\r\n) (@robertcheramy)"

[ytti]

Problem may be lack of calling @ssh.loop here 85c0eb7

I suspect we may not be actually sending 'pre_logout' out. We likely just enqueue it to CHANNEL_DATA, but never dequeue it to wire. So no matter how long we wait channels, the channels aren't closing.
I never quite liked how I implemented 'pre_logout', I knew it is iffy but didn't want to spend time thinking about it. So I'm just using 'cmd' without expecting strings back. So the termination always is gonna be kinda surprise to us. I feared if I try to be more explicit, I run into all kind of bad implementations and decided this rather brute force way about it.

[robertcheramy]

Unfortunately, I cannot reproduce, using C93180YC-FX3H / version 10.4(5).

Like @ytti, I suspect the regression has been introduced by #3721 especialy:

SSH#disconnect directly calls @ssh.close, as #close waits for the channels to be closed anyway. This should work the same way as calling @ssh.loop and @ssh.close after a timeout. I don't expect a regression here, but there might be side effects, the Net::SSH library is complex.

[ytti]

I'm not sure if @ssh.close will dequeue CHANNEL_DATA.

This is likely race condition sensitive, depending on how busy your system is.

If #disconnect returns too fast, I think we may have data just in CHANNEL_DATA, not dequeued into wire. So we never actually ask the remote host to disconnect us. And I suspect @ssh.close doesn't run the loop, it doesn't try to dequeue CHANNEL_DATA to wire?

[robertcheramy]

@ffeingold-clmke Could you try 85c0eb7 and 787f2cd ?
If our suspicion is correct, the first should fail, the second work.

There are no docker images for these commits, but you can build one from git:

git clone https://github.com/ytti/oxidized.git
cd oxidized
git checkout 85c0eb74f27c1168c5cda1337f54a2c8c838e1c3
rake build_container

[ytti]

Second is link to a TFTP commit, I think you mispasted.

[robertcheramy]

Second is link to a TFTP commit, I think you mispasted.

This ist the last commit before changing the behavior of disconnect. If it works, the fix is easy - revert commit 85c0eb7

[ytti]

https://github.com/net-ssh/net-ssh/blob/master/lib/net/ssh/connection/session.rb#L121

Maybe the problem is
a) we have 'exit' in CHANNEL_DATA
b) we close the channel, and for what ever reason this blocks us from dequeueing CHANNEL_DATA, but doesn't close it
c) we loop until there are no more channels

I tried to read net-ssh source, but it wasn't immediately obvious to me what happens after Session#close closes all channals, where Channel only sets '@closing' to true. What exactly does it mean that it is @closing, it affects event loop somehow, but I couldn't immediately see how.

This may be bug in net-ssh, it does look like from code that intention was that CHANNEL_DATA will be empty, but maybe due to bug there is race condition that you can actually have still data left in CHANNEL_DATA, without calling loop (or probably even just #process once).

[ffeingold-clmke]

@robertcheramy I will see what we can do, but I don't have a Ruby development environment, so building the image may take a bit/be a challenge.

[ytti]

Can you just manually edit the files in question, to restore the previous #disconnect behaviour? If that fixes it, we have confirmation to our theory, and we can produce fix to the master, which you can then consume from docker?

[ffeingold-clmke]

@ytti Yes, I can do that, just need a little direction on what to apply. Is it this pull request: https://github.com/ytti/oxidized/pull/3721/files

[ytti]

85c0eb7

you need to revert this, so that disconnect keeps calling @ssh.loop. Our theory is, we need the @ssh.loop to dequeue the exit into the wire.

[robertcheramy]

Here are instruction for an hotfix without rebuilding the container image:

1. Start the container docker.io/oxidized/oxidized:latest as you always do
2. Find the container instance name with docker ps
3. Run a shell into the container: docker exec -it <container_instance_name> bash
4. In the container: vi /var/lib/gems/3.3.0/gems/oxidized-0.35.0/lib/oxidized/input/ssh.rb (sorry, I've got only vi to provide, it should work with the instructions below...)
5. Go to line 72 (72G)
6. Go into inset mode i
7. Paste following text:

    def disconnect
      disconnect_cli
      # if disconnect does not disconnect us, give up after timeout
      Timeout.timeout(@node.timeout) { @ssh.loop }
    rescue Errno::ECONNRESET, Net::SSH::Disconnect, IOError => e
      logger.debug 'The other side closed the connection while ' \
                   "disconnecting, raising #{e.class} with #{e.message}"
    rescue Timeout::Error
      logger.debug "#{@node.name} timed out while disconnecting"
    ensure
      @log.close if Oxidized.config.input.debug?
      (@ssh.close rescue true) unless @ssh.closed? # rubocop:disable Style/RedundantParentheses
    end

8. Exit insert mode (Press ESC key)
9. Write and quit (:wq) - if you encountered a Problem in vi, you can exit without saving with ESC, then :q!and return to step 4.
10. Still inside the container, find the PID of oxidized with ps ax | grep bin/[o]xidized (on my container, it is PID 9
11. Kill the process (kill <process-id>)
12. Exit the shell in the container instance (exit)

Oxidized will restart automatically with the new code. The hotfix is only in the container instance, restarting the container will restore the old code.

I will also provide a container with the fix, which will be easier to test.