IPlacelessLoginSource.getPrincipalByLogin(email) returns None with an email address that was just created

[Guilherme Salgado]

This is OOPS-46D451.

What seems to have happened is that someone created a new account and then we called the BaseLoginTokenView.logInPersonByEmail() method, which in turn called IPlacelessLoginSource.getPrincipalByLogin() with the newly created email.

I don't think the logInPersonByEmail() needs to check the return value of getPrincipalByLogin() because the former is only called with a valid email address, so I think we need to find why getPrincipalByLogin() returned None when it shouldn't.

[Guilherme Salgado (salgado)]

And it happened again: OOPS-53D119

[Guilherme Salgado (salgado)]

I guess using the Launchpad's Holy Grail (a flush_database_updates call) after the account and email are created could eliminate this problem, but I'd rather spend some time investigating to fix it properly, as that would probably avoid other problems in the future.

[James Henstridge (jamesh)]

This is quite weird. In OOPS-46D451, we see the following:

 5. INSERT INTO Person (id, province, teamowner, country, emblem, hide_email_addresses, calendar, defaultmembershipperiod, phone, defaultrenewalperiod, postcode, givenname, timezone, password, city, hackergotchi, displayname, name, datecreated, familyname, merged, teamdescription, subscriptionpolicy, addressline2, addressline1, organization, homepage_content) VALUES (478958, NULL, NULL, NULL, NULL, 'f', NULL, NULL, NULL, NULL, NULL, 'Evelyn', 'UTC', '9Op7s9LfzLQzhT2GaRM3aEgNsU8sonf38GjifvUH+xxQCuAGJ9IUGA==', NULL, NULL, 'EvyKurayami', 'evylynn', CURRENT_TIMESTAMP AT TIME ZONE 'UTC', 'Farias', NULL, NULL, 1, NULL, NULL, NULL, NULL)
 13. INSERT INTO EmailAddress (id, status, person, email) VALUES (480517, 1, 478958, '<email address hidden>')
 14. SELECT status, person, email FROM EmailAddress WHERE id = 480517
 16. UPDATE EmailAddress SET status = 4 WHERE id = 480517
 19. SELECT EmailAddress.id, EmailAddress.status, EmailAddress.person, EmailAddress.email FROM EmailAddress WHERE lower(email) = '<email address hidden>' ORDER BY id LIMIT 2

So the person and email address definitely got created earlier in the transaction. I believe the final query comes from PersonSet.getByEmail() (called by getPrincipalByLogin()):
    def getByEmail(self, email, default=None):
        """See IPersonSet."""
        emailaddress = getUtility(IEmailAddressSet).getByEmail(email)
        if emailaddress is None:
            return default
        return emailaddress.person

So for this to return None, either the emailaddress select must have returned no results (index failure?), or SQLObject's version of that email address object had person == None.

In OOPS-53D119, we are getting a foreign key constraint error because of a missing person record, but the statement log reads:

 6. INSERT INTO Person (id, province, teamowner, country, emblem, hide_email_addresses, calendar, defaultmembershipperiod, phone, defaultrenewalperiod, postcode, givenname, timezone, password, city, hackergotchi, displayname, name, datecreated, familyname, merged, teamdescription, subscriptionpolicy, addressline2, addressline1, organization, homepage_content) VALUES (488115, NULL, NULL, NULL, NULL, 'f', NULL, NULL, NULL, NULL, NULL, 'Minesh', 'UTC', 'QA2/sybfexufbh3B3StEpaSbJ/bQSueTbrUIbQbTnBnBA3HOIW+bVg==', NULL, NULL, 'm1ne5h', 'minesh-khatri', CURRENT_TIMESTAMP AT TIME ZONE 'UTC', 'Khatri', NULL, NULL, 1, NULL, NULL, NULL, NULL)
 14. INSERT INTO EmailAddress (id, status, person, email) VALUES (489687, 1, 488115, '<email address hidden>')

I am not sure how that sequence of statements could have resulted in the error message.

[Guilherme Salgado (salgado)]

> This is quite weird. In OOPS-46D451, we see the following:
>
> 5. INSERT INTO Person (id, province, teamowner, country, emblem, hide_email_addresses, calendar, defaultmembershipperiod, phone, defaultrenewalperiod, postcode, givenname, timezone, password, city, hackergotchi, displayname, name, datecreated, familyname, merged, teamdescription, subscriptionpolicy, addressline2, addressline1, organization, homepage_content) VALUES (478958, NULL, NULL, NULL, NULL, 'f', NULL, NULL, NULL, NULL, NULL, 'Evelyn', 'UTC', '9Op7s9LfzLQzhT2GaRM3aEgNsU8sonf38GjifvUH+xxQCuAGJ9IUGA==', NULL, NULL, 'EvyKurayami', 'evylynn', CURRENT_TIMESTAMP AT TIME ZONE 'UTC', 'Farias', NULL, NULL, 1, NULL, NULL, NULL, NULL)
> 13. INSERT INTO EmailAddress (id, status, person, email) VALUES (480517, 1, 478958, '<email address hidden>')
> 14. SELECT status, person, email FROM EmailAddress WHERE id = 480517
> 16. UPDATE EmailAddress SET status = 4 WHERE id = 480517
> 19. SELECT EmailAddress.id, EmailAddress.status, EmailAddress.person, EmailAddress.email FROM EmailAddress WHERE lower(email) = '<email address hidden>' ORDER BY id LIMIT 2
>
> So the person and email address definitely got created earlier in the transaction. I believe the final query comes from PersonSet.getByEmail() (called by getPrincipalByLogin()):
> def getByEmail(self, email, default=None):
> """See IPersonSet."""
> emailaddress = getUtility(IEmailAddressSet).getByEmail(email)
> if emailaddress is None:
> return default
> return emailaddress.person
>
> So for this to return None, either the emailaddress select must have
> returned no results (index failure?), or SQLObject's version of that
> email address object had person == None.
>

I'll add an "assert emailaddress.person is not None" right before the last
return of that method. Then, if this happens again, we'll be able to tell if
it was emailaddress or emailaddress.person that was None.

> In OOPS-53D119, we are getting a foreign key constraint error because of
> a missing person record, but the statement log reads:
>
> 6. INSERT INTO Person (id, province, teamowner, country, emblem, hide_email_addresses, calendar, defaultmembershipperiod, phone, defaultrenewalperiod, postcode, givenname, timezone, password, city, hackergotchi, displayname, name, datecreated, familyname, merged, teamdescription, subscriptionpolicy, addressline2, addressline1, organization, homepage_content) VALUES (488115, NULL, NULL, NULL, NULL, 'f', NULL, NULL, NULL, NULL, NULL, 'Minesh', 'UTC', 'QA2/sybfexufbh3B3StEpaSbJ/bQSueTbrUIbQbTnBnBA3HOIW+bVg==', NULL, NULL, 'm1ne5h', 'minesh-khatri', CURRENT_TIMESTAMP AT TIME ZONE 'UTC', 'Khatri', NULL, NULL, 1, NULL, NULL, NULL, NULL)
> 14. INSERT INTO EmailAddress (id, status, person, email) VALUES (489687, 1, 488115, '<email address hidden>')
>
> I am not sure how that sequence of statements could have resulted in the
> error message.

This oops shouldn't be in this bug. This oops is
https://launchpad.net/products/launchpad/+bug/32606. Sorry for the confusion.

[James Henstridge (jamesh)]

I think this, bug 32606 and bug 32615 may all be the same problem.

I think flush_database_updates() is a red herring here. It isn't a case of sqlobject buffering up changes: the SQL statement log in these OOPS reports clearly shows that the commands to create these table rows are being sent to the database. The question is why they don't get returned by the subsequent select queries.