asked on

Shell - calculate time between log lines

Hi,

Not sure if this is possible to be done but I need to have a script to calculate the time between two log lines apperas in a log file.

The log file has:

1- Several lines like this:
2014-11-04 00:19:36.183 [164] Debug HttpReceiverServlet Incoming request url : http://otasnq-nmnet-nfce:7900/httpeventadapter/SP_ADD/httpAdapter/ST.TERMINAL_SWITCH query string ST.IMSI=310260567661995&ST.IMEI=86458702147373

And several lines like this:
2014-11-04 00:19:51.625 [232] Flow DbSender Successfully sent request RequestHolder [Notification name=TerminalSwitch_Post, URL=http://XXXXXX-priv-opm:9010/opm/sg/notification, Method=GET, ContentType=application/x-www-form-urlencoded, Url parameters=SG.IMSI=310260567661995,

NOTE that the IMSI and IMEI on these lines differ (not in lenght but in content), for example:

2014-11-04 00:19:37.066 [164] Debug HttpReceiverServlet Incoming request url : http://XXXXXX-nmnet-nfce:7900/httpeventadapter/SP_ADD/httpAdapter/ST.TERMINAL_SWITCH query string ST.IMSI=310260672532625&ST.IMEI=35406806239910

====

The log is linear so for each line like this one for a specific IMSI I have on for this IMSI as well:
2014-11-04 00:19:36.183 [164] Debug HttpReceiverServlet Incoming request url : http://XXXXXX-nmnet-nfce:7900/httpeventadapter/SP_ADD/httpAdapter/ST.TERMINAL_SWITCH query string ST.IMSI=310260567661995&ST.IMEI=86458702147373
.
.
2014-11-04 00:19:51.625 [232] Flow DbSender Successfully sent request RequestHolder [Notification name=TerminalSwitch_Post, URL=http://XXXXXX-priv-opm:9010/opm/sg/notification, Method=GET, ContentType=application/x-www-form-urlencoded, Url parameters=SG.IMSI=310260567661995,

So what I need is for every "pair" of this (connected by the IMSI) is the dif. of the timing between the lines.. i the case above 00:19:51.625 minus 00:19:36.183.

And give as output a count like this:
Difference less than 60 sec = X
Difference more than 60 secs and less the 60 minute = Y
Dif. more than 60 min = Z

Is this possible?

===

There is one more thing.... sometimes I can have a situation like this:

2014-11-06 12:54:33.481 [46] Debug HttpReceiverServlet Incoming request url : http://XXXXXX-nmnet-nfce:7900/httpeventadapter/SP_ADD/httpAdapter/ST.TERMINAL_SWITCH query string ST.IMSI=310260130369278&ST.IMEI=01262600179856
2014-11-06 12:59:05.874 [52] Debug HttpReceiverServlet Incoming request url : http://XXXXXX-nmnet-nfce:7900/httpeventadapter/SP_ADD/httpAdapter/ST.TERMINAL_SWITCH query string ST.IMSI=310260130369278&ST.IMEI=01262600179888
ST.IMSI=310260130369278
2014-11-06 13:04:43.950 [232] Flow DbSender Successfully sent request RequestHolder [Notification name=TerminalSwitch_Post, URL=http://XXXXXX-priv-opm:9010/opm/sg/notification, Method=GET, ContentType=application/x-www-form-urlencoded, Url parameters=SG.IMSI=310260130369278,

Two Incomings and out Successfully... only the last Incoming should be considered.

Tks,
joao

ozo

perl -e 'use Time::Piece;
while( <> ){
if( /([^.]+).*?Successfully.*?IMSI=(\d+)/ ){
$d=Time::Piece->strptime($1,"%Y-%M-%D %T")->epoch - Time::Piece->strptime($I{$2},"%Y-%M-%D %T")->epoch;
$count[($d>60)+($d>3600)]++
}
$I{$2}=$1 if /([^.]+).*?Incoming.*?IMSI=(\d+)/;
}
print "Difference less than 60 sec = $count[0]\n";
print "Difference more than 60 secs and less the 60 minute = $count[1]\n";
print "Dif. more than 60 min = $count[2]\n"; ' < logfile

joaotelles

ASKER

Tks!

But I got this error:
Can't locate Time/Piece.pm in @INC (@INC contains: /usr/perl5/5.8.4/lib/sun4-solaris-64int /usr/perl5/5.8.4/lib /usr/perl5/site_perl/5.8.4/sun4-solaris-64int /usr/perl5/site_perl/5.8.4 /usr/perl5/site_perl /usr/perl5/vendor_perl/5.8.4/sun4-solaris-64int /usr/perl5/vendor_perl/5.8.4 /usr/perl5/vendor_perl .) at -e line 1.
BEGIN failed--compilation aborted at -e line 1.

joaotelles

ASKER

I have installed the time/Pice manually but now Im getting this:

Error parsing time at /usr/perl5/site_perl/5.8.4/sun4-solaris-64int/Time/Piece.pm line 469, <> line 174227.

I installed using this instructions:
# perl Makefile.PL
WARNING: META_MERGE is not a known parameter.
Checking if your kit is complete...
Looks good
'META_MERGE' is not a known MakeMaker parameter name.
Writing Makefile for Time::Piece
# /usr/perl5/bin/perlgcc Makefile.PL
WARNING: META_MERGE is not a known parameter.
'META_MERGE' is not a known MakeMaker parameter name.
Writing Makefile for Time::Piece

# make
cp Seconds.pm blib/lib/Time/Seconds.pm
cp Piece.pm blib/lib/Time/Piece.pm
/usr/perl5/5.8.4/bin/perl /usr/perl5/5.8.4/lib/ExtUtils/xsubpp -typemap /usr/perl5/5.8.4/lib/ExtUtils/typemap Piece.xs > Piece.xsc && mv Piece.xsc Piece.c
gcc -c -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64 -D_TS_ERRNO -O2 -fno-strict-aliasing -DVERSION=\"1.29\" -DXS_VERSION=\"1.29\" -fPIC "-I/usr/perl5/5.8.4/lib/sun4-solaris-64int/CORE" Piece.c
Running Mkbootstrap for Time::Piece ()
chmod 644 Piece.bs
rm -f blib/arch/auto/Time/Piece/Piece.so
LD_RUN_PATH="" gcc -G Piece.o -o blib/arch/auto/Time/Piece/Piece.so
chmod 755 blib/arch/auto/Time/Piece/Piece.so
cp Piece.bs blib/arch/auto/Time/Piece/Piece.bs
chmod 644 blib/arch/auto/Time/Piece/Piece.bs
Manifying blib/man3/Time::Seconds.3
Seconds.pm:181: Unknown command paragraph "=encoding utf8"
Manifying blib/man3/Time::Piece.3

# make test
PERL_DL_NONLAZY=1 /usr/perl5/5.8.4/bin/perl "-MExtUtils::Command::MM" "-e" "test_harness(0, 'blib/lib', 'blib/arch')" t/*.t
t/01base........ok
t/02core........ok
t/03compare.....ok
t/04mjd.........ok
t/05overload....ok
t/06subclass....ok
t/07arith.......ok
All tests successful.
Files=7, Tests=156, 0 wallclock secs ( 0.19 cusr + 0.00 csys = 0.19 CPU)

# make install
Installing /usr/perl5/site_perl/5.8.4/sun4-solaris-64int/auto/Time/Piece/Piece.so
Installing /usr/perl5/site_perl/5.8.4/sun4-solaris-64int/auto/Time/Piece/Piece.bs
Files found in blib/arch: installing files in blib/lib into architecture dependent library tree
Installing /usr/perl5/site_perl/5.8.4/sun4-solaris-64int/Time/Seconds.pm
Installing /usr/perl5/site_perl/5.8.4/sun4-solaris-64int/Time/Piece.pm
Installing /usr/perl5/5.8.4/man/man3/Time::Seconds.3
Installing /usr/perl5/5.8.4/man/man3/Time::Piece.3
Writing /usr/perl5/site_perl/5.8.4/sun4-solaris-64int/auto/Time/Piece/.packlist
Appending installation info to /usr/perl5/5.8.4/lib/sun4-solaris-64int/perllocal.pod

ozo

What is in line 174227 of your logfile?

joaotelles

ASKER

dpa@otablv04 mdm1a> sed -n 174227p mdm1a20141031.log
2014-10-31 06:52:54.302 [36] Flow DbSender Successfully sent request RequestHolder [Notification name=TerminalSwitch_Post, URL=http://XXXXXX-snq-opm-vip:9010/opm/sg/notification, Method=GET, ContentType=application/x-www-form-urlencoded, Url parameters=SG.IMSI=310260211557257,

Looks exacltly the same as the others...

For example:
2014-10-31 06:52:54.698 [36] Flow DbSender Successfully sent request RequestHolder [Notification name=TerminalSwitch_Post, URL=http://XXXXXX
-snq-opm-vip:9010/opm/sg/notification, Method=GET, ContentType=application/x-www-form-urlencoded, Url parameters=SG.IMSI=310260002579222,

and

2014-10-31 06:52:54.729 [36] Flow DbSender Successfully sent request RequestHolder [Notification name=TerminalSwitch_Post, URL=http://XXXXXX
-snq-opm-vip:9010/opm/sg/notification, Method=GET, ContentType=application/x-www-form-urlencoded, Url parameters=SG.IMSI=310260802727386,

Tks,
Joao

ASKER CERTIFIED SOLUTION

ozo

membership

This solution is only available to members.

To access this solution, you must be a member of Experts Exchange.

Start Free Trial

joaotelles

ASKER

Tks Ozo!

Sorry to ask but is there a way to analyze only the lines with IMSIs that appear one time (one pair of Incoming and Notification) ?

I mean to ignore cases like this: where I have more than one Incoming line for a same IMSI and more than one notification for a same IMSI as well...

2014-11-06 12:54:33.481 [46] Debug HttpReceiverServlet Incoming request url : http://XXXXXX-nmnet-nfce:7900/httpeventadapter/SP_ADD/httpAdapter/ST.TERMINAL_SWITCH query string ST.IMSI=310260130369278&ST.IMEI=01262600179856
2014-11-06 12:59:05.874 [52] Debug HttpReceiverServlet Incoming request url : http://XXXXXX-nmnet-nfce:7900/httpeventadapter/SP_ADD/httpAdapter/ST.TERMINAL_SWITCH query string ST.IMSI=310260130369278&ST.IMEI=01262600179888
ST.IMSI=310260130369278
2014-11-06 13:04:43.950 [232] Flow DbSender Successfully sent request RequestHolder [Notification name=TerminalSwitch_Post, URL=http://XXXXXX-priv-opm:9010/opm/sg/notification, Method=GET, ContentType=application/x-www-form-urlencoded, Url parameters=SG.IMSI=310260130369278,

===

So only analyze IMSIs with only one pair of the lines below, if there more than one pair, ignore both of them...
2014-11-04 00:19:36.183 [164] Debug HttpReceiverServlet Incoming request url : http://otasnq-nmnet-nfce:7900/httpeventadapter/SP_ADD/httpAdapter/ST.TERMINAL_SWITCH query string ST.IMSI=310260567661995&ST.IMEI=86458702147373

And several lines like this:
2014-11-04 00:19:51.625 [232] Flow DbSender Successfully sent request RequestHolder [Notification name=TerminalSwitch_Post, URL=http://XXXXXX-priv-opm:9010/opm/sg/notification, Method=GET, ContentType=application/x-www-form-urlencoded, Url parameters=SG.IMSI=310260567661995,

ozo

I'm not sure I understand. Could you give a small example of a complete log file with the output you would want to produce from it?

joaotelles

ASKER

Ok.. Sry...

In the logs I have several lines like this:
2014-10-31 06:52:35.619 [79] Debug HttpReceiverServlet Incoming request url : http://otablv-priv-nfcmh-vip:7900/httpeventadapter/SP_ADD/httpAdapter/ST.TERMINAL_SWITCH query string ST.IMSI=310260112638088&ST.IMEI=35881005000146
2014-10-31 06:52:35.622 [75] Debug HttpReceiverServlet Incoming request url : http://otablv-priv-nfcmh-vip:7900/httpeventadapter/SP_ADD/httpAdapter/ST.TERMINAL_SWITCH query string ST.IMSI=310260112637956&ST.IMEI=35881005000178
2014-10-31 06:52:35.682 [75] Debug HttpReceiverServlet Incoming request url : http://otablv-priv-nfcmh-vip:7900/httpeventadapter/SP_ADD/httpAdapter/ST.TERMINAL_SWITCH query string ST.IMSI=310260502806226&ST.IMEI=35881005000159
2014-10-31 06:52:35.696 [75] Debug HttpReceiverServlet Incoming request url : http://otablv-priv-nfcmh-vip:7900/httpeventadapter/SP_ADD/httpAdapter/ST.TERMINAL_SWITCH query string ST.IMSI=310260220831752&ST.IMEI=35881005000190

And several lines like this:
2014-10-31 06:53:54.662 [36] Flow DbSender Successfully sent request RequestHolder [Notification name=TerminalSwitch_Post, URL=http://otablv-snq-opm-vip:9010/opm/sg/notification, Method=GET, ContentType=application/x-www-form-urlencoded, Url parameters=SG.IMSI=310260902527165,
2014-10-31 06:53:54.773 [36] Flow DbSender Successfully sent request RequestHolder [Notification name=TerminalSwitch_Post, URL=http://otablv-snq-opm-vip:9010/opm/sg/notification, Method=GET, ContentType=application/x-www-form-urlencoded, Url parameters=SG.IMSI=310260612012289,
2014-10-31 06:53:54.899 [36] Flow DbSender Successfully sent request RequestHolder [Notification name=TerminalSwitch_Post, URL=http://otablv-snq-opm-vip:9010/opm/sg/notification, Method=GET, ContentType=application/x-www-form-urlencoded, Url parameters=SG.IMSI=310260612012237,
2014-10-31 06:53:54.972 [36] Flow DbSender Successfully sent request RequestHolder [Notification name=TerminalSwitch_Post, URL=http://otablv-snq-opm-vip:9010/opm/sg/notification, Method=GET, ContentType=application/x-www-form-urlencoded, Url parameters=SG.IMSI=310260112633332,

The thing is for the same IMSI I can have more than one pair of Incoming line and Successfully sent request line.

For example for this one I have only a pair, so this would be taking in consideration for the script to count the time between the lines:
2014-10-31 06:53:22.501 [83] Debug HttpReceiverServlet Incoming request url : http://otablv-priv-nfcmh-vip:7900/httpeventadapter/SP_ADD/httpAdapter/ST.TERMINAL_SWITCH query string ST.IMSI=310260112633332&ST.IMEI=35881005000914

2014-10-31 06:53:54.972 [36] Flow DbSender Successfully sent request RequestHolder [Notification name=TerminalSwitch_Post, URL=http://otablv-snq-opm-vip:9010/opm/sg/notification, Method=GET, ContentType=application/x-www-form-urlencoded, Url parameters=SG.IMSI=310260112633332,

====

But for example on this case:

2014-11-06 12:54:33.481 [46] Debug HttpReceiverServlet Incoming request url : http://XXXXXX-nmnet-nfce:7900/httpeventadapter/SP_ADD/httpAdapter/ST.TERMINAL_SWITCH query string ST.IMSI=310260130369278&ST.IMEI=01262600179856
2014-11-06 12:59:05.874 [52] Debug HttpReceiverServlet Incoming request url : http://XXXXXX-nmnet-nfce:7900/httpeventadapter/SP_ADD/httpAdapter/ST.TERMINAL_SWITCH query string ST.IMSI=310260130369278&ST.IMEI=01262600179888

2014-11-06 13:04:43.950 [232] Flow DbSender Successfully sent request RequestHolder [Notification name=TerminalSwitch_Post, URL=http://XXXXXX-priv-opm:9010/opm/sg/notification, Method=GET, ContentType=application/x-www-form-urlencoded, Url parameters=SG.IMSI=310260130369278,

All these lines would be ignored by the script (not taken in consideration for the final count in the output)

===

So I think this would require a check to see if the IMSI only appear in one pair (to be used) or in several (to be ignored)...

NOTE that the IMSI appear in other lines that are to be ignored... so a grep on a IMSI can have more lines that are not in use for this script as well... like:
2014-10-31 06:53:22.846 [100] Trace SubscriptionDetectionChunk Subscription detection for subscription id 12065088, msisdn 18588919955, imsi 089310260902669658, imei 35881005000916, iccid null. Result: 15

Tks,
jaoo

joaotelles

ASKER

Hi Ozo,

Pls le me know if the description was good or need more detail...

Tks in advance.
Joao

joaotelles

ASKER

Tks