interplay between FFC log and python logging

[Francesco Ballarin]

Dear FFC developers,

I am facing a strange issue related to FFC logging whenever I use in my module the standard python logging.

If call FFC from dolfin as follows

from dolfin import *
from logging import log, ERROR
#log(ERROR, "A")
mesh = UnitSquareMesh(3,3)
V = FunctionSpace(mesh, "CG", 1)

I get as output

Calling FFC just-in-time (JIT) compiler, this may take some time.

However, if I uncomment the third line, i.e.

from dolfin import *
from logging import log, ERROR
log(ERROR, "A")
mesh = UnitSquareMesh(3,3)
V = FunctionSpace(mesh, "CG", 1)

I get a more verbose output

ERROR:root:A
Calling FFC just-in-time (JIT) compiler, this may take some time.
Level 25:FFC:Calling FFC just-in-time (JIT) compiler, this may take some time.
INFO:FFC:Compiling element ffc_element_e0c002ea957b73e574d35ff1e1cd58d549ad36e2

INFO:FFC:Compiler stage 1: Analyzing element(s)
INFO:FFC:--------------------------------------
INFO:FFC:  
INFO:FFC:Compiler stage 1 finished in 0.000185966 seconds.

INFO:FFC:Compiler stage 2: Computing intermediate representation
INFO:FFC:-------------------------------------------------------
INFO:FFC:  Computing representation of 1 elements
DEBUG:FFC:  Reusing element from cache
DEBUG:FFC:  Reusing element from cache
INFO:FFC:  Computing representation of 1 dofmaps
DEBUG:FFC:  Reusing element from cache
INFO:FFC:  Computing representation of 0 coordinate mappings
INFO:FFC:  Computing representation of integrals
INFO:FFC:  Computing representation of forms
INFO:FFC:  
INFO:FFC:Compiler stage 2 finished in 0.0347683 seconds.

INFO:FFC:Compiler stage 3: Optimizing intermediate representation
INFO:FFC:--------------------------------------------------------
INFO:FFC:  Skipping optimizations, add -O or attach {'optimize': True} metadata to integrals
INFO:FFC:  
INFO:FFC:Compiler stage 3 finished in 0.000148296 seconds.

INFO:FFC:Compiler stage 4: Generating code
INFO:FFC:---------------------------------
INFO:FFC:  Generating code for 1 finite_element(s)
INFO:FFC:  Generating code for 1 dofmap(s)
INFO:FFC:  Generating code for 0 coordinate_mapping(s)
INFO:FFC:  Generating code for integrals
INFO:FFC:  Generating code for forms
INFO:FFC:  
INFO:FFC:Compiler stage 4 finished in 0.0188041 seconds.

INFO:FFC:Compiler stage 4.1 finished in 1.66893e-06 seconds.

INFO:FFC:Compiler stage 5: Formatting code
INFO:FFC:---------------------------------
INFO:FFC:  
INFO:FFC:Compiler stage 5 finished in 0.000388622 seconds.

INFO:FFC:FFC finished in 0.0545471 seconds.

of which I was actually expecting only the first two lines. Is this normal? Can your reproduce? (I am using git master versions from earlier this week and tested both with python 2 and 3)

Thanks,

Francesco