broken sort order for plugins, priority_plugins not honored

[binary1230]

This one's fun :) This is one of those bugs where it's literally been busted for years but has by certain system-dependent miracles worked correctly and we never noticed. I need to double check this, but I'm now pretty confident this is real.

TLDR: sideboard doesn't honor the order of priority_plugins

"BUT wait!" I hear you say. "If that were true, it should have been crashing for years, right? How did we never notice??"

We never noticed it wasn't working because on literally every box we've ever run, glob() (which returns an unordered result) happened by PURE CHANCE to return a plugin load order that happened to work despite our sorting not working.

1. glob() ordering is arbitrary, it is not sorted in any way:
   "By checking the source code of glob.glob you see that it internally calls os.listdir, described here:
   http://docs.python.org/library/os.html?highlight=os.listdir#os.listdir
   Key sentence: os.listdir(path) Return a list containing the names of the entries in the directory given by path. The list is in arbitrary order. It does not include the special entries '.' and '..' even if they are present in the directory."

2. that non-ordering shouldn't be a problem because our code is supposed to re-order things so the prioritized plugins get loaded first.

but that's not what happens, here's the result of an instrumented build which spits out some debug info about this process (https://github.com/magfest/sideboard/blob/ordering_testing_NEVERUSE/sideboard/internal/imports.py)

glob() results on Vicki's machine: returns a BROKEN LOAD ORDERING

priority_plugins: ['panels', 'uber'] 
glob("/home/vagrant/uber/sideboard/plugins/*") says:
['/home/vagrant/uber/sideboard/plugins/uber_analytics',
'/home/vagrant/uber/sideboard/plugins/hotel',
'/home/vagrant/uber/sideboard/plugins/barcode',
'/home/vagrant/uber/sideboard/plugins/magclassic',
'/home/vagrant/uber/sideboard/plugins/uber',
'/home/vagrant/uber/sideboard/plugins/tabletop',
'/home/vagrant/uber/sideboard/plugins/bands',
'/home/vagrant/uber/sideboard/plugins/attendee_tournaments',
'/home/vagrant/uber/sideboard/plugins/panels'

would load plugins in the following order:
['uber_analytics', 'hotel', 'barcode', 'magclassic', 'uber', 'tabletop', 'bands', 'attendee_tournaments', 'panels']

NOTE: BROKEN: panels needs to load before tabletop, else tabletop crashes startup

same test but run on staging2 with identical set of plugins and priority_plugins results in a DIFFERENT LOAD ORDER (BUG)

priority_plugins: ['panels', 'uber']

glob("/usr/local/uber/plugins/*") says:
['/usr/local/uber/plugins/barcode',
'/usr/local/uber/plugins/magclassic',
'/usr/local/uber/plugins/attendee_tournaments',
'/usr/local/uber/plugins/uber_analytics',
'/usr/local/uber/plugins/panels',
'/usr/local/uber/plugins/tabletop',
 '/usr/local/uber/plugins/bands',
'/usr/local/uber/plugins/uber',
'/usr/local/uber/plugins/hotel']

would load plugins in the following order:
['barcode', 'magclassic', 'attendee_tournaments', 'uber_analytics', 'panels', 'tabletop', 'bands', 'uber', 'hotel']

That load order is a valid order.

---

solution: uber's code should be handling this case correctly on Vicki's machine but isn't, so it's a legit bug we need to fix. Should be an easy fix, and we should probably unit test the hell out of this to make sure it loads things correctly.

[binary1230]

I should point out the particular failure case here is that on Vicki's machine 'tabletop' plugin is loading before its dependency of 'panels', and it causes it to crash.

[binary1230]

this should probably be fixed in two ways:

1. sort the results of glob alphabetically (which won't fix the prioritization problem, but will ensure that if there's ever a bug there later, it will fail in the same way on every system instead of being dependent on system ordering)
2. fix the prioritization which is loading the panels plugin last instead of second (also loads uber plugin in the wrong order)

[kitsuta]

My confusion here is that:

1. Anthrocon had a broken plugin thing going on (badge_printing was overriding templates that anthrocon_plugin needed to override last) and I fixed it by updating the sideboard development.ini. If the priority plugins were never honored, how did this happen?
2. The order you listed for staging2 also should not work. Several of the plugins loaded before "uber" have Session mixins that depend on uber just like the tabletop plugin has a Session mixin that depends on panels. How are all these plugins not broken if they really are being loaded in that order?

Unrelatedly, why is glob() returning something different inside vagrant? I thought the whole point of vagrant was to NOT have these issues. :\

[EliAndrewC]

Interesting... FWIW, Sideboard doesn't rely on glob order and instead calls sorted to ensure that priority plugins appear before non-priority plugins and that they appear in the correct order. Here's the line where that happens:
https://github.com/magfest/sideboard/blob/master/sideboard/internal/imports.py#L14

I can now see that the bug is that the key lambda function returns 0 both for the last item in priority_plugins and for any item NOT in priority plugins.

That line should be changed from

for plugin_path in sorted(plugin_dirs, reverse=True, key=lambda d: (ordered.index(d) if d in ordered else 0)):

to

for plugin_path in sorted(plugin_dirs, reverse=True, key=lambda d: (ordered.index(d) if d in ordered else -1)):

which will prevent this from happening.

[kitsuta]

@EliAndrewC That was actually one of the first things I tried. I tried it again and it still didn't make a difference. Something's wrong with the key= bit though for sure - maybe it's broken only here because of a Python update or something?

[EliAndrewC]

So to clarify, suppose we had 5 plugins: v, w, x, y, z and of those 5 plugins, and priority_plugins is set to w, y. According to the bug on the line I copy/pasted in my previous comment, w would always be loaded first, and then y may or may not be loaded first.

To answer why glob might return different values, that's because it returns them in the order that they're returned by the operating system, which even on identical boxes might be different.

[kitsuta]

I fixed it.

[kitsuta]

The problem was that plugin_dirs is a list that looks like this:

['/home/vagrant/uber/sideboard/plugins/uber', '/home/vagrant/uber/sideboard/plugins/panels', '/home/vagrant/uber/sideboard/plugins/uber_analytics', '/home/vagrant/uber/sideboard/plugins/hotel', '/home/vagrant/uber/sideboard/plugins/barcode', '/home/vagrant/uber/sideboard/plugins/magclassic', '/home/vagrant/uber/sideboard/plugins/tabletop', '/home/vagrant/uber/sideboard/plugins/bands', '/home/vagrant/uber/sideboard/plugins/attendee_tournaments']

That line checks each item in that list against the ordered list, which according to our config, looks like this:

[ 'uber', 'panels' ]

One of these things is not like the other~

Anyway, I'll commit and PR a fix shortly.

[EliAndrewC]

Ahhhh, good catch!

[kitsuta]

Also of course a million thanks to @binary1230 for helping debug this - I wasn't getting anywhere until he got on my machine and worked on this for like two hours. It was only after this issue was filed that I was able to puzzle anything out.

[binary1230]

btw (guessing) glob() might be returning something different inside vagrant because that folder is being shared into the VM, which means there's some reliance on the host OS filesystem stuff. if your host OS is using a different filesystem than what vagrant or prod ubuntu uses, that could explain it.

As for how this could have worked before:
For uber plugin: I bet that any of our plugins import uber on their own so regardless of when we import the uber plugin, it probably just happens loads correctly even if we load it last. i.e. all the plugins likely do from uber.common import * somewhere which probably forces it to load first.

For panels plugin: Tabletop requires panels plugin to be around, but it never directly imports anything from panels. Thus, it really will crash if panels stuff (like the Events model) doesn't exist.

If you look at the two different outputs, on staging2, panels is indeed loaded before tabletop whereas on yours it was tabletop then panels.

[binary1230]

I still would like to see us immediately sort the glob() output by basename so that the ordering is consistent (even though we don't need to do this to get uber to start and it works fine as-is)

That way, even if there's system dependent ordering from glob(), ALL sideboard instances everywhere still load plugins in the exact same order (despite us not needing to do this).

That way if we ever encounter weird system-specific+plugin-order-specific behavior again, we should hopefully see it fail everywhere instead of just failing on one random computer.

[binary1230]

made a separate issue for the idea of sorting the gloab() output #15

[thaeli]

Have taken my discussion of sorting over to #15

On Wed, May 25, 2016 at 12:10 PM, Dominic Cerquetti <
notifications@github.com> wrote:

made a separate issue for the idea of sorting the gloab() output #15
#15

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub
#13 (comment)