Unable to establish ppp connection with Huawei dongle

Unable to establish ppp connection with Huawei dongle

[rakespani]

[-- Attachment #1: Type: text/plain, Size: 8404 bytes --]

Hi ,

I am trying to enable lte connection with huawei dongle , but I am getting below error log for activat/context. 

Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: Modem: > AT+CGDCONT=1,"IP","airtelgprs.com"\r
Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: Modem: < \r\nOK\r\n
Aug 26 11:36:28 raspberrypi3 daemon.debug ofonod[147]: ../ofono-1.24/drivers/atmodem/gprs-context.c:at_cgdcont_cb() ok 1
Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: Modem: > AT+CGDATA="PPP",1\r
Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: Modem: < \r\nCONNECT 100000000\r\n
Aug 26 11:36:28 raspberrypi3 daemon.debug ofonod[147]: ../ofono-1.24/drivers/atmodem/gprs-context.c:at_cgdata_cb() ok 1
Aug 26 11:36:28 raspberrypi3 daemon.debug ofonod[147]: ../ofono-1.24/drivers/atmodem/gprs-context.c:setup_ppp()
Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_generate_event: current state 0:INITIAL
Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: PPP: event: 0 (Up), action: 2, new_state: 2 (CLOSED)
Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_generate_event: current state 2:CLOSED
Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: PPP: event: 2 (Open), action: 1026, new_state: 6 (REQSENT)
Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_initialize_restart_count: current state 2:CLOSED
Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_send_configure_request: current state 2:CLOSED
Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: PPP: ../ofono-1.24/gatchat/gatppp.c:ppp_enter_phase() 1
Aug 26 11:36:29 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^BOOT:1113056,0,0,0,99\r\n
Aug 26 11:36:30 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^RSSI:31\r\n
Aug 26 11:36:30 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^LTERSRP:-76,-6\r\n
Aug 26 11:36:31 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_timeout: current state 6:REQSENT
Aug 26 11:36:31 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_generate_event: current state 6:REQSENT
Aug 26 11:36:31 raspberrypi3 daemon.info ofonod[147]: PPP: event: 4 (TO+), action: 1006, new_state: 6 (REQSENT)
Aug 26 11:36:31 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_send_configure_request: current state 6:REQSENT
Aug 26 11:36:33 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^RSSI:31\r\n
Aug 26 11:36:33 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^LTERSRP:-76,-6\r\n
Aug 26 11:36:34 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_timeout: current state 6:REQSENT
Aug 26 11:36:34 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_generate_event: current state 6:REQSENT
Aug 26 11:36:34 raspberrypi3 daemon.info ofonod[147]: PPP: event: 4 (TO+), action: 1006, new_state: 6 (REQSENT)
Aug 26 11:36:34 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_send_configure_request: current state 6:REQSENT
Aug 26 11:36:36 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^RSSI:31\r\n
Aug 26 11:36:36 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^LTERSRP:-76,-6\r\n
Aug 26 11:36:37 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_timeout: current state 6:REQSENT
Aug 26 11:36:37 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_generate_event: current state 6:REQSENT
Aug 26 11:36:37 raspberrypi3 daemon.info ofonod[147]: PPP: event: 4 (TO+), action: 1006, new_state: 6 (REQSENT)
Aug 26 11:36:37 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_send_configure_request: current state 6:REQSENT
Aug 26 11:36:39 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^RSSI:31\r\n\r\n^LTERSRP:-76,-6\r\n
Aug 26 11:36:40 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_timeout: current state 6:REQSENT
Aug 26 11:36:40 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_generate_event: current state 6:REQSENT
Aug 26 11:36:40 raspberrypi3 daemon.info ofonod[147]: PPP: event: 4 (TO+), action: 1006, new_state: 6 (REQSENT)
Aug 26 11:36:40 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_send_configure_request: current state 6:REQSENT
Aug 26 11:36:42 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^RSSI:31\r\n
Aug 26 11:36:42 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^LTERSRP:-76,-6\r\n
Aug 26 11:36:43 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_timeout: current state 6:REQSENT
Aug 26 11:36:43 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_generate_event: current state 6:REQSENT
Aug 26 11:36:43 raspberrypi3 daemon.info ofonod[147]: PPP: event: 4 (TO+), action: 1006, new_state: 6 (REQSENT)
Aug 26 11:36:43 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_send_configure_request: current state 6:REQSENT
Aug 26 11:36:45 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^RSSI:31\r\n
Aug 26 11:36:45 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^LTERSRP:-76,-6\r\n
Aug 26 11:36:46 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_timeout: current state 6:REQSENT
Aug 26 11:36:46 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_generate_event: current state 6:REQSENT
Aug 26 11:36:46 raspberrypi3 daemon.info ofonod[147]: PPP: event: 4 (TO+), action: 1006, new_state: 6 (REQSENT)
Aug 26 11:36:46 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_send_configure_request: current state 6:REQSENT
Aug 26 11:36:48 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^RSSI:31\r\n
Aug 26 11:36:48 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^LTERSRP:-76,-6\r\n
Aug 26 11:36:49 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_timeout: current state 6:REQSENT
Aug 26 11:36:49 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_generate_event: current state 6:REQSENT
Aug 26 11:36:49 raspberrypi3 daemon.info ofonod[147]: PPP: event: 4 (TO+), action: 1006, new_state: 6 (REQSENT)
Aug 26 11:36:49 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_send_configure_request: current state 6:REQSENT
Aug 26 11:36:51 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^RSSI:31\r\n
Aug 26 11:36:51 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^LTERSRP:-76,-6\r\n
Aug 26 11:36:52 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_timeout: current state 6:REQSENT
Aug 26 11:36:52 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_generate_event: current state 6:REQSENT
Aug 26 11:36:52 raspberrypi3 daemon.info ofonod[147]: PPP: event: 4 (TO+), action: 1006, new_state: 6 (REQSENT)
Aug 26 11:36:52 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_send_configure_request: current state 6:REQSENT
Aug 26 11:36:54 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^RSSI:31\r\n
Aug 26 11:36:54 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^LTERSRP:-76,-9\r\n
Aug 26 11:36:55 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_timeout: current state 6:REQSENT
Aug 26 11:36:55 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_generate_event: current state 6:REQSENT
Aug 26 11:36:55 raspberrypi3 daemon.info ofonod[147]: PPP: event: 4 (TO+), action: 1006, new_state: 6 (REQSENT)
Aug 26 11:36:55 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_send_configure_request: current state 6:REQSENT
Aug 26 11:36:57 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^RSSI:31\r\n
Aug 26 11:36:57 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^LTERSRP:-76,-7\r\n
Aug 26 11:36:58 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_timeout: current state 6:REQSENT
Aug 26 11:36:58 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_generate_event: current state 6:REQSENT
Aug 26 11:36:58 raspberrypi3 daemon.info ofonod[147]: PPP: event: 5 (TO-), action: 803, new_state: 3 (STOPPED)
Aug 26 11:36:58 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_this_layer_finished: current state 3:STOPPED
Aug 26 11:36:58 raspberrypi3 daemon.info ofonod[147]: PPP: ../ofono-1.24/gatchat/gatppp.c:ppp_enter_phase() 0
Aug 26 11:36:58 raspberrypi3 daemon.info ofonod[147]: PPP: ../ofono-1.24/gatchat/gatppp.c:ppp_dead()
Aug 26 11:36:58 raspberrypi3 daemon.debug ofonod[147]: ../ofono-1.24/drivers/atmodem/gprs-context.c:ppp_disconnect() Reason: 0
Aug 26 11:36:58 raspberrypi3 daemon.debug ofonod[147]: ../ofono-1.24/src/gprs.c:pri_activate_callback() 0x165b9a8
Aug 26 11:36:58 raspberrypi3 daemon.debug ofonod[147]: ../ofono-1.24/src/gprs.c:pri_activate_callback() Activating context failed with error: Unknown error type

Re: Unable to establish ppp connection with Huawei dongle

[Lars Poeschel]

[-- Attachment #1: Type: text/plain, Size: 2837 bytes --]

Hi,

I do notice two things looking at your logs:

On Thu, Aug 27, 2020 at 04:26:40AM -0000, rakespani(a)gmail.com wrote:
> Hi ,
> 
> I am trying to enable lte connection with huawei dongle , but I am getting below error log for activat/context. 
> 
> Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: Modem: > AT+CGDCONT=1,"IP","airtelgprs.com"\r
> Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: Modem: < \r\nOK\r\n
> Aug 26 11:36:28 raspberrypi3 daemon.debug ofonod[147]: ../ofono-1.24/drivers/atmodem/gprs-context.c:at_cgdcont_cb() ok 1

1. You use ofono-1.24 which is fairly old. Latest release is 1.31 so
far.

> Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: Modem: > AT+CGDATA="PPP",1\r
> Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: Modem: < \r\nCONNECT 100000000\r\n
> Aug 26 11:36:28 raspberrypi3 daemon.debug ofonod[147]: ../ofono-1.24/drivers/atmodem/gprs-context.c:at_cgdata_cb() ok 1
> Aug 26 11:36:28 raspberrypi3 daemon.debug ofonod[147]: ../ofono-1.24/drivers/atmodem/gprs-context.c:setup_ppp()
> Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_generate_event: current state 0:INITIAL
> Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: PPP: event: 0 (Up), action: 2, new_state: 2 (CLOSED)
> Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_generate_event: current state 2:CLOSED
> Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: PPP: event: 2 (Open), action: 1026, new_state: 6 (REQSENT)
> Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_initialize_restart_count: current state 2:CLOSED
> Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_send_configure_request: current state 2:CLOSED
> Aug 26 11:36:28 raspberrypi3 daemon.info ofonod[147]: PPP: ../ofono-1.24/gatchat/gatppp.c:ppp_enter_phase() 1
> Aug 26 11:36:29 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^BOOT:1113056,0,0,0,99\r\n
> Aug 26 11:36:30 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^RSSI:31\r\n
> Aug 26 11:36:30 raspberrypi3 daemon.info ofonod[147]: PCUI: < \r\n^LTERSRP:-76,-6\r\n
> Aug 26 11:36:31 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_timeout: current state 6:REQSENT
> Aug 26 11:36:31 raspberrypi3 daemon.info ofonod[147]: PPP: lcp: pppcp_generate_event: current state 6:REQSENT
> Aug 26 11:36:31 raspberrypi3 daemon.info ofonod[147]: PPP: event: 4 (TO+), action: 1006, new_state: 6 (REQSENT)

2. Ofono is trying to communicate with your provider here and sending
ppp configuration requests. It does timeout several times. That means
your mobile provider is not answering this requests.
At some time you should receive something other than a "(TO+)".
If I should guess, I would say this is because of wrong apn settings.
(username/password)

Regards,
Lars

Re: Unable to establish ppp connection with Huawei dongle

[rakespani]

[-- Attachment #1: Type: text/plain, Size: 758 bytes --]

Hi Lars ,

I have updated ofono to 1.31 

After that also same error message I am getting . I  captured pppdump for this . I observe that I am not getting any response from the dongle. 

So to verify if AT commands and APN settings are proper or not I followed below steps using ofono & pppd .

1. list-modems (ofono-testclient)
2. enable-modem (ofono-testclient)
3. create-internet-context airtelgprs.com(ofono-testclient)
4. online-modem (ofono-testclient)
5. echo -e -n 'AT+CGDCONT=1,"IP","airtelgprs.com"\r'  > /dev/ttyUSB0
6. echo -e -n 'AT+CGDATA="PPP",1\r'  > /dev/ttyUSB0
7. /usr/sbin/pppd ttyUSB0 115200 usepeerdns nodetach crtscts noauth passive 

With this ppp interface is up . 

I am using Huawei E392 Modem.

Regards,
Rakes

Re: Unable to establish ppp connection with Huawei dongle

[Lars Poeschel]

[-- Attachment #1: Type: text/plain, Size: 1097 bytes --]

On Wed, Sep 02, 2020 at 10:46:27AM -0000, rakespani(a)gmail.com wrote:
> Hi Lars ,
> 
> I have updated ofono to 1.31 
> 
> After that also same error message I am getting . I  captured pppdump for this . I observe that I am not getting any response from the dongle. 

I think from the log you gave in your last mail that you are not
awaiting a response from the dongle but instead from your mobile
provider.

> So to verify if AT commands and APN settings are proper or not I followed below steps using ofono & pppd .
> 
> 1. list-modems (ofono-testclient)
> 2. enable-modem (ofono-testclient)
> 3. create-internet-context airtelgprs.com(ofono-testclient)
> 4. online-modem (ofono-testclient)
> 5. echo -e -n 'AT+CGDCONT=1,"IP","airtelgprs.com"\r'  > /dev/ttyUSB0
> 6. echo -e -n 'AT+CGDATA="PPP",1\r'  > /dev/ttyUSB0
> 7. /usr/sbin/pppd ttyUSB0 115200 usepeerdns nodetach crtscts noauth passive 
> 
> With this ppp interface is up . 

And now what exactly is the difference between the pppdump you captured
from ofono and the pppdump captured with pppd ?

Regards,
Lars

Re: Unable to establish ppp connection with Huawei dongle

[Rakes Pani]

[-- Attachment #1: Type: text/plain, Size: 2515 bytes --]

Hi Lars,

Only difference I see in case of pppd , config request is going with below options.

Options: (16 bytes), Async Control Character Map(0x00000000), Magic Number, Protocol Field Compression, Address and Control Field Compression

In case of ofono , none of the options are sent .
So I tried hard coding the option's  as ppd , but still no response

+++ b/gatchat/ppp_lcp.c
@@ -119,6 +119,60 @@ static void lcp_generate_config_options(struct lcp_data *lcp)
        lcp->options_len = len;
 }

+static void lcp_generate_config_options_modified(struct pppcp_data *pppcp, struct lcp_data *lcp)
+{
+       guint16 len = 0;
+
+       //if (lcp->req_options & REQ_OPTION_ACCM) {
+               guint32 accm;
+               lcp->accm = 0U;
+               accm = htonl(lcp->accm);
+
+               lcp->options[len] = ACCM;
+               lcp->options[len + 1] = 6;
+               memcpy(lcp->options + len + 2, &accm, sizeof(accm));
+
+               len += 6;
+       //}
+
+       if (lcp->req_options & REQ_OPTION_MRU) {
+               guint16 mru;
+
+               mru = htons(lcp->mru);
+
+               lcp->options[len] = MRU;
+               lcp->options[len + 1] = 4;
+               memcpy(lcp->options + len + 2, &mru, sizeof(mru));
+
+               len += 4;
+       }
+
+       //if (lcp->req_options & REQ_OPTION_ACFC) {
+               lcp->options[len] = ACFC;
+               lcp->options[len + 1] = 2;
+
+               len += 2;
+       //}
+
+       //if (lcp->req_options & REQ_OPTION_PFC) {
+               lcp->options[len] = PFC;
+               lcp->options[len + 1] = 2;
+
+               len += 2;
+       //}
+
+       guint32 magic_number = 123456789;
+       guint32 magic_number1 = htonl(magic_number);
+
+       lcp->options[len] = MAGIC_NUMBER;
+       lcp->options[len + 1] = 6;
+       memcpy(lcp->options + len + 2, &magic_number1, sizeof(magic_number1));
+       len += 6;
+
+
+       lcp->options_len = len;
+}
+
 static void lcp_reset_config_options(struct lcp_data *lcp)
 {
        /* Using the default ACCM */
@@ -392,7 +446,8 @@ struct pppcp_data *lcp_new(GAtPPP *ppp, gboolean is_server)

        pppcp_set_data(pppcp, lcp);

-       lcp_reset_config_options(lcp);
+       //lcp_reset_config_options(pppcp,lcp);
+       lcp_generate_config_options_modified(pppcp,lcp);
        pppcp_set_local_options(pppcp, lcp->options, lcp->options_len);

        return pppcp;

Regards,
Rakes