[WIP] core: Add Cowboy stream log handler #1611
Conversation
|
The problem we will have with this approach is that we will miss errors in the cowboy layer. This is similar to what we have right now with the mochiweb/webmachine setup. I was looking into a way to catch all responses including the one's cowboy generates. A they can be important. In the past we had a hard to catch bug happening only to website visitors from the US. We checked our logs, and evaluated everything carefully. Nothing... when I could use the browser with a remote VNC session I could see a 400 response which was not found in our access logs. For cowboy that is potentially all Currently cowboy does not even log those events. This makes it very hard to catch them and add them to a stats and logging engine. Therefor I would like to try a different approach... Using erlangs tracing mechanism. Maybe we could get together and come up with a plan. Another one might be to contribute code to cowboy so logging and stats can be added. PS I waited a bit with implementing the logging because cowboy's author was working on the stream handling. I had hopes that this would improve things for logging and statistics. |
With my stream handler, I do get the 40x status codes and therefore can log them. I just cannot tell the site they belong to (only the hostname).
Yes, Cowboy now supports a chain of stream handlers. As I mentioned, you can do logging and stats with them; the problem is in integrating that with Zotonic: we’re missing some context. |
|
Only for errors happening at the stream level... Check cowboy_http and cowboy_http2... there are a lot of 400 level errors which will never be logged anywhere. |
|
I see. The problem seems to be: Perhaps @essen can help us out. Will Cowboy 2.0 log those internal errors or make them catchable? |
|
I am aware of this issue and would like to resolve it. I am not sure yet how, perhaps what is needed is a separate callback in stream handlers to inform them that Cowboy sends a response, something like I don't think I've opened a ticket in Cowboy for that yet. |
|
The problem I had at the time was a socket on which a comet request had happened received a timeout message which was handled by mochiweb internals while it was busy with another request (not comet). The comet controller didn't properly cancel the timeout, which caused a 400 response on another request. |
|
@essen https://github.com/knutin/elli has a nice event handling mechanism. It is able to report all kinds of internal events to external code. Maybe something similar is possible in cowboy too. |
|
Yes, that's what stream handlers are about. |
|
To be clear: the intent with stream handlers is to expose everything related to streams. The Cowboy 400 responses are part of a stream, just one that is short-circuited, and so should be exposed (with a different callback function). What that function's interface should be remains to be determined. It should cover HTTP/1.1 cases where Cowboy 400s (with/without closing the connection) and HTTP/2 cases where a stream or connection error is returned, so it will be a little difficult to make it really consistent. Stream handlers will probably receive the error reason (consistent) and the action Cowboy decides to take (not so consistent) and return that action, with minor modifications (for example you may add a body to error responses). I believe that should cover all your cases (and if Cowboy crashes, a crash report is produced). |
So that will solve the problem (reported by @mmzeeman above) of stream handlers being unable to catch internal Cowboy errors. My original problem remains, however:
|
|
It doesn't (lack the info) because stream handlers receive the protocol options you set when starting the listener, which means you can pass them whatever you want. |
|
Unfortunately, that won’t suffice for us: we start one Cowboy instance for multiple (Zotonic) sites. We have a Cowboy middleware that routes to the correct site. So while the middleware knows the site the request/response belong to, the Cowboy listener and stream handler do not. |
|
The errors that are short circuited by Cowboy currently do not reach routing (they occur before we know it's a request, and not random garbage, basically), and the request may therefore not even reach the Host header, so it is not possible to associate them with one or another site. |
|
Right, should we then log in two places instead of one?
A variant of this is to have both middleware and stream handler log to the same file, which then should be the host (not site) name. |
|
As far as Cowboy is concerned:
As far as streams are concerned, you should be able to get everything from a stream handler (provided you put it first in the list). There shouldn't be a need for a Zotonic middleware that does access and error logging, that's what stream handlers are for (and also modifying requests, responses, collecting metrics, stats and so on). Now some streams never reach the point where we call the stream handler's init (especially with HTTP/1.1). Those will have a separate callback that's missing now. That leaves only the case of random garbage, receiving something that doesn't look like a request at all, and for which Cowboy immediately closes the connection (without sending anything in some cases, for example in HTTP/1.1 if no request-line was received). Cowboy will never come with logging code (maybe Cowlib can have log formatting code) as logging solutions are numerous and better taken care of by other projects. |
|
@ddeboer For logging/stats we also need the responses from the stream. This is what I did at the zotonic hackday. data(StreamId, IsFin, Data, #state{stream_state=State}=S) ->
?DEBUG({data, StreamId, self()}),
{Commands, State1} = cowboy_stream_h:data(StreamId, IsFin, Data, State),
log_commands(StreamId, Commands),
{Commands, S#state{stream_state=State1}}.I also added custom stream handlers to collect the info which is important for us. This can collect the information which is important for us. The sites dispatcher decides which site and which controller is used. middlewares => [z_stream_handler, z_sites_dispatcher, z_stream_handler, z_cowmachine_middleware, z_stream_handlerI know, it is a ugly, but it works. |
|
BTW, the access log itself can be sent to syslog. Our master has (or had) code which collected the entries in an ets table which was flushed to syslog once every second. |
src/support/z_access_syslog.erl
Outdated
| @@ -53,6 +53,7 @@ start_link(Ident, Opts, Facility, Level) -> | |||
| z_buffered_worker:start_link(?MODULE, ?MODULE, [[Ident, Opts, Facility], Level]). | |||
|
|
|||
| log_access(_LogData) -> | |||
| %% TODO Do access logging here? | |||
There was a problem hiding this comment.
@mmzeeman This is probably the place you’re referring to for the buffered syslogging.
|
@mmzeeman Please comment on my code in this PR (under ‘Files changed’) so we can become more specific. As you can see there, this:
is now outdated in Cowboy: there’s a separate |
| when Handler::module(), State::state(). | ||
| data(StreamID, IsFin, Data, {Handler, State0}) -> | ||
| z:debug_msg(?MODULE, ?LINE, Data), %% Response body | ||
| cowboy_stream:data(StreamID, IsFin, Data, {Handler, State0}). |
There was a problem hiding this comment.
@essen Thank you for helping us out. We’re definitely clear on stream handlers as the place to do logging, but there’s still the question of how we access request/response context (i.e. Zotonic site information) in this stream handler. See z_cowmachine_middleware.erl for our middleware, which in turn calls https://github.com/zotonic/cowmachine.
There was a problem hiding this comment.
I... don't know Zotonic enough to know what it means. What I do know, however, is that you probably will need to parse the host in the stream handler, independently of the routing of requests (and perhaps cache that info in the environment ultimately given to middlewares).
There was a problem hiding this comment.
@ddeboer The context can be found in the state.
There was a problem hiding this comment.
I'll pull this branch to check things with recon_trace. That can be really helpful to check what is going on. It is a pity cowboy_http doesn't export more functions for debugging purposes.
There was a problem hiding this comment.
Aha, I see what you mean... The context was in the state, but it is not there anymore.
There was a problem hiding this comment.
@ddeboer Maybe we should short circuit things and throw in our own stream handler instead of using the default. That allows access to the middleware and the handlers.
There was a problem hiding this comment.
It is a strange solution because cowboy_stream_h executes the middleware. So the handler already has the things it needs. We also don't use cowboy_router and cowboy_handler, but use our own dispatcher and cowmachine.
There was a problem hiding this comment.
cowboy_stream_h creates a process that executes middlewares. Requests are handled by separate processes due to HTTP/2 concurrency requirements.
|
Plans for debugging involve the new tracer/profiler tool I'm working on for RabbitMQ. It'll be there before 2.0. Stay tuned. :-) |
|
Got access logging to syslog working (for now without Zotonic context): |
ddeboer
force-pushed
the
access-logs
branch
2 times, most recently
from
a6d1e4a
to
cc050d2
Compare
|
Nice, it is a start. |
|
It is possible to add a new message/command for logging. Something like this: (adapted version of cowboy_stream_h) %% @todo
%-spec execute(cowboy_req:req(), #state{}, cowboy_middleware:env(), [module()])
% -> ok.
-spec execute(_, _, _) -> _.
execute(_, _, []) ->
ok; %% @todo Maybe error reason should differ here and there.
execute(Req=#{pid := Pid, streamid := StreamID}, Env, [Middleware|Tail]) ->
z:debug_msg(?MODULE, ?LINE, [self(), Env, Middleware]),
case Middleware:execute(Req, Env) of
{ok, Req2, Env2} ->
Pid ! {{Pid, StreamID}, {log_info, [Middleware, Env2]}}, %% <-- CUSTOM COMMAND
z:debug_msg(?MODULE, ?LINE, [self(), Env2, lager:md()]),
execute(Req2, Env2, Tail);
{suspend, Module, Function, Args} ->
proc_lib:hibernate(?MODULE, resume, [Env, Tail, Module, Function, Args]);
{stop, _Req2} ->
ok %% @todo Maybe error reason should differ here and there.
end.and pick it up in the log stream handler. -spec info(cowboy_stream:streamid(), any(), {Handler, State} | undefined)
-> {cowboy_stream:commands(), {Handler, State} | undefined}
when Handler::module(), State::state().
info(StreamID, {log_info, Msg}, #state{request = _Request, next = _Next} = State) ->
z:debug_msg(?MODULE, ?LINE, ["LOG_INFO!!!!", StreamID, Msg]),
{[], State};Then you get the info in the location where it can be used. |
|
Maybe we should keep @essen in the loop here to see what he thinks about spawning vs keeping it in the same process? |
|
It looks like It is also possible to move the logging to cowmachine instead. Then we do it in cowboy middleware where we also do compression. |
|
I didn't leave the loop. :-) Don't forget that you can edit variables that are given to cowboy_stream_h. So if you have for example stream handlers As for what is more efficient, don't know at this time. I would recommend focusing more on stream handlers than middlewares though, as those are more likely to receive improvements. |
We can always make changes in cowboy_stream_h and submit them as a PR to Cowboy. Although @essen has said before that logging doesn’t belong in Cowboy proper, adding more information (without the logging part) may be ok. |
|
@essen Thanks for the clarification... Are you planning to move cowboy_router, and cowboy_handler to a stream handler? |
|
No plans at this time, and definitely not cowboy_handler since it runs the user code and that must not block the connection process. |
|
@essen Why is that a problem? |
|
HTTP/2 is multiplexed, so we can't have one request blocking everything else. Same with upcoming QUIC. |
|
@mmzeeman I agree with moving the logging to a middleware. Perhaps a separate middleware would be better (alongside cowmachine), so we can keep things separated? |
|
Yep... we can use ets to track meta information on the requests along side the responses. Then both the request and protocol processes can send information to the log. Shall we call this application |
|
@ddeboer In order to speed up the finalisation of 1.0, shall we drop a few requirements and add logging with the newly added |
|
It's temporary. I think it would be good to be able to add user-defined data by sending a message. It can benefit Cowboy too, having the handler can be useful. I'm just not sure how it should be represented. |
|
I was thinking about adding an erlang reference to the request to be able to identify it later. I was planning on sending the information to an ets table and let a separate process purge that table and do the logging. The process can combine the information by using the reference. But all of this can be added when we roll out 1.0 because it doesn't break compatibility. |
|
Yeah. My solution would involve you sending a message to the stream handler, and cowboy_metrics_h storing the information in the state and pass it to the callback at the end. Then the user can just send as many messages as needed to centralize the logging of pretty much anything. |
|
When you have a lot of traffic you will have to do some sort of buffering to keep it speedy. On our stable branch logging is currently a bottleneck. |
|
Yes for the logging itself, it definitely should be in a separate process, no question. But for the gathering of information sending a message is probably perfectly fine. It's not much different than writing the info in ets performance-wise. |
|
Indeed, that is a copy, so you probably want to be able to limit the amount of data here. Maybe by providing a handler function so users can pick the information they want to collect. |
|
Depends. Literals are no longer copied. Binaries > 64 bytes are not copied. I'm guessing for most cases this info will not end up being copied. For Cowboy's built-in use we want to add an atom (handler module name) so that's not the most inefficient operation. And for other uses people can go with other solutions via the callback/other processes/ets/... |
Agreed. @essen We’ll pick up more advanced logging in our 1.1. @mworrell and @mmzeeman have some ideas about how to handling logging correctly for large numbers of requests. |
|
There is one problem with the send a message to logger. If the message box of the logger gets filled then the active senders get lower priority or descheduled (back pressure). I prefer to shed log messages above slower request processing. Using @mmzeeman's ets buffering we can easily shed older messages when the logger can't keep up. So I propose to put the ets table in between. |
mworrell
changed the title
|
Would it be a possibility to add logging using the new Something with:
And then some request depending info. |
|
|
|
See ninenines/cowboy@2e8fcb9 for the new I think all the functionality you need is in. If not, make it known quickly, because I am very close to releasing 2.7, although I will probably wait until next week just in case. |
|
@essen Is there documentation about the metrics handling? Checked the cowboy docs, but I guess I was looking at the wrong place. |
|
Superseded by #2571 |
Description
Fix #1406.
This is a RFC for the access logging solution. @mmzeeman pointed us in the direction of a stream handler for access logs. While a stream handler has all request and response information needed for simple access logging (even in case of 50x), it lacks any contextual information, including site name. This is a problem if we want to have a separate access log file for each site (see #1406). (Although I guess we could reason back from host to site name.)
An alternative solution is to forget about the stream handler and add access logging to Cowmachine: there we have all the information we need (i.e.
cowmachine_site).What do you think?
Todo
Checklist