Sentry-java: Environment variables not honored when using logback?

[gionn]

Hi,

I am setting a bunch of environment variables as describe in docs inside a container running a java webapp with sentry v1.3.0 with logback.

  <appender name="SENTRY" class="com.getsentry.raven.logback.SentryAppender">
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <level>WARN</level>
    </filter>
  </appender>

Relevant environment variables:

                "SENTRY_DSN=https://[email protected]/80269",
                "SENTRY_TAGS=env:staging",
                "SENTRY_RELEASE=latest",
                "SENTRY_ENVIRONMENT=stag",
                "SENTRY_SERVERNAME=staging",

Exception get reported (so DSN in working), however tags, release, servername and environment are ignored and not attached to the reported issue.

Thanks.

[bretthoerner]

It looks like you're still including and using the old dependency, your appender class is com.getsentry.raven.logback.SentryAppender.

That should be io.sentry.logback.SentryAppender. It's probably best that you remove the old Raven dependency too, so it's a bit less confusing. 😄

https://docs.sentry.io/clients/java/migration/

[gionn]

you are right @bretthoerner, long story short is that for retro-compatibility of the configuration file I've added both appenders, but logback is loading the correct one:

3:41:53,551 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
13:41:53,553 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
13:41:53,558 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
13:41:53,574 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [io.sentry.logback.SentryAppender]
13:41:53,575 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [SENTRY]
13:41:53,577 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.liberologico.cloudesire] to DEBUG
13:41:53,577 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.cloudesire] to DEBUG
13:41:53,577 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.liberologico.cloudesire.cmw.authentication.preauth] to INFO
13:41:53,577 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.springframework] to INFO
13:41:53,577 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.hazelcast] to INFO
13:41:53,577 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate] to INFO
13:41:53,577 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate.engine.internal.StatisticalLoggingSessionEventListener] to ERROR
13:41:53,577 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate.stat] to DEBUG
13:41:53,577 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.paypal] to DEBUG
13:41:53,577 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [springfox] to ERROR
13:41:53,577 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [io.swagger] to ERROR
13:41:53,578 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.getsentry.raven.servlet.RavenServletRequestListener] to OFF
13:41:53,578 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
13:41:53,578 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
13:41:53,578 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [SENTRY] to Logger[ROOT]
13:41:53,578 |-INFO in ch.qos.logback.core.joran.util.ConfigurationWatchListUtil@491666ad - Adding [file:/etc/cloudesire/tomcat/cmw-logback.xml] to configuration watch list.

Any suggestion regarding the usage of environment variables?

[bretthoerner]

~Well, the environment variables won't affect the old Raven library.~ (Oops, I forgot SENTRY_RELEASE should be valid for raven-java, too.)

By configuring them both you will be sending each exception twice. Are you sure you're looking at a single event that was sent from sentry-java? The specific SDK should be at the bottom of the event page.

I just did a test using our logback example project,

SENTRY_RELEASE=test-for-gionn SENTRY_DSN="$MY_DSN" mvn clean compile exec:java -Dsentry.version=1.3.0

---

EDIT: Are you sure the environment variables are being passed to the JVM correctly? It looks like a DSN is being configured, are you setting it in any other way (logback.xml, etc?), and maybe that's why the DSN is working?

[bretthoerner]

Can you link me (on Sentry) to the specific event, or is this self hosted?

[gionn]

https://sentry.io/cloudesirecom-srl/backend-cmw/issues/317695842/

Environment variables are correctly set at container level, and the application is run via java, so the environment is inherited.

root@staging /etc/cloudesire # docker exec -ti cmw sh
/ # ps aux
PID   USER     TIME   COMMAND
    1 root       2:32 java -javaagent:/usr/local/java/lib/newrelic.jar -XX:-OmitStackTraceInFastThrow -jar /usr/local/java/cmw.jar
  363 root       0:00 sh
  369 root       0:00 ps aux
/ # echo $SENTRY_RELEASE
latest

I am almost out of ideas, DSN is not configured anywhere else other than via environment variable.

[bretthoerner]

Just as a sanity check could you print one of those environment variables from your app? I just want to rule it out, since a launcher-script (which are almost always used for Java) could strip the env... unless your container literally uses java <args>... as its direct run command?

This is weird because I've used the environment variables forever...

Is there any way you could try running it without the old Raven library included/configured? That is throwing me off a bit... although I admit I can't think of a way could conflict.

[gionn]

Just looking at the ps aux output, you see that the java process has pid 1, so it's running without any wrapper script.

I am trying the configuration on my local environment (without docker and with a proper configuration file), I've switched to logback-classic to match your example project dependency, and I am seeing the same results (notice that server_name this time is gt-xps)

https://sentry.io/cloudesirecom-srl/backend-cmw/issues/317734585/

[bretthoerner]

with a proper configuration file

Do you mean sentry.properties or something else?

Can you set io.sentry.config.Lookup to DEBUG? It prints the configuration it finds.

I tried the ones you provided:

SENTRY_TAGS=env:staging \
SENTRY_RELEASE=latest \
SENTRY_ENVIRONMENT=stag \
SENTRY_SERVERNAME=staging \
SENTRY_DSN="$DSN" \
mvn clean compile exec:java -Dsentry.version=1.3.0

Logs:

10:02:02.723 [io.sentry.example.Application.main()] DEBUG io.sentry.config.Lookup - Found release=latest in System Environment Variables.
10:02:02.724 [io.sentry.example.Application.main()] DEBUG io.sentry.config.Lookup - Found environment=stag in System Environment Variables.
10:02:02.724 [io.sentry.example.Application.main()] DEBUG io.sentry.config.Lookup - Found servername=staging in System Environment Variables.
10:02:02.724 [io.sentry.example.Application.main()] DEBUG io.sentry.config.Lookup - Found tags=env:staging in System Environment Variables.

I'll try with a full uberjar to rule out any Maven weirdness.

[gionn]

Bingo, I've found that we are using a custom client factory, removing it seems to fix the issue:

public class MySentryClientFactory extends DefaultSentryClientFactory
{
    /*
     * Create and use the ForwardedAddressResolver, which will use the
     * X-FORWARDED-FOR header for the remote address if it exists.
     */
    @Override
    public SentryClient createSentryClient( Dsn dsn )
    {
        SentryClient client = new SentryClient( createConnection( dsn ), getContextManager( dsn ) );
        ForwardedAddressResolver forwardedAddressResolver = new ForwardedAddressResolver();
        client.addBuilderHelper( new HttpEventBuilderHelper( forwardedAddressResolver ) );
        return client;
    }
}

Is this still needed to log the upstream IP when behind proxy?

[bretthoerner]

Ahhh. Yeah it's still needed for now. The problem is that upstream changed.

If you'll just change the last line to return configureSentryClient(sentryClient, dsn); I think it'll fix everything.

[bretthoerner]

I'll see if I can't fix that in general though. Definitely an unintended consequence.

[gionn]

Great, it's working now!

I've changed the factory code to:

    @Override
    public SentryClient createSentryClient( Dsn dsn )
    {
        SentryClient sentryClient = super.createSentryClient( dsn );
        ForwardedAddressResolver forwardedAddressResolver = new ForwardedAddressResolver();
        sentryClient.addBuilderHelper( new HttpEventBuilderHelper( forwardedAddressResolver ) );
        return sentryClient;
    }

The broken snippet seems was found here: https://docs.sentry.io/clients/java/config/#implementation

Thanks @bretthoerner for your support! :+1:

[bretthoerner]

Oh crap, that's even better. Yeah, I'll fix the docs. Thanks for your patience.

[bretthoerner]

Errr wait, that's actually adding two HttpEventBuilderHelpers (because super adds one too).

I can improve this in the next release, but for now you may want to do this (or your HTTP data may be smashed by the non-forward-address helper):

    @Override
    public SentryClient createSentryClient(Dsn dsn) {
        SentryClient sentryClient = new SentryClient(createConnection(dsn), getContextManager(dsn));
        ForwardedAddressResolver forwardedAddressResolver = new ForwardedAddressResolver();
        sentryClient.addBuilderHelper( new HttpEventBuilderHelper( forwardedAddressResolver ) );        sentryClient.addBuilderHelper(new ContextBuilderHelper(sentryClient));
        sentryClient.addBuilderHelper(new ContextBuilderHelper(sentryClient));
        return configureSentryClient(sentryClient, dsn);
    }

[bretthoerner]

Fixed the docs to reflect that code above. #222 will improve the ForwardedAddressResolver stuff.

[sambokai]

I'm having the same issue.
Setting the DSN through ENV Variable SENTRY_DSN does not work. Passing via JVM -Dsentry.dsn does work.

Did the sanity checks, ENV variables are set correctly. I'm using o.sentry.logback.SentryAppender.

Any ideas?

logback.xml

<!-- https://www.playframework.com/documentation/latest/SettingsLogger -->
<configuration>

  <conversionRule conversionWord="coloredLevel" converterClass="play.api.libs.logback.ColoredLevel" />

  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <file>${application.home:-.}/logs/application.log</file>
    <encoder>
      <pattern>%date [%level] from %logger in %thread - %message%n%xException</pattern>
    </encoder>
  </appender>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%coloredLevel %logger{15} - %message%n%xException{10}</pattern>
    </encoder>
  </appender>

  <appender name="ASYNCFILE" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="FILE" />
  </appender>

  <appender name="ASYNCSTDOUT" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="STDOUT" />
  </appender>

  <!-- Sentry.io Logging -->
  <appender name="Sentry" class="io.sentry.logback.SentryAppender">
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <level>WARN</level>
    </filter>
  </appender>

  <logger name="play" level="INFO" />
  <logger name="application" level="DEBUG" />
  <logger name="controllers" level="DEBUG" />
  <logger name="clients" level="INFO" />

  <!-- Off these ones as they are annoying, and anyway we manage configuration ourselves -->
  <logger name="com.avaje.ebean.config.PropertyMapLoader" level="OFF" />
  <logger name="com.avaje.ebeaninternal.server.core.XmlConfigLoader" level="OFF" />
  <logger name="com.avaje.ebeaninternal.server.lib.BackgroundThread" level="OFF" />
  <logger name="com.gargoylesoftware.htmlunit.javascript" level="OFF" />

  <root level="WARN">
    <!--<appender-ref ref="ASYNCFILE" />-->
    <appender-ref ref="ASYNCSTDOUT" />
    <appender-ref ref="Sentry"/>
  </root>

</configuration>

sentry-logback version

libraryDependencies += "io.sentry" % "sentry-logback" % "1.7.10"

Any ideas?

[bretthoerner]

Weird, there's nothing too special going on:

https://github.com/getsentry/sentry-java/blob/0626077a0a5316cef31d1f367a0c5fe3b6b02149/sentry/src/main/java/io/sentry/config/Lookup.java#L122-L136

Can you run with DEBUG logging (at least for io.sentry.*), I'm curious what the io.sentry.* logs say at init?