oxidized icon indicating copy to clipboard operation
oxidized copied to clipboard
verified publisher icon ytti

"execution timeout" on IOS-XE on 0.31.0

Open netjordan opened this issue 10 months ago • 2 comments

On the latest release of Oxidized, all of our Cisco IOS-XE devices have stopped working, from the logs I see they just fail with the error

W, [2025-02-17T08:16:39.069636 #49]  WARN -- : 10.69.0.1 raised Timeout::Error with msg "execution expired"

The full logs:

D, [2025-02-17T08:16:17.992870 #49] DEBUG -- : lib/oxidized/worker.rb: Added iosxe/sld9-r3-pres2 to the job queue
D, [2025-02-17T08:16:17.992896 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2025-02-17T08:16:17.993729 #49] DEBUG -- : lib/oxidized/job.rb: Starting fetching process for sld9-r3-pres2 at 2025-02-17 08:16:17 UTC
D, [2025-02-17T08:16:17.994066 #49] DEBUG -- : lib/oxidized/input/ssh.rb: Connecting to sld9-r3-pres2
D, [2025-02-17T08:16:17.995404 #49] DEBUG -- : AUTH METHODS::["none", "publickey", "password"]
D, [2025-02-17T08:16:17.996174 #49] DEBUG -- net.ssh.transport.session[9d9e00]: establishing connection to 10.69.0.1:22
D, [2025-02-17T08:16:17.997601 #49] DEBUG -- net.ssh.transport.session[9d9e00]: connection established
I, [2025-02-17T08:16:17.997669 #49]  INFO -- net.ssh.transport.server_version[9d9e14]: negotiating protocol version
D, [2025-02-17T08:16:17.997685 #49] DEBUG -- net.ssh.transport.server_version[9d9e14]: local is `SSH-2.0-Ruby/Net::SSH_7.3.0 x86_64-linux-gnu'
D, [2025-02-17T08:16:17.998942 #49] DEBUG -- net.ssh.transport.server_version[9d9e14]: remote is `SSH-2.0-Cisco-1.25'
I, [2025-02-17T08:16:17.999179 #49]  INFO -- net.ssh.transport.algorithms[9d9e28]: sending KEXINIT
D, [2025-02-17T08:16:17.999444 #49] DEBUG -- socket[9d9e3c]: queueing packet nr 0 type 20 len 1572
D, [2025-02-17T08:16:17.999520 #49] DEBUG -- socket[9d9e3c]: sent 1576 bytes
D, [2025-02-17T08:16:17.999587 #49] DEBUG -- socket[9d9e3c]: read 518 bytes
D, [2025-02-17T08:16:18.000031 #49] DEBUG -- socket[9d9e3c]: read 162 bytes
D, [2025-02-17T08:16:18.000551 #49] DEBUG -- socket[9d9e3c]: received packet nr 0 type 20 len 676
I, [2025-02-17T08:16:18.000593 #49]  INFO -- net.ssh.transport.algorithms[9d9e28]: got KEXINIT from server
I, [2025-02-17T08:16:18.000664 #49]  INFO -- net.ssh.transport.algorithms[9d9e28]: negotiating algorithms
D, [2025-02-17T08:16:18.000730 #49] DEBUG -- net.ssh.transport.algorithms[9d9e28]: negotiated:
* kex: [email protected]
* host_key: ssh-rsa
* 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, [2025-02-17T08:16:18.000745 #49] DEBUG -- net.ssh.transport.algorithms[9d9e28]: exchanging keys
D, [2025-02-17T08:16:18.001287 #49] DEBUG -- socket[9d9e3c]: queueing packet nr 1 type 30 len 44
D, [2025-02-17T08:16:18.001392 #49] DEBUG -- socket[9d9e3c]: sent 48 bytes
D, [2025-02-17T08:16:18.025189 #49] DEBUG -- socket[9d9e3c]: read 608 bytes
D, [2025-02-17T08:16:18.025312 #49] DEBUG -- socket[9d9e3c]: received packet nr 1 type 31 len 604
D, [2025-02-17T08:16:18.025860 #49] DEBUG -- socket[9d9e3c]: queueing packet nr 2 type 21 len 20
D, [2025-02-17T08:16:18.026470 #49] DEBUG -- socket[9d9e3c]: sent 24 bytes
D, [2025-02-17T08:16:18.026546 #49] DEBUG -- socket[9d9e3c]: read 16 bytes
D, [2025-02-17T08:16:18.026593 #49] DEBUG -- socket[9d9e3c]: received packet nr 2 type 21 len 12
D, [2025-02-17T08:16:18.027014 #49] DEBUG -- net.ssh.authentication.session[9d9e78]: beginning authentication of `exec_oxidized'
D, [2025-02-17T08:16:18.027073 #49] DEBUG -- socket[9d9e3c]: using encrypt-then-mac
D, [2025-02-17T08:16:18.027285 #49] DEBUG -- socket[9d9e3c]: queueing packet nr 3 type 5 len 32
D, [2025-02-17T08:16:18.027323 #49] DEBUG -- socket[9d9e3c]: sent 100 bytes
D, [2025-02-17T08:16:18.227326 #49] DEBUG -- socket[9d9e3c]: read 100 bytes
D, [2025-02-17T08:16:18.227674 #49] DEBUG -- socket[9d9e3c]: received packet nr 3 type 6 len 32
D, [2025-02-17T08:16:18.227838 #49] DEBUG -- net.ssh.authentication.session[9d9e78]: trying none
D, [2025-02-17T08:16:18.228005 #49] DEBUG -- socket[9d9e3c]: using encrypt-then-mac
D, [2025-02-17T08:16:18.228183 #49] DEBUG -- socket[9d9e3c]: queueing packet nr 4 type 50 len 64
D, [2025-02-17T08:16:18.228249 #49] DEBUG -- socket[9d9e3c]: sent 132 bytes
D, [2025-02-17T08:16:18.229363 #49] DEBUG -- socket[9d9e3c]: read 132 bytes
D, [2025-02-17T08:16:18.229576 #49] DEBUG -- socket[9d9e3c]: received packet nr 4 type 51 len 64
D, [2025-02-17T08:16:18.229634 #49] DEBUG -- net.ssh.authentication.session[9d9e78]: allowed methods: publickey,keyboard-interactive,password
D, [2025-02-17T08:16:18.229673 #49] DEBUG -- net.ssh.authentication.methods.none[9d9e8c]: none failed
D, [2025-02-17T08:16:18.229700 #49] DEBUG -- net.ssh.authentication.session[9d9e78]: trying publickey
D, [2025-02-17T08:16:18.229875 #49] DEBUG -- net.ssh.authentication.agent[9d9ea0]: connecting to ssh-agent
E, [2025-02-17T08:16:18.229975 #49] ERROR -- net.ssh.authentication.agent[9d9ea0]: could not connect to ssh-agent: Agent not configured
D, [2025-02-17T08:16:18.230233 #49] DEBUG -- net.ssh.authentication.session[9d9e78]: trying password
D, [2025-02-17T08:16:18.230324 #49] DEBUG -- socket[9d9e3c]: using encrypt-then-mac
D, [2025-02-17T08:16:18.230467 #49] DEBUG -- socket[9d9e3c]: queueing packet nr 5 type 50 len 80
D, [2025-02-17T08:16:18.230605 #49] DEBUG -- socket[9d9e3c]: sent 148 bytes
D, [2025-02-17T08:16:18.262848 #49] DEBUG -- socket[9d9e3c]: read 84 bytes
D, [2025-02-17T08:16:18.263001 #49] DEBUG -- socket[9d9e3c]: received packet nr 5 type 52 len 16
D, [2025-02-17T08:16:18.263128 #49] DEBUG -- net.ssh.authentication.methods.password[9d9eb4]: password succeeded
D, [2025-02-17T08:16:18.263273 #49] DEBUG -- socket[9d9e3c]: using encrypt-then-mac
D, [2025-02-17T08:16:18.263406 #49] DEBUG -- socket[9d9e3c]: queueing packet nr 6 type 90 len 32
D, [2025-02-17T08:16:18.263524 #49] DEBUG -- : lib/oxidized/input/ssh.rb: expecting [/^([\w.@()-]+[#>]\s?)$/] at sld9-r3-pres2
D, [2025-02-17T08:16:18.463977 #49] DEBUG -- socket[9d9e3c]: sent 100 bytes
D, [2025-02-17T08:16:18.564213 #49] DEBUG -- socket[9d9e3c]: read 100 bytes
D, [2025-02-17T08:16:18.564428 #49] DEBUG -- socket[9d9e3c]: received packet nr 6 type 91 len 32
I, [2025-02-17T08:16:18.564600 #49]  INFO -- net.ssh.connection.session[9d9ec8]: channel_open_confirmation: 0 3 8192 4096
I, [2025-02-17T08:16:18.564699 #49]  INFO -- net.ssh.connection.channel[9d9edc]: sending channel request "env"
D, [2025-02-17T08:16:18.564861 #49] DEBUG -- socket[9d9e3c]: using encrypt-then-mac
D, [2025-02-17T08:16:18.564964 #49] DEBUG -- socket[9d9e3c]: queueing packet nr 7 type 98 len 48
I, [2025-02-17T08:16:18.565091 #49]  INFO -- net.ssh.connection.channel[9d9edc]: sending channel request "env"
D, [2025-02-17T08:16:18.565212 #49] DEBUG -- socket[9d9e3c]: using encrypt-then-mac
D, [2025-02-17T08:16:18.565303 #49] DEBUG -- socket[9d9e3c]: queueing packet nr 8 type 98 len 48
I, [2025-02-17T08:16:18.565329 #49]  INFO -- net.ssh.connection.channel[9d9edc]: sending channel request "env"
D, [2025-02-17T08:16:18.565488 #49] DEBUG -- socket[9d9e3c]: using encrypt-then-mac
D, [2025-02-17T08:16:18.565563 #49] DEBUG -- socket[9d9e3c]: queueing packet nr 9 type 98 len 48
I, [2025-02-17T08:16:18.565611 #49]  INFO -- net.ssh.connection.channel[9d9edc]: sending channel request "pty-req"
D, [2025-02-17T08:16:18.565786 #49] DEBUG -- socket[9d9e3c]: using encrypt-then-mac
D, [2025-02-17T08:16:18.565939 #49] DEBUG -- socket[9d9e3c]: queueing packet nr 10 type 98 len 64
D, [2025-02-17T08:16:18.666290 #49] DEBUG -- socket[9d9e3c]: sent 480 bytes
D, [2025-02-17T08:16:18.766536 #49] DEBUG -- socket[9d9e3c]: read 84 bytes
D, [2025-02-17T08:16:18.766751 #49] DEBUG -- socket[9d9e3c]: received packet nr 7 type 99 len 16
I, [2025-02-17T08:16:18.766808 #49]  INFO -- net.ssh.connection.session[9d9ec8]: channel_success: 0
I, [2025-02-17T08:16:18.766945 #49]  INFO -- net.ssh.connection.channel[9d9edc]: sending channel request "shell"
D, [2025-02-17T08:16:18.767060 #49] DEBUG -- socket[9d9e3c]: using encrypt-then-mac
D, [2025-02-17T08:16:18.767153 #49] DEBUG -- socket[9d9e3c]: queueing packet nr 11 type 98 len 32
D, [2025-02-17T08:16:18.867464 #49] DEBUG -- socket[9d9e3c]: sent 100 bytes
D, [2025-02-17T08:16:18.967701 #49] DEBUG -- socket[9d9e3c]: read 1064 bytes
D, [2025-02-17T08:16:18.967911 #49] DEBUG -- socket[9d9e3c]: received packet nr 8 type 99 len 16
I, [2025-02-17T08:16:18.967973 #49]  INFO -- net.ssh.connection.session[9d9ec8]: channel_success: 0
D, [2025-02-17T08:16:18.968240 #49] DEBUG -- socket[9d9e3c]: received packet nr 9 type 94 len 912
I, [2025-02-17T08:16:18.968297 #49]  INFO -- net.ssh.connection.session[9d9ec8]: channel_data: 0 897b
D, [2025-02-17T08:16:18.993962 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2025-02-17T08:16:19.068661 #49] DEBUG -- : lib/oxidized/input/cli.rb: Running post_login commands at sld9-r3-pres2
D, [2025-02-17T08:16:19.068736 #49] DEBUG -- : lib/oxidized/input/cli.rb: Running post_login command: nil, block: #<Proc:0x00007fad739df350 /usr/local/bundle/gems/oxidized-0.31.0/lib/oxidized/model/ios.rb:140> at sld9-r3-pres2
D, [2025-02-17T08:16:19.068824 #49] DEBUG -- : lib/oxidized/input/ssh.rb enable @ sld9-r3-pres2 with expect: /^[pP]assword:/
D, [2025-02-17T08:16:19.068999 #49] DEBUG -- socket[9d9e3c]: using encrypt-then-mac
D, [2025-02-17T08:16:19.069201 #49] DEBUG -- socket[9d9e3c]: queueing packet nr 12 type 94 len 32
D, [2025-02-17T08:16:19.069312 #49] DEBUG -- : lib/oxidized/input/ssh.rb: expecting [/^[pP]assword:/] at sld9-r3-pres2
D, [2025-02-17T08:16:19.269736 #49] DEBUG -- socket[9d9e3c]: sent 100 bytes
D, [2025-02-17T08:16:19.369975 #49] DEBUG -- socket[9d9e3c]: read 688 bytes
D, [2025-02-17T08:16:19.370293 #49] DEBUG -- socket[9d9e3c]: received packet nr 10 type 94 len 16
I, [2025-02-17T08:16:19.370365 #49]  INFO -- net.ssh.connection.session[9d9ec8]: channel_data: 0 1b
D, [2025-02-17T08:16:19.370592 #49] DEBUG -- socket[9d9e3c]: received packet nr 11 type 94 len 16
I, [2025-02-17T08:16:19.370636 #49]  INFO -- net.ssh.connection.session[9d9ec8]: channel_data: 0 1b
D, [2025-02-17T08:16:19.370866 #49] DEBUG -- socket[9d9e3c]: received packet nr 12 type 94 len 16
I, [2025-02-17T08:16:19.370913 #49]  INFO -- net.ssh.connection.session[9d9ec8]: channel_data: 0 1b
D, [2025-02-17T08:16:19.371100 #49] DEBUG -- socket[9d9e3c]: received packet nr 13 type 94 len 16
I, [2025-02-17T08:16:19.371146 #49]  INFO -- net.ssh.connection.session[9d9ec8]: channel_data: 0 1b
D, [2025-02-17T08:16:19.371343 #49] DEBUG -- socket[9d9e3c]: received packet nr 14 type 94 len 16
I, [2025-02-17T08:16:19.371386 #49]  INFO -- net.ssh.connection.session[9d9ec8]: channel_data: 0 1b
D, [2025-02-17T08:16:19.371909 #49] DEBUG -- socket[9d9e3c]: received packet nr 15 type 94 len 16
I, [2025-02-17T08:16:19.371962 #49]  INFO -- net.ssh.connection.session[9d9ec8]: channel_data: 0 1b
D, [2025-02-17T08:16:19.372148 #49] DEBUG -- socket[9d9e3c]: received packet nr 16 type 94 len 16
I, [2025-02-17T08:16:19.372189 #49]  INFO -- net.ssh.connection.session[9d9ec8]: channel_data: 0 2b
D, [2025-02-17T08:16:19.372365 #49] DEBUG -- socket[9d9e3c]: received packet nr 17 type 94 len 32
I, [2025-02-17T08:16:19.372408 #49]  INFO -- net.ssh.connection.session[9d9ec8]: channel_data: 0 14b
I, [2025-02-17T08:16:19.572829 #49]  INFO -- net.ssh.connection.keepalive[9d9ef0]: sending keepalive 0
I, [2025-02-17T08:16:19.572887 #49]  INFO -- net.ssh.connection.session[9d9ec8]: sending global request [email protected]
D, [2025-02-17T08:16:19.572970 #49] DEBUG -- socket[9d9e3c]: using encrypt-then-mac
D, [2025-02-17T08:16:19.573103 #49] DEBUG -- socket[9d9e3c]: queueing packet nr 13 type 80 len 32
D, [2025-02-17T08:16:19.774153 #49] DEBUG -- socket[9d9e3c]: sent 100 bytes
D, [2025-02-17T08:16:19.874396 #49] DEBUG -- socket[9d9e3c]: read 84 bytes
D, [2025-02-17T08:16:19.874614 #49] DEBUG -- socket[9d9e3c]: received packet nr 18 type 82 len 16
I, [2025-02-17T08:16:19.874742 #49]  INFO -- net.ssh.connection.session[9d9ec8]: global request failure
D, [2025-02-17T08:16:19.874782 #49] DEBUG -- net.ssh.connection.keepalive[9d9ef0]: keepalive response successful. Missed 0 keepalives
D, [2025-02-17T08:16:19.995145 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2025-02-17T08:16:20.996309 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2025-02-17T08:16:21.997495 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2025-02-17T08:16:22.998051 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2025-02-17T08:16:23.999251 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2025-02-17T08:16:25.000460 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2025-02-17T08:16:26.001649 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2025-02-17T08:16:27.002059 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2025-02-17T08:16:28.003249 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2025-02-17T08:16:29.004434 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2025-02-17T08:16:30.005612 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2025-02-17T08:16:31.006061 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2025-02-17T08:16:32.007228 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2025-02-17T08:16:33.008304 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2025-02-17T08:16:34.008904 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2025-02-17T08:16:35.010058 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2025-02-17T08:16:36.011233 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2025-02-17T08:16:37.012420 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2025-02-17T08:16:38.013593 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
D, [2025-02-17T08:16:39.014039 #49] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
W, [2025-02-17T08:16:39.069636 #49]  WARN -- : 10.69.0.1 raised Timeout::Error with msg "execution expired"
D, [2025-02-17T08:16:39.069682 #49] DEBUG -- : lib/oxidized/node.rb: Oxidized::SSH failed for sld9-r3-pres2
D, [2025-02-17T08:16:39.069706 #49] DEBUG -- : lib/oxidized/job.rb: Config fetched for sld9-r3-pres2 at 2025-02-17 08:16:39
UTC
W, [2025-02-17T08:16:40.014919 #49]  WARN -- : iosxe/sld9r3-pres2 status no_connection, retry attempt 1

This seems to be happening on devices both with and without enable prompts.

Can anyone advise?

netjordan avatar Feb 17 '25 08:02 netjordan

Not very helpful, but my IOS XE devices works (without enable prompts).

Can you tail -f ~/.config/oxidized/logs/10.69.0.1-ssh, so we can see where it stops?

Can you also run from the latest git:

extra/device2yaml.rb user@device -c "terminal length 0
terminal width 0
show version
show vtp status
show inventory
show running-config
exit" -o spec/model/data/ios:IOS-XE_Version:simulation.yaml

And see if you get errors and share the resulting file?

robertcheramy avatar Feb 17 '25 21:02 robertcheramy

This issue is stale because it has been open 90 days with no activity.

github-actions[bot] avatar May 19 '25 02:05 github-actions[bot]