[SERVER-26445] resmoke.py's LoggerPipe threads can stop consuming output from their pipes for long periods Created: 04/Oct/16 Updated: 02/Dec/22 Resolved: 05/Dec/16 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | Testing Infrastructure |
| Affects Version/s: | None |
| Fix Version/s: | 3.2.12, 3.4.1, 3.5.1 |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | Max Hirschhorn | Assignee: | Max Hirschhorn |
| Resolution: | Done | Votes: | 1 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Issue Links: |
|
||||||||||||
| Backwards Compatibility: | Fully Compatible | ||||||||||||
| Backport Completed: | |||||||||||||
| Sprint: | TIG 2016-12-12 | ||||||||||||
| Participants: | |||||||||||||
| Linked BF Score: | 0 | ||||||||||||
| Description |
|
The LoggerPipe thread calls BufferedHandler.flush_with_lock() when the buffer's size exceeds its capacity. In the case of the buildlogger handlers (i.e. the _BaseBuildloggerHandler class), this is a long-running, blocking network operation that prevents the LoggerPipe thread from continuing to consume output from its pipe. While this is consistent with smoke.py's behavior, it is undesirable to have log message queue up in the pipe's buffer because the timestamps used for ordering log messages from different processes are then skewed. Instead, we should offload the sending of all POST requests to logkeeper to the BufferedHandler's AlarmClock thread. This can be done by changing BufferedHandler.flush() to not require holding the lock during the network call and signaling the thread to wake up sooner than its scheduled sleep interval. Doing so will help ensure the LoggerPipe thread is available to read from its pipe and prevent it from becoming blocked when logging to its logging.Logger instance. Steps to reproduceApply the following patch to simulate a delay when calling the flush_with_lock() method on the fixture's logger and run a test through resmoke.py.
OutputObserve that the timestamp assigned by resmoke.py to the message from the output pipe drifts from the timestamp recorded by the mongod.
|
| Comments |
| Comment by Githook User [ 06/Dec/16 ] |
|
Author: {u'username': u'visemet', u'name': u'Max Hirschhorn', u'email': u'max.hirschhorn@mongodb.com'}Message: Changes the BufferedHandler to always delegate the actual flushing of (cherry picked from commit 93989f1023869e8640dcabbe59de00275e61dfa4) |
| Comment by Githook User [ 06/Dec/16 ] |
|
Author: {u'username': u'visemet', u'name': u'Max Hirschhorn', u'email': u'max.hirschhorn@mongodb.com'}Message: Changes the BufferedHandler to always delegate the actual flushing of (cherry picked from commit 93989f1023869e8640dcabbe59de00275e61dfa4) |
| Comment by Githook User [ 05/Dec/16 ] |
|
Author: {u'username': u'visemet', u'name': u'Max Hirschhorn', u'email': u'max.hirschhorn@mongodb.com'}Message: Changes the BufferedHandler to always delegate the actual flushing of |