I just discovered a weird behaviour of the TeleFlow Server when generating unlimited size logs for applications running on different channels: Duplicate log entries.

I can provide the full log file for you to examine (a 10MB file zipped into a 212KB file), but here are (weird) snippets of the same log lines (same time, different positions in the file):

Lines 12249 to 12251:
2009/01/08 12:17:52.437: [292] Wait
2009/01/08 12:17:52.437: Delay '@vWaitLapse' evaluates to '793'
2009/01/08 12:17:52.437: Waiting 793 milliseconds

Lines 21954 to 21956:
2009/01/08 12:17:52.437: [292] Wait
2009/01/08 12:17:52.437: Delay '@vWaitLapse' evaluates to '793'
2009/01/08 12:17:52.437: Waiting 793 milliseconds

Lines 31663 to 31665:
2009/01/08 12:17:52.437: [292] Wait
2009/01/08 12:17:52.437: Delay '@vWaitLapse' evaluates to '793'
2009/01/08 12:17:52.437: Waiting 793 milliseconds

Lines 41373 to 41375:
2009/01/08 12:17:52.437: [292] Wait
2009/01/08 12:17:52.437: Delay '@vWaitLapse' evaluates to '793'
2009/01/08 12:17:52.437: Waiting 793 milliseconds

Lines 51084 to 51086:
2009/01/08 12:17:52.437: [292] Wait
2009/01/08 12:17:52.437: Delay '@vWaitLapse' evaluates to '793'
2009/01/08 12:17:52.437: Waiting 793 milliseconds

Lines 60796 to 60798:
2009/01/08 12:17:52.437: [292] Wait
2009/01/08 12:17:52.437: Delay '@vWaitLapse' evaluates to '793'
2009/01/08 12:17:52.437: Waiting 793 milliseconds

Lines 70509 to 70511:
2009/01/08 12:17:52.437: [292] Wait
2009/01/08 12:17:52.437: Delay '@vWaitLapse' evaluates to '793'
2009/01/08 12:17:52.437: Waiting 793 milliseconds

So, it seems entire sesions (from app start to shutdown) are copied again and again into the same log file by TFServer.

It does not happen with every log, however: I have two applications, one that receives incoming calls and another which performs outgoing calls (the first asks the second to perform a channel switching) and the log entries duplicated above are from the second application and happens roughly in every port this second app is running.

It may be a bug on the TFServer but also I might be doing something wrong... Can you help me?

I'm writing a program which searchs for events in these logs in order to gather some stats, but this entry duplication messes up everything!

Thanks in advance.

Please zip and send the following to support@engenic.com:
- The log file
- The TFServer log file
- A copy of the .TAL file you were using when this occurred.
- A screen capture of your current TeleFlow Config

It might help the zip reach us if you rename it to a .zp extension, just to be safe.

Are you using the Save Log step in your application(s) at all?

We will follow-up in this thread.

Thanks!

I'm attaching more log files that show the same behaviour, along with the other stuff.

Save Log step? I'm sorry, I didn't know about it... I'm using the Logger template flowchart in the first application (IVR_APP, the one that receives the phone calls and asks for call transfering) and that template does not use the Save Log step either. Where and when should I use it?

These logs were recollected during a controlled test during which some events happened:

• I started up the server at around 11:56am (local time used in the log files)
• Test calls began almost inmediately
• There were 3 separate tests:
  
  • 4 people calling up concurrently to ask for call transfering (the functionality we're testing) from 11:58am to 12:15pm - Few dropped calls
  • 7 people calling up concurrently from 12:20pm to 12:32pm. I witnessed two deadlocks (12:22 & 12:25 aprox) while monitoring, which I "unlocked" by manually deleting the request and response files (used to ask for transfer requests and to acknowlege them)
  • 9 people calling up concurrently from 12:40pm to 12:55pm. At about 12:46pm the server crashed (TFServer, I mean) because the TFMonitor continued execution trying to reconnect to the server, which I restarted manually... however, I think that no more phone calls got in after the restart (people just stopped calling, I guess)

I know this file-based mechanism to ask and acknowledge call transfers is not working as I expected; in fact, I noticed some parsing mistakes when multiple requests are pending. That's why I'm rethinking this mechanism...

I'll probably implement a TCP-based solution (like a FIFO structure managed by a Delphi application running apart), but setting that aside, I'm baffled about the repetitive lines in the log files (the issue I'm reporting).

As I said, I don't know if it's a TFServer bug or something I'm doing wrong somewhere (besides the file-based "inter-process communication" technique), but it's worth a look from the experts...

Can you try re-zipping/sending those files? Something about the zip file isn't right. None of the unzip programs we use can extract the files. (Winzip says they are not in the standard Zip 2.0 format, but other extractors get errors as well)

Save Log allows you to save the TeleFlow application log at a set point in the flow of your applications. This is the same log output you get when logging all events, or an application error log, but takes place exactly where you want. You should only use it if you have an issue you are attempting to track down that isn't easily identified using the normal logs. (This log has the benefit of logging right when you want, as opposed to either full-time logging or logging on error.)

If its of any comfort... can't think of any reason how bugs in the file-based method of communicating transfer requests could cause duplicate entries in the log. You might have issues with your requests, but this should not be one of them.

I'm really curious to see the file samples Chris requested earlier.

I'm sorry about the file format: I have WinZIP v12 and by default I'm using the best compression method available since v11 which produces a 1.1MB ZIP file... but if it's OK with you I may recompress with the standard method which produces a 3.8MB ZIP file and send it back to you.

You may also use WinZIP v12 in trial mode just to unpack the file as well.

We were able to extract the files with the trial version of Winzip v12.

The duplicated log entries appear to be related to an unhandled fatal within the application. Basically, it looks like TeleFlow might be stamping an entire repeat of the log when there is a handled fatal error followed by an unhandled one.

Whenever you have logic after your fatal error label, it is a good idea to set a new fatal Global Event label name, such as "FINAL_FATAL", and make the "FINAL_FATAL" label go to the final FINISH step. This way, if the logic between the fatal label and the end of the application gets a FATAL error, TeleFlow can handle it properly.

We will be looking into some ways of handling this a little better in TeleFlow, but for now, you can probably eliminate the double-logging with the fix to the fatal error handling I have described.