Skip to content

Instantly share code, notes, and snippets.

@lukebakken

lukebakken/stackoverflow-75574227.md

Last active March 2, 2023 18:27
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save lukebakken/621e19cdd117599011c0e905ece59650 to your computer and use it in GitHub Desktop.
Save lukebakken/621e19cdd117599011c0e905ece59650 to your computer and use it in GitHub Desktop.
Download ZIP
Raw
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

@andrinheusser
Copy link

Hey Luke,

Thanks so much for your interest in this issue!

Putting together a test case will take some time as I haven't been able to repoduce this issue in an isolated setup. Will prepare a repo!

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.

I'm not sure about this, aren't the first 16 octets (with escape characters stripped) just: {"payload":{"res ?

@lukebakken
Copy link
Author

lukebakken commented Feb 27, 2023 •
edited

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.

@andrinheusser
Copy link

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/

@lukebakken
Copy link
Author

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?

@andrinheusser
Copy link

andrinheusser commented Mar 1, 2023 •
edited

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.

@lukebakken
Copy link
Author

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

@andrinheusser
Copy link

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

@andrinheusser
Copy link

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

@lukebakken
Copy link
Author

Ok, got it!

@andrinheusser
Copy link

andrinheusser commented Mar 2, 2023 •
edited

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/amqp@v0.23.0/src/amqp_socket.ts:147:5)
    at async Promise.all (index 0)
    at async AmqpChannel.publish (https://deno.land/x/amqp@v0.23.0/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

@lukebakken
Copy link
Author

Cool, that's great.

@lukebakken
Copy link
Author

lukebakken commented Mar 2, 2023 •
edited

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/

@lukebakken
Copy link
Author

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment