Welcome to the VanDyke Software Forums

Join the discussion today!


Go Back   VanDyke Software Forums > Scripting

Reply
 
Thread Tools Rate Thread Display Modes
  #1  
Old 11-30-2010, 06:46 PM
slouw slouw is offline
Registered User
 
Join Date: Nov 2005
Posts: 166
Time issues logging scripted output

Hi There

I have a rudimentary script and a timing problem.
It seems the execution of the script and the Session Logging are not operating in the order that I would like.
I have a logging setup which uses time variables down to the second so that effectively every time logging is enabled a new log file is created. That is accept the unlikely scenario where logging is turned off and on without the elapsing of 1 second in time. My logging setup is shown here:



My script calls for the temporary replacement of this logging setup so that a unique logfile is created for the duration of the script. The output generated by the script operation is supposed to be saved in this logfile. It should then be closed and the orginal logfile name with variables restored. This is summarised in the flow chart below:



The problem is the output is not being recorded in the expected place (File2). I have had some variation but currently the output is being recorded in file 3. Sometimes some of the output is in file (correct) but only some and the rest is lost. Etc I have had timing problems in the past generally fixed with Crt.Sleep and Crt.Screen.Synchronous commands here and there.




Any comments suggestions?
Script is attached
Attached Files
File Type: txt 036 Asia Script004.txt (9.4 KB, 431 views)
Reply With Quote
  #2  
Old 11-30-2010, 07:05 PM
slouw slouw is offline
Registered User
 
Join Date: Nov 2005
Posts: 166
Tried this improvement

I found a problem with Crt.Screen.Synchronous here (below).
I got rid of the extraneous Crt.Screen.Synchronous = False so in effect we are synchronous all the way through.
No change.

Reply With Quote
  #3  
Old 12-01-2010, 10:36 AM
rtb rtb is offline
VanDyke Technical Support
 
Join Date: Aug 2008
Posts: 4,306
Hi slouw,

Thanks for the additional information. After analyzing your script, that was the first problem we found. As a general rule, crt.Screen.Synchronous = True should be the first line of code after a connection is established. In the case of this script, it should be the first line of code.
The line crt.Screen.Synchronous = False should not be used unless you know why it is being used.

The next rule that should always be followed is regarding the Send method. A Send should *always* be followed by a WaitFor... or Read... method. The Sleep method does *not* count, and should not be used to affect the timing of a script where timing matters.

I found 3 places in a row in the script where data is sent without waiting. Sending VBCR twice on one line is two sends.

If you make these suggested changes, does your script behave as expected?
__________________
--Todd

VanDyke Software
Technical Support
support@vandyke.com
505-332-5730
Reply With Quote
  #4  
Old 12-02-2010, 01:20 PM
slouw slouw is offline
Registered User
 
Join Date: Nov 2005
Posts: 166
crt.Screen.Send now followed by ReadStr in all cases

Action
Take script "036 Asia Script004.vbs" (script I posted)
Save it as "036 Asia Script004A01vbs"
Make changes as shown in the screenshot below.

The screenshot is a grep of "036 Asia Script004.vbs" with crt.screen.send OR wait OR read.
The changes amount to deleting 2 for these crt.Screen.Send VbCr & VbCr
Funny enough I put them in to try and gain some control

Results
It changed the outcome but only by variying the results.
There are 2 show commands sent by the script
Show command C1 = "show tech-support" Very long output. I timed one at about 15 seconds although this can vary.
Show command C2 = "show ip route eigrp". Much shorter output ony 3-4 lines.
Refer screenshot below.
Log file L1 was the logfile in use when the script was run
L2 was the logfile generated by the script.
All or most of show command C1 was recorded in L2 (which is desired outcome)
Show command C2 output was missing (which of course is not desired )
Logfile L3 was the restored logfile once the script had ended.
Logfile L3 was completely empty.
So it seems the script and the logging are running at separate speeds.
I can see this by watching the session output and the folder where the logfiles live.

Attached Files
File Type: txt 036 Asia Script004A01.txt (9.5 KB, 371 views)

Last edited by slouw; 12-02-2010 at 01:51 PM. Reason: Add attachment
Reply With Quote
  #5  
Old 12-02-2010, 01:54 PM
rtb rtb is offline
VanDyke Technical Support
 
Join Date: Aug 2008
Posts: 4,306
Hi slouw,

Thanks for the update. It appears as though you have paired a Send with a ReadString, but you have not made the changes regarding synchronization. Here is an example of how *this* script should be using Synchronous:
Code:
#$language = "VBScript"
#$interface = "1.0"
crt.Screen.Synchronous = True
.
.
Dim variable
Dim variable1
.
.
Sub Main
    .
    .
    .
    .
    .
End Sub
If you modify your script such that only the single synchronization line appears at the beginning of the script, do you see the results you want?
__________________
--Todd

VanDyke Software
Technical Support
support@vandyke.com
505-332-5730
Reply With Quote
  #6  
Old 12-02-2010, 02:08 PM
slouw slouw is offline
Registered User
 
Join Date: Nov 2005
Posts: 166
Adding a delay at the end helps (MyRef 007)

I tried this (below) and it had the desired affect.
Namely add Crt.sleep.30000 a 30 second delay before stopping the logging at the end of the script and restoring the original logfile.
I dont think 30seconds was necessary 20 would work I suspect.
The problem is this is rather inflexible but it may help me get something going and also would seem a helpful troubleshooting step

Code:
'# Restore Filename Start ############################################
'# Restore Filename Start ############################################
'# Restore Filename Start ############################################
'# Restore Filename Start ############################################
'# Turn off logging, Restore Filename, start logging again
'# 007 Before turn off logging add delay to try and let the loggin output catch up
'#     with the script
 		crt.Session.SetStatusText("30000 No2")
 		Crt.Sleep 30000
 		crt.Session.SetStatusText("30000 No2 ENDED")
'#Turn off logging
	crt.GetScriptTab.session.log False
'#Restore orginal Log file name
'#Tried without this but there was a problem. We need this so leave it in
	Crt.Session.Config.SetOption "Log Filename", LogFileStr
	Crt.Sleep 500
'#Start logging again
	Crt.GetScriptTab.session.LogUsingSessionOptions

'# Restore Filename End   ############################################
Reply With Quote
  #7  
Old 12-02-2010, 03:57 PM
rtb rtb is offline
VanDyke Technical Support
 
Join Date: Aug 2008
Posts: 4,306
Hi slouw,

Thanks for the additional testing and information.

Another problem with the script that I forgot to mention is the timeouts you are using in your ReadString commands. All bets are off with regards to synchronization when using timeouts with ReadString. This may be the reason that your script needs the 30 second wait at the end.

Additionally, if you run the sh tech command manually, do you actually get more prompts?
__________________
--Todd

VanDyke Software
Technical Support
support@vandyke.com
505-332-5730
Reply With Quote
  #8  
Old 12-02-2010, 04:38 PM
slouw slouw is offline
Registered User
 
Join Date: Nov 2005
Posts: 166
Hi Todd
Firstly thankyou for your sistained interest.
I have done the following:
- Moved the Crt.Screen.Synchronous = True to the top as you suggest'
- changed the script somewhat so that a subroutine is called with the show command;
- Make only 1 call with a much shorter command "show version"
- Removed the timeout parameter from the 3 ReadString calls.

I still get the same result. The output is in the wrong logfile.
I could get rid of the whole business of checking for the "--More--" output if you think it will help. If the output is greater than a certain number of lines then you are prompted to continue the output. In a show tech in fact there is no such prompt. I can work around the whole "--More--" business by setting terminal lenght=0 at the beginning. That you probably know will make the whole output be sent at once.
Attached Files
File Type: txt 036 Asia Script008.txt (7.5 KB, 366 views)
Reply With Quote
  #9  
Old 12-03-2010, 09:40 AM
rtb rtb is offline
VanDyke Technical Support
 
Join Date: Aug 2008
Posts: 4,306
Hi slouw,

You are welcome! Thanks for the information. Would you post the version of SecureCRT you are using?
__________________
--Todd

VanDyke Software
Technical Support
support@vandyke.com
505-332-5730
Reply With Quote
  #10  
Old 12-03-2010, 02:09 PM
slouw slouw is offline
Registered User
 
Join Date: Nov 2005
Posts: 166
Hi Todd
Sometime between my last post and this one I upgraded to the latest I found on vandyke.com. No change in symptoms.
Ver 6.6.1 (x64 build 289) - Official Release - November 4, 2010
Reply With Quote
  #11  
Old 12-03-2010, 04:37 PM
rtb rtb is offline
VanDyke Technical Support
 
Join Date: Aug 2008
Posts: 4,306
Hi slouw,

Thanks for the version of SecureCRT.

We have analyzed the script that you posted in #4 of this thread because the most recent script in post #8 was too buggy to work with. Here is a list of the changes that we made to the script to get it to function:
- Moved <Crt.Screen.Synchronous = True> statement to top of script

- Eliminated Dim statements and comments

- Took out timeouts parameters for all ReadString calls
- Removed the TimeOut variable
- Moved <Session.Log False> to *before* getting log file name from session options.

- Replaced all <crt.GetScriptTab.> with <crt.> so that the script is consistent throughout.

- Removed bogus <crt.Screen.Send VbCr & vbCr> code, because it violates the always-wait/read-after-each-send() general best practice rule of thumb.

- Replaced all
<ReadStr = crt.Screen.ReadString()>
with
<crt.Screen.WaitForStrings()>
making sure to remove all () around the parameters, since we're not doing anything with the results of WaitForStrings.
Most of the changes we made are related to the two suggestions I initially made. As we analyzed the script, we found that all problems were timing related, and the two main problems were the ReadString timeouts and sending the 2 vbcr's in a row.

Here is a simplified example script that should accomplish the same thing as your script:
Code:
#$language = "VBScript"
#$interface = "1.0"
crt.Screen.Synchronous = True

' Determine the shell prompt, so that we know when a command is finished
strShellPrompt = crt.Screen.Get(crt.Screen.CurrentRow,1,crt.Screen.CurrentRow,crt.Screen.CurrentColumn-1)

' Turn off --More-- prompts
crt.Screen.Send "term len 0" & vbcr
crt.Screen.WaitForString strShellPrompt

Sub Main

    ' Turn off logging before manipulating the log file name
    crt.Session.Log False
    
    strLogFileAdd = crt.Dialog.Prompt("Test No & Narrative: ")
    strOrigLogFile = crt.Session.Config.GetOption("Log Filename")
    strNewLogFile = strOrigLogFile & " Asia Audit 004 " & strLogFileAdd & ".log"
    crt.Session.Config.SetOption "Log Filename", strNewLogFile

    ' Start logging to capture desired output
    crt.Session.LogUsingSessionOptions
    
    ' Send each command, one at a time.  Notice that every time Send is called, 
    ' only one carriage return is included, and each Send is followed by a call
    ' to WaitForString.
    crt.Screen.Send "sh tech-support" & VbCr
    crt.Screen.WaitForString strShellPrompt
    crt.Screen.Send "sh IP route eigrp" & VbCr
    crt.Screen.WaitForString strShellPrompt

    ' Now that we are sure that the last command is completed, restore logging
    ' to original session specification
    crt.Session.log False
    crt.Session.Config.SetOption "Log Filename", strOrigLogFile
    strOrigLogFile = crt.Session.Config.GetOption("Log Filename")
    crt.Session.LogUsingSessionOptions

End Sub
Please note that in the first section of this example script we turn off the "--More--" prompt. This is the easiest method for interacting with a Cisco device via scripting.

Does this example script along with the outline of changes we made help you get the timing of your script corrected?
__________________
--Todd

VanDyke Software
Technical Support
support@vandyke.com
505-332-5730
Reply With Quote
  #12  
Old 12-04-2010, 04:06 AM
slouw slouw is offline
Registered User
 
Join Date: Nov 2005
Posts: 166
Asia 2 script results

Hi Todd
It is, as we say, super that you are prepared to offer such great help.
I took your suggested script verbatum and grandly named it 010 Asia 2 000.vbs.
Then I ran it a few times with very interesting results.

Nomenclature
Before we invoke the script we have a logfile open. Lets call that the before log.
During the script we are supposed to be logging to a specially named logfile. Lets call that the audit log.
Once the script is finnished we should be logging to a logfile with the same format as before we ran the script. Lets call that the after log.

Asia 2 Take 1: The entire capture was stored in the after log file. The audit log where all the capture belongs is empty.
I ran this again taking a movie....

Asia 2 Take 2: This is best shown in the screenshot below:



Simlar to Asia2 Take1 but with a strange twist.
Apparently the audit log and the after log are created at the same time.
Aside from that we have the same result as with Asia 2 Take 1 above.
As mentioned I took a movie of this. I have an avi file 6.66Mb.
I am not going to try and lodge it here for now.
Let me know if you want it I could email it to you or send you an invite to download from FTP.
Once again my thanks.
Reply With Quote
  #13  
Old 12-06-2010, 11:17 AM
rtb rtb is offline
VanDyke Technical Support
 
Join Date: Aug 2008
Posts: 4,306
Hi slouw,

I am happy to help. This is an interesting problem, and we want to get to the bottom of it.

We have modified the script to message box data at each point where we are waiting for the prompt. Would you run the new version of the script, and post a screenshot of the whole SecureCRT window ensuring that the message box dialog is not obscuring the SecureCRT terminal window?

We understand if you cannot post the screenshots due to the fact that they may contain sensitive data. If this is the case, please send them to support@vandyke.com with a subject of Attn: Todd - forum thread #6494.

Here is the modified script:
Code:
#$language = "VBScript"
#$interface = "1.0"
nStartTime = Timer
crt.Screen.Synchronous = True

' Determine the shell prompt, so that we know when a command is finished
strShellPrompt = crt.Screen.Get(crt.Screen.CurrentRow,1,crt.Screen.CurrentRow,crt.Screen.CurrentColumn-1)
MsgBox "Shell prompt detected as <" & strShellPrompt & ">" & vbcrlf & _
    "Seconds elapsed: " & Round(Timer - nStartTime, 3)

' Turn off --More-- prompts
crt.Screen.Send "term len 0" & vbcr
crt.Screen.WaitForString strShellPrompt
MsgBox "'term len 0' command completed." & vbcrlf & _
    "Seconds elapsed: " & Round(Timer - nStartTime, 3)

Sub Main

    ' Turn off logging before manipulating the log file name
    crt.Session.Log False
    
    strLogFileAdd = crt.Dialog.Prompt("Test No & Narrative: ")
    strOrigLogFile = crt.Session.Config.GetOption("Log Filename")
    strNewLogFile = strOrigLogFile & " Asia Audit 004 " & strLogFileAdd & ".log"
    crt.Session.Config.SetOption "Log Filename", strNewLogFile

    ' Start logging to capture desired output
    crt.Session.LogUsingSessionOptions
    
    ' Send each command, one at a time.  Notice that every time Send is called, 
    ' only one carriage return is included, and each Send is followed by a call
    ' to WaitForString.
    crt.Screen.Send "sh tech-support" & VbCr
    crt.Screen.WaitForString strShellPrompt
    MsgBox "'sh tech-support' command completed." & vbcrlf & _
        "Seconds elapsed: " & Round(Timer - nStartTime, 3)
    crt.Screen.Send "sh IP route eigrp" & VbCr
    crt.Screen.WaitForString strShellPrompt
    MsgBox "'sh IP route eigrp' command completed." & vbcrlf & _
        "Seconds elapsed: " & Round(Timer - nStartTime, 3)

    ' Now that we are sure that the last command is completed, restore logging
    ' to original session specification
    crt.Session.log False
    crt.Session.Config.SetOption "Log Filename", strOrigLogFile
    strOrigLogFile = crt.Session.Config.GetOption("Log Filename")
    crt.Session.LogUsingSessionOptions

End Sub
__________________
--Todd

VanDyke Software
Technical Support
support@vandyke.com
505-332-5730
Reply With Quote
  #14  
Old 12-07-2010, 03:23 AM
slouw slouw is offline
Registered User
 
Join Date: Nov 2005
Posts: 166
Works perfectly with popups

As I have often found in the past when I put popups in it works
I ran the script, named 010 Asia 2 001.vbs, twice and it worked perfectly both times.
The second time I hit ok as quick as I could.
Screenshots are in order below. In my enthusiasm I have sent you an FTP invite to download a flash movie of proceedings.









Reply With Quote
  #15  
Old 12-07-2010, 11:57 AM
rtb rtb is offline
VanDyke Technical Support
 
Join Date: Aug 2008
Posts: 4,306
Hi slouw,

Thanks for the update. I am glad to hear that we have success with the message boxes enabled. Please see my email response for next steps.
__________________
--Todd

VanDyke Software
Technical Support
support@vandyke.com
505-332-5730
Reply With Quote
Reply


Currently Active Users Viewing This Thread: 1 (0 members and 1 guests)
 
Thread Tools
Display Modes Rate This Thread
Rate This Thread:

Posting Rules
You may not post new threads
You may not post replies
You may not post attachments
You may not edit your posts

BB code is On
Smilies are On
[IMG] code is On
HTML code is Off

Forum Jump


All times are GMT -6. The time now is 11:26 PM.