基於日誌的統計分析按日誌來源一般分為後端 cgi、app 日誌和前端 js 掛碼日誌，其中前端 js 掛碼由於與具體後端業務邏輯低耦合、非同步載入等特性，使得其在網站統計分析領域應用廣泛。

今天就來看一個 nginx 日誌收集過程中的 case。

最近在 review nginx 配置的時候，發現 nginx 每天會有 1% 的 errlog，由於公司的業務訪問量還算比較大的，算下來這 1% 也不是個小數目，有必要搞清楚這 1% 究竟怎麼產生的。

1、錯誤日誌樣式：

錯誤日誌的樣式大致分為兩種，如下：

2014/07/03 00:06:51 [error] 30605#0: *15901655967 client sent invalid userid cookie "cookieuid1=05dvUVObOC+UGCrSG4gWAg==; jobbest_cateid=38676; isfirst=true; showcountdown=true; stopnotice=true; _TCN=4FD2E673D11B18C5060BF413BB796EB5; idooxx="05dz8VO0Lew1TT66I0MUAg=="; ...


2014/08/13 11:01:25 [error] 13702#0: *19402474334 open() "/opt/web/tracklog.ooxx.com.static/mooxx/m3/js/m.lazyload.js" failed (2: No such file or directory), client: 42.249.142.200, server: tracklog.ooxx.com, ...
 

前者在整個 errlog 中佔比 99%，後者 1% 左右，前者就是今天要討論的主題：為什麼 nginx 會報這種錯誤，而後者這種錯誤一般是原本的訪問路徑不正確或者運營商劫持導致訪問路徑錯誤。

2、按圖索驥：track nginx source code

搜了下，網上貌似很少有人問到這個問題，即使問到了也貌似沒有明確的解答，當 STFW 和 RTFM 都不管用的時候，那就只有硬著頭皮看原始碼了，按圖索驥，看看原始碼中，何處丟擲的 client sent invalid userid cookie 這個錯誤：

static ngx_http_userid_ctx_t *
ngx_http_userid_get_uid(ngx_http_request_t *r, ngx_http_userid_conf_t *conf)
{
...

    ngx_log_debug1(NGX_LOG_DEBUG_HTTP, r->connection->log, 0,
                   "uid cookie: "%V"", &ctx->cookie);

    if (ctx->cookie.len < 22) {
        cookies = r->headers_in.cookies.elts;
        ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
                      "client sent too short userid cookie "%V"",
                      &cookies[n]->value);
        return ctx;
    }

    src = ctx->cookie;

    /*
     * we have to limit the encoded string to 22 characters because
     *  1) cookie may be marked by "userid_mark",
     *  2) and there are already the millions cookies with a garbage
     *     instead of the correct base64 trail "=="
     */

    src.len = 22;

    dst.data = (u_char *) ctx->uid_got;

    if (ngx_decode_base64(&dst, &src) == NGX_ERROR) {
        cookies = r->headers_in.cookies.elts;
        ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
                      "client sent invalid userid cookie "%V"",
                      &cookies[n]->value);
        return ctx;
    }

...
}


ngx_int_t
ngx_decode_base64(ngx_str_t *dst, ngx_str_t *src)
{
    static u_char   basis64[] = {
        77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77,
        77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77,
        77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 62, 77, 77, 77, 63,
        52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 77, 77, 77, 77, 77, 77,
        77,  0,  1,  2,  3,  4,  5,  6,  7,  8,  9, 10, 11, 12, 13, 14,
        15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 77, 77, 77, 77, 77,
        77, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40,
        41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 77, 77, 77, 77, 77,

        77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77,
        77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77,
        77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77,
        77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77,
        77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77,
        77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77,
        77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77,
        77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77, 77
    };

    return ngx_decode_base64_internal(dst, src, basis64);
}



static ngx_int_t
ngx_decode_base64_internal(ngx_str_t *dst, ngx_str_t *src, const u_char *basis)
{
...

    for (len = 0; len < src->len; len++) {
        if (src->data[len] == '=') {
            break;
        }

        if (basis[src->data[len]] == 77) {
            return NGX_ERROR;
        }
    }

    if (len % 4 == 1) {
        return NGX_ERROR;
    }

    s = src->data;
    d = dst->data;

    while (len > 3) {
        *d++ = (u_char) (basis[s[0]] << 2 | basis[s[1]] >> 4);
        *d++ = (u_char) (basis[s[1]] << 4 | basis[s[2]] >> 2);
        *d++ = (u_char) (basis[s[2]] << 6 | basis[s[3]]);

        s += 4;
        len -= 4;
    }

...

    return NGX_OK;
}
 

可以看到，原始碼中會對傳入的 cookieId 做 base64 合法性校驗，如果沒有通過校驗，則會丟擲 client sent invalid userid cookie 錯誤，並按 HttpUseridModule 的邏輯重新分配新的 cookieId。

3、測試驗證

為了證明上述推斷的正確性，並解決上述的錯誤，我們只需要找出沒通過校驗的地方，並構造測試用例驗證即可。

我們取一條正常的請求中的 cookie：

idooxx=05dvZ1ODTpI+FjiILHYwAg==; __ag_cm_=1408028234222; __utma=253535702.161ooxx51834.1401114262.1408099300.1408187334.7; __utmz=253535702.1401114262.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none); _bu=201104111325386d88c794; city=bj; ooxxhome=bj; myfeet_tooltip=end; new_session=1; init_refer=; ipcity=bj%7C%u5317%u4EAC; __utmb=253535702.3.9.1408187335363; __utmc=253535702
 

用上述正確的對比錯誤的 cookie，可以看到，cookieId(idooxx) 中包含了雙引號，而導致 cookieId 沒有通過 base64 合法性校驗的可能正是包含了 非 base64 編碼字串。下面我們來驗證下，手動在瀏覽器中構造一個不合法 cookie，看看是不是有同樣的問題。

由於 base64 編碼只包含 64 個字元：大小寫52 + 數字10 + 2個額外字元+/  一共64個字元。如果我們客戶端傳送的 cookieId 中包含了上述非 64 字符集中的字元，那麼 nginx HttpUseridModule 模組就會校驗後認為請求非法，並會重新非配 cookieId。

4、解決方案

原因找到了，要解決起來就不難了，其實分析這些錯誤有個共性，就是這些錯誤都是由移動端產生的，pc 端基本沒有，因為 pc 端的瀏覽器請求的引數都是規範的，而移動端的很多都是 RD 自己拼接然後傳送的，難免會不符合規範，有則改之。

5、Refer：

[1] nginx-1.7.3/src/http/modules/ngx_http_userid_filter_module.c

http://lxr.nginx.org/source/src/http/modules/ngx_http_userid_filter_module.c

[2] nginx-1.7.3/src/core/ngx_string.c

http://lxr.nginx.org/source/src/core/ngx_string.c

[3] Errors using HttpUseridModule

http://www.serverphorums.com/read.php?5,856195

[4] Base64編碼/解碼器

http://base64.xpcha.com/

[5] ngx_http_userid_module模組基本指令整理

http://www.iigrowing.cn/ngx-http-userid-module-mo-kuai-ji-ben-zhi-ling-zheng-li.html