Upgrading to v0.31.0 heroku failing


#1

I attempted to upgrade to 0.31.0 on heroku and keep getting a Java heap space message while checking if DB has unrun migrations. I attempted to fix it by upgrading my dyno but didn’t make a difference. Any suggestions? Log included below.

2018-11-11T21:09:51.634518+00:00 app[web.1]: 11-11 21:09:51 e[1mINFO metabase.dbe[0m :: e[36mVerifying postgres Database Connection ...e[0m
2018-11-11T21:09:52.158638+00:00 app[web.1]: 11-11 21:09:52 e[1mINFO metabase.dbe[0m :: Verify Database Connection ...  ✅
2018-11-11T21:09:52.159206+00:00 app[web.1]: 11-11 21:09:52 e[1mINFO metabase.dbe[0m :: Running Database Migrations...
2018-11-11T21:09:52.235712+00:00 app[web.1]: 11-11 21:09:52 e[1mINFO metabase.dbe[0m :: Setting up Liquibase...
2018-11-11T21:09:52.466246+00:00 app[web.1]: 11-11 21:09:52 e[1mINFO metabase.dbe[0m :: Liquibase is ready.
2018-11-11T21:09:52.467599+00:00 app[web.1]: 11-11 21:09:52 e[1mINFO metabase.dbe[0m :: Checking if Database has unrun migrations...
2018-11-11T21:10:20.439191+00:00 app[web.1]: 11-11 21:10:20 e[1mWARN metabase.utile[0m :: e[31mauto-retry metabase.db$run_schema_migrations_BANG_$fn__15456@72602969: Java heap spacee[0m
2018-11-11T21:10:20.511048+00:00 app[web.1]: 11-11 21:10:20 e[1mINFO metabase.dbe[0m :: Setting up Liquibase...
2018-11-11T21:10:20.601412+00:00 app[web.1]: 11-11 21:10:20 e[1mINFO metabase.dbe[0m :: Liquibase is ready.
2018-11-11T21:10:20.602023+00:00 app[web.1]: 11-11 21:10:20 e[1mINFO metabase.dbe[0m :: Checking if Database has unrun migrations...
2018-11-11T21:10:58.938675+00:00 heroku[router]: at=error code=H12 desc="Request timeout" method=GET path="/" host=metrics.tryfleet.com request_id=06306136-1f59-4f15-bf94-de8f36254c1d fwd="71.236.154.30" dyno=web.1 connect=0ms service=30000ms status=503 bytes=0 protocol=http
2018-11-11T21:11:08.405828+00:00 heroku[router]: at=error code=H12 desc="Request timeout" method=GET path="/api/setup/admin_checklist" host=metrics.tryfleet.com request_id=65be7e9e-4c75-497c-af03-85aa350585d5 fwd="71.236.154.30" dyno=web.1 connect=1ms service=30001ms status=503 bytes=0 protocol=http
2018-11-11T21:11:17.828552+00:00 app[web.1]: Exception in thread "qtp451064016-18" java.lang.OutOfMemoryError: Java heap space
2018-11-11T21:11:29.451136+00:00 heroku[router]: at=error code=H12 desc="Request timeout" method=GET path="/favicon.ico" host=metrics.tryfleet.com request_id=735dbbbd-59be-4afd-97ad-82e2ecb128aa fwd="71.236.154.30" dyno=web.1 connect=1ms service=30000ms status=503 bytes=0 protocol=http
2018-11-11T21:11:39.294219+00:00 app[web.1]: Exception in thread "qtp451064016-17" java.lang.OutOfMemoryError: Java heap space
2018-11-11T21:11:41.440084+00:00 app[web.1]: Exception in thread "qtp451064016-23" java.lang.OutOfMemoryError: Java heap space
2018-11-11T21:11:50.889957+00:00 app[web.1]: 11-11 21:11:50 e[1mERROR metabase.coree[0m :: Metabase Initialization FAILED
2018-11-11T21:11:50.889982+00:00 app[web.1]: java.lang.OutOfMemoryError: Java heap space
2018-11-11T21:11:50.912294+00:00 app[web.1]: 11-11 21:11:50 e[1mINFO metabase.coree[0m :: Metabase Shutting Down ...
2018-11-11T21:11:50.914006+00:00 app[web.1]: 11-11 21:11:50 e[1mINFO metabase.coree[0m :: Metabase Shutdown COMPLETE
2018-11-11T21:11:51.401989+00:00 heroku[web.1]: State changed from up to crashed
2018-11-11T21:11:51.364966+00:00 heroku[web.1]: Process exited with status 1
2018-11-11T21:16:53.000000+00:00 app[api]: Build started by user victor@tryfleet.com
2018-11-11T21:17:12.004954+00:00 heroku[web.1]: State changed from crashed to starting
2018-11-11T21:17:11.775395+00:00 app[api]: Deploy 76e4871b by user victor@tryfleet.com
2018-11-11T21:17:11.775395+00:00 app[api]: Release v7 created by user victor@tryfleet.com
2018-11-11T21:17:12.000000+00:00 app[api]: Build succeeded
2018-11-11T21:17:17.640001+00:00 heroku[web.1]: Starting process with command `HEROKU=true ./bin/start`
2018-11-11T21:17:20.869948+00:00 app[web.1]: Setting JAVA_TOOL_OPTIONS defaults based on dyno size. Custom settings will override them.
2018-11-11T21:17:20.875040+00:00 app[web.1]: Using these JAVA_OPTS: -Xmx300m -Xss512k -XX:CICompilerCount=2 -Dfile.encoding=UTF-8  -Xmx248m -XX:-UseGCOverheadLimit -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:+UseCompressedOops -XX:+UseCompressedClassPointers -XX:+IgnoreUnrecognizedVMOptions -Djava.awt.headless=true -Dfile.encoding=UTF-8 --add-opens=java.base/java.net=ALL-UNNAMED --add-modules=java.xml.bind
2018-11-11T21:17:21.006297+00:00 app[web.1]: Picked up JAVA_TOOL_OPTIONS: -Xmx300m -Xss512k -XX:CICompilerCount=2 -Dfile.encoding=UTF-8
2018-11-11T21:17:34.105552+00:00 app[web.1]: 11-11 21:17:34 e[1mINFO metabase.utile[0m :: Loading Metabase...
2018-11-11T21:17:45.783128+00:00 app[web.1]: 11-11 21:17:45 e[1mINFO util.encryptione[0m :: Saved credentials encryption is DISABLED for this Metabase instance. 🔓
2018-11-11T21:17:45.783139+00:00 app[web.1]: For more information, see https://www.metabase.com/docs/latest/operations-guide/start.html#encrypting-your-database-connection-details-at-rest
2018-11-11T21:18:02.562642+00:00 app[web.1]: 11-11 21:18:02 e[1mINFO metabase.coree[0m :: Starting Metabase in STANDALONE mode
2018-11-11T21:18:02.588306+00:00 app[web.1]: 11-11 21:18:02 e[1mINFO metabase.coree[0m :: Launching Embedded Jetty Webserver with config:
2018-11-11T21:18:02.588310+00:00 app[web.1]: {:port 18082}
2018-11-11T21:18:02.588312+00:00 app[web.1]: 
2018-11-11T21:18:02.674425+00:00 app[web.1]: 11-11 21:18:02 e[1mINFO metabase.coree[0m :: Starting Metabase version v0.31.0 (adf9a89 release-0.31.0) ...
2018-11-11T21:18:02.674816+00:00 app[web.1]: 11-11 21:18:02 e[1mINFO metabase.coree[0m :: System timezone is 'Etc/UTC' ...
2018-11-11T21:18:17.999158+00:00 app[web.1]: WARNING: any? already refers to: #'clojure.core/any? in namespace: monger.collection, being replaced by: #'monger.collection/any?
2018-11-11T21:18:19.301701+00:00 app[web.1]: 11-11 21:18:19 e[1mINFO metabase.coree[0m :: Setting up and migrating Metabase DB. Please sit tight, this may take a minute...
2018-11-11T21:18:19.305685+00:00 app[web.1]: 11-11 21:18:19 e[1mINFO metabase.dbe[0m :: e[36mVerifying postgres Database Connection ...e[0m
2018-11-11T21:18:19.535984+00:00 app[web.1]: 11-11 21:18:19 e[1mINFO metabase.dbe[0m :: Verify Database Connection ...  ✅
2018-11-11T21:18:19.536645+00:00 app[web.1]: 11-11 21:18:19 e[1mINFO metabase.dbe[0m :: Running Database Migrations...
2018-11-11T21:18:19.576929+00:00 app[web.1]: 11-11 21:18:19 e[1mINFO metabase.dbe[0m :: Setting up Liquibase...
2018-11-11T21:18:19.761358+00:00 app[web.1]: 11-11 21:18:19 e[1mINFO metabase.dbe[0m :: Liquibase is ready.
2018-11-11T21:18:19.761970+00:00 app[web.1]: 11-11 21:18:19 e[1mINFO metabase.dbe[0m :: Checking if Database has unrun migrations...
2018-11-11T21:18:43.951816+00:00 app[web.1]: 11-11 21:18:43 e[1mWARN metabase.utile[0m :: e[31mauto-retry metabase.db$run_schema_migrations_BANG_$fn__15456@72602969: Java heap spacee[0m
2018-11-11T21:18:43.997787+00:00 app[web.1]: 11-11 21:18:43 e[1mINFO metabase.dbe[0m :: Setting up Liquibase...
2018-11-11T21:18:44.087964+00:00 app[web.1]: 11-11 21:18:44 e[1mINFO metabase.dbe[0m :: Liquibase is ready.
2018-11-11T21:18:44.088545+00:00 app[web.1]: 11-11 21:18:44 e[1mINFO metabase.dbe[0m :: Checking if Database has unrun migrations...
2018-11-11T21:19:00.037550+00:00 app[web.1]: 11-11 21:19:00 e[1mERROR metabase.coree[0m :: Metabase Initialization FAILED
2018-11-11T21:19:00.037561+00:00 app[web.1]: java.lang.OutOfMemoryError: Java heap space
2018-11-11T21:19:00.037563+00:00 app[web.1]: at java.util.Arrays.copyOf(Arrays.java:3236)
2018-11-11T21:19:00.037564+00:00 app[web.1]: at java.io.ByteArrayOutputStream.toByteArray(ByteArrayOutputStream.java:191)
2018-11-11T21:19:00.037566+00:00 app[web.1]: at java.util.jar.JarVerifier.processEntry(JarVerifier.java:260)
2018-11-11T21:19:00.037568+00:00 app[web.1]: at java.util.jar.JarVerifier.update(JarVerifier.java:230)
2018-11-11T21:19:00.037569+00:00 app[web.1]: at java.util.jar.JarFile.initializeVerifier(JarFile.java:383)
2018-11-11T21:19:00.037571+00:00 app[web.1]: at java.util.jar.JarFile.getInputStream(JarFile.java:450)
2018-11-11T21:19:00.037573+00:00 app[web.1]: at sun.net.www.protocol.jar.JarURLConnection.getInputStream(JarURLConnection.java:164)
2018-11-11T21:19:00.037575+00:00 app[web.1]: at liquibase.resource.ClassLoaderResourceAccessor.getResourcesAsStream(ClassLoaderResourceAccessor.java:53)
2018-11-11T21:19:00.037577+00:00 app[web.1]: at liquibase.util.StreamUtil.singleInputStream(StreamUtil.java:186)
2018-11-11T21:19:00.037578+00:00 app[web.1]: at liquibase.parser.core.yaml.YamlChangeLogParser.parse(YamlChangeLogParser.java:27)
2018-11-11T21:19:00.037579+00:00 app[web.1]: at liquibase.changelog.DatabaseChangeLog.include(DatabaseChangeLog.java:525)
2018-11-11T21:19:00.037581+00:00 app[web.1]: at liquibase.changelog.DatabaseChangeLog.includeAll(DatabaseChangeLog.java:490)
2018-11-11T21:19:00.037583+00:00 app[web.1]: at liquibase.changelog.DatabaseChangeLog.handleChildNode(DatabaseChangeLog.java:368)
2018-11-11T21:19:00.037584+00:00 app[web.1]: at liquibase.changelog.DatabaseChangeLog.load(DatabaseChangeLog.java:293)
2018-11-11T21:19:00.037586+00:00 app[web.1]: at liquibase.parser.core.yaml.YamlChangeLogParser.parse(YamlChangeLogParser.java:78)
2018-11-11T21:19:00.037587+00:00 app[web.1]: at liquibase.Liquibase.getDatabaseChangeLog(Liquibase.java:217)
2018-11-11T21:19:00.037589+00:00 app[web.1]: at liquibase.Liquibase.listUnrunChangeSets(Liquibase.java:1281)
2018-11-11T21:19:00.037590+00:00 app[web.1]: at liquibase.Liquibase.listUnrunChangeSets(Liquibase.java:1274)
2018-11-11T21:19:00.037592+00:00 app[web.1]: at liquibase.Liquibase.listUnrunChangeSets(Liquibase.java:1270)
2018-11-11T21:19:00.037593+00:00 app[web.1]: at metabase.db$has_unrun_migrations_QMARK_.invokeStatic(db.clj:147)
2018-11-11T21:19:00.037595+00:00 app[web.1]: at metabase.db$has_unrun_migrations_QMARK_.invoke(db.clj:140)
2018-11-11T21:19:00.037596+00:00 app[web.1]: at metabase.db$migrate_up_if_needed_BANG_.invokeStatic(db.clj:177)
2018-11-11T21:19:00.037598+00:00 app[web.1]: at metabase.db$migrate_up_if_needed_BANG_.invoke(db.clj:168)
2018-11-11T21:19:00.037599+00:00 app[web.1]: at metabase.db$migrate_BANG_$fn__15423.invoke(db.clj:288)
2018-11-11T21:19:00.037601+00:00 app[web.1]: at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:747)
2018-11-11T21:19:00.037602+00:00 app[web.1]: at clojure.java.jdbc$db_transaction_STAR_.invoke(jdbc.clj:717)
2018-11-11T21:19:00.037604+00:00 app[web.1]: at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:782)
2018-11-11T21:19:00.037606+00:00 app[web.1]: at clojure.java.jdbc$db_transaction_STAR_.invoke(jdbc.clj:717)
2018-11-11T21:19:00.037607+00:00 app[web.1]: at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:730)
2018-11-11T21:19:00.037609+00:00 app[web.1]: at clojure.java.jdbc$db_transaction_STAR_.invoke(jdbc.clj:717)
2018-11-11T21:19:00.037610+00:00 app[web.1]: at metabase.db$migrate_BANG_.invokeStatic(db.clj:276)
2018-11-11T21:19:00.037612+00:00 app[web.1]: at metabase.db$migrate_BANG_.invoke(db.clj:257)
2018-11-11T21:19:00.041766+00:00 app[web.1]: 11-11 21:19:00 e[1mINFO metabase.coree[0m :: Metabase Shutting Down ...
2018-11-11T21:19:00.042695+00:00 app[web.1]: 11-11 21:19:00 e[1mINFO metabase.coree[0m :: Metabase Shutdown COMPLETE
2018-11-11T21:19:00.482413+00:00 heroku[web.1]: Process exited with status 1
2018-11-11T21:19:00.501659+00:00 heroku[web.1]: State changed from up to crashed
2018-11-11T21:19:00.503894+00:00 heroku[web.1]: State changed from crashed to starting
2018-11-11T21:19:08.384566+00:00 heroku[web.1]: Starting process with command `HEROKU=true ./bin/start`
2018-11-11T21:19:11.967292+00:00 app[web.1]: Setting JAVA_TOOL_OPTIONS defaults based on dyno size. Custom settings will override them.
2018-11-11T21:19:11.985830+00:00 app[web.1]: Using these JAVA_OPTS: -Xmx300m -Xss512k -XX:CICompilerCount=2 -Dfile.encoding=UTF-8  -Xmx248m -XX:-UseGCOverheadLimit -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:+UseCompressedOops -XX:+UseCompressedClassPointers -XX:+IgnoreUnrecognizedVMOptions -Djava.awt.headless=true -Dfile.encoding=UTF-8 --add-opens=java.base/java.net=ALL-UNNAMED --add-modules=java.xml.bind
2018-11-11T21:19:12.106798+00:00 app[web.1]: Picked up JAVA_TOOL_OPTIONS: -Xmx300m -Xss512k -XX:CICompilerCount=2 -Dfile.encoding=UTF-8
2018-11-11T21:20:01.007633+00:00 app[web.1]: 11-11 21:20:00 e[1mINFO metabase.utile[0m :: Loading Metabase...
2018-11-11T21:20:38.611185+00:00 heroku[web.1]: Error R10 (Boot timeout) -> Web process failed to bind to $PORT within 90 seconds of launch
2018-11-11T21:20:38.611335+00:00 heroku[web.1]: Stopping process with SIGKILL
2018-11-11T21:20:38.852571+00:00 heroku[web.1]: State changed from starting to crashed
2018-11-11T21:20:38.835971+00:00 heroku[web.1]: Process exited with status 137

Thanks


#2

I’m getting the same java.lang.OutOfMemoryError error when running v0.31.0 locally from the jar file on WIndows.

This is starting from scratch with just the v031.0 jar file, no existing DB:

java -jar metabase.jar
11-12 15:20:50 ←[1mINFO metabase.util←[0m :: Loading Metabase...
11-12 15:20:57 ←[1mINFO util.encryption←[0m :: Saved credentials encryption is DISABLED for this Metabase instance. For more information, see https://www.metabase.com/docs/latest/operations-guide/start.html#encrypting-your-database-connection-details-at-rest
11-12 15:21:30 ←[1mINFO metabase.core←[0m :: Starting Metabase in STANDALONE mode
11-12 15:21:30 ←[1mINFO metabase.core←[0m :: Launching Embedded Jetty Webserverwith config: {:port 3000}
11-12 15:21:30 ←[1mINFO metabase.core←[0m :: Starting Metabase version v0.31.0 (adf9a89 release-0.31.0) ...
11-12 15:21:30 ←[1mINFO metabase.core←[0m :: System timezone is 'Pacific/Auckland' ...WARNING: any? already refers to: #'clojure.core/any? in namespace: monger.collection, being replaced by: #'monger.collection/any?
11-12 15:21:36 ←[1mINFO metabase.core←[0m :: Setting up and migrating Metabase DB. Please sit tight, this may take a minute...
11-12 15:21:36 ←[1mINFO metabase.db←[0m :: Verifying h2 Database Connection ...
11-12 15:21:36 ←[1mINFO metabase.db←[0m :: Verify Database Connection ...
11-12 15:21:36 ←[1mINFO metabase.db←[0m :: Running Database Migrations...
11-12 15:21:36 ←[1mINFO metabase.db←[0m :: Setting up Liquibase...
11-12 15:21:36 ←[1mINFO metabase.db←[0m :: Liquibase is ready.
11-12 15:21:36 ←[1mINFO metabase.db←[0m :: Checking if Database has unrun migrations...
11-12 15:21:55 ←[1mWARN metabase.util←[0m :: auto-retry metabase.db$run_schema_migrations_BANG_$fn__15456@9d5a5a: Java heap space
11-12 15:21:55 ←[1mINFO metabase.db←[0m :: Setting up Liquibase...
11-12 15:21:55 ←[1mINFO metabase.db←[0m :: Liquibase is ready.
11-12 15:21:55 ←[1mINFO metabase.db←[0m :: Checking if Database has unrun migrations...
11-12 15:22:09 ←[1mERROR metabase.core←[0m :: Metabase Initialization FAILEDjava.lang.OutOfMemoryError: Java heap space
        at java.util.Hashtable.rehash(Unknown Source)
        at java.util.Hashtable.addEntry(Unknown Source)
        at java.util.Hashtable.put(Unknown Source)
        at sun.security.util.SignatureFileVerifier.updateSigners(Unknown Source)

        at sun.security.util.SignatureFileVerifier.processImpl(Unknown Source)
        at sun.security.util.SignatureFileVerifier.process(Unknown Source)
        at java.util.jar.JarVerifier.processEntry(Unknown Source)
        at java.util.jar.JarVerifier.update(Unknown Source)
        at java.util.jar.JarFile.initializeVerifier(Unknown Source)
        at java.util.jar.JarFile.getInputStream(Unknown Source)
        at sun.net.www.protocol.jar.JarURLConnection.getInputStream(Unknown Source)
        at liquibase.resource.ClassLoaderResourceAccessor.getResourcesAsStream(ClassLoaderResourceAccessor.java:53)
        at liquibase.util.StreamUtil.singleInputStream(StreamUtil.java:186)
        at liquibase.parser.core.yaml.YamlChangeLogParser.parse(YamlChangeLogParser.java:27)
        at liquibase.changelog.DatabaseChangeLog.include(DatabaseChangeLog.java:525)
        at liquibase.changelog.DatabaseChangeLog.includeAll(DatabaseChangeLog.java:490)
        at liquibase.changelog.DatabaseChangeLog.handleChildNode(DatabaseChangeLog.java:368)
        at liquibase.changelog.DatabaseChangeLog.load(DatabaseChangeLog.java:293)
        at liquibase.parser.core.yaml.YamlChangeLogParser.parse(YamlChangeLogParser.java:78)
        at liquibase.Liquibase.getDatabaseChangeLog(Liquibase.java:217)
        at liquibase.Liquibase.listUnrunChangeSets(Liquibase.java:1281)
        at liquibase.Liquibase.listUnrunChangeSets(Liquibase.java:1274)
        at liquibase.Liquibase.listUnrunChangeSets(Liquibase.java:1270)
        at metabase.db$has_unrun_migrations_QMARK_.invokeStatic(db.clj:147)
        at metabase.db$has_unrun_migrations_QMARK_.invoke(db.clj:140)
        at metabase.db$migrate_up_if_needed_BANG_.invokeStatic(db.clj:177)
        at metabase.db$migrate_up_if_needed_BANG_.invoke(db.clj:168)
        at metabase.db$migrate_BANG_$fn__15423.invoke(db.clj:288)
        at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:747)
        at clojure.java.jdbc$db_transaction_STAR_.invoke(jdbc.clj:717)
        at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:782)
        at clojure.java.jdbc$db_transaction_STAR_.invoke(jdbc.clj:717)
11-12 15:22:09 ←[1mINFO metabase.core←[0m :: Metabase Shutting Down ...
11-12 15:22:09 ←[1mINFO metabase.core←[0m :: Metabase Shutdown COMPLETE

#3

I’d try more RAM, check firewall and (for number 2) check Java version.


#4

I got the same error, downgrade to 0.31.0-RC1 and everything will be back to normal

You need to edit the metabase buildpack to this: https://github.com/metabase/metabase-buildpack#0.31.0-RC1


#5

So the release candidate works? But the actual release doesn’t? Is that what you are saying @jhonnyV?


#6

Java 1.8.0_101-b13. I just found https://metabase.com/docs/latest/troubleshooting-guide/running.html which shows me a work around to specify the memory available to Java. This allows me to run v0.31.0 so it’s a work around, but v0.31-RC1 works without using the work around in the exact same environment so something may have changed for the worse between them.


#7

I got too.
Can I edit to app.json? for downgrade to it


#8

@vic_fleet Yes

@tahisro Yes, I edited app.json to "url": "https://github.com/metabase/metabase-buildpack#0.31.0-RC1" and I also updated the buildpack on the heroku dashboard (settings tab), after that do a commit and it should deploy to RC1


#9

I just ended up taking the heroku instance down and moved it to beanstalk. Its way faster and easier to maintain as well.