When does journald-native work better?

Apr 5, 2016 • Comments

There is already a nice gem called systemd-journal, why another one? Well, because there are some edge cases that it does not cover. I had a trouble with one.

Imagine that your site can receive some arbitrary data from user.

received_message = "HAHA I'M HAXXOR! \\0 SOME CORRUPT DATA"

Then you try to parse it. This will fail with many libraries written in C, JSON for example.

we_need_this_data = JSON["[#{received_message}]"]
# JSON::ParserError: 399: unexpected token at 'HAHA I'M HAXXOR! '

Then we try to log it. Our logger uses systemd-journal:

Systemd::Journal.message(
    priority: Systemd::Journal::LOG_WARNING,
    message:  "Parser failed on some data",
    data:     received_message,
)
# ArgumentError: string contains null byte
#    from .../gems/ffi-1.9.10/lib/ffi/variadic.rb:56:in `invoke'
#    from .../gems/ffi-1.9.10/lib/ffi/variadic.rb:56:in `call'
#    from (eval):3:in `sd_journal_send'
#    from .../gems/systemd-journal-1.2.0/lib/systemd/journal/writable.rb:78:in `message'

Whoops! We crashed the logger! Our logger is affected too! Let's try journald-native:

Journald::Native.send(
    "PRIORITY=#{Journald::LOG_WARNING}",
    "MESSAGE=Parser failed on some data",
    "DATA=#{received_message}",
)
# => 0

OMG! It works! Let's see what is saved.

journalctl -o json-pretty

{
    "PRIORITY" : "4",
    "SYSLOG_IDENTIFIER" : "irb",
    "MESSAGE" : "Parser failed on some data",
    "DATA" : [
        72, 65, 72, 65, 32, 73, 39, 77, 32, 72, 65, 88, 88, 79, 82, 33,
        32, 0,  32, 83, 79, 77, 69, 32, 67, 79, 82, 82, 85, 80, 84, 32,
        68, 65, 84, 65
    ]
}

Our corrupt message is saved as a byte sequence which we can analyze now.

Next post will be about correct handling of Ruby strings in C extensions.