Tribot sometimes fails to download scripts

[Naton 1028]

Tribot sometimes fails to download scripts with intermittent networking issues. I have seen so many reports of this that it's unlikely it's on the users sides, but rather on tribots side (or there's something tribot could do better). Intermittently scripts will fail to start after selecting them in the script selector, or via CLI. This most impacts any customer who uses automation to start scripts, such as CLI(/bulk launcher) based solutions (to be clear, all customers would run into this, but manually starting can easily just retry...).

Ideally at the very least tribot could retry failed script downloads a few times.

 

Can have customers post stack traces etc as they find them here. The debugs/stack traces I've seen have been different over the various reports, but always seems to be something networking related (ex. okhttp throws exception, or okhttp is 'stuck' based on thread dump)

Example, after starting script, this shows in bot debug and script never starts

[18:32:36] java.io.EOFException
[18:32:36] 	at okhttp3.internal.http2.Http2Stream$FramingSource.receive$okhttp(Http2Stream.kt:449)
[18:32:36] 	at okhttp3.internal.http2.Http2Stream.receiveData(Http2Stream.kt:276)
[18:32:36] 	at okhttp3.internal.http2.Http2Connection$ReaderRunnable.data(Http2Connection.kt:650)
[18:32:36] 	at okhttp3.internal.http2.Http2Reader.readData(Http2Reader.kt:180)
[18:32:36] 	at okhttp3.internal.http2.Http2Reader.nextFrame(Http2Reader.kt:119)
[18:32:36] 	at okhttp3.internal.http2.Http2Connection$ReaderRunnable.invoke(Http2Connection.kt:618)
[18:32:36] 	at okhttp3.internal.http2.Http2Connection$ReaderRunnable.invoke(Http2Connection.kt:609)
[18:32:36] 	at okhttp3.internal.concurrent.TaskQueue$execute$1.runOnce(TaskQueue.kt:98)
[18:32:36] 	at okhttp3.internal.concurrent.TaskRunner.runTask(TaskRunner.kt:116)
[18:32:36] 	at okhttp3.internal.concurrent.TaskRunner.access$runTask(TaskRunner.kt:42)
[18:32:36] 	at okhttp3.internal.concurrent.TaskRunner$runnable$1.run(TaskRunner.kt:65)
[18:32:36] 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
[18:32:36] 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
[18:32:36] 	at java.base/java.lang.Thread.run(Thread.java:834)

Or this shows in bot debug too

[08:16:07] Failed to start script

[Nullable 1114]

I think this is the first time I've seen the cause exception. This explains why the current retry logic isn't working. It also suggests the server is closing the connection. The download servers are not hosted by us, by the way. It uses a different mechanism.

Anyway, I just made a few changes that are now live on the beta client:

• Script retry logic should now work for all errors
• Upped retries to 5 max
• Added exponential retry backoff in case of transient serverside errors
• Added more logging to determine which part of the connection/download is failing

 

Once I can verify the beta client is working normally I'll do a main release.

[Nullable 1114]

Live now on Tribot 12.3.21. I'll leave this open for now in case it still happens.

[Polymorphic 116]

Could you let us know what initial backoff time is being used in the retry logic?

[Nullable 1114]

1 hour ago, Polymorphic said:

Could you let us know what initial backoff time is being used in the retry logic?

100ms * ([retryNum]^2)

So first is 100ms, second is 400, 900, 1600, then 2500

[Naton 1028]

Have a customer still reporting it on TRiBot Version: TRiBot 12.3.21

 

Bot debug

[03:02:00] java.io.EOFException
[03:02:00] 	at okhttp3.internal.http2.Http2Stream$FramingSource.receive$okhttp(Http2Stream.kt:449)
[03:02:00] 	at okhttp3.internal.http2.Http2Stream.receiveData(Http2Stream.kt:276)
[03:02:00] 	at okhttp3.internal.http2.Http2Connection$ReaderRunnable.data(Http2Connection.kt:650)
[03:02:00] 	at okhttp3.internal.http2.Http2Reader.readData(Http2Reader.kt:180)
[03:02:00] 	at okhttp3.internal.http2.Http2Reader.nextFrame(Http2Reader.kt:119)
[03:02:00] 	at okhttp3.internal.http2.Http2Connection$ReaderRunnable.invoke(Http2Connection.kt:618)
[03:02:00] 	at okhttp3.internal.http2.Http2Connection$ReaderRunnable.invoke(Http2Connection.kt:609)
[03:02:00] 	at okhttp3.internal.concurrent.TaskQueue$execute$1.runOnce(TaskQueue.kt:98)
[03:02:00] 	at okhttp3.internal.concurrent.TaskRunner.runTask(TaskRunner.kt:116)
[03:02:00] 	at okhttp3.internal.concurrent.TaskRunner.access$runTask(TaskRunner.kt:42)
[03:02:00] 	at okhttp3.internal.concurrent.TaskRunner$runnable$1.run(TaskRunner.kt:65)
[03:02:00] 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
[03:02:00] 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
[03:02:00] 	at java.base/java.lang.Thread.run(Thread.java:834)
[03:02:00] Unknown error downloading script (1). Retrying...
[08:21:25] Generating bug report...

Client debug

[03:02:00] Unable to load store script 'nRestocker'.

[Nullable 1114]

I can see the debug says it’s retrying but I don’t see the debug from the next 4 attempts. 
 

Did they wait for it? What are the time stamps between the start of the download and the error?

[Nullable 1114]

Just fixed another issue with the retry mechanism not working. Some errors deeper in the code were being silently caught and ignored.

Tribot 12.3.22 contains the fix.