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

fix(WorkerPool): trace stacks to avoid duplicated err.messages from workers #13

Merged
merged 8 commits into from
Feb 7, 2018

Conversation

sendilkumarn
Copy link
Contributor

No description provided.

@jsf-clabot
Copy link

jsf-clabot commented Jan 19, 2018

CLA assistant check
All committers have signed the CLA.

@codecov
Copy link

codecov bot commented Jan 19, 2018

Codecov Report

Merging #13 into master will not change coverage.
The diff coverage is 0%.

Impacted file tree graph

@@         Coverage Diff          @@
##           master   #13   +/-   ##
====================================
  Coverage       0%    0%           
====================================
  Files           6     7    +1     
  Lines         359   371   +12     
  Branches       63    64    +1     
====================================
- Misses        314   325   +11     
- Partials       45    46    +1
Impacted Files Coverage Δ
src/WorkerError.js 0% <0%> (ø)
src/WorkerPool.js 0% <0%> (ø) ⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 92c42e5...ce61e12. Read the comment docs.

@sendilkumarn sendilkumarn changed the title Adding addtional option stack to control the stack when there is an erroe Adding addtional option stack to control the stack when there is an error Jan 19, 2018
Copy link
Member

@michael-ciniawsky michael-ciniawsky left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@sendilkumarn Could you post a screenshot of current output you get (for reference) ?

@@ -11,6 +11,7 @@ let workerId = 0;

class PoolWorker {
constructor(options, onJobDone) {
this.options = options;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is this needed or would using options directly also be sufficient ?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I feel this is better and aligns to the style

@@ -186,7 +187,11 @@ class PoolWorker {
const err = new Error(obj.message);
err.message = obj.message;
if (obj.stack) {
err.stack = `${obj.stack}\n\tfrom thread-loader (worker ${this.id})\n${err.stack}`;
let additionalStack = '';
Copy link
Member

@michael-ciniawsky michael-ciniawsky Jan 19, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

err.stack = `${obj.stack}\n\nThread Loader (Worker ${this.id})`

if (this.options.stack) {
  // Limit the err.stack manually in case stackTraces are to verbose
  if (typeof options.stack === 'number')
    Error.stackTraceLimit(options.stack)
  }

  err.stack += `\n\n${err.stack}`
} else {
  // Only the err.message
  const message = (stack) => stack.split('\n')[0]

  err.stack += `\n\n${message(err.stack)}`
}

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I like this idea. the stacktraceLimit is not a function but fairly. I will change the implementation.

@alexander-akait alexander-akait added this to the 1.2.0 milestone Jan 19, 2018
@michael-ciniawsky michael-ciniawsky changed the title Adding addtional option stack to control the stack when there is an error feat: add option to control stack trace formatting (options.stack) Jan 19, 2018
@sendilkumarn
Copy link
Contributor Author

68747470733a2f2f692e696d6775722e636f6d2f7630354951724c2e706e67
This one.

@michael-ciniawsky
Copy link
Member

hmm.. this looks like a duplicate of obj.stack to some point. Is this often the case ?

@sendilkumarn
Copy link
Contributor Author

Yes in terms of create-react-app (& mostly when I test it manually) (but I haven't done extensive research on various other applications) (let me know if there is any that I can check out)

@michael-ciniawsky
Copy link
Member

I also don't have enough knowledge about the {Error} handling here and if outputting the obj.stack would be enough. There most be a reason for adding an additional err.stack, but we should investigate this :)

Copy link
Member

@michael-ciniawsky michael-ciniawsky left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What does the output for

{Boolean}

{ stack: false )

{Number}

{ stack: 5 } // for e.g

look like now ?

@sendilkumarn
Copy link
Contributor Author

Both are same. But when I increase the number to say 10 (default for stack trace) Then I see those many lines

if (this.options.stack) {
// Limit the err.stack manually in case stackTraces are to verbose
if (typeof this.options.stack === 'number') {
Error.stackTraceLimit = (this.options.stack);
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is this setting a global? It seems very non-intuitive to have a package set global configuration like this.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

good one. But I dont think this will have a global impact. But @michael-ciniawsky would be correct one to answer

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You're setting it on a global so I don't see how it could be local.
From the docs (https://nodejs.org/api/errors.html#errors_error_stacktracelimit):

Changes will affect any stack trace captured after the value has been changed.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

But it changes the value in a worker thread. ( well I may be totally wrong) I will check this

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is the code that rethrows the error from the worker so it runs in the main thread.
I suggested another solution below.

@gaearon
Copy link

gaearon commented Jan 19, 2018

OK, so the problem here is that .stack property on Node includes not just the stack trace, but also the message itself.

The original intention was probably to preserve both stacks:

  • the original error stack from the thread
  • the rethrown stack

Both could be valuable depending on what exactly you're debugging (where the error actually happened vs how it "occurred" into your app). So I'd vote to keep both but cut away the duplicate message.

I propose to:

  • Take obj.stack.
  • Add From worker: and err.stack to it but first slice only the part after err.message.

Then we'll get both stacks but the message won't be duplicated.

Copy link

@gaearon gaearon left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why do we need this option at all?

Do you have any reservations about my earlier suggestion?

@sendilkumarn
Copy link
Contributor Author

sendilkumarn commented Jan 21, 2018

err.stack to it but first slice only the part after err.message.

index.js:2178 ./src/App.js
Syntax error: /awesomemac/create-react-app/awesome-app-1/src/App.js: Unexpected token, expected "{" (6:10)

  4 | 
  5 | class App extends Component {
> 6 |   render()) {
    |           ^
  7 |     return (
  8 |       <div className="App">
  9 |         <header className="App-header">
	Thread Loader (Worker 2)
4 | 
  5 | class App extends Component {
> 6 |   render()) {
    |           ^
  7 |     return (
  8 |       <div className="App">
  9 |         <header className="App-header">
	Thread Loader (Worker 2)

This will be the output. If we have just removed the message from err.

Since we are reconstructing the error with the same object. Mostly both of the stack remains the same.

I am not convinced to add the same information again

@gaearon
Copy link

gaearon commented Jan 21, 2018

This will be the output. If we have just removed the message from err.

I don't understand why. Clearly the code frame is identical in your example. The code frame is part of the message. Therefore, if it was not "cut off", the problem is with the code that cuts it off.

I'm not saying my exact algorithm is correct. But hopefully you can see that the .message is the same between two errors, and therefore there should be a way to just cut off the right part from the second .stack property :-)

@sendilkumarn
Copy link
Contributor Author

The code frame is part of the message. Therefore, if it was not "cut off", the problem is with the code that cuts it off.

Interestingly both message and stack is same in both the cases

@sendilkumarn
Copy link
Contributor Author

const err = new Error(obj.message);

Doesn't it wrap and throw the same error 🤔 Ideally when you run this, they should be equal right

@michael-ciniawsky
Copy link
Member

Maybe worth a try

const err = new Error('I\'m an Error')
const stack = err.stack.split('\n').filter((line) => line.includes('at'))
console.log(stack)

const worker = (err) => {
  return new Error(err)
}

const err2 = worker(err)
const stack2 = err2.stack.split('\n').filter((line) => line.includes('at'))
console.log(stack2)

const length = stack2.length - stack.length

const result = stack2.slice(0, length).join('\n')
console.log(result) // at worker (/Users/User/path/to/index.js:6:10)

// ${obj.stack}
//
// Thread Loader (Worker 1)
//
// at worker (/Users/User/path/to/index.js:6:10)

@sendilkumarn
Copy link
Contributor Author

Error screen shot as of now
screen shot 2018-01-22 at 23 26 43

@sendilkumarn
Copy link
Contributor Author

@michael-ciniawsky As I said in the above comment

yes they are literally the same, except for the first line which says that the error is thrown from that corresponding statement's line number. Apart from that everything is same.

@gaearon
Copy link

gaearon commented Jan 22, 2018

@michael-ciniawsky Would you mind keeping Thread Loader prefixed with at like other lines in the stack trace? That would make it more convenient for tools that automatically filter out stack traces with regular expressions.

@michael-ciniawsky
Copy link
Member

michael-ciniawsky commented Jan 23, 2018

const stack = (origin, worker) => {
  origin = origin
    .split('\n')
    .filter((line) => line.includes('at'))

  worker = worker
    .split('\n')
    .filter((line) => line.includes('at'))
    .map((line) => `${line} [Thread Loader (Worker 1)]`) // needs to be replaced with `${id}`

  const diff = worker.slice(0, worker.length - origin.length).join('\n')

  origin.unshift(diff)

  return origin.join('\n')
}

class WorkerError extends Error {
  constructor (err) {
    super(err)

    this.name = err.name
    this.message = err.message

    Error.captureStackTrace(this, this.constructor)

    this.stack = stack(err.stack, this.stack)
  }
}

const err = new Error('I\'m an Error')

const worker = (err) => {
  throw new WorkerError(err)
}

console.log(worker(err))
  throw new WorkerError(err)
  ^

    at worker (/Users/User/path/to/index.js:34:9) [Thread Loader (Worker 1)] // <=
    at Object.<anonymous> (/Users/Cini/DEV/JS/index.js:31:13)
    at Module._compile (module.js:641:30)
    at Object.Module._extensions..js (module.js:652:10)
    at Module.load (module.js:560:32)
    at tryModuleLoad (module.js:503:12)
    at Function.Module._load (module.js:495:3)
    at Function.Module.runMain (module.js:682:10)
    at startup (bootstrap_node.js:191:16)
    at bootstrap_node.js:613:3

@michael-ciniawsky
Copy link
Member

michael-ciniawsky commented Jan 23, 2018

@gaearon Yep, the from thread-loader notice if within the stack should definitely align with 'standard' stack formatting

@gaearon
Copy link

gaearon commented Jan 23, 2018

line.includes('at')

is too broad.

For example,

throw new Error('There was a problem at MyComponent definition.');

will incorrectly match the first line (the message) as being part of the stack trace.

This is why in my suggestion in #13 (comment) I search for first end of the message inside the stack. That's guaranteed to be where the real stack trace starts.

@michael-ciniawsky
Copy link
Member

michael-ciniawsky commented Jan 23, 2018

I just used it includes while prototyping, use a {RegExp}, Array.prototype.indexOf etc to make it bullet proofen 😛

@gaearon
Copy link

gaearon commented Jan 23, 2018

My point is you can’t really reliably match the stack trace without knowing the message.

For all we know, at ... could be a part of the message (e.g. if somebody else manipulates it the same way). We don't want to throw that away.

The only reliable way to know when the real stack trace starts is to check where the message ends inside of it.

(Sorry if I misunderstood and you agree with this point. I’m stressing it because it seems important for correctness.)

@michael-ciniawsky
Copy link
Member

michael-ciniawsky commented Jan 23, 2018

/^(\s+at\s.+\s\(.+\))/.test(line)

But the diffing is already advanced anyways, replacing the stack with the updated one from the worker and maybe prepending e.g Thread Loader [Worker ${id}] as title to the err.message should do the job aswell as long as there aren't duplicates anymore :)

Thread Loader [Worker ${id}] // prepend

// 'Original'
${err.message}
${err.frame}

${worker.stack} // update

@sendilkumarn
Copy link
Contributor Author

@michael-ciniawsky but there are duplicates.

worker.stack contains err.message in it. that causes the duplication.

@michael-ciniawsky
Copy link
Member

worker.stack contains err.message in it. that causes the duplication.

Just remove the err.message from the worker.stack ? :)

@gaearon
Copy link

gaearon commented Feb 5, 2018

I think that’s what my code in #13 (comment) was doing?

@michael-ciniawsky
Copy link
Member

michael-ciniawsky commented Feb 5, 2018

  fromErrorObj (arg) {
    let obj;

    if (typeof arg === 'string') {
      obj = { message: arg };
    } else {
      obj = arg;
    }
-    const err = new Error(obj.message);
+   return new WorkerError(obj);
-    err.message = obj.message;
-    if (obj.stack) {
-      const trim = (error) => {
-        const { stack, message } = error;
-        const trace = stack.indexOf(message) + message.length;
-        return stack.substr(trace);
-      };

-      err.stack = `${obj.stack}\nThread Loader (Worker ${this.id})\n\n${trim(err)}`;-
-    }
-    err.hideStack = obj.hideStack;
-    err.details = obj.details;
-    return err;
  }
class WorkerError extends Error {
    constructor (obj) {
       // ...format the original {Error}
    }
}

export default WorkerError

WorkerError Format (Suggestion)

Thread Loader (Worker ${id})

<Original Message (err.message)>

<Worker Stack>

Is all I'm asking and it's 95% done already :)

@gaearon
Copy link

gaearon commented Feb 5, 2018

Ah okay I see what you mean now 🤗

@sendilkumarn Mind extracting?

Copy link
Member

@michael-ciniawsky michael-ciniawsky left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@sendilkumarn Thx

Can you show a screenshot how it this looks like now please :) ?

@sendilkumarn
Copy link
Contributor Author

Thread Loader (Worker 1)
I'm an Error
    at worker (/Users/sendilkumar/Dev/thread-loader/index.js:6:9)
    at Object.<anonymous> (/Users/sendilkumar/Dev/thread-loader/index.js:3:13)
    at Module._compile (module.js:660:30)
    at Object.Module._extensions..js (module.js:671:10)
    at Module.load (module.js:573:32)
    at tryModuleLoad (module.js:513:12)
    at Function.Module._load (module.js:505:3)
    at Function.Module.runMain (module.js:701:10)
    at startup (bootstrap_node.js:193:16)
    at bootstrap_node.js:617:3

Copy link
Member

@alexander-akait alexander-akait left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why need package-lock.json for this?

@sendilkumarn
Copy link
Contributor Author

@evilebottnawi reverted

@alexander-akait
Copy link
Member

@sendilkumarn good work! Thanks!

@michael-ciniawsky michael-ciniawsky removed this from the 1.1.4 milestone Feb 9, 2018
@michael-ciniawsky
Copy link
Member

michael-ciniawsky commented Feb 21, 2018

Released in v1.1.3 🎉 Sry for the delay here

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

5 participants