audiobookshelf/test/server/utils/libraryBrowseInstrumentation.test.js

const chai = require('chai')
const expect = chai.expect
const sinon = require('sinon')

const {
  createBrowseRequestProfile,
  createBrowsePhaseTiming,
  finishBrowseRequestProfile
} = require('../../../server/utils/queries/libraryBrowseInstrumentation')
const { profile } = require('../../../server/utils/profiler')

describe('libraryBrowseInstrumentation', () => {
  afterEach(() => {
    sinon.restore()
  })

  it('records named browse phases and returns a slow-summary payload', () => {
    const timestamps = [
      100,
      110,
      160,
      170,
      200,
      210,
      235,
      240,
      280,
      320
    ]

    const profile = createBrowseRequestProfile({
      route: 'GET /api/libraries/:id/items',
      libraryId: 'lib_1',
      now: () => timestamps.shift()
    })

    profile.mark('rows:start')
    profile.mark('rows:end')
    profile.mark('count:start')
    profile.mark('count:end')
    profile.mark('derived:start')
    profile.mark('derived:end')
    profile.mark('postprocess:start')
    profile.mark('postprocess:end')

    const result = finishBrowseRequestProfile(profile, { slowMs: 150 })

    expect(result).to.deep.equal({
      route: 'GET /api/libraries/:id/items',
      libraryId: 'lib_1',
      totalMs: 220,
      phases: {
        rows: 50,
        count: 30,
        derived: 25,
        postprocess: 40
      },
      isSlow: true
    })
  })

  it('accumulates repeated timings for the same phase', () => {
    const timestamps = [100, 110, 140, 150, 190, 210]
    const profile = createBrowseRequestProfile({
      route: 'GET /api/libraries/:id/items',
      libraryId: 'lib_1',
      now: () => timestamps.shift()
    })

    profile.mark('rows:start')
    profile.mark('rows:end')
    profile.mark('rows:start')
    profile.mark('rows:end')

    const result = finishBrowseRequestProfile(profile, { slowMs: 500 })

    expect(result.phases).to.deep.equal({ rows: 70 })
    expect(result.isSlow).to.equal(false)
  })

  it('handles null and partial profiles safely', () => {
    expect(finishBrowseRequestProfile(null, { slowMs: 0 })).to.deep.equal({
      route: null,
      libraryId: null,
      totalMs: 0,
      phases: {},
      isSlow: false
    })

    expect(finishBrowseRequestProfile({ route: 'GET /items', marks: [{ name: 'rows:start', at: 10 }] })).to.deep.equal({
      route: 'GET /items',
      libraryId: null,
      totalMs: 0,
      phases: {},
      isSlow: false
    })
  })

  it('composes caller logging with request-scoped browse timing hooks', async () => {
    const timestamps = [100, 110, 150, 180]
    const browseProfile = createBrowseRequestProfile({
      route: 'GET /api/libraries/:id/items',
      libraryId: 'lib_1',
      now: () => timestamps.shift()
    })
    const callerLogging = sinon.spy()
    const originalFindOptions = {
      where: { id: 'item_1' },
      logging: callerLogging,
      requestTiming: createBrowsePhaseTiming(browseProfile, 'rows')
    }

    const wrappedQuery = profile(async (findOptions) => {
      findOptions.logging('SELECT 1', 12)
      return findOptions
    }, true, 'browseRows')

    const wrappedFindOptions = await wrappedQuery(originalFindOptions)
    const result = finishBrowseRequestProfile(browseProfile, { slowMs: 1000 })

    expect(wrappedFindOptions).to.not.equal(originalFindOptions)
    expect(originalFindOptions).to.not.have.property('benchmark')
    expect(callerLogging.calledOnceWithExactly('SELECT 1', 12)).to.equal(true)
    expect(result.phases).to.deep.equal({ rows: 40 })
  })
})