XScheduler web interface becomes unresponsive

[PKingRoch]

Driving my show from the Web API provided in the documentation, after 10 hours of operation, the scheduler stops responding.

This is xLights Scheduler 2018.37 running on Windows 10 1803.

I have been able to reproduce this several times. The Web API becomes unresponsive and the tools web interface will not display anything, Let me know what you need and I can provide it.

[PKingRoch]

This happens every day. I have a program to kill and restart the scheduler, so it isn't that big of a deal. If I don't do that, the web server doesn't respond. If I do, everything every thing is fine.

Happening still with X.44

[keithsw1111]

Changes have been made in .46 to address this.

[PKingRoch]

I didn't recognize anything in the change log. What did you change?

[keithsw1111]

Not everything makes it to the change log ... to see all changes you need to look at the git check in log.

[PKingRoch]

I pulled .47 yesterday and had my show run with it last night. This morning, the web server isn't responding like before, so this is still an issue. Would you like me to get a dump of the process when it is in this state to help with debugging?

[keithsw1111]

I need to see logs. Are you making get requests or websockets?

[PKingRoch]

How can I get you the logs? I'm making web(get) requests.

[PKingRoch]

xSchedule_l4cpp.log The log is odd. I don't see anything in it after the restart at 4:15pm yesterday. All of the other calls for the show are missing until today when I restarted the scheduler.

[keithsw1111]

Yeah I dont see any web requests at all in that log ... successful or not.

[PKingRoch]

I've been noticing some strangeness in the log. If I restart xScheduler with my app, it doesn't log correctly for some reason. I just now manually restarted after my restart step ran. Let me see if I can get any logging for you after this runs tonight.

[keithsw1111]

Likely because you start it from the wrong current working directory

[PKingRoch]

The logging goes into the CWD of where the process start was called? OK. I can make that change on the restarter. Either way, I'll have logging after running my show tonight. It's logging and working right now.

[keithsw1111]

Logging is controlled by the properties file. If it isnt in the CWD then it wont log.

[PKingRoch]

xSchedule_l4cpp.log.zip Here's a zip of the logging files from last night. The scheduler web interface was unresponsive this morning. Let me know what else I can do to help.

[PKingRoch]

I have fixed the CWD/logging issue in my restarter app.

[keithsw1111]

I can see it working in the log at 2018-11-26 07:20:38

[PKingRoch]

Working isn't what it is really doing. It may be getting my request, but it stops servicing them. I see this in the log at that time stamp:

2018-11-26 07:20:38,392 4768 log_base [INFO] Redirecting to 'http://localhost/xScheduleWeb/index.html'. 2018-11-26 07:20:38,400 4768 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/index.html' : '/xScheduleWeb/index.html'. 2018-11-26 07:20:38,415 4768 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/css/bootstrap.min.css' : '/xScheduleWeb/css/bootstrap.min.css'. 2018-11-26 07:20:38,939 4768 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/assets/dataTables.bootstrap4.min.js' : '/xScheduleWeb/js/assets/dataTables.bootstrap4.min.js'. 2018-11-26 07:20:39,440 4768 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/css/bootstrap-slider.min.css' : '/xScheduleWeb/css/bootstrap-slider.min.css'. 2018-11-26 07:20:39,940 4768 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/sidebar.js' : '/xScheduleWeb/js/sidebar.js'. 2018-11-26 07:20:40,441 4768 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/assets/reconnecting-websocket.min.js' : '/xScheduleWeb/js/assets/reconnecting-websocket.min.js'. 2018-11-26 07:20:40,942 4768 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/pageNavagation.js' : '/xScheduleWeb/js/pageNavagation.js'. 2018-11-26 07:20:41,442 4768 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/toggleButtons.js' : '/xScheduleWeb/js/toggleButtons.js'. 2018-11-26 07:20:41,943 4768 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/webSocket.js' : '/xScheduleWeb/js/webSocket.js'. 2018-11-26 07:20:42,443 4768 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/xyzzy.js' : '/xScheduleWeb/js/xyzzy.js'.

Unfortunately, the browser is blank and this is all the farther it goes on the scheduler web server.

This is what the log file looks like when it' working:

2018-11-26 14:44:47,422 1760 log_base [INFO] Redirecting to 'http://localhost/xScheduleWeb/index.html'. 2018-11-26 14:44:47,426 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/index.html' : '/xScheduleWeb/index.html'. 2018-11-26 14:44:47,433 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/css/bootstrap.min.css' : '/xScheduleWeb/css/bootstrap.min.css'. 2018-11-26 14:44:47,436 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/css/dataTables.bootstrap.min.css' : '/xScheduleWeb/css/dataTables.bootstrap.min.css'. 2018-11-26 14:44:47,446 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/css/bootstrap-slider.min.css' : '/xScheduleWeb/css/bootstrap-slider.min.css'. 2018-11-26 14:44:47,447 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/css/bootstrap-colorpicker.min.css' : '/xScheduleWeb/css/bootstrap-colorpicker.min.css'. 2018-11-26 14:44:47,459 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/assets/jquery.min.js' : '/xScheduleWeb/js/assets/jquery.min.js'. 2018-11-26 14:44:47,499 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/assets/bootstrap.min.js' : '/xScheduleWeb/js/assets/bootstrap.min.js'. 2018-11-26 14:44:47,519 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/assets/bootstrap-colorpicker.min.js' : '/xScheduleWeb/js/assets/bootstrap-colorpicker.min.js'. 2018-11-26 14:44:47,531 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/assets/bootstrap-notify.min.js' : '/xScheduleWeb/js/assets/bootstrap-notify.min.js'. 2018-11-26 14:44:47,551 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/assets/bootstrap-slider.min.js' : '/xScheduleWeb/js/assets/bootstrap-slider.min.js'. 2018-11-26 14:44:47,572 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/css/style.css' : '/xScheduleWeb/css/style.css'. 2018-11-26 14:44:47,577 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/assets/dataTables.bootstrap4.min.js' : '/xScheduleWeb/js/assets/dataTables.bootstrap4.min.js'. 2018-11-26 14:44:47,578 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/assets/jquery.dataTables.min.js' : '/xScheduleWeb/js/assets/jquery.dataTables.min.js'. 2018-11-26 14:44:47,606 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/pageNavagation.js' : '/xScheduleWeb/js/pageNavagation.js'. 2018-11-26 14:44:47,607 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/assets/reconnecting-websocket.min.js' : '/xScheduleWeb/js/assets/reconnecting-websocket.min.js'. 2018-11-26 14:44:47,608 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/core.js' : '/xScheduleWeb/js/core.js'. 2018-11-26 14:44:47,626 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/toggleButtons.js' : '/xScheduleWeb/js/toggleButtons.js'. 2018-11-26 14:44:47,628 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/webSocket.js' : '/xScheduleWeb/js/webSocket.js'. 2018-11-26 14:44:47,628 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/xyzzy.js' : '/xScheduleWeb/js/xyzzy.js'. 2018-11-26 14:44:47,630 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/sidebar.js' : '/xScheduleWeb/js/sidebar.js'. 2018-11-26 14:44:47,630 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/img/xlights.png' : '/xScheduleWeb/img/xlights.png'. 2018-11-26 14:44:47,662 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/pages/home.html' : '/xScheduleWeb/pages/home.html'. 2018-11-26 14:44:47,675 1760 log_base [INFO] xScheduleStash received command = 'Retrieve' key = 'uiSettings'. 2018-11-26 14:44:47,687 1760 log_base [INFO] data = '{"webName":"xLights Scheduler","webColor":"#004800","notificationLevel":"1","pages":[{"page":"home","values":[true,false]},{"page":"playlists","values":[true,true]},{"page":"settings","values":[true,true]}],"navbuttons":[{"random":true,"steplooping":false,"playlistlooping":true,"volumeMute":true,"brightnessLevel":false,"outputtolights":true,"toggleMute":false}]}'. Time = 11. 2018-11-26 14:44:47,688 1760 log_base [INFO] xScheduleQuery received query = 'ListWebFolders' parameters = 'Plugins'. 2018-11-26 14:44:47,688 1760 log_base [INFO] data = '{"folders":["Buttons","Not So Big Buttons"],"reference":""}'. Time = 0. 2018-11-26 14:44:47,689 1760 log_base [INFO] xScheduleQuery received query = 'GetPlayLists' parameters = ''. 2018-11-26 14:44:47,689 1760 log_base [INFO] data = '{"playlists":[{"name":"2018 Show","id":"1","nextscheduled":"","length":"91:54.397"},{"name":"a kiss a toy","id":"2","nextscheduled":"","length":"1:36.350"},{"name":"Carol of the Bells","id":"3","nextscheduled":"","length":"2:34.350"},{"name":"Wizards of winter","id":"4","nextscheduled":"","length":"3:05.756"},{"name":"The Greatest Show - 2","id":"5","nextscheduled":"","length":"4:28.750"},{"name":"Bills 2","id":"6","nextscheduled":"","length":"1:00.850"},{"name":"So Long","id":"7","nextscheduled":"","length":"2:55.050"},{"name":"Intro","id":"8","nextscheduled":"","length":"1:25.100"},{"name":"We need a little christmas","id":"9","nextscheduled":"","length":"2:07.450"},{"name":"KCL announce","id":"10","nextscheduled":"","length":"0:55.050"},{"name":"Overdoing it","id":"11","nextscheduled":"","length":"0:28.100"},{"name":"linus and lucy","id":"12","nextscheduled":"","length":"3:06.650"},{"name":"Sleighride","id":"13","nextscheduled":"","length":"2:57.500"},{"name":"Mad Russian","id":"14","nextscheduled":"","length":"4:42.272"},{"name":"Oh Holy Night","id":"15","nextscheduled":"","length":"5:01.800"},{"name":"Dancy of the sugar plum faries","id":"16","nextscheduled":"","length":"1:52.150"},{"name":"I wanna BIG one","id":"17","nextscheduled":"","length":"0:15.900"},{"name":"fireflies","id":"18","nextscheduled":"","length":"2:30.450"},{"name":"Silver Bells","id":"19","nextscheduled":"","length":"3:11.400"},{"name":"The Christmas Song - Chipmunks","id":"20","nextscheduled":"","length":"2:23.420"},{"name":"What Child is This","id":"21","nextscheduled":"","length":"3:47.100"},{"name":"Its the most wonderful time of the year","id":"22","nextscheduled":"","length":"2:31.250"},{"name":"Buddy Cheer","id":"23","nextscheduled":"","length":"0:27.400"},{"name":"Christmas Canon","id":"24","nextscheduled":"","length":"4:18.900"},{"name":"Grinch","id":"25","nextscheduled":"","length":"0:56.100"},{"name":"White Christmas","id":"26","nextscheduled":"","length":"3:05.700"},{"name":"Christmas Eve (sarajevo)","id":"27","nextscheduled":"","length":"3:25.199"},{"name":"Celtic Christmas","id":"28","nextscheduled":"","length":"3:37.650"},{"name":"Plugged in","id":"29","nextscheduled":"","length":"0:12.600"},{"name":"Grandma Got Run Over by a Reindeer","id":"30","nextscheduled":"","length":"3:30.000"},{"name":"do you hear what i hear","id":"31","nextscheduled":"","length":"2:53.250"},{"name":"Welcome christmas","id":"32","nextscheduled":"","length":"2:13.750"},{"name":"we are santas elves","id":"33","nextscheduled":"","length":"1:36.950"},{"name":"take a piece of meat with you","id":"34","nextscheduled":"","length":"2:39.150"},{"name":"feliz navidad","id":"35","nextscheduled":"","length":"3:02.050"},{"name":"Rockin around the christmast tree","id":"36","nextscheduled":"","length":"2:03.200"},{"name":"Display Hours","id":"37","nextscheduled":"","length":"0:30.050"},{"name":"God rest ye marry gentleman","id":"38","nextscheduled":"","length":"2:29.750"},{"name":"Reminder LOR Import","id":"39","nextscheduled":"","length":"0:56.950"},{"name":"WarmUp","id":"40","nextscheduled":"2018-11-26 16:30","length":"11:25.050"},{"name":"silent night","id":"41","nextscheduled":"","length":"3:22.700"},{"name":"CoolDown","id":"42","nextscheduled":"2018-11-26 22:00","length":"12:55.000"},{"name":"Halloween","id":"43","nextscheduled":"","length":"21:36.350"},{"name":"Restart xLights Scheduler","id":"44","nextscheduled":"2018-11-26 16:15","length":"0:00.050"}],"reference":""}'. Time = 0. 2018-11-26 14:44:47,690 1760 log_base [INFO] xScheduleQuery received query = 'GetMatrices' parameters = ''. 2018-11-26 14:44:47,690 1760 log_base [INFO] data = '{"matrices":[],"reference":""}'. Time = 0. 2018-11-26 14:44:47,690 1760 log_base [DEBUG] Xyzzy created. 2018-11-26 14:44:47,690 1760 log_base [DEBUG] High score 0 . 2018-11-26 14:44:47,690 1760 log_base [DEBUG] Xyzzy reset. 2018-11-26 14:44:47,690 1760 log_base [DEBUG] Xyzzy initialising. 2018-11-26 14:44:47,690 1760 log_base [DEBUG] Xyzzy closing. 2018-11-26 14:44:47,690 1760 log_base [DEBUG] Xyzzy reset. 2018-11-26 14:44:47,692 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/img/xyzzy/Spin.wav' : '/xScheduleWeb/img/xyzzy/Spin.wav'. 2018-11-26 14:44:47,696 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/js/pageHome.js' : '/xScheduleWeb/js/pageHome.js'. 2018-11-26 14:44:47,708 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/img/xyzzy/drop.mp3' : '/xScheduleWeb/img/xyzzy/drop.mp3'. 2018-11-26 14:44:47,722 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/img/xyzzy/move.wav' : '/xScheduleWeb/img/xyzzy/move.wav'. 2018-11-26 14:44:47,739 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/img/xyzzy/gameover.wav' : '/xScheduleWeb/img/xyzzy/gameover.wav'. 2018-11-26 14:44:47,745 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/img/xyzzy/success.wav' : '/xScheduleWeb/img/xyzzy/success.wav'. 2018-11-26 14:44:47,755 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/img/xyzzy/start.wav' : '/xScheduleWeb/img/xyzzy/start.wav'. 2018-11-26 14:44:47,764 1760 log_base [INFO] File request received = 'C:\Program Files\xLights/xScheduleWeb/fonts/glyphicons-halflings-regular.woff2' : '/xScheduleWeb/fonts/glyphicons-halflings-regular.woff2'. 2018-11-26 14:44:47,834 1760 log_base [INFO] xScheduleQuery received query = 'GetPlayLists' parameters = ''. 2018-11-26 14:44:47,834 1760 log_base [INFO] data = '{"playlists":[{"name":"2018 Show","id":"1","nextscheduled":"","length":"91:54.397"},{"name":"a kiss a toy","id":"2","nextscheduled":"","length":"1:36.350"},{"name":"Carol of the Bells","id":"3","nextscheduled":"","length":"2:34.350"},{"name":"Wizards of winter","id":"4","nextscheduled":"","length":"3:05.756"},{"name":"The Greatest Show - 2","id":"5","nextscheduled":"","length":"4:28.750"},{"name":"Bills 2","id":"6","nextscheduled":"","length":"1:00.850"},{"name":"So Long","id":"7","nextscheduled":"","length":"2:55.050"},{"name":"Intro","id":"8","nextscheduled":"","length":"1:25.100"},{"name":"We need a little christmas","id":"9","nextscheduled":"","length":"2:07.450"},{"name":"KCL announce","id":"10","nextscheduled":"","length":"0:55.050"},{"name":"Overdoing it","id":"11","nextscheduled":"","length":"0:28.100"},{"name":"linus and lucy","id":"12","nextscheduled":"","length":"3:06.650"},{"name":"Sleighride","id":"13","nextscheduled":"","length":"2:57.500"},{"name":"Mad Russian","id":"14","nextscheduled":"","length":"4:42.272"},{"name":"Oh Holy Night","id":"15","nextscheduled":"","length":"5:01.800"},{"name":"Dancy of the sugar plum faries","id":"16","nextscheduled":"","length":"1:52.150"},{"name":"I wanna BIG one","id":"17","nextscheduled":"","length":"0:15.900"},{"name":"fireflies","id":"18","nextscheduled":"","length":"2:30.450"},{"name":"Silver Bells","id":"19","nextscheduled":"","length":"3:11.400"},{"name":"The Christmas Song - Chipmunks","id":"20","nextscheduled":"","length":"2:23.420"},{"name":"What Child is This","id":"21","nextscheduled":"","length":"3:47.100"},{"name":"Its the most wonderful time of the year","id":"22","nextscheduled":"","length":"2:31.250"},{"name":"Buddy Cheer","id":"23","nextscheduled":"","length":"0:27.400"},{"name":"Christmas Canon","id":"24","nextscheduled":"","length":"4:18.900"},{"name":"Grinch","id":"25","nextscheduled":"","length":"0:56.100"},{"name":"White Christmas","id":"26","nextscheduled":"","length":"3:05.700"},{"name":"Christmas Eve (sarajevo)","id":"27","nextscheduled":"","length":"3:25.199"},{"name":"Celtic Christmas","id":"28","nextscheduled":"","length":"3:37.650"},{"name":"Plugged in","id":"29","nextscheduled":"","length":"0:12.600"},{"name":"Grandma Got Run Over by a Reindeer","id":"30","nextscheduled":"","length":"3:30.000"},{"name":"do you hear what i hear","id":"31","nextscheduled":"","length":"2:53.250"},{"name":"Welcome christmas","id":"32","nextscheduled":"","length":"2:13.750"},{"name":"we are santas elves","id":"33","nextscheduled":"","length":"1:36.950"},{"name":"take a piece of meat with you","id":"34","nextscheduled":"","length":"2:39.150"},{"name":"feliz navidad","id":"35","nextscheduled":"","length":"3:02.050"},{"name":"Rockin around the christmast tree","id":"36","nextscheduled":"","length":"2:03.200"},{"name":"Display Hours","id":"37","nextscheduled":"","length":"0:30.050"},{"name":"God rest ye marry gentleman","id":"38","nextscheduled":"","length":"2:29.750"},{"name":"Reminder LOR Import","id":"39","nextscheduled":"","length":"0:56.950"},{"name":"WarmUp","id":"40","nextscheduled":"2018-11-26 16:30","length":"11:25.050"},{"name":"silent night","id":"41","nextscheduled":"","length":"3:22.700"},{"name":"CoolDown","id":"42","nextscheduled":"2018-11-26 22:00","length":"12:55.000"},{"name":"Halloween","id":"43","nextscheduled":"","length":"21:36.350"},{"name":"Restart xLights Scheduler","id":"44","nextscheduled":"2018-11-26 16:15","length":"0:00.050"}],"reference":""}'. Time = 0. 2018-11-26 14:44:47,835 1760 log_base [INFO] xScheduleQuery received query = 'GetNextScheduledPlayList' parameters = ''. 2018-11-26 14:44:47,835 1760 log_base [INFO] data = '{"playlistname":"Restart xLights Scheduler","playlistid":"44","schedulename":"Restart xLights Scheduler","scheduleid":"4","start":"2018-11-26 16:15","end":"16:16","reference":""}'. Time = 0. 2018-11-26 14:44:55,237 1760 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 305 2018-11-26 14:44:55,604 1760 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 152 2018-11-26 14:44:56,076 1760 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 120 2018-11-26 14:44:56,477 1760 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 123 2018-11-26 14:44:57,005 1760 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 465 2018-11-26 14:44:58,354 1760 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 999 2018-11-26 14:44:58,588 1760 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 233 2018-11-26 14:44:58,804 1760 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 167 2018-11-26 14:44:59,094 1760 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 154 2018-11-26 14:44:59,188 1760 log_base [DEBUG] Viewing log file C:\Users\pking\AppData\Roaming/xSchedule_l4cpp.log.

[keithsw1111]

Are you sure the machine hasnt stopped accepting connections. If you restart xSchedule does it work again?

I will add some logging in .50 to see if xSchedule is even seeing the requests. But i doubt it is.

[PKingRoch]

If I restart xSchedule, it does work again. The machine hasn't been restarted in weeks, but I have to restart xSchedule daily because the webserver in it stops responding correctly.