[RFC] New MessageLogger configuration syntax

[Dr15Jones]

The present configuration syntax used by the MessageLogger service can be confusing to use. Many different parameters often must be changed simultaneously to control the output. Here we propose simplifying some of the options by providing better grouping and avoiding previously required multiple declarations of parameter names. This would entail no changes to the internals of the MessageLogger, just in the way it is configured.

Internally, the MessageLogger has two major concepts: destinations and categories.

A destination sets up where messages are ultimately sent. This could be cout, cerr or to files. Many different options for filtering which messages are ultimately sent are available.

A category is the label passed to the C++ MessageLogger calls. E.g. edm::LogError("BadFoo"), "BadFoo" is the category.

The MessageLogger also has the ability to filter messages based on the label of the cmsRun module which is running when the message was issued.

The structure of the proposed configuration change is below. {NOTE: all variables beginning with _ are for illustrative purposes and not for implementation. They avoid duplicating the same description multiple times}

Service("MessageLogger",
   messageSummaryToJobReport = cms.untracked.bool(False),
   waiting_threshold = cms.untracked.uint32(100),

   modules = cms.untracked.PSet( # all use module labels
       suppressInfo = cms.untracked.vstring(),
       suppressFwkInfo = cms.untracked.vstring(),
       suppressWarning = cms.untracked.vstring(),
       suppressDebug = cms.untracked.vstring(),
       suppressError = cms.untracked.vstring(),
       debugModules = cms.untracked.vstring()
   )

   destinations = cms.untracked.PSet(
       cerr = _destination_base_.clone(enabled = cms.untracked.bool(True))
       cout = _destination_base_.clone(enabled = cms.untracked.bool(False))
       #any other label used will be associated with a file to be written
       allowAnyLabel_ = cms.optional.untracked.PSetTemplate(_destination_file)
   )
)

with the PSet description for cout and cerr being

#configuration fragment used to decide how to deal with each output stream
_destination_base = cms.untracked.PSet(
     noLineBreaks = cms.untracked.bool(False),
     noTimeStamps = cms.untracked.bool(False),
     lineLength = cms.untracked.int32(-1), 
     threshold = cms.untracked.string("INFO"), 
     enableStatistics = cms.untracked.bool(True), #denotes that ML statistics should be written here

     DEBUG = _category.clone(),  
     INFO  = _category.clone(),
     FWKINFO = _category.clone(),
     WARNING = _category.clone(),
     ERROR = _category.clone(),
     categories = cms.untracked.PSet(
          #the parameter labels match the message categories
         allowAnyLabel_ = cms.optional.untracked.PSetTemplate(_category),
     )
)

and the file destinations having a few extra parameters used to control the file name

_destination_file = _destination_base.clone( 
     output = cms.untracked.optional.string,
     filename = cms.untracked.optional.string,
     extension = cms.untracked.optional.string 
)

The options for the categories are

#configuration fragment used to decide how to deal with each message label
_category = cms.untracked.PSet(
   reportEvery = cms.untracked.int32(1),
   limit = cms.untracked.int32(-1),
   timespan = cms.untracked.optional.int32
)

[cmsbuild]

A new Issue was created by @Dr15Jones Chris Jones.

@Dr15Jones, @dpiparo, @silviodonato, @smuzaffar, @makortel, @qliphy can you please review it and eventually sign/assign? Thanks.

cms-bot commands are listed here

[Dr15Jones]

assign core

[cmsbuild]

New categories assigned: core

@Dr15Jones,@smuzaffar,@makortel you have been requested to review this Pull request/Issue and eventually sign? Thanks

[Dr15Jones]

Variant 1

Move the destinations cout and cerr out of the destinations PSet and up to the top level of the MessageLogger PSet. Then change destinations to files.
E.g.

Service("MessageLogger",
   messageSummaryToJobReport = cms.untracked.bool(False),
   generate_preconfiguration_message = cms.untracked.string(), #Intended only for testing
   waiting_threshold = cms.untracked.optional.uint32,

   modules = cms.untracked.PSet( # all use module labels
       suppressInfo = cms.untracked.vstring(),
       suppressFwkInfo = cms.untracked.vstring(),
       suppressWarning = cms.untracked.vstring(),
       suppressDebug = cms.untracked.vstring(),
       suppressError = cms.untracked.vstring(),
       debugModules = cms.untracked.vstring()
   )
   
   cerr = _destination_base_.clone(enabled = cms.untracked.bool(True))
   cout = _destination_base_.clone(enabled = cms.untracked.bool(False))

   files = cms.untracked.PSet(
       allowAnyLabel_ = cms.optional.untracked.PSetTemplate(_destination_file)
   )
)

An advantage here is it keeps the syntax a bit closer to the original and makes it clear that the other destinations are files.

[Dr15Jones]

Variation 2

In the original syntax, there was the option to set default values to be applied to all categories, all destinations or to all categories within a given destination. That could be retained

Service("MessageLogger",
...
   destinations = cms.untracked.PSet(
       defaults = _default
       cerr = _destination_base_.clone(enabled = cms.untracked.bool(True))
       cout = _destination_base_.clone(enabled = cms.untracked.bool(False))
       allowAnyLabel_ = cms.optional.untracked.PSetTemplate(_destination_file)
   )
)

with

#defaults to apply to all destinations and their embedded categories
_default = _destination_base.clone(_category, default = None )

and

_destination_base = cms.untracked.PSet(
...
 default = _category, #applies to categories, DEBUG, INFO, WARNING and ERROR
...
)

I'm not a big fan of this since it makes it more difficult to see exactly what messages will be printed since one needs to check the values of the message expliciltly and the defaults. Also, the same behavior can be accomplished programmatically by the users.

[Dr15Jones]

So, using this new syntax, how would one suppress all INFO messages except for 'MyLabel'? The following does exactly that

process.MessageLogger.destinations.cerr.threshold = 'INFO'
process.MessageLogger.destinations.cerr.INFO.limit = 0 #default all INFOs to not write anything
process.MessageLogger.destinations.cerr.categories.MyLabel = dict(limit=-1) #explicitly say to write all of these

[kpedro88]

Maybe it's worth considering the most common use cases, and how to make those as simple as possible? I think users usually want one of these cases:

1. Enable all messages from [my category]
2. Enable all messages from [given severity]

e.g. for SonicTriton tests, I do this:

cmssw/HeterogeneousCore/SonicTriton/test/tritonTest_cfg.py

Lines 63 to 73 in 9d0ce20

	process.load('FWCore/MessageService/MessageLogger_cfi')
	process.MessageLogger.cerr.FwkReport.reportEvery = 500
	keep_msgs = [options.producer,options.producer+':TritonClient','TritonClient']
	for msg in keep_msgs:
	process.MessageLogger.categories.append(msg)
	setattr(process.MessageLogger.cerr,msg,
	cms.untracked.PSet(
	optionalPSet = cms.untracked.bool(True),
	limit = cms.untracked.int32(10000000),
	)
	)

Something like a "MessageLoggerHelper" function with reasonable defaults and clear parameter explanations could help users do common actions without having to keep track of nested PSet structures etc.

(We should also make it as easy as possible to activate and view LogDebug messages... this is a frequent source of frustration.)

[Dr15Jones]

NOTE: After testing I did determine that my first guess as to how to keep only 1 particular INFO message was the correct configuration. I've update the previous comment accordingly.

[Dr15Jones]

@kpedro88
In the new syntax, your example could be

process.load('FWCore/MessageService/MessageLogger_cfi') 
_cerr = process.MessageLogger.destinations.cerr
_cerr.FwkReport.reportEvery = 500
keep_msgs = [options.producer,options.producer+':TritonClient','TritonClient']
for msg in keep_msgs:
   setattr(_cerr, msg, dict(limit = 10000000))

Since I'd propose making the default limit effectivetly infinite, the setattr would then just be

setattr(_cerr, msg, dict())

[kpedro88]

That's definitely simpler. I would propose a helper (similar to RandomServiceHelper) to make the syntax a bit simpler, e.g.:

from FWCore.MessageService.MessageLoggerHelper import MessageLoggerHelper
msgHelper = MessageLoggerHelper(process.MessageLogger)
msgHelper.activate(categories = keep_msgs, dest = 'cerr')

(or activate() could take one category at a time in a loop)

[makortel]

(just to record here: WM and CRAB do not customize MessageLogger configuration)

[slava77]

I think users usually want one of these cases:

1. Enable all messages from [my category]

2. Enable all messages from [given severity]

I'd add an ability to disable something specifically, not just enable
and also to have control per module.

I can't recall a use case to need to control different destinations for logging of outputs of one processing job (since ever on CMS or before).
I can imagine a contol-room like situation with multiple monitors (displays/humans/bots) looking at the flow of text for different areas/subsystems.

[kpedro88]

I can't recall a use case to need to control different destinations for logging of outputs of one processing job (since ever on CMS or before).

I've occasionally done something like this, but in practice, it's also quite simple just to put everything into cout/cerr and then grep for the desired messages.

[slava77]

I can't recall a use case to need to control different destinations for logging of outputs of one processing job (since ever on CMS or before).

I've occasionally done something like this, but in practice, it's also quite simple just to put everything into cout/cerr and then grep for the desired messages.

fine, I guess having separate destinations is the only way to disentangle Log{Print,Verbatim,Trace}, which have no MSG-generated headers

[fabiocos]

A possible use case is given by tests (possibly unit tests) were you want to isolate a subset of categories into a file, but for debugging purposes you may want to optionally enable a few others. For instance if you debug geometry of one subdetector you may not be interested into all the troubles of others, or of unrelated parts of the code. A practical example I have recently played with is

https://github.com/cms-sw/cmssw/blob/master/Geometry/MTDGeometryBuilder/test/mtd_cfg.py

Grepping files may quickly become very hard, depending on the code executed and/or the number of events. In any case to simplify the analysis of log files I had mad available in CMSSW and old script of mine

https://github.com/cms-sw/cmssw/blob/master/FWCore/MessageLogger/scripts/edmMLParser

which gives a bit of options to parse output.

One part of the MessageLogger that usually looks cumbersome to users is LogDebug, because of the special way of managing it. Anyway I have recently started to appreciate enabling it on a file-by-file basis by prepending code in .cc files with

#define EDM_ML_DEBUG```

[fwyzard]

Is there any use case for having both cout and cerr ?

I don't think we actually use it anywhere in production... and every time I send them to different files (e.g. cmsRun config.py > log 2> err) I end up with very confusing reports, for example with an exception message in the error file and the stack trace in the output.

[fwyzard]

One part of the MessageLogger that usually looks cumbersome to users is LogDebug, because of the special way of managing it. Anyway I have recently started to appreciate enabling it on a file-by-file basis by prepending code in .cc files with

#define EDM_ML_DEBUG```

Right.

I think something that could make it easier would be to have a way to pass to scram a list of packages or files to be rebuilt with -DEDM_ML_DEBUG.

Something like

scram b --debug=DataFormats/TrackReco,RecoTracker'

that would add USER_CXXFLAGS="-g" USER_CUDA_FLAGS="-g -lineinfo" to the compilation of files matching the list.

[fwyzard]

the file destinations having a few extra parameters used to control the file name

_destination_file = _destination_base.clone( 
     output = cms.untracked.optional.string,
     filename = cms.untracked.optional.string,
     extension = cms.untracked.optional.string 
)

what is the purpose of extension ?

[fwyzard]

By the way, here is a recent MessageLogger configuration used at HLT:

process.MessageLogger = cms.Service("MessageLogger",

    categories = cms.untracked.vstring(
      'FwkJob',
      'FwkReport',
      'FwkSummary',
      'Root_NoDictionary'),

    destinations = cms.untracked.vstring(
      'errors',
      'warnings',
      'infos',
      'debugs',
      'cout',
      'cerr'),

    threshold = cms.untracked.string("INFO"),
    
    fwkJobReports = cms.untracked.vstring('FrameworkJobReport'),
    
    FrameworkJobReport = cms.untracked.PSet(
      default = cms.untracked.PSet(limit = cms.untracked.int32(0)),
      FwkJob = cms.untracked.PSet(limit = cms.untracked.int32(10000000))
    ),
    
    # not sure what this does
    statistics = cms.untracked.vstring('cerr'),

    debugModules = cms.untracked.vstring(),

    suppressDebug = cms.untracked.vstring(),

    suppressInfo = cms.untracked.vstring(),

    suppressWarning = cms.untracked.vstring(
      'hltOnlineBeamSpot',
      'hltCtf3HitL1SeededWithMaterialTracks',
      'hltL3MuonsOIState',
      'hltPixelTracksForHighMult',
      'hltHITPixelTracksHE',
      'hltHITPixelTracksHB',
      'hltCtfL1SeededWithMaterialTracks',
      'hltRegionalTracksForL3MuonIsolation',
      'hltSiPixelClusters',
      'hltActivityStartUpElectronPixelSeeds',
      'hltLightPFTracks',
      'hltPixelVertices3DbbPhi',
      'hltL3MuonsIOHit',
      'hltPixelTracks',
      'hltSiPixelDigis',
      'hltL3MuonsOIHit',
      'hltL1SeededElectronGsfTracks',
      'hltL1SeededStartUpElectronPixelSeeds',
      'hltBLifetimeRegionalCtfWithMaterialTracksbbPhiL1FastJetFastPV',
      'hltCtfActivityWithMaterialTracks'),
    
    suppressError = cms.untracked.vstring(
      'hltOnlineBeamSpot',
      'hltL3MuonCandidates',
      'hltL3TkTracksFromL2OIState',
      'hltPFJetCtfWithMaterialTracks',
      'hltL3TkTracksFromL2IOHit',
      'hltL3TkTracksFromL2OIHit'),

    # destinations
    errors = cms.untracked.PSet(
      placeholder = cms.untracked.bool(True),
      threshold = cms.untracked.string("INFO"),
      suppressInfo = cms.untracked.vstring(),
      suppressWarning = cms.untracked.vstring(),
      suppressDebug = cms.untracked.vstring(),
      suppressError = cms.untracked.vstring()
    ),
    warnings = cms.untracked.PSet(
      placeholder = cms.untracked.bool(True),
      threshold = cms.untracked.string("INFO"),
      suppressInfo = cms.untracked.vstring(),
      suppressWarning = cms.untracked.vstring(),
      suppressDebug = cms.untracked.vstring(),
      suppressError = cms.untracked.vstring()
    ),
    infos = cms.untracked.PSet(
      placeholder = cms.untracked.bool(True),
      threshold = cms.untracked.string("INFO"),
      Root_NoDictionary = cms.untracked.PSet(
        limit = cms.untracked.int32(0)
      ),
      suppressInfo = cms.untracked.vstring(),
      suppressWarning = cms.untracked.vstring(),
      suppressDebug = cms.untracked.vstring(),
      suppressError = cms.untracked.vstring()
    ),
    debugs = cms.untracked.PSet(
      placeholder = cms.untracked.bool(True),
      threshold = cms.untracked.string("INFO"),
      suppressInfo = cms.untracked.vstring(),
      suppressWarning = cms.untracked.vstring(),
      suppressDebug = cms.untracked.vstring(),
      suppressError = cms.untracked.vstring()
    ),
    cout = cms.untracked.PSet(
      placeholder = cms.untracked.bool(True)
    ),
    cerr = cms.untracked.PSet(
      threshold = cms.untracked.string("INFO"),
      suppressInfo = cms.untracked.vstring(),
      suppressWarning = cms.untracked.vstring(),
      suppressDebug = cms.untracked.vstring(),
      suppressError = cms.untracked.vstring(),
      noTimeStamps = cms.untracked.bool(False),
      default = cms.untracked.PSet(
        limit = cms.untracked.int32(10000000)
      ),
      INFO = cms.untracked.PSet(
        limit = cms.untracked.int32(0)
      ),
      FwkReport = cms.untracked.PSet(
        reportEvery = cms.untracked.int32(1),
        limit = cms.untracked.int32(0)
      ),
      Root_NoDictionary = cms.untracked.PSet(
        limit = cms.untracked.int32(0)
      ),
      FwkJob = cms.untracked.PSet(
        limit = cms.untracked.int32(0)
      ),
      FwkSummary = cms.untracked.PSet(
        reportEvery = cms.untracked.int32(1),
        limit = cms.untracked.int32(10000000)
      ),
    ),

    # not sure what this does, either
    cerr_stats = cms.untracked.PSet(
      optionalPSet = cms.untracked.bool(True),
      threshold = cms.untracked.string("WARNING"),
      output = cms.untracked.string("cerr"),
    )
)

As you can see there is a lot of stuff that we should probably remove... unfortunately I think it gets added back because we parse the autogenerated cfi file to begin with :-(

[slava77]

By the way, here is a recent MessageLogger configuration used at HLT:

did I read it correctly that the PSet errors and warnings are identical and both have threshold = cms.untracked.string("INFO").
Both are mentioned in destinations.
What do they actually do? (I recall seeing these in the past and being confused of the purpose; I'm trying to understand if this is something mapped to the new proposed syntax)

[fwyzard]

I think they don't actually do anything, because they have

placeholder = cms.untracked.bool(True),

[Dr15Jones]

@slava77

I can't recall a use case to need to control different destinations for logging of outputs of one processing job (since ever on CMS or before).

You can find cases in CMSSW doing that by git grep process.MessageLogger.destinations and then looking for multiple entries.

[Dr15Jones]

Is there any use case for having both cout and cerr ?

I don't think we actually use it anywhere in production... and every time I send them to different files (e.g. cmsRun config.py > log 2> err) I end up with very confusing reports, for example with an exception message in the error file and the stack trace in the output.

Unfortunately, the vast majority of use cases configuring the MessageLogger are not production (since that would make it much easier to do changes :) ).

Again, doing process.MessageLogger.destinations one can see cases were people use cout and even cout and cerr together.

As for the stack trace, it isn't possible to safely redirect the stack trace output to the MessageLogger as the stack trace happens in a unix signal handler which has restrictions on what one is allowed to call, with dynamic memory handling being one of the forbidden items.

[Dr15Jones]

@fwyzard

what is the purpose of extension ?

So by default if one were to write (in the present configuration syntax)

process.add_(cms.Service("MessageLogger",
  destinations = cms.untracked.vstring("foo"),
  foo = cms.untracked.PSet( ... )
) )

Then it would write a file named foo.log. If you were to instead have

process.add_(cms.Service("MessageLogger",
  destinations = cms.untracked.vstring("foo"),
  foo = cms.untracked.PSet( extension = cms.untracked.string("mylog", ...)
) )

Then it would write a file named foo.mylog.

Just to be clear, I am in no way trying to defend the present interface :), I'm just trying to explain what I've found out about it recently.

[Dr15Jones]

I think they don't actually do anything, because they have

placeholder = cms.untracked.bool(True),

@fwyzard is correct. That parameter tells the MessageLogger to just ignore that destination even though it appears in the destinations list.

All this stuff dates back to the dawn of time when the original developer (who wrote this code for CDF) was still the maintainer of the code. It was pointed out to him that the configuration was difficult to use and his solution was to inject these placeholders under the theory that then people could do simple additions.

[Dr15Jones]

@fwyzard

As you can see there is a lot of stuff that we should probably remove... unfortunately I think it gets added back because we parse the autogenerated cfi file to begin with :-(

The FWCore.MessageService.MessageLogger_cfi is actually hand written since the present syntax required by the MessageLogger can't be expressed by the ParameterSet validation code. Another reason for this RFC was to change the syntax so we could use the standard validation code.

As a first step, the pull request
#31888

already removes some of the obsolete options from the default logger cfi, so the HLT will inherit that "for free" :). I'd love to get rid of more of those not so useful options but in a way that doesn't break existing configuration in CMSSW.

By the way, do you know where the list of HLT module suppressions are being injected? That would be useful in the case we do wind up making an interface change.

[fwyzard]

By the way, do you know where the list of HLT module suppressions are being injected? That would be useful in the case we do wind up making an interface change.

It's maintained in ConfDB, so changing the syntax is not trivial but should be doable.

[Dr15Jones]

@fwyzard

It's maintained in ConfDB, so changing the syntax is not trivial but should be doable.

Ah, good to know.

[note earlier this message said under this RFC nothing would change but that is incorrect]

[fwyzard]

By the way - I have a couple of comments / feature requests for the MessageLogger that are not about the syntax used to configure it... I'll mention them here, but I can also open dedicated issues for them :-)

Add support for HTML-formatted log files ?

It could be something as simple as adding few standard headers, some CSS styling and a <div> tag for each message - but it could help for all the case where the logs are viewed in a browser ?
It could be enabled by a per-destination option, and/or based on the file extension.

Add (optional) colours to the Log messages ?

Not the whole message - just the %MSG-w ... header with the category and the footer.
For example:

• LogError: in red
• LogWarning: in yellow
• LogInfo: in white
• LogSystem and LogDebug: not sure...

It could be "disabled" (by default), "auto" (enable only if the output is a console) and "enabled" (explicitly to force it also for files).
We could use ANSI codes for consoles and text output (I think {fmt} supports it already), and CSS styles for HTLM output.

[Dr15Jones]

By the way - I have a couple of comments / feature requests for the MessageLogger that are not about the syntax used to configure it... I'll mention them here, but I can also open dedicated issues for them :-)

Yes, please do open a dedicated issue for those requests. It makes it easier for us to track specific items.

[fwyzard]

Done: #31925 and #31926 .

[Dr15Jones]

@fwyzard

    # not sure what this does
    statistics = cms.untracked.vstring('cerr'),

It tells the message logger to write is job statistics (that huge tabulated list) to cerr at the end of the job.

    # not sure what this does, either
    cerr_stats = cms.untracked.PSet(
      optionalPSet = cms.untracked.bool(True),
      threshold = cms.untracked.string("WARNING"),
      output = cms.untracked.string("cerr"),
    )

I think it would be doing the same thing as the other line if cerr_stats had been in the statistics list.

[Dr15Jones]

Variant 3

This variant should require the smallest number of files to be modified to still be able to get the goal of

• no longer having to multiply declare names, once in a vstring and another time as a parameter in a PSet
• be able to use the ParameterSet description system with MessageLogger which would make edmPluginHelp -p MessageLogger give useful results

The changes would be as follows

1. remove the statistics vstring and instead add a bool parameter named enableStatistics to the destinations PSets
2. move all declarations of new destinations to the top level files parameter PSet and get rid of the destinations vstring
3. added a bool parameter to cout and cerr PSets named enable which would allow toggling on and off those standard outputs.
4. remove the categories vstring as it is no longer needed since the only new PSets declared at the top level would be ones for a new category.

This change could be done in multiple steps to ease migration

1. Add the enableStatistics parameter to the destinations.
2. Migrate the ~80 configurations that explicitly use the statistics parameter
3. Once all configurations are migrated, remove the statistics option
4. Add the files parameter
5. Migrate the ~230 configurations that explicitly add to the destinations parameter
6. Once all configurations are migrated, remove the obsolete parameters

[makortel]

+1

Variant 3 was implemented in #32138

[cmsbuild]

This issue is fully signed and ready to be closed.