In Progress
Unit 1, Lesson 21
In Progress

Logging Program Name

Video transcript & code

We're presently in the midst of a series all about logging in Ruby. Today, let's talk about the concept of "program name" as it pertains to logging.

Let's say we have a program that forks into two processes: a child, which acts as a producer of widgets; and a parent, which acts as consumer of widgets. Both of them log their activity as they proceed.

require "logger"
logger = Logger.new($stderr)

IO.popen "-" do |pipe|
  if pipe
    while widget = pipe.gets.chomp
      logger.info "Frobbing widget #{widget}"
    end
  else
    0.step.each do |i|
      sleep 0.5
      logger.info "Making widget #{i}"
      puts i
    end
  end
end

When we run this, we can see that the output of both processes goes into the same stream. If we look very carefully, we can see that some outputs have a different process ID associated with them than others. But this doesn't tell us anything about the role of the process that emitted those messages.

 $ ruby progname.rb
I, [2015-09-06T16:40:06.876645 #18121]  INFO -- : Making widget 0
I, [2015-09-06T16:40:06.877393 #18119]  INFO -- : Frobbing widget 0
I, [2015-09-06T16:40:07.377402 #18121]  INFO -- : Making widget 1
I, [2015-09-06T16:40:07.377793 #18119]  INFO -- : Frobbing widget 1
I, [2015-09-06T16:40:07.877898 #18121]  INFO -- : Making widget 2
I, [2015-09-06T16:40:07.878208 #18119]  INFO -- : Frobbing widget 2
I, [2015-09-06T16:40:08.378325 #18121]  INFO -- : Making widget 3
I, [2015-09-06T16:40:08.378575 #18119]  INFO -- : Frobbing widget 3
I, [2015-09-06T16:40:08.878776 #18121]  INFO -- : Making widget 4
I, [2015-09-06T16:40:08.879089 #18119]  INFO -- : Frobbing widget 4
I, [2015-09-06T16:40:09.379210 #18121]  INFO -- : Making widget 5
I, [2015-09-06T16:40:09.379578 #18119]  INFO -- : Frobbing widget 5
I, [2015-09-06T16:40:09.879679 #18121]  INFO -- : Making widget 6
I, [2015-09-06T16:40:09.879991 #18119]  INFO -- : Frobbing widget 6

Now let's modify the code to include program names. On the parents side of the fork, we set the progname attribute to "parent". On the child side, we set it to "child".

require "logger"
logger = Logger.new($stderr)

IO.popen "-" do |pipe|
  if pipe
    logger.progname = "parent"
    while widget = pipe.gets.chomp
      logger.info "Frobbing widget #{widget}"
    end
  else
    logger.progname = "child"
    0.step.each do |i|
      sleep 0.5
      logger.info "Making widget #{i}"
      puts i
    end
  end
end

When we run the code this time, we can see a new field appear which had been blank in the past. Now it is abundantly clear which messages were emitted by the parent process, and which by the child.

$ ruby progname2.rb
I, [2015-09-06T16:44:00.935039 #18147]  INFO -- child: Making widget 0
I, [2015-09-06T16:44:00.935767 #18145]  INFO -- parent: Frobbing widget 0
I, [2015-09-06T16:44:01.435818 #18147]  INFO -- child: Making widget 1
I, [2015-09-06T16:44:01.436136 #18145]  INFO -- parent: Frobbing widget 1
I, [2015-09-06T16:44:01.936254 #18147]  INFO -- child: Making widget 2
I, [2015-09-06T16:44:01.936599 #18145]  INFO -- parent: Frobbing widget 2
I, [2015-09-06T16:44:02.436726 #18147]  INFO -- child: Making widget 3
I, [2015-09-06T16:44:02.437098 #18145]  INFO -- parent: Frobbing widget 3
I, [2015-09-06T16:44:02.937181 #18147]  INFO -- child: Making widget 4
I, [2015-09-06T16:44:02.937567 #18145]  INFO -- parent: Frobbing widget 4
I, [2015-09-06T16:44:03.437682 #18147]  INFO -- child: Making widget 5
I, [2015-09-06T16:44:03.438020 #18145]  INFO -- parent: Frobbing widget 5
I, [2015-09-06T16:44:03.938111 #18147]  INFO -- child: Making widget 6
I, [2015-09-06T16:44:03.938425 #18145]  INFO -- parent: Frobbing widget 6

Keeping track of program names can be especially important in a "service-oriented architecture" type of deployment setting. If we have different deployed apps playing different roles, and the logs are all sent to a central collection service, setting the program name may be essential to understanding the interplay of our applications.

Of course, in a scenario like this, we may have some standardized log setup code that we share across multiple programs. In that case, it might be nice to have the log setup automatically assign a program name instead of having to remember to customize it for each service.

Here's one really easy way to do that: we can set the logger progname to the value of the special $PROGRAM_NAME global variable. This variable is set to the name of the currently running executable.

require "logger"
logger = Logger.new($stderr)
logger.progname = $PROGRAM_NAME

logger.info "Hello, world"
logger.info "Well, be seein' ya!"

So if we save this file as producer.rb, we see that filename as the program name.

$ ruby producer.rb
I, [2015-09-07T14:05:03.487813 #26746]  INFO -- producer.rb: Hello, world
I, [2015-09-07T14:05:03.487882 #26746]  INFO -- producer.rb: Well, be seein' ya!

But if we rename the file to consumer.rb, and run it again, we see the new program name reflected.

$ mv producer.rb consumer.rb
$ ruby consumer.rb
I, [2015-09-07T14:10:20.761487 #26761]  INFO -- consumer.rb: Hello, world
I, [2015-09-07T14:10:20.761609 #26761]  INFO -- consumer.rb: Well, be seein' ya!

We can put this code in our shared log setup file, and so long as the different services have different executable names, we'll be able to tell them apart in the logs.

And that's it for today. Happy hacking!

Responses