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.

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

Netgear model: Does not detect end of configuration file #1100

Open
pv2b opened this Issue Nov 15, 2017 · 5 comments

Comments

Projects
None yet
4 participants
@pv2b
Contributor

pv2b commented Nov 15, 2017

It seems part of #920 is still unsolved.

@candlerb mentioned:

So for some reason it doesn't accept the returned prompt, even though it appears to match the prompt regexp in netgear.rb

I am seeing the exact same issue even with the fixed code. After running "show running-config", the prompt is returned at the end, but it seems that it is not matched correctly. Instead I get a timeout like this:

Nov 15 16:09:11 mgt02 oxidized[17108]: W, [2017-11-15T16:09:11.080677 #17108]  WARN -- : 10.0.9.6 raised Timeout::Error with msg "execution expired"
Nov 15 16:09:11 mgt02 oxidized[17108]: W, [2017-11-15T16:09:11.934272 #17108]  WARN -- : swge001-sto-dc1.ita.local status no_connection, retry attempt 1
Nov 15 16:09:35 mgt02 oxidized[17108]: W, [2017-11-15T16:09:35.985670 #17108]  WARN -- : 10.0.9.6 raised Timeout::Error with msg "execution expired"
Nov 15 16:09:36 mgt02 oxidized[17108]: W, [2017-11-15T16:09:36.941394 #17108]  WARN -- : swge001-sto-dc1.ita.local status no_connection, retry attempt 2
Nov 15 16:10:01 mgt02 oxidized[17108]: W, [2017-11-15T16:10:01.144171 #17108]  WARN -- : 10.0.9.6 raised Timeout::Error with msg "execution expired"
Nov 15 16:10:01 mgt02 oxidized[17108]: W, [2017-11-15T16:10:01.948562 #17108]  WARN -- : swge001-sto-dc1.ita.local status no_connection, retry attempt 3
Nov 15 16:10:26 mgt02 oxidized[17108]: W, [2017-11-15T16:10:26.034609 #17108]  WARN -- : 10.0.9.6 raised Timeout::Error with msg "execution expired"
Nov 15 16:10:26 mgt02 oxidized[17108]: W, [2017-11-15T16:10:26.955191 #17108]  WARN -- : swge001-sto-dc1.ita.local status no_connection, retries exhausted, giving up
Nov 15 16:14:26 mgt02 oxidized[17108]: W, [2017-11-15T16:14:26.007384 #17108]  WARN -- : 10.0.9.6 raised Timeout::Error with msg "execution expired"
Nov 15 16:14:27 mgt02 oxidized[17108]: W, [2017-11-15T16:14:27.017702 #17108]  WARN -- : swge001-sto-dc1.ita.local status no_connection, retry attempt 1
Nov 15 16:14:51 mgt02 oxidized[17108]: W, [2017-11-15T16:14:51.170133 #17108]  WARN -- : 10.0.9.6 raised Timeout::Error with msg "execution expired"
Nov 15 16:14:52 mgt02 oxidized[17108]: W, [2017-11-15T16:14:52.024128 #17108]  WARN -- : swge001-sto-dc1.ita.local status no_connection, retry attempt 2
Nov 15 16:15:16 mgt02 oxidized[17108]: W, [2017-11-15T16:15:16.638902 #17108]  WARN -- : 10.0.9.6 raised Timeout::Error with msg "execution expired"
Nov 15 16:15:17 mgt02 oxidized[17108]: W, [2017-11-15T16:15:17.030496 #17108]  WARN -- : swge001-sto-dc1.ita.local status no_connection, retry attempt 3
Nov 15 16:15:41 mgt02 oxidized[17108]: W, [2017-11-15T16:15:41.183825 #17108]  WARN -- : 10.0.9.6 raised Timeout::Error with msg "execution expired"
Nov 15 16:15:42 mgt02 oxidized[17108]: W, [2017-11-15T16:15:42.036360 #17108]  WARN -- : swge001-sto-dc1.ita.local status no_connection, retries exhausted, giving up

My code is stock except for a small change to the prompt regex as per PR #1099

@jsynack

This comment has been minimized.

Show comment
Hide comment
@jsynack

jsynack Nov 15, 2017

Contributor

Do you have the actual session log to the device? Does it drop to another prompt or is it asking a question like in the original report showed?

The session logs can be collected with setting debug: true setting under the input: section in your configuration file and (re)starting oxidized.

You will then find the session logs in a logs sub-directory in your oxidized directory (typically ~oxidized/.config/oxidized/logs if you went with the defaults). The filename would be something like 10.0.9.6-ssh or 10.0.9.6-telnet depending on the input method to the device.

For reference - what model/version of software is the device?

Contributor

jsynack commented Nov 15, 2017

Do you have the actual session log to the device? Does it drop to another prompt or is it asking a question like in the original report showed?

The session logs can be collected with setting debug: true setting under the input: section in your configuration file and (re)starting oxidized.

You will then find the session logs in a logs sub-directory in your oxidized directory (typically ~oxidized/.config/oxidized/logs if you went with the defaults). The filename would be something like 10.0.9.6-ssh or 10.0.9.6-telnet depending on the input method to the device.

For reference - what model/version of software is the device?

@pv2b

This comment has been minimized.

Show comment
Hide comment
@pv2b

pv2b Nov 15, 2017

Contributor

Yes, I have the actual session log. The actual configuration is sensitive and I don't want to post it here, but here is an abbreviated version with the actual config data excluded:

(SWGE001-STO-DC1.ita.local) >enable

(SWGE001-STO-DC1.ita.local) #terminal length 0

(SWGE001-STO-DC1.ita.local) #show running-config

!Current Configuration:
!
! <ACTUAL OUTPUT HAS BEEN REMOVED>
router ospf
exit
exit


(SWGE001-STO-DC1.ita.local) #

Also here is a hex dump of the very end of it, to exclude any possible non-printing characters:

root@mgt02:/etc/oxidized/logs# hexdump -C 10.0.9.6-ssh|tail -5
00003da0  70 66 0d 0a 65 78 69 74  0d 0a 65 78 69 74 0d 0a  |pf..exit..exit..|
00003db0  0d 0a 0d 0a 28 53 57 47  45 30 30 31 2d 53 54 4f  |....(SWGE001-STO|
00003dc0  2d 44 43 31 2e 69 74 61  2e 6c 6f 63 61 6c 29 20  |-DC1.ita.local) |
00003dd0  23                                                |#|
00003dd1
root@mgt02:/etc/oxidized/logs#

Here is the device info:

(SWGE001-STO-DC1.ita.local) #show version

Switch: 2

System Description............................. M5300-28G3 ProSafe 24-port Gigabit L3 with 10 Gigabit Stacking, 10.0.0.44, B1.0.0.5
Machine Model.................................. M5300-28G3
Serial Number..................................<REDACTED>
Burned In MAC Address..........................<REDACTED>
Software Version............................... 10.0.0.44
Bootcode Version............................... B1.0.0.5
Supported Java Plugin Version.................. 1.6
Current Time................................... Feb 15 17:31:24 1971 (UTC+0:00)
Current SNTP Sync Status....................... Other

(SWGE001-STO-DC1.ita.local) #
Contributor

pv2b commented Nov 15, 2017

Yes, I have the actual session log. The actual configuration is sensitive and I don't want to post it here, but here is an abbreviated version with the actual config data excluded:

(SWGE001-STO-DC1.ita.local) >enable

(SWGE001-STO-DC1.ita.local) #terminal length 0

(SWGE001-STO-DC1.ita.local) #show running-config

!Current Configuration:
!
! <ACTUAL OUTPUT HAS BEEN REMOVED>
router ospf
exit
exit


(SWGE001-STO-DC1.ita.local) #

Also here is a hex dump of the very end of it, to exclude any possible non-printing characters:

root@mgt02:/etc/oxidized/logs# hexdump -C 10.0.9.6-ssh|tail -5
00003da0  70 66 0d 0a 65 78 69 74  0d 0a 65 78 69 74 0d 0a  |pf..exit..exit..|
00003db0  0d 0a 0d 0a 28 53 57 47  45 30 30 31 2d 53 54 4f  |....(SWGE001-STO|
00003dc0  2d 44 43 31 2e 69 74 61  2e 6c 6f 63 61 6c 29 20  |-DC1.ita.local) |
00003dd0  23                                                |#|
00003dd1
root@mgt02:/etc/oxidized/logs#

Here is the device info:

(SWGE001-STO-DC1.ita.local) #show version

Switch: 2

System Description............................. M5300-28G3 ProSafe 24-port Gigabit L3 with 10 Gigabit Stacking, 10.0.0.44, B1.0.0.5
Machine Model.................................. M5300-28G3
Serial Number..................................<REDACTED>
Burned In MAC Address..........................<REDACTED>
Software Version............................... 10.0.0.44
Bootcode Version............................... B1.0.0.5
Supported Java Plugin Version.................. 1.6
Current Time................................... Feb 15 17:31:24 1971 (UTC+0:00)
Current SNTP Sync Status....................... Other

(SWGE001-STO-DC1.ita.local) #
@pv2b

This comment has been minimized.

Show comment
Hide comment
@pv2b

pv2b Nov 15, 2017

Contributor

Also, here's the stdout with the global debug set to true:

Nov 15 19:16:51 mgt02 oxidized[19314]: D, [2017-11-15T19:16:51.705473 #19314] DEBUG -- : lib/oxidized/job.rb: Starting fetching process for swge001-sto-dc1.ita.local at 2017-11-15 18:16:51 UTC
Nov 15 19:16:51 mgt02 oxidized[19314]: D, [2017-11-15T19:16:51.706054 #19314] DEBUG -- : lib/oxidized/input/ssh.rb: Connecting to swge001-sto-dc1.ita.local
Nov 15 19:16:52 mgt02 oxidized[19314]: D, [2017-11-15T19:16:52.141393 #19314] DEBUG -- : lib/oxidized/input/ssh.rb: expecting [/^(\([\w\-.]+\)\s[#>])$/] at swge001-sto-dc1.ita.local
Nov 15 19:16:52 mgt02 oxidized[19314]: D, [2017-11-15T19:16:52.705619 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:16:52 mgt02 oxidized[19314]: D, [2017-11-15T19:16:52.947317 #19314] DEBUG -- : lib/oxidized/input/cli.rb: Running post_login commands at swge001-sto-dc1.ita.local
Nov 15 19:16:52 mgt02 oxidized[19314]: D, [2017-11-15T19:16:52.947835 #19314] DEBUG -- : lib/oxidized/input/cli.rb: Running post_login command: nil, block: #<Proc:0x007fc8f80af280@/var/lib/gems/2.3.0/gem
Nov 15 19:16:52 mgt02 oxidized[19314]: D, [2017-11-15T19:16:52.948168 #19314] DEBUG -- : lib/oxidized/input/ssh.rb: expecting [/^.+[#]$/] at swge001-sto-dc1.ita.local
Nov 15 19:16:53 mgt02 oxidized[19314]: D, [2017-11-15T19:16:53.437917 #19314] DEBUG -- : lib/oxidized/input/cli.rb: Running post_login command: "terminal length 0", block: nil at swge001-sto-dc1.ita.loca
Nov 15 19:16:53 mgt02 oxidized[19314]: D, [2017-11-15T19:16:53.438446 #19314] DEBUG -- : lib/oxidized/input/ssh.rb terminal length 0 @ swge001-sto-dc1.ita.local with expect: /^(\([\w\-.]+\)\s[#>])$/
Nov 15 19:16:53 mgt02 oxidized[19314]: D, [2017-11-15T19:16:53.438839 #19314] DEBUG -- : lib/oxidized/input/ssh.rb: expecting [/^(\([\w\-.]+\)\s[#>])$/] at swge001-sto-dc1.ita.local
Nov 15 19:16:53 mgt02 oxidized[19314]: D, [2017-11-15T19:16:53.706405 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:16:53 mgt02 oxidized[19314]: D, [2017-11-15T19:16:53.846273 #19314] DEBUG -- : lib/oxidized/model/model.rb Collecting commands' outputs
Nov 15 19:16:53 mgt02 oxidized[19314]: D, [2017-11-15T19:16:53.846773 #19314] DEBUG -- : lib/oxidized/model/model.rb Executing show running-config
Nov 15 19:16:53 mgt02 oxidized[19314]: D, [2017-11-15T19:16:53.847063 #19314] DEBUG -- : lib/oxidized/input/ssh.rb show running-config @ swge001-sto-dc1.ita.local with expect: /^(\([\w\-.]+\)\s[#>])$/
Nov 15 19:16:53 mgt02 oxidized[19314]: D, [2017-11-15T19:16:53.847473 #19314] DEBUG -- : lib/oxidized/input/ssh.rb: expecting [/^(\([\w\-.]+\)\s[#>])$/] at swge001-sto-dc1.ita.local
Nov 15 19:16:54 mgt02 oxidized[19314]: D, [2017-11-15T19:16:54.707108 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:16:55 mgt02 oxidized[19314]: D, [2017-11-15T19:16:55.656673 #19314] DEBUG -- : lib/oxidized/input/cli.rb Running pre_logout commands at swge001-sto-dc1.ita.local
Nov 15 19:16:55 mgt02 oxidized[19314]: D, [2017-11-15T19:16:55.707849 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:16:56 mgt02 oxidized[19314]: D, [2017-11-15T19:16:56.708516 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:16:57 mgt02 oxidized[19314]: D, [2017-11-15T19:16:57.709197 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:16:58 mgt02 oxidized[19314]: D, [2017-11-15T19:16:58.710170 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:16:59 mgt02 oxidized[19314]: D, [2017-11-15T19:16:59.710500 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:00 mgt02 oxidized[19314]: D, [2017-11-15T19:17:00.710823 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:01 mgt02 oxidized[19314]: D, [2017-11-15T19:17:01.711180 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:02 mgt02 oxidized[19314]: D, [2017-11-15T19:17:02.711531 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:03 mgt02 oxidized[19314]: D, [2017-11-15T19:17:03.711795 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:04 mgt02 oxidized[19314]: D, [2017-11-15T19:17:04.712168 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:05 mgt02 oxidized[19314]: D, [2017-11-15T19:17:05.712442 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:06 mgt02 oxidized[19314]: D, [2017-11-15T19:17:06.712800 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:07 mgt02 oxidized[19314]: D, [2017-11-15T19:17:07.713044 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:08 mgt02 oxidized[19314]: D, [2017-11-15T19:17:08.713277 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:09 mgt02 oxidized[19314]: D, [2017-11-15T19:17:09.713582 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:10 mgt02 oxidized[19314]: D, [2017-11-15T19:17:10.713867 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:11 mgt02 oxidized[19314]: D, [2017-11-15T19:17:11.714244 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:12 mgt02 oxidized[19314]: D, [2017-11-15T19:17:12.715067 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:13 mgt02 oxidized[19314]: D, [2017-11-15T19:17:13.715494 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:14 mgt02 oxidized[19314]: D, [2017-11-15T19:17:14.715789 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:15 mgt02 oxidized[19314]: W, [2017-11-15T19:17:15.660530 #19314]  WARN -- : 10.0.9.6 raised Timeout::Error with msg "execution expired"
Nov 15 19:17:15 mgt02 oxidized[19314]: D, [2017-11-15T19:17:15.660612 #19314] DEBUG -- : lib/oxidized/node.rb: Oxidized::SSH failed for swge001-sto-dc1.ita.local
Nov 15 19:17:15 mgt02 oxidized[19314]: D, [2017-11-15T19:17:15.680978 #19314] DEBUG -- : lib/oxidized/node.rb: Oxidized::Telnet failed for swge001-sto-dc1.ita.local
Nov 15 19:17:15 mgt02 oxidized[19314]: D, [2017-11-15T19:17:15.681311 #19314] DEBUG -- : lib/oxidized/job.rb: Config fetched for swge001-sto-dc1.ita.local at 2017-11-15 18:17:15 UTC

Notice how it says "Running pre_logout commands"? This tells me what it happening is that it is detecting the end prompt, but then the pre_logout command does... nothing... and then it times out waiting for something to happen.

Contributor

pv2b commented Nov 15, 2017

Also, here's the stdout with the global debug set to true:

Nov 15 19:16:51 mgt02 oxidized[19314]: D, [2017-11-15T19:16:51.705473 #19314] DEBUG -- : lib/oxidized/job.rb: Starting fetching process for swge001-sto-dc1.ita.local at 2017-11-15 18:16:51 UTC
Nov 15 19:16:51 mgt02 oxidized[19314]: D, [2017-11-15T19:16:51.706054 #19314] DEBUG -- : lib/oxidized/input/ssh.rb: Connecting to swge001-sto-dc1.ita.local
Nov 15 19:16:52 mgt02 oxidized[19314]: D, [2017-11-15T19:16:52.141393 #19314] DEBUG -- : lib/oxidized/input/ssh.rb: expecting [/^(\([\w\-.]+\)\s[#>])$/] at swge001-sto-dc1.ita.local
Nov 15 19:16:52 mgt02 oxidized[19314]: D, [2017-11-15T19:16:52.705619 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:16:52 mgt02 oxidized[19314]: D, [2017-11-15T19:16:52.947317 #19314] DEBUG -- : lib/oxidized/input/cli.rb: Running post_login commands at swge001-sto-dc1.ita.local
Nov 15 19:16:52 mgt02 oxidized[19314]: D, [2017-11-15T19:16:52.947835 #19314] DEBUG -- : lib/oxidized/input/cli.rb: Running post_login command: nil, block: #<Proc:0x007fc8f80af280@/var/lib/gems/2.3.0/gem
Nov 15 19:16:52 mgt02 oxidized[19314]: D, [2017-11-15T19:16:52.948168 #19314] DEBUG -- : lib/oxidized/input/ssh.rb: expecting [/^.+[#]$/] at swge001-sto-dc1.ita.local
Nov 15 19:16:53 mgt02 oxidized[19314]: D, [2017-11-15T19:16:53.437917 #19314] DEBUG -- : lib/oxidized/input/cli.rb: Running post_login command: "terminal length 0", block: nil at swge001-sto-dc1.ita.loca
Nov 15 19:16:53 mgt02 oxidized[19314]: D, [2017-11-15T19:16:53.438446 #19314] DEBUG -- : lib/oxidized/input/ssh.rb terminal length 0 @ swge001-sto-dc1.ita.local with expect: /^(\([\w\-.]+\)\s[#>])$/
Nov 15 19:16:53 mgt02 oxidized[19314]: D, [2017-11-15T19:16:53.438839 #19314] DEBUG -- : lib/oxidized/input/ssh.rb: expecting [/^(\([\w\-.]+\)\s[#>])$/] at swge001-sto-dc1.ita.local
Nov 15 19:16:53 mgt02 oxidized[19314]: D, [2017-11-15T19:16:53.706405 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:16:53 mgt02 oxidized[19314]: D, [2017-11-15T19:16:53.846273 #19314] DEBUG -- : lib/oxidized/model/model.rb Collecting commands' outputs
Nov 15 19:16:53 mgt02 oxidized[19314]: D, [2017-11-15T19:16:53.846773 #19314] DEBUG -- : lib/oxidized/model/model.rb Executing show running-config
Nov 15 19:16:53 mgt02 oxidized[19314]: D, [2017-11-15T19:16:53.847063 #19314] DEBUG -- : lib/oxidized/input/ssh.rb show running-config @ swge001-sto-dc1.ita.local with expect: /^(\([\w\-.]+\)\s[#>])$/
Nov 15 19:16:53 mgt02 oxidized[19314]: D, [2017-11-15T19:16:53.847473 #19314] DEBUG -- : lib/oxidized/input/ssh.rb: expecting [/^(\([\w\-.]+\)\s[#>])$/] at swge001-sto-dc1.ita.local
Nov 15 19:16:54 mgt02 oxidized[19314]: D, [2017-11-15T19:16:54.707108 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:16:55 mgt02 oxidized[19314]: D, [2017-11-15T19:16:55.656673 #19314] DEBUG -- : lib/oxidized/input/cli.rb Running pre_logout commands at swge001-sto-dc1.ita.local
Nov 15 19:16:55 mgt02 oxidized[19314]: D, [2017-11-15T19:16:55.707849 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:16:56 mgt02 oxidized[19314]: D, [2017-11-15T19:16:56.708516 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:16:57 mgt02 oxidized[19314]: D, [2017-11-15T19:16:57.709197 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:16:58 mgt02 oxidized[19314]: D, [2017-11-15T19:16:58.710170 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:16:59 mgt02 oxidized[19314]: D, [2017-11-15T19:16:59.710500 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:00 mgt02 oxidized[19314]: D, [2017-11-15T19:17:00.710823 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:01 mgt02 oxidized[19314]: D, [2017-11-15T19:17:01.711180 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:02 mgt02 oxidized[19314]: D, [2017-11-15T19:17:02.711531 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:03 mgt02 oxidized[19314]: D, [2017-11-15T19:17:03.711795 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:04 mgt02 oxidized[19314]: D, [2017-11-15T19:17:04.712168 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:05 mgt02 oxidized[19314]: D, [2017-11-15T19:17:05.712442 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:06 mgt02 oxidized[19314]: D, [2017-11-15T19:17:06.712800 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:07 mgt02 oxidized[19314]: D, [2017-11-15T19:17:07.713044 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:08 mgt02 oxidized[19314]: D, [2017-11-15T19:17:08.713277 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:09 mgt02 oxidized[19314]: D, [2017-11-15T19:17:09.713582 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:10 mgt02 oxidized[19314]: D, [2017-11-15T19:17:10.713867 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:11 mgt02 oxidized[19314]: D, [2017-11-15T19:17:11.714244 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:12 mgt02 oxidized[19314]: D, [2017-11-15T19:17:12.715067 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:13 mgt02 oxidized[19314]: D, [2017-11-15T19:17:13.715494 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:14 mgt02 oxidized[19314]: D, [2017-11-15T19:17:14.715789 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:17:15 mgt02 oxidized[19314]: W, [2017-11-15T19:17:15.660530 #19314]  WARN -- : 10.0.9.6 raised Timeout::Error with msg "execution expired"
Nov 15 19:17:15 mgt02 oxidized[19314]: D, [2017-11-15T19:17:15.660612 #19314] DEBUG -- : lib/oxidized/node.rb: Oxidized::SSH failed for swge001-sto-dc1.ita.local
Nov 15 19:17:15 mgt02 oxidized[19314]: D, [2017-11-15T19:17:15.680978 #19314] DEBUG -- : lib/oxidized/node.rb: Oxidized::Telnet failed for swge001-sto-dc1.ita.local
Nov 15 19:17:15 mgt02 oxidized[19314]: D, [2017-11-15T19:17:15.681311 #19314] DEBUG -- : lib/oxidized/job.rb: Config fetched for swge001-sto-dc1.ita.local at 2017-11-15 18:17:15 UTC

Notice how it says "Running pre_logout commands"? This tells me what it happening is that it is detecting the end prompt, but then the pre_logout command does... nothing... and then it times out waiting for something to happen.

@pv2b

This comment has been minimized.

Show comment
Hide comment
@pv2b

pv2b Nov 15, 2017

Contributor

OK, I've done some more investigation, and I think I'm getting closer to an answer.

The root cause seems to be that "falling off the edge" of an SSH session and a telnet session are actually handled differently, so it's failing for SSH but actually working for telnet!

For SSH, if there's a time out waiting for nothing to happen, it throws an error.

However, for telnet, there is no such treatment. See the below logs, first you'll see a failed attempt using ssh and a successful attempt using telnet.

Nov 15 19:36:01 mgt02 oxidized[19314]: D, [2017-11-15T19:36:01.176131 #19314] DEBUG -- : lib/oxidized/job.rb: Starting fetching process for swge001-sto-dc1.ita.local at 2017-11-15 18:36:01 UTC
Nov 15 19:36:01 mgt02 oxidized[19314]: D, [2017-11-15T19:36:01.176803 #19314] DEBUG -- : lib/oxidized/input/ssh.rb: Connecting to swge001-sto-dc1.ita.local
Nov 15 19:36:01 mgt02 oxidized[19314]: D, [2017-11-15T19:36:01.694583 #19314] DEBUG -- : lib/oxidized/input/ssh.rb: expecting [/^(\([\w\-.]+\)\s[#>])$/] at swge001-sto-dc1.ita.local
Nov 15 19:36:02 mgt02 oxidized[19314]: D, [2017-11-15T19:36:02.176311 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:02 mgt02 oxidized[19314]: D, [2017-11-15T19:36:02.500627 #19314] DEBUG -- : lib/oxidized/input/cli.rb: Running post_login commands at swge001-sto-dc1.ita.local
Nov 15 19:36:02 mgt02 oxidized[19314]: D, [2017-11-15T19:36:02.500968 #19314] DEBUG -- : lib/oxidized/input/cli.rb: Running post_login command: nil, block: #<Proc:0x0000000277f900@/var/lib/gems/2.3.0/gems/oxidized-0.21.0/lib/oxidized/model/netgear.rb:18> at swge001-sto-dc1.ita.local
Nov 15 19:36:02 mgt02 oxidized[19314]: D, [2017-11-15T19:36:02.501357 #19314] DEBUG -- : lib/oxidized/input/ssh.rb: expecting [/^.+[#]$/] at swge001-sto-dc1.ita.local
Nov 15 19:36:02 mgt02 oxidized[19314]: D, [2017-11-15T19:36:02.906294 #19314] DEBUG -- : lib/oxidized/input/cli.rb: Running post_login command: "terminal length 0", block: nil at swge001-sto-dc1.ita.local
Nov 15 19:36:02 mgt02 oxidized[19314]: D, [2017-11-15T19:36:02.906967 #19314] DEBUG -- : lib/oxidized/input/ssh.rb terminal length 0 @ swge001-sto-dc1.ita.local with expect: /^(\([\w\-.]+\)\s[#>])$/
Nov 15 19:36:02 mgt02 oxidized[19314]: D, [2017-11-15T19:36:02.907404 #19314] DEBUG -- : lib/oxidized/input/ssh.rb: expecting [/^(\([\w\-.]+\)\s[#>])$/] at swge001-sto-dc1.ita.local
Nov 15 19:36:03 mgt02 oxidized[19314]: D, [2017-11-15T19:36:03.177137 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:03 mgt02 oxidized[19314]: D, [2017-11-15T19:36:03.313472 #19314] DEBUG -- : lib/oxidized/model/model.rb Collecting commands' outputs
Nov 15 19:36:03 mgt02 oxidized[19314]: D, [2017-11-15T19:36:03.313905 #19314] DEBUG -- : lib/oxidized/model/model.rb Executing show running-config
Nov 15 19:36:03 mgt02 oxidized[19314]: D, [2017-11-15T19:36:03.314296 #19314] DEBUG -- : lib/oxidized/input/ssh.rb show running-config @ swge001-sto-dc1.ita.local with expect: /^(\([\w\-.]+\)\s[#>])$/
Nov 15 19:36:03 mgt02 oxidized[19314]: D, [2017-11-15T19:36:03.314783 #19314] DEBUG -- : lib/oxidized/input/ssh.rb: expecting [/^(\([\w\-.]+\)\s[#>])$/] at swge001-sto-dc1.ita.local
Nov 15 19:36:04 mgt02 oxidized[19314]: D, [2017-11-15T19:36:04.177820 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:05 mgt02 oxidized[19314]: D, [2017-11-15T19:36:05.178709 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:05 mgt02 oxidized[19314]: D, [2017-11-15T19:36:05.352687 #19314] DEBUG -- : lib/oxidized/input/cli.rb Running pre_logout commands at swge001-sto-dc1.ita.local
Nov 15 19:36:06 mgt02 oxidized[19314]: D, [2017-11-15T19:36:06.179603 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:07 mgt02 oxidized[19314]: D, [2017-11-15T19:36:07.180427 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:08 mgt02 oxidized[19314]: D, [2017-11-15T19:36:08.181279 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:09 mgt02 oxidized[19314]: D, [2017-11-15T19:36:09.181625 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:10 mgt02 oxidized[19314]: D, [2017-11-15T19:36:10.181950 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:11 mgt02 oxidized[19314]: D, [2017-11-15T19:36:11.182288 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:12 mgt02 oxidized[19314]: D, [2017-11-15T19:36:12.182629 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:13 mgt02 oxidized[19314]: D, [2017-11-15T19:36:13.182983 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:14 mgt02 oxidized[19314]: D, [2017-11-15T19:36:14.183337 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:15 mgt02 oxidized[19314]: D, [2017-11-15T19:36:15.183771 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:16 mgt02 oxidized[19314]: D, [2017-11-15T19:36:16.184126 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:17 mgt02 oxidized[19314]: D, [2017-11-15T19:36:17.184471 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:18 mgt02 oxidized[19314]: D, [2017-11-15T19:36:18.184741 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:19 mgt02 oxidized[19314]: D, [2017-11-15T19:36:19.185120 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:20 mgt02 oxidized[19314]: D, [2017-11-15T19:36:20.185398 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:21 mgt02 oxidized[19314]: D, [2017-11-15T19:36:21.185717 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:22 mgt02 oxidized[19314]: D, [2017-11-15T19:36:22.186056 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:23 mgt02 oxidized[19314]: D, [2017-11-15T19:36:23.186358 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:24 mgt02 oxidized[19314]: D, [2017-11-15T19:36:24.186692 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:25 mgt02 oxidized[19314]: D, [2017-11-15T19:36:25.186997 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:25 mgt02 oxidized[19314]: W, [2017-11-15T19:36:25.356173 #19314]  WARN -- : 10.0.9.6 raised Timeout::Error with msg "execution expired"
Nov 15 19:36:25 mgt02 oxidized[19314]: D, [2017-11-15T19:36:25.356282 #19314] DEBUG -- : lib/oxidized/node.rb: Oxidized::SSH failed for swge001-sto-dc1.ita.local
Nov 15 19:36:25 mgt02 oxidized[19314]: D, [2017-11-15T19:36:25.520601 #19314] DEBUG -- : lib/oxidized/input/cli.rb: Running post_login commands at swge001-sto-dc1.ita.local
Nov 15 19:36:25 mgt02 oxidized[19314]: D, [2017-11-15T19:36:25.521136 #19314] DEBUG -- : lib/oxidized/input/cli.rb: Running post_login command: nil, block: #<Proc:0x0000000203a8e8@/var/lib/gems/2.3.0/gems/oxidized-0.21.0/lib/oxidized/model/netgear.rb:18> at swge001-sto-dc1.ita.local
Nov 15 19:36:25 mgt02 oxidized[19314]: D, [2017-11-15T19:36:25.585001 #19314] DEBUG -- : lib/oxidized/input/cli.rb: Running post_login command: "terminal length 0", block: nil at swge001-sto-dc1.ita.local
Nov 15 19:36:25 mgt02 oxidized[19314]: D, [2017-11-15T19:36:25.585443 #19314] DEBUG -- : Telnet: terminal length 0 @swge001-sto-dc1.ita.local
Nov 15 19:36:25 mgt02 oxidized[19314]: D, [2017-11-15T19:36:25.652695 #19314] DEBUG -- : lib/oxidized/model/model.rb Collecting commands' outputs
Nov 15 19:36:25 mgt02 oxidized[19314]: D, [2017-11-15T19:36:25.653171 #19314] DEBUG -- : lib/oxidized/model/model.rb Executing show running-config
Nov 15 19:36:25 mgt02 oxidized[19314]: D, [2017-11-15T19:36:25.653431 #19314] DEBUG -- : Telnet: show running-config @swge001-sto-dc1.ita.local
Nov 15 19:36:26 mgt02 oxidized[19314]: D, [2017-11-15T19:36:26.093226 #19314] DEBUG -- : lib/oxidized/input/cli.rb Running pre_logout commands at swge001-sto-dc1.ita.local
Nov 15 19:36:26 mgt02 oxidized[19314]: D, [2017-11-15T19:36:26.093740 #19314] DEBUG -- : lib/oxidized/node.rb: Oxidized::Telnet ran for swge001-sto-dc1.ita.local successfully
Nov 15 19:36:26 mgt02 oxidized[19314]: D, [2017-11-15T19:36:26.094035 #19314] DEBUG -- : lib/oxidized/job.rb: Config fetched for swge001-sto-dc1.ita.local at 2017-11-15 18:36:26 UTC
Nov 15 19:36:26 mgt02 oxidized[19314]: I, [2017-11-15T19:36:26.189816 #19314]  INFO -- : Configuration updated for /swge001-sto-dc1.ita.local

See the disconnect methods of the telnet and ssh classes and the disconnect_cli method in cli.rb

def disconnect_cli
Oxidized.logger.debug "lib/oxidized/input/cli.rb Running pre_logout commands at #{node.name}"
@pre_logout.each { |command, block| block ? block.call : (cmd command, nil) }
end

def disconnect
disconnect_cli
# if disconnect does not disconnect us, give up after timeout
Timeout::timeout(Oxidized.config.timeout) { @ssh.loop }
rescue Errno::ECONNRESET, Net::SSH::Disconnect, IOError
ensure
@log.close if Oxidized.config.input.debug?
(@ssh.close rescue true) unless @ssh.closed?
end

def disconnect
begin
disconnect_cli
@telnet.close
rescue Errno::ECONNRESET
end
end

Therefore, I think that while #923 fixed telnet (by adding checks for telnet login prompts etc) it also broke SSH by no longer explicitly quitting any more.

I think the real fix needs to happen at either the ssh or telnet module to make them act consistently. I'd submit a PR but my Ruby isn't quite strong enough and I'm sure I'd end up breaking more stuff than fixed.

Contributor

pv2b commented Nov 15, 2017

OK, I've done some more investigation, and I think I'm getting closer to an answer.

The root cause seems to be that "falling off the edge" of an SSH session and a telnet session are actually handled differently, so it's failing for SSH but actually working for telnet!

For SSH, if there's a time out waiting for nothing to happen, it throws an error.

However, for telnet, there is no such treatment. See the below logs, first you'll see a failed attempt using ssh and a successful attempt using telnet.

Nov 15 19:36:01 mgt02 oxidized[19314]: D, [2017-11-15T19:36:01.176131 #19314] DEBUG -- : lib/oxidized/job.rb: Starting fetching process for swge001-sto-dc1.ita.local at 2017-11-15 18:36:01 UTC
Nov 15 19:36:01 mgt02 oxidized[19314]: D, [2017-11-15T19:36:01.176803 #19314] DEBUG -- : lib/oxidized/input/ssh.rb: Connecting to swge001-sto-dc1.ita.local
Nov 15 19:36:01 mgt02 oxidized[19314]: D, [2017-11-15T19:36:01.694583 #19314] DEBUG -- : lib/oxidized/input/ssh.rb: expecting [/^(\([\w\-.]+\)\s[#>])$/] at swge001-sto-dc1.ita.local
Nov 15 19:36:02 mgt02 oxidized[19314]: D, [2017-11-15T19:36:02.176311 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:02 mgt02 oxidized[19314]: D, [2017-11-15T19:36:02.500627 #19314] DEBUG -- : lib/oxidized/input/cli.rb: Running post_login commands at swge001-sto-dc1.ita.local
Nov 15 19:36:02 mgt02 oxidized[19314]: D, [2017-11-15T19:36:02.500968 #19314] DEBUG -- : lib/oxidized/input/cli.rb: Running post_login command: nil, block: #<Proc:0x0000000277f900@/var/lib/gems/2.3.0/gems/oxidized-0.21.0/lib/oxidized/model/netgear.rb:18> at swge001-sto-dc1.ita.local
Nov 15 19:36:02 mgt02 oxidized[19314]: D, [2017-11-15T19:36:02.501357 #19314] DEBUG -- : lib/oxidized/input/ssh.rb: expecting [/^.+[#]$/] at swge001-sto-dc1.ita.local
Nov 15 19:36:02 mgt02 oxidized[19314]: D, [2017-11-15T19:36:02.906294 #19314] DEBUG -- : lib/oxidized/input/cli.rb: Running post_login command: "terminal length 0", block: nil at swge001-sto-dc1.ita.local
Nov 15 19:36:02 mgt02 oxidized[19314]: D, [2017-11-15T19:36:02.906967 #19314] DEBUG -- : lib/oxidized/input/ssh.rb terminal length 0 @ swge001-sto-dc1.ita.local with expect: /^(\([\w\-.]+\)\s[#>])$/
Nov 15 19:36:02 mgt02 oxidized[19314]: D, [2017-11-15T19:36:02.907404 #19314] DEBUG -- : lib/oxidized/input/ssh.rb: expecting [/^(\([\w\-.]+\)\s[#>])$/] at swge001-sto-dc1.ita.local
Nov 15 19:36:03 mgt02 oxidized[19314]: D, [2017-11-15T19:36:03.177137 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:03 mgt02 oxidized[19314]: D, [2017-11-15T19:36:03.313472 #19314] DEBUG -- : lib/oxidized/model/model.rb Collecting commands' outputs
Nov 15 19:36:03 mgt02 oxidized[19314]: D, [2017-11-15T19:36:03.313905 #19314] DEBUG -- : lib/oxidized/model/model.rb Executing show running-config
Nov 15 19:36:03 mgt02 oxidized[19314]: D, [2017-11-15T19:36:03.314296 #19314] DEBUG -- : lib/oxidized/input/ssh.rb show running-config @ swge001-sto-dc1.ita.local with expect: /^(\([\w\-.]+\)\s[#>])$/
Nov 15 19:36:03 mgt02 oxidized[19314]: D, [2017-11-15T19:36:03.314783 #19314] DEBUG -- : lib/oxidized/input/ssh.rb: expecting [/^(\([\w\-.]+\)\s[#>])$/] at swge001-sto-dc1.ita.local
Nov 15 19:36:04 mgt02 oxidized[19314]: D, [2017-11-15T19:36:04.177820 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:05 mgt02 oxidized[19314]: D, [2017-11-15T19:36:05.178709 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:05 mgt02 oxidized[19314]: D, [2017-11-15T19:36:05.352687 #19314] DEBUG -- : lib/oxidized/input/cli.rb Running pre_logout commands at swge001-sto-dc1.ita.local
Nov 15 19:36:06 mgt02 oxidized[19314]: D, [2017-11-15T19:36:06.179603 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:07 mgt02 oxidized[19314]: D, [2017-11-15T19:36:07.180427 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:08 mgt02 oxidized[19314]: D, [2017-11-15T19:36:08.181279 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:09 mgt02 oxidized[19314]: D, [2017-11-15T19:36:09.181625 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:10 mgt02 oxidized[19314]: D, [2017-11-15T19:36:10.181950 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:11 mgt02 oxidized[19314]: D, [2017-11-15T19:36:11.182288 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:12 mgt02 oxidized[19314]: D, [2017-11-15T19:36:12.182629 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:13 mgt02 oxidized[19314]: D, [2017-11-15T19:36:13.182983 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:14 mgt02 oxidized[19314]: D, [2017-11-15T19:36:14.183337 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:15 mgt02 oxidized[19314]: D, [2017-11-15T19:36:15.183771 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:16 mgt02 oxidized[19314]: D, [2017-11-15T19:36:16.184126 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:17 mgt02 oxidized[19314]: D, [2017-11-15T19:36:17.184471 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:18 mgt02 oxidized[19314]: D, [2017-11-15T19:36:18.184741 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:19 mgt02 oxidized[19314]: D, [2017-11-15T19:36:19.185120 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:20 mgt02 oxidized[19314]: D, [2017-11-15T19:36:20.185398 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:21 mgt02 oxidized[19314]: D, [2017-11-15T19:36:21.185717 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:22 mgt02 oxidized[19314]: D, [2017-11-15T19:36:22.186056 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:23 mgt02 oxidized[19314]: D, [2017-11-15T19:36:23.186358 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:24 mgt02 oxidized[19314]: D, [2017-11-15T19:36:24.186692 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:25 mgt02 oxidized[19314]: D, [2017-11-15T19:36:25.186997 #19314] DEBUG -- : lib/oxidized/worker.rb: 1 jobs running in parallel
Nov 15 19:36:25 mgt02 oxidized[19314]: W, [2017-11-15T19:36:25.356173 #19314]  WARN -- : 10.0.9.6 raised Timeout::Error with msg "execution expired"
Nov 15 19:36:25 mgt02 oxidized[19314]: D, [2017-11-15T19:36:25.356282 #19314] DEBUG -- : lib/oxidized/node.rb: Oxidized::SSH failed for swge001-sto-dc1.ita.local
Nov 15 19:36:25 mgt02 oxidized[19314]: D, [2017-11-15T19:36:25.520601 #19314] DEBUG -- : lib/oxidized/input/cli.rb: Running post_login commands at swge001-sto-dc1.ita.local
Nov 15 19:36:25 mgt02 oxidized[19314]: D, [2017-11-15T19:36:25.521136 #19314] DEBUG -- : lib/oxidized/input/cli.rb: Running post_login command: nil, block: #<Proc:0x0000000203a8e8@/var/lib/gems/2.3.0/gems/oxidized-0.21.0/lib/oxidized/model/netgear.rb:18> at swge001-sto-dc1.ita.local
Nov 15 19:36:25 mgt02 oxidized[19314]: D, [2017-11-15T19:36:25.585001 #19314] DEBUG -- : lib/oxidized/input/cli.rb: Running post_login command: "terminal length 0", block: nil at swge001-sto-dc1.ita.local
Nov 15 19:36:25 mgt02 oxidized[19314]: D, [2017-11-15T19:36:25.585443 #19314] DEBUG -- : Telnet: terminal length 0 @swge001-sto-dc1.ita.local
Nov 15 19:36:25 mgt02 oxidized[19314]: D, [2017-11-15T19:36:25.652695 #19314] DEBUG -- : lib/oxidized/model/model.rb Collecting commands' outputs
Nov 15 19:36:25 mgt02 oxidized[19314]: D, [2017-11-15T19:36:25.653171 #19314] DEBUG -- : lib/oxidized/model/model.rb Executing show running-config
Nov 15 19:36:25 mgt02 oxidized[19314]: D, [2017-11-15T19:36:25.653431 #19314] DEBUG -- : Telnet: show running-config @swge001-sto-dc1.ita.local
Nov 15 19:36:26 mgt02 oxidized[19314]: D, [2017-11-15T19:36:26.093226 #19314] DEBUG -- : lib/oxidized/input/cli.rb Running pre_logout commands at swge001-sto-dc1.ita.local
Nov 15 19:36:26 mgt02 oxidized[19314]: D, [2017-11-15T19:36:26.093740 #19314] DEBUG -- : lib/oxidized/node.rb: Oxidized::Telnet ran for swge001-sto-dc1.ita.local successfully
Nov 15 19:36:26 mgt02 oxidized[19314]: D, [2017-11-15T19:36:26.094035 #19314] DEBUG -- : lib/oxidized/job.rb: Config fetched for swge001-sto-dc1.ita.local at 2017-11-15 18:36:26 UTC
Nov 15 19:36:26 mgt02 oxidized[19314]: I, [2017-11-15T19:36:26.189816 #19314]  INFO -- : Configuration updated for /swge001-sto-dc1.ita.local

See the disconnect methods of the telnet and ssh classes and the disconnect_cli method in cli.rb

def disconnect_cli
Oxidized.logger.debug "lib/oxidized/input/cli.rb Running pre_logout commands at #{node.name}"
@pre_logout.each { |command, block| block ? block.call : (cmd command, nil) }
end

def disconnect
disconnect_cli
# if disconnect does not disconnect us, give up after timeout
Timeout::timeout(Oxidized.config.timeout) { @ssh.loop }
rescue Errno::ECONNRESET, Net::SSH::Disconnect, IOError
ensure
@log.close if Oxidized.config.input.debug?
(@ssh.close rescue true) unless @ssh.closed?
end

def disconnect
begin
disconnect_cli
@telnet.close
rescue Errno::ECONNRESET
end
end

Therefore, I think that while #923 fixed telnet (by adding checks for telnet login prompts etc) it also broke SSH by no longer explicitly quitting any more.

I think the real fix needs to happen at either the ssh or telnet module to make them act consistently. I'd submit a PR but my Ruby isn't quite strong enough and I'm sure I'd end up breaking more stuff than fixed.

@laf

This comment has been minimized.

Show comment
Hide comment
@laf

laf Nov 15, 2017

Collaborator

Thanks for all of the info.

Unfortunately I don't have the answer, maybe someone else will help out.

Collaborator

laf commented Nov 15, 2017

Thanks for all of the info.

Unfortunately I don't have the answer, maybe someone else will help out.

@wk wk added the device_model label Apr 29, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment