debugging in node

Recently at my company, I had a task, where I had to make changes at almost the entire codebase for the server side and of course, I made many mistakes and produced bugs and errors along the way. In this post, I want to show good and bad errors. But actually I don’t care about the error.message. More important are the stacktrace. Because how can an error be fixed, when you don’t know where is comes from. Along the way, I had two times to hack into a framework, to get a complete stacktrace.

a good error

First, I have a good StackTrace. To produce it, I have created a circular data structure, where A has a prop B, that has A.
when pass this in an express to res.json(circular), you get the following trace.

TypeError: Converting circular structure to JSON
   at Object.stringify (native)
   at ServerResponse.json (/testExpress/node_modules/express/lib/response.js:242:19)
   at /testExpress/app.js:8:7
   at Layer.handle [as handle_request] (/testExpress/node_modules/express/lib/router/layer.js:95:5)
   at trim_prefix (/testExpress/node_modules/express/lib/router/index.js:312:13)
   at /testExpress/node_modules/express/lib/router/index.js:280:7
   at Function.process_params (/testExpress/node_modules/express/lib/router/index.js:330:12)
   at next (/testExpress/node_modules/express/lib/router/index.js:271:10)
   at expressInit (/testExpress/node_modules/express/lib/middleware/init.js:33:5)
   at Layer.handle [as handle_request] (/testExpress/node_modules/express/lib/router/layer.js:95:5)

At line four it is pointing to my app. So it is easy to see, where I have produced the circular data structure. In contrast I can name the pomelo framework. If you try there to pass an object to the client, that can not be serialized, you will get an error. The stacktrace then is completely within the node_modules folder.

a bad error from bearcat-dao

Next I have a longer stacktrace that is from bearcat-dao and the underlying mysql-module. This is when I had to introduce a new parameter to the querying function, but did not directly updated all the usages of that method.

{ [Error: ER_PARSE_ERROR: You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '?' at line 1]
  code: 'ER_PARSE_ERROR',
  errno: 1064,
  sqlState: '42000',
  index: 0 }
Error: ER_PARSE_ERROR: You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '?' at line 1
    at Query.Sequence._packetToError (/app/node_modules/mysql/lib/protocol/sequences/Sequence.js:48:14)
    at Query.ErrorPacket (/app/node_modules/mysql/lib/protocol/sequences/Query.js:83:18)
    at Protocol._parsePacket (/app/node_modules/mysql/lib/protocol/Protocol.js:271:23)
    at Parser.write (/app/node_modules/mysql/lib/protocol/Parser.js:77:12)
    at Protocol.write (/app/node_modules/mysql/lib/protocol/Protocol.js:39:16)
    at Socket.<anonymous> (/app/node_modules/mysql/lib/Connection.js:92:28)
    at emitOne (events.js:77:13)
    at Socket.emit (events.js:169:7)
    at readableAddChunk (_stream_readable.js:146:16)
    at Socket.Readable.push (_stream_readable.js:110:10)
    at TCP.onread (net.js:523:20)
    --------------------
    at Protocol._enqueue (/app/node_modules/mysql/lib/protocol/Protocol.js:135:48)
    at PoolConnection.Connection.query (/app/node_modules/mysql/lib/Connection.js:197:25)
    at /app/node_modules/bearcat-dao/lib/template/sql/mysqlTemplate.js:344:26
    at /app/node_modules/bearcat-dao/lib/connection/sql/mysqlConnectionManager.js:58:3
    at /app/node_modules/bearcat-dao/lib/connection/sql/mysqlConnectionManager.js:116:4
    at Ping.onPing [as _callback] (/app/node_modules/mysql/lib/Pool.js:94:5)
    at Ping.Sequence.end (/app/node_modules/mysql/lib/protocol/sequences/Sequence.js:96:24)
    at Ping.Sequence.OkPacket (/app/node_modules/mysql/lib/protocol/sequences/Sequence.js:105:8)
    at Protocol._parsePacket (/app/node_modules/mysql/lib/protocol/Protocol.js:271:23)
    at Parser.write (/app/node_modules/mysql/lib/protocol/Parser.js:77:12)
    at Protocol.write (/app/node_modules/mysql/lib/protocol/Protocol.js:39:16)
    at Socket.<anonymous> (/app/node_modules/mysql/lib/Connection.js:92:28)
    at emitOne (events.js:77:13)
    at Socket.emit (events.js:169:7)
    at readableAddChunk (_stream_readable.js:146:16)
    at Socket.Readable.push (_stream_readable.js:110:10)
    at TCP.onread (net.js:523:20)

The problem is, I can see, there is a missing parameter, but because I was changing so many places, I could not say, what function was now called with a missing parameter.

That made it necessary to look deeper into the bearcat-dao module. What I needed to do, is to provide a peace of stacktrace that is pointing out of bearcat, into my app, and the wrong usage of the query method. And actually that is what Mysql is already doing when using a connection-pool, thats why we have the line with minuses (——————–). The problem for providing a full stack-trace is in asynchronous code. Bearcat-dao manages the connection pool itself, but do not provide the stacktrace. (I already made a pull-request to bearcat-dao at github, we will see when they are going to fix that issue on the npm-module.)

fix of the bearcat error stacktrace

To provide the stacktrace, I created a new Error object. but did not throw or return that error, only when an error occur, I have append its stack to the original Error. In that way, I can see where the error is coming from and where the code querying method was called, to fix that bug.

The stack was then extended by the following stack-trace.

executeQuery Error
    at MysqlTemplate.executeQuery (/app/node_modules/bearcat-dao/lib/template/sql/mysqlTemplate.js:330:41)
    at DomainDaoSupport.getList (/app/node_modules/bearcat-dao/lib/core/domainDaoSupport.js:715:31)
    at FileDao.getSharingChildren (/app/app/mysql/dao/fileDao.js:196:28)
    at VFService.getSharingChildren (/app/app/mysql/service/vfService.js:963:19)
    at Promise.post (/app/node_modules/q/q.js:1161:36)
    at Promise.promise.promiseDispatch (/app/node_modules/q/q.js:788:41)
    at /app/node_modules/q/q.js:1391:14
    at runSingle (/app/node_modules/q/q.js:137:13)
    at flush (/app/node_modules/q/q.js:125:13)
    at doNTCallback0 (node.js:430:9)
    at process._tickDomainCallback (node.js:400:13)

bad error in Q

Until now, we have seed frameworks that stand in the beginning and the end of a process chain. Means express and pomelo provide you a stricture that you can hook into, to provide an API to other machines. Mysql and bearcat-dao provide access to some resource, in this case a database.

Q is a library, that will help you to structure and live directly within your context, to let you write code using promises. We are also using it to execute node-style async methods with promises. The problem, when you have an error, you can see where it occur, but you can not sees, where a method was called to course that Error.

In other situations, I realized that async.js is providing the stack for both sites. you see where the error occur and where the method was called from.

conclusion

Having so much debugging work, I have learned a lot about error-handling and what I do expect from a good error. The error should not just describe what is wrong, it should also describe how the error occur and the stacktrace is a good option for that.

When a library is not providing you a complete stack-trace, it is possible to read the modules code and adjust the error-handling there. And actually I think we all deserve that the libraries we are using are providing a stacktrace that point to your application and when providing a library it should always be possible to provide the stack.