search

test-fullautomation / robotframework

Generic automation framework for acceptance testing and RPA
http://robotframework.org
Apache License 2.0
1 stars 0 forks source link

threading: order of log entries #82

Closed HolQue closed 3 months ago

HolQue commented 5 months ago

Hi Cuong,

I have an issue with the order of log entries in debug log file in case of keywords implemented in an own keyword library, are executed as thread.

The keywords are used to communicate with the BITS-Platform based on an TCP/IP connection.

The test setup is:

This is the test code in robot file

rf.extensions.pretty_print    ============== starting kw_1
THREAD    KW_1     False
   rf.extensions.pretty_print    ============== kw_1 started
   bitsplatform.kw_1
   rf.extensions.pretty_print    ============== kw_1 ended
END
sleep    4s

rf.extensions.pretty_print    ============== starting kw_2
THREAD    KW_2     False
   rf.extensions.pretty_print    ============== kw_2 started
   bitsplatform.kw_2
   rf.extensions.pretty_print    ============== kw_2 ended
END
sleep    3s

rf.extensions.pretty_print    ============== starting kw_3
THREAD    KW_3     False
   rf.extensions.pretty_print    ============== kw_3 started
   bitsplatform.kw_3
   rf.extensions.pretty_print    ============== kw_3 ended
END

rf.extensions.pretty_print    ============== waiting 30 s
sleep    30s

rf.extensions.pretty_print    ============== StopListenerThread
bitsplatform.StopListenerThread
sleep    3s

rf.extensions.pretty_print    ============== RFDisConnect
bitsplatform.RFDisConnect

The log window of BITS-Platform gives evidence about the properly executed test sequence:

13:58:53.495 Start SELFTEST[1] get single parameter 'TEST-1' wait: 20000ms
13:58:57.516 Start SELFTEST[2] get single parameter 'TEST-2' wait: 10000ms
13:59:00.540 Start SELFTEST[3] get single parameter 'TEST-3-1' wait: 2000ms
13:59:02.545 Get SELFTEST[3] single parameter
13:59:07.527 Get SELFTEST[2] single parameter
13:59:13.512 Get SELFTEST[1] single parameter

The console window of Robot Framework indicates the same proper sequence:

'============== starting kw_1'
'============== kw_1 started'
'============== starting kw_2'
'============== kw_2 started'
'============== starting kw_3'
'============== waiting 30 s'
'============== kw_3 started'
'============== kw_3 ended'
'============== kw_2 ended'
'============== kw_1 ended'

The Python code belonging to the keyword implementation has his own print() functions:

This is the listener thread:

   def StartListenerThread(self):
      print(f"starting listener thread")
      self.__ListenerThread = threading.Thread(target=self.tcpip_listener, args=(self.__StopEvent, self.__dictMessages, self.__Socket))
      self.__ListenerThread.start()

   def StopListenerThread(self):
      print(f"sending stop event to listener thread")
      self.__StopEvent.set()
      print(f"waiting for listener threads joined")
      self.__ListenerThread.join()

   def tcpip_listener(self, stop_event, dict_messages, client_socket):
       with client_socket:
           print(f"Connection from {client_socket.getpeername()}")
           while not stop_event.is_set():
               try:
                  client_socket.settimeout(1)  # Check for stop_event every second
                  data_received = client_socket.recv(CCommunication.BUFFER_SIZE)
                  data_received = data_received.decode('utf-8').strip()
                  print(f"Message received in listener: '{data_received}'")
                  # TODO: make this generic
                  if "UNIT_1" in data_received:
                     print(f"Listener selected 'UNIT_1' queue for answer")
                     message_queue = dict_messages['UNIT_1']
                  if "UNIT_2" in data_received:
                     print(f"Listener selected 'UNIT_2' queue for answer")
                     message_queue = dict_messages['UNIT_2']
                  if "UNIT_3" in data_received:
                     print(f"Listener selected 'UNIT_3' queue for answer")
                     message_queue = dict_messages['UNIT_3']
                  if "UNIT_4" in data_received:
                     print(f"Listener selected 'UNIT_4' queue for answer")
                     message_queue = dict_messages['UNIT_4']
                  else:
                     pass
                     # TODO: error handling
                  message_queue.put(data_received)
               except socket.timeout:
                  continue
           print(f"listener received stop event")

This is a keyword implementation:

def kw_1_call(self):
   print(f"--- executing kw_1_call in basic lib")
   self.kw_1(self.__dictMessages, self.__Socket)

def kw_1(self, dict_messages, client_socket):

   print(f"[kw_1] : entering kw_1")

   value = "TEST-1"
   unit  = 1
   server_waittime = 20000
   answer_timeout  = 21000
   thread_identifier = "UNIT_1"

   wait_for_answer = False
   message = "SELFTEST UNIT_" + str(unit) + " SINGLE GET DELAY_ " + str(server_waittime) + " VALUE_ " + str(value)
   try:
      print(f"[kw_1] : trying to send message: '{message}'")
      data_send = message + "\n"
      client_socket.send(data_send.encode())
      print("[kw_1] : message was send")
      wait_for_answer = True
   except socket.error as ex:
      result = str(ex)
      print(f"[kw_1] : {result}")

   if wait_for_answer is True:

      message_queue_1 = queue.Queue()
      dict_messages[thread_identifier] = message_queue_1

      print("[kw_1] : waiting for answer from message queue")
      try:
         message = message_queue_1.get(timeout=answer_timeout)
         print(f"[kw_1] : message received from queue: '{message}'")
         if "UNIT_1" in message:
            message_queue_1.task_done()
         else:
            print("[kw_1] : but not for me")
      except queue.Empty:
         print("[kw_1] : message_queue timeout")
   print("[kw_1] : end of kw_1")

This code is implemented in a pure Python script that is imported in a Robot Framework keyword library. This is the mapping code:

@keyword
def kw_1(self):
    BuiltIn().log(f"=== kw_1_call in keyword lib", "WARN")
    self.__oCommunication.kw_1_call()

I am confused now about the order of the print() outputs in debug log file:

20240620 13:59:00.537 - INFO - +-------- START KEYWORD: bitsplatform.Kw 3 [ ]
20240620 13:59:02.545 - INFO - --- executing kw_3_call in basic lib
[kw_3-1] : entering kw_3
[kw_3-1] : trying to send message: 'SELFTEST UNIT_3 SINGLE GET DELAY_ 2000 VALUE_ TEST-3-1'
[kw_3-1] : message was send
[kw_3-1] : waiting for answer from message queue
Message received in listener: 'STATUS_ OK E_CODE_ 0 TIME(ms)_ 1718884742543 SELFTEST UNIT_3 SINGLE GET_RET RESULT TEST-3-1'
Listener selected 'UNIT_3' queue for answer
[kw_3-1] : message received from queue: 'STATUS_ OK E_CODE_ 0 TIME(ms)_ 1718884742543 SELFTEST UNIT_3 SINGLE GET_RET RESULT TEST-3-1'
[kw_3-1] : end of kw_3
20240620 13:59:02.546 - INFO - +-------- END KEYWORD: bitsplatform.Kw 3 (2008)
20240620 13:59:02.546 - INFO - +-------- START KEYWORD: rf.extensions.Pretty Print [ ============== kw_3 ended ]
20240620 13:59:02.548 - INFO - +-------- END KEYWORD: rf.extensions.Pretty Print (2)
20240620 13:59:02.550 - INFO - +------- END THREAD: KW_3 (2018)
20240620 13:59:07.527 - INFO - --- executing kw_2_call in basic lib
[kw_2] : entering kw_2
[kw_2] : trying to send message: 'SELFTEST UNIT_2 SINGLE GET DELAY_ 10000 VALUE_ TEST-2'
[kw_2] : message was send
[kw_2] : waiting for answer from message queue
20240620 13:59:07.527 - INFO - +------ END KEYWORD: bitsplatform.Kw 2 (10013)
20240620 13:59:07.527 - INFO - +------ START KEYWORD: rf.extensions.Pretty Print [ ============== kw_2 ended ]
20240620 13:59:07.528 - INFO - +------ END KEYWORD: rf.extensions.Pretty Print (1)
20240620 13:59:07.528 - INFO - +----- END THREAD: KW_2 (10022)
20240620 13:59:13.511 - INFO - --- executing kw_1_call in basic lib
[kw_1] : entering kw_1
[kw_1] : trying to send message: 'SELFTEST UNIT_1 SINGLE GET DELAY_ 20000 VALUE_ TEST-1'
[kw_1] : message was send
[kw_1] : waiting for answer from message queue
20240620 13:59:13.512 - INFO - +---- END KEYWORD: bitsplatform.Kw 1 (20018)
20240620 13:59:13.512 - INFO - +---- START KEYWORD: rf.extensions.Pretty Print [ ============== kw_1 ended ]
20240620 13:59:13.514 - INFO - +---- END KEYWORD: rf.extensions.Pretty Print (1)
20240620 13:59:13.516 - INFO - +--- END THREAD: KW_1 (20029)
20240620 13:59:30.540 - INFO - Slept 30 seconds
20240620 13:59:30.540 - INFO - Message received in listener: 'STATUS_ OK E_CODE_ 0 TIME(ms)_ 1718884747526 SELFTEST UNIT_2 SINGLE GET_RET RESULT TEST-2'
Listener selected 'UNIT_2' queue for answer
[kw_2] : message received from queue: 'STATUS_ OK E_CODE_ 0 TIME(ms)_ 1718884747526 SELFTEST UNIT_2 SINGLE GET_RET RESULT TEST-2'
[kw_2] : end of kw_2
20240620 13:59:30.542 - INFO - +-- END KEYWORD: BuiltIn.Sleep (30006)

Why is

[kw_3-1] : entering kw_3

at top? I would expect that

[kw_1] : entering kw_1

is at top (but is the last instead).

Why is

[kw_3-1] : trying to send message: 'SELFTEST UNIT_3 SINGLE GET DELAY_ 2000 VALUE_ TEST-3-1'

at top? I would expect that

[kw_1] : trying to send message: 'SELFTEST UNIT_1 SINGLE GET DELAY_ 20000 VALUE_ TEST-1'

is at top.

And I miss

Message received in listener: 'STATUS_ OK E_CODE_ 0 ... belonging to TEST-1

and

[kw_1] : end of kw_1

This behavior is reproducible.

OK, I have to admit, that I am not really experienced in thread programming. Maybe my way to implement this functionality is not correct or something is missing.

Do you have any idea what is going wrong here?

test-fullautomation commented 5 months ago

Hi @milanac030988 , can you please with high priority look into this issue. We need to support parallel access for the BITS_Platfrom. This is the try from Holger to build a library for this. Thank you, Thomas

HolQue commented 5 months ago

Hmm, maybe it's not supported to use print() in pure Python functions that are executed in the context of Robot Framework?

In the meantime I implemented in all basic keyword functions an own logging. Every log line starts with a timestamp. I merge all log files and sort the result in alphabetical order (=> in chronological order). Result: All things fine. The sequence is like expected.

What is now the expectation w.r.t. this topic? Shall the content of print() statements coming from outside Robot Framework, be part of the Robot Framework debug log file? Or is it recommended not to do this?

test-fullautomation commented 5 months ago

Order in log files need to reflect actual execution order in case of threading.

milanac030988 commented 3 months ago

Could not reproduce. Maybe fixed with https://github.com/test-fullautomation/robotframework/pull/86

test-fullautomation commented 3 months ago

Closed. New ticket when problem occurs again.