info output empty every now and then since 4.2

[calestyo]

Hi.

Since upgrading to 4.2.x we're having a problem that our monitoring shows interruptions in the data every now and then like this:

(both show the used size of a space reservation, each at a different scale)

Turns out that our montoring tool, which downloads
http://lcg-lrz-dcache0.grid.lrz.de:59998/info/reservations every 5 mins gets back an empty XML reply like this:

<?xml version="1.0"?>
<dCache xmlns="http://www.dcache.org/2008/01/Info"/>

every time the graph gets no data.

Port 59998 is the httpd, the exact version is 4.2.23-1.

There's nothing special in the info log, apart from the usual spaming happening since… (#1970):

Feb 10 20:12:54 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:12:54+01:00 (info) [] DGA CellInfoDga triggering too quickly (-23ms): engaging safety.
Feb 10 20:14:05 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:14:05+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-22ms): engaging safety.
Feb 10 20:14:54 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:14:54+01:00 (info) [] DGA CellInfoDga triggering too quickly (-23ms): engaging safety.
Feb 10 20:15:05 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:15:05+01:00 (info) [] DGA ListBasedMessageDga[PoolManager, pools, psux ls pool] triggering too quickly (41ms): engaging safety.
Feb 10 20:16:05 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:16:05+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-16ms): engaging safety.
Feb 10 20:16:54 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:16:54+01:00 (info) [] DGA CellInfoDga triggering too quickly (-23ms): engaging safety.
Feb 10 20:17:34 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:17:34+01:00 (info) [] DGA RoutingMgrDga triggering too quickly (-37ms): engaging safety.
Feb 10 20:18:05 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:18:05+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-24ms): engaging safety.
Feb 10 20:18:54 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:18:54+01:00 (info) [] DGA CellInfoDga triggering too quickly (-25ms): engaging safety.
Feb 10 20:20:05 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:20:05+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-24ms): engaging safety.
Feb 10 20:20:54 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:20:54+01:00 (info) [] DGA CellInfoDga triggering too quickly (-22ms): engaging safety.
Feb 10 20:22:06 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:22:06+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-25ms): engaging safety.
Feb 10 20:22:34 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:22:34+01:00 (info) [] DGA RoutingMgrDga triggering too quickly (-18ms): engaging safety.
Feb 10 20:22:54 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:22:54+01:00 (info) [] DGA CellInfoDga triggering too quickly (7ms): engaging safety.
Feb 10 20:24:06 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:24:06+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-25ms): engaging safety.
Feb 10 20:24:54 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:24:54+01:00 (info) [] DGA CellInfoDga triggering too quickly (-23ms): engaging safety.
Feb 10 20:25:06 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:25:06+01:00 (info) [] DGA ListBasedMessageDga[PoolManager, pools, psux ls pool] triggering too quickly (44ms): engaging safety.
Feb 10 20:26:06 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:26:06+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-22ms): engaging safety.
Feb 10 20:26:54 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:26:54+01:00 (info) [] DGA CellInfoDga triggering too quickly (-16ms): engaging safety.
Feb 10 20:27:35 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:27:35+01:00 (info) [] DGA RoutingMgrDga triggering too quickly (-41ms): engaging safety.
Feb 10 20:28:06 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:28:06+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-24ms): engaging safety.
Feb 10 20:28:55 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:28:55+01:00 (info) [] DGA CellInfoDga triggering too quickly (-23ms): engaging safety.
Feb 10 20:30:06 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:30:06+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-19ms): engaging safety.
Feb 10 20:30:55 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:30:55+01:00 (info) [] DGA CellInfoDga triggering too quickly (-18ms): engaging safety.
Feb 10 20:32:06 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:32:06+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-24ms): engaging safety.
Feb 10 20:32:35 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:32:35+01:00 (info) [] DGA RoutingMgrDga triggering too quickly (-39ms): engaging safety.
Feb 10 20:32:55 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:32:55+01:00 (info) [] DGA CellInfoDga triggering too quickly (-22ms): engaging safety.
Feb 10 20:34:06 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:34:06+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-26ms): engaging safety.
Feb 10 20:34:55 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:34:55+01:00 (info) [] DGA CellInfoDga triggering too quickly (-24ms): engaging safety.
Feb 10 20:36:06 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:36:06+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-24ms): engaging safety.
Feb 10 20:36:55 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:36:55+01:00 (info) [] DGA CellInfoDga triggering too quickly (-21ms): engaging safety.
Feb 10 20:37:35 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:37:35+01:00 (info) [] DGA RoutingMgrDga triggering too quickly (-15ms): engaging safety.
Feb 10 20:38:07 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:38:07+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-13ms): engaging safety.
Feb 10 20:38:55 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:38:55+01:00 (info) [] DGA CellInfoDga triggering too quickly (-18ms): engaging safety.
Feb 10 20:40:07 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:40:07+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-12ms): engaging safety.
Feb 10 20:40:55 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:40:55+01:00 (info) [] DGA CellInfoDga triggering too quickly (-21ms): engaging safety.
Feb 10 20:42:07 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:42:07+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-18ms): engaging safety.
Feb 10 20:42:35 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:42:35+01:00 (info) [] DGA RoutingMgrDga triggering too quickly (-21ms): engaging safety.
Feb 10 20:42:55 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:42:55+01:00 (info) [] DGA CellInfoDga triggering too quickly (-22ms): engaging safety.
Feb 10 20:44:07 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:44:07+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-22ms): engaging safety.
Feb 10 20:44:56 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:44:56+01:00 (info) [] DGA CellInfoDga triggering too quickly (-37ms): engaging safety.
Feb 10 20:46:07 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:46:07+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-22ms): engaging safety.
Feb 10 20:46:56 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:46:56+01:00 (info) [] DGA CellInfoDga triggering too quickly (-18ms): engaging safety.
Feb 10 20:47:35 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:47:35+01:00 (info) [] DGA RoutingMgrDga triggering too quickly (-8ms): engaging safety.
Feb 10 20:48:07 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:48:07+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-14ms): engaging safety.
Feb 10 20:48:56 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:48:56+01:00 (info) [] DGA CellInfoDga triggering too quickly (-23ms): engaging safety.
Feb 10 20:50:07 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:50:07+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-22ms): engaging safety.
Feb 10 20:50:56 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:50:56+01:00 (info) [] DGA CellInfoDga triggering too quickly (-19ms): engaging safety.
Feb 10 20:52:07 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:52:07+01:00 (info) [] DGA StaticDomainDga triggering too quickly (5ms): engaging safety.
Feb 10 20:52:08 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:52:08+01:00 (info) [] DGA ListBasedMessageDga[PoolManager, units, psux ls unit] triggering too quickly (-61ms): engaging safety.
Feb 10 20:52:35 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:52:35+01:00 (info) [] DGA RoutingMgrDga triggering too quickly (-10ms): engaging safety.
Feb 10 20:52:56 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:52:56+01:00 (info) [] DGA CellInfoDga triggering too quickly (-13ms): engaging safety.
Feb 10 20:54:08 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:54:08+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-22ms): engaging safety.
Feb 10 20:54:56 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:54:56+01:00 (info) [] DGA CellInfoDga triggering too quickly (-36ms): engaging safety.
Feb 10 20:56:08 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:56:08+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-23ms): engaging safety.
Feb 10 20:56:56 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:56:56+01:00 (info) [] DGA CellInfoDga triggering too quickly (-21ms): engaging safety.
Feb 10 20:57:36 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:57:36+01:00 (info) [] DGA RoutingMgrDga triggering too quickly (-20ms): engaging safety.
Feb 10 20:58:08 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:58:08+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-19ms): engaging safety.
Feb 10 20:58:56 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 20:58:56+01:00 (info) [] DGA CellInfoDga triggering too quickly (-38ms): engaging safety.
Feb 10 21:00:08 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 21:00:08+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-6ms): engaging safety.
Feb 10 21:00:56 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 21:00:56+01:00 (info) [] DGA CellInfoDga triggering too quickly (-7ms): engaging safety.
Feb 10 21:01:08 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 21:01:08+01:00 (info) [] DGA ListBasedMessageDga[PoolManager, poolgroups, psux ls pgroup] triggering too quickly (-330ms): engaging safety.
Feb 10 21:01:08 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 21:01:08+01:00 (info) [] DGA ListBasedMessageDga[PoolManager, pools, psux ls pool] triggering too quickly (-48ms): engaging safety.
Feb 10 21:02:08 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 21:02:08+01:00 (info) [] DGA StaticDomainDga triggering too quickly (-19ms): engaging safety.
Feb 10 21:02:36 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 21:02:36+01:00 (info) [] DGA RoutingMgrDga triggering too quickly (-17ms): engaging safety.
Feb 10 21:02:57 lcg-lrz-dcache0 dcache@info0[219026]: 2019-02-10 21:02:57+01:00 (info) [] DGA CellInfoDga triggering too quickly (-17ms): engaging safety.

Nothing in the httpd log.

Any ideas?

Cheers,
Chris.

[calestyo]

Anything one can do to fix this issue? Still happens in 6.0

[calestyo]

And it also affects critical stuff, like the output from /usr/sbin/dcache-storage-descriptor is broken all few invocations

[paulmillar]

Sorry for the delay.

Could you check the space-manager log file, to see if there are any errors reported there?

Cheers,
Paul.

[calestyo]

Could you check the space-manager log file, to see if there are any errors reported there?

No:

/var/log/dcache# grep -i SpaceManager storagesystem0.log 
/var/log/dcache# 

but we do have a permanent:

Nov 16 16:27:25 lcg-lrz-dcache0 dcache@info0[17942]: 2021-11-16 16:27:25+01:00 (info) [] DGA RoutingMgrDga triggering too quickly (28ms): engaging safety.
Nov 16 16:28:50 lcg-lrz-dcache0 dcache@info0[17942]: 2021-11-16 16:28:50+01:00 (info) [] DGA StaticDomainDga triggering too quickly (26ms): engaging safety.
Nov 16 16:29:18 lcg-lrz-dcache0 dcache@info0[17942]: 2021-11-16 16:29:18+01:00 (info) [] DGA CellInfoDga triggering too quickly (27ms): engaging safety.
Nov 16 16:30:50 lcg-lrz-dcache0 dcache@info0[17942]: 2021-11-16 16:30:50+01:00 (info) [] DGA StaticDomainDga triggering too quickly (25ms): engaging safety.
Nov 16 16:31:18 lcg-lrz-dcache0 dcache@info0[17942]: 2021-11-16 16:31:18+01:00 (info) [] DGA CellInfoDga triggering too quickly (26ms): engaging safety.
Nov 16 16:32:25 lcg-lrz-dcache0 dcache@info0[17942]: 2021-11-16 16:32:25+01:00 (info) [] DGA RoutingMgrDga triggering too quickly (26ms): engaging safety.
Nov 16 16:32:50 lcg-lrz-dcache0 dcache@info0[17942]: 2021-11-16 16:32:50+01:00 (info) [] DGA StaticDomainDga triggering too quickly (25ms): engaging safety.
Nov 16 16:33:18 lcg-lrz-dcache0 dcache@info0[17942]: 2021-11-16 16:33:18+01:00 (info) [] DGA CellInfoDga triggering too quickly (25ms): engaging safety.
Nov 16 16:34:50 lcg-lrz-dcache0 dcache@info0[17942]: 2021-11-16 16:34:50+01:00 (info) [] DGA StaticDomainDga triggering too quickly (26ms): engaging safety.
Nov 16 16:35:18 lcg-lrz-dcache0 dcache@info0[17942]: 2021-11-16 16:35:18+01:00 (info) [] DGA CellInfoDga triggering too quickly (25ms): engaging safety.
Nov 16 16:36:50 lcg-lrz-dcache0 dcache@info0[17942]: 2021-11-16 16:36:50+01:00 (info) [] DGA StaticDomainDga triggering too quickly (26ms): engaging safety.
Nov 16 16:37:18 lcg-lrz-dcache0 dcache@info0[17942]: 2021-11-16 16:37:18+01:00 (info) [] DGA CellInfoDga triggering too quickly (27ms): engaging safety.
Nov 16 16:37:25 lcg-lrz-dcache0 dcache@info0[17942]: 2021-11-16 16:37:25+01:00 (info) [] DGA RoutingMgrDga triggering too quickly (26ms): engaging safety.

as reported in #1970. Though this may be unrelated, as we get the warnings even when the data is not missing from info.

Also not, that we're running a bit outdated (6.0.18-1).

Cheers,
Chris

[paulmillar]

Thanks for checking, Chris.

Do you think the SpaceManager database is running slowly?

Perhaps you could enable PostGreSQL's slow query logging feature for the space-manager database and see if there are any queries taking longer than 100 ms (just to pull a duration out of thin air)?

You should also upgrade your dCache version.

I strongly doubt upgrading from 6.0 to 6.2 (or newer) will fix this problem; however, that version is now out of support. Therefore, you'll need to upgrade anyway, once this problem is fixed 😉

Cheers,
Paul.

[calestyo]

No, I don't think there are DB load issues... the node has generally a very low load... and I think we have slow query logging even on already and it doesn't give any.

Especially since the problem occurred right after upgrading to 4.2.x without any other major config changes, it seems rather like a regression.

Cheers,
Chris.

[calestyo]

This is also still a bug in 2.7.10... and numerous sites suffer from it, with output like that of dcache-storage-descriptor being broken, leading to errors on other ends...

Isn't there anything one can do to fix this?!?

[calestyo]

Can it be that /info/reservations is completely gone from the info’s XML?!?!!?!

[calestyo]

This might be another issue:

[dCache0] (info@info2) admin > watchers ls
State Watchers:
  PoolgroupSpaceWatcher (enabled, triggered: 862)
  PoolsSummaryMaintainer (enabled, triggered: 68)
  LinkgroupTotalSpaceMaintainer (enabled, triggered: 44)
  LinkSpaceMaintainer (enabled, triggered: 69)
  NormalisedAccessSpaceMaintainer (enabled, triggered: 69)
  ReservationByDescMaintainer (enabled, triggered: 0)

Seems it doesn't upgrade the Reservations.. but why?

[calestyo]

ping @paulmillar @kofemann ... I was told today that numerous ATLAS sites suffer from this.

[kofemann]

Hi Chris,

can you elaborate on ATLAS sites suffer from this?Any details? We have seen any report.