Adicitus / morrigan

Node-based server for websocket-based client management.
0 stars 0 forks source link

Log file cuts off before server is fully shut down #4

Open Adicitus opened 2 years ago

Adicitus commented 2 years ago

Log file ends when .onShutdown is called on components: morrigan-2022-10-12-17.log

Compare with console output:

PS C:\Projects\js-morrigan.providers.agent-pkg\server> npm run test

> @adicitus/morrigan.providers.agent@0.0.1 test
> mocha --exit

  morrigan.server.providers.agent
info: 'start' method called, but server is not in an initialized state. Attempting to initialize...
info: Setting up logging...
2022-10-12T15:11:29.488Z info    | Log dir (C:\Projects\js-morrigan.providers.agent-pkg\server\test/data/log) does not exist, trying to create it...
2022-10-12T15:11:29.504Z info    | Writing log files to 'C:\Projects\js-morrigan.providers.agent-pkg\server\test\data\log'. Log level is set to: 'silly'
2022-10-12T15:11:29.505Z info    | Finished setting up logging.
2022-10-12T15:11:29.506Z info    | Loading components...
2022-10-12T15:11:29.507Z info    | Registered component module '@adicitus/morrigan.components.core' as 'core'
2022-10-12T15:11:29.548Z info    | Registered component module '@adicitus/morrigan.components.authentication' as 'auth'
2022-10-12T15:11:29.549Z info    | Reading server state (looking in 'C:\Projects\js-morrigan.providers.agent-pkg\server\test/data/state')...
2022-10-12T15:11:29.597Z info    | Finished reading server state.
2022-10-12T15:11:29.597Z info    | Running Morrigan server version 0.9.5.
2022-10-12T15:11:29.598Z info    | Creating as HTTP server...
2022-10-12T15:11:29.599Z info    | Adding middleware from 'auth'...
2022-10-12T15:11:29.599Z info    | Starting server...
2022-10-12T15:11:29.600Z info    | Establish connection to MongoDB...
2022-10-12T15:11:29.768Z info    | MongoDB server connected.
2022-10-12T15:11:29.768Z info    | Using DB 'morrigan-server-test'.
2022-10-12T15:11:29.769Z info    | Settings up HTTP(S) listener...
2022-10-12T15:11:29.771Z info    | Listening on port 21034.
2022-10-12T15:11:29.772Z info    | API base URL: http://:::21034
2022-10-12T15:11:29.772Z info    | Setting up components...
2022-10-12T15:11:29.772Z info    | Starting setup of component 'core' (http://:::21034/api/core)
2022-10-12T15:11:29.773Z info    | Starting setup of component 'auth' (http://:::21034/api/auth)
{
  db: Db {
    _events: [Object: null prototype] {},
    _eventsCount: 0,
    _maxListeners: undefined,
    s: {
      dbCache: {},
      children: [],
      topology: [NativeTopology],
      options: [Object],
      logger: [Logger],
      bson: BSON {},
      readPreference: [ReadPreference],
      bufferMaxEntries: -1,
      parentDb: null,
      pkFactory: undefined,
      nativeParser: undefined,
      promiseLibrary: [Function: Promise],
      noListener: false,
      readConcern: undefined,
      writeConcern: undefined,
      namespace: [MongoDBNamespace]
    },
    serverConfig: [Getter],
    bufferMaxEntries: [Getter],
    databaseName: [Getter],
    [Symbol(kCapture)]: false
  },
  log: [Function (anonymous)],
  serverInfo: {
    version: '0.9.5',
    serverRoot: 'C:\\Projects\\js-morrigan.providers.agent-pkg\\server\\node_modules\\@adicitus\\morrigan.server',
    startTime: '2022-10-12T17:11:29.563+02:00',
    hostname: 'LILLDATORN3',
    firstRun: true,
    id: 'ad08fc0e-50e6-4f5d-88c0-129a9e567537',
    installTime: '2022-10-12T17:11:29.590+02:00',
    ips: [ '192.168.56.1', '192.168.1.97' ]
  },
  endpointUrl: 'http://:::21034/api/core',
  router: [Function: router] {
    params: {},
    _params: [],
    caseSensitive: undefined,
    mergeParams: undefined,
    strict: undefined,
    stack: [],
    _morrigan: { route: '/api/core' }
  },
  state: StateStore {
    getNamespace: [Function (anonymous)],
    set: [AsyncFunction (anonymous)],
    get: [AsyncFunction (anonymous)],
    remove: [AsyncFunction (anonymous)],
    getStore: [AsyncFunction: createStore]
  },
  security: [Function: security]
}
2022-10-12T15:11:29.785Z info    | Loading providers...
2022-10-12T15:11:29.785Z info    | Loading provider '@adicitus/morrigan.server.providers.connection'...
2022-10-12T15:11:29.793Z info    | Provider publishes a name, specification does not, using module name ('connection')
2022-10-12T15:11:29.795Z info    | Registering provider module '@adicitus/morrigan.server.providers.connection' v3.0.1 as 'connection'
2022-10-12T15:11:29.795Z info    | Loading provider '@adicitus/morrigan.server.providers.client'...
2022-10-12T15:11:29.803Z info    | Provider publishes a name, specification does not, using module name ('client')
2022-10-12T15:11:29.804Z info    | Registering provider module '@adicitus/morrigan.server.providers.client' v1.0.8 as 'client'
2022-10-12T15:11:29.804Z info    | Reading provider specification: {"name":"4177175ad970d","module":{"name":"agent","version":{"name":"@adicitus/morrigan.providers.agent","version":"0.0.1","description":"Providers for agents: non-interactive clients that can connect to the system and can be used to remotely manage a machine. This package provides endpoints to generate installation packages.","main":"index.js","scripts":{"test":"mocha --exit"},"repository":{"type":"git","url":"git+https://github.com/Adicitus/js-morrigan.providers.agent-pkg.git"},"keywords":["morrigan","agent"],"author":"Joakim Olsson <joakim.olsson@adicitus.cloud>","license":"ISC","bugs":{"url":"https://github.com/Adicitus/js-morrigan.providers.agent-pkg/issues"},"homepage":"https://github.com/Adicitus/js-morrigan.providers.agent-pkg#readme","dependencies":{"jwa":"^2.0.0","nanoid":"^4.0.0","tar":"^6.1.11","uuid":"^8.3.2","webpack":"^5.74.0"},"devDependencies":{"@adicitus/morrigan.server":"^0.9.3"}},"openapi":{},"endpoints":[{"route":"/download","method":"get","openapi":{}},{"route":"/installer","method":"post","openapi":{}},{"route":"/installer","method":"get","openapi":{}},{"route":"/installer/{iid}","method":"get","openapi":{}},{"route":"/installer/{iid}","method":"patch","openapi":{}},{"route":"/installer/{iid}","method":"delete","openapi":{}},{"route":"/key/support","method":"get","security":null,"openapi":{}},{"route":"/key/{kid}","method":"get","security":null,"openapi":{}},{"route":"/key/{kid}/info","method":"get","security":null,"openapi":{}}]}}
2022-10-12T15:11:29.805Z info    | Key 'module' is specified as 'object'
2022-10-12T15:11:29.805Z info    | Registering anonymous provider module v[object Object] as '4177175ad970d'
2022-10-12T15:11:29.807Z info    | Loading providers...
2022-10-12T15:11:29.807Z info    | Loading provider '@adicitus/morrigan.authentication.password'...
2022-10-12T15:11:29.809Z info    | Provider publishes a name, specification does not, using module name ('password')
2022-10-12T15:11:29.809Z info    | Registering provider module '@adicitus/morrigan.authentication.password' v1.0.2 as 'password'
2022-10-12T15:11:29.810Z info    | Component setup Finished.
2022-10-12T15:11:29.810Z info    | Setting up OpenAPI endpoint (@ '/api-docs')...
2022-10-12T15:11:29.811Z info    | OpenAPI setup finished.
2022-10-12T15:11:29.811Z info    | Setting up SwaggerUI (@ '/api-docs/view')
2022-10-12T15:11:29.812Z info    | SwaggerUI setup finished.
2022-10-12T15:11:29.812Z info    | Setting up instance reporting...
2022-10-12T15:11:29.911Z info    | Registering instance...
2022-10-12T15:11:29.913Z info    | Finished instance reporting setup.
2022-10-12T15:11:29.913Z info    | Server is READY.
    key support
2022-10-12T15:11:29.915Z info    | Registered identities: 1
2022-10-12T15:11:29.915Z info    | Registered authentications: 1
2022-10-12T15:11:29.926Z info    | Registering endpoints for 'connection':
2022-10-12T15:11:29.926Z info    |    POST /
2022-10-12T15:11:29.927Z info    |      WS /connect
2022-10-12T15:11:29.927Z info    |     GET /
2022-10-12T15:11:29.927Z info    |     GET /:connectionId
2022-10-12T15:11:29.928Z info    |    POST /:connectionId/send
2022-10-12T15:11:29.928Z info    | Registering endpoints for 'client':
2022-10-12T15:11:29.928Z info    |    POST /provision
2022-10-12T15:11:29.928Z info    |     GET /
2022-10-12T15:11:29.929Z info    |     GET /:clientId
2022-10-12T15:11:29.929Z info    |  DELETE /:clientId
2022-10-12T15:11:29.929Z info    | Registering endpoints for '4177175ad970d':
2022-10-12T15:11:29.929Z info    |     GET /download
2022-10-12T15:11:29.929Z info    |    POST /installer
2022-10-12T15:11:29.930Z info    |     GET /installer
2022-10-12T15:11:29.930Z info    |     GET /installer/{iid}
2022-10-12T15:11:29.930Z info    |   PATCH /installer/{iid}
2022-10-12T15:11:29.930Z info    |  DELETE /installer/{iid}
2022-10-12T15:11:29.931Z info    |     GET /key/support
2022-10-12T15:11:29.931Z info    |     GET /key/{kid}
2022-10-12T15:11:29.931Z info    |     GET /key/{kid}/info
{
  components: {
    parameters: { connectionId: [Object] },
    requestBodies: { 'connection.send.message': [Object] },
    schemas: { 'connection.connectionRecord': [Object] },
    securitySchemes: { 'morrigan.providers.connection.clientAuthentication': [Object] }
  },
  tags: [
    {
      name: 'Connection',
      description: 'WebSocket connections form the basis of communication in the system.'
    }
  ]
}
{ components: { schemas: { clientRecord: [Object] } } }
{}
2022-10-12T15:11:29.943Z http    | --> ::1 GET /api/core/4177175ad970d/key/support 200 - -b 1.416 ms
      ✔ Should be listening on 'http://localhost:21034/api/core/4177175ad970d'
2022-10-12T15:11:29.949Z http    | --> ::1 GET /api/core/4177175ad970d/key/support 200 - -b 0.679 ms
      ✔ Should publish a list of supported key formats at http://localhost:21034/api/core/4177175ad970d/key/support
2022-10-12T15:11:29.951Z info    | Calling onShutdown methods on components...
2022-10-12T15:11:29.952Z info    | Server is shutting down, ending all connections...
2022-10-12T15:11:29.952Z info    | Waiting for components to finish shutting down...
2022-10-12T15:11:29.952Z info    | Components finished shutting down.
2022-10-12T15:11:29.953Z info    | Stopping HTTP server instance...

2022-10-12T15:11:29.954Z info    | HTTP server finished shutting down.
2022-10-12T15:11:29.954Z info    | Stopping server record update interval...
2022-10-12T15:11:29.954Z info    | Updating server record...

Console output also stops early (no 'Bye!').

Adicitus commented 2 years ago

This should be fixed in v0.9.6