Strange scripting behaviour

ASF · November 13, 2018, 3:06am

Hi all,

I’ve got a script which generates four .txt files, and logs data to each of them using a system.tag.queryTagHistory function (side note: I know there are much better ways to generate a report, but this customer has a validated procedure in place that involves .txt files, and apparently updating their procedure is too difficult).

Essentially, my script does the following

generate a .txt file with a header
get min, max and average values for two tags over a set period, returning a dataset
from each row of the dataset, construct a line of text with timestamp, and min/max/average for each tag
append the line of text to the file
append a footer to the file and close it

At a set time each day, I call this script four times with a different set of tag values for each.
At least 75% of the time, one or more (usually all four) files will abruptly stop being appended to halfway through the exact same timestamp. As in, half of the timestamp gets printed, and then nothing more. No more values, no footer.

Then, I wait. Around two minutes later, the files will “magically” have the remaining data and the footer appended. Even stranger is that if I call this script again with a new date range, it will fix the previous files immediately. The previous files will get the rest of their data and the footer added in as normal, while the new files are now incomplete, for a couple of minutes at least.

My current workaround is just to wait half an hour after generating the files before I send them to the printer. But my eye is twitching at the strangeness of it all, and I don’t like unexplained quirks like this.

I’m at a loss as to how to troubleshoot. Any ideas?

witman · November 13, 2018, 5:27am

Post your code if you can; much easier to troubleshoot code than abstract summaries of it.

ASF · November 13, 2018, 9:45pm

[code]#Log data to text file
def printToFile(fileName, fileHeader, tagPath1, tagPath2, header1, header2, startTime, endTime, intervalMins):
#Set up file parameters
filePath = ‘C:/—removed----/’ + system.date.format(endTime, ‘yyyy-MM-dd HH-mm’) + ’ ’ + fileName + ‘.txt’
fileTimestamp = ‘Report generated: ’ + system.date.format(system.date.now(), ‘EEEE, d MMMM YYYY, hh:mm:ss a’)
fileHeader = ‘’’ [client name removed]
[project name removed] Data Log
±-------------------------------------------------------------------------------+
|’’’+fileHeader.center(80)+’’’|
|’’’+fileTimestamp.center(80)+’’’|
±-------------------------------------------------------------------------------+

#create file and write header
file = open(filePath, 'w+')
file.write(fileHeader)

try:
	#get 'minimum' dataset
	minDataSet = system.tag.queryTagHistory(
		paths = [tagPath1, tagPath2],
		startDate = startTime,
		endDate = endTime,
		aggregationMode = 'Minimum',
		intervalMinutes = intervalMins,
		ignoreBadQuality = False,
		timeout = 10000
		)
		
	#get 'maximum' dataset
	maxDataSet = system.tag.queryTagHistory(
		paths = [tagPath1, tagPath2],
		startDate = startTime,
		endDate = endTime,
		aggregationMode = 'Maximum',
		intervalMinutes = intervalMins,
		ignoreBadQuality = False,
		timeout = 10000
		)

	#get 'average' dataset
	avgDataSet = system.tag.queryTagHistory(
		paths = [tagPath1, tagPath2],
		startDate = startTime,
		endDate = endTime,
		aggregationMode = 'Average',
		intervalMinutes = intervalMins,
		ignoreBadQuality = False,
		timeout = 10000
		)

	#for each row in the returned datasets, log the timestamp, min, max and average to the file	
	for row in range(avgDataSet.getRowCount()):
		timestamp = system.date.format(avgDataSet.getValueAt(row, 0), 'YYYY-MM-dd HH:mm:ss')
		newRow = '|' + timestamp + ' |'
		for col in range(1, avgDataSet.getColumnCount()):
			minVal = '%.1F' % minDataSet.getValueAt(row, col)
			maxVal = '%.1F' % maxDataSet.getValueAt(row, col)
			avgVal = '%.1F' % avgDataSet.getValueAt(row, col)
			newRow = newRow + minVal.rjust(7) + '   ' + maxVal.rjust(7) + '   ' + avgVal.rjust(7) + '  |'
		file.write(newRow + '\n')
	
	#append fileFooter and close file
	fileFooter = '''+--------------------+-----------------------------+-----------------------------+
End of Report
	
  * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * *
  *                                                                             *
  *  Checked By (Print Name): _________________________________                 *
  *                                                                             *
  *              (Signature): _________________________________                 *
  *                                                                             *
  *                   (Date): _________________________________                 *
  *                                                                             *
  *                                                                             *
  *                        OK     DEVIATION REPORT   (circle as applicable)     *
  *                                                                             *
  * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * *'''
	file.write(fileFooter)
except:
	try:
		system.gui.errorBox("Error printing " + fileName + ' data log',"Error")
	except:
		print "Error printing " + fileName + ' data log'
file.close()
return filePath[/code]

Please excuse the flashbacks to 1989 and dot matrix printers

What has me the most confused is where it stops. Each time it’s at the exact same timestamp: I’m logging midnight to midnight at 15 minute intervals and it stops at 22:00:00. It prints the “|” character, the timestamp, the space after it, but not the following “|” character.

timestamp = system.date.format(avgDataSet.getValueAt(row, 0), 'YYYY-MM-dd HH:mm:ss') newRow = '|' + timestamp + ' |'
…should set newRow to e.g. “|2018-11-14 22:00:00 |”. Then the following lines should add each data point. Then it should print the whole line to the text file. I’d be less confused if it printed the whole timestamp but no values - maybe there was a problem retrieving values. I’d be less confused if it printed no timestamp at all, maybe there was something up with the timestamp or the script otherwise got hung up. But to get to the line where it starts printing to the text file indicates that it must have successfully executed the newRow = timestamp and the for loop to get all of the column data - only to crash out halfway through printing it to the file, in the exact same spot each time.

And then of course, to have it fix itself a couple of minutes later is just completely odd.

witman · November 13, 2018, 10:08pm

The good old days of dot matrix It’s easier to understand what’s happening with the code sample, though I can’t say anything jumps out at me. Shot in the dark: given this seems to happen at 22:00:00 only, is there something else happening at 22:00:00 that might bog down java or the file system?

pturmel · November 13, 2018, 10:10pm

Consider writing everything to a StringBuilder and then writing to the file in one go. Instead of leaving a file handle open while retrieving the data.

ASF · November 13, 2018, 11:04pm

It’s not 22:00:00 specifically - if I use a different start and end time it craps out in exactly the same spot, only go course the timestamp is different. E.g. from 12pm to 12pm it breaks at 10:00:00.

Using a StringBuilder type method is a good idea, although I didn’t think there was such a thing specifically in python. A quick google throws up a few related options, do you have a particular method in mind or a link you can point me to?

PGriffith · November 13, 2018, 11:04pm

Because this is a Jython environment, you can use Java methods directly:

from java.lang import StringBuilder
sb = StringBuilder()
sb.append("some text")
sb.append("some more text")
finalString = sb.toString()

witman · November 13, 2018, 11:10pm

So rather than relating to a specific time, it sounds like it may relate to the size of the file. In other words, if you added more characters before this, would it stop that many characters earlier?

ASF · November 14, 2018, 2:05am

Thanks for the tips.

I’ve just had to package the servers up ready to go on a plane to site, so I’ll have to try it out next week and report back.

pphillips · November 14, 2018, 10:35pm

There is a statement in the Jython Library documentation under 5.9 File Objects:

Under the file.write(str) - "Due to buffering, the string may not actually show up in the file until the flush() or close() method is called."

You are obviously calling the file.close() method, but what you are describing certainly sounds like data in a buffer that is not completing the write until the next time the routine is called.

witman · November 14, 2018, 10:44pm

Yes, it does. close() is the first thing I looked for in posted code. flush() may be worth a try. Where it stops probably has to do with sizeof what's left in buffer (not enough to push it out in a hurry) rather than size of what's in file so far.

ASF · November 23, 2018, 2:18am

Thanks for the advice all. Using a StringBuilder works perfectly.