Actions
Bug #2803
closed
igmp version reset
Status:
Resolved
Priority:
Normal
Assignee:
-
Category:
-
Target version:
-
Start date:
02/07/2013
Due date:
% Done:
0%
Estimated time:
Plus Target Version:
Release Notes:
Affected Version:
2.0.x
Affected Architecture:
i386
Description
Version 2.0.2-RELEASE (i386)
built on Fri Dec 7 16:30:38 EST 2012
FreeBSD 8.1-RELEASE-p13
"net.inet.igmp.default_version = 2" is set in System/Advanced/System Tunables. Right after reboot things are going well:
22:26:32.329851 IP 80.x.225.170 > 233.166.172.72: igmp v2 report 233.166.172.72
22:26:45.217090 IP 80.x.225.170 > 224.0.0.2: igmp leave 233.166.172.72
22:26:59.620307 IP 80.x.225.170 > 233.166.172.72: igmp v2 report 233.166.172.72
22:27:05.413067 IP 80.x.225.170 > 224.0.0.2: igmp leave 233.166.172.72
But suddenly for some reason the version raises up to 3:
22:28:07.153471 IP 80.x.225.170 > 224.0.0.22: igmp v3 report, 1 group record(s)
22:28:09.364490 IP 80.x.225.170 > 224.0.0.22: igmp v3 report, 1 group record(s)
22:28:12.180853 IP 80.x.225.170 > 224.0.0.22: igmp v3 report, 1 group record(s)
- sysctl -a|grep igmp
net.inet.igmp.gsrdelay: 10
net.inet.igmp.default_version: 2
net.inet.igmp.legacysupp: 0
net.inet.igmp.v2enable: 1
net.inet.igmp.v1enable: 1
net.inet.igmp.sendlocal: 1
net.inet.igmp.sendra: 1
net.inet.igmp.recvifkludge: 1
Please, help!
Updated by Alex Kolesnik over 12 years ago
There is additional package installed - udpxy, which translates http requests into udp multicast (www.udpxy.com):
- ps ax|grep udpx
5337 ?? I 0:00.01 /usr/local/sbin/udpxy -a re0_vlan1 -m xl0_vlan442 -p 8888 -S -l /var/log/udpxy.log -B 2048K -c 2
udpxy authors state they do nothing with igmp version.
Updated by Ermal Luçi over 12 years ago
- Priority changed from High to Normal
More information is needed here rather than this.
Some packet traces and system logs would be useful.
Debugging logs from igmproxy even better.
Updated by Alex Kolesnik over 12 years ago
Here is an excerpt from the system.log for that small period:
/var/log/system.log:Feb 7 22:26:06 gw-2 udpxy[21646]: write_buf: write: Broken pipe /var/log/system.log:Feb 7 22:26:45 gw-2 udpxy[59652]: write_buf: write: Broken pipe /var/log/system.log:Feb 7 22:26:57 gw-2 kernel: WARNING: pseudo-random number generator used for IPsec processing /var/log/system.log:Feb 7 22:27:05 gw-2 udpxy[59687]: write_buf: write: Broken pipe /var/log/system.log:Feb 7 22:27:31 gw-2 apinger: ALARM: Matrix(80.x.225.169) *** Matrixdown *** /var/log/system.log:Feb 7 22:27:31 gw-2 apinger: alarm canceled: Matrix(80.x.225.169) *** Matrixdown *** /var/log/system.log:Feb 7 22:27:41 gw-2 check_reload_status: Reloading filter /var/log/system.log:Feb 7 22:28:12 gw-2 udpxy[46298]: read_buf: read: Resource temporarily unavailable
80.x.225.169 is a default gateway. This might happen b/c I switched Internet feeding cable from one switch port to another. That took couple seconds. And this cable is not plugged into pfSense directly.
Udpxy log:
2013-02-07 22:26:04.852887 MSK 5337 Accepted socket=[11]
2013-02-07 22:26:04.852976 MSK 5337 Reading command from socket [11]
2013-02-07 22:26:04.853015 MSK 5337 Request=[udp/233.166.172.72:1234], length=[23]
2013-02-07 22:26:04.853045 MSK 5337 Command [udp] with params [233.166.172.72:1234] read from socket=[11]
2013-02-07 22:26:04.853064 MSK 5337 udp_relay : new_socket=[11] param=[233.166.172.72:1234]
2013-02-07 22:26:04.853257 MSK 5337 Client process=[21646] started for socket=[11]
2013-02-07 22:26:04.853468 MSK 21646 min socket buffer = [65536], max space to use = [1500], Rmsgs = [1]
2013-02-07 22:26:04.853409 MSK 5337 Added client: pid=[21646], maddr=[233.166.172.72], mport=[1234], saddr=[172.26.200.30], sport=[37149]
2013-02-07 22:26:04.853499 MSK 21646 Setting up multicast listener
2013-02-07 22:26:04.853507 MSK 5337 Closed accepted socket [11]
2013-02-07 22:26:04.853596 MSK 21646 current receive buffer size is [42080] bytes for socket [2]
2013-02-07 22:26:04.853620 MSK 21646 receive buffer size set to [65536] bytes for socket [2]
2013-02-07 22:26:04.854127 MSK 21646 multicast-group [ADD]
2013-02-07 22:26:04.854184 MSK 21646 Mcast listener socket=[2] set up
2013-02-07 22:26:04.854212 MSK 21646 min socket buffer = [65536], max space to use = [1500], Rmsgs = [1]
2013-02-07 22:26:04.854264 MSK 21646 Data buffer will hold up to [1] messages
2013-02-07 22:26:04.854291 MSK 21646 UDP stream, RTP check enabled
2013-02-07 22:26:04.854368 MSK 21646 current send buffer size is [66608] bytes for socket [11]
2013-02-07 22:26:04.854388 MSK 21646 current receive buffer size is [65536] bytes for socket [2]
2013-02-07 22:26:04.854468 MSK 21646 Sent HTTP response code=[200], reason=[OK] to socket=[11]
2013-02-07 22:26:04.854535 MSK 21646 Relaying traffic from socket[2] to socket[11], buffer size=[2097152], Rmsgs=[1], pauses=[0]
2013-02-07 22:26:04.896077 MSK 21646 Established stream as [MPEG-TS]
2013-02-07 22:26:04.896116 MSK 21646 received new [1316] bytes out of [2097152], last=[0]
2013-02-07 22:26:04.896183 MSK 21646 sent [1316] bytes out of [1316], last=[0]
2013-02-07 22:26:05.002316 MSK 21646 read_data: Buffer timed out after [1] seconds
2013-02-07 22:26:06.000830 MSK 21646 read_data: Buffer timed out after [1] seconds
2013-02-07 22:26:06.580127 MSK 21646 write_buf: write: Broken pipe
2013-02-07 22:26:06.580176 MSK 21646 Exited relay loop: received=[1316], sent=[-1], quit=[0]
2013-02-07 22:26:06.580591 MSK 21646 multicast-group [DROP]
2013-02-07 22:26:06.580665 MSK 21646 Mcast listener socket=[2] closed
2013-02-07 22:26:06.580767 MSK 21646 Child process=[21646] exits with rc=[0]
2013-02-07 22:26:06.581112 MSK 5337 *** Caught SIGCHLD in process=[5337] ***
2013-02-07 22:26:06.581198 MSK 5337 Client [21646] has exited.
2013-02-07 22:26:06.581215 MSK 5337 Deleted client: pid=[21646]
2013-02-07 22:26:32.318613 MSK 5337 Accepted socket=[11]
2013-02-07 22:26:32.318678 MSK 5337 Reading command from socket [11]
2013-02-07 22:26:32.328685 MSK 5337 Request=[udp/233.166.172.72:1234], length=[512]
2013-02-07 22:26:32.328710 MSK 5337 Command [udp] with params [233.166.172.72:1234] read from socket=[11]
2013-02-07 22:26:32.328726 MSK 5337 udp_relay : new_socket=[11] param=[233.166.172.72:1234]
2013-02-07 22:26:32.328960 MSK 5337 Client process=[59652] started for socket=[11]
2013-02-07 22:26:32.329021 MSK 5337 Added client: pid=[59652], maddr=[233.166.172.72], mport=[1234], saddr=[172.26.10.1], sport=[36926]
2013-02-07 22:26:32.329166 MSK 5337 Closed accepted socket [11]
2013-02-07 22:26:32.329184 MSK 59652 min socket buffer = [65536], max space to use = [1500], Rmsgs = [1]
2013-02-07 22:26:32.329214 MSK 59652 Setting up multicast listener
2013-02-07 22:26:32.329401 MSK 59652 current receive buffer size is [42080] bytes for socket [2]
2013-02-07 22:26:32.329429 MSK 59652 receive buffer size set to [65536] bytes for socket [2]
2013-02-07 22:26:32.329927 MSK 59652 multicast-group [ADD]
2013-02-07 22:26:32.329972 MSK 59652 Mcast listener socket=[2] set up
2013-02-07 22:26:32.330000 MSK 59652 min socket buffer = [65536], max space to use = [1500], Rmsgs = [1]
2013-02-07 22:26:32.330024 MSK 59652 Data buffer will hold up to [1] messages
2013-02-07 22:26:32.330041 MSK 59652 UDP stream, RTP check enabled
2013-02-07 22:26:32.330109 MSK 59652 current send buffer size is [65700] bytes for socket [11]
2013-02-07 22:26:32.330128 MSK 59652 current receive buffer size is [65536] bytes for socket [2]
2013-02-07 22:26:32.330196 MSK 59652 Sent HTTP response code=[200], reason=[OK] to socket=[11]
2013-02-07 22:26:32.330262 MSK 59652 Relaying traffic from socket[2] to socket[11], buffer size=[2097152], Rmsgs=[1], pauses=[0]
2013-02-07 22:26:32.525582 MSK 59652 Established stream as [MPEG-TS]
2013-02-07 22:26:32.525645 MSK 59652 received new [1316] bytes out of [2097152], last=[0]
2013-02-07 22:26:32.525677 MSK 59652 sent [1316] bytes out of [1316], last=[0]
2013-02-07 22:26:33.001701 MSK 59652 read_data: Buffer timed out after [1] seconds
2013-02-07 22:26:34.002655 MSK 59652 read_data: Buffer timed out after [1] seconds
2013-02-07 22:26:35.001706 MSK 59652 read_data: Buffer timed out after [1] seconds
2013-02-07 22:26:35.052425 MSK 5337 Received TSTAT={ sender=[59652], bytes=[1316000.000000], seconds=[3.000000] }
2013-02-07 22:26:35.052503 MSK 5337 Updated context for pid=[59652]; [428.4] Kb/sec
2013-02-07 22:26:36.002576 MSK 59652 read_data: Buffer timed out after [1] seconds
2013-02-07 22:26:37.000586 MSK 59652 read_data: Buffer timed out after [1] seconds
2013-02-07 22:26:37.579533 MSK 5337 Received TSTAT={ sender=[59652], bytes=[1316000.000000], seconds=[2.000000] }
2013-02-07 22:26:37.579604 MSK 5337 Updated context for pid=[59652]; [642.6] Kb/sec
2013-02-07 22:26:38.002150 MSK 59652 read_data: Buffer timed out after [1] seconds
2013-02-07 22:26:39.001169 MSK 59652 read_data: Buffer timed out after [1] seconds
2013-02-07 22:26:40.002090 MSK 59652 read_data: Buffer timed out after [1] seconds
2013-02-07 22:26:40.110050 MSK 5337 Received TSTAT={ sender=[59652], bytes=[1316000.000000], seconds=[3.000000] }
2013-02-07 22:26:40.110107 MSK 5337 Updated context for pid=[59652]; [428.4] Kb/sec
2013-02-07 22:26:41.001749 MSK 59652 read_data: Buffer timed out after [1] seconds
2013-02-07 22:26:42.003545 MSK 59652 read_data: Buffer timed out after [1] seconds
2013-02-07 22:26:42.639185 MSK 5337 Received TSTAT={ sender=[59652], bytes=[1316000.000000], seconds=[2.000000] }
2013-02-07 22:26:42.639252 MSK 5337 Updated context for pid=[59652]; [642.6] Kb/sec
2013-02-07 22:26:44.001299 MSK 59652 read_data: Buffer timed out after [1] seconds
2013-02-07 22:26:45.001337 MSK 59652 read_data: Buffer timed out after [1] seconds
2013-02-07 22:26:45.167310 MSK 5337 Received TSTAT={ sender=[59652], bytes=[1316000.000000], seconds=[3.000000] }
2013-02-07 22:26:45.167372 MSK 5337 Updated context for pid=[59652]; [428.4] Kb/sec
2013-02-07 22:26:45.216942 MSK 59652 write_buf: write: Broken pipe
2013-02-07 22:26:45.216991 MSK 59652 Exited relay loop: received=[1316], sent=[-1], quit=[0]
2013-02-07 22:26:45.217336 MSK 59652 multicast-group [DROP]
2013-02-07 22:26:45.217390 MSK 59652 Mcast listener socket=[2] closed
2013-02-07 22:26:45.217493 MSK 59652 Child process=[59652] exits with rc=[0]
2013-02-07 22:26:45.217854 MSK 5337 *** Caught SIGCHLD in process=[5337] ***
2013-02-07 22:26:45.217916 MSK 5337 Client [59652] has exited.
2013-02-07 22:26:45.217974 MSK 5337 Deleted client: pid=[59652]
2013-02-07 22:26:59.619202 MSK 5337 Accepted socket=[11]
2013-02-07 22:26:59.619280 MSK 5337 Reading command from socket [11]
2013-02-07 22:26:59.619309 MSK 5337 Request=[udp/233.166.172.72:1234], length=[512]
2013-02-07 22:26:59.619327 MSK 5337 Command [udp] with params [233.166.172.72:1234] read from socket=[11]
2013-02-07 22:26:59.619343 MSK 5337 udp_relay : new_socket=[11] param=[233.166.172.72:1234]
2013-02-07 22:26:59.619562 MSK 5337 Client process=[59687] started for socket=[11]
2013-02-07 22:26:59.619641 MSK 5337 Added client: pid=[59687], maddr=[233.166.172.72], mport=[1234], saddr=[172.26.10.1], sport=[36956]
2013-02-07 22:26:59.619753 MSK 5337 Closed accepted socket [11]
2013-02-07 22:26:59.619763 MSK 59687 min socket buffer = [65536], max space to use = [1500], Rmsgs = [1]
2013-02-07 22:26:59.619793 MSK 59687 Setting up multicast listener
2013-02-07 22:26:59.619879 MSK 59687 current receive buffer size is [42080] bytes for socket [2]
2013-02-07 22:26:59.619901 MSK 59687 receive buffer size set to [65536] bytes for socket [2]
2013-02-07 22:26:59.620325 MSK 59687 multicast-group [ADD]
2013-02-07 22:26:59.620387 MSK 59687 Mcast listener socket=[2] set up
2013-02-07 22:26:59.620416 MSK 59687 min socket buffer = [65536], max space to use = [1500], Rmsgs = [1]
2013-02-07 22:26:59.620441 MSK 59687 Data buffer will hold up to [1] messages
2013-02-07 22:26:59.620465 MSK 59687 UDP stream, RTP check enabled
2013-02-07 22:26:59.620542 MSK 59687 current send buffer size is [65700] bytes for socket [11]
2013-02-07 22:26:59.620562 MSK 59687 current receive buffer size is [65536] bytes for socket [2]
2013-02-07 22:26:59.620630 MSK 59687 Sent HTTP response code=[200], reason=[OK] to socket=[11]
2013-02-07 22:26:59.620706 MSK 59687 Relaying traffic from socket[2] to socket[11], buffer size=[2097152], Rmsgs=[1], pauses=[0]
2013-02-07 22:26:59.659185 MSK 59687 Established stream as [MPEG-TS]
2013-02-07 22:26:59.659219 MSK 59687 received new [1316] bytes out of [2097152], last=[0]
2013-02-07 22:26:59.659266 MSK 59687 sent [1316] bytes out of [1316], last=[0]
2013-02-07 22:27:01.002298 MSK 59687 read_data: Buffer timed out after [1] seconds
2013-02-07 22:27:02.001210 MSK 59687 read_data: Buffer timed out after [1] seconds
2013-02-07 22:27:02.292227 MSK 5337 Received TSTAT={ sender=[59687], bytes=[1316000.000000], seconds=[3.000000] }
2013-02-07 22:27:02.292325 MSK 5337 Updated context for pid=[59687]; [428.4] Kb/sec
2013-02-07 22:27:03.002830 MSK 59687 read_data: Buffer timed out after [1] seconds
2013-02-07 22:27:04.000206 MSK 59687 read_data: Buffer timed out after [1] seconds
2013-02-07 22:27:04.821913 MSK 5337 Received TSTAT={ sender=[59687], bytes=[1316000.000000], seconds=[2.000000] }
2013-02-07 22:27:04.821977 MSK 5337 Updated context for pid=[59687]; [642.6] Kb/sec
2013-02-07 22:27:05.003410 MSK 59687 read_data: Buffer timed out after [1] seconds
2013-02-07 22:27:05.412917 MSK 59687 write_buf: write: Broken pipe
2013-02-07 22:27:05.412968 MSK 59687 Exited relay loop: received=[1316], sent=[-1], quit=[0]
2013-02-07 22:27:05.413317 MSK 59687 multicast-group [DROP]
2013-02-07 22:27:05.413374 MSK 59687 Mcast listener socket=[2] closed
2013-02-07 22:27:05.413479 MSK 59687 Child process=[59687] exits with rc=[0]
2013-02-07 22:27:05.413838 MSK 5337 *** Caught SIGCHLD in process=[5337] ***
2013-02-07 22:27:05.413899 MSK 5337 Client [59687] has exited.
2013-02-07 22:27:05.413916 MSK 5337 Deleted client: pid=[59687]
2013-02-07 22:28:07.016145 MSK 5337 Accepted socket=[11]
2013-02-07 22:28:07.016204 MSK 5337 Reading command from socket [11]
2013-02-07 22:28:07.026242 MSK 5337 Request=[udp/233.166.172.72:1234], length=[512]
2013-02-07 22:28:07.026266 MSK 5337 Command [udp] with params [233.166.172.72:1234] read from socket=[11]
2013-02-07 22:28:07.026285 MSK 5337 udp_relay : new_socket=[11] param=[233.166.172.72:1234]
2013-02-07 22:28:07.026480 MSK 5337 Client process=[46298] started for socket=[11]
2013-02-07 22:28:07.026555 MSK 5337 Added client: pid=[46298], maddr=[233.166.172.72], mport=[1234], saddr=[172.26.10.1], sport=[37011]
2013-02-07 22:28:07.026717 MSK 5337 Closed accepted socket [11]
2013-02-07 22:28:07.026777 MSK 46298 min socket buffer = [65536], max space to use = [1500], Rmsgs = [1]
2013-02-07 22:28:07.026807 MSK 46298 Setting up multicast listener
2013-02-07 22:28:07.026906 MSK 46298 current receive buffer size is [42080] bytes for socket [2]
2013-02-07 22:28:07.026929 MSK 46298 receive buffer size set to [65536] bytes for socket [2]
2013-02-07 22:28:07.027210 MSK 46298 multicast-group [ADD]
2013-02-07 22:28:07.027238 MSK 46298 Mcast listener socket=[2] set up
2013-02-07 22:28:07.027267 MSK 46298 min socket buffer = [65536], max space to use = [1500], Rmsgs = [1]
2013-02-07 22:28:07.027297 MSK 46298 Data buffer will hold up to [1] messages
2013-02-07 22:28:07.027325 MSK 46298 UDP stream, RTP check enabled
2013-02-07 22:28:07.027407 MSK 46298 current send buffer size is [65700] bytes for socket [11]
2013-02-07 22:28:07.027437 MSK 46298 current receive buffer size is [65536] bytes for socket [2]
2013-02-07 22:28:07.027524 MSK 46298 Sent HTTP response code=[200], reason=[OK] to socket=[11]
2013-02-07 22:28:07.027610 MSK 46298 Relaying traffic from socket[2] to socket[11], buffer size=[2097152], Rmsgs=[1], pauses=[0]
2013-02-07 22:28:12.029956 MSK 46298 read_buf: read: Resource temporarily unavailable
2013-02-07 22:28:12.030005 MSK 46298 read_data - EOF
2013-02-07 22:28:12.030032 MSK 46298 Exited relay loop: received=[-1], sent=[0], quit=[0]
2013-02-07 22:28:12.030095 MSK 46298 multicast-group [DROP]
2013-02-07 22:28:12.030142 MSK 46298 Mcast listener socket=[2] closed
2013-02-07 22:28:12.030318 MSK 46298 Child process=[46298] exits with rc=[0]
2013-02-07 22:28:12.030615 MSK 5337 *** Caught SIGCHLD in process=[5337] ***
2013-02-07 22:28:12.030669 MSK 5337 Client [46298] has exited.
2013-02-07 22:28:12.030688 MSK 5337 Deleted client: pid=[46298]
igmpproxy is off:
# !ps ps ax | grep igmp 35864 1 S+ 0:00.00 grep igmp
What packet traces would you like to have? There are a lot of traffic on xl0_vlan442.
Let me know if you need anything else.
Updated by Alex Kolesnik over 12 years ago
Additional info: this morning I rebooted pfSense and after several hours tried to open the stream. igmp v3 appeared again:
# tcpdump -n -i xl0_vlan442 igmp tcpdump: verbose output suppressed, use -v or -vv for full protocol decode listening on xl0_vlan442, link-type EN10MB (Ethernet), capture size 96 bytes 12:00:54.443329 IP 80.x.225.170 > 224.0.0.22: igmp v3 report, 1 group record(s) 12:00:54.843280 IP 80.x.225.170 > 224.0.0.22: igmp v3 report, 1 group record(s) 12:00:59.468331 IP 80.x.225.170 > 224.0.0.22: igmp v3 report, 1 group record(s) # sysctl -a|grep igmp net.inet.igmp.gsrdelay: 10 net.inet.igmp.default_version: 2
So, it seems to be using igmp v2 just a short time after reboot.
Updated by Vasyl Samoilov about 12 years ago
Run into same issue and found some kind of more detailed description.
Reason seems to be that freebsd is very strict on what it is expecting, and there is some mess with the code.
Providers, on the other side, are not capable of sending all messages strict to rfc, reasons vary. While it's fine with windows and linux, freebsd breaks robustness principle here.
in russian: http://forum.lissyara.su/viewtopic.php?f=4&t=35261
in english (google translate): http://translate.google.com/translate?sl=ru&tl=en&js=n&prev=_t&hl=en&ie=UTF-8&eotf=1&u=http%3A%2F%2Fforum.lissyara.su%2Fviewtopic.php%3Ff%3D4%26t%3D35261
Updated by Chris Buechler about 10 years ago
- Status changed from New to Resolved
the linked thread in Vasyl's comment has the solution on 8.1, and 10.x doesn't appear to have same issue.
Actions