Modul 96_SIP

[Wzut]

und ein Auszug aus dem Eventmanager mit Log-File-Einträgen:

Bitte nicht, poste bitte den betreffenden Abschnitt direkt aus der Log Datei (im Event Monitor steht nicht immer alles)
und schneide bitte das Log nicht zu früh ab. In deinem Post hat der Client ja noch gar nicht aufgelegt.

[trabantp60]

Sorry,

ich hoffe, so ist's besser:

Code Auswählen Erweitern

2021.04.20 19:24:21.136 5: SIP_CLIENT, listen process 10710 found
2021.04.20 19:25:20.995 4: SIP_CLIENT[10710], register new expire : 2021-04-20 19:36:20
2021.04.20 19:25:20.997 5: SIP_CLIENT, readingB:state Val:listen_dtmf
2021.04.20 19:25:20.997 5: SIP_CLIENT, readingB:listen_alive Val:10710
2021.04.20 19:25:20.997 5: SIP_CLIENT, readingB:expire Val:660
2021.04.20 19:25:21.241 5: SIP_CLIENT, listen process 10710 found
2021.04.20 19:26:21.323 5: SIP_CLIENT, listen process 10710 found
2021.04.20 19:27:21.374 5: SIP_CLIENT, listen process 10710 found
2021.04.20 19:27:43.666 5: SIP_CLIENT[10710], SIP_filter : <sip:+49160XXXXXXX@ims.vodafone.de;user=phone>;tag=h7g4Esbg_p65554t1618939663m593389c126153s1_3280994596-545925051
2021.04.20 19:27:43.667 4: SIP_CLIENT[10710], SIP_filter: caller sip:+49160XXXXXXX@ims.vodafone.de, caller_nr +49160XXXXXXX, caller_name
2021.04.20 19:27:43.668 4: SIP_CLIENT[10710], cb_create : INVITE
2021.04.20 19:27:43.669 5: SIP_CLIENT, readingB:caller Val:sip:+49160XXXXXXX@ims.vodafone.de
2021.04.20 19:27:43.670 5: SIP_CLIENT, readingB:caller_nr Val:+49160XXXXXXX
2021.04.20 19:27:43.670 5: SIP_CLIENT, readingB:caller_name Val:unknown
2021.04.20 19:27:43.670 5: SIP_CLIENT, readingB:caller_time Val:0
2021.04.20 19:27:43.671 5: SIP_CLIENT, readingB:caller_state Val:calling
2021.04.20 19:27:43.674 5: SIP_CLIENT[10710], cb_invite_dtmf
2021.04.20 19:27:43.687 5: SIP_CLIENT, readingS:caller_state Val:ringing
2021.04.20 19:27:46.804 5: SIP_CLIENT[10710], cb_est_dtmf
2021.04.20 19:27:46.805 5: SIP_CLIENT, readingS:caller_state Val:established
2021.04.20 19:27:47.172 5: SIP_CLIENT[10710], SIP_filter : <sip:+49160XXXXXXX@ims.vodafone.de;user=phone>;tag=h7g4Esbg_p65554t1618939663m593389c126153s1_3280994596-545925051
2021.04.20 19:27:47.172 4: SIP_CLIENT[10710], SIP_filter: caller sip:+49160XXXXXXX@ims.vodafone.de, caller_nr +49160XXXXXXX, caller_name
2021.04.20 19:27:47.173 4: SIP_CLIENT[10710], cb_create : INVITE
2021.04.20 19:27:47.174 5: SIP_CLIENT, readingB:caller Val:sip:+49160XXXXXXX@ims.vodafone.de
2021.04.20 19:27:47.174 5: SIP_CLIENT, readingB:caller_nr Val:+49160XXXXXXX
2021.04.20 19:27:47.175 5: SIP_CLIENT, readingB:caller_name Val:unknown
2021.04.20 19:27:47.175 5: SIP_CLIENT, readingB:caller_time Val:0
2021.04.20 19:27:47.175 5: SIP_CLIENT, readingB:caller_state Val:calling
2021.04.20 19:27:47.178 5: SIP_CLIENT[10710], cb_invite_dtmf
2021.04.20 19:27:47.187 5: SIP_CLIENT, readingS:caller_state Val:ringing
2021.04.20 19:28:21.427 5: SIP_CLIENT, listen process 10710 found
2021.04.20 19:29:21.528 5: SIP_CLIENT, listen process 10710 found
2021.04.20 19:30:21.616 5: SIP_CLIENT, listen process 10710 found
2021.04.20 19:30:51.273 4: SIP_CLIENT[10710], register new expire : 2021-04-20 19:41:51
2021.04.20 19:30:51.432 5: SIP_CLIENT, readingB:state Val:listen_dtmf
2021.04.20 19:30:51.433 5: SIP_CLIENT, readingB:listen_alive Val:10710
2021.04.20 19:30:51.433 5: SIP_CLIENT, readingB:expire Val:660
2021.04.20 19:31:21.683 5: SIP_CLIENT, listen process 10710 found
2021.04.20 19:32:21.734 5: SIP_CLIENT, listen process 10710 found
2021.04.20 19:33:21.823 5: SIP_CLIENT, listen process 10710 found
2021.04.20 19:34:21.904 5: SIP_CLIENT, listen process 10710 found
2021.04.20 19:35:21.989 5: SIP_CLIENT, listen process 10710 found
2021.04.20 19:36:21.564 4: SIP_CLIENT[10710], register new expire : 2021-04-20 19:47:21
2021.04.20 19:36:21.567 5: SIP_CLIENT, readingB:state Val:listen_dtmf
2021.04.20 19:36:21.569 5: SIP_CLIENT, readingB:listen_alive Val:10710
2021.04.20 19:36:21.569 5: SIP_CLIENT, readingB:expire Val:660
2021.04.20 19:36:22.096 5: SIP_CLIENT, listen process 10710 found
2021.04.20 19:37:22.198 5: SIP_CLIENT, listen process 10710 found
2021.04.20 19:38:22.253 5: SIP_CLIENT, listen process 10710 found
2021.04.20 19:39:22.304 5: SIP_CLIENT, listen process 10710 found
2021.04.20 19:40:22.361 5: SIP_CLIENT, listen process 10710 found


Der Raspi werkelt im Übrigen mit statischer IP hinter einem Unifi USG 3 als PPPoE-Client (SIP ALG deaktiviert), hinter einem Draytek Vigor 165 Modem.
Ich habe soeben auch noch einen zweiten Festnetzanschluss getestet, der die selbe (Nicht-) Reaktion zeigt.

[Wzut]

hmm schon komisch :

Code Auswählen Erweitern

2021.04.20 19:27:47.178 5: SIP_CLIENT[10710], cb_invite_dtmf
2021.04.20 19:30:51.273 4: SIP_CLIENT[10710], register new expire : 2021-04-20 19:41:51

nach dem invite kommt lange nichts mehr, muss ichmal suchen wo der sich so stumm rumtreiben könnte,
denn eigentlich sollte das Ende des Calls auch im Log stehen

[hansdepp]

Ich hab ein Problem, das mich jetzt schon länger beschäftigt. Trotz intensiver Suche bin ich noch nicht dahinter gekommen, was das Problem ist.
Es passiert sporadisch, dass bei einem Anruf, den das Modul tätigt, der Status in einem "timeout" endet, obwohl der Anruf korrekt angenommen wurde. Das hat zur Folge, dass der Anruf nach der eingestellten Zeit wiederholt wird.
Und nicht entgegengenomme Anrufe enden korrekterweiße mit dem Status "no answer"
Langsam bin ich am verzweifeln, weil ich schon zig Varianten probiert habe. Wäre cool, wenn mal jemand drüberschauen könnte 

So sieht der Aufruf aus:

Code Auswählen Erweitern


set SIP_Device call 09811234567 120 !Nachricht *-2 &600


Und so meine Konfig:

Code Auswählen Erweitern


define SIP_Device SIP
setuuid SIP_Device 5dfa2ab1-f33f-fbfd-86ce-1a4856d22c14b30f
attr SIP_Device T2S_Device myT2S
attr SIP_Device T2S_Timeout 60
attr SIP_Device audio_converter sox
attr SIP_Device history_file ./log/sip_device.log
attr SIP_Device history_size 50
attr SIP_Device sip_call_audio_delay 2
attr SIP_Device sip_dtmf_loop once
attr SIP_Device sip_dtmf_send audio
attr SIP_Device sip_dtmf_size 2
attr SIP_Device sip_elbc yes
attr SIP_Device sip_force_interval 600
attr SIP_Device sip_from sip:fhem-sip-device@192.168.2.1
attr SIP_Device sip_ip 192.168.2.34
attr SIP_Device sip_listen none
attr SIP_Device sip_registrar 192.168.2.1
attr SIP_Device sip_ringtime 3
attr SIP_Device sip_user fhem-sip-device


sip_device.log:

Code Auswählen Erweitern


2021-05-04 02:33:50|out|unknown|09811234567|timeout|0|  -> wieso passiert das? Der Anruf wurde korrekt entgegen genommen!
2021-05-04 02:45:50|out|unknown|09811234567|timeout|0|  -> wieso passiert das? Der Anruf wurde korrekt entgegen genommen!
2021-05-04 02:57:50|out|unknown|09811234567|ok|19|        -> Passt! Aber erst beim 3. Anlauf geht der Status auf OK
2021-05-04 08:59:28|out|unknown|09811234567|ok|14|        -> Passt!
2021-05-04 12:15:13|out|unknown|09811234567|ok|11|        -> Passt!
2021-05-04 21:18:28|out|unknown|09811234567|no answer|0|        -> Passt!
2021-05-04 21:25:28|out|unknown|09811234567|ok|12|        -> Passt!
2021-05-04 21:27:41|out|unknown|09811234567|ok|13|        -> Passt!


Und hier der FHEM-Log

Code Auswählen Erweitern


2021.05.04 02:33:50 3: SIP_Device, force call &600
2021.05.04 02:33:50 4: SIP_Device, msg will be repeat -2 times
2021.05.04 02:33:50 5: SIP_Device, MD5: Melkroboter Alarm - Mehrere unvollständige Gemelke hintereinander -> 77c6f70923e18bc98ff4c5172bbef660.mp3
2021.05.04 02:33:50 5: SIP_Device, mp3 File file not found in cache
2021.05.04 02:33:50 4: SIP_Device, wait_for_t2s file : cache/a709e0302dab642872e7f54bfe05b8dd.mp3
2021.05.04 02:33:50 4: SIP_Device, new T2S file cache/a709e0302dab642872e7f54bfe05b8dd.mp3
2021.05.04 02:33:50 5: SIP_Device, not converted - using cache/a709e0302dab642872e7f54bfe05b8dd.alaw from cache
2021.05.04 02:33:50 3: SIP_Device, force call &600,99,0
2021.05.04 02:33:50 4: SIP_Device, msg will be repeat -2 times
2021.05.04 02:33:50 4: SIP_Device, audio file cache/a709e0302dab642872e7f54bfe05b8dd.alaw found
2021.05.04 02:33:50 4: SIP_Device, SIP_Device|09811234567|120|cache/a709e0302dab642872e7f54bfe05b8dd.alaw|-2
2021.05.04 02:33:50 4: SIP_Device, call -> SIP_Device|09811234567|120|cache/a709e0302dab642872e7f54bfe05b8dd.alaw|-2|&600,99,0
2021.05.04 02:33:50 5: SIP_Device, call has pid 15858
2021.05.04 02:33:50 4: SIP_Device[15858], my parent is 842
2021.05.04 02:33:50 4: SIP_Device[15858], using Leg.pm to find a free port
2021.05.04 02:33:50 4: SIP_Device[15858], register new expire : 2021-05-04 02:38:50
2021.05.04 02:33:50 5: SIP_Device, readingS:state Val:calling
2021.05.04 02:33:50 4: SIP_Device[15858], CallStart with 4 files - first file : CODE(0x559e696b4ae0) - PCMA/8000 , repeat 2
2021.05.04 02:33:50 4: SIP_Device[15858], calling : 09811234567
2021.05.04 02:33:50 5: SIP_Device, readingS:call_state Val:calling 09811234567
2021.05.04 02:35:50 5: SIP_Device[15858], 0. Ende des ersten Loops
2021.05.04 02:35:50 5: SIP_Device[15858], 1. rtp_done : 0
2021.05.04 02:35:50 5: SIP_Device[15858], 2. fi : 0
2021.05.04 02:35:50 5: SIP_Device[15858], 4. timeout : 1
2021.05.04 02:35:50 5: SIP_Device[15858], 6. call_established : 0
2021.05.04 02:35:50 5: SIP_Device[15858], call->cancel
2021.05.04 02:35:50 5: SIP_Device[15858], RTP done : 0
2021.05.04 02:35:50 5: SIP_Device[15858], Timeout  : 1
2021.05.04 02:35:50 5: SIP_Device[15858], while    : -1
2021.05.04 02:35:50 4: SIP_Device[15858], Calltime : 0
2021.05.04 02:35:50 4: SIP_Device, CALLDone -> SIP_Device|1|timeout|0
2021.05.04 02:35:50 4: SIP_Device, read 50 lines from history file ./log/sip_device.log
2021.05.04 02:35:50 4: SIP_Device, at_forcecall_09811234567_3300 at +00:10:00 set SIP_Device call 09811234567 120 cache/a709e0302dab642872e7f54bfe05b8dd.alaw *-2 &600,99,1
2021.05.04 02:35:50 5: SIP_Device, fifo is empty
2021.05.04 02:35:50 5: SIP_Device, no elbc
2021.05.04 02:45:50 3: SIP_Device, force call &600,99,1
2021.05.04 02:45:50 4: SIP_Device, msg will be repeat -2 times
2021.05.04 02:45:50 4: SIP_Device, audio file cache/a709e0302dab642872e7f54bfe05b8dd.alaw found
2021.05.04 02:45:50 4: SIP_Device, SIP_Device|09811234567|120|cache/a709e0302dab642872e7f54bfe05b8dd.alaw|-2
2021.05.04 02:45:50 4: SIP_Device, call -> SIP_Device|09811234567|120|cache/a709e0302dab642872e7f54bfe05b8dd.alaw|-2|&600,99,1
2021.05.04 02:45:50 5: SIP_Device, call has pid 15859
2021.05.04 02:45:50 4: SIP_Device[15859], my parent is 842
2021.05.04 02:45:50 4: SIP_Device[15859], using Leg.pm to find a free port
2021.05.04 02:45:50 4: SIP_Device[15859], register new expire : 2021-05-04 02:50:50
2021.05.04 02:45:50 5: SIP_Device, readingS:state Val:calling
2021.05.04 02:45:50 4: SIP_Device[15859], CallStart with 4 files - first file : CODE(0x559e69862698) - PCMA/8000 , repeat 2
2021.05.04 02:45:50 4: SIP_Device[15859], calling : 09811234567
2021.05.04 02:45:50 5: SIP_Device, readingS:call_state Val:calling 09811234567
2021.05.04 02:47:50 5: SIP_Device[15859], 0. Ende des ersten Loops
2021.05.04 02:47:50 5: SIP_Device[15859], 1. rtp_done : 0
2021.05.04 02:47:50 5: SIP_Device[15859], 2. fi : 0
2021.05.04 02:47:50 5: SIP_Device[15859], 4. timeout : 1
2021.05.04 02:47:50 5: SIP_Device[15859], 6. call_established : 0
2021.05.04 02:47:50 5: SIP_Device[15859], call->cancel
2021.05.04 02:47:50 5: SIP_Device[15859], RTP done : 0
2021.05.04 02:47:50 5: SIP_Device[15859], Timeout  : 1
2021.05.04 02:47:50 5: SIP_Device[15859], while    : -1
2021.05.04 02:47:50 4: SIP_Device[15859], Calltime : 0
2021.05.04 02:47:50 4: SIP_Device, CALLDone -> SIP_Device|1|timeout|0
2021.05.04 02:47:50 4: SIP_Device, read 50 lines from history file ./log/sip_device.log
2021.05.04 02:47:50 4: SIP_Device, at_forcecall_09811234567_3300 at +00:10:00 set SIP_Device call 09811234567 120 cache/a709e0302dab642872e7f54bfe05b8dd.alaw *-2 &600,99,2
2021.05.04 02:47:50 5: SIP_Device, fifo is empty
2021.05.04 02:47:50 5: SIP_Device, no elbc
2021.05.04 02:57:50 3: SIP_Device, force call &600,99,2
2021.05.04 02:57:50 4: SIP_Device, msg will be repeat -2 times
2021.05.04 02:57:50 4: SIP_Device, audio file cache/a709e0302dab642872e7f54bfe05b8dd.alaw found
2021.05.04 02:57:50 4: SIP_Device, SIP_Device|09811234567|120|cache/a709e0302dab642872e7f54bfe05b8dd.alaw|-2
2021.05.04 02:57:50 4: SIP_Device, call -> SIP_Device|09811234567|120|cache/a709e0302dab642872e7f54bfe05b8dd.alaw|-2|&600,99,2
2021.05.04 02:57:50 5: SIP_Device, call has pid 15860
2021.05.04 02:57:50 4: SIP_Device[15860], my parent is 842
2021.05.04 02:57:50 4: SIP_Device[15860], using Leg.pm to find a free port
2021.05.04 02:57:50 4: SIP_Device[15860], register new expire : 2021-05-04 03:02:50
2021.05.04 02:57:50 5: SIP_Device, readingS:state Val:calling
2021.05.04 02:57:50 4: SIP_Device[15860], CallStart with 4 files - first file : CODE(0x559e69702a18) - PCMA/8000 , repeat 2
2021.05.04 02:57:50 4: SIP_Device[15860], calling : 09811234567
2021.05.04 02:57:50 5: SIP_Device, readingS:call_state Val:calling 09811234567
2021.05.04 02:58:12 4: SIP_Device[15860], cb_final - status : OK
2021.05.04 02:58:12 4: SIP_Device[15860], call established
2021.05.04 02:58:12 5: SIP_Device, readingS:call_state Val:established
2021.05.04 02:58:14 5: SIP_Device[15860], 0. Ende des ersten Loops
2021.05.04 02:58:14 5: SIP_Device[15860], 1. rtp_done : Net::SIP::Simple::Call=HASH(0x559e6973de78)
2021.05.04 02:58:14 5: SIP_Device[15860], 2. fi : 0
2021.05.04 02:58:14 5: SIP_Device[15860], 4. timeout : 0
2021.05.04 02:58:14 5: SIP_Device[15860], 6. call_established : 1
2021.05.04 02:58:14 4: SIP_Device[15860], next file : cache/a709e0302dab642872e7f54bfe05b8dd.alaw
2021.05.04 02:58:15 4: SIP_Device[15860], cb_final - status : OK
2021.05.04 02:58:20 4: SIP_Device[15860], loop rtp_done : Net::SIP::Simple::Call=HASH(0x559e6973de78)
2021.05.04 02:58:20 4: SIP_Device[15860], next file : cache/a709e0302dab642872e7f54bfe05b8dd.alaw
2021.05.04 02:58:20 4: SIP_Device[15860], cb_final - status : OK
2021.05.04 02:58:25 4: SIP_Device[15860], loop rtp_done : Net::SIP::Simple::Call=HASH(0x559e6973de78)
2021.05.04 02:58:25 4: SIP_Device[15860], next file : cache/a709e0302dab642872e7f54bfe05b8dd.alaw
2021.05.04 02:58:25 4: SIP_Device[15860], cb_final - status : OK
2021.05.04 02:58:31 4: SIP_Device[15860], loop rtp_done : Net::SIP::Simple::Call=HASH(0x559e6973de78)
2021.05.04 02:58:31 5: SIP_Device[15860], call->bye
2021.05.04 02:58:31 5: SIP_Device[15860], RTP done : Net::SIP::Simple::Call=HASH(0x559e6973de78)
2021.05.04 02:58:31 5: SIP_Device[15860], Timeout  : 0
2021.05.04 02:58:31 5: SIP_Device[15860], while    : 2
2021.05.04 02:58:31 5: SIP_Device[15860], Status   : OK
2021.05.04 02:58:31 4: SIP_Device[15860], Calltime : 19
2021.05.04 02:58:31 4: SIP_Device, CALLDone -> SIP_Device|1|ok|19
2021.05.04 02:58:31 4: SIP_Device, read 50 lines from history file ./log/sip_device.log
2021.05.04 02:58:31 5: SIP_Device, fifo is empty
2021.05.04 02:58:31 5: SIP_Device, no elbc


[Wzut]

a. so muß eine Fehlerbeschreibung aussehen ! Alle notwendigen Infos gleich vorhanden ohne erst nachfragen zu müssen!
b. aber :

Es passiert sporadisch

ist etwas was man als Modulautor gar nicht lesen möchte ....

Ok, beim lesen des Logs fällt auf :

Code Auswählen Erweitern


2021.05.04 02:33:50 4: SIP_Device[15858], calling : 09811234567
2021.05.04 02:35:50 5: SIP_Device[15858], 0. Ende des ersten Loops
<--snipp-->
2021.05.04 02:45:50 4: SIP_Device[15859], calling : 09811234567
2021.05.04 02:47:50 5: SIP_Device[15859], 0. Ende des ersten Loops
<--snipp-->
2021.05.04 02:57:50 4: SIP_Device[15860], calling : 09811234567
2021.05.04 02:58:12 4: SIP_Device[15860], cb_final - status : OK
Bei den ersten beiden Versuchen wird bereits nach 2 Sekunden im Modul weitergearbeitet obwohl das eigentlich nicht sein kann.
D.h. auch hier haben wir eine ähnliche Situation wir beim Problem von trabantp60, das Logging kann leider nicht in die Tiefen von Net::SIP abtauchen.

@hansdepp, da du dir die Nachricht eh mehrfach vorsagen lässt : lösch doch bitte mal das Attribut attr SIP_Device sip_call_audio_delay 2
Kann purer Zufall sein das die 2 Sekunden so schön mit dem Fehlerbild zusammen passen.
Aber ich muß doch nochmal nachfassen :
Obwohl schon nach 2 Sekunden das Modul seine Arbeit einstellt, wird quasi im Hintergrund der Anruf weiter fortgesetzt und komplett inklusive Wiederholung durchgeführt ?   

[hansdepp]

Obwohl schon nach 2 Sekunden das Modul seine Arbeit einstellt, wird quasi im Hintergrund der Anruf weiter fortgesetzt und komplett inklusive Wiederholung durchgeführt ?

Ich meine eher, dass es 2 Minuten sind, die verstreichen. Während dieser Zeit wird das Telefonat angenommen und die Nachricht komplett abgehört. Irgendwie registriert das Modul dies aber nicht!
Die 2 Minuten würden eher mit den 120 Sek im Befehlsaufruf korrespondieren, die die maximale Nachrichtenlänge angeben soll, wenn ich es richtig verstanden habe. Das reicht für meine Nachrichtenlängen locker aus. Trotzdem habe ich diese Zeit jetzt auch mal auf 300 Sek erhöht. Allerdings habe ich jetzt noch kein Ergebnis dieses Tests.

@hansdepp, da du dir die Nachricht eh mehrfach vorsagen lässt : lösch doch bitte mal das Attribut attr SIP_Device sip_call_audio_delay 2

Ich habe schon sämtliche Attribute variiert oder auch weggelassen.

[Wzut]

Ja hast natürlich Recht mit deinen 2 Minuten, war ich wohl gestsern doch noch nicht richtig wach.
Bei den Anrufen : Bist du wirklich ganz sicher das du auf jeden Fall das Modul "auflegen" lässt nachdem es alle Wiederholungen durch hat ?
Oder kann es auch auch passieren das du auflegst ?

Laut deinem Log und Aussage geht es immer zweimal schief und beim dritten Mal klappt es. Da ein Versuch selbst keine Ahnung hat ob er der erste  zweite oder letzte ist :
Gibt es auch Varianten wo nur einmal wiederholt wird oder alle drei Versuche nicht erfolgreich sind ?

[hansdepp]

Sorry, meine Informationen waren auch nicht alle richtig.

Bei den Anrufen : Bist du wirklich ganz sicher das du auf jeden Fall das Modul "auflegen" lässt nachdem es alle Wiederholungen durch hat ?

Nein. Ich hab nochmal nachgefragt, wie es wirklich war. Und zwar ist überhaupt keine Ansage zu hören. D.h. das Telefonat wird zwar hergestellt (sieht man im FB_Callmonitor oder in der Fritzbox), aber dann nur Stille. Nach ca. 20 Sekunden hatte die Person dann wieder aufgelegt. Und nach 2 Minuten lief das Modul dann in einem Timeout. Zu diesem Zeitpunkt war das Telefonat aber schon beendet.
Bei meinen provozierten Tests hat es immer ohne Probleme funktioniert, deshalb musste ich mich auf die Informationen von jemand anderes verlassen... Sorry nochmal, das war in meiner ursprünglichen Nachricht nicht ganz richtig dargestellt.

Gibt es auch Varianten wo nur einmal wiederholt wird oder alle drei Versuche nicht erfolgreich sind ?

Meistens klappt es beim 1. Versuch. Bei ca. 20% ist ein 2. Versuch notwenig. Und 3 Versuche kommen ganz ganz selten vor.

[Wzut]

Ok, das macht das Ganze in Bezug zum Logfile wenigstens logischer.
D.h. das Modul bzw Net::SIP bekommt nicht mit das abgenommen wurde und startet daher erst gar nicht die nachfolgende Kette sondern wartet brav bis zum 120 Sekunden Timeout.
Das ist jetzt so ein Fall wo man mit Wireshark auf die Netzwerebene runter müsste um zu sehen warum die Info Gegenstelle hat abgenommen nicht durchkommt.

[plin]

09811234567 heißt Du rufst auf einem Endgerät im Festnetz an? Was hängt denn da am anderen Ende? Analog, ISDN, SIP, Telefonanlage???

[hansdepp]

FHEM bzw. das SIP-Modul ruft auf einem analogen Telefon an, das über eine Eumex504-Telefonanlage über den Fon-S0-Anschluss (ISDN) an die Fritzbox angeschlossen ist. Es ist übrigens dieselbe Fritzbox mit der sich auch FHEM verbindet.
Da es sporadisch auftritt (zumindest ist derzeit kein Zusammenhang erkennbar), macht es natürlich nochmals schwieriger.
Aber vielleicht hängt es damit zusammen, dass alles auf dem gleichen Anschluss passiert. Die Anrufe, bei denen ich zum Testen an einem anderen Telekom-Anschluss angerufen habe, haben nämlich keine Probleme gemacht. Kann aber auch Zufall sein, da ich es evtl. noch nicht oft genug versucht habe.

[plin]

Das ist jetzt so ein Fall wo man mit Wireshark auf die Netzwerebene runter müsste um zu sehen warum die Info Gegenstelle hat abgenommen nicht durchkommt.

@wzut: Eine Alternative wäre

Code Auswählen Erweitern

use Net::SIP::Debug '50';
use Net::SIP::Debug qw( Net::SIP*=50 Registrar=1 );

Wenn wir denn das was im Log steht verstehen 

[plin]

FHEM bzw. das SIP-Modul ruft auf einem analogen Telefon an, das über eine Eumex504-Telefonanlage über den Fon-S0-Anschluss (ISDN) an die Fritzbox angeschlossen ist. Es ist übrigens dieselbe Fritzbox mit der sich auch FHEM verbindet.

Wieso musst Du dann eine externe Rufnummer verwenden?

[trabantp60]

Ich hatte heute aus Verzweiflung alle (mir bekannten - sind nicht viele) Mögichkeiten ausprobiert, das Net::SIP Modul neu zu installieren.

Die Installation lief auch fast durch - halt nur fast:

Code Auswählen Erweitern

pi@FHEMPI4:~ $ sudo perl -MCPAN -e shell
Terminal does not support AddHistory.

cpan shell -- CPAN exploration and modules installation (v2.20)
Enter 'h' for help.

cpan[1]> install Net::SIP
Reading '/root/.cpan/Metadata'
  Database was generated on Thu, 06 May 2021 18:29:03 GMT
Running install for module 'Net::SIP'
Checksum for /root/.cpan/sources/authors/id/S/SU/SULLR/Net-SIP-0.829.tar.gz ok
Scanning cache /root/.cpan/build for sizes
............................................................................DONE
Configuring S/SU/SULLR/Net-SIP-0.829.tar.gz with Makefile.PL
Checking if your kit is complete...
Looks good
Generating a Unix-style Makefile
Writing Makefile for Net::SIP
Writing MYMETA.yml and MYMETA.json
  SULLR/Net-SIP-0.829.tar.gz
  /usr/bin/perl Makefile.PL INSTALLDIRS=site -- OK
Running make for S/SU/SULLR/Net-SIP-0.829.tar.gz
cp lib/Net/SIP/Request.pod blib/lib/Net/SIP/Request.pod
cp lib/Net/SIP/NATHelper/Server.pm blib/lib/Net/SIP/NATHelper/Server.pm
cp lib/Net/SIP/NATHelper/Base.pm blib/lib/Net/SIP/NATHelper/Base.pm
cp lib/Net/SIP/Debug.pod blib/lib/Net/SIP/Debug.pod
cp lib/Net/SIP/Packet.pod blib/lib/Net/SIP/Packet.pod
cp lib/Net/SIP/ReceiveChain.pod blib/lib/Net/SIP/ReceiveChain.pod
cp lib/Net/SIP/Authorize.pod blib/lib/Net/SIP/Authorize.pod
cp lib/Net/SIP/Dropper/ByIPPort.pm blib/lib/Net/SIP/Dropper/ByIPPort.pm
cp lib/Net/SIP/Redirect.pod blib/lib/Net/SIP/Redirect.pod
cp lib/Net/SIP/Registrar.pm blib/lib/Net/SIP/Registrar.pm
cp lib/Net/SIP/Packet.pm blib/lib/Net/SIP/Packet.pm
cp lib/Net/SIP.pod blib/lib/Net/SIP.pod
cp lib/Net/SIP/Request.pm blib/lib/Net/SIP/Request.pm
cp lib/Net/SIP/Debug.pm blib/lib/Net/SIP/Debug.pm
cp lib/Net/SIP/Dropper/ByField.pm blib/lib/Net/SIP/Dropper/ByField.pm
cp lib/Net/SIP/NATHelper/Base.pod blib/lib/Net/SIP/NATHelper/Base.pod
cp lib/Net/SIP/DTMF.pm blib/lib/Net/SIP/DTMF.pm
cp lib/Net/SIP.pm blib/lib/Net/SIP.pm
cp lib/Net/SIP/Endpoint.pod blib/lib/Net/SIP/Endpoint.pod
cp lib/Net/SIP/Endpoint/Context.pm blib/lib/Net/SIP/Endpoint/Context.pm
cp lib/Net/SIP/ReceiveChain.pm blib/lib/Net/SIP/ReceiveChain.pm
cp lib/Net/SIP/NATHelper/Server.pod blib/lib/Net/SIP/NATHelper/Server.pod
cp lib/Net/SIP/Dispatcher.pm blib/lib/Net/SIP/Dispatcher.pm
cp lib/Net/SIP/Dropper.pm blib/lib/Net/SIP/Dropper.pm
cp lib/Net/SIP/Blocker.pod blib/lib/Net/SIP/Blocker.pod
cp lib/Net/SIP/NATHelper/Client.pod blib/lib/Net/SIP/NATHelper/Client.pod
cp lib/Net/SIP/NATHelper/Local.pod blib/lib/Net/SIP/NATHelper/Local.pod
cp lib/Net/SIP/Dispatcher.pod blib/lib/Net/SIP/Dispatcher.pod
cp lib/Net/SIP/Leg.pm blib/lib/Net/SIP/Leg.pm
cp lib/Net/SIP/NATHelper/Client.pm blib/lib/Net/SIP/NATHelper/Client.pm
cp lib/Net/SIP/Dispatcher/Eventloop.pod blib/lib/Net/SIP/Dispatcher/Eventloop.pod
cp lib/Net/SIP/Endpoint.pm blib/lib/Net/SIP/Endpoint.pm
cp lib/Net/SIP/Dispatcher/Eventloop.pm blib/lib/Net/SIP/Dispatcher/Eventloop.pm
cp lib/Net/SIP/Registrar.pod blib/lib/Net/SIP/Registrar.pod
cp lib/Net/SIP/Leg.pod blib/lib/Net/SIP/Leg.pod
cp lib/Net/SIP/DTMF.pod blib/lib/Net/SIP/DTMF.pod
cp lib/Net/SIP/Authorize.pm blib/lib/Net/SIP/Authorize.pm
cp lib/Net/SIP/Blocker.pm blib/lib/Net/SIP/Blocker.pm
cp lib/Net/SIP/NATHelper/Local.pm blib/lib/Net/SIP/NATHelper/Local.pm
cp lib/Net/SIP/Redirect.pm blib/lib/Net/SIP/Redirect.pm
cp lib/Net/SIP/Endpoint/Context.pod blib/lib/Net/SIP/Endpoint/Context.pod
cp lib/Net/SIP/Response.pm blib/lib/Net/SIP/Response.pm
cp lib/Net/SIP/Simple/Call.pm blib/lib/Net/SIP/Simple/Call.pm
cp lib/Net/SIP/Util.pod blib/lib/Net/SIP/Util.pod
cp lib/Net/SIP/Response.pod blib/lib/Net/SIP/Response.pod
cp lib/Net/SIP/SDP.pod blib/lib/Net/SIP/SDP.pod
cp lib/Net/SIP/Simple.pm blib/lib/Net/SIP/Simple.pm
cp lib/Net/SIP/Simple/RTP.pm blib/lib/Net/SIP/Simple/RTP.pm
cp lib/Net/SIP/SDP.pm blib/lib/Net/SIP/SDP.pm
cp lib/Net/SIP/StatelessProxy.pm blib/lib/Net/SIP/StatelessProxy.pm
cp lib/Net/SIP/Simple.pod blib/lib/Net/SIP/Simple.pod
cp lib/Net/SIP/SocketPool.pm blib/lib/Net/SIP/SocketPool.pm
cp lib/Net/SIP/Simple/Call.pod blib/lib/Net/SIP/Simple/Call.pod
cp lib/Net/SIP/Util.pm blib/lib/Net/SIP/Util.pm
cp lib/Net/SIP/SocketPool.pod blib/lib/Net/SIP/SocketPool.pod
cp lib/Net/SIP/StatelessProxy.pod blib/lib/Net/SIP/StatelessProxy.pod
cp lib/Net/SIP/Simple/RTP.pod blib/lib/Net/SIP/Simple/RTP.pod
Manifying 30 pod documents
  SULLR/Net-SIP-0.829.tar.gz
  /usr/bin/make -- OK
Running make test
PERL_DL_NONLAZY=1 "/usr/bin/perl" "-MExtUtils::Command::MM" "-MTest::Harness" "-e" "undef *Test::Harness::Switches; test_harness(0, 'blib/lib', 'blib/arch')" t/*.t
t/01_load.t ............................. ok   
t/02_listen_and_invite.t ................ 1/60 # call created
# got ringing
# call established
# call cleaned up
t/02_listen_and_invite.t ................ 9/60 # call created
# got ringing
# call established
# call cleaned up
t/02_listen_and_invite.t ................ 19/60 # call created
# got ringing
# call established
# call cleaned up
t/02_listen_and_invite.t ................ 29/60 # call created
# got ringing
# call established
# call cleaned up
t/02_listen_and_invite.t ................ 41/60 # call created
# got ringing
# call established
# call cleaned up
t/02_listen_and_invite.t ................ 49/60 # call created
# got ringing
# call established
# call cleaned up
t/02_listen_and_invite.t ................ ok     
t/03_forward_stateless.t ................ ok   
t/04_call_with_rtp.t .................... ok     
t/05_call_with_stateless_proxy.t ........ ok       
t/06_call_with_reinvite.t ............... ok       
t/07_call_on_hold.t ..................... ok     
t/08_register_with_auth.t ............... ok     
t/11_invite_timeout.t ................... ok     
t/12_maddr.t ............................ 1/48 # call established
# call cleaned up
t/12_maddr.t ............................ 7/48 # call established
# call cleaned up
t/12_maddr.t ............................ 15/48 # call established
# call cleaned up
t/12_maddr.t ............................ 23/48 # call established
# call cleaned up
t/12_maddr.t ............................ 31/48 # call established
# call cleaned up
t/12_maddr.t ............................ 39/48 # call established
# call cleaned up
t/12_maddr.t ............................ ok     
t/13_maddr_proxy.t ...................... ok   
t/14_bugfix_0.51.t ...................... # UAS   on 127.0.0.1:5062
# UAC   on 127.0.0.1:5060
# PROXY on 127.0.0.1:5063
t/14_bugfix_0.51.t ...................... ok     
t/15_block_invite.t ..................... ok   
t/16_drop_invite.t ...................... ok   
t/17_call_with_reinvite_and_auth.t ...... ok     
t/18_register_with_auth_step_by_step.t .. ok     
t/19_call_with_dtmf.t ................... # UAS on 127.0.0.1:59397
# UAC on 127.0.0.1:48097
t/19_call_with_dtmf.t ................... 1/108 # call created
# call established
t/19_call_with_dtmf.t ................... 5/108 # call cleaned up
# received=468 lost=0 expect ca. 467.5 packets, events='1 2 D # 3 4 B *'
# UAS on 127.0.0.1:35950
# UAC on 127.0.0.1:39145
# call created
# call established
t/19_call_with_dtmf.t ................... 14/108 # call cleaned up
# received=466 lost=0 expect ca. 467.5 packets, events='1 2 D # 3 4 B *'
# UAS on [::1]:38506
# UAC on [::1]:38164
# call created
# call established
t/19_call_with_dtmf.t ................... 23/108 # call cleaned up
# received=466 lost=0 expect ca. 467.5 packets, events='1 2 D # 3 4 B *'
# UAS on [::1]:40189
# UAC on [::1]:39656
# call created
# call established
t/19_call_with_dtmf.t ................... 32/108 # call cleaned up
# received=464 lost=0 expect ca. 467.5 packets, events='1 2 D # 3 4 B *'
# UAS on 127.0.0.1:36151
# UAC on 127.0.0.1:57203
# call created
# call established
t/19_call_with_dtmf.t ................... 41/108 # call cleaned up
# received=466 lost=0 expect ca. 467.5 packets, events='1 2 D # 3 4 B *'
# UAS on 127.0.0.1:50309
# UAC on 127.0.0.1:58517
# call created
# call established
t/19_call_with_dtmf.t ................... 50/108 # call cleaned up
# received=464 lost=0 expect ca. 467.5 packets, events='1 2 D # 3 4 B *'
# UAS on [::1]:43475
# UAC on [::1]:57193
# call created
# call established
t/19_call_with_dtmf.t ................... 59/108 # call cleaned up
# received=465 lost=0 expect ca. 467.5 packets, events='1 2 D # 3 4 B *'
# UAS on [::1]:36591
# UAC on [::1]:42437
# call created
# call established
t/19_call_with_dtmf.t ................... 68/108 # call cleaned up
# received=466 lost=0 expect ca. 467.5 packets, events='1 2 D # 3 4 B *'
# UAS on 127.0.0.1:52497
# UAC on 127.0.0.1:46251
# call created
# call established
t/19_call_with_dtmf.t ................... 77/108 # call cleaned up
# received=465 lost=0 expect ca. 467.5 packets, events='1 2 D # 3 4 B *'
# UAS on 127.0.0.1:57713
# UAC on 127.0.0.1:41761
# call created
# call established
t/19_call_with_dtmf.t ................... 86/108 # call cleaned up
# received=466 lost=0 expect ca. 467.5 packets, events='1 2 D # 3 4 B *'
# UAS on [::1]:49721
# UAC on [::1]:48029
# call created
# call established
t/19_call_with_dtmf.t ................... 95/108 # call cleaned up
# received=467 lost=0 expect ca. 467.5 packets, events='1 2 D # 3 4 B *'
# UAS on [::1]:46209
# UAC on [::1]:45605
# call created
# call established
t/19_call_with_dtmf.t ................... 104/108 # call cleaned up
# received=466 lost=0 expect ca. 467.5 packets, events='1 2 D # 3 4 B *'
t/19_call_with_dtmf.t ................... ok       
t/20_channel_on_hold.t .................. ok     
t/21_channel_on_hold_stateless_proxy.t .. ok       
t/22_stateless_proxy_ack_on_error.t ..... ok       
t/23_valid_message.t .................... ok   
t/24_dtmf_audio.t ....................... ok   
t/25_register_tcp_timeout.t ............. 1/4
#   Failed test at t/25_register_tcp_timeout.t line 17.
#          got: '101'
#     expected: '110'
# Looks like you failed 1 test of 4.
t/25_register_tcp_timeout.t ............. Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/4 subtests

Test Summary Report
-------------------
t/25_register_tcp_timeout.t           (Wstat: 256 Tests: 4 Failed: 1)
  Failed test:  3
  Non-zero exit status: 1
Files=23, Tests=1869, 300 wallclock secs ( 1.87 usr  0.25 sys + 77.87 cusr 18.14 csys = 98.13 CPU)
Result: FAIL
Failed 1/23 test programs. 1/1869 subtests failed.
make: *** [Makefile:978: test_dynamic] Fehler 1
  SULLR/Net-SIP-0.829.tar.gz
  /usr/bin/make test -- NOT OK
//hint// to see the cpan-testers results for installing this module, try:
  reports SULLR/Net-SIP-0.829.tar.gz
Failed during this command:
SULLR/Net-SIP-0.829.tar.gz                   : make_test NO



Welche Ports muss die USG Firewall weiterleiten?

[plin]

Ich hatte heute aus Verzweiflung alle (mir bekannten - sind nicht viele) Mögichkeiten ausprobiert, das Net::SIP Modul neu zu installieren.
...

Wie schaut's denn mit der Variante

Code Auswählen Erweitern

sudo su -
cpan install Net::SIP
aus?