Info

Log message 22790 appear a little while ago, and in a typical test it constitutes a large fraction of all log messages: [js_test:migrateBig_balancer] 2020-09-07T08:22:40.599+0000 s20025| 2020-09-07T08:22:40.592+00:00 I COMMAND 51803 [conn13] "Slow query","attr":{"type":"command","ns":"test.stuff","appName":"MongoDB Shell","command":{"insert":"stuff","ordered":false,"lsid":{"id":{"$uuid":"ddf2a4f1-3008-4095-84ff-9300c385fceb"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1599466960,"i":1}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$db":"test"},"nShards":1,"ninserted":1,"numYields":0,"reslen":170,"protocol":"op_msg","durationMillis":155} [js_test:migrateBig_balancer] 2020-09-07T08:22:40.600+0000 s20025| 2020-09-07T08:22:40.593+00:00 D1 QUERY 22790 [conn13] "Received interrupt request for unknown op","attr":{"opId":54} [js_test:migrateBig_balancer] 2020-09-07T08:22:40.905+0000 d20021| 2020-09-07T08:22:40.904+00:00 I STORAGE 22402 [OplogCapMaintainerThread-local.oplog.rs] "WiredTiger record store oplog truncation finished","attr":{"durationMillis":0} [js_test:migrateBig_balancer] 2020-09-07T08:22:40.905+0000 s20025| 2020-09-07T08:22:40.905+00:00 I COMMAND 51803 [conn13] "Slow query","attr":{"type":"command","ns":"test.stuff","appName":"MongoDB Shell","command":{"insert":"stuff","ordered":false,"lsid":{"id":{"$uuid":"ddf2a4f1-3008-4095-84ff-9300c385fceb"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1599466960,"i":2}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$db":"test"},"nShards":1,"ninserted":1,"numYields":0,"reslen":170,"protocol":"op_msg","durationMillis":153} [js_test:migrateBig_balancer] 2020-09-07T08:22:40.906+0000 s20025| 2020-09-07T08:22:40.905+00:00 D1 QUERY 22790 [conn13] "Received interrupt request for unknown op","attr":{"opId":55} [js_test:migrateBig_balancer] 2020-09-07T08:22:41.227+0000 s20025| 2020-09-07T08:22:41.227+00:00 I COMMAND 51803 [conn13] "Slow query","attr":{"type":"command","ns":"test.stuff","appName":"MongoDB Shell","command":{"insert":"stuff","ordered":false,"lsid":{"id":{"$uuid":"ddf2a4f1-3008-4095-84ff-9300c385fceb"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1599466960,"i":3}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$db":"test"},"nShards":1,"ninserted":1,"numYields":0,"reslen":170,"protocol":"op_msg","durationMillis":158} [js_test:migrateBig_balancer] 2020-09-07T08:22:41.228+0000 s20025| 2020-09-07T08:22:41.227+00:00 D1 QUERY 22790 [conn13] "Received interrupt request for unknown op","attr":{"opId":56} Can we lower this message's log level, or log it only occasionally, or reduce the frequency of the event it's logging about?

Top User Comments

jesse commented on Fri, 6 Nov 2020 19:11:35 +0000: I just wanted a large quantity of irrelevant messages about "Received interrupt request for unknown op" removed from BF logs. I still don't understand why they're constantly generated - is that symptomatic of an underlying bug? Why does the server receive incessant interrupt requests for unknown ops? Anyway, if we want to see log messages for cases where the op is known, then that message shouldn't have been demoted. But none of this is my code, it's up to the Query team. amirsaman.memaripour commented on Fri, 6 Nov 2020 18:58:06 +0000: I believe jesse is in the best position to answer the question, as he originally reported the issue. andrew.paroski commented on Fri, 6 Nov 2020 06:31:40 +0000: kevin.pulo: I don't really have an opinion on the issue you raised - I'll defer to jesse and amirsaman.memaripour to answer your question about what the desired behavior should be. kevin.pulo@10gen.com commented on Fri, 6 Nov 2020 01:54:22 +0000: The original issue here was with the "Received interrupt request for unknown op" messages. I notice that, whilst the committed fix increases by 1 the debug output level required to get these messages, it also increased by 1 the debug level required to get the "Interrupting op" messages, ie. when the provided opId matches an in-progress operation, which is then killed. Is this intentional, and if so, what's the motivation? It seems to me that this may result in actual op kills no longer being logged in some test suites (ie. where they were previously), which could impact the diagnosis of BFs. My understanding is that the "Interrupting op" log messages aren't as voluminous as the "Received interrupt request for unknown op" ones, and so therefore aren't a problem. xgen-internal-githook commented on Tue, 3 Nov 2020 23:24:43 +0000: Author: {'name': 'Drew Paroski', 'email': 'drew.paroski@mongodb.com', 'username': 'paroski'} Message: SERVER-50882 Noisy log message, "Received interrupt request for unknown op" Branch: master https://github.com/mongodb/mongo/commit/56fa2742d7b7e51bfe431bf3ae810ef393f50426

Steps to Reproduce