Exception/termination while getting timeline #500

Closed
opened 2019-01-03 18:03:19 +00:00 by mloftis · 5 comments
Member

visible_for? is getting called with nil,nil on my public timeline and causing a 500 error...(custom metadata in my log output so ignore the file and line)

Jan 03 17:58:25 plz.7td.org mix[30923]: 17:58:25.048 file=lib/pleroma/web/federator/federator.ex line=103 [info] Handling incoming AP activity
Jan 03 17:58:28 plz.7td.org mix[30923]: 17:58:28.686 request_id=2lr6gpeoolum166n200002i1 file=lib/plug/logger.ex line=27 [info] POST /inbox
Jan 03 17:58:28 plz.7td.org mix[30923]: 17:58:28.686 request_id=2lr6gpeoolum166n200002i1 file=lib/pleroma/web/activity_pub/activity_pub_controller.ex line=122 [info] Signature missing or not from author, relayed Create message, fetching object from source
Jan 03 17:58:28 plz.7td.org mix[30923]: 17:58:28.686 request_id=2lr6gpeoolum166n200002i1 file=lib/pleroma/web/activity_pub/activity_pub.ex line=754 [info] Fetching https://mstdn.io/users/SanfordianPhil/statuses/101353934510689149 via AP
Jan 03 17:58:28 plz.7td.org mix[30923]: 17:58:28.686 request_id=2lr6gpeoolum166n200002i1 file=lib/pleroma/web/activity_pub/activity_pub.ex line=787 [info] Fetching https://mstdn.io/users/SanfordianPhil/statuses/101353934510689149 via AP
Jan 03 17:58:54 plz.7td.org mix[30923]: 17:58:54.197 request_id=2lr6gqu9chb9o9m5ts0002j1 file=lib/plug/logger.ex line=27 [info] GET /api/v1/timelines/public
Jan 03 17:58:54 plz.7td.org mix[30923]: 17:58:54.262 request_id=2lr6gqud7qbvuqop0g000023 file=lib/plug/logger.ex line=27 [info] GET /api/v1/timelines/public
Jan 03 17:58:54 plz.7td.org mix[30923]: 17:58:54.314 request_id=2lr6gqu9chb9o9m5ts0002j1 file=lib/phoenix/logger.ex line=35 [info] Converted error :function_clause to 500 response
Jan 03 17:58:54 plz.7td.org mix[30923]: 17:58:54.319 request_id=2lr6gqu9chb9o9m5ts0002j1 file=lib/plug/logger.ex line=34 [info] Sent 500 in 121ms
Jan 03 17:58:54 plz.7td.org mix[30923]: 17:58:54.324 [error] #PID<0.682.0> running Pleroma.Web.Endpoint (cowboy_protocol) terminated
Jan 03 17:58:54 plz.7td.org mix[30923]: Server: plz.7td.org:80 (http)
Jan 03 17:58:54 plz.7td.org mix[30923]: Request: GET /api/v1/timelines/public?limit=40&local=t&max_id=28924
Jan 03 17:58:54 plz.7td.org mix[30923]: ** (exit) an exception was raised:
Jan 03 17:58:54 plz.7td.org mix[30923]:     ** (FunctionClauseError) no function clause matching in Pleroma.User.visible_for?/2
Jan 03 17:58:54 plz.7td.org mix[30923]:         (pleroma) lib/pleroma/user.ex:54: Pleroma.User.visible_for?(nil, nil)
Jan 03 17:58:54 plz.7td.org mix[30923]:         (pleroma) lib/pleroma/web/mastodon_api/views/account_view.ex:20: Pleroma.Web.MastodonAPI.AccountView.render/2
Jan 03 17:58:54 plz.7td.org mix[30923]:         (pleroma) lib/pleroma/web/mastodon_api/views/status_view.ex:129: Pleroma.Web.MastodonAPI.StatusView.render/2
Jan 03 17:58:54 plz.7td.org mix[30923]:         (elixir) lib/enum.ex:1314: Enum."-map/2-lists^map/1-0-"/2
Jan 03 17:58:54 plz.7td.org mix[30923]:         (pleroma) lib/pleroma/web/mastodon_api/views/status_view.ex:39: Pleroma.Web.MastodonAPI.StatusView.render/2
Jan 03 17:58:54 plz.7td.org mix[30923]:         (phoenix) lib/phoenix/view.ex:399: Phoenix.View.render_to_iodata/3
Jan 03 17:58:54 plz.7td.org mix[30923]:         (phoenix) lib/phoenix/controller.ex:729: Phoenix.Controller.__put_render__/5
Jan 03 17:58:54 plz.7td.org mix[30923]: 17:58:54.362 request_id=2lr6gqud7qbvuqop0g000023 file=lib/plug/logger.ex line=34 [info] Sent 200 in 99ms
Jan 03 17:59:26 plz.7td.org mix[30923]: 17:59:26.841 request_id=2lr6gsr32ntk0acg840002m1 file=lib/plug/logger.ex line=27 [info] GET /api/v1/instance
Jan 03 17:59:26 plz.7td.org mix[30923]: 17:59:26.845 request_id=2lr6gsr32ntk0acg840002m1 file=lib/plug/logger.ex line=34 [info] Sent 200 in 4ms
Jan 03 17:59:27 plz.7td.org mix[30923]: 17:59:27.461 request_id=2lr6gss822ct7ieffk0002n1 file=lib/plug/logger.ex line=27 [info] GET /.well-known/nodeinfo
Jan 03 17:59:27 plz.7td.org mix[30923]: 17:59:27.464 request_id=2lr6gss822ct7ieffk0002n1 file=lib/plug/logger.ex line=34 [info] Sent 200 in 2ms
visible_for? is getting called with nil,nil on my public timeline and causing a 500 error...(custom metadata in my log output so ignore the file and line) ``` Jan 03 17:58:25 plz.7td.org mix[30923]: 17:58:25.048 file=lib/pleroma/web/federator/federator.ex line=103 [info] Handling incoming AP activity Jan 03 17:58:28 plz.7td.org mix[30923]: 17:58:28.686 request_id=2lr6gpeoolum166n200002i1 file=lib/plug/logger.ex line=27 [info] POST /inbox Jan 03 17:58:28 plz.7td.org mix[30923]: 17:58:28.686 request_id=2lr6gpeoolum166n200002i1 file=lib/pleroma/web/activity_pub/activity_pub_controller.ex line=122 [info] Signature missing or not from author, relayed Create message, fetching object from source Jan 03 17:58:28 plz.7td.org mix[30923]: 17:58:28.686 request_id=2lr6gpeoolum166n200002i1 file=lib/pleroma/web/activity_pub/activity_pub.ex line=754 [info] Fetching https://mstdn.io/users/SanfordianPhil/statuses/101353934510689149 via AP Jan 03 17:58:28 plz.7td.org mix[30923]: 17:58:28.686 request_id=2lr6gpeoolum166n200002i1 file=lib/pleroma/web/activity_pub/activity_pub.ex line=787 [info] Fetching https://mstdn.io/users/SanfordianPhil/statuses/101353934510689149 via AP Jan 03 17:58:54 plz.7td.org mix[30923]: 17:58:54.197 request_id=2lr6gqu9chb9o9m5ts0002j1 file=lib/plug/logger.ex line=27 [info] GET /api/v1/timelines/public Jan 03 17:58:54 plz.7td.org mix[30923]: 17:58:54.262 request_id=2lr6gqud7qbvuqop0g000023 file=lib/plug/logger.ex line=27 [info] GET /api/v1/timelines/public Jan 03 17:58:54 plz.7td.org mix[30923]: 17:58:54.314 request_id=2lr6gqu9chb9o9m5ts0002j1 file=lib/phoenix/logger.ex line=35 [info] Converted error :function_clause to 500 response Jan 03 17:58:54 plz.7td.org mix[30923]: 17:58:54.319 request_id=2lr6gqu9chb9o9m5ts0002j1 file=lib/plug/logger.ex line=34 [info] Sent 500 in 121ms Jan 03 17:58:54 plz.7td.org mix[30923]: 17:58:54.324 [error] #PID<0.682.0> running Pleroma.Web.Endpoint (cowboy_protocol) terminated Jan 03 17:58:54 plz.7td.org mix[30923]: Server: plz.7td.org:80 (http) Jan 03 17:58:54 plz.7td.org mix[30923]: Request: GET /api/v1/timelines/public?limit=40&local=t&max_id=28924 Jan 03 17:58:54 plz.7td.org mix[30923]: ** (exit) an exception was raised: Jan 03 17:58:54 plz.7td.org mix[30923]: ** (FunctionClauseError) no function clause matching in Pleroma.User.visible_for?/2 Jan 03 17:58:54 plz.7td.org mix[30923]: (pleroma) lib/pleroma/user.ex:54: Pleroma.User.visible_for?(nil, nil) Jan 03 17:58:54 plz.7td.org mix[30923]: (pleroma) lib/pleroma/web/mastodon_api/views/account_view.ex:20: Pleroma.Web.MastodonAPI.AccountView.render/2 Jan 03 17:58:54 plz.7td.org mix[30923]: (pleroma) lib/pleroma/web/mastodon_api/views/status_view.ex:129: Pleroma.Web.MastodonAPI.StatusView.render/2 Jan 03 17:58:54 plz.7td.org mix[30923]: (elixir) lib/enum.ex:1314: Enum."-map/2-lists^map/1-0-"/2 Jan 03 17:58:54 plz.7td.org mix[30923]: (pleroma) lib/pleroma/web/mastodon_api/views/status_view.ex:39: Pleroma.Web.MastodonAPI.StatusView.render/2 Jan 03 17:58:54 plz.7td.org mix[30923]: (phoenix) lib/phoenix/view.ex:399: Phoenix.View.render_to_iodata/3 Jan 03 17:58:54 plz.7td.org mix[30923]: (phoenix) lib/phoenix/controller.ex:729: Phoenix.Controller.__put_render__/5 Jan 03 17:58:54 plz.7td.org mix[30923]: 17:58:54.362 request_id=2lr6gqud7qbvuqop0g000023 file=lib/plug/logger.ex line=34 [info] Sent 200 in 99ms Jan 03 17:59:26 plz.7td.org mix[30923]: 17:59:26.841 request_id=2lr6gsr32ntk0acg840002m1 file=lib/plug/logger.ex line=27 [info] GET /api/v1/instance Jan 03 17:59:26 plz.7td.org mix[30923]: 17:59:26.845 request_id=2lr6gsr32ntk0acg840002m1 file=lib/plug/logger.ex line=34 [info] Sent 200 in 4ms Jan 03 17:59:27 plz.7td.org mix[30923]: 17:59:27.461 request_id=2lr6gss822ct7ieffk0002n1 file=lib/plug/logger.ex line=27 [info] GET /.well-known/nodeinfo Jan 03 17:59:27 plz.7td.org mix[30923]: 17:59:27.464 request_id=2lr6gss822ct7ieffk0002n1 file=lib/plug/logger.ex line=34 [info] Sent 200 in 2ms ```
Member

visible_for?(nil, nil) should be impossible, because in Pleroma IR the activity will always have data->>'actor' populated.

can you run the following SQL queries?

select * from activities where not (data ? 'actor') limit 10;

and

select * from activities where (data ? 'actor') is null limit 10;

I want to verify that your activity graph has fully consistent IR (I suspect it does).

I think the reality is that there is a regression in User.get_cached_by_ap_id().

`visible_for?(nil, nil)` should be impossible, because in Pleroma IR the activity will *always* have `data->>'actor'` populated. can you run the following SQL queries? `select * from activities where not (data ? 'actor') limit 10;` and `select * from activities where (data ? 'actor') is null limit 10;` I want to verify that your activity graph has fully consistent IR (I suspect it does). I think the reality is that there is a regression in `User.get_cached_by_ap_id()`.
Member

User.get_cached_by_ap_id() is failing because User.get_by_ap_id() is failing because of a regression when switching to Tesla.

iex(5)> User.get_follow_requests_query(scs) |> Repo.all()
19:34:30.841 [error] Task #PID<0.475.0> started from Pleroma.Web.Federator terminating
** (FunctionClauseError) no function clause matching in Tesla.Adapter.Hackney.handle/1
    (tesla) lib/tesla/adapter/hackney.ex:81: Tesla.Adapter.Hackney.handle({:ok, {:maybe_redirect, 301, [{"Date", "Thu, 03 Jan 2019 19:34:30 GMT"}, {"Server", "Apache/2.4.25 (Debian)"}, {"Location", "https://social.libreplanetbr.org/main/push/hub"}, {"Content-Length", "344"}, {"Content-Type", "text/html; charset=iso-8859-1"}], {:client, {1546, 544070, 263351}, {:metrics_ng, :metrics_dummy}, :hackney_tcp, 'social.libreplanetbr.org', 80, "social.libreplanetbr.org", [timeout: 10000, recv_timeout: 20000, follow_redirect: true, pool: :default], #Port<0.33>, {:default, #Reference<0.1895928417.2551447560.216194>, {'social.libreplanetbr.org', 80, :hackney_tcp}, #PID<0.502.0>, :hackney_tcp}, #Reference<0.1895928417.2551447560.216194>, true, :hackney_pool, 20000, true, 5, false, 5, nil, nil, {:hparser, :response, 4096, 10, 0, :on_body, "<!DOCTYPE HTML PUBLIC \"-//IETF//DTD HTML 2.0//EN\">\n<html><head>\n<title>301 Moved Permanently</title>\n</head><body>\n<h1>Moved Permanently</h1>\n<p>The document has moved <a href=\"https://social.libreplanetbr.org/main/push/hub\">here</a>.</p>\n<hr>\n<address>Apache/2.4.25 (Debian) Server at social.libreplanetbr.org Port 80</address>\n</body></html>\n", {1, 1}, "", [], 344, "", "", "text/html; charset=iso-8859-1", "https://social.libreplanetbr.org/main/push/hub", :waiting}, {5, {:dict, 5, 16, 16, 8, 80, 48, {[], [], [], [], [], [], [], [], [], [], [], [], ...}, {{[["content-length", {3, "Content-Length", "344"}]], [["location", {2, "Location", "https://social.libreplanetbr.org/main/push/hub"}]], [["date", {0, "Date", "Thu, 03 Jan 2019 19:34:30 GMT"}]], [], [], [["server", {1, ...}]], [], [], [], [], ...}}}}, :connected, :waiting, nil, :normal, false, false, false, :undefined, false, &:hackney_request.send/2, :waiting, nil, 4096, "", [], {1, 1}, 344, nil, nil, "POST", "/main/push/hub", nil}}})
    (tesla) lib/tesla/adapter/hackney.ex:31: Tesla.Adapter.Hackney.call/2
    (pleroma) lib/pleroma/web/websub/websub.ex:229: Pleroma.Web.Websub.request_subscription/3
    (pleroma) lib/pleroma/web/federator/federator.ex:57: Pleroma.Web.Federator.handle/2
    (elixir) lib/task/supervised.ex:89: Task.Supervised.do_apply/2
    (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Function: #Function<9.48575089/0 in Pleroma.Web.Federator.maybe_start_job/2>
    Args: []
`User.get_cached_by_ap_id()` is failing because `User.get_by_ap_id()` is failing because of a regression when switching to Tesla. ``` iex(5)> User.get_follow_requests_query(scs) |> Repo.all() 19:34:30.841 [error] Task #PID<0.475.0> started from Pleroma.Web.Federator terminating ** (FunctionClauseError) no function clause matching in Tesla.Adapter.Hackney.handle/1 (tesla) lib/tesla/adapter/hackney.ex:81: Tesla.Adapter.Hackney.handle({:ok, {:maybe_redirect, 301, [{"Date", "Thu, 03 Jan 2019 19:34:30 GMT"}, {"Server", "Apache/2.4.25 (Debian)"}, {"Location", "https://social.libreplanetbr.org/main/push/hub"}, {"Content-Length", "344"}, {"Content-Type", "text/html; charset=iso-8859-1"}], {:client, {1546, 544070, 263351}, {:metrics_ng, :metrics_dummy}, :hackney_tcp, 'social.libreplanetbr.org', 80, "social.libreplanetbr.org", [timeout: 10000, recv_timeout: 20000, follow_redirect: true, pool: :default], #Port<0.33>, {:default, #Reference<0.1895928417.2551447560.216194>, {'social.libreplanetbr.org', 80, :hackney_tcp}, #PID<0.502.0>, :hackney_tcp}, #Reference<0.1895928417.2551447560.216194>, true, :hackney_pool, 20000, true, 5, false, 5, nil, nil, {:hparser, :response, 4096, 10, 0, :on_body, "<!DOCTYPE HTML PUBLIC \"-//IETF//DTD HTML 2.0//EN\">\n<html><head>\n<title>301 Moved Permanently</title>\n</head><body>\n<h1>Moved Permanently</h1>\n<p>The document has moved <a href=\"https://social.libreplanetbr.org/main/push/hub\">here</a>.</p>\n<hr>\n<address>Apache/2.4.25 (Debian) Server at social.libreplanetbr.org Port 80</address>\n</body></html>\n", {1, 1}, "", [], 344, "", "", "text/html; charset=iso-8859-1", "https://social.libreplanetbr.org/main/push/hub", :waiting}, {5, {:dict, 5, 16, 16, 8, 80, 48, {[], [], [], [], [], [], [], [], [], [], [], [], ...}, {{[["content-length", {3, "Content-Length", "344"}]], [["location", {2, "Location", "https://social.libreplanetbr.org/main/push/hub"}]], [["date", {0, "Date", "Thu, 03 Jan 2019 19:34:30 GMT"}]], [], [], [["server", {1, ...}]], [], [], [], [], ...}}}}, :connected, :waiting, nil, :normal, false, false, false, :undefined, false, &:hackney_request.send/2, :waiting, nil, 4096, "", [], {1, 1}, 344, nil, nil, "POST", "/main/push/hub", nil}}}) (tesla) lib/tesla/adapter/hackney.ex:31: Tesla.Adapter.Hackney.call/2 (pleroma) lib/pleroma/web/websub/websub.ex:229: Pleroma.Web.Websub.request_subscription/3 (pleroma) lib/pleroma/web/federator/federator.ex:57: Pleroma.Web.Federator.handle/2 (elixir) lib/task/supervised.ex:89: Task.Supervised.do_apply/2 (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3 Function: #Function<9.48575089/0 in Pleroma.Web.Federator.maybe_start_job/2> Args: [] ```
Member

Humm, or maybe not.

Humm, or maybe not.
Member

Aha.

These visible_for?(nil, nil) is caused by shitposter.club actor URIs changing.

Working on a mitigation.

Aha. These `visible_for?(nil, nil)` is caused by shitposter.club actor URIs changing. Working on a mitigation.
Member

Moving all SPC-related issues to #501.

Moving all SPC-related issues to #501.
Sign in to join this conversation.
No milestone
No project
No assignees
2 participants
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference
pleroma/pleroma#500
No description provided.