Infinite loop in libcppnetlib-uri.so causing 100% CPU usage

So the mystery of the “NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Host is down” log entries is solved…

It seems Plex is constructing it’s own broadcast address from the IP and netmask rather than using the configured broadcast address (which is of course 255.255.255.255 on that interface). These log entries correspond to unanswered ARP requests.

Just to highlight an offhand comment I made in the initial report so it doesn’t get lost, I have a suspicion that the issue is not in the cpp-netlib source itself, but rather in the boost version it’s built with (or possibly some other dependency).

This is happening cause that’s a public IP. (I mean the broadcast address)

I will admit its a fair critic, we assume the server is running in a private network and not in a public interface, some would argue it offers better security, but I do think if its possible then the user is free to do as he pleases, However its still true this is not well supported, and pms could act differently in such cases.

FWIW there are some internal issues for that, but I would say its probably not top priority right now.

Interesting, we actually recently added support for BSD debug builds, I can’t promise any timing on it, I’m busy with a lot of stuff at the moment, but I could possibly try to run this in a VPS using a debug build and see If I repo this but get a proper backtrace.

Are you ruining this self hosted and have a public IP fro the box/jail or is it a VPS? Just want to gather as much info as possible so I can replicate the scenario… (If you want to send more details fell free to DM me) If this is something else we should still try to figure what it is!

Yeah, I use a fairly beefy system as a server at home, and it handles routing as well as Plex and various other “stuff”.

hum that might be a bit more complicated to replicate :stuck_out_tongue:

The only interactions with other “stuff” on the box is likely to be that port 1900 can’t be bound on the local interface, and no UPnP replies are recieved. I experimented with changing Plex to bind port 1901, which didn’t seem to make a difference, so the binding port 1900 likely isn’t an issue.

Since disabling UPnP on the router seems to solve the issue for others, that’s not likely to be it either. If I were a betting man, I would blame the ARP failure for the broadcast address for triggering the issue… which means you need to be careful not to fix the incorrect broadcast address issue before fixing the infinite loop issue, or you won’t be able to repro. :smiley:

I sent a test build to you directly @RealDeuce.

As for the broadcast issue can you paste me the ifconfig output (for this interface)?

Test build is looking good (aside from complete lack of codecs :smiley: )

ifconfig output for lagg0:

lagg0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
	options=81249b<RXCSUM,TXCSUM,VLAN_MTU,VLAN_HWTAGGING,VLAN_HWCSUM,LRO,WOL_MAGIC,VLAN_HWFILTER>
	ether 00:25:90:f5:9b:75
	inet6 fe80::225:90ff:fef5:9b74%lagg0 prefixlen 64 scopeid 0x6 
	inet6 2001:558:6007:a4:1de6:32ba:121f:3b prefixlen 128 
	inet 107.5.177.180 netmask 0xfffffc00 broadcast 255.255.255.255 
	laggproto lacp lagghash l3,l4
	laggport: em0 flags=1c<ACTIVE,COLLECTING,DISTRIBUTING>
	laggport: em1 flags=1c<ACTIVE,COLLECTING,DISTRIBUTING>
	groups: lagg 
	media: Ethernet autoselect
	status: active
	nd6 options=23<PERFORMNUD,ACCEPT_RTADV,AUTO_LINKLOCAL>

Codecs should be deployed now, sorry about that, its an automated process for beta/public builds but not experimental :slight_smile:

Great news guys!

@RealDeuce for the broadcast I’ve confirmed we do in fact do it wrong in some cases, but it should be harmless except from spamming the log, and as you’ve noticed its unrelated to the issue with cppnetlib which should finally be fixed :pray:

I’ve raised it internally regardless and hopefully it will be fixed to, but might take a bit since its of lower prio.

@RealDeuce if possible can you show me how often that happens in the log? Every 15~30 secs right?

It currently seems to be happening on average every 2 seconds, and it looks like multiple things are trying it. Here’s one minutes worth off logs (this includes all discover packet sends). Everything address except 107.5.179.255 seems to be every ten seconds while 107.5.179.255 is about twice every five seconds.

Jun 14, 2019 15:08:01.434 [0x80ba1aa00] WARN - NetworkServiceBrowser: Error sending out discover packet from 192.168.0.1 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:01.434 [0x80ba1aa00] WARN - NetworkServiceBrowser: Error sending out discover packet from 192.168.1.1 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:01.435 [0x80ba1aa00] WARN - NetworkServiceBrowser: Error sending out discover packet from 192.168.0.4 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:01.435 [0x80ba1aa00] WARN - NetworkServiceBrowser: Error sending out discover packet from fe80::225:90ff:fef5:9b74%lagg0 to ff02::f%6: Permission denied
Jun 14, 2019 15:08:01.435 [0x80ba1aa00] WARN - NetworkServiceBrowser: Error sending out discover packet from 2001:558:6007:a4:1de6:32ba:121f:3b to ff02::f%6: Permission denied
Jun 14, 2019 15:08:01.435 [0x80ba1aa00] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:03.465 [0x810fcb500] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:03.465 [0x80ba1d200] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:08.484 [0x80ba1d200] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:08.484 [0x810fcb500] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:11.490 [0x810fcb500] WARN - NetworkServiceBrowser: Error sending out discover packet from 192.168.0.1 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:11.490 [0x810fcb500] WARN - NetworkServiceBrowser: Error sending out discover packet from 192.168.1.1 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:11.490 [0x810fcb500] WARN - NetworkServiceBrowser: Error sending out discover packet from 192.168.0.4 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:11.490 [0x810fcb500] WARN - NetworkServiceBrowser: Error sending out discover packet from fe80::225:90ff:fef5:9b74%lagg0 to ff02::f%6: Permission denied
Jun 14, 2019 15:08:11.490 [0x810fcb500] WARN - NetworkServiceBrowser: Error sending out discover packet from 2001:558:6007:a4:1de6:32ba:121f:3b to ff02::f%6: Permission denied
Jun 14, 2019 15:08:11.490 [0x810fcb500] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:13.610 [0x810fcb500] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:13.610 [0x80ba1aa00] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:18.797 [0x810fcb500] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:18.797 [0x80ba1aa00] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:21.509 [0x80e741000] WARN - NetworkServiceBrowser: Error sending out discover packet from 192.168.0.1 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:21.509 [0x80e741000] WARN - NetworkServiceBrowser: Error sending out discover packet from 192.168.1.1 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:21.509 [0x80e741000] WARN - NetworkServiceBrowser: Error sending out discover packet from 192.168.0.4 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:21.510 [0x80e741000] WARN - NetworkServiceBrowser: Error sending out discover packet from fe80::225:90ff:fef5:9b74%lagg0 to ff02::f%6: Permission denied
Jun 14, 2019 15:08:21.510 [0x80e741000] WARN - NetworkServiceBrowser: Error sending out discover packet from 2001:558:6007:a4:1de6:32ba:121f:3b to ff02::f%6: Permission denied
Jun 14, 2019 15:08:21.510 [0x80e741000] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:23.814 [0x80e741000] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:23.814 [0x80d534000] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:28.825 [0x80d534000] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:28.825 [0x80e741000] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:31.513 [0x80d5ef500] WARN - NetworkServiceBrowser: Error sending out discover packet from 192.168.0.1 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:31.514 [0x80d5ef500] WARN - NetworkServiceBrowser: Error sending out discover packet from 192.168.1.1 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:31.514 [0x80d5ef500] WARN - NetworkServiceBrowser: Error sending out discover packet from 192.168.0.4 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:31.514 [0x80d5ef500] WARN - NetworkServiceBrowser: Error sending out discover packet from fe80::225:90ff:fef5:9b74%lagg0 to ff02::f%6: Permission denied
Jun 14, 2019 15:08:31.514 [0x80d5ef500] WARN - NetworkServiceBrowser: Error sending out discover packet from 2001:558:6007:a4:1de6:32ba:121f:3b to ff02::f%6: Permission denied
Jun 14, 2019 15:08:31.514 [0x80d5ef500] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:33.846 [0x80d534000] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:33.846 [0x80d5ef500] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:38.870 [0x80d534000] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:38.870 [0x80d5ef500] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:41.553 [0x80ba1b400] WARN - NetworkServiceBrowser: Error sending out discover packet from 192.168.0.1 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:41.553 [0x80ba1b400] WARN - NetworkServiceBrowser: Error sending out discover packet from 192.168.1.1 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:41.553 [0x80ba1b400] WARN - NetworkServiceBrowser: Error sending out discover packet from 192.168.0.4 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:41.553 [0x80ba1b400] WARN - NetworkServiceBrowser: Error sending out discover packet from fe80::225:90ff:fef5:9b74%lagg0 to ff02::f%6: Permission denied
Jun 14, 2019 15:08:41.553 [0x80ba1b400] WARN - NetworkServiceBrowser: Error sending out discover packet from 2001:558:6007:a4:1de6:32ba:121f:3b to ff02::f%6: Permission denied
Jun 14, 2019 15:08:41.553 [0x80ba1b400] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:43.888 [0x80d534000] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:43.889 [0x80ba1b400] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:48.891 [0x80ba1b400] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:48.891 [0x80d534000] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:51.557 [0x8118a0400] WARN - NetworkServiceBrowser: Error sending out discover packet from 192.168.0.1 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:51.557 [0x8118a0400] WARN - NetworkServiceBrowser: Error sending out discover packet from 192.168.1.1 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:51.557 [0x8118a0400] WARN - NetworkServiceBrowser: Error sending out discover packet from 192.168.0.4 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:51.558 [0x8118a0400] WARN - NetworkServiceBrowser: Error sending out discover packet from fe80::225:90ff:fef5:9b74%lagg0 to ff02::f%6: Permission denied
Jun 14, 2019 15:08:51.558 [0x8118a0400] WARN - NetworkServiceBrowser: Error sending out discover packet from 2001:558:6007:a4:1de6:32ba:121f:3b to ff02::f%6: Permission denied
Jun 14, 2019 15:08:51.558 [0x8118a0400] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 239.255.255.250: Permission denied
Jun 14, 2019 15:08:53.911 [0x80d534000] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:53.911 [0x8118a0400] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:58.925 [0x8118a0400] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied
Jun 14, 2019 15:08:58.925 [0x80ba1aa00] WARN - NetworkServiceBrowser: Error sending out discover packet from 107.5.177.180 to 107.5.179.255: Permission denied

It’s interesting that it logs permission denied now. It previously was logging host not found. With the change to permission denied, I’m no longer seeing ARP requests. I wonder if Plex isn’t setting SO_REUSEPORT to bind port 1900 anymore?

It looks like Plex creates two different sockets both bound to 107.5.177.180. They both do the same “stuff”… truss log of one of the sockets:

socket(PF_INET,SOCK_DGRAM,IPPROTO_UDP)           = 85 (0x55)
setsockopt(85,SOL_SOCKET,SO_NOSIGPIPE,0x814400ac0,4) = 0 (0x0)
setsockopt(85,SOL_SOCKET,SO_REUSEADDR,0x814400b90,4) = 0 (0x0)
setsockopt(85,SOL_SOCKET,SO_REUSEPORT,0x814400b90,4) = 0 (0x0)
bind(85,{ AF_INET 107.5.177.180:0 },16)          = 0 (0x0)
fcntl(85,F_SETFD,FD_CLOEXEC)                     = 0 (0x0)
setsockopt(85,SOL_SOCKET,SO_BROADCAST,0x814400cc0,4) = 0 (0x0)
ioctl(85,FIONBIO,0x814400bf4)                    = 0 (0x0)
recvmsg(85,0x814400ac0,0)                        ERR#35 'Resource temporarily unavailable'
sendmsg(85,{{ AF_INET 107.5.179.255:32412 },16,[{"M-SEARCH * HTTP/1.1\r\n",21}],1,{},0,0},0) ERR#13 'Permission denied'
getsockname(85,{ AF_INET 107.5.177.180:14561 },0x810200938) = 0 (0x0)
sendmsg(85,{{ AF_INET 107.5.179.255:32412 },16,[{"M-SEARCH * HTTP/1.1\r\n",21}],1,{},0,0},0) ERR#13 'Permission denied'
getsockname(85,{ AF_INET 107.5.177.180:14561 },0x811004938) = 0 (0x0)

So it is setting SO_REUSEPORT, unfortunately, I can’t tell what it’s setting it to.

Interestingly, it’s sendmsg() that’s returning EACCES, which suggests that SO_BROADCAST isn’t being set to true (even though it’s being set to something).

So checking the SO_BROADCAST shows that it is being set to 1. No idea what’s causing the EACCES.

Ok, so the multicast permission deined issues all seem to stem from not setting the IP_MULTICAST_IF option when using a non-default multicast interface (ie: the internal one). This should be a simple fix since it should be safe to set for all multicast sockets.

I was going to ask if the Permission denied could be due to firewall form you’re first post… but what you posted after does suggest something odd is happening.

Also logging every 2 secs is for sure more then I was expecting.

Can you try to stop PMS, make sure all processes and sockets did die… then start it again and check if you still see this 2 different sockets?

It would make sense if it was both ipv4 and v6 especially on FreeBSD but the log u posted seems to be v4 only.

EDIT (also it would only make sense if you do have ipv6 enabled)

Might be best to open a new topic for this, or if you prefer we can continue in DM I would love to see more details so I can had this to the internal report.

Yeah, I tried shutting down plex… and the truss logs are guaranteed to be from a sing process. :smiley:

I did just notice a difference though… one is trying to send to port 32412 and the other is sending to port 32414.

Truss details for the first (port 32412) socket:

socket(PF_INET,SOCK_DGRAM,IPPROTO_UDP)           = 85 (0x55)
setsockopt(85,SOL_SOCKET,SO_NOSIGPIPE,0x814400ac0,4) = 0 (0x0)
setsockopt(85,SOL_SOCKET,SO_REUSEADDR,0x814400b90,4) = 0 (0x0)
setsockopt(85,SOL_SOCKET,SO_REUSEPORT,0x814400b90,4) = 0 (0x0)
bind(85,{ AF_INET 107.5.177.180:0 },16)          = 0 (0x0)
fcntl(85,F_SETFD,FD_CLOEXEC)                     = 0 (0x0)
setsockopt(85,SOL_SOCKET,SO_BROADCAST,0x814400cc0,4) = 0 (0x0)
ioctl(85,FIONBIO,0x814400bf4)                    = 0 (0x0)
recvmsg(85,0x814400ac0,0)                        ERR#35 'Resource temporarily unavailable'
sendmsg(85,{{ AF_INET 107.5.179.255:32412 },16,[{"M-SEARCH * HTTP/1.1\r\n",21}],1,{},0,0},0) ERR#13 'Permission denied'
getsockname(85,{ AF_INET 107.5.177.180:14561 },0x810200938) = 0 (0x0)

And for the second socket:

socket(PF_INET,SOCK_DGRAM,IPPROTO_UDP)           = 97 (0x61)
setsockopt(97,SOL_SOCKET,SO_NOSIGPIPE,0x814400ac0,4) = 0 (0x0)
setsockopt(97,SOL_SOCKET,SO_REUSEADDR,0x814400b90,4) = 0 (0x0)
setsockopt(97,SOL_SOCKET,SO_REUSEPORT,0x814400b90,4) = 0 (0x0)
bind(97,{ AF_INET 107.5.177.180:0 },16)          = 0 (0x0)
fcntl(97,F_SETFD,FD_CLOEXEC)                     = 0 (0x0)
setsockopt(97,SOL_SOCKET,SO_BROADCAST,0x814400cc0,4) = 0 (0x0)
ioctl(97,FIONBIO,0x814400bf4)                    = 0 (0x0)
recvmsg(97,0x814400ac0,0)                        ERR#35 'Resource temporarily unavailable'
sendmsg(97,{{ AF_INET 107.5.179.255:32414 },16,[{"M-SEARCH * HTTP/1.1\r\n",21}],1,{},0,0},0) ERR#13 'Permission denied'
getsockname(97,{ AF_INET 107.5.177.180:40184 },0x811e00938) = 0 (0x0)

Other than the source and destination port numbers, they’re identical.

Ah ok this makes more sense, they are both used for discovery and that is expected (ofc the wrong broadcast address is still an issue)