|
7 | 7 | import ipaddress |
8 | 8 | import json |
9 | 9 | import logging |
| 10 | +import os |
10 | 11 | import os.path |
11 | 12 | import socket |
12 | 13 | import sys |
13 | 14 | import tempfile |
| 15 | +import threading |
| 16 | +import time |
| 17 | +import traceback |
14 | 18 | from collections import defaultdict |
15 | 19 | from functools import wraps |
16 | | -from typing import Any, DefaultDict, Iterable, List, Mapping, Optional |
| 20 | +from typing import Any, Callable, DefaultDict, Iterable, List, Mapping, Optional |
17 | 21 | from urllib.parse import urlparse |
18 | 22 |
|
19 | 23 | import orjson |
|
49 | 53 | VALID_URL_SCHEMES = ["https"] |
50 | 54 | CLOUD_DEPLOYMENT_MODE = "cloud" |
51 | 55 | _HAS_LOGGED_FOR_SERIALIZATION_ERROR = False |
| 56 | +_DEADLOCK_DIAGNOSTICS_ENV = "AIRBYTE_CDK_DEADLOCK_DIAGNOSTICS" |
| 57 | + |
| 58 | + |
| 59 | +class _DeadlockDiagnostics: |
| 60 | + def __init__( |
| 61 | + self, |
| 62 | + *, |
| 63 | + interval_seconds: float = 30.0, |
| 64 | + stall_interval_count: int = 3, |
| 65 | + dump_repeat_interval_count: int = 10, |
| 66 | + time_fn: Callable[[], float] = time.monotonic, |
| 67 | + write_fn: Callable[[bytes], None] | None = None, |
| 68 | + ) -> None: |
| 69 | + self._interval_seconds = interval_seconds |
| 70 | + self._stall_interval_count = stall_interval_count |
| 71 | + self._dump_repeat_interval_count = dump_repeat_interval_count |
| 72 | + self._time_fn = time_fn |
| 73 | + self._write_fn = write_fn or self._write_to_stderr |
| 74 | + self._stop = threading.Event() |
| 75 | + self._lock = threading.Lock() |
| 76 | + self._thread: threading.Thread | None = None |
| 77 | + self._start_time = self._time_fn() |
| 78 | + self._messages_written = 0 |
| 79 | + self._bytes_written = 0 |
| 80 | + self._print_blocked = False |
| 81 | + self._print_blocked_since = 0.0 |
| 82 | + self._last_messages_written = 0 |
| 83 | + self._stall_count = 0 |
| 84 | + |
| 85 | + def start(self) -> None: |
| 86 | + self._thread = threading.Thread( |
| 87 | + target=self._run, |
| 88 | + name="airbyte-deadlock-diagnostics", |
| 89 | + daemon=True, |
| 90 | + ) |
| 91 | + self._thread.start() |
| 92 | + |
| 93 | + def stop(self) -> None: |
| 94 | + self._stop.set() |
| 95 | + |
| 96 | + def mark_print_started(self) -> None: |
| 97 | + with self._lock: |
| 98 | + self._print_blocked = True |
| 99 | + self._print_blocked_since = self._time_fn() |
| 100 | + |
| 101 | + def mark_print_finished(self) -> None: |
| 102 | + with self._lock: |
| 103 | + self._print_blocked = False |
| 104 | + |
| 105 | + def record_message(self, data: str) -> None: |
| 106 | + with self._lock: |
| 107 | + self._messages_written += 1 |
| 108 | + self._bytes_written += len(data.encode()) |
| 109 | + |
| 110 | + def emit_heartbeat(self) -> None: |
| 111 | + now = self._time_fn() |
| 112 | + with self._lock: |
| 113 | + messages_written = self._messages_written |
| 114 | + bytes_written = self._bytes_written |
| 115 | + print_blocked = self._print_blocked |
| 116 | + print_blocked_since = self._print_blocked_since |
| 117 | + |
| 118 | + if messages_written == self._last_messages_written and messages_written > 0: |
| 119 | + self._stall_count += 1 |
| 120 | + else: |
| 121 | + self._stall_count = 0 |
| 122 | + self._last_messages_written = messages_written |
| 123 | + stall_count = self._stall_count |
| 124 | + |
| 125 | + line = self._heartbeat_line( |
| 126 | + now, |
| 127 | + messages_written, |
| 128 | + bytes_written, |
| 129 | + print_blocked, |
| 130 | + print_blocked_since, |
| 131 | + ) |
| 132 | + if self._should_dump_threads(stall_count): |
| 133 | + line += self._thread_dump() |
| 134 | + |
| 135 | + try: |
| 136 | + self._write_fn(line.encode()) |
| 137 | + except OSError: |
| 138 | + return |
| 139 | + |
| 140 | + def _run(self) -> None: |
| 141 | + while not self._stop.wait(timeout=self._interval_seconds): |
| 142 | + self.emit_heartbeat() |
| 143 | + |
| 144 | + def _heartbeat_line( |
| 145 | + self, |
| 146 | + now: float, |
| 147 | + messages_written: int, |
| 148 | + bytes_written: int, |
| 149 | + print_blocked: bool, |
| 150 | + print_blocked_since: float, |
| 151 | + ) -> str: |
| 152 | + blocked = "YES" if print_blocked else "NO" |
| 153 | + blocked_duration = ( |
| 154 | + f" blocked_since={now - print_blocked_since:.0f}s" if print_blocked else "" |
| 155 | + ) |
| 156 | + return ( |
| 157 | + f"STDOUT_HEARTBEAT: t={now - self._start_time:.0f}s " |
| 158 | + f"msgs={messages_written} bytes={bytes_written} " |
| 159 | + f"print_blocked={blocked}{blocked_duration}" |
| 160 | + f"{self._queue_stats()}\n" |
| 161 | + ) |
| 162 | + |
| 163 | + def _queue_stats(self) -> str: |
| 164 | + from airbyte_cdk.sources.concurrent_source.queue_registry import get_queue |
| 165 | + |
| 166 | + queue = get_queue() |
| 167 | + if queue is None: |
| 168 | + return "" |
| 169 | + |
| 170 | + try: |
| 171 | + return f" queue_size={queue.qsize()} queue_full={queue.full()}" |
| 172 | + except NotImplementedError: |
| 173 | + return "" |
| 174 | + |
| 175 | + def _should_dump_threads(self, stall_count: int) -> bool: |
| 176 | + if stall_count == self._stall_interval_count: |
| 177 | + return True |
| 178 | + return ( |
| 179 | + stall_count > self._stall_interval_count |
| 180 | + and (stall_count - self._stall_interval_count) % self._dump_repeat_interval_count == 0 |
| 181 | + ) |
| 182 | + |
| 183 | + def _thread_dump(self) -> str: |
| 184 | + thread_names = {thread.ident: thread.name for thread in threading.enumerate()} |
| 185 | + lines = ["=== THREAD DUMP (stall detected) ===\n"] |
| 186 | + for thread_id, frame in sys._current_frames().items(): |
| 187 | + lines.append(f"\nThread {thread_names.get(thread_id, 'unknown')} ({thread_id}):\n") |
| 188 | + lines.extend(traceback.format_stack(frame)) |
| 189 | + lines.append("=== END THREAD DUMP ===\n") |
| 190 | + return "".join(lines) |
| 191 | + |
| 192 | + @staticmethod |
| 193 | + def _write_to_stderr(data: bytes) -> None: |
| 194 | + os.write(2, data) |
52 | 195 |
|
53 | 196 |
|
54 | 197 | class AirbyteEntrypoint(object): |
@@ -391,13 +534,34 @@ def _emit_queued_messages(self, source: Source) -> Iterable[AirbyteMessage]: |
391 | 534 | def launch(source: Source, args: List[str]) -> None: |
392 | 535 | source_entrypoint = AirbyteEntrypoint(source) |
393 | 536 | parsed_args = source_entrypoint.parse_args(args) |
| 537 | + diagnostics = ( |
| 538 | + _DeadlockDiagnostics() |
| 539 | + if os.environ.get(_DEADLOCK_DIAGNOSTICS_ENV, "").lower() == "true" |
| 540 | + else None |
| 541 | + ) |
| 542 | + if diagnostics: |
| 543 | + diagnostics.start() |
| 544 | + |
394 | 545 | # temporarily removes the PrintBuffer because we're seeing weird print behavior for concurrent syncs |
395 | 546 | # Refer to: https://github.com/airbytehq/oncall/issues/6235 |
396 | | - with PRINT_BUFFER: |
397 | | - for message in source_entrypoint.run(parsed_args): |
398 | | - # simply printing is creating issues for concurrent CDK as Python uses different two instructions to print: one for the message and |
399 | | - # the other for the break line. Adding `\n` to the message ensure that both are printed at the same time |
400 | | - print(f"{message}\n", end="") |
| 547 | + try: |
| 548 | + with PRINT_BUFFER: |
| 549 | + for message in source_entrypoint.run(parsed_args): |
| 550 | + # simply printing is creating issues for concurrent CDK as Python uses different two instructions to print: one for the message and |
| 551 | + # the other for the break line. Adding `\n` to the message ensure that both are printed at the same time |
| 552 | + data = f"{message}\n" |
| 553 | + if diagnostics: |
| 554 | + diagnostics.mark_print_started() |
| 555 | + try: |
| 556 | + print(data, end="") |
| 557 | + finally: |
| 558 | + if diagnostics: |
| 559 | + diagnostics.mark_print_finished() |
| 560 | + if diagnostics: |
| 561 | + diagnostics.record_message(data) |
| 562 | + finally: |
| 563 | + if diagnostics: |
| 564 | + diagnostics.stop() |
401 | 565 |
|
402 | 566 |
|
403 | 567 | def _init_internal_request_filter() -> None: |
|
0 commit comments