1046054 - RIL is leaking rmnet connections

Status: RESOLVED INCOMPLETE

(Firefox OS Graveyard :: RIL, defect)

Description

[:gerard-majax]

Hacking on stuff on my Nexus S running master, I noticed some cases where we badly leak data connections that are up. I'm wondering how much this may explain some difficulties to get data up when getting out of the subway, for example.

STR:
 0. Make sure you have data up, confirm with |adb shell netcfg|
 1. adb shell stop b2g
 2. adb shell start b2g

Expected:
 Between 1. and 2., we should have no more rmnet connection up.

Actual:
 We still have rmnet connection up.

I noticed several symptoms/consequences to this:
 - on next data call, we will get rmnet1 up
 - it may take a while to get back data up when b2g restarts this way, since rild/radio will properly setup a new data call but gecko seems to lose a bit its head
 - it seems to mess up with routing: when I reproduced this, I had rmnet0, rmnet1 and sometimes rmnet2 up, and no data was working at all

Comment 1

[Anthony Ricaud (:rik)]

Alexandre suspects this could be the cause of not being able to use data when you get out of a tunnel, a subway, a building, etc… Marking as a dogfooding issue.

Comment 2

[:gerard-majax]

Other STR:
 0. Enable data
 1. Check with |adb shell netcfg|
 2. Disable data

Expected:
 netcfg shows no more interface up

Actual:
 It can take 30 secs or more to bring the interface down

Comment 3

[Jessica Jong [:jessica] (inactive)]

Hi, may I know what version of ril is this?

These are some information I'd like to share with you:
- When b2g is stopped, there is not enough time for gecko ril to disconnect the data call, so I think it's normal that you see rmnet0 still up.
- Every time b2g is (re)started and gecko ril gets connected with rild, there is a sequence of radio off and radio on (if airplane mode is disabled). So, when radio is turned off, that existing data call should get disconnected. Gecko ril will set up a new data call when radio is on and data registration is back again. That's why you may find delay in getting your data back.
- rild/radio does not, or is not supposed to, setup a new data call, data calls should be initiated by upper layer.

I have followed the STR and found data call back to normal, with rmnet0 up again. Can you reproduce it all the time?
About not being able to use data when you get out of a tunnel, a subway, a building, etc, I think it should be another issue, I had a fix in Bug 1030810, do you still see this after 1030810?

Thanks.

Comment 4

[:gerard-majax]

(In reply to Jessica Jong [:jjong] [:jessica] from comment #3)
> Hi, may I know what version of ril is this?

Not sure what you want to know, it's Nexus S running current master.

> 
> These are some information I'd like to share with you:
> - When b2g is stopped, there is not enough time for gecko ril to disconnect
> the data call, so I think it's normal that you see rmnet0 still up.

Do we at least issue a disconnect, even if we do not wait for it to finish because we cannot ?

> - Every time b2g is (re)started and gecko ril gets connected with rild,
> there is a sequence of radio off and radio on (if airplane mode is
> disabled). So, when radio is turned off, that existing data call should get
> disconnected. Gecko ril will set up a new data call when radio is on and
> data registration is back again. That's why you may find delay in getting
> your data back.

That is not what I saw looking at radio buffer logcat: I saw a new data call being issues but gecko not seeing it for a while.

> - rild/radio does not, or is not supposed to, setup a new data call, data
> calls should be initiated by upper layer.

You misundertood my point: gecko issue a data call, radio does it properly, and a new interface is up.

> 
> I have followed the STR and found data call back to normal, with rmnet0 up
> again. Can you reproduce it all the time?

Yes.

> About not being able to use data when you get out of a tunnel, a subway, a
> building, etc, I think it should be another issue, I had a fix in Bug
> 1030810, do you still see this after 1030810?

Again, this is uptodate master, so it includes this patch.

> 
> Thanks.

Comment 5

[Jessica Jong [:jessica] (inactive)]

(In reply to Alexandre LISSY :gerard-majax from comment #4)
> (In reply to Jessica Jong [:jjong] [:jessica] from comment #3)
> > Hi, may I know what version of ril is this?
> 
> Not sure what you want to know, it's Nexus S running current master.
> 
> > 
> > These are some information I'd like to share with you:
> > - When b2g is stopped, there is not enough time for gecko ril to disconnect
> > the data call, so I think it's normal that you see rmnet0 still up.
> 
> Do we at least issue a disconnect, even if we do not wait for it to finish
> because we cannot ?

No, not for now. Is there a way to know when b2g is going down like this?

> 
> > - Every time b2g is (re)started and gecko ril gets connected with rild,
> > there is a sequence of radio off and radio on (if airplane mode is
> > disabled). So, when radio is turned off, that existing data call should get
> > disconnected. Gecko ril will set up a new data call when radio is on and
> > data registration is back again. That's why you may find delay in getting
> > your data back.
> 
> That is not what I saw looking at radio buffer logcat: I saw a new data call
> being issues but gecko not seeing it for a while.

From the radio buffer logcat, can you see when the response of setting up data call came back? It seems that your radio is taking very long in setting-up/disconnecting data calls, cause I am not able to reproduce the issue in comment 2 either. That might explain why new data calls are setting up on network interfaces other than rmnet0.

> 
> > - rild/radio does not, or is not supposed to, setup a new data call, data
> > calls should be initiated by upper layer.
> 
> You misundertood my point: gecko issue a data call, radio does it properly,
> and a new interface is up.
> 
> > 
> > I have followed the STR and found data call back to normal, with rmnet0 up
> > again. Can you reproduce it all the time?
> 
> Yes.
> 
> > About not being able to use data when you get out of a tunnel, a subway, a
> > building, etc, I think it should be another issue, I had a fix in Bug
> > 1030810, do you still see this after 1030810?
> 
> Again, this is uptodate master, so it includes this patch.
> 
> > 
> > Thanks.

It'd be great if you can provide logs with radio log enabled and with timestamps, so that we can find out what is going on. Thanks.

Comment 6

[:gerard-majax]

Okay, I could get some radio logs:

> 07-31 19:02:47.152    80   158 E RIL(s)  : request pdp0 disconnected

That's right when disabling data in Gaia's UI.

Then,
> 07-31 19:03:04.847    80   158 E RIL(s)  : deactivating rmnet0 interface.. 

And after a couple of seconds, rmnet0 finally disappears.

Comment 7

[Jessica Jong [:jessica] (inactive)]

(In reply to Alexandre LISSY :gerard-majax from comment #6)
> Okay, I could get some radio logs:
> 
> > 07-31 19:02:47.152    80   158 E RIL(s)  : request pdp0 disconnected
> 
> That's right when disabling data in Gaia's UI.
> 
> Then,
> > 07-31 19:03:04.847    80   158 E RIL(s)  : deactivating rmnet0 interface.. 
> 
> And after a couple of seconds, rmnet0 finally disappears.

Thanks for the logs. These lines seem to be printed from rild or below, and it took at least 17 seconds for modem to deactivate the data call. This latency is much longer than usual (less than 1 second in my case), and we still need to add the time needed from gaia -> gecko -> rild and back. Have you tried on other devices?

Comment 8

[:gerard-majax]

(In reply to Jessica Jong [:jjong] [:jessica] from comment #7)
> (In reply to Alexandre LISSY :gerard-majax from comment #6)
> > Okay, I could get some radio logs:
> > 
> > > 07-31 19:02:47.152    80   158 E RIL(s)  : request pdp0 disconnected
> > 
> > That's right when disabling data in Gaia's UI.
> > 
> > Then,
> > > 07-31 19:03:04.847    80   158 E RIL(s)  : deactivating rmnet0 interface.. 
> > 
> > And after a couple of seconds, rmnet0 finally disappears.
> 
> Thanks for the logs. These lines seem to be printed from rild or below, and
> it took at least 17 seconds for modem to deactivate the data call. This
> latency is much longer than usual (less than 1 second in my case), and we
> still need to add the time needed from gaia -> gecko -> rild and back. Have
> you tried on other devices?

No, I don't have data on the SIM card in my other devices, and I don't have all of them with me. Right now I just reproduced another similar instance of this issue, but I don't have logs (we really need to be able to enable RIL logging from Settings, this is painful to do each time).

Namely, Gecko setup a data connection, it worked for a couple of minutes and then rmnet0 was down and no IP address but Gecko was still showing the "H" icon.

Comment 9

[:gerard-majax]

I'm going to soon drop Nexus S, so ...