Console output messed up for background processes

[mhenrixon]

Trying to use coolline on Mac OS X because readline doesn't work very well but it completely meses up console output.

                                                                                                                                                                               app/views/lists/show.html.haml:161:in `_app_views_lists_show_html_haml___1021052418807862974_70125393452100'
                                                  app/controllers/lists_controller.rb:68:in `show'
                                                                                                    List Load (0.5ms)  SELECT "lists".* FROM "lists" WHERE "lists"."id" = 85 LIMIT 1
                                                                                                                                                                                    Called from: app/models/workflow.rb:92:in `list_todo_percentage'
        app/views/lists/_user_stats.html.haml:12:in `_app_views_lists__user_stats_html_haml__4234996185636509608_70125372887960'
                                                                                                                                 app/views/lists/show.html.haml:161:in `_app_views_lists_show_html_haml___1021052418807862974_70125393452100'
 app/controllers/lists_controller.rb:68:in `show'
                                                 Called from: app/views/lists/_user_stats.html.haml:24:in `_app_views_lists__user_stats_html_haml__4234996185636509608_70125372887960'
                                                                                                                                                                                       app/views/lists/show.html.haml:161:in `_app_views_lists_show_html_haml___1021052418807862974_70125393452100'
                                                       app/controllers/lists_controller.rb:68:in `show'
                                                                                                       Called from: app/views/lists/_user_stats.html.haml:24:in `_app_views_lists__user_stats_html_haml__4234996185636509608_70125372887960'
                                                                                                                                                                                                                                             app/views/lists/show.html.haml:161:in `_app_views_lists_show_html_haml___1021052418807862974_70125393452100'
                                                                                                             app/controllers/lists_controller.rb:68:in `show'
                                                                                                                                                             Called from: app/views/lists/_user_stats.html.haml:24:in `_app_views_lists__user_stats_html_haml__4234996185636509608_70125372887960'
                                                      app/views/lists/show.html.haml:161:in `_app_views_lists_show_html_haml___1021052418807862974_70125393452100'
                                                                                                                                                                   app/controllers/lists_controller.rb:68:in `show'
                                                                                                                                                                                                                     Activity Load (1.7ms)  SELECT "activities".* FROM "activities" WHERE "activities"."workflow_id" = 102 ORDER BY activities.created_at DESC LIMIT 10
                                                                                                                          Called from: app/views/lists/_user_stats.html.haml:24:in `_app_views_lists__user_stats_html_haml__4234996185636509608_70125372887960'
                   app/views/lists/show.html.haml:161:in `_app_views_lists_show_html_haml___1021052418807862974_70125393452100'
                                                                                                                                app/controllers/lists_controller.rb:68:in `show'
                                                                                                                                                                                  Rendered lists/_user_stats.html.haml (93.6ms)
                                                                                                                                                                                                                                 Activity Load (1.7ms)  SELECT "activities".* FROM "activities" WHERE "activities"."list_id" = 85 ORDER BY activities.created_at DESC LIMIT 10
                                                                                                                                 Called from: app/views/lists/show.html.haml:170:in `_app_views_lists_show_html_haml___1021052418807862974_70125393452100'
              app/controllers/lists_controller.rb:68:in `show'
                                                                Rendered activities/_activity.html.haml (6.6ms)
                                                                                                                 Rendered lists/show.html.haml within layouts/application (671.5ms)
                                                                                                                                                                                     Workflow Load (0.6ms)  SELECT "workflows".* FROM "workflows" WHERE "workflows"."user_id" = 1 AND (workflows.archived='f') ORDER BY workflows.position ASC
                                                                                                 Called from: app/views/application/_menu.html.haml:46:in `block in _app_views_application__menu_html_haml__3341304488632390902_70125374568400'
   app/views/application/_menu.html.haml:45:in `_app_views_application__menu_html_haml__3341304488632390902_70125374568400'
                                                                                                                            app/views/layouts/application.html.haml:40:in `_app_views_layouts_application_html_haml___1694226297120499442_70125393188980'
             app/controllers/lists_controller.rb:68:in `show'
                                                               Rendered application/_search_form.html.haml (3.4ms)
                                                                                                                    Rendered application/_menu.html.haml (77.4ms)
                                                                                                                                                                 Called from: app/views/layouts/application.html.haml:45:in `_app_views_layouts_application_html_haml___1694226297120499442_70125393188980'
                                                               app/controllers/lists_controller.rb:68:in `show'
                                                                                                               Called from: app/views/layouts/application.html.haml:45:in `_app_views_layouts_application_html_haml___1694226297120499442_70125393188980'
             app/controllers/lists_controller.rb:68:in `show'
                                                             Called from: app/views/layouts/application.html.haml:45:in `_app_views_layouts_application_html_haml___1694226297120499442_70125393188980'
                                                                                                                                                                                                        app/controllers/lists_controller.rb:68:in `show'
              (0.5ms)  SELECT COUNT(*) FROM "announcements" 
                                                            Called from: app/views/layouts/application.html.haml:45:in `_app_views_layouts_application_html_haml___1694226297120499442_70125393188980'
                                                                                                                                                                                                       app/controllers/lists_controller.rb:68:in `show'
            Announcement Load (0.4ms)  SELECT "announcements".* FROM "announcements" ORDER BY "announcements"."id" DESC LIMIT 1
                                                                                                                               Called from: app/models/announcement.rb:7:in `newest'
                                                                                                                                                                                     app/views/layouts/application.html.haml:46:in `_app_views_layouts_application_html_haml___1694226297120499442_70125393188980'
                                                                      app/controllers/lists_controller.rb:68:in `show'
                                                                                                                        Rendered application/_iphone_footer.html.haml (2.8ms)
                                                                                                                                                                             Completed 200 OK in 1397ms (Views: 782.8ms | ActiveRecord: 43.1ms)

Any ideas why this happens?

[Mon-Ouie]

Could you show how you used it?

I know you can get weird output if the streams are still in raw mode after exiting, but IO#getch will normally turn it on and off automatically.

[mhenrixon]

@Mon-Ouie I just added the gem to the Gemfile to be able to send commands to guard but anytime I visit a page in development mode this is what I get back (what is logged by the Rails.logger.

RSpec output works fine though

group :development, :test do
  gem "rspec-rails"
  gem 'jasminerice'
  gem 'pry-rails'
  gem 'pry-doc'
  gem 'pry-stack_explorer'
  gem 'pry-debugger'
  gem 'bullet'
end

group :development do
  gem 'thin'
  gem 'quiet_assets'
  # gem "lol_dba"
  gem 'rails_best_practices'

  gem 'terminal-notifier-guard'
  gem 'guard'
  gem 'guard-bundler'
  gem 'guard-rails'
  gem 'guard-rspec'
  gem 'guard-rails-assets'
  gem 'guard-jasmine'
  gem 'spork', '> 0.9.0.rc'
  gem 'guard-spork'
  gem 'guard-sidekiq'
  gem 'coolline'
  # gem 'guard-rails_best_practices', github: 'mpouleijn/guard-rails_best_practices'
end

[Mon-Ouie]

You should open a ticket on the guard tracker and reopen one here if it actually turns out to be an issue within coolline. I'd also recommend you check your environment (terminal, etc.) first.

[mhenrixon]

If I remove the coolline gem, everything works fine so how is this guards fault?

[Mon-Ouie]

I don't know anything about Guard, but I assume it uses Coolline if it's there. Coolline ca't possibly change any output if nothing uses it.

[mhenrixon]

Could it have to do with using ZSH?

[netzpirat]

The Guard Cooline interactor is quite small and uses Coolline almost like described in the Coolline README.

coolline = Coolline.new do |cool|
  cool.transform_proc = proc do
    cool.line
  end

  cool.completion_proc = proc do
    word = cool.completed_word
    auto_complete(word)
  end
end

while line = coolline.readline(prompt)
  process_input(line)
end

One thing I noticed is, that without the lines

cool.transform_proc = proc do
  cool.line
end

Coolline will always swallow the first character and doesn't work at all. I'm not sure I I didn't understand something and use it wrong.

[Mon-Ouie]

Thanks for the transform_proc, it was a bug that I never noticed because… well, transform_proc being the very reason I wrote Coolline for, every example had one. :p

And yes, what Guard does does look fine. The string you're printing in your work around does this:

1. Go back to the beginning of the line
2. Select the default colors, font, etc.
3. Remove the content of the rest of the line

I'm not sure how it can affect the output after system has been called.

[mhenrixon]

@Mon-Ouie Had a chance to look at this yet? I saw you did some commit but when I tried it it didn't work for me but that might be because the version needs updating or something?

[Mon-Ouie]

I still can't seem to reproduce it. If I understand correctly it is related to coolline being run in a subprocess? I tried this, but it behaves as expected:

require 'coolline'

if ARGV[0] == "test"
  Coolline.new { |c|

  }.readline ">> "

  puts "hi"
  puts "hi"
else
  system "ruby #$0 test"
  puts "hi"
  puts "hi"
end

[mhenrixon]

interesting, could it be some subtle bug due to how guard runs it's subtasks? I've been trying to find a potential problem but not been successful so far.

[mhenrixon]

Managed to find the root of the problem. To make guard-rails start in the background rails is started via

system 'sh', '-c', 'rails', 's', '-e', 'development'

I just tried removing the sh -c part and then coolline works nicely but unfortunately this keeps rails in the foreground which of course makes the other guards to not start.

[mhenrixon]

If I change this command to use spawn instead of system (which should basically be the equivalent of sh -c) I get the same results so it's the redirection from the background thread to STDOUT that gets corrupted.

[mhenrixon]

I also get the same result with

system 'rails', 's', '-e', 'development', '&'

[Mon-Ouie]

I can get "weird" output with this, but that's because stuff gets written to stdout while Coolline is editing a line, so there isn't much that can be done about it:

require 'coolline'

if ARGV[0] == "test"
  sleep 1

  puts "hi"
  puts "hi"
else
  system "ruby #$0 test &"
  Coolline.new.readline ">> "
end

[mhenrixon]

Of course there is something that can be done about it. Readline doesn't have this problem so it's got to be fixable :)

Does this line has to be handled at all by coolline? Can we output it without processing it or does that break reading input? I haven't had a look at the coolline source code yet but I will.

[Mon-Ouie]

Even with readline, it doesn't look clean:

Code:

if ARGV[0] == "test"
  sleep 1

  puts "hi"
  puts "hi"
else
  require 'readline'
  system "ruby #$0 test &"
  puts "real output: #{Readline.readline(">> ").inspect}"
end

Output:

$ ruby ~/code/rb/tmp.rb
>> selfhi
hi
 teother st
real output: "other self test"

(I typed "self", waited, then " testother ")

[mhenrixon]

Trying to find what RbReadline does to prevent this from happening.

[mhenrixon]

I can't replicate the last example locally using Readline but the cooline is broken for me.

EDIT I can get the result you said if I type real fast before the first hi is outputted but that\s not the same problem, that's the output being intertwined with each other and that can't ever be completely avoided so rather have that for those few times when I type something than have the entire console output be corrupted all the time if you know what I mean.

[Mon-Ouie]

that's the output being intertwined with each other and that can't ever be completely avoided

But that's also the only issue I encountered with the Coolline version (and what I was talking about earlier).

[mhenrixon]

No if you take a closer look

ruby readline.rb 
>> hi
hi
waiting with writing
real output: "waiting with writing"

tmp ❯ ruby coolline.rb
>> hi
     hi
>> waiting with writing                                                                                                                                                                                                                      
real output: "waiting with writing"

There has got to be a way around the indenting of $stdout. Soon as I do require 'coolline' $stdout starts getting indented for subprocesses.

[Mon-Ouie]

Well, that's still output being intertwined to me…

Anyway, that happens because stuff gets inserted in stdout when in raw mode (during the call to $stidn.getch). I'm not sure how you could avoid being in raw mode, as even IO.select wouldn't report new characters without it.

[mhenrixon]

I'm intrigued! You are correct it's totally intertwined outputs it's just really hard to spot for a rookie like me. I've had some semi success with the following code, would this be fixable at all?

  require 'io/wait'
  def char_if_ready
    begin
      system("stty raw -echo") # turn raw input on
      c = nil
      if $stdin.ready?
        c = $stdin.getc
      end
      c.chr if c
    ensure
      system "stty -raw echo" # turn raw input off
    end
  end

  # Reads a line from the terminal
  # @param [String] prompt Characters to print before each line
  def readline(prompt = ">> ")
    @prompt = prompt

    @history.delete_empty

    @line        = ""
    @pos         = 0
    @accumulator = nil

    @history_moved = false

    @should_exit = false

    print "\r\e[0m\e[0K"
    print @prompt

    @history.index = @history.size - 1
    @history << @line

    until (char = char_if_ready) == "\r"
      handle(char)
      return if @should_exit

      if @history_moved
        @history_moved = false
      end

      render
    end

    print "\n"

    @history[-1] = @line if @history.size != 0
    @history.index = @history.size

    @history.save_line

    @line
  end

It gets me a correct output but sometimes I have to press enter 2-3 times before it's accepted back which is not optimal. Maybe if that could be fixed somehow...

Edit Never mind, I was just lucky like 20 times in a row, now when I tested it does the same thing as getch gaah.

[rdp]

so is this closed or not?

[Mon-Ouie]

No, and I do accept patches if anybody figures out an alternative for reading input.

[rdp]

I guess the ticket being 'closed' is what confused me..