From 9c53bc6a2389b205298d85dc0999e3cda054549f Mon Sep 17 00:00:00 2001 From: xmg333 <1318834675@qq.com> Date: Sat, 15 Aug 2026 22:15:12 +0800 Subject: [PATCH 1/2] [Fix-18459][API/Common] Stream task log in bounded chunks to prevent OOM MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Replace whole-file log download with chunked streaming, and keep the legacy whole-file worker RPC unreachable from the download path: - Add ILogService#getTaskInstanceLogFileChunk RPC to read [offset, offset+length) ranges from the worker, clamped to 8 MB per chunk. - API streams chunks via StreamingResponseBody; auth is checked synchronously before the HTTP response is committed so @ApiException still returns JSON errors. - The download path never invokes the legacy whole-file worker RPC (getTaskInstanceWholeLogFileBytes): that RPC reads the entire file into the worker's heap (ByteArrayOutputStream + toByteArray + JSON/base64) before any frame exists to reject, so a large log can OOM the worker — a receiver-side maxFrameSize cannot bound the sender. On a first-chunk failure the only fallback is remote log storage, streamed in bounded chunks; the fallback runs at most once per call and its failures propagate directly, so it cannot re-enter or double-execute. Mid-stream failure throws IOException to avoid a corrupted download. - First-chunk failure handling is guided by how the RPC failed: the worker answered but could not dispatch the method (MethodInvocationException — an old worker without the chunk method, e.g. during a rolling upgrade) fails with an explicit "Worker upgrade required for large log download: chunked log RPC is not available on worker and remote log storage also failed"; the worker never answered (connect refused / timeout — down or unreachable) reports a reachability problem instead of blaming the worker version; a structured non-SUCCESS response from a worker that implements the chunk RPC is reported as-is with its response code. Small-log compatibility with old workers is intentionally dropped: no mechanism can establish a byte-size bound on an old worker before the payload is built. Log viewing (line-bounded) is unaffected; the wire surface is untouched, so an old API server keeps working against a new worker/master. - The remote archive is stable throughout streaming: the remote log handlers rewrite the cache in place, so streamWholeLog snapshots the archive into a private temp file (.download-) inside the striped lock and streams the snapshot outside it — a concurrent download/view re-downloading (and truncating) the cache can no longer cause a premature EOF for an active transfer. Snapshot deletion is guaranteed on every failure path (nested finally, up to Error); orphaned snapshots from JVM death mid-transfer are swept at startup (older than 1h, so a shared-disk instance's in-flight transfer is never touched). streamBounded's short-read guard stays as defense in depth; its message no longer blames a concurrent download (a private snapshot cannot be replaced). - Dead code removed: the byte[] download APIs (LoggerService#getLogBytes, LogClientDelegate#getWholeLogBytes, LocalLogClient#getWholeLog, RemoteLogClient#getWholeLog) and LogUtils#getFileContentBytesFromRemote in dolphinscheduler-common (zero callers after the above; the same whole-file-into-a-byte[] reader shape this PR eliminates). getFileContentBytesFromLocal stays for the worker-side legacy RPC. Tests: worker chunk RPC (range/EOF/not-found/truncated/clamp); LogClientDelegate (chunk loop, remote fallbacks, first-chunk failure distinguishing answered-but-cannot-dispatch vs unreachable vs structured non-SUCCESS, empty log terminal, mid-stream, rotation, node gone); RollingUpgradeLogStreamingIntegrationTest (real Netty wire, old-worker proxy: chunk RPC fails, whole-file RPC works and is invocation-counted — asserts the whole-file payload is never requested on the large-log path, with and without remote storage); ResponseFuture (drain isolation, set-once cause, identity removal, fail/cancel); NettyClientHandler (shared-channel concurrent drain regression, deserialize failure, timeout/interrupt leak guards); TransporterDecoder (per-field and combined frame limits); RemoteLogClient (bounded stream, empty-vs-missing, concurrent cache rewrite mid-transfer — verified to fail on the pre-snapshot code, failed transfer still deletes its snapshot, orphan sweep age gate); real-RPC integration tests (multi-chunk download + deterministic rotation); controller MockMvc (auth failure JSON; success asserts asyncStarted and the final asyncDispatch response — the body is written on the async thread, the old assertions raced it). Verified end-to-end in standalone (embedded Jetty + real Netty RPC): a 1 GB log downloads completely (byte-identical md5) with stable heap in a 1 GB JVM hosting api+master+worker together. Co-Authored-By: Claude --- .../api/controller/LoggerController.java | 41 +- .../api/executor/logging/LocalLogClient.java | 25 +- .../executor/logging/LogClientDelegate.java | 128 ++++- .../api/executor/logging/RemoteLogClient.java | 200 +++++++- .../api/service/LoggerService.java | 29 +- .../api/service/impl/LoggerServiceImpl.java | 124 +++-- .../LoggerControllerStreamingTest.java | 147 ++++++ .../executor/logging/LocalLogClientTest.java | 24 +- .../logging/LogClientDelegateTest.java | 371 ++++++++++++-- .../logging/LogStreamingIntegrationTest.java | 253 ++++++++++ .../executor/logging/RemoteLogClientTest.java | 261 ++++++++++ ...ingUpgradeLogStreamingIntegrationTest.java | 222 +++++++++ .../api/service/LoggerServiceTest.java | 192 ++++---- .../common/utils/LogUtils.java | 42 +- .../common/utils/LogUtilsTest.java | 80 +++ .../base/client/NettyClientHandler.java | 19 +- .../base/client/NettyRemotingClient.java | 75 ++- .../base/config/NettyClientConfig.java | 11 + .../base/config/NettyServerConfig.java | 11 + .../extract/base/future/ResponseFuture.java | 87 +++- .../base/protocal/TransporterDecoder.java | 32 ++ .../base/server/NettyRemotingServer.java | 2 +- .../base/client/NettyClientHandlerTest.java | 466 ++++++++++++++++++ .../base/future/ResponseFutureTest.java | 169 +++++++ .../base/protocal/TransporterDecoderTest.java | 147 ++++++ .../extract/common/ILogService.java | 7 + .../common/service/impl/LogServiceImpl.java | 65 +++ .../common/transportor/LogResponseStatus.java | 7 + .../TaskInstanceLogFileDownloadRequest.java | 17 + .../TaskInstanceLogFileDownloadResponse.java | 5 + .../service/impl/LogServiceImplTest.java | 205 ++++++++ 31 files changed, 3153 insertions(+), 311 deletions(-) create mode 100644 dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/controller/LoggerControllerStreamingTest.java create mode 100644 dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/LogStreamingIntegrationTest.java create mode 100644 dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/RemoteLogClientTest.java create mode 100644 dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/RollingUpgradeLogStreamingIntegrationTest.java create mode 100644 dolphinscheduler-common/src/test/java/org/apache/dolphinscheduler/common/utils/LogUtilsTest.java create mode 100644 dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/client/NettyClientHandlerTest.java create mode 100644 dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/future/ResponseFutureTest.java create mode 100644 dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/protocal/TransporterDecoderTest.java create mode 100644 dolphinscheduler-extract/dolphinscheduler-extract-common/src/test/java/org/apache/dolphinscheduler/extract/common/service/impl/LogServiceImplTest.java diff --git a/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/controller/LoggerController.java b/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/controller/LoggerController.java index f5ac4020c7d3..637683d6c5de 100644 --- a/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/controller/LoggerController.java +++ b/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/controller/LoggerController.java @@ -25,11 +25,16 @@ import org.apache.dolphinscheduler.api.utils.Result; import org.apache.dolphinscheduler.common.constants.Constants; import org.apache.dolphinscheduler.dao.entity.ResponseTaskLog; +import org.apache.dolphinscheduler.dao.entity.TaskInstance; import org.apache.dolphinscheduler.dao.entity.User; +import javax.servlet.http.HttpServletRequest; +import javax.servlet.http.HttpServletResponse; + import org.springframework.beans.factory.annotation.Autowired; import org.springframework.http.HttpHeaders; import org.springframework.http.HttpStatus; +import org.springframework.http.MediaType; import org.springframework.http.ResponseEntity; import org.springframework.web.bind.annotation.GetMapping; import org.springframework.web.bind.annotation.RequestAttribute; @@ -38,6 +43,9 @@ import org.springframework.web.bind.annotation.ResponseBody; import org.springframework.web.bind.annotation.ResponseStatus; import org.springframework.web.bind.annotation.RestController; +import org.springframework.web.context.request.async.StandardServletAsyncWebRequest; +import org.springframework.web.context.request.async.WebAsyncUtils; +import org.springframework.web.servlet.mvc.method.annotation.StreamingResponseBody; import io.swagger.v3.oas.annotations.Operation; import io.swagger.v3.oas.annotations.Parameter; @@ -50,6 +58,15 @@ @RequestMapping("/log") public class LoggerController extends BaseController { + /** + * Endpoint-scoped async timeout for the log download: {@link StreamingResponseBody} runs on + * the async request path where the servlet container's default timeout (30s in Jetty/Tomcat) + * SILENTLY truncates any download that takes longer — large log downloads regularly exceed + * it. Scoped to THIS endpoint instead of the global {@code spring.mvc.async.request-timeout} + * so that no other endpoint ever inherits a 1-hour async timeout. + */ + private static final long LOG_DOWNLOAD_ASYNC_TIMEOUT_MILLIS = 60 * 60 * 1000L; + @Autowired private LoggerService loggerService; @@ -92,14 +109,30 @@ public Result queryLog(@Parameter(hidden = true) @RequestAttrib @GetMapping(value = "/download-log") @ResponseBody @ApiException(DOWNLOAD_TASK_INSTANCE_LOG_FILE_ERROR) - public ResponseEntity downloadTaskLog(@Parameter(hidden = true) @RequestAttribute(value = Constants.SESSION_USER) User loginUser, - @RequestParam(value = "taskInstanceId") int taskInstanceId) { - byte[] logBytes = loggerService.getLogBytes(loginUser, taskInstanceId); + public ResponseEntity downloadTaskLog( + @Parameter(hidden = true) @RequestAttribute(value = Constants.SESSION_USER) User loginUser, + @RequestParam(value = "taskInstanceId") int taskInstanceId, + @Parameter(hidden = true) HttpServletRequest request, + @Parameter(hidden = true) HttpServletResponse response) { + // Sync auth check — throws ServiceException BEFORE response is committed, + // so @ApiException can still return a proper JSON error + final TaskInstance taskInstance = loggerService.checkDownloadLogAuth(loginUser, taskInstanceId); + // Scope a long async timeout to THIS request only (after the auth check, so failures + // stay on the non-async JSON error path). The servlet container's default async + // timeout (30s in Jetty/Tomcat) silently truncates StreamingResponseBody downloads + // that take longer. The WebAsyncManager is request-scoped: installing a custom + // AsyncWebRequest here affects only this endpoint — unlike the global + // spring.mvc.async.request-timeout. + final StandardServletAsyncWebRequest asyncWebRequest = new StandardServletAsyncWebRequest(request, response); + asyncWebRequest.setTimeout(LOG_DOWNLOAD_ASYNC_TIMEOUT_MILLIS); + WebAsyncUtils.getAsyncManager(request).setAsyncWebRequest(asyncWebRequest); + final StreamingResponseBody body = outputStream -> loggerService.streamLogBytes(taskInstance, outputStream); return ResponseEntity .ok() + .contentType(MediaType.APPLICATION_OCTET_STREAM) .header(HttpHeaders.CONTENT_DISPOSITION, "attachment; filename=\"" + System.currentTimeMillis() + ".log" + "\"") - .body(logBytes); + .body(body); } } diff --git a/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/LocalLogClient.java b/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/LocalLogClient.java index ebe8b2e9fea2..b20f00555e9c 100644 --- a/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/LocalLogClient.java +++ b/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/LocalLogClient.java @@ -33,18 +33,6 @@ @Slf4j public class LocalLogClient { - /** - * Download the complete log of a task instance. - * This method is used to retrieve all log information from the start to the end of a task instance, - * suitable for scenarios where a complete log record is required. - * - * @param taskInstance The task instance object, containing information needed to retrieve the log. - * @return The complete log file download response of the task instance, including log content and metadata. - */ - public TaskInstanceLogFileDownloadResponse getWholeLog(TaskInstance taskInstance) { - return getLocalWholeLog(taskInstance); - } - /** * Query a portion of the log of a task instance. * This method is used to query log information of a task instance in a paginated manner, @@ -59,11 +47,14 @@ public TaskInstanceLogPageQueryResponse getPartLog(TaskInstance taskInstance, in return getLocalPartLog(taskInstance, skipLineNum, limit); } - private TaskInstanceLogFileDownloadResponse getLocalWholeLog(TaskInstance taskInstance) { - TaskInstanceLogFileDownloadRequest request = new TaskInstanceLogFileDownloadRequest( - taskInstance.getId(), - taskInstance.getLogPath()); - return getProxyLogService(taskInstance).getTaskInstanceWholeLogFileBytes(request); + /** + * Fetch a single bounded chunk of the task instance log from the worker via chunked RPC. + */ + public TaskInstanceLogFileDownloadResponse getLogChunk(final TaskInstance taskInstance, + final long offset, final int length) { + final TaskInstanceLogFileDownloadRequest request = new TaskInstanceLogFileDownloadRequest( + taskInstance.getId(), taskInstance.getLogPath(), offset, length); + return getProxyLogService(taskInstance).getTaskInstanceLogFileChunk(request); } private TaskInstanceLogPageQueryResponse getLocalPartLog(TaskInstance taskInstance, int skipLineNum, diff --git a/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/LogClientDelegate.java b/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/LogClientDelegate.java index ac5b6ecb2ba4..b08ae1d72e76 100644 --- a/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/LogClientDelegate.java +++ b/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/LogClientDelegate.java @@ -18,6 +18,7 @@ package org.apache.dolphinscheduler.api.executor.logging; import org.apache.dolphinscheduler.dao.entity.TaskInstance; +import org.apache.dolphinscheduler.extract.base.exception.MethodInvocationException; import org.apache.dolphinscheduler.extract.common.transportor.LogResponseStatus; import org.apache.dolphinscheduler.extract.common.transportor.TaskInstanceLogFileDownloadResponse; import org.apache.dolphinscheduler.extract.common.transportor.TaskInstanceLogPageQueryResponse; @@ -25,6 +26,11 @@ import org.apache.dolphinscheduler.registry.api.RegistryClient; import org.apache.dolphinscheduler.registry.api.enums.RegistryNodeType; +import org.apache.commons.lang3.exception.ExceptionUtils; + +import java.io.IOException; +import java.io.OutputStream; + import lombok.extern.slf4j.Slf4j; import org.springframework.beans.factory.annotation.Autowired; @@ -34,6 +40,8 @@ @Component public class LogClientDelegate { + private static final int LOG_CHUNK_SIZE = 8 * 1024 * 1024; // 8 MB + @Autowired private LocalLogClient localLogClient; @Autowired @@ -66,29 +74,6 @@ public String getPartLogString(TaskInstance taskInstance, int skipLineNum, int l } } - /** - * Retrieves the complete log content for a given task instance as a byte array. - * This method first attempts to fetch the log from local storage; if unsuccessful, it tries to obtain the log from remote storage. - * - * @param taskInstance The task instance object, containing information needed for log retrieval. - * @return A byte array containing the complete log content. - */ - public byte[] getWholeLogBytes(TaskInstance taskInstance) { - checkArgs(taskInstance); - if (checkNodeExists(taskInstance)) { - TaskInstanceLogFileDownloadResponse response = localLogClient.getWholeLog(taskInstance); - if (response.getCode() == LogResponseStatus.SUCCESS) { - return response.getLogBytes(); - } else { - log.warn("get whole log bytes is not success for task instance {}; reason :{}", taskInstance.getId(), - response.getMessage()); - return remoteLogClient.getWholeLog(taskInstance); - } - } else { - return remoteLogClient.getWholeLog(taskInstance); - } - } - private static void checkArgs(TaskInstance taskInstance) { if (taskInstance == null) { throw new IllegalArgumentException("canFetchLog task instance is null"); @@ -109,4 +94,101 @@ private boolean checkNodeExists(TaskInstance taskInstance) { return exists; } + /** + * Stream the entire task instance log to {@code outputStream} using bounded chunk RPCs. + * + *

Strategy: + *

    + *
  • If the worker node is gone, read straight from remote log storage (archive), streamed + * in bounded chunks.
    • + *
  • Otherwise stream via the chunk RPC. If the FIRST chunk fails — e.g. an old worker + * during a rolling upgrade does not implement {@code getTaskInstanceLogFileChunk} — + * fall back to remote log storage; if that also fails, throw an explicit error asking + * for a worker upgrade.
    • + *
  • The legacy whole-file worker RPC is deliberately NEVER used: it reads the entire file + * into the worker's heap before serialization, so a large log can OOM the worker. A + * receiver-side maxFrameSize cannot prevent that allocation, and an old worker (already + * deployed, cannot be patched) offers no way to establish a safe size before the whole + * payload is built — so small-log compatibility with old workers is intentionally not + * preserved either.
    • + *
  • If a failure happens mid-stream (bytes already written), throw IOException to avoid + * corrupting the download.
    • + *
+ */ + public void streamWholeLog(final TaskInstance taskInstance, final OutputStream outputStream) throws IOException { + checkArgs(taskInstance); + if (!checkNodeExists(taskInstance)) { + remoteLogClient.streamWholeLog(taskInstance, outputStream); + return; + } + long offset = 0; + while (true) { + final TaskInstanceLogFileDownloadResponse chunk; + try { + chunk = localLogClient.getLogChunk(taskInstance, offset, LOG_CHUNK_SIZE); + } catch (Exception e) { + if (offset > 0) { + throw new IOException("Log streaming failed at offset " + offset, e); + } + log.warn("Chunked log RPC failed for task instance {}, falling back to remote log storage", + taskInstance.getId(), e); + // A MethodInvocationException means the worker ANSWERED but could not dispatch the + // method — that is the old-worker signal (rolling upgrade: the chunk method does + // not exist there), so the upgrade guidance is accurate. Any other transport + // failure (connect refused, timeout) just means the worker is unreachable; blaming + // the worker version would mislead operations. + final String errorMessage = + ExceptionUtils.throwableOfType(e, MethodInvocationException.class) != null + ? "Worker upgrade required for large log download: chunked log RPC is not available" + + " on worker " + taskInstance.getHost() + " and remote log storage also failed" + : "Chunked log RPC to worker " + taskInstance.getHost() + + " failed (the worker may be down or unreachable)" + + " and remote log storage also failed"; + fallbackToRemoteStorage(taskInstance, outputStream, errorMessage); + return; + } + if (chunk == null || chunk.getCode() != LogResponseStatus.SUCCESS) { + final String failure = chunk == null + ? "worker returned no response" + : chunk.getCode() + ": " + chunk.getMessage(); + if (offset > 0) { + throw new IOException("Worker chunk failed at offset " + offset + ": " + failure); + } + log.warn("First chunk failed for task instance {} ({}), falling back to remote log storage", + taskInstance.getId(), failure); + // The worker ANSWERED (structured response) — it supports the chunk RPC, so no + // upgrade guidance here; report both failures as they are. + fallbackToRemoteStorage(taskInstance, outputStream, + "Chunked log fetch failed on worker " + taskInstance.getHost() + " for task instance " + + taskInstance.getId() + " (" + failure + ") and remote log storage also failed"); + return; + } + final byte[] data = chunk.getLogBytes(); + if (data != null && data.length > 0) { + outputStream.write(data); + offset += data.length; + } + if (chunk.isEof() || (data == null || data.length == 0)) { + return; + } + } + } + + /** + * The ONLY fallback of the streaming path: stream the log from remote log storage. If remote + * storage cannot serve the log either, fail with an explicit error — the legacy whole-file + * worker RPC is deliberately never used (it is unbounded on the worker side, see + * {@link #streamWholeLog}). Exceptions from the fallback propagate directly; there is no + * second fallback to re-enter. + */ + private void fallbackToRemoteStorage(final TaskInstance taskInstance, + final OutputStream outputStream, + final String errorMessage) throws IOException { + try { + remoteLogClient.streamWholeLog(taskInstance, outputStream); + } catch (Exception e) { + throw new IOException(errorMessage, e); + } + } + } diff --git a/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/RemoteLogClient.java b/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/RemoteLogClient.java index 1b3542e96209..aa2d6fd73e86 100644 --- a/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/RemoteLogClient.java +++ b/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/RemoteLogClient.java @@ -17,38 +17,214 @@ package org.apache.dolphinscheduler.api.executor.logging; +import org.apache.dolphinscheduler.common.log.remote.RemoteLogUtils; import org.apache.dolphinscheduler.common.utils.LogUtils; import org.apache.dolphinscheduler.dao.entity.TaskInstance; +import org.apache.commons.io.IOUtils; + +import java.io.FileInputStream; +import java.io.IOException; +import java.io.InputStream; +import java.io.OutputStream; +import java.nio.file.Files; +import java.nio.file.Path; +import java.nio.file.Paths; +import java.nio.file.StandardCopyOption; +import java.util.UUID; +import java.util.concurrent.locks.ReentrantLock; +import java.util.stream.Stream; + +import javax.annotation.PostConstruct; + +import lombok.extern.slf4j.Slf4j; + import org.springframework.stereotype.Component; +@Slf4j @Component public class RemoteLogClient { /** - * Retrieves the entire log content for a given task instance. - * This method is used when it is necessary to obtain all the log information for a task instance. - * - * @param taskInstance The task instance object, containing information such as the task ID and log path. - * @return Returns the log content in byte array format. + * Marker of the per-download snapshot files ({@code .download-}), also used + * by the startup sweep to recognize orphans. + */ + private static final String SNAPSHOT_MARKER = ".download-"; + + /** + * Snapshots younger than this are never swept as orphans: on the (unsupported but possible) + * shared-disk setup the age gate protects another live instance's in-flight transfer. + */ + private static final long ORPHAN_SNAPSHOT_MIN_AGE_MILLIS = 60 * 60 * 1000L; + + /** + * Striped locks serializing download + snapshot per log path. The remote log handlers + * rewrite the local archive file in place ({@code new FileOutputStream(logPath)} truncates + * it), so concurrent download/view requests for the same log must not interleave their + * download windows; {@link #streamWholeLog} additionally snapshots the archive into a + * private temp file, so its lock-free streaming read stays stable across later cache + * rewrites. A fixed stripe array avoids unbounded lock-map growth; different logs sharing + * a stripe only lose a little parallelism, never correctness. Each API instance downloads + * to its own local disk, so per-JVM locking is sufficient. + */ + private static final int LOCK_STRIPES = 64; + private static final ReentrantLock[] LOG_PATH_LOCKS = new ReentrantLock[LOCK_STRIPES]; + + static { + for (int i = 0; i < LOCK_STRIPES; i++) { + LOG_PATH_LOCKS[i] = new ReentrantLock(); + } + } + + static ReentrantLock lockFor(final String logPath) { + return LOG_PATH_LOCKS[(logPath.hashCode() & 0x7fffffff) % LOCK_STRIPES]; + } + + /** + * At startup this JVM can have no in-flight transfer, so any snapshot file left over from a + * previous life (graceful shutdown and kill -9 alike skip the transfer's {@code finally}) is + * an orphan and is swept. Best effort: any error just skips the sweep. Does nothing when + * logging is not initialized (e.g. plain unit tests). + */ + @PostConstruct + public void deleteOrphanedSnapshots() { + final String baseDir = LogUtils.getLocalLogBaseDir(); + if (baseDir != null) { + deleteOrphanedSnapshots(Paths.get(baseDir)); + } + } + + void deleteOrphanedSnapshots(final Path baseDir) { + try (Stream walk = Files.walk(baseDir)) { + walk.filter(Files::isRegularFile) + .filter(file -> file.getFileName().toString().contains(SNAPSHOT_MARKER)) + .filter(RemoteLogClient::olderThanOrphanAge) + .forEach(this::deleteSnapshotQuietly); + } catch (Exception e) { + log.warn("Failed to sweep orphaned log download snapshots under {}", baseDir, e); + } + } + + private static boolean olderThanOrphanAge(final Path file) { + // java.io.File#lastModified returns 0 when the time cannot be read — treat that as + // "unknown age, keep it" rather than sweeping blindly. + final long lastModified = file.toFile().lastModified(); + return lastModified > 0 && lastModified < System.currentTimeMillis() - ORPHAN_SNAPSHOT_MIN_AGE_MILLIS; + } + + /** + * Stream the entire remote-archived log to {@code outputStream} without loading the whole + * file into memory. Downloads the archive to a local file, snapshots it into a private temp + * file ({@code .download-}, deleted when the transfer ends; leftovers are + * swept by {@link #deleteOrphanedSnapshots()}) and streams that snapshot — see the + * {@code LOG_PATH_LOCKS} note for why the snapshot is required. Costs a second write of the + * archive (~2x peak disk for one download). + * + * @throws IOException if the log cannot be downloaded, the file is missing, no data is + * available, or the snapshot ends prematurely (local disk trouble). + */ + public void streamWholeLog(final TaskInstance taskInstance, + final OutputStream outputStream) throws IOException { + final String logPath = taskInstance.getLogPath(); + final Path archive = Paths.get(logPath); + final InputStream in; + final long expectedLength; + Path snapshot = null; + final ReentrantLock lock = lockFor(logPath); + lock.lock(); + try { + RemoteLogUtils.getRemoteLog(logPath); + if (!Files.isRegularFile(archive)) { + throw new IOException("Remote log file not found after download (remote log archiving may not be " + + "enabled or the archive is missing): " + logPath); + } + // A 0-byte archive is a LEGAL empty log ("task produced no output") — the same + // terminal state as an empty log served by a live worker — and must stream + // normally (zero bytes; the caller appends the head). Only a MISSING file is an + // error: a missing archive must not be reported as a successful empty download. + snapshot = archive.resolveSibling(archive.getFileName() + SNAPSHOT_MARKER + UUID.randomUUID()); + boolean opened = false; + try { + Files.copy(archive, snapshot, StandardCopyOption.REPLACE_EXISTING); + expectedLength = Files.size(snapshot); + // Open inside the lock, after the size capture — the stream reads our private + // snapshot, which nothing else can modify. + in = new FileInputStream(snapshot.toFile()); + opened = true; + } finally { + // finally (not catch): a partial snapshot must never survive a failed creation, + // whatever the failure type — up to and including Error (e.g. OOM mid-copy). + if (!opened) { + deleteSnapshotQuietly(snapshot); + } + } + } finally { + lock.unlock(); + } + try { + streamBounded(in, expectedLength, outputStream); + } finally { + try { + in.close(); + } catch (Throwable e) { + // Throwable, not IOException: a close failure must neither mask the transfer's + // own exception nor skip the snapshot deletion below. + log.warn("Failed to close the log download snapshot stream for {}", logPath, e); + } + deleteSnapshotQuietly(snapshot); + } + outputStream.flush(); + } + + private void deleteSnapshotQuietly(final Path snapshot) { + try { + Files.deleteIfExists(snapshot); + } catch (Throwable e) { + // Throwable, not IOException: this runs in finally blocks and must never throw + // through them (masking the original failure) or give up on deletion early. + log.warn("Failed to delete the log download snapshot {}", snapshot, e); + } + } + + /** + * Copies exactly {@code expectedLength} bytes from {@code in} to {@code outputStream}; an + * early EOF must fail explicitly rather than end the HTTP response cleanly with a short + * body. With the private snapshot this should be unreachable — nothing else modifies it — + * and is kept as defense in depth against local disk trouble. {@code IOUtils.copyLarge} + * clamps every buffer write to the remaining length, so bytes appended after our size + * snapshot never leak into the stream. */ - public byte[] getWholeLog(TaskInstance taskInstance) { - return LogUtils.getFileContentBytesFromRemote(taskInstance.getLogPath()); + void streamBounded(final InputStream in, final long expectedLength, + final OutputStream outputStream) throws IOException { + final long copied = IOUtils.copyLarge(in, outputStream, 0, expectedLength); + if (copied < expectedLength) { + throw new IOException("Log file short read: expected " + expectedLength + " bytes but the local" + + " snapshot ended after " + copied + " (local disk trouble), please retry"); + } } /** * Retrieves part of the log content for a given task instance, based on the specified line number and the number of lines to read. - * This method is used when it is necessary to browse a portion of the log content, allowing for skipping a certain number of lines and limiting the number of lines read. - * + * This method is used when it is necessary to browse a portion of the log content, allowing for skipping a certain number of lines and limiting the number of lines to read. + * * @param taskInstance The task instance object, containing information such as the task ID and log path. * @param skipLineNum The number of lines to skip, starting from the beginning of the log. * @param limit The maximum number of lines to read. * @return Returns the specified part of the log content in string format. */ public String getPartLog(TaskInstance taskInstance, int skipLineNum, int limit) { - // todo We can optimize requests by the actual range, reducing disk usage and network traffic. - return LogUtils.rollViewLogLines( - LogUtils.readPartFileContentFromRemote(taskInstance.getLogPath(), skipLineNum, limit)); + final ReentrantLock lock = lockFor(taskInstance.getLogPath()); + lock.lock(); + try { + // Download + bounded partial read (response is line-limited) under one lock; the + // download dominates the duration — only same-log requests (or stripe collisions) + // serialize. + // todo We can optimize requests by the actual range, reducing disk usage and network traffic. + return LogUtils.rollViewLogLines( + LogUtils.readPartFileContentFromRemote(taskInstance.getLogPath(), skipLineNum, limit)); + } finally { + lock.unlock(); + } } } diff --git a/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/service/LoggerService.java b/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/service/LoggerService.java index a31b73eefc29..f10bc35d548d 100644 --- a/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/service/LoggerService.java +++ b/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/service/LoggerService.java @@ -19,8 +19,12 @@ import org.apache.dolphinscheduler.api.utils.Result; import org.apache.dolphinscheduler.dao.entity.ResponseTaskLog; +import org.apache.dolphinscheduler.dao.entity.TaskInstance; import org.apache.dolphinscheduler.dao.entity.User; +import java.io.IOException; +import java.io.OutputStream; + public interface LoggerService { /** @@ -34,15 +38,6 @@ public interface LoggerService { */ Result queryLog(User loginUser, int taskInstId, int skipLineNum, int limit); - /** - * get log size - * - * @param loginUser login user - * @param taskInstId task instance id - * @return log byte array - */ - byte[] getLogBytes(User loginUser, int taskInstId); - /** * query log * @@ -56,12 +51,14 @@ public interface LoggerService { String queryLog(User loginUser, long projectCode, int taskInstId, int skipLineNum, int limit); /** - * get log bytes - * - * @param loginUser login user - * @param projectCode project code - * @param taskInstId task instance id - * @return log byte array + * Verify the user has permission to download the task log and return the task instance. + * Must be called BEFORE the HTTP response is committed (i.e., before StreamingResponseBody). + */ + TaskInstance checkDownloadLogAuth(User loginUser, int taskInstId); + + /** + * Stream the task instance log to the given output stream in bounded chunks. The caller must + * have already verified access via {@link #checkDownloadLogAuth}. */ - byte[] getLogBytes(User loginUser, long projectCode, int taskInstId); + void streamLogBytes(TaskInstance taskInstance, OutputStream outputStream) throws IOException; } diff --git a/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/service/impl/LoggerServiceImpl.java b/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/service/impl/LoggerServiceImpl.java index fac27c934575..1448d05a16c7 100644 --- a/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/service/impl/LoggerServiceImpl.java +++ b/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/service/impl/LoggerServiceImpl.java @@ -38,15 +38,16 @@ import org.apache.commons.lang3.StringUtils; +import java.io.IOException; +import java.io.OutputStream; import java.nio.charset.StandardCharsets; +import java.util.concurrent.atomic.AtomicBoolean; import lombok.extern.slf4j.Slf4j; import org.springframework.beans.factory.annotation.Autowired; import org.springframework.stereotype.Service; -import com.google.common.primitives.Bytes; - @Service @Slf4j public class LoggerServiceImpl extends BaseServiceImpl implements LoggerService { @@ -99,24 +100,6 @@ public Result queryLog(User loginUser, int taskInstId, int skip return result; } - /** - * get log size - * - * @param loginUser login user - * @param taskInstId task instance id - * @return log byte array - */ - @Override - public byte[] getLogBytes(User loginUser, int taskInstId) { - TaskInstance taskInstance = taskInstanceDao.queryById(taskInstId); - if (taskInstance == null || StringUtils.isBlank(taskInstance.getHost())) { - throw new ServiceException("task instance is null or host is null"); - } - Project project = projectDao.queryProjectByTaskInstanceId(taskInstId); - projectService.checkProjectAndAuthThrowException(loginUser, project, DOWNLOAD_LOG); - return getLogBytes(taskInstance); - } - /** * query log * @@ -145,32 +128,6 @@ public String queryLog(User loginUser, long projectCode, int taskInstId, int ski return queryLog(task, skipLineNum, limit); } - /** - * get log bytes - * - * @param loginUser login user - * @param projectCode project code - * @param taskInstId task instance id - * @return log byte array - */ - @Override - public byte[] getLogBytes(User loginUser, long projectCode, int taskInstId) { - // check user access for project - projectService.checkProjectAndAuthThrowException(loginUser, projectCode, DOWNLOAD_LOG); - - // check whether the task instance can be found - TaskInstance task = taskInstanceDao.queryById(taskInstId); - if (task == null || StringUtils.isBlank(task.getHost())) { - throw new ServiceException("task instance is null or host is null"); - } - - TaskDefinition taskDefinition = taskDefinitionDao.queryByCode(task.getTaskCode()); - if (taskDefinition != null && projectCode != taskDefinition.getProjectCode()) { - throw new ServiceException("task instance does not exist in project"); - } - return getLogBytes(task); - } - /** * query log * @@ -208,29 +165,66 @@ private String queryLog(TaskInstance taskInstance, int skipLineNum, int limit) { } } - /** - * get log bytes - * - * @param taskInstance task instance - * @return log byte array - */ - private byte[] getLogBytes(TaskInstance taskInstance) { - String host = taskInstance.getHost(); - String logPath = taskInstance.getLogPath(); + @Override + public TaskInstance checkDownloadLogAuth(final User loginUser, final int taskInstId) { + final TaskInstance taskInstance = taskInstanceDao.queryById(taskInstId); + if (taskInstance == null || StringUtils.isBlank(taskInstance.getHost())) { + throw new ServiceException("task instance is null or host is null"); + } + if (StringUtils.isBlank(taskInstance.getLogPath())) { + throw new ServiceException("task instance log path is empty"); + } + final Project project = projectDao.queryProjectByTaskInstanceId(taskInstId); + projectService.checkProjectAndAuthThrowException(loginUser, project, DOWNLOAD_LOG); + return taskInstance; + } - byte[] head = String.format(LOG_HEAD_FORMAT, - logPath, - host, + @Override + public void streamLogBytes(final TaskInstance taskInstance, + final OutputStream outputStream) throws IOException { + final byte[] head = String.format(LOG_HEAD_FORMAT, + taskInstance.getLogPath(), + taskInstance.getHost(), Constants.SYSTEM_LINE_SEPARATOR).getBytes(StandardCharsets.UTF_8); + // Write the head LAZILY, right before the first log byte: writing it up front commits + // the HTTP response, and any startup failure in the fallback chain (missing log on the + // worker AND no remote archive) would then degrade to a broken 200 with a header-only + // .log body instead of a proper JSON error. + final AtomicBoolean headWritten = new AtomicBoolean(false); + final OutputStream lazyHead = new OutputStream() { + + private void ensureHead() throws IOException { + if (headWritten.compareAndSet(false, true)) { + outputStream.write(head); + } + } - byte[] logBytes; + @Override + public void write(final int b) throws IOException { + ensureHead(); + outputStream.write(b); + } - try { - logBytes = logClientDelegate.getWholeLogBytes(taskInstance); - return Bytes.concat(head, logBytes); - } catch (Exception ex) { - log.error("Download TaskInstance: {} Log Error", taskInstance.getName(), ex); - throw new ServiceException(Status.DOWNLOAD_TASK_INSTANCE_LOG_FILE_ERROR); + @Override + public void write(final byte[] b, final int off, final int len) throws IOException { + if (len > 0) { + ensureHead(); + outputStream.write(b, off, len); + } + } + + @Override + public void flush() throws IOException { + if (headWritten.get()) { + outputStream.flush(); + } + } + }; + logClientDelegate.streamWholeLog(taskInstance, lazyHead); + if (!headWritten.get()) { + // Valid empty log: keep the legacy head-only body. + outputStream.write(head); } + outputStream.flush(); } } diff --git a/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/controller/LoggerControllerStreamingTest.java b/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/controller/LoggerControllerStreamingTest.java new file mode 100644 index 000000000000..279ed379d523 --- /dev/null +++ b/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/controller/LoggerControllerStreamingTest.java @@ -0,0 +1,147 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.apache.dolphinscheduler.api.controller; + +import static org.hamcrest.Matchers.containsString; +import static org.mockito.ArgumentMatchers.any; +import static org.mockito.ArgumentMatchers.eq; +import static org.mockito.Mockito.doAnswer; +import static org.mockito.Mockito.doThrow; +import static org.mockito.Mockito.never; +import static org.mockito.Mockito.verify; +import static org.mockito.Mockito.when; +import static org.springframework.test.web.servlet.request.MockMvcRequestBuilders.asyncDispatch; +import static org.springframework.test.web.servlet.request.MockMvcRequestBuilders.get; +import static org.springframework.test.web.servlet.result.MockMvcResultMatchers.content; +import static org.springframework.test.web.servlet.result.MockMvcResultMatchers.header; +import static org.springframework.test.web.servlet.result.MockMvcResultMatchers.request; +import static org.springframework.test.web.servlet.result.MockMvcResultMatchers.status; + +import org.apache.dolphinscheduler.api.exceptions.ApiExceptionHandler; +import org.apache.dolphinscheduler.api.exceptions.ServiceException; +import org.apache.dolphinscheduler.api.service.LoggerService; +import org.apache.dolphinscheduler.common.constants.Constants; +import org.apache.dolphinscheduler.dao.entity.TaskInstance; +import org.apache.dolphinscheduler.dao.entity.User; + +import java.io.OutputStream; +import java.nio.charset.StandardCharsets; + +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.ExtendWith; +import org.mockito.InjectMocks; +import org.mockito.Mock; +import org.mockito.junit.jupiter.MockitoExtension; +import org.springframework.http.HttpHeaders; +import org.springframework.http.MediaType; +import org.springframework.test.web.servlet.MockMvc; +import org.springframework.test.web.servlet.MvcResult; +import org.springframework.test.web.servlet.setup.MockMvcBuilders; + +/** + * Controller-layer test for the streaming log download endpoint. + * + *

Covers the complete API path (controller -> service) that the regression review asked for: + *

    + *
  • Auth failure thrown synchronously, before the response is committed, must come back as a + * JSON error (via @ApiException) — not as a fake .log download.
    • + *
  • Successful auth must stream the log as application/octet-stream with an attachment + * Content-Disposition.
    • + *
+ * LoggerService is mocked so the contract is verified independently of the worker/DB. + */ +@ExtendWith(MockitoExtension.class) +public class LoggerControllerStreamingTest { + + @Mock + private LoggerService loggerService; + + @InjectMocks + private LoggerController loggerController; + + private MockMvc mockMvc; + + @BeforeEach + public void setUp() { + mockMvc = MockMvcBuilders.standaloneSetup(loggerController) + .setControllerAdvice(new ApiExceptionHandler()) + .build(); + } + + @Test + public void downloadTaskLog_authFailure_returnsJsonErrorNotLogFile() throws Exception { + User loginUser = new User(); + loginUser.setId(1); + + // checkDownloadLogAuth runs BEFORE the StreamingResponseBody is returned, so the + // ServiceException is mapped by @ApiException into a JSON error response. + doThrow(new ServiceException("task instance is null or host is null")) + .when(loggerService).checkDownloadLogAuth(eq(loginUser), eq(1)); + + mockMvc.perform(get("/log/download-log") + .requestAttr(Constants.SESSION_USER, loginUser) + .param("taskInstanceId", "1") + .accept(MediaType.APPLICATION_JSON)) + .andExpect(status().isOk()) + .andExpect(content().contentType(MediaType.APPLICATION_JSON)) + .andExpect(content().string(containsString("task instance is null or host is null"))); + + // Nothing must have been streamed on the failure path. + verify(loggerService, never()).streamLogBytes(any(), any()); + } + + @Test + public void downloadTaskLog_success_streamsOctetStreamWithAttachmentHeader() throws Exception { + User loginUser = new User(); + loginUser.setId(1); + TaskInstance taskInstance = new TaskInstance(); + taskInstance.setId(1); + + when(loggerService.checkDownloadLogAuth(eq(loginUser), eq(1))).thenReturn(taskInstance); + + // Simulate the service streaming the log into the response output stream. + byte[] logBytes = "[LOG-PATH]: /tmp/1.log, [HOST]: 127.0.0.1:1234\nSTREAMED_LOG_BODY\n" + .getBytes(StandardCharsets.UTF_8); + doAnswer(invocation -> { + OutputStream os = invocation.getArgument(1); + os.write(logBytes); + os.flush(); + return null; + }).when(loggerService).streamLogBytes(eq(taskInstance), any()); + + // StreamingResponseBody writes on the ASYNC thread, so the initial perform() only + // starts the async processing — the body is not guaranteed to exist yet. Assert + // asyncStarted, then assert the FINAL response through asyncDispatch. + MvcResult mvcResult = mockMvc.perform(get("/log/download-log") + .requestAttr(Constants.SESSION_USER, loginUser) + .param("taskInstanceId", "1")) + .andExpect(request().asyncStarted()) + .andReturn(); + + mockMvc.perform(asyncDispatch(mvcResult)) + .andExpect(status().isOk()) + .andExpect(content().contentType(MediaType.APPLICATION_OCTET_STREAM)) + .andExpect(header().string(HttpHeaders.CONTENT_DISPOSITION, containsString("attachment"))) + .andExpect(content().bytes(logBytes)); + // The endpoint-scoped async timeout (WebAsyncManager + custom AsyncWebRequest) is + // verified end-to-end against a real container in the standalone 1 GB download test; + // MockMvc's AsyncContext defaults do not reflect the wiring faithfully enough to + // assert on here. + } +} diff --git a/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/LocalLogClientTest.java b/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/LocalLogClientTest.java index 38ed86900790..62ffd6cfa83c 100644 --- a/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/LocalLogClientTest.java +++ b/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/LocalLogClientTest.java @@ -17,7 +17,6 @@ package org.apache.dolphinscheduler.api.executor.logging; -import static org.junit.Assert.assertArrayEquals; import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertNotNull; @@ -71,10 +70,10 @@ public void setUp() { @Override public TaskInstanceLogFileDownloadResponse getTaskInstanceWholeLogFileBytes(TaskInstanceLogFileDownloadRequest taskInstanceLogFileDownloadRequest) { if (taskInstanceLogFileDownloadRequest.getTaskInstanceId() == 1) { - return new TaskInstanceLogFileDownloadResponse(new byte[0], LogResponseStatus.SUCCESS, ""); + return new TaskInstanceLogFileDownloadResponse(new byte[0], LogResponseStatus.SUCCESS, "", true); } else if (taskInstanceLogFileDownloadRequest.getTaskInstanceId() == 10) { return new TaskInstanceLogFileDownloadResponse("log content".getBytes(), LogResponseStatus.SUCCESS, - ""); + "", true); } throw new ServiceException("download error"); @@ -98,6 +97,12 @@ public TaskInstanceLogPageQueryResponse pageQueryTaskInstanceLog(TaskInstanceLog public void removeTaskInstanceLog(String taskInstanceLogAbsolutePath) { } + + @Override + public TaskInstanceLogFileDownloadResponse getTaskInstanceLogFileChunk( + TaskInstanceLogFileDownloadRequest request) { + return new TaskInstanceLogFileDownloadResponse(); + } }); springServerMethodInvokerDiscovery.start(); } @@ -109,19 +114,6 @@ public void tearDown() { } } - @Test - public void testGetWholeLogSuccess() { - TaskInstance taskInstance = new TaskInstance(); - taskInstance.setHost("127.0.0.1:" + nettyServerPort); - taskInstance.setId(1); - taskInstance.setLogPath("/path/to/log"); - - TaskInstanceLogFileDownloadResponse actualResponse = localLogClient.getWholeLog(taskInstance); - - assertNotNull(actualResponse); - assertArrayEquals("".getBytes(), actualResponse.getLogBytes()); - } - @Test public void testGetPartLogSuccess() { TaskInstance taskInstance = new TaskInstance(); diff --git a/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/LogClientDelegateTest.java b/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/LogClientDelegateTest.java index edf85268a723..9553142c4f9a 100644 --- a/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/LogClientDelegateTest.java +++ b/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/LogClientDelegateTest.java @@ -19,18 +19,33 @@ import static org.junit.jupiter.api.Assertions.assertArrayEquals; import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertFalse; import static org.junit.jupiter.api.Assertions.assertThrows; +import static org.junit.jupiter.api.Assertions.assertTrue; import static org.mockito.ArgumentMatchers.any; +import static org.mockito.ArgumentMatchers.anyInt; +import static org.mockito.ArgumentMatchers.anyLong; import static org.mockito.ArgumentMatchers.eq; +import static org.mockito.Mockito.doAnswer; +import static org.mockito.Mockito.doThrow; +import static org.mockito.Mockito.never; +import static org.mockito.Mockito.times; +import static org.mockito.Mockito.verify; import static org.mockito.Mockito.when; import org.apache.dolphinscheduler.dao.entity.TaskInstance; +import org.apache.dolphinscheduler.extract.base.exception.MethodInvocationException; import org.apache.dolphinscheduler.extract.common.transportor.LogResponseStatus; import org.apache.dolphinscheduler.extract.common.transportor.TaskInstanceLogFileDownloadResponse; import org.apache.dolphinscheduler.extract.common.transportor.TaskInstanceLogPageQueryResponse; import org.apache.dolphinscheduler.registry.api.RegistryClient; import org.apache.dolphinscheduler.registry.api.enums.RegistryNodeType; +import java.io.ByteArrayOutputStream; +import java.io.IOException; +import java.io.OutputStream; +import java.nio.charset.StandardCharsets; + import org.junit.jupiter.api.Test; import org.junit.jupiter.api.extension.ExtendWith; import org.mockito.InjectMocks; @@ -101,52 +116,344 @@ public void testGetPartLogStringNodeNotExists() { } @Test - public void testGetWholeLogBytesTaskInstanceNullThrowsException() { - assertThrows(IllegalArgumentException.class, () -> logClientDelegate.getWholeLogBytes(null)); + public void testStreamWholeLogTaskInstanceNullThrowsException() { + assertThrows(IllegalArgumentException.class, () -> logClientDelegate.streamWholeLog(null, + new ByteArrayOutputStream())); + } + + // ==================== streamWholeLog tests ==================== + + private static TaskInstance newTaskInstance() { + TaskInstance ti = new TaskInstance(); + ti.setId(1); + ti.setHost("localhost"); + ti.setTaskType("SHELL"); + return ti; } @Test - public void testGetWholeLogBytesNodeExistsLocalSuccess() { - TaskInstance taskInstance = new TaskInstance(); - taskInstance.setId(1); - taskInstance.setHost("localhost"); - taskInstance.setTaskType("SWITCH"); + public void testStreamWholeLogChunkSuccessToEof() throws Exception { + TaskInstance ti = newTaskInstance(); + byte[] full = "0123456789ABCDEFGHIJ".getBytes(StandardCharsets.UTF_8); + + when(registryClient.checkNodeExists(eq(ti.getHost()), any())).thenReturn(true); + when(localLogClient.getLogChunk(eq(ti), anyLong(), anyInt())) + .thenReturn(chunk(full, 0, 10, false)) + .thenReturn(chunk(full, 10, 10, true)); - when(registryClient.checkNodeExists("localhost", RegistryNodeType.MASTER)).thenReturn(true); - when(localLogClient.getWholeLog(taskInstance)).thenReturn( - new TaskInstanceLogFileDownloadResponse("logBytes".getBytes(), LogResponseStatus.SUCCESS, null)); + ByteArrayOutputStream out = new ByteArrayOutputStream(); + logClientDelegate.streamWholeLog(ti, out); - byte[] result = logClientDelegate.getWholeLogBytes(taskInstance); - assertArrayEquals("logBytes".getBytes(), result); + assertArrayEquals(full, out.toByteArray()); } + /** + * First chunk fails with an ERROR code → fall back to remote log storage. The legacy + * whole-file worker RPC no longer exists as a fallback: it is unbounded on the worker side + * (see {@link LogClientDelegate#streamWholeLog}). + */ @Test - public void testGetWholeLogBytesNodeExistsLocalFailure() { - TaskInstance taskInstance = new TaskInstance(); - taskInstance.setId(1); - taskInstance.setHost("localhost"); - taskInstance.setTaskType("SWITCH"); + public void testStreamWholeLogFirstChunkFailsFallsBackToRemote() throws Exception { + TaskInstance ti = newTaskInstance(); + byte[] remoteData = "REMOTE_ARCHIVE".getBytes(StandardCharsets.UTF_8); + + when(registryClient.checkNodeExists(eq(ti.getHost()), any())).thenReturn(true); + when(localLogClient.getLogChunk(eq(ti), anyLong(), anyInt())) + .thenReturn(new TaskInstanceLogFileDownloadResponse(null, LogResponseStatus.ERROR, "down", true)); + mockRemoteStream(ti, remoteData); - when(registryClient.checkNodeExists("localhost", RegistryNodeType.MASTER)).thenReturn(true); - when(localLogClient.getWholeLog(taskInstance)).thenReturn( - new TaskInstanceLogFileDownloadResponse(null, LogResponseStatus.ERROR, "error")); - when(remoteLogClient.getWholeLog(taskInstance)).thenReturn("remoteLogBytes".getBytes()); + ByteArrayOutputStream out = new ByteArrayOutputStream(); + logClientDelegate.streamWholeLog(ti, out); - byte[] result = logClientDelegate.getWholeLogBytes(taskInstance); - assertArrayEquals("remoteLogBytes".getBytes(), result); + assertArrayEquals(remoteData, out.toByteArray()); + verify(remoteLogClient, times(1)).streamWholeLog(eq(ti), any(OutputStream.class)); } + /** + * Old worker simulation: it does not implement the chunk RPC, so the RPC layer fails with + * "Cannot find the ServerMethodInvoker" and the client proxy throws. Must go to remote log + * storage — never to the legacy whole-file RPC. + */ @Test - public void testGetWholeLogBytesNodeNotExists() { - TaskInstance taskInstance = new TaskInstance(); - taskInstance.setId(1); - taskInstance.setHost("localhost"); - taskInstance.setTaskType("SWITCH"); + public void testStreamWholeLogRpcThrowsFallsBackToRemote() throws Exception { + TaskInstance ti = newTaskInstance(); + byte[] remoteData = "REMOTE_ARCHIVE".getBytes(StandardCharsets.UTF_8); + + when(registryClient.checkNodeExists(eq(ti.getHost()), any())).thenReturn(true); + when(localLogClient.getLogChunk(eq(ti), anyLong(), anyInt())) + .thenThrow(new RuntimeException("Cannot find ServerMethodInvoker")); + mockRemoteStream(ti, remoteData); + + ByteArrayOutputStream out = new ByteArrayOutputStream(); + logClientDelegate.streamWholeLog(ti, out); + + assertArrayEquals(remoteData, out.toByteArray()); + verify(remoteLogClient, times(1)).streamWholeLog(eq(ti), any(OutputStream.class)); + } + + /** + * Chunk RPC unavailable because the worker ANSWERED but could not dispatch the method (an + * old worker during a rolling upgrade — the chunk method is missing, the server answers with + * a fail response and the client proxy throws {@link MethodInvocationException}) AND remote + * log storage cannot serve the log either → must fail with the explicit "worker upgrade + * required" error, not silently succeed, and not attempt any unbounded whole-file fetch. + */ + @Test + public void testStreamWholeLogRpcThrowsAndRemoteFailsThrowsUpgradeError() throws Exception { + TaskInstance ti = newTaskInstance(); + + when(registryClient.checkNodeExists(eq(ti.getHost()), any())).thenReturn(true); + when(localLogClient.getLogChunk(eq(ti), anyLong(), anyInt())) + .thenThrow(new MethodInvocationException( + "Cannot find the ServerMethodInvoker of getTaskInstanceLogFileChunk")); + doThrow(new IOException("Remote log file not found after download (remote log archiving may not be enabled " + + "or the archive is missing): /tmp/x.log")) + .when(remoteLogClient).streamWholeLog(eq(ti), any(OutputStream.class)); + + ByteArrayOutputStream out = new ByteArrayOutputStream(); + IOException thrown = assertThrows(IOException.class, () -> logClientDelegate.streamWholeLog(ti, out)); + assertTrue(thrown.getMessage().contains("upgrade required"), + "Old-worker failure must carry the explicit upgrade guidance, got: " + thrown.getMessage()); + assertTrue(thrown.getMessage().contains(ti.getHost())); + // The remote failure must stay visible in the cause chain for diagnosis. + assertTrue(thrown.getCause().getMessage().contains("Remote log file not found")); + assertEquals(0, out.toByteArray().length); + } + + /** + * The worker is DOWN (or unreachable): the RPC fails with a plain transport error — no fail + * response came back, so it is NOT an old-worker signal. The error must point operations at + * the worker's reachability, NOT at a worker upgrade. + */ + @Test + public void testStreamWholeLogWorkerUnreachableAndRemoteFailsThrowsWithoutUpgradeGuidance() throws Exception { + TaskInstance ti = newTaskInstance(); + + when(registryClient.checkNodeExists(eq(ti.getHost()), any())).thenReturn(true); + when(localLogClient.getLogChunk(eq(ti), anyLong(), anyInt())) + .thenThrow(new RuntimeException("connection refused: /10.0.0.5:1235")); + doThrow(new IOException("Remote log file not found after download (remote log archiving may not be enabled " + + "or the archive is missing): /tmp/x.log")) + .when(remoteLogClient).streamWholeLog(eq(ti), any(OutputStream.class)); + + ByteArrayOutputStream out = new ByteArrayOutputStream(); + IOException thrown = assertThrows(IOException.class, () -> logClientDelegate.streamWholeLog(ti, out)); + assertTrue(thrown.getMessage().contains("may be down or unreachable"), + "Unreachable worker must be reported as a reachability problem, got: " + thrown.getMessage()); + assertFalse(thrown.getMessage().contains("upgrade required"), + "Upgrade guidance must NOT appear for a worker that never answered the RPC"); + assertTrue(thrown.getCause().getMessage().contains("Remote log file not found")); + assertEquals(0, out.toByteArray().length); + } + + /** + * The worker ANSWERED with a structured non-SUCCESS code (a new worker that supports the + * chunk RPC — e.g. transient ERROR) and remote storage also failed → the error must report + * both failures as they are, WITHOUT the "worker upgrade required" guidance (the worker is + * not old; that message would mislead). + */ + @Test + public void testStreamWholeLogStructuredFailureAndRemoteFailsThrowsWithoutUpgradeGuidance() throws Exception { + TaskInstance ti = newTaskInstance(); + + when(registryClient.checkNodeExists(eq(ti.getHost()), any())).thenReturn(true); + when(localLogClient.getLogChunk(eq(ti), anyLong(), anyInt())) + .thenReturn(new TaskInstanceLogFileDownloadResponse(null, LogResponseStatus.ERROR, "down", true)); + doThrow(new IOException("Remote log file not found after download (remote log archiving may not be enabled " + + "or the archive is missing): /tmp/x.log")) + .when(remoteLogClient).streamWholeLog(eq(ti), any(OutputStream.class)); + + ByteArrayOutputStream out = new ByteArrayOutputStream(); + IOException thrown = assertThrows(IOException.class, () -> logClientDelegate.streamWholeLog(ti, out)); + assertTrue(thrown.getMessage().contains("Chunked log fetch failed"), + "Structured failure must be reported as-is, got: " + thrown.getMessage()); + assertTrue(thrown.getMessage().contains("ERROR")); + assertFalse(thrown.getMessage().contains("upgrade required"), + "Upgrade guidance must NOT appear for a worker that answered the chunk RPC"); + assertTrue(thrown.getCause().getMessage().contains("Remote log file not found")); + assertEquals(0, out.toByteArray().length); + } + + /** + * A SUCCESS chunk with ZERO bytes is the worker's authoritative "task produced no output" — + * a valid terminal state. Must return normally without touching remote storage. + */ + @Test + public void testStreamWholeLogEmptyLogIsTerminal() throws Exception { + TaskInstance ti = newTaskInstance(); + + when(registryClient.checkNodeExists(eq(ti.getHost()), any())).thenReturn(true); + when(localLogClient.getLogChunk(eq(ti), anyLong(), anyInt())) + .thenReturn(new TaskInstanceLogFileDownloadResponse(new byte[0], LogResponseStatus.SUCCESS, null, + true)); + + ByteArrayOutputStream out = new ByteArrayOutputStream(); + logClientDelegate.streamWholeLog(ti, out); + + assertEquals(0, out.toByteArray().length); + verify(remoteLogClient, never()).streamWholeLog(any(), any(OutputStream.class)); + } - when(registryClient.checkNodeExists("localhost", RegistryNodeType.MASTER)).thenReturn(false); - when(remoteLogClient.getWholeLog(taskInstance)).thenReturn("remoteLogBytes".getBytes()); + @Test + public void testStreamWholeLogNodeGoneFallsBackToRemote() throws Exception { + TaskInstance ti = newTaskInstance(); + byte[] remoteData = "REMOTE".getBytes(StandardCharsets.UTF_8); + + when(registryClient.checkNodeExists(eq(ti.getHost()), any())).thenReturn(false); + mockRemoteStream(ti, remoteData); + + ByteArrayOutputStream out = new ByteArrayOutputStream(); + logClientDelegate.streamWholeLog(ti, out); + + assertArrayEquals(remoteData, out.toByteArray()); + verify(localLogClient, never()).getLogChunk(any(), anyLong(), anyInt()); + verify(remoteLogClient, times(1)).streamWholeLog(eq(ti), any(OutputStream.class)); + } + + @Test + public void testStreamWholeLogMidStreamFailureThrows() throws Exception { + TaskInstance ti = newTaskInstance(); + byte[] full = "0123456789ABCDEFGHIJ".getBytes(StandardCharsets.UTF_8); + + when(registryClient.checkNodeExists(eq(ti.getHost()), any())).thenReturn(true); + when(localLogClient.getLogChunk(eq(ti), anyLong(), anyInt())) + .thenReturn(chunk(full, 0, 10, false)) + .thenReturn(new TaskInstanceLogFileDownloadResponse(null, LogResponseStatus.ERROR, "down", true)); + + ByteArrayOutputStream out = new ByteArrayOutputStream(); + assertThrows(IOException.class, () -> logClientDelegate.streamWholeLog(ti, out)); + assertEquals(10, out.toByteArray().length); + verify(remoteLogClient, never()).streamWholeLog(any(), any(OutputStream.class)); + } + + private static TaskInstanceLogFileDownloadResponse chunk(byte[] full, int off, int len, boolean eof) { + byte[] b = new byte[len]; + System.arraycopy(full, off, b, 0, len); + return new TaskInstanceLogFileDownloadResponse(b, LogResponseStatus.SUCCESS, null, eof); + } + + /** + * chunk RPC explicitly reporting LOG_FILE_NOT_FOUND means a NEW worker authoritatively says + * the file is gone (an old worker cannot report this — it fails the RPC instead). The remote + * archive may still hold the content, so go straight to remote storage. + */ + @Test + public void testStreamWholeLogChunkNotFoundGoesStraightToRemote() throws Exception { + TaskInstance ti = newTaskInstance(); + byte[] remoteData = "REMOTE_ARCHIVE".getBytes(StandardCharsets.UTF_8); + + when(registryClient.checkNodeExists(eq(ti.getHost()), any())).thenReturn(true); + when(localLogClient.getLogChunk(eq(ti), anyLong(), anyInt())) + .thenReturn(new TaskInstanceLogFileDownloadResponse(null, LogResponseStatus.LOG_FILE_NOT_FOUND, + "missing", true)); + mockRemoteStream(ti, remoteData); + + ByteArrayOutputStream out = new ByteArrayOutputStream(); + logClientDelegate.streamWholeLog(ti, out); + + assertArrayEquals(remoteData, out.toByteArray()); + verify(remoteLogClient, times(1)).streamWholeLog(eq(ti), any(OutputStream.class)); + } + + /** + * Worker node is gone AND remote log storage has nothing (archive missing) → must throw + * IOException so a missing log is not reported as a successful header-only download. + */ + @Test + public void testStreamWholeLogThrowsWhenRemoteLogMissing() throws Exception { + TaskInstance ti = newTaskInstance(); + + when(registryClient.checkNodeExists(eq(ti.getHost()), any())).thenReturn(false); + doThrow(new IOException("Log not available")).when(remoteLogClient).streamWholeLog(eq(ti), + any(OutputStream.class)); + + ByteArrayOutputStream out = new ByteArrayOutputStream(); + assertThrows(IOException.class, () -> logClientDelegate.streamWholeLog(ti, out)); + assertEquals(0, out.toByteArray().length); + verify(localLogClient, never()).getLogChunk(any(), anyLong(), anyInt()); + } + + /** + * RPC throws mid-stream (after bytes already written) → must throw, not fallback. + */ + @Test + public void testStreamWholeLogRpcThrowsMidStreamThrows() throws Exception { + TaskInstance ti = newTaskInstance(); + byte[] full = "0123456789ABCDEFGHIJ".getBytes(StandardCharsets.UTF_8); + + when(registryClient.checkNodeExists(eq(ti.getHost()), any())).thenReturn(true); + // First chunk succeeds, second RPC throws + when(localLogClient.getLogChunk(eq(ti), anyLong(), anyInt())) + .thenReturn(chunk(full, 0, 10, false)) + .thenThrow(new RuntimeException("Connection reset")); + + ByteArrayOutputStream out = new ByteArrayOutputStream(); + assertThrows(IOException.class, () -> logClientDelegate.streamWholeLog(ti, out)); + assertEquals(10, out.toByteArray().length); + verify(remoteLogClient, never()).streamWholeLog(any(), any(OutputStream.class)); + } + + /** + * Log rotation/truncation DURING the download (worker reports offset beyond the file's + * current size) must fail explicitly — silently returning what was written so far would + * hand the user a truncated file that looks complete. + */ + @Test + public void testStreamWholeLogLogRotatedMidStreamThrows() throws Exception { + TaskInstance ti = newTaskInstance(); + byte[] full = "0123456789ABCDEFGHIJ".getBytes(StandardCharsets.UTF_8); + + when(registryClient.checkNodeExists(eq(ti.getHost()), any())).thenReturn(true); + // First chunk succeeds, then the file is rotated underneath the reader. + when(localLogClient.getLogChunk(eq(ti), anyLong(), anyInt())) + .thenReturn(chunk(full, 0, 10, false)) + .thenReturn(new TaskInstanceLogFileDownloadResponse(null, LogResponseStatus.LOG_TRUNCATED, + "Log file was truncated/rotated: size 0 < requested offset 10", true)); + + ByteArrayOutputStream out = new ByteArrayOutputStream(); + assertThrows(IOException.class, () -> logClientDelegate.streamWholeLog(ti, out)); + assertEquals(10, out.toByteArray().length); + verify(remoteLogClient, never()).streamWholeLog(any(), any(OutputStream.class)); + } + + /** + * Regression: when the first chunk fails and we fall back to remote storage, the + * remote file must be streamed to the OutputStream in chunks rather than loaded + * into a single byte[]. + */ + @Test + public void testStreamWholeLogRemoteFallbackIsChunked() throws Exception { + TaskInstance ti = newTaskInstance(); + + when(registryClient.checkNodeExists(eq(ti.getHost()), any())).thenReturn(true); + when(localLogClient.getLogChunk(eq(ti), anyLong(), anyInt())) + .thenReturn(new TaskInstanceLogFileDownloadResponse(null, LogResponseStatus.ERROR, "down", true)); + + // Count how many times the mocked remote stream writes to the output stream. + // A byte[]-based implementation would write once; a chunked stream writes many times. + final int[] writeCallCount = {0}; + doAnswer(invocation -> { + OutputStream out = invocation.getArgument(1); + // Simulate a 3-chunk stream of a large log. + for (int i = 0; i < 3; i++) { + out.write(new byte[]{0x01, 0x02}); + writeCallCount[0]++; + } + return null; + }).when(remoteLogClient).streamWholeLog(eq(ti), any(OutputStream.class)); + + ByteArrayOutputStream out = new ByteArrayOutputStream(); + logClientDelegate.streamWholeLog(ti, out); + + assertEquals(3, writeCallCount[0]); + assertEquals(6, out.toByteArray().length); + } - byte[] result = logClientDelegate.getWholeLogBytes(taskInstance); - assertArrayEquals("remoteLogBytes".getBytes(), result); + private void mockRemoteStream(TaskInstance ti, byte[] data) throws IOException { + doAnswer(invocation -> { + OutputStream out = invocation.getArgument(1); + out.write(data); + return null; + }).when(remoteLogClient).streamWholeLog(eq(ti), any(OutputStream.class)); } } diff --git a/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/LogStreamingIntegrationTest.java b/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/LogStreamingIntegrationTest.java new file mode 100644 index 000000000000..64efd9788534 --- /dev/null +++ b/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/LogStreamingIntegrationTest.java @@ -0,0 +1,253 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.apache.dolphinscheduler.api.executor.logging; + +import static org.junit.jupiter.api.Assertions.assertArrayEquals; +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertNotNull; +import static org.junit.jupiter.api.Assertions.assertTrue; +import static org.mockito.ArgumentMatchers.any; +import static org.mockito.ArgumentMatchers.eq; +import static org.mockito.Mockito.atLeast; +import static org.mockito.Mockito.verify; +import static org.mockito.Mockito.when; + +import org.apache.dolphinscheduler.dao.entity.TaskInstance; +import org.apache.dolphinscheduler.extract.base.config.NettyServerConfig; +import org.apache.dolphinscheduler.extract.base.server.SpringServerMethodInvokerDiscovery; +import org.apache.dolphinscheduler.extract.common.service.impl.LogServiceImpl; +import org.apache.dolphinscheduler.registry.api.RegistryClient; +import org.apache.dolphinscheduler.registry.api.enums.RegistryNodeType; + +import java.io.ByteArrayOutputStream; +import java.io.IOException; +import java.io.OutputStream; +import java.net.ServerSocket; +import java.nio.charset.StandardCharsets; +import java.nio.file.Files; +import java.nio.file.Path; +import java.nio.file.StandardCopyOption; +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +import java.util.concurrent.Future; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicBoolean; +import java.util.concurrent.atomic.AtomicLong; + +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.ExtendWith; +import org.mockito.InjectMocks; +import org.mockito.Mock; +import org.mockito.Spy; +import org.mockito.junit.jupiter.MockitoExtension; +import org.mockito.junit.jupiter.MockitoSettings; +import org.mockito.quality.Strictness; + +/** + * Integration test for chunked log streaming. + * + *

Starts an embedded Netty RPC server running the real {@code LogServiceImpl}, writes a log + * file larger than the 8 MB chunk size, and verifies that {@code LogClientDelegate} streams the + * whole file back in multiple chunks, reassembling it byte-for-byte. This exercises the real RPC + * serialization of offset/length/eof and the real chunked file read end-to-end — something the + * unit tests (which mock the RPC) cannot cover. + */ +@ExtendWith(MockitoExtension.class) +@MockitoSettings(strictness = Strictness.LENIENT) +class LogStreamingIntegrationTest { + + /** + * Slightly larger than {@code LogServiceImpl.MAX_CHUNK_SIZE} (8 MB) so the file is guaranteed + * to be split into at least two chunks. + */ + private static final int FILE_SIZE = 9 * 1024 * 1024; + + @Spy + private LocalLogClient localLogClient; + + @Mock + private RegistryClient registryClient; + + @Mock + private RemoteLogClient remoteLogClient; + + @InjectMocks + private LogClientDelegate logClientDelegate; + + private SpringServerMethodInvokerDiscovery springServerMethodInvokerDiscovery; + + private int nettyServerPort = 18080; + + private java.io.File tempLogFile; + + @BeforeEach + void setUp() throws IOException { + try (ServerSocket s = new ServerSocket(0)) { + nettyServerPort = s.getLocalPort(); + } + + springServerMethodInvokerDiscovery = new SpringServerMethodInvokerDiscovery( + NettyServerConfig.builder().serverName("TestChunkedLogServer").listenPort(nettyServerPort).build()); + springServerMethodInvokerDiscovery.registerServerMethodInvokerProvider(new LogServiceImpl()); + springServerMethodInvokerDiscovery.start(); + + tempLogFile = Files.createTempFile("ds-chunked-log", ".log").toFile(); + byte[] content = new byte[FILE_SIZE]; + for (int i = 0; i < FILE_SIZE; i++) { + content[i] = (byte) (i % 256); + } + Files.write(tempLogFile.toPath(), content); + } + + @AfterEach + void tearDown() { + if (springServerMethodInvokerDiscovery != null) { + springServerMethodInvokerDiscovery.close(); + } + if (tempLogFile != null) { + tempLogFile.delete(); + } + } + + @Test + void streamWholeLog_shouldDownloadLargeLogInMultipleChunks() throws Exception { + TaskInstance taskInstance = new TaskInstance(); + taskInstance.setId(1); + taskInstance.setHost("127.0.0.1:" + nettyServerPort); + taskInstance.setLogPath(tempLogFile.getAbsolutePath()); + taskInstance.setTaskType("SHELL"); + + when(registryClient.checkNodeExists(eq(taskInstance.getHost()), any(RegistryNodeType.class))).thenReturn(true); + + ByteArrayOutputStream outputStream = new ByteArrayOutputStream(); + logClientDelegate.streamWholeLog(taskInstance, outputStream); + + byte[] expected = Files.readAllBytes(tempLogFile.toPath()); + assertArrayEquals(expected, outputStream.toByteArray()); + + // The file is 9 MB and the chunk size is 8 MB, so at least two chunk RPCs should have been + // issued against the real embedded worker. + verify(localLogClient, atLeast(2)).getLogChunk(eq(taskInstance), any(Long.class), any(Integer.class)); + } + + /** + * End-to-end regression for log ROTATION during a download: the worker-side file shrinks + * underneath an in-flight stream (logback fixed-window roll renames the active file and a + * fresh one starts from 0). The download must FAIL EXPLICITLY — silently returning the + * bytes written so far would hand the user a truncated file that looks complete. + * + *

Deterministic timing via a gate in the OutputStream: the streaming thread blocks inside + * the first 8 MB write until the test thread has performed the rotation, so the second chunk + * request is guaranteed to observe the shrunk file. No sleeps, no race. + */ + @Test + void streamWholeLog_logRotatedMidDownload_failsExplicitly() throws Exception { + final Path logFile = tempLogFile.toPath(); + final Path rotatedFile = tempLogFile.toPath().resolveSibling(tempLogFile.getName() + ".1"); + + final CountDownLatch firstChunkArrived = new CountDownLatch(1); + final CountDownLatch rotationDone = new CountDownLatch(1); + final AtomicLong written = new AtomicLong(); + + final OutputStream gatedOutput = new OutputStream() { + + private final AtomicBoolean firstWrite = new AtomicBoolean(true); + + @Override + public void write(final int b) { + written.incrementAndGet(); + } + + @Override + public void write(final byte[] b, final int off, final int len) throws IOException { + written.addAndGet(len); + if (firstWrite.compareAndSet(true, false)) { + // First chunk (8 MB) has arrived — hold the stream while the log rotates. + firstChunkArrived.countDown(); + try { + if (!rotationDone.await(15, TimeUnit.SECONDS)) { + throw new IOException("Test gate timed out waiting for rotation"); + } + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + throw new IOException("Test gate interrupted", e); + } + } + } + }; + + TaskInstance taskInstance = new TaskInstance(); + taskInstance.setId(2); + taskInstance.setHost("127.0.0.1:" + nettyServerPort); + taskInstance.setLogPath(tempLogFile.getAbsolutePath()); + taskInstance.setTaskType("SHELL"); + when(registryClient.checkNodeExists(eq(taskInstance.getHost()), any(RegistryNodeType.class))).thenReturn(true); + + final ExecutorService pool = Executors.newSingleThreadExecutor(); + final Future download; + try { + download = pool.submit(() -> { + try { + logClientDelegate.streamWholeLog(taskInstance, gatedOutput); + return null; + } catch (Throwable t) { + return t; + } + }); + + // Wait until the first 8 MB chunk was written, then rotate like logback would: + // rename the active file away, start a fresh (much smaller) one at the same path. + assertTrue(firstChunkArrived.await(15, TimeUnit.SECONDS), + "First chunk never arrived — streaming did not start"); + Files.move(logFile, rotatedFile, StandardCopyOption.REPLACE_EXISTING); + Files.write(logFile, "fresh file after rotation".getBytes(StandardCharsets.UTF_8)); + rotationDone.countDown(); + } finally { + pool.shutdown(); + } + + final Throwable thrown = download.get(30, TimeUnit.SECONDS); + assertNotNull(thrown, "Download must fail after rotation — not return a truncated file"); + assertTrue(thrown instanceof IOException, "Expected IOException but got: " + thrown); + assertTrue(causeChainContains(thrown, "truncated"), + "Error chain must identify truncation (LOG_TRUNCATED propagated from the worker), got: " + + thrown); + // Exactly the first 8 MB chunk was delivered before the failure. + assertEquals(8 * 1024 * 1024, written.get()); + + Files.deleteIfExists(rotatedFile); + } + + private static boolean causeChainContains(final Throwable throwable, final String needle) { + Throwable current = throwable; + while (current != null) { + if (current.getMessage() != null && current.getMessage().contains(needle)) { + return true; + } + final Throwable cause = current.getCause(); + if (cause == current) { + break; + } + current = cause; + } + return false; + } +} diff --git a/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/RemoteLogClientTest.java b/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/RemoteLogClientTest.java new file mode 100644 index 000000000000..1cf5f555cbe2 --- /dev/null +++ b/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/RemoteLogClientTest.java @@ -0,0 +1,261 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.apache.dolphinscheduler.api.executor.logging; + +import static org.junit.jupiter.api.Assertions.assertArrayEquals; +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertNull; +import static org.junit.jupiter.api.Assertions.assertThrows; +import static org.junit.jupiter.api.Assertions.assertTrue; + +import org.apache.dolphinscheduler.dao.entity.TaskInstance; + +import java.io.ByteArrayInputStream; +import java.io.ByteArrayOutputStream; +import java.io.IOException; +import java.io.OutputStream; +import java.nio.charset.StandardCharsets; +import java.nio.file.Files; +import java.nio.file.Path; +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +import java.util.concurrent.Future; +import java.util.concurrent.TimeUnit; +import java.util.stream.Stream; + +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.io.TempDir; + +public class RemoteLogClientTest { + + /** + * Remote logging is disabled in tests, so RemoteLogUtils.getRemoteLog is a no-op and the + * local file placed by the test is streamed as-is. + */ + @Test + public void streamWholeLog_streamsLocalArchiveFile(@TempDir Path tempDir) throws Exception { + Path logFile = tempDir.resolve("task.log"); + byte[] content = "0123456789ABCDEFG".getBytes(StandardCharsets.UTF_8); + Files.write(logFile, content); + + RemoteLogClient client = new RemoteLogClient(); + ByteArrayOutputStream out = new ByteArrayOutputStream(); + client.streamWholeLog(taskInstance(logFile.toString()), out); + + assertArrayEquals(content, out.toByteArray()); + } + + @Test + public void streamWholeLog_missingFileThrows(@TempDir Path tempDir) { + RemoteLogClient client = new RemoteLogClient(); + ByteArrayOutputStream out = new ByteArrayOutputStream(); + + IOException thrown = assertThrows(IOException.class, + () -> client.streamWholeLog(taskInstance(tempDir.resolve("absent.log").toString()), out)); + assertTrue(thrown.getMessage().contains("not found")); + } + + /** + * An archived log that EXISTS but is 0 bytes is a legal empty log ("task produced no + * output") — the same terminal state as an empty log on a live worker. It must stream + * normally (zero bytes written; the caller appends the head), NOT be treated as + * "log unavailable". Only a file that is MISSING after the download is an error. + */ + @Test + public void streamWholeLog_emptyArchiveIsLegalEmptyLog(@TempDir Path tempDir) throws Exception { + Path logFile = tempDir.resolve("empty.log"); + Files.write(logFile, new byte[0]); + + RemoteLogClient client = new RemoteLogClient(); + ByteArrayOutputStream out = new ByteArrayOutputStream(); + + client.streamWholeLog(taskInstance(logFile.toString()), out); + + assertEquals(0, out.toByteArray().length); + } + + /** + * The streaming read is bounded by the file size captured at open time: if a concurrent + * re-download truncates the file mid-transfer, the reader hits EOF early and MUST fail + * explicitly — silently returning a short download that looks complete is data corruption. + */ + @Test + public void streamBounded_shortReadThrowsInsteadOfSilentTruncation() { + final RemoteLogClient client = new RemoteLogClient(); + final byte[] onlyHalfThere = new byte[50]; + final ByteArrayOutputStream out = new ByteArrayOutputStream(); + + // File was 100 bytes when opened; a concurrent truncate left only 50 readable. + IOException thrown = assertThrows(IOException.class, + () -> client.streamBounded(new ByteArrayInputStream(onlyHalfThere), 100, out)); + assertTrue(thrown.getMessage().contains("short read")); + // whatever was read before the failure was already written — that is fine, the point + // is that the failure is EXPLICIT, the client sees a broken transfer not a clean 200. + } + + /** + * Regression: the archive cache is REWRITTEN IN PLACE by a concurrent download or log view + * (a re-download truncates the file) while an active transfer is streaming. The active + * transfer must still deliver the ORIGINAL bytes from its private snapshot — it must not + * fail with a premature EOF, and must not return a truncated download. Deterministic: the + * active download gates after its first written byte until the cache rewrite is done. + */ + @Test + public void streamWholeLog_concurrentCacheRewriteDuringTransfer_activeDownloadUnaffected( + @TempDir Path tempDir) throws Exception { + final Path logFile = tempDir.resolve("task.log"); + final byte[] original = patternedBytes(512 * 1024, 251); + Files.write(logFile, original); + + final CountDownLatch firstByteWritten = new CountDownLatch(1); + final CountDownLatch cacheRewritten = new CountDownLatch(1); + final ByteArrayOutputStream out = new ByteArrayOutputStream() { + + @Override + public void write(final byte[] b, final int off, final int len) { + super.write(b, off, len); + firstByteWritten.countDown(); + try { + if (!cacheRewritten.await(15, TimeUnit.SECONDS)) { + throw new RuntimeException("Test gate timed out waiting for the cache rewrite"); + } + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + throw new RuntimeException("Test gate interrupted", e); + } + } + }; + + final RemoteLogClient client = new RemoteLogClient(); + final ExecutorService pool = Executors.newSingleThreadExecutor(); + try { + final Future transfer = pool.submit(() -> { + try { + client.streamWholeLog(taskInstance(logFile.toString()), out); + return null; + } catch (Throwable t) { + return t; + } + }); + + // Wait until the active transfer has its snapshot and started streaming, then + // rewrite the cache exactly like a concurrent re-download would (truncate + write). + assertTrue(firstByteWritten.await(15, TimeUnit.SECONDS), + "Active transfer never started — streaming did not begin"); + Files.write(logFile, "rewritten-by-a-concurrent-download".getBytes(StandardCharsets.UTF_8)); + cacheRewritten.countDown(); + + final Throwable thrown = transfer.get(30, TimeUnit.SECONDS); + assertNull(thrown, "Active download must survive the concurrent cache rewrite"); + assertArrayEquals(original, out.toByteArray(), "Active download must deliver the original bytes"); + // The private snapshot must be cleaned up after the transfer. + assertOnlyArchiveRemains(tempDir); + } finally { + pool.shutdownNow(); + } + } + + /** + * The snapshot must be deleted even when the TRANSFER fails (client disconnects mid-download + * → the output stream throws): a "delete only on success" regression would slowly fill the + * log dir with one orphaned file per aborted download. The transfer throws on the FIRST + * write, so a small archive is enough — the content is never asserted. + */ + @Test + public void streamWholeLog_transferFailsMidStream_snapshotStillDeleted(@TempDir Path tempDir) throws Exception { + final Path logFile = tempDir.resolve("task.log"); + Files.write(logFile, new byte[64 * 1024]); + + final OutputStream clientDisconnected = new OutputStream() { + + @Override + public void write(final int b) throws IOException { + throw new IOException("client went away"); + } + + @Override + public void write(final byte[] b, final int off, final int len) throws IOException { + throw new IOException("client went away"); + } + }; + + final RemoteLogClient client = new RemoteLogClient(); + assertThrows(IOException.class, + () -> client.streamWholeLog(taskInstance(logFile.toString()), clientDisconnected)); + + // Exactly the archive remains — the failed transfer's snapshot was still cleaned up. + assertOnlyArchiveRemains(tempDir); + } + + /** + * The startup sweep deletes snapshot files orphaned by a previous JVM life, keeps snapshots + * younger than the age gate (another live instance's in-flight transfer on a shared disk) + * and keeps ordinary log files. + */ + @Test + public void deleteOrphanedSnapshots_removesOnlyAgedSnapshots(@TempDir Path tempDir) throws Exception { + final Path oldOrphan = tempDir.resolve("task.log.download-1111"); + Files.write(oldOrphan, new byte[]{1}); + final Path freshSnapshot = tempDir.resolve("task.log.download-2222"); + Files.write(freshSnapshot, new byte[]{2}); + final Path ordinaryLog = tempDir.resolve("task.log"); + Files.write(ordinaryLog, new byte[]{3}); + // Age the first file past the orphan threshold. + oldOrphan.toFile().setLastModified(System.currentTimeMillis() - 2 * 60 * 60 * 1000L); + + final RemoteLogClient client = new RemoteLogClient(); + client.deleteOrphanedSnapshots(tempDir); + + assertTrue(Files.notExists(oldOrphan), "Aged orphan must be swept"); + assertTrue(Files.exists(freshSnapshot), "Snapshot within the age gate must be kept"); + assertTrue(Files.exists(ordinaryLog), "Ordinary log files must never be swept"); + } + + private static TaskInstance taskInstance(final String logPath) { + final TaskInstance taskInstance = new TaskInstance(); + taskInstance.setId(1); + taskInstance.setHost("localhost"); + taskInstance.setLogPath(logPath); + return taskInstance; + } + + /** + * A patterned (non-constant) buffer of {@code size} bytes — makes it possible to detect + * content corruption instead of just length changes. + */ + private static byte[] patternedBytes(final int size, final int modulus) { + final byte[] bytes = new byte[size]; + for (int i = 0; i < size; i++) { + bytes[i] = (byte) (i % modulus); + } + return bytes; + } + + /** + * After a completed (or failed) transfer of the archive {@code tempDir/task.log}, exactly + * that archive must remain: the private download snapshot must be gone. Asserting the file + * COUNT (not a name filter) keeps this honest if the snapshot naming convention ever + * changes. + */ + private static void assertOnlyArchiveRemains(final Path tempDir) throws IOException { + try (Stream leftovers = Files.list(tempDir)) { + assertEquals(1, leftovers.count(), "Only the archive must remain — the snapshot must be deleted"); + } + } +} diff --git a/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/RollingUpgradeLogStreamingIntegrationTest.java b/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/RollingUpgradeLogStreamingIntegrationTest.java new file mode 100644 index 000000000000..2638cdfaf11c --- /dev/null +++ b/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/RollingUpgradeLogStreamingIntegrationTest.java @@ -0,0 +1,222 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.apache.dolphinscheduler.api.executor.logging; + +import static org.junit.jupiter.api.Assertions.assertArrayEquals; +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertThrows; +import static org.junit.jupiter.api.Assertions.assertTrue; +import static org.mockito.ArgumentMatchers.any; +import static org.mockito.ArgumentMatchers.eq; +import static org.mockito.Mockito.doAnswer; +import static org.mockito.Mockito.doThrow; +import static org.mockito.Mockito.times; +import static org.mockito.Mockito.verify; +import static org.mockito.Mockito.when; + +import org.apache.dolphinscheduler.dao.entity.TaskInstance; +import org.apache.dolphinscheduler.extract.base.config.NettyServerConfig; +import org.apache.dolphinscheduler.extract.base.server.SpringServerMethodInvokerDiscovery; +import org.apache.dolphinscheduler.extract.common.ILogService; +import org.apache.dolphinscheduler.extract.common.transportor.LogResponseStatus; +import org.apache.dolphinscheduler.extract.common.transportor.TaskInstanceLogFileDownloadResponse; +import org.apache.dolphinscheduler.registry.api.RegistryClient; +import org.apache.dolphinscheduler.registry.api.enums.RegistryNodeType; + +import java.io.ByteArrayOutputStream; +import java.io.IOException; +import java.io.OutputStream; +import java.lang.reflect.Proxy; +import java.net.ServerSocket; +import java.nio.charset.StandardCharsets; +import java.nio.file.Files; +import java.util.concurrent.atomic.AtomicInteger; + +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.ExtendWith; +import org.mockito.InjectMocks; +import org.mockito.Mock; +import org.mockito.Spy; +import org.mockito.junit.jupiter.MockitoExtension; +import org.mockito.junit.jupiter.MockitoSettings; +import org.mockito.quality.Strictness; + +/** + * Rolling-upgrade regression test for chunked log streaming. + * + *

Simulates an OLD worker (deployed before this feature) behind a real Netty RPC server and a + * real RPC client. The old worker would happily answer the legacy whole-file RPC (it counts and + * would return the full payload), but it does not implement the chunked log download RPC — from + * the client's perspective this is indistinguishable from the real deployed old worker, whose + * server replies "Cannot find the ServerMethodInvoker" for the chunk method. + * + *

The regression under test (issue #18459 review): a large log must NEVER be requested from the + * old worker via the whole-file payload — that RPC reads the entire file into the worker's heap + * before serialization and can OOM it, and a receiver-side maxFrameSize cannot prevent it. The + * download must instead come from remote log storage, or fail with an explicit error. + */ +@ExtendWith(MockitoExtension.class) +@MockitoSettings(strictness = Strictness.LENIENT) +class RollingUpgradeLogStreamingIntegrationTest { + + /** + * Larger than the 8 MB chunk size: exercises the "large log" path the reviewer is concerned + * about. + */ + private static final int FILE_SIZE = 9 * 1024 * 1024; + + @Spy + private LocalLogClient localLogClient; + + @Mock + private RegistryClient registryClient; + + @Mock + private RemoteLogClient remoteLogClient; + + @InjectMocks + private LogClientDelegate logClientDelegate; + + private SpringServerMethodInvokerDiscovery springServerMethodInvokerDiscovery; + + private int nettyServerPort = 18080; + + private java.io.File tempLogFile; + + /** + * Counts invocations of the legacy whole-file RPC on the simulated old worker. The whole-file + * method actually WORKS on the stub (like on a real old worker) — so the assertion + * {@code == 0} is not vacuous: a regressed delegate would get a successful response here and + * the counter would prove it. + */ + private final AtomicInteger wholeFileRpcInvocations = new AtomicInteger(); + + @BeforeEach + void setUp() throws IOException { + try (ServerSocket s = new ServerSocket(0)) { + nettyServerPort = s.getLocalPort(); + } + + tempLogFile = Files.createTempFile("ds-old-worker-log", ".log").toFile(); + byte[] content = new byte[FILE_SIZE]; + for (int i = 0; i < FILE_SIZE; i++) { + content[i] = (byte) (i % 256); + } + Files.write(tempLogFile.toPath(), content); + + // A JDK proxy implementing the CURRENT ILogService keeps the real method identifiers + // (method.toGenericString()) on the wire, so the RPC dispatch behaves exactly like the + // real thing: the chunk call reaches the server and fails, and a whole-file call would + // succeed. + final ILogService oldWorker = (ILogService) Proxy.newProxyInstance( + ILogService.class.getClassLoader(), + new Class[]{ILogService.class}, + (proxy, method, args) -> { + switch (method.getName()) { + case "getTaskInstanceLogFileChunk": + // Old worker does not implement the chunked log download RPC. A real + // old worker fails with "Cannot find the ServerMethodInvoker"; throwing + // here is wire-equivalent from the client's perspective (both come back + // as a failed RPC → MethodInvocationException). + throw new UnsupportedOperationException( + "simulated old worker: chunked log RPC not implemented"); + case "getTaskInstanceWholeLogFileBytes": + wholeFileRpcInvocations.incrementAndGet(); + return new TaskInstanceLogFileDownloadResponse( + Files.readAllBytes(tempLogFile.toPath()), LogResponseStatus.SUCCESS, "", true); + default: + return null; + } + }); + springServerMethodInvokerDiscovery = new SpringServerMethodInvokerDiscovery( + NettyServerConfig.builder().serverName("TestOldWorkerLogServer").listenPort(nettyServerPort).build()); + springServerMethodInvokerDiscovery.registerServerMethodInvokerProvider(oldWorker); + springServerMethodInvokerDiscovery.start(); + } + + @AfterEach + void tearDown() { + if (springServerMethodInvokerDiscovery != null) { + springServerMethodInvokerDiscovery.close(); + } + if (tempLogFile != null) { + tempLogFile.delete(); + } + } + + private TaskInstance newTaskInstance() { + TaskInstance taskInstance = new TaskInstance(); + taskInstance.setId(1); + taskInstance.setHost("127.0.0.1:" + nettyServerPort); + taskInstance.setLogPath(tempLogFile.getAbsolutePath()); + taskInstance.setTaskType("SHELL"); + return taskInstance; + } + + /** + * Rolling upgrade, old worker, remote log storage AVAILABLE: the large log is streamed from + * remote storage and the old worker is NEVER asked for the whole-file payload. + */ + @Test + void oldWorkerLargeLogStreamedFromRemoteStorageNeverWholeFileRpc() throws Exception { + final TaskInstance taskInstance = newTaskInstance(); + when(registryClient.checkNodeExists(eq(taskInstance.getHost()), any(RegistryNodeType.class))) + .thenReturn(true); + final byte[] remoteData = "REMOTE_ARCHIVE".getBytes(StandardCharsets.UTF_8); + doAnswer(invocation -> { + OutputStream out = invocation.getArgument(1); + out.write(remoteData); + return null; + }).when(remoteLogClient).streamWholeLog(eq(taskInstance), any(OutputStream.class)); + + final ByteArrayOutputStream out = new ByteArrayOutputStream(); + logClientDelegate.streamWholeLog(taskInstance, out); + + assertArrayEquals(remoteData, out.toByteArray()); + verify(remoteLogClient, times(1)).streamWholeLog(eq(taskInstance), any(OutputStream.class)); + assertEquals(0, wholeFileRpcInvocations.get(), + "the old worker must NEVER be asked for the whole-file payload on the large-log path"); + } + + /** + * Rolling upgrade, old worker, remote log storage UNAVAILABLE (not enabled / archive missing, + * the default deployment): the download fails with the explicit "worker upgrade required" + * error — and still never asks the old worker for the whole-file payload. + */ + @Test + void oldWorkerLargeLogWithoutRemoteArchiveFailsWithExplicitUpgradeError() throws Exception { + final TaskInstance taskInstance = newTaskInstance(); + when(registryClient.checkNodeExists(eq(taskInstance.getHost()), any(RegistryNodeType.class))) + .thenReturn(true); + doThrow(new IOException("Remote log file not found after download (remote log archiving may not be enabled " + + "or the archive is missing): " + taskInstance.getLogPath())) + .when(remoteLogClient).streamWholeLog(eq(taskInstance), any(OutputStream.class)); + + final ByteArrayOutputStream out = new ByteArrayOutputStream(); + final IOException thrown = assertThrows(IOException.class, + () -> logClientDelegate.streamWholeLog(taskInstance, out)); + + assertTrue(thrown.getMessage().contains("upgrade required"), + "Error must contain the explicit upgrade guidance, got: " + thrown.getMessage()); + assertEquals(0, out.toByteArray().length); + assertEquals(0, wholeFileRpcInvocations.get(), + "the old worker must NEVER be asked for the whole-file payload on the large-log path"); + } +} diff --git a/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/service/LoggerServiceTest.java b/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/service/LoggerServiceTest.java index e932bd1b6e8d..52a50c9d9e08 100644 --- a/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/service/LoggerServiceTest.java +++ b/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/service/LoggerServiceTest.java @@ -24,6 +24,7 @@ import static org.junit.jupiter.api.Assertions.assertEquals; import static org.mockito.ArgumentMatchers.any; import static org.mockito.ArgumentMatchers.anyInt; +import static org.mockito.Mockito.doAnswer; import static org.mockito.Mockito.doNothing; import static org.mockito.Mockito.doThrow; import static org.mockito.Mockito.when; @@ -44,9 +45,8 @@ import org.apache.dolphinscheduler.dao.repository.TaskDefinitionDao; import org.apache.dolphinscheduler.dao.repository.TaskInstanceDao; -import java.text.MessageFormat; -import java.util.HashMap; -import java.util.Map; +import java.io.ByteArrayOutputStream; +import java.io.IOException; import org.junit.jupiter.api.Assertions; import org.junit.jupiter.api.Test; @@ -135,57 +135,6 @@ public void testQueryLog() { () -> loggerService.queryLog(loginUser, 1, 1, 1)); } - @Test - public void testGetLogBytes() { - - User loginUser = new User(); - loginUser.setId(1); - TaskInstance taskInstance = new TaskInstance(); - taskInstance.setId(1); - taskInstance.setExecutorId(loginUser.getId() + 1); - when(taskInstanceDao.queryById(1)).thenReturn(taskInstance); - - // task instance is null - try { - loggerService.getLogBytes(loginUser, 2); - } catch (ServiceException e) { - Assertions.assertEquals(new ServiceException("task instance is null or host is null").getMessage(), - e.getMessage()); - logger.error("testGetLogBytes error: {}", "task instance is null"); - } - - // task instance host is null - try { - loggerService.getLogBytes(loginUser, 1); - } catch (ServiceException e) { - Assertions.assertEquals(new ServiceException("task instance is null or host is null").getMessage(), - e.getMessage()); - logger.error("testGetLogBytes error: {}", "task instance host is null"); - } - - // PROJECT_NOT_EXIST - taskInstance.setHost("127.0.0.1:" + nettyServerPort); - taskInstance.setLogPath("/temp/log"); - doThrow(new ServiceException(Status.PROJECT_NOT_EXIST)).when(projectService) - .checkProjectAndAuthThrowException(loginUser, taskInstance.getProjectCode(), VIEW_LOG); - AssertionsHelper.assertThrowsServiceException(Status.PROJECT_NOT_EXIST, - () -> loggerService.queryLog(loginUser, 1, 1, 1)); - - // USER_NO_OPERATION_PERM - doThrow(new ServiceException(Status.USER_NO_OPERATION_PERM)).when(projectService) - .checkProjectAndAuthThrowException(loginUser, taskInstance.getProjectCode(), VIEW_LOG); - AssertionsHelper.assertThrowsServiceException(Status.USER_NO_OPERATION_PERM, - () -> loggerService.queryLog(loginUser, 1, 1, 1)); - - // SUCCESS - when(logClientDelegate.getWholeLogBytes(any())).thenReturn(new byte[0]); - doNothing().when(projectService).checkProjectAndAuthThrowException(loginUser, taskInstance.getProjectCode(), - DOWNLOAD_LOG); - when(logClientDelegate.getWholeLogBytes(any())).thenReturn(new byte[0]); - byte[] logBytes = loggerService.getLogBytes(loginUser, 1); - Assertions.assertEquals(42, logBytes.length - String.valueOf(nettyServerPort).length()); - } - @Test public void testQueryLogInSpecifiedProject() { long projectCode = 1L; @@ -236,45 +185,101 @@ public void testQueryLogInSpecifiedProject() { } @Test - public void testGetLogBytesInSpecifiedProject() { - long projectCode = 1L; - when(projectDao.queryByCode(projectCode)).thenReturn(getProject(projectCode)); + public void testCheckDownloadLogAuth_taskInstanceNotFound() { + when(taskInstanceDao.queryById(1)).thenReturn(null); - User loginUser = new User(); - loginUser.setId(-1); - loginUser.setUserType(UserType.GENERAL_USER); - Map result = new HashMap<>(); - putMsg(result, Status.SUCCESS, projectCode); + assertThrowsServiceException( + Status.INTERNAL_SERVER_ERROR_ARGS, () -> loggerService.checkDownloadLogAuth(newLoginUser(), 1)); + } + + @Test + public void testCheckDownloadLogAuth_hostIsNull() { + when(taskInstanceDao.queryById(1)).thenReturn(newTaskInstanceForAuth(1, null)); + + assertThrowsServiceException( + Status.INTERNAL_SERVER_ERROR_ARGS, () -> loggerService.checkDownloadLogAuth(newLoginUser(), 1)); + } + + @Test + public void testCheckDownloadLogAuth_logPathIsEmpty() { TaskInstance taskInstance = new TaskInstance(); - TaskDefinition taskDefinition = new TaskDefinition(); - taskDefinition.setProjectCode(projectCode); - taskDefinition.setCode(1L); - // SUCCESS - taskInstance.setTaskCode(1L); taskInstance.setId(1); - taskInstance.setHost("127.0.0.1:" + nettyServerPort); - taskInstance.setLogPath("/temp/log"); - doNothing().when(projectService).checkProjectAndAuthThrowException(loginUser, projectCode, DOWNLOAD_LOG); + taskInstance.setHost("127.0.0.1:18080"); + // logPath intentionally left blank — task dispatched but log path not persisted yet + when(taskInstanceDao.queryById(1)).thenReturn(taskInstance); - when(taskInstanceDao.queryById(1)).thenReturn(null); assertThrowsServiceException( - Status.INTERNAL_SERVER_ERROR_ARGS, () -> loggerService.getLogBytes(loginUser, projectCode, 1)); + Status.INTERNAL_SERVER_ERROR_ARGS, () -> loggerService.checkDownloadLogAuth(newLoginUser(), 1)); + } + @Test + public void testCheckDownloadLogAuth_noPermission() { + User loginUser = newLoginUser(); + TaskInstance taskInstance = newTaskInstanceForAuth(1, "127.0.0.1:18080"); + Project project = getProject(1L); when(taskInstanceDao.queryById(1)).thenReturn(taskInstance); - when(taskDefinitionDao.queryByCode(taskInstance.getTaskCode())).thenReturn(taskDefinition); - when(logClientDelegate.getWholeLogBytes(any())).thenReturn(new byte[0]); - assertDoesNotThrow(() -> loggerService.getLogBytes(loginUser, projectCode, 1)); + when(projectDao.queryProjectByTaskInstanceId(1)).thenReturn(project); + doThrow(new ServiceException(Status.USER_NO_OPERATION_PERM)).when(projectService) + .checkProjectAndAuthThrowException(loginUser, project, DOWNLOAD_LOG); - taskDefinition.setProjectCode(2L); - assertThrowsServiceException(Status.INTERNAL_SERVER_ERROR_ARGS, - () -> loggerService.getLogBytes(loginUser, projectCode, 1)); + assertThrowsServiceException( + Status.USER_NO_OPERATION_PERM, () -> loggerService.checkDownloadLogAuth(loginUser, 1)); + } - taskDefinition.setProjectCode(1L); - taskInstance.setId(100); - when(taskInstanceDao.queryById(100)).thenReturn(taskInstance); - doThrow(new ServiceException("download error")).when(logClientDelegate).getWholeLogBytes(any()); - assertThrowsServiceException(Status.DOWNLOAD_TASK_INSTANCE_LOG_FILE_ERROR, - () -> loggerService.getLogBytes(loginUser, projectCode, 100)); + @Test + public void testCheckDownloadLogAuth_success() { + User loginUser = newLoginUser(); + TaskInstance taskInstance = newTaskInstanceForAuth(1, "127.0.0.1:18080"); + Project project = getProject(1L); + when(taskInstanceDao.queryById(1)).thenReturn(taskInstance); + when(projectDao.queryProjectByTaskInstanceId(1)).thenReturn(project); + doNothing().when(projectService).checkProjectAndAuthThrowException(loginUser, project, DOWNLOAD_LOG); + + TaskInstance result = loggerService.checkDownloadLogAuth(loginUser, 1); + Assertions.assertEquals(taskInstance, result); + } + + @Test + public void testStreamLogBytes_success() throws Exception { + TaskInstance taskInstance = newTaskInstanceForAuth(1, "127.0.0.1:18080"); + + ByteArrayOutputStream outputStream = new ByteArrayOutputStream(); + loggerService.streamLogBytes(taskInstance, outputStream); + + String expectedHead = String.format("[LOG-PATH]: %s, [HOST]: %s%s", + taskInstance.getLogPath(), taskInstance.getHost(), Constants.SYSTEM_LINE_SEPARATOR); + Assertions.assertEquals(expectedHead, outputStream.toString("UTF-8")); + } + + @Test + public void testStreamLogBytes_ioExceptionPropagates() throws Exception { + TaskInstance taskInstance = newTaskInstanceForAuth(1, "127.0.0.1:18080"); + + doThrow(new IOException("stream error")).when(logClientDelegate).streamWholeLog(any(), any()); + + ByteArrayOutputStream outputStream = new ByteArrayOutputStream(); + IOException exception = Assertions.assertThrows(IOException.class, + () -> loggerService.streamLogBytes(taskInstance, outputStream)); + Assertions.assertEquals("stream error", exception.getMessage()); + // The head must NOT be written when streaming fails before any log byte — the HTTP + // response is then still uncommitted and can degrade to a proper JSON error instead of + // a broken 200 with a header-only .log body. + Assertions.assertEquals(0, outputStream.toByteArray().length); + } + + @Test + public void testStreamLogBytes_emptyLogWritesHeadOnly() throws Exception { + TaskInstance taskInstance = newTaskInstanceForAuth(1, "127.0.0.1:18080"); + + // streamWholeLog completes normally without writing any byte (valid empty log). + doAnswer(invocation -> null).when(logClientDelegate).streamWholeLog(any(), any()); + + ByteArrayOutputStream outputStream = new ByteArrayOutputStream(); + loggerService.streamLogBytes(taskInstance, outputStream); + + String expectedHead = String.format("[LOG-PATH]: %s, [HOST]: %s%s", + taskInstance.getLogPath(), taskInstance.getHost(), Constants.SYSTEM_LINE_SEPARATOR); + Assertions.assertEquals(expectedHead, outputStream.toString("UTF-8")); } /** @@ -292,12 +297,19 @@ private Project getProject(long projectCode) { return project; } - private void putMsg(Map result, Status status, Object... statusParams) { - result.put(Constants.STATUS, status); - if (statusParams != null && statusParams.length > 0) { - result.put(Constants.MSG, MessageFormat.format(status.getMsg(), statusParams)); - } else { - result.put(Constants.MSG, status.getMsg()); + private static User newLoginUser() { + User loginUser = new User(); + loginUser.setId(1); + return loginUser; + } + + private static TaskInstance newTaskInstanceForAuth(int id, String host) { + TaskInstance taskInstance = new TaskInstance(); + taskInstance.setId(id); + taskInstance.setLogPath("/temp/log"); + if (host != null) { + taskInstance.setHost(host); } + return taskInstance; } } diff --git a/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/utils/LogUtils.java b/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/utils/LogUtils.java index b007e337ec7b..bebc90881369 100644 --- a/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/utils/LogUtils.java +++ b/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/utils/LogUtils.java @@ -24,6 +24,7 @@ import java.io.FileInputStream; import java.io.IOException; import java.io.InputStream; +import java.io.RandomAccessFile; import java.nio.charset.StandardCharsets; import java.nio.file.Files; import java.nio.file.Paths; @@ -56,11 +57,6 @@ public static byte[] getFileContentBytesFromLocal(String filePath) { return new byte[0]; } - public static byte[] getFileContentBytesFromRemote(String filePath) { - RemoteLogUtils.getRemoteLog(filePath); - return getFileContentBytesFromLocal(filePath); - } - public static List readPartFileContentFromLocal(String filePath, int skipLine, int limit) { @@ -114,4 +110,40 @@ public static String getLocalLogBaseDir() { return loggerContext.getProperty("log.base.ctx"); } + /** + * Read a byte range [offset, offset+length) from a local file using random access, without + * loading the whole file into memory. Used by the chunked log download RPC. + * + *

Single-stat contract: the caller passes the file it already observed (together with + * the length it saw); this method never stats the file itself. Statting again would open a + * race between the two observations (log rotation/shrink in between) that could misclassify + * the read. If the file vanished after the observation, the {@link RandomAccessFile} + * constructor throws {@link java.io.FileNotFoundException}; if it shrank below the observed + * length, {@code readFully} throws an explicit EOF instead of silently returning a short + * chunk — callers can distinguish the two failure types by catching them. + * + * @param file the log file, already existence-checked and length-observed by the caller + * @param offset start byte offset (>= 0); if >= observedFileLength, an empty array is + * returned (clean EOF) + * @param length maximum number of bytes to read (> 0) + * @param observedFileLength the file length observed by the caller immediately before + * this call + * @return the bytes actually read; if fewer than {@code length}, the caller is at EOF + * @throws java.io.FileNotFoundException if the file disappeared since the caller's check + * @throws EOFException if the file shrank below the observed length mid-read + */ + public static byte[] readFileRange(final File file, final long offset, + final int length, final long observedFileLength) throws IOException { + if (offset >= observedFileLength || length <= 0) { + return new byte[0]; + } + final int toRead = (int) Math.min(length, observedFileLength - offset); + final byte[] buf = new byte[toRead]; + try (RandomAccessFile raf = new RandomAccessFile(file, "r")) { + raf.seek(offset); + raf.readFully(buf); + } + return buf; + } + } diff --git a/dolphinscheduler-common/src/test/java/org/apache/dolphinscheduler/common/utils/LogUtilsTest.java b/dolphinscheduler-common/src/test/java/org/apache/dolphinscheduler/common/utils/LogUtilsTest.java new file mode 100644 index 000000000000..508e0e2ba5a6 --- /dev/null +++ b/dolphinscheduler-common/src/test/java/org/apache/dolphinscheduler/common/utils/LogUtilsTest.java @@ -0,0 +1,80 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.apache.dolphinscheduler.common.utils; + +import static org.junit.jupiter.api.Assertions.assertArrayEquals; +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertThrows; + +import java.io.EOFException; +import java.io.FileNotFoundException; +import java.nio.charset.StandardCharsets; +import java.nio.file.Files; +import java.nio.file.Path; + +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.io.TempDir; + +public class LogUtilsTest { + + /** + * The caller passes the file length it observed ONCE (single-stat contract): the read must + * clamp against that length, never stat the file again — re-statting would race against + * rotation/shrink between the two observations. + */ + @Test + public void readFileRange_readsClampedToObservedLength(@TempDir Path tempDir) throws Exception { + Path file = tempDir.resolve("chunk.log"); + byte[] content = "0123456789ABCDEFG".getBytes(StandardCharsets.UTF_8); + Files.write(file, content); + + byte[] data = LogUtils.readFileRange(file.toFile(), 2, 5, content.length); + assertArrayEquals("23456".getBytes(StandardCharsets.UTF_8), data); + } + + @Test + public void readFileRange_offsetAtObservedLengthReturnsEmpty(@TempDir Path tempDir) throws Exception { + Path file = tempDir.resolve("eof.log"); + byte[] content = "hello".getBytes(StandardCharsets.UTF_8); + Files.write(file, content); + + byte[] data = LogUtils.readFileRange(file.toFile(), content.length, 10, content.length); + assertEquals(0, data.length); + } + + /** + * If the file SHRANK after the caller's single stat (rotation/truncation), the read must + * fail explicitly (EOF) instead of silently returning a short chunk — the caller turns + * this into an error response. + */ + @Test + public void readFileRange_fileShrankAfterObservation_failsExplicitly(@TempDir Path tempDir) throws Exception { + Path file = tempDir.resolve("shrunk.log"); + Files.write(file, "short".getBytes(StandardCharsets.UTF_8)); + + // Caller observed 100 bytes; the file is now only 5 — readFully must hit EOF. + assertThrows(EOFException.class, + () -> LogUtils.readFileRange(file.toFile(), 0, 10, 100)); + } + + @Test + public void readFileRange_missingFileThrows(@TempDir Path tempDir) { + assertThrows(FileNotFoundException.class, + () -> LogUtils.readFileRange(tempDir.resolve("absent.log").toFile(), 0, 10, 100)); + } +} diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/client/NettyClientHandler.java b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/client/NettyClientHandler.java index 56b09423608f..81b921de6fbb 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/client/NettyClientHandler.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/client/NettyClientHandler.java @@ -18,11 +18,11 @@ package org.apache.dolphinscheduler.extract.base.client; import org.apache.dolphinscheduler.extract.base.StandardRpcResponse; +import org.apache.dolphinscheduler.extract.base.exception.RemoteException; import org.apache.dolphinscheduler.extract.base.future.ResponseFuture; import org.apache.dolphinscheduler.extract.base.protocal.HeartBeatTransporter; import org.apache.dolphinscheduler.extract.base.protocal.Transporter; import org.apache.dolphinscheduler.extract.base.serialize.JsonSerializer; -import org.apache.dolphinscheduler.extract.base.utils.ChannelUtils; import lombok.extern.slf4j.Slf4j; import io.netty.channel.ChannelFutureListener; @@ -44,7 +44,11 @@ public NettyClientHandler(NettyRemotingClient nettyRemotingClient) { @Override public void channelInactive(ChannelHandlerContext ctx) { log.info("Channel inactive: {}", ctx.channel()); - nettyRemotingClient.onChannelInactive(ChannelUtils.toAddress(ctx.channel())); + // The channel is gone: no response can ever arrive, fail every in-flight request sent on + // it now instead of letting each caller wait for its individual RPC timeout. + ResponseFuture.failAllForChannel(ctx.channel(), + new RemoteException("Channel closed before response arrived: " + ctx.channel())); + nettyRemotingClient.onChannelInactive(ctx.channel()); ctx.channel().close(); } @@ -60,14 +64,21 @@ private void processReceived(final Transporter transporter) { return; } StandardRpcResponse deserialize = JsonSerializer.deserialize(transporter.getBody(), StandardRpcResponse.class); - future.setIRpcResponse(deserialize); + // Only putResponse writes the field — it must go through the done-guard so a future that + // was already failed by a channel error cannot be silently resurrected by a late response. + // If deserialization throws, the request is still in FUTURE_TABLE, so the exception + // flowing into exceptionCaught below fails it with the real error instead of a timeout. future.putResponse(deserialize); } @Override public void exceptionCaught(ChannelHandlerContext ctx, Throwable cause) { log.error("NettyClientHandler catch an exception on channel: {}", ctx.channel(), cause); - nettyRemotingClient.onChannelInactive(ChannelUtils.toAddress(ctx.channel())); + // Fail ALL in-flight requests on this channel with the REAL cause (e.g. + // TooLongFrameException from the maxFrameSize guard) — callers must not wait until RPC + // timeout, and the caller-side error inspection relies on the original exception. + ResponseFuture.failAllForChannel(ctx.channel(), cause); + nettyRemotingClient.onChannelInactive(ctx.channel()); ctx.channel().close(); } diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/client/NettyRemotingClient.java b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/client/NettyRemotingClient.java index 98ecb353e7a6..603680c600e9 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/client/NettyRemotingClient.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/client/NettyRemotingClient.java @@ -106,7 +106,8 @@ public void initChannel(SocketChannel ch) { clientConfig.getHeartBeatIntervalMillis(), 0, TimeUnit.MILLISECONDS)) - .addLast(new TransporterDecoder(), clientHandler, new TransporterEncoder()); + .addLast(new TransporterDecoder(clientConfig.getMaxFrameSize()), + clientHandler, new TransporterEncoder()); } }); isStarted.compareAndSet(false, true); @@ -162,29 +163,60 @@ private IRpcResponse doSendSync(final Transporter transporter, if (channel == null) { throw new RemoteException(String.format("connect to : %s fail", serverHost)); } - final ResponseFuture responseFuture = new ResponseFuture(transporter.getHeader().getOpaque(), timeoutMills); - channel.writeAndFlush(transporter).addListener(future -> { - if (future.isSuccess()) { - responseFuture.setSendOk(true); - return; - } else { - responseFuture.setSendOk(false); - } - responseFuture.setCause(future.cause()); - responseFuture.putResponse(null); - log.error("Send Sync request {} to host {} failed", transporter, serverHost, responseFuture.getCause()); - }); + final ResponseFuture responseFuture = + new ResponseFuture(transporter.getHeader().getOpaque(), timeoutMills, channel); + if (!channel.isActive()) { + // The channel died between getOrCreateChannel's liveness check and this registration + // (e.g. the drain of a concurrent channel failure just ran): no response can ever + // arrive on it. Fail this request NOW — the caller wakes immediately with the cause + // instead of waiting out the full RPC timeout. Checking liveness AFTER registering in + // FUTURE_TABLE is what makes this airtight: if the channel dies after the check, the + // channelInactive drain finds the future in the table and fails it; if it died + // before, this check catches it. + responseFuture.fail(new RemoteException("Channel is not active: " + serverHost)); + } else { + channel.writeAndFlush(transporter).addListener(future -> { + if (future.isSuccess()) { + responseFuture.setSendOk(true); + return; + } else { + responseFuture.setSendOk(false); + } + responseFuture.setCause(future.cause()); + responseFuture.putResponse(null); + log.error("Send Sync request {} to host {} failed", transporter, serverHost, responseFuture.getCause()); + }); + } /* * sync wait for result */ - final IRpcResponse iRpcResponse = responseFuture.waitResponse(); + final IRpcResponse iRpcResponse; + try { + iRpcResponse = responseFuture.waitResponse(); + } catch (InterruptedException e) { + // Caller thread was interrupted while waiting (e.g. shutdownNow / task cancellation). + // Same leak concern as the timeout path below: give up on this request and drop it + // from FUTURE_TABLE — nothing else will clean it up while the channel stays healthy. + responseFuture.cancel(); + throw e; + } if (iRpcResponse != null) { return iRpcResponse; } + // If cause was set (e.g. by exceptionCaught for TooLongFrameException), + // surface it immediately rather than reporting a misleading timeout. + if (responseFuture.getCause() != null) { + throw new RemoteException(serverHost.toString(), responseFuture.getCause()); + } if (responseFuture.isSendOK()) { - throw new RemoteTimeoutException(serverHost.toString(), timeoutMills, responseFuture.getCause()); + // Timed out: the caller gives up. Complete the future and drop it from FUTURE_TABLE — + // nothing else will clean it up while the channel stays healthy (heartbeats keep it + // alive even though the server never responds). A late response finds no future and + // is dropped. + responseFuture.cancel(); + throw new RemoteTimeoutException(serverHost.toString(), timeoutMills, null); } else { - throw new RemoteException(serverHost.toString(), responseFuture.getCause()); + throw new RemoteException(serverHost.toString(), null); } } @@ -253,7 +285,14 @@ private void closeChannels() { } } - public void onChannelInactive(final Host host) { - channels.remove(host); + /** + * Called when a channel died (inactive or pipeline exception). Removes the entry by CHANNEL + * IDENTITY, never by host: by the time this late notification runs, another thread may have + * already built a replacement channel for the same host — removing by host would evict that + * healthy replacement, orphaning it (never reused, never closed) and forcing later requests + * to create yet another connection. + */ + public void onChannelInactive(final Channel channel) { + channels.values().removeIf(ch -> ch == channel); } } diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/config/NettyClientConfig.java b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/config/NettyClientConfig.java index 23042420d5ce..45907518b824 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/config/NettyClientConfig.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/config/NettyClientConfig.java @@ -17,6 +17,8 @@ package org.apache.dolphinscheduler.extract.base.config; +import org.apache.dolphinscheduler.extract.base.protocal.TransporterDecoder; + import java.time.Duration; import lombok.AllArgsConstructor; @@ -67,4 +69,13 @@ public class NettyClientConfig { @Builder.Default private int defaultRpcTimeoutMillis = 10_000; + /** + * Maximum allowed frame size in bytes for a single RPC message (header + body). + * Frames exceeding this size will be rejected by the decoder to prevent OOM. + * Defaults to {@link TransporterDecoder#DEFAULT_MAX_FRAME_SIZE} — see its javadoc for the + * lower-bound rationale before lowering this. + */ + @Builder.Default + private int maxFrameSize = TransporterDecoder.DEFAULT_MAX_FRAME_SIZE; + } diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/config/NettyServerConfig.java b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/config/NettyServerConfig.java index 022d371eeec5..0fe7dcf623d1 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/config/NettyServerConfig.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/config/NettyServerConfig.java @@ -17,6 +17,8 @@ package org.apache.dolphinscheduler.extract.base.config; +import org.apache.dolphinscheduler.extract.base.protocal.TransporterDecoder; + import java.time.Duration; import lombok.AllArgsConstructor; @@ -62,6 +64,15 @@ public class NettyServerConfig { @Builder.Default private int workerThread = Runtime.getRuntime().availableProcessors() * 2; + /** + * Maximum allowed frame size in bytes for a single RPC message (header + body). + * Frames exceeding this size will be rejected by the decoder to prevent OOM. + * Defaults to {@link TransporterDecoder#DEFAULT_MAX_FRAME_SIZE} — see its javadoc for the + * lower-bound rationale before lowering this. + */ + @Builder.Default + private int maxFrameSize = TransporterDecoder.DEFAULT_MAX_FRAME_SIZE; + /** * If done's receive any data from a {@link io.netty.channel.Channel} during 180s then will close it. */ diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/future/ResponseFuture.java b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/future/ResponseFuture.java index 51742323eb44..2e487f131e8a 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/future/ResponseFuture.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/future/ResponseFuture.java @@ -22,11 +22,14 @@ import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.CountDownLatch; import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicBoolean; +import java.util.concurrent.atomic.AtomicReference; import lombok.Getter; import lombok.Setter; import lombok.ToString; import lombok.extern.slf4j.Slf4j; +import io.netty.channel.Channel; @ToString @Slf4j @@ -36,6 +39,8 @@ public class ResponseFuture { private final long opaque; + private final Channel channel; + private final long timeoutMillis; private final CountDownLatch latch = new CountDownLatch(1); @@ -44,15 +49,34 @@ public class ResponseFuture { @Getter @Setter - private IRpcResponse iRpcResponse; + // volatile: the TIMEOUT path in waitResponse returns this field after an await that timed + // out (not after being countDown-woken) — without volatile that read has no happens-before + // edge against a racing putResponse on the event loop and may see a partially-published + // response object. + private volatile IRpcResponse iRpcResponse; private volatile boolean sendOk = true; - private Throwable cause; + /** + * The failure cause, set-once: the first cause wins and later notifications are ignored. + * Two failure paths can hit the same future concurrently — the write-failure listener + * (caller thread) and the channel-error drain (event loop thread) — so a plain field would + * let whichever lands last overwrite the terminal state, and the caller would see an error + * that depends on thread interleaving. + */ + private final AtomicReference cause = new AtomicReference<>(); + + /** + * Guards that the future is completed exactly once. A channel failure may drain several + * pending futures concurrently with a late response arrival; first completion wins so a + * real response cannot be clobbered by a null error completion (or vice versa). + */ + private final AtomicBoolean done = new AtomicBoolean(false); - public ResponseFuture(long opaque, long timeoutMillis) { + public ResponseFuture(long opaque, long timeoutMillis, Channel channel) { this.opaque = opaque; this.timeoutMillis = timeoutMillis; + this.channel = channel; FUTURE_TABLE.put(opaque, this); } @@ -69,9 +93,55 @@ public IRpcResponse waitResponse() throws InterruptedException { } public void putResponse(final IRpcResponse iRpcResponse) { - this.iRpcResponse = iRpcResponse; - this.latch.countDown(); - FUTURE_TABLE.remove(opaque); + if (done.compareAndSet(false, true)) { + this.iRpcResponse = iRpcResponse; + this.latch.countDown(); + } + // Remove by INSTANCE identity: the retry path registers a replacement future under the + // same opaque, and a stale future completing late must not evict the live replacement + // from the table (that would force the replacement's caller to wait out its full + // timeout even after the real response arrives). + FUTURE_TABLE.remove(opaque, this); + } + + /** + * The caller stopped waiting (timeout). Completes the future and drops it from the global + * table so a timed-out request leaks nothing — no response, failure notification or channel + * death will ever arrive to clean it up, because the channel stays healthy (heartbeats). + * The done-guard makes this a no-op if a response or failure already completed the future, + * and a late response afterwards finds no future and is dropped. + */ + public void cancel() { + putResponse(null); + } + + /** + * Fail this future with {@code cause}: complete it (null response) and drop it from the table, + * waking the caller immediately. Used by the channel-death drain and by the send path when the + * channel died between registration and the write. No-op if the future already completed + * successfully — a real response is never clobbered by a failure notification. + */ + public void fail(Throwable cause) { + setCause(cause); + putResponse(null); + } + + /** + * FUTURE_TABLE is the single source of truth for in-flight requests: a future is in the table + * from construction until it completes, and every completion path (response arrival, write + * failure, timeout, interrupt, drain) removes it. When a channel dies no response can ever + * arrive on it again, so fail every future sent on THAT channel (identity match — other + * channels' futures are untouched) instead of letting each caller wait out its RPC timeout. + * + *

Iterating while {@code fail} removes entries is safe on a ConcurrentHashMap (weakly + * consistent iterator); channel death is a rare event so the O(in-flight) scan is negligible. + */ + public static void failAllForChannel(final Channel channel, final Throwable cause) { + for (final ResponseFuture future : FUTURE_TABLE.values()) { + if (future.channel == channel) { + future.fail(cause); + } + } } public static ResponseFuture getFuture(long opaque) { @@ -97,11 +167,12 @@ public void setSendOk(boolean sendOk) { } public void setCause(Throwable cause) { - this.cause = cause; + // First cause wins — this is terminal state, a racing later notification is dropped. + this.cause.compareAndSet(null, cause); } public Throwable getCause() { - return cause; + return this.cause.get(); } } diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/protocal/TransporterDecoder.java b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/protocal/TransporterDecoder.java index 8f2747c07959..894036980cdf 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/protocal/TransporterDecoder.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/protocal/TransporterDecoder.java @@ -25,12 +25,32 @@ import io.netty.buffer.ByteBuf; import io.netty.channel.ChannelHandlerContext; import io.netty.handler.codec.ReplayingDecoder; +import io.netty.handler.codec.TooLongFrameException; @Slf4j public class TransporterDecoder extends ReplayingDecoder { + /** + * Single source of truth for the default frame-size limit; the client/server configs default + * to it. Bump it HERE — setting one side higher than the other makes that side happily send + * frames the other rejects with TooLongFrameException. + * + *

Lower bound: JSON-serialized payloads grow ~4/3 via base64 encoding of byte[] + * fields (an 8 MB log chunk is ~10.7 MB on the wire). Setting this below ~4/3 of the largest + * expected payload plus header headroom silently breaks every such RPC — each one is rejected + * with TooLongFrameException. The default (64 MB) comfortably covers the 8 MB log chunk. + */ + public static final int DEFAULT_MAX_FRAME_SIZE = 64 * 1024 * 1024; + + private final int maxFrameSize; + public TransporterDecoder() { + this(DEFAULT_MAX_FRAME_SIZE); + } + + public TransporterDecoder(int maxFrameSize) { super(State.MAGIC); + this.maxFrameSize = maxFrameSize; } private int headerLength; @@ -49,6 +69,10 @@ protected void decode(ChannelHandlerContext ctx, ByteBuf in, List out) t checkpoint(State.HEADER_LENGTH); case HEADER_LENGTH: headerLength = in.readInt(); + if (headerLength < 0 || headerLength > maxFrameSize) { + throw new TooLongFrameException( + "Header length " + headerLength + " exceeds max frame size " + maxFrameSize); + } checkpoint(State.HEADER); case HEADER: header = new byte[headerLength]; @@ -56,6 +80,14 @@ protected void decode(ChannelHandlerContext ctx, ByteBuf in, List out) t checkpoint(State.BODY_LENGTH); case BODY_LENGTH: bodyLength = in.readInt(); + // maxFrameSize bounds the WHOLE message (header + body), not each field + // separately — per-field checks alone would still allow a 2x maxFrameSize + // total allocation. Long arithmetic: two ints summed can overflow. + if (bodyLength < 0 || (long) headerLength + (long) bodyLength > maxFrameSize) { + throw new TooLongFrameException( + "Frame size (header " + headerLength + " + body " + bodyLength + + ") exceeds max frame size " + maxFrameSize); + } checkpoint(State.BODY); case BODY: body = new byte[bodyLength]; diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/server/NettyRemotingServer.java b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/server/NettyRemotingServer.java index b3f018940027..320e50c89bfe 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/server/NettyRemotingServer.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/server/NettyRemotingServer.java @@ -134,7 +134,7 @@ protected void initChannel(SocketChannel ch) { private void initNettyChannel(SocketChannel ch) { ch.pipeline() .addLast("encoder", new TransporterEncoder()) - .addLast("decoder", new TransporterDecoder()) + .addLast("decoder", new TransporterDecoder(serverConfig.getMaxFrameSize())) .addLast("server-idle-handle", new IdleStateHandler(serverConfig.getConnectionIdleTime(), 0, 0, TimeUnit.MILLISECONDS)) .addLast("handler", channelHandler); diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/client/NettyClientHandlerTest.java b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/client/NettyClientHandlerTest.java new file mode 100644 index 000000000000..7a24b133c383 --- /dev/null +++ b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/client/NettyClientHandlerTest.java @@ -0,0 +1,466 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.apache.dolphinscheduler.extract.base.client; + +import static org.junit.jupiter.api.Assertions.assertNotNull; +import static org.junit.jupiter.api.Assertions.assertNull; +import static org.junit.jupiter.api.Assertions.assertSame; +import static org.junit.jupiter.api.Assertions.assertThrows; +import static org.junit.jupiter.api.Assertions.assertTrue; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.when; + +import org.apache.dolphinscheduler.extract.base.IRpcResponse; +import org.apache.dolphinscheduler.extract.base.RpcMethodRetryStrategy; +import org.apache.dolphinscheduler.extract.base.SyncRequestDto; +import org.apache.dolphinscheduler.extract.base.config.NettyClientConfig; +import org.apache.dolphinscheduler.extract.base.exception.RemoteException; +import org.apache.dolphinscheduler.extract.base.exception.RemoteTimeoutException; +import org.apache.dolphinscheduler.extract.base.future.ResponseFuture; +import org.apache.dolphinscheduler.extract.base.protocal.Transporter; +import org.apache.dolphinscheduler.extract.base.protocal.TransporterDecoder; +import org.apache.dolphinscheduler.extract.base.protocal.TransporterHeader; +import org.apache.dolphinscheduler.extract.base.utils.Host; + +import java.net.InetSocketAddress; +import java.nio.ByteBuffer; +import java.nio.charset.StandardCharsets; +import java.time.Duration; +import java.util.ArrayList; +import java.util.List; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +import java.util.concurrent.Future; +import java.util.concurrent.TimeUnit; + +import org.awaitility.Awaitility; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.Test; +import org.mockito.Mockito; + +import io.netty.bootstrap.ServerBootstrap; +import io.netty.buffer.Unpooled; +import io.netty.channel.Channel; +import io.netty.channel.ChannelHandlerContext; +import io.netty.channel.ChannelInitializer; +import io.netty.channel.EventLoopGroup; +import io.netty.channel.SimpleChannelInboundHandler; +import io.netty.channel.embedded.EmbeddedChannel; +import io.netty.channel.nio.NioEventLoopGroup; +import io.netty.channel.socket.SocketChannel; +import io.netty.channel.socket.nio.NioServerSocketChannel; +import io.netty.handler.codec.TooLongFrameException; + +class NettyClientHandlerTest { + + private EventLoopGroup serverBossGroup; + + private EventLoopGroup serverWorkerGroup; + + private NettyRemotingClient nettyRemotingClient; + + @AfterEach + void tearDown() { + if (nettyRemotingClient != null) { + nettyRemotingClient.close(); + } + if (serverBossGroup != null) { + serverBossGroup.shutdownGracefully(); + } + if (serverWorkerGroup != null) { + serverWorkerGroup.shutdownGracefully(); + } + } + + /** + * When a decoder exception (e.g. TooLongFrameException from the maxFrameSize guard) fires on a + * channel that carries MULTIPLE in-flight requests, the handler must complete ALL pending + * ResponseFutures with the cause — a channel is shared by concurrent requests, so tracking a + * single opaque would leave the others waiting until RPC timeout. + */ + @Test + void exceptionCaught_completesAllPendingFuturesWithCause() throws Exception { + long opaqueA = 888001L; + long opaqueB = 888002L; + + TooLongFrameException cause = + new TooLongFrameException("Body length 123456789 exceeds max frame size 67108864"); + + Channel channel = mock(Channel.class); + ResponseFuture futureA = new ResponseFuture(opaqueA, 30_000, channel); + ResponseFuture futureB = new ResponseFuture(opaqueB, 30_000, channel); + + ChannelHandlerContext ctx = mock(ChannelHandlerContext.class); + when(ctx.channel()).thenReturn(channel); + + NettyRemotingClient mockClient = mock(NettyRemotingClient.class); + NettyClientHandler handler = new NettyClientHandler(mockClient); + + handler.exceptionCaught(ctx, cause); + + // BOTH futures must be completed immediately — no 30 s timeout wait. + IRpcResponse responseA = futureA.waitResponse(); + IRpcResponse responseB = futureB.waitResponse(); + assertNull(responseA, "Response A should be null (error, not a normal RPC response)"); + assertNull(responseB, "Response B should be null (error, not a normal RPC response)"); + assertNotNull(futureA.getCause(), "Cause must be set on future A"); + assertNotNull(futureB.getCause(), "Cause must be set on future B"); + assertSame(cause, futureA.getCause(), "Cause must be the original exception (A)"); + assertSame(cause, futureB.getCause(), "Cause must be the original exception (B)"); + } + + /** + * Channel closure (peer restart, network blip) must fail every in-flight request sent on that + * channel — no response can ever arrive on a closed channel, so waiting for the RPC timeout + * would only add latency to an already-decided failure. + */ + @Test + void channelInactive_completesAllPendingFuturesWithCause() throws Exception { + final Channel channel = mock(Channel.class); + final ResponseFuture futureA = new ResponseFuture(888003L, 30_000, channel); + final ResponseFuture futureB = new ResponseFuture(888004L, 30_000, channel); + + final ChannelHandlerContext ctx = mock(ChannelHandlerContext.class); + when(ctx.channel()).thenReturn(channel); + + final NettyRemotingClient mockClient = mock(NettyRemotingClient.class); + final NettyClientHandler handler = new NettyClientHandler(mockClient); + + handler.channelInactive(ctx); + + final long start = System.nanoTime(); + assertNull(futureA.waitResponse(), "Drained future must not carry a response"); + assertNull(futureB.waitResponse(), "Drained future must not carry a response"); + assertTrue(System.nanoTime() - start < 5_000_000_000L, + "Drained futures must wake immediately, not wait out their timeout"); + assertNotNull(futureA.getCause(), "Channel closure must set a cause on future A"); + assertNotNull(futureB.getCause(), "Channel closure must set a cause on future B"); + assertNull(ResponseFuture.getFuture(888003L), "Drained future must leave FUTURE_TABLE"); + assertNull(ResponseFuture.getFuture(888004L), "Drained future must leave FUTURE_TABLE"); + } + + /** + * When there is no in-flight request on the channel, the handler must not throw — just log, + * close the channel, and move on. + */ + @Test + void exceptionCaught_noPendingFuture_doesNotThrow() { + final Channel channel = mock(Channel.class); + final ChannelHandlerContext ctx = mock(ChannelHandlerContext.class); + when(ctx.channel()).thenReturn(channel); + + final NettyRemotingClient mockClient = mock(NettyRemotingClient.class); + final NettyClientHandler handler = new NettyClientHandler(mockClient); + + org.junit.jupiter.api.Assertions.assertDoesNotThrow( + () -> handler.exceptionCaught(ctx, new RuntimeException("unrelated error"))); + } + + /** + * A response whose body cannot be deserialized must fail the pending request with the real + * error — NOT leave it hanging until RPC timeout. The request stays in FUTURE_TABLE until + * its response has been SUCCESSFULLY handed to the future, so the deserialization error + * flowing into exceptionCaught still finds it there and drains it. Otherwise the failing + * request alone waits out its timeout with a misleading RemoteTimeoutException while every + * OTHER pending request receives the actual error. + */ + @Test + void channelRead_deserializeFailure_failsPendingFutureNotTimeout() throws Exception { + final long opaque = 888101L; + + final NettyRemotingClient mockClient = mock(NettyRemotingClient.class); + final NettyClientHandler handler = new NettyClientHandler(mockClient); + final EmbeddedChannel channel = new EmbeddedChannel(handler); + final ResponseFuture future = new ResponseFuture(opaque, 2_000, channel); + + // Body is not valid JSON → JsonSerializer.deserialize throws inside processReceived, + // the error flows through the real pipeline into exceptionCaught. + final Transporter transporter = Transporter.of( + new TransporterHeader(opaque, "test-method"), + "not-json".getBytes(StandardCharsets.UTF_8)); + + try { + channel.writeInbound(transporter); + channel.checkException(); + } catch (Throwable expected) { + // The deserialization error surfacing here is fine — what matters is the future. + } + + assertNull(future.waitResponse(), "Future must be failed, not completed with a response"); + assertNotNull(future.getCause(), + "The failing request must receive the real error promptly — not hang until timeout"); + } + + /** + * Regression test for the shared-channel race: two CONCURRENT sync requests multiplexed over + * one channel, then the server replies with a frame whose declared body length exceeds + * maxFrameSize. The decoder throws TooLongFrameException and BOTH callers must receive that + * real error promptly — not one caller succeeding while the other hangs until timeout. + */ + @Test + void concurrentRequestsSharingChannel_decoderExceptionFailsAll() throws Exception { + // Server that decodes incoming Transporters; once it has seen both requests it writes a + // malformed frame (declared body length > 64 MB) so the CLIENT decoder throws. + serverBossGroup = new NioEventLoopGroup(1); + serverWorkerGroup = new NioEventLoopGroup(1); + ServerBootstrap serverBootstrap = new ServerBootstrap() + .group(serverBossGroup, serverWorkerGroup) + .channel(NioServerSocketChannel.class) + .childHandler(new ChannelInitializer() { + + @Override + protected void initChannel(SocketChannel ch) { + ch.pipeline() + .addLast(new TransporterDecoder()) + .addLast(new SimpleChannelInboundHandler() { + + private volatile int requestCount = 0; + + @Override + protected void channelRead0(ChannelHandlerContext ctx, Transporter msg) { + requestCount++; + if (requestCount >= 2) { + // Both requests are on the wire — poison the channel. + ctx.writeAndFlush(Unpooled.wrappedBuffer(malformedFrame())); + } + } + }); + } + }); + int serverPort = ((InetSocketAddress) serverBootstrap.bind(0).sync().channel().localAddress()).getPort(); + + nettyRemotingClient = new NettyRemotingClient(NettyClientConfig.builder().build()); + Host host = new Host("localhost", serverPort); + // Pre-warm the channel so both concurrent requests below multiplex over the SAME channel. + nettyRemotingClient.getOrCreateChannel(host); + + ExecutorService pool = Executors.newFixedThreadPool(2); + List> results = new ArrayList<>(); + try { + for (int i = 0; i < 2; i++) { + results.add(pool.submit(() -> { + try { + nettyRemotingClient.sendSync(newSyncRequest(host, 5_000)); + return null; + } catch (Throwable e) { + return e; + } + })); + } + + for (Future result : results) { + Throwable thrown = result.get(30, TimeUnit.SECONDS); + assertNotNull(thrown, "Both requests must fail — the server never sent a valid response"); + assertTrue(thrown instanceof RemoteException, + "Expected RemoteException but got: " + thrown); + assertTrue(findCause(thrown, TooLongFrameException.class), + "The error must carry the real decoder exception (TooLongFrameException), " + + "not a misleading timeout. Got: " + thrown); + } + } finally { + pool.shutdownNow(); + } + } + + /** + * A request that times out while the channel stays HEALTHY (server accepted it but never + * responds; heartbeats keep the connection alive) leaks nothing: the global FUTURE_TABLE + * keeps no trace of the abandoned request. There is no response, no failure notification + * and no channel death that would otherwise clean up — the timeout path itself must drop + * its own state. + */ + @Test + void sendSync_timeout_leaksNothingInFutureTable() throws Exception { + // Server that accepts connections and never responds — the channel stays healthy. + final int serverPort = startSilentServer(); + + nettyRemotingClient = new NettyRemotingClient(NettyClientConfig.builder().build()); + final Host host = new Host("localhost", serverPort); + nettyRemotingClient.getOrCreateChannel(host); + + final SyncRequestDto dto = newSyncRequest(host, 500); + final long opaque = dto.getTransporter().getHeader().getOpaque(); + + assertThrows(RemoteTimeoutException.class, () -> nettyRemotingClient.sendSync(dto)); + + assertNull(ResponseFuture.getFuture(opaque), + "Timed-out request's future must be removed from FUTURE_TABLE"); + } + + /** + * A caller thread INTERRUPTED while waiting for its response must not leak its FUTURE_TABLE + * entry. Interruption (shutdownNow / task cancellation) bypasses the timeout branch, so the + * interrupt path needs its own cleanup — otherwise, with a healthy-but-silent channel, the + * entry leaks per interruption. + */ + @Test + void sendSync_interruptedWhileWaiting_leaksNothingInFutureTable() throws Exception { + // Server that accepts connections and never responds — the channel stays healthy. + final int serverPort = startSilentServer(); + + nettyRemotingClient = new NettyRemotingClient(NettyClientConfig.builder().build()); + final Host host = new Host("localhost", serverPort); + nettyRemotingClient.getOrCreateChannel(host); + + final SyncRequestDto dto = newSyncRequest(host, 60_000); + final long opaque = dto.getTransporter().getHeader().getOpaque(); + + final ExecutorService pool = Executors.newSingleThreadExecutor(); + final java.util.concurrent.Future call = pool.submit(() -> { + try { + nettyRemotingClient.sendSync(dto); + } catch (Exception expected) { + // interrupted — expected + } + }); + try { + // Wait until the request is actually in flight (in FUTURE_TABLE) before interrupting. + Awaitility.await().atMost(Duration.ofSeconds(5)) + .until(() -> ResponseFuture.getFuture(opaque) != null); + call.cancel(true); // interrupt the waiting caller + } finally { + pool.shutdownNow(); + } + assertTrue(pool.awaitTermination(10, TimeUnit.SECONDS), "Interrupted caller must terminate"); + + assertNull(ResponseFuture.getFuture(opaque), + "Interrupted request's future must be removed from FUTURE_TABLE"); + } + + /** + * If the channel dies between {@code getOrCreateChannel}'s liveness check and the request + * registration (e.g. the drain of a concurrent channel failure just ran), the send must fail + * FAST: no write attempt on the dead channel, no FUTURE_TABLE leak, no waiting out the RPC + * timeout for a response that can never arrive. + */ + @Test + void sendSync_inactiveChannelAtSend_failsFastWithoutWriting() throws Exception { + nettyRemotingClient = Mockito.spy(new NettyRemotingClient(NettyClientConfig.builder().build())); + final Channel deadChannel = mock(Channel.class); + when(deadChannel.isActive()).thenReturn(false); + + final Host host = new Host("localhost", 12345); + Mockito.doReturn(deadChannel).when(nettyRemotingClient).getOrCreateChannel(host); + + final SyncRequestDto dto = newSyncRequest(host, 60_000); + final long opaque = dto.getTransporter().getHeader().getOpaque(); + + final long start = System.nanoTime(); + assertThrows(RemoteException.class, () -> nettyRemotingClient.sendSync(dto)); + assertTrue(System.nanoTime() - start < 5_000_000_000L, + "A dead channel must fail the send immediately, not wait out the timeout"); + Mockito.verify(deadChannel, Mockito.never()).writeAndFlush(Mockito.any()); + assertNull(ResponseFuture.getFuture(opaque), + "The abandoned request must not stay in FUTURE_TABLE"); + } + + /** + * A server that accepts connections and never responds — the channel stays healthy. + */ + private int startSilentServer() throws Exception { + serverBossGroup = new NioEventLoopGroup(1); + serverWorkerGroup = new NioEventLoopGroup(1); + ServerBootstrap serverBootstrap = new ServerBootstrap() + .group(serverBossGroup, serverWorkerGroup) + .channel(NioServerSocketChannel.class) + .childHandler(new ChannelInitializer() { + + @Override + protected void initChannel(SocketChannel ch) { + // accept and hold the connection open — never reply + } + }); + return ((InetSocketAddress) serverBootstrap.bind(0).sync().channel().localAddress()).getPort(); + } + + /** + * A no-retry sync request against {@code host} with the given timeout. + */ + private SyncRequestDto newSyncRequest(final Host host, final long timeoutMillis) { + final RpcMethodRetryStrategy noRetry = Mockito.mock(RpcMethodRetryStrategy.class); + when(noRetry.maxRetryTimes()).thenReturn(1); + when(noRetry.retryFor()).thenReturn(new Class[0]); + return SyncRequestDto.builder() + .timeoutMillis(timeoutMillis) + .retryStrategy(noRetry) + .transporter(Transporter.of(TransporterHeader.of("test-method"), new byte[]{0x01})) + .serverHost(host) + .build(); + } + + private static boolean findCause(Throwable throwable, Class type) { + Throwable current = throwable; + while (current != null) { + if (type.isInstance(current)) { + return true; + } + final Throwable cause = current.getCause(); + if (cause == current) { + break; + } + current = cause; + } + return false; + } + + /** + * A late inactive notification for a DEAD channel must not evict the healthy replacement + * another thread already created for the same host. Sequence: C1 dies, caller thread builds + * C2 for host H (channels: H→C2), and only then C1's inactive event fires. Removing by host + * would delete C2 — orphaning it (never reused, never closed by closeChannels) and forcing + * every later request to build yet another connection. Removal must match the channel + * identity, not the host. + */ + @Test + void onChannelInactive_lateEventForDeadChannel_keepsReplacementChannel() throws Exception { + // Minimal echo-less server: connections are accepted and held open. + final int serverPort = startSilentServer(); + + nettyRemotingClient = new NettyRemotingClient(NettyClientConfig.builder().build()); + final Host host = new Host("localhost", serverPort); + + final Channel c1 = nettyRemotingClient.getOrCreateChannel(host); + c1.close().sync(); + // Let C1's real inactive callback finish before building the replacement. + Awaitility.await().atMost(Duration.ofSeconds(5)) + .until(() -> nettyRemotingClient.getOrCreateChannel(host) != c1); + final Channel c2 = nettyRemotingClient.getOrCreateChannel(host); + + // C1's inactive notification arrives LATE (event-loop delay) — after C2 already replaced it. + nettyRemotingClient.onChannelInactive(c1); + + final Channel c3 = nettyRemotingClient.getOrCreateChannel(host); + assertSame(c2, c3, "A late inactive event for the dead channel must not evict its healthy replacement"); + } + + /** + * A syntactically valid frame prefix whose declared body length (64 MB + 1) exceeds the + * decoder's max frame size. Only the prefix is needed — the decoder rejects on the length + * field before any body byte arrives. + */ + private static byte[] malformedFrame() { + final int maxFrameSize = 64 * 1024 * 1024; + ByteBuffer buffer = ByteBuffer.allocate(2 + 4 + 8 + 4); + buffer.put(Transporter.MAGIC); + buffer.put(Transporter.VERSION); + buffer.putInt(8); // header length + buffer.put(new byte[8]); // header bytes + buffer.putInt(maxFrameSize + 1); // body length > maxFrameSize + return buffer.array(); + } +} diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/future/ResponseFutureTest.java b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/future/ResponseFutureTest.java new file mode 100644 index 000000000000..3e1e90aaba1b --- /dev/null +++ b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/future/ResponseFutureTest.java @@ -0,0 +1,169 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.apache.dolphinscheduler.extract.base.future; + +import static org.junit.jupiter.api.Assertions.assertNull; +import static org.junit.jupiter.api.Assertions.assertSame; +import static org.junit.jupiter.api.Assertions.assertTrue; + +import org.apache.dolphinscheduler.extract.base.IRpcResponse; +import org.apache.dolphinscheduler.extract.base.exception.RemoteException; + +import org.junit.jupiter.api.Test; +import org.mockito.Mockito; + +import io.netty.channel.Channel; + +class ResponseFutureTest { + + /** + * The failure cause of a future is terminal state: once set, a racing failure notification + * must not overwrite it. Two failure paths can hit the same future concurrently — the + * write-failure listener (caller thread) and the channel-error drain (event loop thread). + * Whichever lands first defines the cause the caller sees; a later notification must be + * ignored, otherwise the reported error depends on thread interleaving. + */ + @Test + void setCause_afterFirstCause_isIgnored() throws Exception { + final ResponseFuture future = new ResponseFuture(999001L, 1_000, Mockito.mock(Channel.class)); + final Throwable firstCause = new RuntimeException("first: channel decoder error"); + final Throwable lateCause = new RuntimeException("late: write failure"); + + future.setCause(firstCause); + future.putResponse(null); // complete the future on the failure path + + // Late failure notification arrives after the future is already completed — e.g. the + // write-failure listener racing the channel-error drain. + future.setCause(lateCause); + + assertSame(firstCause, future.getCause(), + "Terminal cause must not be overwritten by a racing failure notification"); + } + + /** + * A cause arriving after a SUCCESSFUL completion must not resurrect the future into an error + * state — the response field itself must stay intact. + */ + @Test + void setCause_afterSuccessfulCompletion_responseStaysIntact() throws Exception { + final ResponseFuture future = new ResponseFuture(999002L, 1_000, Mockito.mock(Channel.class)); + final IRpcResponse realResponse = Mockito.mock(IRpcResponse.class); + + future.putResponse(realResponse); + + // A late channel-error drain fires after the real response already completed the future. + future.setCause(new RuntimeException("late cause")); + + assertSame(realResponse, future.waitResponse(), + "A late failure notification must not clobber a successful response"); + } + + /** + * A stale future completing late must not evict the REPLACEMENT future registered under the + * same opaque (the retry path reuses the same transporter/opaque). Removing by key alone + * would drop the live replacement from FUTURE_TABLE, forcing its caller to wait out the full + * timeout even after the real response arrives — removal must match the instance identity. + */ + @Test + void putResponse_onStaleFuture_doesNotEvictReplacementUnderSameOpaque() { + final long opaque = 999003L; + final ResponseFuture staleFuture = new ResponseFuture(opaque, 100, Mockito.mock(Channel.class)); + final ResponseFuture replacement = new ResponseFuture(opaque, 5_000, Mockito.mock(Channel.class)); + + // The first attempt completes late — after the retry already registered its own future. + staleFuture.putResponse(null); + + assertSame(replacement, ResponseFuture.getFuture(opaque), + "A stale future must not evict the live replacement from FUTURE_TABLE"); + } + + /** + * FUTURE_TABLE is the single source of truth for in-flight requests; a channel's death must + * fail every future sent on THAT channel (identity match) and leave futures of other + * channels completely untouched. + */ + @Test + void failAllForChannel_failsOnlyFuturesOfThatChannel() throws Exception { + final Channel channelA = Mockito.mock(Channel.class); + final Channel channelB = Mockito.mock(Channel.class); + final ResponseFuture futureA1 = new ResponseFuture(999101L, 10_000, channelA); + final ResponseFuture futureA2 = new ResponseFuture(999102L, 10_000, channelA); + final ResponseFuture futureB = new ResponseFuture(999103L, 10_000, channelB); + + final RemoteException cause = new RemoteException("channel A died"); + + ResponseFuture.failAllForChannel(channelA, cause); + + // Futures of channel A: completed with the cause, removed from the table, woken + // immediately (elapsed far below their 10 s timeout). + final long start = System.nanoTime(); + assertNull(futureA1.waitResponse(), "Drained future must not carry a response"); + assertNull(futureA2.waitResponse(), "Drained future must not carry a response"); + assertTrue(System.nanoTime() - start < 5_000_000_000L, + "Drained futures must wake immediately, not wait out their timeout"); + assertSame(cause, futureA1.getCause(), "Future A1 must carry the channel-failure cause"); + assertSame(cause, futureA2.getCause(), "Future A2 must carry the channel-failure cause"); + assertNull(ResponseFuture.getFuture(999101L), "Drained future must be removed from FUTURE_TABLE"); + assertNull(ResponseFuture.getFuture(999102L), "Drained future must be removed from FUTURE_TABLE"); + + // Futures of channel B: untouched — still in flight, no cause, still in the table. + assertNull(futureB.getCause(), "A future of another channel must not be failed"); + assertSame(futureB, ResponseFuture.getFuture(999103L), + "A future of another channel must stay in FUTURE_TABLE"); + futureB.cancel(); // tidy up: do not leak the untouched future into other tests + } + + /** + * A channel-failure drain racing a late response must not clobber the response: the future + * was already completed successfully, so failAllForChannel is a no-op on it (done-guard), and + * the caller keeps its real response. + */ + @Test + void failAllForChannel_alreadyCompletedFuture_keepsItsResponse() throws Exception { + final Channel channel = Mockito.mock(Channel.class); + final ResponseFuture future = new ResponseFuture(999104L, 10_000, channel); + final IRpcResponse realResponse = Mockito.mock(IRpcResponse.class); + future.putResponse(realResponse); + + ResponseFuture.failAllForChannel(channel, new RemoteException("late drain")); + + assertSame(realResponse, future.waitResponse(), + "A late channel drain must not clobber an already-completed response"); + assertNull(ResponseFuture.getFuture(999104L), "Completed future must be removed from FUTURE_TABLE"); + } + + /** + * The self-fail path used when the channel died between registration and the write: the + * future is completed with the cause immediately and leaves FUTURE_TABLE, so the caller + * wakes at once instead of waiting out its timeout. + */ + @Test + void fail_completesFutureWithCauseAndRemovesFromTable() throws Exception { + final ResponseFuture future = new ResponseFuture(999105L, 10_000, Mockito.mock(Channel.class)); + final RemoteException cause = new RemoteException("channel not active"); + + final long start = System.nanoTime(); + future.fail(cause); + + assertNull(future.waitResponse(), "Failed future must not carry a response"); + assertTrue(System.nanoTime() - start < 5_000_000_000L, + "A failed future must wake its caller immediately"); + assertSame(cause, future.getCause(), "The failure cause must be preserved"); + assertNull(ResponseFuture.getFuture(999105L), "Failed future must be removed from FUTURE_TABLE"); + } +} diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/protocal/TransporterDecoderTest.java b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/protocal/TransporterDecoderTest.java new file mode 100644 index 000000000000..ef0e07567e1c --- /dev/null +++ b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/protocal/TransporterDecoderTest.java @@ -0,0 +1,147 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.apache.dolphinscheduler.extract.base.protocal; + +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertNotNull; +import static org.junit.jupiter.api.Assertions.assertNull; +import static org.junit.jupiter.api.Assertions.assertThrows; +import static org.junit.jupiter.api.Assertions.assertTrue; + +import org.junit.jupiter.api.Test; + +import io.netty.buffer.Unpooled; +import io.netty.channel.embedded.EmbeddedChannel; +import io.netty.handler.codec.TooLongFrameException; + +class TransporterDecoderTest { + + private static final int MAX_FRAME_SIZE = 64 * 1024 * 1024; + + @Test + void shouldDecodeValidFrameWithinLimit() { + TransporterHeader header = TransporterHeader.of("test-method"); + byte[] headerBytes = header.toBytes(); + byte[] bodyBytes = new byte[]{0x01, 0x02, 0x03}; + + EmbeddedChannel channel = new EmbeddedChannel(new TransporterDecoder()); + channel.writeInbound(Unpooled.wrappedBuffer(encodeFrame(headerBytes, bodyBytes))); + + Transporter decoded = channel.readInbound(); + assertNotNull(decoded); + assertEquals(header.getMethodIdentifier(), decoded.getHeader().getMethodIdentifier()); + assertEquals(header.getOpaque(), decoded.getHeader().getOpaque()); + assertEquals(bodyBytes.length, decoded.getBody().length); + } + + @Test + void shouldRejectHeaderLengthExceedingMaxFrameSize() { + EmbeddedChannel channel = new EmbeddedChannel(new TransporterDecoder()); + byte[] headerBytes = new byte[]{0x01, 0x02}; + byte[] bodyBytes = new byte[]{0x03}; + + TooLongFrameException thrown = assertThrows(TooLongFrameException.class, () -> channel.writeInbound( + Unpooled.wrappedBuffer(encodeFrameWithCustomHeaderLength(headerBytes, bodyBytes, MAX_FRAME_SIZE + 1)))); + assertTrue(thrown.getMessage().contains("Header length")); + assertNull(channel.readInbound()); + } + + @Test + void shouldRejectBodyLengthExceedingMaxFrameSize() { + TransporterHeader header = TransporterHeader.of("test-method"); + byte[] headerBytes = header.toBytes(); + byte[] bodyBytes = new byte[]{0x01}; + + EmbeddedChannel channel = new EmbeddedChannel(new TransporterDecoder()); + TooLongFrameException thrown = assertThrows(TooLongFrameException.class, () -> channel.writeInbound( + Unpooled.wrappedBuffer(encodeFrameWithCustomBodyLength(headerBytes, bodyBytes, MAX_FRAME_SIZE + 1)))); + assertTrue(thrown.getMessage().contains("exceeds max frame size")); + assertNull(channel.readInbound()); + } + + /** + * maxFrameSize bounds the WHOLE message (header + body), not each part separately: checking + * each field individually would still allow a 2×maxFrameSize total allocation. Here header + * (700B) and body (600B) each fit under the 1KB limit but sum to 1300B — must be rejected + * BEFORE the body array is allocated. + */ + @Test + void shouldRejectCombinedHeaderAndBodyExceedingMaxFrameSize() { + final int smallMaxFrameSize = 1024; + byte[] headerBytes = new byte[700]; // fully written so decoding reaches BODY_LENGTH + + EmbeddedChannel channel = new EmbeddedChannel(new TransporterDecoder(smallMaxFrameSize)); + TooLongFrameException thrown = assertThrows(TooLongFrameException.class, () -> channel.writeInbound( + Unpooled.wrappedBuffer( + encodeFrameWithCustomLengths(headerBytes, new byte[]{0x01}, headerBytes.length, 600)))); + assertTrue(thrown.getMessage().contains("exceeds max frame size"), + "Rejection must be on the combined size, got: " + thrown.getMessage()); + assertNull(channel.readInbound()); + } + + /** + * A frame whose header + body is EXACTLY maxFrameSize is legal — the bound is inclusive. + */ + @Test + void shouldAcceptFrameExactlyAtCombinedMaxFrameSize() { + final int smallMaxFrameSize = 1024; + TransporterHeader header = TransporterHeader.of("test-method"); + byte[] headerBytes = header.toBytes(); + // header + body == 1024 exactly + byte[] bodyBytes = new byte[smallMaxFrameSize - headerBytes.length]; + + EmbeddedChannel channel = new EmbeddedChannel(new TransporterDecoder(smallMaxFrameSize)); + channel.writeInbound(Unpooled.wrappedBuffer(encodeFrame(headerBytes, bodyBytes))); + + Transporter decoded = channel.readInbound(); + assertNotNull(decoded); + assertEquals(bodyBytes.length, decoded.getBody().length); + } + + private byte[] encodeFrame(byte[] headerBytes, byte[] bodyBytes) { + return encodeFrameWithCustomLengths(headerBytes, bodyBytes, headerBytes.length, bodyBytes.length); + } + + private byte[] encodeFrameWithCustomHeaderLength(byte[] headerBytes, byte[] bodyBytes, int headerLength) { + return encodeFrameWithCustomLengths(headerBytes, bodyBytes, headerLength, bodyBytes.length); + } + + private byte[] encodeFrameWithCustomBodyLength(byte[] headerBytes, byte[] bodyBytes, int bodyLength) { + return encodeFrameWithCustomLengths(headerBytes, bodyBytes, headerBytes.length, bodyLength); + } + + private byte[] encodeFrameWithCustomLengths(byte[] headerBytes, byte[] bodyBytes, int headerLength, + int bodyLength) { + byte[] frame = new byte[2 + 4 + headerBytes.length + 4 + bodyBytes.length]; + int offset = 0; + frame[offset++] = Transporter.MAGIC; + frame[offset++] = Transporter.VERSION; + frame[offset++] = (byte) (headerLength >> 24); + frame[offset++] = (byte) (headerLength >> 16); + frame[offset++] = (byte) (headerLength >> 8); + frame[offset++] = (byte) headerLength; + System.arraycopy(headerBytes, 0, frame, offset, headerBytes.length); + offset += headerBytes.length; + frame[offset++] = (byte) (bodyLength >> 24); + frame[offset++] = (byte) (bodyLength >> 16); + frame[offset++] = (byte) (bodyLength >> 8); + frame[offset++] = (byte) bodyLength; + System.arraycopy(bodyBytes, 0, frame, offset, bodyBytes.length); + return frame; + } +} diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/ILogService.java b/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/ILogService.java index 4484e519421b..a62c51014fe3 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/ILogService.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/ILogService.java @@ -36,4 +36,11 @@ public interface ILogService { @RpcMethod void removeTaskInstanceLog(String taskInstanceLogAbsolutePath); + /** + * Read a bounded chunk of the log file [offset, offset+length) for streaming download. + * The worker clamps length to a maximum chunk size and returns eof metadata. + */ + @RpcMethod(timeout = 30_000) + TaskInstanceLogFileDownloadResponse getTaskInstanceLogFileChunk(TaskInstanceLogFileDownloadRequest request); + } diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/service/impl/LogServiceImpl.java b/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/service/impl/LogServiceImpl.java index bbe2c09d9291..c9a741a1b8ad 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/service/impl/LogServiceImpl.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/service/impl/LogServiceImpl.java @@ -28,10 +28,14 @@ import org.apache.commons.lang3.exception.ExceptionUtils; +import java.io.File; +import java.io.FileNotFoundException; import java.util.List; public class LogServiceImpl implements ILogService { + private static final int MAX_CHUNK_SIZE = 8 * 1024 * 1024; // 8 MB + /** * Downloads the entire log file for a task instance. * @@ -43,6 +47,18 @@ public TaskInstanceLogFileDownloadResponse getTaskInstanceWholeLogFileBytes(Task final TaskInstanceLogFileDownloadResponse taskInstanceLogFileDownloadResponse = new TaskInstanceLogFileDownloadResponse(); try { + final File logFile = new File(taskInstanceLogFileDownloadRequest.getTaskInstanceLogAbsolutePath()); + if (!logFile.exists() || !logFile.isFile()) { + // Distinguish MISSING from EMPTY: an empty log is a valid SUCCESS ("task produced + // no output"), a missing one must signal callers to fall back to the remote + // archive. getFileContentBytesFromLocal swallows the FileNotFoundException and + // returns an empty array, so without this check the two states are + // indistinguishable on the wire. + taskInstanceLogFileDownloadResponse.setCode(LogResponseStatus.LOG_FILE_NOT_FOUND); + taskInstanceLogFileDownloadResponse.setMessage( + "Log file not found: " + taskInstanceLogFileDownloadRequest.getTaskInstanceLogAbsolutePath()); + return taskInstanceLogFileDownloadResponse; + } byte[] bytes = LogUtils .getFileContentBytesFromLocal(taskInstanceLogFileDownloadRequest.getTaskInstanceLogAbsolutePath()); taskInstanceLogFileDownloadResponse.setLogBytes(bytes); @@ -82,4 +98,53 @@ public void removeTaskInstanceLog(String taskInstanceLogAbsolutePath) { FileUtils.deleteFile(taskInstanceLogAbsolutePath); } + @Override + public TaskInstanceLogFileDownloadResponse getTaskInstanceLogFileChunk( + final TaskInstanceLogFileDownloadRequest request) { + final TaskInstanceLogFileDownloadResponse response = new TaskInstanceLogFileDownloadResponse(); + try { + final String path = request.getTaskInstanceLogAbsolutePath(); + final long offset = Math.max(request.getOffset(), 0); + final int length = request.getLength() <= 0 + ? MAX_CHUNK_SIZE + : Math.min(request.getLength(), MAX_CHUNK_SIZE); + final File logFile = new File(path); + if (!logFile.exists() || !logFile.isFile()) { + response.setCode(LogResponseStatus.LOG_FILE_NOT_FOUND); + response.setMessage("Log file not found: " + path); + response.setEof(true); + return response; + } + // Single stat drives ALL decisions below (missing / truncated / EOF / read clamp): + // re-statting after the read would race against rotation between the two + // observations and could misclassify the result. + final long observedFileLength = logFile.length(); + if (offset > observedFileLength) { + // offset is PAST the observed file size: the file shrank underneath the reader + // (log rotation renamed it, a fresh one started from 0). offset == fileLength + // is the normal clean EOF, but offset > fileLength can only mean truncation — + // reporting SUCCESS here would silently hand the caller a truncated download. + response.setCode(LogResponseStatus.LOG_TRUNCATED); + response.setMessage("Log file was truncated/rotated: size " + + observedFileLength + " < requested offset " + offset); + response.setEof(true); + return response; + } + final byte[] data = LogUtils.readFileRange(logFile, offset, length, observedFileLength); + response.setLogBytes(data); + response.setEof(data.length < length); + } catch (FileNotFoundException e) { + // The file passed the existence check above but vanished before the read opened it. + // Typed — no re-stat: re-statting would race against rotation and could misclassify. + response.setCode(LogResponseStatus.LOG_FILE_NOT_FOUND); + response.setMessage(ExceptionUtils.getRootCauseMessage(e)); + response.setEof(true); + } catch (Exception e) { + response.setCode(LogResponseStatus.ERROR); + response.setMessage(ExceptionUtils.getRootCauseMessage(e)); + response.setEof(true); + } + return response; + } + } diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/transportor/LogResponseStatus.java b/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/transportor/LogResponseStatus.java index c82b6c342cd7..4def8d51ec8a 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/transportor/LogResponseStatus.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/transportor/LogResponseStatus.java @@ -32,4 +32,11 @@ public enum LogResponseStatus { * Log file not found status code. */ LOG_FILE_NOT_FOUND, + + /** + * The log file shrank below the requested offset while streaming — e.g. log rotation + * renamed the active file and a fresh one started from 0. The download the caller is + * assembling is truncated and must fail explicitly instead of silently ending. + */ + LOG_TRUNCATED, } diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/transportor/TaskInstanceLogFileDownloadRequest.java b/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/transportor/TaskInstanceLogFileDownloadRequest.java index dcb8c1da4adf..84783b1f1165 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/transportor/TaskInstanceLogFileDownloadRequest.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/transportor/TaskInstanceLogFileDownloadRequest.java @@ -30,4 +30,21 @@ public class TaskInstanceLogFileDownloadRequest { private String taskInstanceLogAbsolutePath; + /** + * Chunk read offset in bytes. Only read by the chunk RPC — the legacy whole-file method + * ignores it. Non-positive values are clamped to 0 by the worker. + */ + private long offset = 0; + + /** + * Chunk read length in bytes. Only read by the chunk RPC — the legacy whole-file method + * ignores it. Non-positive values are clamped to the worker's maximum chunk size. + */ + private int length = 0; + + public TaskInstanceLogFileDownloadRequest(long taskInstanceId, String taskInstanceLogAbsolutePath) { + this.taskInstanceId = taskInstanceId; + this.taskInstanceLogAbsolutePath = taskInstanceLogAbsolutePath; + } + } diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/transportor/TaskInstanceLogFileDownloadResponse.java b/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/transportor/TaskInstanceLogFileDownloadResponse.java index 6cf6dff623af..01f8eb6ef558 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/transportor/TaskInstanceLogFileDownloadResponse.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/transportor/TaskInstanceLogFileDownloadResponse.java @@ -32,4 +32,9 @@ public class TaskInstanceLogFileDownloadResponse { private String message; + /** + * Whether this is the last chunk (or the only chunk for whole-file responses). + */ + private boolean eof = true; + } diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-common/src/test/java/org/apache/dolphinscheduler/extract/common/service/impl/LogServiceImplTest.java b/dolphinscheduler-extract/dolphinscheduler-extract-common/src/test/java/org/apache/dolphinscheduler/extract/common/service/impl/LogServiceImplTest.java new file mode 100644 index 000000000000..0469776730f1 --- /dev/null +++ b/dolphinscheduler-extract/dolphinscheduler-extract-common/src/test/java/org/apache/dolphinscheduler/extract/common/service/impl/LogServiceImplTest.java @@ -0,0 +1,205 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.apache.dolphinscheduler.extract.common.service.impl; + +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertTrue; + +import org.apache.dolphinscheduler.extract.common.transportor.LogResponseStatus; +import org.apache.dolphinscheduler.extract.common.transportor.TaskInstanceLogFileDownloadRequest; +import org.apache.dolphinscheduler.extract.common.transportor.TaskInstanceLogFileDownloadResponse; + +import java.io.IOException; +import java.nio.charset.StandardCharsets; +import java.nio.file.Files; +import java.nio.file.Path; + +import org.junit.jupiter.api.Test; + +class LogServiceImplTest { + + private final LogServiceImpl logService = new LogServiceImpl(); + + @Test + void getTaskInstanceLogFileChunk_normalRangeReturnsSuccess() throws IOException { + Path file = Files.createTempFile("ds-chunk", ".log"); + try { + byte[] content = new byte[20]; + for (int i = 0; i < 20; i++) { + content[i] = (byte) i; + } + Files.write(file, content); + + TaskInstanceLogFileDownloadRequest req = new TaskInstanceLogFileDownloadRequest(); + req.setTaskInstanceLogAbsolutePath(file.toString()); + req.setOffset(0); + req.setLength(10); + + TaskInstanceLogFileDownloadResponse resp = logService.getTaskInstanceLogFileChunk(req); + assertEquals(LogResponseStatus.SUCCESS, resp.getCode()); + assertEquals(10, resp.getLogBytes().length); + assertTrue(!resp.isEof()); + } finally { + Files.deleteIfExists(file); + } + } + + @Test + void getTaskInstanceLogFileChunk_lastChunkEof() throws IOException { + Path file = Files.createTempFile("ds-chunk-eof", ".log"); + try { + byte[] content = new byte[20]; + Files.write(file, content); + + TaskInstanceLogFileDownloadRequest req = new TaskInstanceLogFileDownloadRequest(); + req.setTaskInstanceLogAbsolutePath(file.toString()); + req.setOffset(16); + req.setLength(10); + + TaskInstanceLogFileDownloadResponse resp = logService.getTaskInstanceLogFileChunk(req); + assertEquals(LogResponseStatus.SUCCESS, resp.getCode()); + assertEquals(4, resp.getLogBytes().length); + assertTrue(resp.isEof()); + } finally { + Files.deleteIfExists(file); + } + } + + /** + * offset BEYOND the file length can only mean the file shrank underneath the reader — + * log rotation (fixed-window renames the active file, a fresh one starts from 0) or + * truncation. A well-behaved client advances offset monotonically from 0, so it can never + * legitimately be past EOF. Reporting SUCCESS+empty here would silently hand the caller a + * truncated download that looks complete. + */ + @Test + void getTaskInstanceLogFileChunk_offsetBeyondShrunkFileReturnsTruncated() throws IOException { + Path file = Files.createTempFile("ds-chunk-beyond", ".log"); + try { + Files.write(file, "hello".getBytes(StandardCharsets.UTF_8)); + + TaskInstanceLogFileDownloadRequest req = new TaskInstanceLogFileDownloadRequest(); + req.setTaskInstanceLogAbsolutePath(file.toString()); + req.setOffset(100); + req.setLength(10); + + TaskInstanceLogFileDownloadResponse resp = logService.getTaskInstanceLogFileChunk(req); + assertEquals(LogResponseStatus.LOG_TRUNCATED, resp.getCode()); + assertTrue(resp.isEof()); + } finally { + Files.deleteIfExists(file); + } + } + + /** + * offset EXACTLY at the file length is the normal end-of-file reached after consuming the + * whole file — must stay SUCCESS+empty+eof (the chunk loop's clean termination path). + */ + @Test + void getTaskInstanceLogFileChunk_offsetEqualsFileLengthIsNormalEof() throws IOException { + Path file = Files.createTempFile("ds-chunk-at-eof", ".log"); + try { + Files.write(file, "hello".getBytes(StandardCharsets.UTF_8)); + + TaskInstanceLogFileDownloadRequest req = new TaskInstanceLogFileDownloadRequest(); + req.setTaskInstanceLogAbsolutePath(file.toString()); + req.setOffset(5); + req.setLength(10); + + TaskInstanceLogFileDownloadResponse resp = logService.getTaskInstanceLogFileChunk(req); + assertEquals(LogResponseStatus.SUCCESS, resp.getCode()); + assertEquals(0, resp.getLogBytes().length); + assertTrue(resp.isEof()); + } finally { + Files.deleteIfExists(file); + } + } + + @Test + void getTaskInstanceLogFileChunk_fileNotFound() { + TaskInstanceLogFileDownloadRequest req = new TaskInstanceLogFileDownloadRequest(); + req.setTaskInstanceLogAbsolutePath("/nonexistent/chunk.log"); + req.setOffset(0); + req.setLength(10); + + TaskInstanceLogFileDownloadResponse resp = logService.getTaskInstanceLogFileChunk(req); + assertEquals(LogResponseStatus.LOG_FILE_NOT_FOUND, resp.getCode()); + assertTrue(resp.isEof()); + } + + /** + * A MISSING log file must be reported as LOG_FILE_NOT_FOUND, not as SUCCESS with an empty + * body: an empty log is a valid terminal state ("task produced no output") while a missing + * one tells the caller to fall back to the remote archive. getFileContentBytesFromLocal + * swallows the FileNotFoundException and returns an empty array, so without this explicit + * check the two states are indistinguishable on the wire. + */ + @Test + void getTaskInstanceWholeLogFileBytes_missingFileReturnsNotFound() { + TaskInstanceLogFileDownloadRequest req = new TaskInstanceLogFileDownloadRequest(); + req.setTaskInstanceLogAbsolutePath("/nonexistent/whole.log"); + + TaskInstanceLogFileDownloadResponse resp = logService.getTaskInstanceWholeLogFileBytes(req); + assertEquals(LogResponseStatus.LOG_FILE_NOT_FOUND, resp.getCode()); + } + + /** + * An EXISTING but empty log file stays SUCCESS with empty bytes — the valid terminal state + * for a task that produced no output. + */ + @Test + void getTaskInstanceWholeLogFileBytes_emptyFileReturnsSuccess() throws IOException { + Path file = Files.createTempFile("ds-whole-empty", ".log"); + try { + Files.write(file, new byte[0]); + + TaskInstanceLogFileDownloadRequest req = new TaskInstanceLogFileDownloadRequest(); + req.setTaskInstanceLogAbsolutePath(file.toString()); + + TaskInstanceLogFileDownloadResponse resp = logService.getTaskInstanceWholeLogFileBytes(req); + assertEquals(LogResponseStatus.SUCCESS, resp.getCode()); + assertEquals(0, resp.getLogBytes().length); + } finally { + Files.deleteIfExists(file); + } + } + + @Test + void getTaskInstanceLogFileChunk_lengthClampedToMaxChunkSize() throws IOException { + Path file = Files.createTempFile("ds-chunk-clamp", ".log"); + try { + // Write more than MAX_CHUNK_SIZE (8 MB) — 9 MB + byte[] mb = new byte[1024 * 1024]; + Files.write(file, mb); + for (int i = 1; i < 9; i++) { + Files.write(file, mb, java.nio.file.StandardOpenOption.APPEND); + } + + TaskInstanceLogFileDownloadRequest req = new TaskInstanceLogFileDownloadRequest(); + req.setTaskInstanceLogAbsolutePath(file.toString()); + req.setOffset(0); + req.setLength(100 * 1024 * 1024); // request 100MB + + TaskInstanceLogFileDownloadResponse resp = logService.getTaskInstanceLogFileChunk(req); + assertEquals(LogResponseStatus.SUCCESS, resp.getCode()); + assertEquals(8 * 1024 * 1024, resp.getLogBytes().length, "Should be clamped to 8MB"); + } finally { + Files.deleteIfExists(file); + } + } +} From 744d282022b3942fb4a2cf9152c049c53c8010f6 Mon Sep 17 00:00:00 2001 From: xmg333 <1318834675@qq.com> Date: Sun, 4 Oct 2026 01:25:05 +0800 Subject: [PATCH 2/2] [Fix-18459][API/Common] Propagate remote log download failures and publish only complete transfers MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The remote fallback could serve a truncated log as a successful download: RemoteLogClient.streamWholeLog() downloaded via RemoteLogUtils.getRemoteLog() and then snapshotted whatever file sat at the local path, while every RemoteLogHandler swallowed download errors — S3/ABS even wrote in place, so a transfer failing mid-stream left a partial file that was streamed as HTTP 200. - RemoteLogHandler#getRemoteLog now declares and propagates IOException. - All five handlers (S3/ABS/OSS/COS/GCS) download into a staging file (.download-) and publish it with an atomic move (RemoteLogUtils#downloadToLocalFileAtomically); a failed transfer deletes the staging file, leaves an existing cached archive untouched, and fails the request instead of serving a partial (or stale) log. - S3/ABS verify the received byte count against the announced object size; GCS reports a missing object explicitly. - The view path (LogUtils#readPartFileContentFromRemote) turns the failure into a RuntimeException instead of reading a possibly stale/partial local file. - The staging marker is shared with RemoteLogClient's streaming snapshot (RemoteLogUtils.DOWNLOAD_TEMP_FILE_MARKER), so the API startup sweep also covers handler staging leftovers; the sweep, its age gate and helpers are now named for per-download temp files (snapshot or staging), not snapshots only. Tests: RemoteLogUtilsTest (complete publish, replace, mid-transfer failure with and without an existing cached archive, runtime-exception wrap), S3RemoteLogHandlerTest (real handler with mocked SDK: mid-transfer failure, existing cache preserved, silent short stream rejected, complete transfer publishes), RemoteLogClientTest (download failure propagates and leaves the cached archive untouched), LogUtilsTest (view path does not fall through to the local file). Review follow-ups: - The RPC wait-failure classification re-reads the future state and keeps the real transport cause (a write failure racing the timeout must not degrade to a bare timeout/host string); dropped late responses and failed sends log the small header and body length only, never the Lombok toString of the transporter (a log chunk response body is ~10 MB). - Leftover cleanup now also covers the archive's own directory: the startup sweep only walks the local log base dir, which is not where task archives are downloaded to (they follow the task log path), so an aged staging/snapshot file is swept before each download as well. - Tests: the fallback test asserted counters its own stub incremented (it could not fail) and is replaced by a pass-through assertion plus a bounded-writes regression test on the real streaming copy; new tests cover the RPC failure classification and the body-free dropped-response log line, and the sweep (unit + at the getRemoteLog call site). Behavior fixes: - The chunked download is a snapshot again: the worker reports the file length of its single stat on every chunk, the API pins the target length to the FIRST chunk's value and clamps the follow-up requests to it, so downloading a live, growing log ends cleanly at the request-time boundary instead of tailing the file until the async timeout. 0 (an old worker) keeps the eof-only termination, so the rolling upgrade is unaffected. - The per-log-path locks are no longer a fixed 64-stripe array: an unrelated log whose path hashed to a busy stripe had to wait for a whole multi-GB remote download. Locks are now per path, reference-counted and dropped with their last user, so different logs never block each other while requests for the same log still coalesce. - Old-worker detection is typed, not message-parsed: the server marks the "Cannot find the ServerMethodInvoker" failure on the wire (StandardRpcResponse#methodNotFound) and the client maps it to MethodNotFoundException, so ONLY a worker that genuinely lacks the chunk method gets the "worker upgrade required" guidance; a current worker whose invocation failed (its pool is full, the method threw) is reported as "the worker answered with an error" instead. Both shapes are covered over the real Netty wire in RollingUpgradeLogStreamingIntegrationTest. BREAKING CHANGE: RemoteLogHandler#getRemoteLog now declares throws IOException, and LogUtils#getFileContentBytesFromRemote is removed; out-of-tree implementations and callers of these public common APIs must be updated (see docs/docs/en/guide/upgrade/incompatible.md). --- docs/docs/en/guide/upgrade/incompatible.md | 1 + docs/docs/zh/guide/upgrade/incompatible.md | 1 + .../executor/logging/LogClientDelegate.java | 66 +++-- .../api/executor/logging/RemoteLogClient.java | 112 ++++++--- .../logging/LogClientDelegateTest.java | 114 +++++++-- .../executor/logging/RemoteLogClientTest.java | 145 ++++++++++- ...ingUpgradeLogStreamingIntegrationTest.java | 95 ++++++-- .../log/remote/AbsRemoteLogHandler.java | 26 +- .../log/remote/CosRemoteLogHandler.java | 11 +- .../log/remote/GcsRemoteLogHandler.java | 16 +- .../log/remote/OssRemoteLogHandler.java | 11 +- .../common/log/remote/RemoteLogHandler.java | 18 +- .../common/log/remote/RemoteLogUtils.java | 144 ++++++++++- .../common/log/remote/S3RemoteLogHandler.java | 21 +- .../common/utils/LogUtils.java | 9 +- .../common/log/remote/RemoteLogUtilsTest.java | 189 +++++++++++++++ .../log/remote/S3RemoteLogHandlerTest.java | 228 ++++++++++++++++++ .../common/utils/LogUtilsTest.java | 25 ++ .../extract/base/IRpcResponse.java | 8 + .../extract/base/StandardRpcResponse.java | 17 ++ .../base/client/NettyClientHandler.java | 8 +- .../base/client/NettyRemotingClient.java | 32 ++- .../base/client/SyncClientMethodInvoker.java | 6 + .../exception/MethodNotFoundException.java | 33 +++ .../base/server/JdkDynamicServerHandler.java | 10 +- .../base/client/NettyClientHandlerTest.java | 41 ++++ .../base/client/NettyRemotingClientTest.java | 80 ++++++ .../client/SyncClientMethodInvokerTest.java | 104 ++++++++ .../extract/common/ILogService.java | 6 + .../common/service/impl/LogServiceImpl.java | 1 + .../TaskInstanceLogFileDownloadResponse.java | 20 ++ .../service/impl/LogServiceImplTest.java | 25 ++ 32 files changed, 1478 insertions(+), 145 deletions(-) create mode 100644 dolphinscheduler-common/src/test/java/org/apache/dolphinscheduler/common/log/remote/RemoteLogUtilsTest.java create mode 100644 dolphinscheduler-common/src/test/java/org/apache/dolphinscheduler/common/log/remote/S3RemoteLogHandlerTest.java create mode 100644 dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/exception/MethodNotFoundException.java create mode 100644 dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/client/NettyRemotingClientTest.java create mode 100644 dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/client/SyncClientMethodInvokerTest.java diff --git a/docs/docs/en/guide/upgrade/incompatible.md b/docs/docs/en/guide/upgrade/incompatible.md index ad118a1d6088..4fe3514d230d 100644 --- a/docs/docs/en/guide/upgrade/incompatible.md +++ b/docs/docs/en/guide/upgrade/incompatible.md @@ -56,3 +56,4 @@ This document records the incompatible updates between each version. You need to * **Removed derived properties**: `cmdTypeIfComplement`, `complementData` (related to complement-data executions; use the detail API to obtain them) * To obtain any of these fields, use the detail API `GET /projects/{projectCode}/workflow-instances/{id}` instead, which continues to return the full `WorkflowInstance` object. ([#18444](https://github.com/apache/dolphinscheduler/pull/18444)) +* `RemoteLogHandler#getRemoteLog` in `dolphinscheduler-common` now declares `throws IOException` and propagates download failures instead of swallowing them; `LogUtils#getFileContentBytesFromRemote` was removed. Out-of-tree implementations and callers of these APIs must be updated. ([#18459](https://github.com/apache/dolphinscheduler/issues/18459)) diff --git a/docs/docs/zh/guide/upgrade/incompatible.md b/docs/docs/zh/guide/upgrade/incompatible.md index a0f945501989..aa4f41df9030 100644 --- a/docs/docs/zh/guide/upgrade/incompatible.md +++ b/docs/docs/zh/guide/upgrade/incompatible.md @@ -56,3 +56,4 @@ * **移除的派生属性**：`cmdTypeIfComplement`、`complementData`（补数执行相关，如需获取请使用详情接口） * 如需获取这些字段，请使用详情接口 `GET /projects/{projectCode}/workflow-instances/{id}`，该接口仍返回完整的 `WorkflowInstance` 对象 ([#18444](https://github.com/apache/dolphinscheduler/pull/18444)) +* `dolphinscheduler-common` 中的 `RemoteLogHandler#getRemoteLog` 现在声明 `throws IOException` 并向上传播下载失败（不再吞掉异常）；`LogUtils#getFileContentBytesFromRemote` 已移除。仓库外的实现与调用方需要相应调整。([#18459](https://github.com/apache/dolphinscheduler/issues/18459)) diff --git a/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/LogClientDelegate.java b/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/LogClientDelegate.java index b08ae1d72e76..bd414cfef9bd 100644 --- a/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/LogClientDelegate.java +++ b/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/LogClientDelegate.java @@ -19,6 +19,7 @@ import org.apache.dolphinscheduler.dao.entity.TaskInstance; import org.apache.dolphinscheduler.extract.base.exception.MethodInvocationException; +import org.apache.dolphinscheduler.extract.base.exception.MethodNotFoundException; import org.apache.dolphinscheduler.extract.common.transportor.LogResponseStatus; import org.apache.dolphinscheduler.extract.common.transportor.TaskInstanceLogFileDownloadResponse; import org.apache.dolphinscheduler.extract.common.transportor.TaskInstanceLogPageQueryResponse; @@ -101,10 +102,13 @@ private boolean checkNodeExists(TaskInstance taskInstance) { *
    *
  • If the worker node is gone, read straight from remote log storage (archive), streamed * in bounded chunks.
    • - *
  • Otherwise stream via the chunk RPC. If the FIRST chunk fails — e.g. an old worker - * during a rolling upgrade does not implement {@code getTaskInstanceLogFileChunk} — - * fall back to remote log storage; if that also fails, throw an explicit error asking - * for a worker upgrade.
    • + *
  • Otherwise stream via the chunk RPC, bounded to a SNAPSHOT of the log taken when the + * download starts: the target length is pinned to the length the worker reports on the + * first chunk, so a live task's growing log ends cleanly at that boundary instead of + * tailing the file until the writer stops (or the request times out).
    • + *
  • If the FIRST chunk fails — e.g. an old worker during a rolling upgrade does not + * implement {@code getTaskInstanceLogFileChunk} — fall back to remote log storage; if + * that also fails, throw an explicit error asking for a worker upgrade.
    • *
  • The legacy whole-file worker RPC is deliberately NEVER used: it reads the entire file * into the worker's heap before serialization, so a large log can OOM the worker. A * receiver-side maxFrameSize cannot prevent that allocation, and an old worker (already @@ -122,28 +126,52 @@ public void streamWholeLog(final TaskInstance taskInstance, final OutputStream o return; } long offset = 0; + // The length of the snapshot this download delivers. Unknown until the first chunk + // reports it; 0 means the worker does not report it (e.g. an old worker during a rolling + // upgrade) and the stream then ends on eof only. + long snapshotLength = -1; while (true) { + if (snapshotLength > 0 && offset >= snapshotLength) { + // The last byte of the request-time snapshot has been delivered. A live task may + // have written more since the first chunk observed the length: the download is a + // snapshot taken when it started, not an unbounded tail of a growing log. + return; + } + // After the first chunk only what is left of the snapshot is requested — the worker + // clamps to the file, so a growing log is never read past the snapshot boundary. + final int chunkLength = snapshotLength > 0 + ? (int) Math.min(LOG_CHUNK_SIZE, snapshotLength - offset) + : LOG_CHUNK_SIZE; final TaskInstanceLogFileDownloadResponse chunk; try { - chunk = localLogClient.getLogChunk(taskInstance, offset, LOG_CHUNK_SIZE); + chunk = localLogClient.getLogChunk(taskInstance, offset, chunkLength); } catch (Exception e) { if (offset > 0) { throw new IOException("Log streaming failed at offset " + offset, e); } log.warn("Chunked log RPC failed for task instance {}, falling back to remote log storage", taskInstance.getId(), e); - // A MethodInvocationException means the worker ANSWERED but could not dispatch the - // method — that is the old-worker signal (rolling upgrade: the chunk method does - // not exist there), so the upgrade guidance is accurate. Any other transport - // failure (connect refused, timeout) just means the worker is unreachable; blaming - // the worker version would mislead operations. - final String errorMessage = - ExceptionUtils.throwableOfType(e, MethodInvocationException.class) != null - ? "Worker upgrade required for large log download: chunked log RPC is not available" - + " on worker " + taskInstance.getHost() + " and remote log storage also failed" - : "Chunked log RPC to worker " + taskInstance.getHost() - + " failed (the worker may be down or unreachable)" - + " and remote log storage also failed"; + // Distinguish the three failure shapes so operations get accurate guidance: + // - MethodNotFoundException: the worker ANSWERED that the chunk method does not + // exist — an old worker during a rolling upgrade, the upgrade guidance fits. + // - any other MethodInvocationException: the worker ANSWERED but the invocation + // failed there (its invocation pool is full, the method threw) — a current + // worker under stress must NOT be told to upgrade. + // - anything else (connect refused, timeout): the worker never answered. + final String errorMessage; + if (ExceptionUtils.throwableOfType(e, MethodNotFoundException.class) != null) { + errorMessage = "Worker upgrade required for large log download: chunked log RPC is not available" + + " on worker " + taskInstance.getHost() + " and remote log storage also failed"; + } else if (ExceptionUtils.throwableOfType(e, MethodInvocationException.class) != null) { + errorMessage = "Chunked log fetch failed on worker " + taskInstance.getHost() + + " for task instance " + taskInstance.getId() + + " (the worker answered with an error: " + ExceptionUtils.getRootCauseMessage(e) + ")" + + " and remote log storage also failed"; + } else { + errorMessage = "Chunked log RPC to worker " + taskInstance.getHost() + + " failed (the worker may be down or unreachable)" + + " and remote log storage also failed"; + } fallbackToRemoteStorage(taskInstance, outputStream, errorMessage); return; } @@ -163,6 +191,10 @@ public void streamWholeLog(final TaskInstance taskInstance, final OutputStream o + taskInstance.getId() + " (" + failure + ") and remote log storage also failed"); return; } + if (snapshotLength < 0) { + // Pin the snapshot from the worker's first stat; 0 keeps the eof-only behavior. + snapshotLength = chunk.getObservedLength(); + } final byte[] data = chunk.getLogBytes(); if (data != null && data.length > 0) { outputStream.write(data); diff --git a/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/RemoteLogClient.java b/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/RemoteLogClient.java index aa2d6fd73e86..07a298f758bf 100644 --- a/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/RemoteLogClient.java +++ b/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/RemoteLogClient.java @@ -32,6 +32,7 @@ import java.nio.file.Paths; import java.nio.file.StandardCopyOption; import java.util.UUID; +import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.locks.ReentrantLock; import java.util.stream.Stream; @@ -46,62 +47,89 @@ public class RemoteLogClient { /** - * Marker of the per-download snapshot files ({@code .download-}), also used - * by the startup sweep to recognize orphans. + * Marker of the per-download temporary files ({@code .download-}): the private + * streaming snapshots of this class and the staging files the remote log handlers download + * into (see {@link RemoteLogUtils#downloadToLocalFileAtomically}). Also used by the startup + * sweep to recognize orphans. */ - private static final String SNAPSHOT_MARKER = ".download-"; + private static final String DOWNLOAD_TEMP_MARKER = RemoteLogUtils.DOWNLOAD_TEMP_FILE_MARKER; /** - * Snapshots younger than this are never swept as orphans: on the (unsupported but possible) - * shared-disk setup the age gate protects another live instance's in-flight transfer. + * Per-download temp files younger than this are never swept as orphans: on the (unsupported + * but possible) shared-disk setup the age gate protects another live instance's in-flight + * transfer. Shared with {@link RemoteLogUtils#deleteAgedDownloadTempFiles(Path)}, the + * per-download cleanup that also covers the directories this startup sweep cannot reach. */ - private static final long ORPHAN_SNAPSHOT_MIN_AGE_MILLIS = 60 * 60 * 1000L; + private static final long ORPHAN_TEMP_FILE_MIN_AGE_MILLIS = + RemoteLogUtils.ORPHAN_DOWNLOAD_TEMP_MIN_AGE_MILLIS; /** - * Striped locks serializing download + snapshot per log path. The remote log handlers - * rewrite the local archive file in place ({@code new FileOutputStream(logPath)} truncates - * it), so concurrent download/view requests for the same log must not interleave their - * download windows; {@link #streamWholeLog} additionally snapshots the archive into a - * private temp file, so its lock-free streaming read stays stable across later cache - * rewrites. A fixed stripe array avoids unbounded lock-map growth; different logs sharing - * a stripe only lose a little parallelism, never correctness. Each API instance downloads - * to its own local disk, so per-JVM locking is sufficient. + * Per-log-path locks: concurrent requests for the SAME log coalesce (the second waits for the + * in-flight download instead of re-downloading a possibly multi-GB archive), while requests + * for different logs never block each other — the previous fixed 64-stripe array made + * unrelated logs that hashed to the same stripe wait behind a whole remote download. Entries + * are reference-counted and removed with the last user, so the map is bounded by the number + * of in-flight log paths, and {@link #streamWholeLog}'s private snapshot keeps its lock-free + * streaming read stable across later cache replacements. Each API instance downloads to its + * own local disk, so per-JVM locking is sufficient. */ - private static final int LOCK_STRIPES = 64; - private static final ReentrantLock[] LOG_PATH_LOCKS = new ReentrantLock[LOCK_STRIPES]; + private static final ConcurrentHashMap LOG_PATH_LOCKS = new ConcurrentHashMap<>(); - static { - for (int i = 0; i < LOCK_STRIPES; i++) { - LOG_PATH_LOCKS[i] = new ReentrantLock(); - } + private static final class LockEntry { + + private final ReentrantLock lock = new ReentrantLock(); + + /** Only touched inside the map's per-key compute calls — never read or written outside. */ + private int references; } + /** + * Take a reference to the lock of {@code logPath}; every call must be paired with + * {@link #unlockFor(String)} (after {@code lock.unlock()}) so the entry can be released. + */ static ReentrantLock lockFor(final String logPath) { - return LOG_PATH_LOCKS[(logPath.hashCode() & 0x7fffffff) % LOCK_STRIPES]; + return LOG_PATH_LOCKS.compute(logPath, (path, entry) -> { + final LockEntry current = entry != null ? entry : new LockEntry(); + current.references++; + return current; + }).lock; } /** - * At startup this JVM can have no in-flight transfer, so any snapshot file left over from a - * previous life (graceful shutdown and kill -9 alike skip the transfer's {@code finally}) is - * an orphan and is swept. Best effort: any error just skips the sweep. Does nothing when - * logging is not initialized (e.g. plain unit tests). + * Drop one reference to {@code logPath}'s lock entry, removing it when the last user is gone. + * Must run AFTER {@code lock.unlock()}: an entry removed while still held would let a new + * arrival lock a fresh entry concurrently with the holder. + */ + static void unlockFor(final String logPath) { + LOG_PATH_LOCKS.computeIfPresent(logPath, (path, entry) -> --entry.references == 0 ? null : entry); + } + + /** + * At startup this JVM can have no in-flight transfer, so any per-download temp file left over + * from a previous life — this class's streaming snapshot or a remote handler's download + * staging file (graceful shutdown and kill -9 alike skip the transfer's {@code finally}) — is + * an orphan and is swept. Only the local log base dir can be walked here; the archive + * directories (which follow task log paths and may live elsewhere) are covered by + * {@link RemoteLogUtils#deleteAgedDownloadTempFiles(Path)} before each download. Best effort: + * any error just skips the sweep. Does nothing when logging is not initialized (e.g. plain + * unit tests). */ @PostConstruct - public void deleteOrphanedSnapshots() { + public void deleteOrphanedTempFiles() { final String baseDir = LogUtils.getLocalLogBaseDir(); if (baseDir != null) { - deleteOrphanedSnapshots(Paths.get(baseDir)); + deleteOrphanedTempFiles(Paths.get(baseDir)); } } - void deleteOrphanedSnapshots(final Path baseDir) { + void deleteOrphanedTempFiles(final Path baseDir) { try (Stream walk = Files.walk(baseDir)) { walk.filter(Files::isRegularFile) - .filter(file -> file.getFileName().toString().contains(SNAPSHOT_MARKER)) + .filter(file -> file.getFileName().toString().contains(DOWNLOAD_TEMP_MARKER)) .filter(RemoteLogClient::olderThanOrphanAge) - .forEach(this::deleteSnapshotQuietly); + .forEach(this::deleteTempFileQuietly); } catch (Exception e) { - log.warn("Failed to sweep orphaned log download snapshots under {}", baseDir, e); + log.warn("Failed to sweep orphaned log download temp files under {}", baseDir, e); } } @@ -109,17 +137,21 @@ private static boolean olderThanOrphanAge(final Path file) { // java.io.File#lastModified returns 0 when the time cannot be read — treat that as // "unknown age, keep it" rather than sweeping blindly. final long lastModified = file.toFile().lastModified(); - return lastModified > 0 && lastModified < System.currentTimeMillis() - ORPHAN_SNAPSHOT_MIN_AGE_MILLIS; + return lastModified > 0 && lastModified < System.currentTimeMillis() - ORPHAN_TEMP_FILE_MIN_AGE_MILLIS; } /** * Stream the entire remote-archived log to {@code outputStream} without loading the whole * file into memory. Downloads the archive to a local file, snapshots it into a private temp * file ({@code .download-}, deleted when the transfer ends; leftovers are - * swept by {@link #deleteOrphanedSnapshots()}) and streams that snapshot — see the + * swept by {@link #deleteOrphanedTempFiles()}) and streams that snapshot — see the * {@code LOG_PATH_LOCKS} note for why the snapshot is required. Costs a second write of the * archive (~2x peak disk for one download). * + *

    A failed remote download propagates — nothing is streamed and any previously published + * archive is left untouched (the handler publishes a download only after a complete + * transfer), so a truncated log can never be served as a successful download. + * * @throws IOException if the log cannot be downloaded, the file is missing, no data is * available, or the snapshot ends prematurely (local disk trouble). */ @@ -142,7 +174,7 @@ public void streamWholeLog(final TaskInstance taskInstance, // terminal state as an empty log served by a live worker — and must stream // normally (zero bytes; the caller appends the head). Only a MISSING file is an // error: a missing archive must not be reported as a successful empty download. - snapshot = archive.resolveSibling(archive.getFileName() + SNAPSHOT_MARKER + UUID.randomUUID()); + snapshot = archive.resolveSibling(archive.getFileName() + DOWNLOAD_TEMP_MARKER + UUID.randomUUID()); boolean opened = false; try { Files.copy(archive, snapshot, StandardCopyOption.REPLACE_EXISTING); @@ -155,11 +187,12 @@ public void streamWholeLog(final TaskInstance taskInstance, // finally (not catch): a partial snapshot must never survive a failed creation, // whatever the failure type — up to and including Error (e.g. OOM mid-copy). if (!opened) { - deleteSnapshotQuietly(snapshot); + deleteTempFileQuietly(snapshot); } } } finally { lock.unlock(); + unlockFor(logPath); } try { streamBounded(in, expectedLength, outputStream); @@ -171,18 +204,18 @@ public void streamWholeLog(final TaskInstance taskInstance, // own exception nor skip the snapshot deletion below. log.warn("Failed to close the log download snapshot stream for {}", logPath, e); } - deleteSnapshotQuietly(snapshot); + deleteTempFileQuietly(snapshot); } outputStream.flush(); } - private void deleteSnapshotQuietly(final Path snapshot) { + private void deleteTempFileQuietly(final Path tempFile) { try { - Files.deleteIfExists(snapshot); + Files.deleteIfExists(tempFile); } catch (Throwable e) { // Throwable, not IOException: this runs in finally blocks and must never throw // through them (masking the original failure) or give up on deletion early. - log.warn("Failed to delete the log download snapshot {}", snapshot, e); + log.warn("Failed to delete the log download temp file {}", tempFile, e); } } @@ -224,6 +257,7 @@ public String getPartLog(TaskInstance taskInstance, int skipLineNum, int limit) LogUtils.readPartFileContentFromRemote(taskInstance.getLogPath(), skipLineNum, limit)); } finally { lock.unlock(); + unlockFor(taskInstance.getLogPath()); } } diff --git a/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/LogClientDelegateTest.java b/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/LogClientDelegateTest.java index 9553142c4f9a..f847a498fb97 100644 --- a/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/LogClientDelegateTest.java +++ b/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/LogClientDelegateTest.java @@ -20,6 +20,7 @@ import static org.junit.jupiter.api.Assertions.assertArrayEquals; import static org.junit.jupiter.api.Assertions.assertEquals; import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertSame; import static org.junit.jupiter.api.Assertions.assertThrows; import static org.junit.jupiter.api.Assertions.assertTrue; import static org.mockito.ArgumentMatchers.any; @@ -35,6 +36,7 @@ import org.apache.dolphinscheduler.dao.entity.TaskInstance; import org.apache.dolphinscheduler.extract.base.exception.MethodInvocationException; +import org.apache.dolphinscheduler.extract.base.exception.MethodNotFoundException; import org.apache.dolphinscheduler.extract.common.transportor.LogResponseStatus; import org.apache.dolphinscheduler.extract.common.transportor.TaskInstanceLogFileDownloadResponse; import org.apache.dolphinscheduler.extract.common.transportor.TaskInstanceLogPageQueryResponse; @@ -204,7 +206,7 @@ public void testStreamWholeLogRpcThrowsAndRemoteFailsThrowsUpgradeError() throws when(registryClient.checkNodeExists(eq(ti.getHost()), any())).thenReturn(true); when(localLogClient.getLogChunk(eq(ti), anyLong(), anyInt())) - .thenThrow(new MethodInvocationException( + .thenThrow(new MethodNotFoundException( "Cannot find the ServerMethodInvoker of getTaskInstanceLogFileChunk")); doThrow(new IOException("Remote log file not found after download (remote log archiving may not be enabled " + "or the archive is missing): /tmp/x.log")) @@ -274,6 +276,35 @@ public void testStreamWholeLogStructuredFailureAndRemoteFailsThrowsWithoutUpgrad assertEquals(0, out.toByteArray().length); } + /** + * A CURRENT worker that answered but failed the invocation (e.g. its invocation pool is + * full) produces the same MethodInvocationException type as an old worker would: the typed + * MethodNotFoundException is what separates them, so the upgrade guidance must NOT appear + * here — the error has to say the worker answered with an error instead. + */ + @Test + public void testStreamWholeLogWorkerAnsweredWithErrorDoesNotSuggestUpgrade() throws Exception { + TaskInstance ti = newTaskInstance(); + + when(registryClient.checkNodeExists(eq(ti.getHost()), any())).thenReturn(true); + when(localLogClient.getLogChunk(eq(ti), anyLong(), anyInt())) + .thenThrow(new MethodInvocationException("NettyRemotingServer's thread pool is full")); + doThrow(new IOException("Remote log file not found after download (remote log archiving may not be enabled " + + "or the archive is missing): /tmp/x.log")) + .when(remoteLogClient).streamWholeLog(eq(ti), any(OutputStream.class)); + + ByteArrayOutputStream out = new ByteArrayOutputStream(); + IOException thrown = assertThrows(IOException.class, () -> logClientDelegate.streamWholeLog(ti, out)); + assertFalse(thrown.getMessage().contains("upgrade required"), + "A saturated current worker must not be reported as needing an upgrade: " + thrown.getMessage()); + assertTrue(thrown.getMessage().contains("the worker answered with an error"), + "The error must say the worker answered and failed, got: " + thrown.getMessage()); + assertTrue(thrown.getMessage().contains("thread pool is full"), + "The server-side failure message must stay visible, got: " + thrown.getMessage()); + assertTrue(thrown.getCause().getMessage().contains("Remote log file not found")); + assertEquals(0, out.toByteArray().length); + } + /** * A SUCCESS chunk with ZERO bytes is the worker's authoritative "task produced no output" — * a valid terminal state. Must return normally without touching remote storage. @@ -332,6 +363,62 @@ private static TaskInstanceLogFileDownloadResponse chunk(byte[] full, int off, i return new TaskInstanceLogFileDownloadResponse(b, LogResponseStatus.SUCCESS, null, eof); } + private static TaskInstanceLogFileDownloadResponse chunkWithLength(byte[] data, boolean eof, long observedLength) { + final TaskInstanceLogFileDownloadResponse response = + new TaskInstanceLogFileDownloadResponse(data, LogResponseStatus.SUCCESS, null, eof); + response.setObservedLength(observedLength); + return response; + } + + /** + * A live task keeps writing while its log is downloaded: the download must be a SNAPSHOT of + * the length observed on the FIRST chunk, not an unbounded tail that never reaches eof. The + * follow-up chunks are requested clamped to the snapshot boundary, so output written after + * the download started is never streamed. + */ + @Test + public void testStreamWholeLogLiveLogStreamsTheRequestTimeSnapshot() throws Exception { + TaskInstance ti = newTaskInstance(); + final int chunkSize = 8 * 1024 * 1024; + + when(registryClient.checkNodeExists(eq(ti.getHost()), any())).thenReturn(true); + // The first chunk pins the snapshot: 6 of 10 bytes delivered, the log already grew to 30. + when(localLogClient.getLogChunk(eq(ti), eq(0L), eq(chunkSize))) + .thenReturn(chunkWithLength("ABCDEF".getBytes(StandardCharsets.UTF_8), false, 10)); + // The second request is clamped to the 4 bytes left of the snapshot. + when(localLogClient.getLogChunk(eq(ti), eq(6L), eq(4))) + .thenReturn(chunkWithLength("GHIJ".getBytes(StandardCharsets.UTF_8), false, 30)); + + ByteArrayOutputStream out = new ByteArrayOutputStream(); + logClientDelegate.streamWholeLog(ti, out); + + assertEquals("ABCDEFGHIJ", new String(out.toByteArray(), StandardCharsets.UTF_8)); + // Exactly the snapshot was fetched — no third request follows the growing tail. + verify(localLogClient, times(2)).getLogChunk(eq(ti), anyLong(), anyInt()); + } + + /** + * An old worker during a rolling upgrade does not report the observed length: the loop must + * fall back to eof-only termination and keep requesting full chunks. + */ + @Test + public void testStreamWholeLogUnreportedObservedLengthKeepsEofOnlyTermination() throws Exception { + TaskInstance ti = newTaskInstance(); + final int chunkSize = 8 * 1024 * 1024; + + when(registryClient.checkNodeExists(eq(ti.getHost()), any())).thenReturn(true); + when(localLogClient.getLogChunk(eq(ti), eq(0L), eq(chunkSize))) + .thenReturn(chunkWithLength("ABCDEF".getBytes(StandardCharsets.UTF_8), false, 0)); + when(localLogClient.getLogChunk(eq(ti), eq(6L), eq(chunkSize))) + .thenReturn(chunkWithLength("GHIJ".getBytes(StandardCharsets.UTF_8), true, 0)); + + ByteArrayOutputStream out = new ByteArrayOutputStream(); + logClientDelegate.streamWholeLog(ti, out); + + assertEquals("ABCDEFGHIJ", new String(out.toByteArray(), StandardCharsets.UTF_8)); + verify(localLogClient, times(2)).getLogChunk(eq(ti), anyLong(), anyInt()); + } + /** * chunk RPC explicitly reporting LOG_FILE_NOT_FOUND means a NEW worker authoritatively says * the file is gone (an old worker cannot report this — it fails the RPC instead). The remote @@ -417,36 +504,33 @@ public void testStreamWholeLogLogRotatedMidStreamThrows() throws Exception { } /** - * Regression: when the first chunk fails and we fall back to remote storage, the - * remote file must be streamed to the OutputStream in chunks rather than loaded - * into a single byte[]. + * The remote fallback must stream into the response's own OutputStream: the delegate must not + * buffer the archive (the OOM shape this PR removes) and must not wrap the stream. The + * byte-level "bounded writes, never one giant array" property is asserted where it actually + * lives: {@code RemoteLogClientTest#streamWholeLog_largeArchive_writesInBoundedChunks}. */ @Test - public void testStreamWholeLogRemoteFallbackIsChunked() throws Exception { + public void testStreamWholeLogRemoteFallbackWritesStraightToTheResponseStream() throws Exception { TaskInstance ti = newTaskInstance(); when(registryClient.checkNodeExists(eq(ti.getHost()), any())).thenReturn(true); when(localLogClient.getLogChunk(eq(ti), anyLong(), anyInt())) .thenReturn(new TaskInstanceLogFileDownloadResponse(null, LogResponseStatus.ERROR, "down", true)); - // Count how many times the mocked remote stream writes to the output stream. - // A byte[]-based implementation would write once; a chunked stream writes many times. - final int[] writeCallCount = {0}; + final OutputStream[] streamHandedToRemote = new OutputStream[1]; doAnswer(invocation -> { OutputStream out = invocation.getArgument(1); - // Simulate a 3-chunk stream of a large log. - for (int i = 0; i < 3; i++) { - out.write(new byte[]{0x01, 0x02}); - writeCallCount[0]++; - } + streamHandedToRemote[0] = out; + out.write(new byte[]{0x01, 0x02, 0x03}); return null; }).when(remoteLogClient).streamWholeLog(eq(ti), any(OutputStream.class)); ByteArrayOutputStream out = new ByteArrayOutputStream(); logClientDelegate.streamWholeLog(ti, out); - assertEquals(3, writeCallCount[0]); - assertEquals(6, out.toByteArray().length); + assertSame(out, streamHandedToRemote[0], + "the fallback must write into the response stream itself, not an intermediate buffer"); + assertArrayEquals(new byte[]{0x01, 0x02, 0x03}, out.toByteArray()); } private void mockRemoteStream(TaskInstance ti, byte[] data) throws IOException { diff --git a/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/RemoteLogClientTest.java b/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/RemoteLogClientTest.java index 1cf5f555cbe2..62a110eadc58 100644 --- a/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/RemoteLogClientTest.java +++ b/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/RemoteLogClientTest.java @@ -19,10 +19,13 @@ import static org.junit.jupiter.api.Assertions.assertArrayEquals; import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertNotSame; import static org.junit.jupiter.api.Assertions.assertNull; +import static org.junit.jupiter.api.Assertions.assertSame; import static org.junit.jupiter.api.Assertions.assertThrows; import static org.junit.jupiter.api.Assertions.assertTrue; +import org.apache.dolphinscheduler.common.log.remote.RemoteLogUtils; import org.apache.dolphinscheduler.dao.entity.TaskInstance; import java.io.ByteArrayInputStream; @@ -32,15 +35,21 @@ import java.nio.charset.StandardCharsets; import java.nio.file.Files; import java.nio.file.Path; +import java.util.ArrayList; +import java.util.Collections; +import java.util.List; import java.util.concurrent.CountDownLatch; import java.util.concurrent.ExecutorService; import java.util.concurrent.Executors; import java.util.concurrent.Future; import java.util.concurrent.TimeUnit; +import java.util.concurrent.locks.ReentrantLock; import java.util.stream.Stream; import org.junit.jupiter.api.Test; import org.junit.jupiter.api.io.TempDir; +import org.mockito.MockedStatic; +import org.mockito.Mockito; public class RemoteLogClientTest { @@ -204,29 +213,149 @@ public void write(final byte[] b, final int off, final int len) throws IOExcepti } /** - * The startup sweep deletes snapshot files orphaned by a previous JVM life, keeps snapshots - * younger than the age gate (another live instance's in-flight transfer on a shared disk) - * and keeps ordinary log files. + * A remote download failure must FAIL the request — even when a complete archive is already + * cached at the log path. Snapshotting whatever file happens to sit there would report a + * failed (possibly truncated) download as a successful response. */ @Test - public void deleteOrphanedSnapshots_removesOnlyAgedSnapshots(@TempDir Path tempDir) throws Exception { + public void streamWholeLog_remoteDownloadFailure_propagatesAndLeavesArchiveUntouched(@TempDir Path tempDir) throws Exception { + final Path logFile = tempDir.resolve("task.log"); + final byte[] cached = "previously published complete log".getBytes(StandardCharsets.UTF_8); + Files.write(logFile, cached); + + final RemoteLogClient client = new RemoteLogClient(); + final ByteArrayOutputStream out = new ByteArrayOutputStream(); + try (MockedStatic remoteLogUtils = Mockito.mockStatic(RemoteLogUtils.class)) { + remoteLogUtils.when(() -> RemoteLogUtils.getRemoteLog(logFile.toString())) + .thenThrow(new IOException("connection reset mid-transfer")); + + final IOException thrown = assertThrows(IOException.class, + () -> client.streamWholeLog(taskInstance(logFile.toString()), out)); + assertEquals("connection reset mid-transfer", thrown.getMessage()); + } + + assertEquals(0, out.toByteArray().length, "A failed download must stream nothing"); + assertArrayEquals(cached, Files.readAllBytes(logFile), + "A failed download must not touch the cached archive"); + assertOnlyArchiveRemains(tempDir); + } + + /** + * The archive is copied to the response in bounded buffers — never in a single write of the + * whole file. This is the memory property the chunked download exists for; a rewrite that + * materializes the file (or hands one giant array to {@code write}) fails here. + */ + @Test + public void streamWholeLog_largeArchive_writesInBoundedChunks(@TempDir Path tempDir) throws Exception { + final Path logFile = tempDir.resolve("big.log"); + final byte[] content = patternedBytes(512 * 1024, 251); + Files.write(logFile, content); + + final List writeSizes = new ArrayList<>(); + final ByteArrayOutputStream received = new ByteArrayOutputStream(); + final OutputStream boundedRecorder = new OutputStream() { + + @Override + public void write(final int b) { + throw new AssertionError("the streaming copy must use bulk writes"); + } + + @Override + public void write(final byte[] b, final int off, final int len) { + writeSizes.add(len); + received.write(b, off, len); + } + }; + + new RemoteLogClient().streamWholeLog(taskInstance(logFile.toString()), boundedRecorder); + + assertEquals(content.length, received.size(), "the full archive must arrive"); + assertTrue(writeSizes.size() > 1, "the archive must be streamed in multiple writes"); + assertTrue(Collections.max(writeSizes) < content.length, + "no single write may carry the whole file, but one carried " + Collections.max(writeSizes) + " bytes"); + } + + /** + * The startup sweep deletes per-download temp files (snapshots or handler staging files) + * orphaned by a previous JVM life, keeps files younger than the age gate (another live + * instance's in-flight transfer on a shared disk) and keeps ordinary log files. + */ + @Test + public void deleteOrphanedTempFiles_removesOnlyAgedOrphans(@TempDir Path tempDir) throws Exception { final Path oldOrphan = tempDir.resolve("task.log.download-1111"); Files.write(oldOrphan, new byte[]{1}); - final Path freshSnapshot = tempDir.resolve("task.log.download-2222"); - Files.write(freshSnapshot, new byte[]{2}); + final Path freshTemp = tempDir.resolve("task.log.download-2222"); + Files.write(freshTemp, new byte[]{2}); final Path ordinaryLog = tempDir.resolve("task.log"); Files.write(ordinaryLog, new byte[]{3}); // Age the first file past the orphan threshold. oldOrphan.toFile().setLastModified(System.currentTimeMillis() - 2 * 60 * 60 * 1000L); final RemoteLogClient client = new RemoteLogClient(); - client.deleteOrphanedSnapshots(tempDir); + client.deleteOrphanedTempFiles(tempDir); assertTrue(Files.notExists(oldOrphan), "Aged orphan must be swept"); - assertTrue(Files.exists(freshSnapshot), "Snapshot within the age gate must be kept"); + assertTrue(Files.exists(freshTemp), "Temp file within the age gate must be kept"); assertTrue(Files.exists(ordinaryLog), "Ordinary log files must never be swept"); } + /** + * Requests for the same log coalesce on one lock: the second request waits for the in-flight + * download instead of re-downloading a possibly multi-GB archive. + */ + @Test + public void logPathLockFor_samePath_coalescesOnTheSameLock() { + final String path = "/tmp/coalesce.log"; + final ReentrantLock first = RemoteLogClient.lockFor(path); + try { + assertSame(first, RemoteLogClient.lockFor(path), + "requests for the same log must coalesce on the same lock"); + } finally { + RemoteLogClient.unlockFor(path); + RemoteLogClient.unlockFor(path); + } + } + + /** + * Requests for different logs never wait behind each other — the previous fixed stripe array + * made unrelated logs sharing a hash stripe block for a whole remote download. + */ + @Test + public void logPathLockFor_differentPaths_neverBlockEachOther() throws Exception { + final String held = "/tmp/held.log"; + final String other = "/tmp/other.log"; + final ReentrantLock heldLock = RemoteLogClient.lockFor(held); + heldLock.lock(); + try { + final ReentrantLock otherLock = RemoteLogClient.lockFor(other); + try { + assertTrue(otherLock.tryLock(5, TimeUnit.SECONDS), + "an unrelated log must never wait behind another log's download"); + } finally { + otherLock.unlock(); + } + } finally { + heldLock.unlock(); + RemoteLogClient.unlockFor(held); + RemoteLogClient.unlockFor(other); + } + } + + /** The lock entries must not leak: the entry is dropped with its last user. */ + @Test + public void logPathLockFor_lastUserRelease_removesTheEntry() { + final String path = "/tmp/released.log"; + final ReentrantLock first = RemoteLogClient.lockFor(path); + RemoteLogClient.unlockFor(path); + + final ReentrantLock second = RemoteLogClient.lockFor(path); + try { + assertNotSame(first, second, "the entry must be removed once the last user releases it"); + } finally { + RemoteLogClient.unlockFor(path); + } + } + private static TaskInstance taskInstance(final String logPath) { final TaskInstance taskInstance = new TaskInstance(); taskInstance.setId(1); diff --git a/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/RollingUpgradeLogStreamingIntegrationTest.java b/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/RollingUpgradeLogStreamingIntegrationTest.java index 2638cdfaf11c..f10f945e4ce4 100644 --- a/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/RollingUpgradeLogStreamingIntegrationTest.java +++ b/dolphinscheduler-api/src/test/java/org/apache/dolphinscheduler/api/executor/logging/RollingUpgradeLogStreamingIntegrationTest.java @@ -19,6 +19,7 @@ import static org.junit.jupiter.api.Assertions.assertArrayEquals; import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertFalse; import static org.junit.jupiter.api.Assertions.assertThrows; import static org.junit.jupiter.api.Assertions.assertTrue; import static org.mockito.ArgumentMatchers.any; @@ -30,6 +31,8 @@ import static org.mockito.Mockito.when; import org.apache.dolphinscheduler.dao.entity.TaskInstance; +import org.apache.dolphinscheduler.extract.base.RpcMethod; +import org.apache.dolphinscheduler.extract.base.RpcService; import org.apache.dolphinscheduler.extract.base.config.NettyServerConfig; import org.apache.dolphinscheduler.extract.base.server.SpringServerMethodInvokerDiscovery; import org.apache.dolphinscheduler.extract.common.ILogService; @@ -61,11 +64,15 @@ /** * Rolling-upgrade regression test for chunked log streaming. * - *

    Simulates an OLD worker (deployed before this feature) behind a real Netty RPC server and a - * real RPC client. The old worker would happily answer the legacy whole-file RPC (it counts and - * would return the full payload), but it does not implement the chunked log download RPC — from - * the client's perspective this is indistinguishable from the real deployed old worker, whose - * server replies "Cannot find the ServerMethodInvoker" for the chunk method. + *

    Two worker simulations run behind a real Netty RPC server with a real RPC client: + *

      + *
    • a stub worker whose chunk call fails server-side while the legacy whole-file RPC still + * works (it counts invocations and returns the full payload) — a current worker under + * stress, and the strongest guard for "the whole-file payload is NEVER requested";
      • + *
    • a server registered WITHOUT any log RPC, which is what a genuinely outdated worker + * answers: "Cannot find the ServerMethodInvoker" — the typed not-found signal + * ({@code MethodNotFoundException}) that alone justifies the upgrade guidance.
      • + *
    * *

    The regression under test (issue #18459 review): a large log must NEVER be requested from the * old worker via the whole-file payload — that RPC reads the entire file into the worker's heap @@ -76,6 +83,18 @@ @MockitoSettings(strictness = Strictness.LENIENT) class RollingUpgradeLogStreamingIntegrationTest { + /** + * A server-side interface with NO log RPC at all. Calling the chunk method against a server + * registered with it finds no invoker — exactly what a REAL old worker (whose ILogService + * predates the chunk method) answers: "Cannot find the ServerMethodInvoker of ...". + */ + @RpcService + interface UnrelatedWorkerService { + + @RpcMethod + String ping(); + } + /** * Larger than the 8 MB chunk size: exercises the "large log" path the reviewer is concerned * about. @@ -131,12 +150,11 @@ void setUp() throws IOException { (proxy, method, args) -> { switch (method.getName()) { case "getTaskInstanceLogFileChunk": - // Old worker does not implement the chunked log download RPC. A real - // old worker fails with "Cannot find the ServerMethodInvoker"; throwing - // here is wire-equivalent from the client's perspective (both come back - // as a failed RPC → MethodInvocationException). + // The stub worker's chunk call fails server-side (a current worker + // whose log RPC threw). The genuinely-missing-method signal of a REAL + // old worker is modelled by the unrelated-server test. throw new UnsupportedOperationException( - "simulated old worker: chunked log RPC not implemented"); + "simulated worker: chunked log RPC failed"); case "getTaskInstanceWholeLogFileBytes": wholeFileRpcInvocations.incrementAndGet(); return new TaskInstanceLogFileDownloadResponse( @@ -196,12 +214,14 @@ void oldWorkerLargeLogStreamedFromRemoteStorageNeverWholeFileRpc() throws Except } /** - * Rolling upgrade, old worker, remote log storage UNAVAILABLE (not enabled / archive missing, - * the default deployment): the download fails with the explicit "worker upgrade required" - * error — and still never asks the old worker for the whole-file payload. + * The worker HAS the chunk method but the call fails on the server side (the log RPC throws) + * and remote log storage is UNAVAILABLE: the download fails with an explicit error reporting + * the worker-side failure — and still never asks the worker for the whole-file payload. The + * upgrade guidance must NOT appear here: the worker answered, it is not outdated. Only a + * worker that does not have the method is (see the missing-method test below). */ @Test - void oldWorkerLargeLogWithoutRemoteArchiveFailsWithExplicitUpgradeError() throws Exception { + void workerAnsweredChunkFailureWithoutRemoteArchiveFailsWithExplicitError() throws Exception { final TaskInstance taskInstance = newTaskInstance(); when(registryClient.checkNodeExists(eq(taskInstance.getHost()), any(RegistryNodeType.class))) .thenReturn(true); @@ -213,10 +233,51 @@ void oldWorkerLargeLogWithoutRemoteArchiveFailsWithExplicitUpgradeError() throws final IOException thrown = assertThrows(IOException.class, () -> logClientDelegate.streamWholeLog(taskInstance, out)); - assertTrue(thrown.getMessage().contains("upgrade required"), - "Error must contain the explicit upgrade guidance, got: " + thrown.getMessage()); + assertTrue(thrown.getMessage().contains("the worker answered with an error"), + "A worker that answered and failed must be reported as such, got: " + thrown.getMessage()); + assertFalse(thrown.getMessage().contains("upgrade required"), + "A current worker whose invocation failed must not be reported as needing an upgrade, got: " + + thrown.getMessage()); assertEquals(0, out.toByteArray().length); assertEquals(0, wholeFileRpcInvocations.get(), - "the old worker must NEVER be asked for the whole-file payload on the large-log path"); + "the worker must NEVER be asked for the whole-file payload on the large-log path"); + } + + /** + * The genuine missing-method signal over the real wire: the worker's ILogService does not + * have the chunk method at all (a REAL old worker), the server answers "Cannot find the + * ServerMethodInvoker" with the typed not-found flag, and with remote storage unavailable + * the download fails with the explicit "worker upgrade required" guidance. + */ + @Test + void missingChunkMethodWorkerWithoutRemoteArchiveFailsWithExplicitUpgradeError() throws Exception { + final int port; + try (ServerSocket s = new ServerSocket(0)) { + port = s.getLocalPort(); + } + final SpringServerMethodInvokerDiscovery unrelatedServer = new SpringServerMethodInvokerDiscovery( + NettyServerConfig.builder().serverName("TestUnrelatedWorkerLogServer").listenPort(port).build()); + unrelatedServer.registerServerMethodInvokerProvider((UnrelatedWorkerService) () -> "pong"); + unrelatedServer.start(); + try { + final TaskInstance taskInstance = newTaskInstance(); + taskInstance.setHost("127.0.0.1:" + port); + when(registryClient.checkNodeExists(eq(taskInstance.getHost()), any(RegistryNodeType.class))) + .thenReturn(true); + doThrow(new IOException("Remote log file not found after download (remote log archiving may not be " + + "enabled or the archive is missing): " + taskInstance.getLogPath())) + .when(remoteLogClient).streamWholeLog(eq(taskInstance), any(OutputStream.class)); + + final ByteArrayOutputStream out = new ByteArrayOutputStream(); + final IOException thrown = assertThrows(IOException.class, + () -> logClientDelegate.streamWholeLog(taskInstance, out)); + + assertTrue(thrown.getMessage().contains("upgrade required"), + "A worker that does not have the chunk method must yield the upgrade guidance, got: " + + thrown.getMessage()); + assertEquals(0, out.toByteArray().length); + } finally { + unrelatedServer.close(); + } } } diff --git a/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/AbsRemoteLogHandler.java b/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/AbsRemoteLogHandler.java index c0df3f6287c7..816f7808cf00 100644 --- a/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/AbsRemoteLogHandler.java +++ b/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/AbsRemoteLogHandler.java @@ -28,6 +28,7 @@ import lombok.extern.slf4j.Slf4j; +import com.azure.storage.blob.BlobClient; import com.azure.storage.blob.BlobContainerClient; import com.azure.storage.blob.BlobServiceClient; import com.azure.storage.blob.BlobServiceClientBuilder; @@ -103,24 +104,31 @@ public void sendRemoteLog(String logPath) { } @Override - public void getRemoteLog(String logPath) { + public void getRemoteLog(String logPath) throws IOException { String objectName = RemoteLogUtils.getObjectNameFromLogPath(logPath); + log.info("get remote log on Azure Blob {} to {}", objectName, logPath); - try { - log.info("get remote log on Azure Blob {} to {}", objectName, logPath); - + RemoteLogUtils.downloadToLocalFileAtomically(logPath, staging -> { + BlobClient blobClient = blobContainerClient.getBlobClient(objectName); try ( - BlobInputStream bis = blobContainerClient.getBlobClient(objectName).openInputStream(); - FileOutputStream fos = new FileOutputStream(logPath)) { + BlobInputStream bis = blobClient.openInputStream(); + FileOutputStream fos = new FileOutputStream(staging.toFile())) { + final long expectedLength = bis.getProperties().getBlobSize(); + long writtenLength = 0; byte[] readBuf = new byte[1024]; int readLen = 0; while ((readLen = bis.read(readBuf)) > 0) { fos.write(readBuf, 0, readLen); + writtenLength += readLen; + } + if (expectedLength >= 0 && writtenLength != expectedLength) { + // The SDK normally fails the read on a broken transfer; this check guarantees + // that a short stream can never be published as a complete log either way. + throw new IOException("Truncated download of the remote log on Azure Blob " + objectName + + ": expected " + expectedLength + " bytes but received " + writtenLength); } } - } catch (Exception e) { - log.error("error while getting remote log on Azure Blob {} to {}", objectName, logPath, e); - } + }); } protected String readAccountName() { diff --git a/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/CosRemoteLogHandler.java b/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/CosRemoteLogHandler.java index 09b2c774c25f..ade714cafb47 100644 --- a/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/CosRemoteLogHandler.java +++ b/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/CosRemoteLogHandler.java @@ -79,15 +79,12 @@ public void sendRemoteLog(String logPath) { } @Override - public void getRemoteLog(String logPath) { + public void getRemoteLog(String logPath) throws IOException { String objectName = RemoteLogUtils.getObjectNameFromLogPath(logPath); + log.info("get remote log from tencent cos {} to {}", objectName, logPath); - try { - log.info("get remote log from tencent cos {} to {}", objectName, logPath); - cosClient.getObject(new GetObjectRequest(bucketName, objectName), new File(logPath)); - } catch (Exception e) { - log.error("error while sending remote log from {} to tencent cos {}, reason:", objectName, logPath, e); - } + RemoteLogUtils.downloadToLocalFileAtomically(logPath, + staging -> cosClient.getObject(new GetObjectRequest(bucketName, objectName), staging.toFile())); } @Override diff --git a/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/GcsRemoteLogHandler.java b/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/GcsRemoteLogHandler.java index ad6e534251e6..fdd5b50ec8ea 100644 --- a/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/GcsRemoteLogHandler.java +++ b/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/GcsRemoteLogHandler.java @@ -96,17 +96,17 @@ public void sendRemoteLog(String logPath) { } @Override - public void getRemoteLog(String logPath) { + public void getRemoteLog(String logPath) throws IOException { String objectName = RemoteLogUtils.getObjectNameFromLogPath(logPath); + log.info("get remote log on GCS {} to {}", objectName, logPath); - try { - log.info("get remote log on GCS {} to {}", objectName, logPath); - + RemoteLogUtils.downloadToLocalFileAtomically(logPath, staging -> { Blob blob = gcsStorage.get(BlobId.of(bucketName, objectName)); - blob.downloadTo(Paths.get(logPath)); - } catch (Exception e) { - log.error("error while getting remote log on GCS {} to {}", objectName, logPath, e); - } + if (blob == null) { + throw new IOException("Remote log object not found on GCS: " + objectName); + } + blob.downloadTo(staging); + }); } protected Storage buildGcsStorage(String credential) throws IOException { diff --git a/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/OssRemoteLogHandler.java b/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/OssRemoteLogHandler.java index 59b139451520..202abbe76dd8 100644 --- a/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/OssRemoteLogHandler.java +++ b/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/OssRemoteLogHandler.java @@ -75,15 +75,12 @@ public void sendRemoteLog(String logPath) { } @Override - public void getRemoteLog(String logPath) { + public void getRemoteLog(String logPath) throws IOException { String objectName = RemoteLogUtils.getObjectNameFromLogPath(logPath); + log.info("get remote log on OSS {} to {}", objectName, logPath); - try { - log.info("get remote log on OSS {} to {}", objectName, logPath); - ossClient.getObject(new GetObjectRequest(bucketName, objectName), new File(logPath)); - } catch (Exception e) { - log.error("error while getting remote log on OSS {} to {}", objectName, logPath, e); - } + RemoteLogUtils.downloadToLocalFileAtomically(logPath, + staging -> ossClient.getObject(new GetObjectRequest(bucketName, objectName), staging.toFile())); } @Override diff --git a/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/RemoteLogHandler.java b/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/RemoteLogHandler.java index 46269243042d..40fb236a6207 100644 --- a/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/RemoteLogHandler.java +++ b/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/RemoteLogHandler.java @@ -17,9 +17,25 @@ package org.apache.dolphinscheduler.common.log.remote; +import java.io.IOException; + public interface RemoteLogHandler { void sendRemoteLog(String logPath); - void getRemoteLog(String logPath); + /** + * Downloads the remote archived log to {@code logPath}. + * + *

    Implementations MUST NOT leave a partially downloaded file at {@code logPath}: the + * download is written to a private staging file and published to {@code logPath} only after + * the transfer completed — implementations should use + * {@link RemoteLogUtils#downloadToLocalFileAtomically(String, RemoteLogUtils.RemoteLogDownloader)}. + * + *

    Failures MUST propagate as {@link IOException}: swallowing them lets the API serve a + * failed (or truncated) download as a successful one. + * + * @throws IOException if the remote object cannot be downloaded; the file at {@code logPath} + * (if any) is left untouched + */ + void getRemoteLog(String logPath) throws IOException; } diff --git a/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/RemoteLogUtils.java b/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/RemoteLogUtils.java index 25d80244740e..7c011653d6d6 100644 --- a/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/RemoteLogUtils.java +++ b/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/RemoteLogUtils.java @@ -22,8 +22,15 @@ import org.apache.dolphinscheduler.common.constants.Constants; import org.apache.dolphinscheduler.common.utils.PropertyUtils; +import java.io.IOException; +import java.nio.file.AtomicMoveNotSupportedException; +import java.nio.file.FileAlreadyExistsException; +import java.nio.file.Files; import java.nio.file.Path; import java.nio.file.Paths; +import java.nio.file.StandardCopyOption; +import java.util.UUID; +import java.util.stream.Stream; import javax.annotation.PostConstruct; @@ -36,6 +43,22 @@ @Slf4j public class RemoteLogUtils { + /** + * Marker of the per-download temporary files created next to a log archive + * ({@code .download-}): the staging file a remote handler downloads into before + * publishing it, and the private streaming snapshot of {@code RemoteLogClient}. The API + * server's startup sweep recognizes leftovers of both kinds (a JVM killed mid-transfer cannot + * run its cleanup) by this marker. + */ + public static final String DOWNLOAD_TEMP_FILE_MARKER = ".download-"; + + /** + * Minimum age of an orphaned per-download temp file before it may be swept: on the + * (unsupported but possible) shared-disk setup the age gate protects another live API + * instance's in-flight transfer. + */ + public static final long ORPHAN_DOWNLOAD_TEMP_MIN_AGE_MILLIS = 60 * 60 * 1000L; + private static RemoteLogService remoteLogService; @Autowired @@ -53,22 +76,139 @@ public static void sendRemoteLog(String logPath) { } } - public static void getRemoteLog(String logPath) { + /** + * Downloads the remote archived log to its local path. + * + *

    A failed download propagates as {@link IOException} — a failed (possibly truncated) + * transfer must never be silently treated as a usable local log. The archive is only replaced + * once a download completed in full, see + * {@link #downloadToLocalFileAtomically(String, RemoteLogDownloader)}. + */ + public static void getRemoteLog(String logPath) throws IOException { if (isRemoteLoggingEnable()) { log.info("Start to get log {} from remote target {}", logPath, PropertyUtils.getString(Constants.REMOTE_LOGGING_TARGET)); mkdirOfLog(logPath); + // Opportunistic cleanup of leftovers next to the archive. The API's startup sweep + // walks the local log base dir, but archives are downloaded to the task's log path, + // which may live under a different component's directory (e.g. worker-server/logs on + // the API host) — a JVM killed mid-transfer would otherwise leak its staging file + // there forever, because no request ever touches the log base dir it was swept from. + deleteAgedDownloadTempFiles(Paths.get(logPath).toAbsolutePath().getParent()); RemoteLogHandler remoteLogHandler = RemoteLogHandlerFactory.getRemoteLogHandler(); if (remoteLogHandler == null) { return; } - remoteLogHandler.getRemoteLog(logPath); + try { + remoteLogHandler.getRemoteLog(logPath); + } catch (IOException e) { + log.error("Failed to get log {} from remote target {}", logPath, + PropertyUtils.getString(Constants.REMOTE_LOGGING_TARGET), e); + throw e; + } log.info("End get log {} from remote target {}", logPath, PropertyUtils.getString(Constants.REMOTE_LOGGING_TARGET)); } } + /** + * Provider-specific part of a remote log download: write the complete remote object to + * {@code stagingFile}. The staging file is private to the download — publishing it as the + * local archive is done by {@link #downloadToLocalFileAtomically}. + */ + @FunctionalInterface + interface RemoteLogDownloader { + + void downloadTo(Path stagingFile) throws Exception; + } + + /** + * Downloads a remote log into a private staging file next to {@code logPath} and publishes it + * with an atomic move, so the archive is only ever replaced by a COMPLETE download: + *

      + *
    • the staging file never appears at {@code logPath} — a reader observes the previously + * published complete archive or the new one, never a partial transfer;
      • + *
    • a failed download removes the staging file, leaves an existing cached archive + * untouched, and propagates as {@link IOException}.
      • + *
    + * A staging file orphaned by a JVM dying mid-transfer is recognized by + * {@link #DOWNLOAD_TEMP_FILE_MARKER} and swept at API server startup, and opportunistically + * before each download (see {@link #deleteAgedDownloadTempFiles(Path)}). + */ + static void downloadToLocalFileAtomically(final String logPath, + final RemoteLogDownloader downloader) throws IOException { + final Path archive = Paths.get(logPath); + final Path staging = + archive.resolveSibling(archive.getFileName() + DOWNLOAD_TEMP_FILE_MARKER + UUID.randomUUID()); + try { + downloader.downloadTo(staging); + publishAtomically(staging, archive); + } catch (Exception e) { + // The archive is deliberately left as it was — a previously published complete + // download, or nothing at all. A failed transfer must never be published. + if (e instanceof IOException) { + throw (IOException) e; + } + throw new IOException("Failed to download remote log " + logPath + + "; the local archive was not modified", e); + } finally { + // After a successful publish the staging file no longer exists (it was moved), so this + // only removes a partial download. Never throws — it runs in a finally block and must + // not mask the download's own failure. + deleteTempFileQuietly(staging); + } + } + + private static void publishAtomically(final Path staging, final Path archive) throws IOException { + try { + Files.move(staging, archive, StandardCopyOption.ATOMIC_MOVE, StandardCopyOption.REPLACE_EXISTING); + } catch (AtomicMoveNotSupportedException | FileAlreadyExistsException e) { + // Some filesystems cannot move atomically, and on Windows an atomic move refuses to + // replace an existing file (REPLACE_EXISTING is ignored). The staging file is a + // sibling of the archive, so this fallback is still a same-filesystem replace, never + // a cross-device copy that a reader could observe partially. + Files.move(staging, archive, StandardCopyOption.REPLACE_EXISTING); + } + } + + private static void deleteTempFileQuietly(final Path tempFile) { + try { + Files.deleteIfExists(tempFile); + } catch (Throwable e) { + // Throwable, not IOException: this runs in a finally block and must never throw + // through it (masking the download's own failure). A leftover file is swept at startup. + log.warn("Failed to delete the log download temp file {}", tempFile, e); + } + } + + /** + * Best-effort deletion of per-download temp files (streaming snapshots or handler staging + * files, see {@link #DOWNLOAD_TEMP_FILE_MARKER}) in {@code dir} that are older than the age + * gate. Called before every download so leftovers are cleaned in the directory that actually + * holds the archive, not only in the API's local log base dir (see {@link #getRemoteLog}). + */ + public static void deleteAgedDownloadTempFiles(final Path dir) { + if (dir == null) { + return; + } + try (Stream files = Files.list(dir)) { + files.filter(Files::isRegularFile) + .filter(file -> file.getFileName().toString().contains(DOWNLOAD_TEMP_FILE_MARKER)) + .filter(RemoteLogUtils::olderThanOrphanAge) + .forEach(RemoteLogUtils::deleteTempFileQuietly); + } catch (Exception e) { + log.warn("Failed to sweep aged log download temp files under {}", dir, e); + } + } + + private static boolean olderThanOrphanAge(final Path file) { + // java.io.File#lastModified returns 0 when the time cannot be read — treat that as + // "unknown age, keep it" rather than sweeping blindly. + final long lastModified = file.toFile().lastModified(); + return lastModified > 0 && lastModified < System.currentTimeMillis() - ORPHAN_DOWNLOAD_TEMP_MIN_AGE_MILLIS; + } + private static void mkdirOfLog(String logPath) { Path directory = Paths.get(logPath).getParent(); directory.toFile().mkdirs(); diff --git a/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/S3RemoteLogHandler.java b/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/S3RemoteLogHandler.java index 4fef7b032a59..2bc526cfe640 100644 --- a/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/S3RemoteLogHandler.java +++ b/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/log/remote/S3RemoteLogHandler.java @@ -81,24 +81,31 @@ public void sendRemoteLog(String logPath) { } @Override - public void getRemoteLog(String logPath) { + public void getRemoteLog(String logPath) throws IOException { String objectName = RemoteLogUtils.getObjectNameFromLogPath(logPath); + log.info("get remote log on S3 {} to {}", objectName, logPath); - try { - log.info("get remote log on S3 {} to {}", objectName, logPath); + RemoteLogUtils.downloadToLocalFileAtomically(logPath, staging -> { S3Object o = s3Client.getObject(bucketName, objectName); + final long expectedLength = o.getObjectMetadata().getContentLength(); + long writtenLength = 0; try ( S3ObjectInputStream s3is = o.getObjectContent(); - FileOutputStream fos = new FileOutputStream(logPath)) { + FileOutputStream fos = new FileOutputStream(staging.toFile())) { byte[] readBuf = new byte[1024]; int readLen = 0; while ((readLen = s3is.read(readBuf)) > 0) { fos.write(readBuf, 0, readLen); + writtenLength += readLen; } } - } catch (Exception e) { - log.error("error while getting remote log on S3 {} to {}", objectName, logPath, e); - } + if (expectedLength >= 0 && writtenLength != expectedLength) { + // The SDK normally fails the read on a broken transfer; this check guarantees that + // a short stream can never be published as a complete log either way. + throw new IOException("Truncated download of the remote log on S3 " + objectName + ": expected " + + expectedLength + " bytes but received " + writtenLength); + } + }); } protected String readBucketName() { diff --git a/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/utils/LogUtils.java b/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/utils/LogUtils.java index bebc90881369..879381993a1a 100644 --- a/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/utils/LogUtils.java +++ b/dolphinscheduler-common/src/main/java/org/apache/dolphinscheduler/common/utils/LogUtils.java @@ -76,7 +76,14 @@ public static List readPartFileContentFromLocal(String filePath, public static List readPartFileContentFromRemote(String filePath, int skipLine, int limit) { - RemoteLogUtils.getRemoteLog(filePath); + try { + RemoteLogUtils.getRemoteLog(filePath); + } catch (IOException e) { + // The view path reports failures as runtime exceptions (see + // readPartFileContentFromLocal); a failed download must never fall through to reading + // a stale or partial local file. + throw new RuntimeException(String.format("Get remote log file: %s error", filePath), e); + } return readPartFileContentFromLocal(filePath, skipLine, limit); } diff --git a/dolphinscheduler-common/src/test/java/org/apache/dolphinscheduler/common/log/remote/RemoteLogUtilsTest.java b/dolphinscheduler-common/src/test/java/org/apache/dolphinscheduler/common/log/remote/RemoteLogUtilsTest.java new file mode 100644 index 000000000000..3cbe505d6b7f --- /dev/null +++ b/dolphinscheduler-common/src/test/java/org/apache/dolphinscheduler/common/log/remote/RemoteLogUtilsTest.java @@ -0,0 +1,189 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.apache.dolphinscheduler.common.log.remote; + +import static org.junit.jupiter.api.Assertions.assertArrayEquals; +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertThrows; +import static org.junit.jupiter.api.Assertions.assertTrue; + +import org.apache.dolphinscheduler.common.constants.Constants; +import org.apache.dolphinscheduler.common.utils.PropertyUtils; + +import java.io.IOException; +import java.nio.charset.StandardCharsets; +import java.nio.file.Files; +import java.nio.file.Path; +import java.util.stream.Stream; + +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.io.TempDir; +import org.mockito.MockedStatic; +import org.mockito.Mockito; + +/** + * Contract of the atomic download helper every remote handler publishes through: the archive is + * only ever replaced by a COMPLETE download, and a failed transfer propagates instead of leaving + * a partial file behind. + */ +public class RemoteLogUtilsTest { + + @Test + public void downloadToLocalFileAtomically_completeTransferPublishesArchive(@TempDir Path tempDir) throws Exception { + final Path archive = tempDir.resolve("task.log"); + final byte[] content = "complete remote log".getBytes(StandardCharsets.UTF_8); + + RemoteLogUtils.downloadToLocalFileAtomically(archive.toString(), staging -> Files.write(staging, content)); + + assertArrayEquals(content, Files.readAllBytes(archive)); + assertEquals(1, fileCount(tempDir), "Only the published archive must remain"); + } + + @Test + public void downloadToLocalFileAtomically_completeTransferReplacesExistingArchive(@TempDir Path tempDir) throws Exception { + final Path archive = tempDir.resolve("task.log"); + Files.write(archive, "previously published log".getBytes(StandardCharsets.UTF_8)); + final byte[] fresh = "freshly downloaded log".getBytes(StandardCharsets.UTF_8); + + RemoteLogUtils.downloadToLocalFileAtomically(archive.toString(), staging -> Files.write(staging, fresh)); + + assertArrayEquals(fresh, Files.readAllBytes(archive)); + assertEquals(1, fileCount(tempDir), "Only the published archive must remain"); + } + + /** + * A transfer failing mid-way must not publish anything: the archive is absent, the partial + * staging file is deleted, and the failure propagates so the download is not reported as a + * successful one. + */ + @Test + public void downloadToLocalFileAtomically_midTransferFailure_publishesNothing(@TempDir Path tempDir) { + final Path archive = tempDir.resolve("task.log"); + + final IOException thrown = assertThrows(IOException.class, + () -> RemoteLogUtils.downloadToLocalFileAtomically(archive.toString(), staging -> { + Files.write(staging, "partial download".getBytes(StandardCharsets.UTF_8)); + throw new IOException("connection reset mid-transfer"); + })); + + assertEquals("connection reset mid-transfer", thrown.getMessage()); + assertTrue(Files.notExists(archive), "A failed download must never be published"); + assertEquals(0, fileCount(tempDir), "The partial staging file must be deleted"); + } + + /** + * A failed re-download must leave an already cached archive byte-identical: the previously + * published complete download must not be replaced by a partial transfer. + */ + @Test + public void downloadToLocalFileAtomically_midTransferFailure_keepsExistingCachedArchive(@TempDir Path tempDir) throws Exception { + final Path archive = tempDir.resolve("task.log"); + final byte[] cached = "previously published complete log".getBytes(StandardCharsets.UTF_8); + Files.write(archive, cached); + + assertThrows(IOException.class, + () -> RemoteLogUtils.downloadToLocalFileAtomically(archive.toString(), staging -> { + Files.write(staging, "partial".getBytes(StandardCharsets.UTF_8)); + throw new IOException("connection reset mid-transfer"); + })); + + assertArrayEquals(cached, Files.readAllBytes(archive), + "The cached archive must not be touched by a failed download"); + assertEquals(1, fileCount(tempDir), "Only the cached archive must remain"); + } + + /** + * A provider reporting a missing object with a runtime exception (e.g. the GCS null-blob + * case) must surface as a download failure, never as a successful empty download. + */ + @Test + public void downloadToLocalFileAtomically_runtimeFailure_isWrappedAsIOException(@TempDir Path tempDir) { + final Path archive = tempDir.resolve("task.log"); + + final IOException thrown = assertThrows(IOException.class, + () -> RemoteLogUtils.downloadToLocalFileAtomically(archive.toString(), staging -> { + throw new IllegalStateException("object not found"); + })); + + assertEquals("object not found", thrown.getCause().getMessage()); + assertTrue(Files.notExists(archive)); + assertEquals(0, fileCount(tempDir)); + } + + /** + * The per-download sweep must delete only per-download temp files (snapshot or staging, the + * marker decides) that are past the age gate — a freshly created temp file may belong to an + * in-flight transfer and ordinary log files are never touched. + */ + @Test + public void deleteAgedDownloadTempFiles_removesOnlyAgedTempFiles(@TempDir Path dir) throws Exception { + final Path agedTemp = Files.write(dir.resolve("1.log" + RemoteLogUtils.DOWNLOAD_TEMP_FILE_MARKER + "orphan"), + new byte[]{1}); + final Path freshTemp = Files.write(dir.resolve("1.log" + RemoteLogUtils.DOWNLOAD_TEMP_FILE_MARKER + "inflight"), + new byte[]{2}); + final Path ordinaryLog = Files.write(dir.resolve("1.log"), new byte[]{3}); + agedTemp.toFile() + .setLastModified(System.currentTimeMillis() - 2 * RemoteLogUtils.ORPHAN_DOWNLOAD_TEMP_MIN_AGE_MILLIS); + + RemoteLogUtils.deleteAgedDownloadTempFiles(dir); + + assertTrue(Files.notExists(agedTemp), "An aged temp file is an orphan and must be swept"); + assertTrue(Files.exists(freshTemp), "A temp file within the age gate may be in flight and must be kept"); + assertTrue(Files.exists(ordinaryLog), "Ordinary log files must never be swept"); + } + + /** + * Regression: archives are downloaded to the task's log path, which can live outside the + * API's local log base dir — the startup sweep alone would never see a leftover there. The + * sweep therefore also runs before each download, in the archive's own directory. + */ + @Test + public void getRemoteLog_sweepsAgedTempFilesNextToTheArchive(@TempDir Path tempDir) throws Exception { + final Path logDir = Files.createDirectories(tempDir.resolve("logs/20261004/1/1")); + final Path logPath = logDir.resolve("1.log"); + final Path agedOrphan = + Files.write(logDir.resolve("1.log" + RemoteLogUtils.DOWNLOAD_TEMP_FILE_MARKER + "orphan"), + new byte[]{1}); + agedOrphan.toFile() + .setLastModified(System.currentTimeMillis() - 2 * RemoteLogUtils.ORPHAN_DOWNLOAD_TEMP_MIN_AGE_MILLIS); + + try (MockedStatic propertyUtils = Mockito.mockStatic(PropertyUtils.class)) { + // Remote logging enabled with an unknown target: the handler factory returns null and + // the download never starts, but the opportunistic sweep must already have run. + propertyUtils.when(() -> PropertyUtils.getBoolean(Constants.REMOTE_LOGGING_ENABLE, Boolean.FALSE)) + .thenReturn(true); + propertyUtils.when(() -> PropertyUtils.getString(Constants.REMOTE_LOGGING_TARGET)) + .thenReturn("not-a-target"); + propertyUtils.when(() -> PropertyUtils.getUpperCaseString(Constants.REMOTE_LOGGING_TARGET)) + .thenReturn("NOT-A-TARGET"); + + RemoteLogUtils.getRemoteLog(logPath.toString()); + } + + assertTrue(Files.notExists(agedOrphan), + "The aged temp file next to the archive must be swept before the download"); + } + + private static long fileCount(final Path dir) { + try (Stream files = Files.list(dir)) { + return files.count(); + } catch (IOException e) { + throw new AssertionError("Failed to list " + dir, e); + } + } +} diff --git a/dolphinscheduler-common/src/test/java/org/apache/dolphinscheduler/common/log/remote/S3RemoteLogHandlerTest.java b/dolphinscheduler-common/src/test/java/org/apache/dolphinscheduler/common/log/remote/S3RemoteLogHandlerTest.java new file mode 100644 index 000000000000..45f603d83f80 --- /dev/null +++ b/dolphinscheduler-common/src/test/java/org/apache/dolphinscheduler/common/log/remote/S3RemoteLogHandlerTest.java @@ -0,0 +1,228 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.apache.dolphinscheduler.common.log.remote; + +import static org.junit.jupiter.api.Assertions.assertArrayEquals; +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertThrows; +import static org.junit.jupiter.api.Assertions.assertTrue; +import static org.mockito.ArgumentMatchers.any; +import static org.mockito.Mockito.when; + +import org.apache.dolphinscheduler.authentication.aws.AmazonS3ClientFactory; +import org.apache.dolphinscheduler.common.constants.Constants; +import org.apache.dolphinscheduler.common.utils.LogUtils; +import org.apache.dolphinscheduler.common.utils.PropertyUtils; + +import java.io.ByteArrayInputStream; +import java.io.IOException; +import java.io.InputStream; +import java.lang.reflect.Field; +import java.nio.charset.StandardCharsets; +import java.nio.file.Files; +import java.nio.file.Path; +import java.util.Collections; +import java.util.stream.Stream; + +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.ExtendWith; +import org.junit.jupiter.api.io.TempDir; +import org.mockito.Mock; +import org.mockito.MockedStatic; +import org.mockito.Mockito; +import org.mockito.junit.jupiter.MockitoExtension; + +import com.amazonaws.services.s3.AmazonS3; +import com.amazonaws.services.s3.model.ObjectMetadata; +import com.amazonaws.services.s3.model.S3Object; +import com.amazonaws.services.s3.model.S3ObjectInputStream; + +/** + * Download contract of a real remote handler (S3 is the one that copies from a raw object + * stream): a transfer failing mid-way propagates and is NEVER published as the local archive — + * not even when a previously downloaded archive is already cached at that path. + */ +@ExtendWith(MockitoExtension.class) +public class S3RemoteLogHandlerTest { + + private static final String BUCKET = "bucket"; + private static final String OBJECT_NAME = "logs/20261003/1/1.log"; + + @Mock + private AmazonS3 s3Client; + + @BeforeEach + public void resetHandlerSingleton() throws Exception { + // The handler is a JVM-wide singleton holding the client built at first use: reset it so + // every test binds to its own mocked client. + final Field instance = S3RemoteLogHandler.class.getDeclaredField("instance"); + instance.setAccessible(true); + instance.set(null, null); + } + + @Test + public void getRemoteLog_midTransferFailure_propagatesAndPublishesNothing(@TempDir Path tempDir) throws Exception { + final Path archive = prepareArchivePath(tempDir); + + try ( + MockedStatic propertyUtils = Mockito.mockStatic(PropertyUtils.class); + MockedStatic logUtils = Mockito.mockStatic(LogUtils.class); + MockedStatic s3ClientFactory = + Mockito.mockStatic(AmazonS3ClientFactory.class)) { + stubS3Client(propertyUtils, logUtils, s3ClientFactory, tempDir); + // 100 bytes announced, the transfer dies after 50 bytes. + when(s3Client.getObject(BUCKET, OBJECT_NAME)).thenReturn(s3Object(failingStreamAfter(50), 100)); + + final IOException thrown = assertThrows(IOException.class, + () -> S3RemoteLogHandler.getInstance().getRemoteLog(archive.toString())); + + assertTrue(thrown.getMessage().contains("connection reset mid-transfer"), thrown.getMessage()); + } + assertTrue(Files.notExists(archive), "The truncated download must not be published"); + assertFileCount(tempDir, 0, "The partial staging file must be deleted"); + } + + /** + * The scenario the review flagged: an archive from an earlier download already sits at the + * log path, and the re-download fails mid-transfer. The cached archive must survive + * byte-identical — the failed transfer must not truncate it and must not be reported as a + * successful download of a shorter log. + */ + @Test + public void getRemoteLog_midTransferFailure_keepsExistingCachedArchive(@TempDir Path tempDir) throws Exception { + final Path archive = prepareArchivePath(tempDir); + final byte[] cached = "previously downloaded complete log".getBytes(StandardCharsets.UTF_8); + Files.write(archive, cached); + + try ( + MockedStatic propertyUtils = Mockito.mockStatic(PropertyUtils.class); + MockedStatic logUtils = Mockito.mockStatic(LogUtils.class); + MockedStatic s3ClientFactory = + Mockito.mockStatic(AmazonS3ClientFactory.class)) { + stubS3Client(propertyUtils, logUtils, s3ClientFactory, tempDir); + when(s3Client.getObject(BUCKET, OBJECT_NAME)).thenReturn(s3Object(failingStreamAfter(50), 100)); + + assertThrows(IOException.class, + () -> S3RemoteLogHandler.getInstance().getRemoteLog(archive.toString())); + } + assertArrayEquals(cached, Files.readAllBytes(archive), + "A failed re-download must not touch the cached archive"); + assertFileCount(tempDir, 1, "Only the cached archive must remain"); + } + + /** + * A stream that ends early WITHOUT reporting an error (the SDK silently returning a short + * body) must still fail: the announced object size is checked against the bytes received, so + * a short transfer can never be published as a complete log. + */ + @Test + public void getRemoteLog_silentlyTruncatedStream_propagatesAndPublishesNothing(@TempDir Path tempDir) throws Exception { + final Path archive = prepareArchivePath(tempDir); + + try ( + MockedStatic propertyUtils = Mockito.mockStatic(PropertyUtils.class); + MockedStatic logUtils = Mockito.mockStatic(LogUtils.class); + MockedStatic s3ClientFactory = + Mockito.mockStatic(AmazonS3ClientFactory.class)) { + stubS3Client(propertyUtils, logUtils, s3ClientFactory, tempDir); + when(s3Client.getObject(BUCKET, OBJECT_NAME)) + .thenReturn(s3Object(new ByteArrayInputStream(new byte[50]), 100)); + + final IOException thrown = assertThrows(IOException.class, + () -> S3RemoteLogHandler.getInstance().getRemoteLog(archive.toString())); + + assertTrue(thrown.getMessage().contains("Truncated download"), thrown.getMessage()); + } + assertTrue(Files.notExists(archive)); + assertFileCount(tempDir, 0, "The partial staging file must be deleted"); + } + + @Test + public void getRemoteLog_completeTransfer_publishesArchive(@TempDir Path tempDir) throws Exception { + final Path archive = prepareArchivePath(tempDir); + final byte[] content = "complete remote log".getBytes(StandardCharsets.UTF_8); + + try ( + MockedStatic propertyUtils = Mockito.mockStatic(PropertyUtils.class); + MockedStatic logUtils = Mockito.mockStatic(LogUtils.class); + MockedStatic s3ClientFactory = + Mockito.mockStatic(AmazonS3ClientFactory.class)) { + stubS3Client(propertyUtils, logUtils, s3ClientFactory, tempDir); + when(s3Client.getObject(BUCKET, OBJECT_NAME)) + .thenReturn(s3Object(new ByteArrayInputStream(content), content.length)); + + S3RemoteLogHandler.getInstance().getRemoteLog(archive.toString()); + } + assertArrayEquals(content, Files.readAllBytes(archive)); + assertFileCount(tempDir, 1, "Only the published archive must remain"); + } + + private void stubS3Client(final MockedStatic propertyUtils, + final MockedStatic logUtils, + final MockedStatic s3ClientFactory, + final Path tempDir) { + propertyUtils.when(() -> PropertyUtils.getString(Constants.AWS_S3_BUCKET_NAME)).thenReturn(BUCKET); + propertyUtils.when(() -> PropertyUtils.getString(Constants.REMOTE_LOGGING_BASE_DIR)).thenReturn("logs"); + propertyUtils.when(() -> PropertyUtils.getByPrefix("aws.s3.", "")).thenReturn(Collections.emptyMap()); + logUtils.when(LogUtils::getLocalLogBaseDir).thenReturn(tempDir.resolve("logs").toString()); + s3ClientFactory.when(() -> AmazonS3ClientFactory.createAmazonS3Client(any())).thenReturn(s3Client); + when(s3Client.doesBucketExistV2(BUCKET)).thenReturn(true); + } + + /** + * Builds {@code /logs/20261003/1/1.log} (the parent dirs are created by + * {@code RemoteLogUtils#getRemoteLog} in production) and returns the archive path. + */ + private static Path prepareArchivePath(final Path tempDir) throws IOException { + return Files.createDirectories(tempDir.resolve("logs/20261003/1")).resolve("1.log"); + } + + private static S3Object s3Object(final InputStream content, final long announcedLength) { + final ObjectMetadata metadata = new ObjectMetadata(); + metadata.setContentLength(announcedLength); + final S3Object s3Object = new S3Object(); + s3Object.setObjectMetadata(metadata); + s3Object.setObjectContent(new S3ObjectInputStream(content, null)); + return s3Object; + } + + private static InputStream failingStreamAfter(final int bytesBeforeFailure) { + return new InputStream() { + + private int remaining = bytesBeforeFailure; + + @Override + public int read() throws IOException { + if (remaining > 0) { + remaining--; + return 'a'; + } + throw new IOException("connection reset mid-transfer"); + } + }; + } + + private static void assertFileCount(final Path dir, final long expected, final String message) { + try (Stream entries = Files.walk(dir)) { + assertEquals(expected, entries.filter(Files::isRegularFile).count(), message); + } catch (IOException e) { + throw new AssertionError("Failed to walk " + dir, e); + } + } +} diff --git a/dolphinscheduler-common/src/test/java/org/apache/dolphinscheduler/common/utils/LogUtilsTest.java b/dolphinscheduler-common/src/test/java/org/apache/dolphinscheduler/common/utils/LogUtilsTest.java index 508e0e2ba5a6..af972bb15694 100644 --- a/dolphinscheduler-common/src/test/java/org/apache/dolphinscheduler/common/utils/LogUtilsTest.java +++ b/dolphinscheduler-common/src/test/java/org/apache/dolphinscheduler/common/utils/LogUtilsTest.java @@ -21,14 +21,19 @@ import static org.junit.jupiter.api.Assertions.assertEquals; import static org.junit.jupiter.api.Assertions.assertThrows; +import org.apache.dolphinscheduler.common.log.remote.RemoteLogUtils; + import java.io.EOFException; import java.io.FileNotFoundException; +import java.io.IOException; import java.nio.charset.StandardCharsets; import java.nio.file.Files; import java.nio.file.Path; import org.junit.jupiter.api.Test; import org.junit.jupiter.api.io.TempDir; +import org.mockito.MockedStatic; +import org.mockito.Mockito; public class LogUtilsTest { @@ -77,4 +82,24 @@ public void readFileRange_missingFileThrows(@TempDir Path tempDir) { assertThrows(FileNotFoundException.class, () -> LogUtils.readFileRange(tempDir.resolve("absent.log").toFile(), 0, 10, 100)); } + + /** + * The view path must fail when the remote download fails — even with a local file sitting at + * the path — instead of falling through to reading a stale or partial file and reporting it + * as the current log. + */ + @Test + public void readPartFileContentFromRemote_downloadFailure_doesNotReadLocalFile(@TempDir Path tempDir) throws Exception { + final Path file = tempDir.resolve("task.log"); + Files.write(file, "stale local content\n".getBytes(StandardCharsets.UTF_8)); + + try (MockedStatic remoteLogUtils = Mockito.mockStatic(RemoteLogUtils.class)) { + remoteLogUtils.when(() -> RemoteLogUtils.getRemoteLog(file.toString())) + .thenThrow(new IOException("connection reset mid-transfer")); + + final RuntimeException thrown = assertThrows(RuntimeException.class, + () -> LogUtils.readPartFileContentFromRemote(file.toString(), 0, 10)); + assertEquals("connection reset mid-transfer", thrown.getCause().getMessage()); + } + } } diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/IRpcResponse.java b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/IRpcResponse.java index 498efb104724..6db598360bf4 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/IRpcResponse.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/IRpcResponse.java @@ -27,4 +27,12 @@ public interface IRpcResponse { byte[] toBytes(); + /** + * Whether the failure is specifically "the server does not have this method" (an old server + * during a rolling upgrade) rather than any other invocation failure. + */ + default boolean isMethodNotFound() { + return false; + } + } diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/StandardRpcResponse.java b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/StandardRpcResponse.java index 21a6afa76ecb..91b6b1944f7d 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/StandardRpcResponse.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/StandardRpcResponse.java @@ -32,6 +32,14 @@ public class StandardRpcResponse implements IRpcResponse { private Class bodyType; + /** + * True only when the failure is specifically "the server does not have this method" — the + * old-server signal during a rolling upgrade. Every other failure (the method threw, the + * server's invocation pool is full) leaves it false, so a caller must never mistake a + * saturated or broken server for an outdated one. Older peers ignore the field. + */ + private boolean methodNotFound; + public static StandardRpcResponse success(byte[] body, Class bodyType) { StandardRpcResponse rpcResponse = new StandardRpcResponse(); rpcResponse.setSuccess(true); @@ -47,6 +55,15 @@ public static StandardRpcResponse fail(String message) { return rpcResponse; } + /** + * The server answered that it does not know the requested method (see {@link #isMethodNotFound()}). + */ + public static StandardRpcResponse methodNotFound(String message) { + StandardRpcResponse rpcResponse = fail(message); + rpcResponse.setMethodNotFound(true); + return rpcResponse; + } + @Override public byte[] toBytes() { return JsonSerializer.serialize(this); diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/client/NettyClientHandler.java b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/client/NettyClientHandler.java index 81b921de6fbb..fea874abb59d 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/client/NettyClientHandler.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/client/NettyClientHandler.java @@ -60,7 +60,13 @@ public void channelRead(ChannelHandlerContext ctx, Object msg) { private void processReceived(final Transporter transporter) { ResponseFuture future = ResponseFuture.getFuture(transporter.getHeader().getOpaque()); if (future == null) { - log.warn("Cannot find the ResponseFuture if transporter: {}", transporter); + // Log the opaque and the body size only: Transporter's Lombok toString renders the + // body byte[] (a log chunk response is ~10 MB), and this branch is hit exactly when a + // timed-out request's late response arrives — rendering it would dump megabytes per + // late response into the log. + log.warn("Cannot find the ResponseFuture for the late response with opaque {} ({} bytes body), dropping it", + transporter.getHeader().getOpaque(), + transporter.getBody() == null ? 0 : transporter.getBody().length); return; } StandardRpcResponse deserialize = JsonSerializer.deserialize(transporter.getBody(), StandardRpcResponse.class); diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/client/NettyRemotingClient.java b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/client/NettyRemotingClient.java index 603680c600e9..04f3daf1a3e4 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/client/NettyRemotingClient.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/client/NettyRemotingClient.java @@ -184,7 +184,11 @@ private IRpcResponse doSendSync(final Transporter transporter, } responseFuture.setCause(future.cause()); responseFuture.putResponse(null); - log.error("Send Sync request {} to host {} failed", transporter, serverHost, responseFuture.getCause()); + // Log the small header (and the body size), never the transporter itself: its + // Lombok toString renders the body byte[] and request bodies can be large. + log.error("Send Sync request {} ({} bytes body) to host {} failed", transporter.getHeader(), + transporter.getBody() == null ? 0 : transporter.getBody().length, serverHost, + responseFuture.getCause()); }); } /* @@ -214,10 +218,30 @@ private IRpcResponse doSendSync(final Transporter transporter, // alive even though the server never responds). A late response finds no future and // is dropped. responseFuture.cancel(); - throw new RemoteTimeoutException(serverHost.toString(), timeoutMills, null); - } else { - throw new RemoteException(serverHost.toString(), null); } + // Deliberately re-read the state here: a write failure can be recorded between the cause + // check above and this classification (the failure drain races the timeout), so neither + // branch may hard-code a null cause. + throw buildEmptyResponseException(serverHost, responseFuture, timeoutMills); + } + + /** + * Classify a request that completed without a response: {@code sendOK} means the request was + * written and the server simply never answered (a genuine timeout); otherwise the write + * itself failed and the recorded cause is the real error, which must never be dropped — a + * bare host string makes "worker down" indistinguishable from "slow response". + * + *

    Package-private for tests: the timing race that makes the cause interesting (a write + * failure landing between the caller's cause check and this classification) cannot be driven + * deterministically through {@link #doSendSync}. + */ + static RemoteException buildEmptyResponseException(final Host serverHost, + final ResponseFuture responseFuture, + final long timeoutMills) { + final Throwable cause = responseFuture.getCause(); + return responseFuture.isSendOK() + ? new RemoteTimeoutException(serverHost.toString(), timeoutMills, cause) + : new RemoteException(serverHost.toString(), cause); } Channel getOrCreateChannel(Host host) { diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/client/SyncClientMethodInvoker.java b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/client/SyncClientMethodInvoker.java index 5a09af2c56f4..43217566bec5 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/client/SyncClientMethodInvoker.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/client/SyncClientMethodInvoker.java @@ -22,6 +22,7 @@ import org.apache.dolphinscheduler.extract.base.StandardRpcRequest; import org.apache.dolphinscheduler.extract.base.SyncRequestDto; import org.apache.dolphinscheduler.extract.base.exception.MethodInvocationException; +import org.apache.dolphinscheduler.extract.base.exception.MethodNotFoundException; import org.apache.dolphinscheduler.extract.base.protocal.Transporter; import org.apache.dolphinscheduler.extract.base.protocal.TransporterHeader; import org.apache.dolphinscheduler.extract.base.serialize.JsonSerializer; @@ -50,6 +51,11 @@ public Object invoke(Object proxy, Method method, Object[] args) throws Throwabl .build(); IRpcResponse iRpcResponse = nettyRemotingClient.sendSync(syncRequestDto); if (!iRpcResponse.isSuccess()) { + if (iRpcResponse.isMethodNotFound()) { + // The server answered that it does not have this method — an old server during a + // rolling upgrade, not a server that failed to execute the call. + throw new MethodNotFoundException(iRpcResponse.getMessage()); + } throw MethodInvocationException.of(iRpcResponse.getMessage()); } if (iRpcResponse.getBody() == null) { diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/exception/MethodNotFoundException.java b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/exception/MethodNotFoundException.java new file mode 100644 index 000000000000..fd7d5b30cd9f --- /dev/null +++ b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/exception/MethodNotFoundException.java @@ -0,0 +1,33 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.apache.dolphinscheduler.extract.base.exception; + +/** + * The server answered that it does not have the requested method — the old-server signal during + * a rolling upgrade. A subclass of {@link MethodInvocationException} so existing callers keep + * working; only callers that must distinguish "outdated peer" from "the invocation failed" (e.g. + * the worker-upgrade guidance of the chunked log download) need to check for this type: every + * other server-side failure — the method threw, the server's invocation pool is full — is + * reported as a plain {@link MethodInvocationException}. + */ +public class MethodNotFoundException extends MethodInvocationException { + + public MethodNotFoundException(String message) { + super(message); + } +} diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/server/JdkDynamicServerHandler.java b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/server/JdkDynamicServerHandler.java index f7578c13400c..a30c527b53cc 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/server/JdkDynamicServerHandler.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/main/java/org/apache/dolphinscheduler/extract/base/server/JdkDynamicServerHandler.java @@ -85,9 +85,15 @@ private void processReceived(final Channel channel, final Transporter transporte ServerMethodInvoker methodInvoker = methodInvokerMap.get(methodIdentifier); try { if (methodInvoker == null) { - log.error("Cannot find the ServerMethodInvoker of : {}", transporter); + // Log the identifier, not the transporter: its Lombok toString renders the + // request body, which can be large. + log.error("Cannot find the ServerMethodInvoker of : {}", methodIdentifier); + // Typed failure: the peer must be able to tell "this server does not have the + // method" (an old server during a rolling upgrade) apart from any other + // invocation failure. StandardRpcResponse iRpcResponse = - StandardRpcResponse.fail("Cannot find the ServerMethodInvoker of " + methodIdentifier); + StandardRpcResponse + .methodNotFound("Cannot find the ServerMethodInvoker of " + methodIdentifier); TransporterHeader transporterHeader = TransporterHeader.of(transporter.getHeader().getOpaque(), methodIdentifier); Transporter response = Transporter.of(transporterHeader, iRpcResponse); diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/client/NettyClientHandlerTest.java b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/client/NettyClientHandlerTest.java index 7a24b133c383..b0a4c355ea07 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/client/NettyClientHandlerTest.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/client/NettyClientHandlerTest.java @@ -17,6 +17,7 @@ package org.apache.dolphinscheduler.extract.base.client; +import static org.junit.jupiter.api.Assertions.assertEquals; import static org.junit.jupiter.api.Assertions.assertNotNull; import static org.junit.jupiter.api.Assertions.assertNull; import static org.junit.jupiter.api.Assertions.assertSame; @@ -42,6 +43,7 @@ import java.nio.charset.StandardCharsets; import java.time.Duration; import java.util.ArrayList; +import java.util.Arrays; import java.util.List; import java.util.concurrent.ExecutorService; import java.util.concurrent.Executors; @@ -52,7 +54,11 @@ import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.Test; import org.mockito.Mockito; +import org.slf4j.LoggerFactory; +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; import io.netty.bootstrap.ServerBootstrap; import io.netty.buffer.Unpooled; import io.netty.channel.Channel; @@ -206,6 +212,41 @@ void channelRead_deserializeFailure_failsPendingFutureNotTimeout() throws Except "The failing request must receive the real error promptly — not hang until timeout"); } + /** + * A late response whose future was already dropped (a timed-out request is removed from + * FUTURE_TABLE) must not render the response body into the log: {@code Transporter}'s Lombok + * toString prints the raw body byte[], which is ~10 MB for a log chunk — one late response per + * timeout would otherwise build megabytes of log text on the Netty event loop. + */ + @Test + void channelRead_unknownOpaque_dropsLateResponseWithoutLoggingItsBody() { + final NettyRemotingClient mockClient = mock(NettyRemotingClient.class); + final NettyClientHandler handler = new NettyClientHandler(mockClient); + final EmbeddedChannel channel = new EmbeddedChannel(handler); + + final byte[] bigBody = new byte[4 * 1024 * 1024]; + Arrays.fill(bigBody, (byte) 'x'); + // Fresh header → the opaque has no future, exactly like a late response after a timeout. + final Transporter lateResponse = Transporter.of(new TransporterHeader("test-method"), bigBody); + + final Logger handlerLogger = (Logger) LoggerFactory.getLogger(NettyClientHandler.class); + final ListAppender appender = new ListAppender<>(); + appender.start(); + handlerLogger.addAppender(appender); + try { + channel.writeInbound(lateResponse); + } finally { + handlerLogger.detachAppender(appender); + channel.finishAndReleaseAll(); + } + + assertEquals(1, appender.list.size(), "the dropped response must be logged exactly once"); + final String message = appender.list.get(0).getFormattedMessage(); + assertTrue(message.length() < 200, + "the log line must identify the response without rendering its body, but was " + message.length() + + " chars"); + } + /** * Regression test for the shared-channel race: two CONCURRENT sync requests multiplexed over * one channel, then the server replies with a frame whose declared body length exceeds diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/client/NettyRemotingClientTest.java b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/client/NettyRemotingClientTest.java new file mode 100644 index 000000000000..083e1adb79f8 --- /dev/null +++ b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/client/NettyRemotingClientTest.java @@ -0,0 +1,80 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.apache.dolphinscheduler.extract.base.client; + +import static org.junit.jupiter.api.Assertions.assertNull; +import static org.junit.jupiter.api.Assertions.assertSame; +import static org.junit.jupiter.api.Assertions.assertTrue; + +import org.apache.dolphinscheduler.extract.base.exception.RemoteException; +import org.apache.dolphinscheduler.extract.base.exception.RemoteTimeoutException; +import org.apache.dolphinscheduler.extract.base.future.ResponseFuture; +import org.apache.dolphinscheduler.extract.base.utils.Host; + +import org.junit.jupiter.api.Test; + +class NettyRemotingClientTest { + + private static final Host HOST = Host.of("worker-1:1234"); + + /** + * A request whose write failed must report the recorded transport cause. Reporting a bare + * host string instead makes "worker died mid-RPC" indistinguishable from a slow response. + */ + @Test + void buildEmptyResponseException_sendFailed_carriesTheRealTransportCause() { + final ResponseFuture responseFuture = new ResponseFuture(1L, 1000L, null); + try { + responseFuture.setSendOk(false); + final RuntimeException cause = new RuntimeException("connection reset by peer"); + responseFuture.setCause(cause); + + final RemoteException thrown = NettyRemotingClient.buildEmptyResponseException(HOST, responseFuture, 1000L); + + assertSame(cause, thrown.getCause(), "a failed write must not degrade to a bare host string"); + } finally { + responseFuture.putResponse(null); + } + } + + /** + * The write-failure listener can record its cause between the caller's cause check and this + * classification (the drain races the timeout). Re-reading the state here is what keeps the + * only diagnostic information from being dropped; the no-race case stays a plain timeout. + */ + @Test + void buildEmptyResponseException_timedOut_reportsTimeoutAndKeepsALateCause() { + final ResponseFuture responseFuture = new ResponseFuture(2L, 1000L, null); + try { + responseFuture.setSendOk(true); + + assertTrue(NettyRemotingClient.buildEmptyResponseException(HOST, responseFuture, + 1000L) instanceof RemoteTimeoutException); + assertNull(NettyRemotingClient.buildEmptyResponseException(HOST, responseFuture, 1000L).getCause()); + + final RuntimeException lateCause = new RuntimeException("channel closed"); + responseFuture.setCause(lateCause); + + assertSame(lateCause, + NettyRemotingClient.buildEmptyResponseException(HOST, responseFuture, 1000L).getCause(), + "a cause recorded after the caller's check must still be surfaced"); + } finally { + responseFuture.putResponse(null); + } + } +} diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/client/SyncClientMethodInvokerTest.java b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/client/SyncClientMethodInvokerTest.java new file mode 100644 index 000000000000..bbe5882d5a25 --- /dev/null +++ b/dolphinscheduler-extract/dolphinscheduler-extract-base/src/test/java/org/apache/dolphinscheduler/extract/base/client/SyncClientMethodInvokerTest.java @@ -0,0 +1,104 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.apache.dolphinscheduler.extract.base.client; + +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertThrows; +import static org.mockito.ArgumentMatchers.any; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.when; + +import org.apache.dolphinscheduler.extract.base.RpcMethod; +import org.apache.dolphinscheduler.extract.base.StandardRpcResponse; +import org.apache.dolphinscheduler.extract.base.exception.MethodInvocationException; +import org.apache.dolphinscheduler.extract.base.exception.MethodNotFoundException; +import org.apache.dolphinscheduler.extract.base.serialize.JsonSerializer; +import org.apache.dolphinscheduler.extract.base.utils.Host; + +import java.lang.reflect.Method; + +import org.junit.jupiter.api.Test; +import org.mockito.Mockito; + +class SyncClientMethodInvokerTest { + + private interface SampleService { + + @RpcMethod + String call(String arg); + } + + private static Method method() throws NoSuchMethodException { + return SampleService.class.getDeclaredMethod("call", String.class); + } + + private static SyncClientMethodInvoker invokerReturning(StandardRpcResponse response) throws Exception { + final NettyRemotingClient nettyRemotingClient = mock(NettyRemotingClient.class); + when(nettyRemotingClient.sendSync(any())).thenReturn(response); + return new SyncClientMethodInvoker(Host.of("server:1234"), method(), nettyRemotingClient); + } + + /** + * The server reporting "I do not have this method" is the only signal that identifies an old + * peer during a rolling upgrade; it must map to the typed exception so callers can give + * upgrade guidance without parsing message strings. + */ + @Test + void invoke_serverWithoutTheMethod_throwsTypedMethodNotFoundException() throws Throwable { + final SyncClientMethodInvoker invoker = + invokerReturning(StandardRpcResponse.methodNotFound("Cannot find the ServerMethodInvoker of x")); + + final MethodNotFoundException thrown = assertThrows(MethodNotFoundException.class, + () -> invoke(invoker)); + + assertEquals("Cannot find the ServerMethodInvoker of x", thrown.getMessage()); + } + + /** + * Every other server-side failure — the invocation pool is full, the method itself threw — + * is reported the same way over the wire. It must stay a plain MethodInvocationException so + * a saturated current server is never mistaken for an outdated one. + */ + @Test + void invoke_serverAnsweredWithAFailure_staysPlainMethodInvocationException() throws Throwable { + final SyncClientMethodInvoker invoker = + invokerReturning(StandardRpcResponse.fail("NettyRemotingServer's thread pool is full")); + + final MethodInvocationException thrown = assertThrows(MethodInvocationException.class, + () -> invoke(invoker)); + + assertFalse(thrown instanceof MethodNotFoundException, + "only the explicit not-found signal may be typed as MethodNotFoundException"); + assertEquals("NettyRemotingServer's thread pool is full", thrown.getMessage()); + } + + /** The happy path is untouched: a success response still deserializes to the return value. */ + @Test + void invoke_successResponse_returnsTheDeserializedBody() throws Throwable { + final SyncClientMethodInvoker invoker = invokerReturning( + StandardRpcResponse.success(JsonSerializer.serialize("result-body"), String.class)); + + assertEquals("result-body", invoke(invoker)); + } + + private static Object invoke(final SyncClientMethodInvoker invoker) throws Throwable { + final Method method = method(); + return invoker.invoke(Mockito.mock(SampleService.class), method, new Object[]{"arg"}); + } +} diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/ILogService.java b/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/ILogService.java index a62c51014fe3..4f4f5f39750e 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/ILogService.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/ILogService.java @@ -39,6 +39,12 @@ public interface ILogService { /** * Read a bounded chunk of the log file [offset, offset+length) for streaming download. * The worker clamps length to a maximum chunk size and returns eof metadata. + * + *

    Each response also reports the file length observed by the worker's single stat + * ({@link TaskInstanceLogFileDownloadResponse#getObservedLength()}). The API uses the FIRST + * chunk's value as the download's target length, so streaming a live, growing log yields a + * snapshot taken at request time. A 0 means the worker does not report it (e.g. an old + * worker) and the caller must end the stream on {@code eof} instead. */ @RpcMethod(timeout = 30_000) TaskInstanceLogFileDownloadResponse getTaskInstanceLogFileChunk(TaskInstanceLogFileDownloadRequest request); diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/service/impl/LogServiceImpl.java b/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/service/impl/LogServiceImpl.java index c9a741a1b8ad..a23de9499324 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/service/impl/LogServiceImpl.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/service/impl/LogServiceImpl.java @@ -119,6 +119,7 @@ public TaskInstanceLogFileDownloadResponse getTaskInstanceLogFileChunk( // re-statting after the read would race against rotation between the two // observations and could misclassify the result. final long observedFileLength = logFile.length(); + response.setObservedLength(observedFileLength); if (offset > observedFileLength) { // offset is PAST the observed file size: the file shrank underneath the reader // (log rotation renamed it, a fresh one started from 0). offset == fileLength diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/transportor/TaskInstanceLogFileDownloadResponse.java b/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/transportor/TaskInstanceLogFileDownloadResponse.java index 01f8eb6ef558..3af8683e3978 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/transportor/TaskInstanceLogFileDownloadResponse.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-common/src/main/java/org/apache/dolphinscheduler/extract/common/transportor/TaskInstanceLogFileDownloadResponse.java @@ -37,4 +37,24 @@ public class TaskInstanceLogFileDownloadResponse { */ private boolean eof = true; + /** + * The file length the worker observed on this chunk's single stat; 0 when unknown (e.g. an + * old worker that does not report it). The API pins the download's target length to the FIRST + * chunk's value, so streaming a live log that keeps growing still yields a snapshot taken at + * request time instead of an unbounded tail. + */ + private long observedLength; + + /** + * Convenience constructor for callers that do not report {@link #observedLength} — it stays + * 0, i.e. unknown. + */ + public TaskInstanceLogFileDownloadResponse(final byte[] logBytes, final LogResponseStatus code, + final String message, final boolean eof) { + this.logBytes = logBytes; + this.code = code; + this.message = message; + this.eof = eof; + } + } diff --git a/dolphinscheduler-extract/dolphinscheduler-extract-common/src/test/java/org/apache/dolphinscheduler/extract/common/service/impl/LogServiceImplTest.java b/dolphinscheduler-extract/dolphinscheduler-extract-common/src/test/java/org/apache/dolphinscheduler/extract/common/service/impl/LogServiceImplTest.java index 0469776730f1..9958e8d90f6e 100644 --- a/dolphinscheduler-extract/dolphinscheduler-extract-common/src/test/java/org/apache/dolphinscheduler/extract/common/service/impl/LogServiceImplTest.java +++ b/dolphinscheduler-extract/dolphinscheduler-extract-common/src/test/java/org/apache/dolphinscheduler/extract/common/service/impl/LogServiceImplTest.java @@ -59,6 +59,31 @@ void getTaskInstanceLogFileChunk_normalRangeReturnsSuccess() throws IOException } } + /** + * The chunk response reports the worker's single-stat file length: the API pins the + * download's snapshot target to the FIRST chunk's value, so it must be present (0 is only + * for workers that do not report it, e.g. during a rolling upgrade). + */ + @Test + void getTaskInstanceLogFileChunk_reportsObservedFileLength() throws IOException { + Path file = Files.createTempFile("ds-chunk-observed", ".log"); + try { + Files.write(file, new byte[20]); + + TaskInstanceLogFileDownloadRequest req = new TaskInstanceLogFileDownloadRequest(); + req.setTaskInstanceLogAbsolutePath(file.toString()); + req.setOffset(0); + req.setLength(10); + + TaskInstanceLogFileDownloadResponse resp = logService.getTaskInstanceLogFileChunk(req); + + assertEquals(LogResponseStatus.SUCCESS, resp.getCode()); + assertEquals(20, resp.getObservedLength(), "the snapshot target comes from this value"); + } finally { + Files.deleteIfExists(file); + } + } + @Test void getTaskInstanceLogFileChunk_lastChunkEof() throws IOException { Path file = Files.createTempFile("ds-chunk-eof", ".log");