Uploaded image for project: 'Product Roadmaps'
  1. Product Roadmaps
  2. MMF-439

Make it easier for users to investigate with logs

    Details

    • Type: MMF
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Labels:

      Description

      Context

      With the clustering, CE logs are now part of sonar.log (MMF-439).
      4 processes are currently writing in sonar.log:

      • app (writes start/stop logs)
      • web
      • ce
      • es

      These ones are working concurrently, and the order in logs does not help to understand the sequence between the different processes.

      Main concerns
      • At DEBUG level, the high verbosity of logs and the fact that sonar.log gathers unrelated operations (es, web and now ce) slows down investigations from the support.
      • Sonarqube.com monitoring tends to require additional info that would be permanently logged (MMF-366 & MMF-361 under specification) .
        At lot of info are available at TRACE level (SQL and ES requests), but the verbosity of TRACE level is not suitable for a production environment because of the impact on performance.
      Mid-term needs to cover (not part of this MMF)
      Technical Needs Ops Support Dev
      Change config dynamically
      Targeted logs  
      Logs gathered by context  
      Usage Ops Support Dev
      Profiling of Web (http, es, sql)
      Profiling of CE (steps,es, sql)
      Monitoring (security)    
      Telemetry (web, ce)    
      Solution
      • Logs are written in different log files depending on the process:
        • sonar.log (from app)
        • web.log
        • ce.log
        • es.log
      • Existing global log level still applies (set to INFO by default, and with same possible values as now: INFO / DEBUG / TRACE)
        This parameter defines the log level applied by default by the different processes in the different log files.
        sonar.log.level=INFO
      • A new log level per process is added, that overrides when specified the log level defined at global level (same possible values: INFO / DEBUG / TRACE)
        sonar.log.level.web=INFO
        sonar.log.level.ce=INFO
        sonar.log.level.es=INFO
        

        It should be possible to activate these log levels via the WS.

      • A new log level per "activity"/logger is also added, that overrides when specified the log level defined at process & global levels (same possible values: INFO / DEBUG / TRACE).
        The name of the logger should be explicit, i.e. for the current scope:
        sonar.log.level.web.sql=TRACE
        sonar.log.level.web.es=TRACE
        

        and possibly, later on (out of the current scope), other pre-defined loggers:
        ex:

        sonar.log.level.web.auth=DEBUG
        ...
        

        This log level per logger mainly targets ops & dev needs.
        This log level would not be documented, but pre-defined logger label should be explicit enough in logs so that a user can easily configure such a log level

        2016.08.27 10:30:59 DEBUG web [] [sql] ...
        2016.08.27 10:31:02 DEBUG web [] [es] ....
        

        Loggers for sql and es will write at TRACE level the current sql/es logs.

      Guidelines:
      • Logs format should be parsable and, as much as possible, stable in time.
        • The format of log (parameters before the "payload") should be the same for all the processes.
          Parameters others than the timestamp, the log level and the process name (app, ce, web, es) should be encapsulated into [ ].
        • The log format should be documented in sonar.properties
      • The context of logs should be explicit enough to understand an error (this should already be the case)
      • Logs should help to follow the workflow, from user interaction to the access to a datastore. Inside a log file, an unique id can help to filter logs relating to a same user/task/action.
        • ce logs will display the task id as a fix parameter.
        • For es, no specific id is needed.
        • For web logs, a request id will be added to help identifying the logs relating to the same request
          Ex:
          2016.08.27 10:30:58 DEBUG [34683232] [] ...
          2016.08.27 10:30:59 DEBUG [34683232] [es] ...
          2016.08.27 10:31:02 DEBUG [34683232] [sql] ....
          

          Adding the possibility to log this id in access.log, the duplicated log about HTTP request will be removed from web logs:

          2016.11.02 18:23:02 DEBUG web[][http] GET /api/users/current | time=13ms
          
      • A common understanding of log levels should be followed:
        • INFO level: This is the default log level and there can't be less logs. Less is more: only errors and a very few logs that help understanding the global activity.
        • DEBUG level: Any log that help investigation but that does not impact performance.
        • TRACE level: All other logs. Activating this log level may impact the performance.

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                christophe.levis Christophe Levis
                Reporter:
                christophe.levis Christophe Levis
              • Votes:
                0 Vote for this issue
                Watchers:
                4 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: