Bug 943757

Created attachment 645556 [details]
y2log

Martin, is there anything we could do about stderr from Ruby libs while
running Yast in ncurses? E.g., forwarding it to y2log?

Side note, Yast ncurses require gems to be in order.

To reproduce:

# /usr/lib/YaST2/bin/y2base ./hello.rb ncurses
# https://bugzilla.suse.com/show_bug.cgi?id=943757

require "yast"
include Yast::UIShortcuts

$stderr.puts "Hello, stderr! 1" # This succeeds

module Yast
  import "UI"

  UI.OpenDialog(PushButton("Hello, World!"))
  $stderr.puts "Hello, stderr! 2" # Bad file descriptor @ io_write
  UI.UserInput
  UI.CloseDialog
end

I thought that we did redirect to the log, but it turns out that since 2008 ncurses redirects stdout and stderr to /dev/null, even with some suspicious flags (defaulting to O_RDONLY) which may never have worked:
https://github.com/libyui/libyui-ncurses/blob/8f861f5ccb77a72fdcc17e909f2811102f09d3b1/src/NCurses.cc#L566
	open( log.c_str(), O_APPEND | O_CREAT, 0666 );

To fix the nokogiri warning, from what I've checked at thalassa it seems that you can uninstall the gem and install a rpm-wrapped gem from 13.2 instead:

# gem uninstall -v 1.6.6.2 nokogiri
# zypper in rubygem-nokogiri

Looks like it was done bu this commit, but that mostly fixes just the formatting https://github.com/libyui/libyui-ncurses/commit/9a033491a3126270b310e9a0106c5dbb96cd9443

Katarina has moved this to a separate function in 2007 https://github.com/libyui/libyui-ncurses/blob/master/ChangeLog#L854

And this was the commit https://github.com/libyui/libyui-ncurses/commit/dd18ea2a3fca3864d43aff710a6d8097206b516f

--> P2

Talking about ruby-based solutions, this works. But it's more an experiment than a reliable fix. I would rather try to replace $stderr by a proper IO object, instead of hijacking #puts and #print (since there are also #printf, #putc, #write...)


require "yast"
include Yast::UIShortcuts

$stderr.puts "Hello, stderr! 1"

$stderr.define_singleton_method(:puts) do |*args|
  if args.empty?
    Yast.y2error($/)
  else
    Yast.y2error(args.join($/))
  end
end

$stderr.define_singleton_method(:print) do |*args|
  if args.empty?
    Yast.y2error($_)
  else
    Yast.y2error(args.map(&:to_s).join($,) + $\.to_s)
  end
end

module Yast
  import "UI"

  UI.OpenDialog(PushButton("Hello, World!"))
  # Al this messages works as expected (logging to YaST logs)
  $stderr.puts "Hello, stderr! 2"
  $stderr.puts "Halo", "stderr!", "2"
  $stderr.print "Hola, ! 2"
  $stderr.print "Ahoj", "stderr!", "2"
  UI.UserInput
  UI.CloseDialog
end

As I see it, we have two options.

1) Fix RedirectToLog. I don't know why it was changed from y2logs to /dev/null, but I can imagine at least one reason: coupling of libyui and YaST.

Btw, it was HuHa who made it, past always comes back. :-)
https://github.com/libyui/libyui-ncurses/commit/3e10a9a29905056b9cf2b6ef746a71796bf055ca

2) Implement the same mechanism in YaST (and Ruby). This script works.

require "yast"
include Yast::UIShortcuts

# We'd need to expose get_log_filename through yast-ruby-bindings.
# Let's fake it for demo purposes
module Yast
  def self.get_log_filename; "/var/log/YaST2/y2log"; end
end

# We'd need to call this before NCurses::init
# (still to be decided exactly when/where)
def redirect_std_streams
  [$stderr, $stdout].each do |stream|
    if stream.tty?
      stream.reopen(Yast.get_log_filename, "a")
      stream.sync = true
    end
  end
end

# Let's call it here for the demo
redirect_std_streams

module Yast
  import "UI"

  UI.OpenDialog(PushButton("Hello, World!"))
  # Al this messages works as expected (logging to YaST logs)
  $stderr.puts "Hello, stderr! 2"
  $stderr.puts "Halo", "stderr!", "2"
  $stderr.print "Hola, ! 2"
  $stderr.print "Ahoj", "stderr!", "2"
  UI.UserInput
  UI.CloseDialog
end

I'd like to know what Martin and HuHa think about it. Maybe they even remember the reason for the /dev/null thingy.

It's been a long time... ;-)

I faintly remember that redirecting all stderr output to the y2log tends to mess up the y2log badly as there are different levels of buffering all over the place. libyui has its own thread-safe logger with its own logging buffer. If some other output is writing to the same file handle, but bypassing that thread-safe log buffer, the output will become mixed, disregarding things like output lines (and of course the y2log line header with the timestamp, PID, source file, function, source line number).

IIRC we used that for a short while and then became frustrated quickly because the logs were messed up in the most critical moments.

There is no easy way around this; IIRC I tried to come up with a strategy to route that output through the thread-safe libyui logger, but if a process simply writes to a file handle, there is no reliable way to do this.

Another approach might be to simply open yet another file dedicated to stderr output. Of course that implies taking care of log rotation etc.; that's probably the reason why back then we had decided to redirect it to /dev/null. That output just wasn't that important.

Of course, we also can insist in the current solution of sending everything to /dev/null and avoid the side effects described by HuHa. In that case, it's still true that we have the same two options - fix RedirectToLog which is clearly not working or implementing the redirection as ruby code in YaST.

I'll check what's the problem with RedirecToLog. Maybe it's completely useless or maybe it's being called too late or simply not called at all.

Thanks to the changes introduced recently in libyui, now it's possible to write an RSpec test like this https://github.com/ancorgs/yast-yast2/commit/f52bc2350e9690415d1f53b5175e107a7529433d

I know it's probably misplaced as part of UI:Dialog tests. The final location of the test will depend on where do we fix the error, but at least is ready.

I have checked RedirectToLog, adding O_WRONLY to the flags works.

I think that it is enough to continue discarding the output.

The issue is fixed in libyui-ncurses 2.47.3 (Tumbleweed and SLE12-SP1)
https://build.suse.de/request/show/68148
https://build.opensuse.org/request/show/331511

Keeping the bug open since we are still deciding where and how integrate the automated test
https://github.com/yast/yast-ruby-bindings/pull/153

The tests have been merged, the bug is thus resolved. Thanks everyone!

*** Bug 956265 has been marked as a duplicate of this bug. ***