[SERVER-50882] Noisy log message, "Received interrupt request for unknown op" Created: 11/Sep/20  Updated: 29/Oct/23  Resolved: 03/Nov/20

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: None
Fix Version/s: 4.9.0

Type: Bug Priority: Minor - P4
Reporter: A. Jesse Jiryu Davis Assignee: Drew Paroski
Resolution: Fixed Votes: 3
Labels: neweng, qexec-team
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Backwards Compatibility: Fully Compatible
Operating System: ALL
Sprint: Query 2020-10-19, Query 2020-11-02, Query 2020-11-16
Participants:

 Description   

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?



 Comments   
Comment by A. Jesse Jiryu Davis [ 06/Nov/20 ]

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.

Comment by Amirsaman Memaripour [ 06/Nov/20 ]

I believe jesse is in the best position to answer the question, as he originally reported the issue.

Comment by Drew Paroski [ 06/Nov/20 ]

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.

Comment by Kevin Pulo [ 06/Nov/20 ]

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.

Comment by Githook User [ 03/Nov/20 ]

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

Generated at Thu Feb 08 05:23:54 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.