Annotation of loncom/metadata_database/parse_activity_log.pl, revision 1.23

1.1       matthew     1: #!/usr/bin/perl
                      2: #
                      3: # The LearningOnline Network
                      4: #
1.23    ! albertel    5: # $Id: parse_activity_log.pl,v 1.22 2006/03/30 05:29:01 albertel Exp $
1.1       matthew     6: #
                      7: # Copyright Michigan State University Board of Trustees
                      8: #
                      9: # This file is part of the LearningOnline Network with CAPA (LON-CAPA).
                     10: #
                     11: # LON-CAPA is free software; you can redistribute it and/or modify
                     12: # it under the terms of the GNU General Public License as published by
                     13: # the Free Software Foundation; either version 2 of the License, or
                     14: # (at your option) any later version.
                     15: #
                     16: # LON-CAPA is distributed in the hope that it will be useful,
                     17: # but WITHOUT ANY WARRANTY; without even the implied warranty of
                     18: # MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
                     19: # GNU General Public License for more details.
                     20: #
                     21: # You should have received a copy of the GNU General Public License
                     22: # along with LON-CAPA; if not, write to the Free Software
                     23: # Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
                     24: #
                     25: # /home/httpd/html/adm/gpl.txt
                     26: #
                     27: # http://www.lon-capa.org/
                     28: #
1.3       matthew    29: #--------------------------------------------------------------------
1.1       matthew    30: #
                     31: # Exit codes
                     32: #   0     Everything is okay
                     33: #   1     Another copy is running on this course
                     34: #   2     Activity log does not exist
                     35: #   3     Unable to connect to database
                     36: #   4     Unable to create database tables
1.9       matthew    37: #   5     Unable to open log file
                     38: #   6     Unable to get lock on activity log
1.1       matthew    39: #
                     40: 
1.8       matthew    41: #
                     42: # Notes:
                     43: #
                     44: # Logging is done via the $logthis variable, which may be the result of 
                     45: # overcleverness.  log via $logthis->('logtext');  Those are parentheses,
                     46: # not curly braces.  If the -log command line parameter is set, the $logthis
                     47: # routine is set to a routine which writes to a file.  If the command line
                     48: # parameter is not set $logthis is set to &nothing, which does what you
                     49: # would expect.
                     50: #
1.21      albertel   51: BEGIN {
                     52:     eval "use Apache2::compat();";
                     53: };
1.1       matthew    54: use strict;
                     55: use DBI;
1.9       matthew    56: use lib '/home/httpd/lib/perl/Apache';
1.8       matthew    57: use lib '/home/httpd/lib/perl/';
                     58: use LONCAPA::Configuration();
                     59: use Apache::lonmysql();
1.1       matthew    60: use lonmysql();
                     61: use Time::HiRes();
                     62: use Getopt::Long();
1.3       matthew    63: use IO::File;
1.5       matthew    64: use File::Copy;
1.7       matthew    65: use Fcntl qw(:flock);
1.14      matthew    66: use HTML::TokeParser;
1.7       matthew    67: 
1.1       matthew    68: #
                     69: # Determine parameters
1.15      matthew    70: my ($help,$course,$domain,$drop_when_done,$srcfile,$logfile,$time_run,$nocleanup,$log,$backup,$xmlfile);
1.1       matthew    71: &Getopt::Long::GetOptions( "course=s"  => \$course,
                     72:                            "domain=s"  => \$domain,
1.5       matthew    73:                            "backup"    => \$backup,
1.1       matthew    74:                            "help"      => \$help,
1.12      matthew    75:                            "logfile=s" => \$logfile,
                     76:                            "srcfile=s" => \$srcfile,
1.15      matthew    77:                            "justloadxml=s" => \$xmlfile,
1.1       matthew    78:                            "timerun"   => \$time_run,
                     79:                            "nocleanup" => \$nocleanup,
1.12      matthew    80:                            "dropwhendone" => \$drop_when_done,
1.2       matthew    81:                            "log"       => \$log);
1.1       matthew    82: if (! defined($course) || $help) {
                     83:     print<<USAGE;
                     84: parse_activity_log.pl
                     85: 
                     86: Process a lon-capa activity log into a database.
                     87: Parameters:
                     88:    course             Required
1.12      matthew    89:    domain             optional
1.5       matthew    90:    backup             optional   if present, backup the activity log file
                     91:                                  before processing it
1.12      matthew    92:    dropwhendone       optional   if present, drop all course 
                     93:                                  specific activity log tables after processing.
                     94:    srcfile            optional   Specify the file to parse, including path
1.1       matthew    95:    time               optional   if present, print out timing data
                     96:    nocleanup          optional   if present, do not remove old files
1.2       matthew    97:    log                optional   if present, prepare log file of activity
1.12      matthew    98:    logfile            optional   specifies the logfile to use
1.1       matthew    99: Examples:
                    100:   $0 -course=123456abcdef -domain=msu
1.12      matthew   101:   $0 -course=123456abcdef -srcfile=activity.log
                    102:   $0 -course-123456abcdef -log -logfile=/tmp/logfile -dropwhendone
1.1       matthew   103: USAGE
                    104:     exit;
                    105: }
                    106: 
                    107: ##
                    108: ## Set up timing code
                    109: my $time_this = \&nothing;
                    110: if ($time_run) {
                    111:     $time_this = \&time_action;
                    112: }
                    113: my $initial_time = Time::HiRes::time;
                    114: 
                    115: ##
1.3       matthew   116: ## Read in configuration parameters
                    117: ##
1.8       matthew   118: my %perlvar = %{&LONCAPA::Configuration::read_conf('loncapa.conf')};
                    119: 
1.3       matthew   120: if (! defined($domain) || $domain eq '') {
                    121:     $domain = $perlvar{'lonDefDomain'};
                    122: }
                    123: &update_process_name($course.'@'.$domain);
                    124: 
                    125: ##
1.2       matthew   126: ## Set up logging code
                    127: my $logthis = \&nothing;
1.12      matthew   128: 
1.2       matthew   129: if ($log) {
1.12      matthew   130:     if (! $logfile) {
                    131:         $logfile = $perlvar{'lonDaemons'}.'/tmp/parse_activity_log.log.'.time;
                    132:     }
1.2       matthew   133:     print STDERR "$0: logging to $logfile".$/;
                    134:     if (! open(LOGFILE,">$logfile")) {
1.9       matthew   135:         warn("Unable to open $logfile for writing.  Run aborted.");
1.17      albertel  136:         &clean_up_and_exit(5);
1.2       matthew   137:     } else {
                    138:         $logthis = \&log_to_file;
                    139:     }
                    140: }
1.3       matthew   141: 
1.1       matthew   142: 
                    143: ##
                    144: ## Determine filenames
                    145: ##
                    146: my $sourcefilename;   # activity log data
                    147: my $newfilename;      # $sourcefilename will be renamed to this
1.3       matthew   148: my $error_filename;   # Errors in parsing the activity log will be written here
1.19      matthew   149: my $chunk_filename;   # where we save data we are not going to write to db
1.12      matthew   150: if ($srcfile) {
                    151:     $sourcefilename = $srcfile;
1.1       matthew   152: } else {
                    153:     $sourcefilename = &get_filename($course,$domain);
                    154: }
1.6       matthew   155: my $sql_filename = $sourcefilename;
1.2       matthew   156: $sql_filename =~ s|[^/]*$|activity.log.sql|;
1.14      matthew   157: my $gz_sql_filename = $sql_filename.'.gz';
                    158: #
1.19      matthew   159: $chunk_filename = $sourcefilename.".unprocessed_chunks";
                    160: #
1.14      matthew   161: my $xml_filename = $sourcefilename;
                    162: my $gz_xml_filename = $xml_filename.'.gz';
1.15      matthew   163: if (defined($xmlfile)) {
                    164:     $xml_filename = $xmlfile;
                    165:     if ($xml_filename =~ /\.gz$/) {
                    166:         $gz_xml_filename = $xml_filename;
                    167:     } else {
                    168:         $gz_xml_filename = $xml_filename.'.gz';
                    169:     }
                    170: } else {
                    171:     my $xml_filename = $sourcefilename;
                    172:     $xml_filename =~ s|[^/]*$|activity.log.xml|;
                    173:     $gz_xml_filename = $xml_filename.'.gz';
                    174: }
1.14      matthew   175: #
1.3       matthew   176: $error_filename = $sourcefilename;
                    177: $error_filename =~ s|[^/]*$|activity.log.errors|;
                    178: $logthis->('Beginning logging '.time);
1.1       matthew   179: 
1.7       matthew   180: #
                    181: # Wait for a lock on the lockfile to avoid collisions
                    182: my $lockfilename = $sourcefilename.'.lock';
1.16      matthew   183: $newfilename = $sourcefilename.'.processing';
1.15      matthew   184: if (! defined($xmlfile)) {
1.16      matthew   185:     open(LOCKFILE,'>'.$lockfilename);
                    186:     if (!flock(LOCKFILE,LOCK_EX|LOCK_NB)) {
                    187:         warn("Unable to lock $lockfilename.  Aborting".$/);
1.17      albertel  188:         # don't call clean_up_and_exit another instance is running and
1.22      albertel  189:         # we don't want to 'cleanup' their files
1.17      albertel  190:         exit 6;
1.16      matthew   191:     }
1.7       matthew   192: 
1.16      matthew   193:     if (! -e $newfilename && -e $sourcefilename) {
                    194:         $logthis->('renaming '.$sourcefilename.' to '.$newfilename);
                    195:         rename($sourcefilename,$newfilename);
                    196:         Copy($newfilename,$newfilename.'.'.time) if ($backup);
                    197:         $logthis->("renamed $sourcefilename to $newfilename");
                    198:     } elsif (! -e $newfilename) {
                    199:         utime(undef,undef,$newfilename);
                    200:     }
1.1       matthew   201: }
                    202: 
                    203: ##
                    204: ## Table definitions
                    205: ##
1.14      matthew   206: my %tables = &table_names($course,$domain);
1.1       matthew   207: my $student_table_def = 
1.14      matthew   208: { id => $tables{'student'},
1.1       matthew   209:   permanent => 'no',
                    210:   columns => [
                    211:               { name => 'student_id',
                    212:                 type => 'MEDIUMINT UNSIGNED',
                    213:                 restrictions => 'NOT NULL',
                    214:                 auto_inc => 'yes', },
                    215:               { name => 'student',
                    216:                 type => 'VARCHAR(100) BINARY',
                    217:                 restrictions => 'NOT NULL', },
                    218:               ],
                    219:       'PRIMARY KEY' => ['student_id',],
                    220:           };
                    221: 
                    222: my $res_table_def = 
1.14      matthew   223: { id => $tables{'res'},
1.1       matthew   224:   permanent => 'no',
                    225:   columns => [{ name => 'res_id',
                    226:                 type => 'MEDIUMINT UNSIGNED',
                    227:                 restrictions => 'NOT NULL',
                    228:                 auto_inc     => 'yes', },
                    229:               { name => 'resource',
                    230:                 type => 'MEDIUMTEXT',
                    231:                 restrictions => 'NOT NULL'},
                    232:               ],
                    233:   'PRIMARY KEY' => ['res_id'],
                    234: };
                    235: 
1.4       matthew   236: #my $action_table_def =
                    237: #{ id => $action_table,
                    238: #  permanent => 'no',
                    239: #  columns => [{ name => 'action_id',
                    240: #                type => 'MEDIUMINT UNSIGNED',
                    241: #                restrictions => 'NOT NULL',
                    242: #                auto_inc     => 'yes', },
                    243: #              { name => 'action',
                    244: #                type => 'VARCHAR(100)',
                    245: #                restrictions => 'NOT NULL'},
                    246: #              ],
                    247: #  'PRIMARY KEY' => ['action_id',], 
                    248: #};
1.1       matthew   249: 
                    250: my $machine_table_def =
1.14      matthew   251: { id => $tables{'machine'},
1.1       matthew   252:   permanent => 'no',
                    253:   columns => [{ name => 'machine_id',
                    254:                 type => 'MEDIUMINT UNSIGNED',
                    255:                 restrictions => 'NOT NULL',
                    256:                 auto_inc     => 'yes', },
                    257:               { name => 'machine',
                    258:                 type => 'VARCHAR(100)',
                    259:                 restrictions => 'NOT NULL'},
                    260:               ],
                    261:   'PRIMARY KEY' => ['machine_id',],
                    262:  };
                    263: 
                    264: my $activity_table_def = 
1.14      matthew   265: { id => $tables{'activity'},
1.1       matthew   266:   permanent => 'no',
                    267:   columns => [
                    268:               { name => 'res_id',
                    269:                 type => 'MEDIUMINT UNSIGNED',
                    270:                 restrictions => 'NOT NULL',},
                    271:               { name => 'time',
                    272:                 type => 'DATETIME',
                    273:                 restrictions => 'NOT NULL',},
                    274:               { name => 'student_id',
1.2       matthew   275:                 type => 'MEDIUMINT UNSIGNED',
1.1       matthew   276:                 restrictions => 'NOT NULL',},
1.4       matthew   277:               { name => 'action',
                    278:                 type => 'VARCHAR(10)',
1.1       matthew   279:                 restrictions => 'NOT NULL',},
                    280:               { name => 'idx',                # This is here in case a student
                    281:                 type => 'MEDIUMINT UNSIGNED', # has multiple submissions during
                    282:                 restrictions => 'NOT NULL',   # one second.  It happens, trust
                    283:                 auto_inc     => 'yes', },     # me.
                    284:               { name => 'machine_id',
1.2       matthew   285:                 type => 'MEDIUMINT UNSIGNED',
1.1       matthew   286:                 restrictions => 'NOT NULL',},
                    287:               { name => 'action_values',
                    288:                 type => 'MEDIUMTEXT', },
                    289:               ], 
1.4       matthew   290:       'PRIMARY KEY' => ['time','student_id','res_id','idx'],
                    291:       'KEY' => [{columns => ['student_id']},
                    292:                 {columns => ['time']},],
1.1       matthew   293: };
1.4       matthew   294: 
1.8       matthew   295: my @Activity_Table = ($activity_table_def);
1.4       matthew   296: my @ID_Tables = ($student_table_def,$res_table_def,$machine_table_def);
1.14      matthew   297:                
1.1       matthew   298: ##
1.13      matthew   299: ## End of table definitions
1.1       matthew   300: ##
1.14      matthew   301: $logthis->('tables = '.join(',',keys(%tables)));
1.1       matthew   302: 
1.3       matthew   303: $logthis->('Connectiong to mysql');
1.8       matthew   304: &Apache::lonmysql::set_mysql_user_and_password('www',
1.1       matthew   305:                                                $perlvar{'lonSqlAccess'});
                    306: if (!&Apache::lonmysql::verify_sql_connection()) {
                    307:     warn "Unable to connect to MySQL database.";
1.2       matthew   308:     $logthis->("Unable to connect to MySQL database.");
1.16      matthew   309:     &clean_up_and_exit(3);
1.1       matthew   310: }
1.3       matthew   311: $logthis->('SQL connection is up');
                    312: 
1.14      matthew   313: my $missing_table = &check_for_missing_tables(values(%tables));
                    314: if (-s $gz_sql_filename && ! -s $gz_xml_filename) {
1.8       matthew   315:     my $backup_modification_time = (stat($gz_sql_filename))[9];
                    316:     $logthis->($gz_sql_filename.' was last modified '.
                    317:                localtime($backup_modification_time).
                    318:                '('.$backup_modification_time.')');
1.14      matthew   319:     if ($missing_table) {
                    320:         # If the backup happened prior to the last table modification,
                    321:         # we need to save the tables.
                    322:         if (&latest_table_modification_time() > $backup_modification_time) {
                    323:             # Save the current tables in case we need them another time.
                    324:             $logthis->('Backing existing tables up');
                    325:             &backup_tables_as_xml($gz_xml_filename.'.save_'.time,\%tables);
1.1       matthew   326:         }
1.14      matthew   327:         $time_this->();
                    328:         &load_backup_sql_tables($gz_sql_filename);
                    329:         &backup_tables_as_xml($gz_xml_filename,\%tables);
                    330:         $time_this->('load backup tables');
1.1       matthew   331:     }
1.14      matthew   332: } elsif (-s $gz_xml_filename) {
                    333:     my $backup_modification_time = (stat($gz_xml_filename))[9];
                    334:     $logthis->($gz_xml_filename.' was last modified '.
                    335:                localtime($backup_modification_time).
                    336:                '('.$backup_modification_time.')');
                    337:     if ($missing_table) {
1.8       matthew   338:         my $table_modification_time = $backup_modification_time;
                    339:         # If the backup happened prior to the last table modification,
1.14      matthew   340:         # we need to save the tables.
                    341:         if (&latest_table_modification_time() > $backup_modification_time) {
1.8       matthew   342:             # Save the current tables in case we need them another time.
1.14      matthew   343:             $logthis->('Backing existing tables up');
                    344:             &backup_tables_as_xml($gz_xml_filename.'.save_'.time,\%tables);
1.8       matthew   345:         }
                    346:         $time_this->();
1.14      matthew   347:         # We have to make our own tables for the xml format
                    348:         &drop_tables();
                    349:         &create_tables();
                    350:         &load_backup_xml_tables($gz_xml_filename,\%tables);
1.8       matthew   351:         $time_this->('load backup tables');
1.14      matthew   352:     }    
1.1       matthew   353: }
                    354: 
1.15      matthew   355: if (defined($xmlfile)) {
1.16      matthew   356:     &clean_up_and_exit(0);
1.15      matthew   357: }
                    358: 
1.3       matthew   359: ##
                    360: ## Ensure the tables we need exist
1.1       matthew   361: # create_tables does not complain if the tables already exist
1.3       matthew   362: $logthis->('creating tables');
1.1       matthew   363: if (! &create_tables()) {
                    364:     warn "Unable to create tables";
1.2       matthew   365:     $logthis->('Unable to create tables');
1.16      matthew   366:     &clean_up_and_exit(4);
1.1       matthew   367: }
                    368: 
1.3       matthew   369: ##
                    370: ## Read the ids used for various tables
1.2       matthew   371: $logthis->('reading id tables');
1.1       matthew   372: &read_id_tables();
1.2       matthew   373: $logthis->('finished reading id tables');
1.1       matthew   374: 
                    375: ##
1.3       matthew   376: ## Set up the errors file
                    377: my $error_fh = IO::File->new(">>$error_filename");
                    378: 
                    379: ##
                    380: ## Parse the course log
                    381: $logthis->('processing course log');
                    382: if (-s $newfilename) {
1.14      matthew   383:     my $result = &process_courselog($newfilename,$error_fh,\%tables);
1.1       matthew   384:     if (! defined($result)) {
                    385:         # Something went wrong along the way...
1.2       matthew   386:         $logthis->('process_courselog returned undef');
1.16      matthew   387:         &clean_up_and_exit(5);
1.1       matthew   388:     } elsif ($result > 0) {
                    389:         $time_this->();
1.15      matthew   390:         $logthis->('process_courselog returned '.$result.'.'.$/.
                    391:                    'Backing up tables');
1.14      matthew   392:         &backup_tables_as_xml($gz_xml_filename,\%tables);
1.1       matthew   393:         $time_this->('write backup tables');
                    394:     }
1.12      matthew   395:     if ($drop_when_done) { &drop_tables(); $logthis->('dropped tables'); }
1.1       matthew   396: }
1.3       matthew   397: close($error_fh);
1.1       matthew   398: 
                    399: ##
                    400: ## Clean up the filesystem
                    401: &Apache::lonmysql::disconnect_from_db();
1.3       matthew   402: unlink($newfilename) if (-e $newfilename && ! $nocleanup);
1.1       matthew   403: 
1.3       matthew   404: ##
                    405: ## Print timing data
                    406: $logthis->('printing timing data');
1.1       matthew   407: if ($time_run) {
1.2       matthew   408:     my $elapsed_time = Time::HiRes::time - $initial_time;
                    409:     print "Overall time: ".$elapsed_time.$/;
1.1       matthew   410:     print &outputtimes();
1.2       matthew   411:     $logthis->("Overall time: ".$elapsed_time);
                    412:     $logthis->(&outputtimes());
                    413: }
                    414: 
1.16      matthew   415: &clean_up_and_exit(0);
                    416: 
                    417: ########################################################
                    418: ########################################################
1.1       matthew   419: 
1.16      matthew   420: sub clean_up_and_exit {
                    421:     my ($exit_code) = @_;
                    422:     # Close files
                    423:     close(LOCKFILE);
                    424:     close(LOGFILE);
                    425:     # Remove zero length files
                    426:     foreach my $file ($lockfilename, $error_filename,$logfile) {
                    427:         if (defined($file) && -z $file) { 
                    428:             unlink($file); 
                    429:         }
1.12      matthew   430:     }
1.16      matthew   431: 
                    432:     exit $exit_code;
1.12      matthew   433: }
                    434: 
1.14      matthew   435: ########################################################
                    436: ########################################################
                    437: sub table_names {
                    438:     my ($course,$domain) = @_;
                    439:     my $prefix = $course.'_'.$domain.'_';
                    440:     #
                    441:     my %tables = 
                    442:         ( student =>&Apache::lonmysql::fix_table_name($prefix.'students'),
                    443:           res     =>&Apache::lonmysql::fix_table_name($prefix.'resource'),
                    444:           machine =>&Apache::lonmysql::fix_table_name($prefix.'machine_table'),
                    445:           activity=>&Apache::lonmysql::fix_table_name($prefix.'activity'),
                    446:           );
                    447:     return %tables;
                    448: }
1.1       matthew   449: 
                    450: ########################################################
                    451: ########################################################
                    452: ##
                    453: ##                 Process Course Log
                    454: ##
                    455: ########################################################
                    456: ########################################################
                    457: #
                    458: # Returns the number of lines in the activity.log file that were processed.
                    459: sub process_courselog {
1.14      matthew   460:     my ($inputfile,$error_fh,$tables) = @_;
1.1       matthew   461:     if (! open(IN,$inputfile)) {
                    462:         warn "Unable to open '$inputfile' for reading";
1.2       matthew   463:         $logthis->("Unable to open '$inputfile' for reading");
1.1       matthew   464:         return undef;
                    465:     }
                    466:     my ($linecount,$insertcount);
                    467:     my $dbh = &Apache::lonmysql::get_dbh();
                    468:     #
1.14      matthew   469:     &store_entry();
1.1       matthew   470:     while (my $line=<IN>){
                    471:         # last if ($linecount > 1000);
                    472:         #
                    473:         # Bulk storage variables
                    474:         $time_this->();
                    475:         chomp($line);
                    476:         $linecount++;
                    477:         # print $linecount++.$/;
                    478:         my ($timestamp,$host,$log)=split(/\:/,$line,3);
                    479:         #
                    480:         # $log has the actual log entries; currently still escaped, and
                    481:         # %26(timestamp)%3a(url)%3a(user)%3a(domain)
                    482:         # then additionally
                    483:         # %3aPOST%3a(name)%3d(value)%3a(name)%3d(value)
                    484:         # or
                    485:         # %3aCSTORE%3a(name)%3d(value)%26(name)%3d(value)
                    486:         #
                    487:         # get delimiter between timestamped entries to be &&&
                    488:         $log=~s/\%26(\d{9,10})\%3a/\&\&\&$1\%3a/g;
                    489:         $log = &unescape($log);
                    490:         # now go over all log entries 
1.2       matthew   491:         if (! defined($host)) { $host = 'unknown'; }
                    492:         my $prevchunk = 'none';
                    493:         foreach my $chunk (split(/\&\&\&/,$log)) {
1.19      matthew   494:             if (length($chunk) > 20000) {
                    495:                 # avoid putting too much data into the database
                    496:                 # (usually an uploaded file or something similar)
1.20      matthew   497:                 if (! &savechunk(\$chunk,$timestamp,$host)) {
1.19      matthew   498:                     close(IN);
                    499:                     return undef;
                    500:                 }
                    501:                 next;
                    502:             }
1.2       matthew   503:             my $warningflag = '';
                    504: 	    my ($time,$res,$uname,$udom,$action,@values)= split(/:/,$chunk);
1.18      matthew   505:             #
1.1       matthew   506:             if (! defined($res) || $res =~ /^\s*$/) {
                    507:                 $res = '/adm/roles';
1.2       matthew   508:                 $action = 'LOGIN';
1.1       matthew   509:             }
                    510:             if ($res =~ m|^/prtspool/|) {
                    511:                 $res = '/prtspool/';
                    512:             }
                    513:             if (! defined($action) || $action eq '') {
1.2       matthew   514:                 $action = 'VIEW';
1.1       matthew   515:             }
1.2       matthew   516:             if ($action !~ /^(LOGIN|VIEW|POST|CSTORE|STORE)$/) {
                    517:                 $warningflag .= 'action';
1.3       matthew   518:                 print $error_fh 'full log entry:'.$log.$/;
1.20      matthew   519:                 print $error_fh 'error on chunk (saving)'.$/;
                    520:                 if (! &savechunk(\$chunk,$timestamp,$host)) {
                    521:                     close(IN);
                    522:                     return undef;
                    523:                 }
                    524:                 $logthis->('(action) Unable to parse chunk'.$/.
1.3       matthew   525:                          'got '.
                    526:                          'time = '.$time.$/.
                    527:                          'res  = '.$res.$/.
                    528:                          'uname= '.$uname.$/.
                    529:                          'udom = '.$udom.$/.
                    530:                          'action='.$action.$/.
1.11      matthew   531:                          '@values = '.join('&',@values));
1.3       matthew   532:                 next; #skip it if we cannot understand what is happening.
1.2       matthew   533:             }
                    534:             #
1.14      matthew   535:             my %data = (student  => $uname.':'.$udom,
                    536:                         resource => $res,
                    537:                         machine  => $host,
                    538:                         action   => $action,
                    539:                         time => &Apache::lonmysql::sqltime($time));
1.11      matthew   540:             if ($action eq 'POST') {
1.14      matthew   541:                 $data{'action_values'} =
1.11      matthew   542:                     $dbh->quote(join('&',map { &escape($_); } @values));
                    543:             } else {
1.14      matthew   544:                 $data{'action_values'} = $dbh->quote(join('&',@values));
                    545:             }
                    546:             my $error = &store_entry($dbh,$tables,\%data);
                    547:             if ($error) {
                    548:                 $logthis->('error store_entry:'.$error." on %data");
1.11      matthew   549:             }
1.2       matthew   550:             $prevchunk = $chunk;
1.1       matthew   551:         }
                    552:     }
1.14      matthew   553:     my $result = &store_entry($dbh,$tables);
                    554:     if (! defined($result)) {
                    555:         my $error = &Apache::lonmysql::get_error();
                    556:         warn "Error occured during insert.".$error;
                    557:         $logthis->('error = '.$error);
1.1       matthew   558:     }
                    559:     close IN;
                    560:     return $linecount;
1.20      matthew   561:     ##
                    562:     ##
                    563:     sub savechunk {
                    564:         my ($chunkref,$timestamp,$host) = @_;
                    565:         my $chunk = &escape(${$chunkref});
                    566:         if (! open(CHUNKFILE,">>$chunk_filename") ||
                    567:             ! print CHUNKFILE $timestamp.':'.$host.':'.$chunk.$/) {
                    568:             # abort
                    569:             close(CHUNKFILE);
                    570:             return 0;
                    571:         }
                    572:         close(CHUNKFILE);
                    573:         return 1;
                    574:     }
1.1       matthew   575: }
                    576: 
1.2       matthew   577: 
                    578: ##
1.14      matthew   579: ## default value for $logthis and $time_this
1.2       matthew   580: sub nothing {
                    581:     return;
                    582: }
                    583: 
                    584: ##
1.14      matthew   585: ## Logging routine (look for $log)
1.2       matthew   586: ##
                    587: sub log_to_file {
                    588:     my ($input)=@_;
                    589:     print LOGFILE $input.$/;
                    590: }
                    591: 
1.1       matthew   592: ##
                    593: ## Timing routines
                    594: ##
                    595: {
                    596:     my %Timing;
                    597:     my $starttime;
                    598: 
                    599: sub time_action {
                    600:     my ($key) = @_;
                    601:     if (defined($key)) {
                    602:         $Timing{$key}+=Time::HiRes::time-$starttime;
                    603:         $Timing{'count_'.$key}++;
                    604:     }
                    605:     $starttime = Time::HiRes::time;
                    606: }
                    607: 
                    608: sub outputtimes {
                    609:     my $Str;
                    610:     if ($time_run) {
                    611:         $Str = "Timing Data:".$/;
                    612:         while (my($k,$v) = each(%Timing)) {
                    613:             next if ($k =~ /^count_/);
                    614:             my $count = $Timing{'count_'.$k};
                    615:             $Str .= 
                    616:                 '  '.sprintf("%25.25s",$k).
                    617:                 '  '.sprintf('% 8d',$count).
                    618:                 '  '.sprintf('%12.5f',$v).$/;
                    619:         }
                    620:     }
                    621:     return $Str;
                    622: }
                    623: 
                    624: }
                    625: 
1.14      matthew   626: sub latest_table_modification_time {
                    627:     my $latest_time;
                    628:     foreach my $table (@Activity_Table,@ID_Tables) {    
                    629:         my %tabledata = &Apache::lonmysql::table_information($table->{'id'});
                    630:         next if (! scalar(keys(%tabledata))); # table does not exist
                    631:         if (! defined($latest_time) ||
                    632:             $latest_time < $tabledata{'Update_time'}) {
                    633:             $latest_time = $tabledata{'Update_time'};
                    634:         }
                    635:     }
                    636:     return $latest_time;
                    637: }
                    638: 
                    639: sub check_for_missing_tables {
                    640:     my @wanted_tables = @_;
                    641:     # Check for missing tables
                    642:     my @Current_Tables = &Apache::lonmysql::tables_in_db();
                    643:     my %Found;
                    644:     foreach my $tablename (@Current_Tables) {
                    645:         foreach my $table (@wanted_tables) {
                    646:             if ($tablename eq  $table) {
                    647:                 $Found{$tablename}++;
                    648:             }
                    649:         }
                    650:     }
                    651:     $logthis->('Found tables '.join(',',keys(%Found)));
                    652:     my $missing_a_table = 0;
                    653:     foreach my $table (@wanted_tables) {
                    654:         if (! $Found{$table}) {
                    655:             $logthis->('Missing table '.$table);
                    656:             $missing_a_table = 1;
                    657:             last;
                    658:         }
                    659:     }
                    660:     return $missing_a_table;
                    661: }
1.1       matthew   662: 
                    663: ##
                    664: ## Use mysqldump to store backups of the tables
                    665: ##
1.14      matthew   666: sub backup_tables_as_sql {
1.6       matthew   667:     my ($gz_sql_filename) = @_;
1.12      matthew   668:     my $command = qq{mysqldump --quote-names --opt loncapa };
1.3       matthew   669:     foreach my $table (@ID_Tables,@Activity_Table) {
1.1       matthew   670:         my $tablename = $table->{'id'};
1.12      matthew   671:         $tablename =~ s/\`//g;
1.1       matthew   672:         $command .= $tablename.' ';
                    673:     }
1.6       matthew   674:     $command .= '| gzip >'.$gz_sql_filename;
1.2       matthew   675:     $logthis->($command);
1.1       matthew   676:     system($command);
                    677: }
                    678: 
                    679: ##
                    680: ## Load in mysqldumped files
                    681: ##
1.14      matthew   682: sub load_backup_sql_tables {
1.6       matthew   683:     my ($gz_sql_filename) = @_;
                    684:     if (-s $gz_sql_filename) {
1.8       matthew   685:         $logthis->('loading data from gzipped sql file');
                    686:         my $command='gzip -dc '.$gz_sql_filename.' | mysql --database=loncapa';
1.6       matthew   687:         system($command);
                    688:         $logthis->('finished loading gzipped data');;
                    689:     } else {
                    690:         return undef;
                    691:     }
1.1       matthew   692: }
                    693: 
                    694: ##
                    695: ## 
                    696: ##
                    697: sub update_process_name {
                    698:     my ($text) = @_;
                    699:     $0 = 'parse_activity_log.pl: '.$text;
                    700: }
                    701: 
                    702: sub get_filename {
                    703:     my ($course,$domain) = @_;
                    704:     my ($a,$b,$c,undef) = split('',$course,4);
                    705:     return "$perlvar{'lonUsersDir'}/$domain/$a/$b/$c/$course/activity.log";
                    706: }
                    707: 
                    708: sub create_tables {
1.3       matthew   709:     foreach my $table (@ID_Tables,@Activity_Table) {
1.1       matthew   710:         my $table_id = &Apache::lonmysql::create_table($table);
                    711:         if (! defined($table_id)) {
                    712:             warn "Unable to create table ".$table->{'id'}.$/;
1.12      matthew   713:             $logthis->('Unable to create table '.$table->{'id'});
                    714:             $logthis->(join($/,&Apache::lonmysql::build_table_creation_request($table)));
1.1       matthew   715:             return 0;
                    716:         }
                    717:     }
                    718:     return 1;
                    719: }
                    720: 
                    721: sub drop_tables {
1.3       matthew   722:     foreach my $table (@ID_Tables,@Activity_Table) {
1.1       matthew   723:         my $table_id = $table->{'id'};
                    724:         &Apache::lonmysql::drop_table($table_id);
                    725:     }
                    726: }
                    727: 
                    728: #################################################################
                    729: #################################################################
                    730: ##
                    731: ## Database item id code
                    732: ##
                    733: #################################################################
                    734: #################################################################
                    735: { # Scoping for ID lookup code
                    736:     my %IDs;
                    737: 
                    738: sub read_id_tables {
1.3       matthew   739:     foreach my $table (@ID_Tables) {
1.1       matthew   740:         my @Data = &Apache::lonmysql::get_rows($table->{'id'});
1.3       matthew   741:         my $count = 0;
1.1       matthew   742:         foreach my $row (@Data) {
                    743:             $IDs{$table->{'id'}}->{$row->[1]} = $row->[0];
                    744:         }
                    745:     }
1.3       matthew   746:     return;
1.1       matthew   747: }
                    748: 
                    749: sub get_id {
                    750:     my ($table,$fieldname,$value) = @_;
1.16      matthew   751:     if (exists($IDs{$table}->{$value}) && $IDs{$table}->{$value} =~ /^\d+$/) {
1.1       matthew   752:         return $IDs{$table}->{$value};
                    753:     } else {
                    754:         # insert into the table - if the item already exists, that is
                    755:         # okay.
                    756:         my $result = &Apache::lonmysql::store_row($table,[undef,$value]);
                    757:         if (! defined($result)) {
1.16      matthew   758:             warn("Got error on id insert for $value\n".
                    759:                  &Apache::lonmysql::get_error());
1.1       matthew   760:         }
                    761:         # get the id
1.16      matthew   762:         my $id = &Apache::lonmysql::get_dbh()->{'mysql_insertid'};
                    763:         if (defined($id)) {
                    764:             $IDs{$table}->{$value}=$id;
1.1       matthew   765:         } else {
1.2       matthew   766:             $logthis->("Unable to retrieve id for $table $fieldname $value");
1.1       matthew   767:             return undef;
                    768:         }
                    769:     }
                    770: }
                    771: 
                    772: } # End of ID scoping
                    773: 
1.14      matthew   774: ###############################################################
                    775: ###############################################################
                    776: ##
                    777: ##   Save as XML
                    778: ##
                    779: ###############################################################
                    780: ###############################################################
                    781: sub backup_tables_as_xml {
                    782:     my ($filename,$tables) = @_;
                    783:     open(XMLFILE,"|gzip - > $filename") || return ('error:unable to write '.$filename);
                    784:     my $query = qq{
                    785:         SELECT B.resource,
                    786:                A.time,
                    787:                A.idx,
                    788:                C.student,
                    789:                A.action,
                    790:                E.machine,
                    791:                A.action_values 
                    792:             FROM $tables->{'activity'} AS A
                    793:             LEFT JOIN $tables->{'res'}      AS B ON B.res_id=A.res_id 
                    794:             LEFT JOIN $tables->{'student'}  AS C ON C.student_id=A.student_id 
                    795:             LEFT JOIN $tables->{'machine'}  AS E ON E.machine_id=A.machine_id
                    796:             ORDER BY A.time DESC
                    797:         };
                    798:     $query =~ s/\s+/ /g;
                    799:     my $dbh = &Apache::lonmysql::get_dbh();
                    800:     my $sth = $dbh->prepare($query);
                    801:     if (! $sth->execute()) {
                    802:         $logthis->('<font color="blue">'.
                    803:                    'WARNING: Could not retrieve from database:'.
                    804:                    $sth->errstr().'</font>');
                    805:         return undef;
                    806:     } else {
                    807:         my ($res,$sqltime,$idx,$student,$action,$machine,$action_values);
                    808:         if ($sth->bind_columns(\$res,\$sqltime,\$idx,\$student,\$action,
                    809:                                \$machine,\$action_values)) {
                    810:             
                    811:             while ($sth->fetch) {
                    812:                 print XMLFILE '<row>'.
                    813:                     qq{<resource>$res</resource>}.
                    814:                     qq{<time>$sqltime</time>}.
                    815:                     qq{<idx>$idx</idx>}.
                    816:                     qq{<student>$student</student>}.
                    817:                     qq{<action>$action</action>}.
                    818:                     qq{<machine>$machine</machine>}.
                    819:                     qq{<action_values>$action_values</action_values>}.
                    820:                     '</row>'.$/;
                    821:             }
                    822:         } else {
                    823:             warn "Unable to bind to columns.\n";
                    824:             return undef;
                    825:         }
                    826:     }
                    827:     close XMLFILE;
                    828:     return;
                    829: }
                    830: 
                    831: ###############################################################
                    832: ###############################################################
                    833: ##
                    834: ##   load as xml
                    835: ##
                    836: ###############################################################
                    837: ###############################################################
1.15      matthew   838: {
                    839:     my @fields = ('resource','time',
                    840:                   'student','action','idx','machine','action_values');
                    841:     my %ids = ();
1.14      matthew   842: sub load_backup_xml_tables {
                    843:     my ($filename,$tables) = @_;
1.16      matthew   844:     my $dbh = &Apache::lonmysql::get_dbh();
1.14      matthew   845:     my $xmlfh;
                    846:     open($xmlfh,"cat $filename | gzip -d - |");
                    847:     if (! defined($xmlfh)) {
                    848:         return ('error:unable to read '.$filename);
                    849:     }
1.15      matthew   850:     #
                    851:     %ids = (resource=> {"\0count"=>1},
                    852:             student=> {"\0count"=>1},
                    853:             machine=> {"\0count"=>1});
                    854:     #
1.14      matthew   855:     my %data;
1.15      matthew   856:     while (my $inputline = <$xmlfh>) {
                    857:         my ($resource,$time,undef,$student,$action,$machine,$action_values) = 
                    858:             ($inputline =~ m{<row>
                    859:                                  <resource>(.*)</resource>
                    860:                                  <time>(.*)</time>
                    861:                                  <idx>(.*)</idx>
                    862:                                  <student>(.*)</student>
                    863:                                  <action>(.*)</action>
                    864:                                  <machine>(.*)</machine>
                    865:                                  <action_values>(.*)</action_values>
                    866:                                  </row>$
                    867:                              }x
                    868:              );
                    869:         my $resource_id = &xml_get_id('resource',$resource);
                    870:         my $student_id  = &xml_get_id('student',$student);
                    871:         my $machine_id  = &xml_get_id('machine',$machine);
1.16      matthew   872:         &xml_store_activity_row(map { defined($_)?$dbh->quote($_):'' 
1.15      matthew   873:                                   } ($resource_id,
                    874:                                      $time,
                    875:                                      $student_id,
                    876:                                      $action,
                    877:                                      'NULL',
                    878:                                      $machine_id,
                    879:                                      $action_values));
                    880:     }
                    881:     &xml_store_activity_row();
                    882:     close($xmlfh);
                    883:     # Store id tables
                    884:     while (my ($id_name,$id_data) = each(%ids)) {
                    885:         if ($id_name eq 'resource') { $id_name = 'res'; }
                    886:         delete($id_data->{"\0count"});
                    887:         &xml_store_id_table($id_name,$id_data);
                    888:     }
                    889:     return;
                    890: }
                    891: 
                    892: sub xml_get_id {
                    893:     my ($table,$element) = @_;
                    894:     if (! exists($ids{$table}->{$element})) {
                    895:         $ids{$table}->{$element} = $ids{$table}->{"\0count"}++;
                    896:     }
                    897:     return $ids{$table}->{$element};
                    898: }
                    899: 
                    900: {
                    901:     my @data_rows;
                    902: sub xml_store_activity_row {
                    903:     my @data = @_;
                    904:     if (scalar(@data)) {
                    905:         push(@data_rows,[@data]);
                    906:     }
                    907:     if (! scalar(@data) || scalar(@data_rows) > 500) {
                    908:         if (! &Apache::lonmysql::bulk_store_rows($tables{'activity'},
                    909:                                                  scalar(@{$data_rows[0]}),
                    910:                                                  \@data_rows)) {
                    911:             $logthis->("Error:".&Apache::lonmysql::get_error());
                    912:             warn("Error:".&Apache::lonmysql::get_error());
                    913:         } else {
                    914:             undef(@data_rows);
1.14      matthew   915:         }
                    916:     }
                    917:     return;
                    918: }
                    919: 
1.15      matthew   920: }
                    921: 
                    922: sub xml_store_id_table {
                    923:     my ($table,$tabledata) =@_;
1.16      matthew   924:     my $dbh = &Apache::lonmysql::get_dbh();
1.15      matthew   925:     if (! &Apache::lonmysql::bulk_store_rows
                    926:         ($tables{$table},2,
1.16      matthew   927:          [map{[$tabledata->{$_},$dbh->quote($_)]} keys(%$tabledata)])) {
1.15      matthew   928:         $logthis->("Error:".&Apache::lonmysql::get_error());
                    929:         warn "Error:".&Apache::lonmysql::get_error().$/;
                    930:     }
                    931: }
                    932: 
                    933: } # End of load xml scoping
1.14      matthew   934: 
                    935: #######################################################################
                    936: #######################################################################
                    937: ##
                    938: ## store_entry - accumulate data to be inserted into the database
1.15      matthew   939: ##
1.14      matthew   940: ## Pass no values in to clear accumulator
                    941: ## Pass ($dbh,\%tables) to initiate storage of values
                    942: ## Pass ($dbh,\%tables,\%data) to use normally
                    943: ##
                    944: #######################################################################
                    945: #######################################################################
                    946: {
                    947:     my @rows;
                    948: 
                    949: sub store_entry {
1.23    ! albertel  950:     my $max_row_count = 100;
1.14      matthew   951:     if (! @_) {
                    952:         undef(@rows);
                    953:         return '';
                    954:     }
                    955:     my ($dbh,$tables,$data) = @_;
                    956:     return if (! defined($tables));
                    957:     if (defined($data)) {
                    958:         my $error;
                    959:         foreach my $field ('student','resource','action','time') {
                    960:             if (! defined($data->{$field}) || $data->{$field} eq ':' ||
                    961:                 $data->{$field}=~ /^\s*$/) {
                    962:                 $error.=$field.',';
                    963:             }
                    964:         }
                    965:         if ($error) { $error=~s/,$//; return $error; }
                    966:         #
                    967:         my $student_id = &get_id($tables->{'student'},'student',
                    968:                                  $data->{'student'});
                    969:         my $res_id     = &get_id($tables->{'res'},
                    970:                                  'resource',$data->{'resource'});
                    971:         my $machine_id = &get_id($tables->{'machine'},
                    972:                                  'machine',$data->{'machine'});
                    973:         my $idx = $data->{'idx'}; if (! $idx) { $idx = "''"; }
                    974:         #
                    975:         push(@rows,[$res_id,
                    976:                     qq{'$data->{'time'}'},
                    977:                     $student_id,
                    978:                     qq{'$data->{'action'}'},
                    979:                     $idx,
                    980:                     $machine_id,
                    981:                     $data->{'action_values'}]);
                    982:     }
1.15      matthew   983:     if (defined($tables) &&
1.14      matthew   984:         ( (! defined($data) && scalar(@rows)) || scalar(@rows)>$max_row_count)
                    985:         ){
                    986:         # Store the rows
1.15      matthew   987:         my $result =
1.14      matthew   988:             &Apache::lonmysql::bulk_store_rows($tables->{'activity'},
                    989:                                                undef,
                    990:                                                \@rows);
                    991:         if (! defined($result)) {
                    992:             my $error = &Apache::lonmysql::get_error();
                    993:             warn "Error occured during insert.".$error;
                    994:             return $error;
                    995:         }
                    996:         undef(@rows);
                    997:         return $result if (! defined($data));
                    998:     }
                    999:     return '';
                   1000: }
                   1001: 
                   1002: } # end of scope for &store_entry
1.1       matthew  1003: 
                   1004: ###############################################################
                   1005: ###############################################################
                   1006: ##
                   1007: ##   The usual suspects
                   1008: ##
                   1009: ###############################################################
                   1010: ###############################################################
                   1011: sub escape {
                   1012:     my $str=shift;
                   1013:     $str =~ s/(\W)/"%".unpack('H2',$1)/eg;
                   1014:     return $str;
                   1015: }
                   1016: 
                   1017: sub unescape {
                   1018:     my $str=shift;
                   1019:     $str =~ s/%([a-fA-F0-9][a-fA-F0-9])/pack("C",hex($1))/eg;
                   1020:     return $str;
                   1021: }

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