Installing support plugin has taken down SCM-Manager

As requested by @pfeuffer in my other Mercurial related thread I installed the support plugin into my SCM-Manager instance. During installation I selected the option to restart SCM-Manager, however the SCM-Manager service did not restart and now will not start.

If I look in the plugins folder I see the scm-support_plugin.smp file was downloaded but not decompressed as there is no scm-support_plugin folder.

SCM Manager 2.24 (fresh install as of a few days ago, no other plugins but standard)
Windows 2019
SCM-Manager service is running with a specific Windows user account, not LocalSystem. (Switching back to LocalSystem now doesn’t help).

My first priority is to get this server back up and running. I’ve tried to find a way to reverse the support plugin installation manually but i can’t find any reference to it in the configuration files. Please advise how this can be achieved as soon as possible.

Your forum won’t accept a zip file so I’ve quoted the relevant sections of the logs rather than uploading the whole thing.

scm-manager.log

2021-10-13 06:35:44.237 [qtp1525037790-54] [5hSlem30oMy] INFO  sonia.scm.plugin.PluginCenterLoader - fetch plugins from https://plugin-center-api.scm-manager.org/api/v1/plugins/2.24.0?os=Windows+Server+2019&arch=64&jre=11.0.12
2021-10-13 06:35:45.426 [qtp1525037790-54] [5hSlem30oMy] INFO  sonia.scm.trace.LoggingExporter - received Plugin Center span, which took 1188ms:
 - url: https://plugin-center-api.scm-manager.org/api/v1/plugins/2.24.0?os=Windows+Server+2019&arch=64&jre=11.0.12
 - method: GET
 - status: 200
2021-10-13 06:36:02.613 [qtp1525037790-30] [7RSlem7QlN3] INFO  sonia.scm.trace.LoggingExporter - received Plugin Center span, which took 1390ms:
 - url: https://plugin-center-api.scm-manager.org/api/v1/download/scm-support-plugin/2.0.0
 - method: GET
 - status: 200
2021-10-13 06:36:03.418 [ScmEventBus-1-3] [          ] WARN  sonia.scm.lifecycle.BootstrapContextFilter - received restart event from interface sonia.scm.plugin.PluginManager with reason: plugin installation
2021-10-13 06:36:03.434 [ScmEventBus-1-3] [          ] WARN  sonia.scm.lifecycle.RestartStrategy - destroy injection context
2021-10-13 06:36:03.434 [ScmEventBus-1-3] [          ] INFO  sonia.scm.lifecycle.modules.ResteasyAllInOneServletDispatcher - destroy resteasy
2021-10-13 06:36:03.480 [ScmEventBus-1-3] [          ] INFO  sonia.scm.lifecycle.BootstrapContextListener - shutdown scm-manager context
2021-10-13 06:36:03.496 [ScmEventBus-1-3] [          ] INFO  sonia.scm.lifecycle.ServletContextCleaner - remove cached attributes from context
2021-10-13 06:36:03.496 [ScmEventBus-1-3] [          ] INFO  sonia.scm.lifecycle.ServletContextCleaner - keep attribute com.google.inject.Injector in servlet context
2021-10-13 06:36:03.496 [ScmEventBus-1-3] [          ] INFO  sonia.scm.lifecycle.ServletContextCleaner - keep attribute javax.servlet.context.tempdir in servlet context
2021-10-13 06:36:03.496 [ScmEventBus-1-3] [          ] INFO  sonia.scm.lifecycle.ServletContextCleaner - keep attribute org.eclipse.jetty.util.DecoratedObjectFactory in servlet context
2021-10-13 06:36:03.496 [ScmEventBus-1-3] [          ] INFO  sonia.scm.lifecycle.ServletContextCleaner - remove attribute org.apache.shiro.web.env.EnvironmentLoader.ENVIRONMENT_ATTRIBUTE_KEY from servlet context
2021-10-13 06:36:03.496 [ScmEventBus-1-3] [          ] INFO  sonia.scm.lifecycle.ServletContextCleaner - keep attribute resourceCache in servlet context
2021-10-13 06:36:03.496 [ScmEventBus-1-3] [          ] INFO  sonia.scm.lifecycle.ServletContextCleaner - remove attribute resteasy.deployments from servlet context
2021-10-13 06:36:03.496 [ScmEventBus-1-3] [          ] INFO  sonia.scm.lifecycle.ServletContextCleaner - keep attribute org.eclipse.jetty.tmpdirConfigured in servlet context
2021-10-13 06:36:03.496 [ScmEventBus-1-3] [          ] INFO  sonia.scm.lifecycle.ServletContextCleaner - keep attribute org.eclipse.jetty.server.Executor in servlet context
2021-10-13 06:36:03.496 [ScmEventBus-1-3] [          ] INFO  sonia.scm.repository.work.WorkdirProvider - deleting 0 old work dirs in C:\Users\scmuser\AppData\Local\Temp\scm-work
2021-10-13 06:36:03.496 [ScmEventBus-1-3] [          ] WARN  sonia.scm.repository.GitWorkQueueShutdownListener - shutdown jGit WorkQueue executor
2021-10-13 06:36:03.512 [ScmEventBus-1-3] [          ] INFO  sonia.scm.cache.GuavaCacheManager - close guava cache manager
2021-10-13 06:36:03.512 [ScmEventBus-1-3] [          ] INFO  sonia.scm.lifecycle.classloading.ClassLoaderLifeCycle - shutdown classloader infrastructure
2021-10-13 06:36:06.251 [ScmEventBus-1-3] [          ] ERROR sonia.scm.lifecycle.WinSWRestartStrategy - scm-manager is in an unrecoverable state, we will now exit the java process

scm-server.err.log does not appear to have anything from the time of the plugin installation, only my subsequent attempts to restart the service.

Oct 12, 2021 2:51:01 PM com.google.inject.servlet.GuiceFilter setPipeline
WARNING: Multiple Servlet injectors detected. This is a warning indicating that you have more than one GuiceFilter running in your web application. If this is deliberate, you may safely ignore this message. If this is NOT deliberate however, your application may not work as expected.
2021-10-12 14:51:05.517:INFO:oejsh.ContextHandler:main: Started o.e.j.w.WebAppContext@153cfd86{SCM-Manager ${project.version},/scm,file:///D:/scm-server/work/scm-webapp/webapp/,AVAILABLE}{./webapp/scm-webapp.war}
2021-10-12 14:51:05.548:INFO:oejw.StandardDescriptorProcessor:main: NO JSP Support for /, did not find org.eclipse.jetty.jsp.JettyJspServlet
2021-10-12 14:51:05.564:INFO:oejsh.ContextHandler:main: Started o.e.j.w.WebAppContext@790654d5{/,[file:///D:/scm-server/webapp/docroot/],AVAILABLE}
2021-10-12 14:51:05.610:INFO:oejs.AbstractConnector:main: Started ServerConnector@7ff95560{HTTP/1.1, (http/1.1)}{0.0.0.0:8080}
2021-10-12 14:51:05.610:INFO:oejs.Server:main: Started @23202ms
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by io.micrometer.core.instrument.binder.jvm.ExecutorServiceMetrics (file:/D:/scm-server/work/scm-webapp/webapp/WEB-INF/lib/micrometer-core-1.6.5.jar) to field java.util.concurrent.Executors$DelegatedExecutorService.e
WARNING: Please consider reporting this to the maintainers of io.micrometer.core.instrument.binder.jvm.ExecutorServiceMetrics
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
2021-10-13 06:43:27.120:INFO::main: Logging initialized @734ms to org.eclipse.jetty.util.log.StdErrLog
2021-10-13 06:43:27.448:WARN:oejx.XmlConfiguration:main: Config error at <Set name="forwarded">true</Set> java.lang.NoSuchMethodException: class org.eclipse.jetty.server.ServerConnector.setForwarded(class java.lang.String) in file:///D:/scm-server/conf/server-config.xml
2021-10-13 06:43:27.448:WARN:oejx.XmlConfiguration:main: Config error at <Call name="addConnector"><Arg>|      <New class="org.eclipse.jetty.server.ServerConnector"><Arg name="server">|          <Ref refid="ScmServer"/>|        </Arg><Arg name="factories">|          <Array type="org.eclipse.jetty.server.ConnectionFactory"><Item>|              <New class="org.eclipse.jetty.server.HttpConnectionFactory"><Arg name="config">|                  <Ref refid="httpConfig"/>|                </Arg></New>|            </Item></Array>|        </Arg><Set name="host">|          <SystemProperty name="jetty.host" default="0.0.0.0"/>|        </Set><Set name="port">|          <SystemProperty name="jetty.port" default="8080"/>|        </Set><Set name="forwarded">true</Set></New>|    </Arg></Call> java.lang.IllegalStateException: No Method: <Call name="addConnector"><Arg>
      <New class="org.eclipse.jetty.server.ServerConnector"><Arg name="server">
          <Ref refid="ScmServer"/>
        </Arg><Arg name="factories">
          <Array type="org.eclipse.jetty.server.ConnectionFactory"><Item>
              <New class="org.eclipse.jetty.server.HttpConnectionFactory"><Arg name="config">
                  <Ref refid="httpConfig"/>
                </Arg></New>
            </Item></Array>
        </Arg><Set name="host">
          <SystemProperty name="jetty.host" default="0.0.0.0"/>
        </Set><Set name="port">
          <SystemProperty name="jetty.port" default="8080"/>
        </Set><Set name="forwarded">true</Set></New>
    </Arg></Call> on class org.eclipse.jetty.server.Server in file:///D:/scm-server/conf/server-config.xml
Exception in thread "main" java.lang.ExceptionInInitializerError
Caused by: sonia.scm.server.ScmServerException: error during server configuration
	at sonia.scm.server.ScmServer.<init>(ScmServer.java:74)
	at sonia.scm.server.ScmServerDaemon.<clinit>(ScmServerDaemon.java:41)
Caused by: java.lang.IllegalStateException: No Method: <Call name="addConnector"><Arg>
      <New class="org.eclipse.jetty.server.ServerConnector"><Arg name="server">
          <Ref refid="ScmServer"/>
        </Arg><Arg name="factories">
          <Array type="org.eclipse.jetty.server.ConnectionFactory"><Item>
              <New class="org.eclipse.jetty.server.HttpConnectionFactory"><Arg name="config">
                  <Ref refid="httpConfig"/>
                </Arg></New>
            </Item></Array>
        </Arg><Set name="host">
          <SystemProperty name="jetty.host" default="0.0.0.0"/>
        </Set><Set name="port">
          <SystemProperty name="jetty.port" default="8080"/>
        </Set><Set name="forwarded">true</Set></New>
    </Arg></Call> on class org.eclipse.jetty.server.Server
	at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.call(XmlConfiguration.java:950)
	at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.configure(XmlConfiguration.java:515)
	at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.configure(XmlConfiguration.java:431)
	at org.eclipse.jetty.xml.XmlConfiguration.configure(XmlConfiguration.java:364)
	at sonia.scm.server.ScmServer.<init>(ScmServer.java:70)
	... 1 more
Caused by: java.lang.NoSuchMethodException: class org.eclipse.jetty.server.ServerConnector.setForwarded(class java.lang.String)
	at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.set(XmlConfiguration.java:742)
	at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.configure(XmlConfiguration.java:509)
	at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.newObj(XmlConfiguration.java:1022)
	at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.itemValue(XmlConfiguration.java:1540)
	at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.value(XmlConfiguration.java:1441)
	at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.access$700(XmlConfiguration.java:395)
	at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration$Args.<init>(XmlConfiguration.java:1699)
	at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration$Args.<init>(XmlConfiguration.java:1686)
	at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.call(XmlConfiguration.java:942)
	... 5 more
	Suppressed: java.lang.NoSuchMethodException: org.eclipse.jetty.server.ServerConnector.setForwarded(java.lang.String)
		at java.base/java.lang.Class.getMethod(Unknown Source)
		at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.set(XmlConfiguration.java:601)
		... 13 more
	Suppressed: java.lang.NoSuchFieldException: TYPE
		at java.base/java.lang.Class.getField(Unknown Source)
		at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.set(XmlConfiguration.java:614)
		... 13 more
	Suppressed: java.lang.NoSuchFieldException: forwarded
		at java.base/java.lang.Class.getField(Unknown Source)
		at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.set(XmlConfiguration.java:629)
		... 13 more

scm-server.wrapper.log showing the last successful start and then failed attempts to restart this morning.

2021-10-12 14:50:42,054 DEBUG - Starting WinSW in service mode
2021-10-12 14:50:42,239 INFO  - Starting D:\Java\bin\java -cp "D:\scm-server\conf";"D:\scm-server\lib\*" -DBASE_DIR="D:\scm-server" -Djava.awt.headless=true -Dlogback.configurationFile=logging.xml sonia.scm.server.ScmServerDaemon
2021-10-12 14:50:42,273 INFO  - Started process 3768
2021-10-12 14:50:42,289 DEBUG - Forwarding logs of the process System.Diagnostics.Process (java) to WinSW.SizeBasedRollingLogAppender
2021-10-13 06:36:05,322 DEBUG - Starting WinSW in console mode
2021-10-13 06:36:06,192 INFO  - Restarting the service with id 'scm-server'
2021-10-13 06:36:06,202 DEBUG - Completed. Exit code is 0
2021-10-13 06:36:06,403 DEBUG - Starting WinSW in console mode
2021-10-13 06:36:06,553 INFO  - Restarting the service with id 'scm-server'
2021-10-13 06:36:06,600 FATAL - WMI Operation failure: AccessDenied
WMI.WmiException: AccessDenied
   at WMI.WmiRoot.BaseHandler.CheckError(ManagementBaseObject result)
   at WMI.WmiRoot.InstanceHandler.Invoke(Object proxy, MethodInfo method, Object[] arguments)
   at WMI.IWin32ServiceProxy.StopService()
   at WinSW.Program.<Run>g__Restart|2_5(<>c__DisplayClass2_0& )
   at WinSW.Program.Run(String[] argsArray, IWinSWConfiguration descriptor)
   at WinSW.Program.Main(String[] args)
2021-10-13 06:43:25,799 DEBUG - Starting WinSW in service mode
2021-10-13 06:43:26,114 INFO  - Starting D:\Java\bin\java -cp "D:\scm-server\conf";"D:\scm-server\lib\*" -DBASE_DIR="D:\scm-server" -Djava.awt.headless=true -Dlogback.configurationFile=logging.xml sonia.scm.server.ScmServerDaemon
2021-10-13 06:43:26,231 INFO  - Started process 7100
2021-10-13 06:43:26,246 DEBUG - Forwarding logs of the process System.Diagnostics.Process (java) to WinSW.SizeBasedRollingLogAppender
2021-10-13 06:45:27,083 DEBUG - Starting WinSW in service mode
2021-10-13 06:45:27,296 INFO  - Starting D:\Java\bin\java -cp "D:\scm-server\conf";"D:\scm-server\lib\*" -DBASE_DIR="D:\scm-server" -Djava.awt.headless=true -Dlogback.configurationFile=logging.xml sonia.scm.server.ScmServerDaemon
2021-10-13 06:45:27,330 INFO  - Started process 3852
2021-10-13 06:45:27,347 DEBUG - Forwarding logs of the process System.Diagnostics.Process (java) to WinSW.SizeBasedRollingLogAppender
2021-10-13 06:48:16,305 DEBUG - Starting WinSW in service mode
2021-10-13 06:48:16,747 INFO  - Starting D:\Java\bin\java -cp "D:\scm-server\conf";"D:\scm-server\lib\*" -DBASE_DIR="D:\scm-server" -Djava.awt.headless=true -Dlogback.configurationFile=logging.xml sonia.scm.server.ScmServerDaemon
2021-10-13 06:48:16,865 INFO  - Started process 3124
2021-10-13 06:48:16,903 DEBUG - Forwarding logs of the process System.Diagnostics.Process (java) to WinSW.SizeBasedRollingLogAppender
2021-10-13 06:48:37,075 DEBUG - Starting WinSW in service mode
2021-10-13 06:48:37,476 INFO  - Starting D:\Java\bin\java -cp "D:\scm-server\conf";"D:\scm-server\lib\*" -DBASE_DIR="D:\scm-server" -Djava.awt.headless=true -Dlogback.configurationFile=logging.xml sonia.scm.server.ScmServerDaemon
2021-10-13 06:48:37,574 INFO  - Started process 5148
2021-10-13 06:48:37,591 DEBUG - Forwarding logs of the process System.Diagnostics.Process (java) to WinSW.SizeBasedRollingLogAppender
2021-10-13 06:55:03,008 DEBUG - Starting WinSW in service mode
2021-10-13 06:55:03,157 INFO  - Starting D:\Java\bin\java -cp "D:\scm-server\conf";"D:\scm-server\lib\*" -DBASE_DIR="D:\scm-server" -Djava.awt.headless=true -Dlogback.configurationFile=logging.xml sonia.scm.server.ScmServerDaemon
2021-10-13 06:55:03,374 INFO  - Started process 1992
2021-10-13 06:55:03,409 DEBUG - Forwarding logs of the process System.Diagnostics.Process (java) to WinSW.SizeBasedRollingLogAppender
2021-10-13 07:01:38,489 DEBUG - Starting WinSW in service mode
2021-10-13 07:01:38,873 INFO  - Starting D:\Java\bin\java -cp "D:\scm-server\conf";"D:\scm-server\lib\*" -DBASE_DIR="D:\scm-server" -Djava.awt.headless=true -Dlogback.configurationFile=logging.xml sonia.scm.server.ScmServerDaemon
2021-10-13 07:01:38,988 INFO  - Started process 540
2021-10-13 07:01:39,023 DEBUG - Forwarding logs of the process System.Diagnostics.Process (java) to WinSW.SizeBasedRollingLogAppender
2021-10-13 07:09:53,918 DEBUG - Starting WinSW in service mode
2021-10-13 07:09:54,034 INFO  - Starting D:\Java\bin\java -cp "D:\scm-server\conf";"D:\scm-server\lib\*" -DBASE_DIR="D:\scm-server" -Djava.awt.headless=true -Dlogback.configurationFile=logging.xml sonia.scm.server.ScmServerDaemon
2021-10-13 07:09:54,130 INFO  - Started process 3228
2021-10-13 07:09:54,144 DEBUG - Forwarding logs of the process System.Diagnostics.Process (java) to WinSW.SizeBasedRollingLogAppender

Hey @lachlang,

Not sure what happened there yet, but try to delete the .smp file and restart your server. We will look into it and try to figure out how this could happen.

Just by looking at your stacktrace, i’m not sure the support plugin could have done this.

Hope this helps.
Eduard

Sorry I should have mentioned I already tried removing the .smp file and restarting the machine. I also tried unpacking the .smp file and putting it in place but that did nothing either.

This is a fresh install of SCM-Manager from just a few days ago. This is all that has been done with it:

  • SCM-Manager is on D:\SCM-Manager
  • The home directory has been set to D:\SCM-Manager-Data
  • Mercurial has been configured to use the hg.exe of a locally installed TortoiseHg instance.
  • It is running on port 8080 but is behind an IIS reverse proxy that is forwarding the SSL requests/responses.
  • The service is configured to run using a local Windows user via the services control panel. The Windows user does not have administrative rights but does have full access to the D drive.
  • No plugins had been installed until the support plugin this morning.

The server was installed about 3 days ago and has been running fine. Yesterday we configured the IIS reverse proxy but we didn’t need to change the SCM-Manager configuration at all to get that running. Looking at the logs the server was restarted several times yesterday as we wrestled with IIS but each time SCM-Server came up fine. This morning I installed the support plugin as requested and SCM-Server has not run successfully since.

I’ll zip up both D drive folders in their current state for later inspection but right now I have to get this server back up and running. If you have some advice on how to do that I’d appreciate it, otherwise I’ll probably have to rebuild the SCM-Server installation.

We’ve managed to get it going again. Turns out it was our fault but you’ll probably want to make sure nobody else falls into this trap.

My server guy just arrived and said he did actually make a configuration change to SCM-Server yesterday while he was trying to get the IIS reverse proxy to work. It was to the \conf\server-config.xml file he added

      <!-- for mod_proxy -->
      <Set name="forwarded">true</Set>

which he found on the documentation for reverse proxying for an earlier SCM-Manager version.

We’ve removed those lines and it started fine, plus our reverse proxying is still working too. I hope you can use this info to stop others from making this same mistake.

2 Likes

Hi, we added a header with a warning to sites that are outdated a few days ago. Maybe this wasn’t in place when your colleague found it. Currently we are struggling with Google a bit, so that it shows the latest pages, but that isn’t as straight forward as we would have liked. Thanks for the hint, though.

It was only yesterday so it would have been there. I think he was grasping at straws and so decided to try it out, perhaps thinking it had been accidentally omitted from the latest version of the docs.

I don’t know exactly what adding that parameter to the server-config.xml file does but I would imagine that a bunch of people who are migrating from older versions will have it set in there. Perhaps the software should either ignore or remove it when it encounters that setting.

1 Like