Probleme bei zwei parallelen Telefonaten about iobroker.tr-064

[Apollon77]

@maeb3 Bitte mit 2.0 vom GitHub neues Debug Log erstellen und posten bzw an [email protected] senden

[maeb3]

TR-064 Adapter (community-Adapter) ist installiert.
Der Fehler tritt auch bei der Version 2.0.0 noch auf.

Wir haben mehrere Telefonnummern/Leitungen in der Fritzbox konfiguriert. Bei zwei eingehenden Telefonaten (die sich zeitlich überlappen), werden diese in der Fritzbox Anrufliste korrekt angezeigt inkl. der Richtung des Anrufs (eingehend/ausgehend):

In der JSON-Calliste im tr-064 Adapter wird aber beim ersten Anruf dann die Richtung nicht übernommen.

Auszug aus der JSON-Calllist:
[{
"id":6372,"type":"1","caller":"0173345xxxx","called":"SIP: 7191xxxx", "callednumber":"7191xxxx","name":"Eberle Matthias","numbertype":"sip","device":"FritzFon 1",
"port":"11","date":"16.12.19 20:14","duration":"0:01","count":"",
"path":"",
"sym":">",
"external":"0173345xxxx"
},
{
"id":6371,"type":"9","caller":"0178180xxxx","called":"SIP: 71910754",
"callednumber":"7191xxxx","name":"Eberle Matthias","numbertype":"sip","device":"FritzFon 2",
"port":"10","date":"16.12.19 20:13","duration":"0:02","count":"",
"path":"",
"external":"0178180xxxx"
}

Das zugehörige Debug-Logfile schicke ich per Mail an die genannte Mail-Adresse.

Grüße,
maeb3

[Apollon77]

Der eine Eintrag hat einen Wert "type: 9" und das ist das problem. Der Adapter kennt typen

const SYMS = {1: '>' /blau/, 2: 'x' /rot/, 3: '<' /grün/ };

Muss jetzt nur finden was das bedeutet. Luft der Call vllt noch?
Hab nur https://service.avm.de/help/en/FRITZ-Box-Fon-WLAN-7490-avme/014/hilfe_fon_anrufliste gefunden, was aber nicht passt.

Und habe gefunden:

Der eigentliche Witz im Zusammenhang mit diesem Thread ist aber die Tatsache, daß diese Datei (am Ende) auch laufende Gespräche enthält, diese werden durch einen Wert > 8 im Type-Feld gekennzeichnet (11 ist dann z.B. ein aktiver ausgehender Anruf).

Also wäre dann erweiterung:

const SYMS = {1: '>' /blau/, 2: 'x' /rot/, 3: '<' /grün/, 9: '>' /blau/, 11: '<' /grün/ };

??!

[Apollon77]

ok, scheinbar noch 10 (Blockiert) dazu.

Bitte neue GitHub version checken (2.0.2)

[maeb3]

Kann die 2.0.2 erst am WE verproben, da aktuell unterwegs. Melde mich dann.

Wenn ich es richtig verstehe, wird zu dem Zeitpunkt, zu dem das erste von zwei parallelen Gesprächen beendet wird,

• sowohl ein Eintrag in der Call-Liste für das gerade beendete Gespräch aufgenommen (mit korrekter Richtung und korrekter Dauer)
• als auch ein Eintrag in der Call-Liste für das zu diesem Zeitpunkt noch laufende Gespräch aufgenommen (ohne Richtung und mit falscher Dauer, da die richtige Dauer zu diesem Zeitpunkt ja noch nicht feststeht - Gespräch läuft ja noch).

Ich nehme an, dass zum späteren Zeitpunkt, wenn dann auch das zweite Gespräch beendet wird, kein neuer Eintrag mehr in der Call-Liste im Adapter erstellt wird, weil das Gespräch mit dieser ID ja bereits enthalten ist. Richtig?
[Ursprünglich hatte ich angenommen, dass die Call-Liste bei jedem Trigger (Gesprächsende) komplett neu aus der Fritzbox geladen wird, so dass immer für alle abgeschlossenen Gespräche alle Einträge in der Call-Liste identisch zur Fritzbox sind mit den korrekten Werten (Richtung + Dauer)].

Wäre es nicht sinnvoller, die Verbindungen mit dem type: 9, 10 und 11 im Adapter einfach zu ignorieren und nicht in die Call-Liste aufzunehmen? Wenn dann das zweite Gespräch zu einem späteren Zeitpunkt beendet wird, käme ja vermutlich ein neuer und dann auch korrekter Eintrag (mit Richtung und Dauer) hinzu, weil ja mit dieser ID noch kein Eintrag in der Liste steht.
Und die Anzeige von laufenden Gesprächen in der Call-Liste hatten wir doch bisher auch nicht im Adapter, oder?

[Apollon77]

Gute Frage ... also lastcall.timestamp sollte - wenn ich den Code korrekt verstehe - nur beim auflegen aktualisiert werden und das löst den refresh der calllist aus.

Also ja bei laufenden Gerprächen wäre die Zeit falsch, man könnte da duration aber auch mit "leer" überschreiben ... ?!

[maeb3]

Zunächst mal die Rückmeldung, dass deine Anpassung (in v.2.0.2) wirkt und die Richtung des zweiten (parallelen) Gesprächs jetzt korrekt angezeigt wird. Vielen Dank.
Die falsche Gesprächsdauer dieses Gesprächs wird wie bereits vermutet dadurch aber nicht korrigiert. 

So wie ich den Code verstehe (bin allerdings ziemlicher Javascript Laie) wird beim Beenden eines der beiden parallelen Gespräch (neuer lastCall.timestamp) die Callliste neu eingelesen:
...
else if (adapter.config.calllists.use && id.indexOf('callmonitor.lastCall.timestamp') > 0) { tr064Client.refreshCalllist();
...

Die neu eingelesene Callliste enthält neben dem gerade beendeten Gespräch aber auch das aktuell noch laufende Gespräch mit entsprechendem call.type = 9 oder 10 oder 11.

Die neuen Einträge der Calllist werden verarbeitet:
in calllist.js (Zeile 136) wird geprüft, ob die IDs (call.id) der neuen Einträge schon vorhanden sind und falls nicht, werden die neuen Einträge in das Array übernommen: 
...
if (!list.array.find(function (v) { return v.id === call.id; })) list.array.unshift(call);
...

D.h. neben dem gerade beendeten Gespräch wird auch das noch laufende Gespräch in das Array eingetragen. 
Wird nun später auch das zweite Gespräch beendet, wird wieder das Einlesen der Callliste getriggert, aber bei der Verarbeitung des neuen Eintrags für das zweite Gespräch (gleiche ID, aber diesmal mit call.type  = 0/1/2/3) festgestellt, dass die ID bereits im Array vorhanden ist und somit wird kein neuer Eintrag im Array vorgenommen und kein vorhandener Eintrag im Array angepasst.
D.h. der Array-Eintrag für das zweite Gespräch bleibt so, wie er zum Zeitpunkt der Beendigung des ersten Gesprächs war (falscher Type, falsche Dauer). 

Von daher wäre es doch sinnvoll, die Einträge mit call.type = 9/10/11 bei der Verarbeitung wegzufiltern, weil diese ja später (wenn auch das zweite Gespräch beendet wurde) nochmal mit korrekter Dauer und call.type = 0/1/2/3 geliefert werden. Könnte man daher nicht einfach (in calllist.js Zeile 146) für die laufenden Gespräche den Eintrag ins Array weglassen?
...
if(call.type > 3) {      
adapter.log.debug('Current connection (call ID: ' + call.id + ') ignored');
return;
}
...

Ich werde mich mal daran versuchen und prüfen, ob ich das im Code lokal bei mir testweise hinbekomme und ob das danach korrekt funktioniert.

Grüße,
maeb3

[Apollon77]

Ok. Gute idee. Schaue ich mir nachher an.

[maeb3]

Habe jetzt verschiedene Tests durchgeführt.
Habe zunächst in this.add (calllist.js ab Zeile 154) folgendes geändert:

if(call.type > 3) {
     adapter.log.debug('Call ID' + call.id + ' still active -> no entry in calllist'); 
} else {   
    this.addListItem(n, call);
    this.addListItem('all', call);
}

damit nur dann ein Eintrag in die Liste vorgenommen wird, wenn der Call nicht mehr aktiv ist (also call.type = 0/1/2/3).

Habe dann allerdings festgestellt, dass bei zwei parallelen Gesprächen, bei denen das zuerst begonnene Gespräch (also mit der niedrigeren Call.id) länger dauer als das zweite Gespräch (mit der höheren Call.id), nur das zuerst beendete Gespräch in die Liste übernommen wird. Das hängt m.E. daran, dass in der function "refresh" (calllist.js ab Zeile 178) nur Calls abgefragt werden mit "neueren IDs als die letzte ID".

let url = data.NewCallListURL;
if (systemData.native.callLists.lastTimestamp) url += '&timestamp=' + systemData.native.callLists.lastTimestamp;
if (systemData.native.callLists.lastId) url += '&id=' + systemData.native.callLists.lastId;

Da die Call.id des ersten Calls ja niedriger ist als die des zweiten bereits erfassten (und somit auch niedriger als die lastId), wird dieser Call hier nicht mehr abgefragt.

Ich habe daher jetzt testweise mal die Zeile 183 auskommentiert:
// if (systemData.native.callLists.lastId) url += '&id=' + systemData.native.callLists.lastId;

Es werden zwar jetzt bei jedem Trigger deutlich mehr Calls abgefragt (da keine Einschränkung mehr auf die letzte Call.id), da aber die meisten IDs bereits zuvor erfasst werden, landen nur die tatsächlich neuen in der calllist (wg. Zeile 136: if (!list.array.find(function (v) { return v.id === call.id; })) list.array.unshift(call); )
Das ist zwar unschön, dass jetzt auch noch bereits erfasste Calls abgefragt werden, aber nach den ersten Tests scheint es für mich nun auch bei parallelen Gesprächen zu funktionieren. Ich kann aber nicht wirklich beurteilen, ob diese Zeile nicht noch andere negative Effekte hat.
Kann irgendwer beurteilen, was es bedeutet, wenn nicht nur die Calls ab der letzten Call.id abgefragt werden?
Gemäß Fritzbox Doku, könnte man die Abfrage auch auf die Calls des aktuellen Tages beschränken.

[Apollon77]

Wie wäre es damit als lastId die zu nehmen des letzten beendeten anrufs wo vorher kein anderer ist ...?!

[Apollon77]

also in calllist L138 den vergleich ändern das er nur die neue "LastId" setzt sobald er vorher keines mit call type 9 oder 11 gefunden hat. man müsste sich also merken ob in der liste ein 9 oder 10er call war und wenn ja die lastId nicht updaten oder ?!

[maeb3]

Hallo,

ich habe jetzt seit ca. einer Woche folgende Anpassung in der calllist.js bei mir am Start und bisher scheinen damit alle bei mir vorkommenden Konstellationen mit parallelen Telefonaten zu funktionieren:

this.addCall2List = function(call, listName) {
        if (!call) return;
        const list = this[listName];
        if (!list || !list.use) return;
        if (!list.array.find(function (v) { return v.id === call.id; })) {
            list.array.unshift(call);
            if (list.array.length > list.cfg.maxEntries) list.array.length = list.cfg.maxEntries;
            if (list.lastId < call.id) {
                list.lastId = call.id;
                list.count += 1;
            }
        }
    };

    this.addCall = function(call){
        call.id = ~~call.id;
        if(call.type > 3){
            adapter.log.debug('Ignoring call ID' + call.id + ' because call still active (call.type = ' + call.type + ')');
        } else {
            adapter.log.debug('Processing call ID' + call.id + ' (call.type = ' + call.type + ')');
            call.sym = SYMS[call.type];
            //call.external = call [externalMapping[~~call.type]];
            call.external = call [(~~call.type) === 3 ? 'called' : 'caller'];
            //call.escapedSym = ESCAPED_SYMS[call.type];
            this.addCall2List(call, NO2NAME[call.type] || call.type);
            this.addCall2List(call, 'all');
        }
    };

    this.add = function(call, timestamp) {
        if (!call) return;
        if (timestamp != undefined && timestamp > this.lastTimestamp) this.lastTimestamp = timestamp;
        let blocker = false;
        if (Array.isArray(call)) {
            adapter.log.debug('Separating parallel calls for calllist handling');
            call.sort((a,b) => (a.id > b.id) ? 1 : -1);  
            // war call.reverse(); scheinbar sortiert die FB aber die calls im Array zuerst nach aktiven Calls und erst dann die abgeschlossenen Calls nach absteigender call.id
            call.forEach(function(singleCall) {  
	        this.addCall(singleCall);                // process all calls of the array
		if(singleCall.type > 3) blocker = true;  // but don't update lastId if an earlier started call is still active
                if(!blocker && singleCall.id > systemData.native.callLists.lastId) systemData.native.callLists.lastId = singleCall.id; 
	    }.bind(this));
        } else {
	    this.addCall(call);
            if (call.id > this.lastId) this.lastId = call.id;
	}
    };

    this.forEach = function (cb) {
        for (const n in TYPES) {
            const list = self[n];
            if (!list || !list.use) continue;
            if (list.cfg.generateHtml) html.build(list);
            cb(list, n, html.result, self);
        }
    };

...

function refresh (err, data, cb, done) {
    if (err || !data) return;
    if (!systemData.native.callLists) return;
    let url = data.NewCallListURL;
    if (systemData.native.callLists.lastTimestamp) url += '&timestamp=' + systemData.native.callLists.lastTimestamp;
    if (systemData.native.callLists.lastId) url += '&id=' + systemData.native.callLists.lastId;
    //url += '&max=999';
    soef.getHttpData(url, {xml2json: true}, function (err, json) {
        adapter.log.debug('Result Callist JSON: ' + JSON.stringify(json));
        systemData.native.callLists.add(json.root.call, ~~json.root.timestamp);
        systemData.native.callLists.forEach(cb);
        systemData.save();
        done && done();
    });
}

Kann die Code-Änderungen auch gerne in Github als PR einstellen.
Da ich aber nicht in der javascript-Welt zu Hause bin, kann vielleicht vorher nochmal ein "Wissender" über den Code schauen.
Habe mit dem Code versucht, zu unterscheiden, ob nur ein neuer Call erkannt wurde (dann bleibt weitestgehend alles beim alten). Falls aber mehrere neue Calls bei einer Abfrage zurückgemeldet werden, dann werden diese separiert und einzeln bearbeitet. Als last.id (für die nächste Abfrage) wird dann die call.id des Calls verwendet, der die niedrigste call.id hat, aber noch läuft (call.type > 3).

Grüße,
maeb

[Apollon77]

mach nen PR, iterieren wir dann im PR drüber! Danke!

[Apollon77]

fixed by 3.0.0