v8.2 - java.lang.IllegalStateException: Invalid for read: id=node123456

[Nicolas Micoud]

Hi,

I've updated a 8.2 instance last wednesday (on branch 8.2, commit 89a095a) but it was not used because it was holidays times.
But since this morning, users are ejected without any noticeable reason.


Checking logs, I found this :

2021-02-22 09:37:42.720:WARN:oejs.HttpChannel:qtp131042621-22: /webui/index.zul
java.lang.IllegalStateException: Invalid for read: id=node0q0quv3h1w22who6u8hpe6zm12 created=1613982381055 accessed=1613983062654 lastaccessed=1613983062650 maxInactiveMs=3600000 expiry=1613986662654
    at org.eclipse.jetty.server.session.Session.checkValidForRead(Session.java:692)
    at org.eclipse.jetty.server.session.Session.getAttribute(Session.java:715)
    at org.zkoss.zk.ui.http.SimpleSession.getAttribute(SimpleSession.java:199)
    at org.zkoss.zk.ui.sys.SessionsCtrl.requestExit(SessionsCtrl.java:130)
    at org.zkoss.zk.ui.http.DHtmlLayoutServlet.doGet(DHtmlLayoutServlet.java:154)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
    at org.eclipse.jetty.servlet.ServletHolder$NotAsync.service(ServletHolder.java:1418)
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:763)
    at org.eclipse.jetty.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1633)
    at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:228)
    at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193)
    at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1609)
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:561)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
    at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:602)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1612)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1434)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501)
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1582)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1349)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
    at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234)
    at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
    at org.eclipse.jetty.server.Server.handle(Server.java:516)
    at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
    at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:556)
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
    at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:773)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:905)
    at java.base/java.lang.Thread.run(Thread.java:834)
    
    

Before the upgrade, sources were based on sources of 2021-01-18 (so until commit 74dbe8a) and it was ok.

ZK_SESSION_TIMEOUT_IN_SECONDS is set to -2

I'm totally lost, any idea where to look ?

Thanks,

Nicolas

[Nicolas Micoud]

Making some tests, I was able to reproduce it on https://test-oracle.idempiere.org/webui

I just logged in with SuperUser (on System) tenant, then open a window.
Then, I did something else and after some minutes, when I return to this instance, I found (see screenshot):

Nicolas

[Nicolas Micoud]

Here's what happened in the console. Every 3 minutes, an error which leads to this popup

I was using this test server for testing purpose before 2021-01-15 (see https://mattermost.idempiere.org/idempiere/pl/wh98zchoz3n3dqj55cm77kgzce) and there was not such issue.
So I think something has been done in the last month.
Checking commits, I would say this is related to https://idempiere.atlassian.net/browse/IDEMPIERE-4676 with those 2 commits (https://github.com/idempiere/idempiere/commit/f27e58ce58e1b357852a2f8eadea9ca36cdee2d2 and https://github.com/idempiere/idempiere/commit/26f883a76dd8bef1768a4682690f4ef93eca6928).
But that's far beyond my skills

wdyt?

Regards,

Nicolas

[Heng Sin Low]

The interesting thing here is the same error doesn't happens at test.idempiere.org

--
You received this message because you are subscribed to the Google Groups "iDempiere" group.
To unsubscribe from this group and stop receiving emails from it, send an email to idempiere+...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/idempiere/2bf1a3a6-71de-4e3f-b865-632cd15d7cc0n%40googlegroups.com.

[Dirk Niemeyer]

On the error log of nginx proxy of test-oracle I can see a number of
entries like
2021/02/22 14:22:44 [warn] 25491#25491: *130933 an upstream response is
buffered to a temporary file /var/lib/nginx/proxy/9/06/0000000069 while
reading upstream, client: xxx.xxx.xxx.xxx, server:
test-oracle.idempiere.org, request: "GET
/webui/zkau/web/afdf99ee/js/zk.wpd HTTP/2.0", upstream:
"http://127.0.0.1:8000/webui/zkau/web/afdf99ee/js/zk.wpd", host:
"test-oracle.idempiere.org", ref
errer: "https://test-oracle.idempiere.org/webui/index.zul"

and

2021/02/22 14:23:45 [error] 25491#25491: *130933 upstream timed out
(110: Connection timed out) while reading response header from upstream,
client: xxx.xxx.xxx.xxx, server: test-oracle.idempiere, request: "POST
/webui/zkau/comet HTTP/2.0", upstream:
"http://127.0.0.1:8000/webui/zkau/comet", host:
"test-oracle.idempiere.org", referrer:
"https://test-oracle.idempiere.org/webui/index.
zul"

Does that tell anything?

idempiere log only shows some (timely unrelated it seems) entries like
14:31:31.378-----------> ZkAtmosphereHandler.warn: Could not find
session: /webui/zkau/comet [178]

Regards,

Dirk Niemeyer



Am 22.02.21 um 13:53 schrieb Heng Sin Low:

>>>> *2021-02-22 09:37:42.720:WARN:oejs.HttpChannel:qtp131042621-22:
>>>> /webui/index.zuljava.lang.IllegalStateException: Invalid for read:

>>>> at java.base/java.lang.Thread.run(Thread.java:834)*

>>>>
>>>>
>>>> Before the upgrade, sources were based on sources of 2021-01-18 (so
>>>> until commit 74dbe8a) and it was ok.
>>>>
>>>> ZK_SESSION_TIMEOUT_IN_SECONDS is set to -2
>>>>
>>>> I'm totally lost, any idea where to look ?
>>>>
>>>> Thanks,
>>>>
>>>> Nicolas
>>>>
>>> --
>> You received this message because you are subscribed to the Google Groups
>> "iDempiere" group.
>> To unsubscribe from this group and stop receiving emails from it, send an
>> email to idempiere+...@googlegroups.com.
>> To view this discussion on the web visit
>> https://groups.google.com/d/msgid/idempiere/2bf1a3a6-71de-4e3f-b865-632cd15d7cc0n%40googlegroups.com

>> <https://groups.google.com/d/msgid/idempiere/2bf1a3a6-71de-4e3f-b865-632cd15d7cc0n%40googlegroups.com?utm_medium=email&utm_source=footer>
>> .
>>
>

[Carlos Antonio Ruiz Gomez]

I just tested from here in test-oracle.idempiere.org and timeout it behaves as expected:

"The page or component you request is no longer available. This is normally caused by timeout or rebooting the server."

Tested with firefox and chromium

El 22/2/21 a las 13:53, Heng Sin Low escribió:

The interesting thing here is the same error doesn't happens at test.idempiere.org

[Carlos Antonio Ruiz Gomez]

Ah, I wrote too fast  :-)

The timeout dialog is shown and then when clicking OK the "Invalid for read" page appears.

I'm going to refresh that server to discard is something about installation.

Regards,

Carlos Ruiz

El 22/2/21 a las 14:59, Carlos Antonio Ruiz Gomez escribió:

[Heng Sin Low]

it is not session timeout but xhr timeout. if you spend some time doing some actitivites at http://test-oracle.idempiere.org/, you will notice there are 504 (gateway timeout) errors captured at console (thats from xhr request onerror) and eventually cause the server not available popup.

the direct fix for that would be to replace line 44 at serverpush.js

if (textStatus != "timeout" && textStatus != "abort" && errorThrown != "SessionNotFound") {

with 

if (textStatus != "timeout" && textStatus != "abort" && errorThrown != "SessionNotFound" && jqxhr.status != 504) {

--
You received this message because you are subscribed to the Google Groups "iDempiere" group.
To unsubscribe from this group and stop receiving emails from it, send an email to idempiere+...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/idempiere/4150d956-47fa-7b2f-6803-7c8302a7504e%40gmail.com.

[Heng Sin Low]

since it doesn't happens at test.idempiere.org and it is timout related, I guess it might be due to the nginx proxy timeout configuration difference between the 2 server.

--
You received this message because you are subscribed to the Google Groups "iDempiere" group.
To unsubscribe from this group and stop receiving emails from it, send an email to idempiere+...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/idempiere/5b225589-c813-8cfc-be79-26192b6fd4ed%40gmail.com.

[Nicolas Micoud]

Hi,

Thanks for the support :)

The guy in charge of the config is away ATM, so I will try the direct fix.

Checking the console in my server, I see errors 502.

Just a question. Does error 502 should also be added here ? (as it seems quite similar to me, but I may be totally wrong, just asking ^^)

So line should be :

if (textStatus != "timeout" && textStatus != "abort" && errorThrown != "SessionNotFound" && jqxhr.status != 504 && jqxhr.status != 502) {

Thanks

Nicolas

[Heng Sin Low]

no, 502 is different and shouldn't be something that's safe to ignore

To view this discussion on the web visit https://groups.google.com/d/msgid/idempiere/b48f0a55-de65-4dae-acf2-c2bcc76f5fc0n%40googlegroups.com.

[Nicolas Micoud]

ok thanks

[Carlos Antonio Ruiz Gomez]

Dirk and I were troubleshooting the server and noticed the nginx conf was missing the proxy location for /webui/zkau/comet

Added that part and things seem to be working fine now.

Regards,

Carlos Ruiz

El 22/2/21 a las 16:23, Nicolas Micoud escribió:

[Eduardo Gil]

Hello read https://groups.google.com/g/idempiere/c/M9bEmmjFmuI his is how i solve this

[Nicolas Micoud]

Hi,

Issue solved here

Thanks everybody !

Nicolas

[Ricardo MP]

genius, this solved it. great job and thanks!

[victor rodriguez]

I'm sorry I'm having the same error from a fresh installation. what did you do to solve it?

[Ayaz Ahmed]

Today I have installed 9.0. Unfortunately I am facing same issue.

[Carlos Antonio Ruiz Gomez]

Can somebody confirm if the patch that Heng Sin proposed works?

We are not able to reproduce the issue in our servers, so would be great also to determine what is the root cause of the issue, common things in the servers where this is happening?

Regards,

Carlos Ruiz

El 25/12/21 a las 14:55, Ayaz Ahmed escribió:

[Sergey Schuvaiev]

Hi!

I have installed the iDempiere 9 today. And faced with same behavior.

Regards,

Serhii Chuvaiev.

суббота, 25 декабря 2021 г. в 16:03:46 UTC+2, car...@gmail.com:

[Heng Sin Low]

please use https instead.

--
You received this message because you are subscribed to the Google Groups "iDempiere" group.
To unsubscribe from this group and stop receiving emails from it, send an email to idempiere+...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/idempiere/008f2c1e-09ad-43b8-9a1a-4ac2de77cf3bn%40googlegroups.com.

[Sergey Schuvaiev]

Thank you Heng Sin Low for your advice!
everything works fine for https

суббота, 25 декабря 2021 г. в 22:09:15 UTC+2, hengsin:

[antonio....@dyensisoftware.it]

We use Idempiere 8.2 with last patch. With Idempiere 7 it does not happen

The problem recurs differently but always due to timeout if a proxy is used. 

If you use port 8443 directly, this does not happen. https://ipaddress:8443/webui/ 

Happen when you use https://ipaddress/webui/  via proxy. We use Apache. The same configuration used with Idempire 7.

When you open a feature, thereafter some minutes, appears the message:

 "The page or component you request is no longer available appears. This is normally caused by timeout or rebooting the server".  

At the console level of the browser there is the following POST error 

https: // ipaddress / webui / zkau / comet 502 (Proxy Error)

error: error errorThrown: Proxy Error status: 502

The functions work correctly but this message always appears after a few minutes

[Heng Sin Low]

I think for a reverse proxy, you need to forward "X-Forwarded-Proto https" from your proxy.

To view this discussion on the web visit https://groups.google.com/d/msgid/idempiere/939467e2-e6d1-4044-96c6-3e2fca1b80e1n%40googlegroups.com.

[Heng Sin Low]

Should be "RequestHeader set X-Forwarded-Proto https" for Apache.

[philba...@gmail.com]

Hi Antonio,

I have just installed Idempiere 9 into our test environment which is via a proxy - pfsense with HAProxy. the connection was resetting every 30 seconds when connecting via proxy, however https://ipaddress:8443/webui/ to the server directly did not have any connection reset issues, which seems consistent with what you're experiencing.

I turned my attention to the HAProxy setup and found that the default server timeout is 30 seconds. Setting this to a higher value fixed the issue in our instance.

[pvanderr...@gmail.com]

Dear all,

Don't know if this will help, but I will give you my two cents (I am not a technical guy). For months I did not update my 8.2 instance. I worked with it on a local network as well as through a VPN (always 8080). No problems. A few days ago I upgraded to version 9 and I experienced the constantly reloading of the page. Thought it had to do with the upgrade, so I uninstalled version 9 and reinstalled the latest version 8.2 on my "old" server, The reloading disappeared, but the system appeared to be very slow if it did not throw me out (f.e. with a cache reset or a simple trial balance report). Then I learned about the https for version 9+ and it also seems to work for my "new" 8.2 version.
In the meantime I also created two fresh new VM servers. One with version 9 and one with latest 8.2 to see if I can find differences or problems (also to see if the things that Carlos and Diego created for me are still working in version 9 and they seem to do). Here I find the same with version 8.2 (8080) very slow and kicking me out every now and then. With 8443, no  problems.

BTW. I also noticed that the trial balance shows the accout IDs in version 9 instead of the Account search key/name which are shown in version 8.2.

Hope you can make "chocolat" out of this.

Op maandag 3 januari 2022 om 08:52:33 UTC+1 schreef philba...@gmail.com:

[Heng Sin Low]

Please always use https for testing since  that's what your user will be using. Also, it is a matter of time that all browsers will stop supporting http.

To view this discussion on the web visit https://groups.google.com/d/msgid/idempiere/cb6999de-8ca6-4c27-af06-06bef153afdan%40googlegroups.com.

[Carlos Antonio Ruiz Gomez]

Hi Pieter,

> BTW. I also noticed that the trial balance shows the accout IDs in
version 9 instead of the Account search key/name which are shown in
version 8.2.

Thanks for reporting, this is now fixed with the latest commit in
IDEMPIERE-4448.

Regards,

Carlos Ruiz



El 3/1/22 a las 12:36, pvanderr...@gmail.com escribió:

[KiênDX - Việt Nam]

I use function Import File Loader on Window. Data about 10,000 record. When import about 3 minutes, system show dialog and timeout

Vào lúc 21:03:46 UTC+7 ngày Thứ Bảy, 25 tháng 12, 2021, car...@gmail.com đã viết: