Highlighted
Super Contributor.. Super Contributor..
Super Contributor..
832 views

Missing SCANNER_EXCLUSIVE_LOCK on node

Jump to solution

Hi:

We have some unfinished InventoryByDiscoveryScanner jobs. Investigating this issue we have seen that many workflows not found the SCANNER_EXCLUSIVE_LOCK on the node.

For example a node which is automatically start the InventoryDiscoveryByScanner at 09:00 runs fine, but at 09:35 the workflows fails on the step "Check Scanner Finished" because they havent fount the lock on scanner node. (The workflow tries to check again and again with no lucky)

<log start="09:35:56" severity="debug">Lock on scanner node for probe "172.24.7.66" and job "MZ_ONCE_Andalucia_Escaner_InventoryDiscoveryWizard_Inventory Discovery by Scanner" is not exists</log>
 <log start="09:35:56" severity="debug">Lock is not owned by this probe/job or expired.</log>
 <log start="09:35:56" severity="workflow-debug">step Check Scanner Finished finished execution with status: FAILURE. triggerCI: 40b4f05101aa7e93b78b3692de9d3e70</log>
 <log start="09:35:56" severity="workflow-debug">step Check Scanner Finished execution failed. triggerCI: 40b4f05101aa7e93b78b3692de9d3e70</log>

 

The lock exist on the node shortly after the workflow runs the "Run Scanner" step.

 <log start="09:03:39" severity="debug">Extracting lock from 172.24.7.66\\\___\\\0\\\___\\\MZ_ONCE_Andalucia_Escaner_InventoryDiscoveryWizard_Inventory Discovery by Scanner\\\___\\\1539587008791\\\___\\\1539673408791</log>
 <log start="09:03:39" severity="debug">Found remote lock:172.24.7.66\\\___\\\0\\\___\\\MZ_ONCE_Andalucia_Escaner_InventoryDiscoveryWizard_Inventory Discovery by Scanner\\\___\\\1539587008791\\\___\\\1539673408791</log>
 <log start="09:03:39" severity="debug">Checking lock expiration. Lock expiration time:1539673408791, compare time:1539587019854</log>
 <log start="09:03:39" severity="debug">Comparing locks.</log>
 <log start="09:03:39" severity="debug">This lock:172.24.7.66\\\___\\\0\\\___\\\MZ_ONCE_Andalucia_Escaner_InventoryDiscoveryWizard_Inventory Discovery by Scanner\\\___\\\1539587019807\\\___\\\1539673419807</log>
 <log start="09:03:39" severity="debug">Compared lock:172.24.7.66\\\___\\\0\\\___\\\MZ_ONCE_Andalucia_Escaner_InventoryDiscoveryWizard_Inventory Discovery by Scanner\\\___\\\1539587008791\\\___\\\1539673408791</log>

But, for some reason the lock on the node dissapear and causes the workflows to run the "Check Scanner Finished" step again and again, because he can't find the lock.

Of course, no changes had made to the node during the scanner.

 

Any ideas?
 

0 Likes
1 Solution

Accepted Solutions
Highlighted
Acclaimed Contributor.
Acclaimed Contributor.

Re: Missing SCANNER_EXCLUSIVE_LOCK on node

Jump to solution

The process is exactly as you described it. The step 

CHECK SCAN FILE EXISTENCE:
============================

At this step the time was 07:03:39 UTC

shoult NOT create a new lock timestamp. When it does that, it seems to be a bug.

The other misleading clue is the message

log start="09:35:56" severity="debug">Lock on scanner node for probe "172.24.7.66" and job "MZ_ONCE_Andalucia_Escaner_InventoryDiscoveryWizard_Inventory Discovery by Scanner" is not exists</log>

Because you trust the message as the lock is not there, but one line after it, it says that the lock exists, but is not matching the timestamp recorded on the probe (the one created at 07:03:39 vs the one at 07:03:28). 

If you are not using the latest CP, I strongly recommend you upgrading to it and check if this issue is fixed. Each CP comes with ton of bugfixes on the discovery scripts.

Petko

Likes are appreciated!

View solution in original post

7 Replies
Highlighted
Acclaimed Contributor.
Acclaimed Contributor.

Re: Missing SCANNER_EXCLUSIVE_LOCK on node

Jump to solution

Hi, 

it looks like you are scanning the servers from several independent UCMDBs. Do you have Dev,Test environments with the same scheduling?

Cheers,

Petko Popadiyski

Freelance Microfocus CMS UCMDB Consulting

Likes are appreciated!
0 Likes
Highlighted
Super Contributor.. Super Contributor..
Super Contributor..

Re: Missing SCANNER_EXCLUSIVE_LOCK on node

Jump to solution

Hello popadiyski:

We only have one UCMDB and two attached probes (for differente IP ranges).

 

Thanks.

 

0 Likes
Highlighted
Acclaimed Contributor.
Acclaimed Contributor.

Re: Missing SCANNER_EXCLUSIVE_LOCK on node

Jump to solution

what I see is that you have executed the job Inventory Scanner for the server twice in fast sequence - first time 0n 7:03:28 GMT, and the second time 7:03:39. The cause may be that you have a node duplication in the UCMDB and the scanner is executed twice when you retrigger the job. Another option I can think of is you have several IPs you can access the same server.

What you have to figure out is which trigger CI executed the job at 7:03:28 

Petko

Likes are appreciated!
Highlighted
Super Contributor.. Super Contributor..
Super Contributor..

Re: Missing SCANNER_EXCLUSIVE_LOCK on node

Jump to solution

Only 1 job is executed against the node.

I attached the completely log. We see the diferent steps of the workflow:

 

REMOVE LOCAL SCAN LOG FILE:

<log start="09:03:25" severity="debug">Starting [Remove Local Scan Log File] step. Requires connect:0, requires lock:0, disconnect on failure1</log>
<log start="09:03:25" severity="workflow-debug">step Remove Local Scan Log File finished execution with status: SUCCESS. triggerCI: 40b4f05101aa7e93b78b3692de9d3e70</log>

SCANNER CONNECT:

 <log start="09:03:25" severity="debug">Starting [Scanner Connect] step. Requires connect:1, requires lock:0, disconnect on failure1</log>
<log start="09:03:28" severity="workflow-debug">step Scanner Connect finished execution with status: SUCCESS. triggerCI: 40b4f05101aa7e93b78b3692de9d3e70</log>

AGENT DRIVEN MODE CHECK:

<log start="09:03:28" severity="debug">Starting [Agent Driven Mode Check] step. Requires connect:1, requires lock:0, disconnect on failure1</log>
<log start="09:03:28" severity="workflow-debug">step Agent Driven Mode Check finished execution with status: SUCCESS. triggerCI: 40b4f05101aa7e93b78b3692de9d3e70</log>

LOCK SCANNER NODE:

<log start="09:03:28" severity="debug">Starting [Lock Scanner Node] step. Requires connect:1, requires lock:0, disconnect on failure1</log>
<log start="09:03:28" severity="workflow-debug">step Lock Scanner Node finished execution with status: SUCCESS. triggerCI: 40b4f05101aa7e93b78b3692de9d3e70</log>

UD UNIQUE ID CHECK:

<log start="09:03:28" severity="debug">Starting [UD Unique ID check] step. Requires connect:1, requires lock:1, disconnect on failure1</log>
<log start="09:03:28" severity="workflow-debug">step UD Unique ID check finished execution with status: SUCCESS. triggerCI: 40b4f05101aa7e93b78b3692de9d3e70</log>

CHECK SCAN FILE EXISTENCE

<log start="09:03:29" severity="debug">Starting [Check Scan File Existence] step. Requires connect:1, requires lock:1, disconnect on failure1</log>
<log start="09:03:29" severity="workflow-debug">step Check Scan File Existence finished execution with status: SUCCESS. triggerCI: 40b4f05101aa7e93b78b3692de9d3e70</log>

UPGRADE SCANNER:

<log start="09:03:29" severity="debug">Starting [Upgrade Scanner] step. Requires connect:1, requires lock:1, disconnect on failure1</log>
<log start="09:03:38" severity="workflow-debug">step Upgrade Scanner finished execution with status: SUCCESS. triggerCI: 40b4f05101aa7e93b78b3692de9d3e70</log>

RUN SCANNER:

<log start="09:03:38" severity="debug">Starting [Run Scanner] step. Requires connect:1, requires lock:1, disconnect on failure1</log>
<log start="09:03:39" severity="workflow-debug">step Run Scanner finished execution with status: SUCCESS. triggerCI: 40b4f05101aa7e93b78b3692de9d3e70</log>

CHECK SCANNER FINISHED:

**The 1st attempt is normally FAILURE because the scanner did not finished

<log start="09:03:39" severity="debug">Starting [Check Scanner Finished] step. Requires connect:1, requires lock:1, disconnect on failure1</log>
<log start="09:03:39" severity="workflow-debug">step Check Scanner Finished finished execution with status: FAILURE. triggerCI: 40b4f05101aa7e93b78b3692de9d3e70</log>
<log start="09:03:39" severity="workflow-debug">step Check Scanner Finished execution failed - go to TIMEOUT parking to:300000 millis, on retry:1. triggerCI: 40b4f05101aa7e93b78b3692de9d3e70

**At the 1st retry of Check Scanner Finished is when the workflow doesn't found the lock on node (the scanner finished on the node)

<log start="09:35:54" severity="debug">Starting [Check Scanner Finished] step. Requires connect:1, requires lock:1, disconnect on failure1</log>
<log start="09:35:56" severity="debug">Lock on scanner node for probe "172.24.7.66" and job "MZ_ONCE_Andalucia_Escaner_InventoryDiscoveryWizard_Inventory Discovery by Scanner" is not exists</log>
 <log start="09:35:56" severity="debug">Lock is not owned by this probe/job or expired.</log>
<log start="09:35:56" severity="workflow-debug">step Check Scanner Finished finished execution with status: FAILURE. triggerCI: 40b4f05101aa7e93b78b3692de9d3e70</log>

** The Check Scanner Finished retries again and again with the same result of the first attempt (the lock on scanner node in not exist)

 

Thanks.

0 Likes
Highlighted
Acclaimed Contributor.
Acclaimed Contributor.

Re: Missing SCANNER_EXCLUSIVE_LOCK on node

Jump to solution

So lock was successfully created at 07:03:28 (1539587008791), but for some reason on the result check, the probe is looking for a lock created at 07:03:39 (1539673419807). This looks like a bug to me. Does it happen on certain occasions, OSes?

If possible, test with the latest CP as well.

Likes are appreciated!
0 Likes
Highlighted
Super Contributor.. Super Contributor..
Super Contributor..

Re: Missing SCANNER_EXCLUSIVE_LOCK on node

Jump to solution

I guess that the probe sets the lock on the node when the step "Lock Scanner Node" runs. (in this node was at 07:03:28 UTC or 1539587008791)

<log start="09:03:28" severity="debug">Starting [Lock Scanner Node] step. Requires connect:1, requires lock:0, disconnect on failure1</log>
<log start="09:03:28" severity="debug">Trying to lock node with value:172.24.7.66\\\___\\\0\\\___\\\MZ_ONCE_Andalucia_Escaner_InventoryDiscoveryWizard_Inventory Discovery by Scanner\\\___\\\1539587008791\\\___\\\1539673408791</log>

 

In the other future steps, the probe compares the actual lock of the current step with the lock of the node. If the actual lock of the current step is more newer than the lock of the node and it's not expired the process continues.

 

CHECK SCAN FILE EXISTENCE:
============================

At this step the time was 07:03:39 UTC and the created lock was 1539587019807


<log start="09:03:39" severity="debug">This lock:172.24.7.66\\\___\\\0\\\___\\\MZ_ONCE_Andalucia_Escaner_InventoryDiscoveryWizard_Inventory Discovery by Scanner\\\___\\\1539587019807\\\___\\\1539673419807</log>

The lock of the current step compares to the lock of the node (07:03:28 UTC or 1539587008791)


<log start="09:03:39" severity="debug">Compared lock:172.24.7.66\\\___\\\0\\\___\\\MZ_ONCE_Andalucia_Escaner_InventoryDiscoveryWizard_Inventory Discovery by Scanner\\\___\\\1539587008791\\\___\\\1539673408791</log>

The lock of the current step is newer than the lock of the node, so the step continues with the process.

 

I guess this is the normal behaviour. For other steps the probe always tries to find the lock of the node and this is when i find the problem.

 

At 07:35:56 UTC (1539588956935) the step "Check Scanner Finished" runs again and the probe creates a new lock based on current time:

<log start="09:35:56" severity="debug">Checking remote lock with current lock:172.24.7.66\\\___\\\0\\\___\\\MZ_ONCE_Andalucia_Escaner_InventoryDiscoveryWizard_Inventory Discovery by Scanner\\\___\\\1539588956935\\\___\\\1539675356935</log>

And when it tries to find the lock of the node it fails, because the lock of the node wasn't found.

<log start="09:35:56" severity="debug">Lock on scanner node for probe "172.24.7.66" and job "MZ_ONCE_Andalucia_Escaner_InventoryDiscoveryWizard_Inventory Discovery by Scanner" is not exists</log>
<log start="09:35:56" severity="debug">Lock is not owned by this probe/job or expired.</log>

 

This is the primary question. Why the lock of the node is missing?
It is assumed that the lock of the node don't dissapear until the "Unlock Sanner node" runs, because this step is responsible for delete the lock of the node.
So, if the lock of the node don't exist, the workflow runs again and again the "Check Scanner Finished" step. The timeout between the retries increases more and more.

 

In my case it happens only on certains occassions, all my nodes are Windows.

 

0 Likes
Highlighted
Acclaimed Contributor.
Acclaimed Contributor.

Re: Missing SCANNER_EXCLUSIVE_LOCK on node

Jump to solution

The process is exactly as you described it. The step 

CHECK SCAN FILE EXISTENCE:
============================

At this step the time was 07:03:39 UTC

shoult NOT create a new lock timestamp. When it does that, it seems to be a bug.

The other misleading clue is the message

log start="09:35:56" severity="debug">Lock on scanner node for probe "172.24.7.66" and job "MZ_ONCE_Andalucia_Escaner_InventoryDiscoveryWizard_Inventory Discovery by Scanner" is not exists</log>

Because you trust the message as the lock is not there, but one line after it, it says that the lock exists, but is not matching the timestamp recorded on the probe (the one created at 07:03:39 vs the one at 07:03:28). 

If you are not using the latest CP, I strongly recommend you upgrading to it and check if this issue is fixed. Each CP comes with ton of bugfixes on the discovery scripts.

Petko

Likes are appreciated!

View solution in original post

The opinions expressed above are the personal opinions of the authors, not of Micro Focus. By using this site, you accept the Terms of Use and Rules of Participation. Certain versions of content ("Material") accessible here may contain branding from Hewlett-Packard Company (now HP Inc.) and Hewlett Packard Enterprise Company. As of September 1, 2017, the Material is now offered by Micro Focus, a separately owned and operated company. Any reference to the HP and Hewlett Packard Enterprise/HPE marks is historical in nature, and the HP and Hewlett Packard Enterprise/HPE marks are the property of their respective owners.