-f does not format new logs #48

LukasJerabek · 2021-03-04T08:16:53Z

Our settings:

version v1.0.0-alpha
json format log files
custom config since time and key levels are different

Problem:

when I watch file with -f parameter and new log event comes to the file then an empty record is shown followed by unformatted log event:

333    

334    "asctime":"2021-03-04T08:30:32+0100".......

if I quit jog and start watching it again (with or without -f) everything looks normal - without empty records and everything formatted.
Well almost, I have also noticed that any time in any mode there is a trailing empty record always shown, even though there is not even a new line in the original log file, like:

289 <last log event>

290

I think that might be the thing that breaks it with -f mode. But I dont know how to get rid of that.

our config:

colorization: true
pattern: "${timestamp} - ${level} - ${app} - ${file}:${message}${stacktrace}${others}"

line-no:
  print: true
  color: FgRed
  print-format: "\n%s"

unknown-line:
  print: true
  color: FgGray

fields:
  others:
    name:
      color: FgYellow
    separator:
      label: =
      color: FgDefault
    value:
      color: FgDefault
    print-format: "\n%s"
  level: # 'level' field is a hard-coded field used for level filter as well, so don't rename it
         # And, it must be an enum.
    print-format: "%s" # follows https://golang.org/pkg/fmt/
    alias: "levelname"
    case-sensitive: false
    enums:
      case-sensitive: false
      NOTSET:
        alias: notset,0
        color: FgGray,OpBold
      DEBUG:
        alias: debug,10
        color: FgGreen,OpBold
      INFO:
        alias: info,20,
        color: FgBlue,OpBold,OpFuzzy
      WARNING:
        alias: warn,warning,30
        color: FgYellow,OpBold
      ERROR:
        alias: error,err,40
        color: FgMagenta,OpBold
      CRITICAL:
        alias: critical,50
        color: FgRed,OpBold
  app:
    print: false
    alias: "name"
    case-sensitive: false
    color: FgLightBlue
  file:
    alias: "filename"
    case-sensitive: false
    color: FgDefault
  message:
    alias: "message"
    case-sensitive: false
    color: FgCyan,OpItalic
    print-format: "\n%s"
  stacktrace:
    alias: "exc_info"
    case-sensitive: false
    color: FgDefault
    print-format: "\nStack trace: \n%s"
  timestamp: # 'timestamp' field is a hard-coded field used for time range filter as well, so don't rename it
    alias: "asctime"
    case-sensitive: false
    color: FgYellow

The text was updated successfully, but these errors were encountered:

qiangyt · 2021-03-04T08:24:59Z

@LukasJerabek , is it possible for you to attach the log files with sensitive information get rid of?

LukasJerabek · 2021-03-04T08:36:17Z

file named xxx-yyy.zzz.log has records like:
{"asctime":"2021-03-04T07:59:25+0100","levelname":"INFO","name":"some_component","filename":"some_file","message":"some_message"}
{"asctime":"2021-03-04T08:02:46+0100","levelname":"CRITICAL","name":"other_component2","filename":"other_file2","message":"other_message2"}
{"asctime":"2021-03-04T09:31:20+0100","levelname":"WARNING","name":"other_component","filename":"other_file","message":"other_message","exc_info":"optional_traceback"}
is this enought?

qiangyt · 2021-03-04T08:38:17Z

Yes, I will check.

LukasJerabek · 2021-03-04T13:18:45Z

One more thing I have noticed in -f mode, If a second log comes fast (/immediately) after the first one, the empty record line is not shown and second log is formatted nicely. If there is some delay after the second log, the empty record line is shown and the third log would be again badly formatted.

qiangyt · 2021-03-05T03:49:02Z

@LukasJerabek,

I tried but cannot reproduce the issue.
Actually the new empty line always appears before all records but I think they're from your configuration? (search '\n' in your configuration yaml file).

Below is what I observed, the 'issue48.jog.yml' the configuration file you pasted above, the issue48.log is the log rows you paster above too:

for not -f mode:

C02YC31HJGH6:darwin i508673$ ls -ailh
total 11792
131892138 drwxr-xr-x  5 i508673  staff   160B Mar  5 11:37 .
131891509 drwxr-xr-x  5 i508673  staff   160B Mar  5 08:56 ..
131893920 -rw-r--r--  1 i508673  staff   1.6K Mar  5 09:00 issue48.jog.yml
131893721 -rw-r--r--  1 i508673  staff   941B Mar  5 09:03 issue48.log
131892749 -rwxr-xr-x  1 i508673  staff   5.7M Mar  5 08:56 jog.darwin
C02YC31HJGH6:darwin i508673$ 
C02YC31HJGH6:darwin i508673$ 
C02YC31HJGH6:darwin i508673$ ./jog.darwin -c issue48.jog.yml issue48.log 

1      2021-03-04T07:59:25+0100 - INFO - some_component - some_file:
some_message

2      2021-03-04T08:02:46+0100 - CRITICAL - other_component2 - other_file2:
other_message2

3      2021-03-04T09:31:20+0100 - WARNING - other_component - other_file:
other_message
Stack trace: 
optional_traceback

4      2021-03-04T09:31:20+0100 - WARNING - other_component - other_file:
other_message
Stack trace: 
optional_traceback

5      2021-03-04T09:31:20+0102 - WARNING - other_component - other_file:
other_message
Stack trace: 
optional_traceback

6      2021-03-04T09:31:20+0103 - WARNING - other_component - other_file:
other_message
Stack trace: 
optional_traceback

C02YC31HJGH6:darwin i508673$

for -f mode, line 1~~6 is the original one, line 7~~8 is the appended lines after several seconds.

C02YC31HJGH6:darwin i508673$ 
C02YC31HJGH6:darwin i508673$ ./jog.darwin -c issue48.jog.yml -f issue48.log 

1      2021-03-04T07:59:25+0100 - INFO - some_component - some_file:
some_message

2      2021-03-04T08:02:46+0100 - CRITICAL - other_component2 - other_file2:
other_message2

3      2021-03-04T09:31:20+0100 - WARNING - other_component - other_file:
other_message
Stack trace: 
optional_traceback

4      2021-03-04T09:31:20+0100 - WARNING - other_component - other_file:
other_message
Stack trace: 
optional_traceback

5      2021-03-04T09:31:20+0102 - WARNING - other_component - other_file:
other_message
Stack trace: 
optional_traceback

6      2021-03-04T09:31:20+0103 - WARNING - other_component - other_file:
other_message
Stack trace: 
optional_traceback

7      2021-03-04T09:31:20+0104 - WARNING - other_component - other_file:
other_message
Stack trace: 
optional_traceback

8      2021-03-04T09:31:20+0105 - WARNING - other_component - other_file:
other_message
Stack trace: 
optional_traceback

LukasJerabek · 2021-03-05T08:00:15Z

I think you missunderstood. Empty line is alright. Empty record is the problem - meaning number without any text as in examples above. And when I see the original log file, there is not anything why it should be there. How to get rid of that empty record when using jog. Obviously you dont have it in you outputs, otherwise the -f mode would look this way in my case:

1      2021-03-04T07:59:25+0100 - INFO - some_component - some_file:
some_message

2      2021-03-04T08:02:46+0100 - CRITICAL - other_component2 - other_file2:
other_message2

3      2021-03-04T09:31:20+0100 - WARNING - other_component - other_file:
other_message
Stack trace: 
optional_traceback

4      2021-03-04T09:31:20+0100 - WARNING - other_component - other_file:
other_message
Stack trace: 
optional_traceback

5      2021-03-04T09:31:20+0102 - WARNING - other_component - other_file:
other_message
Stack trace: 
optional_traceback

6      2021-03-04T09:31:20+0103 - WARNING - other_component - other_file:
other_message
Stack trace: 
optional_traceback

7

8      same text as yours but unformatted

9      2021-03-04T09:31:20+0105 - WARNING - other_component - other_file:
other_message
Stack trace: 
optional_traceback

10

LukasJerabek · 2021-03-05T08:11:50Z

this is what it looks like. First three records where already in file when I issued jog -f ... and the other to came after few seconds. There is only 6 records in original file, but I see 8 numbers in the output.

qiangyt · 2021-03-05T08:42:06Z

I think it is related to how your log source outputs. It seems your log source outputs each record as 2 separated steps: first, a '{' first, then remaining part of the new record. And then jog takes it as 2 records: the first '{' letter is ignored, and the second remaining part is printed by jog as 'unknow-line'. You can find the 'unknown-line' settings in your configuration yaml as:

unknown-line:
  print: true
  color: FgGray

It is printed with gray which matches your settings.

Let me find how to fix.

LukasJerabek · 2021-03-05T09:18:56Z

could be, but even then I would not understand the last empty record (number 8 on the screenshot)

LukasJerabek · 2021-03-05T12:49:42Z

I forgot to mention, in this example I made it manually. I simply opened the file in vim added logs which are shown on lines 5, 6,7 manually closed and saved the file. So under this circumstance it seems unrealted to log source output to me...

qiangyt · 2021-03-11T06:54:20Z

Release 1.0.1 to fix this issue.

qiangyt closed this as completed Mar 5, 2021

qiangyt reopened this Mar 5, 2021

qiangyt added a commit that referenced this issue Mar 11, 2021

fix issue #48

47a04db

qiangyt closed this as completed Mar 11, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

-f does not format new logs #48

-f does not format new logs #48

LukasJerabek commented Mar 4, 2021 •

edited

Loading

qiangyt commented Mar 4, 2021

LukasJerabek commented Mar 4, 2021

qiangyt commented Mar 4, 2021

LukasJerabek commented Mar 4, 2021 •

edited

Loading

qiangyt commented Mar 5, 2021 •

edited

Loading

LukasJerabek commented Mar 5, 2021 •

edited

Loading

LukasJerabek commented Mar 5, 2021 •

edited

Loading

qiangyt commented Mar 5, 2021

LukasJerabek commented Mar 5, 2021

LukasJerabek commented Mar 5, 2021 •

edited

Loading

qiangyt commented Mar 11, 2021

-f does not format new logs #48

-f does not format new logs #48

Comments

LukasJerabek commented Mar 4, 2021 • edited Loading

qiangyt commented Mar 4, 2021

LukasJerabek commented Mar 4, 2021

qiangyt commented Mar 4, 2021

LukasJerabek commented Mar 4, 2021 • edited Loading

qiangyt commented Mar 5, 2021 • edited Loading

LukasJerabek commented Mar 5, 2021 • edited Loading

LukasJerabek commented Mar 5, 2021 • edited Loading

qiangyt commented Mar 5, 2021

LukasJerabek commented Mar 5, 2021

LukasJerabek commented Mar 5, 2021 • edited Loading

qiangyt commented Mar 11, 2021

LukasJerabek commented Mar 4, 2021 •

edited

Loading

LukasJerabek commented Mar 4, 2021 •

edited

Loading

qiangyt commented Mar 5, 2021 •

edited

Loading

LukasJerabek commented Mar 5, 2021 •

edited

Loading

LukasJerabek commented Mar 5, 2021 •

edited

Loading

LukasJerabek commented Mar 5, 2021 •

edited

Loading