CMDBuild Forum

Application loading indefinitely after update to 3.1.1 from 3.1

Hello,
I just installed the 3.1.1 update, and now the Application is loading indefinitely after logging in (logging in works without problems. I looked into the logs and found this in cmdbuild.sys:

2019-10-04 10:24:25.192 [req:59289e] WARN  o.c.w.f.RequestTrackingFilter$$EnhancerBySpringCGLIB$$70555f19 - processed request, returned error for requestId = 59289e87440a44188zxp2al5

2019-10-04 10:24:25.193 [req:0e7f90] WARN o.c.w.f.RequestTrackingFilter$$EnhancerBySpringCGLIB$$70555f19 - processed request, returned error for requestId = 0e7f90135138454215f3e4oo
2019-10-04 10:24:25.196 [req:f8ac1a] WARN o.c.w.f.RequestTrackingFilter$$EnhancerBySpringCGLIB$$70555f19 - processed request, returned error for requestId = f8ac1ad70a274be3jmt1e7fj
2019-10-04 10:24:25.198 [req:2af231] WARN o.c.w.f.RequestTrackingFilter$$EnhancerBySpringCGLIB$$70555f19 - processed request, returned error for requestId = 2af231e2bae54881107tztfz
2019-10-04 10:24:25.197 [req:4cc639] WARN o.c.w.f.RequestTrackingFilter$$EnhancerBySpringCGLIB$$70555f19 - processed request, returned error for requestId = 4cc639b9d0034663xwi9p3sb
2019-10-04 10:24:25.214 [req:a9182c] WARN o.c.w.f.RequestTrackingFilter$$EnhancerBySpringCGLIB$$70555f19 - processed request, returned error for requestId = a9182c22eb8146c7xpwg0r4y
2019-10-04 10:24:25.412 [req:b6defc] WARN o.c.w.f.RequestTrackingFilter$$EnhancerBySpringCGLIB$$70555f19 - processed request, returned error for requestId = b6defc5f4f334282cdwp5548
2019-10-04 10:24:25.417 [req:9b2d48] WARN o.c.w.f.RequestTrackingFilter$$EnhancerBySpringCGLIB$$70555f19 - processed request, returned error for requestId = 9b2d480fe0c24c7f8g08wcyj
2019-10-04 10:25:00.015 [job:sysmonServiceImpl_logSystemStatus_2dfhsjla3tcobsm3btyaza6yy03] WARN o.cmdbuild.sysmon.SysmonServiceImpl - CMO: WARNING: high cpu load, loadavg = 1.31, loadavg/cpu = 1.31
2019-10-04 10:25:00.048 [system] WARN o.c.r.impl.RequestContextServiceImpl - invoked getRequestContext(), but there is no request context set on this thread! generating sys request context = RequestContext{id=sys_org.cmdbuild.sysnoti_cn5y2vz957vq554zrtczpyox}
2019-10-04 10:25:00.049 [system] WARN o.c.r.impl.RequestContextServiceImpl - invoked getRequestContext(), but there is no request context set on this thread! generating sys request context = RequestContext{id=sys_org.cmdbuild.sysnoti_myyg6r3ep16lwz6uffjxluyf}
2019-10-04 10:26:00.014 [job:sysmonServiceImpl_logSystemStatus_2dfhsjla3tcobsm3btyaza6yy03] WARN o.cmdbuild.sysmon.SysmonServiceImpl - CMO: WARNING: high cpu load, loadavg = 1.29, loadavg/cpu = 1.29

Any ideas why this might be happening? I’m return to the old version for now.

Hi, can you please attach the requests that go in error? Also what are the details of the hardware and software you are using to run CMDBuild?

Thank you for replying :slight_smile:

What do you mean by “attaching the request”? I get these errors as soon as the application loads when i’m logged in, I can’t do anything else. In cmdbuild_req.log are the same errors I found in cmdbuild_sys.log.

I’m running psql 9.6.15 and cmdbuild 3.1.1.
It’s a virtual server with 4 cores and 4GB RAM.

Hi, i have the same problem with both installations (demo / empty) i can log in into CMDBuild normally but then i also only get the loading wheel. In my browser consolt i can see the following errors:
grafik
i also get those error entries in the log.

1 Like

Hi, can you please try deleting your browser cache and your browser cookies?

Hi, i just tried it again after clearing my browser cache. I also tried it with a fresh installed browser (firefox) but still no luck

1 Like

Hello, strangely it only worked while still using the old “session” with cookies and the cache, when I tried it with freshly installed firefox it didn’t work at all.

Hope this adds some clue.
I believe it’s about this:
org.springframework.security.authentication.InsufficientAuthenticationException: Full authentication is required to access this resource
I tried several installation and i can only see a bounch of these in tomcat/cmdbuild.log:
2019-10-07 05:50:19.247 [req:188eb3] WARN o.c.w.f.RequestTrackingFilter$$EnhancerBySpringCGLIB$$c53f45a7 - processed request, returned error for requestId = 188eb3dtxmqlcwhhg0gojh1a
2019-10-07 05:50:22.227 [req:ufwj0y] WARN o.c.w.f.RequestTrackingFilter$$EnhancerBySpringCGLIB$$c53f45a7 - processed request, returned error for requestId = ufwj0yg2y3r017x6w0vbg95f
2019-10-07 05:50:24.934 [req:8fkx0v] WARN o.c.w.f.RequestTrackingFilter$$EnhancerBySpringCGLIB$$c53f45a7 - processed request, returned error for requestId = 8fkx0vbdxtsyy7yq2rg6fd41
2019-10-07 05:59:06.256 [req:v98h76] WARN o.c.w.f.RequestTrackingFilter$$EnhancerBySpringCGLIB$$c53f45a7 - processed request, returned error for requestId = v98h76379r94zojp8y741myc

Long shot here but i saw that in the new features the cookie management has been offloaded to tomcat, maybe there is some leftover of the previous code?

Giuseppe

I now set up a dev environment where I can properly test the update.

Upon further investigation I found that this is the main error:

“org.springframework.security.authentication.InsufficientAuthenticationException: Full authentication is required to access this resource”

screenshot

Can you please check in the cmdbuild.log file if there are any errors on the web apllication startup? Can you also attach here the log file?

Hello, I checked the cmdbuild.log file while restarting and there are no errors. There is still the error when loading the application as described in the main post and by @giuseppe.urso.

Here my log file cut off from when I started the update: cmdbuild.log (517.0 KB)

As per previous post, here is the second part of the log:

2019-10-07 07:12:49.603 [system] INFO  o.s.s.web.DefaultSecurityFilterChain - Creating filter chain: OrRequestMatcher [requestMatchers=[Ant [pattern='/services/rest/v*/sessions/**'], Ant [pattern='/services/custom-login'], Ant [pattern='/services/custom-login/**']]], [org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter@45e7d7c, org.springframework.security.web.context.SecurityContextPersistenceFilter@3db9c7d3, org.springframework.security.web.header.HeaderWriterFilter@7bfbf16d, org.springframework.web.filter.CorsFilter@6efb54fc, org.cmdbuild.webapp.security.LenientSessionTokenFilter@59546def, org.springframework.security.web.savedrequest.RequestCacheAwareFilter@634a369b, org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter@479ed306, org.springframework.security.web.authentication.AnonymousAuthenticationFilter@32d0960f, org.springframework.security.web.session.SessionManagementFilter@15207154, org.springframework.security.web.access.ExceptionTranslationFilter@5d707ba4, org.springframework.security.web.access.intercept.FilterSecurityInterceptor@42d53755]
2019-10-07 07:12:49.607 [system] INFO  o.s.s.web.DefaultSecurityFilterChain - Creating filter chain: Ant [pattern='/services/**'], [org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter@f5a7d1c, org.springframework.security.web.context.SecurityContextPersistenceFilter@1e5ee4b2, org.springframework.security.web.header.HeaderWriterFilter@6d6a3f1c, org.springframework.web.filter.CorsFilter@18e17c, org.cmdbuild.webapp.security.SessionTokenFilter@8330b3a, org.springframework.security.web.savedrequest.RequestCacheAwareFilter@4c59bdeb, org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter@70f7f9a3, org.springframework.security.web.authentication.AnonymousAuthenticationFilter@fc7c06f, org.springframework.security.web.session.SessionManagementFilter@4e71b2c7, org.springframework.security.web.access.ExceptionTranslationFilter@3d6df70d, org.springframework.security.web.access.intercept.FilterSecurityInterceptor@64bc79fa]
2019-10-07 07:12:49.630 [system] INFO  o.s.s.web.DefaultSecurityFilterChain - Creating filter chain: org.springframework.security.web.util.matcher.AnyRequestMatcher@1, [org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter@15b303c5, org.springframework.security.web.context.SecurityContextPersistenceFilter@5c69fa4e, org.springframework.security.web.header.HeaderWriterFilter@6c93950a, org.springframework.security.web.authentication.logout.LogoutFilter@41c922d8, org.cmdbuild.webapp.security.UiSessionTokenFilter@3ef47b7c, org.springframework.security.web.savedrequest.RequestCacheAwareFilter@10249b2, org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter@71c9a75d, org.springframework.security.web.authentication.AnonymousAuthenticationFilter@2195ac3c, org.springframework.security.web.session.SessionManagementFilter@488c32ae, org.springframework.security.web.access.ExceptionTranslationFilter@5201e6ef, org.springframework.security.web.access.intercept.FilterSecurityInterceptor@5dd2bee]
2019-10-07 07:12:49.755 [system] INFO  o.cmdbuild.minions.SystemServiceImpl - spring context is ready
2019-10-07 07:12:49.757 [sys:boot] INFO  o.cmdbuild.minions.SystemServiceImpl - start system
2019-10-07 07:12:49.764 [system] INFO  o.s.web.context.ContextLoader - Root WebApplicationContext: initialization completed in 18525 ms
2019-10-07 07:12:49.774 [sys:boot] INFO  o.c.config.service.ConfigServiceImpl - init config beans
2019-10-07 07:12:49.908 [sys:boot] INFO  o.cmdbuild.minions.MinionServiceImpl - loading 14 system services
2019-10-07 07:12:49.916 [sys:boot] INFO  o.c.c.s.ConfigChangeNotifierService - init 16 config change listeners
2019-10-07 07:12:49.926 [sys:boot] INFO  o.c.config.service.ConfigServiceImpl - load config from files
2019-10-07 07:12:49.952 [sys:boot] WARN  o.c.c.s.FilesystemConfigRepositoryImpl - config files backup error
java.io.FileNotFoundException: /opt/tomcat/conf/ROOT/backup/config_files_2019-10-07_07-12-49/database.conf (No such file or directory)
	at java.io.FileOutputStream.open0(Native Method) ~[na:1.8.0_222]
	at java.io.FileOutputStream.open(FileOutputStream.java:270) ~[na:1.8.0_222]
	at java.io.FileOutputStream.<init>(FileOutputStream.java:213) ~[na:1.8.0_222]
	at com.google.common.io.Files$FileByteSink.openStream(Files.java:214) ~[guava-23.0.jar:na]
	at com.google.common.io.Files$FileByteSink.openStream(Files.java:202) ~[guava-23.0.jar:na]
	at com.google.common.io.ByteSource.copyTo(ByteSource.java:268) ~[guava-23.0.jar:na]
	at com.google.common.io.Files.copy(Files.java:325) ~[guava-23.0.jar:na]
	at org.cmdbuild.config.service.FilesystemConfigRepositoryImpl.lambda$backupConfigFiles$4(FilesystemConfigRepositoryImpl.java:130) [cmdbuild-core-config-3-SNAPSHOT.jar:na]
	at org.cmdbuild.utils.lang.LambdaExceptionUtils.lambda$rethrowConsumer$0(LambdaExceptionUtils.java:56) ~[cmdbuild-utils-lang-3-SNAPSHOT.jar:na]
	at java.util.ArrayList.forEach(ArrayList.java:1257) ~[na:1.8.0_222]
	at org.cmdbuild.config.service.FilesystemConfigRepositoryImpl.backupConfigFiles(FilesystemConfigRepositoryImpl.java:128) [cmdbuild-core-config-3-SNAPSHOT.jar:na]
	at org.cmdbuild.config.service.FilesystemConfigRepositoryImpl.getConfigEntries(FilesystemConfigRepositoryImpl.java:80) [cmdbuild-core-config-3-SNAPSHOT.jar:na]
	at org.cmdbuild.config.service.ConfigRepositoryFacadeImpl.loadConfigFromFiles(ConfigRepositoryFacadeImpl.java:48) [cmdbuild-core-config-3-SNAPSHOT.jar:na]
	at org.cmdbuild.config.service.ConfigServiceImpl$2.handleSystemLoadingConfigFilesEvent(ConfigServiceImpl.java:111) [cmdbuild-core-config-3-SNAPSHOT.jar:na]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_222]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_222]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_222]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_222]
	at com.google.common.eventbus.Subscriber.invokeSubscriberMethod(Subscriber.java:91) [guava-23.0.jar:na]
	at com.google.common.eventbus.Subscriber$SynchronizedSubscriber.invokeSubscriberMethod(Subscriber.java:150) [guava-23.0.jar:na]
	at com.google.common.eventbus.Subscriber$1.run(Subscriber.java:76) [guava-23.0.jar:na]
	at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:399) [guava-23.0.jar:na]
	at com.google.common.eventbus.Subscriber.dispatchEvent(Subscriber.java:71) [guava-23.0.jar:na]
	at com.google.common.eventbus.Dispatcher$PerThreadQueuedDispatcher.dispatch(Dispatcher.java:116) [guava-23.0.jar:na]
	at com.google.common.eventbus.EventBus.post(EventBus.java:217) [guava-23.0.jar:na]
	at java.util.Optional.ifPresent(Optional.java:159) ~[na:1.8.0_222]
	at org.cmdbuild.minions.SystemServiceImpl.setSystemStatus(SystemServiceImpl.java:239) ~[cmdbuild-core-all-3-SNAPSHOT.jar:na]
	at org.cmdbuild.minions.SystemServiceImpl.runNextStep(SystemServiceImpl.java:207) ~[cmdbuild-core-all-3-SNAPSHOT.jar:na]
	at org.cmdbuild.minions.SystemServiceImpl.runNextStep(SystemServiceImpl.java:208) ~[cmdbuild-core-all-3-SNAPSHOT.jar:na]
	at org.cmdbuild.minions.SystemServiceImpl.lambda$handleContextRefresh$0(SystemServiceImpl.java:138) ~[cmdbuild-core-all-3-SNAPSHOT.jar:na]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_222]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_222]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[na:1.8.0_222]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[na:1.8.0_222]
	at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_222]
2019-10-07 07:12:50.037 [sys:boot] INFO  o.c.d.d.ConfigurableDataSourceImpl - postgres driver = org.postgresql.Driver
2019-10-07 07:12:50.037 [sys:boot] INFO  o.c.d.d.ConfigurableDataSourceImpl - postgres driver version = PostgreSQL JDBC Driver 42.2.5
2019-10-07 07:12:50.038 [sys:boot] INFO  o.c.d.d.ConfigurableDataSourceImpl - configure datasource with url = jdbc:postgresql://10.0.0.36:5432/cmdbuild with user = cmdbuild
2019-10-07 07:12:50.141 [sys:boot] INFO  o.c.d.d.ConfigurableDataSourceImpl - postgres server version = 9.6.10
2019-10-07 07:12:50.420 [sys:boot] INFO  o.cmdbuild.minions.SystemServiceImpl -



	system is CHECKING_DATABASE



2019-10-07 07:12:50.421 [sys:boot] INFO  o.cmdbuild.minions.SystemServiceImpl - check patch manager
2019-10-07 07:12:50.438 [sys:boot] INFO  o.cmdbuild.minions.SystemServiceImpl -



	system is LOADING_CONFIG



2019-10-07 07:12:50.438 [sys:boot] INFO  o.c.config.service.ConfigServiceImpl - load config from db
2019-10-07 07:12:50.462 [sys:boot] INFO  o.cmdbuild.minions.SystemServiceImpl -



	system is STARTING_SERVICES



2019-10-07 07:12:50.462 [sys:boot] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - run PostStartup method clusterServiceImpl#startIfEnabled
2019-10-07 07:12:50.462 [sys:boot] INFO  o.c.cluster.ClusterServiceImpl - clustering is disabled
2019-10-07 07:12:50.462 [sys:boot] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - run PostStartup method platformServiceImpl#fixPermissions
2019-10-07 07:12:50.463 [sys:boot] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - run PostStartup method rawDataSource#checkAndConfigureSqlLogger
2019-10-07 07:12:50.463 [sys:boot] INFO  o.c.d.d.ConfigurableDataSourceImpl - enable sql logger
2019-10-07 07:12:50.469 [sys:boot] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - run PostStartup method multitenantServiceImpl#check
2019-10-07 07:12:50.470 [sys:boot] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - run PostStartup method jasperReportContextServiceImpl#loadJasperReportsContext
2019-10-07 07:12:51.647 [sys:boot] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - run PostStartup method sharkWebserviceClientImpl#startSharkWsClient
2019-10-07 07:12:51.649 [sys:boot] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - run PostStartup method planServiceDelegateSupplierImpl#loadConfig
2019-10-07 07:12:51.650 [sys:boot] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - run PostStartup method workflowServiceDelegates#loadConfig
2019-10-07 07:12:51.652 [sys:boot] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - run PostStartup method databaseStatusServiceImpl#init
2019-10-07 07:12:51.661 [sys:boot] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - run PostStartup method easyuploadLoaderService#checkUploadsFolderAndLoadContent
2019-10-07 07:12:51.662 [sys:boot] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - run PostStartup method easyuploadFtpService#startFtpServerIfEnabled
2019-10-07 07:12:51.663 [sys:boot] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - run PostStartup method logbackConfigServiceImpl#init
2019-10-07 07:12:51.691 [sys:boot] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - run PostStartup method sysmonServiceImpl#logSystemInfo
2019-10-07 07:12:51.692 [sys:boot] INFO  o.cmdbuild.sysmon.SysmonServiceImpl - default charset = UTF-8
2019-10-07 07:12:51.692 [sys:boot] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - run PostStartup method schedulerServiceImpl#startup
2019-10-07 07:12:51.692 [sys:boot] INFO  o.c.s.quartz.SchedulerServiceImpl - start quartz service
2019-10-07 07:12:51.692 [sys:boot] INFO  o.c.s.quartz.SchedulerServiceImpl - preparing quartz scheduler with job sources = core,jobs
2019-10-07 07:12:51.755 [sys:boot] INFO  org.quartz.impl.StdSchedulerFactory - Using default implementation for ThreadExecutor
2019-10-07 07:12:51.774 [sys:boot] INFO  o.quartz.core.SchedulerSignalerImpl - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
2019-10-07 07:12:51.775 [sys:boot] INFO  org.quartz.core.QuartzScheduler - Quartz Scheduler v.2.2.2 created.
2019-10-07 07:12:51.777 [sys:boot] INFO  o.q.impl.jdbcjobstore.JobStoreTX - Using db table-based data access locking (synchronization).
2019-10-07 07:12:51.779 [sys:boot] INFO  o.q.impl.jdbcjobstore.JobStoreTX - JobStoreTX initialized.
2019-10-07 07:12:51.781 [sys:boot] INFO  org.quartz.core.QuartzScheduler - Scheduler meta-data: Quartz Scheduler (v2.2.2) 'CMDBuildScheduler' with instanceId 'cmdbuild_cmdbuild-test_3555'
  Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
  NOT STARTED.
  Currently in standby mode.
  Number of jobs executed: 0
  Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 5 threads.
  Using job-store 'org.quartz.impl.jdbcjobstore.JobStoreTX' - which supports persistence. and is clustered.

2019-10-07 07:12:51.781 [sys:boot] INFO  org.quartz.impl.StdSchedulerFactory - Quartz scheduler 'CMDBuildScheduler' initialized from an externally provided properties instance.
2019-10-07 07:12:51.781 [sys:boot] INFO  org.quartz.impl.StdSchedulerFactory - Quartz scheduler version: 2.2.2
2019-10-07 07:12:51.783 [sys:boot] INFO  org.quartz.core.QuartzScheduler - JobFactory set to: org.cmdbuild.scheduler.quartz.SchedulerServiceImpl$MyJobFactory@22847ad3
2019-10-07 07:12:51.812 [sys:boot] INFO  o.c.s.quartz.SchedulerServiceImpl - check status of 10 configured jobs
2019-10-07 07:12:51.863 [sys:boot] INFO  o.c.s.quartz.SchedulerServiceImpl - start scheduler
2019-10-07 07:12:51.868 [sys:boot] INFO  o.q.impl.jdbcjobstore.JobStoreTX - ClusterManager: detected 1 failed or restarted instances.
2019-10-07 07:12:51.869 [sys:boot] INFO  o.q.impl.jdbcjobstore.JobStoreTX - ClusterManager: Scanning for instance "cmdbuild_cmdbuild-test_1720"'s failed in-progress jobs.
2019-10-07 07:12:51.884 [sys:boot] INFO  org.quartz.core.QuartzScheduler - Scheduler CMDBuildScheduler_$_cmdbuild_cmdbuild-test_3555 started.
2019-10-07 07:12:51.886 [sys:boot] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - run PostStartup method bimserverClientServiceImpl#init
2019-10-07 07:12:51.887 [sys:boot] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - run PostStartup method databaseHousekeepingService#runDatabaseHousekeepingAtStartup
2019-10-07 07:12:51.887 [sys:boot] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - run PostStartup method postgresDateServiceImpl#printInfo
2019-10-07 07:12:51.891 [system] INFO  o.q.impl.jdbcjobstore.JobStoreTX - Handling 1 trigger(s) that missed their scheduled fire-time.
2019-10-07 07:12:51.892 [system] WARN  o.c.r.impl.RequestContextServiceImpl - invoked getRequestContext(), but there is no request context set on this thread! generating sys request context = RequestContext{id=sys_QuartzScheduler_CMDB_2u8jjq9w6ac62yebz91l556s}
2019-10-07 07:12:51.892 [sys:boot] INFO  o.c.d.p.PostgresDateServiceImpl - postgres db timezone = America/New_York
2019-10-07 07:12:51.895 [sys:boot] INFO  o.c.d.p.PostgresDateServiceImpl - postgres db timezone offset = -04:00
2019-10-07 07:12:51.896 [sys:boot] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - run PostStartup method ws3Loader#startWs3
2019-10-07 07:12:51.896 [sys:boot] INFO  org.cmdbuild.webapp.Ws3Loader - start ws3
2019-10-07 07:12:52.051 [sys:boot] INFO  org.reflections.Reflections - Reflections took 130 ms to scan 1 urls, producing 8 keys and 207 values
2019-10-07 07:12:52.187 [sys:boot] INFO  org.cmdbuild.webapp.Ws3Loader - ws3 ready
2019-10-07 07:12:52.190 [sys:boot] INFO  o.cmdbuild.minions.SystemServiceImpl -



	   ___ __  __ ___  ___      _ _    _
	  / __|  \/  |   \| _ )_  _(_) |__| |
	 | (__| |\/| | |) | _ \ || | | / _` |
	  \___|_|  |_|___/|___/\_,_|_|_\__,_|
	                     v3.1.1 READY



	BIM Bimserver client    	    disabled
	BIM Service             	    disabled
	Clustering              	    disabled
	Cmis DMS client         	    disabled
	DMS Service             	    disabled
	Email Queue             	    disabled
	Ftp Service             	    disabled
	GIS GeoServer client    	    disabled
	GIS Service             	    disabled
	Multitenant             	    disabled
	Postgres DMS Service    	    disabled
	Quartz Scheduler (core) 	*   ready
	Scheduled Jobs          	    disabled
	Workflow Engine         	*   ready


	running source code rev 746fce5/stable/3.1.1 (2019-09-25T08:48:45Z)
	startup (uptime) 34.329s


2019-10-07 07:12:52.191 [sys:boot] INFO  o.c.w.f.BootCheckFilter$$EnhancerBySpringCGLIB$$de41c86 - system running, disable boot services

Thank you,
Giuseppe

Unfortunately the length of the log exceeds the maximum length for a post on this forum.
I cannot post links either, so it’s gonna be in two halves. Sorry about that.

[root@cmdbuild-test logs]# cat ROOT.log
2019-10-07 07:12:31.237 [system] INFO  o.c.w.LogbackConfigurationContextListener - logger ready
2019-10-07 07:12:31.239 [system] INFO  o.s.web.context.ContextLoader - Root WebApplicationContext: initialization started
2019-10-07 07:12:31.357 [system] INFO  o.s.w.c.s.XmlWebApplicationContext - Refreshing Root WebApplicationContext: startup date [Mon Oct 07 07:12:31 EDT 2019]; root of context hierarchy
2019-10-07 07:12:31.410 [system] INFO  o.s.b.f.xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [org/cmdbuild/web-application-context.xml]
2019-10-07 07:12:31.565 [system] INFO  o.s.b.f.xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [org/cmdbuild/core-application-context.xml]
2019-10-07 07:12:32.379 [system] INFO  o.s.b.f.xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [org/cmdbuild/rest/rest_v2.xml]
2019-10-07 07:12:32.390 [system] INFO  o.s.b.f.xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [META-INF/cxf/cxf.xml]
2019-10-07 07:12:32.442 [system] INFO  o.s.b.f.xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [org/cmdbuild/rest/rest_v3.xml]
2019-10-07 07:12:32.450 [system] INFO  o.s.b.f.xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [META-INF/cxf/cxf.xml]
2019-10-07 07:12:32.458 [system] INFO  o.s.b.f.xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [org/cmdbuild/soap/soapws.xml]
2019-10-07 07:12:32.464 [system] INFO  o.s.b.f.xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [META-INF/cxf/cxf.xml]
2019-10-07 07:12:32.470 [system] INFO  o.s.b.f.xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [org/cmdbuild/soap/soapws-r1.xml]
2019-10-07 07:12:32.498 [system] INFO  o.s.b.f.xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [org/cmdbuild/soap/soapws-r2.xml]
2019-10-07 07:12:34.157 [system] INFO  o.s.b.f.a.AutowiredAnnotationBeanPostProcessor - JSR-330 'javax.inject.Inject' annotation found and supported for autowiring
2019-10-07 07:12:34.348 [system] INFO  o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker - Bean 'org.springframework.security.config.annotation.configuration.ObjectPostProcessorConfiguration' of type [class org.springframework.security.config.annotation.configuration.ObjectPostProcessorConfiguration$$EnhancerBySpringCGLIB$$4f94e7d1] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-10-07 07:12:34.640 [system] INFO  o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker - Bean 'objectPostProcessor' of type [class org.springframework.security.config.annotation.configuration.AutowireBeanFactoryObjectPostProcessor] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-10-07 07:12:34.651 [system] INFO  o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker - Bean 'org.springframework.security.access.expression.method.DefaultMethodSecurityExpressionHandler@1378bbf3' of type [class org.springframework.security.access.expression.method.DefaultMethodSecurityExpressionHandler] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-10-07 07:12:34.677 [system] INFO  o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker - Bean 'org.springframework.security.config.annotation.method.configuration.GlobalMethodSecurityConfiguration' of type [class org.springframework.security.config.annotation.method.configuration.GlobalMethodSecurityConfiguration$$EnhancerBySpringCGLIB$$74698a83] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-10-07 07:12:34.786 [system] INFO  o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker - Bean 'methodSecurityMetadataSource' of type [class org.springframework.security.access.method.DelegatingMethodSecurityMetadataSource] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-10-07 07:12:34.828 [system] INFO  o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker - Bean 'configBeanRepositoryImpl' of type [class org.cmdbuild.config.service.ConfigBeanRepositoryImpl] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-10-07 07:12:34.839 [system] INFO  o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker - Bean 'configListenerBeansRepositoryImpl' of type [class org.cmdbuild.config.service.ConfigListenerBeansRepositoryImpl] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-10-07 07:12:34.864 [system] INFO  o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker - Bean 'minionBeanRepository' of type [class org.cmdbuild.minions.MinionBeanRepository] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-10-07 07:12:34.879 [system] INFO  o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker - Bean 'systemEventServiceImpl' of type [class org.cmdbuild.system.SystemEventServiceImpl] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-10-07 07:12:34.903 [system] INFO  o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker - Bean 'annotatedMethodJobService' of type [class org.cmdbuild.scheduler.annotatedmethodjobs.AnnotatedMethodJobService] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-10-07 07:12:34.986 [system] INFO  o.c.w.s.WebappDirectoryServiceImpl - cmdbuild webapp dir = /opt/tomcat/webapps/ROOT
2019-10-07 07:12:34.986 [system] INFO  o.c.w.s.WebappDirectoryServiceImpl - cmdbuild config dir = /opt/tomcat/conf/ROOT
2019-10-07 07:12:34.986 [system] INFO  o.c.w.s.WebappDirectoryServiceImpl - container dir = /opt/tomcat
2019-10-07 07:12:35.091 [system] INFO  o.c.minions.MinionAnnotationHandler - register minion bean = clusterServiceImpl ( org.cmdbuild.cluster.ClusterServiceImpl )
2019-10-07 07:12:35.118 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method clusterServiceImpl#stopSafe for PreShutdown hook
2019-10-07 07:12:35.129 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method clusterServiceImpl#startIfEnabled for PostStartup hook
2019-10-07 07:12:35.169 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method platformServiceImpl#fixPermissions for PostStartup hook
2019-10-07 07:12:35.282 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method rawDataSource#checkAndConfigureSqlLogger for PostStartup hook
2019-10-07 07:12:35.991 [system] INFO  o.c.d.orm.services.CardMapperLoader - scanClassesForHandlers BEGIN
2019-10-07 07:12:36.617 [system] INFO  o.c.d.orm.services.CardMapperLoader - scanClassesForHandlers END
2019-10-07 07:12:37.108 [system] INFO  o.c.minions.MinionAnnotationHandler - register minion bean = multitenantServiceImpl ( org.cmdbuild.auth.multitenant.MultitenantServiceImpl )
2019-10-07 07:12:37.152 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method multitenantServiceImpl#check for PostStartup hook
2019-10-07 07:12:37.496 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method jasperReportContextServiceImpl#loadJasperReportsContext for PostStartup hook
2019-10-07 07:12:38.489 [system] INFO  o.c.a.s.dao.SessionRepositoryImpl - init
2019-10-07 07:12:38.514 [system] INFO  o.c.s.a.ScheduledJobsAnnotationHandler - processing scheduled job from annotated method, bean = SessionRepositoryImpl (sessionRepositoryImpl) method = cleanupSessionStore trigger = '0 0 * * * ?'
2019-10-07 07:12:38.636 [system] INFO  org.cmdbuild.lock.LockRepositoryImpl - init
2019-10-07 07:12:38.655 [system] INFO  o.c.s.a.ScheduledJobsAnnotationHandler - processing scheduled job from annotated method, bean = LockRepositoryImpl (lockRepositoryImpl) method = cleanupLockTable trigger = '0 10 * * * ?'
2019-10-07 07:12:38.864 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method sharkWebserviceClientImpl#startSharkWsClient for PostStartup hook
2019-10-07 07:12:39.106 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method planServiceDelegateSupplierImpl#loadConfig for PostStartup hook
2019-10-07 07:12:39.510 [system] INFO  o.c.minions.MinionAnnotationHandler - register minion bean = cmisDmsProviderService ( org.cmdbuild.dms.cmis.CmisDmsProviderService )
2019-10-07 07:12:39.573 [system] INFO  o.c.minions.MinionAnnotationHandler - register minion bean = pgDmsProviderServiceImpl ( org.cmdbuild.dms.dao.PgDmsProviderServiceImpl )
2019-10-07 07:12:39.596 [system] INFO  o.c.minions.MinionAnnotationHandler - register minion bean = dmsServiceImpl ( org.cmdbuild.dms.core.DmsServiceImpl )
2019-10-07 07:12:40.413 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method workflowServiceDelegates#loadConfig for PostStartup hook
2019-10-07 07:12:40.433 [system] INFO  o.c.minions.MinionAnnotationHandler - register minion bean = workflowServiceFacadeImpl ( org.cmdbuild.workflow.core.WorkflowServiceFacadeImpl )
2019-10-07 07:12:40.651 [system] INFO  o.c.minions.MinionAnnotationHandler - register minion bean = emailQueueServiceImpl ( org.cmdbuild.email.queue.EmailQueueServiceImpl )
2019-10-07 07:12:40.660 [system] INFO  o.c.s.a.ScheduledJobsAnnotationHandler - processing scheduled job from annotated method, bean = EmailQueueServiceImpl (emailQueueServiceImpl) method = processEmailQueue trigger = '0 */10 * * * ?'
2019-10-07 07:12:41.592 [system] INFO  o.c.d.config.inner.PatchServiceImpl - init
2019-10-07 07:12:41.635 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method databaseStatusServiceImpl#init for PostStartup hook
2019-10-07 07:12:41.757 [system] INFO  o.c.minions.MinionAnnotationHandler - register minion bean = geoserverServiceImpl ( org.cmdbuild.gis.geoserver.GeoserverServiceImpl )
2019-10-07 07:12:41.771 [system] INFO  o.c.minions.MinionAnnotationHandler - register minion bean = gisService ( org.cmdbuild.gis.GisServiceImpl )
2019-10-07 07:12:41.872 [system] INFO  o.cmdbuild.minions.SystemServiceImpl - received application context PostConstruct event
2019-10-07 07:12:41.911 [system] INFO  o.c.s.a.ScheduledJobsAnnotationHandler - processing scheduled job from annotated method, bean = ConfigBackupService (configBackupService) method = backupConfig trigger = '0 0 04 * * ?'
2019-10-07 07:12:42.091 [system] INFO  o.c.s.a.ScheduledJobsAnnotationHandler - processing scheduled job from annotated method, bean = EtlDataRepositoryImpl (etlDataRepositoryImpl) method = processedDataCleanup trigger = '0 0 04 * * ?'
2019-10-07 07:12:42.237 [system] INFO  o.c.minions.MinionAnnotationHandler - register minion bean = jobServiceImpl ( org.cmdbuild.jobs.JobServiceImpl )
2019-10-07 07:12:42.472 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method easyuploadLoaderService#checkUploadsFolderAndLoadContent for PostStartup hook
2019-10-07 07:12:42.472 [system] INFO  o.c.s.a.ScheduledJobsAnnotationHandler - processing scheduled job from annotated method, bean = EasyuploadLoaderService (easyuploadLoaderService) method = checkUploadsFolderAndLoadContent trigger = '*/10 * * * * ?'
2019-10-07 07:12:42.517 [system] INFO  o.c.minions.MinionAnnotationHandler - register minion bean = easyuploadFtpService ( org.cmdbuild.easyupload.ftp.EasyuploadFtpService )
2019-10-07 07:12:42.526 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method easyuploadFtpService#startFtpServerIfEnabled for PostStartup hook
2019-10-07 07:12:42.526 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method easyuploadFtpService#stopSafe for PreShutdown hook
2019-10-07 07:12:42.587 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method logbackConfigServiceImpl#init for PostStartup hook
2019-10-07 07:12:42.621 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method sysmonServiceImpl#logSystemInfo for PostStartup hook
2019-10-07 07:12:42.621 [system] INFO  o.c.s.a.ScheduledJobsAnnotationHandler - processing scheduled job from annotated method, bean = SysmonServiceImpl (sysmonServiceImpl) method = logSystemStatus trigger = '0 * * * * ?'
2019-10-07 07:12:42.655 [system] INFO  o.c.l.ErrorOrWarningLogbackAppenderService - init
2019-10-07 07:12:42.678 [system] INFO  o.c.s.a.ScheduledJobsAnnotationHandler - processing scheduled job from annotated method, bean = TempServiceImpl (tempServiceImpl) method = removeExpiredRecords trigger = '0 */10 * * * ?'
2019-10-07 07:12:42.679 [system] WARN  o.c.r.impl.RequestContextServiceImpl - invoked getRequestContext(), but there is no request context set on this thread! generating sys request context = RequestContext{id=sys_localhost-startStop-_dgs2b7dyefbzr0wp5p01nren}
2019-10-07 07:12:42.718 [system] INFO  o.c.s.a.ScheduledJobsAnnotationHandler - processing scheduled job from annotated method, bean = RequestTrackingServiceImpl (requestTrackingServiceImpl) method = doCleanupRequestTable trigger = '0 0 * * * ?'
2019-10-07 07:12:42.805 [system] INFO  o.c.minions.MinionAnnotationHandler - register minion bean = schedulerServiceImpl ( org.cmdbuild.scheduler.quartz.SchedulerServiceImpl )
2019-10-07 07:12:42.851 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method schedulerServiceImpl#stopService for PreShutdown hook
2019-10-07 07:12:42.851 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method schedulerServiceImpl#startup for PostStartup hook
2019-10-07 07:12:42.981 [system] INFO  o.c.minions.MinionAnnotationHandler - register minion bean = bimserverClientServiceImpl ( org.cmdbuild.bim.bimserverclient.BimserverClientServiceImpl )
2019-10-07 07:12:43.020 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method bimserverClientServiceImpl#init for PostStartup hook
2019-10-07 07:12:43.020 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method bimserverClientServiceImpl#cleanup for PreShutdown hook
2019-10-07 07:12:43.024 [system] INFO  o.c.minions.MinionAnnotationHandler - register minion bean = bimServiceImpl ( org.cmdbuild.bim.BimServiceImpl )
2019-10-07 07:12:43.121 [system] INFO  o.cmdbuild.webapp.log.LogServiceImpl - init
2019-10-07 07:12:43.898 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method databaseHousekeepingService#runDatabaseHousekeepingAtStartup for PostStartup hook
2019-10-07 07:12:43.906 [system] INFO  o.c.s.a.ScheduledJobsAnnotationHandler - processing scheduled job from annotated method, bean = DatabaseHousekeepingService (databaseHousekeepingService) method = runDatabaseHousekeepingJob trigger = '0 0 4 * * ?'
2019-10-07 07:12:43.973 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method postgresDateServiceImpl#printInfo for PostStartup hook
2019-10-07 07:12:44.156 [system] INFO  o.c.m.LifecycleBeanMethodAnnotationHandler - register method ws3Loader#startWs3 for PostStartup hook
2019-10-07 07:12:44.369 [system] INFO  o.c.webapp.plus.TomcatPlusHelperImpl - unable to load tomcat plus delegate, tomcat plus is not available
2019-10-07 07:12:45.906 [system] INFO  org.apache.cxf.endpoint.ServerImpl - Setting the server's publish address to be /v2
2019-10-07 07:12:47.458 [system] INFO  org.apache.cxf.endpoint.ServerImpl - Setting the server's publish address to be /v3
2019-10-07 07:12:47.585 [system] INFO  o.a.c.w.s.f.ReflectionServiceFactoryBean - Creating Service {http://soap.services.cmdbuild.org}WebservicesImplService from class org.cmdbuild.services.soap.Webservices
2019-10-07 07:12:48.545 [system] INFO  org.apache.cxf.endpoint.ServerImpl - Setting the server's publish address to be /Webservices
2019-10-07 07:12:48.663 [system] INFO  o.a.c.w.s.f.ReflectionServiceFactoryBean - Creating Service {http://soap.services.cmdbuild.org}PrivateImplService from class org.cmdbuild.services.soap.Private
2019-10-07 07:12:49.078 [system] INFO  org.apache.cxf.endpoint.ServerImpl - Setting the server's publish address to be /Private
2019-10-07 07:12:49.327 [system] INFO  o.s.s.web.DefaultSecurityFilterChain - Creating filter chain: Ant [pattern='/services/rest/v*/boot/status', GET], []
2019-10-07 07:12:49.327 [system] INFO  o.s.s.web.DefaultSecurityFilterChain - Creating filter chain: Ant [pattern='/services/rest/v*/boot/status/', GET], []
2019-10-07 07:12:49.576 [system] INFO  o.s.s.web.DefaultSecurityFilterChain - Creating filter chain: Ant [pattern='/services/rest/v*/boot/**'], [org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter@1462b14f, org.springframework.security.web.context.SecurityContextPersistenceFilter@41cca6a5, org.springframework.security.web.header.HeaderWriterFilter@36af6d82, org.springframework.web.filter.CorsFilter@1354c3fd, org.springframework.security.web.savedrequest.RequestCacheAwareFilter@4b4c0c66, org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter@7e5c80da, org.springframework.security.web.authentication.AnonymousAuthenticationFilter@36045f9e, org.springframework.security.web.session.SessionManagementFilter@86b667f, org.springframework.security.web.access.ExceptionTranslationFilter@5bd0d4e9, org.springframework.security.web.access.intercept.FilterSecurityInterceptor@62eabd2f]

The remaining of the log in my following post.

By any chance do you have multiple instances of CMDBuild on the same server? If yes when switching between instances of different versions make sure you delete the cookies, more in specific the CMDBuild-Authorization cookies:

Screenshot%20from%202019-10-07%2016-16-36

Hi, I used an incognito window as well, the problem persists the same way.
Checking the cookies anyway I see I be maybe missing the CMDBUILD-Authorization, which instead i see on the other instance of 3.1 (see attachment)

The 3.1.1:03

This is instead the 3.1
15

Thanks,
Giuseppe

Sorry but i cannot edit my previous post.
I found also “WebSocket connection to ‘ws://10.0.0.35:8080/services/websocket/v1/main’ failed: HTTP Authentication failed; no valid credentials available”

Giuseppe

Are you using “https” or “http”? Also what browser version are you using?

Hi, I’m hitting directly tomcat on port 8080 so no ssl.
I’m using Chrome Version 77.0.3865.90 (Official Build) (64-bit).
But as I said, 3.1 does work in the same setup.
I can attach my install script.

Tx
Giuseppe

And are you using the standard CMDBuild authentication system or are you using LDAP or any other auth methods?

Hi, I’m using standard CMDBuild auth, just fresh installed with empty database.
Thanks,
Giuseppe