View Javadoc
1   package com.atlassian.plugin.manager;
2   
3   import com.atlassian.plugin.Plugin;
4   import com.atlassian.plugin.PluginAccessor;
5   import com.atlassian.plugin.PluginController;
6   import com.atlassian.plugin.PluginDependencies;
7   import com.atlassian.plugin.PluginState;
8   import com.atlassian.plugin.exception.PluginExceptionInterception;
9   import com.atlassian.plugin.util.PluginUtils;
10  import com.atlassian.plugin.util.WaitUntil;
11  import com.google.common.collect.ImmutableList;
12  import org.slf4j.Logger;
13  import org.slf4j.LoggerFactory;
14  
15  import java.util.ArrayList;
16  import java.util.Collection;
17  import java.util.HashSet;
18  import java.util.Iterator;
19  import java.util.Set;
20  import java.util.concurrent.CopyOnWriteArraySet;
21  import java.util.concurrent.TimeUnit;
22  
23  import static com.atlassian.plugin.util.PluginUtils.isAtlassianDevMode;
24  
25  /**
26   * Helper class that handles the problem of enabling a set of plugins at once. This functionality is used for both the
27   * initial plugin loading and manual plugin enabling. The system waits 60 seconds for all dependencies to be resolved,
28   * then resets the timer to 5 seconds if only one remains.
29   *
30   * @since 2.2.0
31   */
32  public class PluginEnabler {
33      private static final Logger log = LoggerFactory.getLogger(PluginEnabler.class);
34      private static final long LAST_PLUGIN_TIMEOUT = 30 * 1000;
35      private static final long LAST_PLUGIN_WARN_TIMEOUT = 5 * 1000;
36  
37      private final PluginAccessor pluginAccessor;
38      private final PluginController pluginController;
39      private final PluginExceptionInterception pluginExceptionInterception;
40      private final Set<Plugin> pluginsBeingEnabled = new CopyOnWriteArraySet<>();
41  
42      public PluginEnabler(
43              final PluginAccessor pluginAccessor,
44              final PluginController pluginController,
45              final PluginExceptionInterception pluginExceptionInterception) {
46          this.pluginAccessor = pluginAccessor;
47          this.pluginController = pluginController;
48          this.pluginExceptionInterception = pluginExceptionInterception;
49      }
50  
51      /**
52       * Determines, recursively, which disabled plugins this plugin depends upon, and enables all of them at once.
53       * Returns the plugins that were successfully enabled, including dependencies that weren't explicitly specified.
54       *
55       * @param plugins The set of plugins to enable
56       * @return a collection of plugins that were actually enabled
57       */
58      Collection<Plugin> enableAllRecursively(final Collection<Plugin> plugins) {
59          final Collection<Plugin> pluginsToEnable = new ArrayList<>();
60          final Set<String> requiredKeys = new HashSet<>();
61  
62          for (final Plugin plugin : plugins) {
63              scanDependencies(plugin, requiredKeys);
64          }
65  
66          for (final String key : requiredKeys) {
67              pluginsToEnable.add(pluginAccessor.getPlugin(key));
68          }
69          enable(pluginsToEnable);
70  
71          final ImmutableList.Builder<Plugin> enabledPlugins = new ImmutableList.Builder<>();
72          for (final Plugin plugin : pluginsToEnable) {
73              if (plugin.getPluginState().equals(PluginState.ENABLED)) {
74                  enabledPlugins.add(plugin);
75              }
76          }
77          return enabledPlugins.build();
78      }
79  
80      /**
81       * @param plugin The plugin to test
82       * @return If the plugin is currently part of a set that is being enabled
83       */
84      public boolean isPluginBeingEnabled(final Plugin plugin) {
85          return pluginsBeingEnabled.contains(plugin);
86      }
87  
88      /**
89       * Enables a collection of plugins at once, waiting for 60 seconds. If any plugins are still in the enabling state,
90       * the plugins are explicitly disabled.
91       *
92       * @param plugins The plugins to enable
93       */
94      void enable(final Collection<Plugin> plugins) {
95          pluginsBeingEnabled.addAll(plugins);
96          try {
97              actualEnable(plugins);
98          } finally {
99              pluginsBeingEnabled.removeAll(plugins);
100         }
101     }
102 
103     private void actualEnable(final Collection<Plugin> plugins) {
104         log.info("Resolving {} plugins", plugins.size());
105         final Set<Plugin> pluginsInEnablingState = new HashSet<>();
106         // As an optimization, perform a resolve first. This moves work that can be done up front out of the period
107         // covered by the DependencyWaiterApplicationContextExecutor timeouts.
108         for (final Plugin plugin : plugins) {
109             try {
110                 plugin.resolve();
111             } catch (final RuntimeException runtime) {
112                 // Just log - if the situation is not transient (it's probably an OsgiPlugin missing a needed bundle),
113                 // the enable below will hit it and pass it over to interception.
114                 log.error("Cannot resolve plugin '" + plugin.getKey() + "'", runtime);
115             }
116         }
117         log.info("Enabling {} plugins: {}", plugins.size(), plugins);
118         for (final Plugin plugin : plugins) {
119             try {
120                 plugin.enable();
121                 final PluginState pluginState = plugin.getPluginState();
122                 if (pluginState == PluginState.ENABLING) {
123                     pluginsInEnablingState.add(plugin);
124                 } else {
125                     log.info("Plugin '{}' immediately {}", plugin.getKey(), pluginState);
126                 }
127             } catch (final RuntimeException ex) {
128                 final boolean logMsg = pluginExceptionInterception.onEnableException(plugin, ex);
129                 if (logMsg) {
130                     log.error("Unable to enable plugin " + plugin.getKey(), ex);
131                 }
132             }
133         }
134 
135         if (!pluginsInEnablingState.isEmpty()) {
136             log.info("Waiting for {} plugins to finish ENABLING: {}", pluginsInEnablingState.size(), pluginsInEnablingState);
137 
138             // Now try to enable plugins that weren't enabled before, probably due to dependency ordering issues
139             WaitUntil.invoke(new WaitUntil.WaitCondition() {
140                 private long singlePluginTimeout;
141                 private long singlePluginWarn;
142 
143                 public boolean isFinished() {
144                     if (singlePluginTimeout > 0 && singlePluginTimeout < System.currentTimeMillis()) {
145                         return true;
146                     }
147                     for (final Iterator<Plugin> i = pluginsInEnablingState.iterator(); i.hasNext(); ) {
148                         final Plugin plugin = i.next();
149                         final PluginState pluginState = plugin.getPluginState();
150                         if (pluginState != PluginState.ENABLING) {
151                             log.info("Plugin '{}' is now {}", plugin.getKey(), pluginState);
152                             i.remove();
153                         }
154                     }
155                     if (isAtlassianDevMode() && pluginsInEnablingState.size() == 1) {
156                         final long currentTime = System.currentTimeMillis();
157                         if (singlePluginTimeout == 0) {
158                             log.info("Only one plugin left not enabled. Resetting the timeout to " + (LAST_PLUGIN_TIMEOUT / 1000) + " seconds.");
159 
160                             singlePluginWarn = currentTime + LAST_PLUGIN_WARN_TIMEOUT;
161                             singlePluginTimeout = currentTime + LAST_PLUGIN_TIMEOUT;
162                         } else if (singlePluginWarn <= currentTime) {
163                             //PLUG-617: Warn people when it takes a long time to enable a plugin when in dev mode. We bumped
164                             //this timeout from 5 to 30 seconds because the gadget publisher in JIRA can take this long to
165                             //load when running java in DEBUG mode. We are also now going to log a message about slow startup
166                             //since 30 seconds is a long time to wait for your plugin to fail.
167                             final Plugin plugin = pluginsInEnablingState.iterator().next();
168                             final long remainingWait = Math.max(0, Math.round((singlePluginTimeout - currentTime) / 1000.0));
169 
170                             log.warn("Plugin '" + plugin + "' did not enable within " + (LAST_PLUGIN_WARN_TIMEOUT / 1000) + " seconds." + "The plugin should not take this long to enable. Will only attempt to load plugin for another '" + remainingWait + "' seconds.");
171                             singlePluginWarn = Long.MAX_VALUE;
172                         }
173                     }
174                     return pluginsInEnablingState.isEmpty();
175                 }
176 
177                 public String getWaitMessage() {
178                     return "Plugins that have yet to be enabled: (" + pluginsInEnablingState.size() + "): " +
179                             pluginsInEnablingState;
180                 }
181 
182             }, PluginUtils.getDefaultEnablingWaitPeriod(), TimeUnit.SECONDS, 1);
183 
184             // Disable any plugins that aren't enabled by now
185             if (!pluginsInEnablingState.isEmpty()) {
186                 final StringBuilder sb = new StringBuilder();
187                 for (final Plugin plugin : pluginsInEnablingState) {
188                     sb.append(plugin.getKey()).append(',');
189                     pluginController.disablePluginWithoutPersisting(plugin.getKey());
190                 }
191                 sb.deleteCharAt(sb.length() - 1);
192                 log.error("Unable to start the following plugins due to timeout while waiting for plugin to enable: " + sb.toString());
193             }
194         }
195     }
196 
197     /**
198      * Scans, recursively, to build a set of plugin dependencies for the target plugin
199      *
200      * @param plugin       The plugin to scan
201      * @param requiredKeys The set of keys collected so far
202      */
203     private void scanDependencies(final Plugin plugin, final Set<String> requiredKeys) {
204         requiredKeys.add(plugin.getKey());
205 
206         final PluginDependencies dependencies = plugin.getDependencies();
207         Set<String> dependencyKeys = new HashSet<>(dependencies.getMandatory());
208 
209         // Ensure dependent plugins are enabled first
210         for (String dependencyKey : dependencyKeys) {
211             if (!requiredKeys.contains(dependencyKey) &&
212                     (pluginAccessor.getPlugin(dependencyKey) != null) &&
213                     !pluginAccessor.isPluginEnabled(dependencyKey)) {
214                 scanDependencies(pluginAccessor.getPlugin(dependencyKey), requiredKeys);
215             }
216         }
217     }
218 
219     public Set<Plugin> getPluginsBeingEnabled() {
220         return pluginsBeingEnabled;
221     }
222 }