[CONTTAGS-131] In a Public instance, Magnolia Context is not set when publishing tags Created: 22/May/23  Updated: 15/Sep/23  Resolved: 31/Aug/23

Status: Closed
Project: Content Tags
Component/s: None
Affects Version/s: 2.0.4
Fix Version/s: 2.0.5

Type: Bug Priority: Normal
Reporter: Richard Gange Assignee: ricardo gonzalez
Resolution: Fixed Votes: 2
Labels: None
Remaining Estimate: Not Specified
Time Spent: 0.25d
Original Estimate: Not Specified

Issue Links:
Cloners
is cloned by CONTTAGS-139 Port to master: MgnlContext is not se... Closed
relation
Template:
Acceptance criteria:
Empty
Task DoD:
[X]* Doc/release notes changes? Comment present?
[X]* Downstream builds green?
[X]* Solution information and context easily available?
[X]* Tests
[X]* FixVersion filled and not yet released
[X]  Architecture Decision Record (ADR)
Bug DoR:
[X]* Steps to reproduce, expected, and actual results filled
[X]* Affected version filled
Release notes required:
Yes
Date of First Response:
Epic Link: AuthorX Support
Story Points: 3
Team: AuthorX
Work Started:
Approved:
Yes

 Description   

When a node is created the MgnlContext is used to find out the current user so that this can be entered in "mgnl:createdBy". Since this EventListener is asynchronous it is detached from the request and there is no MgnlContext. This then leads to the following error:

2023-02-23 12:17:32,611 ERROR info.magnolia.context.MgnlContext : MgnlContext is not initialized. This could happen if the request does not go through the Magnolia default filters.
java.lang.IllegalStateException: MgnlContext is not set for this thread

Reproduce

  • Open Tour App, edit a tour, add a new tag & save.
  • Publish the tour.
  • Observe the error in the public log.

Expected
The tour can be published without creating an error.

Actual
Exception thrown in the public log.

INFO  info.magnolia.publishing.receiver.operation.jcr.JcrPublicationOperation 22.05.2023 13:16:34 -- About to update content under path [/magnolia-travels/Vietnam--Tradition-and-Today].
INFO  info.magnolia.publishing.transactional.receiver.operation.jcr.JcrTransactionPublicationOperation 22.05.2023 13:16:34 -- 608 User superuser successfully published tours:/magnolia-travels/Vietnam--Tradition-and-Today on ROOT.
ERROR info.magnolia.context.MgnlContext 22.05.2023 13:16:35 -- MgnlContext is not initialized. This could happen if the request does not go through the Magnolia default filters.
java.lang.IllegalStateException: MgnlContext is not set for this thread
	at info.magnolia.context.MgnlContext.getInstance(MgnlContext.java:282) ~[magnolia-core-6.2.34.jar:?]
	at info.magnolia.context.MgnlContext.getUser(MgnlContext.java:91) ~[magnolia-core-6.2.34.jar:?]
	at info.magnolia.jcr.wrapper.MgnlPropertySettingContentDecorator.getCurrentUserName(MgnlPropertySettingContentDecorator.java:728) ~[magnolia-core-6.2.34.jar:?]
	at info.magnolia.jcr.wrapper.MgnlPropertySettingContentDecorator.updateLastModified(MgnlPropertySettingContentDecorator.java:622) ~[magnolia-core-6.2.34.jar:?]
	at info.magnolia.jcr.wrapper.MgnlPropertySettingContentDecorator.updateLastModified(MgnlPropertySettingContentDecorator.java:627) ~[magnolia-core-6.2.34.jar:?]
	at info.magnolia.jcr.wrapper.MgnlPropertySettingNodeWrapper.updateLastModified(MgnlPropertySettingNodeWrapper.java:262) ~[magnolia-core-6.2.34.jar:?]
	at info.magnolia.jcr.wrapper.MgnlPropertySettingNodeWrapper.addNode(MgnlPropertySettingNodeWrapper.java:214) ~[magnolia-core-6.2.34.jar:?]
	at info.magnolia.jcr.wrapper.DelegateNodeWrapper.addNode(DelegateNodeWrapper.java:129) ~[magnolia-core-6.2.34.jar:?]
	at info.magnolia.jcr.decoration.ContentDecoratorNodeWrapper.addNode(ContentDecoratorNodeWrapper.java:131) ~[magnolia-core-6.2.34.jar:?]
	at info.magnolia.audit.MgnlAuditLoggingContentDecoratorNodeWrapper.addNode(MgnlAuditLoggingContentDecoratorNodeWrapper.java:84) ~[magnolia-core-6.2.34.jar:?]
	at info.magnolia.jcr.wrapper.DelegateNodeWrapper.addNode(DelegateNodeWrapper.java:129) ~[magnolia-core-6.2.34.jar:?]
	at info.magnolia.jcr.decoration.ContentDecoratorNodeWrapper.addNode(ContentDecoratorNodeWrapper.java:131) ~[magnolia-core-6.2.34.jar:?]
	at info.magnolia.jcr.wrapper.MagnoliaSessionContentDecorator$1.addNode(MagnoliaSessionContentDecorator.java:67) ~[magnolia-core-6.2.34.jar:?]
	at info.magnolia.jcr.util.NodeUtil.createPath(NodeUtil.java:637) ~[magnolia-core-6.2.34.jar:?]
	at info.magnolia.contenttags.manager.TagManager.getOrCreate(TagManager.java:168) ~[magnolia-content-tags-core-2.0.4.jar:?]
	at info.magnolia.contenttags.manager.TagManager.getOrCreateTag(TagManager.java:162) ~[magnolia-content-tags-core-2.0.4.jar:?]
	at info.magnolia.contenttags.TagsModule.lambda$null$1(TagsModule.java:142) ~[magnolia-content-tags-core-2.0.4.jar:?]
	at info.magnolia.observation.DeferringEventListener$ObservationBasedDelayedExecutor$1.run(DeferringEventListener.java:102) [magnolia-core-6.2.34.jar:?]
	at info.magnolia.cms.util.DelayedExecutor$RunnableWrapper.run(DelayedExecutor.java:103) [magnolia-core-6.2.34.jar:?]
	at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(Unknown Source) [concurrent-1.3.4.jar:?]
	at java.lang.Thread.run(Thread.java:829) [?:?]

Notes
Could also be related to CONTTAGS-130



 Comments   
Comment by Jonathan Heard [ 21/Aug/23 ]

We recently had a lot of those log entries in our logs width the additional log:

 Exception in thread "Thread-8340" java.lang.IllegalStateException: MgnlContext is not set for this thread

where the Thread number changed over time and in the end lead to an Out of Memory error and a crash of magnolia. Unfortunately we can not easily reproduce this. Maybe a race condition? 

023-08-18 10:33:34,651 ERROR info.magnolia.context.MgnlContext                 : MgnlContext is not initialized. This could happen if the request does not go through the Magnolia default filters.
java.lang.IllegalStateException: MgnlContext is not set for this thread
    at info.magnolia.context.MgnlContext.getInstance(MgnlContext.java:282) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.context.MgnlContext.getUser(MgnlContext.java:91) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.jcr.wrapper.MgnlPropertySettingContentDecorator.getCurrentUserName(MgnlPropertySettingContentDecorator.java:728) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.jcr.wrapper.MgnlPropertySettingContentDecorator.updateLastModified(MgnlPropertySettingContentDecorator.java:622) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.jcr.wrapper.MgnlPropertySettingContentDecorator.updateLastModified(MgnlPropertySettingContentDecorator.java:627) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.jcr.wrapper.MgnlPropertySettingNodeWrapper.updateLastModified(MgnlPropertySettingNodeWrapper.java:262) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.jcr.wrapper.MgnlPropertySettingNodeWrapper.addNode(MgnlPropertySettingNodeWrapper.java:214) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.jcr.wrapper.DelegateNodeWrapper.addNode(DelegateNodeWrapper.java:129) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.jcr.decoration.ContentDecoratorNodeWrapper.addNode(ContentDecoratorNodeWrapper.java:131) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.audit.MgnlAuditLoggingContentDecoratorNodeWrapper.addNode(MgnlAuditLoggingContentDecoratorNodeWrapper.java:84) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.jcr.wrapper.DelegateNodeWrapper.addNode(DelegateNodeWrapper.java:129) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.jcr.decoration.ContentDecoratorNodeWrapper.addNode(ContentDecoratorNodeWrapper.java:131) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.jcr.wrapper.MagnoliaSessionContentDecorator$1.addNode(MagnoliaSessionContentDecorator.java:67) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.contenttags.manager.TagManager.getOrCreate(TagManager.java:172) ~[magnolia-content-tags-core-2.0.4.jar:?]
    at info.magnolia.contenttags.manager.TagManager.getOrCreateTag(TagManager.java:162) ~[magnolia-content-tags-core-2.0.4.jar:?]
    at info.magnolia.contenttags.TagsModule.lambda$null$1(TagsModule.java:142) ~[magnolia-content-tags-core-2.0.4.jar:?]
    at info.magnolia.observation.DeferringEventListener$ObservationBasedDelayedExecutor$1.run(DeferringEventListener.java:102) [magnolia-core-6.2.33.jar:?]
    at info.magnolia.cms.util.DelayedExecutor$RunnableWrapper.run(DelayedExecutor.java:103) [magnolia-core-6.2.33.jar:?]
    at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(Unknown Source) [concurrent-1.3.4.jar:?]
    at java.lang.Thread.run(Thread.java:829) [?:?]
Exception in thread "Thread-8340" java.lang.IllegalStateException: MgnlContext is not set for this thread
    at info.magnolia.context.MgnlContext.getInstance(MgnlContext.java:282)
    at info.magnolia.context.MgnlContext.getUser(MgnlContext.java:91)
    at info.magnolia.jcr.wrapper.MgnlPropertySettingContentDecorator.getCurrentUserName(MgnlPropertySettingContentDecorator.java:728)
    at info.magnolia.jcr.wrapper.MgnlPropertySettingContentDecorator.updateLastModified(MgnlPropertySettingContentDecorator.java:622)
    at info.magnolia.jcr.wrapper.MgnlPropertySettingContentDecorator.updateLastModified(MgnlPropertySettingContentDecorator.java:627)
    at info.magnolia.jcr.wrapper.MgnlPropertySettingNodeWrapper.updateLastModified(MgnlPropertySettingNodeWrapper.java:262)
    at info.magnolia.jcr.wrapper.MgnlPropertySettingNodeWrapper.addNode(MgnlPropertySettingNodeWrapper.java:214)
    at info.magnolia.jcr.wrapper.DelegateNodeWrapper.addNode(DelegateNodeWrapper.java:129)
    at info.magnolia.jcr.decoration.ContentDecoratorNodeWrapper.addNode(ContentDecoratorNodeWrapper.java:131)
    at info.magnolia.audit.MgnlAuditLoggingContentDecoratorNodeWrapper.addNode(MgnlAuditLoggingContentDecoratorNodeWrapper.java:84)
    at info.magnolia.jcr.wrapper.DelegateNodeWrapper.addNode(DelegateNodeWrapper.java:129)
    at info.magnolia.jcr.decoration.ContentDecoratorNodeWrapper.addNode(ContentDecoratorNodeWrapper.java:131)
    at info.magnolia.jcr.wrapper.MagnoliaSessionContentDecorator$1.addNode(MagnoliaSessionContentDecorator.java:67)
    at info.magnolia.contenttags.manager.TagManager.getOrCreate(TagManager.java:172)
    at info.magnolia.contenttags.manager.TagManager.getOrCreateTag(TagManager.java:162)
    at info.magnolia.contenttags.TagsModule.lambda$null$1(TagsModule.java:142)
    at info.magnolia.observation.DeferringEventListener$ObservationBasedDelayedExecutor$1.run(DeferringEventListener.java:102)
    at info.magnolia.cms.util.DelayedExecutor$RunnableWrapper.run(DelayedExecutor.java:103)
    at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(Unknown Source)
    at java.base/java.lang.Thread.run(Thread.java:829)
2023-08-18 10:33:47,320 ERROR info.magnolia.context.MgnlContext                 : MgnlContext is not initialized. This could happen if the request does not go through the Magnolia default filters.
java.lang.IllegalStateException: MgnlContext is not set for this thread
Exception in thread "Thread-8342" java.lang.IllegalStateException: MgnlContext is not set for this thread
    at info.magnolia.context.MgnlContext.getInstance(MgnlContext.java:282)
    at info.magnolia.context.MgnlContext.getUser(MgnlContext.java:91)
    at info.magnolia.context.MgnlContext.getInstance(MgnlContext.java:282) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.jcr.wrapper.MgnlPropertySettingContentDecorator.getCurrentUserName(MgnlPropertySettingContentDecorator.java:728)
    at info.magnolia.jcr.wrapper.MgnlPropertySettingContentDecorator.updateLastModified(MgnlPropertySettingContentDecorator.java:622)
    at info.magnolia.jcr.wrapper.MgnlPropertySettingContentDecorator.updateLastModified(MgnlPropertySettingContentDecorator.java:627)
    at info.magnolia.context.MgnlContext.getUser(MgnlContext.java:91) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.jcr.wrapper.MgnlPropertySettingNodeWrapper.updateLastModified(MgnlPropertySettingNodeWrapper.java:262)
    at info.magnolia.jcr.wrapper.MgnlPropertySettingNodeWrapper.addNode(MgnlPropertySettingNodeWrapper.java:214)
    at info.magnolia.jcr.wrapper.MgnlPropertySettingContentDecorator.getCurrentUserName(MgnlPropertySettingContentDecorator.java:728) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.jcr.wrapper.DelegateNodeWrapper.addNode(DelegateNodeWrapper.java:129)
    at info.magnolia.jcr.decoration.ContentDecoratorNodeWrapper.addNode(ContentDecoratorNodeWrapper.java:131)
    at info.magnolia.audit.MgnlAuditLoggingContentDecoratorNodeWrapper.addNode(MgnlAuditLoggingContentDecoratorNodeWrapper.java:84)
    at info.magnolia.jcr.wrapper.DelegateNodeWrapper.addNode(DelegateNodeWrapper.java:129)
    at info.magnolia.jcr.wrapper.MgnlPropertySettingContentDecorator.updateLastModified(MgnlPropertySettingContentDecorator.java:622) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.jcr.wrapper.MgnlPropertySettingContentDecorator.updateLastModified(MgnlPropertySettingContentDecorator.java:627) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.jcr.wrapper.MgnlPropertySettingNodeWrapper.updateLastModified(MgnlPropertySettingNodeWrapper.java:262) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.jcr.wrapper.MgnlPropertySettingNodeWrapper.addNode(MgnlPropertySettingNodeWrapper.java:214) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.jcr.wrapper.DelegateNodeWrapper.addNode(DelegateNodeWrapper.java:129) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.jcr.decoration.ContentDecoratorNodeWrapper.addNode(ContentDecoratorNodeWrapper.java:131) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.audit.MgnlAuditLoggingContentDecoratorNodeWrapper.addNode(MgnlAuditLoggingContentDecoratorNodeWrapper.java:84) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.jcr.wrapper.DelegateNodeWrapper.addNode(DelegateNodeWrapper.java:129) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.jcr.decoration.ContentDecoratorNodeWrapper.addNode(ContentDecoratorNodeWrapper.java:131) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.jcr.decoration.ContentDecoratorNodeWrapper.addNode(ContentDecoratorNodeWrapper.java:131)
    at info.magnolia.jcr.wrapper.MagnoliaSessionContentDecorator$1.addNode(MagnoliaSessionContentDecorator.java:67)
    at info.magnolia.contenttags.manager.TagManager.getOrCreate(TagManager.java:172)
    at info.magnolia.jcr.wrapper.MagnoliaSessionContentDecorator$1.addNode(MagnoliaSessionContentDecorator.java:67) ~[magnolia-core-6.2.33.jar:?]
    at info.magnolia.contenttags.manager.TagManager.getOrCreateTag(TagManager.java:162)
    at info.magnolia.contenttags.manager.TagManager.getOrCreate(TagManager.java:172) ~[magnolia-content-tags-core-2.0.4.jar:?]
    at info.magnolia.contenttags.manager.TagManager.getOrCreateTag(TagManager.java:162) ~[magnolia-content-tags-core-2.0.4.jar:?]
    at info.magnolia.contenttags.TagsModule.lambda$null$1(TagsModule.java:142) ~[magnolia-content-tags-core-2.0.4.jar:?]
    at info.magnolia.contenttags.TagsModule.lambda$null$1(TagsModule.java:142)
    at info.magnolia.observation.DeferringEventListener$ObservationBasedDelayedExecutor$1.run(DeferringEventListener.java:102) [magnolia-core-6.2.33.jar:?]
    at info.magnolia.observation.DeferringEventListener$ObservationBasedDelayedExecutor$1.run(DeferringEventListener.java:102)
    at info.magnolia.cms.util.DelayedExecutor$RunnableWrapper.run(DelayedExecutor.java:103) [magnolia-core-6.2.33.jar:?]
    at info.magnolia.cms.util.DelayedExecutor$RunnableWrapper.run(DelayedExecutor.java:103)
    at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(Unknown Source) [concurrent-1.3.4.jar:?]
    at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(Unknown Source)
    at java.lang.Thread.run(Thread.java:829) [?:?]
    at java.base/java.lang.Thread.run(Thread.java:829)

....


Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "RxIoScheduler-2 (Evictor)"
Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "HeartBeatProvider_heartBeatSenderService-0"
Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "Atmosphere-Scheduler-26330"
Exception in thread "javamelody" java.lang.OutOfMemoryError: Java heap space
Exception in thread "jackrabbit-pool-8" java.lang.OutOfMemoryError: Java heap space
2023-08-19 17:08:03,509 WARN  io.netty.util.concurrent.SingleThreadEventExecutor: Unexpected exception from an event executor:
java.lang.OutOfMemoryError: Java heap space

 

Comment by Sebastian Paasch [ 28/Aug/23 ]

Hi, @Jonathan

yes - it is the same Stacktrace. But I dont think that is the reason of your OutOfMemory - I dont think listener will repeat until the event can be consumed successfully, so there shouldnt be a memory leak on this. But I havent proven it.

Thanks at Magnolia, we will soon check if 2.0.5 will fix this massive error-logging

Comment by Jonathan Heard [ 30/Aug/23 ]

Thanks for the fast update @Sebastian. I think we are iterating over a list of pages in our code and for all of them we query the tags. And when the tag manager then always use another thread, I assume this can easily lead to an outOfMemoryException or? But anyway, when do you plan to publish the new version, so we can test it? Best regards

Comment by Laura Delnevo [ 31/Aug/23 ]

Hi jheard the fix will be in the next release 6.2.39

Generated at Mon Feb 12 00:25:16 CET 2024 using Jira 9.4.2#940002-sha1:46d1a51de284217efdcb32434eab47a99af2938b.