He's Dead, Jim!

He's Dead, Jim!

September 20, 2014 - by Patrick van Bergen

hes-dead-jim.png

The narrowcasting application I had written in Javascript to run exclusively on Chrome was running smoothly. The single page interface showed a presentation, and was running for hours on end. And then, without notice, it crashed.

I had hit what Chrome developers call a "Sad Tab". Such a crashed tab does not respond to any keys and is not debuggable from the current browser session. The only message shown says that the most likely cause is a full memory, but that's just a statistical truth that tells you nothing about your particular case. What should you do?

To check the "memory full" theory, you can run the application and see how its memory usage changes over time. You will see it accumulate and drop occasionaly as the garbage collector kicks in. If it just accumulates, you may have to look for a memory leak in the code. In my case, memory usage was fine.

When Chrome crashes, it does not provide any means to find out what has made it crash. It is not possible to inspect its current state, because there isn't any left. The process was killed and removed.

You can send a crash report to the Chrome developers by following the suggestions on the page

chrome://crashes

The page is only helpful if crash reporting is enabled via Settings / Advanced settings / Automatically report details of possible security incidents to Google

Maybe this will fix your problem, but if you want to have more control over the process, read on.

Via the event log of the operating system it may be possible to locate the application event that was generated when Chrome crashed. But not every tab crash ends up here. If it does, it will give you the time of the crash, and some error information. I did not find the information helpful. Or you may try to run Chrome on WinDbg (for Windows) to generate a memory dump. In my case it was very uninsightful. However, it is very useful to know at least the time of the crash.

Next, what you should do is run Chrome with logging turned on

chrome --enable-logging --v=1

It will create a file called `chrome_debug.log` in Chrome's AppData directory of the active user. Check this page.

Depending on the sort of application you are running, this will provide you with a serious amount of information. Together with the time of the crash, this will give you some insight in the state of Chrome at the time of the crash.

This is what the log looked like in my case:

[4832:5848:0903/145513:VERBOSE1:resource_loader.cc(348)] OnReadCompleted: "http://player.narrowcasting.customersite.nl/l/nl/narrowcasting/player/30/getPresentation/c5235c5082e9fece182b5228ccbe93a800ab066d" bytes_read = 23554
[4832:5848:0903/145513:VERBOSE1:resource_loader.cc(348)] OnReadCompleted: "http://player.narrowcasting.customersite.nl/l/nl/narrowcasting/player/30/getPresentation/c5235c5082e9fece182b5228ccbe93a800ab066d" bytes_read = 8769
[4832:5848:0903/145513:VERBOSE1:resource_loader.cc(348)] OnReadCompleted: "http://player.narrowcasting.customersite.nl/l/nl/narrowcasting/player/30/getPresentation/c5235c5082e9fece182b5228ccbe93a800ab066d" bytes_read = 16376
[4832:5848:0903/145513:VERBOSE1:resource_loader.cc(348)] OnReadCompleted: "http://player.narrowcasting.customersite.nl/l/nl/narrowcasting/player/30/getPresentation/c5235c5082e9fece182b5228ccbe93a800ab066d" bytes_read = 13670
[4832:5848:0903/145513:VERBOSE1:resource_loader.cc(348)] OnReadCompleted: "http://player.narrowcasting.customersite.nl/l/nl/narrowcasting/player/30/getPresentation/c5235c5082e9fece182b5228ccbe93a800ab066d" bytes_read = 0
[4832:5848:0903/145513:VERBOSE1:resource_loader.cc(637)] ResponseCompleted: http://player.narrowcasting.customersite.nl/l/nl/narrowcasting/player/30/getPresentation/c5235c5082e9fece182b5228ccbe93a800ab066d
[0903/145515:VERBOSE1:ipc_sync_channel.cc(385)] Canceling pending sends
[0903/145515:VERBOSE1:ipc_sync_channel.cc(385)] Canceling pending sends
[0903/145515:VERBOSE1:ipc_sync_channel.cc(385)] Canceling pending sends
[4832:5848:0903/145628:VERBOSE1:resource_loader.cc(308)] OnResponseStarted: chrome-extension://pafkbggdmjlpgkdkcbjmhmfcdpncadgh/_generated_background_page.html
[4832:5848:0903/145628:VERBOSE1:resource_loader.cc(348)] OnReadCompleted: "chrome-extension://pafkbggdmjlpgkdkcbjmhmfcdpncadgh/_generated_background_page.html" bytes_read = 129
[4832:5848:0903/145628:VERBOSE1:resource_loader.cc(348)] OnReadCompleted: "chrome-extension://pafkbggdmjlpgkdkcbjmhmfcdpncadgh/_generated_background_page.html" bytes_read = 0
[4832:5848:0903/145628:VERBOSE1:resource_loader.cc(637)] ResponseCompleted: chrome-extension://pafkbggdmjlpgkdkcbjmhmfcdpncadgh/_generated_background_page.html
[4832:5848:0903/145628:VERBOSE1:resource_loader.cc(308)] OnResponseStarted: chrome-extension://pafkbggdmjlpgkdkcbjmhmfcdpncadgh/utility.js

The crash occurred just before the "Canceling pending sends". Chrome had just completed reading an external file when it crashed. On 145628 (which means 14:56:28) it starts loading the "He's dead, Jim" page.

Looking at several of these reports, after several new crashes, I noticed that the crashes happened just after a certain file was loaded. However, the application performed a bunch of actions just after loading the file.

At that point I was out of regular debugging options, and still unsuccessful. I wanted to know what line of the application code Chrome was executing at the time of the crash. The only thing I could think of was just plain console-logging. But I really didn't want to add a line of `console.log` to every second line of code. It would mess up my beautifully composed work. There had to be a smarter way.

I came up with the following. Using Javascript's powerful class modification possibilities, I thought I could rewrite all methods and make them log to the console before continuing with their actual work.

I wrote a function that replaced all of a class's methods by new functions. Each new function did two things:

  1. call console.log() with information about the function call and its arguments, and
  2. call the original function with the original arguments

In my case the class methods were located in the `prototype` property of the constructor function. A classic class setup. Each of the functions in this property I replaced with the result (a wrapper function) of this function:

createLoggingWrapper = function(className, functionName, functionBody)
{
    var self = this;

    var wrapper = function() {

        // log the function call
        self.logFunctionCall(className, functionName, arguments);

        // call the original function
        return functionBody.apply(this, arguments);
    }

    return wrapper;
}

Then I specified all the classes that I needed to have logging. All of this code was only activated if I added a special argument to the application, of course.

At this point, the console showed at runtime exactly which function was called. When Chrome crashed, it showed the last method of the code called.

Even if Chrome is to crash completely, and not just a single tab, the console messages will still show up in the `chrome_debug.log`. Like in this example:

[4176:3256:0917/170845:INFO:CONSOLE(90)] "5:08:45 PM FileSystem:fileExists(003623e8a02f33f1e24f47f5258e8603e3cf8c2c)", source: http://player.narrowcasting.customersite.nl/files/mod_narrowcasting/player/component/FunctionLogger.js (90)
[4176:3256:0917/170845:INFO:CONSOLE(90)] "5:08:45 PM FileSystem:getUrl(003623e8a02f33f1e24f47f5258e8603e3cf8c2c)", source: http://player.narrowcasting.customersite.nl/files/mod_narrowcasting/player/component/FunctionLogger.js (90)

At 170845 (17:08:45) Chrome logs the console log line "5:08:45 PM FileSystem:getUrl(003623e8a02f33f1e24f47f5258e8603e3cf8c2c)" that I generated. In the class `FileSystem` the function `getUrl` was called, with a single parameter.

I ran the application several times and each time it crashed it showed the same method as the last one executed. I had found the culprit.

PS: when you do a lot of logging, you probably best close the developer tools window showing the console.log entries. I found a large log window itself to be a cause of tab crashes (buffer overflow?). When your app crashes, inspect chrome_debug.log.

Share this post!

Comments

Leave a comment!

Italic and bold

*This is italic*, and _so is this_.
**This is bold**, and __so is this__.

Links

This is a link to [Procurios](http://www.procurios.nl).

Lists

A bulleted list can be made with:
- Minus-signs,
+ Add-signs,
* Or an asterisk.

A numbered list can be made with:
1. List item number 1.
2. List item number 2.

Quote

The text below creates a quote:
> This is the first line.
> This is the second line.

Code

A text block with code can be created. Prefix a line with four spaces and a code-block will be made.