HL78xx ttyACM1 PPP port doesn't respond (LCP: timeout sending Config-Requests)

IoT Modules HL78
1

We’re using the latest HL7800 firmware (HL7800.4.6.9) and
2 USB acm ports (UART0 and UART1 port is not connected)

Unfortunately it looks like the PPP data port (ttyACM1) is somehow stuck
after a while. It doesn’t respond to the PPP LCP Config Requests.
It is easy to recreate the problem with the recommended hl78xx and hl78xx-chat script
(from: HL7800 as a network interface in Linux), see:

Aug 31 10:08:06 (none) daemon.notice pppd[5405]: pppd 2.4.8 started by root, uid 0
Aug 31 10:08:07 (none) local2.info chat[5418]: abort on (BUSY)
Aug 31 10:08:07 (none) local2.info chat[5418]: abort on (NO CARRIER)
Aug 31 10:08:07 (none) local2.info chat[5418]: abort on (VOICE)
Aug 31 10:08:07 (none) local2.info chat[5418]: abort on (NO DIALTONE)
Aug 31 10:08:07 (none) local2.info chat[5418]: abort on (NO ANSWER)
Aug 31 10:08:07 (none) local2.info chat[5418]: abort on (DELAYED)
Aug 31 10:08:07 (none) local2.info chat[5418]: abort on (ERROR)
Aug 31 10:08:07 (none) local2.info chat[5418]: timeout set to 10 seconds
Aug 31 10:08:07 (none) local2.info chat[5418]: send (AT^M)
Aug 31 10:08:08 (none) local2.info chat[5418]: expect (OK)
Aug 31 10:08:08 (none) local2.info chat[5418]: AT^M^M
Aug 31 10:08:08 (none) local2.info chat[5418]: OK
Aug 31 10:08:08 (none) local2.info chat[5418]:  -- got it
Aug 31 10:08:08 (none) local2.info chat[5418]: send (ATD*99***1#^M)
Aug 31 10:08:08 (none) local2.info chat[5418]: expect (CONNECT)
Aug 31 10:08:08 (none) local2.info chat[5418]: ^M
Aug 31 10:08:08 (none) local2.info chat[5418]: ATD*99***1#^M^M
Aug 31 10:08:08 (none) local2.info chat[5418]: CONNECT
Aug 31 10:08:08 (none) local2.info chat[5418]:  -- got it
Aug 31 10:08:08 (none) daemon.debug pppd[5405]: Script /usr/sbin/chat -v -t 5 -f /etc/chatscripts/hl78xx-chat finished (pid 5418), status = 0x0
Aug 31 10:08:08 (none) daemon.info pppd[5405]: Serial connection established.
Aug 31 10:08:08 (none) daemon.debug pppd[5405]: using channel 31
Aug 31 10:08:08 (none) daemon.info pppd[5405]: Using interface ppp0
Aug 31 10:08:08 (none) daemon.notice pppd[5405]: Connect: ppp0 <--> /dev/ttyACM1
Aug 31 10:08:08 (none) daemon.info NetworkManager[20998]: <info>  [1630404488.2192] manager: (ppp0): new Ppp device (/org/freedesktop/NetworkManager/Devices/23)
Aug 31 10:08:09 (none) daemon.debug pppd[5405]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x45f67298> <pcomp>]
Aug 31 10:08:09 (none) auth.notice AdminMode[5434]: Initializing D-Bus server
Aug 31 10:08:09 (none) auth.crit AdminMode[5434]: Could not connect to EVSEd. Cannot continue.
Aug 31 10:08:12 (none) daemon.debug pppd[5405]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x45f67298> <pcomp>]
Aug 31 10:08:15 (none) daemon.debug pppd[5405]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x45f67298> <pcomp>]
Aug 31 10:08:18 (none) daemon.debug pppd[5405]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x45f67298> <pcomp>]
Aug 31 10:08:21 (none) daemon.debug pppd[5405]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x45f67298> <pcomp>]
Aug 31 10:08:24 (none) daemon.debug pppd[5405]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x45f67298> <pcomp>]
Aug 31 10:08:27 (none) daemon.debug pppd[5405]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x45f67298> <pcomp>]
Aug 31 10:08:30 (none) daemon.debug pppd[5405]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x45f67298> <pcomp>]
Aug 31 10:08:33 (none) daemon.debug pppd[5405]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x45f67298> <pcomp>]
Aug 31 10:08:36 (none) daemon.debug pppd[5405]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x45f67298> <pcomp>]
Aug 31 10:08:39 (none) daemon.warn pppd[5405]: LCP: timeout sending Config-Requests
Aug 31 10:08:39 (none) daemon.notice pppd[5405]: Connection terminated.
Aug 31 10:08:40 (none) daemon.notice pppd[5405]: Modem hangup
Aug 31 10:08:40 (none) daemon.info pppd[5405]: Exit.

Clearly the modem (USB virtual) PPP port doesn’t respond.

After modem reset (with CFUN=1,1) it does work once, see:

Aug 31 10:18:24 (none) daemon.notice pppd[10224]: pppd 2.4.8 started by root, uid 0
Aug 31 10:18:25 (none) local2.info chat[10235]: abort on (BUSY)
Aug 31 10:18:25 (none) local2.info chat[10235]: abort on (NO CARRIER)
Aug 31 10:18:25 (none) local2.info chat[10235]: abort on (VOICE)
Aug 31 10:18:25 (none) local2.info chat[10235]: abort on (NO DIALTONE)
Aug 31 10:18:25 (none) local2.info chat[10235]: abort on (NO ANSWER)
Aug 31 10:18:25 (none) local2.info chat[10235]: abort on (DELAYED)
Aug 31 10:18:25 (none) local2.info chat[10235]: abort on (ERROR)
Aug 31 10:18:25 (none) local2.info chat[10235]: timeout set to 10 seconds
Aug 31 10:18:25 (none) local2.info chat[10235]: send (AT^M)
Aug 31 10:18:25 (none) local2.info chat[10235]: expect (OK)
Aug 31 10:18:25 (none) local2.info chat[10235]: AT^M^M
Aug 31 10:18:25 (none) local2.info chat[10235]: OK
Aug 31 10:18:25 (none) local2.info chat[10235]:  -- got it
Aug 31 10:18:25 (none) local2.info chat[10235]: send (ATD*99***1#^M)
Aug 31 10:18:25 (none) local2.info chat[10235]: expect (CONNECT)
Aug 31 10:18:25 (none) local2.info chat[10235]: ^M
Aug 31 10:18:25 (none) local2.info chat[10235]: ATD*99***1#^M^M
Aug 31 10:18:25 (none) local2.info chat[10235]: CONNECT
Aug 31 10:18:25 (none) local2.info chat[10235]:  -- got it
Aug 31 10:18:25 (none) daemon.debug pppd[10224]: Script /usr/sbin/chat -v -t 5 -f /etc/chatscripts/hl78xx-chat finished (pid 10235), status = 0x0
Aug 31 10:18:25 (none) daemon.info pppd[10224]: Serial connection established.
Aug 31 10:18:25 (none) daemon.debug pppd[10224]: using channel 32
Aug 31 10:18:25 (none) daemon.info pppd[10224]: Using interface ppp0
Aug 31 10:18:25 (none) daemon.notice pppd[10224]: Connect: ppp0 <--> /dev/ttyACM1
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xae051895> <pcomp> <accomp>]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x4db71c0c> <pcomp>]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: sent [LCP ConfRej id=0x1 <accomp>]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x4db71c0c> <pcomp>]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: rcvd [LCP ConfReq id=0x2 <asyncmap 0x0> <magic 0xae051895> <pcomp>]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: sent [LCP ConfAck id=0x2 <asyncmap 0x0> <magic 0xae051895> <pcomp>]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: sent [LCP EchoReq id=0x0 magic=0x4db71c0c]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: sent [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: rcvd [LCP EchoRep id=0x0 magic=0xae051895]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: rcvd [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 10.0.0.1>]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: sent [IPCP ConfAck id=0x1 <compress VJ 0f 01> <addr 10.0.0.1>]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: rcvd [IPV6CP ConfReq id=0x1]
Aug 31 10:18:26 (none) daemon.warn pppd[10224]: Unsupported protocol 'IPv6 Control Protocol' (0x8057) received
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: sent [LCP ProtRej id=0x2 80 57 01 01 00 04]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: rcvd [CCP ConfReq id=0x1]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: sent [CCP ConfAck id=0x1]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: rcvd [CCP ConfRej id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: sent [CCP ConfReq id=0x2]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: rcvd [IPCP ConfRej id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: sent [IPCP ConfReq id=0x2 <addrs 0.0.0.0 0.0.0.0> <compress VJ 0f 01>]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: rcvd [CCP ConfAck id=0x2]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: rcvd [IPCP ConfRej id=0x2 <addrs 0.0.0.0 0.0.0.0>]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: sent [IPCP ConfReq id=0x3 <compress VJ 0f 01>]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: rcvd [IPCP ConfAck id=0x3 <compress VJ 0f 01>]
Aug 31 10:18:26 (none) daemon.err pppd[10224]: Could not determine local IP address
Aug 31 10:18:26 (none) daemon.info pppd[10224]: Connect time 0.1 minutes.
Aug 31 10:18:26 (none) daemon.info pppd[10224]: Sent 97 bytes, received 89 bytes.
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: sent [IPCP TermReq id=0x4 "Could not determine local IP address"]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: rcvd [IPCP TermAck id=0x4]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: sent [LCP TermReq id=0x3 "No network protocols running"]
Aug 31 10:18:26 (none) daemon.debug pppd[10224]: rcvd [LCP TermAck id=0x3]
Aug 31 10:18:26 (none) daemon.notice pppd[10224]: Connection terminated.
Aug 31 10:18:27 (none) daemon.info pppd[10224]: Exit.

I known there is some local IP address pppd config issue that is causing pppd to fail,
but at least the ttyACM1 PPP port is responding, right?

After this, any subsequent ‘pppd call hl78xx’ fails because the ttyACM1 PPP port doesn’t respond!

Isn’t this a modem PPP port bug or am I missing something?
I guess the internal state of the modem PPP port is confused, is there something I can do to reset the port (apart from CFUN=1,1)?
Can you please investigate this issue?

2

I just tried to dial up in ubuntu 12 using wvdial with HL78 module UART1 (FW 4.6.8.0) , no problem is found.

Suggest you to do the basic dial up on UART first with wvdial to isolate if this is network problem.

3

As mentioned, UART isn’t connected in our case.

4

Can you solder out the lines?

You need to figure out if this is usb or uart or network or dial up tool problem.

5

no, unfortunately we cannot solder out the lines.
we anyway need this (USB only) configuration to work.

I’d expect you to recreate this problem easily once you disable the UART though.

It sure looks like a specific USB problem to me, afterall:

  • you don’t see it with the UART
  • the network registration and is fine. I can show you if you want.
  • it does work after modem reset

I will anyway try to avoid this “local IP address pppd config issue” that we have and retest.

6

While retesting… do you want me to do some detailed modem or linux usbmon tracing?

7
  • it does work after modem reset

Then when is it not working?
Does this mean this is randomly happening only?

8

it’s failing after modem reset and after trying it once. This 1st attempt (after modem reset) runs into this “local IP address pppd config issue” (“Could not determine local IP address”), but this is a different problem.

Once this “local IP address pppd config issue” happened, the modem PPP port never responds and the “LCP: timeout sending Config-Requests” problem happen, this is the problem that concerns me.

9

Have you tried the same fw as mine
Fw 4.6.8.0

10

terminal_log.txt (1.4 KB)

systemlog.txt (10.3 KB)

11

I just did, the same problem occurs.

find attached the terminal log and the system log, these logs contain 4 ‘pppd call hl78xx’ attempts.

The 1st one fails with the “Could not determine local IP address” issue, I still haven’t figured this out yet

In the 2nd and 3rd attempt the call script fails immediately, I think this is due to the ttyACM1 port in data mode (so it doesn’t respond with “OK”) and somehow then there’s a URC “+CEREG: 1,“ED81”,“00BAA50B”,7” that confuses the call script. How to prevent this?

The problem this post is about can be seen in the 4th and final "pppd call hl78xx’ attempt, as you can see there is no PPP response?

It sure looks like this acm1 (/dev/ttyACM1) PPP ports is pretty unreliable

please help.

Please help

12

no problem is found for dial up in ubuntu 12 using usb /dev/ttyACM1 port with FW 4.6.8.0:

Cowner@ubuntu:~$ sudo wvdial
→ WvDial: Internet dialer version 1.61
→ Initializing modem.
→ Sending: AT
AT
OK
→ Modem initialized.
→ Sending: ATDT991#
→ Waiting for carrier.
A
CONNECT
TDT99**1#
→ Carrier detected. Waiting for prompt.
~[7f]}#@!}!}!} }8}!}$}%[14]}"}&} } } } }%}&)Inb}’}"}(}"[q~
→ PPP negotiation detected.
→ Starting pppd at Wed Sep 1 16:28:58 2021
→ Pid of pppd: 3507
→ Using interface ppp0
→ local IP address 10.12.2.136
→ remote IP address 10.0.0.1

owner@ubuntu:~$ sudo cat /etc/wvdial.conf
[sudo] password for owner:
[Dialer Defaults]
Phone = 99**1#
Username = 1
Password = 1
New PPPD = yes
Baud = 115200
Modem = /dev/ttyACM1
PPPD Path = /usr/sbin/pppd
Modem Type = Analog Modem
Auto Reconnect = on
Carrier Check = no
Init1 = AT
owner@ubuntu:~$ ping 8.8.8.8
PING 8.8.8.8 (8.8.8.8) 56(84) bytes of data.
64 bytes from 8.8.8.8: icmp_req=1 ttl=116 time=1864 ms
64 bytes from 8.8.8.8: icmp_req=2 ttl=116 time=966 ms
64 bytes from 8.8.8.8: icmp_req=3 ttl=116 time=333 ms
^C
— 8.8.8.8 ping statistics —
3 packets transmitted, 3 received, 0% packet loss, time 2010ms
rtt min/avg/max/mdev = 333.693/1054.671/1864.228/627.969 ms, pipe 2
owner@ubuntu:~$

13

for me it also worked well initially, what happens if you disconnect/connect 10 times?

what PPP options you use?
what PDP context definition?
does “AT+CGCONTRDP” return a IP address (and gw/dns) details?

14

i used network simulator:

at+cgpaddr=1

+CGPADDR: 1,“192.168.3.2”

OK

if it works intially, and then it does not work, you can do a reset AT+CFUN=1,1 and see if it works again.