search

jeanmarc77 / 123solar

123Solar is a lightweight set of PHP/JS files that makes a web logger to monitor your photovoltaic inverter(s). It just need a web server and PHP, no databases are even needed. The philosophy is: To keep it simple, fast, with a low foot print to run on cheap and low powered devices.
GNU General Public License v3.0
36 stars 12 forks source link

123solar cant run (suddenly after a few months) #62

Closed speeskeek closed 8 months ago

speeskeek commented 8 months ago

suddenly is maybe not fully true - I upgraded to newer debian - with php 8.2 - maybe that's the issue?

If I start 123solar on th e admin page (with the big button) most of the time it doesnt start. When I start at command line it starts, but it also stops somehow. I cant see or read why. even with debug on.

whenb running it has thje correct readings, and displays the value on the gauge. but afetrer ! minute or so it stops...

Is ther eanywhere where I can see what is going wrong? meterN is running fine.

link to my site

jeanmarc77 commented 8 months ago

Hi, Did you use github version or the release https://github.com/jeanmarc77/123solar/releases/tag/1.8.4.5 ?

Git is "work in progress" and use systemd to start/stop the script. It hasn't been tested thoroughly..

speeskeek commented 8 months ago

I reinstalled with the release (an not git). Same issue. Where can I look for a log file? Is it php log?

jeanmarc77 commented 8 months ago

You can enable 'debug' then restart and check 123Solar errors log in help page. Also you can have hints on php error log as well

speeskeek commented 8 months ago

Debug says nothing.

#* 10/01/2024 17:26:24 Starting 123Solar debug (3126995)

it ran all night in debug without stopiing. Moment the sun comes out (and it has to do something) it stops. now I can just start it. A few sec later I can start again

`#* 11/01/2024 08:53:07 Starting 123Solar debug (579819)

* 11/01/2024 08:55:35 Starting 123Solar debug (583860)

* 11/01/2024 08:57:04 Starting 123Solar debug (586393)

* 11/01/2024 08:57:09 Starting 123Solar debug (586526)

* 11/01/2024 08:57:11 Starting 123Solar debug (586606)`

jeanmarc77 commented 8 months ago

and php error log ? did you try the Enhanced com. tester in help page ?

speeskeek commented 8 months ago

IMG_3677 IMG_3680

jeanmarc77 commented 8 months ago

journalctl -r | grep php journalctl -u php-fpm -u php

speeskeek commented 8 months ago

journalctl -u php-fpm -u php $ sudo journalctl -u php-fpm -u php -- No entries --

the other command (ournalctl -r | grep php) is not showing anything usefull now because its dark. I'll check the log again in the morning :)

speeskeek commented 8 months ago

root@Z800:~# journalctl -r | grep php Jan 12 08:39:08 Z800 systemd[1]: Finished phpsessionclean.service - Clean php session files. Jan 12 08:39:08 Z800 systemd[1]: phpsessionclean.service: Deactivated successfully. Jan 12 08:39:07 Z800 systemd[1]: Starting phpsessionclean.service - Clean php session files... Jan 12 08:39:01 Z800 CRON[3103893]: (root) CMD ( [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi) Jan 12 08:15:13 Z800 php[3056871]: (standard_in) 1: syntax error Jan 12 08:15:13 Z800 php[3056848]: parse error: Invalid numeric literal at line 1, column 7 Jan 12 08:15:12 Z800 php[3056752]: (standard_in) 1: syntax error Jan 12 08:15:12 Z800 php[3056749]: parse error: Invalid numeric literal at line 1, column 7 Jan 12 08:15:11 Z800 php[3056729]: (standard_in) 1: syntax error

so it doesn't say something usefull arount the start or stop times of the script.

this is 123solar debug

20240112-08:57:02: aurora: No response after 3 attempts 20240112-08:57:02: aurora: ERROR: Received bad return code (-1 0) 20240112-08:57:02: aurora: No response after 3 attempts 20240112-08:57:02: aurora: ERROR: Received bad return code (-1 0) 20240112-08:57:02: aurora: No response after 3 attempts 20240112-08:57:02: aurora: ERROR: Received bad return code (-1 0)

* 12/01/2024 09:06:36 Starting 123Solar debug (3168158)

* 12/01/2024 09:06:59 Starting 123Solar debug (3168776)

* 12/01/2024 09:10:45 Starting 123Solar debug (3175313)

but it has the aurora errors sometimes.

I'll try to replug the rs485 stick

speeskeek commented 8 months ago

can this be a problem ? Screenshot_20240112_090932 I guess effekta is a protocol, and I'm using aurora protocol?

jeanmarc77 commented 8 months ago

don't start with command line and make sure there isn't a 123solar.pid file. Check also what php scripts runs

speeskeek commented 8 months ago

Here are the processes. I couldnt find an old PID file. it starts but after one minute it stops

is it normale the pid’s of the aurora commands are changing?

IMG_3717 IMG_3718 IMG_3719 IMG_3720 IMG_3721 IMG_3722 IMG_3723

jeanmarc77 commented 8 months ago

Yes, it's normal the aurora's pid is changing continuously. Which [123solar.service] do you use ?

speeskeek commented 8 months ago

123solar.service]

Before all the trouble I was running it wirh a service. Since the problems started I was using not the service - I was starting from the web interface.

Now I started it again with service. It runs. but fails to - but since it's a service it restarts... so I have my logging bacl - but it's not okay to have these errors?

bart@Z800:~$ sudo journalctl --follow -u 123solar.service Jan 14 11:57:19 Z800 systemd[1]: Starting 123solar.service - 123Solar... Jan 14 11:57:19 Z800 systemd[1]: Started 123solar.service - 123Solar. Jan 14 12:06:00 Z800 systemd[1]: 123solar.service: Main process exited, code=exited, status=255/EXCEPTION Jan 14 12:06:00 Z800 systemd[1]: 123solar.service: Failed with result 'exit-code'. Jan 14 12:06:00 Z800 systemd[1]: 123solar.service: Consumed 10.136s CPU time. Jan 14 12:06:30 Z800 systemd[1]: 123solar.service: Scheduled restart job, restart counter is at 1. Jan 14 12:06:30 Z800 systemd[1]: Stopped 123solar.service - 123Solar. Jan 14 12:06:30 Z800 systemd[1]: 123solar.service: Consumed 10.136s CPU time. Jan 14 12:06:30 Z800 systemd[1]: Starting 123solar.service - 123Solar... Jan 14 12:06:30 Z800 systemd[1]: Started 123solar.service - 123Solar. Jan 14 12:06:31 Z800 systemd[1]: 123solar.service: Main process exited, code=exited, status=255/EXCEPTION Jan 14 12:06:31 Z800 systemd[1]: 123solar.service: Failed with result 'exit-code'. Jan 14 12:07:01 Z800 systemd[1]: 123solar.service: Scheduled restart job, restart counter is at 2. Jan 14 12:07:01 Z800 systemd[1]: Stopped 123solar.service - 123Solar. Jan 14 12:07:01 Z800 systemd[1]: Starting 123solar.service - 123Solar... Jan 14 12:07:01 Z800 systemd[1]: Started 123solar.service - 123Solar. Jan 14 12:07:02 Z800 systemd[1]: 123solar.service: Main process exited, code=exited, status=255/EXCEPTION Jan 14 12:07:02 Z800 systemd[1]: 123solar.service: Failed with result 'exit-code'. Jan 14 12:07:32 Z800 systemd[1]: 123solar.service: Scheduled restart job, restart counter is at 3. Jan 14 12:07:32 Z800 systemd[1]: Stopped 123solar.service - 123Solar. Jan 14 12:07:32 Z800 systemd[1]: Starting 123solar.service - 123Solar... Jan 14 12:07:32 Z800 systemd[1]: Started 123solar.service - 123Solar. Jan 14 12:07:33 Z800 systemd[1]: 123solar.service: Main process exited, code=exited, status=255/EXCEPTION

speeskeek commented 8 months ago

Which [123solar.service] do you use ?

bart@Z800:~$ cat /etc/systemd/system/123solar.service

[Unit]
Description=123Solar
Requires=network.target
After=network.target nginx.service php-fpm.service
StartLimitIntervalSec=60
StartLimitBurst=5

[Service] Type=simple WorkingDirectory=/var/www/bartman/123solar/scripts/ ExecStart=/usr/bin/php 123solar.php

ExecStartPost=/bin/sh -c 'systemctl show -p MainPID --value 123solar.service > /var/www/bartman/123solar/scripts/123solar.pid' ExecStopPost=/usr/bin/rm -f /var/www/bartman/123solar/scripts/123solar.pid User=www-data Group=www-data Restart=always RestartSec=30s

Since version 7.4 php-fpm is hardened

ReadWritePaths = /var/lock

[Install] WantedBy=default.target

speeskeek commented 8 months ago

not working great .. because it is not loggin all : (it is 14:00 now)

Screenshot_20240114_140017

jeanmarc77 commented 8 months ago

Hi, You rather should use the old service The new one respawn but it haven't tested thoroughly.

It's odd you don't have info in logs files (php and 123s) Check what's running before and after it hang with "ps -ef | grep php"

speeskeek commented 8 months ago

I tried the old service... but very mucht running after starting it.

First I tried with the localhost mentioned

sudo systemctl status 123solar_old.service ○ 123solar_old.service - 123Solar Loaded: loaded (/etc/systemd/system/123solar_old.service; enabled; preset: enabled) Active: inactive (dead) since Sun 2024-01-14 14:54:11 CET; 3s ago Process: 1558335 ExecStart=/usr/bin/curl http://localhost/123solar/scripts/boot123s.php (code=exited, status=0/SUCCE> Main PID: 1558335 (code=exited, status=0/SUCCESS) CPU: 24ms Jan 14 14:54:10 Z800 systemd[1]: Starting 123solar_old.service - 123Solar... Jan 14 14:54:10 Z800 curl[1558335]: % Total % Received % Xferd Average Speed Time Time Time Current Jan 14 14:54:10 Z800 curl[1558335]: Dload Upload Total Spent Left Speed Jan 14 14:54:11 Z800 curl[1558335]: [158B blob data] Jan 14 14:54:11 Z800 systemd[1]: 123solar_old.service: Deactivated successfully. Jan 14 14:54:11 Z800 systemd[1]: Finished 123solar_old.service - 123Solar.

after that I changed te URL to the real (public one)

sudo systemctl status 123solar_old.service ○ 123solar_old.service - 123Solar Loaded: loaded (/etc/systemd/system/123solar_old.service; enabled; preset: enabled) Active: inactive (dead) since Sun 2024-01-14 14:44:07 CET; 2s ago Process: 1539896 ExecStart=/usr/bin/curl http://bartman.duckdns.org/123solar/scripts/boot123s.php (code=exited, status=0/SUCCESS) Main PID: 1539896 (code=exited, status=0/SUCCESS) CPU: 31ms Jan 14 14:44:07 Z800 systemd[1]: Starting 123solar_old.service - 123Solar... Jan 14 14:44:07 Z800 curl[1539896]: % Total % Received % Xferd Average Speed Time Time Time Current Jan 14 14:44:07 Z800 curl[1539896]: Dload Upload Total Spent Left Speed Jan 14 14:44:07 Z800 curl[1539896]: [158B blob data] Jan 14 14:44:07 Z800 curl[1539896]: Direct access not permitted Jan 14 14:44:07 Z800 systemd[1]: 123solar_old.service: Deactivated successfully. Jan 14 14:44:07 Z800 systemd[1]: Finished 123solar_old.service - 123Solar.

secondly I tried running the boot123.php directly, but that wasnt allowed

sudo -u www-data php scripts/boot123s.php PHP Warning: Undefined array key "SERVER_ADDR" in /var/www/bartman/123solar/scripts/boot123s.php on line 9 PHP Warning: Undefined array key "SERVER_ADDR" in /var/www/bartman/123solar/scripts/boot123s.php on line 9 Direct access not permitted

So I modified the script for trying:

I commented out

if ($_SERVER['SERVER_ADDR'] != '127.0.0.1' && $_SERVER['SERVER_ADDR'] != '::1') {

die('Direct access not permitted');

}

then I executed

sudo -u www-data php scripts/boot123s.php and it ran for 20secs... so no change

(now I uncommented the lines again to have it restored to the original)

The (debug) log, logged the starts

* 14/01/2024 14:43:53 Starting 123Solar on boot debug (1539508)

* 14/01/2024 14:44:48 Starting 123Solar on boot debug (1541052)

* 14/01/2024 14:45:25 Starting 123Solar on boot debug (1543964)

* 14/01/2024 14:48:07 Starting 123Solar on boot debug (1548504)

I'm confused by systemctl status that states:

systemd[1]: 123solar_old.service: Deactivated successfully.

jeanmarc77 commented 8 months ago

Well, give up the .service. Something wrong as your data/123solar.err file don't write today details

speeskeek commented 8 months ago

Dont know how it’s running now - but it runs since yesterday evening. Ain’t gonna touch it.

When browsing trough the files I saw some files weren’t owned by www-data. I think that fixed it. but that was one of the first things I did (sudo chown -R www-data * ). Also the file permission checker didn’t remark anything. Happy for now. Thanks dor the answers and support.

Luckily these were dark days/weeks so not a lot of logging is lost

speeskeek commented 8 months ago

I was too enthousiast… It stops right after starting (on the webpage)

jeanmarc77 commented 8 months ago

Sorry but i cannot debug without error log files. Try to give more details..

speeskeek commented 8 months ago

I don’t know what log to post here but…. hey … good news. It is working stable since a week now (in debug). I did a reboot (unintentionally) and after the reeboot it was still working (in debug). I disabled debug just now and it seems to be working. I disabled the pv output.. maybe there was some error there. not sure if I’ll enable it (there is this nice app PVoutputPro op iOS that is nice to use) later again