Site Network: Home | About

Showing posts with label bug. Show all posts
Showing posts with label bug. Show all posts

I was just going through Powercenter Monitor's help guide and noticed a page describing about the different possible statuses that a workflow or a task can be in at a given point in time. I found a status  called "Unknown Status" as one possbile status, and per guide here is when it can happen.


Unknown Status

Tasks The Integration Service cannot determine the status of the workflow or task, or the Integration Service does not respond to a ping from the Workflow Monitor. The status may be changing. For example, the status may have been Running but is changing to Stopping.


I felt this status is somewhat interesting and thought I should pay some attention. First possible cause (explained in help), failing to ping IS, is quite convincing. However, I am wondering why a workflow would take "Unknown Status" when it changes from  Running to Stopping like in the example explianed in second possible case. I guess if this has to fit in second case, that status would only for a very brief period - brief enough to change the  status from Running to Stopping for example. Please comment on this second point if someone has better idea.


I am posting this now because I have recently experience some other interesting scenario that lead a workflow to "Unknown Status". So, I thought it is worth sharing this experience...


Workflow changed to "Unknown Status" even before it started running. So, no workflow log file generated. Only next obvious source of information is IS log, and I found below entry (slightly modified as it is classified) in there...


From IS Log:


ERROR Wed Oct 7 00:55:09 2009 1409415520 LM_36317 Error in starting execution of workflow [id = 2651] [w_sales_fact].
ERROR Wed Oct 7 00:55:09 2009 1409415520 LM_36363 Workflow [w_sales_fact]: Cannot rename workflow log file [/opt/app/Informatica/pc/server/infa_shared/WorkflowLogs/w_orders_LOAD.log.bin] to [/opt/app/Informatica/pc/server/infa_shared/WorkflowLogs/w_orders_LOAD.log.1.bin].
INFO Wed Oct 7 00:55:01 2009 1409415520 LM_36814 Workflow [w_sales_fact]: Got scheduled request to start workflow.
INFO Wed Oct 7 00:55:01 2009 1398925664 LM_36814 Workflow [w_orders]: Got scheduled request to start workflow.
INFO Wed Oct 7 00:55:00 2009 183009705024 LM_36813 Workflow [w_sales_fact], run instance name [] is scheduled to run now, schedule last saved by user [karteek].
INFO Wed Oct 7 00:55:00 2009 1388435808 VAR_27029 Use persisted repository value [0] for user-defined workflow/worklet variable:[$$Load_Failed_ctr].
INFO Wed Oct 7 00:55:00 2009 1388435808 VAR_27029 Use persisted repository value [0] for user-defined workflow/worklet variable:[$$Is_LoadFailed].
INFO Wed Oct 7 00:55:00 2009 1388435808 VAR_27027 Use default value [] for user-defined workflow/worklet variable:[$$Delay].
INFO Wed Oct 7 00:55:00 2009 183009705024 LM_36813 Workflow [w_orders], run instance name [] is scheduled to run now, schedule last saved by user [karteek].



The reason it went into unknown status was that there were 2 workflows that were wrongly configured with a same log file name (w_orders_LOAD.log), and also scheduled for some time. At one point of time on thier schedule they were both initiated (acquired  the execution lock) and attempted to create their workflow log files. Unfortunately they were doing the write attempt on same file exactly at same time, and only one was through, but other was left in "Unknown Status".


This is very common thing that we as developers miss coding/naming standanrds, and here in Informaica chances would increase when we copy the same object and customize it for a different purpose. We overlook many things as  the original piece worked quite well. Here it exactly happened the same..."w_orders" was copied from "w_sales_fact" , but missed to change its "w_orders" workflow specific changes, and one such  change being the log file name. We corrected the log file name and fixed that problem forever for that workflow. But how many such other workflows with wrong log filenames was a question. So, I then did some research on Powercenter repository database, and wrote the below query. This basically searches wherever conflicts are there between workflow name and its log file name. You can change the log file name pattern below as per your naming standards.

select subject_area, task_name workflow_name, attr_value cur_log_name, task_name || '.log' new_log_name 
from infav8.rep_task_attr a, infav8.rep_all_tasks b
where attr_name = 'Workflow Log File Name'
and a.task_id = b.task_id
and a.version_number = b.version_number
and task_name || '.log' <> attr_value  -- change pattern in this line
order by 1, 2



Hope it helps!

Update 11/28/2009:
I have collected few more situations that can possibly turn a workflow's status into "Unknown Status".
  • When a PowerCenter repository have versioning enabled and a dependent activity is still checked out when scheduling the workflow - solve this by checking in all the dependent objects (from Informatica KB - ID: 100943)
  • There is a known issue (CR 182478) that has been fixed in PowerCenter 8.6, causing workflow to be in "Unknown Status". To resolve the issue, upgrade to PowerCenter 8.6. However, as a workaround in versions earlier than PowerCenter 8.6, set Save workflow log for these runs to zero (0) in workflow properties (ID: 106278).
Update 12/21/2009
When workflow parameter files is defined (in workflow properties), but if either parameter file is not present or no permissions  to read it, then also workflow goes into Unknown status (verified in 8.6). Error message would be like one below.

(my_is) Start task: ERROR: Workflow [wf_test]: Parameter file [/opt/app/Informatica/pc/server/infa_shared/SrcFiles/test.prm] not found. Please check the Integration Service log for more information.



Karteek

Last week, we were trying to bring an improvement in one of our ETL processes. Process is such that Hyperion cube’s load needs to started just after some ETL loads’ completion. Both Informatica and Hyperion are hosted on different servers, and both are Linux. So, there has to be some dependency established between ETL process on Informatica server and Cube load process so that Cube load gets kicked-off immediately after ETL finishes.

If you feel you do not have much time to conver the full details below, you directly skip to here as main purpose of this post is explain the difficultly I faced in using ssh from Informatica.

We could think of an approach where in trigger file (zero byte file) from ETL to notify Cubes’ load job. But this is very loosely coupled – ETL should either send the trigger on to Hyperion server and Cube load process that already started on Hyperion server should be waiting for the trigger to kick-off cubes load. There are some serious drawbacks in this approach -

Both ETL and Cubes’ load jobs should be scheduled on their servers – how does already started Cube load process know about ETL job failed and that current is ignored – fairly acceptable scenario, I believe. As a work around, Cube load job on Hyperion server can for defined time period, and it still doesn’t find trigger file then stop cubes load – some sort of workable, but still not good when schedule of ETL changed or ETL took longer period. (Trigger file released on to a shared file system instead of sftping is just nothing but a trigger file dependent)

A good possible workaround I could think of is an Enterprise Job Scheduler that reduces if not fully eliminates the process dependency barriers among the different servers. In addition to Informatica and Hyperion servers if there is another third server that controls Jobs on rest of the servers this issue is solved – Job scheduler to start the Cube load process only after ETL finishes.

But not every company uses a Job Server/Scheduler, unless the IT is relatively complex and value for money is not identified. My client is not using the Job scheduler, at least that I know of in their well matured BI department. Just because of some rare (at for them) benefits that Job Scheduler can bring, simply ignoring the classic scheduler that Informatica gives is also not good idea. So be with it.


At this point of time, only option I can think of is remote invocation of Cube load process on Hyperion server from Informatica server as part of its ETL itself – no it’s tightly coupled – process of Hyperion server doesn’t even start unless ETL finishes.

So, point is clear by now – I need to start the Cubes’ load process from Informatica, precisely through a command task calling a remote shell script. A code snippet is something like this…

ssh –q –l hyp01 hypsrvr ‘/opt/app/Hyperion/cube_load.ksh’

I noticed a weird behaviour of this process when it was invoked from Informatica 7.1. Even though cube_load.ksh process on Hyperion server is finished, process on Informatica 7.1 server still shows up in the process list (ps -f) forever, and so does in Informatica monitor. The very same command when executed directly on the server (from putty) worked fine. Even a simple ssh command for “date” gave the same result when ran from Informatica. For the first time I tried to use strace on the PID of ssh process, though not successfully – but that was showing only “select(16, [0 13], [], NULL, NULL” – still not helpful.

ssh –q –l hyp01 hypsrvr ‘date’
After breaking my head for couple of hours, I partially suspected pmserver process of Informatica 7.1 (which means Informatica 7.1 it self) which becomes parent process of every process (session, shell command, sql client or anything invoked by Informatica).

I then tried in our other upgraded environment Informatica 8.6 and that worked. I’m suspecting 7.1 has this bug fixed in later releases. I’m not confident enough to say that Informatica 7.1 has this bug, as Linux machine environment settings also a possible reason. So, I deeply appreciate sharing your similar experiences. This is our Informatica Linux server version.

With my boss help I tested rsh too instead ssh – we knew rsh was not the way to go due to the risks involved, we just gave a try and that worked in both 7.1 and 8.6 – only ssh had the problem.

$ uname -svm
Linux #1 SMP Wed Jul 12 23:36:53 EDT 2006 i686 

Something off the topic I learned from him was how to setup .rhosts for rsh. I knew already how to setup the similar for ssh (generating the public keys on client machine and them to host machine’s authorization keys file), but rsh too has some similarity in the setup. There are no encrypted keys generation required, but just adding the client user name in the remote machine’s HOME/.rhosts file and that works.

As I requested, please do share your experiences with Informatica and ssh together.

Karteek

There is some interesting behaviour that I noticed recently in Informatica's repository with respect to session's run time information. If you are not much comfortable with Informatica repository that I now I am going to explain about, here is some quick notes.

Informatica entire application lies on a data repository that consists of several tables (mostly start with OPB*). Perhaps in order to make an ease access to repository information, Informatica also provided several views based on the OPB tables. For many of the common questions you may want the answer REP views should help, bu there is always an exception and OPB tables are there. When you write queries on OPB tables take due care that you do not ruin database with bad joins - for this Informatica manual gives the columns that generally good candidates for joins when using REP views, but generally the same information applies to joining tables as well since a view is just a named query. Some useful views are... REP_WORKFLOWS - Workflow master list REP_WFLOW_RUN - Worklow run time details REP_ALL_TASKS - Master task list REP_TASK_INST_RUN - Task level run time details REP_SESS_LOG - Session's Success/Failed records etc...

With those details, let me explain the what the prob

em is in 7.1. Workflow_Run_ID uniquely identifies each run of a workflow - means when a workflows starts (starting part of the workflow or full workflow or a schedule run) it would have a new workflow_run_id.

For suspended workflow (enabled "Suspend on Failure"), common way we recover it is by resuming it after the fix is provided (in 8.6 option name is "Recover"), and resuming it obviously not a new run so doesn't carry a new worklflow_run_id after resumed. It also means that there would not be a new entry into REP_WFLOW_RUN (or OPB_WFLOW_RUN table) when a workflow is resumed.

Moving a little back, a workflow goes to suspended state when it's meant to fail by the configuration of underlying tasks - means when underlying task fails that makes it's parent (or workflow in a simple setup) to fail and so workflow suspends. So, when such suspended workflow is resumed that actually restarts the failed tasks in the run. I noticed, in 7.1, even though resuming does not create a new workflow_run_id, tasks that restarts when its parent workflow is resumed would create new entries in REP_TASK_INST_RUN. That might be for good reason, but I see that of not much help rather misleading as there is no column that distinguishes task restarts (start_time of task can give that info, but that's not a good candidate).

Moreover, Informatica 7.1 behaves badly in maintaining information in those records - if a task is failed, say 3 times, when resumed multiple times, and finally succeeded in 4th attempt, then all the 4 records of that task run would get updated with last run information (except start_time that I identified) - end_time, error_code etc...and I would say this is completely misleading. Similar behaviour can be noticed in other tables/views that stores the task level run time information like REP_SESS_LOG (OPB_SESS_LOG).

If you run this below query on 7.1 repository you would notice some records being fetched (provided there was atleast one attempt of resuming a suspended workflow)

select workflow_run_id, instance_id, count(*)
from infav71.rep_task_inst_run
group by workflow_run_id, instance_id
having count(*) > 1
Even more dangerous part is with the views that joins OPB_TASK_INST_RUN and OPB_SESS_LOG tables. As I said, there is no good candidate in those tables to identify the multiple task (or instance to be precise) runs when suspended workflow is resumed, joining these 2 tables would make cartesian product - means 4 entries in both these 2 tables would return 8 records - that's a flaw, and you can notice that in 7.1.
select * from infa71.OPB_TASK_INST_RUN     where INSTANCE_ID = 18738 and WORKFLOW_RUN_ID = 7113806;

SUBJECT_ID    WORKFLOW_ID    WORKFLOW_RUN_ID    WORKLET_RUN_ID    CHILD_RUN_ID    INSTANCE_ID    INSTANCE_NAME    TASK_NAME    TASK_ID    TASK_TYPE    START_TIME    END_TIME    RUN_ERR_CODE    RUN_ERR_MSG    RUN_STATUS_CODE    RUN_MODE    VERSION_NUMBER    SERVER_ID    SERVER_NAME
48    13707    7113806    7113823    0    18738    s_m_test    s_m_test    20461    68    8/24/2009 2:00    8/24/2009 2:00    0        1    1    1    1    TEST_SRVR
48    13707    7113806    7113823    0    18738    s_m_test    s_m_test    20461    68    8/24/2009 1:47    8/24/2009 2:00    0        1    1    1    1    TEST_SRVR
48    13707    7113806    7113823    0    18738    s_m_test    s_m_test    20461    68    8/24/2009 1:14    8/24/2009 2:00    0        1    1    1    1    TEST_SRVR
48    13707    7113806    7113823    0    18738    s_m_test    s_m_test    20461    68    8/24/2009 0:52    8/24/2009 2:00    0        1    1    1    1    TEST_SRVR
48    13707    7113806    7113823    0    18738    s_m_test    s_m_test    20461    68    8/24/2009 0:17    8/24/2009 2:00    0        1    1    1    1    TEST_SRVR
48    13707    7113806    7113823    0    18738    s_m_test    s_m_test    20461    68    8/24/2009 0:02    8/24/2009 2:00    0        1    1    1    1    TEST_SRVR

If you look at the above result only start_time is differing, and values of older runs are updated to last run values (error_code, end_time etc... though they have different values from run to run)

Looks like it's fixed in 8.6 - I did not test in version between 7.1 and 8.6 though. In 8.6 however number of resuming of a suspended workflow may be, a failed task instance would have only one run per workflow_run_id. This is much better, rather misleading with more information. if you run the first group by query in your 8.6 repository, you should not be getting any records at all.

select workflow_run_id, instance_id, count(*)
from infav88.rep_task_inst_run
group by workflow_run_id, instance_id
having count(*) > 1
0 row(s) retrieved

Hope that helps.

I appreciate your comments... Thanks!

Karteek