Explicitate the type of log format in appender's names (elastic#12964)

Remove an useful dynamic creation of appender's log file which leverages the `log.format` property 
also when it's explicit by the appender itself.

Log4j configuration leverages the placeholder `${sys:ls.log.format}` to compose the name of the log file.
This generates some not evident conflicts in log4j internals, these conflicts became evident when enabling the `pipeline.separate_logs` feature is enabled and the log4j appender definitions contains both json and plain format.
The problem is that under those circumstances the rollover of the log file doesn't happen.

This commit also add a test against the production log4j configuration, to avoid future regressions.

.gitignore

@@ -60,4 +60,5 @@ html_docs
 lib/pluginmanager/plugin_aliases.yml
 logstash-core/src/main/resources/org/logstash/plugins/plugin_aliases.yml
 spec/unit/plugin_manager/plugin_aliases.yml
-logstash-core/src/test/resources/org/logstash/plugins/plugin_aliases.yml 
+logstash-core/src/test/resources/org/logstash/plugins/plugin_aliases.yml
+qa/integration/fixtures/logs_rollover/log4j2.properties

config/log4j2.properties

@@ -14,8 +14,8 @@ appender.json_console.layout.eventEol = true
 
 appender.rolling.type = RollingFile
 appender.rolling.name = plain_rolling
-appender.rolling.fileName = ${sys:ls.logs}/logstash-${sys:ls.log.format}.log
-appender.rolling.filePattern = ${sys:ls.logs}/logstash-${sys:ls.log.format}-%d{yyyy-MM-dd}-%i.log.gz
+appender.rolling.fileName = ${sys:ls.logs}/logstash-plain.log
+appender.rolling.filePattern = ${sys:ls.logs}/logstash-plain-%d{yyyy-MM-dd}-%i.log.gz
 appender.rolling.policies.type = Policies
 appender.rolling.policies.time.type = TimeBasedTriggeringPolicy
 appender.rolling.policies.time.interval = 1
@@ -30,8 +30,8 @@ appender.rolling.avoid_pipelined_filter.type = PipelineRoutingFilter
 
 appender.json_rolling.type = RollingFile
 appender.json_rolling.name = json_rolling
-appender.json_rolling.fileName = ${sys:ls.logs}/logstash-${sys:ls.log.format}.log
-appender.json_rolling.filePattern = ${sys:ls.logs}/logstash-${sys:ls.log.format}-%d{yyyy-MM-dd}-%i.log.gz
+appender.json_rolling.fileName = ${sys:ls.logs}/logstash-json.log
+appender.json_rolling.filePattern = ${sys:ls.logs}/logstash-json-%d{yyyy-MM-dd}-%i.log.gz
 appender.json_rolling.policies.type = Policies
 appender.json_rolling.policies.time.type = TimeBasedTriggeringPolicy
 appender.json_rolling.policies.time.interval = 1
@@ -78,8 +78,8 @@ appender.json_console_slowlog.layout.eventEol = true
 
 appender.rolling_slowlog.type = RollingFile
 appender.rolling_slowlog.name = plain_rolling_slowlog
-appender.rolling_slowlog.fileName = ${sys:ls.logs}/logstash-slowlog-${sys:ls.log.format}.log
-appender.rolling_slowlog.filePattern = ${sys:ls.logs}/logstash-slowlog-${sys:ls.log.format}-%d{yyyy-MM-dd}-%i.log.gz
+appender.rolling_slowlog.fileName = ${sys:ls.logs}/logstash-slowlog-plain.log
+appender.rolling_slowlog.filePattern = ${sys:ls.logs}/logstash-slowlog-plain-%d{yyyy-MM-dd}-%i.log.gz
 appender.rolling_slowlog.policies.type = Policies
 appender.rolling_slowlog.policies.time.type = TimeBasedTriggeringPolicy
 appender.rolling_slowlog.policies.time.interval = 1
@@ -93,8 +93,8 @@ appender.rolling_slowlog.strategy.max = 30
 
 appender.json_rolling_slowlog.type = RollingFile
 appender.json_rolling_slowlog.name = json_rolling_slowlog
-appender.json_rolling_slowlog.fileName = ${sys:ls.logs}/logstash-slowlog-${sys:ls.log.format}.log
-appender.json_rolling_slowlog.filePattern = ${sys:ls.logs}/logstash-slowlog-${sys:ls.log.format}-%d{yyyy-MM-dd}-%i.log.gz
+appender.json_rolling_slowlog.fileName = ${sys:ls.logs}/logstash-slowlog-json.log
+appender.json_rolling_slowlog.filePattern = ${sys:ls.logs}/logstash-slowlog-json-%d{yyyy-MM-dd}-%i.log.gz
 appender.json_rolling_slowlog.policies.type = Policies
 appender.json_rolling_slowlog.policies.time.type = TimeBasedTriggeringPolicy
 appender.json_rolling_slowlog.policies.time.interval = 1

logstash-core/benchmarks/src/main/resources/log4j2-with-script.properties

@@ -3,8 +3,8 @@ name = LogstashPropertiesConfig
 
 appender.rolling.type = RollingFile
 appender.rolling.name = plain_rolling
-appender.rolling.fileName = ${sys:ls.logs}/logstash-${sys:ls.log.format}.log
-appender.rolling.filePattern = ${sys:ls.logs}/logstash-${sys:ls.log.format}-%d{yyyy-MM-dd}-%i.log.gz
+appender.rolling.fileName = ${sys:ls.logs}/logstash-plain.log
+appender.rolling.filePattern = ${sys:ls.logs}/logstash-plain-%d{yyyy-MM-dd}-%i.log.gz
 appender.rolling.policies.type = Policies
 appender.rolling.policies.time.type = TimeBasedTriggeringPolicy
 appender.rolling.policies.time.interval = 1

logstash-core/benchmarks/src/main/resources/log4j2-without-script.properties

@@ -3,8 +3,8 @@ name = LogstashPropertiesConfig
 
 appender.rolling.type = RollingFile
 appender.rolling.name = plain_rolling
-appender.rolling.fileName = ${sys:ls.logs}/logstash-${sys:ls.log.format}.log
-appender.rolling.filePattern = ${sys:ls.logs}/logstash-${sys:ls.log.format}-%d{yyyy-MM-dd}-%i.log.gz
+appender.rolling.fileName = ${sys:ls.logs}/logstash-plain.log
+appender.rolling.filePattern = ${sys:ls.logs}/logstash-plain-%d{yyyy-MM-dd}-%i.log.gz
 appender.rolling.policies.type = Policies
 appender.rolling.policies.time.type = TimeBasedTriggeringPolicy
 appender.rolling.policies.time.interval = 1

logstash-core/src/test/resources/log4j2-log-pipeline-test.properties

@@ -3,8 +3,8 @@ name = LogstashPropertiesConfig
 
 appender.rolling.type = RollingFile
 appender.rolling.name = plain_rolling
-appender.rolling.fileName = ${sys:ls.logs}/logstash-${sys:ls.log.format}.log
-appender.rolling.filePattern = ${sys:ls.logs}/logstash-${sys:ls.log.format}-%d{yyyy-MM-dd}-%i.log.gz
+appender.rolling.fileName = ${sys:ls.logs}/logstash-plain.log
+appender.rolling.filePattern = ${sys:ls.logs}/logstash-plain-%d{yyyy-MM-dd}-%i.log.gz
 appender.rolling.policies.type = Policies
 appender.rolling.policies.time.type = TimeBasedTriggeringPolicy
 appender.rolling.policies.time.interval = 1

qa/integration/build.gradle

@@ -39,7 +39,28 @@ test {
   exclude '/**'
 }
 
+tasks.register("copyProductionLog4jConfiguration", Copy) {
+  description "Copy the production log4j config to be tested in QA (qa/integration/fixtures/logs_rollover)"
+
+  from "${projectDir}/../../config/log4j2.properties"
+  into "${projectDir}/fixtures/logs_rollover/"
+  filter {
+    // modify rollover policy to make it happen in integration test without need to generate tons of log lines
+    line -> line
+            .replace('appender.rolling.policies.size.size = 100MB',
+                    'appender.rolling.policies.size.size = 1KB')
+            .replace('appender.rolling.filePattern = ${sys:ls.logs}/logstash-plain-%d{yyyy-MM-dd}-%i.log.gz',
+                    'appender.rolling.filePattern = ${sys:ls.logs}/logstash-plain-%d{yyyy-MM-dd}.log')
+  }
+}
+
+clean {
+  delete "${projectDir}/fixtures/logs_rollover/log4j2.properties"
+}
+
 tasks.register("integrationTests", Test) {
+  dependsOn "copyProductionLog4jConfiguration"
+
   inputs.files fileTree("${projectDir}/services")
   inputs.files fileTree("${projectDir}/framework")
   inputs.files fileTree("${projectDir}/fixtures")

qa/integration/fixtures/persistent_queues/log4j2.properties

@@ -14,8 +14,8 @@ appender.json_console.layout.eventEol = true
 
 appender.rolling.type = RollingFile
 appender.rolling.name = plain_rolling
-appender.rolling.fileName = ${sys:ls.logs}/logstash-${sys:ls.log.format}.log
-appender.rolling.filePattern = ${sys:ls.logs}/logstash-${sys:ls.log.format}-%d{yyyy-MM-dd}.log
+appender.rolling.fileName = ${sys:ls.logs}/logstash-plain.log
+appender.rolling.filePattern = ${sys:ls.logs}/logstash-plain-%d{yyyy-MM-dd}.log
 appender.rolling.policies.type = Policies
 appender.rolling.policies.time.type = TimeBasedTriggeringPolicy
 appender.rolling.policies.time.interval = 1
@@ -30,8 +30,8 @@ appender.rolling.avoid_pipelined_filter.type = PipelineRoutingFilter
 
 appender.json_rolling.type = RollingFile
 appender.json_rolling.name = json_rolling
-appender.json_rolling.fileName = ${sys:ls.logs}/logstash-${sys:ls.log.format}.log
-appender.json_rolling.filePattern = ${sys:ls.logs}/logstash-${sys:ls.log.format}-%d{yyyy-MM-dd}.log
+appender.json_rolling.fileName = ${sys:ls.logs}/logstash-json.log
+appender.json_rolling.filePattern = ${sys:ls.logs}/logstash-json-%d{yyyy-MM-dd}.log
 appender.json_rolling.policies.type = Policies
 appender.json_rolling.policies.time.type = TimeBasedTriggeringPolicy
 appender.json_rolling.policies.time.interval = 1
@@ -78,8 +78,8 @@ appender.json_console_slowlog.layout.eventEol = true
 
 appender.rolling_slowlog.type = RollingFile
 appender.rolling_slowlog.name = plain_rolling_slowlog
-appender.rolling_slowlog.fileName = ${sys:ls.logs}/logstash-slowlog-${sys:ls.log.format}.log
-appender.rolling_slowlog.filePattern = ${sys:ls.logs}/logstash-slowlog-${sys:ls.log.format}-%d{yyyy-MM-dd}.log
+appender.rolling_slowlog.fileName = ${sys:ls.logs}/logstash-slowlog-plain.log
+appender.rolling_slowlog.filePattern = ${sys:ls.logs}/logstash-slowlog-plain-%d{yyyy-MM-dd}.log
 appender.rolling_slowlog.policies.type = Policies
 appender.rolling_slowlog.policies.time.type = TimeBasedTriggeringPolicy
 appender.rolling_slowlog.policies.time.interval = 1
@@ -89,8 +89,8 @@ appender.rolling_slowlog.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %m%n
 
 appender.json_rolling_slowlog.type = RollingFile
 appender.json_rolling_slowlog.name = json_rolling_slowlog
-appender.json_rolling_slowlog.fileName = ${sys:ls.logs}/logstash-slowlog-${sys:ls.log.format}.log
-appender.json_rolling_slowlog.filePattern = ${sys:ls.logs}/logstash-slowlog-${sys:ls.log.format}-%d{yyyy-MM-dd}.log
+appender.json_rolling_slowlog.fileName = ${sys:ls.logs}/logstash-slowlog-json.log
+appender.json_rolling_slowlog.filePattern = ${sys:ls.logs}/logstash-slowlog-json-%d{yyyy-MM-dd}.log
 appender.json_rolling_slowlog.policies.type = Policies
 appender.json_rolling_slowlog.policies.time.type = TimeBasedTriggeringPolicy
 appender.json_rolling_slowlog.policies.time.interval = 1

qa/integration/specs/pipeline_log_spec.rb

@@ -21,6 +21,7 @@
 require_relative '../framework/helpers'
 require "logstash/devutils/rspec/spec_helper"
 require "yaml"
+require "fileutils"
 
 describe "Test Logstash Pipeline id" do
   before(:all) {
@@ -56,7 +57,7 @@
     }
     IO.write(@ls.application_settings_file, settings.to_yaml)
     @ls.spawn_logstash("-w", "1" , "-e", config)
-    wait_logstash_process_terminate()
+    wait_logstash_process_terminate(@ls)
     plainlog_file = "#{temp_dir}/logstash-plain.log"
     expect(File.exists?(plainlog_file)).to be true
     expect(IO.read(plainlog_file) =~ /\[logstash.javapipeline\s*\]\[#{pipeline_name}\]/).to be > 0
@@ -70,7 +71,7 @@
     }
     IO.write(@ls.application_settings_file, settings.to_yaml)
     @ls.spawn_logstash("-w", "1" , "-e", config)
-    wait_logstash_process_terminate()
+    wait_logstash_process_terminate(@ls)
     plainlog_file = "#{temp_dir}/logstash-plain.log"
     expect(File.exists?(plainlog_file)).to be true
     expect(IO.read(plainlog_file) =~ /Starting pipeline.*"pipeline.sources"=>\["config string"\]/).to be > 0
@@ -84,7 +85,7 @@
     }
     IO.write(@ls.application_settings_file, settings.to_yaml)
     @ls.spawn_logstash("-w", "1", "-f", "#{initial_config_file}")
-    wait_logstash_process_terminate()
+    wait_logstash_process_terminate(@ls)
     plainlog_file = "#{temp_dir}/logstash-plain.log"
     expect(File.exists?(plainlog_file)).to be true
     expect(IO.read(plainlog_file) =~ /Starting pipeline.*"pipeline.sources"=>\["#{initial_config_file}"\]/).to be > 0
@@ -99,7 +100,7 @@
     }
     IO.write(@ls.application_settings_file, settings.to_yaml)
     @ls.spawn_logstash("-w", "1" , "-e", config)
-    wait_logstash_process_terminate()
+    wait_logstash_process_terminate(@ls)
 
     pipeline_log_file = "#{temp_dir}/pipeline_#{pipeline_name}.log"
     expect(File.exists?(pipeline_log_file)).to be true
@@ -108,8 +109,37 @@
 
     plainlog_file = "#{temp_dir}/logstash-plain.log"
     expect(File.exists?(plainlog_file)).to be true
-    plaing_log_content = IO.read(plainlog_file)
-    expect(plaing_log_content =~ /Pipeline started {"pipeline.id"=>"#{pipeline_name}"}/).to be_nil
+    plainlog_content = IO.read(plainlog_file)
+    expect(plainlog_content =~ /Pipeline started {"pipeline.id"=>"#{pipeline_name}"}/).to be_nil
+  end
+
+  it "should rollover main log file when pipeline.separate_logs is enabled" do
+    pipeline_name = "custom_pipeline"
+    settings = {
+      "path.logs" => temp_dir,
+      "pipeline.id" => pipeline_name,
+      "pipeline.separate_logs" => true
+    }
+    FileUtils.mkdir_p(File.join(temp_dir, "data"))
+    data = File.join(temp_dir, "data")
+    settings = settings.merge({ "path.data" => data })
+    IO.write(File.join(temp_dir, "logstash.yml"), YAML.dump(settings))
+
+    log_definition = File.read('fixtures/logs_rollover/log4j2.properties')
+    expect(log_definition).to match(/appender\.rolling\.policies\.size\.size\s*=\s*1KB/)
+    expect(log_definition).to match(/appender\.rolling\.filePattern\s*=\s*.*\/logstash-plain-%d{yyyy-MM-dd}\.log/)
+    FileUtils.cp("fixtures/logs_rollover/log4j2.properties", temp_dir)
+
+    @ls.spawn_logstash("--path.settings", temp_dir, "-w", "1" , "-e", config)
+    wait_logstash_process_terminate(@ls)
+
+    logstash_logs = Dir.glob("logstash-plain*.log", base: temp_dir)
+    expect(logstash_logs.size).to eq(2)
+    logstash_logs.each do |filename|
+      file_size = File.size(File.join(temp_dir, filename))
+      # should be 1KB = 1024 but due to end of line rounding the rollover goes a little bit over
+      expect(file_size).to be < 1300
+    end
   end
 
   it "should not create separate pipelines log files if not enabled" do
@@ -121,7 +151,7 @@
     }
     IO.write(@ls.application_settings_file, settings.to_yaml)
     @ls.spawn_logstash("-w", "1" , "-e", config)
-    wait_logstash_process_terminate()
+    wait_logstash_process_terminate(@ls)
 
     pipeline_log_file = "#{temp_dir}/pipeline_#{pipeline_name}.log"
     expect(File.exists?(pipeline_log_file)).to be false
@@ -132,12 +162,11 @@
     expect(plaing_log_content =~ /Pipeline started {"pipeline.id"=>"#{pipeline_name}"}/).to be > 0
   end
 
-  @private
-  def wait_logstash_process_terminate
+  def wait_logstash_process_terminate(service)
     num_retries = 100
     try(num_retries) do
-      expect(@ls.exited?).to be(true)
+      expect(service.exited?).to be(true)
     end
-    expect(@ls.exit_code).to be >= 0
+    expect(service.exit_code).to be >= 0
   end
 end