-
Notifications
You must be signed in to change notification settings - Fork 74
[Feat] [SDK-399] Capture logcat output as telemetry events #369
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: master
Are you sure you want to change the base?
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,198 @@ | ||
| package com.rollbar.android; | ||
|
|
||
| import android.util.Log; | ||
|
|
||
| import com.rollbar.api.payload.data.Level; | ||
| import com.rollbar.api.payload.data.Source; | ||
| import com.rollbar.notifier.telemetry.TelemetryEventTracker; | ||
|
|
||
| import java.io.BufferedReader; | ||
| import java.io.IOException; | ||
| import java.io.InputStreamReader; | ||
| import java.nio.charset.Charset; | ||
| import java.util.regex.Matcher; | ||
| import java.util.regex.Pattern; | ||
|
|
||
| class LogcatTelemetryCapture { | ||
|
|
||
| // threadtime format: "MM-dd HH:mm:ss.SSS PID TID L Tag: message" | ||
| private static final Pattern LOGCAT_LINE_PATTERN = Pattern.compile( | ||
| "^\\d{2}-\\d{2} \\d{2}:\\d{2}:\\d{2}\\.\\d{3}\\s+\\d+\\s+\\d+\\s+([VDIWEF])\\s+(.+?):\\s(.*)$" | ||
| ); | ||
|
|
||
| private final TelemetryEventTracker tracker; | ||
| private final Level minimumLevel; | ||
| private final String selfTag; | ||
| private final ProcessFactory processFactory; | ||
|
|
||
| private Thread thread; | ||
| private Process process; | ||
| private volatile boolean running; | ||
|
|
||
| LogcatTelemetryCapture( | ||
| TelemetryEventTracker tracker, | ||
| Level minimumLevel, | ||
| String selfTag | ||
| ) { | ||
| this(tracker, minimumLevel, selfTag, defaultProcessFactory()); | ||
| } | ||
|
|
||
| LogcatTelemetryCapture( | ||
| TelemetryEventTracker tracker, | ||
| Level minimumLevel, | ||
| String selfTag, | ||
| ProcessFactory processFactory | ||
| ) { | ||
| this.tracker = tracker; | ||
| this.minimumLevel = minimumLevel != null ? minimumLevel : Level.WARNING; | ||
| this.selfTag = selfTag; | ||
| this.processFactory = processFactory; | ||
| } | ||
|
|
||
| synchronized void start() { | ||
| if (running) { | ||
| return; | ||
| } | ||
| try { | ||
| this.process = processFactory.start(logcatPriorityFor(this.minimumLevel)); | ||
| } catch (IOException e) { | ||
| Log.w(Rollbar.TAG, "Failed to start logcat telemetry capture", e); | ||
| return; | ||
| } | ||
| running = true; | ||
| thread = new Thread(new Runnable() { | ||
| @Override | ||
| public void run() { | ||
| readLoop(); | ||
| } | ||
| }, "rollbar-logcat-telemetry"); | ||
| thread.setDaemon(true); | ||
| thread.start(); | ||
| } | ||
|
|
||
| synchronized void stop() { | ||
| if (!running) { | ||
| return; | ||
| } | ||
| running = false; | ||
| if (process != null) { | ||
| process.destroy(); | ||
| process = null; | ||
| } | ||
| if (thread != null) { | ||
| thread.interrupt(); | ||
| thread = null; | ||
| } | ||
| } | ||
|
|
||
| private void readLoop() { | ||
| Process currentProcess = this.process; | ||
| if (currentProcess == null) { | ||
| return; | ||
| } | ||
| BufferedReader reader = new BufferedReader( | ||
| new InputStreamReader(currentProcess.getInputStream(), Charset.forName("UTF-8"))); | ||
| try { | ||
| String line; | ||
| while (running && (line = reader.readLine()) != null) { | ||
| processLine(line); | ||
| } | ||
| } catch (IOException e) { | ||
| // Process died or was destroyed — expected on stop(). | ||
| } finally { | ||
| try { | ||
| reader.close(); | ||
| } catch (IOException ignored) { | ||
| } | ||
| } | ||
| } | ||
|
|
||
| void processLine(String line) { | ||
| if (line == null) { | ||
| return; | ||
| } | ||
| Matcher matcher = LOGCAT_LINE_PATTERN.matcher(line); | ||
| if (!matcher.matches()) { | ||
| return; | ||
| } | ||
|
|
||
| String priority = matcher.group(1); | ||
| String tag = matcher.group(2).trim(); | ||
| String message = matcher.group(3); | ||
|
|
||
| if (selfTag != null && selfTag.equals(tag)) { | ||
| return; | ||
| } | ||
|
|
||
| Level level = mapPriorityToLevel(priority); | ||
| if (level == null) { | ||
| return; | ||
| } | ||
| if (level.level() < minimumLevel.level()) { | ||
| return; | ||
| } | ||
|
|
||
| try { | ||
| tracker.recordManualEventFor(level, Source.CLIENT, message); | ||
| } catch (Exception e) { | ||
|
Comment on lines
+135
to
+137
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. 🟡 LogcatTelemetryCapture.processLine() calls tracker.recordManualEventFor(), which classifies automatically-captured logcat entries as TelemetryType.MANUAL instead of TelemetryType.LOG. This misrepresents the data in the Rollbar UI and makes it impossible to filter automatic log capture separately from developer-placed manual instrumentation checkpoints. Fix: change the call on line 136 to tracker.recordLogEventFor(level, Source.CLIENT, message). Extended reasoning...What the bug is and how it manifests In LogcatTelemetryCapture.processLine() (lines 135-137), after parsing a logcat line into its priority, tag, and message components, the code records the telemetry event via: The TelemetryEventTracker interface exposes two distinct methods: recordLogEventFor() which produces a TelemetryType.LOG event, and recordManualEventFor() which produces a TelemetryType.MANUAL event. The wrong method is being called here. The specific code path that triggers it Every time LogcatTelemetryCapture reads and parses a logcat line (in readLoop() -> processLine()), it unconditionally routes through recordManualEventFor(), stamping a "manual" type onto what is in fact automatically-captured log output. This fires on every logcat line at or above the configured minimum level throughout the lifetime of the capture session. Why existing code does not prevent it Both methods share the identical signature (Level, Source, String), so there is no compile-time warning. The tests in LogcatTelemetryCaptureTest verify calls to recordManualEventFor(), which means they pass despite the semantic error - the tests themselves inherit the wrong expectation from the production code. There is no type enforcement at the interface level to distinguish the two use cases. What the impact would be In the Rollbar payload, each captured logcat line will carry type: "manual" instead of type: "log". Users who try to filter their telemetry trail to see only automatic log output will see nothing; users looking at manual checkpoints will see their timeline polluted with automatically-captured logcat lines. The two categories - developer-placed instrumentation and automatic system log capture - become indistinguishable. How to fix it Replace the single call on line 136: The corresponding test assertions that verify recordManualEventFor() should also be updated to verify recordLogEventFor(). Step-by-step proof
|
||
| // Never let a broken tracker kill the reader thread. | ||
| } | ||
| } | ||
|
|
||
| static Level mapPriorityToLevel(String priority) { | ||
| if (priority == null || priority.isEmpty()) { | ||
| return null; | ||
| } | ||
| switch (priority.charAt(0)) { | ||
| case 'V': | ||
| case 'D': | ||
| return Level.DEBUG; | ||
| case 'I': | ||
| return Level.INFO; | ||
| case 'W': | ||
| return Level.WARNING; | ||
| case 'E': | ||
| return Level.ERROR; | ||
| case 'F': | ||
| return Level.CRITICAL; | ||
| default: | ||
| return null; | ||
| } | ||
| } | ||
|
|
||
| static String logcatPriorityFor(Level level) { | ||
| if (level == null) { | ||
| return "W"; | ||
| } | ||
| switch (level) { | ||
| case DEBUG: | ||
| return "D"; | ||
| case INFO: | ||
| return "I"; | ||
| case WARNING: | ||
| return "W"; | ||
| case ERROR: | ||
| return "E"; | ||
| case CRITICAL: | ||
| return "F"; | ||
| default: | ||
| return "W"; | ||
| } | ||
| } | ||
|
Comment on lines
+163
to
+181
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. 🔴 When minimumLevel=Level.DEBUG is configured, Verbose (V) logcat entries are silently dropped because logcatPriorityFor(Level.DEBUG) returns "D", launching logcat with "*:D" which excludes V-priority messages at the OS level. Since mapPriorityToLevel("V") returns Level.DEBUG, the SDK itself declares V as DEBUG-level, but the logcat filter never delivers those messages to the reader thread. Fix: change logcatPriorityFor(Level.DEBUG) to return "V" (and update the corresponding test assertion). Extended reasoning...The inconsistency between the two mapping functions mapPriorityToLevel() maps both "V" and "D" to Level.DEBUG (lines 147–149 of LogcatTelemetryCapture.java). This is the SDK explicit declaration that Verbose logcat entries are semantically equivalent to DEBUG-level telemetry. The regex pattern [VDIWEF] in LOGCAT_LINE_PATTERN further confirms that V-priority lines are expected to be parsed and processed. How the bug manifests logcatPriorityFor(Level.DEBUG) returns "D" (line 169). This return value is used in start() to build the logcat command: logcat -v threadtime :D. Android logcat priority ordering is V(2) < D(3) < I(4) < W(5) < E(6) < F(7). The filter ":D" means "emit messages at priority D and above," so all V-priority messages are discarded by the Android OS-level logcat daemon before they ever reach the app BufferedReader in readLoop(). Why existing code does not prevent it The software-level filter in processLine() (the level.level() < minimumLevel.level() check) is never reached for V messages because they are filtered out upstream at the OS/daemon level. The test suite encodes the broken behavior directly: assertEquals("D", LogcatTelemetryCapture.logcatPriorityFor(Level.DEBUG)) at line 48 of LogcatTelemetryCaptureTest passes with the current (buggy) implementation and will need to be updated to assert "V". Concrete step-by-step proof
Impact Any user who opts into captureLogsAsTelemetry and sets minimumLogCaptureLevel(Level.DEBUG) to capture maximum detail will silently lose all V-priority log output. Since Level.DEBUG is the lowest Rollbar level and is advertised by mapPriorityToLevel as the home for Verbose entries, this represents a complete failure to deliver on the feature implied contract. Fix Change logcatPriorityFor(Level.DEBUG) to return "V" instead of "D", and update the test assertion from assertEquals("D", ...) to assertEquals("V", ...). This aligns the OS-level filter with the SDK own semantic mapping and ensures V messages flow through to processLine(). |
||
|
|
||
| interface ProcessFactory { | ||
| Process start(String priorityFilter) throws IOException; | ||
| } | ||
|
|
||
| private static ProcessFactory defaultProcessFactory() { | ||
| return new ProcessFactory() { | ||
| @Override | ||
| public Process start(String priorityFilter) throws IOException { | ||
| return new ProcessBuilder( | ||
| "logcat", "-v", "threadtime", "*:" + priorityFilter) | ||
| .redirectErrorStream(true) | ||
| .start(); | ||
| } | ||
| }; | ||
|
Comment on lines
+187
to
+196
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. 🔴 The logcat command in Extended reasoning...What the bug is and how it manifests The The specific code path that triggers it
Why existing code doesn't prevent it There is no timestamp comparison, no replay guard, and no duplicate-detection logic anywhere in What the impact would be On a device that has been running for even a short time, the logcat ring buffer easily contains hundreds to thousands of entries. At app startup with How to fix it Add return new ProcessBuilder(
"logcat", "-v", "threadtime", "-T", "1", "*:" + priorityFilter)
.redirectErrorStream(true)
.start();An alternative is Step-by-step proof
|
||
| } | ||
| } | ||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
🔴 When the logcat process dies unexpectedly (e.g., killed by OS, not available on some ROMs),
readLine()returns null andreadLoop()exits silently while leavingrunning=trueand the deadProcessreference intact. Any subsequent call tostart()hits theif (running) returnguard and silently does nothing, permanently disabling telemetry capture with no indication to the caller. Fix by resettingrunning=falseand cleaning up the dead process inreadLoop()'sfinallyblock (or by callingstop()when the loop exits withrunningstilltrue).Extended reasoning...
The bug
LogcatTelemetryCapture.readLoop()exits thewhileloop in two ways: (1)runningbecomesfalse(normalstop()path), or (2)reader.readLine()returnsnullbecause the logcat process has died. Thefinallyblock handles only reader cleanup; it does not reset therunningflag or clean up the deadProcessreference.Concrete code path
After
start()launches the logcat subprocess, the reader thread runsreadLoop(). Suppose the OS kills the logcat process (memory pressure, permission restriction on custom ROMs, or logcat simply unavailable).currentProcess.getInputStream()reaches EOF andreadLine()returnsnull. Thewhilecondition fails and the loop exits. Control falls into thefinallyblock, which closes theBufferedReaderand returns. At this point:running == true,processis the now-deadProcessobject, andthreadholds the terminatedThread.Why existing code doesn't prevent it
The
stop()method correctly setsrunning=false, destroys the process, and nulls both fields — butstop()is only called externally (e.g., fromRollbar.close()). ThereadLoop()method has no symmetric cleanup path for the abnormal-exit case. The comment in thecatchblock says "expected on stop()", which is true for theIOExceptionpath but ignores the equally-possible null-readlinepath.Impact
Once the logcat process dies unexpectedly,
runningstaystrueforever. Every future call tostart()returns immediately atif (running) returnwithout spawning a new process. Telemetry capture is silently disabled with no log message, no exception, and no recovery path short of the caller knowing to callstop()first. On standard Android this is uncommon, but on custom ROMs, restricted-permission environments, or any device wherelogcatis unavailable, the capture will silently fail on the very first process start.Step-by-step proof
start()is called →running = true, subprocess started, reader thread beginsreadLoop().readLine()returnsnull→ while-loop exits normally.finallycloses theBufferedReaderonly.runningis stilltrue.threadfield still holds a reference to the now-dead thread.start()again (e.g., after a configuration change or retry logic): hitssynchronized void start() { if (running) return; }→ returns immediately, no new process launched.LogcatTelemetryCaptureinstance.Fix
In the
finallyblock ofreadLoop(), after closing the reader, check whetherrunningis stilltrue(indicating unexpected exit rather than a cleanstop()call) and if so callstop()— or manually replicate the cleanup: acquire the lock, setrunning=false, callprocess.destroy(), and null bothprocessandthread. Care should be taken to synchronize this cleanup with thestart()/stop()methods to avoid races.