Repository navigation
Message going AWOL #38
Description
Hi Kevin
Sorry I didn't get back the previous logging ticket yet, just haven't had time. Another issue has come up in the meantime. I am sending batches of 100 messages between actors. For some batches the first message of the batch is sent by the first actor (as confirmed by logs) but is never received by the second actor (again confirmed by logs). All the rest of the messages in the batch are sent and received successfully.
I am pretty stumped right now as I have tried to set the THESPLOG_THRESHOLD env var to "Debug" and "Info" but there is nothing in /tmp/ dir (i.e. thespian.log does not exist). I have written some simplified code to try and reproduce what happens in my main system but so far the simplified code works fine.
Again this is running inside a docker container. My simplified code is below but as I said this runs fine without dropping any messages. Anything you can suggest to help me get more information from the Thespian internal logging for example?
Thanks
Andrew
from thespian.troupe import troupe
from thespian.actors import ActorTypeDispatcher
from thespian.actors import ActorSystem
from thespian.actors import WakeupMessage
import logging
class ActorLogFilter(logging.Filter):
def filter(self, logrecord):
return 'actorAddress' in logrecord.__dict__
class NotActorLogFilter(logging.Filter):
def filter(self, logrecord):
return 'actorAddress' not in logrecord.__dict__
def log_config(log_file_path_1, log_file_path_2):
return {
'version': 1,
'formatters': {
'normal': {'format': '%(levelname)-8s %(message)s'},
'actor': {'format': '%(levelname)-8s %(actorAddress)s => %(message)s'}},
'filters': {'isActorLog': {'()': ActorLogFilter},
'notActorLog': {'()': NotActorLogFilter}},
'handlers': {'h1': {'class': 'logging.FileHandler',
'filename': log_file_path_1,
'formatter': 'normal',
'filters': ['notActorLog'],
'level': logging.INFO},
'h2': {'class': 'logging.FileHandler',
'filename': log_file_path_2,
'formatter': 'actor',
'filters': ['isActorLog'],
'level': logging.INFO}, },
'loggers': {'': {'handlers': ['h1', 'h2'], 'level': logging.DEBUG}}
}
class PrimaryActor(ActorTypeDispatcher):
def receiveMsg_WakeupMessage(self, msg ,sender):
if not hasattr(self, "batch_number"):
self.submission_actor_pool_size = 2
self.batch_number = 0
self.last_secondary_actor_used = -1
self.secondary_actors = self.create_secondary_actor_pool(
SecondaryActor,
self.submission_actor_pool_size
)
next_submission_actor_to_use = self.last_secondary_actor_used + 1
for x in range(0, 100):
message = {"number": x, "batch": self.batch_number}
logging.info("Sending message number {0} {1}".format(self.batch_number, x))
self.send(self.secondary_actors[next_submission_actor_to_use], message)
self.batch_number += 1
if self.batch_number >= 5:
return
if next_submission_actor_to_use > self.submission_actor_pool_size - 1:
next_submission_actor_to_use = -1
self.last_submission_actor_used = next_submission_actor_to_use
self.wakeupAfter(1)
def create_secondary_actor_pool(self, actor_code, pool_size):
submission_actor_pool = []
for x in range(0, pool_size):
submission_actor_pool.append(self.createActor(actor_code))
return submission_actor_pool
@troupe(max_count=4000, idle_count=1)
class SecondaryActor(ActorTypeDispatcher):
def receiveMsg_dict(self, msg, sender):
logging.info("Received message number {0} {1}".format(msg["batch"], msg["number"]))
thespian_system = ActorSystem(
"multiprocTCPBase",
{},
logDefs=log_config("bug_check_1.log", "bug_check_2.log")
)
primary_actor = thespian_system.createActor(PrimaryActor)
thespian_system.tell(primary_actor, WakeupMessage(delayPeriod=1))
Activity
kquick commentedon Feb 5, 2019
Hi @andatt,
I've run your tests locally (directly, and not in a Docker container) and I'm unable to reproduce your issue.
I did need to move the "next_submission_actor_to_use" limit/reset up to between the increment and the "for x" loop, but that was the only change.
For my testing, I ensure that the log files are deleted, and that there is no actor system running. I then run your code above (with the modification described) and check the results:
All outputs indicate 100 messages were logged in each direction for each batch.
Can you confirm that you are still seeing the lost messages using the process I describe here?
andatt commentedon Feb 6, 2019
Hi Kevin
I think I have got to the bottom of the problem. The message is sent and received but its not entered in the log (thereby appearing the message never arrives) because the receiveMsg_WakeupMessage method never returns.
This is can be caused in 2 different ways:
a POST call inside this method (in the real code not the example above). This POST successfully connects to an API and thus not does not trigger a timeout. However the API subsequently gets overloaded and hangs leaving numerous actors waiting for a response. Thus the receiveMsg method does not return and no log entries are made. This makes it appear as if the secondary actor never received the message when in fact it did - it is just the logging has not recorded this.
The other cause is where there are so many messages sent to the actor system in a short period of time that the Thespian queue limit of 950 is reached. At this point the associated actor hangs and again no logging entries are made. The logging ceases at a point far before the actual failure occurs due to reasons similar to 1) I believe.
So I have resolved the issue with the API such that it is now able to handle load commensurate with that output by the actor system.
That leaves me with three questions:
What can be done to prevent the queue building up to the critical 950 level? In the example code above I am trying to spread the load across different actors but this doesnt seem to make as much difference as I thought it would. Is the queue a single 'admin' queue not related to a single actor?
When the queue does build to over 950 why is the system not able to recover from that? It hangs without recovery even if nothing more is added to the queue. Is there anything that can be done to mitigate this?
Is there anyway (e.g. some parameter) that will cause log lines to be written as they are invoked? Because the current way of flushing and writing them at some stage well after the log line takes places is very confusing when something goes wrong. It gives the appearance of something in Thespian being the cause when in actual fact this is not the case as is demonstrated by the API issue above.
Thanks
Andrew
kquick commentedon Feb 7, 2019
Hi @andatt,
That's good news: I'm glad you found the problem!
When an actor sends a message, the
self.send()places it onto an outbound queue that is maintained as part of theActorclass internals. Once thereceiveMessage()returns, the Actor will process sends on that queue, as well as wait for other receives. The Actor is not multithreaded, so no actual message sending or receiving is done while it is in thereceiveMessage()method, thus your blocking POST call was preventing any other activity.The logging is done by sending a log message to the logging Actor, which is placed on that same outbound queue, and therefore the POST was blocking the send of the logging message as well. Logging is done this way for two primary reasons: (1) the python logging library does not provide synchronization to the log outputs, so if each actor was writing directly to the log file they would overwrite each other's messages and some would be lost that way, and (2) because any logging from Actors on other systems will then be collected by the central system and logged together.
There are also some reasons why the Actor is single-threaded: it generally makes things simpler operationally, and it also allows for back-propagation of pressure to prevent overloads. This works in conjunction with the outbound queueing threshold of 950 to prevent a runaway actor from overloading the entire system. Slow running Actors (e.g those doing blocking POST calls) will process their inbound sockets much more slowly, so other Actors trying to send them messages will build up those messages on their internal outbound queue. This pressure will propagate backward throughout the system, and the best way to alleviate this is to use more actors in parallel (e.g. with the troupe).
Once the 950 outbound message threshold is reached, that Actor will block on a
send()call, although it will still process the outbound queue as well as receive messages. This effectively prevents the Actor from generating any new send() messages until some of the existing messages have been sent, although it also prevents the Actor from responding to any of the received messages until the outbound queue drops below the threshold, whereupon thesend()call completes and thereceiveMessagecontinues. The overall system should still be able to continue once this point has been reached but it will be much more restricted by the thresholds until messages have been processed, and it is possible that a "deadlock" could occur (two actors sending messages to each other and over the threshold).It sounds like you were able to adjust the POST target responsiveness to help, and I would recommend increasing the actor count as another way to help with this problem.
Let me know if this helps or if you would like more information.
Regards,
Kevin
andatt commentedon Feb 7, 2019
Thanks very much for the detailed response Kevin. It makes sense but I think I am seeing different behaviour with regard to the draining of the queue. Using the example code I posted above I made the following changes:
I ran this code and then waited 40 minutes monitoring the log files and processes. Both the actor logs and thepsian.log are incomplete. The consistent actor log entries end at 345, after which there are only 3 more entries (366- 368). Thespian log seems to be cleared during the processing but you can see here the before and after clearing:
Pre clear the log does not seem to contain all the fail messages I would expect given the missing entries on the actor log.
A ps aux during the first 10 minutes reveals a peak number of actors of 204. This diminishes for the first 10 minutes down to 100. After 40 minutes this still remains at 100. I would expect this to return to 1 given the idle_count param.
The above gives me the impression the system or actors are hanging and not exiting gracefully but maybe that's not right?
kquick commentedon Feb 8, 2019
Hi @andatt,
I believe the issues you are encountering are due to running into system limits, which are causing abnormal behavior that Thespian cannot control or readily react to. In particular, you have your @troupe max_count set to 4000, which would allow up to 4000 processes to be created. Unless your kernel configuration and process limits allow resource levels this high, the kernel will start aborting connection attempts and process creation, which is not something that is easily adapted to. You may want to check
ulimit -ufor the number of user processes you are allowed andulimit -nfor the number of file descriptors (the largest consumer will probably be the troupe leader, which will need 1-2 file descriptors for each troupe member), and alsoulimit -mto ensure it is allowing enough space for these to run. These values might be more restricted in a Docker environment as well.On my system, not using Docker, I am able to run the altered tests you describe with troupe max_count values of up to 300; beyond that I start running into configured limits and I start seeing the aberrant behavior you reported above. As long as I stay below 300 the program above can handle the 500 messages just fine (taking roughly
5 * ((500 / max_count) + 1)seconds to complete).-Kevin
kquick commentedon Feb 8, 2019
Hi @andatt,
I did do some additional work with your example and identified some corner cases that weren't being handled as well as they could be. I've made some changes that seem to improve the original configuration you described (4000 max_jobs); I need to run it through the rest of the test suite and if it still looks good I'll have an update for you to test out sometime later today or tomorrow.
-Kevin
andatt commentedon Feb 9, 2019
Thanks Kevin that's brilliant!
ulimit -uoutputs 63109ulimit -noutputs 1024So I just have one more question:
I changed the for loop so its now got 1000 messages. I also reduce the troupe decorator to 500 as I believe that should be within the limits you describe given the ulimit output above.
When I run the system seems to lock in a similar fashion to the earlier experiment. The actor log indicates a hang at received message 368. There only appear to be 6 actors processes spawned. I checked thespian.log and saw the queue < 950 warning. I would expect to see this but then I would expect to see the queue drain as the actors process and finish their work.
So then I waited 20 minutes and everything was still locked the same - the queue has not drained and no further work was done. There were a couple more messages in thepsian.log
but the actor log showed no movement from 368. What could be causing this? It seems like a burst of messages can cause a hang - is there anything we can do to mitigate this because the troupe decorator doesn't seem to prevent this.
Thanks
Andrew
kquick commentedon Feb 9, 2019
Hi @andatt,
I just released version 3.9.6 (with corresponding github source updates) that will hopefully help with the above. Can you please try this new version and let me know what issues remain?
Thanks,
Kevin
kquick commentedon Feb 11, 2019
I made a few more updates, now version 3.9.7 is available.
andatt commentedon Feb 11, 2019
Hi Kevin
Thanks for doing that! I just tested with 1000 messages again and it works! However when I increased the number to 5000 I get a stack overflow:
I ran this twice and got the same error both times at around 3000 messages. Any ideas?
kquick commentedon Feb 12, 2019
Hi @andatt,
Thank you for confirming the previous fix and for this additional report. I can reproduce this and it looks like there are actually a couple of things involved. I won't have a fix ready for you today, but hopefully by tomorrow.
Regards,
Kevin
kquick commentedon Feb 13, 2019
@andatt, there is a new commit on master (36a60e1) that should help with the above. I am still looking into other issues this test raised, and I have not yet passed the new commit through the full test regimen, but this commit should help move things in a positive direction for you and I'll have more updates in the next day or so.
-Kevin
andatt commentedon Feb 13, 2019
Hi Kevin
Thanks for all you efforts doing this! I just tested again with the new commit. This time there is no stackoveflow which is great. It now gets to 3411 messages received. At this point the number of actors drops down to zero and nothing further is processed. The thespian.log is:
This maybe related to the ongoing issues you are already looking into though so I will await your further updates.
Thanks again!
Andrew
andatt commentedon Feb 13, 2019
One additional piece of information which I forgot to mention before is that I have tested originally (pre fixes) up to 20,000 messages successfully. However the batch size in this case was only 30 (i.e. each for loop was only 30 messages, then there was a 1 seconds pause, then another 30 messages etc). So it seems to be the burst nature of messages being input that causes the issues.
kquick commentedon Feb 13, 2019
Hi @andatt,
The ~3000 messages processed is not specifically what I am still working on: that is a side effect of your configuration, although it also relates to an internal Thespian timer that should be exposed as a new feature.
The fundamental limit is on the number of processes and/or file descriptors that limit the troupe size to less than the 4000 allowed by the code specification (most probably the latter). This prevents the troupe leader from creating the full 4000 processes, so it can only distribute the work to the available processes. However, there is a 5 second delay in each worker for each message, so this limits the overall throughput of processing the messages. There is an internal Thespian timeout set for all attempts to send a message, which comprise the majority of the log messages you noted above. This is intended as a failsafe to handle conditions where an Actor has not gracefully exited but is simply no longer there or no longer responding. When the timeout occurs, the message is returned to the sender in a PoisonPacket wrapper; the sender can handle these however it deems appropriate, and in your implementation the PrimaryActor doesn't provide handling for these at all so they are simply dropped.
Thus, the ~3000 messages is the number that can be sent under the available system resource limits within the timeout period for those messages. I believe that the original configuration was handling 20,000 messages because (1) you did not have the 5 second delay per message, and (2) the PrimaryActor is using a 1 second period between sending batches, as well as sending batches to different troupes, so this staggered the submission of the messages enough that the running troupes were able to process them before the send timeout.
I am considering making the Thespian internal timeout an optional argument to the
self.send(), although I'm not sure if that would end up causing more confusion and failure scenarios for people. The default currently is a 5 minute time period.andatt commentedon Feb 18, 2019
Hi Kevin
Sorry for the delay coming back to you. I wanted to take some time to think about what you said and try a couple of things. Just to clarify - on the previous failing example I was using a troupe decorator with 500 count so this should be within the limits obtained from running the ulimit commands.
I think I understand what you are saying and it makes sense that we will come up against the system limits. But I am still not sure why the logging seems incomplete in thespian.log when these limits are reached. So I would expect to see:
number of failure messages in thespian.log = (5000 - number of successful messages)
5000 being the total messages sent in the initial batch.
Also the PoisonPackets that are recorded. I can find no evidence that they are returned to the Primary actor. I tried defining methods receiveMessage_PoisonMessage, receiveMessage_PoisonPacket and writing to log inside these methods. Nothing was written. To be even more sure I switched the actor to standard Actor class and logged every message coming into receiveMessage. The only message received is the initial wakeup message.
Any idea whats going on here?
Thanks
Andrew
kquick commentedon Feb 20, 2019
Hi @andatt ,
I believe the PoisonPackets were actually directed at the troupe leader rather than the Primary Actor in your scenario.
It took me a little longer than planned, but I appreciate your raising this scenario and continued questioning of the behavior, and I've pushed a number of changes that should resolve the issues you are seeing, and also improve the handling of these issues in the troupe as well as the overall troupe performance. These changes have been pushed to master, and I will probably generate a new release within a couple of days, but I would appreciate it if you have time to try the latest code locally to see if this works better in your situation as well.
Regards,
Kevin
kquick commentedon Feb 26, 2019
Hi @andrewsenseon,
That's good news, I'm glad everything is working well. I'll probably be generating a new release in the next day or so.
Regarding your questions:
At the moment, it's not really possible to flush the log messages because all of the underlying socket transmit functionality is intentionally asynchronous. I understand the use case you are describing, and I have a couple of longer-term thoughts, but at the moment there's nothing direct. One alternative would be that your actor could directly write to its own logging file with synchronous flushing; I understand that this is clearly only a development solution and not as useful in a production environment.
First let me note that the thespian.log is intended for internal thespian debugging; hopefully you should never need to refer to it as a thespian user. That said, there are some environment variables you can use to control this logfile (see thespian.system.utilis for details, but THESPLOG_FILE_MAXSIZE is the variable to control the size of the thesplog file). The default setting for this is fairly small on the assumption that a normal configuration should never need to refer to it and it should therefore have minimal impact, and that the most interesting conditions tend to occur near the end of the file.
Regards,
Kevin
andatt commentedon Mar 4, 2019
Hi Kevin
Any news on the release? If it's delayed I will just go ahead and use the latest version of master branch in my requirements.txt.
Thanks
Andrew
kquick commentedon Mar 5, 2019
I apologize, I did get distracted on a separate feature. I will get this released by tomorrow, Andrew, and thanks for your patience.
Regards,
Kevin
kquick commentedon Mar 6, 2019
Thespian 3.9.8 has been released, thanks again @andatt!
I'm closing this issue to tie it the fixes that have been made relative to the release. I know this doesn't resolve all of your observed problems; let's open another issue to track your remaining problems, and feel free to refer back to this issue as needed.