Upgrading to v0.31.0 heroku failing

vic_fleet · November 11, 2018, 9:31pm

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

notrom · November 12, 2018, 2:26am

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

AndrewMBaines · November 12, 2018, 8:10am

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

jhonnyV · November 12, 2018, 11:29am

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

vic_fleet · November 12, 2018, 5:38pm

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

notrom · November 12, 2018, 8:08pm

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.

tahisro · November 13, 2018, 4:33am

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

jhonnyV · December 5, 2018, 2:11pm

@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

vic_fleet · December 8, 2018, 8:19pm

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