Assignments: Occasional NPEs and severed gradebook associations
Description
relates to
Activity
Sean Horner March 3, 2023 at 3:56 PM
I can make the 7am (US Pacific) meeting on Mar. 14. Unfortunately, I’m not able to attend on Mar. 7.
Earle Nietzel March 3, 2023 at 2:12 PM
I concur with Jesus,public void updateAssignment(Assignment assignment)
should return the updated version of the assignment.
Sean I think we should discuss these issues at the next Core call.
Jesus Maria Mendez Perez March 3, 2023 at 12:52 PM
The assignmentService.updateAssignment(a); should return the assignment.
a = assignmentService.updateAssignment(a);
Sean Horner March 2, 2023 at 10:19 PM
Hello @Earle Nietzel ,
Thank you for your review of this bug. In our Sakai 21 instance, we iteratively added extensive logging to troubleshoot and resolve both this issue (and SAK-48551). Below I’ll walk through an example case from Feb. 13 when this bug was still active for us.
We logged an instance where an instructor posted a new assignment, which starts without having an id defined:
13-Feb-2023 23:28:38.640 INFO [ajp-nio-10.1.8.80-8009-exec-3] org.sakaiproject.assignment.tool.AssignmentAction.post_save_assignment name: (assignmentId); val: ()
The due date entered by the instructor was the following:
13-Feb-2023 23:28:38.641 INFO [ajp-nio-10.1.8.80-8009-exec-3] org.sakaiproject.assignment.tool.AssignmentAction.post_save_assignment name: (duedate); val: (02/20/2023 11:25 pm)
For new assignments, the post_save_assignment method calls:
a = assignmentService.addAssignment(siteId);The addAssignment method stores a new assignment in the AssignmentRepository with only a handful of fields:
Assignment assignment = new Assignment();
assignment.setContext(context);
assignment.setAuthor(sessionManager.getCurrentSessionUserId());
assignment.setPosition(0);
assignmentRepository.newAssignment(assignment);The due date is not included, so the assignment’s due date value at this point is null. We logged the assignment id now generated for this partially saved assignment:
13-Feb-2023 23:28:38.670 INFO [ajp-nio-10.1.8.80-8009-exec-3] org.sakaiproject.assignment.impl.persistence.AssignmentRepositoryImpl.newAssignment Persisted assignment (7d7ee2dc-4978-4f1b-9313-d7780e487b8b)
Later the post_save_assignment calls commitAssignment. We logged to ensure that the dueDate value the instructor entered is preserved.
13-Feb-2023 23:28:38.676 INFO [ajp-nio-10.1.8.80-8009-exec-3] org.sakaiproject.assignment.tool.AssignmentAction.commitAssignment dueTime: (2023-02-21T07:25:00Z)
After setting most of the instructor’s input values into assignment object “a”, commitAssignment then makes a more substantive update of this assignment object by calling:
// commit the changes
assignmentService.updateAssignment(a);Later, commitAssignment processes a few other things, such as scheduling a due date reminder, if the posted assignment is configured to do so, which in this case it was:
assignmentDueReminderService.scheduleDueDateReminder(a.getId());Notice that the call to scheduleDueDateReminder passes in the assignment’s id instead of the assignment object. Thus, scheduleDueDateReminder relies (ultimately) on Hibernate to fetch the assignment object based on the id to access the object’s due date:
Assignment assignment = assignmentService.getAssignment(assignmentId);Immediately following this statement, we introduced a logging statement to check the due date for the assignment object returned for id 7d7ee2dc-4978-4f1b-9313-d7780e487b8b:
13-Feb-2023 23:28:38.730 INFO [ajp-nio-10.1.8.80-8009-exec-3] org.sakaiproject.assignment.impl.reminder.AssignmentDueReminderServiceImpl.scheduleDueDateReminder assignment.getDueDate: (null)
The due date is null; from this I conclude the assignment object returned by Hibernate was stale. It’s the version of the assignment object resulting from when it was initially saved by assignmentRepository.newAssignment.
Furthermore, I concluded that the retrieval of the assignment object within assignmentDueReminderService.scheduleDueDateReminder needs a Hibernate refresh from the database. Upstream, the Hibernate session flush that we introduced when Hibernate saves revisions to the assignment object -- i.e., by way of assignmentService.updateAssignment -- ensures that the object is stored in the database prior to its subsequent retrieval in this runtime logic for posting an assignment.
I concur with your observation that the behavior in this bug is related to SAK-48551. In a comment in SAK-48551, I pose questions there that are relevant for how we might proceed with fixing SAK-48553.
Earle Nietzel March 2, 2023 at 6:14 PM
Hi Sean from line:
if (!assignment.getDraft() && Instant.now().plusSeconds(reminderSeconds).isBefore(assignment.getDueDate())) {assignment.getDueDate() is returning null and is likely a data issue it would be best to understand why the dueDate is returning null it might be in some ways related to https://sakaiproject.atlassian.net/browse/SAK-48551
Details
Details
Priority
Critical
Our institution uncovered over 60 cases across various course sites in Fall 2022 where assignments were configured to “Send grades to the Gradebook” but the associated gradebook item was severed (missing). For most but not all of these cases, the gradebook item originated from Assignments.
(I recognize that when the gradebook item originates from Gradebook, a gradebook association in Assignments can be broken when the gradebook item is renamed or deleted. But that issue is outside the scope of this bug.)
The consequence of this bug means that affected assignments that are intended to be counted toward the course grade in Gradebook may be inadvertently omitted, especially when there are lots of gradebook items for a course; this in turn can affect the final course grade for all students in the course.
The bug occasionally occurs when an instructor posts an assignment configured to “Send grades to the Gradebook”. When the bug occurs during a Post event, instead of directing the instructor to the Assignments tab with the table of assignments, the instructor is redirected back to the add/edit view of the assignment they attempted to post. If the instructor proceeds to click ‘Post’ again, they observe an alert stating that the assignment already exists, which they vouch for when returning to the Assignments tab. Upon re-inspection of the posted assignment, the gradebook association for the assignment is severed.
The post event corresponds to a NullPointerException logged in catalina.out, like the following from an instance of Sakai 21:
31-Dec-2022 10:21:04.917 WARN [ajp-nio-10.1.8.60-8009-exec-73] org.sakaiproject.cheftool.VelocityPortletPaneledAction.actionDispatch Exception calling method doAssignment_form java.lang.reflect.InvocationTargetException (Caused by java.lang.NullPointerException) java.lang.reflect.InvocationTargetException at sun.reflect.GeneratedMethodAccessor4640.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.sakaiproject.cheftool.VelocityPortletPaneledAction.actionDispatch(VelocityPortletPaneledAction.java:757) at org.sakaiproject.cheftool.VelocityPortletPaneledAction.processAction(VelocityPortletPaneledAction.java:566) -- snip -- Caused by: java.lang.NullPointerException at java.time.Instant.compareTo(Instant.java:1255) at java.time.Instant.isBefore(Instant.java:1285) at org.sakaiproject.assignment.impl.reminder.AssignmentDueReminderServiceImpl.scheduleDueDateReminder(AssignmentDueReminderServiceImpl.java:108) at org.sakaiproject.assignment.tool.AssignmentAction.commitAssignment(AssignmentAction.java:9133) at org.sakaiproject.assignment.tool.AssignmentAction.post_save_assignment(AssignmentAction.java:8099) at org.sakaiproject.assignment.tool.AssignmentAction.doPost_assignment(AssignmentAction.java:7769) at org.sakaiproject.assignment.tool.AssignmentAction.doAssignment_form(AssignmentAction.java:10371) ... 56 more Note in the stack trace above that the line numbers therein do not necessarily correspond with line numbering from 21.x source files; this is due to our local customizations of code, especially the insertion of extra logging statements for troubleshooting.Because this bug is not happening for every “Post” event, I surmise that some kind of race condition and/or a caching sync problem is inducing the bug. Introducing Hibernate “flush” and “refresh” calls within key points in the logic for saving posted assignments prevents this bug’s recurrence.