Hello, I think there is something in the way FME python process are interacting that I don't understand. I used the python library "logging" to track exceptions resolved in my python callers, In every python callers, in the creator of the feature processor, I define the loggers, using different files names, and different object names, but in the end every log line is written, not only in said file, but is also stacked in any log file created by any previous python caller... (TL;DR: the log file B.log contains log from pythonCallerB but the log file A.log contains logs from both pythonCallerB and pythonCallerA)

Python logs files from different python callers are stacking

J

Hi,

I suggest you use the logger of FME itself. The documentation can be found here:

https://docs.safe.com/fme/html/FME_Objects_Python_API/fmeobjects.FMELogFile-class.html

Userlevel 4

I suspect you're not initalizing the logger properly, you will have to define separate handlers for each PythonCaller if you want them to log to different files. This is by design in the logging module and is not specific to FME. The first paragraph here probably applies to your case: https://docs.python.org/2/howto/logging-cookbook.html#using-logging-in-multiple-modules

Sample PythonCaller that initializes its own handler:

import fmeimport fmeobjectsimport loggingclass FeatureProcessor1(object):    def __init__(self):        logger_name = self.__class__.__name__        logger_filename = self.__class__.__name__+'.log'        print "%s is logging to file %s" % (logger_name, logger_filename)        self.logger = logging.getLogger(logger_name)        self.logger.setLevel(logging.INFO)        fh = logging.FileHandler(logger_filename)        # create formatter and add it to the handlers        formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')        fh.setFormatter(formatter)        # add the handlers to the logger        self.logger.addHandler(fh)            def input(self,feature):        self.logger.info('A message from PythonCaller_1')        self.pyoutput(feature)

Sample workspace with two PythonCallers that log to separate files using the logging module: pythonlogger.fmwt

For the above to work without modifications, make sure that all your PythonCallers use separate class names, otherwise they'll end competing for the same log file name. Sample output

FeatureProcessor1.log

2017-03-16 13:23:20,411 - FeatureProcessor1 - INFO - A message from PythonCaller_1

FeatureProcessor2.log

2017-03-16 13:23:20,411 - FeatureProcessor2 - INFO - A message from PythonCaller_2

L

Hi,

Are you raising back the exception after logging it?

If this is the case, this is why the previous PythonCallers are also logging the exception.

My understanding is that when you have PythonCaller_1 followed by PythonCaller_2 and PythonCaller_1 calls self.pyoutput, this function call does not return until the feature is written in the output or held by a blocking transformer. Thus, if PythonCaller_2 catch an exception, log and raise it, PythonCaller_2 will catch it too.

And following the discussion I had with @david_r in the comments below, if you are raising back the exception and don't want to have it logged by the previous PythonCallers, you have to place the pyoutput call outside of your try block.

Userlevel 4

Hi,

Are you raising back the exception after logging it?

If this is the case, this is why the previous PythonCallers are also logging the exception.

My understanding is that when you have PythonCaller_1 followed by PythonCaller_2 and PythonCaller_1 calls self.pyoutput, this function call does not return until the feature is written in the output or held by a blocking transformer. Thus, if PythonCaller_2 catch an exception, log and raise it, PythonCaller_2 will catch it too.

And following the discussion I had with @david_r in the comments below, if you are raising back the exception and don't want to have it logged by the previous PythonCallers, you have to place the pyoutput call outside of your try block.

This interests me because it reminds me of some weird behaviour I've seen before, so I tried to reproduce using the attached workspace, but FME 2017 seems to handle it correctly.

PythonCaller_1 raises an exception and the log reads:

2017-03-16 14:28:20,157 - FeatureProcessor1 - INFO - A message from PythonCaller_12017-03-16 14:28:20,157 - FeatureProcessor1 - ERROR - integer division or modulo by zero

The log from PythonCaller_2 remains empty, as expected. See pythonlogger.fmwt

Or am I misunderstanding something?

L

This interests me because it reminds me of some weird behaviour I've seen before, so I tried to reproduce using the attached workspace, but FME 2017 seems to handle it correctly.

PythonCaller_1 raises an exception and the log reads:

2017-03-16 14:28:20,157 - FeatureProcessor1 - INFO - A message from PythonCaller_12017-03-16 14:28:20,157 - FeatureProcessor1 - ERROR - integer division or modulo by zero

The log from PythonCaller_2 remains empty, as expected. See pythonlogger.fmwt

Or am I misunderstanding something?

Note: I don't have 2017 installed yet and I ran your code with 2016.

The behavior depends on two major things.

1- Where the pyoutput is called: inside or outside of the try section.

2- If you are raising back the exception

In your particular case, as soon as there is an exception caught, you are logging and raising back the exception. Since your pyoutput is called after the raise, it is not called.

On the other hand, if you make the code work normally in PythonCaller_1 (P1) and let the feature go to PythonCaller_2 (P2), P2 will catch/raise the exception and P1 will only detect that an exception occured but not catch it because the pyoutput is outside the try block. You'll see in following pictures that the message "(PythonFactory): PythonFactory failed to process feature" appears twice in the second example, one for the first raise in P2 and one when P1 receives the exception raised by P2.

Original code:

Modified code to let the feature go to P2:

Userlevel 4

Note: I don't have 2017 installed yet and I ran your code with 2016.

The behavior depends on two major things.

1- Where the pyoutput is called: inside or outside of the try section.

2- If you are raising back the exception

In your particular case, as soon as there is an exception caught, you are logging and raising back the exception. Since your pyoutput is called after the raise, it is not called.

On the other hand, if you make the code work normally in PythonCaller_1 (P1) and let the feature go to PythonCaller_2 (P2), P2 will catch/raise the exception and P1 will only detect that an exception occured but not catch it because the pyoutput is outside the try block. You'll see in following pictures that the message "(PythonFactory): PythonFactory failed to process feature" appears twice in the second example, one for the first raise in P2 and one when P1 receives the exception raised by P2.

Original code:

Modified code to let the feature go to P2:

Thanks, that makes sense.

V

vchalmel
Author
30 replies
7 years ago
22 March 2017

Hi,

Are you raising back the exception after logging it?

If this is the case, this is why the previous PythonCallers are also logging the exception.

My understanding is that when you have PythonCaller_1 followed by PythonCaller_2 and PythonCaller_1 calls self.pyoutput, this function call does not return until the feature is written in the output or held by a blocking transformer. Thus, if PythonCaller_2 catch an exception, log and raise it, PythonCaller_2 will catch it too.

And following the discussion I had with @david_r in the comments below, if you are raising back the exception and don't want to have it logged by the previous PythonCallers, you have to place the pyoutput call outside of your try block.

Not sure whether or not that applies to my issue, I don't think I raised it back, (I didn't want the workspace to fail in these exceptions handling scenarii) but I will check !

V

vchalmel
Author
30 replies
7 years ago
22 March 2017

I suspect you're not initalizing the logger properly, you will have to define separate handlers for each PythonCaller if you want them to log to different files. This is by design in the logging module and is not specific to FME. The first paragraph here probably applies to your case: https://docs.python.org/2/howto/logging-cookbook.html#using-logging-in-multiple-modules

Sample PythonCaller that initializes its own handler:

import fmeimport fmeobjectsimport loggingclass FeatureProcessor1(object):    def __init__(self):        logger_name = self.__class__.__name__        logger_filename = self.__class__.__name__+'.log'        print "%s is logging to file %s" % (logger_name, logger_filename)        self.logger = logging.getLogger(logger_name)        self.logger.setLevel(logging.INFO)        fh = logging.FileHandler(logger_filename)        # create formatter and add it to the handlers        formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')        fh.setFormatter(formatter)        # add the handlers to the logger        self.logger.addHandler(fh)            def input(self,feature):        self.logger.info('A message from PythonCaller_1')        self.pyoutput(feature)

Sample workspace with two PythonCallers that log to separate files using the logging module: pythonlogger.fmwt

For the above to work without modifications, make sure that all your PythonCallers use separate class names, otherwise they'll end competing for the same log file name. Sample output

FeatureProcessor1.log

2017-03-16 13:23:20,411 - FeatureProcessor1 - INFO - A message from PythonCaller_1

FeatureProcessor2.log

2017-03-16 13:23:20,411 - FeatureProcessor2 - INFO - A message from PythonCaller_2

Well that seems to match with my issue, this was indeed my first guess and as said in the original post, I used different object names for each loggers/formatters/handlers to rule that out, but I always thought that FME was secretly renaming the class to prevent classes from two different callers to interfere.

So... might there be any other things that might be at odds with to pythonCallers sharing their classes names ?

Userlevel 4

Well that seems to match with my issue, this was indeed my first guess and as said in the original post, I used different object names for each loggers/formatters/handlers to rule that out, but I always thought that FME was secretly renaming the class to prevent classes from two different callers to interfere.

So... might there be any other things that might be at odds with to pythonCallers sharing their classes names ?

For what it's worth, I've never seen any evidence of some "secret renaming" of the classes in FME, it works pretty transparently. You do have to be careful about namespaces and scopes, however, but that isn't really specific to FME.

Python logs files from different python callers are stacking

9 replies

Reply

Community Stats

Reply

Community Stats

Sign up

An FME Account is required to contribute

Login to the community

An FME Account is required to contribute

Scanning file for viruses.

This file cannot be downloaded