B4J Question What the Heck? Error Log

Harris

Expert
Licensed User
Longtime User
Very long error. I don't know what it means...
What is "Eat What You Kill" ? (in the error log).


B4X:
   *** - ***  2021/11/04 - 05:08:14 how many new ecmfiles to process: 23
 Folder to create: 72219  file got from: C:\root/www/tripinspect/inecm
   --- 1623847477179_72219.zip is NOT VALID zip
 File to delete: C:\root/www/tripinspect/inecm/1623847477179_72219.zip
   *** - ***  2021/11/04 - 05:08:14 File WAS NOT deleted: C:\root/www/tripinspect/inecm/1623847477179_72219.zip
/ecmfiles
java.lang.RuntimeException: java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 1800011/1800000 ms
java.lang.RuntimeException: java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 1800011/1800000 ms
    at anywheresoftware.b4a.BA.raiseEvent2(BA.java:120)
    at anywheresoftware.b4a.BA.raiseEvent(BA.java:78)
    at anywheresoftware.b4j.object.JServlet$Handle.run(JServlet.java:130)
    at anywheresoftware.b4j.object.JServlet.Handle(JServlet.java:110)
    at anywheresoftware.b4j.object.JServlet.doPost(JServlet.java:80)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:865)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1655)
    at anywheresoftware.b4j.object.JServlet$Handle.run(JServlet.java:135)
    at anywheresoftware.b4j.object.JServlet.Handle(JServlet.java:110)
    at anywheresoftware.b4j.object.JServlet.doFilter(JServlet.java:72)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1642)
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:533)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1253)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203)
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473)
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201)
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1155)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)
    at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
    at org.eclipse.jetty.server.Server.handle(Server.java:531)
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:352)
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:281)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102)
    at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:760)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:678)
    at java.lang.Thread.run(Unknown Source)
Caused by: java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 1800011/1800000 ms
    at org.eclipse.jetty.server.HttpInput$ErrorState.noContent(HttpInput.java:1075)
    at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:313)
    at java.io.InputStream.read(Unknown Source)
    at anywheresoftware.b4a.objects.streams.File.Copy2(File.java:349)
    at abmtripinspect.ti.com.ecmin._handle(ecmin.java:93)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
    at java.lang.reflect.Method.invoke(Unknown Source)
    at anywheresoftware.b4a.BA.raiseEvent2(BA.java:91)
    ... 39 more
Caused by: java.util.concurrent.TimeoutException: Idle timeout expired: 1800011/1800000 ms
    at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:166)
    at org.eclipse.jetty.io.IdleTimeout$1.run(IdleTimeout.java:50)
    at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
    at java.util.concurrent.FutureTask.run(Unknown Source)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(Unknown Source)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
    ... 1 more
    Suppressed: java.lang.Throwable: HttpInput failure
        at org.eclipse.jetty.server.HttpInput.failed(HttpInput.java:821)
        at org.eclipse.jetty.server.HttpConnection$BlockingReadCallback.failed(HttpConnection.java:649)
        at org.eclipse.jetty.io.FillInterest.onFail(FillInterest.java:134)
        at org.eclipse.jetty.io.AbstractEndPoint.onIdleExpired(AbstractEndPoint.java:406)
        ... 9 more
/ecmfiles
java.lang.RuntimeException: java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 1800011/1800000 ms
java.lang.RuntimeException: java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 1800011/1800000 ms
    at anywheresoftware.b4a.BA.raiseEvent2(BA.java:120)
    at anywheresoftware.b4a.BA.raiseEvent(BA.java:78)
    at anywheresoftware.b4j.object.JServlet$Handle.run(JServlet.java:130)
    at anywheresoftware.b4j.object.JServlet.Handle(JServlet.java:110)
    at anywheresoftware.b4j.object.JServlet.doPost(JServlet.java:80)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:865)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1655)
    at anywheresoftware.b4j.object.JServlet$Handle.run(JServlet.java:135)
    at anywheresoftware.b4j.object.JServlet.Handle(JServlet.java:110)
    at anywheresoftware.b4j.object.JServlet.doFilter(JServlet.java:72)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1642)
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:533)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1253)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203)
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473)
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201)
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1155)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)
    at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
    at org.eclipse.jetty.server.Server.handle(Server.java:531)
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:352)
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:281)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102)
    at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:760)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:678)
    at java.lang.Thread.run(Unknown Source)
Caused by: java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 1800011/1800000 ms
    at org.eclipse.jetty.server.HttpInput$ErrorState.noContent(HttpInput.java:1075)
    at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:313)
    at java.io.InputStream.read(Unknown Source)
    at anywheresoftware.b4a.objects.streams.File.Copy2(File.java:349)
    at abmtripinspect.ti.com.ecmin._handle(ecmin.java:93)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
    at java.lang.reflect.Method.invoke(Unknown Source)
    at anywheresoftware.b4a.BA.raiseEvent2(BA.java:91)
    ... 34 more
Caused by: java.util.concurrent.TimeoutException: Idle timeout expired: 1800011/1800000 ms
    at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:166)
    at org.eclipse.jetty.io.IdleTimeout$1.run(IdleTimeout.java:50)
    at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
    at java.util.concurrent.FutureTask.run(Unknown Source)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(Unknown Source)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
    ... 1 more
    Suppressed: java.lang.Throwable: HttpInput failure
        at org.eclipse.jetty.server.HttpInput.failed(HttpInput.java:821)
        at org.eclipse.jetty.server.HttpConnection$BlockingReadCallback.failed(HttpConnection.java:649)
        at org.eclipse.jetty.io.FillInterest.onFail(FillInterest.java:134)
        at org.eclipse.jetty.io.AbstractEndPoint.onIdleExpired(AbstractEndPoint.java:406)
        ... 9 more
/ecmfiles
java.lang.RuntimeException: java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 1800010/1800000 ms
java.lang.RuntimeException: java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 1800010/1800000 ms
    at anywheresoftware.b4a.BA.raiseEvent2(BA.java:120)
    at anywheresoftware.b4a.BA.raiseEvent(BA.java:78)
    at anywheresoftware.b4j.object.JServlet$Handle.run(JServlet.java:130)
    at anywheresoftware.b4j.object.JServlet.Handle(JServlet.java:110)
    at anywheresoftware.b4j.object.JServlet.doPost(JServlet.java:80)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:865)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1655)
    at anywheresoftware.b4j.object.JServlet$Handle.run(JServlet.java:135)
    at anywheresoftware.b4j.object.JServlet.Handle(JServlet.java:110)
    at anywheresoftware.b4j.object.JServlet.doFilter(JServlet.java:72)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1642)
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:533)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1253)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203)
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473)
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201)
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1155)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)
    at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
    at org.eclipse.jetty.server.Server.handle(Server.java:531)
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:352)
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:281)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102)
    at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:760)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:678)
    at java.lang.Thread.run(Unknown Source)
Caused by: java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 1800010/1800000 ms
    at org.eclipse.jetty.server.HttpInput$ErrorState.noContent(HttpInput.java:1075)
 

PdeG

Member
Licensed User
Longtime User
 
Upvote 0

Harris

Expert
Licensed User
Longtime User
Folder to create: 72219 file got from: C:\root/www/tripinspect/inecm
--- 1623847477179_72219.zip is NOT VALID zip
File to delete: C:\root/www/tripinspect/inecm/1623847477179_72219.zip
*** - *** 2021/11/04 - 05:08:14 File WAS NOT deleted: C:\root/www/tripinspect/inecm/1623847477179_72219.zip

I thought I had cured this in another post regarding deleting corrupt zip files.
I checked if the zip file was valid, if not - delete it - and carry on with other files in the list...

In this example, it could not delete it (like some process had a firm handle on it), and it remained in the cue for processing - for many cycles.
Eventually, when new files came in to the cue - IT WAS DELETED! Everything else carried on normally until the mess of the above error log was raised again.

Fortunately, it works its way out but rather disturbing seeing all this (error) in the log. Seems to do with HTTP file transfer but very hard to tell...
I have a notion that the timer jumps on the file to process while it is still in transfer from the device?

Thx
 
Upvote 0

Harris

Expert
Licensed User
Longtime User
The Timer methods.
Essentially, a folder is checked to see if new .zip files exists (every 10 seconds).
These zip files are anywhere from 500 k to 1.5 meg in size...
If a new file does exist - it is checked for validity. If valid check fails, it is deleted (or attempts to delete). I have detected invalid files in the past...
If valid check passes, it is extracted, copied to an archive folder - then deleted...

A file handler is used for incoming new files from devices... (code below).

I don't know, but it may be possible that I am grabbing the file before it is fully written to disk (in transfer).
In this case - it will fail validity check and be locked by the transfer (not able to delete)...
Perhaps I should inject a Sleep(3000) prior to processing - allowing the (potential) transfer to complete prior to jumping on it...???



B4X:
Sub prtim_tick
        proctimer.Enabled = False
        
        Dim lof As List
        lof.Initialize
        lof = File.ListFiles( ecmFolder1 )
        Log(ABMShared.CurrDT&"  --   ECM Timer Check: "&lof.Size)
        
        If lof.Size > 0 Then
            Log(ABMShared.CurrDT&  " how many new ecmfiles to process: "&lof.Size)
        
            For i  = 0 To lof.Size -1
                Dim str As String
                str = lof.Get(i)
                If str.Contains(".zip") Then
                    PlaceinDir(str)
                    Exit  ' process one file and wait for timer to tick again - 5 to 10 seconds, whatever I set it to...
                End If
            Next
        End If

        proctimer.Enabled = True
End Sub


Sub PlaceinDir(fn As String)
    
    Dim str, str1 As String
    Dim id, id1 As Int
    str = fn
    If str.Contains(".zip") Then
        If File.Exists(ecmFolder1,str) Then
            Dim arc1 As Archiver
            id = str.IndexOf("_")
            id1 = str.IndexOf(".")
            str1 = str.SubString2(id+1,id1)
            Log(" Folder to create: "&str1&"  file got from: "&ecmFolder1)
            Dim newfld As String = "TR_"&str1
            File.MakeDir(ecmFolder,newfld)
            File.MakeDir(base_ecm, "hist")
            currdel = str
            
            If arc.IsValidZipFile( ecmFolder1&"/"& str) Then
                Log("   --- "&str&" is VALID zip")
                ' could not use ArchiverPlusZip UnZip...  generated error looking for DoEvents!!!!!
                'arc.UnZip(File.Combine( ecmFolder1,str), File.Combine(  ecmFolder,newfld), "Archiver" )
                arc1.AsyncUnZip(ecmFolder1, str, ecmFolder&"/"&newfld, "unzip")

            Else
                Log("   --- "& str&" is NOT VALID zip")
                delzip(str)   
            End If
            
        End If
    End If
End Sub

Sub delzip(str As String)
    
Log(" File to delete: "&ecmFolder1&"/"&str)

    File.Delete( ecmFolder1,  str)

    If (File.Exists(ecmFolder1,str))  Then
        Log(ABMShared.CurrDT&" File WAS NOT deleted: "&ecmFolder1&"/"&str)
    Else
        Log(ABMShared.CurrDT&" File WAS Deleted!!!: "&ecmFolder1&"/"&str)
    End If

End Sub



In StartServer....
srvr.AddHandler( "/ecmfiles", "ecmIN", False) ' folder for ecm files


The file handler.....
B4X:
'Class module - file handler -  ecmIN
' Handles file transfers from Android devices...
Sub Class_Globals
    
End Sub

Public Sub Initialize

End Sub

Sub Handle(req As ServletRequest, resp As ServletResponse)
    If req.Method <> "POST" Then
        resp.SendError(500, "method not supported.")
        Return
    End If
    'we need to call req.InputStream before calling GetParameter.
    'Otherwise the stream will be read internally (as the parameter might be in the post body).
    Dim In As InputStream = req.InputStream
    Dim reqType As String = req.GetParameter("type")
    Log(" The req URI for ecmIN: "&req.FullRequestURI)
    
    If reqType = "" Then
        resp.SendError(500, "Missing type parameter.")
        Return
    End If
    Select reqType
        Case "text"
            Dim tr As TextReader
            tr.Initialize(In)
            Log("Received text message: " & CRLF & tr.ReadAll)
            resp.Write("Message received successfully.")
        Case "file" ' handle files....
            Dim name As String = req.GetParameter("name")
            Dim pk As String = req.GetParameter("pk")
            Dim out As OutputStream = File.OpenOutput(Main.ecmFolder1, name, False)
            File.Copy2(In, out)
            out.Close
            Log(ABMShared.CurrDT& "Received ECM file: " & name & ", Size=" & File.Size(Main.ecmFolder1, name))
            resp.Write(name)
    End Select
End Sub
 
Upvote 0

EnriqueGonzalez

Well-Known Member
Licensed User
Longtime User
java.lang.RuntimeException: java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 1800011/1800000 ms
is this a websocket server?
if yes, then it means that an alive connection hasnt been used for that amount of time, it is not a jetty settings, it could actually be a OS setting, Java setting or something else. if it is indeed a websocket, then to avoid this issue send a proof of life every x minutes so the server keeps it alive.
 
Upvote 0

Harris

Expert
Licensed User
Longtime User
is this a websocket server?
Yes, no, I guess so... frankly - I don't know... (me being stupid again)

It's my famous ABMaterial project that has been running for over 6 years - without seeing this issue before...
Although, I just refactored the code above - from using FileWatcher to a timer that checks for new files in a dir...
 
Upvote 0

Harris

Expert
Licensed User
Longtime User
The async unzip is a bit suspicious
I could try another method. Like non async... (hold the thread)...
The server is doing basically nothing, other than waiting for files to arrive. Once in a while (once every month), someone will log in to view a page of interest....

Just trying to figure this out without having to worry about a process stalling or exploding the app....

Like I said, worked for 6 years properly - until I switched to a (quick) timer.

I shall solve it... - just reaching...

Thx for the insight...
 
Upvote 0
Top