search

wdoekes / asterisk-chan-dongle

chan_dongle channel driver for Huawei UMTS cards, works with Asterisk 14+
Other
298 stars 104 forks source link

Error reading SMS message #97

Open xakepShilo opened 4 years ago

xakepShilo commented 4 years ago

When starting the module, error: 

ERROR[8664]: at_response.c:481 at_response_error: [Tele2_1] Error reading SMS message
ERROR[8664]: at_response.c:481 at_response_error: [Tele2_2] Error reading SMS message

After starting, it works without errors.

Asterisk 13.14.1 Huawei E1550 - two modems

P.S. Sorry for my bad english :))

turbozapekanka commented 4 years ago

I also get tons of these messages on start

[2020-06-08 09:23:48] ERROR[9846]: at_response.c:481 at_response_error: [mts0] Error reading SMS message [2020-06-08 09:23:48] ERROR[9846]: at_response.c:481 at_response_error: [mts0] Error reading SMS message

hselasky commented 4 years ago

Those error messages are normal. It just means the dongle driver is trying to empty the SMS inbox at startup and that there aren't any SMS messages in there. Not all modems supports inbox query via AT commands, so each and every message must be poked by number during startup to avoid leaving messages behind on the SIM.

wdoekes commented 4 years ago

Well.. in that case perhaps those logs should be toned down to NOTICE level.

(Or DEBUG, if there really are tons of them.)

hselasky commented 4 years ago

Sure. It only happens during startup. Feel free to submit a patch.

wdoekes commented 4 years ago

image

xakepShilo commented 4 years ago

Well.. in that case perhaps those logs should be toned down to NOTICE level.

(Or DEBUG, if there really are tons of them.)

Messages (errors) are really very many!

P.S. 100 error messages! If a call arrives at this moment, it will not be processed. Will give an error. That is, this action suspends the handler.

miopa commented 4 years ago

In my case, the error messages are more than 200. It's always a fixed number of messages for a given modem, but different for each modem I tested.

It's happening on each modem init (e.g. when modem disconnects from network and reconnects again). The initial modem state is SMS, then the messages are displayed and then modem goes to state Free and resumes normal operation.

On slower systems with multiple modems, before these errors, two additional errors may appear:

at_response.c:342 at_response_error: [vip2] Command 'AT+CNUM' failed

This is the more frequent one, resulting in the number stored on the SIM not being used by the driver (it says Private in the dongle state). Sometimes, this error could be followed by:

at_response.c:538 at_response_error: [vip2] Received 'ERROR' for unhandled command 'AT+CSCA'

In which case the dongle state is Not initialized and is ignored by Asterisk (but still responds to dongle commands)

EDIT: dongle restart ... fixes both of these dongle state errors

miopa commented 4 years ago

Not all modems supports inbox query via AT commands, so each and every message must be poked by number during startup to avoid leaving messages behind on the SIM.

Do you have a list of these modems? Maybe this procedure should be done only for them. I've never run into this issue with about 10 different models I've used so far.

xakepShilo commented 4 years ago

On slower systems with multiple modems, before these errors, two additional errors may appear:

at_response.c:342 at_response_error: [vip2] Command 'AT+CNUM' failed

Yes, sometimes this error also appeared.

miopa commented 4 years ago

This bug seems more serious than just ERROR messages.

A call was originated from the modem right after driver reload, in-between the errors:

[2020-06-21 07:18:58] ERROR[11236] at_response.c: [vip1] Error reading SMS message
[2020-06-21 07:18:58] VERBOSE[11253][C-00000001] pbx.c: Executing [s@macro-dialout-trunk:31] Dial("Local/0XXXXXXXX@from-internal-00000001;2", "Dongle/vip1/0XXXXXXXX,300,M(callback-answered)") in new stack
[2020-06-21 07:18:58] ERROR[11236] at_response.c: [vip1] Error reading SMS message
[2020-06-21 07:18:58] VERBOSE[11253][C-00000001] app_dial.c: Called Dongle/vip1/0XXXXXXXX
[2020-06-21 07:18:58] ERROR[11236] at_response.c: [vip1] Error reading SMS message
[2020-06-21 07:18:58] VERBOSE[11253][C-00000001] app_dial.c: Dongle/vip1-0100000000 is making progress passing it to Local/0XXXXXXXX@from-internal-00000001;2
[2020-06-21 07:18:58] VERBOSE[11252] dial.c: Local/0XXXXXXXX@from-internal-00000001;1 is making progress
[2020-06-21 07:18:58] ERROR[11236] at_response.c: [vip1] Error reading SMS message
-----------//-----------
[2020-06-21 07:19:15] VERBOSE[11253][C-00000001] app_dial.c: Dongle/vip1-0100000000 answered Local/0XXXXXXXX@from-internal-00000001;2

Dongle state was stuck at Dialing, and the line dropped after 5 seconds:

[2020-06-21 07:19:20] VERBOSE[11327][C-00000001] bridge_channel.c: Channel Dongle/vip1-0100000000 left 'simple_bridge' basic-bridge <730f52fd-6848-474a-a074-c43313ed54c8>
[2020-06-21 07:19:20] VERBOSE[11253][C-00000001] bridge_channel.c: Channel Local/0XXXXXXXX@from-internal-00000001;2 left 'simple_bridge' basic-bridge <730f52fd-6848-474a-a074-c43313ed54c8>

Dongle state was still Dialing for a minute or two more.

easyyu commented 4 years ago

Is there any fix about this? I got aprox 100 messages per dongle. Im using Huawei E1550 and 153. Asterisk 13.34, and today I compiled the master branch of chan_dongle. The error message appears when asterisk is loading and it looks like: ...... [Jun 24 03:05:24] ERROR[11577]: at_response.c:481 at_response_error: [dongle0] Error reading SMS message [Jun 24 03:05:24] ERROR[11577]: at_response.c:481 at_response_error: [dongle0] Error reading SMS message [Jun 24 03:05:24] ERROR[11577]: at_response.c:481 at_response_error: [dongle0] Error reading SMS message [Jun 24 03:05:24] ERROR[11577]: at_response.c:481 at_response_error: [dongle0] Error reading SMS message [Jun 24 03:05:24] ERROR[11577]: at_response.c:481 at_response_error: [dongle0] Error reading SMS message [Jun 24 03:05:24] ERROR[11577]: at_response.c:481 at_response_error: [dongle0] Error reading SMS message ..... ..... [Jun 24 03:05:26] ERROR[11578]: at_response.c:481 at_response_error: [dongle1] Error reading SMS message [Jun 24 03:05:26] ERROR[11578]: at_response.c:481 at_response_error: [dongle1] Error reading SMS message [Jun 24 03:05:26] ERROR[11578]: at_response.c:481 at_response_error: [dongle1] Error reading SMS message [Jun 24 03:05:26] ERROR[11578]: at_response.c:481 at_response_error: [dongle1] Error reading SMS message ...... It is very annoying, and we will be greatfull if it could be hiden in some way! Thx

easyyu commented 4 years ago

I compiled the master branch..and same..I got a tons of error messages. What I'm doing wrong? I even manulay deleted chan_dongle.so file in /usr/lib/asterisk/modules/ before compile. Restarted asterisk after comiple. But its same...

hselasky commented 4 years ago

Please ignore those error messages. They only happen during startup.

xakepShilo commented 4 years ago

Please ignore those error messages. They only happen during startup.

Not! This also works in other cases. And 100 is too much!

hselasky commented 4 years ago

Do you mean the disk becomes out of space for logging?

I won't object to a fix to hide these errors. Right now the chan_dongle works as expected, regardless of the error codes, and I have other computer work in higher priority :-(

xakepShilo commented 4 years ago

Do you mean the disk becomes out of space for logging?

I won't object to a fix to hide these errors. Right now the chan_dongle works as expected, regardless of the error codes, and I have other computer work in higher priority :-(

OK! Now the old version is working, and I'm on a business trip. As soon as I get back, I’ll make a log and post it here.

miopa commented 4 years ago

@hselasky I object, chan_dongle is absolutely not ready for production with the bugs I described in this thread (https://github.com/wdoekes/asterisk-chan-dongle/issues/97#issuecomment-647191949, https://github.com/wdoekes/asterisk-chan-dongle/issues/97#issuecomment-645049956)

They were introduced in the same merge that introduced the error messages and they seem tightly related.

hselasky commented 4 years ago

@miopa: I'm using chan_dongle every day 24/7. Maybe it depends on the brand of USB modem you've got how well it works. Please be more specific.

miopa commented 4 years ago

@hselasky I'm using it on about 20 production systems ranging from raspberry-pi to brand name servers, some of them since long before this fork was created. There are modems sending or receiving thousands of SMS and hundreds of calls per day. The issues I described here happened in the first week after putting this version on a low volume system with 3 modems, E1552 and E173 (both models were affected).

I've had the issue with messages stuck in storage resolved by periodically issuing AT+CMGD=1,4 to modems, and that worked for every model that I've used so far, regardless if modem or SIM is used as storage.

hselasky commented 4 years ago

@miopa: The issue described only happens during startup. Do you see ERROR messages after startup?

hselasky commented 4 years ago

@miopa : Please note there is a big difference between automated systems (like Raspberry PI), sending fixed SMS strings and human input. The last round of fixes for SMS that are made are fully required for stable operation receiving any kind of SMS, not just automated strings.

hselasky commented 4 years ago

I've had the issue with messages stuck in storage resolved by periodically issuing AT+CMGD=1,4 to modems, and that worked for every model that I've used so far, regardless if modem or SIM is used as storage.

How do you insert this AT command during usage?

easyyu commented 4 years ago

It is simply annoying to have more than 100 errors per modem. Do not understand why this wasn't before and why it is so hard to hide. I see only if I restart the asterisk!

miopa commented 4 years ago

The issue described only happens during startup. Do you see ERROR messages after startup?

Yes, when modem is reset or re-initializes (this can happen after losing carrier network or USB bus connection, or because of some internal firmware bug)

miopa commented 4 years ago

How do you insert this AT command during usage?

dongle cmd dongle0 AT+CMGD=1,4

miopa commented 4 years ago

Please note there is a big difference between automated systems (like Raspberry PI), sending fixed SMS strings and human input. The last round of fixes for SMS that are made are fully required for stable operation receiving any kind of SMS, not just automated strings.

Is there a way I can reproduce the issue you're describing?

hselasky commented 4 years ago

There are some AT command dumps for receiving SMS PDU's in the commit logs. It depends on your operator what headers are inserted into the SMS PDU itself. There were some bugs in this area making it hard to receive SMS in Norway for example.

hselasky commented 4 years ago

@easyyu : I understand. But again, I'm not paid to support this project. It is all volunteer and you can also suggest a patch!

wdoekes commented 4 years ago

Note that PR #107 attempts to hide some errors and make them debug-level instead. Feel free to test and comment.

miopa commented 4 years ago

There are some AT command dumps for receiving SMS PDU's in the commit logs. It depends on your operator what headers are inserted into the SMS PDU itself. There were some bugs in this area making it hard to receive SMS in Norway for example.

@hselasky Is AT+CPMS=? unreliable in that case? It returns the storage size and how many messages are in there. If 0, no need to do all that poking.

hselasky commented 4 years ago

I can check. I tried to look for something like this before, and found not all modems supports it.

hselasky commented 4 years ago

If AT+CPMS=? returns a valid value use that, else fallback to the current logic?

xakepShilo commented 4 years ago

Note that PR #107 attempts to hide some errors and make them debug-level instead. Feel free to test and comment.

The fix really works.

There are no errors, but, as I understand it, the problem itself does not solve. Since it just does not display an error, but the channel freezes for processing time:

[2020-07-02 14:40:28] NOTICE[14553] chan_dongle.c: [Tele2_1] Loaded device
[2020-07-02 14:40:28] NOTICE[14553] chan_dongle.c: [Tele2_2] Loaded device
[2020-07-02 14:40:29] ERROR[14555] at_response.c: [Tele2_1] Error reading SMS message
[2020-07-02 14:40:29] ERROR[14555] at_response.c: [Tele2_1] Error reading SMS message
[2020-07-02 14:40:29] ERROR[14555] at_response.c: [Tele2_1] Error reading SMS message
[2020-07-02 14:40:29] ERROR[14555] at_response.c: [Tele2_1] Error reading SMS message
......
[2020-07-02 14:40:31] ERROR[14556] at_response.c: [Tele2_2] Error reading SMS message
[2020-07-02 14:40:31] ERROR[14556] at_response.c: [Tele2_2] Error reading SMS message
[2020-07-02 14:40:31] ERROR[14556] at_response.c: [Tele2_2] Error reading SMS message
[2020-07-02 14:40:31] ERROR[14556] at_response.c: [Tele2_2] Error reading SMS message
[2020-07-02 14:40:34] ERROR[14555] chan_dongle.c: [Tele2_1] timedout while waiting '+CMGR' in response to 'AT+CMGR'
[2020-07-02 14:40:44] ERROR[14557] at_response.c: [Tele2_1] Error reading SMS message
[2020-07-02 14:40:44] ERROR[14557] at_response.c: [Tele2_1] Error reading SMS message
[2020-07-02 14:40:44] ERROR[14557] at_response.c: [Tele2_1] Error reading SMS message
[2020-07-02 14:40:44] ERROR[14557] at_response.c: [Tele2_1] Error reading SMS message
....
[2020-07-02 14:40:45] ERROR[14557] at_response.c: [Tele2_1] Error reading SMS message
[2020-07-02 14:40:45] ERROR[14557] at_response.c: [Tele2_1] Error reading SMS message
[2020-07-02 14:40:45] ERROR[14557] at_response.c: [Tele2_1] Error reading SMS message
[2020-07-02 14:40:46] ERROR[14557] at_response.c: [Tele2_1] Error reading SMS message

[2020-07-02 14:40:34] ERROR[14555] chan_dongle.c: [Tele2_1] timedout while waiting '+CMGR' in response to 'AT+CMGR' - this error exists after the fix. But not every launch.

miopa commented 4 years ago

If AT+CPMS=? returns a valid value use that, else fallback to the current logic?

That makes sense, but I've yet to find a modem that is not supporting it, we should document it if discovered. I imagine it would be more likely that some SIM cards are incompatible and the reason for the command failure. If that is indeed true, maybe it would be better to use modem storage for those cards.

If AT+CPMS? returns 0 stored messages - do nothing, if non-zero, fallback to current logic.

There is a good explanation of this command at https://www.developershome.com/sms/cpmsCommand3.asp

miopa commented 4 years ago

@hselasky This got me thinking a bit, were the stuck messages already 'displayed' by the driver? If yes, then the startup fix could be as simple as issuing AT+CMGD=1,4 after storage selection (if autodeletesms flag is set)

hselasky commented 4 years ago

@miopa : The problem in the past is that incoming SMS messages simply "got lost" and then I one day got SMS memory full indication. Apparently, nothing was lost, just that the messages never got read out. This was embarrassing. Yes, if autodelete is on and AT+CPMS returns something useful, then iterate only that number of messages, starting at 1. I believe message 0 is not valid. Else fallback to forced readout. Seems like a valid solution.

miopa commented 4 years ago

@hselasky Does your current fix prevent filling of msg storage during operation? Can I stop the periodic cleanup with AT+CMGD=1,4?

hselasky commented 4 years ago

It solves a race if the device reports multiple MSG IDs received in short time.

hselasky commented 4 years ago

If you parse the output from AT+CMGD=1,4, probably yes.

standardgbg commented 1 year ago

Hi,

I reasently got this problem with one of my dongles (E1750). The log get spammed with "[Dec 27 00:17:43] ERROR[16782]: at_response.c:287 log_cmd_response_error: [dongle0] Error reading SMS message" and also sometimes "[Dec 27 00:17:43] WARNING[16782]: at_response.c:1281 at_response_cmgr: [dongle0] Error parsing incoming message: Invalid charset" Is this the same problem? The dongle memory doesn't seem to be full. AT+CPMS? returns: [Dec 28 23:06:37] NOTICE[24358]: at_response.c:1808 at_response: [dongle0] Got Response for user's command:'+CPMS: "SM",2,25,"SM",2,25,"SM",2,25' and if I understand that corectly the memory has 1 message of 25. Is there some way of retreving the SMS to debug it?