CF_TRACE option does not trigger wss traffic traces

[gberche-orange]

The current CF_TRACE env var is very useful to be able to diagnose, troubleshoot and report issues related to the cli or a broken Cf deployment.

Unfortunately the websocket traffic is not dumped by current traces. This makes it hard to debug proxy related problems such as #62

[cf-gitbot]

We have created an issue in Pivotal Tracker to manage this. You can view the current status of your issue at: https://www.pivotaltracker.com/story/show/75183186.

[lcddave]

This is for the cf logs command, right? @ajackson Is this something handled in the loggregator lib?

[ajackson]

It could be something handled in loggregator lib. Since loggregator lib's audience is larger than the CLI, I don't think we should introduce the CF_TRACE env var directly in the library. We could introduce a "debug" option in the library that would do more verbose output from the websocket.

I'm struggling to know what the desired "debug" output would be from a binary websocket? Is the desire to have more debugging info around the initial HTTP connection before the "upgrade" step for the websocket? What would be the most useful?

[gberche-orange]

yes, these traces are lacking when invoking the cf logs command:

$ CF_TRACE=true cf-6.1.2-6a013ca.exe logs myapp--recent

VERSION:
6.1.2-6a013ca

REQUEST: [2014-07-17T17:10:25+02:00]
GET /v2/spaces/3518c030-0b99-4075-834e-1b47e6ec7909/apps?q=name%3ACfConsummerIT-gberche-dev-box-berchegtests-cfapps.elpaaso.net-jeeProbe&inline-relations-depth=1 HTTP/1.1
Host: api.run.pivotal.io
Accept: application/json
Authorization: [PRIVATE DATA HIDDEN]
Content-Type: application/json
User-Agent: go-cli 6.1.2-6a013ca / windows

RESPONSE: [2014-07-17T17:10:26+02:00]
HTTP/1.1 200 OK
Content-Length: 4299
Connection: keep-alive
Content-Type: application/json;charset=utf-8
Date: Thu, 17 Jul 2014 15:10:27 GMT
Server: nginx
X-Content-Type-Options: nosniff
X-Vcap-Request-Id: a527413c-b944-4456-4439-5118bf9569c4::0fdc5b7b-93af-4e4d-8db9-34d26467dc81
{
[...]
}
Connected, dumping recent logs for app myapp in org [...] ...

2014-07-17T17:09:06.89+0200 [API]     OUT Created app with guid 09f8c583-ad06-4697-bd0d-f56133d64006
2014-07-17T17:09:07.95+0200 [API]     OUT Updated app with guid 09f8c583-ad06-4697-bd0d-f56133d64006 ({"route"=>"815343d9-3cd6-4e89-a8e2-49028386bda6"})

In terms of use-cases where these traces would be useful:

• cf users debug connection issues (e.g. invalid FQDN or port from the CF local deployment)
• cf users debug proxy related issues that won't honor the upgrade request (see example at cf logs and http proxy #127 (comment) )
• provide a way for implementors of clients of the CF APIs to benchmark how the cli is making use of the apis, e.g. fix bugs into cf-java-client without having to get the tcpdump/wireshark (BTW, I'm not sure where the loggregator ws protocol reference documentation is beside websocket_server_test.go, could not yet find it into http://apidocs.cloudfoundry.org/ )

In terms of desired debug output, among the 3 following possible levels:

a) just the wss url such as wss://loggregator.run.pivotal.io:4443/tail/?app=005e78a9-e259-4c93-9b00-256823a1a6a8: that we see when it fails with the dial tcp: GetAddrIfoW
b) the full websocket handshake (ex borrowed from http://tools.ietf.org/html/rfc6455 ):

   The handshake from the client:

        GET /chat HTTP/1.1
        Host: server.example.com
        Upgrade: websocket
        Connection: Upgrade
        Sec-WebSocket-Key: dGhlIHNhbXBsZSBub25jZQ==
        Origin: http://example.com
        Sec-WebSocket-Protocol: chat, superchat
        Sec-WebSocket-Version: 13

   The handshake from the server: 

        HTTP/1.1 101 Switching Protocols
        Upgrade: websocket
        Connection: Upgrade
        Sec-WebSocket-Accept: s3pPLMBiTxaQ9kYGzzhZRbK+xOo=
        Sec-WebSocket-Protocol: chat

c) the handshake part + the full data transfer part (as it is currently done for other api calls)

I'd prefer a combinaration of a) + b)

This allows to understand which FQDN the tcp connection is made of (currently missing from other CC API traces) + somewhat debug any malfunctionning proxy not supporting the Upgrade request

Option c) does not seem necessary given that for logs the transfert part is already printed by the cli. When this level of protocol analysis gets required, then tcpdump/wireshark seems more suiteable

[drich10]

@ajackson Is this something we should move into your icebox?

Cheers,
@krishicks && @drich10
CF Community Pair

[ajackson]

@krishicks && @drich10 Yes please.

[krishicks]

@ajackson It looks like we don't have the permissions to move it into your icebox. Would you be able to take care of that?

Cheers,
@krishicks && @drich10
CF Community Pair

[ajackson]

Got it thanks.

On Fri, Jul 25, 2014 at 6:10 PM, Kris Hicks notifications@github.com
wrote:

@ajackson https://github.com/ajackson It looks like we don't have the
permissions to move it into your icebox. Would you be able to take care of
that?

Cheers,
@krishicks https://github.com/krishicks && @drich10
https://github.com/drich10
CF Community Pair

—
Reply to this email directly or view it on GitHub
#214 (comment).

[ajackson]

Additional debugging / tracing for loggregator connections has been added in the latest CLI. @gberche-orange can we consider this issue closed?

[gberche-orange]

Thanks a lot @johannespetzold and @ajackson for the new websocket traces that now properly displays with cf logs command.

I was initially surprised to not see debugging traces when the --recent option is set. Reading the code, the recent logs goes through the new 'recent' http endpoint and only do fallbacks through the old ws 'dump' endpoint.

For consistency, it would be nice to have debugging traces for the loggregator http endpoints as well.

[jberkhahn]

So it seems this has been resolved? Closing this.