Win32Software failing on RollupFix's

[miq-bot]

When performing SmartState Analysis on a Windows 2012 VM the following error appears in the evm.log

[----] E, [2017-04-14T10:11:35.319528 #12806:3a398c] ERROR -- : MIQExtract.extract undefined method `split' for nil:NilClass
[----] E, [2017-04-14T10:11:35.319698 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/gems/pending/metadata/util/win32/Win32Software.rb:165:in `block in initialize'
[----] E, [2017-04-14T10:11:35.319729 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/gems/pending/util/xml/xml_hash.rb:116:in `block in each_element'
[----] E, [2017-04-14T10:11:35.319747 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/gems/pending/util/xml/xml_hash.rb:111:in `block in each'
[----] E, [2017-04-14T10:11:35.319763 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/gems/pending/util/xml/xml_hash.rb:111:in `each'
[----] E, [2017-04-14T10:11:35.319780 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/gems/pending/util/xml/xml_hash.rb:111:in `each'
[----] E, [2017-04-14T10:11:35.319795 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/gems/pending/util/xml/xml_hash.rb:116:in `each_element'
[----] E, [2017-04-14T10:11:35.319811 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/gems/pending/metadata/util/win32/Win32Software.rb:155:in `initialize'
[----] E, [2017-04-14T10:11:35.319827 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/gems/pending/metadata/MIQExtract/MIQExtract.rb:253:in `new'
[----] E, [2017-04-14T10:11:35.319842 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/gems/pending/metadata/MIQExtract/MIQExtract.rb:253:in `getSoftware'
[----] E, [2017-04-14T10:11:35.319859 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/gems/pending/metadata/MIQExtract/MIQExtract.rb:136:in `block in extract'
[----] E, [2017-04-14T10:11:35.319875 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/gems/pending/metadata/MIQExtract/MIQExtract.rb:131:in `each'
[----] E, [2017-04-14T10:11:35.319890 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/gems/pending/metadata/MIQExtract/MIQExtract.rb:131:in `extract'
[----] E, [2017-04-14T10:11:35.319906 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/mixins/scanning_mixin.rb:254:in `block in scan_via_miq_vm'
[----] E, [2017-04-14T10:11:35.319921 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/mixins/scanning_mixin.rb:250:in `each'
[----] E, [2017-04-14T10:11:35.319942 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/mixins/scanning_mixin.rb:250:in `scan_via_miq_vm'
[----] E, [2017-04-14T10:11:35.319960 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/manageiq/providers/vmware/infra_manager/vm_or_template_shared/scanning.rb:18:in `perform_metadata_scan'
[----] E, [2017-04-14T10:11:35.319975 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_server/server_smart_proxy.rb:125:in `scan_metadata'
[----] E, [2017-04-14T10:11:35.319991 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_queue.rb:345:in `block in deliver'
[----] E, [2017-04-14T10:11:35.320007 #12806:3a398c] ERROR -- : MIQExtract.extract /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:89:in `block in timeout'
[----] E, [2017-04-14T10:11:35.320022 #12806:3a398c] ERROR -- : MIQExtract.extract /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:34:in `block in catch'
[----] E, [2017-04-14T10:11:35.320038 #12806:3a398c] ERROR -- : MIQExtract.extract /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:34:in `catch'
[----] E, [2017-04-14T10:11:35.320087 #12806:3a398c] ERROR -- : MIQExtract.extract /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:34:in `catch'
[----] E, [2017-04-14T10:11:35.320106 #12806:3a398c] ERROR -- : MIQExtract.extract /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:104:in `timeout'
[----] E, [2017-04-14T10:11:35.320122 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_queue.rb:341:in `deliver'
[----] E, [2017-04-14T10:11:35.320138 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:106:in `deliver_queue_message'
[----] E, [2017-04-14T10:11:35.320154 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:134:in `deliver_message'
[----] E, [2017-04-14T10:11:35.320169 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:152:in `block in do_work'
[----] E, [2017-04-14T10:11:35.320184 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:146:in `loop'
[----] E, [2017-04-14T10:11:35.320199 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:146:in `do_work'
[----] E, [2017-04-14T10:11:35.320215 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_worker/runner.rb:334:in `block in do_work_loop'
[----] E, [2017-04-14T10:11:35.320244 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_worker/runner.rb:331:in `loop'
[----] E, [2017-04-14T10:11:35.320262 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_worker/runner.rb:331:in `do_work_loop'
[----] E, [2017-04-14T10:11:35.320278 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_worker/runner.rb:153:in `run'
[----] E, [2017-04-14T10:11:35.320293 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_worker/runner.rb:128:in `start'
[----] E, [2017-04-14T10:11:35.320309 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_worker/runner.rb:21:in `start_worker'
[----] E, [2017-04-14T10:11:35.320324 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_worker.rb:347:in `block in start'
[----] E, [2017-04-14T10:11:35.320340 #12806:3a398c] ERROR -- : MIQExtract.extract /opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.3/lib/nakayoshi_fork.rb:24:in `fork'
[----] E, [2017-04-14T10:11:35.320355 #12806:3a398c] ERROR -- : MIQExtract.extract /opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.3/lib/nakayoshi_fork.rb:24:in `fork'
[----] E, [2017-04-14T10:11:35.320374 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_worker.rb:345:in `start'
[----] E, [2017-04-14T10:11:35.320402 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_worker.rb:274:in `start_worker'
[----] E, [2017-04-14T10:11:35.320438 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_worker.rb:154:in `block in sync_workers'
[----] E, [2017-04-14T10:11:35.320470 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_worker.rb:154:in `times'
[----] E, [2017-04-14T10:11:35.320503 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_worker.rb:154:in `sync_workers'
[----] E, [2017-04-14T10:11:35.320526 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:52:in `block in sync_workers'
[----] E, [2017-04-14T10:11:35.320543 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:50:in `each'
[----] E, [2017-04-14T10:11:35.320598 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:50:in `sync_workers'
[----] E, [2017-04-14T10:11:35.320616 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:22:in `monitor_workers'
[----] E, [2017-04-14T10:11:35.320632 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_server.rb:362:in `block in monitor'
[----] E, [2017-04-14T10:11:35.320647 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store'
[----] E, [2017-04-14T10:11:35.320663 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block'
[----] E, [2017-04-14T10:11:35.320678 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_server.rb:362:in `monitor'
[----] E, [2017-04-14T10:11:35.320703 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_server.rb:382:in `block (2 levels) in monitor_loop'
[----] E, [2017-04-14T10:11:35.320728 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store'
[----] E, [2017-04-14T10:11:35.320744 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block'
[----] E, [2017-04-14T10:11:35.320760 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_server.rb:382:in `block in monitor_loop'
[----] E, [2017-04-14T10:11:35.320776 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_server.rb:381:in `loop'
[----] E, [2017-04-14T10:11:35.320791 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_server.rb:381:in `monitor_loop'
[----] E, [2017-04-14T10:11:35.320807 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/app/models/miq_server.rb:266:in `start'
[----] E, [2017-04-14T10:11:35.320822 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/lib/workers/evm_server.rb:65:in `start'
[----] E, [2017-04-14T10:11:35.320838 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/lib/workers/evm_server.rb:92:in `start'
[----] E, [2017-04-14T10:11:35.320854 #12806:3a398c] ERROR -- : MIQExtract.extract /var/www/miq/vmdb/lib/workers/bin/evm_server.rb:4:in `<main>'

I instrumented the code to print out the element details prior to the failure

[----] I, [2017-04-14T10:11:35.317155 #12806:3a398c]  INFO -- : Win32Software::initialize() - Element's keyname starts with Package_, element:
 key {:keyname=>"Package_for_KB3184122_RTM~31bf3856ad364e35~amd64~~6.3.1.1", :fqname=>"software\\Microsoft\\Windows\\CurrentVersion\\Component Based Servicing\\Packages\\Package_for_KB3184122_RTM~31bf3856ad364e35~amd64~~6.3.1.1"}
  value {:type=>:REG_SZ, :name=>"InstallLocation"} \\?\C:\Windows\SoftwareDistribution\Download\c2ea7323991a16f3cf1465dec49374e5\
  value {:type=>:REG_DWORD, :name=>"CurrentState"} 112
  value {:type=>:REG_DWORD, :name=>"Visibility"} 2
  value {:type=>:REG_DWORD, :name=>"InstallTimeHigh"} 30543713
  value {:type=>:REG_DWORD, :name=>"InstallTimeLow"} 1199975721
  key {:keyname=>"Owners", :fqname=>"software\\Microsoft\\Windows\\CurrentVersion\\Component Based Servicing\\Packages\\Package_for_KB3184122_RTM~31bf3856ad364e35~amd64~~6.3.1.1\\Owners"}
[----] I, [2017-04-14T10:11:35.317185 #12806:3a398c]  INFO -- : Win32Software::initialize() - Element's package = ["Package", "for", "KB3184122", "RTM~31bf3856ad364e35~amd64~~6.3.1.1"]
[----] I, [2017-04-14T10:11:35.319416 #12806:3a398c]  INFO -- : Win32Software::initialize() - Element's keyname starts with Package_, element:
 key {:keyname=>"Package_for_RollupFix~31bf3856ad364e35~amd64~~9600.18528.1.5", :fqname=>"software\\Microsoft\\Windows\\CurrentVersion\\Component Based Servicing\\Packages\\Package_for_RollupFix~31bf3856ad364e35~amd64~~9600.18528.1.5"} 
  value {:type=>:REG_SZ, :name=>"InstallLocation"} \\?\C:\Windows\SoftwareDistribution\Download\ba69d3dba8e87f642b7551de27f41459\windows8.1-kb3197874-x64-express.cab
  value {:type=>:REG_DWORD, :name=>"CurrentState"} 112
  value {:type=>:REG_DWORD, :name=>"Visibility"} 1
  value {:type=>:REG_DWORD, :name=>"InstallTimeHigh"} 30559260
  value {:type=>:REG_DWORD, :name=>"InstallTimeLow"} 1808991745
  key {:keyname=>"Owners", :fqname=>"software\\Microsoft\\Windows\\CurrentVersion\\Component Based Servicing\\Packages\\Package_for_RollupFix~31bf3856ad364e35~amd64~~9600.18528.1.5\\Owners"} 

[----] I, [2017-04-14T10:11:35.319446 #12806:3a398c]  INFO -- : Win32Software::initialize() - Element's package = ["Package", "for", "RollupFix~31bf3856ad364e35~amd64~~9600.18528.1.5"]
[----] E, [2017-04-14T10:11:35.319528 #12806:3a398c] ERROR -- : MIQExtract.extract undefined method `split' for nil:NilClass

It appears that https://github.com/ManageIQ/manageiq-gems-pending/blob/master/lib/gems/pending/metadata/util/win32/Win32Software.rb#L159-L161 is assuming that the Package_ string has a minimum of 4 components after splitting by '_'. However, in this case of a "RollupFix" the string only has 3 elements, so when it accesses packages[3] a nil is returned.

---

This issue was moved to this repository from ManageIQ/manageiq-gems-pending#121, originally opened by @nmaludy

[miq-bot]

This issue has been automatically marked as stale because it has not been updated for at least 6 months.

If you can still reproduce this issue on the current release or on master, please reply with all of the information you have about it in order to keep the issue open.

Thank you for all your contributions!

[mfeifer]

@roliveri can you verify this?