실습: 셋톱박스 2대의 로그를 대시보드로 읽어 보기

실습 · 예시 로그 2개 · 결과 수치는 실제 분석 엔진을 돌려 얻은 값 · 2026년 10월 5일

이 글은 대시보드의 예시 데이터로 미리보기에 들어 있는 로그 두 개를 처음부터 끝까지 읽어 보는 실습입니다. 숫자는 짐작이 아니라 대시보드와 같은 분석 코드(log-parser.js)를 Node.js로 실행해 얻은 값입니다. 로그는 설명용으로 만든 합성 데이터이며, 아래에서 원본 파일을 내려받아 직접 따라 할 수 있습니다.

1. 상황 설정

같은 기종의 셋톱박스 두 대에서 하루씩 로그를 받았다고 가정합니다. 받은 제보는 두 가지입니다.

• A 기기: "오후에 채널 목록을 넘기다 앱이 꺼졌고, 저녁에는 VOD 재생 중 화면이 검게 변했다."
• B 기기: "오후에 리모컨이 한동안 안 먹었고, 밤에 EPG(편성표)를 다시 열면 처음부터 로딩된다."

목표는 각 증상이 로그의 어느 기록과 맞는지 찾고, 보고서에 쓸 첫 발생 시각과 근거 줄을 뽑는 것입니다.

2. 숫자 타일부터: 35줄이 27건이 되는 이유

두 파일은 합쳐 35줄인데 기록은 27건으로 셉니다. 크래시 스택트레이스나 ANR 보고처럼 한 번에 남긴 여러 줄짜리 메시지는 logcat이 줄마다 같은 시각·PID·TID·레벨·태그를 붙여 출력하기 때문입니다. 대시보드는 이런 줄을 한 건으로 합칩니다.

차이는 결함 수에서 더 크게 납니다. 레벨이 E 또는 F인 줄을 그냥 세면 19줄이지만, 합쳐서 세면 11건입니다. A 기기의 앱 크래시 하나가 5줄, 네이티브 크래시의 DEBUG 덤프가 3줄, B 기기의 ANR 보고가 3줄이기 때문입니다. 텍스트 편집기에서 E 로 검색해 개수를 세던 방식이라면 크래시 1건이 5건처럼 보였을 것입니다.

3. 감지된 장애 패턴: 무엇이 "죽었는지"부터

대시보드는 심각도 순으로 다음 8종을 보여 줍니다(규칙 설명은 패턴 사전).

여기서 눈여겨볼 점은 강제 종료 2건이 오류 건수에는 전혀 잡히지 않는다는 것입니다. lowmemorykiller의 기록은 I(정보) 레벨이라, 결함 11건 어디에도 EPG 앱이 죽었다는 흔적이 없습니다. "EPG가 처음부터 다시 로딩된다"는 B 기기 제보의 답이 바로 이 기록입니다.

4. A 기기: 앱 크래시와 네이티브 크래시

4-1. 오후 2시 22분, 채널 목록 크래시

10-01 14:22:03.900  1102  1102 E AndroidRuntime: FATAL EXCEPTION: main
10-01 14:22:03.900  1102  1102 E AndroidRuntime: Process: com.example.tv, PID: 1102
10-01 14:22:03.900  1102  1102 E AndroidRuntime: java.lang.NullPointerException: Attempt to invoke virtual method 'int java.lang.String.length()' on a null object reference
10-01 14:22:03.900  1102  1102 E AndroidRuntime: 	at com.example.tv.ui.ChannelListAdapter.onBindViewHolder(ChannelListAdapter.java:88)
10-01 14:22:03.900  1102  1102 E AndroidRuntime: 	at androidx.recyclerview.widget.RecyclerView$Adapter.bindViewHolder(RecyclerView.java:7254)
10-01 14:22:04.115   512   700 I ActivityManager: Process com.example.tv (pid 1102) has died: fg  TOP
10-01 14:22:05.002   512   540 I ActivityManager: Start proc 1388:com.example.tv/u0a12 for activity {...}

패턴 카드의 "첫 기록 원문"을 누르면 위의 크래시가 5줄 통째로 열립니다. 앱 패키지의 가장 위 줄이 ChannelListAdapter.java:88이고, 문자열이 null인데 길이를 구하려 했습니다. 채널 이름이 비어 있는 항목이 있었을 가능성이 높습니다. 0.2초 뒤 has died: fg TOP(화면에 보이던 앱이 죽음), 1초 뒤 Start proc 1388(새 PID로 재시작)이 이어집니다. 이후 이 앱의 로그를 따라갈 때는 PID가 1102에서 1388로 바뀐다는 점을 기억해야 합니다.

4-2. 오후 6시 47분, 재생 중 검은 화면

10-01 18:47:51.220  2201  2250 F libc    : Fatal signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 0x0 in tid 2250 (CodecLooper), pid 2201 (com.example.player)
10-01 18:47:51.540  2290  2290 F DEBUG   : pid: 2201, tid: 2250, name: CodecLooper  >>> com.example.player <<<
10-01 18:47:51.910  2290  2290 F DEBUG   : Tombstone written to: /data/tombstones/tombstone_02

플레이어 앱의 CodecLooper 스레드가 널 주소(fault addr 0x0)에 접근해 죽었습니다. 스레드 이름으로 보아 코덱을 다루는 네이티브 계층입니다. 자바 스택트레이스가 없으므로 원인 위치는 tombstone_02 파일의 백트레이스에서 찾아야 합니다(네이티브 크래시 읽는 법). DEBUG 줄의 PID(2290)가 크래시한 프로세스(2201)와 다른 것은 정상입니다 — 덤프를 쓰는 별도 프로세스가 남긴 기록이기 때문입니다.

참고로 A 기기에는 이 크래시 직후 has died 기록이 없습니다. 예시 로그를 짧게 만든 탓이지만, 실제 로그에서도 수집 방식에 따라 이런 후속 기록이 빠질 수 있으니 패턴 하나가 없다고 사건이 없었다고 단정하지 마세요.

5. B 기기: ANR과 메모리 부족

5-1. 오후 1시 58분, 리모컨 무반응

10-02 13:58:20.400   512   540 E ActivityManager: ANR in com.example.tv (com.example.tv/.MainActivity)
10-02 13:58:20.400   512   540 E ActivityManager: PID: 1102
10-02 13:58:20.400   512   540 E ActivityManager: Reason: Input dispatching timed out (Waiting to send key event because ...)

Reason:이 Input dispatching timed out이고 key event를 기다렸다고 합니다. 리모컨 키 입력을 앱의 메인 스레드가 기본 5초 안에 처리하지 못했다는 뜻으로, 제보 내용과 정확히 맞습니다. 다음 단계는 그 순간 메인 스레드가 무엇을 하고 있었는지 traces 파일로 확인하는 것입니다(ANR 분석 글).

5-2. 오후 8시 15분, EPG가 처음부터 로딩됨

10-02 20:15:09.700   330   330 I lowmemorykiller: Kill 'com.example.epg' (1650), uid 10031, oom_score_adj 900 to free 48212kB rss, 2048kB swap
10-02 20:15:09.731   512   700 I ActivityManager: Process com.example.epg (pid 1650) has died: cch+5 CEM
10-02 20:15:40.118   330   330 I lowmemorykiller: Kill 'com.example.weather' (1702), uid 10044, oom_score_adj 905 to free 31908kB rss, 1024kB swap
10-02 20:15:40.150   512   700 I ActivityManager: Process com.example.weather (pid 1702) has died: cch+15 CEM

30초 사이에 백그라운드 앱 두 개가 메모리 확보를 위해 강제 종료됐습니다. oom_score_adj가 900·905로, 둘 다 화면 뒤에 대기 중이던 캐시 프로세스입니다. 사용자가 EPG를 다시 열면 프로세스가 새로 떠야 하므로 "처음부터 로딩"되는 것입니다. 이것은 EPG 앱의 버그가 아니라 그 시각 메모리를 많이 쓴 다른 무언가를 찾아야 하는 문제입니다 (메모리 강제 종료 글).

20시 16분의 chatty ... identical 37 lines도 놓치지 마세요. 시스템 프로세스의 어떤 기록이 37줄 생략됐다는 뜻이라, 이 시간대의 실제 기록량은 보이는 것보다 많습니다.

6. 반복 오류 묶음: 두 기기에 공통인 것

결함 11건은 실제로 6종입니다. 그중 가장 많은 것은 크래시가 아니라 NetClient의 요청 시간 초과 6건이고, 두 기기 모두에서, 그것도 매일 오전 9시 5분경 5초 간격으로 세 번씩 나타났습니다. 3012ms, 2987ms처럼 숫자가 달라 텍스트 검색으로는 따로 보이지만, 숫자를 지운 서명이 같아 한 묶음이 됐습니다.

기기 두 대가 같은 시각에 같은 오류를 낸다면 기기 문제보다는 그 시각에 도는 예약 작업이나 서버 쪽 사정을 먼저 의심하는 것이 합리적입니다. 사용자 제보에는 없던 내용이지만, 이런 것을 찾아내는 것이 묶음 표의 역할입니다. 반대로 건수가 많다고 해서 사용자 영향이 큰 것은 아닙니다 — 이 시간 초과는 재시도로 끝났을 수도 있습니다.

7. 보고서로 정리하면

[A 기기 / device-A.log / 10-01]
1) 14:22:03 com.example.tv 크래시 — NullPointerException @ ChannelListAdapter.java:88
   → 14:22:05 자동 재시작(PID 1102→1388). 채널명 null 항목 의심.
2) 18:47:51 com.example.player 네이티브 크래시 — SIGSEGV, fault addr 0x0, 스레드 CodecLooper
   → tombstone_02 확보 필요(bugreport).

[B 기기 / device-B.log / 10-02]
3) 13:58:20 com.example.tv ANR — Input dispatching timed out(key event)
   → traces 확보해 메인 스레드 스택 확인 필요.
4) 20:15:09~20:15:40 lmkd 강제 종료 2건(epg adj 900, weather adj 905)
   → EPG 재로딩 원인. 같은 시각 메모리 사용량 큰 프로세스 조사 필요.

[공통]
5) 매일 09:05경 NetClient 요청 시간 초과 3회(5초 간격) — 2대 모두. 서버·예약 작업 확인.

이 양식은 원인 구간 좁히기의 보고 양식을 따른 것입니다. 각 줄에 시각과 파일명이 있으니, 받는 사람이 원문을 바로 찾아볼 수 있습니다.

정리: 이 실습에서 확인한 것

• 여러 줄 메시지를 합쳐 세면 결함 19줄이 11건이 되고, 묶으면 6종이 됩니다. 개수보다 종류와 첫 시각이 중요합니다.
• 메모리 강제 종료처럼 오류 레벨이 아닌 장애는 패턴 감지로만 보입니다.
• 여러 기기를 함께 올리면 공통 패턴(같은 시각의 같은 오류)이 드러납니다.
• 대시보드는 어디를 볼지 알려 줄 뿐입니다. 원인 확정에는 traces·tombstone 같은 추가 자료와 사람의 판단이 필요합니다.