oxidized icon indicating copy to clipboard operation
oxidized copied to clipboard

Published 20 hours ago • verified publisher icon ytti

Oxidized v.0.30.1 backup FortiGate config issue - only backup 70% devices

Open KevinTang8888 opened this issue 10 months ago • 32 comments

Hi I installed Oxidized in my Ubuntu 22.04 server. system is up running without any error. first I loaded 6 Foritgate devices, all backup process fine. oxidized-web also showing green for each devices. Then I loaded 110 Fortigate devices, oxidized-web start showing blue, last update-never and last changed - unknown. Then I enabled SSH debug. If the Fortigate devices had backup successful, I can see their SSH log message. If the Fortigate failed config backup. I did not see their SSH log message. Also oxidized-web start crash after a few minutes.

oxidized.service - Oxidized - Network Device Configuration Backup Tool
     Loaded: loaded (/lib/systemd/system/oxidized.service; enabled; vendor preset: enabled)
     Active: active (running) since Mon 2024-04-15 08:58:56 NZST; **11min ago**
   Main PID: 4218 (oxidized)
      Tasks: 8 (limit: 38334)
     Memory: 223.3M
        CPU: 2min 57.388s
     CGroup: /system.slice/oxidized.service
             └─4218 "puma 3.11.4 (tcp://10.170.32.14:8888) [/]"

Apr 15 08:58:56 ubuntu2204 systemd[1]: Started Oxidized - Network Device Configuration Backup Tool.
Apr 15 08:58:57 ubuntu2204 oxidized[4218]: Puma starting in single mode...
Apr 15 08:58:57 ubuntu2204 oxidized[4218]: * Version 3.11.4 (ruby 3.0.2-p107), codename: Love Song
Apr 15 08:58:57 ubuntu2204 oxidized[4218]: * Min threads: 0, max threads: 16
Apr 15 08:58:57 ubuntu2204 oxidized[4218]: * Environment: development
Apr 15 08:58:57 ubuntu2204 oxidized[4218]: * Listening on tcp://10.170.32.14:8888
Apr 15 08:58:57 ubuntu2204 oxidized[4218]: Use Ctrl-C to stop

--------when oxidized.service crashed, i see this error----------

oxidized.service - Oxidized - Network Device Configuration Backup Tool
     Loaded: loaded (/lib/systemd/system/oxidized.service; enabled; vendor preset: enabled)
     Active: activating (auto-restart) (Result: exit-code) since Mon 2024-04-15 09:49:57 NZST; 2min 14s ago
    Process: 4261 ExecStart=/usr/local/bin/oxidized (code=exited, status=1/FAILURE)
   Main PID: 4261 (code=exited, status=1/FAILURE)
        CPU: 3min 31.563s

-------crash info-----------------------
test@ubuntu2204:~$ sudo cat /home/oxidized/.config/oxidized/crash

/var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/source/csv.rb:16:in `setup'
/var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/manager.rb:18:in `load'
/var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/manager.rb:61:in `loader'
/var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/manager.rb:44:in `add_source'
/var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/nodes.rb:14:in `block in load'
/var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/nodes.rb:133:in `synchronize'
/var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/nodes.rb:133:in `with_lock'
/var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/nodes.rb:11:in `load'
/var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/nodes.rb:128:in `initialize'
/var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/core.rb:14:in `new'
/var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/core.rb:14:in `initialize'
/var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/core.rb:4:in `new'
/var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/core.rb:4:in `new'
/var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/cli.rb:13:in `run'
/var/lib/gems/3.0.0/gems/oxidized-0.30.1/bin/oxidized:5:in `<top (required)>'
/usr/local/bin/oxidized:25:in `load'
/usr/local/bin/oxidized:25:in `<main>'

Not sure what's the problem, Any idea?

Regards

Kevin

(Updated by @robertcheramy for readability)

KevinTang8888 avatar Apr 14 '24 22:04 KevinTang8888

looks like the job only run 76 out 111 devices, then stopped and restart load previous devise again. Not sure why?

D, [2024-04-15T11:41:25.481373 #4626] DEBUG -- : lib/oxidized/worker.rb: Jobs running: 0 of 1 - ended: 70 of 111 D, [2024-04-15T11:41:37.509325 #4626] DEBUG -- : lib/oxidized/worker.rb: Jobs running: 0 of 1 - ended: 71 of 111 D, [2024-04-15T11:41:47.530287 #4626] DEBUG -- : lib/oxidized/worker.rb: Jobs running: 0 of 1 - ended: 72 of 111 D, [2024-04-15T11:41:58.552286 #4626] DEBUG -- : lib/oxidized/worker.rb: Jobs running: 0 of 1 - ended: 73 of 111 D, [2024-04-15T11:42:09.581955 #4626] DEBUG -- : lib/oxidized/worker.rb: Jobs running: 0 of 1 - ended: 74 of 111 D, [2024-04-15T11:42:19.604485 #4626] DEBUG -- : lib/oxidized/worker.rb: Jobs running: 0 of 1 - ended: 75 of 111 D, [2024-04-15T11:42:29.625075 #4626] DEBUG -- : lib/oxidized/worker.rb: Jobs running: 0 of 1 - ended: 76 of 111 D, [2024-04-15T11:47:37.719032 #4647] DEBUG -- : lib/oxidized/worker.rb: Jobs running: 0 of 1 - ended: 1 of 111 D, [2024-04-15T11:47:47.739068 #4647] DEBUG -- : lib/oxidized/worker.rb: Jobs running: 0 of 1 - ended: 2 of 111 D, [2024-04-15T11:47:57.757173 #4647] DEBUG -- : lib/oxidized/worker.rb: Jobs running: 0 of 1 - ended: 3 of 111 D, [2024-04-15T11:48:08.781535 #4647] DEBUG -- : lib/oxidized/worker.rb: Jobs running: 0 of 1 - ended: 4 of 111 D, [2024-04-15T11:48:19.807039 #4647] DEBUG -- : lib/oxidized/worker.rb: Jobs running: 0 of 1 - ended: 5 of 111

KevinTang8888 avatar Apr 15 '24 00:04 KevinTang8888

Is this a regression from 0.29.1 or did you directly try 0.30.1?

robertcheramy avatar Apr 15 '24 06:04 robertcheramy

This is directly using oxidized 0.30.1 with fresh new installation. not upgrade.

/var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/source/csv.rb:16:in `setup'

KevinTang8888 avatar Apr 15 '24 06:04 KevinTang8888

Please check the full error, try using journalctl -u oxidized.service then scroll (g) to the last lines. In the initial post you only see half of the error message.

Atroskelis avatar Apr 15 '24 08:04 Atroskelis

Thanks, this provided a lot of information, can see some errors. uploaded last block message, others are repeating:

Apr 15 21:16:28 ubuntu2204 oxidized[5956]: #<Oxidized::Job:0x000055e8c9237690 /var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/job.rb:8 ru> Apr 15 21:16:28 ubuntu2204 oxidized[5956]: /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/buffer.rb:342:in read_keyblob': unsupported key > Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/buffer.rb:248:in read_key' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/kex/abstract5656.rb:54:in > Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/kex/abstract.rb:48:in exc> Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/algorithms.rb:454:in exch> Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/algorithms.rb:253:in proc> Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/algorithms.rb:192:in acce> Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/session.rb:210:in block i> Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/session.rb:190:in loop' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/session.rb:190:in poll_me> Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/session.rb:227:in block i> Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/session.rb:224:in loop' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/session.rb:224:in wait' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/session.rb:89:in initiali> Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh.rb:258:in new' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh.rb:258:in start' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/input/ssh.rb:27:in connect' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/node.rb:70:in run_input' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/node.rb:47:in block in run' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/node.rb:41:in each' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/node.rb:41:in run' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/job.rb:10:in block in initialize' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/buffer.rb:342:in read_keyblob': unsupported key > Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/buffer.rb:248:in read_key' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/kex/abstract5656.rb:54:in > Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/kex/abstract.rb:48:in exc> Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/algorithms.rb:454:in exch> Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/algorithms.rb:253:in proc> Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/algorithms.rb:192:in acce> Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/session.rb:210:in block i> Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/session.rb:190:in loop' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/session.rb:190:in poll_me> Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/session.rb:227:in block i> Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/session.rb:224:in loop' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/session.rb:224:in wait' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/transport/session.rb:89:in initiali> Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh.rb:258:in new' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh.rb:258:in start' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/input/ssh.rb:27:in connect' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/node.rb:70:in run_input' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/node.rb:47:in block in run' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/node.rb:41:in each' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/node.rb:41:in run' Apr 15 21:16:28 ubuntu2204 oxidized[5956]: from /var/lib/gems/3.0.0/gems/oxidized-0.30.1/lib/oxidized/job.rb:10:in block in initialize' Apr 15 21:16:28 ubuntu2204 systemd[1]: oxidized.service: Main process exited, code=exited, status=1/FAILURE Apr 15 21:16:28 ubuntu2204 systemd[1]: oxidized.service: Failed with result 'exit-code'. Apr 15 21:16:28 ubuntu2204 systemd[1]: oxidized.service: Consumed 3min 30.331s CPU time. Apr 15 21:21:28 ubuntu2204 systemd[1]: oxidized.service: Scheduled restart job, restart counter is at 95. Apr 15 21:21:28 ubuntu2204 systemd[1]: Stopped Oxidized - Network Device Configuration Backup Tool. Apr 15 21:21:28 ubuntu2204 systemd[1]: oxidized.service: Consumed 3min 30.331s CPU time. Apr 15 21:21:28 ubuntu2204 systemd[1]: Started Oxidized - Network Device Configuration Backup Tool. Apr 15 21:21:29 ubuntu2204 oxidized[5974]: Puma starting in single mode... Apr 15 21:21:29 ubuntu2204 oxidized[5974]: * Version 3.11.4 (ruby 3.0.2-p107), codename: Love Song Apr 15 21:21:29 ubuntu2204 oxidized[5974]: * Min threads: 0, max threads: 16 Apr 15 21:21:29 ubuntu2204 oxidized[5974]: * Environment: development Apr 15 21:21:29 ubuntu2204 oxidized[5974]: * Listening on tcp://10.170.32.14:8888 Apr 15 21:21:29 ubuntu2204 oxidized[5974]: Use Ctrl-C to stop

KevinTang8888 avatar Apr 15 '24 09:04 KevinTang8888

buffer.rb#L342 error message should be raise NotImplementedError, "unsupported key type `#{type}'", suggesting key type is not RSA, DSA, ECDSA.

ytti avatar Apr 15 '24 09:04 ytti

I am getting lost, is that net-ssh-7.2.3 problem? How to fix this not supported key issue?

  # Read a keyblob of the given type from the buffer, and return it as
  # a key. Only RSA, DSA, and ECDSA keys are supported.
    else
      raise NotImplementedError, "unsupported key type `#{type}'"
    end

KevinTang8888 avatar Apr 16 '24 05:04 KevinTang8888

I'd say search through the logs, see if you can find exactly what key type does it not support. I also had issues with net-ssh and fortigates. see #3123. In my case i opened an issue to net-ssh project itself.

I did try to change the kex on the fortigates but it would still pick the one that it doesn't work, but you can experiment.

Atroskelis avatar Apr 16 '24 05:04 Atroskelis

FortiGate support ED25519 key, also net-ssh 5 and later support ed25519

https://github.com/net-ssh/net-ssh/issues/565

Why buffer.rb script only support RSA, DSA, and ECDSA keys? Can ED25519 key be added in for support?

KevinTang8888 avatar Apr 17 '24 02:04 KevinTang8888

FortiGate support ED25519 key, also net-ssh 5 and later support ed25519

ed25519 host keys work just fine - https://github.com/net-ssh/net-ssh/blob/master/lib/net/ssh/buffer.rb#L336

Why buffer.rb script only support RSA, DSA, and ECDSA keys? Can ED25519 key be added in for support?

They are supported right now. The problem is fortinet is advertising ssh-rsa key types as rsa-sha2-512, which is invalid behaviour, and break some ssh implementations, like net-ssh. It would be possible to change net-ssh so that it ignores invalid host keys, and as long as it receives >0 valid, it continues. Right now, it sees the host advertising broken host key and it quits.

ytti avatar Apr 17 '24 05:04 ytti

What needs to happen herei is that fortinet needs to be fixed, it needs to start advertiising its RSA key types correctly as ssh-rsa, instead of rsa-sha2-512.

In the meanwhile, #3123 has workaround where you can change 1 line in buffer.rb to define rsa-sha2-512as key type which is treated same as ssh-rsa.

We could also submit fix to net-ssh, where we change behaviour so that it doesn't raise error on unparseable host keys, but continues and raises later if it couldn't find at least 1 parseable host key. I could look into that, but I don't have fortinet to test against.

ytti avatar Apr 17 '24 05:04 ytti

To recreate the problem without using oxidized, try the following:

Create a test.rb with the contents:

gem 'net-ssh', '= 7.2.3'
require 'net/ssh'
puts Net::SSH::Version::CURRENT

@host = 'localhost'
@user = ENV['USER']
Net::SSH.start(@host, @user) do |ssh|
  puts ssh.exec!('echo "hello"')
end

replace @host with the device IP and @user with 'some username'

Save, then do ruby test.rb

It should give you the same error without the trouble of searching through logs.

Atroskelis avatar Apr 17 '24 06:04 Atroskelis

when /^ssh-rsa$/, /^rsa-sha2-(256|512)$/ does not work for me. I still get the error message: Apr 17 21:00:42 ubuntu2204 oxidized[21859]: /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/buffer.rb:342:in read_keyblob': unsupported key type >

because some of the FortiGate finished the config backup process. here is one of the working Net:SSH debug info.

irb(main):009:0> Net::SSH.start("10.8.254.254", "usernamexx", :password => "passwordxx", verbose: Logger::DEBUG) D, [2024-04-17T17:33:52.453654 #21409] DEBUG -- net.ssh.transport.session[2f8]: establishing connection to 10.8.254.254:22 D, [2024-04-17T17:33:52.459108 #21409] DEBUG -- net.ssh.transport.session[2f8]: connection established I, [2024-04-17T17:33:52.459228 #21409] INFO -- net.ssh.transport.server_version[30c]: negotiating protocol version D, [2024-04-17T17:33:52.459275 #21409] DEBUG -- net.ssh.transport.server_version[30c]: local is SSH-2.0-Ruby/Net::SSH_7.2.3 x86_64-linux-gnu' D, [2024-04-17T17:33:52.471619 #21409] DEBUG -- net.ssh.transport.server_version[30c]: remote is SSH-2.0-AqTN-' I, [2024-04-17T17:33:52.472313 #21409] INFO -- net.ssh.transport.algorithms[320]: sending KEXINIT D, [2024-04-17T17:33:52.472565 #21409] DEBUG -- socket[334]: queueing packet nr 0 type 20 len 852 D, [2024-04-17T17:33:52.472793 #21409] DEBUG -- socket[334]: sent 856 bytes D, [2024-04-17T17:33:52.476644 #21409] DEBUG -- socket[334]: read 552 bytes D, [2024-04-17T17:33:52.476726 #21409] DEBUG -- socket[334]: received packet nr 0 type 20 len 548 I, [2024-04-17T17:33:52.476825 #21409] INFO -- net.ssh.transport.algorithms[320]: got KEXINIT from server I, [2024-04-17T17:33:52.476898 #21409] INFO -- net.ssh.transport.algorithms[320]: negotiating algorithms D, [2024-04-17T17:33:52.477025 #21409] DEBUG -- net.ssh.transport.algorithms[320]: negotiated:

  • kex: ecdh-sha2-nistp521
  • host_key: ssh-ed25519
  • encryption_server: aes256-ctr
  • encryption_client: aes256-ctr
  • hmac_client: [email protected]
  • hmac_server: [email protected]
  • compression_client: none
  • compression_server: none
  • language_client:
  • language_server: D, [2024-04-17T17:33:52.477067 #21409] DEBUG -- net.ssh.transport.algorithms[320]: exchanging keys D, [2024-04-17T17:33:52.477473 #21409] DEBUG -- socket[334]: queueing packet nr 1 type 30 len 148 D, [2024-04-17T17:33:52.477538 #21409] DEBUG -- socket[334]: sent 152 bytes D, [2024-04-17T17:33:52.586774 #21409] DEBUG -- socket[334]: read 312 bytes D, [2024-04-17T17:33:52.587105 #21409] DEBUG -- socket[334]: received packet nr 1 type 31 len 292 D, [2024-04-17T17:33:52.600134 #21409] DEBUG -- socket[334]: queueing packet nr 2 type 21 len 20 D, [2024-04-17T17:33:52.600623 #21409] DEBUG -- socket[334]: sent 24 bytes D, [2024-04-17T17:33:52.600866 #21409] DEBUG -- socket[334]: received packet nr 2 type 21 len 12 D, [2024-04-17T17:33:52.601890 #21409] DEBUG -- net.ssh.authentication.session[348]: beginning authentication of `usernamexx' D, [2024-04-17T17:33:52.602128 #21409] DEBUG -- socket[334]: using encrypt-then-mac D, [2024-04-17T17:33:52.602463 #21409] DEBUG -- socket[334]: queueing packet nr 3 type 5 len 32 D, [2024-04-17T17:33:52.602707 #21409] DEBUG -- socket[334]: sent 100 bytes D, [2024-04-17T17:33:52.613060 #21409] DEBUG -- socket[334]: read 100 bytes D, [2024-04-17T17:33:52.613845 #21409] DEBUG -- socket[334]: received packet nr 3 type 6 len 32 D, [2024-04-17T17:33:52.614305 #21409] DEBUG -- net.ssh.authentication.session[348]: trying none D, [2024-04-17T17:33:52.614683 #21409] DEBUG -- socket[334]: using encrypt-then-mac D, [2024-04-17T17:33:52.615430 #21409] DEBUG -- socket[334]: queueing packet nr 4 type 50 len 64 D, [2024-04-17T17:33:52.615827 #21409] DEBUG -- socket[334]: sent 132 bytes D, [2024-04-17T17:33:52.633956 #21409] DEBUG -- socket[334]: read 888 bytes D, [2024-04-17T17:33:52.634533 #21409] DEBUG -- socket[334]: received packet nr 4 type 53 len 720 I, [2024-04-17T17:33:52.634751 #21409] INFO -- net.ssh.authentication.session[348]: PRE WARNING: This is a private computer system. Unauthorized access or use is prohibited and subject to prosecution and/or disciplinary action. Any use of this system constitutes consent to monitoring at all times and users are not entitled to any expectation of privacy. If monitoring reveals possible evidence of violation of criminal statutes, this evidence and any other related information, including identification information about the user, may be provided to law enforcement officials. If monitoring reveals violations of security regulations or unauthorized use, employees who violate security regulations or make unauthorized use of this system are subject to appropriate disciplinary action.

D, [2024-04-17T17:33:52.635300 #21409] DEBUG -- socket[334]: received packet nr 5 type 51 len 32 D, [2024-04-17T17:33:52.635590 #21409] DEBUG -- net.ssh.authentication.session[348]: allowed methods: publickey,password D, [2024-04-17T17:33:52.635802 #21409] DEBUG -- net.ssh.authentication.methods.none[35c]: none failed D, [2024-04-17T17:33:52.636037 #21409] DEBUG -- net.ssh.authentication.session[348]: trying publickey D, [2024-04-17T17:33:52.636596 #21409] DEBUG -- net.ssh.authentication.agent[370]: connecting to ssh-agent E, [2024-04-17T17:33:52.636784 #21409] ERROR -- net.ssh.authentication.agent[370]: could not connect to ssh-agent: Agent not configured D, [2024-04-17T17:33:52.637048 #21409] DEBUG -- net.ssh.authentication.session[348]: trying password D, [2024-04-17T17:33:52.637373 #21409] DEBUG -- socket[334]: using encrypt-then-mac D, [2024-04-17T17:33:52.637688 #21409] DEBUG -- socket[334]: queueing packet nr 5 type 50 len 80 D, [2024-04-17T17:33:52.638107 #21409] DEBUG -- socket[334]: sent 148 bytes D, [2024-04-17T17:33:52.704887 #21409] DEBUG -- socket[334]: read 84 bytes D, [2024-04-17T17:33:52.705439 #21409] DEBUG -- socket[334]: received packet nr 6 type 52 len 16 D, [2024-04-17T17:33:52.705725 #21409] DEBUG -- net.ssh.authentication.methods.password[384]: password succeeded => #<Net::SSH::Connection::Session:0x0000563ec02ca268 @channel_id_counter=-1, @channel_open_handlers={}, @channels={}, @event_loop= #<Net::SSH::Connection::SingleSessionEventLoop:0x0000563ec02c9f98 @logger=nil, @sessions=[#<Net::SSH::Connection::Session:0x0000563ec02ca268 ...>]>, @keepalive= #<Net::SSH::Connection::Keepalive:0x0000563ec02c9fe8 @last_keepalive_sent_at=nil, @logger= #<Logger:0x0000563ebff868e0 @default_formatter=#<Logger::Formatter:0x0000563ebff867c8 @datetime_format=nil>, @formatter=nil, @level=0, @logdev= #<Logger::LogDevice:0x0000563ebff86700 @binmode=false, @dev=#<IO:<STDERR>>, @filename=nil, @mon_data=#Monitor:0x0000563ebff86660, @mon_data_owner_object_id=740, @shift_age=nil, @shift_period_suffix=nil, @shift_size=nil>, @progname=nil>, @session=#<Net::SSH::Connection::Session:0x0000563ec02ca268 ...>, @unresponded_keepalive_count=0>, @listeners={#<Socket:fd 5>=>nil}, @logger= #<Logger:0x0000563ebff868e0 @default_formatter=#<Logger::Formatter:0x0000563ebff867c8 @datetime_format=nil>, @formatter=nil, @level=0, @logdev= #<Logger::LogDevice:0x0000563ebff86700 @binmode=false, @dev=#<IO:<STDERR>>, @filename=nil, @mon_data=#Monitor:0x0000563ebff86660, @mon_data_owner_object_id=740, @shift_age=nil, @shift_period_suffix=nil, @shift_size=nil>, @progname=nil>, @max_pkt_size=32768, @max_win_size=131072, @on_global_request={}, @options= {:auth_methods=>["none", "publickey", "password", "keyboard-interactive"], :send_env=>[/^LANG$/, /^LC_.$/], :password=>"passwordxx", :verbose=>0, :logger=> #<Logger:0x0000563ebff868e0 @default_formatter=#<Logger::Formatter:0x0000563ebff867c8 @datetime_format=nil>, @formatter=nil, @level=0, @logdev= #<Logger::LogDevice:0x0000563ebff86700 @binmode=false, @dev=#<IO:<STDERR>>, @filename=nil, @mon_data=#Monitor:0x0000563ebff86660, @mon_data_owner_object_id=740, @shift_age=nil, @shift_period_suffix=nil, @shift_size=nil>, @progname=nil>, :password_prompt=>#Net::SSH::Prompt:0x0000563ec02d91c8, :user=>"usernamexx", :check_host_ip=>true}, @pending_requests=[], @properties={}, @transport= #<Net::SSH::Transport::Session:0x0000563ec027b0c8 @algorithms= #<Net::SSH::Transport::Algorithms:0x0000563ec0273760 @algorithms= {:host_key=> ["[email protected]", "ssh-ed25519", "[email protected]", "[email protected]", "[email protected]", "ecdsa-sha2-nistp521", "ecdsa-sha2-nistp384", "ecdsa-sha2-nistp256", "[email protected]", "[email protected]", "ssh-rsa", "rsa-sha2-256", "rsa-sha2-512"], :kex=> ["ecdh-sha2-nistp521", "ecdh-sha2-nistp384", "ecdh-sha2-nistp256", "diffie-hellman-group-exchange-sha256", "diffie-hellman-group14-sha256", "diffie-hellman-group14-sha1"], :encryption=>["aes256-ctr", "aes192-ctr", "aes128-ctr"], :hmac=>["[email protected]", "[email protected]", "hmac-sha2-512", "hmac-sha2-256", "hmac-sha1"], :compression=>["none", "[email protected]", "zlib"], :language=>[], :encryption_server=>["aes256-ctr", "aes192-ctr", "aes128-ctr"], :encryption_client=>["aes256-ctr", "aes192-ctr", "aes128-ctr"], :hmac_server=>["[email protected]", "[email protected]", "hmac-sha2-512", "hmac-sha2-256", "hmac-sha1"], :hmac_client=>["[email protected]", "[email protected]", "hmac-sha2-512", "hmac-sha2-256", "hmac-sha1"], :compression_server=>["none", "[email protected]", "zlib"], :compression_client=>["none", "[email protected]", "zlib"], :language_server=>[], :language_client=>[]}, @client_packet= "\x14\x80\xB1\xE9\e\xAC\x93&\xEA,B\x10\x86\x04\xA0\xF8\x02\x00\x00\x00\x97ecdh-sha2-nistp521,ecdh-sha2-nistp384,ecdh-sha2-nistp256,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1\x00\x00\[email protected],ssh-ed25519,[email protected],[email protected],[email protected],ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,[email protected],[email protected],ssh-rsa,rsa-sha2-256,rsa-sha2-512\x00\x00\x00 aes256-ctr,aes192-ctr,aes128-ctr\x00\x00\x00 aes256-ctr,aes192-ctr,aes128-ctr\x00\x00\[email protected],[email protected],hmac-sha2-512,hmac-sha2-256,hmac-sha1\x00\x00\[email protected],[email protected],hmac-sha2-512,hmac-sha2-256,hmac-sha1\x00\x00\x00\x1Anone,[email protected],zlib\x00\x00\x00\x1Anone,[email protected],zlib\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00", @compression_client="none", @compression_server="none", @encryption_client="aes256-ctr", @encryption_server="aes256-ctr", @facility="net.ssh.transport.algorithms[320]", @hmac_client="[email protected]", @hmac_server="[email protected]", @host_key="ssh-ed25519", @initialized=true, @kex="ecdh-sha2-nistp521", @language_client="", @language_server="", @logger= #<Logger:0x0000563ebff868e0 @default_formatter=#<Logger::Formatter:0x0000563ebff867c8 @datetime_format=nil>, @formatter=nil, @level=0, @logdev= #<Logger::LogDevice:0x0000563ebff86700 @binmode=false, @dev=#<IO:<STDERR>>, @filename=nil, @mon_data=#Monitor:0x0000563ebff86660, @mon_data_owner_object_id=740, @shift_age=nil, @shift_period_suffix=nil, @shift_size=nil>, @progname=nil>, @options= {:auth_methods=>["none", "publickey", "password", "keyboard-interactive"], :send_env=>[/^LANG$/, /^LC_.$/], :password=>"passwordxx", :verbose=>0, :logger=> #<Logger:0x0000563ebff868e0 @default_formatter=#<Logger::Formatter:0x0000563ebff867c8 @datetime_format=nil>, @formatter=nil, @level=0, @logdev= #<Logger::LogDevice:0x0000563ebff86700 @binmode=false, @dev=#<IO:<STDERR>>, @filename=nil, @mon_data=#Monitor:0x0000563ebff86660, @mon_data_owner_object_id=740, @shift_age=nil, @shift_period_suffix=nil, @shift_size=nil>, @progname=nil>, :password_prompt=>#Net::SSH::Prompt:0x0000563ec02d91c8, :user=>"usernamexx", :check_host_ip=>true}, @pending=false, @server_data= {:raw=> "\x14\x95\aE\xA3|G\x18IC\xB6\xCD\x13\xE9O\x19\x95\x00\x00\x00zdiffie-hellman-group-exchange-sha256,[email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521\x00\x00\x00\vssh-ed25519\x00\x00\[email protected],aes256-ctr,[email protected]\x00\x00\[email protected],aes256-ctr,[email protected]\x00\x00\x00Whmac-sha2-256,[email protected],hmac-sha2-512,[email protected]\x00\x00\x00Whmac-sha2-256,[email protected],hmac-sha2-512,[email protected]\x00\x00\x00\x15none,[email protected]\x00\x00\x00\x15none,[email protected]\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00", :kex=> ["diffie-hellman-group-exchange-sha256", "[email protected]", "ecdh-sha2-nistp256", "ecdh-sha2-nistp384", "ecdh-sha2-nistp521"], :host_key=>["ssh-ed25519"], :encryption_client=>["[email protected]", "aes256-ctr", "[email protected]"], :encryption_server=>["[email protected]", "aes256-ctr", "[email protected]"], :hmac_client=>["hmac-sha2-256", "[email protected]", "hmac-sha2-512", "[email protected]"], :hmac_server=>["hmac-sha2-256", "[email protected]", "hmac-sha2-512", "[email protected]"], :compression_client=>["none", "[email protected]"], :compression_server=>["none", "[email protected]"], :language_client=>[], :language_server=>[]}, @server_packet= "\x14\x95\aE\xA3|G\x18IC\xB6\xCD\x13\xE9O\x19\x95\x00\x00\x00zdiffie-hellman-group-exchange-sha256,[email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521\x00\x00\x00\vssh-ed25519\x00\x00\[email protected],aes256-ctr,[email protected]\x00\x00\[email protected],aes256-ctr,[email protected]\x00\x00\x00Whmac-sha2-256,[email protected],hmac-sha2-512,[email protected]\x00\x00\x00Whmac-sha2-256,[email protected],hmac-sha2-512,[email protected]\x00\x00\x00\x15none,[email protected]\x00\x00\x00\x15none,[email protected]\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00", @session=#<Net::SSH::Transport::Session:0x0000563ec027b0c8 ...>, @session_id= "]\xDEK1\xBF\x18\xE9D\xB2\x88\xE1\x04\x9EV\xA5i\x923\xC1|\x1F2uz8z\xB8I\x0E\xAD\xB3C\x06\x8D\xB8N\xD4\x8A\xD0\x12\x12x\x00\xECN\xB9\xE9l\xA0\xFD\x12\x88\xB3+C\xB4\x17\x1Dn\x86\xB75Ew">, @bind_address=nil, @facility="net.ssh.transport.session[2f8]", @host="10.8.254.254", @host_as_string="10.8.254.254", @host_key_verifier=#Net::SSH::Verifiers::AcceptNewOrLocalTunnel:0x0000563ec0279868, @host_keys= #<Net::SSH::HostKeys:0x0000563ec0271c58 @host="10.8.254.254", @host_keys= [#<Net::SSH::Authentication::ED25519::PubKey:0x0000563ec0292188 @verify_key=#Ed25519::VerifyKey:a0b8b529eee399035ff1429fc3e905b76cf04b90c24ed4dbe3018116985c363f>], @known_hosts=Net::SSH::KnownHosts, @options= {:auth_methods=>["none", "publickey", "password", "keyboard-interactive"], :send_env=>[/^LANG$/, /^LC_.$/], :password=>"passwordxx", :verbose=>0, :logger=> #<Logger:0x0000563ebff868e0 @default_formatter=#<Logger::Formatter:0x0000563ebff867c8 @datetime_format=nil>, @formatter=nil, @level=0, @logdev= #<Logger::LogDevice:0x0000563ebff86700 @binmode=false, @dev=#<IO:<STDERR>>, @filename=nil, @mon_data=#Monitor:0x0000563ebff86660, @mon_data_owner_object_id=740, @shift_age=nil, @shift_period_suffix=nil, @shift_size=nil>, @progname=nil>, :password_prompt=>#Net::SSH::Prompt:0x0000563ec02d91c8, :user=>"usernamexx", :check_host_ip=>true}>, @logger= #<Logger:0x0000563ebff868e0 @default_formatter=#<Logger::Formatter:0x0000563ebff867c8 @datetime_format=nil>, @formatter=nil, @level=0, @logdev= #<Logger::LogDevice:0x0000563ebff86700 @binmode=false, @dev=#<IO:<STDERR>>, @filename=nil, @mon_data=#Monitor:0x0000563ebff86660, @mon_data_owner_object_id=740, @shift_age=nil, @shift_period_suffix=nil, @shift_size=nil>, @progname=nil>, @options= {:auth_methods=>["none", "publickey", "password", "keyboard-interactive"], :send_env=>[/^LANG$/, /^LC_.$/], :password=>"passwordxx", :verbose=>0, :logger=> #<Logger:0x0000563ebff868e0 @default_formatter=#<Logger::Formatter:0x0000563ebff867c8 @datetime_format=nil>, @formatter=nil, @level=0, @logdev= #<Logger::LogDevice:0x0000563ebff86700 @binmode=false, @dev=#<IO:<STDERR>>, @filename=nil, @mon_data=#Monitor:0x0000563ebff86660, @mon_data_owner_object_id=740, @shift_age=nil, @shift_period_suffix=nil, @shift_size=nil>, @progname=nil>, :password_prompt=>#Net::SSH::Prompt:0x0000563ec02d91c8, :user=>"usernamexx", :check_host_ip=>true}, @port=22, @queue=[], @server_version= #<Net::SSH::Transport::ServerVersion:0x0000563ec0279818 @facility="net.ssh.transport.server_version[30c]", @header="", @logger= #<Logger:0x0000563ebff868e0 @default_formatter=#<Logger::Formatter:0x0000563ebff867c8 @datetime_format=nil>, @formatter=nil, @level=0, @logdev= #<Logger::LogDevice:0x0000563ebff86700 @binmode=false, @dev=#<IO:<STDERR>>, @filename=nil, @mon_data=#Monitor:0x0000563ebff86660, @mon_data_owner_object_id=740, @shift_age=nil, @shift_period_suffix=nil, @shift_size=nil>, @progname=nil>, @version="SSH-2.0-AqTN-">, @socket=#<Socket:fd 5>>> irb(main):010:0>

KevinTang8888 avatar Apr 17 '24 09:04 KevinTang8888

Unfortunately in the provided output, the line

Apr 17 21:00:42 ubuntu2204 oxidized[21859]: /var/lib/gems/3.0.0/gems/net-ssh-7.2.3/lib/net/ssh/buffer.rb:342:in read_keyblob': unsupported key type >

Is truncated, and missing the actual type it is seeing which it perceives as unsupported, so hard to say anything.

ytti avatar Apr 17 '24 10:04 ytti

So, how to get the detail of this "unsupported key type" ?

KevinTang8888 avatar Apr 17 '24 10:04 KevinTang8888

Also from that Net:SSH debug info, we can see FortiGate is using SSH-2.0-AqTN with host_key: ssh-ed25519 net-ssh-7.2.3 client successfully negotiated the connection with FortiGate host/server. why buffer.rb process key type not supported?

net.ssh.transport.algorithms[320]: negotiated: kex: ecdh-sha2-nistp521 host_key: ssh-ed25519 encryption_server: aes256-ctr encryption_client: aes256-ctr hmac_client: [email protected] hmac_server: [email protected]

KevinTang8888 avatar Apr 17 '24 11:04 KevinTang8888

Also from that Net:SSH debug info, we can see FortiGate is using SSH-2.0-AqTN with host_key: ssh-ed25519 net-ssh-7.2.3 client successfully negotiated the connection with FortiGate host/server. why buffer.rb process key type not supported?

the ed25519 is supported, problem is the malformet type advertised for rsa-sha2-512, which causes net-ssh to raise.

Unfortunately I don't have time to walk you through all this.

ytti avatar Apr 17 '24 12:04 ytti

finally fixed the problem by myself.

Down graded to net-ssh-7.1.0

:-)

KevinTang8888 avatar Apr 17 '24 12:04 KevinTang8888

I am going to load another 500 FortiGate devices. 💯

KevinTang8888 avatar Apr 17 '24 12:04 KevinTang8888

after I loaded another 200 devices, net-ssh-7.1.0 start having the same problem too.

Apr 18 10:56:24 ubuntu2204 oxidized[23691]: /var/lib/gems/3.0.0/gems/net-ssh-7.1.0/lib/net/ssh/buffer.rb:342:in `read_keyblob': unsupported key>

KevinTang8888 avatar Apr 17 '24 23:04 KevinTang8888

If you can arrange a 'broken' test host for me to connect to, I can look into this. I'd use 91.198.120.1 as source address.

ytti avatar Apr 18 '24 08:04 ytti

I reiterate the suggestion to run the test code i showed above as to separate this issue from oxidized because it is a net-ssh problem

Atroskelis avatar Apr 18 '24 08:04 Atroskelis

Thanks for you try to help me. I got it working again after using when /^ssh-rsa$/, /^rsa-sha2-(256|512)$/ option. I will keep monitoring it for a few days.

next task to setup e-mail alert if there is a config change.

KevinTang8888 avatar Apr 18 '24 09:04 KevinTang8888

Thanks for you try to help me. I got it working again after using when /^ssh-rsa$/, /^rsa-sha2-(256|512)$/ option. I will keep monitoring it for a few days.

Do bear in mind, we cannot submit this change to upstream, as it is non-sensical, problem is far-end, and this is crude workaround to interoperate with broken far end.

We could submit to upstream change where unparseable host keys will not cause raise, but I cannot produce that fix, unless I have access to broken device to test against.

next task to setup e-mail alert if there is a config change.

ytti avatar Apr 18 '24 10:04 ytti

I am not sure how you can repeat this problem in Lab. with net-ssh-7.2.3 it worked when I only loaded 6 FortiGate devices, after load 110 devices, it's failed. After downgraded to net-ssh-7.1.0, it worked with 110 devices loaded. But after added another 200 FortiGate devices, it failed again. with that work around option, so far it works fine, not crashed yet.

KevinTang8888 avatar Apr 18 '24 23:04 KevinTang8888

Are you sure you've correctly identified the problem, I suspect your problem is, some of your FortiGates are olrder ones, which advertise ssh-rsa, which work, and the moment you add upgradded one, which advertise rsa-sha2-512, those break, and that it has nothing to do with count of devices.

Therefore, reprodo would be easy, just test against broken FortiGate.

There is 0 reason, why the proposed workaround would do anything to allivate any undeterministic race condition problem.

ytti avatar Apr 19 '24 05:04 ytti

can we discuss it privately? avoid to leaking my firewall information to public. what's your e-mail address?

KevinTang8888 avatar Apr 20 '24 02:04 KevinTang8888

can we discuss it privately? avoid to leaking my firewall information to public. what's your e-mail address?

Yes that's fine, [email protected]

ytti avatar Apr 20 '24 04:04 ytti

i think that i might have a similar issue, i need to finish to debug but i also have several fortios devices that fail. I'm trying to identify the issue but it looks that the ones that fail are running forti OS 7.4

configurations saved look like this:

# # COMMAND: get system status
# Unknown action 0
# 
# # COMMAND: get system ha status
# # COMMAND: get hardware status
# Unknown action 0
# 
# COMMAND: show | grep .
Unknown action 0

anubisg1 avatar May 27 '24 09:05 anubisg1

i think that i might have a similar issue, i need to finish to debug but i also have several fortios devices that fail. I'm trying to identify the issue but it looks that the ones that fail are running forti OS 7.4

configurations saved look like this:

# # COMMAND: get system status
# Unknown action 0
# 
# # COMMAND: get system ha status
# # COMMAND: get hardware status
# Unknown action 0
# 
# COMMAND: show | grep .
Unknown action 0

Hello, make sure you have the same admin rights on the user you are using.

Atroskelis avatar May 27 '24 11:05 Atroskelis