Post new topic Reply to topic  [ 9 posts ] 

Board index : TeleFlow Forums : TeleFlow Server & Monitor

Author Message
 Post subject: Duplicate entries on TFServer logs
PostPosted: Thu Jan 15, 2009 4:08 pm 
Offline
User avatar

Joined: Fri Feb 06, 2004 11:05 am
Posts: 115
Location: Costa Rica
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.


Back to top
 Profile  
 
 Post subject: Re: Duplicate entries on TFServer logs
PostPosted: Mon Jan 19, 2009 10:29 am 
Offline

Joined: Wed Mar 19, 2003 4:28 pm
Posts: 510
Location: Canada
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!


Back to top
 Profile WWW 
 
 Post subject: Re: Duplicate entries on TFServer logs
PostPosted: Tue Jan 20, 2009 10:42 am 
Offline
User avatar

Joined: Fri Feb 06, 2004 11:05 am
Posts: 115
Location: Costa Rica
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...


Back to top
 Profile  
 
 Post subject: Re: Duplicate entries on TFServer logs
PostPosted: Tue Jan 20, 2009 11:35 am 
Offline

Joined: Wed Mar 19, 2003 4:28 pm
Posts: 510
Location: Canada
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)


Back to top
 Profile WWW 
 
 Post subject: Re: Duplicate entries on TFServer logs
PostPosted: Tue Jan 20, 2009 11:40 am 
Offline

Joined: Wed Mar 19, 2003 4:28 pm
Posts: 510
Location: Canada
Quote:
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?


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.)


Back to top
 Profile WWW 
 
 Post subject: Re: Duplicate entries on TFServer logs
PostPosted: Tue Jan 20, 2009 6:41 pm 
Offline
Site Admin

Joined: Wed Dec 31, 1969 5:00 pm
Posts: 329
Location: Vancouver, BC
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.


Back to top
 Profile WWW 
 
 Post subject: Re: Duplicate entries on TFServer logs
PostPosted: Wed Jan 21, 2009 7:28 am 
Offline
User avatar

Joined: Fri Feb 06, 2004 11:05 am
Posts: 115
Location: Costa Rica
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.


Back to top
 Profile  
 
 Post subject: Re: Duplicate entries on TFServer logs
PostPosted: Wed Jan 21, 2009 10:43 am 
Offline
Site Admin

Joined: Wed Dec 31, 1969 5:00 pm
Posts: 329
Location: Vancouver, BC
We were able to extract the files with the trial version of Winzip v12.


Back to top
 Profile WWW 
 
 Post subject: Re: Duplicate entries on TFServer logs
PostPosted: Wed Jan 21, 2009 11:29 am 
Offline

Joined: Wed Mar 19, 2003 4:28 pm
Posts: 510
Location: Canada
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.


Back to top
 Profile WWW 
 
Display posts from previous:  Sort by  
Post new topic Reply to topic  [ 9 posts ] 

Board index : TeleFlow Forums : TeleFlow Server & Monitor


You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot post attachments in this forum

Search for:
Jump to:  
Style by Midnight Phoenix & N.Design Studio
Powered by phpBB © 2000, 2002, 2005, 2007 phpBB Group.