Bug 1369895

Summary: SmartState Analysis failed on the Windows instances from Azure providers
Product: Red Hat CloudForms Management Engine Reporter: Hui Song <hsong>
Component: SmartState AnalysisAssignee: Hui Song <hsong>
Status: CLOSED NOTABUG QA Contact: Jeff Teehan <jteehan>
Severity: high Docs Contact:
Priority: high    
Version: 5.6.0CC: cpelland, hsong, jhardy, jkeselma, jteehan, obarenbo, sbulage
Target Milestone: GAKeywords: ZStream
Target Release: 5.7.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard: provider:azure:ssa
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1370571 (view as bug list) Environment:
Last Closed: 2016-08-31 14:57:16 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Bug Depends On:    
Bug Blocks: 1337693, 1370571    

Description Hui Song 2016-08-24 15:56:52 UTC 
Description of problem:

To improve the IO performance during scanning, the disk cache is introduced. It caused some disk related information was missed during filesystem parsing.


Version-Release number of selected component (if applicable):
5.6.1.2.20160810181333_8ba817b

How reproducible:


Steps to Reproduce:
1. Choose the instance with Windows on it from Azure provider;
2. run SSA
3.

Actual results:

[----] D, [2016-08-22T10:05:06.630147 #53692:5c998c] DEBUG -- : MiqDiskCache.d_read_cached(1006272, 8)
[----] I, [2016-08-22T10:05:06.631633 #53692:5c998c]  INFO -- : Registry Parsing time = 4.423949713 sec.  registry segments loaded:[9]
[----] D, [2016-08-22T10:05:06.631733 #53692:5c998c] DEBUG -- : Hive parsing complete in [43.132754495] seconds
[----] D, [2016-08-22T10:05:06.631940 #53692:5c998c] DEBUG -- : WinMount.fs_init: [da[:serial_num]}-da[:starting_sector] = [1540044740-2048]
[----] D, [2016-08-22T10:05:06.632048 #53692:5c998c] DEBUG -- : WinMount.fs_init: [da[:serial_num]}-da[:starting_sector] = [3978295140-2048]
[----] D, [2016-08-22T10:05:06.632163 #53692:5c998c] DEBUG -- : WinMount.fs_init: @rootDriveLetter = idToDriveLetter[3340944128-2048] =
[----] E, [2016-08-22T10:05:06.632308 #53692:5c998c] ERROR -- : Unable to mount filesystem.  Reason:[Could not determine root drive letter.] for VM []
[----] D, [2016-08-22T10:05:06.632576 #53692:5c998c] DEBUG -- : MIQExtract.new /var/www/miq/vmdb/gems/pending/fs/modules/WinMount.rb:41:in `fs_init'
[----] D, [2016-08-22T10:05:06.632658 #53692:5c998c] DEBUG -- : MIQExtract.new /var/www/miq/vmdb/gems/pending/fs/MiqFS/MiqFS.rb:41:in `initialize'
[----] D, [2016-08-22T10:05:06.632727 #53692:5c998c] DEBUG -- : MIQExtract.new /var/www/miq/vmdb/gems/pending/fs/MiqMountManager.rb:41:in `initialize'
[----] D, [2016-08-22T10:05:06.632793 #53692:5c998c] DEBUG -- : MIQExtract.new /var/www/miq/vmdb/gems/pending/fs/MiqMountManager.rb:20:in `new'
[----] D, [2016-08-22T10:05:06.632856 #53692:5c998c] DEBUG -- : MIQExtract.new /var/www/miq/vmdb/gems/pending/fs/MiqMountManager.rb:20:in `block in mountVolumes'
[----] D, [2016-08-22T10:05:06.632920 #53692:5c998c] DEBUG -- : MIQExtract.new /var/www/miq/vmdb/gems/pending/fs/MiqMountManager.rb:11:in `each'
[----] D, [2016-08-22T10:05:06.632983 #53692:5c998c] DEBUG -- : MIQExtract.new /var/www/miq/vmdb/gems/pending/fs/MiqMountManager.rb:11:in `mountVolumes'
[----] D, [2016-08-22T10:05:06.633046 #53692:5c998c] DEBUG -- : MIQExtract.new /var/www/miq/vmdb/gems/pending/MiqVm/MiqVm.rb:167:in `rootTrees'


Expected results:

SSA complete successfully.


Additional info:

After providing the missing information for parsing filesystem (https://bugzilla.redhat.com/show_bug.cgi?id=1369886), SSA still failed. During the scanning, the whole appliance lost the connection from UI. The error message was:

[----] E, [2016-08-24T09:49:24.278070 #23772:90b988] ERROR -- : Q-task_id([04b6aad6-69fe-11e6-a89a-00155d06ac23]) MIQ(VmScan#process_abort) job aborting, scan operation yielded no data. aborting
[----] I, [2016-08-24T09:49:24.308660 #15335:90b988]  INFO -- : MIQ(MiqQueue#delivered) Message id: [811000000214832], State: [ok], Delivered in [209.054648984] seconds
[----] I, [2016-08-24T09:49:24.312240 #23772:90b988]  INFO -- : Q-task_id([04b6aad6-69fe-11e6-a89a-00155d06ac23]) MIQ(VmScan#process_finished) job finished, scan operation yielded no data. aborting
[----] I, [2016-08-24T09:49:24.330848 #23772:90b988]  INFO -- : Q-task_id([04b6aad6-69fe-11e6-a89a-00155d06ac23]) MIQ(VmScan#dispatch_finish) Dispatch Status is 'finished'
[

Also there were many errors about powershell parsing errors:

[----] E, [2016-08-24T03:28:00.954231 #60464:90b988] ERROR -- : <SCVMM> MIQ(Class#log_dos_error_results) #< CLIXML^M
<Objs Version="1.1.0.1" xmlns="http://schemas.microsoft.com/powershell/2004/04"><S S="Error">Select : Cannot process argument because the value of argument "obj" is null. _x000D__x000A_</S><S S="Error">Change the value of argument "obj" to a non-null value._x000D__x000A_</S><S S="Error">At line:13 char:48_x000D__x000A_</S><S S="Error">+     $vm_hash["DVDs"] = @($_.VirtualDVDDrives | Select -Expand ISO | Select _x000D__x000A_</S><S S="Error">-Prop ..._x000D__x000A_</S><S S="Error">+                                                ~~~~~~~~~~~~~~~~~~_x000D__x000A_</S><S S="Error">    + CategoryInfo          : InvalidArgument: (:) [Select-Object], PSArgument _x000D__x000A_</S><S S="Error">   NullException_x000D__x000A_</S><S S="Error">    + FullyQualifiedErrorId : ArgumentNull,Microsoft.PowerShell.Commands.Selec _x000D__x000A_</S><S S="Error">   tObjectCommand_x000D__x000A_</S><S S="Error"> _x000D__x000A_</S><S S="Error">Select : Cannot process argument because the value of argument "obj" is null. _x000D__x000A_</S><S S="Error">Change the value of argument "obj" to a non-null value._x000D__x000A_</S><S S="Error">At line:13 char:48_x000D__x000A_</S><S S="Error">+     $vm_hash["DVDs"] = @($_.VirtualDVDDrives | Select -Expand ISO | Select _x000D__x000A_</S><S S="Error">-Prop ..._x000D__x000A_</S><S S="Error">+                                                ~~~~~~~~~~~~~~~~~~_x000D__x000A_</S><S S="Error">    + CategoryInfo          : InvalidArgument: (:) [Select-Object], PSArgument _x000D__x000A_</S><S S="Error">   NullException_x000D__x000A_</S><S S="Error">    + FullyQualifiedErrorId : ArgumentNull,Microsoft.PowerShell.Commands.Selec _x000D__x000A_</S><S S="Error">   tObjectCommand_x000D__x000A_</S><S S="Error"> _x000D__x000A_</S><S S="Error">Select : Cannot process argument because the value of argument "obj" is null. _x000D__x000A_</S><S S="Error">Change the value of argument "obj" to a non-null value._x000D__x000A_</S><S S="Error">At line:13 char:48_x000D__x000A_</S><S S="Error">+     $vm_hash["DVDs"] = @($_.VirtualDVDDrives | Select -Expand ISO | Select _x000D__x000A_</S><S S="Error">-Prop ..._x000D__x000A_</S><S S="Error">+                                                ~~~~~~~~~~~~~~~~~~_x000D__x000A_</S><S S="Error">    + CategoryInfo          : InvalidArgument: (:) [Select-Object], PSArgument _x000D__x000A_</S><S S="Error">   NullException_x000D__x000A_</S><S S="Error">    + FullyQualifiedErrorId : ArgumentNull,Microsoft.PowerShell.Commands.Selec _x000D__x000A_</S><S S="Error">   tObjectCommand_x000D__x000A_</S><S S="Error"> _x000D__x000A_</S><S S="Error">Select : Cannot process argument because the value of argument "obj" is null. _x000D__x000A_</S><S S="Error">Change the value of argument "obj" to a non-null value._x000D__x000A_</S><S S="Error">At line:13 char:48_x000D__x000A_</S><S S="Error">+     $vm_hash["DVDs"] = @($_.VirtualDVDDrives | Select -Expand ISO | Select _x000D__x000A_</S><S S="Error">-Prop ..._x000D__x000A_</S><S S="Error">+                                                ~~~~~~~~~~~~~~~~~~_x000D__x000A_</S><S S="Error">    + CategoryInfo          : InvalidArgument: (:) [Select-Object], PSArgument _x000D__x000A_</S><S S="Error">   NullException_x000D__x000A_</S><S S="Error">    + FullyQualifiedErrorId : ArgumentNull,Microsoft.PowerShell.Commands.Selec _x000D__x000A_</S><S S="Error">   tObjectCommand_x000D__x000A_</S><S S="Error"> _x000D__x000A_</S><S S="Error">Select : Cannot process argument because the value of argument "obj" is null. _x000D__x000A_</S><S S="Error">Change the value of argument "obj" to a non-null value._x000D__x000A_</S><S S="Error">At line:28 char:47_x000D__x000A_</S><S S="Error">+     $i_hash["DVDs"] = @($_.VirtualDVDDrives | Select -Expand ISO | Select _x000D__x000A_</S><S S="Error">-Prope ..._x000D__x000A_</S><S S="Error">+                                               ~~~~~~~~~~~~~~~~~~_x000D__x000A_</S><S S="Error">    + CategoryInfo          : InvalidArgument: (:) [Select-Object], PSArgument _x000D__x000A_</S><S S="Error">   NullException_x000D__x000A_</S><S S="Error">    + FullyQualifiedErrorId : ArgumentNull,Microsoft.PowerShell.Commands.Selec _x000D__x000A_</S><S S="Error">   tObjectCommand_x000D__x000A_</S><S S="Error"> _x000D__x000A_</S><S S="Error">Select : Cannot process argument because the value of argument "obj" is null. _x000D__x000A_</S><S S="Error">Change the value of argument "obj" to a non-null value._x000D__x000A_</S><S S="Error">At line:28 char:47_x000D__x000A_</S><S S="Error">+     $i_hash["DVDs"] = @($_.VirtualDVDDrives | Select -Expand ISO | Select _x000D__x000A_</S><S S="Error">-Prope ..._x000D__x000A_</S><S S="Error">+                                               ~~~~~~~~~~~~~~~~~~_x000D__x000A_</S><S S="Error">    + CategoryInfo          : InvalidArgument: (:) [Select-Object], PSArgument _x000D__x000A_</S><S S="Error">   NullException_x000D__x000A_</S><S S="Error">    + FullyQualifiedErrorId : ArgumentNull,Microsoft.PowerShell.Commands.Selec _x000D__x000A_</S><S S="Error">   tObjectCommand_x000D__x000A_</S><S S="Error"> _x000D__x000A_</S><S S="Error">Select : Cannot process argument because the value of argument "obj" is
Comment 2 Rich Oliveri 2016-08-24 16:08:20 UTC 
Is this Azure or SCVMM? We don't use power shell in azure SSA.
Comment 4 Jerry Keselman 2016-08-24 16:55:43 UTC 
The powershell is from the SCVMM refresh script.  The thread number in the log messages for the powershell errors does not match that of the SSA - the messages are unrelated.
Comment 6 Hui Song 2016-08-30 13:10:24 UTC 
Hi, Satyajit,

The same problem on the RHEL instance has proved to be an user error (https://bugzilla.redhat.com/show_bug.cgi?id=1369886). I am afraid this one is also a false alarm. Can you run a quick test on a window instance to confirm it? I have tested it works in the dev azure environment.

Thanks,
Comment 7 Jeff Teehan 2016-08-30 16:53:11 UTC 
08/30/16 15:04:03 UTC	08/30/16 14:37:13 UTC	08/30/16 14:37:08 UTC	finished	Process completed successfully	Scan from Vm WS2012-Demo	admin	EVM	Synchronization complete

Make sure you check that the Windows Credentials have been set in the Configuration.  I think that was the problem on .200

New 5612 appliance is 10.16.7.238

Here are the results.  There are still some values with Zeros.

Properties
Name	WS2012-Demo
IP Addresses	10.1.0.17, WS2012-Demo-ip
MAC Addresses	
Container	 azure: 1 CPU, 1792 MB
Platform Tools	N/A
Operating System	 Windows Server 2012 R2 Datacenter
Architecture	
Advanced Settings	 0
Resources	Available
Management Engine GUID	0ba855f2-6e3f-11e6-8e5c-00155d06ac27
Virtualization Type	
Root Device Type	
Lifecycle
Discovered	 Mon Aug 29 23:19:33 UTC 2016
Last Analyzed	 Tue Aug 30 14:37:34 UTC 2016
Retirement Date	 Never
Group	Tenant My Company access
Relationships
Cloud Provider	 AzureJT
Availability Zone	 AzureJT
Cloud Tenants	 None
Flavor	 Standard_A1
VM Template	 None
Drift History	 1
Analysis History	 1
Service	 None
Stack	 Microsoft.WindowsServer2012R2Datacenter-20160717102857
Cloud Networks	 1
Cloud Subnets	 1
Network Routers	 0
Security Groups	 1
Floating Ips	 1
Network Ports	 1
Cloud Volumes	 0
VMsafe
Enable	false
Compliance
Status	Never Verified
History	Not Available
Power Management
Power State	 off
Last Boot Time	N/A
State Changed On	Tue Aug 30 16:35:40 UTC 2016
Security
Users	 2
Groups	 23
Patches	 0
Key Pairs	N/A
Configuration
Applications	 0
Win32 Services	 139
Kernel Drivers	 262
File System Drivers	 26
Files	 0
Registry Entries	 0