net: give better error messages #7285

evanlucas · 2014-03-10T20:44:42Z

Add address and/or port to errors where applicable for better reporting.

Nodejs-Jenkins · 2014-03-10T20:44:46Z

Thank you for contributing this pull request! Here are a few pointers to make sure your submission will be considered for inclusion.

The following commiters were not found in the CLA:

Evan Lucas

You can fix all these things without opening another issue.

Please see CONTRIBUTING.md for more information

evanlucas · 2014-03-10T20:46:54Z

I also went ahead and signed the CLA.

tjfontaine · 2014-03-10T20:57:58Z

Thanks for the contribution!

I think I'd prefer util.format over string concatenation.

Also what about moving some of this logic into errnoException and then just util._extend()ing the potentially returned object -- this means other places we want to decorate get this behavior by default.

evanlucas · 2014-03-10T21:02:00Z

Ok, I can change the string concatenation. That makes more sense. I wasn't sure if moving it would be the direction to go or not. I'll go ahead and try to knock that out.

evanlucas · 2014-03-10T21:56:22Z

alright I moved some of the logic into errnoException and got rid of the string concatenation :]

tjfontaine · 2014-03-10T22:03:46Z

lib/net.js

+      address: req.address
+    };
+    if (req.port) additions.port = req.port;
+    var ex = errnoException(status, 'write', err, additions);


why not pass req directly?

I thought it sometimes could have additional properties, like afterShutdown.

I was looking at https://github.com/joyent/node/blob/master/lib/net.js#L213

We could filter out functions, I'm mostly just looking for a generic way for this to work without having to be too explicit at every callsite

What about building the message from the keys of the object passed to errnoException?

On Mar 10, 2014, at 5:22 PM, Timothy J Fontaine [email protected] wrote:

In lib/net.js:

@@ -769,7 +769,12 @@ function afterWrite(status, handle, req, err) {
}

if (status < 0) {

var ex = errnoException(status, 'write', err);

err = util.format('%s %s:%s', err || '', req.address, req.port);

var additions = {

address: req.address

};

if (req.port) additions.port = req.port;

var ex = errnoException(status, 'write', err, additions);
We could filter out functions, I'm mostly just looking for a generic way for this to work without having to be too explicit at every callsite

—
Reply to this email directly or view it on GitHub.

tj · 2014-03-10T22:07:47Z

didn't look at the diff too closely but we'll have to make sure to support ephemeral ports as well, looks like maybe that's missing

evanlucas · 2014-03-10T22:18:49Z

yep, I'll see if I can get that added tonight.

tjfontaine · 2014-03-10T22:19:31Z

just to be clear, you mean localPort and localAddress?

Depending on when the error is raised and by the time we've been notified it may not be possible to have that information. The most reliable way would be for us to exercise that path by default, but doing so results in an extra syscall by default

tj · 2014-03-10T22:28:20Z

Yeah, passing err.port == 0 etc wouldn't be too useful. We probably wouldn't have to worry about the syscalls, I'd hope errors wouldn't be "hot" code haha :D

tjfontaine · 2014-03-10T22:34:43Z

my point is that the fd may be gone by the time we want that information, so the only reliable way to have that information around is to always ask for that it when the handle is created, which means everyone will feel it -- I'm not opposed to it, it's generally useful, but to date we've so far waited to resolve that information until explicitly asked for it

tj · 2014-03-10T23:07:28Z

Ah ok I see what you're saying. I can only speak for myself there, I'd definitely prefer a tiny performance hit to having logs that have no zero value

trevnorris · 2014-03-11T05:11:52Z

Just curious, what good is knowing the fd after it's been closed? There's
no more inspection on it you can do at that time.

tjfontaine · 2014-03-11T05:34:41Z

That's not the question, he wants to know localPort, localAddress, remotePort, and remoteAddress, which depending on the disposition of the socket requires the fd to be valid when the syscall is performed. If we've already destroyed the handle (which we do by default for errors) the fd is probably invalid.

On the other hand, having the fd is very important for logging especially if you hit the scenario where you have a hung process or similar, being able to correlate lsof results with what you were able to have access to in process is important. Which is why the fact that we've gone to lengths to hide the literal fd is ridiculous, especially since it does have a useful concept on windows.

trevnorris · 2014-03-11T17:49:21Z

ok. well before we introduce a "tiny performance hit" I'd definitely like to review it. Per the usual. ;-)

evanlucas · 2014-03-13T02:18:25Z

Ok, I've included the local port and address (where applicable)...here is the bench-net results:

Master

net/dgram.js
net/dgram.js len=1 num=100 type=send dur=5: 0.00046916
net/dgram.js len=1 num=100 type=recv dur=5: 0.00015590
net/dgram.js len=64 num=100 type=send dur=5: 0.030016
net/dgram.js len=64 num=100 type=recv dur=5: 0.0098559
net/dgram.js len=256 num=100 type=send dur=5: 0.11368
net/dgram.js len=256 num=100 type=recv dur=5: 0.037174
net/dgram.js len=1024 num=100 type=send dur=5: 0.24607
net/dgram.js len=1024 num=100 type=recv dur=5: 0.073494

net/net-c2s.js
net/net-c2s.js len=102400 type=utf dur=5: 3.4344
net/net-c2s.js len=102400 type=asc dur=5: 5.2294
net/net-c2s.js len=102400 type=buf dur=5: 6.0660
net/net-c2s.js len=16777216 type=utf dur=5: 2.4006
net/net-c2s.js len=16777216 type=asc dur=5: 4.5491
net/net-c2s.js len=16777216 type=buf dur=5: 6.1529

net/net-pipe.js
net/net-pipe.js len=102400 type=utf dur=5: 4.2717
net/net-pipe.js len=102400 type=asc dur=5: 5.4593
net/net-pipe.js len=102400 type=buf dur=5: 5.6436
net/net-pipe.js len=16777216 type=utf dur=5: 3.4148
net/net-pipe.js len=16777216 type=asc dur=5: 4.8503
net/net-pipe.js len=16777216 type=buf dur=5: 5.9216

net/net-s2c.js
net/net-s2c.js len=102400 type=utf dur=5: 3.4203
net/net-s2c.js len=102400 type=asc dur=5: 5.2393
net/net-s2c.js len=102400 type=buf dur=5: 6.0843
net/net-s2c.js len=16777216 type=utf dur=5: 2.4413
net/net-s2c.js len=16777216 type=asc dur=5: 4.5410
net/net-s2c.js len=16777216 type=buf dur=5: 6.0884

net/tcp-raw-c2s.js
net/tcp-raw-c2s.js len=102400 type=utf dur=5: 3.2528
net/tcp-raw-c2s.js len=102400 type=asc dur=5: 5.6648
net/tcp-raw-c2s.js len=102400 type=buf dur=5: 5.9811
net/tcp-raw-c2s.js len=16777216 type=utf dur=5: 2.4437
net/tcp-raw-c2s.js len=16777216 type=asc dur=5: 4.4782
net/tcp-raw-c2s.js len=16777216 type=buf dur=5: 5.4020

net/tcp-raw-pipe.js
0 'write'
util.js:741
  var errname = uv.errname(err);
                   ^
Error: err >= 0
    at Object.exports._errnoException (util.js:741:20)
    at fail (/Volumes/DEV/code/node/forks/node-fork/benchmark/net/tcp-raw-pipe.js:32:14)
    at Object.writeReq.oncomplete (/Volumes/DEV/code/node/forks/node-fork/benchmark/net/tcp-raw-pipe.js:63:11)
child process exited with code 1

net/tcp-raw-s2c.js
net/tcp-raw-s2c.js len=102400 type=utf dur=5: 3.6393
net/tcp-raw-s2c.js len=102400 type=asc dur=5: 5.4391
net/tcp-raw-s2c.js len=102400 type=buf dur=5: 5.8850
net/tcp-raw-s2c.js len=16777216 type=utf dur=5: 2.3136
net/tcp-raw-s2c.js len=16777216 type=asc dur=5: 4.1627
net/tcp-raw-s2c.js len=16777216 type=buf dur=5: 5.6639

With Changes

net/dgram.js
net/dgram.js len=1 num=100 type=send dur=5: 0.00046862
net/dgram.js len=1 num=100 type=recv dur=5: 0.00015282
net/dgram.js len=64 num=100 type=send dur=5: 0.029415
net/dgram.js len=64 num=100 type=recv dur=5: 0.0094112
net/dgram.js len=256 num=100 type=send dur=5: 0.10662
net/dgram.js len=256 num=100 type=recv dur=5: 0.033931
net/dgram.js len=1024 num=100 type=send dur=5: 0.23747
net/dgram.js len=1024 num=100 type=recv dur=5: 0.086841

net/net-c2s.js
net/net-c2s.js len=102400 type=utf dur=5: 3.2184
net/net-c2s.js len=102400 type=asc dur=5: 5.0028
net/net-c2s.js len=102400 type=buf dur=5: 5.7852
net/net-c2s.js len=16777216 type=utf dur=5: 2.3048
net/net-c2s.js len=16777216 type=asc dur=5: 4.5286
net/net-c2s.js len=16777216 type=buf dur=5: 5.9653

net/net-pipe.js
net/net-pipe.js len=102400 type=utf dur=5: 4.3703
net/net-pipe.js len=102400 type=asc dur=5: 5.2963
net/net-pipe.js len=102400 type=buf dur=5: 5.4195
net/net-pipe.js len=16777216 type=utf dur=5: 3.3145
net/net-pipe.js len=16777216 type=asc dur=5: 4.9447
net/net-pipe.js len=16777216 type=buf dur=5: 5.5724

net/net-s2c.js
net/net-s2c.js len=102400 type=utf dur=5: 3.0221
net/net-s2c.js len=102400 type=asc dur=5: 4.9844
net/net-s2c.js len=102400 type=buf dur=5: 5.6547
net/net-s2c.js len=16777216 type=utf dur=5: 2.0058
net/net-s2c.js len=16777216 type=asc dur=5: 4.1864
net/net-s2c.js len=16777216 type=buf dur=5: 5.0978

net/tcp-raw-c2s.js
net/tcp-raw-c2s.js len=102400 type=utf dur=5: 2.9586
net/tcp-raw-c2s.js len=102400 type=asc dur=5: 5.0143
net/tcp-raw-c2s.js len=102400 type=buf dur=5: 5.8931
net/tcp-raw-c2s.js len=16777216 type=utf dur=5: 2.2421
net/tcp-raw-c2s.js len=16777216 type=asc dur=5: 4.4877
net/tcp-raw-c2s.js len=16777216 type=buf dur=5: 5.7035

net/tcp-raw-pipe.js
0 'write'
util.js:741
  var errname = uv.errname(err);
                   ^
Error: err >= 0
    at Object.exports._errnoException (util.js:741:20)
    at fail (/Volumes/DEV/code/node/forks/node-fork/benchmark/net/tcp-raw-pipe.js:32:14)
    at Object.writeReq.oncomplete (/Volumes/DEV/code/node/forks/node-fork/benchmark/net/tcp-raw-pipe.js:63:11)
child process exited with code 1

net/tcp-raw-s2c.js
net/tcp-raw-s2c.js len=102400 type=utf dur=5: 3.7949
net/tcp-raw-s2c.js len=102400 type=asc dur=5: 5.6059
net/tcp-raw-s2c.js len=102400 type=buf dur=5: 5.6447
net/tcp-raw-s2c.js len=16777216 type=utf dur=5: 2.3139
net/tcp-raw-s2c.js len=16777216 type=asc dur=5: 4.3200
net/tcp-raw-s2c.js len=16777216 type=buf dur=5: 5.6513

jcspencer · 2014-03-16T04:14:07Z

👍

evanlucas · 2014-04-11T16:41:30Z

anyone else had a chance to take a look at this?

ilanbiala · 2014-07-13T21:33:57Z

Can we get more people to look at this to get it pulled into master? The error messages are still the same after months and they provide very little description as to what the real error is.

evanlucas · 2014-07-13T21:45:50Z

I went ahead and rebased off master again

ilanbiala · 2014-07-13T21:50:08Z

Thanks for all the help @evanlucas!

I'm really hoping to push Node to a point where error messages are very comprehensive and are useful, because some were very confusing for me when I started, even when they shouldn't have been. Some still are complicated, and I'm hoping that merging this will get the ball rolling on revamping the current state of error messages.

I think that if enough people support this, Node's developers will take a look and see how much this issue hinders beginners from using Node and how easy it is to fix compared to most of the other issues in the repository.

gx0r · 2014-07-14T02:43:08Z

👍 nice work.

JacksonTian · 2014-08-12T13:22:51Z

This pull request can be merged? What's the decision?

indutny · 2014-08-12T21:19:08Z

cc @tjfontaine

trevnorris · 2014-08-12T22:34:57Z

lib/net.js

+      var additions = {
+        address: address
+      };
+      if (port) additions.port = port;


Doing two checks for port. I'd change it to the following:

var additions = { address: address }; var details; if (port) { details = util.format('%s:%s', address, port); additions.port = port; } else { details = address; }

trevnorris · 2014-08-12T22:41:33Z

Left a few comments. Ping me back when fixed.

evanlucas · 2014-08-13T03:43:34Z

Thanks!

JacksonTian · 2014-08-27T13:25:52Z

ping reviewers.

trevnorris · 2014-09-02T20:28:34Z

lib/net.js

+                            req.localPort);
+    }
+    var ex = errnoException(status, 'connect', details, req);
+    self._destroy(ex);


Can you go ahead and put this into

self._destroy(errnoException(status, 'connect', details, req));

No need for var ex.

trevnorris · 2014-09-02T20:40:28Z

lib/util.js

+        delete add[key];
+      }
+    }
+    e = add;


When _extend(e, additions) adds object properties to e. So add is superfluous. Just use e.

trevnorris · 2014-09-02T20:53:42Z

Few comments, other than that I'm okay with it.

Though I wonder about extending this to dgram and fs. Think both those places could use similar treatment. Basically, making a very simple generic way to propagate additional information. Like, passing the request itself and in _errnoException() change the following:

if (isNullOrUndefined(val) || isFunction(val))

to

if (isNullOrUndefined(val) || !isPrimitive(val))

I'd like to see if this might work, and then try extending it to the dgram module. Mode devs want "additional information" on the error for pretty much every module, so might as well setup a uniform way of doing it while we're here.

evanlucas · 2014-09-02T20:57:43Z

@trevnorris thanks for your time on reviewing this. I went ahead and made the requested changes. I would love to help in any way on this. Should I go ahead and take a stab at doing this for dgram?

trevnorris · 2014-09-03T05:55:59Z

lib/util.js

+        i--;
+      }
+    }
+    exports._extend(e, additions);


Actually, screw using _extend(). Let's just do this manually:

if (additions && isObject(additions)) { var keys = Object.keys(additions); for (var i = 0; i < keys.length; i++) if (!isNullOrUndefined(keys[i]) && isPrimitive(keys[i])) e[i] = keys[i]; }

There, much simpler.

I use isPrimitive() because I assume no objects would be attached to the error. Would they?

That makes sense to me. I'll get this changed

trevnorris · 2014-09-03T06:00:25Z

@evanlucas One more revision on something I already commented on. Sorry for not seeing that the first round.

If you wouldn't mind doing this on dgram that would be a great way to start making this more ubiquitous.

Now, I would like it if the req object itself could be passed in. Instead of needing to create a new additions object. It would remove a lot of code and make cross-module implementation cleaner and future changes simpler. Think we can do that?

evanlucas · 2014-09-03T13:22:56Z

I think for most cases, yes. Should we just continue using the additions in the event that req has not yet been created?

trevnorris · 2014-09-03T20:09:55Z

@evanlucas Just curious, do you have an example of when the req object hadn't been created before an error is emitted?

evanlucas · 2014-09-03T20:14:34Z

sure https://github.com/evanlucas/node/blob/bug/7005/lib/net.js#L811-L825

trevnorris · 2014-09-03T23:13:24Z

@evanlucas Thanks. Let's make those cases the exception, and pass the req object where possible.

evanlucas · 2014-09-03T23:45:22Z

Ok, _errnoException has been changed and now req is passed when it exists.

trevnorris · 2014-09-04T23:53:53Z

lib/net.js

@@ -742,7 +742,8 @@ function afterWrite(status, handle, req, err) {
  }

  if (status < 0) {
-    var ex = errnoException(status, 'write', err);
+    err = util.format('%s %s:%s', err || '', req.address, req.port);


I'm curious why the err || ''. If status < 0 then we should have an error object. Otherwise Node had a bug.

Hm, I feel like there was a previous test that was failing without that, but after looking like it, doesn't appear to be true.

Let's go ahead and remove it for now.

ah found it. When passing an err to uv.errname, if the err if ENOTFOUND, I get this:

util.js:739 var errname = uv.errname(err); ^ Error: err >= 0 at Error (native) at exports._errnoException (util.js:739:20) at net.js:941:18 at Object.asyncCallback [as callback] (dns.js:78:16) at Object.onlookup [as oncomplete] (dns.js:91:17)

Nice. Thanks for the info.

trevnorris · 2014-09-04T23:59:36Z

Few more comments, but looking great. Thanks for all your work here.

evanlucas · 2014-09-05T00:20:58Z

Thanks! I'm happy to be able to contribute!

trevnorris · 2014-09-05T02:31:46Z

Remember that util._extend() extends the passed object, so there's no need to do var ex =. Go ahead and remove all cases of this.

JacksonTian · 2014-09-18T06:56:00Z

Any update? @evanlucas

evanlucas · 2015-06-22T18:53:37Z

Closing as this landed in io.js a while back

tjfontaine reviewed Mar 10, 2014
View reviewed changes

mmalecki mentioned this pull request Aug 7, 2014

Node error guidelines #8103

Closed

rlidwka mentioned this pull request Aug 11, 2014

net: Add address & port info into listen error message #8123

Closed

trevnorris reviewed Aug 12, 2014
View reviewed changes

trevnorris reviewed Sep 2, 2014
View reviewed changes

net: include local port/address in error messages

e9a2558

trevnorris reviewed Sep 2, 2014
View reviewed changes

evanlucas force-pushed the bug/7005 branch from 7def1f0 to ef7439c Compare September 2, 2014 20:54

trevnorris reviewed Sep 3, 2014
View reviewed changes

Evan Lucas added 2 commits September 3, 2014 18:33

util: don't use _extend in _errnoException

05cbdab

net: Pass req directly to errnoException

af7e194

evanlucas force-pushed the bug/7005 branch from ef7439c to af7e194 Compare September 3, 2014 23:44

trevnorris reviewed Sep 4, 2014
View reviewed changes

evanlucas mentioned this pull request Dec 3, 2014

net: give better error messages nodejs/node#35

Closed

evanlucas closed this Jun 22, 2015

net: give better error messages #7285

net: give better error messages #7285

Conversation

evanlucas commented Mar 10, 2014

Nodejs-Jenkins commented Mar 10, 2014

evanlucas commented Mar 10, 2014

tjfontaine commented Mar 10, 2014

evanlucas commented Mar 10, 2014

evanlucas commented Mar 10, 2014

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tj commented Mar 10, 2014

evanlucas commented Mar 10, 2014

tjfontaine commented Mar 10, 2014

tj commented Mar 10, 2014

tjfontaine commented Mar 10, 2014

tj commented Mar 10, 2014

trevnorris commented Mar 11, 2014

tjfontaine commented Mar 11, 2014

trevnorris commented Mar 11, 2014

evanlucas commented Mar 13, 2014

Master

With Changes

jcspencer commented Mar 16, 2014

evanlucas commented Apr 11, 2014

ilanbiala commented Jul 13, 2014

evanlucas commented Jul 13, 2014

ilanbiala commented Jul 13, 2014

gx0r commented Jul 14, 2014

JacksonTian commented Aug 12, 2014

indutny commented Aug 12, 2014

Choose a reason for hiding this comment

trevnorris commented Aug 12, 2014

evanlucas commented Aug 13, 2014

JacksonTian commented Aug 27, 2014

Choose a reason for hiding this comment

Choose a reason for hiding this comment

trevnorris commented Sep 2, 2014

evanlucas commented Sep 2, 2014

Choose a reason for hiding this comment

Choose a reason for hiding this comment

trevnorris commented Sep 3, 2014

evanlucas commented Sep 3, 2014

trevnorris commented Sep 3, 2014

evanlucas commented Sep 3, 2014

trevnorris commented Sep 3, 2014

evanlucas commented Sep 3, 2014

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

trevnorris commented Sep 4, 2014

evanlucas commented Sep 5, 2014

trevnorris commented Sep 5, 2014

JacksonTian commented Sep 18, 2014

evanlucas commented Jun 22, 2015