openwebwork-devel

[WWdevel] more logging

[John J. <jj...@as...>]

Webwork 1 had a fuller logging procedure, where basically every click 
was logged.  I found that useful since I sometimes had to figure out 
what a teacher had done (in addition to answering questions about what 
students did).

The webwork 2 logging framework made it easy to replicate this: one line 
in global.conf to define the log file, and then one (long) line in 
ContentGenerator to call the writeCourseLog to record the url and the 
cgi parameters.  So, this raised a couple of questions:

    * would we want this facility in the main webwork?
    * if so, should it be more refined (so individual modules can give
      more finely tuned log entries)?

Thoughts?

John

Re: [WWdevel] more logging

[Michael G. <ga...@ma...>]

Hi,

Here is some data about the current logging facilities in WeBWorK2.   
It is taken from global.conf.dist with a few annotations comparing
the facilities with WW1.9

######################################################################## 
########
# Logs
######################################################################## 
########

# FIXME: take logs out of %webworkFiles/%courseFiles and give them  
their own
# top-level hash.

> Fixing this would also allow us to consolidate the writeLog and  
> writeCourseLog subroutines.  Currently the only difference
> is where in the course environment they search for the path to the  
> log file.

# Logs data about how long it takes to process problems. (Do not  
confuse this
# with the /other/ timing log which can be set by WeBWorK::Timing and  
is used
# for benchmarking system performance in general. At some point, this  
timing
# mechanism will be deprecated in favor of the WeBWorK::Timing  
mechanism.)
$webworkFiles{logs}{timing}         = "$webworkDirs{logs}/timing.log";
>    - this is total time taken for any given response.  I find this  
> helpful in moderating day to day
> performance of our local servers.  It is also possible to obtain  
> more detailed timing data
> -- but it is now housed in the Debug.pm module, not Timing.pm.  I  
> don't think it is necessary
> for production installations.  The timing log fills up fast and  
> should be rotated.
# Logs courses created via the web-based Course Administration module.
$webworkFiles{logs}{hosted_courses} = "$webworkDirs{logs}/ 
hosted_courses.log";

> this is only used in the Admin course, and keeps a record of  
> courses created and deleted on the server.

# The transaction log contains data from each recorded answer  
submission. This
# is useful if the database becomes corrupted.
$webworkFiles{logs}{transaction}    = "$courseDirs{logs}/ 
transaction.log";
> This records all of the data provided by a student when they answer  
> a problem. It is updated using the
Utils::writeLog(ce, "transaction" ... ) subroutine.
> It is roughly  equivalent to
> the Global::log_info logging facility in WW1.9 which "captured  
> every key stroke" of the student and store its data in
> the file, usually named access_log.  What it actually saved was the  
> entire url query string, including any hidden data.
>
> There is one important difference in that Global::log_info was  
> called on most scripts, including instructor scripts, while
> the transaction log is only updated when answering a WeBWorK  
> problem. The WW1.9 log contains instructor house keeping
> actions as  well as student actions.

# The answer log stores a history of all users' submitted answers.
$courseFiles{logs}{answer_log}      = "$courseDirs{logs}/answer_log";

> This is a separate log that records the students' answer history.   
> it duplicates some information in the transaction log. It was
> created at a different time and for a different purpose than the  
> transaction.log.  It might be useful to consolidate some of the
> code involved in these two logs.  It also would be worth  
> considering placing this data directly in the sql database.  The  
> upside, particularly for student answers, is that it would become  
> easier to search for certain types of student mistakes using sql  
> queries.  On the downside this might interfere with performance.

> The format for storing the data in both answer_log and in  
> transaction log is somewhat ad hoc.  If we continue to store the  
> data in a file then storing the data in an xml format would  
> facilitate being able to manipulate the data later using  
> standardized tools.  We might store the data in a file, but  
> periodically extract it and store it in an sql database for  
> research purposes.


# Log logins.
$courseFiles{logs}{login_log}       = "$courseDirs{logs}/login.log";

> This merely records each time a student logs in to webwork.


Take care,

Mike

#################

On Aug 27, 2005, at 6:49 PM, John Jones wrote:

> Webwork 1 had a fuller logging procedure, where basically every  
> click was logged.  I found that useful since I sometimes had to  
> figure out what a teacher had done (in addition to answering  
> questions about what students did).
>
> The webwork 2 logging framework made it easy to replicate this: one  
> line in global.conf to define the log file, and then one (long)  
> line in ContentGenerator to call the writeCourseLog to record the  
> url and the cgi parameters.  So, this raised a couple of questions:
> would we want this facility in the main webwork?
> if so, should it be more refined (so individual modules can give  
> more finely tuned log entries)?
> Thoughts?
>
> John
>

Re: [WWdevel] more logging

[John J. <jj...@as...>]

Thanks Mike,

I was aware of most of the information on logging.  The question remains 
as to whether there should be more.  I'll give a couple of scenerios 
where I would have found additional logging to be useful.  It is 
possible I could have found the needed information in the debug log if I 
had that turned on, but I find that it has too much information.  It is 
more appropriate to debugging a problem on a private system when you 
know how to produce it.  Here are the examples:

    * recently I was doing a workshop for CC teachers.  While showing
      how to assign a set to the whole class, I got an add vs. put
      database error.  I don't have any reasonable way to figure out why
      that happened.  I have a guess, but it would have been nice to go
      back to the logs to verify it.
    * this week we had a course which had an sql_single database
      corrupted.  This was a "" vs. 0 type error (every student suddenly
      had 0 allowed attempts on the problems and the problems had value
      0).  I asked the teacher what things he had done, repeated the
      steps, but was unable to reproduce the bug.  With more logging, I
      would know everything that happened to that set from the time it
      was imported, and I think I would then be able to reproduce and
      fix it.  This is a pretty problematic bug, but unless we know how
      to trigger it, it will be hard to fix.
    * every semester we get students who say they did some problems,
      came back, and they no longer had credit for them.  Our guess as
      to what happened are - you only previewed the answers; you were
      after the due date and just checked answers; you were logged in as
      a guest user.  With WW 1.*, we could pin this down.  Now, we have
      no way of verifying the first two since previews and checks don't
      get logged.  If the instructor says, it might be this, or it might
      be that, the student may think "or it was a bug in that system
      they make me use".  If you can say, we checked the logs and here
      is what you did, then it is much more convincing.

For the last item, another approach to dealing with this would be to put 
the information in the answer log (which, as you pointed out, is 
basically redundant with the transaction log).  We would need to add 
another field for whether something was a submit/preview/check, and then 
display that in the "Show Past Answers" page.  That might be a good idea 
in any case since it makes it easy for individual teachers to research 
student complaints.

As it stands, the only changes I made on our systems for this were in 
two files which are entirely local: local.conf (we adopted Davide's 
approach of not touching global.conf.dist; having global.conf load 
global.conf.dist and then load local.conf) and ContentGenerator.pm 
(which we had to fork to accomodate some things related to the ASU login 
scheme).  So, it is no extra work for me to maintain separate versions 
of these files.  I was wondering if others would find this useful enough 
to include it as an option.

John



Michael Gage wrote:

> Hi,
>
> Here is some data about the current logging facilities in WeBWorK2.   
> It is taken from global.conf.dist with a few annotations comparing
> the facilities with WW1.9
>
> ######################################################################## 
> ########
> # Logs
> ######################################################################## 
> ########
>
> # FIXME: take logs out of %webworkFiles/%courseFiles and give them  
> their own
> # top-level hash.
>
>> Fixing this would also allow us to consolidate the writeLog and  
>> writeCourseLog subroutines.  Currently the only difference
>> is where in the course environment they search for the path to the  
>> log file.
>
>
> # Logs data about how long it takes to process problems. (Do not  
> confuse this
> # with the /other/ timing log which can be set by WeBWorK::Timing and  
> is used
> # for benchmarking system performance in general. At some point, this  
> timing
> # mechanism will be deprecated in favor of the WeBWorK::Timing  
> mechanism.)
> $webworkFiles{logs}{timing}         = "$webworkDirs{logs}/timing.log";
>
>>    - this is total time taken for any given response.  I find this  
>> helpful in moderating day to day
>> performance of our local servers.  It is also possible to obtain  
>> more detailed timing data
>> -- but it is now housed in the Debug.pm module, not Timing.pm.  I  
>> don't think it is necessary
>> for production installations.  The timing log fills up fast and  
>> should be rotated.
>
> # Logs courses created via the web-based Course Administration module.
> $webworkFiles{logs}{hosted_courses} = "$webworkDirs{logs}/ 
> hosted_courses.log";
>
>> this is only used in the Admin course, and keeps a record of  courses 
>> created and deleted on the server.
>
>
> # The transaction log contains data from each recorded answer  
> submission. This
> # is useful if the database becomes corrupted.
> $webworkFiles{logs}{transaction}    = "$courseDirs{logs}/ 
> transaction.log";
>
>> This records all of the data provided by a student when they answer  
>> a problem. It is updated using the
>
> Utils::writeLog(ce, "transaction" ... ) subroutine.
>
>> It is roughly  equivalent to
>> the Global::log_info logging facility in WW1.9 which "captured  every 
>> key stroke" of the student and store its data in
>> the file, usually named access_log.  What it actually saved was the  
>> entire url query string, including any hidden data.
>>
>> There is one important difference in that Global::log_info was  
>> called on most scripts, including instructor scripts, while
>> the transaction log is only updated when answering a WeBWorK  
>> problem. The WW1.9 log contains instructor house keeping
>> actions as  well as student actions.
>
>
> # The answer log stores a history of all users' submitted answers.
> $courseFiles{logs}{answer_log}      = "$courseDirs{logs}/answer_log";
>
>> This is a separate log that records the students' answer history.   
>> it duplicates some information in the transaction log. It was
>> created at a different time and for a different purpose than the  
>> transaction.log.  It might be useful to consolidate some of the
>> code involved in these two logs.  It also would be worth  considering 
>> placing this data directly in the sql database.  The  upside, 
>> particularly for student answers, is that it would become  easier to 
>> search for certain types of student mistakes using sql  queries.  On 
>> the downside this might interfere with performance.
>
>
>> The format for storing the data in both answer_log and in  
>> transaction log is somewhat ad hoc.  If we continue to store the  
>> data in a file then storing the data in an xml format would  
>> facilitate being able to manipulate the data later using  
>> standardized tools.  We might store the data in a file, but  
>> periodically extract it and store it in an sql database for  research 
>> purposes.
>
>
>
> # Log logins.
> $courseFiles{logs}{login_log}       = "$courseDirs{logs}/login.log";
>
>> This merely records each time a student logs in to webwork.
>
>
>
> Take care,
>
> Mike
>
> #################
>
> On Aug 27, 2005, at 6:49 PM, John Jones wrote:
>
>> Webwork 1 had a fuller logging procedure, where basically every  
>> click was logged.  I found that useful since I sometimes had to  
>> figure out what a teacher had done (in addition to answering  
>> questions about what students did).
>>
>> The webwork 2 logging framework made it easy to replicate this: one  
>> line in global.conf to define the log file, and then one (long)  line 
>> in ContentGenerator to call the writeCourseLog to record the  url and 
>> the cgi parameters.  So, this raised a couple of questions:
>> would we want this facility in the main webwork?
>> if so, should it be more refined (so individual modules can give  
>> more finely tuned log entries)?
>> Thoughts?
>>
>> John
>>
>
>
>
> -------------------------------------------------------
> SF.Net email is Sponsored by the Better Software Conference & EXPO
> September 19-22, 2005 * San Francisco, CA * Development Lifecycle 
> Practices
> Agile & Plan-Driven Development * Managing Projects & Teams * Testing 
> & QA
> Security * Process Improvement & Measurement * http://www.sqe.com/bsce5sf
> _______________________________________________
> OpenWeBWorK-Devel mailing list
> Ope...@li...
> https://lists.sourceforge.net/lists/listinfo/openwebwork-devel

Re: [WWdevel] more logging

[Michael G. <ga...@ma...>]

>
> Since part of the rationale for the transaction log is to back up  
> the sql database, keeping it as a file makes sense.  But, it should  
> probably be merged with the answer log (with maybe the tiny extra  
> bit of information of logging submit/check/preview :) ).
>
>

Hi John,

I'm not sure that we've ever used the transaction log to rebuild a  
database -- the information is there, but not in a very useable form.
The sql databases have their own efficient methods for dumping a  
backup image, or even of journalling every transaction if that is
desirable.  I want to to shift the burden of backup and efficiency to  
those software projects.  They have a lot more manpower. :-)

Thanks for adding the journalling facility to the current WeBWorK2.   
It is quite useful for trouble shooting problems after the fact.

>> On a separate note I think we would be interested in the changes   
>> needed to accommodate the ASU login and authentication scheme.  We  
>> haven't had much experience with this yet but if it's  possible  
>> I'd like to factor things so that ContentGenerator.pm would be  
>> fixed  and Authen.pm and/or if necessary Login.pm could be   
>> subclassed to allow for a variety of authentication schemes.
>>
>
> Some things would probably be easy, and others much harder.  The  
> main changes to ContentGenerator relate to logout.  We have to show  
> a particular icon for logout, and it has to call a particular  
> university url.  So, I removed the logout link from the left panel  
> and replaced the link in the upper-right corner with the icon  
> linking to the university url instead of calling the logout  
> module.  I tinkered with the logout module, but this meant that I  
> had one fewer module to change.  So, I leave it as is, and it never  
> gets called.  I think I could have done the icon through the  
> template, but then I would still need to remove the webwork logout  
> link in the upper right corner.
>
> I changed Login.pm so the only options are to log in through the  
> university, or to guest login.
>
> I changed Options.pm since webwork has no access to actual  
> passwords.  The standard message was potentially confusing since  
> university passwords could be changed, just not through webwork.   
> If you wanted to make that configurable, I imagine it could be a  
> string to show when password changes are not allowed, and set in  
> Constants.
>
> The biggest changes were to Authen since that's where we need to  
> deal with the university system for login-redirect and reading  
> their cookie.  I think there was something done in webwork to make  
> that easier, but I haven't looked at it.
>
> There are a few things which could be better when it comes to  
> practice users, but they haven't caused any problems.
>
> You can see the result by logging into any of the ASU courses.  Of  
> course, the login through ASU button will just get you the ASU  
> login page where you will be stuck.  But, you can login as a guest  
> and everything looks the same as if you were a registered student.
>
> John

Thanks, John.  Once the beginning of semester flurry dies down I'd  
like to look a the changes you've made in your modules and
also at the experience of others who have been using university  
authentication of one form or another.  We'll see what improvements
can be made in the way the current code is factored.
>
>
>