Issue with log file cursor under Rails (and others?)

[leehambley]

Issue with log file cursor under Rails (and others?)

[leehambley]

To clarify whilst the log cursor issue is a Rails problem, I cannot reproduce the broken escape characters in standalone Rails, nor in this contrived app under Foreman; but I do believe that foreman's output handler is causing the problem.

[ddollar]

Foreman will display to the terminal output anything written to stdout by the processes it launches.

The broken escape codes may be from the buffer getting read across an escape code boundary which causes part of the escape code to be on two different lines with the foreman header in between. I'll have to look into this and see how I can fix it. Patches definitely welcome if you want to take a shot at it as well.

[leehambley]

@ddollar thanks for getting back to me about this, eventually iTerm2 included an "ignore session initiated printing" option, which cured my problem.

I think the further problem is with the Rails log file cursor, same steps to reproduce, and you see a lot of Rails streaming the log, even if it was from another process (that is rails runner vs. script server) - do you think that should be considered a bug? (That it catches-up the log on the next web request?)

[ddollar]

foreman is not actually tailing the log, it's just displaying whatever rails displays on stdout so there's probably not much I can do

[leehambley]

@ddollar, good point, was mixing my terminology, except that foreman does prefix the log lines with | web.1 | or something, and that did seem to be where the print codes were coming from… I'll see if I can file this upstream at rails (rails should be more relaxed about the log cursor, I think, but I expect some limitations mean that it can't be)

[ddollar]

Resolving ancient bugs. Please reopen if this is still an issue.

[leehambley]

It still happens, but I'm pretty sure it's something to do with Rails chasing the log's EOF on the next web request; which is annoying. I don't think I ever remembered to open the bug upstream with Rails. If/when I do, I'll drop a link here. Cheers.

[leehambley]

Update here, I just watched Railscats #391 (pro) and noticed something interesting, Rails only flushes writes to the logfile when the next rack request is finishing, it's handled by the Rails::Rack::Logger middleware.

So the workaround for anyone else suffering is to set the log to autoflush on any background jobs. such as Resque workers/etc, and/or open an issue with Rails and share your feeling that middleware isn't an appropriate place to be flushing logfiles.