Timer Script Problem

gljuk · March 5, 2019, 8:26am

Hello!

Thought ewould not make a new thread and write here instead.
We are using Ignition 7.6.7
It is all fine, but we had to add one Gateway timer script to connect to mailbox and download all the mails. The problem is that after some time (days or even weeks), the script just stops working. For debugging purposes i have added logging the events to a file. The results are quite interesting:

Summary

2019-03-05 10:01:36,976 INFO Logging started
2019-03-05 10:01:44,936 INFO Started to collect data
2019-03-05 10:02:33,309 INFO Logging started
2019-03-05 10:02:33,309 INFO Logging started
2019-03-05 10:02:34,786 INFO Started to collect data
2019-03-05 10:02:34,786 INFO Started to collect data
2019-03-05 10:03:33,309 INFO Logging started
2019-03-05 10:03:33,309 INFO Logging started
2019-03-05 10:03:33,309 INFO Logging started
2019-03-05 10:03:34,015 INFO Started to collect data
2019-03-05 10:03:34,015 INFO Started to collect data
2019-03-05 10:03:34,015 INFO Started to collect data
2019-03-05 10:04:33,309 INFO Logging started
2019-03-05 10:04:33,309 INFO Logging started
2019-03-05 10:04:33,309 INFO Logging started
2019-03-05 10:04:33,309 INFO Logging started
2019-03-05 10:04:33,997 INFO Started to collect data
2019-03-05 10:04:33,997 INFO Started to collect data
2019-03-05 10:04:33,997 INFO Started to collect data
2019-03-05 10:04:33,997 INFO Started to collect data
2019-03-05 10:05:33,311 INFO Logging started
2019-03-05 10:05:33,311 INFO Logging started
2019-03-05 10:05:33,311 INFO Logging started
2019-03-05 10:05:33,311 INFO Logging started
2019-03-05 10:05:33,311 INFO Logging started
2019-03-05 10:05:33,954 INFO Started to collect data
2019-03-05 10:05:33,954 INFO Started to collect data
2019-03-05 10:05:33,954 INFO Started to collect data
2019-03-05 10:05:33,954 INFO Started to collect data
2019-03-05 10:05:33,954 INFO Started to collect data
2019-03-05 10:06:33,311 INFO Logging started
2019-03-05 10:06:33,311 INFO Logging started
2019-03-05 10:06:33,311 INFO Logging started
2019-03-05 10:06:33,311 INFO Logging started
2019-03-05 10:06:33,311 INFO Logging started
2019-03-05 10:06:33,311 INFO Logging started
2019-03-05 10:06:34,055 INFO Started to collect data
2019-03-05 10:06:34,055 INFO Started to collect data
2019-03-05 10:06:34,055 INFO Started to collect data
2019-03-05 10:06:34,055 INFO Started to collect data
2019-03-05 10:06:34,055 INFO Started to collect data
2019-03-05 10:06:34,055 INFO Started to collect data

You see, first it behaves just like it should, one logger entry at a time. On the second execution, there are two entries, then more and more. It seems that each time the new thread is started, but the old thread continues to be executed.

The Timer script looks next:

Summary

import datetime
import email
from email.header import Header
import imaplib
import mailbox
import time
subjects = []
import logging
try:
logger = logging.getLogger(‘myapp’)
hdlr = logging.FileHandler(‘C:/myapp.log’)
formatter = logging.Formatter(’%(asctime)s %(levelname)s %(message)s’)
hdlr.setFormatter(formatter)
logger.addHandler(hdlr)
logger.setLevel(logging.INFO)

#logger.error('We have a problem')
logger.info('Logging started')

except Exception, e:
logger = logging.getLogger(‘myapp’)
logger.error(‘We have a problem with logging’)
try:
EMAIL_ACCOUNT = ‘ee’
PASSWORD = ‘aaa’
mail = imaplib.IMAP4_SSL(‘mail.server’)
mail.login(EMAIL_ACCOUNT, PASSWORD)
mail.list()
mail.select(‘inbox’)
result, data = mail.uid(‘search’, None, “ALL”) # (ALL/UNSEEN)
i = len(data[0].split())
logger.info(‘Started to collect data’)
for x in range(i):
latest_email_uid = data[0].split(’ ‘)[x]
result, email_data = mail.uid(‘fetch’, latest_email_uid, ‘(RFC822)’)
# result, email_data = conn.store(num,’-FLAGS’,’\Seen’)
# this might work to set flag to seen, if it doesn’t already
raw_email = email_data[0][1]
raw_email_string = unicode(raw_email.decode(‘utf-8’))
email_message = email.message_from_string(raw_email_string)
# Header Details
date_tuple = email.utils.parsedate_tz(email_message[‘Date’])
if date_tuple:
local_date = datetime.datetime.fromtimestamp(email.utils.mktime_tz(date_tuple))
local_message_date = “%s” %(str(local_date.strftime("%a, %d %b %Y %H:%M:%S")))
email_from = unicode(email.header.make_header(email.header.decode_header(email_message[‘From’])))
email_to = unicode(email.header.make_header(email.header.decode_header(email_message[‘To’])))
subject = unicode(email.header.make_header(email.header.decode_header(email_message[‘Subject’])))
for part in email_message.walk():
if part.get_content_type() == “text/plain”:
body = part.get_payload(decode=True)
#print “From: %s\nTo: %s\nDate: %s\nSubject: %s\n” %(email_from, email_to,local_message_date, subject) # body.decode(‘utf-16’)
system.db.runPrepUpdate(“INSERT INTO test_table (text, time) VALUES (?,now())”,[body])
try:
comma_id = body.index(":")
object_name = body[0:comma_id]
object_name = object_name.replace(""","")
system.tag.writeToTag(“EMAIL_PUMPLA/” + object_name + “/Name”,0)
system.tag.writeToTag(“EMAIL_PUMPLA/” + object_name + “/Name”,object_name)
except Exception, e:
logger.info(str(e))
pass
else:
continue

mail.select('Inbox')
typ, data = mail.search(None, 'ALL')
for num in data[0].split():
	mail.store(num, '+FLAGS', '\\Deleted')
mail.expunge()
mail.close()
mail.logout()

except Exception, e:
logger.info(str(e))
#logger = getLogger(“TimerScriptTask”)
#logger.errorf(“Test:Could not run email parsing script”)
mail.close()
mail.logout()
pass

Any opinions?
Thank you!

gljuk · March 5, 2019, 12:57pm

We have figured out, that these multiple records started to occur because of logging object not being shut down properly.
logger.close() or logger.shutdown() solves the problem.

Now getting correct behaviour with each row being recorded only once. Still got script freezing problems. Will see.
Thanks

update: seems, it was ok with our testing version of 8.0, but not with client’s 7.6.7

update 2: closing logging did not solve any problem.

nminchin · March 13, 2019, 4:40am

You should copy your code into a code block, as it’s difficult to read as standard text with no indenting.

gljuk · March 15, 2019, 8:21am

Made more research. Today had the same problem. The scripts hanged. Gateway shows “2019-03-15 00:14” as last execution time. Now it is ‘2019-03-15 10:19’. We have memory tag with executions counter. It freezed. All other scripts were working fine. Console log gives no info at all about the situation. Google found some results about python’s imap_ssl lib causing the problem. It hangs without exeption, just like our case.
Ideas: can we somehow restart the script from other thread? Or maybe restart all the gateway scripts by event or by timer? Kind a watchdog.

Summary

import datetime
import email
from email.header import Header
import imaplib
import mailbox
import time
subjects = []


try:
	#system.db.runUpdateQuery("INSERT INTO test_table_errorlog (text) VALUES ('STARTING EXECUTION')")
	EMAIL_ACCOUNT = 'email_account'
	PASSWORD = 'password'
		
	mail = imaplib.IMAP4_SSL('mail.server')
	mail.debug = 4
	mail.login(EMAIL_ACCOUNT, PASSWORD)
	mail.list()
	mail.select('inbox')
	result, data = mail.uid('search', None, "ALL") # (ALL/UNSEEN)
	i = len(data[0].split())
	for x in range(i):
		latest_email_uid = data[0].split(' ')[x]
		result, email_data = mail.uid('fetch', latest_email_uid, '(RFC822)')
		raw_email = email_data[0][1]
		raw_email_string = unicode(raw_email.decode('utf-8'))
		email_message = email.message_from_string(raw_email_string)
	
		# Header Details
		date_tuple = email.utils.parsedate_tz(email_message['Date'])
		if date_tuple:
			local_date = datetime.datetime.fromtimestamp(email.utils.mktime_tz(date_tuple))
			local_message_date = "%s" %(str(local_date.strftime("%a, %d %b %Y %H:%M:%S")))
		email_from = unicode(email.header.make_header(email.header.decode_header(email_message['From'])))
		email_to = unicode(email.header.make_header(email.header.decode_header(email_message['To'])))
		subject = unicode(email.header.make_header(email.header.decode_header(email_message['Subject'])))
		for part in email_message.walk():
			if part.get_content_type() == "text/plain":
				body = part.get_payload(decode=True)
				#print "From: %s\nTo: %s\nDate: %s\nSubject: %s\n" %(email_from, email_to,local_message_date, subject) # body.decode('utf-16')
				system.db.runPrepUpdate("INSERT INTO test_table (text, time) VALUES (?,now())",[body])
				try:
					comma_id = body.index(":")
					object_name = body[0:comma_id]
					object_name = object_name.replace("\"","")
					system.tag.writeToTag("EMAIL_PUMPLA/" + object_name + "/Name",0)
					system.tag.writeToTag("EMAIL_PUMPLA/" + object_name + "/Name",object_name)
								
					if body.find("DI1") > 0:
						system.tag.writeToTag("EMAIL_PUMPLA/" + object_name + "/Alarm_TOITEPINGE",int(body[body.find("DI1")+4:body.find("DI1")+5]))
					
					if body.find("DI2") > 0:
						system.tag.writeToTag("EMAIL_PUMPLA/" + object_name + "/Alarm_TURVAHAIRE",int(body[body.find("DI2")+4:body.find("DI2")+5]))
					
					if body.find("DI3") > 0:
						system.tag.writeToTag("EMAIL_PUMPLA/" + object_name + "/Alarm_KORGENIVOO",int(body[body.find("DI3")+4:body.find("DI3")+5]))
					
					if body.find("DI4") > 0:
						system.tag.writeToTag("EMAIL_PUMPLA/" + object_name + "/Alarm_P1_HAIRE",int(body[body.find("DI4")+4:body.find("DI4")+5]))
						
					if body.find("DI5") > 0:
						if int(float(body[body.find("DI5")+4:body.find("DI5")+6])) < 12:
							system.tag.writeToTag("EMAIL_PUMPLA/" + object_name + "/Alarm_P2_HAIRE",0)
						else:
							system.tag.writeToTag("EMAIL_PUMPLA/" + object_name + "/Alarm_P2_HAIRE",1)
								
					if body.find("DI6") > 0:
						if int(float(body[body.find("DI6")+4:body.find("DI6")+6])) < 12:
							system.tag.writeToTag("EMAIL_PUMPLA/" + object_name + "/Alarm_RESERV",0)
						else:
							system.tag.writeToTag("EMAIL_PUMPLA/" + object_name + "/Alarm_RESERV",1)
					
					if body.find("RSSI") > 0:
						system.tag.writeToTag("EMAIL_PUMPLA/" + object_name + "/RSSI",int(body[body.find("RSSI")+5:body.find("RSSI")+8]))
				except Exception, e:
					system.tag.writeToTag("EMAIL_PUMPLA/ZZscript_error_count",(system.tag.getTagValue("EMAIL_PUMPLA/ZZscript_error_count")+1))
					system.db.runUpdateQuery("INSERT INTO test_table_errorlog (text) VALUES ('%s')" %(str(e).replace("'","-")))
					pass
			else:
				continue
	
	mail.select('Inbox')
	typ, data = mail.search(None, 'ALL')
	for num in data[0].split():
		mail.store(num, '+FLAGS', '\\Deleted')
	mail.expunge()
	mail.close()
	mail.logout()
	
	#system.db.runUpdateQuery("INSERT INTO test_table_errorlog (text) VALUES ('SUCCESSFUL EXECUTION')")
except Exception, e:
	system.tag.writeToTag("EMAIL_PUMPLA/ZZscript_error_count",(system.tag.getTagValue("EMAIL_PUMPLA/ZZscript_error_count")+1))
	system.db.runUpdateQuery("INSERT INTO test_table_errorlog (text) VALUES ('%s')" %(str(e).replace("'","-")))
	pass
system.tag.writeToTag("EMAIL_PUMPLA/ZZscript_execution_count",(system.tag.getTagValue("EMAIL_PUMPLA/ZZscript_execution_count")+1))

Thanks.