Question: Broken pipe - Githubissues

Ryckie commented 10 months ago

Hello, I have this error and I don't know how to fix it.

2023/09/24 05:16:14 INFO Searching for devices...
2023/09/24 05:16:15 INFO Connected to cast device. device="HUB Enrico"
2023/09/24 05:16:19 INFO Connected to cast device. device="Enrico TV"
2023/09/24 06:19:52 ERROR Lost connection to device. device="HUB Enrico" error="unable to write binary format: write tcp 192.168.0.61:51232->192.168.0.107:8009: write: broken pipe"
2023/09/24 06:21:15 INFO Connected to cast device. device="HUB Enrico"

schumi4 commented 10 months ago

Getting this too after switching to a somewhat unstable wifi connection on the host, always put it down to that.

Try decreasing the discovery time as a workaround so your CC gets re-discovered faster.

Ryckie commented 10 months ago

Getting this too after switching to a somewhat unstable wifi connection on the host, always put it down to that.

Try decreasing the discovery time as a workaround so your CC gets re-discovered faster.

Thank you, I changed it to 2m in the config and still the same issue. My wifi is stable, I run my own dns and dhcp.

schumi4 commented 10 months ago

I meant that as a workaround until the issue is fixed. Doesn't help with the broken pipes, but your CC gets re-discovered faster after it so most times you don't notice it.

gabe565 commented 10 months ago

I've occasionally seen this too. The only thing I can think of is maybe the Cast device is expecting some sort of keepalive message, and when it doesn't get it, it closes the connection? I'll see if I can make this more reliable.

Do you get the error more often for a specific device?

In the mean time, the advice from @schumi4 is perfect. Any failed connection will be retried when the discovery is restarted.

schumi4 commented 9 months ago

Follow up to this:

I was used to seeing this all the time (sometimes 10+ times in one hour) when running over wifi on a rpi. Transitioned to running the docker container directly on my router and have had it happen maybe once or twice over a week. Pretty sure this is dUe to poor network connection on either side, CSS or CC.

Ryckie commented 9 months ago

I've occasionally seen this too. The only thing I can think of is maybe the Cast device is expecting some sort of keepalive message, and when it doesn't get it, it closes the connection? I'll see if I can make this more reliable.

Do you get the error more often for a specific device?

In the mean time, the advice from @schumi4 is perfect. Any failed connection will be retried when the discovery is restarted.

I think it's about the same. I run it on a RPI4b with homeassistant, it's running as an addon. The rpi is connected with ethernet, the two cast devices are wifi 2.4ghz connected. One is at 50cm from the router the other at 2 meter.

Starting...
/etc/cont-init.d/00-banner.sh: executing
-----------------------------------------------------------
 Add-on: Castsponsorskip
 skips sponsored YouTube content on all local Chromecasts
-----------------------------------------------------------
 Add-on version: 0.5.0
 You are running the latest version of this add-on.
 System: Home Assistant OS 10.5  (aarch64 / raspberrypi4-64)
 Home Assistant Core: 2023.9.3
 Home Assistant Supervisor: 2023.09.2
-----------------------------------------------------------
 Please, share the above information when looking for help
 or support in, e.g., GitHub, forums
-----------------------------------------------------------
 Provided by: https://github.com/alexbelgium/hassio-addons 
-----------------------------------------------------------
/etc/cont-init.d/00-global_var.sh: executing
CSS_CATEGORIES='sponsor, into, outro, selfpromo'
CSS_DISCOVER_INTERVAL='1m'
CSS_MUTE_ADS='true'
CSS_YOUTUBE_API_KEY='AIzaSyDkOg9CzT9Z298HFHTfCHNwVMukgbpH89U'
/etc/cont-init.d/01-custom_script.sh: executing
[23:40:16] INFO: Execute /config/addons_autoscripts/sponsorblockcast.sh if existing
[23:40:17] INFO: ... no script found
/etc/cont-init.d/99-run.sh: executing
[23:40:22] INFO: Starting app
2023/09/26 23:40:22 INFO CastSponsorSkip v0.5.0 (73d1f7a)
2023/09/26 23:40:22 INFO Searching for devices...
2023/09/26 23:40:23 INFO Connected to cast device. device="HUB Enrico"
2023/09/27 03:58:14 ERROR Failed to connect to device. device="Enrico TV" error="device not found: "
2023/09/27 05:16:25 ERROR Lost connection to device. device="HUB Enrico" error="context deadline exceeded"
2023/09/27 05:18:13 ERROR Failed to connect to device. device="HUB Enrico" error="unable to connect to chromecast at '192.168.0.107:8009': dial tcp 192.168.0.107:8009: i/o timeout"
2023/09/27 05:18:37 INFO Connected to cast device. device="HUB Enrico"
2023/09/28 03:56:14 ERROR Lost connection to device. device="HUB Enrico" error="unable to write binary format: write tcp 192.168.0.61:60680->192.168.0.107:8009: write: broken pipe"
2023/09/28 03:56:24 INFO Connected to cast device. device="HUB Enrico"
2023/09/29 02:27:01 ERROR Lost connection to device. device="HUB Enrico" error="unable to write binary format: write tcp 192.168.0.61:55726->192.168.0.107:8009: write: broken pipe"
2023/09/29 02:27:26 INFO Connected to cast device. device="HUB Enrico"
2023/09/30 02:40:03 ERROR Lost connection to device. device="HUB Enrico" error="unable to write binary format: write tcp 192.168.0.61:32776->192.168.0.107:8009: write: broken pipe"
2023/09/30 02:40:27 INFO Connected to cast device. device="HUB Enrico"
2023/09/30 18:40:29 ERROR Lost connection to device. device="HUB Enrico" error="context deadline exceeded"
2023/09/30 18:41:28 INFO Connected to cast device. device="HUB Enrico"
2023/10/01 04:59:06 ERROR Lost connection to device. device="HUB Enrico" error="unable to write binary format: write tcp 192.168.0.61:44510->192.168.0.107:8009: write: broken pipe"
2023/10/01 04:59:30 INFO Connected to cast device. device="HUB Enrico"
2023/10/01 14:48:22 INFO Detected video stream. device="HUB Enrico" video_id=lpEc5nHqO2c
2023/10/01 14:48:22 INFO No segments found for video. device="HUB Enrico" video_id=lpEc5nHqO2c
2023/10/01 14:51:32 INFO Detected video stream. device="HUB Enrico" video_id=K_Z1i8lVYj4
2023/10/01 14:51:32 INFO No segments found for video. device="HUB Enrico" video_id=K_Z1i8lVYj4
2023/10/02 02:45:31 ERROR Lost connection to device. device="HUB Enrico" error="unable to write binary format: write tcp 192.168.0.61:60638->192.168.0.107:8009: write: broken pipe"
2023/10/02 02:45:33 INFO Connected to cast device. device="HUB Enrico"
2023/10/03 03:39:25 ERROR Lost connection to device. device="HUB Enrico" error="unable to write binary format: write tcp 192.168.0.61:33882->192.168.0.107:8009: write: broken pipe"
2023/10/03 03:39:34 INFO Connected to cast device. device="HUB Enrico"

gabe565 commented 9 months ago

I've looked at some other Cast-related projects and it seems like this normal. Apparently a lot of Cast devices reboot overnight and install updates randomly. It looks like the general fix is to increase the number or retries and don't log the first few failures. I'll go ahead and do that for now. I'm tired of seeing these logs!

gabe565 commented 9 months ago

I'm testing an update locally which will attempt a full reconnect after a few failures in a row. If this fixes the issue, I'll go ahead and release it 🤞

gabe565 commented 9 months ago

@Ryckie @schumi4 This has been fixed in v0.5.2! Let me know if you still see any issues, but I've been running this update for a full day now with 0 broken pipe errors 🙂

gabe565 commented 9 months ago

I realized I should give some more technical info on the fix.

Before v0.5.2: if the device disconnected, CastSponsorSkip would retry a few times, then give up so that the device could be discovered during the next discovery. This could take a few minutes and resulted in the log messages you saw.
Starting with v0.5.2: when a device disconnects, CastSponsorSkip will instantly create a new connection to the device, and will only log an error if that reconnection fails. This seems to match the behavior of other Cast-related apps and has been working well for me. If the reconnection fails, it will still log an error and wait for discovery, but so far that hasn't happened for me!

@Ryckie @schumi4 I'd also suggest raising your discover interval back up to 5m! It doesn't hurt to keep it lower, but if the connection is stable then it's not necessary anymore.

leewhat commented 9 months ago

It still doesn't rediscover for me until I restart the service after chromecast turned on, chromecast gen 1 Use case is TV and chromecast are powered off, only turn on at morning and night.

Oct 18 18:41:11 aml castsponsorskip[6959]: 2023/10/18 18:41:11 INFO CastSponsorSkip v0.5.3 (85f505b)
Oct 18 18:41:11 aml castsponsorskip[6959]: 2023/10/18 18:41:11 INFO Searching for devices...
Oct 18 18:41:11 aml castsponsorskip[6959]: 2023/10/18 18:41:11 INFO Connected to cast device. device="Master Bedroom TV"
Oct 18 18:41:12 aml castsponsorskip[6959]: 2023/10/18 18:41:12 INFO Detected video stream. device="Master Bedroom TV" video_id=LK6XFIHJQMg
Oct 18 18:41:13 aml castsponsorskip[6959]: 2023/10/18 18:41:13 INFO Found segments for video. device="Master Bedroom TV" segments=2
Oct 18 18:43:38 aml castsponsorskip[6959]: 2023/10/18 18:43:38 INFO Detected ad. Muting and attempting to skip... device="Master Bedroom TV"
Oct 18 18:43:52 aml castsponsorskip[6959]: 2023/10/18 18:43:52 INFO Skipped ad. device="Master Bedroom TV"
Oct 18 18:45:39 aml castsponsorskip[6959]: 2023/10/18 18:45:39 INFO Skipping to timestamp. device="Master Bedroom TV" category=sponsor from=1m43s to=2m14s
Oct 18 18:48:30 aml castsponsorskip[6959]: 2023/10/18 18:48:30 ERROR Lost connection to device. device="Master Bedroom TV" error="unable to write binary format: write tcp 192.168.1.250:38068->192.168.1.5:8009: write: broken pipe"

already waited 10 minutes.

gabe565 commented 9 months ago

@leewhat Hmm I'll have to test taking some devices offline, but it should rediscover the device immediately when it comes back online. So it won't ever rediscover when you turn them back on?

Could you set CSS_LOG_LEVEL=debug and post the logs when you turn the device back on?

leewhat commented 9 months ago

@gabe565 yeah, it doesnt rediscover, I let the it ran wholeday.

here is the logs

-- Logs begin at Fri 2023-10-20 03:17:01 WIB, end at Fri 2023-10-20 15:37:44 WIB. --
Oct 20 06:56:29 aml systemd[1]: Stopping Skip YouTube ads and sponsorships on all local Google Cast devices...
Oct 20 06:56:29 aml castsponsorskip[18920]: 2023/10/20 06:56:29 INFO Gracefully closing connections... Press Ctrl+C again to force exit.
Oct 20 06:56:29 aml castsponsorskip[18920]: 2023/10/20 06:56:29 INFO Exiting.
Oct 20 06:56:29 aml systemd[1]: castsponsorskip.service: Succeeded.
Oct 20 06:56:29 aml systemd[1]: Stopped Skip YouTube ads and sponsorships on all local Google Cast devices.
Oct 20 15:29:34 aml systemd[1]: Started Skip YouTube ads and sponsorships on all local Google Cast devices.
Oct 20 15:29:34 aml castsponsorskip[16859]: time=2023-10-20T15:29:34.731+07:00 level=INFO msg="CastSponsorSkip v0.5.3 (85f505b)"
Oct 20 15:29:34 aml castsponsorskip[16859]: time=2023-10-20T15:29:34.732+07:00 level=INFO msg="Searching for devices..."
Oct 20 15:30:16 aml castsponsorskip[16859]: time=2023-10-20T15:30:16.972+07:00 level=DEBUG msg="Failed to connect to device. Retrying..." device="Master Bedroom TV" try=0 error="unable to connect to chromecast at '192.168.1.5:8009': read tcp 192.168.1.250:58816->192.168.1.5:8009: read: connection reset by peer"
Oct 20 15:30:18 aml castsponsorskip[16859]: time=2023-10-20T15:30:18.578+07:00 level=INFO msg="Connected to cast device." device="Master Bedroom TV"
Oct 20 15:30:19 aml castsponsorskip[16859]: time=2023-10-20T15:30:19.079+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:31:19 aml castsponsorskip[16859]: time=2023-10-20T15:31:19.089+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:31:35 aml castsponsorskip[16859]: time=2023-10-20T15:31:35.873+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:31:46 aml castsponsorskip[16859]: time=2023-10-20T15:31:46.723+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:31:46 aml castsponsorskip[16859]: time=2023-10-20T15:31:46.966+07:00 level=INFO msg="Detected video stream." device="Master Bedroom TV" video_id=LK6XFIHJQMg
Oct 20 15:31:46 aml castsponsorskip[16859]: time=2023-10-20T15:31:46.967+07:00 level=DEBUG msg="Request segments" url="https://sponsor.ajay.app/api/skipSegments/f672?actionType=skip&actionType=mute&category=sponsor"
Oct 20 15:31:47 aml castsponsorskip[16859]: time=2023-10-20T15:31:47.222+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:31:47 aml castsponsorskip[16859]: time=2023-10-20T15:31:47.722+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:31:48 aml castsponsorskip[16859]: time=2023-10-20T15:31:48.059+07:00 level=INFO msg="Found segments for video." device="Master Bedroom TV" segments=1
Oct 20 15:31:49 aml castsponsorskip[16859]: time=2023-10-20T15:31:49.184+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:31:49 aml castsponsorskip[16859]: time=2023-10-20T15:31:49.585+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:31:49 aml castsponsorskip[16859]: time=2023-10-20T15:31:49.790+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:31:50 aml castsponsorskip[16859]: time=2023-10-20T15:31:50.222+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:31:54 aml castsponsorskip[16859]: time=2023-10-20T15:31:54.110+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:31:54 aml castsponsorskip[16859]: time=2023-10-20T15:31:54.619+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:31:54 aml castsponsorskip[16859]: time=2023-10-20T15:31:54.977+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:31:55 aml castsponsorskip[16859]: time=2023-10-20T15:31:55.294+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:31:56 aml castsponsorskip[16859]: time=2023-10-20T15:31:56.628+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:31:57 aml castsponsorskip[16859]: time=2023-10-20T15:31:57.199+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:31:57 aml castsponsorskip[16859]: time=2023-10-20T15:31:57.529+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:31:58 aml castsponsorskip[16859]: time=2023-10-20T15:31:58.142+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:31:58 aml castsponsorskip[16859]: time=2023-10-20T15:31:58.361+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:31:58 aml castsponsorskip[16859]: time=2023-10-20T15:31:58.723+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:31:59 aml castsponsorskip[16859]: time=2023-10-20T15:31:59.223+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:31:59 aml castsponsorskip[16859]: time=2023-10-20T15:31:59.722+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:32:00 aml castsponsorskip[16859]: time=2023-10-20T15:32:00.222+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:32:00 aml castsponsorskip[16859]: time=2023-10-20T15:32:00.722+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:32:05 aml castsponsorskip[16859]: time=2023-10-20T15:32:05.728+07:00 level=DEBUG msg=Update device="Master Bedroom TV"
Oct 20 15:32:40 aml castsponsorskip[16859]: time=2023-10-20T15:32:40.737+07:00 level=DEBUG msg="Failed to update device. Reconnecting..." device="Master Bedroom TV" error="context deadline exceeded"
Oct 20 15:32:43 aml castsponsorskip[16859]: time=2023-10-20T15:32:43.739+07:00 level=DEBUG msg="Failed to connect to device. Retrying..." device="Master Bedroom TV" try=0 error="unable to connect to chromecast at '192.168.1.5:8009': dial tcp 192.168.1.5:8009: i/o timeout"
Oct 20 15:32:49 aml castsponsorskip[16859]: time=2023-10-20T15:32:49.242+07:00 level=DEBUG msg="Failed to connect to device. Retrying..." device="Master Bedroom TV" try=1 error="unable to connect to chromecast at '[<nil>]:0': dial tcp: lookup <nil>: no such host"
Oct 20 15:32:55 aml castsponsorskip[16859]: time=2023-10-20T15:32:55.245+07:00 level=DEBUG msg="Failed to connect to device. Retrying..." device="Master Bedroom TV" try=2 error="unable to connect to chromecast at '[<nil>]:0': dial tcp: lookup <nil>: no such host"
Oct 20 15:33:02 aml castsponsorskip[16859]: time=2023-10-20T15:33:02.248+07:00 level=DEBUG msg="Failed to connect to device. Retrying..." device="Master Bedroom TV" try=3 error="unable to connect to chromecast at '[<nil>]:0': dial tcp: lookup <nil>: no such host"
Oct 20 15:33:11 aml castsponsorskip[16859]: time=2023-10-20T15:33:11.249+07:00 level=DEBUG msg="Failed to connect to device. Retrying..." device="Master Bedroom TV" try=4 error="unable to connect to chromecast at '[<nil>]:0': dial tcp: lookup <nil>: no such host"
Oct 20 15:33:24 aml castsponsorskip[16859]: time=2023-10-20T15:33:24.252+07:00 level=DEBUG msg="Failed to connect to device. Retrying..." device="Master Bedroom TV" try=5 error="unable to connect to chromecast at '[<nil>]:0': dial tcp: lookup <nil>: no such host"
Oct 20 15:33:45 aml castsponsorskip[16859]: time=2023-10-20T15:33:45.254+07:00 level=DEBUG msg="Failed to reconnect." device="Master Bedroom TV" error="device not found: "
Oct 20 15:33:45 aml castsponsorskip[16859]: time=2023-10-20T15:33:45.254+07:00 level=ERROR msg="Lost connection to device." device="Master Bedroom TV" error="context deadline exceeded"
Oct 20 15:33:45 aml castsponsorskip[16859]: time=2023-10-20T15:33:45.255+07:00 level=DEBUG msg="Panic during close" device="Master Bedroom TV" error="runtime error: invalid memory address or nil pointer dereference" stack="goroutine 22 [running]:\nruntime/debug.Stack()\n\truntime/debug/stack.go:24 +0x64\ngithub.com/gabe565/castsponsorskip/internal/device.(*Device).closeApp.func1()\n\tgithub.com/gabe565/castsponsorskip/internal/device/watch.go:120 +0x40\npanic({0x72bd80?, 0xe1a5a0?})\n\truntime/panic.go:914 +0x218\ncrypto/tls.(*Conn).Close(0x71fc60?)\n\tcrypto/tls/conn.go:1403 +0x18\ngithub.com/vishen/go-chromecast/cast.(*Connection).Close(0x0?)\n\tgithub.com/vishen/go-chromecast@v0.3.2-0.20231012231916-ce26f51593c1/cast/connection.go:82 +0x94\ngithub.com/vishen/go-chromecast/application.(*Application).Close(0x4000061e78?, 0x24?)\n\tgithub.com/vishen/go-chromecast@v0.3.2-0.20231012231916-ce26f51593c1/application/application.go:431 +0x110\ngithub.com/gabe565/castsponsorskip/internal/device.(*Device).closeApp(0x0?)\n\tgithub.com/gabe565/castsponsorskip/internal/device/watch.go:124 +0x5c\ngithub.com/gabe565/castsponsorskip/internal/device.(*Device).Close(0x400023b080)\n\tgithub.com/gabe565/castsponsorskip/internal/device/watch.go:113 +0x84\ngithub.com/gabe565/castsponsorskip/cmd.run.func1.1()\n\tgithub.com/gabe565/castsponsorskip/cmd/cmd.go:104 +0xa4\ncreated by github.com/gabe565/castsponsorskip/cmd.run.func1 in goroutine 35\n\tgithub.com/gabe565/castsponsorskip/cmd/cmd.go:101 +0x50\n"
Oct 20 15:34:34 aml castsponsorskip[16859]: time=2023-10-20T15:34:34.742+07:00 level=DEBUG msg="Ignoring device." device="Master Bedroom TV" reason="Already connected"

gabe565 commented 9 months ago

@leewhat Thanks for the log! Was the end when you turned the device back on? If so, I think I know what's going on here and I can fix it

leewhat commented 9 months ago

yes, the end is when i turn it on

gabe565 commented 8 months ago

@leewhat I found the root cause of this and was finally able to fix it in v0.6.1! Would you mind verifying?

leewhat commented 8 months ago

@gabe565 it works now, thank you!

gabe565 commented 8 months ago

@leewhat That's great to hear!

gabe565 / CastSponsorSkip

Question: Broken pipe #28