Nginx log error：client sent invalid userid cookie

用户1177713

发布于 2018-02-24 16:38:27

1.6K0

发布于 2018-02-24 16:38:27

文章被收录于专栏：数据之美

基于日志的统计分析按日志来源一般分为后端 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。