[TS-4165] Logging breaks if changing log format

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 6.1.1, 6.2.0
• Component/s: Logging
• Labels: regression
• Assignee: Daniel Xu
• Reporter: Eric Sproul
• Created: 29/Jan/16 19:01
• Updated: 19/Jul/16 20:16
• Resolved: 01/Feb/16 20:37

Description

When upgrading to 6.1.0 from 5.3.2, I was also changing the format of a custom log, and that apparently caused all request logging to stop. In syslog I see this error:

 {0x1} ERROR: <LogObject.cc:1035 (_solve_filename_conflicts)> Cannot roll log file /var/log/circonus/trafficserver/request.blog to fix log filename conflicts

Worked with folks on IRC, and ran under gdb, setting a breakpoint at BaseLogFile::roll and stepping through 3 times subsequently, before taking a backtrace:

(gdb) bt
#0  BaseLogFile::roll (this=0x57f7550, interval_start=<optimized out>, interval_end=<optimized out>) at BaseLogFile.cc:119
#1  0x00000000006ebee0 in LogObjectManager::_solve_filename_conflicts (this=this@entry=0x36b9df8, log_object=log_object@entry=0xf17a90, 
    maxConflicts=maxConflicts@entry=99) at LogObject.cc:1029
#2  0x00000000006ec619 in LogObjectManager::_manage_object (this=0x36b9df8, log_object=0xf17a90, is_api_object=false, maxConflicts=99)
    at LogObject.cc:894
#3  0x00000000006db8db in manage_object (maxConflicts=99, logObject=0xf17a90, this=0x36b9df8) at LogObject.h:394
#4  LogConfig::read_xml_log_config (this=this@entry=0x36b9dd0) at LogConfig.cc:1468
#5  0x00000000006dda70 in setup_log_objects (this=0x36b9dd0) at LogConfig.cc:503
#6  LogConfig::init (this=0x36b9dd0, prev_config=0x0) at LogConfig.cc:388
#7  0x0000000000815bcd in main ()

(gdb) print *this
$1 = {m_fp = 0x0, m_start_time = 1454090917, m_end_time = 0, m_bytes_written = 0, m_signature = 0, m_has_signature = true, 
  m_name = {<ats_scoped_resource<detail::SCOPED_MALLOC_TRAITS<char> >> = {
      _r = 0x5809950 "/var/log/circonus/trafficserver/request.blog"}, <No data fields>}, 
  m_hostname = {<ats_scoped_resource<detail::SCOPED_MALLOC_TRAITS<char> >> = {_r = 0x10fa238 "lbva1"}, <No data fields>}, m_is_regfile = false, 
  m_is_init = false, m_meta_info = 0x0}

amc pointed out that m_is_regfile is false and that m_fp is null, and speculates that ATS might be assuming the file is open when it is not, and failing to roll the file. The one case where we would try to roll the files without them being open is when the log format is changing.