AT channel problem

AT channel problem

[Enrico Sau]

[-- Attachment #1: Type: text/plain, Size: 981 bytes --]

Hi all,

I'm running into a problem with AT command read process and I need some
help because I don't fully understand the code in this case.

Ofono freezes in one particular systematic case when I receive "\r\nOK\r\n"
from the modem port (without quotes).

As I understood the method gatchat/gatchat.c::new_bytes() is called when
something was read from gatchat/gatio.c::received_data(), and the
function p->syntax->feed returns a result based on the syntax structure.

I made some debug and I found out that, in the failing case, syntax->state
is 2, it means that it is trying to read a line, but the process fails
because it doesn't find the ' " ' character.

I don't understand where the variable sysntax->state was set to 2. It
doesn't make sense to me.
I tried to search the code for all possible points where the variable is
set but I couldn't find the correct one.

Does anyone have a suggestion about where should I look?

Thank you all.

Enrico

[-- Attachment #2: attachment.html --]
[-- Type: text/html, Size: 2414 bytes --]

Re: AT channel problem

[Denis Kenzior]

[-- Attachment #1: Type: text/plain, Size: 1181 bytes --]

Hi Enrico,

On 05/05/2016 03:42 AM, Enrico Sau wrote:
> Hi all,
>
> I'm running into a problem with AT command read process and I need some
> help because I don't fully understand the code in this case.
>
> Ofono freezes in one particular systematic case when I receive
> "\r\nOK\r\n" from the modem port (without quotes).
>
> As I understood the method gatchat/gatchat.c::new_bytes() is called when
> something was read from gatchat/gatio.c::received_data(), and the
> function p->syntax->feed returns a result based on the syntax structure.
>
> I made some debug and I found out that, in the failing case,
> syntax->state is 2, it means that it is trying to read a line, but the
> process fails because it doesn't find the ' " ' character.
>

What syntax is being used?

> I don't understand where the variable sysntax->state was set to 2. It
> doesn't make sense to me.
> I tried to search the code for all possible points where the variable is
> set but I couldn't find the correct one.
>

How does the rest of the log look like?

> Does anyone have a suggestion about where should I look?
>
> Thank you all.
>
> Enrico

Regards,
-Denis

Re: AT channel problem

[Enrico Sau]

[-- Attachment #1: Type: text/plain, Size: 1105 bytes --]

​Hi Denis,
​


> What syntax is being used?


​I'm using permissive syntax.​



> How does the rest of the log look like?
>

​The rest of the log look fine to me, I​ had to add prints to understand
why it was blocking.

Anyway, I managed to solve the problem with a simple yet potentially
dangerous fix: I deleted the if statement in the
GSM_PERMISSIVE_STATE_RESPONSE_STRING case, so, it changed from:

​gatchat/gatsyntax.c (row 309 more or less)​
case GSM_PERMISSIVE_STATE_RESPONSE_STRING:
    if (byte == '"')
  syntax->state = GSM_PERMISSIVE_STATE_RESPONSE;
  break;​

​To:

​case GSM_PERMISSIVE_STATE_RESPONSE_STRING:
syntax->state = GSM_PERMISSIVE_STATE_RESPONSE;
  break;​

​With this fix everything seem to work in my case.
Do you think it is dangerous in any way?​

​I still don't understand where the "syntax->state =
GSM_PERMISSIVE_STATE_RESPONSE_STRING"
comes from since the state seems to be managed only in this function. I'm
thinking about some memory corruption but I'm not able to find why.

​Thank you,
Enrico​

[-- Attachment #2: attachment.html --]
[-- Type: text/html, Size: 3907 bytes --]

Re: AT channel problem

[Denis Kenzior]

[-- Attachment #1: Type: text/plain, Size: 902 bytes --]

Hi Enrico,

 > Anyway, I managed to solve the problem with a simple yet potentially
> dangerous fix: I deleted the if statement in the
> GSM_PERMISSIVE_STATE_RESPONSE_STRING case, so, it changed from:
>
> ​gatchat/gatsyntax.c (row 309 more or less)​
> case GSM_PERMISSIVE_STATE_RESPONSE_STRING:
>      if (byte == '"')
> syntax->state = GSM_PERMISSIVE_STATE_RESPONSE;
> break;​
>
> ​To:
>
> ​case GSM_PERMISSIVE_STATE_RESPONSE_STRING:
> syntax->state = GSM_PERMISSIVE_STATE_RESPONSE;
> break;​
>
> ​With this fix everything seem to work in my case.
> Do you think it is dangerous in any way?​

Yes.  This particular logic enables strings (e.g. text enclosed in 
quotes) to contain various special characters that would otherwise be 
interpreted differently.

It looks like you have an unterminated " in one of the AT command 
responses...

Regards,
-Denis

Re: AT channel problem

[Enrico Sau]

[-- Attachment #1: Type: text/plain, Size: 633 bytes --]

​Hi Denis,
​


> This particular logic enables strings (e.g. text enclosed in quotes) to
> contain various special characters that would otherwise be interpreted
> differently.
>

​Ok, understood. I'll try to find another solution.​

It looks like you have an unterminated " in one of the AT command
> responses...


​I will check for this, but what I think is that the state variable is set
outside the syntax state machine, because in my added prints I see that it
is already set to GSM_PERMISSIVE_STATE_RESPONSE_STRING before any parsing.

Does it look strange to you?​

​Thank you,
Enrico​

[-- Attachment #2: attachment.html --]
[-- Type: text/html, Size: 2016 bytes --]

Re: AT channel problem

[Enrico Sau]

[-- Attachment #1: Type: text/plain, Size: 394 bytes --]

​Hi Denis,

discard my last mail please, I went back some step and I found that in the
modem bus there are ​spare characters which may get the state machine
confused.

I'm thinking abut solving the problem from the plugin because this happens
when I insert the sim.

Is there a safe way to reset the modem at channel including the syntax from
the plugin?

Thank you,

Enrico

[-- Attachment #2: attachment.html --]
[-- Type: text/html, Size: 1206 bytes --]

Re: AT channel problem

[Denis Kenzior]

[-- Attachment #1: Type: text/plain, Size: 599 bytes --]

Hi Enrico,

On 05/06/2016 05:06 AM, Enrico Sau wrote:
> ​Hi Denis,
>
> discard my last mail please, I went back some step and I found that in
> the modem bus there are ​spare characters which may get the state
> machine confused.

Do you have a log handy?

>
> I'm thinking abut solving the problem from the plugin because this
> happens when I insert the sim.
>
> Is there a safe way to reset the modem at channel including the syntax
> from the plugin?

Not really, but you can try writing your own syntax if the garbage the 
modem sends is not random.

Regards,
-Denis

Re: AT channel problem

[Enrico Sau]

[-- Attachment #1: Type: text/plain, Size: 438 bytes --]

​Hi Denis,
​


> Do you have a log handy?


​Yes, I attached a log with the following operations:
- enable modem
- activate context
- extract SIM
- insert SIM
- activate context
​


> Not really, but you can try writing your own syntax if the garbage the
> modem sends is not random.
>

​This is a good idea, I will check the randomness of the garbage ad see if
I can do it.

Thank you.​
​Enrico​

[-- Attachment #2: attachment.html --]
[-- Type: text/html, Size: 2001 bytes --]

[-- Attachment #3: log_syntax_block.txt --]
[-- Type: text/plain, Size: 51560 bytes --]

root@enricosa-VirtualBox:/home/enricosa/ofono# ofonod --plugin=udevng,telitmodem,atmodem,he910 -n -d
ofonod[1306]: oFono version 1.15_R5.00.00.B8
ofonod[1306]: 09:33:57|src/plugin.c[114]:__ofono_plugin_init() 
ofonod[1306]: Ignoring udev hardware detection
ofonod[1306]: Ignoring PhoNet / ISI modem driver
ofonod[1306]: Ignoring Generic modem driver for isi
ofonod[1306]: Ignoring Nokia N900 modem driver
ofonod[1306]: Ignoring ST-Ericsson U8500 modem driver
ofonod[1306]: Ignoring Qualcomm QMI modem driver
ofonod[1306]: Ignoring Qualcomm Gobi modem driver
ofonod[1306]: Ignoring Novatel modem driver
ofonod[1306]: Ignoring Sierra modem driver
ofonod[1306]: Ignoring ZTE modem driver
ofonod[1306]: Ignoring Icera modem driver
ofonod[1306]: Ignoring Huawei modem driver
ofonod[1306]: Ignoring Calypso modem driver
ofonod[1306]: Ignoring MBM modem driver
ofonod[1306]: Ignoring HSO modem driver
ofonod[1306]: Ignoring Infineon modem driver
ofonod[1306]: Ignoring STE modem driver
ofonod[1306]: Ignoring Dialup modem driver
ofonod[1306]: Ignoring Hands-Free Profile Driver
ofonod[1306]: Ignoring SpeedUp modem driver
ofonod[1306]: Ignoring Phone Simulator driver
ofonod[1306]: Ignoring CDMA AT modem driver
ofonod[1306]: Ignoring HTC G1 modem driver
ofonod[1306]: Ignoring Wavecom driver
ofonod[1306]: Ignoring TI Calypso modem driver
ofonod[1306]: Ignoring Ericsson MBM modem driver
ofonod[1306]: Ignoring Option HSO modem driver
ofonod[1306]: Ignoring ZTE modem driver
ofonod[1306]: Ignoring HUAWEI Mobile modem driver
ofonod[1306]: Ignoring Sierra Wireless modem driver
ofonod[1306]: Ignoring Novatel Wireless modem driver
ofonod[1306]: Ignoring Palm Pre driver
ofonod[1306]: Ignoring Infineon modem driver
ofonod[1306]: Ignoring ST-Ericsson modem driver
ofonod[1306]: Ignoring ST-Ericsson Modem Init Daemon detection
ofonod[1306]: Ignoring CAIF device detection
ofonod[1306]: Ignoring Cinterion TC65 driver plugin
ofonod[1306]: Ignoring Nokia Datacard modem driver
ofonod[1306]: Ignoring Nokia CDMA AT Modem
ofonod[1306]: Ignoring Linktop Datacard modem driver
ofonod[1306]: Ignoring Icera modem driver
ofonod[1306]: Ignoring Alcatel modem driver
ofonod[1306]: Ignoring Speed Up modem driver
ofonod[1306]: Ignoring Speed Up CDMA modem driver
ofonod[1306]: Ignoring Samsung modem driver
ofonod[1306]: Ignoring SIM900 modem driver
ofonod[1306]: Ignoring ConnMan plugin
ofonod[1306]: Ignoring Telit LE910NA1 driver
ofonod[1306]: Ignoring Quectel driver
ofonod[1306]: Ignoring u-blox modem driver
ofonod[1306]: Ignoring BlueZ 5 Utils Plugin
ofonod[1306]: Ignoring External Hands-Free Profile Plugin
ofonod[1306]: Ignoring Hands-Free Audio Gateway Profile Plugins
ofonod[1306]: Ignoring Dial-up Networking Profile Plugins
ofonod[1306]: Ignoring Provisioning Plugin
ofonod[1306]: Ignoring CDMA provisioning Plugin
ofonod[1306]: Ignoring Example Call History Plugin
ofonod[1306]: Ignoring Example Network Time Plugin
ofonod[1306]: Ignoring Example Provisioning Plugin
ofonod[1306]: Ignoring Example AT Modem Emulator Plugin
ofonod[1306]: Ignoring Example Private Network Plugin
ofonod[1306]: Ignoring STK End-to-End tester driver
ofonod[1306]: Ignoring Smart Messaging Plugin
ofonod[1306]: Ignoring Push Notification Plugin
ofonod[1306]: 09:33:54|plugins/he910.c[432]:he910_init() 
ofonod[1306]: 09:33:57|src/modem.c[2147]:ofono_modem_driver_register() driver: 0x81b6a40, name: he910
ofonod[1306]: 09:34:05|src/radio-settings.c[622]:ofono_radio_settings_driver_register() driver: 0x81b5e20, name: telitmodem
ofonod[1306]: 09:34:09|src/telit-trace.c[538]:ofono_telit_trace_driver_register() driver: 0x81b5e60, name: telitmodem
ofonod[1306]: 09:34:09|src/telit-urc.c[748]:ofono_telit_urc_driver_register() driver: 0x81b5ea0, name: telitmodem
ofonod[1306]: 09:34:09|src/telit-power-management.c[363]:ofono_telit_power_management_driver_register() driver: 0x81b5f0c, name: telitmodem
ofonod[1306]: 09:34:09|src/telit-data-network.c[403]:ofono_telit_data_network_driver_register() driver: 0x81b5f28, name: telitmodem
ofonod[1306]: 09:34:10|src/telit-hw-management.c[481]:ofono_telit_hw_management_driver_register() driver: 0x81b5f5c, name: telitmodem
ofonod[1306]: 09:34:10|src/telit-me-control.c[354]:ofono_telit_me_control_driver_register() driver: 0x81b5f88, name: telitmodem
ofonod[1306]: 09:34:10|src/telit-custom.c[371]:ofono_telit_custom_driver_register() driver: 0x81b5fb0, name: telitmodem
ofonod[1306]: 09:33:58|src/voicecall.c[2636]:ofono_voicecall_driver_register() driver: 0x81b53c0, name: atmodem
ofonod[1306]: 09:33:57|src/modem.c[1544]:ofono_devinfo_driver_register() driver: 0x81b5460, name: atmodem
ofonod[1306]: 09:34:01|src/call-barring.c[1001]:ofono_call_barring_driver_register() driver: 0x81b5418, name: atmodem
ofonod[1306]: 09:34:01|src/call-forwarding.c[1443]:ofono_call_forwarding_driver_register() driver: 0x81b5140, name: atmodem
ofonod[1306]: 09:34:01|src/call-meter.c[686]:ofono_call_meter_driver_register() driver: 0x81b5180, name: atmodem
ofonod[1306]: 09:34:00|src/call-settings.c[1355]:ofono_call_settings_driver_register() driver: 0x81b5040, name: atmodem
ofonod[1306]: 09:34:03|src/phonebook.c[495]:ofono_phonebook_driver_register() driver: 0x81b5438, name: atmodem
ofonod[1306]: 09:33:59|src/ussd.c[769]:ofono_ussd_driver_register() driver: 0x81b5384, name: atmodem
ofonod[1306]: 09:34:00|src/sms.c[1645]:ofono_sms_driver_register() driver: 0x81b50c0, name: atmodem
ofonod[1306]: 09:34:02|src/sim.c[2802]:ofono_sim_driver_register() driver: 0x81b52a0, name: atmodem
ofonod[1306]: 09:34:02|src/sim.c[2802]:ofono_sim_driver_register() driver: 0x81b5240, name: atmodem-noef
ofonod[1306]: 09:34:02|src/stk.c[3117]:ofono_stk_driver_register() driver: 0x81b5364, name: atmodem
ofonod[1306]: 09:33:58|src/network.c[1737]:ofono_netreg_driver_register() driver: 0x81b51e0, name: atmodem
ofonod[1306]: 09:34:04|src/cbs.c[565]:ofono_cbs_driver_register() driver: 0x81b5120, name: atmodem
ofonod[1306]: 09:34:04|src/call-volume.c[404]:ofono_call_volume_driver_register() driver: 0x81b5484, name: atmodem
ofonod[1306]: 09:34:04|src/gprs.c[2598]:ofono_gprs_driver_register() driver: 0x81b54b4, name: atmodem
ofonod[1306]: 09:34:04|src/gprs.c[2391]:ofono_gprs_context_driver_register() driver: 0x81b54d8, name: atmodem
ofonod[1306]: 09:34:06|src/sim-auth.c[46]:ofono_sim_auth_driver_register() driver: 0x81b54f0, name: atmodem
ofonod[1306]: 09:34:08|src/gnss.c[300]:ofono_gnss_driver_register() driver: 0x81b5508, name: atmodem
ofonod[1306]: 09:33:28|plugins/udevng.c[1373]:udev_start() 
ofonod[1306]: 09:33:28|plugins/udevng.c[1286]:enumerate_devices() 
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() hub [(null):(null)]
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() usb [80ee:0021]
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() usbhid [(null):(null)]
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() hub [(null):(null)]
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() usb [058b:0041]
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() cdc_acm [(null):(null)]
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() cdc_acm [(null):(null)]
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() cdc_acm [058b:0041]
ofonod[1306]: 09:33:28|plugins/udevng.c[1009]:remove_device() /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-1/1-1:1.0/tty/ttyACM0
ofonod[1306]: 09:33:28|plugins/udevng.c[1009]:remove_device() /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-1/1-1:1.1
ofonod[1306]: 09:33:28|plugins/udevng.c[1009]:remove_device() /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-1/1-1:1.0
ofonod[1306]: 09:33:28|plugins/udevng.c[1009]:remove_device() /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-1
ofonod[1306]: 09:33:28|plugins/udevng.c[1326]:check_modem_list() 
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() usb [1bc7:0021]
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() cdc_acm [(null):(null)]
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() cdc_acm [(null):(null)]
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() cdc_acm [(null):(null)]
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() cdc_acm [(null):(null)]
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() cdc_acm [(null):(null)]
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() cdc_acm [(null):(null)]
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() cdc_acm [(null):(null)]
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() cdc_acm [1bc7:0021]
ofonod[1306]: 09:33:28|plugins/udevng.c[1075]:add_device() /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-1
ofonod[1306]: 09:33:28|plugins/udevng.c[1076]:add_device() /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-1/1-1:1.4/tty/ttyACM2
ofonod[1306]: 09:33:28|plugins/udevng.c[1078]:add_device() /dev/ttyACM2 (he910) 2/2/1 [04] ==> (null) (null)
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() cdc_acm [1bc7:0021]
ofonod[1306]: 09:33:28|plugins/udevng.c[1075]:add_device() /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-1
ofonod[1306]: 09:33:28|plugins/udevng.c[1076]:add_device() /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-1/1-1:1.2/tty/ttyACM1
ofonod[1306]: 09:33:28|plugins/udevng.c[1078]:add_device() /dev/ttyACM1 (he910) 2/2/1 [02] ==> (null) (null)
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() cdc_acm [(null):(null)]
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() cdc_acm [(null):(null)]
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() cdc_acm [1bc7:0021]
ofonod[1306]: 09:33:28|plugins/udevng.c[1075]:add_device() /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-1
ofonod[1306]: 09:33:28|plugins/udevng.c[1076]:add_device() /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-1/1-1:1.8/tty/ttyACM4
ofonod[1306]: 09:33:28|plugins/udevng.c[1078]:add_device() /dev/ttyACM4 (he910) 2/2/1 [08] ==> (null) (null)
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() cdc_acm [1bc7:0021]
ofonod[1306]: 09:33:28|plugins/udevng.c[1075]:add_device() /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-1
ofonod[1306]: 09:33:28|plugins/udevng.c[1076]:add_device() /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-1/1-1:1.6/tty/ttyACM3
ofonod[1306]: 09:33:28|plugins/udevng.c[1078]:add_device() /dev/ttyACM3 (he910) 2/2/1 [06] ==> (null) (null)
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() cdc_acm [1bc7:0021]
ofonod[1306]: 09:33:28|plugins/udevng.c[1075]:add_device() /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-1
ofonod[1306]: 09:33:28|plugins/udevng.c[1076]:add_device() /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-1/1-1:1.0/tty/ttyACM0
ofonod[1306]: 09:33:28|plugins/udevng.c[1078]:add_device() /dev/ttyACM0 (he910) 2/2/1 [00] ==> (null) (null)
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() cdc_acm [(null):(null)]
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() cdc_acm [(null):(null)]
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() cdc_acm [(null):(null)]
ofonod[1306]: 09:33:28|plugins/udevng.c[1193]:check_usb_device() cdc_acm [1bc7:0021]
ofonod[1306]: 09:33:28|plugins/udevng.c[1075]:add_device() /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-1
ofonod[1306]: 09:33:28|plugins/udevng.c[1076]:add_device() /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-1/1-1:1.10/tty/ttyACM5
ofonod[1306]: 09:33:28|plugins/udevng.c[1078]:add_device() /dev/ttyACM5 (he910) 2/2/1 [0a] ==> (null) (null)
ofonod[1306]: 09:33:28|plugins/udevng.c[1326]:check_modem_list() 
ofonod[1306]: 09:33:28|plugins/udevng.c[1257]:create_modem() /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-1
ofonod[1306]: 09:33:28|plugins/udevng.c[1262]:create_modem() driver=he910
ofonod[1306]: 09:33:57|src/modem.c[1817]:ofono_modem_create() name: (null), type: he910
ofonod[1306]: 09:33:28|plugins/udevng.c[674]:setup_he910() /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-1
ofonod[1306]: 09:33:28|plugins/udevng.c[680]:setup_he910() /dev/ttyACM0 2/2/1 00 (null)
ofonod[1306]: 09:33:28|plugins/udevng.c[680]:setup_he910() /dev/ttyACM1 2/2/1 02 (null)
ofonod[1306]: 09:33:28|plugins/udevng.c[680]:setup_he910() /dev/ttyACM2 2/2/1 04 (null)
ofonod[1306]: 09:33:28|plugins/udevng.c[680]:setup_he910() /dev/ttyACM3 2/2/1 06 (null)
ofonod[1306]: 09:33:28|plugins/udevng.c[680]:setup_he910() /dev/ttyACM4 2/2/1 08 (null)
ofonod[1306]: 09:33:28|plugins/udevng.c[680]:setup_he910() /dev/ttyACM5 2/2/1 0a (null)
ofonod[1306]: 09:33:28|plugins/udevng.c[693]:setup_he910() modem=/dev/ttyACM0 aux=/dev/ttyACM3
ofonod[1306]: 09:33:57|src/modem.c[1667]:set_modem_property() modem 0x88ef560 property Modem
ofonod[1306]: 09:33:57|src/modem.c[1667]:set_modem_property() modem 0x88ef560 property Aux
ofonod[1306]: 09:33:57|src/modem.c[1960]:ofono_modem_register() 0x88ef560
ofonod[1306]: 09:33:54|plugins/he910.c[394]:he910_probe() 0x88ef560
ofonod[1306]: 09:33:57|src/modem.c[1922]:emit_modem_added() 0x88ef560
ofonod[1306]: 09:33:57|src/modem.c[1905]:call_modemwatches() 0x88ef560 added:1
ofonod[1306]: 09:33:54|plugins/he910.c[259]:he910_enable() 0x88ef560
ofonod[1306]: 09:33:57|src/modem.c[1705]:get_modem_property() modem 0x88ef560 property Modem
ofonod[1306]: 09:33:54|plugins/he910.c[100]:open_device() Modem /dev/ttyACM0
ofonod[1306]: 09:33:57|src/modem.c[1705]:get_modem_property() modem 0x88ef560 property Aux
ofonod[1306]: 09:33:54|plugins/he910.c[100]:open_device() Aux /dev/ttyACM3
ofonod[1306]: Aux: > ATE0 +CMEE=1\r
ofonod[1306]: Modem: < \r\n\r\n#QSS: 2\r\n\r\n+CREG: 2\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: Aux: < ATE0 +CMEE=1\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+CFUN=1\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: 09:33:54|plugins/he910.c[215]:cfun_enable_cb() 0x88ef560
ofonod[1306]: 09:33:57|src/modem.c[496]:modem_change_state() old state: 0, new state: 1
ofonod[1306]: 09:33:54|plugins/he910.c[331]:he910_pre_sim() 0x88ef560
ofonod[1306]: Modem: > AT&C0\r
ofonod[1306]: Aux: > AT&C0\r
ofonod[1306]: 09:34:02|src/sim.c[2494]:ofono_sim_add_state_watch() 0x88ed6f0
ofonod[1306]: 09:34:02|src/sim.c[2494]:ofono_sim_add_state_watch() 0x88ed6f0
ofonod[1306]: Modem: < \r\nOK\r\n
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+GCAP\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +GCAP: +CGSM,+DS,+FCLASS,+MS,+ES\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT#QSS=2\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT#QSS?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < #QSS: 2,2\r\n\r\nOK\r\n
ofonod[1306]: 09:33:54|plugins/he910.c[191]:qss_query_cb() 0x88ef560
ofonod[1306]: 09:33:54|plugins/he910.c[131]:switch_sim_state_status() 0x88ef560, SIM status: 2
ofonod[1306]: Aux: > AT+CGMI\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < Telit\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+CRSM=192,12258\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,621F8202412183022FE2A5068001719201008A01058B032F06058002000A880110\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[114]:at_crsm_info_cb() crsm_info_cb: 90, 00, 33
ofonod[1306]: Aux: > AT+CGMM\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < UE910-EUR\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+CRSM=176,12258,0,0,10\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,98931000009002152369\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[241]:at_crsm_read_cb() crsm_read_cb: 90, 00, 10
ofonod[1306]: 09:34:05|src/simfs.c[371]:sim_fs_op_read_block_cb() bufoff: 0, dataoff: 0, tocopy: 10
ofonod[1306]: Aux: > AT+CGMR\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < 12.00.407\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+CRSM=192,28421\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,62278202412183026F05A50E80017192010091067F105FFF1F048A01058B036F060380020004880110\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[114]:at_crsm_info_cb() crsm_info_cb: 90, 00, 41
ofonod[1306]: Aux: > AT+CGSN\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < 354550050002985\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+CRSM=176,28421,0,0,4\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,6974656E\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[241]:at_crsm_read_cb() crsm_read_cb: 90, 00, 4
ofonod[1306]: 09:34:05|src/simfs.c[371]:sim_fs_op_read_block_cb() bufoff: 0, dataoff: 0, tocopy: 4
ofonod[1306]: Aux: > AT+CRSM=192,12037\r
ofonod[1306]: Aux: < \r\n+CME ERROR: 4\r\n
ofonod[1306]: Aux: > AT+CPIN?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CPIN: READY\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[1195]:at_cpin_cb() crsm_pin_cb: READY
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[1064]:at_pin_retries_query() 
ofonod[1306]: Aux: > AT#PCT\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < #PCT: 3\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[908]:at_pct_cb() Note: No password required, returning maximum retries:
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[910]:at_pct_cb() retry counter id=1, val=3
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[911]:at_pct_cb() retry counter id=4, val=3
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[912]:at_pct_cb() retry counter id=9, val=10
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[913]:at_pct_cb() retry counter id=11, val=10
ofonod[1306]: Aux: > AT+CRSM=192,28590\r
ofonod[1306]: Aux: < \r\n+CME ERROR: 4\r\n
ofonod[1306]: Aux: > AT+CRSM=192,28589\r
ofonod[1306]: Aux: < \r\n+CRSM: 144,0,62258202412183026FADA50C80017192010091047F206FAD8A01058B036F060680020004880118\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[114]:at_crsm_info_cb() crsm_info_cb: 90, 00, 39
ofonod[1306]: Aux: > AT+CRSM=176,28589,0,0,4\r
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < +CGREG: 1,"F051","5FA236F",2,"00"\r\n\r\n+CREG: 1,"F051","5FA236F",2\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,00000002\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[241]:at_crsm_read_cb() crsm_read_cb: 90, 00, 4
ofonod[1306]: 09:34:05|src/simfs.c[371]:sim_fs_op_read_block_cb() bufoff: 0, dataoff: 0, tocopy: 4
ofonod[1306]: Aux: > AT+CRSM=192,28438\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 106,130\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+CRSM=192,28472\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,621F8202412183026F38A5068001719201008A01058B036F060480020006880120\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[114]:at_crsm_info_cb() crsm_info_cb: 90, 00, 33
ofonod[1306]: Aux: > AT+CRSM=176,28472,0,0,6\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,0E6A1F1C6304\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[241]:at_crsm_read_cb() crsm_read_cb: 90, 00, 6
ofonod[1306]: 09:34:05|src/simfs.c[371]:sim_fs_op_read_block_cb() bufoff: 0, dataoff: 0, tocopy: 6
ofonod[1306]: Aux: > AT+CRSM=192,28502\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,621F8202412183026F56A5068001719201008A01058B036F060880020001880128\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[114]:at_crsm_info_cb() crsm_info_cb: 90, 00, 33
ofonod[1306]: Aux: > AT+CRSM=176,28502,0,0,1\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,00\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[241]:at_crsm_read_cb() crsm_read_cb: 90, 00, 1
ofonod[1306]: 09:34:05|src/simfs.c[371]:sim_fs_op_read_block_cb() bufoff: 0, dataoff: 0, tocopy: 1
ofonod[1306]: Aux: > AT+CIMI\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < 222017002413226\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[438]:at_cimi_cb() cimi_cb: 222017002413226
ofonod[1306]: 09:33:57|src/modem.c[496]:modem_change_state() old state: 1, new state: 2
ofonod[1306]: 09:33:57|src/modem.c[496]:modem_change_state() old state: 2, new state: 3
ofonod[1306]: 09:33:54|plugins/he910.c[354]:he910_post_online() 0x88ef560
ofonod[1306]: 09:33:49|drivers/telitmodem/radio-settings.c[178]:telit_radio_settings_probe() 
ofonod[1306]: 09:33:42|drivers/atmodem/gprs-context.c[391]:at_gprs_context_probe() 
ofonod[1306]: Aux: > AT+WS46?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +WS46: 25\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+CREG=?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CREG: (0-2)\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+CGDCONT=?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CGDCONT: (1-5),"IP",,,(0,1),(0,1)\r\n+CGDCONT: (1-5),"IPV6",,,(0,1),(0,1)\r\n+CGDCONT: (1-5),"IPV4V6",,,(0,1),(0,1)\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT#AUTOATT=1\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+CRSM=192,28480\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,622782054221001C0183026F40A50C80017192010091047F106F408A01058B036F06058002001C8800\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[114]:at_crsm_info_cb() crsm_info_cb: 90, 00, 41
ofonod[1306]: Aux: > AT+CREG=2\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+CGREG=?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CGREG: (0-2)\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+CRSM=178,28480,1,4,28\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[241]:at_crsm_read_cb() crsm_read_cb: 90, 00, 28
ofonod[1306]: Aux: > AT+CIND=?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CIND: (("battchg",(0-5,99)),("signal",(0-7,99)),("service",(0,1)),("sounder",(0,1)),("message",(0,1)),("call",(0,1)),("roam",(0,1)),("smsfull",(0,1)),("rssi",(0-5,99)))\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+CGREG=2\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+CGAUTO=0\r
ofonod[1306]: Aux: < \r\nERROR\r\n
ofonod[1306]: Aux: > AT+CGEREP=2,1\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+CRSM=192,20256\r
ofonod[1306]: Aux: < \r\n+CME ERROR: 4\r\n
ofonod[1306]: Aux: > AT+CIND=0,0,0,0,0,0,0,0,1\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+CMER=?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CMER: (0-3),(0),(0),(0,2),(0,1)\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/network-registration.c[1553]:build_cmer_string() 
ofonod[1306]: Aux: > AT#PSNT=1\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+CPSB=1\r
ofonod[1306]: Aux: < \r\nERROR\r\n
ofonod[1306]: Aux: > AT+CMER=3,0,0,2\r
ofonod[1306]: Aux: < \r\nOK\r\n\r\n
ofonod[1306]: 09:34:02|src/sim.c[2679]:ofono_sim_add_spn_watch() 0x88ed6f0
ofonod[1306]: 09:33:58|src/network.c[1153]:__ofono_netreg_add_status_watch() 0x88eb2d0
ofonod[1306]: Aux: > AT+CREG?\r
ofonod[1306]: Aux: < +CIEV: rssi,0\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CREG: 2,1,"F051","5FA236F",2\r\n\r\nOK\r\n
ofonod[1306]: 09:33:58|src/network.c[1349]:ofono_netreg_status_notify() /he910_0 status 1 tech 2
ofonod[1306]: 09:34:04|src/gprs.c[1674]:netreg_status_changed() 1
ofonod[1306]: Aux: > AT+CRSM=192,28613\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 106,130\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS=3,2\r
ofonod[1306]: 09:34:05|src/simfs.c[446]:sim_fs_op_read_block() bufoff: 0, seekoff: 39, toread: 17
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +COPS: 0,2,"22201",2\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/network-registration.c[395]:cops_numeric_cb() Cops numeric got mcc: 222, mnc: 01
ofonod[1306]: Aux: > AT+CIND?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CIND: 0,0,1,1,1,0,0,0,0\r\n\r\nOK\r\n
ofonod[1306]: 09:33:58|src/network.c[1536]:ofono_netreg_strength_notify() strength 0
ofonod[1306]: Aux: > AT+CGATT=1\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: 09:34:04|src/gprs.c[1613]:gprs_attach_callback() /he910_0 error = 0
ofonod[1306]: Aux: > AT+CIND?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CIND: 0,0,1,1,1,0,0,0,0\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+CRSM=192,28437\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 106,130\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS=3,0\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +COPS: 0,0,"I TIM",2\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/network-registration.c[344]:cops_cb() cops_cb: I TIM, 222 01 2
ofonod[1306]: 09:33:58|src/network.c[1219]:current_operator_callback() 0x88eb2d0, (nil)
ofonod[1306]: 09:34:04|src/gprs.c[1674]:netreg_status_changed() 1
ofonod[1306]: Aux: > AT+CGREG?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CGREG: 2,1,"F051","5FA236F",2,"00"\r\n\r\nOK\r\n
ofonod[1306]: 09:34:04|src/gprs.c[1594]:registration_status_cb() /he910_0 error 0 status 1
ofonod[1306]: 09:34:04|src/gprs.c[2223]:ofono_gprs_status_notify() /he910_0 status 1
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < #PSNT: 3\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < #PSNT: 3\r\n\r\n+CIEV: rssi,3\r\n
ofonod[1306]: 09:33:58|src/network.c[1536]:ofono_netreg_strength_notify() strength 60
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < #QSS: 3\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < #QSS: 3\r\n
ofonod[1306]: 09:33:54|plugins/he910.c[173]:he910_qss_notify() 0x88ef560
ofonod[1306]: 09:33:54|plugins/he910.c[131]:switch_sim_state_status() 0x88ef560, SIM status: 3
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CIEV: rssi,2\r\n
ofonod[1306]: 09:33:58|src/network.c[1536]:ofono_netreg_strength_notify() strength 40
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CIEV: rssi,3\r\n
ofonod[1306]: 09:33:58|src/network.c[1536]:ofono_netreg_strength_notify() strength 60
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CIEV: rssi,2\r\n
ofonod[1306]: 09:33:58|src/network.c[1536]:ofono_netreg_strength_notify() strength 40
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CIEV: rssi,3\r\n
ofonod[1306]: 09:33:58|src/network.c[1536]:ofono_netreg_strength_notify() strength 60
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CIEV: rssi,2\r\n
ofonod[1306]: 09:33:58|src/network.c[1536]:ofono_netreg_strength_notify() strength 40
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CIEV: rssi,3\r\n
ofonod[1306]: 09:33:58|src/network.c[1536]:ofono_netreg_strength_notify() strength 60
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CIEV: rssi,2\r\n
ofonod[1306]: 09:33:58|src/network.c[1536]:ofono_netreg_strength_notify() strength 40
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < +CREG: 1,"4A3A","F66A",0\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CREG: 1,"4A3A","F66A",0\r\n
ofonod[1306]: 09:33:58|src/network.c[1349]:ofono_netreg_status_notify() /he910_0 status 1 tech 0
ofonod[1306]: 09:34:04|src/gprs.c[1674]:netreg_status_changed() 1
ofonod[1306]: Aux: > AT+COPS=3,2\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +COPS: 0,2,"22201",0\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/network-registration.c[395]:cops_numeric_cb() Cops numeric got mcc: 222, mnc: 01
ofonod[1306]: Aux: > AT+CIND?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CIND: 0,6,1,0,1,0,0,1,2\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS=3,0\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +COPS: 0,0,"I TIM",0\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/network-registration.c[344]:cops_cb() cops_cb: I TIM, 222 01 0
ofonod[1306]: 09:33:58|src/network.c[1219]:current_operator_callback() 0x88eb2d0, 0x88faf38
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < +CGREG: 1,"4A3A","F66A",0,"01"\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CGREG: 1,"4A3A","F66A",0,"01"\r\n
ofonod[1306]: 09:34:04|src/gprs.c[2223]:ofono_gprs_status_notify() /he910_0 status 1
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < #PSNT: 1\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < #PSNT: 1\r\n\r\n+CIEV: rssi,3\r\n
ofonod[1306]: 09:33:58|src/network.c[1536]:ofono_netreg_strength_notify() strength 60
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CIEV: rssi,4\r\n
ofonod[1306]: 09:33:58|src/network.c[1536]:ofono_netreg_strength_notify() strength 80
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < +CGREG: 1,"F051","5FA2B40",2,"00"\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CGREG: 1,"F051","5FA2B40",2,"00"\r\n
ofonod[1306]: 09:34:04|src/gprs.c[2223]:ofono_gprs_status_notify() /he910_0 status 1
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < +CREG: 1,"F051","5FA2B40",2\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CREG: 1,"F051","5FA2B40",2\r\n
ofonod[1306]: 09:33:58|src/network.c[1349]:ofono_netreg_status_notify() /he910_0 status 1 tech 2
ofonod[1306]: 09:34:04|src/gprs.c[1674]:netreg_status_changed() 1
ofonod[1306]: Aux: > AT+COPS=3,2\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +COPS: 0,2,"22201",2\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/network-registration.c[395]:cops_numeric_cb() Cops numeric got mcc: 222, mnc: 01
ofonod[1306]: Aux: > AT+CIND?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CIND: 0,0,1,0,1,0,0,1,4\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS=3,0\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS?\r
ofonod[1306]: Aux: < \r\n+COPS: 0,0,"I TIM",2\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/network-registration.c[344]:cops_cb() cops_cb: I TIM, 222 01 2
ofonod[1306]: 09:33:58|src/network.c[1219]:current_operator_callback() 0x88eb2d0, 0x88faf38
ofonod[1306]: Modem: < \r\n#PSNT: 3\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < #PSNT: 3\r\n\r\n+CIEV: rssi,1\r\n
ofonod[1306]: 09:33:58|src/network.c[1536]:ofono_netreg_strength_notify() strength 20
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < +CGREG: 1,"F051","5FA00F6",2,"00"\r\n\r\n+CREG: 1,"F051","5FA00F6",2\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CGREG: 1,"F051","5FA00F6",2,"00"\r\n\r\n+CREG: 1,"F051","5FA00F6",2\r\n
ofonod[1306]: 09:34:04|src/gprs.c[2223]:ofono_gprs_status_notify() /he910_0 status 1
ofonod[1306]: 09:33:58|src/network.c[1349]:ofono_netreg_status_notify() /he910_0 status 1 tech 2
ofonod[1306]: 09:34:04|src/gprs.c[1674]:netreg_status_changed() 1
ofonod[1306]: Aux: > AT+COPS=3,2\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS?\r
ofonod[1306]: Aux: < \r\n+COPS: 0,2,"22201",2\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/network-registration.c[395]:cops_numeric_cb() Cops numeric got mcc: 222, mnc: 01
ofonod[1306]: Aux: > AT+CIND?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CIND: 0,4,1,0,1,0,0,1,1\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS=3,0\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +COPS: 0,0,"I TIM",2\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/network-registration.c[344]:cops_cb() cops_cb: I TIM, 222 01 2
ofonod[1306]: 09:33:58|src/network.c[1219]:current_operator_callback() 0x88eb2d0, 0x88faf38
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CIEV: rssi,2\r\n
ofonod[1306]: 09:33:58|src/network.c[1536]:ofono_netreg_strength_notify() strength 40
ofonod[1306]: 09:33:42|drivers/atmodem/gprs-context.c[240]:at_gprs_activate_primary() cid 1
ofonod[1306]: Modem: > AT+CGDCONT=1,"IP","ibox.tim.it"\r
ofonod[1306]: Modem: < \r\nOK\r\n
ofonod[1306]: 09:33:42|drivers/atmodem/gprs-context.c[200]:at_cgdcont_cb() ok 1
ofonod[1306]: Modem: > AT+CGDATA="PPP",1\r
ofonod[1306]: Modem: < \r\nCONNECT\r\n
ofonod[1306]: 09:33:42|drivers/atmodem/gprs-context.c[176]:at_cgdata_cb() ok 1
ofonod[1306]: 09:33:42|drivers/atmodem/gprs-context.c[141]:setup_ppp() 
ofonod[1306]: 09:33:42|drivers/atmodem/gprs-context.c[86]:ppp_connect() 
ofonod[1306]: IP: 2.194.193.31
ofonod[1306]: DNS: 10.205.41.16, 10.204.57.104
ofonod[1306]: 09:34:04|src/gprs.c[889]:pri_activate_callback() 0x88fa7d0
ofonod[1306]: 09:33:28|plugins/udevng.c[1326]:check_modem_list() 
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < #QSS: 0\r\n
ofonod[1306]: 09:33:54|plugins/he910.c[173]:he910_qss_notify() 0x88ef560
ofonod[1306]: 09:33:54|plugins/he910.c[131]:switch_sim_state_status() 0x88ef560, SIM status: 0
ofonod[1306]: 09:33:57|src/modem.c[496]:modem_change_state() old state: 3, new state: 1
ofonod[1306]: 09:33:57|src/modem.c[409]:flush_atoms() 
ofonod[1306]: 09:34:04|src/gprs.c[2279]:gprs_context_unregister() 0x88eef68, 0x88ee908
ofonod[1306]: 09:34:04|src/gprs.c[2413]:gprs_context_remove() atom: 0x88eef88
ofonod[1306]: 09:33:42|drivers/atmodem/gprs-context.c[420]:at_gprs_context_remove() 
ofonod[1306]: 09:34:04|src/gprs.c[2644]:gprs_unregister() 0x88ee908
ofonod[1306]: 09:33:58|src/network.c[1173]:__ofono_netreg_remove_status_watch() 0x88eb2d0
ofonod[1306]: 09:34:04|src/gprs.c[2683]:gprs_remove() atom: 0x88ee970
ofonod[1306]: 09:34:02|src/sim.c[2714]:ofono_sim_remove_spn_watch() 0x88ed6f0
ofonod[1306]: 09:33:58|src/network.c[1836]:netreg_remove() atom: 0x88eb338
ofonod[1306]: 09:34:09|src/telit-data-network.c[323]:telit_data_network_remove() atom: 0x88eb1c8
ofonod[1306]: 09:34:09|src/telit-urc.c[668]:telit_urc_remove() atom: 0x88eb0a8
ofonod[1306]: 09:34:05|src/radio-settings.c[657]:radio_settings_remove() atom: 0x88ee578
ofonod[1306]: 09:33:28|plugins/udevng.c[1009]:remove_device() /sys/devices/virtual/net/ppp0
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CGEV: NW DEACT IP, "2.194.193.31", 1\r\n
ofonod[1306]: Modem: < ~\377}#\300!}%}"} }$Y(~
ofonod[1306]: Modem: < \r\nNO CARRIER\r\n
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Modem: < #QSS: 0\r\n\r\n+CREG: 0\r\n\r\n+CGREG: 0\r\n\r\n+CGEV: NW DETACH\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: Aux: < +CGREG: 0\r\n\r\n+CREG: 0\r\n\r\n+CGEV: NW DETACH\r\n\r\n#PSNT: 4\r\n\r\n+CGREG: 0\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < #PSNT: 4\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < #PSNT: 4\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < #PSNT: 4\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < #PSNT: 4\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < #PSNT: 4\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: Aux: < \r\n#PSNT: 4\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < #PSNT: 4\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < #PSNT: 4\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < #PSNT: 4\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < #PSNT: 4\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < #PSNT: 4\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < #PSNT: 4\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Modem: < #PSNT: 4\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: Aux: < #PSNT: 4\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < #QSS: 2\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < #QSS: 2\r\n
ofonod[1306]: 09:33:54|plugins/he910.c[173]:he910_qss_notify() 0x88ef560
ofonod[1306]: 09:33:54|plugins/he910.c[131]:switch_sim_state_status() 0x88ef560, SIM status: 2
ofonod[1306]: Aux: > AT+CRSM=192,12258\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,621F8202412183022FE2A5068001719201008A01058B032F06058002000A880110\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[114]:at_crsm_info_cb() crsm_info_cb: 90, 00, 33
ofonod[1306]: Aux: > AT+CRSM=176,12258,0,0,10\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,98931000009002152369\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[241]:at_crsm_read_cb() crsm_read_cb: 90, 00, 10
ofonod[1306]: 09:34:05|src/simfs.c[371]:sim_fs_op_read_block_cb() bufoff: 0, dataoff: 0, tocopy: 10
ofonod[1306]: Aux: > AT+CRSM=192,28421\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,62278202412183026F05A50E80017192010091067F105FFF1F048A01058B036F060380020004880110\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[114]:at_crsm_info_cb() crsm_info_cb: 90, 00, 41
ofonod[1306]: Aux: > AT+CRSM=176,28421,0,0,4\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,6974656E\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[241]:at_crsm_read_cb() crsm_read_cb: 90, 00, 4
ofonod[1306]: 09:34:05|src/simfs.c[371]:sim_fs_op_read_block_cb() bufoff: 0, dataoff: 0, tocopy: 4
ofonod[1306]: Aux: > AT+CRSM=192,12037\r
ofonod[1306]: Aux: < \r\n+CME ERROR: 4\r\n
ofonod[1306]: Aux: > AT+CPIN?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CPIN: READY\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[1195]:at_cpin_cb() crsm_pin_cb: READY
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[1064]:at_pin_retries_query() 
ofonod[1306]: Aux: > AT#PCT\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < #PCT: 3\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[908]:at_pct_cb() Note: No password required, returning maximum retries:
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[910]:at_pct_cb() retry counter id=1, val=3
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[911]:at_pct_cb() retry counter id=4, val=3
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[912]:at_pct_cb() retry counter id=9, val=10
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[913]:at_pct_cb() retry counter id=11, val=10
ofonod[1306]: Aux: > AT+CRSM=192,28590\r
ofonod[1306]: Aux: < \r\n+CME ERROR: 4\r\n
ofonod[1306]: Aux: > AT+CRSM=192,28589\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,62258202412183026FADA50C80017192010091047F206FAD8A01058B036F060680020004880118\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[114]:at_crsm_info_cb() crsm_info_cb: 90, 00, 39
ofonod[1306]: Aux: > AT+CRSM=176,28589,0,0,4\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,00000002\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[241]:at_crsm_read_cb() crsm_read_cb: 90, 00, 4
ofonod[1306]: 09:34:05|src/simfs.c[371]:sim_fs_op_read_block_cb() bufoff: 0, dataoff: 0, tocopy: 4
ofonod[1306]: Aux: > AT+CRSM=192,28438\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 106,130\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+CRSM=192,28472\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,621F8202412183026F38A5068001719201008A01058B036F060480020006880120\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[114]:at_crsm_info_cb() crsm_info_cb: 90, 00, 33
ofonod[1306]: Aux: > AT+CRSM=176,28472,0,0,6\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,0E6A1F1C6304\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[241]:at_crsm_read_cb() crsm_read_cb: 90, 00, 6
ofonod[1306]: 09:34:05|src/simfs.c[371]:sim_fs_op_read_block_cb() bufoff: 0, dataoff: 0, tocopy: 6
ofonod[1306]: Aux: > AT+CRSM=192,28502\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,621F8202412183026F56A5068001719201008A01058B036F060880020001880128\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[114]:at_crsm_info_cb() crsm_info_cb: 90, 00, 33
ofonod[1306]: Aux: > AT+CRSM=176,28502,0,0,1\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,00\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[241]:at_crsm_read_cb() crsm_read_cb: 90, 00, 1
ofonod[1306]: 09:34:05|src/simfs.c[371]:sim_fs_op_read_block_cb() bufoff: 0, dataoff: 0, tocopy: 1
ofonod[1306]: Aux: > AT+CIMI\r
ofonod[1306]: Aux: < \r\n222017002413226\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[438]:at_cimi_cb() cimi_cb: 222017002413226
ofonod[1306]: 09:33:57|src/modem.c[496]:modem_change_state() old state: 1, new state: 2
ofonod[1306]: 09:33:57|src/modem.c[496]:modem_change_state() old state: 2, new state: 3
ofonod[1306]: 09:33:54|plugins/he910.c[354]:he910_post_online() 0x88ef560
ofonod[1306]: 09:33:49|drivers/telitmodem/radio-settings.c[178]:telit_radio_settings_probe() 
ofonod[1306]: 09:33:42|drivers/atmodem/gprs-context.c[391]:at_gprs_context_probe() 
ofonod[1306]: Aux: > AT+WS46?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +WS46: 25\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+CREG=?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CREG: (0-2)\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+CGDCONT=?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CGDCONT: (1-5),"IP",,,(0,1),(0,1)\r\n+CGDCONT: (1-5),"IPV6",,,(0,1),(0,1)\r\n+CGDCONT: (1-5),"IPV4V6",,,(0,1),(0,1)\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT#AUTOATT=1\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+CRSM=192,28480\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,622782054221001C0183026F40A50C80017192010091047F106F408A01058B036F06058002001C8800\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[114]:at_crsm_info_cb() crsm_info_cb: 90, 00, 41
ofonod[1306]: Aux: > AT+CREG=2\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+CGREG=?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CGREG: (0-2)\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+CRSM=178,28480,1,4,28\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 144,0,FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/sim.c[241]:at_crsm_read_cb() crsm_read_cb: 90, 00, 28
ofonod[1306]: Aux: > AT+CIND=?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CIND: (("battchg",(0-5,99)),("signal",(0-7,99)),("service",(0,1)),("sounder",(0,1)),("message",(0,1)),("call",(0,1)),("roam",(0,1)),("smsfull",(0,1)),("rssi",(0-5,99)))\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+CGREG=2\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+CGAUTO=0\r
ofonod[1306]: Aux: < \r\nERROR\r\n
ofonod[1306]: Aux: > AT+CGEREP=2,1\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+CRSM=192,20256\r
ofonod[1306]: Aux: < \r\n+CME ERROR: 4\r\n
ofonod[1306]: Aux: > AT+CIND=0,0,0,0,0,0,0,0,1\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+CMER=?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CMER: (0-3),(0),(0),(0,2),(0,1)\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/network-registration.c[1553]:build_cmer_string() 
ofonod[1306]: Aux: > AT#PSNT=1\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+CPSB=1\r
ofonod[1306]: Aux: < \r\nERROR\r\n
ofonod[1306]: Aux: > AT+CMER=3,0,0,2\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: 09:34:02|src/sim.c[2679]:ofono_sim_add_spn_watch() 0x88ed6f0
ofonod[1306]: 09:33:58|src/network.c[1153]:__ofono_netreg_add_status_watch() 0x88eb2f8
ofonod[1306]: Aux: > AT+CREG?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CREG: 2,0\r\n\r\nOK\r\n
ofonod[1306]: 09:33:58|src/network.c[1349]:ofono_netreg_status_notify() /he910_0 status 0 tech -1
ofonod[1306]: 09:33:58|src/network.c[1219]:current_operator_callback() 0x88eb2f8, (nil)
ofonod[1306]: 09:34:04|src/gprs.c[1674]:netreg_status_changed() 0
ofonod[1306]: Aux: > AT+CRSM=192,28613\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 106,130\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS=0\r
ofonod[1306]: 09:34:05|src/simfs.c[446]:sim_fs_op_read_block() bufoff: 0, seekoff: 39, toread: 17
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+CRSM=192,28437\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CRSM: 106,130\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+CREG?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CREG: 2,0\r\n\r\nOK\r\n
ofonod[1306]: 09:33:58|src/network.c[1349]:ofono_netreg_status_notify() /he910_0 status 0 tech -1
ofonod[1306]: 09:33:58|src/network.c[1219]:current_operator_callback() 0x88eb2f8, (nil)
ofonod[1306]: 09:34:04|src/gprs.c[1674]:netreg_status_changed() 0
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < +CGREG: 0\r\n\r\n#PSNT: 4\r\n\r\n#PSNT: 4\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CGREG: 0\r\n\r\n#PSNT: 4\r\n\r\n#PSNT: 4\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: 09:34:04|src/gprs.c[2223]:ofono_gprs_status_notify() /he910_0 status 0
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < +CGREG: 3\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CGREG: 3\r\n\r\n#PSNT: 4\r\n
ofonod[1306]: 09:34:04|src/gprs.c[2223]:ofono_gprs_status_notify() /he910_0 status 3
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < +CGREG: 0\r\n\r\n+CREG: 1,"F051","5FA236F",2\r\n\r\n#PSNT: 3\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CGREG: 0\r\n\r\n+CREG: 1,"F051","5FA236F",2\r\n\r\n#PSNT: 3\r\n
ofonod[1306]: 09:34:04|src/gprs.c[2223]:ofono_gprs_status_notify() /he910_0 status 0
ofonod[1306]: 09:33:58|src/network.c[1349]:ofono_netreg_status_notify() /he910_0 status 1 tech 2
ofonod[1306]: 09:34:04|src/gprs.c[1674]:netreg_status_changed() 1
ofonod[1306]: Aux: > AT+COPS=3,2\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +COPS: 0,2,"22201",2\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/network-registration.c[395]:cops_numeric_cb() Cops numeric got mcc: 222, mnc: 01
ofonod[1306]: Aux: > AT+CIND?\r
ofonod[1306]: Aux: < \r\n+CME ERROR: 14\r\n
ofonod[1306]: 09:33:58|src/network.c[1316]:signal_strength_callback() Error during signal strength query
ofonod[1306]: Aux: > AT+CGATT=1\r
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < +CGREG: 1,"F051","5FA236F",2,"00"\r\n
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: 09:34:04|src/gprs.c[1613]:gprs_attach_callback() /he910_0 error = 0
ofonod[1306]: Aux: > AT+COPS=3,0\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CGREG: 1,"F051","5FA236F",2,"00"\r\n
ofonod[1306]: 09:34:04|src/gprs.c[2223]:ofono_gprs_status_notify() /he910_0 status 1
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +COPS: 0,0,"I TIM",2\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/network-registration.c[344]:cops_cb() cops_cb: I TIM, 222 01 2
ofonod[1306]: 09:33:58|src/network.c[1219]:current_operator_callback() 0x88eb2f8, (nil)
ofonod[1306]: 09:34:04|src/gprs.c[1674]:netreg_status_changed() 1
ofonod[1306]: Aux: > AT+CGREG?\r
ofonod[1306]: Aux: < \r\n+CGREG: 2,1,"F051","5FA236F",2,"00"\r\n\r\nOK\r\n
ofonod[1306]: 09:34:04|src/gprs.c[1594]:registration_status_cb() /he910_0 error 0 status 1
ofonod[1306]: 09:34:04|src/gprs.c[2223]:ofono_gprs_status_notify() /he910_0 status 1
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < #QSS: 3\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < #QSS: 3\r\n
ofonod[1306]: 09:33:54|plugins/he910.c[173]:he910_qss_notify() 0x88ef560
ofonod[1306]: 09:33:54|plugins/he910.c[131]:switch_sim_state_status() 0x88ef560, SIM status: 3
ofonod[1306]: 09:33:42|drivers/atmodem/gprs-context.c[240]:at_gprs_activate_primary() cid 1
ofonod[1306]: Modem: > AT+CGDCONT=1,"IP","ibox.tim.it"\r
ofonod[1306]: Modem: < \r\nOK\r\n
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < +CREG: 1,"4A3A","F66A",0\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CREG: 1,"4A3A","F66A",0\r\n
ofonod[1306]: 09:33:58|src/network.c[1349]:ofono_netreg_status_notify() /he910_0 status 1 tech 0
ofonod[1306]: 09:34:04|src/gprs.c[1674]:netreg_status_changed() 1
ofonod[1306]: Aux: > AT+COPS=3,2\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS?\r
ofonod[1306]: Aux: < \r\n+COPS: 0,2,"22201",0\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/network-registration.c[395]:cops_numeric_cb() Cops numeric got mcc: 222, mnc: 01
ofonod[1306]: Aux: > AT+CIND?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CIND: 0,5,1,0,1,0,0,0,2\r\n\r\nOK\r\n
ofonod[1306]: 09:33:58|src/network.c[1536]:ofono_netreg_strength_notify() strength 40
ofonod[1306]: Aux: > AT+COPS=3,0\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +COPS: 0,0,"I TIM",0\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/network-registration.c[344]:cops_cb() cops_cb: I TIM, 222 01 0
ofonod[1306]: 09:33:58|src/network.c[1219]:current_operator_callback() 0x88eb2f8, 0x88fafa0
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Modem: < +CGREG: 1,"4A3A","F66A",0,"01"\r\n
ofonod[1306]: Aux: < +CGREG: 1,"4A3A","F66A",0,"01"\r\n
ofonod[1306]: 09:34:04|src/gprs.c[2223]:ofono_gprs_status_notify() /he910_0 status 1
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < #PSNT: 1\r\n\r\n+CIEV: rssi,3\r\n
ofonod[1306]: 09:33:58|src/network.c[1536]:ofono_netreg_strength_notify() strength 60
ofonod[1306]: Modem: < #PSNT: 1\r\n
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < +CGREG: 1,"F051","5FA2B40",2,"00"\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CGREG: 1,"F051","5FA2B40",2,"00"\r\n
ofonod[1306]: 09:34:04|src/gprs.c[2223]:ofono_gprs_status_notify() /he910_0 status 1
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Modem: < +CREG: 1,"F051","5FA2B40",2\r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CREG: 1,"F051","5FA2B40",2\r\n
ofonod[1306]: 09:33:58|src/network.c[1349]:ofono_netreg_status_notify() /he910_0 status 1 tech 2
ofonod[1306]: 09:34:04|src/gprs.c[1674]:netreg_status_changed() 1
ofonod[1306]: Aux: > AT+COPS=3,2\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS?\r
ofonod[1306]: Aux: < \r\n+COPS: 0,2,"22201",2\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/network-registration.c[395]:cops_numeric_cb() Cops numeric got mcc: 222, mnc: 01
ofonod[1306]: Aux: > AT+CIND?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CIND: 0,0,1,0,1,0,0,0,3\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS=3,0\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +COPS: 0,0,"I TIM",2\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/network-registration.c[344]:cops_cb() cops_cb: I TIM, 222 01 2
ofonod[1306]: 09:33:58|src/network.c[1219]:current_operator_callback() 0x88eb2f8, 0x88fafa0
ofonod[1306]: Modem: < \r\n#PSNT: 3\r\n
ofonod[1306]: Aux: < \r\n#PSNT: 3\r\n\r\n+CIEV: rssi,2\r\n
ofonod[1306]: 09:33:58|src/network.c[1536]:ofono_netreg_strength_notify() strength 40
ofonod[1306]: Modem: < \r\n
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Modem: < +CGREG: 1,"F051","5FA00F6",2,"00"\r\n\r\n+CREG: 1,"F051","5FA00F6",2\r\n
ofonod[1306]: Aux: < +CGREG: 1,"F051","5FA00F6",2,"00"\r\n\r\n+CREG: 1,"F051","5FA00F6",2\r\n
ofonod[1306]: 09:34:04|src/gprs.c[2223]:ofono_gprs_status_notify() /he910_0 status 1
ofonod[1306]: 09:33:58|src/network.c[1349]:ofono_netreg_status_notify() /he910_0 status 1 tech 2
ofonod[1306]: 09:34:04|src/gprs.c[1674]:netreg_status_changed() 1
ofonod[1306]: Aux: > AT+COPS=3,2\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +COPS: 0,2,"22201",2\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/network-registration.c[395]:cops_numeric_cb() Cops numeric got mcc: 222, mnc: 01
ofonod[1306]: Aux: > AT+CIND?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +CIND: 0,4,1,0,1,0,0,0,2\r\n\r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS=3,0\r
ofonod[1306]: Aux: < \r\nOK\r\n
ofonod[1306]: Aux: > AT+COPS?\r
ofonod[1306]: Aux: < \r\n
ofonod[1306]: Aux: < +COPS: 0,0,"I TIM",2\r\n\r\nOK\r\n
ofonod[1306]: 09:33:40|drivers/atmodem/network-registration.c[344]:cops_cb() cops_cb: I TIM, 222 01 2
ofonod[1306]: 09:33:58|src/network.c[1219]:current_operator_callback() 0x88eb2f8, 0x88fafa0

Re: AT channel problem

[Enrico Sau]

[-- Attachment #1: Type: text/plain, Size: 2197 bytes --]

Hi Denis,

I managed to handle the garbage adding a new syntax which is the copy/paste
of gsm_permissive plus a new state.
Here is how the new feed looks:

static GAtSyntaxResult gsm_telit_feed(GAtSyntax *syntax,  const char
*bytes, gsize *len)
{
gsize i = 0;
GAtSyntaxResult res = G_AT_SYNTAX_RESULT_UNSURE;

while (i < *len) {
char byte = bytes[i];

switch (syntax->state) {
case GSM_TELIT_STATE_IDLE:
if (byte == '\r' || byte == '\n')
/* ignore */;
else if (byte == '>')
syntax->state = GSM_TELIT_STATE_PROMPT;
else if (byte == '~')
syntax->state = GSM_TELIT_STATE_GARBAGE;
else if (byte == '"')
syntax->state = GSM_TELIT_STATE_RESPONSE_STRING;
else
syntax->state = GSM_TELIT_STATE_RESPONSE;
break;

case GSM_TELIT_STATE_RESPONSE:
if (byte == '\r') {
syntax->state = GSM_TELIT_STATE_IDLE;

i += 1;
res = G_AT_SYNTAX_RESULT_LINE;
goto out;
} else if (byte == '"')
syntax->state =
GSM_TELIT_STATE_RESPONSE_STRING;
break;

case GSM_TELIT_STATE_RESPONSE_STRING:
if (byte == '"')
syntax->state = GSM_TELIT_STATE_RESPONSE;
break;

case GSM_TELIT_STATE_GUESS_PDU:
if (byte != '\r' && byte != '\n')
syntax->state = GSM_TELIT_STATE_PDU;
break;

case GSM_TELIT_STATE_PDU:
if (byte == '\r') {
syntax->state = GSM_TELIT_STATE_IDLE;

i += 1;
res = G_AT_SYNTAX_RESULT_PDU;
goto out;
}
break;

case GSM_TELIT_STATE_PROMPT:
if (byte == ' ') {
syntax->state = GSM_TELIT_STATE_IDLE;
i += 1;
res = G_AT_SYNTAX_RESULT_PROMPT;
goto out;
}

syntax->state = GSM_TELIT_STATE_RESPONSE;
return G_AT_SYNTAX_RESULT_UNSURE;

case GSM_TELIT_STATE_GUESS_SHORT_PROMPT:
if (byte == '\n')
/* ignore */;
else if (byte == '\r')
syntax->state = GSM_TELIT_STATE_SHORT_PROMPT;
else
syntax->state = GSM_TELIT_STATE_RESPONSE;
break;

case GSM_TELIT_STATE_SHORT_PROMPT:
if (byte == '\n') {
syntax->state = GSM_TELIT_STATE_IDLE;
i += 1;
res = G_AT_SYNTAX_RESULT_PROMPT;
goto out;
}

syntax->state = GSM_TELIT_STATE_RESPONSE;
return G_AT_SYNTAX_RESULT_UNSURE;


case GSM_TELIT_STATE_GARBAGE:
if (byte == '~')
syntax->state = GSM_TELIT_STATE_RESPONSE;
break;

default:
break;
};

i += 1;
}

out:
*len = i;
return res;
}

Enrico

[-- Attachment #2: attachment.html --]
[-- Type: text/html, Size: 15487 bytes --]

Re: AT channel problem

[Denis Kenzior]

[-- Attachment #1: Type: text/plain, Size: 2061 bytes --]

Hi Enrico,

On 05/09/2016 02:43 AM, Enrico Sau wrote:
> ofonod[1306]: Aux: < #QSS: 0\r\n
> ofonod[1306]: 09:33:54|plugins/he910.c[173]:he910_qss_notify() 0x88ef560
> ofonod[1306]: 09:33:54|plugins/he910.c[131]:switch_sim_state_status() 0x88ef560, SIM status: 0
> ofonod[1306]: 09:33:57|src/modem.c[496]:modem_change_state() old state: 3, new state: 1
> ofonod[1306]: 09:33:57|src/modem.c[409]:flush_atoms()
> ofonod[1306]: 09:34:04|src/gprs.c[2279]:gprs_context_unregister() 0x88eef68, 0x88ee908
> ofonod[1306]: 09:34:04|src/gprs.c[2413]:gprs_context_remove() atom: 0x88eef88
> ofonod[1306]: 09:33:42|drivers/atmodem/gprs-context.c[420]:at_gprs_context_remove()
> ofonod[1306]: 09:34:04|src/gprs.c[2644]:gprs_unregister() 0x88ee908
> ofonod[1306]: 09:33:58|src/network.c[1173]:__ofono_netreg_remove_status_watch() 0x88eb2d0
> ofonod[1306]: 09:34:04|src/gprs.c[2683]:gprs_remove() atom: 0x88ee970
> ofonod[1306]: 09:34:02|src/sim.c[2714]:ofono_sim_remove_spn_watch() 0x88ed6f0
> ofonod[1306]: 09:33:58|src/network.c[1836]:netreg_remove() atom: 0x88eb338
> ofonod[1306]: 09:34:09|src/telit-data-network.c[323]:telit_data_network_remove() atom: 0x88eb1c8
> ofonod[1306]: 09:34:09|src/telit-urc.c[668]:telit_urc_remove() atom: 0x88eb0a8
> ofonod[1306]: 09:34:05|src/radio-settings.c[657]:radio_settings_remove() atom: 0x88ee578
> ofonod[1306]: 09:33:28|plugins/udevng.c[1009]:remove_device() /sys/devices/virtual/net/ppp0
> ofonod[1306]: Aux: < \r\n
> ofonod[1306]: Aux: < +CGEV: NW DEACT IP, "2.194.193.31", 1\r\n
> ofonod[1306]: Modem: < ~\377}#\300!}%}"} }$Y(~

Now I get what is happening.  You're on a PPP link and pull the SIM.  So 
oFono tears everything down, but this results in the GAtChat going from 
PPP mode to normal mode too early.

We then receive the final HDLC frame, and that confuses the syntax. 
GSMv1 syntax already has code to handle this, but looks like the 
permissive one doesn't.

> ofonod[1306]: Modem: < \r\nNO CARRIER\r\n
> ofonod[1306]: Modem: < \r\n
> ofonod[1306]: Aux: < \r\n

Regards,
-Denis