Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Disable "App PID stdout|stderr" prefix to simplify app logs forwarding #1915

Closed
evgeny-myasishchev opened this Issue Jan 11, 2017 · 24 comments

Comments

Projects
None yet
@evgeny-myasishchev
Copy link

evgeny-myasishchev commented Jan 11, 2017

Hi,

I have passenger serving ruby app within a docker container. The app is writing logs straight to the stdout and it will then get forwarded by docker elsewhere. Passenger (I have 5.1.1) is now prefixing all stdout from the app like this:

App 9220 stdout: {"time":"2017-01-11T10:10:11.601+02:00","name":"MyApp","level":"INFO","message":"Sample log message"}

So I have to apply some workarounds to have my logs forwarded without the prefix, e.g just like this:

{"time":"2017-01-11T10:10:11.601+02:00","name":"MyApp","level":"INFO","message":"Sample log message"}

It would be good to have some option to disable prefixing in a first place.

@OnixGH

This comment has been minimized.

Copy link
Contributor

OnixGH commented Jan 11, 2017

When thinking about prefix options, should also consider the prefix thoughts here: #1279 (comment)

@jeremywadsack

This comment has been minimized.

Copy link

jeremywadsack commented Apr 26, 2017

No prefix would be really nice for aggregating app logs and feeding into Logstash (or any other log aggregator).

@CamJN

This comment has been minimized.

Copy link
Contributor

CamJN commented Apr 26, 2017

Logstash can strip a prefix quite easily and even maintain parallel execution, perhaps you'd like to expand on your use-case a bit?

@jeremywadsack

This comment has been minimized.

Copy link

jeremywadsack commented Apr 26, 2017

We are aggregating logs from Docker containers on Google Container Engine (GKE). These are pulled into Fluentd which then forwards them on to Stackdriver. I could write a Fluentd parser plugin to strip a prefix, but I can't really change the configuration on GKE because that would be reset whenever I rebuilt the cluster or nodes (I'd really prefer to treat nodes as immutable). Stackdriver doesn't have any tools for prefix stripping (it's pretty lightweight as far as log tools go).

Yes, I could configure Fluentd, Logstash, or whatever, but I felt it would be better to fix the issue at the source.

@jeremywadsack

This comment has been minimized.

Copy link

jeremywadsack commented Apr 26, 2017

Incidentally, we are using a phusion/passenger-docker image which collects logs from nginx through a log forwarder. So I configured that to strip the prefix and now my JSON logs load into Fluentd and Stackdriver correctly without any need to hack those.

Here's my replacement for /etc/service/nginx-log-forwarder/run in our images:

#!/bin/bash
# Forwards the Nginx error.log and access.log to the Docker logs.
# sed command trims off the prefix that Passenger adds to the log lines
set -e
if [[ -e /var/log/nginx/error.log ]]; then
        exec tail -q -F /var/log/nginx/error.log -F /var/log/nginx/access.log | sed -E 's/^App [0-9]+ std[a-z]+: [A-Z], \[[0-9:T. #-]+\] +[A-Z]+ -- : //'
else
        exec sleep 10
fi
@CamJN

This comment has been minimized.

Copy link
Contributor

CamJN commented Apr 27, 2017

Thanks for the perspective.

@fangpinchang

This comment has been minimized.

Copy link

fangpinchang commented Nov 8, 2017

@jeremywadsack, great hint! One minor correction. The path should be /etc/service/nginx-log-forwarder/run.

@jeremywadsack

This comment has been minimized.

Copy link

jeremywadsack commented Nov 8, 2017

@fangpinchang You are correct. I've updated my comment.

@CamJN CamJN removed the SupportCentral label Nov 9, 2017

@ludwick

This comment has been minimized.

Copy link

ludwick commented Apr 28, 2018

Note that I added the following just before the exec tail call:

trap "pkill -TERM -P $$" EXIT

Without it, the call to sv restart /etc/service/nginx-log-forwarder in the nginx run script can cause an extra tail process to persist. We found that this resulted in our container stdout having randomly corrupted json lines which were a mixture of multiple logs lines.

@fangpinchang

This comment has been minimized.

Copy link

fangpinchang commented Apr 30, 2018

@ludwick, I am seeing garbled JSON lines in my logs and thinking maybe it is my log aggregator's problem. I am going to try this out.

@jeremywadsack

This comment has been minimized.

Copy link

jeremywadsack commented Apr 30, 2018

@ludwick Perfect timing on this! I just ran into the same problem for us on Friday (with the 0.9.29 image; I'm not seeing this in our 0.9.19 image). Thank you.

Adding that line resolved it although it does add a message to the logs saying it's terminating the first exec tail command.

It seems that sv restart should be atomic, though, right? Could it be because it doesn't know that the service is running? Could adding a /etc/service/nginx-log-forwarder/check script help?

restart
Send the commands term, cont, and up to the service, and wait up to 7 seconds for the service to restart. Then report the status or timeout. If the script ./check exists in the service directory, sv runs this script to check whether the service is up and available again; it’s considered to be available if ./check exits with 0.

-- http://smarden.org/runit/sv.8.html

@CamJN CamJN removed the SupportCentral label May 9, 2018

@dmalan

This comment has been minimized.

Copy link

dmalan commented Aug 16, 2018

Just wanted to chime in to say that being able to suppress App PID stdout|stderr prefixes (on the console especially) would indeed be nice, particularly for apps for which there's only one App PID anyway. In our case, we use Passenger in an educational setting, and being able to simplify console output, particularly while students are first learning, would be quite helpful so that the output focuses nearly entirely error messages (e.g., Python tracebacks).

@wilsonsilva

This comment has been minimized.

Copy link

wilsonsilva commented Sep 6, 2018

These prefixes don't seem to be documented anywhere. It took me a while to figure out where this was coming from. This causes issues in my Datadog instance. Would be great to have them removed with a configuration.

@alexandergitter

This comment has been minimized.

Copy link

alexandergitter commented Oct 9, 2018

We're using the phusion/passenger-docker image as well and ran into corrupted log output when using the sed workaround from the earlier comments. Adding the --unbuffered flag to sed seems to fix that issue. The script we're using now looks as follows:

#!/bin/bash
# Forwards the Nginx error.log to the Docker logs.
# sed command trims off the prefix that Passenger adds to the log lines
# see https://github.com/phusion/passenger/issues/1915
set -e
if [[ ! -e /var/log/nginx/error.log ]]; then
	touch /var/log/nginx/error.log
fi
trap "pkill -TERM -P $$" EXIT
exec tail -F /var/log/nginx/error.log | sed -u -E 's/^App [0-9]+ [a-z]+: //'

@CamJN CamJN removed the SupportCentral label Nov 27, 2018

@oreststetsiak

This comment has been minimized.

Copy link

oreststetsiak commented Jan 4, 2019

below logstash filter works for us, as a workaround

filter {
...................
    else if [type] == 'aws_ecs' {
        mutate {
            gsub => ["message", "App \d* output: ", ""]
         }
@23tux

This comment has been minimized.

Copy link

23tux commented Jan 23, 2019

Any news on this? I'm searching for a similar solution for Filebeat. Passenger prefixes our logs with App 170 output: {"method":"GET","path":"/foobar"} and I'd like to remove the App 170 output: so that the json is parseable for Filebeat.

@ikottman

This comment has been minimized.

Copy link
Contributor

ikottman commented Jan 29, 2019

@FooBarWidget / @CamJN I'm not sure if this is the best place to comment, let me know if there's a better spot. I'm attempting to create a patch to resolve this issue by adding an optional config flag to disable prefixing logs. Unfortunately, I'm running into an error I can't figure out. My current changes are here, I'm focusing on adding the config to nginx initially.

I've added the passenger_disable_log_prefix flag which when specified will no longer prepend the PID/channel to log statements. I'm using the development VM and for testing purposes I modified the example rack program to immediately throw an error, so I can see app logs easily. I've re-compiled nginx after I made my changes, and I can see what I think is correct auto-generated configuration methods. However, when I run

cd dev/rack.test/
passenger start --nginx-config-template test_nginx.conf.erb --disable-log-prefix

I get:

*** ERROR: the Nginx configuration that Phusion Passenger Standalone generated internally contains problems. The error message returned by the Nginx engine is:

    nginx: [emerg] unknown directive "passenger_disable_log_prefix" in nginx.conf:22
    nginx: configuration file nginx.conf test failed

I'm new to nginx/passenger internals, is there a step I'm missing to let nginx know about my new configuration option? Any help is appreciated, thanks!

@jeremywadsack

This comment has been minimized.

Copy link

jeremywadsack commented Jan 29, 2019

@ikottman I don't have an answer for your question, but I'm really excited that you are working on a patch. I've never contributed to Passenger and I haven't had time to look into this but I've really wanted to make a fix.

Looking at your diff, I was wondering if instead of passenger_disable_log_prefix as a setting (which has a negative connotation — that is when the value is false the behavior is to put a prefix in) do you think it would be clearer to have a setting passenger_log_prefix (with the positive connotation) that defaults to true?

Just a suggestion. I'm am really glad you are taking this on and would appreciate this change anyway you choose to make it!

@CamJN

This comment has been minimized.

Copy link
Contributor

CamJN commented Jan 29, 2019

I'm a bit stretched thin right ATM, but if you like here's a commit that adds a config option that works on the same parts of the code: db23f69 hopefully it's helpful.

@ikottman

This comment has been minimized.

Copy link
Contributor

ikottman commented Jan 30, 2019

@CamJN Thanks for commit, it was a good point to compare to. I think my problem has to do with how I'm compiling or running passenger, and less with the code.

My configuration works when running passenger with nginx, but fails with the aforementioned error in standalone mode. If I re-compile nginx with rake nginx will passenger standalone use the generated config in src/nginx_module/ or is there some other step to get passenger standalone's nginx portion to allow new config?

edit: My config updates now work with both nginx and apache integration, but I still have not gotten past the unrecognized configuration error with passenger standalone.

@ikottman

This comment has been minimized.

Copy link
Contributor

ikottman commented Feb 1, 2019

@jeremywadsack thanks for the feedback. I modeled PassengerDisableLogPrefix after a few other flag arguments, like PassengerDisableSecurityUpdateCheck. I think it makes sense to have a negative connotation when you are turning off a feature that is normally turned on. However, I see other flag examples like PassengerShowVersionInHeader which have a positive connotation and defaults to true. Personally I'm partial to the disable wording, but I'm open to whatever name the community/maintainers thinks is clearest.

@jeremywadsack

This comment has been minimized.

Copy link

jeremywadsack commented Feb 1, 2019

@ikottman You're right and there are other examples where the configuration is "disable". I get the point — you have a configuration that you opt-in to that changes the default value.

I'm just one vote and not a community voice. Let's see what they have to say or go with what you think is best.

@ikottman

This comment has been minimized.

Copy link
Contributor

ikottman commented Feb 14, 2019

I'm interested in this change. Is there an estimated timeline for when 6.0.2 will be released?

@CamJN

This comment has been minimized.

Copy link
Contributor

CamJN commented Feb 15, 2019

I need to get the passenger homebrew formula updated first, then I'll release 6.0.2.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.