[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: |
|
||||||||||||
| 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: | |||||||||||||
| 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
Expected Actual 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 |
| 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 |