Shiny server keeps disconnecting - can't narrow down to a cause through logs

Sanjmeh · February 16, 2019, 3:16am

The app:
I have a hosted shiny app on an Ubuntu 14 server that primarily asks users to scroll through a DT::renderDT() output, make some edits that are then loaded back with DT::replaceData() .There are a bunch of files saved in csv that are used to exchange data between users.

Problem:
Users complain of random disconnection which is not happening at any specific point in the app. The shiny app disconnects randomly at some point - sometimes initially with no data inputs yet done and sometimes after data inputs. I have checked all 6 posts on rstudio including this one and this one.

I have checked the logs coming in:/var/log/shiny-server in each individual file that corresponds to an app session and cannot find any abnormal ending to the app.
I have also checked the global logs in the following 4 files.

-rw-r----- 1 syslog adm      2517 Feb 16 06:54 kern.log
-rw-r----- 1 syslog adm    174044 Feb 16 06:54 syslog
-rw-r----- 1 syslog adm     62983 Feb 16 06:50 mail.log
-rw-r----- 1 syslog adm    708664 Feb 16 06:50 auth.log
-rw-r--r-- 1 root   root  3799705 Feb 16 06:45 shiny-server.log

But I am unable to see a clear correlation with a specific log and the crash.
I need some guidance on what could be going wrong and which log entry could be the reason of the disconnect so that we can delve deeper. I have posted the tail of the few logs to give any idea.

kern.log:

studio@ip-172-31-30-19:/var/log$ sudo tail kern.log
Feb 12 09:26:03 ip-172-31-30-19 kernel: [5604079.054563] TCP: request_sock_TCP: Possible SYN flooding on port 3067. Sending cookies.  Check SNMP counters.
Feb 13 01:06:44 ip-172-31-30-19 kernel: [5660519.418844] audit: type=1400 audit(1550020004.138:22): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="/usr/lib/snapd/snap-confine" pid=29105 comm="apparmor_parser"
Feb 13 01:06:44 ip-172-31-30-19 kernel: [5660519.432293] audit: type=1400 audit(1550020004.154:23): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="/usr/lib/snapd/snap-confine//mount-namespace-capture-helper" pid=29105 comm="apparmor_parser"
Feb 13 09:51:19 ip-172-31-30-19 kernel: [5691994.670187] TCP: request_sock_TCP: Possible SYN flooding on port 6447. Sending cookies.  Check SNMP counters.
Feb 13 16:20:56 ip-172-31-30-19 kernel: [5715372.138169] TCP: request_sock_TCP: Possible SYN flooding on port 4657. Sending cookies.  Check SNMP counters.
Feb 13 20:54:23 ip-172-31-30-19 kernel: [5731778.660324] TCP: request_sock_TCP: Possible SYN flooding on port 6721. Sending cookies.  Check SNMP counters.
Feb 14 12:44:17 ip-172-31-30-19 kernel: [5788772.641030] TCP: request_sock_TCP: Possible SYN flooding on port 3579. Sending cookies.  Check SNMP counters.
Feb 14 15:43:32 ip-172-31-30-19 kernel: [5799527.513622] TCP: request_sock_TCP: Possible SYN flooding on port 5068. Sending cookies.  Check SNMP counters.
Feb 15 12:16:58 ip-172-31-30-19 kernel: [5873533.572321] TCP: request_sock_TCP: Possible SYN flooding on port 4677. Sending cookies.  Check SNMP counters.
Feb 16 01:24:29 ip-172-31-30-19 kernel: [5920785.061662] TCP: request_sock_TCP: Possible SYN flooding on port 7561. Sending cookies.  Check SNMP counters.

syslog:

rstudio@ip-172-31-30-19:/var/log$ sudo tail -25 syslog
Feb 16 01:19:23 ip-172-31-30-19 systemd[1]: Started Daily apt upgrade and clean activities.
Feb 16 01:20:01 ip-172-31-30-19 CRON[12726]: (rstudio) CMD (~/aws-scripts-mon/mon-put-instance-data.pl --mem-used-incl-cache-buff --mem-util --disk-space-util --disk-path=/--from-cron)
Feb 16 01:20:01 ip-172-31-30-19 postfix/pickup[12468]: 691441F6F9B: uid=1001 from=<rstudio>
Feb 16 01:20:01 ip-172-31-30-19 postfix/cleanup[12730]: 691441F6F9B: message-id=<20190216012001.691441F6F9B@ip-172-31-30-19.ap-south-1.compute.internal>
Feb 16 01:20:01 ip-172-31-30-19 postfix/qmgr[10563]: 691441F6F9B: from=<rstudio@gmail.com>, size=801, nrcpt=1 (queue active)
Feb 16 01:20:01 ip-172-31-30-19 postfix/local[12732]: 691441F6F9B: to=<rstudio@gmail.com>, orig_to=<rstudio>, relay=local, delay=0.02, delays=0.01/0/0/0, dsn=2.0.0, status=sent (delivered to mailbox)
Feb 16 01:20:01 ip-172-31-30-19 postfix/qmgr[10563]: 691441F6F9B: removed
Feb 16 01:24:29 ip-172-31-30-19 kernel: [5920785.061662] TCP: request_sock_TCP: Possible SYN flooding on port 7561. Sending cookies.  Check SNMP counters.
Feb 16 01:25:01 ip-172-31-30-19 CRON[12802]: (rstudio) CMD (~/aws-scripts-mon/mon-put-instance-data.pl --mem-used-incl-cache-buff --mem-util --disk-space-util --disk-path=/--from-cron)
Feb 16 01:25:01 ip-172-31-30-19 CRON[12803]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Feb 16 01:25:01 ip-172-31-30-19 postfix/pickup[12468]: 6CF961F6F9B: uid=1001 from=<rstudio>
Feb 16 01:25:01 ip-172-31-30-19 postfix/cleanup[12808]: 6CF961F6F9B: message-id=<20190216012501.6CF961F6F9B@ip-172-31-30-19.ap-south-1.compute.internal>
Feb 16 01:25:01 ip-172-31-30-19 postfix/qmgr[10563]: 6CF961F6F9B: from=<rstudio@gmail.com>, size=801, nrcpt=1 (queue active)
Feb 16 01:25:01 ip-172-31-30-19 postfix/local[12810]: 6CF961F6F9B: to=<rstudio@gmail.com>, orig_to=<rstudio>, relay=local, delay=0.02, delays=0.01/0/0/0, dsn=2.0.0, status=sent (delivered to mailbox)
Feb 16 01:25:01 ip-172-31-30-19 postfix/qmgr[10563]: 6CF961F6F9B: removed
Feb 16 01:26:43 ip-172-31-30-19 systemd[1]: Started Session c882 of user rstudio.
Feb 16 01:26:47 ip-172-31-30-19 dbus[1167]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service'
Feb 16 01:26:47 ip-172-31-30-19 systemd[1]: Starting Time & Date Service...
Feb 16 01:26:47 ip-172-31-30-19 dbus[1167]: [system] Successfully activated service 'org.freedesktop.timedate1'
Feb 16 01:26:47 ip-172-31-30-19 systemd[1]: Started Time & Date Service.
Feb 16 01:27:20 ip-172-31-30-19 systemd[1]: Started Session c883 of user rstudio.
Feb 16 01:27:25 ip-172-31-30-19 dbus[1167]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service'
Feb 16 01:27:25 ip-172-31-30-19 systemd[1]: Starting Time & Date Service...
Feb 16 01:27:25 ip-172-31-30-19 dbus[1167]: [system] Successfully activated service 'org.freedesktop.timedate1'
Feb 16 01:27:25 ip-172-31-30-19 systemd[1]: Started Time & Date Service.

shiny-server.log

rstudio@ip-172-31-30-19:/var/log$ sudo tail -25 shiny-server.log
[2019-02-16T01:27:33.831] [TRACE] shiny-server - Worker #797e51bd04c92a5f releasing http port. 0 HTTP, 1 WebSocket, 0 pending.
[2019-02-16T01:28:02.443] [TRACE] shiny-server - Reusing existing instance
[2019-02-16T01:28:02.443] [TRACE] shiny-server - Worker #797e51bd04c92a5f acquiring http port. 1 HTTP, 1 WebSocket, 0 pending.
[2019-02-16T01:28:02.443] [TRACE] shiny-server - Proxying request: /session/5478455156a413adcce091ac86b57ebe/dataobj/tbl?w=&nonce=b3de3c7ab8173803
[2019-02-16T01:28:02.443] [TRACE] shiny-server - http_proxy event: start
[2019-02-16T01:28:02.443] [TRACE] shiny-server - http_proxy event: proxyReq
[2019-02-16T01:28:02.575] [TRACE] shiny-server - http_proxy event: proxyRes
[2019-02-16T01:28:02.576] [TRACE] shiny-server - http_proxy event: end
[2019-02-16T01:28:02.576] [TRACE] shiny-server - Worker #797e51bd04c92a5f releasing http port. 0 HTTP, 1 WebSocket, 0 pending.
[2019-02-16T01:28:04.830] [TRACE] shiny-server - Reusing existing instance
[2019-02-16T01:28:04.830] [TRACE] shiny-server - Worker #797e51bd04c92a5f acquiring http port. 1 HTTP, 1 WebSocket, 0 pending.
[2019-02-16T01:28:04.830] [TRACE] shiny-server - Proxying request: /session/5478455156a413adcce091ac86b57ebe/dataobj/tbl?w=&nonce=b3de3c7ab8173803
[2019-02-16T01:28:04.830] [TRACE] shiny-server - http_proxy event: start
[2019-02-16T01:28:04.831] [TRACE] shiny-server - http_proxy event: proxyReq
[2019-02-16T01:28:04.879] [TRACE] shiny-server - http_proxy event: proxyRes
[2019-02-16T01:28:04.879] [TRACE] shiny-server - http_proxy event: end
[2019-02-16T01:28:04.880] [TRACE] shiny-server - Worker #797e51bd04c92a5f releasing http port. 0 HTTP, 1 WebSocket, 0 pending.
[2019-02-16T01:28:08.783] [TRACE] shiny-server - Reusing existing instance
[2019-02-16T01:28:08.783] [TRACE] shiny-server - Worker #797e51bd04c92a5f acquiring http port. 1 HTTP, 1 WebSocket, 0 pending.
[2019-02-16T01:28:08.783] [TRACE] shiny-server - Proxying request: /session/5478455156a413adcce091ac86b57ebe/dataobj/tbl?w=&nonce=b3de3c7ab8173803
[2019-02-16T01:28:08.783] [TRACE] shiny-server - http_proxy event: start
[2019-02-16T01:28:08.783] [TRACE] shiny-server - http_proxy event: proxyReq
[2019-02-16T01:28:08.795] [TRACE] shiny-server - http_proxy event: proxyRes
[2019-02-16T01:28:08.795] [TRACE] shiny-server - http_proxy event: end
[2019-02-16T01:28:08.796] [TRACE] shiny-server - Worker #797e51bd04c92a5f releasing http port. 0 HTTP, 1 WebSocket, 0 pending.

andresrcs · February 16, 2019, 3:56am

Have you checked if this issue is related with the number of concurrent users? Maybe you are reaching the RAM memory limit of your server at some point, that would explain the randomnes of the issue.

Sanjmeh · February 16, 2019, 5:23am

If RAM is getting full won't there be a message in any of the logs? I have a t2.medium AWS server with two cores and 4 GM RAM and I am watching its CPU utilisation charts here. It never goes above 10%.

I donot know how to see historical memory utilization on an ubuntu server but I can check it at random times with the top command. It shows less than 10%(8.4% - pasted below). I donot rule out memory getting full although with just 4-5 simultaneous users and dataset sizes of a few 10s of MB I doubt that happening.

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
13509 rstudio   20   0  988544 339252  33244 S   1.0  8.4   0:05.09 rsession
   25 root      39  19       0      0      0 S   0.3  0.0   1:05.83 khugepaged
    1 root      20   0  185292   4984   3284 S   0.0  0.1   0:34.82 systemd
    2 root      20   0       0      0      0 S   0.0  0.0   0:00.06 kthreadd

Are there any other pointers for me? And also I will figure a way to setup mem utilization charts on the AWS server. Any help there could be appreciated as well. Thanks.

Sanjmeh · February 18, 2019, 4:00pm

@andresrcs: Do you know if we can check how many users are connected to the shiny server at any given time?

andresrcs · February 18, 2019, 5:08pm

On the open source version you can check your logs, for inspiration check this shiny app.

https://www.rcharlie.com/post/shiny-monitor/

Sanjmeh · February 19, 2019, 8:13pm

Thanks. I have seen this post and am building a similar (but less complex app) to monitor memory of my ubuntu machine.

Meanwhile I ran into this shiny scoping rule article and now have a strong suspicion that my variables may be clashing across sessions as I freely use <<- for assigning variable across reactive blocks of code. Also the frequent disconnects increase when multiple users concurrently use the app and also disconnections were reported simultaneously by two users using the same part of the app at the same time.

My implementation architecture is nominally repeated here. Kindly advise if this could be a cause of variable clashes.

app.R:

# the packages loaded - in case they are important
library(wrapr)
    library(shinycssloaders)
    library(shiny)
    library(shinyjs)
    library(shinyalert)
    library(shinyWidgets)
    library(shinyBS)
    library(DT)
    library(magrittr)

source(outside.r) # my multiuser shiny app calls a few functions sitting in an external r code - hence sourced the file.

#ui section....(displays a lot of tables; since ui section cannot be responsible for clashes I am omitting the details)
ui <- fluidPage(..)

server <- function(input,output,session){
 observeEvent(input$button1,{
 x <<-  fread(input$filename) # there are many variables that I need to assign with <<- so that I can use them outside the reactive context
 }
 output$tab <- renderDT(x) # using x outside the observeEvent(..)
}

shinyApp(ui=ui, server=server)

I also have variables that are assigned from inside functions that are residing in the sourced file outside.r.

I had presumed the <<- and variables exported from sourced functions were local to the R session. Please correct my understanding.
Apologies to ask a basic question but the scoping article could not clarify my doubt.

andresrcs · February 19, 2019, 8:18pm

On the open source version all your users run the app inside the same R session (same parent environment) so the unnecessary use of <<- could actually be the cause of your problem.

Sanjmeh · February 20, 2019, 6:45am

Gosh! - this will be a serious issue for me. But what I understand is the use of <<- takes the assignment to one level up in the parent namespace and not all the way up to the global Environment. Please correct my understanding that a shiny reactive block is one level inside the server function.

I did a small test.
Turns out I had the correct understanding of <<-.
The below test app was loaded on the open source R shiny server (hosted on AWS ubuntu) and then accessed from two browsers. To my relief the refresh button clicked by one user did not impact the value of x displayed to the other user.

shinyApp(
  ui = fluidPage(
    actionButton("button", "refresh"),
    actionButton("button2", "Show new x"),
    textOutput("timenow")
  ),
  server = function(input, output, session) {
    x <- 1
    observeEvent(input$button2,{ 
      output$timenow <- renderText(x)
      })
    observeEvent(input$button,{
      x <<- x + 1
    })
  }

Update

If I change the location of initialisation for the variable x to outside the server function, then the second user is able to increment the value for the first user. This was sort of expected as x now becomes a global variable.

x<- 1

shinyApp(
  ui = fluidPage(
    actionButton("button", "refresh"),
    actionButton("button2", "Show new x"),
    textOutput("timenow")
  ),
  server = function(input, output, session) {
    observeEvent(input$button2,{ 
      output$timenow <- renderText(x)
      })
    observeEvent(input$button,{
      x <<- x + 1
    })
  }
)

jm_t · February 20, 2019, 9:28am

Hi,

I also faced some unexplained disconnection issues in summer 2018. Was with an ubuntu 16 and shiny server pro. I never found the root cause. The issue was gone after upgrading shiny server to latest release. No config or apps changed involved.

So my question would be: are you running the latest shiny server package?

Regards,

jm

Sanjmeh · February 20, 2019, 11:54am

I have shiny 1.2.0, which is the latest on CRAN.
I have also checked free mem on the Ubuntu 14 server is sufficient (about 1.3 GB).

top - 14:51:04 up 72 days, 20:36,  0 users,  load average: 0.00, 0.00, 0.00
Tasks: 130 total,   1 running, 129 sleeping,   0 stopped,   0 zombie
top - 15:03:14 up 72 days, 20:48,  0 users,  load average: 0.00, 0.00, 0.00
Tasks: 130 total,   1 running, 129 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.2 us,  0.2 sy,  0.0 ni, 99.5 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  4045044 total,  1313624 free,   894468 used,  1836952 buff/cache
KiB Swap:  1048572 total,   892016 free,   156556 used.  2792792 avail Mem

So it is not a memory or CPU overload for sure. When two app users are simultaneously connected it is then when the disconnection happens. But I see no disconnection logs. Perhaps it is time to go back to the server logs and kern logs instead of the shiny user logs. I need someone to please advise if the server logs I attached show anything abnormal. I need pointers where to look for the diagnosis now.

Sanjmeh · February 20, 2019, 4:56pm

I suspect stopApp() triggered by one user (by clicking an exit button) is causing all the connected apps to disconnect. Even when thestopApp() is inside the server() function. Not clear why this would happen through.

andresrcs · February 20, 2019, 5:01pm

Again on open source all users are on the same R session so stopApp kills the app for every one.

Sanjmeh · February 21, 2019, 8:44am

Let me ask the problem in a more general way so that it is beneficial for a lot of people out there.

Imagine a shiny app with the following structure:

shinyApp(
  ui = fluidPage(...),
  server = function(input, output, session) {
   ...

    observeEvent(input$button1,{ 
# module1
    ...
      })


    observeEvent(input$button2,{
# module2
     ...
    })


    observeEvent(input$button3,{
# module3
     ...
    })

  }

Question: How do we share variables between the three code modules without a <<- assignment ?
My solution: I use <<- If we use <<- the variable is available for the session across the server function. But somehow this appears to be unreliably resulting in a clash across multiple sessions (I am still not convinced that open source shiny server allots the same copy of the variable across sessions even if it is declared inside the server function).
I am still trying to debug this out.

andresrcs · February 21, 2019, 4:31pm

Sorry but this is exactly what is happening, have in mind that an app session is not the same as an R session, maybe this article could help you understand how the open source version works, and give you an alternative for deploying your app.

open-meta · February 25, 2019, 12:41am

Although I had a different error message, I had a similar problem and solved it by ditching the rJava package. If you're loading that, I'd find a different solution. My problems are documented as Shiny Server issue 378.

Although having read more of your thread, I think your problem is almost certainly the stopApp(), which is definitely going to disconnect all users. My own code is full of <<-. As long as it's used to assign a value to a server-session-global (ie, a variable you defined inside the server function and not before that) it'a safe and useful.

Tom

system · April 20, 2019, 4:41am

This topic was automatically closed 54 days after the last reply. New replies are no longer allowed.

If you have a query related to it or one of the replies, start a new topic and refer back with a link.