New installation, no data showing up in homer-app

[lukeescude]

Hello!

If you start a fresh installation of Homer7-Docker (updated git, updated Docker images (docker system prune -a), etc.) the homer webapp does not pull calls, registrations, etc. from the database.

Grafana is working, but I cannot search for anything in the web app.

When running "docker logs (web-app container)" it says it cannot ping the database, the database is "closed".

Thanks - Let me know if you need me to help with any diagnostics.

EDIT: This only started yesterday. Previously, I was doing fresh installs every few days and things were fine. So, this is very recent.

[lmangani]

which docker-compose mix are you using?

[lukeescude]

I use hom7-prom-all

The HDD fills up every 12 hours (none of the clean-up and DiscardMethod settings work), so I run docker system prune -a -f to erase everything and re-pull updated images every 12 hours.

[lmangani]

Works for me. Could you pull the latest docker-compose file and try the following:

docker-compose up -d

followed by

docker-compose logs heplify-server db

Please provide the output of both.

[lukeescude]

Hmm, still no data.

Also, I had to switch to port 9030 for Grafana to work.

Here is the output

Attaching to heplify-server, db
heplify-server    | Could not find toml config file, use flag defaults. <nil>
heplify-server    | 2021/03/03 15:51:48.671221 server.go:93: INFO start heplify-server 1.53 with config.HeplifyServer{HEPAddr:"0.0.0.0:9060", HEPTCPAddr:"0.0.0.0:9061", HEPTLSAddr:"", HEPWSAddr:"", ESAddr:"", ESDiscovery:true, ESUser:"", ESPass:"", LokiURL:"http://loki:3100/api/prom/push", LokiBulk:400, LokiTimer:2, LokiBuffer:100000, LokiHEPFilter:[]int{1, 5, 100}, ForceHEPPayload:[]int(nil), PromAddr:"0.0.0.0:9096", PromTargetIP:"", PromTargetName:"", DBShema:"homer7", DBDriver:"postgres", DBAddr:"db:5432", DBUser:"root", DBPass:"<private>", DBDataTable:"homer_data", DBConfTable:"homer_config", DBBulk:400, DBTimer:4, DBBuffer:400000, DBWorker:8, DBRotate:true, DBPartLog:"2h", DBPartIsup:"6h", DBPartSip:"2h", DBPartQos:"6h", DBDropDays:5, DBDropDaysCall:0, DBDropDaysRegister:0, DBDropDaysDefault:0, DBDropOnStart:false, Dedup:false, DiscardMethod:[]string(nil), CensorMethod:[]string(nil), AlegIDs:[]string(nil), ForceALegID:false, CustomHeader:[]string(nil), SIPHeader:[]string{"ruri_user", "ruri_domain", "from_user", "from_tag", "to_user", "callid", "cseq", "method", "user_agent"}, LogDbg:"", LogLvl:"info", LogStd:true, LogSys:false, Config:"./heplify-server.toml", ConfigHTTPAddr:"", ConfigHTTPPW:"", Version:false, ScriptEnable:false, ScriptEngine:"lua", ScriptFolder:"", ScriptHEPFilter:[]int{1, 5, 100}, TLSCertFolder:"."}
heplify-server    | 2021/03/03 15:51:48.671469 prometheus.go:38: INFO expose metrics without or unbalanced targets
heplify-server    | 2021/03/03 15:51:50.680256 rotator.go:94: ERR pq: the database system is starting up
heplify-server    | 2021/03/03 15:51:52.682523 rotator.go:406: WARN pq: database "homer_data" already exists
heplify-server    | 
heplify-server    | 2021/03/03 15:51:52.682820 rotator.go:406: WARN pq: role "homer_user" already exists
heplify-server    | 
heplify-server    | 2021/03/03 15:51:52.683064 rotator.go:406: WARN pq: role "postgres" does not exist
heplify-server    | 
heplify-server    | 2021/03/03 15:51:52.684949 rotator.go:344: INFO start creating tables (2021-03-03 15:51:52.68493248 +0000 UTC m=+4.021870253)
heplify-server    | 2021/03/03 15:51:53.095239 rotator.go:357: INFO end creating tables (2021-03-03 15:51:53.095231578 +0000 UTC m=+4.432169339)
heplify-server    | 2021/03/03 15:51:53.098405 postgres.go:61: INFO postgres connection established
heplify-server    | 2021/03/03 15:52:47.273995 loki.go:134: ERR send size batch: server returned HTTP status 400 Bad Request (400): entry with timestamp 2021-03-03 15:52:47.093621146 +0000 UTC ignored, reason: 'entry out of order' for stream: {job="heplify-server", method="NOTIFY", node="1", response="200", type="sip"},
db                | 
db                | PostgreSQL Database directory appears to contain a database; Skipping initialization
db                | 
db                | 2021-03-03 15:51:48.224 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
db                | 2021-03-03 15:51:48.224 UTC [1] LOG:  listening on IPv6 address "::", port 5432
db                | 2021-03-03 15:51:48.225 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
db                | 2021-03-03 15:51:48.236 UTC [20] LOG:  database system was interrupted; last known up at 2021-03-03 15:50:40 UTC
db                | 2021-03-03 15:51:48.431 UTC [20] LOG:  database system was not properly shut down; automatic recovery in progress
db                | 2021-03-03 15:51:48.433 UTC [20] LOG:  redo starts at 10/E70C3FD8
db                | 2021-03-03 15:51:49.206 UTC [27] FATAL:  the database system is starting up
db                | 2021-03-03 15:51:50.277 UTC [35] FATAL:  the database system is starting up
db                | 2021-03-03 15:51:50.680 UTC [36] FATAL:  the database system is starting up
db                | 2021-03-03 15:51:50.765 UTC [20] LOG:  invalid record length at 10/FFFCE4A8: wanted 24, got 0
db                | 2021-03-03 15:51:50.765 UTC [20] LOG:  redo done at 10/FFFCE480
db                | 2021-03-03 15:51:50.765 UTC [20] LOG:  last completed transaction was at log time 2021-03-03 15:50:43.218681+00
db                | 2021-03-03 15:51:51.323 UTC [1] LOG:  database system is ready to accept connections
db                | 2021-03-03 15:51:51.858 UTC [50] ERROR:  database "homer_config" already exists
db                | 2021-03-03 15:51:51.858 UTC [50] STATEMENT:  CREATE DATABASE homer_config OWNER root
db                | 2021-03-03 15:51:51.885 UTC [51] ERROR:  database "homer_data" already exists
db                | 2021-03-03 15:51:51.885 UTC [51] STATEMENT:  CREATE DATABASE homer_data OWNER root
db                | 2021-03-03 15:51:52.682 UTC [64] ERROR:  database "homer_data" already exists
db                | 2021-03-03 15:51:52.682 UTC [64] STATEMENT:  CREATE DATABASE homer_data
db                | 2021-03-03 15:51:52.682 UTC [64] ERROR:  role "homer_user" already exists
db                | 2021-03-03 15:51:52.682 UTC [64] STATEMENT:  CREATE USER homer_user WITH PASSWORD 'homer_password';
db                | 2021-03-03 15:51:52.682 UTC [64] ERROR:  role "postgres" does not exist
db                | 2021-03-03 15:51:52.682 UTC [64] STATEMENT:  GRANT postgres to homer_user;
db                | 2021-03-03 15:52:06.553 UTC [162] ERROR:  syntax error at end of input at character 113
db                | 2021-03-03 15:52:06.553 UTC [162] STATEMENT:  SELECT * FROM "user_settings"  WHERE ((username != $1 AND category = 'dashboard' and param = $2 and partid = $3)
db                | 2021-03-03 15:52:08.976 UTC [162] ERROR:  syntax error at end of input at character 113
db                | 2021-03-03 15:52:08.976 UTC [162] STATEMENT:  SELECT * FROM "user_settings"  WHERE ((username != $1 AND category = 'dashboard' and param = $2 and partid = $3)

[lukeescude]

Here is the output of docker logs homer-webapp

Pre-Flight provisioning completed!

CONNECT to DB ROOT STRING: [host=db user=root dbname=postgres sslmode=disable port=5432 password=homerSeven]

HOMER - create db [homer_config] with [name=root] 

(/homer-app/migration/migration.go:85) 
[2021-03-03 15:51:51]  pq: database "homer_config" already exists 

(/homer-app/migration/migration.go:85) 
[2021-03-03 15:51:51]  [0.50ms]  CREATE DATABASE homer_config OWNER root  
[0 rows affected or returned ] 

DONE 

HOMER - show users 
    Role name   |   Attributes
------------------------------------------------
    homer_user  |       
    root    |   superuser, create database  

DONE 

CONNECT to DB ROOT STRING: [host=db user=root dbname=postgres sslmode=disable port=5432 password=homerSeven]

HOMER - create db [homer_data] with [name=root] 

(/homer-app/migration/migration.go:85) 
[2021-03-03 15:51:51]  pq: database "homer_data" already exists 

(/homer-app/migration/migration.go:85) 
[2021-03-03 15:51:51]  [0.42ms]  CREATE DATABASE homer_data OWNER root  
[0 rows affected or returned ] 

DONE 

HOMER - show users 
    Role name   |   Attributes
------------------------------------------------
    homer_user  |       
    root    |   superuser, create database  

DONE 

HOMER - creating tables for the config DB [dbname=homer_config] 

DONE 

HOMER - filling tables for the config DB [dbname=homer_config] 

DONE 
Database provisioning completed!

PostgreSQL version: 11.11

         ___              
        /__/\             
        \  \:\           
         \__\:\  
     ___ /  /::\     
    /__/\  /:/\:\     _____ _____    
    \  \:\/:/__\/    |___  |___  |   
     \  \::/            / /   / / 
      \  \:\           / /   / /          
       \  \:\         /_(_) /_/               
        \__\/         

 Version: homer-app 1.3.15 
⇨ http server started on [::]:80
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T15:52:52Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T15:53:52Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T15:54:52Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T15:55:52Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T15:56:52Z"}

[lmangani]

Seems like a little messy here and this strategy or restarting is nothing short of problematic anyhow.

I would suggest to drop all data from postgres and starting fresh without things you probably dont need (such as loki) and correctly setting the DB rotation parameter which is currently set to 5 days, but you said it fills up in 1 (?)

start by stopping everything and dropping the postgres folder

docker-compose down -v
rm -rf postgres-data

Open up docker-compose.yml and comment the following lines - it sounds like you do not need this

#      - "HEPLIFYSERVER_LOKIURL=http://loki:3100/api/prom/push"
#      - "HEPLIFYSERVER_LOKITIMER=2"

then change/add the following:

     - "HEPLIFYSERVER_DBDROPDAYS=2"
     - "HEPLIFYSERVER_DBDROPDAYSCALL=2"
     - "HEPLIFYSERVER_DBDROPDAYSREGISTER=1"
     - "HEPLIFYSERVER_DBDROPDAYSDEFAULT=1"
     - "HEPLIFYSERVER_DBDROPONSTART=true"
     - "HEPLIFYSERVER_DBUSAGEPROTECTION=true"

followed by a restart

docker-compose up -d

next, if you want to be sure things work as intended, run a sample hepgen scenario from anywhere

npm install -g hepgen.js
hepgen.js -s YOUR_HOMER_IP -p 9060 -c $(npm root -g)/hepgen.js/config/b2bcall_rtcp.js

[lukeescude]

Everything is back up, Grafana is populating with data, but still no data in Homer app.

I used Hepgen on localhost (on the homer server) as well as on one of my dev machines, and no data is showing up.

This is definitely very strange....

[lukeescude]

Here is the output of docker info:

Client:
 Context:    default
 Debug Mode: false
 Plugins:
  app: Docker App (Docker Inc., v0.9.1-beta3)
  buildx: Build with BuildKit (Docker Inc., v0.5.1-docker)

Server:
 Containers: 8
  Running: 8
  Paused: 0
  Stopped: 0
 Images: 8
 Server Version: 20.10.3
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Native Overlay Diff: true
 Logging Driver: json-file
 Cgroup Driver: cgroupfs
 Cgroup Version: 1
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
 Swarm: inactive
 Runtimes: io.containerd.runc.v2 io.containerd.runtime.v1.linux runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 269548fa27e0089a8b8278fc4fc781d7f65a939b
 runc version: ff819c7e9184c13b7c2607fe6c30ae19403a7aff
 init version: de40ad0
 Security Options:
  seccomp
   Profile: default
 Kernel Version: 3.10.0-1160.15.2.el7.x86_64
 Operating System: CentOS Linux 7 (Core)
 OSType: linux
 Architecture: x86_64
 CPUs: 3
 Total Memory: 7.638GiB
 Name: (redacted)
 ID: (redacted)
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

[lmangani]

Please be specific here, what data is being populated?

[lukeescude]

The Grafana graphs are being populated. But, homer-app has no data in searches.

[lmangani]

This is the opposite of specific :) What data is being populated? show me some examples please

[lukeescude]

Grafana above

Homer-app above - Performing a Call search for anything, or a REGISTRATION search for anything, and no data is showing up.

[lmangani]

• Do not select anything in the form while you try (CLEAR)
• Are you positive you have configured the right timezone to search into? pick last 24h to be sure its not TZ related

[lukeescude]

No change :( still no data populating.

It's strange this would just suddenly start happening, it's been working great for months.

[lmangani]

you need to check what your db node is doing, but since we can't reproduce it there's not much left to guess

[lukeescude]

This happens whenever I log into the dashboard:

2021-03-03 18:46:45.051 UTC [29599] ERROR:  syntax error at end of input at character 113
2021-03-03 18:46:45.051 UTC [29599] STATEMENT:  SELECT * FROM "user_settings"  WHERE ((username != $1 AND category = 'dashboard' and param = $2 and partid = $3)

And here are the docker logs for homer-webapp:

{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:21:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:22:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:23:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:24:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:25:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:26:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:27:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:28:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:29:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:30:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:31:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:32:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:33:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:34:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:35:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:36:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:37:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:38:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:39:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:40:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:41:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:42:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:43:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:44:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:45:38Z"}
{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:46:38Z"}

I will update docker and disable firewalld and see if anything related to that is causing this.

[adubovikov]

fixed in the master. We will recreate package ASAP

On Wed, 3 Mar 2021 at 19:48, Luke Escudé notifications@github.com wrote:

This happens whenever I log into the dashboard:

2021-03-03 18:46:45.051 UTC [29599] ERROR: syntax error at end of input at character 113 2021-03-03 18:46:45.051 UTC [29599] STATEMENT: SELECT * FROM "user_settings" WHERE ((username != $1 AND category = 'dashboard' and param = $2 and partid = $3)

And here are the docker logs for homer-webapp:

{"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:21:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:22:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:23:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:24:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:25:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:26:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:27:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:28:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:29:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:30:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:31:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:32:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:33:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:34:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:35:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:36:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:37:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:38:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:39:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:40:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:41:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:42:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:43:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:44:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:45:38Z"} {"level":"error","msg":"couldn't make ping to [Host: db]: \nsql: database is closed","time":"2021-03-03T18:46:38Z"}

I will update docker and disable firewalld and see if anything related to that is causing this.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/sipcapture/homer7-docker/issues/98#issuecomment-789970933, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABCN2JJFNHAJBADF7ZLHE4LTBZ77TANCNFSM4YRMEF3A .

[lukeescude]

I pulled the recent updates, and now the following is happening:

Haha sorry to be a pain!!

[lmangani]

@lukeescude not at all, this is useful! we are pushing a fix release in 10 minutes time which should resolve this and other issues!

[lmangani]

could you pull and kindly check if this is now resolved?

[lukeescude]

YAY! All the call data can be searched again!

However, one weird anomaly: The "REGISTRATION" dashboard doesn't work, and it duplicates the Home dashboard a few times:

[lmangani]

The schema has been slightly modified - you MIGHT have to recreate them.

[lukeescude]

Yes they work when you re-create them, although it still repeats them and looks strange.

[lmangani]

@AlexeyOplachko could you reproduce this?

[lukeescude]

This might be related, whenever I try to change the user settings it erases/changes all of them at once.

[AlexeyOplachko]

@AlexeyOplachko could you reproduce this?

Yep, can confirm. Seems like a backend issue. I'll write appropriate ticket for this.

Upd: here's ticket https://github.com/sipcapture/homer-app/issues/420

[lukeescude]

Perfect, everything is back to normal!