Interprétation et modification log4j

thierry.balla · April 19, 2022, 9:41am

Request description

Bonjour,
J’aimerais vous poser une question concernant le fichier de configuration log4j
log4j2.xml (3.5 KB)

Il y a les appenders:

            <Console name="SIMPLICITE-CONSOLE" target="SYSTEM_OUT">
                    <PatternLayout pattern="%highlight{%date|%marker|%level|%message%n%throwable}{FATAL=magenta, ERROR=red, WARN=yellow, INFO=green, DEBUG=blue, TRACE=blue}"/>
            </Console>

            <RollingFile name="SIMPLICITE-FILE" bufferSize="4096" append="true"
                            fileName="${sys:catalina.base}/webapps/ROOT/WEB-INF/log/simplicite.log"
                            filePattern="${sys:catalina.base}/webapps/ROOT/WEB-INF/log/simplicite.%date{yyyy-MM-dd}-%i.log.gz">
                    <PatternLayout pattern="%date|%marker|%level|%message%n%throwable"/>
                    <Policies>
                            <TimeBasedTriggeringPolicy/>
                            <!-- SizeBasedTriggeringPolicy size="100 MB"/ -->
                    </Policies>
                    <DefaultRolloverStrategy max="28"/><!-- 4 weeks -->
            </RollingFile>

            <!-- Sessions appender -->
            <RollingFile name="SIMPLICITE-SESSION" bufferSize="1024" append="false"
                            fileName="${sys:catalina.base}/webapps/ROOT/WEB-INF/log/simplicite-session.log"
                            filePattern="${sys:catalina.base}/webapps/ROOT/WEB-INF/log/simplicite-session.%date{yyyy-MM-dd}-%i.log.gz">
                    <PatternLayout pattern="%date|%marker|%level|%message%n"/>
                    <Policies>
                            <TimeBasedTriggeringPolicy/>
                    </Policies>
                    <DefaultRolloverStrategy max="28"/><!-- 4 weeks -->
            </RollingFile>

            <!-- Redo logs appender -->
            <RollingFile name="SIMPLICITE-REDOLOG" bufferSize="1024" append="true"
                            fileName="${sys:catalina.base}/webapps/ROOT/WEB-INF/log/simplicite-redo.log"
                            filePattern="${sys:catalina.base}/webapps/ROOT/WEB-INF/log/simplicite-session.%date{yyyy-MM-dd}-%i.log.gz">
                    <PatternLayout pattern="%date|%marker|%level|%message%n"/>
                    <Policies>
                            <TimeBasedTriggeringPolicy/>
                    </Policies>
                    <DefaultRolloverStrategy max="28"/><!-- 4 weeks -->
            </RollingFile>

    </Appenders>

Et les Loggers :

            <Root level="debug">
                    <AppenderRef ref="SIMPLICITE-CONSOLE"/>
                    <AppenderRef ref="SIMPLICITE-FILE"/>
            </Root>

            <Logger name="SIMPLICITE-SESSION" level="info" additivity="false">
                    <AppenderRef ref="SIMPLICITE-SESSION"/>
            </Logger>

            <Logger name="SIMPLICITE-REDOLOG" level="info" additivity="false">
                    <AppenderRef ref="SIMPLICITE-REDOLOG"/>
            </Logger>

            <!-- JGit logging to info level -->
            <Logger name="org.eclipse.jgit.util.SystemReader" level="info"/>
            <Logger name="org.eclipse.jgit.util.FS" level="info"/>
            <Logger name="org.eclipse.jgit.internal.storage.file.PackFile" level="info"/>
            <Logger name="org.eclipse.jgit.internal.storage.file.FileSnapshot" level="info"/>

    </Loggers>

De ma compréhension de ce fichier, Simplicite-console et simplicite-file sont en debug

Est ce que j’interprète mal le fichier?

Steps to reproduce

This request concerns an up-to-date Simplicité instance
and those are the steps to reproduce it:

Technical information

Instance /health

---paste the content of your-instance.com/health---

Simplicité logs

---paste the content of the **relevant** server-side logs---

Browser logs

---paste content of the **relevant** browser-side logs---

Other relevant information

----E.g. type of deployment, browser vendor and version, etc.----

david · April 19, 2022, 10:05am

Le root Log4J est en level “debug” par défaut car, dans Simplicité, le logging “normal” (= utilisant AppLog) est géré par la notion paramétrable de log event et certains paramètres systèmes qui permettent d’activer le niveau de trace voulu (jusqu’au niveau debug) à la demande

le LOG_DEBUG (livré par défaut à no) qui détermine si les events de niveau debug sont actifs ou non)
les LOG_INFO, LOG_WARN, etc. (livrés par défaut à yes) qui font de même pour les logs events des autres niveaux
les autres LOG_* qui déterminent si certains loggings système particuliers sont actifs, ex: LOG_SQL_SYSTEM et LOG_SQL_USER qui permettent parfois en dev de débugger certaines requêtes SQL du socle

Il ne faut jamais activer les params LOG_* livrés par défaut à no en prod (sauf éventuellement très ponctuellement pour investiguer un pb précis) car ça induit potentiellement des volumes de logs énormes.

Au delà de ces params systèmes et log events paramétrables, rien ne vous empêche de customiser votre image Docker pour adapter le log4j2.xml et/ou le logging.properties à vos usages (ex: utilisation de traces logs qui n’utilisent pas AppLog) et vos besoins/contraintes.

Par exemple pour mettre le root logger Log4J à “info”:

FROM registry.simplicite.io/platform:<tag>
RUN sed -i '/Root/s/level="debug"/level="info"' /usr/local/tomcat/webapps/ROOT/WEB-INF/classes/log4j2.xml

Ou ajouter des exceptions comme celles qu’on a mis sur les traces des libs JGit.

Etc.

Cela dit, je pense qu’il faudrait commencer par regarder de près ce qui se retrouve effectivement dans vos logs pour mieux cerner ce qui induit éventuellement un volume excessif et donc pouvoir déterminer ce qu’il convient de faire exactement.

david · April 19, 2022, 10:16am

PS: j’avais zappé mais dans les images Docker récentes il y a des variables d’environnement qu’on peut directement passer au container pour ajuster les fichiers de logs sans devoir construire une image custom:

LOG4J_ROOT_LEVEL pour ajuster le root level dans log4j2.xml
LOGGING_CONSOLE_LEVEL et LOGGING_FILE_LEVEL pour ajuster le niveau de log console et fichier dans le logging.properties

cf. Simplicité® documentation/90-operation/docker

Ca ne dispense pas pour autant de l’analyse ci-dessus pour savoir ce qui induit un niveau de log inapproprié dans votre cas et donc pour pouvoir déterminer ce qu’il convient de faire exactement.

thierry.balla · April 20, 2022, 2:01pm

David, j’ai une question sur les logs qui sont affichées dans Simplicite. Sur quoi s’affiche cet affichage? Sur le fichier simplicite.log ou sur la console?

david · April 20, 2022, 2:14pm

Je ne suis pas sûr de comprendre ce que vous entendez par “les logs qui sont affichées dans Simplicite”…

Si on parle de la page UI legacy “log viewer” (que, pour mémoire, il ne faut jamais utiliser autrement que ponctuellement et uniquement en DEV), celle-ci lit dans le fichier simplicite.log configuré en tant que file appender (SIMPLICITE-FILE) dans la config du logger Log4J.
Si on parle des logs accessibles niveau Docker (ex: via un docker logs -f <container ID/name>) il s’agit des logs configurés en tant que console appender (SIMPLICITE-CONSOLE) dans la config Log4J (auxquels s’ajoutent les logs Tomcat configurées au niveau du Java logging qui sont aussi poussées vers la console)
Si on parle des logs remontées dans la console du navigateur via websockets c’est un mécanisme niveau AppLog indépendant du logger Log4J.

thierry.balla · April 20, 2022, 2:31pm

Je parle des logs accessibles via /ui/logs
C’est ça que tu nommes la page UI legacy “log viewer”?

david · April 20, 2022, 3:05pm

Oui la page /ui/logs est ce que j’appelle la page legacy “log viewer”.

C’est plus une “backdoor” historique destinée uniquement au DEV et pas du tout optimale dans son traitement. Il ne faut jamais l’utiliser en PROD (où il faut aller à la source pour consulter les logs = récupérer ce que Docker lit de la console et/ou monter un volume pour accéder aux fichiers logs).

Pour la petite histoire, lorsqu’on a mis en place la mécanique de remontée de traces AppLog via websockets vers la console du navigateur (en 3.1 = en 2014-2015 (!)), on a voulu supprimer définitivement ce “log viewer” historique. Malheureusement les websockets ne sont pas encore bien supportées sur toutes les infras, donc on l’a conservé jusqu’à nouvel ordre pour ne pas frustrer ceux qui ont une infra incompatible avec les websockets. Mais ça reste une “backdoor” à réserver à un usage ponctuel et uniquement en DEV.

Comme dit à plusieurs reprises lors de nos échanges, je soupçonne que vous vous en servez comme votre outil “nominal” pour suivre en permanence les logs de PROD. Si c’est le cas c’est une très mauvaise idée et ça nous conforte dans l’idée que cet outil historique doit être définitivement retiré de la plateforme.

thierry.balla · April 20, 2022, 3:48pm

David,
malgré nos échanges je n’avais pas compris jusque là que tu parlais de ce dispositif. En toute honnêteté, je ne sais pas dans quelle mesure il est utilisé par l’équipe, mais je vais leur transmettre la préco de ne surtout pas l’utiliser en PROD.

david · April 20, 2022, 4:11pm

Pour mémoire, mon soupçon est lié à des infos de supervision JVM fournies qui semblaient indiquer une présence d’instances de classes Java qui ne sont utilisées que par ce composant “log viewer”

Suite à ce soupçon nous avons apportés qques petites améliorations sur ce composant (dans le cadre de la révision 5.1.35) mais ça reste malgré tout fondamentalement une “backdoor” pas optimale (et en fin de vie) qu’il vaut mieux éviter d’utiliser, surtout en PROD.

system · May 20, 2022, 4:11pm

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.