search

vlang / v

Simple, fast, safe, compiled language for developing maintainable software. Compiles itself in <1s with zero library dependencies. Supports automatic C => V translation. https://vlang.io
MIT License
35.83k stars 2.17k forks source link

vweb/server_sent_events intermittent crashes #15112

Open jminor opened 2 years ago

jminor commented 2 years ago

Using latest v source cloned from github today (2022-07-17)

OS: macos, macOS, 12.4, 21F79
Processor: 10 cpus, 64bit, little endian, Apple M1 Max
CC version: Apple clang version 13.1.6 (clang-1316.0.21.2.5)

getwd: /Users/jminor/git/v-repro
vmodules: /Users/jminor/.vmodules
vroot: /Users/jminor/git/v-repro
vexe: /Users/jminor/git/v-repro/v
vexe mtime: 2022-07-17 19:13:39
is vroot writable: true
is vmodules writable: true
V full version: V 0.3.0 706a922
env VFLAGS: "-d dynamic_boehm"

Git version: git version 2.36.1
Git vroot status: weekly.2022.28-26-g706a922e
.git/config present: true
thirdparty/tcc status: thirdparty-macos-amd64 46662e20

Note: I'm using VFLAGS: "-d dynamic_boehm" as a workaround for this: https://github.com/vlang/v/issues/14888 which may be related to these crashes.

What did you do? v run examples/vweb/server_sent_events/server.v and open three browser windows all with the URL http://localhost:8081/

What did you expect to see?

[Vweb] Running app on http://localhost:8081/
> sent event: {"time": "2022-07-17 12:28:50", "random_id": "01G86T50C6T6QEHYS6MYVG8J6K"}
> sent event: {"time": "2022-07-17 12:28:51", "random_id": "01G86T51BFA6JFJAYWSYHRB769"}
> sent event: {"time": "2022-07-17 12:28:51", "random_id": "01G86T51BFA6JFJAYWSYHRB769"}
> sent event: {"time": "2022-07-17 12:28:52", "random_id": "01G86T52AWA0NBVBPANDP0QC6K"}
> sent event: {"time": "2022-07-17 12:28:52", "random_id": "01G86T52AXXCEQRSTDGPYR2X0P"}

etc.

What did you see instead?

> sent event: {"time": "2022-07-17 12:27:13", "random_id": "01G86T223XBMRPTBPYHJE46WJJ"}
signal 11: segmentation fault
signal 11: segmentation fault
0   libsystem_platform.dylib            0x00007ff813d1adfd _sigtramp + 29
0   libsystem_platform.dylib            0x00007ff813d1adfd _sigtramp + 29
1   ???                                 0x0000000000000000 0x0 + 0
1   server                              0x00000001043d2cc0 map_free_string + 0
2   server                              0x00000001043cd797 net__TcpConn_write + 39
2   server                              0x00000001043cd797 net__TcpConn_write + 39
3   server                              0x000000010442a219 vweb__sse__SSEConnection_send_message + 1001
3   server                              0x000000010442a219 vweb__sse__SSEConnection_send_message + 1001
4   server                              0x000000010444653f main__App_sse + 1119
4   server                              0x000000010444653f main__App_sse + 1119
5   server                              0x00000001043cfe3d vweb__handle_conn_T_main__App + 8253
5   server                              0x00000001043cfe3d vweb__handle_conn_T_main__App + 8253
6   server                              0x00000001043cddec vweb__handle_conn_T_main__App_thread_wrapper + 108
6   server                              0x00000001043cddec vweb__handle_conn_T_main__App_thread_wrapper + 108
7   libsystem_pthread.dylib             0x00007ff813d054e1 _pthread_start + 125
7   libsystem_pthread.dylib             0x00007ff813d054e1 _pthread_start + 125
8   libsystem_pthread.dylib             0x00007ff813d00f6b thread_start + 15
8   libsystem_pthread.dylib             0x00007ff813d00f6b thread_start + 15

and

[Vweb] Running app on http://localhost:8081/
error parsing request: net.http.HeaderKeyError: Invalid header key: ''
> sent event: {"time": "2022-07-17 12:27:23", "random_id": "01G86T2BY3F9YT326N57W5EEZF"}
signal 11: segmentation fault
0   libsystem_platform.dylib            0x00007ff813d1adfd _sigtramp + 29
1   ???                                 0x0000000000000000 0x0 + 0
2   ???                                 0x0000000000000008 0x0 + 8

and

> sent event: {"time": "2022-07-17 12:28:14", "random_id": "01G86T3XVTAYBR3VZ7DYK3FXHP"}
> sent event: {"time": "2022-07-17 12:28:15", "random_id": "01G86T3YV4578CD8VGY6W3KNNB"}
> sent event: {"time": "2022-07-17 12:28:15", "random_id": "01G86T3YV4578CD8VGY6W3KNNB"}
> sent event: {"time": "2022-07-17 12:28:16", "random_id": "01G86T3ZTH4MZN2WV11ABZ5FVF"}
signal 11: segmentation fault
0   libsystem_platform.dylib            0x00007ff813d1adfd _sigtramp + 29
1   server                              0x0000000102a5b54f net__http__parse_request_head + 1631
2   libsystem_notify.dylib              0x00007ff8166a8c8f notify_monitor_file + 1997
3   libsystem_notify.dylib              0x00007ff8166a3d73 notify_check + 1538
4   ???                                 0x000000030adcaf20 0x0 + 13067136800

and sometimes

> sent event: {"time": "2022-07-16 00:18:32", "random_id": "01G82XZ2W1DG3Q3DQ2KQ7CK90Y"}
> sent event: {"time": "2022-07-16 00:18:33", "random_id": "01G82XZ3VCWB6MZFHEBDCJFYK3"}
Collecting from unknown thread
jminor commented 2 years ago

I haven't been able to catch this in the debugger with the vweb sample code, but I did get this with my larger application which is having similar crashes.

(base) ~/git/hashfs ⭐ lldb ./hashfs               
(lldb) target create "./hashfs"
Current executable set to '/Users/jminor/git/hashfs/hashfs' (x86_64).
(lldb) run -root data_md5
Process 6289 launched: '/Users/jminor/git/hashfs/hashfs' (x86_64)
HashFS root folder: /Users/jminor/git/hashfs/data_md5
  MD5-60eea08b4d9fb2a23487e64ca88ab29d image/png 9725 c64_logo.png
  MD5-78615d9306bf038ac658c8d6a194f855 image/jpeg 39176 Hilda.jpg
  MD5-34b4bb9502e8513dc7bd906d7f1efca6 image/jpeg 22790 kitten.jpg
[Vweb] Running app on http://localhost:7777/
upload upfile:
wrote {"hash":"MD5-60eea08b4d9fb2a23487e64ca88ab29d","size":9725,"content_type":"image/png","original_filename":"c64_logo.png","upload_date":"Sun, 17 Jul 2022 13:00:29 UTC"} to meta file /Users/jminor/git/hashfs/data_md5/MD5-60eea08b4d9fb2a23487e64ca88ab29d.meta
saved: #1 c64_logo.png image/png 9725 bytes as /Users/jminor/git/hashfs/data_md5/MD5-60eea08b4d9fb2a23487e64ca88ab29d
meta: {"hash":"MD5-60eea08b4d9fb2a23487e64ca88ab29d","size":9725,"content_type":"image/png","original_filename":"c64_logo.png","upload_date":"Sun, 17 Jul 2022 13:00:29 UTC"}
Collecting from unknown thread
Process 6289 stopped
* thread #11, stop reason = signal SIGABRT
    frame #0: 0x00007ff813ccf00e libsystem_kernel.dylib`__pthread_kill + 10
libsystem_kernel.dylib`__pthread_kill:
->  0x7ff813ccf00e <+10>: jae    0x7ff813ccf018            ; <+20>
    0x7ff813ccf010 <+12>: movq   %rax, %rdi
    0x7ff813ccf013 <+15>: jmp    0x7ff813cc91c5            ; cerror_nocancel
    0x7ff813ccf018 <+20>: retq   
Target 0: (hashfs) stopped.
(lldb) where
error: 'where' is not a valid command.
(lldb) bt
* thread #11, stop reason = signal SIGABRT
  * frame #0: 0x00007ff813ccf00e libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007ff813d051ff libsystem_pthread.dylib`pthread_kill + 263
    frame #2: 0x00007ff813c50d24 libsystem_c.dylib`abort + 123
    frame #3: 0x00000001088e7ac1 libgc.1.dylib`GC_push_all_stacks.cold.1 + 25
    frame #4: 0x00000001088e64ff libgc.1.dylib`GC_push_all_stacks + 322
    frame #5: 0x00000001088dd60f libgc.1.dylib`GC_mark_some + 689
    frame #6: 0x00000001088d5e9f libgc.1.dylib`GC_stopped_mark + 177
    frame #7: 0x00000001088d5d49 libgc.1.dylib`GC_try_to_collect_inner + 292
    frame #8: 0x00000001088d6d4e libgc.1.dylib`GC_collect_or_expand + 181
    frame #9: 0x00000001088dbce8 libgc.1.dylib`GC_alloc_large + 206
    frame #10: 0x00000001088dc1cf libgc.1.dylib`GC_generic_malloc + 299
    frame #11: 0x00000001088dc328 libgc.1.dylib`GC_malloc_kind_global + 219
    frame #12: 0x0000000100011f40 hashfs`vcalloc_noscan(n=131072) at builtin.c.v:544:10
    frame #13: 0x0000000100012c1a hashfs`__new_array_with_default_noscan(mylen=131072, cap=131072, elm_size=1, val=0x0000000000000000) at array_d_gcboehm_opt.v:21:56
    frame #14: 0x000000010005ae9d hashfs`io__new_buffered_reader(o=io__BufferedReaderConfig @ 0x0000000304e78160) at buffered_reader.v:29:103
    frame #15: 0x000000010000bc17 hashfs`vweb__handle_conn_T_main__App(conn=0x0000000109432750, app=0x0000000109455800, routes=Map_string_vweb__Route @ 0x0000000304e7bf30) at vweb.v:443:11
    frame #16: 0x000000010000bb3c hashfs`vweb__handle_conn_T_main__App_thread_wrapper(arg=0x0000600003000000) at hashfs.tmp.c:6968:2
    frame #17: 0x00007ff813d054e1 libsystem_pthread.dylib`_pthread_start + 125
    frame #18: 0x00007ff813d00f6b libsystem_pthread.dylib`thread_start + 15
jminor commented 2 years ago

FYI, after switching back to the default gc (no longer using VFLAGS="-d dynamic_boehm") the problem seems to have gone away.

davidebeatrici commented 2 years ago

Could you verify that #15275 solves the issue, please?