eddelbuettel / rpushbullet

R interface to the awesome Pushbullet service
https://eddelbuettel.github.io/rpushbullet
94 stars 19 forks source link

RPushbullet randomly failing to send pushes on Mac OS Catalina (10.15.1) #57

Closed ashannon closed 4 years ago

ashannon commented 4 years ago

Hello,

I have been using RPushbullet without any issues for years on previous versions of Mac OS. However, since upgrading to Mac OS Catalina, RPushbullet randomly fails when sending pushes, giving the following error message:

"Error in curl::curl_fetch_memory(pburl, handle = h): Error in the HTTP2 framing layer"

The error is difficult to reproduce, as it is happening at random. When it does fail, immediately trying again usually ends up working, so a TryCatch workaround could address this, which is what I did. However, eventually this did not work and after too many retries, the following error message was returned:

"Error: C stack usage 7969600 is too close to the limit"

Any help in fixing this problem would be greatly appreciated. Thanks.

Here is my session info:

R version 3.6.1 (2019-07-05) Platform: x86_64-apple-darwin15.6.0 (64-bit) Running under: macOS Catalina 10.15.1

Matrix products: default BLAS: /System/Library/Frameworks/Accelerate.framework/Versions/A/Frameworks/vecLib.framework/Versions/A/libBLAS.dylib LAPACK: /Library/Frameworks/R.framework/Versions/3.6/Resources/lib/libRlapack.dylib

locale: [1] en_CA.UTF-8/en_CA.UTF-8/en_CA.UTF-8/C/en_CA.UTF-8/en_CA.UTF-8

attached base packages: [1] stats graphics grDevices utils datasets methods base

other attached packages: [1] magrittr_1.5 xml2_1.2.2 rib_0.6.3 scales_1.0.0 rstudioapi_0.10 RCurl_1.95-4.12 bitops_1.0-6
[8] MASS_7.3-51.4 quantreg_5.51 SparseM_1.77 fasttime_1.0-2 RSelenium_1.7.5 sigmoid_0.3.0 corpcor_1.6.9
[15] ECOSolveR_0.5.3 RPushbullet_0.3.2 Matrix_1.2-17 timeDate_3043.102 plyr_1.8.4 openxlsx_4.1.3 IBrokers_0.9-12
[22] quantmod_0.4-15 TTR_0.23-5 xts_0.11-2 zoo_1.8-6 stringr_1.4.0 ggplot2_3.2.1 data.table_1.12.6

loaded via a namespace (and not attached): [1] lattice_0.20-38 colorspace_1.4-1 yaml_2.2.0 XML_3.98-1.20 rlang_0.4.1 pillar_1.4.2 withr_2.1.2
[8] rappdirs_0.3.1 semver_0.2.0 MatrixModels_0.4-1 munsell_0.5.0 binman_0.1.1 gtable_0.3.0 zip_2.0.4
[15] caTools_1.17.1.2 wdman_0.2.4 curl_4.2 Rcpp_1.0.2 openssl_1.4.1 jsonlite_1.6 askpass_1.1
[22] stringi_1.4.3 grid_3.6.1 tools_3.6.1 lazyeval_0.2.2 tibble_2.1.3 crayon_1.3.4 pkgconfig_2.0.3
[29] subprocess_0.8.3 assertthat_0.2.1 httr_1.4.1 R6_2.4.0 compiler_3.6.1

eddelbuettel commented 4 years ago

Well as you said, the change vector here is macOS Catalina -- rpushbullet didn't change, and didn't need to.

Maybe @jeroen know something about curl changes.

Just get the obvious question out of the way: did you recompile/reinstall the curl package?

jeroen commented 4 years ago

@ashannon what is your curl::curl_version() ?

ashannon commented 4 years ago

Thanks for the quick responses.

I’m on the road at the moment, with no access to my computer. If it helps, I recently installed a fresh version of R 3.6.1 after upgrading to Catalina, and installed all packages from CRAN (not from source), so my guess is it is the latest version of curl that is installed. Will report back with the exact version as a soon as I can.

ashannon commented 4 years ago

Hello again,

Here is the output provided by curl::curl_version() :

$version [1] "7.64.1"

$ssl_version [1] "(SecureTransport) LibreSSL/2.8.3"

$libz_version [1] "1.2.11"

$libssh_version [1] NA

$libidn_version [1] NA

$host [1] "x86_64-apple-darwin19.0"

$protocols [1] "dict" "file" "ftp" "ftps" "gopher" "http" "https" "imap" "imaps" "ldap" "ldaps" "pop3" "pop3s" "rtsp" "smb"
[16] "smbs" "smtp" "smtps" "telnet" "tftp"

$ipv6 [1] TRUE

$http2 [1] TRUE

$idn [1] FALSE

jeroen commented 4 years ago

Hmm okay. libcurl 7.62 and up enable http/2 by default, but it seems like this server may be running a buggy older version of http/2. Maybe the safest is to disable http/2.

jeroen commented 4 years ago

You didn't install a custom libcurl, right? This is the version in /usr/bin/curl --version ?

ashannon commented 4 years ago

Correct, this is not a custom install. Here is the output from /usr/bin/curl --version:

curl 7.64.1 (x86_64-apple-darwin19.0) libcurl/7.64.1 (SecureTransport) LibreSSL/2.8.3 zlib/1.2.11 nghttp2/1.39.2
Release-Date: 2019-03-27
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtsp smb smbs smtp smtps telnet tftp 
Features: AsynchDNS GSS-API HTTP2 HTTPS-proxy IPv6 Kerberos Largefile libz MultiSSL NTLM NTLM_WB SPNEGO SSL UnixSockets

How does one disable http/2? I can give that a shot and report back.

jeroen commented 4 years ago

I haven't upgraded to Calalina yet, so I can't debug this yet. From your output your libcurl seems to be compiled with two different TLS backends: LibreSSL (default) and SecureTransport.

One thing you can try is switching to SecureTransport (apple's native TLS). To do this you need to set an environment variable in your .Rprofile:

CURL_SSL_BACKEND=SecureTransport

This is explained in the vignette for the case of Windows, but apparently MacOS now also supports this. Can you try starting R with this variable, and tell us what your curl::curl_version() then is?

jeroen commented 4 years ago

Is there a way I can reproduce this (without having to sign up for an account)?

eddelbuettel commented 4 years ago

You probably need the token :-/ But they are not big and evil so it may not be such a big hurdle...

jeroen commented 4 years ago

OK I have a token now. Also running MacOS Catalina. @ashannon any specific combination of API calls that is likely to trigger the problem?

ashannon commented 4 years ago

Hi @jeroen ,

I tried setting CURL_SSL_BACKEND=SecureTransport in .Renviron, but after restarting R, curl::curl:version() still shows the same output:

`$version [1] "7.64.1"

$ssl_version [1] "SecureTransport (LibreSSL/2.8.3)"

$libz_version [1] "1.2.11"

$libssh_version [1] NA

$libidn_version [1] NA

$host [1] "x86_64-apple-darwin19.0"

$protocols [1] "dict" "file" "ftp" "ftps" "gopher" "http" "https" "imap" "imaps" "ldap" "ldaps" "pop3" "pop3s" "rtsp" "smb"
[16] "smbs" "smtp" "smtps" "telnet" "tftp"

$ipv6 [1] TRUE

$http2 [1] TRUE

$idn [1] FALSE`

As for any specific combinations of API calls causing the errors, the failures appear to be happening randomly. My application has a series of preset messages which go off on a set schedule each day (every 15 minutes). These messages are all the same in nature (i.e. a message of type "note" , with a simple title and a body). Most of the time they work, but sometimes (20-30% of the time), I get the reported error message. Sometimes the errors are clustered together, sometimes not. I cannot discern a pattern of any sort.

jeroen commented 4 years ago

The output is not the same, if you look closely the ssl_version is now different,

eddelbuettel commented 4 years ago

Looks like "(SecureTransport) LibreSSL/2.8.3" in both cases, no?

jeroen commented 4 years ago

The second shows the opposite: SecureTransport (LibreSSL/2.8.3) (the one in parenthesis is the inactive backend). See also the windows vignette: https://cran.r-project.org/web/packages/curl/vignettes/windows.html

eddelbuettel commented 4 years ago

Got it. That is one obscure way of printing things...

jeroen commented 4 years ago

Well for about 20 years curl had at most one ssl implementation so that feature string would just contain e.g. "openssl 1.0.2".

But a year ago they merged in a feature to build curl with multiple ssl backends to pick one at runtime. So they had to generalize that string to something that would show all back-ends and also the one in use.

ashannon commented 4 years ago

Good catch @jeroen. I agree with @eddelbuettel that the notation could be a bit more explicit.

I will restart my production app, specifying "SecureTransport" as the curl backend in the .Renviron file, and report back in 24-48 hours.

ashannon commented 4 years ago

Checking in again. It looks like the SecureTransport SSL backend is not making a difference. The error message still occurs in a seemingly random fashion.

eddelbuettel commented 4 years ago

It will be hard to chase this without anything concrete and reproducible.

jeroen commented 4 years ago

OK the best solution then is to not use HTTP/2 for this server. See this chapter for the vignette: https://cran.r-project.org/web/packages/curl/vignettes/intro.html#disabling_http2

ashannon commented 4 years ago

@jeroen, seems like fixing this requires changes to the RPushbullet code itself, as this is where handle_setopt(handle, http_version = 2) can be set.

@eddelbuettel , could you point me to the internal functions in RPushbullet that specify the "handles" that are fed to curl? I can think of RPushbullet:::.createPush(), but are there others that would need to be changed as well?

Thanks

eddelbuettel commented 4 years ago

@ashannon There is nothing hidden -- all the code is in the repo. Beauty of REST (when it works ...), we really just fire off requests with parameters.

ashannon commented 4 years ago

@eddelbuettel , ok I will give modifying the source code a shot to use HTTP 1.1 instead, and report back, probably sometime this weekend.

ashannon commented 4 years ago

The issue appears to be fixed by setting http to v1.1 as per @jeroen 's suggestion.

@eddelbuettel , thanks for accepting my PR to make this change in the master branch!

Best,

A.

eddelbuettel commented 4 years ago

Now @jeroen said best solution then is to not use HTTP/2 for this server. (Emphasis mine.) That is different from turning back to 1.1 everywhere and unconditionally. Shall we maybe just make it an option?

ashannon commented 4 years ago

The benefit of making it an option is having additional flexibility, at the potential expense of adding unnecessary complexity to the package.

The benefit of hard setting it to http v1.1 avoids a (albeit rare) known issue, and, to my knowledge, does not impede RPushbullet's ability to function in any way.

As @jeroen pointed out, http v2.0 was made the default option as of libbcurl version 7.62, which was released relatively recently (oct 2018). This would imply that prior to that date, RPushbullet was using an earlier version of http (I'm guessing v1.1) the whole time without any issues.

It's you call at the end of day, but I'm ok with either approach.

eddelbuettel commented 4 years ago

Good points. Making it a toggle, or an options, with a "sensible" default, may be best. I generally trust upstream, and it is hard to argue webstandards with the curl author who clearly knows what he is doing.

You and other could then set a local option in ~/.Rprofile and alike and locally override without effort. Good enough?

ashannon commented 4 years ago

Yes I think this is a good solution. Better to align the package with where the technology behind it is headed by default (i.e. to set http v2.0 as the default) and to allow an override mechanism providing backwards compatibility if needed.

I must admit I am not sure exactly what would be the best way to implement the override you are suggesting. Would it be to simply set an option for the curl:: package directly to use http v1.1 by default or an option for the RPushbullet:: package which, if set accordingly, would then make a modified call to RPushbullet:::.getCurlHandle() specifying curl::handle_setopt(h,http_version = 2) ?

eddelbuettel commented 4 years ago

I think (and shooting from the hip here) we have models for that already in R/init.R: set up values in the per-package environment with a default, maybe even just TRUE and FALSE for something like useCurlDefaultStandard. The add an accessor function to override that default value easily. And then in the sending function reflect the value and toggle between 2.0 and 1.1 as indicated by the value.

How does that sound?

eddelbuettel commented 4 years ago

@ashannon Thanks for working through this and fixing your use case. I just committed a small change to a new branch and will make that a new pull request (likely #60) is a moment. Could you test that?

The new behaviour does what your change did if and only if you run

options("rpushbullet.useHTTP11"=TRUE) 

in, say, your ~/.Rprofile, or right before running the code RPushbullet code.

eddelbuettel commented 4 years ago

@ashannon let me know if you have a chance to check out #60 which is simple generalization of your change to set the http/1.1 mode.

ashannon commented 4 years ago

Hi @eddelbuettel , thanks for making this change. I will give that shot and report back sometime this week, Thursday at the latest.

ashannon commented 4 years ago

@eddelbuettel , the PR works as intended when specifying options("rpushbullet.useHTTP11"=TRUE) in ~/.Rprofile. Thanks for making this change.

eddelbuettel commented 4 years ago

Thanks for closing the ticket. Looks like I missed that earlier...