Untitled

Mario Vavti via zotlabs.org | Hubzilla Development

Sat, 12 Jan 2019 04:40:17 -0500

@M. Dent if i have the queueworker addon installed, the Master.php Queue tasks start to eat up all of my cpu until the server shuts down due to overheat. For some reason this does not happen with the legacy worker.

Do you have an idea?

!!Hubzilla Development

show all 85 comments

Mario Vavti

Sat, 12 Jan 2019 07:51:37 -0500

Ok, it appears to not be the addon... Maybe the other changes... Will investigate further...

M. Dent

Sat, 12 Jan 2019 08:18:08 -0500

Lol, that's one way to get my adrenaline pumping first thing in the morning! Lol.

I couldn't even think of why it would be - I know @Max Kostikov is running it. I'm also running it on Zot.Social as well as my other hub and have seen no issues.

Thanks for the "wake up" though, Lol. I needed it this morning!

Mario Vavti

Sat, 12 Jan 2019 08:21:59 -0500

Haha... Sorry for that...

It could be something completely else though. But it started yeterday.

Anyway, don't worry... I'll investigate and hopefully find out what is going on...

M. Dent

Sat, 12 Jan 2019 08:25:00 -0500

Reading more closely, the name of the task isn't necessarily what is going on. It is just the name of the first task it picked up off the queue.

Also, check the Mod_queueworker.php and see if it has a check before the it inserts stuff into the workerq table for duplicate tasks. I added that but don't know if I submitted a patch.

You may be running into the duplicate delivery issues identified recently and fixed in the patches you just applied (multiple simultaneous runs of Queue.php duplicating delivery efforts) - also - the queueworker will try to purge the work queue as quickly as possible on uninstall.

The more I think about it, It actully sounds like you're seeing the behaviors that caused me to write the queueworker in the first place!

M. Dent

Sat, 12 Jan 2019 13:29:20 -0500 last edited: Sat, 12 Jan 2019 13:30:30 -0500

@Mario Vavti - I just looked over the stuff that has been committed. The old queue worker had a procedure for de-duplicating the queue so the following scenario wouldn't happen.

What you were probably experiencing is actually the second problem referenced in MR:1465 - https://framagit.org/hubzilla/core/merge_requests/1465 combined with the lack of work queue dedup removal in the new queueworker.

Basically - Daemon/Queue.php would kick off and start chugging away - cron would run a bit later and Queue.php would kick off again but the previous one hadn't yet finished. The problem is that the new one starts back at the start of the list that the first process is already working on - in the mean time, each delivery kicks off remote pickup attempts.

The fixes of 1465/1466 should mitigate it substantially. I've gone back and forth with whether or not to include dedup in the new version because the problem isn't really the duplicates, the real problem ends up that each run of Queue.php ends up starting pulling the whole list from outq and working through it in order - which is already being done with the first run of Queue.php - so it's all wasted effort. With 1465/1466, Queue.php takes only 1 item at a time and randomizes the order - so if another copy is running, they will in all likelihood be working on different items.

Don't forget also that delivery success means that remotes kick off a "pickup" - which increases traffic and DB activity as well. If I'm not mistaken - that may also kick off your hub to do a pickup from the remote and process new items.

All of these back and forth processes for some reason seem to bypass the load average test (still haven't tracked the reason for that down), and so at one point I had a load average of well over 90 as my system spiraled out of control and io got all bound up. The queueworker (in most cases SHOULD) alleviate that by limiting the number of concurrent processes rather than trying to dynamically determine based on load average.

Anyway - I know that's kind of a convoluted explanation - there are still a few things that could be tightened up, but with the queueworker and the other recent updates (1465/1466) it should keep things from spiraling out of control. I might be persuaded to put the dedup code back in - maybe with some sort of allowance to allow up to X duplicates of certain functions (Queue is a candidate here since once the recent updates are applied, we are fairly certain it isn't going to duplicate work - and if a 2nd copy is kicked off when the 1st copy is still running - it means the outq got really big for some reasons and it may be good to have a second process working on clearing it out).

That's where my head is at this point anyway - other thoughts and suggestions are definitely welcome.

Mario Vavti

Sat, 12 Jan 2019 14:23:02 -0500

I have now lowered deliveries per process from 3 to 1 and raised delivery intervsl from 3 to 5 Let's see if this helps...

Mario Vavti

Sat, 12 Jan 2019 14:38:02 -0500

The thing is there is actually nothing to deliver. Only queue items which are not deliverable but i get 2 or more very long running Master.php Queue processes. The last i have seen was over 2 hours...

Mario Vavti

Sat, 12 Jan 2019 15:22:25 -0500 last edited: Sat, 12 Jan 2019 15:28:25 -0500

I think i got something...

This is what happens after killing all lingering Master.php Queue processes:

When the first process is started via cron it keeps calling queue_deliver()about 3-4 times a second and keeps looping on those.

Jän 12 21:05:32 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:33 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:33 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:33 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:34 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:34 server hz-log[2551]: q_deliver: https://squeet.me/receive/users/somebody
Jän 12 21:05:34 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:34 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:34 server hz-log[2551]: q_deliver: https://pirati.ca/receive/users/somebody
Jän 12 21:05:35 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:35 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:35 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:36 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:36 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:36 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:36 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:37 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:37 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:37 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:38 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:38 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:38 server hz-log[2551]: q_deliver: https://squeet.me/receive/users/somebody
Jän 12 21:05:39 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:39 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:39 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:39 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:40 server hz-log[2551]: q_deliver: https://pirati.ca/receive/users/somebody
Jän 12 21:05:40 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:40 server hz-log[2551]: q_deliver: https://squeet.me/receive/users/somebody
Jän 12 21:05:40 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:41 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:41 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:41 server hz-log[2551]: q_deliver: https://squeet.me/receive/users/somebody
Jän 12 21:05:42 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:42 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:42 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:43 server hz-log[2551]: q_deliver: https://squeet.me/receive/users/somebody
Jän 12 21:05:43 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:43 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:43 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:44 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:44 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:44 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:44 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:45 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:45 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:45 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:46 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:46 server hz-log[2551]: q_deliver: https://pirati.ca/receive/users/somebody
Jän 12 21:05:46 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:46 server hz-log[2551]: q_deliver: https://squeet.me/receive/users/somebody
Jän 12 21:05:47 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:47 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:47 server hz-log[2551]: q_deliver: https://pirati.ca/receive/users/somebody
Jän 12 21:05:48 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:48 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:48 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:48 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:49 server hz-log[2551]: q_deliver: https://pirati.ca/receive/users/somebody
Jän 12 21:05:49 server hz-log[2551]: q_deliver: https://squeet.me/receive/users/somebody
Jän 12 21:05:49 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:49 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:50 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:50 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:50 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:51 server hz-log[2551]: q_deliver: https://pirati.ca/receive/users/somebody
Jän 12 21:05:51 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:51 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:52 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:52 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:52 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:52 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:53 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:53 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:53 server hz-log[2551]: q_deliver: https://squeet.me/receive/users/somebody
Jän 12 21:05:54 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:54 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:54 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:54 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:55 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:55 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:55 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:56 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:56 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:56 server hz-log[2551]: q_deliver: https://pirati.ca/receive/users/somebody
Jän 12 21:05:56 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:57 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:57 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:57 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:58 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:58 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:58 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:05:58 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:59 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:59 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:05:59 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:00 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:00 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:00 server hz-log[2551]: q_deliver: https://squeet.me/receive/users/somebody
Jän 12 21:06:01 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:01 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:01 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:01 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:02 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:02 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:02 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:02 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:03 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:03 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:03 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:03 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:04 server hz-log[2551]: q_deliver: https://squeet.me/receive/users/somebody
Jän 12 21:06:04 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:04 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:04 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:05 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:05 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:05 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:06 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:06 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:06 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:06 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:07 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:07 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:07 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:07 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:08 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:08 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:08 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:09 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:09 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:09 server hz-log[2551]: q_deliver: https://pirati.ca/receive/users/somebody
Jän 12 21:06:09 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:10 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:10 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:10 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:11 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:11 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:11 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:11 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:12 server hz-log[2551]: q_deliver: https://squeet.me/receive/users/somebody
Jän 12 21:06:12 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:12 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:12 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:13 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:13 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:13 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:13 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:14 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:14 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:14 server hz-log[2551]: q_deliver: https://squeet.me/receive/users/somebody
Jän 12 21:06:15 server hz-log[2551]: q_deliver: https://pirati.ca/receive/users/somebody
Jän 12 21:06:15 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:15 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:15 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:16 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:16 server hz-log[2551]: q_deliver: https://squeet.me/receive/users/somebody
Jän 12 21:06:16 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:16 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:17 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:17 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:17 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:17 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:18 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:18 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:18 server hz-log[2551]: q_deliver: https://pirati.ca/receive/users/somebody
Jän 12 21:06:19 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:19 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:19 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:19 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:19 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:20 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:20 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:20 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:21 server hz-log[2551]: q_deliver: https://pirati.ca/receive/users/somebody
Jän 12 21:06:21 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:21 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:21 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:22 server hz-log[2551]: q_deliver: https://pirati.ca/receive/users/somebody
Jän 12 21:06:22 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:22 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:23 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:23 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:23 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:24 server hz-log[2551]: q_deliver: https://squeet.me/receive/users/somebody
Jän 12 21:06:24 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:24 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:24 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:25 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:26 server hz-log[2551]: q_deliver: https://pirati.ca/receive/users/somebody
Jän 12 21:06:26 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:26 server hz-log[2551]: q_deliver: https://squeet.me/receive/users/somebody
Jän 12 21:06:27 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:27 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:27 server hz-log[2551]: q_deliver: https://squeet.me/receive/users/somebody
Jän 12 21:06:27 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:28 server hz-log[2551]: q_deliver: https://pirati.ca/receive/users/somebody
Jän 12 21:06:28 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:28 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:28 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:29 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:06:29 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:06:29 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox

Some Master.php Queue processes start and finish quickly. Eventually another starts and does not stop. The looping speed on queue_deliver() is now doubled about 6 per second.

Jän 12 21:15:27 server hz-log[4315]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:27 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:27 server hz-log[4315]: q_deliver: https://pirati.ca/receive/users/somebody
Jän 12 21:15:28 server hz-log[4315]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:15:28 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:28 server hz-log[4315]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:28 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:28 server hz-log[4315]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:15:28 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:29 server hz-log[4315]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:29 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:29 server hz-log[4315]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:29 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:29 server hz-log[4315]: q_deliver: https://squeet.me/receive/users/somebody
Jän 12 21:15:29 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:30 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:30 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:30 server hz-log[4315]: q_deliver: https://pirati.ca/receive/users/somebody
Jän 12 21:15:30 server hz-log[4315]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:30 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:31 server hz-log[4315]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:15:31 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:31 server hz-log[4315]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:31 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:15:31 server hz-log[4315]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:31 server hz-log[2551]: q_deliver: https://squeet.me/receive/users/somebody
Jän 12 21:15:32 server hz-log[4315]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:32 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:15:32 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:32 server hz-log[4315]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:32 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:32 server hz-log[4315]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:15:32 server hz-log[4315]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:15:32 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:15:33 server hz-log[4315]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:33 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:33 server hz-log[4315]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:33 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:33 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:15:33 server hz-log[4315]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:34 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:34 server hz-log[4315]: q_deliver: https://squeet.me/receive/users/somebody
Jän 12 21:15:34 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:34 server hz-log[4315]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:15:34 server hz-log[4315]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:34 server hz-log[2551]: q_deliver: https://pirati.ca/receive/users/somebody
Jän 12 21:15:34 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox
Jän 12 21:15:34 server hz-log[4315]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:15:35 server hz-log[4315]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:15:35 server hz-log[2551]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:15:35 server hz-log[4315]: q_deliver: https://pleroma.panoptikum.io/users/somebody/inbox
Jän 12 21:15:35 server hz-log[2551]: q_deliver: https://pixelfed.social/users/motedting/inbox

This goes on until after some time a 3rd process starts looping etc...

It is notable that all the destinations in the loop are activitypub contacts which are (probably) not deliverable atm.

Mario Vavti

Sat, 12 Jan 2019 16:05:08 -0500

I think i am getting slightly closer... It seems the outq entry for those is not being updated. They all have priority 0 allthough delivery does not seem to succeed...

Mario Vavti

Sat, 12 Jan 2019 16:17:41 -0500

In fact, as far as i see now outq items will not be updated anymore when failing in pubcrawl_queue_deliver() and $immediate is not set.

Max Kostikov

Sat, 12 Jan 2019 16:43:23 -0500

I got the same behaviour with Zotum few hours ago. Hub went down due the lack of memory.

M. Dent

Sat, 12 Jan 2019 16:57:50 -0500

rrg....

Is this also the case with 1465/66 applied? Or only with the new queueworker?

Max Kostikov

Sat, 12 Jan 2019 17:00:43 -0500 last edited: Sat, 12 Jan 2019 17:04:58 -0500

Yes, with MR 1466 and new queue worker addon. It seems something like that happens right now here on my not so weak VPS (8Gb RAM 4 cores CPU with SSD).
It looks like looping on same set of deliveries.

Mario Vavti

Sat, 12 Jan 2019 17:01:59 -0500

Same applies to diaspora_queue_deliver(). If it did not succeed it is not handled anymore...

Not sure what the right fix would be. For now i just run update_queue_item($outq['outq_hash'],10); in {pubcrawl, diaspora}_queue_deliver() if it can not deliver.

This stops the loop at least...

Mario Vavti

Sat, 12 Jan 2019 17:04:36 -0500

This is at current dev with worker addon enabled.

But i think the bug is in the federation plugins (pubcrawl, diaspora) queue handling. Your changes might have just revealed this more clearly...

M. Dent

Sat, 12 Jan 2019 17:12:59 -0500

I'm almost certain that's true (that's what happened with the memory exhaustion issues as well). But based on the description and the logs, I think it may still be a really good idea to include the deduplication code. It will avoid Queue.php from running multiple times - AND - it will avoid multiple copies of the same message being passed to Daemon/Deliver.php.

Ultimately, it shouldn't be necessary - but I think it's a good idea to include it anyway because there is no reason for multiple identical Deliver tasks to occur. We can add logic later to allow multiple Queue.php tasks if we want to.

I'm not at a place where I can easily submit an MR, but this should help:

Insert:


 $workinfo = ['argc'=>$argc,'argv'=>$argv];

 self::qbegin('workerq');

so that it reads ....


 $r = q("select * from workerq where workerq_data = '%s'",
 dbesc(self::maybejson($workerinfo)));

 if ($r) { logger("Ignoring duplicate workerq task"); return; }

into queueworker.php in between the following two lines of

MasterRelease()

 $workinfo = ['argc'=>$argc,'argv'=>$argv];

 $r = q("select * from workerq where workerq_data = '%s'", dbesc(self::maybejson($workerinfo))); if ($r) { logger("Ignoring duplicate workerq task"); return; } self::qbegin('workerq');

That's the "deduplication" code for queueworker.php

M. Dent

Sat, 12 Jan 2019 17:14:44 -0500

*Sorry - formatting got messed up. Looks like an issue with the code tag.... It appears that all the data is there that you need.

M. Dent

Sat, 12 Jan 2019 17:16:03 -0500

I take that back --- That's ALL messed up!

Give me a minute.

M. Dent

Sat, 12 Jan 2019 17:20:24 -0500

Added a commit to DEV through the editor on FRAMAGIT with the changes I noted above. It's the best I could do right now from where I am - didn't want to commit straight away - but figuring out how to branch and submit an MR through the interface would have taken more time than I have. Sorry.

Anyway - dev now has the dedup code. That should MITIGATE the problem - but we should still probably track it down.

M. Dent

Sat, 12 Jan 2019 17:36:21 -0500

AAAAHHHH... yup. update_queue_item($outq['outq_hash'],10); or something similar is going to be the right solution. I know what's going on.

PREVIOUSLY, Queue.php was gathering the whole list of queue items that need to be delivered and looping through the list. When it got to the end, it stopped. So, if update_queue_item wasn't run, it wasn't a big deal - because it naturally terminated when the list was finished.

NOW, Queue.php only gets one item whose outq_scheduled time is before "now". So if it tries to deliver, then fails, but does NOT run update_queue_item to change the value of outq_scheduled - it will remain in the list of "stuff to do right now." And since we're only selecting one "needs to be delivered" item at a time - and that item remains in the "needs to be delivered" list, well, it just keeps trying. Then, Queue.php kicks off again (probably through Cron), and both copies are trying... then a third... then a fourth.... and eventually, meltdown as it just keeps trying to loop.

So - any queue processor (_queue_deliver) needs to be sure to run update_queue_item() on failure - otherwise it will remain in the "stuff to do RIGHT NOW list".

Mike Macgirvin

Sat, 12 Jan 2019 17:38:37 -0500

Diaspora once used a generic "post" delivery driver (which updated the queue correctly on failure). This no longer worked with DIASPORA_V2 and it seems the queue update step went missing during the switch to a custom 'diaspora' queue driver. The pubcrawl driver was modeled originally on the diaspora driver so it looks as if the same omission propagated.

Note: There are two independent queue libraries (include/queue_fn.php and Zotlabs/Lib/Queue.php). These are mostly the same but the latter was created for Zot6 and I don't plan on resolving the duplication until some time after 4.0. There are a couple of places where the zot protocol versions conflict in a big way and the only sane way forward was to create two completely independent protocol stacks.

M. Dent

Sat, 12 Jan 2019 17:39:00 -0500

And now... to change my clothes, finish a sermon and celebrate the Baptism of our Lord. (My life is so weird)

Max Kostikov

Sun, 13 Jan 2019 06:07:13 -0500 last edited: Sun, 13 Jan 2019 06:07:28 -0500

Current situation with queue workers on Zotum hub

root@zotum:/usr/local/www/zotum.net # uptime
 1:04PM  up 12:06, 1 user, load averages: 9.42, 8.17, 6.15
root@zotum:/usr/local/www/zotum.net # ps auxw | grep 'Zotlabs/Daemon/Master.php Queue' | wc -l
      70

And quantity is growing.

M. Dent

Sun, 13 Jan 2019 06:35:28 -0500

What is in the out table with a outq_scheduled < UTC_TIMESTAMP()?

M. Dent

Sun, 13 Jan 2019 06:35:50 -0500

*outq

M. Dent

Sun, 13 Jan 2019 06:36:50 -0500

Also check what is in the workerq table.

Max Kostikov

Sun, 13 Jan 2019 06:46:11 -0500 last edited: Sun, 13 Jan 2019 06:47:10 -0500

I disabled new queue worker addon for a while and rebooted system so don't sure if this output will be useful.
In outq only diaspora messages, in workerq I have now this:

Click to open/close

root@zotum:~ # mysql -u root -p hubzilla
Enter password:
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1554
Server version: 8.0.12 Source distribution

Copyright (c) 2000, 2018, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

root@localhost [hubzilla]> SELECT * FROM `workerq`;
+------------+------------------+-------------------------+------------------------+-----------------------------+
| workerq_id | workerq_priority | workerq_reservationid   | workerq_processtimeout | workerq_data                |
+------------+------------------+-------------------------+------------------------+-----------------------------+
|          3 |                0 | 5c3b1ee2c72f77.89226713 | 0001-01-01 00:00:00    | {"argc":1,"argv":["Queue"]} |
|        165 |                0 | 5c3b2392c90bf6.89103988 | 0001-01-01 00:00:00    | {"argc":1,"argv":["Queue"]} |
+------------+------------------+-------------------------+------------------------+-----------------------------+
2 rows in set (0.01 sec)

I'll enable new queue worker again to see what will happens.

M. Dent

Sun, 13 Jan 2019 06:57:06 -0500

Before you reenable, make sure workerq is completely empty. Or, disable it, empty it, and reenable it.

M. Dent

Sun, 13 Jan 2019 07:01:28 -0500

Hmm. That time out doesn't look right.

Let me know how it goes.

Unfortunately I probably won't be able to do much for a few hours, but I will look again when my morning tasks are compete (probably about 18:00 UTC)

Max Kostikov

Sun, 13 Jan 2019 07:13:02 -0500

Before you reenable, make sure workerq is completely empty. Or, disable it, empty it, and reenable it.

Looks like table workerq exists only when new queue worker addon is enabled.

Max Kostikov

Sun, 13 Jan 2019 07:24:26 -0500

We have +1 /usr/local/bin/php Zotlabs/Daemon/Master.php Queue process on every crontab envoke.
Currently I have 6. Here is workerq:

Click to open/close

root@localhost [hubzilla]> SELECT * FROM `workerq`;
+------------+------------------+-------------------------+------------------------+-----------------------------+
| workerq_id | workerq_priority | workerq_reservationid   | workerq_processtimeout | workerq_data                |
+------------+------------------+-------------------------+------------------------+-----------------------------+
|          6 |                0 | 5c3b2a9aabbe43.81780707 | 0001-01-01 00:00:00    | {"argc":1,"argv":["Queue"]} |
|        360 |                0 | 5c3b2cf279bd35.03155900 | 0001-01-01 00:00:00    | {"argc":1,"argv":["Queue"]} |
+------------+------------------+-------------------------+------------------------+-----------------------------+
2 rows in set (0.00 sec)

Mario Vavti

Sun, 13 Jan 2019 07:28:22 -0500

@Max Kostikov have you added the mods i mentioned to diaspora and pubcrawl?

Max Kostikov

Sun, 13 Jan 2019 07:34:48 -0500

have you added the mods i mentioned to diaspora and pubcrawl?

No. I don't sure where exactly it should be added.

M. Dent

Sun, 13 Jan 2019 07:38:34 -0500

Did you find out from @Mario Vavti where the update_queue_item statements need to go in the Diaspora and pubcrawl addons?

Also - I will add a mitigation in Queue.php this afternoon so that it eventually terminates no matter what. Right now it (intentionally) loops until there is nothing in outq. But if a delivery process doesn't update outq_scheduled on failure for whatever reason, the outq will never be empty. I think I'll set it so that at most it will try to process 3x the number of items in outq and then terminate. That should mitigate any further problems.

It's adding a new Queue process because the queueworker assumes that if a process was kicked off more than 5 minutes ago but didn't delete itself from the table, it died before completing and so it starts again. In this case, that assumption is wrong. I may also add a "only try up to X times and then, just delete it from the workerq table - if it's important enough, some other monitor will catch it and try to restart it.

Mario Vavti

Sun, 13 Jan 2019 07:51:01 -0500

There is a

if(success) {

}

In the mentioned functions. Just add

else
update_queue_item($outq['outq_hash'],10);

After it.

Max Kostikov

Sun, 13 Jan 2019 08:00:45 -0500 last edited: Sun, 13 Jan 2019 09:08:53 -0500

if(success)

This ones?
https://framagit.org/hubzilla/addons/blob/dev/diaspora/diaspora.php#L1183
https://framagit.org/hubzilla/addons/blob/dev/pubcrawl/pubcrawl.php#L1098

Mario Vavti

Sun, 13 Jan 2019 08:29:55 -0500

Yep.

Sorry... I am on the way on mobile...

Max Kostikov

Sun, 13 Jan 2019 08:54:15 -0500

@M. Dent
With proposed fix in Diaspora and Pubcrawl plugins it works fine now. Thanks, @Mario Vavti!

Max Kostikov

Sun, 13 Jan 2019 13:12:17 -0500 last edited: Sun, 13 Jan 2019 13:35:47 -0500

@M. Dent FYI
MySQL 8 with default sql_mode

2019-01-13T18:06:19Z:LOG_INFO:6ac86dc90d:queue_fn.php:65:remove_queue_item: queue: remove queue item 39b94b4f283cbc18e0b4908433f88af31ab8b4635a3679949feef61739e7174e
2019-01-13T18:06:19Z:LOG_ERR:6ac86dc90d:dba_driver.php:459:db_logger: dba_pdo: ERROR: select *,min(outq_created) as earliest from outq where outq_posturl = 'https://zot.social/post'
SQLSTATE[42000]: Syntax error or access violation: 1140 In aggregated query without GROUP BY, expression #1 of SELECT list contains nonaggregated column 'hubzilla.outq.outq_hash'; this is incompatible with sql_mode=only_full_group_by

M. Dent

Sun, 13 Jan 2019 14:12:33 -0500

Submitted an MR to rework to avoid this.

https://framagit.org/hubzilla/core/merge_requests/1468

Mario Vavti

Sun, 13 Jan 2019 14:16:48 -0500

@M. Dent there is another query of this kind in update_queue_item()

Mario Vavti

Sun, 13 Jan 2019 14:20:49 -0500

Oh, and shouldn't the order by clause be after the where clause and have a direction (asc or desc)?

Max Kostikov

Sun, 13 Jan 2019 14:23:36 -0500 last edited: Sun, 13 Jan 2019 14:24:01 -0500

AFAIK order by without argument provided will be always asc

M. Dent

Sun, 13 Jan 2019 14:32:59 -0500

But yes, it should be after the where clause -- fixing now.. I'll also get the update_queue_item (which I think is where I got it from originally) - maybe not -- can't remember all the different iterations....

Mario Vavti

Sun, 13 Jan 2019 14:34:48 -0500

Here is my MR for the federation addon queue fixes: https://framagit.org/hubzilla/addons/merge_requests/184

@Max Kostikov you will have to revert the custom changes before you can merge this.

Max Kostikov

Sun, 13 Jan 2019 14:42:11 -0500

But yes, it should be after the where clause

That's right, thanks.

Here is my MR for the federation addon queue fixes: https://framagit.org/hubzilla/addons/merge_requests/184

Merged, thank you!

M. Dent

Sun, 13 Jan 2019 14:45:30 -0500

It does default to asc.

Update MR 1468 to include update_queue_item() and fixed the query in zot.php.

Max Kostikov

Sun, 13 Jan 2019 14:49:45 -0500

@M. Dent Merged too, thank you!

phani (Hubzilla)

Tue, 15 Jan 2019 11:39:04 -0500 last edited: Tue, 15 Jan 2019 11:46:27 -0500

being on the latest Git snapshot i just had to kill my VPS and revert to an earlier state, before @M. Dent started to 'fix' queue processing

i don't have the time right now to investigate, but it was queue- and MySQL related that caused my 2 CPUs having fits.

after reverting to

commit dc8da4717f59c850633469d2ece792e04c02b834 (HEAD -> tooHot)
Merge: d32360cb3 7b30fc4b8
Author: Mario Vavti <mario@mariovavti.com>
Date:   Fri Jan 11 10:14:06 2019 +0100

    Merge remote-tracking branch 'mike/master' into dev

things are working normmal again.

PS: this is the last commit i pulled before noticing things got too hot:

https://framagit.org/phani00/core/commit/2e94e4cd67e9eb7dd5e42cbd38cc0c4b96d5af3c

and i do not have the experimental queue worker enabled.

M. Dent

Tue, 15 Jan 2019 11:55:55 -0500

Did you also upgrade your addons? If not, the bugs in the federation addons (referenced above) are most likely the actual cause.

See: https://framagit.org/hubzilla/addons/merge_requests/184

If you DID upgrade the addons, definitely let me know.

I do have a plan for mitigating things in case we want to simply hide the fact that there is broken code elsewhere. But, I'd really rather not merge in something that hides problems. BUT -- if we need to, we need to. I'd much rather fix the real causes - not cover them up.

phani (Hubzilla)

Tue, 15 Jan 2019 12:37:52 -0500

i updated both, hzaddons & core. i did not downgrade addons again, but things seem to work. is only a temporary solution anyway.

Mario Vavti

Tue, 15 Jan 2019 13:42:37 -0500

The fderation addon fixes are in dev now. It should actually work now...

Mario Vavti

Tue, 15 Jan 2019 13:44:29 -0500

If a cronjob started between updating core and addons, that might have caused trouble...

phani (Hubzilla)

Tue, 15 Jan 2019 15:55:00 -0500

that's possible. i'll switch back to current dev and see what happens...

phani (Hubzilla)

Tue, 15 Jan 2019 16:10:04 -0500 last edited: Tue, 15 Jan 2019 16:10:41 -0500

hm, after a few minutes Master.php queue started eating CPU resources again, using one core completely and then i killed it. something is fishy. perhaps i'll reinstall the whole thing again to make sure i didn't mess up something.

M. Dent

Tue, 15 Jan 2019 16:18:35 -0500

What do your queue stats look like in the admin panel?

Max Kostikov

Tue, 15 Jan 2019 17:09:51 -0500

@M. Dent
Is max_queue_workers system variable have effect now?
It has been set to 4 but see 13 queue workers right now in the process list.

M. Dent

Tue, 15 Jan 2019 17:20:48 -0500

No. Not currently. I want to add some admin settings to the UI, and since it was an addon, I didn't want to use the regular global config variables. With the other hubbub and the fact that my research on the "Public Audience" stuff provided a path forward, it fell into the background. (OOPS!). I think the variable is currently set at 16. I'm going to put in an MR for the "never ending queue" problem overnight tonight - I'll add a max-queue-worker setting to the /queueworker page as well.

phani (Hubzilla)

Tue, 15 Jan 2019 18:35:22 -0500

What do your queue stats look like in the admin panel?

18    https://hub.reticu.li/post    830
12    https://hub.phanisvara.com/post    850
12    https://silverhaze.eu/post    810
12    https://hubzilla.stefan-muenz.de/post    820
12    https://node.pc-tiede.de/receive/public    410
12    https://hub.toot.cat/post    10
12    https://hubzilla.socdojo.com/post    1160
12    https://hub.lazyteddy.eu/post    80
12    https://node.memo-village.online/post    710
12    https://libranet.de/receive/public    360
11    https://hubz.lazyteddy.eu/post    10
2    https://pixelfed.social/users/alysonsee/inbox    0
2    https://hub.libranet.de/post    10
1    https://zotadel.net/post    20
1    https://pod.datamol.org/post    20

those have been looking simlarly for a long time now.

i had to kill everything and go back to the earlier stage again. ~half a dozen PHP processes (Master.php Queue) have been running wild again.

phani (Hubzilla)

Tue, 15 Jan 2019 19:27:48 -0500 last edited: Tue, 15 Jan 2019 19:46:50 -0500

btw., i can't see this post on @Mario Vavti 's hub: permission denied. got tired scrolling through my /network stream and wanted to have it in it's own page, but doesn't work. even tho i believe i'm connected to mario.

edit: ah, double-exclamation mark; this post doesn't exist in your stream, only on the dev. forum.

M. Dent

Tue, 15 Jan 2019 21:16:37 -0500

Submitted to dev: https://framagit.org/hubzilla/core/merge_requests/1473

Once applied - make sure DEBUG logging is turned on and keep an eye on your log file. It will report what queue items are not being properly handled and are causing the problem you are encountering. With that info, we should be able to track down where in the codebase the actual problem is.

M. Dent

Tue, 15 Jan 2019 21:50:05 -0500

*Note: MR 1473 also returns to the previous behavior of getting the list of items in the queue and working through it a single time rather than continuing to attempt to process the queue until there are no more entries. This will avoid the endless loop you are experiencing from queue items that are not getting updated.

It does it a bit differently from the original code since the original code was prone to run out of memory. This version is smarter about it - it is still remotely possible on a huge site with a mammoth queue that it could exhaust memory, but it is highly unlikely with even a medium to large site.

phani (Hubzilla)

Wed, 16 Jan 2019 01:51:12 -0500

i applied the patch myself and Master.php is working on the queue again, but so far only one process that's not freaking out. have to watch for a while what happens and will attach the log file if something bad happens again.

phani (Hubzilla)

Wed, 16 Jan 2019 01:55:00 -0500

or wait: now 2 proccesses chugging away at the queue, and i find _a lot_ of these messages in the log:

2019-01-16T06:51:55Z:LOG_INFO:eac1ec60eb:queue_fn.php:303:queue_deliver: deliver: remote zot delivery succeeded to https://hub.toot.cat/post
2019-01-16T06:51:55Z:LOG_INFO:eac1ec60eb:zot.php:1118:zot_process_response: encrypted delivery report could not be decrypted
2019-01-16T06:51:55Z:LOG_INFO:eac1ec60eb:queue_fn.php:303:queue_deliver: deliver: remote zot delivery succeeded to https://hubz.lazyteddy.eu/post
2019-01-16T06:51:55Z:LOG_INFO:eac1ec60eb:zot.php:1118:zot_process_response: encrypted delivery report could not be decrypted
2019-01-16T06:51:56Z:LOG_INFO:eac1ec60eb:queue_fn.php:303:queue_deliver: deliver: remote zot delivery succeeded to https://hub.toot.cat/post
2019-01-16T06:51:56Z:LOG_INFO:eac1ec60eb:zot.php:1118:zot_process_response: encrypted delivery report could not be decrypted
2019-01-16T06:51:56Z:LOG_INFO:eac1ec60eb:queue_fn.php:303:queue_deliver: deliver: remote zot delivery succeeded to https://hub.toot.cat/post
2019-01-16T06:51:56Z:LOG_INFO:eac1ec60eb:zot.php:1118:zot_process_response: encrypted delivery report could not be decrypted
2019-01-16T06:51:57Z:LOG_INFO:eac1ec60eb:queue_fn.php:303:queue_deliver: deliver: remote zot delivery succeeded to https://hub.toot.cat/post
2019-01-16T06:51:57Z:LOG_INFO:eac1ec60eb:zot.php:1118:zot_process_response: encrypted delivery report could not be decrypted

...etc., etc.

phani (Hubzilla)

Wed, 16 Jan 2019 02:06:39 -0500

took ~20 min to see 4 PHP processes using one full CPU again. log file attached.

phani (Hubzilla)

Wed, 16 Jan 2019 02:27:29 -0500

20 min in with the pre-queue-fix snapshot and it's all cool again. the debug-log is 1/10 of the size of the previous one, even though those "...encrypted delivery..." things show up too. those seem to have nothing to do with my problem.

Mario Vavti

Wed, 16 Jan 2019 03:52:03 -0500

It seems like if the delivery report could not be decrypted in zot_process_response(), we return. It appears to me that we do not remove the queue item in this case. Or am i overlooking something?

Mario Vavti

Wed, 16 Jan 2019 03:55:11 -0500

@M. Dent are you sure about https://framagit.org/hubzilla/core/merge_requests/1473?
The previous version seemed more straight forward to me...

Mike Macgirvin

Wed, 16 Jan 2019 04:07:31 -0500

It appears to me that we do not remove the queue item in this case.

As long as the delivery was accepted and processed on the remote site, the queue item should be removed.

M. Dent

Wed, 16 Jan 2019 08:29:15 -0500

If by the "previous version" you mean the original, it had a fatal flaw. This is one of the things that caused this "adventure". On an extremely busy site or in certain error conditions it is possible that the number of queued items will grownsonlarge that memory is exhausted and php dies without doing anything.

Personally, I like the "just keep processing until empty" mode and overall would prefer not to do 1473.

But I don't have a good thought to avoid the problems seen if a delivery subsystem doesn't update the outq properly.

Mario Vavti

Wed, 16 Jan 2019 08:41:48 -0500

With "previous version" i mean the version which is now in dev (without 1473)

But I don't have a good thought to avoid the problems seen if a delivery subsystem doesn't update the outq properly.

I think it is possible to find the remaining issues (like we already did with some) and go on...

M. Dent

Wed, 16 Jan 2019 08:49:42 -0500

That would be my preference.

Mario Vavti

Wed, 16 Jan 2019 09:11:23 -0500

I have created a hotfix which i think will fix @phani (Hubzilla)'s issue:
https://framagit.org/hubzilla/core/merge_requests/1475

M. Dent

Wed, 16 Jan 2019 09:16:03 -0500

Though, piggy backing on something @Max Kostikov said earlier - we may want to investigate PNCTL a bit and figure out if it's ubiquitous enough to use.

I'm also not really clear on why, with the most recent patch, he ends up with multiple queue processes. I can't see any way for that to happen - nor why the "old version" doesn't do it - so I'm clearly missing SOMETHING.

M. Dent

Wed, 16 Jan 2019 10:04:23 -0500

Hotfix merged.

@Mario Vavti - that created conflicts with your previous work on dreport (I saw your notes and was about to merge them). I need to head into the office and can't look at resolving the conflicts until tonight.

phani (Hubzilla)

Wed, 16 Jan 2019 11:32:48 -0500

thanks a lot, for all the attention and the fix. i pulled that now and will wait for half an hour or so, see what happens. if it starts misbehaving again i will reinstall the code. it's possible that i did mess up something that isn't covered by Git while jumping around between different branches while playing with themes and what not. (never changed between 'master' and 'dev' of course; just between issue branches from dev.)

i'm off the keyboard for extended periods now, unlike a whle earlier when i was pretty much glued to it.

phani (Hubzilla)

Wed, 16 Jan 2019 12:03:54 -0500

it's been half an hour now and i didn't catch a glimpse of 'Master.php Queue' in htop

it's active since priority values in my queue are slowly changing, but not multiple instances running in circles, as before. i still don't have the time to look at the code in detail, but it's something i want to do eventually. if weird things are happening with my hub, it's something i'd like to understand.

thanks again @Mario Vavti and @M. Dent, this seems to be going somewhere, even if i don't really understand yet what's happening...

Mario Vavti

Wed, 16 Jan 2019 13:30:27 -0500

Good. Remains the question why the decryption of the delivery report failed...

Mario Vavti

Wed, 16 Jan 2019 14:59:52 -0500

Perhaps because @phani (Hubzilla)'s hub is a re-install and the hubs in the log are using an old public key?

Max Kostikov

Wed, 16 Jan 2019 15:23:18 -0500 last edited: Wed, 16 Jan 2019 15:23:43 -0500

@Mario Vavti
I see the same decryption errors for gerzilla.de only on @Zotum hub

2019-01-16T15:09:17Z:LOG_INFO:3d92e21cd3:queue_fn.php:231:queue_deliver: deliver: dest: https://gerzilla.de/post
2019-01-16T15:09:17Z:LOG_INFO:cc28d3cf33:zot.php:1118:zot_process_response: encrypted delivery report could not be decrypted

Mario Vavti

Wed, 16 Jan 2019 15:25:25 -0500

I have never seen this before... Can you look into it?

Max Kostikov

Wed, 16 Jan 2019 15:41:25 -0500 last edited: Wed, 16 Jan 2019 15:58:52 -0500

@Mario Vavti
Logs says not a lot. I found only this suspicious record near decryption errors:

2019-01-16T15:10:05Z:LOG_INFO:300b4c15e1:zot.php:1173:zot_process_response: zot_process_response: Array
(
    [success] => 1
    [delivery_report] =>
)

It appeared only once.
I'll try to debug this.

Mario Vavti

Wed, 16 Jan 2019 16:17:42 -0500

@M. Dent regarding MR #1472, i resolved the conflict and merged to dev...
Thanks for reviewing!

Max Kostikov

Wed, 16 Jan 2019 16:55:10 -0500

gerzilla.de returns abracadabra instead JSON in delivery report packet:

2019-01-16T21:37:03Z:LOG_INFO:9f82e0560e:queue_fn.php:303:queue_deliver: deliver: remote zot delivery succeeded to https://gerzilla.de/post
2019-01-16T21:37:03Z:LOG_INFO:9f82e0560e:zot.php:1116:zot_process_response: crypto_unencapsulate: ~I V6~BXM-<& M-)^M-}<5b^M^HAG&M-IM-'㙇~PM-x[c^S W M-/^MY[ X ^}R^?@u~Is
^C~L~Z^?u
שƤt^UM-}ģ~^M-7y7 R^S  ;u C.~AM-)~^^W ^AAX ~\M-?)) wM-F| M-y0^R~]r}^@~?d((uM-_M-}~V8AM-8M-Q4 x=]'~U!QAM-"2[M-1M-ka M- ~E Tm~M-9̀~SM-01 M-1M-~  T^TH  ~?f^AM|R]~U*pJ~I
~C~YM-~3~O^C^E¢xM-$M-}SgM-,M-O)'5~K^Y^Y^CM-/;~\'~^dM-!~Lh$ŇM-8#.H^M#M-!M-,18
M->^G^\M-hN<M-*4]uN KI~OVX^X^Y1~?^Z ^E^CM-@M-y@x^\~I^TR+FM-V^] KM-%M-*M-vM-ODM-=~\%M-'}7^X M-x^FwM-|^Xr ^G?M-+L^OZ^]Ĕ/
~X   JPVM-*w~Z' EM-0M-?~@ A^S~KM-{^C p %M-/M-L95 ^G^D~]~SM-Mycm[m @^LM-y"\~^KDM- M-}~R @M-4 ~JM-7M-I~S +M-.^O~]M-/~Qh8 \E^F       jq~[u|ЇO@ R VÛG~_^SN
[^HM-<~Yo^S^X Z :H`M--~O^Xt~R: 2hџ~SM-8M--Z~^^?~BqB~?b^]~[^CV^^^GI^MM-4wqxM-#M-*   ~?lu~H;^HM-d^UM-~~KS}^E/^OM-5UڌM-; R^R&M-&~B^C3M-+}~Xc w M~B^L^]M-+drՈ"/MM-w ~[M-<= ~
M-?U^D^_:M-tM-9h~V~Z M-Hѯ^Q3Kg^BqM-23D̦YM-=M-:s~F~W^H6 ~\# X.M--~F^X~?TM-6^MM-A>^Y M->$E N~W^OM-sM-8 ^U _@~O^O^\|M-WP N 0M-!~QyPWIbM-+~E  ~UM-|| M-!M-: W~@M-y M-^~AKM-`Ŷ

So looks like this is local issue at their side.

phani (Hubzilla)

Wed, 16 Jan 2019 23:03:51 -0500 last edited: Wed, 16 Jan 2019 23:05:41 -0500

i turned on debugging again for an hour, with the "data" option, but couldn't find any of those encryption failure errors anymore -- even though posts from the hubs that happened with are still in the queue. strange...

must be those posts were removed from the queue now and i think it's likely it did have something to do with me reinstalling this hub a while ago. i used to be connected to users from those hubs earlier and now. what else could cause this type of error?