Opened 11 years ago

Closed 11 years ago

#3273 closed defect (fixed)

8571-72

Reported by: vvv1980 Owned by: vvv1980
Priority: critical Component: General
Severity: high Keywords: serial
Cc: Sensitive: no

Description

Revision

1.2 rev 8572

Issue Description

After changes in serial communication, serial reader (like DSR9500) doesn't work properly.

When the issue occurs

After rev.8572. 8571 work fine.

How the issue is reproducable

Dont know yet. :(

<Don't forget to ATTACH (NOT post here as text) a log file of oscam in debug mode (start oscam with -d255) and to remove the brackets around the fields! Otherwise, your ticket will be closed as you seem to be unable to read.>

Here is from debug 65535 (-d65535):
2013/04/06 22:44:29 B00008C0 c PCAM [newcamd] TRACE: ecm answer for ecm hash C04BFA5401D5EF3B59E623CDDBA08BBB rc=0
2013/04/06 22:44:29 B00008C0 c Client anonymous csphash 0DE16296 cw B63EFCF06CA90B207491999EE6917CF3 rc 0 0500&050B00/0000/4E86/4B:C04BFA5401D5EF3B59E623CDDBA08BBB
2013/04/06 22:44:29 B00008C0 c send 17 of 17 bytes to client in 18 msec
2013/04/06 22:44:29 B00008C0 04 B6 3E FC F0 6C A9 0B 20 74 91 99 9E E6 91 7C
2013/04/06 22:44:29 B00008C0 F3
2013/04/06 22:44:29 B00008C0 c anonymous (0500&050B00/0000/4E86/4B:C04BFA5401D5EF3B59E623CDDBA08BBB): found (45 ms) by PCAM - HD Кино 2
2013/04/06 22:44:29 B00008C0 c cw:
2013/04/06 22:44:29 B00008C0 B6 3E FC F0 6C A9 0B 20 74 91 99 9E E6 91 7C F3
2013/04/06 22:44:32 1880CC0 p Client PCAM reached 3 seconds timeout but no data received -> Skip, better luck next time!
2013/04/06 22:44:39 0 --- Skipped 2 duplicated log lines ---
2013/04/06 22:44:39 B00008C0 c received 159 bytes from client in 5 msec
2013/04/06 22:44:39 B00008C0 03 30 30 30 35 30 62 30 30 30 35 30 30 38 30 37
2013/04/06 22:44:39 B00008C0 30 34 34 30 30 39 30 30 33 30 35 30 62 30 38 39
2013/04/06 22:44:39 B00008C0 66 30 38 35 32 35 35 35 33 32 61 35 33 34 35 35
2013/04/06 22:44:39 B00008C0 32 35 36 64 65 30 34 35 31 36 30 61 37 63 32 65
2013/04/06 22:44:39 B00008C0 30 30 31 63 30 65 32 30 33 34 32 38 36 64 65 65
2013/04/06 22:44:39 B00008C0 32 30 33 34 32 38 36 30 61 65 32 30 33 34 32 38
2013/04/06 22:44:39 B00008C0 36 63 36 65 61 31 30 39 61 33 32 63 63 63 65 32
2013/04/06 22:44:39 B00008C0 61 61 32 39 30 63 62 39 37 32 36 61 33 62 65 36
2013/04/06 22:44:39 B00008C0 30 64 32 63 37 66 66 66 30 30 38 38 37 63 37 64
2013/04/06 22:44:39 B00008C0 62 30 34 66 66 30 63 32 33 31 36 34 65 38 36
2013/04/06 22:44:39 B00008C0 c plain dsr9500-client granted (anonymous, au=off)
2013/04/06 22:44:39 B00008C0 c before:
2013/04/06 22:44:39 B00008C0 80 70 44 00 90 03 05 0B 08 9F 08 52 55 53 2A 53
2013/04/06 22:44:39 B00008C0 c after:
2013/04/06 22:44:39 B00008C0 80 70 48 00 D2 02 0D 00 40 03 05 0B 08 9F 08 52
2013/04/06 22:44:39 B00008C0 c trying reader 'PCAM' filter 0500:050B00
2013/04/06 22:44:39 B00008C0 c 0500:050B00 allowed by reader 'PCAM' filter 0500:050B00
2013/04/06 22:44:39 B00008C0 c matching_reader became slot attribute of 1
2013/04/06 22:44:39 B00008C0 c [GET_CW] wait_time 0 caid 0500 prov 050B00 srvid 4E86 rc 100 cacheex cl mode 0 ex1rdr 0
2013/04/06 22:44:39 B00008C0 c request_cw stage=3 to reader PCAM ecm hash=A637E4EB9AC01FF866163FCCA2E16ACA
2013/04/06 22:44:39 B00008C0 c add reader job action 5 queue length 1 PCAM
2013/04/06 22:44:39 B00008C0 c Client anonymous ECM dump 0500&050B00/0000/4E86/4B:A637E4EB9AC01FF866163FCCA2E16ACA
2013/04/06 22:44:39 B00008C0 80 70 48 00 D2 02 0D 00 40 03 05 0B 08 9F 08 52
2013/04/06 22:44:39 B00008C0 55 53 2A 53 45 52 56 DE 04 51 60 A7 C2 E0 01 C0
2013/04/06 22:44:39 B00008C0 E2 03 42 86 DE E2 03 42 86 0A E2 03 42 86 C6 EA
2013/04/06 22:44:39 B00008C0 10 9A 32 CC CE 2A A2 90 CB 97 26 A3 BE 60 D2 C7
switch log file
tail: «/var/log/pcam_new.log» был замещен; вывод продолжается для нового файла


OSCam << cardserver log switched at Sat Apr 6 22:44:39 2013


2013/04/06 22:44:39 B00008C0 FF F0 08 87 C7 DB 04 FF 0C 23 16
2013/04/06 22:44:39 1880CC0 p ---- ecm_task 0, idx 3, sflag=1
2013/04/06 22:44:39 1880CC0 p casc ecm (PCAM):
2013/04/06 22:44:39 1880CC0 80 70 48 00 D2 02 0D 00 40 03 05 0B 08 9F 08 52
2013/04/06 22:44:39 1880CC0 55 53 2A 53 45 52 56 DE 04 51 60 A7 C2 E0 01 C0
2013/04/06 22:44:39 1880CC0 E2 03 42 86 DE E2 03 42 86 0A E2 03 42 86 C6 EA
2013/04/06 22:44:39 1880CC0 10 9A 32 CC CE 2A A2 90 CB 97 26 A3 BE 60 D2 C7
2013/04/06 22:44:39 1880CC0 FF F0 08 87 C7 DB 04 FF 0C 23 16
2013/04/06 22:44:39 1880CC0 p trying server '83.243.68.9' filter 0500:040600
2013/04/06 22:44:39 1880CC0 p trying server '83.243.68.9' filter 0500:050B00
2013/04/06 22:44:39 1880CC0 p 0500:050B00 allowed by server '83.243.68.9' filter 0500:050B00
2013/04/06 22:44:39 1880CC0 p send 87 bytes to remote server
2013/04/06 22:44:39 1880CC0 00 55 00 03 4E 86 00 00 00 00 00 00 80 70 48 00
2013/04/06 22:44:39 1880CC0 D2 02 0D 00 40 03 05 0B 08 9F 08 52 55 53 2A 53
2013/04/06 22:44:39 1880CC0 45 52 56 DE 04 51 60 A7 C2 E0 01 C0 E2 03 42 86
2013/04/06 22:44:39 1880CC0 DE E2 03 42 86 0A E2 03 42 86 C6 EA 10 9A 32 CC
2013/04/06 22:44:39 1880CC0 CE 2A A2 90 CB 97 26 A3 BE 60 D2 C7 FF F0 08 87
2013/04/06 22:44:39 1880CC0 C7 DB 04 FF 0C 23 16
2013/04/06 22:44:39 0 >> OSCam << cardserver log switched, version 1.20-unstable_svn, build r8600 (x86_64-pc-linux-gnu)
2013/04/06 22:44:39 B00008C0 c received 2 bytes from client in 5 msec
2013/04/06 22:44:39 B00008C0 0A 0D
2013/04/06 22:44:39 1880CC0 p nmr(): len=2, errno=0
2013/04/06 22:44:39 1880CC0 p nmr: netMsgId=3, from server=3,
2013/04/06 22:44:39 1880CC0 p received 21 bytes from remote server
2013/04/06 22:44:39 1880CC0 00 03 80 10 10 B6 3E FC F0 6C A9 0B 20 C8 2E 5D
2013/04/06 22:44:39 1880CC0 53 C3 8C 90 DF
2013/04/06 22:44:39 1880CC0 p start client thread action 24
2013/04/06 22:44:39 B00008C0 c data from add_job action=24 client c anonymous
2013/04/06 22:44:39 B00008C0 c PCAM [newcamd] TRACE: ecm answer for ecm hash A637E4EB9AC01FF866163FCCA2E16ACA rc=0
2013/04/06 22:44:39 B00008C0 c Client anonymous csphash 8300821C cw B63EFCF06CA90B20C82E5D53C38C90DF rc 0 0500&050B00/0000/4E86/4B:A637E4EB9AC01FF866163FCCA2E16ACA
2013/04/06 22:44:39 B00008C0 c send 17 of 17 bytes to client in 18 msec
2013/04/06 22:44:39 B00008C0 04 B6 3E FC F0 6C A9 0B 20 C8 2E 5D 53 C3 8C 90
2013/04/06 22:44:39 B00008C0 DF
2013/04/06 22:44:39 B00008C0 c anonymous (0500&050B00/0000/4E86/4B:A637E4EB9AC01FF866163FCCA2E16ACA): found (45 ms) by PCAM - HD Кино 2
2013/04/06 22:44:39 B00008C0 c cw:
2013/04/06 22:44:39 B00008C0 B6 3E FC F0 6C A9 0B 20 C8 2E 5D 53 C3 8C 90 DF
2013/04/06 22:44:42 1880CC0 p Client PCAM reached 3 seconds timeout but no data received -> Skip, better luck next time!

It told me, that client doesn't reach by 3 seconds.

Change History (12)

comment:1 by vvv1980, 11 years ago

Summary: 85728571-72

comment:2 by vvv1980, 11 years ago

I am so sorry, but bug has started from 8571. 8570 work fine, 8571 work bad.

comment:3 by vvv1980, 11 years ago

Revert of changes in 8571 fully resolve situation with not decoding. But message about timeout still here.
Here is the log:
2013/04/06 23:13:27 B42CC0 p Client PCAM reached 3 seconds timeout but no data received -> Skip, better luck next time!
2013/04/06 23:13:31 0 --- Skipped 1 duplicated log lines ---
2013/04/06 23:13:31 A00008C0 c detected dsr9500-extended type receiver
2013/04/06 23:13:31 A00008C0 c received 159 bytes from client in 5 msec
2013/04/06 23:13:31 A00008C0 03 30 30 30 35 30 62 30 30 30 35 30 30 38 30 37
2013/04/06 23:13:31 A00008C0 30 34 34 30 30 39 30 30 33 30 35 30 62 30 38 39
2013/04/06 23:13:31 A00008C0 66 30 38 35 32 35 35 35 33 32 61 35 33 34 35 35
2013/04/06 23:13:31 A00008C0 32 35 36 64 65 30 34 35 31 36 30 61 65 38 35 65
2013/04/06 23:13:31 A00008C0 30 30 31 63 30 65 32 30 33 34 32 38 36 64 65 65
switch log file
tail: «/var/log/pcam_new.log» был замещен; вывод продолжается для нового файла


OSCam << cardserver log switched at Sat Apr 6 23:13:31 2013


2013/04/06 23:13:31 A00008C0 32 30 33 34 32 38 36 30 61 65 32 30 33 34 32 38
2013/04/06 23:13:31 A00008C0 36 63 36 65 61 31 30 32 32 63 64 65 64 62 66 35
2013/04/06 23:13:31 A00008C0 62 64 65 62 66 33 39 33 33 33 62 36 34 63 34 64
2013/04/06 23:13:31 A00008C0 63 65 63 63 63 37 31 66 30 30 38 39 37 39 31 63
2013/04/06 23:13:31 A00008C0 62 65 38 37 64 35 39 64 35 32 62 34 65 38 36
2013/04/06 23:13:31 A00008C0 c plain dsr9500-client granted (anonymous, au=off)
2013/04/06 23:13:31 A00008C0 c before:
2013/04/06 23:13:31 A00008C0 80 70 44 00 90 03 05 0B 08 9F 08 52 55 53 2A 53
2013/04/06 23:13:31 A00008C0 c after:
2013/04/06 23:13:31 A00008C0 80 70 48 00 D2 02 0D 00 40 03 05 0B 08 9F 08 52
2013/04/06 23:13:31 A00008C0 c trying reader 'PCAM' filter 0500:050B00
2013/04/06 23:13:31 A00008C0 c 0500:050B00 allowed by reader 'PCAM' filter 0500:050B00
2013/04/06 23:13:31 A00008C0 c matching_reader became slot attribute of 1
2013/04/06 23:13:31 A00008C0 c [GET_CW] wait_time 0 caid 0500 prov 050B00 srvid 4E86 rc 100 cacheex cl mode 0 ex1rdr 0
2013/04/06 23:13:31 A00008C0 c request_cw stage=3 to reader PCAM ecm hash=1B6BEE49714930094C7A3A6F52449787
2013/04/06 23:13:31 A00008C0 c add reader job action 5 queue length 1 PCAM
2013/04/06 23:13:31 A00008C0 c Client anonymous ECM dump 0500&050B00/0000/4E86/4B:1B6BEE49714930094C7A3A6F52449787
2013/04/06 23:13:31 A00008C0 80 70 48 00 D2 02 0D 00 40 03 05 0B 08 9F 08 52
2013/04/06 23:13:31 A00008C0 55 53 2A 53 45 52 56 DE 04 51 60 AE 85 E0 01 C0
2013/04/06 23:13:31 A00008C0 E2 03 42 86 DE E2 03 42 86 0A E2 03 42 86 C6 EA
2013/04/06 23:13:31 A00008C0 10 22 CD ED BF 5B DE BF 39 33 3B 64 C4 DC EC CC
2013/04/06 23:13:31 A00008C0 71 F0 08 97 91 CB E8 7D 59 D5 2B
2013/04/06 23:13:31 B42CC0 p ---- ecm_task 0, idx 2, sflag=1
2013/04/06 23:13:31 B42CC0 p casc ecm (PCAM):
2013/04/06 23:13:31 B42CC0 80 70 48 00 D2 02 0D 00 40 03 05 0B 08 9F 08 52
2013/04/06 23:13:31 B42CC0 55 53 2A 53 45 52 56 DE 04 51 60 AE 85 E0 01 C0
2013/04/06 23:13:31 B42CC0 E2 03 42 86 DE E2 03 42 86 0A E2 03 42 86 C6 EA
2013/04/06 23:13:31 B42CC0 10 22 CD ED BF 5B DE BF 39 33 3B 64 C4 DC EC CC
2013/04/06 23:13:31 B42CC0 71 F0 08 97 91 CB E8 7D 59 D5 2B
2013/04/06 23:13:31 B42CC0 p send 87 bytes to remote server
2013/04/06 23:13:31 B42CC0 00 55 00 02 4E 86 00 00 00 00 00 00 80 70 48 00
2013/04/06 23:13:31 B42CC0 D2 02 0D 00 40 03 05 0B 08 9F 08 52 55 53 2A 53
2013/04/06 23:13:31 B42CC0 45 52 56 DE 04 51 60 AE 85 E0 01 C0 E2 03 42 86
2013/04/06 23:13:31 B42CC0 DE E2 03 42 86 0A E2 03 42 86 C6 EA 10 22 CD ED
2013/04/06 23:13:31 B42CC0 BF 5B DE BF 39 33 3B 64 C4 DC EC CC 71 F0 08 97
2013/04/06 23:13:31 B42CC0 91 CB E8 7D 59 D5 2B
2013/04/06 23:13:31 0 >> OSCam << cardserver log switched, version 1.20-unstable_svn, build r8600 (x86_64-pc-linux-gnu)
2013/04/06 23:13:31 A00008C0 c received 2 bytes from client in 5 msec
2013/04/06 23:13:31 A00008C0 0A 0D
2013/04/06 23:13:32 0 fallback for anonymous 0500&050B00/0000/4E86/4B:1B6BEE49714930094C7A3A6F52449787
2013/04/06 23:13:34 B42CC0 p Client PCAM reached 3 seconds timeout but no data received -> Skip, better luck next time!
2013/04/06 23:13:36 0 timeout for anonymous 0500&050B00/0000/4E86/4B:1B6BEE49714930094C7A3A6F52449787
2013/04/06 23:13:36 0 start client thread action 24
2013/04/06 23:13:36 A00008C0 c data from add_job action=24 client c anonymous
2013/04/06 23:13:36 A00008C0 c Client anonymous csphash 5544ACD4 cw 00000000000000000000000000000000 rc 5 0500&050B00/0000/4E86/4B:1B6BEE49714930094C7A3A6F52449787
2013/04/06 23:13:36 A00008C0 c anonymous (0500&050B00/0000/4E86/4B:1B6BEE49714930094C7A3A6F52449787): timeout (5001 ms) by PCAM - HD Кино 2
2013/04/06 23:13:36 A00008C0 c cw:
2013/04/06 23:13:36 A00008C0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2013/04/06 23:13:36 B42CC0 p nmr(): len=2, errno=0
2013/04/06 23:13:36 B42CC0 p nmr: netMsgId=2, from server=2,
2013/04/06 23:13:36 B42CC0 p received 5 bytes from remote server
2013/04/06 23:13:36 B42CC0 00 02 80 00 00
2013/04/06 23:13:39 B42CC0 p Client PCAM reached 3 seconds timeout but no data received -> Skip, better luck next time!
2013/04/06 23:13:41 A00008C0 c received 159 bytes from client in 6 msec
2013/04/06 23:13:41 A00008C0 03 30 30 30 35 30 62 30 30 30 35 30 30 38 30 37
2013/04/06 23:13:41 A00008C0 30 34 34 30 30 39 30 30 33 30 35 30 62 30 38 39
2013/04/06 23:13:41 A00008C0 66 30 38 35 32 35 35 35 33 32 61 35 33 34 35 35
2013/04/06 23:13:41 A00008C0 32 35 36 64 65 30 34 35 31 36 30 61 65 38 66 65
2013/04/06 23:13:41 A00008C0 30 30 31 63 30 65 32 30 33 34 32 38 36 64 65 65
2013/04/06 23:13:41 A00008C0 32 30 33 34 32 38 36 30 61 65 32 30 33 34 32 38
2013/04/06 23:13:41 A00008C0 36 63 36 65 61 31 30 37 65 33 63 38 61 36 62 32
2013/04/06 23:13:41 A00008C0 61 63 37 36 63 32 39 34 36 64 37 31 32 32 65 66
2013/04/06 23:13:41 A00008C0 61 36 30 35 30 32 62 66 30 30 38 66 64 62 65 31
2013/04/06 23:13:41 A00008C0 66 36 36 36 33 61 36 38 33 31 61 34 65 38 36
2013/04/06 23:13:41 A00008C0 c before:
2013/04/06 23:13:41 A00008C0 80 70 44 00 90 03 05 0B 08 9F 08 52 55 53 2A 53
2013/04/06 23:13:41 A00008C0 c after:
2013/04/06 23:13:41 A00008C0 80 70 48 00 D2 02 0D 00 40 03 05 0B 08 9F 08 52
2013/04/06 23:13:41 A00008C0 c trying reader 'PCAM' filter 0500:050B00
2013/04/06 23:13:41 A00008C0 c 0500:050B00 allowed by reader 'PCAM' filter 0500:050B00

Last edited 11 years ago by vvv1980 (previous) (diff)

comment:4 by Jan Gruuthuse, 11 years ago

remove those WAN ip addresses
2013/04/06 23:13:31 B42CC0 p trying server '
2013/04/06 23:13:31 B42CC0 p 0500:050B00 allowed by server '

comment:5 by theparasol, 11 years ago

The timeout is normal behaviour, it simply states the client didnt give us data for 3 seconds and timeout occured.... better luck next time! After that oscam is advancing to next client (if present!) or retrying listening for 3 seconds something happens.

in reply to:  description comment:6 by vvv1980, 11 years ago

Last edited 11 years ago by vvv1980 (previous) (diff)

comment:7 by vvv1980, 11 years ago

Right now I can see, that this that parameters, like was changed in 8571, it has closed connection each time to dsr9500.
also, it cant send correct answer, because connection already closed. :(
If I changed it back, as was before 8571, then it start work fine. I talk about real picture...

comment:8 by vvv1980, 11 years ago

Owner: set to vvv1980

comment:9 by vvv1980, 11 years ago

Sorry, who can edit main ticket? I have tried, but ... cant do it :( Only can change status :(((
Will be fine to remove wan address from there. :(

Vladimir

comment:11 by vvv1980, 11 years ago

Fine. Thats fully fixed situation! Thanks a lot! Could you make update with some rev?! :)

comment:12 by vvv1980, 11 years ago

Resolution: fixed
Status: newclosed
Note: See TracTickets for help on using tickets.