Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Printing full SQL queries with parameters in debug mode #5026

Open
esistgut opened this issue Feb 19, 2020 · 33 comments
Open

Printing full SQL queries with parameters in debug mode #5026

esistgut opened this issue Feb 19, 2020 · 33 comments
Labels
domain/client Issue in the "Client" domain: Prisma Client, Prisma Studio etc. kind/feature A request for a new feature. topic: dx topic: logging

Comments

@esistgut
Copy link

I am initializing prisma with {debug: true, log: ['info', 'query'],} and this is printing SQL queries without actual parameters, just ? to mask them.
Wouldn't it be useful to print the whole thing?

@janpio
Copy link
Member

janpio commented Feb 19, 2020

It could be useful, but also pretty dangerous as it could show information that you are not expecting to see anywhere really. We will have to think about how exactly we want to expose this functionality to log this data.

(Technically it is not a big challenge, the query engine is already logging the information internally and it is just not getting picked up.)

@pantharshit00 pantharshit00 transferred this issue from prisma/prisma Feb 20, 2020
@pantharshit00 pantharshit00 transferred this issue from prisma/prisma-client-js Jan 13, 2021
@pantharshit00 pantharshit00 added kind/feature A request for a new feature. topic: dx labels Jan 13, 2021
@pantharshit00
Copy link
Contributor

Right now you can use events to log the parameters like so:

const prisma = new PrismaClient({
  log: [
    {
      emit: "event",
      level: "query",
    },
  ],
});

prisma.$on("query", async (e) => {
    console.log(`${e.query} ${e.params}`)
});

We might even close this one considering it is safer to log masked output by default and also provide you a way to customize the output.

@timsuchanek
Copy link
Contributor

Closing as it can be achieved like @pantharshit00 noted.

@Aeolun
Copy link

Aeolun commented Sep 9, 2021

How about providing an option to log it? Like, log: ['querywithparameter']? I think this is a fairly basic thing for which the functionality is now hidden in this ticket.

@aledalgrande
Copy link

This should be active by default in development, it's unnecessarily strict for data that has no value.

@incompletude
Copy link

I'm using Nestjs and I can't find a way to log variable values.

@Isahara86
Copy link

Isahara86 commented Nov 30, 2021

@incompletude
@pantharshit00 approach works for Nestjs as well

import { INestApplication, Injectable, OnModuleInit } from '@nestjs/common';
import { PrismaClient } from '@prisma/client';

@Injectable()
export class PrismaService extends PrismaClient implements OnModuleInit {
  constructor() {
    super({
      log: [
        {
          emit: 'event',
          level: 'query',
        },
      ],
    });
  }

  async onModuleInit(): Promise<void> {
    await this.$connect();
    // eslint-disable-next-line @typescript-eslint/ban-ts-comment
    // @ts-ignore
    this.$on('query', async (e) => {
      // eslint-disable-next-line @typescript-eslint/ban-ts-comment
      // @ts-ignore
      console.log(`${e.query} ${e.params}`);
    });
  }

  async enableShutdownHooks(app: INestApplication): Promise<void> {
    this.$on('beforeExit', async () => {
      await app.close();
    });
  }
}

@rinogo
Copy link

rinogo commented Dec 3, 2021

@Isahara86 Brilliant! Works like a charm.

I'm planning on using this in our Jest tests to confirm that the Prisma "query" matched an expected value before returning the associated mocked result. Does that seem like a good approach, or is there another canonical solution?

@rinogo
Copy link

rinogo commented Dec 3, 2021

P.S. Further research reveals that Jest may run tests in parallel (i.e. for tests in different files), so I suppose this approach could potentially lead to a race condition scenario with other tests.

Might try it out anyway, though, unless someone has a better suggestion.

(Comparing SQL strings sure is a lot easier than comparing the deep Prisma query object that our app dynamically builds.)

@omidh28
Copy link

omidh28 commented May 4, 2022

I'm getting Argument of type '"query"' is not assignable to parameter of type '"beforeExit"'.ts(2345).

@mwitteveen
Copy link

There is indeed a mistake in type definition file.

image

@mwitteveen
Copy link

There is indeed a mistake in type definition file.

image

line 182 of index.d.ts

@omidh28
Copy link

omidh28 commented May 8, 2022

Nah, It's just outdated information. For recent version just pass { log: ['query'] } to Prisma client constructor.

@catcatcatcatcatcatcatcatcatcat

I managed to create some decent prisma slow query log magic with variables interpolated for copy/paste in react/ts

import { PrismaClient } from '@prisma/client'

let prisma
if (process.env.PRISMA_SLOW_QUERY_LOG) {
  prisma = new PrismaClient({
    log: [
      {
        emit: 'event',
        level: 'query',
      },
      {
        emit: 'stdout',
        level: 'error',
      },
      {
        emit: 'stdout',
        level: 'info',
      },
      {
        emit: 'stdout',
        level: 'warn',
      },
    ],
  })
  // Default max duration to 250ms
  const maxDuration: number = +process.env.PRISMA_SLOW_QUERY_LOG_TIME
  prisma.$on('query', async (e) => {
    let query = e.query
    let params = JSON.parse(e.params)
    // Replace $X variables with params in query so it's possible to copy/paste and optimize
    for (let i=0; i < params.length; i++) {
        // Negative lookahead for no more numbers, ie. replace $1 in '$1' but not '$11'
        const re = new RegExp('\\$' + (i as number + 1) + '(?!\\d)', 'g')
        // If string, will quote - if bool or numeric, will not - does the job here
        if (typeof params[i] === 'string')
            params[i] = "'" + params[i].replace("'", "\\'") + "'"
        //params[i] = JSON.stringify(params[i])
        query = query.replace(re, params[i])
    }
    if (e.duration > maxDuration) {
        console.log(`${e.duration}ms: `, query)
    }
  })
  prisma.$use(async (params, next) => {
    const before = Date.now()
    const result = await next(params)
    const duration = Date.now() - before
    if (duration > maxDuration) {
        // log more info about where the query possibly originated from
        console.log(`Query ${params.model}.${params.action} took ${duration}ms`)
    }
    return result
  })
} else {
  prisma = new PrismaClient()
}

export default prisma as PrismaClient

@ogroppo
Copy link

ogroppo commented Jul 20, 2022

@catcatcatcatcatcatcatcatcatcat JSON.parse(e.params) will break if there is a date e.g. [1,2022-07-20 09:30:33.036 UTC,0,100,false,0] hope there is a recommended way to do this!

@janpio
Copy link
Member

janpio commented Jul 30, 2022

(I think someone should turn the desire to have such a complete log, or a function to do that, into a feature request. That would make it much easier to collect workarounds and scripts like the one @catcatcatcatcatcatcatcatcatcat posted above.)

@nikolasburk
Copy link
Member

@janpio do you think it would be enough to re-open this one since this basically is a FR for getting a complete log? or what else would you want to see in a new PR?

@Jackman3005
Copy link

Jackman3005 commented Sep 2, 2022

@ogroppo I solved this for my use-case and it is working with Postgres. I only have TIMESTAMPS in my DB, no dates by themselves, but I imagine you just need to do the same for any dates and it'll work fine. The rebuiltQuery can be pasted into psql and executed without issue, or you can add EXPLAIN ANALYZE before it as was my intended use-case.

const queryParamsArray = e.params.replaceAll(
    /(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{0,3} UTC)/g,
    (match) => {
      return `"TIMESTAMP WITH TIME ZONE '${match}'"`;
    }
  );
  
const paramObjs = JSON.parse(queryParamsArray);
const rebuiltQuery = (e.query || "").replaceAll(
  /\$(\d+)/g,
  (_matchedString, paramIndex) => {
    let param = paramObjs[parseInt(paramIndex) - 1];
    if (typeof param === "string") {
      if (!param.startsWith("TIMESTAMP")) {
        param = `'${param}'`;
      }
    }
    return param;
  }
);

Note that this code is inside the event listener block: prisma.$on('query', async (e) => {...})

@ogroppo
Copy link

ogroppo commented Sep 2, 2022

Thank you @Jackman3005 I will give it a go, however, such a logging capability is expected as the shoddy competitors have it 😆

@janpio janpio reopened this Sep 2, 2022
@ogroppo
Copy link

ogroppo commented Sep 3, 2022

Thank you @janpio for reopening - the ability to copy the query and run it "AS IS" in a DB client is crucial for debugging

@mystist
Copy link

mystist commented Jan 15, 2023

Tested with postgres:

// eslint-disable-next-line @typescript-eslint/ban-ts-comment
// @ts-nocheck

import { Injectable, OnModuleInit } from '@nestjs/common'
import { ConfigService } from '@nestjs/config'
import { PrismaClient } from '@prisma/client'

@Injectable()
export class PrismaService extends PrismaClient implements OnModuleInit {
  constructor(config: ConfigService) {
    const dbConfig = {
      datasources: {
        db: {
          url: config.get('DATABASE_URL'),
        },
      },
    }
    const logConfig = {
      log: [
        {
          emit: 'event',
          level: 'query',
        },
        {
          emit: 'event',
          level: 'error',
        },
      ],
    }
    const initialConfig: any = process.env.NODE_ENV === 'production' ? { ...dbConfig } : { ...dbConfig, ...logConfig }

    super(initialConfig)
  }

  onModuleInit() {
    if (process.env.NODE_ENV === 'production') return

    this.$on('query', (e) => {
      let queryString = e.query
      JSON.parse(e.params).forEach((param, index) => {
        queryString = queryString.replace(`$${index + 1}`, typeof param === 'string' ? `'${param}'` : param)
      })
      
      console.log(queryString)
    })
  }
}

Thank you @janpio for reopening - the ability to copy the query and run it "AS IS" in a DB client is crucial for debugging

@revero-doug
Copy link

there is no known universal workaround as neither " nor , are escaped, so even json-supported values are not properly json serialized

@leppaott
Copy link

@omidh28

I'm getting Argument of type '"query"' is not assignable to parameter of type '"beforeExit"'.ts(2345).

This would be nice to get fixed? Examples provided on docs don't work without some // @ts-ignore

@Jackman3005
Copy link

Jackman3005 commented May 24, 2023

This is slightly off topic, but still very relevant to the debugging of SQL queries.

Does anyone know how to relate the query event received in the prisma.$on('query', ...) handler with the Prisma action that can be found in the middleware (prisma.$use(...))?

I get decent printouts for slow queries, but it's not very traceable, I don't know which Prisma action triggered the Query, so it is hard to determine where in our code the query originates from...

I tried using AsyncLocalStorage to store a unique context for each Prisma action like so:

prisma.$use(async (params, next) => {
    let result;
    await context.run({ my: "unique-context-for-this-action" }, async () => {
      result = await next(params);
    });
    return result;
});

Then tried to access the context in the query event like so:

prisma.$on("query", async (e) => {
     console.log("$on.query context.getStore()", context.getStore());
});

But the context is always undefined in the query event handler.

Is there a way to make this work? Or is there any other way to correlate the query with the Prisma action that triggered the query?

Thanks!
Jack (and the Questmate team)

Edit

I found a related issue that tracks this concern already.

@ethaizone
Copy link

I'm getting Argument of type '"query"' is not assignable to parameter of type '"beforeExit"'.ts(2345).

I faced this issue too. solution is exists but I can came up after I read whole typed stuff in this library. I started to do this after I found this issue but no solution for me. 🥲

  getLogConfig(): Array<{
    level: Prisma.LogLevel
    emit: 'event'
  }> {
    const { logLevel } = getConfig()

    const mapAsEvent = (level: string) => ({ level: level as Prisma.LogLevel, emit: 'event' as 'event' })

    if (logLevel === 'debug' || logLevel === 'info') {
      return ['query', 'info', 'warn', 'error'].map(mapAsEvent)
    }

    if (logLevel === 'warn') {
      return ['warn', 'error'].map(mapAsEvent)
    }

    return ['error'].map(mapAsEvent)
  }
  
  createInstance(): PrismaClient {
    const url = this.getUrl()
    const options = {
      datasources: {
        db: {
          url,
        },
      },
      log: [...this.getLogConfig()],
    }
    const instance = new PrismaClient(options)

    instance.$on('query', e => {
      this.logger.debug(`Query: ${e.query} Params: ${e.params} Duration: ${e.duration} ms`)
    })

    return instance
  }

This is example code to give basic idea so config that passing to Prisma client need to put emit as event for all cases.

type doesn't have any mistake but it's just hard to use if log variable is dynamic value and important line is emit: 'event' as 'event'. This should make anyone understand that type as 'event' isn't same as string.

@ShrihariMohan
Copy link

There is indeed a mistake in type definition file.
image

line 182 of index.d.ts

I just did this and it works

prisma.$on("query" as any, async (e: any) => {
  console.debug(e.params)
});

I am getting params as a output

["clm2zqxxh000c1j3emjhosxk5",1,0]

@cstria0106
Copy link

cstria0106 commented Sep 10, 2023

@incompletude @pantharshit00 approach works for Nestjs as well

import { INestApplication, Injectable, OnModuleInit } from '@nestjs/common';
import { PrismaClient } from '@prisma/client';

@Injectable()
export class PrismaService extends PrismaClient implements OnModuleInit {
  constructor() {
    super({
      log: [
        {
          emit: 'event',
          level: 'query',
        },
      ],
    });
  }

  async onModuleInit(): Promise<void> {
    await this.$connect();
    // eslint-disable-next-line @typescript-eslint/ban-ts-comment
    // @ts-ignore
    this.$on('query', async (e) => {
      // eslint-disable-next-line @typescript-eslint/ban-ts-comment
      // @ts-ignore
      console.log(`${e.query} ${e.params}`);
    });
  }

  async enableShutdownHooks(app: INestApplication): Promise<void> {
    this.$on('beforeExit', async () => {
      await app.close();
    });
  }
}

strict type version

import { Injectable, OnModuleInit } from '@nestjs/common';
import { Prisma, PrismaClient } from '@prisma/client';

const options = {
  log: [
    {
      emit: 'event' as const,
      level: 'query' as const,
    },
    'info' as const,
    'warn' as const,
    'error' as const,
  ],
} satisfies Prisma.PrismaClientOptions;

@Injectable()
export class PrismaService
  extends PrismaClient<typeof options>
  implements OnModuleInit
{
  constructor() {
    super(options);
    this.$on('query', async (e) => {
      console.log(e.query, e.params);
    });
  }
  async onModuleInit() {
    await this.$connect();
  }
}

@clemlucas974
Copy link

Hi ! Thanks to @Jackman3005 solution, I was able to find out a way to avoid JSON.parse error on Prisma date format.
Not the exact queries in some situations, but still fine for the basics.

import { INestApplication, Injectable, OnModuleInit } from '@nestjs/common';
import { PrismaClient } from '@prisma/client';

type QueryInfo = {
  timestamp: string; // Assuming the timestamp is a string in ISO 8601 format
  query: string;
  params: string;
  duration: number;
  target: string;
};

function transformDateForJSONParse(dateString: string): string {
  // Convert to ISO 8601 format
  return new Date(dateString).toISOString();
}

@Injectable()
export class PrismaService extends PrismaClient implements OnModuleInit {
  constructor() {
    super({
      log: [
        { emit: 'event', level: 'query' },
        { emit: 'stdout', level: 'info' },
        { emit: 'stdout', level: 'warn' },
        { emit: 'stdout', level: 'error' },
      ],
    });
  }

  async onModuleInit(): Promise<void> {
    await this.$connect();

    if (process.env.DEBUG) {
      // eslint-disable-next-line @typescript-eslint/ban-ts-comment
      // @ts-ignore
      this.$on('query', async (e: QueryInfo) => {
        try {
          const queryParamsArray = e.params.replaceAll(
            /(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{0,3} UTC)/g,
            (match) => {
              return transformDateForJSONParse(match);
            },
          );

          const paramObjs = JSON.parse(queryParamsArray);
          const rebuiltQuery = (e.query || '').replaceAll(
            /\$(\d+)/g,
            (_matchedString, paramIndex) => {
              let param = paramObjs[parseInt(paramIndex) - 1];
              if (typeof param === 'string') {
                if (!param.startsWith('TIMESTAMP')) {
                  param = `'${param}'`;
                }
              }
              return param;
            },
          );

          // eslint-disable-next-line @typescript-eslint/ban-ts-comment
          // @ts-ignore
          console.debug(rebuiltQuery);
        } catch (error) {
          console.error(error);
        }
      });
    }
  }

  async enableShutdownHooks(app: INestApplication): Promise<void> {
    // eslint-disable-next-line @typescript-eslint/ban-ts-comment
    // @ts-ignore
    this.$on('beforeExit', async () => {
      await app.close();
    });
  }
}

@meotimdihia
Copy link

meotimdihia commented Dec 20, 2023

Not perfectly, but this is what I am using:

    const prisma = new PrismaClient({
      log: [
        {
          emit: "event",
          level: "query"
        },
        {
          emit: "stdout",
          level: "error"
        },
        // {
        //   emit: "stdout",
        //   level: "info",
        // },
        {
          emit: "stdout",
          level: "warn"
        }
      ]
    })



      prisma.$on("query", e => {
      const chalk = require("chalk")
      let query = e.query
      try {
        const params = JSON.parse(e.params)

        for (let i = params.length; i > -1; i--) {
          query = query.replace(
            new RegExp("\\$" + String(i + 1), "g"),
            isNaN(Number(params[i])) ? "'" + params[i] + "'" : params[i]
          )
        }
      } catch (e) {
        console.log(e)
      }
      const statements = [
        "SELECT",
        "JOIN",
        "FROM",
        "WHERE",
        "OFFSET",
        "IN",
        "ORDER BY",
        "ORDER",
        "ASC",
        "DESC",
        "AND",
        "OR",
        "LIMIT",
        "AS",
        "INNER",
        "LEFT",
        "IS NOT NULL",
        "IS NULL"
      ]
      statements.map(statement => {
        query = query.replace(
          new RegExp(statement, "g"),
          chalk.green(statement)
        )
      })
      console.log("----------------")
      console.log(query)

      console.log(
        "Duration: " +
          (e.duration > 100 ? chalk.yellow(e.duration) : e.duration)
      )
    })

@hanayashiki
Copy link

I managed to create some decent prisma slow query log magic with variables interpolated for copy/paste in react/ts

import { PrismaClient } from '@prisma/client'

let prisma
if (process.env.PRISMA_SLOW_QUERY_LOG) {
  prisma = new PrismaClient({
    log: [
      {
        emit: 'event',
        level: 'query',
      },
      {
        emit: 'stdout',
        level: 'error',
      },
      {
        emit: 'stdout',
        level: 'info',
      },
      {
        emit: 'stdout',
        level: 'warn',
      },
    ],
  })
  // Default max duration to 250ms
  const maxDuration: number = +process.env.PRISMA_SLOW_QUERY_LOG_TIME
  prisma.$on('query', async (e) => {
    let query = e.query
    let params = JSON.parse(e.params)
    // Replace $X variables with params in query so it's possible to copy/paste and optimize
    for (let i=0; i < params.length; i++) {
        // Negative lookahead for no more numbers, ie. replace $1 in '$1' but not '$11'
        const re = new RegExp('\\$' + (i as number + 1) + '(?!\\d)', 'g')
        // If string, will quote - if bool or numeric, will not - does the job here
        if (typeof params[i] === 'string')
            params[i] = "'" + params[i].replace("'", "\\'") + "'"
        //params[i] = JSON.stringify(params[i])
        query = query.replace(re, params[i])
    }
    if (e.duration > maxDuration) {
        console.log(`${e.duration}ms: `, query)
    }
  })
  prisma.$use(async (params, next) => {
    const before = Date.now()
    const result = await next(params)
    const duration = Date.now() - before
    if (duration > maxDuration) {
        // log more info about where the query possibly originated from
        console.log(`Query ${params.model}.${params.action} took ${duration}ms`)
    }
    return result
  })
} else {
  prisma = new PrismaClient()
}

export default prisma as PrismaClient

Not perfectly, but this is what I am using:

    const prisma = new PrismaClient({
      log: [
        {
          emit: "event",
          level: "query"
        },
        {
          emit: "stdout",
          level: "error"
        },
        // {
        //   emit: "stdout",
        //   level: "info",
        // },
        {
          emit: "stdout",
          level: "warn"
        }
      ]
    })



      prisma.$on("query", e => {
      const chalk = require("chalk")
      let query = e.query
      try {
        const params = JSON.parse(e.params)

        for (let i = params.length; i > -1; i--) {
          query = query.replace(
            new RegExp("\\$" + String(i + 1), "g"),
            isNaN(Number(params[i])) ? "'" + params[i] + "'" : params[i]
          )
        }
      } catch (e) {
        console.log(e)
      }
      const statements = [
        "SELECT",
        "JOIN",
        "FROM",
        "WHERE",
        "OFFSET",
        "IN",
        "ORDER BY",
        "ORDER",
        "ASC",
        "DESC",
        "AND",
        "OR",
        "LIMIT",
        "AS",
        "INNER",
        "LEFT",
        "IS NOT NULL",
        "IS NULL"
      ]
      statements.map(statement => {
        query = query.replace(
          new RegExp(statement, "g"),
          chalk.green(statement)
        )
      })
      console.log("----------------")
      console.log(query)

      console.log(
        "Duration: " +
          (e.duration > 100 ? chalk.yellow(e.duration) : e.duration)
      )
    })

Does not work when e.params is not real JSON.

My string field contains newlines and escaped regex like \( and they are not converted to \n or \\( between quotes.

@vladinator1000
Copy link

vladinator1000 commented Apr 25, 2024

It would have been a dream if event.params wasn't a string, but actually had the args prisma uses under the hood. (Like the data dapter for example)

e.params: string doesn't work if for non-trivial use-cases, such as serializing / deserializing a JSON string.

let statement = ''
prisma.$on('query', async (e) => {
 let params = JSON.stringify(e.params) <-- this won't work if your params are complex
 
 statement += combineQueryWithParams(e.query, params)
})

As soon as your params are something more complicated like this

    let params = `[
      "2024-04-24 23:43:58.490 UTC",
      "https://images.unsplash.com/photo-1596040078821-9b5f50e71ea5?crop=entropy&cs=tinysrgb&fit=max&fm=jpg&ixid=M3wxNDkxMTV8MHwxfHJhbmRvbXx8fHx8fHx8fDE3MTQwMDIyMzd8&ixlib=rb-4.0.3&q=80&w=1080",
      "[{"name":"youtube","url":"youtube.com"},{"name":"soundcloud","url":"soundcloud.com"},{"name":"spotify","url":"spotify.com"}]",
      "[]"
    ]`

The parsing won't work, because the event type (QueryEvent) prints params as a string, but doesn't escape JSON properly and you get param parsing errors.
SyntaxError: Expected ',' or ']' after array element in JSON at position 427 (line 9 column 11)

@s1owjke
Copy link

s1owjke commented May 19, 2024

We have recently started to use Prisma in a number of our projects and we have run into this problem as well.

Prisma uses a it's own implementation in Rust for stringifying parameters, which in some cases doesn't generate correct JSON (for example, it doesn't escape double quotes).

I made a small zero-dependency npm package for parameter substitution and converting all queries to a single-line format (raw queries are typically formatted with line breaks to make them easier to read).

import { formatQuery } from "prisma-query-formatter";

prisma.$on("query", (e) => {
  console.log(formatQuery(e.query, e.params));
});

@whiskerside
Copy link

Right now you can use events to log the parameters like so:

const prisma = new PrismaClient({
  log: [
    {
      emit: "event",
      level: "query",
    },
  ],
});

prisma.$on("query", async (e) => {
    console.log(`${e.query} ${e.params}`)
});

We might even close this one considering it is safer to log masked output by default and also provide you a way to customize the output.

Works well with D1 SQLite

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
domain/client Issue in the "Client" domain: Prisma Client, Prisma Studio etc. kind/feature A request for a new feature. topic: dx topic: logging
Projects
None yet
Development

No branches or pull requests