Shell script to append a time for the existing error log file

Hi Guys,

the requirement is like this,
i am having a error log file in this format,

[INFO ][memory ] 4594.493: parallel nursery GC 2594592K->2544691K (2969600K), 30.848 ms
[INFO ][memory ] 4605.958: parallel nursery GC 2634887K->2584986K (2969600K), 38.900 ms
[INFO ][memory ] 4619.079: parallel nursery GC 2822555K->2774812K (2969600K), 51.526 ms
[INFO ][memory ] 4623.784: parallel nursery GC 2911872K->2862488K (2969600K), 43.049 ms
[INFO ][memory ] 4634.298: parallel nursery GC 2964037K->2915007K (2969600K), 44.723 ms
[INFO ][memory ] 4642.754-4644.124: GC 2969600K->745408K (2969600K), 1369.515 ms
[INFO ][memory ] 4657.312: parallel nursery GC 843925K->792192K (2969600K), 59.318 ms
[INFO ][memory ] 4667.661: parallel nursery GC 1023736K->973165K (2969600K), 54.639 ms
[INFO ][memory ] 4683.479: parallel nursery GC 1079790K->1028927K (2969600K), 57.430 ms
[INFO ][memory ] 4703.120: parallel nursery GC 1155728K->1104405K (2969600K), 48.580 ms
[INFO ][memory ] 4721.076: parallel nursery GC 1381399K->1331594K (2969600K), 67.131 ms
[INFO ][memory ] 4733.124: parallel nursery GC 1615502K->1565673K (2969600K), 67.668 ms
[INFO ][memory ] 4735.932: parallel nursery GC 1868345K->1818182K (2969600K), 60.527 ms
[INFO ][memory ] 4740.485: parallel nursery GC 1904639K->1852524K (2969600K), 39.426 ms
[INFO ][memory ] 4748.902: parallel nursery GC 1931641K->1880332K (2969600K), 45.826 ms
[INFO ][memory ] 4749.369: parallel nursery GC 1992582K->1939949K (2969600K), 40.806 ms
[INFO ][memory ] 4754.434: parallel nursery GC 2180168K->2130041K (2969600K), 49.643 ms
[INFO ][memory ] 4773.739: parallel nursery GC 2184441K->2132628K (2969600K), 47.404 ms
[INFO ][memory ] 4793.466: parallel nursery GC 2488886K->2439957K (2969600K), 65.046 ms
[INFO ][memory ] 4825.436: parallel nursery GC 2539740K->2489040K (2969600K), 57.110 ms
[INFO ][memory ] 4829.277: parallel nursery GC 2668261K->2617286K (2969600K), 44.117 ms
[INFO ][memory ] 4835.849: parallel nursery GC 2671686K->2619201K (2969600K), 37.932 ms
[INFO ][memory ] 4849.233: parallel nursery GC 2781360K->2730476K (2969600K), 47.521 ms
[INFO ][memory ] 4870.198: parallel nursery GC 2902826K->2851834K (2969600K), 56.248 ms
[INFO ][memory ] 4873.277-4874.744: GC 2947600K->754541K (2969600K), 1467.026 ms
[INFO ][memory ] 4876.460: parallel nursery GC 824428K->769741K (2969600K), 146.708 ms
[INFO ][memory ] 4888.450: parallel nursery GC 916812K->862855K (2969600K), 46.349 ms
[INFO ][memory ] 4902.871: parallel nursery GC 992190K->936997K (2969600K), 30.377 ms
[INFO ][memory ] 4907.508: parallel nursery GC 1167917K->1115851K (2969600K), 63.247 ms
[INFO ][memory ] 4933.191: parallel nursery GC 1293112K->1239053K (2969600K), 51.764 ms
[INFO ][memory ] 4939.716: parallel nursery GC 1339610K->1284920K (2969600K), 41.355 ms

this file will go on displaying all the nursery GC, only 'GC'.

the main aim is that , error log file goes on generating output from weblogic as shown above, we want to take the timespan between two GC's

i.e
[INFO ][memory ] 4642.754-4644.124: GC 2969600K->745408K (2969600K), 1369.515 ms

so i want a script to append time at the end of the line i.e after 'ms'

so will anyone help me out with a script for the above requirement
(atleast suggestions are welcomed)

Which time you want to append? Can you show the output required?

[INFO ][memory ] 4634.298: parallel nursery GC 2964037K->2915007K (2969600K), 44.723 ms
[INFO ][memory ] 4642.754-4644.124: GC 2969600K->745408K (2969600K), 1369.515 ms
[INFO ][memory ] 4657.312: parallel nursery GC 843925K->792192K (2969600K), 59.318 ms

so here one thing to know is :

main GC = [INFO ][memory ] 4642.754-4644.124: GC 2969600K->745408K (2969600K), 1369.515 ms

nursery GC= [INFO ][memory ] 4657.312: parallel nursery GC 843925K->792192K (2969600K), 59.318 ms

so i want to append time to the above data, and the output should be:

[INFO ][memory ] 4642.754-4644.124: GC 2969600K->745408K (2969600K), 1369.515 ms 23:19:32 2007

i.e at the end of the above line it is appended by time as 23:19:32 2007

i had written a script ,

tail -f /filers/f08-perf01/logFiles/wcluster/websites01-perf-1-8901/NodeManagerLogs/cobaltgroup_websites01-perf-1-8901/websites01-perf-1-8901_error.log |grep -v nursery > /home/readonly/g2
date "+%H:%M:%S" >> /home/readonly/g2
cat /home/readonly/g2

or
cd /filers/f08-perf01/logFiles/wcluster/websites01-perf-1-8901/NodeManagerLogs/cobaltgroup_websites01-perf-1-8901/
v1=`tail -f websites01-perf-1-8901_error.log|grep -ivn 'nursery'`
v2=`date "+%H:%M:%S"`
echo $v1 $v2

given executable permission to the file also, but still unable to print the output as
[INFO ][memory ] 4642.754-4644.124: GC 2969600K->745408K (2969600K), 1369.515 ms 23:19:32 2007

awk -v var="23:19:32 2007" ' !/parallel nursery GC/ && /GC/ { $0=$0 " " var } ; 1' filename

awk -v var="23:19:32 2007" ' !/parallel nursery GC/ && /GC/ { $0=$0 " " var } ; 1' filename

here in place of 23:19:32 2007 it should be replaced by system time
that is by making use of date command

also it will be better if u explain ur script,
as i am not much familiar with awk script

awk -v var="$( date +%H":"%M":"%S" "%Y )" ' !/parallel nursery GC/ && /GC/ { $0=$0 " " var } ; 1' filename

Awk read the file line by line and process it.
!/parallel nursery GC/ ! negates the pattern i.e if the line does not contain pattern "parallel nursery GC"

!/parallel nursery GC/ && /GC/ If a line does not contain !/parallel nursery GC/ and contain GC then execute statements in { .. }

$0 contain the current line read from the file.

$0=$0 " " var Append the date

1 means true and print the line

Check man awk and tutorials available in net to know more about awk

Hi anbu23 (will u let me know ur name)

i am prasanna kumar from bangalore

i executed the script
awk -v var="$( date +%H":"%M":"%S" "%Y )" ' !/parallel nursery GC/ && /GC/ { $0=$0 " " var } ; 1' prasanna

where prasanna is a file that contains

[INFO ][memory ] 4149.021: parallel nursery GC 2701220K->2655828K (2969600K), 30.574 ms
[INFO ][memory ] 4154.677: parallel nursery GC 2703428K->2657717K (2969600K), 28.287 ms
[INFO ][memory ] 4158.415: parallel nursery GC 2758546K->2712930K (2969600K), 32.175 ms
[INFO ][memory ] 4162.587: parallel nursery GC 2782109K->2736294K (2969600K), 25.666 ms
[INFO ][memory ] 4169.850: parallel nursery GC 2874669K->2829815K (2969600K), 36.132 ms
[INFO ][memory ] 4172.303-4173.282: GC 2942000K->678250K (2969600K), 979.049 ms
[INFO ][memory ] 4176.626: parallel nursery GC 770077K->723185K (2969600K), 41.395 ms
[INFO ][memory ] 4178.411: parallel nursery GC 793823K->745922K (2969600K), 27.153 ms
[INFO ][memory ] 4187.052: parallel nursery GC 810797K->763420K (2969600K), 27.971 ms
[INFO ][memory ] 4192.911: parallel nursery GC 836546K->788468K (2969600K), 24.864 ms
[INFO ][memory ] 4207.717: parallel nursery GC 954934K->909305K (2969600K), 58.163 ms
[INFO ][memory ] 4220.734: parallel nursery GC 1074869K->1027949K (2969600K), 41.402 ms
[INFO ][memory ] 4223.611: parallel nursery GC 1280344K->1234402K (2969600K), 48.997 ms
[INFO ][memory ] 4226.224: parallel nursery GC 1294774K->1247317K (2969600K), 32.585 ms
[INFO ][memory ] 4227.747: parallel nursery GC 1340665K->1293317K (2969600K), 36.518 ms
[INFO ][memory ] 4231.858: parallel nursery GC 1342917K->1295134K (2969600K), 26.400 ms
[INFO ][memory ] 4237.341: parallel nursery GC 1382464K->1334959K (2969600K), 28.912 ms
[INFO ][memory ] 4244.508: parallel nursery GC 1418893K->1371117K (2969600K), 27.960 ms
[INFO ][memory ] 4250.090: parallel nursery GC 1506707K->1460215K (2969600K), 41.302 ms
[INFO ][memory ] 4253.633: parallel nursery GC 1601128K->1554403K (2969600K), 41.705 ms
[INFO ][memory ] 4256.931: parallel nursery GC 1642007K->1594365K (2969600K), 35.355 ms
[INFO ][memory ] 4262.884: parallel nursery GC 1666922K->1619762K (2969600K), 34.114 ms
[INFO ][memory ] 4266.360: parallel nursery GC 1800444K->1753342K (2969600K), 35.357 ms
[INFO ][memory ] 4272.192: parallel nursery GC 1802942K->1755681K (2969600K), 34.750 ms
[INFO ][memory ] 4280.558: parallel nursery GC 1949104K->1903450K (2969600K), 48.986 ms
[INFO ][memory ] 4287.625: parallel nursery GC 2177829K->2131864K (2969600K), 54.820 ms
[INFO ][memory ] 4290.519: parallel nursery GC 2292667K->2246419K (2969600K), 45.289 ms
[INFO ][memory ] 4293.266: parallel nursery GC 2348322K->2301095K (2969600K), 40.879 ms
[INFO ][memory ] 4297.969: parallel nursery GC 2449739K->2403340K (2969600K), 45.764 ms
[INFO ][memory ] 4300.545: parallel nursery GC 2551023K->2504987K (2969600K), 47.164 ms
[INFO ][memory ] 4302.757: parallel nursery GC 2634647K->2587589K (2969600K), 37.921 ms
[INFO ][memory ] 4305.395: parallel nursery GC 2732599K->2685257K (2969600K), 33.979 ms
[INFO ][memory ] 4306.887: parallel nursery GC 2782062K->2734709K (2969600K), 37.463 ms
[INFO ][memory ] 4311.359: parallel nursery GC 2802868K->2755475K (2969600K), 40.694 ms
[INFO ][memory ] 4315.468: parallel nursery GC 2822175K->2774396K (2969600K), 32.332 ms
[INFO ][memory ] 4316.459: parallel nursery GC 2823996K->2775766K (2969600K), 27.037 ms
[INFO ][memory ] 4317.393: parallel nursery GC 2841257K->2792598K (2969600K), 18.883 ms
[INFO ][memory ] 4321.665-4322.667: GC 2969600K->737073K (2969600K), 1001.966 ms
[INFO ][memory ] 4329.551: parallel nursery GC 916745K->867854K (2969600K), 151.006 ms
[INFO ][memory ] 4332.423: parallel nursery GC 959372K->909114K (2969600K), 29.651 ms
[INFO ][memory ] 4336.080: parallel nursery GC 994303K->944903K (2969600K), 34.629 ms
[INFO ][memory ] 4339.405: parallel nursery GC 996903K->946451K (2969600K), 34.027 ms
[INFO ][memory ] 4345.775: parallel nursery GC 1054838K->1005315K (2969600K), 33.624 ms
[INFO ][memory ] 4355.028: parallel nursery GC 1106687K->1057153K (2969600K), 45.812 ms
[INFO ][memory ] 4362.651: parallel nursery GC 1130232K->1080475K (2969600K), 32.335 ms
[INFO ][memory ] 4372.657: parallel nursery GC 1165734K->1116103K (2969600K), 36.189 ms

it shows error message as
illegal variable name

and also as u said,
!/parallel nursery GC/ && /GC/ If a line does not contain !/parallel nursery GC/ and contain GC then execute statements in { .. }

but every line contain GC, so how can it be

But at first i am thankful to u for ur patience and trying to help me out.....

I am not sure why you get that error message. Its working fine for me. Try to copy as such and run it.

$ awk -v var="$( date +%H":"%M":"%S" "%Y )" ' !/parallel nursery GC/ && /GC/ { $0=$0 " " var } ; 1' filename
[INFO ][memory ] 4594.493: parallel nursery GC 2594592K->2544691K (2969600K), 30.848 ms
[INFO ][memory ] 4605.958: parallel nursery GC 2634887K->2584986K (2969600K), 38.900 ms
[INFO ][memory ] 4619.079: parallel nursery GC 2822555K->2774812K (2969600K), 51.526 ms
[INFO ][memory ] 4623.784: parallel nursery GC 2911872K->2862488K (2969600K), 43.049 ms
[INFO ][memory ] 4634.298: parallel nursery GC 2964037K->2915007K (2969600K), 44.723 ms
[INFO ][memory ] 4642.754-4644.124: GC 2969600K->745408K (2969600K), 1369.515 ms 13:07:23 2007
[INFO ][memory ] 4657.312: parallel nursery GC 843925K->792192K (2969600K), 59.318 ms
[INFO ][memory ] 4667.661: parallel nursery GC 1023736K->973165K (2969600K), 54.639 ms
[INFO ][memory ] 4683.479: parallel nursery GC 1079790K->1028927K (2969600K), 57.430 ms
[INFO ][memory ] 4703.120: parallel nursery GC 1155728K->1104405K (2969600K), 48.580 ms
[INFO ][memory ] 4721.076: parallel nursery GC 1381399K->1331594K (2969600K), 67.131 ms
[INFO ][memory ] 4733.124: parallel nursery GC 1615502K->1565673K (2969600K), 67.668 ms
[INFO ][memory ] 4735.932: parallel nursery GC 1868345K->1818182K (2969600K), 60.527 ms
[INFO ][memory ] 4740.485: parallel nursery GC 1904639K->1852524K (2969600K), 39.426 ms
[INFO ][memory ] 4748.902: parallel nursery GC 1931641K->1880332K (2969600K), 45.826 ms
[INFO ][memory ] 4749.369: parallel nursery GC 1992582K->1939949K (2969600K), 40.806 ms
[INFO ][memory ] 4754.434: parallel nursery GC 2180168K->2130041K (2969600K), 49.643 ms
[INFO ][memory ] 4773.739: parallel nursery GC 2184441K->2132628K (2969600K), 47.404 ms
[INFO ][memory ] 4793.466: parallel nursery GC 2488886K->2439957K (2969600K), 65.046 ms
[INFO ][memory ] 4825.436: parallel nursery GC 2539740K->2489040K (2969600K), 57.110 ms
[INFO ][memory ] 4829.277: parallel nursery GC 2668261K->2617286K (2969600K), 44.117 ms
[INFO ][memory ] 4835.849: parallel nursery GC 2671686K->2619201K (2969600K), 37.932 ms
[INFO ][memory ] 4849.233: parallel nursery GC 2781360K->2730476K (2969600K), 47.521 ms
[INFO ][memory ] 4870.198: parallel nursery GC 2902826K->2851834K (2969600K), 56.248 ms
[INFO ][memory ] 4873.277-4874.744: GC 2947600K->754541K (2969600K), 1467.026 ms 13:07:23 2007
[INFO ][memory ] 4876.460: parallel nursery GC 824428K->769741K (2969600K), 146.708 ms
[INFO ][memory ] 4888.450: parallel nursery GC 916812K->862855K (2969600K), 46.349 ms
[INFO ][memory ] 4902.871: parallel nursery GC 992190K->936997K (2969600K), 30.377 ms
[INFO ][memory ] 4907.508: parallel nursery GC 1167917K->1115851K (2969600K), 63.247 ms
[INFO ][memory ] 4933.191: parallel nursery GC 1293112K->1239053K (2969600K), 51.764 ms
[INFO ][memory ] 4939.716: parallel nursery GC 1339610K->1284920K (2969600K), 41.355 ms

GC is present in all the lines. So to differentiate main and nursery, !/parallel nursery GC/ is enough. But if you have any lines that does not contain GC will also satisfy this. So to avoid these lines i added /GC/.

Hi Anbu,
Thanks for your help,
i got the solution why the script is not executing ,because i am executing the script in tcsh so it displays as illegal error,

so i changed to sh and tried to execute as follows , it displays static time instead of displaying dynamic time for the corresponding dynamic data generation as shown below,

tail -f filename_error.log|awk -v var="$( date +%H":"%M":"%S" "%Y )" ' /parallel nursery GC/ || /GC/ { $0=$0 " " var } ; 1'
[INFO ][memory ] 7654.644: parallel nursery GC 1613483K->1441609K (2969600K), 58.004 ms 01:40:38 2007
[INFO ][memory ] 7672.245: parallel nursery GC 1636286K->1464021K (2969600K), 59.238 ms 01:40:38 2007
[INFO ][memory ] 7680.216: parallel nursery GC 1667206K->1494772K (2969600K), 58.330 ms 01:40:38 2007
[INFO ][memory ] 7691.249: parallel nursery GC 1691520K->1519101K (2969600K), 52.770 ms 01:40:38 2007
[INFO ][memory ] 7698.657: parallel nursery GC 1709864K->1537607K (2969600K), 52.452 ms 01:40:38 2007
[INFO ][memory ] 7705.461: parallel nursery GC 1760051K->1587293K (2969600K), 53.754 ms 01:40:38 2007
[INFO ][memory ] 7713.707: parallel nursery GC 1803076K->1630709K (2969600K), 52.372 ms 01:40:38 2007
[INFO ][memory ] 7719.741: parallel nursery GC 1807109K->1634757K (2969600K), 55.545 ms 01:40:38 2007
[INFO ][memory ] 7725.737: parallel nursery GC 1852025K->1679291K (2969600K), 48.950 ms 01:40:38 2007
[INFO ][memory ] 7731.315: parallel nursery GC 1855691K->1683135K (2969600K), 50.994 ms 01:40:38 2007
[INFO ][memory ] 7738.187: parallel nursery GC 1889400K->1717128K (2969600K), 54.150 ms 01:40:38 2007

Hi Anbu,
Thanks for your help,
i got the solution why the script is not executing ,because i am executing the script in tcsh so it displays as illegal error,

so i changed to sh and tried to execute as follows , it displays static time instead of displaying dynamic time for the corresponding dynamic data generation as shown below,

tail -f filename_error.log|awk -v var="$( date +%H":"%M":"%S" "%Y )" ' /parallel nursery GC/ || /GC/ { $0=$0 " " var } ; 1'
[INFO ][memory ] 7654.644: parallel nursery GC 1613483K->1441609K (2969600K), 58.004 ms 01:40:38 2007
[INFO ][memory ] 7672.245: parallel nursery GC 1636286K->1464021K (2969600K), 59.238 ms 01:40:38 2007
[INFO ][memory ] 7680.216: parallel nursery GC 1667206K->1494772K (2969600K), 58.330 ms 01:40:38 2007
[INFO ][memory ] 7691.249: parallel nursery GC 1691520K->1519101K (2969600K), 52.770 ms 01:40:38 2007
[INFO ][memory ] 7698.657: parallel nursery GC 1709864K->1537607K (2969600K), 52.452 ms 01:40:38 2007
[INFO ][memory ] 7705.461: parallel nursery GC 1760051K->1587293K (2969600K), 53.754 ms 01:40:38 2007
[INFO ][memory ] 7713.707: parallel nursery GC 1803076K->1630709K (2969600K), 52.372 ms 01:40:38 2007
[INFO ][memory ] 7719.741: parallel nursery GC 1807109K->1634757K (2969600K), 55.545 ms 01:40:38 2007
[INFO ][memory ] 7725.737: parallel nursery GC 1852025K->1679291K (2969600K), 48.950 ms 01:40:38 2007
[INFO ][memory ] 7731.315: parallel nursery GC 1855691K->1683135K (2969600K), 50.994 ms 01:40:38 2007
[INFO ][memory ] 7738.187: parallel nursery GC 1889400K->1717128K (2969600K), 54.150 ms 01:40:38 2007

is there any another to get the dynamic time generation to append for an dynamic data generation..................waiting for ur valuable suggestions........

awk ' /parallel nursery GC/ || /GC/ { "date +%H\":\"%M\":\"%S\" \"%Y" | getline var; $0=$0 " " var} ; 1' file