search

AllStarLink / app_rpt

Refactoring and upgrade of AllStarLink's app_rpt, etc.
7 stars 6 forks source link

Erroneous jb_warning_output #209

Open tsawyer opened 1 year ago

tsawyer commented 1 year ago

We talked on Slack about turning off the IAX2 jitter buffer to prevent these messages. I found that, due to the extensive use of the internet to connect nodes, that's not practical.

Is this a bug in IAX2 or are we setting the JB incorrectly?

[2023-08-21 10:42:47.058] WARNING[517779][C-00000039]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 279, this delay 1697, threshold 1074, new offset -1684
[2023-08-21 10:42:54.528] WARNING[517778][C-00000039]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 0, this delay -1699, threshold 1074, new offset 15

Typical AllStar codec and JB settings.

disallow = all   ; The permitted codecs for outgoing connections
;Audio Quality   Bandwidth
;allow = ulaw    ; best    87 kbps
;allow = adpcm   ; good    55 kbps
;allow = gsm     ; medicore    36 kbps
allow = ulaw
allow = adpcm
allow = gsm

jitterbuffer = yes
forcejitterbuffer = yes
dropcount = 2
maxjitterbuffer = 4000
maxjitterinterps = 10
resyncthreshold = 1000
maxexcessbuffer = 80
minexcessbuffer = 10
jittershrinkrate = 1
tos = 0x1E
autokill = yes
delayreject = yes
; iaxthreadcount = 30
; iaxmaxthreadcount = 150
tsawyer commented 11 months ago

I'm getting these messages continuously. I believe there is a bug in the jitter buffer code. As was mentioned here and on Slack the jitter buffer is critical for the internet environment of AllStar.

I've tried other JB settings per nothing seems to fix it. I see this problem on all my Allstar servers eventually. Is it possible this contributes to reduced up times. Can we elevate this problem? 

jitterbuffer = yes
forcejitterbuffer = yes
;dropcount = 2
;maxjitterbuffer = 4000
;maxjitterinterps = 10
;resyncthreshold = 1000
;maxexcessbuffer = 80
;minexcessbuffer = 10
;jittershrinkrate = 1
;tos = 0x1E
;tos = ef
;autokill = yes
;delayreject = yes
;; iaxthreadcount = 30
;; iaxmaxthreadcount = 150
tail -f /var/log/asterisk/messages
[2023-09-30 15:35:48.073] WARNING[2245167][C-00000057] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10632, threshold 2802, new offset -2270255124
[2023-09-30 15:35:48.073] WARNING[2245168][C-00000054] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10631, threshold 2810, new offset -2270255897
[2023-09-30 15:35:53.552] WARNING[2245165] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10321, threshold 1000, new offset -2270261347
[2023-09-30 15:35:55.336] WARNING[2245160] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10442, threshold 1000, new offset -2270262406
[2023-09-30 15:35:58.704] WARNING[2245161][C-00000057] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10616, threshold 2802, new offset -2270265740
[2023-09-30 15:35:58.704] WARNING[2245164][C-00000054] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10616, threshold 2810, new offset -2270266513
[2023-09-30 15:36:03.896] WARNING[2245167] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10335, threshold 1000, new offset -2270271682
[2023-09-30 15:36:05.816] WARNING[2245165] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10471, threshold 1000, new offset -2270272877
[2023-09-30 15:36:09.343] WARNING[2245162][C-00000057] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10630, threshold 2802, new offset -2270276370
[2023-09-30 15:36:09.343] WARNING[2245165][C-00000054] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10625, threshold 2810, new offset -2270277138
[2023-09-30 15:36:14.216] WARNING[2245161] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10305, threshold 1000, new offset -2270281987
[2023-09-30 15:36:16.296] WARNING[2245163] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10465, threshold 1000, new offset -2270283342
[2023-09-30 15:36:19.983] WARNING[2245164][C-00000057] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10625, threshold 2802, new offset -2270286995
[2023-09-30 15:36:19.983] WARNING[2245162][C-00000054] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10624, threshold 2810, new offset -2270287762
[2023-09-30 15:36:24.553] WARNING[2245160] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10328, threshold 1000, new offset -2270292315
[2023-09-30 15:36:26.776] WARNING[2245160] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10471, threshold 1000, new offset -2270293813
[2023-09-30 15:36:30.608] WARNING[2245169][C-00000057] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10610, threshold 2802, new offset -2270297605
[2023-09-30 15:36:30.608] WARNING[2245161][C-00000054] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10617, threshold 2810, new offset -2270298379
[2023-09-30 15:36:34.856] WARNING[2245167] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10288, threshold 1000, new offset -2270302603
[2023-09-30 15:36:37.256] WARNING[2245168] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10465, threshold 1000, new offset -2270304278
[2023-09-30 15:36:41.233] WARNING[2245165][C-00000057] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10610, threshold 2802, new offset -2270308215
[2023-09-30 15:36:41.233] WARNING[2245168][C-00000054] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10609, threshold 2810, new offset -2270308988
[2023-09-30 15:36:45.176] WARNING[2245164] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10311, threshold 1000, new offset -2270312914
[2023-09-30 15:36:47.736] WARNING[2245164] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10471, threshold 1000, new offset -2270314749
[2023-09-30 15:36:51.849] WARNING[2245162][C-00000057] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10607, threshold 2802, new offset -2270318822
[2023-09-30 15:36:51.849] WARNING[2245160][C-00000054] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10607, threshold 2810, new offset -2270319595
[2023-09-30 15:36:55.473] WARNING[2245167] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10453, threshold 1000, new offset -2270323367
[2023-09-30 15:36:58.239] WARNING[2245165] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10488, threshold 1000, new offset -2270325237
[2023-09-30 15:37:02.473] WARNING[2245166][C-00000057] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10609, threshold 2802, new offset -2270329431
[2023-09-30 15:37:02.474] WARNING[2245167][C-00000054] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10608, threshold 2810, new offset -2270330203
[2023-09-30 15:37:05.776] WARNING[2245163] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10294, threshold 1000, new offset -2270333661
[2023-09-30 15:37:08.760] WARNING[2245165] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10511, threshold 1000, new offset -2270335748
[2023-09-30 15:37:13.104] WARNING[2245167][C-00000057] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10622, threshold 2802, new offset -2270340053
[2023-09-30 15:37:13.104] WARNING[2245164][C-00000054] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10614, threshold 2810, new offset -2270340817
[2023-09-30 15:37:16.113] WARNING[2245160] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10322, threshold 1000, new offset -2270343983
[2023-09-30 15:37:19.239] WARNING[2245166] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10465, threshold 1000, new offset -2270346213
[2023-09-30 15:37:23.728] WARNING[2245169][C-00000057] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10609, threshold 2802, new offset -2270350662
[2023-09-30 15:37:23.728] WARNING[2245163][C-00000054] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10615, threshold 2810, new offset -2270351432
[2023-09-30 15:37:26.456] WARNING[2245168] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10334, threshold 1000, new offset -2270354317
[2023-09-30 15:37:29.736] WARNING[2245167] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10488, threshold 1000, new offset -2270356701
[2023-09-30 15:37:34.343] WARNING[2245160][C-00000057] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10600, threshold 2802, new offset -2270361262
[2023-09-30 15:37:34.343] WARNING[2245165][C-00000054] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10769, threshold 2810, new offset -2270362201
[2023-09-30 15:37:36.753] WARNING[2245169] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10279, threshold 1000, new offset -2270364596
[2023-09-30 15:37:40.239] WARNING[2245167] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10488, threshold 1000, new offset -2270367189
[2023-09-30 15:37:44.969] WARNING[2245165][C-00000057] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10617, threshold 2802, new offset -2270371879
[2023-09-30 15:37:44.969] WARNING[2245160][C-00000054] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10616, threshold 2810, new offset -2270372817
[2023-09-30 15:37:47.057] WARNING[2245163] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10294, threshold 1000, new offset -2270374890
[2023-09-30 15:37:50.736] WARNING[2245160] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10482, threshold 1000, new offset -2270377671
[2023-09-30 15:37:55.584] WARNING[2245163][C-00000057] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10765, threshold 2802, new offset -2270382644
[2023-09-30 15:37:55.584] WARNING[2245165][C-00000054] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10600, threshold 2810, new offset -2270383417
[2023-09-30 15:37:57.376] WARNING[2245161] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10305, threshold 1000, new offset -2270385195
[2023-09-30 15:38:01.256] WARNING[2245162] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10682, threshold 1000, new offset -2270388353
[2023-09-30 15:38:06.193] WARNING[2245164][C-00000057] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10597, threshold 2802, new offset -2270393241
[2023-09-30 15:38:06.193] WARNING[2245168][C-00000054] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10600, threshold 2810, new offset -2270394017
[2023-09-30 15:38:07.633] WARNING[2245168] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10248, threshold 1000, new offset -2270395443
[2023-09-30 15:38:11.776] WARNING[2245168] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10511, threshold 1000, new offset -2270398864
[2023-09-30 15:38:16.769] WARNING[2245168][C-00000057] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10561, threshold 2802, new offset -2270403802
[2023-09-30 15:38:16.769] WARNING[2245166][C-00000054] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10561, threshold 2810, new offset -2270404578
[2023-09-30 15:38:17.896] WARNING[2245164] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10248, threshold 1000, new offset -2270405691
[2023-09-30 15:38:22.296] WARNING[2245166] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10505, threshold 1000, new offset -2270409369
[2023-09-30 15:38:27.368] WARNING[2245164][C-00000057] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10590, threshold 2802, new offset -2270414392
[2023-09-30 15:38:27.368] WARNING[2245166][C-00000054] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10591, threshold 2810, new offset -2270415169
[2023-09-30 15:38:28.153] WARNING[2245160] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10248, threshold 1000, new offset -2270415939
[2023-09-30 15:38:32.816] WARNING[2245169] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10511, threshold 1000, new offset -2270419880
[2023-09-30 15:38:38.008] WARNING[2245163][C-00000057] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10625, threshold 2802, new offset -2270425017
[2023-09-30 15:38:38.008] WARNING[2245168][C-00000054] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10624, threshold 2810, new offset -2270425793
[2023-09-30 15:38:38.496] WARNING[2245166] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10328, threshold 1000, new offset -2270426267
[2023-09-30 15:38:43.296] WARNING[2245163] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10465, threshold 1000, new offset -2270430345
[2023-09-30 15:38:48.624] WARNING[2245169][C-00000057] chan_iax2.c: Resyncing the jb. last_delay 0, this delay 10607, threshold 2802, new of
tsawyer commented 11 months ago

Another data point: Disconnecting all nodes stops the Resyncing JB messages. Reconnecting does not start the Resyncing again right away. It will take days or weeks for them to begin again.

I suppose nailing up dozens or more IAX connections for weeks and weeks is atypical Asterisk usage which may explain why this problem has not been identified or fixed. But it is a very common AllStar configuration on "hub" nodes where many "stations" join together to form a radio network.

tsawyer commented 10 months ago

Here's another server doing the same thing. I've found that disconnecting and reconnecting 2 local nodes (both nodes on this server connected via the local loopback) cleared the warning. 

[2023-11-05 14:11:56.533] WARNING[2530828][C-00000012]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 0, this delay 10367, threshold 1368, new offset -4025552785
[2023-11-05 14:11:57.518] WARNING[2530828]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 0, this delay 10415, threshold 1368, new offset -4025553756
[2023-11-05 14:12:06.894] WARNING[2530834][C-00000012]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 0, this delay 10345, threshold 1368, new offset -4025563130
[2023-11-05 14:12:07.918] WARNING[2530834]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 0, this delay 10385, threshold 1368, new offset -4025564141
[2023-11-05 14:12:17.278] WARNING[2530829][C-00000012]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 0, this delay 10375, threshold 1368, new offset -4025573505
[2023-11-05 14:12:18.333] WARNING[2530827]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 0, this delay 10407, threshold 1368, new offset -4025574548
[2023-11-05 14:12:27.614] WARNING[2530832][C-00000012]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 0, this delay 10321, threshold 1368, new offset -4025583826
[2023-11-05 14:12:28.734] WARNING[2530831]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 0, this delay 10385, threshold 1368, new offset -4025584933
[2023-11-05 14:12:37.974] WARNING[2530831][C-00000012]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 0, this delay 10351, threshold 1368, new offset -4025594177
[2023-11-05 14:12:39.134] WARNING[2530828]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 0, this delay 10391, threshold 1368, new offset -4025595324
[2023-11-05 14:12:48.334] WARNING[2530832][C-00000012]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 0, this delay 10345, threshold 1368, new offset -4025604522
[2023-11-05 14:12:49.558] WARNING[2530828]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 0, this delay 10577, threshold 1368, new offset -4025605901