Closed jakovlev54 closed 1 year ago
Hello, Carl! Can you suggest what's wrong?
👋 hey can you get logs and please format the code so it’s easier to see what’s going on. Looks like (from mobile so maybe I’m not seeing well!) that it’s failing to acquire a priv level. In any case logs would be good, also channel logs would be great too!
RP/0/RSP0/CPU0:Mar 17 06:48:16.708 MSK: ipv4_acl_mgr[301]: %ACL-IPV4_ACL-6-IPACCESSLOGP : access-list acl-ACCESSCONTROL (112) permit tcp 10.12.1.13(13523) -> 10.4.24.7(22), 1 packet RP/0/RSP0/CPU0:Mar 17 06:48:17.176 MSK: SSHD[65934]: %SECURITY-SSHD-6-INFOSUCCESS : Successfully authenticated user 'user' from '10.12.1.13' on 'vty1'(cipher 'aes256-gcm@openssh.com', mac 'aes-gcm') RP/0/RSP0/CPU0:Mar 17 06:48:48.032 MSK: SSHD[65934]: %SECURITY-SSHD-6-INFO_USER_LOGOUT : User 'user' from '10.12.1.13' logged out on 'vty1'
Sorry I meant scrapli log/channel log:
https://github.com/carlmontanari/scrapli/blob/main/examples/logging/opinionated_logging.py
and enabling “channel_log” (as a driver argument)
But also comparing the logs on xr side between scrapli and “vanilla” asyncssh would be cool too
This connect "vanilla" asyncssh: RP/0/RSP0/CPU0:Mar 17 06:59:07.675 MSK: ipv4_acl_mgr[301]: %ACL-IPV4_ACL-6-IPACCESSLOGP : access-list acl-ACCESSCONTROL (112) permit tcp 10.12.1.13(57497) -> 10.4.24.7(22), 1 packet RP/0/RSP0/CPU0:Mar 17 06:59:08.124 MSK: SSHD[65934]: %SECURITY-SSHD-6-INFO_SUCCESSCOMMAND : Successfully authenticated user 'user' from '10.12.1.13' on 'vty1'(Cipher 'aes256-gcm@openssh.com', mac 'aes-gcm', Command 'show version') RP/0/RSP0/CPU0:Mar 17 06:59:11.623 MSK: SSHD[65934]: %SECURITY-SSHD-6-INFO_USER_LOGOUT : User 'user' from '10.12.1.13' logged out on 'vty1'
when authenticating, there is a command name
ID | TIMESTAMP | LEVEL | (UID:)HOST:PORT | MESSAGE 1 | 2023-03-17 11:07:58,136 | DEBUG | | AsyncScrapli factory initialized 2 | 2023-03-17 11:07:58,136 | INFO | | Driver '<class 'scrapli.driver.core.cisco_iosxr.async_driver.AsyncIOSXRDriver'>' selected from scrapli core drivers 3 | 2023-03-17 11:07:58,136 | DEBUG | 10.4.24.7:22 | load core transport requested 4 | 2023-03-17 11:07:58,243 | DEBUG | 10.4.24.7:22 | core transport 'asyncssh' loaded successfully 5 | 2023-03-17 11:07:58,243 | DEBUG | 10.4.24.7:22 | generating combined network comms prompt pattern 6 | 2023-03-17 11:07:58,243 | DEBUG | 10.4.24.7:22 | setting 'comms_prompt_pattern' value to '(^[\w.-@/:]{1,63}#\s?$)|(^[\w.-@/:]{1,63}(config[\w.-@/:]{0,32})#\s?$)|(^[\w.-@/:]{1,63}(config[\w.-@/:]{0,32})#\s?$)' 7 | 2023-03-17 11:07:58,244 | INFO | 10.4.24.7:22 | opening connection to '10.4.24.7' on port '22' 8 | 2023-03-17 11:07:58,244 | DEBUG | 10.4.24.7:22 | opening transport connection to '10.4.24.7' on port '22' 9 | 2023-03-17 11:07:59,482 | DEBUG | 10.4.24.7:22 | transport connection to '10.4.24.7' on port '22' opened successfully 10 | 2023-03-17 11:07:59,483 | DEBUG | 10.4.24.7:22 | write: '\n' 11 | 2023-03-17 11:07:59,654 | DEBUG | 10.4.24.7:22 | read : b'\n\nRP/0/RSP0/CPU0:HOST#\nRP/0/RSP0/CPU0:HOST#' 12 | 2023-03-17 11:07:59,654 | INFO | 10.4.24.7:22 | attempting to acquire 'privilege_exec' privilege level 13 | 2023-03-17 11:07:59,655 | DEBUG | 10.4.24.7:22 | determined current privilege level is one of '['privilege_exec']' 14 | 2023-03-17 11:07:59,655 | DEBUG | 10.4.24.7:22 | determined current privilege level is target privilege level, no action needed 15 | 2023-03-17 11:07:59,655 | INFO | 10.4.24.7:22 | sending channel input: terminal length 0; strip_prompt: True; eager: False 16 | 2023-03-17 11:07:59,655 | DEBUG | 10.4.24.7:22 | write: 'terminal length 0' 17 | 2023-03-17 11:07:59,743 | DEBUG | 10.4.24.7:22 | read : b'terminal length 0' 18 | 2023-03-17 11:07:59,743 | DEBUG | 10.4.24.7:22 | write: '\n' 19 | 2023-03-17 11:07:59,831 | DEBUG | 10.4.24.7:22 | read : b'\nCommand authorization failed\n% Incomplete command.\nRP/0/RSP0/CPU0:HOST#' 20 | 2023-03-17 11:07:59,919 | INFO | 10.4.24.7:22 | sending channel input: terminal width 512; strip_prompt: True; eager: False 21 | 2023-03-17 11:07:59,919 | DEBUG | 10.4.24.7:22 | write: 'terminal width 512' 22 | 2023-03-17 11:08:00,008 | DEBUG | 10.4.24.7:22 | read : b'terminal width 512' 23 | 2023-03-17 11:08:00,008 | DEBUG | 10.4.24.7:22 | write: '\n' 24 | 2023-03-17 11:08:00,097 | DEBUG | 10.4.24.7:22 | read : b'\nCommand authorization failed\n% Incomplete command.\nRP/0/RSP0/CPU0:HOST#' 25 | 2023-03-17 11:08:00,164 | INFO | 10.4.24.7:22 | connection to '10.4.24.7' on port '22' opened successfully 26 | 2023-03-17 11:08:00,164 | DEBUG | 10.4.24.7:22 | write: '\n' 27 | 2023-03-17 11:08:00,253 | DEBUG | 10.4.24.7:22 | read : b'\nRP/0/RSP0/CPU0:HOST#' 28 | 2023-03-17 11:08:00,253 | INFO | 10.4.24.7:22 | sending channel input: show version brief; strip_prompt: True; eager: False 29 | 2023-03-17 11:08:00,253 | DEBUG | 10.4.24.7:22 | write: 'show version brief' 30 | 2023-03-17 11:08:00,342 | DEBUG | 10.4.24.7:22 | read : b'show version brief' 31 | 2023-03-17 11:08:00,342 | DEBUG | 10.4.24.7:22 | write: '\n' 32 | 2023-03-17 11:08:00,430 | DEBUG | 10.4.24.7:22 | read : b'\nFri Mar 17 07:08:00.459 MSK\n\nCisco IOS XR Software, Version 6.6.3[Default]\nCopyright (c) 2021 by Cisco Systems, Inc.\n\nROM: System Bootstrap, Version 17.36(c) 1994-2019 by Cisco Systems, Inc.\n\nHOST uptime is 1 year, 36 weeks, 6 days, 11 hours, 17 minutes\nSystem image file is "disk0:asr9k-os-mbi-6.6.3.sp6-1.0.0/0x100305/mbiasr9k-rsp3.vm"\n\ncisco ASR9K Series (Pentium Celeron Stepping 3) processor with 16777216K bytes of memory.\nPentium Celeron Stepping 3 processor at 2404MHz, Revision 2.174\nASR 9006 4 Line Card Slot Chassis with V2 AC PEM\n\n4 Management Ethernet\n1 FastEthernet\n28 TenGigE\n28 DWDM controller(s)\n16 GigabitEthernet\n4 WANPHY controller(s)\n8 HundredGigE\n375k bytes of non-volatile configuration memory.\n5631M bytes of hard disk.\n100027376k bytes of disk0: (Sector size 512 bytes).\n --More-- ' 33 | 2023-03-17 11:08:30,278 | CRITICAL | 10.4.24.7:22 | operation timed out, closing connection 34 | 2023-03-17 11:08:30,279 | DEBUG | 10.4.24.7:22 | closing transport connection to '10.4.24.7' on port '22' 35 | 2023-03-17 11:08:30,279 | DEBUG | 10.4.24.7:22 | transport connection to '10.4.24.7' on port '22' closed successfully 36 | 2023-03-17 11:08:30,280 | INFO | 10.4.24.7:22 | connection to '10.4.24.7' on port '22' closed successfully 37 | 2023-03-17 11:08:30,280 | DEBUG | 10.4.24.7:22 | write: '\n'
Command authorization failed
isk0: (Sector size 512 bytes).\n --More--
your device is not letting us send terminal length 0 and therefore we cannot send show version since it prompts for pagination.
if asyncssh is setup to just send a command and not be in interactive mode then that explains why that is working. this is basically the difference between:
ssh somehost somecommand
where you just execute the command on the remote host vs:
ssh somehost
where you connect and are dropped onto the interactive session.
scrapli is always the latter. (very early versions supported the former but its not really relevant in most network cases). so the fix is you need to have a user who can run terminal length 0.
Carl, many thanks for the prompt reply! I increased the user's privileges.
nice, thanks for updating, glad its working!
Carl, there is another problem. Some IOS XR v 7.1.3 d't return "show admin environment". scrapli_channel.log:
RP/0/RSP0/CPU0:HOST#terminal length 0
Wed Mar 22 03:43:06.055 MSK
RP/0/RSP0/CPU0:HOST#terminal width 512
Wed Mar 22 03:43:06.405 MSK
RP/0/RSP0/CPU0:HOST#
RP/0/RSP0/CPU0:HOST#admin show environment
Wed Mar 22 03:43:06.859 MSK
Wed Mar 22 00:43:10.205 UTC+00:00
================================================================================
Location TEMPERATURE Value Crit Major Minor Minor Major Crit
Sensor (deg C) (Lo) (Lo) (Lo) (Hi) (Hi) (Hi)
--------------------------------------------------------------------------------
0/0
DIE_NP0 47 -10 -5 0 113 122 137
DIE_NP1 43 -10 -5 0 113 122 137
DIE_FabArbiter 41 -10 -5 0 108 122 137
DIE_FIA0 38 -10 -5 0 113 122 137
DIE_FIA1 36 -10 -5 0 113 122 137
DIE_FabSwitch 44 -10 -5 0 113 122 137
MB AIR_Inlet 33 -10 -5 0 60 65 75
MB Outlet 45 -10 -5 0 85 95 105
MB Hotspot0 42 -10 -5 0 90 93 95
MB Hotspot1 36 -10 -5 0 90 93 95
MB Hotspot2 34 -10 -5 0 90 93 95
DIE_Hooper 43 -10 -5 0 113 122 137
DIE_CPU 30 -10 -5 0 80 89 104
Inlet 33 -10 -5 0 60 65 75
Hotspot 44 -10 -5 0 90 93 95
0/1
DIE_NP0 45 -10 -5 0 113 122 137
DIE_NP1 42 -10 -5 0 113 122 137
[7m--More--[27m
scrapli.log:
ID | TIMESTAMP | LEVEL | (UID:)HOST:PORT | MESSAGE
1 | 2023-03-22 07:43:03,307 | DEBUG | | AsyncScrapli factory initialized
2 | 2023-03-22 07:43:03,308 | INFO | | Driver '<class 'scrapli.driver.core.cisco_iosxr.async_driver.AsyncIOSXRDriver'>' selected from scrapli core drivers
3 | 2023-03-22 07:43:03,308 | DEBUG | 10.1.3.18:22 | attempting to resolve 'ssh_config_file' file
4 | 2023-03-22 07:43:03,308 | DEBUG | 10.1.3.18:22 | using '.ssh/config' as resolved 'ssh_config_file' file'
5 | 2023-03-22 07:43:03,309 | DEBUG | 10.1.3.18:22 | load core transport requested
6 | 2023-03-22 07:43:03,418 | DEBUG | 10.1.3.18:22 | core transport 'asyncssh' loaded successfully
7 | 2023-03-22 07:43:03,418 | DEBUG | 10.1.3.18:22 | generating combined network comms prompt pattern
8 | 2023-03-22 07:43:03,418 | DEBUG | 10.1.3.18:22 | setting 'comms_prompt_pattern' value to '(^[\w.\-@/:]{1,63}#\s?$)|(^[\w.\-@/:]{1,63}\(config[\w.\-@/:]{0,32}\)#\s?$)|(^[\w.\-@/:]{1,63}\(config[\w.\-@/:]{0,32}\)#\s?$)'
9 | 2023-03-22 07:43:03,418 | INFO | 10.1.3.18:22 | opening connection to '10.1.3.18' on port '22'
10 | 2023-03-22 07:43:03,418 | DEBUG | 10.1.3.18:22 | opening transport connection to '10.1.3.18' on port '22'
11 | 2023-03-22 07:43:05,115 | DEBUG | 10.1.3.18:22 | transport connection to '10.1.3.18' on port '22' opened successfully
12 | 2023-03-22 07:43:05,116 | INFO | 10.1.3.18:22 | channel log enabled, logging channel output to 'scrapli_channel.log'
13 | 2023-03-22 07:43:05,116 | DEBUG | 10.1.3.18:22 | write: '\n'
14 | 2023-03-22 07:43:05,170 | DEBUG | 10.1.3.18:22 | read : b'\n\n\nRP/0/RSP0/CPU0:HOST#'
15 | 2023-03-22 07:43:05,890 | INFO | 10.1.3.18:22 | attempting to acquire 'privilege_exec' privilege level
16 | 2023-03-22 07:43:05,890 | DEBUG | 10.1.3.18:22 | determined current privilege level is one of '['privilege_exec']'
17 | 2023-03-22 07:43:05,890 | DEBUG | 10.1.3.18:22 | determined current privilege level is target privilege level, no action needed
18 | 2023-03-22 07:43:05,890 | INFO | 10.1.3.18:22 | sending channel input: terminal length 0; strip_prompt: True; eager: False
19 | 2023-03-22 07:43:05,890 | DEBUG | 10.1.3.18:22 | write: 'terminal length 0'
20 | 2023-03-22 07:43:05,944 | DEBUG | 10.1.3.18:22 | read : b'terminal length 0'
21 | 2023-03-22 07:43:05,944 | DEBUG | 10.1.3.18:22 | write: '\n'
22 | 2023-03-22 07:43:05,997 | DEBUG | 10.1.3.18:22 | read : b'\nWed Mar 22 03:43:06.055 MSK\nRP/0/RSP0/CPU0:HOST#'
23 | 2023-03-22 07:43:06,240 | INFO | 10.1.3.18:22 | sending channel input: terminal width 512; strip_prompt: True; eager: False
24 | 2023-03-22 07:43:06,240 | DEBUG | 10.1.3.18:22 | write: 'terminal width 512'
25 | 2023-03-22 07:43:06,294 | DEBUG | 10.1.3.18:22 | read : b'terminal width 512'
26 | 2023-03-22 07:43:06,294 | DEBUG | 10.1.3.18:22 | write: '\n'
27 | 2023-03-22 07:43:06,347 | DEBUG | 10.1.3.18:22 | read : b'\nWed Mar 22 03:43:06.405 MSK\nRP/0/RSP0/CPU0:HOST#'
28 | 2023-03-22 07:43:06,589 | INFO | 10.1.3.18:22 | connection to '10.1.3.18' on port '22' opened successfully
29 | 2023-03-22 07:43:06,589 | DEBUG | 10.1.3.18:22 | write: '\n'
30 | 2023-03-22 07:43:06,642 | DEBUG | 10.1.3.18:22 | read : b'\nRP/0/RSP0/CPU0:HOST#'
31 | 2023-03-22 07:43:06,695 | INFO | 10.1.3.18:22 | modifying driver timeout for current operation, temporary timeout_ops value: '240'
32 | 2023-03-22 07:43:06,696 | DEBUG | 10.1.3.18:22 | setting 'timeout_ops' value to '240'
33 | 2023-03-22 07:43:06,696 | INFO | 10.1.3.18:22 | sending channel input: admin show environment; strip_prompt: True; eager: False
34 | 2023-03-22 07:43:06,696 | DEBUG | 10.1.3.18:22 | write: 'admin show environment'
35 | 2023-03-22 07:43:06,749 | DEBUG | 10.1.3.18:22 | read : b'admin show environment'
36 | 2023-03-22 07:43:06,749 | DEBUG | 10.1.3.18:22 | write: '\n'
37 | 2023-03-22 07:43:06,802 | DEBUG | 10.1.3.18:22 | read : b'\nWed Mar 22 03:43:06.859 MSK\nWed Mar 22 00:43:10.205 UTC+00:00\n================================================================================\nLocation TEMPERATURE Value Crit Major Minor Minor Major Crit\n Sensor (deg C) (Lo) (Lo) (Lo) (Hi) (Hi) (Hi)\n--------------------------------------------------------------------------------\n0/0 \n DIE_NP0 47 -10 -5 0 113 122 137\n DIE_NP1 43 -10 -5 0 113 122 137\n DIE_FabArbiter 41 -10 -5 0 108 122 137\n DIE_FIA0 38 -10 -5 0 113 122 137\n DIE_FIA1 36 -10 -5 0 113 122 137\n DIE_FabSwitch 44 -10 -5 0 113 122 137\n MB AIR_Inlet 33 -10 -5 0 60 65 75\n MB Outlet 45 -10 -5 0 85 95 105\n MB Hotspot0 42 -10 -5 0 90 93 95\n MB Hotspot1 36 -10 -5 0 90 93 95\n MB Hotspot2 34 -10 -5 0 90 93 95\n DIE_Hooper 43 -10 -5 0 113 122 137\n DIE_CPU 30 -10 -5 0 80 89 104\n Inlet 33 -10 -5 0 60 65 75\n Hotspot 44 -10 -5 0 90 93 95\n0/1 \n DIE_NP0 45 -10 -5 0 113 122 137\n DIE_NP1 42 -10 -5 0 113 122 137\n\x1b[7m--More--\x1b[27m'
38 | 2023-03-22 07:47:06,777 | CRITICAL | 10.1.3.18:22 | operation timed out, closing connection
39 | 2023-03-22 07:47:06,777 | DEBUG | 10.1.3.18:22 | closing transport connection to '10.1.3.18' on port '22'
40 | 2023-03-22 07:47:06,778 | DEBUG | 10.1.3.18:22 | transport connection to '10.1.3.18' on port '22' closed successfully
41 | 2023-03-22 07:47:06,778 | INFO | 10.1.3.18:22 | connection to '10.1.3.18' on port '22' closed successfully
42 | 2023-03-22 07:47:06,778 | DEBUG | 10.1.3.18:22 | write: '\n'
there must be some problem with ESC-symbols?
If on other versions "terminal length 0" also applies to admin commands, then on 7.1.3 you need admin level.
Ok so all good here? Just had to send term Len 0 on diff priv level or something (sorry on mobile so didn’t look too closely at logs!)
yes, the problem was priv again (only for 7.1.3 ver)
3. On some devices asr9k, V 6.6.3, a command request via Scrapli crashes by timeout, although with the help of asyncssh with this code everything works in about at 5.3 seconds:
I've read your advice on using timeouts and tried different options timeout_ops, timeout_socket, timeout_transport. It's also not about ssh configuration, I think. Perhaps it's an authorization request on every commands?
USER@SERVER:~$ python3.8 scrapli_test.py
RP/0/RSP0/CPU0:HOST# Traceback (most recent call last): File "/usr/local/lib/python3.8/dist-packages/scrapli/decorators.py", line 191, in decorate return await asyncio.wait_for(wrapped_func(*args, **kwargs), timeout=timeout) File "/usr/lib/python3.8/asyncio/tasks.py", line 501, in wait_for raise exceptions.TimeoutError() asyncio.exceptions.TimeoutError
During handling of the above exception, another exception occurred:
Traceback (most recent call last): File "scrapli_test.py", line 61, in send_show result = await conn.send_command(command, ) File "/usr/local/lib/python3.8/dist-packages/scrapli/driver/network/async_driver.py", line 243, in send_command response = await super().send_command( File "/usr/local/lib/python3.8/dist-packages/scrapli/driver/generic/async_driver.py", line 170, in send_command response: Response = await self._send_command( File "/usr/local/lib/python3.8/dist-packages/scrapli/decorators.py", line 274, in decorate result = await wrapped_func(*args, **kwargs) File "/usr/local/lib/python3.8/dist-packages/scrapli/driver/generic/async_driver.py", line 137, in _send_command raw_response, processed_response = await self.channel.send_input( File "/usr/local/lib/python3.8/dist-packages/scrapli/decorators.py", line 193, in decorate _handle_timeout( File "/usr/local/lib/python3.8/dist-packages/scrapli/decorators.py", line 134, in _handle_timeout raise ScrapliTimeout(message) scrapli.exceptions.ScrapliTimeout: timed out sending input to device
During handling of the above exception, another exception occurred:
Traceback (most recent call last): File "scrapli_test.py", line 89, in
result = asyncio.run(send_command_to_devices(devices, "show version brief"))
File "/usr/lib/python3.8/asyncio/runners.py", line 44, in run
return loop.run_until_complete(main)
File "/usr/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
return future.result()
File "scrapli_test.py", line 78, in send_command_to_devices
result = await asyncio.gather(coroutines)
File "scrapli_test.py", line 61, in send_show
result = await conn.send_command(command, )
File "/usr/local/lib/python3.8/dist-packages/scrapli/driver/base/async_driver.py", line 66, in aexit
await self.close()
File "/usr/local/lib/python3.8/dist-packages/scrapli/driver/base/async_driver.py", line 121, in close
await self.on_close(self)
File "/usr/local/lib/python3.8/dist-packages/scrapli/driver/core/cisco_iosxr/async_driver.py", line 43, in iosxr_on_close
await conn.acquire_priv(desired_priv=conn.default_desired_privilege_level)
File "/usr/local/lib/python3.8/dist-packages/scrapli/driver/network/async_driver.py", line 156, in acquire_priv
current_prompt = await self.channel.get_prompt()
File "/usr/local/lib/python3.8/dist-packages/scrapli/decorators.py", line 191, in decorate
return await asyncio.wait_for(wrapped_func(args, **kwargs), timeout=timeout)
File "/usr/lib/python3.8/asyncio/tasks.py", line 494, in wait_for
return fut.result()
File "/usr/local/lib/python3.8/dist-packages/scrapli/channel/async_channel.py", line 439, in get_prompt
self.send_return()
File "/usr/local/lib/python3.8/dist-packages/scrapli/channel/base_channel.py", line 352, in send_return
self.write(channel_input=self._base_channel_args.comms_return_char)
File "/usr/local/lib/python3.8/dist-packages/scrapli/channel/base_channel.py", line 336, in write
self.transport.write(channel_input=channel_input.encode())
File "/usr/local/lib/python3.8/dist-packages/scrapli/transport/plugins/asyncssh/transport.py", line 267, in write
raise ScrapliConnectionNotOpened
scrapli.exceptions.ScrapliConnectionNotOpened: connection not opened, but attempting to call a method that requires an open connection, do you need to call 'open()'?