Liveupdate strange behavior

britzl · January 22, 2021, 3:52pm

Thank you. Created ticket: https://github.com/defold/defold/issues/5499

Mathias_Westerdahl · January 25, 2021, 2:33pm

We now have a PR for this issue, and when it’s done, we’ll merge it into the 1.2.179 beta for you to test (today or tomorrow)

Mathias_Westerdahl · January 26, 2021, 8:50am

The 1.2.179 BETA is now updated with a fix for the #5499 issue

morgerion · January 26, 2021, 10:01am

Thank you very much!
We have checked - it works.
We’ll keep our fingers crossed for further improvements.

morgerion · March 18, 2021, 10:13am

Hello everyone!
Leeeeet’s delve into another problem with LiveUpdate.

The situation is as follows:

we are doing an apk with a LiveUpdate.
everything used to work.
but at some point the problems started.
the files of the LiveUpdate are downloading badly (see below).

We get mistakes like this:

ERROR:SCRIPT: HTTP request to 'https://battlehive.fra1.cdn.digitaloceanspaces.com/liveupdate/debug/android/02f2b6b25fa9c71be00b791bdbdbe5f6e1075dd3' failed (http result: -1  socket result: 0)
WARNING:DLIB: Unhandled ssl status code: 0 ( 0000)                                                                                                                                                 
ERROR:SCRIPT: HTTP request to 'https://battlehive.fra1.cdn.digitaloceanspaces.com/liveupdate/debug/android/5cadeca8fbc4831e13b724e3a0c88f077b0b9294' failed (http result: -1  socket result: -1000)

Apart from that, it is very common for a message like this to drop:

INFO:DLIB: Flushing http cache to disk

What the hell is that?

And in the end we get this outcome:

ERROR:RESOURCE: Byte mismatch in decrypted manifest signature. Different keys used for signing?                     
ERROR:LIVEUPDATE: Verification failure for Liveupdate archive for resource: 02f2b6b25fa9c71be00b791bdbdbe5f6e1075dd3

BUT! We have already downloaded this file, and successfully!
Yes, the first time it didn’t want to download (see above) but our system re-runs the download in such situations.

What do you think about this?

Mathias_Westerdahl · March 18, 2021, 10:39am

The “Flushing http cache to disk” comes from storing the latest http request info (such as the ETag and max age).

github.com

defold/defold/blob/cc9389b14e0ebd9edea8c3f37e72e35b42808f97/engine/dlib/src/dlib/http_cache.cpp#L371


}


Result Flush(HCache cache)
{
    dmMutex::ScopedLock lock(cache->m_Mutex);
    if (!cache->m_Dirty) {
        return RESULT_OK;
    }


    cache->m_Dirty = false;
    dmLogInfo("Flushing http cache to disk");


    char cache_file[DMPATH_MAX_PATH];
    dmSnPrintf(cache_file, sizeof(cache_file), "%s/%s", cache->m_Path, "index");
    FILE* f = fopen(cache_file, "wb");
    if (f) {
        Result r = WriteIndex(cache, f);
        fclose(f);
        if (r != RESULT_OK) {
            dmLogError("Error writing to index file '%s'", cache_file);
            dmSys::Unlink(cache_file);

The cache is written to disc every 5 seconds (if it’s dirty):

github.com

defold/defold/blob/cc9389b14e0ebd9edea8c3f37e72e35b42808f97/engine/script/src/http_service.cpp#L328


void Loop(void* arg)
{
    Worker* worker = (Worker*) arg;


    uint64_t flush_period = 5 * 1000000U;
    uint64_t next_flush = dmTime::GetTime() + flush_period;
    while (worker->m_Run)
    {
        dmMessage::DispatchBlocking(worker->m_Socket, &Dispatch, worker);
        if (worker->m_CacheFlusher &&  dmTime::GetTime() > next_flush) {
            dmHttpCache::Flush(worker->m_Service->m_HttpCache);
            next_flush = dmTime::GetTime() + flush_period;
        }
    }
}


static void LoadBalancer(void* arg)
{
    HttpService* service = (HttpService*) arg;
    while (service->m_Run) {
        dmMessage::DispatchBlocking(service->m_Socket, &LoadBalance, service);

We have already downloaded this file, and successfully!

Is this the manifest file?
If so, are the ETag and the expiration changed? What is the return HTTP code?

Still, it seems strange that the manifest signature would differ if it’s the same file

As for the https request failing, I’m not really sure what’s causing it. I’m not even sure the socket code “0” is an error code, which is also curious.
What if you print out the headers in this case, what info (e.g. status code) do they return?

britzl · March 18, 2021, 5:00pm

Do you know when and what caused it? An update of Defold? Some change to the server hosting the files?

morgerion · March 18, 2021, 8:54pm

No. Nothing supernatural was going on. It was the first thing we thought of, so we carefully checked exactly what we were changing.

No, it’s just the biggest file in the LiveUpdate - it’s 12 mb. There is only one such file.

D defold  : DEBUG:SCRIPT: URL_NEW:	http://46.216.55.60:8000/debug/android/liveupdate.game.dmanifest
E defold  : ERROR:SCRIPT: HTTP request to 'http://46.216.55.60:8000/debug/android/liveupdate.game.dmanifest' failed (http result: -1  socket result: 0)
W defold  : WARNING:DLIB: Profiler Message.Dispatch @__http_worker_2 took 10.008 seconds
D defold  : DEBUG:SCRIPT: 
D defold  : { --[[0x7c0d02e570]]
D defold  :   status = 0,
D defold  :   response = "
D defold  : ©ГA
D defold  : &†Ъћ (2
D defold  : _»+~јФJњвфѓ.gJ…@њ[Aі
D defold  : „†.Ч‹ъО"Rе;Т=Ц—?
D defold  : Ъ9Јо^kK
D defold  : ?/main/windows/player_new_level/player_new_level_generated_0.gocн“игќҐњ
D defold  : »|",
D defold  :   headers = { --[[0x7c0d02e600]]
D defold  :     server = "SimpleHTTP/0.6 Python/3.8.5",
D defold  :     content-type = "application/octet-stream",
D defold  :     content-length = "1073730",
D defold  :     last-modified = "Thu, 18 Mar 2021 14:21:04 GMT",
D defold  :     date = "Thu, 18 Mar 2021 14:32:11 GMT"
D defold  :   }
D defold  : }
D defold  : DEBUG:SCRIPT: unloaded:	hash: [loading]	->  loaded:	hash: [error]

morgerion · March 18, 2021, 9:03pm

We have a theory.

In the project settings (game.project) there is an item “http_timeout”. The feeling is that this value has an effect even in situations where the timeout is set explicitly.

Next, the file that can not download properly (or can not be saved via resource.store_resource) is the largest file in the entire archive - 12 mb.
However, this is not the case for all users. But it is common enough to be a nuisance.

The funny part of the problem is that this file is downloaded in 4 seconds from the browser, but cannot be downloaded via http.request() from the project.

Perhaps the problem is in the implementation of http.request()?

britzl · March 18, 2021, 9:41pm

Cannot be downloaded? How? Do you get an error?

Are you using the new way of directly downloading to file instead of to memory?

local options = {
    path = "some/path"
}
http.request(..., options)

PS Not sure if it’s only the path you need to provide or path and filename… @JCash knows.

Mathias_Westerdahl · March 19, 2021, 7:41am

@britzl we don’t yet have a way to store a single resource directly from disc.

Also “path” to me suggests directory+ filename name. And yes, you specify the path where the file is to be saved.

Mathias_Westerdahl · March 19, 2021, 7:52am

The network.http_timeoutis used as the default value. If you specify a timeout, it will be used instead.

github.com

defold/defold/blob/dev/engine/script/src/script_http.cpp#L183-L195


uint64_t timeout = g_Timeout;
const char* path = 0;
bool ignore_cache = false;
if (top > 5 && !lua_isnil(L, 6)) {
    luaL_checktype(L, 6, LUA_TTABLE);
    lua_pushvalue(L, 6);
    lua_pushnil(L);
    while (lua_next(L, -2)) {
        const char* attr = lua_tostring(L, -2);
        if (strcmp(attr, "timeout") == 0)
        {
            timeout = luaL_checknumber(L, -1) * 1000000.0f;
        }

Next, the file that can not download properly (or can not be saved via resource.store_resource) is the largest file in the entire archive - 12 mb.

I don’t think our code having any size constraints per se, however, it is an interesting attribute that might be a clue to what’s going on.

The funny part of the problem is that this file is downloaded in 4 seconds from the browser, but cannot be downloaded via http.request() from the project.
Perhaps the problem is in the implementation of http.request()?

It’s hard to tell without investigating some more.
Perhaps you can provide me with that url so I can make some tests towards it too?

As for the suggestion @britzl gave, it’s not (yet) useful for storing live update files one by one. It’s used when downloading the entire .zip file at once. We should look into that very soon though, as it’s faster/leaner than passing all that data via Lua.

britzl · March 19, 2021, 8:11am

Sorry for confusing things! But a good option for the future.

morgerion · March 19, 2021, 9:24am

https://battlehive.fra1.cdn.digitaloceanspaces.com/liveupdate/debug/android/02f2b6b25fa9c71be00b791bdbdbe5f6e1075dd3

Mathias_Westerdahl · March 19, 2021, 10:58am

I can’t reproduce the failed http.request() locally.
Even tried with a network limiter set to 20mbps, and the download takes ~20 seconds.

I wonder if it could be that if bad data is stored in the http cache, the next time we ask for that data, we’ll get bad data back.
Then when we want to store it in live resources, it will produce the manifest signature error. Perhaps if you calculate and print a checksum for that file, to compare

You mention your “system re-runs the download in such situations.”, do you set the “ignore_cache” in that case?
If not, it might retrieve the file again from the cache (if it’s in the cache), so it might be a good thing to try. (not as a permanent solution, but to help try pinpoint the issue)

EDIT: I do get the “/url/ failed (http result: -1 socket result: 0)” if I set it to timeout.
I don’t get the “Unhandled ssl status code” though.

Mathias_Westerdahl · March 20, 2021, 9:22am

@morgerion After looking further into the http requests, I found some issues, and indeed they were related to timeout issues. I have PR’s ready for @britzl and they should be in the next release.

The per-request timeout value wasn’t always used #5669
Don’t reuse socket connection after the previous request (using the same connection) timed out. (Fixes the “Unhandled ssl status code: 0 ( 0000)” in this case) #5671

morgerion · March 20, 2021, 11:30am

Oh, that’s interesting.

In general, our problem is roughly this:

when using wi-fi it is very rare that a 12 mb file cannot be downloaded.
when using a mobile network this file can’t be downloaded often.
in all these cases using a foreign download method (e.g. via a browser) works fine.

I get the impression that http.request() is working strangely.
Suppose a timeout is to blame. But why does the browser download this file in 4 seconds, but http.request() cannot download in 30 seconds?

Mathias_Westerdahl · March 20, 2021, 2:07pm

I’m not sure. during these tests I never got a download time above .6 seconds for that 12mb file (on my Wifi) using Defold.

I just tested using my cell network which is at 15mbit currently, and that worked fine too. Downloading the file in Defold took 5.1s and using wget it tool 7.2s.

Currently I have no real clue as to why in your case it doesn’t download faster.

Both fixes are now building on the alpha branch, and I’ll let you know when you can test that to see if the behavior is still the same.

Edit: The build is now available on https://d.defold.com/alpha/

morgerion · March 25, 2021, 11:20pm

And one more question regarding http.request() behaviour.
If we use up to 32 simultaneous calls to http.request(), the LiveUpdate takes on average a minute to download.
But if we use 4 simultaneous calls to http.request(), the download time averages 4 minutes.

Why? What is the optimal number of simultaneous http.requests()?

britzl · March 26, 2021, 5:07am

I need to do some tests and read a bit of code to give you a definitive answer. One thing I know it’s that the http_service.cpp uses a thread per http_client.cpp instance. The default thread count is 4 but can be configured through the game project setting network.http_thread_count. I’m not entirely sure what happens when more requests are made than the number of threads. I need to investigate this.