Bug #436

Hi Mike,

Looks like the cable modem router bug’s been exercised again,
dropping 30% of pings, and of course noticable in use:

Destination IP: 50.131.246.224
Prior hop IP: 68.86.142.254
Number of pings: 60
PING 50.131.246.224 (50.131.246.224): 56 data bytes
PING 68.86.142.254 (68.86.142.254): 56 data bytes

— 68.86.142.254 ping statistics —
60 packets transmitted, 60 packets received, 0.0% packet loss
round-trip min/avg/max/stddev = 26.⁹⁸⁵⁄₃₄.099/58.088/7.826 ms

— 50.131.246.224 ping statistics —
60 packets transmitted, 42 packets received, 30.0% packet loss
round-trip min/avg/max/stddev = 37.⁷⁸⁸⁄₄₄.²⁰⁵⁄₇₆.⁶⁰⁷⁄₆.609 ms

Tony

On Thu, Aug 08, 2013 at 04:53:14PM -0700, Tony Morel wrote:
> OK, I first ssh’d to oldnet. I’m attaching current.(log|dmesg)
>
> Is there some fine point about dissociating the reboot
> and logging off root before the reboot? Or something?
> Now I get this:
>
> root@oldnet:~# ssh root@172.26.3.1
> ssh: connect to host 172.26.3.1 port 22: Connection refused
>
> Will that require a power cycle to resolve?
>
> Anyway, reboot cleared the dropped packet problem for now:
>
> \$ hopchk
> End-of-hop IP: 50.131.246.224
> Prior hop IP: 68.86.142.250
> Number of pings: 60
> PING 50.131.246.224 (50.131.246.224): 56 data bytes
> PING 68.86.142.250 (68.86.142.250): 56 data bytes
>
> — 68.86.142.250 ping statistics —
> 60 packets transmitted, 60 packets received, 0.0% packet loss
> round-trip min/avg/max/stddev = 27.⁹³¹⁄₅₃.³⁵¹⁄₂₉₄.²⁶⁷⁄₆₂.636 ms
>
> — 50.131.246.224 ping statistics —
> 60 packets transmitted, 60 packets received, 0.0% packet loss
> round-trip min/avg/max/stddev = 34.³¹⁶⁄₆₄.²⁰⁸⁄₃₁₅.³⁵⁴⁄₇₀.786 ms
>
> Tony
>
> On Thu, Aug 08, 2013 at 02:39:01PM -0700, Dave Taht wrote:
> > On Thu, Aug 8, 2013 at 2:26 PM, Tony Morel morel@armory.com wrote:
> > > Hi Mike,
> > >
> > > I, too, have been over busy, but finally dug up my notes
> > > last night - but then found johnd, the machine on the cable side
> > > of the network, evidentally powered off while Irene’s out of town.
> > > Is there another way to find my way to the cable router from
> > > deepthought?
> >
> > I dunno, you should be able to ssh to the internal ip addresses for her network.
> >
> > powering down johnd messes up email so far as I know (it was doing rbls)
> >
> > >
> > > Might as well ask, too: will the router let me
> > > scp the logs back to the mother ship?
> >
> > sure.
> >
> > >
> > > Tony
> > >
> > >
> > > On Wed, Jul 31, 2013 at 02:13:20PM -0700, Dave Taht wrote:
> > >> ENOTIME.
> > >>
> > >> do a
> > >>
> > >> logread > /root/current.log
> > >> dmesg > /root/current.dmesg
> > >>
> > >> and just reboot
> > >>
> > >>
> > >>
> > >> On Wed, Jul 31, 2013 at 2:08 PM, Dave Taht dave.taht@gmail.com wrote:
> > >> > wow. All I remember was that I’d port forwarded 222 somewhere…
> > >> >
> > >> >
> > >> > On Wed, Jul 31, 2013 at 1:41 PM, Tony Morel morel@armory.com wrote:
> > >> >> Hi Mike,
> > >> >>
> > >> >> Irene’s router for the cable modem is dropping ~20% packets again today.
> > >> >> If like last time, it will continue doing so until reset.
> > >> >>
> > >> >> You may recall that when we started to look into this last time, we were
> > >> >> briefly missing the router password, power-cycled the router, got the password,
> > >> >> but then no longer had the logs to look over. The reset remedied the
> > >> >> packet dropping.
> > >> >>
> > >> >> This time we have the password and the logs. Seems like something worth
> > >> >> trying to get to the bottom of, no?
> > >> >>
> > >> >> Tony
> > >> >>
> > >> >>
> > >> >> \$ hopchk
> > >> >> End-of-hop IP: 50.131.246.224
> > >> >> Prior hop IP: 68.86.142.250
> > >> >> Number of pings: 60
> > >> >> PING 68.86.142.250 (68.86.142.250): 56 data bytes
> > >> >> PING 50.131.246.224 (50.131.246.224): 56 data bytes
> > >> >>
> > >> >> — 68.86.142.250 ping statistics —
> > >> >> 60 packets transmitted, 60 packets received, 0.0% packet loss
> > >> >> round-trip min/avg/max/stddev = 26.⁴⁴²⁄₃₁.⁸⁴⁹⁄₄₅.⁴¹⁹⁄₃.476 ms
> > >> >>
> > >> >> — 50.131.246.224 ping statistics —
> > >> >> 60 packets transmitted, 47 packets received, 21.7% packet loss
> > >> >> round-trip min/avg/max/stddev = 33.⁶¹⁶⁄₃₈.⁶⁵¹⁄₆₂.⁸⁷⁸⁄₅.068 ms
> > >> >
> > >> >
> > >> >

I AM puzzled as to why it was noticable at all vs fq_codel, my thought is I should have captured more data than I just did….

I was experiencing 13% packet loss. running at nearly 100% of cpu, too…

the router was runnign 3.7.1, so it predates the official 3.7 release of cerowrt. I have no doubt this bug persisted in later versions and may well persist today.

Also, we had major traps. I am vague on when we fully fixed these, but I’m pretty sure it wasn’t before 3.7.2

root@gw-comcast:/sys/kernel/debug/mips# cat unaligned_instructions
17755733
root@gw-comcast:/sys/kernel/debug/mips# cat unaligned_instructions
17756005
root@gw-comcast:/sys/kernel/debug/mips#

Anyway, after killing off odhcpv6c entirely the system returned to normal

odhcp6c is completely normal on the reboot, blocking in recv… (no ipv6 on this network)

Theory: the packet capture I just took shows “elapsed time” of 655350 ms in the
dhcpv6 field. Perhaps we’ve hit an overflow here, after X time runnning….

root@gw-comcast:~# strace -p 1516
Process 1516 attached
clock_gettime(CLOCK_MONOTONIC, {211, 808127890}) = 0
setsockopt(4, SOL_SOCKET, SO_RCVTIMEO, “\0\0\0000\0\5\300\250”, 8) = 0
recv(4, 0x7ff5897c, 1536, 0) = -1 EAGAIN (Resource temporarily unavailable)
clock_gettime(CLOCK_MONOTONIC, {260, 190780387}) = 0
read(3, “\t![]()\5”, 4) = 4
read(3, “\204\363oB”, 4) = 4
uname({sys=“Linux”, node=“gw-comcast.hm.armory.com”, …}) = 0
sendmsg(4, {msg_name(28)={sa_family=AF_INET6, sin6_port=htons(547), inet_pton(AF_INET6, “ff02::1:2”, &sin6_addr), sin6_flowinfo=0, sin6_scope_id=if_nametoindex(“ge00”)}, msg_iov(11)=[{”\1\177\373\226\0\10\0\2Qe\0\6\0\4”, 14}, {”\0\27\0\30”, 4}, {“”, 0}, {”\0\1\0\n\0\3\0\1\0\216\362\372\241T”, 14}, {NULL, 0}, {”\0\24\0\0”, 4}, {”\0’\0\33\0\ngw-comcast\2hm\6armory\3com\0”, 31}, {”\0\3\0\f\0\0\0\1\0\0\0\0\0\0\0\0”, 16}, {NULL, 0}, {”\0\31\0\f\0\0\0\1\0\0\0\0\0\0\0\0”, 16}, {NULL, 0}], msg_controllen=0, msg_flags=0}, 0) = 99
setsockopt(4, SOL_SOCKET, SO_RCVTIMEO, “\0\0\0w\0\5_\0”, 8) = 0
recv(4,