Discussion :

[RT222]

Je préviens tout de suite : je suis critique, mais je ne pense pas à mal. Il y a plusieurs erreurs dans le code, et je vais les présenter de manière neutre (pas méchante, ni gentillette ; ton neutre, tout ça).

Y'a pas de soucis, je suis au contraire ravi d'avoir l'avis d'un pro et ainsi de pouvoir améliorer mon code.

Par contre je crois qu'il y a méprise sur une partie du fonctionnement de mon logger. Je dis bien je crois, parce que je ne suis pas certain d'avoir parfaitement saisi toutes tes explications. Enfin de toute façon, s'il y a effectivement méprise, c'est de ma faute, j'aurais dû expliquer mon code. Mais je vais corriger cet écueil.

Mon logger fonctionne par groupes (comme celui de Koala). Chacun de ces groupes, identifiés par une chaîne de caractère, peut être configuré indépendamment des autres. Par exemple :

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

rwl::Logger::enable( false, L"RWL" ); // Je désactive tous les logs effectués dans le groupe RWL

Il est aussi possible de ne pas spécifier de groupe du tout si cela n'est pas utile. Ne pas spécifier de groupe revient à manipuler le groupe L"". Pour chaque groupe, je peux spécifier un fichier de log unique, un niveau, ou l'activer/désactiver totalement. Je pense que tout monde avait compris ça, mais je tenais à être complet.

Les groupes et leur configuration sont gérés par la partie statique de mon logger. Il y a une deuxième partie qui est "dynamique", qui elle sert à logger proprement dit :

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
/*
** La partie "dynamique" du logger
*/
public :
	enum class Level
	{
		trace,
		debug,
		info,
		warning,
		error,
		exception,
		fatal
	};
 
				Logger( const std::wstring& name = L"" );
				~Logger( void );
	std::wostringstream&	log( Level level );
 
private :
	std::wstring		m_name;
	std::wostringstream	m_logbuffer;
	Level			m_level;
 
/*
** La partie statique destinée à configurer mes Loggers
*/
public :
	static void enable( bool enable, const std::wstring& name = L"" );
	static void set_level( Level level, const std::wstring& name = L"" );
	static void set_logfile( const std::wstring& file_path, const std::wstring& name = L"" );
 
private:
	class Logger_data
	{
	public :
				Logger_data( void );
				Logger_data( const Logger_data& logger_data );
				~Logger_data( void );
		Logger_data&	operator=( const Logger_data& logger_data );
 
		bool					enable;
		Level					level;
		std::shared_ptr< std::wofstream >	logfile;
	};
	typedef std::map< const std::wstring, Logger_data > Logger_data_map;
 
	static Logger_data_map	m_loggers_data;

Lorsque je souhaite logger un message, je vais en fait construire une instance temporaire de mon Logger, qui sera automatiquement détruite à la fin de l'exécution de la ligne. C'est là que je crois qu'il y a méprise. Je ne récupère pas une instance stockée en statique dans mon Logger, j'en créé une!

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

rwl::Logger( L"RWL" ).log( rwl::Logger::Level::debug ) << L"Coucou, tu veux voir mon logger?" << std::endl;

Cette instance, grâce au nom de son groupe spécifié par l'utilisateur, va retrouver à sa création ses paramètres dans la partie statique du logger. La fonction log() sert, à partir de cette instance, à récupérer l'ostringstream (temporaire lui aussi) du Logger que j'ai créé, et aussi à spécifier le niveau de logging voulu. Comme je l'ai dit, à la fin de la ligne, cette instance est automatiquement détruite, et c'est donc le destructeur qui s'occupera de logger à proprement parler, mais aussi de flusher mes streams.

En résumé, je flush bel et bien mes données à chaque ligne, et donc si j'ai bien compris ce que ça signifiait, je n'écris pas en RAM. J'ai piqué l'idée de l'instance temporaire à ce monsieur : http://www.drdobbs.com/cpp/logging-in-c/201804215

1)Tu n'as pas de globale, mais tu as une statique de classe (qui est une globale aussi ; elle est stockée au même endroit dans la RAM, et est initialisée au même moment). Je sais qu'on t'a dit que c'est mieux, et dans un sens, c'est vrai. Mais dans ce cas précis, ça ne change strictement rien.

2) Ensuite, même en considérant que ton logger protège l'accès à la map sous-jacente, que se passe-t-il lorsque deux thread essaient d'écrire dans le même fichier de log ?

3)Un dernier problème : le log étant identifié par une valeur qui n'est connue qu'au runtime, tu as une possibilité d'erreur supplémentaire : si tu t'es trompé dans la valeur l'identifiant, le problème ne peut être décelé qu'au runtime, pas à la compilation.

1) Je pensais que c'était mieux qu'une globale parce que c'était privé dans une classe. Donc en résumé, pour que ça soit propre, il faudrait que je convertisse la partie statique de mon logger en Singleton? Et c'est mieux parce que comme ça c'est moi qui contrôle le moment de son instanciation? (oui je patine un peu, désolé )

2) Ah oui, je suis bien d'accord. En fait je n'ai absolument pas pensé à cette problématique car je n'ai pas encore besoin d'utiliser plusieurs threads et qu'en plus de ça je ne sais pas vraiment m'en servir. Mais je devrais m'y mettre très prochainement, donc je vais être forcé de résoudre ce problème, je verrais à ce moment là.

3) Là par contre je n'ai pas compris ce que tu veux dire. Tu parles de mes groupes? J'avais considéré que c'était à la charge de l'utilisateur de spécifier correctement le groupe voulu, puisqu'au pire, si il se plante, ça loggera quand même, mais juste pas dans le bon groupe.

Si tu avais vraiement ete inspire par Boost.Log

En fait je l'ai complètement survolé, son implémentation étant un peu trop costaude pour moi. La seule chose que j'ai reprise (en fait copié collé serait plus juste), c'est leurs différents niveaux de logging car ils sont très pertinents.

[germinolegrand]

Les stream C++ ne sont pas threadsafe.

Oh ? A ce point ? Pourtant je peux lire sur cppreference ceci pour chaque stream standard (cout, clog, etc.) :

Unless sync_with_stdio(false) has been issued, it is safe to concurrently access these objects from multiple threads for both formatted and unformatted output.

Ah, ce n'est pas valable pour les fichiers... Dans ce cas ne vaut-il pas mieux utiliser les flux standards ?

D'ailleurs je n'ai jamais vu de cout corrompu sur la sortie standard en multithread...

[Klaim]

En fait je l'ai complètement survolé, son implémentation étant un peu trop costaude pour moi. La seule chose que j'ai reprise (en fait copié collé serait plus juste), c'est leurs différents niveaux de logging car ils sont très pertinents.

Ils sont repris de Log4J (java) et la game de portages sur autres languages... Un classique en fait.

[JolyLoic]

Oh ?
D'ailleurs je n'ai jamais vu de cout corrompu sur la sortie standard en multithread...

Moi, si.

[bountykiler]

Bonjour à tous,

concernant ton implémentation, il y a quand même un truc qui me chiffone grave :
Le fait que l'écriture se fait dans ton destructcteur. Et ce pour 2 raisons:
- Conceptuellement : un destructeur a pour role de libérer les ressources allouées par ta variable, pas d'effectuer le travail comme c'est le cas ici.
- Plus concrètement : sauf erreur de ma part, si un exception est générée dans un destructeur, cela a pour conséquence l'appel à std::terminate et plante directement l'application sans aucune récupération possible. Autrement dit, si le moindre problème survient au moment de l'écriture du message dans le fichier, cela conduira au plantage pur et simple de ton appli.

C'est pourquoi je trouve cette pratique TRES dangeureuse, limite à proscrire (et ce quoi qu'en dise/pense l'auteur de l'article que tu cites), ou alors il faut au minimum protéger cette partie du code avec un try/catch.

Perso, je remplacerai cela par l'utilisation d'une classe logstream qui serai renvoyé par la méthode log.
Cette classe surchargerai l'opérateur <<, serai responsable de construire la chaine de caractère à écrire, et ferai l'écriture dans le fichier proprement dite au moment ou elle reçoit le std::endl.

En plus, cette méthode a pour avantage que tu peux réutiliser ta variable logger plutot que de la réinstancier à chaque fois. Typiquement :

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
 
 
/* dans le .h */
class maClasse{
//...
static Logger logger;
}
 
/* dans le .cpp */
maClasse::Logger logger("RWL");
 
void maClasse::doSomething(int aParameter)
{
    if(aParameter <= 0)
    {
        logger.log(rwl::Logger::Level::info) << "Nothing to do" << std::endl;
    }
    else
    {
        logger.log(rwl::Logger::Level::info) << "Shit, I have to work" << std::endl;
        //...
        logger.log(rwl::Logger::Level::info) << "Work done, finally" << std::endl;
    }
}

@Emmanuel Deloget >> Pour ce qui est de l'histoire de "logguer en mémoire", je crois en fait que l'idée est de construire la chaine à écrire en RAM, et ensuite de tout envoyer au fichier en 1 fois, ce afin d'éviter justement les problèmes liés au multithread (avec à ce moment là un std::endl envoyé au filestream pour s'assurer que le buffer sera bien flushé).

[Emmanuel Deloget]

Oh ? A ce point ? Pourtant je peux lire sur cppreference ceci pour chaque stream standard (cout, clog, etc.) :


Ah, ce n'est pas valable pour les fichiers... Dans ce cas ne vaut-il pas mieux utiliser les flux standards ?

D'ailleurs je n'ai jamais vu de cout corrompu sur la sortie standard en multithread...

La plupart des implémentations mettent des locks sur cout, cerr et cin. Du coup, l'utilisation est "safe", mais la sortie est quand même corrompue.

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

1
2
3
4
5
6
7
8
 
// thread 1
while (1)
  std::cout << "sortie " << "un peu à l'ouest" << std::endl;
 
// thread 2
while (1)
  std::cout << "oh ! " << "La belle bleue !" << std::endl;

Il y a très, très peu de chance pour que la sortie soit vraiement celle que tu attends (tu as plus de chance d'avoir des lignes sautées un peu n'importe comment, des choses mélangées, etc. L'écriture sur le device réel n'est pas atomique - donc il est tout à fait envisageable d'avoir

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

1
2
3
 
sortieoh ! La beun peu àlle bleue !
 !'ouest

Ce qu'on peut quand même qualifier de corruption

[JolyLoic]

- Plus concrètement : sauf erreur de ma part, si un exception est générée dans un destructeur, cela a pour conséquence l'appel à std::terminate et plante directement l'application sans aucune récupération possible. Autrement dit, si le moindre problème survient au moment de l'écriture du message dans le fichier, cela conduira au plantage pur et simple de ton appli.

C'est un peu plus subtil que ça, même si au final, le conseil est le même. Si une exception est lancée, on remonte la pile d'appel en appelant les destructeurs des objets locaux. Donc si un tel destructeur lance une exception, ça signifie qu'il peut y avoir une exception lancée pendant la propagation d'une autre exception. C'est cette situation, où l'on aurait deux exception remontant d'un coup, qui lance un std::terminate.

@Emmanuel Deloget >> Pour ce qui est de l'histoire de "logguer en mémoire", je crois en fait que l'idée est de construire la chaine à écrire en RAM, et ensuite de tout envoyer au fichier en 1 fois, ce afin d'éviter justement les problèmes liés au multithread (avec à ce moment là un std::endl envoyé au filestream pour s'assurer que le buffer sera bien flushé).

Le problème est que généralement on a envie de logger le plus immédiatement possible dans une fichier, de manière à ce que quoi qu'il arrive, même en cas de plantage violent ou de perte d'alimentation de la machine, ce soient les informations les plus récentes possibles qui soient loggées.

[Médinoc]

@Emmanuel Deloget: Ton exemple est mauvais parce que tu as mis des interruptions au milieu des chaînes elles-mêmes, ce qui n'est pas possible avec des locks.

Ça ressemblerait plutôt à ceci:

Code X :

Sélectionner tout - Visualiser dans une fenêtre à part

sortie oh ! un peu à l'ouestla belle bleue !

Ce qui reste de la corruption en effet, donc sur le fond tu avais raison.

[RT222]

Eh bah! Je ne me serais jamais douté que créer un logger, même primaire, était un tel casse tête.

J'ai donc à nouveau suivi vos conseils du mieux que je l'ai pu, et me revoici avec une nouvelle implémentation, proche de la précédente, mais sans utiliser de destructeur pour flusher, et en Singleton :

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
/*
** logger.hpp
*/
#pragma once
 
#include <RWL/Cpp_Tools/class_templates.hpp>
#include <RWL/Cpp_Tools/debug.hpp>
#include <iostream>
#include <string>
#include <sstream>
#include <fstream>
#include <map>
#include <memory>
 
#define LOG_LOCATION	L" [" << __WFILE__ << L", line " << __LINE__ << L"]"
#define RWL_LOGGER	rwl::Logger::get_instance()
 
namespace rwl
{
 
class Logger :
	public Singleton< Logger >
{
	friend class Singleton< Logger >;
 
public :
	enum class Level
	{
		trace,
		debug,
		info,
		warning,
		error,
		exception,
		fatal
	};
 
	class Log_stream
	{
		friend class Logger;
	public:
		Log_stream( void );
		~Log_stream( void );
		Log_stream( const Log_stream& log_stream );
		Log_stream&	operator=( const Log_stream& log_stream );
		template< typename T >
		Log_stream&	operator<<( T&& input );
		Log_stream&	operator<<( std::wostream& ( *f )( std::wostream& ) );
 
	private:
		bool					m_enable;
		Level					m_min_level;
		Level					m_level;
		std::shared_ptr< std::wofstream >	m_logfile;
	};
 
			Logger( void );
			~Logger( void );
	Log_stream&	log( Level level, const std::wstring& name = L"" );
	void		enable( bool enable, const std::wstring& name = L"" );
	void		set_level( Level level, const std::wstring& name = L"" );
	void		set_logfile( const std::wstring& file_path, const std::wstring& name = L"" );
 
private:
	typedef std::map< const std::wstring, Log_stream > Log_stream_map;
 
	Log_stream_map	m_log_streams;
};
 
}

J'ai surchargé l'opérateur << comme me l'a recommandé Bountykiler, et le flush se fait donc via std::endl ou std::flush. Un des avantages de cette méthode, c'est que je n'utilise plus de stream intermédiaire, je logge directement dans les fluxs appropriés :

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
template < typename T >
Logger::Log_stream&	Logger::Log_stream::operator<<( T&& input )
{
	if ( m_enable && m_level >= m_min_level )
	{
		if ( m_level <= Logger::Level::info )
			std::wcout << input;
		else if ( m_level >= Logger::Level::warning )
			std::wcerr << input;
 
		if ( m_logfile->is_open() && m_logfile->good() )
			*m_logfile << input;
	}
	return ( *this );
}

Alors ça n'est toujours pas thread safe, mais j'ai bien compris qu'il faudra que je songe rapidement à corriger cela et l'ai noté en gros et en gras dans ma todo-list.

[bountykiler]

C'est un peu plus subtil que ça, même si au final, le conseil est le même. Si une exception est lancée, on remonte la pile d'appel en appelant les destructeurs des objets locaux. Donc si un tel destructeur lance une exception, ça signifie qu'il peut y avoir une exception lancée pendant la propagation d'une autre exception. C'est cette situation, où l'on aurait deux exception remontant d'un coup, qui lance un std::terminate.

Oui c'est bien ça! Je sais que j'avais déjà lu cela quelque part, mais j'avoue que je me souvenais plus exactement de ce qu'il en était.
Quoi qu'il en soit, merci pour la précision.