too hard to notice cap failure in terminal, because log lines push actual error off screen

[jrochkind]

Here is an error I just got on a cap deploy:

** DEPLOY FAILED
** Refer to log/capistrano.log for details. Here are the last 20 lines:


  INFO [69ce5304] Running bundle exec rake assets:precompile as [email protected]

  INFO [22a16b47] Finished in 16.099 seconds with exit status 0 (successful).

  INFO [71d71cba] Running /usr/bin/env ./config/deploy/bin/link_custom_error_pages.rb 404.html as [email protected]

  INFO [f08c97a9] Finished in 0.188 seconds with exit status 0 (successful).

  INFO [775fba67] Running /usr/bin/env ./config/deploy/bin/link_custom_error_pages.rb 500.html as [email protected]

  INFO [cdc3a2d2] Finished in 0.175 seconds with exit status 0 (successful).

  INFO [d251cb99] Running /usr/bin/env mkdir -p /opt/scihist_digicoll/releases/20190606132005/assets_manifest_backup as [email protected]

  INFO [9d01fce1] Finished in 0.097 seconds with exit status 0 (successful).

  INFO [2e7c2184] Running /usr/bin/env cp /opt/scihist_digicoll/releases/20190606132005/public/assets/.sprockets-manifest-8b9bfd408092ddf68680150358a51d32.json /opt/scihist_digicoll/releases/20190606132005/assets_manifest_backup as [email protected]

  INFO [1899ac6d] Finished in 0.095 seconds with exit status 0 (successful).

  INFO [deploy:migrate] Run `rake db:migrate`

  INFO [a4ce689f] Running bundle exec rake db:migrate as [email protected]

  INFO [515cc3d4] Finished in 1.804 seconds with exit status 0 (successful).

  INFO [6dae8341] Running /usr/bin/env ln -s /opt/scihist_digicoll/releases/20190606132005 /opt/scihist_digicoll/releases/current as [email protected]

  INFO [ceb2909a] Finished in 0.100 seconds with exit status 0 (successful).

  INFO [3bbbae0d] Running /usr/bin/env mv /opt/scihist_digicoll/releases/current /opt/scihist_digicoll as [email protected]

  INFO [7ae7f931] Finished in 0.093 seconds with exit status 0 (successful).

  INFO [d6cc2f57] Running /usr/bin/env sudo /usr/sbin/service resque-pool restart as [email protected]

  INFO [b0f2420b] Finished in 4.329 seconds with exit status 0 (successful).

  INFO [cdb45398] Running /usr/bin/env sudo systemctl restart passenger  as [email protected]

"DEPLOY FAILED" is in red, and "Refer to log/capistrano.log..." is in yellow... but neither are actually in my terminal window, they've scrolled out of the current terminal view, because of the 20 log lines appended to them. (Yes, the intermediate newlines between log lines are ther ein my output too, which doesn't help, but even without them I think it would make the failure notice too easy to miss).

• Is there any way to turn off the "Here are the last 20 lines:" feature?
• Should the red ** DEPLOY FAILED message be REPEATED after the log lines?

Even if configurable to be different, I think this is not a great experience for newbies. It's too easy to run a cap deploy and think it ran successfully, when it failed. Especially because a typical cap deploy has so much logging already, the repeated "last 20 lines" just look like more of it, unless you know what the terminal output should end with, and realize it's not there, or think to scroll back to look for an error message... it is far too easy to not realize your deploy failed.

[leehambley]

Absolutely agreed this can suck, especially in the context of limited scrollback buffers or people who use tmux with unreliable mouse scrolling where you need 5 key presses to get to a scrollback mode.

I'm not actually sure about being able to turn off the last 20 lines repeated, I guess that code was written 5-6 years ago and hasn't been touched meaningfully since, lemme look into it...

[leehambley]

I found the responsible code in the airbrussh gem, it threw me because the output you pasted is not airbrussh format output but our native "pretty" format.

Airbrussh is reading the log file from disk and forwarding the contents which explains why.

The offending code is at https://github.com/mattbrictson/airbrussh/blob/eac9bbe3fbf0990cf655746c36a9ba4e1c47950d/lib/airbrussh/capistrano/tasks.rb#L37-L48 and I can't see an obvious way to change its behaviour, that said, it does appear to simply hook deploy:failed task which you could overwrite, or augment with your own preferred behaviour.

Alternatively don't use the airbrussh formatter, and set the output printer to the :pretty one.

Matt is on hiatus right now so I don't think we can count much on his engagement, but I'd be more than willing to help you shepherd a patch through airbrussh to get that to be configurable.

We currently have a line of configuration options for airbrussh (optionally) in the deploy.rb template, here:

capistrano/lib/capistrano/templates/deploy.rb.erb

Line 18 in 50a307e

# set :format_options, command_output: true, log_file: "log/capistrano.log", color: :auto, truncate: :auto

[jrochkind]

Hmm, I haven't heard of airbrussh before, and have never consciously considered formatters at all or thought about there being different ones. Is airbrussh the default then? I have done nothing on purpose to use it -- is it mysterious that it's being used? (Maybe some other gem I am using made it the default or something?). I'm confused about what's going on.

The simplest fix initially seemed to be just having cap output "DEPLOY FAILED" in red again after the "last 20 lines". But I hadn't considered that this "last 20 lines" was coming from a certain formatter, and other formatters might not have it, which seems to be what you're suggesting? So just outputting the same line again would be unacceptable I guess, messing up people who want alternative or custom formatters and don't want a duplicate line.

I may try the :pretty formatter. If it doesn't have this problem, and I otherwise am okay with it, I may just switch to it -- which would solve the problem for me.

But if the current behaior, using airbrussh, is the default behavior, I still think the default behavior is setting up a trap for new users. But I'm confused about what's default why from your comments about airbrussh. I think the out of the box default behavior ought to leave you with a clear notice of failure in the last line of terminal output, for failed deploys.

[jrochkind]

Okay, looking into it more I see airbrussh is default in recent capistrano.

@leehambley I guess this isn't your gem, but do you have commit rights to it? airbrussh?

The simplest thing that I think would provide a better experience for what is the default capistrano formatter -- what if it just swapped the order of the output? Put the "last 20 log lines" output first, and the line 43 error_line(red("** DEPLOY FAILED")) last?

[jrochkind]

It's also kind of a mystery why the tail_log_file is somehow ending up with a blank line between every capistrano line (not sure if this is the original log file, or is being added, and if being added whether it's accidental or on purpose). But that's kind of a separate issue maybe. Even with no blank line between every log line, I don't think it'd be clear enough.

[leehambley]

Airbrussh is actually Matt's gem, he wrote it to have nicer, prettier output and a few years ago we changed it to be the default formatter in newly generated Capfiles in the initialization template.

what if it just swapped the order of the output? Put the "last 20 log lines" output first, and the line 43 error_line(red("** DEPLOY FAILED")) last?

I think that'd be totally reasonable, I'd recommend opening an issue against Airbrussh, it should be trivial, though beware there are specs for the output handling (🎉 ) which should make testing this a bit easier for you.

Regarding the double newlines, I'm also not sure, maybe it'd be worth chomping the lines read from the file before doing anything with them?

WDYT?