Sometimes calling em.populate does not init a relation

[wasd171]

Describe the bug
Sometimes calling em.populate does not init a relation

Stack trace

Cannot read properties of undefined (reading 'getItems') <- happens to 1:M / M:N relations

or

Cannot return null from non-nullable field <- GraphQL server throws it, happens to 1:1 relations

To Reproduce
Steps to reproduce the behavior:
Unfortunately I was not able to reliably reproduce this behaviour. Mostly it works for us but typically a few times per day we get this error in the same parts of the code. Given its unstable nature I would suspect that there is a race condition somewhere. If needed, I'll be happy to add some debugging info into our code to get more information from runtime exceptions.

We operate a GraphQL API and relevant entities look like the following:

1:N / M:N

abstract class BaseEntity {
	@PrimaryKey({ length: 25, type: 'string' })
	id = cuid()

	@Property({
		type: 'Date',
		fieldName: 'createdAt',
	})
	createdAt = new Date()

	@Property({
		type: 'Date',
		fieldName: 'updatedAt',
		onUpdate: () => new Date(),
	})
	updatedAt = new Date()
}

@Entity({ collection: 'Trait' })
class Trait extends BaseEntity {
	[OptionalProps]?: 'createdAt' | 'updatedAt'

        @OneToMany({ entity: 'Translation', mappedBy: 'trait' })
	translations = new Collection<Translation>(this)

	@OneToMany({ entity: 'Translation', mappedBy: 'traitDescription' })
	descriptions = new Collection<Translation>(this)
}

enum LOCALE {
	DE = 'DE',
	EN = 'EN',
	FR = 'FR',
	ES = 'ES',
	PT = 'PT',
}

@Entity({ collection: 'Translation' })
class Translation extends BaseEntity {
	[OptionalProps]?: 'createdAt' | 'updatedAt'

	@Enum({ items: () => LOCALE, type: 'LOCALE' })
	locale!: LOCALE

	@Property({ columnType: 'text', type: 'string' })
	text!: string

	@ManyToOne({
		entity: () => Trait,
		fieldName: 'trait',
		onDelete: 'cascade',
		nullable: true,
	})
	trait?: Trait

	@ManyToOne({
		entity: () => Trait,
		fieldName: 'traitDescription',
		onDelete: 'cascade',
		nullable: true,
	})
	traitDescription?: Trait
}

async function pseudoGraphQL() {
	const traits = await em.find(Trait, {})

	const getTranslation = async (parent: Trait) => {
		await em.populate(parent, ['translations'])

		const translation = parent.translations
			.getItems()
			.find(({ locale }) => locale === 'EN')

		return translation?.text
	}

	const getDescription = async (parent: Trait) => {
		await em.populate(parent, ['descriptions'])

		const description = parent.descriptions
			.getItems()
			.find(({ locale }) => locale === 'EN')

		return description?.text
	}

	await Promise.all(
		traits.map(traits => {
			return Promise.all([getTranslation(traits), getDescription(traits)])
		})
	)
}

1:1

@Entity({ collection: 'Company' })
class Company extends BaseEntity {
        [OptionalProps]?: 'createdAt' | 'updatedAt'

	@OneToOne({ entity: 'Image', mappedBy: 'companyLogo' })
	logo!: Image

	@OneToOne({ entity: 'Image', mappedBy: 'companyImage' })
	image!: Image
}

@Entity({ collection: 'Image' })
class Image extends BaseEntity {
	[OptionalProps]?: 'createdAt' | 'updatedAt'

	@Property({ columnType: 'text', type: 'string' })
	url!: string

	@OneToOne({ entity: 'Company', nullable: true, onDelete: 'cascade' })
	companyLogo?: Company

	@OneToOne({ entity: 'Company', nullable: true, onDelete: 'cascade' })
	companyImage?: Company
}

async function pseudoGraphQL() {
	const companies = await em.find(Company, {})

	const getLogo = async (parent: Company) => {
		await em.populate(parent, ['logo'])
		if (!parent.logo) {
			throw new Error(
				'Cannot return null for non-nullable field Company.logo'
			)
		}
		return parent.logo
	}

	const getImage = async (parent: Company) => {
		await em.populate(parent, ['image'])
		if (!parent.image) {
			throw new Error(
				'Cannot return null for non-nullable field Company.image'
			)
		}
		return parent.image
	}

	await Promise.all(
		companies.map(company => {
			return Promise.all([getLogo(company), getImage(company)])
		})
	)
}

Expected behavior
Calling em.populate does not result in a property being undefined

Additional context
One thing that comes to my mind is that for both these cases entities are connected twice through different fields:

      <--(logo)--> Image
Company
      <--(image)--> Image



      <--(translations)--> Translation[]
Trait
      <--(descriptions)--> Translation[]

Versions

Dependency	Version
node	16.16.0
typescript	4.4.4
mikro-orm	5.3.1
postgresql	5.3.1

[B4nan]

Well, using Promise.all on single EM instance is never good idea if you ask me. You are working with a single context in parallel, this will introduce race conditions.

[wasd171]

What would be the proper way to query data with mikro-orm in GraphQL then? For us the current logic is that em is forked for every request via RequestContext.create and then GraphQL fields are resolved as a cascade using the same em. We do not use Promise.all directly, but I believe that under the hood GraphQL server does something similar, I think that this is the same as code in one of the integration examples: https://github.com/driescroons/mikro-orm-graphql-example/blob/master/src/resolvers/author.resolver.ts

[wasd171]

I guess we could fork em for every field but then we will be constantly overfetching from the db...

[wasd171]

As a note the issue is specifically with em.populate, so when we do

async function pseudoGraphQL() {
	const { em } = getRegistry()
	const companies = await em.find(Company, {})

	const getLogo = async (parent: Company) => {
		const logo = await em.findOneOrFail(Image, {
			companyLogo: parent,
		})

		return logo
	}

	const getImage = async (parent: Company) => {
		const image = await em.findOneOrFail(Image, {
			companyImage: parent,
		})

		return image
	}

	await Promise.all(
		companies.map(company => {
			return Promise.all([getLogo(company), getImage(company)])
		})
	)
}

^ everything works as expected

[B4nan]

I will need to review this first, maybe its something stupid we can fix. I believe the read operations should be rather fine with Promise.all but that does not mean I like it :]

Can't help with GQL, not my cup of tea.

edit: But I know there is one extension you can use to generate nested populate definition for GQL query or something like that. Not sure how up to date is that or whether there are better solutions.

https://github.com/driescroons/graphql-fields-to-relations

Also be sure to check this discussion:

#2212

[wasd171]

But I know there is one extension you can use to generate nested populate definition for GQL query or something like that. Not sure how up to date is that or whether there are better solutions.

We were looking at recreating something similar for ourselves, but I think that we still had issues:

const companies = await em.find(Company, {}, {populate: ['logo', 'image']})
...
await em.populate(parent, ['logo']) <- because we cannot guarantee path and field might not be loaded yet
parent.logo is undefined

[B4nan]

I am not following, what issues? em.populate ignores already loaded relations. This would be problem only with partial loading - you can't really lazy load 1:1 owner if you did not let the ORM fetch its PK.

[wasd171]

Let me put #3383 (comment) in production to verify again, but I think somehow even though on the top level we were pre-populating the fields children could not get access to them, so in my example parent.logo was undefined, even though it was previously pre-populated via em.find(Company, {}, {populate: ['logo']})

[B4nan]

Then are you really sure there is a value in the database? :] But it should be null in that case I guess, not undefined. undefine sounds more like an ommision via partial loading to me.

[B4nan]

Can you update the repro so it creates some inital data too? And maybe run things multiple times to catch the error?

[B4nan]

I could imagine a race condition where the entity gets added to identity map before it is hydrated - but we need that, not much we can do here. And creating entity is sync, so its weird anyway.

[wasd171]

I am pretty sure that data is in the database :)
When fetching with em.findOneOrFail(Image, {companyLogo: parent.id}) everything work as expected
I can confirm what I wrote in #3383 (comment): pre-populating em.find(Company, {}, ['logo', 'image']) and calling em.populate(parent, ['logo']) causes parent.logo to be undefined.

I still cannot replicate it in the test case, I'll try to assemble a closer-resembling one with GraphQL API, fastify, etc...

Is there any debug info that I could collect on production to help with resolving this?

[jbmikk]

This is happening to me to. It's been happening for a while.
My solution is very similar, I fork for each request, then everything in the request is handled by that single EM.

I haven't reported it yet because I wasn't able to put together a reproduction for the bug, a didn't have time to do it anyway.
I use both GQL and also Promise.all() to fetch things in parallel because it's faster than fetching sequentially.
This is only for reads, all mutations are left to the EM with either flush() or transactional() handling them.
So far I haven't had a single problem except for one specific query where I use both populate: [] and nested where conditions. The error does not always happen, but when it does it happens on that specific query. I have to check that specific populated attribute for null values and force a em.findOneOrFail() when it's not loaded because load() just fails.

By the way, this only started happening to me after moving from v4 to v5 (I don't remember the exact versions). Before that the same code worked well.

I'll try to provide a way of reproducing this when I have time.

[B4nan]

Tried to reproduce based on the code in OP. Ran the final part 10000 times in a row, havent seen that error single time 🤷

Not much I can do without (at least sometimes) failing repro.

Here is what I tried, maybe you can make it fail :]

import { Collection, Entity, Enum, ManyToOne, MikroORM, OneToMany, OptionalProps, PrimaryKey, Property } from '@mikro-orm/core';
import type { SqliteDriver } from '@mikro-orm/sqlite';
import { randomUUID } from 'node:crypto';

abstract class BaseEntity {

  @PrimaryKey({ length: 25, type: 'string' })
  id = randomUUID();

  @Property({
    type: 'Date',
    fieldName: 'createdAt',
  })
  createdAt = new Date();

  @Property({
    type: 'Date',
    fieldName: 'updatedAt',
    onUpdate: () => new Date(),
  })
  updatedAt = new Date();

}

@Entity({ collection: 'Trait' })
class Trait extends BaseEntity {

  [OptionalProps]?: 'createdAt' | 'updatedAt';

  @OneToMany({ entity: 'Translation', mappedBy: 'trait' })
  translations = new Collection<Translation>(this);

  @OneToMany({ entity: 'Translation', mappedBy: 'traitDescription' })
  descriptions = new Collection<Translation>(this);

}

enum LOCALE {
  DE = 'DE',
  EN = 'EN',
  FR = 'FR',
  ES = 'ES',
  PT = 'PT',
}

@Entity({ collection: 'Translation' })
class Translation extends BaseEntity {

  [OptionalProps]?: 'createdAt' | 'updatedAt';

  @Enum({ items: () => LOCALE, type: 'LOCALE' })
  locale!: LOCALE;

  @Property({ columnType: 'text', type: 'string' })
  text!: string;

  @ManyToOne({
    entity: () => Trait,
    fieldName: 'trait',
    onDelete: 'cascade',
    nullable: true,
  })
  trait?: Trait;

  @ManyToOne({
    entity: () => Trait,
    fieldName: 'traitDescription',
    onDelete: 'cascade',
    nullable: true,
  })
  traitDescription?: Trait;

}

describe('GH issue 3383', () => {

  let orm: MikroORM<SqliteDriver>;

  beforeAll(async () => {
    orm = await MikroORM.init({
      entities: [Translation],
      dbName: ':memory:',
      type: 'sqlite',
    });
    await orm.getSchemaGenerator().createSchema();
  });

  afterAll(async () => {
    await orm.close(true);
  });

  test(`GH issue 3383`, async () => {
    const t = orm.em.create(Trait, {
      descriptions: [
        { locale: LOCALE.EN, text: 'descr ENENENEN' },
        { locale: LOCALE.ES, text: 'descr ESESESES' },
        { locale: LOCALE.DE, text: 'descr DEDEDEDE' },
      ],
      translations: [
        { locale: LOCALE.EN, text: 'trans ENENENEN' },
        { locale: LOCALE.ES, text: 'trans ESESESES' },
        { locale: LOCALE.DE, text: 'trans DEDEDEDE' },
      ],
    });
    await orm.em.persist(t).flush();
    orm.em.clear();

    const getTranslation = async (parent: Trait) => {
      await orm.em.populate(parent, ['translations']);

      const translation = parent.translations
        .getItems()
        .find(({ locale }) => locale === 'EN');

      return translation?.text;
    };

    const getDescription = async (parent: Trait) => {
      await orm.em.populate(parent, ['descriptions']);

      const description = parent.descriptions
        .getItems()
        .find(({ locale }) => locale === 'EN');

      return description?.text;
    };

    for (let i = 1; i <= 10000; i++) {
      const traits = await orm.em.find(Trait, {});

      await Promise.all(traits.map(traits => {
          return Promise.all([getTranslation(traits), getDescription(traits)]);
      }));

      orm.em.clear();
    }
  });

});

[wasd171]

I will try to provide a better (failing) example, but one thing to note is that most likely you will not be able to replicate it with sqlite as a database since Knex.js only opens 1 connection to it instead of using pooling (which we have for PostgreSQL)

[B4nan]

Let me try with postgres, but I dont think this is about pooling, it needs to be a race in hydrating the entity which happens at ORM level.

edit: same with postgres as expected

[wasd171]

In the meantime do you think we can provide any useful debug info from our prod environment? I could install some patched version of mikro-orm if needed

[B4nan]

Cannot read properties of undefined (reading 'getItems') <- happens to 1:M / M:N relations

Where is that coming from, is it your code (as in the repro in OP) or something called by the ORM (e.g. serialization)?

I am having hard times believing that em.populate() could wipe existing entity property, especially a collection. Trying to think of a place where that could happen but the only case is when the entity is created without it, not that em.populate() would remove it. So maybe try to ensure this is really about em.populate and not about malformed entity you are passing in.

[B4nan]

This is the place where we conditionally add incomplete entities to the identity map so we can resolve cycles, that would be my first suspect.

https://github.com/mikro-orm/mikro-orm/blob/master/packages/core/src/entity/EntityFactory.ts#L209-L212

[B4nan]

I am not 100% sure if/how this is related, but there is one flaky test that is doing upserts without explicit transaction (which is in general bad idea, but should be doable from the ORM point of view), and contains a race condition in flushing new entities. The consequtive flush via Promise.all can end up with computing changesets from the same state before persisting them, resulting in duplicate insert queries.

I will try to implement some simple locking on the internal entity state object to get around it, probably also in the entity creation part which might help with this issue - would be great if you could use the dev version once its there to see if it helps. Will keep you posted.

[wasd171]

Would be happy to test the dev version to assist

[B4nan]

It looks like I discovered another problem when debugging this. I turned that flaky test into a heavy load test - doing ~1 million requests totally, using 50 entities via Promise.all each time, this way it consistently reproduces the issues with locking. It runs around 10 minutes, and it sometimes fails with a knex connection error (tx already complete). It turns out it is probably caused by making the UoW usable again (via this.working = false here), which is needed for afterFlush hook to work properly...

And the weirdest part? When I comment that problematic line, all tests are passing, including the #3005 issue test that was added together with that change. I guess it got fixed by something else (might be even a dependency update). Will ship this and let's see, worst case I will revert it 🤷

b62799a

[B4nan]

@wasd171 also, have you verified what I was asking for above? Whether the issue is coming from em.populate(), or if the property was undefined before you call it? As I mentioned, I dont really see a way how em.populate would wipe any property, I would expect this to be coming from EntityFactory or hydration layers, so before em.populate() is actually called.

[wasd171]

@B4nan I have added a check in the code to see whether field existed pre- and post-populate, will update you tomorrow

[wasd171]

@B4nan so far our logs show the following:

const [companies, count] = await em.findAndCount(Company, where, {
  limit,
  orderBy,
  populate: ['logo', 'image'],
})
^ not sure what state is at this point but can add logs to check
...
later in the resolver
...
let logo: Image = parent.logo
console.log(typeof logo) <-- undefined
await em.populate(parent, ['logo'])
logo = parent.logo
console.log(typeof logo) <-- undefined
if (!logo) {
  logo = await em.findOneOrFail(Image, {
    companyLogo: parent.id,
  })
  ^ successfully fetches entity
}

Same happens (via a different path) when we do not pre-populate image / logo

[wasd171]

I've added more logs to check for .logo and .image immediately after em.findAndCount and sometimes those are also undefined :(

[B4nan]

those are also undefined :(

also or always? i dont see how em.populate could wipe anything, i would expect it to be coming from the factory all the time, not just sometimes. it would be better to remove the populate hint and check that output first before populating relations.

Are you using the default select in loading strategy?

[wasd171]

also or always?

I am not sure I am following the question.

Does it happen for every request: no, but sometimes it does. Error on the field resolver level (em.populate) happens more often (I guess because we generally do more parallel requests there) than on the query level (em.findAndCount).

Does an error on the query level always imply an error on the resolver level? Yes, so far it looks like it. In case after em.findAndCount fields were not populated, field resolver em.populate also does not populate them

const [companies, count] = await em.findAndCount(Company, where, {
	limit,
	orderBy: { [orderingKey]: QueryOrder.ASC },
	populate: ['logo', 'image'],
})

let hasLogo = true
let hasImage = true
for (const { logo, image } of companies) {
	if (!logo) {
		hasLogo = false
	}
	if (!image) {
		hasImage = false
	}
}
if (!hasLogo || !hasImage) {
	sentry.withScope(scope => {
		scope.setExtras({
			hasLogo,
			hasImage,
		})

		sentry.captureException(
			new Error(
				`Company.logo/image were not found immediately after populate`
			)
		)
	})
}

it would be better to remove the populate hint and check that output first before populating relations.

Not sure exactly what you mean but I think that this is something that I am doing in the example above

Are you using the default select in loading strategy?

I am using joined strategy but open to try default one

[wasd171]

We do not use em.fork directly but rather do

fastify.addHook('onRequest', (_req, _res, done) => {
	RequestContext.create(orm.em, done)
})

Could it be that ems are somehow leaking between requests and this is what causes (potentially) race condition?

[B4nan]

Error on the field resolver level (em.populate)

My point is that to me this all sounds like the problem is not in em.populate as you say. You just try to pass undefined inside it - the value on the entity instance before you call em.populate was wrong, not something in how em.populate works.

The thing is, you cant expect em.populate(foo, ['bar']) to do something if foo.bar is already undefined - that is not how it works, there needs to be a reference already managed by the EM, that should be initialized by the populate call.

Not sure exactly what you mean but I think that this is something that I am doing in the example above

You do em.find(..., { populate: ['foo'] }), that means find entities and populate their foo relation. I ask you to do it without the populate option, check the entities first, and then call em.populate(). That is pretty much the same as how it works internally, you will just be able to see the intermediate state - which I believe is where things get broken.

I am using joined strategy but open to try default one

Now that is a very important detail that was not present in the repro nor in your OP.

Could it be that ems are somehow leaking between requests and this is what causes (potentially) race condition?

I dont think so.

[wasd171]

You do em.find(..., { populate: ['foo'] }), that means find entities and populate their foo relation. I ask you to do it without the populate option, check the entities first, and then call em.populate(). That is pretty much the same as how it works internally, you will just be able to see the intermediate state - which I believe is where things get broken.

If I understand you correctly, I've added this snippet to check, will update you when I have more data

const [companies, count] = await em.findAndCount(Company, where, {
	limit,
	orderBy: { [orderingKey]: QueryOrder.ASC },
})

let hasLogoBefore = true
let hasImageBefore = true
let hasLogoAfter = true
let hasImageAfter = true
for (const company of companies) {
	if (!company.logo) {
		hasLogoBefore = false
	}
	if (!company.image) {
		hasImageBefore = false
	}

	await em.populate(company, ['logo', 'image'])

	if (!company.logo) {
		hasLogoAfter = false
	}
	if (!company.image) {
		hasImageAfter = false
	}
}
if (
	!hasLogoBefore ||
	!hasImageBefore ||
	!hasLogoAfter ||
	!hasImageAfter
) {
	sentry.withScope(scope => {
		scope.setExtras({
			hasLogoBefore,
			hasImageBefore,
			hasLogoAfter,
			hasImageAfter,
		})

		sentry.captureException(
			new Error(
				`Company.logo/image were not found immediately after populate`
			)
		)
	})
}

But I think you are right, most likely the property was already undefined. It is even easier to see in the 1:N / M:N case from my first message:

const getTranslation = async (parent: Trait) => {
  await em.populate(parent, ['translations'])

  const translation = parent.translations
	.getItems()
	.find(({ locale }) => locale === 'EN')

  return translation?.text
}
^ throws
Cannot read properties of undefined (reading 'getItems')

Even non-populated collections should always be defined, right?

Now that is a very important detail that was not present in the repro nor in your OP.

Sorry about that, I did not add it because I think it broke for us in the same fashion a few months ago when using the default select in strategy. I have changed our strategy to select in and now I do not see this issue anymore

[B4nan]

Even non-populated collections should always be defined, right?

For initialized/loaded entities yes, for entity references (not initialized entities) - nope, there it can/should be undefined, as those should only have the PK set.

I think it broke for us in the same fashion a few months ago when using the default select in strategy

Ok, like I can still imagine it won't matter, if its caused by some race condition in hydration. I see the build got broken and my fix I was referring to above is not yet published, will try to do something about that so you can also fix it.

[wasd171]

I already got first logs from #3383 (comment) with JOINED strategy and was able to catch a case of

hasImageAfter === false
hasImageBefore === false
hasLogoAfter === false
hasLogoBefore === false

[B4nan]

The loading strategy wont matter without the populate hint (em.populate is always using select-in method), so this only confirms its a general issue.

Ok so my hunch was correct. I just fixed the build in master, so please the new dev version (dev 19).

[wasd171]

Unfortunately I can still reproduce this behaviour #3383 (comment) on 5.3.2-dev.19

[B4nan]

I am quite sure that you will be able to reproduce this (as long as you actually have the parts responsible for breaking it, not like in the repro from OP), the same way as I did - repeating the test for e.g. 10000 times.

I am affraid I can't help much more without any reproduciton. Let's try to deliver that instead of debugging your production app, as that might only help you to understand it, not me to fix it :]

[B4nan]

I will close this, without some repro its not actionable.