1: #!/usr/bin/perl
2: #
3: # The LearningOnline Network
4: #
5: # $Id: parse_activity_log.pl,v 1.3 2004/08/19 21:08:46 matthew Exp $
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: #
29: #--------------------------------------------------------------------
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
37: # 5 Unspecified error?
38: #
39:
40: use strict;
41: use DBI;
42: use lib '/home/httpd/lib/perl/Apache';
43: use lonmysql();
44: use Time::HiRes();
45: use Getopt::Long();
46: use IO::File;
47:
48: #
49: # Determine parameters
50: my ($help,$course,$domain,$drop,$file,$time_run,$nocleanup,$log);
51: &Getopt::Long::GetOptions( "course=s" => \$course,
52: "domain=s" => \$domain,
53: "help" => \$help,
54: "logfile=s" => \$file,
55: "timerun" => \$time_run,
56: "nocleanup" => \$nocleanup,
57: "drop" => \$drop,
58: "log" => \$log);
59: if (! defined($course) || $help) {
60: print<<USAGE;
61: parse_activity_log.pl
62:
63: Process a lon-capa activity log into a database.
64: Parameters:
65: course Required
66: domain Optional
67: drop optional if present, drop all course
68: specific activity log tables.
69: file optional Specify the file to parse, including path
70: time optional if present, print out timing data
71: nocleanup optional if present, do not remove old files
72: log optional if present, prepare log file of activity
73: Examples:
74: $0 -course=123456abcdef -domain=msu
75: $0 -course=123456abcdef -file=activity.log
76: USAGE
77: exit;
78: }
79:
80: ##
81: ## Set up timing code
82: my $time_this = \¬hing;
83: if ($time_run) {
84: $time_this = \&time_action;
85: }
86: my $initial_time = Time::HiRes::time;
87:
88: ##
89: ## Read in configuration parameters
90: ##
91: my %perlvar;
92: &initialize_configuration();
93: if (! defined($domain) || $domain eq '') {
94: $domain = $perlvar{'lonDefDomain'};
95: }
96: &update_process_name($course.'@'.$domain);
97:
98: ##
99: ## Set up logging code
100: my $logthis = \¬hing;
101: if ($log) {
102: my $logfile = "/tmp/parse_activity_log.log.".time;
103: print STDERR "$0: logging to $logfile".$/;
104: if (! open(LOGFILE,">$logfile")) {
105: die "Unable to open $logfile for writing. Run aborted.";
106: } else {
107: $logthis = \&log_to_file;
108: }
109: }
110:
111:
112: ##
113: ## Determine filenames
114: ##
115: my $sourcefilename; # activity log data
116: my $newfilename; # $sourcefilename will be renamed to this
117: my $sql_filename; # the mysql backup data file name.
118: my $error_filename; # Errors in parsing the activity log will be written here
119: if ($file) {
120: $sourcefilename = $file;
121: } else {
122: $sourcefilename = &get_filename($course,$domain);
123: }
124: $sql_filename = $sourcefilename;
125: $sql_filename =~ s|[^/]*$|activity.log.sql|;
126: $error_filename = $sourcefilename;
127: $error_filename =~ s|[^/]*$|activity.log.errors|;
128: $logthis->('Beginning logging '.time);
129:
130: ##
131: ## There will only be a $newfilename file if a copy of this program is already
132: ## running.
133: my $newfilename = $sourcefilename.'.processing';
134: if (-e $newfilename) {
135: warn "$newfilename exists";
136: $logthis->($newfilename.' exists');
137: exit 2;
138: }
139:
140: if (-e $sourcefilename) {
141: $logthis->('renaming '.$sourcefilename.' to '.$newfilename);
142: rename($sourcefilename,$newfilename);
143: $logthis->("renamed $sourcefilename to $newfilename");
144: } else {
145: my $command = 'touch '.$newfilename;
146: $logthis->($command);
147: system($command);
148: $logthis->('touch was completed');
149: }
150:
151: ##
152: ## Table definitions
153: ##
154: my $prefix = $course.'_'.$domain.'_';
155: my $student_table = $prefix.'students';
156: my $student_table_def =
157: { id => $student_table,
158: permanent => 'no',
159: columns => [
160: { name => 'student_id',
161: type => 'MEDIUMINT UNSIGNED',
162: restrictions => 'NOT NULL',
163: auto_inc => 'yes', },
164: { name => 'student',
165: type => 'VARCHAR(100) BINARY',
166: restrictions => 'NOT NULL', },
167: ],
168: 'PRIMARY KEY' => ['student_id',],
169: };
170:
171: my $res_table = $prefix.'resource';
172: my $res_table_def =
173: { id => $res_table,
174: permanent => 'no',
175: columns => [{ name => 'res_id',
176: type => 'MEDIUMINT UNSIGNED',
177: restrictions => 'NOT NULL',
178: auto_inc => 'yes', },
179: { name => 'resource',
180: type => 'MEDIUMTEXT',
181: restrictions => 'NOT NULL'},
182: ],
183: 'PRIMARY KEY' => ['res_id'],
184: };
185:
186: my $action_table = $prefix.'actions';
187: my $action_table_def =
188: { id => $action_table,
189: permanent => 'no',
190: columns => [{ name => 'action_id',
191: type => 'MEDIUMINT UNSIGNED',
192: restrictions => 'NOT NULL',
193: auto_inc => 'yes', },
194: { name => 'action',
195: type => 'VARCHAR(100)',
196: restrictions => 'NOT NULL'},
197: ],
198: 'PRIMARY KEY' => ['action_id',],
199: };
200:
201: my $machine_table = $prefix.'machine_table';
202: my $machine_table_def =
203: { id => $machine_table,
204: permanent => 'no',
205: columns => [{ name => 'machine_id',
206: type => 'MEDIUMINT UNSIGNED',
207: restrictions => 'NOT NULL',
208: auto_inc => 'yes', },
209: { name => 'machine',
210: type => 'VARCHAR(100)',
211: restrictions => 'NOT NULL'},
212: ],
213: 'PRIMARY KEY' => ['machine_id',],
214: };
215:
216: my $activity_table = $prefix.'activity';
217: my $activity_table_def =
218: { id => $activity_table,
219: permanent => 'no',
220: columns => [
221: { name => 'res_id',
222: type => 'MEDIUMINT UNSIGNED',
223: restrictions => 'NOT NULL',},
224: { name => 'time',
225: type => 'DATETIME',
226: restrictions => 'NOT NULL',},
227: { name => 'student_id',
228: type => 'MEDIUMINT UNSIGNED',
229: restrictions => 'NOT NULL',},
230: { name => 'action_id',
231: type => 'MEDIUMINT UNSIGNED',
232: restrictions => 'NOT NULL',},
233: { name => 'idx', # This is here in case a student
234: type => 'MEDIUMINT UNSIGNED', # has multiple submissions during
235: restrictions => 'NOT NULL', # one second. It happens, trust
236: auto_inc => 'yes', }, # me.
237: { name => 'machine_id',
238: type => 'MEDIUMINT UNSIGNED',
239: restrictions => 'NOT NULL',},
240: { name => 'action_values',
241: type => 'MEDIUMTEXT', },
242: ],
243: 'PRIMARY KEY' => ['res_id','time','student_id','action_id','idx'],
244: };
245: my @Activity_Table = ($activity_table_def);
246: my @ID_Tables = ($student_table_def,$res_table_def,
247: $action_table_def,$machine_table_def);
248:
249:
250: ##
251: ## End of table definitions
252: ##
253:
254: #
255: $logthis->('Connectiong to mysql');
256: &Apache::lonmysql::set_mysql_user_and_password($perlvar{'lonSqlUser'},
257: $perlvar{'lonSqlAccess'});
258: if (!&Apache::lonmysql::verify_sql_connection()) {
259: warn "Unable to connect to MySQL database.";
260: $logthis->("Unable to connect to MySQL database.");
261: exit 3;
262: }
263:
264: $logthis->('SQL connection is up');
265:
266: if ($drop) { &drop_tables(); $logthis->('dropped tables'); }
267:
268: if (-s $sql_filename) {
269: # if ANY one of the tables does not exist, load the tables from the
270: # backup.
271: my @Current_Tables = &Apache::lonmysql::tables_in_db();
272: my %Found;
273: foreach my $tablename (@Current_Tables) {
274: foreach my $table (@Activity_Table,@ID_Tables) {
275: if ($tablename eq $table->{'id'}) {
276: $Found{$tablename}++;
277: }
278: }
279: }
280: foreach my $table (@Activity_Table,@ID_Tables) {
281: if (! $Found{$table->{'id'}}) {
282: $time_this->();
283: &load_backup_tables($sql_filename);
284: $time_this->('load backup tables');
285: last;
286: }
287: }
288: }
289:
290: ##
291: ## Ensure the tables we need exist
292: # create_tables does not complain if the tables already exist
293: $logthis->('creating tables');
294: if (! &create_tables()) {
295: warn "Unable to create tables";
296: $logthis->('Unable to create tables');
297: exit 4;
298: }
299:
300: ##
301: ## Read the ids used for various tables
302: $logthis->('reading id tables');
303: &read_id_tables();
304: $logthis->('finished reading id tables');
305:
306: ##
307: ## Set up the errors file
308: my $error_fh = IO::File->new(">>$error_filename");
309:
310: ##
311: ## Parse the course log
312: $logthis->('processing course log');
313: if (-s $newfilename) {
314: my $result = &process_courselog($newfilename,$error_fh);
315: if (! defined($result)) {
316: # Something went wrong along the way...
317: $logthis->('process_courselog returned undef');
318: exit 5;
319: } elsif ($result > 0) {
320: $time_this->();
321: $logthis->('process_courselog returned '.$result.' backup up tables');
322: &backup_tables($sql_filename);
323: $time_this->('write backup tables');
324: }
325: }
326: close($error_fh);
327:
328: ##
329: ## Clean up the filesystem
330: &Apache::lonmysql::disconnect_from_db();
331: unlink($newfilename) if (-e $newfilename && ! $nocleanup);
332:
333: ##
334: ## Print timing data
335: $logthis->('printing timing data');
336: if ($time_run) {
337: my $elapsed_time = Time::HiRes::time - $initial_time;
338: print "Overall time: ".$elapsed_time.$/;
339: print &outputtimes();
340: $logthis->("Overall time: ".$elapsed_time);
341: $logthis->(&outputtimes());
342: }
343:
344: if ($log) {
345: close LOGFILE;
346: }
347:
348: exit 0; # Everything is okay, so end here before it gets worse.
349:
350: ########################################################
351: ########################################################
352: ##
353: ## Process Course Log
354: ##
355: ########################################################
356: ########################################################
357: #
358: # Returns the number of lines in the activity.log file that were processed.
359: sub process_courselog {
360: my ($inputfile,$error_fh) = @_;
361: if (! open(IN,$inputfile)) {
362: warn "Unable to open '$inputfile' for reading";
363: $logthis->("Unable to open '$inputfile' for reading");
364: return undef;
365: }
366: my ($linecount,$insertcount);
367: my $dbh = &Apache::lonmysql::get_dbh();
368: #
369: # Timing variables
370: my @RowData;
371: while (my $line=<IN>){
372: # last if ($linecount > 1000);
373: #
374: # Bulk storage variables
375: $time_this->();
376: chomp($line);
377: $linecount++;
378: # print $linecount++.$/;
379: my ($timestamp,$host,$log)=split(/\:/,$line,3);
380: $time_this->('splitline');
381: #
382: # $log has the actual log entries; currently still escaped, and
383: # %26(timestamp)%3a(url)%3a(user)%3a(domain)
384: # then additionally
385: # %3aPOST%3a(name)%3d(value)%3a(name)%3d(value)
386: # or
387: # %3aCSTORE%3a(name)%3d(value)%26(name)%3d(value)
388: #
389: # get delimiter between timestamped entries to be &&&
390: $log=~s/\%26(\d{9,10})\%3a/\&\&\&$1\%3a/g;
391: $log = &unescape($log);
392: $time_this->('translate_and_unescape');
393: # now go over all log entries
394: if (! defined($host)) { $host = 'unknown'; }
395: my $machine_id = &get_id($machine_table,'machine',$host);
396: my $prevchunk = 'none';
397: foreach my $chunk (split(/\&\&\&/,$log)) {
398: my $warningflag = '';
399: $time_this->();
400: my ($time,$res,$uname,$udom,$action,@values)= split(/:/,$chunk);
401: my $student = $uname.':'.$udom;
402: if (! defined($res) || $res =~ /^\s*$/) {
403: $res = '/adm/roles';
404: $action = 'LOGIN';
405: }
406: if ($res =~ m|^/prtspool/|) {
407: $res = '/prtspool/';
408: }
409: if (! defined($action) || $action eq '') {
410: $action = 'VIEW';
411: }
412: if ($action !~ /^(LOGIN|VIEW|POST|CSTORE|STORE)$/) {
413: $warningflag .= 'action';
414: print $error_fh 'full log entry:'.$log.$/;
415: print $error_fh 'error on chunk:'.$chunk.$/;
416: $logthis->('(action) Unable to parse '.$/.$chunk.$/.
417: 'got '.
418: 'time = '.$time.$/.
419: 'res = '.$res.$/.
420: 'uname= '.$uname.$/.
421: 'udom = '.$udom.$/.
422: 'action='.$action.$/.
423: '@values = '.join(':',@values));
424: next; #skip it if we cannot understand what is happening.
425: }
426: if (! defined($student) || $student eq ':') {
427: $student = 'unknown';
428: $warningflag .= 'student';
429: }
430: if (! defined($res) || $res =~ /^\s*$/) {
431: $res = 'unknown';
432: $warningflag .= 'res';
433: }
434: if (! defined($action) || $action =~ /^\s*$/) {
435: $action = 'unknown';
436: $warningflag .= 'action';
437: }
438: if (! defined($time) || $time !~ /^\d+$/) {
439: $time = 0;
440: $warningflag .= 'time';
441: }
442: #
443: $time_this->('split_and_error_check');
444: my $student_id = &get_id($student_table,'student',$student);
445: my $res_id = &get_id($res_table,'resource',$res);
446: my $action_id = &get_id($action_table,'action',$action);
447: my $sql_time = &Apache::lonmysql::sqltime($time);
448: #
449: if (! defined($student_id) || $student_id eq '') {
450: $warningflag.='student_id';
451: }
452: if (! defined($res_id) || $res_id eq '') {
453: $warningflag.='res_id';
454: }
455: if (! defined($action_id) || $action_id eq '') {
456: $warningflag.='action_id';
457: }
458: if ($warningflag ne '') {
459: print $error_fh 'full log entry:'.$log.$/;
460: print $error_fh 'error on chunk:'.$chunk.$/;
461: $logthis->('warningflag ('.$warningflag.') on chunk '.
462: $/.$chunk.$/.'prevchunk = '.$/.$prevchunk);
463: $prevchunk .= $chunk;
464: next; # skip this chunk
465: }
466: #
467: my $values = $dbh->quote(join('',@values));
468: $time_this->('get_ids');
469: #
470: my $row = [$res_id,
471: qq{'$sql_time'},
472: $student_id,
473: $action_id,
474: qq{''}, # idx
475: $machine_id,
476: $values];
477: push(@RowData,$row);
478: $time_this->('push_row');
479: $prevchunk = $chunk;
480: #
481: }
482: $time_this->();
483: if ((scalar(@RowData) > 0) && ($linecount % 100 == 0)) {
484: my $result = &Apache::lonmysql::bulk_store_rows($activity_table,
485: undef,
486: \@RowData);
487: # $logthis->('result = '.$result);
488: $time_this->('bulk_store_rows');
489: if (! defined($result)) {
490: my $error = &Apache::lonmysql::get_error();
491: warn "Error occured during insert.".$error;
492: $logthis->('error = '.$error);
493: }
494: undef(@RowData);
495: }
496: }
497: if (@RowData) {
498: $time_this->();
499: $logthis->('storing '.$linecount);
500: my $result = &Apache::lonmysql::bulk_store_rows($activity_table,
501: undef,
502: \@RowData);
503: $logthis->('result = '.$result);
504: $time_this->('bulk_store_rows');
505: if (! defined($result)) {
506: my $error = &Apache::lonmysql::get_error();
507: warn "Error occured during insert.".$error;
508: $logthis->('error = '.$error);
509: }
510: undef(@RowData);
511: }
512: close IN;
513: # print "Number of lines: ".$linecount.$/;
514: # print "Number of inserts: ".$insertcount.$/;
515: return $linecount;
516: }
517:
518:
519: ##
520: ## Somtimes, instead of doing something, doing nothing is appropriate.
521: sub nothing {
522: return;
523: }
524:
525: ##
526: ## Logging routine
527: ##
528: sub log_to_file {
529: my ($input)=@_;
530: print LOGFILE $input.$/;
531: }
532:
533: ##
534: ## Timing routines
535: ##
536: {
537: my %Timing;
538: my $starttime;
539:
540: sub time_action {
541: my ($key) = @_;
542: if (defined($key)) {
543: $Timing{$key}+=Time::HiRes::time-$starttime;
544: $Timing{'count_'.$key}++;
545: }
546: $starttime = Time::HiRes::time;
547: }
548:
549: sub outputtimes {
550: my $Str;
551: if ($time_run) {
552: $Str = "Timing Data:".$/;
553: while (my($k,$v) = each(%Timing)) {
554: next if ($k =~ /^count_/);
555: my $count = $Timing{'count_'.$k};
556: $Str .=
557: ' '.sprintf("%25.25s",$k).
558: ' '.sprintf('% 8d',$count).
559: ' '.sprintf('%12.5f',$v).$/;
560: }
561: }
562: return $Str;
563: }
564:
565: }
566:
567:
568: ##
569: ## Use mysqldump to store backups of the tables
570: ##
571: sub backup_tables {
572: my ($sql_filename) = @_;
573: my $command = qq{mysqldump --opt loncapa };
574:
575: foreach my $table (@ID_Tables,@Activity_Table) {
576: my $tablename = $table->{'id'};
577: $command .= $tablename.' ';
578: }
579: $command .= '>'.$sql_filename;
580: $logthis->($command);
581: system($command);
582: }
583:
584: ##
585: ## Load in mysqldumped files
586: ##
587: sub load_backup_tables {
588: my ($sql_filename) = @_;
589: return undef if (! -e $sql_filename);
590: # Check for .my.cnf
591: my $command = 'mysql -e "SOURCE '.$sql_filename.'" loncapa';
592: $logthis->('loading previously saved sql table'.$/.$command);
593: system($command);
594: $logthis->('finished loading old data');
595: }
596:
597: ##
598: ##
599: ##
600: sub initialize_configuration {
601: # Fake it for now:
602: $perlvar{'lonSqlUser'} = 'www';
603: $perlvar{'lonSqlAccess'} = 'localhostkey';
604: $perlvar{'lonUsersDir'} = '/home/httpd/lonUsers';
605: $perlvar{'lonDefDomain'} = '103';
606: }
607:
608: sub update_process_name {
609: my ($text) = @_;
610: $0 = 'parse_activity_log.pl: '.$text;
611: }
612:
613: sub get_filename {
614: my ($course,$domain) = @_;
615: my ($a,$b,$c,undef) = split('',$course,4);
616: return "$perlvar{'lonUsersDir'}/$domain/$a/$b/$c/$course/activity.log";
617: }
618:
619: sub create_tables {
620: foreach my $table (@ID_Tables,@Activity_Table) {
621: my $table_id = &Apache::lonmysql::create_table($table);
622: if (! defined($table_id)) {
623: warn "Unable to create table ".$table->{'id'}.$/;
624: warn &Apache::lonmysql::build_table_creation_request($table).$/;
625: return 0;
626: }
627: }
628: return 1;
629: }
630:
631: sub drop_tables {
632: foreach my $table (@ID_Tables,@Activity_Table) {
633: my $table_id = $table->{'id'};
634: &Apache::lonmysql::drop_table($table_id);
635: }
636: }
637:
638: #################################################################
639: #################################################################
640: ##
641: ## Database item id code
642: ##
643: #################################################################
644: #################################################################
645: { # Scoping for ID lookup code
646: my %IDs;
647:
648: sub read_id_tables {
649: foreach my $table (@ID_Tables) {
650: my @Data = &Apache::lonmysql::get_rows($table->{'id'});
651: my $count = 0;
652: foreach my $row (@Data) {
653: $IDs{$table->{'id'}}->{$row->[1]} = $row->[0];
654: }
655: }
656: return;
657: }
658:
659: sub get_id {
660: my ($table,$fieldname,$value) = @_;
661: if (exists($IDs{$table}->{$value})) {
662: return $IDs{$table}->{$value};
663: } else {
664: # insert into the table - if the item already exists, that is
665: # okay.
666: my $result = &Apache::lonmysql::store_row($table,[undef,$value]);
667: if (! defined($result)) {
668: warn("Got error on id insert for $value\n".&Apache::lonmysql::get_error());
669: }
670: # get the id
671: my @Data =
672: &Apache::lonmysql::get_rows($table,qq{$fieldname='$value'});
673: if (@Data) {
674: $IDs{$table}->{$value}=$Data[0]->[0];
675: return $IDs{$table}->{$value};
676: } else {
677: $logthis->("Unable to retrieve id for $table $fieldname $value");
678: return undef;
679: }
680: }
681: }
682:
683: } # End of ID scoping
684:
685:
686: ###############################################################
687: ###############################################################
688: ##
689: ## The usual suspects
690: ##
691: ###############################################################
692: ###############################################################
693: sub escape {
694: my $str=shift;
695: $str =~ s/(\W)/"%".unpack('H2',$1)/eg;
696: return $str;
697: }
698:
699: sub unescape {
700: my $str=shift;
701: $str =~ s/%([a-fA-F0-9][a-fA-F0-9])/pack("C",hex($1))/eg;
702: return $str;
703: }
FreeBSD-CVSweb <freebsd-cvsweb@FreeBSD.org>
![[BACK]](/icons/back.gif){kind=icon}
Return to parse_activity_log.pl CVS log ![[TXT]](/icons/text.gif){kind=icon}
![[DIR]](/icons/dir.gif){kind=icon}
Up to [LON-CAPA] / loncom / metadata_database