Skip to content

Commit 925422e

Browse files
asolntsevasolntsev
authored
Add logs to Grid to debug downloading files (#17599)
* add debugging logs for downloading files from grid * add debugging logs for selenium manager * add HasDownloads.toString() * add details to error message when failed to establish WS connection * remove extra semicolon * fully log the actual browser capabilities Method `ImmutableCapabilities.toString()` truncates all values longer than 30 chars: websocket URL, downloads directory etc. But these values are crucial when debugging Grid issues. We need to log them AS IS. * mask credentials in Grid URL Some selenium grids are behind a basic authentication (see #15012), they just put the user+password into the URI. We need to sanitize credentials before writing the URL to logs. * fix flaky test BrowserCommandsTest Sample failure: "TimeoutException: Expected condition failed: Expected to find file "file_1.txt", but found 1 files: [file_1(1).txt]" * fix flaky test BrowserCommandsTest Sample failure: "NullPointerException: this.browser is null"
1 parent aba540c commit 925422e

11 files changed

Lines changed: 110 additions & 35 deletions

File tree

‎java/src/org/openqa/selenium/HasDownloads.java‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -110,5 +110,11 @@ public long getLastModifiedTime() {
110110
public long getSize() {
111111
return size;
112112
}
113+
114+
@Override
115+
public String toString() {
116+
return String.format(
117+
"DownloadedFile{name='%s', modified at: %d, size: %d}", name, lastModifiedTime, size);
118+
}
113119
}
114120
}

‎java/src/org/openqa/selenium/grid/data/NodeStatus.java‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@
1919

2020
import static java.util.Collections.unmodifiableMap;
2121
import static java.util.Collections.unmodifiableSet;
22+
import static org.openqa.selenium.remote.http.jdk.JdkHttpClient.maskUrlCredentials;
2223

2324
import java.net.URI;
2425
import java.time.Duration;
@@ -167,6 +168,10 @@ public URI getExternalUri() {
167168
return externalUri;
168169
}
169170

171+
public String getMaskedUri() {
172+
return maskUrlCredentials(externalUri);
173+
}
174+
170175
public Set<Slot> getSlots() {
171176
return slots;
172177
}

‎java/src/org/openqa/selenium/grid/distributor/local/LocalDistributor.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -369,7 +369,7 @@ public Either<SessionNotCreatedException, CreateSessionResponse> newSession(
369369
span.addEvent(sessionCreatedMessage, attributeMap);
370370
LOG.info(
371371
String.format(
372-
"%s. Id: %s %n Caps: %s", sessionCreatedMessage, sessionId, sessionCaps));
372+
"%s. Id: %s %n Caps: %s", sessionCreatedMessage, sessionId, sessionCaps.asMap()));
373373

374374
return Either.right(response);
375375
} catch (SessionNotCreatedException e) {

‎java/src/org/openqa/selenium/grid/distributor/local/LocalGridModel.java‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -241,7 +241,7 @@ public void purgeDeadNodes() {
241241
LOG.info(
242242
String.format(
243243
"Removing Node %s (uri: %s), unhealthy threshold has been reached",
244-
node.getNodeId(), node.getExternalUri()));
244+
node.getNodeId(), node.getMaskedUri()));
245245
toRemove.add(node);
246246
break;
247247
}
@@ -258,14 +258,14 @@ public void purgeDeadNodes() {
258258
LOG.info(
259259
String.format(
260260
"Switching Node %s (uri: %s) from UP to DOWN",
261-
node.getNodeId(), node.getExternalUri()));
261+
node.getNodeId(), node.getMaskedUri()));
262262
replacements.put(node, rewrite(node, DOWN));
263263
nodePurgeTimes.put(id, Instant.now());
264264
} else if (node.getAvailability() == DOWN && deadTime.isBefore(now)) {
265265
LOG.info(
266266
String.format(
267267
"Removing Node %s (uri: %s), DOWN for too long",
268-
node.getNodeId(), node.getExternalUri()));
268+
node.getNodeId(), node.getMaskedUri()));
269269
toRemove.add(node);
270270
}
271271
}
@@ -310,7 +310,7 @@ public void setAvailability(NodeId id, Availability availability) {
310310
LOG.info(
311311
String.format(
312312
"Switching Node %s (uri: %s) from %s to %s",
313-
id, node.getExternalUri(), node.getAvailability(), availability));
313+
id, node.getMaskedUri(), node.getAvailability(), availability));
314314

315315
NodeStatus refreshed = rewrite(node, availability);
316316
nodes.remove(node);

‎java/src/org/openqa/selenium/grid/distributor/redis/RedisBackedDistributor.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -420,7 +420,7 @@ public Either<SessionNotCreatedException, CreateSessionResponse> newSession(
420420
span.addEvent(sessionCreatedMessage, attributeMap);
421421
LOG.info(
422422
String.format(
423-
"%s. Id: %s %n Caps: %s", sessionCreatedMessage, sessionId, sessionCaps));
423+
"%s. Id: %s %n Caps: %s", sessionCreatedMessage, sessionId, sessionCaps.asMap()));
424424

425425
return Either.right(response);
426426
} catch (SessionNotCreatedException e) {

‎java/src/org/openqa/selenium/grid/distributor/redis/RedisBackedGridModel.java‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -337,7 +337,7 @@ public void purgeDeadNodes() {
337337
LOG.info(
338338
String.format(
339339
"Removing Node %s (uri: %s), unhealthy threshold has been reached",
340-
node.getNodeId(), node.getExternalUri()));
340+
node.getNodeId(), node.getMaskedUri()));
341341
toRemove.add(node);
342342
continue;
343343
}
@@ -357,15 +357,15 @@ public void purgeDeadNodes() {
357357
LOG.info(
358358
String.format(
359359
"Switching Node %s (uri: %s) from UP to DOWN",
360-
node.getNodeId(), node.getExternalUri()));
360+
node.getNodeId(), node.getMaskedUri()));
361361
moveAvailability(id, UP, DOWN);
362362
writeNodeBlob(rewrite(node, DOWN));
363363
redis.set(lastTouchKey(id), String.valueOf(Instant.now().toEpochMilli()));
364364
} else if (avail == DOWN && deadTime.isBefore(now)) {
365365
LOG.info(
366366
String.format(
367367
"Removing Node %s (uri: %s), DOWN for too long",
368-
node.getNodeId(), node.getExternalUri()));
368+
node.getNodeId(), node.getMaskedUri()));
369369
toRemove.add(node);
370370
}
371371
}
@@ -405,7 +405,7 @@ public void setAvailability(NodeId id, Availability availability) {
405405
LOG.info(
406406
String.format(
407407
"Switching Node %s (uri: %s) from %s to %s",
408-
id, node.getExternalUri(), current, availability));
408+
id, node.getMaskedUri(), current, availability));
409409

410410
moveAvailability(id, current, availability);
411411
writeNodeBlob(rewrite(node, availability));

‎java/src/org/openqa/selenium/grid/node/local/LocalNode.java‎

Lines changed: 43 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -610,13 +610,22 @@ public Either<WebDriverException, CreateSessionResponse> newSession(
610610
TemporaryFilesystem.getDefaultTmpFS()
611611
.createTempDir("uuid", uuidForSessionDownloads.toString()));
612612

613+
LOG.info(
614+
() ->
615+
String.format(
616+
"Using file system: %s", downloadsTfs.getBaseDir().getAbsolutePath()));
617+
613618
Capabilities enhanced = setDownloadsDirectory(downloadsTfs, desiredCapabilities);
614619
enhanced = desiredCapabilities.merge(enhanced);
615620
sessionRequest =
616621
new CreateSessionRequest(
617622
sessionRequest.getDownstreamDialects(), enhanced, sessionRequest.getMetadata());
618623
} else {
619624
downloadsTfs = null;
625+
LOG.info(
626+
() ->
627+
String.format(
628+
"Not using file system: desiredCapabilities=%s", desiredCapabilities));
620629
}
621630

622631
Either<WebDriverException, ActiveSession> possibleSession = slotToUse.apply(sessionRequest);
@@ -656,7 +665,7 @@ public Either<WebDriverException, CreateSessionResponse> newSession(
656665
LOG.info(
657666
String.format(
658667
"%s. Id: %s, Caps: %s",
659-
sessionCreatedMessage, sessionId, externalSession.getCapabilities()));
668+
sessionCreatedMessage, sessionId, externalSession.getCapabilities().asMap()));
660669

661670
// Create session data for events and listeners
662671
SessionCreatedData createdData =
@@ -716,6 +725,8 @@ private boolean managedDownloadsRequested(Capabilities capabilities) {
716725

717726
private Capabilities setDownloadsDirectory(TemporaryFilesystem downloadsTfs, Capabilities caps) {
718727
File tempDir = downloadsTfs.createTempDir("download", "");
728+
LOG.info(() -> String.format("Using downloads folder: %s", tempDir.getAbsolutePath()));
729+
719730
if (Browser.CHROME.is(caps) || Browser.EDGE.is(caps)) {
720731
Map<String, Serializable> map =
721732
Map.of(
@@ -725,14 +736,22 @@ private Capabilities setDownloadsDirectory(TemporaryFilesystem downloadsTfs, Cap
725736
tempDir.getAbsolutePath(),
726737
"savefile.default_directory",
727738
tempDir.getAbsolutePath());
739+
LOG.log(Level.FINE, () -> String.format("Adding to capabilities: %s", map));
728740
String optionsKey = Browser.CHROME.is(caps) ? "goog:chromeOptions" : "ms:edgeOptions";
729741
return appendPrefs(caps, optionsKey, map);
730-
}
731-
if (Browser.FIREFOX.is(caps)) {
742+
} else if (Browser.FIREFOX.is(caps)) {
732743
Map<String, Serializable> map =
733744
Map.of(
734745
"browser.download.folderList", 2, "browser.download.dir", tempDir.getAbsolutePath());
746+
LOG.log(Level.FINE, () -> String.format("Adding to capabilities: %s", map));
735747
return appendPrefs(caps, "moz:firefoxOptions", map);
748+
} else {
749+
LOG.info(
750+
() ->
751+
String.format(
752+
"Browser is not one of (%s, %s, %s): %s -> not adding downloads directory to"
753+
+ " capabilities",
754+
Browser.CHROME, Browser.EDGE, Browser.FIREFOX, caps.getBrowserName()));
736755
}
737756
return caps;
738757
}
@@ -902,6 +921,10 @@ public HttpResponse downloadFile(HttpRequest req, SessionId id) {
902921
File downloadsDirectory =
903922
Optional.ofNullable(tempFS.getBaseDir().listFiles()).orElse(new File[] {})[0];
904923

924+
LOG.log(
925+
Level.FINE,
926+
() -> String.format("Downloads directory: %s", downloadsDirectory.getAbsolutePath()));
927+
905928
try {
906929
if (req.getMethod().equals(HttpMethod.GET) && req.getUri().endsWith("/se/files")) {
907930
return listDownloadedFiles(downloadsDirectory);
@@ -948,6 +971,15 @@ private HttpResponse listDownloadedFiles(File downloadsDirectory) {
948971
"names", fileNames,
949972
"files", fileInfos);
950973
Map<String, Map<String, Object>> result = Map.of("value", data);
974+
975+
LOG.log(
976+
Level.FINE,
977+
() ->
978+
String.format(
979+
"Downloaded files in dir %s: %s",
980+
downloadsDirectory.getAbsolutePath(), Arrays.toString(files)));
981+
LOG.log(Level.FINE, () -> String.format("Returning: %s", data));
982+
951983
return new HttpResponse().setContent(asJson(result));
952984
}
953985

@@ -1055,7 +1087,15 @@ private static List<File> downloadedFiles(File downloadsDirectory) {
10551087

10561088
private HttpResponse deleteDownloadedFile(File downloadsDirectory) {
10571089
File[] files = Optional.ofNullable(downloadsDirectory.listFiles()).orElse(new File[] {});
1090+
LOG.log(
1091+
Level.FINE,
1092+
() ->
1093+
String.format(
1094+
"Deleting downloaded files in dir %s: %s",
1095+
downloadsDirectory.getAbsolutePath(), Arrays.toString(files)));
1096+
10581097
for (File file : files) {
1098+
LOG.log(Level.FINE, () -> String.format("Deleted: %s", file.getAbsolutePath()));
10591099
FileHandler.delete(file);
10601100
}
10611101
Map<String, @Nullable Object> toReturn = new HashMap<>();

‎java/src/org/openqa/selenium/manager/SeleniumManager.java‎

Lines changed: 11 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -154,7 +154,10 @@ private static Result runCommand(Path binary, List<String> arguments) {
154154
code = process.exitValue();
155155
output = process.getOutput(StandardCharsets.UTF_8);
156156
} catch (Exception e) {
157-
throw new WebDriverException("Failed to run command: " + arguments, e);
157+
throw new WebDriverException(
158+
String.format(
159+
"Failed to run command \"%s\" with arguments %s", binary.toAbsolutePath(), arguments),
160+
e);
158161
}
159162
SeleniumManagerOutput jsonOutput = null;
160163
JsonException failedToParse = null;
@@ -177,11 +180,16 @@ private static Result runCommand(Path binary, List<String> arguments) {
177180
}
178181
if (code != 0) {
179182
throw new WebDriverException(
180-
"Command failed with code: " + code + ", executed: " + arguments + "\n" + dump,
183+
String.format(
184+
"Command failed with code: %d, executed \"%s\" with arguments %s%n%s",
185+
code, binary.toAbsolutePath(), arguments, dump),
181186
failedToParse);
182187
} else if (failedToParse != null || jsonOutput == null) {
183188
throw new WebDriverException(
184-
"Failed to parse json output, executed: " + arguments + "\n" + dump, failedToParse);
189+
String.format(
190+
"Failed to parse json output, executed \"%s\" with arguments %s%n%s",
191+
binary.toAbsolutePath(), arguments, dump),
192+
failedToParse);
185193
}
186194
return jsonOutput.getResult();
187195
}

‎java/src/org/openqa/selenium/remote/http/jdk/JdkHttpClient.java‎

Lines changed: 17 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -161,7 +161,11 @@ public WebSocket openSocket(HttpRequest request, WebSocket.Listener listener) {
161161
try {
162162
uri = getWebSocketUri(request);
163163
} catch (URISyntaxException e) {
164-
throw new ConnectionFailedException("JdkWebSocket initial request execution error", e);
164+
String message =
165+
String.format(
166+
"JdkWebSocket initial request execution error (uri: %s)",
167+
maskUrlCredentials(messages.getRawUri(request)));
168+
throw new ConnectionFailedException(message, e);
165169
}
166170

167171
java.net.http.WebSocket.Builder builder = client.newWebSocketBuilder();
@@ -251,13 +255,20 @@ public void onError(java.net.http.WebSocket webSocket, Throwable error) {
251255
} catch (ExecutionException e) {
252256
Throwable cause = e.getCause();
253257
throw new ConnectionFailedException(
254-
"JdkWebSocket initial request execution error", (cause != null) ? cause : e);
258+
String.format(
259+
"JdkWebSocket initial request execution error (uri: %s)", maskUrlCredentials(uri)),
260+
(cause != null) ? cause : e);
255261
} catch (InterruptedException e) {
256262
Thread.currentThread().interrupt();
257-
throw new ConnectionFailedException("JdkWebSocket initial request interrupted", e);
263+
throw new ConnectionFailedException(
264+
String.format(
265+
"JdkWebSocket initial request interrupted (uri: %s)", maskUrlCredentials(uri)),
266+
e);
258267
} catch (java.util.concurrent.TimeoutException e) {
259268
webSocketCompletableFuture.cancel(true);
260-
throw new ConnectionFailedException("JdkWebSocket initial request timeout", e);
269+
throw new ConnectionFailedException(
270+
String.format("JdkWebSocket initial request timeout (uri: %s)", maskUrlCredentials(uri)),
271+
e);
261272
}
262273

263274
WebSocket websocket =
@@ -518,15 +529,15 @@ private String describe(HttpRequest req) {
518529
return String.format("%s %s", method, uri);
519530
}
520531

521-
static String maskUrlCredentials(String uri) {
532+
public static String maskUrlCredentials(String uri) {
522533
try {
523534
return maskUrlCredentials(new URI(uri));
524535
} catch (URISyntaxException invalidUri) {
525536
return uri;
526537
}
527538
}
528539

529-
private static String maskUrlCredentials(URI u) {
540+
public static String maskUrlCredentials(URI u) {
530541
if (u.getUserInfo() == null) {
531542
return u.toString();
532543
}

0 commit comments

Comments
 (0)