FWIW, here are logs from a recent send that was successful. One text sent from the device page.
it is not really an error if it just says stream closed becuase of the async nature responses can come in after the socket is already closed and the message has been sent
what was the error state for the one that failed.. do you have the entire log for that message..
the telnetstatus message is called internally but the hub not me.. it is most likely being called where i have an extra closeConnection where the connection is already closed.. i need to check if it is open first.. not sure how to do that..
ok makes sense.
here is the full test 2 and test 3 log section:
dev:4952020-11-18 02:49:55.870 pm debugIn fall through case looking for 250 or 354 or 221 (bye)
dev:4952020-11-18 02:49:55.867 pm debugGot server response 221 value = 2.0.0 lastCommand = (other)
dev:4952020-11-18 02:49:55.863 pm debuglastCommand = other
dev:4952020-11-18 02:49:55.860 pm debugIn parse - 221 2.0.0 Bye
dev:4952020-11-18 02:49:55.857 pm debugIn fall through case looking for 250 or 354 or 221 (bye)
dev:4952020-11-18 02:49:55.854 pm debugGot server response 250 value = 2.0.0 lastCommand = (other)
dev:4952020-11-18 02:49:55.850 pm debuglastCommand = other
dev:4952020-11-18 02:49:55.847 pm debugIn parse - 250 2.0.0 Ok: queued as 0B9E971E002B
dev:4952020-11-18 02:49:55.844 pm debugIn fall through case looking for 250 or 354 or 221 (bye)
dev:4952020-11-18 02:49:55.840 pm debugGot server response 354 value = End lastCommand = (other)
dev:4952020-11-18 02:49:55.836 pm debuglastCommand = other
dev:4952020-11-18 02:49:55.833 pm debugIn parse - 354 End data with .
dev:4952020-11-18 02:49:55.828 pm debugIn fall through case looking for 250 or 354 or 221 (bye)
dev:4952020-11-18 02:49:55.825 pm debugGot server response 250 value = 2.1.5 lastCommand = (other)
dev:4952020-11-18 02:49:55.821 pm debuglastCommand = other
dev:4952020-11-18 02:49:55.816 pm debugIn parse - 250 2.1.5 Ok
dev:4952020-11-18 02:49:55.812 pm debugIn fall through case looking for 250 or 354 or 221 (bye)
dev:4952020-11-18 02:49:55.808 pm debugGot server response 250 value = 2.1.0 lastCommand = (sendmessage)
dev:4952020-11-18 02:49:55.804 pm debuglastCommand = sendmessage
dev:4952020-11-18 02:49:55.800 pm debugIn parse - 250 2.1.0 Ok
dev:4952020-11-18 02:49:55.279 pm debugtelnetStatus: receive error: Stream is closed
dev:4952020-11-18 02:49:55.267 pm debugquit
dev:4952020-11-18 02:49:54.762 pm debug.
dev:4952020-11-18 02:49:54.248 pm debug
dev:4952020-11-18 02:49:53.742 pm debugtest3
dev:4952020-11-18 02:49:53.229 pm debug
dev:4952020-11-18 02:49:52.717 pm debugDate: Wed Nov 18 14:49:49 AEDT 2020
dev:4952020-11-18 02:49:52.201 pm debugSubject: Home Activity Event
dev:4952020-11-18 02:49:51.683 pm debugTo: <to>
dev:4952020-11-18 02:49:51.168 pm debugFrom: <from>
dev:4952020-11-18 02:49:50.664 pm debugDATA
dev:4952020-11-18 02:49:50.161 pm debugRCPT TO: <to>
dev:4952020-11-18 02:49:49.654 pm debugMAIL FROM: <from>
dev:4952020-11-18 02:49:49.650 pm debugin sendData
dev:4952020-11-18 02:49:49.646 pm debugIn helo/Password case
dev:4952020-11-18 02:49:49.643 pm debugGot server response 250 value = msn.com lastCommand = (helo)
dev:4952020-11-18 02:49:49.638 pm debuglastCommand = helo
dev:4952020-11-18 02:49:49.635 pm debugIn parse - 250 msn.com
dev:4952020-11-18 02:49:49.103 pm debughelo [192.168.1.170]
dev:4952020-11-18 02:49:49.100 pm debugIn initialConnect case
dev:4952020-11-18 02:49:49.097 pm debugGot server response 220 value = msn.com lastCommand = (initialConnect)
dev:4952020-11-18 02:49:49.093 pm debuglastCommand = initialConnect
dev:4952020-11-18 02:49:49.090 pm debugIn parse - 220 msn.com ESMTP Postfix
dev:4952020-11-18 02:49:49.018 pm debugConnecting to 192.168.1.104:25
dev:4952020-11-18 02:49:49.014 pm debugFound ok initial state... going on!
dev:4952020-11-18 02:49:49.011 pm debugInitial state found: (Force Closed)
dev:4952020-11-18 02:49:49.004 pm debug-------> In lgk sendmail Version (2.4)
dev:4952020-11-18 02:49:49.001 pm debugExisting State still (null)... Last message appears to have failed. Force closing existing connection and sending new message.
dev:4952020-11-18 02:49:48.997 pm debugStaring up... Initial state found: (other)
dev:4952020-11-18 02:48:48.984 pm debugExisting state (other) indicates last run did not complete. Waiting 1 minute then trying again!
dev:4952020-11-18 02:48:48.980 pm debugInitial state found: (other)
dev:4952020-11-18 02:48:48.977 pm debug-------> In lgk sendmail Version (2.4)
dev:4952020-11-18 02:48:45.058 pm debugExisting state (other) indicates last run did not complete. Waiting 1 minute then trying again!
dev:4952020-11-18 02:48:45.040 pm debugInitial state found: (other)
dev:4952020-11-18 02:48:45.035 pm debug-------> In lgk sendmail Version (2.4)
yes that stream is closed message is erroneous. it appear to be some status message but being returned in the error function and is always right after the quit command, even though the socket is obviously not closed as further messages are queued up and are returned in realtime after that message.
So version 2.4.1 ignore the stream is closed message in the telnetStatus callback function.. Note: I don't call that funcxtion directxly it is called internally from the telnet stack..
i think the error had nothing to do with that as there should be a quit command response coming back in that run that i do not see. like below
maybe your server is not returning 221 bye
but something else that could explain it.
ya yours is returning numbers instead of ok, bye etc.. i may need to update for those cases. do you know what those mean.. That is really strange.
i see the number cases. if the rfc. i am going to have to add extra code to handle those version the current way.
ok pull new version was only looking for the value after the return code in one case to find the bye command.. added your resturn code as well..
Unfortuantely i cannot just check code 221 as it just indicats the connection is closing and can come out in an error case.. that is why i was check for the words after it to make sure it actually is the close case after the email was sucessfully sent.
1 Like
Ok here's the latest test - this was without a preceding email:
dev:4952020-11-18 04:05:37.912 pm debugIn quit case
dev:4952020-11-18 04:05:37.908 pm debugGot server response 221 value = 2.0.0 lastCommand = (other)
dev:4952020-11-18 04:05:37.904 pm debuglastCommand = other
dev:4952020-11-18 04:05:37.901 pm debugIn parse - 221 2.0.0 Bye
dev:4952020-11-18 04:05:37.898 pm debugGot server response 250 value = 2.0.0 lastCommand = (other)
dev:4952020-11-18 04:05:37.894 pm debuglastCommand = other
dev:4952020-11-18 04:05:37.890 pm debugIn parse - 250 2.0.0 Ok: queued as 5437671E002B
dev:4952020-11-18 04:05:37.886 pm debugGot server response 354 value = End lastCommand = (other)
dev:4952020-11-18 04:05:37.883 pm debuglastCommand = other
dev:4952020-11-18 04:05:37.877 pm debugIn parse - 354 End data with .
dev:4952020-11-18 04:05:37.870 pm debugGot server response 250 value = 2.1.5 lastCommand = (other)
dev:4952020-11-18 04:05:37.865 pm debuglastCommand = other
dev:4952020-11-18 04:05:37.861 pm debugIn parse - 250 2.1.5 Ok
dev:4952020-11-18 04:05:37.856 pm debugGot server response 250 value = 2.1.0 lastCommand = (sendmessage)
dev:4952020-11-18 04:05:37.851 pm debuglastCommand = sendmessage
dev:4952020-11-18 04:05:37.847 pm debugIn parse - 250 2.1.0 Ok
dev:4952020-11-18 04:05:37.308 pm debugquit
dev:4952020-11-18 04:05:36.794 pm debug.
dev:4952020-11-18 04:05:36.280 pm debug
dev:4952020-11-18 04:05:35.770 pm debugtest 6
dev:4952020-11-18 04:05:35.252 pm debug
dev:4952020-11-18 04:05:34.739 pm debugDate: Wed Nov 18 16:05:31 AEDT 2020
dev:4952020-11-18 04:05:34.222 pm debugSubject: Home Activity Event
dev:4952020-11-18 04:05:33.708 pm debugTo: <to>
dev:4952020-11-18 04:05:33.205 pm debugFrom: <from>
dev:4952020-11-18 04:05:32.690 pm debugDATA
dev:4952020-11-18 04:05:32.177 pm debugRCPT TO: <to>
dev:4952020-11-18 04:05:31.664 pm debugMAIL FROM: <from>
dev:4952020-11-18 04:05:31.660 pm debugin sendData
dev:4952020-11-18 04:05:31.656 pm debugIn helo/Password case
dev:4952020-11-18 04:05:31.652 pm debugGot server response 250 value = msn.com lastCommand = (helo)
dev:4952020-11-18 04:05:31.648 pm debuglastCommand = helo
dev:4952020-11-18 04:05:31.644 pm debugIn parse - 250 msn.com
dev:4952020-11-18 04:05:31.121 pm debughelo [192.168.1.170]
dev:4952020-11-18 04:05:31.117 pm debugIn initialConnect case
dev:4952020-11-18 04:05:31.113 pm debugGot server response 220 value = msn.com lastCommand = (initialConnect)
dev:4952020-11-18 04:05:31.110 pm debuglastCommand = initialConnect
dev:4952020-11-18 04:05:31.106 pm debugIn parse - 220 msn.com ESMTP Postfix
dev:4952020-11-18 04:05:30.773 pm debugConnecting to 192.168.1.104:25
dev:4952020-11-18 04:05:30.751 pm debugFound ok initial state... going on!
dev:4952020-11-18 04:05:30.748 pm debugInitial state found: (Force Closed)
dev:4952020-11-18 04:05:30.745 pm debug-------> In lgk sendmail Version (2.4.1)
dev:4952020-11-18 04:05:30.741 pm debugExisting State still (null)... Last message appears to have failed. Force closing existing connection and sending new message.
dev:4952020-11-18 04:05:30.737 pm debugStaring up... Initial state found: (other)
dev:4952020-11-18 04:04:30.698 pm debugExisting state (other) indicates last run did not complete. Waiting 1 minute then trying again!
dev:4952020-11-18 04:04:30.694 pm debugInitial state found: (other)
dev:4952020-11-18 04:04:30.690 pm debug-------> In lgk sendmail Version (2.4.1)
One thing I've noticed with your driver is that I cant use authentication against my relay and I have to leave the FQDN blank. (not an issue as my Mail Relay is only used inside my LAN)
I had a play with HEmail too and while it doesn't support queuing at all, it seems to work a little differently. Im not sure if there are bits you could pinch from it seeing as it is abandonware now?
dev:4952020-11-18 04:02:37.246 pm debugsetting state.lastMsg to 221 2.0.0 Bye
dev:4952020-11-18 04:02:37.242 pm debugparse 221 2.0.0 Bye
dev:4952020-11-18 04:02:37.239 pm debugsetting state.lastMsg to 250 2.0.0 Ok: queued as 146E871E002B
dev:4952020-11-18 04:02:37.236 pm debugparse 250 2.0.0 Ok: queued as 146E871E002B
dev:4952020-11-18 04:02:37.222 pm debugsetting state.lastMsg to 354 End data with .
dev:4952020-11-18 04:02:37.218 pm debugparse 354 End data with .
dev:4952020-11-18 04:02:37.212 pm debugsetting state.lastMsg to 250 2.1.5 Ok
dev:4952020-11-18 04:02:37.208 pm debugparse 250 2.1.5 Ok
dev:4952020-11-18 04:02:37.201 pm debugsetting state.lastMsg to 250 2.1.0 Ok
dev:4952020-11-18 04:02:36.957 pm debugSending AUTH PLAIN AERlcmVrAEF0aGxvbjY0
dev:4952020-11-18 04:02:36.953 pm debugDomain Configured!
dev:4952020-11-18 04:02:36.945 pm debugparse 250 2.1.0 Ok
dev:4952020-11-18 04:02:36.929 pm debugsetting state.lastMsg to 235 2.7.0 Authentication successful
dev:4952020-11-18 04:02:36.926 pm debugEmail message sent!
dev:4952020-11-18 04:02:36.690 pm debugtelnetStatus: receive error: Stream is closed
dev:4952020-11-18 04:02:36.669 pm debugSending quit
dev:4952020-11-18 04:02:36.416 pm debugSending .
dev:4952020-11-18 04:02:36.152 pm debugSending
dev:4952020-11-18 04:02:35.900 pm debugSending test 5
dev:4952020-11-18 04:02:35.644 pm debugSending
dev:4952020-11-18 04:02:35.387 pm debugSending Date: Wed Nov 18 16:02:33 AEDT 2020
dev:4952020-11-18 04:02:35.130 pm debugSending Subject: Home Activity Event
dev:4952020-11-18 04:02:34.865 pm debugSending To: <to>
dev:4952020-11-18 04:02:34.613 pm debugSending From: <from>
dev:4952020-11-18 04:02:34.350 pm debugSending DATA
dev:4952020-11-18 04:02:34.092 pm debugSending RCPT TO: <to>
dev:4952020-11-18 04:02:33.843 pm debugSending MAIL FROM: <from>
dev:4952020-11-18 04:02:33.839 pm debugAuthentication Successful!
dev:4952020-11-18 04:02:33.835 pm debugparse 235 2.7.0 Authentication successful
dev:4952020-11-18 04:02:33.828 pm debugsetting state.lastMsg to 250 DSN
dev:4952020-11-18 04:02:33.825 pm debugparse 250 DSN
dev:4952020-11-18 04:02:33.820 pm debugsetting state.lastMsg to 250-8BITMIME
dev:4952020-11-18 04:02:33.816 pm debugparse 250-8BITMIME
dev:4952020-11-18 04:02:33.808 pm debugsetting state.lastMsg to 250-ENHANCEDSTATUSCODES
dev:4952020-11-18 04:02:33.804 pm debugparse 250-ENHANCEDSTATUSCODES
dev:4952020-11-18 04:02:33.797 pm debugsetting state.lastMsg to 250-AUTH=PLAIN LOGIN
dev:4952020-11-18 04:02:33.793 pm debugparse 250-AUTH=PLAIN LOGIN
dev:4952020-11-18 04:02:33.729 pm debugsetting state.lastMsg to 250-AUTH PLAIN LOGIN
dev:4952020-11-18 04:02:33.726 pm debugparse 250-AUTH PLAIN LOGIN
dev:4952020-11-18 04:02:33.719 pm debugsetting state.lastMsg to 250-STARTTLS
dev:4952020-11-18 04:02:33.715 pm debugparse 250-STARTTLS
dev:4952020-11-18 04:02:33.709 pm debugsetting state.lastMsg to 250-ETRN
dev:4952020-11-18 04:02:33.705 pm debugparse 250-ETRN
dev:4952020-11-18 04:02:33.698 pm debugsetting state.lastMsg to 250-SIZE 10485760
dev:4952020-11-18 04:02:33.695 pm debugparse 250-SIZE 10485760
dev:4952020-11-18 04:02:33.688 pm debugsetting state.lastMsg to 250-PIPELINING
dev:4952020-11-18 04:02:33.684 pm debugparse 250-PIPELINING
dev:4952020-11-18 04:02:33.676 pm debugsetting state.lastMsg to 250-msn.com
dev:4952020-11-18 04:02:33.427 pm debugSending AUTH PLAIN AERlcmVrAEF0aGxvbjY0
dev:4952020-11-18 04:02:33.423 pm debugDomain Configured!
dev:4952020-11-18 04:02:33.420 pm debugparse 250-msn.com
dev:4952020-11-18 04:02:33.408 pm debugsetting state.lastMsg to 220 msn.com ESMTP Postfix
dev:4952020-11-18 04:02:33.144 pm debugSending ehlo msn.com
dev:4952020-11-18 04:02:33.140 pm debugConnected to email server!
dev:4952020-11-18 04:02:33.135 pm debugparse 220 msn.com ESMTP Postfix
dev:4952020-11-18 04:02:32.702 pm debugConnecting to 192.168.1.104:25
new version.. not checking code.. check 221 and that message was delivered instead.
v 2.4.2
we need to debug why authentication is not working for you .. did you try base64 encoded or clear text.
he mail doesnt have any checking it sends the message in one string like i do and declares it is done. so it will not find most problems.. i did start with looking at it..
if you set the name fqdn to an ip make sure you include it in square brackets. is i dont do that is you can put a name in there as well which doesnt have the brackets.
Cheers, testing now.
Not really an issue (don't fix it because of me, Im just testing every scenario I can think of). I'm fine not using authentication as it's my local LAN Mail Relay. Clear text didn't work either, not sure why. Just in case it's useful to you here is the log snippet :
dev:4952020-11-18 04:42:48.436 pm debugGot bad response for Username = 535
dev:4952020-11-18 04:42:48.432 pm debugIn Username response looking for 334
dev:4952020-11-18 04:42:48.428 pm debugGot server response 535 value = 5.7.8 lastCommand = (Username)
dev:4952020-11-18 04:42:48.424 pm debuglastCommand = Username
dev:4952020-11-18 04:42:48.420 pm debugIn parse - 535 5.7.8 Error: authentication failed: another step is needed in authentication
dev:4952020-11-18 04:42:47.900 pm debug<UID>
dev:4952020-11-18 04:42:47.896 pm debugGot auth response now sending username
dev:4952020-11-18 04:42:47.892 pm debugIn auth response looking for 334
dev:4952020-11-18 04:42:47.888 pm debugGot server response 334 value = VXNlcm5hbWU6 lastCommand = (Auth)
dev:4952020-11-18 04:42:47.884 pm debuglastCommand = Auth
dev:4952020-11-18 04:42:47.880 pm debugIn parse - 334 VXNlcm5hbWU6
back to the actual sending of emails bit - 2.4.2 seems to work more cleanly:
dev:4952020-11-18 04:46:29.766 pm debugIn quit case
dev:4952020-11-18 04:46:29.762 pm debugGot server response 221 value = 2.0.0 lastCommand = (other)
dev:4952020-11-18 04:46:29.759 pm debuglastCommand = other
dev:4952020-11-18 04:46:29.755 pm debugIn parse - 221 2.0.0 Bye
dev:4952020-11-18 04:46:29.752 pm debugGot server response 250 value = 2.0.0 lastCommand = (other)
dev:4952020-11-18 04:46:29.749 pm debuglastCommand = other
dev:4952020-11-18 04:46:29.746 pm debugIn parse - 250 2.0.0 Ok: queued as 42B3F71E002B
dev:4952020-11-18 04:46:29.742 pm debugGot server response 354 value = End lastCommand = (other)
dev:4952020-11-18 04:46:29.738 pm debuglastCommand = other
dev:4952020-11-18 04:46:29.735 pm debugIn parse - 354 End data with .
dev:4952020-11-18 04:46:29.731 pm debugGot server response 250 value = 2.1.5 lastCommand = (other)
dev:4952020-11-18 04:46:29.728 pm debuglastCommand = other
dev:4952020-11-18 04:46:29.715 pm debugIn parse - 250 2.1.5 Ok
dev:4952020-11-18 04:46:29.709 pm debugGot server response 250 value = 2.1.0 lastCommand = (sendmessage)
dev:4952020-11-18 04:46:29.705 pm debuglastCommand = sendmessage
dev:4952020-11-18 04:46:29.701 pm debugIn parse - 250 2.1.0 Ok
dev:4952020-11-18 04:46:29.169 pm debugquit
dev:4952020-11-18 04:46:28.655 pm debug.
dev:4952020-11-18 04:46:28.142 pm debug
dev:4952020-11-18 04:46:27.629 pm debugtest
dev:4952020-11-18 04:46:27.115 pm debug
dev:4952020-11-18 04:46:26.609 pm debugDate: Wed Nov 18 16:46:23 AEDT 2020
dev:4952020-11-18 04:46:26.093 pm debugSubject: Home Activity Event
dev:4952020-11-18 04:46:25.590 pm debugTo: <to>
dev:4952020-11-18 04:46:25.077 pm debugFrom: <from>
dev:4952020-11-18 04:46:24.563 pm debugDATA
dev:4952020-11-18 04:46:24.050 pm debugRCPT TO: <to>
dev:4952020-11-18 04:46:23.532 pm debugMAIL FROM: <from>
dev:4952020-11-18 04:46:23.528 pm debugin sendData
dev:4952020-11-18 04:46:23.500 pm debugIn helo/Password case
dev:4952020-11-18 04:46:23.497 pm debugGot server response 250 value = msn.com lastCommand = (helo)
dev:4952020-11-18 04:46:23.493 pm debuglastCommand = helo
dev:4952020-11-18 04:46:23.489 pm debugIn parse - 250 msn.com
dev:4952020-11-18 04:46:22.994 pm debughelo [192.168.1.170]
dev:4952020-11-18 04:46:22.990 pm debugIn initialConnect case
dev:4952020-11-18 04:46:22.973 pm debugGot server response 220 value = msn.com lastCommand = (initialConnect)
dev:4952020-11-18 04:46:22.969 pm debuglastCommand = initialConnect
dev:4952020-11-18 04:46:22.966 pm debugIn parse - 220 msn.com ESMTP Postfix
dev:4952020-11-18 04:46:22.818 pm debugConnecting to 192.168.1.104:25
dev:4952020-11-18 04:46:22.812 pm debugFound ok initial state... going on!
dev:4952020-11-18 04:46:22.803 pm debugInitial state found: (quit)
dev:4952020-11-18 04:46:22.799 pm debug-------> In lgk sendmail Version (2.4.2)
now to test the queuing .... 
telnet to your server and issue auth login
my guess is it is not enabled based on the error
usually it is on a differnt port like 587 that may be the issue
helo
250 hello R900
auth login
334 VXNlcm5hbWU6
ie
Ok Queuing isnt quite there yet, but making steps in the right direction. 
The attempt to send a 2nd email doesn't kill the first one but doesn't send either. I'm not even seeing the second attempt in the logs. if I wait till the email is sent and try again, it works perfectly.
dev:4952020-11-18 04:53:55.396 pm debugIn quit case
dev:4952020-11-18 04:53:55.392 pm debugGot server response 221 value = 2.0.0 lastCommand = (other)
dev:4952020-11-18 04:53:55.388 pm debuglastCommand = other
dev:4952020-11-18 04:53:55.384 pm debugIn parse - 221 2.0.0 Bye
dev:4952020-11-18 04:53:55.380 pm debugGot server response 250 value = 2.0.0 lastCommand = (other)
dev:4952020-11-18 04:53:55.376 pm debuglastCommand = other
dev:4952020-11-18 04:53:55.372 pm debugIn parse - 250 2.0.0 Ok: queued as ADEAB71E002B
dev:4952020-11-18 04:53:55.368 pm debugGot server response 354 value = End lastCommand = (other)
dev:4952020-11-18 04:53:55.364 pm debuglastCommand = other
dev:4952020-11-18 04:53:55.360 pm debugIn parse - 354 End data with .
dev:4952020-11-18 04:53:55.354 pm debugGot server response 250 value = 2.1.5 lastCommand = (other)
dev:4952020-11-18 04:53:55.350 pm debuglastCommand = other
dev:4952020-11-18 04:53:55.346 pm debugIn parse - 250 2.1.5 Ok
dev:4952020-11-18 04:53:55.335 pm debugGot server response 250 value = 2.1.0 lastCommand = (sendmessage)
dev:4952020-11-18 04:53:55.326 pm debuglastCommand = sendmessage
dev:4952020-11-18 04:53:55.322 pm debugIn parse - 250 2.1.0 Ok
dev:4952020-11-18 04:53:54.810 pm debugquit
dev:4952020-11-18 04:53:54.298 pm debug.
dev:4952020-11-18 04:53:53.785 pm debug
dev:4952020-11-18 04:53:53.272 pm debugtest 3
dev:4952020-11-18 04:53:52.758 pm debug
dev:4952020-11-18 04:53:52.245 pm debugDate: Wed Nov 18 16:53:49 AEDT 2020
dev:4952020-11-18 04:53:51.730 pm debugSubject: Home Activity Event
dev:4952020-11-18 04:53:51.217 pm debugTo: <to>
dev:4952020-11-18 04:53:50.703 pm debugFrom: <from>
dev:4952020-11-18 04:53:50.190 pm debugDATA
dev:4952020-11-18 04:53:49.677 pm debugRCPT TO: <to>
dev:4952020-11-18 04:53:49.186 pm debugMAIL FROM: <from>
dev:4952020-11-18 04:53:49.182 pm debugin sendData
dev:4952020-11-18 04:53:49.179 pm debugIn helo/Password case
dev:4952020-11-18 04:53:49.176 pm debugGot server response 250 value = msn.com lastCommand = (helo)
dev:4952020-11-18 04:53:49.172 pm debuglastCommand = helo
dev:4952020-11-18 04:53:49.169 pm debugIn parse - 250 msn.com
dev:4952020-11-18 04:53:48.669 pm debughelo [192.168.1.170]
dev:4952020-11-18 04:53:48.666 pm debugIn initialConnect case
dev:4952020-11-18 04:53:48.662 pm debugGot server response 220 value = msn.com lastCommand = (initialConnect)
dev:4952020-11-18 04:53:48.659 pm debuglastCommand = initialConnect
dev:4952020-11-18 04:53:48.655 pm debugIn parse - 220 msn.com ESMTP Postfix
dev:4952020-11-18 04:53:48.609 pm debugConnecting to 192.168.1.104:25
dev:4952020-11-18 04:53:48.605 pm debugFound ok initial state... going on!
dev:4952020-11-18 04:53:48.601 pm debugInitial state found: (Sent Ok)
dev:4952020-11-18 04:53:48.585 pm debug-------> In lgk sendmail Version (2.4.2)
dev:4952020-11-18 04:53:48.580 pm debugStaring up... Initial state found: (Sent Ok)
dev:4952020-11-18 04:53:34.810 pm debugIn quit case
dev:4952020-11-18 04:53:34.807 pm debugGot server response 221 value = 2.0.0 lastCommand = (other)
dev:4952020-11-18 04:53:34.803 pm debuglastCommand = other
dev:4952020-11-18 04:53:34.800 pm debugIn parse - 221 2.0.0 Bye
dev:4952020-11-18 04:53:34.794 pm debugGot server response 250 value = 2.0.0 lastCommand = (other)
dev:4952020-11-18 04:53:34.791 pm debuglastCommand = other
dev:4952020-11-18 04:53:34.788 pm debugIn parse - 250 2.0.0 Ok: queued as 177D171E002B
dev:4952020-11-18 04:53:34.783 pm debugGot server response 354 value = End lastCommand = (other)
dev:4952020-11-18 04:53:34.779 pm debuglastCommand = other
dev:4952020-11-18 04:53:34.776 pm debugIn parse - 354 End data with .
dev:4952020-11-18 04:53:34.768 pm debugGot server response 250 value = 2.1.5 lastCommand = (other)
dev:4952020-11-18 04:53:34.764 pm debuglastCommand = other
dev:4952020-11-18 04:53:34.761 pm debugIn parse - 250 2.1.5 Ok
dev:4952020-11-18 04:53:34.752 pm debugGot server response 250 value = 2.1.0 lastCommand = (sendmessage)
dev:4952020-11-18 04:53:34.748 pm debuglastCommand = sendmessage
dev:4952020-11-18 04:53:34.744 pm debugIn parse - 250 2.1.0 Ok
dev:4952020-11-18 04:53:34.213 pm debugquit
dev:4952020-11-18 04:53:33.700 pm debug.
dev:4952020-11-18 04:53:33.184 pm debug
dev:4952020-11-18 04:53:32.670 pm debugtest 3
dev:4952020-11-18 04:53:32.157 pm debug
dev:4952020-11-18 04:53:31.644 pm debugDate: Wed Nov 18 16:53:28 AEDT 2020
dev:4952020-11-18 04:53:31.128 pm debugSubject: Home Activity Event
dev:4952020-11-18 04:53:30.602 pm debugTo: <to>
dev:4952020-11-18 04:53:30.088 pm debugFrom: <from>
dev:4952020-11-18 04:53:29.573 pm debugDATA
dev:4952020-11-18 04:53:29.060 pm debugRCPT TO: <to>
dev:4952020-11-18 04:53:28.571 pm debugMAIL FROM: <from>
dev:4952020-11-18 04:53:28.567 pm debugin sendData
dev:4952020-11-18 04:53:28.563 pm debugIn helo/Password case
dev:4952020-11-18 04:53:28.560 pm debugGot server response 250 value = msn.com lastCommand = (helo)
dev:4952020-11-18 04:53:28.555 pm debuglastCommand = helo
dev:4952020-11-18 04:53:28.551 pm debugIn parse - 250 msn.com
dev:4952020-11-18 04:53:28.037 pm debughelo [192.168.1.170]
dev:4952020-11-18 04:53:28.032 pm debugIn initialConnect case
dev:4952020-11-18 04:53:28.028 pm debugGot server response 220 value = msn.com lastCommand = (initialConnect)
dev:4952020-11-18 04:53:28.024 pm debuglastCommand = initialConnect
dev:4952020-11-18 04:53:28.020 pm debugIn parse - 220 msn.com ESMTP Postfix
dev:4952020-11-18 04:53:27.879 pm debugConnecting to 192.168.1.104:25
dev:4952020-11-18 04:53:27.875 pm debugFound ok initial state... going on!
dev:4952020-11-18 04:53:27.865 pm debugInitial state found: (Sent Ok)
dev:4952020-11-18 04:53:27.860 pm debug-------> In lgk sendmail Version (2.4.2)
dev:4952020-11-18 04:52:49.329 pm debugIn quit case
dev:4952020-11-18 04:52:49.325 pm debugGot server response 221 value = 2.0.0 lastCommand = (other)
dev:4952020-11-18 04:52:49.322 pm debuglastCommand = other
dev:4952020-11-18 04:52:49.319 pm debugIn parse - 221 2.0.0 Bye
dev:4952020-11-18 04:52:49.315 pm debugGot server response 250 value = 2.0.0 lastCommand = (other)
dev:4952020-11-18 04:52:49.311 pm debuglastCommand = other
dev:4952020-11-18 04:52:49.308 pm debugIn parse - 250 2.0.0 Ok: queued as AE36771E002B
dev:4952020-11-18 04:52:49.304 pm debugGot server response 354 value = End lastCommand = (other)
dev:4952020-11-18 04:52:49.300 pm debuglastCommand = other
dev:4952020-11-18 04:52:49.296 pm debugIn parse - 354 End data with .
dev:4952020-11-18 04:52:49.291 pm debugGot server response 250 value = 2.1.5 lastCommand = (other)
dev:4952020-11-18 04:52:49.288 pm debuglastCommand = other
dev:4952020-11-18 04:52:49.284 pm debugIn parse - 250 2.1.5 Ok
dev:4952020-11-18 04:52:49.280 pm debugGot server response 250 value = 2.1.0 lastCommand = (sendmessage)
dev:4952020-11-18 04:52:49.276 pm debuglastCommand = sendmessage
dev:4952020-11-18 04:52:49.273 pm debugIn parse - 250 2.1.0 Ok
dev:4952020-11-18 04:52:48.764 pm debugquit
dev:4952020-11-18 04:52:48.532 pm debugExisting state (helo) indicates last run did not complete. Waiting 1 minute then trying again!
dev:4952020-11-18 04:52:48.528 pm debugInitial state found: (helo)
dev:4952020-11-18 04:52:48.524 pm debug-------> In lgk sendmail Version (2.4.2)
dev:4952020-11-18 04:52:48.262 pm debug.
dev:4952020-11-18 04:52:47.749 pm debug
dev:4952020-11-18 04:52:47.236 pm debugtest 2
dev:4952020-11-18 04:52:46.734 pm debug
dev:4952020-11-18 04:52:46.221 pm debugDate: Wed Nov 18 16:52:43 AEDT 2020
dev:4952020-11-18 04:52:45.705 pm debugSubject: Home Activity Event
dev:4952020-11-18 04:52:45.191 pm debugTo: <to>
dev:4952020-11-18 04:52:44.689 pm debugFrom: <from>
dev:4952020-11-18 04:52:44.185 pm debugDATA
dev:4952020-11-18 04:52:43.671 pm debugRCPT TO: <to>
dev:4952020-11-18 04:52:43.172 pm debugMAIL FROM: <from>
dev:4952020-11-18 04:52:43.169 pm debugin sendData
dev:4952020-11-18 04:52:43.164 pm debugIn helo/Password case
dev:4952020-11-18 04:52:43.160 pm debugGot server response 250 value = msn.com lastCommand = (helo)
dev:4952020-11-18 04:52:43.155 pm debuglastCommand = helo
dev:4952020-11-18 04:52:43.151 pm debugIn parse - 250 msn.com
dev:4952020-11-18 04:52:42.656 pm debughelo [192.168.1.170]
dev:4952020-11-18 04:52:42.652 pm debugIn initialConnect case
dev:4952020-11-18 04:52:42.648 pm debugGot server response 220 value = msn.com lastCommand = (initialConnect)
dev:4952020-11-18 04:52:42.638 pm debuglastCommand = initialConnect
dev:4952020-11-18 04:52:42.634 pm debugIn parse - 220 msn.com ESMTP Postfix
dev:4952020-11-18 04:52:42.484 pm debugConnecting to 192.168.1.104:25
dev:4952020-11-18 04:52:42.476 pm debugFound ok initial state... going on!
dev:4952020-11-18 04:52:42.471 pm debugInitial state found: (Sent Ok)
dev:4952020-11-18 04:52:42.468 pm debug-------> In lgk sendmail Version (2.4.2)
dev:4952020-11-18 04:52:12.657 pm debugIn quit case
dev:4952020-11-18 04:52:12.653 pm debugGot server response 221 value = 2.0.0 lastCommand = (other)
dev:4952020-11-18 04:52:12.649 pm debuglastCommand = other
dev:4952020-11-18 04:52:12.645 pm debugIn parse - 221 2.0.0 Bye
dev:4952020-11-18 04:52:12.642 pm debugGot server response 250 value = 2.0.0 lastCommand = (other)
dev:4952020-11-18 04:52:12.638 pm debuglastCommand = other
dev:4952020-11-18 04:52:12.634 pm debugIn parse - 250 2.0.0 Ok: queued as 0AD3B71E002B
dev:4952020-11-18 04:52:12.630 pm debugGot server response 354 value = End lastCommand = (other)
dev:4952020-11-18 04:52:12.625 pm debuglastCommand = other
dev:4952020-11-18 04:52:12.621 pm debugIn parse - 354 End data with .
dev:4952020-11-18 04:52:12.617 pm debugGot server response 250 value = 2.1.5 lastCommand = (other)
dev:4952020-11-18 04:52:12.612 pm debuglastCommand = other
dev:4952020-11-18 04:52:12.608 pm debugIn parse - 250 2.1.5 Ok
dev:4952020-11-18 04:52:12.601 pm debugGot server response 250 value = 2.1.0 lastCommand = (sendmessage)
dev:4952020-11-18 04:52:12.594 pm debuglastCommand = sendmessage
dev:4952020-11-18 04:52:12.588 pm debugIn parse - 250 2.1.0 Ok
dev:4952020-11-18 04:52:12.057 pm debugquit
dev:4952020-11-18 04:52:11.543 pm debug.
dev:4952020-11-18 04:52:11.030 pm debug
dev:4952020-11-18 04:52:10.518 pm debugtest 1
dev:4952020-11-18 04:52:10.004 pm debug
dev:4952020-11-18 04:52:09.492 pm debugDate: Wed Nov 18 16:52:06 AEDT 2020
dev:4952020-11-18 04:52:08.977 pm debugSubject: Home Activity Event
dev:4952020-11-18 04:52:08.474 pm debugTo: <to>
dev:4952020-11-18 04:52:08.451 pm debugExisting state (helo) indicates last run did not complete. Waiting 1 minute then trying again!
dev:4952020-11-18 04:52:08.446 pm debugInitial state found: (helo)
dev:4952020-11-18 04:52:08.442 pm debug-------> In lgk sendmail Version (2.4.2)
dev:4952020-11-18 04:52:07.973 pm debugFrom: <from>
dev:4952020-11-18 04:52:07.448 pm debugDATA
dev:4952020-11-18 04:52:06.935 pm debugRCPT TO: <to>
dev:4952020-11-18 04:52:06.436 pm debugMAIL FROM: <from>
dev:4952020-11-18 04:52:06.432 pm debugin sendData
dev:4952020-11-18 04:52:06.429 pm debugIn helo/Password case
dev:4952020-11-18 04:52:06.424 pm debugGot server response 250 value = msn.com lastCommand = (helo)
dev:4952020-11-18 04:52:06.420 pm debuglastCommand = helo
dev:4952020-11-18 04:52:06.416 pm debugIn parse - 250 msn.com
dev:4952020-11-18 04:52:05.897 pm debughelo [192.168.1.170]
dev:4952020-11-18 04:52:05.885 pm debugIn initialConnect case
dev:4952020-11-18 04:52:05.881 pm debugGot server response 220 value = msn.com lastCommand = (initialConnect)
dev:4952020-11-18 04:52:05.876 pm debuglastCommand = initialConnect
dev:4952020-11-18 04:52:05.831 pm debugIn parse - 220 msn.com ESMTP Postfix
dev:4952020-11-18 04:52:05.205 pm debugConnecting to 192.168.1.104:25
dev:4952020-11-18 04:52:05.201 pm debugFound ok initial state... going on!
dev:4952020-11-18 04:52:05.190 pm debugInitial state found: (Sent Ok)
dev:4952020-11-18 04:52:05.186 pm debug-------> In lgk sendmail Version (2.4.2)i see test 1 test 2 and test 3 all being sent in the logs.. are you sure your server is not dropping it.
ie
dev:4952020-11-18 04:52:12.057 pm debugquit
dev:4952020-11-18 04:52:11.543 pm debug.
dev:4952020-11-18 04:52:11.030 pm debug
dev:4952020-11-18 04:52:10.518 pm debugtest 1
dev:4952020-11-18 04:52:10.004 pm debug
dev:4952020-11-18 04:52:48.262 pm debug.
dev:4952020-11-18 04:52:47.749 pm debug
dev:4952020-11-18 04:52:47.236 pm debugtest 2
dev:4952020-11-18 04:52:46.734 pm debug
dev:4952020-11-18 04:53:34.213 pm debugquit
dev:4952020-11-18 04:53:33.700 pm debug.
dev:4952020-11-18 04:53:33.184 pm debug
dev:4952020-11-18 04:53:32.670 pm debugtest 3
dev:4952020-11-18 04:53:32.157 pm debug
scratch that, let me try again..
EDIT: Lol, I was clearly impatient. queing is working fine.
dev:4952020-11-18 05:07:40.810 pm debugIn quit case
dev:4952020-11-18 05:07:40.807 pm debugGot server response 221 value = 2.0.0 lastCommand = (other)
dev:4952020-11-18 05:07:40.803 pm debuglastCommand = other
dev:4952020-11-18 05:07:40.799 pm debugIn parse - 221 2.0.0 Bye
dev:4952020-11-18 05:07:40.796 pm debugGot server response 250 value = 2.0.0 lastCommand = (other)
dev:4952020-11-18 05:07:40.792 pm debuglastCommand = other
dev:4952020-11-18 05:07:40.788 pm debugIn parse - 250 2.0.0 Ok: queued as 2A47F71E002B
dev:4952020-11-18 05:07:40.784 pm debugGot server response 354 value = End lastCommand = (other)
dev:4952020-11-18 05:07:40.781 pm debuglastCommand = other
dev:4952020-11-18 05:07:40.777 pm debugIn parse - 354 End data with .
dev:4952020-11-18 05:07:40.770 pm debugGot server response 250 value = 2.1.5 lastCommand = (other)
dev:4952020-11-18 05:07:40.766 pm debuglastCommand = other
dev:4952020-11-18 05:07:40.761 pm debugIn parse - 250 2.1.5 Ok
dev:4952020-11-18 05:07:40.756 pm debugGot server response 250 value = 2.1.0 lastCommand = (sendmessage)
dev:4952020-11-18 05:07:40.752 pm debuglastCommand = sendmessage
dev:4952020-11-18 05:07:40.748 pm debugIn parse - 250 2.1.0 Ok
dev:4952020-11-18 05:07:40.215 pm debugquit
dev:4952020-11-18 05:07:39.713 pm debug.
dev:4952020-11-18 05:07:39.211 pm debug
dev:4952020-11-18 05:07:38.707 pm debugtest 13
dev:4952020-11-18 05:07:38.194 pm debug
dev:4952020-11-18 05:07:37.692 pm debugDate: Wed Nov 18 17:07:34 AEDT 2020
dev:4952020-11-18 05:07:37.189 pm debugSubject: Home Activity Event
dev:4952020-11-18 05:07:36.687 pm debugTo: <to>
dev:4952020-11-18 05:07:36.181 pm debugFrom: <from>
dev:4952020-11-18 05:07:35.658 pm debugDATA
dev:4952020-11-18 05:07:35.144 pm debugRCPT TO: <to>
dev:4952020-11-18 05:07:34.633 pm debugMAIL FROM: <from>
dev:4952020-11-18 05:07:34.630 pm debugin sendData
dev:4952020-11-18 05:07:34.625 pm debugIn helo/Password case
dev:4952020-11-18 05:07:34.622 pm debugGot server response 250 value = msn.com lastCommand = (helo)
dev:4952020-11-18 05:07:34.618 pm debuglastCommand = helo
dev:4952020-11-18 05:07:34.615 pm debugIn parse - 250 msn.com
dev:4952020-11-18 05:07:34.116 pm debughelo [192.168.1.170]
dev:4952020-11-18 05:07:34.112 pm debugIn initialConnect case
dev:4952020-11-18 05:07:34.108 pm debugGot server response 220 value = msn.com lastCommand = (initialConnect)
dev:4952020-11-18 05:07:34.104 pm debuglastCommand = initialConnect
dev:4952020-11-18 05:07:34.100 pm debugIn parse - 220 msn.com ESMTP Postfix
dev:4952020-11-18 05:07:33.997 pm debugConnecting to 192.168.1.104:25
dev:4952020-11-18 05:07:33.994 pm debugFound ok initial state... going on!
dev:4952020-11-18 05:07:33.989 pm debugInitial state found: (Sent Ok)
dev:4952020-11-18 05:07:33.980 pm debug-------> In lgk sendmail Version (2.4.2)
dev:4952020-11-18 05:07:33.975 pm debugStaring up... Initial state found: (Sent Ok)
dev:4952020-11-18 05:06:37.314 pm debugIn quit case
dev:4952020-11-18 05:06:37.311 pm debugGot server response 221 value = 2.0.0 lastCommand = (other)
dev:4952020-11-18 05:06:37.307 pm debuglastCommand = other
dev:4952020-11-18 05:06:37.304 pm debugIn parse - 221 2.0.0 Bye
dev:4952020-11-18 05:06:37.299 pm debugGot server response 250 value = 2.0.0 lastCommand = (other)
dev:4952020-11-18 05:06:37.295 pm debuglastCommand = other
dev:4952020-11-18 05:06:37.291 pm debugIn parse - 250 2.0.0 Ok: queued as BD52871E002B
dev:4952020-11-18 05:06:37.285 pm debugGot server response 354 value = End lastCommand = (other)
dev:4952020-11-18 05:06:37.281 pm debuglastCommand = other
dev:4952020-11-18 05:06:37.278 pm debugIn parse - 354 End data with .
dev:4952020-11-18 05:06:37.267 pm debugGot server response 250 value = 2.1.5 lastCommand = (other)
dev:4952020-11-18 05:06:37.263 pm debuglastCommand = other
dev:4952020-11-18 05:06:37.259 pm debugIn parse - 250 2.1.5 Ok
dev:4952020-11-18 05:06:37.249 pm debugGot server response 250 value = 2.1.0 lastCommand = (sendmessage)
dev:4952020-11-18 05:06:37.245 pm debuglastCommand = sendmessage
dev:4952020-11-18 05:06:37.241 pm debugIn parse - 250 2.1.0 Ok
dev:4952020-11-18 05:06:36.708 pm debugquit
dev:4952020-11-18 05:06:36.195 pm debug.
dev:4952020-11-18 05:06:35.682 pm debug
dev:4952020-11-18 05:06:35.169 pm debugtest 12
dev:4952020-11-18 05:06:34.666 pm debug
dev:4952020-11-18 05:06:34.164 pm debugDate: Wed Nov 18 17:06:31 AEDT 2020
dev:4952020-11-18 05:06:33.925 pm debugExisting state (helo) indicates last run did not complete. Waiting 1 minute then trying again!
dev:4952020-11-18 05:06:33.921 pm debugInitial state found: (helo)
dev:4952020-11-18 05:06:33.916 pm debug-------> In lgk sendmail Version (2.4.2)
i am not seeing the starting up in your logs.. it should show that when the runin timeout of 1 minute expires.. like this weird
dev:142020-11-18 01:07:55.773 am debugIn quit case
dev:142020-11-18 01:07:55.770 am debugGot server response 221 value = bye lastCommand = (other)
dev:142020-11-18 01:07:55.767 am debuglastCommand = other
dev:142020-11-18 01:07:55.765 am debugIn parse - 221 bye
dev:142020-11-18 01:07:55.755 am debugGot server response 250 value = Message lastCommand = (other)
dev:142020-11-18 01:07:55.753 am debuglastCommand = other
dev:142020-11-18 01:07:55.751 am debugIn parse - 250 Message queued
dev:142020-11-18 01:07:55.743 am debugGot server response 354 value = ok, lastCommand = (other)
dev:142020-11-18 01:07:55.741 am debuglastCommand = other
dev:142020-11-18 01:07:55.739 am debugIn parse - 354 ok, send it; end with .
dev:142020-11-18 01:07:55.728 am debugGot server response 250 value = ok lastCommand = (other)
dev:142020-11-18 01:07:55.725 am debuglastCommand = other
dev:142020-11-18 01:07:55.722 am debugIn parse - 250 ok its for 6034907476@text.att.net
dev:142020-11-18 01:07:55.714 am debugGot server response 250 value = ok lastCommand = (sendmessage)
dev:142020-11-18 01:07:55.711 am debuglastCommand = sendmessage
dev:142020-11-18 01:07:55.708 am debugIn parse - 250 ok
dev:142020-11-18 01:07:55.170 am debugquit
dev:142020-11-18 01:07:54.656 am debug.
dev:142020-11-18 01:07:54.144 am debug
dev:142020-11-18 01:07:53.627 am debugtest2
dev:142020-11-18 01:07:53.115 am debug
dev:142020-11-18 01:07:52.603 am debugDate: Wed Nov 18 01:07:49 EST 2020
dev:142020-11-18 01:07:52.088 am debugSubject: Hubitat NH Notification
dev:142020-11-18 01:07:51.575 am debugTo: 6034907476@text.att.net
dev:142020-11-18 01:07:51.062 am debugFrom: kahn@lgk.com
dev:142020-11-18 01:07:50.558 am debugDATA
dev:142020-11-18 01:07:50.050 am debugRCPT TO: 6034907476@text.att.net
dev:142020-11-18 01:07:49.543 am debugMAIL FROM: kahn@lgk.com
dev:142020-11-18 01:07:49.540 am debugin sendData
dev:142020-11-18 01:07:49.538 am debugIn helo/Password case
dev:142020-11-18 01:07:49.535 am debugGot server response 250 value = hello lastCommand = (helo)
dev:142020-11-18 01:07:49.532 am debuglastCommand = helo
dev:142020-11-18 01:07:49.530 am debugIn parse - 250 hello R900
dev:142020-11-18 01:07:49.005 am debughelo [192.168.11.109]
dev:142020-11-18 01:07:49.002 am debugIn initialConnect case
dev:142020-11-18 01:07:49.000 am debugGot server response 220 value = R900 lastCommand = (initialConnect)
dev:142020-11-18 01:07:48.994 am debuglastCommand = initialConnect
dev:142020-11-18 01:07:48.992 am debugIn parse - 220 R900 (IMail 12.5.7.59 14322-1) NT-ESMTP Server X1
dev:142020-11-18 01:07:48.965 am debugConnecting to mail.lgk.com:25
dev:142020-11-18 01:07:48.963 am debugFound ok initial state... going on!
dev:142020-11-18 01:07:48.927 am debugInitial state found: (Sent Ok)
dev:142020-11-18 01:07:48.914 am debug-------> In lgk sendmail Version (2.4.2)
dev:142020-11-18 01:07:48.911 am debugStaring up... Initial state found: (Sent Ok)
dev:142020-11-18 01:06:53.536 am debugIn quit case
dev:142020-11-18 01:06:53.534 am debugGot server response 221 value = bye lastCommand = (other)
dev:142020-11-18 01:06:53.531 am debuglastCommand = other
dev:142020-11-18 01:06:53.529 am debugIn parse - 221 bye
dev:142020-11-18 01:06:53.513 am debugGot server response 250 value = Message lastCommand = (other)
dev:142020-11-18 01:06:53.511 am debuglastCommand = other
dev:142020-11-18 01:06:53.508 am debugIn parse - 250 Message queued
dev:142020-11-18 01:06:53.101 am debugGot server response 354 value = ok, lastCommand = (other)
dev:142020-11-18 01:06:53.098 am debuglastCommand = other
dev:142020-11-18 01:06:53.096 am debugIn parse - 354 ok, send it; end with .
dev:142020-11-18 01:06:53.085 am debugGot server response 250 value = ok lastCommand = (other)
dev:142020-11-18 01:06:53.083 am debuglastCommand = other
dev:142020-11-18 01:06:53.081 am debugIn parse - 250 ok its for 6034907476@text.att.net
dev:142020-11-18 01:06:53.065 am debugGot server response 250 value = ok lastCommand = (sendmessage)
dev:142020-11-18 01:06:53.063 am debuglastCommand = sendmessage
dev:142020-11-18 01:06:53.060 am debugIn parse - 250 ok
dev:142020-11-18 01:06:52.528 am debugquit
dev:142020-11-18 01:06:52.015 am debug.
dev:142020-11-18 01:06:51.502 am debug
dev:142020-11-18 01:06:50.988 am debugtest
dev:142020-11-18 01:06:50.475 am debug
dev:142020-11-18 01:06:49.961 am debugDate: Wed Nov 18 01:06:46 EST 2020
dev:142020-11-18 01:06:49.454 am debugSubject: Hubitat NH Notification
dev:142020-11-18 01:06:48.953 am debugTo: 6034907476@text.att.net
dev:142020-11-18 01:06:48.879 am debugExisting state (helo) indicates last run did not complete. Waiting 1 minute then trying again!
dev:142020-11-18 01:06:48.877 am debugInitial state found: (helo)
dev:142020-11-18 01:06:48.872 am debug-------> In lgk sendmail Version (2.4.2)
dev:142020-11-18 01:06:48.448 am debugFrom: kahn@lgk.com
dev:142020-11-18 01:06:47.938 am debugDATA
dev:142020-11-18 01:06:47.421 am debugRCPT TO: 6034907476@text.att.net
dev:142020-11-18 01:06:46.905 am debugMAIL FROM: kahn@lgk.com
dev:142020-11-18 01:06:46.900 am debugin sendData
dev:142020-11-18 01:06:46.896 am debugIn helo/Password case
dev:142020-11-18 01:06:46.894 am debugGot server response 250 value = hello lastCommand = (helo)
dev:142020-11-18 01:06:46.891 am debuglastCommand = helo
dev:142020-11-18 01:06:46.888 am debugIn parse - 250 hello R900
dev:142020-11-18 01:06:46.369 am debughelo [192.168.11.109]
dev:142020-11-18 01:06:46.366 am debugIn initialConnect case
dev:142020-11-18 01:06:46.364 am debugGot server response 220 value = R900 lastCommand = (initialConnect)
dev:142020-11-18 01:06:46.361 am debuglastCommand = initialConnect
dev:142020-11-18 01:06:46.359 am debugIn parse - 220 R900 (IMail 12.5.7.59 14318-2) NT-ESMTP Server X1
dev:142020-11-18 01:06:46.168 am debugConnecting to mail.lgk.com:25
dev:142020-11-18 01:06:46.166 am debugFound ok initial state... going on!
dev:142020-11-18 01:06:46.164 am debugInitial state found: (Sent Ok)
dev:142020-11-18 01:06:46.161 am debug-------> In lgk sendmail Version (2.4.2)
--- Live Log Started, waiting for events ---
there we go.. now i see the starting up command.. after 1 minute.
it may not be i need to check. i was wondering if when a second command comes in and one is queued does it cancel the other waiting runin command.. ie can you have more than once scheduled at a time..
2 Likes
yep, looking really good now. 
1 Like
Argh, I went to test this and found Apple have removed Telnet from macOS! 
i think that is the problem when a further runin command comes in it is overwritting the existing.. i just tested test1 test2 (waiting) then test3 , and while it was running put test4
i get test1 then test3 then test4 and test2 never came through ..
still better than it was.. by a longshot but it looks like the only foolproof method would be to implement an actuall queue with push pop etc.. Sounds like a royal pain in the ■■■.
probably lowering the waiting time to 30 sec. would be better too as a lot less risk that another 2 message would come in while one is blocked (the first will run if it is no longer blocked)
try port 587 instead of 25
schedule vs runin doesnot work any differntly it is only allow one run to be schedule. Even though the docs imply otherwise.. maybe not for devices.
