plone 3.3.5 - test catalog query using last_login_time and date range index fails

Question

I'm on Plone 3.3.5 and I'm writing some test for my package.

In the test I need to retrieve all the PloneboardComment since user's last login time.

This the code I'm using:

class FunctionalTestSetup(base.FunctionalTestCase):
    [...]
    def test_new_since_last_login(self):
        # we log in as user1
        userid = 'user1'
        self.login(userid)
        # XXX: last_login_time is not updated
        self.updateLoginTime(userid)
        # and we should get no msg since last login
        new = getNewSinceLastLoginNr(self.forum, userid)
        self.assertEquals(new,0)

    def updateLoginTime(self, userid):
        member = self.portal.portal_membership.getMemberById(userid)
        member.setMemberProperties({'last_login_time': DateTime(),})


def getNewSinceLastLogin(forum, userid):
    """ returns all the new msgs since user's last login
    """
    acl = getToolByName(forum,'acl_users')
    user = acl.getUserById(userid)
    last_login = user.getProperty('last_login_time')

    query = dict(
        path = {'query':"/".join(forum.getPhysicalPath()),
                'depth':-1,},
        portal_type = "PloneboardComment",
        created = {'query':last_login, 'range': 'min'},
    )
    brains = self.catalog(query)
    return brains

On "afterSetup" I create a forum with 2 comments BUT they should not be counted by "getNewSinceLastLogin" because they've been created before user1 logs in.

Anyway, the test fail because on "self.assertEquals(new,0)" new=2 instead of 0.

The weird thing is that if I print all the dates the query should work:

* last_login_time on login:
2011/12/07 13:44:24.131 GMT+1
* updated last_login_time:
2011/12/07 13:44:24.146 GMT+1
* last_login_time on catalog query:
2011/12/07 13:44:24.146 GMT+1
* creation date of comments:
2011/12/07 13:44:23.875 GMT+1
2011/12/07 13:44:24.019 GMT+1

Yes the difference is quite thin but even placing a "sleep(10)" before the "updateLoginTime" doesn't work.

The weird thing is that if a I place "sleep(30)" before the check or if I place a pdb inside the test, and I manually call the methods after some seconds I get 0 (!!!) that is the right query result.

I can't get what's going wrong here... is there any test-specific setup for this kind of query? Why the catalog needs all this time to be up-to-date even if I re-indexed "manually" every object just after creation?

Answer 1

Maybe this is because dates are rounded to 5 minutes. Take a look at these tickets: #11827 and #11936 and #11827