Issue with server upgraded to 5.6

[Segi]

I decided to finally update our production server from 5.5 to 5.6 today.

It is almost working correctly except for 1 issue that I'm having. When I start the Verj Windows service, Verj IO doesn't start properly.

If I run Verj as an application by running start_verjio_server.bat everything works correctly.

This is the output of the server error log when running the Verj service

Code: Select all

2020-01-19 19:02:33 Commons Daemon procrun stderr initialized
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by com.ebasetech.common.ReflectionUtil (file:/C:/VerjIO/Server/webapp/WEB-INF/lib/ufs.jar) to method sun.nio.fs.WindowsPath.register(java.nio.file.WatchService,java.nio.file.WatchEvent$Kind[],java.nio.file.WatchEvent$Modifier[])
WARNING: Please consider reporting this to the maintainers of com.ebasetech.common.ReflectionUtil
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
ache Tomcat/8.5.23
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built:          Sep 28 2017 10:30:11 UTC
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server number:         8.5.23.0
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name:               Windows Server 2012 R2
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version:            6.3
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture:          amd64
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home:             C:\VerjIO\jre
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version:           12.0.1+12
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor:            Oracle Corporation
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE:         C:\VerjIOData\tomcat
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME:         C:\VerjIO\Server\tomcat
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=C:\VerjIO\Server\winservice\..\tomcat
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=C:\VerjIOData\tomcat
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=C:\VerjIOData\tomcat\temp
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=C:\VerjIOData\tomcat\conf\logging.properties
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dverjio.server.home=C:\VerjIO\Server\winservice\..
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dverjio.server.userdata=C:\VerjIOData
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dderby.system.home=C:\VerjIOData\DB
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dfile.encoding=UTF-8
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: exit
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xms128m
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xmx2048m
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent Loaded APR based Apache Tomcat Native library [1.2.14] using APR version [1.6.2].
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true].
19-Jan-2020 19:02:34.324 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR/OpenSSL configuration: useAprConnector [false], useOpenSSL [true]
19-Jan-2020 19:02:35.356 INFO [main] org.apache.catalina.core.AprLifecycleListener.initializeSSL OpenSSL successfully initialized [OpenSSL 1.0.2l  25 May 2017]
19-Jan-2020 19:02:35.418 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["https-openssl-nio-443"]
19-Jan-2020 19:02:35.793 INFO [main] org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a shared selector for servlet write/read
19-Jan-2020 19:02:35.793 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-80"]
19-Jan-2020 19:02:35.793 INFO [main] org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a shared selector for servlet write/read
19-Jan-2020 19:02:35.793 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["ajp-nio-8009"]
19-Jan-2020 19:02:35.793 INFO [main] org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a shared selector for servlet write/read
19-Jan-2020 19:02:35.793 INFO [main] org.apache.catalina.startup.Catalina.load Initialization processed in 2208 ms
19-Jan-2020 19:02:35.903 INFO [main] com.ebasetech.tomcat.Logger.logInfo Starting Atomikos Transaction Manager 
19-Jan-2020 19:02:35.965 INFO [main] com.atomikos.logging.JULLogger.logInfo Loaded jar:file:/C:/VerjIO/Server/tomcat/lib/transactions-4.0.6.jar!/transactions-defaults.properties
19-Jan-2020 19:02:35.965 INFO [main] com.atomikos.logging.JULLogger.logInfo Loaded file:/C:/VerjIOData/tomcat/lib/jta.properties
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.tm_unique_name = 10.10.0.85.tm
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.default_jta_timeout = 10000
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.serial_jta_transactions = true
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: java.naming.factory.initial = com.sun.jndi.rmi.registry.RegistryContextFactory
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.oltp_retry_interval = 10000
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: java.naming.provider.url = rmi://localhost:1099
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.checkpoint_interval = 500
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.client_demarcation = false
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.trust_client_tm = false
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.force_shutdown_on_vm_exit = false
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.rmi_export_class = none
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.enable_logging = true
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.max_timeout = 2000000
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.registered = true
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.oltp_max_retries = 5
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.log_base_dir = C:\VerjIOData\tomcat/work
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.allow_subtransactions = true
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.automatic_resource_registration = true
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.log_base_name = tmlog
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.default_max_wait_time_on_shutdown = 9223372036854775807
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.forget_orphaned_log_entries_delay = 86400000
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.threaded_2pc = false
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.recovery_delay = 10000
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo USING: com.atomikos.icatch.max_actives = -1
19-Jan-2020 19:02:35.996 INFO [main] com.atomikos.logging.JULLogger.logInfo Using default (local) logging and recovery...
19-Jan-2020 19:02:36.059 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]
19-Jan-2020 19:02:36.059 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet Engine: Apache Tomcat/8.5.23
19-Jan-2020 19:02:36.074 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDescriptor Deploying configuration descriptor [C:\VerjIOData\tomcat\conf\Catalina\localhost\ufs.xml]
19-Jan-2020 19:02:36.153 INFO [localhost-startStop-1] com.ebasetech.tomcat.Logger.logInfo Starting Ebase webapp - ufs
19-Jan-2020 19:02:38.153 INFO [localhost-startStop-1] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
19-Jan-2020 19:02:38.419 INFO [localhost-startStop-1] com.ebasetech.tomcat.Logger.logInfo Adding datasource resource: /Catalina/localhost/ufs/EBASE_SAMPLES
19-Jan-2020 19:02:38.981 INFO [localhost-startStop-1] com.ebasetech.tomcat.Logger.logInfo Successfully tested connection to data source, /Catalina/localhost/ufs/EBASE_SAMPLES
19-Jan-2020 19:02:38.981 INFO [localhost-startStop-1] com.ebasetech.tomcat.Logger.logInfo Adding datasource resource: /Catalina/localhost/ufs/UFSREPOSITORY
19-Jan-2020 19:02:39.466 INFO [localhost-startStop-1] com.ebasetech.tomcat.Logger.logInfo Successfully tested connection to data source, /Catalina/localhost/ufs/UFSREPOSITORY
19-Jan-2020 19:02:46.659 SEVERE [localhost-startStop-1] org.apache.catalina.core.StandardContext.filterStart Exception starting filter [javamelody]
 java.lang.NoClassDefFoundError: Could not initialize class java.awt.Toolkit
	at java.desktop/java.awt.Color.<clinit>(Color.java:275)
	at net.bull.javamelody.internal.model.JRobin.<clinit>(JRobin.java:64)
	at net.bull.javamelody.FilterContext.initCollect(FilterContext.java:271)
	at net.bull.javamelody.FilterContext.<init>(FilterContext.java:133)
	at net.bull.javamelody.MonitoringFilter.init(MonitoringFilter.java:148)
	at org.apache.catalina.core.ApplicationFilterConfig.initFilter(ApplicationFilterConfig.java:285)
	at org.apache.catalina.core.ApplicationFilterConfig.getFilter(ApplicationFilterConfig.java:266)
	at org.apache.catalina.core.ApplicationFilterConfig.<init>(ApplicationFilterConfig.java:108)
	at org.apache.catalina.core.StandardContext.filterStart(StandardContext.java:4591)
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5233)
	at com.ebasetech.tomcat.EbaseContext.startInternal(EbaseContext.java:101)
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
	at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:752)
	at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:728)
	at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:734)
	at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:630)
	at org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:1842)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:835)

19-Jan-2020 19:02:46.659 SEVERE [localhost-startStop-1] org.apache.catalina.core.StandardContext.startInternal One or more Filters failed to start. Full details will be found in the appropriate container log file
19-Jan-2020 19:02:46.659 SEVERE [localhost-startStop-1] org.apache.catalina.core.StandardContext.startInternal Context [/ufs] startup failed due to previous errors
19-Jan-2020 19:02:47.612 INFO [localhost-startStop-1] com.atomikos.logging.JULLogger.logInfo atomikos connection pool '/Catalina/localhost/ufs/UFSREPOSITORY': destroying pool...
19-Jan-2020 19:02:47.628 WARNING [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [ufs] appears to have started a thread named [FileSystemWatchService] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.base@12.0.1/sun.nio.fs.WindowsNativeDispatcher.GetQueuedCompletionStatus0(Native Method)
 java.base@12.0.1/sun.nio.fs.WindowsNativeDispatcher.GetQueuedCompletionStatus(WindowsNativeDispatcher.java:1036)
 java.base@12.0.1/sun.nio.fs.WindowsWatchService$Poller.run(WindowsWatchService.java:587)
 java.base@12.0.1/java.lang.Thread.run(Thread.java:835)
19-Jan-2020 19:02:47.737 WARNING [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [ufs] appears to have started a thread named [Workspace File Watcher] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.base@12.0.1/jdk.internal.misc.Unsafe.park(Native Method)
 java.base@12.0.1/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
 java.base@12.0.1/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081)
 java.base@12.0.1/java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:483)
 java.base@12.0.1/java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:671)
 java.base@12.0.1/sun.nio.fs.AbstractWatchService.take(AbstractWatchService.java:118)
 com.ebasetech.ufs.kernel.FileWatcherService.processEvents(FileWatcherService.java:237)
 com.ebasetech.ufs.kernel.FileWatcherService.run(FileWatcherService.java:69)
19-Jan-2020 19:02:48.019 WARNING [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [ufs] appears to have started a thread named [Thread-9] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.base@12.0.1/java.util.HashMap.putVal(HashMap.java:626)
 java.base@12.0.1/java.util.HashMap.put(HashMap.java:607)
 com.lowagie.text.pdf.TrueTypeFont.readFormat4(Unknown Source)
 com.lowagie.text.pdf.TrueTypeFont.readCMaps(Unknown Source)
 com.lowagie.text.pdf.TrueTypeFont.process(Unknown Source)
 com.lowagie.text.pdf.TrueTypeFontUnicode.<init>(Unknown Source)
 com.lowagie.text.pdf.BaseFont.createFont(Unknown Source)
 com.lowagie.text.pdf.BaseFont.createFont(Unknown Source)
 com.lowagie.text.pdf.BaseFont.createFont(Unknown Source)
 com.ebasetech.ufs.validation.outbound.ITextFontResolver.addFont(ITextFontResolver.java:231)
 com.ebasetech.ufs.validation.outbound.ITextFontResolver.addFont(ITextFontResolver.java:224)
 com.ebasetech.ufs.validation.outbound.ITextFontResolver.addAddtionalFont(ITextFontResolver.java:101)
 com.ebasetech.ufs.validation.outbound.ITextFontResolver.addAdditionalFonts(ITextFontResolver.java:92)
 com.ebasetech.ufs.validation.outbound.ITextFontResolver.addAdditionalFonts(ITextFontResolver.java:86)
 com.ebasetech.ufs.validation.outbound.ITextFontResolver.addCommonFontDirectories(ITextFontResolver.java:111)
 com.ebasetech.ufs.validation.outbound.ITextFontResolver.preloadFonts(ITextFontResolver.java:52)
 com.ebasetech.ufs.kernel.UFSServletContextProxy$1.runTask(UFSServletContextProxy.java:267)
 com.ebasetech.ufs.kernel.UFSServletContextProxy$BackgroundLoaderThread.run(UFSServletContextProxy.java:918)
19-Jan-2020 19:02:48.456 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDescriptor Deployment of configuration descriptor [C:\VerjIOData\tomcat\conf\Catalina\localhost\ufs.xml] has finished in [12,382] ms
19-Jan-2020 19:02:48.472 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [C:\VerjIOData\tomcat\webapps\ROOT]
19-Jan-2020 19:02:48.534 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [C:\VerjIOData\tomcat\webapps\ROOT] has finished in [62] ms
19-Jan-2020 19:02:48.597 INFO [Thread-9] org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading Illegal access: this web application instance has been stopped already. Could not load [com.ebasetech.ufs.printing.PDFFontMapper]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
 java.lang.IllegalStateException: Illegal access: this web application instance has been stopped already. Could not load [com.ebasetech.ufs.printing.PDFFontMapper]. 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:1311)
	at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1299)
	at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1158)
	at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1119)
	at com.ebasetech.ufs.kernel.UFSServletContextProxy$1.runTask(UFSServletContextProxy.java:270)
	at com.ebasetech.ufs.kernel.UFSServletContextProxy$BackgroundLoaderThread.run(UFSServletContextProxy.java:918)

Exception in thread "Thread-9" java.lang.NoClassDefFoundError: com/ebasetech/ufs/printing/PDFFontMapper
	at com.ebasetech.ufs.kernel.UFSServletContextProxy$1.runTask(UFSServletContextProxy.java:270)
	at com.ebasetech.ufs.kernel.UFSServletContextProxy$BackgroundLoaderThread.run(UFSServletContextProxy.java:918)
Caused by: java.lang.ClassNotFoundException: Illegal access: this web application instance has been stopped already. Could not load [com.ebasetech.ufs.printing.PDFFontMapper]. 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:1301)
	at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1158)
	at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1119)
	... 2 more
Caused by: java.lang.IllegalStateException: Illegal access: this web application instance has been stopped already. Could not load [com.ebasetech.ufs.printing.PDFFontMapper]. 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:1311)
	at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1299)
	... 4 more
19-Jan-2020 19:02:48.597 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["https-openssl-nio-443"]
19-Jan-2020 19:02:48.612 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-80"]
19-Jan-2020 19:02:48.612 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["ajp-nio-8009"]
19-Jan-2020 19:02:48.628 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 12820 ms
19-Jan-2020 19:03:59.747 WARNING [https-openssl-nio-443-exec-3] org.apache.tomcat.util.buf.ByteBufferUtils.<clinit> Cannot use direct ByteBuffer cleaner, memory leaking may occur
 java.lang.IllegalAccessException: class org.apache.tomcat.util.buf.ByteBufferUtils cannot access class jdk.internal.ref.Cleaner (in module java.base) because module java.base does not export jdk.internal.ref to unnamed module @3b94d659
	at java.base/jdk.internal.reflect.Reflection.newIllegalAccessException(Reflection.java:355)
	at java.base/java.lang.reflect.AccessibleObject.checkAccess(AccessibleObject.java:639)
	at java.base/java.lang.reflect.Method.invoke(Method.java:559)
	at org.apache.tomcat.util.buf.ByteBufferUtils.<clinit>(ByteBufferUtils.java:49)
	at org.apache.tomcat.util.net.SocketBufferHandler.expand(SocketBufferHandler.java:155)
	at org.apache.tomcat.util.net.SecureNioChannel.processSNI(SecureNioChannel.java:320)
	at org.apache.tomcat.util.net.SecureNioChannel.handshake(SecureNioChannel.java:174)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1436)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.base/java.lang.Thread.run(Thread.java:835)

19-Jan-2020 19:05:56.610 INFO [Thread-12] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["https-openssl-nio-443"]
19-Jan-2020 19:05:56.641 INFO [Thread-12] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["http-nio-80"]
19-Jan-2020 19:05:56.720 INFO [Thread-12] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["ajp-nio-8009"]
19-Jan-2020 19:05:56.798 INFO [Thread-12] org.apache.catalina.core.StandardService.stopInternal Stopping service [Catalina]
19-Jan-2020 19:05:56.814 INFO [Thread-12] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["https-openssl-nio-443"]
19-Jan-2020 19:05:56.829 INFO [Thread-12] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["http-nio-80"]
19-Jan-2020 19:05:56.829 INFO [Thread-12] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["ajp-nio-8009"]
19-Jan-2020 19:05:56.845 INFO [Thread-12] com.ebasetech.tomcat.Logger.logInfo Shutting down Atomikos Transaction Manager
19-Jan-2020 19:05:56.845 INFO [Thread-12] com.atomikos.logging.JULLogger.logInfo Transaction Service: Entering shutdown (false, 9223372036854775807)...

[Ben]

Can you post the successful log, when starting with start_verjio_server.bat . We can look for differences.

How did you upgrade? Did you use the setup.exe?

[Segi]

I did the installation by installing 5.6 into a new directory and following the upgrade instructions.

This is the log from C:\VerjIOData\apps\logs\ebase-server.log

https://pastebin.com/YEy1kZxz

Can't paste it here, too long

Strangely, despite all of these errors, everything seems to work when running as an app

[Ben]

Can I see the log at C:\VerjIOData\tomcat\logs\catalina.log. These are normally dated, so the latest one.

The log you have posted doesn't look very happy. But I think it's all the same problem. The database connections are all read-only. I think that's normally because the process user doesn't have write access to the database files (at C:\VerjIOData\DB\UFS)

[Ben]

Because you said that the server started fine from start_verjio_server.bat, but not from the windows service, I'm hoping to see the startup log for each. I think that userdata\tomcat\logs\catalina.log is written for both start_verjio_server.bat and windows service. It's possible that this is all about file permissions.

[Segi]

Made some progress.

Adjusted file permissions on the DB folder and now when I start Verj as an application, the read only SQL DB message does not appear any more.

It's strange that there was a permission issue in the first place because I copied the DB folder from the old location (C:\VerjIO\UFSServer\DB) to the new location (C:\VerjIOData\DB) on the same server, meaning that I did not transfer files across different servers.

Verj still does not start up properly as a service. UI does not load at all even by visiting verj.example.com/ufs/ which should always show the docs page if Verj has started properly.

I will post the results of running Verj as an app and a service from catalina.log when I get a chance to start and stop the service after hours.

Thanks,

Segi

[Segi]

Sorry for the long delay but here's the log when starting Verj as a service:

https://pastebin.com/01i7E7PM

I wonder if the first SEVERE error "java.lang.NoClassDefFoundError: Could not initialize class java.awt.Toolkit" could be the source of the problem. The service starts but Verj is not accessible in the browser and returns a blank page with a 404 error when I visit our Verj instance URL in a browser.

[Ben]

Yes the NoClassDefFoundError is concerning. I wouldn't normally expect java.awt.Toolkit to be a problem on a Windows server. Normally this is seen on Linux servers without a graphics environment (for this we add -Djava.awt.headless=true to the start up parameters). I don't really know what would cause this on Windows. Perhaps a corrupt installation of java, or not enough user privileges. There's the "Allow service to interact with desktop" Windows service property. Verjio server runs fine on my WindowsServer2012R2 straight after installation.


You have said previously that it works when you use start_verjio_server.bat. If that is still the case, then seeing the catalina.log when run from the bat would give me more idea what is going on. (to do this: Stop the VerjIO service, delete or rename C:\VerjioData\tomcat\logs\catalina.???.log, run C:\VerjIO\Server\start_verjio_server.bat, see if the server is working, send me C:\VerjioData\tomcat\logs\catalina.???.log).

[Segi]

For what its worth, I previously tried adding -Djava.awt.headless=true to the Java startup params but still ran into this error.

[Segi]

Ben,

I've attached the logs when running Verj as a service vs running as an app

Thanks,

Segi

[Ben]

I can't see anything in the logs that would identify a problem. Both logs are using the same java, so it must be something about the service process that is causing the problem. I would probably install again using the setup.exe. You can either install to a different location on the same server to see if the service will boot up without error. Or take a copy of your UserData, uninstall and install. If it starts up OK, you can then stop the service, copy in your userdata and try again. You should be able to install a server using the setup.exe within a few minutes.

[Segi]

I tried again tonight and am not having any luck.

I backed up my existing app and user data, deleted the Windows service and did a completely fresh install of 3 different version of Verj 5.5, 5.6 and 5.7 (removing all previous data after each) without any of my existing app data or user data and am still unable to access Verj IO in my browser if I start it as a Windows service.

I get the same error about java.awt.Toolkit missing in the server logs. I am also getting a 404 error in the browser trying to access the Verj IO REST service /ufs/api/UserIsLoggedIn that I created in a Verj IO application called Login which contains the REST service that authenticates the user. I also get a 404 trying to access localhost/ufs where normally that displays the Verj IO docs page.

If I start the server for any of those 3 Verj IO versions by running the batch file, it works fine.

I also completely uninstalled the JRE that I had installed in Program Files to make sure that it wasn't interfering somehow.

I don't know what else to do at this point. Verj just refuses to work as a service any more.

[Ben]

5.5 used to work on this machine, didn't it?

Your logs are saying that java.awt.Toolkit is failing to load, via a call to Toolkit.loadLibraries(). Not a happy situation, and not one I can find any help for on the internet.

The windows service installation is only a thin wrapper around the apache tomcat service installation. We could try to eliminate Verj in order to see if this is just about tomcat. You can download apache-tomcat-8.5.23.exe from https://archive.apache.org/dist/tomcat/ ... 8/v8.5.23/ bin. It has options to chose ports, (which should be free) and start the windows service. If you make a jsp file with the following code and add it to Tomcat8.5/webapps/ROOT, it will test that the awt.Toolkit can load up. (e.g. http://localhost:8080/my.jsp).


<%@ page language="java" contentType="text/html; charset=US-ASCII" pageEncoding="US-ASCII"%>
<!DOCTYPE html PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN" "https://www.w3.org/TR/html4/loose.dtd">
<html>

<body>
<%=new java.util.Date() %><br>
<%=java.awt.Color.WHITE.toString()%><br>
<%=java.awt.Toolkit.getDefaultToolkit().toString()%><br>

</body>
</html>



Alternatively you can zip your whole installation up and send it to us. I can manually install it and the windows service. Somehow I suspect it will work for me though.

[Segi]

Sorry the long delay in response

I set up Apache 8.5.23 and dropped in the index.jsp code and this is the output:

Code: Select all

Wed Aug 05 11:12:30 PDT 2020
java.awt.Color[r=255,g=255,b=255]
sun.awt.windows.WToolkit@2529e438

It appears to be loading the AWT Toolkit correctly

That doesn't tell me why its not working or help me much other than Tomcat works fine natively and doesn't complain about AWT Toolkit.

[Ben]

OK thanks,

This could be a file permission thing. Your windows service is probably running as 'Local Service'. 'Local Service' will need access to the installation, java and userdata directories. You could either increase the power of the user, or give 'Local Service' full access to the verjio directories. The quick test is to change your windows service "Log On As" user to 'Local System'. It's not a great long term solution, but will be informative.

[Segi]

The service was already set to run as Local System.

I changed it to local service and made sure that Local Service has r/w permission on my verjIO and VerjIOdata folders but the problem still persists.

When this problem happens, https://intranet.example.com/ufs gives a 404 error instead of showing the docs page.

In addition to that, our login page is an Angular based web app. When you load the login page, it immediately calls a REST endpoint at https://intranet.example.com/ufs/api/UserIsLoggedIn/ which returns true if the user is already logged with Verj' login service. If this returns true, the user is automatically redirected to the main landing page.

When I run Verj as a service, the Chrome dev console shows this error:

Code: Select all

Call to isUserLoggedIn failed 
Object { headers: {…}, status: 404, statusText: "OK", url: "https://intranet.example.com/ufs/api/UserIsLoggedIn/", ok: false, name: "HttpErrorResponse", message: "Http failure response for https://intranet.example.com/ufs/api/UserIsLoggedIn/: 404 OK", error: "<!doctype html><html lang=\"en\"><head><title>HTTP Status 404 – Not Found</title><style type=\"text/css\">h1 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:22px;} h2 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:16px;} h3 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:14px;} body {font-family:Tahoma,Arial,sans-serif;color:black;background-color:white;} b {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;} p {font-family:Tahoma,Arial,sans-serif;background:white;color:black;font-size:12px;} a {color:black;} a.name {color:black;} .line {height:1px;background-color:#525D76;border:none;}</style></head><body><h1>HTTP Status 404 – Not Found</h1><hr class=\"line\" /><p><b>Type</b> Status Report</p><p><b>Message</b> /ufs/api/UserIsLoggedIn/</p><p><b>Description</b> The origin server did not find a current representation for the target resource or is not willing to disclose that one exists.</p><hr class=\"line\" /><h3>Apache Tomcat/8.5.23</h3></body></html>" }