Openbravo Issue Tracking System - POS2
View Issue Details
IDProjectCategoryView StatusDate SubmittedLast Update
0050769POS2Corepublic2022-11-08 08:392022-11-08 10:07
ReporterAugustoMauch 
Assigned ToAugustoMauch 
PrioritynormalSeveritymajorReproducibilityhave not tried
StatusclosedResolutionfixed 
PlatformOS5OS Version
Product Version 
Target Version22Q4.1Fixed in Version 
Merge Request Status
Review Assigned To
OBNetwork customer
Support ticket
Regression level
Regression date
Regression introduced in release
Regression introduced by commit
Triggers an Emergency PackNo
Summary0050769: When a session is killed the log should be more verbose to know why it was killed
DescriptionWe are currently trying to understand why sometimes Openbravo sessions are terminated without a clear explanation. Sessions are sometimes terminated even if the user has not logged out and when he was actively using that sessions (i.e. requests that update the session timeout were taking place).

At this point our best option is to increase the verbosity of the log written when a session is cleaned, to know not only how many sessions remain active but also the stack trace that will add additional info about the termination reason. This log will be verbose but only needed in some specific moments, so it should be logged using the trace level.

For instance when logging out, the session termination will be written in the log like this:

2022-11-08 08:47:36,977 [http-nio-8080-exec-2] TRACE org.openbravo.erpCommon.security.SessionListener - Stack trace:
org.openbravo.base.exception.OBException: null
    at org.openbravo.erpCommon.security.SessionListener.deactivateSession(SessionListener.java:198) [classes/:?]
    at org.openbravo.erpCommon.security.SessionListener.sessionDestroyed(SessionListener.java:70) [classes/:?]
    at org.apache.catalina.session.StandardSession.expire(StandardSession.java:824) [catalina.jar:8.5.24]
    at org.apache.catalina.session.StandardSession.expire(StandardSession.java:766) [catalina.jar:8.5.24]
    at org.apache.catalina.session.StandardSession.invalidate(StandardSession.java:1266) [catalina.jar:8.5.24]
    at org.apache.catalina.session.StandardSessionFacade.invalidate(StandardSessionFacade.java:171) [catalina.jar:8.5.24]
    at org.openbravo.client.kernel.BaseKernelServlet.invalidateSession(BaseKernelServlet.java:96) [classes/:?]
    at org.openbravo.base.secureApp.HttpSecureAppServlet.logout(HttpSecureAppServlet.java:598) [classes/:?]
    at org.openbravo.client.kernel.BaseKernelServlet.service(BaseKernelServlet.java:63) [classes/:?]
    at org.openbravo.client.kernel.KernelServlet.service(KernelServlet.java:170) [classes/:?]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:742) [servlet-api.jar:?]
Steps To ReproduceWe have not been able to create steps to reproduce for this issue. This is what we see when analyzing the access log:


     147.161.232.121 - - [30/Oct/2022:19:46:11 +0100] TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256 "POST /openbravo/org.openbravo.mobile.core.service.jsonrest/org.openbravo.certification.france.ticketreprint.ProcessTicketReprint?$timeout=15000 HTTP/1.1" 200 253 8596 105 "https://agapes.cloud.openbravo.com/openbravo/web/pos/" [^] "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.45 Safari/537.36" "F93B9F1CAAFF89DEF2675FD4793637C4"
    147.161.232.121 - - [30/Oct/2022:19:46:11 +0100] TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256 "POST /openbravo/org.openbravo.mobile.core.service.jsonrest/org.openbravo.retail.posterminal.CheckTerminalAuth?$timeout=15000&ignoreForSessionTimeout=1&IsAjaxCall=1 HTTP/1.1" 200 285 1757 9 "https://agapes.cloud.openbravo.com/openbravo/web/pos/" [^] "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.45 Safari/537.36" "F93B9F1CAAFF89DEF2675FD4793637C4"
    147.161.232.121 - - [30/Oct/2022:19:46:11 +0100] TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256 "POST /openbravo/org.openbravo.mobile.core.service.jsonrest/org.openbravo.retail.posterminal.CheckTerminalAuth?$timeout=15000&ignoreForSessionTimeout=1&IsAjaxCall=1 HTTP/1.1" 200 286 1757 8 "https://agapes.cloud.openbravo.com/openbravo/web/pos/" [^] "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.45 Safari/537.36" "F93B9F1CAAFF89DEF2675FD4793637C4"
    147.161.232.121 - - [30/Oct/2022:19:46:11 +0100] TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256 "POST /openbravo/org.openbravo.mobile.core.service.jsonrest/org.openbravo.retail.posterminal.CheckTerminalAuth?$timeout=15000&ignoreForSessionTimeout=1&IsAjaxCall=1 HTTP/1.1" 200 286 1757 9 "https://agapes.cloud.openbravo.com/openbravo/web/pos/" [^] "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.45 Safari/537.36" "F93B9F1CAAFF89DEF2675FD4793637C4"
    165.225.20.117 - - [30/Oct/2022:19:46:23 +0100] TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256 "POST /openbravo/org.openbravo.mobile.core.service.jsonrest/org.openbravo.mobile.core.TerminalLogLoader?$timeout=300000&IsAjaxCall=1&ignoreForSessionTimeout=1 HTTP/1.1" 200 253 13945 180 "https://agapes.cloud.openbravo.com/openbravo/web/pos/" [^] "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.45 Safari/537.36" "F93B9F1CAAFF89DEF2675FD4793637C4"
    165.225.20.117 - - [30/Oct/2022:19:46:23 +0100] TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256 "POST /openbravo/org.openbravo.mobile.core.service.jsonrest/org.openbravo.retail.posterminal.CheckTerminalAuth?$timeout=15000&ignoreForSessionTimeout=1&IsAjaxCall=1 HTTP/1.1" 200 286 1756 9 "https://agapes.cloud.openbravo.com/openbravo/web/pos/" [^] "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.45 Safari/537.36" "F93B9F1CAAFF89DEF2675FD4793637C4"
    165.225.20.117 - - [30/Oct/2022:19:46:23 +0100] TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256 "POST /openbravo/org.openbravo.mobile.core.service.jsonrest/org.openbravo.retail.posterminal.CheckTerminalAuth?$timeout=15000&ignoreForSessionTimeout=1&IsAjaxCall=1 HTTP/1.1" 200 285 2050 3 "https://agapes.cloud.openbravo.com/openbravo/web/pos/" [^] "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.45 Safari/537.36" "F93B9F1CAAFF89DEF2675FD4793637C4"
    165.225.20.117 - - [30/Oct/2022:19:46:23 +0100] TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256 "POST /openbravo/org.openbravo.mobile.core.service.jsonrest/org.openbravo.retail.posterminal.CheckTerminalAuth?$timeout=15000&ignoreForSessionTimeout=1&IsAjaxCall=1 HTTP/1.1" 200 286 1756 8 "https://agapes.cloud.openbravo.com/openbravo/web/pos/" [^] "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.45 Safari/537.36" "F93B9F1CAAFF89DEF2675FD4793637C4"
    165.225.20.117 - - [30/Oct/2022:19:46:47 +0100] TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256 "POST /openbravo/org.openbravo.mobile.core.service.jsonrest/com.openbravo.flunch.integration.comarch.server.ComarchServerStateCheck?$timeout=15000&ignoreForSessionTimeout=1&IsAjaxCall=1 HTTP/1.1" 200 291 1957 2 "https://agapes.cloud.openbravo.com/openbravo/web/pos/" [^] "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.45 Safari/537.36" "F93B9F1CAAFF89DEF2675FD4793637C4"
    165.225.20.117 - - [30/Oct/2022:19:47:47 +0100] TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256 "POST /openbravo/org.openbravo.mobile.core.service.jsonrest/com.openbravo.flunch.integration.comarch.server.ComarchServerStateCheck?$timeout=15000&ignoreForSessionTimeout=1&IsAjaxCall=1 HTTP/1.1" 401 147 1957 3 "https://agapes.cloud.openbravo.com/openbravo/web/pos/" [^] "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.45 Safari/537.36" "F93B9F1CAAFF89DEF2675FD4793637C4"

User is working as usual, making requests that update the session timeout (see ProcessTicketReprint), and suddenly a request returns with a 401 error (see latest) and when checking in the backend, we can see the Openbravo session is not active and its latest update was done around the time when the latest request was received.
Proposed Solution
Additional Information
TagsNo tags attached.
Relationships
blocks defect 0050768 closed AugustoMauch When a session is killed the log should be more verbose to know why it was killed 
Attached Files
Issue History
Date ModifiedUsernameFieldChange
2022-11-08 09:32AugustoMauchTypedefect => backport
2022-11-08 09:32AugustoMauchTarget Version => 22Q4.1
2022-11-08 09:36hgbotNote Added: 0143214
2022-11-08 10:07hgbotNote Added: 0143227
2022-11-08 10:07hgbotResolutionopen => fixed
2022-11-08 10:07hgbotStatusscheduled => closed
2022-11-08 10:07hgbotFixed in Version => PR22Q4
2022-11-08 10:07hgbotNote Added: 0143228

Notes
(0143214)
hgbot   
2022-11-08 09:36   
Merge Request created: https://gitlab.com/openbravo/product/openbravo/-/merge_requests/753 [^]
(0143227)
hgbot   
2022-11-08 10:07   
Merge request merged: https://gitlab.com/openbravo/product/openbravo/-/merge_requests/753 [^]
(0143228)
hgbot   
2022-11-08 10:07   
Directly closing issue as related merge request is already approved.

Repository: https://gitlab.com/openbravo/product/openbravo [^]
Changeset: 62dc59af1d11da82ab2c9e8aff19f2f58250b7d9
Author: Augusto Mauch <augusto.mauch@openbravo.com>
Date: 08-11-2022 09:07:48
URL: https://gitlab.com/openbravo/product/openbravo/-/commit/62dc59af1d11da82ab2c9e8aff19f2f58250b7d9 [^]

Fixes ISSUE-50769: Increases the log verbosity when a session is destroyed

---
M src/org/openbravo/erpCommon/security/SessionListener.java
---