http://coldfusion.com logo
Join Slack
Powered by
Having an issue with log levels in a logbox setup ...
# box-products
b
Having an issue with log levels in a logbox setup and hoping someone more familiar with it can tell me where I might be going wrong. Details in the thread
I have this appender (which works) for logging to the database.
Copy code
...
dbLogger      : {
 class      : "DBAppender",
 properties : {
  dsn               : "localdev_testdb_001",
  schema            : "Audit",
  table             : "DiagnosticLogs",
  autocreate        : false,
  async             : true,
  rotationFrequency : 60,
  rotationDays      : 90,
  columnMap         : {
   "id"           : "Guid",
   "severity"     : "LogLevel",
   "category"     : "LogSource",
   "logdate"      : "DateCreated",
   "appendername" : "Logger",
   "extrainfo"    : "Details"
  }
 }
},
...
And the root logger is configured as such in /app/config/ColdBox.cfc
Copy code
root : {
 levelMin  : 0,
 levelMax  : 3,
 appenders : "coldboxTracer,dbLogger,fileLogger"
},
Now, if I inject logbox using
Copy code
property name="log" inject="logbox:logger:{this}" and I dump that property)
and then dump( log ), the min log level is 0 and the max is 4. Which means all of my if( log.canDebug() ) log.debug( ... ) calls always run. Any ideas where things might be going wrong?
w
is this all the config you have or are you also using implicit categories in some place?
b
I do have a category configured for all the coldbox info logs. I will grab the whole thing. once sec.
Copy code
logBox = {
 // Define Appenders
 appenders : {
  coldboxTracer : { class : "coldbox.system.logging.appenders.ConsoleAppender" },

  dbLogger      : {
   class      : "DBAppender",
   properties : {
    dsn               : "localdev_testdb_001",
    schema            : "Audit",
    table             : "DiagnosticLogs",
    autocreate        : false,
    async             : true,
    rotationFrequency : 60,
    rotationDays      : 90,
    columnMap         : {
     "id"           : "Guid",
     "severity"     : "LogLevel",
     "category"     : "LogSource",
     "logdate"      : "DateCreated",
     "appendername" : "Logger",
     "extrainfo"    : "Details"
    }
   }
  },
  fileLogger : {
   class      : "RollingFileAppender",
   properties : {
    filePath        : getSystemSetting( "LOG_FILE_ROOT", "../logs" ),
    fileName        : "logbox",
    autoExpand      : true,
    fileMaxSize     : 2000,
    fileMaxArchives : 5
   }
  },
  coldBoxInfoLogger : {
   class      : "RollingFileAppender",
   properties : {
    filePath        : getSystemSetting( "LOG_FILE_ROOT", "../logs" ),
    fileName        : "logbox_coldbox",
    autoExpand      : true,
    fileMaxSize     : 2000,
    fileMaxArchives : 5
   }
  }
 },
 // Root Logger - If no category matches the log, it falls back on the catch-all root configuration and routes it to all configured appenders
 root : {
  levelMin  : 0,
  levelMax  : 3,
  appenders : "coldboxTracer,dbLogger,fileLogger"
 },
 categories : {
  "coldbox.system" : {
   appenders : "coldBoxInfoLogger",
   levelMin  : 3,
   levelMax  : 3
  }
 }
};
the only thing I've changed in the above was to hardcode the levelMin and levelMax values while trying to figure this out
also, thanks for your blog post(s) on the topic. It was a big help for a first time logboxer
w
as far as I can see here you should never have a DEBUG level. I don’t see the problem yet
so no implicit categories like this at all: 
// silence model.class, model2.class2
off   = ["model.class", "model2.class2"],
// make myNewModule and qb very chatty
debug = ["myNewModule","qb"]
b
Nope, nothing beyond the above
w
Sorry, I don’t see it yet.
I’ll have a closer look later today, time for dinner now.
b
No worries. thanks for looking
a tiny bit more info... given these two properties in any given component...
Copy code
property name="wirebox" inject="wirebox";
property name="log"     inject="logbox:logger:{this}";
dump( log ) always appears to be a new logger instance with none of my settings (including no appenders... even though the dbAppender clearing logs to the db fine) with a default levelMin of 0 and levelMax 4 dump( wirebox.getLog() ) however is getting its levelMin and levelMax values from the coldbox.system category in my config (which are both set to 3). I can changes those values and confirm they update. appenders is an empty struct in both dumps
w
What happens if you rename your property log to myLog? Log is already a preconfigured name in coldbox https://logbox.ortusbooks.com/usage/logbox-in-a-coldbox-application/configuration-within-coldbox
b
that doesn't seem to make a difference
I spun up a new coldbox rest-hmvc and used the same logBox config there and it is working as expected (same coldbox version and build)
So clearly I (or someone) has screwed it up somewhere in between config and inject
I vote me
w
That’s weird. Any other modules installed which have logbox dependenciy?
b
Nope
I am almost certain this worked when it was initially implemented so I will jump back to some older commits until it works and figure out where it got broken.
Explicitly adding levelMin/levelMax to the individual appenders seems to have fixed it.
Which is what all the examples seem to show so I'm not sure how I ended up with what I had
w
To be honest, I still don’t get it why it didn’t work as expected. Setting loglevels for a certain logger is actually a two step process. First step: your logger is created, it checks if there is a category for it and if the category (or an inherited category, e.g. 
coldbox.system.subsystem
) matches, it will take the configured loglevels or if not specified 0 (fatal) to 4 (debug). if your category does not match the rootlogger will be used with configured loglevels or default levels (0-4). Once you try to log something to your logger it will look for the severity level first, and only if it matches (canLog) it will find out which appenders have the correct severity level. So it is a two step filter. Filter 1 is your logger, step 2 is the appender. So if you try to log a debug message and both the root logger AND your 
coldbox.system
logger have a max level of INFO, it shouldn’t log at all, even if your appenders have a debug level. If the first filter (the logger itself) already stops your DEBUG message, the appender config should be irrelevant. So I am assuming somewhere in the proces your logger levels are not set at all or set to incorrect values which could make the maxLevel fallback to DEBUG. On the other hand: if you configure ALL appenders to have a maxLevel of INFO you will not see the DEBUG messages at all, which is what you want. I hope I am clear 🤔 in my explanation. You can see the mechanism in 
coldbox.system,logging.Logger.cfc
in the 
LogMessage()
method. Both the Logger and the Appender have 
canLog
methods, which should obey the configured levels.
b
The new coldbox app I spun up for testing purposes worked exactly as expected. Meaning I did not have to put levelMin and levelMax on the individual appenders. So it seems like i still have some code munging things up somewhere. But at least debug logs aren't pouring in while I figure it out now.
w
Yes you are right. This solves your problem. But the root case is still there. This buys you some time to find the real problem.
👍 1
Maybe you can spin up a new site, copy your problem config and see what’s happening. Not that you have too, maybe you are fine with the current fix
b
that is exactly what I did and it worked as expected
w
Interesting 😀
b
which makes it seem like it must be some other app code but... the only way to the dbAppender is through the root logger and that has the min/max levels set. The dbAppender works for writing the logs to the DB but is just losing the log levels somewhere somehow... If that was a deseried behavior, I have no idea how I'd go about MAKING it happen lol
the "fix" has the logs back in order but no, I'm not fine with it. I'm pretty determined to figure out what's going on so I know how NOT to do it again heh
2 Views
Open in Slack
PreviousNext
Powered by