5:33 pm PT,
the problem seems to be that either the data is suddenly stopped
being sent after 8000 lines, or perhaps that was all the data and no
"end of data" lineis being sent.

Works with other symbols (futures) that I have tried.

-steve

What interval of data are you pulling? I just pulled 24,000 records of 1 minute data on MSFT, 50,000 of tick data, 2955 of daily data and all didn't have any issue. You mention 8000 lines, so I assume you are pulling tick or minute data. Can you try to log out and back in to see if maybe its the server you are connected to?

---

Jay Froscheiser
DTN - Trading Markets

This problem is intermittent and continuing, so it is very hard to debug.
I started printing out all lines received from dtn, which slows things
down noticeably but sadly makes the problem much less frequent.

Here is an instance I was able to capture (the numbers are the line
numbers of data received from the historical request, the following
data is what dtn is sending):

downloading ES this morning,

13603:2005-12-30 13:10:00,1253.50,4,228374,1253.50,1253.75,0,0,0
13604:2005-12-30 13:10:00,1253.50,1,228370,1253.50,1253.75,0,0,0
13605:2005-12-30 13:10:00,1253.75,1,228369,1253.50,1253.75,0,0,0
13606:2005-12-30 13:10:00,1253.75,1,228369,1253.50,1253.75,0,0,0
13607:,1253.75,1,228369,1253.50,1253.75,0,0,0
13608:

from "feed stats" my ip is 66.112.156.226 port 60002

iqfeed version 4.0.0.2

-steve

Steve, I notice that there is no timestamp included on line 13607

Is this the only documented instance of this problem that you have or can you confirm if this is the pattern that the problem follows?

This looks like tic data. What command are you issuing to recieve the data? is it an HX and you are adding your own line numbers? or are you requesting the data via com using RequestTickHistory?

My software adds the line numbers before printing out.

I am using an HX and TCPIP from java.
I believe I have been having problems
with minute data as well but can't confirm that.

The software that receives these quotes was unchanged
at the time the problem started, and has been used for
years successfully.

Right the line is mangled. In other instances I have seen,
probably the large majority, the lines are not mangled,
but instead the last line sent is either missing the \r
before the \n or else has non-printing characters,
I can't tell since I just print out the line.

Steve,

This issue isn't specific to any one symbol correct? (you mentioned MSFT and ES in this thread) Have you seen it in other symbols too?

You mentioned in your previous post that it happens after 8000 data points. Does it ever happen before?

Can you provide more information about how you are utilizing the feed?

For example, how does your program run the history requests? Is it automated? Do you give it a list of symbols and it processes through them? Do you make repeated requests for the same symbols or does your program store/cache the data at some point?

If you make the same request again after the one that fails, do you get the same results or does it complete successfully?

The more information you can provide, the faster we will be able to track down where the problem lies.

Thanks,
Steve

The issue is not specific to the symbol.
It appears to happen more when more data is requested.

I cycle through a list of symbols and request day, minute, then tick
history, caching the results in a local text file.

The problem is fairly repeatable on my system, since almost 85%
of the time that I run my update procedure, the process will get stuck
at some point.

I recently added debugging code to save the most recent data before
such a data timeout. Here is the latest example, from YHOO.
I did a tick request , and after receiving 162000 lines without incident
I received the following lines and then no more:

-----------------------
2005-12-28 10:19:00,40.0500,400,2125060,40.0500,40.0500,0,0,0
2005-12-28 10:19:00,40.0600,200,2124660,40.0500,40.0700,0,0,0
2005-12-28 10:19:00,40.0600,200,2124460,40.0500,40.0700,0,0,0
2005-12-28 10:19:00,40.0600,100,2124260,40.0500,40.0700,0,0,0
2005-12-28 10:19:00,40.0600,200,2124160,40.0500,40.0700,0,0,0
2005-12-28 10:19:00,40.0600,200,2123960,40.0500,40.0700,0,0,0
2005-12-28 10:19:00,40.0600,500,2123760,40.0500,40.0700,0,0,0
2005-12-28 10:19:00,40.0600,100,1423052796,40.0500,40.0700,0,0,0
-----------------------

Notice the unusual total volume value.

in a susequent update, I requested DXH6 daily bars, and received no data.

in a subsequent update, I got a freeze after reading requesting tick
history for USH6 and after getting around 1000 ticks:

-----------------------
2006-01-03 14:51:00,114.31250,18,300742,114.31250,114.34375,0,0,0
2006-01-03 14:51:00,114.31250,24,300724,114.31250,114.34375,0,0,0
2006-01-03 14:51:00,114.31250,6,300700,114.28125,114.31250,0,0,0
2006-01-03 14:51:00,114.31250,5,300694,114.28125,114.31250,0,0,0
2006-01-03 14:51:00,114.31250,1,300689,114.28125,114.31250,0,0,0
2006-01-03 14:51:00,114.31250,14,300688,114.28125,114.31250,0,0,0
2006-01-03 14:51:00,114.31250,1,300674,114.28125,114.31250,0,0,0
2006-01-03 14:51:00,114.31250,18,300673,114.28125,114.31250,0,0,0
2006-01-03 14:51:00,114.31250,14,300655,114.28125,114.31250,0,0,0
2006-01-03 14:51:00,114.31250,1,300641,114.28125,114.31250,0,0,0
2006-01-03 14:51:00,114.31250,2,300640,114.28125,114.31250,0,0,0
2006-01-03 14:51:00,114.31250,32,300638,114.28125,114.31250,0,0,0
2006-01-03 14:51:00,114.31250,20,300606,114.28125,114.31250,0,0,0
2006-01-03 14:51:00,114.31250,30,300586,114.31250,114.34375,0,0,0
-----------------------

Here it appears that all data is correct, but the blank line indicating transmission
is complete was never sent, and I timed out after 12 seconds of waiting.

In a subsequent update, it froze after requesting @TYH6, and after reading
more than 2000 lines:

-----------------------
2006-01-03 14:36:00,109.546875,50,614912,109.531250,109.546875,0,0,0
2006-01-03 14:36:00,109.546875,2,614862,109.531250,109.546875,0,0,0
2006-01-03 14:36:00,109.531250,1,614860,109.531250,109.546875,0,0,0
2006-01-03 14:36:00,109.546875,1,614859,109.531250,109.546875,0,0,0
2006-01-03 14:36:00,109.546875,1,614858,109.531250,109.546875,0,0,0
2006-01-03 14:36:00,109.546875,30,614857,109.531250,109.546875,0,0,0
2006-01-03 14:36:00,109.546875,12,614827,109.531250,109.546875,0,0,0
2006-01-03 14:36:00,109.546875,12,614827,109.531250,109.546875,0,0,0
-----------------------

Note that the last two lines are exactly the same.

Hope this helps.

Here is another example that just happened:

after 3000 history lines for TYH6:

-----------------------
5950,109.562500,109.578125,0,0,0
2006-01-03 14:28:00,109.578125,50,595943,109.562500,109.578125,0,0,0
2006-01-03 14:28:00,109.578125,6,595893,109.562500,109.578125,0,0,0
2006-01-03 14:28:00,109.562500,2,595887,109.562500,109.578125,0,0,0
2006-01-03 14:28:00,109.562500,40,595885,109.562500,109.578125,0,0,0
2006-01-03 14:28:00,109.562500,100,595845,109.562500,109.578125,0,0,0
2006-01-03 14:28:00,109.562500,50,595745,109.562500,109.578125,0,0,0
2006-01-03 14:28:00,109.562500,2,595695,109.562500,109.578125,0,0,0
2006-01-03 14:28:00,109.562500,12,595693,109.562500,109.578125,0,0,0
2006-01-03 14:28:00,109.562500,5,595681,109.562500,109.578125,0,0,0
2006-01-03 14:28:00,109.562500,2,595676,109.562500,109.578125,0,0,0
2006-01-03 14:28:00,109.578125,8,595674,109.562500,109.578125,0,0,0
2006-01-03 14:28:00,109.562500,285215745,595674,109.562500,109.578125,0,0,0
-----------------------

Note the strange volume figure and the repeated total volume. And then the server
sends no more data.

Which version of IQFeed are you currently running?

If it is not the newest version (4.1.0.0 Beta), I would suggest trying this and see if you have better results. There have been some bugs identified and fixed specific to Large History requests between 4.0.0.2 and the 4.1.0.0 beta.

If this doesnt help, I believe we may need to dig into your app to see exactly what is going on here.

-Steve

I was using 4.0.0.2; I just upgraded to 4.1.0.0 beta.

I tested my update twice, and both times it worked without a hitch.

The caveat is that no requests were especially large since the
update had been done earlier. I'll get a better sense tomorrow
how things fare, but early results are encouraging.

fingers crossed,
-steve

Sadly, results of todays updates were not much better than before:

extracting historical tick data for SPX.XO, after 3000 tick bars:

2006-01-04 11:27:00,1271.850,0,0,0.000,0.000,0,0,0
2006-01-04 11:27:00,1271.890,0,0,0.000,0.000,0,0,0
2006-01-04 11:27:00,1271.920,0,0,0.000,0.000,0,0,0
2006-01-04 11:26:00,1271.970,0,0,0.000,0.000,0,0,0
2006-01-04 11:26:00,1272.030,0,0,0.000,0.000,0,0,0
2006-01-04 11:26:00,1272.010,0,0,0.000,0.000,0,0,0
2006-01-04 11:26:00,1272.000,0,0,0.000,0.000,0,0,0
2006-01-04 11:25:00,1272.040,0,0,0.000,0.000,0,0,0
2006-01-04 11:25:00,1272.040,0,0,0.000,0.000,0,0,0
2006-01-04 11:25:00,1272.080,0,0,0.000,0.000,0,0,0
2006-01-04 11:25:00,1272.040,0,0,0.000,0.000,0,0,0
2006-01-04 11:24:00,1271.990,0,0,0.000,0.000,0,0,0
,1271.990,0,0,67244.288,0.000,0,0,0


Note the mangled last line.


in a subsequent update of tick bars for @JYH6, after 4000 bars:
2006-01-05 09:27:00,0.8680,1,16717,0.8680,0.8681,0,0,0
2006-01-05 09:27:00,0.8680,1,16716,0.8680,0.8681,0,0,0
2006-01-05 09:27:00,0.8680,1,16715,0.8679,0.8680,0,0,0
2006-01-05 09:27:00,0.8679,1,16714,0.8679,0.8680,0,0,0
2006-01-05 09:27:00,0.8679,2,16713,0.8679,0.8680,0,0,0
2006-01-05 09:26:00,0.8680,5,16711,0.8679,0.8680,0,0,0
2006-01-05 09:26:00,0.8680,2,16706,0.8679,0.8680,0,0,0
2006-01-05 09:26:00,0.8679,6,16704,0.8678,0.8679,0,0,0
2006-01-05 09:25:00,0.8678,5,16698,0.8678,0.8679,0,0,0
2006-01-05 09:25:00,0.8678,2,16693,0.8678,0.8679,0,0,0
2006-01-05 09:25:00,0.8678,2,16691,0.8678,0.8679,0,0,0
2006-01-05 09:25:00,0.8678,1,16689,0.8678,0.8679,0,0,0
2006-01-05 09:25:00,0.8678,2,16688,0.8677,0.8678,0,0,0
2006-01-05 09:24:00,0.8677,1,16686,0.8677,0.8678,0,0,0
2006-01-05 09:24:00,0.8678,1,16685,0.8677,0.8678,0,0,0
2006-01-05 09:24:00,0.8677,2,16684,0.8677,0.8678,0,0,0
-----------------------

no obvious problems here, except the missing end of data blank line.


By the way two big hints seem to be that it is almost always tick
bars, and also that when I slowed things down by printing out every
line received, things improved alot. Of course, the tick bars relation might
just be the fact that tick history requests are much longer.

I know it is tempting to think the problem might be in my code,
and I fully admit that remote possibility, but:
* every bug I have previously reported turned out to be a bug in your code
* my code used to run great
* I am printing out basically what I receive from the request, and there
are some clear problems. If it was my code, it is highly likely that the
problem would appear in minute and day retrievals, not just tick.

-steve

How many different symbols are you dealing with?

I did some testing this morning and i was able to pull consecutive history requests for 500 different symbols with no errors. All requests were for the last 2 days of tic data (HT,<SYMBOL>,2;). This resulted in requests anywhere from 1200 - 160,000 data points with an average of about 5000 data points each.

would this be an accurate approximation fo the type of requests you are pulling? More? Less?
Edited by DTN_Steve_S on Jan 6, 2006 at 11:14 AM

I will print out my exact requests, and cache the exact data I get back, and then
post here.

-steve

the log of a typical series of requests is at:
http://www.softwaretruth.com/stevek/dtn/replenish4.log

You should open it in wordpad so that the \n are formatted correctly.

search for "--->". Every time I write out a request it appears
in this log as a cr followed by "---->what was written out"
and then another cr.
Otherwise all other text is exactly what was received from the history
socket.

In this file you can see that tick requests for YHOO and NQH6 ended
in a timeout (timeout on the read was set to 24 seconds), and
the last lines sent didn't look right. Also, if you look at the end of
the ESH6 tick request you will see some very strange truncation.

-steve

Thanks for the log.

I am now able to duplicate the issue using the same list of requests you are using.

Unfortunatly I have not figured out exactly what is causing the issue yet.

I'll let you know as soon as I find something.

Steve, Unfortunatly after digging into this a bit further I believe what I thought to be the same issue was simply a bug in my code causing my program to stop recieveing data rather than IQFeed stopping sending it.

Can you post a log from IQConnect for me?

see the developer documentation for info on turning on logging
Edited by DTN_Steve_S on Jan 19, 2006 at 02:14 PM

I'll try this a few more times, but it appears that turning on logging
slows things down CONSIDERABLY, which also has the side effect
of preventing this problem from appearing.

Judging from the speed and other factors,
It appears that you are logging by repeatedly opening the file,
writing a line, and closing the file.
Perhaps you could give me a version of iqfeed which keeps the
log file open until iqfeed is shut down. Then logging would
not appreciably slow down the application and hopefully
the problem would show itself.

-steve

You are correct, currently the file is closed after every write. I'll look into why this was done this way and see if we can get that changed.

I was unable to duplicate the problems with logging turned on, undoubtedly
due to the slow speed. Problem is still there are high speed.

I have since discovered a few more details of the issue:
The following is a snippet that shows what happened while
I was dowloading @ES tick data. After the characteristic
error that indicates trouble ahead, you actually send an
"ENDMSG" and then continue sending the original data mangled.
eventually you produce another ENDMSG when the last of the
mangled ES tick data is sent.

2006-01-11 10:53:00,1294.25,1,269685,1294.00,1294.25,0,0,0
2006-01-11 10:53:00,1294.25,1,269684,1294.00,1294.25,0,0,0
2006-01-11 10:53:00,1294.25,1,269683,1294.00,1294.25,0,0,0
2006-01-11 10:53:00,1294.25,2,201327730,1294.00,1294.25,0,0,0
,1294.25,2,201327730,1294.00,1294.25,0,0,0

!ENDMSG!
,1294.25,2,42537,1294.00,1294.25,0,0,0
,1294.25,16,42536,1294.00,1294.25,0,0,0
,1294.25,2,42520,1294.00,1294.25,0,0,0
,1294.25,1,42518,1294.00,1294.25,0,0,0

I have another example where the spurious ENDMSG is sent, without any
errors before it:

2006-01-11 10:06:00,1295.00,10,147945,1294.75,1295.00,0,0,0
2006-01-11 10:06:00,1295.00,1,147935,1294.75,1295.00,0,0,0
2006-01-11 10:05:00,1295.00,1,147934,1294.75,1295.00,0,0,0
2006-01-11 10:05:00,1295.00,100,147933,1294.75,1295.00,0,0,0

!ENDMSG!
2006-01-11 10:05:00,1295.00,10,717810,1294.75,1295.00,0,0,0
2006-01-11 10:05:00,1295.00,1,717800,1294.75,1295.00,0,0,0
2006-01-11 10:05:00,1292.25,6,717799,1294.75,1295.00,0,0,0

Again, it happened with @ES, which suggests that it is influenced by
the number of ticks requested since I request more ticks for @ES than
any other.
(32880 ticks in this case)..

The spurious ENDMSG is particularly annoying because it means that future
different history requests read the old @ES data that is sent after the ENDMSG.

P.s. I have no idea if it is related to this particular bug, but few programmers
are aware that when you read from a socket, you are not guaranteed to
get a full line sent to you. You might get half a line, a line and a half, or whatever.
Even if you ask for 100 bytes you might get less. If you are waiting for a full line,
you have to keep reading until you read a cr.

I know for a fact that IQFEED used to have this issue. An early version of
my software sent the history request in several pieces, i.e. write("HX"),
write(","), etc... and havoc ensued.

I have created a simple one file app that you can run to
see the problem. The problems have only occurred with the
HX request, and definitely seem to be triggered by large requests.

You will have to edit the file to add in my or your password and app name.

see:

http://direct.softwaretruth.com:8001/stevek/dtn/DtnControllerSimple.java

-steve

Another reason for slow performance could be the virus scanner. I'm running Mcafee. When I turned it off, logging ran faster because the file was not being scanned on each close.

It might be good to do a flush if you don't do a close so that the latest data is available for other programs to use as the file is being appended.

Just wondering if you were still pursuing this problem.....

-steve

Steve - Sorry for not replying to this sooner.

I can see that the logging does cause this to slow down to a very large extent (about 10times slower with logging turned on). I hadnt seen it happen to this extent prior to running your program.

On the subject of the History requests. I am still not able to duplicate this issue internally, even using your example app and turning all file output off (in IQConnect and in your app) to make it process the request list as quick as possible. It still returns every request completely with no socket timeouts.

To run through the list of 39 requests in your app it consistantly takes right around 125s to finish.

This coupled with the fact that this program was unaltered when it stopped working makes me lead towards an outside factor causing the issues. Have you tried to run this from a different pc or if possible a different location (to rule out possible network issues)?

I spent alot of time developing that sample app for you, so I want
to make sure that you ran it in a way that would show you the
problem.

Specifically, if you run it from a console window, or within a debugging
environment that shows you the "std output", then you would have
to scan the output looking for lines that look like:

Error: Found 47 lines that starts with ','

or

java.net.SocketTimeoutException: Read timed out

Of course, if you turned off my printouts then you would not see these errors.
My printouts are an less than trivial amount of time, so there is no benefit to
turning them off.

If you run the app 4 times and get no error lines printed out, then that would
be a sign that we have different environments, since I get errors (in different
places) 9 times out of 10.

In case it depends on the server, it looks like my current connection is to
66.112.156.221 port 60002, version 4.1.0.0
I am using logLevel 1

Also, no amount of network issues could make your program send
extraneous !ENDMSG! lines, right?

I had only disabled the file output. It would still print out the error messages to the console window. The reasoning behind this is because the issue is greatly affected by how quickly the commands are sent. I am directly connected to the servers here and wasn't seeing any issues with them enabled and I was trying to get the program to run as quickly as possible.

I renabled the output in your program this morning and ran it a few more times and am still unable to duplicate the error you are getting with the connection timeouts or bad data.

I did run into an issue this morning where your program reports that it recieves Data after an !ENDMSG!. The instance I came across is related to a different issue reported by stargrazer here: http://forums.iqfeed.net/index.cfm?page=topic&topicID=922

It appears that when some requests return no data, an extra "unknown error" message is being sent. Your program is detecting this extra error message as data after an endmsg. However this doesn't coincide with the issue you were having when you reported the extra lines after an endmessage above.

-edit to add-

I reran your original code (since I had made alterations during my testing) to remove as many possible problems that could arise from our testing conditions.

I had to make two alterations to your code to get it to compile and run properly.

I dont believe either of these could be causing the issues but I am by no means proficient in Java, so in the interest of being thorough, I figured I would add it.

the first is that I removed your package declaration

package nosticator.quotes.dtn;

and second, i removed the check for if IQConnect already running.

 		if (iqfeedRunning())
		{
			System.out.println("IQFeed is already running.  Please stop it and try again.");
			return;
		}

Is the 2 minutes from start to finish that I am seeing close to the same time frame it takes for the program to run on your end?
Edited by DTN_Steve_S on Jan 23, 2006 at 10:21 AM

This weekend I got unexpected error messages when I was trying to retrieve 1 minute interday data during the weekend. I have not tried thinly traded issues on weekdays to see if this same error comes in. To get back historical data I had to increase the number of bar days because I was trying to get it during a non market day.

The following return errors are from a single query for 1 minute data:

!ERROR! !NONE!
!ERROR! Unknown Error.


These errors are not too helpful outside of the fact they in deed give a response to a query avoiding a timeout situation. In the case shown there are three !xxxx! messages that one must contend with. The enumerated part 'Unknown Error' is really not helpful in this response.

Desired: One !ERROR! response that is meaningful for the query given. Should be the same for any query - no multiple error messages, unless this is going to be a known documented protocol.

Thanks!

David

---

IQXP Software
http://www.iqxp.com

LiveWire Update Service
PO Box 1417
Fairfield, IA 52556
641-472-8393
http://www.livewire-cablesoft.com/

David, I agree that the unknown error is not helpful at all except to indicate there was an error. Theoreticly, one should never recieve this error unless they happen to make a request that returns an unexpected error that isnt accounted for.

A valid request that returns no data (as the case is here) SHOULD be returning only

!ERROR! !NONE!

but for some reason the extra

!ERROR! Unknown Error.

Is also being sent.

It is being looked into currently, however, until this fix is implemented, you should be able to work around this fairly easily programaticly

Great, I am glad that you were able to duplicate the
duplicate !ENDMSG! error.
If you look in DtnControllerSimpleLog.txt
which should be in the root directory from which you ran DtnControllerSimple.java
is. If you renable the partof the code that saves output that is received,
then you can search for ENDMSG. When you find the extraneous one,
which is evident because it is followed by more data, and not by another request,
you may also see that the line before the ENDMSG is garbled.

I don't see the relationship to the other thread that you linked
to, since these requests are returning data, and all requests
I do return some data.

To answer your question, the 2 minutes the sample program takes
is similar to the time it takes me. Here are two sample
runs for me:

2 min 42 sec

2 min 15 sec

and errors each time

I am actually not seeing the same issue you are with the extra endmsg.

I am seeing the issue in the other thread (but with your code).

The HM,@QMG6,2,1; command in your code is currently returning no data.

as a result of the bug in the other post it is triggering your error.

When I look at the log file generated, It shows the data exactly as I would expect it to (with the extra error message sent by IQConnect)



I am going to do some more testing on this on a remote location to see if I can duplicate it when not connected to the servers directly.
Edited by DTN_Steve_S on Jan 23, 2006 at 05:01 PM