Openbravo Issue Tracking System - POS2
View Issue Details
IDProjectCategoryView StatusDate SubmittedLast Update
0050768POS2Corepublic2022-11-08 08:392022-11-08 10:07
ReporterAugustoMauch 
Assigned ToAugustoMauch 
PrioritynormalSeveritymajorReproducibilityhave not tried
StatusclosedResolutionfixed 
PlatformOS5OS Version
Product Version 
Target VersionFixed in Version 
Merge Request Statusapproved
Review Assigned To
OBNetwork customerNo
Support ticket
Regression level
Regression date
Regression introduced in release
Regression introduced by commit
Triggers an Emergency PackNo
Summary0050768: 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
related to defect 0050545 closed Triage Platform Base "Session is in an unrecoverable offline" message displayed even if failing request was not done to backend of Openbravo 
depends on backport 005076922Q4.1 closed AugustoMauch When a session is killed the log should be more verbose to know why it was killed 
depends on backport 005077022Q3.3 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 08:39AugustoMauchNew Issue
2022-11-08 08:39AugustoMauchAssigned To => Triage Platform Base
2022-11-08 08:39AugustoMauchOBNetwork customer => No
2022-11-08 08:39AugustoMauchTriggers an Emergency Pack => No
2022-11-08 08:39AugustoMauchAssigned ToTriage Platform Base => AugustoMauch
2022-11-08 08:39AugustoMauchStatusnew => scheduled
2022-11-08 08:49AugustoMauchDescription Updatedbug_revision_view_page.php?rev_id=25053#r25053
2022-11-08 08:53hgbotMerge Request Status => open
2022-11-08 08:53hgbotNote Added: 0143208
2022-11-08 09:32AugustoMauchRelationship addedrelated to 0050545
2022-11-08 09:32AugustoMauchStatusscheduled => acknowledged
2022-11-08 09:32AugustoMauchStatusacknowledged => scheduled
2022-11-08 10:07hgbotMerge Request Statusopen => approved
2022-11-08 10:07hgbotResolutionopen => fixed
2022-11-08 10:07hgbotStatusscheduled => closed
2022-11-08 10:07hgbotNote Added: 0143225
2022-11-08 10:07hgbotFixed in Version => PR23Q1
2022-11-08 10:07hgbotNote Added: 0143226

Notes
(0143208)
hgbot   
2022-11-08 08:53   
Merge Request created: https://gitlab.com/openbravo/product/openbravo/-/merge_requests/751 [^]
(0143225)
hgbot   
2022-11-08 10:07   
Merge request merged: https://gitlab.com/openbravo/product/openbravo/-/merge_requests/751 [^]
(0143226)
hgbot   
2022-11-08 10:07   
Directly closing issue as related merge request is already approved.

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

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

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