Unexpected error while broadcasting shared group rename for user

hawat · September 26, 2019, 8:02am

Hi!
Openfire version 4.4.2
Java openjdk-8-jdk
Ldap Users 763
Ldap groups 109

At “Enable contact list group sharing” “All users” a huge number of errors appear and the server freezes.
Has anyone encountered this?

{"log":"07:49:35.764 [Jetty-QTP-AdminConsole-62] WARN  org.jivesoftware.openfire.roster.Roster - Unexpected error while broadcasting shared group rename for user 'FedorovaIV@belwest.corp'!\n","stream":"stdout","time":"2019-09-26T07:49:35.907229026Z"}
{"log":"org.jivesoftware.openfire.user.UserNotFoundException: FedorovaIV@belwest.corp\n","stream":"stdout","time":"2019-09-26T07:49:35.907241397Z"}
{"log":"\u0009at org.jivesoftware.openfire.roster.Roster.getRosterItem(Roster.java:218) ~[xmppserver-4.4.2.jar:4.4.2]\n","stream":"stdout","time":"2019-09-26T07:49:35.907261152Z"}
{"log":"\u0009at org.jivesoftware.openfire.roster.Roster.shareGroupRenamed(Roster.java:1125) [xmppserver-4.4.2.jar:4.4.2]\n","stream":"stdout","time":"2019-09-26T07:49:35.90728007Z"}
{"log":"\u0009at org.jivesoftware.openfire.roster.RosterManager.groupModified(RosterManager.java:370) [xmppserver-4.4.2.jar:4.4.2]\n","stream":"stdout","time":"2019-09-26T07:49:35.907297794Z"}
{"log":"\u0009at org.jivesoftware.openfire.event.GroupEventDispatcher.dispatchEvent(GroupEventDispatcher.java:145) [xmppserver-4.4.2.jar:4.4.2]\n","stream":"stdout","time":"2019-09-26T07:49:35.90731507Z"}
{"log":"\u0009at org.jivesoftware.openfire.group.DefaultGroupPropertyMap.insertProperty(DefaultGroupPropertyMap.java:483) [xmppserver-4.4.2.jar:4.4.2]\n","stream":"stdout","time":"2019-09-26T07:49:35.907331995Z"}
{"log":"\u0009at org.jivesoftware.openfire.group.DefaultGroupPropertyMap.put(DefaultGroupPropertyMap.java:78) [xmppserver-4.4.2.jar:4.4.2]\n","stream":"stdout","time":"2019-09-26T07:49:35.907349895Z"}
{"log":"\u0009at org.jivesoftware.openfire.group.DefaultGroupPropertyMap.put(DefaultGroupPropertyMap.java:89) [xmppserver-4.4.2.jar:4.4.2]\n","stream":"stdout","time":"2019-09-26T07:49:35.907367031Z"}
{"log":"\u0009at org.jivesoftware.openfire.admin.group_002dedit_jsp._jspService(group_002dedit_jsp.java:342) [xmppserver-4.4.2.jar:4.4.2]\n","stream":"stdout","time":"2019-09-26T07:49:35.907382033Z"}
{"log":"\u0009at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70) [apache-jsp-8.5.40.jar:8.5.40]\n","stream":"stdout","time":"2019-09-26T07:49:35.907391902Z"}
{"log":"\u0009at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) [javax.servlet-api-3.1.0.jar:3.1.0]\n","stream":"stdout","time":"2019-09-26T07:49:35.907401579Z"}
{"log":"\u0009at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:873) [jetty-servlet-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907411156Z"}
{"log":"\u0009at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1623) [jetty-servlet-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907420933Z"}
{"log":"\u0009at com.opensymphony.sitemesh.webapp.SiteMeshFilter.obtainContent(SiteMeshFilter.java:129) [sitemesh-2.4.2.jar:?]\n","stream":"stdout","time":"2019-09-26T07:49:35.907431942Z"}
{"log":"\u0009at com.opensymphony.sitemesh.webapp.SiteMeshFilter.doFilter(SiteMeshFilter.java:77) [sitemesh-2.4.2.jar:?]\n","stream":"stdout","time":"2019-09-26T07:49:35.907441757Z"}
{"log":"\u0009at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) [jetty-servlet-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907451082Z"}
{"log":"\u0009at org.jivesoftware.util.LocaleFilter.doFilter(LocaleFilter.java:73) [xmppserver-4.4.2.jar:4.4.2]\n","stream":"stdout","time":"2019-09-26T07:49:35.907460616Z"}
{"log":"\u0009at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) [jetty-servlet-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.90746993Z"}
{"log":"\u0009at org.jivesoftware.util.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingFilter.java:49) [xmppserver-4.4.2.jar:4.4.2]\n","stream":"stdout","time":"2019-09-26T07:49:35.907487833Z"}
{"log":"\u0009at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) [jetty-servlet-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907498605Z"}
{"log":"\u0009at org.jivesoftware.admin.PluginFilter.doFilter(PluginFilter.java:226) [xmppserver-4.4.2.jar:4.4.2]\n","stream":"stdout","time":"2019-09-26T07:49:35.907508142Z"}
{"log":"\u0009at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) [jetty-servlet-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907517486Z"}
{"log":"\u0009at org.jivesoftware.admin.AuthCheckFilter.doFilter(AuthCheckFilter.java:234) [xmppserver-4.4.2.jar:4.4.2]\n","stream":"stdout","time":"2019-09-26T07:49:35.907527054Z"}
{"log":"\u0009at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1602) [jetty-servlet-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.90753644Z"}
{"log":"\u0009at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:540) [jetty-servlet-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.90754589Z"}
{"log":"\u0009at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146) [jetty-server-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907555268Z"}
{"log":"\u0009at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) [jetty-security-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907564736Z"}
{"log":"\u0009at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) [jetty-server-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907574288Z"}
{"log":"\u0009at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257) [jetty-server-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907584871Z"}
{"log":"\u0009at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1700) [jetty-server-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907594713Z"}
{"log":"\u0009at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) [jetty-server-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907604074Z"}
{"log":"\u0009at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1345) [jetty-server-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907613517Z"}
{"log":"\u0009at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203) [jetty-server-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907623133Z"}
{"log":"\u0009at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480) [jetty-servlet-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907632802Z"}
{"log":"\u0009at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1667) [jetty-server-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907642247Z"}
{"log":"\u0009at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201) [jetty-server-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907651968Z"}
{"log":"\u0009at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1247) [jetty-server-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907661651Z"}
{"log":"\u0009at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144) [jetty-server-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907671067Z"}
{"log":"\u0009at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:220) [jetty-server-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907698382Z"}
{"log":"\u0009at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:152) [jetty-server-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907710096Z"}
{"log":"\u0009at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) [jetty-server-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907719594Z"}
{"log":"\u0009at org.eclipse.jetty.server.Server.handle(Server.java:505) [jetty-server-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907729077Z"}
{"log":"\u0009at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:370) [jetty-server-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.90773857Z"}
{"log":"\u0009at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:267) [jetty-server-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907749134Z"}
{"log":"\u0009at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305) [jetty-io-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907759019Z"}
{"log":"\u0009at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) [jetty-io-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907768508Z"}
{"log":"\u0009at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) [jetty-io-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.90777789Z"}
{"log":"\u0009at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) [jetty-util-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907787291Z"}
{"log":"\u0009at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) [jetty-util-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907796724Z"}
{"log":"\u0009at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) [jetty-util-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.90780636Z"}
{"log":"\u0009at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) [jetty-util-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907816088Z"}
{"log":"\u0009at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) [jetty-util-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907825633Z"}
{"log":"\u0009at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:698) [jetty-util-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907835216Z"}
{"log":"\u0009at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:804) [jetty-util-9.4.18.v20190429.jar:9.4.18.v20190429]\n","stream":"stdout","time":"2019-09-26T07:49:35.907844617Z"}
{"log":"\u0009at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]\n","stream":"stdout","time":"2019-09-26T07:49:35.907854013Z"}

guus · September 26, 2019, 10:28am

The error itself tells you that the user to which the roster change is sent does not exist on your server. Can you verify that a user with the JID “FedorovaIV@belwest.corp” exists on your server?

This error will be logged for every (non-existing) user that is affected by the name change, but is otherwise ignored. I don’t see how this can make the server freeze. Maybe there’s a larger issue at play?

Judging by the output format of your logs, you’re using a modified version of Openfire. Have you tried doing this with an unmodified version of Openfire?

hawat · September 26, 2019, 1:15pm

User FedorovaIV@belwest.corp exists. The same error for all AD users. A full log consists of millions of records of this kind. Openfire launched in docker, tried different versions, the same error.

katbert · April 7, 2020, 11:59am

Same issue with Openfire 4.2.1 (663 ldap users, 156 ldap groups, 30 shared groups)
If I rename group (shared for all users) - Openfire web console thinks ~10 min
After 10 min - console successfully save the group

all. log is full of this messages:
2020.04.07 15:46:09 WARN [Jetty-QTP-AdminConsole-36]: org.jivesoftware.openfire.roster.Roster - Unexpected error while broadcasting shared group rename for user ‘COMP$@domail.local’!

Server try to broadcast shared group renaming to all domain computers, offline users and users without any Jabber clients

Is it possible to decrease “broadcasting shared group rename” timeout?

akrherz · April 7, 2020, 1:28pm

I believe this is fixed with the present version of Openfire, 4.5.1

katbert · April 7, 2020, 3:08pm

Thanks! Upgrade to 4.5.1 fixed issue. Now group renaming is very fast