TT#62215 - Add logging for NGCP Test Framework

* create separate log files for each test case
	 * create files with standard output of
	   Test::More for both errors and results

Change-Id: Ide1979bedf1fe3c3f111abad60afe19b2b85adbb
changes/31/31731/5
Flaviu Mates 6 years ago
parent 5960a16caa
commit 13688f29cc

@ -8,6 +8,7 @@ use DateTime qw();
use DateTime::Format::Strptime qw();
use DateTime::Format::ISO8601 qw();
use Digest::MD5 qw/md5_hex/;
use Log::Log4perl qw(:easy);
use Moose;
use Net::Domain qw(hostfqdn);
use Test::More;
@ -27,6 +28,27 @@ has 'file_path' => (
sub run {
my ( $self ) = @_;
my $test_case_name = $self->file_path;
$test_case_name =~ s/.+\/(\w+).yaml/$1/;
chomp $test_case_name;
Log::Log4perl->easy_init( { level => $DEBUG,
file => ">>/var/log/ngcp/test-framework/$test_case_name.log",
category => "TestFramework::Client",
layout => '%d - %F{1} line %L - %M: %m%n' },
{ level => $DEBUG,
file => ">>/var/log/ngcp/test-framework/$test_case_name.log",
category => "TestFramework::RequestBuilder",
layout => '%d - %F{1} line %L - %M: %m%n' },
{ level => $DEBUG,
file => ">>/var/log/ngcp/test-framework/$test_case_name.log",
category => "TestFramework::TestExecutor",
layout => '%d - %F{1} line %L - %M: %m%n' },
{ level => $DEBUG,
file => ">/var/log/ngcp/test-framework/$test_case_name.log",
layout => '%d - %F{1} line %L - %M: %m%n' }
);
INFO( "Started running the Test TestFramework!" );
unless ( $self->file_path ) {
return;
}
@ -35,17 +57,25 @@ sub run {
$YAML::XS::UseCode = 1;
$YAML::XS::LoadBlessed = 1;
INFO( "Loading YAML file." );
my $testing_data = LoadFile($self->file_path);
INFO( "Setting up the base URI." );
my $base_uri = $ENV{CATALYST_SERVER} || ('https://'.hostfqdn.':4443');
INFO( "Setting up the RequestBuilder." );
my $request_builder = NGCP::TestFramework::RequestBuilder->new({ base_uri => $base_uri });
my $client = NGCP::TestFramework::Client->new( { uri => $base_uri, log_debug => 0 } );
INFO( "Setting up the Client." );
my $client = NGCP::TestFramework::Client->new( { uri => $base_uri } );
INFO( "Setting up the Test Executor." );
my $test_executor = NGCP::TestFramework::TestExecutor->new();
# initializing time to add to fields which need to be unique
my $retained = { unique_id => int(rand(100000)) };
my $test_case_result = { success => 1, error_count => 0 };
foreach my $test ( @$testing_data ) {
DEBUG( "In test '".$test->{name}."'" );
next if ( $test->{skip} );
# build request
@ -56,46 +86,64 @@ sub run {
content => $test->{content} || undef,
retain => $retained
});
DEBUG ( "Request: ".Dumper $request );
# handle separate types
if ( $test->{type} eq 'item' ) {
INFO( "Performing request." );
my $result = $client->perform_request($request);
DEBUG ( "Result: ".Dumper $result );
if ( $test->{retain} ) {
INFO( "Storing retained variables." );
$self->_get_retained_elements( $test->{retain}, $retained, $result );
}
if ( $test->{operations} ) {
$self->_perform_operations( $test->{operations}, $retained );
}
if ( $test->{perl_code} ){
INFO( "Executing perl code." );
my $sub = $test->{perl_code};
warn Dumper $sub;
$sub->( $retained );
}
$test_executor->run_tests( $test->{conditions}, $result, $retained, $test->{name} ) if ( $test->{conditions} );
if ( $test->{conditions} ) {
INFO( "Running tests." );
my $tests_result = $test_executor->run_tests( $test->{conditions}, $result, $retained, $test->{name} );
if ( !$tests_result->{success} ) {
map { print $_." in test case '$test_case_name'\n" } @{$tests_result->{errors}};
$test_case_result->{success} = 0;
$test_case_result->{error_count} += scalar @{$tests_result->{errors}};
}
}
}
elsif ( $test->{type} eq 'batch' ) {
foreach my $iteration ( 1..$test->{iterations} ) {
INFO( "Performing request for iteration $iteration." );
my $result = $client->perform_request($request);
DEBUG ( "Result: ".Dumper $result );
if ( $test->{retain} ) {
INFO( "Storing retained variables." );
$self->_get_retained_elements( $test->{retain}, $retained, $result );
}
if ( $test->{operations} ) {
$self->_perform_operations( $test->{operations}, $retained );
if ( $test->{conditions} ) {
INFO( "Running tests." );
my $tests_result = $test_executor->run_tests( $test->{conditions}, $result, $retained, $test->{name} );
if ( !$tests_result->{success} ) {
map { print $_." in test case '$test_case_name'\n" } @{$tests_result->{errors}};
$test_case_result->{success} = 0;
$test_case_result->{error_count} += scalar @{$tests_result->{errors}};
}
}
$test_executor->run_tests( $test->{conditions}, $result, $retained, $test->{name} ) if ( $test->{conditions} );
$retained->{unique_id}=int(rand(100000));
}
}
elsif ( $test->{type} eq 'pagination' ) {
my $nexturi = $test->{path};
do {
INFO( "Performing request for pagination." );
$request->uri( $base_uri.$nexturi );
my $result = $client->perform_request($request);
DEBUG ( "Result: ".Dumper $result );
if ( $test->{retain} ) {
INFO( "Storing retained variables." );
$self->_get_retained_elements( $test->{retain}, $retained, $result );
}
if ( $test->{operations} ) {
$self->_perform_operations( $test->{operations}, $retained );
}
my $body = decode_json( $result->decoded_content() );
#build default conditions for pagination
@ -118,7 +166,15 @@ sub run {
$test->{conditions}->{ok}->{'${collection}._links.next.href'} = 'defined';
}
$test_executor->run_tests( $test->{conditions}, $result, $retained, $test->{name} ) if ( $test->{conditions} );
if ( $test->{conditions} ) {
INFO( "Running tests." );
my $tests_result = $test_executor->run_tests( $test->{conditions}, $result, $retained, $test->{name} );
if ( !$tests_result->{success} ) {
map { print $_." in test case '$test_case_name'\n" } @{$tests_result->{errors}};
$test_case_result->{success} = 0;
$test_case_result->{error_count} += scalar @{$tests_result->{errors}};
}
}
if( $body->{_links}->{next}->{href} ) {
$nexturi = $body->{_links}->{next}->{href};
@ -128,6 +184,7 @@ sub run {
} while ( $nexturi )
}
}
return $test_case_result;
}
sub _get_retained_elements {

@ -5,6 +5,7 @@ use warnings;
use Data::Dumper;
use Digest::MD5 qw/md5_hex/;
use IO::Uncompress::Unzip;
use Log::Log4perl qw(:easy);
use LWP::UserAgent;
use Moose;
use Time::HiRes qw/gettimeofday tv_interval/;
@ -54,12 +55,6 @@ has 'verify_ssl' => (
default => 0,
);
has 'log_debug' => (
isa => 'Bool',
is => 'rw',
default => 0,
);
has '_crt_path' => (
is => 'ro',
isa => 'Str',
@ -94,16 +89,16 @@ sub _build_ua {
$uri = $self->sub_uri;
}
$self->_uri($uri);
$self->debug("client using uri $uri\n");
DEBUG("client using uri $uri\n");
$uri =~ s/^https?:\/\///;
$self->debug("client using ip:port $uri\n");
DEBUG("client using ip:port $uri\n");
my $realm;
if($self->role eq 'admin' || $self->role eq 'reseller') {
$realm = 'api_admin_http';
} elsif($self->role eq 'subscriber') {
$realm = 'api_subscriber_http';
}
$self->debug("client using realm $realm with user=" . $self->username . " and pass " . $self->password . "\n");
DEBUG("client using realm $realm with user=" . $self->username . " and pass " . $self->password . "\n");
$ua->credentials($uri, $realm, $self->username, $self->password);
unless($self->verify_ssl) {
$ua->ssl_opts(
@ -168,24 +163,11 @@ sub _build_ua {
sub perform_request {
my ($self, $req) = @_;
my $t0 = [gettimeofday];
$self->debug("content of " . $req->method . " request to " . $req->uri . ":\n");
$self->debug($req->content || "<empty request>");
$self->debug("\n");
my $res = $self->_ua->request($req);
my $rtt = tv_interval($t0);
$self->last_rtt($rtt);
$self->debug("content of response:\n");
$self->debug($res->decoded_content || "<empty response>");
$self->debug("\n");
return $res;
}
sub debug {
my ($self, $msg) = @_;
if($self->log_debug) {
print $msg;
}
}
1;

@ -511,7 +511,7 @@
stop => $dtf->format_datetime($now),},];
$retained->{malformed_profilemappings4} = [ { profile_id => $billing_profile_id,
start => $dtf->format_datetime($t1),
stop => $dtf->format_datetime($t2),}, ] , [];
stop => $dtf->format_datetime($t2),}, ];
$retained->{correct_profile_mappings1} = [ { profile_id => $retained->{second_billing_profile_id},
start => undef,
stop => undef, },

@ -602,7 +602,7 @@
stop => $dtf->format_datetime($now),},];
$retained->{malformed_profilemappings4} = [ { profile_id => $billing_profile_id,
start => $dtf->format_datetime($t1),
stop => $dtf->format_datetime($t2),}, ] , [];
stop => $dtf->format_datetime($t2),}, ];
$retained->{correct_profile_mappings1} = [ { profile_id => $retained->{second_billing_profile_id},
start => undef,
stop => undef,

@ -4,6 +4,7 @@ use strict;
use warnings;
use HTTP::Request;
use Cpanel::JSON::XS;
use Log::Log4perl qw(:easy);
use Moose;
use Data::Dumper;

@ -4,13 +4,18 @@ use strict;
use warnings;
use Cpanel::JSON::XS;
use Data::Walk;
use Log::Log4perl qw(:easy);
use Moose;
use Test::More;
use Data::Dumper;
Test::More->builder->output ('/var/log/ngcp/test-framework/result.txt');
Test::More->builder->failure_output ('/var/log/ngcp/test-framework/errors.txt');
sub run_tests {
my ( $self, $conditions, $result, $retained, $test_name ) = @_;
my $tests_result = { success => 1 };
foreach my $condition ( keys %$conditions ) {
if ( $condition eq 'is' ) {
while ( my ( $check_param, $check_value ) = each %{$conditions->{$condition}} ) {
@ -23,18 +28,50 @@ sub run_tests {
if ( $check_param =~ /.+\..+/ ) {
my @splitted_values = split (/\./, $check_param);
$check_param = $self->_retrieve_from_composed_key( $result, \@splitted_values, $retained );
is ($check_param, $check_value, $test_name);
DEBUG ( "Checking is for $check_param and $check_value" );
if ( is ($check_param, $check_value, $test_name) ) {
INFO ( "Check ok." );
}
else {
ERROR ( "NOT OK. Expected: $check_param. Got: $check_value" );
$tests_result->{success} = 0;
push @{$tests_result->{errors}}, "Error at 'is' condition for test '$test_name'";
}
}
elsif ( $check_param eq 'code' ) {
is ($result->code, $check_value, $test_name);
DEBUG ( "Checking is for ".$result->code." and $check_value" );
if ( is ($result->code, $check_value, $test_name) ) {
INFO ( "Check ok." );
}
else {
ERROR ( "NOT OK. Expected: ".$result->code.". Got: $check_value" );
$tests_result->{success} = 0;
push @{$tests_result->{errors}}, "Error at 'is' condition for test '$test_name'";
}
}
elsif ( $check_param eq 'header' ) {
foreach my $header_condition ( keys %{$conditions->{$condition}->{$check_param}} ) {
is ($result->header($header_condition), $check_value->{$header_condition}, $test_name);
DEBUG ( "Checking is for ".$result->header($header_condition)."and ".$check_value );
if ( is ($result->header($header_condition), $check_value->{$header_condition}, $test_name) ) {
INFO ( "Check ok." );
}
else{
ERROR ( "NOT OK. Expected: ".$result->header($header_condition).". Got: ".$check_value->{$header_condition} );
$tests_result->{success} = 0;
push @{$tests_result->{errors}}, "Error at 'is' condition for test '$test_name'";
}
}
}
else {
is ($check_param, $check_value, $test_name);
DEBUG ( "Checking is for $check_param and $check_value" );
if ( is ($check_param, $check_value, $test_name) ) {
INFO ( "Check ok." );
}
else {
ERROR ( "NOT OK. Expected: ".$check_param.". Got: ".$check_value );
$tests_result->{success} = 0;
push @{$tests_result->{errors}}, "Error at 'is' condition for test '$test_name'";
}
}
}
}
@ -43,18 +80,60 @@ sub run_tests {
if ( $check_param eq 'options' ) {
my $body = decode_json($result->decoded_content);
my @hopts = split /\s*,\s*/, $result->header('Allow');
ok(exists $body->{methods} && ref $body->{methods} eq "ARRAY", $test_name);
DEBUG ( "Checking ok for options" );
if ( ok(exists $body->{methods} && ref $body->{methods} eq "ARRAY", $test_name) ) {
INFO ( "Check ok." );
}
else {
ERROR ( "NOT OK. Check failed for existence of methods in body and reference of \$body->{methods} is ARRAY");
$tests_result->{success} = 0;
push @{$tests_result->{errors}}, "Error at 'ok' condition for test '$test_name'";
}
foreach my $opt(@{$conditions->{$condition}->{$check_param}}) {
ok(grep { /^$opt$/ } @hopts, $test_name);
ok(grep { /^$opt$/ } @{ $body->{methods} }, $test_name);
if ( ok(grep { /^$opt$/ } @hopts, $test_name) ) {
INFO ( "Check ok." );
}
else {
ERROR ( "NOT OK. Check failed for existence of ".$opt." in header methods" );
$tests_result->{success} = 0;
push @{$tests_result->{errors}}, "Error at 'ok' condition for test '$test_name'";
}
if ( ok(grep { /^$opt$/ } @{ $body->{methods} }, $test_name) ) {
INFO ( "Check ok." );
}
else {
ERROR ( "NOT OK. Check failed for existence of ".$opt." in body methods" );
$tests_result->{success} = 0;
push @{$tests_result->{errors}}, "Error at 'ok' condition for test '$test_name'";
}
}
}
if ( $conditions->{$condition}->{$check_param} eq 'defined' || $conditions->{$condition}->{$check_param} eq 'undefined') {
if ( $check_param =~ /.+\..+/ ) {
my @splitted_values = split (/\./, $check_param);
my $check_value = $self->_retrieve_from_composed_key( $result, \@splitted_values, $retained );
$conditions->{$condition}->{$check_param} eq 'defined' ?
ok(defined $check_value, $test_name) : ok(!defined $check_value, $test_name);
if ( $conditions->{$condition}->{$check_param} eq 'defined' ) {
DEBUG ( "Checking ok for defined" );
if ( ok(defined $check_value, $test_name) ) {
INFO ( "Check ok." );
}
else {
ERROR ( "NOT OK. Check failed for existence of ".$check_param );
$tests_result->{success} = 0;
push @{$tests_result->{errors}}, "Error at 'ok' condition for test '$test_name'";
}
}
else {
DEBUG ( "Checking ok for undefined" );
if ( ok(!defined $check_value, $test_name) ) {
INFO ( "Check ok." );
}
else {
ERROR ( "NOT OK. Check failed for non-existence of ".$check_param );
$tests_result->{success} = 0;
push @{$tests_result->{errors}}, "Error at 'ok' condition for test '$test_name'";
}
}
}
}
}
@ -64,13 +143,21 @@ sub run_tests {
if ( $check_param =~ /.+\..+/ ) {
my @splitted_values = split (/\./, $check_param);
my $check_value = $self->_retrieve_from_composed_key( $result, \@splitted_values, $retained );
like ($check_value, qr/$conditions->{$condition}->{$check_param}/, $test_name);
DEBUG ( "Checking like for ".$check_value." against ".$conditions->{$condition}->{$check_param} );
if ( like ($check_value, qr/$conditions->{$condition}->{$check_param}/, $test_name) ) {
INFO ( "Check ok." );
}
else{
ERROR ( "NOT OK. Expected: ".$check_value." to be like: ".$conditions->{$condition}->{$check_param} );
$tests_result->{success} = 0;
push @{$tests_result->{errors}}, "Error at 'like' condition for test '$test_name'";
}
}
}
}
elsif ( $condition eq 'is_deeply' ) {
foreach my $check_param (keys %{$conditions->{$condition}}) {
*replace_variables = sub {
local *replace_variables = sub {
if ( ref $_ eq 'HASH' ) {
while ( my ( $key, $value ) = each %$_ ) {
if ( $value && $value =~ /\$\{(.*)\}/ ) {
@ -92,10 +179,19 @@ sub run_tests {
my @splitted_values = split (/\./, $check_param);
$check_value = $self->_retrieve_from_composed_key( $result, \@splitted_values, $retained );
}
is_deeply ($check_value, $conditions->{$condition}->{$check_param}, $test_name);
DEBUG ( "Checking is_deeply for: ".(Dumper $check_value)." and ".(Dumper $conditions->{$condition}->{$check_param}) );
if ( is_deeply ($check_value, $conditions->{$condition}->{$check_param}, $test_name) ) {
INFO ( "Check ok." );
}
else{
ERROR ( "NOT OK. Expected:\n".$check_value."\n. Got:\n".$conditions->{$condition}->{$check_param} );
$tests_result->{success} = 0;
push @{$tests_result->{errors}}, "Error at 'is_deeply' condition for test '$test_name'";
}
}
}
}
return $tests_result;
}
sub _retrieve_from_composed_key {

@ -66,15 +66,19 @@ sub worker {
my ($tests_queue) = @_;
while ( my $test_file = $tests_queue->dequeue_nb() ) {
chomp $test_file;
my $start_time = time;
print "Running tests from $test_file\n";
my $test_framework = NGCP::TestFramework->new( {file_path => $test_file} );
my $result_code = $test_framework->run();
my $result = $test_framework->run();
my $total_time = time - $start_time;
print "Finished test execution for $test_file, test execution returned with exit code $result_code.\n";
print "Tests for $test_file took $total_time seconds.\n";
print "Finished test execution for $test_file, test execution returned with exit code ".$result->{success}."\n";
if ( !$result->{success} ) {
print $result->{error_count}." errors were found!\n";
}
print "Tests for $test_file took $total_time seconds.\n\n";
}
}

Loading…
Cancel
Save