Repeated 'Error: "toString()" failed' on launch.

[rivermont]

Description

As of yesterday, whenever I try to open Desktop, it tries to sync and then crashes.

Version

GitHub Desktop version:
Unknown - (Latest I think?)

OS version:
Windows 10 (Home), Version 1703, Build 15063.296

Steps to Reproduce

1. Open GitHub Desktop...
2. Wait for it to try and sync...
3. Watch your hopes and dreams crumble.

I have two repos cloned in Desktop; https://github.com/rivermont/spidy and https://github.com/rivermont/instagram-graph.

It opens to spidy, and it appears that there is a push that it never manages to send before crashing.

Expected behaviour:
Open GitHub Desktop without problems.

Actual behaviour:
After opening, Desktop tries to sync and then crashes.

Reproduces how often:
100% of the time.

Attempted Debugging

• Force quit Desktop from Task Manager
• Restart computer.
• Push the commit really fast before it crashes.
• Run Update.exe from \AppData\Local\GitHubDesktop\

###Logs

Crash Report
Displayed in a nice red box with a single Quit button:

GitHub Desktop encountered an uncaught exception, leaving it in an invalid state.

Error: "toString()" failed
at Uint8Array.Buffer.toString (buffer.js:503:11)
at StringDecoder.utf8Text [as text] (string_decoder.js:180:16)
at StringDecoder.write (string_decoder.js:64:46)
at readableAddChunk (_stream_readable.js:164:31)
at Socket.Readable.push (_stream_readable.js:134:10)
at Pipe.onread (net.js:551:20)

Crash Logs
Stolen from \AppData\Roaming\GitHub Desktop\logs\:

2017-05-29T02:21:13.993Z - error: Uncaught exception on renderer process
Error: "toString()" failed
at Uint8Array.Buffer.toString (buffer.js:503:11)
at StringDecoder.utf8Text [as text] (string_decoder.js:180:16)
at StringDecoder.write (string_decoder.js:64:46)
at readableAddChunk (_stream_readable.js:164:31)
at Socket.Readable.push (_stream_readable.js:134:10)
at Pipe.onread (net.js:551:20)

[shiftkey]

@rivermont The stack trace doesn't point to anything in the GitHub Desktop source code, so let's see if we can get a repro together.

Wait for it to try and sync...

So on launch there's a good chance that it's doing a fetch against the repository. Does that sound like what you're seeing?

It opens to spidy, and it appears that there is a push that it never manages to send before crashing.

We shouldn't be doing a push unless it's user-initiated. You should be able to open the Dev Tools before you quit the app - anything interesting in there?

[niik]

I believe, from looking at this stack trace, that we're dealing with reading of data from a git shell command. Looking at your repositories they themselves doesn't seem to be of a size that would cause any problems. Is there any chance you have a large file lying in one of the repositories? Committed or otherwise?

[rivermont]

@shiftkey How can I open the developer tools window? I have maybe 10 seconds on launch before crash.

@niik There are some possibly troublesome files in my spidy folder:

• crawler_done.txt is >500MB
• crawler_words.txt is > 400MB
• and crawler_todo.txt is 24MB

but they've been bigger and it's never had a problem with them before.

I haven't touched the other repo - which *is actually https://github.com/rivermont/instagram-graph - in a while and it's pretty small.

[shiftkey]

@niik nice call on the Git shell output being to blame!

@rivermont Node processes set a limit on the output it will accept - we're setting it to 10MB currently by default whenever we invoke Git but clearly there's some places where this still isn't enough.

Looking at the published repository, I see crawler_done.txt and crawler_words.txt are empty files - I gather you haven't committed local changes to those files, and it's trying to parse the diff and encountering this hard limit...

[shiftkey]

Related issues: #1686 and #997

[rivermont]

Thanks guys! So moving the large files out of the folder before starting Desktop allowed it to sync properly. I could then place the files back in and it could process them. It seems that one needs to do this after restarting or force-quitting Desktop; once launched it can be opened just fine.

[niik]

Thank you so much for confirming the theory @rivermont. I'm gonna keep this issue open for a little bit as we try to get to the bottom of what's happening.

we're setting it to 10MB currently by default whenever we invoke Git but clearly there's some places where this still isn't enough.

@shiftkey I don't understand why that limit would produce this particular error though. Reading through some issues online it seems to me that the most likely cause of this particular error is us hitting the maximum string length as defined by V8 (256mb). Our stdout buffer cap should kick in way before that and I wouldn't expect it to throw this particular error either. In trying to reproduce this I intentionally triggered the max stdout buffer case and got this error which is what I would expect.

(Note that the fact that we're not catching this is pretty terrible in itself but it's not directly related to the stack provided by @rivermont)

I think this is related to #1524

@rivermont I'd really like to be able to reproduce this but so far I haven't been able to. Is there anything else you can tell us about your environment? How's your memory consumption? Are you running close to your maximum memory?

Would you be willing to zip up your entire repository with the offending files and let me have a look at it? I imagine since you're mostly dealing with textual content that they'd compress fairly well. We can arrange for you to send it to us privately if that would help.

[shiftkey]

@niik yeah, the stack trace is very different to our typical error handling for the process output - I've not dug into recreating this yet but this thread from Node core does feel relevant nodejs/node#3175

[rivermont]

Here is a screencast of the crash in action, along with Task Manager watching:

http://recordit.co/EU5MD0nquH

It seems that if anything I'm running out of CPU power first; it stops before memory usage climbs above 60%, around 30% at idle.

[shiftkey]

@rivermont if you still have the repository in that weird state, could you open it in a cmd window and run these commands (swap crawler_done.txt for whichever file looks interesting).

To get the number of lines in the file:

> for /f "usebackq" %A in (`TYPE crawler_done.txt ^| find /v /c "" `) do set numlines=%A

To get the total size (in bytes) of the file:

> FORFILES /m crawler_done.txt /c "cmd /c echo @fsize"

This will help give an idea of the file we need to recreate to trigger this issue.

[rivermont]

crawler_done.txt is 513MB (538017268 bytes), and using glogg shows that there are 15172 lines.

Your first command (run both in Powershell and vanilla command prompt) gave me a Missing closing ')' in expression. error.

I am going to try some tests with files of different sizes using fsutil, to see at which point it causes errors.

[rivermont]

It seems that the problem is not with the file size but with the contents of the file...?
Having the crawler_done.txt` file in the folder causes the crash, but an empty file of greater size created using

fsutil file createnew crawler_done.txt 535288000

has no effect. GitHub Desktop will launch just fine. I tried to upload crawler_done.txt to Pastebin but it broke. I will try to find another service, but 500MB might be too big for anyone.
The file is made of URLs scraped by spidy, so there may be some non-Unicode characters or something.

[rivermont]

Update: crawler_done.txt is now hosted via Uploadfiles.io at https://ufile.io/rty5g

[shiftkey]

@rivermont thanks for the link. I'll try it out here and see if I can get the same issue.

Having the crawler_done.txt file in the folder causes the crash, but an empty file of greater size created using ... has no effect.

I'm seeing the same thing here. Very interesting...

[shiftkey]

Running this up against a debug version of Node 7.4 (the one that ships with Electron) I can get a similar error by just reading the contents of the file:

C:\Users\shiftkey\src\node>type test.js
const fs = require('fs')

const path = 'C:\\Users\\shiftkey\\src\\crawler_done.txt'

const text =  fs.readFileSync(path, { encoding: 'utf-8' })

console.log(`got a file with ${text.length} bytes`)
C:\Users\shiftkey\src\node>Debug\node -e "console.log('Hello from Node.js', process.version)"
Hello from Node.js v7.4.0

C:\Users\shiftkey\src\node>Debug\node test.js
buffer.js:503
    throw new Error('"toString()" failed');
    ^

Error: "toString()" failed
    at Buffer.toString (buffer.js:503:11)
    at Object.fs.readFileSync (fs.js:512:41)
    at Object.<anonymous> (C:\Users\shiftkey\src\node\test.js:5:18)
    at Module._compile (module.js:571:32)
    at Object.Module._extensions..js (module.js:580:10)
    at Module.load (module.js:488:32)
    at tryModuleLoad (module.js:447:12)
    at Function.Module._load (module.js:439:3)
    at Module.runMain (module.js:605:10)
    at run (bootstrap_node.js:420:7)

C:\Users\shiftkey\src\node>

That's this code. It's following the result = slowToString.apply(this, arguments); path, so at least know where it's failing.

EDIT: looks like we're deep into node_buffer.cc to fix this.

Tweaking this to drop the encoding parameter returns a buffer with Great Success™:

C:\Users\shiftkey\src\node>type test.js
const fs = require('fs')

const path = 'C:\\Users\\shiftkey\\src\\crawler_done.txt'

const buffer =  fs.readFileSync(path)

console.log(`got a buffer with ${buffer.length} bytes`)
C:\Users\shiftkey\src\node>Debug\node test.js
got a buffer with 538017268 bytes

I'm trying to get VS to break into node.exe when it errors (it seems doable) but this doesn't seem to trip as I'd hoped.

[shiftkey]

So I've nailed this down to the file contents and how we handle this in the app.

To begin with, let's just read the file in using less on Windows. We get to line 282 and it then starts spitting out garbage characters:

    275 https://twitter.com/search?q=%23ycc2015%20AND%20%23U16B&f=tweets&lang=ca
    276 https://twitter.com/search?q=%23ycc2015%20AND%20%23U16B&lang=zh-tw&f=tweets
    277 https://abs.twimg.com/a/1495774371/css/t1/twitter_core.bundle.css
    278 https://abs.twimg.com/a/1495774371/img/search/ic_places_yelp_logo.png
    279 http://play.usaultimate.org/events/2016-Northeastern-High-School-Regional-Championships/schedule/Girls/High-S    279 chool-Girls/
    280 http://www.usaultimate.org/news/2012-hs-states-nominations-coty-mixed/
    281 http://usaultimate.org/archives/2016_youth.aspx#about
    282 http://play.usaultimate.org/events/2016-Georgia-High-School-Girls-State-Championship\\\\\\\\\\\\\\\\\\\\\\\\\   
282 \\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\
282 \\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\
282 \\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\
282 \\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\
282 \\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\

Changing this up to use git diff you'll see the same thing:

$ git diff HEAD --no-ext-diff --patch-with-raw -z --no-color -- crawler_done.txt
...
+https://twitter.com/search?q=%23ycc2015%20AND%20%23U16B&f=tweets&lang=ca
+https://twitter.com/search?q=%23ycc2015%20AND%20%23U16B&lang=zh-tw&f=tweets
+https://abs.twimg.com/a/1495774371/css/t1/twitter_core.bundle.css
+https://abs.twimg.com/a/1495774371/img/search/ic_places_yelp_logo.png
+http://play.usaultimate.org/events/2016-Northeastern-High-School-Regional-Championships/schedule/Girls/High-School-Girls/
+http://www.usaultimate.org/news/2012-hs-states-nominations-coty-mixed/
+http://usaultimate.org/archives/2016_youth.aspx#about
+http://play.usaultimate.org/events/2016-Georgia-High-School-Girls-State-Championship\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\

For reference, on MacOS this problem file is detected as binary:

$ git diff HEAD --no-ext-diff --patch-with-raw -z --no-color -- crawler_done.txt
:100644 100644 e69de29... 0000000... M^@crawler_done.txt^@^@diff --git a/crawler_done.txt b/crawler_done.txt
index e69de29..f394c0a 100644
Binary files a/crawler_done.txt and b/crawler_done.txt differ

I've traced this behaviour through to string_bytes.cc.

      val = String::NewFromUtf8(isolate,
                                buf,
                                String::kNormalString,
                                buflen);

As this isn't doing any encoding detection, and just failing quietly when it encounters the corrupted bytes, we have a couple of options:

• propose a patch to https://github.com/electron/node to handle this better and update Electron in the future. I'm not sure what the right behaviour should be here, but maybe some inspiration will strike. We're also currently blocked on "EPERM: operation not permitted" when tearing down electron.exe electron/electron#9583 which is also Windows-specific, so I'm hesitant to go too further with this.
• switch the diff output over to binary output and attempt the encoding in the app, so we can handle this failure gracefully. I spiked this out in [HACK WEEK][WIP] refining our encodings support #634 but the diff parsing code has changed since then, so it's not as simple as cherry-picking some commits over.

[shiftkey]

For reference, I was able to trigger #1524 just now on macOS using this file. So at least we know these are inter-related...

[shiftkey]

I've mirrored the problem file on Dropbox for those who want to play around with it in the app with the spidy repo.

[joshaber]

switch the diff output over to binary output and attempt the encoding in the app, so we can handle this failure gracefully

It seems like this is something we'll have to do eventually anyways, to support different encodings (cc #1607). So I'd certainly lean towards this.

[shiftkey]

@joshaber yeah, that's the way I'm heading right now to make the crashes go away sooner 😛