No http events when making a https request to scoped nginx

[seanvaleo]

When scoping nginx, and hitting it with a curl request, we do not get http events.

User @coccyx reported an issue first seen in the AppScope Fundamentals sandbox:
"if I scope nginx and then curl --http1.1 -s -k https://localhost/ I would expect scope events --id 1 -t http.req to return some events, but I do not see HTTP events from nginx."

The team was able to reproduce the issue on local environments by configuring nginx to handle TLS requests and scoping it, before hitting it with a cURL request. This is a confirmed bug.

[seanvaleo]

After turning on hex logging in doProtocol() (our protocol detection function) and recompiling, I observed the following pattern (snippet):

commands: sudo ./bin/linux/x86_64/scope run --loglevel=debug -- nginx   curl --http1.1 -k https://localhost/
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.610-0400] fd:14 accept4
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.614-0400] DEBUG: doProtocol(id=-1, fd=14, len=1, src=NETRX, dtyp=BUF) TLS=PENDING PROTO=PENDING (1 bytes)
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.614-0400]   0000:  16                                                .
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.614-0400] DEBUG: doProtocol(id=-1, fd=14, len=517, src=NETRX, dtyp=BUF) TLS=FALSE PROTO=FALSE (64 bytes)
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.615-0400]   0000:  16 03 01 02 00 01 00 01  fc 03 03 1f af b7 ff b6  ................
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.615-0400]   0010:  09 c8 66 5c 2f 7c 17 57  ee a4 5b e1 eb d7 28 ec  ..f\/|.W..[...(.
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.615-0400]   0020:  d4 46 37 50 14 ec 9f 2e  0e de 0a 20 f7 bd 05 79  .F7P....... ...y
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.615-0400]   0030:  13 fe 92 36 9a eb 70 ab  c0 5c ab 4f 2f 02 10 13  ...6..p..\.O/...
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400] DEBUG: doProtocol(id=-1, fd=14, len=1364, src=NETTX, dtyp=BUF) TLS=FALSE PROTO=FALSE (64 bytes)
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400]   0000:  16 03 03 00 7a 02 00 00  76 03 03 15 c9 e7 11 f5  ....z...v.......
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400]   0010:  df 50 0b 54 45 2a ce 01  1c 06 a5 78 7f 99 df db  .P.TE*.....x....
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400]   0020:  55 ae 3a c6 9a dc 20 a4  26 45 92 20 f7 bd 05 79  U.:... .&E. ...y
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400]   0030:  13 fe 92 36 9a eb 70 ab  c0 5c ab 4f 2f 02 10 13  ...6..p..\.O/...
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400] DEBUG: doProtocol(id=-1, fd=14, len=80, src=NETRX, dtyp=BUF) TLS=FALSE PROTO=FALSE (64 bytes)
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400]   0000:  14 03 03 00 01 01 17 03  03 00 45 b1 64 85 0a e8  ..........E.d...
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400]   0010:  d3 d1 05 55 63 96 d9 a9  24 9d e2 ec ed 71 36 d6  ...Uc...$....q6.
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400]   0020:  48 65 f2 e2 df 0b 90 ba  51 5f f8 7a 99 3b 1b cd  He......Q_.z.;..
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400]   0030:  58 e0 d3 7e a0 62 b7 50  c5 9c 22 54 bb f5 78 61  X..~.b.P.."T..xa
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400] DEBUG: doProtocol(id=-1, fd=14, len=287, src=NETTX, dtyp=BUF) TLS=FALSE PROTO=FALSE (64 bytes)
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400]   0000:  17 03 03 01 1a b6 a7 79  43 a4 e6 2f df 72 e4 d0  .......yC../.r..
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400]   0010:  ea 4e d3 71 6e 1e 4a 9b  06 af 5a 70 1f d4 5b 75  .N.qn.J...Zp..[u
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400]   0020:  9a 87 ec 4d b8 76 34 05  e1 b0 3f 2c 8a aa c8 e2  ...M.v4...?,....
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400]   0030:  8a f2 fd 7f 33 97 ba 09  2f 6e 11 6c 87 c1 a8 f8  ....3.../n.l....
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400] DEBUG: doProtocol(id=-1, fd=14, len=287, src=NETTX, dtyp=BUF) TLS=FALSE PROTO=FALSE (64 bytes)
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400]   0000:  17 03 03 01 1a e2 06 96  70 2d 6b 8f 09 2d bb 2f  ........p-k..-./
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400]   0010:  32 96 b7 1a 71 4d 7b b4  62 92 0d 4e 6f 11 be 33  2...qM{.b..No..3
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400]   0020:  73 f7 f0 ae 6c 47 a1 da  dc d1 46 77 81 03 03 ca  s...lG....Fw....
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400]   0030:  78 17 58 de cf c3 18 ab  e5 2f f9 9b f1 10 b8 49  x.X....../.....I
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400] DEBUG: doProtocol(id=-1, fd=14, len=95, src=NETRX, dtyp=BUF) TLS=FALSE PROTO=FALSE (64 bytes)
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400]   0000:  17 03 03 00 5a ea e2 65  16 9c 61 d2 d7 5f 2f a2  ....Z..e..a.._/.
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400]   0010:  67 47 4e c3 21 53 cb 5c  40 c8 18 80 9b 01 66 1f  gGN.!S.\@.....f.
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400]   0020:  ba 28 68 d6 3e ec 3e fc  3b 94 bc 8f 41 bc 8a 23  .(h.>.>.;...A..#
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400]   0030:  ef 56 6e a3 57 51 48 c8  d0 27 0a f5 a5 cd 25 c2  .Vn.WQH..'....%.
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400] DEBUG: doProtocol(id=93940663673824, fd=14, len=73, src=TLSRX, dtyp=BUF) TLS=FALSE PROTO=FALSE (64 bytes)
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.616-0400]   0000:  47 45 54 20 2f 20 48 54  54 50 2f 31 2e 31 0d 0a  GET / HTTP/1.1..
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.617-0400]   0010:  48 6f 73 74 3a 20 6c 6f  63 61 6c 68 6f 73 74 0d  Host: localhost.
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.617-0400]   0020:  0a 55 73 65 72 2d 41 67  65 6e 74 3a 20 63 75 72  .User-Agent: cur
Scope: nginx: master process nginx(pid:37013): [2022-06-27T15:31:33.617-0400]   0030:  6c 2f 37 2e 37 34 2e 30  0d 0a 41 63 63 65 70 74  l/7.74.0..Accept

That first call to doProtocol() with a buffer of length 1 containing 0x16 appears erroneous. Since it's the first message on the socket, it's setting TLS=false and subsequently we aren't able to detect a PROTO later.
Every subsequent call to doProtocol() looks healthy: first some TLS handshaking, then at the end, our http1.1 magic string which would normally set PROTO=true and allow us to generate http req/resp events.
Contrasting this with debug output from a scoped go server (which we know works), we do not see that erroneous first message:

commands: GODEBUG=http2client=0,http2server=0 ./bin/linux/x86_64/scope run --loglevel debug -- tlsServerDynamic18 4430   curl -k --key server.key --cert server.crt https://localhost:4430/hello
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.504-0400] fd:4 go_accept4
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.508-0400] DEBUG: doProtocol(id=-1, fd=4, len=517, src=NETRX, dtyp=BUF) TLS=PENDING PROTO=PENDING (64 bytes)
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.508-0400]   0000:  16 03 01 02 00 01 00 01  fc 03 03 fa cc c1 e4 6b  ...............k
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.508-0400]   0010:  c1 6a 93 57 a0 06 92 f1  8e 32 8a 8a ed df fb c1  .j.W.....2......
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.508-0400]   0020:  59 97 df 87 ba da 6c 02  94 e7 09 20 e4 e9 3a 80  Y.....l.... ..:.
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.508-0400]   0030:  22 d8 18 15 07 3f 8f f5  02 51 f2 07 44 37 ea d7  "....?...Q..D7..
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.508-0400] fd:4 detected TLS
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.510-0400] DEBUG: doProtocol(id=-1, fd=4, len=1179, src=NETTX, dtyp=BUF) TLS=TRUE PROTO=PENDING (64 bytes)
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.510-0400]   0000:  16 03 03 00 7a 02 00 00  76 03 03 91 a2 4b 5d 67  ....z...v....K]g
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.510-0400]   0010:  a9 2b 9c a8 47 9f de 74  2b 37 5f 16 63 de c1 f3  .+..G..t+7_.c...
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.510-0400]   0020:  a3 b4 e7 d7 0a 27 4e a1  91 29 d3 20 e4 e9 3a 80  .....'N..). ..:.
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.510-0400]   0030:  22 d8 18 15 07 3f 8f f5  02 51 f2 07 44 37 ea d7  "....?...Q..D7..
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.511-0400] DEBUG: doProtocol(id=-1, fd=4, len=64, src=NETRX, dtyp=BUF) TLS=TRUE PROTO=PENDING (64 bytes)
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.511-0400]   0000:  14 03 03 00 01 01 17 03  03 00 35 52 9a 6a f9 f6  ..........5R.j..
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.511-0400]   0010:  d2 9a a7 fe 2e 41 22 3c  82 4e 5a ee ad 28 0f 46  .....A"<.NZ..(.F
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.511-0400]   0020:  a3 8b ec a1 b2 90 74 cd  c4 30 ed e9 14 c1 5c c2  ......t..0....\.
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.511-0400]   0030:  ab 1f 1a d6 25 58 8a f2  87 c8 f1 39 cc 35 c2 19  ....%X.....9.5..
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.511-0400] DEBUG: doProtocol(id=-1, fd=4, len=105, src=NETRX, dtyp=BUF) TLS=TRUE PROTO=PENDING (64 bytes)
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.511-0400]   0000:  17 03 03 00 64 c7 0b be  f1 b3 30 0f fa bb 10 c0  ....d.....0.....
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.511-0400]   0010:  63 9d 3a 7b 59 c1 66 84  80 c6 a0 36 53 fd 0f 19  c.:{Y.f....6S...
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.511-0400]   0020:  77 e8 7b b8 4d 78 42 8b  ea f8 cb c6 3f 92 53 32  w.{.MxB.....?.S2
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.511-0400]   0030:  be 2a 06 ec 44 a5 f5 ef  72 83 af f6 9c ab bf 26  .*..D...r......&
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.511-0400] DEBUG: doProtocol(id=0, fd=4, len=83, src=TLSRX, dtyp=BUF) TLS=TRUE PROTO=PENDING (64 bytes)
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.511-0400]   0000:  47 45 54 20 2f 68 65 6c  6c 6f 20 48 54 54 50 2f  GET /hello HTTP/
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.511-0400]   0010:  31 2e 31 0d 0a 48 6f 73  74 3a 20 6c 6f 63 61 6c  1.1..Host: local
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.511-0400]   0020:  68 6f 73 74 3a 34 34 33  30 0d 0a 55 73 65 72 2d  host:4430..User-
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.511-0400]   0030:  41 67 65 6e 74 3a 20 63  75 72 6c 2f 37 2e 37 34  Agent: curl/7.74
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.511-0400] fd:4 detected HTTP
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.511-0400] DEBUG: doProtocol(id=-1, fd=4, len=151, src=NETTX, dtyp=BUF) TLS=TRUE PROTO=TRUE (64 bytes)
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.511-0400]   0000:  17 03 03 00 92 1d ad be  2d 0d b7 eb a1 c5 e8 fe  ........-.......
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.511-0400]   0010:  90 18 e6 50 51 a9 a9 00  86 10 3f c8 b3 3e 66 29  ...PQ.....?..>f)
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.511-0400]   0020:  34 7b 6f 38 1d 07 6e 99  db f7 1e 6a ae 19 fe 73  4{o8..n....j...s
Scope: tlsServerDynamic18(pid:37441): [2022-06-27T16:05:29.511-0400]   0030:  24 81 a0 d3 f0 93 02 29  52 77 e5 b0 4b 0c 82 16  $......)Rw..K...

as a result, TLS detection works, and PROTO detection works also.

So, where is this strange first message coming from? I scoped nginx again, then attached gdb to the worker process and set a breakpoint on doProtocol().
Looking at backtraces, I saw that that first time doProtocol() is called after a request, it's coming from __recv_chk() . Backtrace:

#0  doProtocol (id=18446744073709551615, sockfd=3, buf=0x7ffdacfd42e0, len=1, src=NETRX, dtype=BUF) at src/state.c:1273
#1  0x00007fc1081869f7 in doRecv (sockfd=3, rc=1, buf=0x7ffdacfd42e0, len=1, src=BUF) at src/state.c:2015
#2  0x00007fc10817fd91 in __recv_chk (sockfd=3, buf=0x7ffdacfd42e0, len=1, buflen=108, flags=2) at src/wrap.c:4732
#3  0x0000555be6e8c26e in ?? ()
#4  0x0000555be6e7059b in ?? ()
#5  0x0000555be6e66859 in ngx_process_events_and_timers ()
#6  0x0000555be6e6cafd in ?? ()
#7  0x0000555be6e62528 in ngx_spawn_process ()
#8  0x0000555be6e63a59 in ?? ()
#9  0x0000555be6e6b7f3 in ngx_master_process_cycle ()
#10 0x0000555be6e3e9e4 in main ()

This is the only instance that doProtocol() is called from __recv_chk . In all other cases, we are coming from an interposition of syscall read or write.
A few months ago, we added the ability to interpose *_chk functions when we realized that some OS's compile libraries with fortify_source which provides a layer of security checking against things like buffer overflow attacks.
We did not catch this occasion where __recv_chk is being interposed, creating a bug in protocol detection.
We plan to extend coverage in our nginx tests to check for http req/resp with TLS on.

[seanvaleo]

@jrcheli discovered that nginx is calling __recv_chk with the MSG_PEEK flag set. Essentially, they are taking a look "peek" at the first byte on the network buffer without consuming it from the buffer.

We need to put in place a check for this flag in all recv type interpositions, ignoring any occasions where it is set. This will avoid duplication of data reads which upset things like protocol detection.

[abetones]

Just for the record, per @jrcheli , I updated the Known Issues description.

Since the old one is gone from the docs now, here it is:

AppScope incorrectly handles the single-byte message that web clients sometimes send before their ClientHello message. When you scope a server with TLS enabled, this can cause AppScope to fail to produce HTTP events.

And here is the revised description:

AppScope incorrectly handles the "peek" flag in interposed functions that receive network data. When a server "peeks" at the first byte of data, AppScope counts that byte twice, which breaks protocol detection. AppScope then fails to correctly produce HTTP events.