2 Replies Latest reply on Aug 17, 2018 5:17 AM by Marcel Drechsler

    Log NSH script job name for each line

    Marcel Drechsler

      We're heavily creating NSH script jobs automatically (through BRPM). To make troubleshooting easier, we want to integrate all logging output of those NSH script jobs into Elastic Stack. For being able to search for a specific Request (from BRPM) we need to have an unique key on each logging line.

       

      I already managed to configure the application server logging to log all NSH script job specific output to a certain logfile. Unfortunately I couldn't find any way to log out e.g. the job name for each line through log4j. Is there any way to do this?

       

      This here is an example output I have now:

       

      [12 Aug 2018 00:05:04,391] [Job-Execution-1] [BLAdmin:BLAdmins:] [NSHScript] Started running the job 'Dashboard Report Job' with priority 'NORMAL' on application server 'bsa-appserver'(2,000,000)

      [12 Aug 2018 00:05:04,438] [Job-Execution-1] [BLAdmin:BLAdmins:] [NSHScript] startExecution time for job 'Dashboard Report Job' was 48(ms)

      [12 Aug 2018 00:05:05,440] [WorkItem-Thread-2] [BLAdmin:BLAdmins:] [NSHScript] Executing work item NSH Script Job:Dashboard Report Job;  on application server: bsa-appserver

      [12 Aug 2018 00:05:05,767] [NSH-Exec-PID-15698-Output-stdout-Thread-53] [BLAdmin:BLAdmins:] [NSHScript] ScriptBasedJob: outData = Executing Dashboard Job...

      [12 Aug 2018 00:05:05,768] [NSH-Exec-PID-15698-Output-stdout-Thread-53] [BLAdmin:BLAdmins:] [NSHScript] ScriptBasedJob: outData = Executing Dashboard generation cli

      [12 Aug 2018 00:05:23,611] [NSH-Exec-PID-15698-Output-stdout-Thread-53] [BLAdmin:BLAdmins:] [NSHScript] ScriptBasedJob: outData = voidSuccessfully executed Dashboard job.

      [12 Aug 2018 00:05:23,623] [NSH-Exec-PID-15698-Output-stdout-Thread-53] [BLAdmin:BLAdmins:] [NSHScript] ScriptBasedJob: outData = Exit Code 0

      [12 Aug 2018 00:05:23,624] [NSH-Exec-PID-15698-Output-stdout-Thread-53] [BLAdmin:BLAdmins:] [NSHScript] ScriptBasedJob: set exit code for host "" exitcode 0

      [12 Aug 2018 00:05:23,629] [Job-Execution-4] [BLAdmin:BLAdmins:] [NSHScript] The job 'Dashboard Report Job' has succeeded

       

      What I would like to have would be something like the following:

       

      [12 Aug 2018 00:05:04,391] [Dashboard Report Job] [Job-Execution-1] [BLAdmin:BLAdmins:] [NSHScript] Started running the job 'Dashboard Report Job' with priority 'NORMAL' on application server 'bsa-appserver'(2,000,000)

      [12 Aug 2018 00:05:04,438] [Dashboard Report Job] [Job-Execution-1] [BLAdmin:BLAdmins:] [NSHScript] startExecution time for job 'Dashboard Report Job' was 48(ms)

      [12 Aug 2018 00:05:05,440] [Dashboard Report Job] [WorkItem-Thread-2] [BLAdmin:BLAdmins:] [NSHScript] Executing work item NSH Script Job:Dashboard Report Job;  on application server: bsa-appserver

      ...

        • 1. Re: Log NSH script job name for each line
          Bill Robinson
          I already managed to configure the application server logging to log all NSH script job specific output to a certain logfile.

          care to share how ?  other people might find that useful...  you should also be able to send it directly via syslog...

           

           

          in 8.9.2 or 3 there's more info in the logs:

          [16 Aug 2018 16:29:41,941] [Job-Execution-2] [INFO] [BLAdmin:BLAdmins:] [NSHScript] __JobRun-2001100,1-2004801__ Started running the job 'test1' with priority 'NORMAL' on application server 'blapp893.example.com'(2,000,000)

          [16 Aug 2018 16:29:43,028] [WorkItem-Thread-21] [INFO] [BLAdmin:BLAdmins:] [NSHScript] __JobRun-2001100,1-2004801__ Executing work item NSH Script Job:test1; Server:red7-893.example.com;  on application server: blapp893.example.com

          [16 Aug 2018 16:29:43,332] [WorkItem-Thread-21] [INFO] [BLAdmin:BLAdmins:] [NSHScript] __JobRun-2001100,1-2004801__ Executing command : /opt/bmc/bladelogic/appserver/NSH/bin/nsh --norc -c /opt/bmc/bladelogic/appserver/NSH/tmp/application_server/scripts/job__e1b5c535-63ab-4982-9aa6-9389108fb02e/master_14858761-14c6-4d22-81a7-b416ec5618bb

          [16 Aug 2018 16:29:43,395] [WorkItem-Thread-21] [INFO] [BLAdmin:BLAdmins:] [NSHScript] __JobRun-2001100,1-2004801__ Started pid 6415: /opt/bmc/bladelogic/appserver/NSH/bin/nsh --norc -c /opt/bmc/bladelogic/appserver/NSH/tmp/application_server/scripts/job__e1b5c535-63ab-4982-9aa6-9389108fb02e/master_14858761-14c6-4d22-81a7-b416ec5618bb

          [16 Aug 2018 16:29:43,832] [WaitForProcessThread-PID-6415-10] [INFO] [BLAdmin:BLAdmins:] [NSHScript] __JobRun-2001100,1-2004801__ Process finished: 6415

          [16 Aug 2018 16:29:43,850] [Job-Execution-4] [INFO] [BLAdmin:BLAdmins:] [NSHScript] __JobRun-2001100,1-2004801__ Execution Override not enabled for job 'test1' .

          [16 Aug 2018 16:29:43,852] [Job-Execution-4] [INFO] [BLAdmin:BLAdmins:] [NSHScript] __JobRun-2001100,1-2004801__ Full path to job 'test1' : 'Jobs/Workspace/NSH Script Jobs'

          [16 Aug 2018 16:29:43,858] [Job-Execution-4] [INFO] [BLAdmin:BLAdmins:] [NSHScript] __JobRun-2001100,1-2004801__ Job 'test1' was manually executed by User:Role 'BLAdmin':'BLAdmins'.

          [16 Aug 2018 16:29:43,858] [Job-Execution-4] [INFO] [BLAdmin:BLAdmins:] [NSHScript] __JobRun-2001100,1-2004801__ Debug mode is not enabled for job 'test1' .

          [16 Aug 2018 16:29:43,858] [Job-Execution-4] [INFO] [BLAdmin:BLAdmins:] [NSHScript] __JobRun-2001100,1-2004801__ The job 'test1' has succeeded

          so you have the jobrun id in there which will be unique.

          • 2. Re: Log NSH script job name for each line
            Marcel Drechsler

            Bill Robinson schrieb:

             

            I already managed to configure the application server logging to log all NSH script job specific output to a certain logfile.

            care to share how ?  other people might find that useful...  you should also be able to send it directly via syslog...

             

             

            Good point! I'm happy to share this. I've added the following lines to the log4j.properties in the appserver deployment:

             

            # custom logger

            log4j.logger.com.bladelogic.om.infra.model.job.script=DEBUG, NSHSCRIPTJOB

            log4j.additivity.com.bladelogic.om.infra.model.job.script=false

            log4j.appender.NSHSCRIPTJOB=org.apache.log4j.RollingFileAppender

            log4j.appender.NSHSCRIPTJOB.File=<path_to_logfile>/nshscript_job.log

            log4j.appender.NSHSCRIPTJOB.layout=org.apache.log4j.PatternLayout

            log4j.appender.NSHSCRIPTJOB.layout.ConversionPattern=[%d{DATE}] [%t] [%X{user}:%X{role}:%X{ip}] [%X{action}] %m%n

            log4j.appender.NSHSCRIPTJOB.MaxFileSize=20000KB

            log4j.appender.NSHSCRIPTJOB.MaxBackupIndex=5

             

            We're currently running version 8.6, which is pretty old. From my findings I think that the Thread-Id (e.g. NSH-Exec-PID-15698-Output-stdout-Thread-53) seems to be unique throughout the whole NSH-script run (which makes sense, I guess). I'll check if this is enough for identifying to which BRPM Request this script job relates to. Maybe we can map this value to previous custom logging output.