[Bug] filter-in and filter-out are bugged

[efpies]

In lnav 0.8.4 I have an error with :filter-in and :filter-out commands.

For example, this is what displayed for :filter-in Ethereum.

2019-08-21T17:01:24.294 debug Wallet balance updated {@wallet}
  @mp: {"wallet":{"$type":"WalletRecord","Id":9084,"AccountId":-211...
  PaymentSystem: Ethereum
2019-08-21T17:01:24.413 info Loaded payment system updates {FirstSeq} - {LastSeq}
  @mp: {"wallet":{"$type":"WalletRecord","Id":360,"AccountId":-211...
  PaymentSystem: Ethereum

However, the second log shouldn't have such values in @mp column at all. It belongs to the first kind of logs.

If I press P over the first log line, it will produce:

2019-08-21T17:01:24.294 debug Wallet balance updated {@wallet}
 Received Time: 2019-08-21T17:01:24.294 --  4 minutes and 49 seconds ago
 Known message fields for table log:
 ├ @t               = 2019-08-21T17:01:24.294
 ├ @l               = Debug
 ├ body             = Wallet balance updated {@wallet}
 ├ @mt              = Wallet balance updated {@wallet}
 ├ @mp              = {"wallet":{"$type":"WalletRecord","Id":9084,"AccountId":-211...
 ├ SourceContext    = EthereumAdapter
 ├ ThreadId         = 41
 ├ PaymentSystem    = Ethereum
 JSON fields:
 ├ jget("@mp",'/wallet/$type') = "WalletRecord"
 ├ jget("@mp",'/wallet/Id') = 9084
 ├ jget("@mp",'/wallet/AccountId') = -211
 ├ jget("@mp",'/wallet/PaymentSystem') = "Ethereum"
 Discovered fields for logline table from message format: Wallet balance updated {#}
 └ col_0 = @wallet
  @mp: {"wallet":{"$type":"WalletRecord","Id":9084,"AccountId":-211...
  PaymentSystem: Ethereum

Over the second:

2019-08-21T17:01:24.413 info Loaded payment system updates {FirstSeq} - {LastSeq}
 Received Time: 2019-08-21T17:01:24.413 --  7 minutes and 22 seconds ago
 Known message fields for table log:
 ├ @t               = 2019-08-21T17:01:24.413
 ├ @l               = Information
 ├ body             = Loaded payment system updates {FirstSeq} - {LastSeq}
 ├ @mt              = Loaded payment system updates {FirstSeq} - {LastSeq}
 ├ @mp              = {"FirstSeq":591124,"LastSeq":591124}
 ├ SourceContext    = MyExchange.Wallet.PaymentSystemManager
 ├ ThreadId         = 39
 ├ PaymentSystem    = Omni
 JSON fields:
 ├ jget("@mp",'/FirstSeq') = 591124
 ├ jget("@mp",'/LastSeq') = 591124
 Discovered fields for logline table from message format: Loaded payment system updates {#} # {#}
 ├ col_0 = FirstSeq
 ├ col_1 = -
 └ col_2 = LastSeq
  @mp: {"wallet":{"$type":"WalletRecord","Id":360,"AccountId":-211...
  PaymentSystem: Ethereum

And if we look at these lines in the raw log, they look like that:

{"@t":"2019-08-21T17:01:24.2942033Z","@l":"Debug","@mt":"Wallet balance updated {@wallet}","@mp":{"wallet":{"$type":"WalletRecord","Id":9084,"AccountId":-211,"PaymentSystem":"Ethereum"...}},"SourceContext":"EthereumAdapter","ThreadId":41,"PaymentSystem":"Ethereum"}
{"@t":"2019-08-21T17:01:24.4131437Z","@l":"Information","@mt":"Loaded payment system updates {FirstSeq} - {LastSeq}","@mp":{"FirstSeq":591124,"LastSeq":591124},"SourceContext":"MyExchange.Wallet.PaymentSystemManager","ThreadId":39,"PaymentSystem":"Omni"}
{"@t":"2019-08-21T17:01:24.4650801Z","@l":"Debug","@mt":"Wallet balance updated {@wallet}","@mp":{"wallet":{"$type":"WalletRecord","Id":360,"AccountId":-211,"PaymentSystem":"Ethereum"...}},"SourceContext":"EthereumAdapter","ThreadId":39,"PaymentSystem":"Ethereum"}

As you can see, the 2nd and the 3rd lines got mixed together in the filtered log. It happens at any moment of applying the filter: just after the applying and when the opened log is being updated.

The broken output may look like this:

2019-08-21T17:23:22.253 info Loaded payment system updates {FirstSeq} - {LastSeq}
  @mp: {"FirstSeq":596783,"LastSeq":596783}
  @mp: {"FirstSeq":8340354,"LastSeq":8340654}
  PaymentSystem: Ethereum
2019-08-21T17:25:03.351 info Loaded payment system updates {FirstSeq} - {LastSeq}
  @mp: {"FirstSeq":591128,"LastSeq":591128}
  PaymentSystem: Ethereum
2019-08-21T17:26:48.369 info Loaded payment system updates {FirstSeq} - {LastSeq}
  @mp: {"FirstSeq":8340954,"LastSeq":8341254}
  PaymentSystem: Ethereum
2019-08-21T17:28:40.051 info Loaded payment system updates {FirstSeq} - {LastSeq}

I. e. two different @mps for the first log, wrong @mp for the second, none for the fourth.

I can't update to lnav 0.8.5 at this moment to check if this issue persists there.

[tstack]

Hmm, I'm not able to reproduce the issue on lnav 0.8.4 at the moment. Can you also share your format file?

[dmig-alarstudios]

@efpies did you mean, you open 2 log files at once? I remember experiencing this issue when enabling filter on one of log files and then switching to others with f/F