ReportOverThreshold

ReportOverThreshold SearchSearch
Author Message
Edmund
New member
Username: Edmund

Post Number: 1
Registered: 12-2015
Posted on Thursday, December 31, 2015 - 08:23 pm:   

Hi,

I am facing a problem with 2-way HTTP processing.

I submitted 5 identical SMSes 1 second after another in the same minute (04:00:01 to 04:00:05).

The first SMS gets processed in the same second (04:00:01).

However, the second to fifth SMSes were only processed in the next minute all together (all at 04:01:00).

This happens consistently regardless of message content or time of the day.


Hence, I took a look at SMSDEBUG.LOG and saw this:

04:00:01:974 [11] GetProgramToExecute: http://localhost/processSMS.php
04:00:01:974 [11] ReportOverThreshold: Debug
04:00:01:981 [37] WaitForSocketClose: WinSock reported ioctlsocket complete
04:00:01:981 [37] ThreadProcessInboundConnection: Request processing complete
04:00:01:998 [6] WaitForSocketClose: WinSock reported ioctlsocket complete
04:01:00:001 [11] ThreadProcessInboundSMS: Executing http://localhost/processSMS.php


In my first SMS, the "ReportOverThreshold: Debug" was not present, and the PHP was executed real-time.

In my second SMS, "ReportOverThreshold: Debug" happened, and the execution was postponed to the following minute.


Are you able to help please?
Edmund
New member
Username: Edmund

Post Number: 2
Registered: 12-2015
Posted on Friday, January 01, 2016 - 02:30 pm:   

Figured I'll post more details.

I sent 3 SMSes in these order:
[22:13:18] aaa
[22:13:24] bbb
[22:13:31] ccc

However, the messages were only processed at these timing, in the following order:
[22:13:18] aaa
[22:14:00] ccc
[22:14:00] bbb

As seen in the log, bbb and ccc were delayed, and swapped around.

How can I ensure all SMSes are processed real-time and in the right order?



-----------------SMSDEBUG.log -------------------

22:12:53:952 [0] UseRouteCache: Yes
22:12:55:970 [0] main: Before InitStatCounters
22:12:56:036 [0] main: After InitStatCounters
22:12:56:086 [0] main: Before CheckDatabaseIntegrity
22:12:56:086 [0] main: After CheckDatabaseIntegrity
22:12:56:086 [0] LoadPreferredSenderList: Reload
22:12:56:086 [0] LoadPreferredSender: preferred sender = +6588888888,NowSMSModem - 192.168.0.118
22:12:58:102 [0] main: Now SMS/MMS Gateway v2014.06.30 Web server started on port number 8800
22:12:58:106 [29] ThreadScanAlerts: Before CheckDatabaseIntegrity
22:12:58:107 [29] ThreadScanAlerts: After CheckDatabaseIntegrity
22:12:58:108 [36] ThreadProcessModem: NowSMSModem - 192.168.0.118
22:12:58:176 [36] InetServerConnect: Connected to 192.168.0.118 (192.168.0.118:8990)
22:12:58:176 [36] ThreadProcessModem: GET /init HTTP/1.0
Accept: */*
Connection: close
Host: nowsmsmodem_192.168.0.118
X-NowSMS-ReceiveSMS: Yes
X-NowSMS-ReceiveSMSPort: 8990
X-NowSMS-ReceiveMMS: No


22:12:58:238 [36] HttpResponseWait: Ok
22:12:58:239 [36] ThreadProcessModem: HTTP/1.0 200 OK
X-NowSMS-MCCMNC: 52501
X-NowSMS-MMSURL: http://mms.singtel.com:10021/mmsc
X-NowSMS-MMSProxy: 165.21.42.84:8080
X-NowSMS-DeviceID: 860499029850347
X-NowSMS-DeviceName: Huawei
Content-Type: text/html
Date: Fri, 01 Jan 2016 14:13:00 GMT
Content-Length: 53
Connection: close

<html><head></head><body><p>INIT OK</p></body></html>
22:12:58:239 [36] WaitForSocketClose: WinSock reported ioctlsocket complete
22:13:04:113 [0] UseRouteCache: Yes
22:13:18:349 [2] ThreadListenForInboundConnections: Before accept
22:13:18:350 [2] ThreadListenForInboundConnections: After accept
22:13:18:350 [37] ThreadProcessInboundConnection: Processing connection from 192.168.0.118:20455...
22:13:18:353 [37] ProcessInboundRequest: POST /InboundSMS/NowSMSModem HTTP/1.1
X-NowSMS-DeviceID: 860499029850347
X-NowSMS-DeviceName: Huawei
User-Agent: NowSMS Modem
Connection: close
Content-Type: application/x-nowsms-inboundmessage-sms
Content-Length: 27
Host: 192.168.0.122:8990

Ð}dêÓJ‘?;39;;>($$Q&0+zwk\
22:13:18:353 [37] ProcessInboundRequest: Huawei
22:13:18:353 [37] ProcessInboundRequest: 860499029850347
22:13:18:353 [37] ProcessInboundRequest: From
22:13:18:353 [37] ProcessInboundRequest: +6599999999
22:13:18:353 [37] ProcessInboundRequest: Text
22:13:18:353 [37] ProcessInboundRequest: aaa
22:13:18:353 [37] ProcessInboundRequest: NowSMSModem - 192.168.0.118
22:13:18:387 [11] ThreadProcessInboundSMS: Processing 5682A369.in...
22:13:18:387 [11] GetProgramToExecute: Found 2-way command prefix match *
22:13:18:387 [11] GetProgramToExecute: Best match so far for 2-way command prefix *
22:13:18:388 [11] GetProgramToExecute: http://localhost/processSMS.php?gatewayID=@@MESSAGEID@@&recvDate=@@MSGDATE@@&rec vTime=@@MSGTIME@@&sender=@@SENDER@@&payload=@@FULLSMS@@
22:13:18:388 [11] GetProgramToExecute: http://localhost/processSMS.php?gatewayID=5682A369.in&recvDate=20160101&recvTime =221318&sender=%2B6599999999&payload=aaa
22:13:18:388 [11] ThreadProcessInboundSMS: Executing http://localhost/processSMS.php?gatewayID=5682A369.in&recvDate=20160101&recvTime =221318&sender=%2B6599999999&payload=aaa
22:13:18:388 [11] RetrieveURL: Retrieving http://localhost/processSMS.php?gatewayID=5682A369.in&recvDate=20160101&recvTime =221318&sender=%2B6599999999&payload=aaa
22:13:18:391 [11] InetServerConnect: Connected to localhost (127.0.0.1:80)
22:13:18:391 [11] RetrieveURL: Retrieving processSMS.php?gatewayID=5682A369.in&recvDate=20160101&recvTime=221318&sender=%2 B6599999999&payload=aaa
22:13:18:391 [11] RetrieveURL: GET /processSMS.php?gatewayID=5682A369.in&recvDate=20160101&recvTime=221318&sender=% 2B6599999999&payload=aaa HTTP/1.1
User-Agent: Now SMS/MMS Gateway v2014.06.30
Accept: */*
Host: localhost


22:13:18:400 [37] WaitForSocketClose: WinSock reported ioctlsocket complete
22:13:18:400 [37] ThreadProcessInboundConnection: Request processing complete
22:13:18:411 [11] HttpResponseWait: Ok
22:13:18:411 [11] RetrieveURL: HTTP/1.1 200 OK
Date: Fri, 01 Jan 2016 14:13:18 GMT
Server: Apache/2.4.9 (Win64) PHP/5.5.12
X-Powered-By: PHP/5.5.12
Content-Length: 157
Content-Type: text/html

YAY! SMS received via PHP request.
22:13:18:411 [11] RetrieveURL: Saving keep-alive socket
22:13:18:411 [11] RetrieveURL: got success response
22:13:18:411 [11] RetrieveURL: text/html
22:13:18:411 [11] ThreadProcessInboundSMS: HTTP/1.1 200 OK
Date: Fri, 01 Jan 2016 14:13:18 GMT
Server: Apache/2.4.9 (Win64) PHP/5.5.12
X-Powered-By: PHP/5.5.12
Content-Length: 157
Content-Type: text/html

YAY! SMS 'aaa' received via PHP request.
22:13:18:411 [11] GetProgramToExecute: Found 2-way command prefix match *
22:13:18:411 [11] GetProgramToExecute: Best match so far for 2-way command prefix *
22:13:18:412 [11] ThreadProcessInboundSMS: Processing complete 5682A369.in...
22:13:24:091 [2] ThreadListenForInboundConnections: Before accept
22:13:24:091 [2] ThreadListenForInboundConnections: After accept
22:13:24:092 [37] ThreadProcessInboundConnection: Processing connection from 192.168.0.118:20711...
22:13:24:100 [37] ProcessInboundRequest: POST /InboundSMS/NowSMSModem HTTP/1.1
X-NowSMS-DeviceID: 860499029850347
X-NowSMS-DeviceName: Huawei
User-Agent: NowSMS Modem
Connection: close
Content-Type: application/x-nowsms-inboundmessage-sms
Content-Length: 27
Host: 192.168.0.122:8990

Ó~gêÓJ‘?;39;;>($$Q&0+zwk\
22:13:24:100 [37] ProcessInboundRequest: Huawei
22:13:24:100 [37] ProcessInboundRequest: 860499029850347
22:13:24:100 [37] ProcessInboundRequest: From
22:13:24:100 [37] ProcessInboundRequest: +6599999999
22:13:24:100 [37] ProcessInboundRequest: Text
22:13:24:100 [37] ProcessInboundRequest: bbb
22:13:24:100 [37] ProcessInboundRequest: NowSMSModem - 192.168.0.118
22:13:24:106 [17] ThreadProcessInboundSMS: Processing 5682A36A.in...
22:13:24:106 [17] GetProgramToExecute: Found 2-way command prefix match *
22:13:24:106 [17] GetProgramToExecute: Best match so far for 2-way command prefix *
22:13:24:107 [17] GetProgramToExecute: http://localhost/processSMS.php?gatewayID=@@MESSAGEID@@&recvDate=@@MSGDATE@@&rec vTime=@@MSGTIME@@&sender=@@SENDER@@&payload=@@FULLSMS@@
22:13:24:107 [17] GetProgramToExecute: http://localhost/processSMS.php?gatewayID=5682A36A.in&recvDate=20160101&recvTime =221324&sender=%2B6599999999&payload=bbb
22:13:24:108 [17] ReportOverThreshold: Debug
22:13:24:121 [37] WaitForSocketClose: WinSock reported ioctlsocket complete
22:13:24:121 [37] ThreadProcessInboundConnection: Request processing complete
22:13:24:413 [11] WaitForSocketClose: WinSock reported ioctlsocket complete
22:13:31:355 [2] ThreadListenForInboundConnections: Before accept
22:13:31:356 [2] ThreadListenForInboundConnections: After accept
22:13:31:356 [37] ThreadProcessInboundConnection: Processing connection from 192.168.0.118:20967...
22:13:31:357 [37] ProcessInboundRequest: POST /InboundSMS/NowSMSModem HTTP/1.1
X-NowSMS-DeviceID: 860499029850347
X-NowSMS-DeviceName: Huawei
User-Agent: NowSMS Modem
Connection: close
Content-Type: application/x-nowsms-inboundmessage-sms
Content-Length: 27
Host: 192.168.0.122:8990

ÒfêÓJ‘?;39;;>($$Q&0+zwk\
22:13:31:357 [37] ProcessInboundRequest: Huawei
22:13:31:357 [37] ProcessInboundRequest: 860499029850347
22:13:31:358 [37] ProcessInboundRequest: From
22:13:31:358 [37] ProcessInboundRequest: +6599999999
22:13:31:358 [37] ProcessInboundRequest: Text
22:13:31:358 [37] ProcessInboundRequest: ccc
22:13:31:358 [37] ProcessInboundRequest: NowSMSModem - 192.168.0.118
22:13:31:366 [13] ThreadProcessInboundSMS: Processing 5682A36B.in...
22:13:31:366 [13] GetProgramToExecute: Found 2-way command prefix match *
22:13:31:366 [13] GetProgramToExecute: Best match so far for 2-way command prefix *
22:13:31:368 [13] GetProgramToExecute: http://localhost/processSMS.php?gatewayID=@@MESSAGEID@@&recvDate=@@MSGDATE@@&rec vTime=@@MSGTIME@@&sender=@@SENDER@@&payload=@@FULLSMS@@
22:13:31:369 [13] GetProgramToExecute: http://localhost/processSMS.php?gatewayID=5682A36B.in&recvDate=20160101&recvTime =221331&sender=%2B6599999999&payload=ccc
22:13:31:375 [37] WaitForSocketClose: WinSock reported ioctlsocket complete
22:13:31:375 [37] ThreadProcessInboundConnection: Request processing complete
22:14:00:000 [17] ThreadProcessInboundSMS: Executing http://localhost/processSMS.php?gatewayID=5682A36A.in&recvDate=20160101&recvTime =221324&sender=%2B6599999999&payload=bbb
22:14:00:000 [13] ThreadProcessInboundSMS: Executing http://localhost/processSMS.php?gatewayID=5682A36B.in&recvDate=20160101&recvTime =221331&sender=%2B6599999999&payload=ccc
22:14:00:000 [17] RetrieveURL: Retrieving http://localhost/processSMS.php?gatewayID=5682A36A.in&recvDate=20160101&recvTime =221324&sender=%2B6599999999&payload=bbb
22:14:00:000 [13] RetrieveURL: Retrieving http://localhost/processSMS.php?gatewayID=5682A36B.in&recvDate=20160101&recvTime =221331&sender=%2B6599999999&payload=ccc
22:14:00:002 [13] InetServerConnect: Connected to localhost (127.0.0.1:80)
22:14:00:002 [17] InetServerConnect: Connected to localhost (127.0.0.1:80)
22:14:00:002 [13] RetrieveURL: Retrieving processSMS.php?gatewayID=5682A36B.in&recvDate=20160101&recvTime=221331&sender=%2 B6599999999&payload=ccc
22:14:00:002 [17] RetrieveURL: Retrieving processSMS.php?gatewayID=5682A36A.in&recvDate=20160101&recvTime=221324&sender=%2 B6599999999&payload=bbb
22:14:00:002 [13] RetrieveURL: GET /processSMS.php?gatewayID=5682A36B.in&recvDate=20160101&recvTime=221331&sender=% 2B6599999999&payload=ccc HTTP/1.1
User-Agent: Now SMS/MMS Gateway v2014.06.30
Accept: */*
Host: localhost


22:14:00:002 [17] RetrieveURL: GET /processSMS.php?gatewayID=5682A36A.in&recvDate=20160101&recvTime=221324&sender=% 2B6599999999&payload=bbb HTTP/1.1
User-Agent: Now SMS/MMS Gateway v2014.06.30
Accept: */*
Host: localhost


22:14:00:046 [17] HttpResponseWait: Ok
22:14:00:046 [13] HttpResponseWait: Ok
22:14:00:046 [17] RetrieveURL: HTTP/1.1 200 OK
Date: Fri, 01 Jan 2016 14:14:00 GMT
Server: Apache/2.4.9 (Win64) PHP/5.5.12
X-Powered-By: PHP/5.5.12
Content-Length: 157
Content-Type: text/html

YAY! SMS received via PHP request.
22:14:00:046 [13] RetrieveURL: HTTP/1.1 200 OK
Date: Fri, 01 Jan 2016 14:14:00 GMT
Server: Apache/2.4.9 (Win64) PHP/5.5.12
X-Powered-By: PHP/5.5.12
Content-Length: 157
Content-Type: text/html

YAY! SMS received via PHP request.
22:14:00:046 [17] RetrieveURL: Saving keep-alive socket
22:14:00:046 [13] RetrieveURL: Saving keep-alive socket
22:14:00:046 [17] RetrieveURL: got success response
22:14:00:046 [13] RetrieveURL: got success response
22:14:00:046 [17] RetrieveURL: text/html
22:14:00:046 [13] RetrieveURL: text/html
22:14:00:046 [17] ThreadProcessInboundSMS: HTTP/1.1 200 OK
Date: Fri, 01 Jan 2016 14:14:00 GMT
Server: Apache/2.4.9 (Win64) PHP/5.5.12
X-Powered-By: PHP/5.5.12
Content-Length: 157
Content-Type: text/html

YAY! SMS 'ccc' received via PHP request.
22:14:00:046 [13] ThreadProcessInboundSMS: HTTP/1.1 200 OK
Date: Fri, 01 Jan 2016 14:14:00 GMT
Server: Apache/2.4.9 (Win64) PHP/5.5.12
X-Powered-By: PHP/5.5.12
Content-Length: 157
Content-Type: text/html

YAY! SMS 'bbb' received via PHP request.
22:14:00:046 [17] GetProgramToExecute: Found 2-way command prefix match *
22:14:00:046 [13] GetProgramToExecute: Found 2-way command prefix match *
22:14:00:046 [17] GetProgramToExecute: Best match so far for 2-way command prefix *
22:14:00:046 [13] GetProgramToExecute: Best match so far for 2-way command prefix *
22:14:00:047 [13] ThreadProcessInboundSMS: Processing complete 5682A36B.in...
22:14:00:047 [17] ThreadProcessInboundSMS: Processing complete 5682A36A.in...
22:14:06:050 [13] WaitForSocketClose: WinSock reported ioctlsocket complete
22:14:06:050 [17] WaitForSocketClose: WinSock reported ioctlsocket complete
Des - NowSMS Support
Board Administrator
Username: Desosms

Post Number: 5548
Registered: 08-2008
Posted on Monday, January 04, 2016 - 06:14 pm:   

Hi Edmund,

Sorry for the delay in response, we were closed over the holiday weekend.

For the first issue...the minute delay...

Did you download NowSMS from this website, or from another site?

Is this a trial version or a purchased license?

The symptom of NowSMS sending only 1 message per minute is usually the result of an invalid serial number.

Make sure you have not installed one of the various license cracks that float around the internet. Or if you downloaded NowSMS from a web site other than ours, it might have even been included in the install.

If you are encountering this problem, I would suggest going to the "Serial #" page of the configuration dialog, and removing any listed serial numbers. A trial installation will not show any serial numbers in the list. If you remove a serial number, restart the service to get it back to trial mode.

If NowSMS was download from another web site, it may also be necessary to uninstall and reinstall using the version at http://www.nowsms.com/download-free-trial

For the second issue...the sequence of message processing...

This issue is kind of related to the first.

Multiple messages have been received, and are pending for processing, but being held because of the licensing issue.

Multiple threads are allocated (I'm guessing you are using a 2WaySMSThreadCount setting), and waiting, and it is somewhat random which gets released first. If you used 2WaySMSThreadCount=1, this would not happen, but you'd only get 1 message per minute until the licensing issue is fixed.

Side note: If you want to know the date and time that the message was a received by NowSMS, use @@MSGDATE@@ and @@MSGTME@@ in your 2-way command string.

--
Des
NowSMS Support