[c-nsp] ASR920 and EEM:Mandatory.dualrate_eem.tcl

[Gert Doering]

Hi,

does anyone know what "EEM:Mandatory.dualrate_eem.tcl" is?

We have an ASR920 that grew an unexpected config change upon insertion
of a DAC cable into port ten0/0/12, and "unexpected config change" always
triggers an investigation here (who, why, what).  One part of it was
somewhat related

 interface TenGigabitEthernet0/0/12
  description ...
  no ip address
+ negotiation auto
  service instance 200 ethernet

... but the other part was more interesting

 line vty 0 4
  access-class 9 in
- exec-timeout 240 0
  ipv6 access-class VTY-v6 in
- transport input telnet ssh
+ transport preferred none
+ transport input none
+ transport output none
  escape-character 3

"uh, what?".  So we investigated and found a few log messages about that
script...

Aug 20 13:45:30 CEST: %TRANSCEIVER-6-INSERTED:  F0: iomd:  transceiver module inserted in TenGigabitEthernet0/0/12
<SNIP>
Aug 20 13:45:45 CEST: %IOSXE_SPA-6-DUAL_RATE_CHANGE: TenGigabitEthernet0/0/12: MODE_1G
Aug 20 13:45:47 CEST: %SYS-5-CONFIG_I: Configured from console by  on vty1 (EEM:Mandatory.dualrate_eem.tcl)
Aug 20 13:46:14 CEST: %SYS-5-CONFIG_I: Configured from console by  on vty1 (EEM:Mandatory.dualrate_eem.tcl)
Aug 20 13:46:15 CEST: %SYS-5-CONFIG_I: Configured from console by  on vty0 (EEM:Mandatory.dualrate_eem.tcl)
Aug 20 13:46:17 CEST: %TRANSCEIVER-6-REMOVED:  F0: iomd:  Transceiver module removed from TenGigabitEthernet0/0/12
Aug 20 13:46:20 CEST: %IOSXE-5-PLATFORM:  F0: Aug 20 13:46:20 %SYSTEM-3-SYSTEM_SHELL_LOG: Shell started: vty 1
Aug 20 13:46:20 CEST: %IOSXE-5-PLATFORM:  F0: Aug 20 13:46:20 %SYSTEM-3-SYSTEM_SHELL_LOG: 2019/08/20 13:46:19 : Shell access was granted to user <anon>; Trace file: , /harddisk/tracelogs/system_shell_R0-0.2264_0.20190820134619.bin
ug 20 13:46:26 CEST: %HA_EM-6-LOG: Mandatory.dualrate_eem.tcl: DUAL_RATE_CHANGE Re-configuration of interface TenGigabitEthernet0/0/12 to start re-configuring
Aug 20 13:46:28 CEST: %SYS-5-CONFIG_I: Configured from console by  on vty1 (EEM:Mandatory.dualrate_eem.tcl)
Aug 20 13:46:39 CEST: %SYS-5-CONFIG_C: Running-config file is Modified


... and 441 (!!) lines in the tacacs command accounting log, which
mostly looked like "it replayed the whole config, line by line"... 
until it hit the vty section, which then got messed up...

Aug 20 13:47:08 router     unknown tty3    EEM:Mandatory.dualrate_eem.tcl  stop    task_id=2166    timezone=CEST   service=shell  start_time=1566301628    priv-lvl=15     cmd=configure terminal <cr>
Aug 20 13:47:09 router     unknown tty3    EEM:Mandatory.dualrate_eem.tcl  stop    task_id=2167    timezone=CEST   service=shell  start_time=1566301629    priv-lvl=15     cmd=line vty 0 4 <cr>
Aug 20 13:47:09 router     unknown tty3    EEM:Mandatory.dualrate_eem.tcl  stop    task_id=2168    timezone=CEST   service=shell  start_time=1566301629    priv-lvl=15     cmd=no login authentication <cr>
Aug 20 13:47:09 router     unknown tty3    EEM:Mandatory.dualrate_eem.tcl  stop    task_id=2169    timezone=CEST   service=shell  start_time=1566301629    priv-lvl=15     cmd=no authorization exec <cr>
Aug 20 13:47:09 router     unknown tty3    EEM:Mandatory.dualrate_eem.tcl  stop    task_id=2170    timezone=CEST   service=shell  start_time=1566301629    priv-lvl=15     cmd=no authorization commands 15 <cr>
Aug 20 13:47:10 router     unknown tty3    EEM:Mandatory.dualrate_eem.tcl  stop    task_id=2171    timezone=CEST   service=shell  start_time=1566301630    priv-lvl=15     cmd=no transport preferred <cr>
...
Aug 20 13:47:10 router     unknown tty3    EEM:Mandatory.dualrate_eem.tcl  stop    task_id=2174    timezone=CEST   service=shell  start_time=1566301630    priv-lvl=15     cmd=no exec-timeout <cr>
Aug 20 13:47:11 router     unknown tty3    EEM:Mandatory.dualrate_eem.tcl  stop    task_id=2175    timezone=CEST   service=shell  start_time=1566301631    priv-lvl=1      cmd=no length <cr>
Aug 20 13:47:11 router     unknown tty2    EEM:Mandatory.dualrate_eem.tcl  stop    task_id=2177    timezone=CEST   service=shell  start_time=1566301631    priv-lvl=15     cmd=write memory <cr>


shall I state that I find this a somewhat surprising behaviour?

Haven't opened a TAC case yet (no time) but hopefully someone here 
has see this before and found some more useful results.

gert
-- 
"If was one thing all people took for granted, was conviction that if you 
 feed honest figures into a computer, honest figures come out. Never doubted 
 it myself till I met a computer with a sense of humor."
                             Robert A. Heinlein, The Moon is a Harsh Mistress

Gert Doering - Munich, Germany                             gert at greenie.muc.de
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 630 bytes
Desc: not available
URL: <https://puck.nether.net/pipermail/cisco-nsp/attachments/20190826/9c63691c/attachment.sig>