PPPoE - DTAG - Fritz 3370 Unknown error (USER_REQUEST)

Installing and Using OpenWrt Network and Wireless Configuration
1

Hi all

problem description
I am using OpenWRT now for few weeks as main router at home and I have an issue which comes up from time to time. My wan connection dies and Luci shows Error: Unknown error (USER_REQUEST) on that interface. I dug around a bit and this post https://forum.turris.cz/t/dtag-no-internet-on-reconnect-after-configuration-change/11609/2 and this one PPPoE "unknown error (USER_REQUEST)" seam to be similar but not identical.

most of the issues out there are related to not getting an IP at all and the need to have a VLAN 7 tag enabled on the dsl interface. Which I did. So in fact the connection is working most of the time but restarts suddenly and not periodically (might be config / kernel / driver related?)

More information will happily be provided and any hints are appreciated !

my setup
ISP: DTAG
Contract: VDSL50
Hardware: Fritzbox 3370

my configs
/etc/config/network:
(only wan related stuff)

type or paste code heconfig atm-bridge 'atm'
        option vpi '1'
        option vci '32'
        option encaps 'llc'
        option payload 'bridged'
        option nameprefix 'dsl'
        option unit 'root'

config dsl 'dsl'
        option annex 'b'
        option tone 'bv'
        option xfer_mode 'ptm'
        option line_mode 'vdsl'
        option ds_snr_offset '0'
        option firmware '/lib/firmware/vr9-B-dsl.bin'

config interface 'wan'                               
        option proto 'pppoe'                         
        option ipv6 'auto'                           
        option username 'xxx'
        option password 'xxx'                                
        option keepalive '2 2'                                    
        option ifname 'dsl0.7'                                    
        option host_uniq 'xxx'                               
                                                                  
config device 'wan_dsl0_dev'                                      
        option name 'dsl0'                                        
        option macaddr 'xxx'

config interface 'wan6'                                           
        option ifname '@wan'                                      
        option proto 'dhcpv6'                                     
        option reqaddress 'try'                                   
        option reqprefix 'auto'

logred from link down to all working again:

Sat May 30 17:39:22 2020 kern.warn kernel: [787105.479497] leave showtime
Sat May 30 17:39:22 2020 daemon.notice netifd: Network device 'dsl0' link is down
Sat May 30 17:39:22 2020 daemon.notice netifd: VLAN 'dsl0.7' link is down
Sat May 30 17:39:22 2020 daemon.notice netifd: Interface 'wan' has link connectivity loss
Sat May 30 17:39:22 2020 daemon.info pppd[14922]: Terminating on signal 15
Sat May 30 17:39:22 2020 daemon.info pppd[14922]: Connect time 844.9 minutes.
Sat May 30 17:39:22 2020 daemon.info pppd[14922]: Sent 1301141680 bytes, received 863341251 bytes.
Sat May 30 17:39:22 2020 daemon.err odhcp6c[15106]: Failed to send DHCPV6 message to ff02::1:2 (Permission denied)
Sat May 30 17:39:22 2020 daemon.notice netifd: Network device 'pppoe-wan' link is down
Sat May 30 17:39:22 2020 daemon.notice netifd: Network alias 'pppoe-wan' link is down
Sat May 30 17:39:22 2020 daemon.notice netifd: Interface 'wan6' has link connectivity loss
Sat May 30 17:39:22 2020 daemon.err odhcp6c[15097]: Failed to send RS (Permission denied)
Sat May 30 17:39:22 2020 daemon.notice netifd: Interface 'wan_6' has link connectivity loss
Sat May 30 17:39:22 2020 daemon.err odhcp6c[15106]: Failed to send DHCPV6 message to ff02::1:2 (Permission denied)
Sat May 30 17:39:22 2020 daemon.notice netifd: Interface 'wan_6' is now down
Sat May 30 17:39:22 2020 daemon.err odhcp6c[15097]: Failed to send DHCPV6 message to ff02::1:2 (Permission denied)
Sat May 30 17:39:22 2020 daemon.info dnsmasq[21914]: reading /tmp/resolv.conf.auto
Sat May 30 17:39:22 2020 daemon.notice netifd: Interface 'wan6' is now down
Sat May 30 17:39:22 2020 daemon.notice netifd: Interface 'wan6' is disabled
Sat May 30 17:39:22 2020 daemon.notice netifd: Interface 'wan6' is enabled
Sat May 30 17:39:27 2020 daemon.notice netifd: Interface 'wan' is now down
Sat May 30 17:39:27 2020 daemon.notice netifd: Interface 'wan6' is disabled
Sat May 30 17:39:27 2020 daemon.notice netifd: Interface 'wan' is disabled
Sat May 30 17:39:27 2020 kern.info kernel: [787110.557577] IPv6: ADDRCONF(NETDEV_UP): dsl0: link is not ready
Sat May 30 17:39:27 2020 kern.info kernel: [787110.583334] IPv6: ADDRCONF(NETDEV_UP): dsl0.7: link is not ready
Sat May 30 17:39:27 2020 daemon.notice netifd: Interface 'wan' is enabled
Sat May 30 17:41:20 2020 kern.warn kernel: [787223.648691] enter showtime
Sat May 30 17:41:20 2020 kern.info kernel: [787223.650360] IPv6: ADDRCONF(NETDEV_CHANGE): dsl0: link becomes ready
Sat May 30 17:41:20 2020 daemon.notice netifd: Network device 'dsl0' link is up
Sat May 30 17:41:20 2020 kern.info kernel: [787223.660069] IPv6: ADDRCONF(NETDEV_CHANGE): dsl0.7: link becomes ready
Sat May 30 17:41:20 2020 daemon.notice netifd: VLAN 'dsl0.7' link is up
Sat May 30 17:41:20 2020 daemon.notice netifd: Interface 'wan' has link connectivity
Sat May 30 17:41:20 2020 daemon.notice netifd: Interface 'wan' is setting up now
Sat May 30 17:41:20 2020 kern.warn kernel: [787223.673368] enter showtime
Sat May 30 17:41:20 2020 daemon.err insmod: module is already loaded - slhc
Sat May 30 17:41:20 2020 daemon.err insmod: module is already loaded - ppp_generic
Sat May 30 17:41:20 2020 daemon.err insmod: module is already loaded - pppox
Sat May 30 17:41:20 2020 daemon.err insmod: module is already loaded - pppoe
Sat May 30 17:41:20 2020 daemon.info pppd[9555]: Plugin rp-pppoe.so loaded.
Sat May 30 17:41:20 2020 daemon.info pppd[9555]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Sat May 30 17:41:20 2020 daemon.notice pppd[9555]: pppd 2.4.7 started by root, uid 0
Sat May 30 17:41:25 2020 daemon.info pppd[9555]: PPP session is 17391
Sat May 30 17:41:25 2020 daemon.warn pppd[9555]: Connected to x:x:x:x:x:x via interface dsl0.7
Sat May 30 17:41:25 2020 kern.info kernel: [787229.273196] pppoe-wan: renamed from ppp0
Sat May 30 17:41:25 2020 daemon.info pppd[9555]: Renamed interface ppp0 to pppoe-wan
Sat May 30 17:41:25 2020 daemon.info pppd[9555]: Using interface pppoe-wan
Sat May 30 17:41:25 2020 daemon.notice pppd[9555]: Connect: pppoe-wan <--> dsl0.7
Sat May 30 17:41:26 2020 daemon.info pppd[9555]: Remote message: SRU=11992#SRD=59961#
Sat May 30 17:41:26 2020 daemon.notice pppd[9555]: PAP authentication succeeded
Sat May 30 17:41:26 2020 daemon.notice pppd[9555]: peer from calling number x:x:x:x:x:x authorized
Sat May 30 17:41:26 2020 daemon.notice pppd[9555]: local  IP address x.x.x.x
Sat May 30 17:41:26 2020 daemon.notice pppd[9555]: remote IP address x.x.x.x
Sat May 30 17:41:26 2020 daemon.notice pppd[9555]: primary   DNS address x.x.x.x
Sat May 30 17:41:26 2020 daemon.notice pppd[9555]: secondary DNS address x.x.x.x
Sat May 30 17:41:26 2020 daemon.notice pppd[9555]: local  LL address fe80::x
Sat May 30 17:41:26 2020 daemon.notice pppd[9555]: remote LL address fe80::x
Sat May 30 17:41:26 2020 daemon.notice netifd: Network device 'pppoe-wan' link is up
Sat May 30 17:41:26 2020 daemon.notice netifd: Interface 'wan6' is enabled
Sat May 30 17:41:26 2020 daemon.notice netifd: Network alias 'pppoe-wan' link is up
Sat May 30 17:41:26 2020 daemon.notice netifd: Interface 'wan6' has link connectivity
Sat May 30 17:41:26 2020 daemon.notice netifd: Interface 'wan6' is setting up now
Sat May 30 17:41:26 2020 daemon.notice netifd: Interface 'wan' is now up
Sat May 30 17:41:26 2020 daemon.info dnsmasq[21914]: reading /tmp/resolv.conf.auto
Sat May 30 17:41:26 2020 daemon.notice netifd: Interface 'wan_6' is enabled
Sat May 30 17:41:26 2020 daemon.notice netifd: Interface 'wan_6' has link connectivity
Sat May 30 17:41:26 2020 daemon.notice netifd: Interface 'wan_6' is setting up now
Sat May 30 17:41:33 2020 daemon.notice netifd: Interface 'wan_6' is now up
Sat May 30 17:41:33 2020 daemon.info dnsmasq[21914]: reading /tmp/resolv.conf.auto
Sat May 30 17:41:38 2020 user.notice firewall: Reloading firewall due to ifup of wan_6 (pppoe-wan)
Sat May 30 17:41:39 2020 daemon.notice netifd: Interface 'wan6' is now up
2

Your VDSL link is unstable:

Sat May 30 17:39:22 2020 kern.warn kernel: [787105.479497] leave showtime
Sat May 30 17:39:22 2020 daemon.notice netifd: Network device 'dsl0' link is down
...
Sat May 30 17:41:20 2020 kern.warn kernel: [787223.673368] enter showtime
Sat May 30 17:41:20 2020 daemon.notice netifd: Network device 'dsl0' link is up

Run /etc/init.d/dsl_control status and post its output here, preferably before and after the connection was interrupted.

Do you have another modem you could swap in for comparison?

3

@mpa
thanks for your replay.
It took me a bit to get another occurrence. I tried a periodic check each 15 minutes. The last one before connection loss is this one.
(line uptime is since reboot of the router)

ATU-C Vendor ID:                          Broadcom 193.218
ATU-C System Vendor ID:                   Broadcom
Chipset:                                  Lantiq-VRX200
Firmware Version:                         5.9.1.4.0.7
API Version:                              4.17.18.6
XTSE Capabilities:                        0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x2
Annex:                                    B
Line Mode:                                G.993.5 (VDSL2 with down- and upstream vectoring)
Profile:                                  17a
Line State:                               UP [0x801: showtime_tc_sync]
Forward Error Correction Seconds (FECS):  Near: 0 / Far: 5038
Errored seconds (ES):                     Near: 0 / Far: 12
Severely Errored Seconds (SES):           Near: 0 / Far: 0
Loss of Signal Seconds (LOSS):            Near: 0 / Far: 0
Unavailable Seconds (UAS):                Near: 51522592 / Far: 51522592
Header Error Code Errors (HEC):           Near: 0 / Far: 0
Non Pre-emtive CRC errors (CRC_P):        Near: 0 / Far: 0
Pre-emtive CRC errors (CRCP_P):           Near: 0 / Far: 0
Power Management Mode:                    L0 - Synchronized
Latency [Interleave Delay]:               0.13 ms [Fast]   0.0 ms [Fast]
Data Rate:                                Down: 63.669 Mb/s / Up: 12.735 Mb/s
Line Attenuation (LATN):                  Down: 9.8 dB / Up: 8.6 dB
Signal Attenuation (SATN):                Down: 9.8 dB / Up: 8.5 dB
Noise Margin (SNR):                       Down: 14.1 dB / Up: 24.6 dB
Aggregate Transmit Power (ACTATP):        Down: 0.4 dB / Up: 8.4 dB
Max. Attainable Data Rate (ATTNDR):       Down: 92.995 Mb/s / Up: 36.704 Mb/s
Line Uptime Seconds:                      14326
Line Uptime:                              3h 58m 46s

Second one after a connection loss

ATU-C Vendor ID:                          Broadcom 193.218
ATU-C System Vendor ID:                   Broadcom
Chipset:                                  Lantiq-VRX200
Firmware Version:                         5.9.1.4.0.7
API Version:                              4.17.18.6
XTSE Capabilities:                        0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x2
Annex:                                    B
Line Mode:                                G.993.5 (VDSL2 with down- and upstream vectoring)
Profile:                                  17a
Line State:                               UP [0x801: showtime_tc_sync]
Forward Error Correction Seconds (FECS):  Near: 0 / Far: 0
Errored seconds (ES):                     Near: 0 / Far: 13
Severely Errored Seconds (SES):           Near: 0 / Far: 0
Loss of Signal Seconds (LOSS):            Near: 0 / Far: 0
Unavailable Seconds (UAS):                Near: 51522699 / Far: 51522699
Header Error Code Errors (HEC):           Near: 0 / Far: 0
Non Pre-emtive CRC errors (CRC_P):        Near: 0 / Far: 0
Pre-emtive CRC errors (CRCP_P):           Near: 0 / Far: 0
Power Management Mode:                    L0 - Synchronized
Latency [Interleave Delay]:               0.13 ms [Fast]   0.0 ms [Fast]
Data Rate:                                Down: 63.669 Mb/s / Up: 12.735 Mb/s
Line Attenuation (LATN):                  Down: 9.8 dB / Up: 8.6 dB
Signal Attenuation (SATN):                Down: 9.8 dB / Up: 8.5 dB
Noise Margin (SNR):                       Down: 16.0 dB / Up: 28.8 dB
Aggregate Transmit Power (ACTATP):        Down: 0.7 dB / Up: 8.4 dB
Max. Attainable Data Rate (ATTNDR):       Down: 99.663 Mb/s / Up: 42.716 Mb/s
Line Uptime Seconds:                      161
Line Uptime:                              2m 41s

If you notice something interesting please let me know. From my point of view both look similar.

4 
Forward Error Correction Seconds (FECS):  Near: 0 / Far: 5038

That seems a bit excessive.

Data Rate:                                Down: 63.669 Mb/s / Up: 12.735 Mb/s
Noise Margin (SNR):                       Down: 16.0 dB / Up: 28.8 dB
Max. Attainable Data Rate (ATTNDR):       Down: 99.663 Mb/s / Up: 42.716 Mb/s

This looks like your line has been downgraded to a much lower profile than it would be able to deliver, probably as a reaction to the resyncs.

ATU-C Vendor ID:                          Broadcom 193.218
Firmware Version:                         5.9.1.4.0.7

You are running the exact same setup as I am: Fritz!Box 3370 and a Broadcom 193.218 on the other end of the line. Personally, I did not have great luck with firmware 5.9.1.4.0.7. In fact, I could reliably prompt it to drop and resync the line by just running a random speedtest.

I have been running 5.7.8.9.1.7 for the last few days, and the line seems much happier with it.

5

@takimata
Thanks a lot for that hint. Sounds promising.
I am just a bit directionless in regards to this topic. Since we are talking firmware version in respect to dsl here that would mean I need another version of the vr9-B-dsl.bin right? And I would get it the same way from an older AVM firmware?

If so cold could you please suggest on?

6

That would be the process, yes. Unless you can find an archive of firmwares in a thread in this forum. Cough cough.

7

All right
Got the firmware from the link you posted and /etc/init.d/dsl_control status now shows Version: 5.7.8.9.1.7. Thanks a lot so far.
I will report back on how it works out for me. Hopefully you don't here anything from me until in about a week or so :slight_smile:

8

Judging from your silence I am guessing that 5.7.8.9.1.7 is working well for you?

I'm especially curious if your line returned to a higher profile after a few days. This happened to me, a different firmware (5.7.5.5.1.7) appeared to be even more stable at first, but caused so many errors that the other end of the line decided to downgrade my profile several times. I then switched back to 5.7.8.9.1.7 and, after a few days, the other end decided I can have my full line back.

9

Your are absolutely right. The dsl line has no huge uptime because I was experimenting and restarting but I have been at about 4days uptime before. So much better. Thanks a lot!

Here is the latest dsl status. To be honest I do not relate get much out of it except the Data Rate.
(If you are referging to max attainable and actual rate then this one is because of the contract with my ISP)

ATU-C Vendor ID:                          Broadcom 193.218
ATU-C System Vendor ID:                   Broadcom
Chipset:                                  Lantiq-VRX200
Firmware Version:                         5.7.8.9.1.7
API Version:                              4.17.18.6
XTSE Capabilities:                        0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x2
Annex:                                    B
Line Mode:                                G.993.5 (VDSL2 with down- and upstream vectoring)
Profile:                                  17a
Line State:                               UP [0x801: showtime_tc_sync]
Forward Error Correction Seconds (FECS):  Near: 0 / Far: 5060
Errored seconds (ES):                     Near: 0 / Far: 14
Severely Errored Seconds (SES):           Near: 0 / Far: 0
Loss of Signal Seconds (LOSS):            Near: 0 / Far: 0
Unavailable Seconds (UAS):                Near: 51522582 / Far: 51522582
Header Error Code Errors (HEC):           Near: 0 / Far: 0
Non Pre-emtive CRC errors (CRC_P):        Near: 0 / Far: 0
Pre-emtive CRC errors (CRCP_P):           Near: 0 / Far: 0
Power Management Mode:                    L0 - Synchronized
Latency [Interleave Delay]:               0.13 ms [Fast]   0.0 ms [Fast]
Data Rate:                                Down: 63.668 Mb/s / Up: 12.735 Mb/s
Line Attenuation (LATN):                  Down: 9.4 dB / Up: 8.8 dB
Signal Attenuation (SATN):                Down: 9.3 dB / Up: 8.6 dB
Noise Margin (SNR):                       Down: 8.0 dB / Up: 25.9 dB
Aggregate Transmit Power (ACTATP):        Down: 0.2 dB / Up: 5.3 dB
Max. Attainable Data Rate (ATTNDR):       Down: 71.043 Mb/s / Up: 38.029 Mb/s
Line Uptime Seconds:                      184117
Line Uptime:                              2d 3h 8m 37s

If you are interested in anything else feel free to send me a message. This one is closed from my point of view.

10

This topic was automatically closed 10 days after the last reply. New replies are no longer allowed.