Add context to config logger property

[SpencerKaiser]

Is your feature request related to a problem? Please describe.
When logging information from the ORM, I would like to be able to see additional context surrounding the query

Describe the solution you'd like
I would like to be able to see additional information for a query when one is made; I want to see:

• The calling function (and/or file)
• The query in clean JSON format (instead of the aggressive alias format in queries which isn't super readable)

I doubt you want the extra details to get pumped into console so maybe an advancedLogger property on the config that has those extra properties and the other logger will be overridden if that property is provided.

Describe alternatives you've considered
Adding log commands after queries have executed

Additional context
I tried adding my own little custom log commands AFTER queries (if you try before there's no way to guarantee it'll print with the related query if others are being executed at the same time) but it's kind of messy and isn't super scalable...

/*
namespace Express {
  export interface Request {
    entityManager: EntityManager<PostgreSqlDriver>;
  }
}
*/

// `req` comes from the express handler

const author = await req.entityManager
  .fork()
  .findOne(
    Author,
    { id: 1 },
  );

if (env.dbLoggingEnabled) {
  logger.debug(`\tvia Author Middleware: ${req.originalUrl}\n`);
}

[SpencerKaiser]

@B4nan if you're interested in this, I'd be down to take a crack at it as my first real contribution 😅

[B4nan]

The calling function (and/or file)

Sounds a bit like you would like to generate a stack trace to get that information - that is slow and cannot be done on a query level, it would slow down things significantly.

The query in clean JSON format (instead of the aggressive alias format in queries which isn't super readable)

Not sure what you mean by JSON format? Queries are strings, that is what gets executed. If you mean the object syntax for where queries, that is optional, and is handled on the QB level - the result is a string query and that is what gets executed, and I would definitely stick to that.

I don't mind the idea of more context in the logger, but it would have to be without any perf hit, and I am not sure what you are proposing is what will be feasible - but slower things could be opt-in. I also don't think we need yet another logger instance, sounds a bit confusing to me. Not sure what you wanted to demonstrate in that example? :]

Feel free to give it a try, you will probably have a better understanding of how it could look like once you dive deeper to the codebase.

Maybe it would be enough to add some option to FindOptions and QB interface so its up to you to provide the context? I'd rather have more general approach for this, that allows you to do things your way.

[SpencerKaiser]

Not sure what you mean by JSON format?

Here's an example of one of our queries:

[query] select "i0"."id", "i0"."createdAt", "i0"."updatedAt", "i0"."host", "i0"."durationOption", "i0"."billing_hostHourlyRateInCents", "i0"."roomId", "i0"."billing_paymentIntentId", "i0"."billing_transferId", "i0"."billing_holdPayout", "i0"."status", "i0"."topic", "i0"."user", "h1"."id" as "h1__id", "h1"."createdAt" as "h1__createdAt", "h1"."updatedAt" as "h1__updatedAt", "h1"."user" as "h1__user", "h1"."handle" as "h1__handle", "h1"."displayName" as "h1__displayName", "h1"."title" as "h1__title", "h1"."aboutMe" as "h1__aboutMe", "h1"."expertise" as "h1__expertise", "h1"."stripeAccountId" as "h1__stripeAccountId", "h1"."avatarUrl" as "h1__avatarUrl", "h1"."socialUrls_Website" as "h1__socialUrls_Website", "h1"."socialUrls_Instagram" as "h1__socialUrls_Instagram", "h1"."socialUrls_Twitter" as "h1__socialUrls_Twitter", "h1"."socialUrls_YouTube" as "h1__socialUrls_YouTube", "h1"."socialUrls_Twitch" as "h1__socialUrls_Twitch", "h1"."socialUrls_LinkedIn" as "h1__socialUrls_LinkedIn", "h1"."socialUrls_Facebook" as "h1__socialUrls_Facebook", "h1"."socialUrls_TikTok" as "h1__socialUrls_TikTok", "h1"."socialUrls_Patreon" as "h1__socialUrls_Patreon", "h1"."isFeatured" as "h1__isFeatured", "h1"."referredBy" as "h1__referredBy", "c2"."id" as "c2__id", "c2"."createdAt" as "c2__createdAt", "c2"."updatedAt" as "c2__updatedAt", "c2"."host" as "c2__host", "c2"."title" as "c2__title", "c2"."description" as "c2__description", "c2"."status" as "c2__status", "c2"."position" as "c2__position", "c2"."interactionType" as "c2__interactionType", "c2"."isRecordedByDefault" as "c2__isRecordedByDefault", "c2"."schedulingPreferences_timezone" as "c2__schedulingPreferences_timezone", "c2"."schedulingPreferences_preferredTimes" as "c2__schedulingPreferences_preferredTimes", "c2"."hourlyRateInCents" as "c2__hourlyRateInCents", "d3"."id" as "d3__id", "d3"."createdAt" as "d3__createdAt", "d3"."updatedAt" as "d3__updatedAt", "d3"."callOption" as "d3__callOption", "d3"."lengthInMinutes" as "d3__lengthInMinutes", "d3"."discountPercent" as "d3__discountPercent", "d3"."isDefault" as "d3__isDefault", "d3"."status" as "d3__status", "u4"."id" as "u4__id", "u4"."createdAt" as "u4__createdAt", "u4"."updatedAt" as "u4__updatedAt", "u4"."email" as "u4__email", "u4"."firstName" as "u4__firstName", "u4"."lastName" as "u4__lastName", "u4"."phone" as "u4__phone", "u4"."acceptedTermsOfServiceVersion" as "u4__acceptedTermsOfServiceVersion", "u4"."acceptedPrivacyPolicyVersion" as "u4__acceptedPrivacyPolicyVersion", "u4"."status" as "u4__status", "u4"."host" as "u4__host" from "InstantMeeting" as "i0" left join "Host" as "h1" on "i0"."host" = "h1"."id" left join "CallOption" as "c2" on "h1"."id" = "c2"."host" left join "DurationOption" as "d3" on "c2"."id" = "d3"."callOption" left join "User" as "u4" on "i0"."user" = "u4"."id" where ("i0"."user" = '7' or "i0"."host" = '7') and "i0"."createdAt" >= '2023-02-16T16:15:55.928Z' order by "i0"."createdAt" desc [took 4 ms]

(FYI that is the A->B->C entity I mentioned here)

That's super, super unreadable... what I'd like to see is something like this:

[query]: select Host, populate: 'durationOption.callOption', 'user'
where: {
  createdAt: ">= '2023-02-16T16:15:55.928Z",
}
order by: 'createdAt desc'

I don't mind the idea of more context in the logger, but it would have to be without any perf hit

Totally fair... what about a new property inside the findOptions (which is kinda gross) or adding a new contextOptions object at the end of the Find methods that has a queryLabel value which gets printed with the query?

const author = await em.findOneOrFail(Author, { id: 1 }, { populate: ['books'] }, { queryLabel: 'Author Middleware' });
// [query - Author Middleware]: ...

Not sure what you wanted to demonstrate in that example? :]

I was just trying to show off that it's kinda gross to try to handle sharing that context myself... I'd have to do it manually for all queries and make sure it's AFTER otherwise it'll get scrambled with the other async queries

Maybe it would be enough to add some option to FindOptions and QB interface so its up to you to provide the context? I'd rather have more general approach for this, that allows you to do things your way.

haha we're on the same page... I submitted too quickly. I think that's a good approach... want to use findOptions or add a new value at the end? findOptions will likely be easier, but I like the idea of being able to build upon a new option at the end to track more stuff... could allow for new properties that further enhance debugging/logging.

[B4nan]

I'd say this is really a matter of preference, and logging the exact query instead of this random format sounds like a better thing in general - this way you can clearly see what it generates and debug it further. It is a bit messy because you use joined strategy which selects all the columns explicitly.

Totally fair... what about a new property inside the findOptions (which is kinda gross) or adding a new contextOptions object at the end of the Find methods that has a queryLabel value which gets printed with the query?

I am definitely not adding another parameter after it - that is gross :]

I'd rather see an option you can literally put anything in (so unknown type), and you will get that in your custom logger - and you can do whatever you want inside. You can already bring your own logger via the loggerFactory option.

const author = await em.findOneOrFail(Author, { id: 1 }, {
  populate: ['books'],
  loggerContext: { queryLabel: 'Author Middleware' }, // can be a scalar too, not just an object
});

[SpencerKaiser]

I'd say this is really a matter of preference, and logging the exact query instead of this random format sounds like a better thing in general

Oh 100%; I was saying that I would like that format if I had control over the logger, but I'm totally ok with the option to just add context; that helps enough

I am definitely not adding another parameter after it - that is gross :]

Hahaha well I guess findOptiions isn't really just about the query, it's about the find as a whole, so I'm good with that 👌

I'll work on this this afternoon; I think it's best to start off with a limited type like what I have below and then add onto it; the label alone gets me 90% of what I'd want and that's likely to be a little different than adding additional properties in because the query label, IMO, should get tacked onto the [query] you log before the SQL. Thoughts??

type LoggerContext = string | {
  queryLabel?: string
};

[B4nan]

The thing before query is logger namespace, that is what you use to control what will be logged or not. I'd rather not make this “configurable”, but open for suggestions.

Keep in mind there are more things we log, its not all about queries.

[SpencerKaiser]

Sounds good, I'll take a look and just make a draft before getting more feedback