Remote Debugging - issues with Network.getResponseBody

[Nathan Wray]

I'm running a home-rolled debugging app on CentOS 6, attached to a
build of Chromium "17.0.927.0 (Developer Build 108270 Linux) custom"
(BUILDTYPE=Release, I don't have enough ram to compile for Debug)

Command line switches are:
--proxy-server=our.proxyserver.com:1234
--remote-debugging-port=<an available port>
--disable-popup-blocking
--user-data-dir=<a new directory in temp>
--disable-translate
--no-default-browser-check
--no-message-box
--no-process-singleton-dialog
--noerrdialogs
--no-first-run
--disable-geolocation
about:blank

I send some initialization messages:
{"method": "Console.enable", "id": 23}
{"method": "Console.clearMessages", "id": 24}
{"method": "Network.clearBrowserCache", "id": 25}
{"method": "Network.clearBrowserCookies", "id": 26}
{"method": "Network.enable", "id": 27}
{"method": "Page.enable", "id": 28}
{"method": "Network.setUserAgentOverride", "id": 29, "params":
{"userAgent": "Mozilla/5.0 (Linux; U; Android 2.2.2; en-us; SPH-M920
Build/FROYO) AppleWebKit/533.1 (KHTML, like Gecko) Version/4.0 Mobile
Safari/533.1"}}
{"method": "Network.setExtraHTTPHeaders", "id": 30, "params":
{"headers": { "Accept-Encoding": "gzip" } } }
{"method": "Page.open", "id": 31, "params": {"url": "http://
www.google.com/"}}

(Note that I'm sending the UA string for a Samsumg Android phone, so
I'm receiving a mobile version of the page www.google.com.)

At this point I receive the expected Network.requestWillBeSent,
Network.responseReceived, Network.dataReceived, and
Network.loadingFinished messages for various resources followed by a
Page.loadedEventFired.


If I modify my code to request the body of each resource immediately
after I receive the Network.loadingFinished for that resource, a few
funny things happen:
2011-11-04 10:11:55,824 DEBUG [Thread-11] ChromeSocketClient -
Sending: {"id": 34,"method": "Network.getResponseBody","params":
{"requestId": "8415.13"}}

1) I never get any response on 2 or more resources from www.google.com,
including not receiving an error message of any kind. This varies,
sometimes I'll see 3 or 4 with no response. I get the expected bodies
for the other elements, and generally get the HTML for the base page.

2011-11-04 10:14:55,504 DEBUG [http-80-2] 2 outstanding content
requests:
2011-11-04 10:14:55,506 DEBUG [http-80-2] 34 -->
http://www.google.com/extern_js/f/CgJlbhICdXMrMEU4ACwrMFo4ACwrMA44ACwrMBc4ACwrMDw4ACwrMFE4ACwrMJgBOAAsKzAKOACaAgNtb2IsKzAWOAAsKzAZOAAsKzA1OAAsKzBBOAAsKzBNOAAsKzBOOAAsKzBTOACaAgZzZWFyY2gsKzBUOAAsKzBpOAAsKzBrOAAsKzB2OAAsKzB7OAAsKzCAATgALCswhAE4ACwrMIoBOAAsKzCMATgALCswkgE4ACwrMJYBOAAsKzCoATgALCswrAE4ACwrMLMBOAAsKzC-ATgALCswdzgALCswiwE4ACwrMBg4ACwrMCY4ACyAAlaQAlY/OtFzXg6qbKk.js
2011-11-04 10:14:55,506 DEBUG [http-80-2] 35 -->
http://www.google.com/mbd?mbtype=56&hl=en

I'll also occasionally not get a body for this one:
2011-11-04 11:04:26,836 DEBUG [http-80-2] Harlet - 34 -->
http://www.google.com/images/srpr/logo3w.png

And I'll occasionally see , late in the logfile,
Network.requestWillBeSent messages for the following that are never
followed up with any response, data or loaded messages:
2011-11-04 11:04:26,839 DEBUG [http-80-2] Harlet - never received
loadingFinished for rc: http://clients1.google.com/generate_204
2011-11-04 11:04:26,839 DEBUG [http-80-2] Harlet - never received
loadingFinished for rc: http://www.gstatic.com/m/images/gray_dot.png

2) I never* receive the Page.loadedEventFired message.
* - I have seen once or twice where I received the
Page.loadedEventFired message, and instead received no responses to
any of the Network.getResponseBody requests.

I also tried waiting until the Page.loadedEventFired is received and
then asking for the content of each item, first in batch and then
later one at a time. In both cases I never received any response to
any of the content requests.

I've tested on a few sites, really just prototyping at this point.
The www.google.com mobile site is where I'm consistently seeing these
issues. I believe I had fewer issues on Windows with a Chrome dev
binary. I'm not set up to verify that right now but it may be my next
step.

Anyone have any thoughts on how to get to the root of this, or
anecdotes about remote debugging being unstable and/or non-
deterministic (on Chromium, CentOS, Linux or in general)?
It's almost as though the remote debugging thread(s) are dying in the
browser, is there a logging facility that I can turn on to see any
error messages or dumps from the browser side?

Thanks for any ideas you may have.

BR
Nathan

[pfeldman]

It sounds like the websocket connection terminates. Could you share
the script that is issuing commands? What websocket library are you
using? What version of websocket are you using?

Pavel

> 2011-11-04 10:14:55,506 DEBUG [http-80-2]   34 -->http://www.google.com/extern_js/f/CgJlbhICdXMrMEU4ACwrMFo4ACwrMA44ACw...

> 2011-11-04 10:14:55,506 DEBUG [http-80-2]   35 -->http://www.google.com/mbd?mbtype=56&hl=en
>
> I'll also occasionally not get a body for this one:
> 2011-11-04 11:04:26,836 DEBUG [http-80-2] Harlet -      34 -->http://www.google.com/images/srpr/logo3w.png
>
> And I'll occasionally see , late in the logfile,
> Network.requestWillBeSent messages for the following that are never
> followed up with any response, data or loaded messages:
> 2011-11-04 11:04:26,839 DEBUG [http-80-2] Harlet - never received
> loadingFinished for rc:http://clients1.google.com/generate_204
> 2011-11-04 11:04:26,839 DEBUG [http-80-2] Harlet - never received
> loadingFinished for rc:http://www.gstatic.com/m/images/gray_dot.png
>
> 2) I never* receive the Page.loadedEventFired message.
> * - I have seen once or twice where I received the
> Page.loadedEventFired message, and instead received no responses to
> any of the Network.getResponseBody requests.
>
> I also tried waiting until the Page.loadedEventFired is received and
> then asking for the content of each item, first in batch and then
> later one at a time.  In both cases I never received any response to
> any of the content requests.
>
> I've tested on a few sites, really just prototyping at this point.

> Thewww.google.commobile site is where I'm consistently seeing these

[Nathan Wray]

I'm using the tootallnate websocket library with protocol DRAFT76.  I continue to send and receive messages after the non-responsive body requests, it doesn't appear to be a connection issue.  I'll put together a complete communication log Monday to share.

[Ilya Tikhonovsky]

I'd recommend try to receive an error for a wrong formatted message and a message with no command or id field.

JFYI: The websocket spec was changed significantly this year.  Our backed supports hybi17 version at the moment.

Hixie76 is supported only for backward compatibility with older versions of chrome and safari.

Regards,
Tim.

[Nathan Wray]

Tim, Pavel;

Attached in a zipfile is an I/O log from my app to the browser.  It includes my app sending an invalid request {"method": "Gibberish.notARealMethod", "id": 34} for which no response is received.  I called out some of the requests and their response in a spreadsheet (csv and xlsx).  The request at 2011-11-07 08:27:32,177 is the last one to receive any response, although the app continues to receive messages from the browser. 

Also the request for 24475.3 incorrectly receives an error response:

{"error":{"code":-32000,"message":"No data found for resource with given identifier"},"id":28}

If there is anything you can suggest testing it would be appreciated.

Thank you
Nathan

[Nathan Wray]

For grins, I also added a Page.open call near the end:

{"method": "Page.open", "id": 38, "params": {"url": "https://www.yahoo.com"}}

with a 5 second wait afterwards.  The browser didn't react to this message (the page was not opened, in addition to no acknowledge message being sent).  So there seems to be a breakdown between send and receive. 

I've added some logging in the WebSocket library I'm using's send method and the bytes seem to be going out to the NIO SocketChannel.write() call. 

Is there any way to log what Chromium is receiving?  I added --enable-logging to chromium's command line but the log doesn't seem to have much in it.

BR
Nathan

[Ilya Tikhonovsky]

1) Looks like the backend lost the answer for request id 26

2) could you please do another test with regular requests each 10 sec and reading all the incoming messages in the middle

3) you can sniff the traffic with help of nc command line tool. One nc with listening socket the other nc with direct connection to remote debugging port and tee tool in the middle.

Regards,
Tim.

[Ilya Tikhonovsky]

I was wrong. nc will not help you.

I'll think about that a bit more.

Regards,
Tim.

[Ilya Tikhonovsky]

You can use tcpdump for sniffing the traffic.

Something like tcpdump -i lo0 port 9111

Regards,
Tim.

[Nathan Wray]

Thanks Tim, I'll try that. 

Assuming that the tcpdump shows that the messages are being sent to Chromium, where will that leave me?  Is there any way to diagnose what's happening inside Chromium?

BR
Nathan

[Ilya Tikhonovsky]

I can build a custom binary which will dump all incoming/outgoing messages.

Regards,
Tim.

[Nathan Wray]

tcpdump attached

Nathan

[Ilya Tikhonovsky]

thanks a lot. I'm trying to reproduce the problem locally.

Regards,
Tim.

[Nathan Wray]

Thank you again for your help Tim.  I'm running on CentOS Linux release 6.0 (Final), if that helps.

[Ilya Tikhonovsky]

Intermediate results: I've made the next test:

0) got the latest binaries of chrome. You can get it here http://commondatastorage.googleapis.com/chromium-browser-snapshots/index.html?path=Linux/108903/

0) got the latest devtools_frontend.zip just for simplifying the process;

1) extracted binaries and frontend files;

2) run chrome with the next flags chrome --remote-debugging-port=9111 --debug-devtools-frontend=/Users/loislo/Downloads/devtools/    <-----absolute path here

3) created a dummy frontend test.html (attached below) and saved it to the devtools frontend folder.

this dummy frontend uses two files from the original frontend;

4) opened remote debugging page (http://localhost:9111) in the other chrome instance;

5) clicked on the thumbnail and got the standard devtools frontend page;

6) replaced devtools.html in the url to test.html and hit enter; 

In my case the result url was http://localhost:9111/devtools/test.html?host=localhost:9111&page=1

7) opened the real DevTools for this page;

8) in Console tab I ran WebInspector.loaded() and got the next messages.

undefined

test.html:27connected

InspectorBackendStub.js:300frontend: {"method":"Console.enable","id":1}

InspectorBackendStub.js:300frontend: {"method":"Console.clearMessages","id":2}

InspectorBackendStub.js:300frontend: {"method":"Network.enable","id":3}

InspectorBackendStub.js:300frontend: {"method":"Network.clearBrowserCache","id":4}

InspectorBackendStub.js:300frontend: {"method":"Page.enable","id":5}

InspectorBackendStub.js:300frontend: {"method":"Network.setUserAgentOverride","params":{"userAgent":"Mozilla/5.0 (Linux; U; Android 2.2.2; en-us; SPH-M920 Build/FROYO) AppleWebKit/533.1 (KHTML, like Gecko) Version/4.0 Mobile Safari/533.1"},"id":6}

InspectorBackendStub.js:300frontend: {"method":"Network.setExtraHTTPHeaders","params":{"headers":{"Accept-Encoding":"gzip"}},"id":7}

InspectorBackendStub.js:300frontend: {"method":"Page.open","params":{"url":"http://localhost:9111/json"},"id":8}

InspectorBackendStub.js:321backend: {"result":{},"id":1}

InspectorBackendStub.js:321backend: {"method":"Console.messagesCleared"}

1. InspectorBackendStub.js:386Protocol Error: the message is for non-existing domain 'Console'

InspectorBackendStub.js:321backend: {"result":{},"id":2}

InspectorBackendStub.js:321backend: {"result":{},"id":3}

InspectorBackendStub.js:321backend: {"result":{},"id":4}

InspectorBackendStub.js:321backend: {"result":{},"id":5}

InspectorBackendStub.js:321backend: {"result":{},"id":6}

InspectorBackendStub.js:321backend: {"result":{},"id":7}

InspectorBackendStub.js:321backend: {"method":"Network.requestWillBeSent","params":{"requestId":"25962.3","frameId":"25962.2","loaderId":"25962.4","documentURL":"http://localhost:9111/json","request":{"url":"http://localhost:9111/json","method":"GET","headers":{"Accept-Encoding":"gzip","User-Agent":"Mozilla/5.0 (Linux; U; Android 2.2.2; en-us; SPH-M920 Build/FROYO) AppleWebKit/533.1 (KHTML, like Gecko) Version/4.0 Mobile Safari/533.1","Accept":"text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8","Referer":"http://localhost:9111/JSON"}},"timestamp":1320702585.962449,"initiator":{"type":"other"},"stackTrace":[]}}

1. InspectorBackendStub.js:386Protocol Error: the message is for non-existing domain 'Network'

InspectorBackendStub.js:321backend: {"result":{},"id":8}

InspectorBackendStub.js:321backend: {"method":"Network.responseReceived","params":{"requestId":"25962.3","timestamp":1320702586.069239,"type":"Document","response":{"url":"http://localhost:9111/json","status":200,"statusText":"OK","mimeType":"application/json","connectionReused":true,"connectionId":770,"fromDiskCache":false,"timing":{"requestTime":1320702585.965581,"proxyStart":-1,"proxyEnd":-1,"dnsStart":-1,"dnsEnd":-1,"connectStart":102,"connectEnd":102,"sslStart":-1,"sslEnd":-1,"sendStart":102,"sendEnd":102,"receiveHeadersEnd":102},"headers":{"Content-Length":"173","Content-Type":"application/json; charset=UTF-8"},"headersText":"HTTP/1.1 200 OK\r\nContent-Type:application/json; charset=UTF-8\r\nContent-Length:173\r\n\r\n","requestHeaders":{"Accept-Encoding":"gzip","Accept-Language":"en-US,en;q=0.8","Connection":"keep-alive","Accept-Charset":"ISO-8859-1,utf-8;q=0.7,*;q=0.3","Host":"localhost:9111","User-Agent":"Mozilla/5.0 (Linux; U; Android 2.2.2; en-us; SPH-M920 Build/FROYO) AppleWebKit/533.1 (KHTML, like Gecko) Version/4.0 Mobile Safari/533.1","Accept":"text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8","Referer":"http://localhost:9111/JSON"},"requestHeadersText":"GET /json HTTP/1.1\r\nHost: localhost:9111\r\nConnection: keep-alive\r\nAccept-Encoding: gzip\r\nUser-Agent: Mozilla/5.0 (Linux; U; Android 2.2.2; en-us; SPH-M920 Build/FROYO) AppleWebKit/533.1 (KHTML, like Gecko) Version/4.0 Mobile Safari/533.1\r\nAccept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8\r\nReferer: http://localhost:9111/JSON\r\nAccept-Language: en-US,en;q=0.8\r\nAccept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3\r\n\r\n"}}}

1. InspectorBackendStub.js:386Protocol Error: the message is for non-existing domain 'Network'

InspectorBackendStub.js:321backend: {"method":"Console.messagesCleared"}

1. InspectorBackendStub.js:386Protocol Error: the message is for non-existing domain 'Console'

InspectorBackendStub.js:321backend: {"method":"Inspector.reset"}

1. InspectorBackendStub.js:386Protocol Error: the message is for non-existing domain 'Inspector'

InspectorBackendStub.js:321backend: {"method":"Page.frameNavigated","params":{"frame":{"id":"25962.2","url":"http://localhost:9111/json","loaderId":"25962.4","mimeType":"application/json"},"loaderId":"25962.4"}}

1. InspectorBackendStub.js:386Protocol Error: the message is for non-existing domain 'Page'

InspectorBackendStub.js:321backend: {"method":"Network.dataReceived","params":{"requestId":"25962.3","timestamp":1320702586.077871,"dataLength":173,"encodedDataLength":258}}

1. InspectorBackendStub.js:386Protocol Error: the message is for non-existing domain 'Network'

InspectorBackendStub.js:321backend: {"method":"Page.loadEventFired","params":{"timestamp":1320702586.09925}}

1. InspectorBackendStub.js:386Protocol Error: the message is for non-existing domain 'Page'

InspectorBackendStub.js:321backend: {"method":"Page.domContentEventFired","params":{"timestamp":1320702586.118883}}

1. InspectorBackendStub.js:386Protocol Error: the message is for non-existing domain 'Page'

InspectorBackendStub.js:321backend: {"method":"Network.loadingFinished","params":{"requestId":"25962.3","timestamp":1320702586.068567}}

1. InspectorBackendStub.js:386Protocol Error: the message is for non-existing domain 'Network'

as you see everything looks ok. The error messages were generated because the dummy frontend has no handlers for these events. As the next step I ran getResponseBody command. See results below. I'll try to continue this tomorrow morning.

NetworkAgent.getResponseBody("25962.3")

InspectorBackendStub.js:300frontend: {"method":"Network.getResponseBody","params":{"requestId":"25962.3"},"id":9}

undefined

InspectorBackendStub.js:321backend: {"result":{"body":"[ {\n \"faviconUrl\": \"http://localhost:9111/favicon.ico\",\n \"thumbnailUrl\": \"/thumb/http://localhost:9111/JSON\",\n \"title\": \"\",\n \"url\": \"http://localhost:9111/JSON\"\n} ]\n","base64Encoded":false},"id":9}

NetworkAgent.getResponseBody("25962.1")

InspectorBackendStub.js:300frontend: {"method":"Network.getResponseBody","params":{"requestId":"25962.1"},"id":10}

undefined

InspectorBackendStub.js:321backend: {"error":{"code":-32000,"message":"No resource with given identifier found"},"id":10}

NetworkAgent.getResponseBody("25962.2")

InspectorBackendStub.js:300frontend: {"method":"Network.getResponseBody","params":{"requestId":"25962.2"},"id":11}

undefined

InspectorBackendStub.js:321backend: {"error":{"code":-32000,"message":"No resource with given identifier found"},"id":11}

NetworkAgent.getResponseBody("25962.3")

InspectorBackendStub.js:300frontend: {"method":"Network.getResponseBody","params":{"requestId":"25962.3"},"id":12}

undefined

InspectorBackendStub.js:321backend: {"result":{"body":"[ {\n \"faviconUrl\": \"http://localhost:9111/favicon.ico\",\n \"thumbnailUrl\": \"/thumb/http://localhost:9111/JSON\",\n \"title\": \"\",\n \"url\": \"http://localhost:9111/JSON\"\n} ]\n","base64Encoded":false},"id":12}

NetworkAgent.getResponseBody("25962.4")

InspectorBackendStub.js:300frontend: {"method":"Network.getResponseBody","params":{"requestId":"25962.4"},"id":13}

undefined

InspectorBackendStub.js:321backend: {"error":{"code":-32000,"message":"No resource with given identifier found"},"id":13}

Regards,
Tim.

[Nathan Wray]

Thanks again Tim.  I should point out that I have run my app successfully against many complex sites (for example m.cnn.com) without seeing the errors I'm reporting.  www.google.com reliably causes the errors I'm seeing.

[Nathan Wray]

I added code to send a numbered invalid command before each send.  In the attached log you'll see that the command at line 79 (ID 1012) was the last invalid command that was replied to.  The getResponseBody at line 63 (ID 29) and subsequent getResponseBody commands were not replied to. 

I'm running the chrome-trunk.zip browser you referred to earlier. I get some complaints on stderr when it launches but otherwise the same results.

chrome-linux/chrome: /lib/libz.so.1: no version information available (required by chrome-linux/chrome)
chrome-linux/chrome: /lib/libz.so.1: no version information available (required by chrome-linux/chrome)
chrome-linux/chrome: /lib/libz.so.1: no version information available (required by chrome-linux/chrome)
chrome-linux/chrome: /lib/libz.so.1: no version information available (required by chrome-linux/chrome)
[4730:4730:3400354458:ERROR:browser_main_loop.cc(123)] GLib-GObject: gsignal.c:2270: signal `preedit-changed' is invalid for instance `0xb89e2000'

BR
Nathan

[Nathan Wray]

Tim, I opened a new defect "Issue 103544: Remote Debugging session stops responding to new requests"
http://code.google.com/p/chromium/issues/detail?id=103544

Thank you
Nathan

On Tue, Nov 8, 2011 at 4:08 PM, Ilya Tikhonovsky <loi...@chromium.org> wrote:

please use http://webkit.org/new-inspector-bug for DevTools/WebInspector bugs

or crbug.com for remote debugging bugs.

Regards,
Tim.

On Wed, Nov 9, 2011 at 12:07 AM, Ilya Tikhonovsky <loi...@chromium.org> wrote:

My test works with www.google.com without any problem.

I've made another test run with your command line keys and can reproduce problem with no response for Page.open message. 

If it is possible could you send me the sources of your test app or full scenario for troubleshooting. 

As I understand you are using a third party java lib for the transport. 

If you want to flip to latest WebSocket protocol you can contact to pry...@google.com. He is the owner of http://code.google.com/p/chromedevtools/

Regards,
Tim.