Solved

Logging nor printing no longer works in PythonCaller in FME 2019

  • 13 January 2020
  • 2 replies
  • 11 views
S

Hi,

I have a lot of workspaces for FME 2018.1 that use PythonCaller and PythonCreator and log messages to both the translation log window, and the log file, with the logMessageString function, like this:

def log(message, severity=FME_INFO):
    fmeobjects.FMELogFile().logMessageString(str(message)), severity)

 

After upgrading to FME Desktop 2019.2.2, I noticed that FME will neither log to the translation window, nor write anything in the log file, when using logMessageString, or Python's own print function for that matter. I've tried both FME Python 2.7 (deprecated) and FME Python 3.7+.

 

I have this workspace:

0684Q00000ArCjhQAF.png

 

My PythonCallers (print function included just for additional testing):

0684Q00000ArCgTQAV.png0684Q00000ArD1PQAV.png

 

Running the workspace produces this translation log:

    Command-line to run this workspace:
        "C:\Program Files\FME Desktop 2019.2.2 x64\fme.exe" C:\FMEDataTemp\FME2019-Python-logger.fmw
    
Starting translation...
2020-01-13 11:35:41|   1.0|  1.0|STATS |Storing feature(s) to FME feature store file `C:\TEMP\wb-inspectors-EBxWDa\inspector.ffs'
2020-01-13 11:35:41|   1.0|  0.0|STATS |Creator_XML_Creator (CreationFactory): Created 1 features
2020-01-13 11:35:41|   1.0|  0.0|STATS |Creator_Cloner (TeeFactory): Cloned 1 input feature(s) into 1 output feature(s)
2020-01-13 11:35:41|   1.0|  0.0|STATS |Creator CREATED Splitter (TeeFactory): Cloned 1 input feature(s) into 2 output feature(s)
2020-01-13 11:35:41|   1.0|  0.0|STATS |Creator_CREATED_0_GJAgmIF9G6c= Feature Counter -1 5 (TeeFactory): Cloned 1 input feature(s) into 1 output feature(s)
2020-01-13 11:35:41|   1.0|  0.0|STATS |Creator_CREATED_0_GJAgmIF9G6c= Brancher -1 5 (BranchingFactory): Branched 1 input feature -- 1 feature routed to the target factory, and 0 features routed to the fallback factory.
2020-01-13 11:35:41|   1.0|  0.0|STATS |Creator_CREATED_1_Exx7idfjvCA= Feature Counter -1 8 (TeeFactory): Cloned 1 input feature(s) into 1 output feature(s)
2020-01-13 11:35:41|   1.0|  0.0|STATS |Creator_CREATED_1_Exx7idfjvCA= Brancher -1 8 (BranchingFactory): Branched 1 input feature -- 1 feature routed to the target factory, and 0 features routed to the fallback factory.
2020-01-13 11:35:41|   1.0|  0.0|STATS |_CREATOR_BRANCH_TARGET (TeeFactory): Cloned 2 input feature(s) into 2 output feature(s)
2020-01-13 11:35:41|   1.0|  0.0|STATS |PythonCaller_Class_OUTPUT Feature Counter -1 9 (TeeFactory): Cloned 1 input feature(s) into 1 output feature(s)
2020-01-13 11:35:41|   1.0|  0.0|STATS |PythonCaller_Function_OUTPUT Feature Counter -1 6 (TeeFactory): Cloned 1 input feature(s) into 1 output feature(s)
2020-01-13 11:35:41|   1.0|  0.0|STATS |Stored 2 feature(s) to FME feature store file `C:\TEMP\wb-inspectors-EBxWDa\inspector.ffs'
2020-01-13 11:35:41|   1.0|  0.0|STATS |Destination Feature Type Routing Correlator (RoutingFactory): Tested 0 input feature(s), wrote 0 output feature(s): 0 matched merge filters, 0 were routed to output, 0 could not be routed.
2020-01-13 11:35:41|   1.0|  0.0|STATS |Final Output Nuker (TeeFactory): Cloned 0 input feature(s) into 0 output feature(s)
2020-01-13 11:35:41|   1.0|  0.0|STATS |VisualizerProcessor (CreationFactory): Created 1 features
2020-01-13 11:35:41|   1.0|  0.0|STATS |VisualizerCleaner (TeeFactory): Cloned 1 input feature(s) into 0 output feature(s)
2020-01-13 11:35:41|   1.0|  0.0|STATS |=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-
2020-01-13 11:35:41|   1.0|  0.0|STATS |                            Features Read Summary
2020-01-13 11:35:41|   1.0|  0.0|STATS |=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-
2020-01-13 11:35:41|   1.0|  0.0|STATS |==============================================================================
2020-01-13 11:35:41|   1.0|  0.0|STATS |Total Features Read                                                          0
2020-01-13 11:35:41|   1.0|  0.0|STATS |=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-
2020-01-13 11:35:41|   1.0|  0.0|STATS |=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-
2020-01-13 11:35:41|   1.0|  0.0|STATS |                           Features Written Summary
2020-01-13 11:35:41|   1.0|  0.0|STATS |=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-
2020-01-13 11:35:41|   1.0|  0.0|STATS |==============================================================================
2020-01-13 11:35:41|   1.0|  0.0|STATS |Total Features Written                                                       0
2020-01-13 11:35:41|   1.0|  0.0|STATS |=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-
Translation was SUCCESSFUL

 

And this log file:

2020-01-13 11:35:41|   1.0|  1.0|STATS |Storing feature(s) to FME feature store file `C:\TEMP\wb-inspectors-EBxWDa\inspector.ffs'
2020-01-13 11:35:41|   1.0|  0.0|STATS |Creator_XML_Creator (CreationFactory): Created 1 features
2020-01-13 11:35:41|   1.0|  0.0|STATS |Creator_Cloner (TeeFactory): Cloned 1 input feature(s) into 1 output feature(s)
2020-01-13 11:35:41|   1.0|  0.0|STATS |Creator CREATED Splitter (TeeFactory): Cloned 1 input feature(s) into 2 output feature(s)
2020-01-13 11:35:41|   1.0|  0.0|STATS |Creator_CREATED_0_GJAgmIF9G6c= Feature Counter -1 5 (TeeFactory): Cloned 1 input feature(s) into 1 output feature(s)
2020-01-13 11:35:41|   1.0|  0.0|STATS |Creator_CREATED_0_GJAgmIF9G6c= Brancher -1 5 (BranchingFactory): Branched 1 input feature -- 1 feature routed to the target factory, and 0 features routed to the fallback factory.
2020-01-13 11:35:41|   1.0|  0.0|STATS |Creator_CREATED_1_Exx7idfjvCA= Feature Counter -1 8 (TeeFactory): Cloned 1 input feature(s) into 1 output feature(s)
2020-01-13 11:35:41|   1.0|  0.0|STATS |Creator_CREATED_1_Exx7idfjvCA= Brancher -1 8 (BranchingFactory): Branched 1 input feature -- 1 feature routed to the target factory, and 0 features routed to the fallback factory.
2020-01-13 11:35:41|   1.0|  0.0|STATS |_CREATOR_BRANCH_TARGET (TeeFactory): Cloned 2 input feature(s) into 2 output feature(s)
2020-01-13 11:35:41|   1.0|  0.0|STATS |PythonCaller_Class_OUTPUT Feature Counter -1 9 (TeeFactory): Cloned 1 input feature(s) into 1 output feature(s)
2020-01-13 11:35:41|   1.0|  0.0|STATS |PythonCaller_Function_OUTPUT Feature Counter -1 6 (TeeFactory): Cloned 1 input feature(s) into 1 output feature(s)
2020-01-13 11:35:41|   1.0|  0.0|STATS |Stored 2 feature(s) to FME feature store file `C:\TEMP\wb-inspectors-EBxWDa\inspector.ffs'
2020-01-13 11:35:41|   1.0|  0.0|STATS |Destination Feature Type Routing Correlator (RoutingFactory): Tested 0 input feature(s), wrote 0 output feature(s): 0 matched merge filters, 0 were routed to output, 0 could not be routed.
2020-01-13 11:35:41|   1.0|  0.0|STATS |Final Output Nuker (TeeFactory): Cloned 0 input feature(s) into 0 output feature(s)
2020-01-13 11:35:41|   1.0|  0.0|STATS |VisualizerProcessor (CreationFactory): Created 1 features
2020-01-13 11:35:41|   1.0|  0.0|STATS |VisualizerCleaner (TeeFactory): Cloned 1 input feature(s) into 0 output feature(s)
2020-01-13 11:35:41|   1.0|  0.0|STATS |=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-
2020-01-13 11:35:41|   1.0|  0.0|STATS |                            Features Read Summary
2020-01-13 11:35:41|   1.0|  0.0|STATS |=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-
2020-01-13 11:35:41|   1.0|  0.0|STATS |==============================================================================
2020-01-13 11:35:41|   1.0|  0.0|STATS |Total Features Read                                                          0
2020-01-13 11:35:41|   1.0|  0.0|STATS |=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-
2020-01-13 11:35:41|   1.0|  0.0|STATS |=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-
2020-01-13 11:35:41|   1.0|  0.0|STATS |                           Features Written Summary
2020-01-13 11:35:41|   1.0|  0.0|STATS |=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-
2020-01-13 11:35:41|   1.0|  0.0|STATS |==============================================================================
2020-01-13 11:35:41|   1.0|  0.0|STATS |Total Features Written                                                       0
2020-01-13 11:35:41|   1.0|  0.0|STATS |=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-

 

Neither of which contain my messages. However, both PythonCallers will output the initator feature, so the logMessageString function is called in both instances, without any visible errors, before the initiator feature is returned/outputted from the callers.

The FME Python API documentation still recommends using logMessageString: http://docs.safe.com/fme/html/fmepython/getting_started.html#writing-messages-to-the-fme-log

Is this a bug in FME 2019.2.2? I have not tried with other version of FME 2019.

icon

Best answer by david_r 13 January 2020, 17:25

View original

2 replies

david_r
Rank
Userlevel 4

I just tried your workspace with FME(R) 2019.2.2.0 (20200103 - Build 19817 - WIN64), it seems to work just fine:

Could it be that your FME Options settings have been modified to exclude the INFORM messages?

S

I just tried your workspace with FME(R) 2019.2.2.0 (20200103 - Build 19817 - WIN64), it seems to work just fine:

Could it be that your FME Options settings have been modified to exclude the INFORM messages?

Hi David,

I think it could have been a registry problem. I ended up deleting "Settings" under "Computer\\HKEY_CURRENT_USER\\Software\\Safe Software Inc.\\FME Workbench\\", and now I got it working again.

Reply


Community Stats

28,728
Posts
109,524
Replies
36,566
Members
Terms & ConditionsCookie settings
A product of
Safe Software respectfully acknowledges that we live, learn and work on the traditional and unceded territories of the Kwantlen, Katzie, and Semiahmoo First Nations.