0050769: When a session is killed the log should be more verbose to know why it was killed

Description

We 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 Reproduce

We 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.

Notes
(0143214) hgbot (developer) 2022-11-08 09:36	Merge Request created: https://gitlab.com/openbravo/product/openbravo/-/merge_requests/753 [^]

(0143227) hgbot (developer) 2022-11-08 10:07	Merge request merged: https://gitlab.com/openbravo/product/openbravo/-/merge_requests/753 [^]

(0143228) hgbot (developer) 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 ---

Issue History
Date Modified	Username	Field	Change
2022-11-08 09:32	AugustoMauch	Type	defect => backport
2022-11-08 09:32	AugustoMauch	Target Version	=> 22Q4.1
2022-11-08 09:36	hgbot	Note Added: 0143214
2022-11-08 10:07	hgbot	Note Added: 0143227
2022-11-08 10:07	hgbot	Resolution	open => fixed
2022-11-08 10:07	hgbot	Status	scheduled => closed
2022-11-08 10:07	hgbot	Fixed in Version	=> PR22Q4
2022-11-08 10:07	hgbot	Note Added: 0143228