Re: libsoup websocket server memory problems

[Benjamin Reikowski <reikowski dresearch-fe de>]

Hello Claudio,

thank you for the fast response! As requested, the GDB backtraces with G_MESSAGES_DEBUG=all

(gdb) run
Starting program: /home/benjamin/Downloads/spielwiese/main
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
** Message: 16:38:23.430: ws server started
** Message: 16:38:26.434: websocket_client_connect_cb
(process:24969): libsoup-DEBUG: 16:38:27.582: stopping input source
(process:24969): libsoup-DEBUG: 16:38:27.582: received control frame 8 with 0 payload
(process:24969): libsoup-DEBUG: 16:38:27.582: responding to close request
(process:24969): libsoup-DEBUG: 16:38:27.582: sent frame
(process:24969): libsoup-DEBUG: 16:38:27.582: closing io stream
[New Thread 0x7ffff6a4d700 (LWP 24977)]
(process:24969): libsoup-DEBUG: 16:38:27.583: queued 8 frame of len 4
(process:24969): libsoup-DEBUG: 16:38:27.584: waiting 5 seconds for peer to close io
(process:24969): libsoup-DEBUG: 16:38:27.584: closed: completed io stream close
** Message: 16:38:27.584: websocket_client_closed_cb
**
libsoup:ERROR:../libsoup/soup-websocket-connection.c:1445:soup_websocket_connection_finalize: assertion failed: (!pv->input_source)
Bail out! libsoup:ERROR:../libsoup/soup-websocket-connection.c:1445:soup_websocket_connection_finalize: assertion failed: (!pv->input_source)

Thread 1 "main" received signal SIGABRT, Aborted.
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
50  return ret;
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x00007ffff78778d9 in __GI_abort () at abort.c:79
#2  0x00007ffff7ea3b53 in g_assertion_message
    (domain=<optimized out>, file=<optimized out>, line=<optimized out>, func=0x7ffff7e57e20 <__FUNCTION__.28854> "soup_websocket_connection_finalize", message=<optimized out>)
    at ../glib/gtestutils.c:2912
#3  0x00007ffff7f001df in g_assertion_message_expr
    (domain=domain@entry=0x7ffff7e4c94e "libsoup", file=file@entry=0x7ffff7e56e20 "../libsoup/soup-websocket-connection.c", line=line@entry=1445, func=func@entry=0x7ffff7e57e20 <__FUNCTION__.28854> "soup_websocket_connection_finalize", expr=expr@entry=0x7ffff7e56b26 "!pv->input_source") at ../glib/gtestutils.c:2938
#4  0x00007ffff7e40f79 in soup_websocket_connection_finalize (object=0x42dab0 [SoupWebsocketConnection]) at ../libsoup/soup-websocket-connection.c:1445
#5  0x00007ffff7bb6cb0 in g_object_unref (_object=<optimized out>) at ../gobject/gobject.c:3382
#6  g_object_unref (_object=0x42dab0) at ../gobject/gobject.c:3274
#7  0x00007ffff7e41814 in on_iostream_closed (source=<optimized out>, result=<optimized out>, user_data=user_data@entry=0x42dab0) at ../libsoup/soup-websocket-connection.c:297
#8  0x00007ffff7cad2ba in g_task_return_now (task=0x47a820 [GTask]) at ../gio/gtask.c:1212
#9  0x00007ffff7cade8d in g_task_return (task=0x47a820 [GTask], type=<optimized out>) at ../gio/gtask.c:1281
#10 0x00007ffff7cae7ee in g_task_return (type=G_TASK_RETURN_SUCCESS, task=<optimized out>) at ../gio/gtask.c:1797
#11 g_task_return_boolean (task=<optimized out>, result=<optimized out>) at ../gio/gtask.c:1801
#12 0x0000000000000000 in  ()
(gdb)

Unfortunately I didn't manage to get a full backtrace on my x64 Workstation but on my ARMv7 platform:

(gdb) run
Starting program: /home/root/main2
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/libthread_db.so.1".
** Message: 15:18:58.822: ws server started
** Message: 15:19:07.256: websocket_client_connect_cb
(process:12326): libsoup-DEBUG: 15:19:08.896: stopping input source
(process:12326): libsoup-DEBUG: 15:19:08.896: received control frame 8 with 0 payload
(process:12326): libsoup-DEBUG: 15:19:08.897: responding to close request
(process:12326): libsoup-DEBUG: 15:19:08.897: sent frame
(process:12326): libsoup-DEBUG: 15:19:08.897: closing io stream
[New Thread 0x76823460 (LWP 12329)]
(process:12326): libsoup-DEBUG: 15:19:08.901: queued 8 frame of len 4
(process:12326): libsoup-DEBUG: 15:19:08.902: waiting 5 seconds for peer to close io
(process:12326): libsoup-DEBUG: 15:19:08.902: closed: completed io stream close
** Message: 15:19:08.903: websocket_client_closed_cb
**
libsoup:ERROR:../libsoup-2.68.3/libsoup/soup-websocket-connection.c:1445:soup_websocket_connection_finalize: assertion failed: (!pv->input_source)
Bail out! libsoup:ERROR:../libsoup-2.68.3/libsoup/soup-websocket-connection.c:1445:soup_websocket_connection_finalize: assertion failed: (!pv->input_source)

Thread 1 "main2" received signal SIGABRT, Aborted.
__libc_do_syscall () at libc-do-syscall.S:49
49      libc-do-syscall.S: No such file or directory.
(gdb) bt
#0  0x76c80c46 in __libc_do_syscall () at libc-do-syscall.S:49
#1  0x76c8dfa4 in __libc_signal_restore_set (set=0x7efff758) at ../sysdeps/unix/sysv/linux/internal-signals.h:84
#2  0x76c8dfa4 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:48
#3  0x76c806e6 in __GI_abort () at abort.c:79
#4  0x76f57bde in g_assertion_message
    (domain=domain@entry=0x76ef2f1c "libsoup", file=file@entry=0x76ef93b8 "../libsoup-2.68.3/libsoup/soup-websocket-connection.c", line=line@entry=1445, func=func@entry=0x76efde48 <__FUNCTION__.3022
#5  0x76f57c50 in g_assertion_message_expr
    (domain=0x76ef2f1c "libsoup", file=0x76ef93b8 "../libsoup-2.68.3/libsoup/soup-websocket-connection.c", line=line@entry=1445, func=0x76efde48 <__FUNCTION__.30297> "soup_websocket_connection_fina8
#6  0x76eea218 in soup_websocket_connection_finalize (object=0x2c098 [SoupWebsocketConnection]) at ../libsoup-2.68.3/libsoup/soup-websocket-connection.c:1445
#7  0x76d68528 in g_object_unref (_object=<optimized out>) at ../glib-2.62.4/gobject/gobject.c:3382
#8  0x76d68528 in g_object_unref (_object=0x2c098) at ../glib-2.62.4/gobject/gobject.c:3274
#9  0x76eea8c0 in on_iostream_closed (source=<optimized out>, result=<optimized out>, user_data=0x2c098) at ../libsoup-2.68.3/libsoup/soup-websocket-connection.c:297
#10 0x76e0bbec in g_task_return_now (task=0x2e400 [GTask]) at ../glib-2.62.4/gio/gtask.c:1212
#11 0x76e0c456 in g_task_return (task=0x2e400 [GTask], type=<optimized out>) at ../glib-2.62.4/gio/gtask.c:1281
#12 0x76e0ca88 in g_task_return (type=G_TASK_RETURN_SUCCESS, task=<optimized out>) at ../glib-2.62.4/gio/gtask.c:1797
#13 0x76e0ca88 in g_task_return_boolean (task=<optimized out>, result=<optimized out>) at ../glib-2.62.4/gio/gtask.c:1801
#14 0x76decf84 in async_ready_close_callback_wrapper (source_object=<optimized out>, res=0x2e478, user_data=0x2e400) at ../glib-2.62.4/gio/giostream.c:455
#15 0x76e0bbec in g_task_return_now (task=0x2e478 [GTask]) at ../glib-2.62.4/gio/gtask.c:1212
#16 0x76e0c456 in g_task_return (task=0x2e478 [GTask], type=<optimized out>) at ../glib-2.62.4/gio/gtask.c:1281
#17 0x76e0ca88 in g_task_return (type=G_TASK_RETURN_SUCCESS, task=<optimized out>) at ../glib-2.62.4/gio/gtask.c:1797
#18 0x76e0ca88 in g_task_return_boolean (task=<optimized out>, result=<optimized out>) at ../glib-2.62.4/gio/gtask.c:1801
#19 0x76ed0f34 in close_async_complete (object=0xc268 [GTcpConnection], result=0x2e4f0, user_data=0x2e478) at ../libsoup-2.68.3/libsoup/soup-io-stream.c:147
#20 0x76e0bbec in g_task_return_now (task=0x2e4f0 [GTask]) at ../glib-2.62.4/gio/gtask.c:1212
#21 0x76e0c456 in g_task_return (task=0x2e4f0 [GTask], type=<optimized out>) at ../glib-2.62.4/gio/gtask.c:1281
#22 0x76e0ca88 in g_task_return (type=G_TASK_RETURN_SUCCESS, task=<optimized out>) at ../glib-2.62.4/gio/gtask.c:1797
--Type <RET> for more, q to quit, c to continue without paging--
#23 0x76e0ca88 in g_task_return_boolean (task=<optimized out>, result=<optimized out>) at ../glib-2.62.4/gio/gtask.c:1801
#24 0x76decf84 in async_ready_close_callback_wrapper (source_object=<optimized out>, res=0x2e568, user_data=0x2e4f0) at ../glib-2.62.4/gio/giostream.c:455
#25 0x76e0bbec in g_task_return_now (task=0x2e568 [GTask]) at ../glib-2.62.4/gio/gtask.c:1212
#26 0x76e0bc20 in complete_in_idle_cb (task=0x2e568) at ../glib-2.62.4/gio/gtask.c:1226
#27 0x76f3d08a in g_main_dispatch (context=0x11f78) at ../glib-2.62.4/glib/gmain.c:3179
#28 0x76f3d08a in g_main_context_dispatch (context=context@entry=0x11f78) at ../glib-2.62.4/glib/gmain.c:3844
#29 0x76f3d2f8 in g_main_context_iterate (context=0x11f78, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../glib-2.62.4/glib/gmain.c:3917
#30 0x76f3d534 in g_main_loop_run (loop=0x13430) at ../glib-2.62.4/glib/gmain.c:4111
#31 0x00008c7c in main (argc=1, argv=0x7efffd44) at main2.c:112
(gdb) 

If you still think it's a bug, I will create an issue at https://gitlab.gnome.org/GNOME/libsoup/issues tomorrow.

With best regards

Benjamin Reikowski

On Wed, 15 Jan 2020 at 15:40, Claudio Saavedra <csaavedra gnome org> wrote:

On Wed, 2020-01-15 at 14:12 +0100, Benjamin Reikowski wrote:
> Hello libsoup mailing list members,
>
> I'm using the libsoup websocket server and recently updated my
> libsoup from
> 2.64.2 to 2.68.3 due to a bug that has been fixed with
> https://github.com/GNOME/libsoup/commit/35f1bac5ff9ec694e64b65e51f0e7a3226aa3aaf
>
>
[...]

> This assertion is new and did not happen before the commit I
> mentioned at the beginning. I do NOT run into this g_assert if I'm
> either not using g_object_unref(ws) in function
> websocket_client_closed_cb or delay it by 1s. But I HAVE to use
> g_object_ref(ws) in function websocket_client_connect_cb otherwise
> the SoupWebsocketConnection *ws would not survive. After I discovered
> that, I took a look into your regression code (namely
> tests/websocket-tests.c) and found you doing the same:
> g_object_ref(ws) on every client connect and no g_object_unref(ws) on
> "closed".

The test program does drop the reference to the websocket connection at
some point durign teardown. See the
teardown_direct_connection_method().

You need to keep a reference to the connection, since you're
responsible for it. I think it's reasonably to drop it in the "closed"
handler, but there might be a bug there.

> At last, I used valgrind on my example code and found out that it's
> pretty leaky w/o g_object_unref(ws).
>
> So my question: did I do something wrong in my example code or is
> this possibly a bug?

It's possibly a bug. It would be helpful if you could

1. get a stacktrace at the assertion failure.

2. Enable debug output, I think G_MESSAGES_DEBUG is useful for that.

I think you could report it in gitlab if you have that info.

The commit you referenced above changed how the input sources work. It
is possible that we overlooked something (like that it's possible that
during finalize there is no input source at all).


Claudio


_______________________________________________
libsoup-list mailing list
libsoup-list gnome org
https://mail.gnome.org/mailman/listinfo/libsoup-list

--

Mit freundlichen Grüßen • with best regards

-----------------------------------------------------------------------------------

Benjamin Reikowski
Softwareentwickler (B.Eng.)

Kunden Support/Customer support:

Mail: support dresearch-fe de

Hotline +49 (30) 515 932 112, Mo. - Do. von 10:00 Uhr - 16:00 Uhr, Freitags von 10:00 bis 13:00 Uhr

DResearch Fahrzeugelektronik GmbH

Otto-Schmirgal-Str. 3

D-10319 Berlin, Germany

Phone: +49 30 515 932 231

Fax:     +49 30 515 932 77

E-mail: reikowski dresearch-fe de

www:   http://www.dresearch-fe.de  

General Management  • Geschäftsführung:

Dr. Michael Weber, Werner Mögle

Amtsgericht Berlin Charlottenburg, HRB 130120, Ust.-IDNr. DE273952058

Please consider the environment before printing this email

Wir ziehen um! Bitte beachten Sie unsere neue Anschrift ab 1.4.2020:

We're moving! Please note our new address from 1.4.2020:

DResearch Fahrzeugelektronik GmbH

Tor 2, Aufgang R (R03.020)
Wolfener Straße 36
12681 Berlin