search

evcc-io / evcc

Sonne tanken ☀️🚘
https://evcc.io
MIT License
3.54k stars 656 forks source link

SMA Speedwire: UDP Unicast Fehler #15590

Closed andig closed 1 month ago

andig commented 2 months ago

Bin ebenfalls vom Problem betroffen, downgrade auf 129.0 alles fein, ab 130.0 startet evcc nicht mehr. Raspberry PI 4, alle WR im selben VLAN, alle involvierten Komponenten statische IP (kein DHCP), alles mit Kabel am selben Switch (kein WLAN). Aus den tcpdumps bin ich nicht schlau geworden, aber evtl. hilft euch das trace log der sma-Kommunikation zum entsprechenden WR:

0.130.0 root@rpi4-2:~# evcc --log trace | tee -a /tmp/evcc.trace.0.130.0 root@rpi4-2:~# grep 192.168.1.11 /tmp/evcc.trace.0.130.0 ``` [sma ] TRACE 2024/08/21 21:56:25 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 21:56:25 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 21:56:25 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 21:56:25 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 21:56:25 new inverter at 192.168.1.11 - Serial=305023499 [sma ] TRACE 2024/08/21 21:56:25 found device 305023499 at 192.168.1.11 [sma ] TRACE 2024/08/21 21:56:25 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 21:56:25 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 21:56:25 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 21:56:25 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 21:56:26 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 21:56:26 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 21:56:26 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 21:56:26 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 21:56:26 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 21:56:26 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 21:56:26 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 21:56:26 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 21:56:27 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 21:56:27 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 21:56:27 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 21:56:27 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 21:56:27 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 21:56:27 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 21:56:27 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 21:56:27 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 21:56:28 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 21:56:28 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [main ] FATAL 2024/08/21 21:56:34 cannot create meter 'pv2': cannot create meter type 'template': cannot create meter type 'sma': failed to get device: no Speedwire ping response for 192.168.1.11 ```
0.129.0 root@rpi4-2:~# grep 192.168.1.11 /tmp/evcc.trace.0.129.0 ``` [sma ] TRACE 2024/08/21 22:07:16 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 22:07:17 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 22:07:17 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 new inverter at 192.168.1.11 - Serial=305023499 [sma ] TRACE 2024/08/21 22:07:17 login for 192.168.1.11:9522 [sma ] TRACE 2024/08/21 22:07:17 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 new inverter at 192.168.1.11 - Serial=305023499 [sma ] TRACE 2024/08/21 22:07:17 found device 305023499 at 192.168.1.11 [sma ] TRACE 2024/08/21 22:07:17 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 requestValues for 192.168.1.11:9522: 0x5100 0x263F00 0x263FFF [sma ] TRACE 2024/08/21 22:07:17 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 requestValues for 192.168.1.11:9522: 0x5100 0x295A00 0x295AFF [sma ] TRACE 2024/08/21 22:07:17 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 requestValues for 192.168.1.11:9522: 0x5100 0x411E00 0x4120FF [sma ] TRACE 2024/08/21 22:07:17 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 requestValues for 192.168.1.11:9522: 0x5100 0x464000 0x4642FF [sma ] TRACE 2024/08/21 22:07:17 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 requestValues for 192.168.1.11:9522: 0x5100 0x464800 0x4655FF [sma ] TRACE 2024/08/21 22:07:17 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 requestValues for 192.168.1.11:9522: 0x5100 0x465700 0x4657FF [sma ] TRACE 2024/08/21 22:07:17 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 requestValues for 192.168.1.11:9522: 0x5100 0x491E00 0x495DFF [sma ] TRACE 2024/08/21 22:07:17 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 requestValues for 192.168.1.11:9522: 0x5180 0x214800 0x2148FF [sma ] TRACE 2024/08/21 22:07:17 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 requestValues for 192.168.1.11:9522: 0x5180 0x416400 0x4164FF [sma ] TRACE 2024/08/21 22:07:17 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 requestValues for 192.168.1.11:9522: 0x5200 0x237700 0x2377FF [sma ] TRACE 2024/08/21 22:07:17 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 22:07:17 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 requestValues for 192.168.1.11:9522: 0x5380 0x251E00 0x251EFF [sma ] TRACE 2024/08/21 22:07:17 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:17 requestValues for 192.168.1.11:9522: 0x5380 0x451F00 0x4521FF [sma ] TRACE 2024/08/21 22:07:17 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:18 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:18 requestValues for 192.168.1.11:9522: 0x5400 0x260100 0x2622FF [sma ] TRACE 2024/08/21 22:07:18 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:18 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:18 requestValues for 192.168.1.11:9522: 0x5400 0x462E00 0x462FFF [sma ] TRACE 2024/08/21 22:07:18 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:18 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:18 requestValues for 192.168.1.11:9522: 0x5400 0x496700 0x4988FF [sma ] TRACE 2024/08/21 22:07:18 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:18 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:18 requestValues for 192.168.1.11:9522: 0x5800 0x821E00 0x8220FF [sma ] TRACE 2024/08/21 22:07:18 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:18 recv 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:18 logout for 192.168.1.11:9522 [sma ] TRACE 2024/08/21 22:07:18 send 192.168.1.11: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry] [sma ] TRACE 2024/08/21 22:07:18 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 22:07:18 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 22:07:18 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 22:07:18 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 22:07:19 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 22:07:19 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 22:07:19 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 22:07:20 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] [sma ] TRACE 2024/08/21 22:07:20 recv 192.168.1.11: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry] ```

Habe die Logs noch etwas vergleichen, die Version 0.130.0 sendet keinen Login-Request mehr, an keinen der drei WR, obwohl diese antworten:

root@rpi4-2: grep sma /tmp/evcc.trace.0.130.0 | grep login | head -6 root@rpi4-2: grep sma /tmp/evcc.trace.0.129.0 | grep login | head -6

[sma   ] TRACE 2024/08/21 22:07:17 login for 192.168.1.11:9522
[sma   ] TRACE 2024/08/21 22:07:18 login for 192.168.1.16:9522
[sma   ] TRACE 2024/08/21 22:07:18 login for 192.168.1.12:9522
[sma   ] TRACE 2024/08/21 22:07:23 login for 192.168.1.11:9522
[sma   ] TRACE 2024/08/21 22:07:23 login for 192.168.1.16:9522
[sma   ] TRACE 2024/08/21 22:07:23 login for 192.168.1.12:9522

Hilft das? Bei Bedarf kann ich tcpdumps der Kommunikation, einen strace usw liefern.

Originally posted by @F-L-0 in https://github.com/evcc-io/evcc/discussions/15469#discussioncomment-10412398

andig commented 2 months ago

@f-l-o könntest Du mal eine speziell compilierte Version bei Dir starten?

/cc @bboehmke

F-L-0 commented 2 months ago

@f-l-o könntest Du mal eine speziell compilierte Version bei Dir starten?

Ja, klar, kann ich machen.

andig commented 2 months ago

Welches OS/Architektur? Raspi?

F-L-0 commented 2 months ago

Yup

pi@rpi4-2:~/git $ cat /etc/release PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian

bboehmke commented 2 months ago

Ich habe leider aktuell keine SMA Geräte zum testen sonst würde ich mir das mal genauer anschauen. Mit etwas Glück kann ich am Sonntag mal versuchen ob ich das Problem reproduzieren kann.

andig commented 2 months ago

@bboehmke auf einem System sehe ich (custom logging):

pi@raspberrypi:~ $ ./evcc --log error meter
[main  ] INFO 2024/08/22 18:12:09 evcc 0.130.2 (4a3200b8e)
[main  ] INFO 2024/08/22 18:12:09 using config file: /etc/evcc.yaml
!! DeviceByIP 192.168.0.47 pwd
!! DeviceByIP devices map[]
!! DeviceByIP 192.168.0.27 0000
!! DeviceByIP devices map[]
!! DeviceByIP 192.168.0.24 pwd
!! DeviceByIP 192.168.0.25 pwd
!! DeviceByIP got device &{0x6581110 0000 0x5f6d950 true {372 3011955618} 0x658cbc0}
!! conn.NewDevice device does not respond at 192.168.0.47
!! conn.NewDevice device does not respond at 192.168.0.47
!! conn.NewDevice device does not respond at 192.168.0.47
!! conn.NewDevice device does not respond at 192.168.0.47
!! conn.NewDevice device does not respond at 192.168.0.47
!! conn.NewDevice device does not respond at 192.168.0.47
!! DeviceByIP devices map[]
!! conn.NewDevice device does not respond at 192.168.0.24
!! conn.NewDevice device does not respond at 192.168.0.24
!! conn.NewDevice device does not respond at 192.168.0.24
!! conn.NewDevice device does not respond at 192.168.0.24
!! conn.NewDevice device does not respond at 192.168.0.24
!! conn.NewDevice device does not respond at 192.168.0.24
!! DeviceByIP devices map[]
!! conn.NewDevice device does not respond at 192.168.0.25
!! conn.NewDevice device does not respond at 192.168.0.25
!! conn.NewDevice device does not respond at 192.168.0.25
!! conn.NewDevice device does not respond at 192.168.0.25
!! conn.NewDevice device does not respond at 192.168.0.25
!! conn.NewDevice device does not respond at 192.168.0.25
[main  ] FATAL 2024/08/22 18:12:19 cannot create meter 'pv4': cannot create meter type 'template': cannot create meter type 'sma': failed to get device: no Speedwire ping response for 192.168.0.47

Das passiert in device.go:

        // wait for receive
        receiveCtx, receiveCancel := context.WithTimeout(ctx, time.Millisecond*500)
        net2Entry, err := device.readNet2(receiveCtx)
        receiveCancel()
        if err != nil {
            fmt.Println("!! conn.NewDevice", err)
            continue
        }

Da kommt also gar nix:

func (d *Device) readNet2(ctx context.Context) (*proto.SmaNet2PacketEntry, error) {
    var packet *proto.Packet
    select {
    case packet = <-d.receiver:
    case <-ctx.Done():
        return nil, fmt.Errorf("device does not respond at %s", d.address.IP.String())
    }

    entry := packet.GetEntry(proto.SmaNet2PacketEntryTag)
    if entry == nil {
        return nil, fmt.Errorf("received invalid response from %s", d.address.IP.String())
    }

    return entry.(*proto.SmaNet2PacketEntry), nil
}

Warum das aber wiederrum nur manchmal passieren sollte erschließt sich mir nicht :(

andig commented 2 months ago

@bboehmke noch ein bisschen Log. Wenns durch läuft:

!! DeviceByIP 192.168.0.27 0000
!! DeviceByIP devices map[]
!! DeviceByIP 192.168.0.47!
!! DeviceByIP devices map[]
!! DeviceByIP 192.168.0.24!
!! DeviceByIP 192.168.0.25!
!! DeviceByIP got device &{0x7230db0! 0x6f052c0 false {303 1930201001} 0x68bf500}
!! DeviceByIP devices map[1930201001:0x7231608]
!! DeviceByIP got device &{0x7231650! 0x6f052c0 false {409 3010439533} 0x6cec040}
!! DeviceByIP devices map[1930201001:0x7231608 3010439533:0x72316c8]
!! handlePackets busy 192.168.0.47
!! DeviceByIP got device &{0x742f908! 0x6f052c0 false {409 3010438358} 0x6ef02c0}
!! handlePackets busy 192.168.0.47
!! DeviceByIP got device &{0x7230cc0 0000 0x6f050e0 true {372 3011955618} 0x6cd9dc0}
!! handlePackets busy 192.168.0.47
!! handlePackets busy 192.168.0.24
!! handlePackets busy 192.168.0.47
!! handlePackets busy 192.168.0.25
!! handlePackets busy 192.168.0.47
!! handlePackets busy 192.168.0.24
!! handlePackets busy 192.168.0.25
!! handlePackets busy 192.168.0.47
!! handlePackets busy 192.168.0.47
!! handlePackets busy 192.168.0.47
!! handlePackets busy 192.168.0.24
!! handlePackets busy 192.168.0.25
!! handlePackets busy 192.168.0.47
!! handlePackets busy 192.168.0.47
!! handlePackets busy 192.168.0.47
!! handlePackets busy 192.168.0.25
!! handlePackets busy 192.168.0.47
!! handlePackets busy 192.168.0.24
!! handlePackets busy 192.168.0.47
!! handlePackets busy 192.168.0.25
!! handlePackets busy 192.168.0.24
!! handlePackets busy 192.168.0.47
!! handlePackets busy 192.168.0.47
!! handlePackets busy 192.168.0.24
!! handlePackets busy 192.168.0.25
!! handlePackets busy 192.168.0.24
!! handlePackets busy 192.168.0.25
!! handlePackets busy 192.168.0.25
!! handlePackets busy 192.168.0.24
!! handlePackets busy 192.168.0.25
!! handlePackets busy 192.168.0.24
!! handlePackets busy 192.168.0.25
!! handlePackets busy 192.168.0.24
!! handlePackets busy 192.168.0.25
!! handlePackets busy 192.168.0.24
!! handlePackets busy 192.168.0.25
!! handlePackets busy 192.168.0.24
!! handlePackets busy 192.168.0.27
!! handlePackets busy 192.168.0.24
!! handlePackets busy 192.168.0.25
!! handlePackets busy 192.168.0.25
!! handlePackets busy 192.168.0.47
!! handlePackets busy 192.168.0.47
!! handlePackets busy 192.168.0.24
!! handlePackets busy 192.168.0.24
!! handlePackets busy 192.168.0.24
!! handlePackets busy 192.168.0.25
!! handlePackets busy 192.168.0.25
!! handlePackets busy 192.168.0.27
!! handlePackets busy 192.168.0.25
!! handlePackets busy 192.168.0.24
!! handlePackets busy 192.168.0.25
!! handlePackets busy 192.168.0.24
!! handlePackets busy 192.168.0.25
!! handlePackets busy 192.168.0.24

battery5
--------
!! handlePackets busy 192.168.0.27
!! handlePackets busy 192.168.0.27
Power:        0W
Energy:       2741.3kWh
Soc:          100%
Capacity:     7.7kWh
Controllable: true
...

Wenns nicht durch läuft:

!! conn.NewDevice device does not respond at 192.168.0.24
!! handlePackets busy 192.168.0.24
!! handlePackets busy 192.168.0.27
!! handlePackets busy 192.168.0.27
!! handlePackets busy 192.168.0.27
!! handlePackets busy 192.168.0.27
!! handlePackets busy 192.168.0.27
!! handlePackets busy 192.168.0.27
!! handlePackets busy 192.168.0.27
!! handlePackets busy 192.168.0.27
!! handlePackets busy 192.168.0.27
!! conn.NewDevice device does not respond at 192.168.0.24
!! handlePackets busy 192.168.0.24
!! handlePackets busy 192.168.0.27
!! handlePackets busy 192.168.0.27
!! handlePackets busy 192.168.0.27
!! handlePackets busy 192.168.0.27
!! handlePackets busy 192.168.0.27
!! handlePackets busy 192.168.0.27
!! conn.NewDevice device does not respond at 192.168.0.24
[main  ] FATAL 2024/08/22 18:41:26 cannot create meter 'pv4': cannot create meter type 'template': cannot create meter type 'sma': failed to get device: no Speedwire ping response for 192.168.0.47

Es sieht aus als würde da ein receiver blockieren? Es kommen Pakete von der richtigen IP, können aber nicht verarbeitet werden.

bboehmke commented 2 months ago

Ich werde mal das logging noch etwas erweitern.

darüber hinaus habe ich noch eine Funktion gefunden die eine Liste nicht sauber aufräumt (aber das sollte diese Probleme nicht verursachen)

F-L-0 commented 2 months ago

Kann es sein das das Problem nur bei mehreren Devices auftritt? Ich kenne die internas nicht, aber was mir im strace aufgefallen ist:

PID/Thread-ID raussuchen die die Speedwire Connection zum WR mit der .11 enthält, erster Logeintrag:

root@rpi4-2:~# grep 192.168.1.11 /tmp/strace_evcc.log | head -1
[pid   560] sendto(6, "SMA\0\0[entfernt]"..., 58, 0, {sa_family=AF_INET, sin_port=htons(9522), sin_addr=inet_addr("192.168.1.11")}, 16 <unfinished ...>

Letzter EIntrag zu dieser Thread-ID:

root@rpi4-2:~# grep 192.168.1.11 /tmp/strace_evcc.log | tail -1
[pid   560] write(1, "[main  ] FATAL 2024/08/22 18:49:"..., 197[main  ] FATAL 2024/08/22 18:49:21 cannot create meter 'pv2': cannot create meter type 'template': cannot create meter type 'sma': failed to get device: no Speedwire ping response for 192.168.1.11

Der Thread joined die Multicast-Gruppe des Homemangers/Energy Meters - die WR machen aber Unicast - keine Ahnung ob das von Belang ist:

[pid 560] setsockopt(6, SOL_IP, IP_ADD_MEMBERSHIP, {imr_multiaddr=inet_addr("239.12.255.254"), imr_interface=inet_addr("0.0.0.0")}, 8 <unfinished ...>

Die Kommunikation vom WR (hier .11) kommt beim Thread an:

[pid   560] recvfrom(7, "SMA\0\0\4\2\240\0\0\0\1\0\2\0\0\0\1\0\4\0\20\0\1\0\1\0\4\0 \0\0"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(9522), sin_addr=inet_addr("192.168.1.11")}, [1
12->16]) = 54
[pid   560] clock_gettime(CLOCK_REALTIME, {tv_sec=1724345353, tv_nsec=272668741}) = 0
[pid   560] clock_gettime(CLOCK_MONOTONIC, {tv_sec=203650, tv_nsec=766108058}) = 0
[pid   560] clock_gettime(CLOCK_MONOTONIC, {tv_sec=203650, tv_nsec=766400499}) = 0
[pid   560] futex(0x64625d0, FUTEX_WAKE_PRIVATE, 1) = 1
[pid   560] recvfrom(7, 0x6c32000, 2048, 0, 0x6daedb8, [112]) = -1 EAGAIN (Die Ressource ist zur Zeit nicht verfügbar)

Ich habe den selben strace mit der 0.129.0 gemacht und verglichen.

Thread-ID für den WR mit der .11:

root@rpi4-2:~# grep 192.168.1.11 /tmp/strace_evcc_129.log | head -1
[pid  1150] <... recvfrom resumed> "SMA\0\0\[entfernt]"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(9522), sin_addr=inet_addr("192.168.1.11")}, [112->16]) = 54

Sieht sehr ähnlich aus (auch die EAGAIN Meldungen), was mit als Unterschied aufgefallen ist ist das bei der funktionierenden Version der Multicast-Join in einem anderen Thread passiert, WR ist am Thread 1150, Multicast am Thread 1148:

root@rpi4-2:~# grep "IP_ADD_MEMBERSHIP" /tmp/strace_evcc_129.log
[pid  1148] setsockopt(7, SOL_IP, IP_ADD_MEMBERSHIP, {imr_multiaddr=inet_addr("239.12.255.254"), imr_interface=inet_addr("192.168.1.230")}, 8 <unfinished ...>
[pid  1148] setsockopt(8, SOL_IP, IP_ADD_MEMBERSHIP, {imr_multiaddr=inet_addr("239.12.255.254"), imr_interface=inet_addr("0.0.0.0")}, 8 <unfinished ...>

In der .130.0 erfolgt der Multicast join an 2 verschiedenen Threads:

root@rpi4-2:~# grep "IP_ADD_MEMBERSHIP" /tmp/strace_evcc.log
[pid   560] setsockopt(6, SOL_IP, IP_ADD_MEMBERSHIP, {imr_multiaddr=inet_addr("239.12.255.254"), imr_interface=inet_addr("0.0.0.0")}, 8 <unfinished ...>
[pid   554] setsockopt(7, SOL_IP, IP_ADD_MEMBERSHIP, {imr_multiaddr=inet_addr("239.12.255.254"), imr_interface=inet_addr("192.168.1.230")}, 8 <unfinished ...>

Evtl. irgendwas nicht Thread-Safe? Gibt es so was bei Go?

bboehmke commented 2 months ago

@F-L-0 also das Multicast join sollte egal sein. Speedwire ist "Multicast" ohne group join. (Keine Ahnung was SMA da gemacht hat)

@andig ich hab mal nen paar Änderungen an der sunny lib gepusht. es gibt jetzt ein

sunny.EnableDetailedPacketLogging(true)

womit noch mehr paket details geloggt werden (das kann bei Fehlern das log recht schnell füllen deshalb hinter dem flag).

Du kannst damit ja mal einen test build machen, ich kann das ganze frühstens am Sonntag mit SMA Geräten testen.

F-L-0 commented 2 months ago

@F-L-0 also das Multicast join sollte egal sein. Speedwire ist "Multicast" ohne group join. (Keine Ahnung was SMA da gemacht hat)

Hmm, der Netzwerkstack sieht mir so aus als würde evcc nen multicast Join machen - das ist dann für's EnergyMeter, oder? Die Wechselrichter-Kommunikation schaut im tcpdump nach Unicast (UDP Port 9522) aus.

root@rpi4-2: netstat -gn | grep 239.12.255.254
root@rpi4-2: systemctl start evcc
root@rpi4-2: netstat -gn | grep 239.12.255.254
eth0            2      239.12.255.254
bboehmke commented 2 months ago

Da evcc bzw die lib die normalen Multicast network stack nutzt kommt es zu einem multicast join (das ist bei SMA immer 239.12.255.254:9522). Da allerdings die SMA Geräte keinen Multicast join machen funktioniert das am Ende nicht 100% korrekt (das ist übrigens der Grund warum einige Switche nicht funktionieren bzw warum IGMP snooping deaktiviert werden muss).

Bezüglich der Kommunikation zwischen den Geräten:

  1. Die EnergyMeter hauhen einfach einmal die Sekunde ihre Daten an diese Multicast adresse (egal ob join oder nicht, kann man in Wireshark sehen).

  2. für reguläre Geräte wird der Multicast/Broadcast nur verwendet um sie zu finden. Die restliche Kommunikation findet über Unicast statt. (Die Multicast Gruppe bzw IP ist die gleiche wie beim Energy Meter)

premultiply commented 2 months ago

Das IGMP-Join macht normalerweise der verwendete IP-Stack wenn man auf eine MC-Adresse lauscht und der erste IGMP-fähige Switch verarbeitet das auch normalerweise gleich intern und filtert die Pakete. Daher sieht man die Joins anderer Geräte normalerweise nicht auf anderen Ports im Netzwerk. Da muss man im Zweifelsfall auf dem Switch gucken (der hoffentlich so eine Funktion hat :) ) wer wie und was abonniert hat.

andig commented 2 months ago

fwiw ich sehe das Problem nur, wenn ich versuche >1 Zähler gleichzeitig anzulegen. Bei einem Zähler läufts immer durch. Im neuen Release werden alle Zähler gleichzeitig parallel initialisiert. Es könnten Races sein. Auf dem Test-Raspi kann ich leider keinen -race Build machen, sonst wäre das die nächste Analyse.

andig commented 2 months ago

@F-L-0 könntest Du mal bitte probieren, noch das interface zu konfigurieren?

bboehmke commented 2 months ago

Ich habe jetzt mit evcc 0.130.2 und SMA Geräten (1x EnergyMeter. 1x PV inverter & 1x Batery inverter) getestet und kann das Problem nicht nachstellen.

Was ich im tarce log komisch finde das er einige Geräte mehrfach findet. Aber sonst funktioniert bei mir alles Prima.

[sma   ] TRACE 2024/08/25 11:18:13 send 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:13 recv 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:13 new inverter at 192.168.4.51 - Serial=XXXXXXXXX
[sma   ] TRACE 2024/08/25 11:18:13 login for 192.168.4.51:9522
[sma   ] TRACE 2024/08/25 11:18:13 send 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:13 send 192.168.4.50: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:13 send 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:13 recv 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:13 new inverter at 192.168.4.51 - Serial=XXXXXXXXX
[sma   ] TRACE 2024/08/25 11:18:13 found device XXXXXXXXX at 192.168.4.51
[sma   ] TRACE 2024/08/25 11:18:13 requestValues for 192.168.4.51:9522: 0x5100 0x263F00 0x263FFF
[sma   ] TRACE 2024/08/25 11:18:13 send 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:13 recv 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:13 recv 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:13 requestValues for 192.168.4.51:9522: 0x5100 0x295A00 0x295AFF
[sma   ] TRACE 2024/08/25 11:18:13 send 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:13 recv 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:13 requestValues for 192.168.4.51:9522: 0x5100 0x411E00 0x4120FF
[sma   ] TRACE 2024/08/25 11:18:13 send 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:13 recv 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:13 requestValues for 192.168.4.51:9522: 0x5100 0x464000 0x4642FF
[sma   ] TRACE 2024/08/25 11:18:13 send 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.51:9522: 0x5100 0x464800 0x4655FF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.51:9522: 0x5100 0x465700 0x4657FF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.51:9522: 0x5100 0x491E00 0x495DFF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.51:9522: 0x5180 0x214800 0x2148FF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.51:9522: 0x5180 0x416400 0x4164FF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.51:9522: 0x5200 0x237700 0x2377FF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.51:9522: 0x5380 0x251E00 0x251EFF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.51:9522: 0x5380 0x451F00 0x4521FF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.51:9522: 0x5400 0x260100 0x2622FF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.51:9522: 0x5400 0x462E00 0x462FFF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.50: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 new energy meter at 192.168.4.50 - Serial=XXXXXXXXXX
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.50: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 new inverter at 192.168.4.52 - Serial=XXXXXXXXXX
[sma   ] TRACE 2024/08/25 11:18:14 login for 192.168.4.52:9522
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.51:9522: 0x5400 0x496700 0x4988FF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.51:9522: 0x5800 0x821E00 0x8220FF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 logout for 192.168.4.51:9522
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.51: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.52:9522: 0x5100 0x263F00 0x263FFF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.52:9522: 0x5100 0x295A00 0x295AFF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.52:9522: 0x5100 0x411E00 0x4120FF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.52:9522: 0x5100 0x464000 0x4642FF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.52:9522: 0x5100 0x464800 0x4655FF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 send discover package
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.50: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry, proto.UnknownPacketEntry, proto.UnknownPacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.50: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.51: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.52: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry, proto.UnknownPacketEntry, proto.UnknownPacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.52:9522: 0x5100 0x465700 0x4657FF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.52:9522: 0x5100 0x491E00 0x495DFF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.52:9522: 0x5180 0x214800 0x2148FF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.52:9522: 0x5180 0x416400 0x4164FF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.52:9522: 0x5200 0x237700 0x2377FF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.52:9522: 0x5380 0x251E00 0x251EFF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.52:9522: 0x5380 0x451F00 0x4521FF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.52:9522: 0x5400 0x260100 0x2622FF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.52:9522: 0x5400 0x462E00 0x462FFF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.52:9522: 0x5400 0x496700 0x4988FF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 requestValues for 192.168.4.52:9522: 0x5800 0x821E00 0x8220FF
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 logout for 192.168.4.52:9522
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 send discover package
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.51: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.50: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry, proto.UnknownPacketEntry, proto.UnknownPacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 send 192.168.4.50: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:14 recv 192.168.4.52: [proto.GroupPacketEntry, proto.UnknownPacketEntry, proto.SmaNet2PacketEntry, proto.DiscoveryRequestPacketEntry, proto.DiscoveryIPPacketEntry, proto.UnknownPacketEntry, proto.UnknownPacketEntry, proto.UnknownPacketEntry]
[sma   ] TRACE 2024/08/25 11:18:15 recv 192.168.4.50: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
[sma   ] TRACE 2024/08/25 11:18:15 new energy meter at 192.168.4.50 - Serial=XXXXXXXXXX
[sma   ] TRACE 2024/08/25 11:18:15 found device XXXXXXXXXX at 192.168.4.50
[sma   ] TRACE 2024/08/25 11:18:15 send 192.168.4.52: [proto.GroupPacketEntry, proto.SmaNet2PacketEntry]
pv
--
Power:          1047W
Energy:         48446.8kWh
Current L1..L3: 1.53A 1.53A 1.53A
Voltage L1..L3: 231V 232V 222V
Power L1..L3:   353W 355W 339W

battery
-------
Power:          -180W
Energy:         7533.2kWh
Current L1..L3: 0A 0A 1.02A
Voltage L1..L3: 0V 0V 223V
Power L1..L3:   0W 0W -180W
Soc:            2%

grid
----
Power:          -4W
Energy:         14771.9kWh
Current L1..L3: 2.54A -1.19A -1.23A
Voltage L1..L3: 223V 232V 231V
Power L1..L3:   460W -233W -231W
premultiply commented 2 months ago

Was ich im tarce log komisch finde das er einige Geräte mehrfach findet.

WiFi an den WR aktiv? Dann sind diese ggf. parallel per LAN und WiFi mit unterschiedlichen IPs verbunden. Ein sehr häufiger Konfigurationsfehler, der zu den merkwürdisten Effekten führt. Insbesondere wenn zufällig die WiFi-Verbindung verwendet wird.

bboehmke commented 2 months ago

Nein die Geräte sind alle nur via Kabel angeschlossen und WLAN war nie konfiguriert. Einzig mein Notebook war im LAN und WLAN aber eigentlich hat das Speedwire Zeug bei mir via WLAN nie wirklich funktioniert

F-L-0 commented 2 months ago

@F-L-0 könntest Du mal bitte probieren, noch das interface zu konfigurieren?

Das interface ist/war bereits konfiguriert, hier die entsprechende Config meiner SMA Geräte:

meters:
- type: template
  template: sma-energy-meter
  usage: grid
  host: 192.168.1.13
  interface: eth0
  name: grid1
- type: template
  template: sma-inverter
  usage: pv
  host: 192.168.1.11
  name: STP10000
- type: template
  template: sma-inverter
  usage: pv
  host: 192.168.1.16
  password: [entfernt]
  name: SB36
- type: template
  template: sma-inverter
  usage: battery
  host: 192.168.1.12
  capacity: 13.44
  name: SI60H

Ich habe evcc schon mal selbst auf dem Raspi gebaut (vor 3 Jahren), bekomm das "make assets" aber leider nicht mehr ans laufen, hab da jetzt 2h rumprobiert aber go mod und ich werden da grad keine Freunde...

Im neuen Release werden alle Zähler gleichzeitig parallel initialisiert. Es könnten Races sein.

Das im strace sichtbare geänderte Verhalten zwischen der .129 und der .130 bezüglich der Threads und der Multicast-Kommunikation würde dazu passen. Wenn mir jemand je einen Build vor und nach der Änderung/dem entsprechenden Commit zur Verfügung stellen könnte würde könnte ich das gerne mal testen.

F-L-0 commented 2 months ago

https://github.com/evcc-io/evcc/discussions/15744#discussioncomment-10464887 kann ich bestätigen, hilft auch bei mir. Sobald ich das interface in der Config beim SHM raus nehme startet evcc wieder - sowohl mit der 0.130.0 als auch der 0.130.6

andig commented 2 months ago

Na das ist ja mal spannend! Hat irgendjemand eine Idee warum? Ich würde das immer noch gerne live debuggen, es gab allerdings noch keine gute Idee, wie das netzwerktechnisch gehen sollte. Falls jemand eine Idee hat gerne melden!

encbladexp commented 2 months ago

Da ich auch schon anderweitig mal Spaß mit IGMP bzw. Multicast hatte, ging auch mein EVCC erst nachdem ich das hier gemacht hatte:

ip route add 224.0.0.0/4 dev eth0

Kann man natürlich nur machen wenn einem sonst Multicast eher weniger wichtig ist, sorgt halt dafür das alles was eine Multicast Adresse hat hart über ein spezifisches Interface geroutet wird.

Gibt keine Punkte für Schönheit, hat hier aber mit der 129er Version gut funktioniert. Auf 130 bin ich bisher (aus zeitlichen Gründen) noch nicht.

Hilft dieser Workaround hier auch?

andig commented 2 months ago

@bboehmke hast Du eine Idee, warum ein zugewiesenes Interface in alter Version funktionieren sollte, in neuer aber nicht mehr? So gravierende Änderungen im Go Netzwerkstack kann ich mir fast nicht vorstellen?

bboehmke commented 2 months ago

Mir ist es ein komplettes Rätsel warum es ohne Interface besser funktioniert. Die Funktion ist ja genau dafür das die Pakete über das richtige Interface geschickt werden.

Änderungen am go Netzwerk Stack waren auch meine Idee aber wenn ich mich nicht vertan habe nutzt evcc ja in der 0.129 bereits go1.23. Daher ist das auch unwahrscheinlich.

Ich kann es auch leider bei dem SMA Setup meiner Eltern nicht reproduzieren sonst würde ich versuchen dem genauer auf den Grund zu gehen.

Ich würde gerne irgendwie dem Problem auf den Grund gehen aber ich hab keine Idee was ich noch tun könnte

andig commented 1 month ago

Mangels Möglichkeit das zu testen mache ich hier mal zu. Der Workaround besteht darin, dass interface leer zu lassen.

Daher ist das auch unwahrscheinlich.

@bboehmke das mag durchaus auch an der Version von golang.org/x/sys liegen, weniger der Go Version.