[emulator:database] Long Polling fails when listening on 0.0.0.0

[yuri-sergiichuk]

[REQUIRED] Environment info

firebase-tools: 8.16.2

Platform: Alpine Linux Docker image.

[REQUIRED] Test case

The companion repository with a test example and detailed readme available here: https://github.com/yuri-sergiichuk/firebase-rdb-docker-issue.

[REQUIRED] Steps to reproduce

1. Start Dockerized Firebase RDB emulator with host being set to 0.0.0.0.
2. Try to read/write data from/to the emulator.

[REQUIRED] Expected behavior

You must be able to use the emulator via a forwarded port on localhost.

[REQUIRED] Actual behavior

The emulator handles the first .lp?start request but redirects the caller to 0.0.0.0 and requests fail.

Here's a dump of requests being sent to the emulator from the web page:

---
http://localhost:54897/.lp?start=t&ser=75118654&cb=1&v=5&ns=fake-server

response: 

function pLPCommand(c, a1, a2, a3, a4) {
parent.window["pLPCommand1"] && parent.window["pLPCommand1"](c, a1, a2, a3, a4);
}
function pRTLPCB(pN, data) {
parent.window["pRTLPCB1"] && parent.window["pRTLPCB1"](pN, data);
}
         pLPCommand('start','1','nxExCrtfPv');
pRTLPCB(0,[{"t":"c","d":{"t":"h","d":{"ts":1606404821657,"v":"5","h":"0.0.0.0:54897","s":"kIsNLt22OP58UjyvSTXykWsJGyxPfWEA"}}}]);

---
http://0.0.0.0:54897/.lp?id=1&pw=nxExCrtfPv&ser=42313306&ns=fake-server
---
http://0.0.0.0:54897/.lp?dframe=t&id=1&pw=nxExCrtfPv&ns=fake-server
---
http://0.0.0.0:54897/.lp?id=1&pw=nxExCrtfPv&ser=42313307&ns=fake-server&seg0=0&ts0=1&d0=eyJ0IjoiZCIsImQiOnsiciI6MSwiYSI6InMiLCJiIjp7ImMiOnsic2RrLmpzLjgtMS0xIjoxfX19fQ..
---
http://0.0.0.0:54897/.lp?start=t&ser=96003070&cb=2&v=5&ls=kIsNLt22OP58UjyvSTXykWsJGyxPfWEA&ns=fake-server

WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by io.netty.util.internal.ReflectionUtil (file:/root/.cache/firebase/emulators/firebase-database-emulator-v4.7.1.jar) to field sun.nio.ch.SelectorImpl.selectedKeys
WARNING: Please consider reporting this to the maintainers of io.netty.util.internal.ReflectionUtil
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
15:50:52.634 [NamespaceSystem-akka.actor.default-dispatcher-5] INFO akka.event.slf4j.Slf4jLogger - Slf4jLogger started
15:50:52.779 [main] INFO com.firebase.server.forge.App$ - Listening at 0.0.0.0:54897

[debug] [2020-11-26T15:50:51.160Z] ----------------------------------------------------------------------
[debug] [2020-11-26T15:50:51.163Z] Command:       /usr/local/bin/node /usr/local/bin/firebase emulators:start --debug
[debug] [2020-11-26T15:50:51.163Z] CLI Version:   8.16.2
[debug] [2020-11-26T15:50:51.163Z] Platform:      linux
[debug] [2020-11-26T15:50:51.163Z] Node Version:  v14.15.1
[debug] [2020-11-26T15:50:51.164Z] Time:          Thu Nov 26 2020 15:50:51 GMT+0000 (Coordinated Universal Time)
[debug] [2020-11-26T15:50:51.164Z] ----------------------------------------------------------------------
[debug] [2020-11-26T15:50:51.164Z]
[debug] [2020-11-26T15:50:51.165Z] >>> [apiv2][query] GET https://firebase-public.firebaseio.com/cli.json [none]
[debug] [2020-11-26T15:50:51.190Z] > command requires scopes: ["email","openid","https://www.googleapis.com/auth/cloudplatformprojects.readonly","https://www.googleapis.com/auth/firebase","https://www.googleapis.com/auth/cloud-platform"]
[debug] [2020-11-26T15:50:51.200Z] FirebaseError: Failed to authenticate, have you run firebase login?
[warn] ⚠  emulators: You are not currently authenticated so some features may not work correctly. Please run firebase login to authenticate the CLI.
[info] i  emulators: Starting emulators: database {"metadata":{"emulator":{"name":"hub"},"message":"Starting emulators: database"}}
[debug] [2020-11-26T15:50:51.206Z] database rules config:  []
[warn] ⚠  database: Did not find a Realtime Database rules file specified in a firebase.json config file. The emulator will default to allowing all reads and writes. Learn more about this option: https://firebase.google.com/docs/emulator-suite/install_and_configure#security_rules_configuration. {"metadata":{"emulator":{"name":"database"},"message":"Did not find a Realtime Database rules file specified in a firebase.json config file. The emulator will default to allowing all reads and writes. Learn more about this option: https://firebase.google.com/docs/emulator-suite/install_and_configure#security_rules_configuration."}}
[debug] [2020-11-26T15:50:51.208Z] Ignoring unsupported arg: projectId {"metadata":{"emulator":{"name":"database"},"message":"Ignoring unsupported arg: projectId"}}
[debug] [2020-11-26T15:50:51.209Z] Ignoring unsupported arg: auto_download {"metadata":{"emulator":{"name":"database"},"message":"Ignoring unsupported arg: auto_download"}}
[debug] [2020-11-26T15:50:51.209Z] Ignoring unsupported arg: rules {"metadata":{"emulator":{"name":"database"},"message":"Ignoring unsupported arg: rules"}}
[debug] [2020-11-26T15:50:51.209Z] Starting Database Emulator with command {"binary":"java","args":["-Duser.language=en","-jar","/root/.cache/firebase/emulators/firebase-database-emulator-v4.7.1.jar","--host","0.0.0.0","--port",54897],"optionalArgs":["port","host","functions_emulator_port","functions_emulator_host"],"joinArgs":false} {"metadata":{"emulator":{"name":"database"},"message":"Starting Database Emulator with command {\"binary\":\"java\",\"args\":[\"-Duser.language=en\",\"-jar\",\"/root/.cache/firebase/emulators/firebase-database-emulator-v4.7.1.jar\",\"--host\",\"0.0.0.0\",\"--port\",54897],\"optionalArgs\":[\"port\",\"host\",\"functions_emulator_port\",\"functions_emulator_host\"],\"joinArgs\":false}"}}
[info] i  database: Database Emulator logging to database-debug.log {"metadata":{"emulator":{"name":"database"},"message":"Database Emulator logging to \u001b[1mdatabase-debug.log\u001b[22m"}}
[debug] [2020-11-26T15:50:51.691Z] <<< [apiv2][status] GET https://firebase-public.firebaseio.com/cli.json 200
[debug] [2020-11-26T15:50:51.691Z] <<< [apiv2][body] GET https://firebase-public.firebaseio.com/cli.json {"cloudBuildErrorAfter":1594252800000,"cloudBuildWarnAfter":1590019200000,"defaultNode10After":1594252800000,"minVersion":"3.0.5","node8DeploysDisabledAfter":1613390400000,"node8RuntimeDisabledAfter":1615809600000,"node8WarnAfter":1600128000000}
[debug] [2020-11-26T15:50:51.873Z] WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by io.netty.util.internal.ReflectionUtil (file:/root/.cache/firebase/emulators/firebase-database-emulator-v4.7.1.jar) to field sun.nio.ch.SelectorImpl.selectedKeys
WARNING: Please consider reporting this to the maintainers of io.netty.util.internal.ReflectionUtil
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
 {"metadata":{"emulator":{"name":"database"},"message":"WARNING: An illegal reflective access operation has occurred\nWARNING: Illegal reflective access by io.netty.util.internal.ReflectionUtil (file:/root/.cache/firebase/emulators/firebase-database-emulator-v4.7.1.jar) to field sun.nio.ch.SelectorImpl.selectedKeys\nWARNING: Please consider reporting this to the maintainers of io.netty.util.internal.ReflectionUtil\nWARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations\nWARNING: All illegal access operations will be denied in a future release\n"}}
[debug] [2020-11-26T15:50:52.637Z] 15:50:52.634 [NamespaceSystem-akka.actor.default-dispatcher-5] INFO akka.event.slf4j.Slf4jLogger - Slf4jLogger started
 {"metadata":{"emulator":{"name":"database"},"message":"15:50:52.634 [NamespaceSystem-akka.actor.default-dispatcher-5] INFO akka.event.slf4j.Slf4jLogger - Slf4jLogger started\n"}}
[debug] [2020-11-26T15:50:52.780Z] 15:50:52.779 [main] INFO com.firebase.server.forge.App$ - Listening at 0.0.0.0:54897
 {"metadata":{"emulator":{"name":"database"},"message":"15:50:52.779 [main] INFO com.firebase.server.forge.App$ - Listening at 0.0.0.0:54897\n"}}
[info]
┌──────────────────────────────────────────────────────────────┐
│ ✔  All emulators ready! It is now safe to connect your apps. │
└──────────────────────────────────────────────────────────────┘

┌──────────┬───────────────┐
│ Emulator │ Host:Port     │
├──────────┼───────────────┤
│ Database │ 0.0.0.0:54897 │
└──────────┴───────────────┘
  Other reserved ports:

[yuri-sergiichuk]

Also, the REST API of the emulator works perfectly with such a setup and one can reach the emulator on the forwarded 54798 port using e.g. the following command http localhost:54897/.json which returns the following response:

HTTP/1.1 200 OK
Access-Control-Allow-Origin: *
Cache-Control: no-cache
Content-Length: 4
Content-Type: application/json; charset=utf-8
X-Firebase-Project-Id: fake-server
X-Firebase-Project-Number: 123456789
X-Firebase-Uuid: 8b03ef40-101d-4ca2-ac6f-847d1f7451eb

null

[samtstern]

@yuchenshi or @crwilcox could you take a look at this?

[crwilcox]

Could you mention WSL in the title of the issue? We have seen a number of issues specifically with WSL.

I think firebase/firebase-tools-ui#332 captures most of it. Can you compare your configuration with the config at the end of the issue?

[yuri-sergiichuk]

@crwilcox thx for taking a look at the issue.

I'm not sure it's a WSL issue because I do not run the emulator in the WSL. I use a docker image with the emulator and just start the docker image from Windows PC.

I've just explicitly disabled WSL support on my laptop and reproduced the issue once again.

I'm using the following firebase.json configuration inside the container:

{
  "emulators": {
    "database": {
      "port": "54897",
      "host": "0.0.0.0"
    }
  }
}

I believe that's the one that is recommended as a workaround for WSL users, but again, I'm not running the emulator inside WSL and I'm not binding it to 127.0.0.1.

To run inside the container, I bind the emulator to 0.0.0.0 and then map the emulator port 54897 to the host port 54897. From now on I'm able to access the emulator using either localhost:54897 or 127.0.0.1:54897.

My first request to the emulator goes to the http://127.0.0.1:54897/.lp?start=t&ser=68955949&cb=1&v=5&ns=fake-server and is successful, but the emulator sends back a response to follow up the connection on 0.0.0.0:54897 and that's the place where everything is going to fail.

I mentioned in the issue a repo with a test case and instructions on how to reproduce it: https://github.com/yuri-sergiichuk/firebase-rdb-docker-issue.

I'm also going to do a manual test in Linux env tomorrow.

[yuri-sergiichuk]

I did a check on my Linux machine and what is interesting is that the emulator itself behaves differently while running on Windows and on Linux.

On Windows, it (probably) downgraded my connection from web sockets to HTTP, and then a see the reported error behavior. While on Linux I do not see any HTTP connections to the emulator at all. It just works over the WS and works fine!

Here's what going in the WS data frames:

@crwilcox is there anything else I can grab to help to investigate the issue? It's really blocking us from switching to dockerized environments as the behavior is not consistent for all developers.

[yuchenshi]

FYI: the RTDB JS SDK has a feature where it remembers that connection fails over WebSocket and will fallback to long polling on subsequent tries. It does that by storing a flag in localStorage which persists. Please try again on Windows with a different browser or incognito window and see if it helps. (I think localStoage.clear() may also do the trick, but I'm not 100% sure about this.)

[yuri-sergiichuk]

@yuchenshi you're a lifesaver!

The web page indeed had a value in the local storage and as soon as I removed the entry my simplified example started working. I hope I'll be able to have this same fix applied to our main application and if so, it looks like there's no actual issue with the emulator (except that it may need to improve the long polling support).

[yuri-sergiichuk]

FYI: the RTDB JS SDK has a feature where it remembers that connection fails over WebSocket and will fallback to long polling on subsequent tries. It does that by storing a flag in localStorage which persists. Please try again on Windows with a different browser or incognito window and see if it helps. (I think localStoage.clear() may also do the trick, but I'm not 100% sure about this.)

Works like a charm. In case you see your RTDB connection started working over HTTP while web sockets are expected, prune the local storage and you must be good to go!

I'm closing the issue now. @crwilcox @yuchenshi thx for your help. I guess it might be a good idea to still investigate why the HTTP fallback is not working, but that's a different story.

[yuchenshi]

I've filed an internal bug tracking the redirect issue for the long polling request: b/175025844.

[yuri-sergiichuk]

@yuchenshi any updates on the internal bug? It is a bit annoying to clear the local storage flag each time :-(

[yuchenshi]

We don't have any updates to share at this point. Feel free to dig into why the WebSocket connection fails and open a new bug, and/or make deleting that storage key part of your setup code as a workaround.