Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

"execution timeout" on IOS-XE on 0.31.0 #3406

Open
netjordan opened this issue Feb 17, 2025 · 1 comment
Open

"execution timeout" on IOS-XE on 0.31.0 #3406

netjordan opened this issue Feb 17, 2025 · 1 comment

Comments

@netjordan
Copy link

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 netjordan changed the title "execution timeout" on IOS-XE on "execution timeout" on IOS-XE on 0.31.0 Feb 17, 2025
@robertcheramy
Copy link
Collaborator

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?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@netjordan @robertcheramy