[BACK]Return to parse_activity_log.pl CVS log [TXT] [DIR] Up to [LON-CAPA] / loncom / metadata_database

Diff for /loncom/metadata_database/parse_activity_log.pl between versions 1.1 and 1.3

version 1.1, 2004/08/11 18:37:23 version 1.3, 2004/08/19 21:08:46
Line 26 Line 26
 #  #
 # http://www.lon-capa.org/  # http://www.lon-capa.org/
 #  #
 ###############################################################################  #--------------------------------------------------------------------
 #  
 # Expects  
 #  
 # ../key/$class.key - key file $username:$keynumber  
 # ../rawdata/$class.log - log file  
 # ../rawdata/$class.seq - sequence file  
 # ../data writable  
 # ------------------------------------------------------------------ Course log  
   
 #  #
 # Exit codes  # Exit codes
 #   0     Everything is okay  #   0     Everything is okay
Line 52  use lib '/home/httpd/lib/perl/Apache'; Line 43  use lib '/home/httpd/lib/perl/Apache';
 use lonmysql();  use lonmysql();
 use Time::HiRes();  use Time::HiRes();
 use Getopt::Long();  use Getopt::Long();
   use IO::File;
   
 #  #
 # Determine parameters  # 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,  &Getopt::Long::GetOptions( "course=s"  => \$course,
                            "domain=s"  => \$domain,                             "domain=s"  => \$domain,
                            "help"      => \$help,                             "help"      => \$help,
                            "logfile=s" => \$file,                             "logfile=s" => \$file,
                            "timerun"   => \$time_run,                             "timerun"   => \$time_run,
                            "nocleanup" => \$nocleanup,                             "nocleanup" => \$nocleanup,
                            "drop"      => \$drop);                             "drop"      => \$drop,
                              "log"       => \$log);
 if (! defined($course) || $help) {  if (! defined($course) || $help) {
     print<<USAGE;      print<<USAGE;
 parse_activity_log.pl  parse_activity_log.pl
Line 76  Parameters: Line 69  Parameters:
    file               optional   Specify the file to parse, including path     file               optional   Specify the file to parse, including path
    time               optional   if present, print out timing data     time               optional   if present, print out timing data
    nocleanup          optional   if present, do not remove old files     nocleanup          optional   if present, do not remove old files
      log                optional   if present, prepare log file of activity
 Examples:  Examples:
   $0 -course=123456abcdef -domain=msu    $0 -course=123456abcdef -domain=msu
   $0 -course=123456abcdef -file=activity.log    $0 -course=123456abcdef -file=activity.log
Line 85  USAGE Line 79  USAGE
   
 ##  ##
 ## Set up timing code  ## Set up timing code
 ##  
 my $time_this = \&nothing;  my $time_this = \&nothing;
 if ($time_run) {  if ($time_run) {
     $time_this = \&time_action;      $time_this = \&time_action;
Line 103  if (! defined($domain) || $domain eq '') Line 96  if (! defined($domain) || $domain eq '')
 &update_process_name($course.'@'.$domain);  &update_process_name($course.'@'.$domain);
   
 ##  ##
   ## Set up logging code
   my $logthis = \&nothing;
   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;
       }
   }
   
   
   ##
 ## Determine filenames  ## Determine filenames
 ##  ##
 my $sourcefilename;   # activity log data  my $sourcefilename;   # activity log data
 my $newfilename;      # $sourcefilename will be renamed to this  my $newfilename;      # $sourcefilename will be renamed to this
 my $sql_filename;  # the mysql backup data file name.  my $sql_filename;     # the mysql backup data file name.
   my $error_filename;   # Errors in parsing the activity log will be written here
 if ($file) {  if ($file) {
     $sourcefilename = $file;      $sourcefilename = $file;
 } else {  } else {
     $sourcefilename = &get_filename($course,$domain);      $sourcefilename = &get_filename($course,$domain);
 }  }
 $sql_filename = $sourcefilename;  $sql_filename = $sourcefilename;
 $sql_filename =~ s|[^/]*$|activitylog.sql|;  $sql_filename =~ s|[^/]*$|activity.log.sql|;
   $error_filename = $sourcefilename;
   $error_filename =~ s|[^/]*$|activity.log.errors|;
   $logthis->('Beginning logging '.time);
   
 ##  ##
 ## There will only be a $newfilename file if a copy of this program is already  ## There will only be a $newfilename file if a copy of this program is already
Line 122  $sql_filename =~ s|[^/]*$|activitylog.sq Line 133  $sql_filename =~ s|[^/]*$|activitylog.sq
 my $newfilename = $sourcefilename.'.processing';  my $newfilename = $sourcefilename.'.processing';
 if (-e $newfilename) {  if (-e $newfilename) {
     warn "$newfilename exists";      warn "$newfilename exists";
       $logthis->($newfilename.' exists');
     exit 2;      exit 2;
 }  }
   
 if (-e $sourcefilename) {  if (-e $sourcefilename) {
       $logthis->('renaming '.$sourcefilename.' to '.$newfilename);
     rename($sourcefilename,$newfilename);      rename($sourcefilename,$newfilename);
       $logthis->("renamed $sourcefilename to $newfilename");
   } else {
       my $command = 'touch '.$newfilename;
       $logthis->($command);
       system($command);
       $logthis->('touch was completed');
 }  }
   
 ##  ##
Line 206  my $activity_table_def = Line 225  my $activity_table_def =
                 type => 'DATETIME',                  type => 'DATETIME',
                 restrictions => 'NOT NULL',},                  restrictions => 'NOT NULL',},
               { name => 'student_id',                { name => 'student_id',
                 type => 'VARCHAR(100) BINARY',                  type => 'MEDIUMINT UNSIGNED',
                 restrictions => 'NOT NULL',},                  restrictions => 'NOT NULL',},
               { name => 'action_id',                { name => 'action_id',
                 type => 'VARCHAR(100) BINARY',                  type => 'MEDIUMINT UNSIGNED',
                 restrictions => 'NOT NULL',},                  restrictions => 'NOT NULL',},
               { name => 'idx',                # This is here in case a student                { name => 'idx',                # This is here in case a student
                 type => 'MEDIUMINT UNSIGNED', # has multiple submissions during                  type => 'MEDIUMINT UNSIGNED', # has multiple submissions during
                 restrictions => 'NOT NULL',   # one second.  It happens, trust                  restrictions => 'NOT NULL',   # one second.  It happens, trust
                 auto_inc     => 'yes', },     # me.                  auto_inc     => 'yes', },     # me.
               { name => 'machine_id',                { name => 'machine_id',
                 type => 'VARCHAR(100) BINARY',                  type => 'MEDIUMINT UNSIGNED',
                 restrictions => 'NOT NULL',},                  restrictions => 'NOT NULL',},
               { name => 'action_values',                { name => 'action_values',
                 type => 'MEDIUMTEXT', },                  type => 'MEDIUMTEXT', },
               ],                 ], 
       'PRIMARY KEY' => ['res_id','time','student_id','action_id','idx'],        'PRIMARY KEY' => ['res_id','time','student_id','action_id','idx'],
 };  };
 my @Activity_Tables = ($student_table_def,$res_table_def,  my @Activity_Table = ($activity_table_def);
                        $action_table_def,$machine_table_def,  my @ID_Tables = ($student_table_def,$res_table_def,
                        $activity_table_def);                   $action_table_def,$machine_table_def);
                          
   
 ##  ##
 ## End of table definitions  ## End of table definitions
 ##  ##
   
 #   # 
   $logthis->('Connectiong to mysql');
 &Apache::lonmysql::set_mysql_user_and_password($perlvar{'lonSqlUser'},  &Apache::lonmysql::set_mysql_user_and_password($perlvar{'lonSqlUser'},
                                                $perlvar{'lonSqlAccess'});                                                 $perlvar{'lonSqlAccess'});
 if (!&Apache::lonmysql::verify_sql_connection()) {  if (!&Apache::lonmysql::verify_sql_connection()) {
     warn "Unable to connect to MySQL database.";      warn "Unable to connect to MySQL database.";
       $logthis->("Unable to connect to MySQL database.");
     exit 3;      exit 3;
 }  }
   
 if ($drop) { &drop_tables(); }  $logthis->('SQL connection is up');
 if (-e $sql_filename) {  
   if ($drop) { &drop_tables(); $logthis->('dropped tables'); }
   
   if (-s $sql_filename) {
     # if ANY one of the tables does not exist, load the tables from the      # if ANY one of the tables does not exist, load the tables from the
     # backup.      # backup.
     my @Current_Tables = &Apache::lonmysql::tables_in_db();      my @Current_Tables = &Apache::lonmysql::tables_in_db();
     my %Found;      my %Found;
     foreach my $tablename (@Current_Tables) {      foreach my $tablename (@Current_Tables) {
         foreach my $table (@Activity_Tables) {          foreach my $table (@Activity_Table,@ID_Tables) {
             if ($tablename eq  $table->{'id'}) {              if ($tablename eq  $table->{'id'}) {
                 $Found{$tablename}++;                  $Found{$tablename}++;
             }              }
         }          }
     }      }
     foreach my $table (@Activity_Tables) {          foreach my $table (@Activity_Table,@ID_Tables) {    
         if (! $Found{$table->{'id'}}) {          if (! $Found{$table->{'id'}}) {
             $time_this->();              $time_this->();
             &load_backup_tables($sql_filename);              &load_backup_tables($sql_filename);
Line 263  if (-e $sql_filename) { Line 287  if (-e $sql_filename) {
     }      }
 }  }
   
   ##
   ## Ensure the tables we need exist
 # create_tables does not complain if the tables already exist  # create_tables does not complain if the tables already exist
   $logthis->('creating tables');
 if (! &create_tables()) {  if (! &create_tables()) {
     warn "Unable to create tables";      warn "Unable to create tables";
       $logthis->('Unable to create tables');
     exit 4;      exit 4;
 }  }
   
   ##
   ## Read the ids used for various tables
   $logthis->('reading id tables');
 &read_id_tables();  &read_id_tables();
   $logthis->('finished reading id tables');
   
 ##  ##
 ## Do the main bit of work  ## Set up the errors file
 if (-e $newfilename) {  my $error_fh = IO::File->new(">>$error_filename");
     my $result = &process_courselog($newfilename);  
   ##
   ## Parse the course log
   $logthis->('processing course log');
   if (-s $newfilename) {
       my $result = &process_courselog($newfilename,$error_fh);
     if (! defined($result)) {      if (! defined($result)) {
         # Something went wrong along the way...          # Something went wrong along the way...
           $logthis->('process_courselog returned undef');
         exit 5;          exit 5;
     } elsif ($result > 0) {      } elsif ($result > 0) {
         $time_this->();          $time_this->();
           $logthis->('process_courselog returned '.$result.' backup up tables');
         &backup_tables($sql_filename);          &backup_tables($sql_filename);
         $time_this->('write backup tables');          $time_this->('write backup tables');
     }      }
 }  }
   close($error_fh);
   
 ##  ##
 ## Clean up the filesystem  ## Clean up the filesystem
 ##  
 &Apache::lonmysql::disconnect_from_db();  &Apache::lonmysql::disconnect_from_db();
 unlink($newfilename) if (! $nocleanup);  unlink($newfilename) if (-e $newfilename && ! $nocleanup);
   
   ##
   ## Print timing data
   $logthis->('printing timing data');
 if ($time_run) {  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();      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.  exit 0;   # Everything is okay, so end here before it gets worse.
Line 308  exit 0;   # Everything is okay, so end h Line 357  exit 0;   # Everything is okay, so end h
 #  #
 # Returns the number of lines in the activity.log file that were processed.  # Returns the number of lines in the activity.log file that were processed.
 sub process_courselog {  sub process_courselog {
     my ($inputfile) = @_;      my ($inputfile,$error_fh) = @_;
     if (! open(IN,$inputfile)) {      if (! open(IN,$inputfile)) {
         warn "Unable to open '$inputfile' for reading";          warn "Unable to open '$inputfile' for reading";
           $logthis->("Unable to open '$inputfile' for reading");
         return undef;          return undef;
     }      }
     my ($linecount,$insertcount);      my ($linecount,$insertcount);
Line 341  sub process_courselog { Line 391  sub process_courselog {
         $log = &unescape($log);          $log = &unescape($log);
         $time_this->('translate_and_unescape');          $time_this->('translate_and_unescape');
         # now go over all log entries           # now go over all log entries 
           if (! defined($host)) { $host = 'unknown'; }
         my $machine_id = &get_id($machine_table,'machine',$host);          my $machine_id = &get_id($machine_table,'machine',$host);
         foreach (split(/\&\&\&/,$log)) {          my $prevchunk = 'none';
           foreach my $chunk (split(/\&\&\&/,$log)) {
               my $warningflag = '';
             $time_this->();              $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*$/) {              if (! defined($res) || $res =~ /^\s*$/) {
                 $res = '/adm/roles';                  $res = '/adm/roles';
                 $action = 'log in';                  $action = 'LOGIN';
             }              }
             if ($res =~ m|^/prtspool/|) {              if ($res =~ m|^/prtspool/|) {
                 $res = '/prtspool/';                  $res = '/prtspool/';
             }              }
             if (! defined($action) || $action eq '') {              if (! defined($action) || $action eq '') {
                 $action = 'view';                  $action = 'VIEW';
             }              }
             my $student = $uname.':'.$udom;              if ($action !~ /^(LOGIN|VIEW|POST|CSTORE|STORE)$/) {
                   $warningflag .= 'action';
                   print $error_fh 'full log entry:'.$log.$/;
                   print $error_fh 'error on chunk:'.$chunk.$/;
                   $logthis->('(action) Unable to parse '.$/.$chunk.$/.
                            'got '.
                            'time = '.$time.$/.
                            'res  = '.$res.$/.
                            'uname= '.$uname.$/.
                            'udom = '.$udom.$/.
                            'action='.$action.$/.
                            '@values = '.join(':',@values));
                   next; #skip it if we cannot understand what is happening.
               }
               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');              $time_this->('split_and_error_check');
             my $student_id = &get_id($student_table,'student',$student);              my $student_id = &get_id($student_table,'student',$student);
             my $res_id = &get_id($res_table,'resource',$res);              my $res_id     = &get_id($res_table,'resource',$res);
             my $action_id = &get_id($action_table,'action',$action);              my $action_id  = &get_id($action_table,'action',$action);
             my $sql_time = &Apache::lonmysql::sqltime($time);              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 '') {
                   print $error_fh 'full log entry:'.$log.$/;
                   print $error_fh 'error on chunk:'.$chunk.$/;
                   $logthis->('warningflag ('.$warningflag.') on chunk '.
                              $/.$chunk.$/.'prevchunk = '.$/.$prevchunk);
                   $prevchunk .= $chunk;
                   next; # skip this chunk
               }
               #
             my $values = $dbh->quote(join('',@values));              my $values = $dbh->quote(join('',@values));
             $time_this->('get_ids');              $time_this->('get_ids');
             #              #
Line 373  sub process_courselog { Line 476  sub process_courselog {
                        $values];                         $values];
             push(@RowData,$row);              push(@RowData,$row);
             $time_this->('push_row');              $time_this->('push_row');
               $prevchunk = $chunk;
             #              #
         }          }
         $time_this->();          $time_this->();
         if ($linecount % 100 == 0) {          if ((scalar(@RowData) > 0) && ($linecount % 100 == 0)) {
             my $result = &Apache::lonmysql::bulk_store_rows($activity_table,              my $result = &Apache::lonmysql::bulk_store_rows($activity_table,
                                                             undef,                                                              undef,
                                                             \@RowData);                                                              \@RowData);
               # $logthis->('result = '.$result);
             $time_this->('bulk_store_rows');              $time_this->('bulk_store_rows');
             if (! defined($result)) {              if (! defined($result)) {
                 warn "Error occured during insert.".                  my $error = &Apache::lonmysql::get_error();
                     &Apache::lonmysql::get_error();                  warn "Error occured during insert.".$error;
                   $logthis->('error = '.$error);
             }              }
             undef(@RowData);              undef(@RowData);
         }          }
     }      }
     if (@RowData) {      if (@RowData) {
         $time_this->();          $time_this->();
           $logthis->('storing '.$linecount);
         my $result = &Apache::lonmysql::bulk_store_rows($activity_table,          my $result = &Apache::lonmysql::bulk_store_rows($activity_table,
                                                         undef,                                                          undef,
                                                         \@RowData);                                                          \@RowData);
           $logthis->('result = '.$result);
         $time_this->('bulk_store_rows');          $time_this->('bulk_store_rows');
         if (! defined($result)) {          if (! defined($result)) {
             warn "Error occured during insert.".              my $error = &Apache::lonmysql::get_error();
                 &Apache::lonmysql::get_error();              warn "Error occured during insert.".$error;
               $logthis->('error = '.$error);
         }          }
         undef(@RowData);          undef(@RowData);
     }      }
Line 406  sub process_courselog { Line 515  sub process_courselog {
     return $linecount;      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  ## Timing routines
 ##  ##
Line 413  sub process_courselog { Line 537  sub process_courselog {
     my %Timing;      my %Timing;
     my $starttime;      my $starttime;
   
 sub nothing {  
     return;  
 }  
   
 sub time_action {  sub time_action {
     my ($key) = @_;      my ($key) = @_;
     if (defined($key)) {      if (defined($key)) {
Line 452  sub backup_tables { Line 572  sub backup_tables {
     my ($sql_filename) = @_;      my ($sql_filename) = @_;
     my $command = qq{mysqldump --opt loncapa };      my $command = qq{mysqldump --opt loncapa };
                                                             
     foreach my $table (@Activity_Tables) {      foreach my $table (@ID_Tables,@Activity_Table) {
         my $tablename = $table->{'id'};          my $tablename = $table->{'id'};
         $command .= $tablename.' ';          $command .= $tablename.' ';
     }      }
     $command .= '>'.$sql_filename;      $command .= '>'.$sql_filename;
     warn $command.$/;      $logthis->($command);
     system($command);      system($command);
 }  }
   
Line 469  sub load_backup_tables { Line 589  sub load_backup_tables {
     return undef if (! -e $sql_filename);      return undef if (! -e $sql_filename);
     # Check for .my.cnf      # Check for .my.cnf
     my $command = 'mysql -e "SOURCE '.$sql_filename.'" loncapa';      my $command = 'mysql -e "SOURCE '.$sql_filename.'" loncapa';
     warn $command.$/;      $logthis->('loading previously saved sql table'.$/.$command);
     system($command);      system($command);
       $logthis->('finished loading old data');
 }  }
   
 ##  ##
Line 496  sub get_filename { Line 617  sub get_filename {
 }  }
   
 sub create_tables {  sub create_tables {
     foreach my $table (@Activity_Tables) {      foreach my $table (@ID_Tables,@Activity_Table) {
         my $table_id = &Apache::lonmysql::create_table($table);          my $table_id = &Apache::lonmysql::create_table($table);
         if (! defined($table_id)) {          if (! defined($table_id)) {
             warn "Unable to create table ".$table->{'id'}.$/;              warn "Unable to create table ".$table->{'id'}.$/;
Line 508  sub create_tables { Line 629  sub create_tables {
 }  }
   
 sub drop_tables {  sub drop_tables {
     foreach my $table (@Activity_Tables) {      foreach my $table (@ID_Tables,@Activity_Table) {
         my $table_id = $table->{'id'};          my $table_id = $table->{'id'};
         &Apache::lonmysql::drop_table($table_id);          &Apache::lonmysql::drop_table($table_id);
     }      }
Line 525  sub drop_tables { Line 646  sub drop_tables {
     my %IDs;      my %IDs;
   
 sub read_id_tables {  sub read_id_tables {
     foreach my $table (@Activity_Tables) {      foreach my $table (@ID_Tables) {
         my @Data = &Apache::lonmysql::get_rows($table->{'id'});          my @Data = &Apache::lonmysql::get_rows($table->{'id'});
           my $count = 0;
         foreach my $row (@Data) {          foreach my $row (@Data) {
             $IDs{$table->{'id'}}->{$row->[1]} = $row->[0];              $IDs{$table->{'id'}}->{$row->[1]} = $row->[0];
         }          }
     }      }
       return;
 }  }
   
 sub get_id {  sub get_id {
Line 551  sub get_id { Line 674  sub get_id {
             $IDs{$table}->{$value}=$Data[0]->[0];              $IDs{$table}->{$value}=$Data[0]->[0];
             return $IDs{$table}->{$value};              return $IDs{$table}->{$value};
         } else {          } else {
             warn "Unable to retrieve id for $table $fieldname $value".$/;              $logthis->("Unable to retrieve id for $table $fieldname $value");
             return undef;              return undef;
         }          }
     }      }
Line 578  sub unescape { Line 701  sub unescape {
     $str =~ s/%([a-fA-F0-9][a-fA-F0-9])/pack("C",hex($1))/eg;      $str =~ s/%([a-fA-F0-9][a-fA-F0-9])/pack("C",hex($1))/eg;
     return $str;      return $str;
 }  }
   
Removed from v.1.1  
changed lines
  Added in v.1.3

FreeBSD-CVSweb <freebsd-cvsweb@FreeBSD.org>