--- loncom/metadata_database/parse_activity_log.pl 2004/08/11 18:37:23 1.1 +++ loncom/metadata_database/parse_activity_log.pl 2004/08/18 19:33:27 1.2 @@ -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 @@ use Getopt::Long(); # # 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<$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 @@ if ($file) { $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 @@ $sql_filename =~ s|[^/]*$|activitylog.sq 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 @@ my $activity_table_def = 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 @@ my @Activity_Tables = ($student_table_de $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 @@ if (-e $sql_filename) { # 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 @@ if (-e $newfilename) { 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 @@ if (-e $newfilename) { 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 @@ sub process_courselog { 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 @@ sub process_courselog { $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 @@ sub process_courselog { $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 @@ sub process_courselog { 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 @@ sub process_courselog { my %Timing; my $starttime; -sub nothing { - return; -} - sub time_action { my ($key) = @_; if (defined($key)) { @@ -457,7 +548,7 @@ sub backup_tables { $command .= $tablename.' '; } $command .= '>'.$sql_filename; - warn $command.$/; + $logthis->($command); system($command); } @@ -469,7 +560,7 @@ sub load_backup_tables { 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 @@ sub get_id { $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 @@ sub unescape { $str =~ s/%([a-fA-F0-9][a-fA-F0-9])/pack("C",hex($1))/eg; return $str; } -