Pentaho

 View Only

 ETL execution stops

Marko Jordan's profile image
Marko Jordan posted 09-01-2023 10:07

Hi, sometimes ETL stops at certain step, for instance "Finished job entry [STG83_update_T_KALK_PRD_step1] (result=[false])" without any specific ERROR in the execution log, tranformation is just listed as (result=[false]), no explicit error... other times ETL proceeds with "Finished job entry [STG83_update_T_KALK_PRD_step1] (result=[true])"... 

ETL step where this occures is totaly random, it could be a diferent transformation every time. Any idea what could be the cause of that and why is there no error?

LOG extraction, Execution stops at transformation STG83_update_T_KALK_PRD_step1:

2023/08/31 02:24:15 - 17B existing row.0 - Finished processing (I=0, O=0, R=32303, W=32303, U=0, E=0)
2023/08/31 02:24:15 - 18B prepare TEST.0 - Finished processing (I=0, O=0, R=32303, W=32303, U=0, E=0)
2023/08/31 02:24:15 - 21B is change.0 - Finished processing (I=0, O=0, R=32303, W=32303, U=0, E=0)
2023/08/31 02:24:15 - 22B no change.0 - Finished processing (I=0, O=0, R=32303, W=32303, U=0, E=0)
2023/08/31 02:24:15 - 25B prepare cols.0 - Finished processing (I=0, O=0, R=32303, W=32303, U=0, E=0)
2023/08/31 02:24:15 - 30B update DATs.0 - Finished reading query, closing connection.
2023/08/31 02:24:15 - 30B update DATs.0 - Finished processing (I=0, O=0, R=32303, W=32303, U=0, E=0)
2023/08/31 02:24:15 - JSTG08_read_T_KALK_PRD - Starting entry [STG81_update_STG_KALK_PRD_step2]
2023/08/31 02:24:15 - STG81_update_STG_KALK_PRD_step2 - Dispatching started for transformation [STG81_update_STG_KALK_PRD_step2]
2023/08/31 02:24:15 - 10 update STG_KALK_PRD.0 - Connected to database [STAGE connection (10.0.1.10)] (commit=1000)
2023/08/31 02:24:15 - 00A read STG_KALK_PRD_NEW.0 - Finished reading query, closing connection
2023/08/31 02:24:15 - 00B read STG_KALK_PRD_UPD.0 - Finished reading query, closing connection
2023/08/31 02:24:15 - 05B deactivate existing row.0 - Finished reading query, closing connection.
2023/08/31 02:24:15 - JSTG08_read_T_KALK_PRD - Starting entry [STG83_update_T_KALK_PRD_step1]
2023/08/31 02:24:16 - STG83_update_T_KALK_PRD_step1 - Dispatching started for transformation [STG83_update_T_KALK_PRD_step1]
2023/08/31 02:24:16 - 25A fill T_KALK_PRD_NEW.0 - Connected to database [STAGE connection (10.0.1.10)] (commit=1000)
2023/08/31 02:24:17 - 00A read STG_KALK_PRD.0 - Finished reading query, closing connection
2023/08/31 02:24:17 - 00B read T_KALK_PRD.0 - Finished reading query, closing connection
2023/08/31 02:24:17 - 25A update T_KALK_DAT_DO.0 - Finished reading query, closing connection.
2023/08/31 02:24:17 - 25C FULL update T_KALK_PRD.0 - Finished reading query, closing connection.
2023/08/31 02:24:17 - JSTG08_read_T_KALK_PRD - Finished job entry [STG83_update_T_KALK_PRD_step1] (result=[false])
2023/08/31 02:24:17 - JSTG08_read_T_KALK_PRD - Finished job entry [STG81_update_STG_KALK_PRD_step2] (result=[false])
2023/08/31 02:24:17 - JSTG08_read_T_KALK_PRD - Finished job entry [STG81_update_STG_KALK_PRD_step1] (result=[false])

LOG extraction, ETL Execution continues:

2023/08/31 17:59:36 - 17B existing row.0 - Finished processing (I=0, O=0, R=32303, W=32303, U=0, E=0)
2023/08/31 17:59:36 - 18B prepare TEST.0 - Finished processing (I=0, O=0, R=32303, W=32303, U=0, E=0)
2023/08/31 17:59:36 - 21B is change.0 - Finished processing (I=0, O=0, R=32303, W=32303, U=0, E=0)
2023/08/31 17:59:36 - 22B no change.0 - Finished processing (I=0, O=0, R=32303, W=32303, U=0, E=0)
2023/08/31 17:59:36 - 25B prepare cols.0 - Finished processing (I=0, O=0, R=32303, W=32303, U=0, E=0)
2023/08/31 17:59:36 - 30B update DATs.0 - Finished reading query, closing connection.
2023/08/31 17:59:36 - 30B update DATs.0 - Finished processing (I=0, O=0, R=32303, W=32303, U=0, E=0)
2023/08/31 17:59:36 - JSTG08_read_T_KALK_PRD - Starting entry [STG81_update_STG_KALK_PRD_step2]
2023/08/31 17:59:36 - STG81_update_STG_KALK_PRD_step2 - Dispatching started for transformation [STG81_update_STG_KALK_PRD_step2]
2023/08/31 17:59:36 - 10 update STG_KALK_PRD.0 - Connected to database [STAGE connection (10.0.1.10)] (commit=1000)
2023/08/31 17:59:36 - 00B read STG_KALK_PRD_UPD.0 - Finished reading query, closing connection
2023/08/31 17:59:36 - 00A read STG_KALK_PRD_NEW.0 - Finished reading query, closing connection
2023/08/31 17:59:36 - 05B deactivate existing row.0 - Finished reading query, closing connection.
2023/08/31 17:59:36 - JSTG08_read_T_KALK_PRD - Starting entry [STG83_update_T_KALK_PRD_step1]
2023/08/31 17:59:36 - STG83_update_T_KALK_PRD_step1 - Dispatching started for transformation [STG83_update_T_KALK_PRD_step1]
2023/08/31 17:59:37 - 25D fill T_KALK_PRD_UPD.0 - Connected to database [STAGE connection (10.0.1.10)] (commit=1000)
2023/08/31 17:59:37 - 25A fill T_KALK_PRD_NEW.0 - Connected to database [STAGE connection (10.0.1.10)] (commit=1000)
2023/08/31 17:59:39 - 00B read T_KALK_PRD.0 - Finished reading query, closing connection
2023/08/31 17:59:39 - 00B read T_KALK_PRD.0 - Finished processing (I=44551, O=0, R=0, W=44551, U=0, E=0)
2023/08/31 17:59:39 - 02B prepare cols.0 - Finished processing (I=0, O=0, R=44551, W=44551, U=0, E=0)
2023/08/31 17:59:39 - 10 lookup existing.0 - linenr 50000
2023/08/31 17:59:39 - 00A read STG_KALK_PRD.0 - Finished reading query, closing connection
2023/08/31 17:59:39 - 00A read STG_KALK_PRD.0 - Finished processing (I=44196, O=0, R=0, W=44196, U=0, E=0)
2023/08/31 17:59:39 - 02A prepare cols.0 - Finished processing (I=0, O=0, R=44196, W=44196, U=0, E=0)
2023/08/31 17:59:42 - 10 lookup existing.0 - Finished processing (I=0, O=0, R=88747, W=44196, U=0, E=0)
2023/08/31 17:59:44 - 11 set DATes.0 - Finished processing (I=0, O=0, R=44196, W=44196, U=0, E=0)
2023/08/31 17:59:45 - 12 test existing.0 - Finished processing (I=0, O=0, R=44196, W=44196, U=0, E=0)
2023/08/31 17:59:47 - 13B existing row.0 - Finished processing (I=0, O=0, R=44196, W=44196, U=0, E=0)
2023/08/31 17:59:49 - 14B set PERIOD.0 - Finished processing (I=0, O=0, R=44196, W=44196, U=0, E=0)
2023/08/31 17:59:49 - 15B prepare TEST.0 - Finished processing (I=0, O=0, R=44196, W=44196, U=0, E=0)
2023/08/31 17:59:49 - 15B round TEST.0 - Finished processing (I=0, O=0, R=44196, W=44196, U=0, E=0)
2023/08/31 17:59:49 - 16B get CLOSE_MON.0 - Finished processing (I=0, O=0, R=44196, W=44196, U=0, E=0)
2023/08/31 17:59:49 - 17B test CHANGE.0 - Finished processing (I=0, O=0, R=44196, W=44196, U=0, E=0)
2023/08/31 17:59:49 - 25C FULL update T_KALK_PRD.0 - Finished reading query, closing connection.
2023/08/31 17:59:51 - 18B no change.0 - Finished processing (I=0, O=0, R=44196, W=44196, U=0, E=0)
2023/08/31 17:59:54 - 22B prepare cols.0 - Finished processing (I=0, O=0, R=44196, W=44196, U=0, E=0)
2023/08/31 17:59:58 - 25A update T_KALK_DAT_DO.0 - Finished reading query, closing connection.
2023/08/31 17:59:58 - 25A update T_KALK_DAT_DO.0 - Finished processing (I=0, O=0, R=44196, W=44196, U=0, E=0)
2023/08/31 17:59:58 - JSTG08_read_T_KALK_PRD - Starting entry [STG83_update_T_KALK_PRD_step2]
2023/08/31 17:59:58 - STG83_update_T_KALK_PRD_step2 - Dispatching started for transformation [STG83_update_T_KALK_PRD_step2]
2023/08/31 17:59:58 - 10 update T_KALK_PRD.0 - Connected to database [DWH connection (10.0.1.10)] (commit=5000)
2023/08/31 17:59:58 - 00A read T_KALK_PRD_NEW.0 - Finished reading query, closing connection
2023/08/31 17:59:58 - 00B read T_KALK_PRD_UPD.0 - Finished reading query, closing connection
2023/08/31 17:59:58 - 05B deactivate existing row.0 - Finished reading query, closing connection.
2023/08/31 17:59:59 - JSTG08_read_T_KALK_PRD - Starting entry [Success]
2023/08/31 17:59:59 - JSTG08_read_T_KALK_PRD - Finished job entry [Success] (result=[true])
2023/08/31 17:59:59 - JSTG08_read_T_KALK_PRD - Finished job entry [STG83_update_T_KALK_PRD_step2] (result=[true])
2023/08/31 17:59:59 - JSTG08_read_T_KALK_PRD - Finished job entry [STG83_update_T_KALK_PRD_step1] (result=[true])
2023/08/31 17:59:59 - JSTG08_read_T_KALK_PRD - Finished job entry [STG81_update_STG_KALK_PRD_step2] (result=[true])
2023/08/31 17:59:59 - JSTG08_read_T_KALK_PRD - Finished job entry [STG81_update_STG_KALK_PRD_step1] (result=[true])
2023/08/31 17:59:59 - JSTG08_read_T_KALK_PRD - Finished job entry [Set variables] (result=[true])

Antonio Petrella's profile image
Antonio Petrella posted 09-04-2023 02:57

Hello,

  can it be en error from the database? Try to rerun with the Log Level set to Debug or even Row Level, you might get more info in the log.

Marko Jordan's profile image
Marko Jordan posted 09-04-2023 05:30

Hi Antonio,

I've tried Debug level, not Row level, since it would generate too much data... unfortunately no additional information in Debug level log, after one transformation in the job is succesfully processed (result=[true]), next one goes authomaticaly into (result=[false]), without any error in the log.

Antonio Petrella's profile image
Antonio Petrella posted 09-04-2023 05:50

Hi Marko,

  difficult to analyse this by looking at the logs only. Which steps are you using in the transformation that fails?  Do they correctly handle exceptions? 

Marko Jordan's profile image
Marko Jordan posted 09-04-2023 07:53

Hi Antonio,

nothing special in the transformation (attached), the step in which the execution fails is totally random, next time it would be in a different step, differnet transformation without any error info in the log.... just log entry "Finished job entry (result=[false])", which you can see in the LOG extraction above.

Attachment  View in library
STG83_update_T_KALK_PRD_step2.ktr 39 KB
Antonio Petrella's profile image
Antonio Petrella posted 09-04-2023 11:39

Hi Marko,  

Just a wild guess here: from the log sent, it seems that the STG83....step2.ktr starts, but it does not read any data from the 00A and 00B and it continues to STG83...step1.ktr after initializing 05B deactivate existing rows.

I see that such step is Execute SQL script. In its documentation I read: "Note: The execution of the transformation will halt when a statement in the script fails."  (https://help.hitachivantara.com/Documentation/Pentaho/Data_Integration_and_Analytics/9.4/Products/Execute_SQL_Script). Wonder if that might be the source of your failure too (perhaps a temp table being unavailable at the execution time?). Have you tried swapping the Execute SQL script with Update step?

Stephen Donovan's profile image
Stephen Donovan posted 09-05-2023 13:23

Good suggestions Antonio.  It does look to be a simple update.  You could alternatively add Error Handling to that step, which the Update step also supports.

A simple Write to log step for just one row can often be enlightening.  Better than showing all rows in the logs. You can leave it as Basic or move it up to only show during Debug.

I would recommend that you also separate the logging.  At the entry level you can create a new log for these transformation calls and increase the logging level of one or more.  This might give you additonal insight, without having to bump logging throughout.

Marko Jordan's profile image
Marko Jordan posted 09-07-2023 04:42

Hi guys,

thank you for your suggestions, I've changed the logging settings based to your suggestions... unfortunately the problem is not with that specific transformation... I can run it seperatelly and it woukd be processed without any problem. If I run the whole process again imediatelly (the same dataset) and it would be processed successfully or it would stop in totally different step, different transformation... maybe I was not too clear about that.

My question is more focused into the PDI log, why there is no error logged regardless the logging level I try  (basic, detailed, debug). How can I troubleshoot the problem without any indication of the problem in the log?

Stephen Donovan's profile image
Stephen Donovan posted 09-07-2023 10:28

Marko,

You were quite clear prior.  It is interesting that it does not seem to be repeatable even at failure.  As you stated rerunning the same dataset may or may not result in error.  Since you are doing inserts and updates, the reprocessing of the same data intot he pipeline would change the flow (unless you clean the target prior).  Have you looked at something as simple as memory failures or noisy neighbor issues?

To be clear, the separation of the logs was to allow you to isolate the higher level logging in the case of that failure.  As was the error logging trap on the update.  As Antonio stated, the SQL Execute xstep and binding for a simple update may be failing quietly.  Hvae you changed over to the simple Update step?  Understanding that it might take some time to repeat the error, or confirm it is resolved.

Related Content