Line data Source code
1 : /* Copyright (C) 2022 Wildfire Games.
2 : * This file is part of 0 A.D.
3 : *
4 : * 0 A.D. is free software: you can redistribute it and/or modify
5 : * it under the terms of the GNU General Public License as published by
6 : * the Free Software Foundation, either version 2 of the License, or
7 : * (at your option) any later version.
8 : *
9 : * 0 A.D. is distributed in the hope that it will be useful,
10 : * but WITHOUT ANY WARRANTY; without even the implied warranty of
11 : * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
12 : * GNU General Public License for more details.
13 : *
14 : * You should have received a copy of the GNU General Public License
15 : * along with 0 A.D. If not, see <http://www.gnu.org/licenses/>.
16 : */
17 :
18 : #include "precompiled.h"
19 :
20 : #include "CLogger.h"
21 :
22 : #include "graphics/Canvas2D.h"
23 : #include "graphics/FontMetrics.h"
24 : #include "graphics/TextRenderer.h"
25 : #include "lib/os_path.h"
26 : #include "lib/timer.h"
27 : #include "lib/utf8.h"
28 : #include "ps/CConsole.h"
29 : #include "ps/CStr.h"
30 : #include "ps/CStrInternStatic.h"
31 : #include "ps/Profile.h"
32 : #include "ps/Pyrogenesis.h"
33 :
34 : #include <ctime>
35 : #include <fstream>
36 : #include <iostream>
37 :
38 : #include <boost/algorithm/string/replace.hpp>
39 :
40 1 : CStrW g_UniqueLogPostfix;
41 : static const double RENDER_TIMEOUT = 10.0; // seconds before messages are deleted
42 : static const double RENDER_TIMEOUT_RATE = 10.0; // number of timed-out messages deleted per second
43 : static const size_t RENDER_LIMIT = 20; // maximum messages on screen at once
44 :
45 : // Set up a default logger that throws everything away, because that's
46 : // better than crashing. (This is particularly useful for unit tests which
47 : // don't care about any log output.)
48 2 : struct BlackHoleStreamBuf : public std::streambuf
49 : {
50 1 : } blackHoleStreamBuf;
51 1 : std::ostream blackHoleStream(&blackHoleStreamBuf);
52 1 : CLogger nullLogger(&blackHoleStream, &blackHoleStream, false, true);
53 :
54 : CLogger* g_Logger = &nullLogger;
55 :
56 : const char* html_header0 =
57 : "<!DOCTYPE html>\n"
58 : "<meta charset=\"utf-8\">\n"
59 : "<title>Pyrogenesis Log</title>\n"
60 : "<style>"
61 : "body { background: #eee; color: black; font-family: sans-serif; } "
62 : "p { background: white; margin: 3px 0 3px 0; } "
63 : ".error { color: red; } "
64 : ".warning { color: blue; }"
65 : "</style>\n"
66 : "<h2>0 A.D. (";
67 :
68 : const char* html_header1 = "</h2>\n";
69 :
70 0 : CLogger::CLogger()
71 : {
72 0 : OsPath mainlogPath(psLogDir() / (L"mainlog" + g_UniqueLogPostfix + L".html"));
73 0 : m_MainLog = new std::ofstream(OsString(mainlogPath).c_str(), std::ofstream::out | std::ofstream::trunc);
74 0 : debug_printf("FILES| Main log written to '%s'\n", mainlogPath.string8().c_str());
75 :
76 0 : OsPath interestinglogPath(psLogDir() / (L"interestinglog" + g_UniqueLogPostfix + L".html"));
77 0 : m_InterestingLog = new std::ofstream(OsString(interestinglogPath).c_str(), std::ofstream::out | std::ofstream::trunc);
78 0 : debug_printf("FILES| Interesting log written to '%s'\n", interestinglogPath.string8().c_str());
79 :
80 0 : m_OwnsStreams = true;
81 0 : m_UseDebugPrintf = true;
82 :
83 0 : Init();
84 0 : }
85 :
86 130 : CLogger::CLogger(std::ostream* mainLog, std::ostream* interestingLog, bool takeOwnership, bool useDebugPrintf)
87 : {
88 130 : m_MainLog = mainLog;
89 130 : m_InterestingLog = interestingLog;
90 130 : m_OwnsStreams = takeOwnership;
91 130 : m_UseDebugPrintf = useDebugPrintf;
92 :
93 130 : Init();
94 130 : }
95 :
96 130 : void CLogger::Init()
97 : {
98 130 : m_RenderLastEraseTime = -1.0;
99 : // this is called too early to allow us to call timer_Time(),
100 : // so we'll fill in the initial value later
101 :
102 130 : m_NumberOfMessages = 0;
103 130 : m_NumberOfErrors = 0;
104 130 : m_NumberOfWarnings = 0;
105 :
106 130 : *m_MainLog << html_header0 << engine_version << ") Main log" << html_header1;
107 130 : *m_InterestingLog << html_header0 << engine_version << ") Main log (warnings and errors only)" << html_header1;
108 130 : }
109 :
110 260 : CLogger::~CLogger()
111 : {
112 : char buffer[128];
113 130 : sprintf_s(buffer, ARRAY_SIZE(buffer), " with %d message(s), %d error(s) and %d warning(s).", m_NumberOfMessages,m_NumberOfErrors,m_NumberOfWarnings);
114 :
115 130 : time_t t = time(NULL);
116 130 : struct tm* now = localtime(&t);
117 : char currentDate[17];
118 130 : sprintf_s(currentDate, ARRAY_SIZE(currentDate), "%04d-%02d-%02d", 1900+now->tm_year, 1+now->tm_mon, now->tm_mday);
119 : char currentTime[10];
120 130 : sprintf_s(currentTime, ARRAY_SIZE(currentTime), "%02d:%02d:%02d", now->tm_hour, now->tm_min, now->tm_sec);
121 :
122 : //Write closing text
123 :
124 130 : *m_MainLog << "<p>Engine exited successfully on " << currentDate;
125 130 : *m_MainLog << " at " << currentTime << buffer << "</p>\n";
126 :
127 130 : *m_InterestingLog << "<p>Engine exited successfully on " << currentDate;
128 130 : *m_InterestingLog << " at " << currentTime << buffer << "</p>\n";
129 :
130 130 : if (m_OwnsStreams)
131 : {
132 3 : SAFE_DELETE(m_InterestingLog);
133 3 : SAFE_DELETE(m_MainLog);
134 : }
135 130 : }
136 :
137 544 : static std::string ToHTML(const char* message)
138 : {
139 544 : std::string cmessage = message;
140 544 : boost::algorithm::replace_all(cmessage, "&", "&");
141 544 : boost::algorithm::replace_all(cmessage, "<", "<");
142 544 : return cmessage;
143 : }
144 :
145 284 : void CLogger::WriteMessage(const char* message, bool doRender = false)
146 : {
147 568 : std::string cmessage = ToHTML(message);
148 :
149 568 : std::lock_guard<std::mutex> lock(m_Mutex);
150 :
151 284 : ++m_NumberOfMessages;
152 : // if (m_UseDebugPrintf)
153 : // debug_printf("MESSAGE: %s\n", message);
154 :
155 284 : *m_MainLog << "<p>" << cmessage << "</p>\n";
156 284 : m_MainLog->flush();
157 :
158 284 : if (doRender)
159 : {
160 0 : if (g_Console) g_Console->InsertMessage(std::string("INFO: ") + message);
161 :
162 0 : PushRenderMessage(Normal, message);
163 : }
164 284 : }
165 :
166 234 : void CLogger::WriteError(const char* message)
167 : {
168 468 : std::string cmessage = ToHTML(message);
169 :
170 468 : std::lock_guard<std::mutex> lock(m_Mutex);
171 :
172 234 : ++m_NumberOfErrors;
173 234 : if (m_UseDebugPrintf)
174 0 : debug_printf("ERROR: %.16000s\n", message);
175 :
176 234 : if (g_Console) g_Console->InsertMessage(std::string("ERROR: ") + message);
177 234 : *m_InterestingLog << "<p class=\"error\">ERROR: " << cmessage << "</p>\n";
178 234 : m_InterestingLog->flush();
179 :
180 234 : *m_MainLog << "<p class=\"error\">ERROR: " << cmessage << "</p>\n";
181 234 : m_MainLog->flush();
182 :
183 234 : PushRenderMessage(Error, message);
184 234 : }
185 :
186 26 : void CLogger::WriteWarning(const char* message)
187 : {
188 52 : std::string cmessage = ToHTML(message);
189 :
190 52 : std::lock_guard<std::mutex> lock(m_Mutex);
191 :
192 26 : ++m_NumberOfWarnings;
193 26 : if (m_UseDebugPrintf)
194 0 : debug_printf("WARNING: %s\n", message);
195 :
196 26 : if (g_Console) g_Console->InsertMessage(std::string("WARNING: ") + message);
197 26 : *m_InterestingLog << "<p class=\"warning\">WARNING: " << cmessage << "</p>\n";
198 26 : m_InterestingLog->flush();
199 :
200 26 : *m_MainLog << "<p class=\"warning\">WARNING: " << cmessage << "</p>\n";
201 26 : m_MainLog->flush();
202 :
203 26 : PushRenderMessage(Warning, message);
204 26 : }
205 :
206 0 : void CLogger::Render(CCanvas2D& canvas)
207 : {
208 0 : PROFILE3_GPU("logger");
209 :
210 0 : CleanupRenderQueue();
211 :
212 0 : CStrIntern font_name("mono-stroke-10");
213 0 : CFontMetrics font(font_name);
214 0 : int lineSpacing = font.GetLineSpacing();
215 :
216 0 : CTextRenderer textRenderer;
217 0 : textRenderer.SetCurrentFont(font_name);
218 0 : textRenderer.SetCurrentColor(CColor(1.0f, 1.0f, 1.0f, 1.0f));
219 :
220 : // Offset by an extra 35px vertically to avoid the top bar.
221 0 : textRenderer.Translate(4.0f, 35.0f + lineSpacing);
222 :
223 : // (Lock must come after loading the CFont, since that might log error messages
224 : // and attempt to lock the mutex recursively which is forbidden)
225 0 : std::lock_guard<std::mutex> lock(m_Mutex);
226 :
227 0 : for (const RenderedMessage& msg : m_RenderMessages)
228 : {
229 : const char* type;
230 0 : if (msg.method == Normal)
231 : {
232 0 : type = "info";
233 0 : textRenderer.SetCurrentColor(CColor(0.0f, 0.8f, 0.0f, 1.0f));
234 : }
235 0 : else if (msg.method == Warning)
236 : {
237 0 : type = "warning";
238 0 : textRenderer.SetCurrentColor(CColor(1.0f, 1.0f, 0.0f, 1.0f));
239 : }
240 : else
241 : {
242 0 : type = "error";
243 0 : textRenderer.SetCurrentColor(CColor(1.0f, 0.0f, 0.0f, 1.0f));
244 : }
245 :
246 0 : const CVector2D savedTranslate = textRenderer.GetTranslate();
247 :
248 0 : textRenderer.PrintfAdvance(L"[%8.3f] %hs: ", msg.time, type);
249 : // Display the actual message in white so it's more readable
250 0 : textRenderer.SetCurrentColor(CColor(1.0f, 1.0f, 1.0f, 1.0f));
251 0 : textRenderer.Put(0.0f, 0.0f, msg.message.c_str());
252 :
253 0 : textRenderer.ResetTranslate(savedTranslate);
254 :
255 0 : textRenderer.Translate(0.0f, (float)lineSpacing);
256 : }
257 :
258 0 : canvas.DrawText(textRenderer);
259 0 : }
260 :
261 260 : void CLogger::PushRenderMessage(ELogMethod method, const char* message)
262 : {
263 260 : double now = timer_Time();
264 :
265 : // Add each message line separately
266 260 : const char* pos = message;
267 : const char* eol;
268 292 : while ((eol = strchr(pos, '\n')) != NULL)
269 : {
270 16 : if (eol != pos)
271 : {
272 32 : RenderedMessage r = { method, now, std::string(pos, eol) };
273 16 : m_RenderMessages.push_back(r);
274 : }
275 16 : pos = eol + 1;
276 : }
277 : // Add the last line, if we didn't end on a \n
278 260 : if (*pos != '\0')
279 : {
280 510 : RenderedMessage r = { method, now, std::string(pos) };
281 255 : m_RenderMessages.push_back(r);
282 : }
283 260 : }
284 :
285 0 : void CLogger::CleanupRenderQueue()
286 : {
287 0 : std::lock_guard<std::mutex> lock(m_Mutex);
288 :
289 0 : if (m_RenderMessages.empty())
290 0 : return;
291 :
292 0 : double now = timer_Time();
293 :
294 : // Initialise the timer on the first call (since we can't do it in the ctor)
295 0 : if (m_RenderLastEraseTime == -1.0)
296 0 : m_RenderLastEraseTime = now;
297 :
298 : // Delete old messages, approximately at the given rate limit (and at most one per frame)
299 0 : if (now - m_RenderLastEraseTime > 1.0/RENDER_TIMEOUT_RATE)
300 : {
301 0 : if (m_RenderMessages[0].time + RENDER_TIMEOUT < now)
302 : {
303 0 : m_RenderMessages.pop_front();
304 0 : m_RenderLastEraseTime = now;
305 : }
306 : }
307 :
308 : // If there's still too many then delete the oldest
309 0 : if (m_RenderMessages.size() > RENDER_LIMIT)
310 0 : m_RenderMessages.erase(m_RenderMessages.begin(), m_RenderMessages.end() - RENDER_LIMIT);
311 : }
312 :
313 126 : TestLogger::TestLogger()
314 : {
315 126 : m_OldLogger = g_Logger;
316 126 : g_Logger = new CLogger(&m_Stream, &blackHoleStream, false, false);
317 126 : }
318 :
319 252 : TestLogger::~TestLogger()
320 : {
321 126 : delete g_Logger;
322 126 : g_Logger = m_OldLogger;
323 126 : }
324 :
325 28 : std::string TestLogger::GetOutput()
326 : {
327 28 : return m_Stream.str();
328 : }
329 :
330 0 : TestStdoutLogger::TestStdoutLogger()
331 : {
332 0 : m_OldLogger = g_Logger;
333 0 : g_Logger = new CLogger(&std::cout, &blackHoleStream, false, false);
334 0 : }
335 :
336 0 : TestStdoutLogger::~TestStdoutLogger()
337 : {
338 0 : delete g_Logger;
339 0 : g_Logger = m_OldLogger;
340 3 : }
|
