Kitz Forum
Broadband Related => Router Monitoring Software => Topic started by: kitz on August 23, 2013, 12:14:42 PM
-
I'd noticed that after a couple of days of running HG612 modem stats that my PC would start being a bit sluggish and upon investigating I found that I would have hundreds of instances of HG612_stats.exe running.
Because of the volume, the only way I could clear them all was to reboot the PC. Last night I tried to do some testing and see if I could find out the reason, but unfortunately Ive drawn a blank other than note that a few other users said they had the same issue.
For an hour or so last night I did a fresh reboot and stopped running DSLstats to see if that was the culprit, but it didnt seem to make any difference because every minute a new process HG612_stats.exe *32 would generate in Task Manager.
I also have a few hundred conhost.exe (Console Windows Host) running.
and an awful lot of ONGOING-ISRUNNING-xxxxxx-xxx files in the scripts folder.
At one point I thought I'd found the culprit (having HG612 Settings editor running), but that was closed last night and by this morning I again had 100s of HG612_stats.exe running.
I've found I can trigger multiple instances by having one of the text files in HG612_Modem_Stats\Scripts open, but that shouldnt have accounted for all the new processes overnight.
Anyone else any other ideas?
-
This issue was spotted recently & I have been working on an update that seems to deal with it.
I'm not sure about leaving a text file open being a possible trigger, but it could have some relevance, although I haven't seen that cause any isses at my end.
Could you confirm which particular file or files seemed to trigger the issue?
With a lot of help from ColinS (testing various debugging versions & forwarding resulting error log files etc.), we seem to have found that the method used to allow access to a HG622 modem in v 1.1 has actually introduced a bug for some HG612 users.
Users most affected appear to be those with very slow PCs or having the programs working on very 'busy' PCs, especially when used as servers.
I have attached a copy of the bug-fix version (using an alternative & still automated method of determining & accessing a HG622, that now doesn't cause any issues for HG612 modem users) if you wouldn't mind trying it out.
Simply use it in the Scripts folder instead of the current version of HG612_stats.exe (after termininating any left over instances of HG612_stats.exe, CMD.exe and Conhost.exe - or rebooting the PC).
For now, it generates a specific error log file in the Ongoing_Stats folder named "ERROR.LOG_file_ERROR.TXT"
If any issues are still spotted, it would be most helpful if that log file (or snippets of it) could be posted for my detailed inspection.
FWIW, this version also deals with the known occasional Windows bug, where more than one instance of a Windows Scheduled Task attempts to run, even though it is already running.
The Task Scheduler setting to NOT run another instance doesn't always seem to work as Microsoft intended it to.
(At least on my Windows 7 PC).
http://support.microsoft.com/kb/2461249/en-us?sd=rss&spid=14019
Assuming the debugging version does fix matters properly, I'll release a 'normal' version in due course.
-
Thank you BE... on the ball as usual :)
>> Could you confirm which particular file or files seemed to trigger the issue?
It may or may not be a co-incidence, but I could do a reboot and it would be fine for a couple of times, but when I open say a log or txt file it would seem to trigger it off. eg modem_stats.log, error.log
I only noticed this because I was deliberately looking at the files to see what to keep etc before I tried a fresh install ( & update)
>> Users most affected appear to be those with very slow PCs or having the programs working on very 'busy' PCs, especially when used as servers.
i7-3770 CPU with 8GB of RAM running Win 7 Pro so dont think its hardware.
It at times does get used with some programs that may be a lil bit heavy on resources (such as D/W, photoshop). I dont currently have the FTP or HTTP server running.
Last night all that was open was Mail, a half finished page in DreamWeaver (so it would have periodically been syncing with the site, but that shouldnt cause probs) DSLstats & HG612stats.
>> the method used to allow access to a HG622 modem in v 1.1
Although Ive downloaded v1.1 I've not yet updated it.
>> I have attached a copy of the bug-fix version
I certainly will, thank you.. reason for delay was going to do a quick setting up tutorial for HG612 stats, but not quite finished it.
Will get back to you :)
-
This issue was spotted recently & I have been working on an update that seems to deal with it.
<snip>
With a lot of help from ColinS (testing various debugging versions & forwarding resulting error log files etc.), we seem to have found that the method used to allow access to a HG622 modem in v 1.1 has actually introduced a bug for some HG612 users.
Would you please let me know (and not by a tail peck, thank you) if you have implemented the technique that we recently discussed as the 'work around'? If yes, I'll test its behaviour with a HG622 device. :)
-
Would you please let me know (and not by a tail peck, thank you) if you have implemented the technique that we recently discussed as the 'work around'? If yes, I'll test its behaviour with a HG622 device. :)
Thank you b*cat.
That is indeed that is the method currently implemented in the 'debugging' version.
It seems to work purrfectly with the HG612, but as yet I have not tested with a HG622.
-
Thank you for the confirmation, Mr Eagle. I will check the operation with a HG622 modem/router and report back with my observations.
-
I can now report that with a minor adjustment (detailed in my e-mail message to the Eagles' Nest) the code is also satisfactory for a HG622 modem/router. :)
Time for b*cat is search for his delayed evening meal . . . :angel:
-
The fix 'appears' to have been running successfully now for about 7 hrs with only one instance showing in Task Manager.
However, Im not quite sure what Ive done wrong, but the scheduled current stats for midnight didnt run.. nor did my ongoing stats due at 23:58
24/08/2013 00:38:00.390 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling
24/08/2013 00:38:00.451 - HG612_current_stats.exe was NOT running
24/08/2013 00:38:00.451 - Temp File ONGOING-ISRUNNING-003800-451.TXT was created
24/08/2013 00:38:00.631 - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1.
24/08/2013 00:38:00.645 - *** In exit_2_instances - Closing ERROR.LOG. Status = 1.
23/08/2013 23:58:00.35 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
23/08/2013 23:58:00.37 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
23/08/2013 23:58:00.38 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
23/08/2013 23:58:00.44 - About to create ONGOING-ISRUNNING-235800-432.TXT Status = 1,
23/08/2013 23:58:00.45 - ONGOING-ISRUNNING-235800-432.TXT created. Status = 1,
23/08/2013 23:58:00.57 - ONGOING-ISRUNNING-235800-432.TXT - There are 2 instances of HG612_stats.exe running. Status = 1,
23/08/2013 23:58:00.58 - ONGOING-ISRUNNING-235800-432.TXT - ** About to exit as there are 2 instances of HG612_stats.exe running. Status = 1,
23/08/2013 23:58:00.60 - ONGOING-ISRUNNING-235800-432.TXT - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1,
23/08/2013 23:58:00.61 - ONGOING-ISRUNNING-235800-432.TXT - *** In exit_2_instances - Closing ERROR.LOG. Status = 1,
Last data appears to have been collected at
23/08/2013 18:20 79999 14441 12.6 20.4 14.3 6.9 105128 27659 PTM according to the modem_stats.log.
/me goes to check check and double check my settings.
-
A Windows Scheduled Task is set up via the Settings Editor to run every minute, indefinitely until the task is disabled or deleted.
The task should trigger HG612_Run.exe to run HG612_stats.exe completely 'silently'.
You should only see HG612_stats.exe in Task Manager for around 2 seconds each minute.
If HG612_stats.exe is still running (or 'stuck'), any subsequent attempts to to run it will be exited:-
23/08/2013 23:58:00.57 - ONGOING-ISRUNNING-235800-432.TXT - There are 2 instances of HG612_stats.exe running. Status = 1,
23/08/2013 23:58:00.58 - ONGOING-ISRUNNING-235800-432.TXT - ** About to exit as there are 2 instances of HG612_stats.exe running. Status = 1,
This is intended to allow HG612_stats.exe to complete properly whenever the PC is slowed sufficiently (e.g. by a very resource hungry virus scan etc.) that a new instance tries to start before the original instance has completed.
If HG612_stats.exe is permanently visible in Task Manager, it could be left over from before you started using 'bug-fix' version, some other event has caused it to lock or v 1.1 is still using the HG612_stats.ini file from v 1.0.
If HG612_stats.exe is still showing permanently in Task Manager, possibly hogging up to 25% of CPU resource for each instance, the process(es) should be ended & logging should then continue as intended.
If the last 2 sections are not included in the ini file as shown in this snippet ([Editor] & [Event/Error_logging]), simply copy & paste them in:-
[Logging]
Ongoing_Logging= YES
Current_Stats= YES
Current_Stats_Interval= 8
Current_Stats_Datum= 06
[Editor]
Use_own_tasks= NO
[Event/Error_logging]
Extensive_event_logging= YES
I have tried to reproduce the issue of having the associated text files open in Wordpad & MS Word (causing HG612_stats.exe to lock), but have been unable to do so.
The only effect was to cause missed data from the relevant file.
Closing the files allowed data to be recorded again.
-
>> You should only see HG612_stats.exe in Task Manager for around 2 seconds each minute.
I can confirm this is what was happening after I used the new fix. Last night I removed the task and tried creating a new one, but for some reason I still didnt get any stats logged. I can confirm that I did a reboot inbetween moving in order to clear all the running HG612_stats in task manager.
In the end I put the old v1.1 back and logging has resumed. I did another fresh boot during that process.
This morning I notice that I have lots of the running processes again. I really dont want to reboot the PC atm as I have something open.
What I will do though is clear the task, then manually remove all instances from task manager and replace with the debug version again. I'll do that in a mo and get back to you asap on this although I should be something else atm :D :D
>>> I have tried to reproduce the issue of having the associated text files open
As mentioned above, it may have just been co-incidence then. Sorry for the red herring :/ Sometimes it will be fine for a short while.. until one process gets stuck, then this seems to set the add a new instance every minute.
-
Just had to do a reboot :( :'(
There wasnt anyway I could clear everything too many instances of other things such as cmd.exe, isvbrumming, console etc.. everything just locked up.
I notice it didnt log the current stats again today - which is hardly surprising as it seems that HG612_current_stats.exe is one of the processes which was stuck. In the midst of all this my line did a resync and came back up at 15Mb. It looks like it tried to log the resync stats then broke... all I have is an empty folder with no content. This being stuck was the final straw for my PC and everything became unresponsive hence having to force a shutdown.
Ive put the fix back in place. I can confirm that those lines are appended in the .ini file.
However once again as soon as I put the fix in place then just as before, nothing gets recorded or appended to the modem_stats.log
Last item recorded is 24/08/2013 12:47 79999 15295
I may see if I can quickly put v 1 back on if the file is still around ... I have guests due and Ive still not made up the guest room nor been and got the necessary supplies for this evening.
----
cant find the link for v1.. damn it.... not recording anything atm :(
-
I have attached my own v 1.1 HG612_stats.ini file (also using the bug-fix version of HG612_stats.exe - without any problem at all).
Does yours look similar?
-
yep
[Login]
IP_address= 192.168.1.1
Username= admin
Password= admin
Shell= sh
[Locations]
Main_folder= C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats
Scripts_and_Programs= C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts
Apps_folder= C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Apps
Current_Stats_folder= C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Current_Stats
Ongoing_Stats_folder= C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Ongoing_Stats
[Mode]
Mode= extensive
[Graphing]
Pause_after_obtaining_snapshot_data= NO
Auto_graph_Snapshot_data= YES
Pause_after_snapshot_graphs_plotted= NO
Pause_after_ongoing_graphs_plotted= NO
Plot_area_background_colour= 31
Daily_Graphing= YES
Daily_Graphing_Time= 23:58
[Delays]
Delay_snapshot_data_harvest_seconds= 10
Delay_ongoing_data_harvest_seconds= 0
[Logging]
Ongoing_Logging= YES
Current_Stats= YES
Current_Stats_Interval= 8
Current_Stats_Datum= 06
[Editor]
Use_own_tasks= NO
[Event/Error_logging]
Extensive_event_logging= YES
-
I cant find a link for v1 seems to all re-direct back to 1.1.
anyone got a linky please?
-
1.1 just snarles up my PC, the fix seems to stop any logging completely
-----------------
24/08/2013 12:47 79999 15295 replaced with fix -
no longing until I dropped the 1.1 exe back in
24/08/2013 13:17 79999 15295
continues to log fine until
24/08/2013 13:38 79999 15295
Closed all instances in task manager
Replaced with fixed exe
logging stops completely again.
Replaced with v1.1
logging resumes
24/08/2013 13:42 79999 15295
-
BE dont know if this helps, but you can see for the period
when I was using the fix, (13:39 to 13:41) no data was being appended to HG612_Modem_Stats\Ongoing_Stats\modem_stats.log
13:42 is when I dropped v1.1 back in
24/08/2013 13:40:00.38 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
24/08/2013 13:40:00.39 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
24/08/2013 13:40:00.41 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
24/08/2013 13:40:00.47 - About to create ONGOING-ISRUNNING-134000-462.TXT Status = 1,
24/08/2013 13:40:00.48 - ONGOING-ISRUNNING-134000-462.TXT created. Status = 1,
24/08/2013 13:40:00.60 - ONGOING-ISRUNNING-134000-462.TXT - There are 1 instances of HG612_stats.exe running. Status = 1,
24/08/2013 13:40:00.61 - ONGOING-ISRUNNING-134000-462.TXT - ** Continuing as there are only 1 instances of HG612_stats.exe running **. Status = 1,
24/08/2013 13:40:00.62 - ONGOING-ISRUNNING-134000-462.TXT - C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Ongoing_Stats\ERROR.LOG opened for appending. Status = 1,
24/08/2013 13:40:00.64 - ONGOING-ISRUNNING-134000-462.TXT - malloc() O.K. Status = 1,
24/08/2013 13:40:00.65 - ONGOING-ISRUNNING-134000-462.TXT - WSAStartup() SUCCESSFUL!!! Status = 1,
24/08/2013 13:40:00.66 - ONGOING-ISRUNNING-134000-462.TXT - getaddrinfo() O.K. Status = 1,
24/08/2013 13:40:00.67 - ONGOING-ISRUNNING-134000-462.TXT - connect() O.K. Status = 1,
24/08/2013 13:40:00.68 - ONGOING-ISRUNNING-134000-462.TXT - ********** DEBUG VERSION - Trying the HG622 bodge. Status = 1. **********
24/08/2013 13:40:00.69 - ONGOING-ISRUNNING-134000-462.TXT - ********** The HG622 bodge worked Status = 1. **********
24/08/2013 13:40:00.70 - ONGOING-ISRUNNING-134000-462.TXT - About to log in to the modem. Status = 1,
24/08/2013 13:40:00.91 - ONGOING-ISRUNNING-134000-462.TXT - **** expect("gin:") O.K. Status = 1.
24/08/2013 13:40:00.93 - ONGOING-ISRUNNING-134000-462.TXT - **** reply(config.Username) O.K. Status = 1.
24/08/2013 13:40:01.14 - ONGOING-ISRUNNING-134000-462.TXT - **** expect("ssword:") O.K. Status = 1.
24/08/2013 13:40:01.16 - ONGOING-ISRUNNING-134000-462.TXT - **** reply(config.Password) O.K. Status = 1.
24/08/2013 13:40:01.37 - ONGOING-ISRUNNING-134000-462.TXT - **** expect("ATP>") O.K. Status = 1.
24/08/2013 13:40:01.39 - ONGOING-ISRUNNING-134000-462.TXT - **** reply(config.Shell) O.K. Status = 1.
24/08/2013 13:41:00.37 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
24/08/2013 13:41:00.39 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
24/08/2013 13:41:00.40 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
24/08/2013 13:41:00.46 - About to create ONGOING-ISRUNNING-134100-455.TXT Status = 1,
24/08/2013 13:41:00.47 - ONGOING-ISRUNNING-134100-455.TXT created. Status = 1,
24/08/2013 13:41:00.60 - ONGOING-ISRUNNING-134100-455.TXT - There are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 13:41:00.61 - ONGOING-ISRUNNING-134100-455.TXT - ** About to exit as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 13:41:00.62 - ONGOING-ISRUNNING-134100-455.TXT - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 13:41:00.63 - ONGOING-ISRUNNING-134100-455.TXT - *** In exit_2_instances - Closing ERROR.LOG. Status = 1,
24/08/2013 13:42:00.38 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
24/08/2013 13:42:00.39 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
24/08/2013 13:42:00.40 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
24/08/2013 13:42:00.46 - About to create ONGOING-ISRUNNING-134200-457.TXT Status = 1,
24/08/2013 13:42:00.47 - ONGOING-ISRUNNING-134200-457.TXT created. Status = 1,
24/08/2013 13:42:00.61 - ONGOING-ISRUNNING-134200-457.TXT - There are 1 instances of HG612_stats.exe running. Status = 1,
24/08/2013 13:42:00.62 - ONGOING-ISRUNNING-134200-457.TXT - ** Continuing as there are only 1 instances of HG612_stats.exe running **. Status = 1,
24/08/2013 13:42:00.63 - ONGOING-ISRUNNING-134200-457.TXT - C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Ongoing_Stats\ERROR.LOG opened for appending. Status = 1,
24/08/2013 13:42:00.64 - ONGOING-ISRUNNING-134200-457.TXT - malloc() O.K. Status = 1,
24/08/2013 13:42:00.65 - ONGOING-ISRUNNING-134200-457.TXT - WSAStartup() SUCCESSFUL!!! Status = 1,
24/08/2013 13:42:00.66 - ONGOING-ISRUNNING-134200-457.TXT - getaddrinfo() O.K. Status = 1,
24/08/2013 13:42:00.67 - ONGOING-ISRUNNING-134200-457.TXT - connect() O.K. Status = 1,
24/08/2013 13:42:00.68 - ONGOING-ISRUNNING-134200-457.TXT - ********** DEBUG VERSION - Trying the HG622 bodge. Status = 1. **********
24/08/2013 13:42:00.69 - ONGOING-ISRUNNING-134200-457.TXT - ********** The HG622 bodge worked Status = 1. **********
24/08/2013 13:42:00.71 - ONGOING-ISRUNNING-134200-457.TXT - About to log in to the modem. Status = 1,
24/08/2013 13:42:00.91 - ONGOING-ISRUNNING-134200-457.TXT - **** expect("gin:") O.K. Status = 1.
24/08/2013 13:42:00.92 - ONGOING-ISRUNNING-134200-457.TXT - **** reply(config.Username) O.K. Status = 1.
24/08/2013 13:42:01.11 - ONGOING-ISRUNNING-134200-457.TXT - **** expect("ssword:") O.K. Status = 1.
24/08/2013 13:42:01.12 - ONGOING-ISRUNNING-134200-457.TXT - **** reply(config.Password) O.K. Status = 1.
24/08/2013 13:42:01.32 - ONGOING-ISRUNNING-134200-457.TXT - **** expect("ATP>") O.K. Status = 1.
24/08/2013 13:42:01.33 - ONGOING-ISRUNNING-134200-457.TXT - **** reply(config.Shell) O.K. Status = 1.
24/08/2013 13:42:01.53 - ONGOING-ISRUNNING-134200-457.TXT - **** expect("# ") O.K. Status = 1.
24/08/2013 13:42:01.55 - ONGOING-ISRUNNING-134200-457.TXT - **** Reaching this point means logging in to the modem was successful. Status = 1,
24/08/2013 13:42:01.56 - ONGOING-ISRUNNING-134200-457.TXT - After xdslcmd info --stats(), ERROR.LOG status = 1
24/08/2013 13:42:01.78 - ONGOING-ISRUNNING-134200-457.TXT - After xdslcmd info --pbParams(), ERROR.LOG status = 1
24/08/2013 13:42:02.18 - ONGOING-ISRUNNING-134200-457.TXT - Logged out of modem O.K. Status = 1,
24/08/2013 13:42:02.23 - ONGOING-ISRUNNING-134200-457.TXT - get_log_data() completed. Status = 1,
24/08/2013 13:42:02.26 - ONGOING-ISRUNNING-134200-457.TXT - Appending data to C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Ongoing_Stats\modem_stats.log - Status = 1,
24/08/2013 13:42:02.27 - ONGOING-ISRUNNING-134200-457.TXT - Data has now been written to MSLOGFILE (C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Ongoing_Stats\modem_stats.log) - Status = 1,
24/08/2013 13:42:02.28 - ONGOING-ISRUNNING-134200-457.TXT - Now in exit. Status = 1,
24/08/2013 13:42:02.30 - ONGOING-ISRUNNING-134200-457.TXT - ONGOING-ISRUNNING-134200-457.TXT DELETED - Status = 1,
24/08/2013 13:42:02.31 - ONGOING-ISRUNNING-134200-457.TXT - End of HG612_stats.exe. Status = 1,
-
Kitz, I had a similar issue with the task when I first installed v1.1 when I mistakenly assumed I should carry over the .ini file. Although I added the extra line to the end of it as BE1 suggested I do, to be sure I used the Tasks menu of the Setting Editor to delete and (re)create the task. It may be worth a shot if you haven't already tried this. I think the task naming was different between v1.0 & v1.1
-
While we wait for BE1 to return, some questions and something to try:
What version of Windows are you running?
What version of the HG612/firmware do you have?
Are you running HG612 in any sort of remote session?
Can you try manually logging into the HG612 with telnet - username/passord/sh/xdlscmd info --stats/exit/exit with success?
[Edit]Do you get all the expected prompts and replies, notably the # prompt missing from your failing examples above?
Here's what I get when it's working:
24/08/2013 14:17:00.31 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
24/08/2013 14:17:00.32 - working_directory = F:\HG612\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
24/08/2013 14:17:00.35 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
24/08/2013 14:17:00.68 - About to create ONGOING-ISRUNNING-141700-670.TXT Status = 1,
24/08/2013 14:17:00.71 - ONGOING-ISRUNNING-141700-670.TXT created. Status = 1,
24/08/2013 14:17:01.45 - ONGOING-ISRUNNING-141700-670.TXT - There are 1 instances of HG612_stats.exe running. Status = 1,
24/08/2013 14:17:01.46 - ONGOING-ISRUNNING-141700-670.TXT - ** Continuing as there are only 1 instances of HG612_stats.exe running **. Status = 1,
24/08/2013 14:17:01.48 - ONGOING-ISRUNNING-141700-670.TXT - F:\HG612\HG612_Modem_Stats\Ongoing_Stats\ERROR.LOG opened for appending. Status = 1,
24/08/2013 14:17:01.49 - ONGOING-ISRUNNING-141700-670.TXT - malloc() O.K. Status = 1,
24/08/2013 14:17:01.53 - ONGOING-ISRUNNING-141700-670.TXT - WSAStartup() SUCCESSFUL!!! Status = 1,
24/08/2013 14:17:01.54 - ONGOING-ISRUNNING-141700-670.TXT - getaddrinfo() O.K. Status = 1,
24/08/2013 14:17:01.57 - ONGOING-ISRUNNING-141700-670.TXT - connect() O.K. Status = 1,
24/08/2013 14:17:01.59 - ONGOING-ISRUNNING-141700-670.TXT - ********** DEBUG VERSION - Trying the HG622 bodge. Status = 1. ********
24/08/2013 14:17:01.62 - ONGOING-ISRUNNING-141700-670.TXT - ********** The HG622 bodge worked Status = 1. **********
24/08/2013 14:17:01.63 - ONGOING-ISRUNNING-141700-670.TXT - About to log in to the modem. Status = 1,
24/08/2013 14:17:01.67 - ONGOING-ISRUNNING-141700-670.TXT - **** expect("gin:") O.K. Status = 1.
24/08/2013 14:17:01.68 - ONGOING-ISRUNNING-141700-670.TXT - **** reply(config.Username) O.K. Status = 1.
24/08/2013 14:17:01.85 - ONGOING-ISRUNNING-141700-670.TXT - **** expect("ssword:") O.K. Status = 1.
24/08/2013 14:17:01.88 - ONGOING-ISRUNNING-141700-670.TXT - **** reply(config.Password) O.K. Status = 1.
24/08/2013 14:17:02.06 - ONGOING-ISRUNNING-141700-670.TXT - **** expect("ATP>") O.K. Status = 1.
24/08/2013 14:17:02.09 - ONGOING-ISRUNNING-141700-670.TXT - **** reply(config.Shell) O.K. Status = 1.
24/08/2013 14:17:02.26 - ONGOING-ISRUNNING-141700-670.TXT - **** expect("# ") O.K. Status = 1.
24/08/2013 14:17:02.29 - ONGOING-ISRUNNING-141700-670.TXT - **** Reaching this point means logging in to the modem was successful. Status = 1,
24/08/2013 14:17:02.31 - ONGOING-ISRUNNING-141700-670.TXT - After xdslcmd info --stats(), ERROR.LOG status = 1
24/08/2013 14:17:02.46 - ONGOING-ISRUNNING-141700-670.TXT - After xdslcmd info --pbParams(), ERROR.LOG status = 1
24/08/2013 14:17:02.87 - ONGOING-ISRUNNING-141700-670.TXT - Logged out of modem O.K. Status = 1,
24/08/2013 14:17:02.90 - ONGOING-ISRUNNING-141700-670.TXT - get_log_data() completed. Status = 1,
24/08/2013 14:17:02.93 - ONGOING-ISRUNNING-141700-670.TXT - Appending data to F:\HG612\HG612_Modem_Stats\Ongoing_Stats\modem_stats.log - Status = 1,
24/08/2013 14:17:02.95 - ONGOING-ISRUNNING-141700-670.TXT - Data has now been written to MSLOGFILE (F:\HG612\HG612_Modem_Stats\Ongoing_Stats\modem_stats.log) - Status = 1,
24/08/2013 14:17:02.96 - ONGOING-ISRUNNING-141700-670.TXT - Now in exit. Status = 1,
24/08/2013 14:17:02.99 - ONGOING-ISRUNNING-141700-670.TXT - ONGOING-ISRUNNING-141700-670.TXT DELETED - Status = 1,
24/08/2013 14:17:03.01 - ONGOING-ISRUNNING-141700-670.TXT - End of HG612_stats.exe. Status = 1,
-
Cheers Colin.
I deliberately started completely afresh with v1.1 because I was doing this (http://www.kitz.co.uk/routers/hg612stats_setup.htm), which covers my exact step by step process and a new ini file was created.
(The c:\ root path was mocked just for the tutorial and I have never run from c:\ - as you can see from the setting of the directory path).
Before I started I actually cleared the task via Task Scheduler - not HG612 Editor - because I wanted to make sure nothing was left behind.
None of the original content of v1 was retained ie the Apps and Scripts folders were brand new. The only folders I did retain were Current_Stats & Ongoing_Stats in order to preserve previous logging data.
>>> to be sure I used the Tasks menu of the Setting Editor to delete and (re)create the task.
Ok this is the only thing I did different, as I used Windows Scheduler - so I'll give that a shot now.
>> What version of Windows are you running?
Windows 7 Professional 64bit SP1
>> What version of the HG612/firmware do you have?
Hardware version VER.B
Software version V100R001C01B028SP10
Firmware version A2pv6C030b.d22g
Not had any problem logging into the shell to get pbparams but I'll also try what you say
No problems with xdslcmd info --stats
-
24/08/2013 14:54 logged ok with 1.1
Task deleted, deleted 1.1 exe .
Deleted all HG612 instances in Windows Task Manager
replaced with fix.exe
logging stops confirmed scheduled task exists - all is green
but no logging being appended to modem_stats.log
15:06 replaced fix.exe with 1.1.exe
24/08/2013 15:07 logging resumes.
Contents of ERROR.LOG_file_ERROR.TXT appended.
24/08/2013 14:56:00.36 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
24/08/2013 14:56:00.38 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
24/08/2013 14:56:00.39 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
24/08/2013 14:56:00.44 - About to create ONGOING-ISRUNNING-145600-445.TXT Status = 1,
24/08/2013 14:56:00.46 - ONGOING-ISRUNNING-145600-445.TXT created. Status = 1,
24/08/2013 14:56:00.58 - ONGOING-ISRUNNING-145600-445.TXT - There are 1 instances of HG612_stats.exe running. Status = 1,
24/08/2013 14:56:00.58 - ONGOING-ISRUNNING-145600-445.TXT - ** Continuing as there are only 1 instances of HG612_stats.exe running **. Status = 1,
24/08/2013 14:56:00.60 - ONGOING-ISRUNNING-145600-445.TXT - C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Ongoing_Stats\ERROR.LOG opened for appending. Status = 1,
24/08/2013 14:56:00.61 - ONGOING-ISRUNNING-145600-445.TXT - malloc() O.K. Status = 1,
24/08/2013 14:56:00.63 - ONGOING-ISRUNNING-145600-445.TXT - WSAStartup() SUCCESSFUL!!! Status = 1,
24/08/2013 14:56:00.63 - ONGOING-ISRUNNING-145600-445.TXT - getaddrinfo() O.K. Status = 1,
24/08/2013 14:56:00.64 - ONGOING-ISRUNNING-145600-445.TXT - connect() O.K. Status = 1,
24/08/2013 14:56:00.66 - ONGOING-ISRUNNING-145600-445.TXT - ********** DEBUG VERSION - Trying the HG622 bodge. Status = 1. **********
24/08/2013 14:56:00.67 - ONGOING-ISRUNNING-145600-445.TXT - ********** The HG622 bodge worked Status = 1. **********
24/08/2013 14:56:00.67 - ONGOING-ISRUNNING-145600-445.TXT - About to log in to the modem. Status = 1,
24/08/2013 14:56:00.88 - ONGOING-ISRUNNING-145600-445.TXT - **** expect("gin:") O.K. Status = 1.
24/08/2013 14:56:00.89 - ONGOING-ISRUNNING-145600-445.TXT - **** reply(config.Username) O.K. Status = 1.
24/08/2013 14:56:01.10 - ONGOING-ISRUNNING-145600-445.TXT - **** expect("ssword:") O.K. Status = 1.
24/08/2013 14:56:01.11 - ONGOING-ISRUNNING-145600-445.TXT - **** reply(config.Password) O.K. Status = 1.
24/08/2013 14:56:01.35 - ONGOING-ISRUNNING-145600-445.TXT - **** expect("ATP>") O.K. Status = 1.
24/08/2013 14:56:01.38 - ONGOING-ISRUNNING-145600-445.TXT - **** reply(config.Shell) O.K. Status = 1.
24/08/2013 14:57:00.38 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
24/08/2013 14:57:00.39 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
24/08/2013 14:57:00.41 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
24/08/2013 14:57:00.45 - About to create ONGOING-ISRUNNING-145700-458.TXT Status = 1,
24/08/2013 14:57:00.47 - ONGOING-ISRUNNING-145700-458.TXT created. Status = 1,
24/08/2013 14:57:00.59 - ONGOING-ISRUNNING-145700-458.TXT - There are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 14:57:00.61 - ONGOING-ISRUNNING-145700-458.TXT - ** About to exit as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 14:57:00.63 - ONGOING-ISRUNNING-145700-458.TXT - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 14:57:00.63 - ONGOING-ISRUNNING-145700-458.TXT - *** In exit_2_instances - Closing ERROR.LOG. Status = 1,
24/08/2013 14:58:00.39 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
24/08/2013 14:58:00.39 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
24/08/2013 14:58:00.40 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
24/08/2013 14:58:00.47 - About to create ONGOING-ISRUNNING-145800-456.TXT Status = 1,
24/08/2013 14:58:00.48 - ONGOING-ISRUNNING-145800-456.TXT created. Status = 1,
24/08/2013 14:58:00.61 - ONGOING-ISRUNNING-145800-456.TXT - There are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 14:58:00.62 - ONGOING-ISRUNNING-145800-456.TXT - ** About to exit as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 14:58:00.64 - ONGOING-ISRUNNING-145800-456.TXT - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 14:58:00.65 - ONGOING-ISRUNNING-145800-456.TXT - *** In exit_2_instances - Closing ERROR.LOG. Status = 1,
24/08/2013 14:59:00.39 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
24/08/2013 14:59:00.40 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
24/08/2013 14:59:00.42 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
24/08/2013 14:59:00.46 - About to create ONGOING-ISRUNNING-145900-469.TXT Status = 1,
24/08/2013 14:59:00.48 - ONGOING-ISRUNNING-145900-469.TXT created. Status = 1,
24/08/2013 14:59:00.61 - ONGOING-ISRUNNING-145900-469.TXT - There are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 14:59:00.62 - ONGOING-ISRUNNING-145900-469.TXT - ** About to exit as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 14:59:00.62 - ONGOING-ISRUNNING-145900-469.TXT - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 14:59:00.64 - ONGOING-ISRUNNING-145900-469.TXT - *** In exit_2_instances - Closing ERROR.LOG. Status = 1,
24/08/2013 15:00:00.38 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
24/08/2013 15:00:00.40 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
24/08/2013 15:00:00.40 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
24/08/2013 15:00:00.46 - About to create ONGOING-ISRUNNING-150000-467.TXT Status = 1,
24/08/2013 15:00:00.48 - ONGOING-ISRUNNING-150000-467.TXT created. Status = 1,
24/08/2013 15:00:00.60 - ONGOING-ISRUNNING-150000-467.TXT - There are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 15:00:00.62 - ONGOING-ISRUNNING-150000-467.TXT - ** About to exit as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 15:00:00.63 - ONGOING-ISRUNNING-150000-467.TXT - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 15:00:00.63 - ONGOING-ISRUNNING-150000-467.TXT - *** In exit_2_instances - Closing ERROR.LOG. Status = 1,
24/08/2013 15:01:00.38 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
24/08/2013 15:01:00.40 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
24/08/2013 15:01:00.41 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
24/08/2013 15:01:00.46 - About to create ONGOING-ISRUNNING-150100-465.TXT Status = 1,
24/08/2013 15:01:00.48 - ONGOING-ISRUNNING-150100-465.TXT created. Status = 1,
24/08/2013 15:01:00.60 - ONGOING-ISRUNNING-150100-465.TXT - There are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 15:01:00.62 - ONGOING-ISRUNNING-150100-465.TXT - ** About to exit as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 15:01:00.63 - ONGOING-ISRUNNING-150100-465.TXT - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 15:01:00.63 - ONGOING-ISRUNNING-150100-465.TXT - *** In exit_2_instances - Closing ERROR.LOG. Status = 1,
24/08/2013 15:02:00.35 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
24/08/2013 15:02:00.36 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
24/08/2013 15:02:00.38 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
24/08/2013 15:02:00.43 - About to create ONGOING-ISRUNNING-150200-431.TXT Status = 1,
24/08/2013 15:02:00.44 - ONGOING-ISRUNNING-150200-431.TXT created. Status = 1,
24/08/2013 15:02:00.55 - ONGOING-ISRUNNING-150200-431.TXT - There are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 15:02:00.57 - ONGOING-ISRUNNING-150200-431.TXT - ** About to exit as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 15:02:00.58 - ONGOING-ISRUNNING-150200-431.TXT - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 15:02:00.58 - ONGOING-ISRUNNING-150200-431.TXT - *** In exit_2_instances - Closing ERROR.LOG. Status = 1,
24/08/2013 15:03:00.36 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
24/08/2013 15:03:00.38 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
24/08/2013 15:03:00.39 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
24/08/2013 15:03:00.44 - About to create ONGOING-ISRUNNING-150300-445.TXT Status = 1,
24/08/2013 15:03:00.46 - ONGOING-ISRUNNING-150300-445.TXT created. Status = 1,
24/08/2013 15:03:00.58 - ONGOING-ISRUNNING-150300-445.TXT - There are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 15:03:00.60 - ONGOING-ISRUNNING-150300-445.TXT - ** About to exit as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 15:03:00.61 - ONGOING-ISRUNNING-150300-445.TXT - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 15:03:00.61 - ONGOING-ISRUNNING-150300-445.TXT - *** In exit_2_instances - Closing ERROR.LOG. Status = 1,
24/08/2013 15:04:00.36 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
24/08/2013 15:04:00.38 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
24/08/2013 15:04:00.39 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
24/08/2013 15:04:00.44 - About to create ONGOING-ISRUNNING-150400-442.TXT Status = 1,
24/08/2013 15:04:00.45 - ONGOING-ISRUNNING-150400-442.TXT created. Status = 1,
24/08/2013 15:04:00.58 - ONGOING-ISRUNNING-150400-442.TXT - There are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 15:04:00.59 - ONGOING-ISRUNNING-150400-442.TXT - ** About to exit as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 15:04:00.59 - ONGOING-ISRUNNING-150400-442.TXT - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 15:04:00.61 - ONGOING-ISRUNNING-150400-442.TXT - *** In exit_2_instances - Closing ERROR.LOG. Status = 1,
24/08/2013 15:05:00.37 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
24/08/2013 15:05:00.39 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
24/08/2013 15:05:00.40 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
24/08/2013 15:05:00.47 - About to create ONGOING-ISRUNNING-150500-456.TXT Status = 1,
24/08/2013 15:05:00.48 - ONGOING-ISRUNNING-150500-456.TXT created. Status = 1,
24/08/2013 15:05:00.61 - ONGOING-ISRUNNING-150500-456.TXT - There are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 15:05:00.61 - ONGOING-ISRUNNING-150500-456.TXT - ** About to exit as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 15:05:00.62 - ONGOING-ISRUNNING-150500-456.TXT - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 15:05:00.64 - ONGOING-ISRUNNING-150500-456.TXT - *** In exit_2_instances - Closing ERROR.LOG. Status = 1,
24/08/2013 15:06:00.37 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
24/08/2013 15:06:00.38 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
24/08/2013 15:06:00.40 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
24/08/2013 15:06:00.45 - About to create ONGOING-ISRUNNING-150600-451.TXT Status = 1,
24/08/2013 15:06:00.46 - ONGOING-ISRUNNING-150600-451.TXT created. Status = 1,
24/08/2013 15:06:00.59 - ONGOING-ISRUNNING-150600-451.TXT - There are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 15:06:00.60 - ONGOING-ISRUNNING-150600-451.TXT - ** About to exit as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 15:06:00.60 - ONGOING-ISRUNNING-150600-451.TXT - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1,
24/08/2013 15:06:00.62 - ONGOING-ISRUNNING-150600-451.TXT - *** In exit_2_instances - Closing ERROR.LOG. Status = 1,
-
BE dont know if this helps, but you can see for the period
when I was using the fix, (13:39 to 13:41) no data was being appended to HG612_Modem_Stats\Ongoing_Stats\modem_stats.log
13:42 is when I dropped v1.1 back in
I can see from the data you posted starting 13:42:00.38, the 'fix' was still in use, which appears to have completed correctly.
(unless you dropped the original v 1.1 back in after that instance had completed.
It seems the instance starting from 13:40:00.38 is the one that didn't complete as the instance starting 13:41:00.37 exited as 2 instances were detected.
FWIW, I use TextPad 5.4.2 rather than Wordpad or MS Word for viewing any of the associated text files/logs as it warns that another program (actually HG612_stats.exe - but not named) has updated the file.
The answer to "Reload it?" should be 'YES'.
According to the TextPad website,
Using TextPad means that no data is missed in modem_stats.log or any of the other text files & HG612_stats.exe shouldn't lock up.
I am also using W7 (Home Premium version) & this is the detail for my Scheduled Task (from the SEttings Editor - 'Tasks', 'Display Task Info':-
Folder: \
HostName: PAUL-PC
TaskName: \HG612 Stats Program
Next Run Time: 24/08/2013 15:22:00
Status: Ready
Logon Mode: Interactive/Background
Last Run Time: 24/08/2013 15:21:00
Last Result: 0
Author: Paul
Task To Run: "C:\HG612_Modem_Stats\Scripts\HG612_Run.exe"
Start In: N/A
Comment: N/A
Scheduled Task State: Enabled
Idle Time: Disabled
Power Management: Stop On Battery Mode, No Start On Batteries
Run As User: Paul-PC\Paul
Delete Task If Not Rescheduled: Enabled
Stop Task If Runs X Hours and X Mins: 72:00:00
Schedule: Scheduling data is not available in this format.
Schedule Type: One Time Only, Minute
Start Time: 14:32:00
Start Date: 24/08/2013
End Date: N/A
Days: N/A
Months: N/A
Repeat: Every: 0 Hour(s), 1 Minute(s)
Repeat: Until: Time: None
Repeat: Until: Duration: Disabled
Repeat: Stop If Still Running: Disabled
-
and the ERROR.LOG over the above period is quite telling. Its very obvious where the fix.exe was in use.
24/08/2013 14:54:00.358 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling
24/08/2013 14:54:00.405 - HG612_current_stats.exe was NOT running
24/08/2013 14:54:00.405 - Temp File ONGOING-ISRUNNING-145400-405.TXT was created
24/08/2013 14:54:00.467 - malloc() O.K.
24/08/2013 14:54:00.467 - Initializing Winsock
24/08/2013 14:54:00.483 - WSAStartup() SUCCESSFUL!!!
24/08/2013 14:54:00.483 - Starting getaddrinfo()
24/08/2013 14:54:00.483 - getaddrinfo() O.K.
24/08/2013 14:54:00.483 - Starting socket()
24/08/2013 14:54:00.483 - socket() O.K.
24/08/2013 14:54:00.483 - Starting connect()
24/08/2013 14:54:00.483 - connect() O.K.
24/08/2013 14:54:01.325 - About to reply(xdslcmd info --stats)
24/08/2013 14:54:01.325 - reply(xdslcmd info --stats) O.K.
24/08/2013 14:54:01.543 - get_data() O.K.
24/08/2013 14:54:01.543 - About to determine the xDSL mode
24/08/2013 14:54:01.543 - Modem in use = HG610 or HG612
24/08/2013 14:54:01.543 - About to parse_stats()
24/08/2013 14:54:01.543 - parse_stats completed
24/08/2013 14:54:01.543 - VDSL2 mode detected so about to reply(xdslcmd info --pbParams)
24/08/2013 14:54:01.543 - reply(xdslcmd info --pbParams) O.K.
24/08/2013 14:54:01.746 - get_data() O.K.
24/08/2013 14:54:01.746 - About to parse_pbParams_data()
24/08/2013 14:54:01.746 - parse_pbParams_data() completed
24/08/2013 14:54:01.746 - About to exit Busybox
24/08/2013 14:54:01.746 - Busybox exited
24/08/2013 14:54:01.965 - About to exit ATP
24/08/2013 14:54:01.965 - ATP exited
24/08/2013 14:54:01.965 - Current data harvested at 1377352440 seconds past the epoch
24/08/2013 14:54:01.965 - About to get_log_data()
24/08/2013 14:54:01.965 - Previous log stats date/time = 1377352380 seconds past the epoch
24/08/2013 14:54:01.965 - time_difference = 1 minutes
24/08/2013 14:54:01.980 - About to calc_ES_delta()
24/08/2013 14:54:01.980 - About to calc_RSCorr_delta()
24/08/2013 14:54:01.980 - ds_RSCorr_THIS_PERIOD = 0
24/08/2013 14:54:01.980 - us_RSCorr_THIS_PERIOD = 0
24/08/2013 14:54:01.980 - About to calc_RSUnCorr_delta()
24/08/2013 14:54:01.980 - About to calc_RS_delta()
24/08/2013 14:54:01.980 - About to calc_OHF_delta()
24/08/2013 14:54:01.980 - About to calc_OHFErr_delta()
24/08/2013 14:54:01.980 - About to calc_HEC_delta()
24/08/2013 14:54:01.980 - About to calc_CRC_delta()
24/08/2013 14:54:01.980 - About to calc_FEC_delta()
24/08/2013 14:54:01.996 - About to calc_Bitswap_delta()
24/08/2013 14:54:01.996 - Appending data to C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Ongoing_Stats\modem_stats.log
24/08/2013 14:54:01.996 - Closing MSLOGFILE.log
24/08/2013 14:54:01.996 - END of 1 minute sampling
24/08/2013 14:54:01.996 - About to close(sockfd)
24/08/2013 14:54:01.996 - About to freeadddrinfo(res)
24/08/2013 14:54:01.996 - About to WSACleanup()
24/08/2013 14:54:01.996 - About to free(txbuf)
24/08/2013 14:54:01.996 - About to free(rxbuf)
24/08/2013 14:54:01.996 - Current sync speeds are DS 79999 kbps US 15295 kbps
24/08/2013 14:54:01.996 - Previous sync speeds are DS 79999 kbps US 15295 kbps
24/08/2013 14:54:01.996 - Sync speeds have NOT changed since the previous data harvest
24/08/2013 14:54:01.996 - ONGOING-ISRUNNING-145400-405.TXT DELETED
*********************************************************************************************************************
24/08/2013 14:54:01.996 - Scheduled Current_Stats logging is switched ON via the ini file
24/08/2013 14:54:01.996 - Current_Stats_Datum = 06
24/08/2013 14:54:01.996 - Current_Stats_Interval = 8
24/08/2013 14:54:01.996 - (Time in Hours - Datum) Modulus Interval i.e. (14 - 6) % 8 = 0
24/08/2013 14:54:01.996 - (Time in Minutes) = 54
24/08/2013 14:54:01.996 - Modulus & minutes *BOTH* have to be zero, so scheduled snapshot logging is NOT due yet
*********************************************************************************************************************
24/08/2013 14:54:01.996 - Scheduled Daily_Graphing is switched ON via the ini file
24/08/2013 14:54:01.996 - Daily_Graphing_hour = 23
24/08/2013 14:54:01.996 - Daily_Graphing_minutes = 58
24/08/2013 14:54:01.996 - Current Time is Hours 14, Minutes 54
24/08/2013 14:54:01.996 - scheduled Daily_Graphing is NOT due yet
*********************************************************************************************************************
24/08/2013 14:54:01.996 - End of HG612_stats.exe program, EXIT error code = 0
24/08/2013 14:54:01.996 - End of HG612_stats.exe program, closing ERROR.LOG
24/08/2013 14:57:00.396 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling
24/08/2013 14:57:00.458 - HG612_current_stats.exe was NOT running
24/08/2013 14:57:00.458 - Temp File ONGOING-ISRUNNING-145700-458.TXT was created
24/08/2013 14:57:00.630 - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1.
24/08/2013 14:57:00.646 - *** In exit_2_instances - Closing ERROR.LOG. Status = 1.
24/08/2013 14:58:00.409 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling
24/08/2013 14:58:00.456 - HG612_current_stats.exe was NOT running
24/08/2013 14:58:00.456 - Temp File ONGOING-ISRUNNING-145800-456.TXT was created
24/08/2013 14:58:00.643 - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1.
24/08/2013 14:58:00.659 - *** In exit_2_instances - Closing ERROR.LOG. Status = 1.
24/08/2013 14:59:00.407 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling
24/08/2013 14:59:00.469 - HG612_current_stats.exe was NOT running
24/08/2013 14:59:00.469 - Temp File ONGOING-ISRUNNING-145900-469.TXT was created
24/08/2013 14:59:00.641 - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1.
24/08/2013 14:59:00.641 - *** In exit_2_instances - Closing ERROR.LOG. Status = 1.
24/08/2013 15:00:00.405 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling
24/08/2013 15:00:00.467 - HG612_current_stats.exe was NOT running
24/08/2013 15:00:00.467 - Temp File ONGOING-ISRUNNING-150000-467.TXT was created
24/08/2013 15:00:00.639 - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1.
24/08/2013 15:00:00.639 - *** In exit_2_instances - Closing ERROR.LOG. Status = 1.
24/08/2013 15:01:00.403 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling
24/08/2013 15:01:00.465 - HG612_current_stats.exe was NOT running
24/08/2013 15:01:00.465 - Temp File ONGOING-ISRUNNING-150100-465.TXT was created
24/08/2013 15:01:00.637 - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1.
24/08/2013 15:01:00.652 - *** In exit_2_instances - Closing ERROR.LOG. Status = 1.
24/08/2013 15:02:00.369 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling
24/08/2013 15:02:00.431 - HG612_current_stats.exe was NOT running
24/08/2013 15:02:00.431 - Temp File ONGOING-ISRUNNING-150200-431.TXT was created
24/08/2013 15:02:00.587 - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1.
24/08/2013 15:02:00.603 - *** In exit_2_instances - Closing ERROR.LOG. Status = 1.
24/08/2013 15:03:00.382 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling
24/08/2013 15:03:00.445 - HG612_current_stats.exe was NOT running
24/08/2013 15:03:00.445 - Temp File ONGOING-ISRUNNING-150300-445.TXT was created
24/08/2013 15:03:00.616 - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1.
24/08/2013 15:03:00.616 - *** In exit_2_instances - Closing ERROR.LOG. Status = 1.
24/08/2013 15:04:00.380 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling
24/08/2013 15:04:00.442 - HG612_current_stats.exe was NOT running
24/08/2013 15:04:00.442 - Temp File ONGOING-ISRUNNING-150400-442.TXT was created
24/08/2013 15:04:00.598 - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1.
24/08/2013 15:04:00.614 - *** In exit_2_instances - Closing ERROR.LOG. Status = 1.
24/08/2013 15:05:00.393 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling
24/08/2013 15:05:00.456 - HG612_current_stats.exe was NOT running
24/08/2013 15:05:00.456 - Temp File ONGOING-ISRUNNING-150500-456.TXT was created
24/08/2013 15:05:00.627 - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1.
24/08/2013 15:05:00.643 - *** In exit_2_instances - Closing ERROR.LOG. Status = 1.
24/08/2013 15:06:00.389 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling
24/08/2013 15:06:00.451 - HG612_current_stats.exe was NOT running
24/08/2013 15:06:00.451 - Temp File ONGOING-ISRUNNING-150600-451.TXT was created
24/08/2013 15:06:00.623 - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1.
24/08/2013 15:06:00.623 - *** In exit_2_instances - Closing ERROR.LOG. Status = 1.
24/08/2013 15:07:00.371 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling
24/08/2013 15:07:00.418 - HG612_current_stats.exe was NOT running
24/08/2013 15:07:00.418 - Temp File ONGOING-ISRUNNING-150700-418.TXT was created
24/08/2013 15:07:00.480 - malloc() O.K.
24/08/2013 15:07:00.480 - Initializing Winsock
24/08/2013 15:07:00.480 - WSAStartup() SUCCESSFUL!!!
24/08/2013 15:07:00.480 - Starting getaddrinfo()
24/08/2013 15:07:00.480 - getaddrinfo() O.K.
24/08/2013 15:07:00.480 - Starting socket()
24/08/2013 15:07:00.480 - socket() O.K.
24/08/2013 15:07:00.480 - Starting connect()
24/08/2013 15:07:00.480 - connect() O.K.
24/08/2013 15:07:01.338 - About to reply(xdslcmd info --stats)
24/08/2013 15:07:01.338 - reply(xdslcmd info --stats) O.K.
24/08/2013 15:07:01.541 - get_data() O.K.
24/08/2013 15:07:01.541 - About to determine the xDSL mode
24/08/2013 15:07:01.541 - Modem in use = HG610 or HG612
24/08/2013 15:07:01.541 - About to parse_stats()
24/08/2013 15:07:01.541 - parse_stats completed
24/08/2013 15:07:01.541 - VDSL2 mode detected so about to reply(xdslcmd info --pbParams)
24/08/2013 15:07:01.541 - reply(xdslcmd info --pbParams) O.K.
24/08/2013 15:07:01.759 - get_data() O.K.
24/08/2013 15:07:01.759 - About to parse_pbParams_data()
24/08/2013 15:07:01.759 - parse_pbParams_data() completed
24/08/2013 15:07:01.759 - About to exit Busybox
24/08/2013 15:07:01.759 - Busybox exited
24/08/2013 15:07:01.962 - About to exit ATP
24/08/2013 15:07:01.962 - ATP exited
24/08/2013 15:07:01.978 - Current data harvested at 1377353220 seconds past the epoch
24/08/2013 15:07:01.978 - About to get_log_data()
24/08/2013 15:07:01.978 - Previous log stats date/time = 1377352440 seconds past the epoch
24/08/2013 15:07:01.978 - time_difference = 13 minutes
24/08/2013 15:07:01.978 - WARNING!!! time_difference is more than 1 minute - Ignoring previous logged time
24/08/2013 15:07:01.993 - About to calc_ES_delta()
24/08/2013 15:07:01.993 - About to calc_RSCorr_delta()
24/08/2013 15:07:01.993 - ds_RSCorr_THIS_PERIOD = 0
24/08/2013 15:07:01.993 - us_RSCorr_THIS_PERIOD = 0
24/08/2013 15:07:01.993 - About to calc_RSUnCorr_delta()
24/08/2013 15:07:01.993 - About to calc_RS_delta()
24/08/2013 15:07:01.993 - About to calc_OHF_delta()
24/08/2013 15:07:01.993 - About to calc_OHFErr_delta()
24/08/2013 15:07:01.993 - About to calc_HEC_delta()
24/08/2013 15:07:01.993 - About to calc_CRC_delta()
24/08/2013 15:07:01.993 - About to calc_FEC_delta()
24/08/2013 15:07:02.009 - About to calc_Bitswap_delta()
24/08/2013 15:07:02.009 - Appending data to C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Ongoing_Stats\modem_stats.log
24/08/2013 15:07:02.009 - Closing MSLOGFILE.log
24/08/2013 15:07:02.009 - END of 1 minute sampling
24/08/2013 15:07:02.009 - About to close(sockfd)
24/08/2013 15:07:02.009 - About to freeadddrinfo(res)
24/08/2013 15:07:02.009 - About to WSACleanup()
24/08/2013 15:07:02.009 - About to free(txbuf)
24/08/2013 15:07:02.009 - About to free(rxbuf)
24/08/2013 15:07:02.009 - Current sync speeds are DS 79999 kbps US 15295 kbps
24/08/2013 15:07:02.009 - Previous sync speeds are DS 79999 kbps US 15295 kbps
24/08/2013 15:07:02.009 - Sync speeds have NOT changed since the previous data harvest
24/08/2013 15:07:02.009 - ONGOING-ISRUNNING-150700-418.TXT DELETED
*********************************************************************************************************************
24/08/2013 15:07:02.009 - Scheduled Current_Stats logging is switched ON via the ini file
24/08/2013 15:07:02.009 - Current_Stats_Datum = 06
24/08/2013 15:07:02.009 - Current_Stats_Interval = 8
24/08/2013 15:07:02.009 - (Time in Hours - Datum) Modulus Interval i.e. (15 - 6) % 8 = 1
24/08/2013 15:07:02.009 - (Time in Minutes) = 07
24/08/2013 15:07:02.009 - Modulus & minutes *BOTH* have to be zero, so scheduled snapshot logging is NOT due yet
*********************************************************************************************************************
24/08/2013 15:07:02.009 - Scheduled Daily_Graphing is switched ON via the ini file
24/08/2013 15:07:02.009 - Daily_Graphing_hour = 23
24/08/2013 15:07:02.009 - Daily_Graphing_minutes = 58
24/08/2013 15:07:02.009 - Current Time is Hours 15, Minutes 07
24/08/2013 15:07:02.009 - scheduled Daily_Graphing is NOT due yet
*********************************************************************************************************************
24/08/2013 15:07:02.009 - End of HG612_stats.exe program, EXIT error code = 0
24/08/2013 15:07:02.009 - End of HG612_stats.exe program, closing ERROR.LOG
Our posts have just crossed.
>>>
FWIW, I use TextPad 5.4.2 rather than Wordpad or MS Word
I use Notepad++ which is designed for programmers. Wouldnt dream of using Word because of the additional chars etc.
It also warns yes for reload
This is the contents of the Task
Folder: \
HostName: I7
TaskName: \HG612 Stats Program
Next Run Time: 24/08/2013 15:29:00
Status: Ready
Logon Mode: Interactive only
Last Run Time: 24/08/2013 15:28:00
Last Result: 0
Author: kitz
Task To Run: "C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts\HG612_Run.exe"
Start In: N/A
Comment: N/A
Scheduled Task State: Enabled
Idle Time: Disabled
Power Management: Stop On Battery Mode, No Start On Batteries
Run As User: I7\kitz
Delete Task If Not Rescheduled: Enabled
Stop Task If Runs X Hours and X Mins: 72:00:00
Schedule: Scheduling data is not available in this format.
Schedule Type: One Time Only, Minute
Start Time: 14:41:00
Start Date: 24/08/2013
End Date: N/A
Days: N/A
Months: N/A
Repeat: Every: 0 Hour(s), 1 Minute(s)
Repeat: Until: Time: None
Repeat: Until: Duration: Disabled
Repeat: Stop If Still Running: Disabled
-
I THINK that I may have found the cause of these issue.
For testing purposes, I had 2 separate HG612_stats.exe tasks running overnight via Task Scheduler, (staggered by 30 seconds via Task Scheduler, NOT by adding a delay option via HG612 Settings editor).
There were no issues until my AVG virus kicked in.
As expected, despite AVG being set to run at lowest resource priority, the whole PC slowed down causing another HG612_stats.exe task to start before the first one had completed.
Both instances were exited as planned & the data was not harvested for that minute.
This didn't leave any 'stuck' instances of HG612_stats.exe in Task Manager & as it only happens a couple of times during the virus scan, it isn't of great importance that a data sample is missed here & there.
When only 1 Scheduled task is running (i.e. normal operation for most users), the slowing down issue is even less of a problem.
This morning, to test things out a bit further, I forced both tasks to run at the same time i.e. bang on the minute.
By the time each instance of HG612_stats.exe had checked to see if another instance was already running, there were indeed 2 instances so both instances exited as planned, with no data harvested.
There were no 'stuck' instances of HG612_stats.exe in Task Manager.
This continued until I added a 30 second stagger again & normal service was resumed, with both instances harvesting & storing the data again.
Just for fun, I then added a 3rd Scheduled task to run HG612_stats.exe, staggered by 45 seconds past the minute.
As HG612_stats.exe normally completes in 2 or 3 seconds (when the PC isn't busy), these all worked perfectly with no 'stuck' instances.
Returning to just 2 tasks, I then fired up Eric's DSLStats & started sampling at 10 seconds past the minute.
Neither of my 2 HG612_stats.exe tasks were affected as they didn't attempt to run during DSLStat's sampling period.
DSLStats also worked perfectly.
I then stopped DSLStats from sampling, leaving the program running.
Again, there were no issues.
As a final test, I started DSLStats's sampling again, but this time ensuring sampling would start 5 seconds before one of my tasks was due to start.
When it was time for my task to run, DSLStats was still displaying the Sampling message & I can see that my task reached this point & then locked up:-
25/08/2013 8:04:31.50 - ONGOING-ISRUNNING-080430-509.TXT - **** reply(config.Shell) O.K. Status = 1.
i.e. it couldn't continue to login to the modem & ended up 'stuck' in Task Manager.
That is at exactly the same point it locked up during your testing yesterday afternoon:-
24/08/2013 14:56:01.38 - ONGOING-ISRUNNING-145600-445.TXT - **** reply(config.Shell) O.K. Status = 1.
As this left an instance of HG612_stats.exe in Task Manager, any further attempts for my tasks to run were exited.
Leaving DSLStats running & sampling switched ON, I ended the stuck process just after DSLStats had completed sampling & my first task ran correctly, harvesting & storing the data accordingly.
However, the 2nd of my tasks started during DSLStat's sampling period & the lock up occurred again.
As Eric & I have not yet discovered a method of checking if a Telnet session is already open without actually logging in to the modem, we'll have to find a workaround for when both programs are running together.
I have an idea in mind that I'll run past Eric during today.
However, if you weren't actually running DSLStats at the time HG612_stats reached this point yesterday, I'll have to discard my theory & start again:-
24/08/2013 14:56:01.38 - ONGOING-ISRUNNING-145600-445.TXT - **** reply(config.Shell) O.K. Status = 1.
Finally, as mentioned previously, there is an issue with some versions of Windows (apparently not an issue with XP), where Scheduled tasks can sometimes start more than once in the same minute.
From monitoring this, it seems that the second (spurious) instance can start as quickly as 0.15 seconds after the 'correct' instance.
HG612_stats.exe handles this by exiting one of the instances & thus allowing the other to continue (apart from when both instances start more or less together, in which case both instances exit).
This duplication of tasks is only seen occasionally, often a few hours apart but at the same minute past the hour, so again, it's not much of an issue.
There is a supposed fix for this Windows Task Scheduler issue here, but I haven't tried it yet:-
http://support.microsoft.com/kb/2461249/en-us?sd=rss&spid=14019
-
Thank you BE for the further info.
>> if you weren't actually running DSLStats at the time HG612_stats reached this point yesterday (24th)
You are correct, I was.
-------
Knowing I wouldnt have much chance to spend at the PC yesterday I'd found the old v1 zip file in my Recycle bin, so put v1 back on which ran all day yesterday. Unfortunately though that got snarled at points too, but it would resume logging later.
~ This morning Ive done a complete re-install of v2. This logged ok but had some of the multiple instances.
~ Paused DSLstats. Dropped in the fix. This seems to be working & logging fine
~ Resumed DSLstats and HG612stats refused any further logging of modem stats
~ Paused DSLstats, HG612stats doesnt recommence logging.
~ Completely shut down DSLstats, HG612stats still doesnt recommence logging
It seems that whilst the fix is in place, then one bad instance will switch logging off and wont start logging again until the stuck HG612stats.exe is manually removed from Task Manager?
----
Ive also done a quick test in cmd and it would appear that the HG612 telnet allows 3 instances of the Hauwei CLI to be run at the same time, but only one instance into the Broadcom shell at any one time. I cant see anything obvious in the CLI where the number of simultaneous access for a user can be changed. :(
I also thought about the possibility of creating another user, but it would appear there are 3 pre-configured users
admin|support|user. The 'user' account is crippled and doesnt allow telnet access & I dont have right password for support so there goes that idea I guess. :(
-----
I can confirm that I am also seeing the issue with Scheduled tasks starting more than one instance. Ive had a look through the modem_stats.log and it does seem to happen rather often and can sometimes happen several times in one hour. I cant find any distinct pattern to it. It definitely doesn't appear to be at the same minute past the hour.
----
One thing that does puzzle me is that for several weeks the 2 ran happily side-by-side without conflict & it was only last week that I started noticing the multiple instances and all the ONGOING-ISRUNNING files in the scripts folder. ???
>>> I have an idea in mind that I'll run past Eric during today.
Since HG612stats is run via Windows scheduler it will always commence dead-on the minute.
Could perhaps force some compatibility mode so that DSLstats always commences at 'x' seconds after the minute. I havent checked to see if DSLstats will always run at 'x' seconds.. or if it runs 'x' seconds after the last sample has fully finished. If its the later... then eventually the 2 will coincide.
----
Edited to add.
Ive set DSLstats to only run every 60 seconds. I then paused it and made sure it commenced at 10 seconds past the minute. Its now been running for about 25 mins without conflict. However I notice sampling starts at a couple of seconds after the minute and finishes at 10 seconds.
I'll move the time on a bit to 30 seconds past, then leave them both running whilst I go out... and see what has happened when I get back ;D
-
Thank you BE for the further info.
>> if you weren't actually running DSLStats at the time HG612_stats reached this point yesterday (24th)
You are correct, I was.
-------
Knowing I wouldnt have much chance to spend at the PC yesterday I'd found the old v1 zip file in my Recycle bin, so put v1 back on which ran all day yesterday. Unfortunately though that got snarled at points too, but it would resume logging later.
~ This morning Ive done a complete re-install of v2. This logged ok but had some of the multiple instances.
~ Paused DSLstats. Dropped in the fix. This seems to be working & logging fine
~ Resumed DSLstats and HG612stats refused any further logging of modem stats
~ Paused DSLstats, HG612stats doesnt recommence logging.
~ Completely shut down DSLstats, HG612stats still doesnt recommence logging
It seems that whilst the fix is in place, then one bad instance will switch logging off and wont start logging again until the stuck HG612stats.exe is manually removed from Task Manager?
----
I THINK i've found a partial fix for that (yet another test version is attached if you are keen enough to try it).
As your task seems to be running in Interactive only mode, it may beep every minute with this test version.
Switching the task to Interactive/Background mode gets rid of the beep (Task Scheduler - General tab / Run whether user is logged on or not).
Ive also done a quick test in cmd and it would appear that the HG612 telnet allows 3 instances of the Hauwei CLI to be run at the same time, but only one instance into the Broadcom shell at any one time. I cant see anything obvious in the CLI where the number of simultaneous access for a user can be changed. :(
I believe the attached test version deals with that.
I have temporarily removed HG622 compatibility while it is under test.
I also thought about the possibility of creating another user, but it would appear there are 3 pre-configured users
admin|support|user. The 'user' account is crippled and doesnt allow telnet access & I dont have right password for support so there goes that idea I guess. :(
There's no need to consider doing that (if this test version works O.K. at your end).
I've been running it in tandem with DSLStats for a few hours now without any issues, even when I force the programs to clash.
I can confirm that I am also seeing the issue with Scheduled tasks starting more than one instance. Ive had a look through the modem_stats.log and it does seem to be a regular even and can sometimes happen several times in one hour.. I cant find any distinct pattern to it. It definitely doesnt appear to be at the same minute past the hour.
One thing that does puzzle me is that for several weeks the 2 ran happily side-by-side without conflict & it was only last week that I started noticing the multiple instances and all the ONGOING-ISRUNNING files in the scripts folder. ???
I never used to see that at all.
I wonder if at the latest auto update, Microsoft have reintroduced a bug that a previous update had resolved?
>>> I have an idea in mind that I'll run past Eric during today.
Since HG612stats is run via Windows scheduler it will always commence dead-on the minute.
Theoretically, yes. In practice, things can be delayed on occasions (when the PC is incredibly busy doing something else - e.g. virus scanning).
Could perhaps force some compatability mode so that DSLstats always commences at 'x' seconds after the minute. I havent checked to see if DSLstats will always run at 'x' seconds.. or if it runs 'x' seconds after the last sample has fully finished. If its the later... then eventually the 2 will co-incide.
I don't think that's necessary now.
In any case, on my PC, while I've been testing things out, I have noticed that DSLStats's timing gains approximately 1 second every minute.
e.g. I have 2 tasks running, staggered by 30 seconds.
For testing purposes I started DSLStats sampling at around 30 seconds past the minute to force it to clash with one of my tasks.
Within 30 minutes or so, it had gradually started sampling earlier & earlier until it eventually clashed with my task that runs exactly on the minute.
I haven't been watching DSLStats closely, but it is now sampling at around 45 seconds past the minute.
When I mention this is a partial fix, it means that my every minute start & close programs can run alongside DSLStats, but if Eric included a slight pause, whenever my programs are detected, it could improve matters even further.
My ongoing stats harvest takes around 2 to 3 seconds (depending on PC processor speed) & the scheduled current/snapshot stats take around 7 seconds - a bit longer if auto-graphing.
A 10 second delay (maximum) should be sufficient in DSLStats if either of my programs are running, rather than risk losing a DSLStats sample altogether.
If you do try this latest test version, you'll see what happens when the programs clash by looking at the "ERROR.LOG_file_ERROR.TXT" files in the Scripts folder & the Ongoing_Stats folder.
One is specific to DSLStats handling & the other is a general record of what happens whenever 2 tasks try to start at the same time.
If this test version proves reliable, I'll get rid of the temporarily created ISRUNNING files & the additional debugging logs.
The best of both worlds would be to have my programs & DSLStats working in perfect harmony & believe we are now very, very close to achieving that.
HTH :)
-
Ive also done a quick test in cmd and it would appear that the HG612 telnet allows 3 instances of the Hauwei CLI to be run at the same time, but only one instance into the Broadcom shell at any one time. I cant see anything obvious in the CLI where the number of simultaneous access for a user can be changed.
Yesterday I did a little experiment with the HG622 that I'm currently using, and I found that it happily supports at least three simultaneous admin logins to the Broadcom CLI. This is to be expected, because it's Linux, and Linux normally has no problems with multiple logins. I'm a bit surprised to hear that the HG612 is different, but maybe it's limited by its internal memory or something of that nature.
-
This seems to be the issue:-
If my program attempts to run at around 5 seconds into DSLStat's sampling stage, 'admin' for Username & 'admin' for Password are still O.K., but 'sh' for access to Busybox doesn't work, instead we are simply returned to the ATP> prompt.
My workaround is to keep trying to reply with 'sh' until it either works or a maximum of 50 attempts are tried & failed.
I have only seen a maximum of 31 attempts so far before 'sh' is accepted - presumably when DSLStats logs out of the modem again:-
26/08/2013 10:58:30.18 - In HG612_stats.exe - At the start of the main() function,
26/08/2013 10:58:30.32 - There are 1 instances of HG612_stats.exe running. Status = 0,
26/08/2013 10:58:31.97 - 01 trying reply(sh) again.
26/08/2013 10:58:32.19 - 02 trying reply(sh) again.
26/08/2013 10:58:32.41 - 03 trying reply(sh) again.
26/08/2013 10:58:32.64 - 04 trying reply(sh) again.
26/08/2013 10:58:32.88 - 05 trying reply(sh) again.
26/08/2013 10:58:33.13 - 06 trying reply(sh) again.
26/08/2013 10:58:33.38 - 07 trying reply(sh) again.
26/08/2013 10:58:33.63 - 08 trying reply(sh) again.
26/08/2013 10:58:33.86 - 09 trying reply(sh) again.
26/08/2013 10:58:34.11 - 10 trying reply(sh) again.
26/08/2013 10:58:34.36 - 11 trying reply(sh) again.
26/08/2013 10:58:34.62 - 12 trying reply(sh) again.
26/08/2013 10:58:34.87 - 13 trying reply(sh) again.
26/08/2013 10:58:35.12 - 14 trying reply(sh) again.
26/08/2013 10:58:35.37 - 15 trying reply(sh) again.
26/08/2013 10:58:35.62 - 16 trying reply(sh) again.
26/08/2013 10:58:35.86 - 17 trying reply(sh) again.
26/08/2013 10:58:36.11 - 18 trying reply(sh) again.
26/08/2013 10:58:36.36 - 19 trying reply(sh) again.
26/08/2013 10:58:36.59 - 20 trying reply(sh) again.
26/08/2013 10:58:36.84 - 21 trying reply(sh) again.
26/08/2013 10:58:37.07 - 22 trying reply(sh) again.
26/08/2013 10:58:37.32 - 23 trying reply(sh) again.
26/08/2013 10:58:37.56 - 24 trying reply(sh) again.
26/08/2013 10:58:37.82 - 25 trying reply(sh) again.
26/08/2013 10:58:38.06 - 26 trying reply(sh) again.
26/08/2013 10:58:38.32 - 27 trying reply(sh) again.
26/08/2013 10:58:38.57 - 28 trying reply(sh) again.
26/08/2013 10:58:38.82 - 29 trying reply(sh) again.
26/08/2013 10:58:39.09 - 30 trying reply(sh) again.
26/08/2013 10:58:39.35 - 31 trying reply(sh) again.
26/08/2013 10:58:40.46 - Normal End of In HG612_stats.exe
Fewer & fewer attempts are needed as time passes, until DSLStats eventually starts sampling at a time when Windows Task Scheduler isn't trying to start my task.
26/08/2013 11:03:30.18 - In HG612_stats.exe - At the start of the main() function,
26/08/2013 11:03:30.29 - There are 1 instances of HG612_stats.exe running. Status = 0,
26/08/2013 11:03:31.87 - 01 trying reply(sh) again.
26/08/2013 11:03:32.12 - 02 trying reply(sh) again.
26/08/2013 11:03:32.37 - 03 trying reply(sh) again.
26/08/2013 11:03:32.62 - 04 trying reply(sh) again.
26/08/2013 11:03:32.88 - 05 trying reply(sh) again.
26/08/2013 11:03:33.99 - Normal End of In HG612_stats.exe
26/08/2013 11:04:30.16 - In HG612_stats.exe - At the start of the main() function,
26/08/2013 11:04:30.27 - There are 1 instances of HG612_stats.exe running. Status = 0,
26/08/2013 11:04:31.82 - 01 trying reply(sh) again.
26/08/2013 11:04:32.69 - Normal End of In HG612_stats.exe
26/08/2013 11:05:30.15 - In HG612_stats.exe - At the start of the main() function,
26/08/2013 11:05:30.32 - There are 1 instances of HG612_stats.exe running. Status = 0,
26/08/2013 11:05:33.19 - Normal End of In HG612_stats.exe
-
Ive just got back in and DSLstats now commences its sample at 2 seconds past the minute, so yes like you Im seeing it gain in time, but I wasnt here to see how much...
......woah and as I type its just co-incided and clashed!!!!!
Current_stats.exe also just got stuck too @ its 14:00 run.
26/08/2013 13:59
26/08/2013 14:00
26/08/2013 14:04 <---- manually removed process from Task Manager.
Both programs normally harvest results very quickly. HG612stats only takes 2 seconds. DSLstats about 8 seconds.
>>> I wonder if at the latest auto update, Microsoft have reintroduced a bug that a previous update had resolved?
Possible, because I'm pretty sure I had no problem until last week.
As your task seems to be running in Interactive only mode, it may beep every minute with this test version.
Switching the task to Interactive/Background mode gets rid of the beep (Task Scheduler - General tab / Run whether user is logged on or not).
Thank you - running it now.. its bleeping every min.
Cant switch it to run whether user is logged in or not as I get an error
"User account restriction error. The possible reasons are that blank passwords are not allowed."
I could possibly get around this by setting up another user specifically for running Task Scheduler - which is what I used to do when running MRTG to ignore blank password issue... but for now I'll leave it bleeping.
but 'sh' for access to Busybox doesn't work, instead we are simply returned to the ATP> prompt.
Yes thats what I noticed this morning, when I said it would only accept one instance into the shell.
-
......woah and as I type its just co-incided and clashed!!!!!
Current_stats.exe also just got stuck too @ its 14:00 run.
26/08/2013 13:59
26/08/2013 14:00
26/08/2013 14:04 <---- manually removed process from Task Manager.
Ah, I forgot about adding this workaround to HG612_current_stats.exe. I'll do that now.
Both programs normally harvest results very quickly. HG612stats only takes 2 seconds. DSLstats about 8 seconds.
DSLStats takes around 12-15 seconds on my PC. Your processor is faster than mine though.
>>> I wonder if at the latest auto update, Microsoft have reintroduced a bug that a previous update had resolved?
Possible, because I'm pretty sure I had no problem until last week.
I don't really have any explanation for that as I have also only recently started seeing the duplicated task issue.
As your task seems to be running in Interactive only mode, it may beep every minute with this test version.
Switching the task to Interactive/Background mode gets rid of the beep (Task Scheduler - General tab / Run whether user is logged on or not).
Thank you - running it now.. its bleeping every min.
Cant switch it to run whether user is logged in or not as I get an error
"User account restriction error. The possible reasons are that blank passwords are not allowed."
I could possibly get around this by setting up another user specifically for running Task Scheduler - which is what I used to do when running MRTG to ignore blank password issue... but for now I'll leave it bleeping.
If this test vesion seems to resolve the issue(s), I'll get rid of the bleeping in the next update.
but 'sh' for access to Busybox doesn't work, instead we are simply returned to the ATP> prompt.
Yes thats what I noticed this morning, when I said it would only accept one instance into the shell.
Hopefully, that aspect has now been dealt with.
Fingers crossed.......................... :fingers:
-
A new version of HG612_current_stats.exe is attached, also disabling HG622 compatibility for now, along with including the DSLStats partial workaround.
It doesn't include any of the extra event/error logging, but it does work O.K.
-
Ok will download it. Thank you vm :)
btw previous fix has been running for the best part of an hour and touch wood seems to work fine.
The error.log_file_ERROR.txt reports quite a few of the trying (sh) again. The maximum it got up to was 34, but as expected it did decrease on each subsequent run.
-
I think Paul has put his finger on the critical issue. It's not just the simultaneous logins which are the real problem, but their timing. I don't think I can make the timing of DSLstats' sampling any more accurate than it is unless I somehow synchronise to the Windows scheduler, and I have no idea how to do that. In any event, it's probably not really practical to have two independent programs trying to sync together.
The workaround of repeatedly trying the sh command until it gets a response may deal with the problem, but it would be much better if we can find a way of avoiding it before it happens. In general, DSLstats should handle situations where it can't log in for any reason - it should report the event in the event log and wait until the next sample is due. Perhaps what I should also do in this circumstance is delay the sampling by a few seconds so it doesn't get a succession of failed logins.
Although the total 'Sampling' period appears to be between 8 and 15 seconds, at least some of that time is in processing the data after logging out. For the purposes of what's being discussed here, only the telnet login - logout period matters. I should be able to raise some sort of flag during this period, which HG612-modem-stats could read and use to avoid a clash. The simplest flag would be a temporary file saved somewhere; we would need to agree on a suitable location for saving it, and also a protocol for dealing with the possibility that the temporary file doesn't get deleted at the end of sampling as a result of some unexpected event.
-
I think Paul has put his finger on the critical issue. It's not just the simultaneous logins which are the real problem, but their timing. I don't think I can make the timing of DSLstats' sampling any more accurate than it is unless I somehow synchronise to the Windows scheduler, and I have no idea how to do that. In any event, it's probably not really practical to have two independent programs trying to sync together.
Maybe using Windows system time would work as that's what drives the Windows Task Schedules (and any other user defined schedules within HG612 Modem Stats).
So, as my programs run on the minute by default, perhaps DSLStats could always start sampling at say, 15 or 30 seconds past the minute at 1 minute intervals?
That should also allow for any additional time when HG612_current_stats occasionally harvests data on its few hourly schedule (the most user definable frequency is one hour).
The logging element of my programs CAN be delayed via user settings, to avoid clashes with anything else, but that depends on fixed timings for anything they wish to avoid.
The workaround of repeatedly trying the sh command until it gets a response may deal with the problem, but it would be much better if we can find a way of avoiding it before it happens. In general, DSLstats should handle situations where it can't log in for any reason - it should report the event in the event log and wait until the next sample is due. Perhaps what I should also do in this circumstance is delay the sampling by a few seconds so it doesn't get a succession of failed logins.
It does seem to do that:-
26 Aug 2013 12:08:03 Second stage login failed
I think that happened a couple of seconds into DSLStat's sampling period.
My programs, especially the current stats can be run on demand at any time a user chooses.
Retaining a workaround for those occasions is probably wise.
Although the total 'Sampling' period appears to be between 8 and 15 seconds, at least some of that time is in processing the data after logging out. For the purposes of what's being discussed here, only the telnet login - logout period matters. I should be able to raise some sort of flag during this period, which HG612-modem-stats could read and use to avoid a clash. The simplest flag would be a temporary file saved somewhere; we would need to agree on a suitable location for saving it, and also a protocol for dealing with the possibility that the temporary file doesn't get deleted at the end of sampling as a result of some unexpected event.
TBH, adding a slight delay to DSLStats if either of my programs are already running seems a simpler/tidier solution to me as users may have installed DSLStats in any folder of their choosing.
If, for whatever reason my programs still can't log into the modem, they now exit gracefully, freeing memory & closing open sockets etc.
Worst case scenario seems to be that 1 sample is missed, similar to how DSLStats handles a failed login.
-
users may have installed DSLStats in any folder of their choosing.
Sure, but that doesn't inhibit DSLstats from writing a temporary file to any specified location.
However, if you're happy with my adding a delay to DSLstats sampling if it detects a clash, then that's easy to implement, and I'll add it to the next version. There are a couple of minor tweaks and bugfixes which are already in place, so I'll add this one and release it as a minor version upgrade.
I'll investigate using the Windows timer for the Windows version of DSLstats, but as I know nearly nothing about Windows programming that will take a little longer.
-
users may have installed DSLStats in any folder of their choosing.
Sure, but that doesn't inhibit DSLstats from writing a temporary file to any specified location.
That option may indeed turn out to be necessary, but in attempting to automate as much as possible, I'd rather treat it as a maybe rather than essential for the timebeing
However, if you're happy with my adding a delay to DSLstats sampling if it detects a clash, then that's easy to implement, and I'll add it to the next version. There are a couple of minor tweaks and bugfixes which are already in place, so I'll add this one and release it as a minor version upgrade.
Shall we do that for now & see how it goes?
For curiosity, would you be aiming to detect my programs' processes or modem logging in process?
The 2 main programs that access the modem are HG612_stats.exe & HG612_current_stats.exe.
I have also just remembered that whenever a resync is detected, SET_HG612_DATE_AND_TIME.exe also runs as soon as DSL is up, in order to reset the modem's internal clock.
That one is only necessary for VDSL2 connections when the modem is in its default bridge mode.
It's not really needed for ADSL connections when in router/modem mode as it synchronistes with a choice of time servers.
FWIW, there have been a few calshes since I started DSLStats sampling again at 09:20 this morning & only a couple of them resulted in Second stage login failed.
Maybe a delay in DSLStats would adequately address that minor issue.
-
I'll investigate using the Windows timer for the Windows version of DSLstats, but as I know nearly nothing about Windows programming that will take a little longer.
You probably know just as much as (or more than) I do then :)
With assistance from others, I did work out how to use the PC's system time.
There are a number of options for that - rough & ready or accurate to 1/1000 of a second.
Let me know if you would like me to pass on any pointers that I have stumbled onto along the way.
-
For curiosity, would you be aiming to detect my programs' processes or modem logging in process?
At present I'm keeping it simple and just detecting any circumstance in which DSLstats fails to log in. I'll think about detecting specific processes a bit later. That's easy on Linux, but something else I don't know how to do on Windows.
FWIW, there have been a few clashes since I started DSLStats sampling again at 09:20 this morning & only a couple of them resulted in Second stage login failed.
Second stage login failure isn't necessarily a clash. I see it very occasionally on my system when DSLstats is the only monitoring program running. I've tended to assume that it's a glitch of come sort, a critical timing issue perhaps, or just a non-response from the router.
Let me know if you would like me to pass on any pointers that I have stumbled onto along the way.
Thanks for the offer, but I think it's actually very simple in Lazarus. There's a function "Now" which returns the current date and time. I haven't checked how it's actually implemented in the underlying code, but it seems fairly certain that it actually returns the Windows system time when running on Windows. I can check that quite easily with a little test program.
-
Report from me whilst I was out. Nothing intensive was running on the PC - only mail, DSLstats & HG612stats.
DSLstats is set to report every 60 seconds (not its default 30secs)
HG612 stats has been logging fine and I cant see any missed events.
Its been through 2 complete cycles of retry attmpts with the longest being 40 retries so far.
14:10 - 14:33 & 17:24 - 17:52
retry attempts vary, but very roughly about 20-30ms on average? I'll attach a log sample so you can see
26/08/2013 17:24:00.37 - In HG612_stats.exe - At the start of the main() function,
26/08/2013 17:24:00.43 - There are 1 instances of HG612_stats.exe running. Status = 0,
26/08/2013 17:24:01.65 - 01 trying reply(sh) again.
26/08/2013 17:24:01.88 - 02 trying reply(sh) again.
26/08/2013 17:24:02.10 - 03 trying reply(sh) again.
26/08/2013 17:24:02.33 - 04 trying reply(sh) again.
26/08/2013 17:24:02.56 - 05 trying reply(sh) again.
26/08/2013 17:24:02.79 - 06 trying reply(sh) again.
26/08/2013 17:24:03.01 - 07 trying reply(sh) again.
26/08/2013 17:24:03.24 - 08 trying reply(sh) again.
26/08/2013 17:24:03.46 - 09 trying reply(sh) again.
26/08/2013 17:24:03.69 - 10 trying reply(sh) again.
26/08/2013 17:24:03.92 - 11 trying reply(sh) again.
26/08/2013 17:24:04.15 - 12 trying reply(sh) again.
26/08/2013 17:24:04.38 - 13 trying reply(sh) again.
26/08/2013 17:24:04.61 - 14 trying reply(sh) again.
26/08/2013 17:24:04.83 - 15 trying reply(sh) again.
26/08/2013 17:24:05.06 - 16 trying reply(sh) again.
26/08/2013 17:24:05.28 - 17 trying reply(sh) again.
26/08/2013 17:24:05.50 - 18 trying reply(sh) again.
26/08/2013 17:24:05.72 - 19 trying reply(sh) again.
26/08/2013 17:24:05.94 - 20 trying reply(sh) again.
26/08/2013 17:24:06.17 - 21 trying reply(sh) again.
26/08/2013 17:24:06.39 - 22 trying reply(sh) again.
26/08/2013 17:24:06.62 - 23 trying reply(sh) again.
26/08/2013 17:24:06.85 - 24 trying reply(sh) again.
26/08/2013 17:24:07.08 - 25 trying reply(sh) again.
26/08/2013 17:24:07.31 - 26 trying reply(sh) again.
26/08/2013 17:24:07.52 - 27 trying reply(sh) again.
26/08/2013 17:24:07.73 - 28 trying reply(sh) again.
26/08/2013 17:24:07.95 - 29 trying reply(sh) again.
26/08/2013 17:24:08.18 - 30 trying reply(sh) again.
26/08/2013 17:24:08.40 - 31 trying reply(sh) again.
26/08/2013 17:24:08.63 - 32 trying reply(sh) again.
26/08/2013 17:24:08.85 - 33 trying reply(sh) again.
26/08/2013 17:24:09.07 - 34 trying reply(sh) again.
26/08/2013 17:24:09.29 - 35 trying reply(sh) again.
26/08/2013 17:24:09.50 - 36 trying reply(sh) again.
26/08/2013 17:24:09.73 - 37 trying reply(sh) again.
26/08/2013 17:24:09.96 - 38 trying reply(sh) again.
26/08/2013 17:24:10.19 - 39 trying reply(sh) again.
26/08/2013 17:24:10.41 - 40 trying reply(sh) again.
26/08/2013 17:24:11.40 - Normal End of In HG612_stats.exe
DSLstats appears to also run mostly fine, and although Ive seen a few login failures its not that bad
26 Aug 2013 12:12:30 Recording paused
26 Aug 2013 12:13:11 Recording resumed
26 Aug 2013 12:15:01 Recording paused
26 Aug 2013 12:15:30 Recording resumed
26 Aug 2013 13:31:21 Auto snapshots taken
26 Aug 2013 14:04:02 Second stage login failed
26 Aug 2013 14:05:02 Second stage login failed
26 Aug 2013 15:31:45 Auto snapshots taken
26 Aug 2013 17:21:03 Second stage login failed
26 Aug 2013 17:22:03 Second stage login failed
26 Aug 2013 17:23:02 Second stage login failed
26 Aug 2013 17:32:08 Auto snapshots taken
I'll now try setting DSLstats back to its default 30 seconds to see how that goes.
With assistance from others, I did work out how to use the PC's system time.
Its more than 10yrs since I did anything pascal/dephi, but (Now) uses system time which should be more than accurate enough to work cross platform?
Ive never used lazurus, but if it has a TTimer function like Delphi could you adapt something like this (http://www.informit.com/articles/article.aspx?p=26651&seqNum=3). Ignore me if its not helpful, because I know zilch about lazurus, I was just trying to avoid you having to use a windows specific scheduler... and apologies if its totally on the wrong track.
--
Sorry eric.. just seen that you already mentioned (now) in your post. :-[
-
Report from me whilst I was out. Nothing intensive was running on the PC - only mail, DSLstats & HG612stats.
DSLstats is set to report every 60 seconds (not its default 30secs)
HG612 stats has been logging fine and I cant see any missed events.
Its been through 2 complete cycles of retry attmpts with the longest being 40 retries so far.
14:10 - 14:33 & 17:24 - 17:52
retry attempts vary, but very roughly about 20-30ms on average? I'll attach a log sample so you can see
That's good news.
Some of that time is no doubt spent adding the details to the log file, so when I remove that, I might have to increase the number of tries or add a slight pause between each try.
-
Ive never used lazurus, but if it has a TTimer function like Delphi could you adapt something like this. Ignore me if its not helpful, because I know zilch about lazurus, I was just trying to avoid you having to use a windows specific scheduler... and apologies if its totally on the wrong track.
Yes, I use TTimer, but it's hopelessly inaccurate for any critical timing requirement (that applies to Delphi too) so I use a combination of TTimer and a highly accurate tick count timer for the sample timing in DSLstats.
I've now added two extra checks to DSLstats to try to avoid conflicts:
1. If a possible conflict is detected during sampling, the next sample is delayed by ten seconds.
2. An extra login option "Synchronise with HG612-Modem-Stats" which ensures that recording starts between 15 seconds and 45 seconds after the minute.
I've made the second item a user option because it can lead to a delay of up to 30 seconds before recording starts, which could be a nuisance for users who don't need it (and it applies to the Windows version only, of course).
-
I might have to increase the number of tries or add a slight pause between each try.
I must admit I did wonder about a possible pause if ">AP" rather than the expected "#" was returned... Im assuming it previously exited at this point which is why I wasnt seeing any data was logged.
A pause would certainly be a more elegant solution than firing off 50 attempts :) I suppose a fast & multi threading/core processor which isnt busy could soon go through those before DSLstats has finished. Although saying that I would imagine it wouldnt happen too often to be such a big deal.
I've now added two extra checks to DSLstats to try to avoid conflicts:
Excellent :thumbs:
-
PS BE... Ive just noticed that current_stats doesnt appear to have run.... but unfortunately I have to run now... so I'll look properly later :)
argggh... I was thinking it should have run at 8pm... but Ive not changed the defaults... and its not due to 10pm :wall:
/me gone
-
Not sure I'm following all of this - though it is interesting
What if DSLstats never logs out. At the moment it is logging in/out at each sample - I recall that DMT tool and Routerstats keep the telnet connection open all the time from the moment it starts to when it is closed down. (I've no idea how they handle times when the PC is sleeping)
-
In order to stay logged in indefinitely, RS/DMT have to disable the normal telnet timeout. If the program is terminated abruptly for any reason, that would leave an orphan login permanently resident in the router. And in addition, it seems that the HG612 will only accept a single full login to the shell, so a permanently logged in program would lock out any other monitoring programs which use telnet.
-
Ah - I see, Thankyou
-
Eric,
I can confirm that DSLstats sampling period is also ~13-15secs on my old, slow, server, but I appreciate, as you said, that most of that time it's not logged into the modem.
I am no programmer, and I don't know how you've a) programmed this timer tick or b) how that's mapped down onto Windows, but I do wonder this:
AFAIK relatively speaking the speed of Kitz's machine is > Bald_Eagle's >> my aging server! Kitz runs into this problem very quickly; BE more slowly; and it only happens to me very occasionally.
Could it possibly be something to do with the way this timer tick is mapped down onto windows? Such that it differs from real-time dependent on the processor speed?
I am not in a position to say whether it is or not, just to ask the question, as it does seem, at least, to fit some of the evidence. :(
-
And in addition, it seems that the HG612 will only accept a single full login to the shell, so a permanently logged in program would lock out any other monitoring programs which use telnet.
I've done some tests on this Eric, in test conditions - i.e. when neither DSLstats nor HG612modemstats were running.
on the HG612:
>= 5 concurrent telnet logins are possible and successful
however, of those, only 3 can be in the busybox shell (@ the # prompt) at any time
a 4th or subsequent attempt exits back to the ATP shell (@ the ATP> prompt)
if one of these 3 busybox instances is exited (manually, or by telnet session idle timeout) it will allow another to then be successful, but the limit (probably due to memory, as you have already suggested) remains 3
The HG612 HG622 controls it slightly differently:
no more than 3 concurrent telnet logins are successful.
a 4th or subsequent attempt is not allowed.
HTH
[Edit] Correction
-
Eric,
I can confirm that DSLstats sampling period is also ~13-15secs on my old, slow, server, but I appreciate, as you said, that most of that time it's not logged into the modem.
I am no programmer, and I don't know how you've a) programmed this timer tick or b) how that's mapped down onto Windows, but I do wonder this:
AFAIK relatively speaking the speed of Kitz's machine is > Bald_Eagle's >> my aging server! Kitz runs into this problem very quickly; BE more slowly; and it only happens to me very occasionally.
Could it possibly be something to do with the way this timer tick is mapped down onto windows? Such that it differs from real-time dependent on the processor speed?
I am not in a position to say whether it is or not, just to ask the question, as it does seem, at least, to fit some of the evidence. :(
The high precision timer I'm using is EpikTimer (http://wiki.freepascal.org/EpikTimer) . It's effectively an accurate stopwatch, so it doesn't have the capability to trigger events on its own. That's why I use it in conjunction with another much less accurate timer (alarm clock type) to trigger the start of a new sampling process. I set the 'alarm clock' to 10 milliseconds, and each time it fires it reads the 'stopwatch' to see if the next sample is due.
There may be a better way to do this, but there's no certain way to achieve a really accurate 'alarm clock' on all systems. There's no guarantee that every system will have a properly functioning NTP (or equivalent) implementation to maintain the accuracy of the system timer.
So I think that the solutions discussed above are probably the best way to keep the sampling times of the two programs apart to avoid conflicts.
-
And in addition, it seems that the HG612 will only accept a single full login to the shell, so a permanently logged in program would lock out any other monitoring programs which use telnet.
I've done some tests on this Eric, in test conditions - i.e. when neither DSLstats nor HG612modemstats were running.
on the HG612:
>= 5 concurrent telnet logins are possible and successful
however, of those, only 3 can be in the busybox shell (@ the # prompt) at any time
a 4th or subsequent attempt exits back to the ATP shell (@ the ATP> prompt)
if one of these 3 busybox instances is exited (manually, or by telnet session idle timeout) it will allow another to then be successful, but the limit (probably due to memory, as you have already suggested) remains 3
The HG612 controls it slightly differently:
no more than 3 concurrent telnet logins are successful.
a 4th or subsequent attempt is not allowed.
HTH
Thanks for doing those tests, Colin. It agrees with my findings on the HG622. So there is a little bit of leeway for up to three simultaneous BusyBox logins. Probably the conflicts, when they occur, are related to the times when the two programs are actually going through the login process at the same time - if one program is fully logged in when the other program starts to log in, that shouldn't be a conflict situation.
-
I've done some tests on this Eric, in test conditions - i.e. when neither DSLstats nor HG612modemstats were running.
on the HG612:
>= 5 concurrent telnet logins are possible and successful
Now Im really confused. I have DSLstats paused & and Ive switched off logging for the HG612stats.
Yet I can still only open 3 telnet logins, as soon as I open the 4th I get "Kickout by others, the socket is closed" (see screen cap 1)
I can only access the sh once, further attempts give me the ATP> prompt (see screen cap 2)
So WTH is using up my other sessions? ???
-
There are various Linux commands which will tell you who is logged on (e.g. who, users, finger) but none of them appear to be implemented here.
-
Now Im really confused. I have DSLstats paused & and Ive switched off logging for the HG612stats.
Yet I can still only open 3 telnet logins, as soon as I open the 4th I get "Kickout by others, the socket is closed" (see screen cap 1)
I can only access the sh once, further attempts give me the ATP> prompt (see screen cap 2)
So WTH is using up my other sessions? ???
Obviously, this made me repeat my tests (although I did them several times yesterday). Like you, the results are slightly different today (see the attached image).
so, HG612
on the 5th telnet session today, one of the others also got 'kicked out' (This one had a busybox shell!)
and, only 2 busy box shells were allowed today.
So my guess is either there is another connected somewhere and not timed out (perhaps left by something?), or something has reduced the available memory in the modem. In your case Kitz, it looks like there are two like that???
I need to resync the modem at some point, so it will be possible to repeat the tests again after that .... or these 'phantoms' may timeout .... or not .... ???
-
So my guess is either there is another connected somewhere and not timed out (perhaps left by something?), or something has reduced the available memory in the modem. In your case Kitz, it looks like there are two like that???
Obviously :(
There are various Linux commands which will tell you who is logged on (e.g. who, users, finger) but none of them appear to be implemented here.
I too had a look earlier and cant seem to find a way of checking either.
RS/DMT have to disable the normal telnet timeout. If the program is terminated abruptly for any reason, that would leave an orphan login permanently resident in the router.
This concerns me ^ because I have used both RS and RSLite when I was updating some info for the main site.
I did run RS for a while to monitor my atten before eric kindly put a log in DSLstats for me, but that was weeks ago. Its been uplugged etc and done numerous resyncs, but I guess I should try another just to eliminate this. Dont want to reboot right atm though.. the weather has been hot this w/e and my line is being temperamental again.
-
Ive just done a full reboot of the modem, which seems to have freed up one session.
I can now open 4 instances to the Huawei telnet session, but only 2 instances to the Broadcom shell.
So something is still tying up one instance of the Broadcom shell. ???
-
Not quite sure what happened overnight, so Im listing all events that may be relevant.
1) I lost sync for a short while at about 12:15. HG612stats doesnt seem to have caught this in the RESYNC.LOG, presumably because my sync speed came back up at the same rate?
2) The Scheduled current_stats for 06:00 didnt complete. It created a folder Current_Stats_20130828-0600-SCHEDULED. This folder is empty apart from the Plink log
Last item in Current_Error.log is
27/08/2013 22:00:10.707 - Snapshot graphs should now have been plotted
27/08/2013 22:00:10.707 - End of HG612_current_stats.exe program, closing ERROR.LOG
CURRENT-ISRUNNING-060002-465 is empty (0 bytes)
3) In Task Manager I have lots of multiple instances of:
cmd.exe
conhost.exe
HG612_stats.exe
isRunningVB.exe
Theres also a lot of ONGOING_ISRUNNING files in the Scripts folder. All with the prefix 101154 eg ONGOING-ISRUNNING-101154-[010 to 184]
ERROR.LOG_File_ERROR.TXT
Seemed to be ok up until 06:00 am
28/08/2013 5:59:00.38 - In HG612_stats.exe - At the start of the main() function,
28/08/2013 5:59:00.44 - There are 1 instances of HG612_stats.exe running. Status = 0,
28/08/2013 5:59:02.26 - Normal End of In HG612_stats.exe
28/08/2013 6:00:00.39 - In HG612_stats.exe - At the start of the main() function,
28/08/2013 6:00:00.45 - There are 1 instances of HG612_stats.exe running. Status = 0,
28/08/2013 6:01:00.38 - In HG612_stats.exe - At the start of the main() function,
28/08/2013 6:01:00.44 - There are 2 instances of HG612_stats.exe running. Status = 0,
.../snip/...
28/08/2013 13:43:00.70 - In HG612_stats.exe - At the start of the main() function,
28/08/2013 13:43:17.03 - There are 221 instances of HG612_stats.exe running. Status = 0,
28/08/2013 13:44:00.67 - In HG612_stats.exe - At the start of the main() function,
28/08/2013 13:44:16.92 - There are 222 instances of HG612_stats.exe running. Status = 0,
The ERROR.LOG in \Ongoing_Stats is very strange - Look at the times. It was fine up until 06:00 then this started happening
*********************************************************************************************************************
28/08/2013 05:59:02.240 - Scheduled Daily_Graphing is switched ON via the ini file
28/08/2013 05:59:02.240 - Daily_Graphing_hour = 23
28/08/2013 05:59:02.240 - Daily_Graphing_minutes = 58
28/08/2013 05:59:02.240 - Current Time is Hours 05, Minutes 59
28/08/2013 05:59:02.240 - scheduled Daily_Graphing is NOT due yet
*********************************************************************************************************************
28/08/2013 05:59:02.240 - End of HG612_stats.exe program, EXIT error code = 0
28/08/2013 05:59:02.240 - End of HG612_stats.exe program, closing ERROR.LOG
28/08/2013 08:56:11.158 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling
28/08/2013 08:56:21.413 - From IsRunningVB.exe, HG612_current_stats.exe is running 1 instances.
28/08/2013 10:11:54.010 - HG612_current_stats.exe has now completed, so HG612_current_stats.exe is resuming.
28/08/2013 10:11:54.010 - Temp File ONGOING-ISRUNNING-101154-010.TXT was created
28/08/2013 10:12:04.428 - *** Now in exit_2_instances as there are 252 instances of HG612_stats.exe running. Status = 1.
28/08/2013 10:12:05.195 - *** In exit_2_instances - Closing ERROR.LOG. Status = 1.
28/08/2013 09:53:18.540 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling
28/08/2013 09:53:35.622 - From IsRunningVB.exe, HG612_current_stats.exe is running 1 instances.
28/08/2013 10:11:54.015 - HG612_current_stats.exe has now completed, so HG612_current_stats.exe is resuming.
28/08/2013 10:11:54.015 - Temp File ONGOING-ISRUNNING-101154-015.TXT was created
28/08/2013 10:12:05.020 - *** Now in exit_2_instances as there are 252 instances of HG612_stats.exe running. Status = 1.
28/08/2013 10:12:05.250 - *** In exit_2_instances - Closing ERROR.LOG. Status = 1.
.../snip/.. (look at how it now goes backward in time)
28/08/2013 06:35:01.074 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling
28/08/2013 06:35:01.151 - From IsRunningVB.exe, HG612_current_stats.exe is running 1 instances.
28/08/2013 10:11:54.129 - HG612_current_stats.exe has now completed, so HG612_current_stats.exe is resuming.
28/08/2013 10:11:54.129 - Temp File ONGOING-ISRUNNING-101154-129.TXT was created
28/08/2013 10:12:26.213 - *** Now in exit_2_instances as there are 253 instances of HG612_stats.exe running. Status = 1.
28/08/2013 10:12:26.820 - *** In exit_2_instances - Closing ERROR.LOG. Status = 1.
28/08/2013 06:48:01.108 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling
28/08/2013 06:48:01.268 - From IsRunningVB.exe, HG612_current_stats.exe is running 1 instances.
28/08/2013 10:11:54.123 - HG612_current_stats.exe has now completed, so HG612_current_stats.exe is resuming.
28/08/2013 10:11:54.123 - Temp File ONGOING-ISRUNNING-101154-123.TXT was created
28/08/2013 10:12:26.510 - *** Now in exit_2_instances as there are 253 instances of HG612_stats.exe running. Status = 1.
28/08/2013 10:12:27.119 - *** In exit_2_instances - Closing ERROR.LOG. Status = 1.
28/08/2013 08:09:06.492 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling
28/08/2013 08:09:11.726 - From IsRunningVB.exe, HG612_current_stats.exe is running 1 instances.
28/08/2013 10:11:54.133 - HG612_current_stats.exe has now completed, so HG612_current_stats.exe is resuming.
28/08/2013 10:11:54.133 - Temp File ONGOING-ISRUNNING-101154-133.TXT was created
28/08/2013 10:12:26.498 - *** Now in exit_2_instances as there are 253 instances of HG612_stats.exe running. Status = 1.
28/08/2013 10:12:27.124 - *** In exit_2_instances - Closing ERROR.LOG. Status = 1.
28/08/2013 06:21:00.657 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling
28/08/2013 06:21:00.727 - From IsRunningVB.exe, HG612_current_stats.exe is running 1 instances.
28/08/2013 10:11:54.127 - HG612_current_stats.exe has now completed, so HG612_current_stats.exe is resuming.
28/08/2013 10:11:54.127 - Temp File ONGOING-ISRUNNING-101154-127.TXT was created
28/08/2013 10:12:26.812 - *** Now in exit_2_instances as there are 253 instances of HG612_stats.exe running. Status = 1.
28/08/2013 10:12:27.292 - *** In exit_2_instances - Closing ERROR.LOG. Status = 1.
.../snip/..
8/08/2013 09:46:17.294 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling
28/08/2013 09:46:33.284 - From IsRunningVB.exe, HG612_current_stats.exe is running 1 instances.
28/08/2013 10:11:54.165 - HG612_current_stats.exe has now completed, so HG612_current_stats.exe is resuming.
28/08/2013 10:11:54.165 - Temp File ONGOING-ISRUNNING-101154-165.TXT was created
28/08/2013 10:12:28.156 - *** Now in exit_2_instances as there are 113 instances of HG612_stats.exe running. Status = 1.
28/08/2013 10:12:28.232 - *** In exit_2_instances - Closing ERROR.LOG. Status = 1.
28/08/2013 07:37:04.234 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling
28/08/2013 07:37:07.117 - From IsRunningVB.exe, HG612_current_stats.exe is running 1 instances.
28/08/2013 10:11:54.146 - HG612_current_stats.exe has now completed, so HG612_current_stats.exe is resuming.
28/08/2013 10:11:54.146 - Temp File ONGOING-ISRUNNING-101154-146.TXT was created
28/08/2013 10:12:28.148 - *** Now in exit_2_instances as there are 113 instances of HG612_stats.exe running. Status = 1.
28/08/2013 10:12:28.236 - *** In exit_2_instances - Closing ERROR.LOG. Status = 1.
-------------------
PS
The 2pm currentstats didnt run either and HG612_current_stats.exe got stuck in task manager.
Ive now cleared all stale instance of HG612stats and everything seems to be working ok again. - Well at least its started beeping at me again :D
-
253 instances - that must be some kind of world record! :D
there is another ERROR.LOG_File_ERROR.TXT in the /Scripts directory. Perhaps you could post the relevant extracts from that too? Thanks.
-
:hmm: Perhaps it is time for No-Feathers to take Mrs Eagle on a day-trip to Blackpool? :angel:
-
253 instances - that must be some kind of world record! :D
hahaha.. not even close... I racked up nearly 900 at the w/e.. which is when I cursed cause I couldnt clear them all in task manager and had something open so I didnt want to reboot. I had to reboot in the end cause the PC locked up.. think there was something like 1800+ processes in task manager. All 8 of the core/processes windows were going crazy
there is another ERROR.LOG_File_ERROR.TXT in the /Scripts directory. Perhaps you could post the relevant extracts from that too? Thanks.
I can only see one & that's posted above - 2nd set of the code samples
-
Oh... I found another error log in \Ongoing_Stats\ERROR.LOG_file_ERROR.TXT
Is this what you wanted?
28/08/2013 5:59:02.22 - ONGOING-ISRUNNING-055900-561.TXT - Now in exit. Status = 1,
28/08/2013 5:59:02.23 - ONGOING-ISRUNNING-055900-561.TXT - ONGOING-ISRUNNING-055900-561.TXT DELETED - Status = 1,
28/08/2013 5:59:02.25 - ONGOING-ISRUNNING-055900-561.TXT - End of HG612_stats.exe. Status = 1,
28/08/2013 6:00:00.48 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
28/08/2013 6:00:00.50 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
28/08/2013 6:00:00.51 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
28/08/2013 6:00:00.57 - About to create ONGOING-ISRUNNING-060000-562.TXT Status = 1,
28/08/2013 6:00:00.58 - ONGOING-ISRUNNING-060000-562.TXT created. Status = 1,
28/08/2013 6:00:00.70 - ONGOING-ISRUNNING-060000-562.TXT - There are 1 instances of HG612_stats.exe running. Status = 1,
28/08/2013 6:00:00.71 - ONGOING-ISRUNNING-060000-562.TXT - ** Continuing as there are only 1 instances of HG612_stats.exe running **. Status = 1,
28/08/2013 6:00:00.72 - ONGOING-ISRUNNING-060000-562.TXT - C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Ongoing_Stats\ERROR.LOG opened for appending. Status = 1,
28/08/2013 6:00:00.73 - ONGOING-ISRUNNING-060000-562.TXT - malloc() O.K. Status = 1,
28/08/2013 6:00:00.74 - ONGOING-ISRUNNING-060000-562.TXT - WSAStartup() SUCCESSFUL!!! Status = 1,
28/08/2013 6:00:00.76 - ONGOING-ISRUNNING-060000-562.TXT - getaddrinfo() O.K. Status = 1,
28/08/2013 6:00:00.77 - ONGOING-ISRUNNING-060000-562.TXT - connect() O.K. Status = 1,
28/08/2013 6:00:00.78 - ONGOING-ISRUNNING-060000-562.TXT - ********** DEBUG VERSION - Trying the HG622 bodge. Status = 1. **********
28/08/2013 6:00:00.79 - ONGOING-ISRUNNING-060000-562.TXT - About to log in to the modem. Status = 1,
28/08/2013 6:00:00.98 - ONGOING-ISRUNNING-060000-562.TXT - **** expect("gin:") O.K. Status = 1.
28/08/2013 6:00:00.99 - ONGOING-ISRUNNING-060000-562.TXT - **** reply(config.Username) O.K. Status = 1.
28/08/2013 6:00:01.20 - ONGOING-ISRUNNING-060000-562.TXT - **** expect("ssword:") O.K. Status = 1.
28/08/2013 6:00:01.22 - ONGOING-ISRUNNING-060000-562.TXT - **** reply(config.Password) O.K. Status = 1.
28/08/2013 6:00:01.42 - ONGOING-ISRUNNING-060000-562.TXT - **** expect("ATP>") O.K. Status = 1.
28/08/2013 6:00:01.43 - ONGOING-ISRUNNING-060000-562.TXT - **** reply(config.Shell) O.K. Status = 1.
28/08/2013 6:00:01.64 - ONGOING-ISRUNNING-060000-562.TXT - **** expect("# ") O.K. Status = 1.
28/08/2013 6:00:01.66 - ONGOING-ISRUNNING-060000-562.TXT - **** Reaching this point means logging in to the modem was successful. Status = 1,
28/08/2013 6:00:01.67 - ONGOING-ISRUNNING-060000-562.TXT - After xdslcmd info --stats(), ERROR.LOG status = 1
28/08/2013 6:00:01.90 - ONGOING-ISRUNNING-060000-562.TXT - After xdslcmd info --pbParams(), ERROR.LOG status = 1
28/08/2013 6:00:02.30 - ONGOING-ISRUNNING-060000-562.TXT - Logged out of modem O.K. Status = 1,
28/08/2013 6:00:02.34 - ONGOING-ISRUNNING-060000-562.TXT - get_log_data() completed. Status = 1,
28/08/2013 6:00:02.36 - ONGOING-ISRUNNING-060000-562.TXT - Appending data to C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Ongoing_Stats\modem_stats.log - Status = 1,
28/08/2013 6:00:02.37 - ONGOING-ISRUNNING-060000-562.TXT - Data has now been written to MSLOGFILE (C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Ongoing_Stats\modem_stats.log) - Status = 1,
28/08/2013 6:00:02.39 - ONGOING-ISRUNNING-060000-562.TXT - Now in exit. Status = 1,
28/08/2013 6:00:02.40 - ONGOING-ISRUNNING-060000-562.TXT - ONGOING-ISRUNNING-060000-562.TXT DELETED - Status = 1,
28/08/2013 6:01:00.47 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
28/08/2013 6:01:00.48 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
28/08/2013 6:01:00.50 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
28/08/2013 6:02:00.48 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
28/08/2013 6:02:00.50 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
28/08/2013 6:02:00.51 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
28/08/2013 6:03:00.49 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
28/08/2013 6:03:00.50 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
28/08/2013 6:03:00.52 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
28/08/2013 6:04:00.54 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
28/08/2013 6:04:00.55 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
28/08/2013 6:04:00.57 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
I note that at 6:00 there was no "End of HG612_stats.exe. Status = 1,"
This continues until 14:08, which is when I stopped everything to clear out all the running HG612 processes and ongoing_stats... and started afresh at 14:15.
Unsurprisingly no current_stats were produced at the (8 hour scheduled) 14:00 run either.
28/08/2013 14:08:01.25 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
28/08/2013 14:08:01.41 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
28/08/2013 14:08:01.45 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
28/08/2013 14:15:00.59 - In HG612_stats.exe - After ini_parse(). ERROR.LOG status = 0,
28/08/2013 14:15:00.60 - working_directory = C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Scripts - ERROR.LOG status = 0,
28/08/2013 14:15:00.62 - After attempting to open ERROR.LOG, ERROR.LOG status = 1
28/08/2013 14:15:00.68 - About to create ONGOING-ISRUNNING-141500-678.TXT Status = 1,
28/08/2013 14:15:00.69 - ONGOING-ISRUNNING-141500-678.TXT created. Status = 1,
28/08/2013 14:15:00.84 - ONGOING-ISRUNNING-141500-678.TXT - There are 1 instances of HG612_stats.exe running. Status = 1,
28/08/2013 14:15:00.85 - ONGOING-ISRUNNING-141500-678.TXT - ** Continuing as there are only 1 instances of HG612_stats.exe running **. Status = 1,
28/08/2013 14:15:00.86 - ONGOING-ISRUNNING-141500-678.TXT - C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Ongoing_Stats\ERROR.LOG opened for appending. Status = 1,
28/08/2013 14:15:00.87 - ONGOING-ISRUNNING-141500-678.TXT - malloc() O.K. Status = 1,
28/08/2013 14:15:00.88 - ONGOING-ISRUNNING-141500-678.TXT - WSAStartup() SUCCESSFUL!!! Status = 1,
28/08/2013 14:15:00.89 - ONGOING-ISRUNNING-141500-678.TXT - getaddrinfo() O.K. Status = 1,
28/08/2013 14:15:00.90 - ONGOING-ISRUNNING-141500-678.TXT - connect() O.K. Status = 1,
28/08/2013 14:15:00.92 - ONGOING-ISRUNNING-141500-678.TXT - ********** DEBUG VERSION - Trying the HG622 bodge. Status = 1. **********
28/08/2013 14:15:00.93 - ONGOING-ISRUNNING-141500-678.TXT - About to log in to the modem. Status = 1,
28/08/2013 14:15:01.10 - ONGOING-ISRUNNING-141500-678.TXT - **** expect("gin:") O.K. Status = 1.
28/08/2013 14:15:01.12 - ONGOING-ISRUNNING-141500-678.TXT - **** reply(config.Username) O.K. Status = 1.
28/08/2013 14:15:01.31 - ONGOING-ISRUNNING-141500-678.TXT - **** expect("ssword:") O.K. Status = 1.
28/08/2013 14:15:01.33 - ONGOING-ISRUNNING-141500-678.TXT - **** reply(config.Password) O.K. Status = 1.
28/08/2013 14:15:01.52 - ONGOING-ISRUNNING-141500-678.TXT - **** expect("ATP>") O.K. Status = 1.
28/08/2013 14:15:01.54 - ONGOING-ISRUNNING-141500-678.TXT - **** reply(config.Shell) O.K. Status = 1.
28/08/2013 14:15:01.75 - ONGOING-ISRUNNING-141500-678.TXT - **** expect("# ") O.K. Status = 1.
28/08/2013 14:15:01.77 - ONGOING-ISRUNNING-141500-678.TXT - **** Reaching this point means logging in to the modem was successful. Status = 1,
28/08/2013 14:15:01.78 - ONGOING-ISRUNNING-141500-678.TXT - After xdslcmd info --stats(), ERROR.LOG status = 1
28/08/2013 14:15:02.01 - ONGOING-ISRUNNING-141500-678.TXT - After xdslcmd info --pbParams(), ERROR.LOG status = 1
28/08/2013 14:15:02.40 - ONGOING-ISRUNNING-141500-678.TXT - Logged out of modem O.K. Status = 1,
28/08/2013 14:15:02.43 - ONGOING-ISRUNNING-141500-678.TXT - get_log_data() completed. Status = 1,
28/08/2013 14:15:02.45 - ONGOING-ISRUNNING-141500-678.TXT - Appending data to C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Ongoing_Stats\modem_stats.log - Status = 1,
28/08/2013 14:15:02.46 - ONGOING-ISRUNNING-141500-678.TXT - Data has now been written to MSLOGFILE (C:\Users\kitz\Desktop\Connection\HG612_Modem_Stats\Ongoing_Stats\modem_stats.log) - Status = 1,
28/08/2013 14:15:02.48 - ONGOING-ISRUNNING-141500-678.TXT - Now in exit. Status = 1,
28/08/2013 14:15:02.49 - ONGOING-ISRUNNING-141500-678.TXT - ONGOING-ISRUNNING-141500-678.TXT DELETED - Status = 1,
28/08/2013 14:15:02.50 - ONGOING-ISRUNNING-141500-678.TXT - End of HG612_stats.exe. Status = 1,
-
There are various Linux commands which will tell you who is logged on (e.g. who, users, finger) but none of them appear to be implemented here.
I too had a look earlier and cant seem to find a way of checking either.
If anyone is interested.. I cant find a way to check users logged into the Broadcom shell, but the following command appears works for the Huawei console
ATP> display login
This is the results with just me logged in via telnet
ATP>display login
=============================
User Name : admin
Login IP : 192.168.1.10
Login Time : 2013-08-28 17:44:34
Login TimeLen : 1(Mins) 57(Secs)
ATP>display login
and this is catching DSLstats doing a sample
ATP>display login
=============================
User Name : admin
Login IP : 192.168.1.10
Login Time : 2013-08-28 17:44:48
Login TimeLen : 7(Secs)
=============================
User Name : admin
Login IP : 192.168.1.10
Login Time : 2013-08-28 17:44:34
Login TimeLen : 21(Secs)
ATP>display login
-
Well done, finding that command. Unfortunately it doesn't seem to work on the HG622.
-
I note that at 6:00 there was no "End of HG612_stats.exe. Status = 1,"
In the temporary absence of our esteemed feathered friend ....
The cause of whatever happened on this occasion seems different to (all) the others we've all seen. As you said, it seems on this occasion modem_stats hasn't exited properly from its harvesting. Assuming that this then left that process around, any subsequent harvests, whether by the 1min timer or by the scheduled 'current' snapshots, will are meant to exit as soon as they see that there is already another process running. The fact that they didn't, and also the fact that there seems to be no trace of it making repeated (up to 50) attempts to try to login again successfully after a first failure, makes me wonder which (debugging) version of the modem_stats you are actually running?
That's all I can see atm from the traces, but then I'm no noble bird. ;)
-
>> makes me wonder which (debugging) version of the modem_stats you are actually running
The ones provided by BE in this thread, Ive been dropping them in as he attatches. I hope I have all the right ones.
>>> the fact that there seems to be no trace of it making repeated (up to 50) attempts to try to login again successfully after a first failure,
Hmmm, you are right.. it was logging the repeated attempts up until
27/08/2013 15:04:08.52 - 32 trying reply(sh) again.
Very shortly after that I put in this (http://forum.kitz.co.uk/index.php/topic,12844.msg242930.html#msg242930) current_stats version.
A new version of HG612_current_stats.exe is attached, also disabling HG622 compatibility for now, along with including the DSLStats partial workaround. It doesn't include any of the extra event/error logging, but it does work O.K.
Since I dropped that in, Ive not seen any of the repeated attempts recorded in the logs.
-
A new version of HG612_current_stats.exe is attached, also disabling HG622 compatibility for now, along with including the DSLStats partial workaround. It doesn't include any of the extra event/error logging, but it does work O.K.
Since I dropped that in, Ive not seen any of the repeated attempts recorded in the logs.
Aaaah! I forgot that he said that (see above) - which would explain it obviously :doh:.
If you're not having any further problems, I guess you should just hang on until he flies in again. I'm not sure whether the version you're using is the same as the one I'm using - I suspect possibly not, as that .zip file was 25.84Kb, and the one I'm using (although the same date) was 44Kb. :hmm:
-
I have put together some new debugging versions of HG612_stats.exe, HG612_current_stats.exe & SET_HG612_DATE_AND_TIME.exe
Thanks to Kitz discovering the display login command used at the ATP> prompt, a new log (named Login_events.TXT) is generated including these details:-
***********************************************************************************
29/08/2013 22:06:00.15 - In HG612_stats.exe - At the start of the main() function
29/08/2013 22:06:00.31 - There are 1 instances of HG612_stats.exe running. Status = 0,
29/08/2013 22:06:02.21 - **** reply(display login) O.K. Status = 1.
29/08/2013 22:06:02.43 - **** get_login_data() OK! Status = 1.
=============================
User Name : admin
Login IP : 192.168.1.100
Login Time : 2013-08-29 22:06:00
Login TimeLen : 1(Secs)
=============================
User Name : admin
Login IP : 192.168.1.100
Login Time : 2013-08-29 22:05:56
Login TimeLen : 5(Secs)
=============================
User Name : admin
Login IP : 192.168.1.100
Login Time : 2013-08-29 22:04:47
Login TimeLen : 1(Mins) 14(Secs)
=============================
User Name : admin
Login IP : 192.168.1.100
Login Time : 2013-08-29 22:00:43
Login TimeLen : 5(Mins) 18(Secs)
29/08/2013 22:06:03.18 - 01 trying reply(sh) again.
29/08/2013 22:06:03.94 - 02 trying reply(sh) again.
29/08/2013 22:06:04.74 - 03 trying reply(sh) again.
29/08/2013 22:06:05.50 - 04 trying reply(sh) again.
29/08/2013 22:06:06.28 - 05 trying reply(sh) again.
29/08/2013 22:06:07.06 - 06 trying reply(sh) again.
29/08/2013 22:06:07.31 - ** WARNING!! HG612_stats.exe - Logging in to the modem only succeeded after 06 additional attempts to reply(sh)
29/08/2013 22:06:08.20 - Normal End of HG612_stats.exe
**********************************************************************************
I tried very hard to make it crash by having a number of sessions open at the same time, but the worst that happened was that a few additional attempts were needed during DSLStat's sampling period.
I see that Eric has now released an updated version with compatibility for HG612 Modem Stats.
I'll try that when I get home from work & if all still seems well, I'll attach the amended debugging versions for anyone wishing to test them.
FWIW, while I've been at it, I've 'improved' resync detection for those connections that resync at maximum speeds.
It also now considers AS (available seconds) along with sync speed.
-
Hi Bald Eagle,
Many thanks for all yuor hard work with the HG612 Modem Stats, I have been using the latest updates and does seem to work better although get the occassional glitch but no duplicate exe's running now.
Look forward to trying out the update.
Cheers
-
Thank you BE.
I'm willing to test the new versions if you want to attach them :)
-
O.K. Here they are.
All 3 programs need to be extracted to the 'Scripts' folder
I have been running DSLStats v 3.92 for only a couple of hours (with the "Synchronise with HG612-Modem-Stats" option ticked), but so far so good.
I will attempt to force a clash between DSLStats.exe & HG612_stats.exe later on, just to see if both programs behave as intended, but the signs are promising.
I am still seeing the occasional duplicated Windows task bug, but my programs seem to handle them reasonably well.
As these duplicated tasks run very, very close to each other, there have been 2 occasions today when both instances of HG612_stats.exe spotted each other & both exited, causing that minute's sample to be missed.
Has anyone tried the Microsoft 'fix' for this issue yet?
I haven't.
http://support.microsoft.com/kb/2461249/en-us?sd=rss&spid=14019
It does seem rather strange that it has only become an issue quite recently.
-
Thank you BE... now installed.
---------
btw Ive had a few more of the multiple instances occur and Ive just cleared out a few hundred running instances of HGstats/vbisrumming/conhost.
HG612_current_stats.exe was also stuck & didnt complete the 14:00 run.
As previous this being stuck is what caused HG612stats.exe to also stop logging.
On the whole ive not had any problems with HG612_stats getting stuck.. unless it was triggered by a failed run of HG612_current_stats.
Hopefully the new veriosn of HG_612_current_stats will sort that? :)
-----------
No I havent tried the MS fix, what surprised me when I looked at it was that it supposedly went back to the beginning of last year... but like you Ive only just noticed it... I think it said something about it being included in a future version of windows update. I wonder if it was fixed.. and then like you said in an earlier post.. an update since has broken it again?
-
PS Paul... Ive just had a thought.
Since your fixes, HG612stats has been running fine.. and the only problems I see now have occurred after a failed HG612_current_stats.
-----------
I dont know the internals of your program or code.. but something has just struck me.. if Im not surmising your code correctly ignore me.
- HG612stats checks for other instances and if false runs the code to collect stats.
- HG612_current_stats checks for other instances and if false.. pauses 10 seconds and then collects stats.
During this 10 seconds DSLstats could have started, causing HG612_current_stats to fail. - HG612_current_stats then gets stuck in task manager
- From my observations HG612stats always appears to get stuck when HG612_current_stats does.. and this is when all stat logging ceases... and numerous HG612stats.exe start piling up in task manager
-
Sorry to say BE, but the latest updates still disagrees with my WHS 2011, same symptoms - error log not being written to, isrunning files not being deleted, but does not cause multiple instances.
Is anybody else having these symptoms?
I only run BEs program, but a version of 1.1 I have from July works.
-
PS Paul... Ive just had a thought.
Since your fixes, HG612stats has been running fine.. and the only problems I see now have occurred after a failed HG612_current_stats.
-----------
I dont know the internals of your program or code.. but something has just struck me.. if Im not surmising your code correctly ignore me.
- HG612stats checks for other instances and if false runs the code to collect stats.
- HG612_current_stats checks for other instances and if false.. pauses 10 seconds and then collects stats.
During this 10 seconds DSLstats could have started, causing HG612_current_stats to fail. - HG612_current_stats then gets stuck in task manager
- From my observations HG612stats always appears to get stuck when HG612_current_stats does.. and this is when all stat logging ceases... and numerous HG612stats.exe start piling up in task manager
Not quite.
If HG612_stats.exe is running & HG612_current_stats is run manually, HG612_current_stats.exe is delayed by whatever delay setting is specified via Settings Editor.
However, if HG612_current_stats.exe is triggered by the schedule set via Settings Editor or by a resync being detected whilst running HG612_stats.exe 24/7, any pre-set delays are ignored & as that check is made AFTER HG612_stats.exe has logged out of the modem & written the data to modem_stats.log, there shouldn't really be any problems.
These checks used to happen around 2 seconds into HG612_stats.exe.
With the recent additional checking & dealing with DSLStats.exe also running 24/7 etc., the checks for scheduled logging or resyncs are now made around 3 seconds into HG612_stats.exe.
Grabbing the stats for current_stats takes around 7 seconds & if auto-graphing is switched on, that adds another 4 seconds (approximately).
Adding compatibility for HG622 modems added a little more time due to needing to harvest more/different data & the whole process can now take typically around 14-15 seconds on my PC when scheduled current stats & auto-graphing are all switched on, a bit longer if DSLStats was sampling at the time HG612_stats.exe was due to start.
There did seem a strong possibility that some of this would at some stage clash with DSLStats, hence the recent extra checking that seems to work without any issues (at my end anyway).
Now that Eric has added the "Synchronise with HG612-Modem-Stats" option to v 3.92, any remaining issues will hopefully have been dealt with.
It may just have been that the timing of DSLStats's sampling clashed on your particular setup.
I suppose you'll find out at 22:00 tonight or at 06:00 tomorrow morning (if that's when harvesting/graphing current stats is scheduled on your PC).
-
Sorry to say BE, but the latest updates still disagrees with my WHS 2011, same symptoms - error log not being written to, isrunning files not being deleted, but does not cause multiple instances.
Do you mean today's updates?
If so, could you please email all the logs to me to see if I can spot anything?
The isrunning files from when anything has gone wrong are currently intentionally NOT deleted, just to make it easier to spot the timings of any occasional problems & thus point to a particular point in the various logs rather than having to wade through potentially hundreds/thousands of rows.
There may just be a command or something now being done slightly differently that doesn't agree with WHS 2011.
Does HG612_current_stats.exe run properly when manually started (24/7 logging switched off)?
Is anybody else having these symptoms?
I only run BEs program, but a version of 1.1 I have from July works.
-
Just a thought....................
If the task is disabled via Settings Editor, you'll probably see this in the ini file:-
[Logging]
Ongoing_Logging = NO
Current_Stats = NO
Also only this in the Login_events.TXT file in the Scripts folder:-
***********************************************************************************
30/08/2013 21:23:20.78 - In [HG612_stats.exe] - At the start of the main() function
30/08/2013 21:23:20.95 - There are 1 instances of HG612_stats.exe running. Status = 0,
30/08/2013 21:23:21.65 - Normal End of [HG612_stats.exe]
**********************************************************************************
That's when HG612_stats.exe is run directly & with the task disabled.
You'll also probably just see a quick flash of messages in the CMD.EXE window
If that's the case, manually editing the ini file to show this might be the cure (it also catches me out now & then):-
Ongoing_Logging = YES
-
It may just have been that the timing of DSLStats's sampling clashed on your particular setup.
I suppose you'll find out at 22:00 tonight or at 06:00 tomorrow morning (if that's when harvesting/graphing current stats is scheduled on your PC).
It doesnt happen everytime, mostly it will run for a day or so without problems, but because DSLstats (used to) gradually creep forward and gain a few seconds, at some point in the cycle it would hit at the same time as a sample. For eg I could set it off at 15 seconds past the hour, but slowly it would gain time and start sampling at 14,13,... 2,1,0 seconds past. That is was happened in one of my earlier posts when it hit the 2pm schedule for HG612_current_stats.
-
Do you mean today's updates?
Yes.
If so, could you please email all the logs to me to see if I can spot anything?
I've cleared it out and set it running again, it should generate graphs at 22:00, after that I'll email the logs etc.
The isrunning files from when anything has gone wrong are currently intentionally NOT deleted, just to make it easier to spot the timings of any occasional problems & thus point to a particular point in the various logs rather than having to wade through potentially hundreds/thousands of rows.
I didn't realise the ongoing files were intentionally not being deleted
There may just be a command or something now being done slightly differently that doesn't agree with WHS 2011.
Thats what I was thinking, I've sent you an email before I saw your post, but I didn't mention what versions I used. The one that works is the July 14, the one that doesn't is the one posted on here today.
Does HG612_current_stats.exe run properly when manually started (24/7 logging switched off)?
Yes HG612_current_stats.exe runs properly when manually started.
-
The isrunning files from when anything has gone wrong are currently intentionally NOT deleted, just to make it easier to spot the timings of any occasional problems & thus point to a particular point in the various logs rather than having to wade through potentially hundreds/thousands of rows.
I didn't realise the ongoing files were intentionally not being deleted
That's just a temporary measure until these issues have been fully resolved.
-
:( :( :( :( :(
I am sorry to report it, but unfortunately, Eric's recent changes to DSLstats to try to provide coexistence with HG612modemstats have made the situation significantly worse for me.
The only change I made yesterday was to implement v3.92 of DSLstats. I had not, as yet, made any further changes to HG612modemstats, i.e. the new debugging versions you posted last night. So, I'm still running on the 26/08 version you previously sent me - not any of the ones downloaded from this thread.
I made the change to v3.92 yesterday morning just after Eric posted it's availability, and I used the new 'synchronise' option. Everything seemed OK up until we had to go out last night about 6pm (after your post about your new debugging download on here BE), but by the time we got back late last night, my server was running at 100% CPU, and the same processes as Kitz has previously reported were stacked up with loads of instances, viz:
cmd.exe
conhost.exe
HG612_stats.exe
isRunningVB.exe
Now, as you know BE, apart from hg612-stats.exe I have never seen those other process stacked up in this way before, ever. So, unfortunately, I'm sorry to report that v3.92 has significantly worsened the situation for me, Eric. And to provide additional evidence, since reloading the server last night, and without v3.92 running, there have been no further instances of this issue. :( :( :( :( :(
I will email you the logs & things BE. Sorry Eric. :(
[edit] And just to be explicit, I had previously been running with v3.9 and BE's debugging harvesting without any issues - but then, as I have reported above, my aging server is so slow that I had only rarely seen it 'catch up' with modemstats in time.
-
Colin, all the DSLstats 'synchronise' option does is delay the start of recording if necessary so that it starts between 15 and 45 seconds after the minute. I understand that HG612 Modem Stats starts on the minute, so this should ensure that they're not logging in at the same time (not initially at least). It's hard to see how this could make the situation worse (although I don't doubt what you say of course).
-
Colin, all the DSLstats 'synchronise' option does is delay the start of recording if necessary so that it starts between 15 and 45 seconds after the minute. I understand that HG612 Modem Stats starts on the minute, so this should ensure that they're not logging in at the same time (not initially at least). It's hard to see how this could make the situation worse (although I don't doubt what you say of course).
I appreciate that Eric, and I agree that I can't see how this happened either. :shrug2: All I can say is that it ran from 28/08-30/08 with v3.9 and the 28/08 debugging version I had from Paul with no problems. :no: Installed v3.92 about 10:30 yesterday, and it looks like it failed during the 22:00 Current_stats plot.
Circumstancial I agree, :( but a) this was the only change since 28/08 and b) I have never seen anything other than multiple hg612_stats.exe (the 1min harvesting) stacked up before, ever. So while I apologise in advance if it's just coincidence, :( it was a very unusual set of circumstances for me :o, and I think BE & I have been chasing this problem since about 16/08.
I just need to report what I have seen, so that both you and he can think about it. :hmm:
[Edit] One thing that would help, is if you could produce a debugging version of DSLstats that keeps your log file permanently without asking, and not just on exit, because when a reboot becomes the only option, you can't get in to do so. :-\
-
Colin... I think what may have happened is that purely co-incidence.. & for the first time you ran into the issues that I see.
The problem I have (and possibly happens more frequently on faster processors than slower)... is that DSLstats will start at 15seconds past the minute... then gradually moves forward.. ie 14,13,12...3,2,1 seconds past the minute.
Then when it occurs at exactly the same time as HGstats then you get all the stuck items in task manager such as cmd and vbisrunning.. although I must admit I think vbisrunning & cmd (for me) tends to mostly get stuck after a failed run of HG612_current_stats.
Can you recall if HG612_current_stats.exe also in your task manager? Did you also have a failed run of HG612_current_stats?
-
[Edit] One thing that would help, is if you could produce a debugging version of DSLstats that keeps your log file permanently without asking, and not just on exit, because when a reboot becomes the only option, you can't get in to do so. :-\
Yes, certainly. I'll do that ASAP. I'll make it (optionally) save the event log after each new event is logged. The best option, I think, will be to keep the same filename so each save overwrites the previous one, but increment a number in the filename each time DSLstats is started afresh.
-
The problem I have (and possibly happens more frequently on faster processors than slower)... is that DSLstats will start at 15seconds past the minute... then gradually moves forward.. ie 14,13,12...3,2,1 seconds past the minute.
That's a bit of a puzzle actually. I would have expected the sampling time to slowly get later, not earlier, because the logic goes: "If the time between the last sample and now is greater than or equal to the configured time, then start the next sample".
I'm still thinking over this problem, looking for a better way to keep DSLstats in sync with the Windows timer. One possible way is to change the logic so that the start of each sample is referenced to the time the previous sample should have started, and not to the time when it actually started. This should hopefully eliminate the drift.
-
Colin... I think what may have happened is that purely co-incidence.. & for the first time you ran into the issues that I see.
The problem I have (and possibly happens more frequently on faster processors than slower)... is that DSLstats will start at 15seconds past the minute... then gradually moves forward.. ie 14,13,12...3,2,1 seconds past the minute.
Then when it occurs at exactly the same time as HGstats then you get all the stuck items in task manager such as cmd and vbisrunning.. although I must admit I think vbisrunning & cmd (for me) tends to mostly get stuck after a failed run of HG612_current_stats.
Can you recall if HG612_current_stats.exe also in your task manager? Did you also have a failed run of HG612_current_stats?
Yes, as I said in the post above the failure occured (after or) during the 22:00 Current_stats snapshot - but NOT the earlier 14:00 one, for example. So you may be right about that. However, in testing that I did from as early as 16/08 it never occurred either in all that time. So it would have to be a very exceptionally bad bit of luck (but not impossibly so) for this to suddenly occur now.
And while it may indeed be coincidence, I would simply point out that the time-gaining issue (which I have no doubt at all occurs), has NOT been an issue for me given the ancient 13yr-old CPU that mine's runs on. You will note that it did NOT catch up in 48hours with v3.9, but by this hypothesis it did in ~12hrs. I agree with your feeling that this is directly related to processor speed, although Eric has given the details of the timer he uses in an earlier post.
I would also repeat that it was exceptionally usual for me to see all these other processes stacked up. In fact that has never happened to me before, never. The only thing that has ever happened to me in extensive debugging on this is that several instances of hg612_stats.exe stack up (but never in the number you have seen!).
So, we just need to wait & see what Paul's analysis is of the debugging logs I have already sent him. Unfortuntely I was unable to preserve Eric's ones.
[edited] to clarify on current_stats.
-
That's a bit of a puzzle actually. I would have expected the sampling time to slowly get later, not earlier, because the logic goes: "If the time between the last sample and now is greater than or equal to the configured time, then start the next sample".
It is rather strange, I also would normally expect runs to get slightly later & it certainly is more logical.
But its not just me that's observed this... BE sees it too (http://149.241.127.125).
The only possible thing that springs to mind is that perhaps the timer tries to compensate against running later and intentionally moves forward by xseconds to allow time for the task to complete, but faster processors dont need quite so long? :shrug2:
-
Can you recall if HG612_current_stats.exe also in your task manager? Did you also have a failed run of HG612_current_stats?
Yes, as I said in the post above the failure occured after the 22:00 Current_stats snapshot
Sorry I missed that :-[
I think I was just trying to identify if it was current_stats which caused it.. because from my experience thats when you will see the all the other mentioned tasks and not just HG612stats.exe stacked up.
-
The only possible thing that springs to mind is that perhaps the timer tries to compensate against running later and intentionally moves forward by xseconds to allow time for the task to complete, but faster processors dont need quite so long? :shrug2:
I think it's more the case that the timer I'm using isn't in sync with the Windows timer. It's an independent timing system. The new method which I referred to a couple of messages ago will effectively sync it to the Windows timer (or the corresponding system timer on other OSs). I wish I'd thought of it before.
-
No probs. :) You seem to be right about current stats leaving these other processes about. But, I'm puzzled why I never saw that in over a fortnight's debugging; but then current stats only runs 3 times a day, @ 6am, 2pm & 10pm.
-
The new method which I referred to a couple of messages ago will effectively sync it to the Windows timer (or the corresponding system timer on other OSs). I wish I'd thought of it before.
But you have now, and it sounds like a good thing to try ;)
-
I've now uploaded a version of DSLstats (Windows only) which has the new-style timer and also includes the option to save the event log automatically after each new event. This is the executable only, so just overwrite the v3.92 executable with this one.
http://www.s446074245.websitehome.co.uk/files/dslstats.exe.zip
-
Thank you Eric,
I shall try it immediately, and keep a careful eye on it this evening, particularly at the 22:00 Current_stats run. :fingers:
Cheers.
Eric - it seems to be asking me for a password to extract the .zip file. Is that right, or ...?
-
No, it shouldn't do that. I zipped it in exactly the same way as I zip the normal releases.
I just downloaded the uploaded version, and it unzipped without asking for a password.
Anyway, I can upload the unzipped executable. I'll do that right now.
Done:
http://www.s446074245.websitehome.co.uk/files/dslstats.exe
-
No, it shouldn't do that. I zipped it in exactly the same way as I zip the normal releases.
Oh well, perhaps it didn't download properly. Anyway, now live on v3.93 with the options checked. Thanks again.
-
Eric,
Some feedback on v3.93 - apologies for the delay.
1) I seem to get access violations once I start it, and subsequently every time I select a tab.
2) I was watching the sync when it first started and noticed against the windows clock that the delay was ~10s.
I would have attached the .ini file but, something is still holding onto it, although the process is gone from Task Manager.
-
Probably this issue, Colin: http://forum.kitz.co.uk/index.php/topic,12864.0.html
I'll be uploading corrected versions shortly.
-
O.K. Here they are.
I have been running DSLStats v 3.92 for only a couple of hours (with the "Synchronise with HG612-Modem-Stats" option ticked), but so far so good.
I will attempt to force a clash between DSLStats.exe & HG612_stats.exe later on, just to see if both programs behave as intended, but the signs are promising.
Just a progress report on this to say - so far so good :)
-
Probably this issue, Colin: http://forum.kitz.co.uk/index.php/topic,12864.0.html
And so it was ... now running successfully on v3.94, looking for any interactions with modemstats, expecially @ 22:00. :)
Thank you.
-
OK, the results of some (late-at-night :sleep:) testing .... all times are for my ageing server.
1) DSLstats v3.94 nothing 'unusual' of note in the log (thank you Eric)
01 Sep 2013 16:57:47 Average errors saved as 'errors43.txt' in snapshot directory
01 Sep 2013 16:57:47 Average error data reset
01 Sep 2013 16:58:02 Recording started
01 Sep 2013 16:58:29 IP address is now ....
02 Sep 2013 04:58:25 Auto snapshots taken
2) Last night I obtained BE's latest debugging modules, and decided to swap them in after the normal 23:58 Ongoing stats report for the day.
3) Stopped all modem_stats's logging using the settings editor at about 00:15
4) at ~00:30 ran current stats manually, with (it turns out) just the right timing to discover something ....
But before some results: here are some timings:
1) stats.exe (BE's harvesting) starts on the minute and takes ~3secs on my server
2) DSLstats starts sampling at ~10s past the minute and takes about 13-14 secs. Please note Eric that AFAICS (and I've tried running the new DSLstats a number of times now) it always seems to run at 10s past, no matter when you start the programme (e.g. even at say 30-45secs past)
3) Current stats (which fortunately did run sucessfully this morning at 06:00) is started after the normal harvesting has completed (at about 3 secs past, but then with a further 10s delay, so ~13secs past in reality) and runs until about 31 secs past, i.e. across the 10s-24s past slot when DSLstats sampling occurs, and on this occasion right at the start of the modem sampling period of DSLstats.
So, some results:
********************************************************************************************
02/09/2013 0:30:04.12 - In [HG612_current_stats.exe] - At the start of the main() function
02/09/2013 0:30:15.46 - **** [HG612_current_stats.exe] - reply(display login) O.K. Status = 0.
02/09/2013 0:30:15.68 - **** [HG612_current_stats.exe] - get_login_data() OK! Status = 0.
=============================
User Name : admin
Login IP : 192.168.1.64
Login Time : 2013-09-02 00:30:14
Login TimeLen :
=============================
User Name : admin
Login IP : 192.168.1.64
Login Time : 2013-09-02 00:30:11
Login TimeLen : 3(Secs)
i.e. I started current stats at around 4 seconds past the minute & it was 14 seconds past when it logged in to the modem.
(Login Time : 2013-09-02 00:30:14)
(There is a configurable (default 10s) delay in BE's module to try to avoid a clash with DSLstats when it previously ran on the minute, and in case a previous instance of harvesting has yet to complete due to CPU load, for example)
But we can also see that DSLStats had logged in at 11 seconds past the minute:-
(Login Time : 2013-09-02 00:30:11)
(and as I have recorded above runs until ~24secs past, but not all of that time is logged into the modem, we know)
The net effect was to cause current stats to fail - apparently because it did not get the expected reply to one of it's xdslcmds (perhaps similar to the occasional failure to get tone data that happens to DSLstats, I don't know?)
**************************************************
* *
* Gathering Snapshot Statistics from the modem *
* *
**************************************************
The local time is: 00:30:04.138
There are 0 instances of HG612_stats.exe running. Please wait for it to complete
HG612_stats.exe is NOT running
HG612_stats.exe is NOT running
Temp File CURRENT-ISRUNNING-003004-138 was created
Creating log file Plink_20130902-0030.log
Delaying snapshot data harvesting by 10 seconds to avoid clashes with any other
scheduled data harvesting tasks
# 1 of 16
## 2 of 16
### 3 of 16
In reply(admin)
In reply(admin)
In reply(display login)
rxbuf = User Name : admin
Login IP : 192.168.1.64
Login Time : 2013-09-02 00:30:14
Login TimeLen :
=============================
User Name : admin
Login IP : 192.168.1.64
Login Time : 2013-09-02 00:30:11
Login TimeLen : 3(Secs)
In reply(sh)
#### 4 of 16
In reply(xdslcmd info --stats)
##### 5 of 16
###### 6 of 16
In reply(xdslcmd info --pbParams)
####### 7 of 16
######## 8 of 16
In reply(xdslcmd info --Bits)
######### 9 of 16
########## 10 of 16
In reply(xdslcmd info --linediag)
########### 11 of 16
And that's the point at which it 'stuck'. Had it been running automatically with these same (relative) timings, then it's likely things would have stacked up as I saw yesterday, and Kitz has seen frequently.
These are just the facts. The relevant logs have been sent to BE for further analysis, but in the meantime perhaps Eric might want consider a) why his synch delay doesn't seem to be as he expects b) if it needs to be much longer than that e.g. say 35secs or c) if he could have detected that e.g. current stats was already logged in when his sampling started, and delayed until it finished. At worst (c) might lose one sample every so often, but might be easier to solve than these timing issues. I don't know?
Similarly perhaps I need to reconsider the default (configurable) delay that Paul's programme uses to avoid clashes, because since they are both in effect delaying 10s past the minute, they end up running at ~ the same time again!!! :(
-
Just a quick response to part of that, as I have to go out shortly. I'm not sure why DSLstats is starting recording at 10 seconds past the minute, and I'll look at that, but in the meantime one thing you could do is to turn off the 'synchronise' option and manually start DSLstats recording at (say) 30 seconds past the minute. If your sample repetition rate is set to 60 seconds, then it should remain synchronised at 30 seconds past the minute.
(If you do it this way, then if you pause or stop and restart recording you will need to press the green button at the 30 second point each time.)
-
Eric, Thanks.
I've implemented your suggested work-around, and DSLstats is now sampling between 35-49sec past. :)
:fingers:
-
Colin... I think what may have happened is that purely co-incidence.. & for the first time you ran into the issues that I see.
because since they are both in effect delaying 10s past the minute, they end up running at ~ the same time again!!! :(
With the benefit of hindsight, I think this observation goes some way to explaining that it was, in part, indeed the unintended consequence of Eric's valiant efforts to avoid his sampling clashing with Paul's harvesting. Unfortunately, they both ended up running at approximately the same time, thereby significantly (though unintentionally) increasing the chances of a clash occurring, particularly at the longer-running current stats snapshot intervals.
Well, I think we are all a bit more informed now about what may be happening, and I think everyone who has contributed to that deserves a round of applause from me for that. Thank you all. :clap2:
-
Thanks for the kind thoughts :)
Some more points:
DSLstats' collision avoidance system depends (obviously) on its detecting a collision, and at present the only way it can do that is to try to log in and deal with the consequence of a failed login, if it happens. It rarely happens, and the present action is to delay the next sample by 10 seconds. Now that it has (I believe) a non-drifting timer, it seems to me that this 10 second delay is unnecessary and counterproductive. Better, I think, to keep it sampling consistently at 35-40 seconds after the minute.
If I knew how to check whether any of Paul's programs are running at the time when a sample is due I could possibly take other actions, but it should normally only be the case under error conditions or if a user has started a one-off unscheduled run.
Reading between the lines, Colin, are you starting DSLstats with the "autostart recording" option set? I have yet to check, but it may be the case that the "synchronise" option doesn't work as intended in this case.
[Later edit] I think that the 'synchronise' option is working as designed, including when the autostart option is used. The issue is that the design is slightly defective as a result of a typo by yours truly. It actually starts recording between 10 and 45 seconds after the minute, so if you press the green button outside that time it will always start at 10 seconds after the minute. :-[
-
Colin, I also queried the 10 second delay for current stats a few pages back, but I think Paul covered that in one of his replies.
Im now not certain... but the way I understood the explanation, was the 10 second delay only occurred during a manual run?
-
DSLstats' collision avoidance system depends (obviously) on its detecting a collision, and at present the only way it can do that is to try to log in and deal with the consequence of a failed login, if it happens. It rarely happens, and the present action is to delay the next sample by 10 seconds. Now that it has (I believe) a non-drifting timer, it seems to me that this 10 second delay is unnecessary and counterproductive. Better, I think, to keep it sampling consistently at 35-40 seconds after the minute.
Well, that would work for me ;)
If I knew how to check whether any of Paul's programs are running at the time when a sample is due I could possibly take other actions, but it should normally only be the case under error conditions or if a user has started a one-off unscheduled run.
I did wonder about using the 'display login' info, but then I think you said earlier that it doesn't work on the 622. I'm sure Paul has some code that detects another 'hg612_stats.exe' running ... could you not share that?
Reading between the lines, Colin, are you starting DSLstats with the "autostart recording" option set? I have yet to check, but it may be the case that the "synchronise" option doesn't work as intended in this case.
Just for the record (I had to check!), no I don't.
[Later edit] I think that the 'synchronise' option is working as designed, including when the autostart option is used. The issue is that the design is slightly defective as a result of a typo by yours truly. It actually starts recording between 10 and 45 seconds after the minute, so if you press the green button outside that time it will always start at 10 seconds after the minute. :-[
Ah, yes, I see - it's a facility! :D ;)
-
Thanks for the kind thoughts :)
Some more points:
DSLstats' collision avoidance system depends (obviously) on its detecting a collision, and at present the only way it can do that is to try to log in and deal with the consequence of a failed login, if it happens. It rarely happens, and the present action is to delay the next sample by 10 seconds. Now that it has (I believe) a non-drifting timer, it seems to me that this 10 second delay is unnecessary and counterproductive. Better, I think, to keep it sampling consistently at 35-40 seconds after the minute.
If I knew how to check whether any of Paul's programs are running at the time when a sample is due I could possibly take other actions, but it should normally only be the case under error conditions or if a user has started a one-off unscheduled run.
There are at least a couple of ways to do that:-
One is via a Windows installed program named tasklist.exe
It comes with all Windows versions apart from XP Home (AFAIK).
e.g.
tasklist /fi "imagename eq HG612_stats.exe"
returns this if HG612_stats.exe is running:-
Image Name PID Session Name Session# Mem Usage
========================= ======== ================ =========== ============
HG612_stats.exe 6852 Services 0 3,780 K
tasklist /fi "imagename eq HG612_stats.exe"
returns this if HG612_stats.exe is NOT running:-
INFO: No tasks are running which match the specified criteria.
just running tasklist will list all running tasks.
The output can be directed to a file for parsing if required.
RONSKI also put a small program together for determining if specific processes are running (as used in my programs):-
HG612_stats_running = IsRunningVB.exe "HG612_stats.exe"
HG612_current_stats_running = IsRunningVB.exe "HG612_current_stats.exe"
That stores the number of running processes in the HG612_stats_running or HG612_current_stats_running variables that match the specified program names.
He may be willing to share the code that you could incorporate into DSLStats?
e.g. pseudo code:-
if HG612_stats_running > 0, hang on for a few seconds & keep checking until it equals zero.
-
PS Paul... Ive just had a thought.
- HG612_current_stats checks for other instances and if false.. pauses 10 seconds and then collects stats.
During this 10 seconds DSLstats could have started, causing HG612_current_stats to fail.
Yes, you did question that, and you were spot on about the potential consequences. Sorry no one picked up on it at the time, as then I think the focus was on the timer, which Eric has now improved. However, the delay (default 10s) is configurable via the settings editor - additional settings tab/Delay for snapshot data logging box... [Edit] for manual runs as Paul has clarified below.
I think in my case, use of the new 'synchronise with modem_stats' option within DSLstats (and a small typo) brought the two back into synchronism again in an unintended way. So, for example, without that new sync option, there was less chance (after the timer was fixed) of the two starting at ~10s past.
Some rationalisation of the delays between the two is probably necessary with the changes Eric has now made (and his 35-40s past suggestion).
-
Colin, I also queried the 10 second delay for current stats a few pages back, but I think Paul covered that in one of his replies.
Im now not certain... but the way I understood the explanation, was the 10 second delay only occurred during a manual run?
Yes, that's correct for manual runs.
The delay can be configured via Settings Editor, but it is completely ignored when scheduling current stats via Settings Editor as it runs immediately following any ongoing stats harvesting
-
If I knew how to check whether any of Paul's programs are running at the time when a sample is due I could possibly take other actions, but it should normally only be the case under error conditions or if a user has started a one-off unscheduled run.
RONSKI also put a small program together for determining if specific processes are running (as used in my programs):-
HG612_stats_running = IsRunningVB.exe "HG612_stats.exe"
HG612_current_stats_running = IsRunningVB.exe "HG612_current_stats.exe"
That stores the number of running processes in the HG612_stats_running or HG612_current_stats_running variables that match the specified program names.
He may be willing to share the code that you could incorporate into DSLStats?
e.g. pseudo code:-
if HG612_stats_running > 0, hang on for a few seconds & keep checking until it equals zero.
Roseway, feel free to use the programs if you wish, I most likely got it off the net somewhere and just modified it to suite.
Here's the VBS code, the exe version is just the code compiled.
Option Explicit
Dim strComputer, objWMIService, colProcess, objProcess, qty, Arg
Set Arg = WScript.Arguments
strComputer = "."
if WScript.Arguments.Count = 0 Or WScript.Arguments.Count > 1 then
'WScript.Echo "Missing parameters"
wscript.quit -1
end if
Set objWMIService = GetObject("winmgmts:" & "{impersonationLevel=impersonate}!\\" & strComputer & "\root\cimv2")
Set colProcess = objWMIService.ExecQuery ("Select * from Win32_Process Where Name = '" & arg(0) & "'")
For Each objProcess in colProcess
qty = qty + 1
Next
wscript.quit qty
And here's an example batch file, the script just returns an error number, corresponding to how many instances of the specified program are running.
@ECHO OFF
cls
echo This one returns the amount of processes running, -1 for error.
echo .
echo It is not case sensitive.
echo .
set Var=NOTEPAD.exe
isrunningvb.bat %Var%
echo .
echo There are %ERRORLEVEL% instances of %Var% running
echo .
pause
-
Thanks for the suggestions and help for detecting processes running. At the moment, the VBS code looks like Chinese to me, and may not be easily portable to Lazarus/Freepascal, so some digestion will be needed.
-
Can you not just call the exe program and capture the error number like BE does?
Although it would be better all self contained in your own program.
-
Can you not just call the exe program and capture the error number like BE does?
Probably I can. This is new territory for me, as I don't actually use Windows, but I can certainly launch an external executable and check what data it returns. That will be a lot easier than porting the VBS code.
-
its a shame the hg has no snmpd server, as thats the proper way to do this sort of thing. Sadly modern devices tend to lack snmpd support now unless aimed at geeks like myself.
The old variant of the script (which I still use) doesnt have this issue but the cpu spike every minute when fetching the data is signficant.