Integrate WebSocketLogger

README.md

@@ -24,17 +24,14 @@ Server and client side [Websockets](https://tools.ietf.org/html/rfc6455) protoco
 In the package manager, add WebSockets. Then [paste](https://docs.julialang.org/en/v1/stdlib/REPL/index.html#The-Julian-mode-1) this into a REPL:
 
 ```julia
-julia> using WebSockets, Logging
+julia> using WebSockets
 
 julia> serverWS = ServerWS(handler = (req) -> WebSockets.Response(200), wshandler = (ws_server) -> (writeguarded(ws_server, "Hello"); readguarded(ws_server)))
-ServerWS(handler=#3(req), wshandler=#4(ws_server), logger=Base.DevNull())
+ServerWS(handler=<span>#</span>7(req), wshandler=<span>#</span>8(ws_server))
 
-julia> import Logging.shouldlog
-
-julia> shouldlog(::ConsoleLogger, level, _module, group, id) = _module != WebSockets.HTTP.Servers
-shouldlog (generic function with 4 methods)
-
-julia> ta = @async WebSockets.serve(serverWS, port = 8000)
+julia> ta = @async WebSockets.with_logger(WebSocketLogger()) do
+                WebSockets.serve(serverWS, port = 8000)
+            end
 Task (runnable) @0x000000000fc91cd0
 
 julia> WebSockets.HTTP.get("http://127.0.0.1:8000")
@@ -62,7 +59,7 @@ julia> ta
 Task (done) @0x000000000fc91cd0
 
 ```
-More things to do: Access inline documentation and have a look at the examples folder. The testing files demonstrate a variety of uses. Benchmarks show examples of websockets and servers running on separate processes, as oposed to asyncronous tasks.
+Access inline documentation and have a look at the examples folder! The testing files also demonstrate a variety of uses. Benchmarks show examples of websockets and servers running on separate processes, as oposed to asyncronous tasks.
 
 ### About this package
 Originally from 2013 and Julia 0.2, the WebSockets API has remained largely unchanged. It now depends on [HTTP.jl](https://github.com/JuliaWeb/HTTP.jl) for establishing the http connections. That package is in ambitious development, and most functionality of this package is already implemented directly in HTTP.jl.
@@ -88,20 +85,26 @@ WebSockets are well suited for user interactions via a browser or [cross-platfor
 - Compression is not currenlty implemented, but easily adaptable. On local connections, there's probably not much to gain.
 - If you worry about milliseconds, TCP quirks like 'warm-up' time with low transmission speed after a pause can be avoided with heartbeats. High-performance examples are missing.
 - Garbage collection increases message latency at semi-random intervals, as is visible in  benchmark plots. Benchmarks should include non-memory-allocating examples.
+- Time prefixes in e.g. `@wslog` is not accurate. To accurately track sequences of logging messages, include the time in your logging message.
 
 ##### Debugging with WebSockets.ServeWS servers
 Error messages from run-time are directed to a .out channel. See inline docs: ?Websockets.serve.
+When using `readguarded` or `writeguarded`, errors are logged with `@debug` statements. Set the logging level of the logger you use to 'Debug', as in 'examples/count_with_logger.jl'.
 
 ##### Debugging with WebSockets.HTTP.listen servers
 Error messages may be sent as messages to the client. This may not be good practice if you're serving pages to the internet, but nice while developing locally. There are some inline comments in the source code which may be of help.
 
 ## Further development and comments
 The issues section is used for planning development: Contributions are welcome.
 
-- The /logutils and /benchmark folders contain some features that are not currently fully implemented (or working?), namely a specialized logger. For application development, we generally require very fast logging and this approach may or may not be sufficiently fast.
+- Version 1.3 integrates `WebSocketLogger`. It closely resembles `ConsoleLogger` from the Julia standard library. Additional features: see inline docs and 'examples/count_with_logger.jl'. With this closer integration with Julia's core logging functionality, we also introduce `@debug` statements in `readguarded` and `writeguarded` (as well as when receiving 'ping' or 'pong'). The functions still return a boolean to indicate failure, but return no reason except the logger messages.
+- The /benchmark folder contain some code that is not currently working, pending logging facilities.
 - Alternative Julia packages: [DandelionWebSockets](https://github.com/dandeliondeathray/DandelionWebSockets.jl) and the direct implementation in [HTTP.jl](https://github.com/JuliaWeb/HTTP.jl).
 
 ## Errors after updating?
+### To version 1.3.0
+WebSockets additionaly exports WebSocketLogger, @wslog, Wslog.
+
 ### To version 1.1.0
 This version is driven by large restructuring in HTTP.jl. We import more functions and types into WebSockets, e.g., WebSockets.Request. The main interface does not, intentionally, change, except for 'origin', which should now be qualified as WebSockets.origin.
 

examples/count_with_logger.jl

@@ -0,0 +1,109 @@
+# A server and a client help each other counting to 10.
+using WebSockets
+import WebSockets.with_logger
+import WebSockets.string_with_env_ws
+const COUNTTO = 10
+const PORT = 8090
+addsubproto("count")
+# This overloading only affects the
+# first argument to logging macros, and only when
+# logging with WebSocketLogger
+function string_with_env_ws(env, req::WebSockets.Request)
+    iob = IOBuffer()
+    ioc = IOContext(iob, env)
+    printstyled(ioc, "Request: ", color= :yellow)
+    printstyled(ioc, req.method, color = :bold)
+    print(ioc, " ")
+    printstyled(ioc, req.target, color = :cyan)
+    subprot = subprotocol(req)
+    if subprot != ""
+        print(ioc, "\n")
+        orig = WebSockets.origin(req)
+        print(ioc, "\nOrigin: " * orig * " Subprotocol: " * subprot)
+    end
+    if length(req.headers) > 0
+        print(ioc, " ")
+        printstyled(ioc, "\tHeaders: ", color = :cyan)
+        for (name, value) in req.headers
+            print(ioc, "$name => $value \t")
+        end
+    end
+    String(take!(iob))
+end
+
+httphandler(req::WebSockets.Request) = WebSockets.Response(200, "OK")
+
+function coroutine_count(ws)
+    @wslog ("Enter coroutine, ", ws)
+    success = true
+    protocolfollowed = true
+    counter = 0
+    # Server sends 1
+    if ws.server
+        counter += 1
+        if !writeguarded(ws, Array{UInt8}([counter]))
+            @warn ws, " could not write first message"
+            protocolfollowed = false
+        end
+    end
+
+
+    while isopen(ws) && protocolfollowed && counter < COUNTTO && success
+        protocolfollowed = false
+        data, success = readguarded(ws)
+        if success
+            OUTDATA = data
+            if length(data) == 1
+                if data[1] == counter + 1
+                    protocolfollowed = true
+                    counter += 2
+                    @wslog ws, " Counter: ", counter
+                    writeguarded(ws, Array{UInt8}([counter]))
+                else
+                    @error ws, " unexpected: ", counter
+                end
+            else
+                protocolfollowed = false
+                @warn (ws, " wrong message length: "), length(data)
+                @wslog "Data is type ", typeof(data)
+                @wslog data
+            end
+        end
+    end
+    if protocolfollowed
+        @wslog (ws, " finished counting to $COUNTTO, exiting")
+    else
+        @wslog "Exiting ", ws, " Counter: ", counter
+    end
+end
+
+function gatekeeper(req, ws)
+    @wslog req
+    if subprotocol(req) != ""
+        coroutine_count(ws)
+    else
+        @wslog "No subprotocol"
+    end
+end
+
+function serve_task(logger= WebSocketLogger(stderr, WebSockets.Logging.Debug))
+    server = WebSockets.ServerWS(httphandler, gatekeeper)
+    task = @async   with_logger(logger) do
+        WebSockets.serve(server, port = PORT)
+    end
+    @info "http://localhost:$PORT"
+    return server, task
+end
+
+server, sertask = serve_task()
+
+clitask = @async with_logger(WebSocketLogger(stderr, WebSockets.Logging.Debug)) do
+        WebSockets.open(coroutine_count, "ws://localhost:$PORT", subprotocol = "count")
+    end
+
+@async begin
+    sleep(5)
+    println("Time out 5 s, closing server")
+    put!(server.in, "Close")
+    nothing
+end

examples/minimal_server.jl

@@ -4,32 +4,34 @@ const BAREHTML = "<head><meta http-equiv=\"Content-Type\" content=\"text/html; c
 import Sockets
 const LOCALIP = string(Sockets.getipaddr())
 const PORT = 8080
-const BODY =  "<body><p>Press F12
+const BODY =  "<body><p>Press F12. In console:
                 <p>ws = new WebSocket(\"ws://$LOCALIP:$PORT\")
                 <p>ws.onmessage = function(e){console.log(e.data)}
                 <p>ws.send(\"Browser console says hello!\")
                 </body>"
 
 function coroutine(ws)
+    @info "Started coroutine for " ws
     while isopen(ws)
         data, = readguarded(ws)
         s = String(data)
         if s == ""
             writeguarded(ws, "Goodbye!")
             break
         end
-        println("Received: ", s)
+        @info "Received: $s"
         writeguarded(ws, "Hello! Send empty message to exit, or just leave.")
     end
+    @info "Will now close " ws
 end
 
 function gatekeeper(req, ws)
     orig = WebSockets.origin(req)
-    println("\nOrigin:", orig, "    Target:", target(req), "    subprotocol:", subprotocol(req))
+    @info "\nOrigin: $orig   Target: $(req.target)   subprotocol: $(subprotocol(req))"
     if occursin(LOCALIP, orig)
         coroutine(ws)
     elseif orig == ""
-        @info "Non-browser clients don't send Origin. We liberally accept the update request in this case."
+        @info "Non-browser clients don't send Origin. We liberally accept the update request in this case:" ws
         coroutine(ws)
     else
         @warn "Inacceptable request"
@@ -41,5 +43,7 @@ handle(req) = replace(BAREHTML, "<body></body>" => BODY) |> WebSockets.Response
 const server = WebSockets.ServerWS(handle,
                                     gatekeeper)
 
-@info("Browser > $LOCALIP:$PORT , F12> console > ws = new WebSocket(\"ws://$LOCALIP:$PORT\") ")
-@async WebSockets.serve(server, LOCALIP, PORT);
+@info "In browser > $LOCALIP:$PORT , F12> console > ws = new WebSocket(\"ws://$LOCALIP:$PORT\") "
+@async WebSockets.with_logger(WebSocketLogger()) do
+    WebSockets.serve(server, LOCALIP, PORT)
+end