GrailsFlow

Improve logging for process execution, use correct logger names

Details

  • Type: Sub-task Sub-task
  • Status: Closed Closed
  • Priority: Major Major
  • Resolution: Fixed
  • Affects Version/s: 1.0
  • Fix Version/s: 1.0.12
  • Component/s: None
  • Labels:
    None
  • Request Controller:
    Please Select
  • External Supervisor:
    Please select
  • Executing Programmer:
    Antonicheva, July
  • Estimated Hours:
    10
  • Ext Project Id:
    JCGFW-01

Description

1) Node Activator logs like this:
2011-12-14 20:07:26,861 [quartzScheduler_Worker-9] INFO (grails.app.task.NodeActivatorJob) - *** Amount of Nodes to execute 1 ***
2011-12-14 20:07:26,913 [quartzScheduler_Worker-9] DEBUG (java.lang.Class) - Invoking asynchronous node publishToOPC of process 200278
2011-12-14 20:07:26,913 [quartzScheduler_Worker-9] DEBUG (java.lang.Class) - Invoking asynchronous node publishToOPC of process #200278
2011-12-14 20:07:26,913 [quartzScheduler_Worker-9] DEBUG (java.lang.Class) - Node publishToOPC of process #200278 is already running
2011-12-14 20:07:26,913 [quartzScheduler_Worker-9] DEBUG (java.lang.Class) - Node publishToOPC of process #200278 is invoked

Seems the first two identical except # sign before process id. Do we need both?
"is already running" and "is invoked" are contradicting. Not clear to me whether the node was successfully started.
Does it make sense to include the worker thread id of the thread that is going to execute the node?
java.lang.Class is the wrong logger here. If this is NodeActivator, then the correct logger needs to be selected, otherwise we can't
control log level and it is also very confusing (should be clarified)

2) Wrong logger / Thread name bad / Typo:
2011-12-14 20:07:28,203 [pool-12552-thread-1] INFO (java.lang.Class) - Finished execution helper.SaveCatalogExternalParametersHLAction. Total Memory: 14404 MB; used: 7771 MB free: 6632 MB. Execution time: 0:02:59.626

use correct logger. It needs to indicate what class/script created the output
use better thread names: pool-12552-thread-1 is really bad. If this is a grailsflow thread pool, give it decent names like
node-processor-1, node-processor-2 etc.
Use correct writing style. Full stop ('.') is followed by white space before next sentence

3) Duplicate entries:
2011-12-14 20:07:29,896 [quartzScheduler_Worker-7] DEBUG (com.jcatalog.grailsflow.engine.GrailsflowCachingProcessFactory) - Process class for process type CustomerActivateWorklow loaded from cache
2011-12-14 20:07:30,001 [quartzScheduler_Worker-7] DEBUG (com.jcatalog.grailsflow.engine.GrailsflowCachingProcessFactory) - Process class for process type CustomerActivateWorklow loaded from cache

check if operation performed twice. If yes, why? Is it required? Fix

4) Process not included
2011-12-14 20:11:54,269 [pool-12557-thread-1] INFO (grails.app.service.ProcessManagerService) - Executing node approvalLevel1

  • not clear which process the node belongs to, include processid

Activity

Hide
Antonicheva, July added a comment - 31/Jan/12 1:02 PM - edited

Changes for logging were implemented. Thread prefix was updated from

 [pool-poolNumber-thread-threadNumber] 
to
 [${process?.id}(${process?.type})-${node.nodeID}] 
.
Point 3 - the message isn't duplicated in code and operation isn't performed twice. The message displayed every time when we get process class instance from cache. For example after we press 'start process' link for any process type, we get this message at least 4 times in log:

  • for validation in process class validator(ProcessManagementController);
  • for checking unique identifier(ProcessManagementController);
  • for starting basic process instance (ProcessManagementService);
  • for preparing process details (redirect to process details page after starting);
Show
Antonicheva, July added a comment - 31/Jan/12 1:02 PM - edited Changes for logging were implemented. Thread prefix was updated from
 [pool-poolNumber-thread-threadNumber] 
to
 [${process?.id}(${process?.type})-${node.nodeID}] 
. Point 3 - the message isn't duplicated in code and operation isn't performed twice. The message displayed every time when we get process class instance from cache. For example after we press 'start process' link for any process type, we get this message at least 4 times in log:
  • for validation in process class validator(ProcessManagementController);
  • for checking unique identifier(ProcessManagementController);
  • for starting basic process instance (ProcessManagementService);
  • for preparing process details (redirect to process details page after starting);
Hide
Antonicheva, July added a comment - 31/Jan/12 1:36 PM

Done. Please check changes.

Show
Antonicheva, July added a comment - 31/Jan/12 1:36 PM Done. Please check changes.
Hide
Shwedovsky, Dmitry added a comment - 15/Feb/12 2:28 PM

Logging of process execution checked.

Show
Shwedovsky, Dmitry added a comment - 15/Feb/12 2:28 PM Logging of process execution checked.

People

Vote (0)
Watch (0)

Dates

  • Created:
    05/Jan/12 7:13 AM
    Updated:
    24/Feb/12 8:41 AM
    Resolved:
    24/Feb/12 8:41 AM