Logging sources #502

spuun · 2023-04-19T12:19:24Z

Refactor logging to embrace Crystal's Log pattern with sources.

Instead of adding e.g. entity name to the source it will be appended as metadata in all entries.

New configuration section log_levels:

[log_levels]
lavinmq.vhost = info
lavinmq.launcher = debug

If log_levels is used log_level in main section won't have any effect.

Sources:

lavinmq.amqpconnection
lavinmq.http
lavinmq.http.server
lavinmq.launcher
lavinmq.schema
lavinmq.schema.v4
lavinmq.server
lavinmq.vhost
lavinmq.vhost.client
lavinmq.vhost.client.channel
lavinmq.vhost.exchange
lavinmq.vhost.federation
lavinmq.vhost.federation.upstream
lavinmq.vhost.federation.upstream.exchangelink
lavinmq.vhost.federation.upstream.queuelink
lavinmq.vhost.federation.upstreamstore
lavinmq.vhost.shovel
lavinmq.vhost.shovel.amqpdestination
lavinmq.vhost.shovel.amqpsource
lavinmq.vhost.shovel.httpdestination
lavinmq.vhost.shovel.store
lavinmq.vhost.vhoststore

src/lavinmq/queue/queue.cr

github-actions · 2023-04-19T12:23:28Z

Main benchmark
'Average publish rate: 402353.6 msgs/s'
'Average consume rate: 402127.6 msgs/s'

PR benchmark
'Average publish rate: 272645.7 msgs/s'
'Average consume rate: 271255.5 msgs/s'

Keep in mind, these numbers are not representative of LavinMQ's peak performance.
It is rather an indication of how the changes of this pull request affects the performance of the main branch.

viktorerlingsson

LGTM!

carlhoerberg · 2023-05-12T12:29:00Z

Wondering if the lavinmq. prefix is needed? this software isn't included in other applications (as for example a library would)

carlhoerberg · 2023-05-12T12:29:59Z

What is this new EntityLog? Can't the native Log::Context be used?

spuun · 2023-05-15T06:53:48Z

What is this new EntityLog? Can't the native Log::Context be used?

Log::Context is per fiber, and it may be different fibers accessing the same object. EntityLog will use Metadata and append "context" for the current entity in each log call.

spuun · 2023-05-15T06:55:54Z

Wondering if the lavinmq. prefix is needed? this software isn't included in other applications (as for example a library would)

Maybe not, I just think it's nice to be explicit. Also, if you want debug for lavinmq code but not libraries you must specify a level for each of the libraries too.

spuun · 2023-05-24T11:52:42Z

@carlhoerberg wdyt?

carlhoerberg · 2023-08-08T19:59:19Z

src/lavinmq/client/channel.cr

@@ -12,10 +12,12 @@ module LavinMQ
      include Stats
      include SortableJSON

+      Log = Client::Log.for "channel"


Is this still needed?

Suggested change

Log = Client::Log.for "channel"

It's used by the EntityLog for Channel, and also by Consumer.

Following the docs/"pattern" for Log, declaring a Log per namespace seems to be the way to go. Sticking to always declaring Log in module/class makes it consistent on where source is set. I have no real opinion on this. Also, as I mention in the other comment, I thought it would create a new Log instance for every for call.

carlhoerberg · 2023-08-08T19:59:53Z

src/lavinmq/client/channel/consumer.cr


 module LavinMQ
  class Client
    class Channel
      class Consumer
        include SortableJSON

+        Log = Channel::Log


what is this used by?

It's declared here to show that Consumer has the same log source as Channel. It's then used by each Consumer's EntityLog.

src/lavinmq/config.cr

carlhoerberg · 2023-08-09T19:44:17Z

src/lavinmq/federation/upstream_store.cr


      def initialize(@vhost : VHost)
-        @log = Log.for "UpstreamStore[vhost=#{@vhost}]"
+        @log = @vhost.log.extend(Log)


why not?

Suggested change

@log = @vhost.log.extend(Log)

@log = @vhost.log.extend(Federation::Log.for "upstreamstore")

Isn't there a risk that someone starts to use Log in the class otherwise? and/or that the Log = Federation::Log.for "upstreamstore" is removed because it's not used except here, but kind of implicitly.

Yes, absolutely.

IIRC the reason for setting Log and use that was that I assumed that Log.for would create a new Log instance for every call. Now that I've read the code and I see that it's not, this could be changed.

The Queue::Log instnance is wrapped and vhost name and queue name is passed as metadata to all log entries instead of being a part of the log source.

Make it easier to use Log constans, step by step.

- Use class constant Log as "base" for all logging. - Wrap some Log in EntityLog to "tag" entries

Queue, Exchange and Client are all subentities to vhost.

crystal-lang/crystal#13404

... to get rid of editor warnings

carlhoerberg · 2023-09-13T06:31:11Z

src/lavinmq/launcher.cr

    @tls_context : OpenSSL::SSL::Context::Server?
    @first_shutdown_attempt = true
    @data_dir_lock : DataDirLock?
+    @log_setup = false


doens't seem to be used

Suggested change

@log_setup = false

carlhoerberg · 2023-09-13T06:31:47Z

src/lavinmq/launcher.cr

+::Log.setup_from_env(
+  backend: Log::IOBackend.new(
+    formatter: LavinMQ::Logging::StdoutLogFormat))


means that we get logs in specs, in systemd environments etc with wrong format?

Dunno what you mean with wrong format? It's the same formatter as will be used again when the log is configured from config.

I don't recall exactly why I added this, but it's to have a "default logger" configured before we've parse the config.

Move extend method to Log::Metadata to make it more efficient. This will reduce the need of temporary hashes when creating the new Metadata.

spuun · 2024-03-06T09:51:06Z

Closing this for now. We're probably not going with it.

spuun commented Apr 19, 2023

View reviewed changes

src/lavinmq/queue/queue.cr Outdated Show resolved Hide resolved

spuun force-pushed the logging-sources branch 2 times, most recently from 30bd9bf to 1fdb20e Compare May 2, 2023 07:45

spuun requested review from carlhoerberg, viktorerlingsson and kickster97 May 2, 2023 07:45

spuun marked this pull request as ready for review May 6, 2023 08:48

spuun force-pushed the logging-sources branch from 31b1d66 to 7382c2b Compare May 9, 2023 19:03

kickster97 approved these changes May 12, 2023

View reviewed changes

viktorerlingsson approved these changes May 12, 2023

View reviewed changes

spuun force-pushed the logging-sources branch from 7382c2b to 2c837d9 Compare June 26, 2023 06:02

carlhoerberg reviewed Aug 8, 2023

View reviewed changes

spuun force-pushed the logging-sources branch from 2c837d9 to a1506a2 Compare August 9, 2023 12:42

carlhoerberg reviewed Aug 9, 2023

View reviewed changes

spuun force-pushed the logging-sources branch 3 times, most recently from e21dfdc to fe0b7ef Compare August 16, 2023 08:45

spuun force-pushed the logging-sources branch from fe0b7ef to aac7a52 Compare September 5, 2023 10:45

spuun added 6 commits September 11, 2023 08:00

Append metadata after source in logs

ec61a63

Use EntityLog instead of Log in Queue

6decb94

The Queue::Log instnance is wrapped and vhost name and queue name is passed as metadata to all log entries instead of being a part of the log source.

Use fully-qualified type path when referencing Log

ee50fd8

Make it easier to use Log constans, step by step.

Remove "helper macro"

00fd2cf

Add possibility to create "child loggers"

4205261

Dont emit nil values

590e321

spuun added 18 commits September 11, 2023 08:02

Fix ordering of metadata

f9281dc

Add specs for EntrityLog

cebe084

Replace all loggers with class Log or an EntitiyLog

5404dca

- Use class constant Log as "base" for all logging. - Wrap some Log in EntityLog to "tag" entries

Configure log early

71db606

Add log_sources configuration

d7347cd

Add fiber name to log

e7246c2

Put queue, exchange and client under vhost

5777a8a

Queue, Exchange and Client are all subentities to vhost.

Use log_levels config section if it exists

af3628b

Fix log sources hierarchy

3a91b94

Setup default logging early

cc224aa

Use workaround for broadcast backend bug

942a721

crystal-lang/crystal#13404

Organize logging code

bfc24c1

Move declaration of LavinMQ::Log

82ce072

... to get rid of editor warnings

Add more assertions

8ef946d

Spelling

34fe140

Log thread id

b40dd67

Always add HTTP LogHandler

38ba464

Update changelog

11984c3

spuun force-pushed the logging-sources branch from aac7a52 to 11984c3 Compare September 11, 2023 06:05

carlhoerberg added 3 commits September 12, 2023 11:11

Merge branch 'main' into logging-sources

a010550

don't double include files in spechelper

97dd82b

Log severy parse

5fc470d

carlhoerberg reviewed Sep 13, 2023

View reviewed changes

spuun mentioned this pull request Sep 14, 2023

Use Log#emit and Log::Metadata #573

Merged

Refactor EntityLog extend

228cd53

Move extend method to Log::Metadata to make it more efficient. This will reduce the need of temporary hashes when creating the new Metadata.

spuun closed this Mar 6, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Logging sources #502

Logging sources #502

spuun commented Apr 19, 2023 •

edited

Loading

github-actions bot commented Apr 19, 2023 •

edited

Loading

viktorerlingsson left a comment

carlhoerberg commented May 12, 2023

carlhoerberg commented May 12, 2023

spuun commented May 15, 2023

spuun commented May 15, 2023 •

edited

Loading

spuun commented May 24, 2023

carlhoerberg Aug 8, 2023

spuun Aug 10, 2023

carlhoerberg Aug 8, 2023

spuun Aug 9, 2023

carlhoerberg Aug 9, 2023

spuun Aug 10, 2023

carlhoerberg Sep 13, 2023

carlhoerberg Sep 13, 2023

spuun Sep 13, 2023

spuun commented Mar 6, 2024

	@log = @vhost.log.extend(Log)
	@log = @vhost.log.extend(Federation::Log.for "upstreamstore")

Logging sources #502

Logging sources #502

Conversation

spuun commented Apr 19, 2023 • edited Loading

github-actions bot commented Apr 19, 2023 • edited Loading

viktorerlingsson left a comment

Choose a reason for hiding this comment

carlhoerberg commented May 12, 2023

carlhoerberg commented May 12, 2023

spuun commented May 15, 2023

spuun commented May 15, 2023 • edited Loading

spuun commented May 24, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

spuun commented Mar 6, 2024

spuun commented Apr 19, 2023 •

edited

Loading

github-actions bot commented Apr 19, 2023 •

edited

Loading

spuun commented May 15, 2023 •

edited

Loading