schloerke
commented
2 years ago - [x] Add debug message about queue size
Example debug.log snippet showing that the increased queue size is working past limit = 5. (It would have broken before this PR)
2021-11-24 11:27:57.312 DEBUG [ReadingThread] - %%% Received: a["1E#0|m|{\"custom\":{\"my-custom-message\":{\"i\":20}}}"]
2021-11-24 11:27:57.312 DEBUG [ReadingThread] - %%% Message queue length: 1
2021-11-24 11:27:57.312 DEBUG [ReadingThread] - %%% Received: a["1F#0|m|{\"custom\":{\"my-custom-message\":{\"i\":21}}}"]
2021-11-24 11:27:57.312 DEBUG [ReadingThread] - %%% Message queue length: 2
2021-11-24 11:27:57.313 DEBUG [ReadingThread] - %%% Received: a["20#0|m|{\"custom\":{\"my-custom-message\":{\"i\":22}}}"]
2021-11-24 11:27:57.313 DEBUG [ReadingThread] - %%% Message queue length: 3
2021-11-24 11:27:57.313 DEBUG [ReadingThread] - %%% Received: a["21#0|m|{\"custom\":{\"my-custom-message\":{\"i\":23}}}"]
2021-11-24 11:27:57.313 DEBUG [ReadingThread] - %%% Message queue length: 4
2021-11-24 11:27:57.313 DEBUG [ReadingThread] - %%% Received: a["22#0|m|{\"custom\":{\"my-custom-message\":{\"i\":24}}}"]
2021-11-24 11:27:57.313 DEBUG [ReadingThread] - %%% Message queue length: 5
2021-11-24 11:27:57.313 DEBUG [ReadingThread] - %%% Received: a["23#0|m|{\"custom\":{\"my-custom-message\":{\"i\":25}}}"]
2021-11-24 11:27:57.313 DEBUG [ReadingThread] - %%% Message queue length: 6
2021-11-24 11:27:57.313 DEBUG [ReadingThread] - %%% Received: a["24#0|m|{\"custom\":{\"my-custom-message\":{\"i\":26}}}"]
2021-11-24 11:27:57.313 DEBUG [ReadingThread] - %%% Message queue length: 7
2021-11-24 11:27:57.313 DEBUG [ReadingThread] - %%% Received: a["25#0|m|{\"custom\":{\"my-custom-message\":{\"i\":27}}}"]
2021-11-24 11:27:57.313 DEBUG [ReadingThread] - %%% Message queue length: 8
2021-11-24 11:27:57.313 DEBUG [ReadingThread] - %%% Received: a["26#0|m|{\"custom\":{\"my-custom-message\":{\"i\":28}}}"]
2021-11-24 11:27:57.313 DEBUG [ReadingThread] - %%% Message queue length: 9
2021-11-24 11:27:57.314 DEBUG [ReadingThread] - %%% Received: a["27#0|m|{\"custom\":{\"my-custom-message\":{\"i\":29}}}"]
2021-11-24 11:27:57.314 DEBUG [ReadingThread] - %%% Message queue length: 10
2021-11-24 11:27:57.314 DEBUG [ReadingThread] - %%% Received: a["28#0|m|{\"custom\":{\"my-custom-message\":{\"i\":30}}}"]
2021-11-24 11:27:57.314 DEBUG [ReadingThread] - %%% Message queue length: 11
2021-11-24 11:27:57.314 DEBUG [ReadingThread] - %%% Received: a["29#0|m|{\"custom\":{\"my-custom-message\":{\"i\":31}}}"]
2021-11-24 11:27:57.314 DEBUG [ReadingThread] - %%% Message queue length: 12
2021-11-24 11:27:57.314 DEBUG [ReadingThread] - %%% Received: a["2A#0|m|{\"custom\":{\"my-custom-message\":{\"i\":32}}}"]
2021-11-24 11:27:57.314 DEBUG [ReadingThread] - %%% Message queue length: 13
2021-11-24 11:27:57.314 DEBUG [ReadingThread] - %%% Received: a["2B#0|m|{\"custom\":{\"my-custom-message\":{\"i\":33}}}"]
2021-11-24 11:27:57.314 DEBUG [ReadingThread] - %%% Message queue length: 14
2021-11-24 11:27:57.314 DEBUG [thread01] - WS_RECV received: a["1D#0|m|{\"custom\":{\"my-custom-message\":{\"i\":19}}}"]
2021-11-24 11:27:57.314 DEBUG [ReadingThread] - %%% Received: a["2C#0|m|{\"custom\":{\"my-custom-message\":{\"i\":34}}}"]
2021-11-24 11:27:57.314 DEBUG [ReadingThread] - %%% Message queue length: 14
2021-11-24 11:27:57.314 DEBUG [ReadingThread] - %%% Received: a["2D#0|m|{\"custom\":{\"my-custom-message\":{\"i\":35}}}"]
2021-11-24 11:27:57.314 DEBUG [ReadingThread] - %%% Message queue length: 15
2021-11-24 11:27:57.314 DEBUG [ReadingThread] - %%% Received: a["2E#0|m|{\"custom\":{\"my-custom-message\":{\"i\":36}}}"]
2021-11-24 11:27:57.314 DEBUG [ReadingThread] - %%% Message queue length: 16
2021-11-24 11:27:57.314 DEBUG [thread01] - WS_RECV received: a["1E#0|m|{\"custom\":{\"my-custom-message\":{\"i\":20}}}"]
2021-11-24 11:27:57.315 DEBUG [ReadingThread] - %%% Received: a["2F#0|m|{\"custom\":{\"my-custom-message\":{\"i\":37}}}"]
2021-11-24 11:27:57.315 DEBUG [ReadingThread] - %%% Message queue length: 16(It quickly reduced itself to 0 after this.)
Reprex app:
library(shiny)
ui <- fluidPage(
tags$style("td { border: 1px black solid; }"),
tags$script(htmltools::HTML('
// This receives messages of type "my-custom-message" from the server.
Shiny.addCustomMessageHandler("my-custom-message",
function(message) {
console.log(JSON.stringify(message));
$("#code").text(JSON.stringify(message));
if (message.i == 1) {
setTimeout(function() {
Shiny.setInputValue("testOutput", 2);
}, Math.floor(Math.random() * (1000 / 5) * 0.8))
}
}
);
')),
h1("Non-deterministic custom message app"),
p("Number of messages: ", textOutput("n1", inline = TRUE)),
tags$pre(id = "code"),
p("This app sends ", textOutput("n2", inline = TRUE), " custom messages from the server. The UI will also set a value at a set timeout. Due to natural timing errors, the recorded location of the set input value will be in a different location each time."),
p("In this situation, the fixed branch should not throw an error for up to 50 out-of-order messages. Where as the `main` branch should work only for up to 5 out-of-order-messages (rare)."),
markdown('
|out-of-order count|Works on `main`| Works on `PR`|
|--|--|--|
|`<= 5`|Yes|Yes|
|`6-50`|**No**|**\\*\\*Yes\\*\\*** |
|`>50`|No|No|
'),
tags$code("app.R"),
verbatimTextOutput("app")
)
server <- function(input, output, session) {
n <- 100
output$n1 <- renderText(n)
output$n2 <- renderText(n)
output$app <- renderText(paste0(readLines("app.R"), collapse = "\n"))
send_msgs <- function() {
lapply(seq_len(n), function(i) {
later::later(function() {
session$sendCustomMessage(
type = 'my-custom-message',
message = list(i = i)
)
}, delay = 1 + (i/100) / 5)
})
}
send_msgs()
}
shinyApp(ui, server)
Example
This can occur when
custommessages are received out of order. (Non-deterministic. Very plausible situation.)Previously, the queue had a size of
5. Now it is set to50.If app authors are sending enough non-deterministic custom messages to hit the new limit, I'd love to see what the app is doing and how we could address it.