Teammates: AssertionError: If the instructor hasn't been retrieved yet there is some problem in adding of instructor

[damithc]

Received several of these yesterday and today, from the live server

v 6.11.0

Error Message: teammates.common.util.Logger severe: Exception occured while performing http://teammatesv4.appspot.com/worker/instructorCourseJoinEmail|||
java.lang.AssertionError: If the instructor hasn't been retrieved yet there is some problem in adding of instructor
teammates.common.util.retry.MaximumRetriesExceededException: getInstructor failed after maximum retries
at teammates.common.util.retry.RetryManager.doRetry(RetryManager.java:111)
at teammates.common.util.retry.RetryManager.runUntilNotNull(RetryManager.java:83)
at teammates.ui.automated.InstructorCourseJoinEmailWorkerAction.execute(InstructorCourseJoinEmailWorkerAction.java:54)
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:539)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:333)
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:692)
at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.dispatchRequest(JavaRuntime.java:654)
at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.run(JavaRuntime.java:624)
at com.google.apphosting.runtime.JavaRuntime$NullSandboxRequestRunnable.run(JavaRuntime.java:818)
at com.google.apphosting.runtime.ThreadGroupPool$PoolEntry.run(ThreadGroupPool.java:274)
at java.lang.Thread.run(Thread.java:745)

at teammates.common.util.Assumption.fail(Assumption.java:61)
at teammates.ui.automated.InstructorCourseJoinEmailWorkerAction.execute(InstructorCourseJoinEmailWorkerAction.java:62)
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:539)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:333)
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:692)
at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.dispatchRequest(JavaRuntime.java:654)
at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.run(JavaRuntime.java:624)
at com.google.apphosting.runtime.JavaRuntime$NullSandboxRequestRunnable.run(JavaRuntime.java:818)
at com.google.apphosting.runtime.ThreadGroupPool$PoolEntry.run(ThreadGroupPool.java:274)
at java.lang.Thread.run(Thread.java:745)

[damithc]

@xpdavid this might be related to eventual consistency. Can have a look?

[xpdavid]

This might be the scenario described in https://github.com/TEAMMATES/teammates/issues/9025#issuecomment-418284072

@damithc can you check the log to confirm? You may search the instructor email logged in this failed request.

[damithc]

Doesn't look like that is the case

[xpdavid]

Three add actions of the same instructor?

[damithc]

Three add actions of the same instructor?

Two different instructors. The first one is different from the other two.

[xpdavid]

Let's focus on the first failure:

Can we get the logged parameters courseid and instructoremail and query them in the Google Cloud Console?

https://console.cloud.google.com/datastore/entities/query?project=&ns=&kind=Instructor

In doing this, we can confirm whether it is because of eventual consistency or the deletion of the instructor.

[damithc]

In doing this, we can confirm whether it is because of eventual consistency or the deletion of the instructor.

Both entities exist. In fact, for the second instructor, a reminder has been sent and he eventually joined the course.

[damithc]

Received more of these

[xpdavid]

@damithc Can I get your help to check something?

In the log for failed automated action (/worker/instructorCourseJoinEmail), does the logged email contains extra space?

e.g. "[email protected]" -> "[email protected] " or "[email protected]   " or "  [email protected]      " 

I found that when we store instructor email, we do sanitisation to remove the extra space in the instructor email. However, when we issue task to task scheduler, we use the plain unsanitized email which may contain extra space. Therefore, when the scheduled task get executed, using unsanitized email with extra space of course cannot get the stored entity.

[damithc]

Yup, I checked a few failed cases and they all have trailing spaces. Good catch 💯

[xpdavid]

🎉 🎉 🎉 🎉 🎉 🎉 🎉 then we find the cause finally!