MMSC MM4 connection not starting?

MMSC MM4 connection not starting? SearchSearch
Author Message
Robert Barretto
New member
Username: Barretto

Post Number: 41
Registered: 09-2019
Posted on Wednesday, April 07, 2021 - 04:56 am:   

Hi all,
I'm trying to configure an MM4 connection to Bandwidth using the Linux version of the NextGen server. I configured it via the webgui, matching our production MMSC configuration that is running the older Windows NowSMS MMSC. The configuration screens between the old and NextGen servers aren't exactly the same (examples: The "MMSC VASP" and "MMSC Routing" tabs on the older Windows MMSC have been combined into a single "MMSC Connections" section, and some of the checkboxes on the Windows version are worded oppositely to the NextGen: "Allow Sender Address Override" is checked in the Windows server, but on the NextGen the box is called "Always Use Default Sender Address" which means it should be unchecked to get the same behavior.)
I think I have everything set up properly but I'm not seeing the MMSC send initiate a SMTP "Server Ready" command out to the either the LAX or DAL Bandwidth MM4 Servers like the Windows version does. I don't see a MMSCDEBUG.LOG file on the NextGen server like I do on the Windows server, but that may be because the NextGen hasn't generated any MMSC debug logs? I do see that the format of the MMSC.INI file is different, for example the VASPIN and VASPOUT definitions are now sections inside the MMSC.INI as opposed to being a separate folder and file like in the Windows version.

Here's the MMSC.INI file that I have on the NextGen. I did make a couple of additions, to make it equivalent to Windows MMSC.INI file. I'm assuming those options are still supported, since I'd need them to make routing work. Specifically, I added the ForceRoutingCallback and MMSRoutingURL options in the [MMSC] section. I also tried with and without Debug=Yes set as well.


[MMSC]
DomainName=mm4.inphomatch.com
ForceRoutingCallback=Yes
HostName=*****.***********.com
IPAddress=192.168.69.26
MMSRoutingURL=https://192.168.89.92:443/routing/********.php
MSISDNHeader=X-MSISDN
MSISDNHeaderAutoProvision=Yes
MSISDNHeaderGateways=192.168.*.*,100.*.*.*
SMSEMailTemplate=@@FromAddress@@ /@@Subject@@ /@@Text@@
SMTPIPAddress=192.168.69.26
SMTPPort=25
SMTPRequireAuth=No
WebPort=80
Debug=Yes

[VASPIN-BW-DFW-MMS]
EnableMM4Login=Yes
Description=
MM7Version=5.3.0
Name=BW-DFW-MMS
Password=
RestrictIPAddress=67.231.1.16

[VASPIN-BW-LAX-MMS]
Description=
EnableMM4Login=Yes
MM7Version=5.3.0
Name=BW-LAX-MMS
Password=
RestrictIPAddress=67.231.5.30

[VASPOUT-origs-bw-mm4-dfw]
DefaultSenderAddress=********
Domain=mms-dfw.bandwidthclec.com
MessageFormat=MM4
MM7Version=6.10.0
Name=origs-bw-mm4-dfw
Protocol=MM4
Server=67.231.1.16
ThreadCount=10

[VASPOUT-origs-bw-mm4-lax]
DefaultSenderAddress=********
Domain=mms-lax.bandwidthclec.com
MessageFormat=MM4
MM7Version=6.10.0
Name=origs-bw-mm4-lax
Protocol=MM4
Server=67.231.5.30
ThreadCount=10


I'm monitoring the network with tcpdump and I don't get any traffic to either of the Bandwidth MMSC MM4 Servers. On the Windows server I also have SMTPUseStartTLS=No and SMTPUseAuth=No in the [MMSC] section. I have tried with and without those settings in the NextGen MMSC.INI file, but it did not make a difference. I'd like to use those options on the NextGen file for sure, since I don't have a real cert on this development lab to establish TLS anyway with Bandwidth anyway. I assume these are still supported even if not settable via the webgui (they aren't settable in the Windows GUI either)?

On the NowSMS Server Status page, I see All Connections OK for SMSC Status:, but it's just an empty area for the MMSC Status: line below that. I'm assuming that's empty because the MMSC hasn't tried to initiate any outbound MM4 connection so it has neither succeeded or failed?? I know the local port 25 has been opened successfully by the nowsms process from netstat output.

I verified that the Linux box can connect to both Bandwidth MM4 Servers by telnet-ing to port 25 on either the DAL or LAX server addresses. I also verified that from another Linux machine I can telnet into port 25 on the NextGen server successfully, so I don't believe there's any firewall issues either.

I'm sure I'm missing something obvious, but I just can't tell what it is. Can someone give me a pointer?

Thanks!
//Robert
Des - NowSMS Support
Board Administrator
Username: Desosms

Post Number: 6266
Registered: 08-2008
Posted on Wednesday, April 07, 2021 - 01:32 pm:   

Hi Robert,

What’s the NextGen version?

We had a similar report a week or two ago, but before I review all of the details, I’d try an update first.

There should be a button to download an update near the top of the Admin/System Configuration page.

Or, redownload and run the updated NowSMSInstall which will offer an option to update.

Regards,

Des
NowSMS Support
Robert Barretto
New member
Username: Barretto

Post Number: 42
Registered: 09-2019
Posted on Wednesday, April 07, 2021 - 01:48 pm:   

Hi Des,

Sorry. I should have mentioned that. I've already upgraded to the latest 2021.04.06 version. The behavior was the same on the previous version I was running (2021.03.30), which is why I upgraded to make see if this was a problem already addressed in a newer version.

Cheers,
//Robert
Des - NowSMS Support
Board Administrator
Username: Desosms

Post Number: 6267
Registered: 08-2008
Posted on Wednesday, April 07, 2021 - 01:59 pm:   

Hi Robert,

We're investigating by trying to setup a similar scenario.

Regarding the debug log, everything gets logged to one debug log now, the SMSDEBUG.LOG, so make sure there is a Debug=Yes under the [SMSGW] header in SMSGW.INI. Perhaps that will have a clue.

Regards,

Des
Des - NowSMS Support
Board Administrator
Username: Desosms

Post Number: 6268
Registered: 08-2008
Posted on Wednesday, April 07, 2021 - 02:56 pm:   

Hi Robert,

Have you tried actually sending a message?

The MMSC status is somewhat misleading, because if there are no attempts to send a message to an outbound connection, the status will not update.

By contrast, SMSC statuses are regularly checked and the status updated. However, the SMS protocols are designed for a persistent connection, while the MMS protocols are designed to connect on demand when there is a message to transmit.

It would probably be a good idea for the MMSC to periodically connect to validate connectivity.

That said, the Windows and NextGen versions are consistent ... neither version will connect until there is a message to be transmitted.

However, I do see a difference when configuring a connection:

It appears that the Windows configuration program attempts to validate the MMS connection settings when configuring and the OK button is pressed to save the settings. It is a very lightweight validation, just a test that it can resolve the hostname (if necessary) and connect to the specified port.

The web configurator does not perform any validating when saving/updating these configuration settings.

Does that explain the situation? Have you tried sending a message yet?

Regards,

Des


P.S. - I've tested SMTPUseStartTLS=No and it still works the same way. I'm not finding any SMTPUseAuth=No setting, and am guessing that is a mixup with SMTPRequireAuth=No (the latter of which is a default and not required, but our Windows configurator liked to add the setting to MMSC.INI by default).
Robert Barretto
New member
Username: Barretto

Post Number: 43
Registered: 09-2019
Posted on Wednesday, April 07, 2021 - 03:11 pm:   

Ah cool. I didn't think the check there because the Windows version used separate log files for the MMSC and the SMSC. I just checked the SMSGW.INI and it does have Debug=Yes option. Probably got added via the configuration webgui when I ticked the Enable Debug Logs checkbox on the Admin | Log Files page. I ticked that thinking it would create the MMSCDEBUG.LOG file but when it didn't I added it manually to match the Windows version to see if that would start the log file.

I'm not seeing anything ThreadProcessConnectionSMTP: logs in the SMSDEBUG.LOG file like I do in the MMSCDEBUG.LOG file on the Windows version. Only thing I see are the ProcessAdminRequest logs when I open the MMSC Connections section and when I save a change.

//Robert
Robert Barretto
New member
Username: Barretto

Post Number: 44
Registered: 09-2019
Posted on Wednesday, April 07, 2021 - 03:39 pm:   

Hi Des,

I didn't see your last post until after I submitted my last one. On the Windows version, in my verification lab, I'm definitely seeing the MMSC repeated close and open a new connection with both the Bandwidth DAL and LAX MMSCs via SMTP (about 34-38 seconds for each close and restart loop) even when there are no MM4 messages to be sent or received:


00:02:47:572 [41] ThreadProcessConnectionSMTP: QUIT
00:02:47:572 [41] ThreadProcessConnectionSMTP: 221 Goodbye
00:02:47:572 [41] WaitForSocketClose: WinSock reported ioctlsocket complete
00:02:47:572 [41] ThreadProcessConnectionSMTP: Closing SMTP Connection
00:02:47:572 [41] ThreadProcessConnectionSMTP: Thread ended
00:02:47:577 [41] ThreadProcessConnection: Thread started
00:02:47:578 [41] ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.1.16...
00:02:47:578 [41] ThreadProcessConnectionSMTP: 220 SMTP Ready
00:02:47:591 [41] ThreadProcessConnectionSMTP: EHLO mms-dfw.bandwidthclec.com
00:02:47:591 [41] ThreadProcessConnectionSMTP: 250-Ok
250 HELP
00:03:22:244 [42] ThreadProcessConnectionSMTP: QUIT
00:03:22:244 [42] ThreadProcessConnectionSMTP: 221 Goodbye
00:03:22:245 [42] WaitForSocketClose: WinSock reported ioctlsocket complete
00:03:22:245 [42] ThreadProcessConnectionSMTP: Closing SMTP Connection
00:03:22:245 [42] ThreadProcessConnectionSMTP: Thread ended
00:03:22:279 [42] ThreadProcessConnection: Thread started
00:03:22:279 [42] ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.5.30...
00:03:22:279 [42] ThreadProcessConnectionSMTP: 220 SMTP Ready
00:03:22:314 [42] ThreadProcessConnectionSMTP: EHLO mms-lax.bandwidthclec.com
00:03:22:314 [42] ThreadProcessConnectionSMTP: 250-Ok
250 HELP
00:03:47:601 [41] ThreadProcessConnectionSMTP: QUIT
00:03:47:601 [41] ThreadProcessConnectionSMTP: 221 Goodbye
00:03:47:601 [41] WaitForSocketClose: WinSock reported ioctlsocket complete
00:03:47:601 [41] ThreadProcessConnectionSMTP: Closing SMTP Connection
00:03:47:601 [41] ThreadProcessConnectionSMTP: Thread ended
00:03:47:608 [41] ThreadProcessConnection: Thread started
00:03:47:608 [41] ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.1.16...
00:03:47:609 [41] ThreadProcessConnectionSMTP: 220 SMTP Ready
00:03:47:613 [41] ThreadProcessConnectionSMTP: EHLO mms-dfw.bandwidthclec.com
00:03:47:613 [41] ThreadProcessConnectionSMTP: 250-Ok
250 HELP
00:04:22:357 [42] ThreadProcessConnectionSMTP: QUIT
00:04:22:357 [42] ThreadProcessConnectionSMTP: 221 Goodbye
00:04:22:357 [42] WaitForSocketClose: WinSock reported ioctlsocket complete
00:04:22:357 [42] ThreadProcessConnectionSMTP: Closing SMTP Connection
00:04:22:357 [42] ThreadProcessConnectionSMTP: Thread ended
00:04:22:392 [42] ThreadProcessConnection: Thread started
00:04:22:392 [42] ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.5.30...
00:04:22:392 [42] ThreadProcessConnectionSMTP: 220 SMTP Ready
00:04:22:428 [42] ThreadProcessConnectionSMTP: EHLO mms-lax.bandwidthclec.com
00:04:22:428 [42] ThreadProcessConnectionSMTP: 250-Ok
250 HELP
00:04:47:632 [41] ThreadProcessConnectionSMTP: QUIT
00:04:47:632 [41] ThreadProcessConnectionSMTP: 221 Goodbye
00:04:47:632 [41] WaitForSocketClose: WinSock reported ioctlsocket complete
00:04:47:633 [41] ThreadProcessConnectionSMTP: Closing SMTP Connection
00:04:47:633 [41] ThreadProcessConnectionSMTP: Thread ended
00:04:47:638 [41] ThreadProcessConnection: Thread started
00:04:47:638 [41] ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.1.16...
00:04:47:638 [41] ThreadProcessConnectionSMTP: 220 SMTP Ready
00:04:47:643 [41] ThreadProcessConnectionSMTP: EHLO mms-dfw.bandwidthclec.com
00:04:47:644 [41] ThreadProcessConnectionSMTP: 250-Ok
250 HELP
00:05:22:490 [42] ThreadProcessConnectionSMTP: QUIT
00:05:22:490 [42] ThreadProcessConnectionSMTP: 221 Goodbye
00:05:22:490 [42] WaitForSocketClose: WinSock reported ioctlsocket complete
00:05:22:490 [42] ThreadProcessConnectionSMTP: Closing SMTP Connection
00:05:22:490 [42] ThreadProcessConnectionSMTP: Thread ended
00:05:22:525 [42] ThreadProcessConnection: Thread started
00:05:22:526 [42] ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.5.30...
00:05:22:526 [42] ThreadProcessConnectionSMTP: 220 SMTP Ready
00:05:22:561 [42] ThreadProcessConnectionSMTP: EHLO mms-lax.bandwidthclec.com
00:05:22:561 [42] ThreadProcessConnectionSMTP: 250-Ok
250 HELP


I was expecting to see similar behavior on the NextGen. To me it seems like the MMSC is polling the VASP MMSCs for any incoming MM4 events, as opposed the VASP sending in an MM4 event out of the blue. Actually, looking at my production server I think there's a threading issue. I'm actually seeing clusters of outgoing SMTP connection establishments. For the connection to DAL it's doing the QUIT/SMTP Ready/EHLO loop essentially every 34-ish seconds, but for the LAX VASP, I'm seeing 6 or 7 QUIT/SMTP Ready/EHLO connections come out in a span of 2-3 seconds every 34-ish seconds. So it's like the number of threads creating connections to the VASP is growing?

00:00:49:558 [74] ThreadProcessConnectionSMTP: QUIT
00:00:49:558 [74] ThreadProcessConnectionSMTP: 221 Goodbye
00:00:49:558 [74] WaitForSocketClose: WinSock reported ioctlsocket complete
00:00:49:558 [74] ThreadProcessConnectionSMTP: Closing SMTP Connection
00:00:49:558 [74] ThreadProcessConnectionSMTP: Thread ended
00:00:49:587 [74] ThreadProcessConnection: Thread started
00:00:49:587 [74] ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.5.30...
00:00:49:587 [74] ThreadProcessConnectionSMTP: 220 SMTP Ready
00:00:49:616 [74] ThreadProcessConnectionSMTP: EHLO mms-lax.bandwidthclec.com
00:00:49:616 [74] ThreadProcessConnectionSMTP: 250-Ok
250 HELP
00:01:03:425 [78] ThreadProcessConnectionSMTP: QUIT
00:01:03:425 [78] ThreadProcessConnectionSMTP: 221 Goodbye
00:01:03:425 [78] WaitForSocketClose: WinSock reported ioctlsocket complete
00:01:03:425 [78] ThreadProcessConnectionSMTP: Closing SMTP Connection
00:01:03:425 [78] ThreadProcessConnectionSMTP: Thread ended
00:01:03:426 [77] ThreadProcessConnection: Thread started
00:01:03:426 [77] ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.1.16...
00:01:03:426 [77] ThreadProcessConnectionSMTP: 220 SMTP Ready
00:01:03:427 [77] ThreadProcessConnectionSMTP: EHLO mms-dfw.bandwidthclec.com
00:01:03:427 [77] ThreadProcessConnectionSMTP: 250-Ok
250 HELP
00:01:04:961 [56] ThreadProcessConnectionSMTP: QUIT
00:01:04:961 [56] ThreadProcessConnectionSMTP: 221 Goodbye
00:01:04:961 [56] WaitForSocketClose: WinSock reported ioctlsocket complete
00:01:04:961 [58] ThreadProcessConnectionSMTP: QUIT
00:01:04:961 [66] ThreadProcessConnectionSMTP: QUIT
00:01:04:961 [58] ThreadProcessConnectionSMTP: 221 Goodbye
00:01:04:961 [66] ThreadProcessConnectionSMTP: 221 Goodbye
00:01:04:961 [56] ThreadProcessConnectionSMTP: Closing SMTP Connection
00:01:04:961 [56] ThreadProcessConnectionSMTP: Thread ended
00:01:04:961 [58] WaitForSocketClose: WinSock reported ioctlsocket complete
00:01:04:961 [57] ThreadProcessConnectionSMTP: QUIT
00:01:04:962 [58] ThreadProcessConnectionSMTP: Closing SMTP Connection
00:01:04:962 [58] ThreadProcessConnectionSMTP: Thread ended
00:01:04:962 [57] ThreadProcessConnectionSMTP: 221 Goodbye
00:01:04:962 [57] WaitForSocketClose: WinSock reported ioctlsocket complete
00:01:04:962 [57] ThreadProcessConnectionSMTP: Closing SMTP Connection
00:01:04:962 [57] ThreadProcessConnectionSMTP: Thread ended
00:01:04:961 [60] ThreadProcessConnectionSMTP: QUIT
00:01:04:962 [60] ThreadProcessConnectionSMTP: 221 Goodbye
00:01:04:963 [60] WaitForSocketClose: WinSock reported ioctlsocket complete
00:01:04:961 [66] WaitForSocketClose: WinSock reported ioctlsocket complete
00:01:04:963 [60] ThreadProcessConnectionSMTP: Closing SMTP Connection
00:01:04:963 [60] ThreadProcessConnectionSMTP: Thread ended
00:01:04:963 [66] ThreadProcessConnectionSMTP: Closing SMTP Connection
00:01:04:963 [66] ThreadProcessConnectionSMTP: Thread ended
00:01:04:963 [56] ThreadProcessConnection: Thread started
00:01:04:963 [57] ThreadProcessConnection: Thread started
00:01:04:963 [56] ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.1.16...
00:01:04:963 [57] ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.1.16...
00:01:04:963 [56] ThreadProcessConnectionSMTP: 220 SMTP Ready
00:01:04:963 [57] ThreadProcessConnectionSMTP: 220 SMTP Ready
00:01:04:964 [58] ThreadProcessConnection: Thread started
00:01:04:964 [60] ThreadProcessConnection: Thread started
00:01:04:964 [58] ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.1.16...
00:01:04:964 [60] ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.1.16...
00:01:04:964 [58] ThreadProcessConnectionSMTP: 220 SMTP Ready
00:01:04:964 [60] ThreadProcessConnectionSMTP: 220 SMTP Ready
00:01:04:964 [57] ThreadProcessConnectionSMTP: EHLO mms-dfw.bandwidthclec.com
00:01:04:964 [57] ThreadProcessConnectionSMTP: 250-Ok
250 HELP
00:01:04:964 [56] ThreadProcessConnectionSMTP: EHLO mms-dfw.bandwidthclec.com
00:01:04:964 [56] ThreadProcessConnectionSMTP: 250-Ok
250 HELP
00:01:04:964 [66] ThreadProcessConnection: Thread started
00:01:04:964 [66] ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.1.16...
00:01:04:965 [66] ThreadProcessConnectionSMTP: 220 SMTP Ready
00:01:04:966 [58] ThreadProcessConnectionSMTP: EHLO mms-dfw.bandwidthclec.com
00:01:04:966 [66] ThreadProcessConnectionSMTP: EHLO mms-dfw.bandwidthclec.com
00:01:04:966 [58] ThreadProcessConnectionSMTP: 250-Ok
250 HELP
00:01:04:966 [66] ThreadProcessConnectionSMTP: 250-Ok
250 HELP
00:01:05:067 [60] ThreadProcessConnectionSMTP: EHLO mms-dfw.bandwidthclec.com
00:01:05:067 [60] ThreadProcessConnectionSMTP: 250-Ok
250 HELP
00:01:05:759 [70] ThreadProcessConnectionSMTP: QUIT
00:01:05:759 [70] ThreadProcessConnectionSMTP: 221 Goodbye
00:01:05:759 [70] WaitForSocketClose: WinSock reported ioctlsocket complete
00:01:05:759 [70] ThreadProcessConnectionSMTP: Closing SMTP Connection
00:01:05:759 [70] ThreadProcessConnectionSMTP: Thread ended
00:01:05:787 [70] ThreadProcessConnection: Thread started
00:01:05:787 [70] ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.5.30...
00:01:05:787 [70] ThreadProcessConnectionSMTP: 220 SMTP Ready
00:01:05:818 [70] ThreadProcessConnectionSMTP: EHLO mms-lax.bandwidthclec.com
00:01:05:818 [70] ThreadProcessConnectionSMTP: 250-Ok
250 HELP
00:01:07:148 [63] ThreadProcessConnectionSMTP: QUIT
00:01:07:148 [63] ThreadProcessConnectionSMTP: 221 Goodbye
00:01:07:148 [63] WaitForSocketClose: WinSock reported ioctlsocket complete
00:01:07:148 [63] ThreadProcessConnectionSMTP: Closing SMTP Connection
00:01:07:148 [63] ThreadProcessConnectionSMTP: Thread ended
00:01:07:149 [63] ThreadProcessConnection: Thread started
00:01:07:149 [63] ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.1.16...
00:01:07:149 [63] ThreadProcessConnectionSMTP: 220 SMTP Ready
00:01:07:150 [63] ThreadProcessConnectionSMTP: EHLO mms-dfw.bandwidthclec.com
00:01:07:150 [63] ThreadProcessConnectionSMTP: 250-Ok
250 HELP
00:01:07:386 [64] ThreadProcessConnectionSMTP: QUIT
00:01:07:386 [64] ThreadProcessConnectionSMTP: 221 Goodbye
00:01:07:386 [64] WaitForSocketClose: WinSock reported ioctlsocket complete
00:01:07:386 [64] ThreadProcessConnectionSMTP: Closing SMTP Connection
00:01:07:386 [64] ThreadProcessConnectionSMTP: Thread ended
00:01:07:387 [64] ThreadProcessConnection: Thread started
00:01:07:387 [64] ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.1.16...
00:01:07:387 [64] ThreadProcessConnectionSMTP: 220 SMTP Ready
00:01:07:388 [64] ThreadProcessConnectionSMTP: EHLO mms-dfw.bandwidthclec.com
00:01:07:388 [64] ThreadProcessConnectionSMTP: 250-Ok
250 HELP
00:01:24:069 [61] ThreadProcessConnectionSMTP: QUIT
00:01:24:069 [61] ThreadProcessConnectionSMTP: 221 Goodbye
00:01:24:069 [61] WaitForSocketClose: WinSock reported ioctlsocket complete
00:01:24:069 [61] ThreadProcessConnectionSMTP: Closing SMTP Connection
00:01:24:069 [61] ThreadProcessConnectionSMTP: Thread ended
00:01:24:070 [61] ThreadProcessConnection: Thread started
00:01:24:070 [61] ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.1.16...
00:01:24:070 [61] ThreadProcessConnectionSMTP: 220 SMTP Ready
00:01:24:071 [61] ThreadProcessConnectionSMTP: EHLO mms-dfw.bandwidthclec.com
00:01:24:071 [61] ThreadProcessConnectionSMTP: 250-Ok
250 HELP
00:01:29:019 [62] ThreadProcessConnectionSMTP: QUIT
00:01:29:019 [62] ThreadProcessConnectionSMTP: 221 Goodbye
00:01:29:019 [62] WaitForSocketClose: WinSock reported ioctlsocket complete
00:01:29:019 [62] ThreadProcessConnectionSMTP: Closing SMTP Connection
00:01:29:019 [62] ThreadProcessConnectionSMTP: Thread ended
00:01:29:049 [62] ThreadProcessConnection: Thread started
00:01:29:049 [62] ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.5.30...
00:01:29:049 [62] ThreadProcessConnectionSMTP: 220 SMTP Ready
00:01:29:079 [62] ThreadProcessConnectionSMTP: EHLO mms-lax.bandwidthclec.com
00:01:29:079 [62] ThreadProcessConnectionSMTP: 250-Ok
250 HELP
00:01:29:108 [65] ThreadProcessConnectionSMTP: QUIT
00:01:29:108 [65] ThreadProcessConnectionSMTP: 221 Goodbye
00:01:29:108 [65] WaitForSocketClose: WinSock reported ioctlsocket complete
00:01:29:108 [65] ThreadProcessConnectionSMTP: Closing SMTP Connection
00:01:29:108 [65] ThreadProcessConnectionSMTP: Thread ended
00:01:29:141 [65] ThreadProcessConnection: Thread started
00:01:29:141 [65] ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.5.30...
00:01:29:141 [65] ThreadProcessConnectionSMTP: 220 SMTP Ready
00:01:29:172 [65] ThreadProcessConnectionSMTP: EHLO mms-lax.bandwidthclec.com
00:01:29:172 [65] ThreadProcessConnectionSMTP: 250-Ok


I actually have not tried to originate an MM4 out to Bandwidth yet, since I hadn't seen the same MM4 idle behavior on the NextGen server as I observe on the Windows MMSC. I haven't finished connectivity between my SMSC and my core, so I can't originate from one of my test mobiles yet, but I'll use the webgui to send an MMS out.

Cheers,
//Robert}
Des - NowSMS Support
Board Administrator
Username: Desosms

Post Number: 6269
Registered: 08-2008
Posted on Wednesday, April 07, 2021 - 03:41 pm:   

Hmm...

This is an example of what I see in my SMSDEBUG.LOG when an SMTP/MM4 connection arrives:

09:11:23:731 [2998830112] m=300,0 AssignThreadNumber: ThreadProcessConnectionSMTP
09:11:23:731 [2998830112] m=300,0 ThreadProcessConnectionSMTP: Thread started
09:11:23:731 [2998830112] m=300,0 ThreadProcessConnectionSMTP: Processing SMTP connection from 192.168.0.20...
09:11:23:732 [2998830112] m=301,0 ThreadProcessConnectionSMTP: 220 SMTP Ready
09:11:23:732 [2998830112] m=302,0 ThreadProcessConnectionSMTP: EHLO nextgen.smshosts.com
09:11:23:732 [2998830112] m=302,0 ThreadProcessConnectionSMTP: 250-Ok
250-STARTTLS
250 HELP
09:11:23:733 [2998830112] m=302,0 ThreadProcessConnectionSMTP: STARTTLS
09:11:23:733 [2998830112] m=302,0 ThreadProcessConnectionSMTP: 220 Go Ahead

If I connect to the SMTP port but don't send any data, I see the same sequence, up to and including 220 SMTP Ready.

I wonder if there is another server listening on the port and somehow conflicting.

Regards,

Des
Des - NowSMS Support
Board Administrator
Username: Desosms

Post Number: 6270
Registered: 08-2008
Posted on Wednesday, April 07, 2021 - 03:47 pm:   

Hi Robert,

The behaviour you are currently seeing in the Windows version is very unusual and suggests something is confused and trying to open a connection to send a message that does not actually exist. I am looking into what might cause this.

Regards,

Des
Robert Barretto
New member
Username: Barretto

Post Number: 45
Registered: 09-2019
Posted on Wednesday, April 07, 2021 - 04:00 pm:   

Hi Des,

Ok. I used the Send Message | MMS option on the webgui and I do see the SMTP connection get created and the message does go out (I did have to add the SMTPUseStartTLS=No option first, since I don't have a real cert on my box). The message is being accepted on the Bandwidth side. It's not getting delivered to end point, but that might be a bandwidth issue, since the message is leaving the NowSMS MMSC ok. I'll have to get a wireshark and compare the MM4 content to one on our production server to see if there's some deviation that's causing the error on the Bandwidth side.
I tried an MMS term but that did not arrive, although I can't confirm that Bandwidth got it first, so that may be related to why the orig didn't deliver either. The test DID I have on Bandwidth might not be set up correctly.

So I guess the behavior I was trying to replicate (i.e., the connection polling I see on the Windows version) isn't really applicable for the NextGen version. I had always seen the polling, even when idle, so I assumed that should be the same on the NextGen, which is why I never actually tried to send/receive a message. doh!

Cheers,
//Robert
Des - NowSMS Support
Board Administrator
Username: Desosms

Post Number: 6271
Registered: 08-2008
Posted on Wednesday, April 07, 2021 - 04:09 pm:   

Hi Robert,

Oops...I have a correction to my previous response.

The behaviour is not necessarily unusual. These SMTP connections are not initiated by NowSMS. Bandwidth is initiating the connections. I would assume that they are polling to monitor connectivity issues from their system.

Regards,

Des
Robert Barretto
New member
Username: Barretto

Post Number: 46
Registered: 09-2019
Posted on Wednesday, April 07, 2021 - 04:55 pm:   

Hi Des,

Ok. So the person who setup my number Bandwidth didn't activate messaging service, so that explains the failed delivery. I enabled messaging on Bandwidth, and I also added the +e.164 number in the MMSC Users section on the MMSC. I am able to send and receive MMS. WOOT!

Now that I've been able to send/receive a message, I'm noticing the same SMTP polling behavior on the NextGen that I see on the Windows version. The only difference is the cycle is every 60 seconds as opposed to the ~34 second cycle:


15:49:19:918 [2985076480] m=212,0 ThreadProcessConnectionSMTP: QUIT
15:49:19:919 [2985076480] m=213,0 TestSocketOK: ioctl reported close
15:49:19:919 [2985076480] m=213,0 SendData: socket done
15:49:19:919 [2985076480] m=212,0 ThreadProcessConnectionSMTP: 221 Goodbye
15:49:19:919 [2985076480] m=210,0 TestSocketOK: ioctl reported close
15:49:19:919 [2985076480] m=210,0 ThreadProcessConnectionSMTP: Closing SMTP Connection
15:49:19:919 [2985076480] m=210,0 ThreadProcessConnectionSMTP: Thread ended
15:49:19:919 [2985076480] m=210,0 ReleaseThreadNumber: Exit
15:49:19:922 [2985076480] m=210,0 AssignThreadNumber: ThreadProcessConnectionSMTP
15:49:19:922 [2985076480] m=210,0 ThreadProcessConnectionSMTP: Thread started
15:49:19:922 [2985076480] m=210,0 ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.1.16...
15:49:19:923 [2985076480] m=211,0 ThreadProcessConnectionSMTP: 220 SMTP Ready
15:49:19:927 [2985076480] m=212,0 ThreadProcessConnectionSMTP: EHLO mms-dfw.bandwidthclec.com
15:49:19:928 [2985076480] m=212,0 ThreadProcessConnectionSMTP: 250-Ok
250 HELP
15:49:20:574 [3000948480] m=212,0 ThreadProcessConnectionSMTP: QUIT
15:49:20:575 [3000948480] m=213,0 TestSocketOK: ioctl reported close
15:49:20:575 [3000948480] m=213,0 SendData: socket done
15:49:20:575 [3000948480] m=212,0 ThreadProcessConnectionSMTP: 221 Goodbye
15:49:20:575 [3000948480] m=210,0 TestSocketOK: ioctl reported close
15:49:20:575 [3000948480] m=210,0 ThreadProcessConnectionSMTP: Closing SMTP Connection
15:49:20:575 [3000948480] m=210,0 ThreadProcessConnectionSMTP: Thread ended
15:49:20:575 [3000948480] m=210,0 ReleaseThreadNumber: Exit
15:49:20:609 [3000948480] m=210,0 AssignThreadNumber: ThreadProcessConnectionSMTP
15:49:20:609 [3000948480] m=210,0 ThreadProcessConnectionSMTP: Thread started
15:49:20:609 [3000948480] m=210,0 ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.5.30...
15:49:20:611 [3000948480] m=211,0 ThreadProcessConnectionSMTP: 220 SMTP Ready
15:49:20:645 [3000948480] m=212,0 ThreadProcessConnectionSMTP: EHLO mms-lax.bandwidthclec.com
15:49:20:645 [3000948480] m=212,0 ThreadProcessConnectionSMTP: 250-Ok
250 HELP
15:49:33:795 [2986129152] m=212,0 InternalProcessConnection: GET /?GETTOKEN=Yes HTTP/1.1
15:50:03:796 [2986129152] m=212,0 InternalProcessConnection: GET /?GETTOKEN=Yes HTTP/1.1
15:50:19:932 [2985076480] m=212,0 ThreadProcessConnectionSMTP: QUIT
15:50:19:933 [2985076480] m=212,0 ThreadProcessConnectionSMTP: 221 Goodbye
15:50:19:933 [2985076480] m=210,0 WaitForSocketClose: WinSock reported ioctlsocket complete
15:50:19:933 [2985076480] m=210,0 ThreadProcessConnectionSMTP: Closing SMTP Connection
15:50:19:933 [2985076480] m=210,0 ThreadProcessConnectionSMTP: Thread ended
15:50:19:934 [2985076480] m=210,0 ReleaseThreadNumber: Exit
15:50:19:938 [2985076480] m=210,0 AssignThreadNumber: ThreadProcessConnectionSMTP
15:50:19:938 [2985076480] m=210,0 ThreadProcessConnectionSMTP: Thread started
15:50:19:938 [2985076480] m=210,0 ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.1.16...
15:50:19:943 [2985076480] m=211,0 ThreadProcessConnectionSMTP: 220 SMTP Ready
15:50:19:948 [2985076480] m=212,0 ThreadProcessConnectionSMTP: EHLO mms-dfw.bandwidthclec.com
15:50:19:948 [2985076480] m=212,0 ThreadProcessConnectionSMTP: 250-Ok
250 HELP
15:50:20:680 [3000948480] m=212,0 ThreadProcessConnectionSMTP: QUIT
15:50:20:681 [3000948480] m=213,0 TestSocketOK: ioctl reported close
15:50:20:681 [3000948480] m=213,0 SendData: socket done
15:50:20:681 [3000948480] m=212,0 ThreadProcessConnectionSMTP: 221 Goodbye
15:50:20:681 [3000948480] m=210,0 TestSocketOK: ioctl reported close
15:50:20:681 [3000948480] m=210,0 ThreadProcessConnectionSMTP: Closing SMTP Connection
15:50:20:681 [3000948480] m=210,0 ThreadProcessConnectionSMTP: Thread ended
15:50:20:681 [3000948480] m=210,0 ReleaseThreadNumber: Exit
15:50:20:716 [3000948480] m=210,0 AssignThreadNumber: ThreadProcessConnectionSMTP
15:50:20:716 [3000948480] m=210,0 ThreadProcessConnectionSMTP: Thread started
15:50:20:716 [3000948480] m=210,0 ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.5.30...
15:50:20:725 [3000948480] m=211,0 ThreadProcessConnectionSMTP: 220 SMTP Ready
15:50:20:761 [3000948480] m=212,0 ThreadProcessConnectionSMTP: EHLO mms-lax.bandwidthclec.com
15:50:20:761 [3000948480] m=212,0 ThreadProcessConnectionSMTP: 250-Ok
250 HELP
15:50:28:545 [2999895808] m=212,0 ThreadProcessVASPQ: QUIT
15:50:28:545 [2999895808] m=213,0 ThreadProcessVASPQ: 421 Connection timeout, closing transmission channel

15:50:28:545 [2999895808] m=212,0 TestSocketOK: ioctl reported close
15:50:28:545 [2999895808] m=212,0 ThreadProcessVASPQ: closing keep-alive connection
15:51:03:796 [2986129152] m=212,0 InternalProcessConnection: GET /?GETTOKEN=Yes HTTP/1.1
15:51:19:954 [2985076480] m=212,0 ThreadProcessConnectionSMTP: QUIT
15:51:19:954 [2985076480] m=213,0 TestSocketOK: ioctl reported close
15:51:19:954 [2985076480] m=213,0 SendData: socket done
15:51:19:954 [2985076480] m=212,0 ThreadProcessConnectionSMTP: 221 Goodbye
15:51:19:954 [2985076480] m=210,0 TestSocketOK: ioctl reported close
15:51:19:954 [2985076480] m=210,0 ThreadProcessConnectionSMTP: Closing SMTP Connection
15:51:19:954 [2985076480] m=210,0 ThreadProcessConnectionSMTP: Thread ended
15:51:19:954 [2985076480] m=210,0 ReleaseThreadNumber: Exit
15:51:19:957 [2985076480] m=210,0 AssignThreadNumber: ThreadProcessConnectionSMTP
15:51:19:957 [2985076480] m=210,0 ThreadProcessConnectionSMTP: Thread started
15:51:19:958 [2985076480] m=210,0 ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.1.16...
15:51:19:969 [2985076480] m=211,0 ThreadProcessConnectionSMTP: 220 SMTP Ready
15:51:19:974 [2985076480] m=212,0 ThreadProcessConnectionSMTP: EHLO mms-dfw.bandwidthclec.com
15:51:19:974 [2985076480] m=212,0 ThreadProcessConnectionSMTP: 250-Ok
250 HELP
15:51:20:797 [3000948480] m=212,0 ThreadProcessConnectionSMTP: QUIT
15:51:20:798 [3000948480] m=213,0 TestSocketOK: ioctl reported close
15:51:20:798 [3000948480] m=213,0 SendData: socket done
15:51:20:798 [3000948480] m=212,0 ThreadProcessConnectionSMTP: 221 Goodbye
15:51:20:798 [3000948480] m=210,0 TestSocketOK: ioctl reported close
15:51:20:798 [3000948480] m=210,0 ThreadProcessConnectionSMTP: Closing SMTP Connection
15:51:20:798 [3000948480] m=210,0 ThreadProcessConnectionSMTP: Thread ended
15:51:20:798 [3000948480] m=210,0 ReleaseThreadNumber: Exit
15:51:20:833 [3000948480] m=210,0 AssignThreadNumber: ThreadProcessConnectionSMTP
15:51:20:833 [3000948480] m=210,0 ThreadProcessConnectionSMTP: Thread started
15:51:20:833 [3000948480] m=210,0 ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.5.30...
15:51:20:841 [3000948480] m=211,0 ThreadProcessConnectionSMTP: 220 SMTP Ready
15:51:20:877 [3000948480] m=212,0 ThreadProcessConnectionSMTP: EHLO mms-lax.bandwidthclec.com
15:51:20:878 [3000948480] m=212,0 ThreadProcessConnectionSMTP: 250-Ok
250 HELP

15:51:33:795 [2986129152] m=212,0 InternalProcessConnection: GET /?GETTOKEN=Yes HTTP/1.1
15:52:03:796 [2986129152] m=212,0 InternalProcessConnection: GET /?GETTOKEN=Yes HTTP/1.1
15:52:19:979 [2985076480] m=212,0 ThreadProcessConnectionSMTP: QUIT
15:52:19:980 [2985076480] m=213,0 TestSocketOK: ioctl reported close
15:52:19:980 [2985076480] m=213,0 SendData: socket done
15:52:19:980 [2985076480] m=212,0 ThreadProcessConnectionSMTP: 221 Goodbye
15:52:19:980 [2985076480] m=210,0 TestSocketOK: ioctl reported close
15:52:19:980 [2985076480] m=210,0 ThreadProcessConnectionSMTP: Closing SMTP Connection
15:52:19:980 [2985076480] m=210,0 ThreadProcessConnectionSMTP: Thread ended
15:52:19:980 [2985076480] m=210,0 ReleaseThreadNumber: Exit
15:52:19:986 [2985076480] m=210,0 AssignThreadNumber: ThreadProcessConnectionSMTP
15:52:19:986 [2985076480] m=210,0 ThreadProcessConnectionSMTP: Thread started
15:52:19:986 [2985076480] m=210,0 ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.1.16...
15:52:19:992 [2985076480] m=211,0 ThreadProcessConnectionSMTP: 220 SMTP Ready
15:52:19:996 [2985076480] m=212,0 ThreadProcessConnectionSMTP: EHLO mms-dfw.bandwidthclec.com
15:52:19:996 [2985076480] m=212,0 ThreadProcessConnectionSMTP: 250-Ok
250 HELP
15:52:20:915 [3000948480] m=212,0 ThreadProcessConnectionSMTP: QUIT
15:52:20:915 [3000948480] m=213,0 TestSocketOK: ioctl reported close
15:52:20:915 [3000948480] m=213,0 SendData: socket done
15:52:20:915 [3000948480] m=212,0 ThreadProcessConnectionSMTP: 221 Goodbye
15:52:20:915 [3000948480] m=210,0 TestSocketOK: ioctl reported close
15:52:20:917 [3000948480] m=210,0 ThreadProcessConnectionSMTP: Closing SMTP Connection
15:52:20:917 [3000948480] m=210,0 ThreadProcessConnectionSMTP: Thread ended
15:52:20:917 [3000948480] m=210,0 ReleaseThreadNumber: Exit
15:52:20:949 [3000948480] m=210,0 AssignThreadNumber: ThreadProcessConnectionSMTP
15:52:20:949 [3000948480] m=210,0 ThreadProcessConnectionSMTP: Thread started
15:52:20:949 [3000948480] m=210,0 ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.5.30...
15:52:20:956 [3000948480] m=211,0 ThreadProcessConnectionSMTP: 220 SMTP Ready
15:52:20:990 [3000948480] m=212,0 ThreadProcessConnectionSMTP: EHLO mms-lax.bandwidthclec.com
15:52:20:990 [3000948480] m=212,0 ThreadProcessConnectionSMTP: 250-Ok
250 HELP


Let me know if that's not what you are expecting to see. It doesn't seem to hurt anything on either the Windows or NextGen server. Although the multiples at once on the Windows seems off for sure.

Thanks for the help!
//Robert}
Des - NowSMS Support
Board Administrator
Username: Desosms

Post Number: 6272
Registered: 08-2008
Posted on Wednesday, April 07, 2021 - 05:27 pm:   

Hi Robert,

That activity is OK.

These SMTP connections are not initiated by NowSMS. Bandwidth is initiating the connections. I would assume that they are polling to monitor connectivity issues from their system.

There is a good argument that we should be doing similar checks.

Regards,

Des
NowSMS Support
Robert Barretto
New member
Username: Barretto

Post Number: 47
Registered: 09-2019
Posted on Wednesday, April 07, 2021 - 05:27 pm:   

Des,

Okay, I may have spoke too soon. After I tried the MMS termination test, the MMSC is now restarting over and over again. It looks like the system is choking on the MMSRoutingCallback and causing a shutdown to occur.



16:09:16:126 [3536369600] m=101,0 UseRouteCache: Yes
16:09:18:136 [3536365312] m=103,0 AssignThreadNumber: ThreadListenForConnections
16:09:18:136 [3501672192] m=103,0 AssignThreadNumber: ThreadRouteSMTPOut
16:09:18:136 [3536365312] m=103,0 ThreadListenForConnections: Web Port 8800 active for NowSMS Web Interface
16:09:18:136 [3501672192] m=103,0 ThreadRouteSMTPOut: Thread started
16:09:18:136 [3501672192] m=103,0 ThreadRouteSMTPOut: MMSCOUT
16:09:18:139 [3421497088] m=106,0 AssignThreadNumber: ThreadMMSCCleanUp
16:09:18:139 [3492198144] m=107,0 AssignThreadNumber: ThreadFlushCounters
16:09:18:139 [3499566848] m=107,0 AssignThreadNumber: ThreadRouteSMTPIn
16:09:18:139 [3419391744] m=106,0 AssignThreadNumber: ThreadStartVASPQ
16:09:18:139 [3496408832] m=106,0 AssignThreadNumber: ThreadScanInboundSMS
16:09:18:139 [3422549760] m=106,0 AssignThreadNumber: ThreadScanAlerts
16:09:18:139 [3494303488] m=107,0 AssignThreadNumber: ThreadProcessInboundSMS
16:09:18:139 [3491145472] m=107,0 AssignThreadNumber: ThreadProcessDelayQ
16:09:18:140 [3495356160] m=107,0 AssignThreadNumber: ThreadProcessInboundSMS
16:09:18:140 [3499566848] m=107,0 ThreadRouteSMTPIn: Thread started
16:09:18:140 [3421497088] m=106,0 ThreadMMSCCleanUp: Thread started
16:09:18:139 [3498514176] m=106,0 AssignThreadNumber: ThreadRouteMMSCAck
16:09:18:141 [3419391744] m=106,0 ThreadStartVASPQ: Thread started
16:09:18:143 [3500619520] m=105,0 AssignThreadNumber: ThreadListenSMTPIn
16:09:18:143 [3500619520] m=105,0 ThreadListenSMTPIn: Thread started
16:09:18:143 [3500619520] m=105,0 ThreadListenSMTPIn: Now MMSC SMTP server started on port number 25
16:09:18:143 [3498514176] m=105,0 ThreadRouteMMSCAck: Thread started
16:09:18:140 [3420444416] m=105,0 AssignThreadNumber: ThreadProcessModem
16:09:18:144 [3497461504] m=107,0 AssignThreadNumber: ThreadListenForConnectionsMMSC
16:09:18:144 [3420444416] m=107,0 ThreadProcessModem: SMPP - 192.168.69.25:2778
16:09:18:144 [3497461504] m=114,0 ThreadListenForConnectionsMMSC: Thread started
16:09:18:145 [3497461504] m=114,0 ThreadListenForConnectionsMMSC: Now MMSC server started on port number 80
16:09:18:145 [3417286400] m=113,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:18:145 [3417286400] m=113,0 ThreadProcessVASPQ: Thread started
16:09:18:146 [3418339072] m=116,0 AssignThreadNumber: ThreadProcessSMPPReceiveAsyncQ
16:09:18:646 [3416233728] m=118,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:18:646 [3416233728] m=118,0 ThreadProcessVASPQ: Thread started
16:09:19:146 [3420444416] m=122,0 ConnectWrapper: connected
16:09:19:146 [3415181056] m=122,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:19:146 [3415181056] m=122,0 ThreadProcessVASPQ: Thread started
16:09:19:146 [3420444416] m=125,0 InetServerConnect: Connected to 192.168.69.25 (192.168.69.25:2778)
16:09:19:646 [3414128384] m=126,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:19:646 [3414128384] m=126,0 ThreadProcessVASPQ: Thread started
16:09:20:019 [3536365312] m=128,0 ThreadListenForConnections: Before accept
16:09:20:019 [3536365312] m=128,0 ThreadListenForConnections: After accept
16:09:20:019 [3413075712] m=128,0 AssignThreadNumber: ThreadProcessConnection
16:09:20:019 [3413075712] m=128,0 ThreadProcessConnection: Processing connection from 192.168.70.6...
16:09:20:019 [3413075712] m=129,0 InternalProcessConnection: GET /ADMIN/STATUS?SSEUpdate=Yes HTTP/1.1
16:09:20:054 [3413075712] m=129,0 InternalProcessConnection: GET /LOGIN HTTP/1.1
16:09:20:054 [3413075712] m=129,0 ProcessRequest: /LOGIN
16:09:20:061 [3413075712] m=133,0 SendDataWithHeaderAddContentLengthGZ: compress
16:09:20:062 [3413075712] m=133,0 SendGZip: Size before compression: 14867
16:09:20:062 [3413075712] m=140,0 SendFinalChunk: Sending 4404 bytes
16:09:20:146 [3412023040] m=130,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:20:146 [3412023040] m=130,0 ThreadProcessVASPQ: Thread started
16:09:20:646 [3410970368] m=133,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:20:646 [3410970368] m=133,0 ThreadProcessVASPQ: Thread started
16:09:21:147 [3409917696] m=136,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:21:147 [3409917696] m=136,0 ThreadProcessVASPQ: Thread started
16:09:21:151 [3420444416] m=139,0 ThreadProcessModem: SMPP connection OK
16:09:21:151 [3420444416] m=139,0 ThreadProcessModem: SMPP - 192.168.69.25:2778
16:09:21:151 [3490084608] m=143,0 AssignThreadNumber: ThreadWaitForSocketSignalEvent
16:09:21:151 [3408865024] m=143,0 AssignThreadNumber: ThreadSmppSubmitAsyncHelper
16:09:21:151 [3408865024] m=143,0 ThreadSmppSubmitAsyncHelper: Start Thread
16:09:21:647 [3407812352] m=144,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:21:647 [3407812352] m=144,0 ThreadProcessVASPQ: Thread started
16:09:22:147 [3406759680] m=147,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:22:147 [3406759680] m=147,0 ThreadProcessVASPQ: Thread started
16:09:22:647 [3405707008] m=150,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:22:647 [3405707008] m=150,0 ThreadProcessVASPQ: Thread started
16:09:23:147 [3404654336] m=153,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:23:147 [3404654336] m=153,0 ThreadProcessVASPQ: Thread started
16:09:23:647 [3403601664] m=156,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:23:648 [3403601664] m=156,0 ThreadProcessVASPQ: Thread started
16:09:24:148 [3402548992] m=159,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:24:148 [3402548992] m=159,0 ThreadProcessVASPQ: Thread started
16:09:24:648 [3401496320] m=163,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:24:648 [3401496320] m=163,0 ThreadProcessVASPQ: Thread started
16:09:25:148 [3400443648] m=166,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:25:148 [3400443648] m=166,0 ThreadProcessVASPQ: Thread started
16:09:25:648 [3399390976] m=169,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:25:648 [3399390976] m=169,0 ThreadProcessVASPQ: Thread started
16:09:26:149 [3398338304] m=172,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:26:149 [3398338304] m=172,0 ThreadProcessVASPQ: Thread started
16:09:26:649 [3397285632] m=175,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:26:649 [3397285632] m=175,0 ThreadProcessVASPQ: Thread started
16:09:27:149 [3396232960] m=178,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:27:149 [3396232960] m=178,0 ThreadProcessVASPQ: Thread started
16:09:27:649 [3395180288] m=181,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:27:649 [3395180288] m=181,0 ThreadProcessVASPQ: Thread started
16:09:28:150 [3394127616] m=184,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:28:150 [3394127616] m=184,0 ThreadProcessVASPQ: Thread started
16:09:28:392 [3413075712] m=186,0 InternalProcessConnection: GET /ADMIN/STATUS HTTP/1.1
16:09:28:427 [3413075712] m=186,0 InternalProcessConnection: GET /LOGIN HTTP/1.1
16:09:28:427 [3413075712] m=186,0 ProcessRequest: /LOGIN
16:09:28:434 [3413075712] m=190,0 SendDataWithHeaderAddContentLengthGZ: compress
16:09:28:434 [3413075712] m=190,0 SendGZip: Size before compression: 14867
16:09:28:435 [3413075712] m=197,0 SendFinalChunk: Sending 4404 bytes
16:09:28:593 [3413075712] m=186,0 InternalProcessConnection: GET /?GETTOKEN=Yes HTTP/1.1
16:09:28:650 [3393074944] m=187,0 AssignThreadNumber: ThreadProcessVASPQ
16:09:28:650 [3393074944] m=187,0 ThreadProcessVASPQ: Thread started
16:09:33:795 [3536365312] m=189,0 ThreadListenForConnections: Before accept
16:09:33:795 [3536365312] m=189,0 ThreadListenForConnections: After accept
16:09:33:795 [3392022272] m=189,0 AssignThreadNumber: ThreadProcessConnection
16:09:33:795 [3392022272] m=189,0 ThreadProcessConnection: Processing connection from ::1...
16:09:33:796 [3392022272] m=190,0 InternalProcessConnection: GET /?GETTOKEN=Yes HTTP/1.1
16:09:46:012 [3390969600] m=190,0 AssignThreadNumber: ThreadProcessConnectionSMTP
16:09:46:012 [3390969600] m=190,0 ThreadProcessConnectionSMTP: Thread started
16:09:46:012 [3390969600] m=190,0 ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.1.16...
16:09:46:012 [3390969600] m=191,0 ThreadProcessConnectionSMTP: 220 SMTP Ready
16:09:46:016 [3390969600] m=192,0 ThreadProcessConnectionSMTP: EHLO mms-dfw.bandwidthclec.com
16:09:46:016 [3390969600] m=192,0 ThreadProcessConnectionSMTP: 250-Ok
250 HELP
16:09:46:050 [3381913344] m=192,0 AssignThreadNumber: ThreadProcessConnectionSMTP
16:09:46:050 [3381913344] m=192,0 ThreadProcessConnectionSMTP: Thread started
16:09:46:050 [3381913344] m=192,0 ThreadProcessConnectionSMTP: Processing SMTP connection from 67.231.5.30...
16:09:46:050 [3381913344] m=193,0 ThreadProcessConnectionSMTP: 220 SMTP Ready
16:09:46:084 [3381913344] m=194,0 ThreadProcessConnectionSMTP: EHLO mms-lax.bandwidthclec.com
16:09:46:084 [3381913344] m=194,0 ThreadProcessConnectionSMTP: 250-Ok
250 HELP
16:09:58:603 [3413075712] m=194,0 InternalProcessConnection: GET /?GETTOKEN=Yes HTTP/1.1
16:10:03:797 [3392022272] m=194,0 InternalProcessConnection: GET /?GETTOKEN=Yes HTTP/1.1
16:10:09:623 [3390969600] m=194,0 ThreadProcessConnectionSMTP: MAIL FROM:<+1214*******/TYPE=PLMN@mms-dfw.bandwidthclec.com>
16:10:09:624 [3390969600] m=194,0 ThreadProcessConnectionSMTP: 250 Ok
16:10:09:627 [3390969600] m=194,0 ThreadProcessConnectionSMTP: RCPT TO:<+1469*******/TYPE=PLMN@mm4.inphomatch.com>
16:10:09:628 [3390969600] m=194,0 MMSRoutingCallback: +1469*******
16:10:09:628 [3390969600] m=194,0 setShutdown: Shutdown triggered by SIGSEGV
16:10:09:628 [3390969600] m=194,0 exception: Waiting for shutdown

16:10:09:628 [3494303488] m=194,0 ReleaseThreadNumber: Exit
16:10:09:629 [3495356160] m=194,0 ReleaseThreadNumber: Exit
16:10:09:629 [3417286400] m=193,0 Debug: Signaled
16:10:09:629 [3417286400] m=189,0 ThreadProcessVASPQ: Thread ended
16:10:09:629 [3417286400] m=189,0 ReleaseThreadNumber: Exit
16:10:09:629 [3416233728] m=189,0 Debug: Signaled
16:10:09:629 [3416233728] m=185,0 ThreadProcessVASPQ: Thread ended
16:10:09:629 [3416233728] m=185,0 ReleaseThreadNumber: Exit
16:10:09:629 [3415181056] m=185,0 Debug: Signaled
16:10:09:630 [3415181056] m=182,0 ThreadProcessVASPQ: Thread ended
16:10:09:630 [3415181056] m=182,0 ReleaseThreadNumber: Exit
16:10:09:630 [3414128384] m=182,0 Debug: Signaled
16:10:09:630 [3414128384] m=179,0 ThreadProcessVASPQ: Thread ended
16:10:09:630 [3414128384] m=179,0 ReleaseThreadNumber: Exit
16:10:09:630 [3412023040] m=179,0 Debug: Signaled
16:10:09:630 [3412023040] m=176,0 ThreadProcessVASPQ: Thread ended
16:10:09:630 [3412023040] m=176,0 ReleaseThreadNumber: Exit
16:10:09:630 [3410970368] m=176,0 Debug: Signaled
16:10:09:630 [3410970368] m=173,0 ThreadProcessVASPQ: Thread ended
16:10:09:630 [3410970368] m=173,0 ReleaseThreadNumber: Exit
16:10:09:630 [3409917696] m=173,0 Debug: Signaled
16:10:09:630 [3409917696] m=170,0 ThreadProcessVASPQ: Thread ended
16:10:09:631 [3409917696] m=170,0 ReleaseThreadNumber: Exit
16:10:09:631 [3407812352] m=170,0 Debug: Signaled
16:10:09:631 [3407812352] m=167,0 ThreadProcessVASPQ: Thread ended
16:10:09:631 [3407812352] m=167,0 ReleaseThreadNumber: Exit
16:10:09:631 [3406759680] m=167,0 Debug: Signaled
16:10:09:631 [3406759680] m=164,0 ThreadProcessVASPQ: Thread ended
16:10:09:631 [3406759680] m=164,0 ReleaseThreadNumber: Exit
16:10:09:631 [3405707008] m=164,0 Debug: Signaled
16:10:09:631 [3405707008] m=161,0 ThreadProcessVASPQ: Thread ended
16:10:09:631 [3405707008] m=161,0 ReleaseThreadNumber: Exit
16:10:09:631 [3404654336] m=161,0 Debug: Signaled
16:10:09:631 [3404654336] m=158,0 ThreadProcessVASPQ: Thread ended
16:10:09:631 [3404654336] m=158,0 ReleaseThreadNumber: Exit
16:10:09:631 [3403601664] m=158,0 Debug: Signaled
16:10:09:631 [3403601664] m=154,0 ThreadProcessVASPQ: Thread ended
16:10:09:632 [3403601664] m=154,0 ReleaseThreadNumber: Exit
16:10:09:632 [3402548992] m=154,0 Debug: Signaled
16:10:09:632 [3402548992] m=151,0 ThreadProcessVASPQ: Thread ended
16:10:09:632 [3402548992] m=151,0 ReleaseThreadNumber: Exit
16:10:09:632 [3401496320] m=151,0 Debug: Signaled
16:10:09:632 [3401496320] m=148,0 ThreadProcessVASPQ: Thread ended
16:10:09:632 [3401496320] m=148,0 ReleaseThreadNumber: Exit
16:10:09:632 [3400443648] m=148,0 Debug: Signaled
16:10:09:632 [3400443648] m=145,0 ThreadProcessVASPQ: Thread ended
16:10:09:632 [3400443648] m=145,0 ReleaseThreadNumber: Exit
16:10:09:632 [3399390976] m=145,0 Debug: Signaled
16:10:09:632 [3399390976] m=142,0 ThreadProcessVASPQ: Thread ended
16:10:09:632 [3399390976] m=142,0 ReleaseThreadNumber: Exit
16:10:09:632 [3398338304] m=142,0 Debug: Signaled
16:10:09:632 [3398338304] m=139,0 ThreadProcessVASPQ: Thread ended
16:10:09:632 [3398338304] m=139,0 ReleaseThreadNumber: Exit
16:10:09:633 [3397285632] m=139,0 Debug: Signaled
16:10:09:633 [3397285632] m=136,0 ThreadProcessVASPQ: Thread ended
16:10:09:633 [3397285632] m=136,0 ReleaseThreadNumber: Exit
16:10:09:633 [3396232960] m=136,0 Debug: Signaled
16:10:09:633 [3396232960] m=133,0 ThreadProcessVASPQ: Thread ended
16:10:09:633 [3396232960] m=133,0 ReleaseThreadNumber: Exit
16:10:09:633 [3395180288] m=133,0 Debug: Signaled
16:10:09:633 [3395180288] m=130,0 ThreadProcessVASPQ: Thread ended
16:10:09:633 [3395180288] m=130,0 ReleaseThreadNumber: Exit
16:10:09:633 [3394127616] m=130,0 Debug: Signaled
16:10:09:633 [3394127616] m=127,0 ThreadProcessVASPQ: Thread ended
16:10:09:633 [3394127616] m=127,0 ReleaseThreadNumber: Exit
16:10:09:633 [3393074944] m=127,0 Debug: Signaled
16:10:09:633 [3393074944] m=123,0 ThreadProcessVASPQ: Thread ended
16:10:09:633 [3393074944] m=123,0 ReleaseThreadNumber: Exit
16:10:09:633 [3419391744] m=123,0 ThreadStartVASPQ: Thread ended
16:10:09:634 [3419391744] m=123,0 ReleaseThreadNumber: Exit
16:10:09:634 [3501672192] m=123,0 ThreadRouteSMTPOut: Thread ended
16:10:09:634 [3501672192] m=123,0 ReleaseThreadNumber: Exit
16:10:09:634 [3498514176] m=123,0 ThreadRouteMMSCAck: Thread ended
16:10:09:634 [3498514176] m=123,0 ReleaseThreadNumber: Exit
16:10:09:634 [3496408832] m=123,0 ReleaseThreadNumber: Exit
16:10:09:634 [3421497088] m=123,0 ThreadMMSCCleanUp: Thread exited
16:10:09:634 [3421497088] m=123,0 ReleaseThreadNumber: Exit
16:10:09:634 [3491145472] m=123,0 ReleaseThreadNumber: Exit
16:10:09:634 [3499566848] m=123,0 ThreadRouteSMTPIn: Thread ended
16:10:09:634 [3499566848] m=123,0 ReleaseThreadNumber: Exit
16:10:09:634 [3408865024] m=123,0 ThreadSmppSubmitAsyncHelper: End Thread
16:10:09:634 [3408865024] m=123,0 ReleaseThreadNumber: Exit
16:10:09:634 [3418339072] m=122,0 ReleaseThreadNumber: Exit
16:10:09:634 [3536369600] m=122,0 main: Shutdown in progress
16:10:09:634 [3536369600] m=122,0 main: Waiting for shutdown
16:10:09:634 [3492198144] m=122,0 ReleaseThreadNumber: Exit
16:10:09:634 [3422549760] m=122,0 ReleaseThreadNumber: Exit
16:10:10:635 [3420444416] m=115,0 ReleaseThreadNumber: Exit
16:10:12:209 [3413075712] m=115,0 InternalProcessConnection: GET /?TOKEN=********&AUTH=admin:a*******cf*****4f1 HTTP/1.1
16:10:12:210 [3413075712] m=115,0 userauth: admin:a*******cf*****4f1
16:10:12:210 [3413075712] m=116,0 userauth: before lookup
16:10:12:210 [3413075712] m=116,0 userauth: got user
16:10:12:210 [3413075712] m=117,0 ThreadProcessConnection: Updating cached user info
16:10:12:210 [3413075712] m=117,0 Debug: HTTP/1.1 302 Redirect
Connection: Keep-Alive
Content-length: 0
Cache-Control: no-cache, no-store, must-revalidate
Pragma: no-cache
Expires: Tue, 01 Jan 1980 12:00 GMT
Access-Control-Allow-Origin: *
Location: /ADMIN
Set-Cookie:
Set-Cookie: lastpage=/; expires=Thu, 01 Jan 1970 00:00:00 GMT


16:10:12:210 [3413075712] m=115,0 ThreadProcessConnection: Request processing complete
16:10:12:210 [3413075712] m=115,0 ReleaseThreadNumber: Exit
16:10:12:273 [3536365312] m=115,0 ThreadListenForConnections: Before accept
16:10:12:273 [3536365312] m=115,0 ThreadListenForConnections: After accept
16:10:12:273 [3536365312] m=115,0 ReleaseThreadNumber: Exit
16:10:13:798 [3392022272] m=114,0 ThreadProcessConnection: Request processing complete
16:10:13:798 [3392022272] m=114,0 ReleaseThreadNumber: Exit
16:10:16:066 [3500619520] m=114,0 ThreadListenSMTPIn: Thread ended
16:10:16:066 [3500619520] m=114,0 ReleaseThreadNumber: Exit
16:10:16:114 [3381913344] m=112,0 ThreadProcessConnectionSMTP: Closing SMTP Connection
16:10:16:114 [3381913344] m=112,0 ThreadProcessConnectionSMTP: Thread ended
16:10:16:114 [3381913344] m=112,0 ReleaseThreadNumber: Exit
16:10:18:202 [3497461504] m=112,0 ThreadListenForConnectionsMMSC: Thread ended
16:10:18:202 [3497461504] m=112,0 ReleaseThreadNumber: Exit
16:10:22:198 [3490084608] m=110,0 ReleaseThreadNumber: Exit
16:10:22:198 [3536369600] m=110,0 main: Shutdown


this above set of logs is repeated. Since it's restarting the MMSC, I get kicked out of the webgui and have to log back in. I have removed the ForceRoutingCallback and MMSRoutingURL options in the [MMSC] section, but the restart loop continues??

I'm using the same routing url that I have on the Windows version. I can telnet from the MMSC to that url IP/port with now issues. I don't see any incoming TCP traffic coming in from the MMSC on the remote server though??

I figured removing the two lines from the [MMSC] section would allow it to fix itself but to no avail. Is there some other setting I need to back out?

Thanks!
//Robert
Robert Barretto
New member
Username: Barretto

Post Number: 48
Registered: 09-2019
Posted on Wednesday, April 07, 2021 - 05:33 pm:   

The nowsms-xxxxxxxx.csv file looks like this:


...
2021-04-07 16:23:20.546,Event-Shutdown,,,,,,,,ERROR,,,Shutdown triggered by SIGSEGV,192.168.69.26
2021-04-07 16:23:39.256,Event-Startup,,,,,,,,OK,,,Started NowSMS NextGen Version 2021.04.06,192.168.69.26
2021-04-07 16:24:31.627,Event-Shutdown,,,,,,,,ERROR,,,Shutdown triggered by SIGSEGV,192.168.69.26
2021-04-07 16:24:53.147,Event-Startup,,,,,,,,OK,,,Started NowSMS NextGen Version 2021.04.06,192.168.69.26
2021-04-07 16:25:45.732,Event-Shutdown,,,,,,,,ERROR,,,Shutdown triggered by SIGSEGV,192.168.69.26
2021-04-07 16:26:04.261,Event-Startup,,,,,,,,OK,,,Started NowSMS NextGen Version 2021.04.06,192.168.69.26
...


I also meant "no issues" not "now issues" in my previous post. Hopefully that didn't cause any confusion.

Thanks!
//Robert
Des - NowSMS Support
Board Administrator
Username: Desosms

Post Number: 6273
Registered: 08-2008
Posted on Wednesday, April 07, 2021 - 05:33 pm:   

Can you remove the MMSRoutingURL from MMSC.INI temporarily?

I'm investigating what could be going wrong.
Robert Barretto
New member
Username: Barretto

Post Number: 49
Registered: 09-2019
Posted on Wednesday, April 07, 2021 - 06:08 pm:   

Des,

I already did. I took that and the ForceRoutingCallback options out of the [MMSC] section. I confirmed they were removed from /var/lib/nowsms/MMSC.INI file after making the change via the webgui. The restart loop hasn't stop. I assume it will stop once Bandwidth stops trying to deliver that MMS termination. It's retrying since it's not getting a success/failure response from the MMSC. On the Bandwidth dashboard I confirmed that my termination event is remaining in the "Sending" state, since the message hasn't been able to leave the Bandwidth platform yet. I don't know how long they'll keep trying.

Cheers,
//Robert
Bryce Norwood - NowSMS Support
Board Administrator
Username: Bryce

Post Number: 8436
Registered: 10-2002
Posted on Wednesday, April 07, 2021 - 06:28 pm:   

Hi Robert,

This is a bit of a long shot, but as we've yet to recreate the problem, I want to ask you to try this ...

Edit SMSGW.INI, and under the [SMSGW] header, add StackSize=2048


Cheers,

Bryce
Robert Barretto
New member
Username: Barretto

Post Number: 50
Registered: 09-2019
Posted on Wednesday, April 07, 2021 - 06:38 pm:   

Hi Des,

Sorry for the delay. Was grabbing a quick bite for lunch. I added the StackSize=2048 to the SMSGW.INI but it didn't make a difference. Bummer.

Cheers,
//Robert
Robert Barretto
Frequent Contributor
Username: Barretto

Post Number: 51
Registered: 09-2019
Posted on Wednesday, April 07, 2021 - 06:49 pm:   

Des,

I was able to get the loop to stop by changing the VASP to Local MMS Recipients Only and I also removed the user from MMSC Users. The next time Bandwidth tried to terminate a message the system was able to send back a 550 Recipient unknown or not local response back to Bandwidth, which Bandwidth treated as a final error. So it's not trying anymore.

Do you want me to try a specific experiment to try to re-create the SIGSEGV to occur?

Cheers,
//Robert
Bryce Norwood - NowSMS Support
Board Administrator
Username: Bryce

Post Number: 8437
Registered: 10-2002
Posted on Wednesday, April 07, 2021 - 07:20 pm:   

Hi Robert,

I'd be curious if adding the user back to MMSC Users recreates the problem.

Or any other setting change that brings the problem back.

Also, we are very curious about any changes to what is logged write before the shutdown trigger.


16:10:09:627 [3390969600] m=194,0 ThreadProcessConnectionSMTP: RCPT TO:<+1469*******/TYPE=PLMN@mm4.inphomatch.com>
16:10:09:628 [3390969600] m=194,0 MMSRoutingCallback: +1469*******
16:10:09:628 [3390969600] m=194,0 setShutdown: Shutdown triggered by SIGSEGV


We have noticed in our logs, that the next debug log entry after "MMSRoutingCallback:" refers to "CheckBlackListSender:"

I assume that you see this "CheckBlackListSender:" reference now that the crash is not occurring.

Regards,

Bryce
Robert Barretto
Frequent Contributor
Username: Barretto

Post Number: 52
Registered: 09-2019
Posted on Wednesday, April 07, 2021 - 07:32 pm:   

Hi Des,

If I add the MMSC User back and try another MMS termination to that number, the restart loop begins again. As soon as I delete the user and change the routing to be Local MMS Recipients Only then the loop gets broken. Actually if user is not there, it doesn't matter if I leave the routing as Standard MMS Delivery. Either way, since the TO party isn't known by the MMSC, it's generating the 550 Recipient unknown or not local response back to Bandwidth which makes sense. It was overkill for me to change the setting to Local MMS Recipients Only.

I don't see a CheckBlackListSender line in the SMSDEBUG file at all, whether I'm in the restart loop or if the MMSC is just rejecting the incoming termination because the number is unknown. The logs from my earlier post show everything from starting of the NowSMS to the SIGSEGV to the shutdown. Only thing I altered was the phone number and token stuff by putting in asterisks.

Do you have other logs you want me to capture?

Cheers,
//Robert
Robert Barretto
Frequent Contributor
Username: Barretto

Post Number: 53
Registered: 09-2019
Posted on Wednesday, April 07, 2021 - 07:39 pm:   

Here's some more information about the configuration of the system. I'm running as a VM on ESXi 6.0 CentOS 7.9.2009 (Core) the specific kernel is 3.10.0-1160.21.1.el7.x86_64. It's configured with 2 cores, 2GB RAM, and 30GB of disk space. User limits are stock from this minimal Linux server deploy:

core file size (blocks, -c) 0
data seg size (kbytes, -d) unlimited
scheduling priority (-e) 0
file size (blocks, -f) unlimited
pending signals (-i) 7220
max locked memory (kbytes, -l) 64
max memory size (kbytes, -m) unlimited
open files (-n) 1024
pipe size (512 bytes, -p) 8
POSIX message queues (bytes, -q) 819200
real-time priority (-r) 0
stack size (kbytes, -s) 8192
cpu time (seconds, -t) unlimited
max user processes (-u) 4096
virtual memory (kbytes, -v) unlimited
file locks (-x) unlimited
Robert Barretto
Frequent Contributor
Username: Barretto

Post Number: 54
Registered: 09-2019
Posted on Wednesday, April 07, 2021 - 08:03 pm:   

Des,
Don't know if this would have anything to do with it. I was watching the file system to see what all changes. I don't have any MMSC Users defined, but there's a MMSCUsers.DB that has my one user in it. If I use the webgui to add my MMSC User back, the MMSCUsers.DB gets updated but there's really no change, since my number was already in there. If I think delete the user via the webgui, there's no change to the MMSCUsers.DB file, my number is still there, but now a new directory is created called MMSCUsers. Inside that directory is another directory named +1469, which is the CC and area code for my subscriber. Inside the +1469 directory is another directory with three digit exchange of my subscriber. Then there's no subdirectory inside that one, presumably this would be where the line numbers (the final four digits) would be?

If I restart the NowSMS the MMSCUsers directory gets deleted, but the MMSCUsers.DB file remains, still with my one number in it. I don't think this would have any interaction with the MMSRoutingCallback entry in the debug file, but I figured I'd point it out all the same.

//Robert
Des - NowSMS Support
Board Administrator
Username: Desosms

Post Number: 6274
Registered: 08-2008
Posted on Wednesday, April 07, 2021 - 08:22 pm:   

Hi Robert,

We have created the problem, and are in the process of fixing it.

The root cause is that we forgot one configuration issue when migrating the individual VASP.INI files into MMSC.INI.

Originally, to authenticate an MM4 connection by IP address, it was a requirement that the IP address must be used as the VASP account name. We changed this so that if a VASP account had no password, it would authenticate automatically by its Restricted IP address list. This is failing miserably in NextGen.

Don't make any config changes ... we expect to have a fix for this shortly.

Regards,

Des
NowSMS Support
Robert Barretto
Frequent Contributor
Username: Barretto

Post Number: 55
Registered: 09-2019
Posted on Wednesday, April 07, 2021 - 08:41 pm:   

Hi Des,

Awesome. Thanks for the heads up. I'm leaving everything as is until I hear back.

Thanks!
//Robert
Des - NowSMS Support
Board Administrator
Username: Desosms

Post Number: 6275
Registered: 08-2008
Posted on Thursday, April 08, 2021 - 02:00 pm:   

Hi Robert,

We have posted an update to fix this issue.

Regards,

Des
Robert Barretto
Frequent Contributor
Username: Barretto

Post Number: 56
Registered: 09-2019
Posted on Thursday, April 08, 2021 - 02:14 pm:   

Awesome! I'll upgrade today.

Thanks!
//Robert
Robert Barretto
Frequent Contributor
Username: Barretto

Post Number: 57
Registered: 09-2019
Posted on Thursday, April 08, 2021 - 03:33 pm:   

Des,

I want to make sure I'm not messing up on my upgrade. There was no update available displayed on the webui. I stopped the service (./NowSMS -stop) and then tried ./NowSMS -update but that returned:

# ./NowSMS -update
ERROR: Service Update - No Uodate Available


So I then went back to the original download link (https://nowsms.com/download/linux/nowsms.tar.gz) and downloaded the latest nowsms.tar.gz file. This new file isn't actually gzipped, it appears to be just tarred.

# tar ztvf nowsms.tar.gz
gzip: stdin: not in gzip format
tar: Child returned status 1
tar: Error is not recoverable: exiting now


I extracted the tar using just xf and that worked and extracted a NowSMSInstall file. I tried to run that but got an error:

# ./NowSMSInstall
chmod: cannot access ‘/var/lib/nowsms/PreviousVersions/NowSMSInstall-2021.04.07’: Permission denied
NowSMS Server already active


Which was odd because the server was definitely not running? I re-ran the installer using sudo, but that just started up the NowSMS directly. Is that expected? The existing /usr/local/bin/NowSMS binary did not change, it's still dated from yesterday. So I'm thinking the NowSMSInstall file I extracted was actually really just the NowSMS executable itself?

Inside the /var/lib/nowsms/PreviousVersions shows:

[PreviousVersions]$ ll
total 18896
-rwxr-xr-x. 1 root root 6443904 Mar 30 19:45 NowSMSInstall-2021.03.30
-rwxr-xr-x. 1 root root 6447168 Apr 6 00:00 NowSMSInstall-2021.04.06
-rwxr-xr-x. 1 root root 6447120 Apr 7 22:35 NowSMSInstall-2021.04.07


The 2021.04.06 file matches the one in /usr/local/bin right now, and the 2021.04.07 file matches the file I just extracted, so I don't know what actually occurred when I ran NowSMSInstall and it started the server directly.

I'm thinking I could just move this NowSMSInstall into /usr/local/bin and rename it to NowSMS but I want to make sure I don't blow things up, so if you can tell me what I should do to make.

Thanks!
//Robert}
Des - NowSMS Support
Board Administrator
Username: Desosms

Post Number: 6276
Registered: 08-2008
Posted on Thursday, April 08, 2021 - 03:49 pm:   

Hi Robert,

I'm starting to think this installation is somehow cursed ...

We should not have rushed that fix into the official download, as it appears that most of the install UI functionality has been inadvertently disabled.

Stay tuned.

Regards,

Des
Robert Barretto
Frequent Contributor
Username: Barretto

Post Number: 58
Registered: 09-2019
Posted on Thursday, April 08, 2021 - 04:44 pm:   

Hi Des,

No worries!

Cheers!
//Robert
Bryce Norwood - NowSMS Support
Board Administrator
Username: Bryce

Post Number: 8438
Registered: 10-2002
Posted on Thursday, April 08, 2021 - 05:26 pm:   

Hi Robert,

We've updated the current version download to fix the disabled install functionality.

I want to also take this opportunity to explain a few questions that your previous message raises:

The Upgrade button in the webui can be a bit temperamental. It may be necessary to reload the page before the button is displayed. There is a related issue that the check for updates is limited to once an hour, unless this page is reloaded 5 times. (We have plans to change this, as we actually have separate update channels: release, stable, beta ... but currently no UI to set the channel. This particular update was pushed to release too quickly because of the level of severity of the initial problem.)

The -update parameter is working for NowSMSInstall, but not yet for NowSMS. In other words, it will apply an update that has just been downloaded, but it will not (yet) download and apply an update. (I didn't realize that we had documented those parameters, but I see that a -help related parameter gave away the secret.)

Regarding /var/lib/nowsms/PreviousVersions, this is a new feature that we are in the process of implementing. We want to make it easier to rollback to a previous version if an update causes an unexpected problem. Each time a version is installed, we are archiving the install in this directory. We plan to eventually add a UI for this, but it is possible to run the command first with a /remove parameter, then with an /install parameter to install that version.

Regarding the file not being in gzip format, that has me confused, because I do not know how that would happen.


Regards,

Bryce
NowSMS Support
Robert Barretto
Frequent Contributor
Username: Barretto

Post Number: 59
Registered: 09-2019
Posted on Thursday, April 08, 2021 - 06:47 pm:   

Hi Des,

I understand. I figured it there was some time delay for checking for updates. I only reloaded the page once, and then I tried stopping and starting the NowSMS to see if it would check for an update on start up, but that didn't show the update button either. I never tried reloading the page more than the one time. I only stumbled upon the -update parm because of the -help output. :)

The upgrade button has shown up and I'm applying the update as I type this. I'll let you know how it goes.

Thanks for all the help!
//Robert
Robert Barretto
Frequent Contributor
Username: Barretto

Post Number: 60
Registered: 09-2019
Posted on Thursday, April 08, 2021 - 08:11 pm:   

Hi Des,

New load is working like a champ. I re-added my MMSRoutingURL and when an MM4 termination comes in from either Bandwidth VASP connection the hook is called and the MMSC routes the termination to the route provided back by the routing URL script. woot!

I don't have my SMSC fully connected to my network yet, so I can't do a real origination, but using the webgui I can simulate the origination and the MMSC successfully calls the URL hook and the message is routed out as expected.

Thanks for all your help on this!
//Robert

Add Your Message Here, or click here to start a new topic.
Post:
Bold text Italics Underline Create a hyperlink Insert a clipart image
Options: Automatically activate URLs in message
Action: