soup_message_io_unpause

[ZanderBrown]

My valum application is throwing this seemingly at random:

libsoup-CRITICAL **: 18:41:23.693: soup_message_io_unpause: assertion 'io != NULL' failed

Inital look suggests it's being thrown here:

vsgi/src/servers/vsgi-http.vala

Line 192 in 0ebb83e

soup_server.unpause_message (message);

As for why message becomes null i don't know

[ZanderBrown]

Actually might be here:

vsgi/src/servers/vsgi-http.vala

Line 70 in 0ebb83e

server.unpause_message (message);

Little more debugging needed...

[ZanderBrown]

So Soup is failing deep down here:
https://github.com/GNOME/libsoup/blob/f33de90ae9af9e340198ed2eead1f9cfb1793fd2/libsoup/soup-message-io.c#L1309-L1326

With this patch:

diff --git a/src/servers/vsgi-http.vala b/src/servers/vsgi-http.vala
index aad913a..cbad3ea 100644
--- a/src/servers/vsgi-http.vala
+++ b/src/servers/vsgi-http.vala
@@ -38,6 +38,9 @@ namespace VSGI.HTTP {

                public MessageBodyOutputStream (Soup.Server server, Message message) {
                        Object (server: server, message: message);
+                       message.finished.connect(() => GLib.message("MessageBodyOutputStream Finished"));
+                       message.restarted.connect(() => GLib.message("MessageBodyOutputStream Restarted"));
+                       message.starting.connect(() => GLib.message("MessageBodyOutputStream Starting"));
                }

                construct {
@@ -67,6 +70,9 @@ namespace VSGI.HTTP {
                        if (unlikely (aborted)) {
                                throw new IOError.FAILED ("Request has been aborted.");
                        }
+                       if (message == null) {
+                               warning("Null message in flush");
+                       }
                        server.unpause_message (message);
                        return true;
                }
@@ -113,7 +119,10 @@ namespace VSGI.HTTP {
                                query:             query,
                                headers:           msg.request_headers,
                                body:              new MemoryInputStream.from_data (msg.request_body.data, null));
-               }
+                               message.finished.connect(() => GLib.message("Request Finished"));
+                               message.restarted.connect(() => GLib.message("Request Restarted"));
+                               message.starting.connect(() => GLib.message("Request Starting"));
+                       }

 #if SOUP_2_50
                public override IOStream? steal_connection () {
@@ -159,6 +168,9 @@ namespace VSGI.HTTP {
                                message:     msg,
                                headers:     msg.response_headers,
                                body:        new MessageBodyOutputStream (soup_server, msg));
+                               message.finished.connect(() => GLib.message("Response Finished"));
+                               message.restarted.connect(() => GLib.message("Response Restarted"));
+                               message.starting.connect(() => GLib.message("Response Starting"));
                }

                construct {
@@ -189,6 +201,9 @@ namespace VSGI.HTTP {
                 */
                protected override bool write_headers (MessageHeaders headers, out size_t bytes_written, Cancellable? cancellable = null) throws IOError {
                        bytes_written = 0;
+                       if (message == null) {
+                               warning("Null message in flush");
+                       }
                        soup_server.unpause_message (message);
                        return true;
                }

I get:

** Message: 20:14:50.082: app.vala:72: Request GET /
** Message: 20:14:50.091: vsgi-http.vala:41: MessageBodyOutputStream Finished
** Message: 20:14:50.496: app.vala:72: Request GET /static/style.css
** Message: 20:14:50.496: vsgi-http.vala:122: Request Finished
** Message: 20:14:50.497: vsgi-http.vala:41: MessageBodyOutputStream Finished
** Message: 20:14:50.497: vsgi-http.vala:171: Response Finished

(app:8886): libsoup-CRITICAL **: 20:14:50.497: soup_message_io_unpause: assertion 'io != NULL' failed

(app:8886): libsoup-CRITICAL **: 20:14:50.497: soup_message_io_unpause: assertion 'io != NULL' failed

No idea where to go from here.

[arteymix]

This is probably fixing a long-term problem I had with libsoup: determining when the request is aborted (and thus the message->io NULL). We need to ensure that a IOError is propagated when the finished signal is emitted on futher flush, write and read operations.

[ZanderBrown]

Not quite sure I understand what you mean there?

[arteymix]

Can you test 6cf38f1?

Essentially, when the response is completely out of scope, it triggers a Soup.Server.unpause_message to resume I/O and flush the headers and body, but there's no guarantee that message->io is still usable by then.

[ZanderBrown]

Sure, glad my debug by print has been of some assistance:

** Message: 22:32:37.907: app.vala:72: Request GET /
** Message: 22:32:38.119: app.vala:72: Request GET /static/style.css

** (app:28946): CRITICAL **: 22:32:38.120: valum-basic.vala:169: Connection closed by peer. (g-io-error-quark, 44)

** (app:28946): CRITICAL **: 22:32:38.120: valum-basic.vala:173: Connection closed by peer. (g-io-error-quark, 44)

** (app:28946): CRITICAL **: 22:32:38.121: valum-basic.vala:181: Stream is already closed (g-io-error-quark, 18)
** Message: 22:32:40.810: app.vala:72: Request GET /login
** Message: 22:32:41.030: app.vala:72: Request GET /static/style.css

** (app:28946): CRITICAL **: 22:32:41.031: vsgi-response.vala:536: Could not write the head in the connection stream: Connection closed by peer. (g-io-error-quark, 44).
** Message: 22:32:42.498: app.vala:72: Request POST /login

Interestingly it seems to be consistently /static/style.css that sets it off which is served from gresource like so:

app.get ("/static/<path:path>", serve_from_file (File.new_for_uri ("resource://static")));

For the record client navigator.userAgent:

Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:59.0) Gecko/20100101 Firefox/59.0

[arteymix]

Have you tried serve_from_resource?

I'll test the resource:// URI as well, but I think it has some limitations with ETag.

[ZanderBrown]

How would I do that without a separate resource bundle?

The resource:// solution is taken from the docs

To deliver from the global resources, use the resource:// scheme.

app.get ("/static/path:path", serve_from_file (File.new_for_uri ("resource://static")));

[arteymix]

Can you gist the specific part of code?

[ZanderBrown]

Minimal sample here:
https://github.com/ZanderBrown/valum-problem-demo

Vala source being:

using Valum;
using Valum.Static;
using VSGI;

public int main (string[] args) {
	var app = new Router ();

	app.use (basic ());
	app.use (decode ());

	app.use ((req, res, next) => {
		message("Request %s %s".printf(req.method, req.uri.get_path()));
		res.headers.append ("Server", "Valum/1.0");
		var @params = new HashTable<string, string> (str_hash, str_equal);
		@params["charset"] = "utf-8";
		res.headers.set_content_type ("text/html", @params);
		return next ();
	});

	app.get ("/static/<path:path>", serve_from_file (File.new_for_uri ("resource://static")));

	app.get("/", (req, res, next) => {
		return res.expand_utf8("Teapot?");
	});

	return Server.@new ("http", handler: app).run (args);
}
``

[arteymix]

It works on your side, right? I see the debug message and I'll investigate where it comes from.

[ZanderBrown]

Yes that demo will compile & operate as expected aside from the

Could not write the head in the connection stream: Connection closed by peer.

But the expected resource is still received

[astavale]

If it's any help you can get a stack trace from GLib critical using G_DEBUG and gdb:
G_DEBUG=fatal-criticals gdb my_test_program

A little more detail:
https://wiki.gnome.org/Projects/Vala/DeveloperDocumentation#Debugging
https://wiki.gnome.org/Projects/Vala/Tools/VisualStudioCode#Debugging

With VS Code it should allow you to set a break point and step through the code.

[ZanderBrown]

@astavale that's good to know