View Javadoc

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