--- loncom/metadata_database/parse_activity_log.pl	2004/08/18 19:33:27	1.2
+++ loncom/metadata_database/parse_activity_log.pl	2004/08/19 21:08:46	1.3
@@ -2,7 +2,7 @@
 #
 # The LearningOnline Network
 #
-# $Id: parse_activity_log.pl,v 1.2 2004/08/18 19:33:27 matthew Exp $
+# $Id: parse_activity_log.pl,v 1.3 2004/08/19 21:08:46 matthew Exp $
 #
 # Copyright Michigan State University Board of Trustees
 #
@@ -26,16 +26,7 @@
 #
 # 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
 #   0     Everything is okay
@@ -52,6 +43,7 @@ use lib '/home/httpd/lib/perl/Apache';
 use lonmysql();
 use Time::HiRes();
 use Getopt::Long();
+use IO::File;
 
 #
 # Determine parameters
@@ -87,7 +79,6 @@ USAGE
 
 ##
 ## Set up timing code
-##
 my $time_this = \&nothing;
 if ($time_run) {
     $time_this = \&time_action;
@@ -95,8 +86,17 @@ if ($time_run) {
 my $initial_time = Time::HiRes::time;
 
 ##
-## Set up logging code
+## Read in configuration parameters
+##
+my %perlvar;
+&initialize_configuration();
+if (! defined($domain) || $domain eq '') {
+    $domain = $perlvar{'lonDefDomain'};
+}
+&update_process_name($course.'@'.$domain);
+
 ##
+## Set up logging code
 my $logthis = \&nothing;
 if ($log) {
     my $logfile = "/tmp/parse_activity_log.log.".time;
@@ -107,22 +107,15 @@ if ($log) {
         $logthis = \&log_to_file;
     }
 }
-##
-## Read in configuration parameters
-##
-my %perlvar;
-&initialize_configuration();
-if (! defined($domain) || $domain eq '') {
-    $domain = $perlvar{'lonDefDomain'};
-}
-&update_process_name($course.'@'.$domain);
+
 
 ##
 ## Determine filenames
 ##
 my $sourcefilename;   # activity log data
 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) {
     $sourcefilename = $file;
 } else {
@@ -130,6 +123,9 @@ if ($file) {
 }
 $sql_filename = $sourcefilename;
 $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
@@ -142,8 +138,14 @@ if (-e $newfilename) {
 }
 
 if (-e $sourcefilename) {
+    $logthis->('renaming '.$sourcefilename.' to '.$newfilename);
     rename($sourcefilename,$newfilename);
     $logthis->("renamed $sourcefilename to $newfilename");
+} else {
+    my $command = 'touch '.$newfilename;
+    $logthis->($command);
+    system($command);
+    $logthis->('touch was completed');
 }
 
 ##
@@ -240,16 +242,17 @@ my $activity_table_def =
               ], 
       'PRIMARY KEY' => ['res_id','time','student_id','action_id','idx'],
 };
-my @Activity_Tables = ($student_table_def,$res_table_def,
-                       $action_table_def,$machine_table_def,
-                       $activity_table_def);
-
+my @Activity_Table = ($activity_table_def);
+my @ID_Tables = ($student_table_def,$res_table_def,
+                 $action_table_def,$machine_table_def);
+                       
 
 ##
 ## End of table definitions
 ##
 
 # 
+$logthis->('Connectiong to mysql');
 &Apache::lonmysql::set_mysql_user_and_password($perlvar{'lonSqlUser'},
                                                $perlvar{'lonSqlAccess'});
 if (!&Apache::lonmysql::verify_sql_connection()) {
@@ -258,21 +261,23 @@ if (!&Apache::lonmysql::verify_sql_conne
     exit 3;
 }
 
+$logthis->('SQL connection is up');
+
 if ($drop) { &drop_tables(); $logthis->('dropped tables'); }
-if (-e $sql_filename) {
-    $logthis->('reading in from '.$sql_filename);
+
+if (-s $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();
     my %Found;
     foreach my $tablename (@Current_Tables) {
-        foreach my $table (@Activity_Tables) {
+        foreach my $table (@Activity_Table,@ID_Tables) {
             if ($tablename eq  $table->{'id'}) {
                 $Found{$tablename}++;
             }
         }
     }
-    foreach my $table (@Activity_Tables) {    
+    foreach my $table (@Activity_Table,@ID_Tables) {    
         if (! $Found{$table->{'id'}}) {
             $time_this->();
             &load_backup_tables($sql_filename);
@@ -282,21 +287,31 @@ if (-e $sql_filename) {
     }
 }
 
+##
+## Ensure the tables we need exist
 # create_tables does not complain if the tables already exist
+$logthis->('creating tables');
 if (! &create_tables()) {
     warn "Unable to create tables";
     $logthis->('Unable to create tables');
     exit 4;
 }
 
+##
+## Read the ids used for various tables
 $logthis->('reading id tables');
 &read_id_tables();
 $logthis->('finished reading id tables');
 
 ##
-## Do the main bit of work
-if (-e $newfilename) {
-    my $result = &process_courselog($newfilename);
+## Set up the errors file
+my $error_fh = IO::File->new(">>$error_filename");
+
+##
+## Parse the course log
+$logthis->('processing course log');
+if (-s $newfilename) {
+    my $result = &process_courselog($newfilename,$error_fh);
     if (! defined($result)) {
         # Something went wrong along the way...
         $logthis->('process_courselog returned undef');
@@ -308,13 +323,16 @@ if (-e $newfilename) {
         $time_this->('write backup tables');
     }
 }
+close($error_fh);
 
 ##
 ## Clean up the filesystem
-##
 &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) {
     my $elapsed_time = Time::HiRes::time - $initial_time;
     print "Overall time: ".$elapsed_time.$/;
@@ -339,7 +357,7 @@ exit 0;   # Everything is okay, so end h
 #
 # Returns the number of lines in the activity.log file that were processed.
 sub process_courselog {
-    my ($inputfile) = @_;
+    my ($inputfile,$error_fh) = @_;
     if (! open(IN,$inputfile)) {
         warn "Unable to open '$inputfile' for reading";
         $logthis->("Unable to open '$inputfile' for reading");
@@ -384,17 +402,26 @@ sub process_courselog {
             if (! defined($res) || $res =~ /^\s*$/) {
                 $res = '/adm/roles';
                 $action = 'LOGIN';
-#                $warningflag .= 'res';
             }
             if ($res =~ m|^/prtspool/|) {
                 $res = '/prtspool/';
             }
             if (! defined($action) || $action eq '') {
                 $action = 'VIEW';
-#                $warningflag .= 'action';
             }
             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';
@@ -415,9 +442,9 @@ sub process_courselog {
             #
             $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);
+            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'; 
@@ -429,6 +456,8 @@ sub process_courselog {
                 $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;
@@ -543,7 +572,7 @@ sub backup_tables {
     my ($sql_filename) = @_;
     my $command = qq{mysqldump --opt loncapa };
                              
-    foreach my $table (@Activity_Tables) {
+    foreach my $table (@ID_Tables,@Activity_Table) {
         my $tablename = $table->{'id'};
         $command .= $tablename.' ';
     }
@@ -562,6 +591,7 @@ sub load_backup_tables {
     my $command = 'mysql -e "SOURCE '.$sql_filename.'" loncapa';
     $logthis->('loading previously saved sql table'.$/.$command);
     system($command);
+    $logthis->('finished loading old data');
 }
 
 ##
@@ -587,7 +617,7 @@ sub get_filename {
 }
 
 sub create_tables {
-    foreach my $table (@Activity_Tables) {
+    foreach my $table (@ID_Tables,@Activity_Table) {
         my $table_id = &Apache::lonmysql::create_table($table);
         if (! defined($table_id)) {
             warn "Unable to create table ".$table->{'id'}.$/;
@@ -599,7 +629,7 @@ sub create_tables {
 }
 
 sub drop_tables {
-    foreach my $table (@Activity_Tables) {
+    foreach my $table (@ID_Tables,@Activity_Table) {
         my $table_id = $table->{'id'};
         &Apache::lonmysql::drop_table($table_id);
     }
@@ -616,12 +646,14 @@ sub drop_tables {
     my %IDs;
 
 sub read_id_tables {
-    foreach my $table (@Activity_Tables) {
+    foreach my $table (@ID_Tables) {
         my @Data = &Apache::lonmysql::get_rows($table->{'id'});
+        my $count = 0;
         foreach my $row (@Data) {
             $IDs{$table->{'id'}}->{$row->[1]} = $row->[0];
         }
     }
+    return;
 }
 
 sub get_id {