Second webhook : 404 Not Found

[BhasherBEL]

Using the version 0.2.0, I faced the same issue than #2 . I already have a working instance, using ID "webhook", but failed to create another one, under "webhook_homelab". Here is the content of the releavents log during the creation of the second instance :

[2024-01-31 22:57:37,489] [DEBUG@maubot.instance.webhook_homelab] Plugin instance dependencies loaded
[2024-01-31 22:57:37,501] [DEBUG@maubot.instance.webhook_homelab] Creating background task to save updated config
[2024-01-31 22:57:37,501] [INFO@maubot.instance.webhook_homelab] Webhook available at: https://maubot.xxxx.com/_matrix/maubot/plugin/webhook_homelab/send
[2024-01-31 22:57:37,502] [INFO@maubot.instance.webhook_homelab] Started instance of me.jkhsjdhjs.maubot.webhook v0.2.0 with user @xxxx:xxxx.com

But I got 404 not found error, with no debug line from the webhook_instance.

[2024-01-31 22:58:34,089] [INFO@aiohttp.access] 172.22.0.7 "POST /_matrix/maubot/plugin/webhook_homelab/send 404 173 in 0.0006s"

I tried to restart maubot, with the same result.

[2024-01-31 23:06:06,104] [DEBUG@maubot.instance.webhook_homelab] Plugin instance dependencies loaded
...
[2024-01-31 23:06:06,525] [INFO@maubot.instance.webhook_homelab] Webhook available at: https://maubot.xxxx.com/_matrix/maubot/plugin/webhook_homelab/send
[2024-01-31 23:06:06,525] [INFO@maubot.instance.webhook_homelab] Started instance of me.jkhsjdhjs.maubot.webhook v0.2.0 with user @xxxx:xxxx.com
...
[2024-01-31 23:06:06,553] [DEBUG@maubot.instance.webhook_homelab] Plugin instance dependencies loaded
...
[2024-01-31 23:07:24,412] [INFO@aiohttp.access] 172.22.0.7 "POST /_matrix/maubot/plugin/webhook_homelab/send 404 173 in 0.0027s"
[2024-01-31 23:08:11,003] [INFO@aiohttp.access] 172.22.0.7 "POST /_matrix/maubot/plugin/webhook_homelab/send 404 173 in 0.002s"

any idea of the source of the issue since #2 ? Can I provide something else that could help debug this ?

My first webook, with id "webhook" is still working.

[jkhsjdhjs]

Hmm, I really don't know what's going wrong here, but it looks like something is going wrong with maubot internally, since maubot-webhook simply calls self.webapp.add_route(): https://github.com/jkhsjdhjs/maubot-webhook/blob/703d720ee37baff1845a3ab9ee104d9a7f120678/plugin.py#L135-L138

But it's good that you were able to reproduce the issue after a maubot reboot, maybe we can finally get to the bottom of this issue. As a first step, can you tell me which version of maubot you're using? How familiar are you with python? I think it would be useful if you could insert some debug log statements into maubot and/or aiohttp, but I would have to determine where exactly they would be useful first.

[jkhsjdhjs]

For starters, you can use the following version that has a few debug prints around .add_route(), that might be helpful: me.jkhsjdhjs.maubot.webhook-v0.2.0.zip (Rename it to .mbp, GitHub doesn't allow me to upload .mbp files)

[BhasherBEL]

I was using v0.2.0 and I am well familiar with python, so add debugs or try some fix isn't a problem.

I tried with your version, and after a restart of maubot, here is the complete footprint (I included both instances, as it might be relevant). I also called both instance. I voluntarily don't follow the expected format for the "webhook", to not flood the room (so the 500 error is expected on that line)

[2024-02-01 00:17:57,987] [DEBUG@maubot.instance.zip] Loaded and imported plugin me.jkhsjdhjs.maubot.webhook from /data/plugins/me.jkhsjdhjs.maubot.webhook-v0.2.0-ts1706746620078.mbp
[2024-02-01 00:17:57,992] [INFO@maubot.instance.webhook_homelab] Webapp _resources: []
[2024-02-01 00:17:57,992] [INFO@maubot.instance.webhook_homelab] Webapp _named_resources: {}
[2024-02-01 00:17:57,992] [INFO@maubot.instance.webhook_homelab] Webapp _resources: [<PlainResource  /send>]
[2024-02-01 00:17:57,993] [INFO@maubot.instance.webhook_homelab] Webapp _named_resources: {}
[2024-02-01 00:17:57,993] [INFO@maubot.instance.webhook_homelab] Webhook available at: https://maubot.xxxx.com/_matrix/maubot/plugin/webhook_homelab/send
[2024-02-01 00:17:57,993] [INFO@maubot.instance.webhook_homelab] Started instance of me.jkhsjdhjs.maubot.webhook v0.2.0 with user @xxxx:xxxx.com
[2024-02-01 00:17:57,998] [INFO@maubot.instance.webhook] Webapp _resources: []
[2024-02-01 00:17:57,998] [INFO@maubot.instance.webhook] Webapp _named_resources: {}
[2024-02-01 00:17:57,998] [INFO@maubot.instance.webhook] Webapp _resources: [<PlainResource  /send>]
[2024-02-01 00:17:57,998] [INFO@maubot.instance.webhook] Webapp _named_resources: {}
[2024-02-01 00:17:57,999] [INFO@maubot.instance.webhook] Webhook available at: https://maubot.xxxx.com/_matrix/maubot/plugin/webhook/send
[2024-02-01 00:17:57,999] [INFO@maubot.instance.webhook] Started instance of me.jkhsjdhjs.maubot.webhook v0.2.0 with user @xxxx:xxxx.com
[2024-02-01 00:17:58,071] [DEBUG@maubot.instance.webhook] Plugin instance dependencies loaded
[2024-02-01 00:17:58,071] [DEBUG@maubot.instance.mistral] Plugin instance dependencies loaded
[2024-02-01 00:17:58,071] [DEBUG@maubot.instance.webhook_homelab] Plugin instance dependencies loaded
[2024-02-01 00:17:58,072] [INFO@maubot.server] Listening on http://0.0.0.0:29316
[2024-02-01 00:17:58,072] [INFO@mau.init] Startup actions complete in 0.35 seconds, now running forever
[2024-02-01 00:18:01,935] [DEBUG@maubot.server.websocket] Connection from 172.22.0.7 opened
[2024-02-01 00:18:01,979] [DEBUG@maubot.server.websocket] Connection from 172.22.0.7 authenticated
[2024-02-01 00:18:29,062] [INFO@aiohttp.access] 172.22.0.7 "POST /_matrix/maubot/plugin/webhook_homelab/send 404 173 in 0.0008s"
[2024-02-01 00:20:14,064] [DEBUG@maubot.instance.webhook] Got request <Request POST /send >
[2024-02-01 00:20:14,065] [DEBUG@maubot.instance.webhook] Auth token is valid
[2024-02-01 00:20:14,081] [INFO@aiohttp.access] 172.22.0.7 "POST /_matrix/maubot/plugin/webhook/send 500 217 in 0.0178s"

[jkhsjdhjs]

Interesting, thanks for your reply! We can see that the resource is indeed successfully added to _resources of the PluginWebApp. Now we have to find out why the resource doesn't seem to be detected when a request is handled.

Can you add a few debug prints to the PluginWebApp.handle() function of maubot? https://github.com/maubot/maubot/blob/0c72e6fb1e0dcbccc718cff60f02e951b2b2cc57/maubot/plugin_server.py#L44-L58

I think it would be helpful to know what exactly the variable match_info contains. It apparently has a handler attribute, that holds the function to call for a given request, so my current guess is, that the resolve() function there doesn't correctly resolve the handler for the request. We can confirm this by logging match_info and maybe also match_info.handler explicitly.

EDIT: self._resource_index would also be interesting.

[BhasherBEL]

Here is the output for the not working instance:

<MatchInfoError 404: Not Found>
<bound method SystemRoute._handle of <SystemRoute 404: Not Found>>

And here for the working one:

<MatchInfo {}: <ResourceRoute [POST] <PlainResource  /send> -> <bound method WebhookPlugin.handle_request of <plugin.WebhookPlugin object at 0x7f4b2e06d950>>>
<bound method WebhookPlugin.handle_request of <plugin.WebhookPlugin object at 0x7f4b2e06d950>>

As i'm not really familiar with maubot codebase, I cannot really push forward the investigation.

[jkhsjdhjs]

Thanks! So it seems that indeed the aiohttp URLDispatcher.resolve() function is unable to determine a handler for the request, despite a handler being registered. Can you also log self._resource_index? This dict is used in URLDispatcher.resolve(), maybe the add_route() function added the route to _resources, but not to _resource_index for some reason.

[BhasherBEL]

I'm not very familiar with maubot codebase for this one. Where is the _resource_index property? If I try to print self._resource_index at the same place that the others variables, it doesn't exist.

[jkhsjdhjs]

I just found out why: The _resource_index variable was only recently added in aiohttp 3.9, so you're probably using an older version. This shouldn't cause any problems though, as maubot was developed for older aiohttp versions. (The opposite: it will probably cause issues to use maubot with aiohttp >= 3.9: https://github.com/maubot/maubot/issues/233)

Anyway, I just had a look at the pre-3.9 UrlDispatcher.resolve() function: https://github.com/aio-libs/aiohttp/blob/8d7df03381deb49fd7a8e1514e85688fc2a8b11e/aiohttp/web_urldispatcher.py#L983-L997

It seems to just iterate through self._resources, of which we already know that it contains <PlainResource /send>. It calls .resolve(request) on every resource and returns if it is not None. Thus we know that PlainResource.resolve(request) returns None, because otherwise match_info (which you already logged) wouldn't be 404. PlainResource inherits its resolve() function from Resource, which is defined here: https://github.com/aio-libs/aiohttp/blob/8d7df03381deb49fd7a8e1514e85688fc2a8b11e/aiohttp/web_urldispatcher.py#L347-L361 Could you modify your aiohttp install a bit by printing the match_dict in Resource.resolve()? Can you furthermore log self._path and request.rel_url.raw_path? These are used in PlainResource._match. If they aren't equal, it would explain why 404 is returned. We would then have to investigate why they aren't equal. Thanks in advance!

[jkhsjdhjs]

Hey, is this still an issue for you? Not a problem if you don't have much time currently, just asking because I'd really like to get to the bottom of this issue.

[BhasherBEL]

Hi, yes this is still an issue, but I don't really have time for it now. But it's still (somewhere) on my todo list.

[veso0308]

I noticed some issues when trying to create an instance with non-alphabetic characters in the name. Can you confirm that other instances with names like "secondinstance" or similar, without underscore "_" are working fine?

[veso0308]

Could somebody confirm, if instances with names containing underscore are working? Maybe @jkhsjdhjs :D Many thanks in advance!

[BhasherBEL]

I can confirm that, in my case it isn't. In the initial issue was related to two webhooks, webhook and webhook_homelab. But this issue seems to be specific, as others seems not the face it. You should probably try by yourself, and give us your feedback.

[veso0308]

In your initial issue I can only see errors from an instance containing underscore (webhook_instance). I tried it myself, it isn't working, I could reproduce the issue by creating instances with underscores in the names and I got always a 404. That's why I am asking you, if you are facing your same issue with an instance having only alphabetic characters in the name.

[jkhsjdhjs]

Hmm, instance names containing underscores work fine for me:

00:59:46 INFO instance/webhook_test Webhook available at: POST https://maubot.my.domain/_matrix/maubot/plugin/webhook_test/send

path: /send
method: POST
room: '!someroom:my.domain'
message: Hello world!
message_format: plaintext
auth_type: Basic
auth_token: abc:123
force_json: false
ignore_empty_messages: false

$ curl -X POST -u abc:123 'https://maubot.my.domain/_matrix/maubot/plugin/webhook_test/send'
$ echo $?
0

Which maubot and aiohttp versions do you have? Also I think it would be cool if you could create a new issue for this.

I tested this using the most recent commits, so you can try building the most recent version by yourself and checking whether this makes a difference. Instructions for this can be found in the readme.

[veso0308]

maubot version: 0.4.2 aiohttp version: 3.9.3 webhook version: 0.2.0 python version: 3.11

I've just noticed that you added some changes since the last version (0.2.0) which already solved several issues I had. Are you planning to publish a new version?

[jkhsjdhjs]

Yes, I was just in the process of publishing a new release when this issue was created. I decided to wait with the release until this one is resolved, but maybe I'll just publish a new release in the next days, since I'm not sure when this will be done.

Do you still have issues with underscores? Your versions are the same I also have.

[veso0308]

Would be great!

Yes, those are the versions I encountered the issues with underscores.

[jkhsjdhjs]

@veso0308 I just published a new release

[veso0308]

@jkhsjdhjs : Many thanks!

[fabiencharrasse]

Hello,

I've got the same problem with latest version (0.3), it return 404 on second instances. Same result with underscore and simple letters

Edit : I think I found the problem. I have two instances of Radarr in my homelab, the first instance is called "radarr" and the second instance is called "radar_animes". I just renamed the second one to just "animes" and it works. It seems that there is a path to explore in this direction.

[jkhsjdhjs]

@fabiencharrasse Thank you for this information! Now I can reproduce the issue. I guess it's an aiohttp bug, but I'll investigate.

[jkhsjdhjs]

The order in which the instances are added seems to be an issue. E.g. if you create radarr_animes first and radarr afterwards, it should also work. So a workaround for now is to add the instances in a different order.

[jkhsjdhjs]

I found the cause and reported it to the maubot repo: https://github.com/maubot/maubot/issues/239