JPersson77 / LGTVCompanion

Power On and Off WebOS LG TVs together with your PC
MIT License
964 stars 40 forks source link

A connection attempt failed #176

Closed Tailslide closed 9 months ago

Tailslide commented 11 months ago

At some point in the last few months it seems like maybe the software stopped working for me. I have an LG C1 If I test with the UI the TV turns off and on ok. Checking the logs I see this:

Mon 04:06:56 > ** System requests displays OFF. Mon 04:06:56 > Device1, spawning Thread_DisplayOff(). Mon 04:07:17 > Device1, WARNING! Thread_DisplayOff(): connect: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond [system:10060 at D:\a\LGTVCompanion\LGTVCompanion\vcpkg_installed\x64-windows-static\x64-windows-static\include\boost\asio\detail\win_iocp_socket_service.hpp:632:5 in function 'connect'] Mon 04:16:16 > -daemon 1 useridle Mon 04:16:16 > Device1, spawning Thread_DisplayOff(). Mon 04:16:37 > Device1, WARNING! Thread_DisplayOff(): connect: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond [system:10060 at D:\a\LGTVCompanion\LGTVCompanion\vcpkg_installed\x64-windows-static\x64-windows-static\include\boost\asio\detail\win_iocp_socket_service.hpp:632:5 in function 'connect'] Mon 04:26:16 > -daemon 1 useridle

JPersson77 commented 11 months ago

Hi @Tailslide the log suggests that the app cannot communicate properly with the TV. Usually an error like this indicates that you have the wrong IP configured. Can you post the full log and config.json please and I will have a look.

Tailslide commented 11 months ago

I verified the IP address and MAC match.. I notice there is a second mac in the config that corresponds to the wifi network which is no longer connected not sure if that's the issue.

lgtvLog.zip config.json

JPersson77 commented 11 months ago

kHi @Tailslide as far as I can tell when looking over the most recent parts of the log I can see it working fairly well, so I'm not sure what you mean. Can you describe in more detail what you mean when you say "stopped working for me" please.

On a C1 it is to be expected that the app cannot communicate with the TV when it is off (the always ready feature on C2 and newer is required for that). Hence you will see log entries like the below. At 22.56.43 the system requested the display to turn off (probably due to the power saving settings turn off screen after x min). At 23.05.42 the built in user idle mode detection triggered and another "power off display" message is sent, but since the TV is already off the message will time out and the error message is logged. But it all looks quite normal.

Sun 22:56:43 > ** System requests displays OFF.
Sun 22:56:43 > Device1, spawning Thread_DisplayOff().
Sun 22:56:43 > Device1, [DEBUG] (SSL) OFF response 1: {"type":"registered","id":"register_0","payload":{"client-key":"eda678071598af672e4db09d15f5084d"}}
Sun 22:56:43 > Device1, [DEBUG] (SSL) OFF response 2: {"type":"response","id":37,"payload":{"returnValue":true,"state":"Active"}}
Sun 22:56:43 > Device1, [DEBUG] (SSL) OFF response 4: {"type":"response","id":38,"payload":{"returnValue":true}}
Sun 22:56:43 > Device1, power state is: OFF.
Sun 23:05:42 > -daemon 1 useridle
Sun 23:05:42 > Device1, spawning Thread_DisplayOff().
Sun 23:06:03 > Device1, WARNING! Thread_DisplayOff(): connect: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond [system:10060 at D:\a\LGTVCompanion\LGTVCompanion\vcpkg_installed\x64-windows-static\x64-windows-static\include\boost\asio\detail\win_iocp_socket_service.hpp:632:5 in function 'connect']

Also I note for the previous log snippet you sent that it looks like the app cannot communicate with the TV. There was a two hour window of nothing going on in the log from MON 01:59:41 to MON 04:06:56. Since the communication seem to work in other occasions this looks like you either turned the TV off manually, or the TV had automatically powered down (using the built in TV timer). Or it may be a matter of your network going down, or the TV wifi nic losing contact with the netowkr, or your PC dropping the network. Hard to say.

JPersson77 commented 11 months ago

Addiotnally, wrt the second mac-adress. both MACs will be used. I e two wake on lan packets will be sent with the configured WOL method. In your case you have configured to send the packet to the IP-adress, but only one (with the correct MAC) can actually wake the TV. So in your case it should not matter.

Tailslide commented 11 months ago

Ok.. when I would check in on the PC in the mornings in the past the screen would be off and now the screen is on despite me not using it all night and there being no applications running. I assumed the 'user idle' setting would make sure it was off. Thanks for checking the logs I assume it's some background process making it look like the user is not idle.

JPersson77 commented 11 months ago

Hi, ok so your issue is that the TV is on in the mornings even though you've not been using the PC.

Let's break that down a bit. During the night, either the PC is awoken erroneously, or the display is awoken erroneously. The PC can be awoken for a few different reasons which depend on how it is configured. This may include installing updates, or other devices waking it. The TV can typically only be awoken with a specific wake on lan packet.

So let's try to see what we can gather from the log this morning then (see below). Just from looking at the log it looks like the PC was put to sleep just before midnight. It resumed around two hours later (~2am,), at which point the display powered on. Then not much is going on in the log until two hours later(~4pm) when the system requests the display to be powered off. At this point the request fails for unknown reasons, as mentioned previously. Maybe the TV had auto-powered off at this time. What have you set the TVs auto power of setting to (not the app, the setting in the TV settings)?

Furthermore, the log entries indicate a user was at the PC at this time 2am to 4am (due to the lack of user idle messages).

Then after 4 around am there is a bunch of user idle messages, indicating there is no user at the PC, but the pc is still running. The TV seem to be off as it is not responding to these messages.

At 05:05 the system suspends once again.

At 05.08 the system resumes. The display is powered on.

Then, judging by the info in the log there was a user at the PC from 05:08 to 09:07 since there are no user idle messages. Again a lack of user idle messages indicate that the PC is being used.

At 09:07 you used the test function to power the TV first off and then on.

This tells a story of a PC that keeps waking up for some reason. Since you said the PC wasn't used during the night there is a discrepancy. See what you can gather from my summary of the log. A suggestion to keep the PC from waking up is to disable wake-timers and also ensure that the PC cannot be awoken by WOL packets on your network .

Sun 23:56:28 > ** System is suspending to a low power state.(or event callback is missing)
Mon 01:59:34 > ** System resumed from low power state.
Mon 01:59:34 > ** System requests displays ON.
Mon 01:59:34 > Device1, spawning Thread_DisplayOn().
Mon 01:59:34 > Device1, repeating WOL broadcast started to MAC: B4B291B850F0 using IP address: 192.168.12.151
Mon 01:59:34 > Device1, Best route to IP - interface index 16 LUID 1689399716741120 route protocol 2
Mon 01:59:34 > Device1, WARNING! Thread_DisplayOn(): connect: A socket operation was attempted to an unreachable host [system:10065 at D:\a\LGTVCompanion\LGTVCompanion\vcpkg_installed\x64-windows-static\x64-windows-static\include\boost\asio\detail\win_iocp_socket_service.hpp:632:5 in function 'connect']
Mon 01:59:34 > ** System resumed from low power state (Automatic).
Mon 01:59:35 > Device1, WARNING! Thread_DisplayOn(): connect: A socket operation was attempted to an unreachable host [system:10065 at D:\a\LGTVCompanion\LGTVCompanion\vcpkg_installed\x64-windows-static\x64-windows-static\include\boost\asio\detail\win_iocp_socket_service.hpp:632:5 in function 'connect']
Mon 01:59:37 > Device1, [DEBUG] (SSL) ON response 1: {"type":"registered","id":"register_0","payload":{"client-key":"eda678071598af672e4db09d15f5084d"}}
Mon 01:59:37 > Device1, [DEBUG] (SSL) ON response 2: {"type":"error","id":39,"error":"500 Application error","payload":{"returnValue":false,"errorCode":"-2","errorText":"com.webos.service.tvpower/power is busy"}}
Mon 01:59:37 > Device1, [DEBUG] (SSL) ON response 3: {"type":"response","id":40,"payload":{"returnValue":true,"state":"Suspend","processing":"Screen On"}}
Mon 01:59:37 > Device1, [DEBUG] (SSL) ON response 1: {"type":"registered","id":"register_0","payload":{"client-key":"eda678071598af672e4db09d15f5084d"}}
Mon 01:59:37 > Device1, [DEBUG] (SSL) ON response 2: {"type":"error","id":41,"error":"500 Application error","payload":{"returnValue":false,"errorCode":"-2","errorText":"com.webos.service.tvpower/power is busy"}}
Mon 01:59:37 > Device1, [DEBUG] (SSL) ON response 3: {"type":"response","id":42,"payload":{"returnValue":true,"state":"Suspend","processing":"Screen On"}}
Mon 01:59:39 > Device1, [DEBUG] (SSL) ON response 1: {"type":"registered","id":"register_0","payload":{"client-key":"eda678071598af672e4db09d15f5084d"}}
Mon 01:59:39 > Device1, [DEBUG] (SSL) ON response 2: {"type":"error","id":43,"error":"500 Application error","payload":{"returnValue":false,"errorCode":"-2","errorText":"com.webos.service.tvpower/power is busy"}}
Mon 01:59:39 > Device1, [DEBUG] (SSL) ON response 3: {"type":"response","id":44,"payload":{"returnValue":true,"state":"Suspend","processing":"Screen On"}}
Mon 01:59:39 > Device1, [DEBUG] (SSL) ON response 1: {"type":"registered","id":"register_0","payload":{"client-key":"eda678071598af672e4db09d15f5084d"}}
Mon 01:59:39 > Device1, [DEBUG] (SSL) ON response 2: {"type":"error","id":45,"error":"500 Application error","payload":{"returnValue":false,"errorCode":"-2","errorText":"com.webos.service.tvpower/power is busy"}}
Mon 01:59:39 > Device1, [DEBUG] (SSL) ON response 3: {"type":"response","id":46,"payload":{"returnValue":true,"state":"Suspend","processing":"Screen On"}}
Mon 01:59:40 > Device1, [DEBUG] (SSL) ON response 1: {"type":"registered","id":"register_0","payload":{"client-key":"eda678071598af672e4db09d15f5084d"}}
Mon 01:59:40 > Device1, [DEBUG] (SSL) ON response 2: {"type":"error","id":47,"error":"500 Application error","payload":{"returnValue":false,"errorCode":"-2","errorText":"com.webos.service.tvpower/power is busy"}}
Mon 01:59:40 > Device1, [DEBUG] (SSL) ON response 3: {"type":"response","id":48,"payload":{"returnValue":true,"state":"Suspend","processing":"Screen On"}}
Mon 01:59:41 > Device1, [DEBUG] (SSL) ON response 1: {"type":"registered","id":"register_0","payload":{"client-key":"eda678071598af672e4db09d15f5084d"}}
Mon 01:59:41 > Device1, [DEBUG] (SSL) ON response 2: {"type":"error","id":49,"error":"500 Application error","payload":{"returnValue":false,"state":"Active","errorCode":"-102","errorText":"The current state must be 'Screen Off'"}}
Mon 01:59:41 > Device1, [DEBUG] (SSL) ON response 3: {"type":"response","id":50,"payload":{"returnValue":true,"state":"Active"}}
Mon 01:59:41 > Device1, power state is: ON
Mon 01:59:41 > Device1, repeating WOL broadcast ended
Mon 04:06:56 > ** System requests displays OFF.
Mon 04:06:56 > Device1, spawning Thread_DisplayOff().
Mon 04:07:17 > Device1, WARNING! Thread_DisplayOff(): connect: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond [system:10060 at D:\a\LGTVCompanion\LGTVCompanion\vcpkg_installed\x64-windows-static\x64-windows-static\include\boost\asio\detail\win_iocp_socket_service.hpp:632:5 in function 'connect']
Mon 04:16:16 > -daemon 1 useridle
Mon 04:16:16 > Device1, spawning Thread_DisplayOff().
Mon 04:16:37 > Device1, WARNING! Thread_DisplayOff(): connect: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond [system:10060 at D:\a\LGTVCompanion\LGTVCompanion\vcpkg_installed\x64-windows-static\x64-windows-static\include\boost\asio\detail\win_iocp_socket_service.hpp:632:5 in function 'connect']
Mon 04:26:16 > -daemon 1 useridle
Mon 04:26:16 > Device1, spawning Thread_DisplayOff().
Mon 04:26:37 > Device1, WARNING! Thread_DisplayOff(): connect: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond [system:10060 at D:\a\LGTVCompanion\LGTVCompanion\vcpkg_installed\x64-windows-static\x64-windows-static\include\boost\asio\detail\win_iocp_socket_service.hpp:632:5 in function 'connect']
Mon 04:36:16 > -daemon 1 useridle
Mon 04:36:16 > Device1, spawning Thread_DisplayOff().
Mon 04:36:37 > Device1, WARNING! Thread_DisplayOff(): connect: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond [system:10060 at D:\a\LGTVCompanion\LGTVCompanion\vcpkg_installed\x64-windows-static\x64-windows-static\include\boost\asio\detail\win_iocp_socket_service.hpp:632:5 in function 'connect']
Mon 04:46:16 > -daemon 1 useridle
Mon 04:46:16 > Device1, spawning Thread_DisplayOff().
Mon 04:46:37 > Device1, WARNING! Thread_DisplayOff(): connect: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond [system:10060 at D:\a\LGTVCompanion\LGTVCompanion\vcpkg_installed\x64-windows-static\x64-windows-static\include\boost\asio\detail\win_iocp_socket_service.hpp:632:5 in function 'connect']
Mon 04:56:16 > -daemon 1 useridle
Mon 04:56:16 > Device1, spawning Thread_DisplayOff().
Mon 04:56:37 > Device1, WARNING! Thread_DisplayOff(): connect: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond [system:10060 at D:\a\LGTVCompanion\LGTVCompanion\vcpkg_installed\x64-windows-static\x64-windows-static\include\boost\asio\detail\win_iocp_socket_service.hpp:632:5 in function 'connect']
Mon 05:05:58 > ** System is suspending to a low power state.(or event callback is missing)
Mon 05:08:15 > ** System resumed from low power state (Automatic).
Mon 05:08:15 > ** System requests displays ON.
Mon 05:08:15 > Device1, spawning Thread_DisplayOn().
Mon 05:08:15 > Device1, repeating WOL broadcast started to MAC: B4B291B850F0 using IP address: 192.168.12.151
Mon 05:08:15 > Device1, Best route to IP - interface index 16 LUID 1689399716741120 route protocol 2
Mon 05:08:15 > ** System resumed from low power state.
Mon 05:08:16 > Device1, [DEBUG] (SSL) ON response 1: {"type":"registered","id":"register_0","payload":{"client-key":"eda678071598af672e4db09d15f5084d"}}
Mon 05:08:16 > Device1, [DEBUG] (SSL) ON response 2: {"type":"error","id":2,"error":"500 Application error","payload":{"returnValue":false,"errorCode":"-2","errorText":"com.webos.service.tvpower/power is busy"}}
Mon 05:08:16 > Device1, [DEBUG] (SSL) ON response 3: {"type":"response","id":3,"payload":{"returnValue":true,"state":"Suspend","processing":"Screen On"}}
Mon 05:08:31 > Device1, WARNING! Thread_DisplayOn(): handshake: An existing connection was forcibly closed by the remote host [system:10054]
Mon 05:08:31 > Device1, [DEBUG] (SSL) ON response 1: {"type":"registered","id":"register_0","payload":{"client-key":"eda678071598af672e4db09d15f5084d"}}
Mon 05:08:31 > Device1, [DEBUG] (SSL) ON response 2: {"type":"error","id":4,"error":"500 Application error","payload":{"returnValue":false,"state":"Active","errorCode":"-102","errorText":"The current state must be 'Screen Off'"}}
Mon 05:08:31 > Device1, [DEBUG] (SSL) ON response 3: {"type":"response","id":5,"payload":{"returnValue":true,"state":"Active"}}
Mon 05:08:31 > Device1, power state is: ON
Mon 05:08:32 > Device1, repeating WOL broadcast ended
Mon 09:07:56 > -poweroff Device1
Mon 09:07:56 > [IPC] Force power OFF: Device1 
Mon 09:07:56 > Device1, spawning Thread_DisplayOff().
Mon 09:07:57 > Device1, [DEBUG] (SSL) OFF response 1: {"type":"registered","id":"register_0","payload":{"client-key":"eda678071598af672e4db09d15f5084d"}}
Mon 09:07:57 > Device1, [DEBUG] (SSL) OFF response 2: {"type":"response","id":7,"payload":{"returnValue":true,"state":"Active"}}
Mon 09:07:57 > Device1, [DEBUG] (SSL) OFF response 4: {"type":"response","id":8,"payload":{"returnValue":true}}
Mon 09:07:57 > Device1, power state is: OFF.
Mon 09:08:10 > -poweron Device1
Mon 09:08:10 > [IPC] Force power ON: Device1 
Mon 09:08:10 > Device1, spawning Thread_DisplayOn().
Mon 09:08:10 > Device1, repeating WOL broadcast started to MAC: B4B291B850F0 using IP address: 192.168.12.151
Mon 09:08:10 > Device1, Best route to IP - interface index 16 LUID 1689399716741120 route protocol 2
Mon 09:08:11 > Device1, [DEBUG] (SSL) ON response 1: {"type":"registered","id":"register_0","payload":{"client-key":"eda678071598af672e4db09d15f5084d"}}
Mon 09:08:11 > Device1, [DEBUG] (SSL) ON response 2: {"type":"error","id":9,"error":"500 Application error","payload":{"returnValue":false,"state":"Active","errorCode":"-102","errorText":"The current state must be 'Screen Off'"}}
Mon 09:08:11 > Device1, [DEBUG] (SSL) ON response 3: {"type":"response","id":10,"payload":{"returnValue":true,"state":"Active"}}
Mon 09:08:11 > Device1, power state is: ON
Mon 09:08:11 > Device1, repeating WOL broadcast ended
Tailslide commented 11 months ago

The PC wakes up for a backup between 3 and 3:40 AM so that matches with your log analysis.. no one was at the PC all night and definitely not between 5 and 9am.

Under timers the TV says : Sleep Timer off, Power on Timer Off, Power off Timer Off, Auto Power off after four hours on.

I just now tried turning off wake-timers and wake on lan.. I'll need WOL back eventually but it's a good debugging step thanks for your help I'll report back once I narrow things down a bit more.

Also.. I just noticed the PC Wifi was connected as well as the lan.. not sure how that happened since wifi used to be always off maybe that's the culprit I just tried disabling it.

Greg

Tailslide commented 11 months ago

So.. no use all night and morning.. checked at 2pm and screen was on again.. looks like the computer is not properly sleeping which is maybe half the issue. Not sure why LG Companion doesn't think it's idle might be the same issue. I'll try killing some tasks and services next time around. The TV Auto Power off after four hours feature was off so not sure why it's still got unreachable host messages.

Log.txt

JPersson77 commented 10 months ago

Hi @Tailslide did you have any more progress in troubleshooting the issue?

Tailslide commented 10 months ago

@JPersson77 , the problem is with the user idle detection on my system.. it was detecting me as using the computer when I wasn't. I turned it off and everything is working good now... so I guess you can close this issue?

JPersson77 commented 10 months ago

Hi thanks, I can't really reconcile the info . The app use a trivial api in windows to detect when the user is idle so if the app does not see you as idle then the rest of windows will not see you as idle either. Wrt the PC seemingly waking up I have one more troubleshooting tips, try to disable "wake on pattern match " in your network settings.

Tailslide commented 10 months ago

Wrt the PC seemingly waking up I have one more troubleshooting tips, try to disable "wake on pattern match " in your network settings.

This turned out to be an unrelated issue I tracked down to a USB device that was waking the PC. I turned off the allow device to wake option on it and my computer sleeps good now but I still had the idle issue until I turned off the detect user idle option in LGTVCompanion.

JPersson77 commented 10 months ago

Thanks! But I fail to see how the app can cause an issue with the screen going idle. Potentially there can be a bug which erroneously wake the screen

One thing to try, if you like, is to show the daemon status window with "lgtvdaemon.exe -show" and check the idle counter to try and determine if something is resetting the coutner

Tailslide commented 10 months ago

Not sure what was going on.. my screen never turned off then I disabled the user idle setting and my screen off settings in windows started working again. Maybe some conflict between user idle and my desktop monitor sleep settings? Like if the monitor went into sleep mode at the same time user idle fired off?

I just now tried updating to the latest lgtv companion and set user idle timeout to 1 minute and it seemed to work.. the screen went black but the monitor didn't power off. I'll try setting it back to 10 minutes again and see if I have trouble again.

JPersson77 commented 10 months ago

Hi, I think maybe I read that you have user idle mode and "turn monitor off after x minutes" set to the same time? User idle mode will blank the screen while the other option will turn the TV off, so having them set to the same time is a bit of race condition (and counterproductive). It's better to have user idle mode set to something like 5 minutes and then have the windows power option set to 10 minutes or so.

Maybe I misread your comment

Tailslide commented 10 months ago

I wasn't intentionally setting it to the same time but I also hadn't checked to ensure they were set to different times. I just went back and checked and they were both set to 10 minutes so I changed the windows setting to 15 minutes.

JPersson77 commented 9 months ago

Closing due to resolved. Feel free to reopen as needed