You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@storm.apache.org by "Panovski, Filip" <Fi...@vectron.de> on 2020/02/11 13:35:56 UTC
Issues with logging in Storm workers/topology
Hello,
I’m having difficulties with getting useful logging information out of my workers/topology on Storm 2.1.0. We’re running our Storm workers as Docker services in Swarm mode and forward STDOUT via a GELF Driver to our ELK stack.
To keep it as simple as possible, my current worker log4j2 configurations look as follows (basically – log everything to STDOUT @ INFO, log some topology-specific logs to STDOUT @ DEBUG):
cluster.xml
<Configuration monitorInterval="60" shutdownHook="disable" packages="ch.qos.logback.core">
<Properties>
<property name="logstash">+ %msg +%n</property> <!-- only for 'bug' demonstration purposes -->
</Properties>
<Appenders>
<Console name="CONSOLE">
<PatternLayout>
<Pattern>${logstash}</Pattern>
</PatternLayout>
</Console>
</Appenders>
<Loggers>
<Root level="INFO">
<AppenderRef ref="CONSOLE" />
</Root>
</Loggers>
</Configuration>
worker.xml
<Configuration monitorInterval="60" shutdownHook="disable" packages="ch.qos.logback.core">
<Properties>
<property name="logstash">{"@timestamp":"%d{yyyy-MM-ddTHH:mm:ss.SSS}", "logger": "%logger", "message":"%msg","thread_name":"%t","level":"%level"}%n</property>
</Properties>
<Appenders>
<Console name="CONSOLE">
<PatternLayout>
<Pattern>${logstash}</Pattern>
</PatternLayout>
</Console>
</Appenders>
<Loggers>
<Logger name="org.com.package" level="DEBUG" additivity="false">
<AppenderRef ref="CONSOLE"/>
</Logger>
<Root level="INFO">
<AppenderRef ref="CONSOLE"/>
</Root>
</Loggers>
</Configuration>
According to my this configuration, I would've expected a log message formatted similarly to the following (newlines added for clarity):
{
"@timestamp": "2020-02-11 11:32:40,748",
"logger": "org.com.package.aggregation.SomeAggregation",
"message": "joinStateStream: values: [33333333-4e30-49a6-8e1c-f7817633bb34, 7c777777-a622-4ae4-a504-2490db47cafe, 2020-02-11]",
"thread_name": "Thread-23-b-25-joinState-groupedQ-revQ-executor[22, 22]",
"level": "DEBUG"
}
The resulting message that is delivered, however, looks completely different and ‘wrong’:
+ Worker Process 273c05df-f087-43ca-a59a-e281bae98ab1:
{
"@timestamp":"2020-02-11 11:32:40,748",
"logger": "STDERR",
"message":
"{
"@timestamp":"2020-02-11 11:32:40,748",
"logger": "org.com.package.aggregation.SomeAggregation",
"message":"joinStateStream: values: [33333333-4e30-49a6-8e1c-f7817633bb34, 7c777777-a622-4ae4-a504-2490db47cafe, 2020-02-11]",
"thread_name":"Thread-23-b-25-joinState-groupedQ-revQ-executor[22, 22]",
"level":"DEBUG"
}",
"thread_name":"Thread-2",
"level":"INFO"} +
Basically:
- It seems that any worker logs are actually logged by the supervisor (“Worker Process <id>” prefix as well as the enclosing “+” from the cluste.xml above)
- The worker logs themselves seem to be wrapped for some reason. The “message” part of the outer message seems to contain yet another log message.
And so:
1. I took a look at the source for “org.apache.storm.daemon.supervisor.BasicContainer#launch” and it doesn’t seem like this log prefix (“Worker process <id>:”) is configurable, which is quite surprising. Is there a different way of deployment where this is configurable?
2. What could be causing this “message” wrapping going on? As far as I can see, the “wrappee” is my actual topology log message that I wish to parse, and the “wrapper” is something else entirely (seemingly an error log? With level info? ¯\_(ツ)_/¯
Is there any way to simply get the worker/topology logs in a specified format? As a last resort, I could potentially parse the worker.log files, but I would rather not resort to that as it is not as robust as I’d like (worker could potentially crash between writing to and reading from the log file).
--
Amtsgericht Münster HRB 10502Vertretungsberechtigter Vorstand / Board of Management: Thomas Stümmler (Vorsitz / Chairman), Jens Reckendorf, Silvia OstermannAufsichtsrat / Supervisory Board: Christian Ehlers (Vorsitz / Chairman)
Re: Issues with logging in Storm workers/topology
Posted by Ethan Li <et...@gmail.com>.
Hi,
I don’t claim to know what’s going on here. But just want to give you some input from my little experiment.
By simply replacing https://github.com/apache/storm/blob/v2.1.0/log4j2/worker.xml#L21 <https://github.com/apache/storm/blob/v2.1.0/log4j2/worker.xml#L21> with your pattern:
{"@timestamp":"%d{yyyy-MM-ddTHH:mm:ss.SSS}", "logger": "%logger", "message":"%msg","thread_name":"%t","level":"%level"}%n
I am able to get the log you are looking for, e.g. (worker.log)
{"@timestamp":"2020-03-06 03:48:57,987", "logger": "org.apache.storm.daemon.Task", "message":"Emitting Tuple: taskId=23 componentId=spout stream=default values=[snow white and the seven dwarfs]","thread_name":"Thread-33-spout-executor[23, 23]","level":"INFO”}
I didn’t change anything else. Maybe it has something to do with the packages you configured: packages=“ch.qos.logback.core" or some other setup.
Best
Ethan
> On Feb 11, 2020, at 7:35 AM, Panovski, Filip <Fi...@vectron.de> wrote:
>
> Hello,
>
> I’m having difficulties with getting useful logging information out of my workers/topology on Storm 2.1.0. We’re running our Storm workers as Docker services in Swarm mode and forward STDOUT via a GELF Driver to our ELK stack.
>
> To keep it as simple as possible, my current worker log4j2 configurations look as follows (basically – log everything to STDOUT @ INFO, log some topology-specific logs to STDOUT @ DEBUG):
>
> cluster.xml
>
> <Configuration monitorInterval="60" shutdownHook="disable" packages="ch.qos.logback.core">
> <Properties>
> <property name="logstash">+ %msg +%n</property> <!-- only for 'bug' demonstration purposes -->
> </Properties>
> <Appenders>
> <Console name="CONSOLE">
> <PatternLayout>
> <Pattern>${logstash}</Pattern>
> </PatternLayout>
> </Console>
> </Appenders>
> <Loggers>
> <Root level="INFO">
> <AppenderRef ref="CONSOLE" />
> </Root>
> </Loggers>
> </Configuration>
>
> worker.xml
> <Configuration monitorInterval="60" shutdownHook="disable" packages="ch.qos.logback.core">
> <Properties>
> <property name="logstash">{"@timestamp":"%d{yyyy-MM-ddTHH:mm:ss.SSS}", "logger": "%logger", "message":"%msg","thread_name":"%t","level":"%level"}%n</property>
> </Properties>
> <Appenders>
> <Console name="CONSOLE">
> <PatternLayout>
> <Pattern>${logstash}</Pattern>
> </PatternLayout>
> </Console>
> </Appenders>
> <Loggers>
> <Logger name="org.com.package" level="DEBUG" additivity="false">
> <AppenderRef ref="CONSOLE"/>
> </Logger>
> <Root level="INFO">
> <AppenderRef ref="CONSOLE"/>
> </Root>
> </Loggers>
> </Configuration>
>
> According to my this configuration, I would've expected a log message formatted similarly to the following (newlines added for clarity):
>
> {
> "@timestamp": "2020-02-11 11:32:40,748",
> "logger": "org.com.package.aggregation.SomeAggregation",
> "message": "joinStateStream: values: [33333333-4e30-49a6-8e1c-f7817633bb34, 7c777777-a622-4ae4-a504-2490db47cafe, 2020-02-11]",
> "thread_name": "Thread-23-b-25-joinState-groupedQ-revQ-executor[22, 22]",
> "level": "DEBUG"
> }
>
>
> The resulting message that is delivered, however, looks completely different and ‘wrong’:
>
> + Worker Process 273c05df-f087-43ca-a59a-e281bae98ab1:
> {
> "@timestamp":"2020-02-11 11:32:40,748",
> "logger": "STDERR",
> "message":
> "{
> "@timestamp":"2020-02-11 11:32:40,748",
> "logger": "org.com.package.aggregation.SomeAggregation",
> "message":"joinStateStream: values: [33333333-4e30-49a6-8e1c-f7817633bb34, 7c777777-a622-4ae4-a504-2490db47cafe, 2020-02-11]",
> "thread_name":"Thread-23-b-25-joinState-groupedQ-revQ-executor[22, 22]",
> "level":"DEBUG"
> }",
> "thread_name":"Thread-2",
> "level":"INFO"} +
>
> Basically:
> - It seems that any worker logs are actually logged by the supervisor (“Worker Process <id>” prefix as well as the enclosing “+” from the cluste.xml above)
> - The worker logs themselves seem to be wrapped for some reason. The “message” part of the outer message seems to contain yet another log message.
>
> And so:
> 1. I took a look at the source for “org.apache.storm.daemon.supervisor.BasicContainer#launch” and it doesn’t seem like this log prefix (“Worker process <id>:”) is configurable, which is quite surprising. Is there a different way of deployment where this is configurable?
> 2. What could be causing this “message” wrapping going on? As far as I can see, the “wrappee” is my actual topology log message that I wish to parse, and the “wrapper” is something else entirely (seemingly an error log? With level info? ¯\_(ツ)_/¯
>
> Is there any way to simply get the worker/topology logs in a specified format? As a last resort, I could potentially parse the worker.log files, but I would rather not resort to that as it is not as robust as I’d like (worker could potentially crash between writing to and reading from the log file).
>
>
>
> --
> Amtsgericht M�nster HRB 10502 Vertretungsberechtigter Vorstand / Board of Management: Thomas St�mmler (Vorsitz / Chairman), Jens Reckendorf, Silvia Ostermann Aufsichtsrat / Supervisory Board: Christian Ehlers (Vorsitz / Chairman)