Print

Please login or register.
1 Hour 1 Day 1 Week 1 Month Forever
Login with username, password and session length

[Chrysalis]

sadly doesnt run tho, getting loads of these. (thought would test it quickly)

GET_DATA_ERROR-185500-523.TXT

I guess I report this in the other thread?

[Chrysalis]

thinking might be a dimm now, after another 6 hours or so of tests.

I will post on his thread about this after some sleep.

[Ronski]

I'd be very surprised if it is the motherboard,  I presume you've tried one dimm at a time and manually checked memory settings not relying on any auto settings or profiles? Running at the specified timings and voltages?

Perhaps it would be good to create a thread for this.

[Bald_Eagle1]

sadly doesnt run tho, getting loads of these. (thought would test it quickly)



I guess I report this in the other thread?

Which is the 'other' thread you mention?

You will see CURRENT_GET_DATA_ERROR-185500-523.TXT files whenever the [HG612_current_stats.exe] program makes too many attempts to get the data.
Previously, this could have caused a 'stuck' instance of one or more of the programs, leaving literally thousands of ONGOING-ISRUNNING.TXT files behind & meaning no new data could be obtained.


If you are using the v 2.1 beta programs, you should see something like these entries in the CURRENT_ERROR.LOG_file_ERROR.TXT file when there aren't any problems:-

**** - get_data() for --stats    O.K. Status = 1, times in get_data() loop was 002
**** - get_data() for --pbParams O.K. Status = 1, times in get_data() loop was 002
**** - get_data() for --Bits     O.K. Status = 1, times in get_data() loop was 033
**** - get_data() for --linediag O.K. Status = 1, times in get_data() loop was 228
**** - get_data() for --version  O.K. Status = 1, times in get_data() loop was 002

The fact you have/had  some CURRENT_GET_DATA_ERROR-185500-523.TXT files means that the maximum attempts for one of the data elements was exceeded for some reason.

The maximum No. of times in the attempts loops are:-

--stats = 10
--pbParams = 10
--Bits = 130
--linediag = 500
--version = 10

Some of the sets of data are quite large, so obtaining them is broken into smaller chunks for improved reliability.

In the example from my connection, you can see that the linediag data was broken into 228 chunks.

Anything exceeding the maximum values means there is a problem somewhere, which could be the modem, PC, my programs, an incorrectly configured ini file and/or more than one instance of the program(s) hogging the modem when another instance tries to access it.

[Bald_Eagle1]

I did look there, but I have just noticed that he did say this:-

I will post on his thread about this after some sleep.

At least everyone now knows why CURRENT_GET_DATA_ERROR-185500-523.TXT files might start to appear.

[Chrysalis]

yeah about 40 billion memtest's been chewing up my time but back on topic.

attaching the log file.

[Bald_Eagle1]

Looking at that log file it seems that the maximum No. of attempts (10) was reached without obtaining valid data from the xdslcmd info --stats command.

I could increase the maximum value before the program exits, but it should NEVER take that many attempts to obtain the data as it's a relatively small amount after all.

It did manage to correctly obtain the data once in your log sample (at 18:50:48, 5th April):-

Code: [Select]

05/04/2014 18:50:48.75 - ONGOING-ISRUNNING-185048-187.TXT - In get_data(#01). *** This was included in data received:-  xdslcmd info --stats - (numbytes = 718)
05/04/2014 18:50:48.77 - ONGOING-ISRUNNING-185048-187.TXT - In get_data(#02). *** This was included in data received:-  xdslcmd info --stats - (numbytes = 1020)
05/04/2014 18:50:48.79 - ONGOING-ISRUNNING-185048-187.TXT - In get_data(#03). *** This was included in data received:-  xdslcmd info --stats - (numbytes = 344)
05/04/2014 18:50:48.81 - ONGOING-ISRUNNING-185048-187.TXT - **** - get_data() for --stats O.K..Status = 1, times in get_data() loop was 03

However, it had already run (& failed) at 05/04/2014 18:50:40 (8 seconds earlier).

It also ran again (& failed) at the normal on the minute scheduled time of 18:51:00


The questions have to be...........

What caused the program to run twice within 1 minute?

Why did it fail?


It may well be linked to your DIMM issue, which could be causing 'other' nasty side effects.


Later on, it ran (& failed) at 18:54:00 & another 8 seconds later at 18:54:08 (also failing).

You don't somehow have 2 tasks running, staggered by 8 seconds do you?


I think that once the DIMM issues have been permanently resolved would be the best time to revisit the failed logging issue (if it is indeed still present).

[Chrysalis]

I did manually run the program a few times when trying to diagnose.  So that is probably the reasoning for the timing.

Can I ask why you changed the system? as it previously worked ok.

Dimm issues were not present when I tested either, and are now probably resolved.

[Bald_Eagle1]

I did manually run the program a few times when trying to diagnose.  So that is probably the reasoning for the timing.

O.K. I understand.

Can I ask why you changed the system? as it previously worked ok.

The feedback I have receieved is that the new version works just fine, with users previously experiencing problems now not experiencing them.

I changed it because one or two users were experiencing'stuck' instances of HG612_stats.exe which would continue to be 'stuck' until manually terminating the process.

The solution was to apply a maximum number of retries to obtain valid data before cleanly exiting the program that otherwise could & did end up 'stuck' in an indefinite loop.

The issues with a 'stuck' program were:-

CPU usage could be up to 100% on some rare occasions, obviously causing a massive slowdown of the PC & actually causing more 'stuck' instances of the program.


This mainly affected users with slow PCs and/or using servers that would occasionally hog almost all the machine's resources (CPU & memory) or even users where their anti-virus would hog almost all the machine's resources when carrying out a full disk(s) scan.

Dimm issues were not present when I tested either, and are now probably resolved.

If that's the case, how's about trying the latest versions of ALL of my programs, along with RONSKI's latest GUI version again to see if the issue persists.
If it does, I'll increase the maximum number of retries (the retries do happen very quickly even on a very slow machine).

e.g. even with around 230 retries to grab the linediag data in chunks on my 'reasonable' spec PC, the time taken typically amounts to less than 2 seconds & linediag is by far the largest set of data obtained.
It also takes less than 2 seconds on an old & slow XP laptop that is used for remote monitoring.


The retries certainly won't slow a faster machine down as the program continues as soon as valid data is obtained.

[Chrysalis]

As far as I am aware I am using the latest of all programs, I am using a special gui ronski made which he built only a few days ago and your 2.1 programs, is there newer somewhere?

and yeah I was one of those complaining about the stuck hg612 process :p but mine got fixed after doing a win update heh.

is it possible the retries happen too quick and kick in cutting off a successful connection before it finishes?

login events shows this

Code: [Select]

Login TimeLen :


08/04/2014 22:45:02.38 - ONGOING-ISRUNNING-224500-835.TXT - *** In get_data_exit - Closing ERROR.LOG. Status = 1,
08/04/2014 22:45:02.44 -   Abnormal End of [HG612_stats.exe]
**********************************************************************************
from error.log

Code: [Select]

08/04/2014 22:46:00.283 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling - delayed by user setting of 0 seconds
08/04/2014 22:46:00.332 - HG612_current_stats.exe was NOT running
08/04/2014 22:46:00.332 - Temp File ONGOING-ISRUNNING-224600-062.TXT was created
08/04/2014 22:46:00.500 - malloc() O.K.
08/04/2014 22:46:00.500 - Initializing Winsock
08/04/2014 22:46:00.500 - WSAStartup() SUCCESSFUL!!!
08/04/2014 22:46:00.500 - Starting getaddrinfo()
08/04/2014 22:46:00.500 - getaddrinfo() O.K.
08/04/2014 22:46:00.500 - Starting socket()
08/04/2014 22:46:00.501 - socket() O.K.
08/04/2014 22:46:00.501 - Starting connect()
08/04/2014 22:46:00.501 - connect() O.K.
08/04/2014 22:46:00.613 - About to reply(xdslcmd info --stats)
08/04/2014 22:46:00.613 - reply(xdslcmd info --stats) O.K.
08/04/2014 22:46:00.631 - *** ERROR!!! - Now in get_data_exit as times_in_loop was 10. Status = 1.
08/04/2014 22:46:00.631 - Temp File GET_DATA_ERROR-224600-631.TXT was created
08/04/2014 22:46:00.740 - About to close(sockfd)
08/04/2014 22:46:00.740 - About to freeadddrinfo(res)
08/04/2014 22:46:00.740 - About to WSACleanup()
08/04/2014 22:46:00.783 - About to free(txbuf)
08/04/2014 22:46:00.827 - About to free(rxbuf)
08/04/2014 22:46:00.861 - ONGOING-ISRUNNING-224600-062.TXT DELETED
08/04/2014 22:46:00.876 - *** In get_data_exit - Abnormal end of HG612_stats.exe program, EXIT error code = 99. Status = 1.
08/04/2014 22:46:00.876 - *** In get_data_exit - Closing ERROR.LOG. Status = 1.
updated to these ones which had a newer date.

http://forum.kitz.co.uk/index.php?topic=13763.msg259413#msg259413

Same problem except the error log path is now not under the scripts folder.

[Bald_Eagle1]

I have now increased the retries to 30 for you to test (version attached).

I think something else might be wrong somewhere, as in the older versions there was no limit, yet you were still seeing 'stuck' instances & ONGOING_ISRUNNING files.


All the relevant event/error logs should now be in the folder named Event & Error Logs


The 2 most relevant debugging files for you to post snippets from would be these for now (it would help if you posted a few minutes worth of data from each):-

ONGOING_ERROR.LOG
ONGOING_ERROR.LOG_file_ERROR.TXT

[Chrysalis]

I updated but here is an idea.

can the retries etc. be made configurable, instead of hardcoded?

need 1000 retries?

Code: [Select]

08/04/2014 23:32:05.07 - ONGOING-ISRUNNING-233205-043.TXT - Start of [HG612_stats.exe]
08/04/2014 23:32:05.21 - ONGOING-ISRUNNING-233205-043.TXT - Immediately after ini_parse() - About to determine the OS version. ERROR.LOG status = 0,
08/04/2014 23:32:05.23 - ONGOING-ISRUNNING-233205-043.TXT - *** Windows version = [6.1.7601] ***
08/04/2014 23:32:05.25 - ONGOING-ISRUNNING-233205-043.TXT - In [HG612_stats.exe] - After obtaining the OS version. ERROR.LOG status = 0,
08/04/2014 23:32:05.28 - ONGOING-ISRUNNING-233205-043.TXT - ERROR.LOG successfully opened. Status = 1,
08/04/2014 23:32:05.37 - ONGOING-ISRUNNING-233205-043.TXT - ONGOING-ISRUNNING-233205-043.TXT created. Status = 1,
08/04/2014 23:32:05.52 - ONGOING-ISRUNNING-233205-043.TXT - There are 1 instances of HG612_stats.exe running. Status = 1,
08/04/2014 23:32:05.54 - ONGOING-ISRUNNING-233205-043.TXT - ** Continuing as there are only 1 instances of HG612_stats.exe running **. Status = 1,
08/04/2014 23:32:05.59 - ONGOING-ISRUNNING-233205-043.TXT - **** In expect("gin"),rxbuf includes Welcome Visiting Huawei, so COULD be a HG612 modem.
08/04/2014 23:32:05.60 - ONGOING-ISRUNNING-233205-043.TXT - **** expect("gin:") O.K. Status = 1.
08/04/2014 23:32:05.65 - ONGOING-ISRUNNING-233205-043.TXT - **** Reaching this point means logging in to the modem was successful. Status = 1,
08/04/2014 23:32:05.67 - ONGOING-ISRUNNING-233205-043.TXT - *** ERROR!!! - Now in get_data_exit as times_in_loop was 10. Status = 1,
08/04/2014 23:32:05.69 - ONGOING-ISRUNNING-233205-043.TXT - Temp File GET_DATA_ERROR-233205-680.TXT was created. Status = 1,
08/04/2014 23:32:05.78 - ONGOING-ISRUNNING-233205-043.TXT - About to close(sockfd). Status = 1,
08/04/2014 23:32:05.80 - ONGOING-ISRUNNING-233205-043.TXT - *** WSACleanup has completed.
08/04/2014 23:32:05.82 - ONGOING-ISRUNNING-233205-043.TXT - *** About to free(txbuf).
08/04/2014 23:32:05.83 - ONGOING-ISRUNNING-233205-043.TXT - *** txbuf has been freed.
08/04/2014 23:32:05.84 - ONGOING-ISRUNNING-233205-043.TXT - *** About to free(rxbuf).
08/04/2014 23:32:05.85 - ONGOING-ISRUNNING-233205-043.TXT - *** rxbuf has been freed.
08/04/2014 23:32:05.87 - ONGOING-ISRUNNING-233205-043.TXT - ONGOING-ISRUNNING-233205-043.TXT DELETED - Status = 1,
08/04/2014 23:32:05.90 - ONGOING-ISRUNNING-233205-043.TXT - ERROR.LOG successfully closed. Status = 0,
08/04/2014 23:32:05.91 - ONGOING-ISRUNNING-233205-043.TXT - Abnormal End of [HG612_stats.exe]

08/04/2014 23:33:05.06 - ONGOING-ISRUNNING-233305-041.TXT - Start of [HG612_stats.exe]
08/04/2014 23:33:05.19 - ONGOING-ISRUNNING-233305-041.TXT - Immediately after ini_parse() - About to determine the OS version. ERROR.LOG status = 0,
08/04/2014 23:33:05.20 - ONGOING-ISRUNNING-233305-041.TXT - *** Windows version = [6.1.7601] ***
08/04/2014 23:33:05.21 - ONGOING-ISRUNNING-233305-041.TXT - In [HG612_stats.exe] - After obtaining the OS version. ERROR.LOG status = 0,
08/04/2014 23:33:05.24 - ONGOING-ISRUNNING-233305-041.TXT - ERROR.LOG successfully opened. Status = 1,
08/04/2014 23:33:05.31 - ONGOING-ISRUNNING-233305-041.TXT - ONGOING-ISRUNNING-233305-041.TXT created. Status = 1,
08/04/2014 23:33:05.49 - ONGOING-ISRUNNING-233305-041.TXT - There are 1 instances of HG612_stats.exe running. Status = 1,
08/04/2014 23:33:05.50 - ONGOING-ISRUNNING-233305-041.TXT - ** Continuing as there are only 1 instances of HG612_stats.exe running **. Status = 1,
08/04/2014 23:33:05.55 - ONGOING-ISRUNNING-233305-041.TXT - **** In expect("gin"),rxbuf includes Welcome Visiting Huawei, so COULD be a HG612 modem.
08/04/2014 23:33:05.56 - ONGOING-ISRUNNING-233305-041.TXT - **** expect("gin:") O.K. Status = 1.
08/04/2014 23:33:05.62 - ONGOING-ISRUNNING-233305-041.TXT - **** Reaching this point means logging in to the modem was successful. Status = 1,
08/04/2014 23:33:05.64 - ONGOING-ISRUNNING-233305-041.TXT - In get_data(#20). *** This was included in data received:- xdslcmd info --stats - (numbytes = 1)
08/04/2014 23:33:05.65 - ONGOING-ISRUNNING-233305-041.TXT - In get_data(#21). *** This was included in data received:- xdslcmd info --stats - (numbytes = 542)
08/04/2014 23:33:05.67 - ONGOING-ISRUNNING-233305-041.TXT - In get_data(#22). *** This was included in data received:- xdslcmd info --stats - (numbytes = 554)
08/04/2014 23:33:05.68 - ONGOING-ISRUNNING-233305-041.TXT - In get_data(#23). *** This was included in data received:- xdslcmd info --stats - (numbytes = 848)
08/04/2014 23:33:05.69 - ONGOING-ISRUNNING-233305-041.TXT - In get_data(#24). *** This was included in data received:- xdslcmd info --stats - (numbytes = 115)
08/04/2014 23:33:05.71 - ONGOING-ISRUNNING-233305-041.TXT - **** - get_data() for --stats O.K..Status = 1, times in get_data() loop was 24
08/04/2014 23:33:05.73 - ONGOING-ISRUNNING-233305-041.TXT - After xdslcmd info --stats(), ERROR.LOG status = 1
08/04/2014 23:33:05.76 - ONGOING-ISRUNNING-233305-041.TXT - In get_data(#23). *** This was included in data received:- xdslcmd info --pbParams - (numbytes = 1)
08/04/2014 23:33:05.77 - ONGOING-ISRUNNING-233305-041.TXT - In get_data(#24). *** This was included in data received:- xdslcmd info --pbParams - (numbytes = 1046)
08/04/2014 23:33:05.78 - ONGOING-ISRUNNING-233305-041.TXT - *** ERROR!!! - Now in get_data_exit as times_in_loop was 24. Status = 1,
08/04/2014 23:33:05.81 - ONGOING-ISRUNNING-233305-041.TXT - Temp File GET_DATA_ERROR-233305-793.TXT was created. Status = 1,
08/04/2014 23:33:05.91 - ONGOING-ISRUNNING-233305-041.TXT - About to close(sockfd). Status = 1,
08/04/2014 23:33:05.93 - ONGOING-ISRUNNING-233305-041.TXT - *** WSACleanup has completed.
08/04/2014 23:33:05.95 - ONGOING-ISRUNNING-233305-041.TXT - *** About to free(txbuf).
08/04/2014 23:33:05.96 - ONGOING-ISRUNNING-233305-041.TXT - *** txbuf has been freed.
08/04/2014 23:33:05.98 - ONGOING-ISRUNNING-233305-041.TXT - *** About to free(rxbuf).
08/04/2014 23:33:06.00 - ONGOING-ISRUNNING-233305-041.TXT - *** rxbuf has been freed.
08/04/2014 23:33:06.01 - ONGOING-ISRUNNING-233305-041.TXT - ONGOING-ISRUNNING-233305-041.TXT DELETED - Status = 1,
08/04/2014 23:33:06.04 - ONGOING-ISRUNNING-233305-041.TXT - ERROR.LOG successfully closed. Status = 0,
08/04/2014 23:33:06.06 - ONGOING-ISRUNNING-233305-041.TXT - Abnormal End of [HG612_stats.exe]

08/04/2014 23:34:05.06 - ONGOING-ISRUNNING-233405-037.TXT - Start of [HG612_stats.exe]
08/04/2014 23:34:05.20 - ONGOING-ISRUNNING-233405-037.TXT - Immediately after ini_parse() - About to determine the OS version. ERROR.LOG status = 0,
08/04/2014 23:34:05.21 - ONGOING-ISRUNNING-233405-037.TXT - *** Windows version = [6.1.7601] ***
08/04/2014 23:34:05.22 - ONGOING-ISRUNNING-233405-037.TXT - In [HG612_stats.exe] - After obtaining the OS version. ERROR.LOG status = 0,
08/04/2014 23:34:05.25 - ONGOING-ISRUNNING-233405-037.TXT - ERROR.LOG successfully opened. Status = 1,
08/04/2014 23:34:05.32 - ONGOING-ISRUNNING-233405-037.TXT - ONGOING-ISRUNNING-233405-037.TXT created. Status = 1,
08/04/2014 23:34:05.44 - ONGOING-ISRUNNING-233405-037.TXT - There are 1 instances of HG612_stats.exe running. Status = 1,
08/04/2014 23:34:05.46 - ONGOING-ISRUNNING-233405-037.TXT - ** Continuing as there are only 1 instances of HG612_stats.exe running **. Status = 1,
08/04/2014 23:34:05.50 - ONGOING-ISRUNNING-233405-037.TXT - **** In expect("gin"),rxbuf includes Welcome Visiting Huawei, so COULD be a HG612 modem.
08/04/2014 23:34:05.52 - ONGOING-ISRUNNING-233405-037.TXT - **** expect("gin:") O.K. Status = 1.
08/04/2014 23:34:05.57 - ONGOING-ISRUNNING-233405-037.TXT - **** Reaching this point means logging in to the modem was successful. Status = 1,
08/04/2014 23:34:05.60 - ONGOING-ISRUNNING-233405-037.TXT - In get_data(#20). *** This was included in data received:- xdslcmd info --stats - (numbytes = 1)
08/04/2014 23:34:05.62 - ONGOING-ISRUNNING-233405-037.TXT - In get_data(#21). *** This was included in data received:- xdslcmd info --stats - (numbytes = 952)
08/04/2014 23:34:05.63 - ONGOING-ISRUNNING-233405-037.TXT - In get_data(#22). *** This was included in data received:- xdslcmd info --stats - (numbytes = 734)
08/04/2014 23:34:05.65 - ONGOING-ISRUNNING-233405-037.TXT - In get_data(#23). *** This was included in data received:- xdslcmd info --stats - (numbytes = 380)
08/04/2014 23:34:05.66 - ONGOING-ISRUNNING-233405-037.TXT - **** - get_data() for --stats O.K..Status = 1, times in get_data() loop was 23
08/04/2014 23:34:05.68 - ONGOING-ISRUNNING-233405-037.TXT - After xdslcmd info --stats(), ERROR.LOG status = 1
08/04/2014 23:34:05.70 - ONGOING-ISRUNNING-233405-037.TXT - In get_data(#23). *** This was included in data received:- xdslcmd info --pbParams - (numbytes = 1)
08/04/2014 23:34:05.71 - ONGOING-ISRUNNING-233405-037.TXT - In get_data(#24). *** This was included in data received:- xdslcmd info --pbParams - (numbytes = 917)
08/04/2014 23:34:05.72 - ONGOING-ISRUNNING-233405-037.TXT - In get_data(#25). *** This was included in data received:- xdslcmd info --pbParams - (numbytes = 129)
08/04/2014 23:34:05.74 - ONGOING-ISRUNNING-233405-037.TXT - *** ERROR!!! - Now in get_data_exit as times_in_loop was 25. Status = 1,
08/04/2014 23:34:05.76 - ONGOING-ISRUNNING-233405-037.TXT - Temp File GET_DATA_ERROR-233405-747.TXT was created. Status = 1,
08/04/2014 23:34:05.86 - ONGOING-ISRUNNING-233405-037.TXT - About to close(sockfd). Status = 1,
08/04/2014 23:34:05.89 - ONGOING-ISRUNNING-233405-037.TXT - *** WSACleanup has completed.
08/04/2014 23:34:05.90 - ONGOING-ISRUNNING-233405-037.TXT - *** About to free(txbuf).
08/04/2014 23:34:05.92 - ONGOING-ISRUNNING-233405-037.TXT - *** txbuf has been freed.
08/04/2014 23:34:05.94 - ONGOING-ISRUNNING-233405-037.TXT - *** About to free(rxbuf).
08/04/2014 23:34:05.96 - ONGOING-ISRUNNING-233405-037.TXT - *** rxbuf has been freed.
08/04/2014 23:34:05.97 - ONGOING-ISRUNNING-233405-037.TXT - ONGOING-ISRUNNING-233405-037.TXT DELETED - Status = 1,
08/04/2014 23:34:06.00 - ONGOING-ISRUNNING-233405-037.TXT - ERROR.LOG successfully closed. Status = 0,
08/04/2014 23:34:06.01 - ONGOING-ISRUNNING-233405-037.TXT - Abnormal End of [HG612_stats.exe]


Code: [Select]

08/04/2014 23:32:05.284 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling - delayed by user setting of 5 seconds
08/04/2014 23:32:05.349 - HG612_current_stats.exe was NOT running
08/04/2014 23:32:05.349 - Temp File ONGOING-ISRUNNING-233205-043.TXT was created
08/04/2014 23:32:05.545 - malloc() O.K.
08/04/2014 23:32:05.545 - Initializing Winsock
08/04/2014 23:32:05.547 - WSAStartup() SUCCESSFUL!!!
08/04/2014 23:32:05.547 - Starting getaddrinfo()
08/04/2014 23:32:05.547 - getaddrinfo() O.K.
08/04/2014 23:32:05.547 - Starting socket()
08/04/2014 23:32:05.547 - socket() O.K.
08/04/2014 23:32:05.547 - Starting connect()
08/04/2014 23:32:05.548 - connect() O.K.
08/04/2014 23:32:05.658 - About to reply(xdslcmd info --stats)
08/04/2014 23:32:05.658 - reply(xdslcmd info --stats) O.K.
08/04/2014 23:32:05.680 - *** ERROR!!! - Now in get_data_exit as times_in_loop was 10. Status = 1.
08/04/2014 23:32:05.680 - Temp File GET_DATA_ERROR-233205-680.TXT was created
08/04/2014 23:32:05.785 - About to close(sockfd)
08/04/2014 23:32:05.785 - About to freeadddrinfo(res)
08/04/2014 23:32:05.785 - About to WSACleanup()
08/04/2014 23:32:05.822 - About to free(txbuf)
08/04/2014 23:32:05.845 - About to free(rxbuf)
08/04/2014 23:32:05.880 - ONGOING-ISRUNNING-233205-043.TXT DELETED
08/04/2014 23:32:05.893 - *** In get_data_exit - Abnormal end of HG612_stats.exe program, EXIT error code = 99. Status = 1.
08/04/2014 23:32:05.893 - *** In get_data_exit - Closing ERROR.LOG. Status = 1.


08/04/2014 23:33:05.250 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling - delayed by user setting of 5 seconds
08/04/2014 23:33:05.309 - HG612_current_stats.exe was NOT running
08/04/2014 23:33:05.309 - Temp File ONGOING-ISRUNNING-233305-041.TXT was created
08/04/2014 23:33:05.510 - malloc() O.K.
08/04/2014 23:33:05.510 - Initializing Winsock
08/04/2014 23:33:05.511 - WSAStartup() SUCCESSFUL!!!
08/04/2014 23:33:05.511 - Starting getaddrinfo()
08/04/2014 23:33:05.511 - getaddrinfo() O.K.
08/04/2014 23:33:05.511 - Starting socket()
08/04/2014 23:33:05.511 - socket() O.K.
08/04/2014 23:33:05.511 - Starting connect()
08/04/2014 23:33:05.513 - connect() O.K.
08/04/2014 23:33:05.623 - About to reply(xdslcmd info --stats)
08/04/2014 23:33:05.623 - reply(xdslcmd info --stats) O.K.
08/04/2014 23:33:05.714 - get_data() O.K.
08/04/2014 23:33:05.714 - Modem in use = HG612
08/04/2014 23:33:05.714 - About to determine the xDSL mode
08/04/2014 23:33:05.714 - About to parse_stats()
08/04/2014 23:33:05.718 - parse_stats completed
08/04/2014 23:33:05.738 - VDSL2 mode detected so about to reply(xdslcmd info --pbParams)
08/04/2014 23:33:05.739 - reply(xdslcmd info --pbParams) O.K.
08/04/2014 23:33:05.793 - *** ERROR!!! - Now in get_data_exit as times_in_loop was 24. Status = 1.
08/04/2014 23:33:05.793 - Temp File GET_DATA_ERROR-233305-793.TXT was created
08/04/2014 23:33:05.914 - About to close(sockfd)
08/04/2014 23:33:05.914 - About to freeadddrinfo(res)
08/04/2014 23:33:05.914 - About to WSACleanup()
08/04/2014 23:33:05.956 - About to free(txbuf)
08/04/2014 23:33:05.983 - About to free(rxbuf)
08/04/2014 23:33:06.019 - ONGOING-ISRUNNING-233305-041.TXT DELETED
08/04/2014 23:33:06.031 - *** In get_data_exit - Abnormal end of HG612_stats.exe program, EXIT error code = 99. Status = 1.
08/04/2014 23:33:06.031 - *** In get_data_exit - Closing ERROR.LOG. Status = 1.


08/04/2014 23:34:05.256 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling - delayed by user setting of 5 seconds
08/04/2014 23:34:05.312 - HG612_current_stats.exe was NOT running
08/04/2014 23:34:05.312 - Temp File ONGOING-ISRUNNING-233405-037.TXT was created
08/04/2014 23:34:05.465 - malloc() O.K.
08/04/2014 23:34:05.465 - Initializing Winsock
08/04/2014 23:34:05.466 - WSAStartup() SUCCESSFUL!!!
08/04/2014 23:34:05.466 - Starting getaddrinfo()
08/04/2014 23:34:05.466 - getaddrinfo() O.K.
08/04/2014 23:34:05.466 - Starting socket()
08/04/2014 23:34:05.466 - socket() O.K.
08/04/2014 23:34:05.466 - Starting connect()
08/04/2014 23:34:05.467 - connect() O.K.
08/04/2014 23:34:05.579 - About to reply(xdslcmd info --stats)
08/04/2014 23:34:05.579 - reply(xdslcmd info --stats) O.K.
08/04/2014 23:34:05.669 - get_data() O.K.
08/04/2014 23:34:05.669 - Modem in use = HG612
08/04/2014 23:34:05.669 - About to determine the xDSL mode
08/04/2014 23:34:05.669 - About to parse_stats()
08/04/2014 23:34:05.672 - parse_stats completed
08/04/2014 23:34:05.687 - VDSL2 mode detected so about to reply(xdslcmd info --pbParams)
08/04/2014 23:34:05.687 - reply(xdslcmd info --pbParams) O.K.
08/04/2014 23:34:05.747 - *** ERROR!!! - Now in get_data_exit as times_in_loop was 25. Status = 1.
08/04/2014 23:34:05.747 - Temp File GET_DATA_ERROR-233405-747.TXT was created
08/04/2014 23:34:05.869 - About to close(sockfd)
08/04/2014 23:34:05.869 - About to freeadddrinfo(res)
08/04/2014 23:34:05.869 - About to WSACleanup()
08/04/2014 23:34:05.910 - About to free(txbuf)
08/04/2014 23:34:05.941 - About to free(rxbuf)
08/04/2014 23:34:05.975 - ONGOING-ISRUNNING-233405-037.TXT DELETED
08/04/2014 23:34:05.989 - *** In get_data_exit - Abnormal end of HG612_stats.exe program, EXIT error code = 99. Status = 1.
08/04/2014 23:34:05.989 - *** In get_data_exit - Closing ERROR.LOG. Status = 1.


08/04/2014 23:35:05.328 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling - delayed by user setting of 5 seconds
08/04/2014 23:35:05.428 - HG612_current_stats.exe was NOT running
08/04/2014 23:35:05.428 - Temp File ONGOING-ISRUNNING-233505-062.TXT was created
08/04/2014 23:35:05.627 - malloc() O.K.
08/04/2014 23:35:05.627 - Initializing Winsock
08/04/2014 23:35:05.628 - WSAStartup() SUCCESSFUL!!!
08/04/2014 23:35:05.628 - Starting getaddrinfo()
08/04/2014 23:35:05.628 - getaddrinfo() O.K.
08/04/2014 23:35:05.628 - Starting socket()
08/04/2014 23:35:05.631 - socket() O.K.
08/04/2014 23:35:05.631 - Starting connect()
08/04/2014 23:35:05.631 - connect() O.K.
08/04/2014 23:35:05.742 - About to reply(xdslcmd info --stats)
08/04/2014 23:35:05.742 - reply(xdslcmd info --stats) O.K.
08/04/2014 23:35:05.828 - get_data() O.K.
08/04/2014 23:35:05.828 - Modem in use = HG612
08/04/2014 23:35:05.828 - About to determine the xDSL mode
08/04/2014 23:35:05.828 - About to parse_stats()
08/04/2014 23:35:05.831 - parse_stats completed
08/04/2014 23:35:05.844 - VDSL2 mode detected so about to reply(xdslcmd info --pbParams)
08/04/2014 23:35:05.844 - reply(xdslcmd info --pbParams) O.K.
08/04/2014 23:35:05.899 - *** ERROR!!! - Now in get_data_exit as times_in_loop was 23. Status = 1.
08/04/2014 23:35:05.899 - Temp File GET_DATA_ERROR-233505-899.TXT was created
08/04/2014 23:35:06.188 - About to close(sockfd)
08/04/2014 23:35:06.188 - About to freeadddrinfo(res)
08/04/2014 23:35:06.188 - About to WSACleanup()
08/04/2014 23:35:06.237 - About to free(txbuf)
08/04/2014 23:35:06.271 - About to free(rxbuf)
08/04/2014 23:35:06.306 - ONGOING-ISRUNNING-233505-062.TXT DELETED
08/04/2014 23:35:06.324 - *** In get_data_exit - Abnormal end of HG612_stats.exe program, EXIT error code = 99. Status = 1.
08/04/2014 23:35:06.324 - *** In get_data_exit - Closing ERROR.LOG. Status = 1.


[Bald_Eagle1]

I have increased the max No. of retries to 100 for now as it seems that it takes around 24 or so attempts to grab valid data on your system, compared to the usual 2 or 3 attempts.

I suppose it could be that your modem is very busy uploading/downloading at the time or you are using a very fast PC.
i.e. it COULD be trying to obtain the data quicker than the modem can actually provide it.

I could add a time delay of say 1/4 second between retries that MIGHT allow more data to be obtained at each run through the loop or increase the number of retries or both options.


I have attached a new version for you to try that might work as a temporary fix.



However, I'd prefer to get to the actual root cause & deal with it 'properly'.



I have also attached a batch file that will run the program & log the screen output to a file named "HG612_stats.TXT" (stored in the Scripts folder).

Would you mind running it at say 30 seconds past the minute & attach the resulting text file for me to have a look at?

Included in the text file should be details of exactly what data was obtained during each run through the loop.
That information should help me to determine how best to deal with the issue.

The time taken to log the obtained data to the text file at each run through the loop might actually have the effect of slowing the process down sufficiently that not as many retries are needed.

It would also be very useful if you could provide snippets from the error logs from before you try the new program, when it runs each minute in the baclground, when you run the batch file & finally when it runs each minute in the background again.

[Chrysalis]

ok so it is now working, I will leave it for a short time, then give you 3+ mins of logs? then run the batch file in between scheduled runs? provide the log file for that and then normal logs afterwards?

my gut feeling is you are right in its running too fast on my rig.  Might be tough to hardcode this app to work well on slow and fast rigs.

[Bald_Eagle1]

Thanks for the feedback & agreement to provide some logs.

It shouldn't be too hard to code the program for slow/fast rigs accordingly, once I'm 100% sure where the isuse(s) lie.