Connection to Boxinecloud stopped working

elektroverteiler · April 5, 2024, 6:50pm

Hi all,

sadly my teddycloud does not connect to the Boxine Cloud anymore, when I try I get the following error:

INFO |server.c:0248:httpServerRequestCallback| UA=toniebox-esp32-eu/v5.230.0, ESPFW=eu/v5.230.0
INFO |handler_cloud.c:0303:handleCloudContent|  >> client requested content for rUID 425e1d1b500304e0, auth 019E5164...
INFO |handler_cloud.c:0476:handleCloudContent| Serve cloud content from /v2/content/425e1d1b500304e0
INFO |cloud_request.c:0158:web_request| Connecting to HTTP server prod.de.tbs.toys:443...
INFO |cloud_request.c:0208:web_request|   trying IP: 3.69.182.181
INFO |cloud_request.c:0036:httpClientTlsInitCallbackBase| Initializing TLS...
INFO |cloud_request.c:0071:httpClientTlsInitCallbackBase| Initializing TLS done
ERROR|cloud_request.c:0218:web_request| Failed to connect to HTTP server! Error=271

Here is what I tried:

tried teddycloud versions tc_v0.3.5 and tc_v0.4.3
created new docker container and copied in certificates
reflashed Toniebox. I reset it to factory settings in attempt to get rid of another problem.

My custom tags still work, but the tonies not (since the content cannot be downloaded). Also the setup after flashing fails. I got it to work by enabling ota and disabling it again before the toniebox times out.

What am I missing?

Thanks for your help!

Tobi

0xbadbee · April 5, 2024, 7:16pm

Please try a freshnessCheck to test the connection to teddyCloud. (Long ear press) and check the logs then and post them here.

The failing setup is a known problem. Beware that an update may overwrite your patched hostname on your box (if you did that).

If flashing isn’t a problem for you, you could try to reflash the stock certificates and check if it works directly against the boxine cloud.

elektroverteiler · April 5, 2024, 7:26pm

The see incoming connections from the toniebox in the teddycloud logs. Just the forwarding to the boxine cloud gives me the error above.

Thanks for the hint! - Though the hostname does not seem to be the issue, otherwise I would not see the incoming requests in the logs, no?

I have all the tools for flashing. How do I flash the stock certificates?

0xbadbee · April 5, 2024, 7:27pm

Yes, if you got connections it should be alright

The question is, if this also happens on the freshnessCheck

Just flash your initial backup of the box. If you flashed within the web gui the untouched backup should be within the firmware volume.

elektroverteiler · April 5, 2024, 7:30pm

The question is, if this also happens on the freshnessCheck

Ah, sorry. I didn’t get that.

Just flash your initial backup of the box. If you flashed within the web gui the untouched backup should be within the firmware volume.

Thanks doing that now.

elektroverteiler · April 5, 2024, 7:32pm

With the stock firmware in place. The connection to the Boxine Cloud works.

I will just start over with the flashing process and see if it works then.

elektroverteiler · April 5, 2024, 9:01pm

After patching and flashing the toniebox again I am now stuck in the setup step and can’t seem to get past that.

When the toniebox starts it sends several OTA requests. If the connection to the Boxine Cloud is disabled, I get the output below and the box shouts groundhog.

INFO |server.c:0260:httpServerRequestCallback| UA=RoseRed TB/1666701414, FW=1666701414, SP=0, HW=0
INFO |handler_cloud.c:0040:handleCloudTime|  >> respond with current time
INFO |server.c:0260:httpServerRequestCallback| UA=RoseRed TB/1666701414, FW=1666701414, SP=0, HW=0
INFO |server.c:0260:httpServerRequestCallback| UA=RoseRed TB/1666701414, FW=1666701414, SP=0, HW=0
INFO |handler_cloud.c:0091:handleCloudOTA|  >> OTA-Request for 5 with timestamp 1638869115 (2021-12-07 09:25:15)
INFO |server.c:0260:httpServerRequestCallback| UA=RoseRed TB/1666701414, FW=1666701414, SP=0, HW=0
INFO |handler_cloud.c:0091:handleCloudOTA|  >> OTA-Request for 2 with timestamp 1666701414 (2022-10-25 12:36:54)
INFO |server.c:0260:httpServerRequestCallback| UA=RoseRed TB/1666701414, FW=1666701414, SP=0, HW=0
INFO |handler_cloud.c:0091:handleCloudOTA|  >> OTA-Request for 6 with timestamp 1534781997 (2018-08-20 16:19:57)
INFO |server.c:0260:httpServerRequestCallback| UA=RoseRed TB/1666701414, FW=1666701414, SP=0, HW=0
INFO |handler_cloud.c:0091:handleCloudOTA|  >> OTA-Request for 3 with timestamp 1 (1970-01-01 00:00:01)
INFO |server.c:0260:httpServerRequestCallback| UA=RoseRed TB/1666701414, FW=1666701414, SP=0, HW=0
INFO |handler_cloud.c:0040:handleCloudTime|  >> respond with current time
INFO |server.c:0260:httpServerRequestCallback| UA=RoseRed TB/1666701414, FW=1666701414, SP=0, HW=0
INFO |server.c:0260:httpServerRequestCallback| UA=RoseRed TB/1666701414, FW=1666701414, SP=0, HW=0
INFO |handler_cloud.c:0091:handleCloudOTA|  >> OTA-Request for 5 with timestamp 1638869115 (2021-12-07 09:25:15)
INFO |server.c:0260:httpServerRequestCallback| UA=RoseRed TB/1666701414, FW=1666701414, SP=0, HW=0
INFO |handler_cloud.c:0091:handleCloudOTA|  >> OTA-Request for 2 with timestamp 1666701414 (2022-10-25 12:36:54)
INFO |server.c:0260:httpServerRequestCallback| UA=RoseRed TB/1666701414, FW=1666701414, SP=0, HW=0
INFO |handler_cloud.c:0091:handleCloudOTA|  >> OTA-Request for 6 with timestamp 1534781997 (2018-08-20 16:19:57)
INFO |server.c:0260:httpServerRequestCallback| UA=RoseRed TB/1666701414, FW=1666701414, SP=0, HW=0
INFO |handler_cloud.c:0091:handleCloudOTA|  >> OTA-Request for 3 with timestamp 1 (1970-01-01 00:00:01)

If the connection to the Boxine Cloud is enabled, similar (the same?) OTA requests are emitted but run into the error 271 again (see below). Eventually the box also shouts groundhog.

INFO |server.c:0260:httpServerRequestCallback| UA=RoseRed TB/1666701414, FW=1666701414, SP=0, HW=0
INFO |handler_cloud.c:0040:handleCloudTime|  >> respond with current time
INFO |cloud_request.c:0161:web_request| Connecting to HTTP server prod.de.tbs.toys:443...
INFO |cloud_request.c:0211:web_request|   trying IP: 18.156.186.144
INFO |cloud_request.c:0038:httpClientTlsInitCallbackBase| Initializing TLS...
INFO |cloud_request.c:0073:httpClientTlsInitCallbackBase| Initializing TLS done
ERROR|cloud_request.c:0221:web_request| Failed to connect to HTTP server! Error=Access denied [271]
INFO |server.c:0260:httpServerRequestCallback| UA=RoseRed TB/1666701414, FW=1666701414, SP=0, HW=0
INFO |server.c:0260:httpServerRequestCallback| UA=RoseRed TB/1666701414, FW=1666701414, SP=0, HW=0
INFO |handler_cloud.c:0091:handleCloudOTA|  >> OTA-Request for 5 with timestamp 1638869115 (2021-12-07 09:25:15)
INFO |cloud_request.c:0161:web_request| Connecting to HTTP server prod.de.tbs.toys:443...
INFO |cloud_request.c:0211:web_request|   trying IP: 18.156.186.144
INFO |cloud_request.c:0038:httpClientTlsInitCallbackBase| Initializing TLS...
INFO |cloud_request.c:0073:httpClientTlsInitCallbackBase| Initializing TLS done
ERROR|cloud_request.c:0221:web_request| Failed to connect to HTTP server! Error=Access denied [271]
INFO |server.c:0591:server_init| 2 open HTTPS connections
INFO |handler_cloud.c:0040:handleCloudTime|  >> respond with current time
INFO |mqtt.c:0684:mqtt_init_box| Skipping client 'Toniebox' (cn: 'default')
INFO |cloud_request.c:0161:web_request| Connecting to HTTP server prod.de.tbs.toys:443...
INFO |server.c:0591:server_init| 3 open HTTPS connections
INFO |cloud_request.c:0211:web_request|   trying IP: 18.156.186.144
INFO |cloud_request.c:0038:httpClientTlsInitCallbackBase| Initializing TLS...
INFO |cloud_request.c:0073:httpClientTlsInitCallbackBase| Initializing TLS done
WARN |tls_server_fsm.c:0260:tlsPerformServerHandshake| TLS handshake failure!
INFO |server.c:0591:server_init| 2 open HTTPS connections
ERROR|cloud_request.c:0221:web_request| Failed to connect to HTTP server! Error=Access denied [271]
INFO |handler_cloud.c:0040:handleCloudTime|  >> respond with current time
INFO |mqtt.c:0684:mqtt_init_box| Skipping client 'Toniebox' (cn: 'default')
INFO |cloud_request.c:0161:web_request| Connecting to HTTP server prod.de.tbs.toys:443...
INFO |cloud_request.c:0211:web_request|   trying IP: 3.69.182.181
INFO |cloud_request.c:0038:httpClientTlsInitCallbackBase| Initializing TLS...
INFO |cloud_request.c:0073:httpClientTlsInitCallbackBase| Initializing TLS done
INFO |server.c:0591:server_init| 3 open HTTPS connections
WARN |tls_server_fsm.c:0260:tlsPerformServerHandshake| TLS handshake failure!
INFO |server.c:0591:server_init| 2 open HTTPS connections
ERROR|cloud_request.c:0221:web_request| Failed to connect to HTTP server! Error=Access denied [271]
INFO |handler_cloud.c:0040:handleCloudTime|  >> respond with current time
INFO |mqtt.c:0684:mqtt_init_box| Skipping client 'Toniebox' (cn: 'default')
INFO |cloud_request.c:0161:web_request| Connecting to HTTP server prod.de.tbs.toys:443...
INFO |server.c:0591:server_init| 3 open HTTPS connections
INFO |cloud_request.c:0211:web_request|   trying IP: 3.69.182.181
INFO |cloud_request.c:0038:httpClientTlsInitCallbackBase| Initializing TLS...
INFO |cloud_request.c:0073:httpClientTlsInitCallbackBase| Initializing TLS done
WARN |tls_server_fsm.c:0260:tlsPerformServerHandshake| TLS handshake failure!
INFO |server.c:0591:server_init| 2 open HTTPS connections
ERROR|cloud_request.c:0221:web_request| Failed to connect to HTTP server! Error=Access denied [271]

So far I could not get the toniebox to do a freshness check.

0xbadbee · April 5, 2024, 9:20pm

It is important that you do an update and initialization of the box before connecting it to teddyCloud, as OTA cannot be done if you patched the hostname.

As an alternative, you may try to use the :develop tag. There is an option to cache the OTA files, and then you could patch then with the teddyCloud CLI with your desired hostname.

But it looks like as your client certificate extracted from the box is not okay.
Please try to open http://<teddycloud-ip>/reverse/v1/time. This should trigger the connection to the cloud and show you the boxine clouds time.

elektroverteiler · April 5, 2024, 9:46pm

Thanks for the help!

Ok that makes sense.

How would that work? - Before I patch the OTA files don’t go through the teddyCloud and afterwards the error occurs.

It seems that way. Funny is, that it used to work. It stopped working some time during the last 10 days.

I flashed the original image again now. And completed the setup procedure, that should cover OTA, right?

I am now struggling to read the ROM. I am using the current teddyCloud release tc_v0.4.3and the Read process runs to 100% after that it runs in a timeout and no file is written to disk. Any ideas?

0xbadbee · April 5, 2024, 9:50pm

It is something for the future, if your certificate is fine again. This will download the firmware files to your firmware directory, but won’t deliver it to you box. Then you can edit them with the CLI , enable local OTA and then it the modified firmware will be shipped to your box.

PS:
Beware that v0.4.3 has a bug that makes patching the hostname impossible. Use the develop version or an earlier version that doesn’t crash.

Yes, everything should be fine now.

Try doing it via the command line / legacy way.

elektroverteiler · April 5, 2024, 10:24pm

Excellent!

Yeah, ran into that one already.

That did the trick!

Thanks a lot!

elektroverteiler · April 5, 2024, 10:40pm

Sadly the ERROR=271 remains.

PS: the certificates are identical to those I used before.

running :develop now.

Freshness check output

INFO |server.c:0261:httpServerRequestCallback| UA=toniebox-esp32-eu/v5.230.0, ESPFW=eu/v5.230.0
INFO |mqtt.c:0698:mqtt_init_box| Registered new box 'teddyCloud Box F412FA734EC8' (cn: 'F412FA734EC8')
INFO |mqtt.c:0699:mqtt_init_box| Using base path 'teddyCloud/box/F412FA734EC8' and id 'teddyCloud_Box_F412FA734EC8'
INFO |handler_cloud.c:0800:handleCloudFreshnessCheck| Content (464 of 464)
INFO |handler_cloud.c:0808:handleCloudFreshnessCheck| Found 29 tonies:
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: E00403500EED2F2B, nocloud: 0, live: 0, updated: 0, audioid: 15F44614 (2024-03-15 12:59:00, custom)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: E00403500EED298C, nocloud: 0, live: 0, updated: 0, audioid: 15F41950 (2024-03-15 09:48:00, custom)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: E00403501F1F5A47, nocloud: 0, live: 0, updated: 0, audioid: 65C3698B (2024-02-07 11:29:15)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: E00403501B1D5E42, nocloud: 0, live: 0, updated: 0, audioid: 65FC986B (2024-03-21 20:28:27)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 0000000001000000, nocloud: 0, live: 0, updated: 0, audioid: 58DE2BEB (2017-03-31 10:14:03)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 0100000001000000, nocloud: 0, live: 0, updated: 0, audioid: 00000001 (special)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 0200000001000000, nocloud: 0, live: 0, updated: 0, audioid: 00000001 (special)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 0300000001000000, nocloud: 0, live: 0, updated: 0, audioid: 00000001 (special)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 0400000001000000, nocloud: 0, live: 0, updated: 0, audioid: 00000001 (special)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 0500000001000000, nocloud: 0, live: 0, updated: 0, audioid: 00000001 (special)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 0600000001000000, nocloud: 0, live: 0, updated: 0, audioid: 6582F9DC (2023-12-20 14:27:40)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 0700000001000000, nocloud: 0, live: 0, updated: 0, audioid: 595364DC (2017-06-28 08:12:12)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 0800000001000000, nocloud: 0, live: 0, updated: 0, audioid: 59536396 (2017-06-28 08:06:46)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 0900000001000000, nocloud: 0, live: 0, updated: 0, audioid: 00000001 (special)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 0A00000001000000, nocloud: 0, live: 0, updated: 0, audioid: 595363CC (2017-06-28 08:07:40)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 0B00000001000000, nocloud: 0, live: 0, updated: 0, audioid: 00000001 (special)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 0C00000001000000, nocloud: 0, live: 0, updated: 0, audioid: 00000001 (special)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 0D00000001000000, nocloud: 0, live: 0, updated: 0, audioid: 00000001 (special)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 0E00000001000000, nocloud: 0, live: 0, updated: 0, audioid: 00000001 (special)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 0F00000001000000, nocloud: 0, live: 0, updated: 0, audioid: 00000001 (special)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 1000000001000000, nocloud: 0, live: 0, updated: 0, audioid: 00000001 (special)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 1100000001000000, nocloud: 0, live: 0, updated: 0, audioid: 59F0AC95 (2017-10-25 15:24:05)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 1200000001000000, nocloud: 0, live: 0, updated: 0, audioid: 00000001 (special)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 1300000001000000, nocloud: 0, live: 0, updated: 0, audioid: 00000001 (special)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 1400000001000000, nocloud: 0, live: 0, updated: 0, audioid: 00000001 (special)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 1500000001000000, nocloud: 0, live: 0, updated: 0, audioid: 00000001 (special)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 1600000001000000, nocloud: 0, live: 0, updated: 0, audioid: 00000001 (special)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 1700000001000000, nocloud: 0, live: 0, updated: 0, audioid: 00000001 (special)
INFO |handler_cloud.c:0868:handleCloudFreshnessCheck|   uid: 1800000001000000, nocloud: 0, live: 0, updated: 0, audioid: 00000001 (special)
INFO |cloud_request.c:0161:web_request| Connecting to HTTP server prod.de.tbs.toys:443...
INFO |cloud_request.c:0211:web_request|   trying IP: 18.156.186.144
INFO |cloud_request.c:0038:httpClientTlsInitCallbackBase| Initializing TLS...
INFO |cloud_request.c:0073:httpClientTlsInitCallbackBase| Initializing TLS done
INFO |server.c:0592:server_init| 3 open HTTPS connections
ERROR|cloud_request.c:0221:web_request| Failed to connect to HTTP server! Error=Access denied [271]
INFO |handler_cloud.c:0924:handleCloudFreshnessCheck| Freshness check response: size=14, content=
INFO |handler_cloud.c:0041:handleCloudTime|  >> respond with current time

Also, when I go to http://<teddycloud-ip>/v1/time:

INFO |cloud_request.c:0161:web_request| Connecting to HTTP server prod.de.tbs.toys:443...
INFO |cloud_request.c:0211:web_request|   trying IP: 3.74.99.150
INFO |cloud_request.c:0038:httpClientTlsInitCallbackBase| Initializing TLS...
INFO |cloud_request.c:0073:httpClientTlsInitCallbackBase| Initializing TLS done
INFO |server.c:0592:server_init| 4 open HTTPS connections
WARN |tls_server_fsm.c:0260:tlsPerformServerHandshake| TLS handshake failure!
INFO |server.c:0592:server_init| 3 open HTTPS connections
ERROR|cloud_request.c:0221:web_request| Failed to connect to HTTP server! Error=Access denied [271]

Even though I am using the certificates that I extracted from the new image now.

0xbadbee · April 6, 2024, 5:33am

Could you provide me the certificates via PM or Telegram? Then I can cross check them.

But there must be something wrong / broken with your teddycloud setup. The certificates are okay, as they work with the Boxine cloud. Are you sure, that teddyCloud is using them? Check the config files and / or delete them.

elektroverteiler · April 6, 2024, 8:48am

Thanks.

I started from scratch and I got an error before I copied the certificates back in. So I assume the certificates are used.

0xbadbee · April 6, 2024, 12:35pm

I tried the certificates, work fine for me. So it has something to do specific to your environment.

elektroverteiler · April 6, 2024, 1:03pm

Thanks!

Hmm, I tried deleting the config and even removed the content from both the tiniebox and the teddycloud.
I‘ll try again, maybe I missed something.

elektroverteiler · April 7, 2024, 9:45am

I figured it out, finally!
It was an error in the docker daemon config.

Thanks for all the help!

0xbadbee · April 7, 2024, 10:03am

Do you have any details about the source of the problem for future people?

elektroverteiler · April 7, 2024, 11:01am

Sure.

I am running homassistant in KVM on the same machine, which I setup using this guide. During that process I created a bridge br0. My mistake was to add this bridge to the docker daemon.json (Don’t!). Through this change the network connection inside the docker images was broken. The docker container was essentially offline.
By adding an iptables rule instead (as discussed in the guide) I was able to restore the internet connection in the container.