선로에 실제로 흐르는 것을 봤다

장치가 HTTP 로 보낸 자료가 서버에 안 들어온다. 장치 로그에는 전송 완료가 찍혀 있었다. 양쪽 코드를 아무리 봐도 이유를 못 찾았다.

Open Table of contents

중간을 봤다
응답 코드를 안 보고 있었다
무엇이 잘못됐는지 봤다
코드와 선로의 차이
검증 — 장치 간 통신과 정상 기록
정리

중간을 봤다

선로를 직접 떴다.

$ tcpdump -i eth0 -n host api-01 and port 8080 -w capture.pcap

pcap 을 받아 보니 장치가 요청을 보내고 있었고 서버가 응답도 했다.

device-01.51234 > api-01.8080: Flags [P.], length 214
api-01.8080 > device-01.51234: Flags [P.], length 89

응답 내용을 봤다.

HTTP/1.1 400 Bad Request
{"error":"invalid json"}

400 이다. 장치는 이것을 성공으로 처리하고 있었다.

응답 코드를 안 보고 있었다

전송 코드를 봤다.

int send_data(const char *json) {
    int n = write(sock, req, req_len);
    if (n < 0) return -1;

    log_info("전송 완료 %d bytes", n);
    return 0;
}

write 가 성공하면 끝이고 응답을 안 읽는다. 그 반환값은 커널의 전송 버퍼에 몇 바이트를 넣었는지일 뿐이고 상대가 받아들였는지는 더 뒤의 일이다.

보낸 것과 상대가 받아들인 것은 다르다.

int send_data(const char *json) {
    int n = write(sock, req, req_len);
    if (n < 0) return -1;

    char resp[512];
    int r = read_response(sock, resp, sizeof(resp));
    if (r < 0) return -2;

    int code = parse_status_code(resp);
    if (code != 200) {
        log_error("서버 응답 %d: %s", code, resp);
        return -3;
    }
    return 0;
}

read_response 로 응답을 읽고 parse_status_code 로 확인하는 단계를 넣었다.

무엇이 잘못됐는지 봤다

400 이 나온 이유를 찾으려고 요청 본문을 봤다.

$ tcpdump -i eth0 -n host api-01 -A | grep -A5 "POST"

POST /api/data HTTP/1.1
Content-Length: 214

{"device":"D001","ts":1472457600,"temp":24.5,"hum":58.2,

본문이 잘려 있다. Content-Length 가 214인데 실제 본문이 그보다 짧고 버퍼 크기 계산이 틀렸다.

char body[256];
int len = snprintf(body, sizeof(body), "{\"device\":\"%s\",...}", ...);
/* len 은 "쓰려고 했던 길이"다. 잘렸으면 실제보다 크다 */

sprintf(header, "Content-Length: %d\r\n", len);

snprintf 는 잘려도 원래 쓰려던 길이를 돌려주는데 그 값을 길이로 쓰니 안 맞는다.

int len = snprintf(body, sizeof(body), "...");
if (len >= (int)sizeof(body)) {
    log_error("본문이 버퍼를 넘음: %d >= %zu", len, sizeof(body));
    return -1;
}

넘치면 실패시키고 버퍼도 늘렸다.

코드와 선로의 차이

양쪽 코드를 읽는 것보다 중간을 보는 것이 빨랐다. 코드를 읽으면 이렇게 동작할 것이다를 보고 선로를 보면 실제로 이렇게 나갔다를 본다.

둘이 다를 때 원인이 나온다. 어긋나면 언제나 tcpdump 가 보여 준 쪽이 사실이다. 보내는 쪽도 받는 쪽도 자기 관점만 알고 중간이 진실이다.

이 원인을 코드만 읽어서 찾았으면 며칠이 걸렸을 텐데 tcpdump 로 중간을 잡아 보니 몇 분 만에 답이 나왔다.

검증 — 장치 간 통신과 정상 기록

센서와 장치 사이의 I2C 통신도 마찬가지였다. 논리 분석기로 선을 봤다.

START | ADDR(W) | ACK | REG | ACK | START | ADDR(R) | ACK | DATA | NACK | STOP

기대한 순서와 다른 곳에서 응답이 없으면 그 지점이 문제다. 한 번은 주소 다음에 ACK 가 없었는데 장치가 그 주소로 응답 안 한다는 뜻이라 주소가 틀렸거나 전원이 없는 것이다.

for (uint8_t a = 0x08; a < 0x78; a++) {
    if (i2c_probe(a) == 0) {
        printf("응답: 0x%02X\n", a);
    }
}

주소를 훑어 보니 기대한 주소와 다른 곳에서 응답했다. 사양서에 주소 설정 핀이 있었고 회로에서 다르게 연결돼 있었다.

정상일 때의 통신도 한 번 저장해 뒀다.

capture/normal-20160829.pcap
capture/fail-20160830.pcap

문제가 났을 때 정상 pcap 과 비교하면 어디가 다른지 바로 보인다. 정상 기록이 없으면 무엇이 이상한지 판단할 기준이 없다.

정리

보낸 것과 상대가 받아들인 것은 다르다
write 성공은 전송 버퍼에 넣었다는 뜻이다
응답을 읽고 상태 코드를 확인하는 단계가 필요하다
코드는 이렇게 될 것을 보여 주고 선로는 실제로 이랬다를 보여 준다
둘이 어긋나면 선로 쪽이 사실이다
양쪽 코드를 읽는 것보다 중간을 보는 것이 빠를 때가 많다
snprintf 반환값이 실제 쓴 길이인지 확인한다
장치 간 통신도 신호를 직접 보고 어느 단계에서 끊기는지 본다
주소를 훑어 보면 실제로 어디에 붙어 있는지 나온다
정상일 때의 기록을 저장해 두어야 비교가 된다