Asynchronous Terminal Server slow/delayed when using SSH

Nico Bellack · ‎10-25-2018

hello,

we've a cisco ISR 4221 with a NIM-24 Interface Card.

the Terminal Server works good, when we use Telnet. But when using SSH the console Connection becomes very slow / delayed. We need to wait 1-2 second after pressing a key before it is displayed on Screen. A normal SSH connection to the ISR itself performs well.

here is the configuration:

ip ssh port 2002 rotary 2 25

line 0/1/0
session-timeout 120
exec-timeout 120 0
logging synchronous
login local
rotary 2
no exec
transport input ssh
stopbits 1

The IOS Version is 16.07.01.
Any ideas?

greetz

Nico

sofiane7704 · ‎10-25-2018

Hello Nico,

Maybe some memory/ CPU issue ? can you check memory and CPU usage ?

Nico Bellack · ‎10-25-2018

the CPU is in idle mode during the terminal session.

sh proc cpu history

      233333333333333322222333332222222222222222222222222222222222
100
   90
   80
   70
   60
   50
   40
   30
   20
   10
     0....5....1....1....2....2....3....3....4....4....5....5....6
               0    5    0    5    0    5    0    5    0    5    0
               CPU% per second (last 60 seconds)

sh proc cpu monitor

CPU utilization for five seconds: 3%/2%; one minute: 3%; five minutes: 3%
PID Runtime(ms)     Invoked      uSecs   5Sec   1Min   5Min TTY Process
119      129007     1182682        109 0.15% 0.09% 0.08%   0 IOSXE-RP Punt Se
412         235         439        535 0.15% 0.09% 0.05% 866 SSH Process
83      196965      318473        618 0.15% 0.12% 0.11%   0 IOSD ipc task
37        2575      161470         15 0.07% 0.00% 0.00%   0 IPC Periodic Tim
91        9462      165369         57 0.07% 0.00% 0.00%   0 Environmental Mo
185      104066     2583638         40 0.07% 0.04% 0.05%   0 VRRS Main thread
   6          22          12       1833 0.00% 0.00% 0.00%   0 RF Slave Main Th
   4           0           1          0 0.00% 0.00% 0.00%   0 Retransmission o
   3           0           2          0 0.00% 0.00% 0.00%   0 DiagCard4/-1
   2       14292       33080        432 0.00% 0.00% 0.00%   0 Load Meter
   5           0           1          0 0.00% 0.00% 0.00%   0 IPC ISSU Dispatc
   7           0           1          0 0.00% 0.00% 0.00%   0 EDDRI_MAIN
   8           0           1          0 0.00% 0.00% 0.00%   0 RO Notify Timers
14           4          39        102 0.00% 0.00% 0.00%   0 ARP Input
   9       97691       22230       4394 0.00% 0.05% 0.05%   0 Check heaps
16           0           2          0 0.00% 0.00% 0.00%   0 ATM Idle Timer
10         306        2777        110 0.00% 0.00% 0.00%   0 Pool Manager
18           0           1          0 0.00% 0.00% 0.00%   0 CEF MIB API
11           1           1       1000 0.00% 0.00% 0.00%   0 DiscardQ Backgro
20         103          15       6866 0.00% 0.00% 0.00%   0 Entity MIB API

the Memory utilization is also good

sh proc memory sorted
Processor Pool Total: 1836366584 Used: 283242056 Free: 1553124528
lsmpi_io Pool Total: 6295128 Used: 6294296 Free: 832

Edit:

today, I tested some other IOS Versions (16.06.04, 16.07.02 and 16.09.01). None of the versions fixes the problem

sofiane7704 · ‎10-26-2018

Can you enable ssh debug and post the logging results ? Thank you

Nico Bellack · ‎10-26-2018

XXXXXXXXXX#debug ip ssh
Incoming SSH debugging is on

Oct 26 2018 14:40:35.692 CEST: SSH2: starting SSH control process
Oct 26 2018 14:40:35.692 CEST: SSH2: sent protocol version id SSH-2.0-Cisco-1.25
Oct 26 2018 14:40:35.708 CEST: SSH2: protocol version id is - SSH-2.0-PuTTY_Release_0.70
Oct 26 2018 14:40:35.709 CEST: SSH2 2: kexinit sent: kex algo = diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1
Oct 26 2018 14:40:35.709 CEST: SSH2 2: Server certificate trustpoint not found. Skipping hostkey algo = x509v3-ssh-rsa
Oct 26 2018 14:40:35.709 CEST: SSH2 2: kexinit sent: hostkey algo = ssh-rsa
Oct 26 2018 14:40:35.709 CEST: SSH2 2: kexinit sent: encryption algo = aes128-ctr,aes192-ctr,aes256-ctr
Oct 26 2018 14:40:35.709 CEST: SSH2 2: kexinit sent: mac algo = hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-sha1-96
Oct 26 2018 14:40:35.709 CEST: SSH2 2: send:packet of length 312 (length also includes padlen of 4)
Oct 26 2018 14:40:35.710 CEST: SSH2 2: SSH2_MSG_KEXINIT sent
Oct 26 2018 14:40:35.710 CEST: SSH2 2: ssh_receive: 536 bytes received
Oct 26 2018 14:40:35.710 CEST: SSH2 2: input: total packet length of 1104 bytes
Oct 26 2018 14:40:35.710 CEST: SSH2 2: partial packet length(block size)8 bytes,needed 1096 bytes, maclen 0
Oct 26 2018 14:40:35.713 CEST: SSH2 2: ssh_receive: 536 bytes received
Oct 26 2018 14:40:35.714 CEST: SSH2 2: partial packet length(block size)8 bytes,needed 1096 bytes, maclen 0
Oct 26 2018 14:40:35.714 CEST: SSH2 2: ssh_receive: 56 bytes received
Oct 26 2018 14:40:35.714 CEST: SSH2 2: partial packet length(block size)8 bytes,needed 1096 bytes, maclen 0
Oct 26 2018 14:40:35.714 CEST: SSH2 2: input: padlength 4 bytes
Oct 26 2018 14:40:35.714 CEST: SSH2 2: SSH2_MSG_KEXINIT received
Oct 26 2018 14:40:35.715 CEST: SSH2 2: kex: client->server enc:aes256-ctr mac:hmac-sha2-256
Oct 26 2018 14:40:35.715 CEST: SSH2 2: kex: server->client enc:aes256-ctr mac:hmac-sha2-256
Oct 26 2018 14:40:35.715 CEST: SSH2 2: Using kex_algo = diffie-hellman-group-exchange-sha1
Oct 26 2018 14:40:35.715 CEST: SSH2 2: input: total packet length of 24 bytes
Oct 26 2018 14:40:35.715 CEST: SSH2 2: partial packet length(block size)8 bytes,needed 16 bytes, maclen 0
Oct 26 2018 14:40:35.715 CEST: SSH2 2: input: padlength 6 bytes
Oct 26 2018 14:40:35.715 CEST: SSH2 2: SSH2_MSG_KEX_DH_GEX_REQUEST received
Oct 26 2018 14:40:35.716 CEST: SSH2 2: Range sent by client is - 1024 < 2048 < 8192
Oct 26 2018 14:40:35.716 CEST: SSH2 2: Modulus size established : 2048 bits
Oct 26 2018 14:40:35.716 CEST:
XXXXXXXXXX#SSH2 2: send:packet of length 280 (length also includes padlen of 8)
Oct 26 2018 14:40:35.758 CEST: SSH2 2: expecting SSH2_MSG_KEX_DH_GEX_INIT
Oct 26 2018 14:40:35.759 CEST: SSH2 2: ssh_receive: 272 bytes received
Oct 26 2018 14:40:35.759 CEST: SSH2 2: input: total packet length of 272 bytes
Oct 26 2018 14:40:35.759 CEST: SSH2 2: partial packet length(block size)8 bytes,needed 264 bytes, maclen 0
Oct 26 2018 14:40:35.759 CEST: SSH2 2: input: padlength 5 bytes
Oct 26 2018 14:40:35.759 CEST: SSH2 2: SSH2_MSG_KEXDH_INIT received
Oct 26 2018 14:40:35.857 CEST: SSH2 2: signature length 271
Oct 26 2018 14:40:35.857 CEST: SSH2 2: send:packet of length 832 (length also includes padlen of 8)
Oct 26 2018 14:40:35.858 CEST: SSH2: kex_derive_keys complete
Oct 26 2018 14:40:35.858 CEST: SSH2 2: send:packet of length 16 (length also includes padlen of 10)
Oct 26 2018 14:40:35.858 CEST: SSH2 2: newkeys: mode 1
Oct 26 2018 14:40:35.858 CEST: SSH2 2: SSH2_MSG_NEWKEYS sent
Oct 26 2018 14:40:35.858 CEST: SSH2 2: waiting for SSH2_MSG_NEWKEYS
Oct 26 2018 14:40:35.882 CEST: SSH2 2: ssh_receive: 16 bytes received
Oct 26 2018 14:40:35.882 CEST: SSH2 2: input: total packet length of 16 bytes
Oct 26 2018 14:40:35.882 CEST: SSH2 2: partial packet length(block size)8 bytes,needed 8 bytes, maclen 0
Oct 26 2018 14:40:35.883 CEST: SSH2 2: input: padlength 10 bytes
Oct 26 2018 14:40:35.883 CEST: SSH2 2: newkeys: mode 0
Oct 26 2018 14:40:35.883 CEST: SSH2 2: SSH2_MSG_NEWKEYS received
Oct 26 2018 14:40:35.883 CEST: SSH2 2: ssh_receive: 64 bytes received
Oct 26 2018 14:40:35.883 CEST: SSH2 2: input: total packet length of 32 bytes
Oct 26 2018 14:40:35.883 CEST: SSH2 2: partial packet length(block size)16 bytes,needed 16 bytes, maclen 32
Oct 26 2018 14:40:35.883 CEST: SSH2 2: MAC compared for #4 :ok
Oct 26 2018 14:40:35.883 CEST: SSH2 2: input: padlength 10 bytes
Oct 26 2018 14:40:35.883 CEST: SSH2 2: send:packet of length 32 (length also includes padlen of 10)
Oct 26 2018 14:40:35.883 CEST: SSH2 2: computed MAC for sequence no.#4 type 6
Oct 26 2018 14:40:35.884 CEST: SSH2 2: Authentications that can continue = publickey,keyboard-interactive,password
XXXXXXXXXX#
Oct 26 2018 14:40:40.205 CEST: SSH2 2: ssh_receive: 80 bytes received
Oct 26 2018 14:40:40.205 CEST: SSH2 2: input: total packet length of 48 bytes
Oct 26 2018 14:40:40.205 CEST: SSH2 2: partial packet length(block size)16 bytes,needed 32 bytes, maclen 32
Oct 26 2018 14:40:40.206 CEST: SSH2 2: MAC compared for #5 :ok
Oct 26 2018 14:40:40.206 CEST: SSH2 2: input: padlength 7 bytes
Oct 26 2018 14:40:40.206 CEST: SSH2 2: Using method = none
Oct 26 2018 14:40:40.206 CEST: SSH2 2: Authentications that can continue = publickey,keyboard-interactive,password
Oct 26 2018 14:40:40.206 CEST: SSH2 2: send:packet of length 64 (length also includes padlen of 14)
Oct 26 2018 14:40:40.206 CEST: SSH2 2: computed MAC for sequence no.#5 type 51
Oct 26 2018 14:40:40.210 CEST: SSH2 2: ssh_receive: 112 bytes received
Oct 26 2018 14:40:40.211 CEST: SSH2 2: input: total packet length of 80 bytes
Oct 26 2018 14:40:40.211 CEST: SSH2 2: partial packet length(block size)16 bytes,needed 64 bytes, maclen 32
Oct 26 2018 14:40:40.211 CEST: SSH2 2: MAC compared for #6 :ok
Oct 26 2018 14:40:40.211 CEST: SSH2 2: input: padlength 15 bytes
Oct 26 2018 14:40:40.211 CEST: SSH2 2: Using method = keyboard-interactive
Oct 26 2018 14:40:40.211 CEST: SSH2 2: send:packet of length 48 (length also includes padlen of 11)
XXXXXXXXXX#
Oct 26 2018 14:40:40.211 CEST: SSH2 2: computed MAC for sequence no.#6 type 60
XXXXXXXXXX#
Oct 26 2018 14:40:45.581 CEST: SSH2 2: ssh_receive: 304 bytes received
Oct 26 2018 14:40:45.581 CEST: SSH2 2: input: total packet length of 32 bytes
Oct 26 2018 14:40:45.581 CEST: SSH2 2: partial packet length(block size)16 bytes,needed 16 bytes, maclen 32
Oct 26 2018 14:40:45.581 CEST: SSH2 2: MAC compared for #7 :ok
Oct 26 2018 14:40:45.581 CEST: SSH2 2: input: padlength 13 bytes
Oct 26 2018 14:40:45.584 CEST: SSH2 2: send:packet of length 16 (length also includes padlen of 10)
Oct 26 2018 14:40:45.584 CEST: SSH2 2: computed MAC for sequence no.#7 type 52
Oct 26 2018 14:40:45.585 CEST: SSH2 2: authentication successful for admin
Oct 26 2018 14:40:45.585 CEST: SSH2 2: input: total packet length of 208 bytes
Oct 26 2018 14:40:45.585 CEST: SSH2 2: partial packet length(block size)16 bytes,needed 192 bytes, maclen 32
Oct 26 2018 14:40:45.585 CEST: SSH2 2: MAC compared for #8 :ok
Oct 26 2018 14:40:45.585 CEST: SSH2 2: input: padlength 6 bytes
Oct 26 2018 14:40:45.589 CEST: SSH2 2: ssh_receive: 80 bytes received
Oct 26 2018 14:40:45.589 CEST: SSH2 2: input: total packet length of 48 bytes
Oct 26 2018 14:40:45.589 CEST: SSH2 2: partial packet length(block size)16 bytes,needed 32 bytes, maclen 32
Oct 26 2018 14:40:45.589 CEST: SSH2 2: MAC compared for #9 :ok
Oct 26 2018 14:40:45.589 CEST: SSH2 2: input: padlength 19 bytes
Oct 26 2018 14:40:45.589 CEST: SSH2 2: channel open request
Oct 26 2018 14:40:45.589 CEST: SSH2 2: send:packet of length 32 (length also includes padlen of 10)
Oct 26 2018 14:40:45.589 CEST: SSH2 2: computed MAC for sequence no.#8 type 91
Oct 26 2018 14:40:46.098 CEST: SSH2 2: ssh_receive: 112 bytes received
Oct 26 2018 14:40:46.098 CEST: SSH2 2: input: total packet length of 80 bytes
Oct 26 2018 14:40:46.098 CEST: SSH2 2: partial packet length(block size)16 bytes,needed 64 bytes, maclen 32
Oct 26 2018 14:40:46.098 CEST: SSH2 2: MAC compared for #10 :ok
Oct 26 2018 14:40:46.098 CEST: SSH2 2: input: padlength 8 bytes
Oct 26 2018 14:40:46.098 CEST: SSH2 2: send:packet of length 16 (length also includes padlen of 6)
Oct 26 2018 14:40:46.098 CEST: SSH2 2: computed MAC for sequence no.#9 type 99
Oct 26 2018 14:40:46.099 CEST: SSH2 2: pty-req request
Oct 26 2018 14:40:46.099 CEST: SSH2 2: setting TTY - requested: height 24, width 80; set: height 24, width 80
Oct 26 2018 14:40:46.099 CEST: SSH2 2: ssh_receive: 64 bytes received
Oct 26 2018 14:40:46.099 CEST: SSH2 2: input: total packet length of 32 bytes
Oct 26 2018 14:40:46.099 CEST: SSH2 2: partial packet length(block size)16 bytes,needed 16 bytes, maclen 32
XXXXXXXXXX#
Oct 26 2018 14:40:46.099 CEST: SSH2 2: MAC compared for #11 :ok
Oct 26 2018 14:40:46.099 CEST: SSH2 2: input: padlength 12 bytes
Oct 26 2018 14:40:46.099 CEST: SSH2 2: send:packet of length 16 (length also includes padlen of 6)
Oct 26 2018 14:40:46.099 CEST: SSH2 2: computed MAC for sequence no.#10 type 99
Oct 26 2018 14:40:46.100 CEST: SSH2 2: shell request
Oct 26 2018 14:40:46.100 CEST: SSH2 2: shell message received
Oct 26 2018 14:40:46.100 CEST: SSH2 2: starting tty-daemon for tty
Oct 26 2018 14:40:46.101 CEST: SSH2 2: send:packet of length 48 (length also includes padlen of 19)
Oct 26 2018 14:40:46.101 CEST: SSH2 2: computed MAC for sequence no.#11 type 94
XXXXXXXXXX#
Oct 26 2018 14:40:49.245 CEST: SSH2 2: ssh_receive: 64 bytes received
Oct 26 2018 14:40:49.246 CEST: SSH2 2: input: total packet length of 32 bytes
Oct 26 2018 14:40:49.246 CEST: SSH2 2: partial packet length(block size)16 bytes,needed 16 bytes, maclen 32
Oct 26 2018 14:40:49.246 CEST: SSH2 2: MAC compared for #12 :ok
Oct 26 2018 14:40:49.246 CEST: SSH2 2: input: padlength 17 bytes
Oct 26 2018 14:40:49.472 CEST: SSH2 2: send:packet of length 48 (length also includes padlen of 19)
Oct 26 2018 14:40:49.472 CEST: SSH2 2: computed MAC for sequence no.#12 type 94
XXXXXXXXXX#
Oct 26 2018 14:40:54.269 CEST: SSH2 2: ssh_receive: 64 bytes received
Oct 26 2018 14:40:54.269 CEST: SSH2 2: input: total packet length of 32 bytes
Oct 26 2018 14:40:54.270 CEST: SSH2 2: partial packet length(block size)16 bytes,needed 16 bytes, maclen 32
Oct 26 2018 14:40:54.270 CEST: SSH2 2: MAC compared for #13 :ok
Oct 26 2018 14:40:54.270 CEST: SSH2 2: input: padlength 17 bytes
Oct 26 2018 14:40:54.290 CEST: SSH2 2: send:packet of length 32 (length also includes padlen of 17)
Oct 26 2018 14:40:54.291 CEST: SSH2 2: computed MAC for sequence no.#13 type 94
Oct 26 2018 14:40:54.605 CEST: SSH2 2: ssh_receive: 64 bytes received
Oct 26 2018 14:40:54.605 CEST: SSH2 2: input: total packet length of 32 bytes
Oct 26 2018 14:40:54.605 CEST: SSH2 2: partial packet length(block size)16 bytes,needed 16 bytes, maclen 32
Oct 26 2018 14:40:54.606 CEST: SSH2 2: MAC compared for #14 :ok
Oct 26 2018 14:40:54.606 CEST: SSH2 2: input: padlength 17 bytes
Oct 26 2018 14:40:54.627 CEST: SSH2 2: send:packet of length 32 (length also includes padlen of 17)
Oct 26 2018 14:40:54.627 CEST: SSH2 2: computed MAC for sequence no.#14 type 94
Oct 26 2018 14:40:54.957 CEST: SSH2 2: ssh_receive: 64 bytes received
Oct 26 2018 14:40:54.957 CEST: SSH2 2: input: total packet length of 32 bytes
XXXXXXXXXX#
Oct 26 2018 14:40:54.957 CEST: SSH2 2: partial packet length(block size)16 bytes,needed 16 bytes, maclen 32
Oct 26 2018 14:40:54.957 CEST: SSH2 2: MAC compared for #15 :ok
Oct 26 2018 14:40:54.958 CEST: SSH2 2: input: padlength 17 bytes
Oct 26 2018 14:40:54.978 CEST: SSH2 2: send:packet of length 32 (length also includes padlen of 17)
Oct 26 2018 14:40:54.978 CEST: SSH2 2: computed MAC for sequence no.#15 type 94
Oct 26 2018 14:40:55.741 CEST: SSH2 2: ssh_receive: 64 bytes received
Oct 26 2018 14:40:55.741 CEST: SSH2 2: input: total packet length of 32 bytes
XXXXXXXXXX#
Oct 26 2018 14:40:55.741 CEST: SSH2 2: partial packet length(block size)16 bytes,needed 16 bytes, maclen 32
Oct 26 2018 14:40:55.742 CEST: SSH2 2: MAC compared for #16 :ok
Oct 26 2018 14:40:55.742 CEST: SSH2 2: input: padlength 17 bytes
Oct 26 2018 14:40:55.777 CEST: SSH2 2: send:packet of length 48 (length also includes padlen of 19)
Oct 26 2018 14:40:55.777 CEST: SSH2 2: computed MAC for sequence no.#16 type 94
XXXXXXXXXX#
Oct 26 2018 14:41:01.245 CEST: SSH2 2: ssh_receive: 64 bytes received
Oct 26 2018 14:41:01.245 CEST: SSH2 2: input: total packet length of 32 bytes
Oct 26 2018 14:41:01.246 CEST: SSH2 2: partial packet length(block size)16 bytes,needed 16 bytes, maclen 32
Oct 26 2018 14:41:01.246 CEST: SSH2 2: MAC compared for #17 :ok
Oct 26 2018 14:41:01.246 CEST: SSH2 2: input: padlength 17 bytes
Oct 26 2018 14:41:01.281 CEST: SSH2 2: send:packet of length 48 (length also includes padlen of 19)
Oct 26 2018 14:41:01.281 CEST: SSH2 2: computed MAC for sequence no.#17 type 94
DVZHROVC1020#
Oct 26 2018 14:41:03.133 CEST: SSH2 2: ssh_receive: 64 bytes received
Oct 26 2018 14:41:03.133 CEST: SSH2 2: input: total packet length of 32 bytes
Oct 26 2018 14:41:03.134 CEST: SSH2 2: partial packet length(block size)16 bytes,needed 16 bytes, maclen 32
Oct 26 2018 14:41:03.134 CEST: SSH2 2: MAC compared for #18 :ok
Oct 26 2018 14:41:03.134 CEST: SSH2 2: input: padlength 17 bytes
Oct 26 2018 14:41:03.155 CEST: SSH2 2: send:packet of length 32 (length also includes padlen of 17)
Oct 26 2018 14:41:03.155 CEST: SSH2 2: computed MAC for sequence no.#18 type 94
DVZHROVC1020#
Oct 26 2018 14:41:04.973 CEST: SSH2 2: ssh_receive: 64 bytes received
Oct 26 2018 14:41:04.973 CEST: SSH2 2: input: total packet length of 32 bytes
Oct 26 2018 14:41:04.973 CEST: SSH2 2: partial packet length(block size)16 bytes,needed 16 bytes, maclen 32
Oct 26 2018 14:41:04.973 CEST: SSH2 2: MAC compared for #19 :ok
Oct 26 2018 14:41:04.973 CEST: SSH2 2: input: padlength 17 bytes
Oct 26 2018 14:41:04.994 CEST: SSH2 2: send:packet of length 32 (length also includes padlen of 17)
Oct 26 2018 14:41:04.994 CEST: SSH2 2: computed MAC for sequence no.#19 type 94

r.heitmann · ‎12-13-2021

same issue here...

...did you find a fix for the issue in the meantime?

Nico Bellack · ‎06-01-2023

I believe that in my case it was a client issue. We have replaced our clients in the meantime and since then no more issues.