Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Daemon fails after Sync: Server for vCenterID=1 failed #48

Closed
mikeb93 opened this issue Nov 20, 2018 · 14 comments
Closed

Daemon fails after Sync: Server for vCenterID=1 failed #48

mikeb93 opened this issue Nov 20, 2018 · 14 comments
Assignees
@Thomas-Gelf
Labels
bug feedback Waiting for feedback
Milestone
v1.0.4

Comments

@mikeb93
Copy link

mikeb93 commented Nov 20, 2018

Expected Behavior

Daemon fetches latest state periodically after initial sync

Current Behavior

Daemon fails after sync with:

Pid 13345 stopped
Server for vCenterID=1 failed (PID 13345), will try again in 30 seconds

after that, the initial sync will start again and import everything successfully.
After that the daemon will fail again.

systemd message:
icingacli: The operation is not allowed in the current state.

Possible Solution

Steps to Reproduce (for bugs)

Restart Service after updating to latest master

Your Environment

  • VMware vCenter®/ESXi™-Version: vCenter 6.7
  • Version/GIT-Hash of this module: master
  • Icinga Web 2 version: 2.6.1-1
  • Operating System and version: Ubuntu Server 18.04.1 LTS
  • Webserver, PHP versions: apache2 2.4.29, php7.2
@mikeb93 mikeb93 changed the title Server for vCenterID=1 failed Daemon fails after Sync: Server for vCenterID=1 failed Nov 20, 2018
@Thomas-Gelf
Copy link
Contributor

The message 'The operation is not allowed in the current state' is probably from your vCenter... so the behavior is correct. You wrote that this happens since upgrading to the latest master, did it work for you before? And if so, which version have you been using?

@mikeb93
Copy link
Author

mikeb93 commented Nov 20, 2018

To be honest I can't quite confirm if this is actually the result of an update.
I just noticed this after pulling the latest master.
I don't know which version I was using before, I hope I still have my session window open at work^^ (any way to find out otherwise?)

The message 'The operation is not allowed in the current state' is probably from your vCenter

huh, might be, something must have changed though. The vCenter is not under my administration but I can check with the responsible guys.

@Thomas-Gelf
Copy link
Contributor

Eventually check your permissions, or try to manually log in with the given credentials to check whether there are special restrictions in place. However, they might not be immediately obvious - it could be something weird like being allowed to see VMs and Hosts, but not the DataCenter itself.

You could also try to manually run

icingacli vspheredb daemon run --trace --debug

or

icingacli vspheredb task sync --trace --debug --vCenterId 1

to see more details. Most of this should however also be visible when going to Virtualization (VMware) - Daemon in the frontend.

@mikeb93
Copy link
Author

mikeb93 commented Nov 21, 2018

I updated from fcebb8d to cdcca41.

icingacli vspheredb daemon run --trace --debug:

Ready to run
DB configuration loaded
Reconnecting to DB
Connected to the database
vCenter ID=1 is now starting
Constructing ServerRunner
Starting for vCenterID=1
Initializing vCenter for demovcenter.demo.lab
SOAPClient: got 4.33 KiB response in 32.08ms
vCenter hasn't been changed
Running vCenter Sync for ID=1
Pid 23346 stopped
Ready to fetch id/name/parent list
SOAPClient: got 4.33 KiB response in 23.16ms
SOAPClient: got 1111.00 B response in 1004.14ms
Sending Login request to https://demovcenter.demo.lab/sdk
Got new session cookie from VCenter
SOAPClient: got 820.00 B response in 125.60ms
SOAPClient: got 59.69 KiB response in 1011.94ms
Got id/name/parent for 176 objects
Storing object tree to DB
Managed Objects have not been changed
Task "Managed Object References" took 2372.20ms on demovcenter.demo.lab
Loading existing HostSystem from DB
Got 3 existing HostSystem
SOAPClient: got 10.12 KiB response in 1006.57ms
Got 3 HostSystem from VCenter
Ready to store HostSystem
HostSystem: 0 new, 1 modified, 0 deleted (got 3 from API)
Task "Host Systems" took 1011.66ms on demovcenter.demo.lab
Loading existing VirtualMachine from DB
Got 95 existing VirtualMachine
SOAPClient: got 232.26 KiB response in 1059.31ms
Got 95 VirtualMachine from VCenter
Ready to store VirtualMachine
VirtualMachine: 0 new, 0 modified, 0 deleted (got 95 from API)
Task "Virtual Machines" took 1090.92ms on demovcenter.demo.lab
Ready to sync QuickStats for Hosts and VMs
Loading existing HostSystem from DB
Got 3 existing HostSystem
SOAPClient: got 2.07 KiB response in 1004.62ms
Got 3 HostSystem from VCenter
Ready to store HostSystem
HostSystem: 0 new, 0 modified, 0 deleted (got 3 from API)
Loading existing VirtualMachine from DB
Got 95 existing VirtualMachine
SOAPClient: got 194.91 KiB response in 1016.90ms
Got 95 VirtualMachine from VCenter
Ready to store VirtualMachine
VirtualMachine: 0 new, 95 modified, 0 deleted (got 95 from API)
Task "Quick Stats" took 2086.94ms on demovcenter.demo.lab
Loading existing Datastore from DB
Got 9 existing Datastore
SOAPClient: got 5.50 KiB response in 1003.76ms
Got 9 Datastore from VCenter
Ready to store Datastore
Datastore: 0 new, 7 modified, 0 deleted (got 9 from API)
Task "Data Stores" took 1021.12ms on demovcenter.demo.lab
SOAPClient: got 41.72 KiB response in 1010.41ms
Got VirtualMachine perDatastoreUsage
0 created, 0 changed, 0 deleted
Task "VM DataStore Usage" took 1240.08ms on demovcenter.demo.lab
SOAPClient: got 24.17 KiB response in 1008.57ms
Got 95 VirtualMachines with guest.disk
Got 67 vm_disk_usage objects from DB
0 created, 2 changed, 0 deleted out of 67 objects (API: 67)
Task "VM Disk Usage" took 1015.78ms on demovcenter.demo.lab
SOAPClient: got 15.01 KiB response in 1006.56ms
Got 95 VirtualMachines with snapshot
Got 18 vm_snapshot objects from DB
0 created, 0 changed, 0 deleted out of 18 objects (API: 18)
Task "VM Snapshots" took 1011.20ms on demovcenter.demo.lab
SOAPClient: got 739.30 KiB response in 1057.51ms
Got 95 VirtualMachines with config.hardware
Got 1482 vm_hardware objects from DB
Got 149 vm_disk objects from DB
Got 143 vm_network_adapter objects from DB
0 created, 0 changed, 0 deleted out of 1482 objects (API: 1482)
0 created, 0 changed, 0 deleted out of 149 objects (API: 1482)
0 created, 0 changed, 0 deleted out of 143 objects (API: 1482)
Task "VM Hardware" took 1178.74ms on demovcenter.demo.lab
SOAPClient: got 52.14 KiB response in 1005.25ms
Got 3 HostSystems with hardware.pciDevice
Got 141 host_pci_device objects from DB
0 created, 0 changed, 0 deleted out of 141 objects (API: 141)
Task "Host Hardware" took 1016.28ms on demovcenter.demo.lab
SOAPClient: got 73.13 KiB response in 1006.81ms
Got 0 HostSensors with 3
Got 159 host_sensor objects from DB
0 created, 29 changed, 0 deleted out of 159 objects (API: 159)
Task "Host Sensors" took 1025.86ms on demovcenter.demo.lab
Pid 23350 stopped
Server for vCenterID=1 failed (PID 23350), will try again in 30 seconds

icingacli vspheredb task sync --trace --debug --vCenterId 1

[...]
SOAPClient: got 52.14 KiB response in 1005.98ms
Got 3 HostSystems with hardware.pciDevice
Got 141 host_pci_device objects from DB
0 created, 0 changed, 0 deleted out of 141 objects (API: 141)
Task "Host Hardware" took 1022.97ms on demovcenter.demo.lab
SOAPClient: got 73.13 KiB response in 1006.24ms
Got 0 HostSensors with 3
Got 159 host_sensor objects from DB
0 created, 0 changed, 0 deleted out of 159 objects (API: 159)
Task "Host Sensors" took 1016.39ms on demovcenter.demo.lab
SOAPClient: got 547.00 B response in 1184.57ms
SOAPClient: got 396.00 B response in 1.89ms
SOAPClient: got 1454.18 KiB response in 1053.89ms
1542210093621 <= 1542210093621 & 297911 <= 297912 skipped
1542210093621 <= 1542210093621 & 297912 <= 297912 skipped
PHP Fatal error: Uncaught Error: Call to undefined method stdClass::getTimestampMs() in /usr/share/icingaweb2/modules/vspheredb/library/Vspheredb/EventManager.php:169
Stack trace:
#0 /usr/share/icingaweb2/modules/vspheredb/library/Vspheredb/Daemon/SyncRunner.php(244): Icinga\Module\Vspheredb\EventManager->streamToDb()
#1 /usr/share/icingaweb2/modules/vspheredb/library/Vspheredb/Daemon/SyncRunner.php(105): Icinga\Module\Vspheredb\Daemon\SyncRunner->streamEvents()
#2 /usr/share/icingaweb2/modules/vspheredb/library/Vspheredb/Daemon/SyncRunner.php(183): Icinga\Module\Vspheredb\Daemon\SyncRunner->Icinga\Module\Vspheredb\Daemon{closure}()
#3 /usr/share/icingaweb2/modules/vspheredb/library/Vspheredb/Daemon/SyncRunner.php(197): Icinga\Module\Vspheredb\Daemon\SyncRunner->runNextImmediateTask()
#4 /usr/share/icingaweb2/modules/reactbundle/vendor/react/event-loop/src/Timer/Timers.php(89): Icinga\Module\Vspheredb\Daemon\SyncRunner->Icinga\Module\Vspheredb\Daemon{closure}(Object(React\EventLoop\Timer\Timer))
#5 /usr/share/icingaweb2/mod in /usr/share/icingaweb2/modules/vspheredb/library/Vspheredb/EventManager.php on line 169

Fatal error: Uncaught Error: Call to undefined method stdClass::getTimestampMs() in /usr/share/icingaweb2/modules/vspheredb/library/Vspheredb/EventManager.php:169
Stack trace:
#0 /usr/share/icingaweb2/modules/vspheredb/library/Vspheredb/Daemon/SyncRunner.php(244): Icinga\Module\Vspheredb\EventManager->streamToDb()
#1 /usr/share/icingaweb2/modules/vspheredb/library/Vspheredb/Daemon/SyncRunner.php(105): Icinga\Module\Vspheredb\Daemon\SyncRunner->streamEvents()
#2 /usr/share/icingaweb2/modules/vspheredb/library/Vspheredb/Daemon/SyncRunner.php(183): Icinga\Module\Vspheredb\Daemon\SyncRunner->Icinga\Module\Vspheredb\Daemon{closure}()
#3 /usr/share/icingaweb2/modules/vspheredb/library/Vspheredb/Daemon/SyncRunner.php(197): Icinga\Module\Vspheredb\Daemon\SyncRunner->runNextImmediateTask()
#4 /usr/share/icingaweb2/modules/reactbundle/vendor/react/event-loop/src/Timer/Timers.php(89): Icinga\Module\Vspheredb\Daemon\SyncRunner->Icinga\Module\Vspheredb\Daemon{closure}(Object(React\EventLoop\Timer\Timer))
#5 /usr/share/icingaweb2/mod in /usr/share/icingaweb2/modules/vspheredb/library/Vspheredb/EventManager.php on line 169

Thomas-Gelf added a commit that referenced this issue Nov 21, 2018
@Thomas-Gelf
MappedClass: add missing event types
4a45d0c 
refs #48
@Thomas-Gelf
Copy link
Contributor

@mikeb93: could you please try again? Guess you recently cloned a VM, the related handling was incomplete.

@Thomas-Gelf Thomas-Gelf self-assigned this Nov 21, 2018
@Thomas-Gelf
Copy link
Contributor

Oh, and how did you fix this part:

The message 'The operation is not allowed in the current state' is probably from your vCenter

Was it related to your permissions?

@mikeb93
Copy link
Author

mikeb93 commented Nov 21, 2018 •
edited
Loading

I didn't ^^ It's from systemd and it's still there even with current master. It actually now additionally says Task eventStream failed::

systemctl status icinga-vspheredb
● icinga-vspheredb.service - Icinga vSphereDB Daemon
Loaded: loaded (/etc/systemd/system/icinga-vspheredb.service; enabled; vendor preset: enabled)
Active: active (running) since Wed 2018-11-21 11:27:21 CET; 4h 40min ago
Docs: https://icinga.com/docs/icinga-vsphere/latest/
Main PID: 14440 (icingacli)
Status: "Connected to the database"
Tasks: 2 (limit: 2321)
CGroup: /system.slice/icinga-vspheredb.service
├─14440 Icinga::vSphereDB::main: 1 active runner
└─14469 Icinga::vSphereDB::sync (demovcenter.demo.lab: Event Stream)

Nov 21 16:11:05 mba-icinga2-test icingacli[21502]: Task eventStream failed: The operation is not allowed in the current state.
Nov 21 16:11:07 mba-icinga2-test icingacli[21502]: Task eventStream failed: The operation is not allowed in the current state.
Nov 21 16:11:09 mba-icinga2-test icingacli[21502]: Task eventStream failed: The operation is not allowed in the current state.
Nov 21 16:11:11 mba-icinga2-test icingacli[21502]: Task eventStream failed: The operation is not allowed in the current state.
Nov 21 16:11:13 mba-icinga2-test icingacli[21502]: Task eventStream failed: The operation is not allowed in the current state.
Nov 21 16:11:15 mba-icinga2-test icingacli[21502]: Task eventStream failed: The operation is not allowed in the current state.
Nov 21 16:11:17 mba-icinga2-test icingacli[21502]: Task eventStream failed: The operation is not allowed in the current state.
Nov 21 16:11:19 mba-icinga2-test icingacli[21502]: Task eventStream failed: The operation is not allowed in the current state.
Nov 21 16:11:21 mba-icinga2-test icingacli[21502]: Task eventStream failed: The operation is not allowed in the current state.
Nov 21 16:11:23 mba-icinga2-test icingacli[21502]: Task eventStream failed: The operation is not allowed in the current state.

Issue still persists btw.

Thomas-Gelf added a commit that referenced this issue Nov 21, 2018
@Thomas-Gelf
EventManager: fail on unknown class
34fe41b 
refs #48
@Thomas-Gelf
Copy link
Contributor

Please try again with icingacli vspheredb task sync --trace --debug --vCenterId 1, I added some debugging

@mikeb93
Copy link
Author

mikeb93 commented Nov 22, 2018

No error message anymore:

[...]
SOAPClient: got 547.00 B response in 1161.36ms
SOAPClient: got 396.00 B response in 1.47ms
SOAPClient: got 1454.18 KiB response in 1037.77ms
1542210093621 <= 1542210093621 & 297911 <= 297912 skipped
1542210093621 <= 1542210093621 & 297912 <= 297912 skipped
Fetched 2 events to skip
Got 1000 event(s), there might be more
Task "Event Stream" took 2831.70ms on demovcenter.demo.lab
SOAPClient: got 632.87 KiB response in 333.79ms
Got 477 events
Task "Event Stream" took 585.94ms on demovcenter.demo.lab
SOAPClient: got 394.00 B response in 94.56ms
Task "Event Stream" took 94.94ms on demovcenter.demo.lab
SOAPClient: got 394.00 B response in 120.33ms
Task "Event Stream" took 120.66ms on demovcenter.demo.lab
[...]

although this message still appears in systemd:

Nov 22 08:24:21 mba-icinga2-test icingacli[29422]: Task eventStream failed: The operation is not allowed in the current state.

and it looks like the stats get updated very infrequently.

@Thomas-Gelf
Copy link
Contributor

Looks like there is something wrong with your EventCollector. Please run:

systemctl stop icinga-vspheredb.service
rm -rf /tmp/iwebVsphere*`
systemctl start icinga-vspheredb.service

Does the output change?

@Thomas-Gelf Thomas-Gelf added the feedback Waiting for feedback label Dec 6, 2018
@Tontonitch
Copy link

Hello,
Just some feedback from me, as I've faced exactly the same issue.
With a git clone based on last commit 6c36add and the cleaning of /tmp/iwebVsphere* the issue is solved.

@Thomas-Gelf
Copy link
Contributor

Hi @Tontonitch,

thanks for testing this! In case you're still facing this or similar issues please let me know!

Cheers,
Thomas

@mikeb93
Copy link
Author

mikeb93 commented Dec 17, 2018

Sorry for the late reply.
This issue is indeed not occuring anymore

Thanks

@Thomas-Gelf
Copy link
Contributor

Thanks @mikeb93 for your confirmation!

@Thomas-Gelf Thomas-Gelf added this to the v1.0.4 milestone Aug 12, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@Thomas-Gelf Thomas-Gelf

Labels
bug feedback Waiting for feedback
Projects
None yet
Milestone
v1.0.4
Development

No branches or pull requests
3 participants
@Thomas-Gelf @Tontonitch @mikeb93