Perl Script Help

namishtiwari · February 24, 2009, 5:28am

Hi Experts,

I need help in writing a perl script which can help me in doing the following....

Read the user name and session id from the sample log file provided.
Print the header as risk_assesment for userid(value).
Print the line containing End-to-end time in miliseconds.
There are thoudands of user and i have to calculate the time taken for all the users. The entry for the user name starts at the point where these lines are

Next State: risk_assessment
2009-02-18 00:00:11,687 [TP-Processor11] DEBUG BaseController,(TP-Processor11:301) - Next state: assessrisk.htm
Session id can be found in there.


The portion of the log file for the one user id and session id is below---

2009-02-18 00:00:11,687 [TP-Processor11] INFO  FlowController,(TP-Processor11:121) - Next State: risk_assessment
2009-02-18 00:00:11,687 [TP-Processor11] DEBUG BaseController,(TP-Processor11:301) - Next state: assessrisk.htm
2009-02-18 00:00:11,734 [TP-Processor11] DEBUG RFRiskAssessmentController,(TP-Processor11:122) - Entered callRF
2009-02-18 00:00:11,734 [TP-Processor11] DEBUG RFRiskAssessmentController,(TP-Processor11:122) - Found DID cookie for RF.
2009-02-18 00:00:11,734 [TP-Processor11] DEBUG RFRiskAssessmentController,(TP-Processor11:122) - Returning DID: FXIbNjt4llWFmvPKHSGZoMvZ60WQTd5vFZ3Em+J2jbkZfMHoJxI0XAcDcZfy5G6F
2009-02-18 00:00:11,734 [TP-Processor11] DEBUG RFRiskAssessmentController,(TP-Processor11:122) - Username: 01376128
2009-02-18 00:00:11,734 [TP-Processor11] DEBUG RFRiskAssessmentController,(TP-Processor11:122) - Groupname: MLS
2009-02-18 00:00:11,734 [TP-Processor11] DEBUG RFRiskAssessmentController,(TP-Processor11:122) - Device Signature: 
 {"DEVICESIG":{"VERSION":"1.5","OS_BROWSER":{"browser_ver":"3.0.6","os":"PPC Mac OS X 10.4","browser":"Netscape"},"SCREEN":
 {"colorDepth":"24","availWidth":"1680","width":"1680","height":"1050","availHeight":"1024"},"HTTP_HEADER":
 {"user-agent":"Mozilla/5.0 (Macintosh; U; PPC Mac OS X 10.4; en-US; rv:1.9.0.6) Gecko/2009011912 Firefox/3.0.6"},"OPTIONAL":
 {"SOFTWARE":[]},"USER_PREF":{"sys_lang":"en-us","timezone":"480","user_lang":"en-us"}}}
2009-02-18 00:00:11,734 [TP-Processor11] DEBUG RFRiskAssessmentController,(TP-Processor11:122) - DID retrieved from client system: 
 FXIbNjt4llWFmvPKHSGZoMvZ60WQTd5vFZ3Em+J2jbkZfMHoJxI0XAcDcZfy5G6F
2009-02-18 00:00:11,734 [TP-Processor11] DEBUG RFRiskAssessmentController,(TP-Processor11:122) - IP Address: 216.75.232.70
2009-02-18 00:00:11,734 [TP-Processor11] DEBUG RFRiskAssessmentController,(TP-Processor11:122) - INetAddress received: /216.75.232.70
2009-02-18 00:00:11,734 [TP-Processor11] DEBUG RiskFactory,(TP-Processor11:140) - The object is already created
2009-02-18 00:00:11,734 [TP-Processor11] DEBUG RiskXActionAPI,(TP-Processor11:120) - evaluateRiskAfterLogin: XML Request 
 [<POLICYREQ><MESSAGEID>0</MESSAGEID><CALLERID>4 - MLS - MLS: com.arcot.aok.web.controllers.rf.RFRiskAssessmentController</CALLERID>
 <AUTHPARAMS><ACTION>LOGIN</ACTION><CREDENTIAL>ARCOTID</CREDENTIAL></AUTHPARAMS><IDENTITY>
 <USERID>01376128</USERID><GROUP>MLS</GROUP><SUBGROUP>SUBGROUP2</SUBGROUP></IDENTITY>
 <LOCATION><IPADDRESS>216.75.232.70</IPADDRESS></LOCATION>
 <DEVICEID type="http">FXIbNjt4llWFmvPKHSGZoMvZ60WQTd5vFZ3Em+J2jbkZfMHoJxI0XAcDcZfy5G6F</DEVICEID>
 <DEVICESIG>{"DEVICESIG":{"VERSION":"1.5","OS_BROWSER"
 :{"browser_ver":"3.0.6","os":"
 PPC Mac OS X 10.4","browser":"Netscape"},"SCREEN":
 {"colorDepth":"24","availWidth":"1680","width":"1680","
 height":"1050","availHeight":"1024"},"HTTP_HEADER":{"user-agent":"
 Mozilla/5.0 (Macintosh; U; PPC Mac OS X 10.4; en-US; rv:1.9.0.6) Gecko/2009011912 Firefox/3.0.6"},"
 OPTIONAL":{"SOFTWARE":[]},"USER_PREF":{"sys_lang":"en-us","
 timezone":"480","user_lang":"en-us"}}}</DEVICESIG></POLICYREQ>]
2009-02-18 00:00:11,734 [TP-Processor11] DEBUG SocketPool,(TP-Processor11:32) - borrowSocket: Trying to get lock localCallGetConnectionFlag false callGetConnectionFlag true
2009-02-18 00:00:11,734 [TP-Processor11] DEBUG SocketPool,(TP-Processor11:37) - borrowSocket: In if(callGetConnectionFlag)
2009-02-18 00:00:11,734 [TP-Processor11] DEBUG SocketPool,(TP-Processor11:68) - borrowSocket: Calling borrowObject
2009-02-18 00:00:11,734 [TP-Processor11] DEBUG PoolableSocketFactory,(TP-Processor11:195) - activateObject not supported : No action taken on Socket[addr=/172.16.64.30,port=7680,localport=3188]
2009-02-18 00:00:11,749 [TP-Processor11] DEBUG SocketPool,(TP-Processor11:70) - borrowSocket: Out of borrowObject
2009-02-18 00:00:11,749 [TP-Processor11] DEBUG SocketPool,(TP-Processor11:78) - borrowSocket: Calling Notify
2009-02-18 00:00:11,765 [TP-Processor11] DEBUG PoolableSocketFactory,(TP-Processor11:184) - Validating Object:Socket[addr=/172.16.64.30,port=7680,localport=3188]
2009-02-18 00:00:11,765 [TP-Processor11] INFO  PoolableSocketFactory,(TP-Processor11:199) - passivateObject called on Socket[addr=/172.16.64.30,port=7680,localport=3188]
2009-02-18 00:00:11,765 [TP-Processor11] DEBUG PoolableSocketFactory,(TP-Processor11:184) - Validating Object:Socket[addr=/172.16.64.30,port=7680,localport=3188]
2009-02-18 00:00:11,765 [TP-Processor11] DEBUG RiskXActionAPI,(TP-Processor11:127) - evaluateRiskAfterLogin: 
 Response Packet [<POLICYSERVERDOC DATATYPE="XML"><POLICYRES><MESSAGEID>0</MESSAGEID><SESSIONID>1:2857064</SESSIONID>
 <ACTION>ALLOW</ACTION><RESPONSECODE>0</RESPONSECODE><ERRORSTRING></ERRORSTRING>
 <ERRORCODE>0</ERRORCODE><TRANSACTIONID>1:2857064</TRANSACTIONID><RISKSCORE>10</RISKSCORE>
 <DEVICEID>FXIbNjt4llWFmvPKHSGZoMvZ60WQTd5vFZ3Em+J2jbkZfMHoJxI0XAcDcZfy5G6F</DEVICEID>
 <RISKDETAIL></RISKDETAIL></POLICYRES></POLICYSERVERDOC>]
2009-02-18 00:00:11,765 [TP-Processor11] DEBUG ResponseMessageParser,(TP-Processor11:214) - Error code:0 ErrorMsg:TRANSACTIONID : 1:2857064
2009-02-18 00:00:11,765 [TP-Processor11] DEBUG ResponseMessageParser,(TP-Processor11:214) - Error code:0 ErrorMsg:SESSIONID : 1:2857064
2009-02-18 00:00:11,765 [TP-Processor11] DEBUG ResponseMessageParser,(TP-Processor11:259) - ArcotPacket MessageID [1]
2009-02-18 00:00:11,765 [TP-Processor11] DEBUG ResponseMessageParser,(TP-Processor11:140) - riskAnalysisBuildResponseFromXML: 
 DeviceID [FXIbNjt4llWFmvPKHSGZoMvZ60WQTd5vFZ3Em+J2jbkZfMHoJxI0XAcDcZfy5G6F]
2009-02-18 00:00:11,765 [TP-Processor11] DEBUG ResponseMessageParser,(TP-Processor11:141) - riskAnalysisBuildResponseFromXML:  AggregatorID []
2009-02-18 00:00:11,765 [TP-Processor11] DEBUG ResponseMessageParser,(TP-Processor11:142) - riskAnalysisBuildResponseFromXML: RiskScore [10]
2009-02-18 00:00:11,765 [TP-Processor11] DEBUG ResponseMessageParser,(TP-Processor11:143) - riskAnalysisBuildResponseFromXML: Action [ALLOW]
2009-02-18 00:00:11,765 [TP-Processor11] DEBUG ResponseMessageParser,(TP-Processor11:144) - riskAnalysisBuildResponseFromXML: SessionId [1:2857064]
2009-02-18 00:00:11,765 [TP-Processor11] INFO  RiskXActionAPI,(TP-Processor11:137) - evaluateRiskAfterLogin: donecom.arcot.riskfortAPI.RiskAssessment@25d8c5
2009-02-18 00:00:11,765 [TP-Processor11] INFO  RiskXActionAPI,(TP-Processor11:59) - evaluateRisk: End-to-end time in millisecond 31

I am in need of some help.
I put the things in red which is required, i think that will help you.

Thanks
NT

Note: I edited the post to move code tags closer to logfile and to break up long lines

KevinADC · February 24, 2009, 1:14pm

What have you tried?
Where are you stuck?

Hellish log file......

Tom_de · February 24, 2009, 3:08pm

wow.
Unless I'm missing something there doesn't seem to be anything to tie any of those lines together. If thats the case, you could create your script's logic to check for multiple variables, but thats looks to be hellish in this case also.

So, if you have access to the code you could create your own "debugging" and make that so it that your debugging have a common value. Maybe you could just use the webserver's logs? Looking for the first and last connection?

Is this app yours? Is it a vendor app? What language/code base is it? Is there a database? If there's a database you could use SQL to track your users.

That log file doesn't look like it's going to help you.

Good luck,

Tom de

KevinADC · February 24, 2009, 4:29pm

He did define where a record begins:

Next State: risk_assessment

And this must be the end:

evaluateRisk: End-to-end time in millisecond 31

That would be easy enough to find, but hell if I'm going to try and decipher the rest of the lines in that file. If he can clarify better what records need to pulled from the file and show some effort I am willing to help.

Tom_de · February 24, 2009, 5:39pm

Unfortunatally, like most log files, the user entries will be mixed within each other. So having the first point of the session and last won't help, as the lines in-between probably won't just be one user, but many users.

namishtiwari · February 25, 2009, 1:26am

I am not familiar with Perl much, though i know some shell scripting, i am trying to grep the records,but in perl we dont have that option.If you can help me out with some syntax that will me much appericiable.I need three values user name, session id and the end to end time printed. they are there in the records.

Thanks
NT

Tom_de · February 25, 2009, 10:27am

Perl is like grep on steroids. I understand what you are looking for, but I don't think you'll find it in the log/debug output you posted - for the reasons I've posted already.

So, do you have any answers to our posts? What have you tried already ( post code and output plz.).

Tom de

KevinADC · February 25, 2009, 12:46pm

perl has its own grep function

point them out.

namishtiwari · February 26, 2009, 3:06am

Hi Tom/Kevin/All,

I pointed the records in red, that is what needs to be pulled out from the log snippet.

Thanks
NT

Tom_de · February 26, 2009, 8:18am

2009-02-18 00:00:11,734 [TP-Processor11] DEBUG RFRiskAssessmentController,(TP-Processor11:122) - Username: 01376128

2009-02-18 00:00:11,765 [TP-Processor11] DEBUG ResponseMessageParser,(TP-Processor11:214) - Error code:0 ErrorMsg:SESSIONID : 1:2857064


2009-02-18 00:00:11,765 [TP-Processor11] INFO  RiskXActionAPI,(TP-Processor11:59) - evaluateRisk: End-to-end time in millisecond 31

Ok, not knowing the application, and assuming "TP-Processor11" is the application, there is nothing in common with these lines. That would make it near impossible to make sure the lines are unique to any one user.
You cannot assume that log entries will be in order for each user. That would only happen if your "thousands" of users used the application one user at a time. In reality the log entries will be mixed with multiple users.

That is why, based on the log and requirements you provided I suggested alternate methods in an earlier post.

Although, I have to ask, how confident are you that the log output you posted is accurate to one user? I ask because the highlighted part of the log below:

2009-02-18 00:00:11,734 [TP-Processor11] DEBUG RFRiskAssessmentController,(TP-Processor11:122) - Entered callRF

seems to be the program's internal session ID. Or it seems like it should be.

grep your log for "TP-Processor11:122" to check if this is actually the user's activity.

If so, then it's no problem to grab this and track a user. Otherwise I think you'll have to find a different way to get the info you need.

Tom de

namishtiwari · February 26, 2009, 8:29am

TP-Processor11:122-- It is the actual user activity only because all the users and sessions id is comin into this thread only.If you can provide me a simple syntax i can proceed further.

Thnaks
NT

Tom_de · February 26, 2009, 10:02am

My perl is old and bad, but you should get the idea;(this is pseudo code and could/should be done much better !!)

open(IN , filename)

while (IN){

if  ($_ ~/Username/ ){

     ($a, $b, $c, $d, $user ) = split(/:/, $_) ;            # delimit by :
     ($TP-ID, $blah) = split(/\)/, $d);                       # delimit on ) giving us a number, $d should be "122) - Username"
    print "Username = $user \t TP-Processor11 ID = $TP-ID \n";
    }
     if ( $_ ~/TP-Processor11:$TP-ID:/ && ~/End-to-end/ ){
       $user-end = $_;                                           # just gets the whole line ... lazy
        print "end of user session:\n $user-end \n";
     }
} #end while

close (IN);

ugh, thats bad. But hopefully it helps.

Please feel free to make fun of, point at, and ridicule my code

Tom de

KevinADC · February 26, 2009, 3:26pm

Are we saying these are all different users because the TP-Processor numbers are different?

2009-02-18 00:00:11,734 [TP-Processor11] DEBUG RFRiskAssessmentController,(TP-Processor11:122) - Username: 01376128

2009-02-18 00:00:11,765 [TP-Processor11] DEBUG ResponseMessageParser,(TP-Processor11:214) - Error code:0 ErrorMsg:SESSIONID : 1:2857064


2009-02-18 00:00:11,765 [TP-Processor11] INFO  RiskXActionAPI,(TP-Processor11:59) - evaluateRisk: End-to-end time in millisecond 31

Right now I am too confused to offer any code or suggestions. Clarify the requirements.

Tom_de · February 26, 2009, 3:36pm

I believe OP's original assumption was the output he posted was indeed one user. I questioned this, and I interpreted his response:

To mean that the number after TP-Processor11:xxx is the applications session-id. So that TP-Processor11:122 is one user.

Therefore, his log output is NOT one user but many. I'm guessing that greping his log for TP-Processor11:122 returned one user session.

My thought is 122 is an application internal session-id.

KevinADC · February 26, 2009, 3:43pm

I'm fairly confused now because there are lines with the same session ID but different TP-Processor numbers. Hopefully the OP can give a good definition of what is supposed to be parsed out of the file, otherwise I'm done.

namishtiwari · February 27, 2009, 12:39am

Hi,

Sorry for the confusion made, Those were not diffrent users but the same user.
The session id and the string evelaute time one is in diffrent thread.

2009-02-18 00:00:11,734 [TP-Processor11] DEBUG RFRiskAssessmentController,(TP-Processor11:122) - Username: 01376128

2009-02-18 00:00:11,765 [TP-Processor11] DEBUG ResponseMessageParser,(TP-Processor11:214) - Error code:0 ErrorMsg:SESSIONID : 1:2857064


2009-02-18 00:00:11,765 [TP-Processor11] INFO  RiskXActionAPI,(TP-Processor11:59) - evaluateRisk: End-to-end time in millisecond 31

Here thread 122 holds the user details, thread 214 holds the session id details and thread 59 contains the string.
In whole the log file the entries for the respective user,sessionid and string will be made in thses threads.

I hope this clarifies the problem correctly.
Thanks for the patience and sorry once again if i made u misinterpret the problem.

Thanks
NT

KevinADC · February 27, 2009, 2:13am

my %hash;
open(my $LOG, 'path/to/file') or die "$!";
LOOP1: while(<DATA>) {
   my $user;
   if (/Next State: risk_assessment$/) {
      LOOP2: while(<DATA>) {
         if (/Username:\s+(\S+)$/) {
            $user = $1;
            if (! exists $hash{$user}) {
               $hash{$user} = {SessionID => '', Time => 0 };
            }
         }
         else {
            next LOOP2;
         } 
         LOOP3: while(<DATA>) {
            if (/ErrorMsg:SESSIONID :\s+(\S+)$/) {
               $hash{$user}{SessionID} = $1;
               next LOOP3;
            }
            elsif (/evaluateRisk: End-to-end time in millisecond (\S+)$/) {
               $hash{$user}{Time} += $1;
               next LOOP1;
            }
         }
      }
   }
}
close ($LOG);
use Data::Dumper;
print Dumper \%hash;

I leave coding formatted output up to you. ALso, since the amount of sample data was limited, I would not be surprised if this does not work for the entire file.

KevinADC · February 27, 2009, 2:22am

If the same user can have different session IDs that need to be tracked seperately then the data structure has to be changed

namishtiwari · February 27, 2009, 2:30am

Hi Kevin,

Thanks For the script part, but i can not understand much part of it syntax wise, can you please explain me too what you have done.

Thanks
NT

KevinADC · February 27, 2009, 2:56am

Some loops, some regular expressions, and a hash of hashes for the data.