1. Rogue Monkey Technologies Avatar Rogue Monkey Technologies
  2. Untitled project
  3. PaperTrailLumberjack
  4. Issues

Parentheses in machineName, or brackets in machineName or programName

Issue #13 resolved
Yves-Eric Martin created an issue

I found some weird bugs tying to follow the PaperTrail recommendation and using an iOS app version as machineName. For debugging purposes, I wanted to add the build number and tried something like MyApp-1.0(123) or `MyApp-1.0[123], but neither worked, and was able to track down some weird behaviors:

Parenthesis

When setting a machineName that contains a parenthesis, the previous non-parenthesis machineName is somehow left behind and still inserted in the log line, causing everything to slide to the right: the new machineName becomes the programName, and the new programName becomes part of the message. Note that having parentheses in the programName works fine.

Brackets

When using brackets in machineName, the same issue as above also happens, but on top of that, further corruption of the log line occur (beginning of the line seems to get duplicated). The same corruption happens when brackets are used in the programName.

See the attached PaperTrail screenshot highlighting the buggy part.

Steps to reproduce:

    // Alphanum only
    paperTrailLogger.machineName = "A"
    paperTrailLogger.programName = "X"
    DDLogVerbose("************ machineName: A,    programName: X")
    paperTrailLogger.machineName = "B"
    paperTrailLogger.programName = "Y"
    DDLogVerbose("************ machineName: B,    programName: Y")
    paperTrailLogger.machineName = "C"
    paperTrailLogger.programName = "Z"
    DDLogVerbose("************ machineName: C,    programName: Z")

    // Parentheses in programName
    paperTrailLogger.machineName = "A"
    paperTrailLogger.programName = "X()X"
    DDLogVerbose("********* machineName: A,    programName: X()X")
    paperTrailLogger.machineName = "B"
    paperTrailLogger.programName = "Y()Y"
    DDLogVerbose("********* machineName: B,    programName: Y()Y")
    paperTrailLogger.machineName = "C"
    paperTrailLogger.programName = "Z()Z"
    DDLogVerbose("********* machineName: C,    programName: Z()Z")

    // Brackets in programName
    paperTrailLogger.machineName = "A"
    paperTrailLogger.programName = "X[]X"
    DDLogVerbose("********* machineName: A,    programName: X[]X")
    paperTrailLogger.machineName = "B"
    paperTrailLogger.programName = "Y[]Y"
    DDLogVerbose("********* machineName: B,    programName: Y[]Y")
    paperTrailLogger.machineName = "C"
    paperTrailLogger.programName = "Z[]Z"
    DDLogVerbose("********* machineName: C,    programName: Z[]Z")

    // Parentheses in machineName
    paperTrailLogger.machineName = "A()A"
    paperTrailLogger.programName = "X"
    DDLogVerbose("******** machineName: A()A, programName: X")
    paperTrailLogger.machineName = "B()B"
    paperTrailLogger.programName = "Y"
    DDLogVerbose("******** machineName: B()B, programName: Y")
    paperTrailLogger.machineName = "C()C"
    paperTrailLogger.programName = "Z"
    DDLogVerbose("******** machineName: C()C, programName: Z")

    // Brackets in machineName
    paperTrailLogger.machineName = "A[]A"
    paperTrailLogger.programName = "X"
    DDLogVerbose("********* machineName: A[]A, programName: X")
    paperTrailLogger.machineName = "B[]B"
    paperTrailLogger.programName = "Y"
    DDLogVerbose("********* machineName: B[]B, programName: Y")
    paperTrailLogger.machineName = "C[]C"
    paperTrailLogger.programName = "Z"
    DDLogVerbose("********* machineName: C[]C, programName: Z")

    // Back to alphanum
    paperTrailLogger.machineName = "A"
    paperTrailLogger.programName = "X"
    DDLogVerbose("************ machineName: A,    programName: X")
    paperTrailLogger.machineName = "B"
    paperTrailLogger.programName = "Y"
    DDLogVerbose("************ machineName: B,    programName: Y")
    paperTrailLogger.machineName = "C"
    paperTrailLogger.programName = "Z"
    DDLogVerbose("************ machineName: C,    programName: Z")

Current behavior:

Dec 23 11:56:37 A X: 18079482 AppLogger@setup()29] "************ machineName: A,    programName: X"
Dec 23 11:56:37 B Y: 18079482 AppLogger@setup()32] "************ machineName: B,    programName: Y"
Dec 23 11:56:37 C Z: 18079482 AppLogger@setup()35] "************ machineName: C,    programName: Z"
Dec 23 11:56:37 A X()X: 18079482 AppLogger@setup()40] "********* machineName: A,    programName: X()X"
Dec 23 11:56:37 B Y()Y: 18079482 AppLogger@setup()43] "********* machineName: B,    programName: Y()Y"
Dec 23 11:56:37 C Z()Z: 18079482 AppLogger@setup()46] "********* machineName: C,    programName: Z()Z"
Dec 23 11:56:37 A X: <15>Dec 23 11:56:36 A X[]X: 18079482 AppLogger@setup()51] "********* machineName: A,    programName: X[]X"
Dec 23 11:56:37 B Y: <15>Dec 23 11:56:36 B Y[]Y: 18079482 AppLogger@setup()54] "********* machineName: B,    programName: Y[]Y"
Dec 23 11:56:37 C Z: <15>Dec 23 11:56:36 C Z[]Z: 18079482 AppLogger@setup()57] "********* machineName: C,    programName: Z[]Z"
Dec 23 11:56:37 C A()A: X: 18079482 AppLogger@setup()62] "******** machineName: A()A, programName: X"
Dec 23 11:56:37 C B()B: Y: 18079482 AppLogger@setup()65] "******** machineName: B()B, programName: Y"
Dec 23 11:56:37 C C()C: Z: 18079482 AppLogger@setup()68] "******** machineName: C()C, programName: Z"
Dec 23 11:56:37 C A: <15>Dec 23 11:56:36 A[]A X: 18079482 AppLogger@setup()73] "********* machineName: A[]A, programName: X"
Dec 23 11:56:37 C B: <15>Dec 23 11:56:36 B[]B Y: 18079482 AppLogger@setup()76] "********* machineName: B[]B, programName: Y"
Dec 23 11:56:37 C C: <15>Dec 23 11:56:36 C[]C Z: 18079482 AppLogger@setup()79] "********* machineName: C[]C, programName: Z"
Dec 23 11:56:37 A X: 18079482 AppLogger@setup()84] "************ machineName: A,    programName: X"
Dec 23 11:56:37 B Y: 18079482 AppLogger@setup()87] "************ machineName: B,    programName: Y"
Dec 23 11:56:37 C Z: 18079482 AppLogger@setup()90] "************ machineName: C,    programName: Z"

Expected behavior:

Dec 23 11:56:37 A X: 18079482 AppLogger@setup()29] "************ machineName: A,    programName: X"
Dec 23 11:56:37 B Y: 18079482 AppLogger@setup()32] "************ machineName: B,    programName: Y"
Dec 23 11:56:37 C Z: 18079482 AppLogger@setup()35] "************ machineName: C,    programName: Z"
Dec 23 11:56:37 A X()X: 18079482 AppLogger@setup()40] "********* machineName: A,    programName: X()X"
Dec 23 11:56:37 B Y()Y: 18079482 AppLogger@setup()43] "********* machineName: B,    programName: Y()Y"
Dec 23 11:56:37 C Z()Z: 18079482 AppLogger@setup()46] "********* machineName: C,    programName: Z()Z"
Dec 23 11:56:37 A X[]X: 18079482 AppLogger@setup()51] "********* machineName: A,    programName: X[]X"
Dec 23 11:56:37 B Y[]Y: 18079482 AppLogger@setup()54] "********* machineName: B,    programName: Y[]Y"
Dec 23 11:56:37 C Z[]Z: 18079482 AppLogger@setup()57] "********* machineName: C,    programName: Z[]Z"
Dec 23 11:56:37 A()A: X: 18079482 AppLogger@setup()62] "******** machineName: A()A, programName: X"
Dec 23 11:56:37 B()B: Y: 18079482 AppLogger@setup()65] "******** machineName: B()B, programName: Y"
Dec 23 11:56:37 C()C: Z: 18079482 AppLogger@setup()68] "******** machineName: C()C, programName: Z"
Dec 23 11:56:37 A[]A X: 18079482 AppLogger@setup()73] "********* machineName: A[]A, programName: X"
Dec 23 11:56:37 B[]B Y: 18079482 AppLogger@setup()76] "********* machineName: B[]B, programName: Y"
Dec 23 11:56:37 C[]C Z: 18079482 AppLogger@setup()79] "********* machineName: C[]C, programName: Z"
Dec 23 11:56:37 A X: 18079482 AppLogger@setup()84] "************ machineName: A,    programName: X"
Dec 23 11:56:37 B Y: 18079482 AppLogger@setup()87] "************ machineName: B,    programName: Y"
Dec 23 11:56:37 C Z: 18079482 AppLogger@setup()90] "************ machineName: C,    programName: Z"

Comments (8)

  1. George Malayil

    Hi,

    I haven't tested this, but, we don't do any caching of the machine names with this logger extension. I think the issue might lie with how PaperTrail handles machine names with paranthesis etc. (or there might be some caching going on in a single session on their end). Thanks.

  2. Yves-Eric Martin reporter

    Indeed, this seems to be a Papertrail-side issue: I used a packet sniffer to get the actual log lines that are being sent, and look just as expected:

    <15>Dec 28 15:22:33 A X: 2698594 AppLogger@setup()30] "************ machineName: A,    programName: X"
<15>Dec 28 15:22:33 B Y: 2698594 AppLogger@setup()33] "************ machineName: B,    programName: Y"
<15>Dec 28 15:22:33 C Z: 2698594 AppLogger@setup()36] "************ machineName: C,    programName: Z"
<15>Dec 28 15:22:33 A X()X: 2698594 AppLogger@setup()41] "********* machineName: A,    programName: X()X"
<15>Dec 28 15:22:33 B Y()Y: 2698594 AppLogger@setup()44] "********* machineName: B,    programName: Y()Y"
<15>Dec 28 15:22:33 C Z()Z: 2698594 AppLogger@setup()47] "********* machineName: C,    programName: Z()Z"
<15>Dec 28 15:22:33 A X[]X: 2698594 AppLogger@setup()52] "********* machineName: A,    programName: X[]X"
<15>Dec 28 15:22:33 B Y[]Y: 2698594 AppLogger@setup()55] "********* machineName: B,    programName: Y[]Y"
<15>Dec 28 15:22:33 C Z[]Z: 2698594 AppLogger@setup()58] "********* machineName: C,    programName: Z[]Z"
<15>Dec 28 15:22:33 A()A X: 2698594 AppLogger@setup()63] "******** machineName: A()A, programName: X"
<15>Dec 28 15:22:33 B()B Y: 2698594 AppLogger@setup()66] "******** machineName: B()B, programName: Y"
<15>Dec 28 15:22:33 C()C Z: 2698594 AppLogger@setup()69] "******** machineName: C()C, programName: Z"
<15>Dec 28 15:22:33 A[]A X: 2698594 AppLogger@setup()74] "********* machineName: A[]A, programName: X"
<15>Dec 28 15:22:33 B[]B Y: 2698594 AppLogger@setup()77] "********* machineName: B[]B, programName: Y"
<15>Dec 28 15:22:33 C[]C Z: 2698594 AppLogger@setup()80] "********* machineName: C[]C, programName: Z"
<15>Dec 28 15:22:33 A X: 2698594 AppLogger@setup()85] "************ machineName: A,    programName: X"
<15>Dec 28 15:22:33 B Y: 2698594 AppLogger@setup()88] "************ machineName: B,    programName: Y"
<15>Dec 28 15:22:33 C Z: 2698594 AppLogger@setup()91] "************ machineName: C,    programName: Z"

    I am reporting the issue to Papertrail and will post an update here.

  3. Yves-Eric Martin reporter

    So the weird behavior is something that happens on the Papertrail side, but it is caused by PaperTrailLumberjack using the older (and less flexible) syslog message format RFC 3164, obsoleted by RFC 5424 since 2009.

    Can you consider changing PaperTrailLumberjack to use the newer syslog format? Or even support both, for backwards compatibility and maximum flexibility?

    Thank you.

    For reference, here is the full response from Papertrail:

    Hi Yves-Eric,

    Nice detective work. I admit I wasn't familiar with all of these permutations and had to confirm some of the behavior myself. But there is an explanation. The syslog protocol, particularly the original version from the 80s, is finicky about what's allowed in the header. Moreover, various devices claim to support the syslog protocol but actually use their own proprietary variant. The result is some complicated parsing logic, and in this case, it's choking on the parentheses/brackets. There are a few solutions, though:

    • If possible, use the newer RFC5424 syntax, which supports just about anything in the hostname or program name fields, except for spaces.
    • However, I'm not sure if PaperTrailLumberjack supports that syntax. If not, then I'm afraid the only alternative is to keep brackets and parentheses out of the hostname field. Limit yourself to characters that could actually be part of a DNS hostname, like letters, digits, and hyphens.
    • A third option is to move these details into the actual message body, instead of stuffing it into the syslog header. In case you're curious, when we see something that looks like Dec 23 11:56:37 A X: <15>Dec 23 11:56:36 … in the Papertrail viewer, it means that Papertrail couldn't completely parse the syslog header. When that happens, it either parses what it can, or in some cases will grab header details from the most recently-parsed message. That's because some senders don't always put the syslog header in the right spots, especially if there are embedded newlines. But more importantly, it puts the entire unparsed result into the message body to make it easier to tell what's gone wrong.

    Does that all make sense? I'm happy to help translating these ideas to code, too. Just let me know if you're interested in any particular option.

    Thanks,

  4. George Malayil

    Hi,

    Thanks for following up and letting me know. I will try and get this updated, to use the newer syslog format, over the weekend (or possibly next). If you need it sooner, and are going to update the code on your end, I'd appreciate a pull request :) Thanks

    George

  5. George Malayil

    I've updated the code to format messages using RFC5424 by default. The older version is still available as a configurable option, to those who would need it. In my limited testing, brackets and parentheses seem to work now. I would appreciate it, if you would try the new release, and let me know if you find any issues. Thanks

  6. Yves-Eric Martin reporter

    Hi George, and thanks a lot for the quick update, I just tried it out and it worked perfectly.

    Parentheses, brackets, exclamation or question marks... Everything (but spaces) made it all the way to the Papertrail machineName and programName.

    Thanks again!

  7. George Malayil

    Great! :)

    Spaces are the delimiter in the syslog header format. So, unless they are escaped in some fashion (not sure how though), I doubt they would work.

  8. Yves-Eric Martin reporter

    Yes, the behavior is correct! Sorry I wasn't clear, I should have written:

    [...] but spaces that, since they are not allowed, PaperTrailLumberjack helpfully removes automatically

    So everything is as it should be now. Thanks again!

  9. Log in to comment
Assignee
–
Type
bug
Priority
major
Status
resolved
Votes
0
Watchers
1
Jira: the preferred issue tracker for Bitbucket. Join the team!