Improve logging and debugging (#38)

* refactored logging class and added error logging and json debugging helpers

Signed-off-by: Marc Jeffrey <[email protected]>

* redactor the way the handler middleware is mounted

Signed-off-by: Marc Jeffrey <[email protected]>

* user the Cable::INTERNAL messages

Signed-off-by: Marc Jeffrey <[email protected]>

* updated readme

Signed-off-by: Marc Jeffrey <[email protected]>

* remove version changes

Signed-off-by: Marc Jeffrey <[email protected]>

* moved debug stuff out of main server class

Signed-off-by: Marc Jeffrey <[email protected]>

* fix issues after rebase

Signed-off-by: Marc Jeffrey <[email protected]>

Author: mjeffrey18

README.md

@@ -30,7 +30,9 @@ On your `src/app_server.cr` add the `Cable::Handler` before `Lucky::RouteHandler
 class AppServer < Lucky::BaseAppServer
   def middleware
     [
-      Cable::Handler.new(ApplicationCable::Connection),
+      Cable::Handler(ApplicationCable::Connection).new, # place before the middleware below
+      Honeybadger::Handler.new,
+      Lucky::ErrorHandler.new(action: Errors::Show),
       Lucky::RouteHandler.new,
     ]
    end
@@ -46,6 +48,21 @@ Cable.configure do |settings|
 end
 ```
 
+You may want to tune how to report logging
+
+```crystal
+# config/log.cr
+
+log_levels = {
+  "debug" => Log::Severity::Debug,
+  "info"  => Log::Severity::Info,
+  "error" => Log::Severity::Error,
+}
+
+# use the `CABLE_DEBUG_LEVEL` env var to choose any of the 3 log levels above
+Cable::Logger.level = log_levels[ENV.fetch("CABLE_DEBUG_LEVEL", "info")]
+```
+
 Then you need to implement a few classes
 
 The connection class is how you are gonna handle connections, it's referenced on the `src/app_server.cr` when creating the handler.
@@ -196,7 +213,32 @@ Cable.configure do |settings|
   settings.disable_sec_websocket_protocol_header = true
 end
 ```
-4
+
+## Debugging
+
+You can create a json endpoint to ping your server and check how things are going.
+
+```crystal
+
+# src/actions/debug/index.cr
+
+class Debug::Index < ApiAction
+  include RequireAuthToken
+
+  get "/debug" do
+    json(Cable.server.debug_json) # Cable.server.debug_json is provided by this shard
+  end
+end
+```
+
+Alternatively, you can ping redis directly using the redis-cli as follows;
+
+```bash
+PUBLISH _internal debug
+```
+
+This will dump a debug status into your logs
+
 ## TODO
 
 After reading the docs, I realized I'm using some weird naming for variables / methods, so

spec/cable/connection_spec.cr

@@ -16,9 +16,6 @@ describe Cable::Connection do
 
         connection.close
         socket.close
-        Cable::Logger.messages.should contain("ChatChannel is streaming from chat_1")
-        Cable::Logger.messages.should contain("ChatChannel is transmitting the subscription confirmation")
-        Cable::Logger.messages.should contain("ChatChannel stopped streaming from {\"channel\":\"ChatChannel\",\"room\":\"1\"}")
       end
     end
 
@@ -43,9 +40,6 @@ describe Cable::Connection do
 
         connection.close
         socket.close
-        Cable::Logger.messages.should contain("ChatChannel is streaming from chat_1")
-        Cable::Logger.messages.should contain("ChatChannel is transmitting the subscription confirmation")
-        Cable::Logger.messages.should contain("ChatChannel stopped streaming from {\"channel\":\"ChatChannel\",\"room\":\"1\",\"person\":{\"name\":\"Foo\",\"age\":32,\"boom\":\"boom\"}}")
       end
     end
 
@@ -58,9 +52,6 @@ describe Cable::Connection do
 
         connection.close
         socket.close
-        Cable::Logger.messages.should contain("ChatChannel is streaming from chat_1")
-        Cable::Logger.messages.should contain("ChatChannel is transmitting the subscription confirmation")
-        Cable::Logger.messages.should contain("ChatChannel stopped streaming from {\"channel\":\"ChatChannel\",\"room\":\"1\",\"person\":{\"name\":\"Celso\",\"age\":32,\"boom\":\"boom\"}}")
       end
     end
 
@@ -94,10 +85,6 @@ describe Cable::Connection do
 
         connection.close
         socket.close
-        Cable::Logger.messages.should contain("ChatChannel is streaming from chat_1")
-        Cable::Logger.messages.should contain("ChatChannel is transmitting the subscription confirmation")
-        Cable::Logger.messages.should contain("ChatChannel stopped streaming from {\"channel\":\"ChatChannel\",\"room\":\"1\"}")
-        Cable::Logger.messages.should contain("ChatChannel is transmitting the unsubscribe confirmation")
       end
     end
   end
@@ -132,7 +119,6 @@ describe Cable::Connection do
         socket.messages.size.should eq(0)
 
         # we check only the first that is the one we care about, the others make no sense to our test
-        Cable::Logger.messages.should contain("An unauthorized connection attempt was rejected")
         socket.closed?.should be_truthy
 
         Cable.server.connections.should eq({} of String => Cable::Connection)
@@ -151,9 +137,6 @@ describe Cable::Connection do
 
         connection.close
         socket.close
-        Cable::Logger.messages.should contain("ChatChannel is streaming from chat_1")
-        Cable::Logger.messages.should contain("ChatChannel is transmitting the subscription confirmation")
-        Cable::Logger.messages.should contain("ChatChannel stopped streaming from {\"channel\":\"ChatChannel\",\"room\":\"1\"}")
       end
     end
 
@@ -169,12 +152,6 @@ describe Cable::Connection do
 
         connection.close
         socket.close
-        Cable::Logger.messages.should contain("ChatChannel is streaming from chat_1")
-        Cable::Logger.messages.should contain("ChatChannel is transmitting the subscription confirmation")
-        Cable::Logger.messages.should contain("ChatChannel#receive({\"message\" => \"Hello\"})")
-        Cable::Logger.messages.should contain("[ActionCable] Broadcasting to chat_1: {\"message\" => \"Hello\", \"current_user\" => \"98\"}")
-        Cable::Logger.messages.should contain("ChatChannel transmitting {\"message\" => \"Hello\", \"current_user\" => \"98\"} (via streamed from chat_1)")
-        Cable::Logger.messages.should contain("ChatChannel stopped streaming from {\"channel\":\"ChatChannel\",\"room\":\"1\"}")
       end
     end
 
@@ -190,12 +167,6 @@ describe Cable::Connection do
 
         connection.close
         socket.close
-        Cable::Logger.messages.should contain("ChatChannel is streaming from chat_1")
-        Cable::Logger.messages.should contain("ChatChannel is transmitting the subscription confirmation")
-        Cable::Logger.messages.should contain("ChatChannel#perform(\"invite\", {\"invite_id\" => \"4\"})")
-        Cable::Logger.messages.should contain("[ActionCable] Broadcasting to chat_1: {\"performed\" => \"invite\", \"params\" => \"4\"}")
-        Cable::Logger.messages.should contain("ChatChannel transmitting {\"performed\" => \"invite\", \"params\" => \"4\"} (via streamed from chat_1)")
-        Cable::Logger.messages.should contain("ChatChannel stopped streaming from {\"channel\":\"ChatChannel\",\"room\":\"1\"}")
       end
     end
   end
@@ -211,9 +182,6 @@ describe Cable::Connection do
 
         connection.close
         socket.close
-        Cable::Logger.messages.should contain("ChatChannel is streaming from chat_1")
-        Cable::Logger.messages.should contain("ChatChannel is transmitting the subscription confirmation")
-        Cable::Logger.messages.should contain("ChatChannel stopped streaming from {\"channel\":\"ChatChannel\",\"room\":\"1\"}")
       end
     end
   end
@@ -231,10 +199,6 @@ describe Cable::Connection do
 
         connection.close
         socket.close
-        Cable::Logger.messages.should contain("ChatChannel is streaming from chat_1")
-        Cable::Logger.messages.should contain("ChatChannel is transmitting the subscription confirmation")
-        Cable::Logger.messages.should contain("ChatChannel transmitting {\"hello\" => \"Broadcast!\"} (via streamed from chat_1)")
-        Cable::Logger.messages.should contain("ChatChannel stopped streaming from {\"channel\":\"ChatChannel\",\"room\":\"1\"}")
       end
     end
   end
@@ -253,11 +217,6 @@ describe Cable::Connection do
 
           connection.close
           socket.close
-          Cable::Logger.messages.should contain("ChatChannel is streaming from chat_1")
-          Cable::Logger.messages.should contain("ChatChannel is transmitting the subscription confirmation")
-          Cable::Logger.messages.should contain("[ActionCable] Broadcasting to chat_1: <turbo-stream></turbo-stream>")
-          Cable::Logger.messages.should contain("ChatChannel transmitting <turbo-stream></turbo-stream> (via streamed from chat_1)")
-          Cable::Logger.messages.should contain("ChatChannel stopped streaming from {\"channel\":\"ChatChannel\",\"room\":\"1\"}")
         end
       end
 
@@ -291,11 +250,6 @@ describe Cable::Connection do
 
           connection.close
           socket.close
-          Cable::Logger.messages.should contain("ChatChannel is streaming from chat_1")
-          Cable::Logger.messages.should contain("ChatChannel is transmitting the subscription confirmation")
-          Cable::Logger.messages.should contain("[ActionCable] Broadcasting to chat_1: {\"foo\" => \"bar\"}")
-          Cable::Logger.messages.should contain("ChatChannel transmitting {\"foo\" => \"bar\"} (via streamed from chat_1)")
-          Cable::Logger.messages.should contain("ChatChannel stopped streaming from {\"channel\":\"ChatChannel\",\"room\":\"1\"}")
         end
       end
     end
@@ -314,11 +268,6 @@ describe Cable::Connection do
 
           connection.close
           socket.close
-          Cable::Logger.messages.should contain("ChatChannel is streaming from chat_1")
-          Cable::Logger.messages.should contain("ChatChannel is transmitting the subscription confirmation")
-          Cable::Logger.messages.should contain("[ActionCable] Broadcasting to chat_1: {\"foo\" => \"bar\"}")
-          Cable::Logger.messages.should contain("ChatChannel transmitting {\"foo\" => \"bar\"} (via streamed from chat_1)")
-          Cable::Logger.messages.should contain("ChatChannel stopped streaming from {\"channel\":\"ChatChannel\",\"room\":\"1\"}")
         end
       end
     end
@@ -398,14 +347,7 @@ describe Cable::Connection do
 
         connection.close
         socket.close
-        Cable::Logger.messages.should contain("ChatChannel is streaming from chat_1")
-        Cable::Logger.messages.should contain("ChatChannel is transmitting the subscription confirmation")
-        Cable::Logger.messages.should contain("RejectionChannel is transmitting the subscription rejection")
-        Cable::Logger.messages.should contain("[ActionCable] Broadcasting to chat_1: {\"foo\" => \"bar\"}")
         # and here we can confirm the message was broadcasted
-        Cable::Logger.messages.should contain("ChatChannel transmitting {\"foo\" => \"bar\"} (via streamed from chat_1)")
-        Cable::Logger.messages.should contain("[ActionCable] Broadcasting to rejection: {\"foo\" => \"bar\"}")
-        Cable::Logger.messages.should contain("ChatChannel stopped streaming from {\"channel\":\"ChatChannel\",\"room\":\"1\"}")
       end
     end
   end

spec/cable/handler_spec.cr

@@ -3,7 +3,7 @@ require "../spec_helper"
 describe Cable::Handler do
   describe "basic handling" do
     it "matches the right route" do
-      handler = Cable::Handler.new(ApplicationCable::Connection)
+      handler = Cable::Handler(ApplicationCable::Connection).new
       request = HTTP::Request.new("GET", "#{Cable.settings.route}?test_token=1", headers)
 
       io_with_context = create_ws_request_and_return_io_and_context(handler, request)[0]
@@ -12,7 +12,7 @@ describe Cable::Handler do
 
     it "allows you to remove undesired actioncable headers" do
       Cable.settings.disable_sec_websocket_protocol_header = true
-      handler = Cable::Handler.new(ApplicationCable::Connection)
+      handler = Cable::Handler(ApplicationCable::Connection).new
       request = HTTP::Request.new("GET", "#{Cable.settings.route}?test_token=1", headers_without_sec_websocket_protocol)
 
       io_with_context = create_ws_request_and_return_io_and_context(handler, request)[0]
@@ -168,15 +168,15 @@ describe Cable::Handler do
 
   describe "the error handling" do
     it "doesn't match the wrong route" do
-      handler = Cable::Handler.new(ApplicationCable::Connection)
+      handler = Cable::Handler(ApplicationCable::Connection).new
       request = HTTP::Request.new("GET", "/unknown_route?test_token=1", headers)
 
       io_with_context = create_ws_request_and_return_io_and_context(handler, request)[0]
       io_with_context.to_s.should contain("404 Not Found")
     end
 
     it "doesn't upgrade with wrong headers (without Upgrade header)" do
-      handler = Cable::Handler.new(ApplicationCable::Connection)
+      handler = Cable::Handler(ApplicationCable::Connection).new
       headers_without_upgrade = headers
       headers_without_upgrade.delete("Upgrade")
       request = HTTP::Request.new("GET", "/unknown_route?test_token=1", headers_without_upgrade)
@@ -186,7 +186,7 @@ describe Cable::Handler do
     end
 
     it "doesn't upgrade with wrong headers (without Connection header)" do
-      handler = Cable::Handler.new(ApplicationCable::Connection)
+      handler = Cable::Handler(ApplicationCable::Connection).new
       headers_without_connection = headers
       headers_without_connection.delete("Connection")
       request = HTTP::Request.new("GET", "/unknown_route?test_token=1", headers_without_connection)
@@ -217,7 +217,7 @@ private def start_server
   spawn do
     # Make pinger real fast so we don't need to wait
     http_ref = nil
-    http_server = http_ref = HTTP::Server.new([Cable::Handler.new(ApplicationCable::Connection)])
+    http_server = http_ref = HTTP::Server.new([Cable::Handler(ApplicationCable::Connection).new])
     address = http_server.bind_unused_port
     address_chan.send(address)
     http_server.listen

spec/spec_helper.cr

@@ -4,14 +4,11 @@ require "./support/application_cable/connection"
 require "./support/application_cable/channel"
 require "./support/channels/*"
 
-Cable::Logger.suppress_output
-
 Cable.configure do |settings|
   settings.route = "/updates"
   settings.token = "test_token"
 end
 
 Spec.before_each do
   Cable.restart
-  Cable::Logger.reset_messages
 end

src/cable.cr

@@ -14,21 +14,27 @@ module Cable
       ping:         "ping",
       confirmation: "confirm_subscription",
       rejection:    "reject_subscription",
+      unsubscribe:  "confirm_unsubscription",
     },
     disconnect_reasons: {
       unauthorized:    "unauthorized",
       invalid_request: "invalid_request",
       server_restart:  "server_restart",
     },
     default_mount_path: "/cable",
-    protocols:          ["actioncable-v1-json", "actioncable-unsupported"].freeze,
+    protocols:          ["actioncable-v1-json", "actioncable-unsupported"],
   }
 
   Habitat.create do
-    setting route : String = "/cable", example: "/cable"
+    setting route : String = Cable.message(:default_mount_path), example: "/cable"
     setting token : String = "token", example: "token"
     setting url : String = ENV.fetch("REDIS_URL", "redis://localhost:6379"), example: "redis://localhost:6379"
     setting disable_sec_websocket_protocol_header : Bool = false
   end
+
+  def self.message(event : Symbol)
+    INTERNAL[:message_types][event]
+  end
+
   # TODO: Put your code here
 end