Does not log GraphQL errors

[ndarilek]

For context on this, see https://elixirforum.com/t/what-does-this-absinthe-phoenix-debugging-output-mean/8315. In short, I'm getting debugging info that indicates a query is hitting my schema, but I get a network error in my Apollo client, and no debugging info on the console.

I tweaked the channel resolver code to look like so:

    Absinthe.Logger.log_run(:debug, {
      query,
      config.schema,
      [],
      opts,
    })

    result = Absinthe.run(query, config.schema, opts)
    Absinthe.Logger.log_run(:debug, {
      result
    })

This is bad code and causes a crash. However, the crash reveals what's going on here:

** (FunctionClauseError) no function clause matching in Absinthe.Logger.log_run/2
    (absinthe) lib/absinthe/logger.ex:54: Absinthe.Logger.log_run(:debug, {{:ok, %{errors: [%{locations: [%{column: 0, line: 5}], message: "Cannot query field \"id\" on type \"User\"."}]}}})
    (absinthe_phoenix) lib/absinthe/phoenix/channel.ex:50: Absinthe.Phoenix.Channel.handle_in/3
    (phoenix) lib/phoenix/channel/server.ex:244: anonymous fn/4 in Phoenix.Channel.Server.handle_info/2
    (app) lib/app_web/endpoint.ex:1: AppWeb.Endpoint.instrument/4
    (stdlib) gen_server.erl:616: :gen_server.try_dispatch/4
    (stdlib) gen_server.erl:686: :gen_server.handle_msg/6
    (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3

So, in short, there's an error in my schema, and I failed to export the id field on my User type. But it'd be nice if that error had been reported to me somehow. It also doesn't appear to make it back to my websocket client.

[benwilson512]

@ndarilek this may be an issue with the javascript client. No matter what the error gets pushed out from the channel: https://github.com/absinthe-graphql/absinthe_phoenix/blob/master/lib/absinthe/phoenix/channel.ex#L60

[ndarilek]

Got it. Could it be logged to the console as well? That would have been hugely helpful in at least tracking this down and identifying it as a client issue.

[benwilson512]

We could definitely look at logging it in the javascript console. I don't think it makes any sense to log it in the elixir console, we don't do that for HTTP and I'm unsure why this would be different.

[ndarilek]

Why wouldn't you provide as much debugging info as possible, particularly in dev mode? If I'm building an app, and my queries are broken, I'd hope to see that on the Elixir console in addition to in my browser. That also helps in cases like these, where one reporting system failed to display an error. Had errors been reported in both places, I wouldn't have lost days debugging this.

[benwilson512]

I'll definitely consider it. Right now I see it as the equivalent of returning an ecto changeset error from a phoenix controller, those don't happen either.

Logging the entire response can be an issue even in dev, because large responses will obscure what's going on. I suppose we could log if there's an error key and NO data key.

The network tab should show the response right?

[bruce]

It should be in the websocket frames tab in Chrome DevTools, to be more specific.

[ndarilek]

The analogy breaks down because this isn't a controller failure. This is an unroutable request at best. At worst, it's a broken HTTP request. But either way, it's a loggable offense I'd say. GraphQL is kind of a layer between currently popular layers, and there really isn't a canonical way of thinking about that yet. What you're describing on the controller level is an application/database issue. Some constraint wasn't met or some business logic wasn't satisfied. But, either way, the request was *routed* to that point. If it misses a destination because an invalid query/mutation/subscription is called, a parameter condition wasn't met or bad data was requested, then that's more fundamental and worthy of logging. Or, put another way, the only way I can see an Absinthe error is in the browser. What if I'm not using a browser to hit the channel? Anywho, done rambling. I spent so long debugging this issue that it drove me a bit insane. :) And, unless I'm missing something, I'm not getting these Apollo errors in Firefox. Has anyone tested this house of cards with Firefox? :)

[benwilson512]

Look, I think it's perfectly fine to advocate for additional logging here. I am less fine with the tone which seems to imply we have wronged you here. You seem to be missing the point where the javascript library you're using was dropping the response. Absinthe did in fact respond with everything you needed to know to fix this issue. The client you were using (which we did not write) hid that response from you.

At worst, it's a broken HTTP request.

Not even a little. A push was made over the socket, JSON response was provided. Instead of showing it to you, your javascript client ignored it, and showed you nothing useful.

Or, put another way, the only way I can see an Absinthe error is in the
browser. What if I'm not using a browser to hit the channel?

If you weren't using the problematic javascript client, you would have seen Absinthe's response, fixed the issue, and moved on.

[ndarilek]

Please accept my apologies, no offense was intended. I think part of the problem is that I'm coming from a Node.js-based prototype, and in that instance I *did* get Apollo GraphQL parsing errors in my server console. I'm also blind, and unfortunately browser dev tools are notorious for their inaccessibility. I wish that wasn't the case. Were this a normal HTTP endpoint then I could just hit it with `curl -v` and debug manually, but as a websocket endpoint it's a bit more difficult/impossible to do that. Chrome is inaccessible on Linux, and on Firefox I'm just getting this "Network error: undefined" when anything fails to parse. I take your point about this client probably being broken, I just wish I had a way to work around it until it gets fixed. The query parse stage prints debugging output, so that the error stage doesn't seems inconsistent. And I'm fine with errors from my resolvers not outputting to the console by default, since I can add my own logging there. But in order to catch this error, I had to modify the absinthe_phoenix source itself. Maybe there's a way that my app could have injected that code, but if so then I don't know of it. Thanks.

[benwilson512]

I accept your apology, I confess it did not occur to me how much of a barrier the developer tools can be.

As the subscriptions feature moves out of Beta we'll definitely want to work with client libraries to provide the most helpful responses. In the mean time however I do think there's a good argument to be made for additional server side logging.

I'm at ElixirConf at the moment, but I'll look to make some improvements in this area as I return over the weekend.

[benwilson512]

Hey @ndarilek.

Absinthe master now produces the following log message when in debug mode:

[debug] Absinthe Subscription Publication
Field Topic: {:new_order, "*"}
Subscription id: "__absinthe__:doc:57980196"
Data: %{data: %{"newOrder" => %{"id" => "5"}}}

[ndarilek]

Hey, this is great, thanks! Apologies for not commenting sooner, I just haven't had an opportunity to experiment with this recently. But this looks like it will catch the next schema mismatch I experience.