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.

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

Updated documentation, esp. conclusion.md, and fixed add_handler, STDOUT, current_module() #137

Open
wants to merge 3 commits into
base: master
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from all commits
Commits
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
4 changes: 2 additions & 2 deletions docs/quickstart.jl
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,6 @@ critical(logger, "The world is exploding")
child_logger = getlogger("Foo.bar")
setlevel!(child_logger, "warn")
push!(child_logger, DefaultHandler(tempname(), DefaultFormatter("[{date} | {level} | {name}]: {msg}")));
debug(child_logger, "Something that should only be printed to STDOUT on the root_logger.")
warn(child_logger, "Warning to STDOUT and the log file.")
debug(child_logger, "Something that should only be printed to stdout on the root_logger.")
warn(child_logger, "Warning to stdout and the log file.")
exit()
4 changes: 2 additions & 2 deletions docs/src/contributing.md
Original file line number Diff line number Diff line change
Expand Up @@ -6,9 +6,9 @@ Detailed docs on contributing to Julia packages can be found [here](http://docs.

To start hacking code or writing docs, simply:

1. `julia> Pkg.add("Memento"); Pkg.checkout("Memento")`
1. `julia> using Pkg; Pkg.develop("Memento")`
2. Make your changes.
3. Test your changes with `julia --compilecache=no -e 'Pkg.test("Memento"; coverage=true)'`
3. Test your changes with `julia --compiled-modules=no -e 'using Pkg; Pkg.test("Memento"; coverage=true)'`
4. Check that your changes haven't reduced the test coverage. From the root Memento package folder run `julia -e 'using Coverage; Coverage.get_summary(process_folder())'`.
5. Make a pull request to [Memento](https://github.com/invenia/Memento.jl) and share your changes with the rest of the community.

Expand Down
14 changes: 6 additions & 8 deletions docs/src/faq/change-colors.md
Original file line number Diff line number Diff line change
Expand Up @@ -3,10 +3,9 @@
Colors can be enabled/disabled and set using via the `is_colorized` and `colors` options to the `DefaultHandler`.

```julia
julia> add_handler(logger, DefaultHandler(
STDOUT, DefaultFormatter(),
Dict{Symbol, Any}(:is_colorized => true)),
"console"
julia> push!(logger, DefaultHandler(
stdout, DefaultFormatter(),
Dict{Symbol, Any}(:is_colorized => true))
)
```
will create a `DefaultHandler` with colorization.
Expand All @@ -29,8 +28,8 @@ Dict{AbstractString, Symbol}(
However, you can specify custom colors/log levels like so:

```julia
add_handler(logger, DefaultHandler(
STDOUT, DefaultFormatter(),
push!(logger, DefaultHandler(
stdout, DefaultFormatter(),
Dict{Symbol, Any}(
:colors => Dict{AbstractString, Symbol}(
"debug" => :black,
Expand All @@ -39,8 +38,7 @@ add_handler(logger, DefaultHandler(
"error" => :red,
"crazy" => :green
)
),
"console"
)
)
```

Expand Down
5 changes: 2 additions & 3 deletions docs/src/faq/json-formatting.md
Original file line number Diff line number Diff line change
Expand Up @@ -8,12 +8,11 @@ However, the original behaviour can still be easily achieved by passing in `JSON
```julia
using JSON

add_handler(
push!(
logger,
DefaultHandler(
"json-output.log",
DictFormatter(JSON.json)
),
"JSON"
)
)
```
10 changes: 4 additions & 6 deletions docs/src/faq/logging-to-syslog.md
Original file line number Diff line number Diff line change
Expand Up @@ -21,25 +21,23 @@ end
Now we can start logging to syslog locally:

```julia
add_handler(
push!(
logger,
DefaultHandler(
Syslog(),
DefaultFormatter("{level}: {msg}")
),
"Syslog"
)
)
```

We can also log to remote syslog servers via UDP or TCP:

```julia
add_handler(
push!(
logger,
DefaultHandler(
Syslog(ip"123.34.56.78"),
DefaultFormatter("{level}: {msg}")
),
"Syslog"
)
)
```
10 changes: 5 additions & 5 deletions docs/src/index.md
Original file line number Diff line number Diff line change
Expand Up @@ -65,14 +65,14 @@ julia> push!(child_logger, DefaultHandler(tempname(), DefaultFormatter("[{date}

Memento.DefaultHandler{Memento.DefaultFormatter,IOStream}(Memento.DefaultFormatter("[{date} | {level} | {name}]: {msg}"),IOStream(<file /var/folders/_6/25myjdtx2fxgjvznn19rp22m0000gn/T/julia8lonyA>),Dict{Symbol,Any}(Pair{Symbol,Any}(:is_colorized,false)))

julia> debug(child_logger, "Something that should only be printed to STDOUT on the root_logger.")
[debug | Foo.bar]: Something that should only be printed to STDOUT on the root_logger.
julia> debug(child_logger, "Something that should only be printed to stdout on the root_logger.")
[debug | Foo.bar]: Something that should only be printed to stdout on the root_logger.

julia> warn(child_logger, "Warning to STDOUT and the log file.")
[warn | Foo.bar]: Warning to STDOUT and the log file.
julia> warn(child_logger, "Warning to stdout and the log file.")
[warn | Foo.bar]: Warning to stdout and the log file.
```

NOTE: We used `getlogger("Foo.bar")`, but you can also do `getlogger(current_module())` which allows us to avoid hard coding in logger names.
NOTE: We used `getlogger("Foo.bar")`, but you can also do `getlogger(@__MODULE__)` which allows us to avoid hard coding in logger names.

## Piggybacking onto another package's logger

Expand Down
71 changes: 50 additions & 21 deletions docs/src/man/conclusion.md
Original file line number Diff line number Diff line change
Expand Up @@ -15,7 +15,7 @@ using Memento

function run(f::Function, args...; kwargs...)
ret = nothing
logger = getlogger(current_module())
logger = getlogger(@__MODULE__)
info(logger, "Got logger $logger")

notice(logger, "Running function...")
Expand All @@ -37,7 +37,7 @@ Now we want to start writing our application code that uses this package, but ou
Requirements:

1. This will be run on Amazon EC2 instances and we want our log message to contain information about the machine the code is being run on.
2. We want our logs to be written to an HTTP REST service (kinda like Loggly), where the endpoint is of the form `https://<account_uri>/<app_name>/<level>?AccessKey=<access_key>`.
2. We want our logs to be written to an HTTP REST service (kinda like Loggly), where the endpoint is of the form `https://<account_uri>/<app_name>/<level>?AccessKey=<access_key>`, and an Authorization header and a Content-Type header.
3. We want our logs to be written in a CSV format... for some reason.

Okay, so how do we address all of those requirements using Memento's API?
Expand All @@ -54,7 +54,8 @@ NOTE: The code below is not intended to be a working example because it assumes
# myapp.jl
using Wrapper
using Memento
using Requests # For send logs to our fake logging REST service
using Memento.TimeZones
using HTTP # For send logs to our fake logging REST service

# Start by setting up our basic console logging for the root logger.
logger = Memento.config!("info"; fmt="[{level} | {name}]: {msg}")
Expand All @@ -78,17 +79,17 @@ mutable struct EC2Record <: Record
trace = Attribute{StackTrace}(get_trace)

EC2Record(
Attribute{DateTime}(() -> round(time, Dates.Second)),
Attribute(args[:level]),
Attribute(args[:levelnum]),
Attribute{AbstractString}(get_msg(args[:msg])),
Attribute(args[:name]),
Attribute(myid()),
Attribute{StackFrame}(get_lookup(trace)),
Attribute{ZonedDateTime}(() -> Dates.now(tz"UTC")),
Attribute(level),
Attribute(levelnum),
Attribute{AbstractString}(msg),
Attribute(name),
Attribute(getpid()),
Attribute{Union{StackFrame, Nothing}}(get_lookup(trace)),
trace,
Attribute(ENV["INSTANCE_ID"]),
Attribute(ENV["PUBLIC_IP"]),
Attribute(ENV["IAM_USER"]),
Attribute(get(ENV, "INSTANCE_ID", "no INSTANCE_ID")),
Attribute(get(ENV, "PUBLIC_IP", "no PUBLIC_IP")),
Attribute(get(ENV, "IAM_USER", "no IAM_USER")),
)
end
end
Expand Down Expand Up @@ -121,18 +122,45 @@ end

# Our print method builds the correct uri using the log level
# and sends the put request.
function println(io::REST, level::AbstractString, msg::AbstractString)
uri = "https://$(io.account_uri)/$(io.app_name)/$level?AccessKey=$(io.access_key)"
@async put(uri; data=msg)
global REST_LOG_TASKS = []
Copy link
Member

Choose a reason for hiding this comment

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

Might be better to store this as a Channel in the REST type to avoid having globals floating around? We could then control the size of the queue and have log writing wait until other requests have completed. The cleanup in the Base.atexit could then be done in a finalizer.

Copy link
Member

Choose a reason for hiding this comment

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

Also, this is unrelated to your PR, but I wonder if this example would be simpler if we just made the REST a Handler rather than an IO. This seems complicated enough that it might warrant it now.

Copy link

@peteristhegreat peteristhegreat Jan 24, 2020

Choose a reason for hiding this comment

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

A channel in the struct is probably better, especially if it doesn't touch the global scope. I would assume a channel could take task handles properly.

My logging to Restful interfaces is pretty cookie cutter based on this new code. Adding it as an included Handler would be nice. Though I don't need CSV, just json.

After I finished this PR, I also found I needed to filter out the stack trace more than what Memento was doing, so I added some more lines to remove the stack trace origination out of this new file's calls to get the trace.

Copy link
Member

@rofinn rofinn Jan 27, 2020

Choose a reason for hiding this comment

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

A channel in the struct is probably better, especially if it doesn't touch the global scope. I would assume a channel could take task handles properly.

Yeah, it's just a reference. I think they channel solution would look something like this:

julia> using Distributed

# Construction of the task channel
julia> taskref = Ref{Task}();

julia> c = Channel{Task}(10; taskref=taskref) do ch
           while isopen(ch) || isready(ch)
               t = take!(ch)
               resp = timedwait(() -> istaskdone(t), timeout)
               # resp can be :ok, :timed_out or :error
           end
       end
Channel{Task}(sz_max:10,sz_curr:0)

julia> julia> put!(c, @async 2 + 4)
Task (done) @0x0000000109031450

# Registering cleanup on object cleanup
# Near end of handler constructor
finalizer(handler) do
    timedwait(() -> istaskdone(handler.taskref), timeout)
end

After I finished this PR, I also found I needed to filter out the stack trace more than what Memento was doing, so I added some more lines to remove the stack trace origination out of this new file's calls to get the trace.

Would you mind posting that logic in a separate MR? That sounds like a bug we should fix.

global queue_cleanup = false

function Base.println(io::REST, level::AbstractString, msg::AbstractString)
uri = "https://$(io.account_uri)/$(io.app_name)/$(level)?AccessKey=$(io.access_key)"
headers = [ "Authorization" => io.access_key,
"Content-Type" => "text/csv" ]
data = msg
t = @async HTTP.post(uri, headers, data)

# Bookkeeping for handling @async tasks at exit
global REST_LOG_TASKS, queue_cleanup
push!(REST_LOG_TASKS, t)
filter!(t -> !istaskdone(t), REST_LOG_TASKS)
if !queue_cleanup
queue_cleanup = true
Base.atexit(finish_rest_log_tasks)
end
end

# A flush for @async tasks, to guarantee that the logs will have some time to finish writing, hooked in with atexit lazily
function finish_rest_log_tasks(timeout=5.0)
Copy link
Member

Choose a reason for hiding this comment

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

Since this is only ever used once couldn't you just define the logic here inside a do-block at the Base.atexit call?

Copy link
Member

Choose a reason for hiding this comment

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

Also, why make timeout an argument if we never change it?

Choose a reason for hiding this comment

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

The examples for hooking into the atexit that I've seen before require registering a zero argument function. I don't know if a do block would work. Do you have an example of doing that?

As for the timeout, I think there is a chance someone would want to manually call this function. At least I did while I was testing it. For my splunk server it needed at least 2 seconds to finish sending a log REST message if I logged and closed julia right away.

Copy link
Member

Choose a reason for hiding this comment

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

The examples for hooking into the atexit that I've seen before require registering a zero argument function. I don't know if a do block would work. Do you have an example of doing that?

julia> Base.atexit() do
           println("Goodbye!")
       end

julia> exit()
Goodbye!

As for the timeout, I think there is a chance someone would want to manually call this function. At least I did while I was testing it. For my splunk server it needed at least 2 seconds to finish sending a log REST message if I logged and closed julia right away.

That's fair. Maybe the timeout should be a property of the type? Figuring out the best timeout value would then be configurable as part of the existing public API.

timer = Timer(timeout)
while any(t -> !istaskdone(t), REST_LOG_TASKS) && isopen(timer)
Copy link
Member

Choose a reason for hiding this comment

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

Couldn't you just use timedwait for this?

Choose a reason for hiding this comment

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

I haven't used timedwait before. If it achieves the same functionality, sure!

sleep(0.05)
yield()
filter!(t -> !istaskdone(t), REST_LOG_TASKS)
end
if !isopen(timer) && any(t -> !istaskdone(t), REST_LOG_TASKS)
error("Some REST_LOG_TASKS did not complete! Gave up after $timeout seconds.")
end
end

# Not relevant, but good to have.
flush(io::REST) = io
Base.flush(io::REST) = io

# We still need to special case the `DefaultHandler` `log` method to call `println(io::REST, level, msg)`
function log(handler::DefaultHandler{F, O}, rec::Record) where {F<:Formatter, O<:REST}
msg = format(handler.fmt, rec)
println(handler.io, rec.level, msg)
# We still need to special case the `DefaultHandler` `emit` method to call `println(io::REST, level, msg)` otherwise we will get an error "REST does not support byte I/O"
function emit(handler::DefaultHandler{F, O}, rec::Record) where {F<:Formatter, O<:REST}
println(handler.io, getlevel(rec), format(handler.fmt, rec))
flush(handler.io)
end

Expand All @@ -152,6 +180,7 @@ push!(
)
)


# Don't forget to update the root logger `Record` type.
setrecord!(logger, EC2Record)

Expand Down
4 changes: 2 additions & 2 deletions docs/src/man/loggers.md
Original file line number Diff line number Diff line change
@@ -1,10 +1,10 @@
# [Loggers](@id man_loggers)

A [`Logger`](@ref) is the primary component you use to send formatted log messages to various IO outputs. This type holds information needed to manage the process of creating and storing logs. There is a default "root" logger stored in const `_loggers` inside the `Memento` module. Since Memento implements hierarchical logging you should define child loggers that can be configured independently and better describe the individual components within your code.
To create a new logger for you code it is recommended to do `getlogger(current_module())`.
To create a new logger for you code it is recommended to do `getlogger(@__MODULE__)`.

```julia
julia> logger = getlogger(current_module())
julia> logger = getlogger(@__MODULE__)
```

Log messages are brought to different output streams by [`Handler`s](@ref man_handlers). From here you can add and remove handlers. To add a handler that writes to rotating log files, simply:
Expand Down
2 changes: 1 addition & 1 deletion docs/src/man/records.md
Original file line number Diff line number Diff line change
Expand Up @@ -44,7 +44,7 @@ mutable struct EC2Record <: AttributeRecord
Attribute(levelnum),
Attribute{AbstractString}(msg),
Attribute(name),
Attribute(myid()),
Attribute(getpid()),
Attribute{StackFrame}(get_lookup(trace)),
trace,
Attribute(ENV["INSTANCE_ID"]),
Expand Down
2 changes: 1 addition & 1 deletion src/Memento.jl
Original file line number Diff line number Diff line change
Expand Up @@ -51,7 +51,7 @@ include("memento_test.jl")
include("deprecated.jl")

# Initializing at compile-time will work as long as the loggers which are added do not
# contain references to STDOUT.
# contain references to stdout.
const _loggers = Dict{AbstractString, Logger}(
"root" => Logger("root"),
)
Expand Down
2 changes: 1 addition & 1 deletion src/records.jl
Original file line number Diff line number Diff line change
Expand Up @@ -160,7 +160,7 @@ function DefaultRecord(name::AbstractString, level::AbstractString, levelnum::In
Attribute(levelnum),
Attribute{AbstractString}(msg),
Attribute(name),
Attribute(myid()),
Attribute(getpid()),
Attribute{Union{StackFrame, Nothing}}(get_lookup(trace)),
trace,
)
Expand Down