spurious LF in logs from 'nomad operator debug'

[tgross]

While debugging a problem via nomad operator debug, I found spurious line breaks in the server logs (the file monitor.log in the bundle). This is pretty minor on its face but complicates grepping through the very large log bundles that are characteristic of customer support cases.

It doesn't appear to be load-related and is easy to replicate on Vagrant running Nomad in dev mode:

• In one terminal run nomad operator debug -server-id=all -interval=1m -duration=1m
• In another terminal run while true; do nomad job status; sleep .5; done to generate some log traffic.

I've confirmed this on the current HEAD (Nomad 1.0.2-dev) but I originally noticed this on a log bundle generated by Nomad 0.12.5+ent.

Here's an example output:

$ head -11 monitor.log
2021-01-26T13:54:29.684Z [DEBUG] http: request complete: method=GET path=/v1/jobs duration=149.638µs
2021-01-26T13:54:29.686Z [DEBUG] http: request complete: method=GET path=/v1/deployments duration=221.299µs
2021-01-26T13:54:29.688Z [DEBUG] http: request complete: method=GET path=/v1/evaluations duration=175.331µs
2021-01-26T13:54:29.690Z [DEBUG] http: request complete: method=GET path=/v1/allocations duration=287.553µs
2021-01-26T13:54:29.692Z [DEBUG] http: request complete: method=GET path=/v1/nodes duration=251.309µs
2021-01-26T13:54:29.693Z [DEBUG] http: request complete: method=GET path=/v1/plugins?type=csi duration=130.761µs
2021-01-26T13:54:29.694Z [DEBUG] http: request complete: method=GET path=/v1/volumes?type=csi duration=144.508µs
2021-01-26T13:54:29.696Z [DEBUG] http: request complete: method=GET path=/v1/metrics duration=439.816µs
2021-01-26T13:54:29.698Z [DEBUG] http: request complete: method=GET path=/v1/operator/raft/configuration duration=165.734µs
2021-01-26T13:54:29.699Z [DEBUG] h
ttp: request complete: method=GET path=/v1/operator/scheduler/configuration duration=106.702µs

The extra break is a 0x0a, so a LF character:

$ head -11 monitor.log | tail -3 | xxd
00000000: 3230 3231 2d30 312d 3236 5431 333a 3534  2021-01-26T13:54
00000010: 3a32 392e 3639 385a 205b 4445 4255 475d  :29.698Z [DEBUG]
00000020: 2068 7474 703a 2072 6571 7565 7374 2063   http: request c
00000030: 6f6d 706c 6574 653a 206d 6574 686f 643d  omplete: method=
00000040: 4745 5420 7061 7468 3d2f 7631 2f6f 7065  GET path=/v1/ope
00000050: 7261 746f 722f 7261 6674 2f63 6f6e 6669  rator/raft/confi
00000060: 6775 7261 7469 6f6e 2064 7572 6174 696f  guration duratio
00000070: 6e3d 3136 352e 3733 34c2 b573 0a32 3032  n=165.734..s.202
00000080: 312d 3031 2d32 3654 3133 3a35 343a 3239  1-01-26T13:54:29
00000090: 2e36 3939 5a20 5b44 4542 5547 5d20 680a  .699Z [DEBUG] h.
000000a0: 7474 703a 2072 6571 7565 7374 2063 6f6d  ttp: request com
000000b0: 706c 6574 653a 206d 6574 686f 643d 4745  plete: method=GE
000000c0: 5420 7061 7468 3d2f 7631 2f6f 7065 7261  T path=/v1/opera
000000d0: 746f 722f 7363 6865 6475 6c65 722f 636f  tor/scheduler/co
000000e0: 6e66 6967 7572 6174 696f 6e20 6475 7261  nfiguration dura
000000f0: 7469 6f6e 3d31 3036 2e37 3032 c2b5 730a  tion=106.702..s.

[davemay99]

👍 I have noticed the same. I think it's a problem in the framer, but I haven't been able to track down the source yet.

[github-actions]

I'm going to lock this issue because it has been closed for 120 days ⏳. This helps our maintainers find and focus on the active issues.
If you have found a problem that seems similar to this, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.