diff --git a/docs/docs/en/guide/upgrade/incompatible.md b/docs/docs/en/guide/upgrade/incompatible.md index ad118a1d6088..4fe3514d230d 100644 --- a/docs/docs/en/guide/upgrade/incompatible.md +++ b/docs/docs/en/guide/upgrade/incompatible.md @@ -56,3 +56,4 @@ This document records the incompatible updates between each version. You need to * **Removed derived properties**: `cmdTypeIfComplement`, `complementData` (related to complement-data executions; use the detail API to obtain them) * To obtain any of these fields, use the detail API `GET /projects/{projectCode}/workflow-instances/{id}` instead, which continues to return the full `WorkflowInstance` object. ([#18444](https://github.com/apache/dolphinscheduler/pull/18444)) +* `RemoteLogHandler#getRemoteLog` in `dolphinscheduler-common` now declares `throws IOException` and propagates download failures instead of swallowing them; `LogUtils#getFileContentBytesFromRemote` was removed. Out-of-tree implementations and callers of these APIs must be updated. ([#18459](https://github.com/apache/dolphinscheduler/issues/18459)) diff --git a/docs/docs/zh/guide/upgrade/incompatible.md b/docs/docs/zh/guide/upgrade/incompatible.md index a0f945501989..aa4f41df9030 100644 --- a/docs/docs/zh/guide/upgrade/incompatible.md +++ b/docs/docs/zh/guide/upgrade/incompatible.md @@ -56,3 +56,4 @@ * **移除的派生属性**：`cmdTypeIfComplement`、`complementData`（补数执行相关，如需获取请使用详情接口） * 如需获取这些字段，请使用详情接口 `GET /projects/{projectCode}/workflow-instances/{id}`，该接口仍返回完整的 `WorkflowInstance` 对象 ([#18444](https://github.com/apache/dolphinscheduler/pull/18444)) +* `dolphinscheduler-common` 中的 `RemoteLogHandler#getRemoteLog` 现在声明 `throws IOException` 并向上传播下载失败（不再吞掉异常）；`LogUtils#getFileContentBytesFromRemote` 已移除。仓库外的实现与调用方需要相应调整。([#18459](https://github.com/apache/dolphinscheduler/issues/18459)) diff --git a/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/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..bd414cfef9bd 100644 --- a/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/LogClientDelegate.java +++ b/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/LogClientDelegate.java @@ -18,6 +18,8 @@ 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.base.exception.MethodNotFoundException; import org.apache.dolphinscheduler.extract.common.transportor.LogResponseStatus; import org.apache.dolphinscheduler.extract.common.transportor.TaskInstanceLogFileDownloadResponse; import org.apache.dolphinscheduler.extract.common.transportor.TaskInstanceLogPageQueryResponse; @@ -25,6 +27,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 +41,8 @@ @Component public class LogClientDelegate { + private static final int LOG_CHUNK_SIZE = 8 * 1024 * 1024; // 8 MB + @Autowired private LocalLogClient localLogClient; @Autowired @@ -66,29 +75,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 +95,132 @@ private boolean checkNodeExists(TaskInstance taskInstance) { return exists; } + /** + * Stream the entire task instance log to {@code outputStream} using bounded chunk RPCs. + * + *

Strategy: + *

+ */ + public void streamWholeLog(final TaskInstance taskInstance, final OutputStream outputStream) throws IOException { + checkArgs(taskInstance); + if (!checkNodeExists(taskInstance)) { + remoteLogClient.streamWholeLog(taskInstance, outputStream); + return; + } + long offset = 0; + // The length of the snapshot this download delivers. Unknown until the first chunk + // reports it; 0 means the worker does not report it (e.g. an old worker during a rolling + // upgrade) and the stream then ends on eof only. + long snapshotLength = -1; + while (true) { + if (snapshotLength > 0 && offset >= snapshotLength) { + // The last byte of the request-time snapshot has been delivered. A live task may + // have written more since the first chunk observed the length: the download is a + // snapshot taken when it started, not an unbounded tail of a growing log. + return; + } + // After the first chunk only what is left of the snapshot is requested — the worker + // clamps to the file, so a growing log is never read past the snapshot boundary. + final int chunkLength = snapshotLength > 0 + ? (int) Math.min(LOG_CHUNK_SIZE, snapshotLength - offset) + : LOG_CHUNK_SIZE; + final TaskInstanceLogFileDownloadResponse chunk; + try { + chunk = localLogClient.getLogChunk(taskInstance, offset, chunkLength); + } catch (Exception e) { + if (offset > 0) { + throw new IOException("Log streaming failed at offset " + offset, e); + } + log.warn("Chunked log RPC failed for task instance {}, falling back to remote log storage", + taskInstance.getId(), e); + // Distinguish the three failure shapes so operations get accurate guidance: + // - MethodNotFoundException: the worker ANSWERED that the chunk method does not + // exist — an old worker during a rolling upgrade, the upgrade guidance fits. + // - any other MethodInvocationException: the worker ANSWERED but the invocation + // failed there (its invocation pool is full, the method threw) — a current + // worker under stress must NOT be told to upgrade. + // - anything else (connect refused, timeout): the worker never answered. + final String errorMessage; + if (ExceptionUtils.throwableOfType(e, MethodNotFoundException.class) != null) { + errorMessage = "Worker upgrade required for large log download: chunked log RPC is not available" + + " on worker " + taskInstance.getHost() + " and remote log storage also failed"; + } else if (ExceptionUtils.throwableOfType(e, MethodInvocationException.class) != null) { + errorMessage = "Chunked log fetch failed on worker " + taskInstance.getHost() + + " for task instance " + taskInstance.getId() + + " (the worker answered with an error: " + ExceptionUtils.getRootCauseMessage(e) + ")" + + " and remote log storage also failed"; + } else { + errorMessage = "Chunked log RPC to worker " + taskInstance.getHost() + + " failed (the worker may be down or unreachable)" + + " and remote log storage also failed"; + } + fallbackToRemoteStorage(taskInstance, outputStream, errorMessage); + return; + } + 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; + } + if (snapshotLength < 0) { + // Pin the snapshot from the worker's first stat; 0 keeps the eof-only behavior. + snapshotLength = chunk.getObservedLength(); + } + final byte[] data = chunk.getLogBytes(); + if (data != null && data.length > 0) { + outputStream.write(data); + 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..07a298f758bf 100644 --- a/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/RemoteLogClient.java +++ b/dolphinscheduler-api/src/main/java/org/apache/dolphinscheduler/api/executor/logging/RemoteLogClient.java @@ -17,38 +17,248 @@ 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.ConcurrentHashMap; +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 temporary files ({@code .download-}): the private + * streaming snapshots of this class and the staging files the remote log handlers download + * into (see {@link RemoteLogUtils#downloadToLocalFileAtomically}). Also used by the startup + * sweep to recognize orphans. + */ + private static final String DOWNLOAD_TEMP_MARKER = RemoteLogUtils.DOWNLOAD_TEMP_FILE_MARKER; + + /** + * Per-download temp files younger than this are never swept as orphans: on the (unsupported + * but possible) shared-disk setup the age gate protects another live instance's in-flight + * transfer. Shared with {@link RemoteLogUtils#deleteAgedDownloadTempFiles(Path)}, the + * per-download cleanup that also covers the directories this startup sweep cannot reach. + */ + private static final long ORPHAN_TEMP_FILE_MIN_AGE_MILLIS = + RemoteLogUtils.ORPHAN_DOWNLOAD_TEMP_MIN_AGE_MILLIS; + + /** + * Per-log-path locks: concurrent requests for the SAME log coalesce (the second waits for the + * in-flight download instead of re-downloading a possibly multi-GB archive), while requests + * for different logs never block each other — the previous fixed 64-stripe array made + * unrelated logs that hashed to the same stripe wait behind a whole remote download. Entries + * are reference-counted and removed with the last user, so the map is bounded by the number + * of in-flight log paths, and {@link #streamWholeLog}'s private snapshot keeps its lock-free + * streaming read stable across later cache replacements. Each API instance downloads to its + * own local disk, so per-JVM locking is sufficient. + */ + private static final ConcurrentHashMap LOG_PATH_LOCKS = new ConcurrentHashMap<>(); + + private static final class LockEntry { + + private final ReentrantLock lock = new ReentrantLock(); + + /** Only touched inside the map's per-key compute calls — never read or written outside. */ + private int references; + } + + /** + * Take a reference to the lock of {@code logPath}; every call must be paired with + * {@link #unlockFor(String)} (after {@code lock.unlock()}) so the entry can be released. + */ + static ReentrantLock lockFor(final String logPath) { + return LOG_PATH_LOCKS.compute(logPath, (path, entry) -> { + final LockEntry current = entry != null ? entry : new LockEntry(); + current.references++; + return current; + }).lock; + } + + /** + * Drop one reference to {@code logPath}'s lock entry, removing it when the last user is gone. + * Must run AFTER {@code lock.unlock()}: an entry removed while still held would let a new + * arrival lock a fresh entry concurrently with the holder. + */ + static void unlockFor(final String logPath) { + LOG_PATH_LOCKS.computeIfPresent(logPath, (path, entry) -> --entry.references == 0 ? null : entry); + } + + /** + * At startup this JVM can have no in-flight transfer, so any per-download temp file left over + * from a previous life — this class's streaming snapshot or a remote handler's download + * staging file (graceful shutdown and kill -9 alike skip the transfer's {@code finally}) — is + * an orphan and is swept. Only the local log base dir can be walked here; the archive + * directories (which follow task log paths and may live elsewhere) are covered by + * {@link RemoteLogUtils#deleteAgedDownloadTempFiles(Path)} before each download. Best effort: + * any error just skips the sweep. Does nothing when logging is not initialized (e.g. plain + * unit tests). + */ + @PostConstruct + public void deleteOrphanedTempFiles() { + final String baseDir = LogUtils.getLocalLogBaseDir(); + if (baseDir != null) { + deleteOrphanedTempFiles(Paths.get(baseDir)); + } + } + + void deleteOrphanedTempFiles(final Path baseDir) { + try (Stream walk = Files.walk(baseDir)) { + walk.filter(Files::isRegularFile) + .filter(file -> file.getFileName().toString().contains(DOWNLOAD_TEMP_MARKER)) + .filter(RemoteLogClient::olderThanOrphanAge) + .forEach(this::deleteTempFileQuietly); + } catch (Exception e) { + log.warn("Failed to sweep orphaned log download temp files 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_TEMP_FILE_MIN_AGE_MILLIS; + } + + /** + * Stream the entire remote-archived log to {@code outputStream} without loading the whole + * file into memory. Downloads the archive to a local file, snapshots it into a private temp + * file ({@code .download-}, deleted when the transfer ends; leftovers are + * swept by {@link #deleteOrphanedTempFiles()}) and streams that snapshot — see the + * {@code LOG_PATH_LOCKS} note for why the snapshot is required. Costs a second write of the + * archive (~2x peak disk for one download). + * + *

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

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

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

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

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

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

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

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

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

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