Skip to content

Commit 51b782e

Browse files
EugeniyKiyashkoEugeniyKiyashko
committed
Add logs
1 parent c1e04bd commit 51b782e

3 files changed

Lines changed: 136 additions & 32 deletions

File tree

‎packages/devextreme/docker-ci.sh‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -165,7 +165,14 @@ function start_runner_watchdog {
165165

166166
if [ $stall_count -ge 2 ]; then
167167
echo "Runner stalled for 10 minutes, killing process..."
168+
echo "===== Last 100 lines of RawLog.txt ====="
168169
tail -n 100 $raw_log_file
170+
echo "===== MiscErrors.log (JavaScript logs) ====="
171+
if [ -f "$PWD/testing/MiscErrors.log" ]; then
172+
tail -n 200 "$PWD/testing/MiscErrors.log"
173+
else
174+
echo "(MiscErrors.log not found)"
175+
fi
169176
kill -9 $1
170177
fi
171178
else

‎packages/devextreme/testing/runner/Controllers/MainController.cs‎

Lines changed: 33 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -131,33 +131,50 @@ public void NotifyTestCompleted(string name, bool passed) {
131131
public void NotifySuiteFinalized(string name, bool passed, int runtime)
132132
{
133133
Response.ContentType = "text/plain";
134-
lock (IO_SYNC)
134+
135+
try
135136
{
136-
if (passed && _runFlags.IsContinuousIntegration)
137+
lock (IO_SYNC)
137138
{
138-
IOFile.AppendAllLines(_completedSuitesFileName, new[] { name });
139+
if (passed && _runFlags.IsContinuousIntegration)
140+
{
141+
IOFile.AppendAllLines(_completedSuitesFileName, new[] { name });
142+
}
143+
ConsoleHelper.Write("[");
144+
if (passed)
145+
ConsoleHelper.Write(" OK ", ConsoleColor.Green);
146+
else
147+
ConsoleHelper.Write("FAIL", ConsoleColor.Red);
148+
149+
TimeSpan runSpan = TimeSpan.FromMilliseconds(runtime);
150+
ConsoleHelper.WriteLine($"] {name} in {Math.Round(runSpan.TotalSeconds, 3)}s");
139151
}
140-
ConsoleHelper.Write("[");
141-
if (passed)
142-
ConsoleHelper.Write(" OK ", ConsoleColor.Green);
143-
else
144-
ConsoleHelper.Write("FAIL", ConsoleColor.Red);
145-
146-
TimeSpan runSpan = TimeSpan.FromMilliseconds(runtime);
147-
ConsoleHelper.WriteLine($"] {name} in {Math.Round(runSpan.TotalSeconds, 3)}s");
148-
152+
153+
// Call NotifyIsAlive outside of lock to prevent potential deadlock
149154
NotifyIsAlive();
150155
}
156+
catch (Exception ex)
157+
{
158+
Console.WriteLine($"NotifySuiteFinalized failed for {name}: {ex.Message}");
159+
// Continue execution - don't let exceptions break the test runner
160+
}
151161
}
152162

153-
static readonly object IOLock = new object();
154-
155163
[HttpPost]
156164
public void NotifyIsAlive() {
157165
if (_runFlags.IsContinuousIntegration)
158-
lock (IOLock) {
159-
IOFile.WriteAllText(Path.Combine(_env.ContentRootPath, "testing/LastSuiteTime.txt"), DateTime.Now.ToString("s"));
166+
{
167+
try
168+
{
169+
lock (IO_SYNC) {
170+
IOFile.WriteAllText(Path.Combine(_env.ContentRootPath, "testing/LastSuiteTime.txt"), DateTime.Now.ToString("s"));
171+
}
160172
}
173+
catch (Exception ex)
174+
{
175+
Console.WriteLine($"NotifyIsAlive failed: {ex.Message}");
176+
}
177+
}
161178
}
162179

163180
[HttpPost]

‎packages/devextreme/testing/runner/Views/Main/RunAll.cshtml‎

Lines changed: 96 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -59,9 +59,29 @@
5959
$(function() {
6060
var ROOT_URL = "@Url.Content("~/")";
6161
62+
// Set global AJAX timeout to prevent hanging requests
63+
$.ajaxSetup({
64+
timeout: 30000 // 30 seconds timeout for all AJAX requests
65+
});
66+
67+
// Send important logs to server for CI debugging
68+
var serverLog = function(message) {
69+
console.log(message); // Also log to browser console
70+
71+
// Send to server if in CI mode
72+
if(@Html.Raw(Json.Serialize(Model.IsContinuousIntegration))) {
73+
$.post(@Html.Raw(Json.Serialize(Url.Action("LogMiscError"))), {
74+
msg: "[JS] " + message,
75+
timeout: 5000 // Short timeout for logging
76+
}).fail(function() {
77+
// Silently ignore failures to avoid recursion
78+
});
79+
}
80+
};
81+
6282
var TEST_TIMEOUT_SECONDS = 45,
6383
TEST_TIMEOUT = TEST_TIMEOUT_SECONDS * 1000,
64-
WORKER_STUCK_TIMEOUT = 120 * 1000, // 2 minutes without any activity
84+
WORKER_STUCK_TIMEOUT = 60 * 1000, // 60 seconds without any activity
6585
WORKER_NAME_PREFIX = "workerFrame",
6686
busyCount = 0,
6787
suitesDescription = {
@@ -129,14 +149,20 @@
129149
url: @Html.Raw(Json.Serialize(Url.Action("SaveResults"))),
130150
type: "post",
131151
contentType: "application/json",
132-
data: JSON.stringify(testResults)
152+
data: JSON.stringify(testResults),
153+
timeout: 60000 // 60 second timeout for saving results
133154
}).done(function() {
134155
notifyDeviceTestManager("QUnit.saveResults.done");
135156
removeWorkers();
136157
137158
var frame = document.getElementById("reportFrame");
138159
frame.style.display = "block";
139160
frame.setAttribute("src", @Html.Raw(Json.Serialize(Url.Action("DisplayResults"))));
161+
}).fail(function(jqXHR, textStatus, errorThrown) {
162+
serverLog('SaveResults FAILED: ' + textStatus + ' ' + errorThrown);
163+
// Try to continue anyway
164+
notifyDeviceTestManager("QUnit.saveResults.failed");
165+
removeWorkers();
140166
});
141167
};
142168
@@ -148,7 +174,7 @@
148174
149175
// Safety check: if worker is still busy, do not load next test
150176
if(suitesInProgress[i] !== null && suitesInProgress[i] !== undefined) {
151-
console.error('nextUrl: worker ' + i + ' is still busy with ' + suitesInProgress[i].name + '! Skipping.');
177+
serverLog('ERROR: nextUrl called but worker ' + i + ' is still busy with ' + suitesInProgress[i].name + '! Skipping.');
152178
return;
153179
}
154180
@@ -220,11 +246,12 @@
220246
221247
finalize: function(success) {
222248
if(this.finalized) {
223-
console.warn('Suite already finalized: ' + this.name + ', skipping duplicate finalize');
249+
serverLog('Suite already finalized: ' + this.name + ', skipping duplicate finalize');
224250
return;
225251
}
226252
227253
var suiteName = this.name; // Save name before cleanup
254+
serverLog('===== FINALIZE CALLED for ' + suiteName + ' =====');
228255
229256
this.finalized = true;
230257
this.time = roundTime((new Date() - this.startTime) / 1000);
@@ -238,11 +265,11 @@
238265
suitesInProgress[i] = null;
239266
busyCount--;
240267
241-
console.log('Suite finalized: ' + suiteName + ', worker=' + _i + ', busyCount=' + busyCount +
268+
serverLog('Suite finalized: ' + suiteName + ', worker=' + _i + ', busyCount=' + busyCount +
242269
', scheduling nextUrl in worker ' + _i);
243270
244271
setTimeout(function() {
245-
console.log('Calling nextUrl for worker ' + _i + ' after finalizing ' + suiteName);
272+
serverLog('Calling nextUrl for worker ' + _i + ' after finalizing ' + suiteName);
246273
nextUrl.call(that, _i);
247274
}, 0);
248275
}
@@ -306,15 +333,35 @@
306333
activeWorkers.push('Worker' + i + ':' + suite.name + '(' + inactiveSeconds + 's)');
307334
308335
if(lastActivity && (now - lastActivity) > WORKER_STUCK_TIMEOUT) {
309-
console.error('Worker ' + i + ' is STUCK on test: ' + suite.name + ' (no activity for ' +
336+
serverLog('ERROR: Worker ' + i + ' is STUCK on test: ' + suite.name + ' (no activity for ' +
310337
inactiveSeconds + ' seconds), busyCount=' + busyCount);
311-
console.log('Force finalizing stuck worker ' + i);
338+
serverLog('Force finalizing stuck worker ' + i + ' and loading next test');
312339
313340
// Force finalize the stuck suite (finalize checks for double-finalization)
314341
suite.finalize(false); // Mark as failed
315342
316-
// Reset worker state
343+
// Clear worker state
344+
suitesInProgress[i] = null;
317345
workerLastActivity[i] = now;
346+
347+
// Try to reload the worker by loading next test
348+
var worker = workerByIndex(i);
349+
if(worker) {
350+
try {
351+
// Force stop any running tests in the iframe
352+
if(worker.contentWindow && worker.contentWindow.stop) {
353+
worker.contentWindow.stop();
354+
}
355+
} catch(e) {
356+
serverLog('Could not stop worker iframe: ' + e.message);
357+
}
358+
359+
// Load next test
360+
setTimeout(function() {
361+
serverLog('Loading next test for recovered worker ' + i);
362+
nextUrl(i);
363+
}, 100);
364+
}
318365
}
319366
}
320367
}
@@ -503,11 +550,13 @@
503550
};
504551
505552
window.RUNNER_ON_DONE = function(worker, qunitData) {
553+
serverLog('===== RUNNER_ON_DONE CALLED =====');
554+
506555
var i = indexFromWorkerName(worker),
507556
suite = suitesInProgress[i],
508557
passed = !qunitData.failed;
509558
510-
console.log('RUNNER_ON_DONE: worker=' + i + ', suite=' + (suite ? suite.name : 'null') +
559+
serverLog('RUNNER_ON_DONE: worker=' + i + ', suite=' + (suite ? suite.name : 'null') +
511560
', busyCount=' + busyCount + ', failed=' + qunitData.failed + ', total=' + qunitData.total);
512561
513562
if(suite) {
@@ -519,9 +568,12 @@
519568
}
520569
521570
var suiteName = suite.name; // Save before finalize clears it
571+
serverLog('RUNNER_ON_DONE: About to finalize suite ' + suiteName + ' (worker=' + i + ')');
522572
523573
// finalize() handles busyCount-- internally and prevents double-finalization
524574
suite.finalize(passed, qunitData.total);
575+
576+
serverLog('RUNNER_ON_DONE: About to notify server about ' + suiteName + ' completion');
525577
notifySuiteFinalized(suiteName, passed, qunitData.runtime);
526578
} else {
527579
console.warn('RUNNER_ON_DONE: suite is null for worker ' + i + ' - already finalized, skipping nextUrl call');
@@ -560,10 +612,20 @@
560612
}
561613
562614
function notifySuiteFinalized(name, passed, runtime) {
563-
$.post(@Html.Raw(Json.Serialize(Url.Action("NotifySuiteFinalized"))), { name: name, passed: passed, runtime: runtime })
564-
.fail(function(jqXHR, textStatus, errorThrown) {
565-
console.warn('NotifySuiteFinalized failed:', textStatus, errorThrown);
566-
});
615+
serverLog('notifySuiteFinalized: Sending POST for ' + name);
616+
$.ajax({
617+
url: @Html.Raw(Json.Serialize(Url.Action("NotifySuiteFinalized"))),
618+
type: 'POST',
619+
data: { name: name, passed: passed, runtime: runtime },
620+
timeout: 15000, // 15 second timeout for suite finalization
621+
success: function() {
622+
serverLog('notifySuiteFinalized: Server responded OK for ' + name);
623+
},
624+
error: function(jqXHR, textStatus, errorThrown) {
625+
serverLog('NotifySuiteFinalized FAILED for ' + name + ': ' + textStatus + ' ' + errorThrown);
626+
// Continue despite failure - don't block the worker
627+
}
628+
});
567629
}
568630
function notifyIsAlive(){
569631
$.post(@Html.Raw(Json.Serialize(Url.Action("NotifyIsAlive"))))
@@ -572,8 +634,25 @@
572634
});
573635
}
574636
575-
// Check for stuck workers every 30 seconds
576-
setInterval(checkStuckWorkers, 30000);
637+
// Check for stuck workers every 15 seconds
638+
setInterval(checkStuckWorkers, 15000);
639+
640+
// Log overall state every 10 seconds for debugging
641+
setInterval(function() {
642+
var activeSuites = [];
643+
for(var i = 0; i < WORKER_COUNT; i++) {
644+
if(suitesInProgress[i]) {
645+
activeSuites.push('Worker' + i + ':' + suitesInProgress[i].name);
646+
}
647+
}
648+
649+
// Only log to server if there are active suites or issues
650+
if(activeSuites.length > 0 || busyCount > 0 || (urls.length === 0 && !resultSaving)) {
651+
var stateMsg = '===== STATE: busyCount=' + busyCount + ', urls=' + urls.length +
652+
', resultSaving=' + resultSaving + ', active=' + (activeSuites.length > 0 ? activeSuites.join('; ') : 'none');
653+
serverLog(stateMsg);
654+
}
655+
}, 10000);
577656
578657
function roundTime(time) {
579658
return +(time.toFixed(3));
@@ -585,6 +664,7 @@
585664
notifyIsAlive();
586665
}, 30000); // Reduced from 60000ms to 30000ms (30 seconds) to prevent watchdog timeout
587666
667+
serverLog('Starting test run with ' + WORKER_COUNT + ' workers, ' + urls.length + ' tests');
588668
runFirstBatch();
589669
});
590670
</script>

0 commit comments

Comments
 (0)