search

ibi-group / datatools-server

Server for IBI's GTFS data management platform.
MIT License
49 stars 52 forks source link

Mongo error? #231

Closed gelinger777 closed 4 years ago

gelinger777 commented 5 years ago

Observed behavior

After I have quite successfully installed the Server and the UI inside the VPS (Ubuntu) and logged in as a first admin user I cannot manage to add a project and manage routes etc etc

So when I login as an admin /admin/users and click on admin I see following

image

In the server terminal I see following error

Sep 12 15:46:24.585 [qtp1257822399-20] INFO c.c.d.manager.auth.Auth0Users:89 - Auth0 getUsers URL=https://opentransportam.eu.auth0.com/api/v2/users?sort=email%3A1&per_page=10&page=0&include_totals=false&search_engine=v3&q=app_metadata.datatools.client_id%3ADhb3mglqke6wCoB9tVhDJfqCsWmGmr3X Sep 12 15:46:24.600 [qtp1257822399-18] ERROR c.c.datatools.manager.DataManager:246 - error org.bson.codecs.configuration.CodecConfigurationException: Failed to decode 'subscriptionBeginDate'. readDateTime can only be called when CurrentBSONType is DATE_TIME, not when CurrentBSONType is INT64. at org.bson.codecs.pojo.PojoCodecImpl.decodePropertyModel(PojoCodecImpl.java:171) at org.bson.codecs.pojo.PojoCodecImpl.decodeProperties(PojoCodecImpl.java:149) at org.bson.codecs.pojo.PojoCodecImpl.decode(PojoCodecImpl.java:103) at org.bson.codecs.pojo.PojoCodecImpl.decode(PojoCodecImpl.java:107) at com.mongodb.operation.CommandResultArrayCodec.decode(CommandResultArrayCodec.java:52) at com.mongodb.operation.CommandResultDocumentCodec.readValue(CommandResultDocumentCodec.java:60) at org.bson.codecs.BsonDocumentCodec.decode(BsonDocumentCodec.java:84) at org.bson.codecs.BsonDocumentCodec.decode(BsonDocumentCodec.java:41) at org.bson.codecs.configuration.LazyCodec.decode(LazyCodec.java:47) at org.bson.codecs.BsonDocumentCodec.readValue(BsonDocumentCodec.java:101) at com.mongodb.operation.CommandResultDocumentCodec.readValue(CommandResultDocumentCodec.java:63) at org.bson.codecs.BsonDocumentCodec.decode(BsonDocumentCodec.java:84) at org.bson.codecs.BsonDocumentCodec.decode(BsonDocumentCodec.java:41) at com.mongodb.connection.ReplyMessage.(ReplyMessage.java:50) at com.mongodb.connection.CommandProtocol.getResponseDocument(CommandProtocol.java:132) at com.mongodb.connection.CommandProtocol.execute(CommandProtocol.java:111) at com.mongodb.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:159) at com.mongodb.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:289) at com.mongodb.connection.DefaultServerConnection.command(DefaultServerConnection.java:176) at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:216) at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:207) at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:113) at com.mongodb.operation.FindOperation$1.call(FindOperation.java:715) at com.mongodb.operation.FindOperation$1.call(FindOperation.java:709) at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:433) at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:406) at com.mongodb.operation.FindOperation.execute(FindOperation.java:709) at com.mongodb.operation.FindOperation.execute(FindOperation.java:81) at com.mongodb.Mongo.execute(Mongo.java:810) at com.mongodb.Mongo$2.execute(Mongo.java:797) at com.mongodb.OperationIterable.iterator(OperationIterable.java:47) at com.mongodb.OperationIterable.forEach(OperationIterable.java:70) at com.mongodb.OperationIterable.into(OperationIterable.java:82) at com.mongodb.FindIterableImpl.into(FindIterableImpl.java:220) at com.conveyal.datatools.manager.persistence.TypedPersistence.getAll(TypedPersistence.java:135) at com.conveyal.datatools.manager.controllers.api.OrganizationController.getAllOrganizations(OrganizationController.java:45) at spark.ResponseTransformerRouteImpl$1.handle(ResponseTransformerRouteImpl.java:47) at spark.http.matching.Routes.execute(Routes.java:61) at spark.http.matching.MatcherFilter.doFilter(MatcherFilter.java:130) at spark.embeddedserver.jetty.JettyHandler.doHandle(JettyHandler.java:50) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1568) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) at org.eclipse.jetty.server.Server.handle(Server.java:530) at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:347) at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:256) at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279) at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102) at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:247) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:140) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:382) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:708) at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:626) at java.lang.Thread.run(Thread.java:748) Caused by: org.bson.BsonInvalidOperationException: readDateTime can only be called when CurrentBSONType is DATE_TIME, not when CurrentBSONType is INT64. at org.bson.AbstractBsonReader.verifyBSONType(AbstractBsonReader.java:692) at org.bson.AbstractBsonReader.checkPreconditions(AbstractBsonReader.java:724) at org.bson.AbstractBsonReader.readDateTime(AbstractBsonReader.java:312) at org.bson.codecs.DateCodec.decode(DateCodec.java:37) at org.bson.codecs.DateCodec.decode(DateCodec.java:29) at org.bson.codecs.DecoderContext.decodeWithChildContext(DecoderContext.java:93) at org.bson.codecs.pojo.PojoCodecImpl.decodePropertyModel(PojoCodecImpl.java:165) ... 55 common frames omitted Sep 12 15:46:24.606 [qtp1257822399-18] INFO spark.http.matching.MatcherFilter:162 - The requested route [/api/manager/secure/organization] has not been mapped in Spark for Accept: [application/json] Sep 12 15:46:24.660 [qtp1257822399-16] INFO c.c.d.manager.auth.Auth0Users:153 - Getting new Auth0 API access token (cached token does not exist or has expired). Sep 12 15:46:24.660 [qtp1257822399-20] INFO c.c.d.manager.auth.Auth0Users:153 - Getting new Auth0 API access token (cached token does not exist or has expired). log4j:WARN No appenders could be found for logger (org.apache.http.client.protocol.RequestAddCookies). log4j:WARN No appenders could be found for logger (org.apache.http.client.protocol.RequestAddCookies). log4j:WARN Please initialize the log4j system properly. log4j:WARN Please initialize the log4j system properly.

In Chrome Console we have folloing errors

VM46:1 GET https://mydomainhere/api/manager/secure/organization 404

In Network console the call returns

404 Not found

I Suspect that the reson can be that orgnisation have in MongoDB GTFS collection

subscriptionBeginDate: 1568239200000 subscriptionEndDate: 1599948000000

values and its set as schema type long, but in Java probably you want to treat is at datetime?

n: Failed to decode 'subscriptionBeginDate'. readDateTime can only be called when CurrentBSONType is DATE_TIME, not when CurrentBSONType is INT64. this line in server log ....

Expected behavior

I should be able to manage the User->Company->Project bundle to be able to start creating GTFS feeds

Steps to reproduce the problem

Here is my output of starting the ui server

java -jar target/dt-v3.2.0-540-gaa0a0d7.jar configurations/default/env.yml configurations/default/server.yml 15:37:14,708 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml] 15:37:14,708 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy] 15:37:14,708 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [jar:file:/root/datatools-server/target/dt-v3.2.0-540-gaa0a0d7.jar!/logback.xml] 15:37:14,722 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@3ada9e37 - URL [jar:file:/root/datatools-server/target/dt-v3.2.0-540-gaa0a0d7.jar!/logback.xml] is not of type file 15:37:14,783 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set 15:37:14,784 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender] 15:37:14,793 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT] 15:37:14,848 |-WARN in ch.qos.logback.core.ConsoleAppender[STDOUT] - This appender no longer admits a layout as a sub-component, set an encoder instead. 15:37:14,848 |-WARN in ch.qos.logback.core.ConsoleAppender[STDOUT] - To ensure compatibility, wrapping your layout in LayoutWrappingEncoder. 15:37:14,848 |-WARN in ch.qos.logback.core.ConsoleAppender[STDOUT] - See also http://logback.qos.ch/codes.html#layoutInsteadOfEncoder for details 15:37:14,849 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO 15:37:14,849 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT] 15:37:14,850 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration. 15:37:14,851 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@5cbc508c - Registering current configuration as safe fallback point

Sep 12 15:37:15.044 [main] INFO c.c.datatools.manager.DataManager:468 - Loading env.yml: configurations/default/env.yml Sep 12 15:37:15.049 [main] INFO c.c.datatools.manager.DataManager:469 - Loading server.yml: configurations/default/server.yml Sep 12 15:37:15.124 [main] WARN c.c.datatools.manager.DataManager:408 - Config property BUGSNAG_KEY not found Sep 12 15:37:15.125 [main] INFO c.c.datatools.manager.DataManager:136 - FeedStore Sep 12 15:37:15.568 [main] INFO c.c.d.m.persistence.Persistence:80 - Connecting to local MongoDB instance Sep 12 15:37:15.598 [main] INFO org.mongodb.driver.cluster:71 - Cluster created with settings {hosts=[localhost:27017], mode=SINGLE, requiredClusterType=UNKNOWN, serverSelectionTimeout='30000 ms', maxWaitQueueSize=500} Sep 12 15:37:15.673 [main] INFO c.c.datatools.common.utils.Scheduler:55 - Scheduling recurring project auto fetches Sep 12 15:37:15.689 [cluster-ClusterId{value='5d7a4a0bf0ded321656a748d', description='null'}-localhost:27017] INFO org.mongodb.driver.connection:71 - Opened connection [connectionId{localValue:1, serverValue:5}] to localhost:27017 Sep 12 15:37:15.692 [cluster-ClusterId{value='5d7a4a0bf0ded321656a748d', description='null'}-localhost:27017] INFO org.mongodb.driver.cluster:71 - Monitor thread successfully connected to server with description ServerDescription{address=localhost:27017, type=STANDALONE, state=CONNECTED, ok=true, version=ServerVersion{versionList=[4, 2, 0]}, minWireVersion=0, maxWireVersion=8, maxDocumentSize=16777216, roundTripTimeNanos=927143} Sep 12 15:37:15.737 [main] INFO org.mongodb.driver.connection:71 - Opened connection [connectionId{localValue:2, serverValue:6}] to localhost:27017 Sep 12 15:37:15.752 [main] INFO c.c.datatools.common.utils.Scheduler:61 - Scheduling feed expiration notifications Sep 12 15:37:15.781 [main] INFO com.conveyal.gtfs.GraphQLController:98 - Initialized GTFS GraphQL API at localhost:port/api/manager/secure/gtfs/ Sep 12 15:37:15.805 [Thread-1] INFO org.eclipse.jetty.util.log:192 - Logging initialized @1265ms to org.eclipse.jetty.util.log.Slf4jLog Sep 12 15:37:15.872 [Thread-1] INFO s.e.jetty.EmbeddedJettyServer:142 - == Spark has ignited ... Sep 12 15:37:15.873 [Thread-1] INFO s.e.jetty.EmbeddedJettyServer:146 - >> Listening on 0.0.0.0:4000 Sep 12 15:37:15.876 [Thread-1] INFO org.eclipse.jetty.server.Server:373 - jetty-9.4.z-SNAPSHOT, build timestamp: 2017-11-21T22:27:37+01:00, git hash: 82b8fb23f757335bb3329d540ce37a2a2615f0a8 Sep 12 15:37:15.926 [Thread-1] INFO org.eclipse.jetty.server.session:364 - DefaultSessionIdManager workerName=node0 Sep 12 15:37:15.927 [Thread-1] INFO org.eclipse.jetty.server.session:369 - No SessionScavenger set, using defaults Sep 12 15:37:15.928 [Thread-1] INFO org.eclipse.jetty.server.session:149 - Scavenging every 660000ms Sep 12 15:37:15.947 [Thread-1] INFO o.e.jetty.server.AbstractConnector:288 - Started ServerConnector@6678982f{HTTP/1.1,[http/1.1]}{0.0.0.0:4000} Sep 12 15:37:15.951 [Thread-1] INFO org.eclipse.jetty.server.Server:410 - Started @1410ms Sep 12 15:37:16.215 [main] INFO c.c.d.e.c.api.EditorController:65 - Registering editor routes for /api/editor/secure/agency Sep 12 15:37:16.219 [main] INFO c.c.d.e.c.api.EditorController:65 - Registering editor routes for /api/editor/secure/calendar Sep 12 15:37:16.220 [main] INFO c.c.d.e.c.api.EditorController:65 - Registering editor routes for /api/editor/secure/fareattribute Sep 12 15:37:16.221 [main] INFO c.c.d.e.c.api.EditorController:65 - Registering editor routes for /api/editor/secure/feedinfo Sep 12 15:37:16.221 [main] INFO c.c.d.e.c.api.EditorController:65 - Registering editor routes for /api/editor/secure/route Sep 12 15:37:16.222 [main] INFO c.c.d.e.c.api.EditorController:65 - Registering editor routes for /api/editor/secure/pattern Sep 12 15:37:16.223 [main] INFO c.c.d.e.c.api.EditorController:65 - Registering editor routes for /api/editor/secure/scheduleexception Sep 12 15:37:16.224 [main] INFO c.c.d.e.c.api.EditorController:65 - Registering editor routes for /api/editor/secure/stop Sep 12 15:37:16.224 [main] INFO c.c.d.e.c.api.EditorController:65 - Registering editor routes for /api/editor/secure/trip Sep 12 15:37:16.235 [main] WARN c.c.datatools.manager.DataManager:392 - Config property application.data.s3_credentials_file not found Sep 12 15:37:16.235 [main] WARN c.c.datatools.manager.DataManager:408 - Config property application.data.s3_credentials_file not found Sep 12 15:37:16.235 [main] WARN c.c.datatools.manager.DataManager:392 - Config property application.data.s3_credentials_file not found Sep 12 15:37:16.235 [main] WARN c.c.datatools.manager.DataManager:408 - Config property application.data.s3_credentials_file not found Sep 12 15:37:16.303 [main] WARN c.c.d.m.controllers.DumpController:383 - registered dump w/ prefix / Sep 12 15:37:16.311 [main] INFO c.c.datatools.manager.DataManager:438 - Registering MTC Resource Sep 12 15:37:16.313 [main] INFO c.c.datatools.manager.DataManager:443 - Registering TransitLand Resource Sep 12 15:37:16.314 [main] INFO c.c.datatools.manager.DataManager:448 - Registering TransitFeeds Resource Sep 12 15:37:16.315 [main] WARN c.c.datatools.manager.DataManager:408 - Config property TRANSITFEEDS_KEY not found

Here is the output of UI Start

yarn start yarn run v1.17.3 $ yarn [1/4] Resolving packages... success Already up-to-date. $ mastarm build --env production --minify --serve --proxy http://localhost:4000/api [0002] info Server running at http://127.0.0.1:9966/ (connect) updated dist/index.css updated dist/index.css [0048] 46.4s 25MB (browserify)

Any special notes on configuration used

Please describe any applicable config files that were used

Version of datatools-server and datatools-ui if applicable (exact commit hash or branch name)

UI -> 4af00b7c ->dev Server -> aa0a0d7 -> dev

MongoDB Version

root@opentransport:~/datatools-ui# mongod -v 2019-09-12T15:58:07.580+0200 I CONTROL [main] Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none' 2019-09-12T15:58:07.582+0200 D1 NETWORK [main] fd limit hard:1048576 soft:1024 max conn: 819 2019-09-12T15:58:07.582+0200 I CONTROL [initandlisten] MongoDB starting : pid=9524 port=27017 dbpath=/data/db 64-bit host=opentransport 2019-09-12T15:58:07.582+0200 I CONTROL [initandlisten] db version v4.2.0 2019-09-12T15:58:07.582+0200 I CONTROL [initandlisten] git version: a4b751dcf51dd249c5865812b390cfd1c0129c30 2019-09-12T15:58:07.582+0200 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.1.1 11 Sep 2018 2019-09-12T15:58:07.582+0200 I CONTROL [initandlisten] allocator: tcmalloc 2019-09-12T15:58:07.582+0200 I CONTROL [initandlisten] modules: none 2019-09-12T15:58:07.582+0200 I CONTROL [initandlisten] build environment: 2019-09-12T15:58:07.582+0200 I CONTROL [initandlisten] distmod: ubuntu1804 2019-09-12T15:58:07.582+0200 I CONTROL [initandlisten] distarch: x86_64 2019-09-12T15:58:07.582+0200 I CONTROL [initandlisten] target_arch: x86_64 2019-09-12T15:58:07.582+0200 I CONTROL [initandlisten] options: { systemLog: { verbosity: 1 } } 2019-09-12T15:58:07.582+0200 D1 NETWORK [initandlisten] fd limit hard:1048576 soft:1024 max conn: 819 2019-09-12T15:58:07.582+0200 E STORAGE [initandlisten] Failed to set up listener: SocketException: Address already in use 2019-09-12T15:58:07.583+0200 D1 - [initandlisten] User Assertion: NotMaster: not primary so can't step down src/mongo/db/repl/replication_coordinator_impl.cpp 1977 2019-09-12T15:58:07.583+0200 I CONTROL [initandlisten] now exiting 2019-09-12T15:58:07.583+0200 I CONTROL [initandlisten] shutting down with code:48

server's server.yaml 

application:
  assets_bucket: bucket-name
  public_url: http://localhost:9966
  notifications_enabled: true
  cors:
    enabled: true
    origins: https://google.com
    methods:
    headers:
  port: 4000
  data:
    editor_mapdb: /var/www/gelinger/data/gtfs_db/editor/mapdb
    mapdb: /var/www/gelinger/data/gtfs_db/mapdb
    gtfs: /var/www/gelinger/data/gtfs_db/gtfs
    use_s3_storage: false
    s3_region: us-east-1
    gtfs_s3_bucket: bucket-name
modules:
  dump:
    enabled: true
  enterprise:
    enabled: false
  deployment:
    enabled: true
  editor:
    enabled: true
    url: http://localhost:9001
  alerts:
    enabled: true
    use_extension: mtc
    url: /alerts
  sign_config:
    enabled: true
    use_extension: mtc
    url: /signs # eventually remove this
  user_admin:
    enabled: true
  # Enable GTFS+ module for testing purposes
 gtfsplus:
    enabled: true
  gtfsapi:
    enabled: true
    load_on_fetch: false
    # use_extension: mtc
    # update_frequency: 30 # in seconds

extensions:
  mtc:
    enabled: true
    rtd_api: http://localhost:9876/
    s3_bucket: bucket-name
    s3_prefix: waiting/
    s3_download_prefix: waiting/
  transitland:
    enabled: true
    api: https://transit.land/api/v1/feeds
  transitfeeds:
    enabled: true
    api: http://api.transitfeeds.com/v1/getFeeds
gelinger777 commented 5 years ago

Another interesting string error string is

Sep 12 15:54:54.306 [qtp1257822399-28] INFO spark.http.matching.MatcherFilter:162 - The requested route [/api/manager/secure/organization] has not been mapped in Spark for Accept: [application/json]

gelinger777 commented 5 years ago

@landonreed any ideas how to solve this?