Patience

Following on from yesterday’s post on working with the node stack in AgileBot, Michael had overnight addressed two of my concerns. He’d upgraded from jasmine-node to jasmine-npm, which was allowing our tests to fail in the correct way, i.e. not with catastrophic failures involving no output whatsoever; and he’d got the source maps working so that the stack traces were giving us the correct line numbers in the CoffeeScript source files, which involved creating the following line in spec/helpers/helper.js:

require('coffee-script/register');

It also required adding this jasmine.json file in spec/support:

{
"spec_dir": "spec",
"spec_files": [
"**/*[sS]pec.coffee"
],
"helpers": [
"helpers/**/*.js"
],
"stopSpecOnExpectationFailure": false,
"random": false
}

So two of my four concerns from the previous blog post were addressed. Great work Michael! After Michael took me through all the changes, we could have easily dived into further refactoring, but I tried to step back and take some notes on our options. Here’s what I wrote down at the time:

* refactoring the test harness
- split into separate files
- pull output logic from mock into test to hard code ??
- could look at test coverage to discover untested paths OR work them out
- sepia for recording and playback
VCR --> Sepia --> Yakbak https://github.com/flickr/yakbak
Web mock --> Nock
Sinon vs TestDouble

A little googling showed there was a more recent (than Sepia) node VCR-like node module called yakbak, but since we had nock working I said let’s leave that. Michael also mentioned harmonising the production and staging environments, since at the moment the staging server was hacked to post Slack alerts to a different channel, in order to run manual end-to-end without spamming the community. So simply merging the work we were doing would break the production instance. All this work on creating a testing harness had been motivated by our desire to push the hard coded channel mappings into some sort of config package, i.e. to be able to do that refactoring in safety. So in a fit of “what is this all for” I just started googling different node config approaches (after noting thatprocess.env.NODE_ENV allowed us to get something similar to RACK_ENV in terms of specifying ‘prodcution’, 'development’ or 'test’). I found a few config options:

  • dotenv
  • nconf
  • node-config
  • roll our own

node-config looked slightly more active so we slapped that in, but I was half way through setting it up and baulked at converting our existing CoffeeScript into JSON. We threw it out and hand-rolled the following:

[CHANNELS, GITTER_ROOMS] = require('./../config/' + process.env.LIVE_ENV + '.coffee')

We used our own LIVE_ENV var because actually what we wanted was a switch to move from one endpoint to another, and with this switch we now loadconfig/production.coffee vs config/staging.coffee depending on whether we want to hit the main slack instance or not. We got this working in fairly short order, and so we were tempted to try and knock off a couple of quick refactorings. Splitting the tests over two files, and pulling a little hard coded logic out of the mock and into the tests themselves.

Here we hit another wall. Just splitting the tests over two files introduced a very strange problem:

[tansaku@Samuels-MBP:~/Documents/GitHub/AgileVentures/agile-bot (27_refactor_test_harness)]$ 
→ npm test
> agile-bot@1.0.0 test /Users/tansaku/Documents/GitHub/AgileVentures/agile-bot
> jasmine ENABLE_ROLLBAR=false GITTER_API_TOKEN=101010
Started
......._http_client.js:55
throw new Error('Protocol "' + protocol + '" not supported. ' +
^
Error: Protocol "http:" not supported. Expected "https:"
at new ClientRequest (_http_client.js:55:11)
at RequestOverrider.end (/Users/tansaku/Documents/GitHub/AgileVentures/agile-bot/node_modules/nock/lib/request_overrider.js:251:24)
at OverriddenClientRequest.RequestOverrider.req.end (/Users/tansaku/Documents/GitHub/AgileVentures/agile-bot/node_modules/nock/lib/request_overrider.js:159:7)
at Request.end (/Users/tansaku/Documents/GitHub/AgileVentures/agile-bot/node_modules/request/request.js:1397:14)
at end (/Users/tansaku/Documents/GitHub/AgileVentures/agile-bot/node_modules/request/request.js:554:16)
at Immediate.<anonymous> (/Users/tansaku/Documents/GitHub/AgileVentures/agile-bot/node_modules/request/request.js:581:7)
at runCallback (timers.js:574:20)
at tryOnImmediate (timers.js:554:5)
at processImmediate [as _immediateCallback] (timers.js:533:5)
npm ERR! Test failed.  See above for more details.

Running all the tests in a single file did not lead to this issue. Googling the error provided little help, and we were hunting for the source of the issue by commenting out different sections of the code; back to C debugging style. Again it’s entirely possible that our model of the system was just not sufficiently evolved to make sense of this. None of our mocks or requests had any “http” requests, it was all “https”, so the error above didn’t make much sense, and the stack trace didn’t relate to any of our code. I was suspecting it was a timing issue, and throwing up my hands in frustration, I was like, let’s just get this out with the tests in a single file. I want to get some noticeable improvement into production. We had at least got the variable config working.

Michael and I decided to split. He was keen to hunt this bug down, I was anxious to deploy something. We talked about the tension between wanting to learn a new stack and wanting to deliver features to clients. We did a “side by side” session for a while, where Michael hunted on that bug, and I tried to deploy where we were up to staging. I think we just ended up distracting each other. I got caught in another silly bug where I failed to read the stack trace properly:

[tansaku@Samuels-MBP:~/Documents/GitHub/AgileVentures/agile-bot (staging)]$ 
→ npm test
> agile-bot@1.0.0 test /Users/tansaku/Documents/GitHub/AgileVentures/agile-bot
> jasmine ENABLE_ROLLBAR=false GITTER_API_TOKEN=101010
Started
.......undefined:1
undefined
^
SyntaxError: Unexpected token u in JSON at position 0
at Object.parse (native)
at Request._callback (/Users/tansaku/Documents/GitHub/AgileVentures/agile-bot/scripts/av-hangouts-notifications.coffee:33:22)
at self.callback (/Users/tansaku/Documents/GitHub/AgileVentures/agile-bot/node_modules/request/request.js:187:22)
at emitOne (events.js:96:13)
at Request.emit (events.js:188:7)
at Request.onRequestError (/Users/tansaku/Documents/GitHub/AgileVentures/agile-bot/node_modules/request/request.js:813:8)
at emitOne (events.js:96:13)
at OverriddenClientRequest.emit (events.js:188:7)
at /Users/tansaku/Documents/GitHub/AgileVentures/agile-bot/node_modules/nock/lib/request_overrider.js:206:11
at _combinedTickCallback (internal/process/next_tick.js:67:7)
at process._tickCallback (internal/process/next_tick.js:98:9)
npm ERR! Test failed.  See above for more details.

I was trying to follow up by making all the channel IDs in the staging config point to testing channels and changing one of them generated the above error. In my frustration I totally missed the fact that this JSON error was not related to the config file per se. Remember that we rolled our own config and we were pulling in coffee files, not JSON. I spun my wheels for 20 minutes thinking I had some bad character in the config file, before realising that the tests were hard coded to the particular Gitter channel ID I was trying to change in config.

If I’d calmly read the stack trace I’d have seen the failure was actually at a different point in our code i.e. av-hangouts-notifications.coffee:33 which is the last line in the following:

send_gitter_message_avoid_repeats = (channel, message) ->
request.get "https://api.gitter.im/v1/rooms/#{GITTER_ROOMS['saasbook/AV102']}/chatMessages",
auth:
bearer: process.env.GITTER_API_TOKEN
, (error, response, body) ->
payload = JSON.parse body

I think what was happening was that changing the config meant that our test was stubbing the wrong end point and so our test was really trying to hit Gitter and getting back some data it couldn’t parse. Looking at the line in question we can see it is about parsing JSON so the unexpected token makes some sense. Easy mistake, but my frustration at an unfamiliar stack and my worries about delivering visible changes to the community were not helping me make progress. I’d got used to ignoring the stack traces earlier since they had not been something we could follow. A great back to basics lesson for me.

There’s also an important question about how we’re working. Would Michael and I have made faster progress if we’d engaged on both problems together and one of us had given ground about which to work on first? Over night Michael’s made progress on the multi-file issue and also on getting more sophisticated debugging to work which sounds like a wonderful step forward. Michael has more coding time available to him. I have lots of administrative and family commitments. We need to keep working on the best approach to making progress. I feel we have a good dialogue about our work modes. Let’s see how we can improve next week. I’m definitely inspired by Michael’s tenacity to want to get to the point where we can work efficiently in the node tech stack. We’ve made a lot of progress. Although even with a small legacy app I feel like we are balancing on a lot of brittleness. Could we write something cleaner in the latest version of express? Will I break down and create something in Sinatra?

Oh and I forgot to mention, the agile-bot on staging was thrashing, dumping huge data dumps from slack onto the log. I had to shut it down. We’ve upgraded the whole stack of the agile-bot without checking that this set up will work in the deployment environment! More back to basics … I suspect I will need all my patience :-)

Originally published at: http://nonprofits.agileventures.org/2016/09/09/patience/