Pre save hook called twice during jest testing #61

JakeAi · 2020-01-31T20:39:48Z

I have been trying to track down this issue all day and cannot figure out what is going on. I have a simple service with a register function. My automated login after registration test keeps failing. I found it's because the pre-save hook gets called twice and re-hashes the hashed password. This behavior does not happen during normal operation... only under jest testing.

This code produces the console log at the bottom.

@pre<User>('save', function(next) {
	try {
		console.trace();
		if (this.isModified('password')) {
			const salt = genSaltSync(10);
			this.password = hashSync(this.password, salt);
			console.log(this.password, this.isModified('password'));
		}
		next();
	} catch (error) {
		next();
	}
})

		console.log('before new');
		const newUser = new this.userModel(data);
		console.log(newUser);
		console.log('new');
		newUser.claims.concat(claims || []);
		newUser.agreements.concat(agreements || []);
		console.log('before validate');
		await newUser.validate();
		console.log('validate');
		console.log('before save');
		await newUser.save();
		console.log('save');

  console.log src/app/modules/sso.module/sso.service.ts:66
    new

  console.log src/app/modules/sso.module/sso.service.ts:69
    before validate

  console.log src/app/modules/sso.module/sso.service.ts:71
    validate

  console.log src/app/modules/sso.module/sso.service.ts:72
    before save

  console.error internal/console/constructor.js:334
    Trace: 
        at model.<anonymous> (E:\Development\Node\mm-mono\libs\api\models\user.model.ts:9:11)
        at callMiddlewareFunction (E:\Development\Node\mm-mono\node_modules\kareem\index.js:482:23)
        at model.next (E:\Development\Node\mm-mono\node_modules\kareem\index.js:58:7)
        at _next (E:\Development\Node\mm-mono\node_modules\kareem\index.js:106:10)
        at E:\Development\Node\mm-mono\node_modules\kareem\index.js:507:38
        at processTicksAndRejections (internal/process/task_queues.js:75:11)

  console.log ../../libs/api/models/user.model.ts:13
    $2a$10$l.vp7u7hBdA1JtHr8h2P5OcA9t/Oq1mnVBB7OKDWMJ786tdUAhsxG true

  console.error internal/console/constructor.js:334
    Trace: 
        at model.<anonymous> (E:\Development\Node\mm-mono\libs\api\models\user.model.ts:9:11)
        at callMiddlewareFunction (E:\Development\Node\mm-mono\node_modules\kareem\index.js:482:23)
        at model.next (E:\Development\Node\mm-mono\node_modules\kareem\index.js:58:7)
        at _next (E:\Development\Node\mm-mono\node_modules\kareem\index.js:106:10)
        at E:\Development\Node\mm-mono\node_modules\kareem\index.js:507:38
        at processTicksAndRejections (internal/process/task_queues.js:75:11)

  console.log ../../libs/api/models/user.model.ts:13
    $2a$10$fbPEr0dK3AEk74YT5nQZK.7WWOWB1.4zogJrlY2tRKl1VwNHNzQ/K true

  console.log src/app/modules/sso.module/sso.service.ts:74
    save

The text was updated successfully, but these errors were encountered:

hasezoey · 2020-01-31T20:55:48Z

could you provide an reproduction repository?

JakeAi · 2020-02-02T04:13:58Z

@hasezoey https://github.com/JakeAi/nestjs-typegoose-pre-hook

Run the app with ng serve mm-n-api

Add a mongodb connection string in test.modules.ts

In sso.module.spec.ts you will see two lines

TypegooseModule.forFeature([User,PasswordToken]), // breaks test, calls user pre hook twice
// TypegooseModule.forFeature([User]), // doesnt break test, DOESNT call pre hook twice

hasezoey · 2020-02-02T04:21:20Z

@JakeAi your repo does not exists ("Page Not Found / 404")

JakeAi · 2020-02-02T04:24:29Z

@hasezoey my bad, my stuff defaults to private. Try it now.

hasezoey · 2020-02-02T04:37:18Z

@JakeAi i ran it, but it dosnt seem to be the tests (it started the app), but as i read, it is about the tests, right?

JakeAi · 2020-02-02T04:38:03Z

Oops, yes. The sso.module.spec.ts is ran with jest.

hasezoey · 2020-02-02T04:38:38Z

@JakeAi any specific command or just jest sso.module.spec.ts?

hasezoey · 2020-02-02T04:40:34Z

as general notes: for the connection options you specified already-default values and incompatible options (the options autoReconnect, reconnectTries and reconnectInterval are incompatible with useUnifiedTopology) and i upgraded typegoose, mongoose and types-mongoose just to be sure

JakeAi · 2020-02-02T04:42:56Z

@JakeAi any specific command or just jest sso.module.spec.ts?

I just added a missing jest.config file. I use webstorm to run the tests so I'm not sure what it actually runs. I believe I removed those options in my original project, but when I cloned it I must not've cloned the latest.

hasezoey · 2020-02-02T04:47:56Z

i executed your example with the mentioned edits, and i can not see the hook being executed twice
executed with jest / jest --watch in the repo-root folder

JakeAi · 2020-02-02T04:48:16Z

Jest sso.module.spec.ts produces the same results as webstorm for me.

hasezoey · 2020-02-02T04:51:08Z

0001-WIP.patch.txt (.txt added, because github dosnt allow .patch)
this patch includes all my changes made, apply it with git am < 0001-WIP.patch.txt (if on linux / macos)

JakeAi · 2020-02-02T05:00:36Z

This is with your patch

  console.warn node_modules/mongoose/lib/helpers/printJestWarning.js:4
    Mongoose: looks like you're trying to test a Mongoose app with Jest's default jsdom test environment. Please make sure you read Mongoose's docs on configuring Jest to test Node.js apps: http://mongoosejs.com/docs/jest.html

  console.log node_modules/@typegoose/typegoose/lib/prop.js:30
    Added "User.email" to the Decorator Cache

  console.log node_modules/@typegoose/typegoose/lib/prop.js:30
    Added "User.password" to the Decorator Cache

  console.log node_modules/@typegoose/typegoose/lib/prop.js:30
    Added "PasswordToken.user" to the Decorator Cache

  console.log node_modules/@typegoose/typegoose/lib/prop.js:30
    Added "User.email" to the Decorator Cache

  console.log node_modules/@typegoose/typegoose/lib/prop.js:30
    Added "User.password" to the Decorator Cache

  console.info node_modules/@typegoose/typegoose/lib/internal/utils.js:446
    Assigning global Schema Options to "User"

  console.log node_modules/@typegoose/typegoose/lib/internal/schema.js:28
    _buildSchema Called for User with options: {}

  console.log node_modules/@typegoose/typegoose/lib/prop.js:41
    Starting to process "User.email"

  console.log node_modules/@typegoose/typegoose/lib/prop.js:41
    Starting to process "User.password"

  console.info node_modules/@typegoose/typegoose/lib/typegoose.js:181
    Class "User" already existed in the constructors Map

  console.info node_modules/@typegoose/typegoose/lib/internal/utils.js:446
    Assigning global Schema Options to "PasswordToken"

  console.log node_modules/@typegoose/typegoose/lib/internal/schema.js:28
    _buildSchema Called for PasswordToken with options: {}

  console.log node_modules/@typegoose/typegoose/lib/prop.js:41
    Starting to process "PasswordToken.user"

  console.log node_modules/@typegoose/typegoose/lib/internal/schema.js:73
    Applying Index: { fields: { createdAt: 1 },
      options: { expireAfterSeconds: 7200 } }

  console.info node_modules/@typegoose/typegoose/lib/typegoose.js:181
    Class "PasswordToken" already existed in the constructors Map

  console.log apps/mm-n-api/src/app/modules/sso.module/sso.service.ts:23
    before new

  console.log apps/mm-n-api/src/app/modules/sso.module/sso.service.ts:25
    { _id: 5e365736d63a3471b1b45709,
      email: 'testuser@test.com',
      password: 'Test' }

  console.log apps/mm-n-api/src/app/modules/sso.module/sso.service.ts:26
    new

  console.log apps/mm-n-api/src/app/modules/sso.module/sso.service.ts:27
    before validate

  console.log apps/mm-n-api/src/app/modules/sso.module/sso.service.ts:29
    validate

  console.log apps/mm-n-api/src/app/modules/sso.module/sso.service.ts:30
    before save

  console.log libs/api/models/user.model.ts:12
    $2a$10$765hBdjD0.rXStUflPh0ZOEHNVmIWKUYxgvpyDibL3NHiTEMctcim $2a$10$765hBdjD0.rXStUflPh0ZOEHNVmIWKUYxgvpyDibL3NHiTEMctcim

  console.log libs/api/models/user.model.ts:12
    $2a$10$TsEF5GjbxsMZxvheStc5Oua5TELUhDFrwRsbFghPjFGu.tOQWDCRq $2a$10$TsEF5GjbxsMZxvheStc5Oua5TELUhDFrwRsbFghPjFGu.tOQWDCRq

  console.log apps/mm-n-api/src/app/modules/sso.module/sso.service.ts:32
    save

  console.log apps/mm-n-api/src/app/modules/sso.module/sso.module.spec.ts:96
    { statusCode: 401, error: 'Unauthorized' }


Error: expected 200 "OK", got 401 "Unauthorized"

hasezoey · 2020-02-02T05:07:05Z

@JakeAi now it is appearing too, but when i sent this patch, it was execution just fine

hasezoey · 2020-02-02T05:08:51Z

now i executed it with jest --watch / jest --watchAll and it just runs fine, and when just using jest (run once) it fails, uh what

JakeAi · 2020-02-02T05:09:13Z

It happens on both my macbook and windows :(

JakeAi · 2020-02-02T05:10:31Z

Is it a race condition or something somewhere? So, I wonder... if in production I may or may not notice it, but since I'm running tests ( I JUST switched to nest this week and started porting my express to nest ) I am noticing it because I'm running the test constantly...

hasezoey · 2020-02-02T05:11:15Z

i will look more into it tomorrow

JakeAi · 2020-02-02T05:15:05Z

Now I'm getting it to happen regardless of those two lines I comment and uncomment. Sounds good, thanks @hasezoey

Must be solar flares

hasezoey · 2020-02-02T16:44:39Z

@JakeAi i investigated a bit, and it seems should respond 200 with jwtAccessToken is dependent on should succeed with HTTP 201 Created (to have the user created) maybe this is your race condition?

JakeAi · 2020-02-02T17:06:08Z

But why does the hook call twice?

JakeAi · 2020-02-02T17:09:21Z

This part means it’s called twice. It takes the password, hashes it, then takes the hashed password and hashes it again. Then saves.

console.log apps/mm-n-api/src/app/modules/sso.module/sso.service.ts:30
    before save

  console.log libs/api/models/user.model.ts:12
    $2a$10$765hBdjD0.rXStUflPh0ZOEHNVmIWKUYxgvpyDibL3NHiTEMctcim $2a$10$765hBdjD0.rXStUflPh0ZOEHNVmIWKUYxgvpyDibL3NHiTEMctcim

  console.log libs/api/models/user.model.ts:12
    $2a$10$TsEF5GjbxsMZxvheStc5Oua5TELUhDFrwRsbFghPjFGu.tOQWDCRq $2a$10$TsEF5GjbxsMZxvheStc5Oua5TELUhDFrwRsbFghPjFGu.tOQWDCRq

  console.log apps/mm-n-api/src/app/modules/sso.module/sso.service.ts:32
    save

JakeAi · 2020-02-02T17:20:19Z

Sometimes it works but most of the time it’s hashes twice for me. Is there anything else I can do to log on my end?

hasezoey · 2020-02-02T17:38:14Z

as to why it gets called twice? it is added twice - still need to figure out why any where

hasezoey · 2020-02-02T17:59:29Z

i found the reason on why it is added twice: it is once added to the typegoose maps when the file User is in is imported, and once when it is added in the ref of PasswordToken - i dont really understand why it gets executed again (all the decorators) and the reason it is happening to the hooks and not the properties is because the properties are already on the class, while the hooks are currently on an special map (typegoose/typegoose#44), but i still dont understand why all the hooks get called again

Update: it somehow gets imported twice, which resets the User class (all @prop generated things) but because the hooks are not in the class, it dosnt get reset
-> and i cant get good stack-traces because it only gives me weird ones (like Runtime._execModule)

JakeAi · 2020-02-02T18:24:31Z

@hasezoey My buddy said

the problem is with jest's ts-node transpiler, it loads user.model.ts twice causing the hook to be added twice

Do you get the hash twice like I posted?

yeah, until i compiled it all to js and ran it as js. it's because of ts-node. or the way jest uses ts-node. because the only reason it would run twice logically, is if the hook was added twice. which means the module got executed twice. since it's transpiled in real time i figured it was jest/ts-node

change jest.config.js to:

module.exports = {
    preset: 'ts-jest',
    testEnvironment: 'node',
    moduleNameMapper: {
        "^@mm-mono(.*)": "<rootDir>/libs$1"
    }
};

hasezoey · 2020-02-02T18:36:32Z

after adding moduleNameMapper do? because after adding this, everything runs fine (but still the race condition between tests)

hasezoey · 2020-02-02T18:37:42Z

so i would consider this issue as "not an problem with nestjs-typegoose and typegoose" (except maybe the the mention issue that hooks are still specially handled)

JakeAi · 2020-02-02T18:39:42Z

The moduleNameMapper seems to be the ticket from what i can tell. I'm not concerned about the order of tests are ran in, that's a different animal. The race condition I was talking about (why it was being inconsistent) was just MAYBE something deep within nestjs-typegoose, but apparently not.

hasezoey · 2020-02-02T18:42:16Z

The race condition I was talking about (why it was being inconsistent) was just MAYBE something deep within nestjs-typegoose, but apparently not.

yes, but i meant when you do something like execute the suite case Login After Registration alone, it will still fail because it is missing the setup from should succeed with HTTP 201 Created - that was just an general note

JakeAi · 2020-02-02T18:43:50Z

Oh, yeah. That's fine. I had JUST started porting my express code when this issue came up. I also was coming from a testless environment.

hasezoey · 2020-02-02T18:44:34Z

@JakeAi so is this issue finished? or should it be kept open?

PS: happy porting :)

JakeAi · 2020-02-02T18:45:57Z

I'd say it's finished... because the original jest config came from https://nx.dev/. Unless maybe there is a more recommended jest config approach?

hasezoey · 2020-02-02T18:48:00Z

Unless maybe there is a more recommended jest config approach?

not that i know of

JakeAi · 2020-02-02T19:44:09Z

@hasezoey I created an issue where it needs to be fixed. And I referenced this issue for information.

JakeAi closed this as completed Feb 2, 2020

JakeAi mentioned this issue Feb 2, 2020

Jest Resolver Plugin Doesn't Return Full Path nrwl/nx#2418

Closed

Pre save hook called twice during jest testing #61

Pre save hook called twice during jest testing #61

Comments

JakeAi commented Jan 31, 2020 • edited Loading

hasezoey commented Jan 31, 2020

JakeAi commented Feb 2, 2020 • edited Loading

hasezoey commented Feb 2, 2020

JakeAi commented Feb 2, 2020

hasezoey commented Feb 2, 2020

JakeAi commented Feb 2, 2020

hasezoey commented Feb 2, 2020

hasezoey commented Feb 2, 2020

JakeAi commented Feb 2, 2020

hasezoey commented Feb 2, 2020 • edited Loading

JakeAi commented Feb 2, 2020

hasezoey commented Feb 2, 2020 • edited Loading

JakeAi commented Feb 2, 2020

hasezoey commented Feb 2, 2020

hasezoey commented Feb 2, 2020 • edited Loading

JakeAi commented Feb 2, 2020

JakeAi commented Feb 2, 2020

hasezoey commented Feb 2, 2020

JakeAi commented Feb 2, 2020

hasezoey commented Feb 2, 2020 • edited Loading

JakeAi commented Feb 2, 2020

JakeAi commented Feb 2, 2020

JakeAi commented Feb 2, 2020

hasezoey commented Feb 2, 2020

hasezoey commented Feb 2, 2020 • edited Loading

JakeAi commented Feb 2, 2020 • edited Loading

hasezoey commented Feb 2, 2020

hasezoey commented Feb 2, 2020

JakeAi commented Feb 2, 2020

hasezoey commented Feb 2, 2020

JakeAi commented Feb 2, 2020

hasezoey commented Feb 2, 2020

JakeAi commented Feb 2, 2020

hasezoey commented Feb 2, 2020

JakeAi commented Feb 2, 2020

JakeAi commented Jan 31, 2020 •

edited

Loading

JakeAi commented Feb 2, 2020 •

edited

Loading

hasezoey commented Feb 2, 2020 •

edited

Loading

hasezoey commented Feb 2, 2020 •

edited

Loading

hasezoey commented Feb 2, 2020 •

edited

Loading

hasezoey commented Feb 2, 2020 •

edited

Loading

hasezoey commented Feb 2, 2020 •

edited

Loading

JakeAi commented Feb 2, 2020 •

edited

Loading