[CDRIVER-3978] Add entropy for OpenSSL RAND_bytes to avoid duplicate sequences for same PID Created: 16/Apr/21 Updated: 28/Oct/23 Resolved: 06/Jul/21 |
|
| Status: | Closed |
| Project: | C Driver |
| Component/s: | libmongoc |
| Affects Version/s: | None |
| Fix Version/s: | 1.17.7 |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | Евгений Голендухин | Assignee: | Jeremy Mikola |
| Resolution: | Fixed | Votes: | 1 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Attachments: |
|
||||||||||||
| Issue Links: |
|
||||||||||||
| Backwards Compatibility: | Fully Compatible | ||||||||||||
| Description |
| Comments |
| Comment by Githook User [ 13/Jul/21 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {'name': 'Jeremy Mikola', 'email': 'jmikola@gmail.com', 'username': 'jmikola'}Message: | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Githook User [ 06/Jul/21 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {'name': 'Jeremy Mikola', 'email': 'jmikola@gmail.com', 'username': 'jmikola'}Message: | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Githook User [ 06/Jul/21 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {'name': 'Jeremy Mikola', 'email': 'jmikola@gmail.com', 'username': 'jmikola'}Message: | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Евгений Голендухин [ 06/Jul/21 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hello, Jeremy We tried applying your patch and it worked as intended. Thank you. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Jeremy Mikola [ 02/Jul/21 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
CR: https://github.com/mongodb/mongo-c-driver/pull/815 yeti.moscow@gmail.com: If you're still following this issue, would it be possible for you to test out the patch? It's a small change to mongoc-rand-openssl.c:
The easiest way to do this is likely building the PHP driver from source which pulls in libmongoc as a submodule. You can manually patch mongoc-rand-openssl.c after initializing the libmongoc submodule and before compiling. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Jeremy Mikola [ 04/May/21 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
yeti.moscow@gmail.com: Thanks. 1.0.2k would definitely be affected. We're going to explore a solution in libmongoc to detect PID changes and add entropy as needed for older OpenSSL versions. In the meantime, I'd suggest disabling retryable writes for your script to work around the issue. edwin.zhou: I opened | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Евгений Голендухин [ 03/May/21 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi Jeremy, Edwin Here's the OpenSSl info for the CentOS machine
| ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Jeremy Mikola [ 03/May/21 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
I don't think this is a case of the server re-using a stale lsid. Rather, the OP's issue looks to be caused by RAND_bytes, which is used by libmongoc to generate lsid UUIDs, returning the same value when called at different times and by different processes that happen to share the same PID. This is related to the OP's parent script spawning enough child processes such that the PID counter rolls over, as seen in php_retryWrites_none.log:
I'm fairly certain that you could reproduce the same issue in Python by sending the same commands from my previous PHP script. I think this is entirely caused by duplicate lsid and txnNumber combinations.
My example script refers to five documents (AAA... EEE). I can explain what happens to each:
I think the server is correct in not applying the duplicate writes, but the insert responses leave something to be desired. I didn't test what would happen if I used update or delete instead of insert in this case. I expect the responses would be similarly inaccurate (e.g. including no-ops in the reported totals for updates or deletes). It'd also be interesting to consider what would happen if first command to use the lsid and txnNumber was an insert and the findAndModify was the duplicate. In that case, what would the server return as the "found" document? I think there's definitely room for improvement on the server-side, to ensure that inaccurate results are never reported. In my example script, even having the DDD/EEE insert report n:1 instead of n:2 would be an improvement, and allow the user to infer that something is amiss (expected two insertions and only one occurred). Other ideas:
Known fork-safety issues with OpenSSL's PRNGI did some additional digging on RAND_bytes producing duplicate values and it turned up PHP Bug #71915: openssl_random_pseudo_bytes is not fork-safe. That bug report links to Random fork-safety in the OpenSSL wiki, which I think explains the crux of the issue:
The aforementioned PHP bug was fixed in 0e2447c by adding the current time to entropy before calling RAND_bytes. The patch was later revised to only apply to older versions of OpenSSL 68c3d09. I should point out that the PHP patch has no relation to the PHP driver issue, since we're not using PHP's OpenSSL extension and instead interacting with OpenSSL's APIs directly through libmongoc. That said, the patch above may serve as a good basis for a potential fix for this issue in libmongoc. yeti.moscow@gmail.com: If you can tell us exactly what version of OpenSSL was being utilized in the original test, that should help us confirm that you were hitting the issue described in Random fork-safety. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Edwin Zhou [ 03/May/21 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
yeti.moscow@gmail.com, we highly appreciate your help and prompt responses in this investigation. Thank you! Thanks for your detailed investigation so far. Everything seems to be working as expected. Based on your last comment and the investigation above, I agree that it sounds like this behavior is stemming from an identical lsid being used, but do you think the same identifier is being generated again or do you think we're reusing a stale lsid? Given your last PHP script, in particular the second findAndModify which uses the same lsid and txnNumber, would it be valuable to try to reproduce that same result in Python? In your last script, I also don't quite understand why we don't see documents {"CCC":1}, and {"DDD":1}, but this is a less pressing matter since I think we can generally expect unexpected results when we force misbehaviors like reusing lsid and txnNumber. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Jeremy Mikola [ 30/Apr/21 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
yeti.moscow@gmail.com: Thanks for the additional tests. Given your results, it doesn't look like lack of entropy is an issue. I think this may warrant further investigation in libmongoc to investigate why different processes are generating identical UUIDs. In the meantime, I would just suggest disabling retryable writes for your script as an immediate work-around. Since all of the errors occurred on CentOS, I'd also ask for the exact version of OpenSSL that libmongoc was linked against. That may be helpful should we need to try and reproduce this down the line. edwin.zhou: Based on the last couple of replies, can you confirm that the server is behaving as expected? I wrote another PHP script to conduct a low-level test, as I was wondering what would happen if a subsequent command (same "lsid" and "txnNumber") was a different command (e.g. insert instead of another findAndModify). This isn't using any retryable writes logic in libmongoc/PHP. I'm just executing four different write commands with the same session and manually specifying the same "txnNumber" value:
In the output, we can see identical "lsid" and "txnNumber" fields in outgoing commands. The second findAndModify response repeats the result from the first findAndModify (reproducing the OP's issue); however, both insert commands appear to return unique results with n simply set to the size of the "documents" parameter in the original command. Querying the collection after all four commands have executed shows that only two documents were written: "AAA" from the first findAndModify and "EEE" from the second insert. Despite the command replies being unexpected (and incorrect to boot), the outcome makes sense to me. From the server's respective, the EEE document has a different statement ID (second statement for "txnNumber" 1 vs. every other write being first statement for "txnNumber" 1).
| ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Евгений Голендухин [ 29/Apr/21 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Experiment with an explicit sessionI modified the call as you requested
And ran the test once more. Mismatches still occurred as before, seemingly it didn't change anything. Here's an example of a mismatch
Ubuntu and CentOSAll the tests and all the logs I posted here were made on the CentOS machine. Ubuntu is what I have in my WSL2 on a local machine. I initially wrote both scripts on it. Python: on Ubuntu random.randrange did not need seeding and produced random numbers in each fork. In CentOS without the seeding all the forks got the same theme_id. Mismatches did not occur in Python on both systems. PHP: on Ubuntu I could not reproduce the bug because for some reason the forks did not die properly and just filled my machine and I basically had to restart it. So I could not reproduce the problem but for different reasons. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Jeremy Mikola [ 28/Apr/21 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Parsing log files for conflictsyeti.moscow@gmail.com: Thanks for the quick turn-around on the logs. I wrote a small script to parse all of the conflicts from a log file:
Examining conflicts in the logsAs expected, this found no conflicts in python_retryWrites_false.log or either of the Python logs but there were a number of conflicts in php_retryWrites_none.log once the PIDs started rolling over:
Comparing observed commands/replies for a conflictLooking at the first two conflicts for PID 31617, we can see that both processes happen to use the same lsid and txnNumber, despite the findAndModify commands themselves differing:
Although each server response does include different values for operationTime and $clusterTime (used for causal consistency), the second response appears to re-use the result of the first findAndModify (derived from the oplog). I believe this is expected behavior for the server, since retryable writes consider the combination of lsid (i.e. logical session ID) and txnNumber to uniquely identify a write operation. The txnNumber sequence is also maintained per session, so it's expected for drivers to initialize each sequence at 1. Identical logical session IDsThe underlying issue appears to be that libmongoc is somehow creating two identical logical session IDs in different processes. This is unexpected, as session IDs generated by drivers are UUIDs and should be unique. Looking at _mongoc_server_session_new, we can see that _mongoc_server_session_uuid is used to initialize a 16-byte UUID. Randomness is pulled from _mongoc_rand_bytes, the implementation of which varies according to the crypto library linked by libmongoc (see: Configuring TLS: Supported Libraries). On Linux, we'd expect libcrypto to be used so the relevant implementation is in mongoc-rand-openssl.c. This takes our focus to RAND_bytes, which provides "cryptographically strong pseudo-random bytes" and returns an error if there is insufficient entropy to do so (which libmongoc appears to check for an error accordingly). I'll note that libmongoc does provide additional functions to seed the PRNG (proxies to libcrypto's seed functions), they are not used by the PHP driver. At this point, I think there are two possibilities:
Explicit and implicit sessionsFrom the driver's perspective, there are two types of sessions: explicit and implicit. Explicit sessions would be created by MongoDB\Driver\Manager::startSession() (also called by MongoDB\Client::startSession() and explicitly passed to an operation. In this case, the PHP driver will propagate any error from libmongoc as an exception. Implicit sessions are created internally by the driver. For basic queries (i.e. find) and writes (i.e. insert/update/delete), PHP relies on libmongoc to generate its own implicit sessions; however, for all other commands PHP generates the implicit session directly (necessary to ensure the same session is associated with a command any cursor it may potentially create). This generation happens in phongo_execute_command] and following the call to phongo_create_implicit_session you'll see that any error reported by mongoc_client_start_session is ignored. That is consistent with libmongoc's own logic in mongoc_cmd_parts_assemble. AFAIK, the driver sessions specification does not instruct drivers on what to do if a UUID cannot be generated so this "ignore errors for implicit sessions" behavior may be unique to libmongoc/PHP. The spec does mention that drivers MAY invoke a startSession server command as an alternative, but I'm personally not aware of any drivers that actually do so. Experiment with an explicit sessionIf you'll entertain me, one additional experiment I have would be to modify your PHP script to explicitly create a session object and pass that as the session option to findOneAndUpdate(). This could be accomplished by adding the following as the third $options argument to the method:
This test should allow us to rule out whether libmongoc is raising an error due to lack of entropy, since startSession() would throw an exception. Considering duplicate random valuesBased on the results of the explicit session experiment, I'll shift my attention to libmongoc's UUID generation and see if I can reproduce generating duplicate lsid values locally. I do have a few questions about the following line from your last response:
Without the call to random.seed in Python, were you experiencing duplicate session IDs or was it just random.randrange that was returning duplicate values for theme_id? Since you alluded to CentOS and Ubuntu, can you confirm whether you're able to reproduce the PHP mismatch errors on both operating systems? Which OS was used to produce the attached parse.php php_retryWrites_none.log file? Does the other OS produce a similar result (i.e. mismatches after PIDs start rolling over)? | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Евгений Голендухин [ 28/Apr/21 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi, Jeremy I have run both the tests you asked and attached the log files. php_retryWrites_none.log, python_retryWrites_none.log - is the same setup as before, php_retryWrites_false.log and python_retryWrites_false.log - with added retryWrites=false
Every line in all four files has format (<timestamp> pid:<pid> Command:<command> Reply:<reply>) For each run I've let the script run until pids started repeating then stopped.
retryWrites=false does remove txnNumber from logs and the mismatches do not occur. In all four runs the only one with mismatches was the one in php with no retryWrites parameter (php_retryWrites_none.log) Here's an example of a mismatched request from the file
Seeding in PHP vs. Python I had to add seeding to the python scipt because in CentOS it always returned the same number without seeding, and the problem did not appear in Ubuntu which is strange. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Jeremy Mikola [ 28/Apr/21 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
yeti.moscow@gmail.com: I don't think sendmsg and sendto are significant, as they should be functionally equivalent for the driver's purposes. The send(2) man page discusses some differences between their APIs, but I think the primary reason you see sendmsg in PHP is that libmongoc, which we build upon, uses iovecs for its socket communication. Re-running scripts with command loggingSince you have PHP and Python scripts at the ready, can you investigate further by integrating command monitoring so that we can see exactly what command and reply documents are being exchanged with the server? PyMongo's monitoring component should explains how to do this, and the equivalent documentation for PHP is here. One approach would be to modify the example command subscribers to collect CommandStarted and CommandSucceeded events and log the corresponding command and reply properties as JSON. Since your main script is forking many children, you could either have each child log to a separate file (e.g. named "<timestamp>_<pid>.log") or just have each child log directly to stdout/err (probably prefixing output with a timestamp and pid) if you don't expect the output would clobber each other. This would allow us to examine some of the extra fields appended to outgoing findAndModify commands, such as lsid and txnNumber fields, which are appended for Retryable Writes. As you mentioned PHP seems to be receiving the wrong response from the server, I'd like to confirm if two children happen to be sending the same pair of values, which might be causing the server to conclude that a new findAndModify command is actually a retry attempt of a previous command, and thus return the previous command's response instead of processing it as a new write. Once you have commands and replies being logged, please run the PHP script until a mismatch occurs and then package up the logs (either archive multiple files or a copy of the combined stdout/err output) and attach it for review. You can do the same for Python, but if PyMongo never produces a mismatch I don't think its output will be as useful to review. There's no harm in sharing it if you'd like to run it for approximately the same time as it takes PHP to produce a mismatch, though. Separate test with retryWrites=falseAfter running the above test and capturing command logs leading up to a mismatch event, there is a second test I would like you to conduct (to minimize back and forth on this ticket). Add "retryWrites=false" to your connection string options and re-run the command logging test. This should result in txnNumber being removed from outgoing findAndModify commands, although lsid will still be present. I'd be curious to see if PHP still encounters a mismatch in this case and would be interested in seeing the logs for both PHP and Python if that's not too much trouble. Please name the attached files clearly so we don't mix these logs up with the previous test (i.e. with "retryWrites" unspecified, so it defaults to true). Seeding in PHP vs. PythonI noticed that your Python script was seeding the random number generator, but you were not doing so for PHP. This could mean the PHP children are more likely to generate the same random numbers. I'd like you to keep this behavior (not seeding) as-is for the logging test above so we can investigate the issue as it stands. Down the line, I might suggest changing over to a better random number generator (e.g. random_int) – but I'm very much interested in getting to the bottom of this issue while it can be reliably reproduced on your end. Thanks. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Евгений Голендухин [ 28/Apr/21 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hello, Edwin I tried it with Python on the same server and the error is not reproduced.
Python 3.6.8 pymongo (3.11.3)
Additionally we tried watching strace outputs for both PHP and Python versions and it seems they are a bit different. PHP uses `sendmsg` to send requests and Python uses the `sendto` function. Also for PHP it seems like the wrong answer comes from the server. The screenshot in this issue was added by my colleague and as far as we could understand the `sendmsg` in it contains the right theme_id, while the answer in `recvfrom` contains the wrong one.
Best, Eugene | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Edwin Zhou [ 26/Apr/21 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thank you for your report and reproduction script. We'd like to narrow down whether this is a PHP driver issue or a MongoDB server issue. Are you able to reproduce this using a different MongoDB driver, such as the Python driver? Would you also provide the mongod.log files that cover this issue? We look forward to hearing back from you! Best, |