0050768: 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.

Tags

No tags attached.

Attached Files

Relationships [ Relation Graph ] [ Dependency Graph ]

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	0050769	22Q4.1	closed	AugustoMauch	When a session is killed the log should be more verbose to know why it was killed
depends on	backport	0050770	22Q3.3	closed	AugustoMauch	When a session is killed the log should be more verbose to know why it was killed

Notes
(0143208) hgbot (developer) 2022-11-08 08:53	Merge Request created: https://gitlab.com/openbravo/product/openbravo/-/merge_requests/751 [^]

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

(0143226) 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: 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 ---

Issue History
Date Modified	Username	Field	Change
2022-11-08 08:39	AugustoMauch	New Issue
2022-11-08 08:39	AugustoMauch	Assigned To	=> Triage Platform Base
2022-11-08 08:39	AugustoMauch	Triggers an Emergency Pack	=> No
2022-11-08 08:39	AugustoMauch	Assigned To	Triage Platform Base => AugustoMauch
2022-11-08 08:39	AugustoMauch	Status	new => scheduled
2022-11-08 08:49	AugustoMauch	Description Updated	View Revisions
2022-11-08 08:53	hgbot	Note Added: 0143208
2022-11-08 09:32	AugustoMauch	Relationship added	related to 0050545
2022-11-08 09:32	AugustoMauch	Status	scheduled => acknowledged
2022-11-08 09:32	AugustoMauch	Status	acknowledged => scheduled
2022-11-08 10:07	hgbot	Resolution	open => fixed
2022-11-08 10:07	hgbot	Status	scheduled => closed
2022-11-08 10:07	hgbot	Note Added: 0143225
2022-11-08 10:07	hgbot	Fixed in Version	=> PR23Q1
2022-11-08 10:07	hgbot	Note Added: 0143226