Errors on Debian 10 - malformed-request

[konstantine-v]

OS: Debian 10
Kernel: 4.19.0-12-amd64
Go: na
Xmpp-webhook: 0.3
XMPP Client: Prosody v0.11.2

I get this error below as I try to start the systemd service:

Feb 04 15:43:43 box.andrasmedia.org xmpp-webhook[19658]: panic: malformed-request
Feb 04 15:43:43 box.andrasmedia.org xmpp-webhook[19658]: goroutine 1 [running]:
Feb 04 15:43:43 box.andrasmedia.org xmpp-webhook[19658]: main.panicOnErr(...)
Feb 04 15:43:43 box.andrasmedia.org xmpp-webhook[19658]:         /home/thomas/projects/xmpp-webhook/main.go:23
Feb 04 15:43:43 box.andrasmedia.org xmpp-webhook[19658]: main.main()
Feb 04 15:43:43 box.andrasmedia.org xmpp-webhook[19658]:         /home/thomas/projects/xmpp-webhook/main.go:88 +0x6b6

I'm currently trying to run this on the same machine Prosody is running. I've created the bot users, and tested it before running the script.

I have also tried the script on the machine that runs Grafana where the webhook would be coming from and I get the same errors. That machine runs Ubuntu 20.04 LTS.

Should I try building from source rather than using the binary?

[tmsmr]

What do you mean with "script"? The webhook binary or the Systemd service?
Are you able to connect to Prosody using any other Jabber client (There are also CLI-based ones if you are running headless - e.g. https://profanity-im.github.io/) using the same hostname and protocol?
Feel free to debug/compile the webhook on your own, but there is no need IMO - this seems like a configuration/connection issue.

[konstantine-v]

I apologize, I meant to say the xmpp-webhook binary.
I'm able to connect to Prosody using Profanity and Conversations with OMEMO working.
Sometime this week I will try and check the configuration for this and see what else may have gone wrong and update this issue accordingly.

[tmsmr]

Hey @MaterialFuture, please use https://github.com/tmsmr/xmpp-webhook/releases/tag/v0.4.0 for your tests. v0.4.0 contains mellium/xmpp v0.18.0, which should improve the verbosity of errors.

[tmsmr]

Since there is no feedback, i'm closing the issue.

[XeonSquared]

Also having issues with the same error, Debian 10 host, Prosody 11. Here's my Prosody debug log, with the SASL reply removed because I don't know if that's sensitive or not

Sep 20 21:08:55 socket	debug	server.lua: accepted new client connection from 10.0.0.1:47502 to 5222
Sep 20 21:08:55 c2s559946921d90	info	Client connected
Sep 20 21:08:55 c2s559946921d90	debug	Client sent opening <stream:stream> to shadowkat.net
Sep 20 21:08:55 c2s559946921d90	debug	Sending[c2s_unauthed]: <?xml version='1.0'?>
Sep 20 21:08:55 c2s559946921d90	debug	Sending[c2s_unauthed]: <stream:stream xmlns:stream='http://etherx.jabber.org/streams' version='1.0' from='shadowkat.net' xmlns='jabber:client' xml:lang='en' id='60b00319-b0de-49ea-9634-913aaf47f3dd'>
Sep 20 21:08:55 c2s559946921d90	debug	Sent reply <stream:stream> to client
Sep 20 21:08:55 c2s559946921d90	debug	Not offering authentication on insecure connection
Sep 20 21:08:55 c2s559946921d90	debug	Sending[c2s_unauthed]: <stream:features>
Sep 20 21:08:55 runner9UPu5Cc7	debug	creating new coroutine
Sep 20 21:08:55 c2s559946921d90	debug	Received[c2s_unauthed]: <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'>
Sep 20 21:08:55 c2s559946921d90	debug	Sending[c2s_unauthed]: <proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'>
Sep 20 21:08:55 socket	debug	server.lua: we need to do tls, but delaying until send buffer empty
Sep 20 21:08:55 c2s559946921d90	debug	TLS negotiation started for c2s_unauthed...
Sep 20 21:08:55 socket	debug	server.lua: attempting to start tls on tcp{client}: 0x559945a729a8
Sep 20 21:08:55 socket	debug	server.lua: ssl handshake done
Sep 20 21:08:55 c2s559946921d90	debug	Client sent opening <stream:stream> to shadowkat.net
Sep 20 21:08:55 c2s559946921d90	debug	Sending[c2s_unauthed]: <?xml version='1.0'?>
Sep 20 21:08:55 c2s559946921d90	debug	Sending[c2s_unauthed]: <stream:stream xmlns:stream='http://etherx.jabber.org/streams' version='1.0' from='shadowkat.net' xmlns='jabber:client' xml:lang='en' id='e4f4b7a7-bf5d-499a-95df-4c1508354951'>
Sep 20 21:08:55 c2s559946921d90	debug	Sent reply <stream:stream> to client
Sep 20 21:08:55 c2s559946921d90	info	Stream encrypted (TLSv1.3 with TLS_AES_256_GCM_SHA384)
Sep 20 21:08:55 c2s559946921d90	debug	Offering mechanism SCRAM-SHA-1
Sep 20 21:08:55 c2s559946921d90	debug	Offering mechanism PLAIN
Sep 20 21:08:55 c2s559946921d90	debug	Offering mechanism SCRAM-SHA-1-PLUS
Sep 20 21:08:55 c2s559946921d90	debug	Sending[c2s_unauthed]: <stream:features>
Sep 20 21:08:55 c2s559946921d90	debug	Received[c2s_unauthed]: <auth mechanism='SCRAM-SHA-1-PLUS' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Sep 20 21:08:55 sql	debug	SQL transaction begin [function(mod_storage_sql.lua:62)]
Sep 20 21:08:55 sql	debug	SQL transaction success [function(mod_storage_sql.lua:62)]
Sep 20 21:08:55 shadowkat.net:saslauth	debug	sasl reply: <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>SNIP</challenge>
Sep 20 21:08:55 c2s559946921d90	debug	Sending[c2s_unauthed]: <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Sep 20 21:08:55 c2s559946921d90	debug	Received[c2s_unauthed]: <response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Sep 20 21:08:55 shadowkat.net:saslauth	debug	sasl reply: <failure xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><malformed-request/><text>Invalid channel binding value.</text></failure>
Sep 20 21:08:55 c2s559946921d90	debug	Sending[c2s_unauthed]: <failure xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Sep 20 21:08:55 socket	debug	server.lua: client 10.0.0.1:47502 read error: closed
Sep 20 21:08:55 c2s559946921d90	info	Client disconnected: closed
Sep 20 21:08:55 c2s559946921d90	debug	Destroying session for (unknown) ((unknown)@shadowkat.net): closed
Sep 20 21:08:55 socket	debug	server.lua: closed client handler and removed socket from list

[tmsmr]

Would you mind sharing your Prosody-Config? You are the third one who reported that but i were not able to reproduce the issue yet.

EDIT: I suppose you are using v0.4.0?

[XeonSquared]

Not a problem, put it up as a gist:
https://gist.github.com/XeonSquared/86d74b770f10e7b9affe2c92bc2bdacd

And yup, tried 0.4.0 and 0.3 at various points with the same result.

Additionally, here's the output of prosodyctl about

Prosody 0.11.2

# Prosody directories
Data directory:     /var/lib/prosody
Config directory:   /etc/prosody
Source directory:   /usr/lib/prosody
Plugin directories:
  /usr/lib/prosody/modules/
  /usr/local/lib/prosody/modules - prosody-modules rev: dc35d2932d3e
  /usr/lib/prosody/modules/
  

# Lua environment
Lua version:             	Lua 5.2

Lua module search paths:
  /usr/lib/prosody/?.lua
  /usr/local/share/lua/5.2/?.lua
  /usr/local/share/lua/5.2/?/init.lua
  /usr/local/lib/lua/5.2/?.lua
  /usr/local/lib/lua/5.2/?/init.lua
  /usr/share/lua/5.2/?.lua
  /usr/share/lua/5.2/?/init.lua

Lua C module search paths:
  /usr/lib/prosody/?.so
  /usr/local/lib/lua/5.2/?.so
  /usr/lib/x86_64-linux-gnu/lua/5.2/?.so
  /usr/lib/lua/5.2/?.so
  /usr/local/lib/lua/5.2/loadall.so

LuaRocks:        	Not installed

# Lua module versions
lfs:     	LuaFileSystem 1.6.3
libevent:	2.1.8-stable
luaevent:	0.4.6
lxp:     	LuaExpat 1.3.0
socket:  	LuaSocket 3.0-rc1
ssl:     	0.7

[tmsmr]

@XeonSquared Thanks for the infos.

I am able to reproduce the issue now! I'm on it...

[tmsmr]

There was an issue in Prosody 0.11 where it would advertise channel binding when TLS 1.3 is used.
This is causing the authentication problems. The problem was fixed with https://hg.prosody.im/0.11/rev/1bfd238e05ad. Unfortunately this patch never reached Prosody 0.11 in Buster. Since this is no security issue, i doubt the maintainers are willing to to include the Change.
https://github.com/mellium/sasl/commit/14279962860ce30296ea528fc1cca4f439c480b1 adds an error message regarding that issue. I'll update the lib ASAP, hopefully this will be less confusing then...

Possible solutions:

• Disable SASL Mechanisms with SCRAM (https://prosody.im/doc/modules/mod_saslauth)
• Use Prosody from from buster-backports (I verified this works)
• Update mod_saslauth manually
• I could add an flag to xmpp-webhook which disables Mechanisms with SCRAM
• ...