Windows Service Weirdness

Forum for things that doesn't really have anything to do with hMailServer. Such as php.ini, beer, etc etc.
Post Reply
User avatar
jimimaseye
Moderator
Moderator
Posts: 8159
Joined: 2011-09-08 17:48

Windows Service Weirdness

Post by jimimaseye » 2018-03-01 23:30

Here is a strange thing that heppened today.

Here is part of a Bat script (part of my backup script):

Code: Select all

echo %time% Stopping Hmailserver service... &net stop hmailserver
if errorlevel 1 set FailedHmailservice=Failed to stop. Backup of emails not performed!& echo %FailedHmailservice%!
echo %time% Stopping Spamassassin service... &net stop spamassassin
Here is the NORMAL everyday output (the service stops, the response of it stopping is shown and then it moves on to stopping spamassassin):

Code: Select all

21:08:41.03 Stopping Hmailserver service...

The hMailServer service was stopped successfully.

21:08:41.06 Stopping Spamassassin service...

And yet tonight, this was the output:

Code: Select all

20:00:00.34 Stopping Hmailserver service...
Ok! 
20:01:00.63 Stopping Spamassassin service...
Note the lack of blank lines (line 2 and 4 of normal output) and the response "Ok!" (where it normally says "The hMailServer service was stopped successfully"). Furthermore, it becomes apparent later in the script when it comes to restart the service that actually there was an errorlevel 1 stored and it therefore thought the service didnt actually stop (despite the "Ok!" being shown).

Weird.

Where the diddly does "Ok!" come from and what does it refer to given that we know:

a, a successful stop doesnt return "Ok!" and
b, an unsuccessful stop is unlikely to return "Ok!" given it doesnt make sense.

Why didnt it work? And why the bizarre output?

I rarely see this strange phenomenon happen but see it I do (where the stopping of the service seems to say it did but it didnt). All this happens at a quiet moment of activity.

Comments or theories welcome.
HMS 5.6.6 B2383 on Win Server 2008 R2 Foundation, + 5.6.7-B2415 on test.
SpamassassinForWindows 3.4.0 spamd service
AV: Clamwin + Clamd service + sanesecurity defs : https://www.hmailserver.com/forum/viewtopic.php?f=21&t=26829

mikedibella
Normal user
Normal user
Posts: 181
Joined: 2016-12-08 02:21

Re: Windows Service Weirdness

Post by mikedibella » 2018-03-02 00:13

Check each directory in your %PATH% for an executable named NET.EXE. If there is another executable named NET.EXE in a directory before %SYSTEMROOT%\System32, that program will be executed in your script. To fix, fully qualify the file (i.e. net -> %SYSTEMROOT%\System32\NET.EXE).

User avatar
jimimaseye
Moderator
Moderator
Posts: 8159
Joined: 2011-09-08 17:48

Re: Windows Service Weirdness

Post by jimimaseye » 2018-03-02 00:57

Well i haven't looked but the system is pretty virgin - no reason to think any 3rd party or additional net.exe temporarily appears. Also just running the script again straight after works fine as it does every other night

The problem is i can't reproduced this at will.
HMS 5.6.6 B2383 on Win Server 2008 R2 Foundation, + 5.6.7-B2415 on test.
SpamassassinForWindows 3.4.0 spamd service
AV: Clamwin + Clamd service + sanesecurity defs : https://www.hmailserver.com/forum/viewtopic.php?f=21&t=26829

User avatar
Dravion
Senior user
Senior user
Posts: 1476
Joined: 2015-09-26 11:50
Location: Germany
Contact:

Re: Windows Service Weirdness

Post by Dravion » 2018-03-02 01:53

net.exe is a normal, native console program which was migrated from Microsoft MS-DOS LAN Manager in the early 90s to Windows NT (the predesessor of Win7/8/10 and Win Server Editions).

How ever, like many console programs, it communicates with the User via Standard
IN/OUT/ERR Concept, like most Console programs do. It think the "Diddly" you mention is just a normal Stadard OUT Message by NET.EXE. You can use sc.exe instead which is the more recent method to control and interact with Windows Services.

mikedibella
Normal user
Normal user
Posts: 181
Joined: 2016-12-08 02:21

Re: Windows Service Weirdness

Post by mikedibella » 2018-03-02 03:50

I notice that the time between postings in the successful run is 3/100s of a second, but in the abnormal run the time differential is 1 minute and 29/100s of a second. Maybe there was some kind of failure that produced abend output?

User avatar
jimimaseye
Moderator
Moderator
Posts: 8159
Joined: 2011-09-08 17:48

Re: Windows Service Weirdness

Post by jimimaseye » 2018-03-02 11:13

mikedibella wrote:
2018-03-02 03:50
I notice that the time between postings in the successful run is 3/100s of a second, but in the abnormal run the time differential is 1 minute and 29/100s of a second. Maybe there was some kind of failure that produced abend output?
Good spot. I hadn't noticed that. So the service genuinely failed and timed out (60 seconds seems quite definitive). I guess the hmailserver service may be stuck or failed to stop for a reason but not the 'ok!'.

will look deeper on better errorlevel handling.
HMS 5.6.6 B2383 on Win Server 2008 R2 Foundation, + 5.6.7-B2415 on test.
SpamassassinForWindows 3.4.0 spamd service
AV: Clamwin + Clamd service + sanesecurity defs : https://www.hmailserver.com/forum/viewtopic.php?f=21&t=26829

User avatar
jimimaseye
Moderator
Moderator
Posts: 8159
Joined: 2011-09-08 17:48

Re: Windows Service Weirdness

Post by jimimaseye » 2018-03-02 19:57

Ok, I have a little more sense where the "OK!" came from.

Here is the full unedited code that is actually being carried out:

Code: Select all

echo %time% Stopping Hmailserver service...>> %BackLog%&net stop hmailserver >> %BackLog%
set FailedHmailservice=Ok
set bold=%noBold%&set fontcolor=%fontBlack%
if errorlevel 1 set Failed=true& set FailedHmailservice=Failed to stop. Backup of emails not performed!&set bold=b&set fontcolor=%colorfill%& echo %FailedHmailservice%! >> %BackLog%
echo ^<tr^>^<td^>^<%fontcolor%^>^<%bold%^>Hmailserver service shutdown:^</td^>^<td^>^<%fontcolor%^>^<%bold%^>%FailedHmailservice%^</td^>^</tr^> >>%outf%
In essence it says:
1, stop the service
2, set FailedHmailservice=Ok
3, if errorlevel 1 (due to it failing to stop) then set FailedHmailservice=Failed to stop. Backup of emails not performed! &
set bold=b &
set fontcolor=%colorfill%
echo %FailedHmailservice%!
4, echo %FailedHmailservice% to the final output report

So, basically:
if the service stops (errorlevel = 0) then we should see nothing in the log and "Ok" in the final report
If it doesnt stop (errorlevel = 1) then we should see "Failed to stop. Backup of emails not performed!" in the log file and the output report.

And yet we ended up with FailedHmailservice as "Ok" (as if errorlevel = 0) whilst having FailedHmailservice output to the logfile as if it was errorlevel 1 (hence the appearance of "Ok!"). Further more the output report did report it in bold just as set in the errorlevel 1 clause.

It seems that stage (2) happened, errorlevel 1 occured and entered stage (3) but it then ignored specifically the "set FailedHmailservice=Failed to stop. Backup of emails not performed!" instruction (yet continued to execute everything after it).

So I looked closer and noted the [space] after the first ampersand in "& set FailedHmailservice=Failed to stop. Backup of emails not performed!&set ....". I did a test and proved that to be the cause:

Code: Select all

>set FailedHmailservice=unset

>set Failed=true& set FailedHmailservice=Failed to stop. Backup of emails not performed!&set bold=b& echo %FailedHmailservice%!

unset!
Note that after initially setting the variable to 'unset' it remains as 'unset'.

I removed the space a lo and behold:

Code: Select all

>set Failed=true&set FailedHmailservice=Failed to stop. Backup of emails not performed!&set bold=b& echo %FailedHmailservice%!

Failed to stop. Backup of emails not performed!!
Now it changes the variable correctly.

A fundamental problem and I found the "& set" throughout my script. Ive now changed then all. Thanks goodness. Another lesson learnt.
HMS 5.6.6 B2383 on Win Server 2008 R2 Foundation, + 5.6.7-B2415 on test.
SpamassassinForWindows 3.4.0 spamd service
AV: Clamwin + Clamd service + sanesecurity defs : https://www.hmailserver.com/forum/viewtopic.php?f=21&t=26829

User avatar
jimimaseye
Moderator
Moderator
Posts: 8159
Joined: 2011-09-08 17:48

Re: Windows Service Weirdness

Post by jimimaseye » 2018-03-02 21:11

Dravion wrote:
2018-03-02 01:53
You can use sc.exe instead which is the more recent method to control and interact with Windows Services.
SC.exe would not be suitable and using NET stop/start is necessary. There is a fundamental difference why NET is used and not SC. It is very well explained why here (with a link that further goes in to more detail): https://superuser.com/a/552234
HMS 5.6.6 B2383 on Win Server 2008 R2 Foundation, + 5.6.7-B2415 on test.
SpamassassinForWindows 3.4.0 spamd service
AV: Clamwin + Clamd service + sanesecurity defs : https://www.hmailserver.com/forum/viewtopic.php?f=21&t=26829

Post Reply