hypothesis / h

Annotate with anyone, anywhere.
https://hypothes.is/
BSD 2-Clause "Simplified" License
2.96k stars 427 forks source link

Fix logging of new group memberships #9104

Closed seanh closed 5 days ago

seanh commented 5 days ago

Problem: when a user joins a group the logging of the newly-created group membership is broken because the SQL defaults for the membership haven't yet been generated when the membership is logged:

Added group membership: GroupMembership(id=None, user_id=None, group_id=None, roles=None)

Solution: flush the DB to generate defaults before logging.

Testing:

  1. Create a group (http://localhost:5000/groups/new)
  2. Leave the group
  3. Use the browser's back button to navigate back to the group's page, reload the page, and re-join the group
  4. You should see this logged in the terminal:

    Added group membership: GroupMembership(id=, user_id=, group_id=, roles=['member'])

Generally whenever creating a new ORM object you need to flush the DB before logging about it:

    membership = GroupMembership(group=group, user=user)
    db.add(membership)
    db.flush()
    log.info("Added group membership: %r", membership)

If you don't flush the DB you get log messages like this:

Added group membership: GroupMembership(id=None, user_id=None, group_id=None, roles=None)

Tests will tend not to catch this mistake because the test can't hard-code the auto-generated default values for things like IDs, datetimes that default to now, etc. So they'll tend to do this, which passes:

    assert caplog.messages == [f"Added group membership: {membership!r}"]

Also it seems that the %r's in log messages are evaluated when the test accesses caplog.messages rather than when the method-under-test calls logging.info(). So if the tests do something after calling the method-under-test that triggers an autoflush (e.g. if the tests do a DB query after calling the method-under-test) that will cause default values to be generated. Then when the tests later access caplog.messages it will contain the generated defaults rather than None's.

(The %r's also appear to be re-evaluated each time caplog.messages is accessed so the same log message may at first contain None's then contain the generated defaults if caplog.messages is accessed at two different times in the same test!)