Serial Forwarding: A puzzle

Michael 'Mickey' Lauer mickey at openmoko.org
Sat Feb 28 01:36:37 CET 2009


Guys, I need your help. There's a problem driving me crazy since months
and I'm pretty much out of ideas.

To ease developing, I sometimes prefer executing code on my desktop
instead of the FR, however since I need the modem, I'd like to forward
it via usbeth, making it appear as a pts on the other PC. This works
excellent in single-line modus, but as soon as you enter multiplexing
mode, things go wrong.

With the new muxer -- fso-abyss -- I now have concrete debugging data
and pinpointed the location where it goes wrong. I have attached a
'good' run (running it on the device) and a 'bad' run (running it via
forwarding).

The mystic part is that there is no difference in the data that gets
sent to the modem. The problem starts when we allocate the first
channel:

In the good run we receive the handshake and then the serial status "DSR
CTS" for the newly opened channel.

In the bad run, we receive the handshake and then the serial status "FC
CTS", which means 'Overrun -- please do not send any frames".

The only difference I can think of is the timing, alas I have inserted
sleeps in the forwarding code to mimick the slower processing of the FR,
but it didn't help.

I'm out of ideas. I'd be grateful for any insights.

Cheers,

:M:
-------------- next part --------------
2009-02-27T06:15:02Z: multiplexer.vala:503:  -> answer OK
2009-02-27T06:15:02Z: multiplexer.vala:529: 0710 -> should write 5 bytes
2009-02-27T06:15:02Z: consts.vala:76: >>> 7E 03 3F FC 7E  ~.?.~
2009-02-27T06:15:02Z: multiplexer.vala:538: wrote 5/5 bytes to fd 4
2009-02-27T06:15:02Z: multiplexer.vala:618: device_io_can_read for fd 4
2009-02-27T06:15:02Z: multiplexer.vala:515: 0710 -> should read max 4096 bytes to 0x20f6c
2009-02-27T06:15:02Z: multiplexer.vala:520: read 5 bytes from fd 4
2009-02-27T06:15:02Z: consts.vala:76: <<< 7E 03 73 85 7E  ~.s.~
2009-02-27T06:15:02Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 0, type 0x63, data[0] 0x85, len 
0
2009-02-27T06:15:13Z: server.vala:81: AllocChannel requested for name foo, requested channel 0
2009-02-27T06:15:13Z: server.vala:171: Consumer foo requested channel 0
2009-02-27T06:15:13Z: multiplexer.vala:213: allocChannel requested for name foo, requested channel 1
2009-02-27T06:15:13Z: multiplexer.vala:529: 0710 -> should write 5 bytes
2009-02-27T06:15:13Z: consts.vala:76: >>> 7E 07 3F 89 7E  ~.?.~
2009-02-27T06:15:13Z: multiplexer.vala:538: wrote 5/5 bytes to fd 4
2009-02-27T06:15:13Z: multiplexer.vala:222: 0710 open channel returned result 1
2009-02-27T06:15:13Z: serial.vala:247: <Pseudo TTY  (fd -1)>: constructed
2009-02-27T06:15:13Z: channel.vala:60: <Channel 1 (foo) connected via >: constructed
2009-02-27T06:15:13Z: multiplexer.vala:618: device_io_can_read for fd 4
2009-02-27T06:15:13Z: multiplexer.vala:515: 0710 -> should read max 4095 bytes to 0x20f6d
2009-02-27T06:15:13Z: multiplexer.vala:520: read 49 bytes from fd 4
2009-02-27T06:15:13Z: consts.vala:70: <<< 7E 07 73 F0 7E 7E 01 FF E3 05 07 0D B6 7E 7E 05  ~.s.~~.......~~.
2009-02-27T06:15:13Z: consts.vala:70: <<< EF 41 54 2D 43 6F 6D 6D 61 6E 64 20 49 6E 74 65  .AT-Command Inte
2009-02-27T06:15:13Z: consts.vala:70: <<< 72 70 72 65 74 65 72 20 72 65 61 64 79 0D 0A DF  rpreter ready...
2009-02-27T06:15:13Z: consts.vala:76: <<< 7E  ~
2009-02-27T06:15:13Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 1, type 0x63, data[0] 0xF0, len 
0
2009-02-27T06:15:13Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 0, type 0xEF, data[0] 0xE3, len 
4
2009-02-27T06:15:13Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 0, type 0xE1, data[0] 0x07, len 
2
2009-02-27T06:15:13Z: multiplexer.vala:561: 0710 -> deliver status 13 = 'DSR CTS ' for channel 1
2009-02-27T06:15:13Z: channel.vala:75: <Channel 1 (foo) connected via >: acked; opening pty
2009-02-27T06:15:13Z: channel.vala:124: setSerialStatus()
2009-02-27T06:15:13Z: multiplexer.vala:580: 0710 -> say 'received status line signal, sending response
2009-02-27T06:15:13Z: multiplexer.vala:529: 0710 -> should write 9 bytes
2009-02-27T06:15:13Z: consts.vala:76: >>> 7E 03 EF E1 05 07 0D 70 7E  ~......p~
2009-02-27T06:15:13Z: multiplexer.vala:538: wrote 9/9 bytes to fd 4
2009-02-27T06:15:13Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 1, type 0xEF, data[0] 0x41, len 
30
2009-02-27T06:15:13Z: multiplexer.vala:546: 0710 -> deliver 30 bytes for channel 1
2009-02-27T06:15:14Z: multiplexer.vala:618: device_io_can_read for fd 4
2009-02-27T06:15:14Z: multiplexer.vala:515: 0710 -> should read max 4095 bytes to 0x20f6d
2009-02-27T06:15:14Z: multiplexer.vala:520: read 9 bytes from fd 4
2009-02-27T06:15:14Z: consts.vala:76: <<< 7E 01 FF E3 05 07 0D B6 7E  ~.......~
2009-02-27T06:15:14Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 0, type 0xEF, data[0] 0xE3, len 
4
2009-02-27T06:15:14Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 0, type 0xE1, data[0] 0x07, len 
2
2009-02-27T06:15:14Z: multiplexer.vala:561: 0710 -> deliver status 13 = 'DSR CTS ' for channel 1
2009-02-27T06:15:14Z: channel.vala:124: setSerialStatus()
2009-02-27T06:15:14Z: multiplexer.vala:580: 0710 -> say 'received status line signal, sending response
2009-02-27T06:15:14Z: multiplexer.vala:529: 0710 -> should write 9 bytes
2009-02-27T06:15:14Z: consts.vala:76: >>> 7E 03 EF E1 05 07 0D 70 7E  ~......p~
2009-02-27T06:15:14Z: multiplexer.vala:538: wrote 9/9 bytes to fd 4
2009-02-27T06:15:14Z: multiplexer.vala:618: device_io_can_read for fd 4
2009-02-27T06:15:14Z: multiplexer.vala:515: 0710 -> should read max 4095 bytes to 0x20f6d
2009-02-27T06:15:14Z: multiplexer.vala:520: read 9 bytes from fd 4
2009-02-27T06:15:14Z: consts.vala:76: <<< 7E 01 FF E3 05 07 0D B6 7E  ~.......~
2009-02-27T06:15:14Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 0, type 0xEF, data[0] 0xE3, len 
4
2009-02-27T06:15:14Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 0, type 0xE1, data[0] 0x07, len 
2
2009-02-27T06:15:14Z: multiplexer.vala:561: 0710 -> deliver status 13 = 'DSR CTS ' for channel 1
2009-02-27T06:15:14Z: channel.vala:124: setSerialStatus()
2009-02-27T06:15:14Z: multiplexer.vala:580: 0710 -> say 'received status line signal, sending response
2009-02-27T06:15:14Z: multiplexer.vala:529: 0710 -> should write 9 bytes
2009-02-27T06:15:14Z: consts.vala:76: >>> 7E 03 EF E1 05 07 0D 70 7E  ~......p~
2009-02-27T06:15:14Z: multiplexer.vala:538: wrote 9/9 bytes to fd 4
2009-02-27T06:15:14Z: multiplexer.vala:618: device_io_can_read for fd 4
2009-02-27T06:15:14Z: multiplexer.vala:515: 0710 -> should read max 4095 bytes to 0x20f6d
2009-02-27T06:15:14Z: multiplexer.vala:520: read 9 bytes from fd 4
2009-02-27T06:15:14Z: consts.vala:76: <<< 7E 01 FF E3 05 07 0D B6 7E  ~.......~
2009-02-27T06:15:14Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 0, type 0xEF, data[0] 0xE3, len 
4
2009-02-27T06:15:14Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 0, type 0xE1, data[0] 0x07, len 
2
2009-02-27T06:15:14Z: multiplexer.vala:561: 0710 -> deliver status 13 = 'DSR CTS ' for channel 1
2009-02-27T06:15:14Z: channel.vala:124: setSerialStatus()
2009-02-27T06:15:14Z: multiplexer.vala:580: 0710 -> say 'received status line signal, sending response
2009-02-27T06:15:14Z: multiplexer.vala:529: 0710 -> should write 9 bytes
2009-02-27T06:15:14Z: consts.vala:76: >>> 7E 03 EF E1 05 07 0D 70 7E  ~......p~
2009-02-27T06:15:14Z: multiplexer.vala:538: wrote 9/9 bytes to fd 4



-------------- next part --------------
2009-02-27T23:40:10.773416Z: multiplexer.vala:503:  -> answer OK
2009-02-27T23:40:10.773425Z: multiplexer.vala:529: 0710 -> should write 5 bytes
2009-02-27T23:40:10.773439Z: consts.vala:76: >>> 7E 03 3F FC 7E  ~.?.~
2009-02-27T23:40:10.773659Z: multiplexer.vala:538: wrote 5/5 bytes to fd 4
2009-02-27T23:40:10.785177Z: multiplexer.vala:618: device_io_can_read for fd 4
2009-02-27T23:40:10.785190Z: multiplexer.vala:515: 0710 -> should read max 4096 bytes to 0x169080c
2009-02-27T23:40:10.785200Z: multiplexer.vala:520: read 5 bytes from fd 4
2009-02-27T23:40:10.785213Z: consts.vala:76: <<< 7E 03 73 85 7E  ~.s.~
2009-02-27T23:40:10.785225Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 0, type 0x63, data[0] 
0xFFFFFF85, len 0
2009-02-27T23:40:38.720529Z: server.vala:81: AllocChannel requested for name foo, requested channel 0
2009-02-27T23:40:38.720551Z: server.vala:171: Consumer foo requested channel 0
2009-02-27T23:40:38.720559Z: multiplexer.vala:213: allocChannel requested for name foo, requested channel 1
2009-02-27T23:40:38.720570Z: multiplexer.vala:529: 0710 -> should write 5 bytes
2009-02-27T23:40:38.720585Z: consts.vala:76: >>> 7E 07 3F 89 7E  ~.?.~
2009-02-27T23:40:38.720820Z: multiplexer.vala:538: wrote 5/5 bytes to fd 4
2009-02-27T23:40:38.720827Z: multiplexer.vala:222: 0710 open channel returned result 1
2009-02-27T23:40:38.720884Z: serial.vala:247: <Pseudo TTY  (fd -1)>: constructed
2009-02-27T23:40:38.720897Z: channel.vala:60: <Channel 1 (foo) connected via >: constructed
2009-02-27T23:40:38.733413Z: multiplexer.vala:618: device_io_can_read for fd 4
2009-02-27T23:40:38.733426Z: multiplexer.vala:515: 0710 -> should read max 4095 bytes to 0x169080d
2009-02-27T23:40:38.733436Z: multiplexer.vala:520: read 5 bytes from fd 4
2009-02-27T23:40:38.733450Z: consts.vala:76: <<< 7E 07 73 F0 7E  ~.s.~
2009-02-27T23:40:38.733459Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 1, type 0x63, data[0] 
0xFFFFFFF0, len 0
2009-02-27T23:40:38.740489Z: multiplexer.vala:618: device_io_can_read for fd 4
2009-02-27T23:40:38.740504Z: multiplexer.vala:515: 0710 -> should read max 4095 bytes to 0x169080d
2009-02-27T23:40:38.740514Z: multiplexer.vala:520: read 34 bytes from fd 4
2009-02-27T23:40:38.740535Z: consts.vala:70: <<< 7E 01 FF E3 05 07 0A B6 7E 7E 05 EF 41 54 2D 43  
~.......~~..AT-C
2009-02-27T23:40:38.740552Z: consts.vala:70: <<< 6F 6D 6D 61 6E 64 20 49 6E 74 65 72 70 72 65 74  ommand 
Interpret
2009-02-27T23:40:38.740559Z: consts.vala:76: <<< 65 72  er
2009-02-27T23:40:38.740567Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 0, type 0xEF, data[0] 
0xFFFFFFE3, len 4
2009-02-27T23:40:38.740574Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 0, type 0xE1, data[0] 
0x07, len 2
2009-02-27T23:40:38.740590Z: multiplexer.vala:561: 0710 -> deliver status 10 = 'FC CTS ' for channel 1
2009-02-27T23:40:38.740599Z: channel.vala:75: <Channel 1 (foo) connected via >: acked; opening pty
2009-02-27T23:40:38.740703Z: channel.vala:124: setSerialStatus()
2009-02-27T23:40:38.740717Z: multiplexer.vala:580: 0710 -> say 'received status line signal, sending response
2009-02-27T23:40:38.740726Z: multiplexer.vala:529: 0710 -> should write 9 bytes
2009-02-27T23:40:38.740739Z: consts.vala:76: >>> 7E 03 EF E1 05 07 0A 70 7E  ~......p~
2009-02-27T23:40:38.740825Z: multiplexer.vala:538: wrote 9/9 bytes to fd 4
2009-02-27T23:40:38.753542Z: multiplexer.vala:618: device_io_can_read for fd 4
2009-02-27T23:40:38.753558Z: multiplexer.vala:515: 0710 -> should read max 4071 bytes to 0x1690825
2009-02-27T23:40:38.753568Z: multiplexer.vala:520: read 10 bytes from fd 4
2009-02-27T23:40:38.753586Z: consts.vala:76: <<< 20 72 65 61 64 79 0A 0A DF 7E   ready...~
2009-02-27T23:40:38.753596Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 1, type 0xEF, data[0] 
0x41, len 30
2009-02-27T23:40:38.753606Z: multiplexer.vala:546: 0710 -> deliver 30 bytes for channel 1
2009-02-27T23:40:39.033510Z: multiplexer.vala:618: device_io_can_read for fd 4
2009-02-27T23:40:39.033529Z: multiplexer.vala:515: 0710 -> should read max 4095 bytes to 0x169080d
2009-02-27T23:40:39.033543Z: multiplexer.vala:520: read 9 bytes from fd 4
2009-02-27T23:40:39.033560Z: consts.vala:76: <<< 7E 01 FF E3 05 07 0A B6 7E  ~.......~
2009-02-27T23:40:39.033571Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 0, type 0xEF, data[0] 
0xFFFFFFE3, len 4
2009-02-27T23:40:39.033578Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 0, type 0xE1, data[0] 
0x07, len 2
2009-02-27T23:40:39.033586Z: multiplexer.vala:561: 0710 -> deliver status 10 = 'FC CTS ' for channel 1
2009-02-27T23:40:39.033592Z: channel.vala:124: setSerialStatus()
2009-02-27T23:40:39.033598Z: multiplexer.vala:580: 0710 -> say 'received status line signal, sending response
2009-02-27T23:40:39.033604Z: multiplexer.vala:529: 0710 -> should write 9 bytes
2009-02-27T23:40:39.033616Z: consts.vala:76: >>> 7E 03 EF E1 05 07 0A 70 7E  ~......p~
2009-02-27T23:40:39.033693Z: multiplexer.vala:538: wrote 9/9 bytes to fd 4
2009-02-27T23:40:39.333499Z: multiplexer.vala:618: device_io_can_read for fd 4
2009-02-27T23:40:39.333518Z: multiplexer.vala:515: 0710 -> should read max 4095 bytes to 0x169080d
2009-02-27T23:40:39.333530Z: multiplexer.vala:520: read 9 bytes from fd 4
2009-02-27T23:40:39.333548Z: consts.vala:76: <<< 7E 01 FF E3 05 07 0A B6 7E  ~.......~
2009-02-27T23:40:39.333557Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 0, type 0xEF, data[0] 
0xFFFFFFE3, len 4
2009-02-27T23:40:39.333564Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 0, type 0xE1, data[0] 
0x07, len 2
2009-02-27T23:40:39.333571Z: multiplexer.vala:561: 0710 -> deliver status 10 = 'FC CTS ' for channel 1
2009-02-27T23:40:39.333577Z: channel.vala:124: setSerialStatus()
2009-02-27T23:40:39.333581Z: multiplexer.vala:580: 0710 -> say 'received status line signal, sending response
2009-02-27T23:40:39.333587Z: multiplexer.vala:529: 0710 -> should write 9 bytes
2009-02-27T23:40:39.333599Z: consts.vala:76: >>> 7E 03 EF E1 05 07 0A 70 7E  ~......p~
2009-02-27T23:40:39.333662Z: multiplexer.vala:538: wrote 9/9 bytes to fd 4
2009-02-27T23:40:39.633522Z: multiplexer.vala:618: device_io_can_read for fd 4
2009-02-27T23:40:39.633540Z: multiplexer.vala:515: 0710 -> should read max 4095 bytes to 0x169080d
2009-02-27T23:40:39.633552Z: multiplexer.vala:520: read 9 bytes from fd 4
2009-02-27T23:40:39.633569Z: consts.vala:76: <<< 7E 01 FF E3 05 07 0A B6 7E  ~.......~
2009-02-27T23:40:39.633580Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 0, type 0xEF, data[0] 
0xFFFFFFE3, len 4
2009-02-27T23:40:39.633589Z: multiplexer.vala:580: 0710 -> say '0710 packet ok: chan 0, type 0xE1, data[0] 
0x07, len 2
2009-02-27T23:40:39.633596Z: multiplexer.vala:561: 0710 -> deliver status 10 = 'FC CTS ' for channel 1
2009-02-27T23:40:39.633602Z: channel.vala:124: setSerialStatus()
2009-02-27T23:40:39.633607Z: multiplexer.vala:580: 0710 -> say 'received status line signal, sending response
2009-02-27T23:40:39.633612Z: multiplexer.vala:529: 0710 -> should write 9 bytes
2009-02-27T23:40:39.633624Z: consts.vala:76: >>> 7E 03 EF E1 05 07 0A 70 7E  ~......p~
2009-02-27T23:40:39.633802Z: multiplexer.vala:538: wrote 9/9 bytes to fd 4





More information about the openmoko-kernel mailing list