AC script generating temporary entities stopped to work after moved my domain to Overte

[AleziaKurdis]

Somewhere during the 2 last months, I added this AC script
that simply generates a temporary entity (50 sec lifetime) every 3 seconds.

http://metaverse.bashora.com/objects/virz_junction/ACfirepitCubili.js

It was working fine on Vircadia, but after has moved my domain to Overte, the script has stopped stopped to work.
No more entities are generated.
The script doesn't seems to fail. so it could be a problem to transmit this to the client.

[daleglass]

Been testing it a bit. So far, entities seem to be generated but not transmitted. Also, the problem seems to go a very long way back and to be present in the current Vircadia.

[AleziaKurdis]

Very possible that the build used by the domain wasn't the latest Vircadia's build but the one just before. (I might not have update it if there was no protocol changes)
This seems to be a relatively sever bug for this system. I can probably managed this differently but sooner or later this will be a problem for someone... a server that doesn't serve.

[daleglass]

I'm looking into it. Do you have a server I could connect to and see what it's supposed to look like?

[AleziaKurdis]

Sadly only one whit the script broken (See the "firepit" outside at Virz-Junction)

You can also make a copy of the script, change the position (in the begining of the script) and run it on your own.
this is generating a cube every 3 sec.

[daleglass]

I should see the cubes in the entity list in Create, right? So far I've gone back to Nov 1, 2021, and it still doesn't seem to work.

So I'm wondering if it's very old, or I'm looking for the wrong thing there.

[ksuprynowicz]

Edit: I instrumented the script incorrectly. It works like it should.
Something is most definitely wrong. I put print functions in it and the script is restarting all the time for some reason:

Jul 17 15:37:52 KSu01 assignment-client[23034]: [] GC update start
Jul 17 15:37:52 KSu01 assignment-client[23034]: [] GC Init start
Jul 17 15:37:52 KSu01 assignment-client[23034]: [] GC Init end
Jul 17 15:37:52 KSu01 assignment-client[23034]: [] GC update start
Jul 17 15:37:55 KSu01 assignment-client[23034]: [] GC update start
Jul 17 15:37:55 KSu01 assignment-client[23034]: [] GC Init start
Jul 17 15:37:55 KSu01 assignment-client[23034]: [] GC Init end
Jul 17 15:37:55 KSu01 assignment-client[23034]: [] GC update start
Jul 17 15:37:58 KSu01 assignment-client[23034]: [] GC update start
Jul 17 15:37:58 KSu01 assignment-client[23034]: [] GC Init start
Jul 17 15:37:58 KSu01 assignment-client[23034]: [] GC Init end
Jul 17 15:37:58 KSu01 assignment-client[23034]: [] GC update start
Jul 17 15:38:01 KSu01 assignment-client[23034]: [] GC update start
Jul 17 15:38:01 KSu01 assignment-client[23034]: [] GC Init start
Jul 17 15:38:01 KSu01 assignment-client[23034]: [] GC Init end
Jul 17 15:38:01 KSu01 assignment-client[23034]: [] GC update start

Init-related messages should show only once.

[ksuprynowicz]

I noticed a few error messages in AC server:

Jul 17 15:47:19 KSu01 assignment-client[23713]: DependencyManager::get(): No instance available for 8NodeList
Jul 17 15:47:19 KSu01 assignment-client[23713]: DependencyManager::get(): No instance available for 20DomainAccountManager
Jul 17 15:47:19 KSu01 assignment-client[23713]: QObject::startTimer: Timers cannot have negative intervals

I'm not sure if two first ones are a problem, but the third one probably is.

[daleglass]

The first one of those I'm fairly sure is a harmless bug. Not sure about the second, but the third is definitely worth a check.

[ksuprynowicz]

This is also suspicious:

Jul 17 16:13:28 KSu01 assignment-client[22838]: Script Engine has been running too long, throwing: "about:Entities 1"
Jul 17 16:13:28 KSu01 assignment-client[22838]: [about:Entities 1] Script Engine has stopped:about:Entities 1
Jul 17 16:13:28 KSu01 assignment-client[22838]: Stopping all scripts.... currently known scripts: 1
Jul 17 16:13:28 KSu01 assignment-client[22838]: DONE Stopping all scripts....

[vegaslon]

perhaps this change is causing this? , vircadia/vircadia-native-core#1353

[ksuprynowicz]

The weirdest part is that the script works somwtimes for some reason:

[ksuprynowicz]

This seems to be related to a lot of other problems where entity messages are not sent. For example with voxels sometimes the messages about properties such as scale or dimensions are not sent too, and sometimes just restarting the server helps.

[ksuprynowicz]

perhaps this change is causing this? , vircadia/vircadia#1353

This would be worth checking, especially since the problem happens in a lot of different situations

[daleglass]

Definitely worth looking into

[ksuprynowicz]

I tried adding more such scripts, but they fail to run at all with this message:

Jul 17 17:11:45 KSu01 assignment-client[27774]: [] [UncaughtException evaluate(lint)] Error: Expected `;', `;' in :1
                                                [Backtrace]
                                                    <global>() at -1

[ksuprynowicz]

perhaps this change is causing this? , vircadia/vircadia#1353

It turns out we don't have this PR merged yet.

[vegaslon]

might be a fix then to this issue.

[ksuprynowicz]

When I run assignment client in a debugger, I get entirely different message:

[07/17 18:39:10] [CRITICAL] [hifi.scriptengine] [32338] [agent] [] [UncaughtException evaluate] Error: Can't find variable: avs_sent_last_frame in :1
[07/17 18:39:10] [CRITICAL] [hifi.scriptengine] [32338] [agent] [Backtrace]
[07/17 18:39:10] [CRITICAL] [hifi.scriptengine] [32338] [agent]     <global>() at 1

[ksuprynowicz]

The problem is that every time I run it in debugger it works in a different way. Sometimes critical error message appears and sometimes nothing happens at all.

[ksuprynowicz]

Most of the time when adding script from Domain Server's web UI, script content is displayed as empty, and the script won't run:

[07/17 18:45:13] [INFO] [default] [32815] [agent] Downloaded script: ""

It happens at line 352 in assignment-client/src/Agent.cpp

[ksuprynowicz]

It seems like the part that downloads script is broken:

[07/17 19:47:19] [INFO] [default] [46429] [agent] Downloaded script: "������������������������������������������\u0001"

[daleglass]

Well! That looks like a buffer overflow somewhere

[ksuprynowicz]

That would explain the random behavior

[ksuprynowicz]

For example this time I got:

[07/17 19:53:47] [INFO] [default] [49321] [agent] Downloaded script: "n"
[07/17 19:53:47] [INFO] [default] [49321] [agent] Script URL: "http://127.0.0.1:40100/assignment/1c1d6f52-1709-4903-89c0-640a4d958f6f/"

And later an error:

[07/17 19:53:47] [CRITICAL] [hifi.scriptengine] [49321] [agent] [] [UncaughtException evaluate] Error: Can't find variable: n in :1
[07/17 19:53:47] [CRITICAL] [hifi.scriptengine] [49321] [agent] [Backtrace]
[07/17 19:53:47] [CRITICAL] [hifi.scriptengine] [49321] [agent]     <global>() at 1

[ksuprynowicz]

It looks like the first time the script is sent from domain server it is correct, and the second time it gets corrupted. The bug is on domain server side and not on assignment client side.
To debug further I added this at line 2224 in DomainServer.cpp:
qDebug() << "Ephemeral AC script content: " << qPrintable(it->second);

[ksuprynowicz]

It seems that it's being correctly received from the domain server web UI evert time (line 2499), but gets corrupted before being sent. One example of corrupted data:
[07/17 22:28:35] [DEBUG] [default] Ephemeral AC script content send: can have which <a data-toggle='tooltip' data-html=true title='<p><strong>Domain-Wide User Permissions</strong></p><ul><li><strong>Connect</stronr

[ksuprynowicz]

When domain server runs with Valgrind everything works perfectrly each time.
Here's the Valgrind log:
http://oaktown.pl/tmp/valgrind.log

[ksuprynowicz]

I think we might have found a fix. I will test it tomorrow and post a PR.