Server-side immediate failure when adding a new instructor

[damithc]

When adding an instructor, sometimes it fails immediately in the following manner (see attached). The request is not even sent to the server. A caching issue?

[damithc]

I eventually succeeds if I keep clicking the 'add instructor' button, usually the 2nd time or the 3rd time

[damithc]

I was wrong. It reaches the server and fails on the server-side:

2014-12-14 15:55:42.939 /admin/adminInstructorAccountAdd 200 1620ms 14kb Mozilla/5.0 (Windows NT 6.3; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.95 Safari/537.36 module=default version=5-28 202.166.13.217 - damith [13/Dec/2014:23:55:42 -0800] "POST /admin/adminInstructorAccountAdd HTTP/1.1" 200 15060 - "Mozilla/5.0 (Windows NT 6.3; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.95 Safari/537.36" "teammatesv4.appspot.com" ms=1620 cpu_ms=671 cpm_usd=0.001683 app_engine_release=1.9.17 instance=00c61b117c99a66308dd3a92ca70091cdb929cd0 I 2014-12-14 15:55:41.649 teammates.ui.controller.ControllerServlet doPost: Request received : https://teammatesv4.appspot.com/admin/adminInstructorAccountAdd:{instructorshortname::Ren Loke , instructoremail::eleloke@nus.edu.sg, instructorinstitution::National University of Singapore, Singapore, instructorname::Dr Yuan Ren Loke } I 2014-12-14 15:55:41.649 teammates.ui.controller.ControllerServlet doPost: User agent : Mozilla/5.0 (Windows NT 6.3; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.95 Safari/537.36 I 2014-12-14 15:55:41.649 teammates.ui.controller.ActionFactory getAction: URL received :https://teammatesv4.appspot.com/admin/adminInstructorAccountAdd I 2014-12-14 15:55:41.976 teammates.storage.api.EntitiesDb createEntities: Account I 2014-12-14 15:55:41.997 teammates.storage.api.EntitiesDb createEntities: Account I 2014-12-14 15:55:42.008 teammates.storage.api.EntitiesDb createEntities: Account I 2014-12-14 15:55:42.058 teammates.storage.api.EntitiesDb createEntities: Account I 2014-12-14 15:55:42.107 teammates.storage.api.EntitiesDb createEntities: Account I 2014-12-14 15:55:42.118 teammates.storage.api.EntitiesDb createEntities: Account I 2014-12-14 15:55:42.152 teammates.storage.api.EntitiesDb createEntities: Account I 2014-12-14 15:55:42.199 teammates.storage.api.EntitiesDb createEntities: Account I 2014-12-14 15:55:42.268 teammates.storage.api.AccountsDb updateAccount: Account I 2014-12-14 15:55:42.310 teammates.storage.api.AccountsDb updateAccount: Account I 2014-12-14 15:55:42.332 teammates.storage.api.AccountsDb updateAccount: Account I 2014-12-14 15:55:42.367 teammates.storage.api.AccountsDb updateAccount: Account I 2014-12-14 15:55:42.467 teammates.storage.api.AccountsDb updateAccount: Account I 2014-12-14 15:55:42.551 teammates.storage.api.AccountsDb updateAccount: Account I 2014-12-14 15:55:42.573 teammates.storage.api.AccountsDb updateAccount: Account I 2014-12-14 15:55:42.613 teammates.storage.api.AccountsDb updateAccount: Account I 2014-12-14 15:55:42.623 teammates.storage.api.EntitiesDb createEntities: Recently modified course::eleloke.nus-demo I 2014-12-14 15:55:42.732 teammates.storage.api.EntitiesDb createEntities: Recently modified course::eleloke.nus-demo I 2014-12-14 15:55:42.842 teammates.storage.api.InstructorsDb getInstructorForEmail: Trying to get non-existent Instructor: eleloke.nus-demo/eleloke@nus.edu.sg I 2014-12-14 15:55:42.897 teammates.ui.controller.ControllerServlet doPost: TEAMMATESLOG|||adminInstructorAccountAdd|||adminInstructorAccountAdd|||true|||Admin|||Damith Chatura Rajapakse|||damith|||damith@...|||Servlet Action Failure : null|||/admin/adminInstructorAccountAdd|||1221

[damithc]

It may be due to eventual consistency (trying to read an entity immediately after it was created, which can fail sometimes).

[ymoctavia]

Professor @damithc, yes this is indeed caused by the reading-right-after-writing issue. In admin instructor adding action, will will first use backdoor logic to create entities and to generate the key using :

private String generateRegistrationKey() {
        String uniqueId = getUniqueId();
        SecureRandom prng = new SecureRandom();

        String key = uniqueId + prng.nextInt();

        return key 

Where the uniquedId comes from within the instructor constructor:

this.setUniqueId(this.getEmail() + '%' + this.getCourseId());

And after the above the instructor's email will be used to fetch the updated entity with instructor.key set properly. This key will then be used for verification in invitation email and display on adminInstrucotrAdd page upon successful completed action.

One issue here is: what happens to the entity after the reading failure?

In our logic:

public String sendJoinLinkToNewInstructor(InstructorAttributes instructor, String shortName, String institute) 
           throws EntityDoesNotExistException {

        String joinLink="";

        InstructorAttributes instructorData = getInstructorForEmail(instructor.courseId, instructor.email);                                             

        if (instructorData == null) {
            throw new EntityDoesNotExistException("Instructor [" 
                                                  + instructor.email + instructor.name 
                                                  + "] does not exist in course ["
                                                  + instructor.courseId + "]");
        }

        Emails emailMgr = new Emails();

        try {
            MimeMessage email = emailMgr.generateNewInstructorAccountJoinEmail(instructorData, shortName, institute);
            emailMgr.sendEmail(email);
            joinLink = emailMgr.generateNewInstructorAccountJoinLink(instructorData, institute);

        } catch (Exception e) {
            throw new RuntimeException("Unexpected error while sending email",e);
        }

        return joinLink;
    }

The reading is done before all email generating so this is ok even if the reading is failed because the exception will prevent any email sending to the user.

The question is: will the entity be successfully created but then become "dead entity" because it will not be accessed anymore.

And then I checked the entity adding, it simply uses

getPM().makePersistentAll(entities);

In my understanding, the previously added entity with reading failure will be updated in second addition and hence this will answer the question and hence there will not be any "dead entity". Am I right about this?

[damithc]

The problem happens the write operation and read operation hitting different servers. This can happen even if you use backdoor logic. Is there a way to avoid the read operation? I think if the entity was created, it will eventually get updated, but I'm not sure.

[ymoctavia]

Professor @damithc , currently the key is randomly generated in Instructor class, so it will not have a key until the object is created.

   public Instructor(String instructorGoogleId, String courseId, Boolean isArchived, String instructorName, String instructorEmail,
            String role, boolean isDisplayedToStudents, String displayedName, String instructorPrivilegesAsText) {
        this.setGoogleId(instructorGoogleId);
        this.setCourseId(courseId);
        this.setIsArchived(isArchived);
        this.setName(instructorName);
        this.setEmail(instructorEmail);
        this.setRole(role);
        this.setIsDisplayedToStudents(isDisplayedToStudents);
        this.setDisplayedName(displayedName);
        this.setInstructorPrivilegeAsText(instructorPrivilegesAsText);
        // setId should be called after setting email and courseId
        this.setUniqueId(this.getEmail() + '%' + this.getCourseId());
        this.setRegistrationKey(generateRegistrationKey());
    }

And the generateRegistrationKey is :

private String generateRegistrationKey() {
        String uniqueId = getUniqueId();
        SecureRandom prng = new SecureRandom();

        String key = uniqueId + prng.nextInt();

        return key;
    }

So this will not generate any same number again using this function. If will want to avoid the read option here, we will need to move the key generation logic out of the class (also need to store it somewhere before it as assigned to the object) and make it at least semi-public to allow other class to access, which I do not recommend for security reasons. Or maybe it is not so serious as I thought ?

[damithc]

We can put this issue on hold. It is not a serious issue and it affects admin only.

[ymoctavia]

Ok, I will keep my attention to this and see if there is any better solution.

[ackoroa]

Just a note this occurs in the admin page automated test as well

[damithc]

The original issue refers to adding instructors on the admin side :-) i.e. creating a new instructor account

[ackoroa]

hm? Yes, I'm referring to the test for creating a new instructor on the admin side too

[damithc]

oh yeah, it fails during normal operation and during testing too. :-)

[damithc]

Sometimes I have to try 10 times before I can go past this error. Can try to reduce the incidence of this error, may be by adding a 'wait and retry' if the data is not yet persisted?