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:
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
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
