Strange Error "Terminating renderer for bad IPC message, reason 167" for html template

General
, ,
1

Hi,
I’m getting this error, which happens randomly and it isn’t in the log, only on the server console window

[0620/140004.010:ERROR:bad_message.cc(27)] Terminating renderer for bad IPC message, reason 167

and the full log
[I had to select all and copy the server window to show you]

[2022-06-20 13:59:33.045524] [0x00003fcc] [error]    0# 0x00007FF7C427B906 in casparcg
 1# 0x00007FF7C428F080 in casparcg
 2# raise in ucrtbase
 3# abort in ucrtbase
 4# 0x00007FF7C428F55E in casparcg
 5# terminate in ucrtbase
 6# is_exception_typeof in VCRUNTIME140
 7# is_exception_typeof in VCRUNTIME140
 8# _CxxFrameHandler3 in VCRUNTIME140
 9# _chkstk in ntdll
10# RtlRestoreContext in ntdll
11# RtlRaiseException in ntdll
12# RaiseException in KERNELBASE
13# CxxThrowException in VCRUNTIME140
14# 0x00007FF7C431FB6F in casparcg
15# 0x00007FF7C4521D04 in casparcg
16# 0x00007FF7C4522E2A in casparcg
17# 0x00007FF7C4534C37 in casparcg
18# 0x00007FF7C452FC97 in casparcg
19# 0x00007FF7C436DA20 in casparcg
20# 0x00007FF7C436ED94 in casparcg
21# 0x00007FF7C43DBE05 in casparcg
22# 0x00007FF7C43CD854 in casparcg
23# 0x00007FF7C43CD81C in casparcg
24# 0x00007FF7C43D2EFC in casparcg
25# 0x00007FF7C43C52CF in casparcg
26# 0x00007FF7C43CC0F7 in casparcg
27# 0x00007FF7C4382474 in casparcg
28# 0x00007FF7C43828B8 in casparcg
29# 0x00007FF7C43F20A4 in casparcg
30# 0x00007FF7C43F2FEF in casparcg
31# 0x00007FF7C43F2497 in casparcg
32# 0x00007FF7C43F2797 in casparcg
33# 0x00007FF7C42ADA82 in casparcg
34# 0x00007FF7C43E67D3 in casparcg
35# 0x00007FF7C43E69BE in casparcg
36# 0x00007FF7C43E70C4 in casparcg
37# 0x00007FF7C43EDCF6 in casparcg
38# 0x00007FF7C4284258 in casparcg
39# 0x00007FF7C428DBED in casparcg
40# 0x00007FF7C429111D in casparcg
41# 0x00007FF7C46C6A88 in casparcg
42# BaseThreadInitThunk in KERNEL32
43# RtlUserThreadStart in ntdll

Type "q" to close application.
Logging [trace] or higher severity to log/

[2022-06-20 13:59:33.067] [info]    ############################################################################
[2022-06-20 13:59:33.069] [info]    CasparCG Server is distributed by the Swedish Broadcasting Corporation (SVT)
[2022-06-20 13:59:33.069] [info]    under the GNU General Public License GPLv3 or higher.
[2022-06-20 13:59:33.069] [info]    Please see LICENSE.TXT for details.
[2022-06-20 13:59:33.069] [info]    http://www.casparcg.com/
[2022-06-20 13:59:33.069] [info]    ############################################################################
[2022-06-20 13:59:33.069] [info]    Starting CasparCG Video and Graphics Playout Server 2.3.2 4de6d18f Dev
[2022-06-20 13:59:33.964] [info]    Initializing OpenGL Device.
[2022-06-20 13:59:33.966] [info]    Initialized OpenGL 4.5.0 NVIDIA 511.69 NVIDIA Corporation
[2022-06-20 13:59:34.018] [info]    D3D11: Selected adapter: NVIDIA GeForce RTX 3070 Laptop GPU
[2022-06-20 13:59:34.018] [info]    D3D11: Selected feature level: 45312
[2022-06-20 13:59:34.021] [info]    Initialized image module.
[2022-06-20 13:59:34.022] [info]    Initialized ffmpeg module.
[2022-06-20 13:59:34.022] [info]    Initialized oal module.
[2022-06-20 13:59:34.022] [info]    Initialized decklink module.
[2022-06-20 13:59:34.022] [info]    Initialized screen module.
[2022-06-20 13:59:34.022] [info]    Initialized newtek module.
[2022-06-20 13:59:34.090] [info]    Initialized html module.
[2022-06-20 13:59:34.090] [info]    Flash support is disabled
[2022-06-20 13:59:34.090] [info]    Initialized flash module.
[2022-06-20 13:59:34.091] [info]    Initialized bluefish module.
[2022-06-20 13:59:34.091] [info]    "C:/Users\Sigourney\CasparCG\server\casparcg.config":
[2022-06-20 13:59:34.091] [info]    -----------------------------------------
[2022-06-20 13:59:34.091] [info]    <?xml version="1.0" encoding="utf-8"?>
[2022-06-20 13:59:34.091] [info]    <configuration>
[2022-06-20 13:59:34.091] [info]       <paths>
[2022-06-20 13:59:34.091] [info]          <media-path>media/</media-path>
[2022-06-20 13:59:34.091] [info]          <log-path>log/</log-path>
[2022-06-20 13:59:34.091] [info]          <data-path>data/</data-path>
[2022-06-20 13:59:34.091] [info]          <template-path>template/</template-path>
[2022-06-20 13:59:34.091] [info]       </paths>
[2022-06-20 13:59:34.091] [info]       <lock-clear-phrase>secret</lock-clear-phrase>
[2022-06-20 13:59:34.091] [info]       <log-level>trace</log-level>
[2022-06-20 13:59:34.091] [info]       <html>
[2022-06-20 13:59:34.091] [info]          <enable-gpu>true</enable-gpu>
[2022-06-20 13:59:34.091] [info]       </html>
[2022-06-20 13:59:34.091] [info]       <channels>
[2022-06-20 13:59:34.091] [info]          <channel>
[2022-06-20 13:59:34.091] [info]             <video-mode>1080i5000</video-mode>
[2022-06-20 13:59:34.091] [info]             <consumers>
[2022-06-20 13:59:34.091] [info]                <ndi>
[2022-06-20 13:59:34.091] [info]                   <name>Nostromo</name>
[2022-06-20 13:59:34.091] [info]                   <allow-fields>false</allow-fields>
[2022-06-20 13:59:34.091] [info]                </ndi>
[2022-06-20 13:59:34.091] [info]                <system-audio/>
[2022-06-20 13:59:34.091] [info]             </consumers>
[2022-06-20 13:59:34.091] [info]          </channel>
[2022-06-20 13:59:34.091] [info]          <channel>
[2022-06-20 13:59:34.091] [info]             <video-mode>1080i5000</video-mode>
[2022-06-20 13:59:34.091] [info]             <consumers>
[2022-06-20 13:59:34.091] [info]                <screen>
[2022-06-20 13:59:34.091] [info]                   <windowed>true</windowed>
[2022-06-20 13:59:34.091] [info]                   <key-only>false</key-only>
[2022-06-20 13:59:34.091] [info]                   <borderless>true</borderless>
[2022-06-20 13:59:34.091] [info]                   <interactive>true</interactive>
[2022-06-20 13:59:34.091] [info]                   <x>0</x>
[2022-06-20 13:59:34.091] [info]                   <y>0</y>
[2022-06-20 13:59:34.091] [info]                </screen>
[2022-06-20 13:59:34.091] [info]                <system-audio/>
[2022-06-20 13:59:34.091] [info]             </consumers>
[2022-06-20 13:59:34.091] [info]          </channel>
[2022-06-20 13:59:34.091] [info]       </channels>
[2022-06-20 13:59:34.091] [info]       <controllers>
[2022-06-20 13:59:34.091] [info]          <tcp>
[2022-06-20 13:59:34.091] [info]             <port>5250</port>
[2022-06-20 13:59:34.091] [info]             <protocol>AMCP</protocol>
[2022-06-20 13:59:34.091] [info]          </tcp>
[2022-06-20 13:59:34.091] [info]       </controllers>
[2022-06-20 13:59:34.091] [info]       <amcp>
[2022-06-20 13:59:34.091] [info]          <media-server>
[2022-06-20 13:59:34.091] [info]             <host>localhost</host>
[2022-06-20 13:59:34.091] [info]             <port>8000</port>
[2022-06-20 13:59:34.091] [info]          </media-server>
[2022-06-20 13:59:34.091] [info]       </amcp>
[2022-06-20 13:59:34.091] [info]    </configuration>
[2022-06-20 13:59:34.091] [info]    -----------------------------------------
[2022-06-20 13:59:34.095] [info]    Initialized OpenGL Accelerated GPU Image Mixer for channel 1
[2022-06-20 13:59:34.095] [info]    video_channel[1|1080i5000] Successfully Initialized.
[2022-06-20 13:59:34.096] [info]    Initialized OpenGL Accelerated GPU Image Mixer for channel 2
[2022-06-20 13:59:34.096] [info]    video_channel[2|1080i5000] Successfully Initialized.
[2022-06-20 13:59:34.099] [info]    Loaded "C:\Program Files\NDI\NDI 5 Tools\Runtime\Processing.NDI.Lib.x64.dll"
[2022-06-20 13:59:34.120] [info]    ndi_consumer[1|Nostromo] Initialized.
[2022-06-20 13:59:34.506] [info]    oal[1|1080i5000] Initialized.
[2022-06-20 13:59:34.507] [info]    Screen consumer [2|1080i5000] Initialized.
[2022-06-20 13:59:34.508] [info]    oal[2|1080i5000] Initialized.
[2022-06-20 13:59:34.508] [info]    Initialized channels.
[2022-06-20 13:59:34.510] [info]    Initialized controllers.
[2022-06-20 13:59:34.510] [info]    Initialized osc.
[2022-06-20 13:59:34.546] [trace]   [ffmpeg] [SWR @ 00000287E2161E80] Using fltp internally between filters
[2022-06-20 13:59:34.546] [trace]
[2022-06-20 13:59:34.546] [trace]   [ffmpeg] [SWR @ 00000287E2161E80] Matrix coefficients:
[2022-06-20 13:59:34.546] [trace]
[2022-06-20 13:59:34.546] [trace]   [ffmpeg] [SWR @ 00000287E2161E80] FL:
[2022-06-20 13:59:34.546] [trace]   [ffmpeg] FL:0.320377
[2022-06-20 13:59:34.546] [trace]   [ffmpeg] FR:0.000000
[2022-06-20 13:59:34.546] [trace]   [ffmpeg] FC:0.226541
[2022-06-20 13:59:34.546] [trace]   [ffmpeg] LFE:0.000000
[2022-06-20 13:59:34.546] [trace]   [ffmpeg] BL:0.226541
[2022-06-20 13:59:34.546] [trace]   [ffmpeg] BR:0.000000
[2022-06-20 13:59:34.546] [trace]   [ffmpeg] SL:0.226541
[2022-06-20 13:59:34.546] [trace]   [ffmpeg] SR:0.000000
[2022-06-20 13:59:34.546] [trace]   [ffmpeg]
[2022-06-20 13:59:34.546] [trace]
[2022-06-20 13:59:34.546] [trace]   [ffmpeg] [SWR @ 00000287E2161E80] FR:
[2022-06-20 13:59:34.546] [trace]   [ffmpeg] FL:0.000000
[2022-06-20 13:59:34.546] [trace]   [ffmpeg] FR:0.320377
[2022-06-20 13:59:34.546] [trace]   [ffmpeg] FC:0.226541
[2022-06-20 13:59:34.546] [trace]   [ffmpeg] LFE:0.000000
[2022-06-20 13:59:34.546] [trace]   [ffmpeg] BL:0.000000
[2022-06-20 13:59:34.546] [trace]   [ffmpeg] BR:0.226541
[2022-06-20 13:59:34.546] [trace]   [ffmpeg] SL:0.000000
[2022-06-20 13:59:34.546] [trace]   [ffmpeg] SR:0.226541
[2022-06-20 13:59:34.546] [trace]   [ffmpeg]
[2022-06-20 13:59:34.546] [trace]
[2022-06-20 13:59:34.547] [trace]   [ffmpeg] [SWR @ 00000287E21A7E80] Using fltp internally between filters
[2022-06-20 13:59:34.547] [trace]
[2022-06-20 13:59:34.547] [trace]   [ffmpeg] [SWR @ 00000287E21A7E80] Matrix coefficients:
[2022-06-20 13:59:34.547] [trace]
[2022-06-20 13:59:34.547] [trace]   [ffmpeg] [SWR @ 00000287E21A7E80] FL:
[2022-06-20 13:59:34.547] [trace]   [ffmpeg] FL:0.320377
[2022-06-20 13:59:34.547] [trace]   [ffmpeg] FR:0.000000
[2022-06-20 13:59:34.547] [trace]   [ffmpeg] FC:0.226541
[2022-06-20 13:59:34.547] [trace]   [ffmpeg] LFE:0.000000
[2022-06-20 13:59:34.547] [trace]   [ffmpeg] BL:0.226541
[2022-06-20 13:59:34.547] [trace]   [ffmpeg] BR:0.000000
[2022-06-20 13:59:34.547] [trace]   [ffmpeg] SL:0.226541
[2022-06-20 13:59:34.547] [trace]   [ffmpeg] SR:0.000000
[2022-06-20 13:59:34.547] [trace]   [ffmpeg]
[2022-06-20 13:59:34.547] [trace]
[2022-06-20 13:59:34.547] [trace]   [ffmpeg] [SWR @ 00000287E21A7E80] FR:
[2022-06-20 13:59:34.547] [trace]   [ffmpeg] FL:0.000000
[2022-06-20 13:59:34.547] [trace]   [ffmpeg] FR:0.320377
[2022-06-20 13:59:34.547] [trace]   [ffmpeg] FC:0.226541
[2022-06-20 13:59:34.547] [trace]   [ffmpeg] LFE:0.000000
[2022-06-20 13:59:34.547] [trace]   [ffmpeg] BL:0.000000
[2022-06-20 13:59:34.547] [trace]   [ffmpeg] BR:0.226541
[2022-06-20 13:59:34.547] [trace]   [ffmpeg] SL:0.000000
[2022-06-20 13:59:34.547] [trace]   [ffmpeg] SR:0.226541
[2022-06-20 13:59:34.547] [trace]   [ffmpeg]
[2022-06-20 13:59:34.547] [trace]
[2022-06-20 13:59:34.591] [info]    async_event_server[:5250] Accepted connection from 127.0.0.1 (1 connections).
[2022-06-20 13:59:34.591] [info]    Received message from 127.0.0.1: VERSION SERVER\r\n
[2022-06-20 13:59:34.591] [debug]   Executing command: VERSION
[2022-06-20 13:59:34.591] [debug]   Executed command (0s): VERSION
[2022-06-20 13:59:34.591] [info]    Sent message to 127.0.0.1:201 VERSION OK\r\n2.3.2 4de6d18f Dev\r\n




[2022-06-20 13:59:36.778] [trace]   Ready for a new command
[2022-06-20 14:00:03.875] [info]    Received message from 127.0.0.1: CG 1-20 ADD 1 "RACE_TITLE/RACE_TITLE" 1 "{\"class\":\"MX1\",\"title\":\"Prestige Championship Round 4\",\"location\":\"Arco di Trento (Trentino)\",\"race\":\"Race 2\"}"\r\n
[2022-06-20 14:00:03.875] [debug]   Executing command: CG ADD
[2022-06-20 14:00:03.875] [trace]   [cef_task] executing task
[2022-06-20 14:00:03.876] [trace]   [cef_task] task succeeded
[2022-06-20 14:00:03.876] [debug]   Executed command (0.001s): CG ADD
[2022-06-20 14:00:03.876] [info]    Sent message to 127.0.0.1:202 CG OK\r\n
[2022-06-20 14:00:03.876] [trace]   Ready for a new command
[2022-06-20 14:00:03.952] [trace]   html[file://C:\Users\Sigourney\CasparCG\server\template/RACE_TITLE/RACE_TITLE.html] 1920 1080 50.000000 [renderer_process] context for frame 3 created
[2022-06-20 14:00:03.972] [trace]   [cef_task] executing task
[2022-06-20 14:00:03.972] [trace]   [cef_task] task succeeded
[2022-06-20 14:00:03.972] [trace]   [cef_task] executing task
[2022-06-20 14:00:03.972] [trace]   [cef_task] task succeeded
[0620/140004.010:ERROR:bad_message.cc(27)] Terminating renderer for bad IPC message, reason 167




[2022-06-20 14:00:10.339] [info]    Received message from 127.0.0.1: CG 1-20 ADD 1 "RACE_TITLE/RACE_TITLE" 1 "{\"class\":\"MX1\",\"title\":\"Prestige Championship Round 4\",\"location\":\"Arco di Trento (Trentino)\",\"race\":\"Race 2\"}"\r\n
[2022-06-20 14:00:10.339] [debug]   Executing command: CG ADD
[2022-06-20 14:00:10.339] [trace]   [cef_task] executing task
[2022-06-20 14:00:10.340] [trace]   [cef_task] task succeeded
[2022-06-20 14:00:10.340] [debug]   Executed command (0.001s): CG ADD
[2022-06-20 14:00:10.340] [info]    Sent message to 127.0.0.1:202 CG OK\r\n
[2022-06-20 14:00:10.340] [trace]   Ready for a new command
[2022-06-20 14:00:10.340] [debug]   html[file://C:\Users\Sigourney\CasparCG\server\template/RACE_TITLE/RACE_TITLE.html] Destroying on asynchronous destruction thread.
[2022-06-20 14:00:10.342] [trace]   [cef_task] executing task
[2022-06-20 14:00:10.342] [trace]   [cef_task] task succeeded
[2022-06-20 14:00:10.342] [info]    html[file://C:\Users\Sigourney\CasparCG\server\template/RACE_TITLE/RACE_TITLE.html] Destroyed.
[2022-06-20 14:00:10.408] [trace]   html[file://C:\Users\Sigourney\CasparCG\server\template/RACE_TITLE/RACE_TITLE.html] 1920 1080 50.000000 [renderer_process] context for frame 3 created
[2022-06-20 14:00:10.427] [trace]   [cef_task] executing task
[2022-06-20 14:00:10.427] [trace]   [cef_task] task succeeded
[2022-06-20 14:00:10.427] [trace]   [cef_task] executing task
[2022-06-20 14:00:10.427] [trace]   [cef_task] task succeeded
[2022-06-20 14:00:26.431] [trace]   [cef_task] executing task
[2022-06-20 14:00:26.434] [trace]   [cef_task] task succeeded

the template in this case doesn’t start, but trying other times eventually the error disappear and the template starts
(sometimes 1~2 is enough, sometimes not)

the template is vanilla javascript
running on server 2.3.3 LTS
pc is on windows 11

I’m afraid I’m missing something to install but according to the github page there is nothing needed
and also with “trace” level log there are few lines at the beginning that looks like other errors

any idea what it is?
for now it is just annoying and everything seems to work fine

thanks, Andrea

2

Not a high probability of being your issue, but just in case…

I found 1 reference to a very similar message using a web search. Does your webpage open a websocket to fetch data? If so, check if the socket opened correctly and that the data format returned in response to the web socket request is correctly encoded as JSON.

The chromium cource code for the bad message handler includes a function:

void LogBadMessage(BadMessageReason reason) {
  static auto* const bad_message_reason = base::debug::AllocateCrashKeyString(
      "bad_message_reason", base::debug::CrashKeySize::Size64);
  TRACE_EVENT_INSTANT1("ipc,security", "content::ReceivedBadMessage",
                       TRACE_EVENT_SCOPE_THREAD, "reason", reason);
  LOG(ERROR) << "Terminating renderer for bad IPC message, reason " << reason;
  base::UmaHistogramSparse("Stability.BadMessageTerminated.Content", reason);
  base::debug::SetCrashKeyString(bad_message_reason,
                                 base::NumberToString(reason));
}

The error message you see references line 27, which is the line that starts TRACE_EVENT_INSTANT1 in the code above.

3

Thanks @andyw but unfortunately no websocket is involved, just an xml file loaded with xhr request.
But also other templates without xhr does the same.
Looks like some templates are more affected than others, but I cannot find any significant difference.

4

Websockets are used for the CEF debug port. I’d guess you either have something listening on the same port as html->debug_port in casparcg.config or something that connects to that port automatically.

5

I’m not very familiar with websocket, I try to comment/uncommet the debugging port in the config file

<remote-debugging-port>54001</remote-debugging-port>

but the error still remains, still random
without a deckling consumer looks like a bit less frequent, but can’t be sure

6

I too, am seeing this error sometimes with 2.3.3 of CasparCG server.

Initially, the config file did not have a remote-debugging-port specified, and later, I added it, but, it did not appear to make any difference. Template failed to be started in both cases.

7

Ok, so, I can provide an update on this…

In this case, I have a template that has three.js being used.

If the initialization of three.js happens perhaps too early, I see the dreaded error.

If the initialization of three.js is delayed until as late as possible, even after the ‘load’ event has happened (eg: after the ‘update()’ method is called), then I do not see the error, and the template seems to work very reliably.