https://stackoverflow.com/q/75574227/1466825

stackoverflow-75574227.md

Hello -

Thanks for using RabbitMQ. I'm a member of the core engineering team.

Carefully look at the first 16 octets in this error log message:

2023-02-26 16:43:12.635470+00:00 [error] <0.1056.0>  operation none caused a connection exception frame_error: "type 3, first 16 octets = <<\"{\\\"payload\\\":{\\\"res\">>: {invalid_frame_end_marker,\n                                                      
99}"
2023-02-26 16:43:15.638860+00:00 [error] <0.1056.0> closing AMQP connection <0.1056.0> (10.244.0.18:60608 -> 10.244.0.21:5672):
2023-02-26 16:43:15.638860+00:00 [error] <0.1056.0> fatal_frame_error

It looks as though your client application tried to publish a message containing a RabbitMQ error log message (invalid_frame_end_marker) BACK to RabbitMQ and then another error happened.

What you should do at this point is share a git repository containing a complete, runnable set of code that I can use to reproduce this issue. Basically I should just clone the repo, and execute a command. Assume there is a 3-node RabbitMQ cluster available, or, provide your complete minikube configuration.

Thanks - Luke

Here's where that error text is generated:

https://github.com/rabbitmq/rabbitmq-server/blob/main/deps/rabbit/src/rabbit_reader.erl#L862-L879

...tracing it back, this is where the function was called from (note the error reason of invalid_frame_end_marker):

https://github.com/rabbitmq/rabbitmq-server/blob/main/deps/rabbit/src/rabbit_reader.erl#L1035-L1042

I'm not sure why we're seeing more than 16 octets of data, however 🤷‍♂️

The RabbitMQ log message itself is JSON formatted. RabbitMQ does not format error messages that way so it must have come from your client application (or the library you're using), which is why I think it may be sending error messages back to the broker.

At any rate, some code to review would be helpful.

Hm I can't imagine how an error message would make its way back into a published message, but stranger things have happened, I guess...

The one place it looks, on first glance at least, that an error message would be sent back is here, passing args from the received connection.close back to connection.close-ok:

https://github.com/lenkan/deno-amqp/blob/master/src/amqp_connection.ts#L82-L92

But then when encoding the frame, this is ignored:

https://github.com/lenkan/deno-amqp/blob/master/src/amqp_codec.ts#L1927

---

Concerning the repository for reproduction. I have stripped out A LOT, but still: I'm not comfortable making this available publicly as it contains somewhat confidential information. Can I invite you to a private repository?

While creating the test case I had no luck reproducing the issue outside of a minikube cluster. The repository itself can be run using devspace (devspace dev) - Is this alright?
This of course requires "devspace": https://www.devspace.sh/

Can I invite you to a private repository?

Of course! @lukebakken is my GH handle.

I've never heard of devspace but I'm willing to get it running if that's the only way to reliably reproduce this issue.

Does your test demonstrate the issue every time?

I sent you an invite for the repository.

Does your test demonstrate the issue every time?

Yes, reliably within 30 seconds or so.

Also please note the README in the repo, it contains information about the setup you might find helpful.

Thanks, I'll get to this when I can find time.

No worries, if I'm lucky I'll find some time to reduce the test case even further until the end of the week.

Hey Luke,

I managed to reduce the sample down further and can now share a public repository. I suggest we disregard the privately shared repository and use this one as basis for discussion.

Public Repository

Ok, got it!

Progress: I've published a branch deno-amqp-only which uses the bare deno-amqp library. It creates the same error, but I believe it was previously caught by my code. Edit: I think I saw the message just below because I didn't expose the error which caused the connection to close. This was just when trying to send the next message on the now closed connection.

error: Uncaught (in promise) BadResource: Bad resource ID
    await this.#conn.write(encodeFrame(frame));
    ^
    at async write (deno:ext/net/01_net.js:33:12)
    at async AmqpSocket.write (https://deno.land/x/[email protected]/src/amqp_socket.ts:147:5)
    at async Promise.all (index 0)
    at async AmqpChannel.publish (https://deno.land/x/[email protected]/src/amqp_channel.ts:323:5)
    at async Promise.all (index 0)

Seems the underlying connection gets closed/dropped for some reason.

RabbitMQ logs show our error:

2023-03-02 16:21:16.063377+00:00 [info] <0.608.0> accepting AMQP connection <0.608.0> (10.244.0.4:48082 -> 10.244.0.5:5672)
2023-03-02 16:21:16.112253+00:00 [info] <0.608.0> connection <0.608.0> (10.244.0.4:48082 -> 10.244.0.5:5672): user 'rabbitmq-debug' authenticated and granted access to vhost '/'
2023-03-02 16:21:26.311125+00:00 [error] <0.608.0> Error on AMQP connection <0.608.0> (10.244.0.4:48082 -> 10.244.0.5:5672, vhost: '/', user: 'rabbitmq-debug', state: running), channel 1:
2023-03-02 16:21:26.311125+00:00 [error] <0.608.0>  operation none caused a connection exception frame_error: "type 3, first 16 octets = <<\"\\\"aaaaaaaaaaaaaaa\">>: {invalid_frame_end_marker,\n                                                    97}"
2023-03-02 16:21:29.313974+00:00 [error] <0.608.0> closing AMQP connection <0.608.0> (10.244.0.4:48082 -> 10.244.0.5:5672):
2023-03-02 16:21:29.313974+00:00 [error] <0.608.0> fatal_frame_error

Cool, that's great.

Starting in on getting my Arch Linux dev box up and running with minikube and other requirements. Feel free to delete or archive the private repo.

Notes:
https://www.atlantic.net/dedicated-server-hosting/how-to-set-up-kubernetes-cluster-using-minikube-on-arch-linux/

Let's continue discussion here - https://github.com/andrinheusser/rabbitmq-frame-errors-debug/issues/1