EEM script: "cli_open" command error

[SKC-Korotkov-999]

Hi guys!

The following error occurred while performing EEM scripts.

Two scripts will start simultaneously on the "timer CRON"  (because set "script thread" = 3)

    Both scripts use the cli_open command. An error occurs when you run the command - cli_open.

If you set  "script thread" = 1  (default value) -  then everything is OK.

There is a suspicion of the fact that cisco can't perform these two command simultaneously.

IOS 15.1(4)M1

[Joe Clarke]

What is the exact error?  Two policies that use cli_open can run concurrently provided you have enough spare VTY lines.  Each cli_open requires a VTY line, and EEM requires that there is at least one free VTY line in addition to the line it uses.  So, for two policies to run concurrently, you need three spare VTY lines.

[SKC-Korotkov-999]

VTY lines not fully occupied. The reason probably is somewhat different.

Here debug cli_library:

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : CTL : cli_open called.

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl : DEBUG(cli_lib) : CTL : cli_open called.

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT : i3925E-1>

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : IN  : i3925E-1>en

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl : DEBUG(cli_lib) : OUT : i3925E-1>

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl : DEBUG(cli_lib) : IN  : i3925E-1>en

i3925E-1#

i3925E-1#

i3925E-1#

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT : i3925E-1#

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : IN  : i3925E-1#show policy-map interface gi0/1.91

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl : DEBUG(cli_lib) : OUT : i3925E-1#

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl : DEBUG(cli_lib) : IN  : i3925E-1#show policy-map interface g0/0.200 | inc bps

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :  GigabitEthernet0/1.91

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :   Service-policy input: Download-map

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :     Class-map: Downloads (match-any)

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :       637348961 packets, 851871399747 bytes

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :       30 second offered rate 6956000 bps, drop rate 27000 bps

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :       Match: protocol http host "*(icefile|rapidshare)*"

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :         12110280 packets, 16193832430 bytes

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :         30 second rate 0 bps

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :       Match: protocol http mime "*(pdf|stream)*"

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :         274295913 packets, 380496603060 bytes

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :         30 second rate 815000 bps

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :       Match: protocol http url "*.(zip|rar|avi|mp3|pdf|flv)"

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :         143523540 packets, 160457797285 bytes

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :         30 second rate 3506000 bps

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :       Match: protocol http mime "*x-flv"

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :         205612375 packets, 292254972939 bytes

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :         30 second rate 2632000 bps

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :       Match: protocol http mime "*x-ms-wmv"

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : CTL : 20+ lines read from cli_read, debug output truncated.

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : CTL : cli_close called.

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : CTL : cli_open called.

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl : DEBUG(cli_lib) : OUT :       30 second offered rate 1847000 bps, drop rate 17000 bps

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl : DEBUG(cli_lib) : OUT :           cir 10000000 bps, bc 100000 bytes

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl : DEBUG(cli_lib) : OUT :         conformed 1832000 bps, exceed 17000 bps

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl : DEBUG(cli_lib) : OUT : i3925E-1#

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl : DEBUG(cli_lib) : CTL : cli_close called.

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl : DEBUG(cli_lib) : CTL : cli_open called.

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl: can't read "errorInfo": no such variable

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl:     while executing

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl: "error $result $errorInfo"

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl:     (procedure "CLI_cmd_output" line 5)

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl:     invoked from within

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl: "CLI_cmd_output "show run interface $if | inc descr""

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl:     ("foreach" body line 5)

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl:     invoked from within

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl: "foreach {if} $customer_if {

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl:      set p_output [CLI_cmd_output "show policy-map interface $if | inc bps"];

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl: #puts "P_OUTPUT: $p_output"

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl:      set if_vals..."

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl:     invoked from within

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl: "$slave eval $Contents"

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl:     (procedure "eval_script" line 7)

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl:     invoked from within

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl: "eval_script slave $scriptname"

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl:     invoked from within

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl: "if {$security_level == 1} {       #untrusted script

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl:      interp create -safe slave

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl:      interp share {} stdin slave

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl:      interp share {} stdout slave

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl: ..."

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl:     (file "tmpsys:/lib/tcl/base.tcl" line 50)

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl: Tcl policy execute failed:

Apr  2 15:08:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl: can't read "errorInfo": no such variable

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT : i3925E-1>

Apr  2 15:08:00: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : IN  : i3925E-1>en

Apr  2 15:08:01: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT : i3925E-1#

Apr  2 15:08:01: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : IN  : i3925E-1#show ip nbar protocol-d inter gi0/1.93 stats bit-rate top 1

Apr  2 15:08:01: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :

Apr  2 15:08:01: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :  GigabitEthernet0/1.93

Apr  2 15:08:01: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :

Apr  2 15:08:01: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :  Last clearing of "show ip nbar protocol-discovery" counters 8w3d

Apr  2 15:08:01: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :

Apr  2 15:08:01: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :

Apr  2 15:08:01: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :                             Input                    Output                 

Apr  2 15:08:01: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :                             -----                    ------                 

Apr  2 15:08:01: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :    Protocol                 30sec Bit Rate (bps)     30sec Bit Rate (bps)   

Apr  2 15:08:01: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :    ------------------------ ------------------------ ------------------------

Apr  2 15:08:01: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :    http                     402000                   0                      

Apr  2 15:08:01: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :    unknown                  26000                    0                      

Apr  2 15:08:01: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT :    Total                    452000                   0                      

Apr  2 15:08:01: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : OUT : i3925E-1#

Apr  2 15:08:01: %HA_EM-6-LOG: eem-ISP-if-speedrate.tcl : DEBUG(cli_lib) : CTL : cli_close called.

i3925E-1#

Here part of the script that causes an error:

....

proc CLI_cmd_output {cmd} {

set CLI_output {}

#--- CLI open

if [catch {cli_open} result] {

error $result $errorInfo    <-------- Line 5

} else {

  array set cli1 $result

}

....

PS.

When I change my registration script places an error occurs in a second script, but at the same place and same script command - cli_open.

EEM policy is registered first, always runs to the end sucessfull.

The second registered policy was eliminated in second command [catch {cli_open} result]

.

[Joe Clarke]

This proc hasa problem.  You need to add:

global errorInfo

Just under the proc CLI_cmd_output line.  The error you're seeing is due to this global variable being used incorrectly.  Once that is done, the real error should come through.

[SKC-Korotkov-999]

Thanks Joseph!

Your guess is correct, but how to explain the error

Now issue the following:

Apr  3 09:56:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl: cannot get pty for exec: Error opening vty 'Embedded Event Manager' detected the 'fatal' condition 'no tty lines available, minimum of 2 required by EEM'

Apr  3 09:56:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl:     while executing

Apr  3 09:56:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl: "cli_open"

Apr  3 09:56:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl:     (procedure "CLI_cmd_output" line 5)

Apr  3 09:56:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl:     invoked from within

Apr  3 09:56:00: %HA_EM-6-LOG: eem-if-speedrate(1.1).tcl: "CLI_cmd_output "show run interface $if | inc descr""

But at the same:

i3925E-1#sho line

   Tty Line Typ     Tx/Rx    A Modem  Roty AccO AccI  Uses  Noise Overruns  Int

      0    0 CTY              -    -      -    -    -     0      0    0/0      -

      1    1 AUX   9600/9600  - inout     -    -    -     1      0    0/0      -

*   578  578 VTY              -    -      -    -    3 1222924      0    0/0      -

    579  579 VTY              -    -      -    -    3 1080119      0    0/0      -

    580  580 VTY              -    -      -    -    3 13986      0    0/0      -

    581  581 VTY              -    -      -    -    3  4253      0    0/0      -

    582  582 VTY              -    -      -    -    3     0      0    0/0      -

    583  583 VTY              -    -      -    -    3     0      0    0/0      -

Line(s) not in async mode -or- with no hardware support:

2-577

ie Two VTY lines are always free.

[Joe Clarke]

But as I said, you will need three free lines if two EEM policies will run simultaneously.  That is, you'll need one for the first policy, one for the second, and one that remains free.

[SKC-Korotkov-999]

I did not understand a little bit.

Total lines 6. One is occupied by my telnet session. For two EEM policies require 3 lines.

Why not be enough?

[Joe Clarke]

I should restate.  Each call to cli_open requires two free VTY lines at the time the call is made.  Without seeing your code, I do not know if you're "leaking" VTY lines.  That is, if you do not call cli_close before the next cli_open, then you will need more free VTY lines.  I've never seen a case where this error is printed incorrectly.  At the time the cli_open call is made, there must not have been two free lines (note: the uses count for all lines above is 3, so the lines were in use at some point).

[SKC-Korotkov-999]

Hi Joseph!

I found the cause of the error. Really do not have enough TTY lines.

However reason is different.

I think that the reason is that the IOS can not quickly close the TTY line after the command cli_close.

If you immediately (after command cli_close) comes cli_open command - error occurs.

If you expose a delay of execution 150ms after  cli_close command before next cli_open command - error does not occur! Value 150 ms determined empirically.   (0-100ms -ERROR,    >150ms -NO ERROR occurs)

This occurs when executed the chain of CLI commands and "foreeach" command is called cli_open-cli_close:

                                cli_open -> "enable" -> "user_cmd" -> "cli_close"

The solution:

          1. run all commands in a single cli_open session (is not always possible)

          2. expose a delay (>150ms) of execution next cli_open after cli_close.

[Joe Clarke]

You might want to take a step back and see if doing that flow multiple times in the script is worth it.  If you're doing a lot of CLI consider opening one VTY for the whole script or use the optimized "cli_run" function:

cli_run [list "show ver" "show run"]

In this manner, you only need one VTY.

[SKC-Korotkov-999]

Thanks Joseph!

I was not know with these additional commands.

I have used their own procedures.