Debugging custom model for Oxidized

Hi,

I’m writing a custom model for our Adtran boxes, because the one included doesn’t work (uses the wrong commands, etc. probably made for some different version of the OS).

Here’s what I’ve got so far.

class Adtran < Oxidized::Model
  using Refinements

  # Adtran

  prompt /.*@.*[#>]/

  cmd 'show configuration | no-more'
  cfg :ssh do
    post_login 'cli'
    pre_logout 'exit'
  end
end

It seems to be doing what it should based on the ssh log.

Last login: Mon Mar 17 08:46:49 UTC 2008 from x.x.x.x on ssh
[root@OLT-NESO-ADTRAN-03 ~]# cli
yash 2.3.16-1
hsvroot@OLT-NESO-ADTRAN-03> show configuration | no-more
[REDACTED]
hsvroot@OLT-NESO-ADTRAN-03> exit
[root@OLT-NESO-ADTRAN-03 ~]#

But Oxidized isn’t actually backing up the config. And from the debuging output from Oxidized, it seems that it all works until oxidized needs to disconnect. It simply holds the connection until it times out and then it discards everything says it has no connection to the device. At least that’s my guess of what is going on. Here’s the relevant output from where oxidized starts the log out process (repeating messages were shortened)

D, [2024-03-04T19:51:52.702920 #19696] DEBUG -- : lib/oxidized/input/cli.rb Running pre_logout commands at OLT-NESO-ADTRAN-03
D, [2024-03-04T19:51:52.703003 #19696] DEBUG -- : lib/oxidized/input/ssh.rb exit @ OLT-NESO-ADTRAN-03 with expect: nil
D, [2024-03-04T19:51:52.703185 #19696] DEBUG -- socket[5a0]: using encrypt-then-mac
D, [2024-03-04T19:51:52.703356 #19696] DEBUG -- socket[5a0]: queueing packet nr 17 type 94 len 32
D, [2024-03-04T19:51:52.703641 #19696] DEBUG -- socket[5a0]: sent 184 bytes
D, [2024-03-04T19:51:52.704499 #19696] DEBUG -- socket[5a0]: read 100 bytes
D, [2024-03-04T19:51:52.704698 #19696] DEBUG -- socket[5a0]: received packet nr 117 type 94 len 32
I, [2024-03-04T19:51:52.704782 #19696]  INFO -- net.ssh.connection.session[5dc]: channel_data: 0 4b
D, [2024-03-04T19:51:52.704890 #19696] DEBUG -- socket[5a0]: read 84 bytes
D, [2024-03-04T19:51:52.705022 #19696] DEBUG -- socket[5a0]: received packet nr 118 type 94 len 16
I, [2024-03-04T19:51:52.705068 #19696]  INFO -- net.ssh.connection.session[5dc]: channel_data: 0 2b
D, [2024-03-04T19:51:52.792603 #19696] DEBUG -- socket[5a0]: read 116 bytes
D, [2024-03-04T19:51:52.793240 #19696] DEBUG -- socket[5a0]: received packet nr 119 type 94 len 48
I, [2024-03-04T19:51:52.793460 #19696]  INFO -- net.ssh.connection.session[5dc]: channel_data: 0 29b
D, [2024-03-04T19:51:53.559778 #19696] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2024-03-04T19:51:54.561092 #19696] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2024-03-04T19:51:55.562292 #19696] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2024-03-04T19:51:56.563665 #19696] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
[...]
D, [2024-03-04T19:52:22.821005 #19696] DEBUG -- socket[5a0]: read 116 bytes
D, [2024-03-04T19:52:22.821636 #19696] DEBUG -- socket[5a0]: received packet nr 120 type 98 len 48
I, [2024-03-04T19:52:22.821820 #19696]  INFO -- net.ssh.connection.session[5dc]: channel_request: 0 [email protected] true
D, [2024-03-04T19:52:22.822011 #19696] DEBUG -- socket[5a0]: using encrypt-then-mac
D, [2024-03-04T19:52:22.822259 #19696] DEBUG -- socket[5a0]: queueing packet nr 18 type 100 len 16
D, [2024-03-04T19:52:22.822485 #19696] DEBUG -- socket[5a0]: sent 84 bytes
D, [2024-03-04T19:52:23.600143 #19696] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2024-03-04T19:52:24.601469 #19696] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2024-03-04T19:52:25.602732 #19696] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2024-03-04T19:52:26.604079 #19696] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
[...]
I, [2024-03-04T20:17:12.506237 #19696]  INFO -- net.ssh.connection.session[8e8]: closing remaining channels (1 open)
D, [2024-03-04T20:17:12.506621 #19696] DEBUG -- socket[8ac]: using encrypt-then-mac
D, [2024-03-04T20:17:12.507020 #19696] DEBUG -- socket[8ac]: queueing packet nr 27 type 97 len 16
D, [2024-03-04T20:17:12.507300 #19696] DEBUG -- socket[8ac]: sent 84 bytes
D, [2024-03-04T20:17:12.508348 #19696] DEBUG -- socket[8ac]: read 116 bytes
D, [2024-03-04T20:17:12.508773 #19696] DEBUG -- socket[8ac]: received packet nr 103 type 98 len 48
I, [2024-03-04T20:17:12.508969 #19696]  INFO -- net.ssh.connection.session[8e8]: channel_request: 0 [email protected] true
D, [2024-03-04T20:17:12.509291 #19696] DEBUG -- socket[8ac]: using encrypt-then-mac
D, [2024-03-04T20:17:12.509592 #19696] DEBUG -- socket[8ac]: queueing packet nr 28 type 100 len 16
D, [2024-03-04T20:17:12.509781 #19696] DEBUG -- socket[8ac]: read 200 bytes
D, [2024-03-04T20:17:12.510084 #19696] DEBUG -- socket[8ac]: received packet nr 104 type 98 len 48
I, [2024-03-04T20:17:12.510173 #19696]  INFO -- net.ssh.connection.session[8e8]: channel_request: 0 exit-signal false
D, [2024-03-04T20:17:12.510297 #19696] DEBUG -- socket[8ac]: received packet nr 105 type 97 len 16
I, [2024-03-04T20:17:12.510332 #19696]  INFO -- net.ssh.connection.session[8e8]: channel_close: 0
I, [2024-03-04T20:17:12.510393 #19696]  INFO -- net.ssh.connection.session[8e8]: 192.168.255.41 delete channel 0 which closed locally and remotely
D, [2024-03-04T20:17:12.510492 #19696] DEBUG -- socket[8ac]: sent 84 bytes
W, [2024-03-04T20:17:12.510613 #19696]  WARN -- : 192.168.255.41 raised Timeout::Error with msg "execution expired"
D, [2024-03-04T20:17:12.510643 #19696] DEBUG -- : lib/oxidized/node.rb: Oxidized::SSH failed for OLT-NESO-ADTRAN-03
D, [2024-03-04T20:17:12.510726 #19696] DEBUG -- : lib/oxidized/job.rb: Config fetched for OLT-NESO-ADTRAN-03 at 2024-03-04 20:17:12 UTC
W, [2024-03-04T20:17:12.550138 #19696]  WARN -- : m-p/OLT-NESO-ADTRAN-03 status no_connection, retries exhausted, giving up
D, [2024-03-04T20:17:12.550219 #19696] DEBUG -- : lib/oxidized/worker.rb: Jobs running: 0 of 1 - ended: 1 of 1
D, [2024-03-04T20:17:12.550320 #19696] DEBUG -- : lib/oxidized/worker.rb: Running :nodes_done hook
D, [2024-03-04T20:17:13.550667 #19696] DEBUG -- : lib/oxidized/worker.rb: Jobs running: 0 of 1 - ended: 0 of 1
D, [2024-03-04T20:17:14.552050 #19696] DEBUG -- : lib/oxidized/worker.rb: Jobs running: 0 of 1 - ended: 0 of 1
D, [2024-03-04T20:17:15.553349 #19696] DEBUG -- : lib/oxidized/worker.rb: Jobs running: 0 of 1 - ended: 0 of 1
D, [2024-03-04T20:17:16.554607 #19696] DEBUG -- : lib/oxidized/worker.rb: Jobs running: 0 of 1 - ended: 0 of 1

Still even if that was the case, I’d guess the config would still update, since the output of the “show configuration” command seems to have been collected (and is included in the ssh log that oxidized saves too).

You probably want to post on GitHub for this, we mostly help with the operating of Oxidized. However, I’d hazard a guess the prompt isn’t matching possibly.