search

heroku / heroku-sbt-plugin

An sbt plugin for deploying Heroku Scala applications
MIT License
111 stars 17 forks source link

Failure reported by sbt-heroku Despite Build Success #44

Closed neilchaudhuri closed 4 years ago

neilchaudhuri commented 4 years ago

In my Play Framework (Scala) 2.6.x project, I have the following setup in my plugins.sbt:

addSbtPlugin("com.heroku" % "sbt-heroku" % "2.1.0")

addSbtPlugin("com.typesafe.sbt" % "sbt-native-packager" % "1.2.0")

This has worked for a while, but lately when I deploy with sbt-heroku and the build passes, I see this exception in the console:

java.lang.RuntimeException: The build failed
at com.heroku.sdk.deploy.Deployer.createRelease(Deployer.java:188)
at com.heroku.sdk.deploy.Deployer.deploy(Deployer.java:91)
at com.heroku.sdk.deploy.App.deploy(App.java:61)
at com.heroku.sbt.SbtApp.deploy(SbtApp.scala:98)
at com.heroku.sbt.HerokuPlugin$autoImport$$anonfun$baseHerokuSettings$2.apply(HerokuPlugin.scala:53)
at com.heroku.sbt.HerokuPlugin$autoImport$$anonfun$baseHerokuSettings$2.apply(HerokuPlugin.scala:26)
at scala.Function1$$anonfun$compose$1.apply(Function1.scala:47)
at sbt.$tilde$greater$$anonfun$$u2219$1.apply(TypeFunctions.scala:40)
at sbt.std.Transform$$anon$4.work(System.scala:63)
at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:228)
at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:228)
at sbt.ErrorHandling$.wideConvert(ErrorHandling.scala:17)
at sbt.Execute.work(Execute.scala:237)
at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:228)
at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:228)
at sbt.ConcurrentRestrictions$$anon$4$$anonfun$1.apply(ConcurrentRestrictions.scala:159)
at sbt.CompletionService$$anon$2.call(CompletionService.scala:28)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
[error] (compile:deployHeroku) The build failed

Any ideas why?

Thanks.

Malax commented 4 years ago

Can you share your sbt version or, if possible, an example repo where this issue occurs? You can also try to update sbt-heroku to 2.1.2 and see if that fixes your issue.

neilchaudhuri commented 4 years ago

It was 0.13.8. The weird thing is that it always reported correctly and then didn't, and it was never clear to me what changed (outside of source files).

I will upgrade and see what happens.

neilchaudhuri commented 4 years ago

After upgrading there is no change. The build succeeds, but sbt-heroku reports failure.

Malax commented 4 years ago

I'll take a deeper look to see what might cause this.

Malax commented 4 years ago

@neilchaudhuri I've just updated sbt-heroku to 2.1.4 which might fix the issue you're having. Can you confirm?

neilchaudhuri commented 4 years ago

Unfortunately the update didn't help:

[info] -----> Deploying...
[info] remote: Deployment output not available. Polling for status...
java.lang.RuntimeException: The build failed
    at com.heroku.sdk.deploy.Deployer.createRelease(Deployer.java:188)
    at com.heroku.sdk.deploy.Deployer.deploy(Deployer.java:91)
    at com.heroku.sdk.deploy.App.deploy(App.java:62)
    at com.heroku.sbt.SbtApp.deploy(SbtApp.scala:98)
    at com.heroku.sbt.HerokuPlugin$autoImport$$anonfun$baseHerokuSettings$2.apply(HerokuPlugin.scala:53)
    at com.heroku.sbt.HerokuPlugin$autoImport$$anonfun$baseHerokuSettings$2.apply(HerokuPlugin.scala:26)
    at scala.Function1$$anonfun$compose$1.apply(Function1.scala:47)
    at sbt.$tilde$greater$$anonfun$$u2219$1.apply(TypeFunctions.scala:40)
    at sbt.std.Transform$$anon$4.work(System.scala:63)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:228)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:228)
    at sbt.ErrorHandling$.wideConvert(ErrorHandling.scala:17)
    at sbt.Execute.work(Execute.scala:237)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:228)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:228)
    at sbt.ConcurrentRestrictions$$anon$4$$anonfun$1.apply(ConcurrentRestrictions.scala:159)
    at sbt.CompletionService$$anon$2.call(CompletionService.scala:28)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
[error] (compile:deployHeroku) The build failed

But on the server:

[info] play.api.Play - Application started (Prod)
[info] p.c.s.AkkaHttpServer - Listening for HTTP on /0:0:0:0:0:0:0:0:54154
heroku/web.1: State changed from starting to up
app/api: Build succeeded
Malax commented 4 years ago

This looks like Heroku's API does not correctly confirm that the deployment worked. Can you run

$ HEROKU_DEBUG=1 sbt --debug deployHeroku

and post the output here? It should log the actual response received by the API. Do you happen to run Java lower than 8u101? Older Java versions don't have the necessary root certificates to support Let's Encrypt which is used by at least some parts of the API.

neilchaudhuri commented 4 years ago

Here is the output you requested:

[addSbt] arg = '-debug'
[residual] arg = 'deployHeroku'
[residual] arg = 'deployHeroku'
[process_args] java_version = '11'
[sbt_options] declare -a sbt_options='([0]="-Dsbt.jse.engineType=Node")'
[addMemory] arg = '1024'
[addJava] arg = '-Xms1024m'
[addJava] arg = '-Xmx1024m'
[addJava] arg = '-Xss4M'
[addJava] arg = '-XX:ReservedCodeCacheSize=128m'
[copyRt] java9_rt = '/Users/Neil/.sbt/0.13/java9-rt-ext-adoptopenjdk_11_0_5/rt.jar'
[addJava] arg = '-Dscala.ext.dirs=/Users/Neil/.sbt/0.13/java9-rt-ext-adoptopenjdk_11_0_5'
# Executing command line:
java
-Dfile.encoding=UTF-8
-Xms1024m
-Xmx1024m
-Xss4M
-XX:ReservedCodeCacheSize=128m
-Dscala.ext.dirs=/Users/Neil/.sbt/0.13/java9-rt-ext-adoptopenjdk_11_0_5
-Dsbt.jse.engineType=Node
-jar
/usr/local/Cellar/sbt/1.3.6/libexec/bin/sbt-launch.jar
-debug
deployHeroku

[warn] insecure HTTP request is deprecated 'http://repo.typesafe.com/typesafe/releases'; switch to HTTPS or opt-in as ("typesafe-releases" at "http://repo.typesafe.com/typesafe/releases").withAllowInsecureProtocol(true)ile / unmanagedResources / inputFileStamps 0s

[warn] insecure HTTP request is deprecated 'http://repo.typesafe.com/typesafe/releases'; switch to HTTPS or opt-in as ("typesafe-releases" at "http://repo.typesafe.com/typesafe/releases").withAllowInsecureProtocol(true)ile / unmanagedResources / inputFileStamps 0s

[warn] insecure HTTP request is deprecated 'Patterns(ivyPatterns=Vector(http://repo.typesafe.com/typesafe/ivy-releases/[organization]/[module]/(scala_[scalaVersion]/)(sbt_[sbtVersion]/)[revision]/[type]s/[artifact](-[classifier]).[ext]), artifactPatterns=Vector(http://repo.typesafe.com/typesafe/ivy-releases/[organization]/[module]/(scala_[scalaVersion]/)(sbt_[sbtVersion]/)[revision]/[type]s/[artifact](-[classifier]).[ext]), isMavenCompatible=false, descriptorOptional=false, skipConsistencyCheck=false)'; switch to HTTPS or opt-in as Resolver.url("typesafe-ivy-releasez", url(...)).withAllowInsecureProtocol(true)cope / csrConfiguration 0s

[warn] insecure HTTP request is deprecated 'Patterns(ivyPatterns=Vector(http://repo.typesafe.com/typesafe/ivy-releases/[organization]/[module]/(scala_[scalaVersion]/)(sbt_[sbtVersion]/)[revision]/[type]s/[artifact](-[classifier]).[ext]), artifactPatterns=Vector(http://repo.typesafe.com/typesafe/ivy-releases/[organization]/[module]/(scala_[scalaVersion]/)(sbt_[sbtVersion]/)[revision]/[type]s/[artifact](-[classifier]).[ext]), isMavenCompatible=false, descriptorOptional=false, skipConsistencyCheck=false)'; switch to HTTPS or opt-in as Resolver.url("typesafe-ivy-releasez", url(...)).withAllowInsecureProtocol(true)cope / csrConfiguration 0s

[warn] insecure HTTP request is deprecated 'http://repo.typesafe.com/typesafe/releases'; switch to HTTPS or opt-in as ("typesafe-releases" at "http://repo.typesafe.com/typesafe/releases").withAllowInsecureProtocol(true)ile / unmanagedResources / inputFileStamps 0s

[warn] insecure HTTP request is deprecated 'Patterns(ivyPatterns=Vector(http://repo.typesafe.com/typesafe/ivy-releases/[organization]/[module]/(scala_[scalaVersion]/)(sbt_[sbtVersion]/)[revision]/[type]s/[artifact](-[classifier]).[ext]), artifactPatterns=Vector(http://repo.typesafe.com/typesafe/ivy-releases/[organization]/[module]/(scala_[scalaVersion]/)(sbt_[sbtVersion]/)[revision]/[type]s/[artifact](-[classifier]).[ext]), isMavenCompatible=false, descriptorOptional=false, skipConsistencyCheck=false)'; switch to HTTPS or opt-in as Resolver.url("typesafe-ivy-releasez", url(...)).withAllowInsecureProtocol(true)cope / csrConfiguration 0s

[debug] "not up to date. inChanged = true, force = false

[debug] Updating ProjectRef(uri("file:/Users/Neil/.sbt/1.0/plugins/"), "global-plugins")...

[debug] Done updating ProjectRef(uri("file:/Users/Neil/.sbt/1.0/plugins/"), "global-plugins")

[debug] Full compilation, no sources in previous analysis.
[debug] Copy resource mappings: 
[debug]         
[debug] Other repositories:
[debug] Default repositories:
[debug] Using inline dependencies specified in Scala.
[debug] Checking for meta build source updates
[debug] Checking for meta build source updates
[debug] Checking for meta build source updates
[debug] Checking for meta build source updates
[debug] Checking for meta build source updates
Malax commented 4 years ago

@neilchaudhuri Thank you for the log. It seems to be truncated though. There should be sbt-heroku specific output after [debug] Checking for meta build source updates. Can you confirm that this is all the output you're getting with the command I posted before?

This is what I get:

[debug] +--------------------+
[debug] | sbt-heroku details |
[debug] +--------------------+-----------------------------------------------
[debug] | baseDirectory -> /Users/malax/projects/play-scala-seed
[debug] | targetDir     -> /Users/malax/projects/play-scala-seed/target
[debug] | jdkVersion    -> 1.8
[debug] | appName       -> obscure-brushlands-54722
[debug] | includePaths  ->
[debug] | buildpacks    ->
[debug] +--------------------------------------------------------------------
[info] -----> Packaging application...
[info]        - app: obscure-brushlands-54722
[info]        - including: target/universal/stage/
[debug] Procfile:
[debug] ===================
[debug] web: target/universal/stage/bin/2-8 -Dhttp.port=$PORT
[debug] console: target/universal/stage/bin/2-8 -main scala.tools.nsc.MainGenericRunner -usejavacp
[debug]
[debug] ===================
[debug] Heroku existing config variables: []
[info] -----> Creating build...
[info]        - file: target/heroku/build.tgz
[info]        - size: 47MB
[debug] Heroku Blob URL: https://s3-external-1.amazonaws.com/heroku-sources-production/2b9d4c53-f49b-46b3-adb8-9cc07a44605c?AWSAccessKeyId=AKIAJ6LKZGKGPARPZE4A&Signature=NTINomPKz338hZ0zzwVftCHN5Oo%3D&Expires=1580463401
[info] -----> Uploading slug... (100%)
[info]        - success
[info] -----> Deploying...
[info] remote:
[info] remote: -----> sbt-heroku app detected
[info] remote: -----> Installing JDK 1.8... done
[info] remote: -----> Discovering process types
[info] remote:        Procfile declares types -> console, web
[info] remote:
[info] remote: -----> Compressing...
[info] remote:        Done: 98.2M
[info] remote: -----> Launching...
[info] remote:        Released v9
[info] remote:        https://obscure-brushlands-54722.herokuapp.com/ deployed to Heroku
[info] remote:
[info] -----> Done
neilchaudhuri commented 4 years ago

Sorry, I used the IntelliJ terminal rather than the real terminal. As the output is too long, I will attach a file. sbt.log

Malax commented 4 years ago

@neilchaudhuri In your attached log the deployment seems to work and it is reported as such. You also get the remote: logging you did not get before. Did you change anything else?

neilchaudhuri commented 4 years ago

The successful run was in the terminal on my machine. The failing runs occur via IntelliJ Run Configuration. The weird thing is that the the latter used to run perfectly, and I don't know what changed.

Attached is the Run Configuration.

Screen Shot 2020-02-03 at 8 45 25 AM

And here is the beginning of IntelliJ's output when I execute it:

/Library/Java/JavaVirtualMachines/jdk1.8.0_31.jdk/Contents/Home/bin/java -Xms512M -Xmx1024M -Xss1M -XX:+CMSClassUnloadingEnabled "-javaagent:/Applications/IntelliJ IDEA.app/Contents/lib/idea_rt.jar=54638:/Applications/IntelliJ IDEA.app/Contents/bin" -Dfile.encoding=UTF-8 -classpath "/Users/Neil/Library/Application Support/IntelliJIdea2019.3/Scala/launcher/sbt-launch.jar" xsbt.boot.Boot stage deployHeroku

Looks like the JDK that IntelliJ uses might be the issue.

Malax commented 4 years ago

@neilchaudhuri The main difference I spot is the very different JDK version. 11.0.5 in your regular terminal session and 1.8.0_31 in IntelliJ. The latter version does not have the required root certificate for LetsEncrypt which is required to view the build output (https://bugs.openjdk.java.net/browse/JDK-8154757) so that explains at least why the build output is missing.

java.lang.RuntimeException: The build failed

from your initial report is more puzzling. It could be that u31 of 1.8.0 has issues connecting to the Heroku build API for some reason (maybe also a SSL/TLS issue). As for why the issue came up only recently, maybe the JDK you use within IntelliJ changed? In either case, I suggest upgrading your JDK within IntelliJ and see if that fixes your issue.

neilchaudhuri commented 4 years ago

I upgraded to the latest JDK 8, and as we suspected that was the problem. Configuring IntelliJ to use the upgraded JDK and then running sbt-heroku inside its terminal worked as expected.

The only odd curiosity is that running JDK 11 inside IntelliJ produced a conflict with the old version of SBT I am using currently and ultimately failed, but that configuration works in the terminal as we saw. Weird.

Anyway, I will be upgrading to Play 2.8 soon, and that implies an upgrade to JDK and SBT as well. Hopefully things will be compatible going forward.

Thanks for your help.