|
1 // tclog.cpp |
|
2 // |
|
3 // Copyright (c) 2006 - 2010 Accenture. All rights reserved. |
|
4 // This component and the accompanying materials are made available |
|
5 // under the terms of the "Eclipse Public License v1.0" |
|
6 // which accompanies this distribution, and is available |
|
7 // at the URL "http://www.eclipse.org/legal/epl-v10.html". |
|
8 // |
|
9 // Initial Contributors: |
|
10 // Accenture - Initial contribution |
|
11 // |
|
12 |
|
13 #include <e32base.h> |
|
14 #define USE_CLOGGER |
|
15 #include <fshell/clogger.h> |
|
16 #include <e32math.h> |
|
17 #include <f32file.h> |
|
18 #include <badesca.h> |
|
19 #include <flogger.h> |
|
20 #include "debugrouter.h" |
|
21 |
|
22 _LIT(KStaticTag, "tclog::Main"); |
|
23 _LIT(KTag, "tclog1"); |
|
24 |
|
25 #undef ASSERT |
|
26 #define ASSERT(x) __ASSERT_ALWAYS(x, AssertionFail(#x, __FILE__, __LINE__)) |
|
27 |
|
28 __NORETURN__ void AssertionFail(const char* aAssertion, const char* aFile, TInt aLine) |
|
29 { |
|
30 RDebug::Printf("Assertion failed: \"%s\" in %s:%i", aAssertion, aFile, aLine); |
|
31 __DEBUGGER(); |
|
32 User::Panic(_L("TCLOG"), aLine); |
|
33 } |
|
34 |
|
35 // Don't instanciate this directly (you can't because of non-exported virtuals) but use the tclogger macro to cheat |
|
36 class RTestClogger : public RClogger |
|
37 { |
|
38 public: |
|
39 void FlushLog() |
|
40 { |
|
41 TUint opts = GetGlobalOptions(); |
|
42 SetGlobalOptions(0); // Flush log by disabling buffer |
|
43 SetGlobalOptions(opts); |
|
44 } |
|
45 |
|
46 void ExpectTagChanged() |
|
47 { |
|
48 iFlags |= 0x10000000; // Magic, see KTestTagEnabled in CloggerClient.cpp |
|
49 } |
|
50 |
|
51 void CheckTagChanged() |
|
52 { |
|
53 ASSERT(!(iFlags & 0x10000000)); |
|
54 } |
|
55 |
|
56 void AlignLogToFourK(TInt aLessThisAmount) |
|
57 { |
|
58 SendReceive(2000, TIpcArgs(aLessThisAmount)); // See EDebugAlignLogFile in cliserv.h |
|
59 } |
|
60 |
|
61 void Shutdown() |
|
62 { |
|
63 SendReceive(2001, TIpcArgs()); |
|
64 Close(); |
|
65 RClogger::StaticClose(); // So that our TLS isn't left set to an invalid reference |
|
66 } |
|
67 |
|
68 void ForceBreakpoint() |
|
69 { |
|
70 SendReceive(2003, TIpcArgs()); |
|
71 } |
|
72 }; |
|
73 |
|
74 #define tclogger (*reinterpret_cast<RTestClogger*>(&clogger)) |
|
75 |
|
76 enum TTests |
|
77 { |
|
78 EBasicTests, // 0 |
|
79 ESoakTests, // 1 |
|
80 ERdebugRedirect, // 2 |
|
81 ESoakAndRDebug, // 3 |
|
82 ECreateLogsDir, // 4 |
|
83 EDoPerformanceLogging, // 5 |
|
84 EDebugRouter, // 6 |
|
85 ESessionWriter, // 7 |
|
86 ENumTests // Must be last in list |
|
87 }; |
|
88 |
|
89 void DoBasicTestsL(); |
|
90 void SoakTestsL(TBool aRedirectRDebug); |
|
91 void DoRDebugTestsL(); |
|
92 void DoCreateLogsDirTest(); |
|
93 void TestPerformanceLoggingL(); |
|
94 void DebugRouterL(); |
|
95 void SessionWriterL(); |
|
96 |
|
97 RFs fs; |
|
98 RClogger clogger; |
|
99 |
|
100 void RunTestsL() |
|
101 { |
|
102 TBuf<32> cmd; |
|
103 User::CommandLine(cmd); |
|
104 if (cmd.Length() == 0) |
|
105 { |
|
106 // Syntax: tclog all |
|
107 // tclog 0 3 5 to run tests 0, 3 and 5 |
|
108 User::Invariant(); |
|
109 } |
|
110 |
|
111 // Figure out what tests to run |
|
112 TUint8 runTests[ENumTests]; |
|
113 Mem::FillZ(&runTests, sizeof(runTests)); |
|
114 if (cmd == _L("all")) |
|
115 { |
|
116 Mem::Fill(&runTests, sizeof(runTests), 1); |
|
117 } |
|
118 else |
|
119 { |
|
120 TLex lex(cmd); |
|
121 TInt err = KErrNone; |
|
122 while (err == KErrNone) |
|
123 { |
|
124 TInt n; |
|
125 err = lex.Val(n); |
|
126 if (!err && n < ENumTests) |
|
127 { |
|
128 runTests[n] = ETrue; |
|
129 } |
|
130 lex.SkipSpace(); |
|
131 } |
|
132 } |
|
133 |
|
134 // Now actually run them |
|
135 User::LeaveIfError(clogger.Connect(KTag)); |
|
136 User::LeaveIfError(fs.Connect()); |
|
137 |
|
138 if (runTests[EBasicTests]) DoBasicTestsL(); |
|
139 if (runTests[ESoakTests]) SoakTestsL(EFalse); |
|
140 if (runTests[ERdebugRedirect]) DoRDebugTestsL(); |
|
141 if (runTests[ESoakAndRDebug]) SoakTestsL(ETrue); |
|
142 if (runTests[ECreateLogsDir]) DoCreateLogsDirTest(); |
|
143 if (runTests[EDoPerformanceLogging]) TestPerformanceLoggingL(); |
|
144 if (runTests[EDebugRouter]) DebugRouterL(); |
|
145 if (runTests[ESessionWriter]) SessionWriterL(); |
|
146 |
|
147 tclogger.FlushLog(); |
|
148 clogger.Close(); |
|
149 fs.Close(); |
|
150 } |
|
151 |
|
152 |
|
153 |
|
154 void DoBasicTestsL() |
|
155 { |
|
156 CActiveScheduler* s = NULL; |
|
157 |
|
158 // Try spawning multiple servers to ensure that the failed-to-initialise case is handled ok in the server |
|
159 tclogger.Shutdown(); |
|
160 clogger.Close(); |
|
161 RProcess proc1, proc2, proc3; |
|
162 proc1.Create(_L("CloggerServer.exe"), KNullDesC); |
|
163 proc2.Create(_L("CloggerServer.exe"), KNullDesC); |
|
164 proc3.Create(_L("CloggerServer.exe"), KNullDesC); |
|
165 proc1.Resume(); |
|
166 proc2.Resume(); |
|
167 proc3.Resume(); |
|
168 User::LeaveIfError(clogger.Connect(KTag)); |
|
169 |
|
170 clogger.Log(_L("1 This is %s format string"), L"my"); |
|
171 // Use static methods to check that the format buffer is deallocated when we do our heapcheck at the end |
|
172 SLOG(_L("2 A 16-bit anonymous log entry - the tag at the start should be [%S]"), &KStaticTag); |
|
173 |
|
174 clogger.SetGlobalOptions(RClogger::EBufferLog); |
|
175 ASSERT(clogger.GetGlobalOptions() & RClogger::EBufferLog); // This will fail if the buffer allocation has messed up |
|
176 clogger.Log(_L("3 This should appear when we turn buffering off")); |
|
177 clogger.SetGlobalOptions(0); |
|
178 |
|
179 clogger.SetGlobalOptions(RClogger::ERDebugPrint); |
|
180 clogger.Log(_L8("4 This should appear on RDebug::Print")); |
|
181 clogger.SetGlobalOptions(RClogger::EBufferLog|RClogger::ERDebugPrint); |
|
182 clogger.Log(_L8("5 This and all future lines up until the idle timer one should also appear on RDebug::Print")); |
|
183 |
|
184 clogger.Log(_L("6 An entry...")); |
|
185 User::After(2000000); |
|
186 clogger.Log(_L("7 ...and another 2 seconds later")); |
|
187 |
|
188 clogger.SetEnabled(KStaticTag, 0); |
|
189 _LIT(KEnabled, "Enabled"); |
|
190 _LIT(KDisabled, "Disabled"); |
|
191 SLOG(_L("This shouldn't appear in the log file because the tag is %S"), clogger.IsEnabled(KStaticTag) ? &KEnabled : &KDisabled); |
|
192 |
|
193 clogger.SetEnabled(KStaticTag, RClogger::EAllEnabled); |
|
194 SLOG(_L("8 Tag is now enabled again")); |
|
195 |
|
196 TInt heapSize = User::Allocator().Count(); |
|
197 RClogger::SetStaticLogBehaviour(RClogger::EUseHeapBuffer); |
|
198 RClogger::Slog(_L("9 This call should cause the heapsize to go up by two cells as the TLS is upgraded and the format buffer is cached")); |
|
199 if (User::Allocator().Count() == heapSize + 2) |
|
200 { |
|
201 SLOG("10 And it did!"); |
|
202 } |
|
203 else |
|
204 { |
|
205 SLOG("BUT IT DIDN'T!"); |
|
206 } |
|
207 RClogger::StaticClose(); // So the heaptest passes |
|
208 |
|
209 clogger.SetEnabled(KStaticTag, 2); |
|
210 SLOG(1, _L("This shouldn't appear because the log mask is only 0x2")); |
|
211 SLOG(3, _L8("11 Logging to multiple masks will work so long as at least one of them is enabled")); |
|
212 |
|
213 TInt numBuffers; |
|
214 TInt size = clogger.GetRamBufferSize(&numBuffers); |
|
215 |
|
216 clogger.Log("12 %i buffers of size %i", numBuffers, size); |
|
217 clogger.SetRamBufferSize(1024, 3); |
|
218 size = clogger.GetRamBufferSize(&numBuffers); |
|
219 SLOG("13 new settings %i buffers of size %i", numBuffers, size); |
|
220 |
|
221 s=new(ELeave) CActiveScheduler; |
|
222 CActiveScheduler::Install(s); |
|
223 clogger.SetLogBehaviour(RClogger::EMonitorTagState); |
|
224 clogger.SetEnabled(KTag, EFalse); |
|
225 tclogger.ExpectTagChanged(); |
|
226 //CActiveScheduler::Start(); |
|
227 SLOG("14 Disabled tag"); |
|
228 clogger.Log("This shouldn't appear as we're disabled - in fact it shouldn't get as far as the server"); |
|
229 tclogger.CheckTagChanged(); |
|
230 clogger.SetEnabled(KTag, RClogger::EAllEnabled); |
|
231 |
|
232 TVolumeInfo volInfo; |
|
233 User::LeaveIfError(fs.Volume(volInfo)); |
|
234 if (volInfo.iFree < 67108864) // Don't fill up the drive unless the emulator is using a C drive < 64MB |
|
235 { |
|
236 // ..---------- --:--:--.---: [Clogger] Log truncated due to disk full\r\n |
|
237 _LIT(KTrunc, "15 This log line should be truncated here: |XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX"); |
|
238 const TInt KTimeStampLength = 36; |
|
239 tclogger.AlignLogToFourK(KTrunc().Length() + KTimeStampLength); // This is needed so that the next write forces a disk allocation (and doesn't just fill up an already-allocated cluster) |
|
240 clogger.Log(KTrunc); |
|
241 tclogger.FlushLog(); |
|
242 |
|
243 TFileName tempName; |
|
244 RFile file; |
|
245 file.Temp(fs, _L("C:\\logs\\"), tempName, EFileShareExclusive|EFileWrite); |
|
246 User::LeaveIfError(fs.Volume(volInfo)); |
|
247 TInt err = file.SetSize((TUint)volInfo.iFree); |
|
248 ASSERT(!err); |
|
249 |
|
250 clogger.Log("This line shouldn't appear in the log because the disk is full"); |
|
251 tclogger.FlushLog(); |
|
252 clogger.Log("This line shouldn't either"); |
|
253 tclogger.FlushLog(); |
|
254 |
|
255 file.Close(); |
|
256 User::LeaveIfError(fs.Delete(tempName)); |
|
257 } |
|
258 else |
|
259 { |
|
260 clogger.Log("15 Unable to run disk full test - run emulator with -ci:\\ -- to enable it"); |
|
261 } |
|
262 |
|
263 CDesCArray* tags; |
|
264 RBuf8 enabled; |
|
265 clogger.GetTagStatesL(tags, enabled); |
|
266 TInt n = tags->Count(); |
|
267 while (n--) |
|
268 { |
|
269 TPtrC tagName = tags->MdcaPoint(n); |
|
270 SLOG(_L("16 Tag %S is enabled with 0x%x"), &tagName, *((TInt*)&enabled[n*4])); |
|
271 } |
|
272 SLOG("17 Inverting all tags enabled attributes (and ORing with 0x1 so we can still log)"); |
|
273 n = tags->Count(); |
|
274 for (TInt i = 0; i < n; i++) |
|
275 { |
|
276 *((TUint32*)&enabled[i*4]) = 1 | ~ *((TUint32*)&enabled[i*4]); |
|
277 } |
|
278 clogger.SetTagStatesL(tags, enabled); |
|
279 delete tags; |
|
280 clogger.GetTagStatesL(tags, enabled); |
|
281 n = tags->Count(); |
|
282 while (n--) |
|
283 { |
|
284 TPtrC tagName = tags->MdcaPoint(n); |
|
285 SLOG(_L("18 Tag %S is enabled with 0x%x"), &tagName, *((TInt*)&enabled[n*4])); |
|
286 } |
|
287 |
|
288 enabled.Close(); |
|
289 delete tags; |
|
290 |
|
291 tclogger.FlushLog(); |
|
292 clogger.SetGlobalOptions(RClogger::EBufferLog); |
|
293 clogger.Log("19 This line should appear when the idle timer flushes the buffer"); |
|
294 User::After(1000000); |
|
295 clogger.Log(_L("This shouldn't appear in the log file because we're buffering")); |
|
296 clogger.SetGlobalOptions(RClogger::EBufferLog); // Setting the global options to be the same as before shouldn't trigger a buffer flush |
|
297 |
|
298 // Test cenrep persistance |
|
299 tclogger.Shutdown(); |
|
300 //CActiveScheduler::Start(); //DEBUG testing ServerDied |
|
301 clogger.Connect(KTag); |
|
302 clogger.SetRamBufferSize(3000, 9); |
|
303 clogger.PersistSettings(); |
|
304 tclogger.Shutdown(); |
|
305 clogger.Connect(KTag); |
|
306 size = clogger.GetRamBufferSize(&numBuffers); |
|
307 ASSERT(numBuffers == 9 && size == 3000); // This test can also fail if the disk is full (and therefore cenrep couldn't save the settings). |
|
308 clogger.ResetSettings(); |
|
309 |
|
310 const TUint32 KEnabledMask = 0xB2FA1128; |
|
311 clogger.Log(_L("20 testing persistance of tag enabled settings")); |
|
312 clogger.SetEnabled(KTag, KEnabledMask); |
|
313 clogger.PersistSettings(); |
|
314 tclogger.Shutdown(); |
|
315 clogger.Connect(KTag); |
|
316 ASSERT(clogger.IsEnabled(KTag) == KEnabledMask); |
|
317 |
|
318 TInt err; |
|
319 |
|
320 RClogger clog1, clog2, clog3; |
|
321 clog1.Connect(KTag); |
|
322 clog1.Log("23 Testing multiple sessions for the same tag"); |
|
323 clog2.Connect(KTag); |
|
324 clog3.Connect(KTag); |
|
325 clog2.Log("24 Testing multiple sessions for the same tag"); |
|
326 clog3.Log("25 Testing multiple sessions for the same tag"); |
|
327 clog3.Close(); |
|
328 clog1.Close(); |
|
329 clog2.Close(); |
|
330 |
|
331 _LIT8(KBin, "Newline: \n Null: \0 <EOM>"); // Useful to put a zero byte in there to test that string termination isn't an issue |
|
332 //_LIT(KBigHeader, "27 This header is deliberately more than 256 chars (512 bytes on server side) to check that crazily big headers are handled ok (truncation is fine but crashes aren't!) 123456789 123456789 123456789 123456789 123456789 123456789 123456789 123456789 123456789 End\0\0"); |
|
333 _LIT8(KBigHeader, "27 This header is deliberately more than 256 chars (512 bytes on server side) to check that crazily big headers are handled ok (truncation is fine but crashes aren't!) 123456789 123456789 123456789 123456789 123456789 123456789 123456789 123456789 123456789 End"); |
|
334 //RFileLogger::HexDump(KTag, KNullDesC, EFileLoggingModeAppend, _S16("26 Testing hexdump "), NULL, KBin().Ptr(), KBin().Length()); |
|
335 clogger.HexDump(_L8("26 Testing hexdump"), KBin); |
|
336 //RFileLogger::HexDump(KTag, KNullDesC, EFileLoggingModeAppend, KBigHeader().Ptr(), NULL, KBin().Ptr(), KBin().Length()); |
|
337 clogger.HexDump(KBigHeader, KBin); |
|
338 |
|
339 clogger.SetEnabled(_L("Clogger"), RClogger::EAllEnabled); |
|
340 clogger.Log("28 Testing turning on all of clogger's internal logging"); |
|
341 RClogger longNameClog; |
|
342 _LIT(KBigTag, "This tag is 256 chars to check that big tag names are handled ok, especially when the internal logging is turned on. 123456789 123456789 123456789 123456789 123456789 123456789 123456789 123456789 123456789 123456789 123456789 123456789 123456789 12345 End"); |
|
343 _LIT(KLongTag, "This tag is more than 256 chars to check that too long tag names are return errors when they should. 123456789 123456789 123456789 123456789 123456789 123456789 123456789 123456789 123456789 123456789 123456789 123456789 123456789 123456789 123456789 123456789 12345 End"); |
|
344 err = longNameClog.Connect(KLongTag); |
|
345 ASSERT(err); |
|
346 longNameClog.Connect(KBigTag); |
|
347 longNameClog.SetEnabled(KBigTag, RClogger::EAllEnabled); |
|
348 longNameClog.Log("29 Testing logging with bigTag"); |
|
349 longNameClog.Close(); |
|
350 |
|
351 clogger.Log("29 There should be an empty line after this log statement\n"); |
|
352 clogger.SetLogBehaviour(RClogger::ETrimTrailingNewlines); |
|
353 clogger.Log("30 There should be no empty line after this statement\r\n"); |
|
354 clogger.Log("31 Just checking the trim doesn't fall over if there's no newline!"); |
|
355 |
|
356 delete s; |
|
357 } |
|
358 |
|
359 void DoRDebugTestsL() |
|
360 { |
|
361 clogger.SetGlobalOptions(RClogger::ERedirectRDebugPrintToClogger); |
|
362 RDebug::Printf("30 This should appear in clogger and on RDebug::Print (without a [tag])"); |
|
363 clogger.Log("31 this should not appear on RDebug::Print"); |
|
364 clogger.SetGlobalOptions(RClogger::ERedirectRDebugPrintToClogger | RClogger::EMirrorToRDebugPrint); |
|
365 RDebug::Printf("32 This should appear on RDebug with [tag] and in the clogger log"); |
|
366 clogger.Log("33 So should this"); |
|
367 clogger.SetGlobalOptions(0); |
|
368 RDebug::Printf("This should appear in the RDebug::Print log (without [tag]) and not in the clogger log"); |
|
369 User::After(1000); // Give the rdebug log flusher time to run |
|
370 } |
|
371 |
|
372 _LIT(KTag1, "Static Thread1"); |
|
373 _LIT(KTag2, "Static Thread2"); |
|
374 _LIT(KTag3, "Static Thread3"); |
|
375 _LIT(KTag4, "Static Thread4"); |
|
376 _LIT(KTag5, "Static Thread5"); |
|
377 _LIT(KThreadName1, "Thread1"); |
|
378 _LIT(KThreadName2, "Thread2"); |
|
379 _LIT(KThreadName3, "Thread3"); |
|
380 _LIT(KThreadName4, "Thread4"); |
|
381 _LIT(KThreadName5, "Thread5"); |
|
382 TInt GoGoGadgetThread(TAny* aTag); |
|
383 |
|
384 void SoakTestsL(TBool aRedirectRDebug) |
|
385 { |
|
386 clogger.SetRamBufferSize(512, 2); |
|
387 TUint opt = aRedirectRDebug ? RClogger::ERedirectRDebugPrintToClogger : RClogger::EMirrorToRDebugPrint; |
|
388 clogger.SetGlobalOptions(RClogger::EBufferLog | opt); |
|
389 |
|
390 RThread t[5]; |
|
391 TRequestStatus stat[5]; |
|
392 t[0].Create(KThreadName1, &GoGoGadgetThread, 8192, NULL, (TAny*)&KTag1); |
|
393 t[1].Create(KThreadName2, &GoGoGadgetThread, 8192, NULL, (TAny*)&KTag2); |
|
394 t[2].Create(KThreadName3, &GoGoGadgetThread, 8192, NULL, (TAny*)&KTag3); |
|
395 t[3].Create(KThreadName4, &GoGoGadgetThread, 8192, NULL, (TAny*)&KTag4); |
|
396 t[4].Create(KThreadName5, &GoGoGadgetThread, 8192, NULL, (TAny*)&KTag5); |
|
397 |
|
398 for (TInt i = 0; i < 5; i++) |
|
399 { |
|
400 t[i].Rendezvous(stat[i]); |
|
401 t[i].Resume(); |
|
402 } |
|
403 |
|
404 TInt bytes = 0; |
|
405 for (TInt i = 0; i < 5; i++) |
|
406 { |
|
407 User::WaitForRequest(stat[i]); |
|
408 bytes += stat[i].Int(); |
|
409 t[i].Close(); |
|
410 } |
|
411 |
|
412 clogger.Log("Wrote %i bytes", bytes); |
|
413 clogger.SetGlobalOptions(0); // Flush log |
|
414 } |
|
415 |
|
416 |
|
417 _LIT8(KLorem, "Lorem ipsum dolor sit amet, consectetuer adipiscing elit. Proin ornare, odio quis rhoncus tempor, urna dolor pellentesque arcu, vel feugiat eros odio fringilla magna. Phasellus arcu sapien, malesuada blandit, mollis et, sollicitudin id, felis. Nunc pretium quam a tortor. Sed orci aliquam."); |
|
418 |
|
419 TInt GoGoGadgetThread(TAny* aTag) |
|
420 { |
|
421 // Each thread should log 10000 bytes in as random a way as possible |
|
422 |
|
423 // Use a seed in case we get results we want to replicate |
|
424 TInt64 seed = User::FastCounter(); |
|
425 |
|
426 const TDesC* tag = (const TDesC*)aTag; |
|
427 RClogger clogger; |
|
428 clogger.Connect(*tag); |
|
429 clogger.Log("Connected with random seed %Li", seed); |
|
430 |
|
431 RClogger::SetStaticLogBehaviour(RClogger::EUseHeapBuffer); |
|
432 SLOG(_L("Static logging started from thread %S"), tag); |
|
433 |
|
434 |
|
435 const TInt KNumBytes = 100000; |
|
436 TInt numBytes = 0; |
|
437 |
|
438 TBool rotated = EFalse; |
|
439 while (numBytes < KNumBytes) |
|
440 { |
|
441 TInt rand = Math::Rand(seed); |
|
442 for(TInt i = 0; i < 4; i++) |
|
443 { |
|
444 TInt whatToDo = rand & 0xFF; |
|
445 rand = rand >> 4; |
|
446 |
|
447 if (whatToDo < 16) |
|
448 { |
|
449 User::After(whatToDo); |
|
450 } |
|
451 else |
|
452 { |
|
453 TPtrC8 lorem = KLorem().Left(whatToDo-16); |
|
454 numBytes += 46 + lorem.Size(); // 46 is the size of the timestamp and static tag, |
|
455 if (whatToDo & 0x80) |
|
456 { |
|
457 SLOG(lorem); |
|
458 } |
|
459 else |
|
460 { |
|
461 clogger.Log(lorem); |
|
462 } |
|
463 } |
|
464 } |
|
465 if (aTag == &KTag1 && !rotated && numBytes > KNumBytes/2) |
|
466 { |
|
467 // Thread 1 is responsible for doing a rotate about halfway through |
|
468 rotated = ETrue; |
|
469 clogger.SetRotateBehaviour(4, RClogger::ECopyRotatedToExternalMedia | RClogger::ECompressRotatedLogs); |
|
470 TFileName fn; |
|
471 ASSERT(clogger.Rotate(fn) == KErrNone); |
|
472 ASSERT(fn.Length()); |
|
473 //ASSERT(clogger.Rotate() == KErrNotReady); // Because the server should still be busy doing the background compress |
|
474 // ^ This assumption is not true now, Rotate is now properly synchronous |
|
475 } |
|
476 } |
|
477 clogger.Close(); |
|
478 RClogger::StaticClose(); |
|
479 RThread::Rendezvous(numBytes); |
|
480 return KErrNone; |
|
481 } |
|
482 |
|
483 void DoCreateLogsDirTest() |
|
484 { |
|
485 // Test creating logs folder while server is running |
|
486 tclogger.Shutdown(); |
|
487 TInt err = fs.Rename(_L("C:\\logs"), _L("C:\\logs-disabled")); |
|
488 clogger.Connect(KTag); |
|
489 clogger.SetGlobalOptions(RClogger::EBufferLog); |
|
490 |
|
491 if (err) |
|
492 { |
|
493 SLOG("Couldn't rename logs dir (err=%i)", err); |
|
494 } |
|
495 else |
|
496 { |
|
497 SLOG(_L("21 Started server without logs dir (this will appear in file log because of buffering)")); |
|
498 err = fs.Rename(_L("C:\\logs-disabled"), _L("C:\\logs")); |
|
499 if (!err) |
|
500 { |
|
501 SLOG(_L("22 Logs folder back in business")); |
|
502 } |
|
503 else |
|
504 { |
|
505 SLOG(_L8("Couldn't rename logs-disabled dir (err=%i)"), err); |
|
506 } |
|
507 } |
|
508 } |
|
509 |
|
510 void TestPerformanceLoggingL() |
|
511 { |
|
512 // Can't link directly against both clogger.dll and clogger-buffered.dll, so this is a bit messy |
|
513 RLibrary perfLib; |
|
514 User::LeaveIfError(perfLib.Load(_L("clogger-buffered.dll"))); |
|
515 |
|
516 #ifdef __WINS__ |
|
517 #define KConnectOrdinal 42 |
|
518 #define KSlogOrdinal 34 |
|
519 #define KCloseOrdinal 41 |
|
520 #define KStaticHexDumpOrdinal 50 |
|
521 #else |
|
522 #define KConnectOrdinal 4 |
|
523 #define KSlogOrdinal 20 |
|
524 #define KCloseOrdinal 2 |
|
525 #define KStaticHexDumpOrdinal 49 |
|
526 #endif |
|
527 |
|
528 typedef TInt (*StaticConnectFn)(const TDesC&); |
|
529 StaticConnectFn StaticConnect = (StaticConnectFn)perfLib.Lookup(KConnectOrdinal); |
|
530 typedef void (*SlogFn)(TRefByValue<const TDesC8> aFmt, ...); |
|
531 SlogFn Slog = (SlogFn)perfLib.Lookup(KSlogOrdinal); |
|
532 typedef void (*StaticCloseFn)(); |
|
533 StaticCloseFn StaticClose = (StaticCloseFn)perfLib.Lookup(KCloseOrdinal); |
|
534 typedef void (*StaticHexDumpFn)(const TDesC8& aHeader, const TDesC8& aData); |
|
535 StaticHexDumpFn StaticHexDump = (StaticHexDumpFn)perfLib.Lookup(KStaticHexDumpOrdinal); |
|
536 |
|
537 TInt err = StaticConnect(_L("PerfLog")); |
|
538 ASSERT(!err); |
|
539 |
|
540 Slog(_L8("This better be some %s logging"), "high performance"); |
|
541 User::After(10); |
|
542 Slog(_L8("So had this")); |
|
543 |
|
544 _LIT8(KBin, "Newline: \n Null: xxxxx\0 <EOM>"); // Useful to put a zero byte in there to test that string termination isn't an issue |
|
545 StaticHexDump(_L8("Testing static hexdump function "), KBin); |
|
546 |
|
547 clogger.Log("This should appear before the high-perf logging"); |
|
548 clogger.HexDump(_L8("Normal "), KBin); |
|
549 |
|
550 StaticClose(); |
|
551 perfLib.Close(); |
|
552 } |
|
553 |
|
554 void DebugRouterL() |
|
555 { |
|
556 // Test the debug router LDD directly, to ensure its buffering code works properly |
|
557 tclogger.Shutdown(); // Otherwise the cloggerserver is still registered as the debug router's client (And only one client is allowed) |
|
558 RCloggerDebugRouter router; |
|
559 TInt err = RCloggerDebugRouter::LoadDriver(); |
|
560 ASSERT(!err || err == KErrAlreadyExists); |
|
561 err = router.Open(); |
|
562 ASSERT(!err); |
|
563 RChunk chunk; |
|
564 err = router.OpenChunk(chunk); |
|
565 ASSERT(!err); |
|
566 SDebugChunkHeader* chunkHeader = (SDebugChunkHeader*)chunk.Base(); |
|
567 #define startPtr chunkHeader->iStartOffset |
|
568 #define endPtr chunkHeader->iEndOffset |
|
569 #define overflows chunkHeader->iOverflows |
|
570 |
|
571 err = router.EnableDebugRouting(RCloggerDebugRouter::EEnableRoutingAndConsume); |
|
572 ASSERT(!err); |
|
573 |
|
574 // Test queuing up a bunch of prints before the client has registered |
|
575 const char* lorem = (const char*)KLorem().Ptr(); |
|
576 const TInt KLoremLength = Min(256, KLorem().Length()); // RDebugs are truncated at 256 chars |
|
577 RDebug::Printf(lorem); |
|
578 RDebug::Printf(lorem); |
|
579 RDebug::Printf(lorem); |
|
580 RDebug::Printf(lorem); |
|
581 RDebug::Printf(lorem); |
|
582 |
|
583 TRequestStatus stat; |
|
584 router.ReceiveData(stat); |
|
585 User::WaitForRequest(stat); |
|
586 ASSERT(stat == KErrNone); |
|
587 ASSERT(startPtr == sizeof(SDebugChunkHeader)); // Offset from start of chunk |
|
588 TInt dataLen = endPtr - startPtr; |
|
589 ASSERT(dataLen == (KLoremLength + sizeof(SCloggerTraceInfo)) * 5); |
|
590 SCloggerTraceInfo* traceHeader = (SCloggerTraceInfo*)(chunk.Base() + startPtr); |
|
591 ASSERT(traceHeader->iTraceType == 'U'); |
|
592 |
|
593 // Now do another write, which will go to the middle of the buffer as we haven't said we've handled all the KLorems yet |
|
594 _LIT(KMiddle, "Middle of buffer"); |
|
595 RDebug::Print(KMiddle); |
|
596 |
|
597 router.ReceiveData(stat); |
|
598 User::WaitForRequest(stat); |
|
599 ASSERT(stat == KErrNone); |
|
600 ASSERT(startPtr == sizeof(SDebugChunkHeader) + dataLen); |
|
601 ASSERT(endPtr - startPtr == KMiddle().Length() + sizeof(SCloggerTraceInfo)); |
|
602 |
|
603 // iCurrent and iClientEnd are pointing at the same place, about 1300 bytes in |
|
604 // iClientStart is at start of buffer |
|
605 |
|
606 // Now test wrapping |
|
607 // Need to do 250 writes of KLorem to get to the end of the buffer, 64K/(256+12) ~= 250 |
|
608 // The buffer should wrap around, then overflow as we still haven't acknowledged we've completed up to 1300 bytes |
|
609 |
|
610 TInt loop = 265; // So we put something at the start too |
|
611 while (loop--) |
|
612 { |
|
613 RDebug::Printf(lorem); |
|
614 } |
|
615 |
|
616 TInt prevEnd = endPtr; |
|
617 router.ReceiveData(stat); |
|
618 User::WaitForRequest(stat); |
|
619 ASSERT(stat == KErrNone); |
|
620 ASSERT(startPtr == prevEnd); |
|
621 ASSERT(overflows == 21); // 21 is what you get from doing 265 writes |
|
622 //ASSERT(endPtr == ??); // Can't be bothered right now to figure this out |
|
623 |
|
624 // Simulate unclean shutdown (ie don't call EnabledDebugRouting(EFalse)) |
|
625 |
|
626 router.Close(); |
|
627 chunk.Close(); |
|
628 |
|
629 // Try writing enough to wrap the buffer after we've disconnected (ie while there's no client) |
|
630 loop = 265; |
|
631 while (loop--) |
|
632 { |
|
633 RDebug::Printf(lorem); |
|
634 } |
|
635 |
|
636 // And reconnect and see what happens |
|
637 err = router.Open(); |
|
638 ASSERT(!err); |
|
639 err = router.OpenChunk(chunk); |
|
640 ASSERT(!err); |
|
641 chunkHeader = (SDebugChunkHeader*)chunk.Base(); |
|
642 |
|
643 err = router.EnableDebugRouting(RCloggerDebugRouter::EEnableRoutingAndConsume); |
|
644 ASSERT(!err); |
|
645 |
|
646 router.ReceiveData(stat); |
|
647 User::WaitForRequest(stat); |
|
648 ASSERT(stat == KErrNone); |
|
649 //ASSERT(startPtr == sizeof(SDebugChunkHeader); // Offset from start of chunk |
|
650 traceHeader = (SCloggerTraceInfo*)(chunk.Base() + startPtr); |
|
651 ASSERT(traceHeader->iTraceType == 'U'); |
|
652 |
|
653 ////END |
|
654 |
|
655 |
|
656 // Done! |
|
657 err = router.EnableDebugRouting(RCloggerDebugRouter::EDisable); |
|
658 ASSERT(!err); |
|
659 router.Close(); |
|
660 chunk.Close(); |
|
661 |
|
662 // Now test the CreateChunk API |
|
663 err = router.Open(); |
|
664 ASSERT(!err); |
|
665 RThread meThread; |
|
666 err = meThread.Open(RThread().Id()); |
|
667 ASSERT(!err); |
|
668 SCreateChunkParams params; |
|
669 params.iCommittedSize = 1024; |
|
670 params.iMaxSize = 1024; |
|
671 params.iHandleOfOtherThread = meThread.Handle(); |
|
672 err = router.CreateChunk(params); |
|
673 ASSERT(err == KErrNone); |
|
674 RChunk myChunk, otherChunk; |
|
675 myChunk.SetHandle(params.iChunkHandle); |
|
676 otherChunk.SetHandle(params.iOtherThreadChunkHandle); |
|
677 ASSERT(myChunk.Size() >= 1024); |
|
678 ASSERT(otherChunk.Size() >= 1024); |
|
679 myChunk.Close(); |
|
680 ASSERT(otherChunk.Size()); // Testing that the one handle stays valid when the other closes |
|
681 otherChunk.Close(); |
|
682 meThread.Close(); |
|
683 // Try again with nothing specified for otherChunk |
|
684 params.iHandleOfOtherThread = 0; |
|
685 params.iOtherThreadChunkHandle = 0; |
|
686 err = router.CreateChunk(params); |
|
687 ASSERT(!err); |
|
688 ASSERT(params.iOtherThreadChunkHandle == 0); |
|
689 myChunk.SetHandle(params.iChunkHandle); |
|
690 ASSERT(myChunk.Size() >= 1024); |
|
691 |
|
692 // Try the resize API |
|
693 err = router.AdjustChunk(myChunk, 512); |
|
694 ASSERT(!err); |
|
695 // We can't actually shrink a shared chunk, so this test is not valid. |
|
696 //ASSERT(myChunk.Size() == 512); |
|
697 myChunk.Close(); |
|
698 router.Close(); |
|
699 |
|
700 // Restart clogger |
|
701 clogger.Close(); |
|
702 err = clogger.Connect(KTag); |
|
703 ASSERT(!err); |
|
704 } |
|
705 |
|
706 static void JustPanic(TAny*) |
|
707 { |
|
708 User::Panic(_L("Crash!"), 0); |
|
709 } |
|
710 |
|
711 static void CleanupPanicPushL() |
|
712 { |
|
713 CleanupStack::PushL(TCleanupItem(&JustPanic)); |
|
714 } |
|
715 |
|
716 |
|
717 TInt E32Main() |
|
718 { |
|
719 __UHEAP_MARK; |
|
720 // |
|
721 CTrapCleanup* cleanup=CTrapCleanup::New(); |
|
722 TInt r=KErrNoMemory; |
|
723 if (cleanup) |
|
724 { |
|
725 TRAP(r, CleanupPanicPushL(); RunTestsL(); CleanupStack::Pop()); |
|
726 //ASSERT(!r); |
|
727 delete cleanup; |
|
728 } |
|
729 // |
|
730 __UHEAP_MARKEND; |
|
731 ASSERT(!r); |
|
732 return r; |
|
733 } |
|
734 |
|
735 void SessionWriterL() |
|
736 { |
|
737 //tclogger.Shutdown(); |
|
738 //clogger.Connect(KTag); |
|
739 clogger.SetGlobalOptions(RClogger::ERedirectRDebugPrintToClogger); |
|
740 clogger.SetEnabled(_L("Clogger"), 0); // To shut up the "thread x has started debugging" messages from using the debugrouter |
|
741 |
|
742 RCloggerLogConsumer consumer; |
|
743 TInt err = consumer.Connect(); |
|
744 ASSERT(!err); |
|
745 |
|
746 TRequestStatus stat; |
|
747 TPtrC8 logLine; |
|
748 |
|
749 consumer.GetNextLog(stat, logLine); |
|
750 RDebug::Printf("Shouldn't see this as will cancel session writer!"); // Don't use RClogger::Log directly as this will deadlock. Using the debug router to sidestep this is easier than spawning a separate thread in this test app |
|
751 consumer.CancelGetNextLog(); |
|
752 User::WaitForRequest(stat); |
|
753 |
|
754 consumer.GetNextLog(stat, logLine); |
|
755 _LIT8(KSee, "Better see this\r\n"); |
|
756 RDebug::Printf("Better see this"); |
|
757 User::WaitForRequest(stat); |
|
758 ASSERT(stat == KErrNone); |
|
759 ASSERT(logLine.Right(KSee().Length()) == KSee); |
|
760 |
|
761 consumer.Close(); |
|
762 } |