lemmy
lemmy copied to clipboard
LemmyNet
[Bug]: "Http Signature is expired" when subscribing
Requirements
- [X] Is this a bug report? For questions or discussions use https://lemmy.ml/c/lemmy_support
- [X] Did you check to see if this issue already exists?
- [X] Is this only a single bug? Do not put multiple bugs in one issue.
- [X] Is this a backend issue? Use the lemmy-ui repo for UI / frontend issues.
Summary
I'm attempting to subscribe to a channel on another instance; in the UI, subscribing either doesn't seem to do anything, or the button changes to "subscription pending". On the server though I'm seeing "Http Signature is expired" errors with strange times. I'm running the docker container on my personal server. What I've noticed is that each request is claiming to be expired less than a minute prior to the message arriving. It's not for all messages either, just some, and I haven't been able to figure out a pattern yet.
The time in the docker container matches the time on my sever, with the exception that the docker container is in UTC. I did try installing the tzdata package as well within the container so that it matches my timezone, but that didn't seem to help (might need to be installed when the server starts?).
Steps to Reproduce
- Search for community.
- Click on community link.
- Click subscribe - either the Subscribe button stays on or the Subscription Pending button shows up.
- In the logs you'll get an error after a few seconds stating the Http Signature is expired.
Technical Details
lemmy_1 | 2023-06-23T23:44:06.666088Z INFO HTTP request{http.method=POST http.scheme="http" http.host=lemmy.myinstance.net http.target=/api/v3/community/follow otel.kind="server" request_id=272e3073-97db-44de-87cd-3a912b26ed67}:send:send_lemmy_activity: lemmy_apub::activities: Sending activity https://lemmy.myinstance.net/activities/undo/f29eaf14-6134-4562-88b0-865ef017cbce
lemmy_1 | 2023-06-23T23:44:08.313011Z INFO HTTP request{http.method=POST http.scheme="http" http.host=lemmy.myinstance.net http.target=/api/v3/community/follow otel.kind="server" request_id=765c7a14-eb1b-4510-9d1b-fe4ef686efe9}:send:send_lemmy_activity: lemmy_apub::activities: Sending activity https://lemmy.myinstance.net/activities/follow/4e607623-4783-4aae-90f5-16761e82a2e6
lemmy_1 | 2023-06-23T23:44:49.040296Z WARN Error encountered while processing the incoming HTTP request: lemmy_server::root_span_builder: Other errors which are not explicitly handled
lemmy_1 | 0: lemmy_server::root_span_builder::HTTP request
lemmy_1 | with http.method=POST http.scheme="http" http.host=lemmy.myinstance.net http.target=/inbox otel.kind="server" request_id=d97861f4-ae0e-473b-a2a9-996687bc7c7f
http.status_code=400 otel.status_code="OK"
lemmy_1 | at src/root_span_builder.rs:16
lemmy_1 | LemmyError { message: None, inner: Other errors which are not explicitly handled
lemmy_1 |
lemmy_1 | Caused by:
lemmy_1 | Http Signature is expired, checked Date header, checked at Fri, 23 Jun 2023 23:44:49 GMT, expired at Fri, 23 Jun 2023 23:43:56 GMT, context: SpanTrace [{ target: "lemmy_server::root_span_builder", name: "HTTP request", fields: "\u{1b}[3mhttp.method\u{1b}[0m\u{1b}[2m=\u{1b}[0mPOST \u{1b}[3mhttp.scheme\u{1b}[0m\u{1b}[2m=\u{1b}[0m\"http\" \u{1b}[3mhttp.host\u{1b}[0m\u{1b}[2m=\u{1b}[0mlemmy.myinstance.net \u{1b}[3mhttp.target\u{1b}[0m\u{1b}[2m=\u{1b}[0m/inbox \u{1b}[3motel.kind\u{1b}[0m\u{1b}[2m=\u{1b}[0m\"server\" \u{1b}[3mrequest_id\u{1b}[0m\u{1b}[2m=\u{1b}[0md97861f4-ae0e-473b-a2a9-996687bc7c7f \u{1b}[3mhttp.status_code\u{1b}[0m\u{1b}[2m=\u{1b}[0m400 \u{1b}[3motel.status_code\u{1b}[0m\u{1b}[2m=\u{1b}[0m\"OK\"", file: "src/root_span_builder.rs", line: 16 }] }
lemmy_1 | 2023-06-23T23:44:50.679598Z WARN Error encountered while processing the incoming HTTP request: lemmy_server::root_span_builder: Other errors which are not explicitly handled
lemmy_1 | 0: lemmy_server::root_span_builder::HTTP request
lemmy_1 | with http.method=POST http.scheme="http" http.host=lemmy.myinstance.net http.target=/inbox otel.kind="server" request_id=9087376c-158e-49e3-89bc-b9253be375db
http.status_code=400 otel.status_code="OK"
lemmy_1 | at src/root_span_builder.rs:16
lemmy_1 | LemmyError { message: None, inner: Other errors which are not explicitly handled
lemmy_1 |
lemmy_1 | Caused by:
lemmy_1 | Http Signature is expired, checked Date header, checked at Fri, 23 Jun 2023 23:44:50 GMT, expired at Fri, 23 Jun 2023 23:43:58 GMT, context: SpanTrace [{ target: "lemmy_server::root_span_builder", name: "HTTP request", fields: "\u{1b}[3mhttp.method\u{1b}[0m\u{1b}[2m=\u{1b}[0mPOST \u{1b}[3mhttp.scheme\u{1b}[0m\u{1b}[2m=\u{1b}[0m\"http\" \u{1b}[3mhttp.host\u{1b}[0m\u{1b}[2m=\u{1b}[0mlemmy.myinstance.net \u{1b}[3mhttp.target\u{1b}[0m\u{1b}[2m=\u{1b}[0m/inbox \u{1b}[3motel.kind\u{1b}[0m\u{1b}[2m=\u{1b}[0m\"server\" \u{1b}[3mrequest_id\u{1b}[0m\u{1b}[2m=\u{1b}[0m9087376c-158e-49e3-89bc-b9253be375db \u{1b}[3mhttp.status_code\u{1b}[0m\u{1b}[2m=\u{1b}[0m400 \u{1b}[3motel.status_code\u{1b}[0m\u{1b}[2m=\u{1b}[0m\"OK\"", file: "src/root_span_builder.rs", line: 16 }] }
lemmy_1 | 2023-06-23T23:44:51.109863Z WARN Error encountered while processing the incoming HTTP request: lemmy_server::root_span_builder: Other errors which are not explicitly handled
lemmy_1 | 0: lemmy_server::root_span_builder::HTTP request
lemmy_1 | with http.method=POST http.scheme="http" http.host=lemmy.myinstance.net http.target=/inbox otel.kind="server" request_id=d7f412ce-f162-4ac3-b04d-b3f8c966a408
http.status_code=400 otel.status_code="OK"
lemmy_1 | at src/root_span_builder.rs:16
lemmy_1 | LemmyError { message: None, inner: Other errors which are not explicitly handled
lemmy_1 |
lemmy_1 | Caused by:
lemmy_1 | Http Signature is expired, checked Date header, checked at Fri, 23 Jun 2023 23:44:51 GMT, expired at Fri, 23 Jun 2023 23:43:59 GMT, context: SpanTrace [{ target: "lemmy_server::root_span_builder", name: "HTTP request", fields: "\u{1b}[3mhttp.method\u{1b}[0m\u{1b}[2m=\u{1b}[0mPOST \u{1b}[3mhttp.scheme\u{1b}[0m\u{1b}[2m=\u{1b}[0m\"http\" \u{1b}[3mhttp.host\u{1b}[0m\u{1b}[2m=\u{1b}[0mlemmy.myinstance.net \u{1b}[3mhttp.target\u{1b}[0m\u{1b}[2m=\u{1b}[0m/inbox \u{1b}[3motel.kind\u{1b}[0m\u{1b}[2m=\u{1b}[0m\"server\" \u{1b}[3mrequest_id\u{1b}[0m\u{1b}[2m=\u{1b}[0md7f412ce-f162-4ac3-b04d-b3f8c966a408 \u{1b}[3mhttp.status_code\u{1b}[0m\u{1b}[2m=\u{1b}[0m400 \u{1b}[3motel.status_code\u{1b}[0m\u{1b}[2m=\u{1b}[0m\"OK\"", file: "src/root_span_builder.rs", line: 16 }] }
lemmy_1 | 2023-06-23T23:44:54.188499Z WARN Error encountered while processing the incoming HTTP request: lemmy_server::root_span_builder: duplicate key value violates unique constraint "idx_activity_ap_id"
lemmy_1 | 0: lemmy_apub::insert_activity
lemmy_1 | with ap_id=Url { scheme: "https", cannot_be_a_base: false, username: "", password: None, host: Some(Domain("lemmy.ca")), port: None, path: "/activities/create/0f6b5273-609d-4710-b440-b338e8e2b485", query: None, fragment: None } local=false sensitive=false
lemmy_1 | at crates/apub/src/lib.rs:159
lemmy_1 | 1: lemmy_apub::activities::create_or_update::comment::receive
lemmy_1 | at crates/apub/src/activities/create_or_update/comment.rs:168
lemmy_1 | 2: lemmy_apub::activities::community::announce::receive
lemmy_1 | at crates/apub/src/activities/community/announce.rs:141
lemmy_1 | 3: lemmy_server::root_span_builder::HTTP request
lemmy_1 | with http.method=POST http.scheme="http" http.host=lemmy.myinstance.net http.target=/inbox otel.kind="server" request_id=5b72ea67-7234-4e6d-a814-ad7fb85b63b6
http.status_code=400 otel.status_code="OK"
lemmy_1 | at src/root_span_builder.rs:16
lemmy_1 | LemmyError { message: None, inner: duplicate key value violates unique constraint "idx_activity_ap_id", context: SpanTrace [{ target: "lemmy_apub", name: "insert_activity", fields: "\u{1b}[3map_id\u{1b}[0m\u{1b}[2m=\u{1b}[0mUrl { scheme: \"https\", cannot_be_a_base: false, username: \"\", password: None, host: Some(Domain(\"lemmy.ca\")), port: None, path: \"/activities/create/0f6b5273-609d-4710-b440-b338e8e2b485\", query: None, fragment: None } \u{1b}[3mlocal\u{1b}[0m\u{1b}[2m=\u{1b}[0mfalse \u{1b}[3msensitive\u{1b}[0m\u{1b}[2m=\u{1b}[0mfalse", file: "crates/apub/src/lib.rs", line: 159 }, { target: "lemmy_apub::activities::create_or_update::comment", name: "receive", file: "crates/apub/src/activities/create_or_update/comment.rs", line: 168 }, { target: "lemmy_apub::activities::community::announce", name: "receive", file: "crates/apub/src/activities/community/announce.rs", line: 141 }, { target: "lemmy_server::root_span_builder", name: "HTTP request", fields: "\u{1b}[3mhttp.method\u{1b}[0m\u{1b}[2m=\u{1b}[0mPOST \u{1b}[3mhttp.scheme\u{1b}[0m\u{1b}[2m=\u{1b}[0m\"http\" \u{1b}[3mhttp.host\u{1b}[0m\u{1b}[2m=\u{1b}[0mlemmy.myinstance.net \u{1b}[3mhttp.target\u{1b}[0m\u{1b}[2m=\u{1b}[0m/inbox \u{1b}[3motel.kind\u{1b}[0m\u{1b}[2m=\u{1b}[0m\"server\" \u{1b}[3mrequest_id\u{1b}[0m\u{1b}[2m=\u{1b}[0m5b72ea67-7234-4e6d-a814-ad7fb85b63b6 \u{1b}[3mhttp.status_code\u{1b}[0m\u{1b}[2m=\u{1b}[0m400 \u{1b}[3motel.status_code\u{1b}[0m\u{1b}[2m=\u{1b}[0m\"OK\"", file: "src/root_span_builder.rs", line: 16 }] }
lemmy_1 | 2023-06-23T23:45:00.228439Z INFO lemmy_server::scheduled_tasks: Updating hot ranks for last week...
lemmy_1 | 2023-06-23T23:45:01.957072Z INFO lemmy_server::scheduled_tasks: Done.
Pretty sure the last one is not related, but including it just in case.
Version
0.18.0
Lemmy Instance URL
No response
I don't want to leave you without an answer. What is your server OS? Docker version?
I don't think this is Lemmy code per say, it seems more environment you are instilling on.
Agreed it's probably something in the environment, just not sure what (something not configured right in the docker image maybe?), and I don't know if the docker container showing the time in UTC is a red herring or not.
Host is Ubuntu, docker version is 20.10.21.
Looks like #3314 may be related (which points to https://github.com/LemmyNet/activitypub-federation-rust/issues/46 which deals with signature validation timeouts).
Looks like this is fixed in upstream https://github.com/LemmyNet/activitypub-federation-rust/issues/46. Will this be in the next release? (0.18.1?)
