Avoid poisoning plugin cache (#1737)

* plugins: move addToCache to avoid bad entries

This came from an issue referenced on slack (gophers #buffalo on 2019-07-12) where I could not get buffalo plugins, especially pop, to load properly.

It happened because my machine timed out trying to run `buffalo-pop available`, and it cached a bad entry with no commands.

It seems like we should only cache the commands if we got a successful response from the given binary.

The downside here is that if there is a `buffalo-<something>` binary and we're failing to get commands from it, buffalo will try again on it every time. I've added logging for that error so it's clear to the user why buffalo is loading slowly and so they can fix the issue.

* Updated plugins test

plugins/plugins.go

@@ -144,11 +144,6 @@ func askBin(ctx context.Context, path string) Commands {
 	}()
 
 	commands := Commands{}
-	defer func() {
-		addToCache(path, cachedPlugin{
-			Commands: commands,
-		})
-	}()
 	if cp, ok := findInCache(path); ok {
 		s := sum(path)
 		if s == cp.CheckSum {
@@ -167,12 +162,17 @@ func askBin(ctx context.Context, path string) Commands {
 	cmd.Stdout = bb
 	err := cmd.Run()
 	if err != nil {
+		logrus.Errorf("[PLUGIN] error loading plugin %s: %s\n", path, err)
 		return commands
 	}
+
 	msg := bb.String()
 	for len(msg) > 0 {
 		err = json.NewDecoder(strings.NewReader(msg)).Decode(&commands)
 		if err == nil {
+			addToCache(path, cachedPlugin{
+				Commands: commands,
+			})
 			return commands
 		}
 		msg = msg[1:]

plugins/plugins_test.go

@@ -54,4 +54,8 @@ func TestAskBin_respectsTimeout(t *testing.T) {
 	case <-done:
 		t.Log("timed-out successfully")
 	}
+
+	if _, ok := findInCache(from); ok {
+		r.Fail("expected plugin not to be added to cache on failure, but it was in cache")
+	}
 }