search

declension / squeeze-alexa

Squeezebox integration for Amazon Alexa
GNU General Public License v3.0
59 stars 20 forks source link

CLI closes connection - too many connections open #52

Closed crmbls closed 5 years ago

crmbls commented 6 years ago

The server refuses any connection maybe due to too many exceptions before. It seems that only LMS restart fixes the problem. Server log: _Slim::Plugin::CLI::Plugin::cli_socketaccept (239) Warning: Closing connection: too many connections open! (30) LMS Version : 7.5.1-30836

Lambda log: _Connecting to port 19090 on xxxxx.xxxx.xxx Validated cert for {'commonName': u'xxxxx.xxxx.xxx'} No further response from Squeezebox server at xxxxx.xxxx.xxx:19090. Login problem?: SqueezeboxException Traceback (most recent call last): File "/var/task/handler.py", line 37, in lambdahandler raise e SqueezeboxException: No further response from Squeezebox server at xxxxx.xxxx.xxx:19090. Login problem?

declension commented 6 years ago

Thanks for the report. Looks like a bug, though never experienced it myself.

Actually I realised recently this might be a problem; think the fix shouldn't be too hard.

crmbls commented 6 years ago

This fix and #53 didn't solve the error that the server occasionally refuses any connection which requires a server restart to recover. Server and player control via Web-Interface are not affected. The fixes add three more lines in the trace:

_Connecting to port 19090 on xxxxx.xxxx.xxx Validated cert for {'commonName': u'xxxxx.xxxx.xxx'} <<<< login xuserx xpasswordx Goodbye from Squeezebox server at xxxxx.xxxx.xxx:19090 over SSL Closing xxxxx.xxxx.xxx:19090 over SSL No further response from Squeezebox server at xxxxx.xxxx.xxx:19090. Login problem?: SqueezeboxException Traceback (most recent call last): File "/var/task/handler.py", line 37, in lambdahandler raise e SqueezeboxException: No further response from Squeezebox server at xxxxx.xxxx.xxx:19090. Login problem?

Server log: _Slim::Plugin::CLI::Plugin::cli_socketaccept (239) Warning: Closing connection: too many connections open! (30) LMS Version : 7.5.1-30836

declension commented 6 years ago

@crmbls does this happen every time now, or just when it's run out of connections?

crmbls commented 6 years ago

@declension: The error is so far difficult to reproduce, it happens randomly, but once it occurs, it keeps refusing alexa commands with the same line in the server log. After server restart everything is fine (for a while). It happened two times (but not at every trial) directly after power-up of SB-Touch with the first command (LMS is running on a NAS continuously, only the player is connected to mains when needed). I could not reproduce it repeating commands with no player active (see #37), so my first thought of a relation to exception handling might not be the root cause. Sorry for not being very precise and lack of programming knowledge. ;-)

declension commented 6 years ago

Hmm. One weird this is that log output Goodbye from Squeezebox...

That shouldn't be in current master version - nor is it in the commit that aimed to fix this stuff, so I'm confused what you have deployed exactly now... Perhaps a wipe and redeploy might be good.

Perhaps you've been using the new [Python3 / MQTT branch]() and something's got merged / leftover somehow? If not, this might be worth a go anyway as I'm releasing this as 2.0.0 soon and deprecating the 1.x (Python 2) series then...

crmbls commented 6 years ago

Sorry for confusion. You are right that the "Goodbye..." is not from master but from change "Remove duplicated del method". But let me explain.

End of April I started with your 1.2 release (Python 2.7) and was happy to get it working. Later I tested as well the Python 3 master branch, but found out that it was not that good performing compared to 1.2, maybe because of German language, missing fuzzywuzzy or whatever. Too many fails recognizing slots. I continued based on 1.2 release but tried to improve it for my needs as follows.

  1. Since the genre-tags of my music library is too less different (too much Rock) and I rather play artists or albums I added a couple of more intents such as PlayArtist, PlayAlbum, AddArtist, AddAlbum reusing already existing code parts. To complete I added AlbumShuffle and PlaylistLoop.
  2. Since I was missing a PlayFavoriteIntent (and my programming skills are not capable to program it) I created a workaround creating playlists for each "Favorite"-Radiostation. To get some comfort in responses I added a slot type "Radio" to the PlayPlaylistIntent beside the existing "Playlist" and modified the handler in main.py.
  3. Since searching through albums (~600) takes a while I needed to increase some response timeouts not running into them. Note that the LMS is running on a quite weak NAS QNAP TS-109 (Marvel 500MHz).
  4. I added the fixes you proposed for #52 and #53... and yes the "Goodbye..."
  5. There seemed to be a bug in server.py/refresh_status when debugging is enabled, something with the print_d("Player(s): %s" % (self.players.values(),)).

All in all I did the modifications only to the attached intents.py, main.py, server.py and ssl_wrap.py (Please note my comments inline!), while all other files are original 1.2 release (settings.py not included). I share the files in attached zip. It includes as well my .json interaction model. I tried to fork and create an own repository but it seems I cannot fork from release 1.2 only from current branches.

So far I'm happy with the function, but the robustness and some error handling may be increased but this error is a bit annoying as it requires to restart LMS. However you may get a deeper view now and find more weak points or improvements in the code or get ideas for further extensions. Thanks a lot for your support!

crmbl_squeeze_alexa.zip

crmbls commented 6 years ago

Migrated to release 1.3 (Python 3.6) and continue testing... Ran into same error: _Slim::Plugin::CLI::Plugin::cli_socketaccept (239) Warning: Closing connection: too many connections open! (30)

Traceback:

Connecting to port 19090 on xxxxx.xxxx.xxx
Validated cert for {'commonName': 'xxxxx.xxxx.xxx'}
<<<< login xuserx xpasswordx
No further response from Squeezebox server at xxxxx.xxxx.xxx:19090 over SSL. Login problem?: SqueezeboxException
Traceback (most recent call last):
  File "/var/task/handler.py", line 37, in lambda_handler
    raise e
  File "/var/task/handler.py", line 34, in lambda_handler
    return sqa.handle(event, context)
  File "/var/task/squeezealexa/main.py", line 78, in handle
    return super(SqueezeAlexa, self).handle(event, context)
  File "/var/task/squeezealexa/alexa/handlers.py", line 49, in handle
    return self.on_intent(request, session)
  File "/var/task/squeezealexa/main.py", line 122, in on_intent
    pid = self.player_id_from(intent)
  File "/var/task/squeezealexa/main.py", line 642, in player_id_from
    srv = self.get_server()
  File "/var/task/squeezealexa/main.py", line 113, in get_server
    debug=DEBUG_LMS)
  File "/var/task/squeezealexa/squeezebox/server.py", line 61, in __init__
    self.log_in()
  File "/var/task/squeezealexa/squeezebox/server.py", line 82, in log_in
    result = self.__a_request("login %s %s" % (self.user, self.password))
  File "/var/task/squeezealexa/squeezebox/server.py", line 88, in __a_request
    reply = self._request([line], raw=raw, wait=wait)
  File "/var/task/squeezealexa/squeezebox/server.py", line 130, in _request
    "No further response from %s. Login problem?" % self)
squeezealexa.squeezebox.server.SqueezeboxException: No further response from Squeezebox server at xxxxx.xxxx.xxx:19090 over SSL. Login problem?

Closing Squeezebox server at xxxxx.xxxx.xxx:19090 over SSL
Closing xxxxx.xxxx.xxx:19090 over SSL
declension commented 6 years ago

Oh dear. Clearly that fix hasn't worked for you. I don't think the forthcoming 2.0 release (MQTT support) is going to change that.

So it's going to be hard to get a fix until I can replicate the problem I guess - any ideas taken...

crmbls commented 6 years ago

A migration to 2.0 release didn't fix the problem running into this error (every 4-6 days with LMS restart to recover).

Traceback (most recent call last):
  File "/var/task/handler.py", line 46, in lambda_handler
    raise e
  File "/var/task/handler.py", line 41, in lambda_handler
    sqa = SqueezeAlexa(server=server or get_server(),
  File "/var/task/handler.py", line 33, in get_server
    debug=LMS_SETTINGS.debug)
  File "/var/task/squeezealexa/squeezebox/server.py", line 79, in __init__
    self.log_in()
  File "/var/task/squeezealexa/squeezebox/server.py", line 108, in log_in
    result = self.__a_request("login %s %s" % (self.user, self.password))
  File "/var/task/squeezealexa/squeezebox/server.py", line 114, in __a_request
    reply = self._request([line], raw=raw, wait=wait)
  File "/var/task/squeezealexa/squeezebox/server.py", line 153, in _request
    "No further response from %s. Login problem?" % self)
crmbls commented 5 years ago

I can't reproduce that this commit fixes the bug, i.e. the Warning: Closing connection: too many connections open! (30) still occurs.

declension commented 5 years ago

@crmbls Thanks for re-testing, sorry that didn't fix it. I'm kinda out of ideas at this point though - especially as I can't use SSH transport any more myself.

Perhaps you could post some more recent AWS lambda logs, over a longer period of time (redacted, if there's anything sensitive there)?

I put in some more logging in that commit (and before) around startup / caching which might prove useful here.

rnlgreen commented 5 years ago

If it helps, and sorry for the long post... I added some logging to record the AWS side socket details at connect and disconnect, then watched the sockets on my Synology NAS.

Here's an extract from a CloudWatch log; I was using Alexa development console to send Alexa commands at the time.

08:15:23 START RequestId: e3062003-0b41-11e9-8c38-2f1b593c5445 Version: $LATEST 08:15:23 Creating new server instance 08:15:23 Defaulting to SSL transport 08:15:23 Connecting to port 19090 on myurl.com 08:15:23 Validated cert for {'commonName': 'myurl.com'} 08:15:23 Local IP: 169.254.76.5, Local port: 35384 08:15:23 Refreshing server and player statuses... 08:15:23 Found 2 connected player(s): ['SB-Playroom', 'SB-Lounge'] 08:15:23 Current player is now: SB-Playroom [ff:01] 08:15:23 Session amzn1.echo-api.session.8ee949f9-659c-4ca2-bc16-a9beacbfcb66 ended 08:15:23 Returning {'outputSpeech': {'type': 'PlainText', 'text': 'Hasta la vista. Baby.'}, 'shouldEndSession': True, 'card': {'type': 'Simple', 'title': 'Session Ended', 'content': 'Hasta la vista. Baby.'}} 08:15:23 END RequestId: e3062003-0b41-11e9-8c38-2f1b593c5445 08:15:23 REPORT RequestId: e3062003-0b41-11e9-8c38-2f1b593c5445 Duration: 491.85 ms Billed Duration: 500 ms Memory Size: 128 MB Max Memory Used: 29 MB 08:15:23 START RequestId: e3ff9b30-0b41-11e9-9c96-eb7796eae224 Version: $LATEST 08:15:23 Age of instance: 0.1s 08:15:23 Reusing cached instance Squeezebox server over myurl.com:19090 over SSL 08:15:23 Starting new session amzn1.echo-api.session.a91523f5-b3d2-4443-a1ef-17c67bdd3a5b for request amzn1.echo-api.request.cdb81e1c-e108-411f-aa42-113f9b7c2774 08:15:23 ('SB-Playroom', 95) was the best guess for 'playroom' from dict_keys(['SB-Playroom', 'SB-Lounge']) 08:15:23 Received PlayPlaylistIntent: {'name': 'PlayPlaylistIntent', 'confirmationStatus': 'NONE', 'slots': {'Playlist': {'name': 'Playlist', 'value': 'Christmas', 'resolutions': {'resolutionsPerAuthority': [{'authority': 'amzn1.er-authority.echo-sdk.amzn1.ask.skill.6d82bf02-5050-42a3-bb2b-e04ff8f004cf.PLAYLIST', 'status': {'code': 'ER_SUCCESS_MATCH'}, 'values': [{'value': {'name': 'Christmas', 'id': '81b6 08:15:23 Extracted playlist slot: Christmas 08:15:24 Loaded 45 LMS playlists (e.g. "I Wish") 08:15:24 ('Christmas', 100) was the best guess for 'Christmas' from ['00 s Music', '10 s Music', '60 s Music', '70 s Music', '80 s Music', '90 s Music', "Absolute 80's", 'Aqualung', 'BBC Radio 4 - Friday Night Comedy from BBC Radio 4', 'Burning Down the House', 'The Carol Album Seven centuries of Christmas music', 'Chris s Mix', 'Christmas', 'Christmas Collections', 'Christmas Lite', 'Classical', 'Classica 08:15:24 END RequestId: e3ff9b30-0b41-11e9-9c96-eb7796eae224 08:15:24 REPORT RequestId: e3ff9b30-0b41-11e9-9c96-eb7796eae224 Duration: 872.30 ms Billed Duration: 900 ms Memory Size: 128 MB Max Memory Used: 29 MB 08:16:56 START RequestId: 1b54a585-0b42-11e9-8cf1-b795c179d06e Version: $LATEST 08:16:56 Age of instance: 92.9s 08:16:56 Reusing cached instance Squeezebox server over myurl.com:19090 over SSL 08:16:56 Starting new session amzn1.echo-api.session.0ada4b7a-6181-473a-ae75-ebc56aa69b63 for request amzn1.echo-api.request.49f0e0e1-badf-466f-a14f-3280903cc423 08:16:56 ('SB-Playroom', 95) was the best guess for 'playroom' from dict_keys(['SB-Playroom', 'SB-Lounge']) 08:16:56 Received IncreaseVolumeIntent: {'name': 'IncreaseVolumeIntent', 'confirmationStatus': 'NONE', 'slots': {'Player': {'name': 'Player', 'value': 'playroom', 'resolutions': {'resolutionsPerAuthority': [{'authority': 'amzn1.er-authority.echo-sdk.amzn1.ask.skill.6d82bf02-5050-42a3-bb2b-e04ff8f004cf.PLAYER', 'status': {'code': 'ER_SUCCESS_MATCH'}, 'values': [{'value': {'name': 'Playroom', 'id': '5b00ccb0 08:16:56 END RequestId: 1b54a585-0b42-11e9-8cf1-b795c179d06e 08:16:56 REPORT RequestId: 1b54a585-0b42-11e9-8cf1-b795c179d06e Duration: 1.74 ms Billed Duration: 100 ms Memory Size: 128 MB Max Memory Used: 29 MB 08:17:36 START RequestId: 331b6059-0b42-11e9-809c-755a705a8cc6 Version: $LATEST 08:17:36 Age of instance: 132.8s 08:17:36 Reusing cached instance Squeezebox server over myurl.com:19090 over SSL 08:17:36 Starting new session amzn1.echo-api.session.f5c3393f-0157-45df-9e7c-7062c2686b2b for request amzn1.echo-api.request.f2b4dee6-0be8-43e4-a401-53f9a28afcc0 08:17:36 ('SB-Playroom', 95) was the best guess for 'playroom' from dict_keys(['SB-Playroom', 'SB-Lounge']) 08:17:36 Received IncreaseVolumeIntent: {'name': 'IncreaseVolumeIntent', 'confirmationStatus': 'NONE', 'slots': {'Player': {'name': 'Player', 'value': 'playroom', 'resolutions': {'resolutionsPerAuthority': [{'authority': 'amzn1.er-authority.echo-sdk.amzn1.ask.skill.6d82bf02-5050-42a3-bb2b-e04ff8f004cf.PLAYER', 'status': {'code': 'ER_SUCCESS_MATCH'}, 'values': [{'value': {'name': 'Playroom', 'id': '5b00ccb0 08:17:36 END RequestId: 331b6059-0b42-11e9-809c-755a705a8cc6 08:17:36 REPORT RequestId: 331b6059-0b42-11e9-809c-755a705a8cc6 Duration: 1.51 ms Billed Duration: 100 ms Memory Size: 128 MB Max Memory Used: 29 MB 08:30:19 START RequestId: f9f1d2ab-0b43-11e9-8f5e-a5be6b39863b Version: $LATEST 08:30:19 Age of instance: 895.9s 08:30:19 Killing stale server instance... 08:30:19 Goodbye from <squeezealexa.squeezebox.server.Server object at 0x7ff2ed0f99b0> 08:30:19 Closing myurl.com:19090 over SSL 08:30:19 Local IP: 169.254.76.5, Local port: 35384 08:30:19 Creating new server instance 08:30:19 Defaulting to SSL transport 08:30:19 Connecting to port 19090 on myurl.com 08:30:20 Validated cert for {'commonName': 'myurl.com'} 08:30:20 Local IP: 169.254.76.5, Local port: 35502 08:30:20 Refreshing server and player statuses... 08:30:20 Found 2 connected player(s): ['SB-Playroom', 'SB-Lounge'] 08:30:20 Current player is now: SB-Playroom [ff:01] 08:30:20 Goodbye from <squeezealexa.squeezebox.server.Server object at 0x7ff2ed0f99b0> 08:30:20 Closing myurl.com:19090 over SSL 08:30:20 Local IP: 169.254.76.5, Local port: 35384 08:30:20 Closing myurl.com:19090 over SSL 08:30:20 Local IP: 169.254.76.5, Local port: 35384 08:30:20 Starting new session amzn1.echo-api.session.4d91f956-96a2-4bf8-a814-bd38f57c9e58 for request amzn1.echo-api.request.04617f0f-bae9-4051-a7b2-e66165910537 08:30:20 Received AMAZON.FallbackIntent: {'name': 'AMAZON.FallbackIntent', 'confirmationStatus': 'NONE'} (for player 00:04:20:ff:ff:01) 08:30:20 END RequestId: f9f1d2ab-0b43-11e9-8f5e-a5be6b39863b 08:30:20 REPORT RequestId: f9f1d2ab-0b43-11e9-8f5e-a5be6b39863b Duration: 955.64 ms Billed Duration: 1000 ms Memory Size: 128 MB Max Memory Used: 29 MB 08:33:29 START RequestId: 6b3a388a-0b44-11e9-babd-358f20c2d1d7 Version: $LATEST 08:33:29 Age of instance: 189.1s 08:33:29 Reusing cached instance Squeezebox server over myurl.com:19090 over SSL 08:33:29 Starting new session amzn1.echo-api.session.c8270aca-cd5a-49df-94ee-5ed0346a23d5 for request amzn1.echo-api.request.8b1bfb22-4784-4a66-94a1-2031050c7669 08:33:29 Received AMAZON.NextIntent: {'name': 'AMAZON.NextIntent', 'confirmationStatus': 'NONE'} (for player 00:04:20:ff:ff:01) 08:33:29 END RequestId: 6b3a388a-0b44-11e9-babd-358f20c2d1d7 08:33:29 REPORT RequestId: 6b3a388a-0b44-11e9-babd-358f20c2d1d7 Duration: 212.06 ms Billed Duration: 300 ms Memory Size: 128 MB Max Memory Used: 29 MB 08:33:41 START RequestId: 72217ee7-0b44-11e9-91c6-85f935c9637c Version: $LATEST 08:33:41 Age of instance: 200.7s 08:33:41 Reusing cached instance Squeezebox server over myurl.com:19090 over SSL 08:33:41 Starting new session amzn1.echo-api.session.d73a6607-796e-4cc6-83e3-a49692e00259 for request amzn1.echo-api.request.95884198-86f0-4ed8-ba1e-61f03477b7ed 08:33:41 Received AMAZON.NextIntent: {'name': 'AMAZON.NextIntent', 'confirmationStatus': 'NONE'} (for player 00:04:20:ff:ff:01) 08:33:41 END RequestId: 72217ee7-0b44-11e9-91c6-85f935c9637c 08:33:41 REPORT RequestId: 72217ee7-0b44-11e9-91c6-85f935c9637c Duration: 185.09 ms Billed Duration: 200 ms Memory Size: 128 MB Max Memory Used: 29 MB 08:49:09 START RequestId: 9bae04db-0b46-11e9-85e9-e122d30a1b4a Version: $LATEST 08:49:09 Age of instance: 1129.4s 08:49:09 Killing stale server instance... 08:49:09 Goodbye from <squeezealexa.squeezebox.server.Server object at 0x7ff2ed0f95c0> 08:49:09 Closing myurl.com:19090 over SSL 08:49:09 Local IP: 169.254.76.5, Local port: 35502 08:49:09 Creating new server instance 08:49:09 Defaulting to SSL transport 08:49:09 Connecting to port 19090 on myurl.com 08:49:10 Validated cert for {'commonName': 'myurl.com'} 08:49:10 Local IP: 169.254.76.5, Local port: 35654 08:49:10 Refreshing server and player statuses... 08:49:10 Found 2 connected player(s): ['SB-Playroom', 'SB-Lounge'] 08:49:10 Current player is now: SB-Playroom [ff:01] 08:49:10 Goodbye from <squeezealexa.squeezebox.server.Server object at 0x7ff2ed0f95c0> 08:49:10 Closing myurl.com:19090 over SSL 08:49:10 Local IP: 169.254.76.5, Local port: 35502 08:49:10 Closing myurl.com:19090 over SSL 08:49:10 Local IP: 169.254.76.5, Local port: 35502 08:49:10 Starting new session amzn1.echo-api.session.3e6644b5-f3d3-4048-a075-4bbd82999ed0 for request amzn1.echo-api.request.3ce0f748-de2e-48a2-9aa5-86cb913572a3 08:49:10 Received AMAZON.NextIntent: {'name': 'AMAZON.NextIntent', 'confirmationStatus': 'NONE'} (for player 00:04:20:ff:ff:01) 08:49:12 END RequestId: 9bae04db-0b46-11e9-85e9-e122d30a1b4a 08:49:12 REPORT RequestId: 9bae04db-0b46-11e9-85e9-e122d30a1b4a Duration: 2142.37 ms Billed Duration: 2200 ms Memory Size: 128 MB Max Memory Used: 29 MB 08:53:51 START RequestId: 438abca0-0b47-11e9-9007-4b7daec09a3d Version: $LATEST 08:53:51 Age of instance: 280.7s 08:53:51 Reusing cached instance Squeezebox server over myurl.com:19090 over SSL 08:53:51 Starting new session amzn1.echo-api.session.91a624b4-d7c3-4f4a-949f-52aed746bb11 for request amzn1.echo-api.request.e6136abe-0588-4809-9407-76b217a6be8a 08:53:51 Received AMAZON.NextIntent: {'name': 'AMAZON.NextIntent', 'confirmationStatus': 'NONE'} (for player 00:04:20:ff:ff:01) 08:53:51 END RequestId: 438abca0-0b47-11e9-9007-4b7daec09a3d 08:53:51 REPORT RequestId: 438abca0-0b47-11e9-9007-4b7daec09a3d Duration: 282.04 ms Billed Duration: 300 ms Memory Size: 128 MB Max Memory Used: 29 MB 08:54:39 START RequestId: 60304419-0b47-11e9-803c-f5dbd238916c Version: $LATEST 08:54:39 Age of instance: 328.8s 08:54:39 Reusing cached instance Squeezebox server over myurl.com:19090 over SSL 08:54:39 Starting new session amzn1.echo-api.session.439814b4-924d-492e-b97d-a03e2d1b0a1e for request amzn1.echo-api.request.82995bc7-593a-4fef-950f-ed6636d1f7ea 08:54:39 Received AMAZON.NextIntent: {'name': 'AMAZON.NextIntent', 'confirmationStatus': 'NONE'} (for player 00:04:20:ff:ff:01) 08:54:39 END RequestId: 60304419-0b47-11e9-803c-f5dbd238916c 08:54:39 REPORT RequestId: 60304419-0b47-11e9-803c-f5dbd238916c Duration: 254.39 ms Billed Duration: 300 ms Memory Size: 128 MB Max Memory Used: 29 MB 09:10:59 START RequestId: a80be227-0b49-11e9-8525-39be65366cb5 Version: $LATEST 09:10:59 Age of instance: 1308.3s 09:10:59 Killing stale server instance... 09:10:59 Goodbye from <squeezealexa.squeezebox.server.Server object at 0x7ff2ed0f9cc0> 09:10:59 Closing myurl.com:19090 over SSL 09:10:59 Local IP: 169.254.76.5, Local port: 35654 09:10:59 Creating new server instance 09:10:59 Defaulting to SSL transport 09:10:59 Connecting to port 19090 on myurl.com 09:10:59 Validated cert for {'commonName': 'myurl.com'} 09:10:59 Local IP: 169.254.76.5, Local port: 35794 09:10:59 Refreshing server and player statuses... 09:10:59 Found 2 connected player(s): ['SB-Playroom', 'SB-Lounge'] 09:10:59 Current player is now: SB-Playroom [ff:01] 09:10:59 Goodbye from <squeezealexa.squeezebox.server.Server object at 0x7ff2ed0f9cc0> 09:10:59 Closing myurl.com:19090 over SSL 09:10:59 Local IP: 169.254.76.5, Local port: 35654 09:10:59 Closing myurl.com:19090 over SSL 09:10:59 Local IP: 169.254.76.5, Local port: 35654 09:10:59 Starting new session amzn1.echo-api.session.8cf81651-2e33-41e2-b5a1-9dfd3201b9d8 for request amzn1.echo-api.request.b10fba28-c43f-45fc-b822-0f21c540af82 09:10:59 Received AMAZON.PauseIntent: {'name': 'AMAZON.PauseIntent', 'confirmationStatus': 'NONE'} (for player 00:04:20:ff:ff:01) 09:11:00 END RequestId: a80be227-0b49-11e9-8525-39be65366cb5 09:11:00 REPORT RequestId: a80be227-0b49-11e9-8525-39be65366cb5 Duration: 846.94 ms Billed Duration: 900 ms Memory Size: 128 MB Max Memory Used: 29 MB

But if I look on my NAS those sockets that were supposedly closed are still open

Incoming AWS connections to stunnel:

tcp 0 0 10.0.0.50:19090 54.194.164.35:35384 ESTABLISHED 30704/stunnel tcp 0 0 10.0.0.50:19090 54.194.164.35:35502 ESTABLISHED 30704/stunnel tcp 0 0 10.0.0.50:19090 54.194.164.35:35654 ESTABLISHED 30704/stunnel tcp 0 0 10.0.0.50:19090 54.194.164.35:35794 ESTABLISHED 30704/stunnel

Internal connections between stunnel and LMS CLI:

tcp 0 0 127.0.0.1:54211 127.0.0.1:9090 ESTABLISHED 30704/stunnel tcp 0 0 127.0.0.1:54679 127.0.0.1:9090 ESTABLISHED 30704/stunnel tcp 0 0 127.0.0.1:55237 127.0.0.1:9090 ESTABLISHED 30704/stunnel tcp 0 0 127.0.0.1:55871 127.0.0.1:9090 ESTABLISHED 30704/stunnel tcp 0 0 127.0.0.1:9090 127.0.0.1:54211 ESTABLISHED 25094/perl tcp 0 0 127.0.0.1:9090 127.0.0.1:54679 ESTABLISHED 25094/perl tcp 0 0 127.0.0.1:9090 127.0.0.1:55237 ESTABLISHED 25094/perl tcp 0 0 127.0.0.1:9090 127.0.0.1:55871 ESTABLISHED 25094/perl

rnlgreen commented 5 years ago

As a follow up, here's where my NAS sent TCP resets back to AWS for the open sockets, 12 hours after they were created. Not sure what at this end causes this to happen, but this morning there are no open sockets to the CLI or stunnel.

20:17:36.568778 IP myhost.local.19090 > ec2-54-194-164-35.eu-west-1.compute.amazonaws.com.35384: Flags [R.], seq 1398133423, ack 1554346990, win 167, options [nop,nop,TS val 197122233 ecr 3854901048], length 0 20:33:41.478086 IP myhost.local.19090 > ec2-54-194-164-35.eu-west-1.compute.amazonaws.com.35502: Flags [R.], seq 4063200445, ack 2508051606, win 167, options [nop,nop,TS val 198087142 ecr 3855865955], length 0 20:54:39.919661 IP myhost.local.19090 > ec2-54-194-164-35.eu-west-1.compute.amazonaws.com.35654: Flags [R.], seq 1797022590, ack 1732801285, win 167, options [nop,nop,TS val 199345584 ecr 3857124442], length 0 21:11:00.048884 IP myhost.local.19090 > ec2-54-194-164-35.eu-west-1.compute.amazonaws.com.35794: Flags [R.], seq 342325970, ack 333222361, win 167, options [nop,nop,TS val 200325713 ecr 3858104672], length 0

rnlgreen commented 5 years ago

… looks like stunnel has a default idle timeout of 43200 seconds (12 hours), which is what is cleaning up these stale sockets, so a possible workaround would be to add something like this to stunnel.conf to reduce that value and have idle sockets cleaned down sooner:

TIMEOUTidle=10800

declension commented 5 years ago

@rnlgreen funny, I was literally just thinking of whether stunnel has config around that... :+1:

declension commented 5 years ago

(Thanks for the detailed investigation, just looking through it now)

rnlgreen commented 5 years ago

You're welcome, funny how the socket stays open but at least shouldn't be a problem if folk reduce the idle timeout.

On Sun, 30 Dec 2018, 10:37 Nick Boultbee <notifications@github.com wrote:

(Thanks for the detailed investigation, just looking through it now)

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/declension/squeeze-alexa/issues/52#issuecomment-450551976, or mute the thread https://github.com/notifications/unsubscribe-auth/Ag0f7_F9poY8cIr5qky586YMSif12v94ks5u-JeCgaJpZM4UIHWh .

hagak commented 5 years ago

I was running into a similar issue with HAProxy, my server connection timeout was 50seconds. My solution was to extend the timeout. It appeared that Alexa was reusing a cache connection but HAProxy had already killed the connection. Not sure if you can try to make a new connection if this occurs. Seems right now it just gives up until you hit a certain number of errors then force a disconnection.

hagak commented 5 years ago

Just read in the code the cache connection setting is at 10 minutes, so I assume I need to set my server timeout within HAProxy to 10 minutes. Question any reason that cache is so long? I suppose it is not an issue for us since we are only ever going to have the one connection.

declension commented 5 years ago

@hagak Yes, this is a good point - I haven't mentioned it in the HOWTOs. Yes it'd be ideal if the two timeouts were roughly the same.

The 10 minutes (or at least something more than a few seconds) is a best-efforts performance optimisation, exploiting warm-lambda instances, but it's very hard to test so might not be working. The idea is that by having a reusable AWS instance and a long / restorable connection at each end, you can shave off the semi-expensive SSL. Actually though this is more an issue for MQTT than SSH but still.

(Also if you've got an HAProxy solution, it'd be great if you could push this config / howto :smile: - see #3)

crmbls commented 5 years ago

Verified the stunnel timout workaround. Propose to close this bug.