[Shell/Perl(?)] Prepending timestamps to console output & writing results to a file

Shell Programming and Scripting
1

I do a lot of TSM work and I embarked on what I thought would be an easy task, and I'd be very happy for any input to save the pounding my keyboard is receiving :]

By default, the output of TSM's console has no timestamping, making it hard to sort through accurately.

This puts my console into a file continously:

${DSMPath} -id=${TivUser} -password=${TivPassword} -console 1>/tmp/out.file 2>&1 &

That works, no problems there. The log looks like this:

IBM Tivoli Storage Manager
Command Line Administrative Interface - Version 6, Release 2, Level 1.0
(c) Copyright by IBM Corporation and other(s) 1990, 2010. All Rights Reserved.

Session established with server TSM1_TIVOLI1: AIX
  Server Version 6, Release 2, Level 2.0
  Server date/time: 05/26/12   15:06:16  Last access: 05/26/12   15:00:00

ANR1041I Space reclamation ended for volume NC0657L3.
ANR0568W Session 76132 for admin XXX (AIX) terminated - connection with client severed.
ANR8216W The server experienced a TCP/IP error while sending data on socket 176.  Reason 32.
ANR1040I Space reclamation started for volume 1988AFL3, storage pool TAPEPOOL (process number 1276).
ANR1044I Removable volume 1988AFL3 is required for space reclamation.
ANR1176I Moving data for collocation set 1 of 1 on volume 1988AFL3.
ANR0515I Process 1276 closed volume 1422AFL3.
ANR0407I Session 76170 started for administrator XXX (AIX) (Tcp/Ip tivoli2(58522)).
ANR2017I Administrator XXX issued command: QUERY MOUNT
ANR8330I LTO volume 2126AFL3 is mounted R/W in drive DRIVE08 (/dev/rmt8), status: IN USE.
ANR8330I LTO volume 004AAFL3 is mounted R/W in drive DRIVE04 (/dev/rmt4), status: IN USE.
ANR8329I LTO volume NC0657L3 is mounted R/O in drive DRIVE02 (/dev/rmt2), status: IDLE.
ANR8330I LTO volume 1782AFL3 is mounted R/O in drive DRIVE06 (/dev/rmt6), status: IN USE.
ANR8330I LTO volume 1639AFL3 is mounted R/W in drive DRIVE09 (/dev/rmt9), status: IN USE.
ANR8330I LTO volume 011AAFL3 is mounted R/W in drive DRIVE11 (/dev/rmt11), status: IN USE.
ANR8330I LTO volume 2095AFL3 is mounted R/W in drive DRIVE07 (/dev/rmt7), status: IN USE.
ANR8330I LTO volume NC0377L3 is mounted R/W in drive DRIVE12 (/dev/rmt12), status: IN USE.
ANR8329I LTO volume 1422AFL3 is mounted R/W in drive DRIVE05 (/dev/rmt5), status: IDLE.
ANR8330I LTO volume 948AAFL3 is mounted R/W in drive DRIVE10 (/dev/rmt10), status: IN USE.
ANR8330I LTO volume 052AAFL3 is mounted R/O in drive DRIVE03 (/dev/rmt3), status: IN USE.
ANR8376I Mount point reserved in device class LTO2DEVCLASS, status: RESERVED.
ANR8379I Mount point in device class LTO2DEVCLASS is waiting for the volume mount to complete, status: WAITING FOR VOLUME.
ANR8334I         13 matches found.

The following snippet works - to my screen, and I can't for the life of me get it to output to a file. I know tail -f mucks with my ability to continue piping, but my attempts at adding a file handle to my perl print to output there all failed miserably (I'm very bad/novice level with perl).

tail -f /tmp/out.file | perl -pne '@tm = localtime; printf ("%02d:%02d:%02d ",@tm[2],@tm[1],@tm[0]);

On my screen - it looks like this now (Which is as intended):

15:06:20 IBM Tivoli Storage Manager
15:06:20 Command Line Administrative Interface - Version 6, Release 2, Level 1.0
15:06:20 (c) Copyright by IBM Corporation and other(s) 1990, 2010. All Rights Reserved.
15:06:20
15:06:23 Session established with server TSM1_TIVOLI1: AIX
15:06:23   Server Version 6, Release 2, Level 2.0
15:06:23   Server date/time: 05/26/12   15:06:16  Last access: 05/26/12   15:00:00
15:06:23
15:06:23 ANR0515I Process 1276 closed volume NC0657L3.
15:06:23 ANR8216W The server experienced a TCP/IP error while sending data on socket 176.  Reason 32.
15:06:23 ANR1041I Space reclamation ended for volume NC0657L3.
15:06:23 ANR0568W Session 76132 for admin XXX (AIX) terminated - connection with client severed.
15:06:23 ANR8216W The server experienced a TCP/IP error while sending data on socket 176.  Reason 32.
15:06:23 ANR1040I Space reclamation started for volume 1988AFL3, storage pool TAPEPOOL (process number 1276).
15:06:23 ANR1044I Removable volume 1988AFL3 is required for space reclamation.
15:06:23 ANR1176I Moving data for collocation set 1 of 1 on volume 1988AFL3.
15:06:26 ANR0515I Process 1276 closed volume 1422AFL3.
15:06:28 ANR0407I Session 76170 started for administrator TIPADMIN (AIX) (Tcp/Ip tivoli2(58522)).
15:06:28 ANR2017I Administrator XXX issued command: QUERY MOUNT
15:06:28 ANR8330I LTO volume 2126AFL3 is mounted R/W in drive DRIVE08 (/dev/rmt8), status: IN USE.
15:06:28 ANR8330I LTO volume 004AAFL3 is mounted R/W in drive DRIVE04 (/dev/rmt4), status: IN USE.
15:06:28 ANR8329I LTO volume NC0657L3 is mounted R/O in drive DRIVE02 (/dev/rmt2), status: IDLE.
15:06:28 ANR8330I LTO volume 1782AFL3 is mounted R/O in drive DRIVE06 (/dev/rmt6), status: IN USE.

Would dearly appreciate any help - I'm pretty sure the right answer is to get the print statement going to a file, but I'm just having zero luck. If I do -not- have the right answer, I don't care how I get there, but the above is what I want (Just going to keep 7 files with the days of the weeks worth of console logs, nothing super complicated).

Version Info:
Perl

$ perl -v

This is perl, v5.8.8 built for aix-thread-multi

Copyright 1987-2006, Larry Wall

Perl may be copied only under the terms of either the Artistic License or the
GNU General Public License, which may be found in the Perl 5 source kit.

Complete documentation for Perl, including FAQ lists, should be found on
this system using "man perl" or "perldoc perl".  If you have access to the
Internet, point your browser at http://www.perl.org/, the Perl Home Page.

AIX

# oslevel -s
6100-04-03-1009

Thanks for your time and any help that can be provided.

2

Hi Vryali,

Try this way. Substitute tail -f $ARGV[1] with your TSM command and the script will write output to first parameter file in command line with date inserted at the beginning of each line.

$ cat script.pl
use warnings;
use strict;

open my $ofh, qq/>/, $ARGV[0] or die $!;
select $ofh;
$| = 1;
select \*STDOUT;

open my $fh, qq/-|/, qq/tail -f $ARGV[1]/ or die $!;

while ( <$fh> ) {
        chomp;
        my @t = (localtime)[2, 1, 0];
        printf $ofh qq/%02d:%02d:%02d %s\n/, @t, $_;
}
$ perl script.pl outfile infile
1 Like
3

Can you not just pipe it through your perl programme on the way to the output file? Using awk (I don't do perl) it'd be something like this:

${DSMPath} -id=${TivUser} -password=${TivPassword} -console 2>&1 | awk 'BEGIN { c = "date \"+%D %T\""; } { m=$0; c | getline; close( c ); print $0, m; }' >output &

Test with a simple construct:

ps -elf | awk 'BEGIN { c = "date \"+%D %T\""; } { m=$0; c | getline; close( c ); print $0, m; }' >output &

This will execute quickly enough that I'd expect all timestamps to have the same value, but you'll see that it works.

1 Like
4

Thanks for the responses, but the second one seemed a little easier for me to work with, so I tried that out and it did work as desired.

The only problem I had was with the output to a file instead of STDOUT - no real idea why. Had tried it all as a one-liner like you recommend but it crapped out, so I tried doing it through tail to make it as bland as possible.

That said, your fix works, thanks so much! Would you mind explaining a tiny snippet?

 ...; c | getline; close( c ); ...

Is that just prepending c to $0, basically, and if so, why does it need a close, I don't see an open?

Thanks!

5

Glad it worked. The line you asked about can be confusing.

The variable 'c' is assigned a command and as a result the construct c | getline basically causes awk to execute a popen() call (pipe open) which executes the command in a child process and pipes the results from that command back to awk. The first line of the output from the command is read by the getline, and since no variable is defined, it is parsed into the standard $0, $1... parameters. If a second getline is used with the same command it would attempt to read the next line of input from the command. This would result in and end of file as the date command returns only one line. So, the command must be closed in order for the next to be successful.

Behind the scenes awk maps the command to the file descriptor, so to close the descriptor the command string must be given to the close() function. This is easiest by assigning the command to a variable.

Hope this makes sense.

---------- Post updated at 00:23 ---------- Previous update was at 00:14 ----------

Found a bit more of a description that might do a better job than the paragraph I posted:

Close Files And Pipes - The GNU Awk User's Guide

1 Like
6

Makes sense - I've bookmarked the other bit for reading when I'm more awake.

Wanted to come back and post my script, in case anyone had a use for them courtesy of the google machine later. There isn't a lot to it, and the hard part isn't mine per se, but here we go. Should work on any system with TSM server installed (Except Windows, but if you installed TSM on Windows, that's your own damn fault :])

#!/bin/sh
###############################################################################
#                                                                             #
#  Script Name: TSM-Console.sh                                                #
#  Created on : 05/26/2012                                                    #
#  Author     : Vryali                                                        #
#  Purpose    : Allow for console logging, which is normally more succint and #
#       easier to parse than the actlog, and keep seven days worth of logging.#
#  Note       : This script can be run through the crontab or AutoSys.        #
#  Cron                                                                       #
#       0 0 * * * /usr/local/bin/TSM-LogConsole.sh 1>/dev/null 2>&1           #
#  AutoSys/JIL                                                                #
#   insert_job: SA.TSM.LogConsole                                             #
#   command: /jobs/SA/prod/Prod_Run tsm@tivoli /usr/local/bin/TSM-Console.sh  #
#   permission: gx,wx                                                         #
#   date_conditions: 1                                                        #
#   days_of_week: all                                                         #
#   start_times: "00:01"                                                      #
#   description: "TSM Console Logging Script"                                 #
#   alarm_if_fail: 1                                                          #
#                                                                             #
#  History:                                                                   #
#  00 : Vryali     05/21/2012                                                 #
#       Original version of the script completed.                             #
#                                                                             #
###############################################################################

DSM="/usr/bin/dsmadmc"
TSMUser="username"
TSMPass="password"
PIDFile="/var/run/tsmconsole.pid"
CONLOG="/TSM/home/CONSOLE_LOG/`date +%a`-Console.log"

if [ -s ${PIDFile} ]; then
    cat ${PIDFile} | xargs kill -9
    cp /dev/null ${PIDFile}
fi

# Clear up the old one [if needed] but keep permissions...
cp /dev/null ${CONLOG}

# Start logging
nohup ${DSM} -id=${TSMUser} -pass=${TSMPass} -console| awk 'BEGIN { c = "date \"+%D %T\""; } { m=$0; c | getline; close( c ); print $0, m; }' >> ${CONLOG} 2>&1 &
# $! is actually awk - not DSM, so we'll filter out $$ - which is the subshell before we exit it.
ps -ef| grep $! | grep -v grep | grep -v $$ | awk '{print $2}' > ${PIDFile}
exit 0