timecraft: add trace command #43

achille-roussel · 2023-06-01T08:39:42Z

This is the beginning of a some work on network tracing tools in timecraft.

I implemented a stream.Reader which consumes records from an underlying reader and produces a stream of network trace events.

Here's an example of the output it generates:

2023-06-01T07:13:06.766601Z TCP CLOSE (fd=3, OK)
    ADDR: ?
    PEER: ?

2023-06-01T07:13:06.772326Z TCP ACCEPT (fd=3, OK)
    ADDR: ?
    PEER: ?

2023-06-01T07:13:06.772462Z TCP RECV (fd=3, size=78, OK)
    ADDR: ?
    PEER: ?

------------------------------------------------------------------------------
00000000  47 45 54 20 2f 20 48 54  54 50 2f 31 2e 31 0d 0a  |GET / HTTP/1.1..|
00000010  48 6f 73 74 3a 20 6c 6f  63 61 6c 68 6f 73 74 3a  |Host: localhost:|
00000020  38 30 38 30 0d 0a 55 73  65 72 2d 41 67 65 6e 74  |8080..User-Agent|
00000030  3a 20 63 75 72 6c 2f 37  2e 38 36 2e 30 0d 0a 41  |: curl/7.86.0..A|
00000040  63 63 65 70 74 3a 20 2a  2f 2a 0d 0a 0d 0a        |ccept: */*....|
------------------------------------------------------------------------------

2023-06-01T07:13:06.772620Z TCP SEND (fd=3, size=131, OK)
    ADDR: ?
    PEER: ?

------------------------------------------------------------------------------
00000000  48 54 54 50 2f 31 2e 31  20 32 30 30 20 4f 4b 0d  |HTTP/1.1 200 OK.|
00000010  0a 44 61 74 65 3a 20 54  68 75 2c 20 30 31 20 4a  |.Date: Thu, 01 J|
00000020  75 6e 20 32 30 32 33 20  30 37 3a 31 33 3a 30 36  |un 2023 07:13:06|
00000030  20 47 4d 54 0d 0a 43 6f  6e 74 65 6e 74 2d 4c 65  | GMT..Content-Le|
00000040  6e 67 74 68 3a 20 31 34  0d 0a 43 6f 6e 74 65 6e  |ngth: 14..Conten|
00000050  74 2d 54 79 70 65 3a 20  74 65 78 74 2f 70 6c 61  |t-Type: text/pla|
00000060  69 6e 3b 20 63 68 61 72  73 65 74 3d 75 74 66 2d  |in; charset=utf-|
00000070  38 0d 0a 0d 0a 48 65 6c  6c 6f 2c 20 57 6f 72 6c  |8....Hello, Worl|
00000080  64 21 0a                                          |d!.|
------------------------------------------------------------------------------

Currently hitting some limitations:

It would be really useful to have the network address captured in sock_accept. WASI doesn't expose it in the signature but since we have an abstraction layer between the system and the ABI, maybe we could add the network address while maintaining ABI compatibility? Without this information we rely on hoping that the application will call sock_local_address to have it recorded in the log, which is not ideal.
There seems to be a bug somewhere in our code where the size encoded or decode in fd_read calls is -1, and errno is 0. There is valid content associated with the call so it seems that it might just be the size value that is invalid. Let's not exclude that the bug could come from this PR as well.

Still working on it but opening to share progress, feel free to give early feedback as well!

internal/debug/nettrace/nettrace.go

achille-roussel · 2023-06-01T20:31:52Z

Thanks to dispatchrun/wasi-go#33 we have peer socket addresses now:

2023-06-01T20:28:50.444496Z TCP CLOSE (fd=3, OK)
    ADDR: ?
    PEER: 127.0.0.1:53951

2023-06-01T20:28:50.448951Z TCP ACCEPT (fd=3, OK)
    ADDR: ?
    PEER: 127.0.0.1:53952

2023-06-01T20:28:50.449041Z TCP RECV (fd=3, size=1, OK)
    ADDR: ?
    PEER: 127.0.0.1:53952

------------------------------------------------------------------------------
00000000  47 45 54 20 2f 20 48 54  54 50 2f 31 2e 31 0d 0a  |GET / HTTP/1.1..|
00000010  48 6f 73 74 3a 20 6c 6f  63 61 6c 68 6f 73 74 3a  |Host: localhost:|
00000020  38 30 38 30 0d 0a 55 73  65 72 2d 41 67 65 6e 74  |8080..User-Agent|
00000030  3a 20 63 75 72 6c 2f 37  2e 38 36 2e 30 0d 0a 41  |: curl/7.86.0..A|
00000040  63 63 65 70 74 3a 20 2a  2f 2a 0d 0a 0d 0a        |ccept: */*....|
------------------------------------------------------------------------------

2023-06-01T20:28:50.449125Z TCP SEND (fd=3, size=1, OK)
    ADDR: ?
    PEER: 127.0.0.1:53952

------------------------------------------------------------------------------
00000000  48 54 54 50 2f 31 2e 31  20 32 30 30 20 4f 4b 0d  |HTTP/1.1 200 OK.|
00000010  0a 44 61 74 65 3a 20 54  68 75 2c 20 30 31 20 4a  |.Date: Thu, 01 J|
00000020  75 6e 20 32 30 32 33 20  32 30 3a 32 38 3a 35 30  |un 2023 20:28:50|
00000030  20 47 4d 54 0d 0a 43 6f  6e 74 65 6e 74 2d 4c 65  | GMT..Content-Le|
00000040  6e 67 74 68 3a 20 31 34  0d 0a 43 6f 6e 74 65 6e  |ngth: 14..Conten|
00000050  74 2d 54 79 70 65 3a 20  74 65 78 74 2f 70 6c 61  |t-Type: text/pla|
00000060  69 6e 3b 20 63 68 61 72  73 65 74 3d 75 74 66 2d  |in; charset=utf-|
00000070  38 0d 0a 0d 0a 48 65 6c  6c 6f 2c 20 57 6f 72 6c  |8....Hello, Worl|
00000080  64 21 0a                                          |d!.|
------------------------------------------------------------------------------

2023-06-01T20:28:50.449150Z TCP RECV (fd=3, size=1, OK)
    ADDR: ?
    PEER: 127.0.0.1:53952

Signed-off-by: Achille Roussel <[email protected]>

achille-roussel · 2023-06-04T19:11:52Z

Updated output:

2023/06/04 12:06:10.093567 TCP 127.0.0.1:49965 > 0.0.0.0:8080: ACCEPT OK
2023/06/04 12:06:10.093654 TCP 127.0.0.1:49965 > 0.0.0.0:8080: RECV OK 78
2023/06/04 12:06:10.093743 TCP 0.0.0.0:8080 > 127.0.0.1:49965: SEND OK 131
2023/06/04 12:06:10.093924 TCP 0.0.0.0:8080 > 127.0.0.1:49965: SHUT OK
2023/06/04 12:06:10.098463 TCP 127.0.0.1:49966 > 0.0.0.0:8080: ACCEPT OK
2023/06/04 12:06:10.098554 TCP 127.0.0.1:49966 > 0.0.0.0:8080: RECV OK 78
2023/06/04 12:06:10.098656 TCP 0.0.0.0:8080 > 127.0.0.1:49966: SEND OK 131
2023/06/04 12:06:10.098832 TCP 0.0.0.0:8080 > 127.0.0.1:49966: SHUT OK
2023/06/04 12:06:10.103223 TCP 127.0.0.1:49967 > 0.0.0.0:8080: ACCEPT OK
2023/06/04 12:06:10.103322 TCP 127.0.0.1:49967 > 0.0.0.0:8080: RECV OK 78
2023/06/04 12:06:10.103411 TCP 0.0.0.0:8080 > 127.0.0.1:49967: SEND OK 131
2023/06/04 12:06:10.103550 TCP 0.0.0.0:8080 > 127.0.0.1:49967: SHUT OK
2023/06/04 12:06:10.107865 TCP 127.0.0.1:49968 > 0.0.0.0:8080: ACCEPT OK
2023/06/04 12:06:10.107948 TCP 127.0.0.1:49968 > 0.0.0.0:8080: RECV OK 78
2023/06/04 12:06:10.108028 TCP 0.0.0.0:8080 > 127.0.0.1:49968: SEND OK 131
2023/06/04 12:06:10.108152 TCP 0.0.0.0:8080 > 127.0.0.1:49968: SHUT OK
2023/06/04 12:06:10.112637 TCP 127.0.0.1:49969 > 0.0.0.0:8080: ACCEPT OK
2023/06/04 12:06:10.112709 TCP 127.0.0.1:49969 > 0.0.0.0:8080: RECV OK 78
2023/06/04 12:06:10.112777 TCP 0.0.0.0:8080 > 127.0.0.1:49969: SEND OK 131
2023/06/04 12:06:10.112873 TCP 0.0.0.0:8080 > 127.0.0.1:49969: SHUT OK
2023/06/04 12:06:10.117589 TCP 127.0.0.1:49970 > 0.0.0.0:8080: ACCEPT OK
2023/06/04 12:06:10.117680 TCP 127.0.0.1:49970 > 0.0.0.0:8080: RECV OK 78
2023/06/04 12:06:10.117766 TCP 0.0.0.0:8080 > 127.0.0.1:49970: SEND OK 131
2023/06/04 12:06:10.117901 TCP 0.0.0.0:8080 > 127.0.0.1:49970: SHUT OK

or with the verbose option:

[3235] 2023/06/04 12:06:10.112637 TCP 127.0.0.1:49969 > 0.0.0.0:8080: ACCEPT OK
[3243] 2023/06/04 12:06:10.112709 TCP 127.0.0.1:49969 > 0.0.0.0:8080: RECV OK 78

00000000  47 45 54 20 2f 20 48 54  54 50 2f 31 2e 31 0d 0a  |GET / HTTP/1.1..|
00000010  48 6f 73 74 3a 20 6c 6f  63 61 6c 68 6f 73 74 3a  |Host: localhost:|
00000020  38 30 38 30 0d 0a 55 73  65 72 2d 41 67 65 6e 74  |8080..User-Agent|
00000030  3a 20 63 75 72 6c 2f 37  2e 38 36 2e 30 0d 0a 41  |: curl/7.86.0..A|
00000040  63 63 65 70 74 3a 20 2a  2f 2a 0d 0a 0d 0a        |ccept: */*....|

[3248] 2023/06/04 12:06:10.112777 TCP 0.0.0.0:8080 > 127.0.0.1:49969: SEND OK 131

00000000  48 54 54 50 2f 31 2e 31  20 32 30 30 20 4f 4b 0d  |HTTP/1.1 200 OK.|
00000010  0a 44 61 74 65 3a 20 53  75 6e 2c 20 30 34 20 4a  |.Date: Sun, 04 J|
00000020  75 6e 20 32 30 32 33 20  31 39 3a 30 36 3a 31 30  |un 2023 19:06:10|
00000030  20 47 4d 54 0d 0a 43 6f  6e 74 65 6e 74 2d 4c 65  | GMT..Content-Le|
00000040  6e 67 74 68 3a 20 31 34  0d 0a 43 6f 6e 74 65 6e  |ngth: 14..Conten|
00000050  74 2d 54 79 70 65 3a 20  74 65 78 74 2f 70 6c 61  |t-Type: text/pla|
00000060  69 6e 3b 20 63 68 61 72  73 65 74 3d 75 74 66 2d  |in; charset=utf-|
00000070  38 0d 0a 0d 0a 48 65 6c  6c 6f 2c 20 57 6f 72 6c  |8....Hello, Worl|
00000080  64 21 0a                                          |d!.|

[3259] 2023/06/04 12:06:10.112873 TCP 0.0.0.0:8080 > 127.0.0.1:49969: SHUT OK
[3266] 2023/06/04 12:06:10.117589 TCP 127.0.0.1:49970 > 0.0.0.0:8080: ACCEPT OK
[3274] 2023/06/04 12:06:10.117680 TCP 127.0.0.1:49970 > 0.0.0.0:8080: RECV OK 78

00000000  47 45 54 20 2f 20 48 54  54 50 2f 31 2e 31 0d 0a  |GET / HTTP/1.1..|
00000010  48 6f 73 74 3a 20 6c 6f  63 61 6c 68 6f 73 74 3a  |Host: localhost:|
00000020  38 30 38 30 0d 0a 55 73  65 72 2d 41 67 65 6e 74  |8080..User-Agent|
00000030  3a 20 63 75 72 6c 2f 37  2e 38 36 2e 30 0d 0a 41  |: curl/7.86.0..A|
00000040  63 63 65 70 74 3a 20 2a  2f 2a 0d 0a 0d 0a        |ccept: */*....|

[3279] 2023/06/04 12:06:10.117766 TCP 0.0.0.0:8080 > 127.0.0.1:49970: SEND OK 131

00000000  48 54 54 50 2f 31 2e 31  20 32 30 30 20 4f 4b 0d  |HTTP/1.1 200 OK.|
00000010  0a 44 61 74 65 3a 20 53  75 6e 2c 20 30 34 20 4a  |.Date: Sun, 04 J|
00000020  75 6e 20 32 30 32 33 20  31 39 3a 30 36 3a 31 30  |un 2023 19:06:10|
00000030  20 47 4d 54 0d 0a 43 6f  6e 74 65 6e 74 2d 4c 65  | GMT..Content-Le|
00000040  6e 67 74 68 3a 20 31 34  0d 0a 43 6f 6e 74 65 6e  |ngth: 14..Conten|
00000050  74 2d 54 79 70 65 3a 20  74 65 78 74 2f 70 6c 61  |t-Type: text/pla|
00000060  69 6e 3b 20 63 68 61 72  73 65 74 3d 75 74 66 2d  |in; charset=utf-|
00000070  38 0d 0a 0d 0a 48 65 6c  6c 6f 2c 20 57 6f 72 6c  |8....Hello, Worl|
00000080  64 21 0a                                          |d!.|

[3290] 2023/06/04 12:06:10.117901 TCP 0.0.0.0:8080 > 127.0.0.1:49970: SHUT OK

Signed-off-by: Achille Roussel <[email protected]>

achille-roussel · 2023-06-05T23:41:36Z

I think this is good to go as-is for now; we've talked about the limitations of the current model to get higher level context:

entering the log "in the middle" makes it difficult to figure out where we are in the stream of requests/responses served by a connection
having a stream of protocol messages (e.g. http request/response) needs to also allow for correlation of different types

internal/debug/nettrace/nettrace.go

Signed-off-by: Achille Roussel <[email protected]>

achille-roussel requested review from pelletier, chriso and Pryz June 1, 2023 08:39

chriso reviewed Jun 1, 2023

View reviewed changes

internal/debug/nettrace/nettrace.go Outdated Show resolved Hide resolved

achille-roussel mentioned this pull request Jun 1, 2023

timemachine: support seeking through log records #45

Merged

achille-roussel force-pushed the trace branch from f77edb7 to 617d243 Compare June 1, 2023 20:07

achille-roussel mentioned this pull request Jun 1, 2023

wasi: update signature of SockAccept to access client address #48

Merged

achille-roussel force-pushed the trace branch 2 times, most recently from 8306a09 to 2ebf195 Compare June 3, 2023 18:57

This was referenced Jun 3, 2023

wasicall: fix iovec encoding #52

Merged

timemachine: add record offset #53

Merged

achille-roussel force-pushed the trace branch from 2ebf195 to 6ac406d Compare June 3, 2023 21:56

achille-roussel added 7 commits June 4, 2023 10:43

timecraft: add trace command

bbe1b96

Signed-off-by: Achille Roussel <[email protected]>

use latest timecraft updates

c53dfdb

Signed-off-by: Achille Roussel <[email protected]>

capture peer socket address

dc33608

Signed-off-by: Achille Roussel <[email protected]>

more human friendly output

f3e3b5d

Signed-off-by: Achille Roussel <[email protected]>

more friendly yaml output

7e45dc9

Signed-off-by: Achille Roussel <[email protected]>

add verbose flag

61e2194

Signed-off-by: Achille Roussel <[email protected]>

more compact output

c5c83ac

Signed-off-by: Achille Roussel <[email protected]>

achille-roussel force-pushed the trace branch from 6ac406d to c5c83ac Compare June 4, 2023 17:43

update wasi-go

17623f1

Signed-off-by: Achille Roussel <[email protected]>

update wasi-go to v0.3.2

8d79c58

Signed-off-by: Achille Roussel <[email protected]>

achille-roussel force-pushed the trace branch from 4283fb4 to 8d79c58 Compare June 5, 2023 23:02

chriso approved these changes Jun 6, 2023

View reviewed changes

internal/debug/nettrace/nettrace.go Outdated Show resolved Hide resolved

internal/debug/nettrace/nettrace.go Show resolved Hide resolved

internal/debug/nettrace/nettrace.go Outdated Show resolved Hide resolved

PR feedback

fdafdab

Signed-off-by: Achille Roussel <[email protected]>

achille-roussel merged commit 7bacee5 into main Jun 6, 2023
3 checks passed

achille-roussel deleted the trace branch June 6, 2023 02:50

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

timecraft: add trace command #43

timecraft: add trace command #43

achille-roussel commented Jun 1, 2023

achille-roussel commented Jun 1, 2023

achille-roussel commented Jun 4, 2023

achille-roussel commented Jun 5, 2023

timecraft: add trace command #43

timecraft: add trace command #43

Conversation

achille-roussel commented Jun 1, 2023

achille-roussel commented Jun 1, 2023

achille-roussel commented Jun 4, 2023

achille-roussel commented Jun 5, 2023