I have a Docker setup with latest 10.8.1 and getting a few errors and warnings that might be interesting.
What caught my eye was:
[Core extension repository updater] ERROR aultExtensionRepositoryManager - Unexpected error when trying to find extension [com.google.code.findbugs:annotations/api] in repository [store.xwiki.com:xwiki:https://store.xwiki.com/xwiki/rest]
and a few warnings related to notifications.
Are these known issues?
xwiki.log (36.7 KB)
18-Oct-2018 20:01:06.400 WARNING [localhost-startStop-1] org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [187,032] milliseconds.
18-Oct-2018 20:01:07.468 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/ROOT] has finished in [229,442] ms
Wow this is long… it should normally take 15-20 seconds to deploy XWiki in Tomcat.
2018-10-18 20:11:58,718 [XWiki Scheduler initialization] WARN w.i.AutomaticWatchModeListener - Failed to watch document [xwiki:Scheduler.NotificationEmailHourlySender] for user [xwiki:XWiki.frieder]
org.xwiki.notifications.NotificationException: Error while loading the notification filter preferences of the user [xwiki:XWiki.frieder].
at org.xwiki.notifications.filters.internal.NotificationFilterPreferenceStore.getPreferencesOfUser(NotificationFilterPreferenceStore.java:121)
at org.xwiki.notifications.filters.internal.DefaultModelBridge.getInternalFilterPreferences(DefaultModelBridge.java:93)
at org.xwiki.notifications.filters.internal.DefaultModelBridge.getFilterPreferences(DefaultModelBridge.java:100)
at org.xwiki.notifications.filters.internal.CachedModelBridge.getFilterPreferences(CachedModelBridge.java:113)
at org.xwiki.notifications.filters.internal.UserProfileNotificationFilterPreferenceProvider.getFilterPreferences(UserProfileNotificationFilterPreferenceProvider.java:59)
at org.xwiki.notifications.filters.internal.DefaultNotificationFilterManager.getFilterPreferences(DefaultNotificationFilterManager.java:154)
at org.xwiki.notifications.filters.watch.WatchedLocationReference.isWatched(WatchedLocationReference.java:89)
at org.xwiki.notifications.filters.watch.internal.DefaultWatchedEntitiesManager.entityIsAlreadyInDesiredState(DefaultWatchedEntitiesManager.java:139)
at org.xwiki.notifications.filters.watch.internal.DefaultWatchedEntitiesManager.handleEntity(DefaultWatchedEntitiesManager.java:95)
at org.xwiki.notifications.filters.watch.internal.DefaultWatchedEntitiesManager.watchEntity(DefaultWatchedEntitiesManager.java:63)
at org.xwiki.notifications.filters.watch.internal.AutomaticWatchModeListener.documentModifiedHandler(AutomaticWatchModeListener.java:135)
at org.xwiki.notifications.filters.watch.internal.AutomaticWatchModeListener.onEvent(AutomaticWatchModeListener.java:106)
at org.xwiki.observation.internal.DefaultObservationManager.notify(DefaultObservationManager.java:304)
at org.xwiki.observation.internal.DefaultObservationManager.notify(DefaultObservationManager.java:269)
at com.xpn.xwiki.XWiki.saveDocument(XWiki.java:1830)
at com.xpn.xwiki.XWiki.saveDocument(XWiki.java:1736)
at com.xpn.xwiki.XWiki.saveDocument(XWiki.java:1726)
at com.xpn.xwiki.plugin.scheduler.SchedulerPlugin.saveStatus(SchedulerPlugin.java:636)
at com.xpn.xwiki.plugin.scheduler.SchedulerPlugin.scheduleJob(SchedulerPlugin.java:413)
at com.xpn.xwiki.plugin.scheduler.SchedulerPlugin.register(SchedulerPlugin.java:317)
at com.xpn.xwiki.plugin.scheduler.SchedulerPlugin.register(SchedulerPlugin.java:310)
at com.xpn.xwiki.plugin.scheduler.SchedulerPlugin.restoreExistingJobs(SchedulerPlugin.java:295)
at com.xpn.xwiki.plugin.scheduler.SchedulerPlugin.initAsync(SchedulerPlugin.java:167)
at com.xpn.xwiki.plugin.scheduler.SchedulerPlugin.access$000(SchedulerPlugin.java:79)
at com.xpn.xwiki.plugin.scheduler.SchedulerPlugin$1.run(SchedulerPlugin.java:126)
at org.xwiki.context.concurrent.ExecutionContextRunnable.run(ExecutionContextRunnable.java:70)
at java.lang.Thread.run(Thread.java:748)
Caused by: org.xwiki.query.QueryException: Exception while executing query. Query statement = [select nfp from DefaultNotificationFilterPreference nfp where nfp.owner = :owner order by nfp.id]
at com.xpn.xwiki.store.hibernate.query.HqlQueryExecutor.execute(HqlQueryExecutor.java:195)
at org.xwiki.query.internal.DefaultQueryExecutorManager.execute(DefaultQueryExecutorManager.java:72)
at org.xwiki.query.internal.DefaultQuery.execute(DefaultQuery.java:296)
at org.xwiki.notifications.filters.internal.NotificationFilterPreferenceStore.getPreferencesOfUser(NotificationFilterPreferenceStore.java:113)
… 26 common frames omitted
Caused by: com.xpn.xwiki.XWikiException: Error number 0 in 3: Exception while hibernate execute
at com.xpn.xwiki.store.XWikiHibernateBaseStore.execute(XWikiHibernateBaseStore.java:927)
at com.xpn.xwiki.store.XWikiHibernateBaseStore.executeRead(XWikiHibernateBaseStore.java:990)
at com.xpn.xwiki.store.hibernate.query.HqlQueryExecutor.execute(HqlQueryExecutor.java:177)
… 29 common frames omitted
Caused by: org.hibernate.hql.ast.QuerySyntaxException: DefaultNotificationFilterPreference is not mapped [select nfp from DefaultNotificationFilterPreference nfp where nfp.owner = :owner order by nfp.id]
at org.hibernate.hql.ast.util.SessionFactoryHelper.requireClassPersister(SessionFactoryHelper.java:180)
at org.hibernate.hql.ast.tree.FromElementFactory.addFromElement(FromElementFactory.java:111)
at org.hibernate.hql.ast.tree.FromClause.addFromElement(FromClause.java:93)
at org.hibernate.hql.ast.HqlSqlWalker.createFromElement(HqlSqlWalker.java:327)
at org.hibernate.hql.antlr.HqlSqlBaseWalker.fromElement(HqlSqlBaseWalker.java:3441)
at org.hibernate.hql.antlr.HqlSqlBaseWalker.fromElementList(HqlSqlBaseWalker.java:3325)
at org.hibernate.hql.antlr.HqlSqlBaseWalker.fromClause(HqlSqlBaseWalker.java:733)
at org.hibernate.hql.antlr.HqlSqlBaseWalker.query(HqlSqlBaseWalker.java:584)
at org.hibernate.hql.antlr.HqlSqlBaseWalker.selectStatement(HqlSqlBaseWalker.java:301)
at org.hibernate.hql.antlr.HqlSqlBaseWalker.statement(HqlSqlBaseWalker.java:244)
at org.hibernate.hql.ast.QueryTranslatorImpl.analyze(QueryTranslatorImpl.java:256)
at org.hibernate.hql.ast.QueryTranslatorImpl.doCompile(QueryTranslatorImpl.java:187)
at org.hibernate.hql.ast.QueryTranslatorImpl.compile(QueryTranslatorImpl.java:138)
at org.hibernate.engine.query.HQLQueryPlan.(HQLQueryPlan.java:101)
at org.hibernate.engine.query.HQLQueryPlan.(HQLQueryPlan.java:80)
at org.hibernate.engine.query.QueryPlanCache.getHQLQueryPlan(QueryPlanCache.java:124)
at org.hibernate.impl.AbstractSessionImpl.getHQLQueryPlan(AbstractSessionImpl.java:156)
at org.hibernate.impl.AbstractSessionImpl.createQuery(AbstractSessionImpl.java:135)
at org.hibernate.impl.SessionImpl.createQuery(SessionImpl.java:1770)
at com.xpn.xwiki.store.hibernate.query.HqlQueryExecutor.createHibernateQuery(HqlQueryExecutor.java:220)
at com.xpn.xwiki.store.hibernate.query.HqlQueryExecutor$1.doInHibernate(HqlQueryExecutor.java:183)
at com.xpn.xwiki.store.hibernate.query.HqlQueryExecutor$1.doInHibernate(HqlQueryExecutor.java:178)
at com.xpn.xwiki.store.XWikiHibernateBaseStore.execute(XWikiHibernateBaseStore.java:921)
… 31 common frames omitted
This is because you’re using an old 10.8.1 image I think. Can you try to “docker pull” the image? See XWiki Docker image for 10.8.1 updated
Good to know. I was already wondering if this is not a bit long. I didn’t do much so far. Basically only including the docker image in my setup and starting it.
2018-10-18 19:58:00,542 [Core extension repository updater] ERROR aultExtensionRepositoryManager - Unexpected error when trying to find extension [com.google.code.findbugs:annotations/api] in repository [store.xwiki.com:xwiki:https://store.xwiki.com/xwiki/rest]
org.xwiki.extension.ResolveException: Failed to create extension object for extension [com.google.code.findbugs:annotations/api]
at org.xwiki.extension.repository.xwiki.internal.XWikiExtensionRepository.resolve(XWikiExtensionRepository.java:344)
at org.xwiki.extension.repository.internal.DefaultExtensionRepositoryManager.resolve(DefaultExtensionRepositoryManager.java:286)
at org.xwiki.extension.repository.internal.core.DefaultCoreExtensionScanner.updateExtensions(DefaultCoreExtensionScanner.java:116)
at org.xwiki.extension.repository.internal.core.DefaultCoreExtensionRepository$1.run(DefaultCoreExtensionRepository.java:138)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.io.IOException: Invalid answer [500] from the server when requesting [https://store.xwiki.com/xwiki/rest/repository/extensions/com.google.code.findbugs%3Aannotations/versions/api]
at org.xwiki.extension.repository.xwiki.internal.XWikiExtensionRepository.getRESTResource(XWikiExtensionRepository.java:255)
at org.xwiki.extension.repository.xwiki.internal.XWikiExtensionRepository.getRESTObject(XWikiExtensionRepository.java:305)
at org.xwiki.extension.repository.xwiki.internal.XWikiExtensionRepository.resolve(XWikiExtensionRepository.java:350)
at org.xwiki.extension.repository.xwiki.internal.XWikiExtensionRepository.resolve(XWikiExtensionRepository.java:340)
… 4 common frames omitted
I’ll let @tmortagne or @mflorea reply to this one. There might be a problem with store.xwiki.com.
I don’t think so. I pulled the latest image with tag 10.8.1-mysql-tomcat and the warnings remain.
Hmm I think I know. See https://www.xwiki.org/xwiki/bin/view/ReleaseNotes/Data/XWiki/10.8/#HIssuesspecifictoXWiki10.8
(Check the part in yellow).
Could you check the table name you have: notification_filter_preferences or notification_filter_prefs?
I don’t think I ever used 10.8RC1 at least not that I know.
I don’t have any table like notification_filter_preferences.
mysql> show tables;
+-------------------------------+
| Tables_in_xwiki |
+-------------------------------+
| activitystream_events |
| activitystream_events_status |
| activitystream_events_targets |
| feeds_aggregatorgroup |
| feeds_aggregatorurl |
| feeds_aggregatorurlgroups |
| feeds_feedentry |
| feeds_feedentrytags |
| feeds_keyword |
| mailsender_events |
| xwikiattachment |
| xwikiattachment_archive |
| xwikiattachment_content |
| xwikiattrecyclebin |
| xwikicomments |
| xwikidates |
| xwikidbversion |
| xwikidoc |
| xwikidoubles |
| xwikifloats |
| xwikiid |
| xwikiintegers |
| xwikilargestrings |
| xwikilinks |
| xwikilistitems |
| xwikilists |
| xwikilock |
| xwikilongs |
| xwikiobjects |
| xwikipreferences |
| xwikiproperties |
| xwikircs |
| xwikirecyclebin |
| xwikispace |
| xwikistatsdoc |
| xwikistatsreferer |
| xwikistatsvisit |
| xwikistrings |
+-------------------------------+
38 rows in set (0.00 sec)
hmm that’s a problem, you should have a notification_filter_prefs table as otherwise the notification feature won’t work.
@gdelhumeau Any idea what could be wrong? (Guillaume is the author of this feature)
If it’s an installation on Linux it may be caused by an empty entropy pool (/dev/random).
If all works well, Xwiki needs between 60 and 75 seconds to start, but it easily takes up to several minutes if it’s restarted too often or immediately after server bootup.
It’s somewhat annoying, but probably a known tradeoff between security and usability.
According to my observations, forcing disk activity on the server helps a bit in this case and can accelerate the start time from 3-4 to about 2 minutes.
Actually I did three more restarts and the startup time went down from the 230 seconds seen above, first to 100 seconds and then to 42 seconds. I think I recreated the docker container before the first start, so that might have had some influence.
Starts under 20 seconds for me.
BTW we tried to speed this up by setting this at startup: -Dsecurerandom.source=file:/dev/urandom. Works fine on most machines and I don’t know why it has no effect on yours.
It’s also machine dependent, but for me it takes at least about 50 or 55 seconds as far as I observed. (It’s a virtual machine running on a slightly older Xeon server.)
The thing about -Dsecurerandom.source=file:/dev/urandom is interesting, I’ll have to look into this - it shouldn’t block in this case, but definitely does. In this case the log suspends after starting solr and it takes ages until the startup process continues.