Salamek / huawei-lte-api

API For huawei LAN/WAN LTE Modems
GNU Lesser General Public License v3.0
376 stars 92 forks source link

Issues with multi-part SMS messages (Type 2) #164

Closed biuklija closed 1 year ago

biuklija commented 1 year ago

The issue is present on a B525s-23a, I can't check for sure if other devices have the same problem.

In some cases my provider sends a multi-part message (consisting of two or more texts) and it takes a few seconds for them to all arrive. If I happen to poll for new messages during those few seconds while parts are incoming and happen to mark any of the parts as read, the message is never combined and parts remain under different indexes, usually completely out of order.

All of the parts are categorised as 'SmsType': '2', which I assume is multi-part.

I've tried to replicate the issue by sending my own multi-part messages, but these always came at the same time and were properly combined. Is this something we could prevent? Does the original API have a flag or status which would indicate that the original multi-part message has not yet been recombined?

Salamek commented 1 year ago

Hmm i don't really know to be frank i have never tested this at all, how are messages marked as read? Only by polling them? Does Web UI has same issues? (we cant possibly test for that when we can't reproduce the error by our self)

First we need a reliable way how to reproduce this issue so some experimenting can be done...

biuklija commented 1 year ago

Okay, so I've managed to reproduce the expected behaviour, but not issue. I've polled for new SMS messages every 100 milliseconds and this is what happens - messages are assigned indexes as they arrive and once the message is recombined, the parts are deleted/de-indexed and only the complete message is available, indexed as the message which first arrived. This is a truncated log, I've excluded any repeated messages. In this instance, I haven't been marking messages as read.

2022-12-22 17:58:24 Message 1: This is a very long text message that spans multiple SMS messages, now for some padding.......................................................
{'Smstat': '0', 'Index': '40017', 'Phone': '+XXXXXXXXXXX', 'Content': 'Message 1: This is a very long text message that spans multiple SMS messages, now for some padding.......................................................', 'Date': '2022-12-22 17:58:22', 'Sca': None, 'SaveType': '0', 'Priority': '0', 'SmsType': '2'}
2022-12-22 17:58:24 ....Message 2: This is a very long text message that spans multiple SMS messages, now for some padding...................................................
{'Smstat': '0', 'Index': '40018', 'Phone': '+XXXXXXXXXXX', 'Content': '....Message 2: This is a very long text message that spans multiple SMS messages, now for some padding...................................................', 'Date': '2022-12-22 17:58:22', 'Sca': None, 'SaveType': '0', 'Priority': '0', 'SmsType': '2'}
2022-12-22 17:58:25 ........Message 3: This is a very long text message that spans multiple SMS messages, now for some padding...............................................
{'Smstat': '0', 'Index': '40019', 'Phone': '+XXXXXXXXXXX', 'Content': '........Message 3: This is a very long text message that spans multiple SMS messages, now for some padding...............................................', 'Date': '2022-12-22 17:58:23', 'Sca': None, 'SaveType': '0', 'Priority': '0', 'SmsType': '2'}
2022-12-22 17:58:25 ............Message 4: This is a very long text message that spans multiple SMS messages, now for some padding...........................................
{'Smstat': '0', 'Index': '40025', 'Phone': '+XXXXXXXXXXX', 'Content': '............Message 4: This is a very long text message that spans multiple SMS messages, now for some padding...........................................', 'Date': '2022-12-22 17:58:23', 'Sca': None, 'SaveType': '0', 'Priority': '0', 'SmsType': '2'}
2022-12-22 17:58:25 Message 1: This is a very long text message that spans multiple SMS messages, now for some padding...........................................................Message 2: This is a very long text message that spans multiple SMS messages, now for some padding...........................................................Message 3: This is a very long text message that spans multiple SMS messages, now for some padding...........................................................Message 4: This is a very long text message that spans multiple SMS messages, now for some padding...........................................................
{'Smstat': '0', 'Index': '40017', 'Phone': '+XXXXXXXXXXX', 'Content': 'Message 1: This is a very long text message that spans multiple SMS messages, now for some padding...........................................................Message 2: This is a very long text message that spans multiple SMS messages, now for some padding...........................................................Message 3: This is a very long text message that spans multiple SMS messages, now for some padding...........................................................Message 4: This is a very long text message that spans multiple SMS messages, now for some padding...........................................................', 'Date': '2022-12-22 17:58:23', 'Sca': None, 'SaveType': '0', 'Priority': '0', 'SmsType': '2'}

On my second attempt, I've tried marking the parts as read as soon as they arrive. All the parts were marked as read (including the first part)), but when they were recombined the whole message was "unread".

2022-12-22 18:01:10 Message 1: This is a very long text message that spans multiple SMS messages, now for some padding.......................................................
{'Smstat': '0', 'Index': '40018', 'Phone': '+XXXXXXXXXXX', 'Content': 'Message 1: This is a very long text message that spans multiple SMS messages, now for some padding.......................................................', 'Date': '2022-12-22 18:01:08', 'Sca': None, 'SaveType': '0', 'Priority': '0', 'SmsType': '2'}
2022-12-22 18:01:10 ....Message 2: This is a very long text message that spans multiple SMS messages, now for some padding...................................................
{'Smstat': '0', 'Index': '40019', 'Phone': '+XXXXXXXXXXX', 'Content': '....Message 2: This is a very long text message that spans multiple SMS messages, now for some padding...................................................', 'Date': '2022-12-22 18:01:08', 'Sca': None, 'SaveType': '0', 'Priority': '0', 'SmsType': '2'}
2022-12-22 18:01:11 ........Message 3: This is a very long text message that spans multiple SMS messages, now for some padding...............................................
{'Smstat': '0', 'Index': '40025', 'Phone': '+XXXXXXXXXXX', 'Content': '........Message 3: This is a very long text message that spans multiple SMS messages, now for some padding...............................................', 'Date': '2022-12-22 18:01:08', 'Sca': None, 'SaveType': '0', 'Priority': '0', 'SmsType': '2'}
2022-12-22 18:01:11 ............Message 4: This is a very long text message that spans multiple SMS messages, now for some padding...........................................
{'Smstat': '0', 'Index': '40026', 'Phone': '+XXXXXXXXXXX', 'Content': '............Message 4: This is a very long text message that spans multiple SMS messages, now for some padding...........................................', 'Date': '2022-12-22 18:01:09', 'Sca': None, 'SaveType': '0', 'Priority': '0', 'SmsType': '2'}
2022-12-22 18:01:11 Message 1: This is a very long text message that spans multiple SMS messages, now for some padding...........................................................Message 2: This is a very long text message that spans multiple SMS messages, now for some padding...........................................................Message 3: This is a very long text message that spans multiple SMS messages, now for some padding...........................................................Message 4: This is a very long text message that spans multiple SMS messages, now for some padding...........................................................
{'Smstat': '0', 'Index': '40018', 'Phone': '+XXXXXXXXXXX', 'Content': 'Message 1: This is a very long text message that spans multiple SMS messages, now for some padding...........................................................Message 2: This is a very long text message that spans multiple SMS messages, now for some padding...........................................................Message 3: This is a very long text message that spans multiple SMS messages, now for some padding...........................................................Message 4: This is a very long text message that spans multiple SMS messages, now for some padding...........................................................', 'Date': '2022-12-22 18:01:09', 'Sca': None, 'SaveType': '0', 'Priority': '0', 'SmsType': '2'}

It is possible that the issue I've raised only occurs if you mark certain parts as read as they arrive, instead of all of them or none of them, possibly because of the indexes. My old script based on the relay example did this, as it polled only one unread text at a time. I'm not sure how to reproduce the bug.

Salamek commented 1 year ago

I have put some thought into this, and i think this is race-condition in huawei firmware... Since it would be very hard to put a modem into this situation when using official web UI (there is very small chance that user using official web UI will be able to read one SMS of multi part SMS before it is able to recombine correctly).

So this is technically 'wontfix' since there is nothing i can do with huawei FW, BUT i think i have also came with hack how to prevent this from happening when using the huawei-lte-api when polling SMS.

Lets say we have this untested code as a example of usage that will "trigger" this race-condition:

from huawei_lte_api.Session import Session
from huawei_lte_api.User import UserSession
from huawei_lte_api.Sms import Sms
from huawei_lte_api.enums.sms import BoxTypeEnum

while True:
    try:
        with Session('http://192.168.8.1') as session:
            with UserSession('admin', 'admin'):
                sms = Sms(session)
                fetched_sms = sms.get_sms_list(1, BoxTypeEnum.LOCAL_INBOX, 1, 0, 0, 1)

                # Check if we have any messages
                if not fetched_sms.get('Messages'):
                    continue

                message = fetched_sms.get('Messages', {}).get('Message', {})

                message_index = int(message.get('Index'))
                message_stat = int(message.get('Smstat'))
                message_type = int(message.get('SmsType'))
                message_content = message.get('Content')

                # Skip read message
                if message_stat == 1:
                    continue

                # Process our SMS
                print('You have new SMS:')
                print(message_content)

                # mark message read
                sms.set_read(message_index)
    except Exception as e:
        print('Something failed: {}'.format(e))

    time.sleep(60) # Check every minute

And here are changes (untested) to ~prevent that race condition by check if message is type==2 if is type 2 ignore it until is older then specified type (60 seconds) that should provide enough time for all parts to be received and merged:

import datetime
import aniso8601
from huawei_lte_api.Session import Session
from huawei_lte_api.User import UserSession
from huawei_lte_api.Sms import Sms
from huawei_lte_api.enums.sms import BoxTypeEnum

while True:
    now = datetime.datetime.now()
    try:
        with Session('http://192.168.8.1') as session:
            with UserSession('admin', 'admin'):
                sms = Sms(session)
                fetched_sms = sms.get_sms_list(1, BoxTypeEnum.LOCAL_INBOX, 1, 0, 0, 1)

                # Check if we have any messages
                if not fetched_sms.get('Messages'):
                    continue

                message = fetched_sms.get('Messages', {}).get('Message', {})

                message_index = int(message.get('Index'))
                message_date = aniso8601.parse_datetime(message.get('Date'))
                message_stat = int(message.get('Smstat'))
                message_type = int(message.get('SmsType'))
                message_content = message.get('Content')

                # Skip read message
                if message_stat == 1:
                    continue

                # Check if message is possibly multipart,
                # if it is ignore it if is younger then 60 seconds
                # This way we provide the router with enough time to receive all possible parts and do correct rebuild
                if message_type == 2 and message_date + datetime.timedelta(seconds=60) > now:
                    continue

                # Process our SMS
                print('You have new SMS:')
                print(message_content)

                # mark message read
                sms.set_read(message_index)
    except Exception as e:
        print('Something failed: {}'.format(e))

    time.sleep(60) # Check every minute
biuklija commented 1 year ago

I've figured as much, it's a very specific issue and I assume the firmware itself has similar code which will hold off triggering the "new message" flag until the message is recombined. That's why the the Type flag is there in the first place, I suppose. I'll test out your proposed solution in coming days and report back. It wouldn't hurt to leave a note about this somewhere in the documentation.

biuklija commented 1 year ago

Proposed solution works as intended, the only issue is that aniso8601.parse_datetime expects a "T" delimiter, whereas the API provides a space.

message_date = aniso8601.parse_datetime(msg_text.get('Date'), delimiter=' ')
Salamek commented 1 year ago

Yea i have expected there may be some small issue in datetime parsing.... hmm i think i can use simple datetime.strptime to parse this datetime format, it will save me one dependency

Salamek commented 1 year ago

Also is not 60 seconds too much? what delay between parted SMS did you observe?

biuklija commented 1 year ago

60 seconds is way too much in my opinion. I've used 5 seconds this time around, it was more than enough. You can see from my earlier tests that it took less than two seconds for my four-part SMS message to arrive (first part arrived at 17:58:24, fully recombined at 17:58:25 and I waited 500 ms between polls, if memory serves). It probably depends on the length and network conditions, but I doubt it would ever take more than 5 seconds.

Salamek commented 1 year ago

1.6.10 Implements new method Sms.get_messages that implements this fix and also yields new dataclass Message with SMS info