Re: not "delivered" status report

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=+33614472199 <tel:+33%206%2014%2047%2021%2099>, 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 <[email protected]>:
> 
> 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: +33660003000 <tel:+33%206%2060%2000%2030%2000>
> 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) <+33663940103 <tel:+33%206%2063%2094%2001%2003>>
> 2017-05-19 12:43:59 [455] [6] DEBUG: DLR[internal]: Looking for DLR smsc=multic3, ts=34, dst=+33663940103 <tel:+33%206%2063%2094%2001%2003>, type=1
> 2017-05-19 12:43:59 [455] [6] DEBUG: DLR[internal]: created DLR message for URL <http://localhost/playsms/index.php?app=call&cat=gateway&plugin=kannel&access=dlr&type=%d&smslog_id=277&uid=2&smsc=multic3 <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=+33614472199 <tel:+33%206%2014%2047%2021%2099>, 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 = http://localhost/playsms/index.php?app=call&cat=gateway&plugin=kannel&access=dlr&type=%d&smslog_id=545&uid=2&smsc=multic3 <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: +33660003000 <tel:+33%206%2060%2000%2030%2000>
> 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) <+33614472199 <tel:+33%206%2014%2047%2021%2099>>
> 2017-05-19 12:47:50 [455] [6] DEBUG: DLR[internal]: Looking for DLR smsc=multic3, ts=37, dst=+33614472199 <tel:+33%206%2014%2047%2021%2099>, type=1
> 2017-05-19 12:47:50 [455] [6] WARNING: DLR[internal]: DLR from SMSC<multic3> for DST<+33614472199 <tel:+33%206%2014%2047%2021%2099>> 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 <[email protected] <mailto:[email protected]>>:
> 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="+33660003000 <tel:+33%206%2060%2000%2030%2000>"^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 <http://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=+33783227367 <tel:+33%207%2083%2022%2073%2067>, 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: +33660003000 <tel:+33%206%2060%2000%2030%2000>
> 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) <+33783227367 <tel:+33%207%2083%2022%2073%2067>>
> 2016-10-20 17:27:26 [22525] [6] DEBUG: DLR[internal]: Looking for DLR smsc=multic1, ts=12, dst=+33783227367 <tel:+33%207%2083%2022%2073%2067>, type=1
> 2016-10-20 17:27:26 [22525] [6] WARNING: DLR[internal]: DLR from SMSC<multic1> for DST<+33783227367 <tel:+33%207%2083%2022%2073%2067>> 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
> 
> 
>