Bug 1218106

Created attachment 871394 [details]
y2log

Latest y2log

YaST calls something like this to get the journal entries from systemd:

> LANG=C /usr/bin/journalctl --output json --no-page

According to the attached logs, looks like systemd has decided to season that JSON output with TTY color control characters. Unsurprisingly JSON parsers don't like that.

I guess something have changed in systemd in that regard, since in the past when asked to return JSON it used to return... well... valid JSON.

We can likely put that under control from the YaST side by enforcing then environment variables SYSTEMD_LOG_COLOR and/or SYSTEMD_COLORS.

That being said, I would consider this to be a systemd misbehavior (or, at least, an unexpected change).

(In reply to Ancor Gonzalez Sosa from comment #3)
> I guess something have changed in systemd in that regard, since in the past
> when asked to return JSON it used to return... well... valid JSON.

Let's then ask systemd maintainers ^^^

It doesn't happen in my system. But I was able to force the error adding this to the journalctl call (which is exactly the opposite we actually wanna do, of course):

> SYSTEMD_LOG_COLOR=1 SYSTEMD_COLORS=256 LANG=C /usr/bin/journalctl [...]

So I guess forcing those variables to zero/false would actually fix the problem for this user (and others potentially facing the same).

BTW, I also found we could improve this regular expression[1] since I detected a case in which the output of journalctl doesn't fit what we expect.

It's more robust like this:

> /^\s*(-*\d+)\s+(\w+)\s+(#{TIMESTAMP_RX})[— ]+(#{TIMESTAMP_RX})$/

It's almost equal to the current one. Just note the extra plus sign before the second timestamp.

[1] https://github.com/yast/yast-journal/blob/dee50dacb1b9100865f4d096f0a99d668ee1a877/src/lib/y2journal/query.rb#L102

(In reply to Ancor Gonzalez Sosa from comment #5)
> But I was able to force the error adding
> this to the journalctl call (which is exactly the opposite we actually wanna
> do, of course):

What systemd version do you have?

Interestingly, I can see the colored output regardless of SYSTEMD_LOG_COLOR={0,1} with
> SYSTEMD_LOG_COLOR=0 SYSTEMD_COLORS=256 LANG=C journalctl -ojson
both with
> systemd-254.5-6.1.x86_64
or
> systemd-249.16-150400.8.35.5.x86_64
.

(In reply to Michal Koutný from comment #7)
> 
> What systemd version do you have?

I have systemd 254.5.

I did more experiments and SYSTEMD_LOG_COLOR seems to be irrelevant for this.

Running this I get monochrome output in my tty

> SYSTEMD_COLORS=0 LANG=C /usr/bin/journalctl --output json

Running either of these in my tty I get colored JSON:

> SYSTEMD_COLORS=1 LANG=C /usr/bin/journalctl --output json
>
> LANG=C /usr/bin/journalctl --output json

In any case, I didn't expect YaST to need to force any of those variables, since those color codes should only be inserted if systemd is printing to the tty, which is not the case in YaST (we are executing the command and parsing the output).

(In reply to Ancor Gonzalez Sosa from comment #8)
> 
> I have systemd 254.5.

To be precise, 254.5-5.1

I can confirm that the 'dmesg' output of TW from 2023-12-25 is *very* colorful, but only when I view it in a terminal window.

When I redirect its output to a file, there are no escape sequences.

Even with all latest TW updates, I don't get escape sequences when I redirect the output of 'journalctl' or 'dmesg' to a file. In a terminal, yes, there is some color, but never in a file.

% journalctl --version 
systemd 254 (254.5+suse.21.g071ac409a0)
+PAM +AUDIT +SELINUX +APPARMOR +IMA -SMACK +SECCOMP +GCRYPT +GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBFDISK +PCRE2 +PWQUALITY +P11KIT +QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD +BPF_FRAMEWORK -XKBCOMMON -UTMP +SYSVINIT default-hierarchy=unified

% dmesg --version
dmesg from util-linux 2.39.3

I can understand the ratioale for color output to a tty, but why in the JSON format, too? The purpose of JSON is to be machine-readable, and escape sequences pretty much defeat that.

(In reply to Ancor Gonzalez Sosa from comment #8)
> I did more experiments and SYSTEMD_LOG_COLOR seems to be irrelevant for this.

Right. (It's a gotcha since it applies to log-level coloring, not JSON coloring.)

> which is not the case in YaST (we are executing the command and
> parsing the output).

I was previously focused on the env variables but the coloring based on tty/nontty output works for me. (Curiously, I don't see any recent changes in this area.)

systemd-249.16-150400.8.35.5.x86_64
systemd-254.5-8.1.x86_64


(In reply to Stefan Hundhammer from comment #12)
> The purpose of JSON is to be machine-readable, and escape
> sequences pretty much defeat that.

The reading machine parses a pipe or a saved file and those should be without color escapes. (The logic [1] should boil down to isatty(3).)

Is it possible that something adds SYSTEMD_COLORS > 0 to the environment?
(The variable seems to override tty detection.)


[1] https://github.com/openSUSE/systemd/blob/071ac409a0564863657d8f8a5a35e6a4f914695f/src/basic/terminal-util.c#L1336

I found an easy way to reproduce this, even on Leap 15.5:

  xhost +

  sudo SYSTEMD_COLORS=256 yast2 journal

-> the observed crash


  SYSTEMD_COLORS=256 journalctl --output json

-> colored output

  SYSTEMD_COLORS=256 journalctl --output json >/tmp/x

-> escape sequences in the file

It's the same with or without 'sudo', with 'bash' or with 'zsh' which is my standard.

AFAICS the tty detection fails with '--output json'.

(In reply to Stefan Hundhammer from comment #14)
> AFAICS the tty detection fails with '--output json'.

The code comment under link in comment 13 suggests that SYSTEMD_COLORS > 0 is
meant to override tty detection. Even journalctl(1) says:

> This can be specified to override the automatic decision based on $TERM and
> what the console is connected to.

I don't know why such a twisted logic but it's documented ¯\_(ツ)_/¯                                                                                                                                                                                                                                                                        

Thus, could have something changed in yast2 invocations that would leak the SYSTEMD_COLORS into the environment?

That code is unchanged since 6 years:

https://github.com/yast/yast-journal/blob/master/src/lib/y2journal/journalctl.rb#L62

I guess that `Yast::SCR.Execute(BASH_SCR_PATH, command)` retains environment.

Frank, do you tweak SYSTEMD_COLORS in your environment?

Simple solution:

  https://github.com/yast/yast-journal/pull/52

Normally, YaST modules are called as root. But this is one of the few that can actually also be run as a normal user; and when that user account has environment variables set, they may actually arrive in the YaST calling environment.

But whatever, the fix is easy enough - see comment #18.

Not as far as I know. 

this is from root xterm (yast runs as root)

desktop-tumbleweed root /home/frank> echo $SYSTEMD_COLORS

desktop-tumbleweed root /home/frank> 


What else should I check ?

The fix will arrive in Factory / Tumbleweed as yast2-journal-5.0.1.

Frank, if you want to test / have this fix immediately, simply download this file

https://raw.githubusercontent.com/yast/yast-journal/d9d29dc3e709eab54dc2fb17e1f7530e82008742/src/lib/y2journal/journalctl.rb

and copy it to 

  /usr/share/YaST2/lib/y2journal/journalctl.rb

At the same time I put SYSTEMD_COLORS='' export SYSTEMD_COLORS
into my .bashrc, and ran the YAST module for the journal and there was not
any crash, it displayed perfectly.

As to where the variable was coming from I have absolutely no idea.

Thank you for this !

Environment variables can come from the weirdest of places; your ~/.bashrc, your ~/.profile, their global counterparts from /etc or /usr/etc or other global files like /etc/environment (or today probably /usr/etc/environment).

I've seen login managers overriding my LANG / LC_xxx variables with stuff selected on the login manager page, then written (without telling or asking me) to a file that I had never seen or heard of before (but what do I know, I've only worked in Linux/Unix environments since 1990) ~/.pam-environment .

People come up with the weirdest of places where they can sabotage normal users with new environment variables overriding their explicit wishes, and then they blame those users for never having read a brand-new documentation or man page in some obscure place.  ;-}

Merged https://github.com/yast/yast-journal/pull/52.