Solved: simple command output takes too long in ASR9K

nikos_skalis · ‎09-26-2012

Hello All,

I have written a simple Tcl script that executes 10 times the command "show interfaces detail".

The same script in 7600 gets executed in 2-3 sec, but in ASR9K it times out after 5min, because I have set it like that,

meaning that it takes >5min, making the EEM script in IOS-XR unusuable.

Could you please enlighten me why it is so slow (you can find it attached) ? Perhaps try and run it on another ASR9K to see if it takes the same amount time to complete.

Kind Regards,

Joe Clarke · ‎09-27-2012

Sounds like the commands are running, then. In that case, I think you need to troubleshoot the AAA authorization issue. This will likely involve some AAA-specific debug. This might be best persued on one of the security forums.

View solution in original post

Joe Clarke · ‎09-26-2012

One of my colleagues tested your script and it ran fine. In my previous experience with EEM on XR, I found it takes a few seconds for the Tcl interpreter to spin up, but runtime is usually quick. One thing that may slow down execution is AAA Command authorization. Are you doing this on your XR router? If so, each command needs to be authorized, and that can take a long time with the round-trip to the AAA server.

Also, you might try dumping the output after each iteration to make sure the first one is running. I have seen a bug on XR where prompt matching doesn't work correctly, and this can cause EEM policies to fail.

nikos_skalis · ‎09-26-2012

Thank you Joseph,

You are probably right, I had read this before. I'll test it shortly and I'll let you know.

Currently, my AAA is configured like that :

aaa accounting exec default start-stop group tacacs+

aaa accounting commands default start-stop group tacacs+

aaa authorization exec default group tacacs+ local

aaa authorization commands default group tacacs+

aaa authorization eventmanager default local

aaa authentication login default group tacacs+ local

username eem

group root-system

group cisco-support

secret 5 ...

How it should be in order to avoid authorizing each command in the script ?

removing aaa authentication login default group tacacs+ local I am getting again :

eem_server[199]: %HA-HA_EM-6-FMS_POLICY_TIMEOUT : Policy 'demo.tcl' has hit its maximum execution time of 300.000000000 seconds, and so has been halted

Many Thanks,

Joe Clarke · ‎09-27-2012

The config that is likely causing the problem is:

aaa authorization commands default group tacacs+

I'm not saying that is a problem insomuch as I'm saying because you're doing command authorization, you are adding more overhead to the commands being executed. If you can optimize the roundtrip time between the router and the AAA server, you may have better results.

That said, I would try and dump command output after each execution just to make sure you're not seeing another problem. Make sure you are actually running the show commands correctly.

nikos_skalis · ‎09-27-2012

Thank you Joseph

The 1st dump / 1st show command takes quite some time to get displayed, actually.

What do you mean when you say "Make sure you are actually running the show commands correctly." ?

Once again, Many Thanks.

Joe Clarke · ‎09-27-2012

Sounds like the commands are running, then. In that case, I think you need to troubleshoot the AAA authorization issue. This will likely involve some AAA-specific debug. This might be best persued on one of the security forums.

widmermanuel1987 · ‎10-01-2012

I have exactly the same problem with slow output, when i try to execute the two commands:

show policy-map interface all

show interface

This takes >90 seconds when i execute via eem script, compared to 30-40 seconds when I execute them myself directly on the cli.

my aaa configuration is as follows for eem script:

username eem_usr

group root-system

group cisco-support

aaa authorization commands eem-method none

aaa authorization eventmanager default local

line template eem-template

authorization commands eem-method

vty-pool eem 100 150 line-template eem-template

event manager policy .tcl username eem_usr persist-time infinite type user

I think aaa should not be the issue here. I wonder if there is any resource limitation for eem tcl scripts?

nikos_skalis · ‎10-01-2012

Hi Manuel,

in my case the issue was solved using the file append utility,

just try to sace everything to a file and it will be ok, don't concat strings

widmermanuel1987 · ‎10-01-2012

Thanks for the hint, will give it a try

nikos_skalis · ‎10-01-2012

The reason for the difference is that when EEM executes the cli it reads 128 bytes at one read call.

It is designed to interact with cli (expect for prompt for instance, etc) instead of capturing large output.

So if the output of the cli is 128 KB then it requires 1000 reads to be done. Hence the delay.

in 7600 Tcl rocks, in ASR9K there are some cases like this that I don't like

sarmed alkadumi · ‎03-31-2013

I am facing a similar problem with my ASR and I am using a very simle script, it worked once but stopped working after that showing the same log mentioned above, I wonder if you were able to make it work somehow ?

the only AAA config i made is this:

aaa authorization eventmanager default local

username EEM

group root-system

event manager policy test.tcl username EEM persist-time infinite

the script written is:

::cisco::eem::event_register_syslog occurs 1 pattern $_test maxrun 90

namespace import ::cisco::eem::*

namespace import ::cisco::lib::*

array set cliconn [ cli_open ]

cli_exec $cliconn(fd) "conf t"

cli_exec $cliconn(fd) "router bgp xxxx neighbor cccc address-family ipv4 unicast"

cli_exec $cliconn(fd) "route-policy test out"

cli_exec $cliconn(fd) "commit"

cli_close $cliconn(fd) $cliconn(tty_id)

nikos_skalis · ‎03-31-2013

here is the necessary config :

admin
conf t
username 
group root-system
group cisco-support
secret 
commit
exit
exit
exit

conf t
no banner exec
event manager directory user policy disk0a:/usr
event manager directory user library disk0a:/usr
aaa authorization eventmanager default local
event manager policy  username 
commit
exit

sarmed alkadumi · ‎03-31-2013

My config is pretty much the same except for "group cisco-support" under the username config mode, do you think its the reason the script is taking too long to execute ?

.

i tried adding the command "group cisco-support" and tested again, the script is still timing out after 90 seconds, there seems to be something wrong with the script, any advice ?

widmermanuel1987 · ‎04-02-2013

You could try to find out where your script gets stuck. E.g. place a few puts " successful" between your "cli_exec" statements or surround them with a catch as in the following example :

 
if {[catch {cli_open} result]} {
     action_syslog priority info msg  "failed to open cli session: $result $::errorInfo"
     error $result $::errorInfo
} else {
     array set cli $result
}

if {[catch {cli_exec $cli(fd) "router bgp xxxx address-..."} output]} {

action_syslog priority info msg "failed to execute cli command: $output $::errorInfo"

error $output $::errorInfo

}

puts $output

I'd also "puts" every output of the "cli_exec" commands (just for debugging purpose), it might give you some hints of what is going wrong.

Note: If puts is not working for you (i.e. you don't see any output on cli), try with action_syslog instead of puts and check show log after you've run the tcl scirpt.

sarmed alkadumi · ‎04-03-2013

I combined

cli_exec $cliconn(fd) "router bgp xxxx neighbor cccc address-family ipv4 unicast"

cli_exec $cliconn(fd) "route-policy test out"

into

cli_exec $cliconn(fd) "router bgp xxxx neighbor cccc address-family ipv4 unicast route-policy test out"

and its working now, i will give it a try if it fails again , thanks for the advice.