Multiple calls to BlockLogs() permanently disable logging

[ricrogz]

Found with Release 2020_03_1b1:

In [3]: Chem.MolFromSmiles('garbage')                                                                                                                        
[11:49:29] SMILES Parse Error: syntax error while parsing: garbage
[11:49:29] SMILES Parse Error: Failed parsing SMILES 'garbage' for input: 'garbage'

In [4]: def blocklogs(): 
   ...:     b = Chem.rdBase.BlockLogs() 
   ...:     b = Chem.rdBase.BlockLogs() 
   ...:                                                                                                                                                      

In [5]: blocklogs()                                                                                                                                          

In [6]: Chem.MolFromSmiles('garbage')                                                                                                                        

In [7]:  

This is relevant because we do actually call BlockLogs() multiple times in places like

rdkit/rdkit/Chem/Draw/__init__.py

Lines 447 to 460 in 67409c3

	def _moltoimg(mol, sz, highlights, legend, returnPNG=False, drawOptions=None, **kwargs):
	try:
	blocker = rdBase.BlockLogs()
	mol.GetAtomWithIdx(0).GetExplicitValence()
	except RuntimeError:
	mol.UpdatePropertyCache(False)
	kekulize = _okToKekulizeMol(mol, kwargs.get('kekulize', True))
	wedge = kwargs.get('wedgeBonds', True)
	try:
	blocker = rdBase.BlockLogs()
	mc = rdMolDraw2D.PrepareMolForDrawing(mol, kekulize=kekulize, wedgeBonds=wedge)
	except ValueError: # <- can happen on a kekulization failure

[greglandrum]

It's actually even more entertaining and random than that:

In [4]: bl = rdBase.BlockLogs()

In [5]: Chem.MolFromSmiles('c1cc')

In [6]: bl = None

In [7]: Chem.MolFromSmiles('c1cc')
[15:52:20] SMILES Parse Error: unclosed ring for input: 'c1cc'

In [8]: bl = rdBase.BlockLogs()

In [9]: Chem.MolFromSmiles('c1cc')

In [10]: bl2 = rdBase.BlockLogs()

In [11]: Chem.MolFromSmiles('c1cc')

In [12]: bl = None

In [13]: Chem.MolFromSmiles('c1cc')
[15:52:42] SMILES Parse Error: unclosed ring for input: 'c1cc'

In [14]: bl2 = None

In [15]: Chem.MolFromSmiles('c1cc')

In [16]: bl = rdBase.BlockLogs()

In [17]: Chem.MolFromSmiles('c1cc')

In [18]: bl = None

In [19]: Chem.MolFromSmiles('c1cc')

[greglandrum]

Ok, this happens because BlockLogs() creates a LogStateSetter object which captures the current state of the logs. When the object is destroyed that status is restored.
So the first time you call BlockLogs() it stores the current status.
Then the second time stores "all logs disabled"
So if the second object is destroyed second then the status is left as "all logs disabled"
sigh

[ricrogz]

Yeah, that is what happens if you store both BlockLogs() on the same variable: the second instance gets created before the first is destroyed. Then, it gets assigned to the var, and the first is destroyed, and what you mentioned happens.

If you assign the BlockLogs() to different variables, and then leave the context... race condition, depending on which one gets cleaned up by the garbage collector?

Should we make LogStateSetter() a singleton, so that we can only have one instance at a time, and always restore to the first state?

[bp-kelley]

I think the solution is simpler. For BlockLogs, we should only save the state of logs that were initially enabled. I.e. only save the state of logs we toggled to block. Cheers, Brian

…

On Thu, Apr 7, 2022 at 10:18 AM Ric ***@***.***> wrote: Yeah, that is what happens if you store both BlockLogs() on the same variable: the second instance gets created before the first is destroyed. Then, it gets assigned to the var, and the first is destroyed, and what you mentioned happens. If you assign the BlockLogs() to different variables, and then leave the context... race condition, depending on which one gets cleaned up by the garbage collector? Should we make a LogStateSetter() a singleton, so that we can only have one instance at a time, and always restore to the first state? — Reply to this email directly, view it on GitHub <#5172 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ACLOFIH32FDVVLWC42CZ2Y3VD3VEFANCNFSM5SWP3PVA> . You are receiving this because you are subscribed to this thread.Message ID: ***@***.***>

[greglandrum]

I think the solution is simpler. For BlockLogs, we should only save the state of logs that were initially enabled. I.e. only save the state of logs we toggled to block. Cheers, Brian

I like this solution...