Anyone Decipher router logs

[walkerx 10]

Hi,

 

Is there anyone who can decipher router logs and determine if it is the router causing the connection drop or something else.

 

i've emailed dlink as well but so far no go and this is the 3rd router that is experiencing same issues where it will stay connected for a period of time and then disconnect.

 

Oct  7 23:38:37 dlink825 user.alert kernel: NetUSB:  v6 tcp conn start : port 20006 
Oct  7 23:38:37 dlink825 user.alert kernel: NetUSB:  v6 udp knnon start: port 9303 
Oct  7 23:38:37 dlink825 user.alert kernel: NetUSB: tcpConnector() started...
Oct  7 23:38:37 dlink825 user.alert kernel: NetUSB: Bind to br0
Oct  7 23:38:37 dlink825 user.alert kernel: NetUSB:  use dev Name br0 
Oct  7 23:38:37 dlink825 user.alert kernel: NetUSB:  UDP_BROAD 9303 
Oct  7 23:38:37 dlink825 user.alert kernel: NetUSB:  sleep to wait br0 end.
Oct  7 23:38:37 dlink825 user.alert kernel: NetUSB:  sleep to wait br0 to get IP
Oct  7 23:38:37 dlink825 user.alert kernel: NetUSB: AUTH SIG 
Oct  7 23:38:37 dlink825 user.alert kernel: NetUSB:  PAGE_SIZE 4096 
Oct  7 23:38:37 dlink825 user.alert kernel: NetUSB: SoftwareBus start 24 : 06 
Oct  7 23:38:37 dlink825 user.alert kernel: NetUSB: NetUSB 0.9243, 2009
Oct  7 23:38:36 dlink825 daemon.info dnsmasq[5628]: read /etc/hosts - 1 addresses
Oct  7 23:38:36 dlink825 daemon.info dnsmasq[5628]: using nameserver xx.xxx.xx.xxx#53
Oct  7 23:38:36 dlink825 daemon.info dnsmasq[5628]: using nameserver xx.xxx.xx.xxx#53
Oct  7 23:38:36 dlink825 daemon.info dnsmasq[5628]: reading /etc/resolv.conf
Oct  7 23:38:36 dlink825 daemon.warn dnsmasq[5628]: running as root
Oct  7 23:38:36 dlink825 daemon.info dnsmasq[5628]: compile time options: IPv6 GNU-getopt no-ISC-leasefile no-DBus no-I18N no-TFTP
Oct  7 23:38:36 dlink825 daemon.info dnsmasq[5628]: started, version 2.41 cachesize 150
Oct  7 23:38:36 dlink825 user.alert kernel: ag7100_do_ioctl: val =0x10
Oct  7 23:38:36 dlink825 user.alert kernel: ag7100_do_ioctl: io_speed == parse->svalue
Oct  7 23:38:35 dlink825 user.alert kernel: NetUSB: Softwarebus end
Oct  7 23:38:35 dlink825 user.alert kernel: NetUSB:  tcpconnecter accept error : -512
Oct  7 23:38:35 dlink825 user.alert kernel: NetUSB: prepare to kill tcpKthread
Oct  7 23:38:34 dlink825 user.alert kernel: NetUSB:  v6 tcp ser wait close 
Oct  7 23:38:34 dlink825 user.alert kernel: NetUSB:  v6 tcp ser end -512 
Oct  7 23:38:34 dlink825 user.alert kernel: NetUSB:  accept fail -512 
Oct  7 23:38:34 dlink825 user.alert kernel: NetUSB:  v6 udp annou wait to close 
Oct  7 23:38:34 dlink825 user.alert kernel: NetUSB:  v6 udp annou end 173 
Oct  7 23:38:34 dlink825 user.alert kernel: NetUSB: cleanup_usbArbitrator end
Oct  7 23:38:34 dlink825 user.alert kernel: NetUSB: cleanup_usbGeneralDriver end
Oct  7 23:38:29 dlink825 user.alert kernel: NetUSB: SoftwareBus Cleaning Up....
Oct  7 23:38:29 dlink825 daemon.info dnsmasq[24117]: exiting on receipt of SIGTERM
Oct  7 23:38:28 dlink825 daemon.info dnsmasq[24117]: using nameserver xx.xxx.xx.xxx#53
Oct  7 23:38:28 dlink825 daemon.info dnsmasq[24117]: using nameserver xx.xxx.xx.xxx#53
Oct  7 23:38:28 dlink825 daemon.info dnsmasq[24117]: reading /etc/resolv.conf
Oct  7 23:38:28 dlink825 daemon.notice pppd[5544]: pppd sent restart signal to rc 
Oct  7 23:38:28 dlink825 daemon.notice pppd[5544]: pppd check for rc to be idle ? 
Oct  7 23:38:28 dlink825 daemon.notice pppd[5544]: secondary DNS address xx.xxx.xx.xxx
Oct  7 23:38:28 dlink825 daemon.notice pppd[5544]: primary   DNS address xx.xxx.xx.xxx
Oct  7 23:38:28 dlink825 daemon.notice pppd[5544]: ipcp_up: remote PPP IP address xx.xxx.xx.xxx
Oct  7 23:38:28 dlink825 daemon.notice pppd[5544]: ipcp_up: local PPP IP address xx.xxx.xx.xxx
Oct  7 23:38:28 dlink825 daemon.notice pppd[5544]: ipcp_up: Open /var/tmp/pptp_server_ip.txt (l2tp_server_ip.txt) fail or Using PPPoE
Oct  7 23:38:28 dlink825 daemon.debug pppd[5544]: peerdns2 : xx.xxx.xx.xxx
Oct  7 23:38:28 dlink825 daemon.debug pppd[5544]: peerdns1 : xx.xxx.xx.xxx
Oct  7 23:38:28 dlink825 daemon.debug pppd[5544]: ppp create_resolv in ipcp
Oct  7 23:38:28 dlink825 daemon.debug pppd[5544]: rcvd [iPCP ConfAck id=0x2 <addr xx.xxx.xx.xxx> <ms-dns1 xx.xxx.xx.xxx> <ms-dns3 xx.xxx.xx.xxx>]
Oct  7 23:38:28 dlink825 daemon.debug pppd[5544]: sent [iPCP ConfReq id=0x2 <addr xx.xxx.xx.xxx> <ms-dns1 xx.xxx.xx.xxx> <ms-dns3 xx.xxx.xx.xxx>]
Oct  7 23:38:28 dlink825 daemon.debug pppd[5544]: rcvd [iPCP ConfNak id=0x1 <addr xx.xxx.xx.xxx> <ms-dns1 xx.xxx.xx.xxx> <ms-dns3 xx.xxx.xx.xxx>]
Oct  7 23:38:28 dlink825 daemon.debug pppd[5544]: sent [iPCP ConfAck id=0x1 <addr xx.xxx.xx.xxx>]
Oct  7 23:38:28 dlink825 daemon.debug pppd[5544]: rcvd [iPCP ConfReq id=0x1 <addr xx.xxx.xx.xxx>]
Oct  7 23:38:28 dlink825 daemon.debug pppd[5544]: sent [iPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0>]
Oct  7 23:38:28 dlink825 daemon.notice pppd[5544]: peer from calling number xx:xx:xx:xx:xx:xx authorized
Oct  7 23:38:28 dlink825 daemon.debug pppd[5544]: rcvd [CHAP Success id=0x1 "S=success"]
Oct  7 23:38:28 dlink825 daemon.debug pppd[5544]: rcvd [LCP EchoRep id=0x0 magic=0xmagcode]
Oct  7 23:38:28 dlink825 daemon.debug pppd[5544]: sent [CHAP Response id=0x1 <response>,name = "mylogondetails"]
Oct  7 23:38:28 dlink825 daemon.debug pppd[5544]: rcvd [CHAP Challenge id=0x1 <challenge>, name = "ISP Info"]
Oct  7 23:38:28 dlink825 daemon.debug pppd[5544]: sent [LCP EchoReq id=0x0 magic=0xmagcode]
Oct  7 23:38:28 dlink825 daemon.debug pppd[5544]: rcvd [LCP ConfAck id=0x1 <mru 1492> <magic 0xmagcode>]
Oct  7 23:38:28 dlink825 daemon.debug pppd[5544]: sent [LCP ConfAck id=0x1 <auth chap MS-v2> <magic 0xmagcode>]
Oct  7 23:38:28 dlink825 daemon.debug pppd[5544]: rcvd [LCP ConfReq id=0x1 <auth chap MS-v2> <magic 0xmagcode>]
Oct  7 23:38:28 dlink825 daemon.debug pppd[5544]: sent [LCP ConfReq id=0x1 <mru 1492> <magic 0xmagcode>]
Oct  7 23:38:28 dlink825 daemon.notice pppd[5544]: Connect: ppp0 <--> eth1
Oct  7 23:38:28 dlink825 daemon.info pppd[5544]: Using interface ppp0
Oct  7 23:38:28 dlink825 daemon.debug pppd[5544]: using channel 8
Oct  7 23:38:28 dlink825 daemon.info pppd[5544]: PPP session is 16143
Oct  7 23:38:28 dlink825 daemon.debug pppd[5544]: PADS: Service-Name: ''
Oct  7 23:38:28 dlink825 daemon.err pppoe-relay[24162]: PADS packet from xx:xx:xx:xx:xx:xx on interface eth1 does not have Relay-Session-Id tag
Oct  7 23:38:28 dlink825 daemon.err pppoe-relay[24162]: PADO packet from xx:xx:xx:xx:xx:xx on interface eth1 does not have Relay-Session-Id tag
Oct  7 23:38:28 dlink825 daemon.info pppd[5544]: Sent PADT
Oct  7 23:38:28 dlink825 daemon.info pppd[5544]: rp_pppoe send PADT to terminate the session ID that sent last time
Oct  7 23:38:28 dlink825 daemon.notice pppd[5544]: pppd 2.4.3 started by root, uid 0
Oct  7 23:38:28 dlink825 daemon.info pppd[5541]: RP-PPPoE plugin inform wantimer to reset auth, discovery variable
Oct  7 23:38:28 dlink825 daemon.info pppd[5541]: RP-PPPoE plugin version 3.3 compiled against pppd 2.4.3
Oct  7 23:38:28 dlink825 daemon.info pppd[5541]: Plugin /lib/pppd/2.4.3/rp-pppoe.so loaded.
Oct  7 23:38:22 dlink825 daemon.err pppd[24025]: Send SIGPIPE (ppp terminated) to wantimer
Oct  7 23:38:21 dlink825 daemon.info pppd[24025]: Die Exit.
Oct  7 23:38:21 dlink825 daemon.notice pppd[24025]: get_input: Modem hangup
Oct  7 23:38:21 dlink825 daemon.info pppd[24025]: Sent PADT
Oct  7 23:38:21 dlink825 daemon.warn pppd[24025]: PPPOEDisconnectDevice 
Oct  7 23:38:21 dlink825 daemon.notice pppd[24025]: ppp auth: Connection terminated.
Oct  7 23:38:18 dlink825 daemon.debug pppd[24025]: sent [LCP TermReq id=0x3 "Peer not responding"]
Oct  7 23:38:15 dlink825 daemon.debug pppd[24025]: sent [LCP TermReq id=0x2 "Peer not responding"]
Oct  7 23:38:15 dlink825 daemon.info pppd[24025]: Sent xyz bytes, received xyz bytes.
Oct  7 23:38:15 dlink825 daemon.info pppd[24025]: Connect time 1500.6 minutes.
Oct  7 23:38:15 dlink825 daemon.notice pppd[24025]: Serial link appears to be disconnected.
Oct  7 23:38:15 dlink825 daemon.info pppd[24025]: No response to 4 echo-requests

 

I have stopped the router displaying the logs on screen when access the web interface, but it seems it still logs everything.

 

Would be grateful for any feedback so I can get resolved - i do have something else to test but that won't be until next week at least

 

regards

walkerx

[fnkysknky 10]

The PPP session is getting torn down due to no response to 4 LCP echo requests sent by your router in a row. pppd has an option to use LCP echo requests and echo replies as a link monitoring/keep alive system which your D-Link is using. I think it's more likely that there's a transient problem on the link somewhere that is stopping you being able to pass traffic to the ISP or them being able to pass traffic to you which accounts for the echo requests not getting responded to. Can your ISP run a traffic capture on their kit for you to see if they're getting the LCP echo requests in the first place? It's probably not your router but you never know.

[fnkysknky 10]

Also if you have a hub or a switch that can port mirror then you can stick it between your router and your modem and get a capture of the LCP traffic there to ensure your router is definitely sending the echo requests. If it is and you're not getting any replies you can send that as evidence to your ISP and ask them to investigate.

[walkerx 10]

this is the 3rd router i've had on the line - different brand to others (tplink and netgear) and all after a period of time drop the PPPoE sesssion they even do it if use dynamic connection as well.

 

I know it's not a compatibility issue otherwise it would be happening on a more regular basis, nor is it down to the routers not being able to handle the download speeds as if it was then they shouldn't be sold as cable routers and would be surprised if none of them couldn't handle 50mbps connections.

 

I've also had BT out who have said it's not a line fault as if it was the modems wouldn't stay synced as is what is currently happening and I've sent logs to my ISP who have said there is nothing wrong from their side and advise to reset the router on a regular basis at least once a week as they believe it is the routers possibly not being able to handle high speed internet connections (but most disconnections are when no traffic on line) or failing due to the logging (which you can't turn off and why I'm now waiting for D-Link to respond to my case query).

 

Hopefully next week I maybe able to perform some other tests and if the same issues occur then it has to be something on the ISP's side or equipment (their modem) causing this.

[fnkysknky 10]

As above, have you got a hub handy or a switch that can do port mirroring? If you get a capture from in between your router and the modem and you can see the LCP echo requests going out from your router and you don't see an echo reply coming back from the ISP (at the time the connection stops functioning) then it means one of three things:

 

1. Your echo request isn't getting to the ISP.

2. The ISP's kit is responding to the echo request with an echo reply but it's not getting back as far as the Ethernet port on the modem.

3. The echo request got to the ISP's kit but it didn't respond to it (should never happen, if an echo request is received in an open LCP session the receiving device must respond with an echo reply according to the RFC).

 

If you do see the echo reply and your router still drops the connection then it looks like it's the router however I'd be very surprised if that was the case. By doing the above and sending them the evidence then they can't blame your router as you're results will be from a hop prior to it. At that point they should verify their network is behaving, if it is they should raise it with Thales along with the evidence that packets are going walkies (I'm assuming you're on Digital Region from other posts of yours).

 

If you need a cheap device that can do the port mirroring and/or capturing you coud do worse than get a MikroTik RB750 (http://linitx.com/product/13131) which is essentially a very versatile Linux router with a decent switch chip attached to it (it has a PPPoE client). No wireless on that model though.

Edited October 8, 2011 by fnkysknky

[walkerx 10]

Hi,

 

I don't think my netgear switches do any form of port monitoring so can't use that and my old adsl modem/routers would be no good for monitoring either.

 

I'll think I'll order that router and see what I can find out

[AlexAtkin 10]

There is one thing I'm not sure you have tried. Connect the PC directly to the Cellpipe and use your OS to establish the PPP connection.

 

Being a PC they would have a pretty hard time arguing it died due to logging or being unable to handle a high speed connection.

 

Of course the disadvantage is you are going to need to leave the PC on until the problem occurs. Still, if it finally proves the problem is on their network it would be worth it.

 

WARNING: DO NOT FORGET TO MAKE SURE THE FIREWALL IS ENABLED FOR YOUR CONNECTION WHEN USING IT DIRECT ON THE PC!!

Edited October 8, 2011 by AlexAtkin

[walkerx 10]

There is one thing I'm not sure you have tried. Connect the PC directly to the Cellpipe and use your OS to establish the PPP connection.

 

Being a PC they would have a pretty hard time arguing it died due to logging or being unable to handle a high speed connection.

 

Of course the disadvantage is you are going to need to leave the PC on until the problem occurs. Still, if it finally proves the problem is on their network it would be worth it.

 

WARNING: DO NOT FORGET TO MAKE SURE THE FIREWALL IS ENABLED FOR YOUR CONNECTION WHEN USING IT DIRECT ON THE PC!!

 

that was one of my next tests to setup a lowspec pc running smoothwall - i've used it before so i know what it's like and as you say if that drops the connection in the same manner then to me it's something on the network.

 

i've ordered that router fnkysknky linked to, just to use for further testing, as my tplink is configured as an AP and I could probably do the same for the dlink so no issues there for wireless.

[walkerx 10]

well got the router but not sure how to configure this one to work properly - managed to get it to do pppoe but then no access to internet from it even though it said it was connected - did notice the minute it got connected to the net it reported an attempt by someone to access the administration settings use winbox - luckily i had changed the password.

 

ideally need to set it so my router still does all the authenication and that it just montiors the two ports and logs everything - not sussed out how to do this yet as the options on these routers are totally different to standard routers

[bkcin 10]

well got the router but not sure how to configure this one to work properly - managed to get it to do pppoe but then no access to internet from it even though it said it was connected - did notice the minute it got connected to the net it reported an attempt by someone to access the administration settings use winbox - luckily i had changed the password.

 

ideally need to set it so my router still does all the authenication and that it just montiors the two ports and logs everything - not sussed out how to do this yet as the options on these routers are totally different to standard routers

 

http://wiki.mikrotik.com/wiki/Main_Page

 

Will be your friend for that.

[walkerx 10]

yeh, been trying to read through that already - but i don't think it's very user friendly

[AlexAtkin 10]

That's the thing though, if you used a PC you could already monitor everything. There wasn't really any reason to buy another router.