[Home]

Summary:ASTERISK-04608: tvfix negative timestamps
Reporter:Matthew Simpson (matthewsimpson)Labels:
Date Opened:2005-07-17 13:50:04Date Closed:2005-07-19 11:25:50
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:Getting spammed with errors like these in my asterisk log:
Jul 17 13:45:56 ERROR[17008]: utils.c:509 tvfix: warning negative timestamp -41324.-603625

not sure why. the errors have stopped, no changes to config.

****** ADDITIONAL INFORMATION ******

* running latest CVS 07/17
* using Asterisk as media gateway -- calls come in through zaptel TE-405P PRI and go out SIP
* never saw issue before on last CVS version 06/30

Comments:By: Clod Patry (junky) 2005-07-17 14:55:06

I suspect ASTERISK-4477 to be related on this problem.
By: Michael Jerris (mikej) 2005-07-17 14:56:43

I'm confused, you say you are getting these errors, then you say they have stopped.  Are you getting errors, or are you no longer getting errors you used to?
By: Thierry Wehr (wulfgard) 2005-07-17 15:48:55

I confirm that the error is existing
we are running CVS 2005-07-16 00:06:10 UTC and we have the same error
By: Matthew Simpson (matthewsimpson) 2005-07-17 21:12:31

yeah it's still around i'm getting them again on both boxes

Jul 17 21:13:18 ERROR[29571]: utils.c:509 tvfix: warning negative timestamp -68156.-216625
Jul 17 21:13:18 ERROR[29571]: utils.c:509 tvfix: warning negative timestamp -68156.-196625
Jul 17 21:13:18 ERROR[29571]: utils.c:509 tvfix: warning negative timestamp -68156.-176625
Jul 17 21:13:18 ERROR[29571]: utils.c:509 tvfix: warning negative timestamp -68156.-156625
Jul 17 21:13:18 ERROR[29571]: utils.c:509 tvfix: warning negative timestamp -68156.-136625
Jul 17 21:13:18 ERROR[29571]: utils.c:509 tvfix: warning negative timestamp -68156.-116625
Jul 17 21:13:18 ERROR[29571]: utils.c:509 tvfix: warning negative timestamp -68156.-96625
Jul 17 21:13:18 ERROR[29571]: utils.c:509 tvfix: warning negative timestamp -68156.-76625
Jul 17 21:13:18 ERROR[29571]: utils.c:509 tvfix: warning negative timestamp -68156.-56625
Jul 17 21:13:18 ERROR[29571]: utils.c:509 tvfix: warning negative timestamp -68156.-36625
Jul 17 21:13:18 ERROR[29571]: utils.c:509 tvfix: warning negative timestamp -68156.-16625
Jul 17 21:13:18 ERROR[29571]: utils.c:509 tvfix: warning negative timestamp -68155.-996625
Jul 17 21:13:19 ERROR[29571]: utils.c:509 tvfix: warning negative timestamp -68155.-976625
Jul 17 21:13:19 ERROR[29571]: utils.c:509 tvfix: warning negative timestamp -68155.-956625
Jul 17 21:13:19 ERROR[29571]: utils.c:509 tvfix: warning negative timestamp -68155.-936625
Jul 17 21:13:19 ERROR[29571]: utils.c:509 tvfix: warning negative timestamp -68155.-916625
By: Michael Jerris (mikej) 2005-07-17 21:28:51

can anybody find out what is calling this function when we get this error?
By: Matthew Simpson (matthewsimpson) 2005-07-17 21:35:08

(this post was in error)


By: Thierry Wehr (wulfgard) 2005-07-17 21:37:07

an other issue that may be coming from timestamp
on some incoming calls using g729 or ilbc codecs the calling party has a terrific robot voice
By: Matthew Simpson (matthewsimpson) 2005-07-17 21:37:39

I traced the PID value of the txfix errors back to channels that are Zap --> SIP


By: Andrew Lindh (andrew) 2005-07-18 11:42:00

I'm seeing these errors now too (CVS 7/18/05)....I get them on G.711 (ulaw)
SIP to SIP calls (between polycom phones). Not every call generates the errors.
But the errors (reporting, logging, etc) causes the audio to be very chopy.

My reference system (CVS 07/06/2005) is working fine.

I tried a full make clean/make install/reboot for CVS 7/18/05 and I
still have the same problem. I see the errors in the logs as early as 7/17/05.
By: Russell Bryant (russell) 2005-07-18 13:48:31

does anyone know how to reliably reproduce this?  I got it to happen one time, but I can't make it happen again.
By: Matthew Simpson (matthewsimpson) 2005-07-18 14:19:09

I can't figure out how to force it to happen.  I thought it might be DTMF but in my test calls DTMF did not cause it.  And I am doing Zap-->SIP while andrew is doing SIP-->SIP
By: Andrew Lindh (andrew) 2005-07-18 14:33:38

I'll have to build a new test (or try it later tonight) system because I need
my current test system for some production testing today...

It was a SIP to SIP call after the call was answered and the bridge started.
On calls that were the same (exten 301 to 330) it happend on only some (but
most) calls. With or without NAT, no Zap. I was not able to force it to happen.
By: Fred Meyer (mensaiq) 2005-07-18 15:39:41

I have a repeatable situation, SIP (Polycom 500) -> ZAP (Digium TDM400P-TDM12B).

Jul 18 12:06:49 VERBOSE[4949] logger.c:     -- Executing Dial("SIP/6508-ec2b", "Zap/3/ww8370275") in new stack
Jul 18 12:06:49 VERBOSE[4949] logger.c:     -- Called 3/ww8370275
Jul 18 12:06:53 VERBOSE[4949] logger.c:     -- Zap/3-1 answered SIP/6508-ec2b
Jul 18 12:06:53 ERROR[4949] utils.c: warning negative timestamp -49201.-684500
Jul 18 12:06:53 ERROR[4949] utils.c: warning negative timestamp -49201.-684500
Jul 18 12:06:53 ERROR[4949] utils.c: warning negative timestamp -49201.-664500
...
Jul 18 12:07:05 ERROR[4949] utils.c: warning negative timestamp -49189.-844500
Jul 18 12:07:05 ERROR[4949] utils.c: warning negative timestamp -49189.-824500
Jul 18 12:07:05 ERROR[4949] utils.c: warning negative timestamp -49189.-804500
Jul 18 12:07:05 ERROR[4949] utils.c: warning negative timestamp -49189.-784500
Jul 18 12:07:05 VERBOSE[4949] logger.c:     -- Hungup 'Zap/3-1'
Jul 18 12:07:05 VERBOSE[4949] logger.c:   == Spawn extension (default, 98370275, 1) exited non-zero on 'SIP/6508-ec2b'
By: Andrew Lindh (andrew) 2005-07-18 16:51:15

I setup a new Asterisk box with the current CVS and two Cisco 7960 phones
(with current SIP 7.5 software) and I got the same problem on the first
call between the two phones.....

But after that each call has worked correctly. I have restarted asterisk
and there are still no more errors...

So different phones (cisco vs. polycom) but the same problem (just not as bad).


By: Alejo Alamillo (aap) 2005-07-18 17:31:12

I'm getting the same problem, started after updating Sunday July 17.  Saturday's update did not have tvfix: warning negative timestamp error.
Hope it helps.
By: Clod Patry (junky) 2005-07-18 20:39:41

Just happens to me too.
[...]
Jul 18 20:58:01 ERROR[795]: utils.c:509 tvfix: warning negative timestamp -58922.-230125
Jul 18 20:58:01 ERROR[795]: utils.c:509 tvfix: warning negative timestamp -58922.-210125
[...]
Trying to reproduce it, but i can't at this moment.
By: Kristopher Lalletti (kris2k) 2005-07-18 21:21:51

I just updated to HEAD tonight, and I'm noticing the same problems.

However, I noticed theses errors having a correlation between the RTP debug for the channel created between the starting leg, not the destination leg.

Here we see the RTP call progress tones, and it ends because there's a re-invite between the two polycom's.

  -- Called aro-ip300-331
   -- SIP/aro-ip300-331-7890 is ringing
   -- SIP/aro-ip300-331-7890 answered SIP/aro-ip500-330-455d
   -- Attempting native bridge of SIP/aro-ip500-330-455d and SIP/aro-ip300-331-7890
Jul 18 22:12:13 ERROR[14834]: utils.c:509 tvfix: warning negative timestamp -212079.-629750
Jul 18 22:12:13 ERROR[14834]: utils.c:509 tvfix: warning negative timestamp -212079.-629750
Jul 18 22:12:13 ERROR[14834]: utils.c:509 tvfix: warning negative timestamp -212079.-609750
Jul 18 22:12:13 ERROR[14834]: utils.c:509 tvfix: warning negative timestamp -212079.-589750
 == Spawn extension (macro-aroDialExtension, s, 2) exited non-zero on 'SIP/aro-ip500-330-455d' in macro 'aroDialExtension'
 == Spawn extension (aroExtensions, 331, 1) exited non-zero on 'SIP/aro-ip500-330-455d'

One little detail, of course, this is on a re-invited RTP stream, but on a call process where the RTP goes through the Asterisk box, the RTP only has a negative timestamp between my Cisco Phone to the Asterisk leg, not the Asterisk to my SIP switch.

It's funny, but not he first time I've noticed negative timestamps. Can't recall exactly, but it had to relate with the DTMF in the past.

Got RTP packet from 216.58.12.111:33027 (type 18, seq 38584, ts -2129670482, len 20)
Jul 18 22:11:17 ERROR[14834]: utils.c:509 tvfix: warning negative timestamp -266208.-810250

Sorry, can't provide more, this is a prod machine.


By: Clod Patry (junky) 2005-07-18 21:28:01

IF that could help someone:
it starts like that:
Jul 18 20:57:32 NOTICE[591] chan_iax2.c: Avoiding IAX destroy deadlock
Jul 18 20:57:36 ERROR[795] utils.c: warning negative timestamp -58948.-130125
Jul 18 20:57:36 ERROR[795] utils.c: warning negative timestamp -58948.-130125
By: Fred Meyer (mensaiq) 2005-07-19 01:51:38

I just did a cvshead build again. My tests get the message on:
SIP (Polycom 500) -> FXO and FXO -> SIP (Polycom 500)
SIP (Polycom 500) -> FXS and FXS -> SIP (Polycom 500)
SIP (Polycom 500) -> SIP (AAstra 480i) and SIP (AAstra 480i) -> SIP (Polycom 500)
Although these calls occasionally did NOT produce the errors.

I was unable to get errors on ZAP -> ZAP or ZAP -> AAstra 480i
By: Russell Bryant (russell) 2005-07-19 10:55:06

I'm tracing this down.  As of now, I have it down to rtp.c line 375
By: Russell Bryant (russell) 2005-07-19 11:25:05

fixed in CVS HEAD :)