Event deduping leads to incorrect event results

[thehesiod]

I'm still debugging how deduping works, however what I do know is that if a machine is in monitor mode, executes something that is not allowed, an ALLOW_UNKNOWN event is recorded to the datastore.

If now you move the machine to lockdown, attempt to execute the same executable, you'll get the santa warning, and eventually the event will get synced, and the recorded and last_blocked will get updated, however the event_type will stay at ALLOW_UNKNOWN.

So if you go to the events page it will list the executable as ALLOW_UNKNOWN, when in reality it was blocked.

[msuozzo]

Just so I'm clear, you're describing the following:

1. Monitor-mode Host executes binary A and it runs
2. Event displays ALLOW_UNKNOWN
3. Move Host to Lockdown mode
4. Lockdown-mode Host executes binary A and it gets blocked
5. Event displays ALLOW_UNKNOWN <-- should be BLOCK_UNKNOWN

I would expect this line to dedupe a later event's type to the correct one. If it's not doing so, this is a bug.

Can you confirm this behavior?

[thehesiod]

correct, I think maybe this: https://github.com/google/upvote/blob/master/upvote/gae/datastore/models/base.py#L107 is the issue? I'm going to check in stackdriver

[thehesiod]

ok, so Event._DedupeEarlierEvent is getting called because self is the newer event, and earlier_event/related_event is the existing DB event...and the check is:

    if self.first_blocked_dt > related_event.first_blocked_dt:
      self._DedupeEarlierEvent(related_event)

so the behavior seems to be wrong, probably the logic should be re-visited, would make more sense to be called existing_db_event or something

[thehesiod]

so ya this is really bad, because this leads to incorrect data being logged to the DB and displayed via the admin UI. It may end up showing things are blocked when they're allowed, and vice versa

[msuozzo]

But isn't that what you want? In that case, the newer Event's event_type will be set, no?

[thehesiod]

no, look:

  def _DedupeEarlierEvent(self, earlier_event):
    """Updates if the related Event occurred earlier than the current one."""
    self.first_blocked_dt = earlier_event.first_blocked_dt
    self.event_type = earlier_event.event_type

it's overriding self.event_type (the newer/recent event), to the earlier's (from DB) event type

[msuozzo]

Ahhh my mistake. Yeah it makes sense to just move that to the DedupeMoreRecentEvent. I'll make the change.

[msuozzo]

Oh wait yeah so the base Event and SantaEvent disagreed on how to dedupe event_type. I'll fix the base implementation and remove that behavior from the Santa version of the model.

[msuozzo]

Okay the fix is in. It'll be updated in the next export.