JSON decode failed: Syntax error when running initial tasks

[mikeb93]

Hi,

I've tried to add one vCenter 6.7 and one ESXi Server 6.5 (either on separate icinga2 systems).
I've been running into the error "JSON decode failed: Syntax error" both times.

vCenter gets Stuck on Task hostSystems after the log message:
Ready to store HostSystem
I don't see any information on the vCenter or it's Servers / VMs on this installation.

On the other Icinga2 host where I tried adding a single ESXi Server I get stuck on the Task quickStats after the log message:
Ready to store VirtualMachine
I can See info about the ESXi Server but no VMs appear. Just the Info how many VMs the Host has.

Please let me know how I can help debug this issue further
Thanks in advance :)

Full debug log from icingacli vspheredb daemon run --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
Loading sdk/vimService.wsdl
Loading sdk/vim.wsdl
Loading sdk/core-types.xsd
Loading sdk/query-types.xsd
Loading sdk/query-messagetypes.xsd
Loading sdk/reflect-types.xsd
Loading sdk/reflect-messagetypes.xsd
Loading sdk/vim-types.xsd
Loading sdk/vim-messagetypes.xsd
SOAPClient: got 4.33 KiB response in 2.52ms
vCenter hasn't been changed
Running vCenter Sync for ID=1
Pid 2155 stopped
Task: moRefs
Ready to fetch id/name/parent list
SOAPClient: got 4.33 KiB response in 23.03ms
SOAPClient: got 1111.00 B response in 1003.77ms
Sending Login request to https://demovcenter.demo.lab/sdk
Got new session cookie from VCenter
SOAPClient: got 819.00 B response in 85.29ms
SOAPClient: got 57.98 KiB response in 1010.28ms
Got id/name/parent for 171 objects
Storing object tree to DB
Managed Objects have not been changed
Task: hostSystems
Loading existing HostSystem from DB
Got 0 existing HostSystem
SOAPClient: got 9.53 KiB response in 1005.74ms
Got 3 HostSystem from VCenter
Ready to store HostSystem
JSON decode failed: Syntax error

[Thomas-Gelf]

@mikeb93: today I pushed some more error handling to the GIT master, could you please check whether that one gives you more information?

[mikeb93]

@Thomas-Gelf I'm already using the latest master on both systems.
By the way: the systemd service has the user "icingaweb2" specified, this user does not exist on a clean install on Ubuntu Server.
When running the service I get an user error. I changed it to www-data for now. Which user should run the service when there is no icingaweb2 user?

[mzac]

@Thomas-Gelf I'm already using the latest master on both systems.
By the way: the systemd service has the user "icingaweb2" specified, this user does not exist on a clean install on Ubuntu Server.
When running the service I get an user error. I changed it to www-data for now. Which user should run the service when there is no icingaweb2 user?

I had the same issue, on my Ubuntu system I changed the user to 'www-data' which is the same user as my Apache process is running.

On a Redhat system I changed it to 'apache' which is the default that httpd runs as

[mzac]

Maybe this could be added to the docs as part of the install process:

For Debian based systems with Apache:
sed -i "/User=icingaweb2/c User=www-data" /etc/systemd/system/icinga-vspheredb.service

For CentOS/Redhat with httpd:
sed -i "/User=icingaweb2/c User=apache" /etc/systemd/system/icinga-vspheredb.service

[Thomas-Gelf]

Guess there is some room for improvement in the documentation, thanks for the hint. But this didn't solve the original issue for you, did it?

[Thomas-Gelf]

@Thomas-Gelf I'm already using the latest master on both systems.

@mikeb93: your log output does not reflect todays master, I changed many details in 675b7c6 this night

[mikeb93]

@Thomas-Gelf I'm already using the latest master on both systems.

@mikeb93: your log output does not reflect todays master, I changed many details in 675b7c6 this night

Committed 20h ago... I installed the module (for the vCenter integration) today at 10am CET.
I also pulled the master around that time for the other Icinga2 instance.

this is the debug log output on the latter from right now using the latest master branch:

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 10.99.0.10
SOAPClient: got 2.73 KiB response in 39.91ms
vCenter hasn't been changed
Running vCenter Sync for ID=1
Pid 9172 stopped
Ready to fetch id/name/parent list
SOAPClient: got 2.73 KiB response in 37.05ms
SOAPClient: got 6.70 KiB response in 1013.77ms
Got id/name/parent for 19 objects
Storing object tree to DB
Managed Objects have not been changed
Task "Managed Object References" took 1242.89ms on 10.99.0.10
Loading existing HostSystem from DB
Got 1 existing HostSystem
SOAPClient: got 3.43 KiB response in 1011.23ms
Got 1 HostSystem from VCenter
Ready to store HostSystem
HostSystem: 0 new, 0 modified, 0 deleted (got 1 from API)
Task "Host Systems" took 1014.82ms on 10.99.0.10
Loading existing VirtualMachine from DB
Got 7 existing VirtualMachine
SOAPClient: got 18.57 KiB response in 1051.71ms
Got 7 VirtualMachine from VCenter
Ready to store VirtualMachine
VirtualMachine: 0 new, 0 modified, 0 deleted (got 7 from API)
Task "Virtual Machines" took 1057.35ms on 10.99.0.10
Ready to sync QuickStats for Hosts and VMs
Loading existing HostSystem from DB
Got 1 existing HostSystem
SOAPClient: got 758.00 B response in 1009.42ms
Got 1 HostSystem from VCenter
Ready to store HostSystem
HostSystem: 0 new, 1 modified, 0 deleted (got 1 from API)
Loading existing VirtualMachine from DB
Got 0 existing VirtualMachine
SOAPClient: got 3.69 KiB response in 1098.38ms
Got 7 VirtualMachine from VCenter
Ready to store VirtualMachine
JSON decode failed: Syntax error

I'll pull the master for the vCenter one tomorrow. The DemoLab at work is a major pain in the ass to get to from remote :(

[Thomas-Gelf]

@mikeb93: looks much better than the former one, this is the latest master. It somehow fails during/after storing QuickStats. Could you please stop the daemon and run the following command (with icingaweb2/apache/httpd privileges):

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

This will print NetString-encoded JSON-RPC, I guess there some uncaught error string mixed into your output.

Thanks,
Thomas

[mikeb93]

Looks like it's looping at the end so I stopped it at some point, but here it is:

97:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Ready to fetch id/name/parent list"]},105:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 2.73 KiB response in 42.55ms"]},107:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 6.70 KiB response in 1013.79ms"]},96:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got id/name/parent for 19 objects"]},86:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Storing object tree to DB"]},98:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Managed Objects have not been changed"]},124:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Managed Object References" took 1274.80ms on 10.99.0.10"]},96:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Loading existing HostSystem from DB"]},86:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 1 existing HostSystem"]},107:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 3.43 KiB response in 1011.82ms"]},90:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 1 HostSystem from VCenter"]},86:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Ready to store HostSystem"]},118:{"jsonrpc":"2.0","method":"logger.log","params":["debug","HostSystem: 0 new, 0 modified, 0 deleted (got 1 from API)"]},111:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Host Systems" took 1015.40ms on 10.99.0.10"]},100:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Loading existing VirtualMachine from DB"]},90:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 7 existing VirtualMachine"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 18.57 KiB response in 1040.82ms"]},94:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 7 VirtualMachine from VCenter"]},90:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Ready to store VirtualMachine"]},122:{"jsonrpc":"2.0","method":"logger.log","params":["debug","VirtualMachine: 0 new, 0 modified, 0 deleted (got 7 from API)"]},115:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Virtual Machines" took 1046.02ms on 10.99.0.10"]},103:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Ready to sync QuickStats for Hosts and VMs"]},96:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Loading existing HostSystem from DB"]},86:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 1 existing HostSystem"]},107:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 758.00 B response in 1007.74ms"]},90:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 1 HostSystem from VCenter"]},86:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Ready to store HostSystem"]},118:{"jsonrpc":"2.0","method":"logger.log","params":["debug","HostSystem: 0 new, 1 modified, 0 deleted (got 1 from API)"]},100:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Loading existing VirtualMachine from DB"]},90:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 0 existing VirtualMachine"]},107:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 3.69 KiB response in 1088.12ms"]},94:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 7 VirtualMachine from VCenter"]},90:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Ready to store VirtualMachine"]},0:,95:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Loading existing Datastore from DB"]},85:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 0 existing Datastore"]},107:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 854.00 B response in 1004.64ms"]},89:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 1 Datastore from VCenter"]},85:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Ready to store Datastore"]},213:{"jsonrpc":"2.0","method":"logger.log","params":["error","PDOException in /usr/share/icingaweb2/library/vendor/Zend/Db/Adapter/Pdo/Abstract.php:302 with message: There is already an active transaction"]},107:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 3.53 KiB response in 1005.62ms"]},97:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got VirtualMachine perDatastoreUsage"]},213:{"jsonrpc":"2.0","method":"logger.log","params":["error","PDOException in /usr/share/icingaweb2/library/vendor/Zend/Db/Adapter/Pdo/Abstract.php:302 with message: There is already an active transaction"]},107:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 2.94 KiB response in 1021.18ms"]},98:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 7 VirtualMachines with guest.disk"]},96:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 0 vm_disk_usage objects from DB"]},213:{"jsonrpc":"2.0","method":"logger.log","params":["error","PDOException in /usr/share/icingaweb2/library/vendor/Zend/Db/Adapter/Pdo/Abstract.php:302 with message: There is already an active transaction"]},107:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 808.00 B response in 1004.43ms"]},96:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 7 VirtualMachines with snapshot"]},94:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 0 vm_snapshot objects from DB"]},213:{"jsonrpc":"2.0","method":"logger.log","params":["error","PDOException in /usr/share/icingaweb2/library/vendor/Zend/Db/Adapter/Pdo/Abstract.php:302 with message: There is already an active transaction"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 46.10 KiB response in 1011.69ms"]},103:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 7 VirtualMachines with config.hardware"]},94:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 0 vm_hardware objects from DB"]},90:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 0 vm_disk objects from DB"]},101:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 0 vm_network_adapter objects from DB"]},213:{"jsonrpc":"2.0","method":"logger.log","params":["error","PDOException in /usr/share/icingaweb2/library/vendor/Zend/Db/Adapter/Pdo/Abstract.php:302 with message: There is already an active transaction"]},107:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 8.11 KiB response in 1005.51ms"]},102:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 1 HostSystems with hardware.pciDevice"]},98:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 0 host_pci_device objects from DB"]},213:{"jsonrpc":"2.0","method":"logger.log","params":["error","PDOException in /usr/share/icingaweb2/library/vendor/Zend/Db/Adapter/Pdo/Abstract.php:302 with message: There is already an active transaction"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 14.84 KiB response in 1008.12ms"]},85:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 0 HostSensors with 1"]},94:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Got 0 host_sensor objects from DB"]},213:{"jsonrpc":"2.0","method":"logger.log","params":["error","PDOException in /usr/share/icingaweb2/library/vendor/Zend/Db/Adapter/Pdo/Abstract.php:302 with message: There is already an active transaction"]},107:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 547.00 B response in 1009.31ms"]},104:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 396.00 B response in 4.69ms"]},106:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 52.06 KiB response in 10.79ms"]},213:{"jsonrpc":"2.0","method":"logger.log","params":["error","PDOException in /usr/share/icingaweb2/library/vendor/Zend/Db/Adapter/Pdo/Abstract.php:302 with message: There is already an active transaction"]},104:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 394.00 B response in 3.45ms"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Event Stream" took 3.98ms on 10.99.0.10"]},104:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 394.00 B response in 3.62ms"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Event Stream" took 3.93ms on 10.99.0.10"]},104:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 394.00 B response in 3.49ms"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Event Stream" took 3.82ms on 10.99.0.10"]},104:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 394.00 B response in 4.09ms"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Event Stream" took 4.35ms on 10.99.0.10"]},104:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 394.00 B response in 3.96ms"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Event Stream" took 4.29ms on 10.99.0.10"]},104:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 394.00 B response in 3.60ms"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Event Stream" took 3.93ms on 10.99.0.10"]},104:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 394.00 B response in 4.21ms"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Event Stream" took 4.53ms on 10.99.0.10"]},104:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 394.00 B response in 3.58ms"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Event Stream" took 3.93ms on 10.99.0.10"]},104:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 394.00 B response in 3.29ms"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Event Stream" took 3.65ms on 10.99.0.10"]},104:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 394.00 B response in 3.50ms"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Event Stream" took 3.83ms on 10.99.0.10"]},104:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 394.00 B response in 4.49ms"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Event Stream" took 4.77ms on 10.99.0.10"]},104:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 394.00 B response in 3.44ms"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Event Stream" took 3.76ms on 10.99.0.10"]},104:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 394.00 B response in 3.00ms"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Event Stream" took 3.26ms on 10.99.0.10"]},104:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 394.00 B response in 3.46ms"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Event Stream" took 3.79ms on 10.99.0.10"]},104:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 394.00 B response in 3.77ms"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Event Stream" took 4.10ms on 10.99.0.10"]},104:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 394.00 B response in 5.03ms"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Event Stream" took 5.36ms on 10.99.0.10"]},104:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 394.00 B response in 3.72ms"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Event Stream" took 4.04ms on 10.99.0.10"]},104:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 394.00 B response in 3.60ms"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Event Stream" took 3.93ms on 10.99.0.10"]},104:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 394.00 B response in 3.70ms"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Event Stream" took 4.21ms on 10.99.0.10"]},104:{"jsonrpc":"2.0","method":"logger.log","params":["debug","SOAPClient: got 394.00 B response in 3.46ms"]},108:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Task "Event Stream" took 3.72ms on 10.99.0.10"]},^C

[Thomas-Gelf]

Looks like it's looping at the end so I stopped it at some point [..]

Don't worry, it's not looping. It works as expected, created an EventCollector in it's SOAP session and polls it every two seconds. The error is in the middle:

{
  "jsonrpc": "2.0",
  "method": "logger.log",
  "params": [
    "error",
    "PDOException in [..]/Pdo/Abstract[..]: There is already an active transaction"
  ]
}

How does your DB resource configuration look like? Did you configure persistent connections? This is weird, as I cannot find a place in the code where this could possibly happen. It also doesn't explain the JSON-decode error, but let's dig into this step by step. We'll fix it, don't worry.

[mikeb93]

We'll fix it, don't worry.

I'm sure you will ;)

I followed your documentation very closely.
from /etc/icingaweb2/resources.ini:

[vSphere DB]
type = "db"
db = "mysql"
host = "localhost"
dbname = "vspheredb"
username = "vspheredb"
password = "****"
use_ssl = "0"

from /etc/icingaweb2/modules/vspheredb/config.ini:

[db]
resource = "vSphere DB

[Thomas-Gelf]

@mikeb93: what's your PHP version? Any special settings/modules loaded? It would be great if you could share the output of php -i. I checked your NetString-encoded output - string lengths seem to be just wrong at first sight... this is weird

[Thomas-Gelf]

Found an empty string that has been sent:

["debug","Ready to store VirtualMachine"]},0:,95:{"jsonrpc":"2.0","method":"logger.log",

This (0:,) is NOT valid and might explain the json_decode error. Wondering how this managed it to get there.

[mikeb93]

php7.2
I'm not sure what qualifies as a special setting/module.
The current installation we are looking at right now is a machine I've been running for quite some time in my personal home lab so there could be some strange stuff in there. Also keep in mind I'm not a dev in any way so sometimes I have no idea what I'm doing ^^

The other Module I installed freshly this morning, whole machine is actually a fresh install. also php7.2.

I attached a file with the output of php -i
php.txt

[Thomas-Gelf]

The problem starts before dealing with your DataStores for the very first time, at that point an empty string has been streamed through the NetString wrapper. And when trying to persist the DataStores the "transaction already in process" error pops up - correctly encoded.

[mikeb93]

Found an empty string that has been sent:

["debug","Ready to store VirtualMachine"]},0:,95:{"jsonrpc":"2.0","method":"logger.log",

This (0:,) is NOT valid and might explain the json_decode error. Wondering how this managed it to get there.

Hm, any idea how to further troubleshoot?

[Thomas-Gelf]

Sure :-) I found nothing special in your configuration, but I got a better understanding of what happened:

a) it works fine, reaches the QuickStats task:

103:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Ready to sync QuickStats for Hosts and VMs"]},

b) Host information has been stored:

86:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Ready to store HostSystem"]},
118:{"jsonrpc":"2.0","method":"logger.log","params":["debug","HostSystem: 0 new, 1 modified, 0 deleted (got 1 from API)"]},

c) it proceeds with VMs, is ready to store them - but there is no message reporting successful storage:

90:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Ready to store VirtualMachine"]},

d) instead of the expected message, an empty string has been sent over the wire:

0:,

This is where I continue my investigation right now, there must have been some error - it it eventually wasn't able to encode the error message.

e) it then starts to fetch DataStore information:

95:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Loading existing Datastore from DB"]},

f) it fails to persist DataStores, as the former DB transaction is probably still in progress:

85:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Ready to store Datastore"]},
213:{"jsonrpc":"2.0","method":"logger.log","params":["error","PDOException in /usr/share/icingaweb2/library/vendor/Zend/Db/Adapter/Pdo/Abstract.php:302 with message: There is already an active transaction"]},

And then it breaks. There is concurrency where it shouldn't be, I'll re-check this immediately. Another thing I noticed was that the very first message seems to be wrong. NetString reads <length>:<message>, and this is what I copied from your post:

97:{"jsonrpc":"2.0","method":"logger.log","params":["debug","Ready to fetch id/name/parent list"]},

Length does not include leading colon and trailing comma, so this must read 95 and not 97. Very strange. Because if it has been sent like this it should have been rejected immediately after this part.

[Thomas-Gelf]

@mikeb93: please try again with the current master, eventually we can see the real error right now.

[mikeb93]

output with new master:

97:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Ready to fetch id\/name\/parent list" ] }, 105:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 2.73 KiB response in 36.02ms" ] }, 108:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 1135.00 B response in 1006.84ms" ] }, 111:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Sending Login request to https:\/\/10.99.0.10\/sdk" ] }, 95:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "info", "Got new session cookie from VCenter" ] }, 105:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 816.00 B response in 64.96ms" ] }, 107:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 6.70 KiB response in 1014.75ms" ] }, 96:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got id\/name\/parent for 19 objects" ] }, 86:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Storing object tree to DB" ] }, 98:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Managed Objects have not been changed" ] }, 124:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Task \"Managed Object References\" took 2459.28ms on 10.99.0.10" ] }, 96:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Loading existing HostSystem from DB" ] }, 86:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 1 existing HostSystem" ] }, 107:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 3.43 KiB response in 1012.00ms" ] }, 90:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 1 HostSystem from VCenter" ] }, 86:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Ready to store HostSystem" ] }, 118:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "HostSystem: 0 new, 0 modified, 0 deleted (got 1 from API)" ] }, 111:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Task \"Host Systems\" took 1015.86ms on 10.99.0.10" ] }, 100:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Loading existing VirtualMachine from DB" ] }, 90:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 7 existing VirtualMachine" ] }, 108:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 18.57 KiB response in 1041.72ms" ] }, 94:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 7 VirtualMachine from VCenter" ] }, 90:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Ready to store VirtualMachine" ] }, 122:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "VirtualMachine: 0 new, 0 modified, 0 deleted (got 7 from API)" ] }, 115:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Task \"Virtual Machines\" took 1047.23ms on 10.99.0.10" ] }, 103:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Ready to sync QuickStats for Hosts and VMs" ] }, 96:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Loading existing HostSystem from DB" ] }, 86:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 1 existing HostSystem" ] }, 107:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 758.00 B response in 1007.75ms" ] }, 90:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 1 HostSystem from VCenter" ] }, 86:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Ready to store HostSystem" ] }, 118:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "HostSystem: 0 new, 1 modified, 0 deleted (got 1 from API)" ] }, 100:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Loading existing VirtualMachine from DB" ] }, 90:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 0 existing VirtualMachine" ] }, 107:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 3.69 KiB response in 1021.74ms" ] }, 94:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 7 VirtualMachine from VCenter" ] }, 90:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Ready to store VirtualMachine" ] }, 0:, 95:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Loading existing Datastore from DB" ] }, 85:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 0 existing Datastore" ] }, 107:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 854.00 B response in 1005.05ms" ] }, 89:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 1 Datastore from VCenter" ] }, 85:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Ready to store Datastore" ] }, 99:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "error", "There is already an active transaction" ] }, 107:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 3.53 KiB response in 1005.04ms" ] }, 97:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got VirtualMachine perDatastoreUsage" ] }, 99:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "error", "There is already an active transaction" ] }, 107:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 2.94 KiB response in 1021.77ms" ] }, 98:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 7 VirtualMachines with guest.disk" ] }, 96:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 0 vm_disk_usage objects from DB" ] }, 99:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "error", "There is already an active transaction" ] }, 107:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 808.00 B response in 1004.80ms" ] }, 96:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 7 VirtualMachines with snapshot" ] }, 94:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 0 vm_snapshot objects from DB" ] }, 99:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "error", "There is already an active transaction" ] }, 108:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 46.10 KiB response in 1011.53ms" ] }, 103:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 7 VirtualMachines with config.hardware" ] }, 94:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 0 vm_hardware objects from DB" ] }, 90:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 0 vm_disk objects from DB" ] }, 101:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 0 vm_network_adapter objects from DB" ] }, 99:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "error", "There is already an active transaction" ] }, 107:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 8.11 KiB response in 1005.62ms" ] }, 102:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 1 HostSystems with hardware.pciDevice" ] }, 98:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 0 host_pci_device objects from DB" ] }, 99:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "error", "There is already an active transaction" ] }, 108:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 14.84 KiB response in 1008.49ms" ] }, 85:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 0 HostSensors with 1" ] }, 94:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Got 0 host_sensor objects from DB" ] }, 99:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "error", "There is already an active transaction" ] }, 107:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 547.00 B response in 1004.93ms" ] }, 104:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 396.00 B response in 3.06ms" ] }, 105:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 52.06 KiB response in 8.60ms" ] }, 99:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "error", "There is already an active transaction" ] }, 104:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 394.00 B response in 3.13ms" ] }, 108:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Task \"Event Stream\" took 3.70ms on 10.99.0.10" ] }, 104:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 394.00 B response in 3.37ms" ] }, 108:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Task \"Event Stream\" took 3.68ms on 10.99.0.10" ] }, 104:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 394.00 B response in 3.47ms" ] }, 108:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Task \"Event Stream\" took 3.79ms on 10.99.0.10" ] }, 104:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 394.00 B response in 3.82ms" ] }, 108:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Task \"Event Stream\" took 4.15ms on 10.99.0.10" ] }, 104:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "SOAPClient: got 394.00 B response in 3.96ms" ] }, 108:{ "jsonrpc":"2.0", "method":"logger.log", "params":[ "debug", "Task \"Event Stream\" took 4.29ms on 10.99.0.10" ] }

[Thomas-Gelf]

This is the exact same error :-( You're on e206488, correct?

[mikeb93]

This is the exact same error :-( You're on e206488, correct?

yep it's the latest. Got your change, pulled and tried again.

[Thomas-Gelf]

Any chance to provide me direct access to this lab host? Please contact me at thomas@gelf.net if you see a chance to make this possible, it could speed things up. I'm unable to reproduce this problem here. In the meantime I'll fire up a new Ubuntu 18.04 container, seems this is what you're using. Still unsure whether this will help, but I'll figure it out.

[mikeb93]

Sure it's my home setup.

[Thomas-Gelf]

Just for the records, reason for this was negative (!!) Host Memory Usage on a running VM. VM also showed zero uptime, but was running for quite some time. While debugging this we discovered some flaws in our error handling, this has been improved.

@mikeb93, thanks for your time!

[mikeb93]

@Thomas-Gelf
sure, happy to help out :)
I've just sent you the debug info for the vCenter instance. Maybe there is some valuable info in there for you, too.

[Thomas-Gelf]

Maybe this could be added to the docs as part of the install process: [..]

Followup: mentioned the User in d147e6c.