[LON-CAPA-cvs] cvs: loncom /metadata_database parse_activity_log.pl
matthew
lon-capa-cvs@mail.lon-capa.org
Wed, 18 Aug 2004 19:33:27 -0000
This is a MIME encoded message
--matthew1092857607
Content-Type: text/plain
matthew Wed Aug 18 15:33:27 2004 EDT
Modified files:
/loncom/metadata_database parse_activity_log.pl
Log:
Added logging code.
--matthew1092857607
Content-Type: text/plain
Content-Disposition: attachment; filename="matthew-20040818153327.txt"
Index: loncom/metadata_database/parse_activity_log.pl
diff -u loncom/metadata_database/parse_activity_log.pl:1.1 loncom/metadata_database/parse_activity_log.pl:1.2
--- loncom/metadata_database/parse_activity_log.pl:1.1 Wed Aug 11 14:37:23 2004
+++ loncom/metadata_database/parse_activity_log.pl Wed Aug 18 15:33:27 2004
@@ -2,7 +2,7 @@
#
# The LearningOnline Network
#
-# $Id: parse_activity_log.pl,v 1.1 2004/08/11 18:37:23 matthew Exp $
+# $Id: parse_activity_log.pl,v 1.2 2004/08/18 19:33:27 matthew Exp $
#
# Copyright Michigan State University Board of Trustees
#
@@ -55,14 +55,15 @@
#
# Determine parameters
-my ($help,$course,$domain,$drop,$file,$time_run,$nocleanup);
+my ($help,$course,$domain,$drop,$file,$time_run,$nocleanup,$log);
&Getopt::Long::GetOptions( "course=s" => \$course,
"domain=s" => \$domain,
"help" => \$help,
"logfile=s" => \$file,
"timerun" => \$time_run,
"nocleanup" => \$nocleanup,
- "drop" => \$drop);
+ "drop" => \$drop,
+ "log" => \$log);
if (! defined($course) || $help) {
print<<USAGE;
parse_activity_log.pl
@@ -76,6 +77,7 @@
file optional Specify the file to parse, including path
time optional if present, print out timing data
nocleanup optional if present, do not remove old files
+ log optional if present, prepare log file of activity
Examples:
$0 -course=123456abcdef -domain=msu
$0 -course=123456abcdef -file=activity.log
@@ -93,6 +95,19 @@
my $initial_time = Time::HiRes::time;
##
+## Set up logging code
+##
+my $logthis = \¬hing;
+if ($log) {
+ my $logfile = "/tmp/parse_activity_log.log.".time;
+ print STDERR "$0: logging to $logfile".$/;
+ if (! open(LOGFILE,">$logfile")) {
+ die "Unable to open $logfile for writing. Run aborted.";
+ } else {
+ $logthis = \&log_to_file;
+ }
+}
+##
## Read in configuration parameters
##
my %perlvar;
@@ -114,7 +129,7 @@
$sourcefilename = &get_filename($course,$domain);
}
$sql_filename = $sourcefilename;
-$sql_filename =~ s|[^/]*$|activitylog.sql|;
+$sql_filename =~ s|[^/]*$|activity.log.sql|;
##
## There will only be a $newfilename file if a copy of this program is already
@@ -122,11 +137,13 @@
my $newfilename = $sourcefilename.'.processing';
if (-e $newfilename) {
warn "$newfilename exists";
+ $logthis->($newfilename.' exists');
exit 2;
}
if (-e $sourcefilename) {
rename($sourcefilename,$newfilename);
+ $logthis->("renamed $sourcefilename to $newfilename");
}
##
@@ -206,17 +223,17 @@
type => 'DATETIME',
restrictions => 'NOT NULL',},
{ name => 'student_id',
- type => 'VARCHAR(100) BINARY',
+ type => 'MEDIUMINT UNSIGNED',
restrictions => 'NOT NULL',},
{ name => 'action_id',
- type => 'VARCHAR(100) BINARY',
+ type => 'MEDIUMINT UNSIGNED',
restrictions => 'NOT NULL',},
{ name => 'idx', # This is here in case a student
type => 'MEDIUMINT UNSIGNED', # has multiple submissions during
restrictions => 'NOT NULL', # one second. It happens, trust
auto_inc => 'yes', }, # me.
{ name => 'machine_id',
- type => 'VARCHAR(100) BINARY',
+ type => 'MEDIUMINT UNSIGNED',
restrictions => 'NOT NULL',},
{ name => 'action_values',
type => 'MEDIUMTEXT', },
@@ -237,11 +254,13 @@
$perlvar{'lonSqlAccess'});
if (!&Apache::lonmysql::verify_sql_connection()) {
warn "Unable to connect to MySQL database.";
+ $logthis->("Unable to connect to MySQL database.");
exit 3;
}
-if ($drop) { &drop_tables(); }
+if ($drop) { &drop_tables(); $logthis->('dropped tables'); }
if (-e $sql_filename) {
+ $logthis->('reading in from '.$sql_filename);
# if ANY one of the tables does not exist, load the tables from the
# backup.
my @Current_Tables = &Apache::lonmysql::tables_in_db();
@@ -266,10 +285,13 @@
# create_tables does not complain if the tables already exist
if (! &create_tables()) {
warn "Unable to create tables";
+ $logthis->('Unable to create tables');
exit 4;
}
+$logthis->('reading id tables');
&read_id_tables();
+$logthis->('finished reading id tables');
##
## Do the main bit of work
@@ -277,9 +299,11 @@
my $result = &process_courselog($newfilename);
if (! defined($result)) {
# Something went wrong along the way...
+ $logthis->('process_courselog returned undef');
exit 5;
} elsif ($result > 0) {
$time_this->();
+ $logthis->('process_courselog returned '.$result.' backup up tables');
&backup_tables($sql_filename);
$time_this->('write backup tables');
}
@@ -292,8 +316,15 @@
unlink($newfilename) if (! $nocleanup);
if ($time_run) {
- print "Overall time: ".(Time::HiRes::time - $initial_time).$/;
+ my $elapsed_time = Time::HiRes::time - $initial_time;
+ print "Overall time: ".$elapsed_time.$/;
print &outputtimes();
+ $logthis->("Overall time: ".$elapsed_time);
+ $logthis->(&outputtimes());
+}
+
+if ($log) {
+ close LOGFILE;
}
exit 0; # Everything is okay, so end here before it gets worse.
@@ -311,6 +342,7 @@
my ($inputfile) = @_;
if (! open(IN,$inputfile)) {
warn "Unable to open '$inputfile' for reading";
+ $logthis->("Unable to open '$inputfile' for reading");
return undef;
}
my ($linecount,$insertcount);
@@ -341,26 +373,68 @@
$log = &unescape($log);
$time_this->('translate_and_unescape');
# now go over all log entries
+ if (! defined($host)) { $host = 'unknown'; }
my $machine_id = &get_id($machine_table,'machine',$host);
- foreach (split(/\&\&\&/,$log)) {
+ my $prevchunk = 'none';
+ foreach my $chunk (split(/\&\&\&/,$log)) {
+ my $warningflag = '';
$time_this->();
- my ($time,$res,$uname,$udom,$action,@values)= split(/:/,$_);
+ my ($time,$res,$uname,$udom,$action,@values)= split(/:/,$chunk);
+ my $student = $uname.':'.$udom;
if (! defined($res) || $res =~ /^\s*$/) {
$res = '/adm/roles';
- $action = 'log in';
+ $action = 'LOGIN';
+# $warningflag .= 'res';
}
if ($res =~ m|^/prtspool/|) {
$res = '/prtspool/';
}
if (! defined($action) || $action eq '') {
- $action = 'view';
+ $action = 'VIEW';
+# $warningflag .= 'action';
}
- my $student = $uname.':'.$udom;
+ if ($action !~ /^(LOGIN|VIEW|POST|CSTORE|STORE)$/) {
+ $warningflag .= 'action';
+ }
+ if (! defined($student) || $student eq ':') {
+ $student = 'unknown';
+ $warningflag .= 'student';
+ }
+ if (! defined($res) || $res =~ /^\s*$/) {
+ $res = 'unknown';
+ $warningflag .= 'res';
+ }
+ if (! defined($action) || $action =~ /^\s*$/) {
+ $action = 'unknown';
+ $warningflag .= 'action';
+ }
+ if (! defined($time) || $time !~ /^\d+$/) {
+ $time = 0;
+ $warningflag .= 'time';
+ }
+ #
$time_this->('split_and_error_check');
my $student_id = &get_id($student_table,'student',$student);
my $res_id = &get_id($res_table,'resource',$res);
my $action_id = &get_id($action_table,'action',$action);
my $sql_time = &Apache::lonmysql::sqltime($time);
+ #
+ if (! defined($student_id) || $student_id eq '') {
+ $warningflag.='student_id';
+ }
+ if (! defined($res_id) || $res_id eq '') {
+ $warningflag.='res_id';
+ }
+ if (! defined($action_id) || $action_id eq '') {
+ $warningflag.='action_id';
+ }
+ if ($warningflag ne '') {
+ $logthis->('warningflag ('.$warningflag.') on chunk '.
+ $/.$chunk.$/.'prevchunk = '.$/.$prevchunk);
+ $prevchunk .= $chunk;
+ next; # skip this chunk
+ }
+ #
my $values = $dbh->quote(join('',@values));
$time_this->('get_ids');
#
@@ -373,30 +447,36 @@
$values];
push(@RowData,$row);
$time_this->('push_row');
+ $prevchunk = $chunk;
#
}
$time_this->();
- if ($linecount % 100 == 0) {
+ if ((scalar(@RowData) > 0) && ($linecount % 100 == 0)) {
my $result = &Apache::lonmysql::bulk_store_rows($activity_table,
undef,
\@RowData);
+ # $logthis->('result = '.$result);
$time_this->('bulk_store_rows');
if (! defined($result)) {
- warn "Error occured during insert.".
- &Apache::lonmysql::get_error();
+ my $error = &Apache::lonmysql::get_error();
+ warn "Error occured during insert.".$error;
+ $logthis->('error = '.$error);
}
undef(@RowData);
}
}
if (@RowData) {
$time_this->();
+ $logthis->('storing '.$linecount);
my $result = &Apache::lonmysql::bulk_store_rows($activity_table,
undef,
\@RowData);
+ $logthis->('result = '.$result);
$time_this->('bulk_store_rows');
if (! defined($result)) {
- warn "Error occured during insert.".
- &Apache::lonmysql::get_error();
+ my $error = &Apache::lonmysql::get_error();
+ warn "Error occured during insert.".$error;
+ $logthis->('error = '.$error);
}
undef(@RowData);
}
@@ -406,6 +486,21 @@
return $linecount;
}
+
+##
+## Somtimes, instead of doing something, doing nothing is appropriate.
+sub nothing {
+ return;
+}
+
+##
+## Logging routine
+##
+sub log_to_file {
+ my ($input)=@_;
+ print LOGFILE $input.$/;
+}
+
##
## Timing routines
##
@@ -413,10 +508,6 @@
my %Timing;
my $starttime;
-sub nothing {
- return;
-}
-
sub time_action {
my ($key) = @_;
if (defined($key)) {
@@ -457,7 +548,7 @@
$command .= $tablename.' ';
}
$command .= '>'.$sql_filename;
- warn $command.$/;
+ $logthis->($command);
system($command);
}
@@ -469,7 +560,7 @@
return undef if (! -e $sql_filename);
# Check for .my.cnf
my $command = 'mysql -e "SOURCE '.$sql_filename.'" loncapa';
- warn $command.$/;
+ $logthis->('loading previously saved sql table'.$/.$command);
system($command);
}
@@ -551,7 +642,7 @@
$IDs{$table}->{$value}=$Data[0]->[0];
return $IDs{$table}->{$value};
} else {
- warn "Unable to retrieve id for $table $fieldname $value".$/;
+ $logthis->("Unable to retrieve id for $table $fieldname $value");
return undef;
}
}
@@ -578,4 +669,3 @@
$str =~ s/%([a-fA-F0-9][a-fA-F0-9])/pack("C",hex($1))/eg;
return $str;
}
-
--matthew1092857607--