Commit c07def92 authored by Leigh B Stoller's avatar Leigh B Stoller

More Logfile changes. For protogeni we want store for a short time,

the metadata even if there is nothing in the logfile. Mostly so that
the URL link works and we can get the header info if needed.

Also add slice_urn and slice_idx to the metadata so we find all the
logs associated with a slice.

Fixes.
parent c351215e
......@@ -309,26 +309,41 @@ sub Store($)
$self->Close();
#
# Use first two letters of the id for the subdir.
# Well, what if we have metadata but the logfile is empty? The
# metadata is still interesting in some situations, but rather
# then compress a null file and take an inode, just set the
# filename to null. This currently happens from the protogeni API.
# If the size of the logfiles table gets out of control, we can
# revisit this, but I think we just need to age out old ones
# on a regular basis.
#
my $dir = lc(substr($logid, 0, 2));
$newname = "$newname/$dir/${logid}.gz";
if (-e $newname) {
print STDERR "Logfile::Store ($logid) - $newname exists\n";
return -1;
if (-e $filename && -s $filename) {
#
# Use first two letters of the id for the subdir.
#
my $dir = lc(substr($logid, 0, 2));
$newname = "$newname/$dir/${logid}.gz";
if (-e $newname) {
print STDERR "Logfile::Store ($logid) - $newname exists\n";
return -1;
}
my $output = emutil::ExecQuiet("$GZIP -c $filename > $newname");
if ($?) {
SENDMAIL($TBOPS, "Logfile Store Error",
"Failed to store $filename to $newname\n\n".
"-----------------\n".
"$output\n", $TBOPS);
return -1
}
$newname = "'" . $newname . "'";
}
my $output = emutil::ExecQuiet("$GZIP -c $filename > $newname");
if ($?) {
SENDMAIL($TBOPS, "Logfile Store Error",
"Failed to store $filename to $newname\n\n".
"-----------------\n".
"$output\n", $TBOPS);
return -1
else {
$newname = "NULL";
}
unlink($filename);
DBQueryWarn("update logfiles set ".
" stored=1,compressed=1,filename='$newname' ".
" stored=1,compressed=1,filename=$newname ".
"where logid='$logid'")
or return -1;
......
......@@ -263,6 +263,7 @@ sub ListResources()
my $xml = undef;
if ($slice_urn) {
main::AddLogfileMetaData("slice_urn", $slice_urn);
# If $slice_urn is defined, this turns into a Resolve call. We
# need to resolve twice: once to get the sliver urn from the
......@@ -895,6 +896,10 @@ sub Update
if (GeniResponse::IsResponse($cred));
my ($slice, $aggregate) = GeniCMV2::Credential2SliceAggregate($cred);
if (defined($slice)) {
main::AddLogfileMetaData("slice_urn", $slice_urn);
main::AddLogfileMetaData("slice_idx", $slice->idx());
}
# The URN list must be either empty or contain the slice URN.
if (scalar(@urns) > 1 ||
......@@ -977,6 +982,7 @@ sub AllocateTicket
if (GeniResponse::IsResponse($combined)) {
return $combined;
}
my $args = {
'slice_urn' => $slice_urn,
'ticket' => $ticketStr,
......
......@@ -64,6 +64,7 @@ use Time::Local;
use Compress::Zlib;
use File::Temp qw(tempfile);
use MIME::Base64;
use Errno;
# Configure variables
my $TB = "@prefix@";
......@@ -118,8 +119,7 @@ sub GetVersion()
"output_rspec" => "2",
"ad_rspec" => \@ad_rspec_versions
};
return GeniResponse->Create( GENIRESPONSE_SUCCESS, $blob);
return GeniResponse->Create(GENIRESPONSE_SUCCESS, $blob);
}
#
......@@ -388,7 +388,7 @@ sub CreateSliver($)
require Experiment;
require libtestbed;
require libaudit;
# For now, I am not worrying about the slice_urn argument.
if (! (defined($credentials) &&
defined($slice_urn) && defined($rspecstr))) {
......@@ -404,6 +404,8 @@ sub CreateSliver($)
return $credential
if (GeniResponse::IsResponse($credential));
main::AddLogfileMetaData("slice_urn", $slice_urn);
#
# In this implementation, the user must provide a slice credential,
# so we ignore the slice_urn. For CreateSliver(), the slice must not
......@@ -418,6 +420,8 @@ sub CreateSliver($)
return GeniResponse->Create(GENIRESPONSE_FORBIDDEN(), undef,
"Credential does not match the URN");
}
main::AddLogfileMetaData("slice_idx", $slice->idx());
#
# Watch for a placeholder slice and update it.
#
......@@ -456,6 +460,13 @@ sub CreateSliver($)
return $rspec
if (GeniResponse::IsResponse($rspec));
my $slice = GeniSlice->Lookup($credential->target_urn());
if (!defined($slice)) {
print STDERR "CreateSliver: Could not find slice for $credential\n";
return GeniResponse->Create(GENIRESPONSE_ERROR, undef,"Internal Error");
}
main::AddLogfileMetaData("slice_idx", $slice->idx());
# Make sure that the next phase sees all changes.
Experiment->FlushAll();
Node->FlushAll();
......@@ -470,12 +481,13 @@ sub CreateSliver($)
# up by the daemon. This is mostly cause I am reaching into
# the V1 code, and its messy.
#
my $slice = GeniSlice->Lookup($credential->target_urn());
if ($slice->Lock() != 0) {
print STDERR "CreateSliver: Could not lock $slice before delete\n";
return $response;
}
$slice = GeniSlice->Lookup($credential->target_urn());
if (defined($slice)) {
if ($slice->Lock() != 0) {
print STDERR
"CreateSliver: Could not lock $slice before delete\n";
return $response;
}
GeniCM::CleanupDeadSlice($slice, 1);
}
return $response;
......@@ -485,12 +497,6 @@ sub CreateSliver($)
#
# Leave the slice intact on error, so we can go look at it.
#
$slice = GeniSlice->Lookup($credential->target_urn());
if (!defined($slice)) {
print STDERR "CreateSliver: Could not find slice for $credential\n";
return GeniResponse->Create(GENIRESPONSE_ERROR, undef,
"Internal Error");
}
if ($slice->Lock() != 0) {
print STDERR "CreateSliver: Could not lock $slice before start\n";
return GeniResponse->Create(GENIRESPONSE_ERROR, undef,
......@@ -545,6 +551,8 @@ sub DeleteSliver($)
return $credential
if (GeniResponse::IsResponse($credential));
main::AddLogfileMetaData("sliver_urn", $sliver_urn);
#
# In this implementation, the user must provide a slice or sliver
# credential
......@@ -557,6 +565,9 @@ sub DeleteSliver($)
return GeniResponse->Create(GENIRESPONSE_SEARCHFAILED, undef,
"Sliver does not exist");
}
main::AddLogfileMetaData("slice_urn", $slice->urn());
main::AddLogfileMetaData("slice_idx", $slice->idx());
if ($sliver_urn ne $aggregate->urn()) {
return GeniResponse->Create(GENIRESPONSE_FORBIDDEN(), undef,
"Credential does not match the URN");
......@@ -661,6 +672,9 @@ sub DeleteSlice($)
return GeniResponse->Create(GENIRESPONSE_SEARCHFAILED, undef,
"No such slice here");
}
main::AddLogfileMetaData("slice_urn", $slice_urn);
main::AddLogfileMetaData("slice_idx", $slice->idx());
if ($slice_urn ne $slice->urn()) {
return GeniResponse->Create(GENIRESPONSE_FORBIDDEN(), undef,
"Credential does not match the URN");
......@@ -785,6 +799,11 @@ sub SliverAction($$$$$)
return $slice
if (defined($slice) && GeniResponse::IsResponse($slice));
if (defined($slice)) {
main::AddLogfileMetaData("slice_urn", $slice_urn);
main::AddLogfileMetaData("slice_idx", $slice->idx());
}
if ( (!defined($slice)) &&
($credential->target_urn() =~ /\+authority\+cm$/)) {
# administrative credentials are presented.
......@@ -999,6 +1018,9 @@ sub SliverStatus($)
return GeniResponse->Create(GENIRESPONSE_SEARCHFAILED, undef,
"No slice or aggregate here");
}
main::AddLogfileMetaData("slice_urn", $slice->urn());
main::AddLogfileMetaData("slice_idx", $slice->idx());
if ($slice_urn ne $slice->urn()) {
return GeniResponse->Create(GENIRESPONSE_FORBIDDEN(), undef,
"Credential does not match the URN");
......@@ -1111,6 +1133,9 @@ sub Shutdown($)
if (!defined($slice)) {
return GeniResponse->Create(GENIRESPONSE_SUCCESS);
}
main::AddLogfileMetaData("slice_urn", $slice_urn);
main::AddLogfileMetaData("slice_idx", $slice->idx());
#
# Do not worry about locking when setting the shutdown time.
# This can lead to race though, if a clear shutdown comes in first.
......@@ -1174,6 +1199,9 @@ sub RenewSlice($)
return GeniResponse->Create(GENIRESPONSE_BADARGS, undef,
"No slice or aggregate here");
}
main::AddLogfileMetaData("slice_urn", $slice_urn);
main::AddLogfileMetaData("slice_idx", $slice->idx());
if ($slice_urn ne $slice->urn()) {
return GeniResponse->Create(GENIRESPONSE_FORBIDDEN(), undef,
"Credential does not match the URN");
......@@ -1209,6 +1237,8 @@ sub GetTicket($)
return $credential
if (GeniResponse::IsResponse($credential));
main::AddLogfileMetaData("slice_urn", $slice_urn);
#
# This implementation requires a slice credential, and it must
# match the slice_urn.
......@@ -1218,6 +1248,8 @@ sub GetTicket($)
return $slice
if (GeniResponse::IsResponse($slice));
main::AddLogfileMetaData("slice_idx", $slice->idx());
if ($slice_urn ne $slice->urn()) {
return GeniResponse->Create(GENIRESPONSE_FORBIDDEN(), undef,
"Credential does not match the URN");
......@@ -1277,8 +1309,18 @@ sub GetTicket($)
else {
# Slice does not exist yet.
}
return GeniCM::GetTicketAux($credential,
$rspecstr, 0, $impotent, 1, 1, undef);
my $response =
GeniCM::GetTicketAux($credential, $rspecstr, 0, $impotent, 1, 1, undef);
return $response
if (GeniResponse::IsResponse($response));
$slice = GeniSlice->Lookup($slice_urn);
if (!defined($slice)) {
return GeniResponse->Create(GENIRESPONSE_SUCCESS);
}
main::AddLogfileMetaData("slice_idx", $slice->idx());
return $response;
}
#
......@@ -1304,6 +1346,8 @@ sub UpdateTicket($)
return $credential
if (GeniResponse::IsResponse($credential));
main::AddLogfileMetaData("slice_urn", $slice_urn);
defined($credential) &&
($credential->HasPrivilege( "pi" ) or
$credential->HasPrivilege( "instantiate" ) or
......@@ -1330,6 +1374,8 @@ sub UpdateTicket($)
return GeniResponse->Create(GENIRESPONSE_SEARCHFAILED(), undef,
"Slice does not exist here");
}
main::AddLogfileMetaData("slice_idx", $slice->idx());
if ($slice->IsExpired()) {
return GeniResponse->Create(GENIRESPONSE_REFUSED, undef,
"Slice has expired");
......@@ -1404,6 +1450,8 @@ sub UpdateSliver($)
return $credential
if (GeniResponse::IsResponse($credential));
main::AddLogfileMetaData("sliver_urn", $sliver_urn);
defined($credential) &&
($credential->HasPrivilege( "pi" ) or
$credential->HasPrivilege( "instantiate" ) or
......@@ -1419,6 +1467,9 @@ sub UpdateSliver($)
return GeniResponse->Create(GENIRESPONSE_BADARGS, undef,
"No slice or aggregate here");
}
main::AddLogfileMetaData("slice_urn", $slice->urn());
main::AddLogfileMetaData("slice_idx", $slice->idx());
# Must be an aggregate (top level sliver).
if (ref($aggregate) ne "GeniAggregate") {
return GeniResponse->MalformedArgsResponse("Must supply aggregate");
......@@ -1499,6 +1550,9 @@ sub RedeemTicket($)
return GeniResponse->Create(GENIRESPONSE_BADARGS, undef,
"No slice here");
}
main::AddLogfileMetaData("slice_urn", $slice_urn);
main::AddLogfileMetaData("slice_idx", $slice->idx());
my $open_ticket = GeniTicket->SliceTicket($slice);
if (! defined($open_ticket) || $open_ticket->idx() ne $ticket->idx()) {
return GeniResponse->Create(GENIRESPONSE_BADARGS, undef,
......@@ -1603,6 +1657,9 @@ sub ReleaseTicket($)
return GeniResponse->Create(GENIRESPONSE_SEARCHFAILED, undef,
"No slice here");
}
main::AddLogfileMetaData("slice_urn", $slice_urn);
main::AddLogfileMetaData("slice_idx", $slice->idx());
if ($slice_urn ne $slice->urn()) {
return GeniResponse->Create(GENIRESPONSE_FORBIDDEN(), undef,
"Credential does not match the URN");
......@@ -1770,6 +1827,9 @@ sub ReserveVlanTags($)
return GeniResponse->BusyResponse();
}
}
main::AddLogfileMetaData("slice_urn", $slice_urn);
main::AddLogfileMetaData("slice_idx", $slice->idx());
#
# Confirm that the certificate is the same.
#
......@@ -2253,6 +2313,9 @@ sub InjectEvent($)
return GeniResponse->Create(GENIRESPONSE_SEARCHFAILED, undef,
"Sliver does not exist");
}
main::AddLogfileMetaData("slice_urn", $slice_urn);
main::AddLogfileMetaData("slice_idx", $slice->idx());
if ($slice_urn ne $slice->urn()) {
return GeniResponse->Create(GENIRESPONSE_FORBIDDEN(), undef,
"Credential does not match the URN");
......@@ -2310,6 +2373,9 @@ sub CreateImage($)
return $slice
if (defined($slice) && GeniResponse::IsResponse($slice));
main::AddLogfileMetaData("slice_urn", $slice_urn);
main::AddLogfileMetaData("slice_idx", $slice->idx());
if (! (defined($slice) && defined($aggregate))) {
return GeniResponse->Create(GENIRESPONSE_SEARCHFAILED, undef,
"Slice does not exist");
......@@ -2457,6 +2523,8 @@ sub DeleteImage($)
return $credential
if (GeniResponse::IsResponse($credential));
main::AddLogfileMetaData("image_urn", $image_urn);
my $user = GeniCM::CreateUserFromCertificate($credential);
return $user
if (GeniResponse::IsResponse($user));
......
......@@ -55,10 +55,12 @@ BEGIN {
# Configure variables
my $MAINSITE = @TBMAINSITE@;
my $TBOPS = "@TBOPSEMAIL@";
my $TBLOGS = "@TBLOGSEMAIL@";
my $PORTAL_ENABLE = @PORTAL_ENABLE@;
my $PORTAL_ISPRIMARY = @PORTAL_ISPRIMARY@;
my $TBBASE = "@TBBASE@";
my $GENIGROUP = "GeniSlices";
my $PGERRORS = "protogeni-errors\@flux.utah.edu";
my $MODULE;
my $GENIURN;
......@@ -99,9 +101,13 @@ use Group;
# Need a command line option.
my $debug = 0;
my $mailerrors = 1;
my $mailsendlog= 0;
my $nostorelogs= 0;
# Flag for XMLERROR.
my $logging = 0;
my $logforked = 0;
my $iserror = 0;
my $rpcerror = 0;
# Determined by version.
my $responder;
......@@ -321,6 +327,28 @@ if( $PROJECT ) {
$ENV{'MYURN'} = $certificate->urn();
}
# Look at sitevars to determine debugging level.
my $sitevarname = "protogeni/wrapper_" . lc($MODULE) . "_debug_level";
if (SiteVarExists($sitevarname)) {
my $debug_level;
if (GetSiteVar($sitevarname, \$debug_level) == 0) {
$debug = $debug_level
if (defined($debug_level));
}
}
elsif ($MODULE eq "emulab") {
# XXX Special case, obviously
$debug = 2;
}
# Override default setting above.
if (SiteVarExists("protogeni/wrapper_debug_sendlog")) {
my $debug_sendlog;
if (GetSiteVar("protogeni/wrapper_debug_sendlog", \$debug_sendlog) == 0) {
$mailsendlog = $debug_sendlog
if (defined($debug_sendlog));
}
}
#
# Create and set our RPC context for any calls we end up making.
#
......@@ -356,6 +384,14 @@ my @metadata = ();
#
sub WrapperFork()
{
# Need this in the child.
my $parent_lockname = "lock_$PID";
# Before the fork, lock the lock in the parent. It will be
# unlocked just before the parent exits, this informing the
# child.
emdb::DBQueryWarn("select GET_LOCK('$parent_lockname', 5)");
my $mypid = fork();
if ($mypid) {
# Flag for below (parent only).
......@@ -364,9 +400,10 @@ sub WrapperFork()
# Tell caller we are the parent,
return $mypid;
}
# XXX Need to let the parent finish up first. Might need to
# get more fancy.
sleep(2);
# XXX Need to let the parent finish up first, but the parent is
# is in the "defunct" state, so cannot use kill(0) to figure out
# it is gone.
emdb::DBQueryWarn("select GET_LOCK('$parent_lockname', 15)");
# This switches the file that we are writing to in the child.
libaudit::AuditFork();
......@@ -374,12 +411,30 @@ sub WrapperFork()
}
#
# Use libaudit to capture any output from libraries and programs.
# Send that to tbops so they can be fixed.
# Upcall to set the slice urn in the logfile metadata. Difficult to
# know so let the callee tell us.
#
sub AddLogfileMetaData($$)
{
my ($key, $val) = @_;
# We want to watch for duplicates,
foreach my $foo (@metadata) {
my ($metakey,$metaval) = @{$foo};
return
if ($key eq $metakey);
}
push(@metadata, [$key, $val]);
}
#
# Use libaudit to capture any output from libraries and programs. We
# do not let it send the email though, we do that below, unless it
# exits abnormally via the END block.
#
if ($MAINSITE) {
LogStart(0, $logfile->filename(), LIBAUDIT_NODELETE());
AddAuditInfo("to", "protogeni-errors\@flux.utah.edu")
AddAuditInfo("to", $PGERRORS);
}
else {
LogStart(0, $logfile->filename(), LIBAUDIT_LOGTBLOGS()|LIBAUDIT_NODELETE());
......@@ -387,7 +442,7 @@ else {
$logging = 1;
# CC errors to Utah for now.
AddAuditInfo("cc", "protogeni-errors\@flux.utah.edu");
AddAuditInfo("cc", $PGERRORS);
#
# This is lifted from the Frontier code. I want the actual response
......@@ -411,54 +466,38 @@ my $method = $call->{'method_name'};
if (!defined($GENI_METHODS->{$method})) {
XMLError(XMLRPC_APPLICATION_ERROR() + 3, "no such method $method\n");
}
# Strictly for debugging the CM.
my $target;
if (defined($call->{'value'})) {
my ($argref) = @{ $call->{'value'} };
if (ref($argref) eq "HASH") {
if (exists($argref->{'slice_urn'})) {
$target = $argref->{'slice_urn'};
}
elsif (exists($argref->{'sliver_urn'})) {
$target = $argref->{'sliver_urn'};
}
}
# Debugging overrides, to avoid email blasting.
# Too much output.
if ($method eq "ListResources" ||
$method eq "GetVersion" ||
$method eq "GetKeys" ||
$method eq "RegisterSliver" ||
$method eq "UnRegisterSliver" ||
$method eq "GetCredential" ||
$method eq "Resolve" ||
$method eq "DiscoverResources") {
$debug = 0;
# Do no even bother with logs unless an error.
$nostorelogs = 1;
}
# Happens too often and not interesting unless an error.
if ($method eq "Resolve") {
$debug = 0;
}
# We always want as much data as possible for these.
if ($method eq "CreateSliver" ||
$method eq "RedeemTicket" ||
$method eq "GetTicket") {
$debug = 2;
}
my $result;
push(@metadata, ["URN", $GENIURN]);
push(@metadata, ["Target", $target]) if (defined($target));
push(@metadata, ["Module", $MODULE]);
push(@metadata, ["Method", $method]);
push(@metadata, ["Version", $GENI_VERSION]) if (defined($GENI_VERSION));
push(@metadata, ["StartTime", TBTimeStamp()]);
# Debug the CM and AM modules
if ($MODULE eq "cm" || $MODULE eq $AM_MODULE) {
$debug = 0;
# Too much output.
if ($method eq "ListResources" ||
$method eq "DiscoverResources") {
$debug = 0;
}
# Happens too often and not interesting
if ($method eq "Resolve" ||
$method eq "SliverStatus" ||
$method eq "GetVersion") {
$debug = 0;
}
# We always want as much data as possible for these.
if ($method eq "CreateSliver" ||
$method eq "RedeemTicket" ||
$method eq "GetTicket") {
$debug = 2;
}
}
elsif ($MODULE eq "emulab") {
$debug = 2;
}
my $starttime = [gettimeofday()];
eval { $result = &{ $GENI_METHODS->{$method} }(@{ $call->{'value'} }) };
if ($@) {
......@@ -468,8 +507,8 @@ if ($@) {
#
# These errors should get mailed to tbops.
#
$rpcerror = $iserror = 1;
print STDERR "Error executing RPC method $method:\n" . $@ . "\n";
AddAuditInfo("to", $TBOPS);
$response = $decoder->encode_fault(XMLRPC_SERVER_ERROR(),
"Internal Error executing $method");
......@@ -478,8 +517,6 @@ if ($@) {
my ($key,$val) = @{$foo};
$message .= sprintf("%-15s: %s\n", $key, $val);
}
AddAuditInfo("message", $message .
"Error executing RPC:\n" . $@ . "\n\n" . $request);
}
else {
# In case the callee flipped.
......@@ -506,6 +543,12 @@ else {
push(@metadata, ["Code", $result->{'code'}])
}
}
# Add first line of result output to metadata. Bigger stuff
# will land at the end of the file.
if (ref($result) && defined($result->{'output'}) &&
$result->{'output'} ne "") {
push(@metadata, ["Output", ( split /\n/, $result->{'output'} )[0]]);
}
# Purge old data; if we forked we want latest.
$logfile->SetMetadata(\@metadata, 1);
......@@ -513,52 +556,56 @@ else {
my ($key,$val) = @{$foo};
$message .= sprintf("%-15s: %s\n", $key, $val);
}
AddAuditInfo("message", $message);
if (ref($result)) {
$message .= "Output: " . $result->{'output'} . "\n"
if (defined($result->{'output'}) && $result->{'output'} ne "");
if (GeniResponse::IsError($result) || $debug > 1) {
$message .= "Result:\n" . Dumper($result->{'value'}) . "\n\n";
# Do not send debugging mail for these two errors and do not save
# the logfiles.
if (GeniResponse::IsError($result)) {
if ($result->{'code'} == GENIRESPONSE_SEARCHFAILED() ||