# # Copyright (c) 2001-2013 NetApp, Inc., All Rights Reserved # Any use, modification, or distribution is prohibited # without prior written consent from NetApp, Inc. # ## @summary SystemLogDetector Task Module ## @author dl-nacl-dev@netapp.com ## @status shared ## @pod here =head1 NAME NACL::MTask::SystemLogDetector =head1 DESCRIPTION This task is to be used for validating the system logs for presence or absence of given message/regex. Many testcases require verification that certain system log messages have or have not been triggered. This package provides methods for selecting the time ranges between which the system log messages will be verified (for presence/absence) of the given message or regex and also gives the options for message should come in future n seconds via `wait_for_log` option. This task supports CLI interface only. System log example: Here 'license.db.migrate.vol.success' is the system log messsage. 00000011.0002aa11 0162411b Tue Jun 28 2011 05:28:25 -04:00 [license.db.migrate.vol.success:debug] Successfully migrated licenses for volume task_flex_aggr. # Example : Verify the logs between the time frame (start to check) use NACL::MTask::SystemLogDetector; ... my $detector = NACL::MTask::SystemLogDetector->->new( command_interface => $Cluster, check_for_all_presence => [ 'message.must.occur' , qr /message.with.regex/], check_for_absence => [ 'should.not.occur' , 'license.db.migrate.vol.success' ], ); $detector->start(); ... # Perform any operation here ... # Verify the logs from start to check (current time) $detector->check(); # End test # Example : Verify the logs between the time frame (start to check+wait_for_log) use NACL::MTask::SystemLogDetector; ... my $detector = NACL::MTask::SystemLogDetector->->new( command_interface => $Cluster, check_for_all_presence => [ 'message.must.occur' ], check_for_absence => [ 'should.not.occur' ], ); $detector->start(); ... # Perform any operation here ... # Verify the logs from start to check+wait_for_log time $detector->check(wait_for_log => 100); # End test =cut package NACL::MTask::SystemLogDetector; use strict; use warnings; use Tharn qw( sleep); use NATE::Log qw(log_global); my $Log = log_global(); my $may_enter = $Log->may_enter(); my $may_exit = $Log->may_exit(); use NATE::ParamSet; use Params::Validate qw(validate validate_with BOOLEAN HASHREF OBJECT ARRAYREF UNDEF SCALAR); use NATE::Exceptions::Argument qw(:try); use NATE::BaseException qw(:try); use NACL::Exceptions::EventCheckFailure qw(:try); use NACL::CS::ClusterDate; use NACL::C::Component; use NACL::ComponentUtils qw(Dumper); use NACL::Transit; use Time::Local; #Task related constant use constant POLL_DELTA => 10; use constant DEFAULT_TIMEOUT => 120; =head1 METHODS =head2 new my $detector = Task::SystemLogDetector->new( command_interface => $Cluster, %options ); Create a SystemLogDetector object that can be used to check for the presence or absence of events during a time range. =over =item Options =over =item C<< command_interface => $ci >> (Required, isa NACL::C::CommandInterface) The command interface on which to read and verify the system logs. See L =item C<< set_log_file => ['system.logs'] >> (Optional), default = * # all files The list of files (could be with path or without path) on which to lookup the system logs. If snapmirror_audit is provided as one of the files, then this MTask automatically adds snapmirror_audit.0 to the list. This is because logs are rotated at midnight, at which time the contents of snapmirror_audit is moved to snapmirror_audit.0. =item C<< set_log_dir => '/mroot/' >> (Optional) The directory on which to lookup the logs. Default value for '7mode' : '/mroot/etc'. Default value for 'Cmode' : '/mroot/etc/mlog'. =item C<< nacltask_timeout => $nacltask_timeout >> (Optional) Controls how long the command will wait before completing. Default is 120. =item C<< nacltask_skip_nonascii_file => 1|0 >> (Optional) Option to skip non-ascii file read. Default is 1, so this task will skip non-ascii file read by default. If set to 0, task will try to read the non-ascii file and truncate the non-ascii characters. =back =back =cut use Class::MethodMaker [ new => [ '-hash', '-init', 'new' ], scalar => 'logging_begin_time', scalar => 'logging_end_time', scalar => 'check_for_all_presence', scalar => 'check_for_absence', scalar => 'check_for_any_presence', scalar => 'set_log_file', scalar => 'set_log_dir', scalar => 'wait_for_log', scalar => 'logs', scalar => 'matched_logs', scalar => 'initial_files_stats', scalar => 'current_year', scalar => 'nacltask_timeout', scalar => 'nacltask_skip_nonascii_file', scalar => [ { -type => 'NACL::C::CommandInterface::ONTAP' }, 'command_interface' ], ]; use vars qw(%rotated); sub init { $Log->enter() if $may_enter; my $self = shift; my %opts = validate_with( params => \@_, spec => { command_interface => { isa => 'NACL::C::CommandInterface' }, check_for_all_presence => { type => ARRAYREF | UNDEF, optional => 1 }, check_for_absence => { type => ARRAYREF | UNDEF, optional => 1 }, check_for_any_presence => { type => ARRAYREF | UNDEF, optional => 1 }, set_log_file => { type => ARRAYREF, optional => 1 }, nacltask_skip_nonascii_file => { type => SCALAR, default => 1 }, logs => { type => ARRAYREF, optional => 1 }, set_log_dir => { type => SCALAR, optional => 1 }, wait_for_log => { type => SCALAR, optional => 1 }, logging_begin_time => { type => SCALAR, optional => 1 }, logging_end_time => { type => SCALAR, optional => 1 }, nacltask_timeout => { type => SCALAR, optional => 1 }, %{ NACL::C::Component->_common_validate_spec_without_ci() } }, ); #burt 769464 logs are rotated from # snapmirror_audit to snapmirror_audit.0 during midnight # if snapmirror_audit file is presrnt in list and # snapmirror_audit.o is not present in the set_log_file array, append the same. if ( defined $self->set_log_file() ) { my @set_log_file = @{$self->set_log_file()}; if ( (grep/^snapmirror_audit$/, @set_log_file) && (!grep/^snapmirror_audit\.0$/, @set_log_file) ) { push (@set_log_file, 'snapmirror_audit.0'); $self->set_log_file(\@set_log_file); } } if (defined $opts{nacltask_timeout}) { $self->nacltask_timeout($opts{nacltask_timeout}); } else { $self->nacltask_timeout(DEFAULT_TIMEOUT); } $self->nacltask_skip_nonascii_file($opts{nacltask_skip_nonascii_file}); my $date = NACL::CS::ClusterDate->fetch( command_interface => $self->{command_interface} )->date(); if ($date =~ /\d+\/\d+\/(\d+)\s+/) { $self->current_year($1); } $Log->debug("current year ".$self->current_year()); $Log->exit() if $may_exit; } ## end sub init =head2 start $detector->start(); (Instance method) Marks the time stamp which will be used as the start point for system logs to be validated. This does not have any return value. Instead, it updates the time stamp on the instance with the key "logging_begin_time". =cut sub start { $Log->enter() if $may_enter; my $self = shift; my %opts = validate_with( params => \@_, spec => NACL::C::Component->_common_validate_spec_without_ci() ); $self->_check_connection(); my $sys_date = $self->_get_system_time(); $self->logging_begin_time($sys_date); $Log->debug( "System logs logging begin time : " . $self->logging_begin_time() ); # getting the initial files details my $initial_stats=$self->_pull_logs_file_details(); $self->initial_files_stats($initial_stats); $Log->debug( "Details of initial files hash INITIAL_FILES_STATS:" . Dumper($initial_stats) ); $Log->exit() if $may_exit; } ## end sub start =head2 get_logs my $logs_as_string = $detector->get_logs(); or my @logs_array = $detector->get_logs(); (Instance method) Return the all generated logs between the start() and get_logs()/check() call. =over =item Options =item C<< skip_cached_logs => 1 >> ( Optional, defaults to 1 ) If set to '1', it will fetch the logs from start() to current time. If set to '0', it will check cache first ( previous check()/get_logs() msgs ). If present, returns the log else does log fetch. =item C<< command_output_level => trace | comment >> ( Optional ) This output log level will be used while fetching the logs. =back =cut sub get_logs { $Log->enter() if $may_enter; my $self = shift; my %opts = validate_with( params => \@_, spec => { skip_cached_logs => { type => BOOLEAN, default => 0 }, command_output_level => { regex => qr/trace|comment/, optional => 1}, %{ NACL::C::Component->_common_validate_spec_without_ci() } }, ); my %log_level; if (exists $opts{command_output_level}) { $log_level{'connectrec-output_log_level'} = delete $opts{command_output_level}; } $self->_check_connection(); if ( !defined( $self->logging_begin_time() ) ) { $Log->exit() if $may_exit; NATE::Exceptions::Argument->throw( "It is mandatory to run start() before get_logs()"); } if ( $opts{skip_cached_logs} || ref( $self->logs() ) ne 'ARRAY' ) { $self->_grep_logs(%log_level); } $Log->debug( "All generated logs " . Dumper( $self->logs() ) ); $Log->exit() if $may_exit; return ( wantarray() ? @{ $self->logs() } : join( "\n", @{ $self->logs() } ) ); } ## end sub get_logs =head2 get_matched_logs my $logs_as_string = $detector->get_matched_logs(); or my @logs_array = $detector->get_matched_logs(); (Instance method) Return the all matched logs between the start() and check() call. =cut sub get_matched_logs { $Log->enter() if $may_enter; my $self = shift; my %opts = validate_with( params => \@_, spec => NACL::C::Component->_common_validate_spec_without_ci() ); $self->_check_connection(); if ( !defined( $self->logging_end_time() ) ) { $Log->exit() if $may_exit; NATE::Exceptions::Argument->throw( "It is mandatory to run check() before get_matched_logs"); } if ( ref( $self->matched_logs() ) ne 'HASH' ) { $Log->exit() if $may_exit; NACL::Exceptions::EventCheckFailure->throw( "No matching logs Found:" . Dumper( $self->matched_logs() ) ); } my $mathced_logs = $self->matched_logs(); my @logs = (); # getting the all matched logs into @logs while ( my ( $method, $value ) = each( %${mathced_logs} ) ) { while ( my ( $event, $value ) = each( %{ $mathced_logs->{$method} } ) ) { push @logs, @{$value}; } ## end while ( my ( $event, $value... } ## end while ( my ( $method, $value... if ( $#logs == -1 ) { $Log->exit() if $may_exit; NACL::Exceptions::EventCheckFailure->throw( "No matched logs found" . Dumper( $self->matched_logs() ) ); } my %seen=(); @logs = grep { ! $seen{$_}++ } @logs ; $Log->debug( "All metched logs " . Dumper( \@logs ) ); $Log->exit() if $may_exit; return ( wantarray() ? @logs : join( "\n", @logs ) ); } ## end sub get_matched_logs =head2 check $detector->check(); Verifies the system logs occured during the time frame between start() and check() methods based on the options provided. NACL::Exceptions::EventCheckFailure with the appropriate message will be thrown if the verification fails. =over =item Options =over =item C<< check_for_all_presence => $array_ref >> ( Optional, defaults to reference to a null array ) Reference to a list of events names/Regexp to check. If any of the given system logs are not found, throws a NACL::Exceptions::EventCheckFailure exception with appropriate error message. =item C<< check_for_absence => $array_ref >> ( Optional, defaults to reference to a null array ) Reference to a list of events names/Regexp to check. If any of the given system logs are found, throws a NACL::Exceptions::EventCheckFailure exception with appropriate error message. =item C<< check_for_any_presence => $array_ref >> ( Optional, defaults to reference to a null array ) Reference to a list of events names/Regexp to check. If none of the given system logs are found, throws a NACL::Exceptions::EventCheckFailure exception with appropriate error message. =item C<< wait_for_log => $waiting_time >> ( Optional, defaults to '0' seconds ) Check the system logs further $waiting_time seconds after check(). If it is '0', it will check the system logs immediately after check() called. =back =back =cut sub check { $Log->enter() if $may_enter; my $self = shift; my %opts = validate_with( params => \@_, spec => { %{ $self->_check_validate_spec() }, %{ NACL::C::Component->_common_validate_spec_without_ci() }, }, ); $Log->debug( "Arguments list passed to check method:" . Dumper(%opts) ); my $wait_for_log = $opts{'wait_for_log'}; $self->_check_connection(); # Check for start logging if ( !defined( $self->logging_begin_time() ) ) { $Log->exit() if $may_exit; NATE::Exceptions::Argument->throw( "It is mandatory to call start() before calling check()"); } # Defining logging end time my $end_time = $self->_get_system_time() + $wait_for_log; $self->logging_end_time($end_time); $Log->debug( "Logging end time : " . $self->logging_end_time() ); # ensure atleast one of the check criteria is provided as param my $check_patterns = {}; if ( exists( $opts{'check_for_any_presence'} ) ) { $check_patterns->{check_for_any_presence} = $opts{'check_for_any_presence'}; } else { $check_patterns->{check_for_any_presence} = $self->check_for_any_presence(); } if ( exists( $opts{check_for_absence} ) ) { $check_patterns->{check_for_absence} = $opts{'check_for_absence'}; } else { $check_patterns->{check_for_absence} = $self->check_for_absence(); } if ( exists( $opts{check_for_all_presence} ) ) { $check_patterns->{check_for_all_presence} = $opts{'check_for_all_presence'}; } else { $check_patterns->{check_for_all_presence} = $self->check_for_all_presence(); } if (!( $check_patterns->{check_for_any_presence} || $check_patterns->{check_for_all_presence} || $check_patterns->{check_for_absence} ) ) { $Log->exit() if $may_exit; NATE::Exceptions::Argument->throw( "It is mandatory to specify atleast one of these parameters \(check_for_absence, check_for_any_presence, check_for_all_presence\)" ); } ## end if ( !( $check_patterns... my $error_msg = undef; my $error_flag = 0; my %exception_args; my $start_time; while (1) { $start_time = $self->_get_system_time(); # grep the all generated logs and store in $self->logs() $self->_grep_logs(); # match the logs $self->_match_log_with_event_or_regex($check_patterns); my $logs_matched = $self->matched_logs(); $Log->debug( "Matched log with time range " . $self->logging_begin_time() . " to $start_time :" . Dumper($logs_matched) ); $error_msg = ''; $error_flag = 0; %exception_args = ( 'matched_event' => [], 'unmatched_event' => [] ); if ( defined $check_patterns->{check_for_absence} ) { while ( my ( $pattern, $mlog ) = each( %{ $logs_matched->{check_for_absence} } ) ) { if ( $#$mlog >= 0 ) { $error_msg .= "@$mlog Unexpected message " . "found matching $pattern pattern"; push @{ $exception_args{'matched_event'} }, $pattern; $error_flag = 1; } ## end if ( $#$mlog >= 0 ) } ## end while ( my ( $pattern, $mlog... if ( $start_time < $end_time && $error_flag == 0 ) { $error_flag = 1; } } ## end if ( defined $check_patterns... if ( defined $check_patterns->{check_for_any_presence} ) { my $any_present = 0; while ( my ( $pattern, $mlog ) = each( %{ $logs_matched->{check_for_any_presence} } ) ) { if ( $#$mlog >= 0 ) { $any_present = 1; } } ## end while ( my ( $pattern, $mlog... if ( !$any_present ) { $error_flag = 1; $error_msg .= "No matching events found for any of the messages mentioned in \'check_for_any_presence\'\n"; push @{ $exception_args{'matched_event'} }, @{ $check_patterns->{check_for_any_presence} }; } ## end if ( !$any_present ) } ## end if ( defined $check_patterns... if ( defined $check_patterns->{check_for_all_presence} ) { while ( my ( $pattern, $mlog ) = each( %{ $logs_matched->{check_for_all_presence} } ) ) { if ( $#$mlog == -1 ) { $error_flag = 1; $error_msg .= "No events found for the events($pattern) mentioned in \'check_for_all_presence\'"; push @{ $exception_args{'unmatched_event'} }, $pattern; } ## end if ( $#$mlog == -1 ) } ## end while ( my ( $pattern, $mlog... } ## end if ( defined $check_patterns... $Log->debug( "Error flag = $error_flag start_time=$start_time end_time=$end_time" ); if ( $error_flag == 0 or $start_time >= $end_time ) { last; } Tharn::snooze(POLL_DELTA); } ## end while (1) if ($error_flag) { $Log->exit() if $may_exit; NACL::Exceptions::EventCheckFailure->throw( $error_msg, %exception_args ); } $Log->exit() if $may_exit; } ## end sub check # Returns validate spec for check() method based on if the check() is invoked as instance method or class method sub _check_validate_spec { my $self = shift; return { 'check_for_all_presence' => { type => ARRAYREF | UNDEF, optional => 1 }, 'check_for_absence' => { type => ARRAYREF | UNDEF, optional => 1 }, 'check_for_any_presence' => { type => ARRAYREF | UNDEF, optional => 1 }, 'wait_for_log' => { type => SCALAR, default => 0 }, }; } ## end sub _check_validate_spec =begin comment # When you want to use parse function in pod, replace "head parse" with "head2 parse" =head parse # Parse the logs between the time frame (start to parse) use NACL::MTask::SystemLogDetector; ... my $detector = NACL::MTask::SystemLogDetector->new( command_interface => $Cluster, set_log_file => ['/mroot/etc/log/backup'], ); $detector->start(); ... # Perform dump or restore operation here ... # It will parse the logs from start time to current time my $parsed_log = $detector->parse(); (Instance method) Parse the logs in /mroot/etc/log/backup file occured during the time frame between start() and parse() methods and provide the required output. Return the reference to a hash of parsed output logs between the start() and parse() call. Caller should pass 'set_log_file => ['/mroot/etc/log/backup']' with NACL::MTask::SystemLogDetector->new construction call if parser is called after that. $parsed_log i.e. output is a reference to a hash. Users can access individual key value pair as required. my $operation_type = $parsed_log->{'op_type'}; Example hash of result: For Dump: $VAR1 = { 'volume' => 'component_source_volume', 'phaseIV_time' => '0s', 'phaseI_time' => '1s', 'phaseV_time' => '1s', 'data' => { 'nt_dirs' => '0', 'reg_inodes' => '1', 'acls' => '0', 'other_inodes' => '0', 'dirs' => '0', 'nt_inodes' => '0', 'size' => '40MB' }, 'size' => { '=0' => '0', '<=128K' => '0', '<=512M' => '1', '<=1G' => '0', '<=4K' => '0', '<=1M' => '0', '<=10G' => '0', '<=256K' => '0', '<=512K' => '0', '<=32K' => '0', '<=64K' => '0', '>10G' => '0', '<=64' => '0' }, 'tape_changes' => '1', 'level' => '0', 'op_type' => 'dmp', 'phaseIII_time' => 0, 'snapshot' => 'snapshot_for_backup.481', 'total_time' => '2s', 'phaseII_time' => 0, 'tape_used' => { '0' => 'nrst1a' } }; For restore: $VAR1 = { 'level' => '0', 'volume' => 'component_source_volume', 'op_type' => 'rst', 'phaseFiles_time' => '0s', 'data' => { 'files' => '1', 'size' => '40MB' }, 'total_time' => '3s', 'phaseDir_time' => '2s', 'tape_used' => 'nrst1a' }; =over =item Options =over =item C<< type => $log_type >> ( Optional, defaults to tape type ) If the type is tape, the method parses the /mroot/log/backup logs only else the method will throw NATE::BaseException exception. In future we can add parsing support for other log files as well when required. =item C<< wait_for_log => $waiting_time >> ( Optional, defaults to '0' seconds ) Check the system logs further $waiting_time seconds after parse(). If it is '0', it will check the system logs immediately after parse() called. =back =back sub parse { $Log->enter() if $may_enter; my $self = shift; my %opts = validate_with( params => \@_, spec => { %{ NACL::C::Component->_common_validate_spec_without_ci() }, 'type' => { type => SCALAR, default => 'tape' }, 'wait_for_log' => { type => SCALAR, default => 0 }, }, ); $Log->debug( {"Arguments list passed to parse method:" . Dumper(%opts)} ); my $file = $self->set_log_file(); if (${$file}[0] !~ /\/mroot\/etc\/log\/backup/){ $Log->exit() if $may_exit; NATE::Exceptions::Argument->throw("Backup File path provided should be /mroot/etc/log/backup"); } my $wait_for_log = $opts{'wait_for_log'}; $self->_check_connection(); # Check for start logging if ( !defined( $self->logging_begin_time() ) ) { $Log->exit() if $may_exit; NATE::BaseException->throw( "It is mandatory to call start() before calling parse()"); } Tharn::sleep($wait_for_log) if($wait_for_log); my $parsed_log = {}; my @logs_as_array = $self->get_logs(skip_cached_logs => 1); unless( @logs_as_array){ $Log->exit() if $may_exit; NATE::BaseException->throw("No log message generated."); } my $count = 0; my @op_type = split /\W+/, $logs_as_array[0]; $parsed_log->{op_type} = $op_type[0]; $logs_as_array[0] =~ /Start\s+(\S+)\s+(\d+)/i; $parsed_log->{level} = $2; $logs_as_array[0] =~ /(.+)\/(.+)\/(.+)/ ; $parsed_log->{volume} = $2 ; for (my $i = 0; $i <= $#logs_as_array; ++$i) { local $_ = $logs_as_array[$i]; if ($op_type[0] =~ /dmp/i) { if ($_ =~ /Snapshot\s+\((\S+),/i) { $parsed_log->{snapshot} = $1 ; } if ($_ =~ /Tape changes:\s+(\d+)/i) { $parsed_log->{tape_changes} = $1 ; } if ($_ =~ /Error\s+[(\S+)\s]/i){ my @result = split(/error/i, $_); $parsed_log->{error} = $result[$#result]; } if ($_ =~ /Tape_open/i ) { my $first = $i; my (@tapes , $c) ; $tapes[$c++] = $first ; if($logs_as_array[++$i] =~ /Phase_change\s+\(I\)/i ) { $parsed_log->{phaseI_time} = $self->_get_time_difference($_ , $logs_as_array[$i] ).'s'; $logs_as_array[++$i] =~ /Phase_change\s+\(II\)/i; $parsed_log->{phaseII_time} = $self->_get_time_difference($logs_as_array[$i-1] , $logs_as_array[$i] ); $logs_as_array[++$i] =~ /Phase_change\s+\(III\)/i; $parsed_log->{phaseIII_time} = $self->_get_time_difference($logs_as_array[$i-1] , $logs_as_array[$i] ); $logs_as_array[++$i] =~ /Phase_change\s+\(IV\)/i; $parsed_log->{phaseIV_time} = $self->_get_time_difference($logs_as_array[$i-1] , $logs_as_array[$i] ).'s'; my $prev = $i; $count = 0; while($logs_as_array[$i] !~ /Phase_change\s+\(V\)/i && $i < $#logs_as_array ) { $tapes[$c++] = $i if($logs_as_array[++$i] =~ /Tape_open/i); $count++; } for ($c =0 ;$c <= $#tapes ; $c++){ $logs_as_array[$tapes[$c]] =~ /Tape_open\s+\((\S+)\)/i; $parsed_log->{tape_used}->{$c} = $1 ; } if ($logs_as_array[$i] =~ /Phase_change\s+\(V\)/i){ $parsed_log->{phaseV_time} = $self->_get_time_difference($logs_as_array[$prev] , $logs_as_array[$i] ).'s'; }else { $i = $i - $count; } $parsed_log->{total_time} = $self->_get_time_difference($logs_as_array[$first] , $logs_as_array[++$i] ).'s'; }else { --$i; } } if ($_ =~ /=0\s+<=64\s+<=4K\s+<=32K\s+<=64K\s+<=128K\s+<=256K/i ){ my @size = split(/\s+/, $logs_as_array[++$i]); my @key = split(/\s+/, $_); my $j = 0; for(my $k = $#size; $k > 8 ; $k--){ chop($size[$k]) if $size[$k] =~ /\)/; chop($key[$#key - $j]) if $key[$#key - $j] =~ /\)/; $parsed_log->{size}->{$key[$#key - $j]} = $size[$k]; $j++; } } if ($_ =~ /<=512K\s+<=1M\s+<=512M\s+<=1G\s+<=10G\s+>10G/i ){ my @size = split(/\s+/, $logs_as_array[++$i]); my @key = split(/\s+/, $_); my $j = 0; for(my $k = $#size; $k > 8 ; $k--){ chop($size[$k]) if $size[$k] =~ /\)/; chop($key[$#key - $j]) if $key[$#key - $j] =~ /\)/; $parsed_log->{size}->{$key[$#key - $j]} = $size[$k] ; $j++; } } if ($_ =~ /End\s+\((\d+)\s+(\S+)\)/i ){ $parsed_log->{data}->{size} = $1.$2; $_ = $logs_as_array[++$i]; if ($_ =~ /reg inodes: (\d+)/i ){ $parsed_log->{data}->{reg_inodes} = $1; } if ($_ =~ /other inodes:\s+(\d+)/i ){ $parsed_log->{data}->{other_inodes} = $1; } if ($_ =~ /dirs:\s+(\d+)/i ){ $parsed_log->{data}->{dirs} = $1; } if ($_ =~ /nt dirs:\s+(\d+)/i ){ $parsed_log->{data}->{nt_dirs} = $1; } if ($_ =~ /nt inodes:\s+(\d+)/i ){ $parsed_log->{data}->{nt_inodes} = $1; } if ($_ =~ /acls:\s+(\d+)/i ){ $parsed_log->{data}->{acls} = $1; } } }else { my $first; if ($_ =~ /Tape_open\s+\((\S+)\)/i ) { $parsed_log->{tape_used} = $1 ; $count = 0; $first = $i; while($logs_as_array[$i] !~ /Phase_change \(Dirs\)/i && $i < $#logs_as_array ) { ++$i; $count++; } if($logs_as_array[$i] =~ /Phase_change\s+\(Dirs\)/i) { $parsed_log->{phaseDir_time} = $self->_get_time_difference($_ , $logs_as_array[$i]).'s'; $parsed_log->{phaseFiles_time} = $self->_get_time_difference($logs_as_array[$i] , $logs_as_array[++$i]).'s'; } else { $i = $i - $count ; } } if ($_ =~ /Error\s+[(\S+)\s]/i){ my @result = split(/error/i, $_); $parsed_log->{error} = $result[$#result]; } if($_ =~ /Tape_close/){ $parsed_log->{total_time} = $self->_get_time_difference($logs_as_array[$first], $_ ).'s'; } if ($_ =~ /End\s+\((\d+)\s+(\S+),\s+(\d+)\s+(\S+)\)/i ){ $parsed_log->{data}->{files} = $1; $parsed_log->{data}->{size} = $3.$4; } } } $Log->exit() if $may_exit; return $parsed_log ; } ## end sub parse # Returns difference between time in seconds. Input - Two strings that contain time input. sub _get_time_difference { $Log->enter() if $may_enter; my $self = shift; my ($log1, $log2)= @_; my %months = ( Jan => 1, Feb => 2, Mar => 3, Apr => 4, May => 5, Jun => 6, Jul => 7, Aug => 8, Sep => 9, Oct => 10, Nov => 11, Dec => 12 ); my @b = split(/[:\s]+/, $log1); my @e = split(/[:\s]+/, $log2); #Since the log file does not have year information, using dummy year for timelocal(). my $year = $self->current_year(); my $b = timelocal($b[6], $b[5], $b[4], $b[3], $months{$b[2]}-1, $year); if($b[2] =~ /Dec/i && $e[2] =~ /Jan/i){ ++$year; } my $e = timelocal($e[6], $e[5], $e[4], $e[3], $months{$e[2]}-1, $year); $Log->exit() if $may_exit; return $e - $b ; } =end comment =cut # It will grep the all logs in the given time frame sub _grep_logs { $Log->enter() if $may_enter; my ($self, %opts) = @_; my $initial_stats = $self->initial_files_stats(); my $last_stats = $self->_pull_logs_file_details(); my $normalize_cmd = q/| tr -cd '\000-\177'/; # Filtering the modified logs files foreach my $inode ( keys( %{$last_stats} ) ) { if(!exists($initial_stats->{$inode})) { $initial_stats->{$inode}=$last_stats->{$inode}; } } ## end foreach my $inode ( keys( %... # Getting the all logs generated in between start() & check() # in @generated_logs array my @generated_logs=(); my $ibs = 1024; foreach my $inode ( keys( %{$initial_stats} ) ) { my $file_inode = $initial_stats->{$inode}; my $file_size = $file_inode->{size}; my $skip_blocks = int $file_size / $ibs; my $offset = $file_size % $ibs; my $command = 'dd if='. $file_inode->{'name'}->[0] . ' ibs='. $ibs . ' skip='. $skip_blocks; my $file_type = $self->apiset()->execute_raw_command( command => 'file -i ' . $file_inode->{'name'}->[0], 'connectrec-timeout' => $self->nacltask_timeout(), %opts ); if ( $file_type !~ /charset=.*?ascii/ ) { if($self->nacltask_skip_nonascii_file()) { $Log->trace("skipping reading non ascii file: " . $file_inode->{'name'}->[0]); next; } else { $command .= $normalize_cmd; } } my $resp_buffer = $self->apiset()->execute_raw_command( command => $command, 'connectrec-timeout' => $self->nacltask_timeout(), %opts ); # Sometime bytes copied by dd are less than the offset(Not # sure why). So wanted to make sure offset used in substr # function is minimum of ($bytes_transferred, $offset) my ($bytes_transferred) = ( $resp_buffer =~ /(\d+) bytes transferred in/); if(!defined $bytes_transferred) { $bytes_transferred = $ibs + 1; } $offset = ($offset <= $bytes_transferred)? $offset : $bytes_transferred; ##If new file is generated by log file rotaion ##then all logs of that new file will be included in resp_buffer without doing substr if (!defined ($rotated{$file_inode->{'name'}->[0]})){ $resp_buffer = substr($resp_buffer, $offset); } my @g_logs=split(/\n+/, $resp_buffer); # Removing the last 3 entry of records in/out & xfer info(only if exists) pop(@g_logs) if (scalar(@g_logs) > 0 and ($g_logs[-1] =~ /(\d+) bytes transferred in/)); pop(@g_logs) if (scalar(@g_logs) > 0 and ($g_logs[-1] =~ /records out/)); pop(@g_logs) if (scalar(@g_logs) > 0 and ($g_logs[-1] =~ /records in/)); push @generated_logs, @g_logs; } ## end foreach my $inode ( keys( %... $self->logs( \@generated_logs ); $Log->debug( "All generated logs".Dumper(\@generated_logs) ); $Log->exit() if $may_exit; } ## end sub _grep_logs sub get_current_logfilename { my ( $self, $root_logname ) = @_; my $out; my $filename; $out = $self->apiset()->execute_raw_command( command => "ls -1 ".$root_logname.".* | sort -r", 'connectrec-timeout' => $self->nacltask_timeout()); chomp( $out ); my @files = split("\n", $out); # If you have the following files: # /mroot/etc/mlog/vifmgr.log.0000000003 # /mroot/etc/mlog/vifmgr.log.0000000002 # /mroot/etc/mlog/vifmgr.log.0000000001 # vifmgr.log and vifmgr.log.0000000003 are the same # so the file with the largest suffix is the "current" log file. $filename = $files[0]; return $filename; } # Checks if the given message or regex matches the event log message sub _match_log_with_event_or_regex { $Log->enter() if $may_enter; my $self = shift; my $pattern_lookups = shift; # gets all the generated logs my $generated_logs = $self->logs(); my $logs_found = {}; my @log_lookups = ( 'check_for_all_presence', 'check_for_any_presence', 'check_for_absence' ); foreach my $method (@log_lookups) { my $patterns = $pattern_lookups->{$method}; foreach my $log_pattern ( @{$patterns} ) { $logs_found->{$method}->{"$log_pattern"} = []; if ( ref $log_pattern eq 'Regexp' ) { push @{ $logs_found->{$method}->{"$log_pattern"} }, ( grep {/$log_pattern/} @{$generated_logs} ); } else { push @{ $logs_found->{$method}->{"$log_pattern"} }, ( grep {/\Q$log_pattern\E/} @{$generated_logs} ); } } ## end foreach my $log_pattern ( @... } ## end foreach my $method (@log_lookups) $Log->debug( 'Matched logs ' . Dumper($logs_found) ); $self->matched_logs($logs_found); $Log->exit() if $may_exit; } ## end sub _match_log_with_event_or_regex # This method will generate the key, value relationship of files details # key will be inode and value will be size and name sub _pull_logs_file_details { $Log->enter() if $may_enter; my $self = shift; my %opts = @_; my $cmd = $opts{'command'}; my $command_interface = $self->command_interface(); # getting list of files to check logs my $files_details = $self->set_log_file(); my $files; # setting the cwd USER define or based upon filer mode my $log_dir = $self->set_log_dir(); if ( !defined($log_dir) ) { if ( $command_interface->mode() eq '7Mode' ) { $log_dir = '/mroot/etc'; } elsif ( $command_interface->mode() eq 'CMode' ) { $log_dir = '/mroot/etc/mlog'; } } ## end if ( !defined($log_dir... ## Single log file rotation is being handled by following code my @filearray; foreach my $filename (@{$files_details}){ my $PATH; if ($filename =~ m/\//){ $PATH = $filename; }else{ $PATH = $log_dir."/".$filename; } $self->{original}{$filename} = $self->{current}{$filename} if (defined $self->{current}{$filename}); $self->{current}{$filename} = $self->get_current_logfilename($PATH); if (!defined $self->{original}{$filename}){ push @filearray,$self->{current}{$filename}; next; }else{ if($self->{original}{$filename} eq $self->{current}{$filename}){ push @filearray,$self->{original}{$filename}; }else{ push @filearray,$self->{original}{$filename}; push @filearray,$self->{current}{$filename}; $rotated{$self->{current}{$filename}} = 1; } } } if ( @filearray ) { $files = join( ' ', @filearray ); } else { $files = '*'; } $self->apiset()->execute_raw_command( command => "cd $log_dir" ); my $resp_buffer; if ( $files ne '*' ) { $resp_buffer = $self->apiset()->execute_raw_command( command => "ls -ltri $files", output_log_level => 'trace', 'connectrec-timeout' => $self->nacltask_timeout() ); } elsif ( defined($cmd) ) { $resp_buffer = $self->apiset()->execute_raw_command( command => $cmd, output_log_level => 'trace', 'connectrec-timeout' => $self->nacltask_timeout() ); } else { $resp_buffer = $self->apiset()->execute_raw_command( command => "ls -ltri", output_log_level => 'trace', 'connectrec-timeout' => $self->nacltask_timeout() ); } ## end else [ if ( $files ne '*' ) my @files = split( /\r*\n/, $resp_buffer ); $files_details = {}; foreach (@files) { # Greping the details of the file like inode, size and name s/^\s*//g; my @tmp = split(/\s+/); next if ( $#tmp < 9 ); if($tmp[1] =~ /^d/) { $Log->debug("file $tmp[9] is a directory. So skipping"); next; } my ( $inode, $size, $name ) = ( $tmp[0], $tmp[5], $tmp[9] ); if ( exists( $files_details->{$inode} ) ) { push @{ $files_details->{$inode}->{name} }, $name; } else { $files_details->{$inode} = { size => $size, inode => $inode, name => [$name] }; } } ## end foreach (@files) $Log->exit() if $may_exit; return $files_details; } ## end sub _pull_logs_file_details # get the time of filer sub _get_system_time { $Log->enter() if $may_enter; my $self = shift; my $resp_buffer = $self->apiset()->execute_raw_command( command => 'date +%s' ); my $date; $date = $1 if ( $resp_buffer =~ /^(\d+)\s*/ ); $Log->exit() if $may_exit; return $date; } ## end sub _get_system_time # Reconnect the session if filer reboots # Due to Burt527565, We are reconnecting the APIset in while loop # for 300 seconds. sub _check_connection { $Log->enter() if $may_enter; my $self = shift; if ( !$self->apiset()->api_is_session_alive() ) { $Log->trace("Apiset connection is down. reconnecting..."); my $transit_obj = NACL::Transit->new( name => $self->{command_interface}->name() ); $transit_obj->change_state( to => 'CLI' ); my $time =time()+300; $self->{command_interface}->refresh_command_interface(); while (1) { try { if ( $self->apiset()->api_is_session_alive() ) { last; } else { $self->apiset()->api_reconnect_session(); } } ## end try catch NATE::BaseException with { $Log->debug("Retrying connection..."); }; if(time()>=$time && !$self->apiset()->api_is_session_alive()) { $Log->exit() if $may_exit; NATE::BaseException->throw("Unable to reconnect to filer after connection loss"); } } ## end while (1) } ## end if ( !$self->apiset()->api_is_session_alive... $Log->exit() if $may_exit; } ## end sub _check_connection sub apiset { $Log->enter() if $may_enter; my $self = $_[0]; $Log->exit() if $may_exit; return $self->command_interface()->apiset( category => 'Node', interface => 'CLI', set => "Systemshell", ); } 1;