Standard output from workers gets corrupted, consider sending over IPC instead

[F1LT3R]

Description

AVA seems to sometimes garble node-canvas dataurls that I stdout back out to the console. This behavior is reproducible, but slight tweaks to the values make it work/not-work. Very odd. I spent the past few days thinking Node-Canvas was buggy. Now I think AVA might be doing some transpiling or character replacement under the hood that's throwing things off perhaps?

Test Source

This output is what I expect to see in my console after running the code...

Here is that code:

const canvas = require('canvas')

const meassureFontChar = font => {
	const _canvas = canvas.createCanvas(0, 0)
	const _ctx = _canvas.getContext('2d')
	_ctx.font = font
	const size = _ctx.measureText('W')
	return size
}

class Thing {
	constructor (opts) {
		this.opts = opts
	}

	start () {
		const fontSize = meassureFontChar('bold 23px Courier')

		this.canvas = canvas.createCanvas(201, 56)
		this.ctx = this.canvas.getContext('2d')
		this.ctx.font = 'regular 13px Courier'

		this.ctx.antialias = 'subpixel'
		this.ctx.fillStyle = '#000'
		this.ctx.fillRect(0, 0, this.canvas.width, this.canvas.height)

		const offsetTop = fontSize.emHeightAscent + fontSize.emHeightDescent
		const offsetLeft = 0
		this.ctx.translate(offsetLeft, offsetTop)
		this.ctx.scale(2, 2)
	}

	chunk () {
		this.ctx.fillStyle = 'rgba(0, 0, 0, 0)'
		this.ctx.fillRect(0, -11.200000000000001, 42.0068359375, 15)
		this.ctx.fillStyle = '#D3D3D3'
		this.ctx.fillText('Your ', 0, 0)
		this.ctx.fillStyle = 'rgba(0, 0, 0, 0)'
		this.ctx.fillRect(42.0068359375, -11.200000000000001, 33.60546875, 15)
		this.ctx.fillStyle = '#B22222'
		this.ctx.fillText('wish', 42.0068359375, 0)
		this.ctx.fillStyle = 'rgba(0, 0, 0, 0)'
		this.ctx.fillRect(75.6123046875, -11.200000000000001, 25.2041015625, 15)
		this.ctx.fillStyle = '#D3D3D3'
		this.ctx.fillText(' is', 75.6123046875, 0)
		this.ctx.fillStyle = 'rgba(0, 0, 0, 0)'
		this.ctx.fillRect(0, 3.799999999999999, 8.4013671875, 15)
		this.ctx.fillStyle = '#D3D3D3'
		this.ctx.fillText(' ', 0, 15)
		this.ctx.fillStyle = '#DAA520'
		this.ctx.fillRect(8.4013671875, 3.799999999999999, 16.802734375, 15)
		this.ctx.fillStyle = '#D3D3D3'
		this.ctx.fillText('my', 8.4013671875, 15)
		this.ctx.fillStyle = 'rgba(0, 0, 0, 0)'
		this.ctx.fillRect(25.2041015625, 3.799999999999999, 75.6123046875, 15)
		this.ctx.fillStyle = '#D3D3D3'
		this.ctx.fillText(' command.', 25.2041015625, 15)
	}

	end () {
		const data = this.canvas.toDataURL()
		console.log(`\u001B]1337;File=inline=1:${data.substr(22)}\u0007`)
	}
}

const thing = new Thing({})
thing.start()
thing.chunk()
thing.end()

But here is what I get if I wrap that same code in an AVA test:

I get a DATA URL back, but the console log seems to get destroyed. Lines get deleted upwards and such.

Here is that code wrapped in a test. Apologies for the repetition.

import canvas from 'canvas'
import test from 'ava'

test('thing', t => {
    const meassureFontChar = font => {
        const _canvas = canvas.createCanvas(0, 0)
        const _ctx = _canvas.getContext('2d')
        _ctx.font = font
        const size = _ctx.measureText('W')
        return size
    }

    class Thing {
        constructor (opts) {
            this.opts = opts
        }

        start () {
            const fontSize = meassureFontChar('bold 23px Courier')

            this.canvas = canvas.createCanvas(201, 56)
            this.ctx = this.canvas.getContext('2d')
            this.ctx.font = 'regular 13px Courier'

            this.ctx.antialias = 'subpixel'
            this.ctx.fillStyle = '#000'
            this.ctx.fillRect(0, 0, this.canvas.width, this.canvas.height)

            const offsetTop = fontSize.emHeightAscent + fontSize.emHeightDescent
            const offsetLeft = 0
            this.ctx.translate(offsetLeft, offsetTop)
            this.ctx.scale(2, 2)
        }

        chunk () {
            this.ctx.fillStyle = 'rgba(0, 0, 0, 0)'
            this.ctx.fillRect(0, -11.200000000000001, 42.0068359375, 15)
            this.ctx.fillStyle = '#D3D3D3'
            this.ctx.fillText('Your ', 0, 0)
            this.ctx.fillStyle = 'rgba(0, 0, 0, 0)'
            this.ctx.fillRect(42.0068359375, -11.200000000000001, 33.60546875, 15)
            this.ctx.fillStyle = '#B22222'
            this.ctx.fillText('wish', 42.0068359375, 0)
            this.ctx.fillStyle = 'rgba(0, 0, 0, 0)'
            this.ctx.fillRect(75.6123046875, -11.200000000000001, 25.2041015625, 15)
            this.ctx.fillStyle = '#D3D3D3'
            this.ctx.fillText(' is', 75.6123046875, 0)
            this.ctx.fillStyle = 'rgba(0, 0, 0, 0)'
            this.ctx.fillRect(0, 3.799999999999999, 8.4013671875, 15)
            this.ctx.fillStyle = '#D3D3D3'
            this.ctx.fillText(' ', 0, 15)
            this.ctx.fillStyle = '#DAA520'
            this.ctx.fillRect(8.4013671875, 3.799999999999999, 16.802734375, 15)
            this.ctx.fillStyle = '#D3D3D3'
            this.ctx.fillText('my', 8.4013671875, 15)
            this.ctx.fillStyle = 'rgba(0, 0, 0, 0)'
            this.ctx.fillRect(25.2041015625, 3.799999999999999, 75.6123046875, 15)
            this.ctx.fillStyle = '#D3D3D3'
            this.ctx.fillText(' command.', 25.2041015625, 15)
        }

        end () {
            const data = this.canvas.toDataURL()
            console.log(`\u001B]1337;File=inline=1:${data.substr(22)}\u0007`)
        	t.pass()
        }
    }

    const thing = new Thing({})
    thing.start()
    thing.chunk()
    thing.end()
})

Here is where things get super-weird.

If I change the background color of the canvas on line 26...

- 26            this.ctx.fillStyle = '#000'
+ 26            this.ctx.fillStyle = '#AAA'

... now I see the logged image.

Remember, this weird behavior does not happen without AVA.

Is this a transpiling issue?

It's a bit frustrating that I can't use AVA to run canvas tests and see the results in the CLI. As a work-around I can probably export the dataurl to a file for now.

Error Message & Stack Trace

N/A

Config

Copy the relevant section from package.json:

{
	"ava": {
		"failFast": true
	}
}

Command-Line Arguments

Copy your npm build scripts or the ava command used:

ava canvas.test.js

Environment

Node.js v9.6.1
darwin 17.4.0
ava --version 0.25.0
npm --version 5.6.0

[novemberborn]

I don't think this is a transpiling issue. Since tests run in child processes it might just be hard to forward standard output reliably, especially if there's several kilobytes of it. Perhaps you could give https://github.com/avajs/ava/pull/1722 a try? It has better process communication and writes all standard output from the test files to stderr on the main process.

Data may still get cut up into multiple chunks though. I've considered capturing all standard output and sending it through the process communication channel, which should be more consistent, but didn't think it was worth it. It might solve your use case so perhaps it's something to consider.

(I'm closing this issue for housekeeping purposes, for now, but let's keep the conversation going.)

[F1LT3R]

Thanks @novemberborn - I've whittled things down a bit, and created a test case for you:

AVA iTerm2 - No 1337 IMG Support

https://github.com/F1LT3R/ava-iterm2-no-1337-img

I'm happy to try #1722 if you can give me instructions on how to do this? If it's complicated, perhaps you might find it easier to run my test case than explaining it to me. :)

[novemberborn]

Cheers for the test case @F1LT3R. This is not working with #1722. I'll reopen this issue, and I am tempted to make all worker->AVA communication go over IPC, rather than having some go over stdout / stderr, but no guarantees on whether that'll actually happen.

For the time being it seems t.log() works, though arguably that should escape ANSI codes too.

[F1LT3R]

Thanks, @novemberborn - makes sense.

Good to know about t.log, I will try that out.

[F1LT3R]

The things that makes this really tricky @novemberborn - I'm writing an image diff library to run in AVA, so you get image diffs in the CLI as colored ANSI output. Logging via t requires passing t to my library, which feels really weird. I wouldn't want the user to have to pass t.log into the function that calls my library just so they could see the correct visual output.

Hope that makes sense.

What works is if I pass in t and then call t.log from within my library. But what fails is pass t.log and calling that function, because I get:

TypeError {
    message: 'Cannot read property \'addLog\' of undefined',
}

This also makes my test look like this...

test('Scorecard grid', async t => {
	const img1 = 'fixtures/green-circle.jpg'
	const img2 = 'fixtures/green-circle.png'
	const opts = {
		grid: {
			columns: 8,
			rows: 8
		},
		tolerance: {
			hue: 1,
			sat: 20,
			lum: 0.2,
			alp: 0
		},
		display: {
			images: 32
		},
		$MODE: 'CLI',
		// Can't add T here (merging kills the function)
		t
	}
    // I'm forced to pass t in as a param
    //            passing in t here -----------\ /
	const result = await fuzi(img1, img2, opts, t)
	t.true(result.fail)
})

Then inside my library:

	if (t) {
		t.log(ansiImgDiff)
	}

This is far from ideal. I would have to ask the user to pass t into every call to the library.

This is output that should only be being seen in CI. Putting some kind of "if it fails, then t.log(all the image diff info)" into each test, would be so cumbersome.

At the moment this is making me wish I'd stuck with Mocha, but I'm hoping I can find a workaround because I prefer AVA.

[F1LT3R]

"I am tempted to make all worker->AVA communication go over IPC, rather than having some go over stdout / stderr, but no guarantees on whether that'll actually happen."

Is this something I could do? Can you point me in the right direction @novemberborn ?

[novemberborn]

I'm hoping to try this in #1722. You're welcome to have a poke around as well. Perhaps start with the reporters and work your way back to fork.js and then the workers.

[F1LT3R]

Ok thanks @novemberborn

[F1LT3R]

In case this helps anyone:

• Calling t.log() from within my test file test('x', async t) logs long output strings correctly
• Calling t.log() directly from within an imported library still seems to cause long output strings to get corrupted

The least painful workaround I have for now is to add a reporter option to my tests:

test('My img diff test', async t => {
	const img2 = 'fixtures/green-circle.jpg'
	const img1 = 'fixtures/green-circle.png'

	const opts = {
		tolerance: {
			hue: 1,
			sat: 20,
			lum: 0.2,
			alp: 0
		},

        // PASS IN A REPORTER CALLBACK OPTION HERE
		reporter: err => {
			t.log(err)
		}
	}
	const result = await fuzi(img1, img2, opts)
	t.true(result.fail)

Then I can pass this back into the context of test(), which then gives the inline output correctly when tests fail:

It appears that t.log() is already using IPC? It definitely feels a lot slower using t.log() than console.log(), but at least the output is correct.

[novemberborn]

It appears that t.log() is already using IPC?

It does, yea.

t definitely feels a lot slower using t.log() than console.log(), but at least the output is correct.

Yea that's one concern, but I don't think raw stdout performance is critical for test runs. We'll see 😄

[F1LT3R]

Is there a trick to get t.log to work in CI?

Even though t.log helps locally, things still look ugly remote:

https://travis-ci.org/F1LT3R/fuzi/builds/368486782

Locally with t.log this looks like:

[novemberborn]

@F1LT3R that's likely your CI not handling the image output. I don't think that's related to AVA.

[F1LT3R]

It's not images being output. It's ANSI characters.

From what I'm seeing, IPC might not be doing what you expect on Linux. (Assuming you would expect 0 corruptions over IPC.)

Note: even if I remove all ANSI escape sequences from the t.log calls, I still see corruptions in CI.

[novemberborn]

Sure, was just trying to say that it might depend on your CI understanding the sequences.

I think Node.js serializes the IPC communication so it shouldn't get chopped up. Note that t.log() does apply some formatting so perhaps you're running into that.

[novemberborn]

I decided to land #1722 without trying this. I still want to look into this, though if anybody else wants to give it a try please give a shout.