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] [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); + } + } +}