1 //
2 // Copyright (c) 2010-2024 Antmicro
3 //
4 // This file is licensed under the MIT License.
5 // Full license text is available in 'licenses/MIT.txt'.
6 //
7 using System;
8 using System.Linq;
9 using System.Collections.Generic;
10 using System.Diagnostics;
11 using System.Threading;
12 using System.Text.RegularExpressions;
13 using Antmicro.Renode.Logging;
14 using Antmicro.Renode.Testing;
15 using Antmicro.Renode.Core;
16 using Antmicro.Renode.Utilities;
17 
18 namespace Antmicro.Renode.RobotFramework
19 {
20     public class LogTester : TextBackend
21     {
LogTester(float virtualSecondsTimeout)22         public LogTester(float virtualSecondsTimeout)
23         {
24             // we need to use synchronous logging in order to pause the emulation precisely
25             EmulationManager.Instance.CurrentEmulation.CurrentLogger.SynchronousLogging = true;
26 #if TRACE_ENABLED
27             Logger.Log(LogLevel.Warning, "Using LogTester with tracing enabled will cause deadlock on pausing emulation.");
28 #endif
29 
30             this.defaultTimeout = virtualSecondsTimeout;
31             messages = new List<LogEntry>();
32             predicateEvent = new AutoResetEvent(false);
33         }
34 
Dispose()35         public override void Dispose()
36         {
37             lock(messages)
38             {
39                 messages.Clear();
40             }
41         }
42 
Log(LogEntry entry)43         public override void Log(LogEntry entry)
44         {
45             if(!ShouldBeLogged(entry))
46             {
47                 return;
48             }
49 
50             lock(messages)
51             {
52                 messages.Add(entry);
53 
54                 if(predicate == null)
55                 {
56                     // we are currently not waiting for any message
57                     return;
58                 }
59 
60                 if(!predicate(entry))
61                 {
62                     // not found anything interesting
63                     return;
64                 }
65 
66                 if(pauseEmulation)
67                 {
68 #if TRACE_ENABLED
69                     throw new InvalidOperationException("Pausing emulation in LogTester with tracing enabled causes deadlock.");
70 #endif
71                     if(!EmulationManager.Instance.CurrentEmulation.TryGetExecutionContext(out var machine, out var cpu) || !cpu.OnPossessedThread)
72                     {
73                         // we are not on a CPU thread so we can issue a global pause
74                         EmulationManager.Instance.CurrentEmulation.PauseAll();
75                     }
76                     else
77                     {
78                         // mind that we don't use precise pausing as there is no guarantee this code is being executed from a CPU thread with a pause guard
79                         // it is still deterministic though
80                         machine.PauseAndRequestEmulationPause(precise: false);
81                     }
82                     pauseEmulation = false;
83                 }
84 
85                 predicate = null;
86                 predicateEvent.Set();
87             }
88         }
89 
WaitForEntry(string pattern, out IEnumerable<string> bufferedMessages, float? timeout = null, bool keep = false, bool treatAsRegex = false, bool pauseEmulation = false, LogLevel level = null)90         public string WaitForEntry(string pattern, out IEnumerable<string> bufferedMessages, float? timeout = null, bool keep = false, bool treatAsRegex = false,
91             bool pauseEmulation = false, LogLevel level = null)
92         {
93             var emulation = EmulationManager.Instance.CurrentEmulation;
94             var regex = treatAsRegex ? new Regex(pattern) : null;
95             var predicate = treatAsRegex ? (Predicate<LogEntry>)(x => regex.IsMatch(x.FullMessage)) : (x => x.FullMessage.Contains(pattern));
96             if(level != null)
97             {
98                 var innerPredicate = predicate;
99                 predicate = x => x.Type == level && innerPredicate(x);
100             }
101             var effectiveTimeout = timeout ?? defaultTimeout;
102 
103             lock(messages)
104             {
105                 var entry = FlushAndCheckLocked(emulation, predicate, keep, out bufferedMessages);
106                 if(entry != null || (effectiveTimeout == 0))
107                 {
108                     return entry;
109                 }
110 
111                 this.pauseEmulation = pauseEmulation;
112                 this.predicate = predicate;
113                 this.predicateEvent.Reset();
114             }
115 
116             var emulationPausedEvent = emulation.GetStartedStateChangedEvent(false);
117             var timeoutEvent = emulation.MasterTimeSource.EnqueueTimeoutEvent((ulong)(effectiveTimeout * 1000), () =>
118             {
119                 if(this.pauseEmulation)
120                 {
121                     emulation.PauseAll();
122                 }
123             });
124 
125             if(!emulation.IsStarted)
126             {
127                 emulation.StartAll();
128             }
129 
130             var eventId = WaitHandle.WaitAny(new [] { timeoutEvent.WaitHandle, predicateEvent });
131 
132             if(eventId == 1)
133             {
134                 // predicate event; we know the machine is paused, now we need to check for the rest of the emulation to stop
135                 timeoutEvent.Cancel();
136                 if(pauseEmulation)
137                 {
138                     emulationPausedEvent.WaitOne();
139                 }
140             }
141 
142             // let's check for the last time and lock any incoming messages
143             return FlushAndCheckLocked(emulation, predicate, keep, out bufferedMessages);
144         }
145 
ClearHistory()146         public void ClearHistory()
147         {
148             lock(messages)
149             {
150                 messages.Clear();
151             }
152         }
153 
FlushAndCheckLocked(Emulation emulation, Predicate<LogEntry> predicate, bool keep, out IEnumerable<string> bufferedMessages)154         private string FlushAndCheckLocked(Emulation emulation, Predicate<LogEntry> predicate, bool keep, out IEnumerable<string> bufferedMessages)
155         {
156             emulation.CurrentLogger.Flush();
157             lock(messages)
158             {
159                 if(TryFind(predicate, keep, out var result))
160                 {
161                     bufferedMessages = null;
162                     return result.FullMessage;
163                 }
164 
165                 bufferedMessages = messages.Select(x => x.FullMessage).ToList();
166                 return null;
167             }
168         }
169 
TryFind(Predicate<LogEntry> predicate, bool keep, out LogEntry result)170         private bool TryFind(Predicate<LogEntry> predicate, bool keep, out LogEntry result)
171         {
172             lock(messages)
173             {
174                 var idx = messages.FindIndex(predicate);
175                 if(idx != -1)
176                 {
177                     result = messages[idx];
178                     if(!keep)
179                     {
180                         messages.RemoveRange(0, idx + 1);
181                     }
182                     return true;
183                 }
184             }
185 
186             result = null;
187             return false;
188         }
189 
190         private bool pauseEmulation;
191         private Predicate<LogEntry> predicate;
192 
193         private readonly AutoResetEvent predicateEvent;
194         private readonly List<LogEntry> messages;
195         private readonly float defaultTimeout;
196     }
197 }
198