Skip to content

Commit

Permalink
Fix logging of new group memberships
Browse files Browse the repository at this point in the history
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=<id>, user_id=<user_id>, group_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!)
  • Loading branch information
seanh committed Nov 21, 2024
1 parent 61b6952 commit 04bdf88
Showing 1 changed file with 3 additions and 0 deletions.
3 changes: 3 additions & 0 deletions h/services/group_members.py
Original file line number Diff line number Diff line change
Expand Up @@ -76,6 +76,9 @@ def member_join(self, group, userid):
membership = GroupMembership(group=group, user=user)
self.db.add(membership)

# Flush the DB to generate SQL defaults for `membership` before logging it.
self.db.flush()

log.info("Added group membership: %r", membership)
self.publish("group-join", group.pubid, userid)

Expand Down

0 comments on commit 04bdf88

Please sign in to comment.