ktbyers/netmiko

Not able to catch output proper

Closed this issue · 10 comments

Description of Issue/Question

Note: Please check https://guides.github.com/features/mastering-markdown/
to see how to properly format your request.

Setup

Netmiko version

(Paste verbatim output from pip freeze | grep netmiko between quotes below)


Netmiko device_type (if relevant to the issue)

(Paste device_type between quotes below)

Cisco C9300

Steps to Reproduce the Issue

Error Traceback

(Paste the complete traceback of the exception between quotes below)

Im adding two tracebacks, one working, one not, code is the same. 

working one:
SWITCH#
SWITCH#
SWITCH#
SWITCH#
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:[find_prompt()]: prompt is SWITCH#
DEBUG:netmiko:write_channel: b'show install committed\n'
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: show i
DEBUG:netmiko:read_channel: nstall comm
DEBUG:netmiko:read_channel: itted

DEBUG:netmiko:Pattern found: (show\ install\ committed) show install committed
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: [ Switch 1 2 3 ] Committed Package(s) Information:
State (St): I - Inactive, U - Activated & Uncommitted,
            C - Activated & Committed, D - Deactivated & Uncommitted
--------------------------------------------------------------------------------
Type  St   Filename/Version
--------------------------------------------------------------------------------
IMG   C    17.09.03.0.4111

--------------------------------------------------------------------------------
Auto abort timer: inactive
--------------------------------------------------------------------------------


SWITCH#
INFO:netmiko:Firmware successfully insalled
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:write_channel: b'\n'
DEBUG:netmiko:read_channel: 
SWITCH#
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:[find_prompt()]: prompt is SWITCH#
DEBUG:netmiko:write_channel: b'show reload\n'
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: show
DEBUG:netmiko:read_channel:  reload

DEBUG:netmiko:Pattern found: (show\ reload) show reload
DEBUG:netmiko:read_channel: Reload scheduled for 03:00:00 CEST Wed Jun 19 2024 (in 13 hours and 31 minutes) by xxx on vty1 (xxx)
Reload reason: FirmwareUpdate
SWITCH#
INFO:netmiko:Reboot successfull scheduled for: 03:00 - 19 / Jun
INFO:netmiko:Firmware successfully installed and reboot scheduled in 0:07:41.603764
DEBUG:netmiko:write_channel: b'\n'
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 
SWITCH#
DEBUG:netmiko:Pattern found: ([>#]) 
SWITCH#
DEBUG:netmiko:write_channel: b'exit\n'




Faulty one:



DEBUG:netmiko:read_channel: Reload scheduled for 03:00:00 CEST Wed Jun 19 2024 (in 13 hours and 3 minutes) by xxx on vty0 (xxx)
Reload reason: FirmwareUpdateReload command is being issued on Active unit, this will reload the whole stack
Proceed with reload? [confirm]
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 

SWITCH2
SWITCH2sho
DEBUG:netmiko:read_channel: w instal
DEBUG:netmiko:read_channel: l commit
DEBUG:netmiko:read_channel: ted

DEBUG:netmiko:Pattern found: (show\ install\ committed) Reload scheduled for 03:00:00 CEST Wed Jun 19 2024 (in 13 hours and 3 minutes) by xxx on vty0 (xxx)
Reload reason: FirmwareUpdateReload command is being issued on Active unit, this will reload the whole stack
Proceed with reload? [confirm]

SWITCH2
SWITCH2show install committed
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: [ Switch 1 2 3 ] Committed Package(s) Information:
State (St): I - Inactive, U - Activated & Uncommitted,
            C - Activated & Committed, D - Deactivated & Uncommitted
--------------------------------------------------------------------------------
Type  St   Filename/Version
--------------------------------------------------------------------------------
IMG   C    17.09.03.0.4111

--------------------------------------------------------------------------------
Auto abort timer: inactive
--------------------------------------------------------------------------------


SWITCH2
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 
And so on till timeout...

Relevant Python code

(Please try to essentialize your Python code to the minimum code needed to reproduce the issue)
(Paste the code between the quotes below)

 with ConnectHandler(**cisco1) as net_connect:
        logger.info(name+" Connected")
        
        start_time = datetime.now() 
        end_time = datetime.now()
        delta_time = datetime.now() + timedelta(days=1) 
        
        output = net_connect.send_command(
            command_string="dir", 

        )
       
        if version not in output:
            output += "Missing Firmware File."
            print ("Missing Firmware File.")
            return
        else:
            try:
                net_connect.write_channel("conf t")
                net_connect.write_channel("\r\n")
                net_connect.write_channel("boot system flash:packages.conf")
                net_connect.write_channel("\r\n")
                net_connect.write_channel("exit")
                net_connect.write_channel("\r\n")
                net_connect.save_config()
                net_connect.write_channel("request platform software package install switch all file flash:"+version+" auto-copy")
                net_connect.send_command_expect(
                        command_string="\n\r",
                        read_timeout=3000,
                        expect_string = r"(>|#)"
                    )
                net_connect.save_config()
                net_connect.write_channel("Reload at 03:00 "+delta_time.strftime("%d")+" "+ delta_time.strftime("%b") +" reason FirmwareUpdate") #Should catch change of month (31.01->1.06) 
                net_connect.write_channel("\r\n")
                net_connect.write_channel("\r\n")
            
                output += net_connect.send_command(
                    command_string= "show install committed"
                )
                if "IMG" in output: #Check if .img is successfull installed an in comitted queue
                    logger.info("Firmware successfully insalled")
                    print("Firmware successfully insalled")
                else: #Raise Exception if not successfull
                    logger.info("Firmware could'nt be installed")
                    print ("Firmware could'nt be installed")
                    raise Exception("Firmware could'nt be installed - please check Logfiles and contact 2nd-Level")
                
                output += net_connect.send_command(
                    command_string="show reload", 
                )
                if "Reload scheduled" in output: #Check if reboot is successfull scheduled
                    logger.info("Reboot successfull scheduled for: 03:00 - "+delta_time.strftime("%d")+" / "+ delta_time.strftime("%b"))
                    print ("Reboot successfull scheduled for: 03:00 - "+delta_time.strftime("%d")+" / "+ delta_time.strftime("%b"))
                else: #Raise Exception if no reboot is scheduled
                    logger.info("Reboot couldn't be scheduled")
                    print ("Reboot couldn't be scheduled")
                    raise Exception("Reboot couldn't be scheduled - please check Logfiles and contact 2nd-Level")
                
            finally:
                end_time = datetime.now()
                print(f"Firmware successfully installed and reboot scheduled in {end_time - start_time}")
                logger.info(f"Firmware successfully installed and reboot scheduled in {end_time - start_time}")
    
    net_connect.disconnect()
    return

Oh - i see i didn't add it up. I'm on Version 4.3.0.

@tomdertoms So is this working properly then i.e. no issue?

The Code you see can drop both outputs, i dont know why or where the difference is. Sometimes it works flawless as in dump 1 - something it end's in timeout as you see in dump2. I really don't understand what's the issue.
I already tried adding find_prompt() as i seemed to me he just didnt "catch" the output, but that didn't solve it. Do you have any idea what could cause this behaviour or what i'm doin wrong?

Thank you very much in advance!

No one any idea? :/

I see three oddities in your "faulty" output:

  1. You have the following show up Proceed with reload? [confirm] (twice).
  2. You then try to move onto show install committed without verifying you have handled this [confirm] properly.
  3. You have a set of SWITCH2 in the failing output with no terminating character (no # at the end)?

Your use of all of these write_channel calls is likely going to be problematic in the way you are seeing.

If you do the write_channel() calls, then you need to put in checks that you are in the right state (i.e. do a bunchread_channe() and make sure you are where you expect you should be). Otherwise, Netmiko/Python will very likely go much faster than the underlying network device i.e. you will do a whole bunch of writes and the device will not have even responded to the first one.

It would likely be better to use send_command for all of these and use expect_string argument to match on any needed patterns you need to match (like confirm).

I already tried that way, if i go with send_command and my code looks like this:

output += net_connect.send_command( command_string = "conf t" ) net_connect.find_prompt() output +=net_connect.send_command( command_string = "boot system flash:packages.conf" ) net_connect.find_prompt() output += net_connect.send_command( command_string = "exit" ) net_connect.find_prompt() output += net_connect.send_command( command_string = "request platform software package install switch all file flash:"+version+" auto-copy" ) net_connect.find_prompt() output += net_connect.send_command_expect( command_string="\n\r", read_timeout=3000, expect_string = r"(>|#)" ) net_connect.find_prompt() output += net_connect.send_command( command_string = "reload at 03:00 "+delta_time.strftime("%d")+" "+ delta_time.strftime("%b") +" reason FirmwareUpdate" ) output += net_connect.send_command_expect( command_string="\n\r", expect_string = r"\[yes/no\]:" ) net_connect.find_prompt() output += net_connect.send_command( command_string= "show install committed" )

This is what happens - it just stops working after finishing one order :/

Directory of flash:/

688131 -rw- 2097152 Jun 17 2024 08:25:27 +02:00 nvram_config_bkup
688130 -rw- 2097152 Jun 17 2024 08:25:27 +02:00 nvram_config
49153 drwx 4096 Jun 14 2024 11:26:14 +02:00 .installer
688132 -rw- 1258131142 Jun 14 2024 11:24:52 +02:00 cat9k_iosxe.17.09.05.SPA.bin
688155 -rw- 3016 Nov 8 2023 04:12:34 +01:00 stby-vlan.dat
688152 -rw- 3016 Nov 8 2023 04:10:19 +01:00 vlan.dat
688185 -rw- 0 Nov 8 2023 04:10:19 +01:00 dope_hist
688149 -rw- 17004 Nov 8 2023 04:10:19 +01:00 rdope_out.txt
688151 -rw- 89 Nov 8 2023 04:10:18 +01:00 rdope.log
65537 drwx 4096 Nov 8 2023 04:10:05 +01:00 .prst_sync
688142 -rw- 634 Nov 8 2023 04:03:20 +01:00 boothelper.log
688148 -rwx 2049 Nov 8 2023 04:02:34 +01:00 svl_ipc.tcl
688147 -rw- 137940 Nov 8 2023 04:02:34 +01:00 memleak.tcl
688184 -rw- 1924 Nov 8 2023 04:02:32 +01:00 ISRGRootX1CrossSignDST.ca
688174 drwx 4096 Nov 8 2023 04:02:26 +01:00 EDScisco
106528 drwx 4096 Nov 8 2023 04:02:26 +01:00 dc_profile_dir
106497 drwx 4096 Nov 8 2023 04:02:26 +01:00 tech_support
688181 -rw- 35 Nov 8 2023 04:02:13 +01:00 mcelog.txt
688144 -rw- 444 Nov 8 2023 04:02:13 +01:00 bootloader_evt_handle.log
688180 -rwx 0 Nov 8 2023 04:01:12 +01:00 mode_event_log
688157 drwx 4096 Nov 8 2023 04:01:12 +01:00 SHARED-IOX
688182 -rw- 7488 Nov 7 2023 22:29:30 +01:00 packages.conf.00-
688183 -rw- 7535 Nov 7 2023 22:29:30 +01:00 packages.conf
319492 -rw- 7535 Nov 7 2023 22:27:55 +01:00 cat9k_iosxe.17.09.03.SPA.conf
450565 -rw- 53773515 Nov 7 2023 22:27:55 +01:00 cat9k-rpboot.17.09.03.SPA.pkg
450564 -rw- 9220 Nov 7 2023 22:26:42 +01:00 cat9k-wlc.17.09.03.SPA.pkg
450563 -rw- 18809860 Nov 7 2023 22:26:42 +01:00 cat9k-webui.17.09.03.SPA.pkg
450562 -rw- 39785480 Nov 7 2023 22:26:42 +01:00 cat9k-srdriver.17.09.03.SPA.pkg
385026 -rw- 65811460 Nov 7 2023 22:26:41 +01:00 cat9k-sipspa.17.09.03.SPA.pkg
352262 -rw- 51717128 Nov 7 2023 22:26:41 +01:00 cat9k-sipbase.17.09.03.SPA.pkg
335876 -rw- 816768004 Nov 7 2023 22:26:40 +01:00 cat9k-rpbase.17.09.03.SPA.pkg
335875 -rw- 9220 Nov 7 2023 22:26:39 +01:00 cat9k-lni.17.09.03.SPA.pkg
335874 -rw- 2151432 Nov 7 2023 22:26:39 +01:00 cat9k-guestshell.17.09.03.SPA.pkg
319494 -rw- 173028360 Nov 7 2023 22:26:39 +01:00 cat9k-espbase.17.09.03.SPA.pkg
319493 -rw- 26047500 Nov 7 2023 22:26:38 +01:00 cat9k-cc_srdriver.17.09.03.SPA.pkg
688176 drwx 4096 Oct 24 2022 02:02:19 +02:00 .rommon_sync
688160 -rw- 1606 Oct 24 2022 02:02:17 +02:00 StarfieldServicesRootCA.ca
688175 -rw- 1261 Oct 24 2022 02:02:17 +02:00 Baltimore.ca
688159 -rw- 1338 Oct 24 2022 02:02:17 +02:00 DigiCertGlobalRootCA.ca
688146 drwx 4096 Oct 24 2022 02:02:12 +02:00 fp_cc_crash
688161 -rw- 6802 Oct 21 2022 17:06:07 +02:00 packages.conf.01-
688153 -rw- 64 Oct 8 2021 10:25:35 +02:00 private-KS1
57347 drwx 4096 Sep 9 2021 07:51:28 +02:00 pnp-tech
49155 drwx 4096 Aug 13 2021 13:11:02 +02:00 .dbpersist
49160 drwx 4096 Aug 13 2021 13:03:50 +02:00 Apps
688154 -rw- 1440 Aug 13 2021 13:02:14 +02:00 2021_08_13T11_02_11.849205.xml
57345 drwx 4096 Aug 13 2021 12:54:32 +02:00 core
188417 drwx 4096 Aug 13 2021 12:54:15 +02:00 guest-share
180225 drwx 4096 Aug 13 2021 12:54:12 +02:00 pnp-info
163841 drwx 4096 Aug 13 2021 12:54:12 +02:00 onep
147457 drwx 4096 Aug 13 2021 12:46:31 +02:00 Tbot
106530 drwx 4096 Aug 13 2021 12:46:23 +02:00 sys_report
81921 drwx 4096 Aug 13 2021 12:46:15 +02:00 .rollback_timer

11353194496 bytes total (8047722496 bytes free)
Switch#
Switch#conf t
Enter configuration commands, one per line. End with CNTL/Z.
Switch(config)#
Switch(config)#
Switch(config)#end
Switch#
Switch#exit

Sorry - my code wasn't formatted - here again.

  output += net_connect.send_command(
                    command_string = "conf t"
                )
                net_connect.find_prompt()
                output +=net_connect.send_command(
                    command_string = "boot system flash:packages.conf"
                )
                net_connect.find_prompt()
                output += net_connect.send_command(
                    command_string = "exit"
                )
                net_connect.find_prompt()
                output += net_connect.send_command(
                    command_string = "request platform software package install switch all file flash:"+version+" auto-copy"
                )
                net_connect.find_prompt()
                output += net_connect.send_command_expect(
                        command_string="\n\r",
                        read_timeout=3000,
                        expect_string = r"(>|#)"
                ) 
                net_connect.find_prompt()
                output += net_connect.send_command(
                    command_string = "reload at 03:00 "+delta_time.strftime("%d")+" "+ delta_time.strftime("%b") +" reason FirmwareUpdate"
                )               
                output += net_connect.send_command_expect(
                        command_string="\n\r",
                        expect_string = r"\[yes/no\]:"
                )
                net_connect.find_prompt()
                output += net_connect.send_command(
                    command_string= "show install committed"
                )

I would expect more like:

If output exists before "boot" command then change to output += to append output.

output = net_connect.send_config_set("boot system flash:packages.conf")
cmd = f"request platform software package install switch all file flash:{version} auto-copy"
output += net_connect.send_command(
    command_string=cmd,
    read_timeout=3000,
    expect_string=r"(>|#)",         
)
day_of_month = delta_time.strftime("%d")
month = delta_time.strftime("%b")
cmd2 = f"reload at 03:00 {day_of_month} {month} reason FirmwareUpdate"
# This cmd2 should result in a "Proceed with reload? [confirm]" message
output += net_connect.send_command(
    command_string=cmd2,
    expect_string="confirm",
)
# Send an <enter> in response to the 'confirm' message.
output += net_connect.send_command(
    command_string="\n",
    expect_string=r"(>|#)",
)
output += net_connect.send_command(command_string="show install committed")

For config changes, you should use send_config_set which automatically enters and exits config mode.

send_command and send_command_expect are the same method.

For send_command calls that do NOT result in a prompt being returned, then you should use the expect_string argument.

Please verify that the CLI interaction is exactly as per the above (when you do this manually). OS upgrades are pretty hard you need to verify the interactions step-by-step which is pretty time consuming.

Regards,

Kirk

Thank you very much for your helps and efforts, i think i got finally the idea behind it and will try it during the weekend and give you feedback asap. Thank you you again very much!

Beste regards,
Tom

I just can say - thank you! I Implemented your suggestion and followed up the "way" it should be done, and it works simply flawless. I got a rudimentary way now and can build up on that. Thank you very much!
For all who struggle, here's a working base:

with ConnectHandler(**cisco1) as net_connect:
logger.info(name+" Connected")

    start_time = datetime.now() 
    end_time = datetime.now()
    delta_time = datetime.now() + timedelta(days=1) 
    
    net_connect.find_prompt()
    output = net_connect.send_command(
        command_string="dir", 

    )
   
    if version not in output:
        output += "Missing Firmware File."
        print ("Missing Firmware File.")
        return
    else:
        try:
            output = net_connect.send_config_set("boot system flash:packages.conf")
            output += net_connect.save_config()
            cmd = f"request platform software package install switch all file flash:{version} auto-copy"
            output += net_connect.send_command(
                command_string=cmd,
                read_timeout=3000,
                expect_string=r"(>|#)",         
            )
            cmd2 = f"reload at 03:00 {delta_time.strftime("%d")+" / "+ delta_time.strftime("%b")} reason FirmwareUpdate"
            # This cmd2 should result in a "Proceed with reload? [confirm]" message
            output += net_connect.send_command(
                command_string=cmd2,
                expect_string=r"\b"+"confirm"+r"\b",
            )
            # Send an <enter> in response to the 'confirm' message.
            output += net_connect.send_command(
                command_string="\n",
                expect_string=r"(>|#)",
            )
            output += net_connect.send_command(
                command_string="show install committed",
                expect_string=r"\b"+"Committed Package"+r"\b",
            )
            net_connect.find_prompt()
            if "IMG" in output: #Check if .img is successfull installed an in comitted queue
                logger.info("Firmware successfully installed")
                print("Firmware successfully insalled")
            else: #Raise Exception if not successfull
                logger.info("Firmware could'nt be installed")
                print ("Firmware could'nt be installed")
                raise Exception("Firmware could'nt be installed - please check Logfiles and contact 2nd-Level")
            net_connect.find_prompt()
            output += net_connect.send_command(
                command_string="show reload", 
            )
            net_connect.find_prompt()
            if "Reload scheduled" in output: #Check if reboot is successfull scheduled
                logger.info("Reboot successfull scheduled for: 03:00 - "+delta_time.strftime("%d")+" / "+ delta_time.strftime("%b"))
                print ("Reboot successfull scheduled for: 03:00 - "+delta_time.strftime("%d")+" / "+ delta_time.strftime("%b"))
            else: #Raise Exception if no reboot is scheduled
                logger.info("Reboot couldn't be scheduled")
                print ("Reboot couldn't be scheduled")
                raise Exception("Reboot couldn't be scheduled - please check Logfiles and contact 2nd-Level")
        except (NetmikoTimeoutException, ReadException, ReadTimeout) as e: 
            print("Something went wrong - please check Logfiles and contact 2nd-Level")
            print("Error details:", e)
            print("Continuing with next device")    
        finally:
            end_time = datetime.now()
            print(f"Firmware successfully installed and reboot scheduled in {end_time - start_time} at {name}")
            logger.info(f"Firmware successfully installed and reboot scheduled in {end_time - start_time} at {name}"

net_connect.disconnect()