-
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
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:
