Auto-Instrumentation does not produce spans after PR #1066

[jeremydvoss]

I am on Windows 11. Here are my steps to reproduce:

virtualenv auto_autoinstrumentation 
source auto_instrumentation/Scripts/activate 
pip list 
opentelemetry-api                      1.12.0rc1 c:\users\jeremyvoss\workplace\opentelemetry-python\opentelemetry-api\src 
opentelemetry-distro                   0.31b0    c:\users\jeremyvoss\workplace\opentelemetry-python-contrib\opentelemetry-distro\src
opentelemetry-instrumentation          0.31b0    c:\users\jeremyvoss\workplace\opentelemetry-python-contrib\opentelemetry-instrumentation\src 
opentelemetry-instrumentation-flask    0.31b0    c:\users\jeremyvoss\workplace\opentelemetry-python-contrib\instrumentation\opentelemetry-instrumentation-flask\src 
opentelemetry-instrumentation-requests 0.31b0    c:\users\jeremyvoss\workplace\opentelemetry-python-contrib\instrumentation\opentelemetry-instrumentation-requests\src 
opentelemetry-instrumentation-wsgi     0.31b0    c:\users\jeremyvoss\workplace\opentelemetry-python-contrib\instrumentation\opentelemetry-instrumentation-wsgi\src 
opentelemetry-proto                    1.12.0rc1 c:\users\jeremyvoss\workplace\opentelemetry-python\opentelemetry-proto\src 
opentelemetry-sdk                      1.12.0rc1 c:\users\jeremyvoss\workplace\opentelemetry-python\opentelemetry-sdk\src 
opentelemetry-semantic-conventions     0.31b0    c:\users\jeremyvoss\workplace\opentelemetry-python\opentelemetry-semantic-conventions\src 
opentelemetry-util-http                0.31b0    c:\users\jeremyvoss\workplace\opentelemetry-python-contrib\util\opentelemetry-util-http\src 
pip                                    22.1 
 
opentelemetry-instrument --traces_exporter console python opentelemetry-python/docs/examples/auto-instrumentation/server_uninstrumented.py
$ Error in sitecustomize; set PYTHONVERBOSE for traceback: 
error: incomplete escape \u at position 2 
* Serving Flask app 'server_uninstrumented' (lazy loading) 
* Environment: production 
   WARNING: This is a development server. Do not use it in a production deployment. 
   Use a production WSGI server instead. 
* Debug mode: off 
* Running on http://127.0.0.1:8082 (Press CTRL+C to quit) 
None 
 
#In other terminal in virtualenv: 
python opentelemetry-python/docs/examples/auto-instrumentation/client.py testing 
{ 
    "name": "client-server", 
    "context": { 
        "trace_id": "0x73acdf4567483e0687b68750cfb4f949", 
        "span_id": "0xd64fe9ef65f7755b", 
        "trace_state": "[]" 
    }, 
    "kind": "SpanKind.INTERNAL", 
    "parent_id": "0x38d3f426cefc6cc1", 
    "start_time": "2022-05-19T19:50:19.645699Z", 
    "end_time": "2022-05-19T19:50:21.694709Z", 
    "status": { 
        "status_code": "UNSET" 
    }, 
    "attributes": {}, 
    "events": [], 
    "links": [], 
    "resource": { 
        "telemetry.sdk.language": "python", 
        "telemetry.sdk.name": "opentelemetry", 
        "telemetry.sdk.version": "1.12.0rc1", 
        "service.name": "unknown_service" 
    } 
} 
{ 
    "name": "client", 
    "context": { 
        "trace_id": "0x73acdf4567483e0687b68750cfb4f949", 
        "span_id": "0x38d3f426cefc6cc1", 
        "trace_state": "[]" 
    }, 
    "kind": "SpanKind.INTERNAL", 
    "parent_id": null, 
    "start_time": "2022-05-19T19:50:19.645699Z", 
    "end_time": "2022-05-19T19:50:21.694709Z", 
    "status": { 
        "status_code": "UNSET" 
    }, 
    "attributes": {}, 
    "events": [], 
    "links": [], 
    "resource": { 
        "telemetry.sdk.language": "python", 
        "telemetry.sdk.name": "opentelemetry", 
        "telemetry.sdk.version": "1.12.0rc1", 
        "service.name": "unknown_service" 
    } 
} 
 
#Back in original terminal: 
$ testing 
127.0.0.1 - - [19/May/2022 12:50:21] "GET /server_request?param=testing HTTP/1.1" 200 - 
# No spans 

But, if I move the code block back to the finally, I get the spans:

$ Error in sitecustomize; set PYTHONVERBOSE for traceback:
error: incomplete escape \u at position 2
 * Serving Flask app 'server_uninstrumented' (lazy loading)
 * Environment: production
   WARNING: This is a development server. Do not use it in a production deployment.
   Use a production WSGI server instead.
 * Debug mode: off
testing
{
    "name": "/server_request",
    "context": {
        "trace_id": "0x17de907a560abb09fe4bb12c7ae959b7",
        "span_id": "0x7be5ba63f32fe5f6",
        "trace_state": "[]"
    },
    "kind": "SpanKind.SERVER",
    "parent_id": "0x134b353700b64083",
    "start_time": "2022-05-19T20:35:04.538593Z",
    "end_time": "2022-05-19T20:35:04.538593Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "http.method": "GET",
        "http.server_name": "127.0.0.1",
        "http.scheme": "http",
        "net.host.port": 8082,
        "http.host": "localhost:8082",
        "http.target": "/server_request?param=testing",
        "net.peer.ip": "127.0.0.1",
        "http.user_agent": "python-requests/2.27.1",
        "net.peer.port": 59869,
        "http.flavor": "1.1",
        "http.route": "/server_request",
        "http.status_code": 200
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.12.0rc1",
        "telemetry.auto.version": "0.31b0",
        "service.name": "unknown_service"
    }
}

Notice that in both cases, I get the Error in sitecustomize; set PYTHONVERBOSE for traceback: error: incomplete escape \u at position 2 message which may only occur on Windows. I believe it's related to the rf-string, but need to investigate more.

[jeremydvoss]

I've determined that Error in sitecustomize; set PYTHONVERBOSE for traceback: error: incomplete escape \u at position 2 refers to the first escaped character of rf"{dirname(abspath(__file__))}{pathsep}?". For instance, on my machine, the value of is r"C:\Users\<USER>\workplace;?" and the incomplete escape \u at position 2 refers to the \U in User. The error comes from the sub function not being able to handle that character for some reason:

File "c:\users\jeremyvoss\workplace\opentelemetry-python-contrib\opentelemetry-instrumentation\src\opentelemetry\instrumentation\auto_instrumentation\sitecustomize.py", line 136, in <module>
    initialize()
  File "c:\users\jeremyvoss\workplace\opentelemetry-python-contrib\opentelemetry-instrumentation\src\opentelemetry\instrumentation\auto_instrumentation\sitecustomize.py", line 115, in initialize
    environ["PYTHONPATH"] = sub(
  File "C:\Users\jeremyvoss\AppData\Local\Programs\Python\Python310\lib\re.py", line 209, in sub
    return _compile(pattern, flags).sub(repl, string, count)
  File "C:\Users\jeremyvoss\AppData\Local\Programs\Python\Python310\lib\re.py", line 303, in _compile
    p = sre_compile.compile(pattern, flags)
  File "C:\Users\jeremyvoss\AppData\Local\Programs\Python\Python310\lib\sre_compile.py", line 764, in compile
    p = sre_parse.parse(p, flags)
  File "C:\Users\jeremyvoss\AppData\Local\Programs\Python\Python310\lib\sre_parse.py", line 950, in parse
    p = _parse_sub(source, state, flags & SRE_FLAG_VERBOSE, 0)
  File "C:\Users\jeremyvoss\AppData\Local\Programs\Python\Python310\lib\sre_parse.py", line 443, in _parse_sub
    itemsappend(_parse(source, state, verbose, nested + 1,
  File "C:\Users\jeremyvoss\AppData\Local\Programs\Python\Python310\lib\sre_parse.py", line 525, in _parse
    code = _escape(source, this, state)
  File "C:\Users\jeremyvoss\AppData\Local\Programs\Python\Python310\lib\sre_parse.py", line 375, in _escape
    raise source.error("incomplete escape %s" % escape, len(escape))
re.error: incomplete escape \u at position 2

Furthermore, I have confirmed that this is not an issue with escapable characters like \n \\ or \? but fails for characters that do not have escapable purposes, like \U \u or `g. Finally, although the error comes from the sub function, the value of environ["PYTHONPATH"]` does not seem to matter. So, it seems the issue is either with how Windows handles raw python strings. Or perhaps linux paths just happen to contain escapable characters the function can handle.

[jeremydvoss]

@aabmass I think I found the issue. the sub function is not meant to take a string, per se, but rather a pattern. So, if we send it r"C:\User..." or the equivalent "C:\\User...", it tries to esacpe a u character and breaks. So the \s have to be double escaped. Passing r"C:\\Users\\jeremyvoss\\workplace;?" or the equivalent "C:\\\\Users\\\\jeremyvoss\\\\workplace;?" does not produce the error. Since I believe linux uses / as the path separator instead of Window's /, testing on linux could not catch the issue.

[jeremydvoss]

Adding a re.escape(...) call seems to fix the problem on Windows! Preparing a commit.

[lzchen]

Fixed by #1100