Teammates: Fix assertion error in instructorCourseJoinEmail on live server

[damithc]

v6.1
Found many of these in log.
On a related note, these are logged as 'warning' rather than 'severe'. Shouldn't they be severe?

com.google.apphosting.runtime.jetty9.JettyLogger warn: Error for /worker/instructorCourseJoinEmail (JettyLogger.java:29)
java.lang.AssertionError: null
    at teammates.common.util.Assumption.fail(Assumption.java:61)
    at teammates.common.util.Assumption.assertTrue(Assumption.java:29)
    at teammates.common.util.Assumption.assertNotNull(Assumption.java:272)
    at teammates.common.util.Assumption.assertNotNull(Assumption.java:263)
    at teammates.ui.automated.InstructorCourseJoinEmailWorkerAction.execute(InstructorCourseJoinEmailWorkerAction.java:37)
    at teammates.ui.automated.AutomatedServlet.doPost(AutomatedServlet.java:41)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:848)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1772)
    at com.googlecode.objectify.ObjectifyFilter.doFilter(ObjectifyFilter.java:48)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759)
    at com.google.apphosting.utils.servlet.ParseBlobUploadFilter.doFilter(ParseBlobUploadFilter.java:125)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759)
    at com.google.apphosting.runtime.jetty9.SaveSessionFilter.doFilter(SaveSessionFilter.java:37)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759)
    at com.google.apphosting.utils.servlet.JdbcMySqlConnectionCleanupFilter.doFilter(JdbcMySqlConnectionCleanupFilter.java:60)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759)
    at com.google.apphosting.utils.servlet.TransactionCleanupFilter.doFilter(TransactionCleanupFilter.java:48)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759)
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:582)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
    at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:524)
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226)
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180)
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512)
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
    at com.google.apphosting.runtime.jetty9.AppVersionHandlerMap.handle(AppVersionHandlerMap.java:297)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
    at org.eclipse.jetty.server.Server.handle(Server.java:534)
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:320)
    at com.google.apphosting.runtime.jetty9.RpcConnection.handle(RpcConnection.java:202)
    at com.google.apphosting.runtime.jetty9.RpcConnector.serviceRequest(RpcConnector.java:81)
    at com.google.apphosting.runtime.jetty9.JettyServletEngineAdapter.serviceRequest(JettyServletEngineAdapter.java:108)
    at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.dispatchServletRequest(JavaRuntime.java:680)
    at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.dispatchRequest(JavaRuntime.java:642)
    at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.run(JavaRuntime.java:612)
    at com.google.apphosting.runtime.JavaRuntime$NullSandboxRequestRunnable.run(JavaRuntime.java:806)
    at com.google.apphosting.runtime.ThreadGroupPool$PoolEntry.run(ThreadGroupPool.java:274)
    at java.lang.Thread.run(Thread.java:745)

[wkurniawan07]

these are logged as 'warning' rather than 'severe'

That log comes from internal tool, JettyLogger, not our custom-built logger. All assertion errors will be logged in that manner.

[damithc]

The assertion failure happens in our code. I suppose we can't catch it because this happens in ta task that is in the task queue. Is there a way to catch all exceptions in tasks in task queues and log them similar to how we do it for assertion failures in other places?
Otherwise this kind of errors can go unnoticed. I only noticed this by chance and it seems to have been happening for a while.

[whipermr5]

I believe this happens because AutomatedServlet only catches Exceptions but not Throwables, unlike ControllerServlet:

https://github.com/TEAMMATES/teammates/blob/bcae38f2e837306558cff5d8fc046d8936e19296/src/main/java/teammates/ui/automated/AutomatedServlet.java#L42-L47

https://github.com/TEAMMATES/teammates/blob/bcae38f2e837306558cff5d8fc046d8936e19296/src/main/java/teammates/ui/controller/ControllerServlet.java#L149-L158

AssertionError is a subclass of Error which is a subclass of Throwable. All we need to do is update AutomatedServlet to catch Throwables too. @wkurniawan07 correct me if I'm missing anything. Was the intention to signal GAE that the task failed? If so, we can rethrow the Throwable after severe logging it with our custom logger.

[wkurniawan07]

@damithc I'm not denying the assertion error comes from our code. Only that the warn level there is not something we deliberately decide.
@whipermr5 I didn't think that far ahead when designing AutomatedServlet, so now is actually a good time to go back to the drawing board. Catching Throwable and logging it should be something that is done as per ControllerServlet's implementation, but I'm not entirely sure about re-throwing it.

[whipermr5]

I think if we don't re-throw it, GAE will think the task succeeded and the built-in retry mechanism will not kick in:
https://github.com/TEAMMATES/teammates/blob/bcae38f2e837306558cff5d8fc046d8936e19296/src/main/webapp/WEB-INF/queue.xml#L99-L111

[whipermr5]

@damithc What was the HTTP error code for the request?

[damithc]

@damithc What was the HTTP error code for the request?

500

[whipermr5]

Is it possible for accounts to be deleted? The stack trace seems to indicate that the account of the inviter (the existing instructor who added the new instructor) no longer exists:
https://github.com/TEAMMATES/teammates/blob/f6a641453158a8323bc806cbd751d35123ab2cca/src/main/java/teammates/ui/automated/InstructorCourseJoinEmailWorkerAction.java#L36-L37

The possible actions that enqueued the task both use the logged in user's Google ID as the inviterId parameter, so it is unlikely that the parameter was incorrect:
https://github.com/TEAMMATES/teammates/blob/f6a641453158a8323bc806cbd751d35123ab2cca/src/main/java/teammates/ui/controller/InstructorCourseInstructorAddAction.java#L38-L39
https://github.com/TEAMMATES/teammates/blob/f6a641453158a8323bc806cbd751d35123ab2cca/src/main/java/teammates/ui/controller/InstructorCourseRemindAction.java#L71-L72

[damithc]

Only admin can delete accounts. I haven't deleted any accounts in the last year or so. May be a persistence issue? In any case, we can add more logging in case this happens again. May be add an explanatory message indicating which course, which instructor, etc.?

[whipermr5]

I'm in favour of logging all request parameters for worker actions. Edit: just realised #8457 does this for uncaught errors, however I feel like doing it for all requests since some worker actions catch bare exceptions by themselves and only give generic error messages without logging the parameters.

[damithc]

A few of these cropped up during live server testing. Seems to be caused by test data.
{instructoremail::[email protected], invitergoogleid::..., courseid::InsCrsEdit.CS2104} (Logger.java:34)

[damithc]

Received a few more of this today. These are unlikely to be from test data.

[damithc]

Received a few more in the recent few days. Raising priority.

[damithc]

Received a few more today

[damithc]

Some more info from the logs of such a case. The person actually exists in the course though. May be trying to access the instructor object before it is properly persisted?

[tshradheya]

The problem in #8911 and this issue seems to be the same.

The worker action which is supposed to send email happens before the student/instructor account has properly persisted in the database. This is why the logic.getInstructorForEmail(courseId, instructorEmail); returns a NULL value as it cant read the instructor which hasn't been stored in the database yet.

Currently, this problem hasn't been reported maybe because the retry limit of the instructor-course-join-email-queue is 2 and hence the join email is eventually sent out when the data has been stored properly.

To make it more safe, we can increase the value of task-retry-limit to ensure the join email is always sent.
https://github.com/TEAMMATES/teammates/blob/402e5c967f26b75afacdc503877193bbabd219fc/src/main/webapp/WEB-INF/queue.xml#L100-L106

Or we can use RetryManager to ensure that it keeps retrying for a while so that it returns the instructor account and then proceeds to send the email. Something like this:

InstructorCourseJoinEmailWorkerAction.java

@TEAMMATES/seniordevs Any inputs?

[xpdavid]

If you access an object by using an index in GAE Datastore, it might not return the data you just put. Index building takes time. Typically this can be done within 100ms. It looks like the time interval above is 43ms and that is why we have persistence issue. <- maybe the task is get immediately executed after schedule before the persistence.

However, if you access an object by using the key, the data will always be the lasted version (so you read what you write). More information here, but the summary is what I have said. https://cloud.google.com/appengine/articles/transaction_isolation

The solution would be to change db.getInstructorEntityForEmail(). Since we store the id using the format Format: email%courseId e.g., [email protected]%cs1101. We can also construct the id(key) back using courseId and email.

private Instructor getInstructorEntityForEmail(String courseId, String email) {
        return load().id(email + "%" + courseId).now();
    }

[tshradheya]

Wow. That's a very efficient and nice solution.
However, I am wondering why didn't we adopt this method before for all the entities? Since this happens for students also, ~we need to use it there was well to solve the assertion error~(we cannot because the googleId is the Id and not done in a similar manner as Instructor , ~so I was wondering if it will be a good idea to refactor in all possible places to make it effecient~

[damithc]

However, I am wondering why didn't we adopt this method before for all the entities?

Only if the key is predictable. In the case of students, I believe the key is an auto-generated random string.

[xpdavid]

@tshradheya We can only see if the patches work after the next deployment. Let me schedule a deployment soon.

[xpdavid]

@damithc Just to check. Is the error gone?

[damithc]

@damithc Just to check. Is the error gone?

So far, no recurrence. Will have to wait longer to be sure as it was not frequent even before. Will report here if it recurs.

[damithc]

Got a few today 😢 :

Error Message: teammates.common.util.Logger severe: Exception occured while performing http://teammatesv4.appspot.com/worker/instructorCourseJoinEmail|||
java.lang.AssertionError: null
at teammates.common.util.Assumption.fail(Assumption.java:61)
at teammates.common.util.Assumption.assertTrue(Assumption.java:29)
at teammates.common.util.Assumption.assertNotNull(Assumption.java:272)
at teammates.common.util.Assumption.assertNotNull(Assumption.java:263)
at teammates.ui.automated.InstructorCourseJoinEmailWorkerAction.execute(InstructorCourseJoinEmailWorkerAction.java:48)
at teammates.ui.automated.AutomatedServlet.doPost(AutomatedServlet.java:46)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:848)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1772)
at com.googlecode.objectify.ObjectifyFilter.doFilter(ObjectifyFilter.java:48)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759)
at com.google.apphosting.utils.servlet.JdbcMySqlConnectionCleanupFilter.doFilter(JdbcMySqlConnectionCleanupFilter.java:60)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:582)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:524)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
at com.google.apphosting.runtime.jetty9.ParseBlobUploadHandler.handle(ParseBlobUploadHandler.java:120)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1182)
at com.google.apphosting.runtime.jetty9.AppEngineWebAppContext.doHandle(AppEngineWebAppContext.java:171)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at com.google.apphosting.runtime.jetty9.AppVersionHandlerMap.handle(AppVersionHandlerMap.java:297)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
at org.eclipse.jetty.server.Server.handle(Server.java:534)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:320)
at com.google.apphosting.runtime.jetty9.RpcConnection.handle(RpcConnection.java:202)
at com.google.apphosting.runtime.jetty9.RpcConnector.serviceRequest(RpcConnector.java:81)
at com.google.apphosting.runtime.jetty9.JettyServletEngineAdapter.serviceRequest(JettyServletEngineAdapter.java:123)
at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.dispatchServletRequest(JavaRuntime.java:693)
at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.dispatchRequest(JavaRuntime.java:655)
at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.run(JavaRuntime.java:625)
at com.google.apphosting.runtime.JavaRuntime$NullSandboxRequestRunnable.run(JavaRuntime.java:819)
at com.google.apphosting.runtime.ThreadGroupPool$PoolEntry.run(ThreadGroupPool.java:274)
at java.lang.Thread.run(Thread.java:745)

[xpdavid]

@damithc Would like to check the activity traces for the instructor (email + '%' + courseId) before the exception happen.

[damithc]

One case happened just now.

Looks like the three attempts to retrieve the instructor object failed possibly because the entity is not saved yet.
I went to the instructors page of that course and resent the email using the 'Resend Invite' button. The email went through that time.
May be we need to retry more times, possibly with a longer delay?

[xpdavid]

I think so.

Refer to the documentation of DataStore

When a commit returns successfully (means createInstructor() return no error), the transaction is guaranteed to be applied, but that does not mean the result of your write is immediately visible to readers.

A request that looks up an updated entity by its key at a time after milestone A is guaranteed to see the latest version of that entity.

So I guess when we are inbetween the commi() and milestone A and the worker action is triggered, the exception will happen (Indeed, there are less than 1s between the two actions).

To really achieve the strong consistency, we need to use acestor group which is quite complex and need data migration.

@tshradheya, our fix only decrease the occurrence of the error but not eliminated it (Previously we need to wait until Milestone B). Therefore, I think a fair enough solution would be to just increase the delay between the two actions.

[tshradheya]

To make it more foolproof, we can do both of these:

• Add <min-backoff-seconds>2</min-backoff-seconds>, so that next time it retries the changes to entities is visible and we can send the email. This will be done as a fault tolerance method to ensure email is send no matter what

https://github.com/TEAMMATES/teammates/blob/45cad236e9f61c0206a6552a3807ce7d52ab1269/src/main/webapp/WEB-INF/queue.xml#L100-L107

• As for increasing time between the two actions, we may have to add something like Thread.sleep(1000) between line 37 and 38 so that it gives enough time for entities to become visible before the InstructorCourseJoinEmailWorkerAction action is invoked by the scheduler

https://github.com/TEAMMATES/teammates/blob/45cad236e9f61c0206a6552a3807ce7d52ab1269/src/main/java/teammates/ui/controller/InstructorCourseInstructorAddAction.java#L35-L46

[damithc]

Don't increase the gap between the two actions too much as it slows down the request, which affects the performance for other concurrent users as well. It even increases the risk of the request being killed because it exceeded the 60s limit.

Try tweaking the task queues instead: increasing the number of retries, the gap between retries, etc.

[damithc]

Received this today. Is it the same?

teammates.common.util.Logger severe: Unexpected exception caught by ControllerServlet : (Logger.java:52)
java.lang.AssertionError: null
at teammates.common.util.Assumption.fail(Assumption.java:61)
at teammates.common.util.Assumption.assertTrue(Assumption.java:29)
at teammates.common.util.Assumption.assertNotNull(Assumption.java:272)
at teammates.common.util.Assumption.assertNotNull(Assumption.java:263)
at teammates.ui.controller.InstructorCourseJoinAction.execute(InstructorCourseJoinAction.java:25)
at teammates.ui.controller.Action.executeAndPostProcess(Action.java:476)
at teammates.ui.controller.ControllerServlet.doPost(ControllerServlet.java:75)
at teammates.ui.controller.ControllerServlet.doGet(ControllerServlet.java:50)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:848)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1772)
at com.googlecode.objectify.ObjectifyFilter.doFilter(ObjectifyFilter.java:48)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759)
at com.google.apphosting.utils.servlet.JdbcMySqlConnectionCleanupFilter.doFilter(JdbcMySqlConnectionCleanupFilter.java:60)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:582)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:524)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
at com.google.apphosting.runtime.jetty9.ParseBlobUploadHandler.handle(ParseBlobUploadHandler.java:120)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1182)
at com.google.apphosting.runtime.jetty9.AppEngineWebAppContext.doHandle(AppEngineWebAppContext.java:171)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at com.google.apphosting.runtime.jetty9.AppVersionHandlerMap.handle(AppVersionHandlerMap.java:297)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
at org.eclipse.jetty.server.Server.handle(Server.java:534)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:320)
at com.google.apphosting.runtime.jetty9.RpcConnection.handle(RpcConnection.java:202)
at com.google.apphosting.runtime.jetty9.RpcConnector.serviceRequest(RpcConnector.java:81)
at com.google.apphosting.runtime.jetty9.JettyServletEngineAdapter.serviceRequest(JettyServletEngineAdapter.java:123)
at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.dispatchServletRequest(JavaRuntime.java:693)
at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.dispatchRequest(JavaRuntime.java:655)
at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.run(JavaRuntime.java:625)
at com.google.apphosting.runtime.JavaRuntime$NullSandboxRequestRunnable.run(JavaRuntime.java:819)
at com.google.apphosting.runtime.ThreadGroupPool$PoolEntry.run(ThreadGroupPool.java:274)
at java.lang.Thread.run(Thread.java:745)

[xpdavid]

@damithc Can we do same search as this one? https://github.com/TEAMMATES/teammates/issues/9025#issuecomment-418039134

[damithc]

@damithc Can we do same search as this one? #9025 (comment)

Did that. No results.

[xpdavid]

Oh.. Just realise the stack trace is different. It is from InstructorCourseJoinAction, which is not automated action. Someone is trying to visit the page without regkey present (so it is user error I believe). I think it is not a big issue.