[Bug]: Inconsistent arrow-in with synonyms

n8henrie commented 2 years ago

Before submitting your bug report, please confirm you have completed the following steps

[X] Searched the issue is not already listed in the Issue List (I've searched it)
[X] Searched in the Quicksilver Users' Group for questions relating to tech support.
[X] Downloaded the latest version of Quicksilver for your system and confirmed the issue still persists.

Bug description

I use asdf as a synonym for Clipboard History, since I use it so often. I used to be able to asdf ⇥ and go to the history. For the last few QS versions I usually but not always get the "bounce" when I ⇥ from the alias (using Clipboard History ⇥ continues to work as expected).

Sometimes I can asdf ⇥ and get a couple of bounces and then it works on the 3rd or 4th ⇥, sometimes I can try to arrow-in for as long as I want and it never resolves.

Seems like some kind of race condition with a background process? Or perhaps background indexing?

As an experiment, I made a synonym: dls -> ~/Downloads and see similar behavior. I can do Downloads and ⇥ just fine. If I do dls it resolves the synonym as expected, but ⇥ bounces for a few seconds and then eventually works.

Steps to reproduce

Catalog -> Synonym -> create one for an existing directory
Invoke QS -> synonym -> ⇥
If it bounces, keep hitting ⇥ for a few seconds

Expected behavior

Synonyms consistently behave like their target (or perhaps consistently refuse to if we want, but I think the former is preferable).

MacOS Version

macOS 12

Quicksilver Version

2.4.0 (4039)

Relevant Plugins

Clipboard

Crash Logs or Spindump

None

Screenshots

https://user-images.githubusercontent.com/1234956/182415842-baeb4a16-5aaa-423d-be1f-4d3803b0cba8.mov

Additional info

I should probably do a bisect on this at some point.

pjrobertson commented 2 years ago

Confirmed. git bisect to find the culprit commit is what's needed 👍

pjrobertson commented 2 years ago

So the real cause of this problem was a race condition in -[QSLibrarian reloadSets:]. Basically, the first line there: [self.objectDictionary removeAllObjects]

Originally introduced in dbe8512c3

Reminder: we shouldn't 'remove all objects' from a dictionary, then re-create the dictionary. That means there's a brief period of time when the dictionary is empty. Instead, we should rebuild a brand new dictionary, and replace the old dictionary with it.

This fix should also hopefully fix several other edge-case issues.

n8henrie commented 2 years ago

For my future reference, and perhaps if we need to show / teach a user how to bisect, my bisect process was to first manually find an old commit that didn't seem to have the bug and start a bisect from there:

$ git log --since='1 year ago'
$ git checkout 9dca102f2f716ac316967f9de6c9c54a9f4d501b # verify it seems to not have the bug
$ git bisect start main HEAD # start a bisect from current commit until `main`

Then create the below script named again.sh that force cleans and tries to build and launch QS:

#!/usr/bin/env bash

set -Eeuf -o pipefail
shopt -s inherit_errexit
set -x

main() {
  # Kill leftover qs processes from prior runs
  killall Quicksilver || true

  # force clean everything in Quicksilver (keeping this script around in the repo root)
  rm -rf /tmp/QS
  git clean -xffd -- ./Quicksilver
  git submodule foreach --recursive 'git clean -xffd'
  git submodule foreach --recursive 'git reset --hard'
  git submodule update --init --recursive

  pushd Quicksilver
  xcodebuild clean

  # Try to build a few times, break the loop on success
  for _ in {1..3}; do
    xcodebuild \
      -destination platform=macOS,arch=arm64 \
      -configuration Debug \
      -scheme 'Quicksilver Distribution' build && break
  done

  # Exit error if executable wasn't built
  qs=/tmp/QS/build/Debug/Quicksilver.app/Contents/MacOS/Quicksilver
  [[ -x "${qs}" ]] || exit 1

  # Run QS in background process to allow the script to exit cleanly
  "${qs}" &> /dev/null &
}
main "$@"

It seemed like we had a few commits that failed to build entirely, so I would run the script in a loop like this, skipping any commits that failed to build in 3 tries (the retry loop in the script):

$ until ./again.sh; do git bisect skip; done

In this way I could start the script and go do something else while it cleans and builds (and possibly skips a commit and tries a different one). After a successful build I'd see the familiar QS popup, test, and either git bisect good or git bisect bad, then rerun the until ... command.

I noticed a few of these in the log / console output:

The synonym 'asdf' refers to something that isn't in the catalog: [Shelf]:QSPasteboardHistory

I eventually got to:

76a942455e4355463858962bda07e66d1ed273df is the first bad commit
commit 76a942455e4355463858962bda07e66d1ed273df
Author: Patrick Robertson <robertson.patrick@gmail.com>
Date:   Wed Jun 22 23:28:18 2022 +0800

    Don't write mnemonics on the main thread

    Plus: queue up writing mnemonics so we don't overload the disk

 Quicksilver/Code-QuickStepCore/QSMnemonics.h |  1 +
 Quicksilver/Code-QuickStepCore/QSMnemonics.m | 26 ++++++++++++++------------
 2 files changed, 15 insertions(+), 12 deletions(-)

Manual verification:

$ git checkout 76a942455e4355463858962bda07e66d1ed273df
$ ./again.sh # sure enough it has the bug
$ git checkout HEAD^
$ ./again.sh # sure enough no bug

I'll take a look at 76a942455e4355463858962bda07e66d1ed273df and see if I can identify a culprit.

For any readers new to bisect, the great part about a binary search is that it reduced the search space of ~450 commits:

$ git rev-list --count 76a942455e4355463858962bda07e66d1ed273df..main
452

down to 14 steps

$ git bisect log | grep '^# \(good\|bad\)' | wc -l
14

quicksilver / Quicksilver