Re: unexpected pdp ctx deactivation
Hi Alexey, Il giorno mer 31 ago 2022 alle ore 14:43 Alexey Orishko ha scritto: > > Hi, > > I'm implementing ecm support in telit plugin (baseline: latest main). if it's not a reserved piece of information, which Telit model are you using? Regards, Daniele > Somehow modem goes in connect-disconnect loop with a few seconds in between. > I'm trying to identify a reason for disconnect and related issues in MM debug > log. > > Q1. Is a negative value in profile_id (and eventually in > index_field_value_str) a legal one? > Does a negative value mean uninitialized data in profile context? Coz CGACT > output has always positive ctx index: > AT+CGACT? > +CGACT: 1,1 > +CGACT: 3,0 > > ModemManager[]: [1661944714.481355] [modem0] set profile state (3/8): > select profile (best) > ModemManager[]: [1661944714.481370] [modem0] found exact context at > profile 1 > ModemManager[]: [1661944714.481375] [modem0] reusing profile '1' > ModemManager[]: [1661944714.481379] [modem0] set profile state (4/8): > check activated profile > ModemManager[]: [1661944714.481390] [modem0] checking if profile with > id '1' is already activated... > ModemManager[]: [1661944714.481402] [ttyUSB1/at] device open count is > 4 (open) > ModemManager[]: [1661944714.481418] [ttyUSB1/at] device open count is > 3 (close) > ModemManager[]: [1661944714.481436] [ttyUSB1/at] --> 'AT+CGACT?' > ModemManager[]: [1661944714.518369] [ttyUSB1/at] <-- '+CGACT: > 1,1+CGACT: 3,0OK' > ModemManager[]: [1661944714.518463] [modem0] profile '-1' is activated > ModemManager[]: [1661944714.518479] [modem0] set profile state (5/8): > deactivate profile > ModemManager[]: [1661944714.518488] [modem0] deactivating profile > with id '1'... > ModemManager[]: [1661944714.518502] [ttyUSB1/at] device open count is > 4 (open) > ModemManager[]: [1661944714.518519] [ttyUSB1/at] device open count is > 3 (close) > ModemManager[]: [1661944714.518540] [ttyUSB1/at] --> > 'AT+CGACT=0,1' > ModemManager[]: [1661944714.561517] [ttyUSB1/at] <-- > 'OK' > ModemManager[]: [1661944714.561599] [modem0] deactivated profile '-1' > ModemManager[]: [1661944714.561610] [modem0] set profile state (6/8): > profile already stored > ModemManager[]: [1661944714.561616] [modem0] set profile state (8/8): > all done > ModemManager[]: [1661944714.561639] [modem0/bearer0] (shared-telit) > ECM: selecting NW interface as a data port > ModemManager[]: [1661944714.561664] [ttyUSB1/at] device open count is > 2 (close) > ModemManager[]: [1661944714.561700] [modem0/wwan0/net] port now > connected > ModemManager[]: [1661944714.561707] [modem0/bearer0] connected > ModemManager[]: [1661944714.561776] [modem0] state changed > (connecting -> connected) > ModemManager[]: [1661944714.562088] [modem0] simple connect state > (10/10): all done > ModemManager[]: [1661944730.307060] [modem0] user request to > disconnect modem (all bearers) > > > Q2: Since no mmcli or any other human input was used, what the phrase "user > request to disconnect modem" really mean? > Could internal MM logic be considered as "user input"? > > Q3. Will MM always tear down existing pdp context instead of reusing it? > (even if all parameters are the same) > Q4: If answer to Q3 is yes, is there a way to force MM always reusing > existing pdp context? (at least as a private patch) > > Regards, > Alexey >
Re: unexpected pdp ctx deactivation
> > I'm implementing ecm support in telit plugin (baseline: latest main). > > Somehow modem goes in connect-disconnect loop with a few seconds in between. > > I'm trying to identify a reason for disconnect and related issues in MM > > debug log. > > > > Q1. Is a negative value in profile_id (and eventually in > > index_field_value_str) a legal one? > > Does a negative value mean uninitialized data in profile context? Coz CGACT > > output has always positive ctx index: > > AT+CGACT? > > +CGACT: 1,1 > > +CGACT: 3,0 > > > > ModemManager[]: [1661944714.481355] [modem0] set profile state > > (3/8): select profile (best) > > ModemManager[]: [1661944714.481370] [modem0] found exact context at > > profile 1 > > ModemManager[]: [1661944714.481375] [modem0] reusing profile '1' > > ModemManager[]: [1661944714.481379] [modem0] set profile state > > (4/8): check activated profile > > ModemManager[]: [1661944714.481390] [modem0] checking if profile > > with id '1' is already activated... > > ModemManager[]: [1661944714.481402] [ttyUSB1/at] device open count > > is 4 (open) > > ModemManager[]: [1661944714.481418] [ttyUSB1/at] device open count > > is 3 (close) > > ModemManager[]: [1661944714.481436] [ttyUSB1/at] --> 'AT+CGACT?' > > ModemManager[]: [1661944714.518369] [ttyUSB1/at] <-- > > '+CGACT: 1,1+CGACT: 3,0OK' > > ModemManager[]: [1661944714.518463] [modem0] profile '-1' is > > activated > > ModemManager[]: [1661944714.518479] [modem0] set profile state > > (5/8): deactivate profile > > ModemManager[]: [1661944714.518488] [modem0] deactivating profile > > with id '1'... > > ModemManager[]: [1661944714.518502] [ttyUSB1/at] device open count > > is 4 (open) > > ModemManager[]: [1661944714.518519] [ttyUSB1/at] device open count > > is 3 (close) > > ModemManager[]: [1661944714.518540] [ttyUSB1/at] --> > > 'AT+CGACT=0,1' > > ModemManager[]: [1661944714.561517] [ttyUSB1/at] <-- > > 'OK' > > ModemManager[]: [1661944714.561599] [modem0] deactivated profile > > '-1' > > ModemManager[]: [1661944714.561610] [modem0] set profile state > > (6/8): profile already stored > > ModemManager[]: [1661944714.561616] [modem0] set profile state > > (8/8): all done > > ModemManager[]: [1661944714.561639] [modem0/bearer0] (shared-telit) > > ECM: selecting NW interface as a data port > > ModemManager[]: [1661944714.561664] [ttyUSB1/at] device open count > > is 2 (close) > > ModemManager[]: [1661944714.561700] [modem0/wwan0/net] port now > > connected > > ModemManager[]: [1661944714.561707] [modem0/bearer0] connected > > ModemManager[]: [1661944714.561776] [modem0] state changed > > (connecting -> connected) > > ModemManager[]: [1661944714.562088] [modem0] simple connect state > > (10/10): all done > > ModemManager[]: [1661944730.307060] [modem0] user request to > > disconnect modem (all bearers) > > > > Is this recent change somehow related maybe? > https://gitlab.freedesktop.org/mobile-broadband/ModemManager/-/merge_requests/829 > > > > > Q2: Since no mmcli or any other human input was used, what the phrase "user > > request to disconnect modem" really mean? > > Could internal MM logic be considered as "user input"? > > > > Humm... that message should exclusively happen when a > Modem.Simple.Disconnect() DBus call arrives, that's why it's "user > input". > > > Q3. Will MM always tear down existing pdp context instead of reusing it? > > (even if all parameters are the same) > > The answer, I'm afraid, is "it depends". The MBIM implementation > ensures the profile is disconnected before attempting a new > connection, while other implementations don't do that, they try to > launch a new connection even if it was already up, letting the modem > return an error if it's appropriate. The thing is, MM doesn't expect > any PDP context to be up (ideally) if it didn´t bring it up MM itself. > The most notable cases where this is not true is with initial default > EPS bearers (attach bearers) which may be exposed as being up before > triggering any new connection (and some implementations like the ones > for u-blox TOBY modules try to handle that gracefully, because > attempting to disconnect them would result in de-registering from the > network), and also with "autoconnected" modems, where the data bearer > is brought up by the modem itself automatically (and there is no > general way to handle those yet anywhere really) > Actually... I'm a bit wrong here. There is some generic logic to deactivate a profile before setting it up again in the 3GPP manager "set profile" sequence, which is used when the user didn't specify a given "profile-id" to use. See e.g. select_profile_3gpp() in mm-broadband-bearer.c (applicable to all AT modems) and the set_profile_step() method in mm-iface-modem-3gpp-profile-manager.c -- Aleksander
Re: unexpected pdp ctx deactivation
Hey Alexey, > I'm implementing ecm support in telit plugin (baseline: latest main). > Somehow modem goes in connect-disconnect loop with a few seconds in between. > I'm trying to identify a reason for disconnect and related issues in MM debug > log. > > Q1. Is a negative value in profile_id (and eventually in > index_field_value_str) a legal one? > Does a negative value mean uninitialized data in profile context? Coz CGACT > output has always positive ctx index: > AT+CGACT? > +CGACT: 1,1 > +CGACT: 3,0 > > ModemManager[]: [1661944714.481355] [modem0] set profile state (3/8): > select profile (best) > ModemManager[]: [1661944714.481370] [modem0] found exact context at > profile 1 > ModemManager[]: [1661944714.481375] [modem0] reusing profile '1' > ModemManager[]: [1661944714.481379] [modem0] set profile state (4/8): > check activated profile > ModemManager[]: [1661944714.481390] [modem0] checking if profile with > id '1' is already activated... > ModemManager[]: [1661944714.481402] [ttyUSB1/at] device open count is > 4 (open) > ModemManager[]: [1661944714.481418] [ttyUSB1/at] device open count is > 3 (close) > ModemManager[]: [1661944714.481436] [ttyUSB1/at] --> 'AT+CGACT?' > ModemManager[]: [1661944714.518369] [ttyUSB1/at] <-- '+CGACT: > 1,1+CGACT: 3,0OK' > ModemManager[]: [1661944714.518463] [modem0] profile '-1' is activated > ModemManager[]: [1661944714.518479] [modem0] set profile state (5/8): > deactivate profile > ModemManager[]: [1661944714.518488] [modem0] deactivating profile > with id '1'... > ModemManager[]: [1661944714.518502] [ttyUSB1/at] device open count is > 4 (open) > ModemManager[]: [1661944714.518519] [ttyUSB1/at] device open count is > 3 (close) > ModemManager[]: [1661944714.518540] [ttyUSB1/at] --> > 'AT+CGACT=0,1' > ModemManager[]: [1661944714.561517] [ttyUSB1/at] <-- > 'OK' > ModemManager[]: [1661944714.561599] [modem0] deactivated profile '-1' > ModemManager[]: [1661944714.561610] [modem0] set profile state (6/8): > profile already stored > ModemManager[]: [1661944714.561616] [modem0] set profile state (8/8): > all done > ModemManager[]: [1661944714.561639] [modem0/bearer0] (shared-telit) > ECM: selecting NW interface as a data port > ModemManager[]: [1661944714.561664] [ttyUSB1/at] device open count is > 2 (close) > ModemManager[]: [1661944714.561700] [modem0/wwan0/net] port now > connected > ModemManager[]: [1661944714.561707] [modem0/bearer0] connected > ModemManager[]: [1661944714.561776] [modem0] state changed > (connecting -> connected) > ModemManager[]: [1661944714.562088] [modem0] simple connect state > (10/10): all done > ModemManager[]: [1661944730.307060] [modem0] user request to > disconnect modem (all bearers) > Is this recent change somehow related maybe? https://gitlab.freedesktop.org/mobile-broadband/ModemManager/-/merge_requests/829 > > Q2: Since no mmcli or any other human input was used, what the phrase "user > request to disconnect modem" really mean? > Could internal MM logic be considered as "user input"? > Humm... that message should exclusively happen when a Modem.Simple.Disconnect() DBus call arrives, that's why it's "user input". > Q3. Will MM always tear down existing pdp context instead of reusing it? > (even if all parameters are the same) The answer, I'm afraid, is "it depends". The MBIM implementation ensures the profile is disconnected before attempting a new connection, while other implementations don't do that, they try to launch a new connection even if it was already up, letting the modem return an error if it's appropriate. The thing is, MM doesn't expect any PDP context to be up (ideally) if it didn´t bring it up MM itself. The most notable cases where this is not true is with initial default EPS bearers (attach bearers) which may be exposed as being up before triggering any new connection (and some implementations like the ones for u-blox TOBY modules try to handle that gracefully, because attempting to disconnect them would result in de-registering from the network), and also with "autoconnected" modems, where the data bearer is brought up by the modem itself automatically (and there is no general way to handle those yet anywhere really) -- Aleksander
unexpected pdp ctx deactivation
Hi, I'm implementing ecm support in telit plugin (baseline: latest main). Somehow modem goes in connect-disconnect loop with a few seconds in between. I'm trying to identify a reason for disconnect and related issues in MM debug log. Q1. Is a negative value in profile_id (and eventually in index_field_value_str) a legal one? Does a negative value mean uninitialized data in profile context? Coz CGACT output has always positive ctx index: AT+CGACT? +CGACT: 1,1 +CGACT: 3,0 ModemManager[]: [1661944714.481355] [modem0] set profile state (3/8): select profile (best) ModemManager[]: [1661944714.481370] [modem0] *found exact context at profile 1* ModemManager[]: [1661944714.481375] [modem0] *reusing profile '1'* ModemManager[]: [1661944714.481379] [modem0] set profile state (4/8): check activated profile ModemManager[]: [1661944714.481390] [modem0] checking if profile with id '1' is already activated... ModemManager[]: [1661944714.481402] [ttyUSB1/at] device open count is 4 (open) ModemManager[]: [1661944714.481418] [ttyUSB1/at] device open count is 3 (close) ModemManager[]: [1661944714.481436] [ttyUSB1/at] --> 'AT+CGACT?' ModemManager[]: [1661944714.518369] [ttyUSB1/at] <-- '+CGACT: 1,1+CGACT: 3,0OK' ModemManager[]: [1661944714.518463] [modem0] *profile '-1' is activated* ModemManager[]: [1661944714.518479] [modem0] set profile state (5/8): deactivate profile ModemManager[]: [1661944714.518488] [modem0] *deactivating profile with id '1'*... ModemManager[]: [1661944714.518502] [ttyUSB1/at] device open count is 4 (open) ModemManager[]: [1661944714.518519] [ttyUSB1/at] device open count is 3 (close) ModemManager[]: [1661944714.518540] [ttyUSB1/at] --> 'AT+CGACT=0,1' ModemManager[]: [1661944714.561517] [ttyUSB1/at] <-- 'OK' ModemManager[]: [1661944714.561599] [modem0] *deactivated profile '-1'* ModemManager[]: [1661944714.561610] [modem0] set profile state (6/8): profile already stored ModemManager[]: [1661944714.561616] [modem0] set profile state (8/8): all done ModemManager[]: [1661944714.561639] [modem0/bearer0] (shared-telit) ECM: selecting NW interface as a data port ModemManager[]: [1661944714.561664] [ttyUSB1/at] device open count is 2 (close) ModemManager[]: [1661944714.561700] *[modem0/wwan0/net] port now connected* ModemManager[]: [1661944714.561707] *[modem0/bearer0] connected* ModemManager[]: [1661944714.561776] [modem0] state changed (connecting -> connected) ModemManager[]: [1661944714.562088] [modem0] simple connect state (10/10): all done ModemManager[]: [1661944730.307060] [modem0] *user request to disconnect modem* (all bearers) Q2: Since no mmcli or any other human input was used, what the phrase "user request to disconnect modem*"* really mean? Could internal MM logic be considered as "user input"? Q3. Will MM always tear down existing pdp context instead of reusing it? (even if all parameters are the same) Q4: If answer to Q3 is yes, is there a way to force MM always reusing existing pdp context? (at least as a private patch) Regards, Alexey
