title: n_gsm Line discipline problem with Telit LE910B1 Modem and CMUX
body: <p>We are using a Telit LE910B1 modem on an embedded device running a Linux 5.1.0 kernel.  We only have a single UART available for the modem so we are using n_gsm line discipline with CMUX on the modem.  Once everything is setup, our app creates two virtual ttys, uses one to get modem information and the other is passed to pppd to start a PPP session. We can then start data RX/TX over TCP/IP.  This all works fine for a short time, with small data transfers, but when we try to transfer large amounts of data, the PPP connection locks up and the only way to get things running again is to kill pppd, power cycle the modem, and restart the application.</p>
  
  <p>Telit was able to reproduce the problem with two different versions of Ubuntu (18.04 and , and was able to obtain tracing information from the modem, which they pass to Intel for further diagnosis.  Intel's response was that they think the "host application side" may not be making correct CMUX frames or is not respecting max frame size. Here are some extracts given to us by Telit from the analysis of the modem trace:</p>
  
  <pre><code>&lt;-- Packet discarded because of flag("0xF9") missing in CMUX frame.
  &lt;-- Packet discarded because of dlc is not valid in frame.
  &lt;-- Packet discarded because of length size more then RD_BUF_SIZE = 1510
  &lt;-- Packet dropped because of in PPP frame FCS is not valid
  </code></pre>
  
  <p>In my case, the "host application side" is the n_gsm driver in Linux and the only things I can set are the mru and mtu sizes, which I've set to what Telit says is the modem's default (i.e. 121).</p>
  
  <p>The code I use to configure the modem is pretty straight forward (error checking is omitted for brevity):</p>
  
  <pre><code>struct termios tio;
  int serial_fd;
  
  serial_fd = open("/dev/ttyS1", O_RDWR | O_NOCTTY | O_NDELAY);
  tcgetattr(serial_fd, &amp;tio);
  tio.c_iflag = 0;
  tio.c_oflag = 0;
  tio.c_cflag = CS8 | CREAD | CLOCAL;
  tio.c_cflag |= CRTSCTS;
  tio.c_lflag = 0;
  tio.c_cc[VMIN] = 1;
  tio.c_cc[VTIME] = 0;
  
  cfsetospeed(&amp;tio, B115200);
  cfsetispeed(&amp;tio, B115200);
  tcsetattr(serial_fd, TCSANOW, &amp;tio);
  </code></pre>
  
  <p>To configure the modem I use the following:</p>
  
  <pre><code>send_at_command(serial_fd, "ATE0V1&amp;K3&amp;D2\r");
  send_at_command(serial_fd, "AT#CMUXMODE=5\r");
  send_at_command(serial_fd, "AT+CMUX=0,0\r");
  </code></pre>
  
  <p>Once that's done, I enable n_gsm discipline</p>
  
  <pre><code>struct gsm_config gsm;
  
  int ldisc = N_GSM0710;
  ioctl(serial_fd, TIOCSETD, &amp;ldisc);
  ioctl(serial_fd, GSMIOC_GETCONF, &amp;gsm) ;
  
  gsm.initiator = 1;
  gsm.encapsulation = 0;
  gsm.mru = 121;
  gsm.mtu = 121;
  
  ioctl(serial_fd, GSMIOC_SETCONF, &amp;gsm);
  /* Create /dev/ttyGSM1 and /dev/ttyGSM2. Do not close /dev/ttyS1 */
  </code></pre>
  
  <p>Has anyone else used an LE910* modem with CMUX and n_gsm line discipline on a Linux 5.1.0 or later kernel?  Have you had any problems? Are there any problem with the code I've shown or can you suggest something I could try?</p>
  
  <p><strong>EDIT</strong></p>
  
  <p>I looked at the n_gsm.c driver code and discovered that there are 3 trace level you can enable.  I started by enabling level 4 and 2:</p>
  
  <pre><code>echo "6" &gt; /sys/module/n_gsm/parameters/debug
  </code></pre>
  
  <p>and this would log packets as they are built and sent to the tty.  What I found was that what Intel said was correct.  The driver is sending garbage to the modem.  The log shows normal packets going out but then this:</p>
  
  <pre><code>Jan 19 18:09:51 ZFG0000805 kern.debug kernel: gsm_data_kick: 00000000: f9 0b ef f3 21 45 10 05 74 aa 6a 40 00 40 06 d1  ....!E..t.j@.@..
  Jan 19 18:09:51 ZFG0000805 kern.debug kernel: gsm_data_kick: 00000010: a5 46 19 8e 6f cc 65 18 76 00 16 0b 58 5b e6 da  .F..o.e.v...X[..
  Jan 19 18:09:51 ZFG0000805 kern.debug kernel: gsm_data_kick: 00000020: 55 bd 3e 38 ad 80 18 1f 4a 4d dc 00 00 01 01 08  U.&gt;8....JM......
  Jan 19 18:09:51 ZFG0000805 kern.debug kernel: gsm_data_kick: 00000030: 0a 65 3c e5 73 7b 9d 4c 86 f8 53 e4 9f ff a4 9e  .e&lt;.s{.L..S.....
  Jan 19 18:09:51 ZFG0000805 kern.debug kernel: gsmld_output: 00000060: 27 3c ee ab 28 29 51 e7 4e 04 f4 70 ce d4 e3 f2  '&lt;..()Q.N..p....
  Jan 19 18:09:51 ZFG0000805 kern.debug kernel: gsmld_output: 00000070: 93 ed 71 30 c7 1e 93 d8 b3 4a 90 88 e7 f9        ..q0.....J....
  </code></pre>
  
  <p>Normally you see a kick followed by an output where the packet is exactly the same, but not here.  CMUX packets should start and end with a 0xf9 byte but the "output" packet appears corrupt. After this, all kick logging shows complete packets but the following output trace starts one byte off from the start-of-frame character.</p>
  
  <pre><code>Jan 19 18:09:52 ZFG0000805 kern.debug kernel: gsm_data_kick: 00000000: f9 0b ef f3 87 8d e0 d0 db 2a 22 96 92 80 b6 a4  .........*".....
  Jan 19 18:09:52 ZFG0000805 kern.debug kernel: gsm_data_kick: 00000010: 31 33 43 f0 13 e9 f3 79 13 d9 b4 13 8a 85 10 15  13C....y........
  Jan 19 18:09:52 ZFG0000805 kern.debug kernel: gsm_data_kick: 00000020: 26 0d ab c2 89 f2 ad a2 6f cd 5d a9 15 f2 fe e8  &amp;.......o.].....
  Jan 19 18:09:52 ZFG0000805 kern.debug kernel: gsm_data_kick: 00000030: 6a 90 06 ef f3 d2 4c c1 65 4e 3c 22 f5 db f8 66  j.....L.eN&lt;"...f
  Jan 19 18:09:52 ZFG0000805 kern.debug kernel: gsm_data_kick: 00000040: d5 d7 70 fa f5 47 03 09 52 d3 1f 30 91 55 20 ce  ..p..G..R..0.U .
  Jan 19 18:09:52 ZFG0000805 kern.debug kernel: gsm_data_kick: 00000050: bc 71 51 b5 f7 ac f4 2a 7d 5d 1d 47 8d 30 73 22  .qQ....*}].G.0s"
  Jan 19 18:09:52 ZFG0000805 kern.debug kernel: gsm_data_kick: 00000060: 38 fa 39 f4 64 9f f6 7d 5d 7d 5d 2a ab b6 a6 cf  8.9.d..}]}]*....
  Jan 19 18:09:52 ZFG0000805 kern.debug kernel: gsm_data_kick: 00000070: 76 dd 8f 0a fd 27 8f 09 b2 78 99 da f8 e7 f9     v....'...x.....
  Jan 19 18:09:52 ZFG0000805 kern.debug kernel: gsmld_output: 00000000: 0b ef f3 87 8d e0 d0 db 2a 22 96 92 80 b6 a4 31  ........*".....1
  Jan 19 18:09:52 ZFG0000805 kern.debug kernel: gsmld_output: 00000010: 33 43 f0 13 e9 f3 79 13 d9 b4 13 8a 85 10 15 26  3C....y........&amp;
  Jan 19 18:09:52 ZFG0000805 kern.debug kernel: gsmld_output: 00000020: 0d ab c2 89 f2 ad a2 6f cd 5d a9 15 f2 fe e8 6a  .......o.].....j
  Jan 19 18:09:52 ZFG0000805 kern.debug kernel: gsmld_output: 00000030: 90 06 ef f3 d2 4c c1 65 4e 3c 22 f5 db f8 66 d5  .....L.eN&lt;"...f.
  Jan 19 18:09:52 ZFG0000805 kern.debug kernel: gsmld_output: 00000040: d7 70 fa f5 47 03 09 52 d3 1f 30 91 55 20 ce bc  .p..G..R..0.U ..
  Jan 19 18:09:52 ZFG0000805 kern.debug kernel: gsmld_output: 00000050: 71 51 b5 f7 ac f4 2a 7d 5d 1d 47 8d 30 73 22 38  qQ....*}].G.0s"8
  Jan 19 18:09:52 ZFG0000805 kern.debug kernel: gsmld_output: 00000060: fa 39 f4 64 9f f6 7d 5d 7d 5d 2a ab b6 a6 cf 76  .9.d..}]}]*....v
  Jan 19 18:09:52 ZFG0000805 kern.debug kernel: gsmld_output: 00000070: dd 8f 0a fd 27 8f 09 b2 78 99 da f8 e7 f9        ....'...x.....
  </code></pre>
  
  <p>Now the really weird part.  When I enable packet logging, </p>
  
  <pre><code>echo "7" &gt; /sys/module/n_gsm/parameters/debug
  </code></pre>
  
  <p>Packets are logged just before being queued for sending.  This slows down the whole system but no matter what I tried, I could not get the network session to hang.   Everything seemed to work fine, although it was gawd awful slow. </p>