Conversation

Notices

1. Embed this notice
   feld (feld@bikeshed.party)'s status on Monday, 19-Aug-2024 05:37:33 JST feld
   Pleroma users: would you like it better if the logs were less noisy and only had useful information like this?
   
   Not pictured are MRF rejects which will show very clear information about which MRF caused a reject of which activity
   • narcolepsy and alcoholism :flag: likes this.
   • Embed this notice
     Haelwenn /элвэн/ :triskell: (lanodan@queer.hacktivis.me)'s status on Monday, 19-Aug-2024 05:37:32 JST Haelwenn /элвэн/ :triskell:

     in reply to

     @feld Makes me wonder how it works for normal ones lol

     Like scrolling up I got [error] Object rejected while fetching https://poa.st/objects/[redacted-uuid] {:fetch, {:error, {:reject, "Filtered by id"}}} but filter-by-id isn't merged yet :D

   • Embed this notice
     feld (feld@bikeshed.party)'s status on Monday, 19-Aug-2024 23:41:34 JST feld

     in reply to

     These new logs/telemetry make Mastodon look even stupider

     14:38:08.468 [info] Inbox: received Delete of https://mastodon.social/users/Gfernades#delete 14:38:08.506 [error] Could not decode featured collection at fetch https://mastodon.social/users/Gfernades/collections/featured, {:error, :not_found} 14:38:08.517 [info] User: created Gfernades@mastodon.social 14:38:08.522 [info] User: updated Gfernades@mastodon.social 14:38:08.522 [info] User: deleted Gfernades@mastodon.social 14:38:08.532 [info] User: updated Gfernades@mastodon.social

     edit: but also this shows that we waste time creating a user for a fucking DELETE 😭 😭 😭 😭

     Haelwenn /элвэн/ :triskell: and Fish of Rage like this.
   • Embed this notice
     Haelwenn /элвэн/ :triskell: (lanodan@queer.hacktivis.me)'s status on Monday, 19-Aug-2024 23:41:39 JST Haelwenn /элвэн/ :triskell:

     in reply to

     • Phantasm
     @feld @phnt Well modern syslog should also be able to keep or drop metadata, at least RFC5424 allows this case.
   • Embed this notice
     feld (feld@bikeshed.party)'s status on Monday, 19-Aug-2024 23:41:40 JST feld

     in reply to

     • Phantasm
     @phnt AIUI The logging is completely unified, so I don't think we can have some subset of logs go one place and another elsewhere, only use the levels. Unless we intercept certain events and do it ourselves, which would be possible by ferrying the log events through the telemetry. I've been thinking about this too, but don't have a certain path forward yet
     
     Leveraging the logger metadata to hold the massive debug error dumps could be a good solution. And if you enable structured logging you can make it spit out JSON and it will then be easily viewable.
     
     We'll see where this goes, but getting better logs and metrics will really help mature the administration story
   • Embed this notice
     Phantasm (phnt@fluffytail.org)'s status on Monday, 19-Aug-2024 23:41:41 JST Phantasm

     in reply to
     @feld If possible and easy to do, I would like split logs. Where syslog gets simplified messages that don't dump the whole error and object for federation issues (like pictured in your post) and only logs internal errors like process termination, timeouts etc. with the full error, to make the difference between files and syslog less confusing. And a log file that gets the full messages for debugging and more thorough monitoring.
     
     It is sort of possible now with different log levels for syslog and console, but I don't know how hard it would be effectively sending two different messages through Elixir's logger.
     
     Also it would be nice to put a status to success messages like {:fetch, :ok} instead of showing them only on errors (as pictured above).
     
     EDIT: Looks like the error could be passed as metadata to the logging system instead of the current way of dumping it to the message. That way it can be easily formatted in the config (omitting the metadata in the syslog format and including it in the file log.)
     
     As for logging to file, I don't know how hard it is in Elixir. There's a module for it in Hex, but I don't know what stance Pleroma has regarding 3rd party modules for stuff like this. Or completely sidestep the issue by logging to console and redirecting stdout to a file in a start script/service.
   • Embed this notice
     feld (feld@bikeshed.party)'s status on Monday, 19-Aug-2024 23:41:42 JST feld

     in reply to
     IMO the Phoenix web logs are 99% useless and should just be disabled by default unless you need to debug something. If you want web logs it's easier to just access the logs of your reverse proxy anyway (nginx, whatever)
   • Embed this notice
     feld (feld@bikeshed.party)'s status on Monday, 19-Aug-2024 23:41:43 JST feld

     in reply to
     as part of this work to start jamming important logs through the Telemetry framework I will be able to build prom_ex modules so we can export more statistics in prometheus format to build Grafana dashboards with
   • Embed this notice
     Haelwenn /элвэн/ :triskell: (lanodan@queer.hacktivis.me)'s status on Tuesday, 20-Aug-2024 02:22:44 JST Haelwenn /элвэн/ :triskell:

     in reply to

     • Phantasm
     @phnt @feld Which is just ugly as fuck, like you'd end up with two log files to read for no reason and console should be for purely runtime like launching it manually.
   • Embed this notice
     Phantasm (phnt@fluffytail.org)'s status on Tuesday, 20-Aug-2024 02:22:45 JST Phantasm

     in reply to

     • Haelwenn /элвэн/ :triskell:

     @lanodan @feld I was thinking something like this:

     $mix run Hello world from Logger asdf=with metadata $tail -n 1 /var/log/everything.log Elixir[31282]: Hello world from Logger config :logger, :console, format: "\n$message\n" config :logger, :ex_syslogger, format: "\n$message $metadata\n" metadata: [:asdf]

     This way the syslog is less noisy without the error dumps and the console log is sent to stdout that can be then redirected to a file in the service declaration. systemd already has a config for that and OpenRC and BSD inits can probably also redirect output with >some_log.txt

     The default Pleroma config.exs already has some metadata configured like that for actors, paths and users.

   • Embed this notice
     Haelwenn /элвэн/ :triskell: (lanodan@queer.hacktivis.me)'s status on Tuesday, 20-Aug-2024 02:27:41 JST Haelwenn /элвэн/ :triskell:

     in reply to

     • Haelwenn /элвэн/ :triskell:
     • Phantasm
     @phnt @feld And to point it precisely: https://www.rfc-editor.org/rfc/rfc5424#section-6.3
   • Embed this notice
     feld (feld@bikeshed.party)'s status on Tuesday, 20-Aug-2024 04:46:05 JST feld

     in reply to

     • Haelwenn /элвэн/ :triskell:
     • Phantasm
     @phnt @lanodan this is essentially what I was thinking about too. You can do it two ways:
     
     Logger.error("message here", reason: error)
     
     or simply
     
     # attach this error metadata to ALL logs emitted by this process
     Logger.metadata([reason: error])
     Logger.error("message here")
     
     
     the nice part about using Logger.metadata is that we could probably write a helper function that will just keep appending errors to a list so we can accumulate them
     Haelwenn /элвэн/ :triskell: likes this.
   • Embed this notice
     Phantasm (phnt@fluffytail.org)'s status on Tuesday, 20-Aug-2024 04:46:06 JST Phantasm

     in reply to

     • Haelwenn /элвэн/ :triskell:

     @lanodan @feld I've looked through the telemetry branch and implementing this would require rewrites, so it's not worth doing it this way anyway.

     On develop it would only require rewriting the calls that dump the full error into something like this: Logger.error("Objected rejected while fetching #{id}", reason: error) and and editing the config.

     The structured data in syslog looks nice, if it is actually supported by Elixir and daemons.

   • Embed this notice
      (mint@ryona.agency)'s status on Friday, 23-Aug-2024 08:21:08 JST 

     in reply to
     @feld Trying to tackle that, first (actually second, the first one was a brainfart when I tried to handle it in transmogrifier) instinct was to handle it in Federator but that would only work for users that already exist in local DB and thus will do nothing. The problem is the very first thing Pleroma does upon receiving any activity from unknown actor is fetching and saving the actor in ReceiverWorker in order to verify its signature, thus I don't see a way to preemtively filter them without tackling shit onto it.
   • Embed this notice
     feld (feld@bikeshed.party)'s status on Friday, 23-Aug-2024 08:21:09 JST feld

     in reply to

     • 
     @mint oh yeah I opened an issue for it. Now that we can easily see it's happening... :sigh: like wtf man 🇸🇬
   • Embed this notice
      (mint@ryona.agency)'s status on Friday, 23-Aug-2024 08:21:10 JST 

     in reply to
     @feld Might be worth preemptively filtering Delete activities coming from accounts that don't exist in local DB.
   • Embed this notice
      (mint@ryona.agency)'s status on Friday, 23-Aug-2024 09:05:25 JST 

     in reply to

     • 
     @feld Something like that. Wonder if there's any further demand for preemptive activity filtering before ever resolving the pubkeys (resulting in actor getting fetched), if so it should be expanded into proper facility.
     https://git.pleroma.social/mint/pleroma/-/commit/1fbe696c011fea497828fb16f0fd73bc1cfeff6e
     Haven't made any tests yet, partially because I'm not sure how to handle them, partially because rebar throws some cryptic error on my workstation when compiling syslogger.
   • Embed this notice
     feld (feld@bikeshed.party)'s status on Friday, 23-Aug-2024 09:14:07 JST feld

     in reply to

     • 
     @mint Try cleaning out ~/.rebar and ~/.mix, I think that was part of the cause of that syslog error
      likes this.
   • Embed this notice
      (mint@ryona.agency)'s status on Friday, 23-Aug-2024 09:15:08 JST 

     in reply to
     @feld I'd prefer not to touch Repo. With this it should just behave like any other canceled job in the queue, except getting canceled much earlier than others. Anyway, analysis tests are also failing for whatever reason.
   • Embed this notice
     feld (feld@bikeshed.party)'s status on Friday, 23-Aug-2024 09:15:09 JST feld

     in reply to

     • 
     @mint I don't know how much work it would be to refactor things but you could wrap a stage in a Repo.Transaction and then you could error and rollback would happen automatically
   • Embed this notice
     :blank: (i@declin.eu)'s status on Friday, 23-Aug-2024 09:20:25 JST :blank:

     in reply to

     • 
     @mint @feld had to downgrade to asdf because upstream fucked something up again, it's like the third time pleroma suffers from this
      likes this.
   • Embed this notice
      (mint@ryona.agency)'s status on Friday, 23-Aug-2024 09:21:17 JST 

     in reply to

     • :blank:
     @i @feld Was it this?
     Screenshot_20240823_024718.png
   • Embed this notice
     :blank: (i@declin.eu)'s status on Friday, 23-Aug-2024 09:26:20 JST :blank:

     in reply to

     • 
     @mint @feld mine was even less specific, complaining about not even finding code to work with, diagnostic didn't show much either
      likes this.
   • Embed this notice
     feld (feld@bikeshed.party)'s status on Friday, 23-Aug-2024 09:30:14 JST feld

     in reply to

     • 
     @mint Actually this could be easier than you think.
     
     https://git.pleroma.social/pleroma/pleroma/-/blob/develop/lib/pleroma/web/federator.ex?ref_type=heads#L105
     
     You just wrap this entire with statement in Pleroma.Repo.transaction() and if it exits with an error none of the database changes are committed.
     
     https://hexdocs.pm/ecto/Ecto.Repo.html#c:transaction/2
      likes this.
   • Embed this notice
      (mint@ryona.agency)'s status on Friday, 23-Aug-2024 09:33:07 JST 

     in reply to
     @feld In case of receiving an activity from unknown user, Federator is called after ReceiverWorker which first has to fetch the actor and its signature. If you put it there, Pleroma would still create the entry for freshly deleted remote user.
   • Embed this notice
      (mint@ryona.agency)'s status on Friday, 23-Aug-2024 09:34:21 JST 

     in reply to

     • 
     @feld And analysis was throwing errors because I put the alias in non-alphabetic order as if it's the worst thing to worry about.
   • Embed this notice
     feld (feld@bikeshed.party)'s status on Friday, 23-Aug-2024 09:35:10 JST feld

     in reply to

     • 
     @mint However, this means that if there are any side effects of the failure we need to keep in the database like tracking reachability of the instance we would need to change that side effect to a process we can message so that database work doesn't get rolled back. This is super easy to do and I'll help with it.
      likes this.
   • Embed this notice
     feld (feld@bikeshed.party)'s status on Friday, 23-Aug-2024 09:38:51 JST feld

     in reply to

     • 
     @mint Ahh that sounds correct, dang. I'll keep thinking about this. There has to be a way we can stop people from being able to fill the database with entries. This is a bug and will be treated as such
      likes this.
   • Embed this notice
      (mint@ryona.agency)'s status on Friday, 23-Aug-2024 09:47:13 JST 

     in reply to
     @feld I'm trying to handle #3311 which bloats the users table thanks to mastodon's Delete behavior. Filling the Oban queue is a different issue as it can be done with any other activity type as long as you send a request with a valid structure of the signature header; that has to be solved with some more advanced ratelimiting than we already have.
   • Embed this notice
      (mint@ryona.agency)'s status on Friday, 23-Aug-2024 09:52:13 JST 

     in reply to

     • 
     @feld Anyway, made an MR. Will do tests later, it's almost 4 AM.
     https://git.pleroma.social/pleroma/pleroma/-/merge_requests/4235
   • Embed this notice
     :blank: (i@declin.eu)'s status on Friday, 23-Aug-2024 17:59:39 JST :blank:

     in reply to

     • 
     • :blank:
     @mint @feld seems like the hotfix for otp27 to keep ancient rebar projects like syslog happy is {plugins, [{pc, "1.15.0"}]} in deps/syslog/rebar.config
     
     https://github.com/processone/ejabberd/issues/4186
      likes this.
   • Embed this notice
     feld (feld@bikeshed.party)'s status on Friday, 23-Aug-2024 17:59:44 JST feld

     in reply to

     • 
     @mint We should be able to capture the domain in the json and ip it's being sent from and have two Hammer rate limit queues or something similar in a Plug filter on the inbox, right? We don't have to do any validation or anything at this step. If either hits a threshold we can start erroring there and come up with a way to exfiltrate useful metadata so people can automate firewalls or something too. Lots of options here
      likes this.
   • Embed this notice
      (mint@ryona.agency)'s status on Friday, 23-Aug-2024 18:02:12 JST 

     in reply to
     @feld Yeah, I'm thinking an additional ratelimiiter plug on inbox endpoints that limits the incoming activities by actor or even a whole domain.
   • Embed this notice
     feld (feld@bikeshed.party)'s status on Saturday, 24-Aug-2024 03:12:12 JST feld

     in reply to

     • 
     @mint this was my approach that I'm testing
     
     https://git.pleroma.social/pleroma/pleroma/-/merge_requests/4236
      likes this.
   • Embed this notice
      (mint@ryona.agency)'s status on Saturday, 24-Aug-2024 03:15:58 JST 

     in reply to
     @feld Returning a boolean makes more sense, yeah. Not sure why you deleted the {:ok, %User{}} assertion from get_or_fetch_by_ap_id that's called after that.
   • Embed this notice
     feld (feld@bikeshed.party)'s status on Saturday, 24-Aug-2024 03:18:43 JST feld

     in reply to

     • 
     @mint it's still essentially the same functionality as we don't use that value but whewwww didn't notice that :doh:
      likes this.
   • Embed this notice
     feld (feld@bikeshed.party)'s status on Saturday, 24-Aug-2024 03:18:44 JST feld

     in reply to

     • 
     @mint oh god that was not intentional haha O_O
      likes this.
   • Embed this notice
      (mint@ryona.agency)'s status on Saturday, 24-Aug-2024 03:22:13 JST 

     in reply to
     @feld I'd add a check for deletes not getting dropped for actors that exist, just in case.
   • Embed this notice
     feld (feld@bikeshed.party)'s status on Saturday, 24-Aug-2024 03:23:36 JST feld

     in reply to

     • 
     @mint I'm gonna move this into the controller and check it at the inbox endpoint, actually. I don't want them to be able to write to the database at all
      likes this.
   • Embed this notice
     feld (feld@bikeshed.party)'s status on Saturday, 24-Aug-2024 04:17:16 JST feld

     in reply to

     • 
     @mint I just cleaned up all my dead accounts with this
     
     DELETE FROM users WHERE note_count = '0' AND actor_type = 'Person' AND NOT nickname = 'internal.fetch';
     
     I'll just be patient now.
     
     
     edit: that's potentially dangerous as e.g., users who only follow or have only done boosts will get caught up in that query, so don't run it on a server you actually care about
      likes this.
   • Embed this notice
     feld (feld@bikeshed.party)'s status on Saturday, 24-Aug-2024 04:17:17 JST feld

     in reply to

     • 
     @mint I think this might be working now because I received:
     
     18:26:07.193 [info] Inbox: received Delete of https://fairy.id/users/artandperception#delete
     
     and that user is not in my database
     
     
     edit: no that's a bad example, you can't fetch their profile if their account is deleted. So I need to watch closer for deletes of activities that cause a user to be created
      likes this.
   • Embed this notice
      (mint@ryona.agency)'s status on Saturday, 24-Aug-2024 04:19:37 JST 

     in reply to
     @feld In case of follows one can just check the follow relationships table. With reports having a bunch of orphaned ones in DB likely won't hurt anything, but you should also skip relays and other service actors.
   • Embed this notice
      (mint@ryona.agency)'s status on Saturday, 24-Aug-2024 04:20:16 JST 

     in reply to

     • 
     @feld I've actually ran a similar query here at one point, nothing exploded.