Teslamate: Broken Synology docker package 18.09.0-0505

[natrlhy]

It’s like TeslaMate isn’t running after doing a pull then a docker-compose up -d

I only see ERR_CONNECTION_CLOSED

[IMgoRt]

Does this apply to you:
https://github.com/adriankumpf/teslamate/issues/108

[natrlhy]

I’ll have to look it over. I’ve not changed anything in my Yaml file since 1st gettingbitvall going. Hope I don’t lose any data. I’m doing this on my iPhone remote

[IMgoRt]

What's your server platform?

[natrlhy]

Synology

[IMgoRt]

Then it applies, specifically my fix at https://github.com/adriankumpf/teslamate/issues/108#issuecomment-526937207

[fetzu]

To make it short: the latest Docker package from Synology (version 18.09.0-0505) is broken and does not read environment variables when using docker-compose.

You can either enter the env vars manually in the UI or downgrade to the previous version of the Docker package (https://usdl.synology.com/download/Package/spk/Docker/17.05.0-0401/) and use docker-compose as before. If going the latter route, pay attention during the package uninstall (to not delete data) and you'll be fine.

[natrlhy]

@fetzu or @IMgoRt

I'm not sure what ENV variables to put in the UI for Synology as my original method was all from SSH and editing the docker-compose.yml file in my SSH session. Any help?

Ok I think I get where/what I need to put in the Synology Docker UI

Thinks like:
DATABASE_USER
DATABASE_PASS
DATABASE_NAME
etc

Specific for each container

EDIT: I'm stuck. I added ENV stuff in the UI, still couldn't connect to port :4000

I downreved the version on Synology to Docker-x64-17.05.0-0401.spk and tried starting things up after removing my manual ENV entries. Still stuck.

[fetzu]

@natrlhy : can you look into the logs for the TeslaMate, grafana and database container? Maybe it would help us zero in on the issue.

In any case, try to
docker-compose down and docker-compose up -d again if you haven't yet.

[natrlhy]

Hi, I've restarted each container multiple times. I just now restarted each one and here's the resulting logs for the startup:

DB:

2019-09-03 13:57:05.855 UTC [1] LOG: received smart shutdown request
2019-09-03 13:57:06.539 UTC [1] LOG: background worker "logical replication launcher" (PID 30) exited with exit code 1
2019-09-03 13:57:06.721 UTC [25] LOG: shutting down
2019-09-03 13:57:08.032 UTC [1] LOG: database system is shut down
2019-09-03 13:57:25.952 UTC [1] LOG: listening on IPv4 address "0.0.0.0", port 5432
2019-09-03 13:57:25.952 UTC [1] LOG: listening on IPv6 address "::", port 5432
2019-09-03 13:57:26.001 UTC [1] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2019-09-03 13:57:26.119 UTC [23] LOG: database system was shut down at 2019-09-03 13:57:07 UTC
2019-09-03 13:57:26.202 UTC [1] LOG: database system is ready to accept connections
2019-09-03 14:00:25.906 UTC [32] LOG: incomplete startup packet

Grafana:

t=2019-09-03T13:58:23+0000 lvl=info msg="Starting Grafana" logger=server version=6.3.4 commit=a557646 branch=HEAD compiled=2019-08-19T14:28:51+0000
t=2019-09-03T13:58:23+0000 lvl=info msg="Config loaded from" logger=settings file=/usr/share/grafana/conf/defaults.ini
t=2019-09-03T13:58:23+0000 lvl=info msg="Config loaded from" logger=settings file=/etc/grafana/grafana.ini
t=2019-09-03T13:58:23+0000 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.data=/var/lib/grafana"
t=2019-09-03T13:58:23+0000 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.logs=/var/log/grafana"
t=2019-09-03T13:58:23+0000 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.plugins=/var/lib/grafana/plugins"
t=2019-09-03T13:58:23+0000 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.provisioning=/etc/grafana/provisioning"
t=2019-09-03T13:58:23+0000 lvl=info msg="Config overridden from command line" logger=settings arg="default.log.mode=console"
t=2019-09-03T13:58:23+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_PATHS_DATA=/var/lib/grafana"
t=2019-09-03T13:58:23+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_PATHS_LOGS=/var/log/grafana"
t=2019-09-03T13:58:23+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_PATHS_PLUGINS=/var/lib/grafana/plugins"
t=2019-09-03T13:58:23+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_PATHS_PROVISIONING=/etc/grafana/provisioning"
t=2019-09-03T13:58:23+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_ANALYTICS_REPORTING_ENABLED=FALSE"
t=2019-09-03T13:58:23+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_SECURITY_ADMIN_USER=admin"
t=2019-09-03T13:58:23+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_SECURITY_ADMIN_PASSWORD=***"
t=2019-09-03T13:58:23+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_SECURITY_DISABLE_GRAVATAR=true"
t=2019-09-03T13:58:23+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_SECURITY_ALLOW_EMBEDDING=true"
t=2019-09-03T13:58:23+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_USERS_ALLOW_SIGN_UP=false"
t=2019-09-03T13:58:23+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_AUTH_ANONYMOUS_ENABLED=true"
t=2019-09-03T13:58:23+0000 lvl=info msg="Config overridden from Environment variable" logger=settings var="GF_AUTH_BASIC_ENABLED=false"
t=2019-09-03T13:58:23+0000 lvl=info msg="Path Home" logger=settings path=/usr/share/grafana
t=2019-09-03T13:58:23+0000 lvl=info msg="Path Data" logger=settings path=/var/lib/grafana
t=2019-09-03T13:58:23+0000 lvl=info msg="Path Logs" logger=settings path=/var/log/grafana
t=2019-09-03T13:58:23+0000 lvl=info msg="Path Plugins" logger=settings path=/var/lib/grafana/plugins
t=2019-09-03T13:58:23+0000 lvl=info msg="Path Provisioning" logger=settings path=/etc/grafana/provisioning
t=2019-09-03T13:58:23+0000 lvl=info msg="App mode production" logger=settings
t=2019-09-03T13:58:23+0000 lvl=info msg="Initializing SqlStore" logger=server
t=2019-09-03T13:58:23+0000 lvl=info msg="Connecting to DB" logger=sqlstore dbtype=sqlite3
t=2019-09-03T13:58:23+0000 lvl=info msg="Starting DB migration" logger=migrator
t=2019-09-03T13:58:23+0000 lvl=info msg="Initializing HTTPServer" logger=server
t=2019-09-03T13:58:23+0000 lvl=info msg="Initializing InternalMetricsService" logger=server
t=2019-09-03T13:58:23+0000 lvl=info msg="Initializing RemoteCache" logger=server
t=2019-09-03T13:58:23+0000 lvl=info msg="Initializing QuotaService" logger=server
t=2019-09-03T13:58:23+0000 lvl=info msg="Initializing PluginManager" logger=server
t=2019-09-03T13:58:23+0000 lvl=info msg="Starting plugin search" logger=plugins
t=2019-09-03T13:58:23+0000 lvl=info msg="Registering plugin" logger=plugins name=Discrete
t=2019-09-03T13:58:23+0000 lvl=info msg="Registering plugin" logger=plugins name=TrackMap
t=2019-09-03T13:58:23+0000 lvl=info msg="Initializing RenderingService" logger=server
t=2019-09-03T13:58:23+0000 lvl=info msg="Initializing AlertEngine" logger=server
t=2019-09-03T13:58:23+0000 lvl=info msg="Initializing DatasourceCacheService" logger=server
t=2019-09-03T13:58:23+0000 lvl=info msg="Initializing HooksService" logger=server
t=2019-09-03T13:58:23+0000 lvl=info msg="Initializing LoginService" logger=server
t=2019-09-03T13:58:23+0000 lvl=info msg="Initializing SearchService" logger=server
t=2019-09-03T13:58:23+0000 lvl=info msg="Initializing ServerLockService" logger=server
t=2019-09-03T13:58:23+0000 lvl=info msg="Initializing TracingService" logger=server
t=2019-09-03T13:58:23+0000 lvl=info msg="Initializing UsageStatsService" logger=server
t=2019-09-03T13:58:23+0000 lvl=info msg="Initializing UserAuthTokenService" logger=server
t=2019-09-03T13:58:23+0000 lvl=info msg="Initializing CleanUpService" logger=server
t=2019-09-03T13:58:23+0000 lvl=info msg="Initializing NotificationService" logger=server
t=2019-09-03T13:58:23+0000 lvl=info msg="Initializing provisioningServiceImpl" logger=server
t=2019-09-03T13:58:24+0000 lvl=info msg="Initializing Stream Manager"
t=2019-09-03T13:58:24+0000 lvl=info msg="HTTP Server Listen" logger=http.server address=0.0.0.0:3000 protocol=http subUrl= socket=

Teslamate:

07:00:33.805 [info] Already up
07:01:06.090 [info] Running TeslaMateWeb.Endpoint with cowboy 2.6.3 at :::4000 (http)
07:01:06.153 [info] Access TeslaMateWeb.Endpoint at http://10.10.10.10
07:01:06.575 [info] Found 'SHUYE 3G'
07:01:06.606 [info] Adding elevation to 1000 positions ...
07:01:06.659 [info] Querying location for elevation takes longer than 50ms ...
07:01:06.920 [info] Initializing handler
07:01:06.921 [info] Connection has been established
07:01:06.944 car_id=1 [info] Start / :offline
07:01:07.501 [error] Task #PID<0.3514.0> started from TeslaMate.Mapping terminating
* (CaseClauseError) no case clause matching: 25921570
(srtm) lib/data_cell.ex:13: SRTM.DataCell.from_file!/1
(srtm) lib/client.ex:103: anonymous fn/4 in SRTM.Client.load_cell/2
(srtm) lib/client.ex:90: SRTM.Client.get_data_cell/3
(srtm) lib/client.ex:81: SRTM.Client.get_elevation/3
(teslamate) lib/teslamate/mapping.ex:160: TeslaMate.Mapping.do_get_elevation/2
(elixir) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
(elixir) lib/task/supervised.ex:35: Task.Supervised.reply/5
(stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Function: #Function<2.93367123/0 in TeslaMate.Mapping.handle_event/4>
Args: []
07:01:07.683 [info] Adding elevation to 1000 positions ...
07:01:07.736 [info] Querying location for elevation takes longer than 50ms ...
07:01:07.915 [error] Task #PID<0.3532.0> started from TeslaMate.Mapping terminating
* (CaseClauseError) no case clause matching: 25921570
(srtm) lib/data_cell.ex:13: SRTM.DataCell.from_file!/1
(srtm) lib/client.ex:103: anonymous fn/4 in SRTM.Client.load_cell/2
(srtm) lib/client.ex:90: SRTM.Client.get_data_cell/3
(srtm) lib/client.ex:81: SRTM.Client.get_elevation/3
(teslamate) lib/teslamate/mapping.ex:160: TeslaMate.Mapping.do_get_elevation/2
(elixir) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
(elixir) lib/task/supervised.ex:35: Task.Supervised.reply/5
(stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Function: #Function<2.93367123/0 in TeslaMate.Mapping.handle_event/4>
Args: []
07:01:08.028 [info] Adding elevation to 1000 positions ...
07:01:08.080 [info] Querying location for elevation takes longer than 50ms ...
07:01:08.556 [error] Task #PID<0.3534.0> started from TeslaMate.Mapping terminating
* (CaseClauseError) no case clause matching: 25921570
(srtm) lib/data_cell.ex:13: SRTM.DataCell.from_file!/1
(srtm) lib/client.ex:103: anonymous fn/4 in SRTM.Client.load_cell/2
(srtm) lib/client.ex:90: SRTM.Client.get_data_cell/3
(srtm) lib/client.ex:81: SRTM.Client.get_elevation/3
(teslamate) lib/teslamate/mapping.ex:160: TeslaMate.Mapping.do_get_elevation/2
(elixir) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
(elixir) lib/task/supervised.ex:35: Task.Supervised.reply/5
(stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Function: #Function<2.93367123/0 in TeslaMate.Mapping.handle_event/4>
Args: []
07:01:08.715 [info] Adding elevation to 1000 positions ...
07:01:08.768 [info] Querying location for elevation takes longer than 50ms ...
07:01:09.119 [error] Task #PID<0.3536.0> started from TeslaMate.Mapping terminating
* (CaseClauseError) no case clause matching: 25921570
(srtm) lib/data_cell.ex:13: SRTM.DataCell.from_file!/1
(srtm) lib/client.ex:103: anonymous fn/4 in SRTM.Client.load_cell/2
(srtm) lib/client.ex:90: SRTM.Client.get_data_cell/3
(srtm) lib/client.ex:81: SRTM.Client.get_elevation/3
(teslamate) lib/teslamate/mapping.ex:160: TeslaMate.Mapping.do_get_elevation/2
(elixir) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
(elixir) lib/task/supervised.ex:35: Task.Supervised.reply/5
(stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Function: #Function<2.93367123/0 in TeslaMate.Mapping.handle_event/4>
Args: []
07:01:09.148 [info] Application teslamate exited: shutdown
{"Kernel pid terminated",application_controller,"{application_terminated,teslamate,shutdown}"}
Kernel pid terminated (application_controller) ({application_terminated,teslamate,shutdown})

Crash dump is being written to: erl_crash.dump...done

[natrlhy]

So I opened a new issue and was trying to downgrade back to 1.6.2. In that process, as I had some DB errors due to the DB not getting fully downgraded, I tried the latest again and things are working again

https://github.com/adriankumpf/teslamate/issues/135#issuecomment-527488342

[adriankumpf]

Okay, I'll leave this open for a while. Let's see how long it takes for the Synology Docker package to be fixed ...

[natrlhy]

Ok @adriankumpf

I was just considering closing this but hope this can help others. Updating the EID was a big find, too as mentioned in other issues with resolutions

[bahree]

So, it seems Docker is going to release an update sometime next week - as per their forum. I personally don't have experience with their forum so can't say on how they usually are with the timelines. I have used their support in the past (had a device replaced under warranty and that process was AWESOME).

[AmpManNC]

I'm on Synology and my teslamate stopped working about 5 days ago. I am on Docker 17.xxx.

I updated my teslamate version (I was on an early one), and am getting the following error when doing "docker-compose up -d":

=============================================

Creating network "docker_default" with the default driver
Creating docker_mosquitto_1 ...
Creating docker_grafana_1 ...
Creating docker_db_1 ...
Creating docker_teslamate_1 ...
Creating docker_mosquitto_1
Creating docker_grafana_1
Creating docker_db_1
Creating docker_mosquitto_1 ... error

ERROR: for docker_mosquitto_1 Cannot start service mosquitto: driver failed programming external connectivity on endpoint docker_mosquitto_1 (585b73Creating docker_grafana_1 ... error

ERROR: for docker_grafana_1 Cannot start service grafana: driver failed programming external connectivity on endpoint docker_grafana_1 (ad93f9e59d00Creating docker_teslamate_1 ... done

ERROR: for mosquitto Cannot start service mosquitto: driver failed programming external connectivity on endpoint docker_mosquitto_1 (585b7375b3443f624b32d854244d024df00bd9a8f35f0488b334d3c596032c9c): Bind for 0.0.0.0:9001 failed: port is already allocated

ERROR: for grafana Cannot start service grafana: driver failed programming external connectivity on endpoint docker_grafana_1 (ad93f9e59d00e6af28df031941e02fc5427cdec7064fb9b2f8d59640ce7e12f5): Bind for 0.0.0.0:3000 failed: port is already allocated
ERROR: Encountered errors while bringing up the project.

===============================================

When I go to port 4000, I correctly see the car state. But none of the port 3000 grafana functions are working (not recording trips, charging sessions, etc.).

Any ideas? I've tried compose down and up a few times, and it's still no go...

[AmpManNC]

I rebooted the NAS, and now get nothing on port 4000.

"Cannot start" errors as per previous post are still occurring when doing "docker-compose up -d".

[AmpManNC]

Turns out I had some "STOP"ped instances of the containers around, which I guess were holding the ports, so I ended up with multiple instances of the containers. Killing all of them and starting over has got it all working again.

[adriankumpf]

Synology has released the update and it has been confirmed that it fixes the problem.

https://www.synology.com/en-global/releaseNote/Docker
https://community.synology.com/enu/forum/15/post/128146?page=3