Re: not "delivered" status report

classic Classic list List threaded Threaded
1 message Options
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: not "delivered" status report

amalysh
Hi Hakim,

please don’t crosspost both mailing lists.

As far as I see you are using internal DLR storage.
2017-05-19 12:47:50 [455] [6] DEBUG: DLR[internal]: Looking for DLR smsc=multic3, ts=37, dst=<a href="tel:+33%206%2014%2047%2021%2099" value="+33614472199" target="_blank" class="">+33614472199, type=1
                                     ^^^^^^^^^^^^^

Are you sure that you didn’t restart bearerbox in between, because internal DLR storage is not persistent and mainly purpose of it is for testing ? 

Thanks,
Alex

Am 27.07.2017 um 17:21 schrieb Hakim Bimazgane <[hidden email]>:

Hi,

Time passed but my DLR problem is still here, and I've got now 2 kannel servers for 3 modems, and the problem of the non-reliable "Delivered" DLRs appears on the 3 modems...

I checked with Multitech support, and they seems to agree on the fact that Kannel is making the problem here.

I sent them those 2 cases (one success / one failure):

the success one:

2017-05-19 12:43:59 [455] [6] DEBUG: AT2[multic3]: <-- +CDS: 25
2017-05-19 12:43:59 [455] [6] DEBUG: AT2[multic3]: <-- 07913366003000F006220B913366930401F3715091014400807150910144008000
2017-05-19 12:43:59 [455] [6] DEBUG: AT2[multic3]: received message from SMSC: <a href="tel:+33%206%2060%2000%2030%2000" value="+33660003000" target="_blank" class="">+33660003000
2017-05-19 12:43:59 [455] [6] DEBUG: AT2[multic3]: got STATUS-REPORT for message <34>:
2017-05-19 12:43:59 [455] [6] DEBUG: AT2[multic3]: Numeric receiver (international) <<a href="tel:+33%206%2063%2094%2001%2003" value="+33663940103" target="_blank" class="">+33663940103>
2017-05-19 12:43:59 [455] [6] DEBUG: DLR[internal]: Looking for DLR smsc=multic3, ts=34, dst=<a href="tel:+33%206%2063%2094%2001%2003" value="+33663940103" target="_blank" class="">+33663940103, type=1
2017-05-19 12:43:59 [455] [6] DEBUG: DLR[internal]: created DLR message for URL <<a href="http://localhost/playsms/index.php?app=call&amp;cat=gateway&amp;plugin=kannel&amp;access=dlr&amp;type=%d&amp;smslog_id=277&amp;uid=2&amp;smsc=multic3" target="_blank" class="">http://localhost/playsms/index.php?app=call&cat=gateway&plugin=kannel&access=dlr&type=%d&smslog_id=277&uid=2&smsc=multic3>
2017-05-19 12:44:01 [455] [6] DEBUG: AT2[multic3]: TP-Validity-Period: 24.0 hours

and here is the failing one:

2017-05-19 12:47:47 [455] [6] DEBUG: DLR[internal]: Adding DLR smsc=multic3, ts=39, src=1234, dst=<a href="tel:+33%206%2014%2047%2021%2099" value="+33614472199" target="_blank" class="">+33614472199, mask=31, boxc=
2017-05-19 12:47:47 [455] [6] DEBUG: SMSC[multic3]: creating DLR message
2017-05-19 12:47:47 [455] [6] DEBUG: SMSC[multic3]: DLR = <a href="http://localhost/playsms/index.php?app=call&amp;cat=gateway&amp;plugin=kannel&amp;access=dlr&amp;type=%d&amp;smslog_id=545&amp;uid=2&amp;smsc=multic3" target="_blank" class="">http://localhost/playsms/index.php?app=call&cat=gateway&plugin=kannel&access=dlr&type=%d&smslog_id=545&uid=2&smsc=multic3
2017-05-19 12:47:50 [455] [6] DEBUG: AT2[multic3]: <-- +CDS: 25
2017-05-19 12:47:50 [455] [6] DEBUG: AT2[multic3]: <-- 07913366003000F006250B913316442791F9715091018400807150910184008000
2017-05-19 12:47:50 [455] [6] DEBUG: AT2[multic3]: received message from SMSC: <a href="tel:+33%206%2060%2000%2030%2000" value="+33660003000" target="_blank" class="">+33660003000
2017-05-19 12:47:50 [455] [6] DEBUG: AT2[multic3]: got STATUS-REPORT for message <37>:
2017-05-19 12:47:50 [455] [6] DEBUG: AT2[multic3]: Numeric receiver (international) <<a href="tel:+33%206%2014%2047%2021%2099" value="+33614472199" target="_blank" class="">+33614472199>
2017-05-19 12:47:50 [455] [6] DEBUG: DLR[internal]: Looking for DLR smsc=multic3, ts=37, dst=<a href="tel:+33%206%2014%2047%2021%2099" value="+33614472199" target="_blank" class="">+33614472199, type=1
2017-05-19 12:47:50 [455] [6] WARNING: DLR[internal]: DLR from SMSC<multic3> for DST<<a href="tel:+33%206%2014%2047%2021%2099" value="+33614472199" target="_blank" class="">+33614472199> not found.
2017-05-19 12:47:50 [455] [6] DEBUG: AT2[multic3]: Received delivery notification but can't find that ID in the DLR storage
2017-05-19 12:47:50 [455] [6] DEBUG: System error 1: Operation not permitted
2017-05-19 12:47:50 [455] [6] ERROR: AT2[multic3]: could not decode PDU to a message.

And here is the response from Multitech:

Your test 1:
Module output following acknowledgement to application which module received from network:
07913366003000F006250B913316442791F9715091018400807150910184008000

Your test 2:
Module output following acknowledgement to application which module received from network:
07913366003000F006220B913366930401F3715091014400807150910144008000

Your test 1 & 2
When you look at modem output side by side structure is identical
07913366003000F006250B913316442791F9715091018400807150910184008000
07913366003000F006220B913366930401F3715091014400807150910144008000

Per Steve suggestion I used SMS application to interpret the acknowledgments and it had no issues with either message. So it appears the error is not due to the structure of the acknowledgment. See attached images illustrating the messages are similar in structure and not in error. 

The module forwards acknowledgements it receives from network to the application when the messages arrive. Message received from network/output to application appears to be structurally correct. This does not appear to be a device/module issue but an issue with SMS software not finding a match for acknowledgement being received from cellular network. This assessment is based on log indicating "can't find that ID in the DLR storage." We are not familiar with this software so we would suggest you ask SMS application support why their application is not finding a match for acknowledgements received from network in 40-60% of cases.


So, how do I fix this wierd bug ? And also, how I'm the only one getting this ?
Can anyone help me make the Delivered DLR works with Kannel ?

If it needs to change the source code of Kannel, I'm okay with that, but just give me some hints on where I can find the bug in the source code.

Thanks,
 
 

Hakim BIMAZGANE
Lead Developer

Vitalliance


2016-10-20 18:16 GMT+02:00 Hakim Bimazgane <[hidden email]>:
Hi,

I'm using Kannel version 1.5.0 on a Debian x64 with PlaySMS 1.4.
I use a MultiTech MultiConnect Cell 100 (MTC-H5-B03-KIT) as GSM modem.

I got some problems with some DLRs (concatened SMS activated).

I see on my app and on playSMS that I receive the "sent" status, but I got very rarely the "delivered" status.

I don't know, but I think it's about errors I got after the +CDS command:

2016-10-20 17:23:37 [22525] [6] DEBUG: AT2[multic1]: detecting modem type
2016-10-20 17:23:37 [22525] [6] INFO: AT2[multic1]: opening device
2016-10-20 17:23:37 [22525] [6] DEBUG: AT2[multic1]: device opened. Telnet mode = 0
2016-10-20 17:23:38 [22525] [6] DEBUG: AT2[multic1]: device opened
2016-10-20 17:23:38 [22525] [6] INFO: AT2[multic1]: speed set to 115200
2016-10-20 17:23:38 [22525] [6] DEBUG: AT2[multic1]: --> ATZ^M
2016-10-20 17:23:38 [22525] [6] DEBUG: AT2[multic1]: <-- OK
2016-10-20 17:23:38 [22525] [6] DEBUG: AT2[multic1]: --> AT^M
2016-10-20 17:23:38 [22525] [6] DEBUG: AT2[multic1]: <-- AT
2016-10-20 17:23:38 [22525] [6] DEBUG: AT2[multic1]: <-- OK
2016-10-20 17:23:38 [22525] [6] DEBUG: AT2[multic1]: --> ^M
2016-10-20 17:23:40 [22525] [6] DEBUG: AT2[multic1]: --> AT^M
2016-10-20 17:23:40 [22525] [6] DEBUG: AT2[multic1]: <-- AT
2016-10-20 17:23:40 [22525] [6] DEBUG: AT2[multic1]: <-- OK
2016-10-20 17:23:40 [22525] [6] DEBUG: AT2[multic1]: --> AT&F^M
2016-10-20 17:23:40 [22525] [6] DEBUG: AT2[multic1]: <-- AT&F
2016-10-20 17:23:40 [22525] [6] DEBUG: AT2[multic1]: <-- OK
2016-10-20 17:23:40 [22525] [6] DEBUG: AT2[multic1]: --> ATE0^M
2016-10-20 17:23:41 [22525] [6] DEBUG: AT2[multic1]: <-- ATE0
2016-10-20 17:23:41 [22525] [6] DEBUG: AT2[multic1]: <-- OK
2016-10-20 17:23:41 [22525] [6] DEBUG: AT2[multic1]: --> ATI^M
2016-10-20 17:23:41 [22525] [6] DEBUG: AT2[multic1]: <-- 332
2016-10-20 17:23:41 [22525] [6] DEBUG: AT2[multic1]: <-- OK
2016-10-20 17:23:41 [22525] [6] DEBUG: AT2[multic1]: found string <332>, using modem definition <Multitech>
2016-10-20 17:23:41 [22525] [6] DEBUG: AT2[multic1]: --> AT+CSMS=?^M
2016-10-20 17:23:41 [22525] [6] DEBUG: AT2[multic1]: <-- +CSMS: (0,1)
2016-10-20 17:23:41 [22525] [6] DEBUG: AT2[multic1]: <-- OK
2016-10-20 17:23:41 [22525] [6] INFO: AT2[multic1]: Phase 2+ is supported
2016-10-20 17:23:41 [22525] [6] INFO: AT2[multic1]: Closing device
2016-10-20 17:23:41 [22525] [6] INFO: AT2[multic1]: opening device
2016-10-20 17:23:41 [22525] [6] DEBUG: AT2[multic1]: device opened. Telnet mode = 0
2016-10-20 17:23:41 [22525] [6] DEBUG: AT2[multic1]: device opened
2016-10-20 17:23:41 [22525] [6] INFO: AT2[multic1]: Logging in
2016-10-20 17:23:41 [22525] [6] INFO: AT2[multic1]: init device
2016-10-20 17:23:41 [22525] [6] INFO: AT2[multic1]: speed set to 115200
2016-10-20 17:23:41 [22525] [6] DEBUG: AT2[multic1]: --> ATZ^M
2016-10-20 17:23:41 [22525] [6] DEBUG: AT2[multic1]: <-- OK
2016-10-20 17:23:41 [22525] [6] DEBUG: AT2[multic1]: --> AT^M
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: <-- AT
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: <-- OK
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: --> AT&F^M
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: <-- AT&F
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: <-- OK
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: --> ATE0^M
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: <-- ATE0
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: <-- OK
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: --> AT+IFC=2,2^M
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: <-- OK
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: --> AT+CPIN?^M
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: <-- +CPIN: READY
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: --> AT+CSCA="<a href="tel:+33%206%2060%2000%2030%2000" value="+33660003000" target="_blank" class="">+33660003000"^M
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: <-- OK
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: --> AT+CMGF=0^M
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: <-- OK
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: --> AT+CSMS=?^M
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: <-- OK
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: --> AT+CSQ;+CGDCONT=1,"IP","mmsbouygtel.com";+CGSMS=2;+CNMI=2,2,0,1,0;+CPMS="ME","ME","ME";#SGACTCFG=1,3,200^M
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: <-- +CSMS: (0,1)
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: <-- OK
2016-10-20 17:23:42 [22525] [6] INFO: AT2[multic1]: AT SMSC successfully opened.
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: <-- +CSQ: 12,0
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: <-- +CPMS: "ME",100,100,"ME",100,100,"ME",100,100
2016-10-20 17:23:42 [22525] [6] DEBUG: AT2[multic1]: <-- OK
2016-10-20 17:27:23 [22525] [6] DEBUG: AT2[multic1]: TP-Validity-Period: 24.0 hours
2016-10-20 17:27:23 [22525] [6] DEBUG: AT2[multic1]: --> AT+CMGS=154^M
2016-10-20 17:27:23 [22525] [6] DEBUG: AT2[multic1]: <--
2016-10-20 17:27:23 [22525] [6] DEBUG: AT2[multic1]: <-- >
2016-10-20 17:27:23 [22525] [6] DEBUG: AT2[multic1]: send command status: 1
2016-10-20 17:27:23 [22525] [6] DEBUG: AT2[multic1]: --> 0071000B913387237263F70008A78C0500030003010050006F007300740065002000E000200070006F007500720076006F0069007200200070006F0075007200200075006E002000320034006800200073007500720020003200340020006300680065007A0020003100200070006500720073006F006E006E0065002000E2006700E9006500200064006F006D006900630069006C006900E90065
2016-10-20 17:27:23 [22525] [6] DEBUG: AT2[multic1]: --> ^Z
2016-10-20 17:27:25 [22525] [6] DEBUG: AT2[multic1]: <-- +CMGS: 26
2016-10-20 17:27:25 [22525] [6] DEBUG: AT2[multic1]: <-- OK
2016-10-20 17:27:25 [22525] [6] DEBUG: AT2[multic1]: send command status: 0
2016-10-20 17:27:25 [22525] [6] DEBUG: DLR[internal]: Adding DLR smsc=multic1, ts=26, src=1234, dst=<a href="tel:+33%207%2083%2022%2073%2067" value="+33783227367" target="_blank" class="">+33783227367, mask=31, boxc=
2016-10-20 17:27:26 [22525] [6] DEBUG: AT2[multic1]: <-- +CDS: 25
2016-10-20 17:27:26 [22525] [6] DEBUG: AT2[multic1]: <-- 07913366003000F0060C0B913387237263F7610102715245806101027152558000
2016-10-20 17:27:26 [22525] [6] DEBUG: AT2[multic1]: received message from SMSC: <a href="tel:+33%206%2060%2000%2030%2000" value="+33660003000" target="_blank" class="">+33660003000
2016-10-20 17:27:26 [22525] [6] DEBUG: AT2[multic1]: got STATUS-REPORT for message <12>:
2016-10-20 17:27:26 [22525] [6] DEBUG: AT2[multic1]: Numeric receiver (international) <<a href="tel:+33%207%2083%2022%2073%2067" value="+33783227367" target="_blank" class="">+33783227367>
2016-10-20 17:27:26 [22525] [6] DEBUG: DLR[internal]: Looking for DLR smsc=multic1, ts=12, dst=<a href="tel:+33%207%2083%2022%2073%2067" value="+33783227367" target="_blank" class="">+33783227367, type=1
2016-10-20 17:27:26 [22525] [6] WARNING: DLR[internal]: DLR from SMSC<multic1> for DST<<a href="tel:+33%207%2083%2022%2073%2067" value="+33783227367" target="_blank" class="">+33783227367> not found.
2016-10-20 17:27:26 [22525] [6] DEBUG: AT2[multic1]: Received delivery notification but can't find that ID in the DLR storage
2016-10-20 17:27:26 [22525] [6] DEBUG: System error 1: Operation not permitted
2016-10-20 17:27:26 [22525] [6] ERROR: AT2[multic1]: could not decode PDU to a message.

I've read that there was this problem on the 1.4 version, but I'm on the 1.5...

Any idea of the problem ?

Thank you,
 

Hakim BIMAZGANE
Lead Développeur

Vitalliance
              Service professionnel d'aide à domicile




Loading...