1. This site uses cookies. By continuing to use this site, you are agreeing to our use of cookies. Learn More.

Received LCP Termination-Request -- Does *NOT* mean ISP disconnected!

Discussion in 'Tomato Firmware' started by Planiwa, Feb 14, 2009.

  1. Planiwa

    Planiwa LI Guru Member

    Aztech DSL605EU in Bridge mode connected to Tomato 1.22 on WRT54GL.

    At 23:30 I intentionally disconnected the phone cable for about 10 seconds.

    Modem log:

    Code:
    Feb 13 22:58:25 manager_get_defaults - !node 
    [B]Feb 13 23:30:53 DSL Carrier is down 
    Feb 13 23:31:23 DSL Carrier is up 
    [/B]Feb 13 23:31:23 auto_vcc_default oamPing(0.35)result(2) 
    Feb 13 23:31:23 auto_vcc_default oamPing(1.33)result(2) 
    Feb 13 23:31:23 auto_vcc_default oamPing(0.50)result(2) 
    Feb 13 23:31:24 auto_vcc_default oamPing(0.32)result(2) 
    Feb 13 23:31:24 auto_vcc_default oamPing(0.38)result(2) 
    Feb 13 23:31:24 auto_vcc_default oamPing(0.96)result(2) 
    Feb 13 23:31:24 auto_vcc_default oamPing(0.100)result(2) 
    Feb 13 23:31:24 auto_vcc_default oamPing(8.48)result(2) 
    Feb 13 23:31:24 auto_vcc_search oamPing(1.32)result(2) 
    Feb 13 23:31:24 auto_vcc_search oamPing(8.35)result(2) 
    Feb 13 23:31:24 auto_vcc_search oamPing(0.43)result(2) 
    Feb 13 23:31:24 auto_vcc_search oamPing(0.51)result(2) 
    Feb 13 23:31:24 auto_vcc_search oamPing(0.59)result(2) 
    Feb 13 23:31:24 auto_vcc_search oamPing(8.43)result(2) 
    Feb 13 23:31:24 auto_vcc_search oamPing(8.51)result(2) 
    Feb 13 23:31:24 auto_vcc_search oamPing(8.32)result(2) 
    Feb 14 00:54:28 manager_get_defaults - !node 
    
    Tomato log:

    Code:
    [B]Feb 13 23:31:44 ROUTER daemon.info pppoe[1064]: Received LCP Termination-Request[/B]
    Feb 13 23:31:44 ROUTER daemon.info pppoe[1064]: Sending LCP Termination-Ack
    Feb 13 23:31:44 ROUTER daemon.info pppoe[1064]: Received LCP Termination-Request
    Feb 13 23:31:44 ROUTER daemon.info pppoe[1064]: Sending LCP Termination-Ack
    Feb 13 23:31:47 ROUTER daemon.info pppoe[1064]: Connection terminated.
    Feb 13 23:31:47 ROUTER daemon.notice pppoe[1064]: Disconnected.
    Feb 13 23:31:47 ROUTER daemon.notice pppoe[1064]: Connect time 136.7 minutes.
    Feb 13 23:31:47 ROUTER daemon.notice pppoe[1064]: Sent 14055274 bytes, received 24121237 bytes.
    Feb 13 23:31:47 ROUTER daemon.info pppoe[1064]: Sending PADT.
    Feb 13 23:31:57 ROUTER daemon.info pppoe[1064]: Sending PADI.
    Feb 13 23:31:57 ROUTER daemon.info pppoe[1064]: Received PADT for 0x1211, expecting 0x0000
    Feb 13 23:31:57 ROUTER daemon.info pppoe[1064]: Received PADO.
    Feb 13 23:31:57 ROUTER daemon.info pppoe[1064]: Sending PADR.
    Feb 13 23:31:57 ROUTER daemon.info pppoe[1064]: Received PADS. SID: 0x061B
    Feb 13 23:31:57 ROUTER daemon.info pppoe[1064]: Sending LCP Configuration-Request
    Feb 13 23:31:57 ROUTER daemon.info pppoe[1064]: Received LCP Configuration-Request
    Feb 13 23:31:57 ROUTER daemon.info pppoe[1064]: Sending LCP Configuration-Ack
    Feb 13 23:31:57 ROUTER daemon.info pppoe[1064]: Received LCP Configuration-Ack
    Feb 13 23:31:57 ROUTER daemon.info pppoe[1064]: Sending PAP Authenticate-Request.
    Feb 13 23:32:00 ROUTER daemon.info pppoe[1064]: Sending PAP Authenticate-Request.
    Feb 13 23:32:00 ROUTER daemon.info pppoe[1064]: PAP authentication succeeded.
    Feb 13 23:32:00 ROUTER daemon.info pppoe[1064]: Sending IPCP Configuration-Request
    Feb 13 23:32:00 ROUTER daemon.info pppoe[1064]: Received IPCP Configuration-Request
    Feb 13 23:32:00 ROUTER daemon.info pppoe[1064]: Sending IPCP Configuration-Ack
    Feb 13 23:32:00 ROUTER daemon.info pppoe[1064]: Received IPCP Configuration-Nak
    Feb 13 23:32:00 ROUTER daemon.info pppoe[1064]: Sending IPCP Configuration-Request
    Feb 13 23:32:00 ROUTER daemon.info pppoe[1064]: Received IPCP Configuration-Ack
    Feb 13 23:32:00 ROUTER daemon.notice pppoe[1064]: Connected.
    
    Clearly in this case it was a local wiring problem.

    Why is it that the router is oblivious to the modem's knowledge that the DSL carrier has gone down?
    Why, if I pull the dsl cable, will the router keep on trying to establish a PPPoW connection over a nonexistent DSL link?
    Why does the router's DNSMASQ keep polluting the message log when there is no WAN?


    And yes, two important caveats:

    0. Not all "modems" are in bridge mode after factory reset.
    1. Never use Safari to try to configure "modems".
    2. It's possible for a modem to be in "bridge-router" mode. In this mode, all the connection data it displays is fictitious. Apparently the modem's PPPOE tries to run in parallel with the router's. (Who knows, mebbe there really are two parallel links).



    This can be a real hazard when accessing the modem via the router.
    You need to make sure it is in total bridge mode. (Here is where some browsers may not be compatible with some modems.)

    Perhaps others can elaborate on all this?

    Thanks.
     
  2. mstombs

    mstombs Network Guru Member

    You need to review the OSI communications model.

    The Router talks PPPoE, the Ethernet link does not get broken, just the higher level PPP one.

    Your 'modem' which is itself a Linux router (with buggy Aztech code -"manager_get_defaults - !node") handles the conversion to carrying the PPPoE over ATM, and the hardware ATM and DSP drivers. In full bridge mode it tries to be as transparent as possible.
     
  3. occamsrazor

    occamsrazor Network Guru Member

  4. Planiwa

    Planiwa LI Guru Member

    Which particular statement of mine might have been better informed by OSI model understanding, how?

    Surely you are not suggesting that the router, connected via ethernet to the modem, "cannot possibly know that the modem knows that there is no DSL" because the OSI model prevents this?

    I expect that this is more likely the result of poor design. For example, while the information about DSL status is available on the modem's web pages, it (and the system log) is not (readily) available through the telnet interface. Much less available to the router, perhaps.

    Surely you mean the Ethernet link between the router and the modem. That link is not being discussed at all. It is the link between the modem and the ISP that is under discussion. *Any* link -- cabling, DSL, ATM, Ether, PPPoE. It would have been pretty silly of me to expect the router to *know* that I have yanked the phone cable (because the modem *knows* that, if I had also yanked the ether connection between modem and router. :)

    Clearly there is something I am not following here.


    Keeping the router unaware that there is nothing on the far side of the modem sounds more like obscurity than transparency. :)



    Meanwhile ...

    Yes. It was precisely my stupid repeating of what others had been repeating -- that the message (c.f. Subject) means ISP disconnected -- that prompted me to post this correction . I think it is a pretty serious mis-assumption to "blame" the ISP, when the cause could very well be between the modem and the ISP.

    In this case, since there was nothing upstream of the modem, clearly any LCP Termination request could only have been made by the modem.

    Perhaps (mstombs is suggesting that) the modem should not have issued that request, and it was buggy code. Regardless, it was clearly a phone cable problem, not an ISP problem.


    I have to manage these setups remotely. I would like the router to be more aware of what is happening on the modem side. (Such as whether DSL is up.) And I would like it to be more intelligent in its reconnection efforts.

    In any case, to know that the "LCP Termination Request" could have been issued by the local modem is both significant, and, has not been expressed here, as far as I am aware.

    * * *

    I just did another experiment -- disconnecting the phoneline:

    Modem log:

    Code:
    Feb 14 11:52:03 DSL Carrier is down 
    Feb 14 11:53:43 DSL Carrier is up 
    Feb 14 11:53:43 auto_vcc_default oamPing(0.35)result(2) 
    Feb 14 11:53:43 auto_vcc_default oamPing(1.33)result(2) 
    Feb 14 11:53:43 auto_vcc_default oamPing(0.50)result(2) 
    Feb 14 11:53:43 auto_vcc_default oamPing(0.32)result(2) 
    Feb 14 11:53:43 auto_vcc_default oamPing(0.38)result(2) 
    Feb 14 11:53:43 auto_vcc_default oamPing(0.96)result(2) 
    Feb 14 11:53:43 auto_vcc_default oamPing(0.100)result(2) 
    Feb 14 11:53:43 auto_vcc_default oamPing(8.48)result(2) 
    Feb 14 11:53:43 auto_vcc_search oamPing(1.32)result(2) 
    Feb 14 11:53:43 auto_vcc_search oamPing(8.35)result(2) 
    Feb 14 11:53:43 auto_vcc_search oamPing(0.43)result(2) 
    Feb 14 11:53:44 auto_vcc_search oamPing(0.51)result(2) 
    Feb 14 11:53:44 auto_vcc_search oamPing(0.59)result(2) 
    Feb 14 11:53:44 auto_vcc_search oamPing(8.43)result(2) 
    Feb 14 11:53:44 auto_vcc_search oamPing(8.51)result(2) 
    Feb 14 11:53:44 auto_vcc_search oamPing(8.32)result(2) 
    
    Router log:

    Code:
    [B]Feb 14 11:55:08 ROUTER daemon.warn pppoe[1064]: LCP appears to be disconnected (pending: 5).[/B]
    Feb 14 11:55:08 ROUTER daemon.info pppoe[1064]: Sending LCP Termination-Request
    Feb 14 11:55:11 ROUTER daemon.info pppoe[1064]: Sending LCP Termination-Request
    Feb 14 11:55:14 ROUTER daemon.info pppoe[1064]: Connection terminated.
    Feb 14 11:55:14 ROUTER daemon.notice pppoe[1064]: Disconnected.
    Feb 14 11:55:14 ROUTER daemon.notice pppoe[1064]: Connect time 743.1 minutes.
    Feb 14 11:55:14 ROUTER daemon.notice pppoe[1064]: Sent 77048425 bytes, received 128514404 bytes.
    Feb 14 11:55:14 ROUTER daemon.info pppoe[1064]: Sending PADT.
    Feb 14 11:55:24 ROUTER daemon.info pppoe[1064]: Sending PADI.
    Feb 14 11:55:33 ROUTER daemon.info pppoe[1064]: Resending...
    Feb 14 11:55:34 ROUTER user.info redial[1063]: WAN down. Reconnecting...
    Feb 14 11:55:34 ROUTER daemon.info dnsmasq[8264]: exiting on receipt of SIGTERM
    Feb 14 11:55:36 ROUTER daemon.info dnsmasq[13591]: started, version 2.46 cachesize 150
    Feb 14 11:55:36 ROUTER daemon.info dnsmasq[13591]: compile time options: no-IPv6 GNU-getopt no-RTC no-DBus no-I18N no-TFTP
    Feb 14 11:55:36 ROUTER daemon.info dnsmasq[13591]: DHCP, IP range 192.168.2.100 -- 192.168.2.149, lease time 1d
    Feb 14 11:55:36 ROUTER daemon.warn dnsmasq[13591]: no servers found in /etc/resolv.dnsmasq, will retry
    Feb 14 11:55:36 ROUTER daemon.info dnsmasq[13591]: read /etc/hosts - 0 addresses
    Feb 14 11:55:36 ROUTER daemon.info dnsmasq[13591]: read /etc/hosts.dnsmasq - 4 addresses
    Feb 14 11:55:36 ROUTER daemon.info pppoe[13593]: Starting
    Feb 14 11:55:36 ROUTER daemon.info pppoe[13593]: Sending PADI.
    Feb 14 11:55:36 ROUTER user.info redial[13594]: Started. Time: 60
    Feb 14 11:55:46 ROUTER daemon.info pppoe[13593]: Resending...
    Feb 14 11:55:56 ROUTER daemon.info pppoe[13593]: Resending...
    Feb 14 11:55:56 ROUTER daemon.info pppoe[13593]: Received PADO.
    Feb 14 11:55:56 ROUTER daemon.info pppoe[13593]: Sending PADR.
    Feb 14 11:55:56 ROUTER daemon.info pppoe[13593]: Received PADS. SID: 0xC308
    Feb 14 11:55:56 ROUTER daemon.info pppoe[13593]: Sending LCP Configuration-Request
    Feb 14 11:55:56 ROUTER daemon.info pppoe[13593]: Received LCP Configuration-Request
    Feb 14 11:55:56 ROUTER daemon.info pppoe[13593]: Sending LCP Configuration-Ack
    Feb 14 11:55:56 ROUTER daemon.info pppoe[13593]: Received LCP Configuration-Ack
    Feb 14 11:55:56 ROUTER daemon.info pppoe[13593]: Sending PAP Authenticate-Request.
    Feb 14 11:55:57 ROUTER daemon.info pppoe[13593]: Received LCP Configuration-Request
    Feb 14 11:55:57 ROUTER daemon.info pppoe[13593]: Sending LCP Configuration-Request
    Feb 14 11:55:57 ROUTER daemon.info pppoe[13593]: Sending LCP Configuration-Reject
    Feb 14 11:55:57 ROUTER daemon.info pppoe[13593]: Received LCP Configuration-Ack
    Feb 14 11:55:57 ROUTER daemon.info pppoe[13593]: Received LCP Configuration-Request
    Feb 14 11:55:57 ROUTER daemon.info pppoe[13593]: Sending LCP Configuration-Ack
    Feb 14 11:55:57 ROUTER daemon.info pppoe[13593]: Sending PAP Authenticate-Request.
    Feb 14 11:55:57 ROUTER daemon.info pppoe[13593]: PAP authentication succeeded.
    Feb 14 11:55:57 ROUTER daemon.info pppoe[13593]: Sending IPCP Configuration-Request
    Feb 14 11:55:57 ROUTER daemon.info pppoe[13593]: Received IPCP Configuration-Request
    Feb 14 11:55:57 ROUTER daemon.info pppoe[13593]: Sending IPCP Configuration-Ack
    Feb 14 11:55:57 ROUTER daemon.info pppoe[13593]: Received IPCP Configuration-Nak
    Feb 14 11:55:57 ROUTER daemon.info pppoe[13593]: Sending IPCP Configuration-Request
    Feb 14 11:55:57 ROUTER daemon.info pppoe[13593]: Received IPCP Configuration-Ack
    Feb 14 11:55:57 ROUTER daemon.notice pppoe[13593]: Connected.
    
    Note the different message from the router this time. (LCP appears to be disconnected (pending: 5)).

    BTW, I have a way to tell if DSL is up, via telnet, for this modem (Aztech DSL605EU) if anyone is interested.
     
  5. humba

    humba Network Guru Member

    What is the point of your original message? Are you claiming the router does something wrong? If so, can you point out where in the PPPoE and associated protocols there's the message "somebody unplugged a cable"? Not even the modem knows that for sure.
    Or, was it a question (I didn't see a question there but perhaps you understood it as one)
    ?

    mstombs is correct to point out the OSI layers.. your unplugging the phone line is a layer 1 disconnect. PPPoE works on layer 3.. and it is unaware of the state of the lower layers.. it just knows the remote end doesn't work. Suppose you unplug the Ethernet cable to your computer.. then try visiting a website. Your webbrowser won't tell you it cannot reach the site because you unplugged the cable.. it just tells you it cannot reach the site. It's the same for the router.. in your first case it got a link control protocol message telling it to tear down the link. If you check out the LCP protocol there's no message that says "DSL link down" or "lower layer down".

    In the end, unless your router is your modem, it really has no chance to report that the dsl link is down. If you need that info, you could probably write a script on your router that telnets into the modem and pulls that info and adds it to the event log but since it's different for every model (starting with the modem's ip address) there's little to no chance that this ever be a standard tomato feature.

    And as far as dnsmasq goes.. tomato is probably programmed this way to restart it under certain conditions and you managed to trigger that condition with your second disconnect. For the whys and hows perhaps the author could tell you.
     
  6. Planiwa

    Planiwa LI Guru Member

    The Subject title is pretty clear about the main point. Everything else is about trying to achieve more clarity in context.

    The modem knows that there is no DSL.

    Is there a "good" reason that this knowledge should be deliberately kept from the router? If so, why is that "reason" not used to keep it from a human user?

    We could eliminate the DSL light, for starters. :)

    If there is no *good* *reason* then perhaps there is a better way? I look for better ways.

    If the modem can tell the router to tear down the link, why can't it tell it "there's no onward link"? Then the router needs one query, instead of an endless repetition of:

    Code:
    Feb 13 20:05:43 ROUTER user.info redial[29476]: WAN down. Reconnecting...                                  
    Feb 13 20:05:43 ROUTER daemon.info dnsmasq[29467]: exiting on receipt of SIGTERM                           
    Feb 13 20:05:43 ROUTER daemon.info dnsmasq[29541]: started, version 2.46 cachesize 150                     
    Feb 13 20:05:43 ROUTER daemon.info dnsmasq[29541]: compile time options: no-IPv6 GNU-getopt no-RTC no-DBus 
    Feb 13 20:05:43 ROUTER daemon.info dnsmasq[29541]: DHCP, IP range 192.168.2.100 -- 192.168.2.149, lease tim
    Feb 13 20:05:43 ROUTER daemon.warn dnsmasq[29541]: no servers found in /etc/resolv.dnsmasq, will retry     
    Feb 13 20:05:43 ROUTER daemon.info dnsmasq[29541]: read /etc/hosts - 0 addresses                           
    Feb 13 20:05:43 ROUTER daemon.info dnsmasq[29541]: read /etc/hosts.dnsmasq - 4 addresses                   
    Feb 13 20:05:50 ROUTER daemon.info pppoe[29549]: Starting                                                  
    Feb 13 20:05:50 ROUTER daemon.info pppoe[29549]: Sending PADI.                                             
    Feb 13 20:05:50 ROUTER user.info redial[29550]: Started. Time: 60                                          
    Feb 13 20:06:00 ROUTER daemon.info pppoe[29549]: Resending...                                              
    Feb 13 20:06:10 ROUTER daemon.info pppoe[29549]: Resending...                                              
    Feb 13 20:06:17 ROUTER daemon.info pppoe[29549]: Resending...                                              
    Feb 13 20:06:20 ROUTER daemon.info pppoe[29549]: Resending...                                              
    Feb 13 20:06:27 ROUTER daemon.info pppoe[29549]: Resending...                                              
    Feb 13 20:06:35 ROUTER daemon.info pppoe[29549]: Resending...                                              
    Feb 13 20:06:39 ROUTER daemon.info pppoe[29549]: Resending...                                              
    Feb 13 20:06:47 ROUTER daemon.info pppoe[29549]: Resending...                                              
    Feb 13 20:06:50 ROUTER daemon.info pppoe[29549]: Resending...                                              
    Feb 13 20:06:59 ROUTER daemon.info pppoe[29549]: Resending...                                              
    Feb 13 20:07:00 ROUTER user.info redial[29550]: WAN down. Reconnecting...                                  
    
    If the reason that the router can't find out what the modem knows about the line is because it was designed out of the protocols, that still leaves the possibility that the question is legitimate and the design suboptimal.

    But no one has yet stated that the router cannot possibly access lower level information. After all, it is well known that usually, implementers relax the strict layering scheme when building protocol software.


    That's not the case at all. This is exactly how it happens. Repeatedly. Always.

    I can see that some others have not not had disconnection problems and have not had the need to read the related log file, with this stuff ad-infinitum, pushing out any useful information that might have been in the log just before the incident.

    (I rather expect that this particular implementation was considered safe and easy, and the optimal approach when the expected number of connection attempts before success is close to 1.)
     
  7. mstombs

    mstombs Network Guru Member

    Your modem appears to do the bridging in its kernel - the link is set up by a br2684ctl utility - which checks the DSL status by looking for the string "SHOWTIME" in /proc/avalanche/avsar_modem_training - which you could also do by Telnet - but not remotely when the DSL link is down!

    Tomato doesn't need to know it is connected to a DSL router - it could be a cable router or Ethernet network out of the WAN port.

    If the modem didn't tell the router the ppp link was broken I guess the router would find out itself soon enough (LCP echo commands?).
     
  8. Planiwa

    Planiwa LI Guru Member

    That's very helpful, thanks. I had already figured that /proc/avalanche/avsar_modem_status has no Rates when there is no DSL, but avsar_modem_training is much more specific. Right now it contains:

    Code:
    SHOWTIME
    1
    failTrains=4
    
    I could start a long-running telnet session from the router that logs changes in this file. Probably worth logging to NVRAM in case the router is rebooted.


    If the modem could handle just DSL/PPPoE and the router just get the WAN-IP from the modem, that would simplify some things. But there are probably problems with that too, such as modems insisting to do DHCP, NAT, FW, QoS, ...


    The situation is that, yes, the router can figure that the link is gone ...

    Code:
    Feb 14 11:55:08 ROUTER daemon.warn pppoe[1064]: LCP appears to be disconnected (pending: 5)
    But it seems a real shame that it does not know that the link cannot possibly be restored before DSL is up. More than once it tried all night when the phone line was broken (ice or squirrels).

    I suppose I could instruct my long-running process to shut down WAN until DSL is back up. Sounds easy enough. :)

    I now have a Thomson-Alcatel STM516 modem. I'm hoping it will be (even) better than the Aztech, even though it doesn't run Unix. (May not be possible to run programs on it).
     
  9. humba

    humba Network Guru Member

    I've spent quite a bit of time reading through various RFCs now and the way I understand PPPoE, if it receives an LCP connection down message, it's supposed to release the connection and if it wants to set up another connection, it has to restart PPPoE all over again - and that starts with a PADI. Here's the link to the RFC.

    Look under other configurations:
    That's exactly what Tomato does.. it sends a PADI, receives no PADO, and restarts.

    I'm afraid the problem seems to be that the connection is always established from host to host.. there's no mechanism for the modem to tell the PPPoE initiator that the link is back up.. it's always up to the PPPoE initiator to try and establish a connection.
    If the same device that is responsible for the physical link also sets up the PPPoE link, then you can set up mechanisms outside the RFCs and only restart the PPPoE connection attempt once you know that the physical layer is up. But if you separate physical layer from PPPoE there just doesn't seem to be a standard mechanism to do that..

    Now as far as dnsmasq goes, there you might have a point as it seems rather weird to me that it is being restarted before the WAN link even comes back up. But Jon might be able to explain why he did it that way and why it makes sense to do it that way rather than the obvious way (restarting when WAN is up, or perhaps a restart isn't even necessary at all).

    P.S. I also read the PPP RFC and you'll see that there are events that seem applicable to our particular situation. So there is an event to tell that the lower layer is up or down. Unfortunately, as per the PPPoE RFC, when the PPPoE process receives a link down request, it must end the session and start a new one so it never gets those events so it cannot know when the physical layer is back up. If it were a simple PPP connection, then I suppose the router would still receive those events and wouldn't have to retry, but since PPPoE says tear down everything and restart with the PADI, the router simply has no way to get that information.

    I suggest fur forther protocol discussion you find the place where the developers of the pppoe daemon meet to talk - but be careful about RTMF. My own experience is that the more specialized the people you encounter, the more you need to do your homework before asking questions.
     
  10. mstombs

    mstombs Network Guru Member

    I have my suspicions as to what OS the Speedtouch runs - it does have Telnet and its own cli language.

    You could have a look at RouterTech firmware on your Aztech now you have a backup. Maybe later DSP drivers would be more robust and a few more options to run custom commands - but most 'features' are for use as a router not a bridge modem.

    Re dnsmasq - I'm pretty sure it does not now have to be restarted - older versions may have when the resolv dns servers were changed - the latest version can just monitor the file for change. Restarting may be a cure-all for cache problems etc!
     
  11. Odin-60

    Odin-60 LI Guru Member

    @ Planiwa:

    As to your first experiment, please take a look at the timestamps:
    Code:
    Feb 13 23:30:53 DSL Carrier is down 
    Feb 13 23:31:23 DSL Carrier is up 
    ...
    Feb 13 23:31:44 ROUTER daemon.info pppoe[1064]: Received LCP Termination-Request
    
    What has happened?

    The ISP's PPPoE server detected a loss of data (most likely, missing
    LCP echo replies). In this case the PPPoE session is to be closed,
    since the data stream is likely to be corrupted. The PPPoE server
    sent an LCP Termination-Request to your router, in order to try to
    close the PPPoE session properly. (Of course, this request would
    be lost, if the line was still down, but the server tries nevertheless.)
    In your case the line was, however, up again, so your router
    did receive and log this request, and would terminate the PPPoE
    session as expected.

    In the second experiment the line outage was a little bit longer:
    Code:
    Feb 14 11:52:03 DSL Carrier is down 
    Feb 14 11:53:43 DSL Carrier is up 
    
    Thus, the Termination-Request from the ISP did not reach the router.
    So in this case it was your router, which noticed a loss of data, tried
    (in vain) to send two Termination-Requests
    Code:
    Feb 14 11:55:08 ROUTER daemon.info pppoe[1064]: Sending LCP Termination-Request
    Feb 14 11:55:11 ROUTER daemon.info pppoe[1064]: Sending LCP Termination-Request
    
    and finally terminated the PPPoE session itself, after having waited
    a few seconds for any acknowledgement. Obviously, also the PPPOE
    server had already given up the connection; that's why it did not reply
    to these Termination-Requests any more, even though the line was up
    again.
     
  12. Planiwa

    Planiwa LI Guru Member

    This is so interesting. The major conclusion about the main topic then is this:

    The LCP Termination Request *did* come from the ISP side (not the bridge-modem), but it came in response to an "unrecoverable" local problem. (Which was detected by the ISP side, although when it was detected it was no longer a problem, which is why the request made it to the router at all. :) :)


    After writing a nice 2-cycle 48h monitoring script, I did some more experiments. Dropping phone line and ethernet. One thing I found is that the far side tends to regard all my disconnections as noise. My SNR margins started out as 15/25, and even after my experiments stopped, the DS margin kept dropping steadily ... over the last 24 hours steadily from 17 to 15: 14/15

    So, no more experiments until I find out what makes it rise. Maybe several GB of error-free transfer. :)

    (I would not be at all surprised if, after several hours of experiments, the far side were to decide that the line is too "noisy" to be usable at all. :)


    Odin's message also explains something. I monitor routers remotely, and get a tail -f of /var/log/messages

    So, I see this:

    Feb 16 17:36:08 ROUTER daemon.info pppoe[13056]: Received LCP Termination-Request
    Feb 16 17:36:08 ROUTER daemon.info pppoe[13056]: Sending LCP Termination-Ack
    Feb 16 17:36:08 ROUTER daemon.info pppoe[13056]: Received LCP Termination-Request
    Feb 16 17:36:08 ROUTER daemon.info pppoe[13056]: Sending LCP Termination-Ack
    Feb 16 17:36:10 ROUTER user.info redial[13057]: WAN down. Reconnecting...
    Feb 16 17:36:10 ROUTER daemon.info dnsmasq[13070]: exiting on receipt of SIGTERM
    Connection to xxxxxxx.sytes.net closed.

    I've always thought this is a little more than I should get. (How can I get the "WAN down" message over the WAN, with the WAN down? :)
     
  13. mstombs

    mstombs Network Guru Member

    Don't look at margins alone, they are related to connect speed. If you get regular disconnects the ISP may raise the snr margin target which means the connect speed is lower. With older firmwares on the Speedtouch you can tweak the reported margin to tweak speed. Latest DSL standards allow for continuous rate adjustment - but I'm not too sure many ISPs yet use.
     
  14. Odin-60

    Odin-60 LI Guru Member

    Where is the problem? First the router closed the connection, then it reported
    "WAN down".

    The message did not come in over the WAN; it was written by the router
    itself! Note also that "WAN down" means that the PPPoE connection is
    logically down, regardless of whether or not the lower communication
    layers are still usable.

    This is indeed possible. No, I'm not joking: In a similar situation I needed
    to call my ISP and ask to reset the DSLAM :cool:
     
  15. Planiwa

    Planiwa LI Guru Member

    Hm. Perhaps ...
    and also
    ... were not as self-explanatory as I had assumed?

    The system xxxxxxx.sytes.net is several hops away in the Internet. :)
    Anything its router says to me must go through the WAN.

    ...

    Quoting:
    (I would not be at all surprised if, after several hours of experiments, the far side were to decide that the line is too "noisy" to be usable at all. :)

    [Here, the ISP has no direct access to the DSLAM -- it is owned and controlled by the ((not quite) former) monopoly which both supplies the ISP and competes with it. (Of course it would never intentionally degrade the "independent" dependent ISP. Oh no, no, no.) The Independents are dreaming about colo and similar options, but for now they have no CO access.]

    ...

    I'm happy to report that (yesterday I took my Aztech modem to (the most troublesome) remote site and started using the Speedtouch locally, and) my SNR margins have crept up again:

    Code:
    xDSL linestate up 
    (downstream: 5056 kbit/s, upstream: 800 kbit/s;
    output Power Down: 7.5 dBm, Up: 12.5 dBm;
    line Attenuation Down: 1.0 dB, Up: 0.0 dB;
    snr Margin Down: 22.0 dB, Up: 18.0 dB)
    (There must be something I can do to improve that DS line attenuation, no? :biggrin:)

    ...

    Moreover, I am now able to telnet to the (Aztech) modem from the remote router to which it is attached. Yay!

    And just as soon as someone kindly compiles an uncrippled nc for my WRT54GL routers, I will be able to provide a web page for the LAN users with the network status, etc.
     

Share This Page