Error in process_request eval block: Child server process timed out! #23
Comments
|
+1
As far as I can see it is only happening with when it scans emails with a rather large attachments. ( ~6MB pdf ) Ubuntu Server 18.04 |
|
We probably need more info to find out where it is actually hanging. That timeout message should be coming only after the If any of this can't complete before the destination server gives up listening ( After the quoted error about the timeout, do either of you see any other spampd errors, perhaps about closing sockets? What about anything from the Postfix servers (they must log some kind of timeout also?). Now in theory if it times out during the SA checks (quite possible if there are network checks or whatnot), you should be seeing a slightly different timeout message. But the processes are nested and the timeouts are all pretty close to each other, so it's possible SA is timing out but it's not obvious. You could try disabling all SA network checks and see if that helps. If you have external plugins working with SA then maybe disable those as well. If the mail volume is low enough and this happens frequently, enabling debug logging might prove to be useful.
I don't know why it would timeout during the HELO phase, if that's what this is saying. Only thing that comes to mind is if the destination is trying to do reverse lookup or some other kind of long-running task whenever SpamPD connects to it. Remember SpamPD is just a proxy, especially during HELO it's just relaying the server messages, so if either of the servers hangs up then it will look like an SpamPD timeout.
Seems like a good clue that perhaps SA is running slowly (or some other resource contention, disk or whatever). What do you have set for |
|
I don't think this is to do with anything remote because I'm still seeing this while sending between accounts on the same server, for example when I'm also not seeing any correlation with large messages or attachments. The things that are being held up most often (though probably only because our server gets lots of them) are simple notifications, no more than a few kb for the entire message. What I have noticed a correlation with is high message counts - these emails are often outputs from dev environments with lots of monitoring, so message counts get large, and the queue expands - however, as far as I can see the queue only expands because of this hang-up, and I can't think of anything to stop them being delivered more or less instantly since they should be exempted from SA, the server is doing nothing else, and has capacity to burn. One other clue is that whatever has changed, it happened with the 0.40 release - our inbound traffic pattern has not changed, but this problem only started after we migrated to this release. Of course we also had to switch server and OS, so there may be many other factors at work, which doesn't help. |
If it's still routing through SpamPD then it's not being excluded. Once it's "in" SpamPD then it is getting run through SA regardless of any Postfix settings. It should save a lot of resources if you can exclude all those small internal notices from being scanned.
Coming from which version? I don't think anything fundamental has changed in a long time, but might be worth a look. |
|
Our notifications tend to come in waves, leading to long queues. Here are some grabs from munin, all from the same time period. First the mail queue, showing a typical deferred backlog - it's not very big (250 messages), but takes the entire day to clear:
At the same time, the server is doing nothing:
I could understand that helping if the server was maxed out and thrashing, but it's doing very little. This makes me think that it has to be an internal breakage/misconfig, not a resource problem. Any ideas how to prevent passing messages through SA, either altogether (receiving some spam is better than these delays!), or via an allowed source list, given that the postfix tweak doesn't seem to work? We upgraded via the approved route, from 0.30 - apart from this issue it all went very smoothly. |
|
Yea that delay looks like something systematic, not basic resources. Something is throttling delivery, perhaps artificially (eg. greylisting). At this point you really need to narrow down the source of the delay, whether it really has anything to do with SpamPD and/or SA. Turn on I don't know anything about MiaB or what the setup is (except the quick look I had just now... never knew they used SPD). So I can't give you any advice there. I see they use Dovecot LDA on the other side of SpamPD, which I also know nothing about. I also don't see from their diagram how outgoing or internal mail is being scanned (via which path). Seems like there would be instructions somewhere for disabling scanning of internal/outgoing mail in their setup, as that is a pretty common requirement (a waste of time if all internal mail is trusted anyway). Seems like a lot of users... is there a forum or something you could post in? Are there other reports of this? Their GH repo site has too many open issues for me to scan through but a search on "spampd" doesn't bring up anything relevant. @MasterPCUK Are you also using Mail in a Box? |
|
Apologies - I was getting mixed up between my various issues - I should have posted most of what I wrote above in the mailinabox tracker rather than here, but your input is much appreciated! I think I have managed to enable debug logging in spampd, so I'll wait and see if it logs anything interesting. |
|
@mpaperno Yes I am also using Mail In A Box. Also, it does seem to happen with any size of emails, so my assumption that it is only happening with emails over 6mb is false. |
|
OK, I have debug logging that covers this error: Then there's this, which looks odd - spampd spawns some child processes, then kills them? |
|
Interesting... but need more of the first type of log. Would be good to see the whole lifetime of a spampd child (the ID in This only tells us that a child died due to timeout and was respawned (which we already knew). The sending server gives up at this point because the socket was closed when the original child died. Where it shows a new connection after the "Child Preforked" message, I think that's a new connection entirely, which then disconnects a little bit later (for whatever reason). Interesting that this one died apparently during data transfer, vs. the others say during initial greeting. Would perhaps be useful to see both types logged. As for the 2nd chunk... I have no idea. Looks like something is connecting to spampd/destination server and then disconnecting right away. spampd is spawning server/client pairs there (for the relay), not new children. But each child has a limit to how many connections it processes before it is killed and respawned ( |
|
Here are all the log entries relating to that process ID: That last line shows a large time offset, supporting the timeout message. Here are the entries relating to the transaction ID: |
|
👍 The child process log shows a success and then the failure. In this case spampd is waiting for the destination to ack both recipients (code) with a 250 response. You can see it happen in the first transaction, but on the 2nd one for some reason the destination never acks the 2nd recipient. And yea the 2nd part also shows how at the end one recipient got through and the other didn't. This doesn't explain any "timed out while receiving the initial server greeting" errors, but I'm guessing it's something similar. Nor does it explain why the destination (Dovecot?) appears to be hanging, of course. |
I'm having trouble with my mail server (built with https://mailinabox.email v0.4 and using spampd version 2.42) timing out when it gets a large volume of messages (not that much - hundreds per hour), the server has load of < 0.1, 99% idle, but is showing this in logs:
It is sending delay messages like this:
It's notable that this is an internal message, being sent from one user to another within the same mail server, so no external traffic is involved. I found this report which appears to be the same problem from many years ago. I really don't know where to look for what might be causing this, but it appears to be inside spampd. Any ideas?
The text was updated successfully, but these errors were encountered: