Ticket #2223 (assigned defect)

Opened 10 years ago

Last modified 9 years ago

gsm0710muxd loosing packets?

Reported by: kapiteined Owned by: mickey
Priority: high Milestone: Om2008.12
Component: GSM Modem Version: unspecified
Severity: normal Keywords: gsm 07.10 multiplexer, flow control
Cc: Blocked By:
Blocking: Estimated Completion (week):
HasPatchForReview: no PatchReviewResult:
Reproducible:

Description

I use gsm0710muxd to make a GPRS connection and start a ssh tunnel to my home network.
if i start sending larger packets (ping -s 1400) the connection comes to a halt and no packets are forwarded any more.
If i stop gsm0710muxd and use /dev/ttySAC0 everything works fine. it seems like gsm0710muxd is loosing packets and my ssh tunnel becomes detached. the gprs connection itself stays intact.
As you can see from the ping log, the response times are increasing and then comes to a halt.

I read somewhere that a sillent buffer overflow was detected, so that might be my problem too. but i could not find a bug about that though.

I did run gsm0710muxd with the -v option and attached the log.
At 11:09:32 i stopped the connection manually.

Attachments

logread.txt (63.5 KB) - added by kapiteined 10 years ago.
logread dump
ping.log (978 bytes) - added by kapiteined 10 years ago.
log of ping times and loss
bad.log (13.0 KB) - added by kapiteined 10 years ago.
good.log (7.8 KB) - added by kapiteined 10 years ago.

Change History

Changed 10 years ago by kapiteined

logread dump

Changed 10 years ago by kapiteined

log of ping times and loss

comment:1 Changed 10 years ago by kapiteined

Hi,

Today (12 feb 2009) i took the code from the git repository and build gsm0710muxd.
it still does not work well with this version.

comment:2 Changed 10 years ago by mickey

Please flash moko11b1 firmware, this has an important fix with regards to flow control. gsm0710muxd is likely not the problem here.

Changed 10 years ago by kapiteined

Changed 10 years ago by kapiteined

comment:3 Changed 10 years ago by kapiteined

Hi mickey,

I did flash it. the flashing worked alright.
But the problem with the gprs connection is still there.
I make two logs, bad.log and good.log
with bad.log i use the /dev/pts/2 i get from the gsm0710muxd.
If i start pinging with larger packets ping times go up until the pings
stop.

with the good.log i use /dev/ttySAC0, after killing gsm0710muxd and qpe.
as you can see, the pingtimes are stable and not increasing much this time.

it still seems that i have high(er) packetloss when using gsm0710muxd.
and if parts of the retransmits are
lost too, i have retransmit on retransmit, until the connection chokes.

Thanks for the help so far !

Kind regards,
Ed

comment:4 Changed 10 years ago by mickey

This is with using my new multiplexer fso-abyss:

root@om-gta02:~# ping -s 1400 heise.de
PING heise.de (193.99.144.80): 1400 data bytes
1408 bytes from 193.99.144.80: seq=0 ttl=242 time=2521.968 ms
1408 bytes from 193.99.144.80: seq=1 ttl=242 time=2409.901 ms
1408 bytes from 193.99.144.80: seq=4 ttl=242 time=2801.211 ms
1408 bytes from 193.99.144.80: seq=5 ttl=242 time=2875.850 ms
1408 bytes from 193.99.144.80: seq=6 ttl=242 time=2401.183 ms
1408 bytes from 193.99.144.80: seq=7 ttl=242 time=1841.451 ms
1408 bytes from 193.99.144.80: seq=9 ttl=242 time=2391.964 ms
1408 bytes from 193.99.144.80: seq=10 ttl=242 time=2490.054 ms
1408 bytes from 193.99.144.80: seq=12 ttl=242 time=2407.468 ms
1408 bytes from 193.99.144.80: seq=13 ttl=242 time=2511.972 ms
1408 bytes from 193.99.144.80: seq=14 ttl=242 time=2332.015 ms
1408 bytes from 193.99.144.80: seq=15 ttl=242 time=2651.661 ms
1408 bytes from 193.99.144.80: seq=16 ttl=242 time=2761.595 ms
1408 bytes from 193.99.144.80: seq=17 ttl=242 time=2410.165 ms
1408 bytes from 193.99.144.80: seq=18 ttl=242 time=1848.718 ms
1408 bytes from 193.99.144.80: seq=20 ttl=242 time=2410.162 ms
1408 bytes from 193.99.144.80: seq=21 ttl=242 time=2891.949 ms
1408 bytes from 193.99.144.80: seq=23 ttl=242 time=2511.832 ms
1408 bytes from 193.99.144.80: seq=24 ttl=242 time=2647.290 ms
1408 bytes from 193.99.144.80: seq=25 ttl=242 time=2418.948 ms
1408 bytes from 193.99.144.80: seq=26 ttl=242 time=2434.499 ms
1408 bytes from 193.99.144.80: seq=29 ttl=242 time=2356.914 ms
1408 bytes from 193.99.144.80: seq=30 ttl=242 time=2422.326 ms
1408 bytes from 193.99.144.80: seq=31 ttl=242 time=1886.346 ms
1408 bytes from 193.99.144.80: seq=33 ttl=242 time=2420.823 ms
1408 bytes from 193.99.144.80: seq=34 ttl=242 time=2430.039 ms
1408 bytes from 193.99.144.80: seq=36 ttl=242 time=2516.453 ms
1408 bytes from 193.99.144.80: seq=37 ttl=242 time=2585.322 ms
1408 bytes from 193.99.144.80: seq=38 ttl=242 time=2393.405 ms
1408 bytes from 193.99.144.80: seq=39 ttl=242 time=2758.472 ms
1408 bytes from 193.99.144.80: seq=40 ttl=242 time=3319.996 ms
1408 bytes from 193.99.144.80: seq=41 ttl=242 time=2646.584 ms
1408 bytes from 193.99.144.80: seq=42 ttl=242 time=2393.595 ms
1408 bytes from 193.99.144.80: seq=43 ttl=242 time=2394.847 ms
1408 bytes from 193.99.144.80: seq=46 ttl=242 time=3319.976 ms
1408 bytes from 193.99.144.80: seq=47 ttl=242 time=2982.334 ms
1408 bytes from 193.99.144.80: seq=48 ttl=242 time=2654.863 ms
1408 bytes from 193.99.144.80: seq=49 ttl=242 time=2396.831 ms
1408 bytes from 193.99.144.80: seq=50 ttl=242 time=2415.035 ms
1408 bytes from 193.99.144.80: seq=53 ttl=242 time=1925.361 ms
1408 bytes from 193.99.144.80: seq=54 ttl=242 time=2395.551 ms
1408 bytes from 193.99.144.80: seq=55 ttl=242 time=1767.319 ms
1408 bytes from 193.99.144.80: seq=57 ttl=242 time=2397.221 ms
1408 bytes from 193.99.144.80: seq=58 ttl=242 time=2485.213 ms
1408 bytes from 193.99.144.80: seq=60 ttl=242 time=2384.111 ms
1408 bytes from 193.99.144.80: seq=61 ttl=242 time=2322.923 ms
1408 bytes from 193.99.144.80: seq=62 ttl=242 time=2315.131 ms
1408 bytes from 193.99.144.80: seq=63 ttl=242 time=2384.892 ms
1408 bytes from 193.99.144.80: seq=64 ttl=242 time=2389.788 ms
1408 bytes from 193.99.144.80: seq=65 ttl=242 time=2419.811 ms
1408 bytes from 193.99.144.80: seq=68 ttl=242 time=1900.657 ms
1408 bytes from 193.99.144.80: seq=69 ttl=242 time=2410.158 ms
1408 bytes from 193.99.144.80: seq=70 ttl=242 time=1810.339 ms
1408 bytes from 193.99.144.80: seq=72 ttl=242 time=2415.057 ms
1408 bytes from 193.99.144.80: seq=73 ttl=242 time=2411.042 ms

We're releasing milestone 5.1 in a couple of days which will ship it (albeit disabled by default, still using gsm0710muxd), so please have a go with that one.

comment:5 Changed 10 years ago by roh

  • Owner changed from julian_chu to Nytowl

maintainer change

comment:6 Changed 10 years ago by kapiteined

This is with using my new multiplexer fso-abyss:

root@om-gta02:~# ping -s 1400 heise.de
PING heise.de (193.99.144.80): 1400 data bytes
1408 bytes from 193.99.144.80: seq=0 ttl=242 time=2521.968 ms
1408 bytes from 193.99.144.80: seq=1 ttl=242 time=2409.901 ms

Missing reply 2 and 3

1408 bytes from 193.99.144.80: seq=4 ttl=242 time=2801.211 ms
1408 bytes from 193.99.144.80: seq=5 ttl=242 time=2875.850 ms
1408 bytes from 193.99.144.80: seq=6 ttl=242 time=2401.183 ms
1408 bytes from 193.99.144.80: seq=7 ttl=242 time=1841.451 ms

8 is also missing

1408 bytes from 193.99.144.80: seq=9 ttl=242 time=2391.964 ms
1408 bytes from 193.99.144.80: seq=10 ttl=242 time=2490.054 ms

And so is 11

1408 bytes from 193.99.144.80: seq=12 ttl=242 time=2407.468 ms
1408 bytes from 193.99.144.80: seq=13 ttl=242 time=2511.972 ms
1408 bytes from 193.99.144.80: seq=14 ttl=242 time=2332.015 ms
1408 bytes from 193.99.144.80: seq=15 ttl=242 time=2651.661 ms
1408 bytes from 193.99.144.80: seq=16 ttl=242 time=2761.595 ms
1408 bytes from 193.99.144.80: seq=17 ttl=242 time=2410.165 ms
1408 bytes from 193.99.144.80: seq=18 ttl=242 time=1848.718 ms

hey 19 is gone

1408 bytes from 193.99.144.80: seq=20 ttl=242 time=2410.162 ms
1408 bytes from 193.99.144.80: seq=21 ttl=242 time=2891.949 ms

what happened to 22?

1408 bytes from 193.99.144.80: seq=23 ttl=242 time=2511.832 ms
1408 bytes from 193.99.144.80: seq=24 ttl=242 time=2647.290 ms
1408 bytes from 193.99.144.80: seq=25 ttl=242 time=2418.948 ms
1408 bytes from 193.99.144.80: seq=26 ttl=242 time=2434.499 ms

27 and 28 on a holiday?

1408 bytes from 193.99.144.80: seq=29 ttl=242 time=2356.914 ms

etc

As you can see, some replies are lost, and because i build a ssh tunnel
(tcp) over the grps connection it will cause a retransmit.
And this will acumulate over time if the retransmits also loose packets.
i think that is why my ping times are increasing to the point where it
stops.

Kind regards,
Ed

comment:7 Changed 10 years ago by mickey

You're right, I didn't spot these losses. I don't think the packets are lost in the multiplexer though, I rather think it's too much for the modem to transmit. Needs further research.

comment:8 Changed 10 years ago by kapiteined

Might be the case, although without the multiplexer i don't have these losses. that is why i suspected the multiplexer in the first place.

Thanks for troubleshooting so far!

Kind regards,
Ed

comment:9 Changed 10 years ago by mickey

  • Owner changed from Nytowl to mickey
  • Status changed from new to assigned
  • Component changed from Distro to GSM Modem
  • Keywords gsm 07.10 multiplexer, flow control added
  • Priority changed from normal to high

I took some time to further analyse the problem. What I suspected was true -- the modem can't take the huge frames in multiplexing mode, it's too slow to process it. It doesn't happen in single mode since the processing load on the modem is less than in multiplexing mode. The good thing though is that the modem is actually telling us when it is fed up. The new multiplexer fso-abyss clearly shows that it sends us an 'FC' signal, when all its buffers are full. The real problem is that we do not honor this flag (we should stop sending data in that case until the 'FC' flag has been cleared again), but keep flooding the modem with data. This is what we have to fix to make it solid.

comment:10 Changed 10 years ago by kapiteined

Thanks mate!

Verry wel done indeed, i hope you will be able to implement this in the next release.

Kind regards,
Ed

comment:11 Changed 9 years ago by mickey

I have just released fso-abyss 0.3.3, which implements handling FC on virtual channels. If the modem tells us that it's overloaded, we pause reading from the incoming pty and forwarding to the modem. Unfortunately the situation does not improve a lot though as we're still missing 30% of packages. Ping times stay stable though. I'm afraid this is as good as it gets in multiplexing mode.

root@om-gta02:~# ping -s 1400 heise.de
PING heise.de (193.99.144.80): 1400 data bytes
1408 bytes from 193.99.144.80: seq=0 ttl=244 time=2316.521 ms
1408 bytes from 193.99.144.80: seq=1 ttl=244 time=2327.868 ms
1408 bytes from 193.99.144.80: seq=3 ttl=244 time=2714.493 ms
1408 bytes from 193.99.144.80: seq=4 ttl=244 time=2842.771 ms
1408 bytes from 193.99.144.80: seq=5 ttl=244 time=2423.056 ms
1408 bytes from 193.99.144.80: seq=6 ttl=244 time=1982.775 ms
1408 bytes from 193.99.144.80: seq=7 ttl=244 time=2278.681 ms
1408 bytes from 193.99.144.80: seq=8 ttl=244 time=2105.886 ms
1408 bytes from 193.99.144.80: seq=10 ttl=244 time=2324.001 ms
1408 bytes from 193.99.144.80: seq=11 ttl=244 time=1765.912 ms
1408 bytes from 193.99.144.80: seq=13 ttl=244 time=2302.947 ms
1408 bytes from 193.99.144.80: seq=14 ttl=244 time=2643.071 ms
1408 bytes from 193.99.144.80: seq=17 ttl=244 time=2305.379 ms
1408 bytes from 193.99.144.80: seq=18 ttl=244 time=2559.822 ms
1408 bytes from 193.99.144.80: seq=20 ttl=244 time=3317.812 ms
1408 bytes from 193.99.144.80: seq=21 ttl=244 time=2543.438 ms
1408 bytes from 193.99.144.80: seq=22 ttl=244 time=2076.930 ms
1408 bytes from 193.99.144.80: seq=23 ttl=244 time=2334.724 ms
1408 bytes from 193.99.144.80: seq=24 ttl=244 time=2227.979 ms
1408 bytes from 193.99.144.80: seq=26 ttl=244 time=2919.540 ms
1408 bytes from 193.99.144.80: seq=27 ttl=244 time=2392.641 ms
1408 bytes from 193.99.144.80: seq=28 ttl=244 time=1898.725 ms
1408 bytes from 193.99.144.80: seq=29 ttl=244 time=1986.046 ms
1408 bytes from 193.99.144.80: seq=30 ttl=244 time=2342.832 ms
1408 bytes from 193.99.144.80: seq=31 ttl=244 time=1783.018 ms
1408 bytes from 193.99.144.80: seq=33 ttl=244 time=2334.830 ms
1408 bytes from 193.99.144.80: seq=34 ttl=244 time=1764.226 ms
1408 bytes from 193.99.144.80: seq=36 ttl=244 time=2400.281 ms
1408 bytes from 193.99.144.80: seq=37 ttl=244 time=1843.098 ms
1408 bytes from 193.99.144.80: seq=38 ttl=244 time=1970.256 ms
1408 bytes from 193.99.144.80: seq=39 ttl=244 time=2257.258 ms
1408 bytes from 193.99.144.80: seq=40 ttl=244 time=2297.496 ms
1408 bytes from 193.99.144.80: seq=41 ttl=244 time=2343.043 ms
1408 bytes from 193.99.144.80: seq=43 ttl=244 time=2567.716 ms
1408 bytes from 193.99.144.80: seq=44 ttl=244 time=2703.397 ms
1408 bytes from 193.99.144.80: seq=45 ttl=244 time=2318.970 ms
1408 bytes from 193.99.144.80: seq=46 ttl=244 time=3375.201 ms
1408 bytes from 193.99.144.80: seq=48 ttl=244 time=3772.943 ms
1408 bytes from 193.99.144.80: seq=50 ttl=244 time=3394.475 ms
1408 bytes from 193.99.144.80: seq=51 ttl=244 time=3787.687 ms
1408 bytes from 193.99.144.80: seq=55 ttl=244 time=2384.851 ms
1408 bytes from 193.99.144.80: seq=56 ttl=244 time=3277.650 ms
1408 bytes from 193.99.144.80: seq=58 ttl=244 time=2437.990 ms
1408 bytes from 193.99.144.80: seq=59 ttl=244 time=2502.766 ms
1408 bytes from 193.99.144.80: seq=60 ttl=244 time=2325.132 ms
1408 bytes from 193.99.144.80: seq=61 ttl=244 time=2615.389 ms
1408 bytes from 193.99.144.80: seq=64 ttl=244 time=2363.622 ms
1408 bytes from 193.99.144.80: seq=65 ttl=244 time=3732.000 ms
1408 bytes from 193.99.144.80: seq=66 ttl=244 time=3350.878 ms
1408 bytes from 193.99.144.80: seq=67 ttl=244 time=3959.354 ms
1408 bytes from 193.99.144.80: seq=68 ttl=244 time=4008.114 ms
1408 bytes from 193.99.144.80: seq=71 ttl=244 time=3355.381 ms
1408 bytes from 193.99.144.80: seq=72 ttl=244 time=3916.634 ms
1408 bytes from 193.99.144.80: seq=73 ttl=244 time=3954.284 ms
1408 bytes from 193.99.144.80: seq=76 ttl=244 time=2997.926 ms
1408 bytes from 193.99.144.80: seq=77 ttl=244 time=3652.744 ms
1408 bytes from 193.99.144.80: seq=78 ttl=244 time=3765.881 ms
1408 bytes from 193.99.144.80: seq=79 ttl=244 time=3392.738 ms
1408 bytes from 193.99.144.80: seq=80 ttl=244 time=2947.989 ms
1408 bytes from 193.99.144.80: seq=81 ttl=244 time=2442.889 ms
1408 bytes from 193.99.144.80: seq=82 ttl=244 time=1949.540 ms
1408 bytes from 193.99.144.80: seq=83 ttl=244 time=2572.841 ms
1408 bytes from 193.99.144.80: seq=84 ttl=244 time=2306.575 ms
1408 bytes from 193.99.144.80: seq=85 ttl=244 time=2162.662 ms
1408 bytes from 193.99.144.80: seq=87 ttl=244 time=2462.885 ms
1408 bytes from 193.99.144.80: seq=88 ttl=244 time=2607.891 ms
1408 bytes from 193.99.144.80: seq=89 ttl=244 time=2301.532 ms
1408 bytes from 193.99.144.80: seq=90 ttl=244 time=3337.746 ms
1408 bytes from 193.99.144.80: seq=92 ttl=244 time=3369.255 ms
1408 bytes from 193.99.144.80: seq=94 ttl=244 time=3605.355 ms
1408 bytes from 193.99.144.80: seq=98 ttl=244 time=2323.780 ms
1408 bytes from 193.99.144.80: seq=99 ttl=244 time=3593.060 ms
1408 bytes from 193.99.144.80: seq=101 ttl=244 time=3329.190 ms
1408 bytes from 193.99.144.80: seq=102 ttl=244 time=3432.794 ms
1408 bytes from 193.99.144.80: seq=103 ttl=244 time=2981.716 ms
1408 bytes from 193.99.144.80: seq=105 ttl=244 time=2331.526 ms
1408 bytes from 193.99.144.80: seq=106 ttl=244 time=1768.243 ms
1408 bytes from 193.99.144.80: seq=108 ttl=244 time=2315.895 ms
1408 bytes from 193.99.144.80: seq=109 ttl=244 time=2695.941 ms
1408 bytes from 193.99.144.80: seq=112 ttl=244 time=2303.161 ms
1408 bytes from 193.99.144.80: seq=113 ttl=244 time=2582.927 ms
1408 bytes from 193.99.144.80: seq=115 ttl=244 time=3291.146 ms
1408 bytes from 193.99.144.80: seq=117 ttl=244 time=2103.509 ms
1408 bytes from 193.99.144.80: seq=119 ttl=244 time=2308.521 ms
1408 bytes from 193.99.144.80: seq=120 ttl=244 time=1697.625 ms
1408 bytes from 193.99.144.80: seq=122 ttl=244 time=2297.846 ms
1408 bytes from 193.99.144.80: seq=123 ttl=244 time=2594.404 ms
1408 bytes from 193.99.144.80: seq=126 ttl=244 time=2266.765 ms
1408 bytes from 193.99.144.80: seq=127 ttl=244 time=2682.942 ms
1408 bytes from 193.99.144.80: seq=128 ttl=244 time=2142.829 ms
1408 bytes from 193.99.144.80: seq=129 ttl=244 time=3288.996 ms
1408 bytes from 193.99.144.80: seq=130 ttl=244 time=2567.394 ms
1408 bytes from 193.99.144.80: seq=131 ttl=244 time=2096.869 ms
1408 bytes from 193.99.144.80: seq=132 ttl=244 time=2344.162 ms
1408 bytes from 193.99.144.80: seq=133 ttl=244 time=2520.693 ms
1408 bytes from 193.99.144.80: seq=135 ttl=244 time=2923.189 ms
1408 bytes from 193.99.144.80: seq=136 ttl=244 time=2343.847 ms
1408 bytes from 193.99.144.80: seq=137 ttl=244 time=2203.397 ms
1408 bytes from 193.99.144.80: seq=139 ttl=244 time=2374.293 ms
1408 bytes from 193.99.144.80: seq=140 ttl=244 time=1804.944 ms
1408 bytes from 193.99.144.80: seq=141 ttl=244 time=1918.291 ms
1408 bytes from 193.99.144.80: seq=142 ttl=244 time=2299.653 ms
1408 bytes from 193.99.144.80: seq=143 ttl=244 time=1712.856 ms
1408 bytes from 193.99.144.80: seq=145 ttl=244 time=2307.461 ms
1408 bytes from 193.99.144.80: seq=146 ttl=244 time=2669.165 ms
1408 bytes from 193.99.144.80: seq=149 ttl=244 time=2278.222 ms
1408 bytes from 193.99.144.80: seq=150 ttl=244 time=3142.857 ms
1408 bytes from 193.99.144.80: seq=152 ttl=244 time=3333.898 ms
1408 bytes from 193.99.144.80: seq=153 ttl=244 time=2570.146 ms
1408 bytes from 193.99.144.80: seq=154 ttl=244 time=2073.336 ms
^C
--- heise.de ping statistics ---
158 packets transmitted, 110 packets received, 30% packet loss
round-trip min/avg/max = 1697.625/2615.688/4008.114 ms

comment:12 Changed 9 years ago by kapiteined

Hi mickey,

Thanks a lot for your effort!
I hope i am able to test it later this weekend.
As you said already, i don't think it will help my situation a lot,
so i have to find another way of working around this bug.

Thank you so much for your good work, i really appreciate it.
Kind regards,
Ed

Note: See TracTickets for help on using tickets.