Cinterion radio bands

Wed May 20 11:03:49 UTC 2020

Hey Aleksander,

thank you for your answer.

On Wed, May 20, 2020 at 11:37 AM Aleksander Morgado
<aleksander at aleksander.es> wrote:
>
> Hey Giacinto,
>
> > I have finally submitted a merge request for the band reading and
> > setting for Cinterion Modems.
> >
> > Not sure whether is it good quality, thou. I would appreciate a review
> > and comments.
> > Starting for example from the naming of the udev variable, and then
> > the use of other variables to track formats, and the existing 2g/3g
> > one, also used for differentiating models.
> > I am wondering if there is a smart way to reduce all these variables
> > and corresponding if()'s to something more structured.
> >
> > Apart from that, the code works.
> > The Band setting also goes well, but...
> > 1) the command is veeeerry slow (about 30-50 seconds) on PLS62, but
> > there seems to be a problem with MM itself, because I have set a
> > timeout to 3 minutes, and sometimes MM still times out, but the
> > command has already succeeded and the bands are changed.
> >     Any idea why the command would timeout? is there a maximum timeout
> > that MM would tolerate? How to go round this limitation?
>
> Are you testing this with mmcli? If so, mmcli has a default timeout
> for the DBus requests of 30s. If you believe a command you run may
> take longer, you need to use --timeout to explicitly request a longer
> timeout of the mmcli command. The mmcli timeout is orthogonal to the
> actual AT command timeout; so even if you configure the AT command to
> timeout at 120s, the mmcli command may timeout earlier for the user
> (but the AT command would still be running in MM until the 120s
> timeout).
>

I prefer d-feet (under Ubuntu) for unit tests, because it shows me all
options and I am sure I am making a single dbus call, so that I have a
fine control on the sequence.
Nevertheless, you are right: it seems to be a timeout on the client side.

>
> >     It looks like that the PLS62 applies the bands at once, rescans
> > (so also it de-registers and re-registers), and I think this is the
> > reason why it is slow.
> >
>
> Possibly. In this case, we need to make sure we reload registration
> settings after setting bands. I believe this is already the case, but
> we should recheck.

it looks like it re-reads the current bands, but not the registration
status & co. See trace below.

>
> > 2) If I reduce the current mask, say from
> > [1,2,3,4,5,7,9,10,11,12,31,32,33,34,35,37,38,42,48,49,50,58,219]
> > to     [1,2,10,11,12,48,49,50,58], and I re-read the CurrentBands
> > property, a realloc fails and MM crashes.
>
> Oh? the daemon crashes? How are you reading the properties, via custom
> DBus commands?

d-feet uses the standard GetProperty when it recognizes the
properties, as it is the case for ModemManager.
But looking at the timestamps below, maybe MM crashed on the
SetCurrentBands already, and the effects were only visible on the next
action?

>
> >     It seems to be completely on the dbus handling, and also
> > independent from this patch.
> >     I have traced it with gdb, but wasn't able to get to the root of
> > the issue, because the stack starts from the dbus get property call.
> >     If I don't read the property, it works fine.
> >     Also, if the setting is done in the other direction (from less to
> > more bands), then it works.
> >     Any idea?
>
> Could you please share how exactly you're triggering the error, and
> what's that gdb stacktrace?
>

Please see at the end of the trace below

ModemManager[17390]: <debug> [1589971907.559079] [modem0] setting new
list of bands: egsm, dcs, utran-8, utran-9, utran-2, eutran-18,
eutran-19, eutran-20, eutran-28
ModemManager[17390]: <debug> [1589971907.559231] [modem0/ttyACM0/at]
opening serial port...
ModemManager[17390]: <debug> [1589971907.560245] [modem0/ttyACM0/at]
setting up baudrate: 57600
ModemManager[17390]: <debug> [1589971907.560289] [modem0/ttyACM0/at]
no flow control explicitly requested for device
ModemManager[17390]: <debug> [1589971907.560372] [modem0/ttyACM0/at]
device open count is 1 (open)
ModemManager[17390]: <debug> [1589971907.560466] [modem0/ttyACM0/at]
--> 'AT^SCFG="Radio/Band/2G","0030007800300030003000300030003000310034";^SCFG="Radio/Band/3G","0030007800300030003000300030003100380032";^SCFG="Radio/Band/4G","0030007800300038003000450030003000300030"<CR>'
ModemManager[17390]: <debug> [1589971908.596000] [modem0/ttyACM0/at]
<-- '<CR><LF>^SCFG:
"Radio/Band/2G","0030007800300030003000300030003000310034"<CR><LF>'
ModemManager[17390]: <debug> [1589971927.537323] [modem0/ttyACM0/at]
<-- '<CR><LF>^SCFG:
"Radio/Band/3G","0030007800300030003000300030003100380032"<CR><LF>'
ModemManager[17390]: <debug> [1589971935.727578] [modem0/ttyACM0/at]
<-- '<CR><LF>^SCFG:
"Radio/Band/4G","0030007800300038003000450030003000300030"<CR><LF><CR><LF>OK<CR><LF>'
ModemManager[17390]: <debug> [1589971935.727753] [modem0/ttyACM0/at]
device open count is 2 (open)
ModemManager[17390]: <debug> [1589971935.727790] [modem0/ttyACM0/at]
device open count is 1 (close)
ModemManager[17390]: <debug> [1589971935.727820] [modem0/ttyACM0/at]
--> 'AT^SCFG?<CR>'
ModemManager[17390]: <debug> [1589971935.752061] [modem0/ttyACM0/at]
<-- '<CR><LF>^SCFG:
"MEopMode/Prov/AutoSelect","006F00660066"<CR><LF>^SCFG:
"MEopMode/Prov/Cfg","00610074007400750073"<CR><LF>^SCFG:
"Serial/Ifc","0"<CR><LF>^SCFG:
"RemoteWakeUp/Ports","00630075007200720065006E0074"<CR><LF>^SCFG:
"RemoteWakeUp/Ports","0070006F00770065007200750070"<CR><LF>^SCFG:
"Gpio/mode/ASC1","006700700069006F"<CR><LF>^SCFG:
"Gpio/mode/DCD0","006700700069006F"<CR><LF>^SCFG:
"Gpio/mode/DSR0","006700700069006F"<CR><LF>^SCFG:
"Gpio/mode/DTR0","006700700069006F"<CR><LF>^SCFG:
"Gpio/mode/FSR","006700700069006F"<CR><LF>^SCFG:
"Gpio/mode/PULSE","006700700069006F"<CR><LF>^SCFG:
"Gpio/mode/PWM","006700700069006F"<CR><LF>^SCFG:
"Gpio/mode/HWAKEUP","006700700069006F"<CR><LF>^SCFG:
"Gpio/mode/RING0","006700700069006F"<CR><LF>^SCFG:
"Gpio/mode/SPI","006700700069006F"<CR><LF>^SCFG:
"Gpio/mode/SYNC","006700700069006F"<CR><LF>^SCFG:
"GPRS/AutoAttach","0065006E00610062006C00650064"<CR><LF>^SCFG:
"Ident/Manufacturer","Cinterion"<CR><LF>^SCFG:
"Ident/Product","PLS62-W"<CR><LF>^SCFG:
"MEopMode/SoR","006F00660066"<CR><LF>^SCFG:
"MEopMode/CregRoam","0030"<CR><LF>^SCFG:
"MeOpMode/SRPOM","0030"<CR><LF>^SCFG:
"MEopMode/RingOnData","006F00660066"<CR><LF>^SCF'
ModemManager[17390]: <debug> [1589971935.752393] [modem0/ttyACM0/at] <-- 'G: '
ModemManager[17390]: <debug> [1589971935.763663] [modem0/ttyACM0/at]
<-- '"MEShutdown/Fso","0030"<CR><LF>^SCFG:
"MEShutdown/sVsup/threshold","0030","0030"<CR><LF>^SCFG:
"Radio/Band/2G","0030007800300030003000300030003000310034"<CR><LF>^SCFG:
"Radio/Band/3G","0030007800300030003000300030003100380032"<CR><LF>^SCFG:
"Radio/Band/4G","0030007800300038003000450030003000300030"<CR><LF>^SCFG:
"Radio/Mtpl/2G","0030"<CR><LF>^SCFG:
"Radio/Mtpl/3G","0030"<CR><LF>^SCFG:
"Radio/Mtpl/4G","0030"<CR><LF>^SCFG:
"Radio/OutputPowerReduction","0034"<CR><LF>^SCFG:
"Serial/Interface/Allocation","0030","0030"<CR><LF>^SCFG:
"Serial/USB/DDD","0030","0030","0030003400300039","0031004500320044","0030003000350042","00430069006E0074006500720069006F006E00200057006900720065006C0065007300730020004D006F00640075006C00650073","0050004C00530078",""<CR><LF>^SCFG:
"Tcp/IRT","0033"<CR><LF>^SCFG: "Tcp/MR","00310030"<CR><LF>^SCFG:
"Tcp/OT","0036003000300030"<CR><LF>^SCFG:
"Tcp/WithURCs","006F006E"<CR><LF>^SCFG:
"Trace/Syslog/OTAP","0030"<CR><LF>^SCFG:
"Urc/Ringline","006C006F00630061006C"<CR><LF>^SCFG:
"Urc/Ringline/ActiveTime","0032"<CR><LF>^SCFG:
"Userware/Autostart","0030"<CR><LF>^SCFG:
"Userware/Autostart/Delay","0030"<CR><LF>^SCFG:'
ModemManager[17390]: <debug> [1589971935.764337] [modem0/ttyACM0/at] <-- ' "U'
ModemManager[17390]: <debug> [1589971935.775349] [modem0/ttyACM0/at]
<-- 'serware/DebugInterface","0030002E0030002E0030002E0030","0030002E0030002E0030002E0030","0030"<CR><LF>^SCFG:
"Userware/DebugMode","006F00660066"<CR><LF>^SCFG:
"Userware/Passwd",<CR><LF>^SCFG:
"Userware/Stdout","006E0075006C006C",,,,"006F00660066"<CR><LF>^SCFG:
"Userware/Watchdog","0030"<CR><LF>^SCFG:
"MEopMode/ExpectDTR","00630075007200720065006E0074"<CR><LF>^SCFG:
"MEopMode/ExpectDTR","0070006F00770065007200750070"<CR><LF><CR><LF>OK<CR><LF>'
ModemManager[17390]: <debug> [1589971935.775638] [modem0] periodic
signal check refresh ignored: checks not enabled
ModemManager[17390]: <debug> [1589971935.775749] [modem0/ttyACM0/at]
device open count is 0 (close)
ModemManager[17390]: <debug> [1589971935.775773] [modem0/ttyACM0/at]
closing serial port...
ModemManager[17390]: <debug> [1589971935.776572] [modem0/ttyACM0/at]
serial port closed
ModemManager: malloc.c:2868: mremap_chunk: Assertion `((size + offset)
& (GLRO (dl_pagesize) - 1)) == 0' failed.

Thread 5 "gdbus" received signal SIGABRT, Aborted.
[Switching to Thread 0x7ffff2c23700 (LWP 17397)]
__GI_raise (sig=sig at entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
51 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0  0x00007ffff6366e97 in __GI_raise (sig=sig at entry=6) at
../sysdeps/unix/sysv/linux/raise.c:51
#1  0x00007ffff6368801 in __GI_abort () at abort.c:79
#2  0x00007ffff63ba2c9 in __malloc_assert (file=<optimized out>,
function=<optimized out>, line=<optimized out>, assertion=<optimized
out>) at malloc.c:298
#3  0x00007ffff63ba2c9 in mremap_chunk (p=<optimized out>,
p at entry=0x5555559182a0, new_size=<optimized out>, new_size at entry=48)
at malloc.c:2868
#4  0x00007ffff63c0e15 in __GI___libc_realloc (oldmem=0x5555559182b0,
bytes=32) at malloc.c:3201
#5  0x00007ffff6c0db70 in g_realloc () at
/usr/lib/x86_64-linux-gnu/libglib-2.0.so.0
#6  0x00007ffff6c41184 in g_variant_builder_end () at
/usr/lib/x86_64-linux-gnu/libglib-2.0.so.0
#7  0x00007ffff71eefc1 in g_dbus_message_to_blob () at
/usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
#8  0x00007ffff71e363c in  () at /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
#9  0x00007ffff71e4997 in  () at /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
#10 0x00007ffff71f8607 in  () at /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
#11 0x00007ffff71b4263 in  () at /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
#12 0x00007ffff71b4299 in  () at /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
#13 0x00007ffff6c08285 in g_main_context_dispatch () at
/usr/lib/x86_64-linux-gnu/libglib-2.0.so.0
#14 0x00007ffff6c08650 in  () at /usr/lib/x86_64-linux-gnu/libglib-2.0.so.0
#15 0x00007ffff6c08962 in g_main_loop_run () at
/usr/lib/x86_64-linux-gnu/libglib-2.0.so.0
#16 0x00007ffff71f6276 in  () at /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
#17 0x00007ffff6c30175 in  () at /usr/lib/x86_64-linux-gnu/libglib-2.0.so.0
#18 0x00007ffff67206db in start_thread (arg=0x7ffff2c23700) at
pthread_create.c:463
#19 0x00007ffff644988f in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:95
(gdb)

Regards,
Giacinto