Repository: phoenixframework/phoenix (elixir)

Issue:
PubSub config required at compile time
If an application has the following in `config.exs`:

```elixir
# Configures the endpoint
config :config_test, ConfigTestWeb.Endpoint,
  render_errors: [view: ConfigTestWeb.ErrorView, accepts: ~w(html json)],
  pubsub: [name: ConfigTest.PubSub, adapter: Phoenix.PubSub.PG2, pool_size: 1]
```

Then the supervision tree looks like this (correctly using the PubSub name):

![config-exs](https://user-images.githubusercontent.com/477511/43637976-fcba05f4-970e-11e8-94e5-ef0d49765214.png)

However, if the same config us in the `MyApp.Endoint.init/2` function:

```elixir
  def init(_, config) do
    {:ok, Keyword.merge(config, default_config())}
  end

  defp default_config() do
    [
      pubsub: [name: ConfigTest.PubSub, adapter: Phoenix.PubSub.PG2, pool_size: 1]
    ]
  end
```

 then it looks like:

![config-init](https://user-images.githubusercontent.com/477511/43637988-0ae4d28a-970f-11e8-953d-e1bef616a80e.png)

In this case, a generic name of `Elixir.Supervisor` is used (this is as a result of `Module.concat(nil, "Supervisor")` from https://github.com/phoenixframework/phoenix_pubsub/blob/daedc139726f38b6de2a84ca8d9d1eeb4f5b6307/lib/phoenix/pubsub/pg2.ex#L50)

Pull request:
Raise if the pubsub server name is not configured at compile time
If the pubsub server is configured at runtime (e.g. in the init callback) then
everything will appear to work as normal, but the pubsub server will have the
name of `Elixir.Supervisor` due to having nil as a name.

This closes #2992

Patch:
diff --git a/CHANGELOG.md b/CHANGELOG.md
index cdb0719cf..fabf0a693 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -43,6 +43,8 @@ The old APIs for building transports are also deprecated. The good news is: adap
   * [Router] Display list of available routes on debugger 404 error page
   * [Router] Raise on duplicate plugs in `pipe_through` scopes
   * [Presence] Add `Presence.get_by_key` to fetch presences for specific user
+  * [Socket] Add new `phoenix_socket_connect` instrumentation
+  * [Logger] Log calls to user socket connect
 
 ### Bug Fixes
 
diff --git a/lib/phoenix/endpoint.ex b/lib/phoenix/endpoint.ex
index 8465962bb..7af12f7aa 100644
--- a/lib/phoenix/endpoint.ex
+++ b/lib/phoenix/endpoint.ex
@@ -351,6 +351,9 @@ defmodule Phoenix.Endpoint do
     * `:phoenix_channel_receive` - the receipt of an incoming message over a
       channel. The `%Phoenix.Socket{}`, payload, event, and ref are passed as
       runtime metadata via `:socket`, `:params`, `:event`, and `:ref`
+    * `:phoenix_socket_connect` - the connection of the user socket transport.
+      The map of runtime metadata contains the `:transport`, `:params`, a map of
+      `connect_info`, and the `:user_socket` module.
 
   ### Dynamic instrumentation
 
@@ -507,7 +510,8 @@ defmodule Phoenix.Endpoint do
       server
     else
       raise ArgumentError, """
-      no :pubsub server configured, please setup :pubsub in your config.
+      no :pubsub server was configured at compile time, please setup :pubsub
+      in your config.
 
       By default this looks like:
 
diff --git a/lib/phoenix/endpoint/supervisor.ex b/lib/phoenix/endpoint/supervisor.ex
index c4adf2891..93afebecd 100644
--- a/lib/phoenix/endpoint/supervisor.ex
+++ b/lib/phoenix/endpoint/supervisor.ex
@@ -54,7 +54,7 @@ defmodule Phoenix.Endpoint.Supervisor do
 
     if adapter = pub_conf[:adapter] do
       pub_conf = [fastlane: Phoenix.Channel.Server] ++ pub_conf
-      [supervisor(adapter, [mod.__pubsub_server__(), pub_conf])]
+      [supervisor(adapter, [Phoenix.Endpoint.__pubsub_server__!(mod), pub_conf])]
     else
       []
     end
diff --git a/lib/phoenix/logger.ex b/lib/phoenix/logger.ex
index 999c2d823..fd4d7c6c8 100644
--- a/lib/phoenix/logger.ex
+++ b/lib/phoenix/logger.ex
@@ -66,6 +66,24 @@ defmodule Phoenix.Logger do
   end
   def phoenix_channel_receive(:stop, _compile, :ok), do: :ok
 
+  def phoenix_socket_connect(:start, _compile, %{log: false}), do: :ok
+  def phoenix_socket_connect(:start, _compile, %{log: level} = meta) do
+    %{
+      transport: transport,
+      params: params,
+      connect_info: connect_info,
+      user_socket: user_socket,
+    } = meta
+
+    Logger.log(level, fn ->
+      "CONNECT #{inspect(user_socket)}\n" <>
+      "  Transport: #{inspect(transport)}\n" <>
+      "  Connect Info: #{inspect(connect_info)}\n" <>
+      "  Parameters: #{inspect(filter_values(params))}"
+    end)
+  end
+  def phoenix_socket_connect(:stop, _compile, _), do: :ok
+
   @doc false
   def filter_values(values, params \\ Application.get_env(:phoenix, :filter_parameters))
   def filter_values(values, {:discard, params}), do: discard_values(values, params)
diff --git a/lib/phoenix/socket.ex b/lib/phoenix/socket.ex
index c86d568f4..69ff8de03 100644
--- a/lib/phoenix/socket.ex
+++ b/lib/phoenix/socket.ex
@@ -68,6 +68,14 @@ defmodule Phoenix.Socket do
     * `:transport_pid` - The pid of the socket's transport process
     * `:serializer` - The serializer for socket messages
 
+  ## Logging
+
+  Logging for socket connections is set via the `:log` option, for example:
+
+      use Phoenix.Socket, log: :debug
+
+  Defaults to the `:info` log level. Pass `false` to disable logging.
+
   ## Client-server communication
 
   The encoding of server data and the decoding of client data is done
@@ -121,6 +129,7 @@ defmodule Phoenix.Socket do
   """
 
   require Logger
+  require Phoenix.Endpoint
   alias Phoenix.Socket
   alias Phoenix.Socket.{Broadcast, Message, Reply}
 
@@ -202,7 +211,7 @@ defmodule Phoenix.Socket do
           transport_pid: pid,
         }
 
-  defmacro __using__(_opts) do
+  defmacro __using__(opts) do
     quote do
       ## User API
 
@@ -211,6 +220,7 @@ defmodule Phoenix.Socket do
       @before_compile Phoenix.Socket
       Module.register_attribute(__MODULE__, :phoenix_channels, accumulate: true)
       @phoenix_transports %{}
+      @phoenix_log Keyword.get(unquote(opts), :log, :info)
 
       ## Callbacks
 
@@ -222,7 +232,7 @@ defmodule Phoenix.Socket do
       end
 
       @doc false
-      def connect(map), do: Phoenix.Socket.__connect__(__MODULE__, map)
+      def connect(map), do: Phoenix.Socket.__connect__(__MODULE__, map, @phoenix_log)
 
       @doc false
       def init(state), do: Phoenix.Socket.__init__(state)
@@ -446,7 +456,7 @@ defmodule Phoenix.Socket do
     supervisor(Phoenix.Socket.PoolSupervisor, [args], id: handler)
   end
 
-  def __connect__(handler, map) do
+  def __connect__(user_socket, map, log) do
     %{
       endpoint: endpoint,
       options: options,
@@ -454,13 +464,29 @@ defmodule Phoenix.Socket do
       params: params,
       connect_info: connect_info
     } = map
-
     vsn = params["vsn"] || "1.0.0"
+    meta = Map.merge(map, %{vsn: vsn, user_socket: user_socket, log: log})
 
-    case negotiate_serializer(Keyword.fetch!(options, :serializer), vsn) do
-      {:ok, serializer} -> user_connect(handler, endpoint, transport, serializer, params, connect_info)
-      :error -> :error
-    end
+    Phoenix.Endpoint.instrument(endpoint, :phoenix_socket_connect, meta, fn ->
+      case negotiate_serializer(Keyword.fetch!(options, :serializer), vsn) do
+        {:ok, serializer} ->
+          user_socket
+          |> user_connect(endpoint, transport, serializer, params, connect_info)
+          |> log_connect_result(user_socket, log)
+
+        :error -> :error
+      end
+    end)
+  end
+
+  defp log_connect_result(result, _user_socket, false = _level), do: result
+  defp log_connect_result({:ok, _} = result, user_socket, level) do
+    Logger.log(level, fn -> "Replied #{inspect(user_socket)} :ok" end)
+    result
+  end
+  defp log_connect_result(:error = result, user_socket, level) do
+    Logger.log(level, fn -> "Replied #{inspect(user_socket)} :error" end)
+    result
   end
 
   def __init__({state, %{id: id, endpoint: endpoint} = socket}) do


Test patch:
diff --git a/test/phoenix/endpoint/endpoint_test.exs b/test/phoenix/endpoint/endpoint_test.exs
index 0bec3a3ab..0e22cdd1b 100644
--- a/test/phoenix/endpoint/endpoint_test.exs
+++ b/test/phoenix/endpoint/endpoint_test.exs
@@ -12,6 +12,8 @@ defmodule Phoenix.Endpoint.EndpointTest do
            pubsub: [adapter: Phoenix.PubSub.PG2, name: :endpoint_pub]]
   Application.put_env(:phoenix, __MODULE__.Endpoint, @config)
 
+  Application.put_env(:phoenix, __MODULE__.NoPubSubEndpoint, Keyword.delete(@config, :pubsub))
+
   defmodule Endpoint do
     use Phoenix.Endpoint, otp_app: :phoenix
 
@@ -21,6 +23,15 @@ defmodule Phoenix.Endpoint.EndpointTest do
     assert code_reloading? == false
   end
 
+  defmodule NoPubSubEndpoint do
+    use Phoenix.Endpoint, otp_app: :phoenix
+
+    def init(_, config) do
+      pubsub = [adapter: Phoenix.PubSub.PG2, name: :named_at_runtime_endpoint_pub]
+      {:ok, Keyword.put(config, :pubsub, pubsub)}
+    end
+  end
+
   setup_all do
     Endpoint.start_link()
     on_exit fn -> Application.delete_env(:phoenix, :serve_endpoints) end
@@ -35,6 +46,12 @@ defmodule Phoenix.Endpoint.EndpointTest do
     }
   end
 
+  test "errors if pubsub is not set at runtime and not compile time" do
+    Process.flag(:trap_exit, true)
+    {:error, {%ArgumentError{message: message}, _}} = NoPubSubEndpoint.start_link()
+    assert message =~ "no :pubsub server was configured at compile time"
+  end
+
   test "has reloadable configuration" do
     assert Endpoint.config(:url) == [host: {:system, "ENDPOINT_TEST_HOST"}, path: "/api"]
     assert Endpoint.config(:static_url) == [host: "static.example.com"]
diff --git a/test/phoenix/integration/websocket_channels_test.exs b/test/phoenix/integration/websocket_channels_test.exs
index 9e4f7ddd0..4192c554b 100644
--- a/test/phoenix/integration/websocket_channels_test.exs
+++ b/test/phoenix/integration/websocket_channels_test.exs
@@ -61,7 +61,7 @@ defmodule Phoenix.Integration.WebSocketChannelsTest do
   end
 
   defmodule UserSocketConnectInfo do
-    use Phoenix.Socket
+    use Phoenix.Socket, log: false
 
     channel "room:*", RoomChannel
 
@@ -70,7 +70,7 @@ defmodule Phoenix.Integration.WebSocketChannelsTest do
       address = Tuple.to_list(connect_info.peer_data.address) |> Enum.join(".")
       uri = Map.from_struct(connect_info.uri)
       x_headers = Enum.into(connect_info.x_headers, %{})
-      
+
       connect_info =
         connect_info
         |> update_in([:peer_data], &Map.put(&1, :address, address))
@@ -245,6 +245,25 @@ defmodule Phoenix.Integration.WebSocketChannelsTest do
                                       "port" => 80}}}}
       end
 
+      test "logs user socket connect when enabled" do
+        log = capture_log(fn ->
+          {:ok, _} = WebsocketClient.start_link(self(), "#{@vsn_path}&logging=enabled", @serializer)
+        end)
+        assert log =~ "CONNECT #{inspect(UserSocket)}"
+      end
+
+      test "does not log user socket connect when disabled" do
+        log = capture_log(fn ->
+          {:ok, _} =
+            WebsocketClient.start_link(
+              self(),
+              "ws://127.0.0.1:#{@port}/ws/connect_info/websocket?vsn=#{@vsn}",
+              @serializer
+            )
+        end)
+        assert log =~ ""
+      end
+
       test "logs and filter params on join and handle_in" do
         topic = "room:admin-lobby2"
         {:ok, sock} = WebsocketClient.start_link(self(), "#{@vsn_path}&logging=enabled", @serializer)
diff --git a/test/phoenix/logger_test.exs b/test/phoenix/logger_test.exs
index 23dddfd1c..06011a141 100644
--- a/test/phoenix/logger_test.exs
+++ b/test/phoenix/logger_test.exs
@@ -164,6 +164,24 @@ defmodule Phoenix.LoggerTest do
     assert log == ""
   end
 
+  test "logs phoenix_socket_connect as configured by the user socket" do
+    meta = %{
+      transport: :websocket,
+      params: %{},
+      connect_info: %{},
+      user_socket: TestUserSocket,
+    }
+
+    log = capture_log(fn ->
+      Phoenix.Logger.phoenix_socket_connect(:start, %{}, Map.put(meta, :log, :info))
+    end)
+    assert log =~ "CONNECT TestUserSocket"
+
+    log = capture_log(fn ->
+      Phoenix.Logger.phoenix_socket_connect(:start, %{}, Map.put(meta, :log, false))
+    end)
+    assert log == ""
+  end
 
   defp action(conn) do
     LoggerController.call(conn, LoggerController.init(:index))