Android Clients connect CMS too often (> 1.7 R52)

Hi,
I use Xibo 1.7.4 and have 9 clients running, the update interval for all of them is set to 10 minutes. But 6 of them connect the CMS EVERY SINGLE minute! These are the android clients using 1.7 R53, R55 and R56.

I have two android clients with R52 who behave as expected, they only fetch new data every 10 minutes. My one and only windows client is also doing fine.
I tested it with different Layouts, also running one single static layout (without RSS, Twitter etc.) on all of clients.

Anyone experienced the same? Is there something I can do?

Thanks,

Michael

Hi Michael,

Well, as you know android client should check with CMS every collection interval, it seems odd that some of your devices are trying to reach CMS every minute. Although even if they do, if there aren’t any changes to schedule/content for them then it shouldn’t be a problem.

Sorry for asking, but are you 100% sure that all of your devices are assigned to the same display profile? (with 10 min collection interval)

Hi Peter,

thanks for your reply. Yes, they are all using the same profile, I also doublechecked the settings in Display -> Edit -> Advanced.
As I found out now, the devices pull new updates only after the 10 minutes cycle. But they really access the CMS between the cycles every minute, as shown in the column “last accessed” in the display menu. And I checked the apache logs where I can also find these connects.
If I assign a new layout to one of the screens, the status changes remains “Display is out of date but has not checked in with the server” although the “Last Accessed” time updates every minute until the next 10-minute-cycle is completed.

By now, this isn’t really a problem for me. But with more clients this could be a performance issue…

Thanks,

Michael

There are a few things that trigger communication outside of the collection interval (see here for more information).

As you have a static layout it is unlikely to be a “resource download”, which leaves:

  • downloading library media - i.e. stored files.
  • notifying the current layout (if switched on)
  • sending a screenshot (if switched on)

Stats/Logs, etc are only sent every collection interval.

Do you have any error messages on the status screen of the player itself? Perhaps it is having trouble saving a file and therefore attempted a repeat download.

Hi dan,
thanks, I checked all of these points.

Layout notify is switched off, no screenshot is requested and the necessary library files have been downloaded completly. There’s no error message in the status screen and “Last 5 log messages” is empty. There are no queued download connections and all files are up to date, no invalid layouts.

Could there be something else the client is trying to get which doesn’t result in a full login and doesn’t start the download of an updated schedule and library files?

Michael

Can you get a web server access log showing the URL they are requesting?

Here are the log entries of one of my clients outside of the collection interval:

xxx.xxx.xxx.xxx - - [15/Sep/2015:16:28:30 +0200] “POST /system/xmds.php?v=4 HTTP/1.1” 200 3056 “-” "ksoap2-android/2.6.0+"
xxx.xxx.xxx.xxx - - [15/Sep/2015:16:28:30 +0200] “POST /system/xmds.php?v=4 HTTP/1.1” 200 3656 “-” "ksoap2-android/2.6.0+"
xxx.xxx.xxx.xxx - - [15/Sep/2015:16:28:30 +0200] “POST /system/xmds.php?v=4 HTTP/1.1” 200 3910 “-” "ksoap2-android/2.6.0+"
xxx.xxx.xxx.xxx - - [15/Sep/2015:16:28:30 +0200] “POST /system/xmds.php?v=4 HTTP/1.1” 200 3082 “-” "ksoap2-android/2.6.0+"
xxx.xxx.xxx.xxx - - [15/Sep/2015:16:29:19 +0200] “POST /system/xmds.php?v=4 HTTP/1.1” 200 2994 “-” "ksoap2-android/2.6.0+"
xxx.xxx.xxx.xxx - - [15/Sep/2015:16:29:19 +0200] “POST /system/xmds.php?v=4 HTTP/1.1” 200 3684 “-” "ksoap2-android/2.6.0+"
xxx.xxx.xxx.xxx - - [15/Sep/2015:16:29:20 +0200] “POST /system/xmds.php?v=4 HTTP/1.1” 200 2967 “-” "ksoap2-android/2.6.0+"
xxx.xxx.xxx.xxx - - [15/Sep/2015:16:29:20 +0200] “POST /system/xmds.php?v=4 HTTP/1.1” 200 3413 “-” "ksoap2-android/2.6.0+"
xxx.xxx.xxx.xxx - - [15/Sep/2015:16:29:20 +0200] “POST /system/xmds.php?v=4 HTTP/1.1” 200 3474 “-” "ksoap2-android/2.6.0+"
xxx.xxx.xxx.xxx - - [15/Sep/2015:16:30:01 +0200] “POST /system/xmds.php?v=4 HTTP/1.1” 200 3281 “-” "ksoap2-android/2.6.0+"
xxx.xxx.xxx.xxx - - [15/Sep/2015:16:30:01 +0200] “POST /system/xmds.php?v=4 HTTP/1.1” 200 3474 “-” "ksoap2-android/2.6.0+"
xxx.xxx.xxx.xxx - - [15/Sep/2015:16:30:43 +0200] “POST /system/xmds.php?v=4 HTTP/1.1” 200 3671 “-” "ksoap2-android/2.6.0+"
xxx.xxx.xxx.xxx - - [15/Sep/2015:16:30:43 +0200] “POST /system/xmds.php?v=4 HTTP/1.1” 200 3023 “-” "ksoap2-android/2.6.0+"
xxx.xxx.xxx.xxx - - [15/Sep/2015:16:30:43 +0200] “POST /system/xmds.php?v=4 HTTP/1.1” 200 3110 “-” "ksoap2-android/2.6.0+"
xxx.xxx.xxx.xxx - - [15/Sep/2015:16:30:43 +0200] “POST /system/xmds.php?v=4 HTTP/1.1” 200 3073 “-” "ksoap2-android/2.6.0+"
xxx.xxx.xxx.xxx - - [15/Sep/2015:16:30:43 +0200] “POST /system/xmds.php?v=4 HTTP/1.1” 200 3474 “-” “ksoap2-android/2.6.0+”

Hi Dan,
could you discover anything that is going wrong?

Michael

Sorry, it is on my ever expanding list of things to look at :smile:

A POST to xmds.php?v=4 means it is something in the SOAP service, which also means it is fairly limited as to what it can be.

The only things in the SOAP service that are called outside of the collection interval are the items mentioned previously - so I am rather confused.

Does your bandwidth statistics highlight anything in particular?
Were all those requests from the same IP?

And now it’s me who is late… :wink:

I can’t see anything unusual in the bandwidth statistics. The used bandwidth is nearly the same for those clients connecting every minute and those who behave normal.

And yes, the requests in the example where all from the same IP.

If you enable auditing for that display, then hopefully it should start logging what it’s doing to the CMS log. You can then export that and redact anything sensitive and share it here.

Hi,

I could not post the log of one of the clients of the last 10 minutes here because it had 10 times more characters than the amount allowed.
I uploaded the file here:
http://212.227.85.71/log.txt

Hope you can find a reason…

Thanks!!

Michael

So do the SubmitStats events tie up with the extra connections you see? It looks to me like they do.

In which case it’s just the number of statistics being generated on the Player and then being uploaded back to the CMS. The number generated will depend on the schedule so it could well differ between Players on the same server.

XFA R56 has an option to turn off stats reporting - however that option is only available in 1.8 CMS.

You may be able to patch your 1.7 CMS by adding this array element to this in 1.7.

Stats should only be sent back once every collection interval, which may mean that this is not the root cause.


Actually in those logs, the entire “collection” - schedule, requirefiles, stats, etc is happening every minute which implies that the collection interval is set to 1 minute for that particular display.

If we look at the RegisterDisplay response we see:

<display status="0" code="READY" message="Display is active and ready to start." version_instructions=""><emailAddress type="string">service@nameofsite.de</emailAddress><settingsPassword type="string"></settingsPassword><collectInterval type="int">60</collectInterval><orientation type="int">0</orientation><startOnBoot type="checkbox">1</startOnBoot><actionBarMode type="int">1</actionBarMode><actionBarDisplayDuration type="int">30</actionBarDisplayDuration><screenDimensions type="string"></screenDimensions><autoRestart type="checkbox">1</autoRestart><startOnBootDelay type="int">60</startOnBootDelay><blacklistVideo type="checkbox">1</blacklistVideo><storeHtmlOnInternal type="checkbox">0</storeHtmlOnInternal><sendCurrentLayoutAsStatusUpdate type="checkbox">0</sendCurrentLayoutAsStatusUpdate><screenShotRequestInterval type="int">0</screenShotRequestInterval><expireModifiedLayouts type="checkbox">0</expireModifiedLayouts><screenShotIntent type="string"></screenShotIntent><updateStartWindow type="string">0</updateStartWindow><updateEndWindow type="string">0</updateEndWindow><downloadStartWindow type="string">0</downloadStartWindow><downloadEndWindow type="string">0</downloadEndWindow><webViewPluginState type="string">DEMAND</webViewPluginState><displayName type="string">15-R

This has ended badly!

I now wonder if there is a character in your display name that has broken the XML generated and therefore your displays haven’t reconfigured themselves…

Dan, Alex, I’m SO SORRY!! I logged the wrong display…
This one and only device was switched some days ago to an update interval of 1 minute for testing layouts.

I’ll log one of the other clients now and come back to you.

Sorry again for the mistage!

I observed another of the concerned clients which is set to an update interval of 5 minutes. As described before it really fetches new layout or media only every 5 minutes but connects to the server every minute. The timestamp in “Last Accessed” in “Dispays” changes every minute and I have matching connects in the apache log.

I now activated auditing for this client. But surprisingly there are only entries in the Xibo Log every 5 minutes!!!

You can find a new apache log (filtered by the IP of the client) here:
http://212.227.85.71/log2.txt
No other client is working with this IP. The domain name and the IP are altered for this post, the rest is untouched.

The Apache log won’t tell us anything we haven’t found out already.

If Auditing that display isn’t getting anything in the log then put the whole CMS in to Audit mode. There will be loads of logs but then you can tie up the access times from your Apache log against the actions the CMS is taking at the time.

Any set of calls that isn’t immediately preceeded by

123.123.122.138 - - [23/Oct/2015:08:03:38 +0200] "GET /system/xmds.php?what HTTP/1.1" 200 1 "-" "okhttp/2.2.0"

Is an “out of collection” call.

As you have screenshot and notify disabled I propose that this is a GetResource call and that you have a ticker or dataset on one of the Layouts scheduled on those displays set to an update interval of 0, which means it will update ever time it is loaded.

You must be accessing the CMS on the same android display then?

You must be accessing the CMS on the same android display then?

No, I meant that I have some clients running connectint my CMS. But some of the clients have different IPs so I can sperate this special one in the apache log. By the way: This is hard to do in the audit log of xibo…

I now got a log sequence of which should be out of the collect interval.

Isn’t “LayoutInformation” the notify which Layout is running on the client? I doublechecked all settings, notify is switched off in the CMS. Or is this something else??

243365	15-10-25 03:14:33	CMS	TranslationEngine	InitLocale	Resolved language en_EN not available.
243366	15-10-25 03:14:33	CMS	TranslationEngine	InitLocale	Resolved language en_EN not available.
243367	15-10-25 03:14:33	CMS	XMDSSoap4	RegisterDisplay	serverKey: [abcdefghijkl], hardwareKey: [fdfadsfasdfasdfdasfd], displayName: [dfadfadsfasdf]
243368	15-10-25 03:14:33	CMS	DisplayProfile	Load	Load DisplayProfileId: 6
243369	15-10-25 03:14:33	CMS	Display	Touch	IN
243370	15-10-25 03:14:33	CMS	TranslationEngine	InitLocale	Resolved language en_EN not available.
243371	15-10-25 03:14:33	CMS	Display	Touch	IN
243372	15-10-25 03:14:34	CMS	TranslationEngine	InitLocale	Resolved language en_EN not available.
243373	15-10-25 03:14:34	CMS	Display	Touch	IN
243374	15-10-25 03:14:34	CMS	layout	LayoutInformation	[IN]
243375	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243376	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243377	15-10-25 03:14:34	CMS	layout	SetDomXML	Loading LayoutXml into the DOM
243378	15-10-25 03:14:34	CMS	layout	SetDomXML	Loaded LayoutXml into the DOM
243379	15-10-25 03:14:34	CMS	layout	GetRegionList	[IN] Loaded XML into DOM
243380	15-10-25 03:14:34	CMS	layout	GetRegionList	[OUT]
243381	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 5406999454e35a95ca7e8
243382	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243383	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243384	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243385	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 18104799555548a2d667243
243386	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243387	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243388	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243389	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 11429676155548ec103d2d3
243390	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243391	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243392	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243393	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 289080194554b23860eb6c
243394	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243395	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243396	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243397	15-10-25 03:14:34	CMS	layout	LayoutInformation	[IN]
243398	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243399	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243400	15-10-25 03:14:34	CMS	layout	SetDomXML	Loading LayoutXml into the DOM
243401	15-10-25 03:14:34	CMS	layout	SetDomXML	Loaded LayoutXml into the DOM
243402	15-10-25 03:14:34	CMS	layout	GetRegionList	[IN] Loaded XML into DOM
243403	15-10-25 03:14:34	CMS	layout	GetRegionList	[OUT]
243404	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 55924f2332ffd
243405	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243406	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243407	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243408	15-10-25 03:14:34	CMS	layout	LayoutInformation	[IN]
243409	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243410	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243411	15-10-25 03:14:34	CMS	layout	SetDomXML	Loading LayoutXml into the DOM
243412	15-10-25 03:14:34	CMS	layout	SetDomXML	Loaded LayoutXml into the DOM
243413	15-10-25 03:14:34	CMS	layout	GetRegionList	[IN] Loaded XML into DOM
243414	15-10-25 03:14:34	CMS	layout	GetRegionList	[OUT]
243415	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 5406999454e35a95ca7e8
243416	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243417	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243418	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243419	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 504198138554cec6557141
243420	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243421	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243422	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243423	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 23952561455ddf912a4839
243424	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243425	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243426	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243427	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 1706482653561e86bc983ac
243428	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243429	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243430	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243431	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 988910625620f790cef94
243432	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243433	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243434	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243435	15-10-25 03:14:34	CMS	layout	LayoutInformation	[IN]
243436	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243437	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243438	15-10-25 03:14:34	CMS	layout	SetDomXML	Loading LayoutXml into the DOM
243439	15-10-25 03:14:34	CMS	layout	SetDomXML	Loaded LayoutXml into the DOM
243440	15-10-25 03:14:34	CMS	layout	GetRegionList	[IN] Loaded XML into DOM
243441	15-10-25 03:14:34	CMS	layout	GetRegionList	[OUT]
243442	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 5406999454e35a95ca7e8
243443	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243444	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243445	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243446	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 504198138554cec6557141
243447	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243448	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243449	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243450	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 23952561455ddf912a4839
243451	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243452	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243453	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243454	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 147784156655ddf92504cbf
243455	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243456	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243457	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243458	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 167544300755ddf99f4d2e5
243459	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243460	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243461	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243462	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 4339413855620f9a97489b
243463	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243464	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243465	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243466	15-10-25 03:14:34	CMS	layout	LayoutInformation	[IN]
243467	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243468	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243469	15-10-25 03:14:34	CMS	layout	SetDomXML	Loading LayoutXml into the DOM
243470	15-10-25 03:14:34	CMS	layout	SetDomXML	Loaded LayoutXml into the DOM
243471	15-10-25 03:14:34	CMS	layout	GetRegionList	[IN] Loaded XML into DOM
243472	15-10-25 03:14:34	CMS	layout	GetRegionList	[OUT]
243473	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 5406999454e35a95ca7e8
243474	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243475	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243476	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243477	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 11429676155548ec103d2d3
243478	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243479	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243480	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243481	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 18419900965571413875271
243482	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243483	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243484	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243485	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 189749164655d4c6951a676
243486	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243487	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243488	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243489	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 174386243555d4ca4fe8cee
243490	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243491	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243492	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243493	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 26392257055de0a9ff00ed
243494	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243495	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243496	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243497	15-10-25 03:14:34	CMS	layout	LayoutInformation	Assessing Region: 47431614655ef2f95cefd9
243498	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	IN
243499	15-10-25 03:14:34	CMS	Layout	GetLayoutXml	OUT
243500	15-10-25 03:14:34	CMS	layout	LayoutInformation	Finished with Region
243501	15-10-25 03:14:34	CMS	TranslationEngine	InitLocale	Resolved language en_EN not available.
243502	15-10-25 03:14:34	CMS	Display	Touch	IN
243503	15-10-25 03:14:34	CMS	Display	Touch	IN
243504	15-10-25 03:14:35	CMS	TranslationEngine	InitLocale	Resolved language en_EN not available.
243505	15-10-25 03:14:35	CMS	Display	Touch	IN
243506	15-10-25 03:14:35	CMS	TranslationEngine	InitLocale	Resolved language en_EN not available.
243507	15-10-25 03:14:35	CMS	Display	Touch	IN
243508	15-10-25 03:14:35	CMS	Display	Touch	IN