0051532: IE prints too verbose log when queue size limit is reached

Description

When trying to process import entries and the limit of the executor service queue size (import.max.task.queue.size) is reached, a message with warn level is logged including the stack trace. This log is too verbose and typically useless, specially taking into account it gets typically repeated several times in a short period of time.

Steps To Reproduce

1. To emulate this situation install https://gitlab.com/openbravo/tools/platform/org.openbravo.util.ieloadsim [^]
2. Log in BO
3. Launch a IE load simulation executing "Simulate IE Load" with these parameters:

"Data Type 1",
"t1Entries": 1500, --> Assuming max queue is kept as the 1K default
"t1T": 1,
"t1Cycles": 1,
"t1Delay": 0,
"t1ExecTime": 1000,
"t1Keys": 1500

4. Check openbravo log is full of

2023-02-02 10:20:54,689 [Import Entry Manager Main] WARN org.openbravo.service.importprocess.ImportEntryManager - Exception while trying to add runnable key:1495 cycle: 15 processing: none
   queue: (1) - [2CCE3563803E429492CD8139ADB740D1] to the list of tasks to run
java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@39bae2a1[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@c11867c[Wrapped task = key:1495 cycle: 15 processing: none
   queue: (1) - [2CCE3563803E429492CD8139ADB740D1]]] rejected from java.util.concurrent.ThreadPoolExecutor@2aa57904[Running, pool size = 11, active threads = 11, queued tasks = 1000, completed tasks = 360]
    at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2055) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:825) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1355) ~[?:?]
    at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:118) ~[?:?]
    at org.openbravo.service.importprocess.ImportEntryManager.submitRunnable(ImportEntryManager.java:270) [classes/:?]
    at jdk.internal.reflect.GeneratedMethodAccessor458.invoke(Unknown Source) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
    at org.jboss.weld.bean.proxy.AbstractBeanInstance.invoke(AbstractBeanInstance.java:38) [weld-core-impl-3.1.7.SP1.jar:3.1.7.SP1]
    at org.jboss.weld.bean.proxy.ProxyMethodHandler.invoke(ProxyMethodHandler.java:106) [weld-core-impl-3.1.7.SP1.jar:3.1.7.SP1]
    at org.openbravo.service.importprocess.ImportEntryManager$Proxy$_$$_WeldClientProxy.submitRunnable(Unknown Source) [classes/:?]
    at org.openbravo.service.importprocess.ImportEntryProcessor.assignEntryToThread(ImportEntryProcessor.java:213) [classes/:?]
    at org.openbravo.service.importprocess.ImportEntryProcessor.handleImportEntry(ImportEntryProcessor.java:152) [classes/:?]
    at org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIEP$LoadSimulatorIEP1$Proxy$_$$_WeldClientProxy.handleImportEntry(Unknown Source) [classes/:?]
    at org.openbravo.service.importprocess.ImportEntryManager.handleImportEntry(ImportEntryManager.java:406) [classes/:?]
    at org.openbravo.service.importprocess.ImportEntryManager$ImportEntryManagerThread.run(ImportEntryManager.java:675) [classes/:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
    at java.lang.Thread.run(Thread.java:829) [?:?]

Proposed Solution

Remove stack trace from the warn log and include currently queued runnables as well as the limit to easily identify the case.

Keep stack trace at trace level in case some additional debugging is required for some other case.

Tags

No tags attached.

Attached Files

Relationships [ Relation Graph ] [ Dependency Graph ]

blocks

design defect

0036162

acknowledged

Triage Platform Base

clean up openbravo.log

Notes
(0146158) hgbot (developer) 2023-02-02 10:56	Merge Request created: https://gitlab.com/openbravo/product/openbravo/-/merge_requests/817 [^]

(0146552) hgbot (developer) 2023-02-15 08:29	Merge request merged: https://gitlab.com/openbravo/product/openbravo/-/merge_requests/817 [^]

(0146553) hgbot (developer) 2023-02-15 08:29	Directly closing issue as related merge request is already approved. Repository: https://gitlab.com/openbravo/product/openbravo [^] Changeset: 8b879d824aa539259c5c63059b022d30d42c4cc7 Author: Asier Lostalé <asier.lostale@openbravo.com> Date: 15-02-2023 07:26:32 URL: https://gitlab.com/openbravo/product/openbravo/-/commit/8b879d824aa539259c5c63059b022d30d42c4cc7 [^] fixed ISSUE-51532: IE prints too verbose log when queue size limit is reached * Removes stack trace unless the log level is trace. * Adds information about the currently queued runnables and the limit. --- M src/org/openbravo/service/importprocess/ImportEntryManager.java ---

Issue History
Date Modified	Username	Field	Change
2023-02-02 10:52	alostale	New Issue
2023-02-02 10:52	alostale	Assigned To	=> Triage Platform Base
2023-02-02 10:52	alostale	Modules	=> Core
2023-02-02 10:52	alostale	Triggers an Emergency Pack	=> No
2023-02-02 10:56	hgbot	Note Added: 0146158
2023-02-02 10:56	alostale	Assigned To	Triage Platform Base => alostale
2023-02-02 10:57	alostale	Relationship added	blocks 0036162
2023-02-02 11:04	gorkaion	Issue Monitored: gorkaion
2023-02-15 08:29	hgbot	Resolution	open => fixed
2023-02-15 08:29	hgbot	Status	new => closed
2023-02-15 08:29	hgbot	Note Added: 0146552
2023-02-15 08:29	hgbot	Fixed in Version	=> PR23Q2
2023-02-15 08:29	hgbot	Note Added: 0146553