i8beef / HomeAutio.Mqtt.GoogleHome

MIT License
215 stars 29 forks source link

Application exception ocurred while processing message #59

Closed Vayatoalla closed 5 years ago

Vayatoalla commented 5 years ago

I have been using homeautio for several months without errors until 5 days ago, when it stopped working. I do not know why, but the app throws an exception every time it have an interaction with google. It begins the transaction ok until it stops exactly for a minute, and then gives an exception. First time I saw this, I was trying to action a device, but I have the same issue if I try to report a state to homegraph. As I didnt get to resolve it, I decided to reinstall the app (and upgraded to the latest docker image). But it kept failing at the same point. I removed the aplication in my phone, and now the app fails when I try to add the device in Google Home. I have spend a lot of hours trying to solve it but no success. Any idea?. I copy here the point in my logs where the exception happens.

` 2019-09-07 19:59:28.796 +02:00 [Information] Route matched with "{action = \"Post\", controller = \"GoogleHome\"}". Executing controller action with signature "Microsoft.AspNetCore.Mvc.IActionResult Post(HomeAutio.Mqtt.GoogleHome.Models.Request.Request)" on controller "HomeAutio.Mqtt.GoogleHome.Controllers.GoogleHomeController" ("HomeAutio.Mqtt.GoogleHome").

2019-09-07 19:59:43.688 +02:00 [Information] Removing expired grants 2019-09-07 20:00:28.855 +02:00 [Error] Exception occurred while processing message. System.InvalidOperationException: IDX20803: Unable to obtain configuration from: '[PII is hidden]'. ---> System.IO.IOException: IDX20804: Unable to retrieve document from: '[PII is hidden]'. ---> System.Threading.Tasks.TaskCanceledException: The operation was canceled. ---> System.IO.IOException: Unable to read data from the transport connection: Operation canceled. ---> System.Net.Sockets.SocketException: Operation canceled --- End of inner exception stack trace --- at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error) at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.GetResult(Int16 token) at System.Net.FixedSizeReader.ReadPacketAsync(Stream transport, AsyncProtocolRequest request) at System.Net.Security.SslState.ThrowIfExceptional() at System.Net.Security.SslState.InternalEndProcessAuthentication(LazyAsyncResult lazyResult) at System.Net.Security.SslState.EndProcessAuthentication(IAsyncResult result) at System.Net.Security.SslStream.EndAuthenticateAsClient(IAsyncResult asyncResult) at System.Net.Security.SslStream.<>c.b__47_1(IAsyncResult iar) at System.Threading.Tasks.TaskFactory1.FromAsyncCoreLogic(IAsyncResult iar, Func2 endFunction, Action1 endAction, Task1 promise, Boolean requiresSynchronization) --- End of stack trace from previous location where exception was thrown --- at System.Net.Http.ConnectHelper.EstablishSslConnectionAsyncCore(Stream stream, SslClientAuthenticationOptions sslOptions, CancellationToken cancellationToken) --- End of inner exception stack trace --- at System.Net.Http.ConnectHelper.EstablishSslConnectionAsyncCore(Stream stream, SslClientAuthenticationOptions sslOptions, CancellationToken cancellationToken) at System.Threading.Tasks.ValueTask1.get_Result()

i8beef commented 5 years ago

Its failing in the OAuth handshake. This app has an embedded identity server. The API it exposes has to validate tokens sent to it by making calls to that embedded identity server: i.e., the app calls itself for certain operations. Notice the failure is exactly a minute after the request? I think you're seeing

  1. Google calls the API with a token
  2. The API has to call the identity server to validate the token
  3. When it does, its timing out talking to itself, 60 seconds after initiating the call

WHY it can't talk to itself, depends a lot on your setup.

  1. You said docker, so I'll assume you are proxying through apache or nginx? Whats that setup look like? Any changes there recently?
  2. Anything special about your docker setup / using docker-compose? Can you establish a shell on the container and ensure that you can curl back to itself?
  3. Im assuming you have an SSL cert on the proxy. Is it expired? Whats oauth:requireSSL set to?
  4. What are authority and publicOrigin set to?
Vayatoalla commented 5 years ago

Thanks for your help. I didn't know this internal traffic in OAuth handshake. Knowing this, I rechecked my router, since this problem started the day I changed my ISP provider: new router, new line, new fixed IP address. It's a bit strange, because the https connection to the application from the Internet worked fine all this time, but I understand that this traffic coming and going from the router may suffer more problems. I have changed the connection on my Wifi Raspberry to a wired connection and now the application works again well. By the way, yes, I am proxying homeautio with nginx, using docker-compose.

i8beef commented 5 years ago

Yeah, its an artifact of the underlying OpenID connect OAuth provider. Just how it works. Especially with this that uses what is likely the public DNS address of the external interface, sometimes that can really confuse the network routing. I have a hairpin NAT rule on my router for this reason, but I have a Mikrotik which is a bit lower level than most consumer grade routers, so I get to setup some odd things you probably don't have to 😛