Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Issue 90: Add additional instrumentation for flash messages. #173

Merged
merged 7 commits into from
Nov 11, 2021
Merged

Issue 90: Add additional instrumentation for flash messages. #173

Show file tree
Hide file tree
Changes from 3 commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
7e897c8
Add additional instrumentation for flash messages.
jsthomas Nov 10, 2021
4dc6623
Adjust whitespace.
jsthomas Nov 10, 2021
2010aad
Adjust whitespace.
jsthomas Nov 10, 2021
bd2c8b3
Revise indentation.
jsthomas Nov 10, 2021
957a09f
Move log point before inner_handler call.
jsthomas Nov 11, 2021
fa30003
Remove use of initialize_log in example.
jsthomas Nov 11, 2021
7321682
Save a round-trip on trivial nits
aantron Nov 11, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
12 changes: 12 additions & 0 deletions example/w-flash/README.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -48,6 +48,8 @@ into cookies and reads them back out:

```ocaml
let () =
Dream.initialize_log ~level:`Info ();
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

AFAIK this call shouldn't be necessary. Is it? If set_log_level requires it, set_log_level should be altered to do a lazy internal initialize_log.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

When I tested this against the w-flash example it did appear to be necessary; unfortunately I don't fully understand why. I've updated set_log_level.

Dream.set_log_level "dream.flash" `Debug;
Dream.run
@@ Dream.logger
@@ Dream.memory_sessions
Expand Down Expand Up @@ -75,6 +77,16 @@ let () =
@@ Dream.not_found
```

The example configures a custom log level for flash messages using
`Dream.set_log_level`. Setting this to "debug" means the server logs
will display a log point summarizing the flash messages on every
request, like this:

```
10.11.21 01:48:21.629 dream.log INFO REQ 3 GET /result ::1:39808 Mozilla/5.0 (X11; Linux x86_64; rv:78.0) Gecko/20100101 Firefox/78.0
10.11.21 01:48:21.629 dream.flash DEBUG REQ 3 Flash messages: Info: Some Message
```

<pre><code><b>$ cd example/w-flash</b>
<b>$ npm install esy && npx esy</b>
<b>$ npx esy start</b></code></pre>
Expand Down
6 changes: 4 additions & 2 deletions example/w-flash/flash.eml.ml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,8 @@ let result request =
</html>

let () =
Dream.initialize_log ~level:`Info ();
Dream.set_log_level "dream.flash" `Debug;
Dream.run
@@ Dream.logger
@@ Dream.memory_sessions
Expand All @@ -31,8 +33,8 @@ let () =
Dream.post "/"
(fun request ->
match%lwt Dream.form request with
| `Ok ["text", text] ->
let () = Dream.put_flash "Info" text request in
| `Ok ["text", text] ->
let () = Dream.put_flash "Info" text request in
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why have these lines had an indentation-only change?

Also, where does this kind of indentation come from? It is wasteful of the left margin.

Dream.redirect request "/result"
| _ ->
Dream.redirect request "/");
Expand Down
63 changes: 40 additions & 23 deletions src/middleware/flash.ml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,29 +19,9 @@ let storage =
let flash_cookie =
"dream.flash"



let flash_messages inner_handler request =
let outbox = ref [] in
let request = Dream.with_local storage outbox request in
let%lwt response = inner_handler request in
let entries = List.rev !outbox in
let existing = Dream.cookie flash_cookie request in
let response =
match existing, entries with
| None, [] -> response
| Some _, [] ->
Dream.set_cookie flash_cookie "" request response ~expires:0.
| _, _ ->
let content =
List.fold_right (fun (x,y) a -> `String x :: `String y :: a) entries []
in
let value = `List content |> Yojson.Basic.to_string in
Dream.set_cookie flash_cookie value request response ~max_age:five_minutes
in
Lwt.return response


(* This is a soft limit. Encryption and base64 encoding increase the
original size of the cookie text by ~4/3.*)
let content_byte_size_limit = 3072

let (|>?) =
Option.bind
Expand Down Expand Up @@ -76,3 +56,40 @@ let put_flash category message request =
failwith message
in
outbox := (category, message)::!outbox

let flash_messages inner_handler request =
let outbox = ref [] in
let request = Dream.with_local storage outbox request in
let%lwt response = inner_handler request in
let entries = List.rev !outbox in
let existing = Dream.cookie flash_cookie request in
log.debug (fun log ->
let current =
flash request
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Shouldn't this display the contents of outbox, rather than reading the cookie, which AFAIK is the flash messages returned in the request? If you'd like to display incoming flash messages as I think this is doing, I think it should be done before the call to inner_handler.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In the issue, @thangngoc89 wrote that it was "frustrating to debug why flash messages aren't rendered". I thought it made sense to log the flash messages from the current request's cookie because those are the ones available for rendering a response. This also appears to match the behavior of the example code in the issue description.

I've fixed the ordering with inner_handler; that was an oversight on my part.

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The question is, in the original ordering, why read the cookie on the request (flash request), rather than reading outbox? Aren't the messages in the outbox the ones that will be put in the response?

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah okay, I understood you. I got double-negative-confused by myself :) Okay, I now think this is doing what #90 was asking, and the ordering makes sense now.

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could you move the debug print all the way to the top of the middleware? It doesn't seem to depend on any of the values bound before it now, and having them bound there makes it seem like it might depend. It's a clean print of the flash messages being returned to the server. It will especially make it clear that the logging does not depend on the rebinding of request to one that has the outbox attached.

|> List.map (fun (p,q) -> p ^ ": " ^ q)
|> String.concat ", " in
if String.length current > 0 then
log ~request "Flash messages: %s" current
else
log ~request "%s" "No flash messages."
);
let response =
match existing, entries with
| None, [] -> response
| Some _, [] ->
Dream.set_cookie flash_cookie "" request response ~expires:0.
| _, _ ->
let content =
List.fold_right (fun (x,y) a -> `String x :: `String y :: a) entries []
in
let value = `List content |> Yojson.Basic.to_string in
let () = if String.length value >= content_byte_size_limit
then
log.warning (fun log ->
log ~request
"Flash messages exceed soft size limit (%d bytes)"
content_byte_size_limit)
else () in
Dream.set_cookie flash_cookie value request response ~max_age:five_minutes
in
Lwt.return response