Repeated sql query with load relations

[ntvsx193]

I catch this sql when load relations.

+ 26 ms : select * from "sessions" order by "created_at" DESC limit 10
+ 44 ms : select * from "sessions_places" where "session_id" in (23, 22, 21, 20, 19, 18, 17, 16, 15, 14)
+ 40 ms : select * from "sessions_places" where "session_id" in (23, 22, 21, 20, 19, 18, 17, 16, 15, 14)
+ 37 ms : select * from "sessions_places" where "session_id" in (23, 22, 21, 20, 19, 18, 17, 16, 15, 14)
+ 18 ms : select * from "helmets" where "id" in (1, 2, 1, 3, 2, 1, 3)
+ 15 ms : select * from "players" where "id" in (1, 2, 2, 2, 2, 1, 3)
+ 11 ms : select * from "helmets" where "id" in (1, 2, 1, 3, 2, 1, 3)
+ 28 ms : select * from "players" where "id" in (1, 2, 2, 2, 2, 1, 3)
+ 26 ms : select * from "helmets" where "id" in (1, 2, 1, 3, 2, 1, 3)
+ 21 ms : select * from "players" where "id" in (1, 2, 2, 2, 2, 1, 3)

Lucid version 3.0.16, driver pg PostgreSQL 9.6
For reproduce this bug see under.

Route & controller

Route.get('/rest/session', 'SessionsController.index')

'use strict'

const _ = require('lodash')
const Session = use('App/Model/Session')

class SessionsController {

  * index (request, response) {
    let query = request.get()

    const defaultQuery = {
      page: 1,
      limit: 30,
      sort: 'created_at',
    }

    query = _.extend({}, defaultQuery, query)

    const result = yield Session.query()
      .with(['places', 'places.player', 'places.helmet'])
      .orderBy(query.sort)
      .paginate(query.page, query.limit)

    response.json(result)
  }
}

Models

'use strict'

const Lucid = use('Lucid')

class Session extends Lucid {

  static get table () {
    return 'sessions'
  }

  places () {
    return this.hasMany('App/Model/SessionPlace')
  }

}

module.exports = Session

'use strict'

const Lucid = use('Lucid')

class SessionPlaces extends Lucid {

  static get table () {
    return 'sessions_places'
  }

  player () {
    return this.belongsTo('App/Model/Player')
  }

  helmet () {
    return this.belongsTo('App/Model/Helmet')
  }

  session () {
    return this.belongsTo('App/Model/Session')
  }

}

module.exports = SessionPlaces

'use strict'

const Lucid = use('Lucid')

class Player extends Lucid {

  static get table () {
    return 'players'
  }

}

module.exports = Player

'use strict'

const Lucid = use('Lucid')

class Helmet extends Lucid {

  static get table () {
    return 'helmets'
  }

}

module.exports = Helmet

Migrations

'use strict'

const Schema = use('Schema')

class PlayersTableSchema extends Schema {

  up () {
    this.create('players', table => {
      table.increments()
      table.text('nickname').notNullable().unique()
      table.integer('money').notNullable().defaultTo(0)
      table.timestamps()
    })
  }

  down () {
    this.drop('players')
  }

}

module.exports = PlayersTableSchema

'use strict'

const Schema = use('Schema')

class HelmetsTableSchema extends Schema {

  up () {
    this.create('helmets', table => {
      table.increments()
      table.text('code').unique()
      table.timestamps()
    })
  }

  down () {
    this.drop('helmets')
  }

}

module.exports = HelmetsTableSchema

'use strict'

const Schema = use('Schema')

class SessionsTableSchema extends Schema {

  up () {
    this.create('sessions', table => {
      table.increments()
      table.timestamps()
      table.timestamp('started_at')
      table.timestamp('ended_at')

      table.index(['started_at', 'ended_at'])
    })
  }

  down () {
    this.drop('sessions')
  }

}

module.exports = SessionsTableSchema

'use strict'

const Schema = use('Schema')

class SessionsPlacesTableSchema extends Schema {

  up () {
    this.create('sessions_places', table => {
      table.increments()
      table.integer('player_id')
        .notNullable()
        .references('id').inTable('players').onUpdate('cascade').onDelete('cascade')
        .index()
      table.integer('session_id')
        .notNullable()
        .references('id').inTable('sessions').onUpdate('cascade').onDelete('cascade')
        .index()
      table.integer('helmet_id')
        .notNullable()
        .references('id').inTable('helmets').onUpdate('cascade').onDelete('cascade')
        .index()

      table.timestamps()

      table.unique(['session_id', 'player_id'])
      table.unique(['session_id', 'helmet_id'])
    })
  }

  down () {
    this.drop('sessions_places')
  }

}

module.exports = SessionsPlacesTableSchema

[ntvsx193]

I found bug in code, wait PR

[ntvsx193]

I do not know if a bug is being reproduced in lucid 4.0

[thetutlage]

Ill be looking into the issue tonight and will if 4.0 fixes it by default or not

[ntvsx193]

@thetutlage Any progress? I need this fix.

[thetutlage]

@ntvsx193 Sorry for responding late to it, can u reproduce this issue with 4.0?. I tried with 4.0 and all seems to be fine there atleast

[ntvsx193]

Okay, I'm do it today later

[ntvsx193]

I tried with route

const Route = use('Route')
const Session = use('App/Models/Session')

Route.get('/', async () => {
  return await Session.query()
    .with('places')
    .with('places.player')
    .with('places.helmet')
    .paginate(1, 10)
})

And catch throw Cannot set property 'player' of null on node_modules/@adonisjs/lucid/src/Lucid/Relations/Parser.js:44:77

[thetutlage]

Want to try now from github?

adonis install https://github.com/adonisjs/adonis-lucid\#develop

[ntvsx193]

I'm tried, throw catch again Cannot set property 'player' of null

[thetutlage]

Can u make sure that you have the latest from github, since package-lock file prevents updating from a locked version

[ntvsx193]

I'm tried with droped node_modules/ and package-lock.json.

[ntvsx193]

From package-lock.json:

 "@adonisjs/lucid": {
      "version": "git+https://github.com/adonisjs/adonis-lucid.git#713b55f26b82a4c0821eaad59093eb161adeaa8a",
      "requires": {
        "@adonisjs/generic-exceptions": "1.0.0",
        "chance": "1.0.10",
        "debug": "2.6.8",
        "knex": "0.13.0",
        "lodash": "4.17.4",
        "moment": "2.18.1",
        "pluralize": "6.0.0",
        "pretty-hrtime": "1.0.3",
        "require-all": "2.2.0"
      }
    },

[thetutlage]

Ok so #161 issue works fine for me, Lemme reproduce this one too

[thetutlage]

Okay another push, wanna try now? 48bdbba

[ntvsx193]

Yep, it's worked now! :)
Good work!

[thetutlage]

Can u see multiple queries, or is it logging expected number of queries?

[ntvsx193]

Wait, I'm fine server in debug

[ntvsx193]

So good, I don't see repeated queries.

  knex:pool INFO pool postgresql:pg:client0 - dispense() clients=1 available=0 +0ms
  knex:client acquired connection from pool: __knexUid1 +17ms
  knex:query select count(*) as "total" from "sessions" +4ms
  knex:bindings [] +0ms
  knex:client releasing connection to pool: __knexUid1 +6ms
  knex:pool INFO pool postgresql:pg:client0 - dispense() clients=0 available=1 +0ms
  knex:pool INFO pool postgresql:pg:client0 - dispense() clients=0 available=2 +0ms
  knex:pool INFO pool postgresql:pg:client0 - dispense() clients=0 available=3 +0ms
  knex:pool INFO pool postgresql:pg:client0 - dispense() clients=1 available=3 +1ms
  knex:client acquired connection from pool: __knexUid1 +0ms
  knex:query select * from "sessions" limit ? +2ms
  knex:bindings [ 10 ] +1ms
  knex:client releasing connection to pool: __knexUid1 +4ms
  knex:pool INFO pool postgresql:pg:client0 - dispense() clients=0 available=3 +0ms
  knex:pool INFO pool postgresql:pg:client0 - dispense() clients=1 available=3 +10ms
  knex:client acquired connection from pool: __knexUid2 +0ms
  knex:query select * from "sessions_places" where "session_id" in (?, ?, ?, ?) +2ms
  knex:bindings [ 13, 14, 24, 25 ] +0ms
  knex:client releasing connection to pool: __knexUid2 +4ms
  knex:pool INFO pool postgresql:pg:client0 - dispense() clients=0 available=3 +1ms
  knex:pool INFO pool postgresql:pg:client0 - dispense() clients=1 available=3 +3ms
  knex:client acquired connection from pool: __knexUid3 +0ms
  knex:query select * from "players" where "id" in (?, ?, ?, ?, ?, ?, ?) +2ms
  knex:bindings [ 1, 1, 2, 2, 17, 3, 1 ] +0ms
  knex:client releasing connection to pool: __knexUid3 +3ms
  knex:pool INFO pool postgresql:pg:client0 - dispense() clients=0 available=3 +0ms

[ntvsx193]

I'm try add listener Database.on for see output now

[ntvsx193]

Database.on('sql', console.log) not work, I don't know why..

I'm tried with Database.on('query', console.log) and all so good :)

{ __knexUid: '__knexUid1',
  method: 'select',
  options: {},
  timeout: false,
  cancelOnTimeout: false,
  bindings: [],
  __knexQueryUid: '8b3eeca8-42e3-4727-a105-fbf87f6f5a6c',
  sql: 'select count(*) as "total" from "sessions"' }
{ __knexUid: '__knexUid2',
  method: 'select',
  options: {},
  timeout: false,
  cancelOnTimeout: false,
  bindings: [ 10 ],
  __knexQueryUid: '79ade114-1830-4dd5-b95e-40820e125d99',
  sql: 'select * from "sessions" limit ?' }
{ __knexUid: '__knexUid1',
  method: 'select',
  options: {},
  timeout: false,
  cancelOnTimeout: false,
  bindings: [ 13, 14, 24, 25 ],
  __knexQueryUid: '6ad473fd-fdd5-4a95-9710-7ca763e83018',
  sql: 'select * from "sessions_places" where "session_id" in (?, ?, ?, ?)' }
{ __knexUid: '__knexUid2',
  method: 'select',
  options: {},
  timeout: false,
  cancelOnTimeout: false,
  bindings: [ 1, 1, 2, 2, 17, 3, 1 ],
  __knexQueryUid: 'e1e91621-639a-4e24-9538-243eb389a91f',
  sql: 'select * from "players" where "id" in (?, ?, ?, ?, ?, ?, ?)' }

[ntvsx193]

knexjs supports only query, query-error, query-response events
http://knexjs.org/#Interfaces-Events

But in comment on https://github.com/adonisjs/adonis-lucid/blob/develop/src/Database/index.js#L64 u write for support sql.

[ntvsx193]

I think this issue need close, problem solved.
For log database sql I can create new issue.