search

RIPE-NCC / rpki-validator

Other
64 stars 20 forks source link

Doesn't work since v2.23 - possibly due to a DbMigrate failure #34

Closed toreanderson closed 6 years ago

toreanderson commented 6 years ago

Tried to upgrade to the latest version the other day. It simply didn't work. On the Trust Anchors page Processed items are all 0, Expires in and Last updated are all empty, and Next update is for all anchors «any moment» - this didn't change even though I left if overnight. I cleared out the workdir/datadir, so it's starting from a clean slate. As you can see from the log messages below, it does encounter some DbMigrate error which is the only thing that seems wrong to me.

Both v2.23 and v2.24 suffers from the issue; the last working version was v2.22.

2018-02-22 12:27:37,402 INFO    [main] Main$ Starting up the RPKI validator...
2018-02-22 12:27:38,273 INFO    [main] Main Prefer RRDP=false
2018-02-22 12:27:38,340 INFO    [main] PersistentDataSerialiser$ Config file does not exist: File '/var/lib/rpki-validator/data.json' does not exist
2018-02-22 12:27:38,449 INFO    [main] TrustAnchors$ Loading trust anchors...
2018-02-22 12:27:38,600 INFO    [main] RTRServer RTR server listening on 0.0.0.0/0.0.0.0:8282
2018-02-22 12:27:38,626 INFO    [main] log Logging initialized @2190ms
2018-02-22 12:27:38,856 INFO    [main] Server jetty-9.2.17.v20160517
2018-02-22 12:27:38,933 INFO    [main] ContextHandler Started o.e.j.s.ServletContextHandler@620b8972{/,jar:file:/opt/rpki-validator-app-2.24/lib/rpki-validator-app-2.24.jar!/public,AVAILABLE}
2018-02-22 12:27:38,936 INFO    [main] AbstractNCSARequestLog Opened /var/log/rpki-validator/access.log
2018-02-22 12:27:38,945 INFO    [main] ServerConnector Started ServerConnector@5534578f{HTTP/1.1}{0.0.0.0:8080}
2018-02-22 12:27:38,946 INFO    [main] Server Started @2511ms
2018-02-22 12:27:38,947 INFO    [main] Main Welcome to the RIPE NCC RPKI Validator, now available on port 8080. Hit CTRL+C to terminate.
2018-02-22 12:27:39,571 INFO    [New I/O server boss #1 ([id: 0x693e9ac0, /0:0:0:0:0:0:0:0:8282])] RTRServerHandler Client connected : /0:0:0:0:0:0:0:1:34268
2018-02-22 12:27:39,607 INFO    [New I/O server worker #1-1] RTRServerHandler Client disconnected : /0:0:0:0:0:0:0:1:34268
2018-02-22 12:27:39,616 WARN    [default-akka.actor.default-dispatcher-4] LoggingOutputStream Feb 22, 2018 12:27:39 PM org.springframework.jdbc.datasource.DriverManagerDataSource setDriverClassName
INFO: Loaded JDBC driver: org.apache.derby.jdbc.EmbeddedDriver

2018-02-22 12:27:43,432 INFO    [default-akka.actor.default-dispatcher-4] MetaDataTableImpl Creating Metadata table: "APP"."schema_version"
2018-02-22 12:27:44,848 INFO    [default-akka.actor.default-dispatcher-2] BgpRisDumpDownloader Retrieved 68029 entries from http://www.ris.ripe.net/dumps/riswhoisdump.IPv6.gz, last modified at 2018-02-22T11:06:03.000+01:00
2018-02-22 12:27:44,922 INFO    [default-akka.actor.default-dispatcher-4] DbMigrate Current version of schema "APP": << Empty Schema >>
2018-02-22 12:27:44,923 INFO    [default-akka.actor.default-dispatcher-4] DbMigrate Migrating schema "APP" to version 1
2018-02-22 12:27:44,984 ERROR   [default-akka.actor.default-dispatcher-4] DbMigrate Migration of schema "APP" to version 1 failed! Changes successfully rolled back.
2018-02-22 12:27:45,387 INFO    [default-akka.actor.default-dispatcher-2] BgpRisDump$ toAnnouncedRoutes time 0.531 seconds
2018-02-22 12:27:46,616 INFO    [default-akka.actor.default-dispatcher-3] BgpRisDumpDownloader Retrieved 846784 entries from http://www.ris.ripe.net/dumps/riswhoisdump.IPv4.gz, last modified at 2018-02-22T11:03:16.000+01:00
2018-02-22 12:27:47,550 INFO    [default-akka.actor.default-dispatcher-3] BgpRisDump$ toAnnouncedRoutes time 0.933 seconds
2018-02-22 12:27:47,582 INFO    [default-akka.actor.default-dispatcher-3] BgpAnnouncementValidator Started validating 778573 BGP announcements with 0 RTR prefixes.
2018-02-22 12:27:48,949 INFO    [default-akka.actor.default-dispatcher-3] BgpAnnouncementValidator Completed validating 778573 BGP announcements with 0 RTR prefixes in 1.342 seconds
2018-02-22 12:27:55,224 INFO    [New I/O server boss #1 ([id: 0x693e9ac0, /0:0:0:0:0:0:0:0:8282])] RTRServerHandler Client connected : [snip]
2018-02-22 12:27:55,291 INFO    [New I/O server boss #1 ([id: 0x693e9ac0, /0:0:0:0:0:0:0:0:8282])] RTRServerHandler Client connected : [snip]
2018-02-22 12:27:55,387 INFO    [New I/O server boss #1 ([id: 0x693e9ac0, /0:0:0:0:0:0:0:0:8282])] RTRServerHandler Client connected : [snip]
timbru commented 6 years ago

Hi,

Cleaning out the workdir (./tmp by default) should fix any migration issues for the embedded database; migration works when I do a clean install. Are you sure the process has write access and there is space on the filesystem?

Thanks Tim

toreanderson commented 6 years ago

I have the following:

locations.workdir=/var/lib/rpki-validator/tmp
locations.datadir=/var/lib/rpki-validator
locations.rsyncdir=/var/lib/rpki-validator/rsync

When I start it up on a clean install, locations.datadir exists and is writable by the user the validator runs as (but empty). The tmp subdir is automatically created after I start it, but I still get the DbMigrate error.

By the way, I've found out that if I start up v2.22 from a clean slate and let it do the DbMigrate stuff successfully, I can then upgrade to v2.24 as long as I leave the contents of the data dirs intact.

toreanderson commented 6 years ago

I did a little bit more testing, and found that it fails even if I run it in my home directory with everything at defaults. Just untar and then ./rpki-validator.sh run. However I saw now that there's an error being spat out to stdout as well (previously I just checked validator.log):

tore@rpki-validator:~/rpki-validator-app-2.24$ ./rpki-validator.sh run
[ warn ] JAVA_HOME is not set, will try to find java on path.
[ info ] Starting rpki-validator...
[ info ] writing logs under log directory
[ info ] Web user interface is available on port 8080
[ info ] Routers can connect on port 8282
[ERROR] [02/28/2018 08:59:18.574] [default-akka.actor.default-dispatcher-5] [TaskInvocation] Error executing statement at line 5: CALL DROP_TABLE_IF_EXISTS('RETRIEVED_OBJECTS')
com.googlecode.flyway.core.command.FlywaySqlScriptException: Error executing statement at line 5: CALL DROP_TABLE_IF_EXISTS('RETRIEVED_OBJECTS')
        at com.googlecode.flyway.core.dbsupport.SqlScript.execute(SqlScript.java:92)
        at com.googlecode.flyway.core.resolver.sql.SqlMigrationExecutor.execute(SqlMigrationExecutor.java:72)
        at com.googlecode.flyway.core.command.DbMigrate$2.doInTransaction(DbMigrate.java:243)
        at com.googlecode.flyway.core.command.DbMigrate$2.doInTransaction(DbMigrate.java:241)
        at com.googlecode.flyway.core.util.jdbc.TransactionTemplate.execute(TransactionTemplate.java:72)
        at com.googlecode.flyway.core.command.DbMigrate.applyMigration(DbMigrate.java:241)
        at com.googlecode.flyway.core.command.DbMigrate.access$700(DbMigrate.java:44)
        at com.googlecode.flyway.core.command.DbMigrate$1.doInTransaction(DbMigrate.java:186)
        at com.googlecode.flyway.core.command.DbMigrate$1.doInTransaction(DbMigrate.java:135)
        at com.googlecode.flyway.core.util.jdbc.TransactionTemplate.execute(TransactionTemplate.java:72)
        at com.googlecode.flyway.core.command.DbMigrate.migrate(DbMigrate.java:135)
        at com.googlecode.flyway.core.Flyway$1.execute(Flyway.java:872)
        at com.googlecode.flyway.core.Flyway$1.execute(Flyway.java:819)
        at com.googlecode.flyway.core.Flyway.execute(Flyway.java:1200)
        at com.googlecode.flyway.core.Flyway.migrate(Flyway.java:819)
        at net.ripe.rpki.validator.store.DataSources$.net$ripe$rpki$validator$store$DataSources$$migrate(DataSources.scala:87)
        at net.ripe.rpki.validator.store.DataSources$DSSingletons$$anonfun$$init$$1.apply(DataSources.scala:47)
        at net.ripe.rpki.validator.store.DataSources$DSSingletons$$anonfun$$init$$1.apply(DataSources.scala:43)
        at net.ripe.rpki.validator.store.SimpleSingletons.apply(Storage.scala:80)
        at net.ripe.rpki.validator.store.DataSources$.DurableDataSource(DataSources.scala:54)
        at net.ripe.rpki.validator.store.DurableCaches$$anonfun$$init$$1.apply(CacheStore.scala:229)
        at net.ripe.rpki.validator.store.DurableCaches$$anonfun$$init$$1.apply(CacheStore.scala:228)
        at net.ripe.rpki.validator.store.SimpleSingletons.apply(Storage.scala:80)
        at net.ripe.rpki.validator.store.DurableCaches$.apply(CacheStore.scala:231)
        at net.ripe.rpki.validator.config.Main.net$ripe$rpki$validator$config$Main$$runValidator(Main.scala:171)
        at net.ripe.rpki.validator.config.Main.net$ripe$rpki$validator$config$Main$$runValidator(Main.scala:162)
        at net.ripe.rpki.validator.config.Main$$anonfun$1.apply$mcV$sp(Main.scala:135)
        at akka.actor.DefaultScheduler$$anon$4.run(Scheduler.scala:161)
        at akka.actor.DefaultScheduler$$anon$2$$anon$5.run(Scheduler.scala:172)
        at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:137)
        at akka.dispatch.ForkJoinExecutorConfigurator$MailboxExecutionTask.exec(AbstractDispatcher.scala:506)
        at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
        at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
        at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
        at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)
Caused by: java.sql.SQLSyntaxErrorException: The class 'net.ripe.rpki.validator.StoredProcedures' does not exist or is inaccessible. This can happen if the class is not public.
        at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
        at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
        at org.apache.derby.impl.jdbc.Util.seeNextException(Unknown Source)
        at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(Unknown Source)
        at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(Unknown Source)
        at org.apache.derby.impl.jdbc.EmbedConnection.handleException(Unknown Source)
        at org.apache.derby.impl.jdbc.ConnectionChild.handleException(Unknown Source)
        at org.apache.derby.impl.jdbc.EmbedStatement.execute(Unknown Source)
        at org.apache.derby.impl.jdbc.EmbedStatement.execute(Unknown Source)
        at com.googlecode.flyway.core.dbsupport.JdbcTemplate.executeStatement(JdbcTemplate.java:230)
        at com.googlecode.flyway.core.dbsupport.SqlScript.execute(SqlScript.java:90)
        ... 34 more
Caused by: ERROR 42X51: The class 'net.ripe.rpki.validator.StoredProcedures' does not exist or is inaccessible. This can happen if the class is not public.
        at org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
        at org.apache.derby.impl.jdbc.SQLExceptionFactory.wrapArgsForTransportAcrossDRDA(Unknown Source)
        ... 45 more
Caused by: java.lang.ClassNotFoundException: net.ripe.rpki.validator.StoredProcedures : net/ripe/rpki/validator/StoredProcedures : Unsupported major.minor version 52.0
        at org.apache.derby.impl.services.reflect.DatabaseClasses.loadApplicationClass(Unknown Source)
        at org.apache.derby.iapi.services.loader.ClassInspector.getClass(Unknown Source)
        at org.apache.derby.iapi.services.loader.ClassInspector.accessible(Unknown Source)
        at org.apache.derby.impl.sql.compile.QueryTreeNode.verifyClassExist(Unknown Source)
        at org.apache.derby.impl.sql.compile.StaticMethodCallNode.bindExpressionMinion(Unknown Source)
        at org.apache.derby.impl.sql.compile.StaticMethodCallNode.bindExpression(Unknown Source)
        at org.apache.derby.impl.sql.compile.JavaToSQLValueNode.bindExpression(Unknown Source)
        at org.apache.derby.impl.sql.compile.CallStatementNode.bindStatement(Unknown Source)
        at org.apache.derby.impl.sql.GenericStatement.prepMinion(Unknown Source)
        at org.apache.derby.impl.sql.GenericStatement.prepare(Unknown Source)
        at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(Unknown Source)
        ... 38 more

Same thing happens with v2.23, but not with v2.22.

For the record, I'm running Ubuntu 14.04.5 LTS with openjdk-7-jre-headless:amd64 version 7u151-2.6.11-2ubuntu0.14.04.1.

omuravskiy commented 6 years ago

Hi Tore,

I looks this version requires java8 to run, despite readme file saying it "should" work with java7.

Could you give it a try with java8?

Otherwise I could try to compile a version that does not require java8.

Cheers, Oleg

toreanderson commented 6 years ago

Seems I'll need to upgrade to Ubuntu Xenial to get java8 (and java9), and I don't have time to do that right now. That said, v2.24 is running fine on Trusty with java7 for me right now, it's just provisioning it from scratch on that platform that doesn't work any more. So it's not high priority for me in any way. If you want to deal with this by simply amending the readme/release notes to point out java8 is now required, that's fine by me.

omuravskiy commented 6 years ago

If you're not against using non-official PPAs, you could install java8 as described here: http://tecadmin.net/install-oracle-java-8-ubuntu-via-ppa

Alternatively you could grab JDK as a tarball from here: http://www.oracle.com/technetwork/java/javase/downloads/index.html, unpack it and point JAVA_HOME at it before starting the validator.

toreanderson commented 6 years ago

I just tested with Docker. Seems to work fine on Ubuntu Xenial with Java 8:

[root@sloth ~]# docker run -it -p 8080:8080 ubuntu:xenial
root@5885c5f5ccd5:/# (apt-get update && apt-get -y install openjdk-8-jre-headless curl rsync) &> /dev/null
root@5885c5f5ccd5:/# curl -s https://lirportal.ripe.net/certification/content/static/validator/rpki-validator-app-2.24-dist.tar.gz | tar zx
root@5885c5f5ccd5:/# cd rpki-validator-app-2.24; ./rpki-validator.sh run
[ warn ] JAVA_HOME is not set, will try to find java on path.
[ info ] Starting rpki-validator...
[ info ] writing logs under log directory
[ info ] Web user interface is available on port 8080
[ info ] Routers can connect on port 8282

...and looking at http://localhost:8080 all seems to be working just fine.

This in contrast to the behaviour on Ubuntu Trusty with Java 7:

[root@sloth ~]# docker run -it -p 8080:8080 ubuntu:trusty
root@c4461f0c4373:/# (apt-get update && apt-get -y install openjdk-7-jre-headless curl rsync) &> /dev/null
root@c4461f0c4373:/# curl -s https://lirportal.ripe.net/certification/content/static/validator/rpki-validator-app-2.24-dist.tar.gz | tar zx
root@c4461f0c4373:/# cd rpki-validator-app-2.24; ./rpki-validator.sh run
[ warn ] JAVA_HOME is not set, will try to find java on path.
[ info ] Starting rpki-validator...
[ info ] writing logs under log directory
[ info ] Web user interface is available on port 8080
[ info ] Routers can connect on port 8282
[ERROR] [02/28/2018 16:46:42.671] [default-akka.actor.default-dispatcher-3] [TaskInvocation] Error executing statement at line 5: CALL DROP_TABLE_IF_EXISTS('RETRIEVED_OBJECTS')
com.googlecode.flyway.core.command.FlywaySqlScriptException: Error executing statement at line 5: CALL DROP_TABLE_IF_EXISTS('RETRIEVED_OBJECTS')
        at com.googlecode.flyway.core.dbsupport.SqlScript.execute(SqlScript.java:92)
        at com.googlecode.flyway.core.resolver.sql.SqlMigrationExecutor.execute(SqlMigrationExecutor.java:72)
        at com.googlecode.flyway.core.command.DbMigrate$2.doInTransaction(DbMigrate.java:243)
        at com.googlecode.flyway.core.command.DbMigrate$2.doInTransaction(DbMigrate.java:241)
        at com.googlecode.flyway.core.util.jdbc.TransactionTemplate.execute(TransactionTemplate.java:72)
        at com.googlecode.flyway.core.command.DbMigrate.applyMigration(DbMigrate.java:241)
        at com.googlecode.flyway.core.command.DbMigrate.access$700(DbMigrate.java:44)
        at com.googlecode.flyway.core.command.DbMigrate$1.doInTransaction(DbMigrate.java:186)
        at com.googlecode.flyway.core.command.DbMigrate$1.doInTransaction(DbMigrate.java:135)
        at com.googlecode.flyway.core.util.jdbc.TransactionTemplate.execute(TransactionTemplate.java:72)
        at com.googlecode.flyway.core.command.DbMigrate.migrate(DbMigrate.java:135)
        at com.googlecode.flyway.core.Flyway$1.execute(Flyway.java:872)
        at com.googlecode.flyway.core.Flyway$1.execute(Flyway.java:819)
        at com.googlecode.flyway.core.Flyway.execute(Flyway.java:1200)
        at com.googlecode.flyway.core.Flyway.migrate(Flyway.java:819)
        at net.ripe.rpki.validator.store.DataSources$.net$ripe$rpki$validator$store$DataSources$$migrate(DataSources.scala:87)
        at net.ripe.rpki.validator.store.DataSources$DSSingletons$$anonfun$$init$$1.apply(DataSources.scala:47)
        at net.ripe.rpki.validator.store.DataSources$DSSingletons$$anonfun$$init$$1.apply(DataSources.scala:43)
        at net.ripe.rpki.validator.store.SimpleSingletons.apply(Storage.scala:80)
        at net.ripe.rpki.validator.store.DataSources$.DurableDataSource(DataSources.scala:54)
        at net.ripe.rpki.validator.store.DurableCaches$$anonfun$$init$$1.apply(CacheStore.scala:229)
        at net.ripe.rpki.validator.store.DurableCaches$$anonfun$$init$$1.apply(CacheStore.scala:228)
        at net.ripe.rpki.validator.store.SimpleSingletons.apply(Storage.scala:80)
        at net.ripe.rpki.validator.store.DurableCaches$.apply(CacheStore.scala:231)
        at net.ripe.rpki.validator.config.Main.net$ripe$rpki$validator$config$Main$$runValidator(Main.scala:171)
        at net.ripe.rpki.validator.config.Main.net$ripe$rpki$validator$config$Main$$runValidator(Main.scala:162)
        at net.ripe.rpki.validator.config.Main$$anonfun$1.apply$mcV$sp(Main.scala:135)
        at akka.actor.DefaultScheduler$$anon$4.run(Scheduler.scala:161)
        at akka.actor.DefaultScheduler$$anon$2$$anon$5.run(Scheduler.scala:172)
        at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:137)
        at akka.dispatch.ForkJoinExecutorConfigurator$MailboxExecutionTask.exec(AbstractDispatcher.scala:506)
        at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
        at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
        at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
        at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)
Caused by: java.sql.SQLSyntaxErrorException: The class 'net.ripe.rpki.validator.StoredProcedures' does not exist or is inaccessible. This can happen if the class is not public.
        at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
        at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
        at org.apache.derby.impl.jdbc.Util.seeNextException(Unknown Source)
        at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(Unknown Source)
        at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(Unknown Source)
        at org.apache.derby.impl.jdbc.EmbedConnection.handleException(Unknown Source)
        at org.apache.derby.impl.jdbc.ConnectionChild.handleException(Unknown Source)
        at org.apache.derby.impl.jdbc.EmbedStatement.execute(Unknown Source)
        at org.apache.derby.impl.jdbc.EmbedStatement.execute(Unknown Source)
        at com.googlecode.flyway.core.dbsupport.JdbcTemplate.executeStatement(JdbcTemplate.java:230)
        at com.googlecode.flyway.core.dbsupport.SqlScript.execute(SqlScript.java:90)
        ... 34 more
Caused by: ERROR 42X51: The class 'net.ripe.rpki.validator.StoredProcedures' does not exist or is inaccessible. This can happen if the class is not public.
        at org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
        at org.apache.derby.impl.jdbc.SQLExceptionFactory.wrapArgsForTransportAcrossDRDA(Unknown Source)
        ... 45 more
Caused by: java.lang.ClassNotFoundException: net.ripe.rpki.validator.StoredProcedures : net/ripe/rpki/validator/StoredProcedures : Unsupported major.minor version 52.0
        at org.apache.derby.impl.services.reflect.DatabaseClasses.loadApplicationClass(Unknown Source)
        at org.apache.derby.iapi.services.loader.ClassInspector.getClass(Unknown Source)
        at org.apache.derby.iapi.services.loader.ClassInspector.accessible(Unknown Source)
        at org.apache.derby.impl.sql.compile.QueryTreeNode.verifyClassExist(Unknown Source)
        at org.apache.derby.impl.sql.compile.StaticMethodCallNode.bindExpressionMinion(Unknown Source)
        at org.apache.derby.impl.sql.compile.StaticMethodCallNode.bindExpression(Unknown Source)
        at org.apache.derby.impl.sql.compile.JavaToSQLValueNode.bindExpression(Unknown Source)
        at org.apache.derby.impl.sql.compile.CallStatementNode.bindStatement(Unknown Source)
        at org.apache.derby.impl.sql.GenericStatement.prepMinion(Unknown Source)
        at org.apache.derby.impl.sql.GenericStatement.prepare(Unknown Source)
        at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(Unknown Source)
        ... 38 more
timbru commented 6 years ago

Hi Tore,

Apologies, I did not see immediately that this is a java version issue. That said, I would like to close this issue for now since things do work with Java 8.