Uploaded image for project: 'Artifactory Binary Repository'
  1. Artifactory Binary Repository
  2. RTFACT-27061

Artifactory service not stopping on Windows

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Open
    • Resolution: Unresolved
    • Affects Version/s: 7.37.14
    • Fix Version/s: None
    • Component/s: Artifactory
    • Labels:
    • Environment:

      Artifactory OSS 7.37.14 on Windows Server 2022 Standard 21H2

    • Severity:
      Medium
    • Location:
      External

      Description

      I have a fresh installation of Artifactory OSS 7.37.14 on Windows Server 2022 Standard 21H2.

      I set JFROG_HOME=E:\jfrog, unzipped jfrog-artifactory-oss-7.37.14-windows.zip to E:\jfrog and ran E:\jfrog\artifactory-oss-7.37.14\app\bin\InstallService.bat as an Administrator.
      The service starts and I can log into http://localhost:8082/

      When I now execute sc stop Artifactory I can see in Process Explorer that it shuts down most of the Processes under artifactory-service.exe, but not the java.exe running the tomcat catalina server.

      Before Shutdown:

      After Shutdown:

      If I now open http://localhost:8082/ it just shows the JFrog logo and loads for ever.
      The command sc query Artifactory allways returns the state 3 STOP_PENDING. Artifactory never fully shuts down. Also Artifactory cannot be restarted with sc start Artifactory since the service is already runnning.

      Once I manually kill the tomcat catalina java.exe the artifactory-service.exe terminates and everything is shutdown.

      If I try to stop Artifactory with artifactory.bat stop instead of sc stop Artifactory it results in exactly the same problems. This is the output:

      E:\>jfrog\artifactory-oss-7.37.14\app\bin\artifactory.bat stop
      ERFOLGREICH: Der Prozess "jf-router.exe" mit PID 5148 wurde beendet.
      ERFOLGREICH: Der Prozess "jf-metadata.exe" mit PID 5340 wurde beendet.
      ERFOLGREICH: Der Prozess "jf-observability.exe" mit PID 7556 wurde beendet.
      ERFOLGREICH: Der Prozess "jf-integration.exe" mit PID 3956 wurde beendet.
      ERFOLGREICH: Der Prozess "node.exe" mit PID 2288 wurde beendet.
      2022-05-03T12:58:25:25Z [INFO ] [artifactory.bat ] [main]- Stopping artifactory
      Using CATALINA_BASE:   "E:\jfrog\artifactory-oss-7.37.14\app\artifactory\tomcat"
      Using CATALINA_HOME:   "E:\jfrog\artifactory-oss-7.37.14\app\artifactory\tomcat"
      Using CATALINA_TMPDIR: "E:\jfrog\artifactory-oss-7.37.14\app\artifactory\tomcat\temp"
      Using JRE_HOME:        "E:\jfrog\artifactory-oss-7.37.14\app\third-party\java"
      Using CLASSPATH:       "E:\jfrog\artifactory-oss-7.37.14\app\artifactory\tomcat\bin\bootstrap.jar;E:\jfrog\artifactory-oss-7.37.14\app\artifactory\tomcat\bin\tomcat-juli.jar"
      Using CATALINA_OPTS:   "-server -Xms512m -Xmx2g -XX:+UseG1GC --add-opens java.base/java.util=ALL-UNNAMED --add-opens java.base/java.lang.reflect=ALL-UNNAMED --add-opens java.base/java.lang.invoke=ALL-UNNAMED --add-opens java.base/java.text=ALL-UNNAMED --add-opens java.base/java.nio=ALL-UNNAMED --add-opens java.desktop/java.awt.font=ALL-UNNAMED -Dfile.encoding=UTF8 -Djruby.compile.invokedynamic=false -Djruby.bytecode.version=1.8 -Dartdist=zip -Djf.product.home=E:\jfrog\artifactory-oss-7.37.14  -Dorg.apache.tomcat.util.buf.UDecoder.ALLOW_ENCODED_SLASH=true"
      

      If I start Artifactory manually with E:\jfrog\artifactory-oss-7.37.14\app\bin\artifactory.bat and then try to stop it from another Admin-CMD using E:\jfrog\artifactory-oss-7.37.14\app\bin\artifactory.bat stop it still has the same problems.
      Here is the output of Artifactory once I executed the stop command:

      2022-05-03T11:08:04.091Z ←[1;32m[jfrt ]←[0;39m ←[31m[WARN ]←[0;39m [                ] [.j.a.c.g.GrpcStreamObserver:88] [c-default-executor-2] - refreshing affected permissions stream - target server is unavailable
      2022-05-03T11:08:04.091Z ←[1;32m[jfrt ]←[0;39m ←[31m[WARN ]←[0;39m [                ] [.j.a.c.g.GrpcStreamObserver:88] [c-default-executor-1] - refreshing affected projects stream - target server is unavailable
      2022-05-03T11:08:04.091Z ←[1;32m[jfrt ]←[0;39m ←[31m[WARN ]←[0;39m [                ] [.j.a.c.g.GrpcStreamObserver:88] [c-default-executor-0] - refreshing affected platform config stream - target server is unavailable
      2022-05-03T11:08:04.091Z ←[1;32m[jfrt ]←[0;39m ←[31m[WARN ]←[0;39m [                ] [.j.a.c.g.GrpcStreamObserver:88] [c-default-executor-3] - refreshing affected platform config stream - target server is unavailable
      2022-05-03T13:08:05.387L ←[35m[tomct]←[0m [INFORMATION] [                ] [org.apache.catalina.core.StandardServer] [org.apache.catalina.core.StandardServer await] - A valid shutdown command was received via the shutdown port. Stopping the Server instance.
      2022-05-03T13:08:05.387L ←[35m[tomct]←[0m [INFORMATION] [                ] [org.apache.coyote.http11.Http11NioProtocol] [org.apache.coyote.AbstractProtocol pause] - Pausing ProtocolHandler ["http-nio-8081"]
      2022-05-03T13:08:05.418L ←[35m[tomct]←[0m [INFORMATION] [                ] [org.apache.coyote.http11.Http11NioProtocol] [org.apache.coyote.AbstractProtocol pause] - Pausing ProtocolHandler ["http-nio-127.0.0.1-8091"]
      2022-05-03T13:08:05.429L ←[35m[tomct]←[0m [INFORMATION] [                ] [org.apache.coyote.http11.Http11NioProtocol] [org.apache.coyote.AbstractProtocol pause] - Pausing ProtocolHandler ["http-nio-127.0.0.1-8040"]
      2022-05-03T13:08:05.430L ←[35m[tomct]←[0m [INFORMATION] [                ] [org.apache.catalina.core.StandardService] [org.apache.catalina.core.StandardService stopInternal] - Stopping service [Catalina]
      2022-05-03T11:08:05.449Z ←[1;32m[jfrt ]←[0;39m ←[34m[INFO ]←[0;39m [f5ad35ace71178df] [ifactoryApplicationContext:582] [Catalina-utility-2  ] - Artifactory application context set to NOT READY by destroy
      2022-05-03T11:08:05.457Z ←[1;32m[jfrt ]←[0;39m ←[34m[INFO ]←[0;39m [                ] [o.j.c.w.FileWatcher:217       ] [file-watcher-poller ] - Watch service ended on destroy
      2022-05-03T11:08:05.457Z ←[1;32m[jfrt ]←[0;39m ←[34m[INFO ]←[0;39m [f5ad35ace71178df] [ifactoryApplicationContext:398] [Catalina-utility-2  ] - Destroying 52 Artifactory Spring Beans
      2022-05-03T11:08:05.457Z ←[1;32m[jfrt ]←[0;39m ←[34m[INFO ]←[0;39m [                ] [o.j.c.w.FileWatcher:224       ] [file-watcher-poller ] - End watch of folder configurations
      2022-05-03T11:08:05.457Z ←[1;32m[jfrt ]←[0;39m ←[34m[INFO ]←[0;39m [f5ad35ace71178df] [askServiceDescriptorHandler:45] [Catalina-utility-2  ] - Removing all job Backup from task service handler.
      2022-05-03T11:08:05.457Z ←[1;32m[jfrt ]←[0;39m ←[34m[INFO ]←[0;39m [f5ad35ace71178df] [.w.NodeEventTaskManagerImpl:57] [Catalina-utility-2  ] - Removing dispatcher thread for operator 'metadata-operator-events'
      2022-05-03T11:08:05.457Z ←[1;32m[jfrt ]←[0;39m ←[34m[INFO ]←[0;39m [f5ad35ace71178df] [FeatureAdoptionServiceImpl:110] [Catalina-utility-2  ] - Stopped feature adoption service.
      2022-05-03T11:08:05.457Z ←[1;32m[jfrt ]←[0;39m ←[34m[INFO ]←[0;39m [f5ad35ace71178df] [askServiceDescriptorHandler:45] [Catalina-utility-2  ] - Removing all job Indexer from task service handler.
      2022-05-03T11:08:05.457Z ←[1;32m[jfrt ]←[0;39m ←[34m[INFO ]←[0;39m [f5ad35ace71178df] [askServiceDescriptorHandler:45] [Catalina-utility-2  ] - Removing all job Garbage Collector from task service handler.
      2022-05-03T11:08:05.473Z ←[1;32m[jfrt ]←[0;39m ←[34m[INFO ]←[0;39m [f5ad35ace71178df] [o.a.m.f.MetricsServiceImpl:265] [Catalina-utility-2  ] - Stopped metric service.
      2022-05-03T11:08:05.473Z ←[1;32m[jfrt ]←[0;39m ←[34m[INFO ]←[0;39m [f5ad35ace71178df] [askServiceDescriptorHandler:45] [Catalina-utility-2  ] - Removing all job Artifact Cleanup from task service handler.
      2022-05-03T11:08:09.559Z ←[1;32m[jfrt ]←[0;39m ←[1;31m[ERROR]←[0;39m [f5ad35ace71178df] [ifactoryApplicationContext:409] [Catalina-utility-2  ] - Exception while destroying org.artifactory.state.model.ArtifactoryStateManager (UNAVAILABLE: io exception).
      2022-05-03T11:08:09.559Z ←[1;32m[jfrt ]←[0;39m ←[31m[WARN ]←[0;39m [f5ad35ace71178df] [.AsyncWorkQueueServiceImpl:219] [Catalina-utility-2  ] - Work queue job await termination ended unsuccessfully
      2022-05-03T11:08:09.559Z ←[1;32m[jfrt ]←[0;39m ←[34m[INFO ]←[0;39m [f5ad35ace71178df] [actorySchedulerFactoryBean:847] [Catalina-utility-2  ] - Shutting down Quartz Scheduler
      2022-05-03T11:08:09.574Z ←[1;32m[jfrt ]←[0;39m ←[34m[INFO ]←[0;39m [f5ad35ace71178df] [a.e.ShiftEventsServiceImpl:147] [Catalina-utility-2  ] - Shutdown terminated: true
      2022-05-03T11:08:09.574Z ←[1;32m[jfrt ]←[0;39m ←[31m[WARN ]←[0;39m [f5ad35ace71178df] [c.z.h.u.DriverDataSource:70   ] [Catalina-utility-2  ] - Registered driver with driverClassName=org.apache.derby.jdbc.EmbeddedDriver was not found, trying direct instantiation.
      2022-05-03T13:08:09.715L ←[35m[tomct]←[0m [INFORMATION] [                ] [org.apache.coyote.http11.Http11NioProtocol] [org.apache.coyote.AbstractProtocol stop] - Stopping ProtocolHandler ["http-nio-8081"]
      2022-05-03T13:08:09.731L ←[35m[tomct]←[0m [INFORMATION] [                ] [org.apache.coyote.http11.Http11NioProtocol] [org.apache.coyote.AbstractProtocol stop] - Stopping ProtocolHandler ["http-nio-127.0.0.1-8091"]
      2022-05-03T13:08:09.746L ←[35m[tomct]←[0m [INFORMATION] [                ] [org.apache.coyote.http11.Http11NioProtocol] [org.apache.coyote.AbstractProtocol stop] - Stopping ProtocolHandler ["http-nio-127.0.0.1-8040"]
      2022-05-03T13:08:09.762L ←[35m[tomct]←[0m [INFORMATION] [                ] [org.apache.coyote.http11.Http11NioProtocol] [org.apache.coyote.AbstractProtocol destroy] - Destroying ProtocolHandler ["http-nio-8081"]
      2022-05-03T13:08:09.762L ←[35m[tomct]←[0m [INFORMATION] [                ] [org.apache.coyote.http11.Http11NioProtocol] [org.apache.coyote.AbstractProtocol destroy] - Destroying ProtocolHandler ["http-nio-127.0.0.1-8091"]
      2022-05-03T13:08:09.762L ←[35m[tomct]←[0m [INFORMATION] [                ] [org.apache.coyote.http11.Http11NioProtocol] [org.apache.coyote.AbstractProtocol destroy] - Destroying ProtocolHandler ["http-nio-127.0.0.1-8040"]
      Exception in thread "grpc-nio-worker-ELG-1-1" Exception in thread "grpc-nio-worker-ELG-1-2" java.lang.NoClassDefFoundError: io/netty/buffer/PoolArena$1
              at io.netty.buffer.PoolArena.freeChunk(PoolArena.java:247)
              at io.netty.buffer.PoolThreadCache$MemoryRegionCache.freeEntry(PoolThreadCache.java:432)
              at io.netty.buffer.PoolThreadCache$MemoryRegionCache.free(PoolThreadCache.java:396)
              at io.netty.buffer.PoolThreadCache$MemoryRegionCache.free(PoolThreadCache.java:388)
              at io.netty.buffer.PoolThreadCache.free(PoolThreadCache.java:254)
              at io.netty.buffer.PoolThreadCache.free(PoolThreadCache.java:245)
              at io.netty.buffer.PoolThreadCache.free(PoolThreadCache.java:218)
              at io.netty.buffer.PooledByteBufAllocator$PoolThreadLocalCache.onRemoval(PooledByteBufAllocator.java:534)
              at io.netty.buffer.PooledByteBufAllocator$PoolThreadLocalCache.onRemoval(PooledByteBufAllocator.java:501)
              at io.netty.util.concurrent.FastThreadLocal.remove(FastThreadLocal.java:257)
              at io.netty.util.concurrent.FastThreadLocal.removeAll(FastThreadLocal.java:67)
              at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:1039)
              at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
              at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
              at java.base/java.lang.Thread.run(Thread.java:829)
      java.lang.NoClassDefFoundError: io/netty/buffer/PoolArena$1
              at io.netty.buffer.PoolArena.freeChunk(PoolArena.java:247)
              at io.netty.buffer.PoolThreadCache$MemoryRegionCache.freeEntry(PoolThreadCache.java:432)
              at io.netty.buffer.PoolThreadCache$MemoryRegionCache.free(PoolThreadCache.java:396)
              at io.netty.buffer.PoolThreadCache$MemoryRegionCache.free(PoolThreadCache.java:388)
              at io.netty.buffer.PoolThreadCache.free(PoolThreadCache.java:254)
              at io.netty.buffer.PoolThreadCache.free(PoolThreadCache.java:245)
              at io.netty.buffer.PoolThreadCache.free(PoolThreadCache.java:218)
              at io.netty.buffer.PooledByteBufAllocator$PoolThreadLocalCache.onRemoval(PooledByteBufAllocator.java:534)
              at io.netty.buffer.PooledByteBufAllocator$PoolThreadLocalCache.onRemoval(PooledByteBufAllocator.java:501)
              at io.netty.util.concurrent.FastThreadLocal.remove(FastThreadLocal.java:257)
              at io.netty.util.concurrent.FastThreadLocal.removeAll(FastThreadLocal.java:67)
              at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:1039)
              at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
              at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
              at java.base/java.lang.Thread.run(Thread.java:829)
      Caused by: java.lang.ClassNotFoundException: Illegal access: this web application instance has been stopped already. Could not load [io.netty.buffer.PoolArena$1]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
              at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1417)
              at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1254)
              at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1215)
              ... 15 more
      Caused by: java.lang.IllegalStateException: Illegal access: this web application instance has been stopped already. Could not load [io.netty.buffer.PoolArena$1]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
              at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading(WebappClassLoaderBase.java:1427)
              at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1415)
              ... 17 more
      

      And then once I kill the java.exe:

      2022-05-03T13:09:53:30Z [INFO ] [artifactory.bat ] [main]- Starting graceful shutdown
      FEHLER: Der Prozess "node.exe" wurde nicht gefunden.
      2022-05-03T13:09:54:30Z [INFO ] [artifactory.bat ] [main]- Stopping artifactory
      Using CATALINA_BASE:   "E:\jfrog\artifactory-oss-7.37.14\app\artifactory\tomcat"
      Using CATALINA_HOME:   "E:\jfrog\artifactory-oss-7.37.14\app\artifactory\tomcat"
      Using CATALINA_TMPDIR: "E:\jfrog\artifactory-oss-7.37.14\app\artifactory\tomcat\temp"
      Using JRE_HOME:        "E:\jfrog\artifactory-oss-7.37.14\app\third-party\java"
      Using CLASSPATH:       "E:\jfrog\artifactory-oss-7.37.14\app\artifactory\tomcat\bin\bootstrap.jar;E:\jfrog\artifactory-oss-7.37.14\app\artifactory\tomcat\bin\tomcat-juli.jar"
      Using CATALINA_OPTS:   "-server -Xms512m -Xmx2g -XX:+UseG1GC --add-opens java.base/java.util=ALL-UNNAMED --add-opens java.base/java.lang.reflect=ALL-UNNAMED --add-opens java.base/java.lang.invoke=ALL-UNNAMED --add-opens java.base/java.text=ALL-UNNAMED --add-opens java.base/java.nio=ALL-UNNAMED --add-opens java.desktop/java.awt.font=ALL-UNNAMED -Dfile.encoding=UTF8 -Djruby.compile.invokedynamic=false -Djruby.bytecode.version=1.8 -Dartdist=zip -Djf.product.home=E:\jfrog\artifactory-oss-7.37.14  -Dorg.apache.tomcat.util.buf.UDecoder.ALLOW_ENCODED_SLASH=true"
      

      It seems I am not the only person with this problem: https://stackoverflow.com/questions/71563828/artifactory-service-not-stopping-on-windows

      Some other weird things I observed:

      • Some of the log entries are apparently in the wrong timezone. I am in UTC+01:00 and it is just after 13:00. Some of the lines in the last output are correctly at 13:09:53 for example, but some are incorrectly at 11:08:09 for example, which is 2 hours of.
      • When I try to view the logs in the UI via http://localhost:8082/ui/admin/monitoring/system_logs the page loads forever with a green circle:

        Attachments

          Activity

              People

              Assignee:
              Unassigned
              Reporter:
              Adrodoc Adrodoc
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

                Dates

                Created:
                Updated:

                  Sync Status

                  Connection: RTFACT Sync
                  RTMID-27125 -
                  SYNCHRONIZED
                  • Last Sync Date: