Empty result when using TCP input to collect NLog JSON events

tbugbee · March 29, 2018, 2:36pm

Hello,

I am attempting to collect logs using NLog targets and save them into a log file. The NLog target is sending events to Logstash using TCP and formats them in this way:

 <target xsi:type="Network" name="logstash" address="tcp://<hostname>:5602" layout="${message}" />

My logstash.conf file is as follows:

input {
  TCP {
    port => 5602
  }
}

output {
  file {
    path => "E:\Logstash\logs.txt"
  }
}

Instead of seeing the logs.txt file populated, we are seeing these 4 lines in the debug output each time an event is sent over TCP:

[2018-03-29T09:32:03,783][DEBUG][logstash.codecs.line     ] config LogStash::Codecs::Line/@id = "line_dd3649e0-e8ea-4986-a849-4386ebc6e247"
[2018-03-29T09:32:03,783][DEBUG][logstash.codecs.line     ] config LogStash::Codecs::Line/@enable_metric = true
[2018-03-29T09:32:03,783][DEBUG][logstash.codecs.line     ] config LogStash::Codecs::Line/@charset = "UTF-8"
[2018-03-29T09:32:03,783][DEBUG][logstash.codecs.line     ] config LogStash::Codecs::Line/@delimiter = "\n"

We have verified the following:

We observe correct behavior when using stdin as input and stdout as output.
We observe correct behavior when using stdin as input and the "file" output plugin as output.
We observe the identical 4 lines when using the "TCP" input plugin as input and stdout as output.
We observe the correct TCP port binding when the process is run with the "TCP" input plugin.

Thank you for any help you can provide.

yaauie · March 29, 2018, 9:37pm

What version of Logstash?

bin/logstash --version

What version of logstash-input-tcp?

bin/logstash list --verbose logstash-input-tcp

Are there any other interesting entries in the logs?

How are you sending the events over TCP? Does it work if you use netcat to read the same file that works for the file input?

If the TCP connections each contain exactly one event, codec => plain may be a better match (the default is codec => lines, which only emits events each time a newline is reached or the connection closed and flushed).

tbugbee · March 30, 2018, 2:14pm

Hi,

Logstash is version 5.6.0.

Logstash-input-tcp is version 4.2.3.

The events are sent over TCP using NLog. A client service posts logs in formatted JSON to a centralized web server, which uses the NLog configuration to distribute these logs to several locations (SQL DB, ElasticSearch buffer, and now logstash). The logs are arriving correctly to ElasticSearch and the DB. We are using the NLog.targets.elasticsearch plugin for NLog, but no such plugin exists for Logstash.

(we are aware of the Lumberjack protocol for a generic NLog target but this does not fulfill our requirements)

I have attached the full logs at the debug level. Notice at line 97 that Logstash is automatically switching from the plain codec to the line codec (after detecting the tcp input plugin). Is there a way to force the plain codec?

FYI, elastic documentation for the tcp input plugin says that the default codec is "plain", which doesn't seem to be the case.

tbugbee · March 30, 2018, 4:30pm

Logs (part 1)

[2018-03-30T09:54:26,423][INFO ][logstash.modules.scaffold] Initializing module {:module_name=>"fb_apache", :directory=>"C:/Elk/logstash/modules/fb_apache/configuration"}
[2018-03-30T09:54:26,439][DEBUG][logstash.plugins.registry] Adding plugin to the registry {:name=>"fb_apache", :type=>:modules, :class=>#<LogStash::Modules::Scaffold:0x62e0f3d3 @kibana_version_parts=["5", "6", "0"], @module_name="fb_apache", @directory="C:/Elk/logstash/modules/fb_apache/configuration">}
[2018-03-30T09:54:26,455][INFO ][logstash.modules.scaffold] Initializing module {:module_name=>"netflow", :directory=>"C:/Elk/logstash/modules/netflow/configuration"}
[2018-03-30T09:54:26,455][DEBUG][logstash.plugins.registry] Adding plugin to the registry {:name=>"netflow", :type=>:modules, :class=>#<LogStash::Modules::Scaffold:0x663fe242 @kibana_version_parts=["5", "6", "0"], @module_name="netflow", @directory="C:/Elk/logstash/modules/netflow/configuration">}
[2018-03-30T09:54:26,533][DEBUG][logstash.runner          ] -------- Logstash Settings (* means modified) ---------
[2018-03-30T09:54:26,533][DEBUG][logstash.runner          ] node.name: "${HOSTNAME}"
[2018-03-30T09:54:26,548][DEBUG][logstash.runner          ] *path.config: ".\\logstash.conf"
[2018-03-30T09:54:26,548][DEBUG][logstash.runner          ] path.data: "C:/Elk/logstash/data"
[2018-03-30T09:54:26,548][DEBUG][logstash.runner          ] modules.cli: []
[2018-03-30T09:54:26,548][DEBUG][logstash.runner          ] modules: []
[2018-03-30T09:54:26,548][DEBUG][logstash.runner          ] modules_setup: false
[2018-03-30T09:54:26,564][DEBUG][logstash.runner          ] config.test_and_exit: false
[2018-03-30T09:54:26,564][DEBUG][logstash.runner          ] config.reload.automatic: false
[2018-03-30T09:54:26,564][DEBUG][logstash.runner          ] config.support_escapes: false
[2018-03-30T09:54:26,564][DEBUG][logstash.runner          ] config.reload.interval: 3
[2018-03-30T09:54:26,564][DEBUG][logstash.runner          ] metric.collect: true
[2018-03-30T09:54:26,580][DEBUG][logstash.runner          ] pipeline.id: "main"
[2018-03-30T09:54:26,580][DEBUG][logstash.runner          ] pipeline.system: false
[2018-03-30T09:54:26,580][DEBUG][logstash.runner          ] pipeline.workers: 2
[2018-03-30T09:54:26,580][DEBUG][logstash.runner          ] pipeline.output.workers: 1
[2018-03-30T09:54:26,580][DEBUG][logstash.runner          ] pipeline.batch.size: 125
[2018-03-30T09:54:26,580][DEBUG][logstash.runner          ] pipeline.batch.delay: 5
[2018-03-30T09:54:26,595][DEBUG][logstash.runner          ] pipeline.unsafe_shutdown: false
[2018-03-30T09:54:26,595][DEBUG][logstash.runner          ] path.plugins: []
[2018-03-30T09:54:26,595][DEBUG][logstash.runner          ] config.debug: false
[2018-03-30T09:54:26,595][DEBUG][logstash.runner          ] *log.level: "debug" (default: "info")
[2018-03-30T09:54:26,595][DEBUG][logstash.runner          ] version: false
[2018-03-30T09:54:26,595][DEBUG][logstash.runner          ] help: false
[2018-03-30T09:54:26,611][DEBUG][logstash.runner          ] log.format: "plain"
[2018-03-30T09:54:26,611][DEBUG][logstash.runner          ] http.host: "127.0.0.1"
[2018-03-30T09:54:26,611][DEBUG][logstash.runner          ] http.port: 9600..9700
[2018-03-30T09:54:26,611][DEBUG][logstash.runner          ] http.environment: "production"
[2018-03-30T09:54:26,611][DEBUG][logstash.runner          ] queue.type: "memory"
[2018-03-30T09:54:26,611][DEBUG][logstash.runner          ] queue.drain: false
[2018-03-30T09:54:26,611][DEBUG][logstash.runner          ] queue.page_capacity: 262144000
[2018-03-30T09:54:26,611][DEBUG][logstash.runner          ] queue.max_bytes: 1073741824
[2018-03-30T09:54:26,611][DEBUG][logstash.runner          ] queue.max_events: 0
[2018-03-30T09:54:26,611][DEBUG][logstash.runner          ] queue.checkpoint.acks: 1024
[2018-03-30T09:54:26,611][DEBUG][logstash.runner          ] queue.checkpoint.writes: 1024
[2018-03-30T09:54:26,642][DEBUG][logstash.runner          ] queue.checkpoint.interval: 1000
[2018-03-30T09:54:26,642][DEBUG][logstash.runner          ] dead_letter_queue.enable: false
[2018-03-30T09:54:26,642][DEBUG][logstash.runner          ] dead_letter_queue.max_bytes: 1073741824
[2018-03-30T09:54:26,658][DEBUG][logstash.runner          ] slowlog.threshold.warn: -1
[2018-03-30T09:54:26,673][DEBUG][logstash.runner          ] slowlog.threshold.info: -1
[2018-03-30T09:54:26,673][DEBUG][logstash.runner          ] slowlog.threshold.debug: -1
[2018-03-30T09:54:26,673][DEBUG][logstash.runner          ] slowlog.threshold.trace: -1
[2018-03-30T09:54:26,689][DEBUG][logstash.runner          ] path.queue: "C:/Elk/logstash/data/queue"
[2018-03-30T09:54:26,689][DEBUG][logstash.runner          ] path.dead_letter_queue: "C:/Elk/logstash/data/dead_letter_queue"
[2018-03-30T09:54:26,689][DEBUG][logstash.runner          ] path.settings: "C:/Elk/logstash/config"
[2018-03-30T09:54:26,689][DEBUG][logstash.runner          ] path.logs: "C:/Elk/logstash/logs"

tbugbee · March 30, 2018, 4:31pm

Logs (part 2)

[2018-03-30T09:54:26,689][DEBUG][logstash.runner          ] --------------- Logstash Settings -------------------
[2018-03-30T09:54:26,783][DEBUG][logstash.agent           ] Agent: Configuring metric collection
[2018-03-30T09:54:26,783][DEBUG][logstash.instrument.periodicpoller.os] PeriodicPoller: Starting {:polling_interval=>5, :polling_timeout=>120}
[2018-03-30T09:54:26,861][DEBUG][logstash.instrument.periodicpoller.jvm] PeriodicPoller: Starting {:polling_interval=>5, :polling_timeout=>120}
[2018-03-30T09:54:26,955][DEBUG][logstash.instrument.periodicpoller.persistentqueue] PeriodicPoller: Starting {:polling_interval=>5, :polling_timeout=>120}
[2018-03-30T09:54:26,986][DEBUG][logstash.instrument.periodicpoller.deadletterqueue] PeriodicPoller: Starting {:polling_interval=>5, :polling_timeout=>120}
[2018-03-30T09:54:27,017][DEBUG][logstash.agent           ] Reading config file {:config_file=>"C:/Elk/logstash/bin/logstash.conf"}
[2018-03-30T09:54:27,345][DEBUG][logstash.plugins.registry] On demand adding plugin to the registry {:name=>"tcp", :type=>"input", :class=>LogStash::Inputs::Tcp}
[2018-03-30T09:54:27,502][DEBUG][logstash.plugins.registry] On demand adding plugin to the registry {:name=>"plain", :type=>"codec", :class=>LogStash::Codecs::Plain}
[2018-03-30T09:54:27,517][DEBUG][logstash.codecs.plain    ] config LogStash::Codecs::Plain/@id = "plain_6eb5cc2c-d66c-40bc-9329-846a365429de"
[2018-03-30T09:54:27,533][DEBUG][logstash.codecs.plain    ] config LogStash::Codecs::Plain/@enable_metric = true
[2018-03-30T09:54:27,533][DEBUG][logstash.codecs.plain    ] config LogStash::Codecs::Plain/@charset = "UTF-8"
[2018-03-30T09:54:27,533][DEBUG][logstash.inputs.tcp      ] config LogStash::Inputs::Tcp/@port = 5602
[2018-03-30T09:54:27,548][DEBUG][logstash.inputs.tcp      ] config LogStash::Inputs::Tcp/@codec = <LogStash::Codecs::Plain id=>"plain_6eb5cc2c-d66c-40bc-9329-846a365429de", enable_metric=>true, charset=>"UTF-8">
[2018-03-30T09:54:27,548][DEBUG][logstash.inputs.tcp      ] config LogStash::Inputs::Tcp/@id = "d7492f4627404a1e83db0eca753c38812abe558c-1"
[2018-03-30T09:54:27,565][DEBUG][logstash.inputs.tcp      ] config LogStash::Inputs::Tcp/@enable_metric = true
[2018-03-30T09:54:27,565][DEBUG][logstash.inputs.tcp      ] config LogStash::Inputs::Tcp/@add_field = {}
[2018-03-30T09:54:27,565][DEBUG][logstash.inputs.tcp      ] config LogStash::Inputs::Tcp/@host = "0.0.0.0"
[2018-03-30T09:54:27,580][DEBUG][logstash.inputs.tcp      ] config LogStash::Inputs::Tcp/@data_timeout = -1
[2018-03-30T09:54:27,580][DEBUG][logstash.inputs.tcp      ] config LogStash::Inputs::Tcp/@mode = "server"
[2018-03-30T09:54:27,580][DEBUG][logstash.inputs.tcp      ] config LogStash::Inputs::Tcp/@proxy_protocol = false
[2018-03-30T09:54:27,580][DEBUG][logstash.inputs.tcp      ] config LogStash::Inputs::Tcp/@ssl_enable = false
[2018-03-30T09:54:27,580][DEBUG][logstash.inputs.tcp      ] config LogStash::Inputs::Tcp/@ssl_verify = true
[2018-03-30T09:54:27,595][DEBUG][logstash.inputs.tcp      ] config LogStash::Inputs::Tcp/@ssl_key_passphrase = <password>
[2018-03-30T09:54:27,595][DEBUG][logstash.inputs.tcp      ] config LogStash::Inputs::Tcp/@ssl_extra_chain_certs = []
[2018-03-30T09:54:27,642][DEBUG][logstash.plugins.registry] On demand adding plugin to the registry {:name=>"file", :type=>"output", :class=>LogStash::Outputs::File}
[2018-03-30T09:54:27,752][DEBUG][logstash.plugins.registry] On demand adding plugin to the registry {:name=>"json_lines", :type=>"codec", :class=>LogStash::Codecs::JSONLines}
[2018-03-30T09:54:27,767][DEBUG][logstash.codecs.jsonlines] config LogStash::Codecs::JSONLines/@id = "json_lines_b66d9848-dc41-47c4-8b9a-06a0d4610493"
[2018-03-30T09:54:27,767][DEBUG][logstash.codecs.jsonlines] config LogStash::Codecs::JSONLines/@enable_metric = true
[2018-03-30T09:54:27,783][DEBUG][logstash.codecs.jsonlines] config LogStash::Codecs::JSONLines/@charset = "UTF-8"
[2018-03-30T09:54:27,783][DEBUG][logstash.codecs.jsonlines] config LogStash::Codecs::JSONLines/@delimiter = "\n"
[2018-03-30T09:54:27,783][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@path = "E:\\Logstash\\logs.txt"
[2018-03-30T09:54:27,798][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@id = "d7492f4627404a1e83db0eca753c38812abe558c-2"
[2018-03-30T09:54:27,830][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@enable_metric = true
[2018-03-30T09:54:27,830][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@codec = <LogStash::Codecs::JSONLines id=>"json_lines_b66d9848-dc41-47c4-8b9a-06a0d4610493", enable_metric=>true, charset=>"UTF-8", delimiter=>"\n">
[2018-03-30T09:54:27,830][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@workers = 1
[2018-03-30T09:54:27,830][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@flush_interval = 2
[2018-03-30T09:54:27,830][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@gzip = false
[2018-03-30T09:54:27,845][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@filename_failure = "_filepath_failures"
[2018-03-30T09:54:27,845][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@create_if_deleted = true
[2018-03-30T09:54:27,861][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@dir_mode = -1
[2018-03-30T09:54:27,861][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@file_mode = -1

tbugbee · March 30, 2018, 4:32pm

Logs (part 3)

[2018-03-30T09:54:27,923][DEBUG][logstash.agent           ] starting agent
[2018-03-30T09:54:27,939][DEBUG][logstash.agent           ] starting pipeline {:id=>"main"}
[2018-03-30T09:54:27,955][INFO ][logstash.pipeline        ] Starting pipeline {"id"=>"main", "pipeline.workers"=>2, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>5, "pipeline.max_inflight"=>250}
[2018-03-30T09:54:28,080][INFO ][logstash.inputs.tcp      ] Automatically switching from plain to line codec {:plugin=>"tcp"}
[2018-03-30T09:54:28,111][DEBUG][logstash.codecs.line     ] config LogStash::Codecs::Line/@charset = "UTF-8"
[2018-03-30T09:54:28,111][DEBUG][logstash.codecs.line     ] config LogStash::Codecs::Line/@id = "line_16016713-9079-408a-81c3-e20db723d78e"
[2018-03-30T09:54:28,111][DEBUG][logstash.codecs.line     ] config LogStash::Codecs::Line/@enable_metric = true
[2018-03-30T09:54:28,127][DEBUG][logstash.codecs.line     ] config LogStash::Codecs::Line/@delimiter = "\n"
[2018-03-30T09:54:28,877][INFO ][logstash.pipeline        ] Pipeline main started
[2018-03-30T09:54:29,002][DEBUG][logstash.agent           ] Starting puma
[2018-03-30T09:54:29,033][DEBUG][logstash.agent           ] Trying to start WebServer {:port=>9600}
[2018-03-30T09:54:29,033][DEBUG][logstash.api.service     ] [api-service] start
[2018-03-30T09:54:29,439][INFO ][logstash.agent           ] Successfully started Logstash API endpoint {:port=>9600}
[2018-03-30T09:54:33,893][DEBUG][logstash.pipeline        ] Pushing flush onto pipeline
[2018-03-30T09:54:38,893][DEBUG][logstash.pipeline        ] Pushing flush onto pipeline
[2018-03-30T09:54:43,893][DEBUG][logstash.pipeline        ] Pushing flush onto pipeline
[2018-03-30T09:54:48,894][DEBUG][logstash.pipeline        ] Pushing flush onto pipeline
[2018-03-30T09:54:51,300][DEBUG][logstash.codecs.line     ] config LogStash::Codecs::Line/@charset = "UTF-8"
[2018-03-30T09:54:51,300][DEBUG][logstash.codecs.line     ] config LogStash::Codecs::Line/@id = "line_16016713-9079-408a-81c3-e20db723d78e"
[2018-03-30T09:54:51,316][DEBUG][logstash.codecs.line     ] config LogStash::Codecs::Line/@enable_metric = true
[2018-03-30T09:54:51,316][DEBUG][logstash.codecs.line     ] config LogStash::Codecs::Line/@delimiter = "\n"
[2018-03-30T09:54:53,894][DEBUG][logstash.pipeline        ] Pushing flush onto pipeline
[2018-03-30T09:54:58,910][DEBUG][logstash.pipeline        ] Pushing flush onto pipeline
[2018-03-30T09:55:03,942][DEBUG][logstash.pipeline        ] Pushing flush onto pipeline
[2018-03-30T09:55:08,942][DEBUG][logstash.pipeline        ] Pushing flush onto pipeline
[2018-03-30T09:55:12,520][WARN ][logstash.runner          ] SIGINT received. Shutting down the agent.
[2018-03-30T09:55:12,520][DEBUG][logstash.instrument.periodicpoller.os] PeriodicPoller: Stopping
[2018-03-30T09:55:12,536][DEBUG][logstash.instrument.periodicpoller.jvm] PeriodicPoller: Stopping
[2018-03-30T09:55:12,536][DEBUG][logstash.instrument.periodicpoller.persistentqueue] PeriodicPoller: Stopping
[2018-03-30T09:55:12,536][DEBUG][logstash.instrument.periodicpoller.deadletterqueue] PeriodicPoller: Stopping
[2018-03-30T09:55:12,552][WARN ][logstash.agent           ] stopping pipeline {:id=>"main"}
[2018-03-30T09:55:12,567][DEBUG][logstash.pipeline        ] Closing inputs
[2018-03-30T09:55:12,567][DEBUG][logstash.inputs.tcp      ] stopping {:plugin=>"LogStash::Inputs::Tcp"}
[2018-03-30T09:55:13,942][DEBUG][logstash.pipeline        ] Pushing flush onto pipeline
[2018-03-30T09:55:14,834][DEBUG][logstash.inputs.tcp      ] closing {:plugin=>"LogStash::Inputs::Tcp"}
[2018-03-30T09:55:16,958][DEBUG][logstash.pipeline        ] Input plugins stopped! Will shutdown filter/output workers.
[2018-03-30T09:55:16,974][DEBUG][logstash.pipeline        ] Closed inputs
[2018-03-30T09:55:17,021][DEBUG][logstash.pipeline        ] Pushing flush onto pipeline
[2018-03-30T09:55:17,021][DEBUG][logstash.pipeline        ] Pushing shutdown {:thread=>"#<Thread:0x4df8a023 sleep>"}
[2018-03-30T09:55:17,036][DEBUG][logstash.pipeline        ] Pushing shutdown {:thread=>"#<Thread:0x16d786 run>"}
[2018-03-30T09:55:17,036][DEBUG][logstash.pipeline        ] Shutdown waiting for worker thread #<Thread:0x4df8a023>
[2018-03-30T09:55:17,099][DEBUG][logstash.pipeline        ] Shutdown waiting for worker thread #<Thread:0x16d786>
[2018-03-30T09:55:17,099][DEBUG][logstash.outputs.file    ] closing {:plugin=>"LogStash::Outputs::File"}
[2018-03-30T09:55:17,099][DEBUG][logstash.outputs.file    ] Close: closing files
[2018-03-30T09:55:17,114][DEBUG][logstash.pipeline        ] Pipeline main has been shutdown

system · April 27, 2018, 4:33pm

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.