search

zephyrproject-rtos / zephyr

Primary Git Repository for the Zephyr Project. Zephyr is a new generation, scalable, optimized, secure RTOS for multiple hardware architectures.
https://docs.zephyrproject.org
Apache License 2.0
10.82k stars 6.59k forks source link

Support use general modem (e.g SIM800 with CMUX) in the driver cellular modem #78269

Open chihosin opened 1 month ago

chihosin commented 1 month ago

Is your enhancement proposal related to a problem? Please describe. Support use general modem (e.g SIM800 with CMUX) in the driver cellular modem.

Describe the solution you'd like In version 3.6, the gsm_modem driver worked correctly, but now it is not functioning properly with the cellular_modem. I tried adding a code snippet based on the SIM7080 to support SIM800’s initialization commands, but even after removing the PAP authentication part, it still fails to connect to the network.

Describe alternatives you've considered

Additional context Here is the log after running the modified code.

[00:00:12.689,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGDCONT=1,"IP",""
[00:00:12.690,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:1 cr:1 pf:0 type:UIH dlen:20
[00:00:12.690,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     41 54 2b 43 47 44 43 4f  4e 54 3d 31 2c 22 49 50 |AT+CGDCO NT=1,"IP
                                     22 2c 22 22                                      |",""             
[00:00:12.690,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:1 cr:1 pf:0 type:UIH dlen:1
[00:00:12.690,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d                                               |.                
[00:00:12.721,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:1 cr:0 pf:0 type:UIH dlen:6
[00:00:12.721,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d 0a 4f 4b 0d 0a                                |..OK..           
[00:00:12.722,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:12.722,000] <dbg> modem_chat: modem_chat_script_next: simcom_sim7080_dial_chat_script: step: 2
[00:00:12.722,000] <dbg> modem_chat: modem_chat_script_next: sending: ATD*99#
[00:00:12.722,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:1 cr:1 pf:0 type:UIH dlen:7
[00:00:12.722,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     41 54 44 2a 39 39 23                             |ATD*99#          
[00:00:12.722,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:1 cr:1 pf:0 type:UIH dlen:1
[00:00:12.722,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d                                               |.                
[00:00:12.751,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:1 cr:0 pf:0 type:UIH dlen:11
[00:00:12.751,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d 0a 43 4f 4e 4e 45 43  54 0d 0a                |..CONNEC T..     
[00:00:12.751,000] <dbg> modem_chat: modem_chat_log_received_command: CONNECT
[00:00:12.751,000] <dbg> modem_chat: modem_chat_script_stop: simcom_sim7080_dial_chat_script: complete
[00:00:12.751,000] <dbg> modem_cellular: modem_cellular_log_event: event script success
[00:00:12.752,000] <dbg> modem_cellular: modem_cellular_log_state_changed: switch from run dial script to await registered
[00:00:13.089,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:0 pf:0 type:UIH dlen:24
[00:00:13.089,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d 0a 2b 43 47 45 56 3a  20 45 50 53 20 50 44 4e |..+CGEV:  EPS PDN
                                     20 41 43 54 20 38 0d 0a                          | ACT 8..         
[00:00:13.090,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: +CGEV: EPS PDN ACT 8
[00:00:13.090,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:3 cr:0 pf:0 type:UIH dlen:24
[00:00:13.090,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d 0a 2b 43 47 45 56 3a  20 45 50 53 20 50 44 4e |..+CGEV:  EPS PDN
                                     20 41 43 54 20 38 0d 0a                          | ACT 8..         
[00:00:13.090,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: +CGEV: EPS PDN ACT 8
[00:00:14.753,000] <dbg> modem_cellular: modem_cellular_log_event: event timeout
[00:00:14.753,000] <dbg> modem_chat: modem_chat_script_start: running script: simcom_sim7080_periodic_chat_script
[00:00:14.753,000] <dbg> modem_chat: modem_chat_script_next: simcom_sim7080_periodic_chat_script: step: 0
[00:00:14.753,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CREG?
[00:00:14.753,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:2 cr:1 pf:0 type:UIH dlen:8
[00:00:14.753,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     41 54 2b 43 52 45 47 3f                          |AT+CREG?         
[00:00:14.754,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:2 cr:1 pf:0 type:UIH dlen:1
[00:00:14.754,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d                                               |.                
[00:00:14.780,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:0 pf:0 type:UIH dlen:8
[00:00:14.780,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     41 54 2b 43 52 45 47 3f                          |AT+CREG?         
[00:00:14.780,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:0 pf:0 type:UIH dlen:1
[00:00:14.780,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d                                               |.                
[00:00:14.780,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:0 pf:0 type:UIH dlen:14
[00:00:14.780,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d 0a 2b 43 52 45 47 3a  20 30 2c 36 0d 0a       |..+CREG:  0,6..  
[00:00:14.780,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:0 pf:0 type:UIH dlen:6
[00:00:14.780,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d 0a 4f 4b 0d 0a                                |..OK..           
[00:00:14.780,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CREG?
[00:00:14.781,000] <dbg> modem_chat: modem_chat_log_received_command: +CREG:  0 6
[00:00:14.781,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:14.781,000] <dbg> modem_chat: modem_chat_script_next: simcom_sim7080_periodic_chat_script: step: 1
[00:00:14.781,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG?
[00:00:14.781,000] <dbg> modem_cellular: modem_cellular_log_event: event deregistered
[00:00:14.781,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:2 cr:1 pf:0 type:UIH dlen:9
[00:00:14.781,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     41 54 2b 43 45 52 45 47  3f                      |AT+CEREG ?       
[00:00:14.781,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:2 cr:1 pf:0 type:UIH dlen:1
[00:00:14.781,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d                                               |.                
[00:00:14.808,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:0 pf:0 type:UIH dlen:9
[00:00:14.808,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     41 54 2b 43 45 52 45 47  3f                      |AT+CEREG ?       
[00:00:14.808,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:0 pf:0 type:UIH dlen:1
[00:00:14.808,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d                                               |.                
[00:00:14.808,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:0 pf:0 type:UIH dlen:15
[00:00:14.808,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d 0a 2b 43 45 52 45 47  3a 20 30 2c 31 0d 0a    |..+CEREG : 0,1.. 
[00:00:14.808,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:0 pf:0 type:UIH dlen:6
[00:00:14.808,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d 0a 4f 4b 0d 0a                                |..OK..           
[00:00:14.809,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CEREG?
[00:00:14.809,000] <dbg> modem_chat: modem_chat_log_received_command: +CEREG:  0 1
[00:00:14.809,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:14.809,000] <dbg> modem_chat: modem_chat_script_next: simcom_sim7080_periodic_chat_script: step: 2
[00:00:14.809,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGREG?
[00:00:14.809,000] <dbg> modem_cellular: modem_cellular_log_event: event registered
[00:00:14.810,000] <dbg> modem_cellular: modem_cellular_log_state_changed: switch from await registered to carrier on
[00:00:14.810,000] <dbg> net_l2_ppp: ppp_change_phase_debug: (net_mgmt): [0x3fcaf110] phase DEAD (0) => ESTABLISH (1) (ppp_open_async():202)
[00:00:14.810,000] <dbg> net_l2_ppp: ppp_open_async: (net_mgmt): Starting LCP
[00:00:14.811,000] <dbg> net_l2_ppp: ppp_fsm_lower_up: (net_mgmt): [LCP/0x3fcaf148] Current state INITIAL (0)
[00:00:14.811,000] <dbg> net_l2_ppp: ppp_change_state_debug: (net_mgmt): [LCP/0x3fcaf148] state INITIAL (0) => CLOSED (2) (():312)
[00:00:14.811,000] <dbg> net_l2_ppp: ppp_fsm_open: (net_mgmt): [LCP/0x3fcaf148] Current state CLOSED (2)
[00:00:14.811,000] <dbg> net_l2_ppp: ppp_change_state_debug: (net_mgmt): [LCP/0x3fcaf148] state CLOSED (2) => REQUEST_SENT (6) (():335)
[00:00:14.812,000] <dbg> net_l2_ppp: fsm_send_configure_req: (net_mgmt): [LCP/0x3fcaf148] Sending Configure-Req (1) id 1 to peer while in REQUEST_SENT (6)
[00:00:14.813,000] <dbg> net_l2_ppp: ppp_send_pkt: (net_mgmt): [LCP/0x3fcaf148] Sending 10 bytes pkt 0x3fc9ce9c (options len 4)
[00:00:14.813,000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[00:00:14.813,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc9ce9c
                                     c0 21 01 01 00 08                                |.!....           
[00:00:14.813,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc9ce9c
                                     01 04 05 dc                                      |....             
[00:00:14.813,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:2 cr:1 pf:0 type:UIH dlen:9
[00:00:14.814,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     41 54 2b 43 47 52 45 47  3f                      |AT+CGREG ?       
[00:00:14.814,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:2 cr:1 pf:0 type:UIH dlen:1
[00:00:14.814,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d                                               |.                
[00:00:14.815,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:1 cr:1 pf:0 type:UIH dlen:24
[00:00:14.815,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     7e ff 7d 23 c0 21 7d 21  7d 21 7d 20 7d 28 7d 21 |~.}#.!}! }!} }(}!
                                     7d 24 7d 25 dc 51 c1 7e                          |}$}%.Q.~         
[00:00:14.844,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:0 pf:0 type:UIH dlen:9
[00:00:14.844,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     41 54 2b 43 47 52 45 47  3f                      |AT+CGREG ?       
[00:00:14.844,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:0 pf:0 type:UIH dlen:1
[00:00:14.844,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d                                               |.                
[00:00:14.844,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:0 pf:0 type:UIH dlen:15
[00:00:14.844,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d 0a 2b 43 47 52 45 47  3a 20 30 2c 31 0d 0a    |..+CGREG : 0,1.. 
[00:00:14.844,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:0 pf:0 type:UIH dlen:6
[00:00:14.844,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d 0a 4f 4b 0d 0a                                |..OK..           
[00:00:14.845,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CGREG?
[00:00:14.845,000] <dbg> modem_chat: modem_chat_log_received_command: +CGREG:  0 1
[00:00:14.845,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:14.845,000] <dbg> modem_chat: modem_chat_script_stop: simcom_sim7080_periodic_chat_script: complete
[00:00:14.846,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:1 cr:0 pf:0 type:UIH dlen:51
[00:00:14.846,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     7e ff 7d 23 c0 21 7d 21  7d 21 7d 20 7d 38 7d 22 |~.}#.!}! }!} }8}"
                                     7d 26 7d 20 7d 20 7d 20  7d 20 7d 23 7d 24 c0 23 |}&} } }  } }#}$.#
                                     7d 25 7d 26 36 d1 7c 2b  7d 27 7d 22 7d 28 7d 22 |}%}&6.|+ }'}"}(}"
                                     6e 73 7e                                         |ns~              
[00:00:14.846,000] <dbg> modem_cellular: modem_cellular_log_event: event registered
[00:00:14.846,000] <dbg> modem_cellular: modem_cellular_log_event: event script success
[00:00:14.847,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Receiving PPP frame
[00:00:14.847,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Received PPP frame (len 28)
[00:00:14.847,000] <dbg> net_l2_ppp: net_pkt_hexdump: recv L2
[00:00:14.847,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc9cf8c
                                     c0 21 01 01 00 18 02 06  00 00 00 00 03 04 c0 23 |.!...... .......#
                                     05 06 36 d1 7c 2b 07 02  08 02                   |..6.|+.. ..      
[00:00:14.848,000] <dbg> net_l2_ppp: ppp_fsm_input: (rx_q[0]): [LCP/0x3fcaf148] LCP Configure-Req (1) id 1 payload len 20
[00:00:14.848,000] <dbg> net_l2_ppp: fsm_recv_configure_req: (rx_q[0]): [LCP/0x3fcaf148] Current state REQUEST_SENT (6)
[00:00:14.848,000] <dbg> net_l2_ppp: ppp_parse_options: (rx_q[0]): [LCP/0x3fcaf148] option ASYNC_CTRL_CHAR_MAP (2) len 6
[00:00:14.849,000] <dbg> net_l2_ppp: ppp_parse_option_conf_req_unsupported: (rx_q[0]): [LCP/0x3fcaf148] Check option ASYNC_CTRL_CHAR_MAP (2) len 4
[00:00:14.849,000] <dbg> net_l2_ppp: ppp_parse_options: (rx_q[0]): [LCP/0x3fcaf148] option AUTH_PROTO (3) len 4
[00:00:14.849,000] <dbg> net_l2_ppp: ppp_parse_option_conf_req_unsupported: (rx_q[0]): [LCP/0x3fcaf148] Check option AUTH_PROTO (3) len 2
[00:00:14.849,000] <dbg> net_l2_ppp: ppp_parse_options: (rx_q[0]): [LCP/0x3fcaf148] option MAGIC_NUMBER (5) len 6
[00:00:14.849,000] <dbg> net_l2_ppp: ppp_parse_option_conf_req_unsupported: (rx_q[0]): [LCP/0x3fcaf148] Check option MAGIC_NUMBER (5) len 4
[00:00:14.849,000] <dbg> net_l2_ppp: ppp_parse_options: (rx_q[0]): [LCP/0x3fcaf148] option PROTO_COMPRESS (7) len 2
[00:00:14.849,000] <dbg> net_l2_ppp: ppp_parse_option_conf_req_unsupported: (rx_q[0]): [LCP/0x3fcaf148] Check option PROTO_COMPRESS (7) len 0
[00:00:14.849,000] <dbg> net_l2_ppp: ppp_parse_options: (rx_q[0]): [LCP/0x3fcaf148] option ADDR_CTRL_COMPRESS (8) len 2
[00:00:14.849,000] <dbg> net_l2_ppp: ppp_parse_option_conf_req_unsupported: (rx_q[0]): [LCP/0x3fcaf148] Check option ADDR_CTRL_COMPRESS (8) len 0
[00:00:14.849,000] <dbg> net_l2_ppp: fsm_recv_configure_req: (rx_q[0]): [LCP/0x3fcaf148] Sending Configure-Rej (4) id 1 to peer while in REQUEST_SENT (6)
[00:00:14.850,000] <dbg> net_l2_ppp: ppp_send_pkt: (rx_q[0]): [LCP/0x3fcaf148] Sending 22 bytes pkt 0x3fc9ce9c (options len 16)
[00:00:14.850,000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[00:00:14.850,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc9ce9c
                                     c0 21 04 01 00 14                                |.!....           
[00:00:14.850,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc9ce9c
                                     02 06 00 00 00 00 05 06  36 d1 7c 2b 07 02 08 02 |........ 6.|+....
[00:00:14.851,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:1 cr:0 pf:0 type:UIH dlen:24
[00:00:14.851,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     7e ff 7d 23 c0 21 7d 22  7d 21 7d 20 7d 28 7d 21 |~.}#.!}" }!} }(}!
                                     7d 24 7d 25 dc 81 4b 7e                          |}$}%..K~         
[00:00:14.851,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Receiving PPP frame
[00:00:14.851,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Received PPP frame (len 12)
[00:00:14.851,000] <dbg> net_l2_ppp: net_pkt_hexdump: recv L2
[00:00:14.852,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc9cf8c
                                     c0 21 02 01 00 08 01 04  05 dc                   |.!...... ..      
[00:00:14.852,000] <dbg> net_l2_ppp: ppp_fsm_input: (rx_q[0]): [LCP/0x3fcaf148] LCP Configure-Ack (2) id 1 payload len 4
[00:00:14.852,000] <dbg> net_l2_ppp: fsm_recv_configure_ack: (rx_q[0]): [LCP/0x3fcaf148] Current state REQUEST_SENT (6)
[00:00:14.852,000] <dbg> net_l2_ppp: ppp_change_state_debug: (rx_q[0]): [LCP/0x3fcaf148] state REQUEST_SENT (6) => ACK_RECEIVED (7) (():735)
[00:00:14.853,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:1 cr:1 pf:0 type:UIH dlen:40
[00:00:14.853,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     7e ff 7d 23 c0 21 7d 24  7d 21 7d 20 7d 34 7d 22 |~.}#.!}$ }!} }4}"
                                     7d 26 7d 20 7d 20 7d 20  7d 20 7d 25 7d 26 36 d1 |}&} } }  } }%}&6.
                                     7c 2b 7d 27 7d 22 7d 28                          ||+}'}"}(         
[00:00:14.853,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:1 cr:1 pf:0 type:UIH dlen:5
[00:00:14.853,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     7d 22 a4 e3 7e                                   |}"..~            
[00:00:14.883,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:1 cr:0 pf:0 type:UIH dlen:23
[00:00:14.883,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     7e ff 7d 23 c0 21 7d 21  7d 22 7d 20 7d 28 7d 23 |~.}#.!}! }"} }(}#
                                     7d 24 c0 23 23 eb 7e                             |}$.##.~          
[00:00:14.883,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Receiving PPP frame
[00:00:14.883,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Received PPP frame (len 12)
[00:00:14.884,000] <dbg> net_l2_ppp: net_pkt_hexdump: recv L2
[00:00:14.884,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc9cf8c
                                     c0 21 01 02 00 08 03 04  c0 23                   |.!...... .#      
[00:00:14.884,000] <dbg> net_l2_ppp: ppp_fsm_input: (rx_q[0]): [LCP/0x3fcaf148] LCP Configure-Req (1) id 2 payload len 4
[00:00:14.884,000] <dbg> net_l2_ppp: fsm_recv_configure_req: (rx_q[0]): [LCP/0x3fcaf148] Current state ACK_RECEIVED (7)
[00:00:14.885,000] <dbg> net_l2_ppp: ppp_parse_options: (rx_q[0]): [LCP/0x3fcaf148] option AUTH_PROTO (3) len 4
[00:00:14.885,000] <dbg> net_l2_ppp: ppp_parse_option_conf_req_unsupported: (rx_q[0]): [LCP/0x3fcaf148] Check option AUTH_PROTO (3) len 2
[00:00:14.885,000] <dbg> net_l2_ppp: ppp_parse_options: (rx_q[0]): [LCP/0x3fcaf148] option AUTH_PROTO (3) len 4
[00:00:14.885,000] <dbg> net_l2_ppp: lcp_auth_proto_parse: (rx_q[0]): [LCP] Received auth protocol c023 (PAP)
[00:00:14.885,000] <dbg> net_l2_ppp: lcp_config_info_req: (rx_q[0]): Authentication protocol negotiated: c023 (PAP)
[00:00:14.886,000] <dbg> net_l2_ppp: fsm_recv_configure_req: (rx_q[0]): [LCP/0x3fcaf148] Sending Configure-Ack (2) id 2 to peer while in ACK_RECEIVED (7)
[00:00:14.886,000] <dbg> net_l2_ppp: ppp_send_pkt: (rx_q[0]): [LCP/0x3fcaf148] Sending 10 bytes pkt 0x3fc9ce9c (options len 4)
[00:00:14.886,000] <dbg> net_l2_ppp: ppp_change_state_debug: (rx_q[0]): [LCP/0x3fcaf148] state ACK_RECEIVED (7) => OPENED (9) (():653)
[00:00:14.886,000] <dbg> net_l2_ppp: ppp_link_established: (rx_q[0]): [0x3fcaf110] Link established
[00:00:14.887,000] <dbg> net_l2_ppp: ppp_change_phase_debug: (rx_q[0]): [0x3fcaf110] phase ESTABLISH (1) => AUTH (2) (do_auth():74)
[00:00:14.887,000] <dbg> net_l2_ppp: ppp_fsm_open: (rx_q[0]): [PAP/0x3fcaf300] Current state INITIAL (0)
[00:00:14.887,000] <dbg> net_l2_ppp: ppp_change_state_debug: (rx_q[0]): [PAP/0x3fcaf300] state INITIAL (0) => STARTING (1) (():349)
[00:00:14.887,000] <dbg> net_l2_ppp: ppp_fsm_lower_up: (rx_q[0]): [IPCP/0x3fcaf220] Current state INITIAL (0)
[00:00:14.887,000] <dbg> net_l2_ppp: ppp_change_state_debug: (rx_q[0]): [IPCP/0x3fcaf220] state INITIAL (0) => CLOSED (2) (():312)
[00:00:14.887,000] <dbg> net_l2_ppp: ppp_fsm_lower_up: (rx_q[0]): [PAP/0x3fcaf300] Current state STARTING (1)
[00:00:14.888,000] <dbg> net_l2_ppp: fsm_send_configure_req: (rx_q[0]): [PAP/0x3fcaf300] Sending Configure-Req (1) id 1 to peer while in STARTING (1)
[00:00:14.888,000] <dbg> net_l2_ppp: ppp_send_pkt: (rx_q[0]): [PAP/0x3fcaf300] Sending 18 bytes pkt 0x3fc9ced8 (options len 12)
[00:00:14.888,000] <dbg> net_l2_ppp: ppp_change_state_debug: (rx_q[0]): [PAP/0x3fcaf300] state STARTING (1) => REQUEST_SENT (6) (():317)
[00:00:14.888,000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[00:00:14.888,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc9ce9c
                                     c0 21 02 02 00 08                                |.!....           
[00:00:14.888,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc9ce9c
                                     03 04 c0 23                                      |...#             
[00:00:14.888,000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[00:00:14.888,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc9ced8
                                     c0 23 01 01 00 10                                |.#....           
[00:00:14.888,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc9ced8
                                     05 62 6c 61 6e 6b 05 62  6c 61 6e 6b             |.blank.b lank    
[00:00:14.890,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:1 cr:1 pf:0 type:UIH dlen:23
[00:00:14.890,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     7e ff 7d 23 c0 21 7d 22  7d 22 7d 20 7d 28 7d 23 |~.}#.!}" }"} }(}#
                                     7d 24 c0 23 f3 61 7e                             |}$.#.a~          
[00:00:14.891,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:1 cr:1 pf:0 type:UIH dlen:31
[00:00:14.891,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     7e ff 7d 23 c0 23 7d 21  7d 21 7d 20 7d 30 7d 25 |~.}#.#}! }!} }0}%
                                     62 6c 61 6e 6b 7d 25 62  6c 61 6e 6b ad f2 7e    |blank}%b lank..~ 
[00:00:15.036,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:1 cr:0 pf:0 type:UIH dlen:14
[00:00:15.036,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     7e ff 03 c0 23 02 01 00  06 00 00 fc 25 7e       |~...#... ....%~  
[00:00:15.037,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x03 because 0x7d was expected.
[00:00:15.037,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0xc0 because 0x7e was expected.
[00:00:15.037,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x23 because 0x7e was expected.
[00:00:15.037,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x02 because 0x7e was expected.
[00:00:15.037,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x01 because 0x7e was expected.
[00:00:15.037,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x00 because 0x7e was expected.
[00:00:15.037,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x06 because 0x7e was expected.
[00:00:15.037,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x00 because 0x7e was expected.
[00:00:15.037,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x00 because 0x7e was expected.
[00:00:15.037,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0xfc because 0x7e was expected.
[00:00:15.037,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x25 because 0x7e was expected.
github-actions[bot] commented 1 month ago

Hi @chihosin! We appreciate you submitting your first issue for our open-source project. 🌟

Even though I'm a bot, I can assure you that the whole community is genuinely grateful for your time and effort. 🤖💙

bjarki-andreasen commented 1 month ago

This frame is not a valid as it is not encapsulated:

[00:00:15.036,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:1 cr:0 pf:0 type:UIH dlen:14
[00:00:15.036,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     7e ff 03 c0 23 02 01 00  06 00 00 fc 25 7e       |~...#... ....%~

The frame should be:

7e ff    03 ... 7e <- unencapsulated
7e ff 7d 23 ... 7e <- encapsulated (0x7d, 0x23 means escape, ((0x23 ^ 0x20) == 0x03))

This may be because of some special rules in the PPP protocol, or it is just a bug in the simcom firmware. In either case, the modem subsystem expects all PPP packets to be encapsulated at this time.

bjarki-andreasen commented 1 month ago

I found this spec https://datatracker.ietf.org/doc/html/rfc1661#section-2 of the PPP protocol, maybe you can find something in there which allows for unencapsulated packets, which we can then implement in modem_ppp :)

chihosin commented 1 month ago
image

Thank you for your response. It seems that I have found the function causing the PPP connection process to stall. The issue appears to be the unrecognized PPP protocol at this point. I’ll try to resolve it when I have time.